[-BUG- FIXED in 1.1.1.0] [1.1.0.0-1.1.0.3] [All providers] Non-deterministic track truncation

Discussion in 'AnyStream' started by 0x0x0x0x0, Apr 2, 2021.

  1. 0x0x0x0x0

    0x0x0x0x0 Well-Known Member

    So, progress report for 1.1.0.2: for most part it's gone but is present intermittently (on the rarer side). I downloaded the from N- fine, downloaded from D cut audio (aha! I thought), ok, downloaded another from N to check bitrate, that was fine. Ok, now I know what to focus on, quit AS, start again, download the same title from D as gave cut audio before---full audio (thresholding at 1s), damn, lost log for that. Never mind, try another title that was giving problems before, that was fine too... Try one more from D---audio cuts out at the end (video frames roll but abrupt ending of the audio track), so it's become infrequent cf. every(?) download:-

    Code:
    !A Title_from_D_S01E01_.mp4 |v @ 640x480|=22:49,368 |a AAC @ 128000 (en)|=22:48,000 (1.368 s)
    !A Title_from_A_S01E08_.mp4 |v @ 1920x1080|=44:10,022 |a E-AC-3 @ 224000 (en)|=44:08,000 (2.022 s)
    
    cf. Title_from_A with verboten version, when my tool is in pedantic mode (thresholding at 0):-
    Code:
    !V Title_from_A_S01E08_.mp4 |v @ 1920x1080|=44:10,022 |a E-AC-3 @ 224000 (en)|=44:10,048 (-0.026 s)
    
     

    Attached Files:

  2. Lowpro

    Lowpro Well-Known Member

    I'm not sure if this is the correct place to post this, but I just gave 1.1.0.2 (32-bit) a try to see if the video was still getting cut short at the end of a given download. I downloaded a TV episode from N and it's still happening. The progress bar stops at 99% and the post-processing starts. Once completed the resulting MP4 file is missing 11 seconds of video at the end. The video should have been 43 minutes 07 seconds, but was only 42 minutes 56 seconds. The audio was fine. The audio was the full 43 minutes 07 seconds. I then downloaded the same TV episode using 1.0.9.1 (32-bit) and no issues. Both the audio and video were 43 minutes 07 seconds. Log files from each download attached.
     
    Last edited: Apr 5, 2021
  3. 0x0x0x0x0

    0x0x0x0x0 Well-Known Member

    I'm getting more and more convinced it's a threading problem, I'm getting different cut offs depending on how many times I try, for example, the same episode:

    Code:
    !A Title_S01E08_.bad-1.mp4 |v @ 640x480|=22:38,090 |a AAC @ 128000 (en)|=22:32,000 (6.09 s)
    !A Title_S01E08_.bad-2.mp4 |v @ 640x480|=22:33,352 |a AAC @ 128000 (en)|=22:32,000 (1.352 s)
    
    More extreme example running my script in pedantic mode with the last entry being a "good" download (not in the attached logs):
    Code:
    !A Title_S01E03_.bad-1.mp4 |v @ 640x480|=22:38,524 |a AAC @ 128000 (en)|=22:32,000 (6.524 s)
    !A Title_S01E03_.bad-2.mp4 |v @ 640x480|=22:38,524 |a AAC @ 128000 (en)|=22:32,000 (6.524 s)
    !A Title_S01E03_.bad-3.mp4 |v @ 640x480|=22:38,524 |a AAC @ 128000 (en)|=22:32,000 (6.524 s)
    !A Title_S01E03_.bad-4.mp4 |v @ 640x480|=22:38,524 |a AAC @ 128000 (en)|=22:32,000 (6.524 s)
    !V Title_S01E03_.mp4 |v @ 640x480|=22:38,524 |a AAC @ 128000 (en)|=22:38,549 (-0.025 s)
    
     

    Attached Files:

    Last edited: Apr 5, 2021
    Lowpro likes this.
  4. Prospere

    Prospere RedFox Development Team

    We shall keep looking into the problem.
     
  5. Jason Mulree

    Jason Mulree Member

    I wonder if varying the download speed affects the outcome as it has before?
     
  6. Kamala

    Kamala Well-Known Member

    same problem here with the latest (beta) version ...
    cutting off the download during the end credits, log attached...
    does not happen with all videos,but with this documentary it did..
     

    Attached Files:

  7. primal

    primal Member

    version
    1.1.0.2
    picard S01E03 AP-UK. Video cuts off while audio is going at the end of show. I also note that 640DD+ is not available anymore...it gave me 512DD+. I created a log file.
     

    Attached Files:

  8. 0x0x0x0x0

    0x0x0x0x0 Well-Known Member

    Great minds and all that ;) literally, as you posted that I was about a minute into downloading at realtime speed, and it was looking so promising from a previously bad e02 till e04 broke "the record" in a non-deterministic way again (bad-1 was done at realtime, bad-2 at unlimited); again, with pedantic verification:-

    Code:
    !V Title_S01E02_.bad-4.mp4 |v @ 640x480|=22:41,360 |a AAC @ 128000 (en)|=22:48,000 (-6.64 s)
    !V Title_S01E02_.mp4 |v @ 640x480|=22:48,450 |a AAC @ 128000 (en)|=22:48,491 (-0.041 s)
    !V Title_S01E03_.mp4 |v @ 640x480|=22:48,701 |a AAC @ 128000 (en)|=22:48,725 (-0.024 s)
    !A Title_S01E04_.bad-1.mp4 |v @ 640x480|=22:47,700 |a AAC @ 128000 (en)|=22:40,000 (7.7 s)
    !A Title_S01E04_.bad-2.mp4 |v @ 640x480|=22:41,360 |a AAC @ 128000 (en)|=22:40,000 (1.36 s)
    
     

    Attached Files:

  9. Jason Mulree

    Jason Mulree Member

    Indeed (y)

    I have conducted some preliminary testing and unfortunately the first title I downloaded suffered from truncation using AS 1.1.0.2 :(

    Some observations:
    * The truncation issue is still present.
    * Downloading the same title multiple times yields different outputs.
    * Varying the download speed between 1x, 4x, and unlimited yields different, and inconsistent, outputs.
    * Setting the download speed to 2x yields a consistent output, and the resulting output DOES NOT appear to suffer the truncation issue!

    I will conduct additional testing when I have some time.
     
  10. 0x0x0x0x0

    0x0x0x0x0 Well-Known Member

    I was hoping you found a way to mitigate the guillotine lottery, alas (Edit: but it was fine at full throttle...):-
    Code:
    !A Title_S01E01_.bad-1.mp4 |v @ 640x480|=22:53,163 |a AAC @ 128000 (en)|=22:48,000 (5.163 s)
    !V Title_S01E01_.mp4 |v @ 640x480|=22:53,163 |a AAC @ 128000 (en)|=22:53,205 (-0.042 s)
    
    Edit 2: so I ploughed through to get a an overall sense of how things look (note the massive whopper in e12). Looks like a reasonable $thresh for D is about 100ms (the tail bumper on e5 doesn't play through the end):

    Code:
    !A Title_S01E01_.bad-1.mp4 |v @ 640x480|=22:53,163 |a AAC @ 128000 (en)|=22:48,000 (5.163 s)
    !V Title_S01E01_.mp4 |v @ 640x480|=22:53,163 |a AAC @ 128000 (en)|=22:53,205 (-0.042 s)
    !V Title_S01E02_.mp4 |v @ 640x480|=22:50,244 |a AAC @ 128000 (en)|=22:50,283 (-0.039 s)
    !A Title_S01E03_.bad-1.mp4 |v @ 640x480|=22:49,368 |a AAC @ 128000 (en)|=22:48,000 (1.368 s)
    !V Title_S01E04_.mp4 |v @ 640x480|=22:49,201 |a AAC @ 128000 (en)|=22:49,237 (-0.036 s)
    !V Title_S01E05_.bad-1.mp4 |v @ 640x480|=22:49,368 |a AAC @ 128000 (en)|=22:50,112 (-0.744 s)
    !V Title_S01E06_.bad-1.mp4 |v @ 640x480|=22:49,368 |a AAC @ 128000 (en)|=22:52,032 (-2.664 s)
    !A Title_S01E07_.bad-1.mp4 |v @ 640x480|=22:52,705 |a AAC @ 128000 (en)|=22:48,000 (4.705 s)
    !A Title_S01E08_.bad-1.mp4 |v @ 640x480|=22:52,204 |a AAC @ 128000 (en)|=22:48,000 (4.204 s)
    !V Title_S01E09_.mp4 |v @ 640x480|=22:49,535 |a AAC @ 128000 (en)|=22:49,557 (-0.022 s)
    !V Title_S01E10_.mp4 |v @ 640x480|=22:50,786 |a AAC @ 128000 (en)|=22:50,816 (-0.03 s)
    !V Title_S01E11_.mp4 |v @ 640x480|=22:50,286 |a AAC @ 128000 (en)|=22:50,325 (-0.039 s)
    !V Title_S01E12_.bad-1.mp4 |v @ 640x480|=12:16,736 |a AAC @ 128000 (en)|=22:48,000 (-631.264 s)
    !V Title_S01E13_.mp4 |v @ 640x480|=22:51,996 |a AAC @ 128000 (en)|=22:52,032 (-0.036 s)
    
     

    Attached Files:

    Last edited: Apr 6, 2021
  11. 0x0x0x0x0

    0x0x0x0x0 Well-Known Member

    GOT IT!!! :dance: I think...

    So looking at full-run (setting aside e12, which seems to have a transient error with "empty fragment"), every single time there was a bad download, either the video or the audio pump signalled

    Code:
    ... [Debug] [...] There are no open requests.
    
    which ever pump signals that, that pump comes up short (both are short when both signal).

    When the tracks were < 50ms different, that signal was absent.


    I've redownloaded e12, which nonetheless came up short
    Code:
    !A Title_S01E12_.bad-2.mp4 |v @ 640x480|=22:49,368 |a AAC @ 128000 (en)|=22:48,000 (1.368 s)
    
    but in line with my hypothesis:-
    Code:
    ... [Debug] [Pump:audio1:disney] There are no open requests.
    ... [Debug] [Pump:video:disney] There are no open requests.
    
    (video cuts prematurely as well)
     

    Attached Files:

    Last edited: Apr 6, 2021
  12. Mollenoh

    Mollenoh Well-Known Member

    Tried downloading Violetta Season 1 Episode 1 from D+ several times, and both audio and video gets truncated every time. Video more so than audio.
     

    Attached Files:

  13. Ch3vr0n

    Ch3vr0n Translator NL & Mod

    still being worked on. 1102 was supposed to fix it, but didn't.
     
    donaf likes this.
  14. donaf

    donaf Well-Known Member

    I can confirm that per Disney+ it is still apparently a work in progress per my observation (but better than before from what I've seen).

    Even better, the two episodes of Mission Impossible in Amazon Prime I had issues with truncation are now downloading perfectly with 1.1.0.2 version... Kudos! :dance::thankyou:
     
  15. 0x0x0x0x0

    0x0x0x0x0 Well-Known Member

    If you look at the log window (File->Show log messages) after the download completes and there is nothing that resembles
    Code:
    ... - [Debug] [Pump:...] There are no open requests.
    
    you get a clean download. If there are those messages then whatever the track that that message belongs to is (audio or video, or both) that track is truncated.
     
  16. donaf

    donaf Well-Known Member

    Thanks! That's good to know. I just ran into a couple of other episodes in Amazon Prime with truncation occurring (just when I thought it was completely fixed)! One of them I just checked had this line: 00:03:05.529 - [Debug] [Pump:audio1: prime] There are no open requests.
     

    Attached Files:

    Last edited: Apr 6, 2021
  17. 0x0x0x0x0

    0x0x0x0x0 Well-Known Member

    It's sporadic, so you might download the same episode four times and it'd be truncated but on the fifth it'd be perfectly fine. But now that we know what log message is a sign of the problem, hopefully @Prospere will have a much easier time fixing it, as before it was pretty much an intractable task. Audio cut out? ;)
     
    Last edited: Apr 6, 2021
  18. donaf

    donaf Well-Known Member

    Yep @0x0x0x0x0 that's what it is in the case I noted... Video continues with no audio. I've seen the opposite as well though in some cases where the audio continues and the video is frozen.
     
    Last edited: Apr 6, 2021
  19. 0x0x0x0x0

    0x0x0x0x0 Well-Known Member

    In the one where the video cuts out, you'd have something along the lines of "... - [Debug] [Pump:video:prime] There are no open requests." and potentially one for audio if that cuts out later as well.

    I think we just need to let the dev figure out why and how the condition is being triggered and what to do to avoid it :)
     
    Last edited: Apr 6, 2021
  20. Prospere

    Prospere RedFox Development Team

    @0x0x0x0x0 Nice observation, but not quite right. This has very little to nothing to do with truncation. A coincidence of some sort.