search

nschlia / ffmpegfs

FUSE-based transcoding filesystem with video support from many formats to FLAC, MP4, TS, WebM, OGG, MP3, HLS, and others.
https://nschlia.github.io/ffmpegfs/
GNU General Public License v3.0
198 stars 14 forks source link

Partial transcode of some files #22

Closed lenzj closed 5 years ago

lenzj commented 5 years ago

I'm having an issue and I'm not sure if it's in the settings I've chosen or if it's a bug in ffmpegfs. When transcoding a flac file to opus the last few seconds of the audio file are missing. If I recopy the file immediately afterwards it results in a flawless transcode, so it only happens during the first transcode. The second copy pulls from the ffmpegfs cache I believe. My fstab entry is as follows:

ffmpegfs#/path/to/flacdir /path/to/opusdir fuse allow_other,ro,desttype=opus,audiobitrate=96K 0 0

Any suggestions would be greatly appreciated. If you need me to run additional test scenarios to debug this just let me know.

Below is the version I'm running (git commit 95993f0).

Built with : gcc 7.3.0 (linux-gnu) configuration : --prefix=/nix/store/0mknxlcypy082jnzq5dzp45fhf7b6nld-ffmpegfs-95993f0 FFMPEGFS Version : 1.6 FFmpeg Version : 3.4.4 Video CD Library : enabled DVD Library : enabled Bluray Library : 1.0.2 FUSE library version: 2.9.8 fusermount version: 2.9.8 using FUSE kernel interface version 7.19

nschlia commented 5 years ago

Maybe an old problem I had reappeared...

Please set the logging level to at least INFO and check these message like:

Predicted/final size: 6626133/6482597 bytes, diff: -143536 (98.3%%).

Almost probably, if the diff is > 0, during first transcode it sends out only the predicted amount of bytes, resulting in some time to be cut off. When you access the file again it comes from cache and the file size is correct, thus nothing is missing.

So if for cut files the diff is always positive while if the files are not truncated negative it's that old bug again. I'll check to see what's happened.

lenzj commented 5 years ago

OK, I think I have the scenario pinned down that creates this issue. It appears to happen when the bandwidth is limited on the output stream. I was copying files over the network and seeing the issue, but the issue went away when I tried to replicate directly on the source machine (no network in between).

I was able to turn the problem on and off on the local machine using rsync with and without the bandwidth limiting parameter (--bwlimit).

First I used the following two commands to remove the cache and start ffmpegfs from a clean slate before each of the test scenarios below:

