2025-07-03 17:23:03.591725 DEBUG [src/alsadevice.rs:389] Playback: setting channels to 4
2025-07-03 17:23:03.591754 DEBUG [src/alsadevice.rs:393] Playback: supported samplerates: Discrete([44100, 48000, 88200, 96000, 176400, 192000])
2025-07-03 17:23:03.591757 DEBUG [src/alsadevice.rs:394] Playback: setting rate to 192000
2025-07-03 17:23:03.591764 DEBUG [src/alsadevice.rs:398] Playback: supported sample formats: [S32LE]
2025-07-03 17:23:03.591767 DEBUG [src/alsadevice.rs:408] Playback: setting format to S32LE
2025-07-03 17:23:03.591773 DEBUG [src/alsadevice_buffermanager.rs:57] Setting buffer size to 4096 frames
2025-07-03 17:23:03.591783 DEBUG [src/alsadevice_buffermanager.rs:70] Device is using a buffer size of 4096 frames
2025-07-03 17:23:03.591786 DEBUG [src/alsadevice_buffermanager.rs:78] Setting period size to 512 frames
2025-07-03 17:23:03.591795 DEBUG [src/alsadevice_buffermanager.rs:94] Device is using a period size of 512 frames
2025-07-03 17:23:03.632935 DEBUG [src/alsadevice.rs:432] Opening Playback device "hw:M4" with parameters: HwParams { channels: Ok(4), rate: "Ok(192000) 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)
2025-07-03 17:23:03.632956 DEBUG [src/alsadevice.rs:437] Playback device "hw:M4" successfully opened
2025-07-03 17:23:03.632972 DEBUG [src/bin.rs:272] Playback thread ready to start
2025-07-03 17:23:03.632977 DEBUG [src/bin.rs:275] Both capture and playback ready, release barrier
2025-07-03 17:23:03.632985 DEBUG [src/bin.rs:277] Supervisor loop starts now!
2025-07-03 17:23:03.632990 DEBUG [src/alsadevice.rs:1147] Starting playback loop
2025-07-03 17:23:03.632995 DEBUG [src/alsadevice.rs:464] Playback device supports pausing the stream
2025-07-03 17:23:03.632994 DEBUG [src/alsadevice.rs:1237] Starting captureloop
2025-07-03 17:23:03.632998 DEBUG [src/alsadevice.rs:467] Playback loop uses a buffer of 1024 frames
2025-07-03 17:23:03.632992 DEBUG [src/processing.rs:103] Processing loop starts now!
2025-07-03 17:23:03.633085 DEBUG [src/alsadevice.rs:500] Playback thread has real-time priority.
2025-07-03 17:23:03.633172 DEBUG [src/alsadevice_utils.rs:597] Look up element with name PCM Rate Shift 100000
2025-07-03 17:23:03.633178 DEBUG [src/alsadevice_utils.rs:600] Found element with name PCM Rate Shift 100000 and numid 57
2025-07-03 17:23:03.633181 DEBUG [src/alsadevice_utils.rs:597] Look up element with name Capture Pitch 1000000
2025-07-03 17:23:03.633185 DEBUG [src/alsadevice_utils.rs:597] Look up element with name PCM Slave Active
2025-07-03 17:23:03.633187 DEBUG [src/alsadevice_utils.rs:600] Found element with name PCM Slave Active and numid 59
2025-07-03 17:23:03.633190 DEBUG [src/alsadevice_utils.rs:597] Look up element with name Capture Rate
2025-07-03 17:23:03.633193 INFO [src/alsadevice.rs:798] Capture device supports rate adjust
2025-07-03 17:23:03.633196 DEBUG [src/alsadevice.rs:807] Capture loop uses a buffer of 1024 frames
2025-07-03 17:23:03.633201 DEBUG [src/alsadevice.rs:840] Capture thread has real-time priority.
2025-07-03 17:23:03.633210 DEBUG [src/alsadevice.rs:254] Starting capture from state: SND_PCM_STATE_PREPARED, Ready to start
2025-07-03 17:23:03.638129 INFO [src/alsadevice.rs:117] PB: Starting playback from Prepared state
2025-07-03 17:23:03.654214 DEBUG [src/countertimer.rs:271] Number of values changed. New 4, prev 2. Clearing history.
2025-07-03 17:23:03.654223 DEBUG [src/countertimer.rs:271] Number of values changed. New 4, prev 2. Clearing history.
2025-07-03 17:23:04.789892 DEBUG [src/countertimer.rs:73] Pausing processing
2025-07-03 17:23:04.789934 DEBUG [src/alsadevice.rs:653] Pausing playback device
2025-07-03 17:23:18.035714 DEBUG [src/alsadevice_utils.rs:406] Event from numid 59
2025-07-03 17:23:18.035754 DEBUG [src/alsadevice_utils.rs:466] Loopback active: Some(true)
2025-07-03 17:23:18.081896 DEBUG [src/countertimer.rs:68] Resuming processing
2025-07-03 17:23:18.082167 DEBUG [src/alsadevice.rs:122] PB: Device is in paused state, unpausing.
2025-07-03 17:23:18.082216 DEBUG [src/helpers.rs:162] Rate controller, ramp step 1/20, current target 2555.203396582944
2025-07-03 17:23:18.082222 DEBUG [src/alsadevice.rs:629] Send SetSpeed message for speed 1.0000147117563485
2025-07-03 17:23:18.082291 DEBUG [src/alsadevice.rs:638] PB: buffer level: 2437.5, signal rms: Some(HistoryRecord { time: Instant { tv_sec: 441, tv_nsec: 696353719 }, values: [0.12668188, 0.13480762, 0.12668188, 0.13480762] })
2025-07-03 17:23:18.082299 DEBUG [src/bin.rs:393] SetSpeed message received
2025-07-03 17:23:18.089995 DEBUG [src/alsadevice.rs:866] Setting capture loopback speed to 1.0000147117563485
2025-07-03 17:23:18.090023 DEBUG [src/alsadevice_utils.rs:406] Event from numid 57
2025-07-03 17:23:28.090152 DEBUG [src/helpers.rs:162] Rate controller, ramp step 2/20, current target 2655.710681775701
2025-07-03 17:23:28.090187 DEBUG [src/alsadevice.rs:629] Send SetSpeed message for speed 1.0000833980041017
2025-07-03 17:23:28.090197 DEBUG [src/alsadevice.rs:638] PB: buffer level: 2008.1, signal rms: Some(HistoryRecord { time: Instant { tv_sec: 451, tv_nsec: 704288042 }, values: [0.0030225574, 0.0032948188, 0.0030225574, 0.0032948188] })
2025-07-03 17:23:28.090308 DEBUG [src/bin.rs:393] SetSpeed message received
2025-07-03 17:23:28.097994 DEBUG [src/alsadevice.rs:866] Setting capture loopback speed to 1.0000833980041017
2025-07-03 17:23:28.098157 DEBUG [src/alsadevice_utils.rs:406] Event from numid 57
2025-07-03 17:23:38.090211 DEBUG [src/helpers.rs:162] Rate controller, ramp step 3/20, current target 2740.7919129380844
2025-07-03 17:23:38.090244 DEBUG [src/alsadevice.rs:629] Send SetSpeed message for speed 1.000079700622627
2025-07-03 17:23:38.090252 DEBUG [src/alsadevice.rs:638] PB: buffer level: 2230.7, signal rms: Some(HistoryRecord { time: Instant { tv_sec: 461, tv_nsec: 704346536 }, values: [0.00073938083, 0.0008281712, 0.00073938083, 0.0008281712] })
2025-07-03 17:23:38.090267 DEBUG [src/bin.rs:393] SetSpeed message received
2025-07-03 17:23:38.097985 DEBUG [src/alsadevice.rs:866] Setting capture loopback speed to 1.000079700622627
2025-07-03 17:23:38.098020 DEBUG [src/alsadevice_utils.rs:406] Event from numid 57
2025-07-03 17:23:42.978051 DEBUG [src/countertimer.rs:73] Pausing processing
2025-07-03 17:23:42.978189 DEBUG [src/alsadevice.rs:653] Pausing playback device
2025-07-03 17:23:44.713894 DEBUG [src/countertimer.rs:68] Resuming processing
2025-07-03 17:23:44.714147 DEBUG [src/alsadevice.rs:122] PB: Device is in paused state, unpausing.
2025-07-03 17:23:48.090899 DEBUG [src/helpers.rs:162] Rate controller, ramp step 4/20, current target 2812.1126280373833
2025-07-03 17:23:48.090935 DEBUG [src/alsadevice.rs:629] Send SetSpeed message for speed 1.0000327415471182
2025-07-03 17:23:48.090943 DEBUG [src/alsadevice.rs:638] PB: buffer level: 2762.7, signal rms: Some(HistoryRecord { time: Instant { tv_sec: 471, tv_nsec: 705034982 }, values: [0.0024704149, 0.0026790292, 0.0024704149, 0.0026790292] })
2025-07-03 17:23:48.090963 DEBUG [src/bin.rs:393] SetSpeed message received
2025-07-03 17:23:48.098044 DEBUG [src/alsadevice.rs:866] Setting capture loopback speed to 1.0000327415471182
2025-07-03 17:23:48.098074 DEBUG [src/alsadevice_utils.rs:406] Event from numid 57
2025-07-03 17:23:58.091472 DEBUG [src/helpers.rs:162] Rate controller, ramp step 5/20, current target 2871.243191442757
2025-07-03 17:23:58.091507 DEBUG [src/alsadevice.rs:629] Send SetSpeed message for speed 0.9999794120257893
2025-07-03 17:23:58.091515 DEBUG [src/alsadevice.rs:638] PB: buffer level: 3256.7, signal rms: Some(HistoryRecord { time: Instant { tv_sec: 481, tv_nsec: 705608277 }, values: [0.002354231, 0.0023670234, 0.002354231, 0.0023670234] })
2025-07-03 17:23:58.091527 DEBUG [src/bin.rs:393] SetSpeed message received
2025-07-03 17:23:58.098007 DEBUG [src/alsadevice.rs:866] Setting capture loopback speed to 0.9999794120257893
2025-07-03 17:23:58.098043 DEBUG [src/alsadevice_utils.rs:406] Event from numid 57
2025-07-03 17:24:08.092199 DEBUG [src/helpers.rs:162] Rate controller, ramp step 6/20, current target 2919.6587939252336
2025-07-03 17:24:08.092236 DEBUG [src/alsadevice.rs:629] Send SetSpeed message for speed 0.9999584539870324
2025-07-03 17:24:08.092244 DEBUG [src/alsadevice.rs:638] PB: buffer level: 3408.6, signal rms: Some(HistoryRecord { time: Instant { tv_sec: 491, tv_nsec: 706335767 }, values: [0.0032086964, 0.0026694443, 0.0032086964, 0.0026694443] })
2025-07-03 17:24:08.092258 DEBUG [src/bin.rs:393] SetSpeed message received
2025-07-03 17:24:08.093998 DEBUG [src/alsadevice.rs:866] Setting capture loopback speed to 0.9999584539870324
2025-07-03 17:24:08.094029 DEBUG [src/alsadevice_utils.rs:406] Event from numid 57
2025-07-03 17:24:18.093015 DEBUG [src/helpers.rs:162] Rate controller, ramp step 7/20, current target 2958.73945265771
2025-07-03 17:24:18.093052 DEBUG [src/alsadevice.rs:629] Send SetSpeed message for speed 0.9999372505053585
2025-07-03 17:24:18.093060 DEBUG [src/alsadevice.rs:638] PB: buffer level: 3535.8, signal rms: Some(HistoryRecord { time: Instant { tv_sec: 501, tv_nsec: 707150776 }, values: [0.0018250339, 0.0014847502, 0.0018250339, 0.0014847502] })
2025-07-03 17:24:18.093074 DEBUG [src/bin.rs:393] SetSpeed message received
2025-07-03 17:24:18.094000 DEBUG [src/alsadevice.rs:866] Setting capture loopback speed to 0.9999372505053585
2025-07-03 17:24:18.094032 DEBUG [src/alsadevice_utils.rs:406] Event from numid 57
2025-07-03 17:24:28.093834 DEBUG [src/helpers.rs:162] Rate controller, ramp step 8/20, current target 2989.7700112149532
2025-07-03 17:24:28.093879 DEBUG [src/alsadevice.rs:629] Send SetSpeed message for speed 0.999920604830442
2025-07-03 17:24:28.093887 DEBUG [src/alsadevice.rs:638] PB: buffer level: 3603.8, signal rms: Some(HistoryRecord { time: Instant { tv_sec: 511, tv_nsec: 707969749 }, values: [0.0025557321, 0.0031326166, 0.0025557321, 0.0031326166] })
2025-07-03 17:24:28.093902 DEBUG [src/bin.rs:393] SetSpeed message received
2025-07-03 17:24:28.097985 DEBUG [src/alsadevice.rs:866] Setting capture loopback speed to 0.999920604830442
2025-07-03 17:24:28.098024 DEBUG [src/alsadevice_utils.rs:406] Event from numid 57
2025-07-03 17:24:38.094591 DEBUG [src/helpers.rs:162] Rate controller, ramp step 9/20, current target 3013.940139573598
2025-07-03 17:24:38.094626 DEBUG [src/alsadevice.rs:629] Send SetSpeed message for speed 0.9999124194939426
2025-07-03 17:24:38.094635 DEBUG [src/alsadevice.rs:638] PB: buffer level: 3591.1, signal rms: Some(HistoryRecord { time: Instant { tv_sec: 521, tv_nsec: 708726900 }, values: [0.003583157, 0.0034784533, 0.003583157, 0.0034784533] })
2025-07-03 17:24:38.094645 DEBUG [src/bin.rs:393] SetSpeed message received
2025-07-03 17:24:38.098021 DEBUG [src/alsadevice.rs:866] Setting capture loopback speed to 0.9999124194939426
2025-07-03 17:24:38.098059 DEBUG [src/alsadevice_utils.rs:406] Event from numid 57
2025-07-03 17:24:48.095357 DEBUG [src/helpers.rs:162] Rate controller, ramp step 10/20, current target 3032.3443341121497
2025-07-03 17:24:48.095391 DEBUG [src/alsadevice.rs:629] Send SetSpeed message for speed 0.9999099292045011
2025-07-03 17:24:48.095399 DEBUG [src/alsadevice.rs:638] PB: buffer level: 3533.3, signal rms: Some(HistoryRecord { time: Instant { tv_sec: 531, tv_nsec: 709492982 }, values: [0.0023939388, 0.0031491308, 0.0023939388, 0.0031491308] })
2025-07-03 17:24:48.095409 DEBUG [src/bin.rs:393] SetSpeed message received
2025-07-03 17:24:48.101985 DEBUG [src/alsadevice.rs:866] Setting capture loopback speed to 0.9999099292045011
2025-07-03 17:24:48.102014 DEBUG [src/alsadevice_utils.rs:406] Event from numid 57
2025-07-03 17:24:58.096111 DEBUG [src/helpers.rs:162] Rate controller, ramp step 11/20, current target 3045.9819176109813
2025-07-03 17:24:58.096146 DEBUG [src/alsadevice.rs:629] Send SetSpeed message for speed 0.9999058957427325
2025-07-03 17:24:58.096155 DEBUG [src/alsadevice.rs:638] PB: buffer level: 3495.7, signal rms: Some(HistoryRecord { time: Instant { tv_sec: 541, tv_nsec: 710246680 }, values: [0.0036377604, 0.0046143467, 0.0036377604, 0.0046143467] })
2025-07-03 17:24:58.096175 DEBUG [src/bin.rs:393] SetSpeed message received
2025-07-03 17:24:58.097989 DEBUG [src/alsadevice.rs:866] Setting capture loopback speed to 0.9999058957427325
2025-07-03 17:25:08.096857 DEBUG [src/helpers.rs:162] Rate controller, ramp step 12/20, current target 3055.7570392523367
2025-07-03 17:25:08.096894 DEBUG [src/alsadevice.rs:629] Send SetSpeed message for speed 0.9999023032895545
2025-07-03 17:25:08.096903 DEBUG [src/alsadevice.rs:638] PB: buffer level: 3459.2, signal rms: Some(HistoryRecord { time: Instant { tv_sec: 551, tv_nsec: 710992864 }, values: [0.0030512975, 0.0030611977, 0.0030512975, 0.0030611977] })
2025-07-03 17:25:08.096924 DEBUG [src/bin.rs:393] SetSpeed message received
2025-07-03 17:25:08.102008 DEBUG [src/alsadevice.rs:866] Setting capture loopback speed to 0.9999023032895545
2025-07-03 17:25:18.097590 DEBUG [src/helpers.rs:162] Rate controller, ramp step 13/20, current target 3062.478674620327
2025-07-03 17:25:18.097625 DEBUG [src/alsadevice.rs:629] Send SetSpeed message for speed 0.9998968384989599
2025-07-03 17:25:18.097633 DEBUG [src/alsadevice.rs:638] PB: buffer level: 3442.4, signal rms: Some(HistoryRecord { time: Instant { tv_sec: 561, tv_nsec: 711725493 }, values: [0.0016091937, 0.0016941882, 0.0016091937, 0.0016941882] })
2025-07-03 17:25:18.097643 DEBUG [src/bin.rs:393] SetSpeed message received
2025-07-03 17:25:18.105986 DEBUG [src/alsadevice.rs:866] Setting capture loopback speed to 0.9998968384989599
2025-07-03 17:25:18.106020 DEBUG [src/alsadevice_utils.rs:406] Event from numid 57
2025-07-03 17:25:28.098313 DEBUG [src/helpers.rs:162] Rate controller, ramp step 14/20, current target 3066.8606257009346
2025-07-03 17:25:28.098352 DEBUG [src/alsadevice.rs:629] Send SetSpeed message for speed 0.9998967040930107
2025-07-03 17:25:28.098361 DEBUG [src/alsadevice.rs:638] PB: buffer level: 3384.6, signal rms: Some(HistoryRecord { time: Instant { tv_sec: 571, tv_nsec: 712448720 }, values: [0.0029364263, 0.003129836, 0.0029364263, 0.003129836] })
2025-07-03 17:25:28.098373 DEBUG [src/bin.rs:393] SetSpeed message received
2025-07-03 17:25:28.105995 DEBUG [src/alsadevice.rs:866] Setting capture loopback speed to 0.9998967040930107
2025-07-03 17:25:38.099030 DEBUG [src/helpers.rs:162] Rate controller, ramp step 15/20, current target 3069.521520882009
2025-07-03 17:25:38.099066 DEBUG [src/alsadevice.rs:629] Send SetSpeed message for speed 0.9998949260346104
2025-07-03 17:25:38.099075 DEBUG [src/alsadevice.rs:638] PB: buffer level: 3348.5, signal rms: Some(HistoryRecord { time: Instant { tv_sec: 581, tv_nsec: 713165914 }, values: [0.001429604, 0.0016194506, 0.001429604, 0.0016194506] })
2025-07-03 17:25:38.099094 DEBUG [src/bin.rs:393] SetSpeed message received
2025-07-03 17:25:38.106145 DEBUG [src/alsadevice.rs:866] Setting capture loopback speed to 0.9998949260346104
2025-07-03 17:25:48.099732 DEBUG [src/helpers.rs:162] Rate controller, ramp step 16/20, current target 3070.984814953271
2025-07-03 17:25:48.099769 DEBUG [src/alsadevice.rs:629] Send SetSpeed message for speed 0.9998958871336099
2025-07-03 17:25:48.099778 DEBUG [src/alsadevice.rs:638] PB: buffer level: 3295.8, signal rms: Some(HistoryRecord { time: Instant { tv_sec: 591, tv_nsec: 713868442 }, values: [0.0017313857, 0.0020574299, 0.0017313857, 0.0020574299] })
2025-07-03 17:25:48.099797 DEBUG [src/bin.rs:393] SetSpeed message received
2025-07-03 17:25:48.102004 DEBUG [src/alsadevice.rs:866] Setting capture loopback speed to 0.9998958871336099
2025-07-03 17:25:58.102087 DEBUG [src/helpers.rs:162] Rate controller, ramp step 17/20, current target 3071.6787891063086
2025-07-03 17:25:58.102124 DEBUG [src/alsadevice.rs:629] Send SetSpeed message for speed 0.9998962697195795
2025-07-03 17:25:58.102132 DEBUG [src/alsadevice.rs:638] PB: buffer level: 3255.9, signal rms: Some(HistoryRecord { time: Instant { tv_sec: 601, tv_nsec: 716222779 }, values: [0.0036298132, 0.004141044, 0.0036298132, 0.004141044] })
2025-07-03 17:25:58.102146 DEBUG [src/bin.rs:393] SetSpeed message received
2025-07-03 17:25:58.109948 DEBUG [src/alsadevice.rs:866] Setting capture loopback speed to 0.9998962697195795
2025-07-03 17:26:08.106130 DEBUG [src/helpers.rs:162] Rate controller, ramp step 18/20, current target 3071.9365509345794
2025-07-03 17:26:08.106165 DEBUG [src/alsadevice.rs:629] Send SetSpeed message for speed 0.9998974260861636
2025-07-03 17:26:08.106174 DEBUG [src/alsadevice.rs:638] PB: buffer level: 3216.2, signal rms: Some(HistoryRecord { time: Instant { tv_sec: 611, tv_nsec: 720266597 }, values: [0.0030654566, 0.0030592312, 0.0030654566, 0.0030592312] })
2025-07-03 17:26:08.106317 DEBUG [src/bin.rs:393] SetSpeed message received
2025-07-03 17:26:08.117986 DEBUG [src/alsadevice.rs:866] Setting capture loopback speed to 0.9998974260861636
2025-07-03 17:26:18.110159 DEBUG [src/helpers.rs:162] Rate controller, ramp step 19/20, current target 3071.9960344334113
2025-07-03 17:26:18.110193 DEBUG [src/alsadevice.rs:629] Send SetSpeed message for speed 0.9998994297086118
2025-07-03 17:26:18.110201 DEBUG [src/alsadevice.rs:638] PB: buffer level: 3176.2, signal rms: Some(HistoryRecord { time: Instant { tv_sec: 621, tv_nsec: 724294991 }, values: [0.0022646438, 0.002895398, 0.0022646438, 0.002895398] })
2025-07-03 17:26:18.110210 DEBUG [src/bin.rs:393] SetSpeed message received
2025-07-03 17:26:18.117983 DEBUG [src/alsadevice.rs:866] Setting capture loopback speed to 0.9998994297086118
2025-07-03 17:26:28.114080 DEBUG [src/helpers.rs:162] Rate controller, ramp step 20/20, current target 3072
2025-07-03 17:26:28.114112 DEBUG [src/alsadevice.rs:629] Send SetSpeed message for speed 0.9999111909836912
2025-07-03 17:26:28.114120 DEBUG [src/alsadevice.rs:638] PB: buffer level: 3064.8, signal rms: Some(HistoryRecord { time: Instant { tv_sec: 631, tv_nsec: 728215231 }, values: [0.0022902503, 0.003336593, 0.0022902503, 0.003336593] })
2025-07-03 17:26:28.114129 DEBUG [src/bin.rs:393] SetSpeed message received
2025-07-03 17:26:28.122006 DEBUG [src/alsadevice.rs:866] Setting capture loopback speed to 0.9999111909836912
2025-07-03 17:26:28.122040 DEBUG [src/alsadevice_utils.rs:406] Event from numid 57
2025-07-03 17:26:38.119154 DEBUG [src/alsadevice.rs:629] Send SetSpeed message for speed 0.9999240343116941
2025-07-03 17:26:38.119194 DEBUG [src/alsadevice.rs:638] PB: buffer level: 2963.2, signal rms: Some(HistoryRecord { time: Instant { tv_sec: 641, tv_nsec: 733289923 }, values: [0.002647602, 0.0028143928, 0.002647602, 0.0028143928] })
2025-07-03 17:26:38.119235 DEBUG [src/bin.rs:393] SetSpeed message received
2025-07-03 17:26:38.125994 DEBUG [src/alsadevice.rs:866] Setting capture loopback speed to 0.9999240343116941
2025-07-03 17:26:38.126027 DEBUG [src/alsadevice_utils.rs:406] Event from numid 57