ffmpeg operation on fuse mount

[Torsten85]

Hi there, I'm trying to convert a movie file which is in a acd cli fuse mount. Ffmpeg failes after some seconds with an "illegal seek" error. This only happens when the new file is also on this mount, so I guess it has to do something with writing to the fuse mount.

I know that partial writes are not possible and that might exactly what ffmpeg does. Is there a workaround for this? Maybe only upload the file when ffmpeg is done?

Converting the file to a location outside of the fuse drive and then uploading it is not possible in my setup.

Thanks in advance Torsten

[bgemmill]

Have a look at my PR #374, it uses write-back caching and there are fewer usage patterns that cause the seek error.

[Torsten85]

@bgemmill thanks for your reply.

Do I have to do something special to get your PR working or just pip3 install --upgrade git+https://github.com/bgemmill/acd_cli.git? I tried it that way and ffmpeg did run as it should, but at the end the acd_cli process (started with acd_cli -nl -d mount -i0 -fg --modules="subdir,subdir=/Test" /Users/torsten/test) did shut down on its own without any error message and without correctly unmounting the mountpoint... the converted file has a size of 0 bytes.

[bgemmill]

pip install as you mentioned, delete your nodes.db and resync (since the PR is handling extra info for each file), and when you mount, try mounting with no extra options first. acdcli mount /some/dir

As far as quitting without errors, if that happens again, can you post the relevant part of ~/.cache/acd_cli/acd_cli.log?

[Torsten85]

@bgemmill I did as you told me and it happened again. Is your PR maybe linux-only? I'm currently on a MacOS machine but will try again on ubuntu tomorrow.

Until then, here are the last lines of the log:

16-12-26 22:34:59.937 [DEBUG] [acdcli.acd_fuse] - -> write /Test/out.mkv (4096, 4096, 3)
16-12-26 22:34:59.937 [DEBUG] [acdcli.acd_fuse] - <- write 4096
16-12-26 22:34:59.937 [DEBUG] [acdcli.acd_fuse] - -> write /Test/out.mkv (4096, 4096, 3)
16-12-26 22:34:59.937 [DEBUG] [acdcli.acd_fuse] - <- write 4096
16-12-26 22:34:59.937 [DEBUG] [acdcli.acd_fuse] - -> write /Test/out.mkv (4096, 4096, 3)
16-12-26 22:34:59.937 [DEBUG] [acdcli.acd_fuse] - <- write 4096
16-12-26 22:34:59.938 [DEBUG] [acdcli.acd_fuse] - -> write /Test/out.mkv (4096, 0, 3)
16-12-26 22:34:59.938 [DEBUG] [acdcli.acd_fuse] - <- write 4096
16-12-26 22:34:59.938 [DEBUG] [acdcli.acd_fuse] - -> getattr /Test/out.mkv (None,)
16-12-26 22:34:59.938 [DEBUG] [acdcli.acd_fuse] - <- getattr {'st_ctime': 1482783565.954, 'st_size': 3180535577, 'st_mode': 33206, 'st_nlink': 1, 'st_atime': 1482788099.938579, 'st_mtime': 1482783566.046}
16-12-26 22:34:59.938 [DEBUG] [acdcli.acd_fuse] - -> flush /Test/out.mkv (3,)
16-12-26 22:34:59.939 [DEBUG] [acdcli.api.backoff_req] - Retry 0, waiting -112.559421s
16-12-26 22:34:59.939 [INFO] [acdcli.api.backoff_req] - PUT "https://content-eu.drive.amazonaws.com/cdproxy/nodes/HBx4yVxVTtq5SS0muOK5jQ/content"
16-12-26 22:34:59.939 [DEBUG] [acdcli.api.backoff_req] - <MultipartEncoder: {('content', ('file.bin', <acdcli.api.content._TeeBufferedReader object at 0x11362e2b0>, 'application/octet-stream'))}>
16-12-26 22:35:00.213 [DEBUG] [acdcli.acd_fuse] - -> access / (0,)
16-12-26 22:35:00.213 [DEBUG] [acdcli.acd_fuse] - <- access 0
16-12-26 22:35:00.306 [DEBUG] [acdcli.acd_fuse] - -> access / (0,)
16-12-26 22:35:00.307 [DEBUG] [acdcli.acd_fuse] - <- access 0
16-12-26 22:35:00.307 [DEBUG] [acdcli.acd_fuse] - -> getxattr / ('com.apple.FinderInfo', 0)
16-12-26 22:35:00.307 [DEBUG] [acdcli.acd_fuse] - <- getxattr 41
16-12-26 22:35:00.550 [DEBUG] [acdcli.acd_fuse] - -> access / (0,)
16-12-26 22:35:00.550 [DEBUG] [acdcli.acd_fuse] - <- access 0
16-12-26 22:35:00.552 [DEBUG] [acdcli.acd_fuse] - -> access / (0,)
16-12-26 22:35:00.552 [DEBUG] [acdcli.acd_fuse] - <- access 0
16-12-26 22:35:30.305 [DEBUG] [acdcli.acd_fuse] - -> access / (0,)
16-12-26 22:35:30.305 [DEBUG] [acdcli.acd_fuse] - <- access 0
16-12-26 22:35:30.306 [DEBUG] [acdcli.acd_fuse] - -> getattr / (None,)
16-12-26 22:35:30.306 [DEBUG] [acdcli.acd_fuse] - <- getattr {'st_nlink': 1, 'st_mtime': 1482779838.278, 'st_ctime': 1360274477.984, 'st_atime': 1482788130.306456, 'st_mode': 16895}
16-12-26 22:35:30.307 [DEBUG] [acdcli.acd_fuse] - -> getxattr / ('com.apple.FinderInfo', 0)
16-12-26 22:35:30.307 [DEBUG] [acdcli.acd_fuse] - <- getxattr 41
16-12-26 22:35:30.520 [DEBUG] [acdcli.acd_fuse] - -> access / (0,)
16-12-26 22:35:30.520 [DEBUG] [acdcli.acd_fuse] - <- access 0
16-12-26 22:35:30.523 [DEBUG] [acdcli.acd_fuse] - -> access / (0,)
16-12-26 22:35:30.523 [DEBUG] [acdcli.acd_fuse] - <- access 0
16-12-26 22:36:00.590 [DEBUG] [acdcli.acd_fuse] - -> destroy / ()
16-12-26 22:36:00.591 [DEBUG] [acdcli.acd_fuse] - <- destroy None

