NUT Package (2.8.1 and above)

ghound

@dennypage said in NUT Package (2.8.1 and above):

@ghound If I understood you correctly, you had previously said that you had to physically disconnect the USB cable after the UPS disappeared. However the usbconfig output you posted shows that the UPS is still connected. Also, there are not kernel USB messages. Can you clarify please?

When the UPS stops, have you tried restarting the UPS service?

Lastly, can you please post anything you have in the "Extra Arguments to driver" and "Additional configuration lines for ups.conf" sections?

This is a clean log of being in the failed condition, trying service restart - still in failed condition, stop-nut/disconnect/reconnect/start-nut - connection restored sequence:

 ~ ~ ~ Nut Service Restart ~ ~ ~
Mar  5 15:06:16 router01 upsmon[54708]: Poll UPS [TrippLite] failed - Driver not connected
Mar  5 15:06:19 router01 upsmon[54708]: Signal 15: exiting
Mar  5 15:06:19 router01 upsd[53855]: User local-monitor@::1 logged out from UPS [TrippLite]
Mar  5 15:06:19 router01 upsd[53855]: mainloop: Interrupted system call
Mar  5 15:06:19 router01 upsd[53855]: Signal 15: exiting
Mar  5 15:06:19 router01 upsd[54022]: listening on 127.0.0.1 port 3493
Mar  5 15:06:19 router01 upsd[54022]: listening on ::1 port 3493
Mar  5 15:06:19 router01 upsd[54022]: Can't connect to UPS [TrippLite] (usbhid-ups-TrippLite): No such file or directory
Mar  5 15:06:19 router01 upsd[54022]: Found 1 UPS defined in ups.conf
Mar  5 15:06:19 router01 upsd[54239]: Startup successful
Mar  5 15:06:20 router01 upsmon[54725]: Startup successful
Mar  5 15:06:20 router01 upsd[54239]: User local-monitor@::1 logged into UPS [TrippLite]
Mar  5 15:06:20 router01 upsmon[55048]: Poll UPS [TrippLite] failed - Driver not connected
Mar  5 15:06:20 router01 upsmon[55048]: Communications with UPS TrippLite lost
Mar  5 15:06:25 router01 upsmon[55048]: Poll UPS [TrippLite] failed - Driver not connected
Mar  5 15:06:25 router01 upsmon[55048]: UPS TrippLite is unavailable
Mar  5 15:06:30 router01 upsmon[55048]: Poll UPS [TrippLite] failed - Driver not connected
Mar  5 15:08:05 router01 upsmon[55048]: Poll UPS [TrippLite] failed - Driver not connected
 ~ ~ ~ Nut Service Stoped / USB disconnect-reconnect/Nut Service Started ~ ~ ~
Mar  5 15:08:08 router01 upsmon[55048]: Signal 15: exiting
Mar  5 15:08:08 router01 upsd[54239]: User local-monitor@::1 logged out from UPS [TrippLite]
Mar  5 15:08:08 router01 upsd[54239]: mainloop: Interrupted system call
Mar  5 15:08:08 router01 upsd[54239]: Signal 15: exiting
Mar  5 15:08:30 router01 kernel: ugen1.2: <Tripp Lite ECO850LCD> at usbus1 (disconnected)
Mar  5 15:08:44 router01 kernel: ugen1.2: <Tripp Lite ECO850LCD> at usbus1
Mar  5 15:08:44 router01 kernel: uhid0 on uhub1
Mar  5 15:08:44 router01 kernel: uhid0: <Tripp Lite ECO850LCD, class 0/0, rev 2.00/0.02, addr 2> on usbus1
Mar  5 15:09:04 router01 upsd[98800]: listening on 127.0.0.1 port 3493
Mar  5 15:09:04 router01 upsd[98800]: listening on ::1 port 3493
Mar  5 15:09:04 router01 upsd[98800]: Can't connect to UPS [TrippLite] (usbhid-ups-TrippLite): No such file or directory
Mar  5 15:09:04 router01 upsd[98800]: Found 1 UPS defined in ups.conf
Mar  5 15:09:04 router01 upsd[643]: Startup successful
Mar  5 15:09:05 router01 usbhid-ups[99491]: using 'battery.charge' to set battery low state
Mar  5 15:09:05 router01 kernel: uhid0: at uhub1, port 1, addr 2 (disconnected)
Mar  5 15:09:05 router01 kernel: uhid0: detached
Mar  5 15:09:05 router01 usbhid-ups[99491]: using 'battery.runtime' to set battery low state
Mar  5 15:09:05 router01 usbhid-ups[962]: Startup successful
Mar  5 15:09:05 router01 upsmon[2297]: Startup successful
Mar  5 15:09:05 router01 upsd[643]: Connected to UPS [TrippLite]: usbhid-ups-TrippLite
Mar  5 15:09:05 router01 upsd[643]: User local-monitor@::1 logged into UPS [TrippLite]

dennypage

@ghound I don't see any error entries from usbhid-ups suggesting a reason for exit.

Can you run the driver by hand in debug mode via ssh please?

First start the service, and then kill the driver:

killall usbhid-ups

Then, run the driver with debug:

/usr/local/libexec/nut/usbhid-ups -DDDDDD -a TrippLite

And post the output. This may be lengthy, so it's okay to eliminate duplicated line in the middle.

ghound

@dennypage said in NUT Package (2.8.1 and above):

Can you run the driver by hand in debug mode via ssh please?

First start the service, and then kill the driver:

killall usbhid-ups
Then, run the driver with debug:

/usr/local/libexec/nut/usbhid-ups -DDDDDD -a TrippLite
And post the output. This may be lengthy, so it's okay to eliminate duplicated line in the middle.

