Stopping a Live Stream Caused Recording to End Prematurely

[bungee91 98]

Overlooking the log, this is what it looks like happened.

All I know is the recording ended early.

 

What I noticed: A recording, NFL Football 2018_09_23_15_25_00 - Chicago Bears at Arizona Cardinals.ts was set to record for 4 hours,  (guide of 3hr, I added 60min to it).

 

I started watching this later as an in-progress recording, and about 2 hours in the recording stopped.

I looked and it was no longer active, and then I scheduled it again to continue recording.

 

This channel was being streamed by two external users concurrently during my watching of it.

I have no idea if they just started watching the channel, or the in-progress recording (I'd assume the channel directly).

 

I see in the log that one of the users stopped watching the channel, and at that point the log shows the following activity: 

2018-09-23 17:09:42.231 Info SessionManager: Playback stopped reported by app Roku SG 3.0.97 playing WFLD-DT. Stopped at 113000 ms
2018-09-23 17:09:42.232 Info MediaSourceManager: Live stream native_92d66927260f45eebfc47f319a9583b3_8e9f5d9fd49a89574e730b1c4b44f805 consumer count is now 0
2018-09-23 17:09:42.232 Info MediaSourceManager: Closing live stream a17c75760a04e99b68cf766e11316e1c_09efa0d56b934a82adec00a87b837fb0_native_92d66927260f45eebfc47f319a9583b3_8e9f5d9fd49a89574e730b1c4b44f805
2018-09-23 17:09:42.232 Info App: Closing SharedHttpStream
2018-09-23 17:09:42.233 Info App: Recording stopped: /mnt/user/Recorded_TV/NFL Football/NFL Football 2018_09_23_15_25_00 - Chicago Bears at Arizona Cardinals.ts
2018-09-23 17:09:42.235 Info App: Deleting temp files /mnt/disks/WD2TB/transcoding-temp/b9685a1fb0604be985bd5c932b619860.ts

I have serious doubts that the end user stopped the recording prematurely (chose cancel on it), so I think that the activity of stopping playback for some reason stopped the recording from continuing.

 

Full log attached, I've also since updated from 3.5.2 to 3.5.3 (even though that shouldn't have fixed this issue).

 

 

Edit: removed attachment

Edited September 25, 2018 by bungee91

[Luke 37128]

Its' difficult to say. The roku app reported that it stopped, which suggests that it was stopped. Can you make this happen again?

[bungee91 98]

This situation could happen weekly, so I'll report if it does happen again.

 

I don't understand though @@Luke , the log states that:

Playback stopped reported by app Roku SG 3.0.97 playing WFLD-DT. Stopped at 113000 ms

with details for closing the live stream.

 

Why would this happen (specifically Recording stopped): 

Recording stopped: /mnt/user/Recorded_TV/NFL Football/NFL Football 2018_09_23_15_25_00 - Chicago Bears at Arizona Cardinals.ts

if just the live stream was closed? Why would that impact the in-progress recording?

 

I've removed the log, let me know if you need it again.

[Luke 37128]

Correct it shouldn't affect the recording. I have tested and don't see any problem with this on the beta so if there is an issue then it probably has been resolved for the next release. Thanks.

[bungee91 98]

@@Luke this continues to be the case, but I understand that with the changes to the beta it could be fixed once that's pushed to stable (as in, that's when I'll find out)...

 

Here's what's weird though.

 

I wasn't watching the recording, I just started watching the channel and was a little behind the Live point.

