Loading Events Delay

[jordanconstable]

ZmNinja 1.4.3 Android 10 Oneplus 8 Pro & Windows 10
Zoneminder 1.34.15 Ubuntu 18.04.4

Did you build the package from source code yourself?**
N

When playing back any recorded events, after opening the event there is a 10-15 second delay at a black screen before the event will start to play. WebPHP in the ZM logs will give an error every few seconds during this delay before the event will eventually play. The 4 below entries in the log is what was given for opening one event in ZmNinja. The FAQ the error suggests says that Cambozola should be installed for jpeg streaming but I don't think this is relevant to the issue?
Event playback works instantly and gives no errors when using ZM in the browser. This bug happens on all devices I use ZmNinja on, both mobile and Windows desktops, possibly suggesting this is a problem with my ZM config but I can't work out where in ZM this would be caused. I can't remember exactly when this began but I keep ZmNinja updated and this has occurred across multiple releases.
Thanks

Debug logs

2020-07-04 17:08:54 | web_php |   | 16533 | ERR | Socket /var/run/zm/zms-142386s.sock does not exist. This file is created by zms, and since it does not exist, either zms did not run, or zms exited early. Please check your zms logs and ensure that CGI is enabled in apache and check that the PATH_ZMS is set correctly. Make sure that ZM is actually recording. If you are trying to view a live stream and the capture process (zmc) is not running then zms will exit. Please go to http://zoneminder.readthedocs.io/en/latest/faq.html#why-can-t-i-see-streamed-images-when-i-can-see-stills-in-the-zone-window-etc for more information. | /usr/share/zoneminder/www/includes/functions.php | 2177
2020-07-04 17:08:52 | web_php |   | 19015 | ERR | Socket /var/run/zm/zms-603998s.sock does not exist. This file is created by zms, and since it does not exist, either zms did not run, or zms exited early. Please check your zms logs and ensure that CGI is enabled in apache and check that the PATH_ZMS is set correctly. Make sure that ZM is actually recording. If you are trying to view a live stream and the capture process (zmc) is not running then zms will exit. Please go to http://zoneminder.readthedocs.io/en/latest/faq.html#why-can-t-i-see-streamed-images-when-i-can-see-stills-in-the-zone-window-etc for more information. | /usr/share/zoneminder/www/includes/functions.php | 2177
2020-07-04 17:08:49 | web_php |   | 19015 | ERR | Socket /var/run/zm/zms-603998s.sock does not exist. This file is created by zms, and since it does not exist, either zms did not run, or zms exited early. Please check your zms logs and ensure that CGI is enabled in apache and check that the PATH_ZMS is set correctly. Make sure that ZM is actually recording. If you are trying to view a live stream and the capture process (zmc) is not running then zms will exit. Please go to http://zoneminder.readthedocs.io/en/latest/faq.html#why-can-t-i-see-streamed-images-when-i-can-see-stills-in-the-zone-window-etc for more information. | /usr/share/zoneminder/www/includes/functions.php | 2177
2020-07-04 17:08:46 | web_php |   | 19015 | ERR | Socket /var/run/zm/zms-603998s.sock does not exist. This file is created by zms, and since it does not exist, either zms did not run, or zms exited early. Please check your zms logs and ensure that CGI is enabled in apache and check that the PATH_ZMS is set correctly. Make sure that ZM is actually recording. If you are trying to view a live stream and the capture process (zmc) is not running then zms will exit. Please go to http://zoneminder.readthedocs.io/en/latest/faq.html#why-can-t-i-see-streamed-images-when-i-can-see-stills-in-the-zone-window-etc for more information. | /usr/share/zoneminder/www/includes/functions.php | 2177

[welcome]

👋 Thanks for opening your first issue here! If you're reporting a 🐞 bug, please make sure you follow the issue template or I may not respond.

[pliablepixels]

Questions:

1. Did you compare the performance between zmNinja and ZM on the same Android device?
2. Are these mp4 files or JPEG streams?
3. Can I look at zmNinja logs when you start playing a video?

[jordanconstable]

Thanks for your reply. Below is the log from Zmninja when opening an event.
Playback is instant in the browser both on a PC and on the android device.
I believe these are MP4 recordings and playback within the browser is an MP4 stream

Thanks!

Jul 4, 2020 05:33:49 PM DEBUG TimelineCtrl/drawGraph:You clicked on item 340939
Jul 4, 2020 05:33:49 PM DEBUG TimelineCtrl/drawGraph: clicked item details:{"id":"340939","content":"<span class='my-vis-font'>( <i class='ion-android-notifications'></i>8) (340939) Motion: All</span>","start":"2020-07-04T12:34:40.000Z","end":"2020-07-04T12:34:49.000Z","group":"1","style":"background-color:#E57373;border-color:#E57373","myframes":"73","mydur":"8.99","myeid":"340939","myename":"CAM1- 340939","myvideo":"340939-video.mp4","myevent":{"Event":{"Id":"340939","MonitorId":"1","StorageId":"1","SecondaryStorageId":"0","Name":"CAM1- 340939","Cause":"Motion","StartTime":"2020-07-04 13:34:40","EndTime":"2020-07-04 13:34:49","Width":"1280","Height":"720","Length":"8.99","Frames":"73","AlarmFrames":"8","DefaultVideo":"340939-video.mp4","SaveJPEGs":"0","TotScore":"70","AvgScore":"8","MaxScore":"11","Archived":"0","Videoed":"0","Uploaded":"0","Emailed":"0","Messaged":"0","Executed":"0","Notes":"Motion: All","StateId":"1","Orientation":"ROTATE_0","DiskSpace":null,"Scheme":"Medium","Locked":false,"MaxScoreFrameId":"43407849","FileSystemPath":"/var/cache/zoneminder/events/1/2020-07-04/340939","MonitorName":"CAM1 Driveway","streamingURL":"http://cctv.lan/zm/cgi-bin","recordingURL":"http://cctv.lan/zm","imageMode":"fid"}}}
Jul 4, 2020 05:33:49 PM INFO Using stream mode single
Jul 4, 2020 05:33:49 PM DEBUG EventModalCtrl called from app.timeline
Jul 4, 2020 05:33:49 PM DEBUG Setting playback to undefined
Jul 4, 2020 05:33:49 PM DEBUG I was explictly asked not to show live, cross my fingers...
Jul 4, 2020 05:33:49 PM DEBUG Generated Connkey:684761
Jul 4, 2020 05:33:49 PM INFO *** Constructed API for detailed events: http://cctv.lan/zm/api/events/340939.json?&token=<removed>
Jul 4, 2020 05:33:49 PM DEBUG resize/orient: 1920(w) * 1037(h)
Jul 4, 2020 05:33:52 PM INFO >>>Starting checkAllEvents interval...
Jul 4, 2020 05:33:53 PM DEBUG Hmm I found an error {"result":"Error","message":"Socket /var/run/zm/zms-684761s.sock does not exist.  This file is created by zms, and since it does not exist, either zms did not run, or zms exited early.  Please check your zms logs and ensure that CGI is enabled in apache and check that the PATH_ZMS is set correctly.  Make sure that ZM is actually recording.  If you are trying to view a live stream and the capture process (zmc) is not running then zms will exit. Please go to http://zoneminder.readthedocs.io/en/latest/faq.html#why-can-t-i-see-streamed-images-when-i-can-see-stills-in-the-zone-window-etc for more information."}
Jul 4, 2020 05:33:56 PM DEBUG Hmm I found an error {"result":"Error","message":"Socket /var/run/zm/zms-684761s.sock does not exist.  This file is created by zms, and since it does not exist, either zms did not run, or zms exited early.  Please check your zms logs and ensure that CGI is enabled in apache and check that the PATH_ZMS is set correctly.  Make sure that ZM is actually recording.  If you are trying to view a live stream and the capture process (zmc) is not running then zms will exit. Please go to http://zoneminder.readthedocs.io/en/latest/faq.html#why-can-t-i-see-streamed-images-when-i-can-see-stills-in-the-zone-window-etc for more information."}
Jul 4, 2020 05:33:59 PM DEBUG Hmm I found an error {"result":"Error","message":"Socket /var/run/zm/zms-684761s.sock does not exist.  This file is created by zms, and since it does not exist, either zms did not run, or zms exited early.  Please check your zms logs and ensure that CGI is enabled in apache and check that the PATH_ZMS is set correctly.  Make sure that ZM is actually recording.  If you are trying to view a live stream and the capture process (zmc) is not running then zms will exit. Please go to http://zoneminder.readthedocs.io/en/latest/faq.html#why-can-t-i-see-streamed-images-when-i-can-see-stills-in-the-zone-window-etc for more information."}
Jul 4, 2020 05:34:02 PM DEBUG No object detection found in notes
Jul 4, 2020 05:34:02 PM DEBUG Neighbor next URL=http://cctv.lan/zm/api/events/index/StartTime >:2020-07-04 13:34:40/MonitorId =:1/AlarmFrames >=:1.json?sort=StartTime&direction=asc&limit=1&token=<removed>
Jul 4, 2020 05:34:02 PM DEBUG Neighbor pre URL=http://cctv.lan/zm/api/events/index/StartTime <:2020-07-04 13:34:40/MonitorId =:1/AlarmFrames >=:1.json?sort=StartTime&direction=desc&limit=1&token=<removed>
Jul 4, 2020 05:34:02 PM DEBUG Video url passed to player is: http://cctv.lan/zm/index.php?view=view_video&eid=340939&token=<removed>
Jul 4, 2020 05:34:02 PM DEBUG On Play Ready invoked
Jul 4, 2020 05:34:02 PM DEBUG Setting cue points..
Jul 4, 2020 05:34:02 PM DEBUG API-Total length:8.99
Jul 4, 2020 05:34:02 PM DEBUG Player-Total length:0
Jul 4, 2020 05:34:02 PM DEBUG Hmm I found an error {"result":"Error","message":"Socket /var/run/zm/zms-684761s.sock does not exist.  This file is created by zms, and since it does not exist, either zms did not run, or zms exited early.  Please check your zms logs and ensure that CGI is enabled in apache and check that the PATH_ZMS is set correctly.  Make sure that ZM is actually recording.  If you are trying to view a live stream and the capture process (zmc) is not running then zms will exit. Please go to http://zoneminder.readthedocs.io/en/latest/faq.html#why-can-t-i-see-streamed-images-when-i-can-see-stills-in-the-zone-window-etc for more information."}
Jul 4, 2020 05:34:02 PM DEBUG neighbors of 340939are pre=340933 next=340942
Jul 4, 2020 05:34:04 PM DEBUG This video can be played
Jul 4, 2020 05:34:04 PM DEBUG obfuscate: original:6482 obfuscated:1821 scheme:lzs
Jul 4, 2020 05:34:04 PM DEBUG Setting play at rate:1 as video can be played
Jul 4, 2020 05:34:04 PM DEBUG Video state=play
Jul 4, 2020 05:34:09 PM DEBUG display overlays:false
Jul 4, 2020 05:34:09 PM DEBUG TimelineCtrl:Close & Destroy Modal
Jul 4, 2020 05:34:09 PM INFO TimelineCtrl: closeModal: stopNework: Calling window.stop()
Jul 4, 2020 05:34:09 PM DEBUG Removing keyboard handler
Jul 4, 2020 05:34:09 PM DEBUG Modal removed - killing connkey
Jul 4, 2020 05:34:09 PM DEBUG display overlays:true
Jul 4, 2020 05:34:12 PM DEBUG Removing keyboard handler
Jul 4, 2020 05:34:29 PM DEBUG resize/orient: 984(w) * 741(h)
Jul 4, 2020 05:34:30 PM DEBUG resize/orient: 1920(w) * 997(h)
Jul 4, 2020 06:03:15 PM DEBUG resize/orient: 1920(w) * 1037(h)
Jul 4, 2020 06:03:15 PM DEBUG resize/orient: 1920(w) * 1037(h)

