Bug 245864 - 3.14.1 fails to read usb apc information from device
3.14.1 fails to read usb apc information from device
Status: CLOSED ERRATA
Product: Fedora
Classification: Fedora
Component: apcupsd (Show other bugs)
7
x86_64 Linux
low Severity low
: ---
: ---
Assigned To: Orion Poplawski
Fedora Extras Quality Assurance
:
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2007-06-26 23:54 EDT by Jay Goodman
Modified: 2007-11-30 17:12 EST (History)
1 user (show)

See Also:
Fixed In Version: 3.14.1-2.fc7
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2007-07-03 12:25:25 EDT
Type: ---
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)
requested apcupsd.conf (11.51 KB, text/plain)
2007-06-27 14:36 EDT, Jay Goodman
no flags Details
strace of apcupd: start, apcaccess, kill (171.72 KB, text/plain)
2007-06-27 14:49 EDT, Jay Goodman
no flags Details
apcupsd -d1000 -T -f /etc/apcupsd/apcupsd.conf (4.97 KB, application/octet-stream)
2007-06-27 16:36 EDT, Jay Goodman
no flags Details

  None (edit)
Description Jay Goodman 2007-06-26 23:54:07 EDT
Description of problem:

apcupsd fails to read the usb ups in latest version.  Prior to
apcupsd-3.14.1-1.fc7, apcaccess showed relevant battery information such as
LOTRANS, BCHARGE, &  LINEV  and responded correctly to power failures. 

Upstream apcupsd claims  new usb recognition logic was enabled in the 3.14.1
release which may not play well with Fedora 7.   Reverting to 3.14.0 restored
correct behavior. 

Version-Release number of selected component (if applicable):

apcupsd-3.14.1-1.fc7


snippet from /proc/bus/usb/devices

T:  Bus=01 Lev=01 Prnt=01 Port=02 Cnt=03 Dev#=  4 Spd=1.5 MxCh= 0
D:  Ver= 1.10 Cls=00(>ifc ) Sub=00 Prot=00 MxPS= 8 #Cfgs=  1
P:  Vendor=051d ProdID=0002 Rev= 1.06
S:  Manufacturer=APC
S:  Product=Back-UPS ES 500 FW:801.e5.D USB FW:e5
S:  SerialNumber=JB0344028794  
C:* #Ifs= 1 Cfg#= 1 Atr=e0 MxPwr=  0mA
I:* If#= 0 Alt= 0 #EPs= 1 Cls=03(HID  ) Sub=00 Prot=00 Driver=usbhid
E:  Ad=81(I) Atr=03(Int.) MxPS=   6 Ivl=10ms




