Chapter image extraction fails/doesn't complete for several files

[voodoo5_6k 29]

Yesterday, I observed several chapter image extraction operations fail. I end up with a movie having chapter images for like 2/3 of the chapters, with the last 1/3 not having images. So far so... good.

Attached is part of a log, showing the errors. What could be done about those?

Also, is there a way to let the task try again for just the missing ones? Now, it just runs for 0 seconds and nothing happens.

I tested with copying one of these files to a new folder and give it a different name (to simulate a new movie), and it errors out again, but at a different chapter.

embyserver.txt

[sa2000 674]

5 hours ago, voodoo5_6k said:

Yesterday, I observed several chapter image extraction operations fail. I end up with a movie having chapter images for like 2/3 of the chapters, with the last 1/3 not having images. So far so... good.

I can see that extraction stopped at certain offset and to the end

These were the offsets for the Star Wars movie

8,21.2,114.6,293.3,448.8,535.2,681.7,923.6,1159.9,1393.3,1512.2,1645.2,1732.3,1933.8,2072.6,2193.8,2325.3,2480.9,2530.4,2639.8,2820.7,2946,3022,3100.7,3108.5,3270.9,3403.8,3641.8,3827.4,3952.9,4203.3,4303.6,4484.8,4600.4,4740.4,4951.3,5073.1,5247.2,5479.2,5651,5737.8,5828.2,5935.5,6008.4,6127.9,6408.1,6744.2,6892.6,6934.2,7039.8

and the failures started at 

2024-05-21 14:18:08.832 Error ChapterImagesTask: Error during chapter image extraction for Star Wars at 5479200ms.
2024-05-21 14:18:08.832 Error ChapterImagesTask: Error during chapter image extraction for Star Wars at 5651000ms.
2024-05-21 14:18:08.832 Error ChapterImagesTask: Error during chapter image extraction for Star Wars at 5737800ms.
2024-05-21 14:18:08.832 Error ChapterImagesTask: Error during chapter image extraction for Star Wars at 5828200ms.
2024-05-21 14:18:08.832 Error ChapterImagesTask: Error during chapter image extraction for Star Wars at 5935500ms.
2024-05-21 14:18:08.832 Error ChapterImagesTask: Error during chapter image extraction for Star Wars at 6008400ms.
2024-05-21 14:18:08.832 Error ChapterImagesTask: Error during chapter image extraction for Star Wars at 6127900ms.
2024-05-21 14:18:08.832 Error ChapterImagesTask: Error during chapter image extraction for Star Wars at 6408100ms.
2024-05-21 14:18:08.832 Error ChapterImagesTask: Error during chapter image extraction for Star Wars at 6744200ms.
2024-05-21 14:18:08.832 Error ChapterImagesTask: Error during chapter image extraction for Star Wars at 6892600ms.
2024-05-21 14:18:08.832 Error ChapterImagesTask: Error during chapter image extraction for Star Wars at 6934200ms.
2024-05-21 14:18:08.832 Error ChapterImagesTask: Error during chapter image extraction for Star Wars at 7039800ms.

I don't know if it is memory related and we will probably need a file to test it out with  and debug - I presume these are huge mkv files?

Would need a file that results in these errors - the smallest file that this happens on. Can you establish how much memory Emby server processes are using at the time of failure  - in case it is memory releated.

Any other log files generated during this ?

And please upload full log files - obtained the Emby Web download logs page.

Edited May 22, 2024 by sa2000

[voodoo5_6k 29]

Thank you for looking into it.

Yes, these are 60+ GB *.mkv. (I can make one of them available privately if desired)

I have renamed the Star Wars one to something that'll never exist in my collection and repeated it. Log attached.

Regarding RAM. This the official TrueNAS SCALE application, running on Dragonfish. The system has a Xeon E-2124G and 96GB ECC RAM. During the image extraction, free RAM went from 6.6GB to 5.1GB while the ZFS cache increased accordingly. One thread was at close to 100%, the rest of the CPU idle. Don't know about the application, but the system was hardly breaking a sweat.

embyserver.txt

[voodoo5_6k 29]

Just rebooted the server and renamed the file to something else again. With empty ZFS cache and 88GB free RAM, the task also fails. Log attached.

embyserver.txt

[Luke 42078]

Is it only happening with videos on the zfs store?

[voodoo5_6k 29]

Hi Luke! Yes, but...

...there is no other storage than ZFS. I use solely ZFS for reliable storage. There are thousands of video files on there for emby (and other stuff like music for JRiver MC etc.), and this here is the first time I notice these errors. Of course I don't know whether this happened before, as I don't have checked all chapters of all files. But I have checked larger *.mkv (approaching 100GB), and there the chapter images are fine (although these files have less chapters than the Star Wars videos here with 50 each). There's also one 4k concert video with almost 3h length which has a lot of chapters (haven't counted), and the images are all there.

