search

mcguirepr89 / BirdNET-Pi

A realtime acoustic bird classification system for the Raspberry Pi 4B, 3B+, and 0W2 built on the TFLite version of BirdNET.
Other
1.3k stars 139 forks source link

"sox FAIL trim: Position 1 is behind the following position" #973

Open jgelsey opened 1 year ago

jgelsey commented 1 year ago

BirdNet stoped analyzing yesterday with "sox FAIL trim: Position 1 is behind the following position" in the log. I see "unable to reach network" in the output of print_diagnostic_info.sh (below) but a ping has no trouble reaching the mentioned network device, and the rtsp streams play fine in VLC media player. Tools->System Controls->Clear ALL Data got detections started again. FWIW using 7 rtsp streams for audio input (from Unifi cameras), no USB microphone.

birdnet:~$ cat print_diagnostic_info.txt 
========== caddy status ==========
● caddy.service - Caddy
     Loaded: loaded (/lib/systemd/system/caddy.service; enabled; vendor preset: enabled)
    Drop-In: /etc/systemd/system/caddy.service.d
             └─override.conf
     Active: active (running) since Sat 2023-07-08 08:20:32 PDT; 22min ago
       Docs: https://caddyserver.com/docs/
   Main PID: 1711 (caddy)
      Tasks: 9 (limit: 8755)
        CPU: 508ms
     CGroup: /system.slice/caddy.service
             └─1711 /usr/bin/caddy run --environ --config /etc/caddy/Caddyfile

Jul 08 08:20:32 birdnet caddy[1711]: {"level":"warn","ts":1688829632.3530626,"msg":"Caddyfile input is not formatted; run the 'caddy fmt' command to fix inconsistencies","adapter":"caddyfile","file":"/etc/caddy/Caddyfile","line":1}
Jul 08 08:20:32 birdnet caddy[1711]: {"level":"info","ts":1688829632.3585544,"logger":"admin","msg":"admin endpoint started","address":"localhost:2019","enforce_origin":false,"origins":["//localhost:2019","//[::1]:2019","//127.0.0.1:2019"]}
Jul 08 08:20:32 birdnet caddy[1711]: {"level":"info","ts":1688829632.3655381,"logger":"tls.cache.maintenance","msg":"started background certificate maintenance","cache":"0x40004091f0"}
Jul 08 08:20:32 birdnet caddy[1711]: {"level":"warn","ts":1688829632.368039,"logger":"http","msg":"server is listening only on the HTTP port, so no automatic HTTPS will be applied to this server","server_name":"srv0","http_port":80}
Jul 08 08:20:32 birdnet caddy[1711]: {"level":"info","ts":1688829632.377894,"logger":"tls","msg":"cleaning storage unit","description":"FileStorage:/var/lib/caddy/.local/share/caddy"}
Jul 08 08:20:32 birdnet caddy[1711]: {"level":"info","ts":1688829632.378084,"logger":"tls","msg":"finished cleaning storage units"}
Jul 08 08:20:32 birdnet caddy[1711]: {"level":"info","ts":1688829632.384936,"logger":"http.log","msg":"server running","name":"srv0","protocols":["h1","h2","h3"]}
Jul 08 08:20:32 birdnet caddy[1711]: {"level":"info","ts":1688829632.3893967,"msg":"autosaved config (load with --resume flag)","file":"/var/lib/caddy/.config/caddy/autosave.json"}
Jul 08 08:20:32 birdnet caddy[1711]: {"level":"info","ts":1688829632.390183,"msg":"serving initial configuration"}
Jul 08 08:20:32 birdnet systemd[1]: Started Caddy.

========== birdnet_analysis status ==========
● birdnet_analysis.service - BirdNET Analysis
     Loaded: loaded (/home/jon/BirdNET-Pi/templates/birdnet_analysis.service; enabled; vendor preset: enabled)
     Active: active (running) since Sat 2023-07-08 08:20:17 PDT; 22min ago
   Main PID: 395 (bash)
      Tasks: 2 (limit: 8755)
        CPU: 1.016s
     CGroup: /system.slice/birdnet_analysis.service
             ├─ 395 bash /usr/local/bin/birdnet_analysis.sh
             └─3569 /home/jon/BirdNET-Pi/birdnet/bin/python3 /home/jon/BirdNET-Pi/scripts/analyze.py --i /home/jon/BirdSongs/StreamData/2023-07-07-birdnet-RTSP_3-10:18:25.wav --o /home/jon/BirdSongs/StreamData/2023-07-07-birdnet-RTSP_3-10:18:25.wav.csv --lat 48.6212 --lon -122.8459 --week 26 --overlap 0.0 --sensitivity 1.25 --min_conf 0.7 --birdweather_id zEX9jPQnTXLxfS1g9FUxx39P

Jul 08 08:20:17 birdnet systemd[1]: Started BirdNET Analysis.
Jul 08 08:20:37 birdnet birdnet_analysis.sh[395]: Files loaded
Jul 08 08:20:38 birdnet birdnet_analysis.sh[395]: RECORDING_LENGTH set to 15
Jul 08 08:20:38 birdnet birdnet_analysis.sh[395]: /home/jon/BirdNET-Pi/birdnet/bin/python3 /home/jon/BirdNET-Pi/scripts/analyze.py --i /home/jon/BirdSongs/StreamData/2023-07-07-birdnet-RTSP_3-10:18:25.wav --o /home/jon/BirdSongs/StreamData/2023-07-07-birdnet-RTSP_3-10:18:25.wav.csv --lat 49.XX --lon -122.XX --week 26 --overlap 0.0 --sensitivity 1.25 --min_conf 0.7 --birdweather_id "IN_USE"

