[puithove]

I've only seen this when watching Live TV, never with recorded TV, never with ripped media. It'll be playing along nicely, then suddenly the audio stops, and video drops to playing what looks like one frame every few seconds. I can bring back playback by either hitting X (stop) and restart same channel, or switch to another channel and back (effectively starting a new stream either way).

XBMC built on Feb 15th - 13.0-ALPHA12 Git:20140215-97a3fad
PVR Addons built on Feb 15th
Backend: MythTV 0.27
Tuner: HDHomeRun Prime w/cablecard
XBMC running on Archlinux x64 w/ Kernel: 3.12.9-2-ARCH #1 SMP PREEMPT Fri Jan 31 10:22:54 CET 2014 x86_64 GNU/Linux

Debug Log: http://pastebin.com/xgZtf6P4

This log shows a fresh start of XBMC, starting a live TV stream. The issue occurs at 7:25:39 with what appears to be audio errors:

Code:

07:25:39 T:140139141453568    INFO: CDVDPlayerVideo - Stillframe left, switching to normal playback
07:25:39 T:140139141453568 WARNING: CRenderManager::WaitForBuffer - timeout waiting for buffer
07:25:39 T:140139942635264 WARNING: Previous line repeats 7 times.
07:25:39 T:140139942635264   DEBUG: CDVDPlayer::HandleMessages - player started 2
07:25:39 T:140139141453568 WARNING: CRenderManager::WaitForBuffer - timeout waiting for buffer
07:25:41 T:140139133060864 WARNING: Previous line repeats 9 times.
07:25:41 T:140139133060864   ERROR: CDVDAudio::AddPacketsRenderer - timeout adding data to renderer
07:25:41 T:140139133060864   DEBUG: CDVDPlayerAudio:: Discontinuity1 - was:25700963161.597290, should be:25697232468.539703, error:-3730693.057587
07:25:42 T:140139133060864   ERROR: CDVDAudio::AddPacketsRenderer - timeout adding data to renderer
07:25:42 T:140139133060864   ERROR: AddPackets - failed to add leftover bytes to render
07:25:42 T:140139133060864   DEBUG: CDVDPlayerAudio:: Discontinuity1 - was:25698637826.496704, should be:25697488400.000000, error:-1149426.496704

This was on a 1080i channel with AC3 5.1 audio. I know those are what we have been watching. Not sure if it's happened on a 720p channel so I'm running that right now.

I do notice that right before the issue started, the log appears to show an EPG update - I know there's an option to disable EPG updates during playback, so I'll also try to do a run with that option enabled.

[puithove]

Well, just like that, I was proven wrong. Despite having played hour upon hour of recorded content successfully, just had it happen on a recorded show. This is on a different client machine from the log above - with different hardware running the same OS and XBMC versions. Coming from the same MythTV backend. It is also a 1080i. In this, I do NOT see the EPG update at the same time of the failure. I'm still running the 720p test on the previous machine from above - and on that one I cranked up the EPG refresh interval to every 15 minutes. Has been playing successfully for a few hours now.

Here's the new log:
http://pastebin.com/9GigAQH1

This one happened immediately after a commskip section. However, the one above was liveTV without any commskip.

Here's the interesting parts where the issue starts:

Code:

