Nut upsdev - Sep 2010 - usbhid-ups causing hang on boot with 2.6.35 - any ideas?

(Arjen - I apologize if you get two copies, I sent the first one to the old 
de-korte.org address)

Arjen, all,

	I've run into a usbhid-ups problem with nut on Arch Linux with the new
2.6.35
kernels. (latest is 2.6.35.4-1) For some reason when you get to the udev events 
on boot and it tries to load the usbhid-ups driver, it hangs until the 120 sec 
timeout occurs and then boot continues but with no usbhid-ups configured. Here 
is the log info:

Aug 30 20:31:03 archangel upsd[2295]: listening on 192.168.6.14 port 3493
Aug 30 20:31:03 archangel upsd[2295]: listening on 127.0.0.1 port 3493
Aug 30 20:31:03 archangel upsd[2295]: Can't connect to UPS [archangel_ups] 
(usbhid-ups-archangel_ups): No such file or directory
Aug 30 20:31:03 archangel upsd[2296]: Startup successful
Aug 30 20:31:03 archangel upsmon[2298]: Startup successful
Aug 30 20:31:03 archangel upsmon[2300]: Login on UPS [archangel_ups at
localhost]
failed - got [ERR ACCESS-DENIED]
Aug 30 20:31:03 archangel upsmon[2300]: Login on UPS 
[nirvana_ups at nirvana.3111skyline.com] failed - got [ERR ACCESS-DENIED]
Aug 30 20:31:06 archangel kernel: INFO: task modprobe:1579 blocked for more than
120 seconds.
Aug 30 20:31:06 archangel kernel: "echo 0 > 
/proc/sys/kernel/hung_task_timeout_secs" disables this message.
Aug 30 20:31:06 archangel kernel: modprobe      D 0000000000000000     0  1579 
1576 0x00000000
Aug 30 20:31:06 archangel kernel: ffff88022616da28 0000000000000082 
ffffffff8167eb00 ffff880200000000
Aug 30 20:31:06 archangel kernel: 0000000000014f40 0000000000014f40 
ffff88022616dfd8 ffff88022616dfd8
Aug 30 20:31:06 archangel kernel: ffff88022616dfd8 ffff8802269c1bc0 
ffff88022616dfd8 0000000000014f40
Aug 30 20:31:06 archangel kernel: Call Trace:
Aug 30 20:31:06 archangel kernel: [<ffffffffa0202ba5>]
usb_kill_urb+0x85/0xc0
[usbcore]
Aug 30 20:31:06 archangel kernel: [<ffffffff810718d0>] ? 
autoremove_wake_function+0x0/0x40
Aug 30 20:31:06 archangel kernel: [<ffffffffa02e0831>] 
usbhid_init_reports+0xb1/0x120 [usbhid]
Aug 30 20:31:06 archangel kernel: [<ffffffffa02e0d53>]
usbhid_start+0x4b3/0x5a0
[usbhid]
Aug 30 20:31:06 archangel kernel: [<ffffffffa02ca6d8>] 
hid_device_probe+0x98/0xe0 [hid]
Aug 30 20:31:06 archangel kernel: [<ffffffff812877ea>] ?
driver_sysfs_add+0x5a/0x90
Aug 30 20:31:06 archangel kernel: [<ffffffff81287ac6>] 
driver_probe_device+0x96/0x1c0
Aug 30 20:31:06 archangel kernel: [<ffffffff81287c90>] ?
__device_attach+0x0/0x60
Aug 30 20:31:06 archangel kernel: [<ffffffff81287cdb>]
__device_attach+0x4b/0x60
Aug 30 20:31:06 archangel kernel: [<ffffffff812866a4>]
bus_for_each_drv+0x64/0x90
Aug 30 20:31:06 archangel kernel: [<ffffffff8128795f>]
device_attach+0x8f/0xb0
Aug 30 20:31:06 archangel kernel: [<ffffffff81287115>]
bus_probe_device+0x25/0x40
Aug 30 20:31:06 archangel kernel: [<ffffffff81284e5f>]
device_add+0x4ff/0x5e0
Aug 30 20:31:06 archangel kernel: [<ffffffffa02ca0a7>]
hid_add_device+0x87/0x1b0
[hid]
Aug 30 20:31:06 archangel kernel: [<ffffffffa02de4b9>]
usbhid_probe+0x329/0x500
[usbhid]
Aug 30 20:31:06 archangel kernel: [<ffffffffa0207a2b>] 
usb_probe_interface+0xfb/0x1f0 [usbcore]
Aug 30 20:31:06 archangel kernel: [<ffffffff81287ac6>] 
driver_probe_device+0x96/0x1c0
Aug 30 20:31:06 archangel kernel: [<ffffffff81287c8b>]
__driver_attach+0x9b/0xa0
Aug 30 20:31:06 archangel kernel: [<ffffffff81287bf0>] ?
__driver_attach+0x0/0xa0
Aug 30 20:31:06 archangel kernel: [<ffffffff812869fe>]
bus_for_each_dev+0x5e/0x90
Aug 30 20:31:06 archangel kernel: [<ffffffff81287789>]
driver_attach+0x19/0x20
Aug 30 20:31:06 archangel kernel: [<ffffffff81287297>]
bus_add_driver+0xc7/0x2e0
Aug 30 20:31:06 archangel kernel: [<ffffffff81287f01>]
driver_register+0x71/0x140
Aug 30 20:31:06 archangel kernel: [<ffffffffa02066f8>] 
usb_register_driver+0xb8/0x170 [usbcore]
Aug 30 20:31:06 archangel kernel: [<ffffffffa0299000>] ? hid_init+0x0/0xd1
[usbhid]
Aug 30 20:31:06 archangel kernel: [<ffffffffa0299093>] hid_init+0x93/0xd1
[usbhid]
Aug 30 20:31:06 archangel kernel: [<ffffffff81002149>]
do_one_initcall+0x39/0x1a0
Aug 30 20:31:06 archangel kernel: [<ffffffff8108cefb>]
sys_init_module+0xbb/0x200
Aug 30 20:31:06 archangel kernel: [<ffffffff81009e82>] 
system_call_fastpath+0x16/0x1b
Aug 30 20:31:08 archangel upsmon[2300]: Poll UPS [archangel_ups at localhost] 
failed - Driver not connected
Aug 30 20:31:08 archangel upsmon[2300]: Communications with UPS 
archangel_ups at localhost lost
Aug 30 20:31:08 archangel wall[2302]: wall: user nut broadcasted 1 lines (54
chars)
Aug 30 20:31:13 archangel upsmon[2300]: Poll UPS [archangel_ups at localhost] 
failed - Driver not connected
Aug 30 20:31:13 archangel upsmon[2300]: UPS archangel_ups at localhost is
unavailable
Aug 30 20:31:13 archangel wall[2305]: wall: user nut broadcasted 1 lines (44
chars)
Aug 30 20:31:18 archangel upsmon[2300]: Poll UPS [archangel_ups at localhost] 
failed - Driver not connected
Aug 30 20:31:23 archangel upsmon[2300]: Poll UPS [archangel_ups at localhost] 
failed - Driver not connected

