Nut upsuser - Jan 2015 - CyberPower BR850ELCD ignores offdelay and turns itself back on while still on battery

Hi there,

I just purchased a CyberPower BR850ELCD and while setting NUT up with 
the install instructions from the homepage was pretty straightforward, 
and the UPS was detected by the usbhid-ups driver, I'm having problems 
getting the UPS to work properly.

First issue: whatever I set as the offdelay, seems to be ignored and the 
UPS just cuts the power about 2sec after receiving the shutdown command.

Second issue: When the UPS is on battery power and I issue the shutdown, 
it goes off, but after about 15sec it comes back on even while still on 
battery power. I tried setting ondelay to -1 and while that keeps the 
USV off, when the power comes back, the USV appears to turn on, but 
there is no power on its outlets. Only the additional 3 outlets that are 
not covered by the battery, do have power. The only fix is to turn off 
the USV and turn it back on.
For this issue, I attached three driver debug logs:

1. debug_default-ondelay.txt - it starts with the UPS on battery power 
getting a shutdown. Afterward the driver quits, I run it right away to 
capture the UPS coming back while still on battery.

2. debug_ondelay_-1.txt - starts again with the shutdown command while 
on battery. After about 15sec the UPS relay clicks as usual while still 
on battery, but this time it doesn't switch on the connected device. I 
restore the power to the UPS and still the connected device remains 
without power. I did verify that the non UPS outlets of the UPS do carry 
power.
I turn off the UPS and back on, which returns power to the connected 
device.

3. debug_no-prior-shutdown.txt - that's a log I recorded first without 
running any of the shutdown tests.


In addition to the debug logs, I also was curious to see if anything 
changed in the uspc output after I issued the shutdown command. I 
attached that as the upsc_output_on_shutdown.txt file. Only on the first 
command, did I include all the variables. For subsequent commands, I 
just included the ones that changed over the course of the test.

Before cutting the power, you can see the "OB DISCHARG" status in
2))))
as I would expect it for when the UPS is on battery power.
That changes into "OB CHRG" in 3)))) after I issued the shutdown 
command. What does that mean? on battery + charge doesn't make any sense 
to me.
4)))) is then shortly before the UPS turns power back on (while still on 
battery) - the "ups.timer.shutdown" variable is back to the default.
5)))) is after the UPS turned the power back on (still running on 
battery) - The status changed to "OB DISCHARG" and the
"ups.timer.start"
is also back to default.


I'm running Debian 7 with the latest security updates installed on an 
ODroid U3 (armhf architecture).
NUT version is 2.6.4-2.3+deb7u1 and was installed via apt-get package 
manager.
UPS is the CyberPower BR850ELCD - specs are on the homepage:
http://eu.cyberpowersystems.com/products/ups_systems/brics_lcd/br850elcd.htm

Does anyone have an idea on what I could change to get the UPS to not 
turn back on while still on battery?

As a next test, I'll try to run the battery down to see how it acts 
then. I'm hoping that it'll not turn on the power until the mains is 
plugged back in.

Thanks,
Sebastian
-------------- next part --------------
A non-text attachment was scrubbed...
Name: logs.zip
Type: application/zip
Size: 12399 bytes
Desc: not available
URL:
<http://lists.alioth.debian.org/pipermail/nut-upsuser/attachments/20150121/76d6d069/attachment-0001.zip>

On Jan 21, 2015, at 9:15 AM, Sebastian Hosche <sebastian.hosche at web.de>
wrote:
> Hi there,
> 
> I just purchased a CyberPower BR850ELCD and while setting NUT up with the
install instructions from the homepage was pretty straightforward, and the UPS
was detected by the usbhid-ups driver, I'm having problems getting the UPS
to work properly.
> 
> First issue: whatever I set as the offdelay, seems to be ignored and the
UPS just cuts the power about 2sec after receiving the shutdown command.
What values have you tried? I wonder if it is rounding down to 0 seconds.
> Second issue: When the UPS is on battery power and I issue the shutdown, it
goes off, but after about 15sec it comes back on even while still on battery
power. I tried setting ondelay to -1 and while that keeps the USV off, when the
power comes back, the USV appears to turn on, but there is no power on its
outlets. Only the additional 3 outlets that are not covered by the battery, do
have power. The only fix is to turn off the USV and turn it back on.
> For this issue, I attached three driver debug logs:
USV == UPS, correct? Or is there another module involved?

I know this sounds off-topic, but in the logs, the PercentLoad is always 0. Is
this actually the case, or is this a measurement error?

Two possibilities:

1) the UPS has some sort of "ECO" mode that thinks there is no load,
and it was not expecting the particular shutdown command that NUT sent

2) the PercentLoad variable is being scaled incorrectly. In this case, the
values for offdelay and ondelay might also be similarly affect.

Case #2 is also likely because after 2.6.4 was released, we patched
drivers/cps-hid.c to scale the battery voltage.

