Recorded TV freezes then any play select results in 'Cannot play stream <ID>' (1 Viewer)

[Mat Walker]

I've had a good old search for this issue as it has been driving me bananas for a while.

Randomly, every few days playing a Recorded TV item will freeze. Usually when my 4yo is watching!

If it left alone, eventually it will go back to the main menu screen. However, any subsequent attempts to play another recorded TV item results in the error 'Cannot play stream <ID>' (I think that is the text!).

The recorded TV disk has lots of room on it. Looking at the streamer log there maybe isnt enough info to go on; is there something else I should be logging to more of an idea?

The streaming server log shows:-

(Tom and Jerry was being watched when it froze.The Hive/Playschool etc were the ones that failed to play with the error message.)
.
.
.
15-11-2015 14:16:24.267 tspen D:\RecordedTV\The Tom & Jerry Show-2015-08-31-14-32.ts
15-11-2015 14:16:24.267 ts:ctor:56194c0
15-11-2015 14:16:24.268 CTSBuffer:etChannelType() - Buffer size set to TV (32336)
15-11-2015 14:16:24.268 ts:size 1110212944
15-11-2015 14:16:24.271 StreamingServer:: Seek-> 1343.075000/2692.503906
15-11-2015 14:16:24.271 seek to 1343.075000 filepos:210242cc pid:30
15-11-2015 14:16:24.328 stop seek: 1343.041354 at 20b6c085 - target: 1343.075000, diff: 0.033646
15-11-2015 14:16:24.329 ts seekStreamSource 1343.075000 / 2692.503906 ->553796503
15-11-2015 14:16:25.824 generateSDPDescription() duration 5959.429199 : a=range:npt=0-5959.429
15-11-2015 14:16:30.75 generateSDPDescription() duration 5963.689941 : a=range:npt=0-5963.690
.
.
.
15-11-2015 14:19:41.282 generateSDPDescription() duration 6050.357910 : a=range:npt=0-6050.358
15-11-2015 14:19:45.531 generateSDPDescription() duration 6054.619141 : a=range:npt=0-6054.619
15-11-2015 14:19:49.779 generateSDPDescription() duration 6058.841797 : a=range:npt=0-6058.842
15-11-2015 14:19:54.29 generateSDPDescription() duration 6063.064941 : a=range:npt=0-6063.065
15-11-2015 14:19:58.278 generateSDPDescription() duration 6067.326172 : a=range:npt=0-6067.326
15-11-2015 14:28:02.105 MultiFileReader has error 0x80 in Loop 0. Try to clear SMB Cache.
15-11-2015 14:37:53.601 MultiFileReader has error 0x80 in Loop 0. Try to clear SMB Cache.
15-11-2015 14:49:30.362 Stream server: add mpeg-2 ts stream 7AE1F17E filename:\RecordedTV\The Hive-2015-08-08-16-59.ts
15-11-2015 14:49:30.362 Stream server: url for stream is rtsp://192.168.0.20/7AE1F17E
15-11-2015 14:49:40.441 Stream server: add mpeg-2 ts stream B7D9C0F7 filename:\RecordedTV\Play School-2015-10-01-12-30.ts
15-11-2015 14:49:40.442 Stream server: url for stream is rtsp://192.168.0.20/B7D9C0F7
15-11-2015 14:49:48.106 Stream server: add mpeg-2 ts stream D396838E filename:\RecordedTV\Pocoyo-2015-08-12-10-42.ts
15-11-2015 14:49:48.107 Stream server: url for stream is rtsp://192.168.0.20/D396838E

 

[mm1352000]

Hello Mat

is there something else I should be logging to more of an idea?

Yes. For example: the TsReader log file on the client.

Honestly, it sounds like this problem is likely to be something quite technical, and you may well need help to figure it out. To enable other people to help you I'd suggest:

1. Mention the date and time (as precise as you can) that the freeze occurred.
2. Zip and attach all the TV Server log files. The log files are all in the same folder as the streaming server log file.
3. Use the MediaPortal Watchdog tool with option 3 to export the log files from the client into a zip file, then attach the zip file.

 

[Mat Walker]

