Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

confusing behavior when UI and server interpret time zone name differently #167

Open
jlpoolen opened this issue Sep 19, 2021 · 8 comments
Open
Labels

Comments

@jlpoolen
Copy link
Contributor

I"m running a moonfire-nvr on a VM referencing a camera that is about 3' of network cable away and goes through a Power Over Ethernet ("PoE") and a Switch, I'm testing packet loss. I have two feeds, a "main" and a "sub". When I try to view a listing of the "main", nothing appears. When I try to view a listing of the "sub", entries duly appear.

To Reproduce
Log into ares:8080, click the main view, no entries appear. Click the sub view, then another heading appears with entries for the sub.

Expected behavior
I should see entries for the "main" video

Screenshots

2021-09-18_20-31

Server (please complete the following information):

  • If building from git: git describe --dirty + moonfire-nvr --version

    ares /usr/local/src/moonfire-nvr.git # svn status
    ? trunk/server/target
    ? trunk/ui/build
    ? trunk/ui/node_modules
    ares /usr/local/src/moonfire-nvr.git # svn info
    Path: .
    Working Copy Root Path: /usr/local/src/moonfire-nvr.git
    URL: https://github.com/scottlamb/moonfire-nvr.git
    Relative URL: ^/
    Repository Root: https://github.com/scottlamb/moonfire-nvr.git
    Repository UUID: 69f685ad-12d6-831e-7d07-ce57b7db7bff
    Revision: 1244
    Node Kind: directory
    Schedule: normal
    Last Changed Author: john.poole
    Last Changed Rev: 1244
    Last Changed Date: 2021-09-13 17:00:43 -0700 (Mon, 13 Sep 2021)

    ares /usr/local/src/moonfire-nvr.git #

  • Attach a log file. Run with the RUST_BACKTRACE=1 environment variable set if possible.

Not sure where the port 8080 server's log file is. I'm saving a copy of the moonfire-nvr STDERR file and provide entries around 8:30 p.m. 9/19/21 PDT when I attempted to list entries for "main"

Camera (please complete the following information):
Device Name: ReolinkNetworkTest1
Model: RLC-420-5MP
Build No. build 19013001
Hw No. IPC=51516M5M
Cfg version: v2.0.0.0
Fw Version: V2.0.0.354-19013001
Details: IPC_51516M5M110000000100000
IP 192.168.1.56

Desktop (please complete the following information):

  • OS:
    taurus /usr/local/src # uname -a
    Linux taurus 5.10.27-gentoo Rust #6 SMP Mon May 10 20:44:46 PDT 2021 x86_64 Intel(R) Core(TM) i7-8550U CPU @ 1.80GHz GenuineIntel GNU/Linux
    taurus /usr/local/src #

  • Browser Firefox

  • Version 92.0 (64-bit)

Smartphone (please complete the following information):
NA

Additional context
Running moonfire-nvr on Gentoo VM "ares". I noticed the following when trying to use hwclock:

ares /home/jlpoole # date
Sat Sep 18 20:01:59 PDT 2021
ares /home/jlpoole # hwclock
hwclock: Cannot access the Hardware Clock via any known method.
hwclock: Use the --verbose option to see the details of our search for an access method.
ares /home/jlpoole # 

Also, files are being written to the directory, videos/main, specified for "main". Here is a listing:

group_root      10M     0   10M   0% /sys/fs/cgroup
ares /home/jlpoole # ls -la video/main
total 2104393
drwxrwxrwx 2 jlpoole  jlpoole      4096 Sep 18 20:01 .
drwxrwxrwx 4 jlpoole  jlpoole      1024 Sep 14 20:32 ..
-rw------- 1 moonfire moonfire 30977021 Sep 18 18:53 0000000100000d70
-rw------- 1 moonfire moonfire 31036023 Sep 18 18:54 0000000100000d71
-<snip>
-rw------- 1 moonfire moonfire 31303378 Sep 18 19:55 0000000100000dae
-rw------- 1 moonfire moonfire 31026452 Sep 18 19:56 0000000100000daf
-rw------- 1 moonfire moonfire 31089433 Sep 18 19:57 0000000100000db0
-rw------- 1 moonfire moonfire 31356529 Sep 18 19:58 0000000100000db1
-rw------- 1 moonfire moonfire 31122776 Sep 18 19:59 0000000100000db2
-rw------- 1 moonfire moonfire 30822281 Sep 18 20:00 0000000100000db3
-rw------- 1 moonfire moonfire 31305949 Sep 18 20:01 0000000100000db4
-rw------- 1 moonfire moonfire 14051330 Sep 18 20:01 0000000100000db5
-rwxrwxrwx 1 root     root          512 Sep 18 08:51 meta
ares /home/jlpoole # date
Sat Sep 18 20:01:59 PDT 2021
ares /home/jlpoole # hwclock

