Issue: iOS real device test recording shorter than intended

Have no problem with 12 phones on one macMini.

  1. I use a bit other port combination:
    public AppiumDriverPorts(int appium) {
        this.appium = appium;
        this.wda = appium + 100;
        this.video = appium + 200;
        this.chrome = appium + 400;
        this.system = appium + 400;
    }
  1. do not use webkitDebugProxyPort
  2. appium logs are always ‘ERROR’ (not sure if important)
  3. do not use robot-address
  4. showIOSLog and showXcodeLog disabled all time. enabling only when have issue to get logs.

I have determined its not an issue with parallel testing, the same device using the same wda build sometimes (about 1 out of 10 times) at some point during the test closes the mjpeg server port for some reason and I get this error:

2022-01-08 16:10:48:069 [[email protected]:4733] Connection was refused to port 4733
2022-01-08 16:10:49:972 [ffmpeg] [http @ 0x7fc55ea04400] Stream ends prematurely at 286003269, should be 18446744073709551615
2022-01-08 16:10:49:972 [ffmpeg] 
2022-01-08 16:10:49:977 [ffmpeg] [mjpeg @ 0x7fc55d815600] overread 8
2022-01-08 16:10:49:977 [ffmpeg] [mjpeg @ 0x7fc55d815600] EOI missing, emulating
2022-01-08 16:10:50:033 [ffmpeg] http://127.0.0.1:4733: Input/output error
2022-01-08 16:10:50:034 [ffmpeg] 
2022-01-08 16:10:50:122 [[email protected]:4733] Connection was refused to port 4733
2022-01-08 16:10:52:429 [[email protected]:4733] Connection was refused to port 4733
2022-01-08 16:10:55:640 [[email protected]:4733] Connection was refused to port 4733
2022-01-08 16:10:59:795 [[email protected]:4733] Connection was refused to port 4733
2022-01-08 16:11:04:952 [[email protected]:4733] Connection was refused to port 4733
2022-01-08 16:11:29:116 [[email protected]:4733] Connection was refused to port 4733
2022-01-08 16:11:36:277 [[email protected]:4733] Connection was refused to port 4733
2022-01-08 16:11:54:301 [[email protected]:4733] Connection was refused to port 4733
2022-01-08 16:12:03:352 [[email protected]:4733] Connection was refused to port 4733
2022-01-08 16:12:13:504 [[email protected]:4733] Connection was refused to port 4733
2022-01-08 16:12:23:830 [[email protected]:4733] Connection was refused to port 4733

log of this run https://gist.github.com/sSpockderpantss/eb2d37319dcd18658bd52c7dcc79dba4

Maybe change ffmpeg version?
Also i see it quite problem of ffmpeg. What bitrate you are using?

One of suggestion given is increase bitrate.

I installed ffmpeg 2.8, I can’t change the bitrate because that is handled by appium in the backend right?

Log shows no errors, but video ends halfway through the test. Logs: https://gist.github.com/sSpockderpantss/fd66eb2ab026c6e1a40aa5da7e27cb40

steps to replicate:

  • start recording for 10 mins on real ios device (possibly only happens with python client, I have not tested other clients)
  • look at recording

try more than once if it doesn’t happen the first time

With ios you can change many things including bitrate.

https://appium.io/docs/en/commands/device/recording-screen/start-recording-screen/

I see, the bitrate argument is Android only, if you mean the FPS then I did try 20 fps and 30fps and 40fps, this changes the duration yes, but it does not change the starting point and ending point. The issue I have is the end point is not in the video because the recording stops too soon.

maybe it help - I use:

new IOSStartScreenRecordingOptions()
                            .withFps(24)
                            .withVideoScale("320:-2")
                            .withVideoType("h264") // require ffmpeg
                            .withTimeLimit(Duration.ofMinutes(10)));

and mine version is ffmpeg version 4.1.1

BTW: withTimeLimit The default value is 180 seconds (3 minutes)!

updated ffmpeg to version 4.4.1, used the following as suggested:

        args = dict(
            forceRestart=True,
            timeLimit=60 * 10,
            videoType='h264',
            videoFps=24,
            videoScale="320:-2"
        )

        self.appium_driver.start_recording_screen(**args)

recordings are no longer too short!! however, some recordings don’t even open (tried with divx player and tried with vlc)

vlc gives this log:


