nut icon indicating copy to clipboard operation
nut copied to clipboard

apc_modbus "buffer overflow detected" - usb enabled libmodbus

Open cbrherms opened this issue 1 year ago • 12 comments

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

cbrherms avatar Jan 28 '24 20:01 cbrherms