2024-08-25 16:51:31.474993 INFO [src/bin.rs:683] CamillaDSP version 2.0.3
2024-08-25 16:51:31.475062 INFO [src/bin.rs:684] Running on linux, aarch64
2024-08-25 16:51:31.475122 DEBUG [src/bin.rs:728] Loaded state: None
2024-08-25 16:51:31.475138 DEBUG [src/bin.rs:732] Using command line argument for initial volume
2024-08-25 16:51:31.475148 DEBUG [src/bin.rs:755] Using default initial mute
2024-08-25 16:51:31.475157 DEBUG [src/bin.rs:765] Initial mute: [false, false, false, false, false]
2024-08-25 16:51:31.475166 DEBUG [src/bin.rs:766] Initial volume: [-40.0, -40.0, -40.0, -40.0, -40.0]
2024-08-25 16:51:31.475181 DEBUG [src/bin.rs:768] Read config file None
2024-08-25 16:51:31.475473 DEBUG [src/socketserver.rs:432] Start websocket server on 0.0.0.0:1234
2024-08-25 16:51:31.475657 DEBUG [src/bin.rs:994] Wait for config
2024-08-25 16:51:31.475678 DEBUG [src/bin.rs:1010] Waiting to receive a command
2024-08-25 16:51:45.323826 DEBUG [/root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tungstenite-0.21.0/src/handshake/server.rs:285] Server handshake done.
2024-08-25 16:51:45.324037 DEBUG [src/socketserver.rs:522] parsed command: Ok(SetConfigFilePath("/root/camilladsp/configs/gadget_m4.yml"))
2024-08-25 16:51:45.325575 DEBUG [src/socketserver.rs:522] parsed command: Ok(Reload)
2024-08-25 16:51:45.326560 DEBUG [src/socketserver.rs:555] WS: Config file loaded successfully, send to controller
2024-08-25 16:51:45.326696 DEBUG [/root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tungstenite-0.21.0/src/protocol/mod.rs:675] Received close frame: None
2024-08-25 16:51:45.326717 DEBUG [/root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tungstenite-0.21.0/src/protocol/mod.rs:692] Replying to close with Frame { header: FrameHeader { is_final: true, rsv1: false, rsv2: false, rsv3: false, opcode: Control(Close), mask: None }, payload: [] }
2024-08-25 16:51:45.326737 DEBUG [src/socketserver.rs:522] parsed command: Ok(None)
2024-08-25 16:51:45.326750 DEBUG [src/socketserver.rs:522] Sending no reply
2024-08-25 16:51:45.326766 DEBUG [src/socketserver.rs:522] Connection was closed
2024-08-25 16:51:45.326737 DEBUG [src/bin.rs:1013] Config change command received
2024-08-25 16:51:45.326786 DEBUG [src/bin.rs:999] New config is available and there are no queued commands, continuing
2024-08-25 16:51:45.326797 DEBUG [src/bin.rs:1036] Config ready, start processing
2024-08-25 16:51:45.327323 DEBUG [src/bin.rs:157] Using channels [true, true, false, true, false, false]
2024-08-25 16:51:45.327272 DEBUG [src/filters.rs:488] Build new pipeline
2024-08-25 16:51:45.327702 DEBUG [src/filters.rs:364] Build filter group from config
2024-08-25 16:51:45.327736 DEBUG [src/basicfilters.rs:329] Building delay filter 'delay' with delay 8640 samples
2024-08-25 16:51:45.327940 DEBUG [src/filters.rs:364] Build filter group from config
2024-08-25 16:51:45.327956 DEBUG [src/basicfilters.rs:329] Building delay filter 'delay' with delay 8640 samples
2024-08-25 16:51:45.328129 DEBUG [src/filters.rs:364] Build filter group from config
2024-08-25 16:51:45.328141 DEBUG [src/basicfilters.rs:329] Building delay filter 'delay' with delay 8640 samples
2024-08-25 16:51:45.328317 DEBUG [src/processing.rs:19] build filters, waiting to start processing loop
2024-08-25 16:51:45.440998 DEBUG [src/alsadevice.rs:334] Available Playback devices: [("hw:M4,0,0", "M4, USB Audio, subdevice #0"), ("hw:ICUSBAUDIO7D,0,0", "ICUSBAUDIO7D, USB Audio, subdevice #0"), ("hw:Loopback,0,0", "Loopback, Loopback PCM, subdevice #0"), ("hw:Loopback,0,1", "Loopback, Loopback PCM, subdevice #1"), ("hw:Loopback,0,2", "Loopback, Loopback PCM, subdevice #2"), ("hw:Loopback,0,3", "Loopback, Loopback PCM, subdevice #3"), ("hw:Loopback,0,4", "Loopback, Loopback PCM, subdevice #4"), ("hw:Loopback,0,5", "Loopback, Loopback PCM, subdevice #5"), ("hw:Loopback,0,6", "Loopback, Loopback PCM, subdevice #6"), ("hw:Loopback,0,7", "Loopback, Loopback PCM, subdevice #7"), ("hw:Loopback,1,0", "Loopback, Loopback PCM, subdevice #0"), ("hw:Loopback,1,1", "Loopback, Loopback PCM, subdevice #1"), ("hw:Loopback,1,2", "Loopback, Loopback PCM, subdevice #2"), ("hw:Loopback,1,3", "Loopback, Loopback PCM, subdevice #3"), ("hw:Loopback,1,4", "Loopback, Loopback PCM, subdevice #4"), ("hw:Loopback,1,5", "Loopback, Loopback PCM, subdevice #5"), ("hw:Loopback,1,6", "Loopback, Loopback PCM, subdevice #6"), ("hw:Loopback,1,7", "Loopback, Loopback PCM, subdevice #7"), ("null", "Discard all samples (playback) or generate zero samples (capture)"), ("sysdefault", "Default Audio Device"), ("sysdefault:CARD=M4", "M4, USB Audio\nDefault Audio Device"), ("front:CARD=M4,DEV=0", "M4, USB Audio\nFront output / input"), ("surround21:CARD=M4,DEV=0", "M4, USB Audio\n2.1 Surround output to Front and Subwoofer speakers"), ("surround40:CARD=M4,DEV=0", "M4, USB Audio\n4.0 Surround output to Front and Rear speakers"), ("surround41:CARD=M4,DEV=0", "M4, USB Audio\n4.1 Surround output to Front, Rear and Subwoofer speakers"), ("surround50:CARD=M4,DEV=0", "M4, USB Audio\n5.0 Surround output to Front, Center and Rear speakers"), ("surround51:CARD=M4,DEV=0", "M4, USB Audio\n5.1 Surround output to Front, Center, Rear and Subwoofer speakers"), ("surround71:CARD=M4,DEV=0", "M4, USB Audio\n7.1 Surround output to Front, Center, Side, Rear and Woofer speakers"), ("iec958:CARD=M4,DEV=0", "M4, USB Audio\nIEC958 (S/PDIF) Digital Audio Output"), ("sysdefault:CARD=ICUSBAUDIO7D", "ICUSBAUDIO7D, USB Audio\nDefault Audio Device"), ("front:CARD=ICUSBAUDIO7D,DEV=0", "ICUSBAUDIO7D, USB Audio\nFront output / input"), ("surround21:CARD=ICUSBAUDIO7D,DEV=0", "ICUSBAUDIO7D, USB Audio\n2.1 Surround output to Front and Subwoofer speakers"), ("surround40:CARD=ICUSBAUDIO7D,DEV=0", "ICUSBAUDIO7D, USB Audio\n4.0 Surround output to Front and Rear speakers"), ("surround41:CARD=ICUSBAUDIO7D,DEV=0", "ICUSBAUDIO7D, USB Audio\n4.1 Surround output to Front, Rear and Subwoofer speakers"), ("surround50:CARD=ICUSBAUDIO7D,DEV=0", "ICUSBAUDIO7D, USB Audio\n5.0 Surround output to Front, Center and Rear speakers"), ("surround51:CARD=ICUSBAUDIO7D,DEV=0", "ICUSBAUDIO7D, USB Audio\n5.1 Surround output to Front, Center, Rear and Subwoofer speakers"), ("surround71:CARD=ICUSBAUDIO7D,DEV=0", "ICUSBAUDIO7D, USB Audio\n7.1 Surround output to Front, Center, Side, Rear and Woofer speakers"), ("iec958:CARD=ICUSBAUDIO7D,DEV=0", "ICUSBAUDIO7D, USB Audio\nIEC958 (S/PDIF) Digital Audio Output"), ("sysdefault:CARD=Loopback", "Loopback, Loopback PCM\nDefault Audio Device"), ("front:CARD=Loopback,DEV=0", "Loopback, Loopback PCM\nFront output / input"), ("surround21:CARD=Loopback,DEV=0", "Loopback, Loopback PCM\n2.1 Surround output to Front and Subwoofer speakers"), ("surround40:CARD=Loopback,DEV=0", "Loopback, Loopback PCM\n4.0 Surround output to Front and Rear speakers"), ("surround41:CARD=Loopback,DEV=0", "Loopback, Loopback PCM\n4.1 Surround output to Front, Rear and Subwoofer speakers"), ("surround50:CARD=Loopback,DEV=0", "Loopback, Loopback PCM\n5.0 Surround output to Front, Center and Rear speakers"), ("surround51:CARD=Loopback,DEV=0", "Loopback, Loopback PCM\n5.1 Surround output to Front, Center, Rear and Subwoofer speakers"), ("surround71:CARD=Loopback,DEV=0", "Loopback, Loopback PCM\n7.1 Surround output to Front, Center, Side, Rear and Woofer speakers")]
2024-08-25 16:51:45.441407 DEBUG [src/alsadevice.rs:334] Available Capture devices: [("hw:M4,0,0", "M4, USB Audio, subdevice #0"), ("hw:ICUSBAUDIO7D,0,0", "ICUSBAUDIO7D, USB Audio, subdevice #0"), ("hw:UAC2Gadget,0,0", "UAC2_Gadget, UAC2 PCM, subdevice #0"), ("hw:Loopback,0,0", "Loopback, Loopback PCM, subdevice #0"), ("hw:Loopback,0,1", "Loopback, Loopback PCM, subdevice #1"), ("hw:Loopback,0,2", "Loopback, Loopback PCM, subdevice #2"), ("hw:Loopback,0,3", "Loopback, Loopback PCM, subdevice #3"), ("hw:Loopback,0,4", "Loopback, Loopback PCM, subdevice #4"), ("hw:Loopback,0,5", "Loopback, Loopback PCM, subdevice #5"), ("hw:Loopback,0,6", "Loopback, Loopback PCM, subdevice #6"), ("hw:Loopback,0,7", "Loopback, Loopback PCM, subdevice #7"), ("hw:Loopback,1,0", "Loopback, Loopback PCM, subdevice #0"), ("hw:Loopback,1,1", "Loopback, Loopback PCM, subdevice #1"), ("hw:Loopback,1,2", "Loopback, Loopback PCM, subdevice #2"), ("hw:Loopback,1,3", "Loopback, Loopback PCM, subdevice #3"), ("hw:Loopback,1,4", "Loopback, Loopback PCM, subdevice #4"), ("hw:Loopback,1,5", "Loopback, Loopback PCM, subdevice #5"), ("hw:Loopback,1,6", "Loopback, Loopback PCM, subdevice #6"), ("hw:Loopback,1,7", "Loopback, Loopback PCM, subdevice #7"), ("null", "Discard all samples (playback) or generate zero samples (capture)"), ("sysdefault", "Default Audio Device"), ("sysdefault:CARD=M4", "M4, USB Audio\nDefault Audio Device"), ("front:CARD=M4,DEV=0", "M4, USB Audio\nFront output / input"), ("sysdefault:CARD=ICUSBAUDIO7D", "ICUSBAUDIO7D, USB Audio\nDefault Audio Device"), ("front:CARD=ICUSBAUDIO7D,DEV=0", "ICUSBAUDIO7D, USB Audio\nFront output / input"), ("sysdefault:CARD=UAC2Gadget", "UAC2_Gadget, UAC2 PCM\nDefault Audio Device"), ("sysdefault:CARD=Loopback", "Loopback, Loopback PCM\nDefault Audio Device"), ("front:CARD=Loopback,DEV=0", "Loopback, Loopback PCM\nFront output / input")]
2024-08-25 16:51:45.442087 DEBUG [src/alsadevice.rs:352] Playback: supported channels, min: 4, max: 4, list: [4]
2024-08-25 16:51:45.442114 DEBUG [src/alsadevice.rs:353] Playback: setting channels to 4
2024-08-25 16:51:45.442201 DEBUG [src/alsadevice.rs:357] Playback: supported samplerates: Discrete([44100, 48000, 88200, 96000, 176400, 192000])
2024-08-25 16:51:45.442212 DEBUG [src/alsadevice.rs:358] Playback: setting rate to 48000
2024-08-25 16:51:45.442239 DEBUG [src/alsadevice.rs:362] Playback: supported sample formats: [S32LE]
2024-08-25 16:51:45.442250 DEBUG [src/alsadevice.rs:363] Playback: setting format to S32LE
2024-08-25 16:51:45.442271 DEBUG [src/alsadevice_buffermanager.rs:57] Setting buffer size to 4096 frames
2024-08-25 16:51:45.442307 DEBUG [src/alsadevice_buffermanager.rs:70] Device is using a buffer size of 4096 frames
2024-08-25 16:51:45.442319 DEBUG [src/alsadevice_buffermanager.rs:78] Setting period size to 512 frames
2024-08-25 16:51:45.453870 DEBUG [src/alsadevice.rs:387] Opening Playback device "hw:M4,0,0" with parameters: HwParams { channels: Ok(4), rate: "Ok(48000) Hz", format: Ok(S32LE), access: Ok(RWInterleaved), period_size: "Ok(512) frames", buffer_size: "Ok(4096) frames" }, SwParams(avail_min: Ok(1024) frames, start_threshold: Ok(1) frames, stop_threshold: Ok(4096) frames)
2024-08-25 16:51:45.453947 DEBUG [src/alsadevice.rs:392] Playback device "hw:M4,0,0" successfully opened
2024-08-25 16:51:45.454018 DEBUG [src/bin.rs:265] Playback thread ready to start
2024-08-25 16:51:45.454567 DEBUG [src/alsadevice.rs:352] Capture: supported channels, min: 6, max: 6, list: [6]
2024-08-25 16:51:45.454597 DEBUG [src/alsadevice.rs:353] Capture: setting channels to 6
2024-08-25 16:51:45.454617 DEBUG [src/alsadevice.rs:357] Capture: supported samplerates: Discrete([48000])
2024-08-25 16:51:45.454628 DEBUG [src/alsadevice.rs:358] Capture: setting rate to 48000
2024-08-25 16:51:45.454645 DEBUG [src/alsadevice.rs:362] Capture: supported sample formats: [S32LE]
2024-08-25 16:51:45.454653 DEBUG [src/alsadevice.rs:363] Capture: setting format to S32LE
2024-08-25 16:51:45.454675 DEBUG [src/alsadevice_buffermanager.rs:57] Setting buffer size to 4096 frames
2024-08-25 16:51:45.454705 DEBUG [src/alsadevice_buffermanager.rs:70] Device is using a buffer size of 2720 frames
2024-08-25 16:51:45.454717 DEBUG [src/alsadevice_buffermanager.rs:78] Setting period size to 340 frames
2024-08-25 16:51:45.454850 DEBUG [src/alsadevice.rs:387] Opening Capture device "hw:UAC2Gadget,0,0" with parameters: HwParams { channels: Ok(6), rate: "Ok(48000) Hz", format: Ok(S32LE), access: Ok(RWInterleaved), period_size: "Ok(170) frames", buffer_size: "Ok(2720) frames" }, SwParams(avail_min: Ok(1024) frames, start_threshold: Ok(0) frames, stop_threshold: Ok(2720) frames)
2024-08-25 16:51:45.454897 DEBUG [src/alsadevice.rs:392] Capture device "hw:UAC2Gadget,0,0" successfully opened
2024-08-25 16:51:45.454930 DEBUG [src/bin.rs:275] Capture thread ready to start
2024-08-25 16:51:45.454944 DEBUG [src/bin.rs:278] Both capture and playback ready, release barrier
2024-08-25 16:51:45.454965 DEBUG [src/bin.rs:280] Supervisor loop starts now!
2024-08-25 16:51:45.454975 DEBUG [src/alsadevice.rs:1037] Starting captureloop
2024-08-25 16:51:45.454997 DEBUG [src/alsadevice.rs:951] Starting playback loop
2024-08-25 16:51:45.455014 DEBUG [src/alsadevice.rs:415] Playback loop uses a buffer of 1024 frames
2024-08-25 16:51:45.455051 DEBUG [src/processing.rs:21] Processing loop starts now!
2024-08-25 16:51:45.455466 INFO [src/alsadevice.rs:648] Capture device supports rate adjust
2024-08-25 16:51:45.455486 DEBUG [src/alsadevice.rs:657] Capture loop uses a buffer of 2720 frames
2024-08-25 16:51:45.455578 DEBUG [src/alsadevice.rs:253] Starting capture from state: SND_PCM_STATE_PREPARED, Ready to start
2024-08-25 16:51:45.539758 INFO [src/alsadevice.rs:799] Capture device is stalled, processing is stalled
2024-08-25 16:51:45.540524 DEBUG [src/countertimer.rs:240] Number of values changed. New 6, prev 2. Clearing history.
2024-08-25 16:51:45.540568 DEBUG [src/countertimer.rs:240] Number of values changed. New 6, prev 2. Clearing history.
2024-08-25 16:51:45.540760 DEBUG [src/alsadevice.rs:253] Starting capture from state: SND_PCM_STATE_PREPARED, Ready to start
2024-08-25 16:52:16.190075 INFO [src/alsadevice.rs:142] PB: Starting playback from Prepared state
2024-08-25 16:52:16.232360 DEBUG [src/countertimer.rs:240] Number of values changed. New 4, prev 2. Clearing history.
2024-08-25 16:52:16.232422 DEBUG [src/countertimer.rs:240] Number of values changed. New 4, prev 2. Clearing history.
2024-08-25 16:52:16.232890 DEBUG [src/alsadevice.rs:573] PB: buffer level: 1024.0, signal rms: Some(HistoryRecord { time: Instant { tv_sec: 214, tv_nsec: 579724146 }, values: [0.0, 0.0, 0.0, 0.0] })
2024-08-25 16:52:18.240523 DEBUG [src/alsadevice_utils.rs:251] Avg. buffer delay: 2038.0, target delay: 2047, diff: -9, prev_div: -1023, corrected capture rate: 100.0000%
2024-08-25 16:52:18.240730 DEBUG [src/bin.rs:386] SetSpeed message received
2024-08-25 16:52:18.240824 DEBUG [src/alsadevice.rs:573] PB: buffer level: 2038.0, signal rms: Some(HistoryRecord { time: Instant { tv_sec: 216, tv_nsec: 587351459 }, values: [3.1863026e-5, 0.0, 0.0, 0.0] })
2024-08-25 16:52:20.245014 DEBUG [src/alsadevice_utils.rs:251] Avg. buffer delay: 2043.2, target delay: 2047, diff: -3.8085106382977756, prev_div: -9, corrected capture rate: 100.0010%
2024-08-25 16:52:20.245247 DEBUG [src/bin.rs:386] SetSpeed message received
2024-08-25 16:52:20.245341 DEBUG [src/alsadevice.rs:573] PB: buffer level: 2043.2, signal rms: Some(HistoryRecord { time: Instant { tv_sec: 218, tv_nsec: 591842070 }, values: [0.0, 0.0, 0.0, 0.0] })
2024-08-25 16:52:22.250084 DEBUG [src/alsadevice_utils.rs:251] Avg. buffer delay: 2060.5, target delay: 2047, diff: 13.531243404255747, prev_div: -3.8085106382977756, corrected capture rate: 100.0000%
2024-08-25 16:52:22.250289 DEBUG [src/bin.rs:386] SetSpeed message received
2024-08-25 16:52:22.250363 DEBUG [src/alsadevice.rs:573] PB: buffer level: 2060.5, signal rms: Some(HistoryRecord { time: Instant { tv_sec: 220, tv_nsec: 596912741 }, values: [0.0, 0.0, 0.0, 0.0] })
2024-08-25 16:52:24.254527 DEBUG [src/alsadevice_utils.rs:251] Avg. buffer delay: 2067.8, target delay: 2047, diff: 20.808510638297776, prev_div: 13.531243404255747, corrected capture rate: 99.9990%
2024-08-25 16:52:24.254688 DEBUG [src/alsadevice.rs:573] PB: buffer level: 2067.8, signal rms: Some(HistoryRecord { time: Instant { tv_sec: 222, tv_nsec: 601353554 }, values: [0.0, 3.2553507e-5, 0.0, 0.0] })
2024-08-25 16:52:24.254822 DEBUG [src/bin.rs:386] SetSpeed message received
2024-08-25 16:52:25.000013 INFO [src/alsadevice.rs:799] Capture device is stalled, processing is stalled
2024-08-25 16:52:25.000752 DEBUG [src/alsadevice.rs:253] Starting capture from state: SND_PCM_STATE_PREPARED, Ready to start
2024-08-25 16:52:26.257630 DEBUG [/root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tungstenite-0.21.0/src/handshake/server.rs:285] Server handshake done.
2024-08-25 16:52:26.258030 DEBUG [src/socketserver.rs:522] parsed command: Ok(AdjustVolume(1.0))
2024-08-25 16:52:26.258412 DEBUG [/root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tungstenite-0.21.0/src/protocol/mod.rs:675] Received close frame: None
2024-08-25 16:52:26.258440 DEBUG [/root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tungstenite-0.21.0/src/protocol/mod.rs:692] Replying to close with Frame { header: FrameHeader { is_final: true, rsv1: false, rsv2: false, rsv3: false, opcode: Control(Close), mask: None }, payload: [] }
2024-08-25 16:52:26.258469 DEBUG [src/socketserver.rs:522] parsed command: Ok(None)
2024-08-25 16:52:26.258485 DEBUG [src/socketserver.rs:522] Sending no reply
2024-08-25 16:52:26.258526 DEBUG [src/socketserver.rs:522] Connection was closed
2024-08-25 16:52:26.481914 DEBUG [/root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tungstenite-0.21.0/src/handshake/server.rs:285] Server handshake done.
2024-08-25 16:52:26.482306 DEBUG [src/socketserver.rs:522] parsed command: Ok(AdjustVolume(1.0))
2024-08-25 16:52:26.482534 DEBUG [/root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tungstenite-0.21.0/src/protocol/mod.rs:675] Received close frame: None
2024-08-25 16:52:26.482566 DEBUG [/root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tungstenite-0.21.0/src/protocol/mod.rs:692] Replying to close with Frame { header: FrameHeader { is_final: true, rsv1: false, rsv2: false, rsv3: false, opcode: Control(Close), mask: None }, payload: [] }
2024-08-25 16:52:26.482596 DEBUG [src/socketserver.rs:522] parsed command: Ok(None)
2024-08-25 16:52:26.482611 DEBUG [src/socketserver.rs:522] Sending no reply
2024-08-25 16:52:26.482653 DEBUG [src/socketserver.rs:522] Connection was closed
2024-08-25 16:52:26.685683 DEBUG [/root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tungstenite-0.21.0/src/handshake/server.rs:285] Server handshake done.
2024-08-25 16:52:26.686033 DEBUG [src/socketserver.rs:522] parsed command: Ok(AdjustVolume(1.0))
2024-08-25 16:52:26.686425 DEBUG [/root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tungstenite-0.21.0/src/protocol/mod.rs:675] Received close frame: None
2024-08-25 16:52:26.686456 DEBUG [/root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tungstenite-0.21.0/src/protocol/mod.rs:692] Replying to close with Frame { header: FrameHeader { is_final: true, rsv1: false, rsv2: false, rsv3: false, opcode: Control(Close), mask: None }, payload: [] }
2024-08-25 16:52:26.686486 DEBUG [src/socketserver.rs:522] parsed command: Ok(None)
2024-08-25 16:52:26.686501 DEBUG [src/socketserver.rs:522] Sending no reply
2024-08-25 16:52:26.686541 DEBUG [src/socketserver.rs:522] Connection was closed
2024-08-25 16:52:26.782227 WARN [src/alsadevice.rs:138] PB: Prepare playback after buffer underrun
2024-08-25 16:52:26.824758 DEBUG [src/alsadevice_utils.rs:251] Avg. buffer delay: 2080.8, target delay: 2047, diff: 33.81790129032288, prev_div: 20.808510638297776, corrected capture rate: 99.9980%
2024-08-25 16:52:26.824850 DEBUG [src/alsadevice.rs:573] PB: buffer level: 2080.8, signal rms: Some(HistoryRecord { time: Instant { tv_sec: 225, tv_nsec: 171588995 }, values: [0.0, 3.16169e-5, 0.0, 0.0] })
2024-08-25 16:52:26.825036 DEBUG [src/bin.rs:386] SetSpeed message received
2024-08-25 16:52:28.832504 DEBUG [src/alsadevice_utils.rs:251] Avg. buffer delay: 2043.5, target delay: 2047, diff: -3.5617029166664906, prev_div: 33.81790129032288, corrected capture rate: 100.0010%
2024-08-25 16:52:28.832659 DEBUG [src/alsadevice.rs:573] PB: buffer level: 2043.5, signal rms: Some(HistoryRecord { time: Instant { tv_sec: 227, tv_nsec: 179332551 }, values: [6.3575106e-5, 0.0, 0.0, 0.0] })
2024-08-25 16:52:28.832716 DEBUG [src/bin.rs:386] SetSpeed message received
2024-08-25 16:52:30.836981 DEBUG [src/alsadevice_utils.rs:251] Avg. buffer delay: 2066.0, target delay: 2047, diff: 19.052575212765987, prev_div: -3.5617029166664906, corrected capture rate: 99.9980%
2024-08-25 16:52:30.837144 DEBUG [src/alsadevice.rs:573] PB: buffer level: 2066.0, signal rms: Some(HistoryRecord { time: Instant { tv_sec: 229, tv_nsec: 183810150 }, values: [0.0, 0.0, 0.0, 0.0] })
2024-08-25 16:52:30.837222 DEBUG [src/bin.rs:386] SetSpeed message received
2024-08-25 16:52:32.842055 DEBUG [src/alsadevice_utils.rs:251] Avg. buffer delay: 2073.6, target delay: 2047, diff: 26.55427276595765, prev_div: 19.052575212765987, corrected capture rate: 99.9970%
2024-08-25 16:52:32.842214 DEBUG [src/alsadevice.rs:573] PB: buffer level: 2073.6, signal rms: Some(HistoryRecord { time: Instant { tv_sec: 231, tv_nsec: 188883110 }, values: [0.0, 0.0, 0.0, 0.0] })
2024-08-25 16:52:32.842274 DEBUG [src/bin.rs:386] SetSpeed message received
2024-08-25 16:52:34.846497 DEBUG [src/alsadevice_utils.rs:251] Avg. buffer delay: 2090.6, target delay: 2047, diff: 43.564940744680825, prev_div: 26.55427276595765, corrected capture rate: 99.9960%
2024-08-25 16:52:34.846653 DEBUG [src/alsadevice.rs:573] PB: buffer level: 2090.6, signal rms: Some(HistoryRecord { time: Instant { tv_sec: 233, tv_nsec: 193325514 }, values: [0.0, 6.495279e-5, 0.0, 0.0] })
2024-08-25 16:52:34.846693 DEBUG [src/bin.rs:386] SetSpeed message received
2024-08-25 16:52:36.854492 DEBUG [src/alsadevice_utils.rs:251] Avg. buffer delay: 2106.3, target delay: 2047, diff: 59.202982553192214, prev_div: 43.564940744680825, corrected capture rate: 99.9950%
2024-08-25 16:52:36.854641 DEBUG [src/alsadevice.rs:573] PB: buffer level: 2106.3, signal rms: Some(HistoryRecord { time: Instant { tv_sec: 235, tv_nsec: 201320827 }, values: [0.0, 0.0, 0.0, 0.0] })
2024-08-25 16:52:36.854751 DEBUG [src/bin.rs:386] SetSpeed message received
2024-08-25 16:52:38.859568 DEBUG [src/alsadevice_utils.rs:251] Avg. buffer delay: 2084.2, target delay: 2047, diff: 37.129830851064526, prev_div: 59.202982553192214, corrected capture rate: 99.9950%
2024-08-25 16:52:38.859726 DEBUG [src/alsadevice.rs:573] PB: buffer level: 2084.2, signal rms: Some(HistoryRecord { time: Instant { tv_sec: 237, tv_nsec: 206396894 }, values: [0.0, 0.0, 0.0, 0.0] })
2024-08-25 16:52:38.859767 DEBUG [src/bin.rs:386] SetSpeed message received
^C2024-08-25 16:52:39.681302 DEBUG [src/bin.rs:835] Received signal: 2
2024-08-25 16:52:39.681541 INFO [src/bin.rs:868] Shutting down
2024-08-25 16:52:39.681605 DEBUG [src/bin.rs:244] Exit requested...
2024-08-25 16:52:39.690723 DEBUG [src/alsadevice.rs:688] Exit message received, sending EndOfStream
2024-08-25 16:52:39.698515 DEBUG [src/bin.rs:1038] Processing ended with status Ok(Exit)
2024-08-25 16:52:39.698577 DEBUG [src/bin.rs:1048] Exiting