[jordanconstable]

Some screenshots, during the delay and while the errors are showing in ZM the black screen is shown and event info is not shown at the top. After 10 seconds or so, the event info is fetched and shown at the top and the small cloud Icon bounces up and down for a second and then the event will play.

[pliablepixels]

According to your logs:

This is when the video URL is passed to zmNinja

Jul 4, 2020 05:34:02 PM DEBUG Video url passed to player is: http://cctv.lan/zm/index.php?view=view_video&eid=340939&token=

This is when it can play the video

Jul 4, 2020 05:34:04 PM DEBUG Video state=play

That is 2 seconds?

Basically, the video gets downloaded and then played. If you are using the latest ZM master, then it is capable of playing in fragments, but if your bandwidth is low, apparently it can lead to longer load times. But your logs don't show the long load times.

and the small cloud Icon bounces up and down for a second and then the event will play.

I think you'll notice that is starts playing during that 1 second or so. That is an animation after effect - it takes around a second to turn off.

[jordanconstable]

Thanks for looking into this
I agree having looked at this line in the logs there is around 1-2 seconds between the video URL being passed and ZMninja playing the recording. However the delay between opening the event and it playing stands around 15 seconds.
The errors in the log are produced during this time.

The delay in receiving the video URL would suggest this could be a ZM problem, however, as I cannot recreate the problem anywhere else and all events can be called up and played instantly in the browser, I'm at a bit of a loss as to where this problem could lie within ZM itself.

