Serializing NaiveDatetime on AVR crashes

[rihardsk]

Whenever i try to serialize a chrono::NaiveDateTime or any struct that contains it internally, the program resets, if it's being run on an AVR microcontroller (ATmega328p specifically). It can be as simple as:

let entry = NaiveDateTime::MIN;
// This is where it crashes and the board resets and restarts running from the beginning
let output: postcard::Result<Vec<u8, 64>> = to_vec(&entry);

Serializing other stuff seems to work fine, e.g., this example code from the docs works as expected:

#[derive(Serialize, Deserialize, Debug, Eq, PartialEq)]
struct RefStruct<'a> {
    bytes: &'a [u8],
    str_s: &'a str,
}

let message = "hElLo";
let bytes = [0x01, 0x10, 0x02, 0x20];
let output: postcard::Result<Vec<u8, 11>> = to_vec(&RefStruct {
    bytes: &bytes,
    str_s: message,
});

Also, the same code runs without issue on x64, which makes me suspect a miscompilation on AVR but verifying that seems to be beyond my ability currently (tried looking at the AVR disassembly but there's simply too much going on there).

I'm building the code using the nightly-2023-03-24 toolchain.

Minimal reproducible example

main.rs

#![no_std]
#![no_main]

use chrono::NaiveDateTime;
use serde::{Deserialize, Serialize};

use heapless::Vec;
use panic_halt as _;
use postcard::to_vec;

#[derive(Serialize, Deserialize, Debug, Eq, PartialEq)]
struct RefStruct<'a> {
    bytes: &'a [u8],
    str_s: &'a str,
}

#[arduino_hal::entry]
fn main() -> ! {
    let dp = arduino_hal::Peripherals::take().unwrap();
    let pins = arduino_hal::pins!(dp);

    let mut serial = arduino_hal::default_serial!(dp, pins, 9600);

    ufmt::uwriteln!(&mut serial, "Serial set up, entering loop").unwrap();

    arduino_hal::delay_ms(1000);
    loop {
        let entry = NaiveDateTime::MIN;

        ufmt::uwriteln!(&mut serial, "Converting").unwrap();
        arduino_hal::delay_ms(1000);

        // For some reason this serialization code works ...
        //
        // let message = "hElLo";
        // let bytes = [0x01, 0x10, 0x02, 0x20];
        // let output: postcard::Result<Vec<u8, 11>> = to_vec(&RefStruct {
        //     bytes: &bytes,
        //     str_s: message,
        // });

        // ... but this doesn't
        //
        // NOTE: Not sure how much memory this takes but 64 bytes should be
        // plenty for serialization, i guess
        let output: postcard::Result<Vec<u8, 64>> = to_vec(&entry);

        ufmt::uwriteln!(&mut serial, "Writing").unwrap();
        arduino_hal::delay_ms(1000);
        match output {
            Ok(output) => {
                for byte in output {
                    serial.write_byte(byte);
                }
                serial.flush();
            }
            Err(_e) => ufmt::uwriteln!(&mut serial, "Serialization error").unwrap(),
        }

        arduino_hal::delay_ms(5000);
    }
}

Cargo.toml

[package]
name = "templog-arduino"
version = "0.1.0"
edition = "2021"
license = "MIT OR Apache-2.0"

[[bin]]
name = "templog-arduino"
test = false
bench = false

[dependencies]
panic-halt = "0.2.0"
ufmt = "0.1.0"
embedded-hal = "0.2.3"
serde = { version = "1.0.147", features = ["derive"], default-features = false }
chrono = { version = "0.4.23", features = ["serde"], default-features = false }
heapless = { git = "https://github.com/japaric/heapless" }

[dependencies.postcard]
# this refers to postcard rev 62c05473f76ead781aaa9d4a3e4057b86e543747
# with an updated version of `heapless` dependency
path = "../../postcard"