Unfortunately, 2.6.4 is old enough that it does not print fractional values, so
we would need to infer scale problems from the HID Report Descriptor.
> 1. debug_default-ondelay.txt - it starts with the UPS on battery power
getting a shutdown. Afterward the driver quits, I run it right away to capture
the UPS coming back while still on battery.
> 
> 2. debug_ondelay_-1.txt - starts again with the shutdown command while on
battery. After about 15sec the UPS relay clicks as usual while still on battery,
but this time it doesn't switch on the connected device. I restore the power
to the UPS and still the connected device remains without power. I did verify
that the non UPS outlets of the UPS do carry power.
> I turn off the UPS and back on, which returns power to the connected
device.
> 
> 3. debug_no-prior-shutdown.txt - that's a log I recorded first without
running any of the shutdown tests.
Can you do one more log with a higher debug level? 

"-DDD" should get the report descriptor mentioned above. It
doesn't need to run for long.
> In addition to the debug logs, I also was curious to see if anything
changed in the uspc output after I issued the shutdown command. I attached that
as the upsc_output_on_shutdown.txt file. Only on the first command, did I
include all the variables. For subsequent commands, I just included the ones
that changed over the course of the test.
> 
> Before cutting the power, you can see the "OB DISCHARG" status in
2)))) as I would expect it for when the UPS is on battery power.
> That changes into "OB CHRG" in 3)))) after I issued the shutdown
command. What does that mean? on battery + charge doesn't make any sense to
me.
Doesn't make any sense to me either, but it's definitely what the UPS is
reporting:

from debug_ondelay_-1.txt

   2.131848     Path: UPS.PowerSummary.PresentStatus.ACPresent, Type: Feature,
ReportID: 0x22, Offset: 0, Size: 1, Value: 0
   2.131970     Path: UPS.PowerSummary.PresentStatus.Charging, Type: Feature,
ReportID: 0x22, Offset: 1, Size: 1, Value: 1
   2.132153     Path: UPS.PowerSummary.PresentStatus.Discharging, Type: Feature,
ReportID: 0x22, Offset: 2, Size: 1, Value: 0

Ordinarily, I would check to see if the OB and CHRG bits are coming from
different reports, but they are from the same byte of Report 0x22.
> 4)))) is then shortly before the UPS turns power back on (while still on
battery) - the "ups.timer.shutdown" variable is back to the default.
> 5)))) is after the UPS turned the power back on (still running on battery)
- The status changed to "OB DISCHARG" and the
"ups.timer.start" is also back to default.
This is also confusing, but I'll have to look at the code again to see what
should be happening.
> 
> I'm running Debian 7 with the latest security updates installed on an
ODroid U3 (armhf architecture).
> NUT version is 2.6.4-2.3+deb7u1 and was installed via apt-get package
manager.
Thank you, it is very helpful to have such specific information.
> UPS is the CyberPower BR850ELCD - specs are on the homepage:
>
http://eu.cyberpowersystems.com/products/ups_systems/brics_lcd/br850elcd.htm
> 
> Does anyone have an idea on what I could change to get the UPS to not turn
back on while still on battery?
> 
> As a next test, I'll try to run the battery down to see how it acts
then. I'm hoping that it'll not turn on the power until the mains is
plugged back in.
> 
> Thanks,
> Sebastian
> <logs.zip>_______________________________________________
> Nut-upsuser mailing list
> Nut-upsuser at lists.alioth.debian.org
> http://lists.alioth.debian.org/cgi-bin/mailman/listinfo/nut-upsuser
-- 
Charles Lepple
clepple at gmail

Hi Charles,

Thanks so much for your quick and detailed reply! I've added my answers 
and details inline.

