app gets into weird state that prevents timeline from populating and syslog goes nuts from montage

[alager]

Here is a 1 second sample of syslog when this is happening:

Aug 26 17:28:18 myZoneMonitor zms[6011]: FAT [Unable to load monitor id 1 for streaming]
Aug 26 17:28:18 myZoneMonitor zms[6012]: FAT [Unable to load monitor id 2 for streaming]
Aug 26 17:28:18 myZoneMonitor zms[6010]: INF [Got signal 15 (Terminated), exiting]
Aug 26 17:28:18 myZoneMonitor zms[6009]: FAT [Unable to load monitor id 3 for streaming]
Aug 26 17:28:18 myZoneMonitor mysqld: 150826 17:28:18 [Warning] Aborted connection 12519 to db: 'zm' user: 'zmuser' host: 'localhost' (Unknown error)
Aug 26 17:28:18 myZoneMonitor mysqld: 150826 17:28:18 [Warning] Aborted connection 12524 to db: 'zm' user: 'zmuser' host: 'localhost' (Unknown error)
Aug 26 17:28:18 myZoneMonitor mysqld: 150826 17:28:18 [Warning] Aborted connection 12515 to db: 'zm' user: 'zmuser' host: 'localhost' (Unknown error)
Aug 26 17:28:18 myZoneMonitor mysqld: 150826 17:28:18 [Warning] Aborted connection 12516 to db: 'zm' user: 'zmuser' host: 'localhost' (Unknown error)
Aug 26 17:28:18 myZoneMonitor mysqld: 150826 17:28:18 [Warning] Aborted connection 12521 to db: 'zm' user: 'zmuser' host: 'localhost' (Unknown error)
Aug 26 17:28:18 myZoneMonitor mysqld: 150826 17:28:18 [Warning] Aborted connection 12523 to db: 'zm' user: 'zmuser' host: 'localhost' (Unknown error)
Aug 26 17:28:18 myZoneMonitor zms[6004]: INF [Got signal 15 (Terminated), exiting]
Aug 26 17:28:18 myZoneMonitor zms[6005]: INF [Got signal 15 (Terminated), exiting]
Aug 26 17:28:18 myZoneMonitor zms[6006]: FAT [Unable to load monitor id 3 for streaming]
Aug 26 17:28:18 myZoneMonitor mysqld: 150826 17:28:18 [Warning] Aborted connection 12529 to db: 'zm' user: 'zmuser' host: 'localhost' (Unknown error)
Aug 26 17:28:18 myZoneMonitor mysqld: 150826 17:28:18 [Warning] Aborted connection 12526 to db: 'zm' user: 'zmuser' host: 'localhost' (Unknown error)
Aug 26 17:28:18 myZoneMonitor zms[6010]: FAT [Unable to load monitor id 4 for streaming]
Aug 26 17:28:18 myZoneMonitor mysqld: 150826 17:28:18 [Warning] Aborted connection 12517 to db: 'zm' user: 'zmuser' host: 'localhost' (Unknown error)
Aug 26 17:28:18 myZoneMonitor mysqld: 150826 17:28:18 [Warning] Aborted connection 12522 to db: 'zm' user: 'zmuser' host: 'localhost' (Unknown error)
Aug 26 17:28:18 myZoneMonitor zms[6005]: FAT [Unable to load monitor id 4 for streaming]
Aug 26 17:28:18 myZoneMonitor zms[6004]: FAT [Unable to load monitor id 2 for streaming]
Aug 26 17:28:18 myZoneMonitor mysqld: 150826 17:28:18 [Warning] Aborted connection 12520 to db: 'zm' user: 'zmuser' host: 'localhost' (Unknown error)
Aug 26 17:28:18 myZoneMonitor mysqld: 150826 17:28:18 [Warning] Aborted connection 12527 to db: 'zm' user: 'zmuser' host: 'localhost' (Unknown error)
Aug 26 17:28:18 myZoneMonitor mysqld: 150826 17:28:18 [Warning] Aborted connection 12525 to db: 'zm' user: 'zmuser' host: 'localhost' (Unknown error)
Aug 26 17:28:18 myZoneMonitor mysqld: 150826 17:28:18 [Warning] Aborted connection 12528 to db: 'zm' user: 'zmuser' host: 'localhost' (Unknown error)
Aug 26 17:28:18 myZoneMonitor zms[6014]: FAT [Unable to load monitor id 2 for streaming]
Aug 26 17:28:18 myZoneMonitor zms[6013]: FAT [Unable to load monitor id 1 for streaming]
Aug 26 17:28:18 myZoneMonitor mysqld: 150826 17:28:18 [Warning] Aborted connection 12531 to db: 'zm' user: 'zmuser' host: 'localhost' (Unknown error)
Aug 26 17:28:18 myZoneMonitor mysqld: 150826 17:28:18 [Warning] Aborted connection 12533 to db: 'zm' user: 'zmuser' host: 'localhost' (Unknown error)
Aug 26 17:28:18 myZoneMonitor mysqld: 150826 17:28:18 [Warning] Aborted connection 12530 to db: 'zm' user: 'zmuser' host: 'localhost' (Unknown error)
Aug 26 17:28:18 myZoneMonitor mysqld: 150826 17:28:18 [Warning] Aborted connection 12532 to db: 'zm' user: 'zmuser' host: 'localhost' (Unknown error)
Aug 26 17:28:18 myZoneMonitor zms[6015]: FAT [Unable to load monitor id 3 for streaming]
Aug 26 17:28:18 myZoneMonitor mysqld: 150826 17:28:18 [Warning] Aborted connection 12534 to db: 'zm' user: 'zmuser' host: 'localhost' (Unknown error)
Aug 26 17:28:18 myZoneMonitor mysqld: 150826 17:28:18 [Warning] Aborted connection 12535 to db: 'zm' user: 'zmuser' host: 'localhost' (Unknown error)
Aug 26 17:28:18 myZoneMonitor zms[6016]: FAT [Unable to load monitor id 4 for streaming]
Aug 26 17:28:18 myZoneMonitor mysqld: 150826 17:28:18 [Warning] Aborted connection 12536 to db: 'zm' user: 'zmuser' host: 'localhost' (Unknown error)
Aug 26 17:28:18 myZoneMonitor mysqld: 150826 17:28:18 [Warning] Aborted connection 12537 to db: 'zm' user: 'zmuser' host: 'localhost' (Unknown error)
Aug 26 17:28:18 myZoneMonitor zms[6018]: FAT [Unable to load monitor id 4 for streaming]
Aug 26 17:28:18 myZoneMonitor mysqld: 150826 17:28:18 [Warning] Aborted connection 12538 to db: 'zm' user: 'zmuser' host: 'localhost' (Unknown error)
Aug 26 17:28:18 myZoneMonitor mysqld: 150826 17:28:18 [Warning] Aborted connection 12542 to db: 'zm' user: 'zmuser' host: 'localhost' (Unknown error)
Aug 26 17:28:18 myZoneMonitor zms[6020]: FAT [Unable to load monitor id 1 for streaming]
Aug 26 17:28:18 myZoneMonitor zms[6019]: FAT [Unable to load monitor id 2 for streaming]
Aug 26 17:28:18 myZoneMonitor zms[6022]: FAT [Unable to load monitor id 2 for streaming]
Aug 26 17:28:18 myZoneMonitor mysqld: 150826 17:28:18 [Warning] Aborted connection 12539 to db: 'zm' user: 'zmuser' host: 'localhost' (Unknown error)
Aug 26 17:28:18 myZoneMonitor mysqld: 150826 17:28:18 [Warning] Aborted connection 12540 to db: 'zm' user: 'zmuser' host: 'localhost' (Unknown error)
Aug 26 17:28:18 myZoneMonitor mysqld: 150826 17:28:18 [Warning] Aborted connection 12545 to db: 'zm' user: 'zmuser' host: 'localhost' (Unknown error)
Aug 26 17:28:18 myZoneMonitor mysqld: 150826 17:28:18 [Warning] Aborted connection 12548 to db: 'zm' user: 'zmuser' host: 'localhost' (Unknown error)
Aug 26 17:28:18 myZoneMonitor mysqld: 150826 17:28:18 [Warning] Aborted connection 12541 to db: 'zm' user: 'zmuser' host: 'localhost' (Unknown error)
Aug 26 17:28:18 myZoneMonitor mysqld: 150826 17:28:18 [Warning] Aborted connection 12546 to db: 'zm' user: 'zmuser' host: 'localhost' (Unknown error)