[dependencies.arduino-hal]
git = "https://github.com/rahix/avr-hal"
rev = "3b8f39fa2ec5e3359c7bedc33d982e75e8cc3700"
features = ["arduino-uno"]

# This doesn't seem to have any effect, don't know why
# [patch.crates-io]
# heapless = { git = 'https://github.com/japaric/heapless' }

# Configure the build for minimal size - AVRs have very little program memory
[profile.dev]
panic = "abort"
lto = true
opt-level = "s"

[profile.release]
panic = "abort"
codegen-units = 1
debug = true
lto = true
opt-level = "s"

Other things to note

I'm using postcard rev 62c05473f76ead781aaa9d4a3e4057b86e543747 with the following diff applied to it to work around #82

diff --git a/Cargo.toml b/Cargo.toml
index 6498e55..d16e0dd 100644
--- a/Cargo.toml
+++ b/Cargo.toml
@@ -29,7 +29,8 @@ version = "0.2.24"
 optional = true
 
 [dependencies.heapless]
-version = "0.7.0"
+# version = "0.7.0"
+git = 'https://github.com/japaric/heapless'
 default-features = false
 features = ["serde"]
 optional = true

heapless is at rev 644653bf3b831c6bb4963be2de24804acf5e5001.

[jamesmunns]

I think this code:

postcard/src/ser/serializer.rs

Lines 321 to 388 in 62c0547

	fn collect_str<T: ?Sized>(self, value: &T) -> Result<Self::Ok>
	where
	T: core::fmt::Display,
	{
	use core::fmt::Write;
	// Unfortunately, we need to know the size of the serialized data before
	// we can place it into the output. In order to do this, we run the formatting
	// of the output data TWICE, the first time to determine the length, the
	// second time to actually format the data
	//
	// There are potentially other ways to do this, such as:
	//
	// * Reserving a fixed max size, such as 5 bytes, for the length field, and
	// leaving non-canonical trailing zeroes at the end. This would work up
	// to some reasonable length, but might have some portability vs max size
	// tradeoffs, e.g. 64KiB if we pick 3 bytes, or 4GiB if we pick 5 bytes
	// * Expose some kind of "memmove" capability to flavors, to allow us to
	// format into the buffer, then "scoot over" that many times.
	//
	// Despite the current approaches downside in speed, it is likely flexible
	// enough for the rare-ish case where formatting a Debug impl is necessary.
	// This is better than the previous panicking behavior, and can be improved
	// in the future.
	struct CountWriter {
	ct: usize,
	}
	impl Write for CountWriter {
	fn write_str(&mut self, s: &str) -> core::result::Result<(), core::fmt::Error> {
	self.ct += s.as_bytes().len();
	Ok(())
	}
	}
	let mut ctr = CountWriter { ct: 0 };
	// This is the first pass through, where we just count the length of the
	// data that we are given
	write!(&mut ctr, "{}", value).map_err(|_| Error::CollectStrError)?;
	let len = ctr.ct;
	self.try_push_varint_usize(len)
	.map_err(|_| Error::SerializeBufferFull)?;
	struct FmtWriter<'a, IF>
	where
	IF: Flavor,
	{
	output: &'a mut IF,
	}
	impl<'a, IF> Write for FmtWriter<'a, IF>
	where
	IF: Flavor,
	{
	fn write_str(&mut self, s: &str) -> core::result::Result<(), core::fmt::Error> {
	self.output
	.try_extend(s.as_bytes())
	.map_err(|_| core::fmt::Error::default())
	}
	}
	// This second pass actually inserts the data.
	let mut fw = FmtWriter {
	output: &mut self.output,
	};
	write!(&mut fw, "{}", value).map_err(|_| Error::CollectStrError)?;
	Ok(())
	}