========== birdnet_log status ==========
● birdnet_log.service - BirdNET Analysis Log
     Loaded: loaded (/home/jon/BirdNET-Pi/templates/birdnet_log.service; enabled; vendor preset: enabled)
     Active: active (running) since Sat 2023-07-08 08:20:17 PDT; 22min ago
   Main PID: 392 (gotty)
      Tasks: 14 (limit: 8755)
        CPU: 979ms
     CGroup: /system.slice/birdnet_log.service
             ├─   392 /usr/local/bin/gotty --address localhost -p 8080 -P log --title-format BirdNET-Pi Log birdnet_log.sh
             ├─300665 bash /usr/local/bin/birdnet_log.sh
             ├─300667 journalctl --no-hostname -q -o short -fu birdnet_analysis -ubirdnet_server -uextraction
             └─300669 sed s/Jul 08 //g;s/\/home\/jon\///g;/Line/d;/find/d;/systemd/d;s/ .*\[.*\]: /---/

Jul 08 08:32:40 birdnet gotty[392]: 2023/07/08 08:32:40 127.0.0.1:45668 200 GET /log/auth_token.js
Jul 08 08:32:40 birdnet gotty[392]: 2023/07/08 08:32:40 127.0.0.1:45668 200 GET /log/config.js
Jul 08 08:32:40 birdnet gotty[392]: 2023/07/08 08:32:40 127.0.0.1:45682 200 GET /log/css/xterm_customize.css
Jul 08 08:32:40 birdnet gotty[392]: 2023/07/08 08:32:40 127.0.0.1:45676 200 GET /log/js/gotty-bundle.js
Jul 08 08:32:40 birdnet gotty[392]: 2023/07/08 08:32:40 New client connected: 127.0.0.1:45692, connections: 1/0
Jul 08 08:33:08 birdnet gotty[392]: 2023/07/08 08:33:08 Connection closed by client: 127.0.0.1:45692, connections: 0/0
Jul 08 08:33:20 birdnet gotty[392]: 2023/07/08 08:33:20 127.0.0.1:45676 200 GET /log/
Jul 08 08:33:20 birdnet gotty[392]: 2023/07/08 08:33:20 127.0.0.1:45682 200 GET /log/auth_token.js
Jul 08 08:33:20 birdnet gotty[392]: 2023/07/08 08:33:20 127.0.0.1:45676 200 GET /log/config.js
Jul 08 08:33:20 birdnet gotty[392]: 2023/07/08 08:33:20 New client connected: 127.0.0.1:48282, connections: 1/0

========== birdnet_recording status ==========
● birdnet_recording.service - BirdNET Recording
     Loaded: loaded (/home/jon/BirdNET-Pi/templates/birdnet_recording.service; enabled; vendor preset: enabled)
     Active: active (running) since Sat 2023-07-08 08:20:17 PDT; 22min ago
   Main PID: 393 (bash)
      Tasks: 2 (limit: 8755)
        CPU: 2min 24.258s
     CGroup: /system.slice/birdnet_recording.service
             ├─   393 bash /usr/local/bin/birdnet_recording.sh
             └─524967 ffmpeg -hide_banner -loglevel error -nostdin -vn -thread_queue_size 512 -i rtsp://192.168.1.1:7447/LbkHs1CUv5pDM49D -map 0:a:0 -t 15 -acodec pcm_s16le -ac 2 -ar 48000 file:/home/jon/BirdSongs/StreamData/2023-07-08-birdnet-RTSP_1-08:42:44.wav -vn -thread_queue_size 512 -i rtsp://192.168.1.1:7447/QozIFGB0VElAaVSP -map 1:a:0 -t 15 -acodec pcm_s16le -ac 2 -ar 48000 file:/home/jon/BirdSongs/StreamData/2023-07-08-birdnet-RTSP_2-08:42:44.wav -vn -thread_queue_size 512 -i rtsp://192.168.1.1:7447/F1SymeQO4PHcJurI -map 2:a:0 -t 15 -acodec pcm_s16le -ac 2 -ar 48000 file:/home/jon/BirdSongs/StreamData/2023-07-08-birdnet-RTSP_3-08:42:44.wav -vn -thread_queue_size 512 -i rtsp://192.168.1.1:7447/LtFMqP6kIOrVVTxY -map 3:a:0 -t 15 -acodec pcm_s16le -ac 2 -ar 48000 file:/home/jon/BirdSongs/StreamData/2023-07-08-birdnet-RTSP_4-08:42:44.wav -vn -thread_queue_size 512 -i rtsp://192.168.1.1:7447/cb1wDD4SbDN9cWeC -map 4:a:0 -t 15 -acodec pcm_s16le -ac 2 -ar 48000 file:/home/jon/BirdSongs/StreamData/2023-07-08-birdnet-RTSP_5-08:42:44.wav -vn -thread_queue_size 512 -i rtsp://192.168.1.1:7447/BRKNAGf9fewu5h20 -map 5:a:0 -t 15 -acodec pcm_s16le -ac 2 -ar 48000 file:/home/jon/BirdSongs/StreamData/2023-07-08-birdnet-RTSP_6-08:42:44.wav -vn -thread_queue_size 512 -i rtsp://192.168.1.1:7447/yjxrrkqAoK1p6klT -map 6:a:0 -t 15 -acodec pcm_s16le -ac 2 -ar 48000 file:/home/jon/BirdSongs/StreamData/2023-07-08-birdnet-RTSP_7-08:42:44.wav

