Opened 12 years ago

Closed 10 years ago

Last modified 10 years ago

#5278 closed defect (fixed)

Firewire Uses Bad Port Number and Fails

Reported by: scottadmi@… Owned by: Jarod Wilson
Priority: minor Milestone: 0.24
Component: MythTV - Recording Version: 0.21
Severity: medium Keywords:
Cc: Ticket locked: no

Description

This occurs when using mythtv with a firewire connected HD cable box. Specifically Motorola DCH3200.

Occasionally (often after performing a channel change), the backend will no longer record or stream any channel via firewire - this condition persists until the mythbackend is restarted at which point it works again. Further, no error is displayed, rather (if in live tv mode) the screen will simply remain blank for half a minute then return to the menu.

The issue is not related to channel changing or stable broadcast as it will successfully change channels on the digital box and firewire_tester indicates a stable connection. Rather, it seems like the firewire node or port number is reverting to -1 for some reason (which presumably gets cleared out when restarting the backend and corrects the problem).

Below are the relevant log entries from such an occurence:

TVRec(4): Changing from None to WatchingLiveTV TVRec(4): HW Tuner: 4->4 LAVCInfo(), Error: Unable to get handle for port: -1

eno: Invalid argument (22)

ret_pid(0) child(9135) status(0x0) ret_pid(9135) child(9135) status(0x0) External Tuning program exited with no error LAVCInfo(), Error: Unable to get handle for port: -1

eno: Invalid argument (22)

... Preview Error: Previewer file '/mnt/store/recordings/2212_20080430235337.mpg' is not valid. Preview Error: Run() file not local: '/mnt/store/recordings/2212_20080430235337.mpg' Preview Error: Preview process not ok.

fileinfo(/mnt/store/recordings/2212_20080430235337.mpg.png) exists: 0 readable: 0 size: 0

From reference after stopping and starting the mythbackend, the same operation performs correctly and results in this log:

TVRec(4): Changing from None to WatchingLiveTV TVRec(4): HW Tuner: 4->4 ret_pid(0) child(9471) status(0x0) ret_pid(9471) child(9471) status(0x0) External Tuning program exited with no error AutoExpire?: CalcParams?(): Max required Free Space: 4.0 GB w/freq: 15 min LFireDev(001C11FFFEA14FC5): Buffered packets 2000 (8000 KB)

Change History (53)

comment:1 Changed 12 years ago by anonymous

Easier to read version of above log:

2008-05-01 00:06:12.775 TVRec(4): Changing from None to WatchingLiveTV
2008-05-01 00:06:12.778 TVRec(4): HW Tuner: 4->4
2008-05-01 00:06:12.779 LAVCInfo(), Error: Unable to get handle for port: -1
                        eno: Invalid argument (22)
2008-05-01 00:06:13.788 ret_pid(0) child(9273) status(0x0)
2008-05-01 00:06:14.792 ret_pid(9273) child(9273) status(0x0)
2008-05-01 00:06:14.793 External Tuning program exited with no error
2008-05-01 00:06:15.904 LAVCInfo(), Error: Unable to get handle for port: -1
                        eno: Invalid argument (22)
2008-05-01 00:06:17.171 Preview Error: Previewer file '/mnt/store/recordings/2212_20080501000614.mpg' is not valid.
2008-05-01 00:06:17.173 Preview Error: Run() file not local: '/mnt/store/recordings/2212_20080501000614.mpg'
2008-05-01 00:06:17.179 Preview Error: Preview process not ok.
                        fileinfo(/mnt/store/recordings/2212_20080501000614.mpg.png) exists: 0 readable: 0 size: 0

comment:2 Changed 11 years ago by foom@…

I had this same problem, also with a DCH3200. I worked around it by telling myth to use broadcast mode instead of P2P, and I think myth is now working reliably, but I've not been using it long enough to say that with certainty.

comment:3 Changed 11 years ago by anonymous

Thanks for the comment. In this case, I however, already am using broadcast mode for firewire (as P2P was consistently inconsistent so to speak) so I don't think thats the root of the issue I've been seeing. Especially as the firewire-tester confirms a valid broadcast connection.

comment:4 Changed 11 years ago by danielk

Owner: changed from Isaac Richards to danielk
Status: newassigned

comment:5 Changed 11 years ago by danielk

Does it work if you use the internal channel changer rather than an external one?

comment:6 Changed 11 years ago by anonymous

