bhyve "falls over" - where do I find the logs?

[Yorick]

I'll be "that guy". For the most part, TrueNAS 13.0 is the most boring upgrade yet, and that's a compliment. However, I do have a Linux VM that "falls over" ... stops responding ... every couple weeks or so. The very same VM was happy with 12.0.

Which makes me think I need to look at bhyve logs, and if there's a "there" there, open a Jira ticket. Not sure where to even start ... where would potential failures be logged, in TrueNAS? Which file(s)?

 

[Samuel Tai]

I very occasionally see bhyve faults in /var/log/messages or its rolled-over bzip2 compressed variants.

Code:

root@raven:/var/log # bzcat messages.* | grep bhyve
Dec  8 21:42:32 raven kernel: pid 1888 (bhyve), jid 0, uid 0: exited on signal 6
Jul 20 19:07:34 raven kernel: pid 2139 (bhyve), jid 0, uid 0: exited on signal 6
Jul 17 09:46:49 raven kernel: pid 2108 (bhyve), jid 0, uid 0: exited on signal 6
Jul  3 11:38:47 raven kernel: pid 84629 (bhyve), jid 0, uid 0: exited on signal 6

Signal 6 is ABRT. The presence of a job ID attached to root indicates these are middleware API-driven terminations.

The middlewared.log and its rollovers also have some status for the VM itself.

Code:

root@raven:/var/log # grep rancher middlewared.log*
middlewared.log:[2022/01/08 06:05:01] (DEBUG) middlewared.status():1699 - Failed to retrieve VM status for rancher
middlewared.log:[2022/01/22 06:05:01] (DEBUG) middlewared.status():1699 - Failed to retrieve VM status for rancher
middlewared.log:[2022/02/05 06:05:00] (DEBUG) middlewared.status():1699 - Failed to retrieve VM status for rancher
middlewared.log:[2022/02/19 06:05:00] (DEBUG) middlewared.status():1699 - Failed to retrieve VM status for rancher
middlewared.log:[2022/04/02 06:05:00] (DEBUG) middlewared.status():1699 - Failed to retrieve VM status for rancher
middlewared.log:[2022/05/21 06:05:00] (DEBUG) middlewared.status():1699 - Failed to retrieve VM status for rancher
middlewared.log.1:[2021/01/16 07:46:01] (INFO) ZFSSnapshot.do_create():1031 - Snapshot taken: main/.bhyve/1_rancher@auto-2021-01-16_07-46
middlewared.log.1:[2021/01/16 07:46:01] (INFO) ZFSSnapshot.do_create():1031 - Snapshot taken: main/zvols/rancher-zvol@auto-2021-01-16_07-46
middlewared.log.1:[2021/01/23 06:05:01] (DEBUG) middlewared.status():1647 - Failed to retrieve VM status for rancher
middlewared.log.1:[2021/01/30 06:05:01] (DEBUG) middlewared.status():1647 - Failed to retrieve VM status for rancher
middlewared.log.1:middlewared.service_exception.CallError: [EFAULT] Unable to send encrypted dataset 'main/zvols/rancher-zvol' to existing unencrypted or unrelated dataset 'Backup/zvols/rancher-zvol'.
middlewared.log.1:middlewared.service_exception.CallError: [EFAULT] Unable to send encrypted dataset 'main/zvols/rancher-zvol' to existing unencrypted or unrelated dataset 'Backup/zvols/rancher-zvol'.
middlewared.log.1:[2021/01/30 10:11:24] (INFO) ZFSSnapshot.do_create():1031 - Snapshot taken: main/zvols/rancher-zvol@auto-2021-01-30_10-11
middlewared.log.1:middlewared.service_exception.CallError: [EFAULT] Unable to send encrypted dataset 'main/zvols/rancher-zvol' to existing unencrypted or unrelated dataset 'Backup/zvols/rancher-zvol'.
middlewared.log.1:middlewared.service_exception.CallError: [EFAULT] Source 'main/zvols/rancher-zvol' is a volume, but target 'Backup/zvols/rancher-zvol' already exists and is a filesystem.
middlewared.log.1:middlewared.service_exception.CallError: [EFAULT] Source 'main/zvols/rancher-zvol' is a volume, but target 'Backup/zvols' already exists and is a filesystem.
middlewared.log.1:[2021/02/18 11:54:17] (DEBUG) middlewared.status():1695 - Failed to retrieve VM status for rancher
middlewared.log.1:[2021/02/18 12:02:00] (WARNING) middlewared.do_delete():1353 - Target rancher-development is in use.
middlewared.log.1:[2021/02/20 06:05:00] (DEBUG) middlewared.status():1695 - Failed to retrieve VM status for rancher
middlewared.log.1:[2021/02/27 06:05:00] (DEBUG) middlewared.status():1695 - Failed to retrieve VM status for rancher
middlewared.log.1:[2021/03/06 06:05:01] (DEBUG) middlewared.status():1695 - Failed to retrieve VM status for rancher
middlewared.log.1:[2021/03/20 06:05:00] (DEBUG) middlewared.status():1695 - Failed to retrieve VM status for rancher
middlewared.log.1:[2021/04/10 06:05:01] (DEBUG) middlewared.status():1695 - Failed to retrieve VM status for rancher
middlewared.log.1:Exception in thread post_stop_devices_1_rancher:
middlewared.log.1:[2021/04/16 20:35:47] (DEBUG) middlewared.status():1699 - Failed to retrieve VM status for rancher
middlewared.log.1:[2021/04/17 05:55:00] (DEBUG) middlewared.status():1699 - Failed to retrieve VM status for rancher
middlewared.log.1:[2021/04/17 06:05:00] (DEBUG) middlewared.status():1699 - Failed to retrieve VM status for rancher
middlewared.log.1:[2021/04/17 06:05:00] (DEBUG) middlewared.status():1699 - Failed to retrieve VM status for rancher
middlewared.log.1:[2021/04/17 06:05:00] (DEBUG) middlewared.status():1699 - Failed to retrieve VM status for rancher
middlewared.log.1:[2021/04/17 06:05:00] (DEBUG) middlewared.status():1699 - Failed to retrieve VM status for rancher
middlewared.log.1:[2021/04/17 07:17:13] (DEBUG) middlewared.status():1699 - Failed to retrieve VM status for rancher
middlewared.log.1:[2021/04/17 07:17:13] (DEBUG) middlewared.status():1699 - Failed to retrieve VM status for rancher
middlewared.log.1:[2021/04/17 07:17:13] (DEBUG) middlewared.status():1699 - Failed to retrieve VM status for rancher
middlewared.log.1:[2021/04/17 07:18:16] (DEBUG) middlewared.status():1699 - Failed to retrieve VM status for rancher
middlewared.log.1:[2021/04/17 07:18:16] (DEBUG) middlewared.status():1699 - Failed to retrieve VM status for rancher
middlewared.log.1:[2021/04/17 07:18:16] (DEBUG) middlewared.status():1699 - Failed to retrieve VM status for rancher
middlewared.log.1:[2021/04/17 07:19:09] (DEBUG) middlewared.status():1699 - Failed to retrieve VM status for rancher
middlewared.log.1:[2021/04/17 07:19:15] (DEBUG) middlewared.status():1699 - Failed to retrieve VM status for rancher
middlewared.log.1:[2021/04/17 07:20:06] (DEBUG) middlewared.status():1699 - Failed to retrieve VM status for rancher
middlewared.log.1:[2021/04/17 07:20:06] (DEBUG) middlewared.status():1699 - Failed to retrieve VM status for rancher
middlewared.log.1:[2021/04/17 07:20:06] (DEBUG) middlewared.status():1699 - Failed to retrieve VM status for rancher
middlewared.log.1:[2021/04/17 07:20:12] (DEBUG) middlewared.status():1699 - Failed to retrieve VM status for rancher
middlewared.log.1:[2021/04/17 07:20:12] (DEBUG) middlewared.status():1699 - Failed to retrieve VM status for rancher
middlewared.log.1:[2021/04/17 07:20:12] (DEBUG) middlewared.status():1699 - Failed to retrieve VM status for rancher
middlewared.log.1:[2021/04/17 07:20:12] (DEBUG) middlewared.status():1699 - Failed to retrieve VM status for rancher
middlewared.log.1:[2021/04/17 07:21:00] (DEBUG) middlewared.status():1699 - Failed to retrieve VM status for rancher
middlewared.log.1:[2021/04/17 07:21:00] (DEBUG) middlewared.status():1699 - Failed to retrieve VM status for rancher
middlewared.log.1:[2021/04/17 07:21:00] (DEBUG) middlewared.status():1699 - Failed to retrieve VM status for rancher
middlewared.log.1:[2021/04/17 07:21:22] (DEBUG) middlewared.status():1699 - Failed to retrieve VM status for rancher
middlewared.log.1:[2021/04/17 07:21:22] (DEBUG) middlewared.status():1699 - Failed to retrieve VM status for rancher
middlewared.log.1:[2021/04/17 07:21:22] (DEBUG) middlewared.status():1699 - Failed to retrieve VM status for rancher
middlewared.log.1:[2021/04/17 07:21:22] (DEBUG) middlewared.status():1699 - Failed to retrieve VM status for rancher
middlewared.log.1:[2021/04/17 07:21:55] (DEBUG) middlewared.status():1699 - Failed to retrieve VM status for rancher
middlewared.log.1:[2021/04/17 07:22:00] (DEBUG) middlewared.status():1699 - Failed to retrieve VM status for rancher
middlewared.log.1:[2021/04/24 06:05:00] (DEBUG) middlewared.status():1699 - Failed to retrieve VM status for rancher
middlewared.log.1:[2021/04/30 16:30:19] (DEBUG) middlewared.status():1699 - Failed to retrieve VM status for rancher
middlewared.log.1:[2021/05/05 15:53:32] (DEBUG) middlewared.status():1699 - Failed to retrieve VM status for rancher
middlewared.log.1:[2021/06/05 06:05:00] (DEBUG) middlewared.status():1699 - Failed to retrieve VM status for rancher
middlewared.log.1:Exception in thread post_stop_devices_1_rancher:
middlewared.log.1:[2021/07/20 20:59:47] (DEBUG) middlewared.status():1699 - Failed to retrieve VM status for rancher
middlewared.log.1:[2021/07/20 20:59:47] (DEBUG) middlewared.status():1699 - Failed to retrieve VM status for rancher
middlewared.log.1:[2021/07/20 20:59:47] (DEBUG) middlewared.status():1699 - Failed to retrieve VM status for rancher
middlewared.log.1:[2021/07/20 21:00:28] (DEBUG) middlewared.status():1699 - Failed to retrieve VM status for rancher
middlewared.log.1:[2021/07/20 21:00:28] (DEBUG) middlewared.status():1699 - Failed to retrieve VM status for rancher
middlewared.log.1:[2021/07/20 21:00:28] (DEBUG) middlewared.status():1699 - Failed to retrieve VM status for rancher
middlewared.log.1:[2021/07/20 21:01:29] (DEBUG) middlewared.status():1699 - Failed to retrieve VM status for rancher
middlewared.log.1:[2021/07/20 21:01:31] (DEBUG) middlewared.status():1699 - Failed to retrieve VM status for rancher
middlewared.log.1:[2021/07/31 06:05:00] (DEBUG) middlewared.status():1699 - Failed to retrieve VM status for rancher
middlewared.log.1:[2021/10/02 06:05:00] (DEBUG) middlewared.status():1699 - Failed to retrieve VM status for rancher

Hope this helps you to track down your VM issue.

 

[Yorick]

Nothing in either, alas. I think I'll go with Jira and ask for help that way. https://jira.ixsystems.com/browse/NAS-116896

 

[Yorick]

"wontfix" - that's unfortunately reasonable. SCALE for VMs and such; Core for just storage. Fair enough. I'll make the move to Scale eventually.