catalyst: After stream restarts, certain servers can't replicate stream

[ddvtech]

catalyst: After stream restarts, certain servers can't replicate stream

[emranemran]

Another additional failure condition is also being caught using the test defined in livepeer/catalyst#86.
Logs attached.
stream-interruption.log

[emranemran]

A few updates:

• This issue is fairly easy to reproduce with 2 nodes and one ingest stream - stopping/starting the ingest stream will trigger the error condition and playback streams are not able to recover. The test in livepeer/catalyst#86 will catch this condition (currently forced to pass until the issue is resolved)

• I setup a single catalyst node with one ingest stream and can still reproduce the issue - so it's not specific to two separate nodes and the DTSC link in between (verbose logs attached).
  single-node-error.log

• Discussed with @Thulinma and it looks like a race condition where the "new" HTTP output attempts to read from the previously deleted stream buffers as that previous session shuts down. Adding a few debug prints as next step to understand the code paths.

[emranemran]

Repro steps:
(logs here: out.log)

• Used this ffmpeg command for ingest:

ffmpeg -re -f lavfi -i testsrc=size=480x320:rate=30 -f lavfi -i sine -vf drawtext="text='%{localtime\:%X}':fontsize=20:fontcolor=white:x=7:y=7" -pix_fmt yuv420p -vcodec libx264 -vb 2000k -preset ultrafast -acodec aac -f flv 'rtmp://127.0.0.1:1935/live/stream+foo'

• Started Mist standalone (not dockerized) as follows (used json config from catalyst repo since it was setup already):
  Note: built Mist using catalyst branch of mistserver repo

./MistController -c ../catalyst/config/catalyst-one.json -g 5 > out.log 2>&1

• Verified stream is visible in the Mist UI preview page

• Used https://hls-js.netlify.app/demo/ to attempt playing back in an external player. Got a few manifestLoad errors but after refreshing the page a few times, got the player to stream successfully here:

[2022-08-08 21:59:26] MistOutHTTP (670714) INFO: Received request: /hls/stream foo/index.m3u8 => HLS (stream+foo) (/home/parallels/mac/mistserver/src/output/output_http.cpp:210) 
[2022-08-08 21:59:26] MistOutHTTP (670716) INFO: Received request: /hls/stream foo/0_1/chunk_50023.0.ts => HLS (stream+foo) (/home/parallels/mac/mistserver/src/output/output_http.cpp:210) 
[2022-08-08 21:59:26] MistOutHTTP (670718) INFO: Received request: /hls/stream foo/0_1/chunk_50023.5.ts => HLS (stream+foo) (/home/parallels/mac/mistserver/src/output/output_http.cpp:210) 

• Then ctrl+C-ed on ffmpeg process and restart the ffmpeg cmd right away. Immediately hits the Shared metadata not ready yet error and the external player is not able to playback anymore.

---

Observations:
To track the code path, I added a few simple prints as attached in the patch below to understand the flow a bit better.

I can see MistInBuffer responding when I killed the ffmpeg stream here:

[2022-08-08 21:59:38] MistInBuffer:stream+foo (670197) INFO: Disconnected track 1 (/home/parallels/mac/mistserver/src/input/input_buffer.cpp:486) 
[2022-08-08 21:59:38] MistInBuffer:stream+foo (670197) INFO: Should remove track 1 (/home/parallels/mac/mistserver/src/input/input_buffer.cpp:324) 
[2022-08-08 21:59:38] MistInBuffer:stream+foo (670197) INFO: Disconnected track 0 (/home/parallels/mac/mistserver/src/input/input_buffer.cpp:486) 
[2022-08-08 21:59:38] MistInBuffer:stream+foo (670197) INFO: Should remove track 0 (/home/parallels/mac/mistserver/src/input/input_buffer.cpp:324) 
[2022-08-08 21:59:38] MistInBuffer:stream+foo (670197) INFO: Input closing clean, reason: source disconnected for non-resumable stream (/home/parallels/mac/mistserver/src/input/input.cpp:678) 

