[[6.9.0 betas & 6.9.1] Apcupsd issue when booting]

It is with great regret, and some slight deja vu, that I have to report that my "solution" didn't in fact, work.  It turns out that the same underlying problem remains - you only get valid data after you unplug/plug in the UPS and run the daemon, or apctest, >once<.  After that, it's buggered.

 

My current suspicion is that the UPS becomes out of sync with the port / hid status and considers itself still communicating with it.  So any subsequent "Hi, I'm apctest, let's start from scratch and get to know each other" is met by the UPS with, "...the other day, and so Sally then said,...". 

 

In other words, something needs to tell the ups "HEY, STOP.  Now start like you've never met me before".

[[6.9.0 betas & 6.9.1] Apcupsd issue when booting]

[I just spent 3 hours documenting the step by step work I'd been doing on this for logging in this thread.  I have the same UPS and the same errors and the same problems.  I don't use unRAID though but I'm sure it's nothing to do with unRaid.  I've spent several nights attacking this problem from a low level USB /HID driver problem.

 

Then, 5 minutes ago, I tried something different.

 

And it fixed it.

What... the...

 

No guarantees, but here's what I did:

# usb_modeswitch -v 0x051d -p 0x0003 --reset-usb

(Check lsusb output to find out your vendor and product IDs)

That's it.  apctest works.  apcaccess now reports ALL data.]

 

Background:

UPS: APC smc1500-2UC (same as the smc1500 but rack-mount. )

bios: 1.41, modbus enabled via front panel.

ubuntu 20.04

apcupsd 3.14.14

apcupsd.conf:
    UPSCABLE usb
    UPSTYPE modbus
    DEVICE

Unplug the usb cable then plug it back in.

lsusb reports the device with the incremented port:

root@sophie:/etc/apcupsd# lsusb
Bus 001 Device 022: ID 051d:0003 American Power Conversion UPS

 

dmesg shows:

[Sun Jan 17 21:31:31 2021] usb 1-6.4: USB disconnect, device number 21
[Sun Jan 17 21:31:36 2021] usb 1-6.4: new full-speed USB device number 22 using xhci_hcd
[Sun Jan 17 21:31:36 2021] usb 1-6.4: New USB device found, idVendor=051d, idProduct=0003, bcdDevice= 0.01
[Sun Jan 17 21:31:36 2021] usb 1-6.4: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[Sun Jan 17 21:31:36 2021] usb 1-6.4: Product: Smart-UPS_1500 FW:UPS 04.1 / ID=1018
[Sun Jan 17 21:31:36 2021] usb 1-6.4: Manufacturer: American Power Conversion  
[Sun Jan 17 21:31:36 2021] usb 1-6.4: SerialNumber: 3S2012X12122     
[Sun Jan 17 21:31:36 2021] hid-generic 0003:051D:0003.001C: hiddev1,hidraw5: USB HID v1.11 Device [American Power Conversion  Smart-UPS_1500 FW:UPS 04.1 / ID=1018] on usb-0000:00:14.0-6.4/input0

 

Making sure that apcupsd is not running, I can run apctest but get the following:
 

root@sophie:/etc/apcupsd# apctest

        2021-01-17 21:15:44 apctest 3.14.14 (31 May 2016) debian
        Checking configuration ...
        sharenet.type = Network & ShareUPS Disabled
        cable.type = USB Cable
        mode.type = MODBUS UPS Driver
        Setting up the port ...
        0.837 apcupsd: ModbusUsbComm.cpp:142 ModbusRx: TIMEOUT
        Doing prep_device() ...
        4.091 apcupsd: ModbusUsbComm.cpp:142 ModbusRx: TIMEOUT

        You are using a MODBUS cable type, so I'm entering MODBUS test mode
        Hello, this is the apcupsd Cable Test program.
        This part of apctest is for testing MODBUS UPSes.

        Getting UPS capabilities...SUCCESS

        Please select the function you want to perform.

        1)  Test kill UPS power
        2)  Perform self-test
        3)  Read last self-test result
        4)  View/Change battery date
        5)  View manufacturing date
        10) Perform battery calibration
        11) Test alarm
        Q) Quit

