strange data in logs, file_report_buffer: expected 2 bytes, but got 512

[fenugrec]

(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 ?

[jimklimov]

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.

[fenugrec]

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 ?