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

[RonD]

The "unable to play" problems in this thread are all for finished recordings. This has indirect connection to the "RecordingFileHandler: Delete" problem, since I'm using networked MP-Client to watch recordings with episode management so StreamingServer has opened the files since this (I thought) is tied to the delete problem. In general when I play the recordings for testing, I select the "resume from NN:NN" timepoint from the last time I watched the Recording.

 

[RonD]

Did get a VideoExit error case, see zip for logs. On the server logs, last night win10 updates did reboot, logs are for today.

At 09:47:15 local, played last night recorded "The Ten O'clock News on KTVU Fox 2", resumed from about 58 minute point, video played for 1-2 seconds, then exited

At 09:50:08 local, played the same recording, there was no "resume option", played from beginning no problems

 

[RonD]

went back to Client, started playing last night's news, 3 more "unable to play" type bugs, see logs. Seems like I should be able to find a "reproduce bug" usage pattern. If needed I'll look into getting wireshark setup on Client/Server

info for 3 failing cases from MediaPortal.log (Client). In all cases I did resume from previous stop point.

Unable to play from resume CBS Evening News With Scott Pelley - 2017-05-10.ts
[2017-05-11 10:14:52,278] [Log ] [MPMain ] [INFO ] - PlayRecording:rtsp://MePoTVS:554/70B933F2 - using rtsp mode:True
[2017-05-11 10:14:52,807] [Error ] [MPMain ] [ERROR] - TSReaderPlayer: Failed to open file:rtsp://MePoTVS:554/70B933F2 :0x80004005

Unable to play from resume KPIX 5 News at 5pm - 2017-05-10.ts
[2017-05-11 10:16:51,641] [Log ] [MPMain ] [INFO ] - PlayRecording:rtsp://MePoTVS:554/C35F685C - using rtsp mode:True
[2017-05-11 10:16:52,167] [Error ] [MPMain ] [ERROR] - TSReaderPlayer: Failed to open file:rtsp://MePoTVS:554/C35F685C :0x80004005

Unable to play from resume ABC7 News 4_00PM - 2017-05-10.ts
[2017-05-11 10:17:42,564] [Log ] [MPMain ] [INFO ] - PlayRecording:rtsp://MePoTVS:554/12E8DF41 - using rtsp mode:True
[2017-05-11 10:17:43,089] [Error ] [MPMain ] [ERROR] - TSReaderPlayer: Failed to open file:rtsp://MePoTVS:554/12E8DF41 :0x80004005

retry resume ABC7 News 4_00PM - 2017-05-10.ts 2nd time, and it works from same resume point
[2017-05-11 10:19:19,244] [Log ] [MPMain ] [INFO ] - PlayRecording:rtsp://MePoTVS:554/12E8DF41 - using rtsp mode:True

 

[Owlsroost]

At 09:47:15 local, played last night recorded "The Ten O'clock News on KTVU Fox 2", resumed from about 58 minute point, video played for 1-2 seconds, then exited

It seems to be a related problem to the 'unable to play' one - an RTSP PLAY request from client to server is timing out after 0.5 sec:

[2017-05-11 09:47:14,327] [ bad9638] [ efc] - CRTSPClient:lay(): start = 3115.000000, duration = 3716.076904, m_duration = 3715.077881
[2017-05-11 09:47:14,327] [ bad9638] [ efc] - CRTSPClient::InternalPlay() - start = 3115.000000
[2017-05-11 09:47:14,828] [ bad9638] [ efc] - CRTSPClient::InternalPlay(): RTSP PLAY timed out
[2017-05-11 09:47:14,828] [ bad9638] [ efc] - CRTSPClient:hutdown()
[2017-05-11 09:47:14,828] [ bad9638] [ efc] - CRTSPClient:hutdown(): send RTSP TEARDOWN
[2017-05-11 09:47:15,154] [ bad9638] [ efc] - CRTSPClient:topBufferThread()
[2017-05-11 09:47:15,154] [ bad9638] [1ec4] - CRTSPClient::ThreadProc(): thread stopping, thread ID = 7876
[2017-05-11 09:47:15,154] [ bad9638] [ efc] - CRTSPClient:topBufferThread(): done

