WTH? zmdc thinks zmc exited 255 but it's actually running.

[wlssenatus]

So I've been upgrading my debian to testing. I have a long-existing zoneminder install, and now I am on 1.30.0+dfsg-2.

I can't view streams and the zoneminder web console says it isn't running, yet it is catching events; the console shows e.g. 2 in the last hour.

Cranked up some specific debugging and I see the following (excerpted)

Code: Select all

08/02/17 20:42:49.966548 zmdc[26817].INF ['zmc -d /dev/video3' starting at 17/02/08 20:42:49, pid = 26909]
08/02/17 20:42:49.966605 zmdc[26909].INF ['zmc -d /dev/video3' started at 17/02/08 20:42:49]
08/02/17 20:42:50.099670 zmdc[26817].ERR ['zmc -d /dev/video3' exited abnormally, exit status 255]
08/02/17 20:42:50.101801 zmdc[26817].INF [Starting pending process, zmc -d /dev/video3]
08/02/17 20:42:50.107214 zmdc[26817].INF ['zmc -d /dev/video3' starting at 17/02/08 20:42:50, pid = 26912]
08/02/17 20:42:50.107217 zmdc[26912].INF ['zmc -d /dev/video3' started at 17/02/08 20:42:50]

Note that I only have one CATV camera on video3. But... two processes (26909 and 26912)?

zm_debug.log.26909:

Code: Select all