I have the driver running by hand as requested. Output is to the console, should I redirect it to a file or will I be able to capture what you are looking for from console scrollback? Here is one frame of output while the driver seems to be running successfully.

 524.757599	[D5] send_to_all: SETINFO driver.state "updateinfo"
 524.757772	[D6] send_to_all: write 34 bytes to socket 9 succeeded (ret=34): SETINFO driver.state "updateinfo"

 524.757789	[D1] upsdrv_updateinfo...
 524.782403	[D2] file_report_buffer: expected 4 bytes, but got 512 instead
 524.782484	[D3] Report[err]: (512 bytes) => 32 00 00 09 00 00 00 00 f0 9f 6a 80 00 00 00 00
 524.782515	[D3]  00 00 00 00 00 00 00 00 98 ea f4 45 48 49 3a c1 80 a0 6a 80 ff ff ff ff 40
 524.782544	[D3]  9e 6a 80 00 00 00 00 14 b1 b6 83 00 00 00 00 26 06 ee 65 00 00 00 00 00 50
 524.782574	[D3]  27 00 00 00 00 00 00 00 00 00 00 00 00 00 00 60 27 00 00 00 00 00 02 00 00
 524.782603	[D3]  00 00 00 00 00 00 60 27 00 00 00 00 00 41 3c 21 00 00 00 00 00 5c 8d 20 00
 524.782632	[D3]  00 00 00 00 78 9f 6a 80 00 00 00 00 00 02 00 00 00 00 00 00 f0 a1 6a 80 00
 524.782661	[D3]  00 00 00 30 9f 6a 80 00 00 00 00 f0 9e 6a 80 00 00 00 00 d8 ff ff ff 80 ff
 524.782689	[D3]  ff ff 3f 9f 6a 80 00 00 00 00 b8 c3 c2 83 00 00 00 00 9a 9f 6a 80 00 00 00
 524.782719	[D3]  00 00 00 00 00 dd 01 00 00 08 02 ff ff 00 00 00 00 78 9f 6a 80 00 00 00 00
 524.782748	[D3]  ff 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
 524.782777	[D3]  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
 524.782806	[D3]  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
 524.782835	[D3]  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
 524.782863	[D3]  4d 19 bd 83 98 ea f4 45 48 49 3a c1 00 9e 6a 80 00 00 00 00 cc 63 b7 83 00
 524.782893	[D3]  00 00 00 00 00 00 00 00 00 00 00 00 60 27 00 00 00 00 00 02 00 00 00 00 00
 524.782922	[D3]  00 00 00 70 27 00 00 00 00 00 41 3c 21 00 00 00 00 00 0d 00 00 00 00 00 00
 524.782951	[D3]  00 0d 00 00 00 00 00 00 00 68 9e 6a 80 00 00 00 00 26 06 ee 65 00 00 00 00
 524.782979	[D3]  2d ee 9c 21 5f d5 5e 68 00 00 00 00 00 00 00 00 98 ea f4 45 48 49 3a c1 30
 524.783008	[D3]  9e 6a 80 00 00 00 00 9c 5f b7 83 00 00 00 00 0d 00 00 00 00 00 00 00 00 00
 524.783037	[D3]  00 00 00 00 00 00 68 9e 6a 80 00 00 00 00 a0 9e 6a 80 00 00 00 00 80 9e 6a
 524.783063	[D3]  80 00 00 00 00 8c 61 b0 83 00 00 00 00 5c 8d 20 00 00 00 00 00
 524.783737	[D1] Got 9 HID objects...
 524.783796	[D3] Report[buf]: (4 bytes) => 32 00 00 09
 524.783812	[D5] PhyMax = 0, PhyMin = 0, LogMax = 1, LogMin = 0
 524.783826	[D5] Unit = 00000000, UnitExp = 0
 524.783838	[D5] Exponent = 0
 524.783854	[D5] hid_lookup_path: 00840004 -> UPS
 524.783870	[D5] hid_lookup_path: 00840024 -> PowerSummary
 524.783884	[D5] hid_lookup_path: 00840002 -> PresentStatus
 524.783898	[D5] hid_lookup_path: 00840062 -> InternalFailure
 524.783915	[D2] Path: UPS.PowerSummary.PresentStatus.InternalFailure, Type: Input, ReportID: 0x32, Offset: 7, Size: 1, Value: 0
 524.784119	[D5] hu_find_infoval: found !commfault (value: 0)
 524.784149	[D5] process_boolean_info: !commfault
 524.784179	[D3] Report[buf]: (4 bytes) => 32 00 00 09
 524.784195	[D5] PhyMax = 0, PhyMin = 0, LogMax = 1, LogMin = 0
 524.784207	[D5] Unit = 00000000, UnitExp = 0
 524.784219	[D5] Exponent = 0
 524.784233	[D5] hid_lookup_path: 00840004 -> UPS
 524.784247	[D5] hid_lookup_path: 00840024 -> PowerSummary
 524.784261	[D5] hid_lookup_path: 00840002 -> PresentStatus
 524.784275	[D5] hid_lookup_path: 00840069 -> ShutdownImminent
 524.784291	[D2] Path: UPS.PowerSummary.PresentStatus.ShutdownImminent, Type: Input, ReportID: 0x32, Offset: 9, Size: 1, Value: 0
 524.784307	[D5] hu_find_infoval: found !shutdownimm (value: 0)
 524.784336	[D5] process_boolean_info: !shutdownimm
 524.784357	[D3] Report[buf]: (4 bytes) => 32 00 00 09
 524.784371	[D5] PhyMax = 0, PhyMin = 0, LogMax = 1, LogMin = 0
 524.784383	[D5] Unit = 00000000, UnitExp = 0
 524.784394	[D5] Exponent = 0
 524.784407	[D5] hid_lookup_path: 00840004 -> UPS
 524.784421	[D5] hid_lookup_path: 00840024 -> PowerSummary
 524.784434	[D5] hid_lookup_path: 00840002 -> PresentStatus
 524.784449	[D5] hid_lookup_path: 008500d0 -> ACPresent
 524.784465	[D2] Path: UPS.PowerSummary.PresentStatus.ACPresent, Type: Input, ReportID: 0x32, Offset: 16, Size: 1, Value: 1
 524.785177	[D5] hu_find_infoval: found online (value: 1)
 524.785224	[D5] process_boolean_info: online
 524.785252	[D3] Report[buf]: (4 bytes) => 32 00 00 09
 524.785268	[D5] PhyMax = 0, PhyMin = 0, LogMax = 1, LogMin = 0
 524.785282	[D5] Unit = 00000000, UnitExp = 0
 524.785294	[D5] Exponent = 0
 524.785309	[D5] hid_lookup_path: 00840004 -> UPS
 524.785335	[D5] hid_lookup_path: 00840024 -> PowerSummary
 524.785350	[D5] hid_lookup_path: 00840002 -> PresentStatus
 524.785365	[D5] hid_lookup_path: 00850042 -> BelowRemainingCapacityLimit
 524.785381	[D2] Path: UPS.PowerSummary.PresentStatus.BelowRemainingCapacityLimit, Type: Input, ReportID: 0x32, Offset: 18, Size: 1, Value: 0
 524.785399	[D5] hu_find_infoval: found !lowbatt (value: 0)
 524.785412	[D5] process_boolean_info: !lowbatt
 524.785433	[D3] Report[buf]: (4 bytes) => 32 00 00 09
 524.785446	[D5] PhyMax = 0, PhyMin = 0, LogMax = 1, LogMin = 0
 524.785459	[D5] Unit = 00000000, UnitExp = 0
 524.785470	[D5] Exponent = 0
 524.785482	[D5] hid_lookup_path: 00840004 -> UPS
 524.785496	[D5] hid_lookup_path: 00840024 -> PowerSummary
 524.785509	[D5] hid_lookup_path: 00840002 -> PresentStatus
 524.785524	[D5] hid_lookup_path: 00850046 -> FullyCharged
 524.785539	[D2] Path: UPS.PowerSummary.PresentStatus.FullyCharged, Type: Input, ReportID: 0x32, Offset: 19, Size: 1, Value: 1
 524.785556	[D5] hu_find_infoval: found fullycharged (value: 1)
 524.785568	[D5] process_boolean_info: fullycharged
 524.785591	[D3] Report[buf]: (4 bytes) => 32 00 00 09
 524.785604	[D5] PhyMax = 0, PhyMin = 0, LogMax = 1, LogMin = 0
 524.785616	[D5] Unit = 00000000, UnitExp = 0
 524.785627	[D5] Exponent = 0
 524.785640	[D5] hid_lookup_path: 00840004 -> UPS
 524.785653	[D5] hid_lookup_path: 00840024 -> PowerSummary
 524.785666	[D5] hid_lookup_path: 00840002 -> PresentStatus
 524.785681	[D5] hid_lookup_path: 00850044 -> Charging
 524.785695	[D2] Path: UPS.PowerSummary.PresentStatus.Charging, Type: Input, ReportID: 0x32, Offset: 20, Size: 1, Value: 0
 524.785711	[D5] hu_find_infoval: found !chrg (value: 0)
 524.785723	[D5] process_boolean_info: !chrg
 524.785740	[D3] Report[buf]: (4 bytes) => 32 00 00 09
 524.785754	[D5] PhyMax = 0, PhyMin = 0, LogMax = 1, LogMin = 0
 524.785766	[D5] Unit = 00000000, UnitExp = 0
 524.785777	[D5] Exponent = 0
 524.785789	[D5] hid_lookup_path: 00840004 -> UPS
 524.785802	[D5] hid_lookup_path: 00840024 -> PowerSummary
 524.785816	[D5] hid_lookup_path: 00840002 -> PresentStatus
 524.785830	[D5] hid_lookup_path: 00850045 -> Discharging
 524.785845	[D2] Path: UPS.PowerSummary.PresentStatus.Discharging, Type: Input, ReportID: 0x32, Offset: 21, Size: 1, Value: 0
 524.785861	[D5] hu_find_infoval: found !dischrg (value: 0)
 524.785872	[D5] process_boolean_info: !dischrg
 524.785891	[D3] Report[buf]: (4 bytes) => 32 00 00 09
 524.785904	[D5] PhyMax = 0, PhyMin = 0, LogMax = 1, LogMin = 0
 524.785916	[D5] Unit = 00000000, UnitExp = 0
 524.785928	[D5] Exponent = 0
 524.785940	[D5] hid_lookup_path: 00840004 -> UPS
 524.785953	[D5] hid_lookup_path: 00840024 -> PowerSummary
 524.785967	[D5] hid_lookup_path: 00840002 -> PresentStatus
 524.785981	[D5] hid_lookup_path: 00850047 -> FullyDischarged
 524.785996	[D2] Path: UPS.PowerSummary.PresentStatus.FullyDischarged, Type: Input, ReportID: 0x32, Offset: 22, Size: 1, Value: 0
 524.786011	[D5] hu_find_infoval: found !depleted (value: 0)
 524.786023	[D5] process_boolean_info: !depleted
 524.786044	[D3] Report[buf]: (4 bytes) => 32 00 00 09
 524.786058	[D5] PhyMax = 0, PhyMin = 0, LogMax = 1, LogMin = 0
 524.786070	[D5] Unit = 00000000, UnitExp = 0
 524.786082	[D5] Exponent = 0
 524.786094	[D5] hid_lookup_path: 00840004 -> UPS
 524.786107	[D5] hid_lookup_path: 00840024 -> PowerSummary
 524.786120	[D5] hid_lookup_path: 00840002 -> PresentStatus
 524.786134	[D5] hid_lookup_path: 0085004b -> NeedReplacement
 524.786149	[D2] Path: UPS.PowerSummary.PresentStatus.NeedReplacement, Type: Input, ReportID: 0x32, Offset: 23, Size: 1, Value: 0
 524.786165	[D5] hu_find_infoval: found !replacebatt (value: 0)
 524.786176	[D5] process_boolean_info: !replacebatt
 524.786195	[D1] Quick update...
 524.786210	[D4] Entering libusb_get_report
 524.787372	[D3] Report[get]: (3 bytes) => 61 ff ff
 524.787461	[D5] PhyMax = 0, PhyMin = 0, LogMax = 65535, LogMin = 0
 524.787478	[D5] Unit = 00001001, UnitExp = 0
 524.787491	[D5] Exponent = 0
 524.787508	[D2] Path: UPS.OutletSystem.Outlet.DelayBeforeStartup, Type: Feature, ReportID: 0x61, Offset: 0, Size: 16, Value: 65535
 524.787540	[D4] Entering libusb_get_report
 524.788372	[D3] Report[get]: (3 bytes) => 15 ff ff
 524.788461	[D5] PhyMax = 0, PhyMin = 0, LogMax = 65535, LogMin = 0
 524.788485	[D5] Unit = 00001001, UnitExp = 0
 524.788507	[D5] Exponent = 0
 524.788537	[D2] Path: UPS.OutletSystem.Outlet.DelayBeforeShutdown, Type: Feature, ReportID: 0x15, Offset: 0, Size: 16, Value: 65535
 524.788580	[D4] Entering libusb_get_report
 524.789535	[D3] Report[get]: (3 bytes) => 17 ff ff
 524.789623	[D5] PhyMax = 0, PhyMin = 0, LogMax = 65535, LogMin = 0
 524.789639	[D5] Unit = 00001001, UnitExp = 0
 524.789651	[D5] Exponent = 0
 524.789669	[D2] Path: UPS.OutletSystem.Outlet.DelayBeforeReboot, Type: Feature, ReportID: 0x17, Offset: 0, Size: 16, Value: 65535
 524.789869	[D3] Report[buf]: (4 bytes) => 32 00 00 09
 524.789896	[D5] PhyMax = 0, PhyMin = 0, LogMax = 1, LogMin = 0
 524.789910	[D5] Unit = 00000000, UnitExp = 0
 524.789922	[D5] Exponent = 0
 524.789938	[D2] Path: UPS.PowerSummary.PresentStatus.ACPresent, Type: Feature, ReportID: 0x32, Offset: 16, Size: 1, Value: 1
 524.789952	[D5] hu_find_infoval: found online (value: 1)
 524.789965	[D5] process_boolean_info: online
 524.789984	[D3] Report[buf]: (4 bytes) => 32 00 00 09
 524.789998	[D5] PhyMax = 0, PhyMin = 0, LogMax = 1, LogMin = 0
 524.790010	[D5] Unit = 00000000, UnitExp = 0
 524.790021	[D5] Exponent = 0
 524.790036	[D2] Path: UPS.PowerSummary.PresentStatus.BelowRemainingCapacityLimit, Type: Feature, ReportID: 0x32, Offset: 18, Size: 1, Value: 0
 524.790049	[D5] hu_find_infoval: found !lowbatt (value: 0)
 524.790061	[D5] process_boolean_info: !lowbatt
 524.790079	[D3] Report[buf]: (4 bytes) => 32 00 00 09
 524.790092	[D5] PhyMax = 0, PhyMin = 0, LogMax = 1, LogMin = 0
 524.790104	[D5] Unit = 00000000, UnitExp = 0
 524.790115	[D5] Exponent = 0
 524.790130	[D2] Path: UPS.PowerSummary.PresentStatus.FullyCharged, Type: Feature, ReportID: 0x32, Offset: 19, Size: 1, Value: 1
 524.790142	[D5] hu_find_infoval: found fullycharged (value: 1)
 524.790154	[D5] process_boolean_info: fullycharged
 524.790175	[D3] Report[buf]: (4 bytes) => 32 00 00 09
 524.790189	[D5] PhyMax = 0, PhyMin = 0, LogMax = 1, LogMin = 0
 524.790201	[D5] Unit = 00000000, UnitExp = 0
 524.790212	[D5] Exponent = 0
 524.790226	[D2] Path: UPS.PowerSummary.PresentStatus.Charging, Type: Feature, ReportID: 0x32, Offset: 20, Size: 1, Value: 0
 524.790832	[D5] hu_find_infoval: found !chrg (value: 0)
 524.790875	[D5] process_boolean_info: !chrg
 524.790903	[D3] Report[buf]: (4 bytes) => 32 00 00 09
 524.790919	[D5] PhyMax = 0, PhyMin = 0, LogMax = 1, LogMin = 0
 524.790932	[D5] Unit = 00000000, UnitExp = 0
 524.790945	[D5] Exponent = 0
 524.790960	[D2] Path: UPS.PowerSummary.PresentStatus.Discharging, Type: Feature, ReportID: 0x32, Offset: 21, Size: 1, Value: 0
 524.790973	[D5] hu_find_infoval: found !dischrg (value: 0)
 524.790984	[D5] process_boolean_info: !dischrg
 524.791002	[D3] Report[buf]: (4 bytes) => 32 00 00 09
 524.791015	[D5] PhyMax = 0, PhyMin = 0, LogMax = 1, LogMin = 0
 524.791027	[D5] Unit = 00000000, UnitExp = 0
 524.791038	[D5] Exponent = 0
 524.791053	[D2] Path: UPS.PowerSummary.PresentStatus.FullyDischarged, Type: Feature, ReportID: 0x32, Offset: 22, Size: 1, Value: 0
 524.791066	[D5] hu_find_infoval: found !depleted (value: 0)
 524.791077	[D5] process_boolean_info: !depleted
 524.791151	[D5] send_to_all: SETINFO driver.state "quiet"
 524.791401	[D6] send_to_all: write 29 bytes to socket 9 succeeded (ret=29): SETINFO driver.state "quiet"