[bgemmill]

My PR should work on any system that supports fuse. From the getattr call it looks like your file is around 3.2G when you're done with it and the upload starts with the PUT log line, and no errors back from amazon is interesting.

Do you see this working with smaller files?

[segin]

EDIT: I told Emby to use broken encoder settings, and it was causing issues unrelated to acd_cli.

I'm using @bgemmill's fork with Emby, but it's not working. Emby uses ffmpeg to transcode media in real-time for streaming.

The relevant logs are:

17-01-03 04:39:01.993 [DEBUG] [acdcli.acd_fuse] - -> getattr / (None,)
17-01-03 04:39:01.994 [DEBUG] [acdcli.acd_fuse] - <- getattr {'st_mtime': 1482930995.525, 'st_nlink': 1, 'st_ctime': 1482922881.616, 'st_mode': 16895, 'st_atime': 1483436341.9944534}
17-01-03 04:39:01.994 [DEBUG] [acdcli.acd_fuse] - -> statfs / ()
17-01-03 04:39:01.995 [DEBUG] [acdcli.acd_fuse] - <- statfs {'f_blocks': 209715200, 'f_bavail': 209543167, 'f_bsize': 524288, 'f_frsize': 524288, 'f_namemax': 256, 'f_bfree': 209543167}
17-01-03 04:39:01.996 [DEBUG] [acdcli.acd_fuse] - -> statfs / ()
17-01-03 04:39:01.996 [DEBUG] [acdcli.acd_fuse] - <- statfs {'f_blocks': 209715200, 'f_bavail': 209543167, 'f_bsize': 524288, 'f_frsize': 524288, 'f_namemax': 256, 'f_bfree': 209543167}
17-01-03 04:39:21.977 [DEBUG] [acdcli.acd_fuse] - -> getattr /TV (None,)
17-01-03 04:39:21.977 [DEBUG] [acdcli.acd_fuse] - <- getattr {'st_mtime': 1482934109.261, 'st_nlink': 1, 'st_ctime': 1482930802.726, 'st_mode': 16895, 'st_atime': 1483436361.9777234}
17-01-03 04:39:21.978 [DEBUG] [acdcli.acd_fuse] - -> getattr /TV/Rick and Morty (None,)
17-01-03 04:39:21.978 [DEBUG] [acdcli.acd_fuse] - <- getattr {'st_mtime': 1482934111.015, 'st_nlink': 1, 'st_ctime': 1482934109.25, 'st_mode': 16895, 'st_atime': 1483436361.9784822}
17-01-03 04:39:21.978 [DEBUG] [acdcli.acd_fuse] - -> getattr /TV/Rick and Morty/Season 1 (None,)
17-01-03 04:39:21.979 [DEBUG] [acdcli.acd_fuse] - <- getattr {'st_mtime': 1482935573.816, 'st_nlink': 1, 'st_ctime': 1482934110.179, 'st_mode': 16895, 'st_atime': 1483436361.9791203}
17-01-03 04:39:21.979 [DEBUG] [acdcli.acd_fuse] - -> getattr /TV/Rick and Morty/Season 1/[pseudo] Rick and Morty S01E01 Pilot [BDRip] [1080p] [h.265].mkv (None,)
17-01-03 04:39:21.979 [DEBUG] [acdcli.acd_fuse] - <- getattr {'st_size': 225895488, 'st_mtime': 1482935526.851, 'st_ctime': 1482935473.071, 'st_mode': 33206, 'st_nlink': 1, 'st_atime': 1483436361.9796846}
17-01-03 04:39:21.979 [DEBUG] [acdcli.acd_fuse] - -> open /TV/Rick and Morty/Season 1/[pseudo] Rick and Morty S01E01 Pilot [BDRip] [1080p] [h.265].mkv ('0x8000',)
17-01-03 04:39:21.979 [DEBUG] [acdcli.acd_fuse] - <- open 6
17-01-03 04:39:21.989 [DEBUG] [acdcli.acd_fuse] - -> flush /TV/Rick and Morty/Season 1/[pseudo] Rick and Morty S01E01 Pilot [BDRip] [1080p] [h.265].mkv (6,)
17-01-03 04:39:21.989 [DEBUG] [acdcli.acd_fuse] - <- flush None
17-01-03 04:39:21.989 [DEBUG] [acdcli.acd_fuse] - -> release /TV/Rick and Morty/Season 1/[pseudo] Rick and Morty S01E01 Pilot [BDRip] [1080p] [h.265].mkv (6,)
17-01-03 04:39:21.989 [DEBUG] [acdcli.acd_fuse] - <- release None

