FreeNAS unexpected and sudden restart

[okynnor]

Hi,

I was wondering why FreeNAS would unexpectedly and suddenly restart? It's the first time I've encountered this issue so I wanted to understand what's going on so I can plan for it, if that's even possible. With this incident, all my production servers that were relying on FreeNAS iSCSI were interrupted and had to be restarted.

"FreeNAS.freenas.local had an unscheduled system reboot.
The operating system successfully came back online at Mon Oct 7 08:26:10 2019."

 

[dlavigne]

What else is in /var/log/messages prior to the re-booting messages?

 

[okynnor]

I'm including the log here. I hope that's more helpful.

 

[dlavigne]

Nothing in there. Do you have any tasks (replication, scrubs, cron jobs, etc.) that run around 1:30 in the morning?

 

[okynnor]

I'm sorry. nothing that runs just on the date. I got a scrub task on the 01 and 15th of the month. but this is October 7... far from it.
Further, I got SMART TESTs (long and short) tasks but none are on the 7th.

 

[Glorious1]

Power interruption?

 

[okynnor]

It is attached to a UPS though.

 

[Glorious1]

I wonder if debug.log would show anything? Yesterday's would be bzipped but you can read it with bzcat.

 

[okynnor]

thanks once again. Here is yesterday's debug log. I added txt to bypass the extension limit here.

 

[Glorious1]

That is daemon.log, not debug.log. You can read it directly on your machine with bzcat and look at the time around when it restarted. I'm no expert at interpreting the messages it contains, but look for something that isn't happening repetitively.

 

[okynnor]

I'm sorry about that. I"m multitasking and wires got crossed. Here's the log.

Oct 7 01:29:54 FreeNAS collectd[3492]: type = disk, key = Disk, value = /^gptid/

Oct 7 01:29:54 FreeNAS collectd[3492]: type = disk, key = Disk, value = /^md/

Oct 7 01:29:54 FreeNAS collectd[3492]: type = disk, key = Disk, value = /^pass/

Oct 7 01:29:54 FreeNAS collectd[3492]: type = disk, key = IgnoreSelected, value = true

Oct 7 01:29:54 FreeNAS collectd[3492]: type = geom_stat, key = Filter, value = ^([a]?da|ciss|md|mfi|md|nvd|pmem|xbd|vtbd)[0123456789]+$

Oct 7 01:29:54 FreeNAS collectd[3492]: geom_stat: geom_init

Oct 7 01:29:54 FreeNAS collectd[3492]: geom_stat: geom_init - running init.

Oct 7 01:29:54 FreeNAS collectd[3492]: geom_stat: geom_init - complete.

Oct 7 01:29:54 FreeNAS collectd[3492]: geom_stat: Valid filter accepted re_format(7) : ^([a]?da|ciss|md|mfi|md|nvd|pmem|xbd|vtbd)[0123456789]+$

Oct 7 01:29:54 FreeNAS collectd[3492]: type = syslog, key = LogLevel, value = err

Oct 7 01:29:55 FreeNAS uwsgi: [freeadmin.navtree:114] Unable to import 'django.contrib.sessions' 'forms': No module named 'django.contrib.sessions.forms'

Oct 7 01:29:55 FreeNAS uwsgi: [freeadmin.navtree:114] Unable to import 'django.contrib.staticfiles' 'forms': No module named 'django.contrib.staticfiles.forms'

Oct 7 01:29:55 FreeNAS uwsgi: [freeadmin.navtree:114] Unable to import 'freenasUI.api' 'forms': No module named 'freenasUI.api.forms'

Oct 7 01:29:55 FreeNAS uwsgi: [freeadmin.navtree:114] Unable to import 'freenasUI.reporting' 'forms': No module named 'freenasUI.reporting.forms'

Oct 7 01:29:55 FreeNAS uwsgi: [freeadmin.site:68] Model <class 'freenasUI.network.models.VLAN'> already registered, overwriting...

Oct 7 01:29:56 FreeNAS /netcli: [urllib3.connectionpool:208] Starting new HTTP connection (1): 192.168.1.5

Oct 7 01:29:56 FreeNAS /netcli: [urllib3.connectionpool:396] http://192.168.1.5:443 "HEAD / HTTP/1.1" 400 0

Oct 7 01:29:56 FreeNAS /netcli: [urllib3.connectionpool:824] Starting new HTTPS connection (1): 192.168.1.5