(and support for the collect_str method) were added due to issues with chrono (see #32).

If I had to guess, I would suspect an AVR miscompilation of dyn Trait items, which is used by the core::fmt::Write implementation?

[rihardsk]

What do you mean by

dyn Trait items, which is used by the core::fmt::Write implementation

I didn't notice any dyn Trait items when looking around.

I tried to probe this thing some more, but the only thing I discovered, is that NaiveDateTimes core::fmt::Display implementation seems to be working ok on its own. So that makes it somewhat more likely that something in postcard is causing this.

But I'm not sure how to proceed from here. Should I try to somehow inline collect_str implementation and pepper it with ufmt::writeln! calls to find out where exactly it breaks? Or could this be enough info as is, to open an issue on https://github.com/rust-lang/rust and see what they say about this?

[jamesmunns]

As far as I am aware, there are quite a few parts under the hood of the fmt::Write and write!() machinery that may end up using dyn Traits.

An interesting test might be something like:

use core::fmt::Write;

let mut buf: heapless::String<256> = heapless::String::new();
let data: NaiveDateTime = ...; // your test data here
write!(&mut buf, "{}", &data).unwrap();

And see if that works. This would use the same core::fmt::Write machinery I am using in postcard, without actually using postcard.

If that works on other targets (desktop, cortex-m), and NOT on AVR, I'd be pretty convinced it was something wrong with the AVR code generation. If that DOES work on AVR, then I'd certainly be confused!

[rihardsk]

When I said that

the only thing I discovered, is that NaiveDateTimes core::fmt::Display implementation seems to be working ok on its own

I meant that I already tried something similar. This is what i did:

        struct SerialWriter<'a, T> {
            serial: &'a mut T,
        }
        impl<'a, T> Write for SerialWriter<'a, T> where T: uWrite {
            fn write_str(&mut self, s: &str) -> core::result::Result<(), core::fmt::Error> {
                ufmt::uwrite!(&mut self.serial, "{}", s).map_err(|_| core::fmt::Error::default())?;
                Ok(())
            }
        }

        let mut serial_writer = SerialWriter { serial: &mut serial };

        let entry = NaiveDateTime::MIN;
        write!(&mut serial_writer, "{}", entry).unwrap();

        // This outputs:
        // -262144-01-01 00:00:00
        // over the serial connection

this works on AVR.

I tried out your code as well. It produces the same output when printed out with ufmt::uwriteln!(&mut serial, "{}", buf.as_str()).unwrap(). So that probably means that there's something else going on.

Btw, I searched for "AVR miscompilation" in the Rust repo and found this rust-lang/rust#74743 which does indicate that the AVR backend has issues with dyn Trait stuff. But I guess the observations above indicate that this might not be relevant (unless postcard also uses some dyn Trait stuff internally). I didn't find anything else that seems relevant, though.

[jamesmunns]

ufmt explicitly doesn't use dynamic dispatch: https://docs.rs/ufmt/latest/ufmt/

No dynamic dispatch in generated code

It might be worth trying without using ufmt at all to see if you get the same issues. Since core::fmt::Write/writeln!() DOES use dyn dispatch, and ufmt::Write/ufmt::writeln!() DOESN'T, this is a pretty significant difference.

[rihardsk]

Here's how I invoked your code. It doesn't crash.

        use core::fmt::Write;
        let mut buf: heapless::String<256> = heapless::String::new();
        let data: NaiveDateTime = NaiveDateTime::MIN; // your test data here
        // This uses core::fmt::Write
        write!(&mut buf, "{}", &data).unwrap();

        // This uses ufmt::Write. Added for convenience to check the results
        ufmt::uwriteln!(&mut serial, "{}", buf.as_str()).unwrap();

AFAIK I'm exercising core::fmt::Write on the 5th line. The last line uses ufmt::Write but it's only for convenience and doesn't affect what's happening before that, commenting it out has no effect other than me not seeing the value of buf (still no crash without it). Is this what you're asking, or am I misunderstanding something?

[Patryk27]

btw, the newest nightly (since rust-lang/rust#114048) brought lots of fixes for the AVR backend - it might be worthwhile to recheck on it 🙂

[rihardsk]

Thanks, I'll have a look as soon as I get a chance.