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...
What's the actual output from apcaccess? I have the same UPS connected to a F7 box without trouble.
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
http://smolt.fedoraproject.org/show?UUID=ba3125b5-217e-43c8-8e91-a23b9ce7205e
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?
Created attachment 158037 [details] requested apcupsd.conf requested apcupsd.conf
Created attachment 158041 [details] strace of apcupd: start, apcaccess, kill strace out
> Any avc denials in /var/log/messages or /var/log/audit/audit.log? selinux is disabled on this system
Okay, how about a /var/log/apcupsd.trace from: apcupsd -d1000 -T -f /etc/apcupsd/apcupsd.conf
Created attachment 158060 [details] apcupsd -d1000 -T -f /etc/apcupsd/apcupsd.conf start, apcaccess, kill
Are there any other hid devices on your system? ls -l /dev/hiddev*
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
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;
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.
Fixed in apcupsd CVS, linux-usb.c rev 1.26.6.2 on Branch-3_14. Would appreciate test by submitter.
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.
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.