syslog flooded by 1.36.35

[eggenbef]

Yeah I've been able to reproduce it. Don't worry about logs

excellent - so one step closer to get this figured out . btw the logs i sent you were taken from a 22.04 installation but on 24.04 i ran into the same issue ... with 1.36.35 while 1.36.33 is running perfectly fine with my configuration/camera setup both on ubuntu 22.04 and 24.04.

[eggenbef]

also, if the creation of jpges is disabled then (and only then) the following error is raised

Code: Select all

11/20/24, 11:55:09 AM GMT+1	web_php		7634	ERR	Can't create frame images from video for this event 56339-video.mp4Command was: /usr/bin/ffmpeg -ss 1.00 -i /media/user/LINUX-EXT/zmdata/2/2024-11-20/56339/56339-video.mp4 -frames:v 1 /media/user/LINUX-EXT/zmdata/2/2024-11-20/56339/00005-capture.jpg 2>&1Output was: ffmpeg version 4.4.2-0ubuntu0.22.04.1 Copyright (c) 2000-2021 the FFmpeg developers built with gcc 11 (Ubuntu 11.2.0-19ubuntu1) configuration: --prefix=/usr --extra-version=0ubuntu0.22.04.1 --toolchain=hardened --libdir=/usr/lib/x86_64-linux-gnu --incdir=/usr/include/x86_64-linux-gnu --arch=amd64 --enable-gpl --disable-stripping --enable-gnutls --enable-ladspa --enable-libaom --enable-libass --enable-libbluray --enable-libbs2b --enable-libcaca --enable-libcdio --enable-libcodec2 --enable-libdav1d --enable-libflite --enable-libfontconfig --enable-libfreetype --enable-libfribidi --enable-libgme --enable-libgsm --enable-libjack --enable-libmp3lame --enable-libmysofa --enable-libopenjpeg --enable-libopenmpt --enable-libopus --enable-libpulse --enable-librabbitmq --enable-librubberband --enable-libshine --enable-libsnappy --enable-libsoxr --enable-libspeex --enable-libsrt --enable-libssh --enable-libtheora --enable-libtwolame --enable-libvidstab --enable-libvorbis --enable-libvpx --enable-libwebp --enable-libx265 --enable-libxml2 --enable-libxvid --enable-libzimg --enable-libzmq --enable-libzvbi --enable-lv2 --enable-omx --enable-openal --enable-opencl --enable-opengl --enable-sdl2 --enable-pocketsphinx --enable-librsvg --enable-libmfx --enable-libdc1394 --enable-libdrm --enable-libiec61883 --enable-chromaprint --enable-frei0r --enable-libx264 --enable-shared libavutil 56. 70.100 / 56. 70.100 libavcodec 58.134.100 / 58.134.100 libavformat 58. 76.100 / 58. 76.100 libavdevice 58. 13.100 / 58. 13.100 libavfilter 7.110.100 / 7.110.100 libswscale 5. 9.100 / 5. 9.100 libswresample 3. 9.100 / 3. 9.100 libpostproc 55. 9.100 / 55. 9.100[mov,mp4,m4a,3gp,3g2,mj2 @ 0x5d4d656ce680] moov atom not found/media/user/LINUX-EXT/zmdata/2/2024-11-20/56339/56339-video.mp4: Invalid data found when processing input	/usr/share/zoneminder/www/views/image.php	295

i think i figured this one out. i am running remote detection and at the time the detection service was requesting to access frame 00005 for analysis the event was still open in zm and the mp4 file generation therefore not completed yet. ffmpeg may presumably not be able to access frames from a video file of which the generation is still in progress and therefore failed to extract this frame. this error does not occur anymore once the mp4 file has been generated (i.e. once the event has been closed) and never occurs when frames are also written as jpegs. i will therefore leave the creation of jpegs enabled what will require more storage space but keep the object detection process as fast as it is today

any luck with the root cause analysis of the main issue of this thread (log flooding with "non increasing dts" messages when using 1.36.35 while 1.36.33 is running without this problem)