<snip ~15 more Driver not connected>

Aug 30 20:33:06 archangel kernel: INFO: task modprobe:1579 blocked for more than
120 seconds.
Aug 30 20:33:06 archangel kernel: "echo 0 > 
/proc/sys/kernel/hung_task_timeout_secs" disables this message.
Aug 30 20:33:06 archangel kernel: modprobe      D 0000000000000000     0  1579 
1576 0x00000000
Aug 30 20:33:06 archangel kernel: ffff88022616da28 0000000000000082 
ffffffff8167eb00 ffff880200000000
Aug 30 20:33:06 archangel kernel: 0000000000014f40 0000000000014f40 
ffff88022616dfd8 ffff88022616dfd8
Aug 30 20:33:06 archangel kernel: ffff88022616dfd8 ffff8802269c1bc0 
ffff88022616dfd8 0000000000014f40
Aug 30 20:33:06 archangel kernel: Call Trace:
Aug 30 20:33:06 archangel kernel: [<ffffffffa0202ba5>]
usb_kill_urb+0x85/0xc0
[usbcore]
Aug 30 20:33:06 archangel kernel: [<ffffffff810718d0>] ? 
autoremove_wake_function+0x0/0x40
Aug 30 20:33:06 archangel kernel: [<ffffffffa02e0831>] 
usbhid_init_reports+0xb1/0x120 [usbhid]
Aug 30 20:33:06 archangel kernel: [<ffffffffa02e0d53>]
usbhid_start+0x4b3/0x5a0
[usbhid]
Aug 30 20:33:06 archangel kernel: [<ffffffffa02ca6d8>] 
hid_device_probe+0x98/0xe0 [hid]
Aug 30 20:33:06 archangel kernel: [<ffffffff812877ea>] ?
driver_sysfs_add+0x5a/0x90
Aug 30 20:33:06 archangel kernel: [<ffffffff81287ac6>] 
driver_probe_device+0x96/0x1c0
Aug 30 20:33:06 archangel kernel: [<ffffffff81287c90>] ?
__device_attach+0x0/0x60
Aug 30 20:33:06 archangel kernel: [<ffffffff81287cdb>]
__device_attach+0x4b/0x60
Aug 30 20:33:06 archangel kernel: [<ffffffff812866a4>]
bus_for_each_drv+0x64/0x90
Aug 30 20:33:06 archangel kernel: [<ffffffff8128795f>]
device_attach+0x8f/0xb0
Aug 30 20:33:06 archangel kernel: [<ffffffff81287115>]
bus_probe_device+0x25/0x40
Aug 30 20:33:06 archangel kernel: [<ffffffff81284e5f>]
device_add+0x4ff/0x5e0
Aug 30 20:33:06 archangel kernel: [<ffffffffa02ca0a7>]
hid_add_device+0x87/0x1b0
[hid]
Aug 30 20:33:06 archangel kernel: [<ffffffffa02de4b9>]
usbhid_probe+0x329/0x500
[usbhid]
Aug 30 20:33:06 archangel kernel: [<ffffffffa0207a2b>] 
usb_probe_interface+0xfb/0x1f0 [usbcore]
Aug 30 20:33:06 archangel kernel: [<ffffffff81287ac6>] 
driver_probe_device+0x96/0x1c0
Aug 30 20:33:06 archangel kernel: [<ffffffff81287c8b>]
__driver_attach+0x9b/0xa0
Aug 30 20:33:06 archangel kernel: [<ffffffff81287bf0>] ?
__driver_attach+0x0/0xa0
Aug 30 20:33:06 archangel kernel: [<ffffffff812869fe>]
bus_for_each_dev+0x5e/0x90
Aug 30 20:33:06 archangel kernel: [<ffffffff81287789>]
driver_attach+0x19/0x20
Aug 30 20:33:06 archangel kernel: [<ffffffff81287297>]
bus_add_driver+0xc7/0x2e0
Aug 30 20:33:06 archangel kernel: [<ffffffff81287f01>]
driver_register+0x71/0x140
Aug 30 20:33:06 archangel kernel: [<ffffffffa02066f8>] 
usb_register_driver+0xb8/0x170 [usbcore]
Aug 30 20:33:06 archangel kernel: [<ffffffffa0299000>] ? hid_init+0x0/0xd1
[usbhid]
Aug 30 20:33:06 archangel kernel: [<ffffffffa0299093>] hid_init+0x93/0xd1
[usbhid]
Aug 30 20:33:06 archangel kernel: [<ffffffff81002149>]
do_one_initcall+0x39/0x1a0
Aug 30 20:33:06 archangel kernel: [<ffffffff8108cefb>]
sys_init_module+0xbb/0x200
Aug 30 20:33:06 archangel kernel: [<ffffffff81009e82>] 
system_call_fastpath+0x16/0x1b
Aug 30 20:33:06 archangel kernel: INFO: task usbhid-ups:2006 blocked for more 
than 120 seconds.
Aug 30 20:33:06 archangel kernel: "echo 0 > 
/proc/sys/kernel/hung_task_timeout_secs" disables this message.
Aug 30 20:33:06 archangel kernel: usbhid-ups    D 0000000000000000     0  2006 
   1 0x00000000