2/08/17 20:42:50.093727 zmc_dvideo3[26909].DB1-zm_logger.cpp/234 [LogOpts: level=DB9/DB9, screen=OFF, database=ERR, logfile=DB9->/tmp/zm/zm_debug.log.26909, syslog=ERR]
02/08/17 20:42:50.093802 zmc_dvideo3[26909].DB1-zm_utils.cpp/265 [Detected a x86\x86-64 processor with SSE3]
02/08/17 20:42:50.093819 zmc_dvideo3[26909].DB1-zm_monitor.cpp/2060 [Loading Local Monitors with select Id, Name, ServerId, Function+0, Enabled, LinkedMonitors, Device, Channel, Format, V4LMultiBuffer, V4LCapturesPerFrame, Method, Width, Height, Colours, Palette, Orientation+0, Deinterlacing, Brightness, Contrast, Hue, Colour, EventPrefix, LabelFormat, LabelX, LabelY, LabelSize, ImageBufferCount, WarmupCount, PreEventCount, PostEventCount, StreamReplayBuffer, AlarmFrameCount, SectionLength, FrameSkip, MotionFrameSkip, AnalysisFPS, AnalysisUpdateDelay, MaxFPS, AlarmMaxFPS, FPSReportInterval, RefBlendPerc, AlarmRefBlendPerc, TrackMotion, SignalCheckColour, Exif from Monitors where Function != 'None' and Type = 'Local' AND Device='/dev/video3']
02/08/17 20:42:50.094419 zmc_dvideo3[26909].DB4-zm_db.cpp/89 [Success running query: select Id, Name, ServerId, Function+0, Enabled, LinkedMonitors, Device, Channel, Format, V4LMultiBuffer, V4LCapturesPerFrame, Method, Width, Height, Colours, Palette, Orientation+0, Deinterlacing, Brightness, Contrast, Hue, Colour, EventPrefix, LabelFormat, LabelX, LabelY, LabelSize, ImageBufferCount, WarmupCount, PreEventCount, PostEventCount, StreamReplayBuffer, AlarmFrameCount, SectionLength, FrameSkip, MotionFrameSkip, AnalysisFPS, AnalysisUpdateDelay, MaxFPS, AlarmMaxFPS, FPSReportInterval, RefBlendPerc, AlarmRefBlendPerc, TrackMotion, SignalCheckColour, Exif from Monitors where Function != 'None' and Type = 'Local' AND Device='/dev/video3']
02/08/17 20:42:50.094444 zmc_dvideo3[26909].DB1-zm_monitor.cpp/2068 [Got 1 monitors]
02/08/17 20:42:50.094457 zmc_dvideo3[26909].DB1-zm_monitor.cpp/2101 [Got 1 for v4l_captures_per_frame]
02/08/17 20:42:50.094485 zmc_dvideo3[26909].DB2-zm_camera.cpp/39 [New camera id: 5 width: 768 height: 576 colours: 3 subpixelorder: 6 capture: 1]
02/08/17 20:42:50.094521 zmc_dvideo3[26909].DB2-zm_local_camera.cpp/309 [V4L support enabled, using V4L2 api]
02/08/17 20:42:50.094532 zmc_dvideo3[26909].DB2-zm_local_camera.cpp/332 [little-endian processor detected]
02/08/17 20:42:50.094543 zmc_dvideo3[26909].INF-zm_local_camera.cpp/412 [No direct match for the selected palette (^D02/08/17 20:42:50.094554 zmc_dvideo3[26909].DB2-zm_local_camera.cpp/419 [Using swscale for image conversion]
02/08/17 20:42:50.094582 zmc_dvideo3[26909].DB3-zm_local_camera.cpp/616 [Selected subpixelorder: 6]
02/08/17 20:42:50.095211 zmc_dvideo3[26909].DB2-zm_image.cpp/176 [Blend: Using SSE2 fast blend function]
02/08/17 20:42:50.095223 zmc_dvideo3[26909].DB2-zm_image.cpp/229 [Delta: Using SSE2 delta functions]
02/08/17 20:42:50.095233 zmc_dvideo3[26909].DB2-zm_image.cpp/263 [Deinterlace: Using standard delta functions]
02/08/17 20:42:50.095243 zmc_dvideo3[26909].DB2-zm_image.cpp/269 [Image buffer copy: Using SSE2 aligned memcpy]
02/08/17 20:42:50.095253 zmc_dvideo3[26909].DB3-zm_image.cpp/276 [Setting up static colour tables]
02/08/17 20:42:50.095298 zmc_dvideo3[26909].DB1-zm_monitor.cpp/390 [monitor purpose=1]
02/08/17 20:42:50.095309 zmc_dvideo3[26909].DB1-zm_monitor.cpp/398 [mem.size=53085760]

zm_debug.log.26912 (excerpted):

Code: Select all

02/08/17 20:42:50.214807 zmc_dvideo3[26912].DB1-zm_logger.cpp/234 [LogOpts: level=DB9/DB9, screen=OFF, database=ERR, logfile=DB9->/tmp/zm/zm_debug.log.26912, syslog=ERR]
02/08/17 20:42:50.214912 zmc_dvideo3[26912].DB1-zm_utils.cpp/265 [Detected a x86\x86-64 processor with SSE3]
02/08/17 20:42:50.214929 zmc_dvideo3[26912].DB1-zm_monitor.cpp/2060 [Loading Local Monitors with select Id, Name, ServerId, Function+0, Enabled, LinkedMonitors, Device, Channel, Format, V4LMultiBuffer, V4LCapturesPerFrame, Method, Width, Height, Colours, Palette, Orientation+0, Deinterlacing, Brightness, Contrast, Hue, Colour, EventPrefix, LabelFormat, LabelX, LabelY, LabelSize, ImageBufferCount, WarmupCount, PreEventCount, PostEventCount, StreamReplayBuffer, AlarmFrameCount, SectionLength, FrameSkip, MotionFrameSkip, AnalysisFPS, AnalysisUpdateDelay, MaxFPS, AlarmMaxFPS, FPSReportInterval, RefBlendPerc, AlarmRefBlendPerc, TrackMotion, SignalCheckColour, Exif from Monitors where Function != 'None' and Type = 'Local' AND Device='/dev/video3']
02/08/17 20:42:50.215515 zmc_dvideo3[26912].DB4-zm_db.cpp/89 [Success running query: select Id, Name, ServerId, Function+0, Enabled, LinkedMonitors, Device, Channel, Format, V4LMultiBuffer, V4LCapturesPerFrame, Method, Width, Height, Colours, Palette, Orientation+0, Deinterlacing, Brightness, Contrast, Hue, Colour, EventPrefix, LabelFormat, LabelX, LabelY, LabelSize, ImageBufferCount, WarmupCount, PreEventCount, PostEventCount, StreamReplayBuffer, AlarmFrameCount, SectionLength, FrameSkip, MotionFrameSkip, AnalysisFPS, AnalysisUpdateDelay, MaxFPS, AlarmMaxFPS, FPSReportInterval, RefBlendPerc, AlarmRefBlendPerc, TrackMotion, SignalCheckColour, Exif from Monitors where Function != 'None' and Type = 'Local' AND Device='/dev/video3']
02/08/17 20:42:50.215539 zmc_dvideo3[26912].DB1-zm_monitor.cpp/2068 [Got 1 monitors]
02/08/17 20:42:50.215551 zmc_dvideo3[26912].DB1-zm_monitor.cpp/2101 [Got 1 for v4l_captures_per_frame]
02/08/17 20:42:50.215580 zmc_dvideo3[26912].DB2-zm_camera.cpp/39 [New camera id: 5 width: 768 height: 576 colours: 3 subpixelorder: 6 capture: 1]
02/08/17 20:42:50.215622 zmc_dvideo3[26912].DB2-zm_local_camera.cpp/309 [V4L support enabled, using V4L2 api]
02/08/17 20:42:50.215633 zmc_dvideo3[26912].DB2-zm_local_camera.cpp/332 [little-endian processor detected]
02/08/17 20:42:50.215644 zmc_dvideo3[26912].INF-zm_local_camera.cpp/412 [No direct match for the selected palette (^D02/08/17 20:42:50.215655 zmc_dvideo3[26912].DB2-zm_local_camera.cpp/419 [Using swscale for image conversion]
02/08/17 20:42:50.215681 zmc_dvideo3[26912].DB3-zm_local_camera.cpp/616 [Selected subpixelorder: 6]
02/08/17 20:42:50.216290 zmc_dvideo3[26912].DB2-zm_image.cpp/176 [Blend: Using SSE2 fast blend function]
02/08/17 20:42:50.216302 zmc_dvideo3[26912].DB2-zm_image.cpp/229 [Delta: Using SSE2 delta functions]
02/08/17 20:42:50.216312 zmc_dvideo3[26912].DB2-zm_image.cpp/263 [Deinterlace: Using standard delta functions]
02/08/17 20:42:50.216322 zmc_dvideo3[26912].DB2-zm_image.cpp/269 [Image buffer copy: Using SSE2 aligned memcpy]
02/08/17 20:42:50.216331 zmc_dvideo3[26912].DB3-zm_image.cpp/276 [Setting up static colour tables]
02/08/17 20:42:50.216375 zmc_dvideo3[26912].DB1-zm_monitor.cpp/390 [monitor purpose=1]
02/08/17 20:42:50.216386 zmc_dvideo3[26912].DB1-zm_monitor.cpp/398 [mem.size=53085760]
02/08/17 20:42:50.216414 zmc_dvideo3[26912].DB1-zm_monitor.cpp/543 [Unable to map file /dev/shm/zm.mmap.5 (53085760 bytes) to locked memory, trying unlocked]
02/08/17 20:42:50.216431 zmc_dvideo3[26912].DB1-zm_monitor.cpp/546 [Mapped file /dev/shm/zm.mmap.5 (53085760 bytes) to locked memory, unlocked]
02/08/17 20:42:50.311263 zmc_dvideo3[26912].DB1-zm_monitor.cpp/449 [Monitor Front has no zones, adding one.]
02/08/17 20:42:50.311383 zmc_dvideo3[26912].DB1-zm_zone.cpp/51 [Initialised zone 0/All - 1 - 768x576 - Rgb:0000ff, CM:3, MnAT:15, MxAT:0, MnAP:50, MxAP:75000, FB:3x3, MnFP:50, MxFP:50000, MnBS:10, MxBS:0, MnB:0, MxB:0, OF: 0, AF: 0]

...

02/08/17 20:42:50.359665 zmc_dvideo3[26912].DB3-zm_local_camera.cpp/798 [Setting up request buffers]
02/08/17 20:42:50.359681 zmc_dvideo3[26912].DB3-zm_local_camera.cpp/811 [Request buffers count is 8]
02/08/17 20:42:50.359712 zmc_dvideo3[26912].DB3-zm_local_camera.cpp/831 [Setting up data buffers: Channels 1 MultiBuffer 0 Buffers: 
8]
02/08/17 20:42:50.359817 zmc_dvideo3[26912].DB3-zm_local_camera.cpp/881 [Configuring video source]
02/08/17 20:42:50.359864 zmc_dvideo3[26912].DB2-zm_local_camera.cpp/1976 [Priming capture]
02/08/17 20:42:50.359880 zmc_dvideo3[26912].DB3-zm_local_camera.cpp/1980 [Queueing buffers]
02/08/17 20:42:50.368831 zmc_dvideo3[26912].DB3-zm_local_camera.cpp/1996 [Starting video stream]
02/08/17 20:42:50.368914 zmc_dvideo3[26912].DB2-zm_local_camera.cpp/2024 [Pre-capturing]
02/08/17 20:42:50.368933 zmc_dvideo3[26912].DB3-zm_local_camera.cpp/2030 [Capturing]
02/08/17 20:42:50.368948 zmc_dvideo3[26912].DB3-zm_local_camera.cpp/2059 [Capturing 1 frames]
02/08/17 20:42:50.468591 zmc_dvideo3[26912].DB3-zm_local_camera.cpp/2083 [Captured frame 0/3 from channel 3]
02/08/17 20:42:50.468646 zmc_dvideo3[26912].DB3-zm_local_camera.cpp/2127 [Performing format conversion]
02/08/17 20:42:50.468661 zmc_dvideo3[26912].DB9-zm_local_camera.cpp/2138 [Calling sws_scale to perform the conversion]
02/08/17 20:42:50.470359 zmc_dvideo3[26912].DB2-zm_local_camera.cpp/2177 [Post-capturing]
02/08/17 20:42:50.470373 zmc_dvideo3[26912].DB3-zm_local_camera.cpp/2202 [Requeueing buffer 0]
02/08/17 20:42:50.470398 zmc_dvideo3[26912].DB2-zm_local_camera.cpp/2024 [Pre-capturing]
02/08/17 20:42:50.470411 zmc_dvideo3[26912].DB3-zm_local_camera.cpp/2030 [Capturing]
02/08/17 20:42:50.470422 zmc_dvideo3[26912].DB3-zm_local_camera.cpp/2059 [Capturing 1 frames]
02/08/17 20:42:50.508590 zmc_dvideo3[26912].DB3-zm_local_camera.cpp/2083 [Captured frame 1/4 from channel 3]
02/08/17 20:42:50.508644 zmc_dvideo3[26912].DB3-zm_local_camera.cpp/2127 [Performing format conversion]
02/08/17 20:42:50.508659 zmc_dvideo3[26912].DB9-zm_local_camera.cpp/2138 [Calling sws_scale to perform the conversion]
02/08/17 20:42:50.510275 zmc_dvideo3[26912].DB2-zm_local_camera.cpp/2177 [Post-capturing]
02/08/17 20:42:50.510288 zmc_dvideo3[26912].DB3-zm_local_camera.cpp/2202 [Requeueing buffer 1]

[SteveGilvarry]

Confused as I see one process dying and the other being started, those processes are not running at the same time.

Code: Select all

08/02/17 20:42:50.099670 zmdc[26817].ERR ['zmc -d /dev/video3' exited abnormally, exit status 255]
08/02/17 20:42:50.101801 zmdc[26817].INF [Starting pending process, zmc -d /dev/video3]

Or was your concern the web saying it was not running, but it still was? In which case I would be checking service status, over what the web guide says.

[wlssenatus]

Confused as I see one process dying and the other being started, those processes are not running at the same time.

Code: Select all

08/02/17 20:42:50.099670 zmdc[26817].ERR ['zmc -d /dev/video3' exited abnormally, exit status 255]
08/02/17 20:42:50.101801 zmdc[26817].INF [Starting pending process, zmc -d /dev/video3]

Or was your concern the web saying it was not running, but it still was? In which case I would be checking service status, over what the web guide says.

Both processes are started by zmdc.pl from the same zmpkg.pl start invocation (which is tied to systemd). I guess my first question would be, is it normal for two zmc processes to be started sequentially (second 0.01 seconds behind the first) for the same camera? I have never examined the startup in detailed debugging before so I am not sure what's normal. If somebody could share what they normally see on the service zoneminder start / systemctl start zoneminder invocation, I would have a "normal" baseline to compare to. Understanding why the first fails with 255 yet the second succeeds, 1/100th of a second later, is a (related?) different question.

[SteveGilvarry]

It starts the first process, which fails, and then starts the second one due to the failure, it is not starting two, just trying to get one to run. Not sure why it failed first time, sometimes it can do that due to something not being ready. You could try debugging it or sometimes I used to get good details with running something like zmc -d /dev/video3 directly, as www-user.

[wlssenatus]

Thanks Steve. Direct run succeeds, but with full 9-level debug I see nothing from zmc itself (either the passed or the failed). Manual strace is no help since the manual invocation of zmc -d /dev/video3 works. I tend to agree with you that there's some race condition. I did not know that zmdc will try to re-launch the process - I consider it a minor bug if it relaunches and succeeds, but passes back a return code for the previous failure, causing zmpkg to think that Zoneminder isn't running.

I have resolved the incident (although not determined the root cause, and I still see that return-failure-on-success a bug) by wiping out my database and recreating it (I only had 8 monitors so it's not too onerous). Obviously I lost my tuned zone settings, but at least it's working. So probably there was an error in the database - it has been upgraded in increments ever since 1.24 or so, and each upgrade is an opportunity for data collision/corruption I suppose.