Boot loop in Artemis

[floitsch]

The attached firmware goes into a boot loop.
We found that the culprit seems to be the programs partition. After erasing it, the loop is gone.

Relevant commands:

esptool.py --port /dev/ttyUSB0 read_flash 0x0 0x400000 fw-backup-4M.bin
esptool.py --port /dev/ttyUSB0 write_flash 0x0 0x400000 fw-backup-4M.bin
esptool.py erase_region 0x360000 0x0a0000

fw-backup-4M.bin.tar.gz

[kasperl]

No smoking gun yet, but I did notice that our flash allocation validation checks are awfully weak, so the risk of us finding some garbage in the flash and treating it as a program is higher than expected. Tried to address this here: toitlang/toit#1628.

[kasperl]

It looks like a stack overflow on the Toit execution stack, where we end up writing into the guard zone:

0x40088505: panic_abort + 0x15
0x4009dbb9: abort + 0x7d
0x400fa227: toit::fail(char const*, ...) + 0x5b
0x400d288b: toit::Stack::transfer_from_interpreter(toit::Interpreter*) + 0xf
0x400e7ca7: toit::Interpreter::store_stack(toit::Object**, toit::Method) + 0x17
0x400ee623: toit::primitive_encode_error(toit::Process*, toit::Object**) + 0x53
0x40083ee1: toit::Interpreter::run() + 0x2529
0x400f90b4: toit::Scheduler::run_process(toit::Locker&, toit::Process*, toit::SchedulerThread*) + 0x68
0x400f935a: toit::Scheduler::run(toit::SchedulerThread*) + 0x6a
0x400f9389: toit::SchedulerThread::entry() + 0x9
0x400ea39a: toit::Thread::_boot() + 0x26
0x400ea3c1: toit::esp_thread_start(void*) + 0x5

Full disassembly:

kasper@mole toit % toit.run tools/stacktrace.toit --backtrace "Backtrace:0x40088505:0x3ffceca00x4009a4cd:0x3ffcecc0 0x4009dbb9:0x3ffcece0 0x400fa227:0x3ffced50 0x400d288b:0x3ffceda0 0x400e7ca7:0x3ffcedc0 0x400ee623:0x3ffcede0 0x40083ee1:0x3ffcee20 0x400f90b4:0x3ffceea0 0x400f935a:0x3ffceef0 0x400f9389:0x3ffcef20 0x400ea39a:0x3ffcef40 0x400ea3c1:0x3ffcef60" ~/Toit/toit.io/artemis/firmware.elf --disassemble

0x40088505: panic_abort + 0x15
  400884f0:	004136        	entry	a1, 32
  400884f3:	e0f381        	l32r	a8, 400808c0 <_iram_text_start+0x4bc>
  400884f6:	190c      	movi.n	a9, 1
  400884f8:	004892        	s8i	a9, a8, 0
  400884fb:	0020c0        	memw
  400884fe:	e0f181        	l32r	a8, 400808c4 <_iram_text_start+0x4c0>
  40088501:	0829      	s32i.n	a2, a8, 0
  40088503:	080c      	movi.n	a8, 0
* 40088505:	0020c0        	memw
  40088508:	0889      	s32i.n	a8, a8, 0
  4008850a:	0041f0        	break	1, 15
  4008850d:	000000        	ill
  40088510:	004136        	entry	a1, 32
  40088513:	03eb20        	rsr.prid	a2


0x4009dbb9: abort + 0x7d
...
  4009db9b:	34c132        	addi	a3, a1, 52
  4009db9e:	f129      	s32i.n	a2, a1, 60
  4009dba0:	020c      	movi.n	a2, 0
  4009dba2:	d189      	s32i.n	a8, a1, 52
  4009dba4:	20a110        	or	a10, a1, a1
  4009dba7:	01c222        	addi	a2, a2, 1
  4009dbaa:	03b8      	l32i.n	a11, a3, 0
  4009dbac:	334b      	addi.n	a3, a3, 4
  4009dbae:	0020c0        	memw
  4009dbb1:	fa9425        	call8	400984f4 <strcat>
  4009dbb4:	ec4266        	bnei	a2, 4, 4009dba4 <abort+0x68>
  4009dbb7:	01ad      	mov.n	a10, a1