Aug 30 20:33:06 archangel kernel: ffff880227789b98 0000000000000082 
ffff880227789ae8 ffffffff00000000
Aug 30 20:33:06 archangel kernel: 0000000000014f40 0000000000014f40 
ffff880227789fd8 ffff880227789fd8
Aug 30 20:33:06 archangel kernel: ffff880227789fd8 ffff880226c9b780 
ffff880227789fd8 0000000000014f40
Aug 30 20:33:06 archangel kernel: Call Trace:
Aug 30 20:33:06 archangel kernel: [<ffffffff81371879>] 
__mutex_lock_slowpath+0x139/0x310
Aug 30 20:33:06 archangel kernel: [<ffffffff81371a61>]
mutex_lock+0x11/0x30
Aug 30 20:33:06 archangel kernel: [<ffffffffa020c195>]
usbdev_open+0x145/0x330
[usbcore]
Aug 30 20:33:06 archangel kernel: [<ffffffff81127807>]
chrdev_open+0x127/0x270
Aug 30 20:33:06 archangel kernel: [<ffffffff811276e0>] ?
chrdev_open+0x0/0x270
Aug 30 20:33:06 archangel kernel: [<ffffffff81121d2b>]
__dentry_open+0x11b/0x3c0
Aug 30 20:33:06 archangel kernel: [<ffffffff811a263a>] ? 
security_inode_permission+0x1a/0x20
Aug 30 20:33:06 archangel kernel: [<ffffffff81122f64>]
nameidata_to_filp+0x54/0x70
Aug 30 20:33:06 archangel kernel: [<ffffffff811311f0>] do_last+0x480/0x740
Aug 30 20:33:06 archangel kernel: [<ffffffff8113169d>]
do_filp_open+0x1ed/0x680
Aug 30 20:33:06 archangel kernel: [<ffffffff8113cc74>] ?
alloc_fd+0xf4/0x150
Aug 30 20:33:06 archangel kernel: [<ffffffff81122fe4>]
do_sys_open+0x64/0x130
Aug 30 20:33:06 archangel kernel: [<ffffffff811230cb>] sys_open+0x1b/0x20
Aug 30 20:33:06 archangel kernel: [<ffffffff81009e82>] 
system_call_fastpath+0x16/0x1b
Aug 30 20:33:08 archangel upsmon[2300]: Poll UPS [archangel_ups at localhost] 
failed - Driver not connected
Aug 30 20:33:13 archangel upsmon[2300]: Poll UPS [archangel_ups at localhost] 
failed - Driver not connected

     Looks like some type of udev issue or kernel issue, but I thought I would 
