syslog flooded by 1.36.35

[eggenbef]

hi there

having a perfectly running 1.36.33 instance on ubuntu 22.04 i gave 1.36.35 a try on a freshly set up 24.04 box. using the same camera and video settings this resulted in a flood of logs of the videowriter in the zm log and syslog:

Code: Select all

2024-11-04T17:26:43.316615+01:00 myhostname zmc_m1[22164]: WAR [zmc_m1] [non increasing dts, fixing. our dts 25769945 stream 0 last_dts 25830042 difference 60097 last_duration 22500. reorder_queue_size=150]
2024-11-04T17:26:43.493604+01:00 myhostname zmc_m1[22164]: WAR [zmc_m1] [non increasing dts, fixing. our dts 25785808 stream 0 last_dts 25852542 difference 66734 last_duration 22500. reorder_queue_size=150]
2024-11-04T17:26:43.770340+01:00 myhostname zmc_m1[22164]: WAR [zmc_m1] [non increasing dts, fixing. our dts 25792716 stream 0 last_dts 25875042 difference 82326 last_duration 22500. reorder_queue_size=150]
2024-11-04T17:26:43.848736+01:00 myhostname zmc_m1[22164]: WAR [zmc_m1] [non increasing dts, fixing. our dts 25847673 stream 0 last_dts 25897542 difference 49869 last_duration 22500. reorder_queue_size=150]
2024-11-04T17:26:44.451546+01:00 myhostname zmc_m1[22164]: WAR [zmc_m1] [non increasing dts, fixing. our dts 25854185 stream 0 last_dts 25920042 difference 65857 last_duration 22500. reorder_queue_size=150]
2024-11-04T17:26:44.477693+01:00 myhostname zmc_m1[22164]: WAR [zmc_m1] [non increasing dts, fixing. our dts 25879442 stream 0 last_dts 25942542 difference 63100 last_duration 22500. reorder_queue_size=150]

based on various hints in this forum i first set the reorder_queue_size parameter to 2*keyframe interval but since this did not resolve the issue i then increased it continuously - with the only effect that the box eventually ran out of memory.

ffmpeg version on the 24.04 box is 6.1.1-3ubuntu5 while on the 22.04 box it's 4.4.2-0ubuntu0.22.04.1.
various posts suggest that the reason for the above warning is the version of ffmpeg (i.e. > 4.8.). i was not able to downgrade ffmpeg on the 24.04 box but did so with zm and surprisingly version 1.36.33 (which is part of the standard 24.04 distribution) is working perfectly fine on the 24.04 box without changing the ffmpeg version (i.e. running on 6.1.1-3ubuntu5).

anyone else experiencing similar issues with the video writer of 1.36.35?

[Andyrh]

There is a thread about it.

viewtopic.php?t=31827

[eggenbef]

There is a thread about it.

viewtopic.php?t=31827

yes, this is one of the threads i was referring to which seems to say that the root cause of this issue is the version of ffmpeg (i.e. > 4.8.). this doesn't seem to apply here, though. while the issue occurs with zm 1.36.35 on ubuntu 24.04 (ffmpeg version 6.1.1) it does NOT if zm 1.36.33 is installed instead on the same box with the same OS/ffmpeg version as well as the same reolink camera attached and identical camera/zm configuration parameters:

Code: Select all

- Source Type: Ffmpeg
- Function: Mocord, Analysis Enabled
- Source Path: rtsp://myuser:@myhostname:554/h264Preview_01_main
- Method: TCP
- Target colorspace: 24 bit colour
- Capture Resolution: 2304 x 1296
- fps: 4 (camera setting)
- Deinterlacing: Disabled
- Save JPEGs: Frames + Analysis images
- Video Writer: Encode
- OutputCodec: h264
- Encoder: libx264
- Optional Encoder Parameter: crf=23, reorder_queue_size parameter=[see my original post]
- Image Buffer Size: 3
- Maximum Image Buffer Size: 0 (no limit set)
- Warmup Frames: 0
- Pre/Post Event Image Count: 5
- Stream Replay Image Buffer: 0
- Alarm Frame Count: 2
- Section length: 600
- Minimum section length: 20
- Frame Skip: 0
- Motion Frame Skip: 0
- Analysis Update Delay: 0
- FPS Report Interval: 200

