Meant to reply to the list with this as well. nomad
---------- Forwarded message --------- From: Lee Damon <[email protected]> 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 <[email protected]> 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
Script started on Mon Dec 23 13:06:20 2024 : || nomad@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@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@castle ~ [53] ; exit exit Script done on Mon Dec 23 13:07:11 2024
_______________________________________________ Nut-upsuser mailing list [email protected] https://alioth-lists.debian.net/cgi-bin/mailman/listinfo/nut-upsuser