check here to see if you guys have any more info on the problem. Anybody seen 
this behavior before?

     Seems to effect my MSI nvidia 8200 chipset box more than others. This box 
has never had a problem with this before the 2.6.35 kernels so something has 
changed that impacts the driver, but I'm not sure what it is. Can you think
of
any other tests I could run to help narrow it down?

     Any help would be appreciated - thanks.

-- 
David C. Rankin, J.D.,P.E.
Rankin Law Firm, PLLC
510 Ochiltree Street
Nacogdoches, Texas 75961
Telephone: (936) 715-9333
Facsimile: (936) 715-9339
www.rankinlawfirm.com

Citeren "David C. Rankin" <drankinatty op suddenlinkmail.com>:
> (Arjen - I apologize if you get two copies, I sent the first one to  
> the old de-korte.org address)
That address isn't old, but the mailserver is configured to only  
accept messages from the mailinglist server.
> Aug 30 20:31:03 archangel upsd[2295]: listening on 192.168.6.14 port 3493
> Aug 30 20:31:03 archangel upsd[2295]: listening on 127.0.0.1 port 3493
> Aug 30 20:31:03 archangel upsd[2295]: Can't connect to UPS  
> [archangel_ups] (usbhid-ups-archangel_ups): No such file or directory
This means the driver isn't running (but you probably already knew that).
> Aug 30 20:31:03 archangel upsd[2296]: Startup successful
> Aug 30 20:31:03 archangel upsmon[2298]: Startup successful
> Aug 30 20:31:03 archangel upsmon[2300]: Login on UPS  
> [archangel_ups op localhost] failed - got [ERR ACCESS-DENIED]
> Aug 30 20:31:03 archangel upsmon[2300]: Login on UPS  
> [nirvana_ups op nirvana.3111skyline.com] failed - got [ERR ACCESS-DENIED]
The above two error messages indicate there is a problem with logging  
into the server. You could run the server in debug mode, but my guess  
is this has to do with either NUT being build with tcp-wrappers  
support and you failed setting this up properly (see 'man 8 upsd') or  
the credentials you're using are incorrect.

[...]
>     Looks like some type of udev issue or kernel issue, but I  
> thought I would check here to see if you guys have any more info on  
> the problem. Anybody seen this behavior before?
This looks like the udev rules are incorrect. If memory serves, there  
have been some changes in the syntax (BUS was changed to SUBSYSTEMS).  
Other than that, there are no known issues.

Best regards, Arjen
-- 
Please keep list traffic on the list (off-list replies will be rejected)