[pliablepixels]

The problem description:
Chrome does not allow more than 6 open TCP connections. When viewing monitor feeds in montage, I am using the "single image" mode of ZMS instead of "open stream" mode. This allows me to keep opening and closing connections at will and lets me display more than 6 monitors at the same time. I do a new image grab every second. The problem is that these requests are authenticated and each hit logs an INF record that user XXX logged in. Unlike in Aaron's case, I am not getting a "Aborted connection" - Im getting INF logs about authentication, but I suspect the core issue is the same.

Right now I don't have an easy way to solve this, but solve we must..... will think.....

[pliablepixels]

Okay , note to self: I think I can fix it but I need to use ZM's auth token and not user=&pass=

[pliablepixels]

@alager actually this issue does not seem to be the issue I thought it was. According to your log report, mysqld is throwing warnings --> it also shows failed zms. Are your montage view feeds working?

[alager]

It appears that they stop after some event on the app. Like maybe the phone going to sleep?
They do show an image, it just isn't updating.

[alager]

It's in that mode again...The montage on the phone isn't loading any images. Also, while it's doing that, the web console has difficulty displaying the monitors and the montage there doesn't work at the same time. If I go over to the logs panel (to get it to stop pulling data) then the web console starts working again.
If I let the app montage continue to "load" then the web console eventually returns this:
Unable to connect to ZM db.SQLSTATE[HY000] [1040] Too many connections
max_connections is 100 in my.cnf.

