syslog-ng crash?

pixel8383

pixel8383

Explorer
Joined
Apr 19, 2018
Messages
80
During the last night my FreeNAS crashed somehow.

The last log collected are these:
Code:
May 30 03:17:29 NAS upsmon[1229]: upsmon parent: read
May 30 03:17:30 NAS syslog-ng[86326]: syslog-ng starting up; version='3.23.1'
May 30 03:17:30 NAS , 1250.
May 30 03:17:30 NAS kernel: pid 17206 (syslog-ng), jid 0, uid 0: exited on signal 6 (core dumped)
May 30 03:17:35 NAS kernel: vnet0.2: link state changed to DOWN
May 30 03:17:35 NAS kernel: vnet0.2: link state changed to DOWN
May 30 03:17:35 NAS kernel: epair0b: link state changed to DOWN
May 30 03:17:35 NAS kernel: epair0b: link state changed to DOWN
May 30 03:17:38 NAS kernel: vnet0.3: link state changed to DOWN
May 30 03:17:38 NAS kernel: vnet0.3: link state changed to DOWN
May 30 03:17:38 NAS kernel: epair0b: link state changed to DOWN
May 30 03:17:38 NAS kernel: epair0b: link state changed to DOWN
May 30 03:17:40 NAS kernel: vnet0.4: link state changed to DOWN
May 30 03:17:40 NAS kernel: vnet0.4: link state changed to DOWN
May 30 03:17:40 NAS kernel: epair0b: link state changed to DOWN
May 30 03:17:40 NAS kernel: epair0b: link state changed to DOWN
May 30 03:17:43 NAS syslog-ng[86326]: syslog-ng shutting down; version='3.23.1'


I am running FreeNAS-11.3-U3.1 and it was pretty stable until now.

Do you think I can find somewhere else some other interesting data in order to better understand what happened? Seems like a soft shutdown happened since I can see this in console.log:
Code:
May 30 03:17:24 NAS Stopping cron.
May 30 03:17:24 NAS Waiting for PIDS: 1564.
May 30 03:17:24 NAS Stopping zfsd.
May 30 03:17:24 NAS Waiting for PIDS: 1553.
May 30 03:17:26 NAS Stopping collectd_daemon.
May 30 03:17:26 NAS Waiting for collectd to terminate.
May 30 03:17:26 NAS Waiting for PIDS: 2633.
May 30 03:17:26 NAS Stopping django.
May 30 03:17:27 NAS Waiting for PIDS: 1368.
May 30 03:17:27 NAS stopping mdnsadvertise.
May 30 03:17:27 NAS Stopping mdnsd.
May 30 03:17:27 NAS Waiting for PIDS: 1315.
May 30 03:17:27 NAS Stopping netatalk.
May 30 03:17:27 NAS Waiting for PIDS: 57376.
May 30 03:17:27 NAS Stopping nginx.
May 30 03:17:27 NAS Waiting for PIDS: 1299.
May 30 03:17:27 NAS Stopping openssh.
May 30 03:17:27 NAS Waiting for PIDS: 1295.
May 30 03:17:27 NAS Stopping rrdcached.
May 30 03:17:28 NAS Waiting for PIDS: 1279.
May 30 03:17:28 NAS Stopping smartd_daemon.
May 30 03:17:28 NAS Waiting for PIDS: 1273.
May 30 03:17:28 NAS Stopping nmbd.
May 30 03:17:28 NAS Waiting for PIDS: 1243.
May 30 03:17:28 NAS Stopping smbd.
May 30 03:17:30 NAS Stopping winbindd.
May 30 03:17:30 NAS Waiting for PIDS: 1259.
May 30 03:17:30 NAS Network UPS Tools upsmon 2.7.4
May 30 03:17:30 NAS Stopping nut_upslog.
May 30 03:17:30 NAS Waiting for PIDS: 1226.
May 30 03:17:30 NAS Stopping nut.
May 30 03:17:30 NAS Waiting for PIDS: 1223
May 30 03:17:30 NAS , 1223.
May 30 03:17:30 NAS Network UPS Tools - UPS driver controller 2.7.4
May 30 03:17:30 NAS Stopping powerd.
May 30 03:17:30 NAS Waiting for PIDS: 1206.
May 30 03:17:30 NAS Stopping ntpd.
May 30 03:17:31 NAS Shutting down local daemons:.
May 30 03:17:31 NAS Stopping rtsold.
May 30 03:17:31 NAS Waiting for PIDS: 859.
May 30 03:17:31 NAS Stopping devd.
May 30 03:17:31 NAS Waiting for PIDS: 926.
May 30 03:17:31 NAS Writing entropy file:.
May 30 03:17:31 NAS Writing early boot entropy file:.
May 30 03:17:32 NAS Stopping middlewared.
May 30 03:17:35 NAS Waiting for PIDS: 75
May 30 03:17:43 NAS
May 30 03:17:43 NAS

Any idea?
 
Samuel Tai

Samuel Tai