dennypage

@ghound said in NUT Package (2.8.1 and above):

Output is to the console, should I redirect it to a file or will I be able to capture what you are looking for from console scrollback?

I expect that you will want to direct it to a file so you don't loose it due to scrolling or other issues.

ghound

@dennypage said in NUT Package (2.8.1 and above):

Can you run the driver by hand in debug mode via ssh please?

First start the service, and then kill the driver:

killall usbhid-ups
Then, run the driver with debug:

/usr/local/libexec/nut/usbhid-ups -DDDDDD -a TrippLite

This is the result around the point when connection to the UPS was lost (around one day after the process was started):

72245.572443	[D1] upsdrv_updateinfo...
72245.599003	[D2] file_report_buffer: expected 4 bytes, but got 512 instead
72245.599080	[D3] Report[err]: (512 bytes) => 32 00 00 09 00 00 00 00 f0 9f 6a 80 00 00 00 00
72245.599112	[D3]  00 00 00 00 00 00 00 00 98 ea f4 45 48 49 3a c1 80 a0 6a 80 ff ff ff ff 40
72245.599141	[D3]  9e 6a 80 00 00 00 00 14 b1 b6 83 00 00 00 00 4f 1e ef 65 00 00 00 00 00 50
72245.599171	[D3]  27 00 00 00 00 00 00 00 00 00 00 00 00 00 00 60 27 00 00 00 00 00 02 00 00
72245.599201	[D3]  00 00 00 00 00 00 60 27 00 00 00 00 00 41 3c 21 00 00 00 00 00 5c 8d 20 00
72245.599230	[D3]  00 00 00 00 78 9f 6a 80 00 00 00 00 00 02 00 00 00 00 00 00 f0 a1 6a 80 00
72245.599259	[D3]  00 00 00 30 9f 6a 80 00 00 00 00 f0 9e 6a 80 00 00 00 00 d8 ff ff ff 80 ff
72245.599288	[D3]  ff ff 3f 9f 6a 80 00 00 00 00 b8 c3 c2 83 00 00 00 00 9a 9f 6a 80 00 00 00
72245.599317	[D3]  00 00 00 00 00 dd 01 00 00 08 02 ff ff 00 00 00 00 78 9f 6a 80 00 00 00 00
72245.599346	[D3]  ff 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
72245.599414	[D3]  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
72245.599446	[D3]  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
72245.599476	[D3]  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
72245.599504	[D3]  52 25 8a 3f 98 ea f4 45 48 49 3a c1 00 9e 6a 80 00 00 00 00 cc 63 b7 83 00
72245.599533	[D3]  00 00 00 00 00 00 00 00 00 00 00 00 60 27 00 00 00 00 00 02 00 00 00 00 00
72245.599562	[D3]  00 00 00 70 27 00 00 00 00 00 41 3c 21 00 00 00 00 00 0d 00 00 00 00 00 00
72245.599591	[D3]  00 0d 00 00 00 00 00 00 00 68 9e 6a 80 00 00 00 00 4f 1e ef 65 00 00 00 00
72245.599620	[D3]  f9 65 6b 7b 2f e6 eb 38 00 00 00 00 00 00 00 00 98 ea f4 45 48 49 3a c1 30
72245.599649	[D3]  9e 6a 80 00 00 00 00 9c 5f b7 83 00 00 00 00 0d 00 00 00 00 00 00 00 00 00
72245.599678	[D3]  00 00 00 00 00 00 68 9e 6a 80 00 00 00 00 a0 9e 6a 80 00 00 00 00 80 9e 6a
72245.599704	[D3]  80 00 00 00 00 8c 61 b0 83 00 00 00 00 5c 8d 20 00 00 00 00 00
72245.599732	[D1] Got 9 HID objects...
72245.599752	[D3] Report[buf]: (4 bytes) => 32 00 00 09
72245.599768	[D5] PhyMax = 0, PhyMin = 0, LogMax = 1, LogMin = 0
72245.599781	[D5] Unit = 00000000, UnitExp = 0
72245.599793	[D5] Exponent = 0
72245.599808	[D5] hid_lookup_path: 00840004 -> UPS
72245.599823	[D5] hid_lookup_path: 00840024 -> PowerSummary
72245.599837	[D5] hid_lookup_path: 00840002 -> PresentStatus
72245.599850	[D5] hid_lookup_path: 00840062 -> InternalFailure
72245.599866	[D2] Path: UPS.PowerSummary.PresentStatus.InternalFailure, Type: Input, ReportID: 0x32, Offset: 7, Size: 1, Value: 0
72245.599884	[D5] hu_find_infoval: found !commfault (value: 0)
72245.599897	[D5] process_boolean_info: !commfault
72245.599924	[D3] Report[buf]: (4 bytes) => 32 00 00 09
72245.599938	[D5] PhyMax = 0, PhyMin = 0, LogMax = 1, LogMin = 0
72245.599950	[D5] Unit = 00000000, UnitExp = 0
72245.599961	[D5] Exponent = 0
72245.599973	[D5] hid_lookup_path: 00840004 -> UPS
72245.599986	[D5] hid_lookup_path: 00840024 -> PowerSummary
72245.600000	[D5] hid_lookup_path: 00840002 -> PresentStatus
72245.600013	[D5] hid_lookup_path: 00840069 -> ShutdownImminent
72245.600028	[D2] Path: UPS.PowerSummary.PresentStatus.ShutdownImminent, Type: Input, ReportID: 0x32, Offset: 9, Size: 1, Value: 0
72245.600044	[D5] hu_find_infoval: found !shutdownimm (value: 0)
72245.600056	[D5] process_boolean_info: !shutdownimm
72245.600076	[D3] Report[buf]: (4 bytes) => 32 00 00 09
72245.600089	[D5] PhyMax = 0, PhyMin = 0, LogMax = 1, LogMin = 0
72245.600101	[D5] Unit = 00000000, UnitExp = 0
72245.600112	[D5] Exponent = 0
72245.600124	[D5] hid_lookup_path: 00840004 -> UPS
72245.600138	[D5] hid_lookup_path: 00840024 -> PowerSummary
72245.600151	[D5] hid_lookup_path: 00840002 -> PresentStatus
72245.600167	[D5] hid_lookup_path: 008500d0 -> ACPresent
72245.600183	[D2] Path: UPS.PowerSummary.PresentStatus.ACPresent, Type: Input, ReportID: 0x32, Offset: 16, Size: 1, Value: 1
72245.600197	[D5] hu_find_infoval: found online (value: 1)
72245.600209	[D5] process_boolean_info: online
72245.600227	[D3] Report[buf]: (4 bytes) => 32 00 00 09
72245.600240	[D5] PhyMax = 0, PhyMin = 0, LogMax = 1, LogMin = 0
72245.600252	[D5] Unit = 00000000, UnitExp = 0
72245.600263	[D5] Exponent = 0
72245.600275	[D5] hid_lookup_path: 00840004 -> UPS
72245.600288	[D5] hid_lookup_path: 00840024 -> PowerSummary
72245.600301	[D5] hid_lookup_path: 00840002 -> PresentStatus
72245.600315	[D5] hid_lookup_path: 00850042 -> BelowRemainingCapacityLimit
72245.600330	[D2] Path: UPS.PowerSummary.PresentStatus.BelowRemainingCapacityLimit, Type: Input, ReportID: 0x32, Offset: 18, Size: 1, Value: 0
72245.600345	[D5] hu_find_infoval: found !lowbatt (value: 0)
72245.600356	[D5] process_boolean_info: !lowbatt
72245.600374	[D3] Report[buf]: (4 bytes) => 32 00 00 09
72245.600394	[D5] PhyMax = 0, PhyMin = 0, LogMax = 1, LogMin = 0
72245.600407	[D5] Unit = 00000000, UnitExp = 0
72245.600418	[D5] Exponent = 0
72245.600430	[D5] hid_lookup_path: 00840004 -> UPS
72245.600444	[D5] hid_lookup_path: 00840024 -> PowerSummary
72245.600457	[D5] hid_lookup_path: 00840002 -> PresentStatus
72245.600470	[D5] hid_lookup_path: 00850046 -> FullyCharged
72245.600486	[D2] Path: UPS.PowerSummary.PresentStatus.FullyCharged, Type: Input, ReportID: 0x32, Offset: 19, Size: 1, Value: 1
72245.600501	[D5] hu_find_infoval: found fullycharged (value: 1)
72245.600513	[D5] process_boolean_info: fullycharged
72245.600535	[D3] Report[buf]: (4 bytes) => 32 00 00 09
72245.600548	[D5] PhyMax = 0, PhyMin = 0, LogMax = 1, LogMin = 0
72245.600560	[D5] Unit = 00000000, UnitExp = 0
72245.600571	[D5] Exponent = 0
72245.600583	[D5] hid_lookup_path: 00840004 -> UPS
72245.600596	[D5] hid_lookup_path: 00840024 -> PowerSummary
72245.600609	[D5] hid_lookup_path: 00840002 -> PresentStatus
72245.600623	[D5] hid_lookup_path: 00850044 -> Charging
72245.600637	[D2] Path: UPS.PowerSummary.PresentStatus.Charging, Type: Input, ReportID: 0x32, Offset: 20, Size: 1, Value: 0
72245.600652	[D5] hu_find_infoval: found !chrg (value: 0)
72245.600664	[D5] process_boolean_info: !chrg
72245.600682	[D3] Report[buf]: (4 bytes) => 32 00 00 09
72245.600695	[D5] PhyMax = 0, PhyMin = 0, LogMax = 1, LogMin = 0
72245.600707	[D5] Unit = 00000000, UnitExp = 0
72245.600718	[D5] Exponent = 0
72245.600730	[D5] hid_lookup_path: 00840004 -> UPS
72245.600744	[D5] hid_lookup_path: 00840024 -> PowerSummary
72245.600757	[D5] hid_lookup_path: 00840002 -> PresentStatus
72245.600770	[D5] hid_lookup_path: 00850045 -> Discharging
72245.600785	[D2] Path: UPS.PowerSummary.PresentStatus.Discharging, Type: Input, ReportID: 0x32, Offset: 21, Size: 1, Value: 0
72245.600800	[D5] hu_find_infoval: found !dischrg (value: 0)
72245.600811	[D5] process_boolean_info: !dischrg
72245.600829	[D3] Report[buf]: (4 bytes) => 32 00 00 09
72245.600842	[D5] PhyMax = 0, PhyMin = 0, LogMax = 1, LogMin = 0
72245.600854	[D5] Unit = 00000000, UnitExp = 0
72245.600865	[D5] Exponent = 0
72245.600877	[D5] hid_lookup_path: 00840004 -> UPS
72245.600890	[D5] hid_lookup_path: 00840024 -> PowerSummary
72245.600903	[D5] hid_lookup_path: 00840002 -> PresentStatus
72245.600917	[D5] hid_lookup_path: 00850047 -> FullyDischarged
72245.600931	[D2] Path: UPS.PowerSummary.PresentStatus.FullyDischarged, Type: Input, ReportID: 0x32, Offset: 22, Size: 1, Value: 0
72245.600946	[D5] hu_find_infoval: found !depleted (value: 0)
72245.600958	[D5] process_boolean_info: !depleted
72245.600979	[D3] Report[buf]: (4 bytes) => 32 00 00 09
72245.600993	[D5] PhyMax = 0, PhyMin = 0, LogMax = 1, LogMin = 0
72245.601005	[D5] Unit = 00000000, UnitExp = 0
72245.601017	[D5] Exponent = 0
72245.601029	[D5] hid_lookup_path: 00840004 -> UPS
72245.601042	[D5] hid_lookup_path: 00840024 -> PowerSummary
72245.601055	[D5] hid_lookup_path: 00840002 -> PresentStatus
72245.601069	[D5] hid_lookup_path: 0085004b -> NeedReplacement
72245.601084	[D2] Path: UPS.PowerSummary.PresentStatus.NeedReplacement, Type: Input, ReportID: 0x32, Offset: 23, Size: 1, Value: 0
72245.601099	[D5] hu_find_infoval: found !replacebatt (value: 0)
72245.601111	[D5] process_boolean_info: !replacebatt
72245.601129	[D1] Quick update...
72245.601144	[D4] Entering libusb_get_report
72245.601911	[D3] Report[get]: (3 bytes) => 61 ff ff
72245.601975	[D5] PhyMax = 0, PhyMin = 0, LogMax = 65535, LogMin = 0
72245.601991	[D5] Unit = 00001001, UnitExp = 0
72245.602004	[D5] Exponent = 0
72245.602021	[D2] Path: UPS.OutletSystem.Outlet.DelayBeforeStartup, Type: Feature, ReportID: 0x61, Offset: 0, Size: 16, Value: 65535
72245.602051	[D4] Entering libusb_get_report
72245.602892	[D3] Report[get]: (3 bytes) => 15 ff ff
72245.602944	[D5] PhyMax = 0, PhyMin = 0, LogMax = 65535, LogMin = 0
72245.602958	[D5] Unit = 00001001, UnitExp = 0
72245.602972	[D5] Exponent = 0
72245.602988	[D2] Path: UPS.OutletSystem.Outlet.DelayBeforeShutdown, Type: Feature, ReportID: 0x15, Offset: 0, Size: 16, Value: 65535
72245.603016	[D4] Entering libusb_get_report
72245.603890	[D3] Report[get]: (3 bytes) => 17 ff ff
72245.603934	[D5] PhyMax = 0, PhyMin = 0, LogMax = 65535, LogMin = 0
72245.603948	[D5] Unit = 00001001, UnitExp = 0
72245.603961	[D5] Exponent = 0
72245.603978	[D2] Path: UPS.OutletSystem.Outlet.DelayBeforeReboot, Type: Feature, ReportID: 0x17, Offset: 0, Size: 16, Value: 65535
72245.604013	[D3] Report[buf]: (4 bytes) => 32 00 00 09
72245.604027	[D5] PhyMax = 0, PhyMin = 0, LogMax = 1, LogMin = 0
72245.604040	[D5] Unit = 00000000, UnitExp = 0
72245.604051	[D5] Exponent = 0
72245.604067	[D2] Path: UPS.PowerSummary.PresentStatus.ACPresent, Type: Feature, ReportID: 0x32, Offset: 16, Size: 1, Value: 1
72245.604080	[D5] hu_find_infoval: found online (value: 1)
72245.604092	[D5] process_boolean_info: online
72245.604111	[D3] Report[buf]: (4 bytes) => 32 00 00 09
72245.604124	[D5] PhyMax = 0, PhyMin = 0, LogMax = 1, LogMin = 0
72245.604136	[D5] Unit = 00000000, UnitExp = 0
72245.604148	[D5] Exponent = 0
72245.604162	[D2] Path: UPS.PowerSummary.PresentStatus.BelowRemainingCapacityLimit, Type: Feature, ReportID: 0x32, Offset: 18, Size: 1, Value: 0
72245.604175	[D5] hu_find_infoval: found !lowbatt (value: 0)
72245.604187	[D5] process_boolean_info: !lowbatt
72245.604205	[D3] Report[buf]: (4 bytes) => 32 00 00 09
72245.604218	[D5] PhyMax = 0, PhyMin = 0, LogMax = 1, LogMin = 0
72245.604230	[D5] Unit = 00000000, UnitExp = 0
72245.604241	[D5] Exponent = 0
72245.604256	[D2] Path: UPS.PowerSummary.PresentStatus.FullyCharged, Type: Feature, ReportID: 0x32, Offset: 19, Size: 1, Value: 1
72245.604268	[D5] hu_find_infoval: found fullycharged (value: 1)
72245.604280	[D5] process_boolean_info: fullycharged
72245.604302	[D3] Report[buf]: (4 bytes) => 32 00 00 09
72245.604315	[D5] PhyMax = 0, PhyMin = 0, LogMax = 1, LogMin = 0
72245.604327	[D5] Unit = 00000000, UnitExp = 0
72245.604339	[D5] Exponent = 0
72245.604353	[D2] Path: UPS.PowerSummary.PresentStatus.Charging, Type: Feature, ReportID: 0x32, Offset: 20, Size: 1, Value: 0
72245.604366	[D5] hu_find_infoval: found !chrg (value: 0)
72245.604392	[D5] process_boolean_info: !chrg
72245.604409	[D3] Report[buf]: (4 bytes) => 32 00 00 09
72245.604423	[D5] PhyMax = 0, PhyMin = 0, LogMax = 1, LogMin = 0
72245.604435	[D5] Unit = 00000000, UnitExp = 0
72245.604446	[D5] Exponent = 0
72245.604460	[D2] Path: UPS.PowerSummary.PresentStatus.Discharging, Type: Feature, ReportID: 0x32, Offset: 21, Size: 1, Value: 0
72245.604473	[D5] hu_find_infoval: found !dischrg (value: 0)
72245.604484	[D5] process_boolean_info: !dischrg
72245.604502	[D3] Report[buf]: (4 bytes) => 32 00 00 09
72245.604515	[D5] PhyMax = 0, PhyMin = 0, LogMax = 1, LogMin = 0
72245.604527	[D5] Unit = 00000000, UnitExp = 0
72245.604538	[D5] Exponent = 0
72245.604552	[D2] Path: UPS.PowerSummary.PresentStatus.FullyDischarged, Type: Feature, ReportID: 0x32, Offset: 22, Size: 1, Value: 0
72245.604565	[D5] hu_find_infoval: found !depleted (value: 0)
72245.604576	[D5] process_boolean_info: !depleted
72245.604640	[D5] send_to_all: SETINFO driver.state "quiet"
72245.604783	[D6] send_to_all: write 29 bytes to socket 9 succeeded (ret=29): SETINFO driver.state "quiet"