Something happened (I'd guess the remote user had an issue, or some sort of drop) and this action then stopped the recording.

When this occurred, it stopped my live playback, and I obviously lost the bit of buffer I had from pausing.

I'd assume since it was recording this same channel, my buffer from tuning the station live is the same temp file (correct?).

 

So then when the recording was stopped for whatever reason, my playback got stopped.

I'd also assume this happened for all users during that time (including me, there are two others watching the same NFL broadcast).

 

It shows this again, and I'm certain the other users didn't tell the app to stop recording (that'd make zero sense 23 minutes into the game):

2018-09-30 12:23:02.323 Info SessionManager: Playback stopped reported by app Roku SG 3.0.109 playing WFLD-DT. Stopped at 1022000 ms
2018-09-30 12:23:02.323 Info MediaSourceManager: Live stream native_92d66927260f45eebfc47f319a9583b3_8e9f5d9fd49a89574e730b1c4b44f805 consumer count is now 0
2018-09-30 12:23:02.323 Info MediaSourceManager: Closing live stream a17c75760a04e99b68cf766e11316e1c_09efa0d56b934a82adec00a87b837fb0_native_92d66927260f45eebfc47f319a9583b3_8e9f5d9fd49a89574e730b1c4b44f805
2018-09-30 12:23:02.323 Info App: Closing SharedHttpStream
2018-09-30 12:23:02.324 Info App: Deleting temp files /mnt/disks/WD2TB/transcoding-temp/df85e4e968f64a17806ce5c692977148.ts
2018-09-30 12:23:02.324 Info App: Recording stopped: /mnt/user/Recorded_TV/NFL Football/NFL Football 2018_09_30_12_00_00 - Tampa Bay Buccaneers at Chicago Bears.ts

I can provide the full log if it'd be helpful, if so let me know and I'll send it to you directly.

 

Thanks.

[maegibbons 1267]

Lets see the full log so we can track all the attachments to the shared stream.

 

Krs

 

Mark

[bungee91 98]

@@maegibbons as requested, the full log is attached.

Thanks.

 

Edit:removed log

Edited October 1, 2018 by bungee91

[maegibbons 1267]

Hi

 

Can you enable debug logging so that if it happens again we get more info.

 

Krs

 

Mark

[bungee91 98]

Sure, I can do that.

Is this option in the server settings somewhere?  

Thanks.

[ebr 14937]

Sure, I can do that.

Is this option in the server settings somewhere?  

Thanks.

 

Yes, on the "Logs" tab in the dashboard.  Please re-start the server after turning it on.

 

This appears to be the key line - almost as if the recording isn't getting counted as a consumer of the stream...

consumer count is now 0

[bungee91 98]

 

Yes, on the "Logs" tab in the dashboard.  Please re-start the server after turning it on.

 

This appears to be the key line - almost as if the recording isn't getting counted as a consumer of the stream...

consumer count is now 0

 

Ok, will plan to enable this prior to the next time this may happen (it'll be two weeks out, my NFL team is on bye next week). Who knows, maybe by then I'll be testing with the new fixes from beta into stable?. 

As for the consumer count... I wondered what that indicated, good to know!

[Luke 37128]

Great, thanks.

[bungee91 98]

This is unfortunately still occurring, random yes, but still occurring.

Fortunately (with no extra effort) HDHR DVR auto records my NFL team without any input from me (wink, wink), so I watched the game from that.

 

New log attached.

Where the issue seemed to have happened, and no the user did not cancel the recording.

2019-08-24 18:21:35.635 Info App: Deleting partial stream file(s) /config/transcoding-temp/d3017a86fdee07ac7de894943fc053c2.m3u8
2019-08-24 18:21:35.635 Info SessionManager: Playback stopped reported by app Emby Web 4.2.0.46 playing WFLDDT. Stopped at 131115 ms
2019-08-24 18:21:35.636 Info MediaSourceManager: Live stream native_82e38cab1af388fe93805a088b78b9bd_769baedfc61138e74a97964baffd3116 consumer count is now 0
2019-08-24 18:21:35.636 Info MediaSourceManager: Closing live stream 06044cf0e6f93cdae5f285c9ecfaaeb4_01413a525b3a9622ce6fdf19f7dde354_native_82e38cab1af388fe93805a088b78b9bd_769baedfc61138e74a97964baffd3116
2019-08-24 18:21:35.636 Info SharedHttpPipelineSource: Closing SharedHttpPipelineSource
2019-08-24 18:21:35.636 Info LiveTV: Recording stopped: /mnt/user/Recorded_TV/NFL Football (2018)/NFL Football 2019_08_24_18_00_00 - Chicago Bears at Indianapolis Colts.ts
2019-08-24 18:21:35.636 Info LiveTV: Triggering refresh on /mnt/user/Recorded_TV/NFL Football (2018)/NFL Football 2019_08_24_18_00_00 - Chicago Bears at Indianapolis Colts.ts
2019-08-24 18:21:35.636 Info LiveTV: Refreshing recording parent /mnt/user/Recorded_TV/NFL Football (2018)

The recording itself is this part of the log:

2019-08-24 18:00:00.435 Info LiveTV: Getting media sources for recording from channel 102397 102397
2019-08-24 18:00:00.435 Info LiveTV: Opening live stream for recording from channel 102397 102397
2019-08-24 18:00:00.435 Info LiveTvManager: Opening channel stream from Emby, external channel Id: hdhr_190
2019-08-24 18:00:00.435 Info LiveTV: Streaming Channel hdhr_190
2019-08-24 18:00:00.435 Info LiveTV: Live stream native_82e38cab1af388fe93805a088b78b9bd_769baedfc61138e74a97964baffd3116 consumer count is now 2
2019-08-24 18:00:00.435 Info MediaSourceManager: Live tv media info probe took 0.0001572 seconds
2019-08-24 18:00:00.435 Info MediaSourceManager: Live stream opened: {"Protocol":"Http","Id":"native_82e38cab1af388fe93805a088b78b9bd_769baedfc61138e74a97964baffd3116","Path":"http://127.0.0.1:8096/LiveTv/LiveStreamFiles/5e565efeb3c84bfd9b2bccb5ed24e59e/stream.ts","Type":"Default","Container":"mpegts","IsRemote":false,"SupportsTranscoding":true,"SupportsDirectStream":true,"SupportsDirectPlay":false,"IsInfiniteStream":true,"RequiresOpening":true,"RequiresClosing":true,"LiveStreamId":"06044cf0e6f93cdae5f285c9ecfaaeb4_01413a525b3a9622ce6fdf19f7dde354_native_82e38cab1af388fe93805a088b78b9bd_769baedfc61138e74a97964baffd3116","RequiresLooping":false,"SupportsProbing":false,"MediaStreams":[{"Codec":"mpeg2video","TimeBase":"1/90000","CodecTimeBase":"1001/60000","VideoRange":"SDR","DisplayTitle":"720p MPEG2VIDEO","IsInterlaced":false,"BitRate":8000000,"RefFrames":1,"IsDefault":false,"IsForced":false,"Height":720,"Width":1280,"AverageFrameRate":59.94006,"RealFrameRate":59.94006,"Profile":"Main","Type":"Video","AspectRatio":"16:9","Index":-1,"IsExternal":false,"IsTextSubtitleStream":false,"SupportsExternalStream":false,"Protocol":"File","PixelFormat":"yuv420p","Level":4,"IsAnamorphic":false},{"Codec":"ac3","TimeBase":"1/90000","CodecTimeBase":"1/48000","DisplayTitle":"Dolby Digital 5.1","IsInterlaced":false,"ChannelLayout":"5.1","BitRate":448000,"Channels":6,"SampleRate":48000,"IsDefault":false,"IsForced":false,"Type":"Audio","Index":-1,"IsExternal":false,"IsTextSubtitleStream":false,"SupportsExternalStream":false,"Protocol":"File","Level":0}],"Formats":[],"Bitrate":8448000,"RequiredHttpHeaders":{},"ReadAtNativeFramerate":false}
2019-08-24 18:00:00.436 Info LiveTV: Will record to /mnt/user/Recorded_TV/NFL Football (2018)/NFL Football 2019_08_24_18_00_00 - Chicago Bears at Indianapolis Colts.ts for 239.992728301667 minutes.
2019-08-24 18:00:00.484 Info LiveTV: Triggering refresh on /mnt/user/Recorded_TV/NFL Football (2018)/NFL Football 2019_08_24_18_00_00 - Chicago Bears at Indianapolis Colts.ts
2019-08-24 18:00:00.484 Info LiveTV: Refreshing recording parent /mnt/user/Recorded_TV/NFL Football (2018)
2019-08-24 18:00:00.484 Info LiveTV: Copying recording stream to file /mnt/user/Recorded_TV/NFL Football (2018)/NFL Football 2019_08_24_18_00_00 - Chicago Bears at Indianapolis Colts.ts

Thanks.

 

Edit: This time with the log attached.

embyserver-63702288000.txt

Edited August 27, 2019 by bungee91

[Luke 37128]

And it's only if you play the recording in progress that this happens?

[bungee91 98]

I honestly don't know, as I wanted to watch this recording about two hours in and noticed that it was only 21 minutes long and no longer recording.

[Luke 37128]

@@denz are you able to reproduce?

[denz 426]

No I tried it last night and no issues. I will keep testing in different clients and see can I reproduce it.