zmc_m dying repeatedly

dsdee · Post by **dsdee** » Tue May 09, 2006 1:36 pm

using ZM 1.22.1.

I've upped the buffer size, i've changed it back to system default (yes, i've rebooted between them).

i have two network cameras, Panasonic BL-C10A's.

My zmc_m# processes keep dying more and more frequently since i upgraded from 1.22.0 to 1.22.1, with the following messages:

Code: Select all

May  9 07:25:14 ogtzeta zmc_m2[10255]: ERR [Found unsupported content type '']
May  9 07:25:14 ogtzeta zmdc[4889]: ERR ['zmc -m 2' exited abnormally, exit status 255]

Nothing has changed with the physical camera configs, themselves, so I'm figuring it is something in the ZM code.

Both cameras are set to 'modetect', although the problem occurs whether the cams are set to 'modetect' or 'monitor'

I've tried the following trying to alleviate this problem:
1) Turned on and off the Network/Regular Expression option (used to work fine with it off)
2) Turned on and off the "Farm Out Analysis" option (had been working fine with this on)

Buffering is set as follow:

Code: Select all

ImageBufferCount   	36  	28
WarmupCount 	1 	1
PreEventCount 	9 	6
PostEventCount 	9 	8
AlarmFrameCount 	1 	1
SectionLength 	600 	600
FrameSkip 	0 	0
MaxFPS 	5.00 	3.00
AlarmMaxFPS 	6.00 	4.00

Probably related: I am often seeing events in the event log with large-# durations, eg, 12460056.46, because one of the frames is showing up with a timestamp of 17:00:00, which would equate to my "00:00:00" when adjusted for GMT, that is:

Code: Select all

Frame Id 	Alarm Frame 	Time Stamp 	Time Delta 	Score
1 	No 	07:25:11 	-2.00 	0
2 	No 	07:25:11 	-1.67 	0
3 	No 	07:25:12 	-1.31 	0
4 	No 	07:25:12 	-0.98 	0
5 	No 	07:25:12 	-0.65 	0
6 	No 	07:25:13 	-0.28 	0
7 	Yes 	17:00:00 	9,999,999.99 	2

Hopefully that's enough information to go on. Any help would be mucho appreciated...

--David

dsdee · Post by **dsdee** » Wed May 10, 2006 1:21 pm

Thoughts on whether to play more with buffer sizing, memory problems, speed problems, or what ???

Thanks

Post by **zoneminder** » Wed May 10, 2006 2:03 pm

Without anything definate to go on I don't know what this might be. Your 'unsupported content type' message inplies that the cameras are returning bogus strings after the content-type header, if this is regular you could try capturing it with wget. Otherwise I would suggest putting up the debug level and capturing some debug just prior to the death of the process. That should at least give us something to go on.

dsdee · Post by **dsdee** » Wed May 10, 2006 3:23 pm

here's the debug log for a zmc right before it died.

