ASIO backend panics with "attempt to add with overflow" in TimeBase::to_stream_instant after a few minutes (debug builds), small buffer size

[ZackPedretti]

Summary

Using the ASIO host with a small fixed buffer size (16 frames), the ASIO
input/output stream panics after a few minutes of continuous playback with
attempt to add with overflow inside TimeBase::to_stream_instant
(src/host/asio/stream.rs:44). Only reproduces in debug builds (overflow
checks enabled); release builds presumably wrap silently instead.

Environment

• cpal: 0.18.2
• OS: Windows 11 Professional (10.0.26200 Build 26200)
• Interface: Focusrite USB ASIO (Focusrite Scarlett 2i2 3rd Gen)
• Rust toolchain: (rustc 1.98.1 (48a229cea 2026-09-01))
• Profile: debug (cargo run)

Minimal repro, using a Focusrite interface over ASIO with a 16-frame fixed
buffer, 44.1kHz, 2ch, i32, simply copying input channel 0 to both output
channels via a ring buffer:

use std::time::Duration;
use anyhow::anyhow;
use cpal::{BufferSize, StreamConfig};
use cpal::traits::{DeviceTrait, HostTrait, StreamTrait};
use ringbuf::consumer::Consumer;
use ringbuf::HeapRb;
use ringbuf::producer::Producer;
use ringbuf::traits::Split;

fn main() -> anyhow::Result<()> {
    let host = cpal::host_from_id(cpal::HostId::Asio)?;
    let devices = host.devices()?;

    let focusrite = devices
        .filter_map(|device| {
            let description = device.description().ok()?;

            if description.to_string().contains("Focusrite USB ASIO") {
                Some(device)
            } else {
                None
            }
        })
        .next()
        .ok_or_else(|| anyhow!("Focusrite USB ASIO not found"))?;

    println!("Using device: {}", focusrite.description()?);

    let config = StreamConfig {
        channels: 2,
        sample_rate: 44_100,
        buffer_size: BufferSize::Fixed(16),
    };

    println!("Config: {config:?}");

    let ring = HeapRb::<i32>::new(16_384);

    let (mut producer, mut consumer) = ring.split();

    let input_stream = focusrite.build_input_stream(
        config,
        move |data: &[i32], _info| {
            for frame in data.chunks(2) {
                let input_1 = frame[0];
                let _ = producer.try_push(input_1);
            }
        },
        move |err| {
            eprintln!("INPUT ERROR: {err}");
        },
        None,
    )?;

    let output_stream = focusrite.build_output_stream(
        config,
        move |data: &mut [i32], _info| {
            for frame in data.chunks_mut(2) {
                let sample = consumer.try_pop().unwrap_or(0);

                frame[0] = sample;
                frame[1] = sample;
            }
        },
        move |err| {
            eprintln!("OUTPUT ERROR: {err}");
        },
        None,
    )?;

    input_stream.play()?;
    output_stream.play()?;

    println!("Running...");
    println!("Focusrite Input 1 -> Output 1");
    println!("Press Ctrl+C to stop.");

    loop {
        std::thread::sleep(Duration::from_secs(1));
    }
    Ok(())
}

Cargo.toml:

[dependencies]
anyhow = "1.0.104"
cpal = { version = "0.18.2", features = ["asio"] }
ringbuf = "0.5.2"

Observed

After a few minutes of continuous audio, the input callback thread panics:

thread '<unnamed>' (8468) panicked at C:\Users\Zack\.cargo\registry\src\index.crates.io-1949cf8c6b5b557f\cpal-0.18.2\src\host\asio\stream.rs:44:13:
attempt to add with overflow
error: process didn't exit successfully: target\debug\guitar_host.exe (exit code: 0xc0000409, STATUS_STACK_BUFFER_OVERRUN)

Full stacktrace:

thread '<unnamed>' (3184) panicked at C:\Users\Zack\.cargo\registry\src\index.crates.io-1949cf8c6b5b557f\cpal-0.18.2\src\host\asio\stream.rs:44:13:
attempt to add with overflow
stack backtrace:
   0:     0x7ff60f33f689 - std::backtrace_rs::backtrace::win64::trace
                               at /rustc/48a229ceaefd4985c50990b14116b6d856af0985/library\std\src\..\..\backtrace\src\backtrace\win64.rs:85
   1:     0x7ff60f33f689 - std::backtrace_rs::backtrace::trace_unsynchronized
                               at /rustc/48a229ceaefd4985c50990b14116b6d856af0985/library\std\src\..\..\backtrace\src\backtrace\mod.rs:66
   2:     0x7ff60f33f689 - std::sys::backtrace::_print_fmt
                               at /rustc/48a229ceaefd4985c50990b14116b6d856af0985/library\std\src\sys\backtrace.rs:74
   3:     0x7ff60f33f689 - std::sys::backtrace::impl$0::print::impl$0::fmt
                               at /rustc/48a229ceaefd4985c50990b14116b6d856af0985/library\std\src\sys\backtrace.rs:44
   4:     0x7ff60f34dca1 - core::fmt::write
                               at /rustc/48a229ceaefd4985c50990b14116b6d856af0985/library\core\src\fmt\mod.rs:0
   5:     0x7ff60f342f24 - std::io::default_write_fmt
                               at /rustc/48a229ceaefd4985c50990b14116b6d856af0985/library\std\src\io\mod.rs:626
   6:     0x7ff60f342f24 - std::io::Write::write_fmt<std::sys::stdio::windows::Stderr>
                               at /rustc/48a229ceaefd4985c50990b14116b6d856af0985/library\std\src\io\mod.rs:1730
   7:     0x7ff60f337d85 - std::sys::backtrace::BacktraceLock::print
                               at /rustc/48a229ceaefd4985c50990b14116b6d856af0985/library\std\src\sys\backtrace.rs:47
   8:     0x7ff60f337d85 - std::panicking::default_hook::closure$0
                               at /rustc/48a229ceaefd4985c50990b14116b6d856af0985/library\std\src\panicking.rs:292
   9:     0x7ff60f33b5aa - std::panicking::default_hook
                               at /rustc/48a229ceaefd4985c50990b14116b6d856af0985/library\std\src\panicking.rs:319
  10:     0x7ff60f33b7b3 - std::panicking::panic_with_hook
                               at /rustc/48a229ceaefd4985c50990b14116b6d856af0985/library\std\src\panicking.rs:815
  11:     0x7ff60f337e94 - std::panicking::panic_handler::closure$0
                               at /rustc/48a229ceaefd4985c50990b14116b6d856af0985/library\std\src\panicking.rs:681
  12:     0x7ff60f336b9f - std::sys::backtrace::__rust_end_short_backtrace<std::panicking::panic_handler::closure_env$0,never$>
                               at /rustc/48a229ceaefd4985c50990b14116b6d856af0985/library\std\src\sys\backtrace.rs:182
  13:     0x7ff60f3384ee - std::panicking::panic_handler
                               at /rustc/48a229ceaefd4985c50990b14116b6d856af0985/library\std\src\panicking.rs:679
  14:     0x7ff60f358d6d - core::panicking::panic_fmt
                               at /rustc/48a229ceaefd4985c50990b14116b6d856af0985/library\core\src\panicking.rs:80
  15:     0x7ff60f358e9e - core::panicking::panic_const::panic_const_add_overflow
                               at /rustc/48a229ceaefd4985c50990b14116b6d856af0985/library\core\src\panicking.rs:175
  16:     0x7ff60f2d1004 - cpal::host::asio::stream::TimeBase::to_stream_instant
                               at C:\Users\Zack\.cargo\registry\src\index.crates.io-1949cf8c6b5b557f\cpal-0.18.2\src\host\asio\stream.rs:44
  17:     0x7ff60f2b8d23 - cpal::host::asio::stream::impl$3::build_input_stream_raw::closure$4<cpal::traits::DeviceTrait::build_input_stream::closure_env$0<cpal::platform::platform_impl::Device,i32,guitar_host::main::closure_env$2,guitar_host::main::closure_env$3>,guitar_host::main:
                               at C:\Users\Zack\.cargo\registry\src\index.crates.io-1949cf8c6b5b557f\cpal-0.18.2\src\host\asio\stream.rs:253
  18:     0x7ff60f3232c3 - alloc::boxed::impl$32::call_mut<tuple$<ref$<asio_sys::bindings::CallbackInfo> >,dyn$<core::ops::function::FnMut<tuple$<ref$<asio_sys::bindings::CallbackInfo> >,assoc$<Output,tuple$<> > >,core::marker::Send>,alloc::alloc::Global>
                               at C:\Users\Zack\.rustup\toolchains\stable-x86_64-pc-windows-msvc\lib\rustlib\src\rust\library\alloc\src\boxed.rs:2326
  19:     0x7ff60f3286d8 - asio_sys::bindings::BufferCallback::run
                               at C:\Users\Zack\.cargo\registry\src\index.crates.io-1949cf8c6b5b557f\asio-sys-0.4.0\src\bindings\mod.rs:503
  20:     0x7ff60f329c01 - asio_sys::bindings::buffer_switch_time_info
                               at C:\Users\Zack\.cargo\registry\src\index.crates.io-1949cf8c6b5b557f\asio-sys-0.4.0\src\bindings\mod.rs:1240
  21:      0x22cadb25056 - DllUnregisterServer
  22:      0x22cadb24812 - DllUnregisterServer
  23:      0x22cadb239ec - DllUnregisterServer
  24:      0x22cadb240ce - DllUnregisterServer
  25:      0x22cadb226c6 - DllGetClassObject
  26:     0x7fff60f1cd30 - wcsrchr
  27:     0x7fff6237cd87 - BaseThreadInitThunk
  28:     0x7fff6376caec - RtlUserThreadStart