Yes, the behavior is the same when using either internal or external channel changing (currently I'm using internal changing and it fails in this manner). It seems to happen more readily if accidentally try to change channels before it has acquired a full "LAM" lock on the current one.

comment:7 Changed 11 years ago by Mike Rice <mikerice1969@…>

I've seen this as well. I'm currently trying to get stable recordings from a DCH3416 box. I am still trying to understand the code but I can explain what I am seeing in hopes it helps.

Using the internal changer (and broadcast mode) things usually appear fine directly after restarting the backend. A recording (or LiveTV) starts recording and after some minutes 15-45 minutes typically there is no longer any data available and the backend tries to recover with SignalReset?. That does the UpdateDeviceList?() which goes through the ports and nodes and gets the guid (get_guid). My problem is that get_guid will no longer get the guid as it errors with "temporarily unavailable". Once it gets into this state it usually stays unavailable but occasionally it recovers. Of course I can run plugreport during the time the get_guid read is "temporarily unavailable" and it will report the guid just fine so I am not sure what to think here.

In any case once the guid goes offline the port and node are set to -1 and then some odd things start happening. I don't understand the flow enough to see how OpenPort? gets called for one of these offline port/nodes but it is occasionally appearing in my logs. I've been concentrating on figuring out why get_guid is failing for me but I'll test any patches or ideas that are generated.

comment:8 Changed 11 years ago by anonymous

It seems like allowing the firewire setup as in older versions (in which the node number was specified manually) as an alternate option to using GUID could be a work around to this problem, though not a true fix.

comment:9 Changed 11 years ago by notivan

I have the "same" problem with a Motorola 6200 STB using Mythtv 7.1 and the "beta" mythprime. This happens quite often and seemingly at random. Sometimes recording works for a day or two but stable periods rarely last more than 5 -10 recordings

A typical log of the error is:

2008-07-24 22:59:29.435 TVRec(1): ASK_RECORDING 1 29 0 0 2008-07-24 23:00:02.343 TVRec(1): Changing from None to RecordingOnly? 2008-07-24 23:00:02.376 TVRec(1): HW Tuner: 1->1 2008-07-24 23:00:02.377 LAVCInfo(), Error: Unable to get handle for port: -1

eno: Invalid argument (22)

2008-07-24 23:00:02.409 TVRec(1) Error: Failed to set channel to 63. Reverting to kState_None 2008-07-24 23:00:02.411 TVRec(1): Changing from RecordingOnly? to None

comment:10 in reply to:  9 Changed 11 years ago by daver

I'm seeing the same problem with a DCH3200 HD cable box using a Firewire connection into a Ubuntu Hardy dedicated backend box running the mythtv-backend package (0.21.0+fixes16838).

I have the Firewire Capture Card Setup configured using the built-in DCH-3200 settings with a Broadcast connection at 100 Mbps and both signal and tuning timeouts set at 4000 ms.

Similar to what others have reported above, every day or two (5-10 Firewire recordings, although there doesn't seem to be any consistency in this) I get the above LAVCInfo() and TVRec() errors and the Reverting to kState_None. I think this usually follows a long series of "Warning: No Input in xxx msec..." warnings from LFireDev and subsequent "ResetBus?" and "SignalReset?" messages. As has been reported by others above, simply stopping and restarting the backend seems to fix the Firewire after it fails.

I also have two pcHDTV cards for unencrypted cable signals that are rock solid, so the rest of the system works great.

Please let me know if there has been any progress on this issue. Very frustrating to miss recordings.

comment:11 Changed 11 years ago by scottadmi@…

Lately a new (possibly related issue) has cropped up. The primary issue described here remains. Additionally, though, sometimes when I am watching live HD TV (via firewire) it will lock up when it reaches the end of the show. In other words, if I'm watching the news on channel 10, and the show the time hits 7:00PM (marking the end of that show) the backend will screw up trying to continue watching that very channel live. This log output does not occur when changing channels - which sometimes works - just when a new show is starting while watching live HD. The following is a sample log output:

008-10-05 23:00:01.492 Finished recording Planet Earth "Ice Worlds": channel 2191 2008-10-05 23:00:04.083 AFD: Opened codec 0x82d6370, id(MPEG2VIDEO) type(Video) 2008-10-05 23:00:04.090 AFD: codec AC3 has 6 channels 2008-10-05 23:00:04.092 AFD: Opened codec 0x82d6960, id(AC3) type(Audio) 2008-10-05 23:00:04.468 Preview: Grabbed preview '/mnt/store/recordings/2191_20081005225519.mpg' 1920x1088@630s 2008-10-05 23:00:05.738 LFireDev(001C11FFFEA14FC5), Warning: No Input in 600 msec... 2008-10-05 23:00:05.798 LFireDev(001C11FFFEA14FC5), Warning: No Input in 650 msec... 2008-10-05 23:00:05.858 LFireDev(001C11FFFEA14FC5), Warning: No Input in 700 msec... 2008-10-05 23:00:05.910 LFireDev(001C11FFFEA14FC5), Warning: No Input in 750 msec... 2008-10-05 23:00:05.962 LFireDev(001C11FFFEA14FC5), Warning: No Input in 800 msec... 2008-10-05 23:00:06.014 LFireDev(001C11FFFEA14FC5), Warning: No Input in 850 msec... 2008-10-05 23:00:06.066 LFireDev(001C11FFFEA14FC5), Warning: No Input in 900 msec... 2008-10-05 23:00:06.118 LFireDev(001C11FFFEA14FC5), Warning: No Input in 950 msec... 2008-10-05 23:00:06.170 LFireDev(001C11FFFEA14FC5), Warning: No Input in 1000 msec... 2008-10-05 23:00:06.222 LFireDev(001C11FFFEA14FC5), Warning: No Input in 1050 msec... 2008-10-05 23:00:06.223 LFireDev(001C11FFFEA14FC5): ResetBus?() -- begin 2008-10-05 23:00:06.226 LFireDev(001C11FFFEA14FC5): ResetBus?() -- end 2008-10-05 23:00:06.226 LFireDev(001C11FFFEA14FC5): SignalReset?(157->158) 2008-10-05 23:00:06.227 LFireDev(001C11FFFEA14FC5): SignalReset?(157->158): Updating device list -- begin 2008-10-05 23:00:06.547 LFireDev(001C11FFFEA14FC5): SignalReset?(157->158): Updating device list -- end 2008-10-05 23:00:06.598 LFireDev(001C11FFFEA14FC5), Warning: No Input in 50 msec... 2008-10-05 23:00:06.650 LFireDev(001C11FFFEA14FC5), Warning: No Input in 100 msec... libiec61883 warning: iec61883_cmp_create_bcast_output: Failed to set the oPCR[0] plug for node 63. 2008-10-05 23:00:06.651 LFireDev(001C11FFFEA14FC5), Error: Bus Reset : Failed to reconnect 2008-10-05 23:00:06.702 LFireDev(001C11FFFEA14FC5), Warning: No Input in 150 msec...

It will then repeat this ad-infinidum, requiring me to exit mythtv or the log will be filled in short order.

comment:12 Changed 11 years ago by eric@…

I've seen this or a similar problem also with a Motorola DHC 3200.

What seems to be happening is that my cable box is actually jumping back and forth between node 0 and node 1. I set up a cron job to run plugreport hourly and dump the result to a log file. The box has GUID 0x001aadfffe47916e, which usually shows up as node 0, but sometimes as node 1. Here's an excerpt:

Wed Oct  1 18:41:01 EDT 2008
libiec61883 error: error reading oMPR
libiec61883 error: error reading iMPR
Host Adapter 0
==============

Node 0 GUID 0x001aadfffe47916e
------------------------------
oMPR n_plugs=1, data_rate=2, bcast_channel=63
oPCR[0] online=1, bcast_connection=0, n_p2p_connections=0
        channel=63, data_rate=0, overhead_id=0, payload=376
iMPR n_plugs=0, data_rate=2

Node 1 GUID 0x002d8f3600001fd0
------------------------------

Wed Oct  1 19:41:01 EDT 2008
libiec61883 error: error reading oMPR
libiec61883 error: error reading iMPR
Host Adapter 0
==============

Node 0 GUID 0x002d8f3600001fd0
------------------------------

Node 1 GUID 0x001aadfffe47916e
------------------------------
oMPR n_plugs=1, data_rate=2, bcast_channel=63
oPCR[0] online=1, bcast_connection=0, n_p2p_connections=0
        channel=63, data_rate=0, overhead_id=0, payload=376
iMPR n_plugs=0, data_rate=2

Wed Oct  1 20:41:01 EDT 2008
libiec61883 error: error reading oMPR
libiec61883 error: error reading iMPR
Host Adapter 0
==============

Node 0 GUID 0x001aadfffe47916e
------------------------------
oMPR n_plugs=1, data_rate=2, bcast_channel=63
oPCR[0] online=1, bcast_connection=0, n_p2p_connections=0
        channel=62, data_rate=0, overhead_id=0, payload=376
iMPR n_plugs=0, data_rate=2

Node 1 GUID 0x002d8f3600001fd0
------------------------------

The box appears as node 0 at 18:41 and 20:41, but at 19:41 it was on node 1. (That was the only time I captured it on node one since I set up the script.)

It seems like whenever a node flip happens, the mythtv backend loses all ability to control the box until the backend process is restarted and then everything works fine after that for a few hours to a few days.

comment:13 Changed 11 years ago by Marc MERLIN

Are you all using the firewire chipset from your MB, maybe a VIA one? If so, that was the cause of my problems. I got a non VIA FW PCI card and things worked a lot better after that.

Also, another reason for my problems was that my cable connection to the DCH-3200 wasn't that good and sometimes I was getting errors that were simply because it couldn't tune the channel. Once I changed the FW card and recrimped my cable to the STB, it's been working near perfectly since then (broadcast mode of course), all this with myth 0.21 with the mythprime script as shipped on ubuntu hardy (version .55b beta)

comment:14 Changed 11 years ago by anonymous

I am using a PCI based firewire card (though this has happened with too different firewire boards). And as indicated in the description, this is not a tuning issue. The channel will always change on the cable box.

comment:15 Changed 11 years ago by danielk

Owner: danielk deleted
Status: assignednew

I don't have a firewire STB anymore, unassigning ticket.

comment:16 Changed 11 years ago by scottgprice@…

I also am having this problem with my DCH-3200. The most frustrating thing about this bug is that it makes my DCH unusable, because Myth as a whole doesn't detect a problem. Once it goes into the mode described above I get no shows recorded but Myth thinks everything is fine and doesn't mark this tuner as "Unavailable". Because of this I end up with 8 to 10 empty files of our favorite shows instead of just 1 missed show and nothing to give me a clue. I have even tried using a script to restart Myth Backend but this only works about 50% of the time. The rest of the time I have to completely reboot the machine or get behind the furniture and unplug the firewire cable. At least marking the tuner "Unavailable" when the data stops would be a big help. I have had this problem with 2 different firewire cards using different chip sets.

comment:17 Changed 11 years ago by anonymous

I very hacked work around which has worked consistently for me was to write a logsurfer script which basically monitors the backend for the culprit error messages (there are two variations of this failure) and reset the backend so at least recordings will try to resume. It doesn't fix the problem, but it does help to catch recordings that would otherwise be blank.

comment:18 in reply to:  17 Changed 11 years ago by foom@…

Replying to anonymous:

I very hacked work around which has worked consistently for me was to write a logsurfer script which basically monitors the backend for the culprit error messages (there are two variations of this failure) and reset the backend so at least recordings will try to resume. It doesn't fix the problem, but it does help to catch recordings that would otherwise be blank.

Me too. I use this script to run mythbackend for the last 4 months.

#!/bin/sh
sleep 3
echo -n "******* Restarting mythbackend at: " >> /home/mythtv/logs/mythbackend.log
date >> /home/mythtv/logs/mythbackend.log

# restart mythbackend if it gets certain errors. and exit if a new mythbackend is started.
tail -f -c0 /home/mythtv/logs/mythbackend.log| \
awk '/Error: Unable to get handle for port: -1/ {system("killall mythbackend"); exit} '\
'/^\*\*\*\*\*\*\* Restarting mythbackend at:/ {exit}' &

/usr/bin/mythbackend --pidfile /var/run/mythtv/mythbackend.pid >> /home/mythtv/logs/mythbackend.log

I also have a line:

m2:2:respawn:/usr/local/sbin/start-mythbackend

in /etc/inittab to monitor mythbackend and restart it if anything happens (either it crashes by itself or I explicitly kill it, above)

It's been working reliably with that.

comment:19 Changed 11 years ago by scottgprice@…

Thanks, both of you, I will try it.

comment:20 Changed 11 years ago by Derek Atkins <warlord@…>

I've been noticing this on my backend for the last few days. I have two DCH3200 boxes and a PCI Firewire card with a TI Chipset (so it's not the VIA problem). I dont want to just restart the backend because box #2 might still be recording something when box #1 "dies". I wonder if something is losing a file descriptor somewhere or not properly closing a connection?

It's too bad that Danielk isn't working on this anymore. Are there any other Devs that are using Firewire? Or has everyone moved over to HD-PVR?

comment:21 Changed 11 years ago by eric@…

The restart script wouldn't work for me, since I don't seem to get anything in the log file when the problem happens.

What I've noticed is that the backend will always lose the ability to control the box if it tries to tune to a channel that is (I believe) 5C encrypted.

On the other hand, majoridiot's scanfw utility (https://wiki.ubuntu.com/majoridiot) can scan the encrypted channels without losing control of the box, so it still seems like a problem in the backend, not something fundamentally wrong with the STB or firewire connection.

I don't know who's working on firewire capture and who has moved on to the HD-PVR. When it works, firewire capture should be the preferred solution, since it avoids a digtial-analog-digital conversion step.

comment:22 in reply to:  21 ; Changed 11 years ago by foom@…

Replying to eric@lisaneric.org:

The restart script wouldn't work for me, since I don't seem to get anything in the log file when the problem happens.

What I've noticed is that the backend will always lose the ability to control the box if it tries to tune to a channel that is (I believe) 5C encrypted.

Seems likely you're running into a different bug, then.

comment:23 in reply to:  22 Changed 11 years ago by anonymous

Replying to foom@fuhm.net:

Replying to eric@lisaneric.org:

The restart script wouldn't work for me, since I don't seem to get anything in the log file when the problem happens.

Seems likely you're running into a different bug, then.

No I think the logging verbosity level has just been turned down in the version I'm using.

comment:24 Changed 10 years ago by anonymous

Same problem here with 2 DCT6200's. Happens every few days; usually while I'm at work and my wife wants to watch some LiveTV.

From uname:

Linux tivvy 2.6.27-11-generic #1 SMP Thu Jan 29 19:28:32 UTC 2009 x86_64 GNU/Linux

From lspci:

05:03.0 FireWire (IEEE 1394): Agere Systems FW323 (rev 70)

From plugreport:

Host Adapter 0
==============

Node 0 GUID 0x002210fffe6c0313
------------------------------
oMPR n_plugs=1, data_rate=2, bcast_channel=63
oPCR[0] online=1, bcast_connection=0, n_p2p_connections=0
        channel=63, data_rate=2, overhead_id=0, payload=376
iMPR n_plugs=0, data_rate=2

Node 1 GUID 0x002374fffe3ccd32
------------------------------
oMPR n_plugs=1, data_rate=2, bcast_channel=63
oPCR[0] online=1, bcast_connection=0, n_p2p_connections=0
        channel=62, data_rate=2, overhead_id=0, payload=376
iMPR n_plugs=0, data_rate=2

Node 2 GUID 0x001e8c00017d9557
------------------------------
libiec61883 error: error reading oMPR
libiec61883 error: error reading iMPR

from mythbackend.log:

2009-06-22 14:15:23.689 LFireDev(002374FFFE3CCD32), Warning: No Input in 850 msec...
2009-06-22 14:15:23.745 LFireDev(002374FFFE3CCD32), Warning: No Input in 900 msec...
2009-06-22 14:15:23.796 LFireDev(002374FFFE3CCD32), Warning: No Input in 950 msec...
2009-06-22 14:15:23.848 LFireDev(002374FFFE3CCD32), Warning: No Input in 1000 msec...
2009-06-22 14:15:23.900 LFireDev(002374FFFE3CCD32), Warning: No Input in 1050 msec...
2009-06-22 14:15:23.900 LFireDev(002374FFFE3CCD32): ResetBus() -- begin
2009-06-22 14:15:23.903 LFireDev(002374FFFE3CCD32): ResetBus() -- end
2009-06-22 14:15:23.903 LFireDev(002210FFFE6C0313): SignalReset(208->209)
2009-06-22 14:15:23.909 LFireDev(002210FFFE6C0313): SignalReset(208->209): Updating device list -- begin
2009-06-22 14:15:23.918 LFireDev(002210FFFE6C0313): SignalReset(208->209): Updating device list -- end
2009-06-22 14:15:23.925 LFireDev(002374FFFE3CCD32): SignalReset(208->209)
2009-06-22 14:15:23.933 LFireDev(002374FFFE3CCD32): SignalReset(208->209): Updating device list -- begin
2009-06-22 14:15:23.941 LFireDev(002374FFFE3CCD32): SignalReset(208->209): Updating device list -- end
2009-06-22 14:15:23.999 LFireDev(002374FFFE3CCD32), Warning: No Input in 50 msec...
2009-06-22 14:15:24.051 LFireDev(002374FFFE3CCD32), Warning: No Input in 100 msec...
2009-06-22 14:15:24.328 LFireDev(002374FFFE3CCD32), Warning: No Input in 150 msec...
2009-06-22 14:15:24.380 LFireDev(002374FFFE3CCD32), Warning: No Input in 200 msec...
2009-06-22 14:15:24.432 LFireDev(002374FFFE3CCD32), Warning: No Input in 250 msec...
2009-06-22 14:15:24.484 LFireDev(002374FFFE3CCD32), Warning: No Input in 300 msec...
2009-06-22 14:15:24.536 LFireDev(002374FFFE3CCD32), Warning: No Input in 350 msec...
2009-06-22 14:15:24.588 LFireDev(002374FFFE3CCD32), Warning: No Input in 400 msec...
2009-06-22 14:15:24.640 LFireDev(002374FFFE3CCD32), Warning: No Input in 450 msec...
2009-06-22 14:15:24.692 LFireDev(002374FFFE3CCD32), Warning: No Input in 500 msec...
2009-06-22 14:15:24.744 LFireDev(002374FFFE3CCD32), Warning: No Input in 550 msec...
2009-06-22 14:15:24.796 LFireDev(002374FFFE3CCD32), Warning: No Input in 600 msec...
2009-06-22 14:15:24.849 LFireDev(002374FFFE3CCD32), Warning: No Input in 650 msec...
2009-06-22 14:15:24.900 LFireDev(002374FFFE3CCD32), Warning: No Input in 700 msec...
2009-06-22 14:15:24.952 LFireDev(002374FFFE3CCD32), Warning: No Input in 750 msec...
2009-06-22 14:15:25.004 LFireDev(002374FFFE3CCD32), Warning: No Input in 800 msec...
2009-06-22 14:15:25.055 LFireDev(002374FFFE3CCD32), Warning: No Input in 850 msec...
2009-06-22 14:15:25.109 LFireDev(002374FFFE3CCD32), Warning: No Input in 900 msec...
2009-06-22 14:15:25.160 LFireDev(002374FFFE3CCD32), Warning: No Input in 950 msec...
2009-06-22 14:15:25.211 LFireDev(002374FFFE3CCD32), Warning: No Input in 1000 msec...
2009-06-22 14:15:25.263 LFireDev(002374FFFE3CCD32), Warning: No Input in 1050 msec...
2009-06-22 14:15:25.264 LFireDev(002374FFFE3CCD32): ResetBus() -- begin
2009-06-22 14:15:25.267 LFireDev(002374FFFE3CCD32): ResetBus() -- end
2009-06-22 14:15:25.267 LFireDev(002210FFFE6C0313): SignalReset(209->210)
2009-06-22 14:15:25.273 LFireDev(002210FFFE6C0313): SignalReset(209->210): Updating device list -- begin
2009-06-22 14:15:25.588 LFireDev(002210FFFE6C0313): SignalReset(209->210): Updating device list -- end
2009-06-22 14:15:25.588 LFireDev(002374FFFE3CCD32): SignalReset(209->210)
2009-06-22 14:15:25.593 LFireDev(002374FFFE3CCD32): SignalReset(209->210): Updating device list -- begin
2009-06-22 14:15:25.896 LFireDev(002374FFFE3CCD32): SignalReset(209->210): Updating device list -- end
2009-06-22 14:15:25.947 LFireDev(002374FFFE3CCD32), Warning: No Input in 50 msec...
2009-06-22 14:15:26.000 LFireDev(002374FFFE3CCD32), Warning: No Input in 100 msec...
libiec61883 warning: iec61883_cmp_create_bcast_output: Failed to set the oPCR[0] plug for node 63.
2009-06-22 14:15:26.001 LFireDev(002374FFFE3CCD32), Error: Bus Reset : Failed to reconnect
2009-06-22 14:15:26.052 LFireDev(002374FFFE3CCD32), Warning: No Input in 150 msec...
2009-06-22 14:15:26.103 LFireDev(002374FFFE3CCD32), Warning: No Input in 200 msec...
2009-06-22 14:15:26.155 LFireDev(002374FFFE3CCD32), Warning: No Input in 250 msec...
2009-06-22 14:15:26.209 LFireDev(002374FFFE3CCD32), Warning: No Input in 300 msec...
2009-06-22 14:15:26.260 LFireDev(002374FFFE3CCD32), Warning: No Input in 350 msec...
2009-06-22 14:15:26.312 LFireDev(002374FFFE3CCD32), Warning: No Input in 400 msec...
2009-06-22 14:15:26.364 LFireDev(002374FFFE3CCD32), Warning: No Input in 450 msec...
2009-06-22 14:15:26.416 LFireDev(002374FFFE3CCD32), Warning: No Input in 500 msec...
2009-06-22 14:15:26.468 LFireDev(002374FFFE3CCD32), Warning: No Input in 550 msec...
2009-06-22 14:15:26.521 LFireDev(002374FFFE3CCD32), Warning: No Input in 600 msec...
2009-06-22 14:15:26.572 LFireDev(002374FFFE3CCD32), Warning: No Input in 650 msec...
2009-06-22 14:15:26.624 LFireDev(002374FFFE3CCD32), Warning: No Input in 700 msec...
2009-06-22 14:15:26.675 LFireDev(002374FFFE3CCD32), Warning: No Input in 750 msec...
2009-06-22 14:15:26.727 LFireDev(002374FFFE3CCD32), Warning: No Input in 800 msec...
2009-06-22 14:15:26.780 LFireDev(002374FFFE3CCD32), Warning: No Input in 850 msec...
2009-06-22 14:15:26.832 LFireDev(002374FFFE3CCD32), Warning: No Input in 900 msec...
2009-06-22 14:15:26.884 LFireDev(002374FFFE3CCD32), Warning: No Input in 950 msec...
2009-06-22 14:15:26.936 LFireDev(002374FFFE3CCD32), Warning: No Input in 1000 msec...
2009-06-22 14:15:26.988 LFireDev(002374FFFE3CCD32), Warning: No Input in 1050 msec...
2009-06-22 14:15:26.988 LFireDev(002374FFFE3CCD32): ResetBus() -- begin
2009-06-22 14:15:26.991 LFireDev(002374FFFE3CCD32): ResetBus() -- end
2009-06-22 14:15:26.991 LFireDev(002210FFFE6C0313): SignalReset(210->211)
2009-06-22 14:15:27.001 LFireDev(002210FFFE6C0313): SignalReset(210->211): Updating device list -- begin
2009-06-22 14:15:27.011 LFireDev(002210FFFE6C0313): SignalReset(210->211): Updating device list -- end
2009-06-22 14:15:27.017 LFireDev(002374FFFE3CCD32): SignalReset(210->211)
2009-06-22 14:15:27.025 LFireDev(002374FFFE3CCD32): SignalReset(210->211): Updating device list -- begin
2009-06-22 14:15:27.035 LFireDev(002374FFFE3CCD32): SignalReset(210->211): Updating device list -- end
2009-06-22 14:15:27.092 LFireDev(002374FFFE3CCD32), Warning: No Input in 50 msec...
2009-06-22 14:15:27.144 LFireDev(002374FFFE3CCD32), Warning: No Input in 100 msec...
2009-06-22 14:15:27.195 LFireDev(002374FFFE3CCD32), Warning: No Input in 150 msec...
2009-06-22 14:15:27.248 LFireDev(002374FFFE3CCD32), Warning: No Input in 200 msec...
2009-06-22 14:15:27.299 LFireDev(002374FFFE3CCD32), Warning: No Input in 250 msec...
2009-06-22 14:15:27.352 LFireDev(002374FFFE3CCD32), Warning: No Input in 300 msec...
2009-06-22 14:15:27.404 LFireDev(002374FFFE3CCD32), Warning: No Input in 350 msec...
2009-06-22 14:15:27.456 LFireDev(002374FFFE3CCD32), Warning: No Input in 400 msec...
2009-06-22 14:15:27.508 LFireDev(002374FFFE3CCD32), Warning: No Input in 450 msec...
2009-06-22 14:15:27.560 LFireDev(002374FFFE3CCD32), Warning: No Input in 500 msec...
2009-06-22 14:15:27.613 LFireDev(002374FFFE3CCD32), Warning: No Input in 550 msec...
2009-06-22 14:15:27.665 LFireDev(002374FFFE3CCD32), Warning: No Input in 600 msec...
2009-06-22 14:15:27.716 LFireDev(002374FFFE3CCD32), Warning: No Input in 650 msec...
2009-06-22 14:15:27.767 LFireDev(002374FFFE3CCD32), Warning: No Input in 700 msec...
2009-06-22 14:15:27.819 LFireDev(002374FFFE3CCD32), Warning: No Input in 750 msec...
2009-06-22 14:15:27.871 LFireDev(002374FFFE3CCD32), Warning: No Input in 800 msec...
2009-06-22 14:15:27.923 LFireDev(002374FFFE3CCD32), Warning: No Input in 850 msec...
2009-06-22 14:15:27.976 LFireDev(002374FFFE3CCD32), Warning: No Input in 900 msec...
2009-06-22 14:15:28.029 LFireDev(002374FFFE3CCD32), Warning: No Input in 950 msec...
2009-06-22 14:15:28.080 LFireDev(002374FFFE3CCD32), Warning: No Input in 1000 msec...
2009-06-22 14:15:28.132 LFireDev(002374FFFE3CCD32), Warning: No Input in 1050 msec...
2009-06-22 14:15:28.132 LFireDev(002374FFFE3CCD32): ResetBus() -- begin
2009-06-22 14:15:28.135 LFireDev(002374FFFE3CCD32): ResetBus() -- end
2009-06-22 14:15:28.135 LFireDev(002210FFFE6C0313): SignalReset(211->212)
2009-06-22 14:15:28.140 LFireDev(002210FFFE6C0313): SignalReset(211->212): Updating device list -- begin
2009-06-22 14:15:28.456 LFireDev(002210FFFE6C0313): SignalReset(211->212): Updating device list -- end
2009-06-22 14:15:28.456 LFireDev(002374FFFE3CCD32): SignalReset(211->212)
2009-06-22 14:15:28.461 LFireDev(002374FFFE3CCD32): SignalReset(211->212): Updating device list -- begin
2009-06-22 14:15:28.764 LFireDev(002374FFFE3CCD32): SignalReset(211->212): Updating device list -- end
2009-06-22 14:15:28.816 LFireDev(002374FFFE3CCD32), Warning: No Input in 50 msec...
2009-06-22 14:15:28.869 LFireDev(002374FFFE3CCD32), Warning: No Input in 100 msec...
libiec61883 warning: iec61883_cmp_create_bcast_output: Failed to set the oPCR[0] plug for node 63.
2009-06-22 14:15:28.870 LFireDev(002374FFFE3CCD32), Error: Bus Reset : Failed to reconnect
2009-06-22 14:15:28.920 LFireDev(002374FFFE3CCD32), Warning: No Input in 150 msec...
2009-06-22 14:15:28.972 LFireDev(002374FFFE3CCD32), Warning: No Input in 200 msec...
2009-06-22 14:15:29.023 LFireDev(002374FFFE3CCD32), Warning: No Input in 250 msec...
2009-06-22 14:15:29.076 LFireDev(002374FFFE3CCD32), Warning: No Input in 300 msec...
2009-06-22 14:15:29.127 LFireDev(002374FFFE3CCD32), Warning: No Input in 350 msec...
2009-06-22 14:15:29.179 LFireDev(002374FFFE3CCD32), Warning: No Input in 400 msec...
2009-06-22 14:15:29.231 LFireDev(002374FFFE3CCD32), Warning: No Input in 450 msec...
2009-06-22 14:15:29.284 LFireDev(002374FFFE3CCD32), Warning: No Input in 500 msec...
2009-06-22 14:15:29.336 LFireDev(002374FFFE3CCD32), Warning: No Input in 550 msec...
2009-06-22 14:15:29.389 LFireDev(002374FFFE3CCD32), Warning: No Input in 600 msec...
2009-06-22 14:15:29.439 LFireDev(002374FFFE3CCD32), Warning: No Input in 650 msec...
2009-06-22 14:15:29.492 LFireDev(002374FFFE3CCD32), Warning: No Input in 700 msec...
2009-06-22 14:15:29.544 LFireDev(002374FFFE3CCD32), Warning: No Input in 750 msec...
2009-06-22 14:15:29.596 LFireDev(002374FFFE3CCD32), Warning: No Input in 800 msec...
2009-06-22 14:15:29.648 LFireDev(002374FFFE3CCD32), Warning: No Input in 850 msec...
2009-06-22 14:15:29.700 LFireDev(002374FFFE3CCD32), Warning: No Input in 900 msec...
2009-06-22 14:15:29.752 LFireDev(002374FFFE3CCD32), Warning: No Input in 950 msec...
2009-06-22 14:15:29.803 LFireDev(002374FFFE3CCD32), Warning: No Input in 1000 msec...
2009-06-22 14:15:29.855 LFireDev(002374FFFE3CCD32), Warning: No Input in 1050 msec...
2009-06-22 14:15:29.856 LFireDev(002374FFFE3CCD32): ResetBus() -- begin
2009-06-22 14:15:29.859 LFireDev(002374FFFE3CCD32): ResetBus() -- end
2009-06-22 14:15:29.859 LFireDev(002210FFFE6C0313): SignalReset(212->213)
2009-06-22 14:15:29.865 LFireDev(002210FFFE6C0313): SignalReset(212->213): Updating device list -- begin
2009-06-22 14:15:29.969 LFireDev(002210FFFE6C0313): SignalReset(212->213): Updating device list -- end
2009-06-22 14:15:29.970 LFireDev(002374FFFE3CCD32): SignalReset(212->213)
2009-06-22 14:15:29.973 LFireDev(002374FFFE3CCD32): SignalReset(212->213): Updating device list -- begin
2009-06-22 14:15:29.984 LFireDev(002374FFFE3CCD32): SignalReset(212->213): Updating device list -- end
2009-06-22 14:15:30.039 LFireDev(002374FFFE3CCD32), Warning: No Input in 50 msec...
2009-06-22 14:15:30.092 LFireDev(002374FFFE3CCD32), Warning: No Input in 100 msec...
2009-06-22 14:15:30.144 LFireDev(002374FFFE3CCD32), Warning: No Input in 150 msec...
2009-06-22 14:15:30.196 LFireDev(002374FFFE3CCD32), Warning: No Input in 200 msec...
2009-06-22 14:15:30.249 LFireDev(002374FFFE3CCD32), Warning: No Input in 250 msec...
2009-06-22 14:15:30.299 LFireDev(002374FFFE3CCD32), Warning: No Input in 300 msec...
2009-06-22 14:15:30.351 LFireDev(002374FFFE3CCD32), Warning: No Input in 350 msec...
2009-06-22 14:15:30.403 LFireDev(002374FFFE3CCD32), Warning: No Input in 400 msec...
2009-06-22 14:15:30.456 LFireDev(002374FFFE3CCD32), Warning: No Input in 450 msec...
2009-06-22 14:15:30.508 LFireDev(002374FFFE3CCD32), Warning: No Input in 500 msec...
2009-06-22 14:15:30.561 LFireDev(002374FFFE3CCD32), Warning: No Input in 550 msec...
2009-06-22 14:15:30.612 LFireDev(002374FFFE3CCD32), Warning: No Input in 600 msec...
2009-06-22 14:15:30.663 LFireDev(002374FFFE3CCD32), Warning: No Input in 650 msec...
2009-06-22 14:15:30.715 LFireDev(002374FFFE3CCD32), Warning: No Input in 700 msec...
2009-06-22 14:15:30.767 LFireDev(002374FFFE3CCD32), Warning: No Input in 750 msec...
2009-06-22 14:15:30.819 LFireDev(002374FFFE3CCD32), Warning: No Input in 800 msec...
2009-06-22 14:15:30.871 LFireDev(002374FFFE3CCD32), Warning: No Input in 850 msec...
2009-06-22 14:15:30.923 LFireDev(002374FFFE3CCD32), Warning: No Input in 900 msec...
2009-06-22 14:15:30.975 LFireDev(002374FFFE3CCD32), Warning: No Input in 950 msec...
2009-06-22 14:15:31.028 LFireDev(002374FFFE3CCD32), Warning: No Input in 1000 msec...
2009-06-22 14:15:31.080 LFireDev(002374FFFE3CCD32), Warning: No Input in 1050 msec...
2009-06-22 14:15:31.080 LFireDev(002374FFFE3CCD32): ResetBus() -- begin
2009-06-22 14:15:31.082 LFireDev(002210FFFE6C0313): SignalReset(213->214)
2009-06-22 14:15:31.083 LFireDev(002374FFFE3CCD32): ResetBus() -- end
2009-06-22 14:15:31.084 LFireDev(002210FFFE6C0313): SignalReset(213->214): Updating device list -- begin
2009-06-22 14:15:31.404 LFireDev(002210FFFE6C0313): SignalReset(213->214): Updating device list -- end
2009-06-22 14:15:31.404 LFireDev(002374FFFE3CCD32): SignalReset(213->214)
2009-06-22 14:15:31.409 LFireDev(002374FFFE3CCD32): SignalReset(213->214): Updating device list -- begin
2009-06-22 14:15:31.716 LFireDev(002374FFFE3CCD32): SignalReset(213->214): Updating device list -- end
2009-06-22 14:15:31.769 LFireDev(002374FFFE3CCD32), Warning: No Input in 50 msec...
2009-06-22 14:15:31.821 LFireDev(002374FFFE3CCD32), Warning: No Input in 100 msec...
libiec61883 warning: iec61883_cmp_create_bcast_output: Failed to set the oPCR[0] plug for node 63.
2009-06-22 14:15:31.822 LFireDev(002374FFFE3CCD32), Error: Bus Reset : Failed to reconnect
2009-06-22 14:15:31.872 LFireDev(002374FFFE3CCD32), Warning: No Input in 150 msec...
2009-06-22 14:15:31.924 LFireDev(002374FFFE3CCD32), Warning: No Input in 200 msec...
2009-06-22 14:15:31.975 LFireDev(002374FFFE3CCD32), Warning: No Input in 250 msec...
2009-06-22 14:15:32.028 LFireDev(002374FFFE3CCD32), Warning: No Input in 300 msec...
2009-06-22 14:15:32.076 TVRec(1): Changing from WatchingLiveTV to None
2009-06-22 14:15:32.081 LFireDev(002374FFFE3CCD32), Warning: No Input in 350 msec...
2009-06-22 14:15:32.135 LFireDev(002374FFFE3CCD32), Warning: No Input in 400 msec...
2009-06-22 14:15:33.046 MainServer::HandleAnnounce Playback
2009-06-22 14:15:33.050 adding: tivvy3 as a client (events: 0)
2009-06-22 14:15:33.052 TVRec(1): Changing from None to WatchingLiveTV
2009-06-22 14:15:33.059 TVRec(1): HW Tuner: 1->1
2009-06-22 14:15:33.060 LAVCInfo(), Error: Unable to get handle for port: -1
                        eno: Invalid argument (22)
2009-06-22 14:15:33.080 TVRec(1) Error: Failed to set channel to 13. Reverting to kState_None
2009-06-22 14:15:33.080 TVRec(1): Changing from WatchingLiveTV to None
2009-06-22 14:15:33.832 MainServer::HandleAnnounce Playback
2009-06-22 14:15:33.838 adding: tivvy3 as a client (events: 0)
2009-06-22 14:15:33.839 TVRec(1): Changing from None to WatchingLiveTV
2009-06-22 14:15:33.842 TVRec(1): HW Tuner: 1->1
2009-06-22 14:15:33.845 LAVCInfo(), Error: Unable to get handle for port: -1
                        eno: Invalid argument (22)
2009-06-22 14:15:33.850 TVRec(1) Error: Failed to set channel to 13. Reverting to kState_None
2009-06-22 14:15:33.854 TVRec(1): Changing from WatchingLiveTV to None

comment:25 in reply to:  7 Changed 10 years ago by anonymous

Replying to Mike Rice <mikerice1969@gmail.com>:

Using the internal changer (and broadcast mode) things usually appear fine directly after restarting the backend. A recording (or LiveTV) starts recording and after some minutes 15-45 minutes typically there is no longer any data available and the backend tries to recover with SignalReset?. That does the UpdateDeviceList?() which goes through the ports and nodes and gets the guid (get_guid). My problem is that get_guid will no longer get the guid as it errors with "temporarily unavailable". Once it gets into this state it usually stays unavailable but occasionally it recovers. Of course I can run plugreport during the time the get_guid read is "temporarily unavailable" and it will report the guid just fine so I am not sure what to think here.

Further to above and in followup to reply-7, get_guid claims it is copied from some version of plugreport. In actuality, it seems loosely based on rom1394_get_guid() in libavc1394. The difference is the version in libavc1394 uses a cooked1394_read() which retries the read 20 times with a delay between each attempt. This is probably why plugreport succeeds and get_guid fails. Looks like the way to fix this is to remove get_guid and simply call rom1394_get_guid. I suspect get_guid was copied from an old version of plugreport and since then, get_guid was moved out of plugreport and into libavc1394, and then subsequently repaired; leaving this version of it to rot.

-- HP

comment:26 Changed 10 years ago by stuartm

Component: mythtvMythTV - Recording
Owner: set to Isaac Richards
Status: newassigned

comment:27 Changed 10 years ago by achew22+mythtv@…

I'm encountering this error too with a (from lspci) FireWire? (IEEE 1394): VIA Technologies, Inc. Device 3403 and a DCH6200. I'm using broadcast mode and the internal (to myth) channel changer. If more information is needed I'm happy to provide it please just comment on this ticket with what you need.

Uname -a = "Linux mythtv 2.6.28-15-server #49-Ubuntu SMP Tue Aug 18 19:30:06 UTC 2009 i686 GNU/Linux" SVN revision 21929

Plugreport:

$ plugreport 
Host Adapter 0
==============

Node 0 GUID 0x002374fffe433ae2
------------------------------
oMPR n_plugs=1, data_rate=2, bcast_channel=63
oPCR[0] online=1, bcast_connection=0, n_p2p_connections=0
	channel=63, data_rate=0, overhead_id=0, payload=376
iMPR n_plugs=0, data_rate=2

Node 1 GUID 0x001e8c0001f76b2b
------------------------------
libiec61883 error: error reading oMPR
libiec61883 error: error reading iMPR

Log follows:

2009-09-18 00:45:51.544 New DB connection, total: 2
2009-09-18 00:45:51.548 mythbackend: MythBackend started as master server
2009-09-18 00:45:52.168 New DB connection, total: 3
2009-09-18 00:45:53.692 SetLastChannel(61): cleared: no
2009-09-18 00:45:53.703 New DB scheduler connection
2009-09-18 00:45:54.416 Main::Registering HttpStatus Extension
2009-09-18 00:45:54.418 Enabled verbose msgs: important
2009-09-18 00:45:54.421 AutoExpire: CalcParams(): Max required Free Space: 1.0 GB w/freq: 15 min
2009-09-18 00:45:57.223 scheduler: Scheduled items: Scheduled 458 items in 0.5 = 0.02 match + 0.49 place
2009-09-18 00:45:57.234 Seem to be woken up by USER
2009-09-18 00:46:03.709 mythbackend: Running housekeeping thread
2009-09-18 00:46:09.565 adding: mythtv as a client (events: 0)
2009-09-18 00:46:09.570 adding: mythtv as a client (events: 1)
2009-09-18 00:46:09.612 adding: mythtv as a client (events: 0)
2009-09-18 00:46:09.629 TVRec(1): Changing from None to Watching WatchingLiveTV
2009-09-18 00:46:09.655 TVRec(1): HW Tuner: 1->1
2009-09-18 00:46:11.166 SetLastChannel(61): cleared: yes
2009-09-18 00:46:11.196 AutoExpire: CalcParams(): Max required Free Space: 3.0 GB w/freq: 15 min
2009-09-18 00:46:11.197 LFireDev(002374FFFE433AE2): Buffered packets 2000 (8000 KB)
2009-09-18 00:46:11.263 LFireDev(002374FFFE433AE2), Warning: No Input in 50 msec...
2009-09-18 00:46:11.328 LFireDev(002374FFFE433AE2), Warning: No Input in 100 msec...
2009-09-18 00:46:11.384 LFireDev(002374FFFE433AE2), Warning: No Input in 150 msec...
2009-09-18 00:46:11.436 LFireDev(002374FFFE433AE2), Warning: No Input in 200 msec...
2009-09-18 00:46:11.487 LFireDev(002374FFFE433AE2), Warning: No Input in 250 msec...
2009-09-18 00:46:11.538 LFireDev(002374FFFE433AE2), Warning: No Input in 300 msec...
2009-09-18 00:46:11.589 LFireDev(002374FFFE433AE2), Warning: No Input in 350 msec...
2009-09-18 00:46:11.639 LFireDev(002374FFFE433AE2), Warning: No Input in 400 msec...
2009-09-18 00:46:11.690 LFireDev(002374FFFE433AE2), Warning: No Input in 450 msec...
2009-09-18 00:46:11.741 LFireDev(002374FFFE433AE2), Warning: No Input in 500 msec...
2009-09-18 00:46:11.792 LFireDev(002374FFFE433AE2), Warning: No Input in 550 msec...
2009-09-18 00:46:11.842 LFireDev(002374FFFE433AE2), Warning: No Input in 600 msec...
2009-09-18 00:46:11.893 LFireDev(002374FFFE433AE2), Warning: No Input in 650 msec...
2009-09-18 00:46:11.944 LFireDev(002374FFFE433AE2), Warning: No Input in 700 msec...
2009-09-18 00:46:11.994 LFireDev(002374FFFE433AE2), Warning: No Input in 750 msec...
2009-09-18 00:46:12.045 LFireDev(002374FFFE433AE2), Warning: No Input in 800 msec...
2009-09-18 00:46:12.096 LFireDev(002374FFFE433AE2), Warning: No Input in 850 msec...
2009-09-18 00:46:12.147 LFireDev(002374FFFE433AE2), Warning: No Input in 900 msec...
2009-09-18 00:46:12.197 LFireDev(002374FFFE433AE2), Warning: No Input in 950 msec...
2009-09-18 00:46:12.248 LFireDev(002374FFFE433AE2), Warning: No Input in 1000 msec...
2009-09-18 00:46:12.299 LFireDev(002374FFFE433AE2), Warning: No Input in 1050 msec...
2009-09-18 00:46:12.300 LFireDev(002374FFFE433AE2): ResetBus() -- begin
2009-09-18 00:46:12.302 LFireDev(002374FFFE433AE2): ResetBus() -- end
2009-09-18 00:46:12.303 LFireDev(002374FFFE433AE2): SignalReset(442->443)
2009-09-18 00:46:12.304 LFireDev(002374FFFE433AE2): SignalReset(442->443): Updating device list -- begin
2009-09-18 00:46:12.607 LFireDev(002374FFFE433AE2): SignalReset(442->443): Updating device list -- end
2009-09-18 00:46:12.658 LFireDev(002374FFFE433AE2), Warning: No Input in 50 msec...
2009-09-18 00:46:12.709 LFireDev(002374FFFE433AE2), Warning: No Input in 100 msec...
libiec61883 warning: iec61883_cmp_create_bcast_output: Failed to set the oPCR[0] plug for node 63.
2009-09-18 00:46:12.710 LFireDev(002374FFFE433AE2), Error: Bus Reset : Failed to reconnect
2009-09-18 00:46:12.761 LFireDev(002374FFFE433AE2), Warning: No Input in 150 msec...

It goes on like that forever (if you need more I'm happy to post)

comment:28 Changed 10 years ago by scottadmi@…

I took the advice above and found it is very straightforward to replace the get_guid function inside linuxfirewiredevice.cpp to call the one from libavc1394. For the purposes of testing, I merely replaced the contents of the existing function so it looks like this:

static bool get_guid(raw1394handle_t handle, nodeid_t node, uint64_t &guid,
                     bool &temp_unavailable)
{
    node = 0x003f & node;
    guid = rom1394_get_guid(handle, node);
    return true;
}   

Note: the first line (node = 0x003f & node) exists only to reverse the unnecessary padding done by the caller. The correct solution would be to simply remove the "0xffc0 | node" from the call, but for the purposes of a simple single location fix, I left that as is and just replaced the function as above. So far, this fix has performed well though I haven't been using it long enough to know if it might still return invalid GUIDs which are the cause of this bug in the first place.

For a long time, I had been getting by with a script which monitors the myth backend log and resets it if it detects this type of failure so HD recordings don't get missed because and I don't have to manually restart the backend if I'm watching live TV and it happens (though it does take a bit to restart). I can post this if anyone is curious, but hopefully this will render it unnecessary.

comment:29 Changed 10 years ago by anonymous

scottadmi:

Thanks for the update. I did try something similar myself but it didn't seem to make any difference for my setup. Please keep me posted.

What I've done in the meantime is provided my wife with a cgi she can call from her browser to reset the mythtv-backend in case it fails so that's cut down the irritation factor somewhat...

I'm curious to know how your fix is performing in the coming weeks.

-- HP

comment:30 Changed 10 years ago by scottadmi@…

So far, the switch has worked well (it no longer fails to get the GUID for the firewire reset). As I mentioned, I created a script which watches the log file and automatically resets the backend if it detects this failure. Since I applied this fix (currently to 0.22) it's been behaving much better but if you feel like the log-monitoring script would be of use, let me know and I'll post it.

comment:31 Changed 10 years ago by anonymous

I've implemented exactly the patch described above and tried antagonizing it in a way which would cause it to fail previously... It hasn't failed yet and my logs indicate it also hasn't failed for my wife in the last 2 days...There's a problem with the above, however. Since 'tmp' isn't technically initialized, we could go in to get_guid and come back out with 'tmp' != 0 and consequently loop indefinitely. We don't really need any of that old code, however, so can get rid of get_guid entirely. There's one problem with my diff however; and that is cooked1394_read() will time out after 20*20ms read attempts. After 2 of those, we could return from rom1394_get_guid() with a bogus guid... We should probably still use the guid_timer to detect this condition and do something smart; but I'm not sure what 'something smart' is in this case...

Here's what I've got... This does appear to work and I've not been able to antagonize it into failing ...

Index: linuxfirewiredevice.cpp
===================================================================
--- linuxfirewiredevice.cpp     (revision 20752)
+++ linuxfirewiredevice.cpp     (working copy)
@@ -120,8 +120,6 @@
 static QString speed_to_string(uint speed);
 static int linux_firewire_device_bus_reset_handler(
     raw1394handle_t handle, uint generation);
-static bool get_guid(raw1394handle_t handle, nodeid_t node,
-                     uint64_t &guid, bool &temp_unavailable);
 
 LinuxFirewireDevice::LinuxFirewireDevice(
     uint64_t guid, uint subunitid,
@@ -881,27 +879,15 @@
             continue;
         }
 
-        MythTimer guid_timer;
-        guid_timer.start();
         for (int node = 0; node < raw1394_get_nodecount(item.handle); node++)
         {
-            bool tmp;
             uint64_t guid;
-            if (!get_guid(item.handle, 0xffc0 | node, guid, tmp))
-            {
-                if (tmp && (guid_timer.elapsed() < 200))
-                { // device has gone off-line temporarily
-                    usleep(10 * 1000);
-                    node--;
-                }
-                continue; // device has gone off-line
-            }
 
+            guid = rom1394_get_guid(item.handle, node);
             item.port = port;
             item.node = node;
             UpdateDeviceListItem(guid, &item);
             guid_online[guid] = true;
-            guid_timer.start();
         }
 
         raw1394_destroy_handle(item.handle);
@@ -1030,36 +1016,3 @@
 
     return 0;
 }
-
-// get_guid copied from plugreport, Copyright 2002-2004 Dan Dennedy GPL v2+
-#define PLUGREPORT_GUID_HI 0x0C
-#define PLUGREPORT_GUID_LO 0x10
-static bool get_guid(raw1394handle_t handle, nodeid_t node, uint64_t &guid,
-                     bool &temp_unavailable)
-{
-    uint64_t offset = CSR_REGISTER_BASE + CSR_CONFIG_ROM + PLUGREPORT_GUID_HI;
-    uint32_t quadlet;
-    int err = raw1394_read(handle, node, offset, sizeof(uint32_t), &quadlet);
-    if (-1 == err)
-    {
-        temp_unavailable = (errno == 11);
-        if (!temp_unavailable)
-            VERBOSE(VB_IMPORTANT, "get_guid 1, Error: " + ENO);
-        return false;
-    }
-    guid = htonl(quadlet);
-    guid <<= 32;
-
-    offset = CSR_REGISTER_BASE + CSR_CONFIG_ROM + PLUGREPORT_GUID_LO;
-    err = raw1394_read(handle, node, offset, sizeof(uint32_t), &quadlet);
-    if (-1 == err)
-    {
-        temp_unavailable = (errno == 11);
-        if (!temp_unavailable)
-            VERBOSE(VB_IMPORTANT, "get_guid 2, Error: " + ENO);
-        return false;
-    }
-    guid += htonl(quadlet);
-
-    return true;
-}

comment:32 Changed 10 years ago by anonymous

The above fix has been working flawlessly for 2 weeks now... This seems like a more or less correct fix.

-- hp

comment:33 Changed 10 years ago by anonymous

I currently have this problem in my Myth box. Is there something wrong with the diff described by anon in the post above? I would love my myth box to just go back to working and it sounds like the above fix would do that.

comment:34 Changed 10 years ago by Stuart Auchterlonie

Milestone: unknown0.23

comment:35 Changed 10 years ago by anonymous

Well, it was working fine for 9 weeks and has just started doing it again... I've had other problems with the recordings from DCT-6200's so maybe that's caused some longer delays...

I'm now getting this:

2010-01-16 12:44:06.065 LAVCInfo(), Error: Unable to get handle for port: -1

eno: Invalid argument (22)

I'm not sure what call is returning EINVAL...

-- hp

comment:36 Changed 10 years ago by Foliage

scottadmi:

Can you post the script you used to monitor the log file and restart when this failure appears? I'm at my wit's end with this issue, and your script would be helpful. Thanks!

comment:37 Changed 10 years ago by robertm

Ticket locked: set

comment:38 Changed 10 years ago by Jarod Wilson

(In [23656]) Drop internal and possibly sub-standard get_guid function from linux firewire code, and replace it with a call to libavc1394's rom1394_get_guid.

May possibly help some firewire cable boxes be more reliably discovered. Even if it doesn't, it makes a lot of sense to use the standard library function that is available instead of our own implementation.

Patch from "hp" in ticket #5278.

Refs #5278. Not sure it actually entirely fixes it though.

comment:39 Changed 10 years ago by robertm

Milestone: 0.230.24

Since the patch was applied, bumping this to .24 when ideally we can confirm that all is well and close this.

comment:40 Changed 10 years ago by stuartm

Owner: changed from Isaac Richards to Jarod Wilson

comment:41 Changed 10 years ago by stuartm

Status: assignedinfoneeded

We're waiting to know if the committed fix has worked for everyone, so change the state to infoneeded.

comment:42 Changed 10 years ago by robertm

Resolution: fixed
Status: infoneededclosed

If this isn't fixed for you in .23, please reopen.

comment:43 Changed 10 years ago by robertm

Ticket locked: unset

Unlocking for comment

comment:44 Changed 10 years ago by eric@…

I'm not sure if this is fixed or not. I don't see "Unable to get handle for port: -1" in my logs since upgrading to .23-rc2 (that error is there as recently as the morning before the upgrade) but it's still not working reliably. For example, on a recent attempt to record The Daily Show, I only got about 3 minutes of it.

2010-04-14 22:59:02.515 Scheduled 1772 items in 11.6 = 0.00 match + 11.61 place
2010-04-14 22:59:19.888 TVRec(3): ASK_RECORDING 3 29 0 0
2010-04-14 22:59:19.977 TVRec(4): ASK_RECORDING 4 29 0 0
2010-04-14 22:59:51.593 ProgramInfo(): Updated pathname '':'' -> '3828_20100414230000.mpg'
2010-04-14 22:59:51.668 TVRec(4): Changing from None to RecordingOnly
2010-04-14 22:59:51.670 TVRec(4): HW Tuner: 4->4
2010-04-14 22:59:53.237 SetLastChannel(828): cleared: no
2010-04-14 22:59:53.245 LFireDev(001AADFFFE47916E): Buffered packets 2000 (8000 KB)
2010-04-14 22:59:53.333 AutoExpire: CalcParams(): Max required Free Space: 42.0 GB w/freq: 7 min
2010-04-14 22:59:53.334 Started recording: The Daily Show With Jon Stewart: channel 3828 on cardid 4, sourceid 3
2010-04-14 22:59:53.392 ProgramInfo(): Updated pathname '':'' -> '2526_20100414230000.mpg'
2010-04-14 22:59:53.465 TVRec(3): Changing from None to RecordingOnly
2010-04-14 22:59:53.469 TVRec(3): HW Tuner: 3->3
2010-04-14 22:59:53.561 AutoExpire: CalcParams(): Max required Free Space: 42.0 GB w/freq: 4 min
2010-04-14 22:59:53.562 Started recording: Good Eats "Oh My, Meat Pie": channel 2526 on cardid 3, sourceid 2
2010-04-14 22:59:54.013 TVRec(3): rec->GetFileName(): '/var/lib/mythtv/2526_20100414230000.mpg'
2010-04-14 22:59:55.283 TVRec(4): rec->GetFileName(): '/var/lib/mythtv/3828_20100414230000.mpg'
2010-04-14 22:59:55.287 LFireDev(001AADFFFE47916E): Buffered packets 2000 (8000 KB)
[..]
2010-04-14 23:02:23.172 LFireDev(001AADFFFE47916E), Warning: No Input in 50 msec...
2010-04-14 23:02:23.222 LFireDev(001AADFFFE47916E), Warning: No Input in 100 msec...
2010-04-14 23:02:23.272 LFireDev(001AADFFFE47916E), Warning: No Input in 150 msec...
[..]
2010-04-14 23:02:24.132 LFireDev(001AADFFFE47916E), Warning: No Input in 1000 msec...
2010-04-14 23:02:24.189 LFireDev(001AADFFFE47916E), Warning: No Input in 1050 msec...
2010-04-14 23:02:24.210 LFireDev(001AADFFFE47916E): ResetBus() -- begin
2010-04-14 23:02:24.220 LFireDev(001AADFFFE47916E): ResetBus() -- end
2010-04-14 23:02:24.271 LFireDev(001AADFFFE47916E), Warning: No Input in 50 msec...
2010-04-14 23:02:24.321 LFireDev(001AADFFFE47916E), Warning: No Input in 100 msec...
[....]
2010-04-14 23:30:30.505 LFireDev(001AADFFFE47916E), Warning: No Input in 800 msec...
2010-04-14 23:30:30.556 LFireDev(001AADFFFE47916E), Warning: No Input in 850 msec...
2010-04-14 23:30:30.607 LFireDev(001AADFFFE47916E), Warning: No Input in 900 msec...
2010-04-14 23:30:30.640 TVRec(4): Changing from RecordingOnly to None
2010-04-14 23:30:30.641 ProgramInfo(): Updated pathname '':'' -> '3828_20100414230000.mpg'
2010-04-14 23:30:30.642 Finished recording The Daily Show With Jon Stewart: channel 3828
2010-04-14 23:30:30.643 ProgramInfo(3828_20100414230000.mpg): Recording designated 1080i/p because width was 1920
2010-04-14 23:30:30.655 Reschedule requested for id 0.

It's quite possible that this is a different bug, but all I can really say is that recording via firewire from a DCH3200 still isn't stable for me. .23 doesn't seem any better than .22 was.

Is it possible that the change makes the error message go away but doesn't fix the underlying problem?

Is anyone else having successes or failures with this?

comment:45 Changed 10 years ago by robertm

This message is consistent with 5C status changing in the program, which can and does happen. Have you captured in any other program to determine that your firewire connection is otherwise functional and rock solid?

comment:46 in reply to:  45 Changed 10 years ago by eric@…

Replying to robertm:

This message is consistent with 5C status changing in the program, which can and does happen.

I know, but I don't think that's it in this case.

I had a bunch of channels I couldn't capture and I assumed it was a 5C issue, even though the diagnostic screen for the STB said the channels weren't enabled for 5C. However, after switching from a TI firewire controller to a VIA one I can get those channels now.

I still think it's something to do with the way the box changes port numbers.

Have you captured in any other program to determine that your firewire connection is otherwise functional and rock solid?

I've been recording over firewire from this STB for quite some time. Probably close to two years. (My first comment on this ticket says "Changed 19 months ago by eric@...") It's always been "functional" but never "rock solid".

Since upgrading to .23, I haven't yet caught a failure like this while it was happening. It used to be that restarting mythbackend would get things working again. (Which, again, suggests it's not a 5C problem.) I'm going to need to keep an eye on it and see if I can reproduce that.