A listing of the directory .../videos/sub duly shows lots of files.

The api call:

http://ares:8080/api/?/api/?days=true&cameraConfigs=true

displays:

ares /usr/local/src/moonfire-nvr.git # svn status
?       trunk/server/target
?       trunk/ui/build
?       trunk/ui/node_modules
ares /usr/local/src/moonfire-nvr.git # svn info
Path: .
Working Copy Root Path: /usr/local/src/moonfire-nvr.git
URL: https://github.com/scottlamb/moonfire-nvr.git
Relative URL: ^/
Repository Root: https://github.com/scottlamb/moonfire-nvr.git
Repository UUID: 69f685ad-12d6-831e-7d07-ce57b7db7bff
Revision: 1244
Node Kind: directory
Schedule: normal
Last Changed Author: john.poole
Last Changed Rev: 1244
Last Changed Date: 2021-09-13 17:00:43 -0700 (Mon, 13 Sep 2021)

ares /usr/local/src/moonfire-nvr.git # 

timeZoneName	"US/Pacific\n"
cameras	
0	
uuid	"42ba2a2b-9d87-4f16-88fd-93878838974c"
id	1
shortName	"ReolinkNetworkTest1"
description	"This is the revised attempt to add a camera since I could not change the previous entry's disk locations, I deleted the camera and am starting anew here."
config	
onvifHost	"http://192.168.1.56:9000"
username	"moon"
password	"fire123"
streams	
main	
id	1
retainBytes	2147483648
minStartTime90k	146881603931688
maxEndTime90k	146881976510898
totalDuration90k	372579210
totalSampleFileBytes	2144612917
fsBytes	2144735232
record	true
config	
rtspUrl	"rtsp://192.168.1.56:554/h264Preview_01_main"
sub	
id	2
retainBytes	2147483648
minStartTime90k	146878216543213
maxEndTime90k	146881973968515
totalDuration90k	3732373873
totalSampleFileBytes	103190051
fsBytes	104837120
record	true
config	
rtspUrl	"rtsp://192.168.1.56:554/h264Preview_01_sub"
session	
username	"jlpoole"
csrf	"DiDFjnEwTrOp+i5QtTNHiVE8eJ2O4Ckb"
signals	[]
signalTypes	[]
@jlpoolen
Copy link
Contributor Author

I created a new log file where:

launched moonfire-nvr

visited UI, select "main", just heading appeared, no entries. select "sub", entries + heading appeared. Deselected both.

shutdown moonfire-nvr.

here is the log:

moonfire@ares /usr/local/src/moonfire-nvr.git/trunk/server/target/release $ moonfire@ares /usr/local/src/moonfire-nvr.git/trunk/server/target/release $ ./moonfire-nvr run
I20210918 21:12:18.893 main moonfire_nvr::cmds] Opening /var/lib/moonfire-nvr/db/db in ReadWrite mode with SQLite version 3.35.5
I20210918 21:12:18.961 main moonfire_db::db] Loading video sample entries
I20210918 21:12:18.961 main moonfire_db::db] Loaded 2 video sample entries
I20210918 21:12:18.961 main moonfire_db::db] Loading sample file dirs
I20210918 21:12:18.961 main moonfire_db::db] Loaded 3 sample file dirs
I20210918 21:12:18.961 main moonfire_db::db] Loading cameras
I20210918 21:12:18.961 main moonfire_db::db] Loaded 1 cameras
I20210918 21:12:18.961 main moonfire_db::db] Loading streams
I20210918 21:12:18.961 main moonfire_db::db] Loaded 2 streams
I20210918 21:12:18.961 main moonfire_db::db] Loading recordings for camera ReolinkNetworkTest1 stream Main
I20210918 21:12:18.962 main moonfire_db::db] Loaded 70 recordings for camera ReolinkNetworkTest1 stream Main
I20210918 21:12:18.962 main moonfire_db::db] Loading recordings for camera ReolinkNetworkTest1 stream Sub
I20210918 21:12:18.966 main moonfire_db::db] Loaded 733 recordings for camera ReolinkNetworkTest1 stream Sub
I20210918 21:12:18.966 main moonfire_nvr::cmds::run] Database is loaded.
I20210918 21:12:19.062 main moonfire_nvr::cmds::run] Directories are opened.
I20210918 21:12:19.062 main moonfire_nvr::cmds::run] Resolved timezone: US/Pacific