I have screen recorded a different random event on Android for real time delay. The delay is the same for any event.
https://photos.app.goo.gl/wwUXdTHprt3j2Vnc7

[pliablepixels]

Okay, so here is another observation. The chances are that you have a lot of events and/or your API responsiveness is slow.

Jul 4, 2020 05:33:49 PM INFO *** Constructed API for detailed events: http://cctv.lan/zm/api/events/340939.json?&token=<removed>

Jul 4, 2020 05:34:02 PM DEBUG No object detection found in notes

That is an almost 13 second delay. ZM console does not use APIs. zmNinja does.

So try this: Open a browser, log into ZM, open a new tab and do http://cctv.lan/zm/api/events/340939.json -> how long does it take?

However the delay between opening the event and it playing stands around 15 seconds. The errors in the log are produced during this time.

So what is happening here is because that API above is taking a very long time, some parts of the playback checking code (that polls playback status) starts earlier and because the stream hasn't yet started, you see those errors. Besides creating those messages, these don't really cause any other issues.

So bottom line, maybe you can focus on why that API is taking such a long time by looking at ZM logs/CPU at the time of that API seek.

[jordanconstable]

Thank you for the explanation of this
Browsing to the API address you have provided does indeed represent the same delay that is experienced inside of the ZMninja app, so this is a server issue.
The rest of the API works with no problem at all and ZMninja works fine in all other areas, and testing other areas of the API with different addresses load instantly so the API responsiveness is isolated to only pulling the event data. Having followed your advice, CPU load is acceptable and does not change when trying to open an event and the ZM logs show nothing further than the errors we have discussed above.
If you have any further experience with this/suggestions as to where I could look to fix this API problem that would be much appreciated, but I understand however this is not an issue relating to you.
Thanks for your help

[pliablepixels]

It may be possible that your events table is very large and it is taking a lot of time. There may be DB optimizations that can help, but I don't know. However, if you join the ZM slack group (it is on their github page) then you can ask there - Isaac Connor hangs out and may be able to offer perspectives. You can also post in the ZM 1.3x forums