Jul 08 08:20:28 birdnet birdnet_recording.sh[1179]: rtsp://192.168.1.1:7447/LbkHs1CUv5pDM49D: Network is unreachable
Jul 08 08:20:28 birdnet birdnet_recording.sh[1283]: [tcp @ 0x559d5a3e60] Connection to tcp://192.168.1.1:7447?timeout=0 failed: Network is unreachable
Jul 08 08:20:28 birdnet birdnet_recording.sh[1283]: rtsp://192.168.1.1:7447/LbkHs1CUv5pDM49D: Network is unreachable
Jul 08 08:20:29 birdnet birdnet_recording.sh[1379]: [tcp @ 0x55a2cb9e60] Connection to tcp://192.168.1.1:7447?timeout=0 failed: Network is unreachable
Jul 08 08:20:29 birdnet birdnet_recording.sh[1379]: rtsp://192.168.1.1:7447/LbkHs1CUv5pDM49D: Network is unreachable
Jul 08 08:20:29 birdnet birdnet_recording.sh[1484]: [tcp @ 0x5583c1be60] Connection to tcp://192.168.1.1:7447?timeout=0 failed: Network is unreachable
Jul 08 08:20:29 birdnet birdnet_recording.sh[1484]: rtsp://192.168.1.1:7447/LbkHs1CUv5pDM49D: Network is unreachable
Jul 08 08:23:04 birdnet birdnet_recording.sh[53045]: [udp @ 0x55a93ad4c0] bind failed: Address already in use
Jul 08 08:23:33 birdnet birdnet_recording.sh[53045]:     Last message repeated 2 times
Jul 08 08:32:49 birdnet birdnet_recording.sh[286055]: [udp @ 0x55a7ea4650] bind failed: Address already in use

========== birdnet_server status ==========
● birdnet_server.service - BirdNET Analysis Server
     Loaded: loaded (/home/jon/BirdNET-Pi/templates/birdnet_server.service; enabled; vendor preset: enabled)
     Active: active (running) since Sat 2023-07-08 08:20:17 PDT; 22min ago
   Main PID: 394 (python3)
      Tasks: 3 (limit: 8755)
        CPU: 6.907s
     CGroup: /system.slice/birdnet_server.service
             └─394 /home/jon/BirdNET-Pi/birdnet/bin/python3 /usr/local/bin/server.py

Jul 08 08:20:17 birdnet systemd[1]: Started BirdNET Analysis Server.
Jul 08 08:20:37 birdnet python3[394]: INFO: Created TensorFlow Lite XNNPACK delegate for CPU.
Jul 08 08:20:38 birdnet python3[394]: LOADING TF LITE MODEL... DONE!
Jul 08 08:20:39 birdnet python3[394]: READING AUDIO DATA... DONE! READ 0 CHUNKS.
Jul 08 08:20:39 birdnet python3[394]: Date-time: 2023-07-07 10:18:25

========== birdnet_stats status ==========
● birdnet_stats.service - BirdNET Stats
     Loaded: loaded (/home/jon/BirdNET-Pi/templates/birdnet_stats.service; enabled; vendor preset: enabled)
     Active: active (running) since Sat 2023-07-08 08:20:17 PDT; 22min ago
   Main PID: 396 (streamlit)
      Tasks: 5 (limit: 8755)
        CPU: 10.180s
     CGroup: /system.slice/birdnet_stats.service
             └─396 /home/jon/BirdNET-Pi/birdnet/bin/python3 /home/jon/BirdNET-Pi/birdnet/bin/streamlit run /home/jon/BirdNET-Pi/scripts/plotly_streamlit.py --browser.gatherUsageStats false --server.address localhost --server.baseUrlPath /stats

Jul 08 08:20:17 birdnet systemd[1]: Started BirdNET Stats.
Jul 08 08:20:34 birdnet streamlit[396]:   You can now view your Streamlit app in your browser.
Jul 08 08:20:34 birdnet streamlit[396]:   URL: http://localhost:8501/stats

========== chart_viewer status ==========
● chart_viewer.service - BirdNET-Pi Chart Viewer Service
     Loaded: loaded (/home/jon/BirdNET-Pi/templates/chart_viewer.service; enabled; vendor preset: enabled)
     Active: activating (auto-restart) since Sat 2023-07-08 08:41:59 PDT; 48s ago
    Process: 505888 ExecStart=/home/jon/BirdNET-Pi/birdnet/bin/python3 /usr/local/bin/daily_plot.py (code=exited, status=0/SUCCESS)
   Main PID: 505888 (code=exited, status=0/SUCCESS)
        CPU: 6.941s

========== extraction status ==========
● extraction.service - BirdNET BirdSound Extraction
     Loaded: loaded (/home/jon/BirdNET-Pi/templates/extraction.service; enabled; vendor preset: enabled)
     Active: active (running) since Sat 2023-07-08 08:20:17 PDT; 22min ago
   Main PID: 405 (bash)
      Tasks: 4 (limit: 8755)
        CPU: 29min 9.851s
     CGroup: /system.slice/extraction.service
             ├─   405 bash -c while true;do extract_new_birdsounds.sh;sleep 3;done
             ├─513977 bash /usr/local/bin/extract_new_birdsounds.sh
             └─526226 [bash]

