Random crashes caused by incorrect goroutine stack size detection

[digitalentity]

I'm encountering random crashes with my test application, which is essentially blinky on steroids. The app code is here: https://github.com/digitalentity/tinygo_gotchas/blob/master/src/ticker_crash/main.go. This is an extract from a different up to create a smaller repro environment.

Nothing really complicated, but it sometimes dies with a message fatal error: undefined instruction with sp=0x20000fd4 pc=0x00000091 or similar to the console.

The biggest problem is that they are not deterministic - sometimes the app can run for hours, sometimes is crashes within minutes which makes debugging really hard. Right now I have it running under GDB for about 1h without any sign of issue.

I never saw crashes when using time.Sleep(), it started when I started adding time.Ticker for a more accurate intervals. I can't use Sleep because I need to reasonably accurately run the closed loop controller every 2ms and this inverval needs to be measured more or less accurately.

I would appreciate any pointers.

[digitalentity]

Finally crashed. Console:

fatal error: undefined instruction with sp=0x20000fd4 pc=nil

GDB trace is not very useful (consequence of -panic=trap?):

0x08003392 in runtime.abort () at /home/ksharlaimov/dev/tinygo_gotchas/toolchain/tinygo/src/runtime/runtime_cortexm_abort.go:16
16			arm.Asm("wfi")
(gdb) bt
#0  0x08003392 in runtime.abort () at /home/ksharlaimov/dev/tinygo_gotchas/toolchain/tinygo/src/runtime/runtime_cortexm_abort.go:16
#1  HardFault_Handler () at /home/ksharlaimov/dev/tinygo_gotchas/toolchain/tinygo/src/runtime/runtime_cortexm_hardfault_debug.go:110
#2  0x20001d7c in machine._UART1.7 ()
Backtrace stopped: previous frame identical to this frame (corrupt stack?)

[eliasnaur]