[eggenbef]

just gave it another try on a different 22.04 ubuntu box with a flawlessly running 1.36.33 zm instance using standard ffmpeg version 4.4.2-0ubuntu0.22.04.1 and reorder_queue_size=0. zm and camera configurations are identical to the ones previously posted. no warnings were raised with the 1.36.33 installation.

after the upgrade to 1.36.35 with the package from ppa:iconnor/zoneminder-1.36 both zmc_m*.log and syslog are being flooded with warnings even after an increase of reorder_queue_size=500:

Code: Select all

11/14/24, 11:57:29 AM GMT+1	zmc_m2		9616	WAR	non increasing dts, fixing. our dts 10277457 stream 0 last_dts 10439253 difference 161796 last_duration 21643. reorder_queue_size=500	zm_videostore.cpp	1479
11/14/24, 11:57:29 AM GMT+1	zmc_m2		9616	WAR	non increasing dts, fixing. our dts 10261462 stream 0 last_dts 10414002 difference 152540 last_duration 25251. reorder_queue_size=500	zm_videostore.cpp	1479
11/14/24, 11:57:29 AM GMT+1	zmc_m2		9616	WAR	non increasing dts, fixing. our dts 10237150 stream 0 last_dts 10392360 difference 155210 last_duration 21642. reorder_queue_size=500	zm_videostore.cpp	1479
11/14/24, 11:57:28 AM GMT+1	zmc_m2		9616	WAR	non increasing dts, fixing. our dts 10221498 stream 0 last_dts 10370716 difference 149218 last_duration 21644. reorder_queue_size=500	zm_videostore.cpp	1479
11/14/24, 11:57:28 AM GMT+1	zmc_m2		9616	WAR	non increasing dts, fixing. our dts 10215438 stream 0 last_dts 10349073 difference 133635 last_duration 21643. reorder_queue_size=500	zm_videostore.cpp	1479
11/14/24, 11:57:28 AM GMT+1	zmc_m2		9616	WAR	non increasing dts, fixing. our dts 10209764 stream 0 last_dts 10323822 difference 114058 last_duration 25251. reorder_queue_size=500	zm_videostore.cpp	1479
11/14/24, 11:57:28 AM GMT+1	zmc_m2		9616	WAR	non increasing dts, fixing. our dts 10202878 stream 0 last_dts 10302179 difference 99301 last_duration 21643. reorder_queue_size=500	zm_videostore.cpp	1479
11/14/24, 11:57:28 AM GMT+1	zmc_m2		9616	WAR	non increasing dts, fixing. our dts 10109963 stream 0 last_dts 10280536 difference 170573 last_duration 21643. reorder_queue_size=500	zm_videostore.cpp	1479
11/14/24, 11:57:27 AM GMT+1	zmc_m2		9616	WAR	non increasing dts, fixing. our dts 10081165 stream 0 last_dts 10233642 difference 152477 last_duration 25251. reorder_queue_size=500	zm_videostore.cpp	1479
11/14/24, 11:57:27 AM GMT+1	zmc_m2		9616	WAR	non increasing dts, fixing. our dts 10055675 stream 0 last_dts 10211999 difference 156324 last_duration 21643. reorder_queue_size=500	zm_videostore.cpp	1479
11/14/24, 11:57:26 AM GMT+1	zmc_m2		9616	WAR	non increasing dts, fixing. our dts 10041504 stream 0 last_dts 10190356 difference 148852 last_duration 21643. reorder_queue_size=500	zm_videostore.cpp	1479
11/14/24, 11:57:26 AM GMT+1	zmc_m2		9616	WAR	non increasing dts, fixing. our dts 10034488 stream 0 last_dts 10168713 difference 134225 last_duration 21643. reorder_queue_size=500	zm_videostore.cpp	1479
11/14/24, 11:57:26 AM GMT+1	zmc_m2		9616	WAR	non increasing dts, fixing. our dts 10029249 stream 0 last_dts 10143462 difference 114213 last_duration 25251. reorder_queue_size=500	zm_videostore.cpp	1479
11/14/24, 11:57:26 AM GMT+1	zmc_m2		9616	WAR	non increasing dts, fixing. our dts 10022748 stream 0 last_dts 10121819 difference 99071 last_duration 21643. reorder_queue_size=500	zm_videostore.cpp	1479
11/14/24, 11:57:26 AM GMT+1	zmc_m2		9616	WAR	non increasing dts, fixing. our dts 9928261 stream 0 last_dts 10100176 difference 171915 last_duration 21643. reorder_queue_size=500	zm_videostore.cpp	1479
11/14/24, 11:57:25 AM GMT+1	zmc_m2		9616	WAR	non increasing dts, fixing. our dts 9921399 stream 0 last_dts 10078533 difference 157134 last_duration 21643. reorder_queue_size=500	zm_videostore.cpp	1479
11/14/24, 11:57:25 AM GMT+1	zmc_m2		9616	WAR	non increasing dts, fixing. our dts 9897009 stream 0 last_dts 10053284 difference 156275 last_duration 25249. reorder_queue_size=500	zm_videostore.cpp	1479
11/14/24, 11:57:24 AM GMT+1	zmc_m2		9616	WAR	non increasing dts, fixing. our dts 9855982 stream 0 last_dts 9963103 difference 107121 last_duration 25250. reorder_queue_size=500	zm_videostore.cpp	1479

