[mythtv-users] Firewire Recording via RNG-110 not working

Sun Aug 15 17:13:51 UTC 2010

I believe my firewire setup in the OS (Linux, kernel 2.6.34.1, debian testing)
is correct and working, however MythTV (tags/release-0-23-1, debian multimedia)
is not recording (0 byte files). Haven't found any helpful hints in the 
list archive or by general googling. The STB (RNG-110) seems to supply
a valid MPG stream via firewire.

Setup Details:

 - single myth FE/BE, has been working for years fine with
   Clear QAM via pcHDTV5500 (LiveTV, recording), and still
   does now after setting up the firewire device.
 - Comcast supplied RNG-110, setup with P2P; firewire_tester
   reports success consistently, test_mpeg2 works consistently
   in creating mpg files that mplayer plays just fine (so no 5c 
   flag, at least for the channels I tested with), all tested with
   mythtv user (no permission problems).
   Followed pretty much http://www.mythtv.org/wiki/FireWire for all
   of that.
 - mythbackend set up with the device, connected to video source,
   channels imported, mythfilldatabase, no problem here.
 - I tried setting the STB up in the backend as a "generic" device, 
   and changing channels with 6200ch (works), 100 and 400 Mbps. 
   As well per another post I found as a DCT6200 with no channelchanger 
   script (works, too), and 400Mps.

Problem: Mythtv changes the RNG-110 to the right channel (confirmed)
   and starts recoding (so it says), but I end up with 0Byte files in
   LiveTV and scheduled recordings. LiveTV OSD shows "partial lock" only
   and no video. Different Mbps settings make no difference.

Some (hopefully) relevant backend logs (-v important,channel,record), 
set up as a 6200, are attached to this email.  
The file Mythtv is recoding does exist, but it is and stays empty:

-rw-r--r--  1 mythtv mythtv    0 Aug 15 12:32 5062_20100815123258.mpg

I am thinking I am probably missing something obvious, but I have no idea
at the moment what. Any pointers appreciated.

Thanks a bunch,

        Jens

MythTV Version   : 0.23.1
MythTV Branch    : tags/release-0-23-1
Network Protocol : 23056
Library API      : 0.23.1.201000710-1
QT Version       : 4.6.3
Options compiled in:
 linux release using_oss using_alsa using_pulse using_jack using_pulseoutput using_backend using_directfb using_dvb using_firewire using_fribidi using_frontend using_glx_proc_addr_arb using_hdhomerun using_hdpvr using_iptv using_ivtv using_joystick_menu using_libfftw3 using_lirc using_mheg using_opengl_video using_opengl_vsync using_qtdbus using_qtwebkit using_v4l using_x11 using_xrandr using_xv using_xvmc using_xvmc_vld using_xvmcw using_bindings_perl using_bindings_python using_opengl using_vdpau using_ffmpeg_threads using_libavc_5_3 using_live using_mheg