72247.581943	[D5] send_to_all: SETINFO driver.state "updateinfo"
72247.582155	[D6] send_to_all: write 34 bytes to socket 9 succeeded (ret=34): SETINFO driver.state "updateinfo"

72247.582177	[D1] upsdrv_updateinfo...
72247.647068	[D2] file_report_buffer: expected 2 bytes, but got 512 instead
72247.647148	[D3] Report[err]: (512 bytes) => 34 64 00 00 00 00 00 00 f0 9f 6a 80 00 00 00 00
72247.647180	[D3]  00 00 00 00 00 00 00 00 98 ea f4 45 48 49 3a c1 80 a0 6a 80 ff ff ff ff 40
72247.647210	[D3]  9e 6a 80 00 00 00 00 14 b1 b6 83 00 00 00 00 51 1e ef 65 00 00 00 00 00 50
72247.647239	[D3]  27 00 00 00 00 00 00 00 00 00 00 00 00 00 00 60 27 00 00 00 00 00 02 00 00
72247.647268	[D3]  00 00 00 00 00 00 60 27 00 00 00 00 00 41 3c 21 00 00 00 00 00 5c 8d 20 00
72247.647297	[D3]  00 00 00 00 78 9f 6a 80 00 00 00 00 00 02 00 00 00 00 00 00 f0 a1 6a 80 00
72247.647326	[D3]  00 00 00 30 9f 6a 80 00 00 00 00 f0 9e 6a 80 00 00 00 00 d8 ff ff ff 80 ff
72247.647355	[D3]  ff ff 3f 9f 6a 80 00 00 00 00 b8 c3 c2 83 00 00 00 00 9a 9f 6a 80 00 00 00
72247.647388	[D3]  00 00 00 00 00 dd 01 00 00 08 02 ff ff 00 00 00 00 78 9f 6a 80 00 00 00 00
72247.647418	[D3]  ff 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
72247.647448	[D3]  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
72247.647477	[D3]  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
72247.647506	[D3]  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
72247.647534	[D3]  3f 78 09 41 98 ea f4 45 48 49 3a c1 00 9e 6a 80 00 00 00 00 cc 63 b7 83 00
72247.647564	[D3]  00 00 00 00 00 00 00 00 00 00 00 00 60 27 00 00 00 00 00 02 00 00 00 00 00
72247.647593	[D3]  00 00 00 70 27 00 00 00 00 00 41 3c 21 00 00 00 00 00 0d 00 00 00 00 00 00
72247.647622	[D3]  00 0d 00 00 00 00 00 00 00 68 9e 6a 80 00 00 00 00 51 1e ef 65 00 00 00 00
72247.647653	[D3]  93 e8 dc 78 a4 e7 69 3b 00 00 00 00 00 00 00 00 98 ea f4 45 48 49 3a c1 30
72247.647682	[D3]  9e 6a 80 00 00 00 00 9c 5f b7 83 00 00 00 00 0d 00 00 00 00 00 00 00 00 00
72247.647710	[D3]  00 00 00 00 00 00 68 9e 6a 80 00 00 00 00 a0 9e 6a 80 00 00 00 00 80 9e 6a
72247.647737	[D3]  80 00 00 00 00 8c 61 b0 83 00 00 00 00 5c 8d 20 00 00 00 00 00
72247.647764	[D1] Got 1 HID objects...
72247.647781	[D3] Report[buf]: (2 bytes) => 34 64
72247.647797	[D5] PhyMax = 0, PhyMin = 0, LogMax = 255, LogMin = 0
72247.647810	[D5] Unit = 00000000, UnitExp = 0
72247.647822	[D5] Exponent = 0
72247.647837	[D5] hid_lookup_path: 00840004 -> UPS
72247.647852	[D5] hid_lookup_path: 00840024 -> PowerSummary
72247.647867	[D5] hid_lookup_path: 00850066 -> RemainingCapacity
72247.647884	[D2] Path: UPS.PowerSummary.RemainingCapacity, Type: Input, ReportID: 0x34, Offset: 0, Size: 8, Value: 100
72247.647919	[D1] Quick update...
72247.647935	[D4] Entering libusb_get_report
72247.648925	[D3] Report[get]: (3 bytes) => 61 ff ff
72247.648983	[D5] PhyMax = 0, PhyMin = 0, LogMax = 65535, LogMin = 0
72247.649032	[D5] Unit = 00001001, UnitExp = 0
72247.649047	[D5] Exponent = 0
72247.649064	[D2] Path: UPS.OutletSystem.Outlet.DelayBeforeStartup, Type: Feature, ReportID: 0x61, Offset: 0, Size: 16, Value: 65535
72247.649095	[D4] Entering libusb_get_report
72247.649932	[D3] Report[get]: (3 bytes) => 15 ff ff
72247.649995	[D5] PhyMax = 0, PhyMin = 0, LogMax = 65535, LogMin = 0
72247.650010	[D5] Unit = 00001001, UnitExp = 0
72247.650023	[D5] Exponent = 0
72247.650041	[D2] Path: UPS.OutletSystem.Outlet.DelayBeforeShutdown, Type: Feature, ReportID: 0x15, Offset: 0, Size: 16, Value: 65535
72247.650072	[D4] Entering libusb_get_report
72247.727371	nut_libusb_get_report: No device
72247.727469	[D1] Can't retrieve Report 17: Interrupted system call
72247.727532	[D5] send_to_all: SETINFO driver.state "reconnect.trying"
72247.727733	[D6] send_to_all: write 40 bytes to socket 9 succeeded (ret=40): SETINFO driver.state "reconnect.trying"

