What a day. Spent the day hunting a bug in my code, only to find out that it wasn’t in my code. (Update: Turns out my code was wrong in two ways, more below the original entry.) (Update 2: There are options to set this in the Arduino IDE Preferences)
There’s an error in the sprintf and snprintf implementation on Arduino that occurs when more than 8 varargs are passed in after the format specifier.
The problem is that:
- an extra ’00’ sneaks into the output string between the 1st and 2nd parameter outputs
- the last parameter does not make it into the output string
This can lead to day-long debugging sessions of unrelated software modules which actually were correctly implemented, in order to determine the root cause.
Here’s an example sketch that demonstrates what goes wrong:
|
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
|
/**
* Demonstrate that the sprintf / snprintf implementation on Arduino is broken.
*
* sprintf / snprintf, when used with more than 8 varargs:
* inserts an extra '00' in the output string
* removes the last parameter from the output string
*
* This causes a lot of extra debugging.
*
* Expected: abcd0001020304050607
* Actual: abcd0000010203040506
*/
enum {
OUTPUT_LENGTH = 50
};
uint32_t shortId = 0xabcd;
uint8_t buffer[8] = { 0, 1, 2, 3, 4, 5, 6, 7 };
void setup()
{
Serial.begin(115200);
char output[OUTPUT_LENGTH] = { 0 };
// ERROR: The buggy way.
//
// Prints: abcd0000010203040506
snprintf(output, OUTPUT_LENGTH, "%04x%02x%02x%02x%02x%02x%02x%02x%02x",
shortId,
buffer[0],
buffer[1],
buffer[2],
buffer[3],
buffer[4],
buffer[5],
buffer[6],
buffer[7],
buffer[8]);
Serial.println(output);
// OK: The way that actually works.
//
// Prints: abcd0001020304050607
snprintf(output, OUTPUT_LENGTH, "%04x",
shortId);
snprintf(output + 4, OUTPUT_LENGTH - 4, "%02x%02x%02x%02x%02x%02x%02x%02x",
buffer[0],
buffer[1],
buffer[2],
buffer[3],
buffer[4],
buffer[5],
buffer[6],
buffer[7],
buffer[8]);
Serial.println(output);
// ERROR: Another buggy way.
//
// Prints: abcd0000010203040506
sprintf(output, "%04x%02x%02x%02x%02x%02x%02x%02x%02x",
shortId,
buffer[0],
buffer[1],
buffer[2],
buffer[3],
buffer[4],
buffer[5],
buffer[6],
buffer[7],
buffer[8]);
Serial.println(output);
}
void loop()
{
}
|
Which produces the following output in the Serial Monitor:
abcd0000010203040506 abcd0001020304050607 abcd0000010203040506
Update: the Real Problem is in the Arduino IDE
So, it turns out there were two problems in my code above. I’m a bit embarrassed by one, but by the other I am not.
- There’s a buffer overread in the *printf() functions, buffer[8] is the 9th byte in an 8 byte array.
- The format specifier %04x expects a 2-byte int on Arduino, where I am forcing in a 4-byte int. Ooops. Perhaps the Arduino IDE should have given me a warning about the mismatch between format specifiers and inputs? In fact, the Arduino IDE goes out of its way to hide useful information like this from the programmer. This is bad, both for learners, and advanced learners (like me).
The default warning settings in the Arduino IDE are:
compiler.warning_flags=-w
compiler.warning_flags.none=-w
compiler.warning_flags.default=
compiler.warning_flags.more=-Wall
compiler.warning_flags.all=-Wall -Wextra
By default, the Arduino IDE uses compiler.warning_flags when compiling .c and .cpp files.
What does the -w flag do? Well, let’s look at what the gcc manual says:
Nice. This is akin to giving children scissors and asking them to go play on the highway.
Now, most modern compilers can and do provide warnings about the exact problems I described. But you have to make sure those warnings don’t get suppressed!
So, on OS X, open up /Applications/Arduino.app/Contents/Java/hardware/arduino/avr/platform.txt (if you’re using Arduino 1.6.5), and change the lines that start with:
to:
Reopen the Arduino environment, and rebuild the above code. Now the compiler provides warnings about the exact problem I just spent hours debugging:
/Applications/Arduino.app/Contents/Java/hardware/tools/avr/bin/avr-g++ -c -g -Os -Wall -Wextra -fno-exceptions -ffunction-sections -fdata-sections -fno-threadsafe-statics -MMD -mmcu=atmega328p -DF_CPU=16000000L -DARDUINO=10605 -DARDUINO_AVR_UNO -DARDUINO_ARCH_AVR -std=c++11 -I/Applications/Arduino.app/Contents/Java/hardware/arduino/avr/cores/arduino -I/Applications/Arduino.app/Contents/Java/hardware/arduino/avr/variants/standard /var/folders/w3/_drc6cyx5b90w1qnmf_r7xlh0000gr/T/build5772315147861768801.tmp/FixedSnprintf.cpp -o /var/folders/w3/_drc6cyx5b90w1qnmf_r7xlh0000gr/T/build5772315147861768801.tmp/FixedSnprintf.cpp.o
FixedSnprintf.ino: In function 'void setup()':
FixedSnprintf.ino:40:18: warning: format '%x' expects argument of type 'unsigned int', but argument 4 has type 'uint32_t {aka long unsigned int}' [-Wformat=]
FixedSnprintf.ino:40:18: warning: too many arguments for format [-Wformat-extra-args]
FixedSnprintf.ino:48:16: warning: format '%x' expects argument of type 'unsigned int', but argument 4 has type 'uint32_t {aka long unsigned int}' [-Wformat=]
FixedSnprintf.ino:59:18: warning: too many arguments for format [-Wformat-extra-args]
FixedSnprintf.ino:76:18: warning: format '%x' expects argument of type 'unsigned int', but argument 3 has type 'uint32_t {aka long unsigned int}' [-Wformat=]
FixedSnprintf.ino:76:18: warning: too many arguments for format [-Wformat-extra-args]
FixedSnprintf.ino:93:18: warning: too many arguments for format [-Wformat-extra-args]
FixedSnprintf.ino:40:17: warning: array subscript is above array bounds [-Warray-bounds]
FixedSnprintf.ino:59:17: warning: array subscript is above array bounds [-Warray-bounds]
FixedSnprintf.ino:76:17: warning: array subscript is above array bounds [-Warray-bounds]
FixedSnprintf.ino:93:17: warning: array subscript is above array bounds [-Warray-bounds]
warning: too many arguments for format [-Wformat-extra-args] and warning: array subscript is above array bounds [-Warray-bounds] pop up for every buffer[8] in the code.
warning: format '%x' expects argument of type 'unsigned int', but argument 4 has type 'uint32_t {aka long unsigned int}' [-Wformat=] is shown for the *printf() function calls that produce errors.
This kind of thing goes totally against the principle of least astonishment, and is one of the reasons I still can’t take the Arduino ecosystem seriously.
Warnings are part of a compiler to help people at any level of proficiency improve their code. Explicitly turning them off may in the short run seem like a useful thing to ease novices into a programming environment, but it simply causes more problems among the wider user base.
The fixed, warning-free code, looks like this:
|
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
|
enum {
OUTPUT_LENGTH = 50
};
uint32_t shortId = 0xabcd;
uint8_t buffer[8] = { 0, 1, 2, 3, 4, 5, 6, 7 };
void setup()
{
Serial.begin(115200);
char output[OUTPUT_LENGTH] = { 0 };
// ERROR: The buggy way.
//
// Prints: abcd0000010203040506
snprintf(output, OUTPUT_LENGTH, "%04x%02x%02x%02x%02x%02x%02x%02x%02x",
(uint16_t) shortId,
buffer[0],
buffer[1],
buffer[2],
buffer[3],
buffer[4],
buffer[5],
buffer[6],
buffer[7]);
Serial.println(output);
// OK: The way that actually works.
//
// Prints: abcd0001020304050607
snprintf(output, OUTPUT_LENGTH, "%04x",
(uint16_t) shortId);
snprintf(output + 4, OUTPUT_LENGTH - 4, "%02x%02x%02x%02x%02x%02x%02x%02x",
buffer[0],
buffer[1],
buffer[2],
buffer[3],
buffer[4],
buffer[5],
buffer[6],
buffer[7]);
Serial.println(output);
// ERROR: Another buggy way.
//
// Prints: abcd0000010203040506
sprintf(output, "%04x%02x%02x%02x%02x%02x%02x%02x%02x",
(uint16_t) shortId,
buffer[0],
buffer[1],
buffer[2],
buffer[3],
buffer[4],
buffer[5],
buffer[6],
buffer[7]);
Serial.println(output);
// FIX: Explicitly cast the varargs to the expected size.
//
// Prints: abcd0001020304050607
snprintf(output, OUTPUT_LENGTH, "%04x%02x%02x%02x%02x%02x%02x%02x%02x",
(uint16_t) shortId,
buffer[0],
buffer[1],
buffer[2],
buffer[3],
buffer[4],
buffer[5],
buffer[6],
buffer[7]);
Serial.println(output);
}
void loop()
{
}
|
Update 2: Arduino IDE Preferences
Set those warning flags more easily through the Preferences pane:
Damn it! You deserve a good pint of beer for this. Thanks! I’ve been scratching my head for 2 days now wondering why my sprintf decided to stop working (when I didn’t touch that part of the code at all!). First value (int) looked really strange and short, and second value (string) was null.. Enabling all warnings finally highlighted that I did change the declaration of the 1st int to long int. Such a small change to cause such a big issue elsewhere lol.. Thanks 🙂 All working again.