* 4009dbb9:	fc90e5        	call8	4009a4c8 <esp_system_abort>
  4009dbbc:	024136        	entry	a1, 0x120
  4009dbbf:	eca0a2        	movi	a10, 236
  4009dbc2:	bc0c      	movi.n	a12, 11
  4009dbc4:	0b0c      	movi.n	a11, 0
  4009dbc6:	a1aa      	add.n	a10, a1, a10


0x400fa227: toit::fail(char const*, ...) + 0x5b
...
  400fa20b:	032aa2        	l32i	a10, a10, 12
  400fa20e:	5c1981        	l32r	a8, 400d1274 <_stext+0x1254>
  400fa211:	0008e0        	callx8	a8
  400fa214:	5c1681        	l32r	a8, 400d126c <_stext+0x124c>
  400fa217:	0008e0        	callx8	a8
  400fa21a:	3ab8      	l32i.n	a11, a10, 12
  400fa21c:	aa0c      	movi.n	a10, 10
  400fa21e:	5c1681        	l32r	a8, 400d1278 <_stext+0x1258>
  400fa221:	0008e0        	callx8	a8
  400fa224:	5c1681        	l32r	a8, 400d127c <_stext+0x125c>
* 400fa227:	0008e0        	callx8	a8
  400fa22c:	004136        	entry	a1, 32
  400fa22f:	20a220        	or	a10, a2, a2
  400fa232:	5b7d81        	l32r	a8, 400d1028 <_stext+0x1008>
  400fa235:	0008e0        	callx8	a8


0x400d288b: toit::Stack::transfer_from_interpreter(toit::Interpreter*) + 0xf
  400d287c:	004136        	entry	a1, 32
  400d287f:	20a220        	or	a10, a2, a2
  400d2882:	ffcfe5        	call8	400d2580 <toit::Stack::is_guard_zone_touched()>
  400d2885:	005a16        	beqz	a10, 400d288e <toit::Stack::transfer_from_interpreter(toit::Interpreter*)+0x12>
  400d2888:	f5eba1        	l32r	a10, 400d0034 <_stext+0x14>
* 400d288b:	279425        	call8	400fa1cc <toit::fail(char const*, ...)>
  400d288e:	042392        	l32i	a9, a3, 16
  400d2891:	27c2a2        	addi	a10, a2, 39
  400d2894:	c099a0        	sub	a9, a9, a10
  400d2897:	0bc282        	addi	a8, a2, 11


0x400e7ca7: toit::Interpreter::store_stack(toit::Object**, toit::Method) + 0x17
  400e7c90:	004136        	entry	a1, 32
  400e7c93:	038c      	beqz.n	a3, 400e7c97 <toit::Interpreter::store_stack(toit::Object**, toit::Method)+0x7>
  400e7c95:	4239      	s32i.n	a3, a2, 16
  400e7c97:	02bd      	mov.n	a11, a2
  400e7c99:	1238      	l32i.n	a3, a2, 4
  400e7c9b:	412332        	l32i	a3, a3, 0x104
  400e7c9e:	333b      	addi.n	a3, a3, 3
  400e7ca0:	0338      	l32i.n	a3, a3, 0
  400e7ca2:	03ad      	mov.n	a10, a3
  400e7ca4:	0020c0        	memw
* 400e7ca7:	eabd65        	call8	400d287c <toit::Stack::transfer_from_interpreter(toit::Interpreter*)>
  400e7caa:	448c      	beqz.n	a4, 400e7cb2 <toit::Interpreter::store_stack(toit::Object**, toit::Method)+0x22>
  400e7cac:	13c332        	addi	a3, a3, 19
  400e7caf:	006342        	s32i	a4, a3, 0
  400e7cb2:	090c      	movi.n	a9, 0
  400e7cb4:	18c232        	addi	a3, a2, 24


