Could not get a new fragment to download after 10 tries and we are the only active downloader

[Lytexx]

im always getting this error on streams from this channel https://www.youtube.com/channel/UCWCc8tO-uUl_7SJXIKJACMw

here is my log https://pastebin.com/EhUTRBYU

the video-download thread doesnt close so its just stuck like this

the files that are left are not loading properly and deleting them only works after a restart i uploaded them here https://gofile.io/d/mJPZWb i hope you can do something with this

also the ffprobe output from the .f137 and .f140 files

[mov,mp4,m4a,3gp,3g2,mj2 @ 000002464d14b180] Found duplicated MOOV Atom. Skipped it
    Last message repeated 396 times
Input #0, mov,mp4,m4a,3gp,3g2,mj2, from 'C:\Users\Lytexx\Downloads\OzxQWYvHPl0__3mcao98c\[20210427] 【歌枠_アーカイブな し​】不要不急の歌配信です。【神楽めあ​】 [神楽めあ _ KaguraMea] (OzxQWYvHPl0).f140.ts':
  Metadata:
    creation_time   : 2021-04-27T10:05:56.000000Z
    major_brand     : dash
    minor_version   : 0
    compatible_brands: iso6mp41
  Duration: 00:06:37.99, start: 0.000000, bitrate: 180 kb/s
  Stream #0:0(und): Audio: aac (LC) (mp4a / 0x6134706D), 44100 Hz, stereo, fltp, 128 kb/s (default)
    Metadata:
      creation_time   : 2021-04-27T10:05:56.000000Z
      handler_name    : ISO Media file produced by Google Inc. Created on: 04/27/2021.
      vendor_id       : [0][0][0][0]

[mov,mp4,m4a,3gp,3g2,mj2 @ 000001d8f5b4b180] Found duplicated MOOV Atom. Skipped it
    Last message repeated 308 times
Input #0, mov,mp4,m4a,3gp,3g2,mj2, from 'C:\Users\Lytexx\Downloads\OzxQWYvHPl0__3mcao98c\[20210427] 【歌枠_アーカイブな し​】不要不急の歌配信です。【神楽めあ​】 [神楽めあ _ KaguraMea] (OzxQWYvHPl0).f137.ts':
  Metadata:
    creation_time   : 2021-04-27T10:05:56.000000Z
    major_brand     : dash
    minor_version   : 0
    compatible_brands: iso6avc1mp41
  Duration: 00:05:10.00, start: 0.000000, bitrate: 2403 kb/s
  Stream #0:0(und): Video: h264 (Main) (avc1 / 0x31637661), yuv420p(tv, bt709, progressive), 1920x1080 [SAR 1:1 DAR 16:9], 2362 kb/s, 30 fps, 30 tbr, 90k tbn, 60 tbc (default)
    Metadata:
      creation_time   : 2021-04-27T10:05:56.000000Z
      handler_name    : ISO Media file produced by Google Inc. Created on: 04/27/2021.
      vendor_id       : [0][0][0][0]

[Kethsar]

I think it's somehow getting stuck on its call to os.remove(), since the log shows it has 310 video fragments, which means it at least manages to append to the larger .ts file and reports that progress, but then dies between that and finishing the loop, without throwing an exception. Are you unable to remove any of the files until after a restart, or just the larger .ts and one of the last two fragments downloaded? Also, how consistently does this happen, and is it really only for this channel?

[Lytexx]

Are you unable to remove any of the files until after a restart, or just the larger .ts and one of the last two fragments downloaded?

I already deleted them i will check that the next time it happens

Also, how consistently does this happen, and is it really only for this channel?

this happend for every streams i tried to download and yes its really only this channel

[Kethsar]

Interesting. I'll have to keep an eye out for any streams then and see if it affects me in Linux and/or Windows then. If it really is os.remove() then I am not entirely certain there is anything I can do, but I'll look into it more once I figure that out.

[Lytexx]

i got to kind of replicate it on polkas stream

pastebin is currently having maintenance. so i will post my log here