Your stack trace mentions "UART1", which raises my suspicion that the UART is used simultaneously because of missing locking around inside the "println" builtin (called on https://github.com/digitalentity/tinygo_gotchas/blob/d27bb822c090c05bd367bc659d669e11a6949e1d/src/ticker_crash/main.go#L57).
Try adding your own locking around "println" and see whether that helps. If not, the culprit is likely the scheduler.

[digitalentity]

The printstat() goroutine is not started - commented out in main: https://github.com/digitalentity/tinygo_gotchas/blob/d27bb822c090c05bd367bc659d669e11a6949e1d/src/ticker_crash/main.go#L68

The stack trace likely mentions UART because of the panic handler which printed the fatal error: undefined instruction with sp=0x20000fd4 pc=nil message before calling HardFault_Handler. The original code where I encountered the problem doesn't even configure UART yet.

I've changed the build flags to -panic=print, waiting for it to crash again (already about 30 min and counting)...

[digitalentity]

I was not able to reproduce this with panicStrategy set to print, only when set to trap.

Looking at the panic.go:

func panicOrGoexit(message interface{}, panicking panicState) {
	if panicStrategy() == tinygo.PanicStrategyTrap {
		trap()
	}
	// Note: recover is not supported inside interrupts.
	// (This could be supported, like defer, but we currently don't).
	if supportsRecover() && !interrupt.In() {
		frame := (*deferFrame)(task.Current().DeferFrame)
		if frame != nil {
			frame.PanicValue = message
			frame.Panicking = panicking
			tinygo_longjmp(frame)
			// unreachable
		}
	}
	if panicking == panicGoexit {
		// Call to Goexit() instead of a panic.
		// Exit the goroutine instead of printing a panic message.
		deadlock()
	}
	printstring("panic: ")
	printitf(message)
	printnl()
	abort()
}

If the panic is not trapped, there is a silent recover if we have a DeferFrame set. I'm now wondering if I'm hitting a recoverable panic which I don't notice because the recovery is silent. I'll add a print there and see what happens.

[digitalentity]

Ha! This is not hitting a panic at all. We're just hitting HardFault_Handler somewhere and getting an illegal opcode.

Which was kinda obvious from the beginning (fatal error: undefined instruction with sp=0x20000fd4 pc=0x00000007). The question is - how the heck did we end up at pc=0x00000007 if ROM on STM32 begins at 0x8000000.

Might be UART- or interrupt-related after all...

[digitalentity]

Interesting. I disabled the UART interrupt attachment in the board_nucleof722ze.go:

func init() {
	// UART1.Interrupt = interrupt.New(stm32.IRQ_USART3, _UART1.handleInterrupt)
}

... which should have disabled the UART IRQ at the NVIC level, yet I still got the fault somewhere in the _UART1 methods, despite the fact that I am not using UART at all:

(gdb) bt
#0  0x08007042 in runtime.abort () at /home/ksharlaimov/dev/tinygo_gotchas/toolchain/tinygo/src/runtime/runtime_cortexm_abort.go:16
#1  HardFault_Handler () at /home/ksharlaimov/dev/tinygo_gotchas/toolchain/tinygo/src/runtime/runtime_cortexm_hardfault_debug.go:110
#2  0x20001da8 in machine._UART1.6 ()
Backtrace stopped: previous frame identical to this frame (corrupt stack?)

[digitalentity]

Unbelievable. Built it with -opt=0 and it keeps working for 4 hours straight without issue.

[digitalentity]

With -opt=1 crashed almost instantly:

#0  0x08007752 in runtime.abort () at /home/ksharlaimov/dev/tinygo_gotchas/toolchain/tinygo/src/runtime/runtime_cortexm_abort.go:16
#1  HardFault_Handler () at /home/ksharlaimov/dev/tinygo_gotchas/toolchain/tinygo/src/runtime/runtime_cortexm_hardfault_debug.go:110
#2  0x20001db4 in machine._UART1.7 ()

Question is, how we end up executing from RAM or even from what seems to be the nil pointer (if we can trust the HardFault stack frame decoding).

[digitalentity]

So we definitely end up jumping to an illegal address which triggers the hardfault. No idea how to debug this further because the issue seems to be very random.

[digitalentity]

I think I got it.

Let's unwind the events:

Here we call the time.NewTicker to create a new ticker:

func led2() {
	led := machine.LED_BLUE
	led.Configure(machine.PinConfig{Mode: machine.PinOutput})

	t := time.NewTicker(time.Millisecond * 20)
	s := bool(false)
	for range t.C {
		// toggle LED
	}
}

The time.NewTicker calls the newTimer the toolchain's src/runtime/time_go123.go and registers this timer in a global timerQueue using a timerNode that points to a field inside that timeTimer struct.

//go:linkname newTimer time.newTimer
func newTimer(when, period int64, f func(arg any, seq uintptr, delta int64), arg any, c unsafe.Pointer) *timeTimer {
	tim := &timeTimer{
		c:    c,
		init: true,
		timer: timer{
			when:   when,
			period: period,
			f:      f,
			arg:    arg,
		},
	}
	scheduleLog("new timer")
	addTimer(&timerNode{
		timer:    &tim.timer,  // <-- Uses tim.timer, but not the tim. This is fine because tim escapes.
		callback: timerCallback,
	})
	return tim
}

Because tim escapes, it's allocated on the heap, which is confirmed by the -print-allocs:

...
/home/ksharlaimov/dev/tinygo_gotchas/toolchain/tinygo/src/runtime/time_go123.go:35.1,35.19 1 0
...

The problem with this is that the tim allocated by the newTimer is returned back to led2() where it is never used:

func led2() {
    // ...
    t := time.NewTicker(time.Millisecond * 20)
    s := bool(false)
    for range t.C { // <--- Only t.C is used here, not the t itself!
        // ... toggle LED ...
    }
}

Hwre I use t.C (the channel), but I never reference t (the Ticker) again, so LLMVs escape analysis decides t is "dead" as soon as the loop starts.

The GC eventually runs, sees no pointers to t on the stack, and collects the timeTimer struct.

But the timerQueue still has a timerNode pointing to the now-freed memory where the timer's callback function was stored.

The next time the timer fires, the scheduler jumps to a corrupted or nil function pointer, leading to PC=0x00000001 and a HardFault.

Why it didn't crash with time.Sleep?

The time.Sleep does not return a handle that the user must manage. It directly suspends the current goroutine (Task) and puts it in a sleepQueue. Since the Task struct is the goroutine itself, it cannot be collected while it's running/sleeping.

Why -opt=0 "fixed" it

With optimizations disabled, the compiler is much less aggressive and probably keeps all local variables alive until the function returns, effectively preventing the GC from collecting the Ticker.

The fix:

Add defer t.Stop() to the led2():

func led2() {
	led := machine.LED_BLUE
	led.Configure(machine.PinConfig{Mode: machine.PinOutput})

	t := time.NewTicker(time.Millisecond * 20)
	defer t.Stop() // This keeps 't' alive until led2 returns!

	s := bool(false)
	for range t.C {
        // ... toggle LED ...
	}
}

This is good practice anyway to avoid leaking timers, and apparently this is absolutely mandatory in TinyGo to avoid premature collection of the Ticker.

[digitalentity]

@eliasnaur I think it makes sense to add this gotcha to the https://github.com/tinygo-org/tinygo/wiki/Tips-for-developing-with-TinyGo, WDYT?

[eliasnaur]

I don't it's worth documenting, because not calling Ticker.Stop should never cause weird memory corruption faults. Besides, go doc time.NewTicker says:

The Stop method is no longer necessary to help the garbage collector.

This chain of events seem suspect:

The GC eventually runs, sees no pointers to t on the stack, and collects the timeTimer struct.

But the timerQueue still has a timerNode pointing to the now-freed memory where the timer's callback function was stored.

This doesn't explain how t can be freed when timerQueue contains a reference to it.

[digitalentity]

The timerQueue doesn't containt the reference to t or tim (as it is called in the newTimer. The newTimer references the tim.timer (a child object), the parent tim is returned back to the original caller and is never referenced.

	addTimer(&timerNode{
		timer:    &tim.timer,
		callback: timerCallback,
	})

I am not 100% convinced that I found the true root cause, but the test app is running for an hour now without issue - previously it was more or less reliably crashing after 3-5 minutes.

[digitalentity]

The TinyGo's conservative GC (gc_stack_raw.go + gc_blocks.go) does not scan the scheduler's timerQueue or sleepQueue:

In the runGC() in src/runtime/gc_blocks.go:

func runGC() (freeBytes uintptr) {
    gcMarkReachable() // Scans stacks and globals
    if baremetal && hasScheduler {
        // ... scans ONLY the runqueue ...
        runqueue := schedulerRunQueue()
        // ... (iterates and marks everything in runqueue) ...
    }
    finishMark()
    // ... sweep ...
}

It means that the pending timer allocated on heap can be easily collected by the GC, as well as the goroutine which happens to be sleeping at the wrong time.