Section length not working anymore

[jbg70]

Hi,
I thing it is not depending to zoneminder bug, but something broken in my system!
I am using mocord mode and debian buster updated.
Even if I change the section length from 600 to 6000, or some different numbers, every event lasts 60 seconds! Sometime 120 seconds.
Rolling back to 1.30.4 does not solve the problem.

A fresh install on debian buster fully updated works nice.

Just to understand....
Where can I check to solve the problem?

Thanks.

[iconnor]

Look in the logs. Maybe even turn debug on.

The reason why events start/stop is logged in zma logs.

[jbg70]

Testing conditions:
1 cam active
Record mode
Event length = 600
Debug active
All Debug data go only into zm_debug.log
Debug level 9

Code: Select all

cat zm_debug.log |grep Closing
12/12/18 22:56:48.515045 zma_m1[17920].INF-zm_monitor.cpp/1460 [CAM00: 9603 - Closing event 1464929, section end forced ]
12/12/18 22:57:48.544172 zma_m1[17920].INF-zm_monitor.cpp/1460 [CAM00: 10800 - Closing event 1464930, section end forced ]
12/12/18 22:59:48.536801 zma_m1[17920].INF-zm_monitor.cpp/1460 [CAM00: 13194 - Closing event 1464931, section end forced ]
12/12/18 23:00:00.044038 zma_m1[17920].INF-zm_monitor.cpp/1460 [CAM00: 13424 - Closing event 1464932, section end forced ]
12/12/18 23:01:48.531831 zma_m1[17920].INF-zm_monitor.cpp/1460 [CAM00: 15585 - Closing event 1464933, section end forced ]
12/12/18 23:03:48.543720 zma_m1[17920].INF-zm_monitor.cpp/1460 [CAM00: 17982 - Closing event 1464934, section end forced ]
12/12/18 23:04:48.515761 zma_m1[17920].INF-zm_monitor.cpp/1460 [CAM00: 19179 - Closing event 1464935, section end forced ]
12/12/18 23:07:48.543843 zma_m1[17920].INF-zm_monitor.cpp/1460 [CAM00: 22769 - Closing event 1464936, section end forced ]
12/12/18 23:09:48.544012 zma_m1[17920].INF-zm_monitor.cpp/1460 [CAM00: 25158 - Closing event 1464937, section end forced ]
12/12/18 23:10:00.034974 zma_m1[17920].INF-zm_monitor.cpp/1460 [CAM00: 25388 - Closing event 1464938, section end forced ]
12/12/18 23:12:48.569085 zma_m1[17920].INF-zm_monitor.cpp/1460 [CAM00: 28745 - Closing event 1464939, section end forced ]
12/12/18 23:13:48.537074 zma_m1[17920].INF-zm_monitor.cpp/1460 [CAM00: 29939 - Closing event 1464940, section end forced ]
12/12/18 23:14:48.526426 zma_m1[17920].INF-zm_monitor.cpp/1460 [CAM00: 31134 - Closing event 1464941, section end forced ]

All events < 600 sec.

Going a little bit into the log, near event closing time, to avoid to fill the post with logs:

Code: Select all