error: process didn't exit successfully: `target\debug\guitar_host.exe` (exit code: 0xc0000409, STATUS_STACK_BUFFER_OVERRUN)

Expected

No panic; timestamps should remain correct (or at least not overflow) for
long-running streams, so it does not panic in dev mode (since release mode seems and sounds like it works just fine).

[LastExceed]

I am unfortunately unable to reproduce this. I ran your code for half an hour with no issues. But looking at the source:

cpal/src/host/asio/stream.rs

Lines 38 to 51 in d2f2f25

	/// Convert a nanosecond timestamp to a monotonic `StreamInstant`.
	fn to_stream_instant(&self, ns: u64) -> StreamInstant {
	// `Relaxed` is sufficient: callbacks run on a single ASIO thread. The only
	// cross-thread caller is `now()`, which may race at wrap time (~1µs every 49.7 days).
	let prev = self.last_ns.swap(ns, Ordering::Relaxed);
	let epoch = if ns < prev {
	self.epoch_ns
	.fetch_add(TIMEGETIME_WRAP_NS, Ordering::Relaxed)
	+ TIMEGETIME_WRAP_NS
	} else {
	self.epoch_ns.load(Ordering::Relaxed)
	};
	StreamInstant::from_nanos(epoch + ns)
	}

the panic happening on line 44 is peculiar, because that branch is supposed to only ever be reached once every 49.7 days when the system time overflows, yet you seem to be able to reproduce this panic on demand (right?).

The only part of your code that I changed was the device description string, since I dont have a focusrite interface. Perhaps it is a driver bug? ASIO does have a strange way of handling 64bit values, as it predates widespread adoption of 64bit architecture. Could you put a print in that function and verify that the timestamps advance normally? (i.e. incrementing by 1_000_000_000 per second)

[LastExceed]

From the ASIO 2.3 spec:

ASIOSamples ASIOTimeStamp

Number of samples - data type is 64-bit integer
Timestamp data type is 64-bit integer. The Time format is Nanoseconds.
Note:
The 64-bit data is passed via a structure with two 32-bit values.

struct {
    unsigned long hi; // most significant bits (Bits 32..63)
    unsigned long lo; // least significant bits (Bits 0..31)
};

Unfortunately, the ASIO API was implemented it before compiler supported consistently 64-bit
integer types. By using the structure, the data layout on a little-endian system like the Intel x86
architecture will result in a "non-native" storage of the 64-bit data. The most significant 32-bit are
stored first in memory; the least significant bits are stored in the higher memory space. However,
each 32-bit is stored in the native little-endian fashion.

Amusingly, the ASIO SDK implements this like so:

#if NATIVE_INT64
	typedef long long int ASIOSamples;
#else
	typedef struct ASIOSamples {
		unsigned long hi;
		unsigned long lo;
	} ASIOSamples;