C:\Users\Lytexx\Downloads>yta Enter a youtube livestream URL: https://www.youtube.com/watch?v=6KldgpmSoGE 14:35:42 INFO: Loaded cookie file cookies.txt
Available video qualities: audio_only, 144p, 240p, 360p, 480p, 720p, 720p60, 1080p60, best Enter desired video quality: Selected quality: 1080p60 (h264) 14:35:45 INFO: Starting download to 6KldgpmSoGEojzo414e[20210428] POLKA♡April♡LIVE♡2021 #ぽるうた 【ホロライブ_尾丸ポルカ】 [Polka Ch. 尾丸ポルカ] (6KldgpmSoGE).f140.ts 14:35:45 INFO: Starting download to 6KldgpmSoGE__ojzo414e[20210428] POLKA♡April♡LIVE♡2021 #ぽるうた 【ホロライブ_尾丸ポルカ】 [Polka Ch. 尾丸ポルカ] (6KldgpmSoGE).f299.ts 14:38:45 DEBUG: audio0: Starved for fragment numbers and multiple fragment threads running
14:38:45 DEBUG: audio0: Closing this thread to minimize unneeded network requests
14:38:45 DEBUG: audio0: exiting
14:38:46 DEBUG: audio1: Starved for fragment numbers and multiple fragment threads running
14:38:46 DEBUG: audio1: Closing this thread to minimize unneeded network requests
14:38:46 DEBUG: audio1: exiting
14:39:43 DEBUG: audio3: Starved for fragment numbers and multiple fragment threads running
14:39:43 DEBUG: audio3: Closing this thread to minimize unneeded network requests
14:39:43 DEBUG: audio3: exiting
14:39:44 DEBUG: audio2: Starved for fragment numbers and multiple fragment threads running
14:39:44 DEBUG: audio2: Closing this thread to minimize unneeded network requests
14:39:44 DEBUG: audio2: exiting
14:41:04 DEBUG: video0: Starved for fragment numbers and multiple fragment threads running
14:41:04 DEBUG: video0: Closing this thread to minimize unneeded network requests
14:41:04 DEBUG: video0: exiting
14:41:05 DEBUG: video3: Starved for fragment numbers and multiple fragment threads running
14:41:05 DEBUG: video3: Closing this thread to minimize unneeded network requests
14:41:05 DEBUG: video3: exiting
14:41:09 DEBUG: video1: Starved for fragment numbers and multiple fragment threads running
14:41:09 DEBUG: video1: Closing this thread to minimize unneeded network requests
14:41:09 DEBUG: video1: exiting
14:44:23 DEBUG: audio4: Starved for fragment numbers and multiple fragment threads running
14:44:23 DEBUG: audio4: Closing this thread to minimize unneeded network requests
14:44:23 DEBUG: audio4: exiting
14:49:48 WARNING: audio-download: Error deleting fragment 2926: [WinError 5] Zugriff verweigert: '6KldgpmSoGEojzo414e\[20210428] POLKA♡April♡LIVE♡2021 #ぽるうた 【ホロライブ_尾丸ポルカ】 [Polka Ch. 尾丸ポルカ] (6KldgpmSoGE).f140.frag2926.ts' 14:49:48 WARNING: audio-download: Will try again after the download has finished
15:02:10 DEBUG: video4: Starved for fragment numbers and multiple fragment threads running
15:02:10 DEBUG: video4: Closing this thread to minimize unneeded network requests
15:02:10 DEBUG: video4: exiting
Video fragments: 4496; Audio fragments: 4496; Max sequence: 4495; Total Downloaded: 2.99GiB Keyboard Interrupt, stopping download... 15:15:59 DEBUG: video5: exiting
15:15:59 DEBUG: audio5: exiting
15:15:59 DEBUG: video2: exiting
15:15:59 INFO: Deleting file 6KldgpmSoGE__ojzo414e[20210428] POLKA♡April♡LIVE♡2021 #ぽるうた 【ホロライブ_尾丸ポルカ】 [Polka Ch. 尾丸ポルカ] (6KldgpmSoGE).f299.frag4497.ts 15:15:59 DEBUG: video-download thread closing
15:15:59 INFO: audio-download: Attempting to delete fragments that failed to be deleted before
15:15:59 INFO: Deleting file 6KldgpmSoGE__ojzo414e[20210428] POLKA♡April♡LIVE♡2021 #ぽるうた 【ホロライブ_尾丸ポルカ】 [Polka Ch. 尾丸ポルカ] (6KldgpmSoGE).f140.frag2926.ts

it got stuck here again while trying to delete the fragment there where 3 files left the .f299 .f140 and the frag2926.ts file only the fragment file is undeletable

the download itself didnt break seems like thats a different problem

[Kethsar]

I'd say the issue is one and the same, just that this time it properly threw an exception during the download, only to lock up trying to delete it later. I might have to look into some way to create a timeout and send a signal or get a stack trace. I could also create a complete separate thread to handle deleting files, I guess. That sounds dumb as hell though, and could lead to fragments not being deleted if even one causes it to lock up.