to further narrow down the root cause of this issue, i also attached another camera with different resolution and fps settings but the issue persisted.

any ideas what else i could try?

also, would be great if you could share your setup/configuration details if you are using the video writer of 1.36.35 on an ubuntu LTS system (22.04 or 24.04) with an h264 encoded video stream. thank you.

[ox45tallboy]

I'm also having an issue with the log being flooded, however with a different message. I'm running ZM v1.36.35 on Ubuntu 24.04.1.

My system is a 2009 Compaq HP dc9700 (yes, I know) with a Core 2 Duo 3.0GHz, 8 Gb DDR2, with Ubuntu installed on a 160 GB 7200rpm SATA drive. I currently have one iCamera2 connected via wifi to a router, with the PC hardwired to the router. The PC connects to Internet via a PCI-e Wifi card. It has no PCI-e video, only on-board video.

This is a fresh install, and I've never used Zoneminder before last week when I set this up (so my experience is very limited). I also am not very knowledgeable about Linux, but I've been doing PC and networking installation and support for decades so I know how much I don't know but I'm not afraid to learn.

The system has been up and running for only about 48 hours at this point and my log has almost 95,000 entries.

My log is endless repetition of this:
11/18/24, 10:12:47 PM UTC zmc_m2 44254 WAR Found iterator at beginning of queue. Some thread isn't keeping up zm_packetqueue.cpp 273
11/18/24, 10:12:46 PM UTC zmc_m2 44254 WAR Found iterator at beginning of queue. Some thread isn't keeping up zm_packetqueue.cpp 273
11/18/24, 10:12:45 PM UTC zmc_m2 44254 WAR Found iterator at beginning of queue. Some thread isn't keeping up zm_packetqueue.cpp 273
11/18/24, 10:12:40 PM UTC zmc_m2 44254 WAR Found iterator at beginning of queue. Some thread isn't keeping up zm_packetqueue.cpp 273
11/18/24, 10:12:39 PM UTC zmc_m2 44254 WAR Found iterator at beginning of queue. Some thread isn't keeping up zm_packetqueue.cpp 273

Because my log entries are different from the others that were shared, my issue could be different, and if so I'll start a different thread.

[eggenbef]