After writing the above; I restarted the TV Server service (I am a server and remote clients setup). The client said it could see the db but TCP Remote was blocked. Looking at the TVService error log it see:-
[2015-11-15 15:07:54,640] [Log ] [4 ] [ERROR] - Exception ystem.Runtime.Remoting.RemotingException: Remoting configuration failed with the exception 'System.Reflection.TargetInvocationException: Exception has been thrown by the target of an invocation. ---> System.Net.Sockets.SocketException: Only one usage of each socket address (protocol/network address/port) is normally permitted
at System.Net.Sockets.Socket.DoBind(EndPoint endPointSnapshot, SocketAddress socketAddress)
at System.Net.Sockets.Socket.Bind(EndPoint localEP)
at System.Net.Sockets.TcpListener.Start(Int32 backlog)
at System.Runtime.Remoting.Channels.ExclusiveTcpListener.Start(Boolean exclusiveAddressUse)
at System.Runtime.Remoting.Channels.Tcp.TcpServerChannel.StartListening(Object data)
at System.Runtime.Remoting.Channels.Tcp.TcpServerChannel.SetupChannel()
at System.Runtime.Remoting.Channels.Tcp.TcpServerChannel..ctor(IDictionary properties, IServerChannelSinkProvider sinkProvider, IAuthorizeRemotingConnection authorizeCallback)
at System.Runtime.Remoting.Channels.Tcp.TcpServerChannel..ctor(IDictionary properties, IServerChannelSinkProvider sinkProvider)
--- End of inner exception stack trace ---
at System.RuntimeMethodHandle.InvokeMethod(Object target, Object[] arguments, Signature sig, Boolean constructor)
at System.Reflection.RuntimeConstructorInfo.Invoke(BindingFlags invokeAttr, Binder binder, Object[] parameters, CultureInfo culture)
at System.RuntimeType.CreateInstanceImpl(BindingFlags bindingAttr, Binder binder, Object[] args, CultureInfo culture, Object[] activationAttributes, StackCrawlMark& stackMark)
at System.Activator.CreateInstance(Type type, BindingFlags bindingAttr, Binder binder, Object[] args, CultureInfo culture, Object[] activationAttributes)
at System.Runtime.Remoting.RemotingConfigHandler.CreateChannelFromConfigEntry(ChannelEntry entry)
at System.Runtime.Remoting.RemotingConfigHandler.ConfigureChannels(RemotingXmlConfigFileData configData, Boolean ensureSecurity)
at System.Runtime.Remoting.RemotingConfigHandler.ConfigureRemoting(RemotingXmlConfigFileData configData, Boolean ensureSecurity)'.
at System.Runtime.Remoting.RemotingConfigHandler.ConfigureRemoting(RemotingXmlConfigFileData configData, Boolean ensureSecurity)
at System.Runtime.Remoting.RemotingConfigHandler.DoConfiguration(String filename, Boolean ensureSecurity)
at System.Runtime.Remoting.RemotingConfiguration.Configure(String filename, Boolean ensureSecurity)
at TvService.TvServiceThread..ctor()

And TV Service log:-
[2015-11-15 15:07:54,436] [Log ] [4 ] [DEBUG] - Setting up EventWaitHandle with name: Global\MPTVServiceInitializedEvent
[2015-11-15 15:07:54,446] [Log ] [4 ] [INFO ] - Global\MPTVServiceInitializedEvent was not created
[2015-11-15 15:07:54,640] [Log ] [4 ] [ERROR] - Exception ystem.Runtime.Remoting.RemotingException: Remoting configuration failed with the exception 'System.Reflection.TargetInvocationException: Exception has been thrown by the target of an invocation. ---> System.Net.Sockets.SocketException: Only one usage of each socket address (protocol/network address/port) is normally permitted
at System.Net.Sockets.Socket.DoBind(EndPoint endPointSnapshot, SocketAddress socketAddress)
at System.Net.Sockets.Socket.Bind(EndPoint localEP)
at System.Net.Sockets.TcpListener.Start(Int32 backlog)
at System.Runtime.Remoting.Channels.ExclusiveTcpListener.Start(Boolean exclusiveAddressUse)
at System.Runtime.Remoting.Channels.Tcp.TcpServerChannel.StartListening(Object data)
at System.Runtime.Remoting.Channels.Tcp.TcpServerChannel.SetupChannel()
at System.Runtime.Remoting.Channels.Tcp.TcpServerChannel..ctor(IDictionary properties, IServerChannelSinkProvider sinkProvider, IAuthorizeRemotingConnection authorizeCallback)
at System.Runtime.Remoting.Channels.Tcp.TcpServerChannel..ctor(IDictionary properties, IServerChannelSinkProvider sinkProvider)
--- End of inner exception stack trace ---
at System.RuntimeMethodHandle.InvokeMethod(Object target, Object[] arguments, Signature sig, Boolean constructor)
at System.Reflection.RuntimeConstructorInfo.Invoke(BindingFlags invokeAttr, Binder binder, Object[] parameters, CultureInfo culture)
at System.RuntimeType.CreateInstanceImpl(BindingFlags bindingAttr, Binder binder, Object[] args, CultureInfo culture, Object[] activationAttributes, StackCrawlMark& stackMark)
at System.Activator.CreateInstance(Type type, BindingFlags bindingAttr, Binder binder, Object[] args, CultureInfo culture, Object[] activationAttributes)
at System.Runtime.Remoting.RemotingConfigHandler.CreateChannelFromConfigEntry(ChannelEntry entry)
at System.Runtime.Remoting.RemotingConfigHandler.ConfigureChannels(RemotingXmlConfigFileData configData, Boolean ensureSecurity)
at System.Runtime.Remoting.RemotingConfigHandler.ConfigureRemoting(RemotingXmlConfigFileData configData, Boolean ensureSecurity)'.
at System.Runtime.Remoting.RemotingConfigHandler.ConfigureRemoting(RemotingXmlConfigFileData configData, Boolean ensureSecurity)
at System.Runtime.Remoting.RemotingConfigHandler.DoConfiguration(String filename, Boolean ensureSecurity)
at System.Runtime.Remoting.RemotingConfiguration.Configure(String filename, Boolean ensureSecurity)
at TvService.TvServiceThread..ctor()
[2015-11-15 15:07:55,485] [Log ] [4 ] [INFO ] - Set loglevel to: Error

