Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Some recordings have wrong duration #2477

Closed
1 of 13 tasks
0ip opened this issue Oct 7, 2023 · 10 comments · Fixed by #2715
Closed
1 of 13 tasks

Some recordings have wrong duration #2477

0ip opened this issue Oct 7, 2023 · 10 comments · Fixed by #2715
Labels
bug Something isn't working general

Comments

@0ip
Copy link

0ip commented Oct 7, 2023

Which version are you using?

v1.1.1

Which operating system are you using?

  • Linux amd64 standard
  • Linux amd64 Docker
  • Linux arm64 standard
  • Linux arm64 Docker
  • Linux arm7 standard
  • Linux arm7 Docker
  • Linux arm6 standard
  • Linux arm6 Docker
  • Windows amd64 standard
  • Windows amd64 Docker (WSL backend)
  • macOS amd64 standard
  • macOS amd64 Docker
  • Other (please describe)

Describe the issue

Some recordings of my security camera have a wrong or absurdly high length duration instead of the actually set 10 seconds. While this problem doesn't show up in VLC (duration is said to be 10 s) and the videos play fine there, ffmpeg and chrome report the wrong durations:

ffprobe of a video that is affected by this bug:
image

ffprobe of a normal video:
image

relevant config parts:

record: yes
recordPath: /dev/shm/recordings/%path/%Y-%m-%d_%H-%M-%S-%f
recordFormat: fmp4
recordPartDuration: 100ms
recordSegmentDuration: 10s
recordDeleteAfter: 4m
...
writeQueueSize: 1024

rtspAddress: :8554
protocols: [tcp]
...
paths:
  64/high:
    source: rtsp://x:y@192.168.1.64:554/Streaming/Channels/101
    sourceOnDemand: no
    sourceProtocol: tcp
    record: yes

I can forward you the files via email if desired.

Describe how to replicate the issue

  1. start the server
  2. publish rtsp stream
  3. record
  4. some recordings have a wrong duration, some are normal as expected

Did you attach the server logs?

no

Did you attach a network dump?

no

@aler9
Copy link
Member

aler9 commented Nov 18, 2023

Hello, in order to identify the issue we need

  • a sample recording segment that shows the bug
  • server logs, if they show errors or warnings about lost packets

My guess is that some video frames get assigned a negative timestamp, due to the video / audio synchronization algorithm of the server. FFmpeg decodes timestamps into unsigned variables, the sign is lost and is interpreted as the most significant bit, and here you have your distant point in the future.

@aler9 aler9 added bug Something isn't working general labels Nov 18, 2023
@0ip
Copy link
Author

0ip commented Nov 18, 2023

I have recorded some segments and replicated the bug, again. I'll forward them to you privately via mail. The log did not reveal anything noteworthy. No lost packets or the like.

@aler9
Copy link
Member

aler9 commented Nov 19, 2023

Thanks for providing the recording file that allowed to replicate the issue. There's a small delay between video timestamp and audio timestamp, and the first audio samples get a negative timestamp, which, as i have already mentioned, is not supported by fMP4. I created a patch that discards samples with a negative timestamp. Please test the nightly release in this page ("Artifacts", "binaries") and let me know if it fixes the issue:

https://github.com/bluenviron/mediamtx/actions/runs/6920341925

@0ip
Copy link
Author

0ip commented Nov 19, 2023

While testing the nightly release you provided, I again noticed incorrect segments. I have sent you another test sample.

@aler9
Copy link
Member

aler9 commented Nov 19, 2023

The sample you sent has the same exact problem as before, it has a negative base timestamp in the first part, in the audio track. I don't understand why it's happening, so i've updated the patch in order to print the base timestamp on the console, please test it and attach a server log:

https://github.com/bluenviron/mediamtx/actions/runs/6923278140

@0ip
Copy link
Author

0ip commented Nov 20, 2023

Here's the server log:

Nov 20 13:17:05 pi50 mediamtx[7088]: 2023/11/20 13:17:05 INF MediaMTX
Nov 20 13:17:05 pi50 mediamtx[7088]: 2023/11/20 13:17:05 INF configuration loaded from /usr/local/etc/mediamtx.yml
Nov 20 13:17:05 pi50 mediamtx[7088]: 2023/11/20 13:17:05 INF [path 64/high] [RTSP source] started
Nov 20 13:17:05 pi50 mediamtx[7088]: 2023/11/20 13:17:05 INF [RTSP] listener opened on :8554 (TCP)
Nov 20 13:17:05 pi50 mediamtx[7088]: 2023/11/20 13:17:05 INF [HLS] listener opened on :8601
Nov 20 13:17:05 pi50 mediamtx[7088]: 2023/11/20 13:17:05 INF [WebRTC] listener opened on :8600 (HTTP), :8189 (ICE/UDP)
Nov 20 13:17:05 pi50 mediamtx[7088]: 2023/11/20 13:17:05 INF [SRT] listener opened on :8890 (UDP)
Nov 20 13:17:05 pi50 mediamtx[7088]: 2023/11/20 13:17:05 INF [path 64/high] [record] recording 2 tracks
Nov 20 13:17:05 pi50 mediamtx[7088]: 2023/11/20 13:17:05 INF [path 64/high] [RTSP source] ready: 2 tracks (H264, MPEG-4 Audio)
Nov 20 13:17:05 pi50 mediamtx[7088]: BASE TIME 94.518µs 0s 8
Nov 20 13:17:05 pi50 mediamtx[7088]: BASE TIME 0s 0s 0
Nov 20 13:17:07 pi50 mediamtx[7088]: BASE TIME 1.984s 0s 178560
Nov 20 13:17:07 pi50 mediamtx[7088]: BASE TIME 2.040094518s 0s 183608
Nov 20 13:17:09 pi50 mediamtx[7088]: BASE TIME 4.032s 0s 362880
Nov 20 13:17:09 pi50 mediamtx[7088]: BASE TIME 4.040094518s 0s 363608
Nov 20 13:17:11 pi50 mediamtx[7088]: BASE TIME 6.080094518s 0s 547208
Nov 20 13:17:11 pi50 mediamtx[7088]: BASE TIME 6.08s 0s 547200
Nov 20 13:17:14 pi50 mediamtx[7088]: BASE TIME 8.064s 0s 725760
Nov 20 13:17:14 pi50 mediamtx[7088]: BASE TIME 8.120094518s 0s 730808
Nov 20 13:17:15 pi50 mediamtx[7088]: BASE TIME 10.079094518s 10.079094518s 0
Nov 20 13:17:15 pi50 mediamtx[7088]: BASE TIME 10.112s 10.079094518s 2961
Nov 20 13:17:17 pi50 mediamtx[7088]: BASE TIME 12.119094518s 10.079094518s 183600
Nov 20 13:17:17 pi50 mediamtx[7088]: BASE TIME 12.096s 10.079094518s 181521
Nov 20 13:17:19 pi50 mediamtx[7088]: BASE TIME 14.159094518s 10.079094518s 367200
Nov 20 13:17:19 pi50 mediamtx[7088]: BASE TIME 14.144s 10.079094518s 365841
Nov 20 13:17:21 pi50 mediamtx[7088]: BASE TIME 16.199094518s 10.079094518s 550800
Nov 20 13:17:21 pi50 mediamtx[7088]: BASE TIME 16.192s 10.079094518s 550161
Nov 20 13:17:24 pi50 mediamtx[7088]: BASE TIME 18.24s 10.079094518s 734481
Nov 20 13:17:24 pi50 mediamtx[7088]: BASE TIME 18.278094518s 10.079094518s 737910
Nov 20 13:17:26 pi50 mediamtx[7088]: BASE TIME 20.288s 10.079094518s 918801
Nov 20 13:17:26 pi50 mediamtx[7088]: BASE TIME 20.318094518s 10.079094518s 921510
Nov 20 13:17:26 pi50 mediamtx[7088]: BASE TIME 21.078094518s 21.078094518s 0
Nov 20 13:17:26 pi50 mediamtx[7088]: BASE TIME 21.056s 21.078094518s 18446742085
Nov 20 13:17:28 pi50 mediamtx[7088]: BASE TIME 23.118094518s 21.078094518s 183600
Nov 20 13:17:28 pi50 mediamtx[7088]: BASE TIME 23.104s 21.078094518s 182331
Nov 20 13:17:30 pi50 mediamtx[7088]: BASE TIME 25.158094518s 21.078094518s 367200
Nov 20 13:17:30 pi50 mediamtx[7088]: BASE TIME 25.152s 21.078094518s 366651
Nov 20 13:17:32 pi50 mediamtx[7088]: BASE TIME 27.2s 21.078094518s 550971
Nov 20 13:17:32 pi50 mediamtx[7088]: BASE TIME 27.237094518s 21.078094518s 554310
Nov 20 13:17:35 pi50 mediamtx[7088]: BASE TIME 29.248s 21.078094518s 735291
Nov 20 13:17:35 pi50 mediamtx[7088]: BASE TIME 29.277094518s 21.078094518s 737910
Nov 20 13:17:37 pi50 mediamtx[7088]: BASE TIME 31.317094518s 21.078094518s 921510
Nov 20 13:17:37 pi50 mediamtx[7088]: BASE TIME 31.296s 21.078094518s 919611
Nov 20 13:17:37 pi50 mediamtx[7088]: BASE TIME 32.077094518s 32.077094518s 0
Nov 20 13:17:37 pi50 mediamtx[7088]: BASE TIME 32.064s 32.077094518s 18446742895
Nov 20 13:17:40 pi50 mediamtx[7088]: BASE TIME 34.117094518s 32.077094518s 183600
Nov 20 13:17:40 pi50 mediamtx[7088]: BASE TIME 34.112s 32.077094518s 183141
Nov 20 13:17:41 pi50 mediamtx[7088]: BASE TIME 36.16s 32.077094518s 367461
Nov 20 13:17:41 pi50 mediamtx[7088]: BASE TIME 36.196094518s 32.077094518s 370710
Nov 20 13:17:43 pi50 mediamtx[7088]: BASE TIME 38.208s 32.077094518s 551781
Nov 20 13:17:43 pi50 mediamtx[7088]: BASE TIME 38.236094518s 32.077094518s 554310
Nov 20 13:17:46 pi50 mediamtx[7088]: BASE TIME 40.276094518s 32.077094518s 737910
Nov 20 13:17:46 pi50 mediamtx[7088]: BASE TIME 40.256s 32.077094518s 736101
Nov 20 13:17:48 pi50 mediamtx[7088]: BASE TIME 42.316094518s 32.077094518s 921510
Nov 20 13:17:48 pi50 mediamtx[7088]: BASE TIME 42.304s 32.077094518s 920421
Nov 20 13:17:48 pi50 mediamtx[7088]: BASE TIME 43.075094518s 43.075094518s 0
Nov 20 13:17:48 pi50 mediamtx[7088]: BASE TIME 43.072s 43.075094518s 18446743795
Nov 20 13:17:50 pi50 mediamtx[7088]: BASE TIME 45.056s 43.075094518s 178281
Nov 20 13:17:50 pi50 mediamtx[7088]: BASE TIME 45.115094518s 43.075094518s 183600
Nov 20 13:17:52 pi50 mediamtx[7088]: BASE TIME 47.115094518s 43.075094518s 363600
Nov 20 13:17:52 pi50 mediamtx[7088]: BASE TIME 47.104s 43.075094518s 362601
Nov 20 13:17:54 pi50 mediamtx[7088]: BASE TIME 49.155094518s 43.075094518s 547200
Nov 20 13:17:54 pi50 mediamtx[7088]: BASE TIME 49.152s 43.075094518s 546921
Nov 20 13:17:56 pi50 mediamtx[7088]: BASE TIME 51.136s 43.075094518s 725481
Nov 20 13:17:56 pi50 mediamtx[7088]: BASE TIME 51.195094518s 43.075094518s 730800
Nov 20 13:17:58 pi50 mediamtx[7088]: BASE TIME 53.194094518s 43.075094518s 910710
Nov 20 13:17:58 pi50 mediamtx[7088]: BASE TIME 53.184s 43.075094518s 909801
Nov 20 13:17:59 pi50 mediamtx[7088]: BASE TIME 54.074094518s 54.074094518s 0
Nov 20 13:17:59 pi50 mediamtx[7088]: BASE TIME 54.08s 54.074094518s 531
Nov 20 13:18:01 pi50 mediamtx[7088]: BASE TIME 56.064s 54.074094518s 179091
Nov 20 13:18:01 pi50 mediamtx[7088]: BASE TIME 56.114094518s 54.074094518s 183600
Nov 20 13:18:03 pi50 mediamtx[7088]: BASE TIME 58.114094518s 54.074094518s 363600
Nov 20 13:18:03 pi50 mediamtx[7088]: BASE TIME 58.112s 54.074094518s 363411
Nov 20 13:18:05 pi50 mediamtx[7088]: BASE TIME 1m0.16s 54.074094518s 547731
Nov 20 13:18:05 pi50 mediamtx[7088]: BASE TIME 1m0.193094518s 54.074094518s 550710
Nov 20 13:18:08 pi50 mediamtx[7088]: BASE TIME 1m2.208s 54.074094518s 732051
Nov 20 13:18:08 pi50 mediamtx[7088]: BASE TIME 1m2.233094518s 54.074094518s 734310
Nov 20 13:18:10 pi50 mediamtx[7088]: BASE TIME 1m4.273094518s 54.074094518s 917910
Nov 20 13:18:10 pi50 mediamtx[7088]: BASE TIME 1m4.256s 54.074094518s 916371
Nov 20 13:18:10 pi50 mediamtx[7088]: BASE TIME 1m5.073094518s 1m5.073094518s 0
Nov 20 13:18:10 pi50 mediamtx[7088]: BASE TIME 1m5.088s 1m5.073094518s 1341
Nov 20 13:18:13 pi50 mediamtx[7088]: BASE TIME 1m7.072s 1m5.073094518s 179901
Nov 20 13:18:13 pi50 mediamtx[7088]: BASE TIME 1m7.113094518s 1m5.073094518s 183600
Nov 20 13:18:15 pi50 mediamtx[7088]: BASE TIME 1m9.056s 1m5.073094518s 358461
Nov 20 13:18:15 pi50 mediamtx[7088]: BASE TIME 1m9.112094518s 1m5.073094518s 363510
Nov 20 13:18:16 pi50 mediamtx[7088]: BASE TIME 1m11.112094518s 1m5.073094518s 543510
Nov 20 13:18:16 pi50 mediamtx[7088]: BASE TIME 1m11.104s 1m5.073094518s 542781
Nov 20 13:18:18 pi50 mediamtx[7088]: BASE TIME 1m13.152094518s 1m5.073094518s 727110
Nov 20 13:18:18 pi50 mediamtx[7088]: BASE TIME 1m13.152s 1m5.073094518s 727101
Nov 20 13:18:20 pi50 mediamtx[7088]: BASE TIME 1m15.136s 1m5.073094518s 905661
Nov 20 13:18:20 pi50 mediamtx[7088]: BASE TIME 1m15.192094518s 1m5.073094518s 910710
Nov 20 13:18:21 pi50 mediamtx[7088]: BASE TIME 1m16.072094518s 1m16.072094518s 0
Nov 20 13:18:21 pi50 mediamtx[7088]: BASE TIME 1m16.096s 1m16.072094518s 2151
Nov 20 13:18:23 pi50 mediamtx[7088]: BASE TIME 1m18.111094518s 1m16.072094518s 183510
Nov 20 13:18:23 pi50 mediamtx[7088]: BASE TIME 1m18.144s 1m16.072094518s 186471
Nov 20 13:18:25 pi50 mediamtx[7088]: BASE TIME 1m20.128s 1m16.072094518s 365031
Nov 20 13:18:25 pi50 mediamtx[7088]: BASE TIME 1m20.151094518s 1m16.072094518s 367110
Nov 20 13:18:27 pi50 mediamtx[7088]: BASE TIME 1m22.191094518s 1m16.072094518s 550710
Nov 20 13:18:27 pi50 mediamtx[7088]: BASE TIME 1m22.176s 1m16.072094518s 549351
Nov 20 13:18:30 pi50 mediamtx[7088]: BASE TIME 1m24.231094518s 1m16.072094518s 734310
Nov 20 13:18:30 pi50 mediamtx[7088]: BASE TIME 1m24.224s 1m16.072094518s 733671
Nov 20 13:18:32 pi50 mediamtx[7088]: BASE TIME 1m26.272s 1m16.072094518s 917991
Nov 20 13:18:32 pi50 mediamtx[7088]: BASE TIME 1m26.310094518s 1m16.072094518s 921420
Nov 20 13:18:32 pi50 mediamtx[7088]: BASE TIME 1m27.070094518s 1m27.070094518s 0
Nov 20 13:18:32 pi50 mediamtx[7088]: BASE TIME 1m27.104s 1m27.070094518s 3051
Nov 20 13:18:34 pi50 mediamtx[7088]: BASE TIME 1m29.088s 1m27.070094518s 181611
Nov 20 13:18:34 pi50 mediamtx[7088]: BASE TIME 1m29.110094518s 1m27.070094518s 183600
Nov 20 13:18:36 pi50 mediamtx[7088]: BASE TIME 1m31.150094518s 1m27.070094518s 367200
Nov 20 13:18:36 pi50 mediamtx[7088]: BASE TIME 1m31.136s 1m27.070094518s 365931
Nov 20 13:18:38 pi50 mediamtx[7088]: BASE TIME 1m33.190094518s 1m27.070094518s 550800
Nov 20 13:18:38 pi50 mediamtx[7088]: BASE TIME 1m33.184s 1m27.070094518s 550251
Nov 20 13:18:41 pi50 mediamtx[7088]: BASE TIME 1m35.232s 1m27.070094518s 734571
Nov 20 13:18:41 pi50 mediamtx[7088]: BASE TIME 1m35.269094518s 1m27.070094518s 737910
Nov 20 13:18:43 pi50 mediamtx[7088]: BASE TIME 1m37.28s 1m27.070094518s 918891
Nov 20 13:18:43 pi50 mediamtx[7088]: BASE TIME 1m37.309094518s 1m27.070094518s 921510
Nov 20 13:18:43 pi50 mediamtx[7088]: BASE TIME 1m38.069094518s 1m38.069094518s 0
Nov 20 13:18:43 pi50 mediamtx[7088]: BASE TIME 1m38.112s 1m38.069094518s 3861
Nov 20 13:18:45 pi50 mediamtx[7088]: BASE TIME 1m40.109094518s 1m38.069094518s 183600
Nov 20 13:18:45 pi50 mediamtx[7088]: BASE TIME 1m40.096s 1m38.069094518s 182421
Nov 20 13:18:47 pi50 mediamtx[7088]: BASE TIME 1m42.149094518s 1m38.069094518s 367200
Nov 20 13:18:47 pi50 mediamtx[7088]: BASE TIME 1m42.144s 1m38.069094518s 366741
Nov 20 13:18:49 pi50 mediamtx[7088]: BASE TIME 1m44.192s 1m38.069094518s 551061
Nov 20 13:18:49 pi50 mediamtx[7088]: BASE TIME 1m44.228094518s 1m38.069094518s 554310
Nov 20 13:18:52 pi50 mediamtx[7088]: BASE TIME 1m46.24s 1m38.069094518s 735381
Nov 20 13:18:52 pi50 mediamtx[7088]: BASE TIME 1m46.268094518s 1m38.069094518s 737910