Jul 08 08:38:18 birdnet env[373653]: NEWFILE=Chestnut-backed_Chickadee-84-2023-07-06-birdnet-RTSP_1-18:18:31.mp3
Jul 08 08:38:18 birdnet env[419457]: sox FAIL trim: Position 1 is behind the following position.
Jul 08 08:40:17 birdnet env[419464]: Line = 2023-07-06-birdnet-RTSP_1-18:18:31.wav.csv
Jul 08 08:40:17 birdnet env[419464]: Line = 21.0;24.0;Poecile rufescens;Chestnut-backed Chickadee;0.8422627
Jul 08 08:40:17 birdnet env[419464]: NEWFILE=Chestnut-backed_Chickadee-84-2023-07-06-birdnet-RTSP_1-18:18:31.mp3
Jul 08 08:40:17 birdnet env[468160]: sox FAIL trim: Position 1 is behind the following position.
Jul 08 08:42:13 birdnet env[468182]: Line = 2023-07-06-birdnet-RTSP_1-18:18:31.wav.csv
Jul 08 08:42:13 birdnet env[468182]: Line = 21.0;24.0;Poecile rufescens;Chestnut-backed Chickadee;0.8422627
Jul 08 08:42:13 birdnet env[468182]: NEWFILE=Chestnut-backed_Chickadee-84-2023-07-06-birdnet-RTSP_1-18:18:31.mp3
Jul 08 08:42:13 birdnet env[513970]: sox FAIL trim: Position 1 is behind the following position.

========== web_terminal status ==========
● web_terminal.service - BirdNET-Pi Web Terminal
     Loaded: loaded (/home/jon/BirdNET-Pi/templates/web_terminal.service; enabled; vendor preset: enabled)
     Active: active (running) since Sat 2023-07-08 08:20:17 PDT; 22min ago
   Main PID: 450 (gotty)
      Tasks: 8 (limit: 8755)
        CPU: 61ms
     CGroup: /system.slice/web_terminal.service
             └─450 /usr/local/bin/gotty --address localhost -w -p 8888 -P terminal --title-format BirdNET-Pi Terminal login

Jul 08 08:20:17 birdnet systemd[1]: Started BirdNET-Pi Web Terminal.
Jul 08 08:20:18 birdnet gotty[450]: 2023/07/08 08:20:18 GoTTY is starting with command: login
Jul 08 08:20:18 birdnet gotty[450]: 2023/07/08 08:20:18 Permitting clients to write input to the PTY.
Jul 08 08:20:19 birdnet gotty[450]: 2023/07/08 08:20:18 HTTP server is listening at: http://127.0.0.1:8888/terminal/

========== spectrogram_viewer status ==========
● spectrogram_viewer.service - BirdNET-Pi Spectrogram Viewer
     Loaded: loaded (/home/jon/BirdNET-Pi/templates/spectrogram_viewer.service; enabled; vendor preset: enabled)
     Active: active (running) since Sat 2023-07-08 08:20:17 PDT; 22min ago
   Main PID: 421 (bash)
      Tasks: 2 (limit: 8755)
        CPU: 7.857s
     CGroup: /system.slice/spectrogram_viewer.service
             ├─   421 bash /usr/local/bin/spectrogram.sh
             └─525581 sleep 3

Jul 08 08:20:17 birdnet systemd[1]: Started BirdNET-Pi Spectrogram Viewer.

========== livestream status ==========
● livestream.service - BirdNET-Pi Live Stream
     Loaded: loaded (/home/jon/BirdNET-Pi/templates/livestream.service; enabled; vendor preset: enabled)
     Active: active (running) since Sat 2023-07-08 08:20:30 PDT; 22min ago
   Main PID: 1722 (bash)
      Tasks: 6 (limit: 8755)
        CPU: 1min 15.563s
     CGroup: /system.slice/livestream.service
             ├─1722 bash /usr/local/bin/livestream.sh
             └─1727 ffmpeg -nostdin -loglevel error -ac 1 -i rtsp://192.168.1.1:7447/LbkHs1CUv5pDM49D -acodec libmp3lame -b:a 320k -ac 1 -content_type audio/mpeg -f mp3 icecast://source:birdnetpi@localhost:8000/stream -re

Jul 08 08:20:30 birdnet systemd[1]: Started BirdNET-Pi Live Stream.

