Ticket #135 (closed defect: fixed)

Opened 18 months ago

Last modified 10 months ago

igdaemon crashes intermittantly

Reported by: eudoxus Owned by: jdunn
Priority: normal Component: USB IR Transceiver
Version: Severity: normal
Keywords: Cc:

Description

Previously posted in Ticket  116, but seems not as related because I am not transmitting. Tickets  85 and  125 as also seem to be related to transmitting issues.

I am having a stability problem on hardy (8.04) with lirc-0.8.4a. My igdaemon crashes after an indeterminate period of time, but I'm not using the transmit function. I have it just set up to receive. Running 

igclient --get-version --get-features gives
igclient: /lib/libpopt.so.0: no version information available
(required by igclient) (I don't think this is a problem)
get version: success: version=0x0205
get features: success: features=0x2

I'm running igdaemon with --no-threads and have the 0.99.1-4ubuntu1 driver installed.

The error in my iguanaIR.log is: 

Apr 01 23:15:38 2009 ERROR: can't read from USB device: Failed to read (interrupt end point): No error
Apr 01 23:15:38 2009 INFO: Worker 0 exiting

There was no error in my syslog this time. Previously, the error in my iguanaIR.log was: 

Mar 31 21:21:54 2009 ERROR: can't read from USB device: Failed to read
(interrupt end point): No error
Mar 31 21:21:54 2009 INFO: Worker 0 exiting

And the error in my syslog was: 

Mar 31 21:21:55 mythbox lircd-0.8.4a[4008]: error response: Input/output error

Restarting igdaemon cures the problem. With more testing I found that restarting lircd and gdm is not required.

Attachments

iguanaIR.log Download (7.7 KB) - added by eudoxus 18 months ago.
iguanaIR.log

Change History

Changed 18 months ago by eudoxus

iguanaIR.log

Changed 17 months ago by eudoxus

  • summary changed from igdaemon crash intermittantly to igdaemon crashes intermittantly

Without any action on this ticket, I turned up the verbosity on the logging in /etc/default/iguanaIR to: LOGLEVEL = 4 (log debug3 (excessively excessive)). Unfortunately, this did not provide any new information that I could make sense of; just a 20MB log file. I have included the entries for the second in which the device fails: 

Apr 11 15:12:41 2009 DEBUG2: i0x8080808080808000
Apr 11 15:12:41 2009 DEBUG2: Data without ctl header assuming IG_DEV_RECV.
Apr 11 15:12:41 2009 DEBUG3: Notifying of packet: type = 0x30
Apr 11 15:12:41 2009 DEBUG2: Returning data packet (0x30, 7 byte payload)
Apr 11 15:12:41 2009 DEBUG3: Sent receivers: 0x3000000004000000
0x55550200
Apr 11 15:12:41 2009 DEBUG2: i0x8080808080808000
Apr 11 15:12:41 2009 DEBUG2: Data without ctl header assuming IG_DEV_RECV.
Apr 11 15:12:41 2009 DEBUG3: Notifying of packet: type = 0x30
Apr 11 15:12:41 2009 DEBUG2: Returning data packet (0x30, 7 byte payload)
Apr 11 15:12:41 2009 DEBUG3: Sent receivers: 0x3000000004000000
0x55550200
Apr 11 15:12:41 2009 DEBUG2: i0x8080808080808000
Apr 11 15:12:41 2009 DEBUG2: Data without ctl header assuming IG_DEV_RECV.
Apr 11 15:12:41 2009 DEBUG3: Notifying of packet: type = 0x30
Apr 11 15:12:41 2009 DEBUG2: Returning data packet (0x30, 7 byte payload)
Apr 11 15:12:41 2009 DEBUG3: Sent receivers: 0x3000000004000000
0x55550200
Apr 11 15:12:41 2009 DEBUG2: i0x8080808080808000
Apr 11 15:12:41 2009 DEBUG2: Data without ctl header assuming IG_DEV_RECV.
Apr 11 15:12:41 2009 DEBUG3: Notifying of packet: type = 0x30
Apr 11 15:12:41 2009 DEBUG2: Returning data packet (0x30, 7 byte payload)
Apr 11 15:12:41 2009 DEBUG3: Sent receivers: 0x3000000004000000
0x55550200
Apr 11 15:12:41 2009 DEBUG2: i0x8080808080808000
Apr 11 15:12:41 2009 DEBUG2: Data without ctl header assuming IG_DEV_RECV.
Apr 11 15:12:41 2009 DEBUG3: Notifying of packet: type = 0x30
Apr 11 15:12:41 2009 DEBUG2: Returning data packet (0x30, 7 byte payload)
Apr 11 15:12:41 2009 DEBUG3: Sent receivers: 0x3000000004000000
0x55550200
Apr 11 15:12:41 2009 DEBUG2: i0x8080808080808000
Apr 11 15:12:41 2009 DEBUG2: Data without ctl header assuming IG_DEV_RECV.
Apr 11 15:12:41 2009 DEBUG3: Notifying of packet: type = 0x30
Apr 11 15:12:41 2009 DEBUG2: Returning data packet (0x30, 7 byte payload)
Apr 11 15:12:41 2009 DEBUG3: Sent receivers: 0x3000000004000000
0x55550200
Apr 11 15:12:41 2009 ERROR: can't read from USB device: Failed to read (interrupt end point): No error
Apr 11 15:12:41 2009 INFO: Worker 0 exiting

Does anyone have an idea about how interpret this log or about what may be causing the device to fail?

Changed 17 months ago by jdunn

  • owner changed from somebody to jdunn
  • status changed from new to assigned

It's a long shot, but could you collect a usbmon log? Install usbmon and trace just the bus that our usb device is on. See what the log collects shortly before the disconnect. That will tell us if the fault is on the device or in the daemon. My suspicion is that you have an actual hardware fault and that the device is just cutting out randomly, as if the power was cutting off. Ever had problems with other USB devices on this computer?

Changed 17 months ago by eudoxus

So I collected a usbmon log while the device was up and running. Here are the results of lsusb: 

Bus 005 Device 004: ID 13b1:000d Linksys 
Bus 005 Device 001: ID 0000:0000  
Bus 004 Device 002: ID 045e:009d Microsoft Corp. 
Bus 004 Device 001: ID 0000:0000  
Bus 003 Device 001: ID 0000:0000  
Bus 002 Device 002: ID 1781:0938 Multiple Vendors Iguanaworks USB IR Transceiver
Bus 002 Device 001: ID 0000:0000  
Bus 001 Device 004: ID 15c2:ffdc SoundGraph Inc. iMON PAD Remote Controller
Bus 001 Device 001: ID 0000:0000

The results of cat /sys/kernel/debug/usbmon/2u > /tmp/2u.usbmon.log generated a pretty big file; repeating the first six lines over and over. I cut out all except the last few seconds of entries: 

f44e8f00 3541606022 C Ii:2:002:1 -2:8 0
f44e8f00 3541606615 S Ii:2:002:1 -115:8 8 <
f44e8f00 3541662022 C Ii:2:002:1 -2:8 0
f44e8f00 3541662070 S Ii:2:002:1 -115:8 8 <
f44e8f00 3541704027 C Ii:2:002:1 0:8 8 = 80808080 80808000
f44e8f00 3541704093 S Ii:2:002:1 -115:8 8 <
f44e8f00 3541758032 C Ii:2:002:1 -2:8 0
f44e8f00 3541758080 S Ii:2:002:1 -115:8 8 <
f44e8f00 3541814035 C Ii:2:002:1 -2:8 0
f44e8f00 3541814090 S Ii:2:002:1 -115:8 8 <
f44e8f00 3541856043 C Ii:2:002:1 0:8 8 = 80808080 80808000
f44e8f00 3541856139 S Ii:2:002:1 -115:8 8 <
f44e8f00 3541910045 C Ii:2:002:1 -2:8 0
f44e8f00 3541910093 S Ii:2:002:1 -115:8 8 <
f44e8f00 3541966048 C Ii:2:002:1 -2:8 0
f44e8f00 3541966106 S Ii:2:002:1 -115:8 8 <
f44e8f00 3542008052 C Ii:2:002:1 0:8 8 = 80808080 80808000
f44e8f00 3542008089 S Ii:2:002:1 -115:8 8 <
f44e8f00 3542061053 C Ii:2:002:1 -2:8 0
f44e8f00 3542061101 S Ii:2:002:1 -115:8 8 <
f44e8f00 3542114060 C Ii:2:002:1 -2:8 0
f44e8f00 3542114125 S Ii:2:002:1 -115:8 8 <
f44e8f00 3542168062 C Ii:2:002:1 0:8 8 = 80808080 80808000
f44e8f00 3542193853 S Co:2:002:0 s 01 0b 0000 0000 0000 0
f44e8f00 3542196064 C Co:2:002:0 -32 0
f44e8f00 3542196078 S Co:2:002:0 s 02 01 0000 0081 0000 0
f44e8f00 3542199064 C Co:2:002:0 0 0
f44e8f00 3542199117 S Co:2:002:0 s 02 01 0000 0002 0000 0
f44e8f00 3542202062 C Co:2:002:0 0 0

Previously, I moved the device from Bus 1 to Bus 2 so as to rule out any conflict with the other device on Bus 1. The behavior did not change. It still died randomly.

Does this offer any clues?

Changed 17 months ago by eudoxus

Any progress on finding out what may be going on with my device?

Changed 17 months ago by jdunn

Sorry I missed your post on 4/13, but this may offer some clues. The 6 lines that are repeating are just the data coming in from the USB device. In this case empty spaces (no IR signals seen). The last 6 lines containing Co:2:002:0 are the interesting ones. Could you attach a log of the normal shutdown? Start the daemon, start a receiver (same thing you had running here), then shut down the receiver (kill LIRC?), and then shut down the daemon. I'm looking for similarities and differences between these last 6 lines and the normal disconnect process.

Changed 17 months ago by eudoxus

Okay this is what I did. The device is in the same usb port as before; that is, lsusb look exactly the same as above. Then I prep for collecting the usbmon log. Next I kill off any existing instances of the daemon and lirc. I start collecting the log with cat /sys/kernel/debug/usbmon/2u > /tmp/2u.usbmon.log. Next, start daemon, start lirc, stop lirc and stop daemon with the following output: 

junk@junk:~$ sudo /etc/init.d/iguanaIR start
 * Starting Iguanaworks USB IR daemon...                                                                                          
/usr/bin/igdaemon: /lib/libpopt.so.0: no version information available (required by /usr/bin/igdaemon)
                                                                                                                                                              [ OK ]
junk@junk:~$ sudo /etc/init.d/lirc start
 * Starting remote control daemon(s) : LIRC                                                                                  [ OK ] 
junk@junk:~$ sudo /etc/init.d/lirc stop
 * Stopping remote control daemon(s): LIRC                                                                                 [ OK ] 
junk@junk:~$ sudo /etc/init.d/iguanaIR stop
 * Stopping Iguanaworks USB IR daemon...                                                                                   [ OK ]

All seems normal to this point. The usbmon.log shows the following start, middle and finish. I cut out two parts of the middle which just repeats the two lines containing '-2:8 0' and '-115:8 8 <': 

f00f0800 1634018686 S Co:2:004:0 s 00 09 0001 0000 0000 0
f00f0800 1634020780 C Co:2:004:0 0 0
f00f0080 1634022466 S Ii:2:004:1 -115:8 8 <
f00f0080 1634075784 C Ii:2:004:1 -2:8 0
f00f0080 1634075861 S Io:2:004:2 -115:8 4 = 0000cd01
f00f0080 1634077782 C Io:2:004:2 0:8 4 >
f00f0080 1634077807 S Ii:2:004:1 -115:8 8 <
f00f0080 1634085783 C Ii:2:004:1 0:8 6 = 0000dc01 0502
f00f0080 1634085873 S Ii:2:004:1 -115:8 8 <
f00f0080 1634139787 C Ii:2:004:1 -2:8 0
f00f0080 1634139809 S Io:2:004:2 -115:8 4 = 0000cd1f
f00f0080 1634141787 C Io:2:004:2 0:8 4 >
f00f0080 1634141805 S Ii:2:004:1 -115:8 8 <
f00f0080 1634195792 C Ii:2:004:1 -2:8 0
...
f00f0080 1636848022 S Ii:2:004:1 -115:8 8 <
f00f0080 1636899997 C Ii:2:004:1 -2:8 0
f00f0080 1636900012 S Ii:2:004:1 -115:8 8 <
f00f0080 1636952002 C Ii:2:004:1 -2:8 0
e5180800 1636952021 S Ii:2:004:1 -115:8 8 <
e5180800 1637004004 C Ii:2:004:1 -2:8 0
e5180800 1637004018 S Ii:2:004:1 -115:8 8 <
e5180800 1637056008 C Ii:2:004:1 -2:8 0
...
e5180800 1679557237 C Ii:2:004:1 -2:8 0
e5180800 1679557463 S Ii:2:004:1 -115:8 8 <
e5180800 1679577236 C Ii:2:004:1 -108:8 0
e5180800 1679577285 S Co:2:004:0 s 01 0b 0000 0000 0000 0
e5180800 1679580231 C Co:2:004:0 -32 0
e5180800 1679580242 S Co:2:004:0 s 02 01 0000 0081 0000 0
e5180800 1679583232 C Co:2:004:0 0 0
e5180800 1679583244 S Co:2:004:0 s 02 01 0000 0002 0000 0
e5180800 1679586231 C Co:2:004:0 0 0

Three things of note: First same set up as before but the usbmon.log looks different. The new log is missing lines that look like: 'f44e8f00 3541856043 C Ii:2:002:1 0:8 8 = 80808080 80808000'. Second, some where in the middle of the log the initial information in the line changes from 'f44e8f00' to 'e5180800'. Third, the only line that differs between abnormal shutdown and normal shutdown is the seventh from the bottom. Abnormal shut down is 'f44e8f00 3542168062 C Ii:2:002:1 0:8 8 = 80808080 80808000' while normal shutdown is 'e5180800 1679577236 C Ii:2:004:1 -108:8 0'. I have no idea if any of this is significant.

Thought?

Changed 17 months ago by eudoxus

Any progress on this defect? After a hairy upgrade to Jaunty, it is time to look into this again.

Changed 16 months ago by scgmille

I too have had this problem ever since purchasing the device. With debugging on, I get this trace:

May 11 21:47:43 2009 DEBUG2: Returning data packet (0x30, 7 byte payload) May 11 21:47:43 2009 DEBUG2: i0x8080808080808000 May 11 21:47:43 2009 DEBUG2: Data without ctl header assuming IG_DEV_RECV. May 11 21:47:43 2009 DEBUG2: Returning data packet (0x30, 7 byte payload) May 11 21:47:43 2009 DEBUG2: i0x8080808080808000 May 11 21:47:43 2009 DEBUG2: Data without ctl header assuming IG_DEV_RECV. May 11 21:47:43 2009 DEBUG2: Returning data packet (0x30, 7 byte payload) May 11 21:47:43 2009 DEBUG2: i0x8080808080808000 May 11 21:47:43 2009 DEBUG2: Data without ctl header assuming IG_DEV_RECV. May 11 21:47:43 2009 DEBUG2: Returning data packet (0x30, 7 byte payload) May 11 21:47:43 2009 DEBUG2: i0x8080808080808000 May 11 21:47:43 2009 DEBUG2: Data without ctl header assuming IG_DEV_RECV. May 11 21:47:43 2009 DEBUG2: Returning data packet (0x30, 7 byte payload) May 11 21:47:43 2009 DEBUG2: i0x8080808080808000 May 11 21:47:43 2009 DEBUG2: Data without ctl header assuming IG_DEV_RECV. May 11 21:47:43 2009 DEBUG2: Returning data packet (0x30, 7 byte payload) May 11 21:47:44 2009 DEBUG2: i0x8080808080808000 May 11 21:47:44 2009 DEBUG2: Data without ctl header assuming IG_DEV_RECV. May 11 21:47:44 2009 DEBUG2: Returning data packet (0x30, 7 byte payload) May 11 21:47:44 2009 DEBUG2: i0x8080808080808000 May 11 21:47:44 2009 DEBUG2: Data without ctl header assuming IG_DEV_RECV. May 11 21:47:44 2009 DEBUG2: Returning data packet (0x30, 7 byte payload) May 11 21:47:44 2009 DEBUG2: i0x8080808080808000 May 11 21:47:44 2009 DEBUG2: Data without ctl header assuming IG_DEV_RECV. May 11 21:47:44 2009 DEBUG2: Returning data packet (0x30, 7 byte payload) May 11 21:47:44 2009 ERROR: can't read from USB device: Failed to read (interrupt end point): No error May 11 21:47:44 2009 INFO: Worker 0 exiting

The device only manages to work for a few minutes at a time before needing a daemon restart. Its a shame, as this seems to be the only commercial USB IR receiver of a decent size.

Changed 16 months ago by scgmille

Er, sorry about the formatting there: 

May 11 21:47:43 2009 DEBUG2: Returning data packet (0x30, 7 byte payload)
May 11 21:47:43 2009 DEBUG2: i0x8080808080808000
May 11 21:47:43 2009 DEBUG2: Data without ctl header assuming IG_DEV_RECV.
May 11 21:47:43 2009 DEBUG2: Returning data packet (0x30, 7 byte payload)
May 11 21:47:43 2009 DEBUG2: i0x8080808080808000
May 11 21:47:43 2009 DEBUG2: Data without ctl header assuming IG_DEV_RECV.
May 11 21:47:43 2009 DEBUG2: Returning data packet (0x30, 7 byte payload)
May 11 21:47:43 2009 DEBUG2: i0x8080808080808000
May 11 21:47:43 2009 DEBUG2: Data without ctl header assuming IG_DEV_RECV.
May 11 21:47:43 2009 DEBUG2: Returning data packet (0x30, 7 byte payload)
May 11 21:47:43 2009 DEBUG2: i0x8080808080808000
May 11 21:47:43 2009 DEBUG2: Data without ctl header assuming IG_DEV_RECV.
May 11 21:47:43 2009 DEBUG2: Returning data packet (0x30, 7 byte payload)
May 11 21:47:43 2009 DEBUG2: i0x8080808080808000
May 11 21:47:43 2009 DEBUG2: Data without ctl header assuming IG_DEV_RECV.
May 11 21:47:43 2009 DEBUG2: Returning data packet (0x30, 7 byte payload)
May 11 21:47:44 2009 DEBUG2: i0x8080808080808000
May 11 21:47:44 2009 DEBUG2: Data without ctl header assuming IG_DEV_RECV.
May 11 21:47:44 2009 DEBUG2: Returning data packet (0x30, 7 byte payload)
May 11 21:47:44 2009 DEBUG2: i0x8080808080808000
May 11 21:47:44 2009 DEBUG2: Data without ctl header assuming IG_DEV_RECV.
May 11 21:47:44 2009 DEBUG2: Returning data packet (0x30, 7 byte payload)
May 11 21:47:44 2009 DEBUG2: i0x8080808080808000
May 11 21:47:44 2009 DEBUG2: Data without ctl header assuming IG_DEV_RECV.
May 11 21:47:44 2009 DEBUG2: Returning data packet (0x30, 7 byte payload)
May 11 21:47:44 2009 ERROR: can't read from USB device: Failed to read (interrupt end point): No error
May 11 21:47:44 2009 INFO: Worker 0 exiting

Changed 16 months ago by scgmille

After changing the daemon from no-threads to threaded, and increasing the timeout to 1000, the daemon seems much more stable. Its at least staying up for hours at a time rather than minutes.

Changed 16 months ago by dhopper

I also have experienced this problem with the same signature ever since I purchased two USB IR receivers nearly 3 months ago.

Both were supplied with firmware 0x0205. Each are plugged into separate Ubuntu 8.10 MythTV clients, different motherboards on each client, each with proven USB controllers. Tried hubs, no hubs, etc. to no effect. Whenever igdaemon goes belly-up, I have to shutdown mythclient, lircd, and then restart the three daemons in the proper sequence. It's a bit annoying, as it can happen anywhere from several times a week to several times a day.

As with eudoxus, the failure signature is: 

May 20 13:28:44 2009 ERROR: can't read from USB device: Failed to read (interrupt end point): No error
May 20 13:28:44 2009 INFO: Worker 0 exiting
May 20 13:28:44 chewie lircd-0.8.3[31328]: error response: Input/output error

I've been lurking the tickets, hoping for this problem to be root-caused and fixed, but after all this time I'm considering sticking the devices in a box and finding another IR solution. However, I would really like to use these USB IR receivers if the stability problem can be resolved, or at least if some work-arounds are found.

Thanks, Dan

Changed 16 months ago by jdunn

First of all, thank you to all of you for reporting the details of this issue and I apologize for not figuring this one out. I've been trying on and off to reproduce the problem on my hardware and have yet to find a reliable way. Ideally I would like a script that could cause this crash within seconds or minutes, not hours. Alternatively, if someone could provide me with root (well, sudo) access on a machine with the problem that would help as well.

If you have a script that can trigger the issue, please post it here so others can confirm that. If you have a machine I can log into I need a username and password, libraries and the compiler to build new versions of the driver, preferably emacs, sudo, and the ability to reboot the machine at will. If we can schedule a time that would work for both of us, it might be nice to have someone on the far end of an AIM connection who can unplug and replug during testing as well.

Again, sorry for the long delay one this. I am regretting our initial use of libusb due to deeply hidden bugs along with compatibility issues on other operating systems, which negates the primary reason for it's use. For those of you who would like to try upgrading libusb to version 1.0 (beta I believe) please report your experiences here, but I have had some reports of success. We do not use the newer API, but apparently the reimplementation resolves the root cause of this problem.

-Joseph

Changed 15 months ago by jwhite

Don't have much to add to solve the problem at this point, I'm just reporting this same issue on my Jaunty MythTV frontend. As others have reported, restarting iguanaIR solves the problem, temporarily. No need to restart myth or lirc.

Changed 15 months ago by jwhite

Below is a complete band-aid to the solution, but I'm using the perl Simple Event Correlator (sec.pl) to monitor and react to iguana errors. If it sees the error in the log, it restarts the iguana daemon and sends me a Myth OSD message (if I'm watching TV).

snip from sec.conf: 

type=Single
ptype=RegExp
pattern=(^.+\d+ \d+:\d+:\d+ \d+) ERROR: can't read from USB device: Failed to read \(interrupt end point\): No error
desc=iguana error detect and restart
action=shellcmd /home/myth/iguana_restart.sh

/home/myth/iguana_restart.sh 

#!/bin/sh
/etc/init.d/iguanaIR restart && mythtvosd --template=alert alert_text="Restarted Iguana"

It's crude and not tested all that much, but it's stopping the bleeding for now. Hope that's helpful to someone else.

Changed 12 months ago by bluey

We've made numerous changes / fixes in our new iguanaIR-1.0pre1 software and 0306 firmware. Please upgrade both and post back here if the problem remains. Otherwise we will assume the problem has been fixed and close the ticket. Thank you,

Changed 12 months ago by bluey

  • status changed from accepted to closed
  • resolution set to fixed

Changed 10 months ago by dhopper

I upgraded to the suggested release and firmware on 9/10/09 and both front-ends' igdaemons have been crash-free ever since. Big improvement!

Dan

Note: See TracTickets for help on using tickets.