[awp0]

Question for the experts: I've noticed a weird state that my XBMC/WMC/HDHomerun environment gets into sometimes. What happens is that I'll be watching a channel and then I'll hit "stop" (which returns me to the Timeline EPG view) and then if I try to restart the same channel that I was just watching, it errors out with a "stream timeout, unknown problem" error.

In order to watch this channel again, I have to tune into another channel and then stop and tune back to the original channel, at which point it plays fine. The weird thing is that it only seems to happen on a certain channel, and when I restart ServerWMC then it seems to resolve the issue entirely and I can start/stop the "bad" channel without a problem. So something is causing the server to get into this weird state and I'm not sure what is.

Following is my ServerWMC log for the day. I'm sorry it's a little long, but at the end of it you can see I was struggling with the issue as it throws the following errors:
2013/12/01 19:59:54.745 StreamProc> process start error: Stream file 'ts' exists but is empty, timeout: 10,000 ms reached. calling Close()

http://pastebin.com/PmcR1trC

Any ideas? Has anyone else encountered this? So far the add-in has been working great. I'm just trying to make it bulletproof for my wife. Thanks!

[krustyreturns]

When you say it only happens on a certain channel, do you really mean it only happens on the channel WBZDT-804. Or other channels too?

When you switch channels to another channel and switch back, this channel plays again. But if you stop and start it again will it play? Or is that what requires restarting the server?

[scarecrow420]

Analyzing your log file I can see something a bit funny.

You first watch channel 804 around 16:10 - 17:07 and then stop it. It sits idle until around 19:40 when you go to watch 804 again and it fails. At this point, the live TV WTV recording contains a strange Audio stream with a weird langauge character (where the normal 3 letter language characters like eng or spa are) as well as a second "unknown" video stream. You attempt to open 804 twice, and both times these streams are present and both times the operation fails with a 10 second timeout waiting for the remuxed TS file to contain data.

2013/12/01 19:40:15.184 Remux::FindDescriptors> wtv scanned (2.65 sec), Streams found:
2013/12/01 19:40:15.184 > Other: ID:39 MS TV Caption
2013/12/01 19:40:15.184 > Video: ID:40 Unknown
2013/12/01 19:40:15.184 > Audio: ID:41 (ª‚4F) AC3
2013/12/01 19:40:15.184 > Audio: ID:42 (eng) AC3
2013/12/01 19:40:15.184 > Audio: ID:43 (spa) AC3 2.0 48000 Hz 192 kb/s
2013/12/01 19:40:15.185 > Video: ID:44 MPEG-2 MP-HL 1920x1080i fps: 30000/1001 AR: 16:9
2013/12/01 19:40:15.185 Remux::FindDescriptors> Output streams:
2013/12/01 19:40:15.185 > Audio: ID:41 (ª‚4F) AC3
2013/12/01 19:40:15.185 > Audio: ID:42 (eng) AC3
2013/12/01 19:40:15.185 > Audio: ID:43 (spa) AC3 2.0 48000 Hz 192 kb/s
2013/12/01 19:40:15.185 > Video: ID:44 MPEG-2 MP-HL 1920x1080i fps: 30000/1001 AR: 16:9
2013/12/01 19:40:25.203 StreamProc> process start error: Stream file 'ts' exists but is empty, timeout: 10,000 ms reached. calling Close()

Then after you flip to channel 805, then back to 804, and only 30 seconds after the failure (and presumably still the same program/show being on?), the WTV file now only has more normal looking streams - only the english and spanish audio and a single video stream.

