How can I avoid having all live archiving create 1 second VODs?

[Keagel]

Hey!

Thanks for the work on Ganymede. I don't remember if it was happening with Ceres already, however for as long as I've been using Ganymede every live archiving creates two VOD entries in the database: the first one fails and has a duration of one second (and stays "processing" forever) and the second one downloads correctly. The last one for example is stuck on "Save Info" but sometimes it goes as far as Video Convert/Video Move. My live_check_interval is set to 15 seconds.

Do you know what could be the cause? Thanks!

[Zibbp]

Hi, Do you happen to have any logs from the container around the time the issues occurs. It may be beneficial to edit the config.json and enable debugging. This requires a container restart so ensure there are no active jobs.

If you were to look at the created_at fields in the database or admin interface for both queue items, are they created at the exact same time or a few seconds apart?

The queue jobs stuck on "save info", are they in a failed state or hanging in a processing state?

[Keagel]

Do you happen to have any logs from the container around the time the issues occurs. It may be beneficial to edit the config.json and enable debugging. This requires a container restart so ensure there are no active jobs.

I assume ganymede-api is the container responsible for the downloads? In any case, none of the containers show any error from when the issue occurred. I'll enable debugging.

If you were to look at the created_at fields in the database or admin interface for both queue items, are they created at the exact same time or a few seconds apart?

Unfortunately I've already cleaned up the queue and removed the 1 second VODs from the database.

The queue jobs stuck on "save info", are they in a failed state or hanging in a processing state?

All those 1 second jobs are stuck in a processing state, sometimes stuck on different steps. The one I noticed today was stuck on "save info" (not failed, just hanging) but on other occasions I've seen the process fail on video convert while the queue item is still marked as processing.

[Zibbp]

I assume ganymede-api is the container responsible for the downloads?

Yes. When this happens again, the debug logs and creation dates for the queue items should help in figuring out the issue. Until then I can only speculate what happened.

I've seen the process fail on video convert while the queue item is still marked as processing.

The video convert can really only fail two ways. If the input file is missing or if there is no disk space left.

[Keagel]

Alright so the issue just happened again with two different streams. With the first stream, two queue items are stuck in processing with a duration of 1 second before the final queue item downloads fully. With the second stream I have 3 queue items stuck processing. All of those fail at the "video convert" step (/tmp/xxxx-video.mp4: No such file or directory), except it's actually the download that fails.

[cli][info] Found matching plugin twitch for URL https://twitch.tv/LockLear
error: Unable to open URL: https://usher.ttvnw.net/api/channel/hls/LockLear.m3u8?... (('Connection aborted.', ConnectionResetError(104, 'Connection reset by peer')))

The ganymede-api logs don't show much more:

2022-11-18T09:10:43.897398608Z {"level":"debug","time":"2022-11-18T09:10:43Z","message":"locklear is now live"}
2022-11-18T09:10:43.925430048Z {"level":"debug","time":"2022-11-18T09:10:43Z","message":"starting task vod create folder for vod e18da2c3-6720-11ed-8121-0242ac1c0002"}
2022-11-18T09:10:43.932242345Z {"level":"debug","time":"2022-11-18T09:10:43Z","message":"creating folder: locklear/46314259212_e18da2c3-6720-11ed-8121-0242ac1c0002"}
2022-11-18T09:10:43.941331750Z {"level":"debug","time":"2022-11-18T09:10:43Z","message":"starting task vod download thumbnail for live stream e18da2c3-6720-11ed-8121-0242ac1c0002"}
2022-11-18T09:10:43.945910355Z {"level":"debug","time":"2022-11-18T09:10:43Z","message":"getting live streams using the following query param: ?user_login=locklear"}
2022-11-18T09:10:44.152770401Z {"level":"debug","time":"2022-11-18T09:10:44Z","message":"downloading file: https://static-cdn.jtvnw.net/previews-ttv/live_user_locklear-1920x1080.jpg"}
2022-11-18T09:10:44.187279372Z {"level":"debug","time":"2022-11-18T09:10:44Z","message":"downloading file: https://static-cdn.jtvnw.net/previews-ttv/live_user_locklear-640x360.jpg"}
2022-11-18T09:10:44.216149358Z {"level":"debug","time":"2022-11-18T09:10:44Z","message":"starting task vod save info for vod e18da2c3-6720-11ed-8121-0242ac1c0002"}
2022-11-18T09:10:44.216438444Z {"level":"debug","time":"2022-11-18T09:10:44Z","message":"refresh live thumbnails called...sleeping for 30 minutes"}
2022-11-18T09:10:44.220721357Z {"level":"debug","time":"2022-11-18T09:10:44Z","message":"getting live streams using the following query param: ?user_login=locklear"}
2022-11-18T09:10:44.444897096Z {"level":"debug","time":"2022-11-18T09:10:44Z","message":"starting task video download for live stream e18da2c3-6720-11ed-8121-0242ac1c0002"}
2022-11-18T09:10:45.425874896Z {"level":"debug","time":"2022-11-18T09:10:45Z","message":"finished downloading live video for 46314259212"}
2022-11-18T09:10:45.438648339Z {"level":"debug","time":"2022-11-18T09:10:45Z","message":"getting video duration"}
2022-11-18T09:10:45.459727650Z {"level":"error","error":"exit status 1","time":"2022-11-18T09:10:45Z","message":"error getting video duration"}
2022-11-18T09:10:45.459745828Z {"level":"error","error":"exit status 1","time":"2022-11-18T09:10:45Z","message":"error getting video duration"}
2022-11-18T09:10:45.459749649Z {"level":"debug","time":"2022-11-18T09:10:45Z","message":"starting task video convert for vod e18da2c3-6720-11ed-8121-0242ac1c0002"}
2022-11-18T09:10:45.462116339Z {"level":"debug","time":"2022-11-18T09:10:45Z","message":"video convert args: [-y -hide_banner -i /tmp/46314259212_e18da2c3-6720-11ed-8121-0242ac1c0002-video.mp4 -c:v copy -c:a copy /tmp/46314259212_e18da2c3-6720-11ed-8121-0242ac1c0002-video-convert.mp4]"}
2022-11-18T09:10:45.482599746Z {"level":"error","error":"exit status 1","time":"2022-11-18T09:10:45Z","message":"error running ffmpeg for vod video convert"}
2022-11-18T09:10:45.482619197Z {"level":"error","error":"exit status 1","time":"2022-11-18T09:10:45Z","message":"error converting video"}

