UCSD-E4E / ASM-rpi-node

Aye-Aye Sleep Monitoring Project Raspberry Pi Node
MIT License
0 stars 0 forks source link

[Bug]: Default heartbeat period is too high #31

Closed ntlhui closed 1 year ago

ntlhui commented 2 years ago

Commit Hash

6979d9d93662690b74daed39d586df915a96683a

Steps to Reproduce?

  1. Set up server and node with default settings
  2. Check heartbeat log after 1 day

Observed Behavior

lots of heartbeats that drown out everything else

Desired Behavior

fewer heartbeat messages

Component

Server

Relevant Sensor Node log output

No response

Relevant Sensor Node configuration

No response

Relevant Server log output

No response

Relevant Server configuration

No response

ntlhui commented 2 years ago

Evaluate at 300s

ntlhui commented 2 years ago

Test plan:

  1. Switch asm-285a1fe8-091a-11ec-b104-54e1ad5146fa.dynamic.ucsd.edu to 300s period
  2. Scrub logs from 132.249.242.142 and asm-285a1fe8-091a-11ec-b104-54e1ad5146fa.dynamic.ucsd.edu
  3. Run for 5 days
  4. Evaluate logs
ntlhui commented 2 years ago

Configuration:

IP_CAMERA: address: 192.168.2.65 port: 554 user: [redacted] password: [redacted]


- ayeayespy
  - ASM-common: 10526a0
  - ASM-data-server: 6979d9d
  - ASM_protocol: d4c97cc

$ cat /usr/local/etc/ASMDataServer/asm_config.yaml

This is a sample configuration for the Aye-Aye Sleep Monitoring Data Server.

Use this as a basis for configuring the data server for the specific server.

Local path in which to store the data hierarchy

data_dir: /ayeayedata

This is the primary port for the data server.

port: 9000

Data Server UID

#

This is the UUID that uniquely identifies this device.

server_uuid: '33cc5438-3d39-11ec-8957-378c22225c74'

This is the maximum length of video data

video_increment: 300

RTSP Server Port Block

#

This is the block of ports that RTSP servers should use.

rtsp_port_block: [10000, 10100]

ntlhui commented 2 years ago

On start:

$ sudo service asm_server status
● asm_server.service - ASM Data Server
     Loaded: loaded (/lib/systemd/system/asm_server.service; enabled; vendor preset: enabled)
     Active: active (running) since Wed 2022-07-06 16:46:12 UTC; 14s ago
   Main PID: 223343 (python3)
      Tasks: 6 (limit: 19170)
     Memory: 46.3M
     CGroup: /system.slice/asm_server.service
             ├─223343 /home/asm-data/.asm_venv/bin/python3 /home/asm-data/.asm_venv/bin/runServer.py
             ├─223364 /bin/sh -c ffmpeg -i tcp://@:10000?listen -c copy -flags +global_header -f segment -segment_time 300 -strftime 1 -reset_timestamps 1 /ayeayedata/a4a5090c-fc41-47d4-a180-e82cf8bfc899/%Y.%m.%d.%H.%M.%S.mp4  2>&1 | /home/asm-data/.asm_venv/bin/python3>
             ├─223366 ffmpeg -i tcp://@:10000?listen -c copy -flags +global_header -f segment -segment_time 300 -strftime 1 -reset_timestamps 1 /ayeayedata/a4a5090c-fc41-47d4-a180-e82cf8bfc899/%Y.%m.%d.%H.%M.%S.mp4
             └─223367 /home/asm-data/.asm_venv/bin/python3 -m ASM_utils.ffmpeg.split_log /var/log/ffmpeg_logs/a4a5090c-fc41-47d4-a180-e82cf8bfc899/stats.log /var/log/ffmpeg_logs/a4a5090c-fc41-47d4-a180-e82cf8bfc899/info.log

