MP1.16 Remote Client Unable to Play: B43534E1 error watching Recorded TV (1 Viewer)

[RonD]

With MP1.16, on remote network connected MP-Clients sometimes see “Unable to Play: B43534E1” type error popup when trying to play a RecordedTV over network connection. Close error, play again and it works 2nd try. The stream ID numbers “B43534E1” etc vary. Does not happen 100% of the time and never saw this with MP1.12.

Attached zip has log files.
Unable2PlayClient has logs from Client Startup
Unable2PlayServer has logs from TV Server Startup a few days ago.

@mm1352000 and @Owlsroost , I 1st saw this with the “MP1.16 released version” of StreamingServer.dll. Also see this with StreamingServer_dll_v1.1.5.zip from the “RecordingFileHandler: Error while deleting” thread. I’m using this for all my testing.

The Client logs are from 2nd set of tests in TV Server Logs, starting at 10:45 local, I saw similar error at 10:32, but closed Client then restarted Client to be sure I had consistent log files.

Started tesing at 10:45 AM local, 2 Shows failed then worked 2nd try
The Ten O'clock News on KTVU Fox 2 - 2017-05-09.ts
CBS Evening News With Scott Pelley - 2017-05-09.ts

From client MediaPortal.log

1st time failed, The Ten O'clock News on KTVU Fox 2
[2017-05-10 10:44:50,813] [Log ] [MPMain ] [INFO ] - PlayRecording:rtsp://MePoTVS:554/B43534E1 - using rtsp mode:True
[2017-05-10 10:44:51,501] [Error ] [MPMain ] [ERROR] - TSReaderPlayer: Failed to open file:rtsp://MePoTVS:554/B43534E1 :0x80004005
2nd time works
[2017-05-10 10:48:08,412] [Log ] [MPMain ] [INFO ] - PlayRecording:rtsp://MePoTVS:554/B43534E1 - using rtsp mode:True

Watch next show, 1st time failed, CBS Evening News With Scott Pelley - 2017-05-09.ts
[2017-05-10 10:48:57,971] [Log ] [MPMain ] [INFO ] - PlayRecording:rtsp://MePoTVS:554/71E234B9 - using rtsp mode:True
[2017-05-10 10:48:58,506] [Error ] [MPMain ] [ERROR] - TSReaderPlayer: Failed to open file:rtsp://MePoTVS:554/71E234B9 :0x80004005
2nd time works
[2017-05-10 10:49:18,210] [Log ] [MPMain ] [INFO ] - PlayRecording:rtsp://MePoTVS:554/71E234B9 - using rtsp mode:True

 

[mm1352000]

Hello again Ron

The error numbers “B43534E1” etc vary.

These are stream IDs.

Looking at the log files now, thanks.

 

[mm1352000]

Hmmmm, it looks like the request to open the recording is failing due to this:
[2017-05-10 10:44:51,499] [16735aa8] [200c] - CRTSPClient::UpdateDuration(): RTSP DESCRIBE timed out, message = liveMedia1

The allowed time is half a second. Second time around the request takes only 7 milliseconds:
[2017-05-10 10:48:08,443] [16735aa8] [26f8] - CRTSPClient::ThreadProc(): thread started, thread ID = 9976
[2017-05-10 10:48:08,450] [16735aa8] [200c] - CRTSPClient::OpenStream(): duration = 3712138

...so something is strange there.

Most tellingly, on the server side, I don't see the streaming server receiving the request at all. The streaming server only seems to receive the second request. So, in my opinion the most likely cause of this problem is one (or more) of:

• the client is not actually sending the request
• security software on the client or server is preventing the request from making it to the server

It should be possible to confirm what's going on by using Wireshark at both ends to capture/dump the received/sent traffic. Would you be able to do that?

 

[Owlsroost]

For the later 71E234B9 stream (K:\MePo1\recordings\KPIX-TV\CBS Evening News With Scott Pelley\CBS Evening News With Scott Pelley - 2017-05-09.ts), for the failed start StreamingServer does seem to respond to an UpdateDuration() request, even though it times out at the client:

(note: it looks like there is about a 9s logging time skew between the client and server)

The failed start:

TsReader.log:
[2017-05-10 10:48:58,006] [1682cad8] [2f64] - CRTSPClient::ThreadProc(): thread started, thread ID = 12132
[2017-05-10 10:48:58,505] [1682cad8] [200c] - CRTSPClient::UpdateDuration(): RTSP DESCRIBE timed out, message = liveMedia1

