getLastCommandOutput() returns incomplete result after execution

[iammert]

Description
FFmpeg.getLastCommandOutput() returns incomplete result after execution. But Config.enableLogCallback{ } still emitting values and complete values after execution is completed.

Expected behavior
I think FFmpeg.getLastCommandOutput() should return complete result if it is called after FFmpeg.execute() operation is complete. And also Config.enableLogCallback{ } should stop emitting value after FFmpeg.execute() operation returns a value.

Code Sample

Config.enableLogCallback {
        Log.v(TAG, "Logging: ${FFmpeg.getLastCommandOutput().contains("Audio")"}
}
        
val result = FFmpeg.execute(command)
Log.v(TAG, "Result: ${FFmpeg.getLastCommandOutput().contains("Audio")"}

Output:

Logging: false
...
Logging: false
Result: false
Logging: false
...
Logging: true
...
Logging: true

Environment

• Platform: Android
• Architecture: arm64-v8a

[tanersener]

I never experienced this behavior but technically it can happen. Unfortunately, there is not an easy solution for this.

MobileFFmpeg uses an internal queue to collect ffmpeg logs and distributes collected logs using a dedicated thread (callback thread). This dedicated thread is responsible of invoking both Log Callback and Statistics Callback functions.

In your case, when execute process has finished, there are still ffmpeg logs waiting in the queue. They are not distributed by the callback thread and last command output is not complete yet. This can happen if Callback Thread can not distribute collected logs fast enough because of the following reasons:

1. Your command generates too much logs
2. You are doing too much work in LogCallback and/or StatisticsCallback callback functions

Can you give me more details about the command you use? I tried to reproduce this issue locally but I wasn't successful.

[iammert]

Actually, I am not doing too much work inside LogCallback. I am just notifying listener to cancel the notification. So we can eliminate the second reason.

So when we back to the first reason you gave, It might be the reason. We are using FFmpeg in our Video Editor project which is not a simple video editor. So user can combine, crop, filter, resize videos and audios, also command script has lots of input including, gifs, overlay images, audios, etc.

But, besides all, I think, execute() operation has to wait for all other logging threads or drop invalid logs and emit last possible and complete log when it is completed. By the way, I don't know if it is possible on your library side.

I believe you can reproduce this issue locally by using my command script, but as I said before, I have lots of params. So It is really hard to attach all files with my script here. But here is the script in case you can find some clue about the situation.

(Reformatted for readability)

-i
/storage/emulated/0/Download/SampleVideo_1280x720_30mb.mp4
-i
/storage/emulated/0/Download/SampleVideo_1280x720_30mb.mp4
-f
lavfi
-t
0.1
-i
anullsrc
-ignore_loop
0
-i
/data/user/0/com.lyrebirdstudio.videoeditor/files/STCKR_1564141463093_1.gif
-ignore_loop
0
-i
/data/user/0/com.lyrebirdstudio.videoeditor/files/STCKR_1564141465389_5.gif
-ignore_loop
0
-i
/data/user/0/com.lyrebirdstudio.videoeditor/files/STCKR_1564141465875_6.gif
-i
/storage/emulated/0/video_editor/collection/music/Air.mp3
-i
/data/user/0/com.lyrebirdstudio.videoeditor/files/FILIGRAN_480.png
-filter_complex
[0:v]trim=69.183:170.859,setpts=1.0*(PTS-STARTPTS)[trimVideo0]
[1:v]transpose=1,trim=69.183:170.859,setpts=0.5*(PTS-STARTPTS)[trimVideo1]
[trimVideo0]split=2[trimVideo0][trimVideoCopy0]
[trimVideo0]scale=640.0:-2[scaledVideo0]
[trimVideoCopy0]scale=-2:480.0,setsar=1,crop=w=640.0:h=480.0,boxblur=luma_radius=min(h\,w)/26:luma_power=3:chroma_radius=min(cw\,ch)/26:chroma_power=1[scaledVideoBackground0]
[scaledVideoBackground0][scaledVideo0]overlay=0.0:60.0[scaledVideoResult0]
[trimVideo1]split=2[trimVideo1][trimVideoCopy1]
[trimVideo1]scale=-2:480.0[scaledVideo1]
[trimVideoCopy1]scale=640.0:-2,setsar=1,crop=w=640.0:h=480.0,boxblur=luma_radius=min(h\,w)/40:luma_power=3:chroma_radius=min(cw\,ch)/40:chroma_power=1[scaledVideoBackground1]
[scaledVideoBackground1][scaledVideo1]overlay=370.0:0.0[scaledVideoResult1]
[0:a]atrim=69.183:170.859,aformat=sample_fmts=fltp:sample_rates=44100:channel_layouts=stereo,volume=1.0,asetpts=PTS-STARTPTS,atempo=1.0[trimVideoAudio0]
[scaledVideoResult0]curves=psfile=/data/user/0/com.lyrebirdstudio.videoeditor/files/c3.acv[scaledVideoResult0]
[scaledVideoResult0][trimVideoAudio0][scaledVideoResult1][2:a]concat=n=2:v=1:a=1[v][a]
[3:v]crop=w=640.0:h=480.0[sticker3]
[v][sticker3]overlay=0:0:enable=between(t\,0.0\,152.514):shortest=1[v]
[4:v]crop=w=640.0:h=480.0[sticker4]
[v][sticker4]overlay=0:0:enable=between(t\,0.0\,152.514):shortest=1[v]
[5:v]crop=w=640.0:h=480.0[sticker5]
[v][sticker5]overlay=0:0:enable=between(t\,0.0\,152.514):shortest=1[v]
[6:a]aformat=sample_fmts=fltp:sample_rates=44100:channel_layouts=stereo,volume=1.0,atrim=0.712:44.712,asetpts=PTS-STARTPTS,adelay=0|0[audioResult6]
[a][audioResult6]amix=2[a]
[v][7:v]overlay=x=(main_w-overlay_w):y=(main_h-overlay_h)[v]
-map
[v]
-map
[a]
-preset
superfast
-crf
17
-codec:v
libx264
-codec:a
aac
-pix_fmt
yuv420p
/storage/emulated/0/video_editor/20190822_102218.mp4

I did a little hack. (Thread.sleep(400) after execute() command has finished) It is working for now. But it is a workaround. I am really appreciated If you find out a fix for the problem.

[tanersener]

Thanks.

First versions of the library didn't have a queue and a callback thread. So technically, execute was waiting for all logging to complete. The problem was that design was decreasing execution time significantly and users who wasn't interested in logs complained too much about the speed. This is why I implemented a queue and a callback thread.

I don't want to change the current design but I agree that getLastCommandOutput should be improved and always return full output. I'll work on it.

However, improving getLastCommandOutput won't solve your issues and you'll still need to sleep/wait after execute. I don't know how can I improve that. I have a similar case inside the library and I'm solving it inside the Config.systemExecute function. It is doing what you're currently doing.

[tanersener]

Fixed in the development branch.