72247.727777	[D5] send_to_all: SETINFO driver.state "quiet"
72247.727879	[D6] send_to_all: write 29 bytes to socket 9 succeeded (ret=29): SETINFO driver.state "quiet"

72249.583257	[D5] send_to_all: SETINFO driver.state "updateinfo"
72249.583466	[D6] send_to_all: write 34 bytes to socket 9 succeeded (ret=34): SETINFO driver.state "updateinfo"

72249.583501	[D1] upsdrv_updateinfo...
72249.583516	[D1] Got to reconnect!
72249.583543	[D5] send_to_all: SETINFO driver.state "reconnect.trying"
72249.583569	[D6] send_to_all: write 40 bytes to socket 9 succeeded (ret=40): SETINFO driver.state "reconnect.trying"

72249.583596	[D4] Closing comm_driver previous handle
72249.586916	[D4] ===================================================================
72249.586973	[D4]  device has been disconnected, try to reconnect
72249.586987	[D4] ===================================================================
72249.586999	[D4] Opening comm_driver ...
72249.587552	[D2] Checking device 1 of 3 (0000/0000)
72249.587798	[D1] nut_libusb_open: invalid libusb bus number 0
72249.587882	[D2] - VendorID: 0000
72249.587897	[D2] - ProductID: 0000
72249.587910	[D2] - Manufacturer: Generic
72249.587922	[D2] - Product: XHCI root HUB
72249.587934	[D2] - Serial Number: unknown
72249.587946	[D2] - Bus: 000
72249.587957	[D2] - Bus Port: unknown
72249.587968	[D2] - Device: 001
72249.587980	[D2] - Device release number: 0100
72249.587991	[D2] Trying to match device
72249.588013	[D2] match_function_subdriver (non-SHUT mode): matching a device...
72249.588048	[D2] match_function_subdriver (non-SHUT mode): failed to match a subdriver to vendor and/or product ID
72249.588062	[D2] Device does not match - skipping
72249.588150	[D2] Checking device 2 of 3 (0000/0000)
72249.588301	[D1] nut_libusb_open: invalid libusb bus number 0
72249.588361	[D2] - VendorID: 0000
72249.588384	[D2] - ProductID: 0000
72249.588397	[D2] - Manufacturer: Marvell
72249.588409	[D2] - Product: EHCI root HUB
72249.588421	[D2] - Serial Number: unknown
72249.588432	[D2] - Bus: 001
72249.588443	[D2] - Bus Port: unknown
72249.588454	[D2] - Device: 001
72249.588466	[D2] - Device release number: 0100
72249.588477	[D2] Trying to match device
72249.588496	[D2] match_function_subdriver (non-SHUT mode): matching a device...
72249.588525	[D2] match_function_subdriver (non-SHUT mode): failed to match a subdriver to vendor and/or product ID
72249.588539	[D2] Device does not match - skipping
72249.588619	[D2] Checking device 3 of 3 (09AE/3024)
72249.743398	[D1] nut_libusb_open get iManufacturer failed, retrying...
72249.893627	[D1] nut_libusb_open get iManufacturer failed, retrying...
72250.048371	[D1] nut_libusb_open get iManufacturer failed, retrying...
72250.198508	[D1] nut_libusb_open get iProduct failed, retrying...
72250.347839	[D1] nut_libusb_open get iProduct failed, retrying...
72250.499443	[D1] nut_libusb_open get iProduct failed, retrying...
72250.649305	[D1] nut_libusb_open get iSerialNumber failed, retrying...
72250.803444	[D1] nut_libusb_open get iSerialNumber failed, retrying...
72250.955470	[D1] nut_libusb_open get iSerialNumber failed, retrying...
72250.955570	[D2] - VendorID: 09ae
72250.955585	[D2] - ProductID: 3024
72250.955597	[D2] - Manufacturer: unknown
72250.955609	[D2] - Product: unknown
72250.955621	[D2] - Serial Number: unknown
72250.955633	[D2] - Bus: 001
72250.955644	[D2] - Bus Port: 001
72250.955655	[D2] - Device: 002
72250.955667	[D2] - Device release number: 0002
72250.955679	[D2] Trying to match device
72250.955704	[D2] match_function_subdriver (non-SHUT mode): matching a device...
72250.955744	[D3] match_function_regex: matching a device...
72250.955766	[D3] match_function_exact: matching a device...
72250.955782	[D2] match_function_exact: failed match of Vendor: (null) != Tripp Lite
72250.955795	[D2] Device does not match - skipping
72250.955954	[D2] libusb1: No appropriate HID device found
72250.955978	libusb1: Could not open any HID devices: insufficient permissions on everything
72250.955994	[D4] Opening comm_driver returns ret=-1
72250.956021	[D5] send_to_all: SETINFO driver.state "quiet"
72250.956052	[D6] send_to_all: write 29 bytes to socket 9 succeeded (ret=29): SETINFO driver.state "quiet"

72250.956067	[D5] send_to_all: DATASTALE
72250.956086	[D6] send_to_all: write 10 bytes to socket 9 succeeded (ret=10): DATASTALE

72251.588983	[D5] send_to_all: SETINFO driver.state "updateinfo"
72251.589141	[D6] send_to_all: write 34 bytes to socket 9 succeeded (ret=34): SETINFO driver.state "updateinfo"

72251.589165	[D1] upsdrv_updateinfo...
72251.589179	[D1] Got to reconnect!
72251.589201	[D5] send_to_all: SETINFO driver.state "reconnect.trying"
72251.589225	[D6] send_to_all: write 40 bytes to socket 9 succeeded (ret=40): SETINFO driver.state "reconnect.trying"