[Zibbp]

Does this happen with every streamer, or just a few? Random?

Can you pull down the latest api and frontend containers, just got released a few hours ago, and try archiving a live stream again? It appears Streamlink is having some issues connecting according to the log you posted. The streamlink version was recently updated so I would like to check if the update fixes the issue first.

If it still fails, try adding --loglevel=debug to the Streamlink arguments found in Admin > Settings. Ensure it is comma separated like the default arguments shown. Once the argument is added, start up another live archive and post the full log video download logs in the mounted /logs folder.

[Zibbp]

On a side note, the reason why the video download is being marked as successful but it's failing is because I use the "failed" state for Streamlink to detect if the stream went down.

I'll have to look if there is a better way to accomplish that because it's confusing if the video download really failed but was marked as sucessful.

[Keagel]

Does this happen with every streamer, or just a few? Random?

Happens with every streamer and with almost every stream.

Can you pull down the latest api and frontend containers, just got released a few hours ago, and try archiving a live stream again? It appears Streamlink is having some issues connecting according to the log you posted. The streamlink version was recently updated so I would like to check if the update fixes the issue first.

I just pulled and recreated my containers, I'll let you know if it still occurs when another stream starts archiving.

I'll have to look if there is a better way to accomplish that because it's confusing if the video download really failed but was marked as sucessful.

I don't know anything about Go but if you can access the error thrown/returned by Streamlink you could differentiate between the different error messages.

[Keagel]

Sorry about the delay. I thought the issue was fixed for a while as it hadn't occurred since I last posted, but in the past few days it's happened again. Unfortunately the debug level logs don't tell much more.

Here is an example from a stream that failed 3 times before it downloaded successfully:

[cli][debug] OS:         Linux-5.15.0-52-generic-x86_64-with
[cli][debug] Python:     3.10.8
[cli][debug] Streamlink: 5.1.0
[cli][debug] Dependencies:
[cli][debug]  isodate: 0.6.1
[cli][debug]  lxml: 4.9.1
[cli][debug]  pycountry: 22.3.5
[cli][debug]  pycryptodome: 3.15.0
[cli][debug]  PySocks: 1.7.1
[cli][debug]  requests: 2.28.1
[cli][debug]  urllib3: 1.26.12
[cli][debug]  websocket-client: 1.4.2
[cli][debug] Arguments:
[cli][debug]  url=https://twitch.tv/aypierre
[cli][debug]  stream=['best', 'best']
[cli][debug]  --loglevel=debug
[cli][debug]  --output=/tmp/46368289420_1d64f12b-7345-11ed-8551-0242ac1e0002-video.mp4
[cli][debug]  --force=True
[cli][debug]  --force-progress=True
[cli][debug]  --twitch-disable-hosting=True
[cli][debug]  --twitch-low-latency=True
[cli][info] Found matching plugin twitch for URL https://twitch.tv/aypierre
[plugins.twitch][debug] Getting live HLS streams for aypierre
[plugins.twitch][debug] {'adblock': False, 'geoblock_reason': '', 'hide_ads': False, 'server_ads': True, 'show_ads': True}
[utils.l10n][debug] Language code: en_US
error: Unable to open URL: https://usher.ttvnw.net/api/channel/hls/aypierre.m3u8?player=twitchweb&p=365277&type=any&allow_source=true&allow_audio_only=true&allow_spectre=false&sig=xxx&token=%7B%22adblock%22%3Afalse%2C%22authorization%22%3A%7B%22forbidden%22%3Afalse%2C%22reason%22%3A%22%22%7D%2C%22blackout_enabled%22%3Afalse%2C%22channel%22%3A%22aypierre%22%2C%22channel_id%22%3A29753247%2C%22chansub%22%3A%7B%22restricted_bitrates%22%3A%5B%22archives%22%5D%2C%22view_until%22%3A1924905600%7D%2C%22ci_gb%22%3Afalse%2C%22geoblock_reason%22%3A%22%22%2C%22device_id%22%3Anull%2C%22expires%22%3A1670098821%2C%22extended_history_allowed%22%3Afalse%2C%22game%22%3A%22%22%2C%22hide_ads%22%3Afalse%2C%22https_required%22%3Atrue%2C%22mature%22%3Afalse%2C%22partner%22%3Afalse%2C%22platform%22%3A%22web%22%2C%22player_type%22%3A%22embed%22%2C%22private%22%3A%7B%22allowed_to_view%22%3Atrue%7D%2C%22privileged%22%3Afalse%2C%22role%22%3A%22%22%2C%22server_ads%22%3Atrue%2C%22show_ads%22%3Atrue%2C%22subscriber%22%3Afalse%2C%22turbo%22%3Afalse%2C%22user_id%22%3Anull%2C%22user_ip%22%3A%22xxxx%22%2C%22version%22%3A2%7D&fast_bread=True (('Connection aborted.', ConnectionResetError(104, 'Connection reset by peer')))