I'm thinking of deleting the emby installation, redo everything, and then finally switch on the image extraction, so I'd at least have all errors in one or two log files. Or is there a way to see the errors?

Hypothetically, if a cause for these failures could be found, and that everything would work in terms of image extraction, wouldn't it be good idea to have the scheduled task also address previously failed extractions, rather than ignoring them?

Thanks again.

[voodoo5_6k 29]

To follow up on my thought of the extraction task addressing the missing chapters after a failure, I renamed the file again, and removed all chapters up to the failure point. Running the extraction, all of these formerly failing chapter images are created, and the task finishes. While doing hat, the emby application hovered around 500MB RAM and 25% CPU, according to the TrueNAS application dashboard. Log attached.

Looks almost like a resource issue within the task.

embyserver.txt

[sa2000 674]

6 hours ago, voodoo5_6k said:

To follow up on my thought of the extraction task addressing the missing chapters after a failure, I renamed the file again, and removed all chapters up to the failure point. Running the extraction, all of these formerly failing chapter images are created, and the task finishes. While doing hat, the emby application hovered around 500MB RAM and 25% CPU, according to the TrueNAS application dashboard. Log attached.

Thank you for doing this test - with only 12 chapter images to extract the logs do show completion without error

The logs show that with 50 chapter offsets for image extraction, the process failed after 32 and after 34 and after 38 completed image extractions.

Will need to establish if it is to do with the number of chapters or size of the video file or combination of both.

This shows the analysis of the logs

Edited May 23, 2024 by sa2000

[voodoo5_6k 29]

No problem!

I also have the Star Wars trilogy (2004 Special Edition) as SD version (PAL DVD), ripped to *.mkv. These have the same amount of chapters, and those images are all there, as far as I can tell (I will verify that later). Maybe it's really not the amount of chapters alone...

[sa2000 674]

20 hours ago, voodoo5_6k said:

I can make one of them available privately if desired

We can have a go at this - send me a download link by Private Message for a zip of the smallest file exhibiting this issue

[rbjtech 5284]

I suggest you include @softworkz  The chapter image creation uses various ffmpeg methods to quickly locate the image to grab - so depending on the MKV 'timing' this may be getting stuck or in a loop that it cannot recover from.    If it works on most files but fails on others, I would start looking into file timing construction/corruption as a first step.

My LOTR Return of the King is 140GB with about 70 chapters - no issues with chapter extraction - so I don't believe it's related to file size nor the number of chapters .. ?

[rbjtech 5284]

ah - is this related to multi-version image files (.bif)

https://emby.media/community/index.php?/topic/128934-chapter-image-extraction/&do=findComment&comment=1357150