kind regards and thank you so much for maintaining/extending this awesome software!

[iconnor]

I think when writing the mp4, it flushes to disk after every keyframe or so... so you may be able to access the incomplete mp4, but you do need to lag behind a little bit.

As to the dts issue, I thought I had recreated it, but then I realised that I hadn't specified a crf option to the encoder. For some reason without it, the encoder generates a crap video file with timestamps all over the place. How do your videos look? Good or starting off with grey and smearing and slowly coming in?

[eggenbef]

How do your videos look? Good or starting off with grey and smearing and slowly coming in?

the video i just generated with 1.36.35 looks fine to me even though the zmc log was flooded with "non increasing dts" WAR messages during the whole recording period along with one single "non increasing dts" DB1 message (see attached). when debug level 3 or 2 was enabled then the logs did again not include any "non increasing dts" entries

as this issue only happens with 1.36.35 but not with 1.36.33 my guess would still be that it is related to a change which was made with 1.36.34 or 1.33.35. i ran a diff of videostore.cpp v33 vs v35 and wonder whether the issue could be related to these lines:

Code: Select all

1393c1473
<       last_dts[stream->index] = 0;
---
>       last_dts[stream->index] = -1;
1397,1400c1477,1490
<     if ((last_dts[stream->index] != AV_NOPTS_VALUE) and (pkt->dts < last_dts[stream->index])) {
<       Warning("non increasing dts, fixing. our dts %" PRId64 " stream %d last_dts %" PRId64 ". reorder_queue_size=%zu",
<           pkt->dts, stream->index, last_dts[stream->index], reorder_queue_size);
<       pkt->dts = last_dts[stream->index];
---
>     if (last_dts[stream->index] != AV_NOPTS_VALUE) {
>       if (pkt->dts < last_dts[stream->index]) {
>         Warning("non increasing dts, fixing. our dts %" PRId64 " stream %d last_dts %" PRId64 " difference %" PRId64 " last_duration %" PRId64 ". reorder_queue_size=%zu",
>             pkt->dts, stream->index, last_dts[stream->index], (last_dts[stream->index]-pkt->dts), last_duration[stream->index], reorder_queue_size);
>         pkt->dts = last_dts[stream->index]+last_duration[stream->index];
>         if (pkt->dts > pkt->pts) pkt->pts = pkt->dts; // Do it here to avoid warning below
>       } else if (pkt->dts == last_dts[stream->index]) {
>         // Commonly seen
>         Debug(1, "non increasing dts, fixing. our dts %" PRId64 " stream %d last_dts %" PRId64 ". reorder_queue_size=%zu",
>             pkt->dts, stream->index, last_dts[stream->index], reorder_queue_size);
>         // dts MUST monotonically increase, so add 1 which should be a small enough time difference to not matter.
>         pkt->dts = last_dts[stream->index]+last_duration[stream->index]-1;
>         if (pkt->dts > pkt->pts) pkt->pts = pkt->dts; // Do it here to avoid warning below
>       }

i haven't written c++ code for ages so it's just a hunch that the issue could be related to the excerpt of diff output above. may be setting last_dts value to -1 and comparing it later on with a variable which was declared to be unsigned? any other thoughts/suggestions?

[eggenbef]

setting last_dts value to -1 and comparing it later on with a variable which was declared to be unsigned?

please ignore this one - i was overlooking the cast to int64_t of this variable. any other/better suggestion?

[iconnor]

That -1 does look sketchy, but I'm not convinced.

I don't see why turning on debugging would change the behaviour.

I need a debug level 3 log.

[iconnor]

I think the duration calculations are completely bogus. We are using the duration from the frame we are stuffing into the codec but that isn't necessarily the frame we get out of the codec.

[eggenbef]

That -1 does look sketchy, but I'm not convinced.

I don't see why turning on debugging would change the behaviour.

I need a debug level 3 log.

sure, no problem and thank you very much for your time/effort to get this sorted out . i just ran 1.36.35 with debug level 3 and shortly after that with level 1. both logs are attached. with level 1 more than 100 "non increasing dts" entries were generated within less than 30 seconds. the level 3 log on the other hand does not include any such entry even though the system was running for more than 2 minutes with level 3. this behavior is consistent with what i have experienced so far. may be the difference between level 3 and level 1 regarding the "non increasing dts" issue is caused by timing assuming that level 3 may impact performance more than level 1? also, in the level 3 log i found a warning saying "Some thread isn't keeping up". may be a hint?

[eggenbef]

I think the duration calculations are completely bogus. We are using the duration from the frame we are stuffing into the codec but that isn't necessarily the frame we get out of the codec.

you are probably referring to this change which is referred to in the release notes of 1.36.34 as follows:

Use last duration instead of 1 when adjusting dts when non-monotonic. Some googling indicates this might be a better approach. What I am seeing with a tapo C520WS agrees

not sure where in the code of 1.36.33 the dts adjustment with an increment of 1 is carried out but in 1.36.35 the adjusted dts seems to be the last_duration added to the last_dts:

Code: Select all

pkt->dts = last_dts[stream->index]+last_duration[stream->index];

while in 1.36.33 dts adjustment seems to be implemented by simply resetting dts to the value of the last_dts:

Code: Select all

pkt->dts = last_dts[stream->index];

also, i wonder what configurations were tested with the tapo c520ws as a basis of the implementation of this change which could potentially be the root cause of the "non increasing dts" issue reported in this thread

[eggenbef]

I think the duration calculations are completely bogus. We are using the duration from the frame we are stuffing into the codec but that isn't necessarily the frame we get out of the codec.

the trouble in the context of this thread seems to be that with 1.36.35 the calculated duration is also used to adjust the dts in case a non-monotonic value. this is not the case in release 1.36.33 where the adjustment is performed without using the calculated duration.

as you can see in the below logs from a 1.36.35 instance the flooding kicks off with a dts value which is identical to the value of last_dts and is therefore increased by the calculated duration which, however, seems to be far too high. as a consequence the dts of the following packets are much lower than the value of the last_dts which was adjusted before with the calculated duration. this goes on forever, i.e. until zm has been be restarted. (and then of course starts again with the first case of a non-monotonic dts value...)

may be worth considering a roll back of the fixing of non-monotonic dts values to the version which was implemented in release 1.36.33?

Code: Select all

11/29/24 09:29:35.997890 zmc_m2[9876].DB1-zm_videostore.cpp/1485 [non increasing dts, fixing. our dts 14 stream 0 last_dts 14. reorder_queue_size=0]
11/29/24 09:29:36.240651 zmc_m2[9876].WAR-zm_videostore.cpp/1479 [non increasing dts, fixing. our dts 22 stream 0 last_dts 25263 difference 25241 last_duration 21643. reorder_queue_size=0]
11/29/24 09:29:36.290810 zmc_m2[9876].WAR-zm_videostore.cpp/1479 [non increasing dts, fixing. our dts 22 stream 0 last_dts 46906 difference 46884 last_duration 21643. reorder_queue_size=0]
11/29/24 09:29:36.353377 zmc_m2[9876].WAR-zm_videostore.cpp/1479 [non increasing dts, fixing. our dts 24 stream 0 last_dts 68549 difference 68525 last_duration 21644. reorder_queue_size=0]
11/29/24 09:29:36.393698 zmc_m2[9876].WAR-zm_videostore.cpp/1479 [non increasing dts, fixing. our dts 26 stream 0 last_dts 90193 difference 90167 last_duration 25250. reorder_queue_size=0]
11/29/24 09:29:36.433611 zmc_m2[9876].WAR-zm_videostore.cpp/1479 [non increasing dts, fixing. our dts 27 stream 0 last_dts 115443 difference 115416 last_duration 21643. reorder_queue_size=0]
11/29/24 09:29:36.477248 zmc_m2[9876].WAR-zm_videostore.cpp/1479 [non increasing dts, fixing. our dts 28 stream 0 last_dts 137086 difference 137058 last_duration 21644. reorder_queue_size=0]
11/29/24 09:29:36.519754 zmc_m2[9876].WAR-zm_videostore.cpp/1479 [non increasing dts, fixing. our dts 28 stream 0 last_dts 158730 difference 158702 last_duration 21642. reorder_queue_size=0]
11/29/24 09:29:36.574932 zmc_m2[9876].WAR-zm_videostore.cpp/1479 [non increasing dts, fixing. our dts 29 stream 0 last_dts 180372 difference 180343 last_duration 25251. reorder_queue_size=0]
11/29/24 09:29:36.920052 zmc_m2[9876].WAR-zm_videostore.cpp/1479 [non increasing dts, fixing. our dts 29 stream 0 last_dts 205623 difference 205594 last_duration 21643. reorder_queue_size=0]
11/29/24 09:29:37.134891 zmc_m2[9876].WAR-zm_videostore.cpp/1479 [non increasing dts, fixing. our dts 30 stream 0 last_dts 227266 difference 227236 last_duration 21643. reorder_queue_size=0]
11/29/24 09:29:37.390334 zmc_m2[9876].WAR-zm_videostore.cpp/1479 [non increasing dts, fixing. our dts 27420 stream 0 last_dts 248909 difference 221489 last_duration 21644. reorder_queue_size=0]
11/29/24 09:29:37.555123 zmc_m2[9876].WAR-zm_videostore.cpp/1479 [non increasing dts, fixing. our dts 38409 stream 0 last_dts 270553 difference 232144 last_duration 25250. reorder_queue_size=0]
11/29/24 09:29:37.593100 zmc_m2[9876].WAR-zm_videostore.cpp/1479 [non increasing dts, fixing. our dts 58215 stream 0 last_dts 295803 difference 237588 last_duration 21643. reorder_queue_size=0]
11/29/24 09:29:38.349991 zmc_m2[9876].WAR-zm_videostore.cpp/1479 [non increasing dts, fixing. our dts 79297 stream 0 last_dts 317446 difference 238149 last_duration 21643. reorder_queue_size=0]

[iconnor]

I think we have definitely pinpointed the issue. I don't want to revert as that fix was there for a reason. But I really think the calculated duration is wrong so I can look into that.

Still doesn't explain why it doesn't happen using log level 3.

[eggenbef]

I think we have definitely pinpointed the issue. I don't want to revert as that fix was there for a reason. But I really think the calculated duration is wrong so I can look into that.

appreciate it - thank you so much

[eggenbef]

Still doesn't explain why it doesn't happen using log level 3.

couldn't non-monotonic dts values be caused by heavy network traffic e.g. if packages are dropped? this might happen with a higher probability when debugging is off because the system will then probably run more performant and hence with a higher network impact.

even with debug level 1 enabled a truly non-monotonic dts was actually only identified once according to the log i shared: when the dts value was identical to last_dts at the beginning of the log. this is btw a scenariao which is not treated as non-monotonic in 1.36.33 and for which no warning but only a debug 1 message exists . this is another change introduced with 1.36.34/35 that may explain why the issue reported in this thread has never been experienced with 1.36.33.

[iconnor]

yes but we aren't using the incoming pkt timestamps when encoding. We use wall clock. One thing that can happen though, is that we are using /1000000 timebase because we are using microsecond precision. The mp4 stream timebase is typically /90000. So we lose some precision and if packets come in too close together, we could end up with packets with the same dts after conversion.

It's kinda tricky but so far I have only seen that with audio packets.

[eggenbef]

the reason why this issue happens with 1.36.35 but not with 1.36.33 is according to the analysis of the videostore code and the shared logs that the way non-monotonic dts values are being identified was changed as part of 1.36.34 or 35.

anyway, it seems that no one else has a configuration/setup which is impacted by this issue and i have decided not to upgrade to > 1.36.33 - so never mind.