I20210918 21:12:19.062 main moonfire_nvr::cmds::run] Starting syncer for path /home/jlpoole/video/main
I20210918 21:12:19.063 main moonfire_nvr::cmds::run] Starting syncer for path /home/jlpoole/video/sub
I20210918 21:12:19.096 main moonfire_db::db] Flush 1 (why: synchronous deletion): no recording changes
I20210918 21:12:19.131 main moonfire_db::db] Flush 2 (why: synchronous deletion): no recording changes
I20210918 21:12:19.205 main moonfire_db::db] Flush 3 (why: synchronous garbage collection):
/home/jlpoole/video/main: added 0B in 0 recordings (), deleted 0B in 0 (), GCed 1 recordings (1/3503).
I20210918 21:12:19.206 main moonfire_nvr::cmds::run] Starting streamer for ReolinkNetworkTest1-main
I20210918 21:12:19.206 main moonfire_nvr::cmds::run] Starting streamer for ReolinkNetworkTest1-sub
I20210918 21:12:19.206 main moonfire_nvr::cmds::run] Ready to serve HTTP requests
I20210918 21:12:19.206 s-ReolinkNetworkTest1-main moonfire_nvr::streamer] ReolinkNetworkTest1-main: Opening input: rtsp://192.168.1.56:554/h264Preview_01_main 
I20210918 21:12:19.207 s-ReolinkNetworkTest1-sub moonfire_nvr::streamer] ReolinkNetworkTest1-sub: Opening input: rtsp://192.168.1.56:554/h264Preview_01_sub
W20210918 21:12:19.234 tokio-runtime-worker retina::client] Connecting via TCP to known-broken RTSP server "LIVE555 Streaming Media v2013.04.08". See <https://github.com/scottlamb/retina/issues/17>. Consider using UDP instead!
W20210918 21:12:19.248 tokio-runtime-worker retina::client] Connecting via TCP to known-broken RTSP server "LIVE555 Streaming Media v2013.04.08". See <https://github.com/scottlamb/retina/issues/17>. Consider using UDP instead!
^CI20210918 21:12:47.908 main moonfire_nvr::cmds::run] Shutting down streamers.
I20210918 21:12:47.961 s-ReolinkNetworkTest1-sub moonfire_nvr::streamer] ReolinkNetworkTest1-sub: shutting down
I20210918 21:12:47.975 s-ReolinkNetworkTest1-main moonfire_nvr::streamer] ReolinkNetworkTest1-main: shutting down
I20210918 21:12:48.324 main moonfire_nvr::cmds::run] Waiting for HTTP requests to finish.
I20210918 21:12:48.324 main moonfire_nvr::cmds::run] Waiting for TEARDOWN requests to complete.
I20210918 21:12:48.324 main moonfire_nvr::cmds::run] Exiting.
I20210918 21:12:48.358 main moonfire_db::db] Flush 4 (why: drop):
/home/jlpoole/video/sub: added 75K 851B in 1 recordings (2/3576), deleted 0B in 0 (), GCed 0 recordings ().
/home/jlpoole/video/main: added 13M 785K 359B in 1 recordings (1/3574), deleted 0B in 0 (), GCed 0 recordings ().
moonfire@ares /usr/local/src/moonfire-nvr.git/trunk/server/target/release $ 

@scottlamb
Copy link
Owner

Sorry, I'm just noticing this issue now. Are you still having this problem?

The http://ares:8080/api/?/api/?days=true&cameraConfigs=true output says the main stream's maxEndTime90k is 146881976510898 (that's 2021-09-18T20:26:01:20898-07:00 as you can see via the moonfire-nvr ts subcommand) so I certainly would expect the UI to show entries for it on the 18th.

What does http://ares:8080/api/cameras/42ba2a2b-9d87-4f16-88fd-93878838974/main/recordings say?

@jlpoolen
Copy link
Contributor Author

I had to ad a "c" to the end of the URL, so this URL works:

http://ares:8080/api/cameras/42ba2a2b-9d87-4f16-88fd-93878838974c/main/recordings

I launched moonfire and then entered the URL above and received:

 {"recordings":[{"startTime90k":146881825337054,"endTime90k":146882181814096,"sampleFileBytes":2050473341,"videoSamples":119017,"videoSampleEntryId":1,"startId":3506,"openId":27,"endId":3572},{"startTime90k":146882223723055,"endTime90k":146882225840665,"sampleFileBytes":12093372,"videoSamples":708,"videoSampleEntryId":1,"startId":3573,"openId":28},{"startTime90k":146882226598632,"endTime90k":146882229105582,"sampleFileBytes":14435687,"videoSamples":838,"videoSampleEntryId":1,"startId":3574,"openId":29},{"startTime90k":146924623445560,"endTime90k":146924624676580,"sampleFileBytes":6854667,"videoSamples":412,"videoSampleEntryId":1,"startId":3575,"openId":30},{"startTime90k":146924627471118,"endTime90k":146924639388961,"sampleFileBytes":65131608,"videoSamples":3979,"videoSampleEntryId":1,"startId":3576,"openId":31,"firstUncommitted":3577,"endId":3577,"growing":true}],"videoSampleEntries":{"1":{"width":2560,"height":1920,"paspHSpacing":1,"paspVSpacing":1,"aspectWidth":4,"aspectHeight":3}}}

