NETGEAR is aware of a growing number of phone and online scams. To learn how to stay safe click here.
Forum Discussion
RN314 found suddenly blocked with "Get_next_timer_interrupt+17a" message displayed on LCD
Hello!
On late night last Friday (01/12/2017) I started to receive various alerts messages related to failed backups attempts from my RN314 (ReadyNAS OS 6.9.0+4) so I accessed the Customer network remotely to check what was going on: no ping to RN314, no connection to it using RAIDar 6.3 too, no Web GUI were available to access, no SMB shares were visible (I didn't tried SSH which was enabled but I was pretty sure it wasn't available too)...it looked like the RN314 was shutted down...but, from the networking standpoint, I was able to see that Switch's port to which it was connected reported "Active"...so it was effectively powered on...simply no connection was apparently possible to it.
The unit remained in this state for all W/E failing all the scheduled backup tasks and today early morning - Monday 04/12/2017 - I asked a customer employee for a visual check about the RN314. It was found with the message in the Subject: "Get_next_timer_interrupt+17a" (it could have been 0x17a...not exactly sure, I wasn't there and I didn't asked for a shot because I was in a hurry to have it up and running again).
Reported LEDs status was: Blue of Power ON pushbutton, Green of 1, 2, 3 and 4 disk bays...like when the unit runs normally.
I asked to power it down: initially short power on pushbutton pressure did nothing so I then asked to press a little bit longer (more than 5 seconds)...so the unit powered down. RN314 was consequently powered on: it came back as nothing happened (all services were functioning).
Downloaded complete logs that I can submit on request (Logs through Web GUI didn't reported anything special).
Notice from status.log:
[17/12/01 19:05:12 CET] notice:backup:LOGMSG_SUCCESS_BACKUP Successfully completed backup job Night_WAM_Uploader_files_backup_to_NAS01.
[17/12/04 08:18:08 CET] info:system:LOGMSG_READYNASD_ABORTED_NOINFO ReadyNASOS service or process was restarted.
[17/12/04 08:18:12 CET] notice:system:LOGMSG_FIRMWARE_UPDATE_NOTICE A new firmware version (6.9.1) is available.
[17/12/04 08:18:13 CET] notice:system:LOGMSG_USB_PLUG External storage device connected.
[17/12/04 08:18:14 CET] info:system:LOGMSG_START_READYNASD ReadyNASOS background service started.
Nothing in between (19:05:12 was the last backup task done before the unit disappeared...two hours after - at 21 - the next backup task failed).
More from the system.log:
Dec 01 19:00:00 nas01 dbus[2767]: [system] Activating service name='org.opensuse.Snapper' (using servicehelper)
Dec 01 19:00:00 nas01 dbus[2767]: [system] Successfully activated service 'org.opensuse.Snapper'
Dec 01 19:03:21 nas01 connmand[2770]: ntp: adjust (slew): +0.003348 sec
Dec 01 19:05:01 nas01 CRON[15718]: pam_unix(cron:session): session opened for user root by (uid=0)
Dec 01 19:05:01 nas01 CRON[15722]: (root) CMD (/frontview/bin/fvbackup 005 &> /dev/null)
Dec 01 19:05:01 nas01 CRON[15718]: pam_unix(cron:session): session closed for user root
-- Reboot --
Dec 04 08:17:45 nas01 dbus[2787]: [system] Successfully activated service 'org.freedesktop.systemd1'
Dec 04 08:17:45 nas01 wsdd2[2792]: starting.
Dec 04 08:17:45 nas01 cron[2793]: (CRON) INFO (pidfile fd = 3)
Dec 04 08:17:45 nas01 connmand[2790]: Connection Manager version 1.35
Dec 04 08:17:45 nas01 cron[2793]: (CRON) INFO (Running reboot jobs)
Any idea of what could have happened? it was like the Kernel suffered a panic...
Forgot to mention that the RN314 has a USB3 external disk permanently connected to it (a Toshiba Canvio Basic 1TB).
Thanks, Davide.
15 Replies
Replies have been turned off for this discussion
The message on the LCD error is a snippet from a critical kernel error message. Is the full error in kernel.log or systemd-journal.log? These logs have timestamped entries. The important entries should be just before you rebooted it if they were logged.
Also we have newer firmware (6.9.1) now available.
Hello mdgm-ntgr, here some lines before/after the event:
As logged into kernel.log:
Dec 01 07:12:05 nas01 kernel: BTRFS info (device md127): found 8 extents Dec 01 07:12:15 nas01 kernel: BTRFS info (device md127): found 8 extents Dec 01 07:12:15 nas01 kernel: BTRFS info (device md127): relocating block group 516801167360 flags data Dec 01 07:12:25 nas01 kernel: BTRFS info (device md127): found 26 extents Dec 01 07:12:36 nas01 kernel: BTRFS info (device md127): found 26 extents Dec 01 07:12:36 nas01 kernel: BTRFS info (device md127): relocating block group 393790619648 flags data Dec 01 07:12:37 nas01 kernel: BTRFS info (device md127): found 11 extents Dec 01 07:12:42 nas01 kernel: BTRFS info (device md127): found 11 extents Dec 01 07:12:42 nas01 kernel: BTRFS info (device md127): relocating block group 391643136000 flags data Dec 01 07:12:47 nas01 kernel: BTRFS info (device md127): found 560 extents Dec 01 07:13:04 nas01 kernel: BTRFS info (device md127): found 560 extents Dec 01 07:13:04 nas01 kernel: BTRFS info (device md127): relocating block group 390569394176 flags data Dec 01 07:13:05 nas01 kernel: BTRFS info (device md127): found 9 extents Dec 01 07:13:09 nas01 kernel: BTRFS info (device md127): found 9 extents Dec 01 07:13:09 nas01 kernel: BTRFS info (device md127): relocating block group 389495652352 flags data Dec 01 07:13:10 nas01 kernel: BTRFS info (device md127): found 10 extents Dec 01 07:13:15 nas01 kernel: BTRFS info (device md127): found 10 extents Dec 01 07:13:15 nas01 kernel: BTRFS info (device md127): relocating block group 388421910528 flags data Dec 01 07:13:19 nas01 kernel: BTRFS info (device md127): found 497 extents Dec 01 07:13:29 nas01 kernel: BTRFS info (device md127): found 497 extents Dec 01 12:05:03 nas01 kernel: CIFS VFS: cifs_mount failed w/return code = -112 Dec 01 12:05:03 nas01 kernel: CIFS VFS: cifs_mount failed w/return code = -112 Dec 01 12:05:03 nas01 kernel: CIFS VFS: cifs_mount failed w/return code = -112 Dec 01 12:05:03 nas01 kernel: CIFS VFS: cifs_mount failed w/return code = -112 Dec 01 12:05:03 nas01 kernel: CIFS VFS: cifs_mount failed w/return code = -112 Dec 01 12:05:03 nas01 kernel: CIFS VFS: cifs_mount failed w/return code = -112 Dec 01 19:05:10 nas01 kernel: CIFS VFS: cifs_mount failed w/return code = -112 Dec 01 19:05:10 nas01 kernel: CIFS VFS: cifs_mount failed w/return code = -112 Dec 01 19:05:10 nas01 kernel: CIFS VFS: cifs_mount failed w/return code = -112 Dec 01 19:05:10 nas01 kernel: CIFS VFS: cifs_mount failed w/return code = -112 Dec 01 19:05:10 nas01 kernel: CIFS VFS: cifs_mount failed w/return code = -112 Dec 01 19:05:10 nas01 kernel: CIFS VFS: cifs_mount failed w/return code = -112 -- Reboot -- Dec 04 08:17:40 nas01 kernel: Initializing cgroup subsys cpuset Dec 04 08:17:40 nas01 kernel: Initializing cgroup subsys cpu Dec 04 08:17:40 nas01 kernel: Initializing cgroup subsys cpuacct Dec 04 08:17:40 nas01 kernel: Linux version 4.4.91.x86_64.1 (jenkins@blocks) (gcc version 4.9.2 (Debian 4.9.2-10) ) #1 SMP Tue Oct 10 14:55:58 PDT 2017 Dec 04 08:17:40 nas01 kernel: Command line: initrd=initrd.gz reason=normal BOOT_IMAGE=kernel Dec 04 08:17:40 nas01 kernel: KERNEL supported cpus: Dec 04 08:17:40 nas01 kernel: Intel GenuineIntel Dec 04 08:17:40 nas01 kernel: Disabled fast string operations Dec 04 08:17:40 nas01 kernel: x86/fpu: Legacy x87 FPU detected. Dec 04 08:17:40 nas01 kernel: x86/fpu: Using 'lazy' FPU context switches. Dec 04 08:17:40 nas01 kernel: e820: BIOS-provided physical RAM map: Dec 04 08:17:40 nas01 kernel: BIOS-e820: [mem 0x0000000000000000-0x000000000009b3ff] usable Dec 04 08:17:40 nas01 kernel: BIOS-e820: [mem 0x000000000009b400-0x000000000009ffff] reserved Dec 04 08:17:40 nas01 kernel: BIOS-e820: [mem 0x00000000000e0000-0x00000000000fffff] reserved Dec 04 08:17:40 nas01 kernel: BIOS-e820: [mem 0x0000000000100000-0x000000007f0f5fff] usable Dec 04 08:17:40 nas01 kernel: BIOS-e820: [mem 0x000000007f0f6000-0x000000007f13bfff] ACPI NVS Dec 04 08:17:40 nas01 kernel: BIOS-e820: [mem 0x000000007f13c000-0x000000007f26ffff] reserved Dec 04 08:17:40 nas01 kernel: BIOS-e820: [mem 0x000000007f270000-0x000000007f270fff] usable Dec 04 08:17:40 nas01 kernel: BIOS-e820: [mem 0x000000007f271000-0x000000007f271fff] ACPI NVS Dec 04 08:17:40 nas01 kernel: BIOS-e820: [mem 0x000000007f272000-0x000000007f286fff] reserved Dec 04 08:17:40 nas01 kernel: BIOS-e820: [mem 0x000000007f287000-0x000000007f28cfff] ACPI NVS Dec 04 08:17:40 nas01 kernel: BIOS-e820: [mem 0x000000007f28d000-0x000000007f293fff] ACPI data Dec 04 08:17:40 nas01 kernel: BIOS-e820: [mem 0x000000007f294000-0x000000007f29bfff] ACPI NVS Dec 04 08:17:40 nas01 kernel: BIOS-e820: [mem 0x000000007f29c000-0x000000007f2c2fff] reserved Dec 04 08:17:40 nas01 kernel: BIOS-e820: [mem 0x000000007f2c3000-0x000000007f305fff] ACPI NVS Dec 04 08:17:40 nas01 kernel: BIOS-e820: [mem 0x000000007f306000-0x000000007f59cfff] usable Dec 04 08:17:40 nas01 kernel: BIOS-e820: [mem 0x000000007f59d000-0x000000007f6e6fff] reserved Dec 04 08:17:40 nas01 kernel: BIOS-e820: [mem 0x000000007f6e7000-0x000000007f6effff] usable Dec 04 08:17:40 nas01 kernel: BIOS-e820: [mem 0x000000007f6f0000-0x000000007fffffff] reserved Dec 04 08:17:40 nas01 kernel: BIOS-e820: [mem 0x00000000fed1c000-0x00000000fed1ffff] reserved Dec 04 08:17:40 nas01 kernel: BIOS-e820: [mem 0x00000000fee00000-0x00000000fee00fff] reserved Dec 04 08:17:40 nas01 kernel: BIOS-e820: [mem 0x00000000ff000000-0x00000000ffffffff] reserved Dec 04 08:17:40 nas01 kernel: NX (Execute Disable) protection: active Dec 04 08:17:40 nas01 kernel: SMBIOS 2.7 present.
And some other from the systemd-journal.log during the same time window:
Dec 01 18:29:13 nas01 connmand[2770]: ntp: adjust (slew): -0.009003 sec Dec 01 18:46:17 nas01 connmand[2770]: ntp: adjust (slew): +0.005046 sec Dec 01 18:55:35 nas01 systemd[1]: Starting Debian Package List Updater... Dec 01 18:55:36 nas01 apt-update.sh[15416]: Get:1 http://security.debian.org jessie/updates InRelease [63.1 kB] Dec 01 18:55:36 nas01 apt-update.sh[15416]: Ign:2 http://mirrors.kernel.org/debian jessie InRelease Dec 01 18:55:36 nas01 apt-update.sh[15416]: Hit:3 http://apt.readynas.com/packages/readynasos 6.9.0 InRelease Dec 01 18:55:36 nas01 apt-update.sh[15416]: Hit:4 http://mirrors.kernel.org/debian jessie Release Dec 01 18:55:37 nas01 apt-update.sh[15416]: Fetched 63.1 kB in 0s (66.7 kB/s) Dec 01 18:55:40 nas01 apt-update.sh[15416]: Reading package lists... Dec 01 18:55:40 nas01 apt-update.sh[15416]: Reading package lists... Dec 01 18:55:40 nas01 apt-update.sh[15416]: Building dependency tree... Dec 01 18:55:40 nas01 apt-update.sh[15416]: Reading state information... Dec 01 18:55:41 nas01 apt-update.sh[15416]: 0 upgraded, 0 newly installed, 0 to remove and 3 not upgraded. Dec 01 18:55:41 nas01 systemd[1]: Started Debian Package List Updater. Dec 01 19:00:00 nas01 dbus[2767]: [system] Activating service name='org.opensuse.Snapper' (using servicehelper) Dec 01 19:00:00 nas01 dbus[2767]: [system] Successfully activated service 'org.opensuse.Snapper' Dec 01 19:00:00 nas01 readynasd[2930]: Snapshot c_1512151200 was successfully created for share or LUN Offerte_Commerciali. Dec 01 19:03:16 nas01 readynasd[2930]: dumping id mapping from /var/lib/samba/winbindd_idmap.tdb Dec 01 19:03:21 nas01 connmand[2770]: ntp: adjust (slew): +0.003348 sec Dec 01 19:04:35 nas01 systemd[1]: Starting Cleanup of Temporary Directories... Dec 01 19:04:35 nas01 systemd[1]: Started Cleanup of Temporary Directories. Dec 01 19:05:01 nas01 CRON[15718]: pam_unix(cron:session): session opened for user root by (uid=0) Dec 01 19:05:01 nas01 CRON[15722]: (root) CMD (/frontview/bin/fvbackup 005 &> /dev/null) Dec 01 19:05:01 nas01 CRON[15718]: pam_unix(cron:session): session closed for user root Dec 01 19:05:01 nas01 fvbackup-q[3331]: Command: enqueue:5 Dec 01 19:05:01 nas01 fvbackup-q[3331]: write(/var/log/frontview/backup/status_backup_005,BACKUP_STATUS__IN_QUEUE!!1512151501!!OK) Dec 01 19:05:01 nas01 fvbackup-q[3331]: Push: job_id=5 q_wp=107 q_rp=107 Dec 01 19:05:10 nas01 fvbackup-q[3331]: cmd=/frontview/bin/fvbackup -e 5 Dec 01 19:05:10 nas01 fvbackup-q[3331]: mount error(112): Host is down Dec 01 19:05:10 nas01 fvbackup-q[3331]: Refer to the mount.cifs(8) manual page (e.g. man mount.cifs) Dec 01 19:05:10 nas01 kernel: CIFS VFS: cifs_mount failed w/return code = -112 Dec 01 19:05:10 nas01 fvbackup-q[3331]: mount error(112): Host is down Dec 01 19:05:10 nas01 fvbackup-q[3331]: Refer to the mount.cifs(8) manual page (e.g. man mount.cifs) Dec 01 19:05:10 nas01 kernel: CIFS VFS: cifs_mount failed w/return code = -112 Dec 01 19:05:10 nas01 fvbackup-q[3331]: mount error(112): Host is down Dec 01 19:05:10 nas01 fvbackup-q[3331]: Refer to the mount.cifs(8) manual page (e.g. man mount.cifs) Dec 01 19:05:10 nas01 kernel: CIFS VFS: cifs_mount failed w/return code = -112 Dec 01 19:05:10 nas01 fvbackup-q[3331]: mount error(112): Host is down Dec 01 19:05:10 nas01 fvbackup-q[3331]: Refer to the mount.cifs(8) manual page (e.g. man mount.cifs) Dec 01 19:05:10 nas01 kernel: CIFS VFS: cifs_mount failed w/return code = -112 Dec 01 19:05:10 nas01 fvbackup-q[3331]: mount error(112): Host is down Dec 01 19:05:10 nas01 fvbackup-q[3331]: Refer to the mount.cifs(8) manual page (e.g. man mount.cifs) Dec 01 19:05:10 nas01 kernel: CIFS VFS: cifs_mount failed w/return code = -112 Dec 01 19:05:10 nas01 fvbackup-q[3331]: mount error(112): Host is down Dec 01 19:05:10 nas01 fvbackup-q[3331]: Refer to the mount.cifs(8) manual page (e.g. man mount.cifs) Dec 01 19:05:10 nas01 kernel: CIFS VFS: cifs_mount failed w/return code = -112 Dec 01 19:05:12 nas01 readynasd[2930]: Successfully completed backup job Night_WAM_Uploader_files_backup_to_NAS01. -- Reboot -- Dec 04 08:17:40 nas01 systemd-journald[1362]: Runtime journal (/run/log/journal/) is 8.0M, max 99.1M, 91.1M free. Dec 04 08:17:40 nas01 systemd-journald[1362]: System journal (/var/log/journal/) is 71.1M, max 50.0M, 0B free. Dec 04 08:17:40 nas01 systemd-journald[1362]: Time spent on flushing to /var is 3.235ms for 2 entries. Dec 04 08:17:40 nas01 kernel: Initializing cgroup subsys cpuset Dec 04 08:17:40 nas01 kernel: Initializing cgroup subsys cpu Dec 04 08:17:40 nas01 kernel: Initializing cgroup subsys cpuacct Dec 04 08:17:40 nas01 kernel: Linux version 4.4.91.x86_64.1 (jenkins@blocks) (gcc version 4.9.2 (Debian 4.9.2-10) ) #1 SMP Tue Oct 10 14:55:58 PDT 2017 Dec 04 08:17:40 nas01 kernel: Command line: initrd=initrd.gz reason=normal BOOT_IMAGE=kernel Dec 04 08:17:40 nas01 kernel: KERNEL supported cpus: Dec 04 08:17:40 nas01 kernel: Intel GenuineIntel Dec 04 08:17:40 nas01 kernel: Disabled fast string operations Dec 04 08:17:40 nas01 kernel: x86/fpu: Legacy x87 FPU detected. Dec 04 08:17:40 nas01 kernel: x86/fpu: Using 'lazy' FPU context switches.
This is from volume.log (this NAS has about 5640 hours of Power-On...so it's fairly new):
=== maintenance history === device operation start_time end_time result details ---------- --------- ------------------- ------------------- --------- ---------------------------------------------------------------- data resilver 2017-04-07 14:29:39 2017-04-07 16:40:55 completed tank resilver 2017-04-07 17:22:50 2017-04-07 20:50:43 completed tank scrub 2017-04-07 21:09:28 2017-04-08 00:36:21 pass tank balance 2017-04-08 03:58:21 2017-04-08 03:58:27 completed tank defrag 2017-04-08 03:58:41 2017-04-08 03:58:41 completed tank balance 2017-04-18 15:24:15 2017-04-18 15:24:18 completed tank scrub 2017-05-08 16:24:52 2017-05-08 21:14:29 pass tank scrub 2017-05-13 15:39:02 2017-05-13 20:57:36 pass tank defrag 2017-05-15 17:05:21 2017-05-15 17:05:55 completed tank balance 2017-05-15 17:06:23 2017-05-15 17:06:24 completed Done, had to relocate 0 out of 88 chunks Done, had to relocate 1 tank disk test 2017-06-10 19:00:02 2017-06-10 21:10:15 pass tank scrub 2017-06-11 17:00:02 2017-06-12 00:31:01 pass tank defrag 2017-06-11 19:30:02 2017-06-11 19:36:25 completed tank disk test 2017-06-17 19:00:01 2017-06-17 21:16:12 pass tank defrag 2017-06-17 20:30:01 2017-06-17 20:33:19 completed tank disk test 2017-06-24 19:00:01 2017-06-24 21:17:52 pass tank defrag 2017-06-24 20:30:01 2017-06-24 20:34:11 completed tank balance 2017-07-01 12:00:01 2017-07-01 12:00:04 completed Done, had to relocate 0 out of 355 chunks Done, had to relocate tank defrag 2017-07-01 20:30:02 2017-07-01 20:31:59 completed tank defrag 2017-07-08 20:30:02 2017-07-08 20:33:55 completed tank scrub 2017-07-12 18:00:02 2017-07-13 06:15:56 pass tank defrag 2017-07-15 20:30:01 2017-07-15 20:35:51 completed tank disk test 2017-07-20 20:00:01 2017-07-20 22:33:00 pass tank defrag 2017-07-22 20:30:01 2017-07-22 20:39:34 completed tank defrag 2017-07-29 20:30:01 2017-07-29 20:34:04 completed tank balance 2017-08-01 12:00:01 2017-08-01 12:00:17 completed Done, had to relocate 0 out of 556 chunks Done, had to relocate tank defrag 2017-08-05 20:30:01 2017-08-05 20:37:48 completed tank scrub 2017-08-12 18:00:02 2017-08-13 11:15:35 pass tank defrag 2017-08-12 20:30:02 2017-08-12 20:54:32 completed tank defrag 2017-08-19 20:30:02 2017-08-19 20:35:07 completed tank disk test 2017-08-20 20:00:01 2017-08-20 22:10:12 pass tank defrag 2017-08-26 20:30:01 2017-08-26 20:41:23 completed tank balance 2017-09-01 12:00:01 2017-09-01 12:01:14 completed Done, had to relocate 0 out of 731 chunks Done, had to relocate tank defrag 2017-09-02 20:30:01 2017-09-02 20:36:30 completed tank defrag 2017-09-09 20:30:02 2017-09-09 20:36:50 completed tank scrub 2017-09-12 18:00:02 2017-09-13 17:12:25 pass tank defrag 2017-09-16 20:30:02 2017-09-16 20:43:57 completed tank disk test 2017-09-20 20:00:02 2017-09-20 22:37:16 pass tank defrag 2017-09-23 20:30:01 2017-09-23 20:39:26 completed tank defrag 2017-09-30 20:30:01 2017-09-30 20:37:36 completed tank balance 2017-10-01 12:00:01 2017-10-01 12:05:23 completed Done, had to relocate 0 out of 933 chunks Done, had to relocate tank defrag 2017-10-07 20:30:01 2017-10-07 20:36:27 completed tank scrub 2017-10-12 18:00:01 tank defrag 2017-10-14 20:30:02 2017-10-14 20:37:30 completed tank disk test 2017-10-20 20:00:01 2017-10-20 22:46:41 pass tank defrag 2017-10-21 20:30:01 2017-10-21 20:39:13 completed tank defrag 2017-10-28 20:30:01 2017-10-28 20:35:44 completed tank balance 2017-11-01 12:00:01 2017-11-01 12:02:03 completed Done, had to relocate 0 out of 928 chunks Done, had to relocate tank defrag 2017-11-04 20:30:01 2017-11-04 20:40:40 completed tank defrag 2017-11-11 20:30:01 2017-11-11 20:39:04 completed tank scrub 2017-11-12 18:00:01 2017-11-13 15:30:12 pass tank defrag 2017-11-18 20:30:01 2017-11-18 20:38:30 completed tank disk test 2017-11-20 20:00:01 2017-11-20 22:39:14 pass tank defrag 2017-11-25 20:30:01 2017-11-25 20:38:04 completed tank balance 2017-12-01 07:00:01 2017-12-01 07:13:31 completed Done, had to relocate 0 out of 929 chunks Done, had to relocate
Should I update it to 6.9.1 ASAP?
Thanks, Davide.
Well, I did the ReadyNAS OS 6.9.0 (exactly 6.9.0+4) -> 6.9.1 (as I see it today 6.9.1+1) update yesterday late night...so I'll monitor that unit to see if this very particular issue will repeat or not (still I'm curious to know if other experienced such unit blockage).
Noticed the Kernel build changed - was expected - from (6.9.0+4) Linux 4.4.91 (Tue Oct 10 14:55:58 PDT 2017) to (6.9.1+1) Linux 4.4.98 (Thu Nov 16 11:42:47 PST) so I'm in hope that, if it was Kernel related, it was maybe already fixed...
NETGEAR Academy
Boost your skills with the Netgear Academy - Get trained, certified and stay ahead with the latest Netgear technology!
Join Us!