Jul 06 16:46:13 ayeayespy python3[223362]:     -S <string>           look for differences that change the number of occurrences of the specified string
Jul 06 16:46:13 ayeayespy python3[223362]:     -G <regex>            look for differences that change the number of occurrences of the specified regex
Jul 06 16:46:13 ayeayespy python3[223362]:     --pickaxe-all         show all changes in the changeset with -S or -G
Jul 06 16:46:13 ayeayespy python3[223362]:     --pickaxe-regex       treat <string> in -S as extended POSIX regular expression
Jul 06 16:46:13 ayeayespy python3[223362]:     -O <file>             control the order in which files appear in the output
Jul 06 16:46:13 ayeayespy python3[223362]:     --find-object <object-id>
Jul 06 16:46:13 ayeayespy python3[223362]:                           look for differences that change the number of occurrences of the specified object
Jul 06 16:46:13 ayeayespy python3[223362]:     --diff-filter [(A|C|D|M|R|T|U|X|B)...[*]]
Jul 06 16:46:13 ayeayespy python3[223362]:                           select files by diff type
Jul 06 16:46:13 ayeayespy python3[223362]:     --output <file>       Output to a specific file
$ sudo service asm_sensor_node status
● asm_sensor_node.service - ASM Sensor Node
   Loaded: loaded (/lib/systemd/system/asm_sensor_node.service; enabled; vendor preset: enabled)
   Active: active (running) since Wed 2022-07-06 17:46:23 BST; 42s ago
 Main PID: 7685 (python3)
    Tasks: 3 (limit: 4915)
   CGroup: /system.slice/asm_sensor_node.service
           ├─7685 /usr/bin/python3 /usr/local/bin/runSensorNode.py
           ├─7691 /bin/sh -c ffmpeg -i rtsp://[redacted]@192.168.2.65:554/live.sdp -acodec libmp3lame -ar 11025 -vcodec copy -f mpegts tcp://132.249.242.142:10000 2>&1 | /usr/bin/python3 /home/pi/nthui/ASM-common/ASM_utils/ffmpeg/split_log.py /var/log/ffmpeg_logs/
           └─7693 /usr/bin/python3 /home/pi/nthui/ASM-common/ASM_utils/ffmpeg/split_log.py /var/log/ffmpeg_logs/ffstats.log /var/log/ffmpeg_logs/ffinfo.log

Jul 06 17:46:23 asm-285a1fe8-091a-11ec-b104-54e1ad5146fa systemd[1]: Started ASM Sensor Node.
Jul 06 17:46:24 asm-285a1fe8-091a-11ec-b104-54e1ad5146fa python3[7685]: 2022-07-06 17:46:24.%f BST - NodeCreator - ERROR - Failed to import SensorNode.sensor_nodes.animalFlipper
Jul 06 17:46:24 asm-285a1fe8-091a-11ec-b104-54e1ad5146fa python3[7685]: fatal: not a git repository (or any of the parent directories): .git
Jul 06 17:46:24 asm-285a1fe8-091a-11ec-b104-54e1ad5146fa python3[7685]: Not a git repository
Jul 06 17:46:24 asm-285a1fe8-091a-11ec-b104-54e1ad5146fa python3[7685]: To compare two paths outside a working tree:
Jul 06 17:46:24 asm-285a1fe8-091a-11ec-b104-54e1ad5146fa python3[7685]: usage: git diff [--no-index] <path> <path>
ntlhui commented 2 years ago

Top lines:

2022-07-06 16:46:13.153 - Server - INFO - Starting ASM Data Server v0.0.0.1,  dirty
2022-07-06 16:46:13.155 - root - INFO - Discovered data_dir: /ayeayedata
2022-07-06 16:46:13.155 - root - INFO - Discovered port: 9000
2022-07-06 16:46:13.155 - root - INFO - Discovered server_uuid: 33cc5438-3d39-11ec-8957-378c22225c74
2022-07-06 16:46:13.155 - root - INFO - Discovered video_increment: 300
2022-07-06 16:46:13.155 - root - INFO - Discovered rtsp_port_block: [10000, 10100]
2022-07-06 16:46:13.155 - root - INFO - Data Directory: /ayeayedata
2022-07-06 16:46:13.186 - asyncio - DEBUG - Using selector: EpollSelector
2022-07-06 16:46:13.188 - Server - INFO - Connecting to :9000
2022-07-06 16:46:24.245 - ClientHandler - INFO - Getting client for uuid a4a5090c-fc41-47d4-a180-e82cf8bfc899
2022-07-06 16:46:24.245 - ClientHandler - INFO - Got heartbeat from a4a5090c-fc41-47d4-a180-e82cf8bfc899 (Auto-registered device) at 2022-07-06 16:46:24.242000
2022-07-06 16:46:24.246 - ClientHandler - INFO - Got RTP Start Command
2022-07-06 16:46:24.246 - ClientHandler - INFO - Got port 10000
2022-07-06 16:46:24.246 - ClientHandler - INFO - Started ffmpeg with command: ffmpeg -i tcp://@:10000?listen -c copy -flags +global_header -f segment -segment_time 300 -strftime 1 -reset_timestamps 1 /ayeayedata/a4a5090c-fc41-47d4-a180-e82cf8bfc899/%Y.%m.%d.%H.%M.%S.mp4  2>&1 | /home/asm-data/.asm_venv/bin/python3 -m ASM_utils.ffmpeg.split_log /var/log/ffmpeg_logs/a4a5090c-fc41-47d4-a180-e82cf8bfc899/stats.log /var/log/ffmpeg_logs/a4a5090c-fc41-47d4-a180-e82cf8bfc899/info.log
2022-07-06 16:46:24.249 - ClientHandler - INFO - RTP Server on port 10000 started outputting to /ayeayedata/a4a5090c-fc41-47d4-a180-e82cf8bfc899
2022-07-06 16:46:24.249 - ClientHandler - INFO - FFmpeg logging to: /var/log/ffmpeg_logs/a4a5090c-fc41-47d4-a180-e82cf8bfc899
2022-07-06 16:51:24.253 - ClientHandler - INFO - Got heartbeat from a4a5090c-fc41-47d4-a180-e82cf8bfc899 (Auto-registered device) at 2022-07-06 16:51:24.243000
2022-07-06 16:56:24.256 - ClientHandler - INFO - Got heartbeat from a4a5090c-fc41-47d4-a180-e82cf8bfc899 (Auto-registered device) at 2022-07-06 16:56:24.244000
2022-07-06 17:01:24.251 - ClientHandler - INFO - Got heartbeat from a4a5090c-fc41-47d4-a180-e82cf8bfc899 (Auto-registered device) at 2022-07-06 17:01:24.244000
2022-07-06 17:06:24.249 - ClientHandler - INFO - Got heartbeat from a4a5090c-fc41-47d4-a180-e82cf8bfc899 (Auto-registered device) at 2022-07-06 17:06:24.245000
2022-07-06 17:11:24.250 - ClientHandler - INFO - Got heartbeat from a4a5090c-fc41-47d4-a180-e82cf8bfc899 (Auto-registered device) at 2022-07-06 17:11:24.245000
2022-07-06 17:15:01.862 - ClientHandler - INFO - Rx closed
2022-07-06 17:15:01.862 - ClientHandler - INFO - Tx closed
2022-07-06 17:16:24.251 - ClientHandler - INFO - Got heartbeat from a4a5090c-fc41-47d4-a180-e82cf8bfc899 (Auto-registered device) at 2022-07-06 17:16:24.246000
2022-07-06 17:21:24.252 - ClientHandler - INFO - Got heartbeat from a4a5090c-fc41-47d4-a180-e82cf8bfc899 (Auto-registered device) at 2022-07-06 17:21:24.246000
2022-07-06 17:26:24.271 - ClientHandler - INFO - Got heartbeat from a4a5090c-fc41-47d4-a180-e82cf8bfc899 (Auto-registered device) at 2022-07-06 17:26:24.247000
2022-07-06 17:31:24.254 - ClientHandler - INFO - Got heartbeat from a4a5090c-fc41-47d4-a180-e82cf8bfc899 (Auto-registered device) at 2022-07-06 17:31:24.248000
2022-07-06 17:36:24.255 - ClientHandler - INFO - Got heartbeat from a4a5090c-fc41-47d4-a180-e82cf8bfc899 (Auto-registered device) at 2022-07-06 17:36:24.248000
2022-07-06 17:41:24.260 - ClientHandler - INFO - Got heartbeat from a4a5090c-fc41-47d4-a180-e82cf8bfc899 (Auto-registered device) at 2022-07-06 17:41:24.249000
2022-07-06 17:46:24.257 - ClientHandler - INFO - Got heartbeat from a4a5090c-fc41-47d4-a180-e82cf8bfc899 (Auto-registered device) at 2022-07-06 17:46:24.249000
2022-07-06 17:50:39.670 - ClientHandler - INFO - Rx closed
2022-07-06 17:50:39.671 - ClientHandler - INFO - Tx closed
2022-07-06 17:50:45.875 - ClientHandler - INFO - Rx closed
2022-07-06 17:50:45.875 - ClientHandler - INFO - Tx closed
2022-07-06 17:50:46.123 - ClientHandler - INFO - Rx closed
2022-07-06 17:50:46.123 - ClientHandler - INFO - Tx closed
2022-07-06 17:50:52.373 - ClientHandler - INFO - Rx closed
2022-07-06 17:50:52.373 - ClientHandler - INFO - Tx closed
2022-07-06 17:50:58.607 - ClientHandler - INFO - Rx closed
2022-07-06 17:50:58.608 - ClientHandler - INFO - Tx closed
2022-07-06 17:51:04.815 - ClientHandler - INFO - Rx closed
2022-07-06 17:51:04.815 - ClientHandler - INFO - Tx closed
2022-07-06 17:51:08.162 - ClientHandler - INFO - Rx closed
2022-07-06 17:51:08.162 - ClientHandler - INFO - Tx closed
2022-07-06 17:51:11.397 - ClientHandler - INFO - Rx closed
2022-07-06 17:51:11.397 - ClientHandler - INFO - Tx closed
2022-07-06 17:51:20.613 - ClientHandler - INFO - Rx closed
2022-07-06 17:51:20.613 - ClientHandler - INFO - Tx closed
2022-07-06 17:51:24.259 - ClientHandler - INFO - Got heartbeat from a4a5090c-fc41-47d4-a180-e82cf8bfc899 (Auto-registered device) at 2022-07-06 17:51:24.250000
2022-07-06 17:56:24.260 - ClientHandler - INFO - Got heartbeat from a4a5090c-fc41-47d4-a180-e82cf8bfc899 (Auto-registered device) at 2022-07-06 17:56:24.250000
2022-07-06 18:01:24.256 - ClientHandler - INFO - Got heartbeat from a4a5090c-fc41-47d4-a180-e82cf8bfc899 (Auto-registered device) at 2022-07-06 18:01:24.251000
2022-07-06 18:06:24.260 - ClientHandler - INFO - Got heartbeat from a4a5090c-fc41-47d4-a180-e82cf8bfc899 (Auto-registered device) at 2022-07-06 18:06:24.251000
2022-07-06 18:11:24.263 - ClientHandler - INFO - Got heartbeat from a4a5090c-fc41-47d4-a180-e82cf8bfc899 (Auto-registered device) at 2022-07-06 18:11:24.252000

Might need to do a "Failed to receive heartbeat" message instead. This will require enabling the server to discover the heartbeat period!