#endif

But then goes ahead with

#if defined(_WIN32) || defined(_WIN64)
	...
	#define NATIVE_INT64 0
#elif ...

So the native representation (which differs both in sign and memory layout) is never actually used. But on first glance, this will easily trick a reader into thinking that using a native 64bit integer is fine, and if Focusrite fell for that in their driver implementation, then that would explain why you're reaching the system time overflow branch regularly.

Although, with some quick napkin math, it should still take a little over 5 hours for the u64 to overflow (which is what causes the panic), but I'm not super confident in my math. Maybe it has to do with the fact that the timestamp doesn't necessarily start at 0...

[ZackPedretti]

Thank you for your responses.

Here is the printed data of the timestamps for the 100 first calls to the callback:

[1] ts=StreamInstant { secs: 305622, nanos: 988717000 }
[2] ts=StreamInstant { secs: 305622, nanos: 989079800 }
[3] ts=StreamInstant { secs: 305622, nanos: 989716600 }
[4] ts=StreamInstant { secs: 305622, nanos: 990079400 }
[5] ts=StreamInstant { secs: 305622, nanos: 990442200 }
[6] ts=StreamInstant { secs: 305622, nanos: 990716700 }
[7] ts=StreamInstant { secs: 305622, nanos: 991079500 }
[8] ts=StreamInstant { secs: 305622, nanos: 991442300 }
[9] ts=StreamInstant { secs: 305622, nanos: 991765300 }
[10] ts=StreamInstant { secs: 305622, nanos: 992128100 }
[11] ts=StreamInstant { secs: 305622, nanos: 992490900 }
[12] ts=StreamInstant { secs: 305622, nanos: 992765500 }
[13] ts=StreamInstant { secs: 305622, nanos: 993128300 }
[14] ts=StreamInstant { secs: 305622, nanos: 993763900 }
[15] ts=StreamInstant { secs: 305622, nanos: 994126700 }
[16] ts=StreamInstant { secs: 305622, nanos: 994489500 }
[17] ts=StreamInstant { secs: 305622, nanos: 994765500 }
[18] ts=StreamInstant { secs: 305622, nanos: 995128300 }
[19] ts=StreamInstant { secs: 305622, nanos: 995491100 }
[20] ts=StreamInstant { secs: 305622, nanos: 995763400 }
[21] ts=StreamInstant { secs: 305622, nanos: 996126200 }
[22] ts=StreamInstant { secs: 305622, nanos: 996489000 }
[23] ts=StreamInstant { secs: 305622, nanos: 996764400 }
[24] ts=StreamInstant { secs: 305622, nanos: 997127200 }
[25] ts=StreamInstant { secs: 305622, nanos: 997762400 }
[26] ts=StreamInstant { secs: 305622, nanos: 998125200 }
[27] ts=StreamInstant { secs: 305622, nanos: 998488000 }
[28] ts=StreamInstant { secs: 305622, nanos: 998762500 }
[29] ts=StreamInstant { secs: 305622, nanos: 999125300 }
[30] ts=StreamInstant { secs: 305622, nanos: 999488100 }
[31] ts=StreamInstant { secs: 305623, nanos: 266800 }
[32] ts=StreamInstant { secs: 305623, nanos: 629600 }
[33] ts=StreamInstant { secs: 305623, nanos: 992400 }
[34] ts=StreamInstant { secs: 305623, nanos: 1271500 }
[35] ts=StreamInstant { secs: 305623, nanos: 1634300 }
[36] ts=StreamInstant { secs: 305623, nanos: 2271900 }
[37] ts=StreamInstant { secs: 305623, nanos: 2634700 }
[38] ts=StreamInstant { secs: 305623, nanos: 2997500 }
[39] ts=StreamInstant { secs: 305623, nanos: 3271700 }
[40] ts=StreamInstant { secs: 305623, nanos: 3634500 }
[41] ts=StreamInstant { secs: 305623, nanos: 3997300 }
[42] ts=StreamInstant { secs: 305623, nanos: 4273100 }
[43] ts=StreamInstant { secs: 305623, nanos: 4635900 }
[44] ts=StreamInstant { secs: 305623, nanos: 4998700 }
[45] ts=StreamInstant { secs: 305623, nanos: 5272400 }
[46] ts=StreamInstant { secs: 305623, nanos: 5635200 }
[47] ts=StreamInstant { secs: 305623, nanos: 6272100 }
[48] ts=StreamInstant { secs: 305623, nanos: 6634900 }
[49] ts=StreamInstant { secs: 305623, nanos: 6997700 }
[50] ts=StreamInstant { secs: 305623, nanos: 7274200 }
[51] ts=StreamInstant { secs: 305623, nanos: 7637000 }
[52] ts=StreamInstant { secs: 305623, nanos: 7999800 }
[53] ts=StreamInstant { secs: 305623, nanos: 8272300 }
[54] ts=StreamInstant { secs: 305623, nanos: 8635100 }
[55] ts=StreamInstant { secs: 305623, nanos: 8997900 }
[56] ts=StreamInstant { secs: 305623, nanos: 9271300 }
[57] ts=StreamInstant { secs: 305623, nanos: 9634100 }
[58] ts=StreamInstant { secs: 305623, nanos: 10273400 }
[59] ts=StreamInstant { secs: 305623, nanos: 10636200 }
[60] ts=StreamInstant { secs: 305623, nanos: 10999000 }
[61] ts=StreamInstant { secs: 305623, nanos: 11585600 }
[62] ts=StreamInstant { secs: 305623, nanos: 11948400 }
[63] ts=StreamInstant { secs: 305623, nanos: 12311200 }
[64] ts=StreamInstant { secs: 305623, nanos: 12585700 }
[65] ts=StreamInstant { secs: 305623, nanos: 12948500 }
[66] ts=StreamInstant { secs: 305623, nanos: 13311300 }
[67] ts=StreamInstant { secs: 305623, nanos: 13585400 }
[68] ts=StreamInstant { secs: 305623, nanos: 13948200 }
[69] ts=StreamInstant { secs: 305623, nanos: 14585400 }
[70] ts=StreamInstant { secs: 305623, nanos: 14948200 }
[71] ts=StreamInstant { secs: 305623, nanos: 15311000 }
[72] ts=StreamInstant { secs: 305623, nanos: 15587000 }
[73] ts=StreamInstant { secs: 305623, nanos: 15949800 }
[74] ts=StreamInstant { secs: 305623, nanos: 16312600 }
[75] ts=StreamInstant { secs: 305623, nanos: 16585900 }
[76] ts=StreamInstant { secs: 305623, nanos: 16948700 }
[77] ts=StreamInstant { secs: 305623, nanos: 17311500 }
[78] ts=StreamInstant { secs: 305623, nanos: 17585700 }
[79] ts=StreamInstant { secs: 305623, nanos: 17948500 }
[80] ts=StreamInstant { secs: 305623, nanos: 18585800 }
[81] ts=StreamInstant { secs: 305623, nanos: 18948600 }
[82] ts=StreamInstant { secs: 305623, nanos: 19311400 }
[83] ts=StreamInstant { secs: 305623, nanos: 19586800 }
[84] ts=StreamInstant { secs: 305623, nanos: 19949600 }
[85] ts=StreamInstant { secs: 305623, nanos: 20312400 }
[86] ts=StreamInstant { secs: 305623, nanos: 20586300 }
[87] ts=StreamInstant { secs: 305623, nanos: 20949100 }
[88] ts=StreamInstant { secs: 305623, nanos: 21311900 }
[89] ts=StreamInstant { secs: 4600590, nanos: 316586300 }
[90] ts=StreamInstant { secs: 4600590, nanos: 316949100 }
[91] ts=StreamInstant { secs: 4600590, nanos: 317855700 }
[92] ts=StreamInstant { secs: 4600590, nanos: 318218500 }
[93] ts=StreamInstant { secs: 4600590, nanos: 318581300 }
[94] ts=StreamInstant { secs: 4600590, nanos: 318855100 }
[95] ts=StreamInstant { secs: 4600590, nanos: 319217900 }
[96] ts=StreamInstant { secs: 4600590, nanos: 319580700 }
[97] ts=StreamInstant { secs: 4600590, nanos: 319856200 }
[98] ts=StreamInstant { secs: 4600590, nanos: 320219000 }
[99] ts=StreamInstant { secs: 4600590, nanos: 320581800 }
[100] ts=StreamInstant { secs: 4600590, nanos: 320856800 }