-------------- next part --------------
2010-08-15 12:32:57.307 TVRec(9): SetChannel(62) -- begin
2010-08-15 12:32:57.308 TVRec(9): ClearFlags(RingBufferReady,) -> FrontendReady,RunMainLoop,
CancelNextRecording,WaitingForSignal,NeedToStartRecorder,SignalMonitorRunning,DummyRecorderR
unning,
2010-08-15 12:32:57.308 TVRec(9): Request: Program(no) channel(62) input() flags(LiveTV,)
2010-08-15 12:32:57.308 ChannelBase(9): Looking for startchannel '62' on input 'MPEG2TS'
2010-08-15 12:32:57.314 ChannelBase(9): Found startchannel '62' on input 'MPEG2TS'
2010-08-15 12:32:57.316 TVRec(9): HW Tuner: 9->9
2010-08-15 12:32:57.316 TVRec(9): TeardownSignalMonitor() -- begin
2010-08-15 12:32:57.316 FireSM(005094000036487B): dtor
2010-08-15 12:32:57.317 FireSM(005094000036487B): Stop() -- begin
2010-08-15 12:32:57.317 SM(005094000036487B)::Stop: begin
2010-08-15 12:32:57.349 SM(005094000036487B)::Stop: end
2010-08-15 12:32:57.424 FireSM(005094000036487B): RunTableMonitor(): -- shutdown
2010-08-15 12:32:57.424 FireDev(005094000036487B): RemoveListener() 0
2010-08-15 12:32:57.424 LFireDev(005094000036487B): Stopping A/V streaming -- really
2010-08-15 12:32:57.427 LFireDev(005094000036487B): Stopped A/V streaming
2010-08-15 12:32:57.427 LFireDev(005094000036487B): Closing A/V stream object
2010-08-15 12:32:57.428 LFireDev(005094000036487B): Closing P2P connection
2010-08-15 12:32:57.438 LFireDev(005094000036487B): Stopping Port Handler Thread
2010-08-15 12:32:57.438 LFireDev(005094000036487B): Stopping Port Handler Thread -- locked
2010-08-15 12:32:57.449 LFireDev(005094000036487B): ClosePort()
2010-08-15 12:32:57.454 FireSM(005094000036487B): RunTableMonitor(): -- end
2010-08-15 12:32:57.454 FireSM(005094000036487B): Stop() -- end
2010-08-15 12:32:57.455 SM(005094000036487B)::Stop: begin
2010-08-15 12:32:57.455 SM(005094000036487B)::Stop: end
2010-08-15 12:32:57.455 TVRec(9): TeardownSignalMonitor() -- end
2010-08-15 12:32:57.456 TVRec(9): ClearFlags(SignalMonitorRunning,) -> FrontendReady,RunMainLoop,CancelNextRecording,WaitingForSignal,NeedToStartRecorder,DummyRecorderRunning,
2010-08-15 12:32:57.456 TVRec(9): ClearFlags(WaitingForSignal,) -> FrontendReady,RunMainLoop,CancelNextRecording,NeedToStartRecorder,DummyRecorderRunning,
2010-08-15 12:32:57.456 TVRec(9): ClearFlags(PENDINGACTIONS,) -> FrontendReady,RunMainLoop,CancelNextRecording,DummyRecorderRunning,
2010-08-15 12:32:57.456 TVRec(9): No recorder yet, calling TuningFrequency
2010-08-15 12:32:57.457 FireChan(005094000036487B): Open()
2010-08-15 12:32:57.460 FireChan(005094000036487B): SetChannelByString(62)
2010-08-15 12:32:57.463 SetChannelByNumber(62)
2010-08-15 12:32:57.464 FireDev(005094000036487B): Requesting STB Power State
2010-08-15 12:32:57.466 FireDev(005094000036487B): STB Power State: On
2010-08-15 12:32:57.466 SetChannel(model DCT-6200, alt 0, chan 62)
2010-08-15 12:32:57.467 SetChannel() -- locked
2010-08-15 12:32:58.982 SetLastChannel(62): cleared: no
2010-08-15 12:32:58.982 FireChan(005094000036487B): SetChannelByString(62) success
2010-08-15 12:32:58.983 TVRec(9): SwitchLiveTVRingBuffer(discont 1, set_rec 0)
2010-08-15 12:32:58.983 TVRec(9): GetProgramRingBufferForLiveTV()
2010-08-15 12:32:58.995 TVRec(9): StartedRecording(0x7f9e78747360) fn(/var/myth/mythtv/LiveTV/5062_20100815123258.mpg)
2010-08-15 12:32:59.007 ProgramInfo(): Updated pathname '':'' -> '5034_20100815123236.mpg'
2010-08-15 12:32:59.008 ProgramInfo(): Updated pathname '':'' -> '5034_20100815123236.mpg'
2010-08-15 12:32:59.009 TVRec(9): FinishedRecording(Golf) in recgroup: LiveTV
2010-08-15 12:32:59.010 Chain: Updated endtime for '5034_20100815123236' to 20100815123259
2010-08-15 12:32:59.020 Chain: Appended at 1 '5062_20100815123258'
2010-08-15 12:32:59.022 TVRec(9): ClearFlags(DummyRecorderRunning,) -> FrontendReady,RunMainLoop,CancelNextRecording,
2010-08-15 12:32:59.034 TVRec(9): Starting Signal Monitor
2010-08-15 12:32:59.034 TVRec(9): SetupSignalMonitor(1, 1)
2010-08-15 12:32:59.034 FireChan(005094000036487B): Open()
2010-08-15 12:32:59.035 FireSM(005094000036487B): ctor
2010-08-15 12:32:59.035 SM(005094000036487B)::AddFlags: Seen() Match() Wait(Sig,)
2010-08-15 12:32:59.035 FireDev(005094000036487B): Requesting STB Power State
2010-08-15 12:32:59.038 FireDev(005094000036487B): STB Power State: On
2010-08-15 12:32:59.038 TVRec(9): Signal monitor successfully created
2010-08-15 12:32:59.038 TVRec(9): Setting up table monitoring.
2010-08-15 12:32:59.042 Using profile 'Live TV' to record
2010-08-15 12:32:59.042 TVRec(9): MPEG program number: 1
2010-08-15 12:32:59.043 DTVSM(005094000036487B)::SetProgramNumber(1):
2010-08-15 12:32:59.043 SM(005094000036487B)::RemoveFlags: Seen(PMT,Crypt,) Match(PMT,Crypt,) Wait()
2010-08-15 12:32:59.043 SM(005094000036487B)::AddFlags: Seen() Match() Wait(PMT,)
2010-08-15 12:32:59.043 SM(005094000036487B)::AddFlags: Seen() Match() Wait(PAT,PMT,Pos,)
2010-08-15 12:32:59.044 TVRec(9): Successfully set up MPEG table monitoring.
2010-08-15 12:32:59.044 SM(005094000036487B)::Start: begin
2010-08-15 12:32:59.044 FireDev(005094000036487B): Requesting STB Power State
2010-08-15 12:32:59.044 SM(005094000036487B)::Start: end
2010-08-15 12:32:59.045 TVRec(9): SetFlags(SignalMonitorRunning,) -> FrontendReady,RunMainLoop,CancelNextRecording,SignalMonitorRunning,
2010-08-15 12:32:59.045 TVRec(9): ClearFlags(WaitingForSignal,) -> FrontendReady,RunMainLoop,CancelNextRecording,SignalMonitorRunning,
2010-08-15 12:32:59.045 TVRec(9): SetFlags(WaitingForSignal,) -> FrontendReady,RunMainLoop,CancelNextRecording,WaitingForSignal,SignalMonitorRunning,
2010-08-15 12:32:59.046 TVRec(9): SetFlags(DummyRecorderRunning,) -> FrontendReady,RunMainLoop,CancelNextRecording,WaitingForSignal,SignalMonitorRunning,DummyRecorderRunning,
2010-08-15 12:32:59.061 DummyDTVRecorder -- started
2010-08-15 12:32:59.066 TVRec(9): SetFlags(RingBufferReady,) -> FrontendReady,RunMainLoop,CancelNextRecording,WaitingForSignal,SignalMonitorRunning,DummyRecorderRunning,RingBufferReady,
2010-08-15 12:32:59.067 TVRec(9): ClearFlags(NeedToStartRecorder,) -> FrontendReady,RunMainLoop,CancelNextRecording,WaitingForSignal,SignalMonitorRunning,DummyRecorderRunning,RingBufferReady,
2010-08-15 12:32:59.067 TVRec(9): SetFlags(NeedToStartRecorder,) -> FrontendReady,RunMainLoop,CancelNextRecording,WaitingForSignal,NeedToStartRecorder,SignalMonitorRunning,DummyRecorderRunning,RingBufferReady,
2010-08-15 12:32:59.072 TVRec(9): SetChannel(62) -- end
2010-08-15 12:32:59.072 TVRec(9): SetChannel(62) -- end
2010-08-15 12:32:59.091 AutoExpire: CalcParams(): Max required Free Space: 4.0 GB w/freq: 7 min
2010-08-15 12:32:59.046 FireDev(005094000036487B): STB Power State: On
2010-08-15 12:32:59.092 SM(005094000036487B)::AddFlags: Seen(STB,) Match(STB,) Wait()
2010-08-15 12:32:59.093 FireSM(005094000036487B): UpdateValues() -- Waiting for table monitor to start
2010-08-15 12:32:59.094 ProgramInfo(): Updated pathname '':'' -> '5062_20100815123258.mpg'
2010-08-15 12:32:59.095 FireSM(005094000036487B): RunTableMonitor(): -- begin
2010-08-15 12:32:59.096 FireSM(005094000036487B): UpdateValues() -- Table monitor started
2010-08-15 12:32:59.097 ProgramInfo(): Updated pathname '':'' -> '5034_20100815123236.mpg'
2010-08-15 12:32:59.100 LFireDev(005094000036487B): Starting Port Handler Thread
2010-08-15 12:32:59.102 LFireDev(005094000036487B): Starting Port Handler Thread -- locked
2010-08-15 12:32:59.103 LFireDev(005094000036487B): OpenPort()
2010-08-15 12:32:59.103 LFireDev(005094000036487B): OpenPort() -- got lock
2010-08-15 12:32:59.103 FireDev(005094000036487B): AddListener() 1
2010-08-15 12:32:59.103 LFireDev(005094000036487B): Opening P2P connection
2010-08-15 12:32:59.126 LFireDev(005094000036487B): OpenAVStream
2010-08-15 12:32:59.198 LFireDev(005094000036487B): Opening A/V stream object
2010-08-15 12:32:59.199 LFireDev(005094000036487B): Buffered packets 2000 (8000 KB)
2010-08-15 12:32:59.199 LFireDev(005094000036487B): Starting A/V streaming -- really
2010-08-15 12:32:59.131 ProgramInfo(): Updated pathname '':'' -> '5062_20100815123258.mpg'
2010-08-15 12:32:59.231 ProgramInfo(): Updated pathname '':'' -> '5034_20100815123236.mpg'
2010-08-15 12:32:59.209 LFireDev(005094000036487B): Starting A/V streaming -- done
2010-08-15 12:33:07.637 TVRec(4): Deleting stale pending recording 1 'Mystery Date'
2010-08-15 12:33:07.709 TVRec(5): Deleting stale pending recording 1 'Mystery Date'
2010-08-15 12:33:07.720 TVRec(6): Deleting stale pending recording 1 'Mystery Date'
2010-08-15 12:33:07.834 TVRec(7): Deleting stale pending recording 1 'Mystery Date'
2010-08-15 12:33:46.744 AutoExpire: CalcParams(): Max required Free Space: 4.0 GB w/freq: 7 min
2010-08-15 12:33:46.748 Expiring 1551 MBytes for 2171 @ Thu May 6 21:00:00 2010 => The Office "The Cover-Up"
2010-08-15 12:33:46.752 ProgramInfo(): Updated pathname '':'' -> '2171_20100506210843.mpg'
2010-08-15 12:33:46.758 Expiring 56 MBytes for 2040 @ Tue Jun 29 07:00:00 2010 => The Early Show
2010-08-15 12:33:46.765 ProgramInfo(2171_20100506210843.mpg), Error: GetPlaybackURL: '2171_20100506210843.mpg' should be local, but it can not be found.
2010-08-15 12:33:46.766 ERROR when trying to delete file: GetPlaybackURL/UNABLE/TO/FIND/LOCAL/FILE/ON/arthur/2171_20100506210843.mpg. File doesn't exist.  Database metadata will not be removed.
2010-08-15 12:33:46.769 mythbackend: Delete Recording: File GetPlaybackURL/UNABLE/TO/FIND/LOCAL/FILE/ON/arthur/2171_20100506210843.mpg does not exist for chanid 2171 at Thu May 6 21:08:43 2010 when trying to delete recording.
2010-08-15 12:33:46.776 ProgramInfo(): Updated pathname '':'' -> '2040_20100629073415.mpg'
2010-08-15 12:33:46.786 ProgramInfo(2040_20100629073415.mpg), Error: GetPlaybackURL: '2040_20100629073415.mpg' should be local, but it can not be found.
2010-08-15 12:33:46.799 ERROR when trying to delete file: GetPlaybackURL/UNABLE/TO/FIND/LOCAL/FILE/ON/arthur/2040_20100629073415.mpg. File doesn't exist.  Database metadata will not be removed.
2010-08-15 12:33:46.809 mythbackend: Delete Recording: File GetPlaybackURL/UNABLE/TO/FIND/LO2010-08-15 12:34:14.066 ProgramInfo(): Updated pathname '':'' -> '5062_20100815123258.mpg'
2010-08-15 12:34:14.066 TVRec(9): Changing from WatchingLiveTV to None
2010-08-15 12:34:14.067 TVRec(9): ClearFlags(FrontendReady,CancelNextRecording,) -> RunMainLoop,WaitingForSignal,NeedToStartRecorder,SignalMonitorRunning,DummyRecorderRunning,RingBufferReady,
2010-08-15 12:34:14.067 TVRec(9): Request: Program(no) channel() input() flags(KillRec,KillRingBuffer,)
2010-08-15 12:34:14.067 TVRec(9): TeardownSignalMonitor() -- begin
2010-08-15 12:34:14.067 FireSM(005094000036487B): dtor
2010-08-15 12:34:14.068 FireSM(005094000036487B): Stop() -- begin
2010-08-15 12:34:14.068 SM(005094000036487B)::Stop: begin
2010-08-15 12:34:14.107 SM(005094000036487B)::Stop: end
2010-08-15 12:34:14.196 FireSM(005094000036487B): RunTableMonitor(): -- shutdown
2010-08-15 12:34:14.197 FireDev(005094000036487B): RemoveListener() 0
2010-08-15 12:34:14.197 LFireDev(005094000036487B): Stopping A/V streaming -- really
2010-08-15 12:34:14.199 LFireDev(005094000036487B): Stopped A/V streaming
2010-08-15 12:34:14.200 LFireDev(005094000036487B): Closing A/V stream object
2010-08-15 12:34:14.200 LFireDev(005094000036487B): Closing P2P connection
2010-08-15 12:34:14.210 LFireDev(005094000036487B): Stopping Port Handler Thread
2010-08-15 12:34:14.210 LFireDev(005094000036487B): Stopping Port Handler Thread -- locked
2010-08-15 12:34:14.211 LFireDev(005094000036487B): ClosePort()
2010-08-15 12:34:14.211 FireSM(005094000036487B): RunTableMonitor(): -- end
2010-08-15 12:34:14.212 FireSM(005094000036487B): Stop() -- end
2010-08-15 12:34:14.212 SM(005094000036487B)::Stop: begin
2010-08-15 12:34:14.212 SM(005094000036487B)::Stop: end
2010-08-15 12:34:14.212 TVRec(9): TeardownSignalMonitor() -- end
2010-08-15 12:34:14.213 TVRec(9): ClearFlags(SignalMonitorRunning,) -> RunMainLoop,WaitingForSignal,NeedToStartRecorder,DummyRecorderRunning,RingBufferReady,
2010-08-15 12:34:14.213 TVRec(9): ClearFlags(WaitingForSignal,) -> RunMainLoop,NeedToStartRecorder,DummyRecorderRunning,RingBufferReady,
2010-08-15 12:34:14.213 TVRec(9): ClearFlags(DummyRecorderRunning,) -> RunMainLoop,NeedToStartRecorder,RingBufferReady,
2010-08-15 12:34:14.214 ProgramInfo(): Updated pathname '':'' -> '5062_20100815123258.mpg'
2010-08-15 12:34:14.215 TVRec(9): FinishedRecording(10 Dollar Dinners With Melissa D'Arabian) in recgroup: LiveTV
2010-08-15 12:34:14.216 Chain: Updated endtime for '5062_20100815123258' to 20100815123414
2010-08-15 12:34:14.221 FireChan(005094000036487B): Close()
2010-08-15 12:34:14.221 LFireDev(005094000036487B): Stopping Port Handler Thread
2010-08-15 12:34:14.221 LFireDev(005094000036487B): Stopping Port Handler Thread -- locked
2010-08-15 12:34:14.222 LFireDev(005094000036487B): ClosePort()
2010-08-15 12:34:14.222 LFireDev(005094000036487B): Waiting for port handler thread to stop
2010-08-15 12:34:14.261 LFireDev(005094000036487B): RunPortHandler -- end
2010-08-15 12:34:14.264 LFireDev(005094000036487B): Joining port handler thread
2010-08-15 12:34:14.265 LAVCInfo(): Releasing raw1394 handle
2010-08-15 12:34:14.272 ProgramInfo(): Updated pathname '':'' -> '5062_20100815123258.mpg'
2010-08-15 12:34:14.295 TVRec(9): Tearing down RingBuffer
2010-08-15 12:34:14.344 TVRec(9): ClearFlags(PENDINGACTIONS,) -> RunMainLoop,RingBufferReady,
2010-08-15 12:34:14.345 TVRec(9): SetFlags(FrontendReady,) -> FrontendReady,RunMainLoop,RingBufferReady,
2010-08-15 12:34:14.485 ProgramInfo(): Updated pathname '':'' -> '5062_20100815123258.mpg'