Durations are still inconsistent, i.e. some are okay, some are not:

Duration of 2023-11-20_13-15-11-170241.mp4: 11.045000 seconds
Duration of 2023-11-20_13-15-22-165588.mp4: 11.063000 seconds
Duration of 2023-11-20_13-15-33-141778.mp4: 8.203000 seconds
Duration of 2023-11-20_13-17-05-993183.mp4: 10.112000 seconds
Duration of 2023-11-20_13-17-15-988797.mp4: 11.009800 seconds
Duration of 2023-11-20_13-17-26-939632.mp4: 204965.848944 seconds
Duration of 2023-11-20_13-17-37-975150.mp4: 204965.857944 seconds
Duration of 2023-11-20_13-17-48-971823.mp4: 204965.803944 seconds
Duration of 2023-11-20_13-17-59-957327.mp4: 11.019800 seconds
Duration of 2023-11-20_13-18-10-991347.mp4: 11.037800 seconds
Duration of 2023-11-20_13-18-21-949741.mp4: 11.055800 seconds
Duration of 2023-11-20_13-18-32-947840.mp4: 11.075800 seconds
Duration of 2023-11-20_13-18-43-984965.mp4: 11.029800 seconds
Duration of 2023-11-20_13-18-54-993304.mp4: 204965.858944 seconds
Duration of 2023-11-20_13-19-05-985939.mp4: 204965.868944 seconds
Duration of 2023-11-20_13-19-17-000356.mp4: 10.999000 seconds
Duration of 2023-11-20_13-19-27-955832.mp4: 204965.822944 seconds
Duration of 2023-11-20_13-19-38-973326.mp4: 204965.831944 seconds
Duration of 2023-11-20_13-19-49-982042.mp4: 204965.777944 seconds
Duration of 2023-11-20_13-20-00-971350.mp4: 204965.786944 seconds
Duration of 2023-11-20_13-20-11-940154.mp4: 204965.859944 seconds
Duration of 2023-11-20_13-20-22-903881.mp4: 204965.805944 seconds
#!/bin/bash
cd /dev/shm/recordings/64/high/
for file in *.mp4; do
    duration=$(ffprobe -v quiet -print_format json -show_format -show_streams "$file" 2>&1 | jq -r '.format.duration')
    echo "Duration of $file: $duration seconds"
done

@aler9
Copy link
Member

aler9 commented Nov 22, 2023

@0ip thanks again for providing feedback that allowed to replicate the residual bug (if you take a look at BASE TIME, there are some lines that ends with large numbers, that in reality are negative signed integers casted to unsigned integers). I should have fixed this scenario too. Here's another nightly release:

https://github.com/bluenviron/mediamtx/actions/runs/6962789837

@0ip
Copy link
Author

0ip commented Nov 22, 2023

Thank you. That last iteration did the trick! Now all recordings have consistent, plausible durations.

Copy link
Contributor

This issue is mentioned in release v1.3.1 🚀
Check out the entire changelog by clicking here

Copy link
Contributor

This issue is being locked automatically because it has been closed for more than 6 months.
Please open a new issue in case you encounter a similar problem.

@github-actions github-actions bot locked and limited conversation to collaborators May 31, 2024
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
bug Something isn't working general
Projects
None yet
2 participants