main debug: processing request item: recording_0.mp4, node: Playlist, skip: 0
main debug: rebuilding array of current - root Playlist
main debug: rebuild done - 2 items, index 1
main debug: starting playback of new item
main debug: resyncing on recording_0.mp4
main debug: recording_0.mp4 is at 1
main debug: creating new input thread
main debug: Creating an input for 'recording_0.mp4'
main debug: requesting art for new input thread
main debug: using timeshift granularity of 50 MiB
main debug: using timeshift path: C:\Users\G4G\AppData\Local\Temp
main debug: `file:///C:/Users/G4G/Desktop/New%20folder/recording_0.mp4' gives access `file' demux `any' path `/C:/Users/G4G/Desktop/New%20folder/recording_0.mp4'
main debug: creating demux: access='file' demux='any' location='/C:/Users/G4G/Desktop/New%20folder/recording_0.mp4' file='C:\Users\G4G\Desktop\New folder\recording_0.mp4'
main debug: looking for access_demux module matching "file": 15 candidates
main debug: looking for meta fetcher module matching "any": 1 candidates
main debug: no access_demux modules matched
main debug: creating access: file:///C:/Users/G4G/Desktop/New%20folder/recording_0.mp4
main debug: (path: C:\Users\G4G\Desktop\New folder\recording_0.mp4)
main debug: looking for access module matching "file": 27 candidates
main debug: using access module "filesystem"
main debug: looking for stream_filter module matching "prefetch,cache_read": 24 candidates
cache_read debug: Using stream method for AStream*
cache_read debug: starting pre-buffering
cache_read debug: received first data after 0 ms
cache_read debug: pre-buffering done 1024 bytes in 0s - 1000000 KiB/s
main debug: using stream_filter module "cache_read"
main debug: looking for stream_filter module matching "any": 24 candidates
lua debug: Trying Lua scripts in C:\Users\G4G\AppData\Roaming\vlc\lua\meta\fetcher
lua debug: Trying Lua scripts in C:\Program Files\VideoLAN\VLC\lua\meta\fetcher
main debug: no meta fetcher modules matched
main debug: looking for art finder module matching "any": 2 candidates
lua debug: Trying Lua scripts in C:\Users\G4G\AppData\Roaming\vlc\lua\playlist
lua debug: Trying Lua scripts in C:\Program Files\VideoLAN\VLC\lua\playlist
lua debug: Trying Lua playlist script C:\Program Files\VideoLAN\VLC\lua\playlist\anevia_streams.luac
lua debug: Trying Lua playlist script C:\Program Files\VideoLAN\VLC\lua\playlist\anevia_xml.luac
lua debug: Trying Lua scripts in C:\Users\G4G\AppData\Roaming\vlc\lua\meta\art
lua debug: Trying Lua scripts in C:\Program Files\VideoLAN\VLC\lua\meta\art
lua debug: Trying Lua playlist script C:\Program Files\VideoLAN\VLC\lua\meta\art\00_musicbrainz.luac
lua debug: Trying Lua playlist script C:\Program Files\VideoLAN\VLC\lua\playlist\appletrailers.luac
lua debug: skipping script (unmatched scope) C:\Program Files\VideoLAN\VLC\lua\meta\art\00_musicbrainz.luac
lua debug: Trying Lua playlist script C:\Program Files\VideoLAN\VLC\lua\meta\art\01_googleimage.luac
lua debug: Trying Lua playlist script C:\Program Files\VideoLAN\VLC\lua\playlist\bbc_co_uk.luac
lua debug: skipping script (unmatched scope) C:\Program Files\VideoLAN\VLC\lua\meta\art\01_googleimage.luac
lua debug: Trying Lua playlist script C:\Program Files\VideoLAN\VLC\lua\meta\art\02_frenchtv.luac
lua debug: Trying Lua playlist script C:\Program Files\VideoLAN\VLC\lua\playlist\cue.luac
lua debug: skipping script (unmatched scope) C:\Program Files\VideoLAN\VLC\lua\meta\art\02_frenchtv.luac
lua debug: Trying Lua playlist script C:\Program Files\VideoLAN\VLC\lua\meta\art\03_lastfm.luac
lua debug: Trying Lua playlist script C:\Program Files\VideoLAN\VLC\lua\playlist\dailymotion.luac
lua debug: skipping script (unmatched scope) C:\Program Files\VideoLAN\VLC\lua\meta\art\03_lastfm.luac
main debug: no art finder modules matched
lua debug: Trying Lua playlist script C:\Program Files\VideoLAN\VLC\lua\playlist\jamendo.luac
qt debug: IM: Setting an input
lua debug: Trying Lua playlist script C:\Program Files\VideoLAN\VLC\lua\playlist\koreus.luac
lua debug: Trying Lua playlist script C:\Program Files\VideoLAN\VLC\lua\playlist\liveleak.luac
lua debug: Trying Lua playlist script C:\Program Files\VideoLAN\VLC\lua\playlist\newgrounds.luac
lua debug: Trying Lua playlist script C:\Program Files\VideoLAN\VLC\lua\playlist\rockbox_fm_presets.luac
lua debug: Trying Lua playlist script C:\Program Files\VideoLAN\VLC\lua\playlist\soundcloud.luac
lua debug: Trying Lua playlist script C:\Program Files\VideoLAN\VLC\lua\playlist\twitch.luac
lua debug: Trying Lua playlist script C:\Program Files\VideoLAN\VLC\lua\playlist\vimeo.luac
lua debug: Trying Lua playlist script C:\Program Files\VideoLAN\VLC\lua\playlist\vocaroo.luac
lua debug: Trying Lua playlist script C:\Program Files\VideoLAN\VLC\lua\playlist\youtube.luac
main debug: no stream_filter modules matched
main debug: looking for stream_directory module matching "any": 1 candidates
main debug: no stream_directory modules matched
main debug: attachment of directory-extractor failed for file:///C:/Users/G4G/Desktop/New%20folder/recording_0.mp4
main debug: looking for stream_filter module matching "record": 24 candidates
main debug: using stream_filter module "record"
main debug: creating demux: access='file' demux='any' location='/C:/Users/G4G/Desktop/New%20folder/recording_0.mp4' file='C:\Users\G4G\Desktop\New folder\recording_0.mp4'
main debug: looking for demux module matching "mp4": 55 candidates
mp4 warning: found an invalid sized 0 box mdat @40
mp4 warning: found an invalid sized 0 box mdat @40
mp4 warning: MP4 plugin discarded (not a valid initialization chunk)
mp4 debug: freeing all memory
main debug: looking for xml reader module matching "any": 1 candidates
main debug: using xml reader module "xml"
webvtt debug: subtitle demux discarded
ts debug: TS module discarded (lost sync)
mod debug: MOD validation failed (ext=mp4)
avcodec debug: trying url: C:\Users\G4G\Desktop\New folder\recording_0.mp4
avcodec debug: CPU flags: 0x0007d3db
avcodec debug: detected format: mov,mp4,m4a,3gp,3g2,mj2
avcodec debug: Trying to seek too far : EOF?
avcodec debug: Trying to seek too far : EOF?
avcodec error: Could not open C:\Users\G4G\Desktop\New folder\recording_0.mp4: Unknown error
ps warning: this does not look like an MPEG PS stream, continuing anyway
main debug: using demux module "ps"
main debug: looking for a subtitle file in C:\Users\G4G\Desktop\New folder\
main debug: looking for meta reader module matching "any": 2 candidates
lua debug: Trying Lua scripts in C:\Users\G4G\AppData\Roaming\vlc\lua\meta\reader
lua debug: Trying Lua scripts in C:\Program Files\VideoLAN\VLC\lua\meta\reader
lua debug: Trying Lua playlist script C:\Program Files\VideoLAN\VLC\lua\meta\reader\filename.luac
main debug: no meta reader modules matched
main debug: `file:///C:/Users/G4G/Desktop/New%20folder/recording_0.mp4' successfully opened
ps warning: garbage at input from 509, trying to resync...
ps warning: found sync code
ps warning: garbage at input, trying to resync...
ps warning: found sync code
ps warning: garbage at input, trying to resync...
ps warning: found sync code
ps warning: garbage at input, trying to resync...
ps warning: found sync code
ps warning: garbage at input, trying to resync...
ps warning: found sync code
ps warning: garbage at input, trying to resync...
ps warning: found sync code
ps warning: garbage at input, trying to resync...
ps warning: found sync code
ps warning: garbage at input, trying to resync...
ps warning: found sync code
ps warning: garbage at input, trying to resync...
main debug: selecting program id=0
main debug: looking for packetizer module matching "any": 25 candidates
main debug: using packetizer module "mpegvideo"
main debug: looking for video decoder module matching "any": 19 candidates
avcodec debug: using ffmpeg Lavc58.6.103
avcodec debug: CPU flags: 0x0007d3db
avcodec debug: allowing 6 thread(s) for decoding
avcodec debug: codec (mpeg2video) started
main debug: using video decoder module "avcodec"
ps warning: found sync code
main debug: looking for packetizer module matching "any": 25 candidates
main debug: using packetizer module "mpegaudio"
main debug: looking for audio decoder module matching "any": 23 candidates
mpg123 debug: mpga->f32l, bits per sample: 32
main debug: using audio decoder module "mpg123"
mpegvideo debug: waiting for sequence start
ps warning: garbage at input from 62128, trying to resync...
mpegvideo debug: waiting for sequence start
mpegvideo debug: waiting for sequence start
mpegaudio debug: waiting for PTS
ps warning: found sync code
ps warning: garbage at input from 116783, trying to resync...
ps warning: found sync code
ps warning: garbage at input from 137271, trying to resync...
ps warning: found sync code
ps warning: garbage at input from 185907, trying to resync...
ps warning: found sync code
main debug: looking for packetizer module matching "any": 25 candidates
main debug: using packetizer module "mpegvideo"
main debug: looking for video decoder module matching "any": 19 candidates
avcodec debug: using ffmpeg Lavc58.6.103
avcodec debug: CPU flags: 0x0007d3db
avcodec debug: allowing 6 thread(s) for decoding
avcodec debug: codec (mpeg2video) started
main debug: using video decoder module "avcodec"
ps warning: garbage at input from 203461, trying to resync...
ps warning: found sync code
ps warning: garbage at input from 247889, trying to resync...
ps warning: found sync code
mpegvideo debug: waiting for sequence start
mpegvideo debug: waiting for sequence start
mpegvideo debug: size 1049x2592/1056x2592 fps=0.015
ps warning: garbage at input from 267334, trying to resync...
ps warning: found sync code
ps warning: garbage at input from 314600, trying to resync...
ps warning: found sync code
ps warning: garbage at input from 336927, trying to resync...
ps warning: found sync code
main debug: killing decoder fourcc `mpga'
main debug: removing module "mpg123"
main debug: removing module "mpegaudio"
main debug: looking for packetizer module matching "any": 25 candidates
main debug: using packetizer module "mpegaudio"
main debug: looking for audio decoder module matching "any": 23 candidates
mpg123 debug: mpga->f32l, bits per sample: 32
main debug: using audio decoder module "mpg123"
ps warning: garbage at input from 398198, trying to resync...
ps warning: found sync code
mpegaudio debug: waiting for PTS
ps warning: garbage at input from 446135, trying to resync...
ps warning: found sync code
ps warning: garbage at input from 464560, trying to resync...
ps warning: found sync code
ps warning: garbage at input from 515197, trying to resync...
ps warning: found sync code
ps warning: garbage at input from 534414, trying to resync...
ps warning: found sync code
ps warning: garbage at input from 582353, trying to resync...
ps warning: found sync code
ps warning: garbage at input from 600350, trying to resync...
ps warning: found sync code
ps warning: garbage at input from 652543, trying to resync...
ps warning: found sync code
ps warning: garbage at input from 671911, trying to resync...
ps warning: found sync code
ps warning: garbage at input from 726692, trying to resync...
ps warning: found sync code
ps warning: garbage at input from 744543, trying to resync...
ps warning: found sync code
ps warning: garbage at input from 805302, trying to resync...
ps warning: found sync code
ps warning: garbage at input from 858344, trying to resync...
ps warning: found sync code
ps warning: garbage at input from 886288, trying to resync...
ps warning: found sync code
ps warning: garbage at input from 927072, trying to resync...
ps warning: found sync code
ps warning: garbage at input from 945373, trying to resync...
ps warning: found sync code
ps warning: garbage at input from 992835, trying to resync...
ps warning: found sync code
ps warning: garbage at input from 1027668, trying to resync...
ps warning: found sync code
ps warning: garbage at input from 1078100, trying to resync...
ps warning: found sync code
main debug: looking for packetizer module matching "any": 25 candidates
main debug: using packetizer module "mpegvideo"
main debug: looking for video decoder module matching "any": 19 candidates
avcodec debug: using ffmpeg Lavc58.6.103
avcodec debug: CPU flags: 0x0007d3db
avcodec debug: allowing 6 thread(s) for decoding
avcodec debug: codec (mpeg2video) started
main debug: using video decoder module "avcodec"
ps warning: garbage at input from 1129646, trying to resync...
ps warning: found sync code
ps warning: garbage at input from 1164848, trying to resync...
mpegvideo debug: waiting for sequence start
ps warning: found sync code
mpegvideo debug: waiting for sequence start
mpegvideo debug: waiting for sequence start
ps warning: garbage at input from 1203849, trying to resync...
ps warning: found sync code
ps warning: garbage at input from 1221683, trying to resync...
ps warning: found sync code
ps warning: garbage at input from 1270614, trying to resync...
ps warning: found sync code
ps warning: garbage at input from 1290605, trying to resync...
ps warning: found sync code
ps warning: garbage at input from 1335316, trying to resync...
ps warning: found sync code
ps warning: garbage at input from 1338137, trying to resync...
ps warning: found sync code
ps warning: garbage at input from 1599385, trying to resync...
ps warning: found sync code
ps warning: garbage at input from 1683556, trying to resync...
ps warning: found sync code
main debug: Buffering 0%
ps warning: garbage at input from 1755838, trying to resync...
ps warning: found sync code
ps warning: garbage at input from 1796667, trying to resync...
ps warning: found sync code
ps warning: garbage at input from 2291614, trying to resync...
ps warning: found sync code
ps warning: garbage at input from 3240275, trying to resync...
main debug: EOF reached
main debug: Stream buffering done (0 ms in 0 ms)
mpegvideo debug: need a starting pts/dts
mpegvideo debug: need a starting pts/dts
mpegvideo debug: need a starting pts/dts
main error: buffer deadlock prevented
main error: buffer deadlock prevented
main error: buffer deadlock prevented
main error: buffer deadlock prevented
main debug: Decoder wait done in 0 ms
main debug: killing decoder fourcc `mpgv'
main debug: removing module "avcodec"
main debug: removing module "mpegvideo"
main debug: killing decoder fourcc `mpgv'
main debug: removing module "avcodec"
main debug: removing module "mpegvideo"
main debug: killing decoder fourcc `mpga'
main debug: removing module "mpg123"
main debug: removing module "mpegaudio"
main debug: killing decoder fourcc `mpgv'
main debug: removing module "avcodec"
main debug: removing module "mpegvideo"
main debug: removing module "ps"
main debug: Program doesn't contain anymore ES
main debug: removing module "record"
main debug: removing module "cache_read"
main debug: removing module "filesystem"
main debug: dead input
main debug: changing item without a request (current 1/2)
main debug: nothing to play
qt debug: IM: Deleting the input

tried to convert the video afterwards with ffmpeg, got this error:

[mov,mp4,m4a,3gp,3g2,mj2 @ 000001aa8ea728c0] moov atom not found
recording_0.mp4: Invalid data found when processing input

appium log of failed video run https://gist.github.com/sSpockderpantss/aaa5c879334aefc498bf653c2be050a4

I play them in Allure report in Chrome or in QuickTime Apple player. Never had any issue.
You can send me in private message to try if you wish.

BTW share logic how you handle end of test?
e.g. mine after test:

  • check if test passed or failed
  • failed test ->
    • get page source
    • sleep 3 sec to record a bit more (found that stop record can swallow 1-2sec of end. just problem of video cording I guess)
  • stop video recording and if test failed attach it to allure report
  • NOW! quit driver

Logic of teardown is:

check app state (frozen or closed or open etc)
stop recording
get server logs from driver
quit driver
quit server

specifying the pixel format also fixed the corrupt recordings (or it happens rarely anyway):

            forceRestart=True,
            timeLimit=60 * 10,
            videoType='libx265',
            videoFps=24,
            videoScale="320:-2"
            pixelFormat="yuv420p"

I think its fixed! Thank you for your help!

update:
It seems like only 2 videos in 20 videos are shorter than intended now, which is low enough, but I don’t know why

Shorter how? Few sec or several minutes?

1-2 mins too short (for a 10 minute video), ran 20 more tests and happened once.

ran a few more tests for 30 minute videos, and one was 6 mins shorter, most were 2 mins shorter

I have only few tests that longer then 6-7min and can’t compare.
Interesting where the problem:

  • video stops recording
  • did you try compare string result length of video returned and saved file size?

What I’ve found: 25 fps is the input, if I use 30fps then the video ends 1-2 mins too early. If i use 25fps then the video end point is correct, which fixes the issue of this thread (together with the videoScale and pixelFormat arguments mentioned above) BUT the video duration is shorter than intended (so the video is too fast when using 25fps), so i have to convert the video afterward using -filter:v "setpts=1.075*PTS", to correct the speed. Then the speed and end point are both correct!

Unfortunately for some reason if I specify setpts=1.075*PTS as a videoFilter in the start_recording function then the videos are too short again!

So I will take a video and convert the video manually afterward, this is the fix :slight_smile:

I will test this a few times, if I find an issue again I will return here. Thanks again!

(I ran 20 tests, no problems)

1 Like

Wow. Yes video itself may run faster than actial. This i mentioned but! all steps were in video.
Anyway nice happy end!

1 Like

made a feature request relating to this issue Appium recording does not support dynamic input frame rate