[Kethsar]

@Lytexx A friend has contributed some code to hopefully get some information if (when) it happens again. It will create a minidump if a call to os.remove() takes more than 10 seconds. The downside is, if my suspicion is correct and it's os.remove() getting stuck, I am not entirely certain I will be able to fix it. But it depends on what information the minidump will have. My suspicions right now are that either your disk or filesystem is subtly broken in a way that's not normally an issue.

[Lytexx]

@Lytexx A friend has contributed some code to hopefully get some information if (when) it happens again. It will create a minidump if a call to os.remove() takes more than 10 seconds.

my log https://pastebin.com/m4NNnqJN the files are deletable but the coredump file is empty

[Kethsar]

TypeError: logwarn() got an unexpected keyword argument 'end'

EEEEEEEEEEEEEEEEED One moment while I see if I can figure this out.

@Lytexx try now onegai. Amazing you hit it so fast, but at the same time worrying. I really think you should run a test on whatever drive you are downloading to. And also potentially try downloading to other drives to see if they suffer the same issue.

[Lytexx]

@Lytexx try now onegai. Amazing you hit it so fast

no idea why it happend so fast this time also i can delete the files without any problems it usually doesnt happen and is not a big issue just on the channel i mentioned above

i will post the coredump here when i get it again

I really think you should run a test on whatever drive you are downloading to. And also potentially try downloading to other drives to see if they suffer the same issue.

i have this problem on 2 different SSD's if its a problem on my side then probably something with windows

[Kethsar]

I realized after posting the edit that it happened so fast not because it was the deadlock issue, but because the unhandled exception didn't let the function do its thing, so the watchdog triggered when it otherwise would not have. Also if you manage to catch and record Kagura Mea's next stream and it happens, try using youtube-dl as well. Surely it also calls os.remove() on the fragments. Unless it's ffmpeg taking care of it all.

[Lytexx]

Didnt throw any error this time i will get back to you when i get it again

[9001]

EEEEEEEEEEEEEEEEED

😝^🤛

ok so you mentioned SSD, that kills my first theory (NAS or other network disk which is glitching out), but now i'm suspecting this is due to some antivirus software peeking at the file and causing issues

one way to almost-definitely figure this out is doing systemwide monitoring of the folder that ytarchive is writing to -- it's kind of a big hammer but it's the best i can think of

unfortunately the recorder we'll be using is singlethreaded and (i think?) reduces the ripping speed to 1 video fragment per second on my ryzen 3700x, but even so it should still be able to finish downloading the video in time, even if it's deleted immediately after

if this is something you'd like to try then please enjoy this step-by-step, most of it is just one-time setup which you can do at any time before ripping a vid

to make sure we don't capture anything unrelated, first make a new empty folder and copy ytarchive.py into it (this is where we'll be running ytarchive later)

then start by grabbing an older version of procmon since the recent versions are busted; either link below is fine:

• https://ocv.me/stuff/bin/ProcessMonitor-3.53.zip
• https://web.archive.org/web/20200617001707/https://download.sysinternals.com/files/ProcessMonitor.zip

then run procmon64.exe and