========= Syslog snippet ==========
Jul  8 08:29:11 birdnet systemd[1]: chart_viewer.service: Scheduled restart job, restart counter is at 4.
Jul  8 08:29:11 birdnet systemd[1]: Stopped BirdNET-Pi Chart Viewer Service.
Jul  8 08:29:11 birdnet systemd[1]: chart_viewer.service: Consumed 6.989s CPU time.
Jul  8 08:29:11 birdnet systemd[1]: Started BirdNET-Pi Chart Viewer Service.
Jul  8 08:29:18 birdnet systemd[1]: chart_viewer.service: Succeeded.
Jul  8 08:29:18 birdnet systemd[1]: chart_viewer.service: Consumed 7.271s CPU time.
Jul  8 08:30:01 birdnet CRON[220751]: (jon) CMD (/usr/local/bin/disk_check.sh >/dev/null 2>&1)
Jul  8 08:30:01 birdnet CRON[220752]: (jon) CMD (/usr/local/bin/cleanup.sh >/dev/null 2>&1)
Jul  8 08:30:26 birdnet env[184385]: Line = 2023-07-06-birdnet-RTSP_1-18:18:31.wav.csv
Jul  8 08:30:26 birdnet env[184385]: Line = 21.0;24.0;Poecile rufescens;Chestnut-backed Chickadee;0.8422627
Jul  8 08:30:26 birdnet env[184385]: NEWFILE=Chestnut-backed_Chickadee-84-2023-07-06-birdnet-RTSP_1-18:18:31.mp3
Jul  8 08:30:26 birdnet env[233234]: sox FAIL trim: Position 1 is behind the following position.
Jul  8 08:31:18 birdnet systemd[1]: chart_viewer.service: Scheduled restart job, restart counter is at 5.
Jul  8 08:31:18 birdnet systemd[1]: Stopped BirdNET-Pi Chart Viewer Service.
Jul  8 08:31:18 birdnet systemd[1]: chart_viewer.service: Consumed 7.271s CPU time.
Jul  8 08:31:18 birdnet systemd[1]: Started BirdNET-Pi Chart Viewer Service.
Jul  8 08:31:25 birdnet systemd[1]: chart_viewer.service: Succeeded.
Jul  8 08:31:25 birdnet systemd[1]: chart_viewer.service: Consumed 6.920s CPU time.
Jul  8 08:32:23 birdnet env[233240]: Line = 2023-07-06-birdnet-RTSP_1-18:18:31.wav.csv
Jul  8 08:32:23 birdnet env[233240]: Line = 21.0;24.0;Poecile rufescens;Chestnut-backed Chickadee;0.8422627
Jul  8 08:32:23 birdnet env[233240]: NEWFILE=Chestnut-backed_Chickadee-84-2023-07-06-birdnet-RTSP_1-18:18:31.mp3
Jul  8 08:32:23 birdnet env[279037]: sox FAIL trim: Position 1 is behind the following position.
Jul  8 08:32:39 birdnet gotty[392]: 2023/07/08 08:32:39 127.0.0.1:45668 200 GET /log/
Jul  8 08:32:39 birdnet gotty[392]: 2023/07/08 08:32:39 127.0.0.1:45668 200 GET /log/css/index.css
Jul  8 08:32:40 birdnet gotty[392]: 2023/07/08 08:32:40 127.0.0.1:45668 200 GET /log/css/xterm.css
Jul  8 08:32:40 birdnet gotty[392]: 2023/07/08 08:32:40 127.0.0.1:45668 200 GET /log/auth_token.js
Jul  8 08:32:40 birdnet gotty[392]: 2023/07/08 08:32:40 127.0.0.1:45668 200 GET /log/config.js
Jul  8 08:32:40 birdnet gotty[392]: 2023/07/08 08:32:40 127.0.0.1:45682 200 GET /log/css/xterm_customize.css
Jul  8 08:32:40 birdnet gotty[392]: 2023/07/08 08:32:40 127.0.0.1:45676 200 GET /log/js/gotty-bundle.js
Jul  8 08:32:40 birdnet gotty[392]: 2023/07/08 08:32:40 New client connected: 127.0.0.1:45692, connections: 1/0
Jul  8 08:32:49 birdnet birdnet_recording.sh[286055]: [udp @ 0x55a7ea4650] bind failed: Address already in use
Jul  8 08:33:01 birdnet CRON[292972]: (jon) CMD (/usr/local/bin/cleanup.sh >/dev/null 2>&1)
Jul  8 08:33:08 birdnet gotty[392]: 2023/07/08 08:33:08 Connection closed by client: 127.0.0.1:45692, connections: 0/0
Jul  8 08:33:20 birdnet gotty[392]: 2023/07/08 08:33:20 127.0.0.1:45676 200 GET /log/
Jul  8 08:33:20 birdnet gotty[392]: 2023/07/08 08:33:20 127.0.0.1:45682 200 GET /log/auth_token.js
Jul  8 08:33:20 birdnet gotty[392]: 2023/07/08 08:33:20 127.0.0.1:45676 200 GET /log/config.js
Jul  8 08:33:20 birdnet gotty[392]: 2023/07/08 08:33:20 New client connected: 127.0.0.1:48282, connections: 1/0
Jul  8 08:33:25 birdnet systemd[1]: Started Session 11 of user jon.
Jul  8 08:33:25 birdnet systemd[1]: chart_viewer.service: Scheduled restart job, restart counter is at 6.
Jul  8 08:33:25 birdnet systemd[1]: Stopped BirdNET-Pi Chart Viewer Service.
Jul  8 08:33:25 birdnet systemd[1]: chart_viewer.service: Consumed 6.920s CPU time.
Jul  8 08:33:25 birdnet systemd[1]: Started BirdNET-Pi Chart Viewer Service.
Jul  8 08:33:32 birdnet systemd[1]: chart_viewer.service: Succeeded.
Jul  8 08:33:32 birdnet systemd[1]: chart_viewer.service: Consumed 6.988s CPU time.
Jul  8 08:34:21 birdnet env[279043]: Line = 2023-07-06-birdnet-RTSP_1-18:18:31.wav.csv
Jul  8 08:34:21 birdnet env[279043]: Line = 21.0;24.0;Poecile rufescens;Chestnut-backed Chickadee;0.8422627
Jul  8 08:34:22 birdnet env[279043]: NEWFILE=Chestnut-backed_Chickadee-84-2023-07-06-birdnet-RTSP_1-18:18:31.mp3
Jul  8 08:34:22 birdnet env[324928]: sox FAIL trim: Position 1 is behind the following position.
Jul  8 08:35:01 birdnet CRON[339606]: (jon) CMD (/usr/local/bin/disk_check.sh >/dev/null 2>&1)
Jul  8 08:35:24 birdnet systemd[1]: Starting Cleanup of Temporary Directories...
Jul  8 08:35:24 birdnet systemd[1]: systemd-tmpfiles-clean.service: Succeeded.
Jul  8 08:35:24 birdnet systemd[1]: Finished Cleanup of Temporary Directories.
Jul  8 08:35:32 birdnet systemd[1]: chart_viewer.service: Scheduled restart job, restart counter is at 7.
Jul  8 08:35:32 birdnet systemd[1]: Stopped BirdNET-Pi Chart Viewer Service.
Jul  8 08:35:32 birdnet systemd[1]: chart_viewer.service: Consumed 6.988s CPU time.
Jul  8 08:35:32 birdnet systemd[1]: Started BirdNET-Pi Chart Viewer Service.
Jul  8 08:35:38 birdnet systemd[1]: chart_viewer.service: Succeeded.
Jul  8 08:35:38 birdnet systemd[1]: chart_viewer.service: Consumed 6.954s CPU time.
Jul  8 08:36:01 birdnet CRON[365054]: (jon) CMD (/usr/local/bin/cleanup.sh >/dev/null 2>&1)
Jul  8 08:36:21 birdnet env[324934]: Line = 2023-07-06-birdnet-RTSP_1-18:18:31.wav.csv
Jul  8 08:36:21 birdnet env[324934]: Line = 21.0;24.0;Poecile rufescens;Chestnut-backed Chickadee;0.8422627
Jul  8 08:36:22 birdnet env[324934]: NEWFILE=Chestnut-backed_Chickadee-84-2023-07-06-birdnet-RTSP_1-18:18:31.mp3
Jul  8 08:36:22 birdnet env[373647]: sox FAIL trim: Position 1 is behind the following position.
Jul  8 08:37:38 birdnet systemd[1]: chart_viewer.service: Scheduled restart job, restart counter is at 8.
Jul  8 08:37:38 birdnet systemd[1]: Stopped BirdNET-Pi Chart Viewer Service.
Jul  8 08:37:38 birdnet systemd[1]: chart_viewer.service: Consumed 6.954s CPU time.
Jul  8 08:37:38 birdnet systemd[1]: Started BirdNET-Pi Chart Viewer Service.
Jul  8 08:37:45 birdnet systemd[1]: chart_viewer.service: Succeeded.
Jul  8 08:37:45 birdnet systemd[1]: chart_viewer.service: Consumed 6.899s CPU time.
Jul  8 08:38:18 birdnet env[373653]: Line = 2023-07-06-birdnet-RTSP_1-18:18:31.wav.csv
Jul  8 08:38:18 birdnet env[373653]: Line = 21.0;24.0;Poecile rufescens;Chestnut-backed Chickadee;0.8422627
Jul  8 08:38:18 birdnet env[373653]: NEWFILE=Chestnut-backed_Chickadee-84-2023-07-06-birdnet-RTSP_1-18:18:31.mp3
Jul  8 08:38:18 birdnet env[419457]: sox FAIL trim: Position 1 is behind the following position.
Jul  8 08:39:01 birdnet systemd[1]: Starting Clean php session files...
Jul  8 08:39:01 birdnet CRON[435622]: (root) CMD (  [ -x /usr/lib/php/sessionclean ] && if [ ! -d /run/systemd/system ]; then /usr/lib/php/sessionclean; fi)
Jul  8 08:39:01 birdnet CRON[435623]: (jon) CMD (/usr/local/bin/cleanup.sh >/dev/null 2>&1)
Jul  8 08:39:01 birdnet systemd[1]: phpsessionclean.service: Succeeded.
Jul  8 08:39:01 birdnet systemd[1]: Finished Clean php session files.
Jul  8 08:39:45 birdnet systemd[1]: chart_viewer.service: Scheduled restart job, restart counter is at 9.
Jul  8 08:39:45 birdnet systemd[1]: Stopped BirdNET-Pi Chart Viewer Service.
Jul  8 08:39:45 birdnet systemd[1]: chart_viewer.service: Consumed 6.899s CPU time.
Jul  8 08:39:45 birdnet systemd[1]: Started BirdNET-Pi Chart Viewer Service.
Jul  8 08:39:52 birdnet systemd[1]: chart_viewer.service: Succeeded.
Jul  8 08:39:52 birdnet systemd[1]: chart_viewer.service: Consumed 7.008s CPU time.
Jul  8 08:40:01 birdnet CRON[460218]: (jon) CMD (/usr/local/bin/disk_check.sh >/dev/null 2>&1)
Jul  8 08:40:17 birdnet env[419464]: Line = 2023-07-06-birdnet-RTSP_1-18:18:31.wav.csv
Jul  8 08:40:17 birdnet env[419464]: Line = 21.0;24.0;Poecile rufescens;Chestnut-backed Chickadee;0.8422627
Jul  8 08:40:17 birdnet env[419464]: NEWFILE=Chestnut-backed_Chickadee-84-2023-07-06-birdnet-RTSP_1-18:18:31.mp3
Jul  8 08:40:17 birdnet env[468160]: sox FAIL trim: Position 1 is behind the following position.
Jul  8 08:41:52 birdnet systemd[1]: chart_viewer.service: Scheduled restart job, restart counter is at 10.
Jul  8 08:41:52 birdnet systemd[1]: Stopped BirdNET-Pi Chart Viewer Service.
Jul  8 08:41:52 birdnet systemd[1]: chart_viewer.service: Consumed 7.008s CPU time.
Jul  8 08:41:52 birdnet systemd[1]: Started BirdNET-Pi Chart Viewer Service.
Jul  8 08:41:59 birdnet systemd[1]: chart_viewer.service: Succeeded.
Jul  8 08:41:59 birdnet systemd[1]: chart_viewer.service: Consumed 6.941s CPU time.
Jul  8 08:42:01 birdnet CRON[509012]: (jon) CMD (/usr/local/bin/cleanup.sh >/dev/null 2>&1)
Jul  8 08:42:13 birdnet env[468182]: Line = 2023-07-06-birdnet-RTSP_1-18:18:31.wav.csv
Jul  8 08:42:13 birdnet env[468182]: Line = 21.0;24.0;Poecile rufescens;Chestnut-backed Chickadee;0.8422627
Jul  8 08:42:13 birdnet env[468182]: NEWFILE=Chestnut-backed_Chickadee-84-2023-07-06-birdnet-RTSP_1-18:18:31.mp3
Jul  8 08:42:13 birdnet env[513970]: sox FAIL trim: Position 1 is behind the following position.
========== Mounted File Systems ==========
Filesystem      Size  Used Avail Use% Mounted on
/dev/root        58G   52G  3.4G  94% /
devtmpfs        3.6G     0  3.6G   0% /dev
tmpfs           3.9G     0  3.9G   0% /dev/shm
tmpfs           1.6G  1.2M  1.6G   1% /run
tmpfs           5.0M  4.0K  5.0M   1% /run/lock
/dev/mmcblk0p1  255M   32M  224M  13% /boot
tmpfs           782M  4.0K  782M   1% /run/user/1000