Here's a /var/log/apcupsd.trace from the offending verision:
0.000 apcupsd: apcupsd.c:220 Options parsed.
0.000 apcupsd: apcconfig.c:800 After config scriptdir: "/etc/apcupsd"
0.000 apcupsd: apcconfig.c:801 After config pwrfailpath: "/etc/apcupsd"
0.000 apcupsd: apcconfig.c:802 After config nologinpath: "/etc"
0.000 apcupsd: apcupsd.c:243 Config file /etc/apcupsd/apcupsd.conf processed.
0.000 apcupsd: newups.c:99 write_lock at drivers.c:181
0.000 apcupsd: drivers.c:183 Looking for driver: usb
0.000 apcupsd: drivers.c:187 Driver dumb is configured.
0.000 apcupsd: drivers.c:187 Driver apcsmart is configured.
0.000 apcupsd: drivers.c:187 Driver net is configured.
0.000 apcupsd: drivers.c:187 Driver usb is configured.
0.000 apcupsd: drivers.c:190 Driver usb found and attached.
0.000 apcupsd: newups.c:105 write_unlock at drivers.c:207
0.000 apcupsd: drivers.c:209 Driver ptr=0x4318c8
0.000 apcupsd: apcupsd.c:262 Attached to driver: usb
0.002 apcupsd: newups.c:99 write_lock at linux-usb.c:580
0.002 apcupsd: linux-usb.c:110 Attempting to open "/dev/usb/hiddev0"
0.002 apcupsd: linux-usb.c:110 Attempting to open "/dev/usb/hiddev1"
0.002 apcupsd: linux-usb.c:110 Attempting to open "/dev/usb/hiddev2"
0.002 apcupsd: linux-usb.c:110 Attempting to open "/dev/usb/hiddev3"
0.002 apcupsd: linux-usb.c:110 Attempting to open "/dev/usb/hiddev4"
0.002 apcupsd: linux-usb.c:110 Attempting to open "/dev/usb/hiddev5"
0.002 apcupsd: linux-usb.c:110 Attempting to open "/dev/usb/hiddev6"
0.002 apcupsd: linux-usb.c:110 Attempting to open "/dev/usb/hiddev7"
0.002 apcupsd: linux-usb.c:110 Attempting to open "/dev/usb/hiddev8"
0.002 apcupsd: linux-usb.c:110 Attempting to open "/dev/usb/hiddev9"
0.002 apcupsd: linux-usb.c:110 Attempting to open "/dev/usb/hiddev10"
0.002 apcupsd: linux-usb.c:110 Attempting to open "/dev/usb/hiddev11"
0.002 apcupsd: linux-usb.c:110 Attempting to open "/dev/usb/hiddev12"
0.002 apcupsd: linux-usb.c:110 Attempting to open "/dev/usb/hiddev13"
0.003 apcupsd: linux-usb.c:110 Attempting to open "/dev/usb/hiddev14"
0.003 apcupsd: linux-usb.c:110 Attempting to open "/dev/usb/hiddev15"
0.003 apcupsd: linux-usb.c:110 Attempting to open "/dev/usb/hid/hiddev0"
0.003 apcupsd: linux-usb.c:110 Attempting to open "/dev/usb/hid/hiddev1"
0.003 apcupsd: linux-usb.c:110 Attempting to open "/dev/usb/hid/hiddev2"
0.003 apcupsd: linux-usb.c:110 Attempting to open "/dev/usb/hid/hiddev3"
0.003 apcupsd: linux-usb.c:110 Attempting to open "/dev/usb/hid/hiddev4"
0.003 apcupsd: linux-usb.c:110 Attempting to open "/dev/usb/hid/hiddev5"
0.003 apcupsd: linux-usb.c:110 Attempting to open "/dev/usb/hid/hiddev6"
0.003 apcupsd: linux-usb.c:110 Attempting to open "/dev/usb/hid/hiddev7"
0.003 apcupsd: linux-usb.c:110 Attempting to open "/dev/usb/hid/hiddev8"
0.003 apcupsd: linux-usb.c:110 Attempting to open "/dev/usb/hid/hiddev9"
0.003 apcupsd: linux-usb.c:110 Attempting to open "/dev/usb/hid/hiddev10"
0.003 apcupsd: linux-usb.c:110 Attempting to open "/dev/usb/hid/hiddev11"
0.003 apcupsd: linux-usb.c:110 Attempting to open "/dev/usb/hid/hiddev12"
0.003 apcupsd: linux-usb.c:110 Attempting to open "/dev/usb/hid/hiddev13"
0.003 apcupsd: linux-usb.c:110 Attempting to open "/dev/usb/hid/hiddev14"
0.003 apcupsd: linux-usb.c:110 Attempting to open "/dev/usb/hid/hiddev15"
0.003 apcupsd: linux-usb.c:110 Attempting to open "/dev/hiddev0"
0.003 apcupsd: linux-usb.c:129 Successfully opened "/dev/hiddev0"
0.003 apcupsd: newups.c:105 write_unlock at linux-usb.c:612
0.007 apcupsd: newups.c:99 write_lock at linux-usb.c:655
0.008 apcupsd: newups.c:105 write_unlock at linux-usb.c:729
0.008 apcupsd: newups.c:99 write_lock at usb.c:764
0.908 apcupsd: newups.c:105 write_unlock at usb.c:772
0.908 apcupsd: apcupsd.c:311 NIS thread started.
0.909 apcupsd: apclog.c:42 apcupsd 3.14.1 (04 May 2007) redhat startup succeeded
0.909 apcupsd: usb.c:728 Enter usb_ups_read_volatile_data
0.909 apcupsd: newups.c:99 write_lock at usb.c:740
1.400 apcupsd: newups.c:105 write_unlock at usb.c:752
1.400 apcupsd: device.c:204 Before do_action: 0x7000000 (OB:0).
1.400 apcupsd: newups.c:99 write_lock at action.c:358
1.400 apcupsd: newups.c:105 write_unlock at action.c:651
1.400 apcupsd: device.c:210 Before fillUPS: 0x7000000 (OB:0).
1.400 apcupsd: usb.c:728 Enter usb_ups_read_volatile_data
1.400 apcupsd: newups.c:99 write_lock at usb.c:740
1.888 apcupsd: newups.c:105 write_unlock at usb.c:752
1.888 apcupsd: device.c:216 Before do_action: 0x7000000 (OB:0).
1.888 apcupsd: newups.c:99 write_lock at action.c:358
1.888 apcupsd: newups.c:105 write_unlock at action.c:651
1.888 apcupsd: device.c:222 Before do_reports: 0x7000000 (OB:0).
1.888 apcupsd: device.c:230 Before device_check_state: 0x7000000 (OB:0).
1.888 apcupsd: apclog.c:42 NIS server startup succeeded