comment:47 Changed 10 years ago by scottadmi@…

This patch has worked flawlessly for the original problem for this ticket, and thus can and should be included for release (as the original reporter, I can say definitely the problem that happened before, is no longer occurring with this patch). For my setup with a Motorola cable box, it reliably works and has never required a reset of mythbackend to re-establish firewire channel changing and recording. Some channels do not consistently work, but this seems to be a result of the particular cable provider, as if no lock is acquired, it usually has the same issue from other programs and even testing with other computers.

The problems mentioned in previous comments do not indicate they are a result of a failed reset because of "LAVCInfo(), Error: Unable to get handle for port: -1" This is the only problem this patch was designed to address and it does so successfully, other issues related to firewire capture should probably be filled as separate bug reports so they don't hold up this fix.

comment:48 Changed 10 years ago by robertm

The patch was applied six weeks ago.

comment:49 Changed 10 years ago by eric@…

Scott, do you have any cases where the recording starts and then fails in the middle?

comment:50 Changed 10 years ago by foom@…

This bug used to affect me. However, I've since upgraded my computer, and it's never happened since. I replaced the entire machine (motherboard, CPU, etc), and also am running a new kernel (2.6.32.11), with the new firewire stack (firewire_core module instead of ieee1394 module).

I'm still running MythTV 0.22, though, and still have the exact same FireWire? set-top-box (DCH3200).