========== Memory Usage ==========
               total        used        free      shared  buff/cache   available
Mem:           7.6Gi       446Mi       5.0Gi       3.0Mi       2.2Gi       7.1Gi
Swap:           99Mi          0B        99Mi

========== Load Averages ==========
 08:42:47 up 22 min,  2 users,  load average: 1.77, 1.92, 1.60

========== CPU Info ==========
processor   : 0
BogoMIPS    : 108.00
Features    : fp asimd evtstrm crc32 cpuid
CPU implementer : 0x41
CPU architecture: 8
CPU variant : 0x0
CPU part    : 0xd08
CPU revision    : 3

processor   : 1
BogoMIPS    : 108.00
Features    : fp asimd evtstrm crc32 cpuid
CPU implementer : 0x41
CPU architecture: 8
CPU variant : 0x0
CPU part    : 0xd08
CPU revision    : 3

processor   : 2
BogoMIPS    : 108.00
Features    : fp asimd evtstrm crc32 cpuid
CPU implementer : 0x41
CPU architecture: 8
CPU variant : 0x0
CPU part    : 0xd08
CPU revision    : 3

processor   : 3
BogoMIPS    : 108.00
Features    : fp asimd evtstrm crc32 cpuid
CPU implementer : 0x41
CPU architecture: 8
CPU variant : 0x0
CPU part    : 0xd08
CPU revision    : 3