Has this even been implemented ?  ie you can now have different chapter files for each file version - hence the offsets (as I've never seen those used before in emby) ?

[pwhodges 2012]

3 hours ago, rbjtech said:

ah - is this related to multi-version image files (.bif)

https://emby.media/community/index.php?/topic/128934-chapter-image-extraction/&do=findComment&comment=1357150

Has this even been implemented ?  ie you can now have different chapter files for each file version - hence the offsets (as I've never seen those used before in emby) ?

Only if it was in the last few days...

Paul

[voodoo5_6k 29]

7 hours ago, sa2000 said:

We can have a go at this - send me a download link by Private Message for a zip of the smallest file exhibiting this issue

PM sent. Thank you!

 

3 hours ago, rbjtech said:

ah - is this related to multi-version image files (.bif)

https://emby.media/community/index.php?/topic/128934-chapter-image-extraction/&do=findComment&comment=1357150

Has this even been implemented ?  ie you can now have different chapter files for each file version - hence the offsets (as I've never seen those used before in emby) ?

Not related, but maybe a reason why I just now saw the issue. I split up the grouping, so the UHD versions are now separate from the SD versions. That's when I saw the missing chapter images and started poking around. This also explained why emby ignored the chapter names in those UHD versions... Because it showed the chapter images and names of the SD version (just Chapter xx). See link below, last sentence of the second paragraph in the OP.

 

[rbjtech 5284]

53 minutes ago, voodoo5_6k said:

PM sent. Thank you!

 

Not related, but maybe a reason why I just now saw the issue. I split up the grouping, so the UHD versions are now separate from the SD versions. That's when I saw the missing chapter images and started poking around. This also explained why emby ignored the chapter names in those UHD versions... Because it showed the chapter images and names of the SD version (just Chapter xx). See link below, last sentence of the second paragraph in the OP.

 

so it is related then ?

Until this above mentioned feature is implemented, emby will only use a single version of the bif file and single set of metadata - thus the chapters etc may be wrong depending on what version it is using.

We need @Luketo confirm what he plans to implement here - but I would hope each version 'should' use it's own bif file and show the appropriate metadata and chapter images for each version.

[Luke 42078]

Quote

We need @Luketo confirm what he plans to implement here - but I would hope each version 'should' use it's own bif file and show the appropriate metadata and chapter images for each version.

They do. It's just the UI that needs to be updated to use the chapters applicable to the version being played.

[sa2000 674]

22 hours ago, sa2000 said:

This shows the analysis of the logs

 

An observation ... All those that failed above failed after 5 minutes processing. I wonder if there is a time limit forcing a failed exit after that - just a thought. 

I now have access to the first file on the list above and started to download the zips.

[Luke 42078]

On 5/24/2024 at 5:27 AM, sa2000 said:

An observation ... All those that failed above failed after 5 minutes processing. I wonder if there is a time limit forcing a failed exit after that - just a thought. 

I now have access to the first file on the list above and started to download the zips.

Actually yes there is a time limit of 5 minutes. I guess we should double this.

[rbjtech 5284]

23 minutes ago, Luke said:

Actually yes there is a time limit of 5 minutes. I guess we should double this.

Not sure why you would you put an arbitrary time limit on an extraction process ?   Surely it would be better to base the time limit off the file size and a typical throughput I/O speed ?

So on a 10Gb file -

@ 100 Mbps - 14 mins, 19 seconds

@1000 Mbps - 1 min, 26 seconds

On lets say a typical 4K Remux of 70Gb -

@ 100 Mbps - 1hr, 40 mins, 13 seconds

@1000 Mbps - 10 min, 1 seconds (so yea, 10 mins is actually about right if using over 1Gb Ethernet..  )

But I believe we also need to factor in that the entire file is not being read, it's only actually reading 1 frame every 10 seconds - so assuming it read all the frames for that second, it should read ~ 10 times faster ?

The issue is going to be when you have 'remote' media over say a poor WAN connection.

Maybe you need to make this a configurable item in an XML for those that need to modify/change it ? 

[voodoo5_6k 29]

1 hour ago, Luke said:

Actually yes there is a time limit of 5 minutes. I guess we should double this.

Oh, that's really interesting. Yeah, making it longer, or "flexible" as @rbjtechsuggested, might be good. However, maybe it shouldn't be based on assumed I/O speeds etc. but perhaps the process could monitor itself in terms of whether or not it's actually progressing. Once it gets stuck, then it could be killed off after a configurable amount of time, e.g 1 minute after getting stuck. That way, the process is flexible, yet it won't run forever in case it gets stuck.

[rbjtech 5284]

36 minutes ago, voodoo5_6k said:

Oh, that's really interesting. Yeah, making it longer, or "flexible" as @rbjtechsuggested, might be good. However, maybe it shouldn't be based on assumed I/O speeds etc. but perhaps the process could monitor itself in terms of whether or not it's actually progressing. Once it gets stuck, then it could be killed off after a configurable amount of time, e.g 1 minute after getting stuck. That way, the process is flexible, yet it won't run forever in case it gets stuck.

But how do you know it's 'stuck' vs just being resource contrained ? 

You need to draw the line somewhere - unless you want to do the calculation per item (seems unrealistic) - 10-15 minutes timeout per item does seem reasonable for 4K remux media.   If you are trying to use this type of media over a connection slower than 100Mbit/sec - then you are going to hit normal playback issues anyway - so it's unlikely to be a valid use case.

[voodoo5_6k 29]

4 minutes ago, rbjtech said:

But how do you know it's 'stuck' vs just being resource contrained ? 

You need to draw the line somewhere - unless you want to do the calculation per item (seems unrealistic) - 10-15 minutes timeout per item does seem reasonable for 4K remux media.   If you are trying to use this type of media over a connection slower than 100Mbit/sec - then you are going to hit normal playback issues anyway - so it's unlikely to be a valid use case.

That's right, the "watchdog" needs some sort of criterion to judge this realistically. But anyhow, the technical solution approach is up to someone else, this was just a suggestion

In this case (TrueNAS SCALE, official emby application), for some reason, the process hit the time limit, although the media is "local", i.e. emby has direct host access to the pool, and it itself is running on a separate, all NVMe mirror. So, maybe, there's a resource component after all, contributing to the issue.

[voodoo5_6k 29]

Just saw this here in github for emby server 4.8.8.0:

• Increase image extraction timeout

Cool, looking forward to test it once it reaches TrueNAS SCALE. Thanks @Luke:)

[voodoo5_6k 29]

Finally, I received the update available notification...

Redid the three movies, and the image extraction succeeded. Brilliant, thanks @Luke

Also thanks @sa2000for your help!

Now, all that's missing is the GUI changes in server & client, so that these chapters can actually be used/seen when dealing with multi-version video files grouped together...

embyserver.txt

[voodoo5_6k 29]

As I had reset my server recently, I had the image extraction run again last night. I browsed through the log and saw a few failures, the three The Lord Of The Rings movies, and one episode of Columbo. While investigating with copies of these under different names, I ran the extraction again, and to my astonishment, I saw that all the missing ones had been redone for the original entries.

@LukeIs the task now able to pick up where it errored out? That's a great improvement for the server's robustness.