Feel free to request more info...
Comment 1 Orion Poplawski 2007-06-27 11:55:20 EDT
What's the actual output from apcaccess?  I have the same UPS connected to a F7
box without trouble.
Comment 2 Jay Goodman 2007-06-27 12:42:15 EDT
Here's both first 3.14.0, second 3.14.1

After updating to 3.14.0, I stopped the apcupsd daemon
restarted the daemon
rmmod ohci and ehci and uhci
modprobed them all to force the udev triggers (the hard way)

Got the wall message that usb UPS communications were restored this time

So it seems that the ups talks. However, it cannot pull the information needed
to function correctly.  I have the apcupsd configured to shut down at 5% battery
remaining, but since it cannot get the battery level, the machine just stays up
until full battery exhaution and then loses power without shutdown being called.

Side note: starting apcupsd 3.14.1 takes about 15 seconds compared to the 1
second with 3.14.0



root@linbox [~]$ cat 1
APC      : 001,036,0912
DATE     : Wed Jun 27 12:18:08 EDT 2007
HOSTNAME : linbox.buffett.lan
RELEASE  : 3.14.0
VERSION  : 3.14.0 (9 February 2007) redhat
UPSNAME  : linbox.buffett.lan
CABLE    : USB Cable
MODEL    : Back-UPS ES 500
UPSMODE  : Stand Alone
STARTTIME: Tue Jun 26 14:01:22 EDT 2007
STATUS   : ONLINE
LINEV    : 120.0 Volts
LOADPCT  :   0.0 Percent Load Capacity
BCHARGE  : 100.0 Percent
TIMELEFT :  83.6 Minutes
MBATTCHG : 4 Percent
MINTIMEL : 2 Minutes
MAXTIME  : 0 Seconds
SENSE    : Medium
LOTRANS  : 088.0 Volts
HITRANS  : 138.0 Volts
ALARMDEL : Always
BATTV    : 13.5 Volts
LASTXFER : No transfers since turnon
NUMXFERS : 0
TONBATT  : 0 seconds
CUMONBATT: 0 seconds
XOFFBATT : N/A
STATFLAG : 0x07000008 Status Flag
MANDATE  : 2003-10-29
SERIALNO : JB0344028794
BATTDATE : 2000-00-00
NOMINV   : 120
NOMBATTV :  12.0
FIRMWARE : 801.e5.D USB FW:e5
APCMODEL : Back-UPS ES 500
END APC  : Wed Jun 27 12:18:41 EDT 2007


