1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
|
---
title: Fixing the Mysterious Broken Bootloader
author: Nick Winans
author_title: Contributor
author_url: https://github.com/Nicell
author_image_url: https://avatars1.githubusercontent.com/u/9439650
tags: [bootloader, keyboards, firmware, oss, ble]
---
Recently I was able to fix the "stuck in the bootloader" issue in
[#322](https://github.com/zmkfirmware/zmk/pull/322) that had been plaguing us
for quite some time. I want to go over what the issue was, how the issue was
diagnosed, and how it was fixed.
## Background
What exactly is the "stuck in the bootloader" issue? Seemingly randomly, users'
keyboards would suddenly stop working and when they would reset their keyboard
they would get put into the bootloader instead of back into the firmware. This
would require the user to re-flash the firmware again to get into the firmware.
That wouldn't be so bad except for the fact that once this occurs, every reset
would require the user to re-flash the firmware again. The only way to really
fix this issue was to re-flash the bootloader itself, which is a huge pain.
Going into this, all we knew was that this issue was most likely introduced
somewhere in the [#133](https://github.com/zmkfirmware/zmk/pull/133), which
added Bluetooth profile management. We've had quite a few attempts at trying to
recreate the issue, but we never were able to get it to happen consistently.
## Diagnosing the issue
This issue had been happening sporadically for the past month, and I finally
decided to dig in to see what was going on. We started in the Discord and
discussed what was common between all of the people who have experienced this
issue. Everyone who had this issue reported that they did quite a bit of profile
switching. This lined up with the possible connection to the Bluetooth profile
management pull request.
### Pinpointing the cause
I had a hunch that this was related to the settings system. The settings system
is used by profile Bluetooth switching, and the settings system works directly
with the system flash. Based on this hunch, I tried spamming the RGB underglow
cycle behavior on my main keyboard. Sure enough after a couple minutes, I got
stuck in the bootloader. I was even able to reproduce it again.
This was an important discovery for two reasons. First, I was able to recreate
the issue consistently, which meant I could set up logging and more closely
monitor what the board was doing. Second, this more or less proved that it was
specifically the settings system at fault. Both Bluetooth profile switching and
RGB underglow cycling trigger it, and the one common piece is they save their
state to settings.
### Settings system overview
To understand what's going wrong, we first need to understand how the settings
system works. Here's a diagram to explain the flash space that the settings
system holds for our nRF52840 based boards (nice!nano, nRFMicro, BlueMicro).
The settings flash space lives at the end of the flash of the chip. In this case
it starts at `0xF8000` and is `0x8000` bytes long, which is 32KB in more
comprehensible units. Then due to the chip's architecture, this flash space is
broken into pages, which are `0x1000` bytes in size (4KB).
The backend that carries out the settings save and read operation in ZMK is
called NVS. NVS calls these pages sectors. Due to how flash works, you can't
write to the same bytes multiple times without erasing them first, and to erase
bytes, you need to erase the entire sector of flash. This means when NVS writes
to the settings flash if there's no erased space available for the new value, it
will need to erase a sector.
### Logging discoveries
So first I enabled logging of the NVS module by adding
`CONFIG_NVS_LOG_LEVEL_DBG=y` to my `.conf` file. I repeated the same test of
spamming RGB underglow effect cycle and the resulting logs I got were this:
```
[00:00:00.000,671] <inf> fs_nvs: 8 Sectors of 4096 bytes
[00:00:00.000,671] <inf> fs_nvs: alloc wra: 3, f70
[00:00:00.000,671] <inf> fs_nvs: data wra: 3, f40
// A bunch of effect cycle spam
[00:02:34.781,188] <dbg> fs_nvs: Erasing flash at fd000, len 4096
// A bunch more effect cycle spam
[00:06:42.219,970] <dbg> fs_nvs: Erasing flash at ff000, len 4096
// A bunch more effect cycle spam
// KABOOM - bootloader issue
```
So at start up, we can see that the 8 sectors of 4KB are found by NVS properly,
however, I wasn't sure what the second and third lines meant, but we'll get back
to that. Nonetheless the next two logs from NVS showed erasing the sector at
`0xFD000` and then erasing the `0xFF000` sector.
It's really odd that the third to last sector and the last sector are erased,
and then shortly after the bootloader issue is hit. I really had no explanation
for this behavior.
### Reaching out to Zephyr
At this point, I nor anyone else working on the ZMK project knew enough about
NVS to explain what was going on here. [Pete
Johanson](https://github.com/petejohanson), project founder, reached out on the
Zephyr Project's Slack (ZMK is built on top of Zephyr if you weren't aware).
Justin B and Laczen assisted by first explaining that those `alloc wra` and
`data wra` logs from earlier are showing what data NVS found at startup.
More specifically, `data wra` should be `0` when it first starts up on a clean
flash. As we can see from my earlier logging on a clean flash I was instead
getting `f40`. NVS is finding data in our settings sectors when they should be
blank! We were then given the advice to double check our bootloader.
### The Adafruit nRF52 Bootloader
Most of the boards the contributors of ZMK use have the [Adafruit nRF52
Bootloader](https://github.com/adafruit/Adafruit_nRF52_Bootloader), which allows
for extremely easy flashing by dragging and dropping `.uf2` files onto the board
as a USB drive. Every bootloader takes up a portion of the flash, and in the
README explains that the first `0x26000` is reserved for the bootloader with the
nRF52840, and we've properly allocated that.
However, there isn't a full explanation of the flash allocation of the
bootloader in the README. There's a possibility that the bootloader is using
part of the same flash area we're using. I reached out on the Adafruit Discord,
and [Dan Halbert](https://github.com/dhalbert) pointed me towards the [linker
map](https://github.com/adafruit/Adafruit_nRF52_Bootloader/blob/master/linker/nrf52840.ld)
of the nRF52840. Let's take a look.
```
FLASH (rx) : ORIGIN = 0xF4000, LENGTH = 0xFE000-0xF4000-2048 /* 38 KB */
BOOTLOADER_CONFIG (r): ORIGIN = 0xFE000 - 2048, LENGTH = 2048
/** Location of mbr params page in flash. */
MBR_PARAMS_PAGE (rw) : ORIGIN = 0xFE000, LENGTH = 0x1000
/** Location of bootloader setting in flash. */
BOOTLOADER_SETTINGS (rw) : ORIGIN = 0xFF000, LENGTH = 0x1000
```
Here's a diagram to show this a bit better.
We've found the issue! As you can see from the red bar (representing our
settings flash area), we've put the settings flash area _right on top_ of the
Adafruit bootloader's flash space. Oops!
This also shines some light on why NVS erased `0xFD000` and `0xFF000` sectors.
It's possible there was no flash written to `0xFD000` because the bootloader
didn't use up all of that space it has, and then there possibly weren't any
bootloader settings set yet, so `0xFF000` could be used and erased by NVS too.
After erasing `0xFF000`, NVS probably next erased a rather important part of the
bootloader that resulted in this issue at hand. In my opinion, we're pretty
lucky that it didn't delete an even more vital part of the bootloader. At least
we could still get to it, so that we could re-flash the bootloader easily!
## The solution
Now that we've found the issue, we can pretty easily fix this. We'll need to
move the settings flash area back so that it doesn't overlap with the
bootloader. First we calculate the size of the of flash area the bootloader is using.
```
0x100000 (end of flash) - 0x0F4000 (start of bootloader) = 0xC000 (48KB)
```
So the bootloader is using the last 48KB of the flash, this means all we need to
do is shift back the settings area and code space `0xC000` bytes. We'll apply
this to all of the `.dts` files for the boards that were affected by this issue.
```diff
code_partition: partition@26000 {
label = "code_partition";
- reg = <0x00026000 0x000d2000>;
+ reg = <0x00026000 0x000c6000>;
};
- storage_partition: partition@f8000 {
+ storage_partition: partition@ec000 {
label = "storage";
- reg = <0x000f8000 0x00008000>;
+ reg = <0x000ec000 0x00008000>;
};
```
And with those changes, we should no longer run into this issue! In the process
of these changes, we lost 48KB of space for application code, but we're only
using around 20% of it anyways. 🎉
|