Looking at my syslog (which logs "*.*" nothing else appeared to be doing much around that time other than the ZMC stuff logging.

My cam1 was fine through this time, only cam2 erred (same problem).

however, 10 mins later (as i'm composing this), cam 1 erred with the same issue (unsupported content type) although it caused the problem with the 00:00:00 timestamps (and the 12366644.23 secs apparent duration)

here's the 09:01 failure:

Code: Select all

...
05/10/06 09:06:06.253203 zmc_m2[27735].DB3-zm_remote_camera.cpp/923 [Got subcontent type 'image/jpeg']
05/10/06 09:06:06.253252 zmc_m2[27735].DB3-zm_remote_camera.cpp/979 [Got end of image by length, content-length = 47831]
05/10/06 09:06:06.253301 zmc_m2[27735].DB3-zm_remote_camera.cpp/1045 [Returning 47831 (50885) bytes of captured content]
05/10/06 09:06:06.592915 zmc_m2[27735].DB4-zm_remote_camera.cpp/878 [Got boundary subheader '--myboundary
Content-length: 947
Content-type: image/jpeg

ï¿½ï¿½ï¿½ï¿½']
05/10/06 09:06:06.593027 zmc_m2[27735].DB4-zm_remote_camera.cpp/884 [Got content length subheader ' 947']
05/10/06 09:06:06.593210 zmc_m2[27735].DB4-zm_remote_camera.cpp/890 [Got content type subheader ' image/jpeg']
05/10/06 09:06:06.593262 zmc_m2[27735].DB3-zm_remote_camera.cpp/910 [Got boundary '--myboundary']
05/10/06 09:06:06.593314 zmc_m2[27735].DB3-zm_remote_camera.cpp/916 [Got subcontent length '947']
05/10/06 09:06:06.593361 zmc_m2[27735].DB3-zm_remote_camera.cpp/923 [Got subcontent type 'image/jpeg']
05/10/06 09:06:06.593409 zmc_m2[27735].DB3-zm_remote_camera.cpp/979 [Got end of image by length, content-length = 947]
05/10/06 09:06:06.593458 zmc_m2[27735].DB3-zm_remote_camera.cpp/1045 [Returning 947 (2989) bytes of captured content]
05/10/06 09:06:06.932920 zmc_m2[27735].DB4-zm_remote_camera.cpp/878 [Got boundary subheader '--myboundary
Content-length: 947
Content-type: image/jpeg

ï¿½ï¿½ï¿½ï¿½']
05/10/06 09:06:06.933030 zmc_m2[27735].DB4-zm_remote_camera.cpp/884 [Got content length subheader ' 947']
05/10/06 09:06:06.933080 zmc_m2[27735].DB4-zm_remote_camera.cpp/890 [Got content type subheader ' image/jpeg']
05/10/06 09:06:06.933128 zmc_m2[27735].DB3-zm_remote_camera.cpp/910 [Got boundary '--myboundary']
05/10/06 09:06:06.933179 zmc_m2[27735].DB3-zm_remote_camera.cpp/916 [Got subcontent length '947']
05/10/06 09:06:06.933227 zmc_m2[27735].DB3-zm_remote_camera.cpp/923 [Got subcontent type 'image/jpeg']
05/10/06 09:06:06.933276 zmc_m2[27735].DB3-zm_remote_camera.cpp/979 [Got end of image by length, content-length = 947]
05/10/06 09:06:06.933324 zmc_m2[27735].DB3-zm_remote_camera.cpp/1045 [Returning 947 (1977) bytes of captured content]
05/10/06 09:06:07.188938 zmc_m2[27735].DB4-zm_remote_camera.cpp/878 [Got boundary subheader '--myboundary
Content-length: 947
Content-type: image/jpeg

ï¿½ï¿½ï¿½ï¿½']
05/10/06 09:06:07.189049 zmc_m2[27735].DB4-zm_remote_camera.cpp/884 [Got content length subheader ' 947']
05/10/06 09:06:07.189099 zmc_m2[27735].DB4-zm_remote_camera.cpp/890 [Got content type subheader ' image/jpeg']
05/10/06 09:06:07.189147 zmc_m2[27735].DB3-zm_remote_camera.cpp/910 [Got boundary '--myboundary']
05/10/06 09:06:07.189198 zmc_m2[27735].DB3-zm_remote_camera.cpp/916 [Got subcontent length '947']
05/10/06 09:06:07.189245 zmc_m2[27735].DB3-zm_remote_camera.cpp/923 [Got subcontent type 'image/jpeg']
05/10/06 09:06:07.189296 zmc_m2[27735].DB3-zm_remote_camera.cpp/979 [Got end of image by length, content-length = 947]
05/10/06 09:06:07.189346 zmc_m2[27735].DB3-zm_remote_camera.cpp/1045 [Returning 947 (965) bytes of captured content]
05/10/06 09:06:07.444965 zmc_m2[27735].DB4-zm_remote_camera.cpp/878 [Got boundary subheader '--myboundary

ï¿½dï¿½mï¿½9e-!$ï¿½ï¿½ï¿½Ô»']
05/10/06 09:06:07.445082 zmc_m2[27735].DB3-zm_remote_camera.cpp/910 [Got boundary '--myboundary']
05/10/06 09:06:07.445133 zmc_m2[27735].DB3-zm_remote_camera.cpp/916 [Got subcontent length '0']
05/10/06 09:06:07.445181 zmc_m2[27735].DB3-zm_remote_camera.cpp/923 [Got subcontent type '']
05/10/06 09:06:07.445230 zmc_m2[27735].ERR-zm_remote_camera.cpp/955 [Found unsupported content type '']
[ogtzeta!pts/2!dsdee!292] 9:19am /tmp/zm ->

Post by **zoneminder** » Wed May 10, 2006 4:07 pm

What looks a little odd is that at the top of your log it appears to be processing an image of 47831 bytes. Then the next one appears with these headers

Content-length: 947
Content-type: image/jpeg

which seems rather small for an image. Then after that image you get a boundary with nothing after it. At first glance it does look like a problem with the stream from your camera but I can't think why it would be behaving like this.

If you get this a lot when I would suggest doing a

Code: Select all

wget -s -S <path to image> > wget.log

and letting it run for a while and then inspecting the log to see if we can catch exactly what it is sending.

dsdee · Post by **dsdee** » Wed May 10, 2006 4:52 pm

Bingo. That pointed me directly to it, after looking at the other logs I had captured earlier today...

So the Panasonic Network Cameras evidently have a setting that says "after XXX minutes of continuous motion viewing, change the display to refresh the image YYY seconds"

I had my cam1 set to 30 minutes (and then 3seconds), and cam2 set to 10 minutes (and then 3 seconds), which coincided with the intervals-between-failures of the zmc captures.

I've bumped both those up to 60 minutes, and things should stabilize. I'm not sure why i didn't see this under 1.22.0, unless it just handled the restart a bit quieter, possibly without leaving the black frames in the "picture"

-----------

ok, so that leaves only one remaining issue:

When these failures happen, they're still causing the infinity(?) duration events to be recorded in the event log.

Phil, if I haven't explained that one sufficiently, or correctly, let me know, and I can set u up with an account here so you can view the Eventlogs...

Thanks for pointing me in a direction that allowed me to find this!!!

--David

Post by **zoneminder** » Thu May 11, 2006 10:22 am

I will have a look and see if I can see why the events are created like this. Do you think you could capture some debug from zma (rather than zmc) when these events are captured. That might help me track this down.

dsdee · Post by **dsdee** » Thu May 11, 2006 1:49 pm

Thanks Phil;

I've turned up debug, and I've turned the cam timeout back down to hopefully cause a failure to happen sooner than later, so that I can capture the info for you. In the past 90 mins it's been running like that, it of course has had the ZMC failures we talked about yesterday, but the infinity-times have not happened as of yet. I'll keep a watch out for the results.

Thanks,
David

dsdee · Post by **dsdee** » Thu May 11, 2006 10:24 pm

ok, I think I've narrowed down the culprit.

I can't say why the frames are coming up as part of the event in question, but the answer is that some of the events are not there, so (probably) fstat returns a 0 or -1, which diff'ed with the 'end time' of the event (or beginning time if it's the ending frames that are missing) comes up with the large duration number.

So, then, the question is: why are some of the frames of the event gone, and some are not ?

Well, it appears that ZMFilter is removing some "current" events (ie, within the last minute or two) when it runs, which would be part of the problem.

I am also noting that zmaudit _may_ (need to watch this one closer) be removing event-frames/events of events that aren't completely in the database yet (or, it may be current events that zmfilter is removing at the same time that zma/f is inserting into the database). I'm not sure on this one.

Which leaves the question of: Why is ZMFilter removing "current" events ?? Is there something funky in Filter queries?? from mysql, my Filters line in the database is:

Code: Select all

trms=2&obr1=&cbr1=&attr1=Archived&op1==&val1=0&cnj2=and&obr2=&cbr2=&attr2=DateTime&op2=<&val2=-5 days&sort_field=Id&sort_asc=1&limit=40

or, more textually:
Archive Status -- "equal to" -- Unarchived Only
and Date/Time -- less than -- "-5 days"
sort by -- id -- Asc
limit to first -- 40 -- results

so it shouldn't be getting anything "current", except for maybe if the timestamp for the frames was "before" the date, which would happen if it was 0/-1 ??

I didn't see any changes in zmfilter that look like they would've affected this, but maybe I missed something.

Or, maybe I'm looking the wrong place, and it's the frame-writer that's writing/inserting with incorrect dates??

Phil ???

Thanks,
David

dsdee · Post by **dsdee** » Fri May 12, 2006 12:48 am

ok, when a signal is lost, and then reacquired, an event is made in the DB as:

Code: Select all

05/11/06 18:03:57.938458 zmfilter[7516].DBG [Checking event 11898]
05/11/06 18:03:57.938831 zmfilter[7516].INF [Deleting event 11898 vvv]
05/11/06 18:03:57.940280 zmfilter[7516].DBG [$VAR1 = {
          'Time' => '0',
          'AvgScore' => '100',
          'Videoed' => '0',
          'Archived' => '0',
          'Uploaded' => '0',
          'MonitorName' => 'Cam2',
          'DefaultScale' => '75',
          'MaxScore' => '100',
          'DefaultRate' => '100',
          'StartTime' => '1969-12-31 17:00:00',
          'Frames' => '12',
          'Emailed' => '0',
          'MonitorId' => '2',
          'Notes' => 'Signal: Reacquired',
          'Id' => '11898',
          'TotScore' => '100',
          'Executed' => '0',
          'Cause' => 'Signal',
          'Messaged' => '0',
          'Length' => '0.00',
          'AlarmFrames' => '1',
          'EndTime' => '1969-12-31 17:00:00',
          'Name' => 'Event-11898'
        };]
05/11/06 18:03:57.940674 zmfilter[7516].INF [Deleting event 11898 ^^^]
05/11/06 18:03:57.942803 zmfilter[7516].INF [Sleeping for 60 seconds]

In this case, the above event ID is 11898. Looking at *11897*, I see the problem:

- 3 frames of good captures, and then 9 frames of black.
- The duration on 11897 is 12249099.54 seconds

the 12 files in the 11897 directory are:

Code: Select all

-rw-r--r--  1 apache apache 50097 May 11 18:01 001-capture.jpg
-rw-r--r--  1 apache apache 50173 May 11 18:01 002-capture.jpg
-rw-r--r--  1 apache apache 50096 May 11 18:01 003-capture.jpg
-rw-r--r--  1 apache apache  7614 May 11 18:01 004-capture.jpg
-rw-r--r--  1 apache apache  7614 May 11 18:01 005-capture.jpg
-rw-r--r--  1 apache apache 12292 May 11 18:01 006-analyse.jpg
-rw-r--r--  1 apache apache  7614 May 11 18:01 006-capture.jpg
-rw-r--r--  1 apache apache  7614 May 11 18:01 007-capture.jpg
-rw-r--r--  1 apache apache  7614 May 11 18:01 008-capture.jpg
-rw-r--r--  1 apache apache  7614 May 11 18:01 009-capture.jpg
-rw-r--r--  1 apache apache  7614 May 11 18:01 010-capture.jpg
-rw-r--r--  1 apache apache  7614 May 11 18:01 011-capture.jpg
-rw-r--r--  1 apache apache  7614 May 11 18:01 012-capture.jpg

and the entries for the event are:

Code: Select all

1 	No 	18:01:05 	-5.14  	0
2 	No 	18:01:05 	-4.81 	0
3 	No 	17:00:00 	9,999,999.99 	0
4 	No 	17:00:00 	9,999,999.99 	0
5 	No 	17:00:00 	9,999,999.99 	0
6 	Yes 	17:00:00 	9,999,999.99 	100
7 	No 	17:00:00 	9,999,999.99 	0
8 	No 	17:00:00 	9,999,999.99 	0
9 	No 	17:00:00 	9,999,999.99 	0
10 	No 	17:00:00 	9,999,999.99 	0
11 	No 	17:00:00 	9,999,999.99 	0
12 	No 	17:00:00 	9,999,999.99 	0

Post by **zoneminder** » Fri May 12, 2006 11:13 am

Thanks. I will see if I can find anything from this.

ZoneMinder Forums

zmc_m dying repeatedly

zmc_m dying repeatedly

Any thoughts on this??

ok, here's the subcontent type issue:

Bingo.... (aka, "And then there was only one issue left

waiting...

Long Duration Events

signal reacquired...