Streaming server log:-
15-11-2015 15:07:56.816 -------------- v1.0.5 ---------------
15-11-2015 15:07:56.816 Stream serveretup stream server for ip: 192.168.0.20


This may well be just due to the streaming service leaving Net Sockets in a bad way after a thread crash; but thought I'd chuck it up anyway (Only bolded stuff for visibility...)....[DOUBLEPOST=1447565962][/DOUBLEPOST]

...it sounds like this problem is likely to be something quite technical, and you may well need help to figure it out. To enable other people to help you I'd suggest...

Yeah - me thinks it could be techy as well. [If it helps, I'm a tech (but not 100% on TMP ).]

I've attched the TSReader log from the offending client. Issue occured about 14:28 on 15-11-2015. Not many clues in that it looks like - only the issue with the not able to reconnect after the server service was restarted.

I'll get the watchdog going with option 3 (will it affect users -ie slow down stuff or fill drives quickly so I need to be careful to watch space usage etc?)

Thanks mm

 

[mm1352000]

I'll get the watchdog going with option 3 (will it affect users -ie slow down stuff or fill drives quickly so I need to be careful to watch space usage etc?)

No, it just collects the log files into a zip. Shouldn't take more than 2 minutes, and uses very little HDD space.

 

[mm1352000]

From the TsReader log and your description, it looks like the TV Server and/or the network connection has fallen over for some reason. The log reports that TsReader thought it had reached the end of the recording. If that was not actually the case then it's an indication that TsReader had lost contact with the streaming server...

 

[Mat Walker]

From the TsReader log and your description, it looks like the TV Server and/or the network connection has fallen over for some reason. The log reports that TsReader thought it had reached the end of the recording. If that was not actually the case then it's an indication that TsReader had lost contact with the streaming server...

Yeah, fair play. I've set it up for more logging so hopefully there will be more info when next it happens.

I'm going to dig out that file that was being played and replay it to see if there is a repro on it. I'm wondering (and pure speculation) if the recording may have been corrupted - perhaps a signal glitch making the codec doing the recording chuck a brain-fade - that then made whatever does the rtsp lockup which then caused the MP client to not see it had finished. As the rtsp thing had locked up that could result in the 'Cannot playback stream <xyz>' on subsequent plays etc..... Do you know if the thing doing the rtsp sends a signal to the client when it finishes playing, or is there another way the end is _seen_ by the client? Something i didnt mention (sorry) was that the TVServer service was sat on 13% cpu as well (not varying; sat at a constant 13%) which kinda struck me as odd; if it was stuck in a loop, why not 100% cpu (and possibly an eventual stack or memory out exception)? Does that "15-11-2015 14:28:02.105 MultiFileReader has error 0x80 in Loop 0. Try to clear SMB Cache." mean anything (If watching a recording, it is rtsp and the SMB is not being used is it?)?

Mat

 

[mm1352000]

I'm wondering (and pure speculation) if the recording may have been corrupted - perhaps a signal glitch making the codec doing the recording chuck a brain-fade...

There are no codecs involved in the recording process, so I'm not sure whether this explanation works.

Do you know if the thing doing the rtsp sends a signal to the client when it finishes playing, or is there another way the end is _seen_ by the client?

"The thing doing RTSP" is called the streaming server. It definitely does not send a signal to the client. Rather, the client sends a duration update request every 5 seconds or so:
15-11-2015 14:19:49.779 generateSDPDescription() duration 6058.841797 : a=range:npt=0-6058.842
15-11-2015 14:19:54.29 generateSDPDescription() duration 6063.064941 : a=range:npt=0-6063.065
15-11-2015 14:19:58.278 generateSDPDescription() duration 6067.326172 : a=range:npt=0-6067.326

Using that information, the client is able to know how much of the recording is left to play etc.

Something i didnt mention (sorry) was that the TVServer service was sat on 13% cpu as well (not varying; sat at a constant 13%) which kinda struck me as odd; if it was stuck in a loop, why not 100% cpu (and possibly an eventual stack or memory out exception)?

A loop is a single thread, so it is more likely to only max out one core. If your CPU only has one core then that would translate to 100% CPU; on the other hand if your CPU has 8 cores that would translate to 12.5% CPU (100 / 8). In other words, TV Server may well have been stuck in a loop. Without access to all the log files that I asked for (especially the TVService.log for the relevant period) I'm not able to say more than that.

Does that "15-11-2015 14:28:02.105 MultiFileReader has error 0x80 in Loop 0. Try to clear SMB Cache." mean anything (If watching a recording, it is rtsp and the SMB is not being used is it?)?

Sure it's suspicious, but It's hard to know if it is really relevant without access to the other log files (particularly TsWriter).
Note SMB may be used if you were recording to a share. That doesn't appear to apply for you, so the message may be a misinterpretation of the cause for a particular set of symptoms. Again, I can't say more than that without access to the other log files.