So, I suspect that the fundamental problem is/was either a driver bug or hardware bug, and not actually a bug in myth. It's of course possible that this changeset does completely reliably work-around the issue in whatever component was broken, but it seems like it might still be fragile, given that the fix is apparently just to retry every 20ms, 20 times or until it works.

I'm now using this firewire chipset, which is integrated into a GA-MA785GM-US2H motherboard:

03:0e.0 FireWire (IEEE 1394): Texas Instruments TSB43AB23 IEEE-1394a-2000 Controller (PHY/Link)

I don't have the name of the old chipset which wasn't reliable easily available, but it was an integrated firewire controller on a VIA KM266 motherboard.

Hope that info helps someone...and good luck to everyone still having the problem. :)

comment:51 Changed 10 years ago by eric@…

For the record, I'm currently running Debian unstable with kernel 2.6.32-3-amd64. I have two firewire controllers:

03:00.0 FireWire (IEEE 1394): VIA Technologies, Inc. VT6306/7/8 [Fire II(M)] IEEE 1394 OHCI Controller (rev 46)
03:07.0 FireWire (IEEE 1394): Texas Instruments TSB43AB23 IEEE-1394a-2000 Controller (PHY/Link)

The TI chip is on the motherboard and I couldn't ever get it working even remotely reliably with the Juju firewire stack. Jarod said he thought there were driver bugs with the handling of OHCI 1.1 chips. These problems may have been eliminated in later kernels. I already had a spare PCI firewire controller card with the VIA chip on it, and it worked with juju (at least most of the time). Maybe I should try switching back to the TI controller.

comment:52 Changed 10 years ago by Jarod Wilson

If I'm thinking clearly, the ohci 1.1 dual-buffer isochronous receive mode was disabled by default in 2.6.32, and then removed entirely in 2.6.33, so all cards should now be using packet-per-buffer isochronous receive, part of the ohci 1.0 spec.

Given that the original reporter says their problem is fixed, if we want to further discuss firewire reliability issues, I suggest someone with ongoing problems open up a new ticket.

comment:53 Changed 10 years ago by scottadmi@…

I didn't mean to imply the patch wasn't already applied, simply that based on my experience this bug can be validly marked as closed with this patch formally in place.

It is certainly plausible other issues remain with firewire capture (particularly given variations in chipsets and drivers), but I have been fortunate not to have issues other than this one. In response to the question, I have not had an issue with firewire recordings failing midstream (aside from the occasional mpeg glitches). Once a successful firewire capture is initiated, it seems to consistently record for the full duration.

Note: See TracTickets for help on using tickets.