Then this is where one MistOutHTTP is exiting and a new one is spawned lining up with the new request from the player.

[2022-08-08 21:59:38] MistOutHLS:stream+foo (670785) INFO: Received signal Terminated (15) from process 670197 (/home/parallels/mac/mistserver/lib/config.cpp:620) 
[2022-08-08 21:59:38] MistOutHTTP (670401) INFO: Exit reason: signal Terminated (15) from process 670197 (/home/parallels/mac/mistserver/src/output/mist_out.cpp:73) 
[2022-08-08 21:59:38] MistOutRTMP:stream foo (670810) INFO: Waiting for stream+foo buffer to be ready... (0) (/home/parallels/mac/mistserver/src/output/output.cpp:1988) 
[2022-08-08 21:59:38] MistOutHLS:stream+foo (670785) INFO: Received signal Terminated (15) from process 670197 (/home/parallels/mac/mistserver/lib/config.cpp:620) 
[2022-08-08 21:59:38] MistOutHLS:stream+foo (670785) INFO: Received signal Terminated (15) from process 670197 (/home/parallels/mac/mistserver/lib/config.cpp:620) 
[2022-08-08 21:59:38] MistOutHTTP (670814) INFO: Received request: /stream+foo.mp4 => MP4 (stream+foo) (/home/parallels/mac/mistserver/src/output/output_http.cpp:210) 
[2022-08-08 21:59:38] MistOutMP4:stream+foo (670814) INFO: Switching to Websocket mode (/home/parallels/mac/mistserver/src/output/output_http.cpp:310) 
[2022-08-08 21:59:38] MistOutHTTP (670815) INFO: Received request: /json_stream+foo.js => HTTP (stream+foo) (/home/parallels/mac/mistserver/src/output/output_http.cpp:210) 
[2022-08-08 21:59:38] MistOutHTTP (670815) INFO: Inside websocketHandler (/home/parallels/mac/mistserver/src/output/output_http_internal.cpp:1088) 
[2022-08-08 21:59:38] MistOutHTTP (670815) INFO: Checking metadata (/home/parallels/mac/mistserver/src/output/output_http_internal.cpp:1119) 
[2022-08-08 21:59:38] MistOutHTTP (670815) INFO: Checking metadata (/home/parallels/mac/mistserver/src/output/output_http_internal.cpp:1119) 
[2022-08-08 21:59:39] MistOutHLS:stream+foo (670785) INFO: Received signal Terminated (15) from process 670197 (/home/parallels/mac/mistserver/lib/config.cpp:620) 
[2022-08-08 21:59:39] MistOutHTTP (670815) INFO: Checking metadata (/home/parallels/mac/mistserver/src/output/output_http_internal.cpp:1119) 
[2022-08-08 21:59:39] MistController (670046) INFO: Stream stream+foo became inactive (/home/parallels/mac/mistserver/src/controller/controller_statistics.cpp:169) 
[2022-08-08 21:59:39] MistOutHLS:stream+foo (670785) INFO: Received signal Terminated (15) from process 670197 (/home/parallels/mac/mistserver/lib/config.cpp:620) 
[2022-08-08 21:59:39] MistOutHTTP (670815) INFO: Checking metadata (/home/parallels/mac/mistserver/src/output/output_http_internal.cpp:1119) 
[2022-08-08 21:59:39] MistOutRTMP:stream foo (670810) INFO: Reconnecting to stream+foo buffer... (0) (/home/parallels/mac/mistserver/src/output/output.cpp:1993) 

After which point the metadata check goes from invalid to valid but streams still can't recover:

[2022-08-08 21:59:41] MistInBuffer:stream+foo (670905) INFO: Input booting (/home/parallels/mac/mistserver/src/input/input.cpp:310) 
[2022-08-08 21:59:41] MistInBuffer:stream+foo (670907) INFO: Starting serve (/home/parallels/mac/mistserver/src/input/input.cpp:536) 
[2022-08-08 21:59:41] MistInBuffer:stream+foo (670907) INFO: Input started (/home/parallels/mac/mistserver/src/input/input.cpp:652) 
[2022-08-08 21:59:41] MistInBuffer:stream+foo (670907) INFO: Setting maxKeepAway from 0 to new value of 45000 (/home/parallels/mac/mistserver/src/input/input_buffer.cpp:586) 
[2022-08-08 21:59:41] MistOutHLS:stream+foo (670900) INFO: QQQ: Shared metadata not ready yet - no tracks valid (/home/parallels/mac/mistserver/lib/dtsc.cpp:2151) 
[2022-08-08 21:59:41] MistOutHTTP (670815) INFO: Checking metadata (/home/parallels/mac/mistserver/src/output/output_http_internal.cpp:1119) 
[2022-08-08 21:59:41] MistOutHTTP (670815) INFO: Checking metadata (/home/parallels/mac/mistserver/src/output/output_http_internal.cpp:1119) 
[2022-08-08 21:59:41] MistOutHTTP (670815) INFO: Checking metadata (/home/parallels/mac/mistserver/src/output/output_http_internal.cpp:1119) 
[2022-08-08 21:59:42] MistOutHLS:stream+foo (670900) INFO: QQQ: Shared metadata not ready yet - no tracks valid (/home/parallels/mac/mistserver/lib/dtsc.cpp:2151) 
[2022-08-08 21:59:42] MistOutHTTP (670815) INFO: Checking metadata (/home/parallels/mac/mistserver/src/output/output_http_internal.cpp:1119) 
[2022-08-08 21:59:42] MistOutHTTP (670815) INFO: Checking metadata (/home/parallels/mac/mistserver/src/output/output_http_internal.cpp:1119) 
[2022-08-08 21:59:42] MistOutHLS:stream+foo (670900) INFO: QQQ: Shared metadata not ready yet - no tracks valid (/home/parallels/mac/mistserver/lib/dtsc.cpp:2151) 
[2022-08-08 21:59:42] MistOutHTTP (670815) INFO: Checking metadata (/home/parallels/mac/mistserver/src/output/output_http_internal.cpp:1119) 
[2022-08-08 21:59:43] MistOutHLS:stream+foo (670900) INFO: QQQ: Shared metadata not ready yet - no tracks valid (/home/parallels/mac/mistserver/lib/dtsc.cpp:2151) 
[2022-08-08 21:59:43] MistController (670046) INFO: Stream stream+foo became active (/home/parallels/mac/mistserver/src/controller/controller_statistics.cpp:163) 
[2022-08-08 21:59:43] MistOutHLS:stream+foo (670900) INFO: QQQ: Shared metadata not ready yet - no tracks valid (/home/parallels/mac/mistserver/lib/dtsc.cpp:2151) 
[2022-08-08 21:59:44] MistOutHLS:stream+foo (670900) INFO: QQQ: Shared metadata not ready yet - no tracks valid (/home/parallels/mac/mistserver/lib/dtsc.cpp:2151) 
[2022-08-08 21:59:44] MistOutHLS:stream+foo (670900) INFO: QQQ: Shared metadata not ready yet - no tracks valid (/home/parallels/mac/mistserver/lib/dtsc.cpp:2151) 
[2022-08-08 21:59:45] MistOutHLS:stream+foo (670900) INFO: QQQ: Shared metadata not ready yet - no tracks valid (/home/parallels/mac/mistserver/lib/dtsc.cpp:2151) 
[2022-08-08 21:59:45] MistOutHLS:stream+foo (670900) INFO: QQQ: Shared metadata not ready yet - no tracks valid (/home/parallels/mac/mistserver/lib/dtsc.cpp:2151) 
[2022-08-08 21:59:46] MistOutHLS:stream+foo (670900) INFO: QQQ: Shared metadata not ready yet - no tracks valid (/home/parallels/mac/mistserver/lib/dtsc.cpp:2151) 
[2022-08-08 21:59:46] MistOutHLS:stream+foo (670900) INFO: QQQ: Shared metadata not ready yet - no tracks valid (/home/parallels/mac/mistserver/lib/dtsc.cpp:2151) 
[2022-08-08 21:59:47] MistOutHLS:stream+foo (670900) INFO: QQQ: Shared metadata not ready yet - no tracks valid (/home/parallels/mac/mistserver/lib/dtsc.cpp:2151) 
[2022-08-08 21:59:47] MistOutHTTP (670815) INFO: Checking metadata (/home/parallels/mac/mistserver/src/output/output_http_internal.cpp:1119) 
[2022-08-08 21:59:47] MistOutHTTP (670815) INFO: metadata valid (/home/parallels/mac/mistserver/src/output/output_http_internal.cpp:1121) 
[2022-08-08 21:59:47] MistOutHTTP (670815) INFO: Checking metadata (/home/parallels/mac/mistserver/src/output/output_http_internal.cpp:1119) 
[2022-08-08 21:59:47] MistOutHTTP (670815) INFO: metadata valid (/home/parallels/mac/mistserver/src/output/output_http_internal.cpp:1121) 
[2022-08-08 21:59:47] MistOutHTTP (670815) INFO: Checking metadata (/home/parallels/mac/mistserver/src/output/output_http_internal.cpp:1119) 
[2022-08-08 21:59:47] MistOutHTTP (670815) INFO: metadata valid (/home/parallels/mac/mistserver/src/output/output_http_internal.cpp:1121) 
[2022-08-08 21:59:47] MistOutHTTP (670815) INFO: Checking metadata (/home/parallels/mac/mistserver/src/output/output_http_internal.cpp:1119) 
[2022-08-08 21:59:47] MistOutHTTP (670815) INFO: metadata valid (/home/parallels/mac/mistserver/src/output/output_http_internal.cpp:1121) 
[2022-08-08 21:59:47] MistOutHTTP (670936) INFO: Received request: /stream+foo.mp4 => MP4 (stream+foo) (/home/parallels/mac/mistserver/src/output/output_http.cpp:210) 
[2022-08-08 21:59:47] MistOutMP4:stream+foo (670936) INFO: Switching to Websocket mode (/home/parallels/mac/mistserver/src/output/output_http.cpp:310) 
[2022-08-08 21:59:47] MistOutHLS:stream+foo (670900) INFO: QQQ: Shared metadata not ready yet - no tracks valid (/home/parallels/mac/mistserver/lib/dtsc.cpp:2151) 