@scottlamb
Copy link
Owner

(Oh, yes, I made a typo in the UUID.) That response looks correct. Probably a Javascript-side problem then. Hmm, if you open up your browser's developer console and have the network tab open when you load the page, what URLs does it request? There should be one like this with a ?startTime90k=...&endTime90k=... and I wonder if it's requesting the wrong day or something.

@jlpoolen
Copy link
Contributor Author

Did as requested. I had not been running moonfire while this issue lingered, and I started and stopped moonfire to perform the tests you suggested today, 9/24. Hence, there will not be a lot of backlog.

What this problem is looking to be is a difference of time zones, i.e. UTC vs. local time (PDT). See that the most recent file has a UTC timestamp, whereas I am accessing it at 9:00 a.m. PDT

firefox_2021-09-24_09-01-18

Again, I am running moonfire on a VM on Xen and see the failure of accessing hwclock from within a guest VM. This suggests to me that there is a mismatch between UTC and local time somewhere. Maybe there should be a clock on the UI indicating the time that the server thinks it is? Or maybe have the default start time be the time the page is instantiated and/or refreshed (but this might interfere with caching values a user may want instead?)?

@scottlamb
Copy link
Owner

Hmm. The server is supposed to tell the browser what time zone to use for display. Looking more closely, its API response in your opening comment says timeZoneName "US/Pacific\n". I wonder if that \n is throwing things off. I'm not sure where it came from. What do these say in the Xen VM?

echo $TZ
ls -laF /etc/localtime /etc/timezone
cat /etc/timezone

Maybe there should be a clock on the UI indicating the time that the server thinks it is?

Yeah, I could probably put this in the top bar somewhere. I've struggled with Javascript time libraries but probably can also put in a warning if the time zone can't be found.

Or maybe have the default start time be the time the page is instantiated and/or refreshed (but this might interfere with caching values a user may want instead?)?

My goal is to use the server-side time zone regardless of the browser. Sometimes I do look at a NVR in another time zone and I find this way less confusing; then the UI matches the timestamp the cameras embed in the video stream, the time zone I'd use when communicating with anyone actually near the house, etc.

@jlpoolen
Copy link
Contributor Author

moonfire@ares /usr/local/src/moonfire-nvr.git/trunk/server/target/release $ date
Fri Sep 24 09:32:30 PDT 2021
moonfire@ares /usr/local/src/moonfire-nvr.git/trunk/server/target/release $ echo $TZ

moonfire@ares /usr/local/src/moonfire-nvr.git/trunk/server/target/release $ ls -laF /etc/localtime /etc/timezone
-rw-r--r-- 1 root root 2836 Jul 18 13:33 /etc/localtime
-rw-r--r-- 1 root root   11 Feb 28  2021 /etc/timezone
moonfire@ares /usr/local/src/moonfire-nvr.git/trunk/server/target/release $ cat /etc/timezone
US/Pacific
moonfire@ares /usr/local/src/moonfire-nvr.git/trunk/server/target/release $

Seeing nothing set for TZ, I set it with:

  export TZ=US/Pacific

and then started moonfire-nvr and this time the time settings were my local time:

firefox_2021-09-24_09-35-16

I believe that the reason the files were not showing up at the start of this issue is because I had files dated in the next day as of UTC whereas my date, PDT, was not the same, so nothing was showing.

The work-around is to export one's TZ into the environment before running moonfire-nvr.

Thank you!

@scottlamb
Copy link
Owner

My server-side time zone detection works like this:

  1. try the TZ environment, which wasn't set until just now.
  2. try seeing where a /etc/localtime symlink points, but it wasn't a symlink on your system.
  3. try reading the contents of /etc/timezone. And yours ends with a newline, which my code wasn't expecting. I'll fix it to trim this string.

@scottlamb scottlamb changed the title UI Does Not List Main Recordings confusing behavior when UI and server disagree about time zone Nov 23, 2021
@scottlamb scottlamb added the bug label Nov 23, 2021
@scottlamb scottlamb changed the title confusing behavior when UI and server disagree about time zone confusing behavior when UI and server interpret time zone name differently Nov 23, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

No branches or pull requests

2 participants