Here's the modified main.ts:

use std::time::Duration;
use anyhow::anyhow;
use cpal::{BufferSize, InputCallbackInfo, StreamConfig, StreamInstant};
use cpal::traits::{DeviceTrait, HostTrait, StreamTrait};
use ringbuf::consumer::Consumer;
use ringbuf::HeapRb;
use ringbuf::producer::Producer;
use ringbuf::traits::Split;

fn main() -> anyhow::Result<()> {
    let host = cpal::host_from_id(cpal::HostId::Asio)?;
    let devices = host.devices()?;

    let focusrite = devices
        .filter_map(|device| {
            let description = device.description().ok()?;
            if description.to_string().contains("Focusrite USB ASIO") {
                Some(device)
            } else {
                None
            }
        })
        .next()
        .ok_or_else(|| anyhow!("Focusrite USB ASIO not found"))?;

    println!("Using device: {}", focusrite.description()?);

    let config = StreamConfig {
        channels: 2,
        sample_rate: 44_100,
        buffer_size: BufferSize::Fixed(16),
    };

    println!("Config: {config:?}");

    let ring = HeapRb::<i32>::new(16_384);
    let (mut producer, mut consumer) = ring.split();

    let mut call_count: u64 = 0;
    let input_stream = focusrite.build_input_stream(
        config,
        move |data: &[i32], info: &InputCallbackInfo| {
            call_count += 1;
            let ts = info.timestamp().callback;

            if call_count <= 100 {
                println!("[{call_count}] ts={ts:?}");
            }

            for frame in data.chunks(2) {
                let input_1 = frame[0];
                let _ = producer.try_push(input_1);
            }
        },
        move |err| {
            eprintln!("INPUT ERROR: {err}");
        },
        None,
    )?;

    let output_stream = focusrite.build_output_stream(
        config,
        move |data: &mut [i32], _info| {
            for frame in data.chunks_mut(2) {
                let sample = consumer.try_pop().unwrap_or(0);
                frame[0] = sample;
                frame[1] = sample;
            }
        },
        move |err| {
            eprintln!("OUTPUT ERROR: {err}");
        },
        None,
    )?;

    input_stream.play()?;
    output_stream.play()?;

    println!("Running...");
    println!("Focusrite Input 1 -> Output 1");
    println!("Press Ctrl+C to stop.");

    loop {
        std::thread::sleep(Duration::from_secs(1));
    }
}