13:04:21 T:140152289822464   DEBUG: CDVDPlayerAudio:: Dropping packet of 32 ms
13:07:23 T:140151445444352   DEBUG: Previous line repeats 15 times.
13:07:23 T:140151445444352   DEBUG: CheckAutoSceneSkip - Clock in commercial break [01:04:31.301 - 01:05:31.461]: 01:04:31.314. Automatically skipping to end of commercial break (only done once per break)
13:07:23 T:140151445444352   DEBUG: demuxer seek to: 3931462
13:07:23 T:140151445444352    INFO: AddOnLog: MythTV cmyth PVR Client: ReadRecordedStream: Read 0 Bytes!
13:07:23 T:140151445444352    INFO: Previous line repeats 1 times.
13:07:23 T:140151445444352   DEBUG: SeekTime - seek ended up on time 3930946
13:07:23 T:140151445444352   DEBUG: demuxer seek to: 3931462, success
13:07:31 T:140151453837056   DEBUG: CDVDPlayerVideo - CDVDMsg::GENERAL_SYNCHRONIZE
13:07:31 T:140151453837056   DEBUG: CDVDPlayerVideo - CDVDMsg::GENERAL_RESYNC(3931469255.222222, 1)
13:07:31 T:140152289822464   DEBUG: CDVDPlayerAudio - CDVDMsg::GENERAL_SYNCHRONIZE
13:07:31 T:140152289822464 WARNING: CDVDMessageQueue(audio)::Get - asked for new data packet, with nothing available
13:07:31 T:140151453837056 WARNING: CDVDMessageQueue(video)::Get - asked for new data packet, with nothing available
13:07:31 T:140151445444352   DEBUG: CDVDPlayer::SetCaching - caching state 1
13:07:31 T:140151453837056    INFO: CDVDPlayerVideo - Stillframe left, switching to normal playback
13:07:31 T:140151445444352   DEBUG: CheckPlayerInit - dropping packet type:1 dts:3931090355.222223 to get to start point at 3931462000.000000
13:07:31 T:140151445444352   DEBUG: CDVDPlayer::SetCaching - caching state 4
13:07:31 T:140151445444352   DEBUG: CheckPlayerInit - dropping packet type:1 dts:3931122355.222222 to get to start point at 3931462000.000000
13:07:31 T:140151445444352   DEBUG: CheckPlayerInit - dropping packet type:1 dts:3931154355.222221 to get to start point at 3931462000.000000
13:07:31 T:140151445444352   DEBUG: CheckPlayerInit - dropping packet type:1 dts:3931186355.222220 to get to start point at 3931462000.000000
13:07:31 T:140151445444352   DEBUG: CheckPlayerInit - dropping packet type:1 dts:3931218355.222219 to get to start point at 3931462000.000000
13:07:31 T:140152289822464   DEBUG: CDVDPlayerAudio:: Discontinuity1 - was:3931997553.599556, should be:3930994607.079581, error:-1002946.519975
13:07:31 T:140152289822464 WARNING: CDVDMessageQueue(audio)::Get - asked for new data packet, with nothing available
13:07:31 T:140151445444352   DEBUG: CDVDPlayer::HandleMessages - player started 1
13:07:31 T:140151445444352   DEBUG: CheckPlayerInit - dropping packet type:1 dts:3931250355.222222 to get to start point at 3931462000.000000
13:07:31 T:140151445444352   DEBUG: CheckPlayerInit - dropping packet type:1 dts:3931282355.222222 to get to start point at 3931462000.000000
13:07:31 T:140151445444352   DEBUG: CheckPlayerInit - dropping packet type:1 dts:3931314355.222221 to get to start point at 3931462000.000000
13:07:31 T:140151445444352   DEBUG: CheckPlayerInit - dropping packet type:1 dts:3931346355.222220 to get to start point at 3931462000.000000
13:07:31 T:140151445444352   DEBUG: CheckPlayerInit - dropping packet type:1 dts:3931378355.222219 to get to start point at 3931462000.000000
13:07:31 T:140152289822464   DEBUG: CDVDPlayerAudio:: Discontinuity1 - was:3931042294.861581, should be:3931159690.550005, error:117395.688425
13:07:31 T:140152289822464 WARNING: CDVDMessageQueue(audio)::Get - asked for new data packet, with nothing available
13:07:31 T:140151445444352   DEBUG: CheckPlayerInit - dropping packet type:1 dts:3931410355.222222 to get to start point at 3931462000.000000
13:07:31 T:140151445444352   DEBUG: CheckPlayerInit - dropping packet type:1 dts:3931442355.222221 to get to start point at 3931462000.000000
13:07:31 T:140152289822464   DEBUG: CDVDPlayerAudio:: Discontinuity1 - was:3931181022.888005, should be:3931287607.454713, error:106584.566708
13:07:31 T:140152289822464   DEBUG: CDVDPlayerAudio - CDVDMsg::GENERAL_RESYNC(3931474355.222221, 0)
13:07:31 T:140151453837056   DEBUG: CPullupCorrection: pattern lost on diff -1935838094.277777
13:07:31 T:140151445444352   DEBUG: CDVDPlayer::HandleMessages - player started 2
13:07:33 T:140152289822464   ERROR: CDVDAudio::AddPacketsRenderer - timeout adding data to renderer
13:07:33 T:140152289822464   DEBUG: CDVDPlayerAudio:: Discontinuity1 - was:3932499429.221713, should be:3931474355.222221, error:-1025073.999492
13:07:33 T:140151445444352   DEBUG: CDVDPlayer::SetCaching - caching state 0
13:07:34 T:140152289822464   ERROR: CDVDAudio::AddPacketsRenderer - timeout adding data to renderer
13:07:34 T:140152289822464   ERROR: AddPackets - failed to add leftover bytes to render
13:07:34 T:140152289822464   DEBUG: CDVDPlayerAudio:: Discontinuity1 - was:3932681829.243221, should be:3931474355.222221, error:-1207474.021000
13:07:35 T:140152289822464   ERROR: CDVDAudio::AddPacketsRenderer - timeout adding data to renderer
13:07:35 T:140152289822464   DEBUG: CDVDPlayerAudio:: Discontinuity1 - was:3932688050.087221, should be:3931474355.222221, error:-1213694.865000