72251.589247	[D4] Not closing comm_driver previous handle: already closed
72251.589260	[D4] ===================================================================
72251.589272	[D4]  device has been disconnected, try to reconnect
72251.589284	[D4] ===================================================================
72251.589296	[D4] Opening comm_driver ...
72251.589870	[D2] Checking device 1 of 3 (0000/0000)
72251.590057	[D1] nut_libusb_open: invalid libusb bus number 0
72251.590139	[D2] - VendorID: 0000
72251.590154	[D2] - ProductID: 0000
72251.590166	[D2] - Manufacturer: Generic
72251.590178	[D2] - Product: XHCI root HUB
72251.590190	[D2] - Serial Number: unknown
72251.590203	[D2] - Bus: 000
72251.590214	[D2] - Bus Port: unknown
72251.590226	[D2] - Device: 001
72251.590237	[D2] - Device release number: 0100
72251.590249	[D2] Trying to match device
72251.590271	[D2] match_function_subdriver (non-SHUT mode): matching a device...
72251.590307	[D2] match_function_subdriver (non-SHUT mode): failed to match a subdriver to vendor and/or product ID
72251.590322	[D2] Device does not match - skipping
72251.590444	[D2] Checking device 2 of 3 (0000/0000)
72251.590658	[D1] nut_libusb_open: invalid libusb bus number 0
72251.590755	[D2] - VendorID: 0000
72251.590771	[D2] - ProductID: 0000
72251.590785	[D2] - Manufacturer: Marvell
72251.590797	[D2] - Product: EHCI root HUB
72251.590809	[D2] - Serial Number: unknown
72251.590821	[D2] - Bus: 001
72251.590832	[D2] - Bus Port: unknown
72251.590843	[D2] - Device: 001
72251.590855	[D2] - Device release number: 0100
72251.590867	[D2] Trying to match device
72251.590886	[D2] match_function_subdriver (non-SHUT mode): matching a device...
72251.590918	[D2] match_function_subdriver (non-SHUT mode): failed to match a subdriver to vendor and/or product ID
72251.590932	[D2] Device does not match - skipping
72251.591030	[D2] Checking device 3 of 3 (09AE/3024)
72251.745371	[D1] nut_libusb_open get iManufacturer failed, retrying...
72251.895872	[D1] nut_libusb_open get iManufacturer failed, retrying...
72252.050367	[D1] nut_libusb_open get iManufacturer failed, retrying...
72252.205384	[D1] nut_libusb_open get iProduct failed, retrying...
72252.359364	[D1] nut_libusb_open get iProduct failed, retrying...
72252.513419	[D1] nut_libusb_open get iProduct failed, retrying...
72252.667482	[D1] nut_libusb_open get iSerialNumber failed, retrying...
72252.820954	[D1] nut_libusb_open get iSerialNumber failed, retrying...
72252.971389	[D1] nut_libusb_open get iSerialNumber failed, retrying...
72252.971473	[D2] - VendorID: 09ae
72252.971489	[D2] - ProductID: 3024
72252.971501	[D2] - Manufacturer: unknown
72252.971516	[D2] - Product: unknown
72252.971528	[D2] - Serial Number: unknown
72252.971540	[D2] - Bus: 001
72252.971551	[D2] - Bus Port: 001
72252.971563	[D2] - Device: 002
72252.971574	[D2] - Device release number: 0002
72252.971586	[D2] Trying to match device
72252.971609	[D2] match_function_subdriver (non-SHUT mode): matching a device...
72252.971645	[D3] match_function_regex: matching a device...
72252.971663	[D3] match_function_exact: matching a device...
72252.971678	[D2] match_function_exact: failed match of Vendor: (null) != Tripp Lite
72252.971690	[D2] Device does not match - skipping
72252.971846	[D2] libusb1: No appropriate HID device found
72252.971869	libusb1: Could not open any HID devices: insufficient permissions on everything
72252.971885	[D4] Opening comm_driver returns ret=-1
72252.971912	[D5] send_to_all: SETINFO driver.state "quiet"
72252.972008	[D6] send_to_all: write 29 bytes to socket 9 succeeded (ret=29): SETINFO driver.state "quiet"

ghound

@dennypage said in NUT Package (2.8.1 and above):

Can you run the driver by hand in debug mode via ssh please?

First start the service, and then kill the driver:

killall usbhid-ups
Then, run the driver with debug:

/usr/local/libexec/nut/usbhid-ups -DDDDDD -a TrippLite

FYI - this is the output when I tried to manually restart the driver after connection was lost:

   0.002954	[D2] Initializing an USB-connected UPS with library libusb-1.0.0 (API: 0x1000102) (NUT subdriver name='USB communication driver (libusb 1.0)' ver='0.46')
   0.003874	[D2] Checking device 1 of 3 (0000/0000)
   0.004670	[D1] nut_libusb_open: invalid libusb bus number 0
   0.004804	[D2] - VendorID: 0000
   0.004821	[D2] - ProductID: 0000
   0.004833	[D2] - Manufacturer: Generic
   0.004845	[D2] - Product: XHCI root HUB
   0.004856	[D2] - Serial Number: unknown
   0.004868	[D2] - Bus: 000
   0.004878	[D2] - Bus Port: unknown
   0.004889	[D2] - Device: 001
   0.004901	[D2] - Device release number: 0100
   0.004912	[D2] Trying to match device
   0.004934	[D2] match_function_subdriver (non-SHUT mode): matching a device...
   0.004978	[D2] match_function_subdriver (non-SHUT mode): failed to match a subdriver to vendor and/or product ID
   0.004991	[D2] Device does not match - skipping
   0.005115	[D2] Checking device 2 of 3 (0000/0000)
   0.005340	[D1] nut_libusb_open: invalid libusb bus number 0
   0.005432	[D2] - VendorID: 0000
   0.005447	[D2] - ProductID: 0000
   0.005458	[D2] - Manufacturer: Marvell
   0.005470	[D2] - Product: EHCI root HUB
   0.005481	[D2] - Serial Number: unknown
   0.005492	[D2] - Bus: 001
   0.005502	[D2] - Bus Port: unknown
   0.005513	[D2] - Device: 001
   0.005525	[D2] - Device release number: 0100
   0.005535	[D2] Trying to match device
   0.005554	[D2] match_function_subdriver (non-SHUT mode): matching a device...
   0.005596	[D2] match_function_subdriver (non-SHUT mode): failed to match a subdriver to vendor and/or product ID
   0.005610	[D2] Device does not match - skipping
   0.005713	[D2] Checking device 3 of 3 (09AE/3024)
   0.156567	[D1] nut_libusb_open get iManufacturer failed, retrying...
   0.310568	[D1] nut_libusb_open get iManufacturer failed, retrying...
   0.461572	[D1] nut_libusb_open get iManufacturer failed, retrying...
   0.608445	[D1] nut_libusb_open get iProduct failed, retrying...
   0.762543	[D1] nut_libusb_open get iProduct failed, retrying...
   0.912962	[D1] nut_libusb_open get iProduct failed, retrying...
   1.066550	[D1] nut_libusb_open get iSerialNumber failed, retrying...
   1.218542	[D1] nut_libusb_open get iSerialNumber failed, retrying...
   1.369116	[D1] nut_libusb_open get iSerialNumber failed, retrying...
   1.369185	[D2] - VendorID: 09ae
   1.369200	[D2] - ProductID: 3024
   1.369214	[D2] - Manufacturer: unknown
   1.369226	[D2] - Product: unknown
   1.369238	[D2] - Serial Number: unknown
   1.369249	[D2] - Bus: 001
   1.369261	[D2] - Bus Port: 001
   1.369273	[D2] - Device: 002
   1.369285	[D2] - Device release number: 0002
   1.369296	[D2] Trying to match device
   1.369319	[D2] match_function_subdriver (non-SHUT mode): matching a device...
   1.369424	[D3] match_function_regex: matching a device...
   1.369447	[D2] Device matches
   1.369460	[D2] Reading configuration descriptor 1 of 1
   1.369848	[D3] libusb_kernel_driver_active() returned 0: Success
   1.369919	[D2] Claimed interface 0 successfully
   1.369944	[D3] nut_usb_set_altinterface: skipped libusb_set_interface_alt_setting(udev, 0, 0)
   1.446624	[D2] Unable to get HID descriptor (No device)
   1.446696	[D3] HID descriptor length (method 1) -1
   1.446713	[D4] i=0, extra[i]=09, extra[i+1]=21
   1.446736	[D3] HID descriptor, method 2: (9 bytes) => 09 21 11 01 21 01 22 75 03
   1.446775	[D3] HID descriptor length (method 2) 885
   1.446789	[D2] HID descriptor length 885
   1.523598	[D2] Unable to get Report descriptor: Input/output error
   1.523845	[D2] libusb1: No appropriate HID device found
   1.524098	libusb1: Could not open any HID devices: insufficient permissions on everything
   1.524142	No matching HID UPS found
   1.524226	[D5] send_to_all: SETINFO driver.state "cleanup.exit"
   1.524248	upsnotify: failed to notify about state 4: no notification tech defined, will not spam more about it

And this was the initial good manual startup:

0.002990	[D2] Initializing an USB-connected UPS with library libusb-1.0.0 (API: 0x1000102) (NUT subdriver name='USB communication driver (libusb 1.0)' ver='0.46')
   0.003801	[D2] Checking device 1 of 3 (0000/0000)
   0.004569	[D1] nut_libusb_open: invalid libusb bus number 0
   0.004704	[D2] - VendorID: 0000
   0.004723	[D2] - ProductID: 0000
   0.004734	[D2] - Manufacturer: Generic
   0.004745	[D2] - Product: XHCI root HUB
   0.004757	[D2] - Serial Number: unknown
   0.004768	[D2] - Bus: 000
   0.004778	[D2] - Bus Port: unknown
   0.004789	[D2] - Device: 001
   0.004800	[D2] - Device release number: 0100
   0.004810	[D2] Trying to match device
   0.004832	[D2] match_function_subdriver (non-SHUT mode): matching a device...
   0.004876	[D2] match_function_subdriver (non-SHUT mode): failed to match a subdriver to vendor and/or product ID
   0.004888	[D2] Device does not match - skipping
   0.005006	[D2] Checking device 2 of 3 (0000/0000)
   0.005231	[D1] nut_libusb_open: invalid libusb bus number 0
   0.005323	[D2] - VendorID: 0000
   0.005337	[D2] - ProductID: 0000
   0.005349	[D2] - Manufacturer: Marvell
   0.005360	[D2] - Product: EHCI root HUB
   0.005371	[D2] - Serial Number: unknown
   0.005381	[D2] - Bus: 001
   0.005391	[D2] - Bus Port: unknown
   0.005402	[D2] - Device: 001
   0.005412	[D2] - Device release number: 0100
   0.005422	[D2] Trying to match device
   0.005442	[D2] match_function_subdriver (non-SHUT mode): matching a device...
   0.005476	[D2] match_function_subdriver (non-SHUT mode): failed to match a subdriver to vendor and/or product ID
   0.005489	[D2] Device does not match - skipping
   0.005585	[D2] Checking device 3 of 3 (09AE/3024)
   0.018725	[D2] - VendorID: 09ae
   0.018775	[D2] - ProductID: 3024
   0.018789	[D2] - Manufacturer: Tripp Lite
   0.018800	[D2] - Product: ECO850LCD       
   0.018811	[D2] - Serial Number: 3216CV4BC87F303175
   0.018822	[D2] - Bus: 001
   0.018832	[D2] - Bus Port: 001
   0.018843	[D2] - Device: 002
   0.018853	[D2] - Device release number: 0002
   0.018864	[D2] Trying to match device
   0.018884	[D2] match_function_subdriver (non-SHUT mode): matching a device...
   0.018983	[D3] match_function_regex: matching a device...
   0.019006	[D2] Device matches