sudo rm -Rf /tmp/ffmpegfs/*
sudo ffmpegfs -d -f --audiobitrate=96k --desttype=OPUS --log_stderr --log_maxlevel=INFO /path/to/flac /path/to/opus -o allow_other,ro

Use case 1 - Rate limited using rsync with local copy. Opus file is cut short:

rsync -av --bwlimit=100 /path/to/opusfile /path/to/outputfile

full log output in link below: https://pastebin.com/eA6RqJEd

Use case 2 - No rate limit. Opus file is fine:

rsync -av /path/to/opusfile /path/to/outputfile

full log output in link below: https://pastebin.com/Mfm8ih1b

Other observations in logs I'm not sure if it's relevant to this issue or not but there were some errors such as the following in the log output as well:

unique: 4, opcode: ACCESS (34), nodeid: 3, insize: 48, pid: 2392
  unique: 4, error: -38 (Function not implemented), outsize: 16
nschlia commented 5 years ago

Thanks, these are a lot of leads to follow. I'll try to figure out what happens.

nschlia commented 5 years ago

So far I could not find a reason, do you access ffmpegfs directly or via Samba? If so, did you enable aio for your share?

 oplocks = no
 aio read size = 1

I currently added this option (reasons see #23) but it appears the problem is still there.

lenzj commented 5 years ago

Thanks for asking / checking, but no I do not use Samba. I was accessing ffmpegfs directly on the host computer. It sounds like you were able to recreate the issue as well? I was curious whether it was something just with my setup or if it occurs for you also.

lenzj commented 5 years ago

I ran quite a few more tests and the issue is still there with the latest commit 80d5e13, however I think I misstated case 2 above. The issue appears to always happen for me when using rsync whether the --bwlimit option is there or not. When I use the standard "cp" command, the copy is good, but when I use "rsync" it crops the file short. The two commands seem to access and copy the file differently.

When I use "ls -l" on the ffmpegfs directory before copying the file it displays the shorter cropped file size. After copying the file out and re-running "ls -l" on the ffmpegfs directory, the file size is the correct final size. The rsync command creates a file exactly the same size as listed in the initial directory listing. I'm guessing the rsync command copies and stops based on the size of the file it sees initially, whereas cp probably ignores the initial file size and just keeps copying until EOF is reached.

On a related note, I tried this mounting as flac->mp3 and observed the exact same issue, so it doesn't appear that it's just an opus issue.

Hopefully this is helpful. I'm wondering if ffmpegfs was adjusted such that it always makes the initial file size estimate slightly larger rather than slightly smaller if that would solve this? I tried using the --disable_cache option as well but that didn't help this issue.

If I'm trying to do something that ffmpegfs isn't designed to do then maybe just putting warnings in with respect to use of certain file access methods or utilities would cover this. Thanks!

nschlia commented 5 years ago

Thanks for your patience. You are not using ffmpegs the wrong way. It is designed to expose the files in a transparent way, i.e., as if they were really there.

My tests revealed that rsync seems to handle the files in an incompatible way. It seems to do a prescan, then copy them (but of course it won't get what it expected). I'm not sure if I can fix that but I will try for some future release. I always had to run rsync twice so that it got files from cache. Copying while transcoding did not work well.

I already added a safety margin to the size prediction, about 5%, but this can cause another problem I was hunting after the last days in issue #23 : Some applications scan the end of the file, then read it from the beginning and that sometimes ends in an error 2 (file not found) when the file size is actually smaller than expected, but the app is trying to read on. Issue #23 caused Samba to lock all shares for the workstation that read the file (causing "Application not responding" messages galore). This was a big problem for me so it kept me busy :)

If you do "ls -l" for the first time you'll get the predicted sizes. When you cp a file, you will get the real size from then on (and the fully recoded file from cache when doing another cp). With the --disable_cache option the file will be recoded over, but the correct file size from the first recode is still cached for "ls -l" etc.

What's strange is, if you do cp and the file is smaller as predicted, you either get the correctly sized file, or one that's as large as predicted but stuffed with zeros at the end. If the file is large, you may get a file that's missing the end or the correct size.

In both cases you either get the correct file or not. I could not find out what's the cause.

So far I only had the problem via Samba so I suspected something with the Samba server. As you said, the problem is the same when ffmpegs is accessed locally. This is an important observation, I'll try to recreate that here. Seems to be caused by fuse and that also explains why it is not only happening with Opus.

nschlia commented 5 years ago

Tested with:

Built with : gcc 6.3.0 20170516 (linux-gnu) configuration : --no-create --no-recursion

FFMPEGFS Version : 1.6 FFmpeg Version : 3.2.12-1~deb9u1 Video CD Library : enabled DVD Library : enabled Bluray Library : 0.9.3 FUSE library version: 2.9.7 fusermount version: 2.9.7 using FUSE kernel interface version 7.19

Real data test

Log excerpt of copying a DVD:

Log Info
2018-12-30 21:36:42 DEBUG : [01. Chapter 001.webm] Predicted transcoded size of 130355 bytes.
2018-12-30 21:36:42 DEBUG : [02. Chapter 001.webm] Predicted transcoded size of 6609381 bytes.
2018-12-30 21:36:42 DEBUG : [03. Chapter 001.webm] Predicted transcoded size of 3466754 bytes.
2018-12-30 21:36:42 DEBUG : [04. Chapter 001.webm] Predicted transcoded size of 532611944 bytes.
2018-12-30 21:36:42 DEBUG : [04. Chapter 002.webm] Predicted transcoded size of 98098 bytes.
2018-12-30 21:36:42 DEBUG : [05. Chapter 001.webm] Predicted transcoded size of 5490482 bytes.
2018-12-30 21:36:42 DEBUG : [06. Chapter 001.webm] Predicted transcoded size of 5665183 bytes.
2018-12-30 21:36:42 DEBUG : [06. Chapter 002.webm] Predicted transcoded size of 103833538 bytes.
2018-12-30 21:36:42 DEBUG : [06. Chapter 003.webm] Predicted transcoded size of 97153694 bytes.
2018-12-30 21:36:42 DEBUG : [06. Chapter 004.webm] Predicted transcoded size of 83624893 bytes.
2018-12-30 21:36:42 DEBUG : [06. Chapter 005.webm] Predicted transcoded size of 115586685 bytes.
2018-12-30 21:36:42 DEBUG : [06. Chapter 006.webm] Predicted transcoded size of 113895584 bytes.
2018-12-30 21:36:42 DEBUG : [06. Chapter 007.webm] Predicted transcoded size of 96900028 bytes.
2018-12-30 21:36:42 DEBUG : [06. Chapter 008.webm] Predicted transcoded size of 101804219 bytes.
2018-12-30 21:36:42 DEBUG : [06. Chapter 009.webm] Predicted transcoded size of 69673319 bytes.
2018-12-30 21:36:42 DEBUG : [06. Chapter 010.webm] Predicted transcoded size of 90812069 bytes.
2018-12-30 21:36:42 DEBUG : [06. Chapter 011.webm] Predicted transcoded size of 113219145 bytes.
2018-12-30 21:36:42 DEBUG : [06. Chapter 012.webm] Predicted transcoded size of 108484063 bytes.
2018-12-30 21:36:42 DEBUG : [06. Chapter 013.webm] Predicted transcoded size of 98083799 bytes.
2018-12-30 21:36:42 DEBUG : [06. Chapter 014.webm] Predicted transcoded size of 236697 bytes.
2018-12-30 21:36:42 DEBUG : [07. Chapter 001.webm] Predicted transcoded size of 19151707 bytes.
2018-12-30 21:36:42 DEBUG : [01. Chapter 001.webm] Predicted/final size: 130355/5958 bytes, diff: -124397 (5%). OK
2018-12-30 21:36:44 DEBUG : [02. Chapter 001.webm] Predicted/final size: 6609381/5149724 bytes, diff: -1459657 (78.4%). OK
2018-12-30 21:36:46 DEBUG : [03. Chapter 001.webm] Predicted/final size: 3466754/3257027 bytes, diff: -209727 (94.4%). OK
2018-12-30 21:38:29 DEBUG : [04. Chapter 002.webm] Predicted/final size: 98098/21403 bytes, diff: -76695 (22.3%). OK
2018-12-30 21:38:31 DEBUG : [05. Chapter 001.webm] Predicted/final size: 5490482/1966632 bytes, diff: -3523850 (36.3%). OK
2018-12-30 21:38:37 DEBUG : [06. Chapter 001.webm] Predicted/final size: 5665183/21045669 bytes, diff: 15380486 (371.9%). cut/stuffed, fully decoded
2018-12-30 21:38:44 INFO : [04. Chapter 001.webm] Suspend timeout. Transcoding suspended after 15 seconds inactivity. cut/stuffed, real size 2.5 GB
2018-12-30 21:38:59 WARNING: [04. Chapter 001.webm] Timeout! Transcoding aborted after 30 seconds inactivity.
2018-12-30 21:39:37 DEBUG : [06. Chapter 002.webm] Predicted/final size: 103833538/90858822 bytes, diff: -12974716 (88%). OK
2018-12-30 21:40:37 DEBUG : [06. Chapter 003.webm] Predicted/final size: 97153694/91615933 bytes, diff: -5537761 (94.7%). OK
2018-12-30 21:41:27 DEBUG : [06. Chapter 004.webm] Predicted/final size: 83624893/71516319 bytes, diff: -12108574 (86%). OK
2018-12-30 21:42:34 DEBUG : [06. Chapter 005.webm] Predicted/final size: 115586685/101991213 bytes, diff: -13595472 (88.7%). OK
2018-12-30 21:43:47 DEBUG : [06. Chapter 006.webm] Predicted/final size: 113895584/100402315 bytes, diff: -13493269 (88.6%). OK
2018-12-30 21:44:47 DEBUG : [06. Chapter 007.webm] Predicted/final size: 96900028/86758963 bytes, diff: -10141065 (90%). OK
2018-12-30 21:45:47 DEBUG : [06. Chapter 008.webm] Predicted/final size: 101804219/89165431 bytes, diff: -12638788 (88%). OK
2018-12-30 21:46:32 DEBUG : [06. Chapter 009.webm] Predicted/final size: 69673319/61580237 bytes, diff: -8093082 (88.8%). OK
2018-12-30 21:47:28 DEBUG : [06. Chapter 010.webm] Predicted/final size: 90812069/84235089 bytes, diff: -6576980 (93.2%). OK
2018-12-30 21:48:38 DEBUG : [06. Chapter 011.webm] Predicted/final size: 113219145/96416109 bytes, diff: -16803036 (85.6%). OK
2018-12-30 21:49:41 DEBUG : [06. Chapter 012.webm] Predicted/final size: 108484063/91748897 bytes, diff: -16735166 (85%). OK
2018-12-30 21:50:46 DEBUG : [06. Chapter 013.webm] Predicted/final size: 98083799/90938587 bytes, diff: -7145212 (93.2%). OK
2018-12-30 21:50:47 DEBUG : [06. Chapter 014.webm] Predicted/final size: 236697/20660 bytes, diff: -216037 (9.2%). OK
2018-12-30 21:50:56 DEBUG : [07. Chapter 001.webm] Predicted/final size: 19151707/15297599 bytes, diff: -3854108 (80.3%). OK

Results

Windows over Samba

copy

Verification fails with "WARNING: 06. Chapter 009.webm failed verification -- update discarded (will try again)."

See rsync.log.

nschlia commented 5 years ago

The cut ends I experienced come from the access method: I play the files over a web server, the webserver accesses the files via Samba on a different machine. Files that are larger than predicted (i.e. like 04. Chapter 001.webm and 06. Chapter 001.webm) are cut short. When played again (from cache) they are OK.

Unfortunately I can't recreate the problem on my side, when using "cp" I even got the 2.5 GB file ist properly copied, although the prediction is totally wrong (the file has 500% of the predicted size):

Predicted/final size: 532611944/2690554117 bytes, diff: 2157942173 (505.6%).

lenzj commented 5 years ago

Yes, "cp" works well for me also. I see the issue of the shortened file when using rsync. If the file size is changing in real time during rsync access it only copies what it sees initially and ignores changes in file size after start of copy. For example I found the following link which talks about copying an Apache log file that is still being written while rsync is copying. The first two paragraphs in the answer are the relevant parts. [https://superuser.com/questions/847850/behavior-of-rsync-with-file-thats-still-being-written]()

I noticed also that mp3fs only supports constant bit rate (CBR) files which makes it possible to exactly predict the file size at the beginning of copy. I'm assuming khenricks made that decision to avoid some of the challenges we are experiencing here. Would it be possible to add the option to use CBR?

nschlia commented 5 years ago

CBR is not an option because mp3 is the only format that actually uses that. WebM, Opus, mp4 etc. are VBR by default. Some of these formats offer something similar to CBR but that will create ridicously large files (a 10 second silence will create a file as large as one with a symphony orchestra playing vivacissimo). The only way to create CBR files with ffmpegfs is to use mp3...

I've tested the --inplace parameter as suggested by the link, and played around with --whole-file and --checksum.

With --inplace the files are first copied with their predicted size (smaller files stuffed with zeros), in the second phase the smaller once are reset to the correct size. The bigger ones also, if recoded before time out (when the recode times out the result is a file with arbitrary length). So if no file is too large to be recoded without timeout, all is OK. The error messages are similar to those in rsync.log.

With -whole-file/--checksum building the incremental file list takes very long because rsync waits until all files are recoded, the copies them. The result is the same - timeout files are cut, all others are OK.

It appears that rsync is not an option to copy files from ffmpegfs. I'll add that to the documentation.

My recommendation is to use

cp -uv /path/to/source /path/to/target

(optionally with the -r parameter)

lenzj commented 5 years ago

OK, sounds good. Thanks for the quick follow up.

nschlia commented 5 years ago

Thanks for you help and patience. Sorry I could not help, but this is not something I can fix on my side. I'll close this one now.

I added some info to the readme about the issue.