root@linbox [~]$ cat 2
APC      : 001,019,0486
DATE     : Wed Jun 27 12:26:30 EDT 2007
HOSTNAME : linbox.buffett.lan
RELEASE  : 3.14.1
VERSION  : 3.14.1 (04 May 2007) redhat
UPSNAME  : linbox.buffett.lan
CABLE    : USB Cable
MODEL    : USB UPS Driver
UPSMODE  : Stand Alone
STARTTIME: Wed Jun 27 12:25:35 EDT 2007
STATUS   :
MBATTCHG : 4 Percent
MINTIMEL : 2 Minutes
MAXTIME  : 0 Seconds
NUMXFERS : 0
TONBATT  : 0 seconds
CUMONBATT: 0 seconds
XOFFBATT : N/A
STATFLAG : 0x07000000 Status Flag
END APC  : Wed Jun 27 12:27:11 EDT 2007
Comment 4 Orion Poplawski 2007-06-27 13:12:03 EDT
Can you attach your /etc/apcupsd/apcupsd.conf file?  Also the output
(/tmp/apcupsd, gzipped) of (with apcupsd stopped):

strace -f -o /tmp/apcupsd /usr/sbin/apcupsd -f /etc/apcupsd/apcupsd.conf

run apcaccess, then kill the apcupsd process and then collect the /tmp/apcupsd file.

Any avc denials in /var/log/messages or /var/log/audit/audit.log?
Comment 5 Jay Goodman 2007-06-27 14:36:04 EDT
Created attachment 158037 [details]
requested apcupsd.conf

requested apcupsd.conf
Comment 6 Jay Goodman 2007-06-27 14:49:49 EDT
Created attachment 158041 [details]
strace of apcupd:  start, apcaccess, kill

strace out
Comment 7 Jay Goodman 2007-06-27 14:53:01 EDT
> Any avc denials in /var/log/messages or /var/log/audit/audit.log?

selinux is disabled on this system
Comment 8 Orion Poplawski 2007-06-27 15:48:02 EDT
Okay, how about a /var/log/apcupsd.trace from:

apcupsd -d1000 -T -f /etc/apcupsd/apcupsd.conf            
Comment 9 Jay Goodman 2007-06-27 16:36:09 EDT
Created attachment 158060 [details]
apcupsd -d1000 -T -f /etc/apcupsd/apcupsd.conf   

start, apcaccess, kill
Comment 10 Orion Poplawski 2007-06-27 16:42:45 EDT
Are there any other hid devices on your system?  ls -l /dev/hiddev*
Comment 11 Jay Goodman 2007-06-27 17:26:13 EDT
Yep:   
crw------- 1 root root 180, 96 2007-06-27 14:37 /dev/hiddev0
crw------- 1 root root 180, 97 2007-06-27 14:37 /dev/hiddev1
crw------- 1 root root 180, 98 2007-06-27 14:37 /dev/hiddev2


the ups is on minor 97 (hiddev1) according to dmesg. Looks like apcupsd is
trying to ask my keyboard for the battery info according to the trace. :)


input,hiddev96: USB HID v1.10 Device [CHICONY USB Keyboard] on usb-0000:00:02.0-2
hiddev97: USB HID v1.10 Device [APC Back-UPS ES 500 FW:801.e5.D USB FW:e5] on
usb-0000:00:02.0-3
input,hiddev98: USB HID v1.10 Keyboard [Acer IR  Receiver] on usb-0000:00:02.0-9
Comment 12 Jay Goodman 2007-06-27 23:55:20 EDT
Thanks for getting me started in the right path Orion.  I got the src.rpm and
debuginfo and went to town.    I just posted this bug on the apcupsd-users list
since they don't have a formal bug reporting system


======================================================

