Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

apc_modbus "buffer overflow detected" - usb enabled libmodbus #2289

Open
cbrherms opened this issue Jan 28, 2024 · 12 comments
Open

apc_modbus "buffer overflow detected" - usb enabled libmodbus #2289

cbrherms opened this issue Jan 28, 2024 · 12 comments
Labels
APC bug impacts-release-2.8.1 Issues reported against NUT release 2.8.1 (maybe vanilla or with minor packaging tweaks) modbus

Comments

@cbrherms
Copy link

Running in to a similar (if not the same), issue as mentioned in #2063 (comment)

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
@jimklimov jimklimov added bug APC modbus impacts-release-2.8.1 Issues reported against NUT release 2.8.1 (maybe vanilla or with minor packaging tweaks) labels Jan 28, 2024
@jimklimov
Copy link
Member

CC @EchterAgo

@jimklimov
Copy link
Member

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.

@jimklimov
Copy link
Member

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.

@jimklimov
Copy link
Member

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.

@cbrherms
Copy link
Author

cbrherms commented Jan 29, 2024 •
edited
Loading

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?

@jimklimov
Copy link
Member

jimklimov commented Jan 29, 2024 •
edited
Loading

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? :\

@ZerglingGo
Copy link

I have the same problem with using libusb-1.x:

strace log

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)

@jimklimov
Copy link
Member

CC @EchterAgo : does this ring a bell, please?

@deniscuculic
Copy link

/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

@deniscuculic
Copy link

gcc -D_FORTIFY_SOURCE=1 ?

@danielm234
Copy link

Getting same error...

@jimklimov jimklimov mentioned this issue Sep 24, 2024
Open
@jimklimov
Copy link
Member

jimklimov commented Sep 24, 2024 •
edited
Loading

UPDATE: Seems like a practical duplicate of #2609, please continue discussion there to keep it compact :)

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
APC bug impacts-release-2.8.1 Issues reported against NUT release 2.8.1 (maybe vanilla or with minor packaging tweaks) modbus
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
5 participants
@jimklimov @ZerglingGo @cbrherms @deniscuculic @danielm234