[alager]

restarting the app returns the syslog messaging to normal and I can run montage on both the web console and the app at the same time.

[pliablepixels]

So I just updated my version of ZM to the latest version. I am just not seeing mysqld warnings or errors. I somehow feel for some reason you have an issue with mysql's configuration. I'll dig more, but I've checked on my DB and I've asked some other testers on Android and they don't seem to be seeing this.

What they are however seeing is while in montage view or monitor live view mode, a log entry INF [Authenticated user 'admin'] every second - I am aware of that part and am going to fix it (eventually)

[pliablepixels]

try this: don't go to montage view. Go to some other view and wait for your logs to stabilize. Then go to "Monitor" view and click on "Live View" - do you see your mysqld complaining?

[alager]

After the app has been sitting a while, with the phone idle(screen shuts down), then starting it up:
Sitting on one monitor, the first few lines come in with an error, then nothing else for a while. The monitor was fully functional the whole time:

Aug 27 14:52:04 myZoneMonitor zma_m7[11421]: INF [Bullet-958c: 52000 - Analysing at 4.98 fps]
Aug 27 14:52:08 myZoneMonitor nph-zms[16504]: ERR [Can't insert log entry: MySQL server has gone away]
Aug 27 14:52:08 myZoneMonitor nph-zms[16504]: INF [Got signal 15 (Terminated), exiting]
Aug 27 14:52:08 myZoneMonitor zms[16503]: INF [Got signal 15 (Terminated), exiting]
Aug 27 14:53:25 myZoneMonitor zmc_m5[11403]: INF [Dome-92a9: 53000 - Capturing at 5.00 fps]

I have constant motion events happening and one camera recording, so the DB should have plenty of "traffic" to keep it awake. I don't see these types of messages now that it's up. I can go to any of the other live views and no messages. I can also go to the live view on the web console, no error messages.

[alager]

my db setting for wait_timeout was set to 600. I put it back to the default of 28800, we'll see if that makes things better.

[alager]

With montage working, my syslogs look like this:

Aug 27 15:14:53 myZoneMonitor zmc_m6[17713]: WAR [Packet in sequence, gap 433]
Aug 27 15:14:53 myZoneMonitor zmc_m6[17713]: WAR [Discarding frame 2633]
Aug 27 15:14:53 myZoneMonitor zmc_m5[17704]: WAR [Packet in sequence, gap 543]
Aug 27 15:14:53 myZoneMonitor zmc_m5[17704]: WAR [Discarding frame 2686]
Aug 27 15:14:53 myZoneMonitor zmc_m8[17745]: WAR [Packet in sequence, gap 712]
Aug 27 15:14:53 myZoneMonitor zmc_m8[17745]: WAR [Discarding frame 1778]
Aug 27 15:14:56 myZoneMonitor zmc_m5[17704]: WAR [Packet in sequence, gap 424]
Aug 27 15:14:56 myZoneMonitor zmc_m5[17704]: WAR [Discarding frame 2700]
Aug 27 15:14:56 myZoneMonitor zmc_m6[17713]: WAR [Packet in sequence, gap 779]
Aug 27 15:14:56 myZoneMonitor zmc_m6[17713]: WAR [Discarding frame 2647]
Aug 27 15:14:56 myZoneMonitor zmc_m7[17729]: WAR [Packet in sequence, gap 414]
Aug 27 15:14:56 myZoneMonitor zmc_m7[17729]: WAR [Discarding frame 2667]
Aug 27 15:14:58 myZoneMonitor zmc_m8[17745]: WAR [Packet in sequence, gap 1102]
Aug 27 15:14:58 myZoneMonitor zmc_m8[17745]: WAR [Discarding frame 1793]
Aug 27 15:15:02 myZoneMonitor zmc_m6[17713]: WAR [Packet in sequence, gap 354]
Aug 27 15:15:02 myZoneMonitor zmc_m6[17713]: WAR [Discarding frame 2675]
Aug 27 15:15:09 myZoneMonitor zmc_m7[17729]: WAR [Packet in sequence, gap 260]
Aug 27 15:15:09 myZoneMonitor zmc_m7[17729]: WAR [Discarding frame 2733]
Aug 27 15:15:11 myZoneMonitor zmc_m6[17713]: WAR [Packet in sequence, gap 148]
Aug 27 15:15:11 myZoneMonitor zmc_m6[17713]: WAR [Discarding frame 2719]
Aug 27 15:15:16 myZoneMonitor zmc_m6[17713]: WAR [Packet in sequence, gap 612]
Aug 27 15:15:16 myZoneMonitor zmc_m6[17713]: WAR [Discarding frame 2742]
Aug 27 15:15:19 myZoneMonitor zmc_m7[17729]: WAR [Packet in sequence, gap 475]
Aug 27 15:15:19 myZoneMonitor zmc_m7[17729]: WAR [Discarding frame 2783]
Aug 27 15:15:22 myZoneMonitor zmc_m8[17745]: WAR [Packet in sequence, gap 189]
Aug 27 15:15:22 myZoneMonitor zmc_m8[17745]: WAR [Discarding frame 1879]
Aug 27 15:15:22 myZoneMonitor zmc_m8[17745]: WAR [Packet in sequence, gap 900]
Aug 27 15:15:22 myZoneMonitor zmc_m8[17745]: WAR [Discarding frame 1881]
Aug 27 15:15:26 myZoneMonitor zmc_m6[17713]: WAR [Packet in sequence, gap 401]
Aug 27 15:15:27 myZoneMonitor zmc_m6[17713]: WAR [Discarding frame 2793]
Aug 27 15:15:29 myZoneMonitor zmc_m7[17729]: WAR [Packet in sequence, gap 317]

[pliablepixels]

Thanks. These logs are related to ZM capturing rtsp frames. They should
also occur if you are viewing the ZM web montage.
So no more dB errors?

On Thursday, August 27, 2015, alager notifications@github.com wrote:

With montage working, my syslogs look like this:

Aug 27 15:14:53 myZoneMonitor zmc_m6[17713]: WAR [Packet in sequence, gap 433]
Aug 27 15:14:53 myZoneMonitor zmc_m6[17713]: WAR [Discarding frame 2633]
Aug 27 15:14:53 myZoneMonitor zmc_m5[17704]: WAR [Packet in sequence, gap 543]
Aug 27 15:14:53 myZoneMonitor zmc_m5[17704]: WAR [Discarding frame 2686]
Aug 27 15:14:53 myZoneMonitor zmc_m8[17745]: WAR [Packet in sequence, gap 712]
Aug 27 15:14:53 myZoneMonitor zmc_m8[17745]: WAR [Discarding frame 1778]
Aug 27 15:14:56 myZoneMonitor zmc_m5[17704]: WAR [Packet in sequence, gap 424]
Aug 27 15:14:56 myZoneMonitor zmc_m5[17704]: WAR [Discarding frame 2700]
Aug 27 15:14:56 myZoneMonitor zmc_m6[17713]: WAR [Packet in sequence, gap 779]
Aug 27 15:14:56 myZoneMonitor zmc_m6[17713]: WAR [Discarding frame 2647]
Aug 27 15:14:56 myZoneMonitor zmc_m7[17729]: WAR [Packet in sequence, gap 414]
Aug 27 15:14:56 myZoneMonitor zmc_m7[17729]: WAR [Discarding frame 2667]
Aug 27 15:14:58 myZoneMonitor zmc_m8[17745]: WAR [Packet in sequence, gap 1102]
Aug 27 15:14:58 myZoneMonitor zmc_m8[17745]: WAR [Discarding frame 1793]
Aug 27 15:15:02 myZoneMonitor zmc_m6[17713]: WAR [Packet in sequence, gap 354]
Aug 27 15:15:02 myZoneMonitor zmc_m6[17713]: WAR [Discarding frame 2675]
Aug 27 15:15:09 myZoneMonitor zmc_m7[17729]: WAR [Packet in sequence, gap 260]
Aug 27 15:15:09 myZoneMonitor zmc_m7[17729]: WAR [Discarding frame 2733]
Aug 27 15:15:11 myZoneMonitor zmc_m6[17713]: WAR [Packet in sequence, gap 148]
Aug 27 15:15:11 myZoneMonitor zmc_m6[17713]: WAR [Discarding frame 2719]
Aug 27 15:15:16 myZoneMonitor zmc_m6[17713]: WAR [Packet in sequence, gap 612]
Aug 27 15:15:16 myZoneMonitor zmc_m6[17713]: WAR [Discarding frame 2742]
Aug 27 15:15:19 myZoneMonitor zmc_m7[17729]: WAR [Packet in sequence, gap 475]
Aug 27 15:15:19 myZoneMonitor zmc_m7[17729]: WAR [Discarding frame 2783]
Aug 27 15:15:22 myZoneMonitor zmc_m8[17745]: WAR [Packet in sequence, gap 189]
Aug 27 15:15:22 myZoneMonitor zmc_m8[17745]: WAR [Discarding frame 1879]
Aug 27 15:15:22 myZoneMonitor zmc_m8[17745]: WAR [Packet in sequence, gap 900]
Aug 27 15:15:22 myZoneMonitor zmc_m8[17745]: WAR [Discarding frame 1881]
Aug 27 15:15:26 myZoneMonitor zmc_m6[17713]: WAR [Packet in sequence, gap 401]
Aug 27 15:15:27 myZoneMonitor zmc_m6[17713]: WAR [Discarding frame 2793]
Aug 27 15:15:29 myZoneMonitor zmc_m7[17729]: WAR [Packet in sequence, gap 317]

—
Reply to this email directly or view it on GitHub
https://github.com/pliablepixels/zmNinja/issues/26#issuecomment-135571086
.

[alager]

No I still get them. I'm trying to narrow it down. I know that if I start the app and go to the montage, there are no errors. But if I lock the phone (without exiting the app) and then try it some time later, then I get the errors.
That's why I thought it might be the 600 second timeout, but that didn't make a difference.

I won't be able to try any more until Monday.