ghound

@dennypage said in NUT Package (2.8.1 and above):

First start the service, and then kill the driver:

killall usbhid-ups
Then, run the driver with debug:

/usr/local/libexec/nut/usbhid-ups -DDDDDD -a TrippLite

Here is system log after disconnecting / reconnecting USB cable:

Mar 11 11:40:04	upsmon	8414	Poll UPS [TrippLite] failed - Driver not connected
Mar 11 11:40:01	kernel		 uhid0: <Tripp Lite ECO850LCD, class 0/0, rev 2.00/0.02, addr 2> on usbus1
Mar 11 11:40:01	kernel		uhid0 on uhub1
Mar 11 11:40:01	kernel		ugen1.2: <Tripp Lite ECO850LCD> at usbus1
Mar 11 11:39:59	upsmon	8414	Poll UPS [TrippLite] failed - Driver not connected
Mar 11 11:39:54	upsmon	8414	Poll UPS [TrippLite] failed - Driver not connected
Mar 11 11:39:49	upsmon	8414	Poll UPS [TrippLite] failed - Driver not connected
Mar 11 11:39:48	kernel		ugen1.2: <Tripp Lite ECO850LCD> at usbus1 (disconnected)
Mar 11 11:39:44	upsmon	8414	Poll UPS [TrippLite] failed - Driver not connected

After disconnecting / reconnecting USB cable and manual driver start, UPS is available again:

   0.002865	[D2] Initializing an USB-connected UPS with library libusb-1.0.0 (API: 0x1000102) (NUT subdriver name='USB communication driver (libusb 1.0)' ver='0.46')
   0.003797	[D2] Checking device 1 of 3 (0000/0000)
   0.004739	[D1] nut_libusb_open: invalid libusb bus number 0
   0.004878	[D2] - VendorID: 0000
   0.004897	[D2] - ProductID: 0000
   0.004909	[D2] - Manufacturer: Generic
   0.004920	[D2] - Product: XHCI root HUB
   0.004932	[D2] - Serial Number: unknown
   0.004943	[D2] - Bus: 000
   0.004953	[D2] - Bus Port: unknown
   0.004963	[D2] - Device: 001
   0.004974	[D2] - Device release number: 0100
   0.004985	[D2] Trying to match device
   0.005008	[D2] match_function_subdriver (non-SHUT mode): matching a device...
   0.005052	[D2] match_function_subdriver (non-SHUT mode): failed to match a subdriver to vendor and/or product ID
   0.005065	[D2] Device does not match - skipping
   0.005194	[D2] Checking device 2 of 3 (0000/0000)
   0.005421	[D1] nut_libusb_open: invalid libusb bus number 0
   0.005517	[D2] - VendorID: 0000
   0.005532	[D2] - ProductID: 0000
   0.005543	[D2] - Manufacturer: Marvell
   0.005554	[D2] - Product: EHCI root HUB
   0.005565	[D2] - Serial Number: unknown
   0.005576	[D2] - Bus: 001
   0.005586	[D2] - Bus Port: unknown
   0.005596	[D2] - Device: 001
   0.005607	[D2] - Device release number: 0100
   0.005617	[D2] Trying to match device
   0.005637	[D2] match_function_subdriver (non-SHUT mode): matching a device...
   0.005669	[D2] match_function_subdriver (non-SHUT mode): failed to match a subdriver to vendor and/or product ID
   0.005682	[D2] Device does not match - skipping
   0.005775	[D2] Checking device 3 of 3 (09AE/3024)
   0.018671	[D2] - VendorID: 09ae
   0.018723	[D2] - ProductID: 3024
   0.018736	[D2] - Manufacturer: Tripp Lite
   0.018748	[D2] - Product: ECO850LCD       
   0.018762	[D2] - Serial Number: 3216CV4BC87F303175
   0.018774	[D2] - Bus: 001
   0.018784	[D2] - Bus Port: 001
   0.018794	[D2] - Device: 002
   0.018805	[D2] - Device release number: 0002
   0.018816	[D2] Trying to match device
   0.018843	[D2] match_function_subdriver (non-SHUT mode): matching a device...
   0.018946	[D3] match_function_regex: matching a device...
   0.018967	[D2] Device matches

dennypage

@ghound said in NUT Package (2.8.1 and above):

72251.591030 [D2] Checking device 3 of 3 (09AE/3024)
72251.745371 [D1] nut_libusb_open get iManufacturer failed, retrying...
72251.895872 [D1] nut_libusb_open get iManufacturer failed, retrying...
72252.050367 [D1] nut_libusb_open get iManufacturer failed, retrying...
72252.205384 [D1] nut_libusb_open get iProduct failed, retrying...
72252.359364 [D1] nut_libusb_open get iProduct failed, retrying...
72252.513419 [D1] nut_libusb_open get iProduct failed, retrying...
72252.667482 [D1] nut_libusb_open get iSerialNumber failed, retrying...
72252.820954 [D1] nut_libusb_open get iSerialNumber failed, retrying...
72252.971389 [D1] nut_libusb_open get iSerialNumber failed, retrying...
72252.971473 [D2] - VendorID: 09ae
72252.971489 [D2] - ProductID: 3024
72252.971501 [D2] - Manufacturer: unknown
72252.971516 [D2] - Product: unknown
72252.971528 [D2] - Serial Number: unknown
72252.971540 [D2] - Bus: 001
72252.971551 [D2] - Bus Port: 001
72252.971563 [D2] - Device: 002
72252.971574 [D2] - Device release number: 0002
72252.971586 [D2] Trying to match device
72252.971609 [D2] match_function_subdriver (non-SHUT mode): matching a device...
72252.971645 [D3] match_function_regex: matching a device...
72252.971663 [D3] match_function_exact: matching a device...
72252.971678 [D2] match_function_exact: failed match of Vendor: (null) != Tripp Lite
72252.971690 [D2] Device does not match - skipping

@ghound said in NUT Package (2.8.1 and above):

0.005713 [D2] Checking device 3 of 3 (09AE/3024)
0.156567 [D1] nut_libusb_open get iManufacturer failed, retrying...
0.310568 [D1] nut_libusb_open get iManufacturer failed, retrying...
0.461572 [D1] nut_libusb_open get iManufacturer failed, retrying...
0.608445 [D1] nut_libusb_open get iProduct failed, retrying...
0.762543 [D1] nut_libusb_open get iProduct failed, retrying...
0.912962 [D1] nut_libusb_open get iProduct failed, retrying...
1.066550 [D1] nut_libusb_open get iSerialNumber failed, retrying...
1.218542 [D1] nut_libusb_open get iSerialNumber failed, retrying...
1.369116 [D1] nut_libusb_open get iSerialNumber failed, retrying...
1.369185 [D2] - VendorID: 09ae
1.369200 [D2] - ProductID: 3024
1.369214 [D2] - Manufacturer: unknown
1.369226 [D2] - Product: unknown
1.369238 [D2] - Serial Number: unknown
1.369249 [D2] - Bus: 001
1.369261 [D2] - Bus Port: 001
1.369273 [D2] - Device: 002
1.369285 [D2] - Device release number: 0002

For some reason we are loosing the ability to query device manufacturer and product. That it is persistent indicates that there is a problem in the kernel's USB drivers or the hardware itself. Unfortunately this is well outside of NUT's control.

Looking at your usbconfig output, the one thing I would recommend is to try a different USB port on the host. Something that connects to bus0 (generic XHCI) rather than bus1 (Marvell EHCI).

ghound

@dennypage said in NUT Package (2.8.1 and above):

For some reason we are loosing the ability to query device manufacturer and product. That it is persistent indicates that there is a problem in the kernel's USB drivers or the hardware itself. Unfortunately this is well outside of NUT's control.

Looking at your usbconfig output, the one thing I would recommend is to try a different USB port on the host. Something that connects to bus0 (generic XHCI) rather than bus1 (Marvell EHCI).

Thank you for looking at all the logs. This is a Netgate SG1100 box, so I connected to the USB3 port at ugen0.1: <Generic XHCI root HUB> at usbus0 – Bus:000 Bus Port: 002; vice my original connection to the USB2 port at ugen1.1: <Marvell EHCI root HUB> at usbus1 – Bus:001 Bus Port: 001. Again, connection was lost after around one day of operation. I do have another SG1100 I can try. Any other troubleshooting ideas? Thank you.

Log USB3 port connection:

   0.007864	[D2] Checking device 3 of 3 (09AE/3024)
   0.010883	[D2] - VendorID: 09ae
   0.010949	[D2] - ProductID: 3024
   0.010964	[D2] - Manufacturer: Tripp Lite
   0.010976	[D2] - Product: ECO850LCD       
   0.010987	[D2] - Serial Number: 3216CV4BC87F303175
   0.010998	[D2] - Bus: 000
   0.011009	[D2] - Bus Port: 002
   0.011019	[D2] - Device: 002
   0.011030	[D2] - Device release number: 0002
   0.011041	[D2] Trying to match device
   0.011062	[D2] match_function_subdriver (non-SHUT mode): matching a device...
   0.011164	[D3] match_function_regex: matching a device...
   0.011185	[D2] Device matches

dennypage

@ghound said in NUT Package (2.8.1 and above):