Never underestimate your own stupidity
Moderator
Joined
Apr 24, 2020
Messages
5,399
What does daemon.log look like? Do you have your FreeNAS server on a UPS?
 
pixel8383

pixel8383

Explorer
Joined
Apr 19, 2018
Messages
80
Yes, the system is on a UPS. The daemon.log tells:
Code:
May 30 03:17:24 NAS zfsd: Disconnecting from devd.
May 30 03:17:27 NAS mDNSResponder: mDNSResponder (FreeBSD 11.0) (May 20 2020 20:58:34) stopping
May 30 03:17:27 NAS mDNSResponder: mDNS_FinalExit failed to send goodbye for: 0000000801091580 01   23 _adisk._tcp.local. PTR NAS._adisk._tcp.local.
May 30 03:17:27 NAS mDNSResponder: mDNS_FinalExit failed to send goodbye for: 0000000801092980 01   28 _afpovertcp._tcp.local. PTR NAS._afpovertcp._tcp.local.
May 30 03:17:27 NAS mDNSResponder: mDNS_FinalExit failed to send goodbye for: 0000000801093D80 01   29 _device-info._tcp.local. PTR NAS._device-info._tcp.loc>
May 30 03:17:27 NAS mDNSResponder: mDNS_FinalExit failed to send goodbye for: 0000000801095180 01   22 _http._tcp.local. PTR NAS._http._tcp.local.
May 30 03:17:27 NAS mDNSResponder: mDNS_FinalExit failed to send goodbye for: 0000000801096580 01   23 _https._tcp.local. PTR NAS._https._tcp.local.
May 30 03:17:27 NAS mDNSResponder: mDNS_FinalExit failed to send goodbye for: 0000000801097980 01   28 _middleware._tcp.local. PTR NAS._middleware._tcp.local.
May 30 03:17:27 NAS mDNSResponder: mDNS_FinalExit failed to send goodbye for: 0000000801098D80 01   32 _middleware-ssl._tcp.local. PTR NAS._middleware-ssl._t>
May 30 03:17:27 NAS mDNSResponder: mDNS_FinalExit failed to send goodbye for: 000000080109B580 01   21 _ssh._tcp.local. PTR NAS._ssh._tcp.local.
May 30 03:17:27 NAS mDNSResponder: mDNS_FinalExit failed to send goodbye for: 000000080109C980 01   21 _smb._tcp.local. PTR NAS._smb._tcp.local.
May 30 03:17:28 NAS smartd[1273]: smartd received signal 15: Terminated
May 30 03:17:28 NAS smartd[1273]: smartd is exiting (exit status 0)
May 30 03:17:29 NAS upsmon[1231]: Signal 15: exiting
May 30 03:17:29 NAS upsd[1223]: User upsmon@127.0.0.1 logged out from UPS [ups]
May 30 03:17:29 NAS upsmon[1229]: upsmon parent: read
May 30 12:49:17 NAS usbhid-ups[1221]: Startup successful
 
Samuel Tai

Samuel Tai

Never underestimate your own stupidity
Moderator
Joined
Apr 24, 2020
Messages
5,399
OK, so there does appear to have been a reboot. What about middlewared.log and debug.log around that same time?
 
pixel8383

pixel8383

