XigmaNAS ignores shutdown timer
Posted: 31 Aug 2019 18:27
I'm running XigmaNAS 12.0.0.4 - Reticulus (revision 6766) embedded, connected to a APC BackUPS RS 1500 - this was upgraded from an older embedded version a couple of weeks ago, and the UPS worked fine with the previous version (can't remember which, but it was old as it was prior to the name change from NAS4Free).
Strangely the NAS picks up a power loss event and initiates shutdown instantly, but completely ignores the 30 second grace period.
After booting, system.log contains the following entries pertaining to the UPS-
These read confirmation messages repeat through the remainder of the log.
daemon.log contains the following entries pertaining to the UPS -
Again, these "read confirmation" messages repeat.
I figured from the somewhat cryptic output that it might be referring to a permissions issue of some sort but don't have much more to go on than that. The only other mention of messages of this kind that I can find refer to a regression issue in NUT 2.6.4 from mailing list posts from 2012, and as this version of XigmaNAS runs 2.7.4 I doubt it's relevant.
Just in case there were potential issues with my previous upgrade I also tried the latest live USB distro, and this appeared to work properly as long as it was provided with the additional option -x pollonly to suppress "libusb_get_interrupt: Unknown error" messages. Thinking I'd got to the bottom of the issue, I wrote a completely fresh copy of the embedded distro to the USB stick and booted that, only to be confronted by the original issues as detailed above.
I'm at a loss as to how to proceed - any pointers or advice would be greatly appreciated. Thanks
Strangely the NAS picks up a power loss event and initiates shutdown instantly, but completely ignores the 30 second grace period.
After booting, system.log contains the following entries pertaining to the UPS-
Code: Select all
Aug 31 17:01:38 alexandria 1 2019-08-31T17:01:38.843447+01:00 alexandria.dwhweb.org upsmon 2128 - - UPS RS1500@localhost battery is low
Aug 31 17:01:39 alexandria 1 2019-08-31T17:01:39.098192+01:00 alexandria.dwhweb.org upssched 2139 - - read confirmation got [ERR UNKNOWN own"]
Aug 31 17:01:39 alexandria 1 2019-08-31T17:01:39.098375+01:00 alexandria.dwhweb.org upssched 2139 - - read confirmation got [ERR UNKNOWN own"]
Aug 31 17:01:39 alexandria 1 2019-08-31T17:01:39.098426+01:00 alexandria.dwhweb.org upssched 2139 - - read confirmation got [ERR UNKNOWN own"]
Aug 31 17:01:39 alexandria 1 2019-08-31T17:01:39.098475+01:00 alexandria.dwhweb.org upssched 2139 - - read confirmation got [ERR UNKNOWN own"]
Aug 31 17:01:39 alexandria 1 2019-08-31T17:01:39.098522+01:00 alexandria.dwhweb.org upssched 2139 - - read confirmation got [ERR UNKNOWN own"]
Aug 31 17:01:39 alexandria 1 2019-08-31T17:01:39.098590+01:00 alexandria.dwhweb.org upssched 2139 - - read confirmation failed, trying again
daemon.log contains the following entries pertaining to the UPS -
Code: Select all
Aug 31 17:01:35 alexandria 1 2019-08-31T17:01:35.968797+01:00 alexandria.dwhweb.org rpc.statd 1934 - - Starting
Aug 31 17:01:35 alexandria 1 2019-08-31T17:01:35.975143+01:00 alexandria.dwhweb.org rpc.lockd 1937 - - Starting
Aug 31 17:01:38 alexandria 1 2019-08-31T17:01:38.797034+01:00 alexandria.dwhweb.org usbhid-ups 2075 - - Startup successful
Aug 31 17:01:38 alexandria 1 2019-08-31T17:01:38.798586+01:00 alexandria.dwhweb.org upsd 2076 - - listening on ::1 port 3493
Aug 31 17:01:38 alexandria 1 2019-08-31T17:01:38.798705+01:00 alexandria.dwhweb.org upsd 2076 - - listening on 127.0.0.1 port 3493
Aug 31 17:01:38 alexandria 1 2019-08-31T17:01:38.799006+01:00 alexandria.dwhweb.org upsd 2076 - - Connected to UPS [RS1500]: usbhid-ups-RS1500
Aug 31 17:01:38 alexandria 1 2019-08-31T17:01:38.800068+01:00 alexandria.dwhweb.org upsd 2077 - - Startup successful
Aug 31 17:01:38 alexandria 1 2019-08-31T17:01:38.810185+01:00 alexandria.dwhweb.org upslog 2091 - - Startup successful
Aug 31 17:01:38 alexandria 1 2019-08-31T17:01:38.842198+01:00 alexandria.dwhweb.org upsmon 2126 - - Startup successful
Aug 31 17:01:38 alexandria 1 2019-08-31T17:01:38.843306+01:00 alexandria.dwhweb.org upsd 2077 - - User root@127.0.0.1 logged into UPS [RS1500]
Aug 31 17:01:38 alexandria 1 2019-08-31T17:01:38.843447+01:00 alexandria.dwhweb.org upsmon 2128 - - UPS RS1500@localhost battery is low
Aug 31 17:01:38 alexandria 1 2019-08-31T17:01:38.846367+01:00 alexandria.dwhweb.org upssched 2141 - - Timer daemon started
Aug 31 17:01:39 alexandria 1 2019-08-31T17:01:39.098081+01:00 alexandria.dwhweb.org upssched 2141 - - Unknown command on socket:
Aug 31 17:01:39 alexandria 1 2019-08-31T17:01:39.098101+01:00 alexandria.dwhweb.org upssched 2141 - - arg 0: START
Aug 31 17:01:39 alexandria 1 2019-08-31T17:01:39.098107+01:00 alexandria.dwhweb.org upssched 2141 - - arg 1: shutdown
Aug 31 17:01:39 alexandria 1 2019-08-31T17:01:39.098192+01:00 alexandria.dwhweb.org upssched 2139 - - read confirmation got [ERR UNKNOWN own"]
I figured from the somewhat cryptic output that it might be referring to a permissions issue of some sort but don't have much more to go on than that. The only other mention of messages of this kind that I can find refer to a regression issue in NUT 2.6.4 from mailing list posts from 2012, and as this version of XigmaNAS runs 2.7.4 I doubt it's relevant.
Just in case there were potential issues with my previous upgrade I also tried the latest live USB distro, and this appeared to work properly as long as it was provided with the additional option -x pollonly to suppress "libusb_get_interrupt: Unknown error" messages. Thinking I'd got to the bottom of the issue, I wrote a completely fresh copy of the embedded distro to the USB stick and booted that, only to be confronted by the original issues as detailed above.
I'm at a loss as to how to proceed - any pointers or advice would be greatly appreciated. Thanks