0x400ee623: toit::primitive_encode_error(toit::Process*, toit::Object**) + 0x53
...
  400ee606:	11a8      	l32i.n	a10, a1, 4
  400ee608:	0020c0        	memw
  400ee60b:	af6ca5        	call8	4009dcd4 <cfree>
  400ee60e:	f01d      	retw.n
  400ee610:	01cd00        	slli	a12, a13, 32
  400ee613:	18c1a2        	addi	a10, a1, 24
  400ee616:	f84da5        	call8	400e6af0 <toit::ProgramOrientedEncoder::ProgramOrientedEncoder(toit::Program*, toit::Buffer*)>
  400ee619:	5f24a2        	l32i	a10, a4, 0x17c
  400ee61c:	02cd      	mov.n	a12, a2
  400ee61e:	02bd      	mov.n	a11, a2
  400ee620:	18caa2        	addi	a10, a10, 24
* 400ee623:	f966e5        	call8	400e7c90 <toit::Interpreter::store_stack(toit::Object**, toit::Method)>
  400ee626:	412482        	l32i	a8, a4, 0x104
  400ee629:	03cd      	mov.n	a12, a3
  400ee62b:	883b      	addi.n	a8, a8, 3
  400ee62d:	05bd      	mov.n	a11, a5
  400ee62f:	18c1a2        	addi	a10, a1, 24


0x40083ee1: toit::Interpreter::run() + 0x2529
...
  40083ec5:	1978      	l32i.n	a7, a9, 4
  40083ec7:	771b      	addi.n	a7, a7, 1
  40083ec9:	1177e0        	slli	a7, a7, 2
  40083ecc:	b37a      	add.n	a11, a3, a7
  40083ece:	0998      	l32i.n	a9, a9, 0
  40083ed0:	12a8      	l32i.n	a10, a2, 4
  40083ed2:	046232        	s32i	a3, a2, 16
  40083ed5:	01a032        	movi	a3, 1
  40083ed8:	146182        	s32i	a8, a1, 80
  40083edb:	136192        	s32i	a9, a1, 76
  40083ede:	0020c0        	memw
* 40083ee1:	0009e0        	callx8	a9
  40083ee4:	14c0a0        	extui	a12, a10, 0, 2
  40083ee7:	42b8      	l32i.n	a11, a2, 16
  40083ee9:	142182        	l32i	a8, a1, 80
  40083eec:	132192        	l32i	a9, a1, 76
  40083eef:	723c66        	bnei	a12, 3, 40083f65 <toit::Interpreter::run()+0x25ad>


0x400f90b4: toit::Scheduler::run_process(toit::Locker&, toit::Process*, toit::SchedulerThread*) + 0x68
...
  400f9096:	0e0c      	movi.n	a14, 0
  400f9098:	814682        	s8i	a8, a6, 129
  400f909b:	0020c0        	memw
  400f909e:	0e6d      	mov.n	a6, a14
  400f90a0:	0e8d      	mov.n	a8, a14
  400f90a2:	2d99e7        	bne	a9, a14, 400f90d3 <toit::Scheduler::run_process(toit::Locker&, toit::Process*, toit::SchedulerThread*)+0x87>
  400f90a5:	03ad      	mov.n	a10, a3
  400f90a7:	0139      	s32i.n	a3, a1, 0
  400f90a9:	0020c0        	memw
  400f90ac:	f0fa25        	call8	400ea050 <toit::Locker::leave()>
  400f90af:	07ad      	mov.n	a10, a7
  400f90b1:	603481        	l32r	a8, 400d1184 <_stext+0x1164>
* 400f90b4:	0008e0        	callx8	a8
  400f90b7:	0a8d      	mov.n	a8, a10
  400f90b9:	41a9      	s32i.n	a10, a1, 16
  400f90bb:	01ad      	mov.n	a10, a1
  400f90bd:	0d6d      	mov.n	a6, a13
  400f90bf:	9189      	s32i.n	a8, a1, 36
  400f90c1:	51b9      	s32i.n	a11, a1, 20