The 4th attempt (successful):

[cli][debug] OS:         Linux-5.15.0-52-generic-x86_64-with
[cli][debug] Python:     3.10.8
[cli][debug] Streamlink: 5.1.0
[cli][debug] Dependencies:
[cli][debug]  isodate: 0.6.1
[cli][debug]  lxml: 4.9.1
[cli][debug]  pycountry: 22.3.5
[cli][debug]  pycryptodome: 3.15.0
[cli][debug]  PySocks: 1.7.1
[cli][debug]  requests: 2.28.1
[cli][debug]  urllib3: 1.26.12
[cli][debug]  websocket-client: 1.4.2
[cli][debug] Arguments:
[cli][debug]  url=https://twitch.tv/aypierre
[cli][debug]  stream=['best', 'best']
[cli][debug]  --loglevel=debug
[cli][debug]  --output=/tmp/46368289420_38391aa0-7345-11ed-8551-0242ac1e0002-video.mp4
[cli][debug]  --force=True
[cli][debug]  --force-progress=True
[cli][debug]  --twitch-disable-hosting=True
[cli][debug]  --twitch-low-latency=True
[cli][info] Found matching plugin twitch for URL https://twitch.tv/aypierre
[plugins.twitch][debug] Getting live HLS streams for aypierre
[plugins.twitch][debug] {'adblock': False, 'geoblock_reason': '', 'hide_ads': False, 'server_ads': True, 'show_ads': True}
[utils.l10n][debug] Language code: en_US
[cli][info] Available streams: audio_only, 160p (worst), 360p, 480p, 720p, 720p60, 1080p60 (best)
[cli][info] Opening stream: 1080p60 (hls)
[cli][info] Writing output to
/tmp/46368289420_38391aa0-7345-11ed-8551-0242ac1e0002-video.mp4
[cli][debug] Checking file output
[plugins.twitch][info] Low latency streaming (HLS live edge: 2)
[stream.hls][debug] Reloading playlist
[cli][debug] Pre-buffering 8192 bytes
[stream.hls][debug] First Sequence: 0; Last Sequence: 3
[stream.hls][debug] Start offset: 0; Duration: None; Start Sequence: 2; End Sequence: None
[stream.hls][debug] Adding segment 2 to queue
[stream.hls][debug] Adding segment 3 to queue
[stream.hls][debug] Writing segment 2 to output
[cli][debug] Writing stream to output
[stream.hls][debug] Segment 2 complete
[stream.hls][debug] Writing segment 3 to output
[stream.hls][debug] Segment 3 complete

Could it simply be that it takes a while for the stream to properly start?

[Zibbp]

Could it simply be that it takes a while for the stream to properly start?

I'm going to guess this is what is causing the issue. I see the stream in question is probably not located in the USA which could cause delays with Twitch's CDN propagating the stream playlist depending on where you located causing Streamlink to not find the playlist in time.

I took a look through Streamlink's documentation and found an argument that will continuously retry the provided URL until it succeeds every X seconds defined by the provided argument. https://streamlink.github.io/cli.html#cmdoption-retry-streams

The command is normally --retry-streams 3, to retry every 3 seconds. For it to work in Ganymede, it needs to be comma separated without a space like so --retry-streams,3. This can be included in the Admin > Settings "Streamlink Args" setting. It should like similar to the following.

--retry-streams,3,--force-progress,--force,--twitch-low-latency,--twitch-disable-hosting

I tested this locally using the Streamlink CLI and it kept retrying until I started streaming. I cannot test it with Ganymede as I can't recreate your issue so you will have to try it out yourself.

[Keagel]

Thanks for the tip! Hopefully that works. I also added --retry-max,20 to avoid a potential infinite loop. I'll let you know how it goes.

[Keagel]

Seems like that did it. No error for the past 3 days. Thanks again!