networkupstools
strange data in logs, `file_report_buffer: expected 2 bytes, but got 512 `
(same device and system discussed in #2399 )
looking at logs, I thought it strange that a request would return 512 bytes :
54.285255 [D1] Quick update...
54.285266 [D4] Entering libusb_get_report
54.287751 [D3] Report[get]: (3 bytes) => 16 00 00
54.287793 [D2] Path: UPS.BELKINControls.BELKINDelayBeforeStartup, Type: Feature, ReportID: 0x16, Offset: 0, Size: 16, Value: 0
54.287813 [D4] Entering libusb_get_report
54.290724 [D3] Report[get]: (3 bytes) => 15 00 00
.... trimmed
54.302802 [D4] Entering libusb_get_report
54.304747 [D3] Report[get]: (2 bytes) => 23 10
54.304789 [D2] Path: UPS.BELKINStatus.BELKINBatteryStatus, Type: Feature, ReportID: 0x23, Offset: 0, Size: 8, Value: 16
54.304804 [D3] Report[buf]: (2 bytes) => 23 10
54.304816 [D2] Path: UPS.BELKINStatus.BELKINBatteryStatus, Type: Feature, ReportID: 0x23, Offset: 0, Size: 8, Value: 16
56.260381 [D1] upsdrv_updateinfo...
56.268762 [D2] file_report_buffer: expected 2 bytes, but got 512 instead
56.268810 [D3] Report[err]: (512 bytes) => 34 64 00 00 00 00 00 00 d0 12 2d 0b 1b 5d 00 00
56.268835 [D3] 4d 8a c5 09 1b 5d 00 00 30 b6 76 c7 fd 7f 00 00 70 13 2d 0b 1b 5d 00 00 10
56.268855 [D3] 00 00 00 00 00 00 00 0a 00 00 00 00 00 00 00 53 39 c5 09 1b 5d 00 00 10 00
56.268877 [D3] 00 00 30 00 00 00 20 b8 76 c7 fd 7f 00 00 40 b7 76 c7 fd 7f 00 00 b8 22 03
56.268897 [D3] 00 00 00 00 00 75 70 64 61 74 65 69 6e 66 6f 00 c7 fd 7f 00 00 00 00 00 00
56.268916 [D3] 00 00 00 00 00 00 00 00 00 00 00 00 72 6f 75 6e 64 20 70 72 6f 63 65 73 73
56.268935 [D3] 2c 20 62 20 50 49 44 20 66 69 6c 65 20 61 6e 79 77 61 79 73 73 2c 20 62 75
56.268954 [D3] 74 20 73 61 76 69 6e 67 20 61 c0 4a f9 e7 13 70 00 00 10 04 00 00 00 00 00
56.268975 [D3] 00 a0 38 2f 0b 1b 5d 00 00 08 53 e5 e7 13 70 00 00 c0 4a f9 e7 13 70 00 00
56.268994 [D3] 00 00 00 00 00 00 00 00 38 ce 76 c7 fd 7f 00 00 70 37 30 0b 1b 5d 00 00 ba
56.269014 [D3] c9 c5 09 1b 5d 00 00 69 56 e5 e7 13 70 00 00 00 00 00 00 02 00 00 00 04 00
56.269033 [D3] 00 00 00 00 00 00 b6 63 1d 66 00 00 00 00 98 76 03 00 00 00 00 00 b0 fe ff
56.269053 [D3] ff ff ff ff ff 02 00 00 00 00 00 00 00 38 ce 76 c7 fd 7f 00 00 93 7e e5 e7
56.269072 [D3] 13 70 00 00 26 ce 76 c7 fd 7f 00 00 38 ce 76 c7 fd 7f 00 00 70 37 30 0b 1b
56.269092 [D3] 5d 00 00 00 c6 75 ff fd cd a7 90 26 ce 76 c7 fd 7f 00 00 00 c6 75 ff fd cd
56.269111 [D3] a7 90 17 00 00 00 00 00 00 00 b0 10 2f 0b 1b 5d 00 00 62 b1 a3 00 00 00 00
56.269131 [D3] 00 18 00 00 00 00 00 00 00 75 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
56.269150 [D3] c0 4a f9 e7 13 70 00 00 e8 fe ff ff ff ff ff ff 08 00 00 00 00 00 00 00 00
56.269170 [D3] 00 00 00 00 00 00 00 80 14 30 0b 1b 5d 00 00 ed 77 e5 e7 13 70 00 00 07 00
56.269190 [D3] 00 00 00 00 00 00 0e 23 ec e7 13 70 00 00 c0 b7 76 c7 fd 7f 00 00 00 00 00
56.269221 [D3] 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
56.269232 [D1] Got 1 HID objects...
56.269244 [D3] Report[buf]: (2 bytes) => 34 64
56.269264 [D2] Path: UPS.PowerSummary.RemainingCapacity, Type: Input, ReportID: 0x34, Offset: 0, Size: 8, Value: 100
56.269278 [D3] NUT doesn't use this HID object
56.269291 [D1] Quick update...
I thought some of that data looked like ASCII, so out of curiosity I ran it through xxd -r -p | xxd -b 1 :
00000000: 4d 8a c5 09 1b 5d 00 00 30 b6 76 c7 fd 7f 00 00 M....]..0.v.....
00000010: 70 13 2d 0b 1b 5d 00 00 10 00 00 00 00 00 00 00 p.-..]..........
00000020: 0a 00 00 00 00 00 00 00 53 39 c5 09 1b 5d 00 00 ........S9...]..
00000030: 10 00 00 00 30 00 00 00 20 b8 76 c7 fd 7f 00 00 ....0... .v.....
00000040: 40 b7 76 c7 fd 7f 00 00 b8 22 03 00 00 00 00 00 @.v......"......
00000050: 75 70 64 61 74 65 69 6e 66 6f 00 c7 fd 7f 00 00 updateinfo......
00000060: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
00000070: 72 6f 75 6e 64 20 70 72 6f 63 65 73 73 2c 20 62 round process, b
00000080: 20 50 49 44 20 66 69 6c 65 20 61 6e 79 77 61 79 PID file anyway
00000090: 73 73 2c 20 62 75 74 20 73 61 76 69 6e 67 20 61 ss, but saving a
000000a0: c0 4a f9 e7 13 70 00 00 10 04 00 00 00 00 00 00 .J...p..........
000000b0: a0 38 2f 0b 1b 5d 00 00 08 53 e5 e7 13 70 00 00 .8/..]...S...p..
000000c0: c0 4a f9 e7 13 70 00 00 00 00 00 00 00 00 00 00 .J...p..........
000000d0: 38 ce 76 c7 fd 7f 00 00 70 37 30 0b 1b 5d 00 00 8.v.....p70..]..
000000e0: ba c9 c5 09 1b 5d 00 00 69 56 e5 e7 13 70 00 00 .....]..iV...p..
000000f0: 00 00 00 00 02 00 00 00 04 00 00 00 00 00 00 00 ................
00000100: b6 63 1d 66 00 00 00 00 98 76 03 00 00 00 00 00 .c.f.....v......
00000110: b0 fe ff ff ff ff ff ff 02 00 00 00 00 00 00 00 ................
00000120: 38 ce 76 c7 fd 7f 00 00 93 7e e5 e7 13 70 00 00 8.v......~...p..
00000130: 26 ce 76 c7 fd 7f 00 00 38 ce 76 c7 fd 7f 00 00 &.v.....8.v.....
00000140: 70 37 30 0b 1b 5d 00 00 00 c6 75 ff fd cd a7 90 p70..]....u.....
00000150: 26 ce 76 c7 fd 7f 00 00 00 c6 75 ff fd cd a7 90 &.v.......u.....
00000160: 17 00 00 00 00 00 00 00 b0 10 2f 0b 1b 5d 00 00 ........../..]..
00000170: 16 ac a3 00 00 00 00 00 18 00 00 00 00 00 00 00 ................
00000180: 75 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 u...............
00000190: c0 4a f9 e7 13 70 00 00 e8 fe ff ff ff ff ff ff .J...p..........
000001a0: 08 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
000001b0: 80 14 30 0b 1b 5d 00 00 ed 77 e5 e7 13 70 00 00 ..0..]...w...p..
000001c0: 07 00 00 00 00 00 00 00 0e 23 ec e7 13 70 00 00 .........#...p..
000001d0: c0 b7 76 c7 fd 7f 00 00 00 00 00 00 00 00 00 00 ..v.............
000001e0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
And, it just so happens that I have this warning earlier in journalctl :
nut-driver@belk[30528]: Running as foreground process, but saving a PID file anyway
How is that text ending up in a seemingly unrelated place ?
The decoding should have started earlier, with 34 64 00 00 00 00 00 00 d0 12 2d 0b 1b 5d 00 00 line - and it ends the string with 0x00 after two bytes of data ;)
On one hand, it is indeed odd that it returns 512 bytes, using an uninitialized memory block. By content, it was memory that once belonged to the process and was since freed. So the bytes in it are not too much surprising, the length is. Code comments are about broken device report descriptors, so maybe that's just it - many vendors can't read USB specs well.
Just some notes as I look at this superficially ;
HIDGetEvents() has
r = (interrupt_size > 0 && interrupt_size < sizeof(buf))
? interrupt_size : sizeof(buf);
where sizeof(buf) == SMALLBUF == 512. This would be used if interrupt_size is <=0; this (global !) variable is set in usbhid-ups.c from (I think) a config key "interruptsize". I wonder if it's set to 0 by default ?
Looked at this again today. My previous comments re interrupt_size were on the wrong track; it's fine to request a 512B transfer . But https://github.com/networkupstools/nut/blob/master/drivers/libusb1.c#L1093 should be returning the actual xfer size, not the caller's buffer size ! Will submit a PR shortly.