On 22.1.2015 04:46, Charles Lepple wrote:
> On Jan 21, 2015, at 9:15 AM, Sebastian Hosche <sebastian.hosche at
web.de>
> wrote:
> 
>> First issue: whatever I set as the offdelay, seems to be ignored and 
>> the UPS just cuts the power about 2sec after receiving the shutdown 
>> command.
> 
> What values have you tried? I wonder if it is rounding down to 0 
> seconds.
Great idea! I did some testing and it appears anything lower than 60 for 
offdelay simply gets ignored. In fact, setting offdelay to 60sec also 
fixes the second issue. Even with no device plugged into the UPS, it 
stays off while still on battery power!
> 
>> Second issue: When the UPS is on battery power and I issue the 
>> shutdown, it goes off, but after about 15sec it comes back on even 
>> while still on battery power. I tried setting ondelay to -1 and while 
>> that keeps the USV off, when the power comes back, the USV appears to 
>> turn on, but there is no power on its outlets. Only the additional 3 
>> outlets that are not covered by the battery, do have power. The only 
>> fix is to turn off the USV and turn it back on.
>> For this issue, I attached three driver debug logs:
> 
> USV == UPS, correct? Or is there another module involved?
Yes, USV is the German acronym for UPS, which I accidentally slipped in.
> I know this sounds off-topic, but in the logs, the PercentLoad is
> always 0. Is this actually the case, or is this a measurement error?
That's a measurement error on the UPS. As a test I had a 40W lamp 
plugged into it and in later testing, I looked at its display, it was 
also showing a 0% load. It's rated for a max of 510W and I guess isn't 
very sensitive in the lower 2 digit watts.
I plugged in another 50W lamp and then it finally started showing a 19% 
load. The equipment I intend to run via the UPS usually shouldn't 
consume more than 30W, so I guess the load indicator won't be of any 
use, but since the increasing offdelay fixed both issues, I'm hoping no 
long term issues creep up in the future.
> 2) the PercentLoad variable is being scaled incorrectly. In this case,
> the values for offdelay and ondelay might also be similarly affect.
> 
> Case #2 is also likely because after 2.6.4 was released, we patched
> drivers/cps-hid.c to scale the battery voltage.
> 
> Unfortunately, 2.6.4 is old enough that it does not print fractional
> values, so we would need to infer scale problems from the HID Report
> Descriptor.
Even though this doesn't appear to be the issue, I still included the 
debug_DDD.txt for you in case there's an useful info in it.
>> Before cutting the power, you can see the "OB DISCHARG"
status in
>> 2)))) as I would expect it for when the UPS is on battery power.
>> That changes into "OB CHRG" in 3)))) after I issued the
shutdown
>> command. What does that mean? on battery + charge doesn't make any 
>> sense to me.
> 
> Doesn't make any sense to me either, but it's definitely what the
UPS
> is reporting:
> 
> Ordinarily, I would check to see if the OB and CHRG bits are coming
> from different reports, but they are from the same byte of Report
> 0x22.
No worries - likely just some quirk of the device.
>> 4)))) is then shortly before the UPS turns power back on (while still 
>> on battery) - the "ups.timer.shutdown" variable is back to
the
>> default.
>> 5)))) is after the UPS turned the power back on (still running on 
>> battery) - The status changed to "OB DISCHARG" and the 
>> "ups.timer.start" is also back to default.
> 
> This is also confusing, but I'll have to look at the code again to see
> what should be happening.
Thanks, but I think there's no need to investigate this further as I 
don't see it influencing any functionality. If you still would like to 
take a closer look and need any further details from me, let me know.

there's one additional issues I came across - on boot, the driver fails 
to load. Here's a syslog snippet:
Jan  1 02:00:13 beagle kernel: [    5.932402] usb 1-3.2: New USB device 
found, idVendor=0764, idProduct=0501
Jan  1 02:00:13 beagle kernel: [    5.935372] usb 1-3.2: New USB device 
strings: Mfr=3, Product=1, SerialNumber=0
Jan  1 02:00:13 beagle kernel: [    5.942662] usb 1-3.2: Product: 
BR850ELCD
Jan  1 02:00:13 beagle kernel: [    5.946589] usb 1-3.2: Manufacturer: 
CPS

between the USB device detected and upsd failing to start, there are 
about 50 more lines in the syslog, including the following services - 
acpid, ntpd, networkmanager, dbus
Then follows:

Jan  1 02:00:13 beagle kernel: [   10.406794] hid-generic 
0003:0764:0501.0003: hiddev0,hidraw2: USB HID v1.10 Device [CPS 
BR850ELCD] on usb-s5p-ehci-3.2/input0

following this, are multiple lines from the modemananger service and 
another USB device getting recognized. Only then, upsd is loaded and 
fails:
Jan  1 02:00:14 beagle upsd[2744]: listening on 127.0.0.1 port 3493
Jan  1 02:00:14 beagle upsd[2744]: listening on ::1 port 3493
Jan  1 02:00:14 beagle upsd[2744]: Can't connect to UPS [cyberdyne] 
(usbhid-ups-cyberdyne): No such file or directory
Jan  1 02:00:14 beagle upsd[2754]: Startup successful
Jan  1 02:00:14 beagle upsmon[2803]: Startup successful
Jan  1 02:00:14 beagle upsd[2754]: User upsmaster at 127.0.0.1 logged into 
UPS [cyberdyne]
Jan  1 02:00:14 beagle upsmon[2805]: Poll UPS [cyberdyne at localhost] 
failed - Driver not connected
Jan  1 02:00:14 beagle upsmon[2805]: Communications with UPS 
cyberdyne at localhost lost
Jan  1 02:02:04 beagle upsmon[3125]: Poll UPS [cyberdyne at localhost] 
failed - Driver not connected

I've worked around the issue by preventing nut-server and nut-client 
from starting directly and adding a script to rc.local that waits for 15 
sec before starting up nut-server and then 15sec later starting 
nut-client. That does seem to do the trick, but it is kind of hacky.

Is there a way to start up nut-server on boot in some debug mode to have 
it add more details to the log?


All the best,
Sebastian
-------------- next part --------------
A non-text attachment was scrubbed...
Name: debug_log.zip
Type: application/zip
Size: 4409 bytes
Desc: not available
URL:
<http://lists.alioth.debian.org/pipermail/nut-upsuser/attachments/20150122/2c5f7cac/attachment.zip>