This is where I'm a bit lost - does the MistOutHLS process need to be kicked again for it to not look for the older memory pages?

patch with prints FYI:

diff --git a/src/output/output_http_internal.cpp b/src/output/output_http_internal.cpp
index 50bd526b..817c58af 100644
--- a/src/output/output_http_internal.cpp
+++ b/src/output/output_http_internal.cpp
@@ -1085,6 +1085,7 @@ namespace Mist{
   }

   bool OutHTTP::websocketHandler(const HTTP::Parser & req, bool headersOnly){
+    INFO_MSG("Inside websocketHandler");
     stayConnected = true;
     std::string reqHost = HTTP::URL(req.GetHeader("Host")).host;
     if (req.GetHeader("X-Mst-Path").size()){mistPath = req.GetHeader("X-Mst-Path");}
@@ -1115,7 +1116,11 @@ namespace Mist{
         newState = streamStatus.mapped[0];
       }

-      if (meta){meta.reloadReplacedPagesIfNeeded();}
+      INFO_MSG("Checking metadata");
+      if (meta){
+              INFO_MSG("metadata valid");
+	      meta.reloadReplacedPagesIfNeeded();
+      }
       if (newState != prevState || (newState == STRMSTAT_READY && M.getValidTracks() != prevTracks)){
         if (newState == STRMSTAT_READY){
           thisError = "";
           

[Thulinma]

Can you see if 950089a perhaps fixes the issue?