Hardware    : BCM2835
Revision    : d03114
Serial      : 10000000479308b8
Model       : Raspberry Pi 4 Model B Rev 1.4

========== System Temperature ==========
CPU Temperature: 54.53°C / 130.15°F

========== Extra Info ==========
........................................IPs.....................................
LAN IP: 192.168.3.254
Public IP: 207.32.170.120
..................................`vcgencmd stats`..............................
throttled=0x0
Binary: 0
....................................Clock Speeds................................
arm:    frequency(48)=1800457088
core:   frequency(1)=500000992
h264:   frequency(28)=0
isp:    frequency(45)=0
v3d:    frequency(46)=500000992
uart:   frequency(22)=48001464
pwm:    frequency(25)=107143064
emmc:   frequency(50)=250000496
pixel:  frequency(29)=81000000
vec:    frequency(10)=0
hdmi:   frequency(9)=119997072
dpi:    frequency(4)=0
........................................Volts...................................
core:   volt=0.9160V
sdram_c:    volt=1.1000V
sdram_i:    volt=1.1000V
sdram_p:    volt=1.1000V
.....................................Caddyfile..................................
http://  {
  root * /home/jon/BirdSongs/Extracted
  file_server browse
  handle /By_Date/* {
    file_server browse
  }
  handle /Charts/* {
    file_server browse
  }
  reverse_proxy /stream localhost:8000
  php_fastcgi unix//run/php/php7.4-fpm.sock
  reverse_proxy /log* localhost:8080
  reverse_proxy /stats* localhost:8501
  reverse_proxy /terminal* localhost:8888
}
.................................... Crontab....................................

SHELL=/bin/sh
PATH=/usr/local/sbin:/usr/local/bin:/sbin:/bin:/usr/sbin:/usr/bin

17 *    * * *   root    cd / && run-parts --report /etc/cron.hourly
25 6    * * *   root    test -x /usr/sbin/anacron || ( cd / && run-parts --report /etc/cron.daily )
47 6    * * 7   root    test -x /usr/sbin/anacron || ( cd / && run-parts --report /etc/cron.weekly )
52 6    1 * *   root    test -x /usr/sbin/anacron || ( cd / && run-parts --report /etc/cron.monthly )
*/5 * * * * jon /usr/local/bin/disk_check.sh >/dev/null 2>&1
*/3 * * * * jon /usr/local/bin/cleanup.sh >/dev/null 2>&1
@reboot jon /usr/local/bin/cleanup.sh >/dev/null 2>&1
0 1 * * 1 jon /usr/local/bin/weekly_report.sh >/dev/null 2>&1