There seems some pretty sketchy logic in the USB auto detection routines in
linux-usb.c in the latest 3.14.1 release. This version 1.26.6.1 of the file
tagged Release-3_14_1


I've got three hid devices
Keyboard, APC UPS, and IR

# ls /dev/hiddev*
crw------- 1 root root 180, 96 2007-06-27 14:37 /dev/hiddev0
crw------- 1 root root 180, 97 2007-06-27 14:37 /dev/hiddev1
crw------- 1 root root 180, 98 2007-06-27 14:37 /dev/hiddev2


dmesg shows the apc upsd on minor 97 which is hiddev1

# dmesg | grep hiddev
input,hiddev96: USB HID v1.10 Device [CHICONY USB Keyboard] on usb-0000:00:02.0-2
hiddev97: USB HID v1.10 Device [APC Back-UPS ES 500 FW:801.e5.D USB FW:e5] on
usb-0000:00:02.0-3
input,hiddev98: USB HID v1.10 Keyboard [Acer IR  Receiver] on usb-0000:00:02.0-9


So in my case, open_device( ) is called for /dev/hiddev0  (the keyboard in my case)

Line 116 loops

i     ret       ret&ffff000     UPS_USAGE&ffff0000   ==
0     0x10080   0x10000          0x840000            (nope)
1     0xc0001   0xc0000          0x840000            (nope)
2     negative                                       (jump line 121)


Line 121 oops , this should probably read
if (ret >= 0)
but since it doesn't apcupsd thinks it found the apc device and happily, but
unsuccessfully, probes my keyboard for battery status :)

Also, I'm not familiar with the HIDIOAPPLICATION ioctl, but ioctl in general
allows 0 for successful return value as well positive ints.   That would change
the comparator in in the for loop in line 116 as well


 113    fd = open(dev, O_RDWR | O_NOCTTY);
 114    if (fd >= 0) {
 115       /* Check for the UPS application HID usage */
 116       for (i = 0; (ret = ioctl(fd, HIDIOCAPPLICATION, i)) > 0; i++) {
 117          if ((ret & 0xffff000) == (UPS_USAGE & 0xffff0000))
 118             break;
 119       }
 120       /* If we found the UPS application usage, we're good to go */    
 121       if (ret) {
 122          /* Request full uref reporting from read() */
 123          if (FORCE_COMPAT24 || ioctl(fd, HIDIOCSFLAG, &flaguref)) {
 124             Dmsg0(100, "HIDIOCSFLAG failed; enabling linux-2.4 "
 125                    "compatibility mode\n");
 126             my_data->compat24 = true;
 127          }
 128          /* Successfully opened the device */
 129          Dmsg1(200, "Successfully opened \"%s\"\n", dev);
 130          return fd;
 131       }
 132       close(fd);
 133    }
 134
 135    /* Failed to open the device */
 136    return -1;

Comment 13 Adam Kropelin 2007-06-28 13:29:26 EDT
Analysis looks correct. I introduced that bug in the 3.14.1 device locating
rewrite. Line 121 should use a >0 check. HIDIOCAPPLICATION ioctl returns the
usage word (non-zero) or a negative error code. I'll fix it up in CVS ASAP.
Comment 14 Adam Kropelin 2007-06-29 18:19:35 EDT
Fixed in apcupsd CVS, linux-usb.c rev 1.26.6.2 on Branch-3_14. Would appreciate
test by submitter.
Comment 15 Jay Goodman 2007-06-30 00:41:13 EDT
Build with release_3_14_1 tag with an updated linux-usb.c to rev 1.26.6.2 is now
working with multiple hid devices (with the ups not being hiddev0)

Thanks Adam.  
Comment 16 Fedora Update System 2007-07-03 12:25:16 EDT
apcupsd-3.14.1-2.fc7 has been pushed to the Fedora 7 stable repository.  If problems still persist, please make note of it in this bug report.

Note You need to log in before you can comment on or make changes to this bug.