nut
nut copied to clipboard
networkupstools
apc_modbus "buffer overflow detected" - usb enabled libmodbus
Running in to a similar (if not the same), issue as mentioned in https://github.com/networkupstools/nut/pull/2063#issuecomment-1905299561
This is with a 2020 SMT2200RM12U, connected via USB and attempting to use apc_modbus. Have been able to build the modified libmodbus fine (and attempted to use apc-test-client but showed a similar error), but upon building nut with this modified lib for the driver, copying driver to the correct place, and installing over the apt package of nut as described in wiki/comments on the issue thread, the driver won't load.
Output when trying to start the driver directly:
cbrherms@nutpi:~$ sudo /lib/nut/apc_modbus -a apc-2200 -u nut -DDDDDD -d1
0.000001 [D5] send_to_all: SETINFO driver.state "init.starting"
Network UPS Tools - NUT APC Modbus driver 0.01 (2.8.1-403-g746cb8611)
0.000478 [D5] send_to_all: SETINFO driver.version.usb "libusb-1.0.25 (API: 0x1000109)"
0.000527 [D1] Using USB implementation: libusb-1.0.25 (API: 0x1000109)
0.000716 [D5] do_upsconf_args: confupsname=(null), var=pollinterval, val=1
0.000755 [D5] do_upsconf_args: call do_global_args()
0.000792 [D3] do_global_args: var='pollinterval' val='1'
0.000829 [D6] testval_reloadable: var=pollinterval, oldval=2, newval=1, reloadable=1, reload_flag=0
0.000891 [D1] testval_reloadable: setting 'pollinterval' exists and differs: new value '1' vs. '2'
0.000934 [D6] testval_reloadable: verdict for (re)loading var=pollinterval value: 1
0.000989 [D5] do_upsconf_args: confupsname=(null), var=maxretry, val=3
0.001034 [D5] do_upsconf_args: call do_global_args()
0.001086 [D3] do_global_args: var='maxretry' val='3'
0.001129 [D5] do_upsconf_args: confupsname=apc-2200, var=driver, val=apc_modbus
0.001175 [D5] do_upsconf_args: call main_arg()
0.001216 [D3] main_arg: var='driver' val='apc_modbus'
0.001252 [D5] do_upsconf_args: not a main_arg()
0.001295 [D5] do_upsconf_args: this is a 'driver' setting, may we proceed?
0.001338 [D6] testval_reloadable: var=driver, oldval=apc_modbus, newval=apc_modbus, reloadable=0, reload_flag=0
0.001402 [D6] testval_reloadable: verdict for (re)loading var=driver value: -1
0.001456 [D5] do_upsconf_args: 'driver' setting already applied with this value
0.001522 [D5] do_upsconf_args: confupsname=apc-2200, var=port, val=auto
0.001583 [D5] do_upsconf_args: call main_arg()
0.001631 [D3] main_arg: var='port' val='auto'
0.001673 [D6] testinfo_reloadable: var=port, infoname=driver.parameter.port, newval=auto, reloadable=0, reload_flag=0
0.001723 [D6] testinfo_reloadable: verdict for (re)loading var=port value: 1
0.001784 [D5] send_to_all: SETINFO driver.parameter.port "auto"
0.001848 [D5] do_upsconf_args: confupsname=apc-2200, var=vendorid, val=051D
0.001902 [D5] do_upsconf_args: call main_arg()
0.001943 [D3] main_arg: var='vendorid' val='051D'
0.001990 [D5] do_upsconf_args: not a main_arg()
0.002042 [D5] do_upsconf_args: process as value
0.002091 [D6] testvar_reloadable: searching for var=vendorid, vartype=2, reload_flag=0
0.002150 [D6] testvar_reloadable: found var=vendorid, val='(null)' => '051D', vartype=2 => 2, found=0, reloadable=0, reload_flag=0
0.002205 [D6] testvar_reloadable: verdict for (re)loading var=vendorid value: 1
0.002260 [D5] send_to_all: SETINFO driver.parameter.vendorid "051D"
0.002314 [D5] do_upsconf_args: confupsname=apc-2200, var=productid, val=0003
0.002377 [D5] do_upsconf_args: call main_arg()
0.002419 [D3] main_arg: var='productid' val='0003'
0.002466 [D5] do_upsconf_args: not a main_arg()
0.002522 [D5] do_upsconf_args: process as value
0.002569 [D6] testvar_reloadable: searching for var=productid, vartype=2, reload_flag=0
0.002625 [D6] testvar_reloadable: found var=productid, val='(null)' => '0003', vartype=2 => 2, found=0, reloadable=0, reload_flag=0
0.002680 [D6] testvar_reloadable: verdict for (re)loading var=productid value: 1
0.002739 [D5] send_to_all: SETINFO driver.parameter.productid "0003"
0.002804 [D5] do_upsconf_args: confupsname=apc-2200, var=product, val=Smart-UPS 2200 FW:UPS 15.0 / ID=18
0.002867 [D5] do_upsconf_args: call main_arg()
0.002908 [D3] main_arg: var='product' val='Smart-UPS 2200 FW:UPS 15.0 / ID=18'
0.002957 [D5] do_upsconf_args: not a main_arg()
0.003013 [D5] do_upsconf_args: process as value
0.003061 [D6] testvar_reloadable: searching for var=product, vartype=2, reload_flag=0
0.003116 [D6] testvar_reloadable: found var=product, val='(null)' => 'Smart-UPS 2200 FW:UPS 15.0 / ID=18', vartype=2 => 2, found=0, reloadable=0, reload_flag=0
0.003172 [D6] testvar_reloadable: verdict for (re)loading var=product value: 1
0.003228 [D5] send_to_all: SETINFO driver.parameter.product "Smart-UPS 2200 FW:UPS 15.0 / ID=18"
0.003283 [D5] do_upsconf_args: confupsname=apc-2200, var=serial, val=AS2034242877
0.003347 [D5] do_upsconf_args: call main_arg()
0.003391 [D3] main_arg: var='serial' val='AS2034242877'
0.003438 [D5] do_upsconf_args: not a main_arg()
0.003487 [D5] do_upsconf_args: process as value
0.003539 [D6] testvar_reloadable: searching for var=serial, vartype=2, reload_flag=0
0.003595 [D6] testvar_reloadable: found var=serial, val='(null)' => 'AS2034242877', vartype=2 => 2, found=0, reloadable=0, reload_flag=0
0.003650 [D6] testvar_reloadable: verdict for (re)loading var=serial value: 1
0.003709 [D5] send_to_all: SETINFO driver.parameter.serial "AS2034242877"
0.003770 [D5] do_upsconf_args: confupsname=apc-2200, var=vendor, val=American Power Conversion
0.003832 [D5] do_upsconf_args: call main_arg()
0.003880 [D3] main_arg: var='vendor' val='American Power Conversion'
0.003933 [D5] do_upsconf_args: not a main_arg()
0.003982 [D5] do_upsconf_args: process as value
0.004037 [D6] testvar_reloadable: searching for var=vendor, vartype=2, reload_flag=0
0.004093 [D6] testvar_reloadable: found var=vendor, val='(null)' => 'American Power Conversion', vartype=2 => 2, found=0, reloadable=0, reload_flag=0
0.004165 [D6] testvar_reloadable: verdict for (re)loading var=vendor value: 1
0.004227 [D5] send_to_all: SETINFO driver.parameter.vendor "American Power Conversion"
0.004277 [D5] do_upsconf_args: confupsname=apc-2200, var=bus, val=001
0.004338 [D5] do_upsconf_args: call main_arg()
0.004391 [D3] main_arg: var='bus' val='001'
0.004432 [D5] do_upsconf_args: not a main_arg()
0.004478 [D5] do_upsconf_args: process as value
0.004531 [D6] testvar_reloadable: searching for var=bus, vartype=2, reload_flag=0
0.004583 [D6] testvar_reloadable: found var=bus, val='(null)' => '001', vartype=2 => 2, found=0, reloadable=0, reload_flag=0
0.004639 [D6] testvar_reloadable: verdict for (re)loading var=bus value: 1
0.004698 [D5] send_to_all: SETINFO driver.parameter.bus "001"
0.004752 [D5] do_upsconf_args: confupsname=apc-2200, var=device, val=004
0.004805 [D5] do_upsconf_args: call main_arg()
0.004860 [D3] main_arg: var='device' val='004'
0.004908 [D5] do_upsconf_args: not a main_arg()
0.004960 [D5] do_upsconf_args: process as value
0.005014 [D6] testvar_reloadable: searching for var=device, vartype=2, reload_flag=0
0.005065 [D6] testvar_reloadable: found var=device, val='(null)' => '004', vartype=2 => 2, found=0, reloadable=0, reload_flag=0
0.005120 [D6] testvar_reloadable: verdict for (re)loading var=device value: 1
0.005180 [D5] send_to_all: SETINFO driver.parameter.device "004"
0.005233 [D5] do_upsconf_args: confupsname=apc-2200, var=busport, val=003
0.005282 [D5] do_upsconf_args: call main_arg()
0.005342 [D3] main_arg: var='busport' val='003'
0.005390 [D5] do_upsconf_args: not a main_arg()
0.005443 [D5] do_upsconf_args: process as value
0.005497 [D6] testvar_reloadable: searching for var=busport, vartype=2, reload_flag=0
0.005547 [D6] testvar_reloadable: found var=busport, val='(null)' => '003', vartype=2 => 2, found=0, reloadable=0, reload_flag=0
0.005602 [D6] testvar_reloadable: verdict for (re)loading var=busport value: 1
0.005678 [D5] send_to_all: SETINFO driver.parameter.busport "003"
0.005794 [D1] Built-in default or configured user for drivers 'nut' was ignored due to 'nut' specified on command line
0.005876 [D1] Network UPS Tools version 2.8.1-403-g746cb8611 (release/snapshot of 2.8.1.1) built with gcc (Ubuntu 11.4.0-1ubuntu1~22.04) 11.4.0 and configured with flags: --with-drivers=usbhid-ups,apc_modbus,apcsmart --with-usb --prefix= --sysconfdir=/etc/nut --with-statepath=/run/nut --with-user=nut --with-group=nut --with-modbus --with-modbus-includes=-I/home/cbrherms/libmodbus/prefix/include/modbus --with-modbus-libs='-L/home/cbrherms/libmodbus/prefix/lib -lmodbus'
0.005951 [D1] debug level is '6'
0.006000 [D5] send_to_all: SETINFO driver.debug "6"
0.006059 [D5] send_to_all: SETFLAGS driver.debug RW NUMBER
0.013012 [D1] Succeeded to become_user(nut): now UID=114 GID=123
0.013108 [D5] send_to_all: SETINFO device.type "ups"
0.013152 [D5] send_to_all: SETINFO driver.state "init.device"
Number of USB devices: 4
Considering device #0 (051d:0003)
0.036808 [D3] match_function_regex: matching a device...
0.037914 [D2] _apc_modbus_usb_callback: Matched American Power Conversion Smart-UPS 2200 FW:UPS 15.0 / ID=18 (USB VID/PID 051d:0003)
0.038000 [D2] _apc_modbus_usb_callback: Checking American Power Conversion Smart-UPS 2200 FW:UPS 15.0 / ID=18 (USB VID/PID 051d:0003) report descriptors
0.038460 [D1] _apc_modbus_usb_callback: Found report ids RX=0x90 TX=0x89
0.038523 [D5] send_to_all: SETINFO ups.vendorid "051d"
0.038567 [D5] send_to_all: SETINFO ups.productid "0003"
Found Device 0 (Path 1-1.3):
Vendor ID: 0x051d
Product ID: 0x0003
Bytes flushed (63)
0.050102 [D5] send_to_all: SETINFO driver.state "init.quiet"
0.050195 [D5] send_to_all: SETINFO driver.version "2.8.1-403-g746cb8611"
0.050259 [D5] send_to_all: SETINFO driver.version.internal "0.01"
0.050323 [D5] send_to_all: SETINFO driver.name "apc_modbus"
0.050384 [D5] send_to_all: SETINFO driver.state "init.info"
[01][03][02][04][00][58]
Waiting for a confirmation...
*** buffer overflow detected ***: terminated
Aborted
And my syslog has the entry at the time of trying to run the driver of:
kernel: [ 2104.577931] usb 1-1.3: usbfs: process 1371 (apc_modbus) did not claim interface 0 before use
Not really sure where to start on this one if anyone has any ideas?
Can't say i've done any debugging before, but if someone could possibly give me a rundown on what i'd need to do to get something useful out of gdb, I could run through it. I'm aware that on Ubuntu i've apport installed by default for crash dumps and i've enabled it taking these in crashdb.conf
Searching in sources, the error does not seem to be reported - by neither NUT, nor libmodubs (rtu_usb branch), nor libusb (at least 1.0.26 that I have locally). Probably there is some security-conscious libmalloc variant used on your platform which detects (or claims) an overflow and causes the program to abort.
Arbitrarily, as common errors go, I would guess that in the driver we provide a buffer for I/O, maybe even pass the length, and the other side in one of those libraries does not honour this limit. Points to check:
- do we pass the buffer size at all?
- do we pass it correctly (e.g. look out for off-by-one error, if we should keep a reservation for the trailing zero byte)?
- does libmodbus (especially new code in rtu_usb branch) or libusb honour that limit?
Maybe it would symptomatically help to find the buffer involved and just allocate it larger than the expected transfers. Brute, uncivilized, prone to repeating if something changes later and we are none the wiser from debugging - but a quick and dirty hotfix, at least.
You both mentioned that kernel complains about lack of claiming the device. Maybe it is also involved, but I am not sure how :) If the kernel did hand off the device (and nobody else intervenes, especially with virtualization and pass-through involved in that #2063 comment), I suppose it does pass all the data between devices and programs honestly.
For gdb, generally you can start your driver program (with all competitors disabled) like gdb --args ./apc_modbus [-x key=val...] and it would run in the debugger until it fails. Then you can type bt to get a backtrace, unless that memory library causes some sort of clean exit which obscures things.
It may help to pass CFLAGS="-g3 -gdwarf-2 -O0" to configure to have debugging symbols built into the program.
For some cases, it may be simpler to run programs through strace, ptrace, truss or whatever your system offers, which should at least report the syscalls made -- often this is also sufficiently revealing.
I should probably mention that this is all being done on a raspberry pi 3b+
But, okay so here's the weird thing.... I've just gone and re-configured both libmodbus and nut with the CFLAGS and make / installed, and now the driver just started working. Albeit with a large number of connection lost and established messages:
Broadcast message from nut@nutpi (somewhere) (Mon Jan 29 00:22:25 2024):
Communications with UPS apc-2200@localhost established
Broadcast message from nut@nutpi (somewhere) (Mon Jan 29 00:22:25 2024):
Communications with UPS apc-2200@localhost established
Broadcast message from nut@nutpi (somewhere) (Mon Jan 29 00:22:35 2024):
Communications with UPS apc-2200@localhost lost
Broadcast message from nut@nutpi (somewhere) (Mon Jan 29 00:22:35 2024):
Communications with UPS apc-2200@localhost lost
Broadcast message from nut@nutpi (somewhere) (Mon Jan 29 00:22:40 2024):
Communications with UPS apc-2200@localhost established
Broadcast message from nut@nutpi (somewhere) (Mon Jan 29 00:22:40 2024):
Communications with UPS apc-2200@localhost established
Broadcast message from nut@nutpi (somewhere) (Mon Jan 29 00:23:50 2024):
Communications with UPS apc-2200@localhost lost
Broadcast message from nut@nutpi (somewhere) (Mon Jan 29 00:23:50 2024):
Communications with UPS apc-2200@localhost lost
Broadcast message from nut@nutpi (somewhere) (Mon Jan 29 00:23:55 2024):
Communications with UPS apc-2200@localhost established
Broadcast message from nut@nutpi (somewhere) (Mon Jan 29 00:23:55 2024):
Communications with UPS apc-2200@localhost established
The only thing that I can think of having changed between the two times building libmodbus, was that inbetween i'd installed nut and nut-cgi via apt, and as part of the nut package installation it installed libusb-0.1-4 as a dependency.
I'd previously just had libusb-1.0-0-dev (2:1.0.25-1ubuntu2) installed the first time. May that be related?
I think the libmodbus changes for USB support might primarily require libusb-1.x - so wonder if it got somehow built against wrong implementation then (would rely on having the "dev" packages and so headers for both, and then mixing something up while building modbus and NUT). But that's mostly a guess.
I think the USB-capable drivers should report which libusb they use, in debug and recently (since 2.8.0) in upsc reports, e.g. on a box nearby I see:
driver.version.data: MGE HID 1.46
driver.version.internal: 0.52
driver.version.usb: libusb-1.0.24 (API: 0x1000108)
Regarding how it started working... maybe the nut package re-installation restarted udev service so it recognized the IDs needed for APC modbus? :\
I have the same problem with using libusb-1.x:
root@akane:~# apc_modbus -a akane -DDDDDD
0.000000 [D5] send_to_all: SETINFO driver.state "init.starting"
Network UPS Tools driver 2.8.2.986-986-gf31b1ebf7 (development iteration after 2.8.2) - NUT APC Modbus driver 0.10
0.000087 [D5] send_to_all: SETINFO driver.version.usb "libusb-1.0.27 (API: 0x100010a)"
0.000093 [D1] Using USB implementation: libusb-1.0.27 (API: 0x100010a)
0.000207 [D5] do_upsconf_args: confupsname=akane, var=driver, val=apc_modbus
0.000214 [D5] do_upsconf_args: call main_arg()
0.000219 [D3] main_arg: var='driver' val='apc_modbus'
0.000226 [D5] do_upsconf_args: not a main_arg()
0.000231 [D5] do_upsconf_args: this is a 'driver' setting, may we proceed?
0.000236 [D6] testval_reloadable: var=driver, oldval=apc_modbus, newval=apc_modbus, reloadable=0, reload_flag=0
0.000241 [D6] testval_reloadable: verdict for (re)loading var=driver value: -1
0.000248 [D5] do_upsconf_args: 'driver' setting already applied with this value
0.000254 [D5] do_upsconf_args: confupsname=akane, var=port, val=auto
0.000259 [D5] do_upsconf_args: call main_arg()
0.000263 [D3] main_arg: var='port' val='auto'
0.000268 [D6] testinfo_reloadable: var=port, infoname=driver.parameter.port, newval=auto, reloadable=0, reload_flag=0
0.000274 [D6] testinfo_reloadable: verdict for (re)loading var=port value: 1
0.000280 [D5] send_to_all: SETINFO driver.parameter.port "auto"
0.000305 [D5] do_upsconf_args: confupsname=akane, var=porttype, val=usb
0.000311 [D5] do_upsconf_args: call main_arg()
0.000318 [D3] main_arg: var='porttype' val='usb'
0.000324 [D5] do_upsconf_args: not a main_arg()
0.000330 [D5] do_upsconf_args: process as value
0.000338 [D6] testvar_reloadable: searching for var=porttype, vartype=2, reload_flag=0
0.000344 [D6] testvar_reloadable: found var=porttype, val='(null)' => 'usb', vartype=2 => 2, found=0, reloadable=0, reload_flag=0
0.000356 [D6] testvar_reloadable: verdict for (re)loading var=porttype value: 1
0.000365 [D5] send_to_all: SETINFO driver.parameter.porttype "usb"
0.000371 [D5] do_upsconf_args: confupsname=akane, var=vendorid, val=051D
0.000377 [D5] do_upsconf_args: call main_arg()
0.000384 [D3] main_arg: var='vendorid' val='051D'
0.000389 [D5] do_upsconf_args: not a main_arg()
0.000396 [D5] do_upsconf_args: process as value
0.000401 [D6] testvar_reloadable: searching for var=vendorid, vartype=2, reload_flag=0
0.000407 [D6] testvar_reloadable: found var=vendorid, val='(null)' => '051D', vartype=2 => 2, found=0, reloadable=0, reload_flag=0
0.000419 [D6] testvar_reloadable: verdict for (re)loading var=vendorid value: 1
0.000429 [D5] send_to_all: SETINFO driver.parameter.vendorid "051D"
0.000435 [D5] do_upsconf_args: confupsname=akane, var=productid, val=0003
0.000441 [D5] do_upsconf_args: call main_arg()
0.000447 [D3] main_arg: var='productid' val='0003'
0.000454 [D5] do_upsconf_args: not a main_arg()
0.000461 [D5] do_upsconf_args: process as value
0.000466 [D6] testvar_reloadable: searching for var=productid, vartype=2, reload_flag=0
0.000473 [D6] testvar_reloadable: found var=productid, val='(null)' => '0003', vartype=2 => 2, found=0, reloadable=0, reload_flag=0
0.000484 [D6] testvar_reloadable: verdict for (re)loading var=productid value: 1
0.000493 [D5] send_to_all: SETINFO driver.parameter.productid "0003"
0.000501 [D5] do_upsconf_args: confupsname=akane, var=product, val=Smart-UPS 3000 FW:UPS 09.3 / ID=18
0.000507 [D5] do_upsconf_args: call main_arg()
0.000514 [D3] main_arg: var='product' val='Smart-UPS 3000 FW:UPS 09.3 / ID=18'
0.000520 [D5] do_upsconf_args: not a main_arg()
0.000525 [D5] do_upsconf_args: process as value
0.000533 [D6] testvar_reloadable: searching for var=product, vartype=2, reload_flag=0
0.000541 [D6] testvar_reloadable: found var=product, val='(null)' => 'Smart-UPS 3000 FW:UPS 09.3 / ID=18', vartype=2 => 2, found=0, reloadable=0, reload_flag=0
0.000551 [D6] testvar_reloadable: verdict for (re)loading var=product value: 1
0.000558 [D5] send_to_all: SETINFO driver.parameter.product "Smart-UPS 3000 FW:UPS 09.3 / ID=18"
0.000565 [D5] do_upsconf_args: confupsname=akane, var=serial, val=AS1547140889
0.000571 [D5] do_upsconf_args: call main_arg()
0.000576 [D3] main_arg: var='serial' val='AS1547140889'
0.000582 [D5] do_upsconf_args: not a main_arg()
0.000587 [D5] do_upsconf_args: process as value
0.000593 [D6] testvar_reloadable: searching for var=serial, vartype=2, reload_flag=0
0.000600 [D6] testvar_reloadable: found var=serial, val='(null)' => 'AS1547140889', vartype=2 => 2, found=0, reloadable=0, reload_flag=0
0.000608 [D6] testvar_reloadable: verdict for (re)loading var=serial value: 1
0.000620 [D5] send_to_all: SETINFO driver.parameter.serial "AS1547140889"
0.000629 [D5] do_upsconf_args: confupsname=akane, var=vendor, val=American Power Conversion
0.000638 [D5] do_upsconf_args: call main_arg()
0.000646 [D3] main_arg: var='vendor' val='American Power Conversion'
0.000654 [D5] do_upsconf_args: not a main_arg()
0.000660 [D5] do_upsconf_args: process as value
0.000667 [D6] testvar_reloadable: searching for var=vendor, vartype=2, reload_flag=0
0.000674 [D6] testvar_reloadable: found var=vendor, val='(null)' => 'American Power Conversion', vartype=2 => 2, found=0, reloadable=0, reload_flag=0
0.000689 [D6] testvar_reloadable: verdict for (re)loading var=vendor value: 1
0.000696 [D5] send_to_all: SETINFO driver.parameter.vendor "American Power Conversion"
0.000704 [D5] do_upsconf_args: confupsname=akane, var=bus, val=003
0.000712 [D5] do_upsconf_args: call main_arg()
0.000721 [D3] main_arg: var='bus' val='003'
0.000726 [D5] do_upsconf_args: not a main_arg()
0.000736 [D5] do_upsconf_args: process as value
0.000741 [D6] testvar_reloadable: searching for var=bus, vartype=2, reload_flag=0
0.000747 [D6] testvar_reloadable: found var=bus, val='(null)' => '003', vartype=2 => 2, found=0, reloadable=0, reload_flag=0
0.000753 [D6] testvar_reloadable: verdict for (re)loading var=bus value: 1
0.000760 [D5] send_to_all: SETINFO driver.parameter.bus "003"
0.000766 [D5] do_upsconf_args: confupsname=akane, var=device, val=004
0.000772 [D5] do_upsconf_args: call main_arg()
0.000779 [D3] main_arg: var='device' val='004'
0.000786 [D5] do_upsconf_args: not a main_arg()
0.000794 [D5] do_upsconf_args: process as value
0.000799 [D6] testvar_reloadable: searching for var=device, vartype=2, reload_flag=0
0.000806 [D6] testvar_reloadable: found var=device, val='(null)' => '004', vartype=2 => 2, found=0, reloadable=0, reload_flag=0
0.000821 [D6] testvar_reloadable: verdict for (re)loading var=device value: 1
0.000833 [D5] send_to_all: SETINFO driver.parameter.device "004"
0.000840 [D5] do_upsconf_args: confupsname=akane, var=busport, val=003
0.000846 [D5] do_upsconf_args: call main_arg()
0.000852 [D3] main_arg: var='busport' val='003'
0.000858 [D5] do_upsconf_args: not a main_arg()
0.000862 [D5] do_upsconf_args: process as value
0.000868 [D6] testvar_reloadable: searching for var=busport, vartype=2, reload_flag=0
0.000874 [D6] testvar_reloadable: found var=busport, val='(null)' => '003', vartype=2 => 2, found=0, reloadable=0, reload_flag=0
0.000882 [D6] testvar_reloadable: verdict for (re)loading var=busport value: 1
0.000891 [D5] send_to_all: SETINFO driver.parameter.busport "003"
0.000902 [D1] Network UPS Tools version 2.8.2.986-986-gf31b1ebf7 (development iteration after 2.8.2) built with gcc (Ubuntu 13.2.0-23ubuntu4) 13.2.0 and configured with flags: --with-drivers=apc_modbus --with-usb --with-modbus --with-modbus-includes='-I/opt/libmodbus/include/modbus ' --with-modbus-libs='-L/opt/libmodbus/lib -lmodbus ' --with-user=nut --with-group=nut --datadir=/usr/share/nut --sysconfdir=/etc/nut --with-statepath=/run/nut --with-pidpath=/run --with-altpidpath=/run/nut --with-drvpath=/usr/sbin --with-systemdsystemunitdir=/usr/lib/systemd/system --with-pkgconfig-dir=/usr/share/pkgconfig --with-udev-dir=/usr/lib/udev --libdir=/usr/lib/
0.000927 [D1] debug level is '6'
0.000933 [D5] send_to_all: SETINFO driver.debug "6"
0.000941 [D5] send_to_all: SETFLAGS driver.debug RW NUMBER
0.002107 [D1] Succeeded to become_user(nut): now UID=108 GID=105
0.002126 [D1] Signalling UPS [akane]: driver.exit (quietly, no fuss if no driver is running or responding)
0.002142 Can't open /run/nut/apc_modbus-akane: No such file or directory
0.002148 [D1] Request for other driver to exit returned code -1
0.002155 [D1] Socket dialog with the other driver instance (may be absent) failed: No such file or directory
0.002162 [D5] send_to_all: SETINFO device.type "ups"
0.002170 [D5] send_to_all: SETINFO driver.state "init.device"
Number of USB devices: 8
Considering device #0 (05e3:0620)
libusb_open for device #0 failed: Access denied (insufficient permissions)
Considering device #2 (051d:0003)
0.029682 [D3] match_function_regex: matching a device...
0.029856 [D2] _apc_modbus_usb_callback: Matched American Power Conversion Smart-UPS 3000 FW:UPS 09.3 / ID=18 (USB VID/PID 051d:0003)
0.029867 [D2] _apc_modbus_usb_callback: Checking American Power Conversion Smart-UPS 3000 FW:UPS 09.3 / ID=18 (USB VID/PID 051d:0003) report descriptors
0.029952 [D1] _apc_modbus_usb_callback: Found report ids RX=0x90 TX=0x89
0.029960 [D5] send_to_all: SETINFO ups.vendorid "051d"
0.029966 [D5] send_to_all: SETINFO ups.productid "0003"
Found Device 2 (Path 3-2.3):
Vendor ID: 0x051d
Product ID: 0x0003
Bytes flushed (0)
0.040121 [D5] send_to_all: SETINFO driver.state "init.quiet"
0.040130 [D5] send_to_all: SETINFO driver.version "2.8.2.986-986-gf31b1ebf7"
0.040138 [D5] send_to_all: SETINFO driver.version.internal "0.10"
0.040146 [D5] send_to_all: SETINFO driver.name "apc_modbus"
0.040156 [D5] send_to_all: SETINFO driver.state "init.info"
[01][03][02][04][00][78]
Waiting for a confirmation...
*** bit out of range 0 - FD_SETSIZE on fd_set ***: terminated
Aborted (core dumped)
/usr/local/ups/bin$ sudo ./apc_modbus -a ups -DDDDDD 0.000000 [D5] send_to_all: SETINFO driver.state "init.starting" Network UPS Tools driver 2.8.2.986-986-gf31b1ebf7 (development iteration after 2.8.2) - NUT APC Modbus driver 0.10 0.000040 [D5] send_to_all: SETINFO driver.version.usb "libusb-0.1 (or compat)" 0.000145 [D1] Using USB implementation: libusb-0.1 (or compat) 0.000219 [D5] do_upsconf_args: confupsname=ups, var=driver, val=apc_modbus 0.000226 [D5] do_upsconf_args: call main_arg() 0.000228 [D3] main_arg: var='driver' val='apc_modbus' 0.000268 [D5] do_upsconf_args: not a main_arg() 0.000292 [D5] do_upsconf_args: this is a 'driver' setting, may we proceed? 0.000313 [D6] testval_reloadable: var=driver, oldval=apc_modbus, newval=apc_modbus, reloadable=0, reload_flag=0 0.000332 [D6] testval_reloadable: verdict for (re)loading var=driver value: -1 0.000334 [D5] do_upsconf_args: 'driver' setting already applied with this value 0.000336 [D5] do_upsconf_args: confupsname=ups, var=port, val=auto 0.000338 [D5] do_upsconf_args: call main_arg() 0.000339 [D3] main_arg: var='port' val='auto' 0.000341 [D6] testinfo_reloadable: var=port, infoname=driver.parameter.port, newval=auto, reloadable=0, reload_flag=0 0.000343 [D6] testinfo_reloadable: verdict for (re)loading var=port value: 1 0.000345 [D5] send_to_all: SETINFO driver.parameter.port "auto" 0.000369 [D5] do_upsconf_args: confupsname=ups, var=vendorid, val=051D 0.000403 [D5] do_upsconf_args: call main_arg() 0.000425 [D3] main_arg: var='vendorid' val='051D' 0.000446 [D5] do_upsconf_args: not a main_arg() 0.000467 [D5] do_upsconf_args: process as value 0.000487 [D6] testvar_reloadable: searching for var=vendorid, vartype=2, reload_flag=0 0.000497 [D6] testvar_reloadable: found var=vendorid, val='(null)' => '051D', vartype=2 => 2, found=0, reloadable=0, reload_flag=0 0.000515 [D6] testvar_reloadable: verdict for (re)loading var=vendorid value: 1 0.000567 [D5] send_to_all: SETINFO driver.parameter.vendorid "051D" 0.000582 [D5] do_upsconf_args: confupsname=ups, var=productid, val=0003 0.000598 [D5] do_upsconf_args: call main_arg() 0.000618 [D3] main_arg: var='productid' val='0003' 0.000640 [D5] do_upsconf_args: not a main_arg() 0.000660 [D5] do_upsconf_args: process as value 0.000683 [D6] testvar_reloadable: searching for var=productid, vartype=2, reload_flag=0 0.000704 [D6] testvar_reloadable: found var=productid, val='(null)' => '0003', vartype=2 => 2, found=0, reloadable=0, reload_flag=0 0.000751 [D6] testvar_reloadable: verdict for (re)loading var=productid value: 1 0.000793 [D5] send_to_all: SETINFO driver.parameter.productid "0003" 0.000836 [D5] do_upsconf_args: confupsname=ups, var=product, val=Smart-UPS_1500 FW:UPS 06.0 / ID=1027 0.000838 [D5] do_upsconf_args: call main_arg() 0.000840 [D3] main_arg: var='product' val='Smart-UPS_1500 FW:UPS 06.0 / ID=1027' 0.000841 [D5] do_upsconf_args: not a main_arg() 0.000843 [D5] do_upsconf_args: process as value 0.000844 [D6] testvar_reloadable: searching for var=product, vartype=2, reload_flag=0 0.000866 [D6] testvar_reloadable: found var=product, val='(null)' => 'Smart-UPS_1500 FW:UPS 06.0 / ID=1027', vartype=2 => 2, found=0, reloadable=0, reload_flag=0 0.000891 [D6] testvar_reloadable: verdict for (re)loading var=product value: 1 0.000932 [D5] send_to_all: SETINFO driver.parameter.product "Smart-UPS_1500 FW:UPS 06.0 / ID=1027" 0.000956 [D5] do_upsconf_args: confupsname=ups, var=serial, val=3S2343X23271 0.000997 [D5] do_upsconf_args: call main_arg() 0.001018 [D3] main_arg: var='serial' val='3S2343X23271' 0.001040 [D5] do_upsconf_args: not a main_arg() 0.001061 [D5] do_upsconf_args: process as value 0.001081 [D6] testvar_reloadable: searching for var=serial, vartype=2, reload_flag=0 0.001104 [D6] testvar_reloadable: found var=serial, val='(null)' => '3S2343X23271', vartype=2 => 2, found=0, reloadable=0, reload_flag=0 0.001146 [D6] testvar_reloadable: verdict for (re)loading var=serial value: 1 0.001186 [D5] send_to_all: SETINFO driver.parameter.serial "3S2343X23271" 0.001210 [D5] do_upsconf_args: confupsname=ups, var=vendor, val=American Power Conversion 0.001251 [D5] do_upsconf_args: call main_arg() 0.001271 [D3] main_arg: var='vendor' val='American Power Conversion' 0.001292 [D5] do_upsconf_args: not a main_arg() 0.001313 [D5] do_upsconf_args: process as value 0.001333 [D6] testvar_reloadable: searching for var=vendor, vartype=2, reload_flag=0 0.001355 [D6] testvar_reloadable: found var=vendor, val='(null)' => 'American Power Conversion', vartype=2 => 2, found=0, reloadable=0, reload_flag=0 0.001376 [D6] testvar_reloadable: verdict for (re)loading var=vendor value: 1 0.001428 [D5] send_to_all: SETINFO driver.parameter.vendor "American Power Conversion" 0.001434 [D5] do_upsconf_args: confupsname=ups, var=bus, val=002 0.001450 [D5] do_upsconf_args: call main_arg() 0.001477 [D3] main_arg: var='bus' val='002' 0.001500 [D5] do_upsconf_args: not a main_arg() 0.001520 [D5] do_upsconf_args: process as value 0.001542 [D6] testvar_reloadable: searching for var=bus, vartype=2, reload_flag=0 0.001566 [D6] testvar_reloadable: found var=bus, val='(null)' => '002', vartype=2 => 2, found=0, reloadable=0, reload_flag=0 0.001586 [D6] testvar_reloadable: verdict for (re)loading var=bus value: 1 0.001627 [D5] send_to_all: SETINFO driver.parameter.bus "002" 0.001650 [D5] do_upsconf_args: confupsname=ups, var=device, val=004 0.001691 [D5] do_upsconf_args: call main_arg() 0.001711 [D3] main_arg: var='device' val='004' 0.001731 [D5] do_upsconf_args: not a main_arg() 0.001754 [D5] do_upsconf_args: process as value 0.001774 [D6] testvar_reloadable: searching for var=device, vartype=2, reload_flag=0 0.001797 [D6] testvar_reloadable: found var=device, val='(null)' => '004', vartype=2 => 2, found=0, reloadable=0, reload_flag=0 0.001838 [D6] testvar_reloadable: verdict for (re)loading var=device value: 1 0.001859 [D5] send_to_all: SETINFO driver.parameter.device "004" 0.001923 [D1] Network UPS Tools version 2.8.2.986-986-gf31b1ebf7 (development iteration after 2.8.2) built with gcc (Ubuntu 11.4.0-1ubuntu1~22.04) 11.4.0 and configured with flags: --with-drivers=apc_modbus --with-usb --with-modbus --with-modbus-includes=-I/usr/local/ups/include/modbus --with-modbus-libs='-L/usr/local/ups/lib -lmodbus' 0.001938 [D1] debug level is '6' 0.001955 [D5] send_to_all: SETINFO driver.debug "6" 0.001999 [D5] send_to_all: SETFLAGS driver.debug RW NUMBER 0.002246 [D1] Succeeded to become_user(nobody): now UID=65534 GID=65534 0.002292 [D1] Signalling UPS [ups]: driver.exit (quietly, no fuss if no driver is running or responding) 0.002301 Can't open /var/state/ups/apc_modbus-ups: No such file or directory 0.002338 [D1] Request for other driver to exit returned code -1 0.002378 [D1] Socket dialog with the other driver instance (may be absent) failed: No such file or directory 0.002426 [D5] send_to_all: SETINFO device.type "ups" 0.002442 [D5] send_to_all: SETINFO driver.state "init.device" Number of USB devices: 5 Considering device #1 (051d:0003) 5.423922 [D3] match_function_regex: matching a device... 5.424066 [D2] match_function_regex: failed match of Vendor: (null) 5.424074 [D2] _apc_modbus_usb_callback: Matched (null) (null) (USB VID/PID 051d:0003) 5.424093 [D2] _apc_modbus_usb_callback: Checking (null) (null) (USB VID/PID 051d:0003) report descriptors 5.424180 [D1] _apc_modbus_usb_callback: Found report ids RX=0x90 TX=0x89 5.424203 [D5] send_to_all: SETINFO ups.vendorid "051d" 5.424220 [D5] send_to_all: SETINFO ups.productid "0003" Found Device 1 (Path 2-2.1): Vendor ID: 0x051d Product ID: 0x0003 Bytes flushed (126) 5.438261 [D5] send_to_all: SETINFO driver.state "init.quiet" 5.438266 [D5] send_to_all: SETINFO driver.version "2.8.2.986-986-gf31b1ebf7" 5.438329 [D5] send_to_all: SETINFO driver.version.internal "0.10" 5.438334 [D5] send_to_all: SETINFO driver.name "apc_modbus" 5.438365 [D5] send_to_all: SETINFO driver.state "init.info" [01][03][02][04][00][78] Waiting for a confirmation... ***** buffer overflow detected *: terminated Aborted
UPDATE: Seems like a practical duplicate of #2609, please continue discussion there to keep it compact :)
Note that what I fixed in #2982 cannot have anything to do with buffer overflows / memory corruption, so this bug should remain as a separate issue.
I tried running the driver under valgrind but alas, the machine I'm using for this is an old Arch Linux ARM install on a Raspberry Pi, and it looks like valgrind is broken (classic ALARM...), nor does the issue repro for me in general anyway.
For those who can repro and have a less broken system, installing valgrind and running sudo valgrind ./apc_modbus -a ups -DDDDDD (or similar) would be a good first shot to try to find the bug.
I have an APC Smart-UPS 750 connected via USB to a Intel i3 N355 based server,
ups.conf:
[smartups]
driver = "apc_modbus"
port = "auto"
vendorid = "051D"
productid = "0003"
product = "Smart-UPS_750 FW:UPS 16.5 / ID=1047"
serial = "AS2509262881"
vendor = "American Power Conversion"
# bus = "003"
# device = "002"
Checking with valgrind
valgrind -s /usr/local/bin/apc_modbus -a smartups -u nut -DDDDD
==736766== Memcheck, a memory error detector
==736766== Copyright (C) 2002-2022, and GNU GPL'd, by Julian Seward et al.
==736766== Using Valgrind-3.22.0 and LibVEX; rerun with -h for copyright info
==736766== Command: /usr/local/bin/apc_modbus -a smartups -u nut -DDDDD
==736766==
0.000263 [D5] send_to_all: SETINFO driver.state "init.starting"
Network UPS Tools 2.8.4.8-8+g0459ffb8d (development iteration after 2.8.4) - NUT APC Modbus driver with USB support (libmodbus link type: dynamic) 0.16
0.027232 [D5] send_to_all: SETINFO driver.version.usb "libusb-0.1 (or compat)"
0.028093 [D1] Using USB implementation: libusb-0.1 (or compat)
0.028714 [D1] This build of the driver is USB-capable; also Serial and TCP Modbus RTU are supported
0.041832 [D5] do_upsconf_args: confupsname=smartups, var=driver, val=apc_modbus
0.042180 [D5] do_upsconf_args: call main_arg()
0.042604 [D3] main_arg: var='driver' val='apc_modbus'
0.044158 [D5] do_upsconf_args: not a main_arg()
0.044448 [D5] do_upsconf_args: this is a 'driver' setting, may we proceed?
0.045189 [D5] do_upsconf_args: 'driver' setting already applied with this value
0.045331 [D5] do_upsconf_args: confupsname=smartups, var=port, val=auto
0.045367 [D5] do_upsconf_args: call main_arg()
0.045405 [D3] main_arg: var='port' val='auto'
0.046077 [D5] send_to_all: SETINFO driver.parameter.port "auto"
0.046314 [D5] do_upsconf_args: confupsname=smartups, var=vendorid, val=051D
0.046351 [D5] do_upsconf_args: call main_arg()
0.046386 [D3] main_arg: var='vendorid' val='051D'
0.046424 [D5] do_upsconf_args: not a main_arg()
0.046613 [D5] do_upsconf_args: process as value
0.048537 [D5] send_to_all: SETINFO driver.parameter.vendorid "051D"
0.048776 [D5] do_upsconf_args: confupsname=smartups, var=productid, val=0003
0.048813 [D5] do_upsconf_args: call main_arg()
0.048846 [D3] main_arg: var='productid' val='0003'
0.048877 [D5] do_upsconf_args: not a main_arg()
0.048909 [D5] do_upsconf_args: process as value
0.048989 [D5] send_to_all: SETINFO driver.parameter.productid "0003"
0.049331 [D5] do_upsconf_args: confupsname=smartups, var=product, val=Smart-UPS_750 FW:UPS 16.5 / ID=1047
0.049376 [D5] do_upsconf_args: call main_arg()
0.049410 [D3] main_arg: var='product' val='Smart-UPS_750 FW:UPS 16.5 / ID=1047'
0.049444 [D5] do_upsconf_args: not a main_arg()
0.049477 [D5] do_upsconf_args: process as value
0.049560 [D5] send_to_all: SETINFO driver.parameter.product "Smart-UPS_750 FW:UPS 16.5 / ID=1047"
0.049747 [D5] do_upsconf_args: confupsname=smartups, var=serial, val=AS2509262881
0.049782 [D5] do_upsconf_args: call main_arg()
0.049820 [D3] main_arg: var='serial' val='AS2509262881'
0.049853 [D5] do_upsconf_args: not a main_arg()
0.049882 [D5] do_upsconf_args: process as value
0.049956 [D5] send_to_all: SETINFO driver.parameter.serial "AS2509262881"
0.050016 [D5] do_upsconf_args: confupsname=smartups, var=vendor, val=American Power Conversion
0.050047 [D5] do_upsconf_args: call main_arg()
0.050078 [D3] main_arg: var='vendor' val='American Power Conversion'
0.050134 [D5] do_upsconf_args: not a main_arg()
0.050165 [D5] do_upsconf_args: process as value
0.050240 [D5] send_to_all: SETINFO driver.parameter.vendor "American Power Conversion"
0.055261 [D1] Built-in default or configured user for drivers 'nut' was ignored due to 'nut' specified on command line
0.055609 [D1] Network UPS Tools version 2.8.4.8-8+g0459ffb8d (development iteration after 2.8.4), 64-bit build for x86_64, built with gcc (Ubuntu 13.3.0-6ubuntu2~24.04) 13.3.0 and configured with flags: --with-drivers=apc_modbus --with-usb --with-modbus --with-modbus-includes=-I/usr/local/include/modbus --with-modbus-libs='-L/usr/local/lib -lmodbus' --sysconfdir=/etc/nut --includedir=/usr/local/include --prefix=/usr/local --runstatedir=/run --localstatedir=/usr/local/var --with-user=nut --with-group=nut
0.056924 [D1] debug level is '5'
0.057099 [D5] send_to_all: SETINFO driver.debug "5"
0.059100 [D5] send_to_all: SETFLAGS driver.debug RW NUMBER
0.253874 [D1] Succeeded to become_user(nut): now UID=129 GID=126
0.255647 [D1] Signalling UPS [smartups]: driver.exit (quietly, no fuss if no driver is running or responding)
0.261659 Can't open /var/state/ups/apc_modbus-smartups: No such file or directory
0.262602 [D1] Request for other driver to exit returned code -1
0.263515 [D1] Socket dialog with the other driver instance (may be absent) failed: No such file or directory
0.263991 [D5] send_to_all: SETINFO device.type "ups"
0.264704 [D5] send_to_all: SETINFO driver.state "init.device"
0.535379 [D3] match_function_regex: matching a device...
0.552799 [D2] _apc_modbus_usb_callback: Matched American Power Conversion Smart-UPS_750 FW:UPS 16.5 / ID=1047 (USB VID/PID 051d:0003)
0.553151 [D2] _apc_modbus_usb_callback: Checking American Power Conversion Smart-UPS_750 FW:UPS 16.5 / ID=1047 (USB VID/PID 051d:0003) report descriptors
0.559533 [D1] _apc_modbus_usb_callback: Found report ids RX=0x90 TX=0x89
0.559893 [D5] send_to_all: SETINFO ups.vendorid "051d"
0.560075 [D5] send_to_all: SETINFO ups.productid "0003"
==736766== Invalid read of size 1
==736766== at 0x484F226: strlen (in /usr/libexec/valgrind/vgpreload_memcheck-amd64-linux.so)
==736766== by 0x493F352: strdup (strdup.c:41)
==736766== by 0x1151B0: USBNewExactMatcher (usb-common.c:147)
==736766== by 0x110332: _apc_modbus_create_reopen_matcher (apc_modbus.c:923)
==736766== by 0x11232E: upsdrv_initups (apc_modbus.c:1970)
==736766== by 0x10EDBA: main (main.c:2837)
==736766== Address 0x1ffeffebf0 is on thread 1's stack
==736766== 2792 bytes below stack pointer
==736766==
==736766== Invalid read of size 1
==736766== at 0x484F234: strlen (in /usr/libexec/valgrind/vgpreload_memcheck-amd64-linux.so)
==736766== by 0x493F352: strdup (strdup.c:41)
==736766== by 0x1151B0: USBNewExactMatcher (usb-common.c:147)
==736766== by 0x110332: _apc_modbus_create_reopen_matcher (apc_modbus.c:923)
==736766== by 0x11232E: upsdrv_initups (apc_modbus.c:1970)
==736766== by 0x10EDBA: main (main.c:2837)
==736766== Address 0x1ffeffebf1 is on thread 1's stack
==736766== 2791 bytes below stack pointer
==736766==
==736766== Invalid read of size 1
==736766== at 0x4853E10: __memcpy_chk (in /usr/libexec/valgrind/vgpreload_memcheck-amd64-linux.so)
==736766== by 0x1151B0: USBNewExactMatcher (usb-common.c:147)
==736766== by 0x110332: _apc_modbus_create_reopen_matcher (apc_modbus.c:923)
==736766== by 0x11232E: upsdrv_initups (apc_modbus.c:1970)
==736766== by 0x10EDBA: main (main.c:2837)
==736766== Address 0x1ffeffebf0 is on thread 1's stack
==736766== 2824 bytes below stack pointer
==736766==
==736766== Invalid read of size 1
==736766== at 0x4853E1E: __memcpy_chk (in /usr/libexec/valgrind/vgpreload_memcheck-amd64-linux.so)
==736766== by 0x1151B0: USBNewExactMatcher (usb-common.c:147)
==736766== by 0x110332: _apc_modbus_create_reopen_matcher (apc_modbus.c:923)
==736766== by 0x11232E: upsdrv_initups (apc_modbus.c:1970)
==736766== by 0x10EDBA: main (main.c:2837)
==736766== Address 0x1ffeffebf2 is on thread 1's stack
==736766== 2822 bytes below stack pointer
==736766==
==736766== Invalid read of size 1
==736766== at 0x484F226: strlen (in /usr/libexec/valgrind/vgpreload_memcheck-amd64-linux.so)
==736766== by 0x493F352: strdup (strdup.c:41)
==736766== by 0x1151C6: USBNewExactMatcher (usb-common.c:148)
==736766== by 0x110332: _apc_modbus_create_reopen_matcher (apc_modbus.c:923)
==736766== by 0x11232E: upsdrv_initups (apc_modbus.c:1970)
==736766== by 0x10EDBA: main (main.c:2837)
==736766== Address 0x1ffeffecf0 is on thread 1's stack
==736766== 2536 bytes below stack pointer
==736766==
==736766== Invalid read of size 1
==736766== at 0x484F234: strlen (in /usr/libexec/valgrind/vgpreload_memcheck-amd64-linux.so)
==736766== by 0x493F352: strdup (strdup.c:41)
==736766== by 0x1151C6: USBNewExactMatcher (usb-common.c:148)
==736766== by 0x110332: _apc_modbus_create_reopen_matcher (apc_modbus.c:923)
==736766== by 0x11232E: upsdrv_initups (apc_modbus.c:1970)
==736766== by 0x10EDBA: main (main.c:2837)
==736766== Address 0x1ffeffecf1 is on thread 1's stack
==736766== 2535 bytes below stack pointer
==736766==
==736766== Invalid read of size 1
==736766== at 0x4853E10: __memcpy_chk (in /usr/libexec/valgrind/vgpreload_memcheck-amd64-linux.so)
==736766== by 0x1151C6: USBNewExactMatcher (usb-common.c:148)
==736766== by 0x110332: _apc_modbus_create_reopen_matcher (apc_modbus.c:923)
==736766== by 0x11232E: upsdrv_initups (apc_modbus.c:1970)
==736766== by 0x10EDBA: main (main.c:2837)
==736766== Address 0x1ffeffecf0 is on thread 1's stack
==736766== 2568 bytes below stack pointer
==736766==
==736766== Invalid read of size 1
==736766== at 0x4853E1E: __memcpy_chk (in /usr/libexec/valgrind/vgpreload_memcheck-amd64-linux.so)
==736766== by 0x1151C6: USBNewExactMatcher (usb-common.c:148)
==736766== by 0x110332: _apc_modbus_create_reopen_matcher (apc_modbus.c:923)
==736766== by 0x11232E: upsdrv_initups (apc_modbus.c:1970)
==736766== by 0x10EDBA: main (main.c:2837)
==736766== Address 0x1ffeffecf2 is on thread 1's stack
==736766== 2566 bytes below stack pointer
==736766==
==736766== Invalid read of size 1
==736766== at 0x484F226: strlen (in /usr/libexec/valgrind/vgpreload_memcheck-amd64-linux.so)
==736766== by 0x493F352: strdup (strdup.c:41)
==736766== by 0x1151DC: USBNewExactMatcher (usb-common.c:149)
==736766== by 0x110332: _apc_modbus_create_reopen_matcher (apc_modbus.c:923)
==736766== by 0x11232E: upsdrv_initups (apc_modbus.c:1970)
==736766== by 0x10EDBA: main (main.c:2837)
==736766== Address 0x1ffeffedf0 is on thread 1's stack
==736766== 2280 bytes below stack pointer
==736766==
==736766== Invalid read of size 1
==736766== at 0x484F234: strlen (in /usr/libexec/valgrind/vgpreload_memcheck-amd64-linux.so)
==736766== by 0x493F352: strdup (strdup.c:41)
==736766== by 0x1151DC: USBNewExactMatcher (usb-common.c:149)
==736766== by 0x110332: _apc_modbus_create_reopen_matcher (apc_modbus.c:923)
==736766== by 0x11232E: upsdrv_initups (apc_modbus.c:1970)
==736766== by 0x10EDBA: main (main.c:2837)
==736766== Address 0x1ffeffedf1 is on thread 1's stack
==736766== 2279 bytes below stack pointer
==736766==
==736766== Invalid read of size 1
==736766== at 0x4853E10: __memcpy_chk (in /usr/libexec/valgrind/vgpreload_memcheck-amd64-linux.so)
==736766== by 0x1151DC: USBNewExactMatcher (usb-common.c:149)
==736766== by 0x110332: _apc_modbus_create_reopen_matcher (apc_modbus.c:923)
==736766== by 0x11232E: upsdrv_initups (apc_modbus.c:1970)
==736766== by 0x10EDBA: main (main.c:2837)
==736766== Address 0x1ffeffedf0 is on thread 1's stack
==736766== 2312 bytes below stack pointer
==736766==
==736766== Invalid read of size 1
==736766== at 0x4853E1E: __memcpy_chk (in /usr/libexec/valgrind/vgpreload_memcheck-amd64-linux.so)
==736766== by 0x1151DC: USBNewExactMatcher (usb-common.c:149)
==736766== by 0x110332: _apc_modbus_create_reopen_matcher (apc_modbus.c:923)
==736766== by 0x11232E: upsdrv_initups (apc_modbus.c:1970)
==736766== by 0x10EDBA: main (main.c:2837)
==736766== Address 0x1ffeffedf2 is on thread 1's stack
==736766== 2310 bytes below stack pointer
==736766==
0.592379 [D5] send_to_all: SETINFO driver.state "init.quiet"
0.592644 [D5] send_to_all: SETINFO driver.version "2.8.4.8-8+g0459ffb8d"
0.592822 [D5] send_to_all: SETINFO driver.version.internal "0.16"
0.592982 [D5] send_to_all: SETINFO driver.name "apc_modbus"
0.593192 [D5] send_to_all: SETINFO driver.state "init.info"
1.106405 _apc_modbus_read_registers: Read of 516:636 failed: Connection timed out (auto)
2.126777 Can't read inventory information from the UPS
2.131693 [D5] send_to_all: SETINFO driver.state "cleanup.upsdrv"
2.156269 [D5] send_to_all: SETINFO driver.state "cleanup.exit"
2.157849 [D1] upsnotify: failed to notify about state NOTIFY_STATE_STOPPING: no notification tech defined, will not spam more about it
2.158376 [D1] On systems without service units, consider `export NUT_QUIET_INIT_UPSNOTIFY=true`
==736766==
==736766== HEAP SUMMARY:
==736766== in use at exit: 186,855 bytes in 557 blocks
==736766== total heap usage: 3,564 allocs, 3,007 frees, 1,054,365 bytes allocated
==736766==
==736766== LEAK SUMMARY:
==736766== definitely lost: 1,640 bytes in 10 blocks
==736766== indirectly lost: 181,257 bytes in 538 blocks
==736766== possibly lost: 0 bytes in 0 blocks
==736766== still reachable: 3,958 bytes in 9 blocks
==736766== suppressed: 0 bytes in 0 blocks
==736766== Rerun with --leak-check=full to see details of leaked memory
==736766==
==736766== ERROR SUMMARY: 160 errors from 12 contexts (suppressed: 0 from 0)
==736766==
==736766== 1 errors in context 1 of 12:
==736766== Invalid read of size 1
==736766== at 0x484F226: strlen (in /usr/libexec/valgrind/vgpreload_memcheck-amd64-linux.so)
==736766== by 0x493F352: strdup (strdup.c:41)
==736766== by 0x1151DC: USBNewExactMatcher (usb-common.c:149)
==736766== by 0x110332: _apc_modbus_create_reopen_matcher (apc_modbus.c:923)
==736766== by 0x11232E: upsdrv_initups (apc_modbus.c:1970)
==736766== by 0x10EDBA: main (main.c:2837)
==736766== Address 0x1ffeffedf0 is on thread 1's stack
==736766== 2280 bytes below stack pointer
==736766==
==736766==
==736766== 1 errors in context 2 of 12:
==736766== Invalid read of size 1
==736766== at 0x484F226: strlen (in /usr/libexec/valgrind/vgpreload_memcheck-amd64-linux.so)
==736766== by 0x493F352: strdup (strdup.c:41)
==736766== by 0x1151C6: USBNewExactMatcher (usb-common.c:148)
==736766== by 0x110332: _apc_modbus_create_reopen_matcher (apc_modbus.c:923)
==736766== by 0x11232E: upsdrv_initups (apc_modbus.c:1970)
==736766== by 0x10EDBA: main (main.c:2837)
==736766== Address 0x1ffeffecf0 is on thread 1's stack
==736766== 2536 bytes below stack pointer
==736766==
==736766==
==736766== 1 errors in context 3 of 12:
==736766== Invalid read of size 1
==736766== at 0x484F226: strlen (in /usr/libexec/valgrind/vgpreload_memcheck-amd64-linux.so)
==736766== by 0x493F352: strdup (strdup.c:41)
==736766== by 0x1151B0: USBNewExactMatcher (usb-common.c:147)
==736766== by 0x110332: _apc_modbus_create_reopen_matcher (apc_modbus.c:923)
==736766== by 0x11232E: upsdrv_initups (apc_modbus.c:1970)
==736766== by 0x10EDBA: main (main.c:2837)
==736766== Address 0x1ffeffebf0 is on thread 1's stack
==736766== 2792 bytes below stack pointer
==736766==
==736766==
==736766== 8 errors in context 4 of 12:
==736766== Invalid read of size 1
==736766== at 0x4853E1E: __memcpy_chk (in /usr/libexec/valgrind/vgpreload_memcheck-amd64-linux.so)
==736766== by 0x1151DC: USBNewExactMatcher (usb-common.c:149)
==736766== by 0x110332: _apc_modbus_create_reopen_matcher (apc_modbus.c:923)
==736766== by 0x11232E: upsdrv_initups (apc_modbus.c:1970)
==736766== by 0x10EDBA: main (main.c:2837)
==736766== Address 0x1ffeffedf2 is on thread 1's stack
==736766== 2310 bytes below stack pointer
==736766==
==736766==
==736766== 9 errors in context 5 of 12:
==736766== Invalid read of size 1
==736766== at 0x4853E10: __memcpy_chk (in /usr/libexec/valgrind/vgpreload_memcheck-amd64-linux.so)
==736766== by 0x1151DC: USBNewExactMatcher (usb-common.c:149)
==736766== by 0x110332: _apc_modbus_create_reopen_matcher (apc_modbus.c:923)
==736766== by 0x11232E: upsdrv_initups (apc_modbus.c:1970)
==736766== by 0x10EDBA: main (main.c:2837)
==736766== Address 0x1ffeffedf0 is on thread 1's stack
==736766== 2312 bytes below stack pointer
==736766==
==736766==
==736766== 13 errors in context 6 of 12:
==736766== Invalid read of size 1
==736766== at 0x4853E1E: __memcpy_chk (in /usr/libexec/valgrind/vgpreload_memcheck-amd64-linux.so)
==736766== by 0x1151B0: USBNewExactMatcher (usb-common.c:147)
==736766== by 0x110332: _apc_modbus_create_reopen_matcher (apc_modbus.c:923)
==736766== by 0x11232E: upsdrv_initups (apc_modbus.c:1970)
==736766== by 0x10EDBA: main (main.c:2837)
==736766== Address 0x1ffeffebf2 is on thread 1's stack
==736766== 2822 bytes below stack pointer
==736766==
==736766==
==736766== 14 errors in context 7 of 12:
==736766== Invalid read of size 1
==736766== at 0x4853E10: __memcpy_chk (in /usr/libexec/valgrind/vgpreload_memcheck-amd64-linux.so)
==736766== by 0x1151B0: USBNewExactMatcher (usb-common.c:147)
==736766== by 0x110332: _apc_modbus_create_reopen_matcher (apc_modbus.c:923)
==736766== by 0x11232E: upsdrv_initups (apc_modbus.c:1970)
==736766== by 0x10EDBA: main (main.c:2837)
==736766== Address 0x1ffeffebf0 is on thread 1's stack
==736766== 2824 bytes below stack pointer
==736766==
==736766==
==736766== 16 errors in context 8 of 12:
==736766== Invalid read of size 1
==736766== at 0x484F234: strlen (in /usr/libexec/valgrind/vgpreload_memcheck-amd64-linux.so)
==736766== by 0x493F352: strdup (strdup.c:41)
==736766== by 0x1151DC: USBNewExactMatcher (usb-common.c:149)
==736766== by 0x110332: _apc_modbus_create_reopen_matcher (apc_modbus.c:923)
==736766== by 0x11232E: upsdrv_initups (apc_modbus.c:1970)
==736766== by 0x10EDBA: main (main.c:2837)
==736766== Address 0x1ffeffedf1 is on thread 1's stack
==736766== 2279 bytes below stack pointer
==736766==
==736766==
==736766== 17 errors in context 9 of 12:
==736766== Invalid read of size 1
==736766== at 0x4853E1E: __memcpy_chk (in /usr/libexec/valgrind/vgpreload_memcheck-amd64-linux.so)
==736766== by 0x1151C6: USBNewExactMatcher (usb-common.c:148)
==736766== by 0x110332: _apc_modbus_create_reopen_matcher (apc_modbus.c:923)
==736766== by 0x11232E: upsdrv_initups (apc_modbus.c:1970)
==736766== by 0x10EDBA: main (main.c:2837)
==736766== Address 0x1ffeffecf2 is on thread 1's stack
==736766== 2566 bytes below stack pointer
==736766==
==736766==
==736766== 19 errors in context 10 of 12:
==736766== Invalid read of size 1
==736766== at 0x4853E10: __memcpy_chk (in /usr/libexec/valgrind/vgpreload_memcheck-amd64-linux.so)
==736766== by 0x1151C6: USBNewExactMatcher (usb-common.c:148)
==736766== by 0x110332: _apc_modbus_create_reopen_matcher (apc_modbus.c:923)
==736766== by 0x11232E: upsdrv_initups (apc_modbus.c:1970)
==736766== by 0x10EDBA: main (main.c:2837)
==736766== Address 0x1ffeffecf0 is on thread 1's stack
==736766== 2568 bytes below stack pointer
==736766==
==736766==
==736766== 26 errors in context 11 of 12:
==736766== Invalid read of size 1
==736766== at 0x484F234: strlen (in /usr/libexec/valgrind/vgpreload_memcheck-amd64-linux.so)
==736766== by 0x493F352: strdup (strdup.c:41)
==736766== by 0x1151B0: USBNewExactMatcher (usb-common.c:147)
==736766== by 0x110332: _apc_modbus_create_reopen_matcher (apc_modbus.c:923)
==736766== by 0x11232E: upsdrv_initups (apc_modbus.c:1970)
==736766== by 0x10EDBA: main (main.c:2837)
==736766== Address 0x1ffeffebf1 is on thread 1's stack
==736766== 2791 bytes below stack pointer
==736766==
==736766==
==736766== 35 errors in context 12 of 12:
==736766== Invalid read of size 1
==736766== at 0x484F234: strlen (in /usr/libexec/valgrind/vgpreload_memcheck-amd64-linux.so)
==736766== by 0x493F352: strdup (strdup.c:41)
==736766== by 0x1151C6: USBNewExactMatcher (usb-common.c:148)
==736766== by 0x110332: _apc_modbus_create_reopen_matcher (apc_modbus.c:923)
==736766== by 0x11232E: upsdrv_initups (apc_modbus.c:1970)
==736766== by 0x10EDBA: main (main.c:2837)
==736766== Address 0x1ffeffecf1 is on thread 1's stack
==736766== 2535 bytes below stack pointer
==736766==
==736766== ERROR SUMMARY: 160 errors from 12 contexts (suppressed: 0 from 0)
==736766== could not unlink /tmp/vgdb-pipe-from-vgdb-to-736766-by-root-on-???
==736766== could not unlink /tmp/vgdb-pipe-to-vgdb-from-736766-by-root-on-???
==736766== could not unlink /tmp/vgdb-pipe-shared-mem-vgdb-736766-by-root-on-???
nut was build from source. head SHA of main is 0459ffb8db15fff0264335f316f0cbd1d71badc3
libmodbus also built from source, head SHA of main 1c372e31663714fc0c707936735358a27365b074 (tag: v3.1.11+rtu_usb-NUTv2.8.4)
Traveling now so can't check in detail, but there's no strdup.c in NUT at least (we do carry some fallbacks for obscure platforms, but not this one). So something in system libs and/or valgrind's own honeypots considers these reads invalid. No idea why - is there some overflow-by-1, or a read of one byte (e.g. the '\0' for an empty valid string?.. At least does not seem to be a null dereference...
The broken function is _apc_modbus_usb_lib_to_nut(). This is assigning string members of the modbus_usb_device_t it is called with directly to the output USBDevice_t structure. Since this codepath is called in a callback from libmodbus, via _apc_modbus_usb_callback(), the strings are only allocated on the stack inside modbus, and are illegal to hold onto after the callback completes. When the USBDevice_t is later used, the pointers are invalid and dereferencing them is undefined behavior.
Classic C lifetime bug, and this is exactly the kind of bug that is prevalent in C codebases (due to lax lifetime documentation and no compiler support for enforcing it), and which is impossible in Rust. You know the drill ;)
Fix is to strdup those buffers into the heap (and, if this is expected to be called more than once per lifetime of the driver anyway, add a cleanup path so they don't leak forever).
Aha, got it, thanks for the analysis. I'll be largely online only after a few days - care to offer a PR please?
See #3069. I don't have time to fully test right now, but at least the source file is compile tested. @asrashley try that branch maybe?
using the marcan:apc_modbus_strdup branch
0.000000 [D5] send_to_all: SETINFO driver.state "init.starting"
Network UPS Tools 2.8.4.11.2-13+ge9d254ef7 (development iteration after 2.8.4) - NUT APC Modbus driver with USB support (libmodbus link type: dynamic) 0.16
0.000207 [D5] send_to_all: SETINFO driver.version.usb "libusb-0.1 (or compat)"
0.000220 [D1] Using USB implementation: libusb-0.1 (or compat)
0.000228 [D1] This build of the driver is USB-capable; also Serial and TCP Modbus RTU are supported
0.000392 [D5] do_upsconf_args: confupsname=smartups, var=driver, val=apc_modbus
0.000408 [D5] do_upsconf_args: call main_arg()
0.000427 [D3] main_arg: var='driver' val='apc_modbus'
0.000445 [D5] do_upsconf_args: not a main_arg()
0.000452 [D5] do_upsconf_args: this is a 'driver' setting, may we proceed?
0.000461 [D5] do_upsconf_args: 'driver' setting already applied with this value
0.000471 [D5] do_upsconf_args: confupsname=smartups, var=port, val=auto
0.000478 [D5] do_upsconf_args: call main_arg()
0.000485 [D3] main_arg: var='port' val='auto'
0.000495 [D5] send_to_all: SETINFO driver.parameter.port "auto"
0.000508 [D5] do_upsconf_args: confupsname=smartups, var=vendorid, val=051D
0.000516 [D5] do_upsconf_args: call main_arg()
0.000526 [D3] main_arg: var='vendorid' val='051D'
0.000534 [D5] do_upsconf_args: not a main_arg()
0.000544 [D5] do_upsconf_args: process as value
0.000558 [D5] send_to_all: SETINFO driver.parameter.vendorid "051D"
0.000572 [D5] do_upsconf_args: confupsname=smartups, var=productid, val=0003
0.000582 [D5] do_upsconf_args: call main_arg()
0.000595 [D3] main_arg: var='productid' val='0003'
0.000611 [D5] do_upsconf_args: not a main_arg()
0.000643 [D5] do_upsconf_args: process as value
0.000659 [D5] send_to_all: SETINFO driver.parameter.productid "0003"
0.000677 [D5] do_upsconf_args: confupsname=smartups, var=product, val=Smart-UPS_750 FW:UPS 16.5 / ID=1047
0.000687 [D5] do_upsconf_args: call main_arg()
0.000699 [D3] main_arg: var='product' val='Smart-UPS_750 FW:UPS 16.5 / ID=1047'
0.000710 [D5] do_upsconf_args: not a main_arg()
0.000717 [D5] do_upsconf_args: process as value
0.000742 [D5] send_to_all: SETINFO driver.parameter.product "Smart-UPS_750 FW:UPS 16.5 / ID=1047"
0.000755 [D5] do_upsconf_args: confupsname=smartups, var=serial, val=AS2509262881
0.000763 [D5] do_upsconf_args: call main_arg()
0.000770 [D3] main_arg: var='serial' val='AS2509262881'
0.000776 [D5] do_upsconf_args: not a main_arg()
0.000783 [D5] do_upsconf_args: process as value
0.000795 [D5] send_to_all: SETINFO driver.parameter.serial "AS2509262881"
0.000815 [D5] do_upsconf_args: confupsname=smartups, var=vendor, val=American Power Conversion
0.000844 [D5] do_upsconf_args: call main_arg()
0.000852 [D3] main_arg: var='vendor' val='American Power Conversion'
0.000875 [D5] do_upsconf_args: not a main_arg()
0.000894 [D5] do_upsconf_args: process as value
0.000931 [D5] send_to_all: SETINFO driver.parameter.vendor "American Power Conversion"
0.000961 [D1] Built-in default or configured user for drivers 'nut' was ignored due to 'nut' specified on command line
0.000988 [D1] Network UPS Tools version 2.8.4.11.2-13+ge9d254ef7 (development iteration after 2.8.4), 64-bit build for x86_64, built with gcc (Ubuntu 13.3.0-6ubuntu2~24.04) 13.3.0 and configured with flags: --with-drivers=apc_modbus --with-usb --with-modbus --with-modbus-includes=-I/usr/local/include/modbus --with-modbus-libs='-L/usr/local/lib -lmodbus' --sysconfdir=/etc/nut --includedir=/usr/local/include --prefix=/usr/local --runstatedir=/run --localstatedir=/usr/local/var --with-user=nut --with-group=nut
0.001057 [D1] debug level is '5'
0.001068 [D5] send_to_all: SETINFO driver.debug "5"
0.001087 [D5] send_to_all: SETFLAGS driver.debug RW NUMBER
0.003532 [D1] Succeeded to become_user(nut): now UID=129 GID=126
0.003578 [D1] Signalling UPS [smartups]: driver.exit (quietly, no fuss if no driver is running or responding)
0.003588 Can't open /var/state/ups/apc_modbus-smartups: No such file or directory
0.003590 [D1] Request for other driver to exit returned code -1
0.003598 [D1] Socket dialog with the other driver instance (may be absent) failed: No such file or directory
0.003602 [D5] send_to_all: SETINFO device.type "ups"
0.003606 [D5] send_to_all: SETINFO driver.state "init.device"
0.041472 [D3] match_function_regex: matching a device...
0.041707 [D2] _apc_modbus_usb_callback: Matched American Power Conversion Smart-UPS_750 FW:UPS 16.5 / ID=1047 (USB VID/PID 051d:0003)
0.041731 [D2] _apc_modbus_usb_callback: Checking American Power Conversion Smart-UPS_750 FW:UPS 16.5 / ID=1047 (USB VID/PID 051d:0003) report descriptors
0.041910 [D1] _apc_modbus_usb_callback: Found report ids RX=0x90 TX=0x89
0.041951 [D5] send_to_all: SETINFO ups.vendorid "051d"
0.041963 [D5] send_to_all: SETINFO ups.productid "0003"
0.052178 [D5] send_to_all: SETINFO driver.state "init.quiet"
0.052212 [D5] send_to_all: SETINFO driver.version "2.8.4.11.2-13+ge9d254ef7"
0.052225 [D5] send_to_all: SETINFO driver.version.internal "0.16"
0.052235 [D5] send_to_all: SETINFO driver.name "apc_modbus"
0.052244 [D5] send_to_all: SETINFO driver.state "init.info"
0.560255 _apc_modbus_read_registers: Read of 516:636 failed: Connection timed out (auto)
1.571011 Can't read inventory information from the UPS
1.571070 [D5] send_to_all: SETINFO driver.state "cleanup.upsdrv"
1.571428 [D5] send_to_all: SETINFO driver.state "cleanup.exit"
1.571450 [D1] upsnotify: failed to notify about state NOTIFY_STATE_STOPPING: no notification tech defined, will not spam more about it
1.571469 [D1] On systems without service units, consider `export NUT_QUIET_INIT_UPSNOTIFY=true`
valgrind is happier with these changes applied
==2916111== HEAP SUMMARY:
==2916111== in use at exit: 186,855 bytes in 557 blocks
==2916111== total heap usage: 3,586 allocs, 3,029 frees, 1,051,585 bytes allocated
==2916111==
==2916111== LEAK SUMMARY:
==2916111== definitely lost: 1,640 bytes in 10 blocks
==2916111== indirectly lost: 181,257 bytes in 538 blocks
==2916111== possibly lost: 0 bytes in 0 blocks
==2916111== still reachable: 3,958 bytes in 9 blocks
==2916111== suppressed: 0 bytes in 0 blocks
==2916111== Rerun with --leak-check=full to see details of leaked memory
==2916111==
==2916111== ERROR SUMMARY: 0 errors from 0 contexts (suppressed: 0 from 0)
The kernel messages still showing
[369031.866162] usb 3-4: usbfs: process 2912725 (apc_modbus) did not claim interface 0 before use
it sounds like there might be multiple issues, not just the invalid memory access.
@asrashley That's now #2609. The kernel message is harmless, the issue is just that communication with the UPS simply doesn't work at all for some reason.
Perhaps now this bug can be closed and the remaining issues tracked in #2609? It would be nice if @cbrherms could confirm that the original crash is fixed.