Some more details, I don't know if any of it could be useful:

• The interface is a Focusrite Scarlett 2i2 third gen, its "INST" function was enabled for input 1 (which is the one I was listening)
• The Windows version is slightly modified, as I patched the image with Tiny11. Maybe it could cause the bug
• The bug usually appears after around 5 minutes

[LastExceed]

There is a clear discontinuity between the 88th and 89th instant, however it doesn't fit the pattern of what I was suspecting. Still, looking at your timestamps in binary reveals an interesting pattern:

click to expand

Anyway, to test whether or not this is a driver issue, can you try running with #1331 and check if similar discontinuities appear in the timestamps? (there should be no panic since I haven't implemented monotonicity yet)

Just change your cpal dependency in Cargo.toml to cpal = { git = "https://github.com/LastExceed/cpal/", branch = "azo" }

[LastExceed]

Also, is the loopback required to reproduce the issue?

[roderickvd]

You're right, it does look like a driver bug. It's jumping from secs: 305623 to secs: 4600590 which is suspiciously close to a TIMEGETIME_WRAP_NS discontinuity (2^32 * 1_000_000 ns).

Simplest way to make the panic go away is by using wrapping_add like in release builds instead of checked_add, but it'd still return garbage timestamps.

[LastExceed]

suspiciously close to a TIMEGETIME_WRAP_NS discontinuity

oh right, I didn't even notice this. It could actually be a cpal bug then. The code comment says

callbacks run on a single ASIO thread

but isn't this entirely driver dependent? I'm not very familiar with atomic ordering so I don't know how likely this this, but an out-of-order access of last_ns would perfectly explain that discontinuity

[roderickvd]

Please try #1374 for an easy solution to the panic.