Because my log entries are different from the others that were shared, my issue could be different, and if so I'll start a different thread.

yes, yours don't seem to be the "non increasing dts" warnings raised by the video writer of 1.36.35 while the video writer of 1.36.33 works perfectly well within the same environment and the same configuration without any such warnings. may be i should have chosen a more specific title for my post
...but i am still hopeful and would be very grateful indeed if this issue could be looked into by someone who knows the details of the changes which were carried out as part of 1.36.34 or 1.36.35.

[iconnor]

Wait @eggenbef.... you are encoding? These dts issues should only happen with passthrough. We use the wall clock for timestamps when encoding...

Also, why store both jpgs and encode to to mp4?

Also, using 32bit colourspace will save a lot of CPU because we can use SSE instructions...

[eggenbef]

Also, why store both jpgs and encode to to mp4?

Also, using 32bit colourspace will save a lot of CPU because we can use SSE instructions...

storage and cpu are currently not of my main concern as i only have two cameras in operation. may be sth to consider when adding additional cameras but currently i prefer to be on the safe side (therefore both mp4 and jpgs) and thanks for the hint regarding 32bit colorspace. i wasn't aware that 24bit colorspace would need more resources (actually thought the opposite is true).

[eggenbef]

Wait @eggenbef.... you are encoding? These dts issues should only happen with passthrough. We use the wall clock for timestamps when encoding...

yes, i am using zm in mocord mode with analysis enabled and encoding with h264 using libx264 (see earlier in this post for further configuration details). this works flawlessly in my "productive" environment using 1.36.33 . a really great piece of software and as a zm enthusiastic i'd of course like to keep up with any of the continuously released extensions and improvements. Unfortunately, 1.36.34 was not running within my environment due to the api authorization issue of this version. This was resolved with 1.36.35 (thank you!) but with this release i've got "non increasing dts" issues flooding my logs on fresh installs as well as upgraded zm instances, both on ubuntu 22.04 and 24.04 with exactly the same configuration and identical cameras as the perfectly well running 1.36.33 instance. hence i am assuming that this issue is related to one of the changes introduced either with 1.36.34 or 1.36.35:

Code: Select all