0x400f935a: toit::Scheduler::run(toit::SchedulerThread*) + 0x6a
...
  400f933e:	0008e0        	callx8	a8
  400f9341:	204aa0        	or	a4, a10, a10
  400f9344:	20b110        	or	a11, a1, a1
  400f9347:	02ad      	mov.n	a10, a2
  400f9349:	5f8281        	l32r	a8, 400d1154 <_stext+0x1134>
  400f934c:	0008e0        	callx8	a8
  400f934f:	fdaa56        	bnez	a10, 400f932d <toit::Scheduler::run(toit::SchedulerThread*)+0x3d>
  400f9352:	03dd      	mov.n	a13, a3
  400f9354:	04cd      	mov.n	a12, a4
  400f9356:	01bd      	mov.n	a11, a1
  400f9358:	02ad      	mov.n	a10, a2
* 400f935a:	ffcf25        	call8	400f904c <toit::Scheduler::run_process(toit::Locker&, toit::Process*, toit::SchedulerThread*)>
  400f935d:	ffe9c6        	j	400f9308 <toit::Scheduler::run(toit::SchedulerThread*)+0x18>
  400f9360:	22a200        	orb	b10, b2, b0
  400f9363:	e42501        	l32r	a0, 400f23f8 <toit::primitive_aead_start_message(toit::Process*, toit::Object**)+0x4c>
  400f9366:	2282f0        	orb	b8, b2, b15


0x400f9389: toit::SchedulerThread::entry() + 0x9
  400f9380:	004136        	entry	a1, 32
  400f9383:	0522a2        	l32i	a10, a2, 20
  400f9386:	20b220        	or	a11, a2, a2
* 400f9389:	fff665        	call8	400f92f0 <toit::Scheduler::run(toit::SchedulerThread*)>
  400f938c:	000090        	retw
  400f9390:	004136        	entry	a1, 32
  400f9393:	5e2482        	l32i	a8, a4, 0x178
  400f9396:	00a092        	movi	a9, 0


0x400ea39a: toit::Thread::_boot() + 0x26
...
  400ea37d:	808830        	add	a8, a8, a3
  400ea380:	0829      	s32i.n	a2, a8, 0
  400ea382:	022242        	l32i	a4, a2, 8
  400ea385:	0020c0        	memw
  400ea388:	fff225        	call8	400ea2ac <toit::OS::get_heap_tag()>
  400ea38b:	203aa0        	or	a3, a10, a10
  400ea38e:	a7afa2        	movi	a10, -89
  400ea391:	fff0a5        	call8	400ea29c <toit::OS::set_heap_tag(int)>
  400ea394:	0288      	l32i.n	a8, a2, 0
  400ea396:	02ad      	mov.n	a10, a2
  400ea398:	2888      	l32i.n	a8, a8, 8
* 400ea39a:	0008e0        	callx8	a8
  400ea39d:	0d0c      	movi.n	a13, 0
  400ea39f:	0dcd      	mov.n	a12, a13
  400ea3a1:	14a8      	l32i.n	a10, a4, 4
  400ea3a3:	0dbd      	mov.n	a11, a13
  400ea3a5:	979281        	l32r	a8, 400d01f0 <_stext+0x1d0>
  400ea3a8:	0008e0        	callx8	a8


0x400ea3c1: toit::esp_thread_start(void*) + 0x5
  400ea3bc:	004136        	entry	a1, 32
  400ea3bf:	02ad      	mov.n	a10, a2
* 400ea3c1:	fffb25        	call8	400ea374 <toit::Thread::_boot()>
  400ea3c4:	f01d      	retw.n
  400ea3c8:	004136        	entry	a1, 32
  400ea3cb:	0288      	l32i.n	a8, a2, 0
  400ea3cd:	0b0c      	movi.n	a11, 0
  400ea3cf:	103380        	and	a3, a3, a8

[kasperl]

We have found an issue in how we compute the necessary size for stacks when we shrink them during GC. Will be addressed in v2.0.0-alpha.84.