2013/12/01 19:40:48.899 Remux::FindDescriptors> wtv scanned (2.89 sec), Streams found:
2013/12/01 19:40:48.899 > Audio: ID:51 (eng) AC3 5.1 48000 Hz 384 kb/s
2013/12/01 19:40:48.899 > Audio: ID:52 (spa) AC3 2.0 48000 Hz 192 kb/s
2013/12/01 19:40:48.899 > Video: ID:53 MPEG-2 MP-HL 1920x1080i fps: 30000/1001 AR: 16:9
2013/12/01 19:40:48.899 > Other: ID:54 MS TV Caption
2013/12/01 19:40:48.899 Remux::FindDescriptors> Output streams:
2013/12/01 19:40:48.899 > Audio: ID:51 (eng) AC3 5.1 48000 Hz 384 kb/s
2013/12/01 19:40:48.899 > Audio: ID:52 (spa) AC3 2.0 48000 Hz 192 kb/s
2013/12/01 19:40:48.899 > Video: ID:53 MPEG-2 MP-HL 1920x1080i fps: 30000/1001 AR: 16:9
2013/12/01 19:40:50.073 StreamProc> 'ts' file created, size: 720,896 in 4.06 sec
2013/12/01 19:40:50.073 StreamProc> total time: 4.08 sec

From a critical analysis point of view, the thing that is different on both failures compared to the eventual success, is these weird streams. So without being an expert, I wonder whether this could have something to do with the failure.

If you turn off the "delete temporary files" option on the Debug tab, you should be able to grab the WTV file the next time this happens and upload it for us to have a look at (along with another server log).


Also the "output streams" shows that we are not trying to remux the unknown video stream to the TS file, but we are trying to do the weird audio stream. The server does have a language option to only do a nominated language, so if you set that to "eng" it would ignore the spanish and presumably the "weird" audio stream... it would be interesting to know if this succeeds (proving that it's the strange audio stream that is causing grief). To confirm this you would set the server option to "eng" language, do a bunch of channel viewing etc, then monitor/review the logs to see if you ever encounter a WTV parse that shows the weird streams present, but the output now only remuxing the "eng" stream meant that things worked now...

[awp0]

Hi guys, thanks so much for taking a look.

Krusty: Actually, I don't know for sure. When it was happening tonight, it seemed to be only channel 804. I tried a few other channels and they seemed to work as expected (I could stop playback and then restart on the same channel without a problem). After restarting ServerWMC I can't seem to reproduce this on any channels. But I think it's happened once or twice before (not sure if same 804 channel), so I'll keep an eye out for it.

Scarecrow: Excellent, thanks for this analysis. It seems like you're on to something with the audio stream. And it's correct that I tested this a few times during the same timeslot and show so I would have expected the available streams to be the same, at least during a few of my attempts.

When this happens again I will try to capture the WTV file. And it's great to know that I can specify english and hopefully avoid it. Thanks guys!!

[krustyreturns]

Also the "output streams" shows that we are not trying to remux the unknown video stream to the TS file, but we are trying to do the weird audio stream. The server does have a language option to only do a nominated language, so if you set that to "eng" it would ignore the spanish and presumably the "weird" audio stream... it would be interesting to know if this succeeds (proving that it's the strange audio stream that is causing grief). To confirm this you would set the server option to "eng" language, do a bunch of channel viewing etc, then monitor/review the logs to see if you ever encounter a WTV parse that shows the weird streams present, but the output now only remuxing the "eng" stream meant that things worked now...

Good eye scarecrow. Wtf is up with those audio stream? Why would he only get these when going back to the channel? Possibly there is something in the remux that is not being reset completely.

[scarecrow420]

It seems unlikely the actual broadcast would have these weird streams in it, and then not again, within the same time slot. So yeah I guess something with the remuxer doing the same channel in a row (possibly after some idle time in between). Also given the audio type of "strange little postscript a character" rather than a proper language identifier would further indicate some kind of corrupt or uninitialised variable etc . Id love to see a WTV file example though to really see whether the WTV istelf had the streams or if it was purely an artefact in the remuxer

[awp0]

I'll run a couple of days without configuring the "english only" setting that scarecrow mentioned. If I can reproduce it then I should be able to capture the WTV and I'll post it for you guys. Thanks again!