Explorer
Joined
Apr 19, 2018
Messages
80
I can't find anything around the same time in debug.log while I can see the shutdown of the iocage jails inside middlewared.log:
Code:
[2020/05/30 03:17:31] (DEBUG) JailService.stop_on_shutdown():1493 - Stopping jails on shutdown: PENDING
[2020/05/30 03:17:32] (WARNING) middlewared.devd_loop():70 - devd connection refused, retrying...
[2020/05/30 03:17:32] (INFO) middlewared.terminate():1379 - Terminating
[2020/05/30 03:17:33] (WARNING) middlewared.devd_loop():70 - devd connection refused, retrying...
[2020/05/30 03:17:34] (INFO) iocage.callback():67 - * Stopping Duplicity
[2020/05/30 03:17:34] (INFO) iocage.callback():67 -   + Executing prestop OK
[2020/05/30 03:17:34] (WARNING) middlewared.devd_loop():70 - devd connection refused, retrying...
[2020/05/30 03:17:34] (INFO) iocage.callback():67 -   + Stopping services OK
[2020/05/30 03:17:35] (INFO) iocage.callback():67 -   + Tearing down VNET OK
[2020/05/30 03:17:35] (INFO) iocage.callback():67 -   + Removing devfs_ruleset: 6 OK
[2020/05/30 03:17:35] (INFO) iocage.callback():67 -   + Removing jail process OK
[2020/05/30 03:17:35] (INFO) iocage.callback():67 -   + Executing poststop OK
[2020/05/30 03:17:35] (WARNING) middlewared.devd_loop():70 - devd connection refused, retrying...
[2020/05/30 03:17:36] (WARNING) middlewared.devd_loop():70 - devd connection refused, retrying...
[2020/05/30 03:17:36] (INFO) iocage.callback():67 - * Stopping FTPServer
[2020/05/30 03:17:36] (INFO) iocage.callback():67 -   + Executing prestop OK
[2020/05/30 03:17:37] (INFO) iocage.callback():67 -   + Stopping services OK
[2020/05/30 03:17:37] (WARNING) middlewared.devd_loop():70 - devd connection refused, retrying...
[2020/05/30 03:17:37] (INFO) iocage.callback():67 -   + Tearing down VNET OK
[2020/05/30 03:17:38] (INFO) iocage.callback():67 -   + Removing devfs_ruleset: 6 OK
[2020/05/30 03:17:38] (INFO) iocage.callback():67 -   + Removing jail process OK
[2020/05/30 03:17:38] (INFO) iocage.callback():67 -   + Executing poststop OK
[2020/05/30 03:17:38] (WARNING) middlewared.devd_loop():70 - devd connection refused, retrying...
[2020/05/30 03:17:39] (INFO) iocage.callback():67 - * Stopping HomeAssistant
[2020/05/30 03:17:39] (INFO) iocage.callback():67 -   + Executing prestop OK
[2020/05/30 03:17:39] (WARNING) middlewared.devd_loop():70 - devd connection refused, retrying...
[2020/05/30 03:17:40] (INFO) iocage.callback():67 -   + Stopping services OK
[2020/05/30 03:17:40] (INFO) iocage.callback():67 -   + Tearing down VNET OK
[2020/05/30 03:17:40] (INFO) iocage.callback():67 -   + Removing devfs_ruleset: 7 OK
[2020/05/30 03:17:40] (WARNING) middlewared.devd_loop():70 - devd connection refused, retrying...
[2020/05/30 03:17:40] (INFO) iocage.callback():67 -   + Removing jail process OK
[2020/05/30 03:17:40] (INFO) iocage.callback():67 -   + Executing poststop OK
[2020/05/30 03:17:41] (WARNING) middlewared.devd_loop():70 - devd connection refused, retrying...
[2020/05/30 03:17:41] (INFO) iocage.callback():67 - * Stopping Plex
[2020/05/30 03:17:41] (INFO) iocage.callback():67 -   + Executing prestop OK
[2020/05/30 03:17:42] (WARNING) middlewared.devd_loop():70 - devd connection refused, retrying...
[2020/05/30 03:17:42] (ERROR) middlewared.__terminate():1391 - Failed to terminate jail
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/site-packages/middlewared/main.py", line 1389, in __terminate
    await asyncio.wait_for(service.terminate(), 10)
  File "/usr/local/lib/python3.7/asyncio/tasks.py", line 449, in wait_for
    raise futures.TimeoutError()
concurrent.futures._base.TimeoutError
 
Samuel Tai

Samuel Tai

Never underestimate your own stupidity
Moderator
Joined
Apr 24, 2020
Messages
5,399
What about /var/log/nut/ups.log? What's the capacity of your UPS? I wonder if this was a UPS-commanded shutdown?
 
pixel8383

pixel8383

Explorer
Joined
Apr 19, 2018
Messages
80
Sorry for the late reply. Nothing relevant on that timespan has been registered inside ups.log (there is no update there since Dec 2017).
 
Samuel Tai

Samuel Tai

Never underestimate your own stupidity
Moderator
Joined
Apr 24, 2020
Messages
5,399
Also check /var/log/ups.log. This concerns me that the UPS service stopped logging. A UPS-commanded shutdown is the most likely explanation.
 
pixel8383

pixel8383

Explorer
Joined
Apr 19, 2018
Messages
80
Sorry for the misunderstanding, I was refering to /var/log/ups.log.

The /var/log/nut/ups.log shows the UPS was fine:

Code:
20200530 030350 100 228.0 13 [OL] NA NA
20200530 030850 100 228.0 11 [OL] NA NA
20200530 031350 100 228.0 7 [OL] NA NA
20200530 031729 100 228.0 12 [OL] NA NA
20200530 124917 NA NA NA [WAIT] NA NA

The last record is when I woke back up the server.
 
You must log in or register to reply here.

Important Announcement for the TrueNAS Community.

The TrueNAS Community has now been moved. This forum will now become READ-ONLY for historical purposes. Please feel free to join us on the new TrueNAS Community Forums.

Related topics on forums.truenas.com for thread: "syslog-ng crash?"

Similar threads

T
smartctl -l scttemp output question
Replies
4
Views
3K
Chris Moore
Chris Moore
S
  • Locked
FreeNAS 9.2.1.x cannot enable Active Directory
Replies
0
Views
1K
Sciskaty
S
P
  • Locked
The volume ROOT state is UNKNOWN
Replies
9
Views
2K
P33444
P
thepixelgeek
Intermittent Plex server connection issues
Replies
0
Views
2K
thepixelgeek
thepixelgeek
C
  • Locked
Connecting to Active Directory
Replies
1
Views
3K
dlavigne
D
Top