Note that it glitches during initialisation but gets there in the end.  Trying a safe function (Perform self-test) works, as does 'Read last self-test result'.

 

However, the moment I exit apctest, the following appears in dmesg:

[Sun Jan 17 21:17:27 2021] usb 1-6.4: reset full-speed USB device number 21 using xhci_hcd

 

Ok, fine.  apctest resets the device.  However, if I try to re-run apctest immediately, the following occurs:

root@sophie:/etc/apcupsd# apctest
        2021-01-17 21:18:31 apctest 3.14.14 (31 May 2016) debian
        Checking configuration ...
        sharenet.type = Network & ShareUPS Disabled
        cable.type = USB Cable
        mode.type = MODBUS UPS Driver
        Setting up the port ...
        0.289 apcupsd: ModbusUsbComm.cpp:258 WaitIdle: interrupt_read failed: Success
        0.849 apcupsd: ModbusUsbComm.cpp:142 ModbusRx: TIMEOUT
        1.402 apcupsd: ModbusUsbComm.cpp:142 ModbusRx: TIMEOUT
        1.602 apcupsd: ModbusComm.cpp:201 SendAndWait: Wrong size (exp=7, rx=21)
        1.674 apcupsd: ModbusComm.cpp:201 SendAndWait: Wrong size (exp=7, rx=21)
        1.962 apcupsd: ModbusComm.cpp:201 SendAndWait: Wrong size (exp=21, rx=7)
        2.033 apcupsd: ModbusComm.cpp:201 SendAndWait: Wrong size (exp=21, rx=7)
        ...

 

followed by many, many more glitchy lines, and eventually the menu.

Exiting apctest and trying to start up the apcupsd daemon causes the following to start appearing in the syslogs:

[Sun Jan 17 21:19:28 2021] usb 1-6.4: reset full-speed USB device number 21 using xhci_hcd
[Sun Jan 17 21:19:55 2021] usb 1-6.4: reset full-speed USB device number 21 using xhci_hcd
[Sun Jan 17 21:19:57 2021] usb 1-6.4: reset full-speed USB device number 21 using xhci_hcd
[Sun Jan 17 21:24:08 2021] usb 1-6.4: reset full-speed USB device number 21 using xhci_hcd
[Sun Jan 17 21:25:09 2021] usb 1-6.4: reset full-speed USB device number 21 using xhci_hcd

 

Which I assume is happening as a consequence of something "not quite right".

 

Here's the (wrong) output of apcaccess when things aren't working:
 

root@sophie:/etc/apcupsd# systemctl start apcupsd

root@sophie:/etc/apcupsd# apcaccess

        APC      : 001,018,0436
        DATE     : 2021-01-17 21:19:46 -0800  
        HOSTNAME : sophie
        VERSION  : 3.14.14 (31 May 2016) debian
        UPSNAME  : sophieUPS
        CABLE    : USB Cable
        DRIVER   : MODBUS UPS Driver
        UPSMODE  : Stand Alone
        STARTTIME: 2021-01-17 21:19:43 -0800  
        STATUS   :
        MBATTCHG : 5 Percent
        MINTIMEL : 3 Minutes
        MAXTIME  : 0 Seconds
        NUMXFERS : 0
        TONBATT  : 0 Seconds
        CUMONBATT: 0 Seconds
        XOFFBATT : N/A
        STATFLAG : 0x05000000
        END APC  : 2021-01-17 21:19:46 -0800  

 

And even when things are sort of working, here's the output of apcacess that still isn't any good:

 

 

 

 

