BirdNET-Pi
BirdNET-Pi copied to clipboard
mcguirepr89
"sox FAIL trim: Position 1 is behind the following position"
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:~$
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:
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.