Page 2 of 4
Posted: Tue Mar 01, 2005 8:48 am
by zoneminder
Yes, I should have made that clear. Just 'make', 'make install' and then the changes will take effect the next time you restart ZM.
Phil[/code]
Posted: Tue Mar 01, 2005 3:13 pm
by Eklectick
Well today in the morning upon checking I found that two cameras had lost yet again one event
I struggled my way into the events trying to find which one was lost and found the following...
Cameras that are not losing events show the directory in this manner:
See how folders are created every ten minutes?
Now, on the lost event camera folder I saw this....
The time and date corresponds with my visit to the console. But events do not show times and dates on a "normal" fashion.
But... on the other camera where the event was lost, date and time runs down normal, except for the fact of the lost event:
Messages shows events on those particular cameras ending and starting (but I am yet to modify Phils file to get it running with more info).
Well this is the status
Regards!
Posted: Wed Mar 02, 2005 3:03 pm
by Eklectick
Here is some additional info showing lost events. Today quite a lot more were lost, though just one pretty much for each camera on the same time frame. Here is a query of event Ids 3975 to 4005 where instead of showing 30 hits just displays 16, meaning of course numbers in between account for lost events:
My visit to messages on that particular time shows this:
Code: Select all
Mar 2 03:30:00 videoserver zma-m3[3182]: INF [Ended event]
Mar 2 03:30:00 videoserver zma-m7[3572]: INF [Ended event]
Mar 2 03:30:01 videoserver zma-m14[4258]: INF [Ended event]
Mar 2 03:30:02 videoserver zma-m12[4059]: INF [Ended event]
Mar 2 03:30:02 videoserver zma-m3[3182]: INF [ppnl0v25: 12516 - Starting new event]
Mar 2 03:30:02 videoserver zma-m7[3572]: INF [ppnl0v29: 12502 - Starting new event]
Mar 2 03:30:02 videoserver zma-m14[4258]: INF [ppnl0v36: 12437 - Starting new event]
Mar 2 03:30:02 videoserver zma-m18[4663]: INF [Ended event]
Mar 2 03:30:02 videoserver zma-m10[3864]: INF [Ended event]
Mar 2 03:30:02 videoserver zma-m12[4059]: INF [ppnl0v34: 12461 - Starting new event]
Mar 2 03:30:03 videoserver zma-m18[4663]: INF [ppnl0v40: 12377 - Starting new event]
Mar 2 03:30:03 videoserver zma-m10[3864]: INF [ppnl0v32: 12482 - Starting new event]
Mar 2 03:30:03 videoserver zma-m8[3669]: INF [Ended event]
Mar 2 03:30:03 videoserver zma-m8[3669]: INF [ppnl0v30: 12499 - Starting new event]
Mar 2 03:30:03 videoserver zma-m11[3961]: INF [Ended event]
Mar 2 03:30:04 videoserver zma-m11[3961]: INF [ppnl0v33: 12472 - Starting new event]
Mar 2 03:30:04 videoserver zma-m5[3378]: INF [Ended event]
Mar 2 03:30:04 videoserver zma-m5[3378]: INF [ppnl0v27: 12510 - Starting new event]
Mar 2 03:30:04 videoserver zma-m4[3280]: INF [Ended event]
Mar 2 03:30:04 videoserver zma-m4[3280]: INF [ppnl0v26: 12513 - Starting new event]
Mar 2 03:30:05 videoserver zma-m9[13544]: INF [Ended event]
Mar 2 03:30:05 videoserver zma-m1[2928]: INF [Ended event]
Mar 2 03:30:06 videoserver zma-m9[13544]: INF [ppnl0v31: 5646 - Starting new event]
Mar 2 03:30:06 videoserver zma-m1[2928]: INF [ppnl0v23: 12525 - Starting new event]
Mar 2 03:30:06 videoserver zma-m2[3027]: INF [Ended event]
Mar 2 03:30:06 videoserver zma-m2[3027]: INF [ppnl0v24: 12522 - Starting new event]
Mar 2 03:30:07 videoserver zma-m19[4762]: INF [Ended event]
Mar 2 03:30:07 videoserver zma-m19[4762]: INF [ppnl0v41: 12360 - Starting new event]
Mar 2 03:30:08 videoserver zma-m16[4466]: INF [Ended event]
Mar 2 03:30:08 videoserver zma-m16[4466]: INF [ppnl0v38: 12408 - Starting new event]
Mar 2 03:30:08 videoserver zma-m15[4356]: INF [Ended event]
Mar 2 03:30:08 videoserver zma-m15[4356]: INF [ppnl0v37: 12425 - Starting new event]
Mar 2 03:30:09 videoserver zma-m6[3474]: INF [Ended event]
Mar 2 03:30:09 videoserver zma-m6[3474]: INF [ppnl0v28: 12507 - Starting new event]
Mar 2 03:30:11 videoserver zma-m13[4160]: INF [Ended event]
Mar 2 03:30:11 videoserver zma-m17[4564]: INF [Ended event]
Mar 2 03:30:11 videoserver zma-m13[4160]: INF [ppnl0v35: 12450 - Starting new event]
Mar 2 03:30:11 videoserver zma-m17[4564]: INF [ppnl0v39: 12394 - Starting new event]
Mar 2 03:40:01 videoserver zma-m7[3572]: INF [Ended event]
Mar 2 03:40:01 videoserver zma-m3[3182]: INF [Ended event]
Mar 2 03:40:01 videoserver zma-m17[4564]: INF [Ended event]
Mar 2 03:40:01 videoserver zma-m13[4160]: INF [Ended event]
Mar 2 03:40:02 videoserver zma-m14[4258]: INF [Ended event]
Mar 2 03:40:02 videoserver zma-m12[4059]: INF [Ended event]
Mar 2 03:40:02 videoserver zma-m10[3864]: INF [Ended event]
Mar 2 03:40:03 videoserver zma-m18[4663]: INF [Ended event]
Mar 2 03:40:03 videoserver zma-m8[3669]: INF [Ended event]
Mar 2 03:40:04 videoserver zma-m10[3864]: INF [ppnl0v32: 12542 - Starting new event]
Mar 2 03:40:04 videoserver zma-m13[4160]: INF [ppnl0v35: 12509 - Starting new event]
Mar 2 03:40:04 videoserver zma-m3[3182]: INF [ppnl0v25: 12576 - Starting new event]
Mar 2 03:40:04 videoserver zma-m7[3572]: INF [ppnl0v29: 12562 - Starting new event]
Mar 2 03:40:04 videoserver zma-m11[3961]: INF [Ended event]
Mar 2 03:40:04 videoserver zma-m14[4258]: INF [ppnl0v36: 12497 - Starting new event]
Mar 2 03:40:04 videoserver zma-m18[4663]: INF [ppnl0v40: 12437 - Starting new event]
Mar 2 03:40:04 videoserver zma-m17[4564]: INF [ppnl0v39: 12453 - Starting new event]
Mar 2 03:40:04 videoserver zma-m12[4059]: INF [ppnl0v34: 12521 - Starting new event]
Mar 2 03:40:04 videoserver zma-m8[3669]: INF [ppnl0v30: 12559 - Starting new event]
Mar 2 03:40:05 videoserver zma-m11[3961]: INF [ppnl0v33: 12532 - Starting new event]
Mar 2 03:40:05 videoserver zma-m5[3378]: INF [Ended event]
Mar 2 03:40:05 videoserver zma-m4[3280]: INF [Ended event]
Mar 2 03:40:06 videoserver zma-m5[3378]: INF [ppnl0v27: 12570 - Starting new event]
Mar 2 03:40:07 videoserver zma-m4[3280]: INF [ppnl0v26: 12573 - Starting new event]
Mar 2 03:40:07 videoserver zma-m1[2928]: INF [Ended event]
Mar 2 03:40:07 videoserver zma-m9[13544]: INF [Ended event]
Mar 2 03:40:07 videoserver zma-m19[4762]: INF [Ended event]
Mar 2 03:40:07 videoserver zma-m9[13544]: INF [ppnl0v31: 5706 - Starting new event]
Mar 2 03:40:07 videoserver zma-m1[2928]: INF [ppnl0v23: 12585 - Starting new event]
Mar 2 03:40:07 videoserver zma-m2[3027]: INF [Ended event]
Mar 2 03:40:07 videoserver zma-m19[4762]: INF [ppnl0v41: 12420 - Starting new event]
Mar 2 03:40:08 videoserver zma-m2[3027]: INF [ppnl0v24: 12582 - Starting new event]
Mar 2 03:40:08 videoserver zma-m16[4466]: INF [Ended event]
Mar 2 03:40:08 videoserver zma-m16[4466]: INF [ppnl0v38: 12468 - Starting new event]
Mar 2 03:40:08 videoserver zma-m15[4356]: INF [Ended event]
Mar 2 03:40:09 videoserver zma-m15[4356]: INF [ppnl0v37: 12485 - Starting new event]
Mar 2 03:40:09 videoserver zma-m6[3474]: INF [Ended event]
Mar 2 03:40:09 videoserver zma-m6[3474]: INF [ppnl0v28: 12567 - Starting new event]
Mar 2 03:50:00 videoserver zma-m17[4564]: INF [Ended event]
Mar 2 03:50:00 videoserver zma-m3[3182]: INF [Ended event]
Mar 2 03:50:01 videoserver zma-m13[4160]: INF [Ended event]
Mar 2 03:50:01 videoserver zma-m7[3572]: INF [Ended event]
Mar 2 03:50:01 videoserver zma-m10[3864]: INF [Ended event]
Mar 2 03:50:02 videoserver zma-m14[4258]: INF [Ended event]
Mar 2 03:50:02 videoserver zma-m12[4059]: INF [Ended event]
Mar 2 03:50:03 videoserver zma-m10[3864]: INF [ppnl0v32: 12602 - Starting new event]
Mar 2 03:50:03 videoserver zma-m3[3182]: INF [ppnl0v25: 12636 - Starting new event]
Mar 2 03:50:03 videoserver zma-m17[4564]: INF [ppnl0v39: 12513 - Starting new event]
Mar 2 03:50:03 videoserver zma-m13[4160]: INF [ppnl0v35: 12569 - Starting new event]
Mar 2 03:50:03 videoserver zma-m7[3572]: INF [ppnl0v29: 12622 - Starting new event]
Mar 2 03:50:03 videoserver zma-m14[4258]: INF [ppnl0v36: 12557 - Starting new event]
Mar 2 03:50:03 videoserver zma-m18[4663]: INF [Ended event]
Mar 2 03:50:04 videoserver zma-m8[3669]: INF [Ended event]
Mar 2 03:50:04 videoserver zma-m11[3961]: INF [Ended event]
Mar 2 03:50:04 videoserver zma-m5[3378]: INF [Ended event]
Mar 2 03:50:04 videoserver zma-m12[4059]: INF [ppnl0v34: 12581 - Starting new event]
Mar 2 03:50:05 videoserver zma-m4[3280]: INF [Ended event]
Mar 2 03:50:05 videoserver zma-m8[3669]: INF [ppnl0v30: 12619 - Starting new event]
Which is pretty much consistent upon showing that events are actually starting and ending on a pretty normal fashion. As you can see, ten minutes before, events show "starting new" and those too show and end, ten minutes later.
Phil I apologize as of yet not implementing the change you suggested, although my guess will be that it will show event Ids actually being assigned but dropped somewhere along the way.
Regards!
Posted: Mon Mar 07, 2005 12:06 am
by zoneminder
Hi,
Just bringing this to the top to show I haven't forgotten about it. I'd be interested to see what you see with the extra debug I suggested if you get chance. Otherwise I'll take a fresh look at this tomorrow.
Phil
Posted: Mon Mar 07, 2005 1:22 pm
by Eklectick
Thanks Phil, these are my findings...
I added the debug line to see which number was being assigned to each event. Before the debug line, I tried changing events to 900 seconds (600 previously) which produce 4 events per hour. Unfortunately this did not change anything, events were still being dropped. After the debug my visit to the console showed up these dropped events:
Where Id Cameras 10, 11 and 12 showed dropped events. Messages shows numbers being assigned to these particular events as follows:
So naturally I went into each folder looking for the particular event but they were not there
I am yet to try to change the frequency of the capture of images, being that, right now, one image is being captured every 10 seconds but I do not know if that will do any good because this has shown to be quite persistent.
Regards!
Posted: Tue Mar 08, 2005 6:05 am
by Eklectick
Phil
Dont know how to figure this out but let me brainstorm with you. One thing I saw a few moments ago when I visited the console was 9 cameras dropping events at the same hour:minute. The thing that puzzles me is why are events which in number are greater than others, get a creation time of one or two seconds before a previous one? (You can see an example in the previous post where event 17250 should be event 17268 has an earlier time than 17230). Then again others do not show this but yet are missing.
Not only that, if events are created at a certain time and jpgs are being captured live... then where are they? (I am just shooting bullets in the air here mate
)
Is there a possibility that the system is holding this events in memory (not yet actually physically writing them to disk) and at a certain time then dumped/lost at swap (or somewhere) that newer ones get written first than older ones and something screwing up in the procedure? On the other hand, even if the folders are numerically larger than the next one, jpgs do have the correct time frame inside each. Perhaps this time tags do get assigned in memory, they hold there, and then get written to disk?
If this memory theory is viable is there anyway to disable it and force real time capture/write? (which I am certain it should do because I can see jpgs being written by refreshing a current event folder)
.
Tried looking for a way of "recovering" lost folders/data but I think trying such a thing on ext3 (by a simple Google search) prooves to be quite an adventure
Some time ago I played with an Axis cam FTPing into a windows machine to say Folder01 which got dumped every five minutes to say Folder02, there it held jpgs for about a minute after which an application appended these jpgs into a zip file on say Folder03 which once appended cleard Folder02 to wait for another set of fresh jpgs. In this rudimentary way I got daily folders with captured images and zipped (because windows has a limit on the number of files it can handle).
Sometimes my rudimentary procedure got mixed up where Folder02 was getting cleared before appending to zip on Folder03. Perhaps I am not making myself clear but what I am trying to say is that maybe somewhere in the loop a short cut that drops events is happening.
I will be happy to try any more debug suggestions you may have.
Thanks in advance.
Regards!
Posted: Tue Mar 08, 2005 12:11 pm
by zoneminder
Thanks for all the detail. It looks to me like the events are being created and then deleted before anything can happen to them. In Linux it is entirely possible for a directory to be deleted but continue to have files added to if a process is resident within that directory as deleting just removes one link, usually leaving zero, but not necessarily physically removing the entries. I am most suspicious that perhaps zmaudit is wiping out the events perhaps because of a timing issue and maybe it happens across the directory or DB event when it is empty and thinks it is bogus.
Can you confirm you have checked zmaudit.log? If not please do so, then perhaps we need to temporarily disable it and see if that stops the problem. The other thing to do is to add DB logging to mysql. To do this edit the my.cnf file on your system (it's location may vary) and just add the single word 'log' on a line by itself in the [mysqld] section. Then restart mysqld and you should get a log created in the same location. It will get enormous, I suspect, with the volume of data you are generating. If/when you see an event disapear you will need to grep this log (or logs) and see if we can find any evidence for deliberate deletion.
Phil
Posted: Tue Mar 08, 2005 2:24 pm
by Eklectick
Phil
Thanks for the input I guess we will debug the zmaudit first. I did a "locate zmaudit" and got:
Code: Select all
/usr/local/bin/zmaudit.pl
/usr/src/zm-1.19.5/scripts/zmaudit.pl
/usr/src/zm-1.19.5/scripts/zmaudit.pl.z
... and did not find zmaudit.log, perhaps it needs to be told to be created? Looked for it in /var/log/ but it was not there either.
On another note would you please tell me how to temporarily enable/disable it or perhaps be told to be run less frequent?
Would opting out ZM_OPT_FAST_DELETE do any good?
Regards!
Posted: Tue Mar 08, 2005 3:15 pm
by zoneminder
You might find the zmaudit.log in /tmp I would think. The simplest way of preventing it running is to edit /usr/local/bin/zmpkg.pl and comment out the line that starts it. Then restart ZM.
I don't think turning off fast deletes will have any effect as that just relies on zmaudit hoovering up inconsistencies which are deliberately created. In this case we might have the same (very temporary) inconsistencies which it is cleaning up anyway.
Phil
Posted: Tue Mar 08, 2005 4:52 pm
by Eklectick
Phil
Well I am up to now pleased to at least finding a log that points to these dropped events!
Browsed zmaudit.log back looking for events 17250, 17252 and 17256 (and others) and found this:
Code: Select all
Database event '11/17252' does not exist in filesystem, deleting
Database event '1/17249' does not exist in filesystem, deleting
Database event '12/17256' does not exist in filesystem, deleting
Database event '10/17250' does not exist in filesystem, deleting
Filesystem event '11/17252' does not exist in database, deleting
Filesystem event '12/17256' does not exist in database, deleting
Filesystem event '1/17249' does not exist in database, deleting
Filesystem event '10/17250' does not exist in database, deleting
Found orphaned frame records for event '17249', deleting
Found orphaned frame records for event '17250', deleting
Found orphaned frame records for event '17252', deleting
Found orphaned frame records for event '17256', deleting
By the way I see this, perhaps (correct me if I am wrong) there might be "hiccups" on the net whereas some jpgs are being captured abnormaly from the cameras, thus the "event ´xx/xxxxx´ does not exist in filesystem" which subsecuently triggers the deletion?
I am not sure of stopping zmaudit to run as perhaps my fear of wrecking another havoc, although, as I see it, this is the one that is erasing events (?) so please advise!
Regards!
Posted: Tue Mar 08, 2005 8:22 pm
by zoneminder
I think this is a bug in zmaudit where it finds events in the DB that don't (yet) have anything in the filesystem. Usually this happens when they haven't been deleted properly but in your case it's catching it just at the instant where the event is created in the DB but before anything has been written to the disk.
I'll try and come up with a mod that you can try out to see if it corrects this.
Phil
Posted: Fri Mar 11, 2005 5:17 am
by Eklectick
Phil
I edited zmpkg.pl and found the place where zm audit.pl is called, will a simple "#" before the line as exampled under here do the trick of not loading it?
Code: Select all
# This is now started unconditionally
execute( ZM_PATH_BIN."/zmdc.pl start zmfilter.pl" );
# execute( ZM_PATH_BIN."/zmdc.pl start zmaudit.pl -d 900 -y" );
execute( ZM_PATH_BIN."/zmfix -a" );
And one more question: without zmaudit running, could something bad happen? (I am not that desperate to try it).
Regards!
Posted: Fri Mar 11, 2005 8:00 am
by zoneminder
Yes, the # will do it and no nothing really bad should happen in the short term. You can caways run zmaudit manually at your convenience. I'll fix it up anyway in the next release or two.
Phil
Posted: Fri Mar 11, 2005 2:20 pm
by Eklectick
Ok, thanks Phil, anyway, if you do come with a fix for zmaudit on 1.19.5 I would appreciate for you to post it rather than me starting up from zero
Phil, when you say "in the short term" I still feel a little uncomfortable, would you suggest perhaps running it with the -d option: once a day, after several hours, hourly, just to try to be on the safe side before a definite fix?
Regards!
Posted: Fri Mar 11, 2005 4:56 pm
by zoneminder
Nothing bad really will happen if you don't run zmaudit, at the worst you might have stuff on disc that doesn't belong to any event. Running it manually every two or three days should be fine especially if you have FAST_DELETES switched off.
I should be able to find some time to figure out a fix in the next few days. When I do I expect it will be only a line or two so I'll post instructions here so you can update your copy as well.
Phil