WIthout going into the 3 day jungle safari that has been my digging into learning the apcupcd code and how usb devices work when plugged into linux, suffice to say that I learned much about things I will never have a use for, but eventually worked out that I wanted to be able to disconnect and reconnect the usb device "at will", in the hopes of using the failed workaround documented by @Gnomuz.

This led me through HID space and the frustrations of identifying the device path when something is plugged in.  But then I discovered that 'mod_switch' has a reset parameter, and you only need to provide it with the Vendor and product IDs reported by 'lsusb'.

 

Thus, the still-unbelievable simplicity of this:

root@sophie:/etc/apcupsd# usb_modeswitch -v 0x051d -p 0x0003 --reset-usb
Look for default devices ...
Found devices in default mode (1)
Access device 022 on bus 001
Get the current device configuration ...
Current configuration number is 1
Use interface number 0
with class 3
Warning: no switching method given. See documentation
Reset USB device .
Device was reset
-> Run lsusb to note any changes. Bye!

 

Followed pessimistically by

root@sophie:/etc/apcupsd# apctest

2021-01-17 22:38:48 apctest 3.14.14 (31 May 2016) debian
Checking configuration ...
sharenet.type = Network & ShareUPS Disabled
cable.type = USB Cable
mode.type = MODBUS UPS Driver
Setting up the port ...
Doing prep_device() ...

You are using a MODBUS cable type, so I'm entering MODBUS test mode
Hello, this is the apcupsd Cable Test program.
This part of apctest is for testing MODBUS UPSes.

Getting UPS capabilities...SUCCESS

Please select the function you want to perform.

1)  Test kill UPS power
2)  Perform self-test
3)  Read last self-test result
4)  View/Change battery date
5)  View manufacturing date
10) Perform battery calibration
11) Test alarm
Q) Quit

Select function number: q

 

Where I noticed that I didn't get any of the glitch messages at all.

I then repeatedly ran apctest over and over expecting errors, and got none.  Anywhere.

 

Still not believing anything, I started up apcupsd:

 

root@sophie:/etc/apcupsd# systemctl start apcupsd

 

and of course immediately tried the penultimate test, apcaccess.  Which now reported this [you're gonna love this]:

root@sophie:/etc/apcupsd# apcaccess
APC      : 001,038,0879
DATE     : 2021-01-17 22:39:52 -0800   
HOSTNAME : sophie
VERSION  : 3.14.14 (31 May 2016) debian
UPSNAME  : SophieUPS
CABLE    : USB Cable
DRIVER   : MODBUS UPS Driver
UPSMODE  : Stand Alone
STARTTIME: 2021-01-17 22:39:45 -0800   
STATUS   : ONLINE  
LINEV    : 118.4 Volts
LOADPCT  : 34.9 Percent
LOADAPNT : 22.6 Percent
BCHARGE  : 98.4 Percent
TIMELEFT : 28.0 Minutes
MBATTCHG : 5 Percent
MINTIMEL : 3 Minutes
MAXTIME  : 0 Seconds
OUTPUTV  : 118.4 Volts
DWAKE    : 0 Seconds
DSHUTD   : 180 Seconds
ITEMP    : 22.6 C
BATTV    : 26.0 Volts
LINEFREQ : 60.0 Hz
OUTCURNT : 2.75 Amps
NUMXFERS : 0
TONBATT  : 0 Seconds
CUMONBATT: 0 Seconds
XOFFBATT : N/A
SELFTEST : OK
STATFLAG : 0x05000008
MANDATE  : 2020-03-17
SERIALNO : 3S2012X12122
BATTDATE : 2020-04-14
NOMOUTV  : 120 Volts
NOMPOWER : 900 Watts
NOMAPNT  : 1440 VA
FIRMWARE : UPS 04.1 / 00.5
END APC  : 2021-01-17 22:40:46 -0800

 

It's all there, and more.

My current best guess is that something isn't being initialized properly, or reset properly, within the apcupsd / apctest code.  But running usb_modeswitch resets it properly/fully.

 

That'll do me.