11/20/24, 11:55:07 AM GMT+1	zmc_m2		14173	WAR	non increasing dts, fixing. our dts 3729515 stream 0 last_dts 3765915 difference 36400 last_duration 0. reorder_queue_size=500	zm_videostore.cpp	1479
11/20/24, 11:55:06 AM GMT+1	zmc_m2		14173	WAR	non increasing dts, fixing. our dts 3688942 stream 0 last_dts 3765915 difference 76973 last_duration 0. reorder_queue_size=500	zm_videostore.cpp	1479
11/20/24, 11:55:06 AM GMT+1	zmc_m2		14173	WAR	non increasing dts, fixing. our dts 3618750 stream 0 last_dts 3765915 difference 147165 last_duration 0. reorder_queue_size=500	zm_videostore.cpp	1479
11/20/24, 11:55:06 AM GMT+1	zmc_m2		14173	WAR	non increasing dts, fixing. our dts 3550684 stream 0 last_dts 3765915 difference 215231 last_duration 0. reorder_queue_size=500	zm_videostore.cpp	1479
11/20/24, 11:55:06 AM GMT+1	zmc_m2		14173	WAR	non increasing dts, fixing. our dts 3488676 stream 0 last_dts 3765915 difference 277239 last_duration 0. reorder_queue_size=500	zm_videostore.cpp	1479
11/20/24, 11:55:06 AM GMT+1	zmc_m2		14173	WAR	non increasing dts, fixing. our dts 3437365 stream 0 last_dts 3719021 difference 281656 last_duration 25250. reorder_queue_size=500	zm_videostore.cpp	1479
11/20/24, 11:55:06 AM GMT+1	zmc_m2		14173	WAR	non increasing dts, fixing. our dts 3435928 stream 0 last_dts 3697378 difference 261450 last_duration 21643. reorder_queue_size=500	zm_videostore.cpp	1479
11/20/24, 11:55:06 AM GMT+1	zmc_m2		14173	WAR	non increasing dts, fixing. our dts 3371774 stream 0 last_dts 3675735 difference 303961 last_duration 21643. reorder_queue_size=500	zm_videostore.cpp	1479
11/20/24, 11:55:05 AM GMT+1	zmc_m2		14173	WAR	non increasing dts, fixing. our dts 3369716 stream 0 last_dts 3654092 difference 284376 last_duration 21643. reorder_queue_size=500	zm_videostore.cpp	1479
11/20/24, 11:55:05 AM GMT+1	zmc_m2		14173	WAR	non increasing dts, fixing. our dts 3350060 stream 0 last_dts 3628842 difference 278782 last_duration 25250. reorder_queue_size=500	zm_videostore.cpp	1479
11/20/24, 11:55:05 AM GMT+1	zmc_m2		14173	WAR	non increasing dts, fixing. our dts 3327990 stream 0 last_dts 3607198 difference 279208 last_duration 21644. reorder_queue_size=500	zm_videostore.cpp	1479
11/20/24, 11:55:05 AM GMT+1	zmc_m2		14173	WAR	non increasing dts, fixing. our dts 3307518 stream 0 last_dts 3585555 difference 278037 last_duration 21643. reorder_queue_size=500	zm_videostore.cpp	1479
11/20/24, 11:55:05 AM GMT+1	zmc_m2		14173	WAR	non increasing dts, fixing. our dts 3277890 stream 0 last_dts 3563912 difference 286022 last_duration 21643. reorder_queue_size=500	zm_videostore.cpp	1479
11/20/24, 11:55:05 AM GMT+1	zmc_m2		14173	WAR	non increasing dts, fixing. our dts 3256502 stream 0 last_dts 3538662 difference 282160 last_duration 25250. reorder_queue_size=500	zm_videostore.cpp	1479

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

[iconnor]

I'll review the changes with an eye towards encoding...

That last error suggests something very wrong with the encoding..

[eggenbef]

I'll review the changes with an eye towards encoding...

That last error suggests something very wrong with the encoding..

the last error could not be reproduced but i've attached a debug level 3 log with the "non increasing dts" issue which i am experiencing with 1.36.35 regardless of the reorder_queue_size and whether jpegs are saved or not. thank you so much for taking your time to get to the bottom of this issue.

[iconnor]

Ok, I know what is happening. Your packets are coming in out of order, but because you are encoding, we actually use wall clock timestamps. So since we resorted the packets, they are now out of order in terms of wallclock. So I'm disabling the reorder_queue stuff when doing encoding.

You should just remove that setting, it is only useful for passthrough.

[eggenbef]

Ok, I know what is happening. Your packets are coming in out of order, but because you are encoding, we actually use wall clock timestamps. So since we resorted the packets, they are now out of order in terms of wallclock. So I'm disabling the reorder_queue stuff when doing encoding.

You should just remove that setting, it is only useful for passthrough.

thank you so much for your time and the prompt reply
reorder_queue_size was obviously wrongly assumed to be a potential solution for this problem which, however, also exists on 1.36.35 if the reorder_queue_size option is not set. attached please find the logs just taken earlier today from an 1.36.35 installation on ubuntu 24.04 with camera/zm configuration identical to the ones included in the beginning of this post and reorder_queue_size option not set. i tried several times and the problem did not occur when debugging level 3 was activated but it always occurred when debugging was off or set to level 1. hopefully this information will be helpful to get to the bottom of this issue which does not occur with 1.36.33 using the otherwise same setup/configuration.
kind regards and again many thanks!

[iconnor]

I really need level 3. level 1 doesn't contain the timestamps.

It isn't clear to me why we would get out of order packets from the codec if we are stuff in order packets into it... also, you'd think I'd be able to reproduce this. Which I will try to do.

[iconnor]

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