cat zm_debug.log | grep '23:13:48.5'
12/12/18 23:13:48.526966 zmc_m1[17867].DB5-zm_ffmpeg_camera.cpp/206 [Got packet from stream 1 dts (12028095) pts(12028095)]
12/12/18 23:13:48.527253 zmc_m1[17867].DB4-zm_ffmpeg_camera.cpp/294 [Different stream_index 1]
12/12/18 23:13:48.527868 zmc_m1[17867].DB5-zm_ffmpeg_camera.cpp/206 [Got packet from stream 0 dts (135315340) pts(135315340)]
12/12/18 23:13:48.530456 zmc_m1[17867].DB4-zm_ffmpeg_camera.cpp/260 [Decoded video packet at frame 29982]
12/12/18 23:13:48.530678 zmc_m1[17867].DB4-zm_ffmpeg_camera.cpp/263 [Got frame 29982]
12/12/18 23:13:48.534449 zmc_m1[17867].DB4-zm_monitor.cpp/2396 [Return from Capture (1)]
12/12/18 23:13:48.536488 zma_m1[17920].DB4-zm_monitor.cpp/1282 [ReadIndex:81, WriteIndex: 82, PendingFrames = 1, ReadMargin = 129, Step = 1]
12/12/18 23:13:48.536670 zma_m1[17920].DB3-zm_monitor.cpp/1345 [Motion detection is enabled signal(1) signal_change(0)]
12/12/18 23:13:48.536794 zma_m1[17920].DB3-zm_monitor.cpp/1445 [Detected new event at (1544652828.534592)]
12/12/18 23:13:48.536950 zma_m1[17920].DB3-zm_monitor.cpp/1453 [Section length (600) Last Section Mod(230), new section mod(228)]
12/12/18 23:13:48.537074 zma_m1[17920].INF-zm_monitor.cpp/1460 [CAM00: 29939 - Closing event 1464940, section end forced ]
12/12/18 23:13:48.537217 zma_m1[17920].DB2-zm_event.cpp/245 [start_time:1544652768.532295 end_time1544652828.537216]
12/12/18 23:13:48.537332 zma_m1[17920].DB1-zm_event.cpp/248 [Adding closing frame 1194 to DB]
12/12/18 23:13:48.537707 zma_m1[17920].DB1-zm_event.cpp/256 [Success writing last frame]
12/12/18 23:13:48.537714 zma_m1[17920].ERR-zm_logger.cpp/564 [Can't insert log entry: sql(12/12/18 23:13:48.537707 zma_m1[17920].DB1-zm_event.cpp/256 [Success writing last frame) error(db is locked)]
12/12/18 23:13:48.537726 zma_m1[17920].WAR-zm_db.cpp/35 [Calling zmDbConnect when already connected]
12/12/18 23:13:48.538388 zma_m1[17920].DB4-zm_db.cpp/105 [Success running query: SELECT Id FROM States WHERE IsActive=1]
12/12/18 23:13:48.538397 zma_m1[17920].ERR-zm_logger.cpp/564 [Can't insert log entry: sql(12/12/18 23:13:48.538388 zma_m1[17920].DB4-zm_db.cpp/105 [Success running query: SELECT Id FROM States WHERE IsActive=1) error(db is locked)]
12/12/18 23:13:48.538409 zma_m1[17920].WAR-zm_db.cpp/35 [Calling zmDbConnect when already connected]
12/12/18 23:13:48.538419 zma_m1[17920].DB5-zm_db.cpp/141 [Success]
12/12/18 23:13:48.538931 zma_m1[17920].INF-zm_monitor.cpp/1482 [CAM00: 29939 - Opening new event 1464941, section start]
12/12/18 23:13:48.539033 zma_m1[17920].DB1-zm_event.cpp/519 [Writing capture frame 1 to /var/cache/zoneminder/events/1/2018-12-12/1464941/00001-capture.jpg]
12/12/18 23:13:48.539135 zma_m1[17920].DB3-zm_event.cpp/293 [Writing image to /var/cache/zoneminder/events/1/2018-12-12/1464941/00001-capture.jpg]
12/12/18 23:13:48.544457 zma_m1[17920].DB1-zm_event.cpp/547 [Adding frame 1 of type "Normal" to DB]
12/12/18 23:13:48.567473 zmc_m1[17867].DB5-zm_ffmpeg_camera.cpp/206 [Got packet from stream 0 dts (135319846) pts(135319846)]
12/12/18 23:13:48.570174 zmc_m1[17867].DB4-zm_ffmpeg_camera.cpp/260 [Decoded video packet at frame 29983]
12/12/18 23:13:48.570370 zmc_m1[17867].DB4-zm_ffmpeg_camera.cpp/263 [Got frame 29983]
12/12/18 23:13:48.574314 zmc_m1[17867].DB4-zm_monitor.cpp/2396 [Return from Capture (1)]
12/12/18 23:13:48.578188 zma_m1[17920].DB4-zm_monitor.cpp/1282 [ReadIndex:82, WriteIndex: 83, PendingFrames = 1, ReadMargin = 129, Step = 1]
12/12/18 23:13:48.578352 zma_m1[17920].DB3-zm_monitor.cpp/1345 [Motion detection is enabled signal(1) signal_change(0)]
12/12/18 23:13:48.578480 zma_m1[17920].DB3-zm_monitor.cpp/1445 [Detected new event at (1544652828.574462)]
12/12/18 23:13:48.578588 zma_m1[17920].DB3-zm_monitor.cpp/1453 [Section length (600) Last Section Mod(0), new section mod(228)]
12/12/18 23:13:48.578701 zma_m1[17920].DB1-zm_event.cpp/519 [Writing capture frame 2 to /var/cache/zoneminder/events/1/2018-12-12/1464941/00002-capture.jpg]
12/12/18 23:13:48.578804 zma_m1[17920].DB3-zm_event.cpp/293 [Writing image to /var/cache/zoneminder/events/1/2018-12-12/1464941/00002-capture.jpg]
12/12/18 23:13:48.580920 zmc_m1[17867].DB5-zm_ffmpeg_camera.cpp/206 [Got packet from stream 1 dts (12028607) pts(12028607)]
12/12/18 23:13:48.581071 zmc_m1[17867].DB4-zm_ffmpeg_camera.cpp/294 [Different stream_index 1]
12/12/18 23:13:48.584220 zma_m1[17920].DB1-zm_event.cpp/547 [Adding frame 2 of type "Normal" to DB]

It this useful?

Thanks.

[iconnor]

Your debug logs pointed out another bug which I have now fixed in master.

However I don't the issue here is a bug. What do you have for Options -> Config -> Event_Close_Mode ? I'm betting it's something other than time.

[jbg70]

I double checked and it is "time"!
That is not a bug I suspected and said on my first post, since on a fresh debian installation, I do not have the problem.
So I looked for a suggestion to look somewhere in my system, but I do not know where!
Is there some system call, somewhere in ZM code that close the event?

Thanks.

PS... Happy, at least, to help you to fix a bug!

[flyingpiglet]

I would like to join this company of section length friends on ZM v.1.32.3.
I noticed zma/zmc processes getting signal 15 and restarting which leads to current section end and the next section start.
This happens on my system three-four times faster than default section length (600s) lasts.
I also remember that after the very first install the section length worked for me.
There is no disk space problem. Actually i have no idea what's the problem.

[iconnor]

This may mean that zmwatch is killing them. Increase values of WATCH_MAX_DELAY