MythTV Problem when shutting down a recording

[kontakt@…]

Hi,

someone is reporting following issue to us:

MythTV Frontend: 2010-10-05 22:37:05.538 TV: Attempting to change from None to WatchingLiveTV 2010-10-05 22:37:05.549 MythContext: Connecting to backend server: 192.168.1.11:6543 (try 1 of 1) 2010-10-05 22:37:05.550 Using protocol version 56 2010-10-05 22:37:05.578 Spawning LiveTV Recorder -- begin 2010-10-05 22:37:09.408 Spawning LiveTV Recorder -- end 2010-10-05 22:37:09.417 ProgramInfo?(): Updated pathname : -> '1008_20101005223708.mpg' 2010-10-05 22:37:09.477 We have a playbackURL(myth://192.168.1.11:6543/1008_20101005223708.mpg) & cardtype(DUMMY) 2010-10-05 22:37:09.477 We have a RingBuffer? 2010-10-05 22:37:09.597 NVP(1): Disabling Audio, params(-1,2,44100) 2010-10-05 22:37:09.658 ProgramInfo?(): Updated pathname : -> '1008_20101005223708.mpg' 2010-10-05 22:37:09.687 VideoOutputXv?: XVideo Adaptor Name: 'ATI Radeon AVIVO Video' 2010-10-05 22:37:09.738 OSD Theme Dimensions W: 1280 H: 720 greedyhdeint: size changed from 0 x 0 -> 720 x 576 2010-10-05 22:37:09.838 Realtime priority would require SUID as root. 2010-10-05 22:37:09.838 OpenGLVideoSync() 2010-10-05 22:37:09.903 TV: Changing from None to WatchingLiveTV 2010-10-05 22:37:09.903 TV: State is LiveTV & mctx == ctx 2010-10-05 22:37:09.912 TV: UpdateOSDInput done 2010-10-05 22:37:09.912 TV: UpdateLCD done 2010-10-05 22:37:09.912 TV: ITVRestart done 2010-10-05 22:37:09.952 ScreenSaverX11Private: DPMS Deactivated 1 2010-10-05 22:37:10.002 Video timing method: SGI OpenGL 2010-10-05 22:37:11.164 ProgramInfo?(): Updated pathname : -> '1008_20101005223710.mpg' 2010-10-05 22:37:12.145 TV: Attempting to change from WatchingLiveTV to None 2010-10-05 22:37:12.145 RingBuf?(myth://192.168.1.11:6543/1008_20101005223710.mpg) Warning: Peek() requested 2048 bytes, but only returning 376 2010-10-05 22:37:12.145 NVP::OpenFile?(): Error, couldn't read file: myth://192.168.1.11:6543/1008_20101005223710.mpg 2010-10-05 22:37:12.146 NVP(1), Error: JumpToProgram? failed. 2010-10-05 22:37:12.146 NVP(1), Error: Unknown recorder error, exiting decoder 2010-10-05 22:37:12.154 ~OpenGLVideoSync() -- closing opengl vsync 2010-10-05 22:37:13.145 RingBuf?(myth://192.168.1.11:6543/1008_20101005223710.mpg): Waited too long for ringbuffer pause.. 2010-10-05 22:37:14.385 TV: Changing from WatchingLiveTV to None 2010-10-05 22:37:14.397 MythSystemEventHandler? ERROR: SendMythSystemPlayEvent?() called with empty ProgramInfo? 2010-10-05 22:37:14.414 ScreenSaverX11Private: DPMS Reactivated 1 2010-10-05 22:37:14.459 TV: Attempting to change from None to WatchingLiveTV 2010-10-05 22:37:14.459 MythContext: Connecting to backend server: 192.168.1.11:6543 (try 1 of 1) 2010-10-05 22:37:14.469 Using protocol version 56 2010-10-05 22:37:14.489 Spawning LiveTV Recorder -- begin 2010-10-05 22:37:17.848 Spawning LiveTV Recorder -- end 2010-10-05 22:37:17.861 ProgramInfo?(): Updated pathname : -> '1008_20101005223717.mpg' 2010-10-05 22:37:17.882 We have a playbackURL(myth://192.168.1.11:6543/1008_20101005223717.mpg) & cardtype(DUMMY) 2010-10-05 22:37:17.882 We have a RingBuffer? 2010-10-05 22:37:17.933 TV Error: LiveTV not successfully started 2010-10-05 22:37:18.001 ScreenSaverX11Private: DPMS Deactivated 1 2010-10-05 22:37:18.001 ScreenSaverX11Private: DPMS Reactivated 1 2010-10-05 22:37:19.424 MythSystemEventHandler? ERROR: SendMythSystemPlayEvent?() called with empty ProgramInfo?

2010-10-05 22:37:14.427 adding: bilbo as a client (events: 0) 2010-10-05 22:37:14.444 TVRec(1): Changing from None to WatchingLiveTV 2010-10-05 22:37:14.482 TVRec(1): HW Tuner: 1->1 2010-10-05 22:37:14.989 DVBChan(1:/dev/dvb/adapter0/frontend0) Warning: Symbol Rate setting (6952000) is out of range (min/max:6250000/690 0000) 2010-10-05 22:37:17.832 AutoExpire?: CalcParams?(): Max required Free Space: 3.0 GB w/freq: 14 min 2010-10-05 22:37:17.871 ProgramInfo?(): Updated pathname : -> '1008_20101005223717.mpg' 2010-10-05 22:37:17.899 ProgramInfo?(): Updated pathname : -> '1008_20101005223717.mpg' 2010-10-05 22:37:17.916 TVRec(1): Changing from WatchingLiveTV to None 2010-10-05 22:37:18.207 ProgramInfo?(): Updated pathname : -> '1008_20101005223717.mpg' 2010-10-05 22:37:18.221 Finished recording The Breed "Amerikansk gyser fra 2006. En gruppe unge venner flyver til en tilsyneladende forladt for at feste og slappe af.": channel 1008 2010-10-05 22:37:18.252 ProgramInfo?(): Updated pathname : -> '1008_20101005223717.mpg' 2010-10-05 22:37:18.271 ProgramInfo?(): Updated pathname : -> '1008_20101005223717.mpg' 2010-10-05 22:37:18.294 ProgramInfo?(): Updated pathname : -> '1008_20101005223717.mpg' 2010-10-05 22:38:18.927 DVBChan(1:/dev/dvb/adapter0/frontend0) Warning: Symbol Rate setting (6952000) is out of range (min/max:6250000/6900000)

(please note the Symbol Rate issue is already fixed).

We were not able to reproduce this however according to the code there should be a possibility that this can happen.

The original User seems to be able to reproduce this sometimes.

Question is why should mythtv bother about the buffer when the stream is shutting down anyway? Calling this Peek() function seems to be error prone once the recording stops.

Used version:

• backend: Ubuntu 10.04, mythtv-backend version 0.23.0
• frontend: Ubuntu 10.04, mythtv-frontend version 0.23.20100314-1

[robertm]

Please see the ticket howto and do not set milestones on tickets. Can you please describe the problem rather than simply pasting logs and expecting us to figure out what they are seeing?

[beirdo]

Additionally, the backend and frontend versions aren't identical. This is usually a recipe for disaster.

[Markus]

I just tried to paste the logfile in a nice form:

2010-10-05 22:37:05.538 TV: Attempting to change from None to WatchingLiveTV
2010-10-05 22:37:05.549 MythContext: Connecting to backend server: 192.168.1.11:6543 (try 1 of 1)
2010-10-05 22:37:05.550 Using protocol version 56
2010-10-05 22:37:05.578 Spawning LiveTV Recorder -- begin
2010-10-05 22:37:09.408 Spawning LiveTV Recorder -- end
2010-10-05 22:37:09.417 ProgramInfo(): Updated pathname '':'' -> '1008_20101005223708.mpg'
2010-10-05 22:37:09.477 We have a playbackURL(myth://192.168.1.11:6543/1008_20101005223708.mpg) & cardtype(DUMMY)
2010-10-05 22:37:09.477 We have a RingBuffer
2010-10-05 22:37:09.597 NVP(1): Disabling Audio, params(-1,2,44100)
2010-10-05 22:37:09.658 ProgramInfo(): Updated pathname '':'' -> '1008_20101005223708.mpg'
2010-10-05 22:37:09.687 VideoOutputXv: XVideo Adaptor Name: 'ATI Radeon AVIVO Video'
2010-10-05 22:37:09.738 OSD Theme Dimensions W: 1280 H: 720
greedyhdeint: size changed from 0 x 0 -> 720 x 576
2010-10-05 22:37:09.838 Realtime priority would require SUID as root.
2010-10-05 22:37:09.838 OpenGLVideoSync()
2010-10-05 22:37:09.903 TV: Changing from None to WatchingLiveTV
2010-10-05 22:37:09.903 TV: State is LiveTV & mctx == ctx
2010-10-05 22:37:09.912 TV: UpdateOSDInput done
2010-10-05 22:37:09.912 TV: UpdateLCD done
2010-10-05 22:37:09.912 TV: ITVRestart done
2010-10-05 22:37:09.952 ScreenSaverX11Private: DPMS Deactivated 1
2010-10-05 22:37:10.002 Video timing method: SGI OpenGL
2010-10-05 22:37:11.164 ProgramInfo(): Updated pathname '':'' -> '1008_20101005223710.mpg'
2010-10-05 22:37:12.145 TV: Attempting to change from WatchingLiveTV to None
2010-10-05 22:37:12.145 RingBuf(myth://192.168.1.11:6543/1008_20101005223710.mpg) Warning: Peek() requested 2048 bytes, but only returning 376
2010-10-05 22:37:12.145 NVP::OpenFile(): Error, couldn't read file: myth://192.168.1.11:6543/1008_20101005223710.mpg
2010-10-05 22:37:12.146 NVP(1), Error: JumpToProgram failed.
2010-10-05 22:37:12.146 NVP(1), Error: Unknown recorder error, exiting decoder
2010-10-05 22:37:12.154 ~OpenGLVideoSync() -- closing opengl vsync
2010-10-05 22:37:13.145 RingBuf(myth://192.168.1.11:6543/1008_20101005223710.mpg): Waited too long for ringbuffer pause..
2010-10-05 22:37:14.385 TV: Changing from WatchingLiveTV to None
2010-10-05 22:37:14.397 MythSystemEventHandler ERROR: SendMythSystemPlayEvent() called with empty ProgramInfo
2010-10-05 22:37:14.414 ScreenSaverX11Private: DPMS Reactivated 1
2010-10-05 22:37:14.459 TV: Attempting to change from None to WatchingLiveTV
2010-10-05 22:37:14.459 MythContext: Connecting to backend server: 192.168.1.11:6543 (try 1 of 1)
2010-10-05 22:37:14.469 Using protocol version 56
2010-10-05 22:37:14.489 Spawning LiveTV Recorder -- begin
2010-10-05 22:37:17.848 Spawning LiveTV Recorder -- end
2010-10-05 22:37:17.861 ProgramInfo(): Updated pathname '':'' -> '1008_20101005223717.mpg'
2010-10-05 22:37:17.882 We have a playbackURL(myth://192.168.1.11:6543/1008_20101005223717.mpg) & cardtype(DUMMY)
2010-10-05 22:37:17.882 We have a RingBuffer
2010-10-05 22:37:17.933 TV Error: LiveTV not successfully started
2010-10-05 22:37:18.001 ScreenSaverX11Private: DPMS Deactivated 1
2010-10-05 22:37:18.001 ScreenSaverX11Private: DPMS Reactivated 1
2010-10-05 22:37:19.424 MythSystemEventHandler ERROR: SendMythSystemPlayEvent() called with empty ProgramInfo


MythTV Backend:

2010-10-05 22:37:14.427 adding: bilbo as a client (events: 0)
2010-10-05 22:37:14.444 TVRec(1): Changing from None to WatchingLiveTV
2010-10-05 22:37:14.482 TVRec(1): HW Tuner: 1->1
2010-10-05 22:37:14.989 DVBChan(1:/dev/dvb/adapter0/frontend0) Warning: Symbol Rate setting (6952000) is out of range (min/max:6250000/690
0000)
2010-10-05 22:37:17.832 AutoExpire: CalcParams(): Max required Free Space: 3.0 GB w/freq: 14 min
2010-10-05 22:37:17.871 ProgramInfo(): Updated pathname '':'' -> '1008_20101005223717.mpg'
2010-10-05 22:37:17.899 ProgramInfo(): Updated pathname '':'' -> '1008_20101005223717.mpg'
2010-10-05 22:37:17.916 TVRec(1): Changing from WatchingLiveTV to None
2010-10-05 22:37:18.207 ProgramInfo(): Updated pathname '':'' -> '1008_20101005223717.mpg'
2010-10-05 22:37:18.221 Finished recording The Breed "Amerikansk gyser fra 2006. En gruppe unge venner flyver til en tilsyneladende forladt  for at feste og slappe af.": channel 1008
2010-10-05 22:37:18.252 ProgramInfo(): Updated pathname '':'' -> '1008_20101005223717.mpg'
2010-10-05 22:37:18.271 ProgramInfo(): Updated pathname '':'' -> '1008_20101005223717.mpg'
2010-10-05 22:37:18.294 ProgramInfo(): Updated pathname '':'' -> '1008_20101005223717.mpg'
2010-10-05 22:38:18.927 DVBChan(1:/dev/dvb/adapter0/frontend0) Warning: Symbol Rate setting (6952000) is out of range (min/max:6250000/6900000)

I'm concerned about this one:

2010-10-05 22:37:12.145 TV: Attempting to change from WatchingLiveTV to None

2010-10-05 22:37:12.145 RingBuf?(myth://192.168.1.11:6543/1008_20101005223710.mpg) Warning: Peek() requested 2048 bytes, but only returning 376

2010-10-05 22:37:12.145 NVP::OpenFile?(): Error, couldn't read file: myth://192.168.1.11:6543/1008_20101005223710.mpg

Since the myth frontend is printing this any idea why/what is causing this?

It's a normal Ubuntu 10.04 setup it seems.

[robertm]

Is there an actual perceived bug here, or just nervousness over an error message? Neither is, in isolation, a sign of anything fatal.

[robertm]

Upon discussion with the reporter, user alleges live TV can longer be started after he sees this. Requested that user test with trunk.

[robertm]

No results from requested test, no response, closing.