[Nut-upsuser] Fwd: NUT on FBSD 14-2 fails to shut down UPS - select with socket: Invalid argument
Lee Damon
lvd at uw.edu
Mon Dec 23 21:22:27 GMT 2024
Meant to reply to the list with this as well.
nomad
---------- Forwarded message ---------
From: Lee Damon <lvd at uw.edu>
Date: Mon, Dec 23, 2024 at 1:19 PM
Subject: Re: [Nut-upsuser] NUT on FBSD 14-2 fails to shut down UPS - select
with socket: Invalid argument
On Tue, Dec 17, 2024 at 11:59 AM Jim Klimov <jimklimov+nut at gmail.com> wrote:
> ZjQcmQRYFpfptBannerEnd
> Also, is the write-capable community set in the config (and enabled on
> SNMP UPS side)?
>
Yes.
> Try starting the driver command with debug, e.g.
>
> snmp-ups -a ups-bottom -DDDDDD -k
>
> (-k is for shutdown/killpower).
>
I managed to grab some -DDDDDD output, attached.
nomad
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://alioth-lists.debian.net/pipermail/nut-upsuser/attachments/20241223/96f71881/attachment-0001.htm>
-------------- next part --------------
Script started on Mon Dec 23 13:06:20 2024
: || nomad at castle ~ [51] ; ps ax | grep ups
1341 - Ss 0:00.07 /usr/local/libexec/nut/snmp-ups -a upstop
1343 - Ss 0:00.07 /usr/local/libexec/nut/snmp-ups -a upsbottom
1345 - Ss 0:00.21 /usr/local/sbin/upsd
1365 - Is 0:00.00 /usr/local/sbin/upsmon localhost
1367 - S 0:00.02 /usr/local/sbin/upsmon localhost
1588 - Is 0:00.00 sshd: /usr/sbin/sshd [listener] 0 of 10-100 startups (sshd)
1770 0 S+ 0:00.00 script nut_shutdown_upsbottom.out
1780 1 S+ 0:00.00 grep ups
: || nomad at castle ~ [52] ; sudo /usr/local/libexec/nut/snmp-ups -a upsbottom -DDDDDD -k
Password:
0.000000 [D5] send_to_all: SETINFO driver.state "init.starting"
Network UPS Tools - Generic SNMP UPS driver 1.31 (2.8.2)
0.000138 [D1] entering upsdrv_makevartable()
0.000513 [D5] do_upsconf_args: confupsname=upstop, var=driver, val=snmp-ups
0.000529 [D5] do_upsconf_args: confupsname=upstop, var=port, val=[IPv4 address redacted}
0.000535 [D5] do_upsconf_args: confupsname=upstop, var=mibs, val=apcc
0.000542 [D5] do_upsconf_args: confupsname=upstop, var=desc, val=SMART-UPS 3000
0.000550 [D5] do_upsconf_args: confupsname=upstop, var=secLevel, val=authPriv
0.000556 [D5] do_upsconf_args: confupsname=upstop, var=secName, val=nut
0.000565 [D5] do_upsconf_args: confupsname=upstop, var=authPassword, val=[SNMP v3 PW redacted]
0.000576 [D5] do_upsconf_args: confupsname=upstop, var=privPassword, val=[SNMP v3 PW redacted]
0.000583 [D5] do_upsconf_args: confupsname=upstop, var=authProtocol, val=MD5
0.000589 [D5] do_upsconf_args: confupsname=upstop, var=privProtocol, val=DES
0.000597 [D5] do_upsconf_args: confupsname=upsbottom, var=driver, val=snmp-ups
0.000602 [D5] do_upsconf_args: call main_arg()
0.000612 [D3] main_arg: var='driver' val='snmp-ups'
0.000617 [D5] do_upsconf_args: not a main_arg()
0.000622 [D5] do_upsconf_args: this is a 'driver' setting, may we proceed?
0.000627 [D6] testval_reloadable: var=driver, oldval=snmp-ups, newval=snmp-ups, reloadable=0, reload_flag=0
0.000638 [D6] testval_reloadable: verdict for (re)loading var=driver value: -1
0.000643 [D5] do_upsconf_args: 'driver' setting already applied with this value
0.000649 [D5] do_upsconf_args: confupsname=upsbottom, var=port, val=[IPv4 address redacted]
0.000653 [D5] do_upsconf_args: call main_arg()
0.000657 [D3] main_arg: var='port' val='[IPv4 address redacted]'
0.000671 [D6] testinfo_reloadable: var=port, infoname=driver.parameter.port, newval=[IPv4 address redacted], reloadable=0, reload_flag=0
0.000676 [D6] testinfo_reloadable: verdict for (re)loading var=port value: 1
0.000684 [D5] send_to_all: SETINFO driver.parameter.port "[IPv4 address redacted]"
0.000690 [D5] do_upsconf_args: confupsname=upsbottom, var=mibs, val=apcc
0.000694 [D5] do_upsconf_args: call main_arg()
0.000698 [D3] main_arg: var='mibs' val='apcc'
0.000702 [D5] do_upsconf_args: not a main_arg()
0.000706 [D5] do_upsconf_args: process as value
0.000711 [D6] testvar_reloadable: searching for var=mibs, vartype=2, reload_flag=0
0.000719 [D6] testvar_reloadable: found var=mibs, val='(null)' => 'apcc', vartype=2 => 2, found=0, reloadable=0, reload_flag=0
0.000727 [D6] testvar_reloadable: verdict for (re)loading var=mibs value: 1
0.000747 [D5] send_to_all: SETINFO driver.parameter.mibs "apcc"
0.000760 [D5] do_upsconf_args: confupsname=upsbottom, var=desc, val=SMART-UPS 3000
0.000766 [D5] do_upsconf_args: call main_arg()
0.000773 [D3] main_arg: var='desc' val='SMART-UPS 3000'
0.000784 [D5] do_upsconf_args: confupsname=upsbottom, var=secLevel, val=authPriv
0.000788 [D5] do_upsconf_args: call main_arg()
0.000792 [D3] main_arg: var='secLevel' val='authPriv'
0.000796 [D5] do_upsconf_args: not a main_arg()
0.000800 [D5] do_upsconf_args: process as value
0.000804 [D6] testvar_reloadable: searching for var=secLevel, vartype=2, reload_flag=0
0.000811 [D6] testvar_reloadable: found var=secLevel, val='(null)' => 'authPriv', vartype=2 => 2, found=0, reloadable=0, reload_flag=0
0.000815 [D6] testvar_reloadable: verdict for (re)loading var=secLevel value: 1
0.000824 [D5] send_to_all: SETINFO driver.parameter.secLevel "authPriv"
0.000831 [D5] do_upsconf_args: confupsname=upsbottom, var=secName, val=nut
0.000835 [D5] do_upsconf_args: call main_arg()
0.000839 [D3] main_arg: var='secName' val='nut'
0.000843 [D5] do_upsconf_args: not a main_arg()
0.000846 [D5] do_upsconf_args: process as value
0.000851 [D6] testvar_reloadable: searching for var=secName, vartype=2, reload_flag=0
0.000857 [D6] testvar_reloadable: found var=secName, val='(null)' => 'nut', vartype=6 => 2, found=0, reloadable=0, reload_flag=0
0.000861 [D6] testvar_reloadable: verdict for (re)loading var=secName value: 1
0.000872 [D4] storeval: skip dparam_setinfo() for sensitive variable 'secName'
0.000882 [D5] do_upsconf_args: confupsname=upsbottom, var=authPassword, val=[SNMP v3 PW redacted]
0.000887 [D5] do_upsconf_args: call main_arg()
0.000891 [D3] main_arg: var='authPassword' val='[SNMP v3 PW redacted]'
0.000895 [D5] do_upsconf_args: not a main_arg()
0.000899 [D5] do_upsconf_args: process as value
0.000904 [D6] testvar_reloadable: searching for var=authPassword, vartype=2, reload_flag=0
0.000910 [D6] testvar_reloadable: found var=authPassword, val='(null)' => '[SNMP v3 PW redacted]', vartype=6 => 2, found=0, reloadable=0, reload_flag=0
0.000915 [D6] testvar_reloadable: verdict for (re)loading var=authPassword value: 1
0.000920 [D4] storeval: skip dparam_setinfo() for sensitive variable 'authPassword'
0.000931 [D5] do_upsconf_args: confupsname=upsbottom, var=privPassword, val=[SNMP v3 PW redacted]
0.000938 [D5] do_upsconf_args: call main_arg()
0.000945 [D3] main_arg: var='privPassword' val='[SNMP v3 PW redacted]'
0.000954 [D5] do_upsconf_args: not a main_arg()
0.000958 [D5] do_upsconf_args: process as value
0.000964 [D6] testvar_reloadable: searching for var=privPassword, vartype=2, reload_flag=0
0.000975 [D6] testvar_reloadable: found var=privPassword, val='(null)' => '[SNMP v3 PW redacted]', vartype=6 => 2, found=0, reloadable=0, reload_flag=0
0.000985 [D6] testvar_reloadable: verdict for (re)loading var=privPassword value: 1
0.000993 [D4] storeval: skip dparam_setinfo() for sensitive variable 'privPassword'
0.001000 [D5] do_upsconf_args: confupsname=upsbottom, var=authProtocol, val=MD5
0.001005 [D5] do_upsconf_args: call main_arg()
0.001009 [D3] main_arg: var='authProtocol' val='MD5'
0.001013 [D5] do_upsconf_args: not a main_arg()
0.001017 [D5] do_upsconf_args: process as value
0.001021 [D6] testvar_reloadable: searching for var=authProtocol, vartype=2, reload_flag=0
0.001027 [D6] testvar_reloadable: found var=authProtocol, val='(null)' => 'MD5', vartype=2 => 2, found=0, reloadable=0, reload_flag=0
0.001032 [D6] testvar_reloadable: verdict for (re)loading var=authProtocol value: 1
0.001040 [D5] send_to_all: SETINFO driver.parameter.authProtocol "MD5"
0.001048 [D5] do_upsconf_args: confupsname=upsbottom, var=privProtocol, val=DES
0.001052 [D5] do_upsconf_args: call main_arg()
0.001057 [D3] main_arg: var='privProtocol' val='DES'
0.001061 [D5] do_upsconf_args: not a main_arg()
0.001064 [D5] do_upsconf_args: process as value
0.001071 [D6] testvar_reloadable: searching for var=privProtocol, vartype=2, reload_flag=0
0.001081 [D6] testvar_reloadable: found var=privProtocol, val='(null)' => 'DES', vartype=2 => 2, found=0, reloadable=0, reload_flag=0
0.001087 [D6] testvar_reloadable: verdict for (re)loading var=privProtocol value: 1
0.001096 [D5] send_to_all: SETINFO driver.parameter.privProtocol "DES"
0.001120 [D1] Network UPS Tools version 2.8.2 (release/snapshot of 2.8.2) built with FreeBSD clang version 16.0.6 (https://github.com/llvm/llvm-project.git llvmorg-16.0.6-0-g7cbf1a259152); Target: x86_64-unknown-freebsd14.0; Thread model: posix and configured with flags: --sysconfdir=/usr/local/etc/nut --program-transform-name= --localstatedir=/var/db/nut --datadir=/usr/local/etc/nut --with-devd-dir=/usr/local/etc/devd --with-drvpath=/usr/local/libexec/nut --with-statepath=/var/db/nut --with-altpidpath=/var/db/nut --with-pidpath=/var/db/nut --with-pkgconfig-dir=/usr/local/libdata/pkgconfig --with-user=nut --with-group=nut --with-python=/usr/local/bin/python3.9 --without-python2 --with-python3=/usr/local/bin/python3.9 --without-nut_monitor --with-ltdl --with-nut-scanner --with-avahi --with-cgi --with-cgipath=/usr/local/www/cgi-bin/nut --with-htmlpath=/usr/local/www/nut --with-gd-includes=-I/usr/local/include --with-gd-libs='-L/usr/local/lib -lgd' --without-dev --with-freeipmi --without-ipmi --with-doc=man=auto --with-modbus --with-neon --without-nss --with-openssl --with-powerman --with-serial --with-snmp --with-usb=auto --prefix=/usr/local --mandir=/usr/local/share/man --disable-silent-rules --infodir=/usr/local/share/info/ --build=amd64-portbld-freebsd14.0
0.001144 [D1] debug level is '6'
0.001155 [D5] send_to_all: SETINFO driver.debug "6"
0.001169 [D5] send_to_all: SETFLAGS driver.debug RW NUMBER
0.001766 [D1] Succeeded to become_user(nut): now UID=316 GID=316
0.001846 [D5] upsdrvquery_write: write to driver socket: NOBROADCAST
0.001870 [D5] upsdrvquery_write: write to driver socket: PING
0.001878 [D5] upsdrvquery_prepare: waiting for a while to flush server messages
0.001990 [D5] upsdrvquery_read_timeout: received 5 bytes from driver socket: PONG
0.002006 [D5] upsdrvquery_prepare: got expected PONG
0.002012 [D5] upsdrvquery_prepare: ready for tracked commands
0.002030 [D5] upsdrvquery_write: write to driver socket: SET driver.flag.allow_killpower 1 TRACKING 7923D4F5-A1E8-4E75-8ED5-9AC3EB2077E3
0.002044 [D5] upsdrvquery_request: will wait up to 15.000000 sec for response to SET driver.flag.allow_killpower 1
0.002139 [D5] upsdrvquery_read_timeout: received 48 bytes from driver socket: TRACKING 7923D4F5-A1E8-4E75-8ED5-9AC3EB2077E3 0
0.002169 [D5] upsdrvquery_request: parsed out command status: 0
0.002229 [D5] upsdrvquery_write: write to driver socket: NOBROADCAST
0.002242 [D5] upsdrvquery_write: write to driver socket: PING
0.002250 [D5] upsdrvquery_prepare: waiting for a while to flush server messages
0.002307 [D5] upsdrvquery_read_timeout: received 5 bytes from driver socket: PONG
0.002321 [D5] upsdrvquery_prepare: got expected PONG
0.002326 [D5] upsdrvquery_prepare: ready for tracked commands
0.002338 [D5] upsdrvquery_write: write to driver socket: INSTCMD driver.killpower TRACKING AC70D0EB-24D0-4411-8164-09DE6AF411D3
0.002354 [D1] upsdrvquery_request: will wait indefinitely for response to INSTCMD driver.killpower
0.002400 select with socket: Invalid argument
0.002418 [D1] Socket dialog with the other driver instance: Invalid argument
0.002429 [D5] send_to_all: SETINFO device.type "ups"
0.002437 [D5] send_to_all: SETINFO driver.state "init.device"
0.002442 [D1] SNMP UPS driver: entering upsdrv_initups()
0.002448 [D2] SNMP UPS driver: entering nut_snmp_init(snmp-ups)
0.036779 [D2] Setting SNMP retries to 5
0.036799 [D2] Setting SNMP timeout to 1 second(s)
0.036941 [D1] SNMP UPS driver: entering load_mib2nut(apcc) to detect proper MIB for device [upsbottom] (host [IPv4 address redacted])
0.036955 [D4] load_mib2nut: checking against mapping table entry #0 "apc_ats"
0.036962 [D2] load_mib2nut: skip the "apc_ats" entry from the mapping table which is not "apcc" (and which in turn is not "auto")
0.036968 [D4] load_mib2nut: checking against mapping table entry #1 "apc_pdu"
0.036975 [D2] load_mib2nut: skip the "apc_pdu" entry from the mapping table which is not "apcc" (and which in turn is not "auto")
0.036980 [D4] load_mib2nut: checking against mapping table entry #2 "apc_pdu"
0.036984 [D2] load_mib2nut: skip the "apc_pdu" entry from the mapping table which is not "apcc" (and which in turn is not "auto")
0.036989 [D4] load_mib2nut: checking against mapping table entry #3 "apc_pdu"
0.036996 [D2] load_mib2nut: skip the "apc_pdu" entry from the mapping table which is not "apcc" (and which in turn is not "auto")
0.037001 [D4] load_mib2nut: checking against mapping table entry #4 "apc"
0.037005 [D2] load_mib2nut: skip the "apc" entry from the mapping table which is not "apcc" (and which in turn is not "auto")
0.037011 [D4] load_mib2nut: checking against mapping table entry #5 "apcc"
0.037015 [D2] load_mib2nut: trying classic sysOID matching method with 'apcc' mib
0.037030 [D3] su_find_info: unknown info type (device.model)
0.037037 [D3] su_find_info: "ups.model" found
0.037044 [D2] Found entry, not a template .1.3.6.1.4.1.318.1.1.1.1.1.1.0
0.037049 [D2] Testing ups.model using OID .1.3.6.1.4.1.318.1.1.1.1.1.1.0
0.037053 [D3] Entering nut_snmp_get_str()
0.037059 [D3] nut_snmp_get(.1.3.6.1.4.1.318.1.1.1.1.1.1.0)
0.037063 [D3] nut_snmp_walk(.1.3.6.1.4.1.318.1.1.1.1.1.1.0)
0.037067 [D4] nut_snmp_walk: max. iteration = 1
0.071128 [D3] load_mib2nut: testOID provided and matches MIB 'apcc'!
0.071150 [D1] load_mib2nut: using apcc MIB for device [upsbottom] (host [IPv4 address redacted]
0.071163 [D3] su_find_info: "ups.model" found
0.071168 [D2] Found entry, not a template .1.3.6.1.4.1.318.1.1.1.1.1.1.0
0.071179 [D3] Entering nut_snmp_get_str()
0.071184 [D3] nut_snmp_get(.1.3.6.1.4.1.318.1.1.1.1.1.1.0)
0.071190 [D3] nut_snmp_walk(.1.3.6.1.4.1.318.1.1.1.1.1.1.0)
0.071194 [D4] nut_snmp_walk: max. iteration = 1
0.086704 Detected Smart-UPS 3000 RM on host [IPv4 address redacted] (mib: apcc 1.60)
0.086728 [D1] Checking if daisychain support has to be enabled
0.086745 [D3] su_find_info: unknown info type (device.count)
0.086751 [D1] No device.count entry found, daisychain support not needed
0.086762 [D3] su_find_info: unknown info type (device.model)
0.086767 [D1] daisychain_init: No device.model entry found.
0.086771 [D1] daisychain_init: daisychain support is disabled
0.086790 [D3] su_find_info: unknown info type (load.off.delay)
0.086803 [D3] su_find_info: unknown info type (load.on.delay)
0.086814 [D3] su_find_info: unknown info type (load.off.delay)
0.086821 [D3] Entering nut_snmp_get_str()
0.086826 [D3] nut_snmp_get(.1.3.6.1.2.1.1.1.0)
0.086831 [D3] nut_snmp_walk(.1.3.6.1.2.1.1.1.0)
0.086836 [D4] nut_snmp_walk: max. iteration = 1
0.103755 [D2] Using IETF-MIB default to get and publish sysDescr for device.description (once)
0.103789 [D5] send_to_all: SETINFO device.description "APC Web/SNMP Management Card (MB:v4.1.1 PF:v3.9.4 PN:apc_hw02_aos_394.bin AF1:v3.9.3 AN1:apc_hw02_sumx_393.bin MN:AP9617 HR:A10"
0.103797 [D3] Entering nut_snmp_get_str()
0.103802 [D3] nut_snmp_get(.1.3.6.1.2.1.1.4.0)
0.103806 [D3] nut_snmp_walk(.1.3.6.1.2.1.1.4.0)
0.103810 [D4] nut_snmp_walk: max. iteration = 1
0.132593 [D2] Using IETF-MIB default to get and publish sysContact for device.contact (once)
0.132614 [D5] send_to_all: SETINFO device.contact "nomad"
0.132622 [D3] Entering nut_snmp_get_str()
0.132627 [D3] nut_snmp_get(.1.3.6.1.2.1.1.6.0)
0.132632 [D3] nut_snmp_walk(.1.3.6.1.2.1.1.6.0)
0.132636 [D4] nut_snmp_walk: max. iteration = 1
0.173208 [D2] Using IETF-MIB default to get and publish sysLocation for device.location (once)
0.173232 [D5] send_to_all: SETINFO device.location "server room"
0.173244 [D5] send_to_all: SETINFO driver.state "init.quiet"
0.173252 Initiating UPS shutdown
0.173257 [D1] upsdrv_shutdown...
0.173264 [D2] entering su_setOID(instcmd, shutdown.return, (null))
0.173277 [D3] su_find_info: "shutdown.return" found
0.173296 [D1] entering nut_snmp_set(.1.3.6.1.4.1.318.1.1.1.6.1.1.0, i, 2)
6.376424 [upsbottom] nut_snmp_set: can't set .1.3.6.1.4.1.318.1.1.1.6.1.1.0: Timeout
6.376454 [D1] su_setOID: cannot execute command 'shutdown.return'
6.376465 [D2] entering su_setOID(instcmd, shutdown.reboot, (null))
6.376485 [D3] su_find_info: unknown info type (shutdown.reboot)
6.376491 [D2] su_setOID: info element unavailable shutdown.reboot
6.376497 [D2] entering su_setOID(instcmd, load.off.delay, (null))
6.376508 [D3] su_find_info: unknown info type (load.off.delay)
6.376513 [D2] su_setOID: info element unavailable load.off.delay
6.376518 Shutdown failed!
6.376532 [D1] set_exit_flag: raising exit flag due to signal -1
6.376558 [D5] send_to_all: SETINFO driver.state "cleanup.upsdrv"
6.377340 [D5] send_to_all: SETINFO driver.state "cleanup.exit"
6.377358 upsnotify: failed to notify about state 4: no notification tech defined, will not spam more about it
>> sudo: 1
: || nomad at castle ~ [53] ; exit
exit
Script done on Mon Dec 23 13:07:11 2024
More information about the Nut-upsuser
mailing list