...but without the server logs for the same period we only have half the story. Since it's already played some of the file (before doing the 'seek' to get to the resume point, which is when it fails), it can't be due to disks not running. The StreamingServer.log should show the seek commands happening (when you can catch another instance of the failure).

 

[happyf1sh]

Interested in this thread. In my case, I had a similar issue and I had assumed it was wakeup time of the hard drive. I swapped to SDD for both recording storage and time shift and problem hasn't returned (yet).

Sent from my GT-I9505 using Tapatalk

 

[RonD]

...but without the server logs for the same period we only have half the story.

the server logs are in zip files, see VideoExitServer folder, for the start then stop after 1 second, streaming server.Log starts with

EDIT ADD comments from log
[2017-05-11 07:32:18,113] [1128] - -------------- v1.1.5 ---------------
[2017-05-11 07:32:18,113] [1128] - Stream serveretup stream server for ip: 192.168.0.102
[2017-05-11 09:47:15,400] [2454] - Stream server: add mpeg-2 ts stream B34E3402 filename:K:\MePo1\recordings\KTVU-HD\The Ten O'clock News on KTVU Fox 2\The Ten O'clock News on KTVU Fox 2 - 2017-05-10.ts

farther in the log
[2017-05-11 09:47:18,323] [a94] - StreamingServer:: Seek-> 3115.000000/3715.077881
3115/60 = 51.9 minutes, about what I remember for resume time

a little latter, 2nd play video starts
[2017-05-11 09:50:08,618] [a94] - TsMp2TFSMediaSubsession::duration(), actual: 3715.077881 s, total: 3715.077881 s
[2017-05-11 09:50:08,628] [a94] - tspen K:\MePo1\recordings\KTVU-HD\The Ten O'clock News on KTVU Fox 2\The Ten O'clock News on KTVU Fox 2 - 2017-05-10.ts

 

[Owlsroost]

the server logs are in zip files, see VideoExitServer folder

Oops...sorry

OK - the related entries in the StreamingServer log are:

[2017-05-11 09:47:18,323] [a94] - StreamingServer:: Seek-> 3115.000000/3715.077881
[2017-05-11 09:47:18,323] [a94] - FileSeek: seek to 3115.000000 filepos:e1f7921c pid:30
[2017-05-11 09:47:19,139] [a94] - FileSeek: stop seek: 3115.233225 at e243bf70 - target: 3115.000000, diff: 0.233225, iterations: 10
[2017-05-11 09:47:19,141] [a94] - CTSBuffer - m_maxReqSize: 1316)
[2017-05-11 09:47:19,147] [a94] - CTSBuffer - m_minReqSize: 1316)

Note that the' FileSeek: stop seek' (seek completed) line is about 0.8s after the 'FileSeek: seek' (seek start) line - this feels like a long time for a seek operation on a local hard disk...

What are the system specs for the TV server?
Are all the recording folders etc. excluded from security software scanning?

We could increase the RTSP command timeouts at the Client (in TsReader), but it would be nice to try and work out why the server is being so slow sometimes.

 

[RonD]

0.8 sec for disk seek on an idle drive seems very long. TV server was idle (in other room) with some chrome web browsers open

using W10 Defender, have exclusions set for MP folders see pictures. For HDD W10 power settings are set for Turn Off Hard Disk = 0 minutes see pictures. So HDD TurnOff = DISABLED. If I push the time setting below "0" I see "Never" (ServerInfo2). If I press Apply, OK, then bring back Advanced Settings, the "Never" flips back to 0, so it looks like Msft uses numbers. Prevent Hard Drive from going to Sleep in Windows 10/8/7

TV Server is core i5, 3.1 GHz, 4 core, 12 GB DRAM, Windows 10 Home
C-drive is EVO 850 SSD 240 GB, used for windows, MP programs, MP data, SQL database
K-drive is WD HDD 3000 GB about 600 GB free space dedicated for recordings,
L-drive is WD HDD 2000 GB timeshift and other misc stuff

 

[mm1352000]

@RonD

0.8 sec for disk seek on an idle drive seems very long.

Agreed there.
Have you checked the system's DPC latency?
If not, please do using LatencyMon.

 

[RonD]

picture shows LatencyMon for 5 minutes. Text file as copy/paste of stats for 9 minutes. TV Server running with 4 chrome windows about 20 tabs, email client open, usual pile of stuff I have running on TV server when using MP-Clients in other room