StreamingServer.log:
[2017-05-10 10:49:08,068] [2cd0] - TsMp2TFSMediaSubsession::duration(), actual: 1927.209961 s, total: 1927.209961 s
(the reported duration matches the duration when it is successfully started next time, so it's for the correct file)

The successful start:

TsReader.log:
[2017-05-10 10:49:18,245] [1682cad8] [ 9e4] - CRTSPClient::ThreadProc(): thread started, thread ID = 2532
[2017-05-10 10:49:18,250] [1682cad8] [200c] - CRTSPClient::OpenStream(): duration = 1927210

StreamingServer.log:
[2017-05-10 10:49:27,762] [2cd0] - tspen K:\MePo1\recordings\KPIX-TV\CBS Evening News With Scott Pelley\CBS Evening News With Scott Pelley - 2017-05-09.ts
[2017-05-10 10:49:27,762] [2cd0] - CTSBuffer::ctor
[2017-05-10 10:49:27,763] [2cd0] - ts:ctor:3fbe6d0

 

[RonD]

updated wording to say "stream ID".

Will look into getting wireshark setup, BUT not obvious how to reproduce this problem on-demand. I thought the key to reproduce was close MP Client, open MP Client, wait a few minutes for TV-Series etc to finish all startup, scanning, etc. Then watch RecordedTV, see 1st fail then work. I tried to reproduce 2 or 3 times later and problem did not show up again. What was weird, the problem 1st happened at 10:32 when I 1st noticed problem, then again at 10:45 with the Client Log files I uploaded.

I've seen this on 2 or 3 different days since upgrade to MP1.16, never saw this problem with MP1.12, all on same TV-Server, MP-Client systems, and network setup.

This Client (L3521) is wired 1 Gbps Ethernet through 2 ethernet switches to TV Server, all 1 Gbps Ethernet. I've also seen this problem on 2nd MP-Client that uses 5 GHz Wifi to ethernet switch to TV Server. This is all after closing MP Client, start MP Client, going to RecordedTV, so MP Client and Server have sent a fair amount of network traffic, strange that "open" fails after all that traffic, video streaming then a 2nd "open" fails.

 

[mm1352000]

For the later 71E234B9 stream (K:\MePo1\recordings\KPIX-TV\CBS Evening News With Scott Pelley\CBS Evening News With Scott Pelley - 2017-05-09.ts), for the failed start StreamingServer does seem to respond to an UpdateDuration() request, even though it times out at the client

Good catch.
Do you think that 500 ms is an unreasonable time limit for calculating the duration?
To me it seems generous. I'd have thought that we'd only be in danger of hitting it if an HDD had to spin up on the server side... or something like that. In this case the HDD - if K: is in fact an HDD - should have already been prepared because it was active less than a minute earlier. So I wonder what could be taking so long.

 

[RonD]

drive K: is HDD, 3000 GB WD drive about 600 GB free space. Another HDD drive L: is used for timeshifting, but TV Sever was idle for everything else when I was doing testing.

TV Server system has EVO850 240GB SSD for Windows C: drive, all MP programs (exe dlls etc) are on SSD, all MP Data and SQL database is also on SSD. SSD is about 50% empty.

EDIT: Checked my Win-10 power settings, Turn Off Hard Disk = 0 minute (NEVER), full speed ahead

 

[mm1352000]

@Owlsroost
I'm discovering that the missing duration entry for the first recording in the streaming server log is not necessarily an indication that the server hasn't received a request.

The streaming server log file shows earlier interactions for both recordings. Those earlier interactions are the reason for the difference in duration logging. For the second recording, the interaction immediately prior to the failed playback attempt was a seek followed by a manual stop, whereas for the first recording it was a playback completion (end of file reached). That difference affects the value of m_iDurationCount which in turn determines whether the duration will be logged before the next playback attempt.

In my opinion it would be nice to have the duration logged before playback starts (ie. as per the second recording).

All this is to say that more investigation is required. Wireshark may give us the best picture of what's going on.

 

[RonD]

I have seen 1 other glitch with RecordedTV rtsp streaming. A few times playing a recording starts ok, but if I timeshift +1 minute get past the pre-store, the video exits back to the RecordedTV screen. I can start playing the recording again and everything is normal. I don't have this any of the logs, but will grab the Client/Server log next time I see the problem.

 

[Owlsroost]

All this is to say that more investigation is required. Wireshark may give us the best picture of what's going on.

I agree.

Do you think that 500 ms is an unreasonable time limit for calculating the duration?

It should be fine (provided the HDD is not sleeping) - it basically just reads a very small amount of data from each end of the file to find PCR timestamps, then subtracts start PCR from end PCR.

I have seen 1 other glitch with RecordedTV rtsp streaming. A few times playing a recording starts ok, but if I timeshift +1 minute get past the pre-store, the video exits back to the RecordedTV screen. I can start playing the recording again and everything is normal. I don't have this any of the logs, but will grab the Client/Server log next time I see the problem.

It shouldn't do this. There is specific handling in the 'seek' code to make sure it doesn't seek right to - or past - the end of the file (and hence trigger 'end of file' stopping of the stream, which is annoying...). I'll need the client and server logs to work out what might be happening in your case.

Is this a finished recording, or one in-progress i.e. a 'live' recording?