• options >> turn off show resolved network addresses
• filter >> turn on drop filtered events (this is the thing that's broken in newer versions of procmon)
• filter >> filter...

add the following filter:

• Path contains Users\ed\ytarc then Include
  • (replace Users\ed\ytarc with the new folder you'll be running yta in, either the full path or just a part of it like the example)

then file >> backing files

• (*) use file named: C:\Users\ed\procmon.pml
  • replace the path with something convenient outside of the yta folder
  • it will require roughly 2x the size of the final video file (but depending on antivirus etc it could be much more)

this should be enabled already but make sure the show file system activity toolbar button is enabled, it's near the green arrow

quit procmon

that was the preparations, so the remaining steps are for when you're about to start ripping a video:

start procmon

file >> turn on capture events if it wasn't already

run ytarchive on a livestream and let it finish like you normally would

file >> save...

• events to save: all events
• format: native process monitor format (PML)

then finally use 7zip to compress the pml since it shrinks to like 1% of the size w

we would still love the coredumps from ytarchive if it happens again! preferably along with the procmon pml too

[9001]

sorry for the wall of text

[Lytexx]

somehow didnt happen since the update i will reopen this issue when it happens again

[Lytexx]

my log https://pastebin.com/giQmwtLq it wrote 4 coredumps 2 .txt and 2 .dmp https://gofile.io/d/KEqOnz

i will try to get the procmon pml if this doesnt help enough

[9001]

well the good and the bad news is that you confirmed we're hitting a python bug

if you could rerun the command while recording with procmon then that would be fantastic, for this particular bug it would help tremendously to have the filesystem trace too

thanks a lot for your hlep so far!

[Kethsar]

Also while attempting to run the command ourselves another bug was found that I'll need to take into account. That is, apparently raw video/audio URLs attempt to redirect you sometimes. Unsure of when this happens, but the video you were using was still available so maybe that was the case. Though if you are around and can re-try the download as per 9001's request with the same URLs, that would be lovely. Any reason for the raw URLs instead of the usual youtube.com link? Were they given to you as a request to download?

[Lytexx]

if you could rerun the command while recording with procmon then that would be fantastic

okay i will try to set it up

Any reason for the raw URLs instead of the usual youtube.com link? Were they given to you as a request to download?

the stream was stuck processing for 3 days and since its over 2 hours i tried to get the full stream this way

[Lytexx]

i got it set up and seems to be working thanks for the detailed explanation the stream i tried this on is processed now so i have to find a new one

just curious the logs are showing a lot of buffer overflow as result especially when merging is that normal?

[Kethsar]

ytarchive logs or procmon logs?

[Lytexx]

ytarchive logs or procmon logs?

procmon

even though it deleted the fragment i got the permission denied error again somewhere at 13:45:24 here is the procmon log if you want to look into it https://gofile.io/d/SkRweS

[9001]

just curious the logs are showing a lot of buffer overflow as result especially when merging is that normal?

yeah looks like that's how FFmpeg rolls, so nothing to worry about, just a bit funky

even though it deleted the fragment i got the permission denied error again somewhere at 13:45:24

heh the log is incomplete - i'm guessing this pml is not the final logfile that you saved at the end, but instead it's one of the procmon tempfiles :p and also, catching the permission-denied thing in procmon is good but i hope we'll manage to get the big one too -- they're definitely related but most likely due to different things

and I just realized that procmon adds ReadFile and WriteFile as filters by default! would be better to delete those since they could hide some important context for what's going on

so good testrun and thanks again :>

[Lytexx]

yeah looks like that's how FFmpeg rolls, so nothing to worry about, just a bit funky

okay thanks

heh the log is incomplete - i'm guessing this pml is not the final logfile that you saved at the end, but instead it's one of the procmon tempfiles :p

i forgot i had to save the log file manually sorry for that

and also, catching the permission-denied thing in procmon is good but i hope we'll manage to get the big one too -- they're definitely related but most likely due to different things

i know i will try my best but getting it is rather hard since it doesnt happen consistently

and I just realized that procmon adds ReadFile and WriteFile as filters by default! would be better to delete those since they could hide some important context for what's going on

i cant find any filter like that i added 2 to exclude them

[9001]

i know i will try my best but getting it is rather hard since it doesnt happen consistently

yeah bugs like that are the worst, no worries just whenever it shows up o/

i cant find any filter like that i added 2 to exclude them

oh wait no i meant it the other way around! as in not having the filters is good, since seeing the reads/writes in the log helps :> good thing i'm better at debugging than english w

[Kethsar]

I finally dug around for the code Python calls for os.remove() in Windows and it basically just ends up as a call to DeleteFileW in the Win32 API.

So if nothing else it's 100% Windows causing issues. Did you have any Windows updates before this issue started happening? Also when was the first time you noticed this happen, anyway?

The current plan discussed with ed is to add an option to re-enable keeping fragments in memory and just writing them to the larger .ts file instead of writing them to disk before hand. Potential for increased memory usage but at least that way it won't lock up mid-download, and if the issue arises it will be on the completed download where it doesn't matter as much.

I might at some point maybe possibly not try updating my VM to the 2004 update since it's just not being hit on the 1909 update it's currently on. But ultimately I'd be surprised if there's anything we could do even if we find the true underlying cause, as it's effectively undocumented behaviour being hit.

[9001]

Alright yeah that will fix the problem for ytarchive, but i'm still curious what's going on on Lytexx's computer :p Still betting on the antivirus-or-something idea and procmon should be able to identify that

So! if you are curious as well and decide to keep running ytarchive with procmon and without the new --no-frag-files then i'd be happy to take a look at the procmon logs if you run into the issue again :>

[Lytexx]

thank you so much for helping me i will keep running procmon for while