========== Connected Microphone Devices ==========
**** List of CAPTURE Hardware Devices ****

null
    Discard all samples (playback) or generate zero samples (capture)
default
    Playback/recording through the PulseAudio sound server
lavrate
    Rate Converter Plugin Using Libav/FFmpeg Library
samplerate
    Rate Converter Plugin Using Samplerate Library
speexrate
    Rate Converter Plugin Using Speex Resampler
jack
    JACK Audio Connection Kit
oss
    Open Sound System
pulse
    PulseAudio Sound Server
upmix
    Plugin for channel upmix (4,6,8)
vdownmix
    Plugin for channel downmix (stereo) with a simple spacialization
usbstream:CARD=Headphones
    bcm2835 Headphones
    USB Stream Output
usbstream:CARD=vc4hdmi0
    vc4-hdmi-0
    USB Stream Output
usbstream:CARD=vc4hdmi1
    vc4-hdmi-1
    USB Stream Output

========= Date and Time ==========
Sat  8 Jul 08:42:48 PDT 2023
===========================================
birdnet:~$
PeterMescher commented 1 year ago

I've hit this one twice so far. I'll collect more data next time if needed, but for whatever reason, Analyzer is reading in more data (in my case, 5 chunks instead of 10); if there's a successful detection in the latter half, this error occurs when it tries to write the resulting .mp3.

To temporarily fix this issue, you simply need to edit the offending .csv in StreamData-Analyzed to claim the detection occurred earlier in the file. (You can also simply delete it, but this way you don't even lose the detection!)

I'll gather more data next time (the offending .csv and .wav, and the following .csv and .wav.) Don't quote me on this, but I do think that the .wav was indeed twice as long as it should have been.

And this certainly will happen again, so I expect to have a re-create in the next day or two: I searched the logs, and "READ 10 CHUNKS" (signaling a too-long file) seems to occur once or twice an hour. The next time there's a successful detection in the 2nd half of one of those, the bug will trigger again.

So I can be helpful, what would be useful to collect? Besides the relevant journalctl entries (although they don't reveal anything interesting; it looks like the sound file should only be 15 seconds long.)

Here's my diagnostic data:

sox_fail_trim.txt

PeterMescher commented 10 months ago

Here's a script I put in place to work around the issue: (courtesy chatgpt... I dimly remember shell scripting from college a quarter-century ago... took me minutes instead of hours to write this!) This looks for the oldest file of a particular type in a directory, and if it's still there 30 seconds later, delete it. In our case, we want to delete a .csv file that's still there 30 seconds after creation, since it's supposed to process these in less than 15 seconds. (After the deletion, the normal BirdNet scripts will clean up the whole directory once it gets caught up, including the over-sized .wav file.)

Obviously you'll want to modify the sleep time if your interval is different from 15 seconds. (e.g. If running on a Pi Zero once a minutes, you'll want to sleep for two minutes.)

The script is stored in /root.

@#!/bin/bash

# Define the directory and file extension
directory="/home/pi/BirdSongs/StreamData-Analyzed"
extension=".csv"  # Change this to your desired file extension
logfile="/root/csv_logfile.txt"  # Specify the path to your logfile

# Check if the directory exists
if [ ! -d "$directory" ]; then
  echo "Error: Directory does not exist.">> "$logfile"
  exit 1
fi

# Check if there are any files with the specified extension
files=("$directory"/*"$extension")
if [ ${#files[@]} -eq 0 ]; then
  echo "No files with the specified extension found." >> "$logfile"
  exit 0
fi

# Find the oldest file
oldest_file="${files[0]}"
oldest_time=$(stat -c %Y "$oldest_file") 2>> /dev/null

for file in "${files[@]}"; do
  file_time=$(stat -c %Y "$file") 2>> /dev/null
  if [ "$file_time" -lt "$oldest_time" ]; then
    oldest_file="$file"
    oldest_time="$file_time"
  fi
done

# Wait for 30 seconds
sleep 30

# Check if the oldest file is still present
if [ -e "$oldest_file" ]; then
  # Delete the oldest file
  rm "$oldest_file"
  echo "$(date '+%Y-%m-%d %H:%M:%S') Deleted the oldest file: $oldest_file" >> "$logfile"
fi

And don't forget to chmod 755 csv_cleanup.sh to make it executable!

I put in a crontab entry of /5 * /root/csv_cleanup.sh

and that seems to have stopped the problem cold. I had it set to every 30 minutes, but if the problem happened twice in a half-hour, it still got stuck.

Obviously, you will not have recordings for these particular birds in your files, though birdweather still runs on the detection.