Oct 7 01:29:56 FreeNAS /netcli: [urllib3.connectionpool:396] https://192.168.1.5:443 "HEAD / HTTP/1.1" 200 0

Oct 7 01:29:56 FreeNAS /netcli: [urllib3.connectionpool:208] Starting new HTTP connection (1): 192.168.1.5

Oct 7 01:29:56 FreeNAS /netcli: [urllib3.connectionpool:396] http://192.168.1.5:80 "HEAD / HTTP/1.1" 200 0

Oct 7 03:02:26 FreeNAS sudo: root : TTY=unknown ; PWD=/root ; USER=root ; COMMAND=/etc/find_alias_for_smtplib.sh -i root

 

[Glorious1]

According to your first post it rebooted at 08:26. Nothing just before that?

 

[okynnor]

Since I don't know what we're looking for, I'm attaching the entire log.

 

[Glorious1]

No, nothing there. Funny - your debug log has WAY less stuff than mine. Mine reaches the size limit and turns over every day - yours goes back to June!

Maybe this will remain a mystery. I have to say, FreeNAS is remarkably stable. If a drive didn't need attention occasionally or updating, I think it would run for years without problem.

Maybe report your detailed hardware configuration. The hardware police may have something to say.

 

[okynnor]

in August 2019, I got new hardware. I reported some issues in this post. The guru said that I am running FreeNAS on really new hardware. Would that be an issue here?

 

[Glorious1]

No idea. You would have to report your hardware (actually a requirement on the forum), and a guru smarter than me would have to comment.

 

[styno]

If you create a debug dump (system - advanced - save debug) you can find the files in /var/db/system/ixdiagnose/ixdiagnose/crash.
Then grep on panic and it should give you the reason if it was a kernel panic that caused the reboot:

Code:

root@freenas:/var/db/system/ixdiagnose/ixdiagnose/crash # grep -i panic info*
info.0:  Panic String: I/O to pool 'yourpool' appears to be hung on vdev guid 18310426492370138759 at '/dev/gptid/08ab2e82-2a2b-11e9-a607-0cc47a6cc8d8'.
info.last:  Panic String: I/O to pool 'yourpool' appears to be hung on vdev guid 18310426492370138759 at '/dev/gptid/08ab2e82-2a2b-11e9-a607-0cc47a6cc8d8'.

 

[okynnor]

Hi there,
the system and *another* unscheduled restart. :(. any assistance?

I wanted to note that this occurrence started happening after installing the latest update, which is version: FreeNAS-11.2-U6

System config:
Intel(R) Xeon(R) CPU D-1521 @ 2.40GHz (8 cores)
32GB ECC RAM
it's using a custom M/B by Asus
I had outlined this in this post before

FreeNAS.mybooks.private had an unscheduled system reboot.
The operating system successfully came back online at Thu Oct 10 01:41:41 2019.

 

[okynnor]

If you create a debug dump (system - advanced - save debug) you can find the files in /var/db/system/ixdiagnose/ixdiagnose/crash.
Then grep on panic and it should give you the reason if it was a kernel panic that caused the reboot:

Code:

root@freenas:/var/db/system/ixdiagnose/ixdiagnose/crash # grep -i panic info*
info.0:  Panic String: I/O to pool 'yourpool' appears to be hung on vdev guid 18310426492370138759 at '/dev/gptid/08ab2e82-2a2b-11e9-a607-0cc47a6cc8d8'.
info.last:  Panic String: I/O to pool 'yourpool' appears to be hung on vdev guid 18310426492370138759 at '/dev/gptid/08ab2e82-2a2b-11e9-a607-0cc47a6cc8d8'.

I ran the command and this is what I got:

root@FreeNAS:~ # /var/db/system/ixdiagnose/ixdiagnose/crash # grep -i panic info*

/var/db/system/ixdiagnose/ixdiagnose/crash: No match.

 

[styno]

My bad, I should be more specific in my instructions, this one should be copypaste-able from anywhere in the shell:
grep -i panic /var/db/system/ixdiagnose/ixdiagnose/crash/info*

But anyways, this is your panic string:
Panic String: I/O to pool 'MybooksVolume' appears to be hung on vdev guid 16849957480317237995 at '/dev/gptid/85ec03d5-7af9-11e7-9214-1078d29b61a3'.

For some reason I/O got stuck and FreeNAS rebooted itself. This could be hardware or driver related, I am afraid I can't tell you much more....