[puithove]

Ok, the theory I'm currently testing is that this may have been caused by changing setting: System / Audio Output / Output Configuration from the default of "Optimized" to "Best Match". Best Match says that it'll change the output properties midstream according to whatever is in the source. My theory being that in live or recorded TV there may either be changes or glitches in the source stream, and when it tries to adjust to that midstream, something goes wrong. I've switched back to "Optimized" so that it's just set once at the beginning of the stream. I'll see how that goes.

[puithove]

Nope, wasn't the audio settings either. I'm actually now looking into the possibility of a backend Myth issue - possibly dropping connection with the HDHomerun.

[nickr]

Could possibly be a reception problem too.

Does it happen with mythfrontend?
Does it always happen at the same spot on a recording?

---

Also is it possibly at a transition from 720 to 1080 or back again? Or from one audio format to another?

A common thing for broadcasters to do is change video framesize or audio when transitioning in and out of commercial breaks.

[puithove]

Could possibly be a reception problem too.

Does it happen with mythfrontend?
Does it always happen at the same spot on a recording?

---

Also is it possibly at a transition from 720 to 1080 or back again? Or from one audio format to another?

A common thing for broadcasters to do is change video framesize or audio when transitioning in and out of commercial breaks.

Yes, I did try mythfrontend and saw it once there as well - that's what had me looking towards a backend issue. I do think I need to spend some more time with mythfrontend though now that I found and fixed a NIC issue on the backend.

No, does not always happen in the same spot. I'd wondered this as well. However I had it happen again on a recording, stopped, restarted, rewound and played back through the same section with no issues.

It definitely does seem to occur more often on particular channels. So... the search continues.

[puithove]

Was not able to reproduce the issue in Mythfrontend. I think the one occurrence I saw in mythfrontend must have been a fluke, the result of me playing with something at the same time, or maybe it was something with the NIC flakiness I mentioned. For whatever reason, I haven't been able to get it to happen again in mythfrontend.

Yet it's happening quite consistently in XBMC 13. Here's a couple more debug logs, with verbose logging turned on for cmyth too. These are both fresh restarts of XBMC, directly into live tv playback up to the time that the issue was occurring.
http://pastebin.com/X0RjUW5u
http://pastebin.com/0iTW7Wvh

FWIW, I also saw it occur on a OSX build of the same vintage running on OSX 10.9.1.

So, after spending a bunch of time messing around with all kinds of stuff, I did what I probably should have done in the first place - rolled back to the current release version of 12.3 Frodo. It's been playing live TV just fine on the same two boxes non-stop for the past 4 hours. Same setup including channel I was using to reliably reproduce the issue.

It does seem to me that there's something amiss somewhere in the new stuff.

[puithove]

Update on this - I've continued to try new builds every few days. It appears as though this was fixed in something between af78970 and 189d55d. Running with 189d55d now and things seem to be good.

Previously I had done some more playing around - had two different boxes running on the same channel (two different tuners / streams of course because that's the way that Myth works) - when the hang happened, both hung at the exact same spot. I didn't do any deep comarison, but visually it looked like it was most likely the same frame. Sounds like something in the stream triggers it.