Emby envokes ffmpeg as: /usr/bin/ffmpeg -ss 00:00:09.000 -codec:0 hevc -codec:1 aac -codec:2 aac -codec:5 mjpeg -i file:"/home/acd/TV/Rick and Morty/Season 1/[pseudo] Rick and Morty S01E01 Pilot [BDRip] [1080p] [h.265].mkv" -map_metadata -1 -map_chapters -1 -threads 0 -map 0:0 -map 0:1 -map -0:s -codec:v:0 h264_omx -maxrate 2735012 -bufsize 5470024 -vsync -1 -force_key_frames "expr:gte(t,n_forced*3)" -flags -global_header -copyts -codec:a:0 aac -strict experimental -ac 6 -ab 192000 -af "adelay=1,aresample=async=1" -max_delay 5000000 -avoid_negative_ts disabled -start_at_zero -hls_time 3 -start_number 3 -hls_list_size 0 -y "/var/lib/emby-server/transcoding-temp/638d7bf15fe131ad7a873037b3b5a0ca.m3u8"

[bgemmill]

@segin From the log, I see emby using an open, flush, close chain of calls on the mount, with no writes. Is that what you meant by broken encoder settings?

[segin]

@bgemmill - Emby was invoking 'ffmpeg' and telling it to use the OMX video acceleration libraries, which were not installed. I didn't notice this until I went digging around for further logs from Emby, ffmpeg, etc.

As such, ffmpeg simply errored out instead of actually doing anything, and Emby would appear to have been broken.

I didn't notice this behaviour until I started using acd_cli, so I had assumed reading media using acd_cli's FUSE mount was the direct cause.

Since it was Emby passing bad encoder settings to ffmpeg causing the problems, and in a way that's nothing to do with acd_cli, please disregard entirely.