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).
Re: RN314 found suddenly blocked with "Get_next_timer_interrupt+17a" message displayed on
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.
Re: RN314 found suddenly blocked with "Get_next_timer_interrupt+17a" message displayed on
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
Re: RN314 found suddenly blocked with "Get_next_timer_interrupt+17a" message displayed on
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...
Re: RN314 found suddenly blocked with "Get_next_timer_interrupt+17a" message displayed on
Looks like you were having some problems with SMB/CIFS backup jobs on 6.9.0. There are some fixes for some issues related to backup jobs over SMB in 6.9.1
Re: RN314 found suddenly blocked with "Get_next_timer_interrupt+17a" message displayed on
Hi @mdgm-ntgr, if you were referring to issues of 6.9.0 solved with 6.9.0+4 I agree with you but the lock happened when the RN314 already was at 6.9.0+4 and the Backup jobs managed by the ReadyNAS were back working again correctly (exactly from ReadyNAS 314 to USB3 external disk directly attached)...so the update from 6.9.0+4 to 6.9.1 (6.9.1+1) was a sort of pro-forma to have the latest Kernel in order to see if the ReadyNAS total blockage will repeat or not (reporting the same Kernel related error message at LCD).
Or...are you telling me that ReadyNAS 314 still logged some SMB/CIF issues when it was 6.9.0+4?
I ask because, from the user level perspective, I see really no problems with backup tasks managed by ReadyNAS 314 with its USB3 external drive as target or with backup tasks performed by other software tools - Acronis Backup server in primis - with the ReadyNAS 314 as target...
Re: RN314 found suddenly blocked with "Get_next_timer_interrupt+17a" message displayed on
@mdgm-ntgr, that's OK (my point was that Backup Tasks managed by ReadyNAS 314 in 6.9.0+4 were all working as expected...)...so if you are referring to these log lines (before the unit gone blocked for an entire week-end):
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.
those log lines, as far as I can tell, where related to the very latest backup task scheduled (cron) which was completed by the ReadyNAS 314 before locking...so were those mount errors the cause or the result? since the job completed and only the next one scheduled two hours past didn't...I'm not sure...the only thing I could do now (at 6.9.1+1) is to observe if, before any scheduled backup, those lines appear again or not...
Re: RN314 found suddenly blocked with "Get_next_timer_interrupt+17a" message displayed on
I think mount error messages I saw (see):
Dec 07 19:05:01 nas01 CRON[31098]: pam_unix(cron:session): session opened for user root by (uid=0)
Dec 07 19:05:01 nas01 CRON[31102]: (root) CMD (/frontview/bin/fvbackup 005 &> /dev/null)
Dec 07 19:05:01 nas01 CRON[31098]: pam_unix(cron:session): session closed for user root
Dec 07 19:05:02 nas01 fvbackup-q[3368]: Command: enqueue:5
Dec 07 19:05:02 nas01 fvbackup-q[3368]: write(/var/log/frontview/backup/status_backup_005,BACKUP_STATUS__IN_QUEUE!!1512669902!!OK)
Dec 07 19:05:02 nas01 fvbackup-q[3368]: Push: job_id=5 q_wp=5 q_rp=5
Dec 07 19:05:02 nas01 fvbackup-q[3368]: cmd=/frontview/bin/fvbackup -e 5
Dec 07 19:05:02 nas01 fvbackup-q[3368]: mount error(112): Host is down
Dec 07 19:05:02 nas01 fvbackup-q[3368]: Refer to the mount.cifs(8) manual page (e.g. man mount.cifs)
Dec 07 19:05:02 nas01 kernel: CIFS VFS: cifs_mount failed w/return code = -112
Dec 07 19:05:02 nas01 fvbackup-q[3368]: mount error(112): Host is down
Dec 07 19:05:02 nas01 fvbackup-q[3368]: Refer to the mount.cifs(8) manual page (e.g. man mount.cifs)
Dec 07 19:05:02 nas01 kernel: CIFS VFS: cifs_mount failed w/return code = -112
Dec 07 19:05:02 nas01 fvbackup-q[3368]: mount error(112): Host is down
Dec 07 19:05:02 nas01 kernel: CIFS VFS: cifs_mount failed w/return code = -112
Dec 07 19:05:02 nas01 fvbackup-q[3368]: Refer to the mount.cifs(8) manual page (e.g. man mount.cifs)
Dec 07 19:05:02 nas01 fvbackup-q[3368]: mount error(112): Host is down
Dec 07 19:05:02 nas01 fvbackup-q[3368]: Refer to the mount.cifs(8) manual page (e.g. man mount.cifs)
Dec 07 19:05:02 nas01 kernel: CIFS VFS: cifs_mount failed w/return code = -112
Dec 07 19:05:02 nas01 fvbackup-q[3368]: mount error(112): Host is down
Dec 07 19:05:02 nas01 fvbackup-q[3368]: Refer to the mount.cifs(8) manual page (e.g. man mount.cifs)
Dec 07 19:05:02 nas01 kernel: CIFS VFS: cifs_mount failed w/return code = -112
Dec 07 19:05:02 nas01 fvbackup-q[3368]: mount error(112): Host is down
Dec 07 19:05:02 nas01 fvbackup-q[3368]: Refer to the mount.cifs(8) manual page (e.g. man mount.cifs)
Dec 07 19:05:02 nas01 kernel: CIFS VFS: cifs_mount failed w/return code = -112
Dec 07 19:05:03 nas01 readynasd[2945]: Successfully completed backup job Night_WAM_Uploader_files_backup_to_NAS01.
are unrelated to the issue reported "Get_next_timer_interrupt+17a" since I continue to see them despite the backup job they referenced to completed (completes).
WRT to those messages I need to investigate further the return code 112...and see if it can be related to one setting of the scheduled backup job (fvbackup -e 5).
The strange think (here we go OT) is that return code 112 seems to be related to name resolution issues...but, if so, the scheduled backup job didn't (and doesn't) use hostnames at all:
Re: RN314 found suddenly blocked with "Get_next_timer_interrupt+17a" message displayed on
It appeared to be duiring a backup
Mon Jun 4 2018 6:55:04
System: Alert message failed to send.
Mon Jun 4 2018 6:55:05
System: ReadyNASOS background service started.
Mon Jun 4 2018 6:55:04
Volume: Less than 30% of volume data's capacity is free. NETGEAR recommends that you add capacity to maintain current performance levels. Continuous protection snapshots will be deleted when volume free space is less than 5%.
Mon Jun 4 2018 6:53:51
System: ReadyNASOS service or process was restarted.
Sun Jun 3 2018 0:12:45
Backup: Successfully completed backup job Backup #Diving To Remote.
Sun Jun 3 2018 0:12:05
Backup: Successfully completed backup job Backup #Main Files to Remote.
Wed May 30 2018 21:34:41
Volume: Volume data is resynced.
Wed May 30 2018 17:34:54
Volume: Resyncing started for Volume data.
Wed May 30 2018 17:34:43
Disk: Disk in channel 3 (Internal) changed state from RESYNC to ONLINE.
Wed May 30 2018 17:34:43
Volume: Volume data health changed from Degraded to Redundant.
Wed May 30 2018 17:34:43
Volume: Volume data is resynced.
Wed May 30 2018 9:09:14
Volume: Resyncing started for Volume data.
Wed May 30 2018 9:09:02
Disk: Disk Model:TOSHIBA DT01ACA300 Serial:37U9EXNAS was added to Channel 3 of the head unit.
Wed May 30 2018 9:07:22
Volume: Volume data health changed from Redundant to Degraded.
Wed May 30 2018 9:07:17
Disk: Disk Model:ST2000DM001-1ER164 Serial:Z4Z4JYPT was removed from Channel 3 of the head unit.
Wed May 30 2018 8:55:07
System: Alert message failed to send.
Wed May 30 2018 8:55:08
System: ReadyNASOS background service started.
Wed May 30 2018 8:55:07
System: Firmware was upgraded to 6.9.3.
Wed May 30 2018 8:55:07
Volume: Less than 20% of volume data's capacity is free. Performance on volume data will degrade if additional capacity is consumed. NETGEAR recommends that you add capacity to avoid performance degradation.
Re: RN314 found suddenly blocked with "Get_next_timer_interrupt+17a" message displayed on
Hello! In my case no issues with NIC settings (it was manually set and it is still manually set, no fallback to DHCP happened after the forced reboot due to the reported issue), I hadn't time to investigate further but it happened once again at end of March when the RN314 was already at 6.9.3+2 (updated during March, 22nd...actually it runs 6.9.3+3 since the update happened during May, 3rd), same "Get Time Interrupt +17 A" Error Message on LCD and unit totally locked and unreacheable, once again only forcing power off and then powering again solved the lock.
