Recover from init fail

Cargo.toml

@@ -9,7 +9,11 @@ name = "creaturedex"
 path = "./src/bin/main.rs"
 
 [dependencies]
-esp-hal = { version = "~1.1.0", features = ["esp32s3", "log-04", "unstable"] } #, "embassy", "embassy-time-timg0", "embassy-executor-thread"] }
+esp-hal = { version = "~1.1.0", features = [
+  "esp32s3",
+  "log-04",
+  "unstable",
+] } #, "embassy", "embassy-time-timg0", "embassy-executor-thread"] }
 
 esp-rtos = { version = "0.3.0", features = [
   "embassy",
@@ -24,8 +28,7 @@ log                    = "0.4.27"
 
 critical-section = "1.2.0"
 embedded-io = "0.7.1"
-embassy-executor = { version = "0.10.0", features = [
+embassy-executor = { version = "0.10.0", features = [] }
-] }
 embassy-time = { version = "0.5.1", default-features = false }
 embassy-futures = "0.1.2"
 esp-alloc = "0.10.0"
@@ -48,6 +51,9 @@ embedded-hal-async = "1.0.0"
 i2c-character-display = "0.5.1"
 ch1115 = { version = "0.1.2", features = ["graphics"] }
 
+[build-dependencies]
+log = "0.4.27"
+
 
 [patch.crates-io]
 ch1115 = { git = "https://github.com/ede1998/ch1115.git", rev = "2d3a3ba38050efe012e6a210afe3e125ec280c37" }

build.rs

@@ -1,4 +1,5 @@
 fn main() {
+    generate_filter_snippet();
     linker_be_nice();
     // make sure linkall.x is the last linker script (otherwise might cause problems with flip-link)
     println!("cargo:rustc-link-arg=-Tlinkall.x");
@@ -68,3 +69,165 @@ fn linker_be_nice() {
         std::env::current_exe().unwrap().display()
     );
 }
+
+// Taken over from esp_println because impossible to just extend their existing env logger.
+// https://github.com/esp-rs/esp-hal/blob/8fa6d7e985e724d6ad998e34307429b0920da370/esp-println/build.rs
+fn generate_filter_snippet() {
+    use log::LevelFilter;
+    use std::{env, path::Path};
+
+    let out_dir = env::var_os("OUT_DIR").unwrap();
+    let dest_path = Path::new(&out_dir).join("log_filter.rs");
+
+    let filter = env::var("ESP_LOG");
+    let snippet = if let Ok(filter) = filter {
+        let res = parse_spec(&filter);
+
+        if !res.errors.is_empty() {
+            panic!("Error parsing `ESP_LOG`: {:?}", res.errors);
+        } else {
+            let max = res
+                .directives
+                .iter()
+                .map(|v| v.level)
+                .max()
+                .unwrap_or(LevelFilter::Off);
+            let max = match max {
+                LevelFilter::Off => "Off",
+                LevelFilter::Error => "Error",
+                LevelFilter::Warn => "Warn",
+                LevelFilter::Info => "Info",
+                LevelFilter::Debug => "Debug",
+                LevelFilter::Trace => "Trace",
+            };
+
+            let mut snippet = String::new();
+
+            snippet.push_str(&format!(
+                "pub(crate) const FILTER_MAX: log::LevelFilter = log::LevelFilter::{max};"
+            ));
+
+            snippet
+                .push_str("pub(crate) fn is_enabled(level: log::Level, _target: &str) -> bool {");
+
+            let mut global_level = None;
+            for directive in res.directives {
+                let level = match directive.level {
+                    LevelFilter::Off => "Off",
+                    LevelFilter::Error => "Error",
+                    LevelFilter::Warn => "Warn",
+                    LevelFilter::Info => "Info",
+                    LevelFilter::Debug => "Debug",
+                    LevelFilter::Trace => "Trace",
+                };
+
+                if let Some(name) = directive.name {
+                    // If a prefix matches, don't continue to the next directive
+                    snippet.push_str(&format!(
+                        "if _target.starts_with(\"{name}\") {{ return level <= log::LevelFilter::{level}; }}"
+                    ));
+                } else {
+                    if global_level.is_some() {
+                        panic!("Multiple global log levels specified in `ESP_LOG`");
+                    }
+                    global_level = Some(level);
+                }
+            }
+
+            // Place the fallback rule at the end
+            if let Some(level) = global_level {
+                snippet.push_str(&format!("level <= log::LevelFilter::{level}"));
+            } else {
+                snippet.push_str(" false");
+            }
+            snippet.push('}');
+            snippet
+        }
+    } else {
+        "pub(crate) const FILTER_MAX: log::LevelFilter = log::LevelFilter::Off; pub(crate) fn is_enabled(_level: log::Level, _target: &str) -> bool { true }".to_string()
+    };
+
+    std::fs::write(&dest_path, &snippet).unwrap();
+}
+
+#[derive(Default, Debug)]
+struct ParseResult {
+    pub(crate) directives: Vec<Directive>,
+    pub(crate) errors: Vec<String>,
+}
+
+impl ParseResult {
+    fn add_directive(&mut self, directive: Directive) {
+        self.directives.push(directive);
+    }
+
+    fn add_error(&mut self, message: String) {
+        self.errors.push(message);
+    }
+}
+
+#[derive(Debug)]
+struct Directive {
+    pub(crate) name: Option<String>,
+    pub(crate) level: log::LevelFilter,
+}
+
+/// Parse a logging specification string (e.g:
+/// `crate1,crate2::mod3,crate3::x=error/foo`) and return a vector with log
+/// directives.
+fn parse_spec(spec: &str) -> ParseResult {
+    use log::LevelFilter;
+
+    let mut result = ParseResult::default();
+
+    let mut parts = spec.split('/');
+    let mods = parts.next();
+
+    if let Some(m) = mods {
+        for s in m.split(',').map(|ss| ss.trim()) {
+            if s.is_empty() {
+                continue;
+            }
+            let mut parts = s.split('=');
+            let (log_level, name) =
+                match (parts.next(), parts.next().map(|s| s.trim()), parts.next()) {
+                    (Some(part0), None, None) => {
+                        // if the single argument is a log-level string or number,
+                        // treat that as a global fallback
+                        match part0.parse() {
+                            Ok(num) => (num, None),
+                            Err(_) => (LevelFilter::max(), Some(part0)),
+                        }
+                    }
+                    (Some(part0), Some(""), None) => (LevelFilter::max(), Some(part0)),
+                    (Some(part0), Some(part1), None) => {
+                        if let Ok(num) = part1.parse() {
+                            (num, Some(part0))
+                        } else {
+                            result.add_error(format!("invalid logging spec '{part1}'"));
+                            continue;
+                        }
+                    }
+                    _ => {
+                        result.add_error(format!("invalid logging spec '{s}'"));
+                        continue;
+                    }
+                };
+
+            result.add_directive(Directive {
+                name: name.map(|s| s.to_owned()),
+                level: log_level,
+            });
+        }
+    }
+
+    // Sort by length so that the most specific prefixes come first
+    result
+        .directives
+        .sort_by(|a, b| match (a.name.as_ref(), b.name.as_ref()) {
+            (Some(a), Some(b)) => b.len().cmp(&a.len()),
+            _ => std::cmp::Ordering::Equal,
+        });
+
+    result
+}

src/bin/main.rs

@@ -52,7 +52,7 @@ esp_bootloader_esp_idf::esp_app_desc!();
 )]
 #[esp_rtos::main]
 async fn main(spawner: Spawner) {
-    esp_println::logger::init_logger_from_env();
+    creaturedex::logging::init();
 
     let config = esp_hal::Config::default().with_cpu_clock(CpuClock::max());
     let peripherals = esp_hal::init(config);
@@ -64,7 +64,9 @@ async fn main(spawner: Spawner) {
     let timg0 = TimerGroup::new(peripherals.TIMG0);
     esp_rtos::start(timg0.timer0, sw_interrupt.software_interrupt0);
 
-    let (primary, mut secondaries) = spi_bus::DisplayPinConfiguration {
+    let (primary, mut secondaries) = retry(
+        5,
+        spi_bus::DisplayPinConfiguration {
             spi_peripheral: peripherals.SPI2,
             sck: peripherals.GPIO36,
             mosi: peripherals.GPIO35,
@@ -76,25 +78,33 @@ async fn main(spawner: Spawner) {
             reset_primary: peripherals.GPIO10,
             reset_secondary: peripherals.GPIO47,
             dc_pin: peripherals.GPIO12,
-    }
+        },
-    .build();
+        spi_bus::DisplayPinConfiguration::build,
+    );
 
     // Initialize the shared I2C bus using the refactored i2c_bus module.
     let shared_i2c = {
-        let config = I2cBusPinConfiguration {
+        use alloc::boxed::Box;
+        let bus = retry(5, I2cBusPinConfiguration {
             i2c_peripheral: peripherals.I2C0,
             scl: peripherals.GPIO18,
             sda: peripherals.GPIO17,
-        };
+        }, I2cBusPinConfiguration::build);
-        config.build()
+        Box::leak(Box::new(bus))
     };
 
-    let mut lcd: TertiaryDisplay = TertiaryDisplayPinConfiguration { i2c: shared_i2c }.build();
+    let mut lcd: TertiaryDisplay = retry(
+        5,
+        TertiaryDisplayPinConfiguration { i2c: shared_i2c },
+        TertiaryDisplayPinConfiguration::build,
+    );
     lcd.load_charset(EXAMPLE).unwrap();
     let h = EXAMPLE[HEART];
     let e = EXAMPLE[EMPTY];
     let b = EXAMPLE[BOX];
-    if let Err(e) = lcd.write(&alloc::format!("Custom symbols: {h}{e}{b} And more stuff to wrap and cut off please.")) {
+    if let Err(e) = lcd.write(&alloc::format!(
+        "Custom symbols: {h}{e}{b} And more stuff to wrap and cut off please."
+    )) {
         log::error!(
             "Tertiary LCD startup text write failed over shared I2C bus; check the shared bus, wiring, and device responses: {e}"
         );
@@ -138,6 +148,7 @@ async fn main(spawner: Spawner) {
     log::info!("Setup complete, entering main loop");
     spawner.spawn(navigation::run(inputs, outputs).expect("run task failed"));
     spawner.spawn(background_tasks::nfc_scanner(nfc_driver).expect("nfc scanner task failed"));
+    core::future::pending::<()>().await
 }
 
 fn display_shit(oled: &mut SecondaryDisplay<'static>, text: &str) {
@@ -149,3 +160,17 @@ fn display_shit(oled: &mut SecondaryDisplay<'static>, text: &str) {
         .unwrap();
     oled.flush().unwrap();
 }
+
+fn retry<T, U, F: FnMut(T) -> Result<U, T>>(repetitions: u32, input: T, mut action: F) -> U {
+    let mut initial_state = input;
+    for iteration in 0..repetitions {
+        log::debug!("Trying to initialize. Retries: {iteration}");
+
+        match action(initial_state) {
+            Ok(success) => return success,
+            Err(recovered_input) => initial_state = recovered_input,
+        }
+    }
+
+    panic!("Init failed after {repetitions} retries.")
+}

src/drivers/i2c_bus.rs

@@ -1,4 +1,3 @@
-use alloc::boxed::Box;
 use embedded_hal_bus::i2c::AtomicDevice;
 use embedded_hal_bus::util::AtomicCell;
 use esp_hal::gpio::interconnect::PeripheralInput;
@@ -21,18 +20,19 @@ where
     SCL: PeripheralOutput<'a> + PeripheralInput<'a>,
     SDA: PeripheralOutput<'a> + PeripheralInput<'a>,
 {
-    pub fn build(self) -> I2cBus<'a> {
+    pub fn build(self) -> Result<AtomicCell<InnerI2cBus<'a>>, Self> {
         let config = Config::default().with_frequency(esp_hal::time::Rate::from_khz(400));
-        let i2c = match I2c::new(self.i2c_peripheral, config) {
+        match I2c::new(self.i2c_peripheral, config) {
-            Ok(bus) => bus.with_sda(self.sda).with_scl(self.scl),
+            Ok(bus) => {
+                let i2c = bus.with_sda(self.sda).with_scl(self.scl);
+                log::info!("Shared I2C bus ready on GPIO17 (SDA) and GPIO18 (SCL)");
+                Ok(AtomicCell::new(i2c))
+            }
             Err(e) => {
                 log::error!("Shared I2C bus initialization failed for GPIO17/GPIO18: {e:?}");
-                panic!("Shared I2C bus initialization failed");
+                unimplemented!("Partial move makes it impossible to retry.");
-            }
+                // Err(self)
-        };
+            }
-        let shared_i2c = Box::leak(Box::new(AtomicCell::new(i2c)));
+        }
-        log::info!("Shared I2C bus ready on GPIO17 (SDA) and GPIO18 (SCL)");
-
-        shared_i2c
     }
 }

src/drivers/spi_bus.rs

@@ -135,7 +135,7 @@ where
     RES2: OutputPin + 'static,
     DC: OutputPin + 'static,
 {
-    pub fn build(self) -> (PrimaryDisplay<'static>, [SecondaryDisplay<'static>; 3]) {
+    pub fn build(self) -> Result<(PrimaryDisplay<'static>, [SecondaryDisplay<'static>; 3]), Self> {
         let spi = Spi::new(
             self.spi_peripheral,
             SpiConfig::default()
@@ -178,7 +178,7 @@ where
         }
         .build();
 
-        (primary, secondaries)
+        Ok((primary, secondaries))
     }
 }
 

src/drivers/tertiary_lcd.rs

@@ -15,19 +15,20 @@ pub struct TertiaryDisplayPinConfiguration<'a> {
 }
 
 impl<'a> TertiaryDisplayPinConfiguration<'a> {
-    pub fn build(self) -> TertiaryDisplay<'a> {
+    pub fn build(self) -> Result<TertiaryDisplay<'a>, Self> {
         let device = AtomicDevice::new(self.i2c);
         let mut lcd = CharacterDisplayPCF8574T::new(device, LcdDisplayType::Lcd16x2, Delay::new());
         match lcd.init() {
             Ok(()) => {
                 log::info!("I2C tertiary LCD initialized on PCF8574T at address 0x27");
-                TertiaryDisplay {
+                Ok(TertiaryDisplay {
                     display: lcd,
                     charset: create_custom_char_set!(),
-                }
+                })
             }
             Err(e) => {
-                panic!("I2C tertiary LCD init failed on PCF8574T at address 0x27: {e}");
+                log::error!("I2C tertiary LCD init failed on PCF8574T at address 0x27: {e}");
+                Err(self)
             }
         }
     }
@@ -407,4 +408,3 @@ pub const BOX: CharMap = [
 ];
 
 pub const EXAMPLE: CustomCharset = create_custom_char_set!(HEART, BOX, EMPTY);
-

src/lib.rs

@@ -6,6 +6,7 @@ pub mod background_tasks;
 pub mod card;
 pub mod display;
 pub mod drivers;
+pub mod logging;
 pub mod navigation;
 pub mod network;
 pub mod storage;

src/logging.rs

@@ -0,0 +1,83 @@
+mod logging_config {
+    include!(concat!(env!("OUT_DIR"), "/log_filter.rs"));
+}
+
+struct EnvLogger;
+
+impl log::Log for EnvLogger {
+    fn enabled(&self, metadata: &log::Metadata) -> bool {
+        let level = metadata.level();
+        let target = metadata.target();
+        logging_config::is_enabled(level, target)
+    }
+
+    fn log(&self, record: &log::Record) {
+        if !self.enabled(record.metadata()) {
+            return;
+        }
+
+        // print with color? default to true if env var unset or set but empty.
+        let with_color = 1
+            == option_env!("ESP_LOG_COLOR")
+                .unwrap_or("1")
+                .parse()
+                .unwrap_or(1);
+        let (color, reset) = if with_color {
+            const RESET: &str = "\u{001B}[0m";
+            const RED: &str = "\u{001B}[31m";
+            const GREEN: &str = "\u{001B}[32m";
+            const YELLOW: &str = "\u{001B}[33m";
+            const BLUE: &str = "\u{001B}[34m";
+            const CYAN: &str = "\u{001B}[35m";
+
+            let color = match record.level() {
+                log::Level::Error => RED,
+                log::Level::Warn => YELLOW,
+                log::Level::Info => GREEN,
+                log::Level::Debug => BLUE,
+                log::Level::Trace => CYAN,
+            };
+            let reset = RESET;
+            (color, reset)
+        } else {
+            ("", "")
+        };
+
+        let [now_s, now_ms] = {
+            let now = esp_hal::time::Instant::now()
+                .duration_since_epoch()
+                .as_millis();
+
+            [now / 1000, now % 1000]
+        };
+
+        let level = match record.level() {
+            log::Level::Error => "E",
+            log::Level::Warn => "W",
+            log::Level::Info => "I",
+            log::Level::Debug => "D",
+            log::Level::Trace => "T",
+        };
+        let args = record.args();
+        let line = record.line().unwrap_or(0);
+        let target = record.target();
+        let module = record.module_path().unwrap_or("???");
+
+        let (module, divider) = if module == target {
+            ("", "")
+        } else {
+            (module, " ")
+        };
+
+        esp_println::println!(
+            "{color}{now_s:>4}.{now_ms:03}s {level} {target}{divider}{module}:{line} - {args}{reset}"
+        );
+    }
+
+    fn flush(&self) {}
+}
+
+pub fn init() {
+    log::set_logger(&EnvLogger).expect("Failed to init logger.");
+    log::set_max_level(logging_config::FILTER_MAX);
+}