0.007864 [D2] Checking device 3 of 3 (09AE/3024)
0.010883 [D2] - VendorID: 09ae
0.010949 [D2] - ProductID: 3024
0.010964 [D2] - Manufacturer: Tripp Lite
0.010976 [D2] - Product: ECO850LCD
0.010987 [D2] - Serial Number: 3216CV4BC87F303175
0.010998 [D2] - Bus: 000
0.011009 [D2] - Bus Port: 002
0.011019 [D2] - Device: 002
0.011030 [D2] - Device release number: 0002

This looks correct (working). Manufacturer and Product are identifiable. If this subsequently fails, to confirm that the issue is the same as experienced on the other port, I would need to see what the driver says when it isn't working. Also interested to see the output of "usbconfig -v" when it isn't working.

ghound

@dennypage said in NUT Package (2.8.1 and above):

This looks correct (working). Manufacturer and Product are identifiable. If this subsequently fails, to confirm that the issue is the same as experienced on the other port, I would need to see what the driver says when it isn't working. Also interested to see the output of "usbconfig -v" when it isn't working.

Below is result of usbconfig -v when the connection is not working (on USB3 port):

[23.09.1-RELEASE][admin@router01.localr01]/dev/usb: usbconfig -v
ugen0.1: <Generic XHCI root HUB> at usbus0, cfg=0 md=HOST spd=SUPER (5.0Gbps) pwr=SAVE (0mA)
ugen0.1.0: uhub0: <Generic XHCI root HUB, class 9/0, rev 3.00/1.00, addr 1>

  bLength = 0x0012
  bDescriptorType = 0x0001
  bcdUSB = 0x0300
  bDeviceClass = 0x0009  <HUB>
  bDeviceSubClass = 0x0000
  bDeviceProtocol = 0x0003
  bMaxPacketSize0 = 0x0009
  idVendor = 0x0000
  idProduct = 0x0000
  bcdDevice = 0x0100
  iManufacturer = 0x0001  <Generic>
  iProduct = 0x0002  <XHCI root HUB>
  iSerialNumber = 0x0000  <no string>
  bNumConfigurations = 0x0001


 Configuration index 0

    bLength = 0x0009
    bDescriptorType = 0x0002
    wTotalLength = 0x001f
    bNumInterfaces = 0x0001
    bConfigurationValue = 0x0001
    iConfiguration = 0x0000  <no string>
    bmAttributes = 0x0040
    bMaxPower = 0x0000

    Interface 0
      bLength = 0x0009
      bDescriptorType = 0x0004
      bInterfaceNumber = 0x0000
      bAlternateSetting = 0x0000
      bNumEndpoints = 0x0001
      bInterfaceClass = 0x0009  <HUB>
      bInterfaceSubClass = 0x0000
      bInterfaceProtocol = 0x0000
      iInterface = 0x0000  <no string>

     Endpoint 0
        bLength = 0x0007
        bDescriptorType = 0x0005
        bEndpointAddress = 0x0081  <IN>
        bmAttributes = 0x0003  <INTERRUPT>
        wMaxPacketSize = 0x0002
        bInterval = 0x00ff
        bRefresh = 0x0000
        bSynchAddress = 0x0000

      Additional Descriptor

      bLength = 0x06
      bDescriptorType = 0x30
      bDescriptorSubType = 0x00
       RAW dump:
       0x00 | 0x06, 0x30, 0x00, 0x00, 0x00, 0x00




ugen1.1: <Marvell EHCI root HUB> at usbus1, cfg=0 md=HOST spd=HIGH (480Mbps) pwr=SAVE (0mA)
ugen1.1.0: uhub1: <Marvell EHCI root HUB, class 9/0, rev 2.00/1.00, addr 1>

  bLength = 0x0012
  bDescriptorType = 0x0001
  bcdUSB = 0x0200
  bDeviceClass = 0x0009  <HUB>
  bDeviceSubClass = 0x0000
  bDeviceProtocol = 0x0001
  bMaxPacketSize0 = 0x0040
  idVendor = 0x0000
  idProduct = 0x0000
  bcdDevice = 0x0100
  iManufacturer = 0x0001  <Marvell>
  iProduct = 0x0002  <EHCI root HUB>
  iSerialNumber = 0x0000  <no string>
  bNumConfigurations = 0x0001


 Configuration index 0

    bLength = 0x0009
    bDescriptorType = 0x0002
    wTotalLength = 0x0019
    bNumInterfaces = 0x0001
    bConfigurationValue = 0x0001
    iConfiguration = 0x0000  <no string>
    bmAttributes = 0x0040
    bMaxPower = 0x0000

    Interface 0
      bLength = 0x0009
      bDescriptorType = 0x0004
      bInterfaceNumber = 0x0000
      bAlternateSetting = 0x0000
      bNumEndpoints = 0x0001
      bInterfaceClass = 0x0009  <HUB>
      bInterfaceSubClass = 0x0000
      bInterfaceProtocol = 0x0000
      iInterface = 0x0000  <no string>

     Endpoint 0
        bLength = 0x0007
        bDescriptorType = 0x0005
        bEndpointAddress = 0x0081  <IN>
        bmAttributes = 0x0003  <INTERRUPT>
        wMaxPacketSize = 0x0008
        bInterval = 0x00ff
        bRefresh = 0x0000
        bSynchAddress = 0x0000



ugen0.2: <Tripp Lite ECO850LCD> at usbus0, cfg=0 md=HOST spd=FULL (12Mbps) pwr=ON (100mA)

  bLength = 0x0012
  bDescriptorType = 0x0001
  bcdUSB = 0x0200
  bDeviceClass = 0x0000  <Probed by interface class>
  bDeviceSubClass = 0x0000
  bDeviceProtocol = 0x0000
  bMaxPacketSize0 = 0x0040
  idVendor = 0x09ae
  idProduct = 0x3024
  bcdDevice = 0x0002
  iManufacturer = 0x0003  <retrieving string failed>
  iProduct = 0x0001  <retrieving string failed>
  iSerialNumber = 0x0005  <retrieving string failed>
  bNumConfigurations = 0x0001


 Configuration index 0

    bLength = 0x0009
    bDescriptorType = 0x0002
    wTotalLength = 0x0022
    bNumInterfaces = 0x0001
    bConfigurationValue = 0x0001
    iConfiguration = 0x0000  <no string>
    bmAttributes = 0x00a0
    bMaxPower = 0x0032

    Interface 0
      bLength = 0x0009
      bDescriptorType = 0x0004
      bInterfaceNumber = 0x0000
      bAlternateSetting = 0x0000
      bNumEndpoints = 0x0001
      bInterfaceClass = 0x0003  <HID device>
      bInterfaceSubClass = 0x0000
      bInterfaceProtocol = 0x0000
      iInterface = 0x0000  <no string>

      Additional Descriptor

      bLength = 0x09
      bDescriptorType = 0x21
      bDescriptorSubType = 0x11
       RAW dump:
       0x00 | 0x09, 0x21, 0x11, 0x01, 0x21, 0x01, 0x22, 0x75,
       0x08 | 0x03

     Endpoint 0
        bLength = 0x0007
        bDescriptorType = 0x0005
        bEndpointAddress = 0x0081  <IN>
        bmAttributes = 0x0003  <INTERRUPT>
        wMaxPacketSize = 0x0040
        bInterval = 0x00ff
        bRefresh = 0x0000
        bSynchAddress = 0x0000




Broadcast Message from root@router01.localr01
        (no tty) at 16:01 EDT...

UPS TrippLite is unavailable

dennypage

@ghound said in NUT Package (2.8.1 and above):

iManufacturer = 0x0003 <retrieving string failed>
iProduct = 0x0001 <retrieving string failed>
iSerialNumber = 0x0005 <retrieving string failed>

It was worth a shot.

Can you confirm that this behavior started following an upgrade of pfSense?

ghound

@dennypage said in NUT Package (2.8.1 and above):

Can you confirm that this behavior started following an upgrade of pfSense?

Behavior has persisted through several updates. (In fact, UPS has never not had this issue from its first day out of the box.)

dennypage

@ghound said in NUT Package (2.8.1 and above):

Behavior has persisted through several updates. (In fact, UPS has never not had this issue from its first day out of the box.)

Okay, I'm confused. Please detail what previous version/date that the problem did not occur, and what version/date began to occurr.

ghound

@dennypage said in NUT Package (2.8.1 and above):

Okay, I'm confused. Please detail what previous version/date that the problem did not occur, and what version/date began to occurr.

TrippLite UPS was purchased new in May '23 and connected to SG-1100 (23.05 / 2.8.0_2). You gave me a few tips to properly load usbhid-ups. Once usbhid-ups loaded correctly, after a few days, UPS lost connection (so the UPS has never operated without the lost connection problem every few days). At the time, I believed this was the "lost connection" problem mentioned in the thread. The problem has persisted from first connection to today. SG-1100 is currently 23.09.1 and Nut 2.8.2_1.

dennypage

@ghound said in NUT Package (2.8.1 and above):

TrippLite UPS was purchased new in May '23 and connected to SG-1100 (23.05 / 2.8.0_2). You gave me a few tips to properly load usbhid-ups. Once usbhid-ups loaded correctly, after a few days, UPS lost connection (so the UPS has never operated without the lost connection problem every few days). At the time, I believed this was the "lost connection" problem mentioned in the thread. The problem has persisted from first connection to today. SG-1100 is currently 23.09.1 and Nut 2.8.2_1.

Ah, okay. It's never operated correctly. I had misunderstood that it was a regression.

pvk1

@dennypage Sorry if this is the wrong place. I migrated the configuration to a Netgate 4200. I have NUT package 2.8.2_1. It had permission errors. After including user=root in the ups.conf section (as suggested by you in the previous track) it started working. It also worked on the previous system.
Schermafbeelding 2024-03-30 091809.png

dennypage

@pvk1 Ownership of the /var/db/nut directory is incorrect. The following command will fix that:

chown -R nut:nut /var/db/nut

The errors for /usr/local/etc/nut are more of an issue. Those files should be accessed prior to switching to user "nut". What version of pfSense are you running? What does

pkg info | grep nut

report? Thx.

pvk1

@dennypage
I am running: 23.09.1-RELEASE (amd64)

pkg info:

nut-devel-2024.01.03 Network UPS Tools
pfSense-pkg-nut-2.8.2_1 Network UPS Tools

thx

dennypage

@pvk1 Can you post the output of the the following commands please?

ls -l /var/db/nut
ls -l /usr/local/etc/nut

Thanks