diff --git a/.github/copilot-instructions.md b/.github/copilot-instructions.md index 5c1c99e97c..114afd1a21 100644 --- a/.github/copilot-instructions.md +++ b/.github/copilot-instructions.md @@ -332,6 +332,7 @@ firmware/ - Follow existing code style - run `trunk fmt` before commits - Prefer `LOG_DEBUG`, `LOG_INFO`, `LOG_WARN`, `LOG_ERROR` for logging +- **Three logging tiers for diagnostics.** `LOG_TRACE` is the per-packet/per-poll firehose - compiled out by default (`MESHTASTIC_TRACE_LOGGING=1` enables; always on for portduino). Subsystem bring-up detail routes through a per-subsystem gate macro instead, e.g. `LOG_DEBUG_GPS(...)` in `src/gps/GPSLog.h` (`GPS_DEBUG=1` enables; costs no flash when off) - model new subsystem gates on it or on `LOG_MIGRATION` (`src/mesh/WarmNodeStore.h`): `#ifndef` value-default, `#if SYM` value test, `((void)0)` off-branch. Genuine anomalies stay unconditional `LOG_WARN`/`LOG_ERROR`. - **Format node IDs and packet IDs as `0x%08x` in logs.** This covers `NodeNum`/`PacketId` and the `uint32_t` packet fields `from`, `to`, `id`, `dest`, `source`, `request_id`, and `node_id`. They are 32-bit, so 8 hex digits is exact - `%08x` never truncates or leaves a value ragged. Do **not** use `%x` (variable width) or `%0x` (a no-op typo for `%08x` - the `0` flag does nothing without a width). User-facing display uses `!%08x` (the `!xxxxxxxx` convention), e.g. `Applet::hexifyNodeNum`. - **Do not zero-pad one-byte values to 8.** `next_hop`, `relay_node`, and the next-hop hint are `uint8_t` last-byte route hints, and `channel` is a one-byte hash/index - log these as `0x%x` (or `%d`). Padding a byte to `0x000000ab` falsely implies a full node number. The same goes for I2C addresses, register values, flags/bitmasks, and error/reason codes: they are not IDs, so leave them `0x%x`. - Use `assert()` for invariants that should never fail diff --git a/src/DebugConfiguration.h b/src/DebugConfiguration.h index 65b258fc1b..247776a897 100644 --- a/src/DebugConfiguration.h +++ b/src/DebugConfiguration.h @@ -48,6 +48,16 @@ extern MemGet memGet; #define DEBUG_PORT (*console) // Serial debug port +// LOG_TRACE costs no flash unless enabled: -DMESHTASTIC_TRACE_LOGGING(=1) turns it on, =0 forces it off. +// Default is on only for portduino (traceFilename packet traces, logoutputlevel=trace), off elsewhere. +#ifndef MESHTASTIC_TRACE_LOGGING +#ifdef ARCH_PORTDUINO +#define MESHTASTIC_TRACE_LOGGING 1 +#else +#define MESHTASTIC_TRACE_LOGGING 0 +#endif +#endif + #ifdef USE_SEGGER // #undef DEBUG_PORT #define LOG_DEBUG(...) SEGGER_RTT_printf(0, __VA_ARGS__) @@ -55,16 +65,24 @@ extern MemGet memGet; #define LOG_WARN(...) SEGGER_RTT_printf(0, __VA_ARGS__) #define LOG_ERROR(...) SEGGER_RTT_printf(0, __VA_ARGS__) #define LOG_CRIT(...) SEGGER_RTT_printf(0, __VA_ARGS__) +#if MESHTASTIC_TRACE_LOGGING #define LOG_TRACE(...) SEGGER_RTT_printf(0, __VA_ARGS__) #else +#define LOG_TRACE(...) +#endif +#else #if defined(DEBUG_PORT) && !defined(DEBUG_MUTE) #define LOG_DEBUG(...) DEBUG_PORT.log(MESHTASTIC_LOG_LEVEL_DEBUG, __VA_ARGS__) #define LOG_INFO(...) DEBUG_PORT.log(MESHTASTIC_LOG_LEVEL_INFO, __VA_ARGS__) #define LOG_WARN(...) DEBUG_PORT.log(MESHTASTIC_LOG_LEVEL_WARN, __VA_ARGS__) #define LOG_ERROR(...) DEBUG_PORT.log(MESHTASTIC_LOG_LEVEL_ERROR, __VA_ARGS__) #define LOG_CRIT(...) DEBUG_PORT.log(MESHTASTIC_LOG_LEVEL_CRIT, __VA_ARGS__) +#if MESHTASTIC_TRACE_LOGGING #define LOG_TRACE(...) DEBUG_PORT.log(MESHTASTIC_LOG_LEVEL_TRACE, __VA_ARGS__) #else +#define LOG_TRACE(...) +#endif +#else #define LOG_DEBUG(...) #define LOG_INFO(...) #define LOG_WARN(...) diff --git a/src/FSCommon.cpp b/src/FSCommon.cpp index 38b704e738..c00b07684b 100644 --- a/src/FSCommon.cpp +++ b/src/FSCommon.cpp @@ -340,7 +340,7 @@ void listDir(const char *dirname, uint8_t levels, bool del) file.close(); FSCom.remove(buffer); } else { - LOG_DEBUG(" %s (%i Bytes)", filepath, file.size()); + LOG_TRACE(" %s (%i Bytes)", filepath, file.size()); file.close(); } } @@ -394,7 +394,7 @@ void fsInit() #if defined(ARCH_ESP32) LOG_DEBUG("Filesystem files (%d/%d Bytes):", FSCom.usedBytes(), FSCom.totalBytes()); #else - LOG_DEBUG("Filesystem files:"); + LOG_TRACE("Filesystem files:"); #endif listDir("/", 10); #endif diff --git a/src/GPSStatus.h b/src/GPSStatus.h index 2a384c8b5c..e9f7325c87 100644 --- a/src/GPSStatus.h +++ b/src/GPSStatus.h @@ -2,6 +2,7 @@ #include "NodeDB.h" #include "Status.h" #include "configuration.h" +#include "gps/GPSLog.h" #include namespace meshtastic @@ -92,9 +93,7 @@ class GPSStatus : public Status bool matches(const GPSStatus *newStatus) const { -#ifdef GPS_DEBUG - LOG_DEBUG("GPSStatus.match() new pos@%x to old pos@%x", newStatus->p.timestamp, p.timestamp); -#endif + LOG_DEBUG_GPS("GPSStatus.match() new pos@%x to old pos@%x", newStatus->p.timestamp, p.timestamp); return (newStatus->hasLock != hasLock || newStatus->isConnected != isConnected || newStatus->hasTime != hasTime || newStatus->isPowerSaving != isPowerSaving || newStatus->p.latitude_i != p.latitude_i || newStatus->p.longitude_i != p.longitude_i || newStatus->p.altitude != p.altitude || diff --git a/src/Power.cpp b/src/Power.cpp index 2a0938e2ad..d347e7f931 100644 --- a/src/Power.cpp +++ b/src/Power.cpp @@ -606,7 +606,7 @@ class AnalogBatteryLevel : public HasBatteryLevel // get current flow from INA sensor - negative value means power flowing // into the battery default assuming BATTERY+ <--> INA_VIN+ <--> SHUNT // RESISTOR <--> INA_VIN- <--> LOAD - LOG_DEBUG("Using INA on I2C addr 0x%x for charging detection", config.power.device_battery_ina_address); + LOG_TRACE("Using INA on I2C addr 0x%x for charging detection", config.power.device_battery_ina_address); #if defined(INA_CHARGING_DETECTION_INVERT) return getINACurrent() > 0; #else @@ -1881,10 +1881,10 @@ class LipoCharger : public HasBatteryLevel bool isCharging = PPM->isCharging(); if (bq) { if (isCharging) { - LOG_DEBUG("BQ27220 time to full charge: %d min", bq->getTimeToFull()); + LOG_TRACE("BQ27220 time to full charge: %d min", bq->getTimeToFull()); } else { if (!PPM->isVbusIn()) { - LOG_DEBUG("BQ27220 time to empty: %d min (%d mAh)", bq->getTimeToEmpty(), bq->getRemainingCapacity()); + LOG_TRACE("BQ27220 time to empty: %d min (%d mAh)", bq->getTimeToEmpty(), bq->getRemainingCapacity()); } } } diff --git a/src/detect/ReClockI2C.h b/src/detect/ReClockI2C.h index 503f1a48b1..24a166d53f 100644 --- a/src/detect/ReClockI2C.h +++ b/src/detect/ReClockI2C.h @@ -35,20 +35,20 @@ class ReClockI2C uint32_t currentClock = this->getClock(); if (currentClock) { - LOG_DEBUG("Current I2C frequency: %uHz", currentClock); + LOG_TRACE("Current I2C frequency: %uHz", currentClock); } if (currentClock != desiredClock) { - LOG_DEBUG("Changing I2C clock to %uHz", desiredClock); + LOG_TRACE("Changing I2C clock to %uHz", desiredClock); this->i2cBus->setClock(desiredClock); // If the clock is 0Hz, we still store it // We'll check in restoreClock function setPreviousClock(currentClock); - LOG_DEBUG("Stored previous clock I2C clock: %uHz", this->previousClock); + LOG_TRACE("Stored previous clock I2C clock: %uHz", this->previousClock); return true; } - LOG_DEBUG("I2C clock was already %uHz. Skipping", desiredClock); + LOG_TRACE("I2C clock was already %uHz. Skipping", desiredClock); setPreviousClock(0); return false; } @@ -56,12 +56,12 @@ class ReClockI2C bool restoreClock() { if (this->previousClock) { - LOG_DEBUG("Restoring I2C clock to %uHz", this->previousClock); + LOG_TRACE("Restoring I2C clock to %uHz", this->previousClock); i2cBus->setClock(this->previousClock); setPreviousClock(0); return true; } - LOG_DEBUG("I2C clock was unknown. Not restored"); + LOG_TRACE("I2C clock was unknown. Not restored"); return false; } diff --git a/src/gps/GPS.cpp b/src/gps/GPS.cpp index 0a8c7252cf..fd5be417e7 100644 --- a/src/gps/GPS.cpp +++ b/src/gps/GPS.cpp @@ -5,6 +5,7 @@ #if !MESHTASTIC_EXCLUDE_GPS #include "Default.h" #include "GPS.h" +#include "GPSLog.h" #include "GpioLogic.h" #include "NodeDB.h" #include "PowerMon.h" @@ -337,7 +338,7 @@ uint8_t GPS::makeCASPacket(uint8_t class_id, uint8_t msg_id, uint8_t payload_siz } CASChecksum(UBXscratch, (payload_size + 10)); -#if defined(GPS_DEBUG) && defined(DEBUG_PORT) +#if GPS_DEBUG && defined(DEBUG_PORT) LOG_DEBUG("CAS packet: "); DEBUG_PORT.hexDump(MESHTASTIC_LOG_LEVEL_DEBUG, UBXscratch, payload_size + 10); #endif @@ -350,26 +351,22 @@ GPS_RESPONSE GPS::getACK(const char *message, uint32_t waitMillis) uint8_t b; int bytesRead = 0; uint32_t startTimeout = millis() + waitMillis; -#ifdef GPS_DEBUG +#if GPS_DEBUG std::string debugmsg = ""; #endif while (millis() < startTimeout) { if (_serial_gps->available()) { b = _serial_gps->read(); -#ifdef GPS_DEBUG +#if GPS_DEBUG debugmsg += vformat("%c", (b >= 32 && b <= 126) ? b : '.'); #endif buffer[bytesRead] = b; bytesRead++; if ((bytesRead == 767) || (b == '\r')) { -#ifdef GPS_DEBUG - LOG_DEBUG(debugmsg.c_str()); -#endif + LOG_DEBUG_GPS("%s", debugmsg.c_str()); if (strnstr((char *)buffer, message, bytesRead) != nullptr) { -#ifdef GPS_DEBUG - LOG_DEBUG("Found: %s", message); // Log the found message -#endif + LOG_DEBUG_GPS("Found: %s", message); // Log the found message return GNSS_RESPONSE_OK; } else { bytesRead = 0; @@ -418,17 +415,13 @@ GPS_RESPONSE GPS::getACKCas(uint8_t class_id, uint8_t msg_id, uint32_t waitMilli // Check for an ACK-ACK for the specified class and message id if ((msg_cls == 0x05) && (msg_msg_id == 0x01) && payload_cls == class_id && payload_msg == msg_id) { -#ifdef GPS_DEBUG - LOG_INFO("Got ACK for class %02X msg %02X in %dms", class_id, msg_id, millis() - startTime); -#endif + LOG_DEBUG_GPS("Got ACK for class %02X msg %02X in %dms", class_id, msg_id, millis() - startTime); return GNSS_RESPONSE_OK; } // Check for an ACK-NACK for the specified class and message id if ((msg_cls == 0x05) && (msg_msg_id == 0x00) && payload_cls == class_id && payload_msg == msg_id) { -#ifdef GPS_DEBUG - LOG_WARN("Got NACK for class %02X msg %02X in %dms", class_id, msg_id, millis() - startTime); -#endif + LOG_DEBUG_GPS("Got NACK for class %02X msg %02X in %dms", class_id, msg_id, millis() - startTime); return GNSS_RESPONSE_NAK; } @@ -450,7 +443,7 @@ GPS_RESPONSE GPS::getACK(uint8_t class_id, uint8_t msg_id, uint32_t waitMillis) uint32_t startTime = millis(); const char frame_errors[] = "More than 100 frame errors"; int sCounter = 0; -#ifdef GPS_DEBUG +#if GPS_DEBUG std::string debugmsg = ""; #endif @@ -467,9 +460,7 @@ GPS_RESPONSE GPS::getACK(uint8_t class_id, uint8_t msg_id, uint32_t waitMillis) while (Throttle::isWithinTimespanMs(startTime, waitMillis)) { if (ack > 9) { -#ifdef GPS_DEBUG - LOG_INFO("Got ACK for class %02X msg %02X in %dms", class_id, msg_id, millis() - startTime); -#endif + LOG_DEBUG_GPS("Got ACK for class %02X msg %02X in %dms", class_id, msg_id, millis() - startTime); return GNSS_RESPONSE_OK; // ACK received } if (_serial_gps->available()) { @@ -477,25 +468,20 @@ GPS_RESPONSE GPS::getACK(uint8_t class_id, uint8_t msg_id, uint32_t waitMillis) if (b == frame_errors[sCounter]) { sCounter++; if (sCounter == 26) { -#ifdef GPS_DEBUG - - LOG_DEBUG(debugmsg.c_str()); -#endif + LOG_DEBUG_GPS("%s", debugmsg.c_str()); return GNSS_RESPONSE_FRAME_ERRORS; } } else { sCounter = 0; } -#ifdef GPS_DEBUG +#if GPS_DEBUG debugmsg += vformat("%02X", b); #endif if (b == buf[ack]) { ack++; } else { if (ack == 3 && b == 0x00) { // UBX-ACK-NAK message -#ifdef GPS_DEBUG - LOG_DEBUG(debugmsg.c_str()); -#endif + LOG_DEBUG_GPS("%s", debugmsg.c_str()); LOG_WARN("Got NAK for class %02X msg %02X", class_id, msg_id); return GNSS_RESPONSE_NAK; // NAK received } @@ -503,10 +489,8 @@ GPS_RESPONSE GPS::getACK(uint8_t class_id, uint8_t msg_id, uint32_t waitMillis) } } } -#ifdef GPS_DEBUG - LOG_DEBUG(debugmsg.c_str()); - LOG_WARN("No response for class %02X msg %02X", class_id, msg_id); -#endif + LOG_DEBUG_GPS("%s", debugmsg.c_str()); + LOG_DEBUG_GPS("No response for class %02X msg %02X", class_id, msg_id); return GNSS_RESPONSE_NONE; // No response received within timeout } @@ -577,9 +561,7 @@ int GPS::getACK(uint8_t *buffer, uint16_t size, uint8_t requestedClass, uint8_t ubxFrameCounter = 0; } else { // return payload length -#ifdef GPS_DEBUG - LOG_INFO("Got ACK for class %02X msg %02X in %dms", requestedClass, requestedID, millis() - startTime); -#endif + LOG_DEBUG_GPS("Got ACK for class %02X msg %02X in %dms", requestedClass, requestedID, millis() - startTime); return needRead; } break; @@ -1234,9 +1216,7 @@ void GPS::writePinEN(bool on) // Write and log enablePin->set(on); -#ifdef GPS_DEBUG - LOG_DEBUG("Pin EN %s", on == HIGH ? "HI" : "LOW"); -#endif + LOG_DEBUG_GPS("Pin EN %s", on == HIGH ? "HI" : "LOW"); } // Set the value of the STANDBY pin, if relevant @@ -1259,9 +1239,7 @@ void GPS::writePinStandby(bool standby) _serial_gps->write("$PMTK225,4*2F\r\n"); } -#ifdef GPS_DEBUG - LOG_DEBUG("Pin STANDBY %s", val == HIGH ? "HI" : "LOW"); -#endif + LOG_DEBUG_GPS("Pin STANDBY %s", val == HIGH ? "HI" : "LOW"); #endif } @@ -1272,9 +1250,7 @@ void GPS::writePinRFEN(bool on) bool val = on ? GPS_RF_EN_ACTIVE : !GPS_RF_EN_ACTIVE; pinMode(PIN_GPS_RF_EN, OUTPUT); digitalWrite(PIN_GPS_RF_EN, val); -#ifdef GPS_DEBUG - LOG_DEBUG("Pin RF EN %s", val == HIGH ? "HI" : "LOW"); -#endif + LOG_DEBUG_GPS("Pin RF EN %s", val == HIGH ? "HI" : "LOW"); #else (void)on; #endif @@ -1310,9 +1286,7 @@ void GPS::setPowerPMU(bool on) // t-beam v1.1 GNSS power channel on ? PMU->enablePowerOutput(XPOWERS_LDO3) : PMU->disablePowerOutput(XPOWERS_LDO3); } -#ifdef GPS_DEBUG - LOG_DEBUG("PMU %s", on ? "on" : "off"); -#endif + LOG_DEBUG_GPS("PMU %s", on ? "on" : "off"); #endif } @@ -1358,9 +1332,7 @@ void GPS::setPowerUBLOX(bool on, uint32_t sleepMs) // Send the UBX packet gps->_serial_gps->write(gps->UBXscratch, msglen); -#ifdef GPS_DEBUG - LOG_DEBUG("UBLOX: sleep for %dmS", sleepMs); -#endif + LOG_DEBUG_GPS("UBLOX: sleep for %dmS", sleepMs); } } @@ -1546,7 +1518,7 @@ int32_t GPS::runOnce() // 2. Got a lock for the first time, or 3. Got a lock after turning back on bool gotLoc = lookForLocation(); if (gotLoc) { -#ifdef GPS_DEBUG +#if GPS_DEBUG if (!hasValidLocation) { // declare that we have location ASAP LOG_DEBUG("hasValidLocation RISING EDGE"); } @@ -1561,9 +1533,7 @@ int32_t GPS::runOnce() if (holdTime > GPS_FIX_HOLD_MAX_MS) holdTime = GPS_FIX_HOLD_MAX_MS; fixHoldEnds = millis() + holdTime; -#ifdef GPS_DEBUG - LOG_DEBUG("Holding for %ums after lock", holdTime); -#endif + LOG_DEBUG_GPS("Holding for %ums after lock", holdTime); } } @@ -1575,9 +1545,7 @@ int32_t GPS::runOnce() p = meshtastic_Position_init_default; hasValidLocation = false; shouldPublish = true; -#ifdef GPS_DEBUG - LOG_DEBUG("hasValidLocation FALLING EDGE"); -#endif + LOG_DEBUG_GPS("hasValidLocation FALLING EDGE"); } } @@ -1597,7 +1565,7 @@ int32_t GPS::runOnce() down(); } -#ifdef GPS_DEBUG +#if GPS_DEBUG } else if (fixHoldEnds != 0) { LOG_DEBUG("Holding for GPS data download: %d ms (numSats=%d)", fixHoldEnds - millis(), p.sats_in_view); #endif @@ -1824,7 +1792,6 @@ GnssModel_t GPS::probe(int serialSpeed) break; } - LOG_DEBUG("Module Info : "); LOG_DEBUG("Soft version: %s", ublox_info.swVersion); LOG_DEBUG("Hard version: %s", ublox_info.hwVersion); LOG_DEBUG("Extensions:%d", ublox_info.extensionNo); @@ -1904,27 +1871,21 @@ GnssModel_t GPS::getProbeResponse(unsigned long timeout, const std::vector= 2 && response[responseLen - 2] == '\r' && response[responseLen - 1] == '\n') { -#ifdef GPS_DEBUG - LOG_DEBUG(response.get()); -#endif + LOG_DEBUG_GPS("%s", response.get()); // Reset the response buffer for the next potential message responseLen = 0; response[0] = '\0'; } } } -#ifdef GPS_DEBUG - LOG_DEBUG(response.get()); -#endif + LOG_DEBUG_GPS("%s", response.get()); return GNSS_MODEL_UNKNOWN; // Return unknown on timeout } @@ -2125,7 +2086,7 @@ bool GPS::lookForLocation() #ifndef TINYGPS_OPTION_NO_STATISTICS if (reader.failedChecksum() > lastChecksumFailCount) { // In a GPS_DEBUG build we want to log all of these. In production, we only care if there are many of them. -#ifndef GPS_DEBUG +#if !GPS_DEBUG if (reader.failedChecksum() > 4) #endif LOG_WARN("%u new GPS checksum failures, total %u", reader.failedChecksum() - lastChecksumFailCount, @@ -2142,7 +2103,7 @@ bool GPS::lookForLocation() if (!hasLock()) return false; -#ifdef GPS_DEBUG +#if GPS_DEBUG LOG_DEBUG("AGE: LOC=%d FIX=%d DATE=%d TIME=%d", reader.location.age(), #ifndef TINYGPS_OPTION_NO_CUSTOM_FIELDS gsafixtype.age(), @@ -2173,15 +2134,11 @@ bool GPS::lookForLocation() // Bail out EARLY to avoid overwriting previous good data (like #857) if (toDegInt(loc.lat) > 900000000) { -#ifdef GPS_DEBUG - LOG_DEBUG("Bail out EARLY on LAT %i", toDegInt(loc.lat)); -#endif + LOG_DEBUG_GPS("Bail out EARLY on LAT %i", toDegInt(loc.lat)); return false; } if (toDegInt(loc.lng) > 1800000000) { -#ifdef GPS_DEBUG - LOG_DEBUG("Bail out EARLY on LNG %i", toDegInt(loc.lng)); -#endif + LOG_DEBUG_GPS("Bail out EARLY on LNG %i", toDegInt(loc.lng)); return false; } @@ -2266,7 +2223,7 @@ bool GPS::whileActive() { unsigned int charsInBuf = 0; bool isValid = false; -#ifdef GPS_DEBUG +#if GPS_DEBUG std::string debugmsg = ""; #endif if (powerState != GPS_ACTIVE) { @@ -2283,7 +2240,7 @@ bool GPS::whileActive() while (_serial_gps->available() > 0) { int c = _serial_gps->read(); UBXscratch[charsInBuf] = c; -#ifdef GPS_DEBUG +#if GPS_DEBUG debugmsg += vformat("%c", (c >= 32 && c <= 126) ? c : '.'); #endif isValid |= reader.encode(c); @@ -2296,9 +2253,9 @@ bool GPS::whileActive() charsInBuf++; } } -#ifdef GPS_DEBUG +#if GPS_DEBUG if (debugmsg != "") { - LOG_DEBUG(debugmsg.c_str()); + LOG_DEBUG("%s", debugmsg.c_str()); } #endif return isValid; diff --git a/src/gps/GPSLog.h b/src/gps/GPSLog.h new file mode 100644 index 0000000000..9ee85096d9 --- /dev/null +++ b/src/gps/GPSLog.h @@ -0,0 +1,14 @@ +#pragma once + +#include "DebugConfiguration.h" + +// GPS_DEBUG=1 enables verbose GNSS diagnostics (probe/ACK byte dumps, pin states, NMEA ages). +// Costs no flash when off. Genuine LOG_WARN anomalies stay unconditional. +#ifndef GPS_DEBUG +#define GPS_DEBUG 0 +#endif +#if GPS_DEBUG +#define LOG_DEBUG_GPS(...) LOG_DEBUG(__VA_ARGS__) +#else +#define LOG_DEBUG_GPS(...) ((void)0) +#endif diff --git a/src/gps/RTC.cpp b/src/gps/RTC.cpp index 5e65ac8adc..99153e764f 100644 --- a/src/gps/RTC.cpp +++ b/src/gps/RTC.cpp @@ -2,6 +2,7 @@ #include "configuration.h" #include "detect/ScanI2C.h" #include "detect/ScanI2CTwoWire.h" +#include "gps/GPSLog.h" #include "main.h" #include "mesh/MeshService.h" #include "modules/NodeInfoModule.h" @@ -127,8 +128,8 @@ RTCSetResult readFromRTC() } #endif - LOG_DEBUG("RTC time from RV3028 getTime: %02d-%02d-%02d %02d:%02d:%02d (%ld)", t.tm_year + 1900, t.tm_mon + 1, t.tm_mday, - t.tm_hour, t.tm_min, t.tm_sec, printableEpoch); + LOG_DEBUG_GPS("RTC time from RV3028 getTime: %02d-%02d-%02d %02d:%02d:%02d (%ld)", t.tm_year + 1900, t.tm_mon + 1, + t.tm_mday, t.tm_hour, t.tm_min, t.tm_sec, printableEpoch); if (currentQuality == RTCQualityNone) { RTCQuality oldQuality = currentQuality; timeStartMsec = now; @@ -173,8 +174,8 @@ RTCSetResult readFromRTC() } #endif - LOG_DEBUG("RTC time from %s getDateTime: %02d-%02d-%02d %02d:%02d:%02d (%ld)", rtc.getChipName(), t.tm_year + 1900, - t.tm_mon + 1, t.tm_mday, t.tm_hour, t.tm_min, t.tm_sec, printableEpoch); + LOG_DEBUG_GPS("RTC time from %s getDateTime: %02d-%02d-%02d %02d:%02d:%02d (%ld)", rtc.getChipName(), t.tm_year + 1900, + t.tm_mon + 1, t.tm_mday, t.tm_hour, t.tm_min, t.tm_sec, printableEpoch); if (currentQuality == RTCQualityNone) { RTCQuality oldQuality = currentQuality; timeStartMsec = now; @@ -200,8 +201,8 @@ RTCSetResult readFromRTC() tv.tv_usec = 0; uint32_t printableEpoch = tv.tv_sec; // Print lib only supports 32 bit but time_t can be 64 bit on some platforms - LOG_DEBUG("RTC time from RX8130CE getDateTime: %02d-%02d-%02d %02d:%02d:%02d (%ld)", t.tm_year + 1900, t.tm_mon + 1, - t.tm_mday, t.tm_hour, t.tm_min, t.tm_sec, printableEpoch); + LOG_DEBUG_GPS("RTC time from RX8130CE getDateTime: %02d-%02d-%02d %02d:%02d:%02d (%ld)", t.tm_year + 1900, + t.tm_mon + 1, t.tm_mday, t.tm_hour, t.tm_min, t.tm_sec, printableEpoch); #ifdef BUILD_EPOCH if (tv.tv_sec < BUILD_EPOCH) { if (Throttle::isWithinTimespanMs(lastTimeValidationWarning, TIME_VALIDATION_WARNING_INTERVAL_MS) == false) { @@ -294,14 +295,14 @@ RTCSetResult perhapsSetRTC(RTCQuality q, const struct timeval *tv, bool forceUpd LOG_DEBUG("Upgrade time to quality %s", RtcName(q)); } else if (q == RTCQualityGPS) { shouldSet = true; - LOG_DEBUG("Reapply GPS time: %ld secs", printableEpoch); + LOG_DEBUG_GPS("Reapply GPS time: %ld secs", printableEpoch); } else if (q == RTCQualityNTP && !Throttle::isWithinTimespanMs(lastSetMsec, (30 * 60 * 1000UL))) { // Every 30 minutes we will slam in a new NTP or Phone GPS / NTP time, to correct for local RTC clock drift shouldSet = true; - LOG_DEBUG("Reapply external time to fix clock drift %ld secs", printableEpoch); + LOG_DEBUG_GPS("Reapply external time to fix clock drift %ld secs", printableEpoch); } else { shouldSet = false; - LOG_DEBUG("RTC quality: %s. Ignore time of quality %s", RtcName(currentQuality), RtcName(q)); + LOG_DEBUG_GPS("RTC quality: %s. Ignore time of quality %s", RtcName(currentQuality), RtcName(q)); } if (shouldSet) { @@ -327,10 +328,10 @@ RTCSetResult perhapsSetRTC(RTCQuality q, const struct timeval *tv, bool forceUpd // tv_sec is a long, which is not time_t everywhere: on Windows // time_t is 64-bit while long is 32-bit. Copy before taking &. time_t setSecs = tv->tv_sec; - tm *t = gmtime(&setSecs); + const tm *t = gmtime(&setSecs); rtc.setTime(t->tm_year + 1900, t->tm_mon + 1, t->tm_wday, t->tm_mday, t->tm_hour, t->tm_min, t->tm_sec); - LOG_DEBUG("RV3028_RTC setTime %02d-%02d-%02d %02d:%02d:%02d (%ld)", t->tm_year + 1900, t->tm_mon + 1, t->tm_mday, - t->tm_hour, t->tm_min, t->tm_sec, printableEpoch); + LOG_DEBUG_GPS("RV3028_RTC setTime %02d-%02d-%02d %02d:%02d:%02d (%ld)", t->tm_year + 1900, t->tm_mon + 1, t->tm_mday, + t->tm_hour, t->tm_min, t->tm_sec, printableEpoch); } else { LOG_WARN("RTC set: not found (addr 0x%02X)", rtc_found.address); } @@ -352,10 +353,10 @@ RTCSetResult perhapsSetRTC(RTCQuality q, const struct timeval *tv, bool forceUpd // tv_sec is a long, which is not time_t everywhere: on Windows // time_t is 64-bit while long is 32-bit. Copy before taking &. time_t setSecs = tv->tv_sec; - tm *t = gmtime(&setSecs); + const tm *t = gmtime(&setSecs); rtc.setDateTime(*t); - LOG_DEBUG("%s setDateTime %02d-%02d-%02d %02d:%02d:%02d (%ld)", rtc.getChipName(), t->tm_year + 1900, t->tm_mon + 1, - t->tm_mday, t->tm_hour, t->tm_min, t->tm_sec, printableEpoch); + LOG_DEBUG_GPS("%s setDateTime %02d-%02d-%02d %02d:%02d:%02d (%ld)", rtc.getChipName(), t->tm_year + 1900, + t->tm_mon + 1, t->tm_mday, t->tm_hour, t->tm_min, t->tm_sec, printableEpoch); } else { LOG_WARN("RTC set: not found (addr 0x%02X)", rtc_found.address); } @@ -369,10 +370,10 @@ RTCSetResult perhapsSetRTC(RTCQuality q, const struct timeval *tv, bool forceUpd // tv_sec is a long, which is not time_t everywhere: on Windows // time_t is 64-bit while long is 32-bit. Copy before taking &. time_t setSecs = tv->tv_sec; - tm *t = gmtime(&setSecs); + const tm *t = gmtime(&setSecs); if (rtc.setTime(*t)) { - LOG_DEBUG("RX8130CE setDateTime %02d-%02d-%02d %02d:%02d:%02d (%ld)", t->tm_year + 1900, t->tm_mon + 1, - t->tm_mday, t->tm_hour, t->tm_min, t->tm_sec, printableEpoch); + LOG_DEBUG_GPS("RX8130CE setDateTime %02d-%02d-%02d %02d:%02d:%02d (%ld)", t->tm_year + 1900, t->tm_mon + 1, + t->tm_mday, t->tm_hour, t->tm_min, t->tm_sec, printableEpoch); } else { LOG_WARN("RX8130CE set time failed"); } diff --git a/src/graphics/EInkDisplay2.cpp b/src/graphics/EInkDisplay2.cpp index a44e8ef4b3..dca31be605 100644 --- a/src/graphics/EInkDisplay2.cpp +++ b/src/graphics/EInkDisplay2.cpp @@ -99,7 +99,6 @@ bool EInkDisplay::forceDisplay(uint32_t msecLimit) // End the update process endUpdate(); - LOG_DEBUG("done"); return true; } diff --git a/src/graphics/EInkDynamicDisplay.cpp b/src/graphics/EInkDynamicDisplay.cpp index a48ba5c939..be05cd0c36 100644 --- a/src/graphics/EInkDynamicDisplay.cpp +++ b/src/graphics/EInkDynamicDisplay.cpp @@ -157,7 +157,7 @@ bool EInkDynamicDisplay::determineMode() resetRateLimiting(); // Once determineMode() ends, will have to wait again hashImage(); // Generate here, so we can still copy it to previousImageHash, even if we skip the comparison check - LOG_DEBUG("determineMode(): "); // Begin log entry + LOG_TRACE("determineMode(): "); // Begin log entry // Once mode determined, any remaining checks will bypass checkCosmetic(); @@ -254,7 +254,7 @@ void EInkDynamicDisplay::checkRateLimiting() if (Throttle::isWithinTimespanMs(previousRunMs, 1000)) { refresh = SKIPPED; reason = EXCEEDED_RATELIMIT_FAST; - LOG_DEBUG("refresh=SKIPPED, reason=EXCEEDED_RATELIMIT_FAST, frameFlags=0x%x", frameFlags); + LOG_TRACE("refresh=SKIPPED, reason=EXCEEDED_RATELIMIT_FAST, frameFlags=0x%x", frameFlags); return; } } @@ -271,7 +271,7 @@ void EInkDynamicDisplay::checkCosmetic() if (frameFlags & COSMETIC) { refresh = FULL; reason = FLAGGED_COSMETIC; - LOG_DEBUG("refresh=FULL, reason=FLAGGED_COSMETIC, frameFlags=0x%x", frameFlags); + LOG_TRACE("refresh=FULL, reason=FLAGGED_COSMETIC, frameFlags=0x%x", frameFlags); } } @@ -286,7 +286,7 @@ void EInkDynamicDisplay::checkDemandingFast() if (frameFlags & DEMAND_FAST) { refresh = FAST; reason = FLAGGED_DEMAND_FAST; - LOG_DEBUG("refresh=FAST, reason=FLAGGED_DEMAND_FAST, frameFlags=0x%x", frameFlags); + LOG_TRACE("refresh=FAST, reason=FLAGGED_DEMAND_FAST, frameFlags=0x%x", frameFlags); } } @@ -306,7 +306,7 @@ void EInkDynamicDisplay::checkFrameMatchesPrevious() if (frameFlags == BACKGROUND && fastRefreshCount > 0) { refresh = FULL; reason = REDRAW_WITH_FULL; - LOG_DEBUG("refresh=FULL, reason=REDRAW_WITH_FULL, frameFlags=0x%x", frameFlags); + LOG_TRACE("refresh=FULL, reason=REDRAW_WITH_FULL, frameFlags=0x%x", frameFlags); return; } #endif @@ -314,7 +314,7 @@ void EInkDynamicDisplay::checkFrameMatchesPrevious() // Not redrawn, not COSMETIC, not DEMAND_FAST refresh = SKIPPED; reason = FRAME_MATCHED_PREVIOUS; - LOG_DEBUG("refresh=SKIPPED, reason=FRAME_MATCHED_PREVIOUS, frameFlags=0x%x", frameFlags); + LOG_TRACE("refresh=SKIPPED, reason=FRAME_MATCHED_PREVIOUS, frameFlags=0x%x", frameFlags); } // Have too many fast-refreshes occurred consecutively, since last full refresh? @@ -328,7 +328,7 @@ void EInkDynamicDisplay::checkConsecutiveFastRefreshes() if (frameFlags & UNLIMITED_FAST) { refresh = FAST; reason = NO_OBJECTIONS; - LOG_DEBUG("refresh=FAST, reason=UNLIMITED_FAST_MODE_ACTIVE, frameFlags=0x%x", frameFlags); + LOG_TRACE("refresh=FAST, reason=UNLIMITED_FAST_MODE_ACTIVE, frameFlags=0x%x", frameFlags); return; } @@ -336,7 +336,7 @@ void EInkDynamicDisplay::checkConsecutiveFastRefreshes() if (fastRefreshCount >= EINK_LIMIT_FASTREFRESH) { refresh = FULL; reason = EXCEEDED_LIMIT_FASTREFRESH; - LOG_DEBUG("refresh=FULL, reason=EXCEEDED_LIMIT_FASTREFRESH, frameFlags=0x%x", frameFlags); + LOG_TRACE("refresh=FULL, reason=EXCEEDED_LIMIT_FASTREFRESH, frameFlags=0x%x", frameFlags); } } @@ -351,13 +351,13 @@ void EInkDynamicDisplay::checkFastRequested() // If we want BACKGROUND to use fast. (FULL only when a limit is hit) refresh = FAST; reason = BACKGROUND_USES_FAST; - LOG_DEBUG("refresh=FAST, reason=BACKGROUND_USES_FAST, fastRefreshCount=%lu, frameFlags=0x%x", fastRefreshCount, + LOG_TRACE("refresh=FAST, reason=BACKGROUND_USES_FAST, fastRefreshCount=%lu, frameFlags=0x%x", fastRefreshCount, frameFlags); #else // If we do want to use FULL for BACKGROUND updates refresh = FULL; reason = FLAGGED_BACKGROUND; - LOG_DEBUG("refresh=FULL, reason=FLAGGED_BACKGROUND"); + LOG_TRACE("refresh=FULL, reason=FLAGGED_BACKGROUND"); #endif } @@ -365,7 +365,7 @@ void EInkDynamicDisplay::checkFastRequested() if (frameFlags & RESPONSIVE) { refresh = FAST; reason = NO_OBJECTIONS; - LOG_DEBUG("refresh=FAST, reason=NO_OBJECTIONS, fastRefreshCount=%lu, frameFlags=0x%x", fastRefreshCount, frameFlags); + LOG_TRACE("refresh=FAST, reason=NO_OBJECTIONS, fastRefreshCount=%lu, frameFlags=0x%x", fastRefreshCount, frameFlags); } } @@ -430,7 +430,7 @@ void EInkDynamicDisplay::countGhostPixels() } } - LOG_DEBUG("ghostPixels=%hu, ", ghostPixelCount); + LOG_TRACE("ghostPixels=%hu, ", ghostPixelCount); } // Check if ghost pixel count exceeds the defined limit @@ -446,7 +446,7 @@ void EInkDynamicDisplay::checkExcessiveGhosting() if (ghostPixelCount > EINK_LIMIT_GHOSTING_PX) { refresh = FULL; reason = EXCEEDED_GHOSTINGLIMIT; - LOG_DEBUG("refresh=FULL, reason=EXCEEDED_GHOSTINGLIMIT, frameFlags=0x%x", frameFlags); + LOG_TRACE("refresh=FULL, reason=EXCEEDED_GHOSTINGLIMIT, frameFlags=0x%x", frameFlags); } } diff --git a/src/graphics/niche/InkHUD/PlatformioConfig.ini b/src/graphics/niche/InkHUD/PlatformioConfig.ini index 4c03773b9f..f5bc5c28c4 100644 --- a/src/graphics/niche/InkHUD/PlatformioConfig.ini +++ b/src/graphics/niche/InkHUD/PlatformioConfig.ini @@ -24,4 +24,4 @@ build_flags = -D HAS_BUTTON=0 ; Suppress default ButtonThread lib_deps = # renovate: datasource=github-tags depName=GFX_Root packageName=ZinggJM/GFX_Root - https://github.com/ZinggJM/GFX_Root/archive/3195764e352a0d2567c8d277ac408ca7293a99b0.zip ; Used by InkHUD as a "slimmer" version of AdafruitGFX + https://github.com/ZinggJM/GFX_Root.git#3195764e352a0d2567c8d277ac408ca7293a99b0 ; Used by InkHUD as a "slimmer" version of AdafruitGFX diff --git a/src/graphics/niche/Utils/FlashData.h b/src/graphics/niche/Utils/FlashData.h index 3c12fc930a..43fcd7355a 100644 --- a/src/graphics/niche/Utils/FlashData.h +++ b/src/graphics/niche/Utils/FlashData.h @@ -96,7 +96,7 @@ template class FlashData f.close(); } else { - LOG_ERROR("Can't open / read %s", filename.c_str()); + LOG_ERROR("Can't open/read %s", filename.c_str()); okay = false; } #else diff --git a/src/mesh/MeshService.cpp b/src/mesh/MeshService.cpp index b67d9f44d1..77540660bc 100644 --- a/src/mesh/MeshService.cpp +++ b/src/mesh/MeshService.cpp @@ -13,6 +13,7 @@ #include "PowerFSM.h" #include "TypeConversions.h" #include "UptimeClock.h" +#include "gps/GPSLog.h" #include "gps/RTC.h" #include "graphics/draw/MessageRenderer.h" #include "main.h" @@ -596,9 +597,7 @@ int MeshService::onGPSChanged(const meshtastic::GPSStatus *newStatus) pos = gps->p; } else { // The GPS has lost lock -#ifdef GPS_DEBUG - LOG_DEBUG("onGPSchanged() - lost validLocation"); -#endif + LOG_DEBUG_GPS("onGPSchanged() - lost validLocation"); } // Used fixed position if configured regardless of GPS lock if (config.position.fixed_position) { diff --git a/src/mesh/NextHopRouter.cpp b/src/mesh/NextHopRouter.cpp index c4eb5c6819..d7d396f60d 100644 --- a/src/mesh/NextHopRouter.cpp +++ b/src/mesh/NextHopRouter.cpp @@ -67,7 +67,7 @@ ErrorCode NextHopRouter::send(meshtastic_MeshPacket *p) wasSeenRecently(p); // FIXME, move this to a sniffSent method p->next_hop = getNextHop(p->to, p->relay_node).value_or(NO_NEXT_HOP_PREFERENCE); // set the next hop - LOG_DEBUG("Set next hop for dest 0x%08x to 0x%x", p->to, p->next_hop); + LOG_TRACE("Set next hop for dest 0x%08x to 0x%x", p->to, p->next_hop); // If it's from us, ReliableRouter already handles retransmissions if want_ack is set. If a next hop is set and hop limit is // not 0 or want_ack is set, start retransmissions @@ -314,7 +314,7 @@ std::optional NextHopRouter::getNextHop(NodeNum to, uint8_t relay_node) } ResolvedNode r = nodeDB->resolveLastByte(hint, /*requireDirectNeighbor=*/true); if (r.status == LastByteResolution::Unique) { - LOG_DEBUG("Next hop for 0x%08x is 0x%x (TMM cache)", to, hint); + LOG_TRACE("Next hop for 0x%08x is 0x%x (TMM cache)", to, hint); return hint; } LOG_WARN("TMM next hop 0x%x for 0x%08x %s; set no pref", hint, to, @@ -512,7 +512,7 @@ void NextHopRouter::setNextTx(PendingPacket *pending) assert(iface); auto d = iface->getRetransmissionMsec(pending->packet); pending->nextTxMsec = millis() + d; - LOG_DEBUG("Next retransmission in %u msecs", d); + LOG_TRACE("Next retransmission in %u msecs", d); printPacket("", pending->packet); setReceivedMessage(); // Run ASAP, so we can figure out our correct sleep time } diff --git a/src/mesh/NodeDB.cpp b/src/mesh/NodeDB.cpp index 9ccc8065d2..e6c1ac67e6 100644 --- a/src/mesh/NodeDB.cpp +++ b/src/mesh/NodeDB.cpp @@ -3434,9 +3434,9 @@ void NodeDB::updateTelemetry(uint32_t nodeId, const meshtastic_Telemetry &t, RxS if (t.which_variant == meshtastic_Telemetry_device_metrics_tag) { if (src == RX_SRC_LOCAL) { - LOG_DEBUG("updateTelemetry LOCAL device"); + LOG_TRACE("updateTelemetry LOCAL device"); } else { - LOG_DEBUG("updateTelemetry REMOTE device node=0x%08x", nodeId); + LOG_TRACE("updateTelemetry REMOTE device node=0x%08x", nodeId); } #if !MESHTASTIC_EXCLUDE_TELEMETRYDB concurrency::LockGuard guard(&satelliteMutex); @@ -3446,9 +3446,9 @@ void NodeDB::updateTelemetry(uint32_t nodeId, const meshtastic_Telemetry &t, RxS } else if (t.which_variant == meshtastic_Telemetry_environment_metrics_tag) { if (src == RX_SRC_LOCAL) { - LOG_DEBUG("updateTelemetry LOCAL env"); + LOG_TRACE("updateTelemetry LOCAL env"); } else { - LOG_DEBUG("updateTelemetry REMOTE env node=0x%08x", nodeId); + LOG_TRACE("updateTelemetry REMOTE env node=0x%08x", nodeId); } #if !MESHTASTIC_EXCLUDE_ENVIRONMENTDB concurrency::LockGuard guard(&satelliteMutex); @@ -3649,7 +3649,7 @@ void NodeDB::updateFrom(const meshtastic_MeshPacket &mp) return; } if (mp.which_payload_variant == meshtastic_MeshPacket_decoded_tag && mp.from) { - LOG_DEBUG("Update DB node 0x%08x, rx_time=%u", mp.from, mp.rx_time); + LOG_TRACE("Update DB node 0x%08x, rx_time=%u", mp.from, mp.rx_time); // mp.from is unauthenticated, so rate-limit admission once the database is full: otherwise // invented node numbers churn it at packet rate and push real neighbours out. diff --git a/src/mesh/PacketHistory.cpp b/src/mesh/PacketHistory.cpp index 87a5c69d71..da745a25e7 100644 --- a/src/mesh/PacketHistory.cpp +++ b/src/mesh/PacketHistory.cpp @@ -107,7 +107,7 @@ bool PacketHistory::wasSeenRecently(const meshtastic_MeshPacket *p, bool withUpd // Check for hop_limit upgrade scenario if (seenRecently && wasUpgraded && getHighestHopLimit(*found) < p->hop_limit) { - LOG_DEBUG("Packet History - Hop limit upgrade: packet 0x%08x hop_limit=%d -> %d", p->id, getHighestHopLimit(*found), + LOG_TRACE("Packet History - Hop limit upgrade: packet 0x%08x hop_limit=%d -> %d", p->id, getHighestHopLimit(*found), p->hop_limit); *wasUpgraded = true; } else if (wasUpgraded) { diff --git a/src/mesh/PhoneAPI.cpp b/src/mesh/PhoneAPI.cpp index 696c370faf..e093d5be0f 100644 --- a/src/mesh/PhoneAPI.cpp +++ b/src/mesh/PhoneAPI.cpp @@ -486,7 +486,7 @@ bool PhoneAPI::handleToRadio(const uint8_t *buf, size_t bufLength) break; #if !MESHTASTIC_EXCLUDE_MQTT case meshtastic_ToRadio_mqttClientProxyMessage_tag: - LOG_DEBUG("Got MqttClientProxy message"); + LOG_TRACE("Got MqttClientProxy message"); if (state != STATE_SEND_PACKETS) { LOG_WARN("Ignore MqttClientProxy msg during config handshake"); break; @@ -514,7 +514,7 @@ bool PhoneAPI::handleToRadio(const uint8_t *buf, size_t bufLength) nodeInfoModule->sendOurNodeInfo(NODENUM_BROADCAST, true, 0, true); } } else { - LOG_DEBUG("Got client heartbeat"); + LOG_TRACE("Got client heartbeat"); heartbeatReceived = true; } break; @@ -558,7 +558,7 @@ size_t PhoneAPI::getFromRadio(uint8_t *buf) fromRadioScratch.queueStatus = router->getQueueStatus(); heartbeatReceived = false; size_t numbytes = pb_encode_to_bytes(buf, meshtastic_FromRadio_size, &meshtastic_FromRadio_msg, &fromRadioScratch); - LOG_DEBUG("FromRadio=STATE_SEND_QUEUE_STATUS, numbytes=%u", numbytes); + LOG_TRACE("FromRadio=STATE_SEND_QUEUE_STATUS, numbytes=%u", (unsigned)numbytes); return numbytes; } @@ -571,7 +571,7 @@ size_t PhoneAPI::getFromRadio(uint8_t *buf) // Advance states as needed switch (state) { case STATE_SEND_NOTHING: - LOG_DEBUG("FromRadio=STATE_SEND_NOTHING"); + LOG_TRACE("FromRadio=STATE_SEND_NOTHING"); break; case STATE_SEND_MY_INFO: LOG_DEBUG("FromRadio=STATE_SEND_MY_INFO"); @@ -1002,7 +1002,7 @@ size_t PhoneAPI::getFromRadio(uint8_t *buf) } else { fromRadioScratch.which_payload_variant = meshtastic_FromRadio_fileInfo_tag; fromRadioScratch.fileInfo = filesManifest.at(config_state); - LOG_DEBUG("File: %s (%d) bytes", fromRadioScratch.fileInfo.file_name, fromRadioScratch.fileInfo.size_bytes); + LOG_TRACE("File: %s (%d) bytes", fromRadioScratch.fileInfo.file_name, fromRadioScratch.fileInfo.size_bytes); config_state++; } break; @@ -1015,7 +1015,7 @@ size_t PhoneAPI::getFromRadio(uint8_t *buf) case STATE_SEND_PACKETS: pauseBluetoothLogging = false; // Do we have a message from the mesh or packet from the local device? - LOG_DEBUG("FromRadio=STATE_SEND_PACKETS"); + LOG_TRACE("FromRadio=STATE_SEND_PACKETS"); if (queueStatusPacketForPhone) { fromRadioScratch.which_payload_variant = meshtastic_FromRadio_queueStatus_tag; fromRadioScratch.queueStatus = *queueStatusPacketForPhone; @@ -1100,7 +1100,7 @@ size_t PhoneAPI::getFromRadio(uint8_t *buf) return numbytes; } - LOG_DEBUG("No FromRadio packet available"); + LOG_TRACE("No FromRadio packet available"); return 0; } @@ -1204,7 +1204,7 @@ void PhoneAPI::prefetchNodeInfos() nodeInfoQueue.push_back(info); // Log progress here (at fetch time) so readIndex is accurate and each value logs only once. if (readIndex == 2 || readIndex % 20 == 0) { - LOG_DEBUG("nodeinfo: %d/%d", readIndex, nodeDB->getNumMeshNodes()); + LOG_TRACE("nodeinfo: %d/%d", readIndex, nodeDB->getNumMeshNodes()); } added = true; } diff --git a/src/mesh/RadioLibInterface.cpp b/src/mesh/RadioLibInterface.cpp index 7c45728cc4..a826a51318 100644 --- a/src/mesh/RadioLibInterface.cpp +++ b/src/mesh/RadioLibInterface.cpp @@ -131,14 +131,14 @@ bool RadioLibInterface::receiveDetected(uint16_t irq, unsigned long syncWordHead if (!(irq & syncWordHeaderValidFlag)) { // The HEADER_VALID flag should be set by now if it was really a packet, so ignore PREAMBLE_DETECTED flag activeReceiveStart = 0; - LOG_DEBUG("Ignore false preamble detection"); + LOG_TRACE("Ignore false preamble detection"); return false; } else { uint32_t maxPacketTimeMsec = getPacketTime(meshtastic_Constants_DATA_PAYLOAD_LEN + sizeof(PacketHeader)); if (!Throttle::isWithinTimespanMs(activeReceiveStart, maxPacketTimeMsec)) { // We should have gotten an RX_DONE IRQ by now if it was really a packet, so ignore HEADER_VALID flag activeReceiveStart = 0; - LOG_DEBUG("Ignore false header detection"); + LOG_TRACE("Ignore false header detection"); return false; } } @@ -187,7 +187,7 @@ ErrorCode RadioLibInterface::send(meshtastic_MeshPacket *p) #ifndef LORA_DISABLE_SENDING printPacket("enqueue for send", p); - LOG_DEBUG("txGood=%d,txRelay=%d,rxGood=%d,rxBad=%d", txGood, txRelay, rxGood, rxBad); + LOG_TRACE("txGood=%d,txRelay=%d,rxGood=%d,rxBad=%d", txGood, txRelay, rxGood, rxBad); bool dropped = false; ErrorCode res = txQueue.enqueue(p, &dropped) ? ERRNO_OK : ERRNO_UNKNOWN; @@ -290,7 +290,7 @@ void RadioLibInterface::updateNoiseFloor() currentNoiseFloor = getAverageNoiseFloorInternal(); - LOG_DEBUG("Noise floor: %d dBm (samples: %d, latest: %d dBm)", currentNoiseFloor, getNoiseFloorSampleCountInternal(), rssi); + LOG_TRACE("Noise floor: %d dBm (samples: %d, latest: %d dBm)", currentNoiseFloor, getNoiseFloorSampleCountInternal(), rssi); } uint8_t RadioLibInterface::getNoiseFloorSampleCountInternal() const @@ -468,7 +468,7 @@ void RadioLibInterface::onNotify(uint32_t notification) txp = txQueue.dequeue(); assert(txp); startSend(txp); - LOG_DEBUG("%d packets in TX queue", txQueue.getMaxLen() - txQueue.getFree()); + LOG_TRACE("%d packets in TX queue", txQueue.getMaxLen() - txQueue.getFree()); } } } @@ -505,7 +505,7 @@ void RadioLibInterface::setTransmitDelay() startTransmitTimer(true); } else { // If there is a SNR, start a timer scaled based on that SNR. - LOG_DEBUG("rx_snr found. hop_limit:%d rx_snr:%f", p->hop_limit, p->rx_snr); + LOG_TRACE("rx_snr found. hop_limit:%d rx_snr:%f", p->hop_limit, p->rx_snr); startTransmitTimerRebroadcast(p); } } @@ -539,7 +539,7 @@ void RadioLibInterface::clampToLateRebroadcastWindow(NodeNum from, PacketId id) p->tx_after = millis() + getTxDelayMsecWeightedWorst(p->rx_snr); bool dropped = false; if (txQueue.enqueue(p, &dropped)) { - LOG_DEBUG("Move queued packet to late rebroadcast window %dms from now", p->tx_after - millis()); + LOG_TRACE("Move queued packet to late rebroadcast window %ums from now", (uint32_t)(p->tx_after - millis())); } else { packetPool.release(p); } diff --git a/src/mesh/Router.cpp b/src/mesh/Router.cpp index 5e33db235a..3a938e03c5 100644 --- a/src/mesh/Router.cpp +++ b/src/mesh/Router.cpp @@ -311,7 +311,7 @@ PacketId generatePacketId() rollingPacketId &= ID_COUNTER_MASK; // Mask out the top 22 bits PacketId id = rollingPacketId | random(UINT32_MAX & 0x7fffffff) << 10; // top 22 bits - LOG_DEBUG("Partially randomized packet id %u", id); + LOG_TRACE("Partially randomized packet id 0x%08x", id); return id; } @@ -408,7 +408,7 @@ ErrorCode Router::sendLocal(meshtastic_MeshPacket *p, RxSource src) ChannelIndex chIndex = getEffectiveChannelIndex(p); if (chIndex) { p->channel = chIndex; - LOG_DEBUG("localSend to channel %d", p->channel); + LOG_TRACE("localSend to channel %d", p->channel); } } @@ -701,7 +701,7 @@ bool checkXeddsaReceivePolicy(meshtastic_MeshPacket *p) if (!node) return false; nodeInfoLiteSetBit(node, NODEINFO_BITFIELD_HAS_XEDDSA_SIGNED_MASK, true); - LOG_DEBUG("Verified XEdDSA signature from 0x%08x", p->from); + LOG_TRACE("Verified XEdDSA signature from 0x%08x", p->from); } else { LOG_WARN("XEdDSA signature verify failed from 0x%08x, drop", p->from); return false; @@ -884,7 +884,7 @@ DecodeState perhapsDecode(meshtastic_MeshPacket *p) licensedPkiCandidate = true; } else if (pkiCandidate) { pkiAttempted = true; - LOG_DEBUG("Attempt PKI decryption"); + LOG_TRACE("Attempt PKI decryption"); // Resolve the sender's key only for actual PKI-decrypt candidates, not every encrypted channel // packet: copyPublicKeyForDecrypt() can fall through to a linear scan of TrafficManagement's large // NodeInfo cache. It returns authoritative keys (hot/warm), or a cold-tier cache key only when it is @@ -1146,7 +1146,7 @@ meshtastic_Routing_Error perhapsEncode(meshtastic_MeshPacket *p) if (crypto->xeddsa_sign(p->from, p->id, p->decoded.portnum, p->decoded.payload.bytes, p->decoded.payload.size, p->decoded.xeddsa_signature.bytes)) { p->decoded.xeddsa_signature.size = XEDDSA_SIGNATURE_SIZE; - LOG_DEBUG("XEdDSA signed packet 0x%08x", p->id); + LOG_TRACE("XEdDSA signed packet 0x%08x", p->id); } } #endif diff --git a/src/mesh/SX126xInterface.cpp b/src/mesh/SX126xInterface.cpp index e8d5baf102..750ebbbefb 100644 --- a/src/mesh/SX126xInterface.cpp +++ b/src/mesh/SX126xInterface.cpp @@ -336,7 +336,7 @@ template void SX126xInterface::addReceiveMetadata(meshtastic_Mes mp->rx_snr = lora.getSNR(); mp->rx_rssi = lround(lora.getRSSI()); mp->has_rx_rssi = true; // rx_rssi has explicit presence - a genuine reading must be marked present to survive encoding - LOG_DEBUG("Corrected frequency offset: %f", lora.getFrequencyError()); + LOG_TRACE("Corrected frequency offset: %f", lora.getFrequencyError()); } /** We override to turn on transmitter power as needed. diff --git a/src/modules/AdminModule.cpp b/src/modules/AdminModule.cpp index 2967989236..80bb799036 100644 --- a/src/modules/AdminModule.cpp +++ b/src/modules/AdminModule.cpp @@ -151,7 +151,7 @@ bool AdminModule::handleReceivedProtobuf(const meshtastic_MeshPacket &mp, meshta LOG_INFO("Ignore admin response from 0x%08x, no outstanding request", mp.from); return handled; } - LOG_DEBUG("Allow admin response message"); + LOG_TRACE("Allow admin response message"); } else if (mp.from == 0) { // Local admin from a BLE/USB/TCP client. from == 0 cannot arrive from the // mesh: RF drops packets without a sender (RadioLibInterface) and MQTT treats @@ -2168,7 +2168,7 @@ bool AdminModule::messageIsRequest(const meshtastic_AdminMessage *r) void AdminModule::handleSendInputEvent(const meshtastic_AdminMessage_InputEvent &inputEvent) { - LOG_DEBUG("Processing input event: event_code=%u, kb_char=%u, touch_x=%u, touch_y=%u", inputEvent.event_code, + LOG_TRACE("Processing input event: event_code=%u, kb_char=%u, touch_x=%u, touch_y=%u", inputEvent.event_code, inputEvent.kb_char, inputEvent.touch_x, inputEvent.touch_y); // Create InputEvent for injection. diff --git a/src/modules/CannedMessageModule.cpp b/src/modules/CannedMessageModule.cpp index 02f94b22a8..0013012751 100644 --- a/src/modules/CannedMessageModule.cpp +++ b/src/modules/CannedMessageModule.cpp @@ -112,7 +112,7 @@ void CannedMessageModule::LaunchWithDestination(NodeNum newDest, uint8_t newChan e.action = UIFrameEvent::Action::REGENERATE_FRAMESET; notifyObservers(&e); - LOG_DEBUG("[CannedMessage] LaunchWithDestination dest=0x%08x ch=%d", dest, channel); + LOG_TRACE("[CannedMessage] LaunchWithDestination dest=0x%08x ch=%d", dest, channel); } void CannedMessageModule::LaunchFreetextWithDestination(NodeNum newDest, uint8_t newChannel) @@ -135,7 +135,7 @@ void CannedMessageModule::LaunchFreetextWithDestination(NodeNum newDest, uint8_t e.action = UIFrameEvent::Action::REGENERATE_FRAMESET; notifyObservers(&e); - LOG_DEBUG("[CannedMessage] LaunchFreetextWithDestination dest=0x%08x ch=%d", dest, channel); + LOG_TRACE("[CannedMessage] LaunchFreetextWithDestination dest=0x%08x ch=%d", dest, channel); } static bool returnToCannedList = false; @@ -891,8 +891,8 @@ bool CannedMessageModule::handleFreeTextInput(const InputEvent *event) // Confirm select (Enter) bool isSelect = isSelectEvent(event); if (isSelect) { - LOG_DEBUG("[SELECT] handleFreeTextInput: runState=%d, dest=%u, channel=%d, freetext='%s'", (int)runState, dest, channel, - freetext.c_str()); + LOG_TRACE("[SELECT] handleFreeTextInput: runState=%d, dest=0x%08x, channel=%d, freetext='%s'", (int)runState, dest, + channel, freetext.c_str()); if (dest == 0) dest = NODENUM_BROADCAST; // Defensive: If channel isn't valid, pick the first available channel @@ -2336,7 +2336,6 @@ AdminMessageHandleResult CannedMessageModule::handleAdminMessageForModule(const void CannedMessageModule::handleGetCannedMessageModuleMessages(const meshtastic_MeshPacket &req, meshtastic_AdminMessage *response) { - LOG_DEBUG("*** handleGetCannedMessageModuleMessages"); if (req.decoded.want_response) { response->which_payload_variant = meshtastic_AdminMessage_get_canned_message_module_messages_response_tag; strncpy(response->get_canned_message_module_messages_response, cannedMessageModuleConfig.messages, @@ -2351,7 +2350,7 @@ void CannedMessageModule::handleSetCannedMessageModuleMessages(const char *from_ if (*from_msg) { changed |= strcmp(cannedMessageModuleConfig.messages, from_msg); strncpy(cannedMessageModuleConfig.messages, from_msg, sizeof(cannedMessageModuleConfig.messages)); - LOG_DEBUG("*** from_msg.text:%s", from_msg); + LOG_TRACE("*** from_msg.text:%s", from_msg); } if (changed) { diff --git a/src/modules/NeighborInfoModule.cpp b/src/modules/NeighborInfoModule.cpp index 3803c953e7..a05b09b0fa 100644 --- a/src/modules/NeighborInfoModule.cpp +++ b/src/modules/NeighborInfoModule.cpp @@ -14,11 +14,11 @@ NOTE: For debugging only */ void NeighborInfoModule::printNeighborInfo(const char *header, const meshtastic_NeighborInfo *np) { - LOG_DEBUG("%s NEIGHBORINFO PACKET from Node 0x%08x to Node 0x%08x (last sent by 0x%08x)", header, np->node_id, + LOG_TRACE("%s NEIGHBORINFO PACKET from Node 0x%08x to Node 0x%08x (last sent by 0x%08x)", header, np->node_id, nodeDB->getNodeNum(), np->last_sent_by_id); - LOG_DEBUG("Packet contains %d neighbors", np->neighbors_count); + LOG_TRACE("Packet contains %d neighbors", np->neighbors_count); for (int i = 0; i < np->neighbors_count; i++) { - LOG_DEBUG("Neighbor %d: node_id=0x%08x, snr=%.2f", i, np->neighbors[i].node_id, np->neighbors[i].snr); + LOG_TRACE("Neighbor %d: node_id=0x%08x, snr=%.2f", i, np->neighbors[i].node_id, np->neighbors[i].snr); } } @@ -28,9 +28,9 @@ NOTE: for debugging only */ void NeighborInfoModule::printNodeDBNeighbors() { - LOG_DEBUG("Our NodeDB contains %d neighbors", neighbors.size()); + LOG_TRACE("Our NodeDB contains %u neighbors", (unsigned)neighbors.size()); for (size_t i = 0; i < neighbors.size(); i++) { - LOG_DEBUG("Node %d: node_id=0x%08x, snr=%.2f", i, neighbors[i].node_id, neighbors[i].snr); + LOG_TRACE("Node %u: node_id=0x%08x, snr=%.2f", (unsigned)i, neighbors[i].node_id, neighbors[i].snr); } } @@ -162,18 +162,18 @@ Pass it to an upper client; do not persist this data on the mesh */ bool NeighborInfoModule::handleReceivedProtobuf(const meshtastic_MeshPacket &mp, meshtastic_NeighborInfo *np) { - LOG_DEBUG("NeighborInfo: handleReceivedProtobuf"); + LOG_TRACE("NeighborInfo: handleReceivedProtobuf"); if (np) { printNeighborInfo("RECEIVED", np); // Ignore dummy/interceptable packets: single neighbor with nodeId 0 and snr 0 if (np->neighbors_count != 1 || np->neighbors[0].node_id != 0 || np->neighbors[0].snr != 0.0f) { - LOG_DEBUG(" Updating neighbours"); + LOG_TRACE(" Updating neighbours"); updateNeighbors(mp, np); } else { LOG_DEBUG(" Ignoring dummy neighbor info packet (single neighbor with nodeId 0, snr 0)"); } } else if (getHopsAway(mp) == 0) { - LOG_DEBUG("Get or create neighbor: %u with snr %f", mp.from, mp.rx_snr); + LOG_TRACE("Get or create neighbor: 0x%08x with snr %f", mp.from, mp.rx_snr); // If the hopLimit is the same as hopStart, then it is a neighbor getOrCreateNeighbor(mp.from, mp.from, 0, mp.rx_snr); // Set the broadcast interval to 0, as we don't know it @@ -202,7 +202,6 @@ void NeighborInfoModule::resetNeighbors() void NeighborInfoModule::updateNeighbors(const meshtastic_MeshPacket &mp, const meshtastic_NeighborInfo *np) { - LOG_DEBUG("updateNeighbors"); // The last sent ID will be 0 if the packet is from the phone, which we don't // count as an edge. So we assume that if it's zero, then this packet is from // our node. diff --git a/src/modules/PositionModule.cpp b/src/modules/PositionModule.cpp index 893cfd87ca..9ee985b156 100644 --- a/src/modules/PositionModule.cpp +++ b/src/modules/PositionModule.cpp @@ -10,6 +10,7 @@ #include "TypeConversions.h" #include "airtime.h" #include "configuration.h" +#include "gps/GPSLog.h" #include "gps/GeoCoord.h" #include "gps/RTC.h" #include "main.h" @@ -81,13 +82,13 @@ bool PositionModule::handleReceivedProtobuf(const meshtastic_MeshPacket &mp, mes nodeDB->setLocalPosition(p, true); return false; } else { - LOG_DEBUG("Incoming update from MYSELF"); + LOG_TRACE("Incoming update from MYSELF"); nodeDB->setLocalPosition(p); } } // Log packet size and data fields - LOG_DEBUG("POSITION node=0x%08x l=%d lat=%d lon=%d msl=%d hae=%d geo=%d pdop=%d hdop=%d vdop=%d siv=%d fxq=%d fxt=%d pts=%d " + LOG_TRACE("POSITION node=0x%08x l=%d lat=%d lon=%d msl=%d hae=%d geo=%d pdop=%d hdop=%d vdop=%d siv=%d fxq=%d fxt=%d pts=%d " "time=%d", getFrom(&mp), mp.decoded.payload.size, p.latitude_i, p.longitude_i, p.altitude, p.altitude_hae, p.altitude_geoidal_separation, p.PDOP, p.HDOP, p.VDOP, p.sats_in_view, p.fix_quality, p.fix_type, p.timestamp, @@ -363,7 +364,7 @@ meshtastic_MeshPacket *PositionModule::allocAtakPli() memcpy(mp->decoded.payload.bytes + 1, protobuf_bytes, proto_size); mp->decoded.payload.size = proto_size + 1; - LOG_DEBUG("TAK V2 PLI payload: %zu bytes (1 flags + %zu protobuf)", mp->decoded.payload.size, proto_size); + LOG_TRACE("TAK V2 PLI payload: %zu bytes (1 flags + %zu protobuf)", mp->decoded.payload.size, proto_size); return mp; } @@ -557,9 +558,7 @@ int32_t PositionModule::runOnce() if (lastGpsSend == 0 || msSinceLastSend >= effectiveIntervalMs) { if (waitingForFreshPosition) { -#ifdef GPS_DEBUG - LOG_DEBUG("Skip initial position send; no fresh position since boot"); -#endif + LOG_DEBUG_GPS("Skip initial position send; no fresh position since boot"); } else if (nodeDB->hasValidPosition(node)) { lastGpsSend = now; @@ -591,11 +590,7 @@ int32_t PositionModule::runOnce() if (smartPosition.hasTraveledOverThreshold && Throttle::execute( &lastGpsSend, minimumTimeThreshold, []() { positionModule->sendOurPosition(); }, - []() { -#ifdef GPS_DEBUG - LOG_DEBUG("Skip smart broadcast: time throttled"); -#endif - })) { + []() { LOG_DEBUG_GPS("Skip smart broadcast: time throttled"); })) { LOG_DEBUG("Sent smart pos@%x:6 to mesh (distanceTraveled=%fm, minDistanceThreshold=%im, timeElapsed=%ims, " "minTimeInterval=%ims)", @@ -701,11 +696,7 @@ void PositionModule::handleNewPosition() if (smartPosition.hasTraveledOverThreshold && Throttle::execute( &lastGpsSend, minimumTimeThreshold, []() { positionModule->sendOurPosition(); }, - []() { -#ifdef GPS_DEBUG - LOG_DEBUG("Skip smart broadcast: time throttled"); -#endif - })) { + []() { LOG_DEBUG_GPS("Skip smart broadcast: time throttled"); })) { LOG_DEBUG("Sent smart pos@%x:6 to mesh (distanceTraveled=%fm, minDistanceThreshold=%im, timeElapsed=%ims, " "minTimeInterval=%ims)", localPosition.timestamp, smartPosition.distanceTraveled, smartPosition.distanceThreshold, msSinceLastSend, diff --git a/src/modules/RangeTestModule.cpp b/src/modules/RangeTestModule.cpp index 11a2cdc648..46475a3ae2 100644 --- a/src/modules/RangeTestModule.cpp +++ b/src/modules/RangeTestModule.cpp @@ -99,7 +99,7 @@ int32_t RangeTestModule::runOnce() } } } else { - LOG_INFO("Range Test Module - Disabled"); + LOG_INFO("Range Test Module Disabled"); } #endif diff --git a/src/modules/Telemetry/AirQualityTelemetry.cpp b/src/modules/Telemetry/AirQualityTelemetry.cpp index 5418d66208..b67a18327f 100644 --- a/src/modules/Telemetry/AirQualityTelemetry.cpp +++ b/src/modules/Telemetry/AirQualityTelemetry.cpp @@ -187,7 +187,7 @@ int32_t AirQualityTelemetryModule::runOnce() // - We can publish the data on the mesh shortly // - Or we can send it to the phone // TODO: This will need to be refurbished once we implement separate intervals - LOG_INFO("Waking up sensors"); + LOG_INFO("Waking sensors"); for (TelemetrySensor *sensor : sensors) { if (!sensor->canSleep()) { LOG_DEBUG("%s: no sleep support, skip", sensor->sensorName); @@ -207,7 +207,7 @@ int32_t AirQualityTelemetryModule::runOnce() } if (!sensor->isActive()) { - LOG_DEBUG("Waking up: %s", sensor->sensorName); + LOG_DEBUG("Waking %s", sensor->sensorName); if (awakeAheadOfTimeMs == 0) startAirQualityTelemetryCycle = millis(); awakeAheadOfTimeMs = max(awakeAheadOfTimeMs, sensor->wakeUpTimeMs()); diff --git a/src/modules/Telemetry/PowerTelemetry.cpp b/src/modules/Telemetry/PowerTelemetry.cpp index a3e588778a..b00672d2d6 100644 --- a/src/modules/Telemetry/PowerTelemetry.cpp +++ b/src/modules/Telemetry/PowerTelemetry.cpp @@ -312,7 +312,7 @@ bool PowerTelemetryModule::sendTelemetry(NodeNum dest, bool phoneOnly) LOG_WARN("Power telemetry unavailable this cycle, sleep without sending"); sleepOnNextExecution = true; preflightSleepDeferrals = 0; - LOG_DEBUG("Start next execution in 5s then sleep"); + LOG_DEBUG("Start next execution in 5s, then sleep"); setIntervalFromNow(FIVE_SECONDS_MS); } return validTelemetry; diff --git a/src/modules/Telemetry/Sensor/BME680Sensor.cpp b/src/modules/Telemetry/Sensor/BME680Sensor.cpp index 5130e12be2..e3badbe262 100644 --- a/src/modules/Telemetry/Sensor/BME680Sensor.cpp +++ b/src/modules/Telemetry/Sensor/BME680Sensor.cpp @@ -136,7 +136,7 @@ void BME680Sensor::loadState() file.read((uint8_t *)&bsecState, BSEC_MAX_STATE_BLOB_SIZE); file.close(); bme680.setState(bsecState); - LOG_INFO("%s state read from %s", sensorName, bsecConfigFileName); + LOG_INFO("%s: state read from %s", sensorName, bsecConfigFileName); } else { LOG_INFO("No %s state found (File: %s)", sensorName, bsecConfigFileName); } @@ -177,7 +177,7 @@ void BME680Sensor::updateState() } auto file = FSCom.open(bsecConfigFileName, FILE_O_WRITE); if (file) { - LOG_INFO("%s state write to %s", sensorName, bsecConfigFileName); + LOG_INFO("%s: state write to %s", sensorName, bsecConfigFileName); file.write((uint8_t *)&bsecState, BSEC_MAX_STATE_BLOB_SIZE); file.flush(); file.close(); diff --git a/src/modules/Telemetry/Sensor/DS248XSensor.cpp b/src/modules/Telemetry/Sensor/DS248XSensor.cpp index f3158d4321..d0e1385528 100644 --- a/src/modules/Telemetry/Sensor/DS248XSensor.cpp +++ b/src/modules/Telemetry/Sensor/DS248XSensor.cpp @@ -63,8 +63,6 @@ bool DS248XSensor::initDevice(TwoWire *bus, ScanI2C::FoundDevice *dev) #ifdef DS248X_I2C_CLOCK_SPEED reClockI2C.setup(_bus, _port); - - LOG_INFO("%s: attempting to reclock speed to %uHz", sensorName, DS248X_I2C_CLOCK_SPEED); reClockI2C.setClock(DS248X_I2C_CLOCK_SPEED); #endif /* DS248X_I2C_CLOCK_SPEED */ @@ -176,7 +174,6 @@ bool DS248XSensor::initDevice(TwoWire *bus, ScanI2C::FoundDevice *dev) } #ifdef DS248X_I2C_CLOCK_SPEED - LOG_INFO("%s: restoring clock speed", sensorName); reClockI2C.restoreClock(); #endif /* DS248X_I2C_CLOCK_SPEED */ @@ -193,7 +190,6 @@ bool DS248XSensor::isValidROM(const uint8_t *rom) float DS248XSensor::readTemperatureROM(const uint8_t *rom) { #ifdef DS248X_I2C_CLOCK_SPEED - LOG_DEBUG("%s: attempting to reclock speed to %uHz", sensorName, DS248X_I2C_CLOCK_SPEED); reClockI2C.setClock(DS248X_I2C_CLOCK_SPEED); #endif /* DS248X_I2C_CLOCK_SPEED */ @@ -224,7 +220,6 @@ float DS248XSensor::readTemperatureROM(const uint8_t *rom) } #ifdef DS248X_I2C_CLOCK_SPEED - LOG_DEBUG("%s: restoring clock speed", sensorName); reClockI2C.restoreClock(); #endif /* DS248X_I2C_CLOCK_SPEED */ diff --git a/src/modules/Telemetry/Sensor/HM330XSensor.cpp b/src/modules/Telemetry/Sensor/HM330XSensor.cpp index 1d44cd133f..20b2a5e660 100644 --- a/src/modules/Telemetry/Sensor/HM330XSensor.cpp +++ b/src/modules/Telemetry/Sensor/HM330XSensor.cpp @@ -17,14 +17,11 @@ bool HM330XSensor::initDevice(TwoWire *bus, ScanI2C::FoundDevice *dev) #ifdef HM330X_I2C_CLOCK_SPEED _port = dev->address.port; reClockI2C.setup(_bus, _port); - - LOG_INFO("%s: attempting to reclock speed to %uHz", sensorName, HM330X_I2C_CLOCK_SPEED); reClockI2C.setClock(HM330X_I2C_CLOCK_SPEED); #endif /* HM330X_I2C_CLOCK_SPEED */ if (hm330x.init(_bus) != HM330XErrorCode::NO_ERROR) { #ifdef HM330X_I2C_CLOCK_SPEED - LOG_INFO("%s: restoring clock speed", sensorName); reClockI2C.restoreClock(); #endif /* HM330X_I2C_CLOCK_SPEED */ LOG_WARN("%s error in sensor init", sensorName); @@ -32,7 +29,6 @@ bool HM330XSensor::initDevice(TwoWire *bus, ScanI2C::FoundDevice *dev) } #ifdef HM330X_I2C_CLOCK_SPEED - LOG_INFO("%s: restoring clock speed", sensorName); reClockI2C.restoreClock(); #endif /* HM330X_I2C_CLOCK_SPEED */ @@ -83,21 +79,18 @@ int32_t HM330XSensor::pendingForReadyMs() bool HM330XSensor::getMetrics(meshtastic_Telemetry *measurement) { #ifdef HM330X_I2C_CLOCK_SPEED - LOG_DEBUG("%s: attempting to reclock speed to %uHz", sensorName, HM330X_I2C_CLOCK_SPEED); reClockI2C.setClock(HM330X_I2C_CLOCK_SPEED); #endif /* HM330X_I2C_CLOCK_SPEED */ if (hm330x.read_sensor_value(buffer, 29)) { LOG_WARN("%s: read result failed", sensorName); #ifdef HM330X_I2C_CLOCK_SPEED - LOG_INFO("%s: restoring clock speed", sensorName); reClockI2C.restoreClock(); #endif /* HM330X_I2C_CLOCK_SPEED */ return false; } #ifdef HM330X_I2C_CLOCK_SPEED - LOG_INFO("%s: restoring clock speed", sensorName); reClockI2C.restoreClock(); #endif /* HM330X_I2C_CLOCK_SPEED */ diff --git a/src/modules/Telemetry/Sensor/MAX17048Sensor.cpp b/src/modules/Telemetry/Sensor/MAX17048Sensor.cpp index 1a6792d3a8..8e6406b80d 100644 --- a/src/modules/Telemetry/Sensor/MAX17048Sensor.cpp +++ b/src/modules/Telemetry/Sensor/MAX17048Sensor.cpp @@ -53,7 +53,7 @@ bool MAX17048Singleton::isBatteryCharging() chargeState = MAX17048ChargeState::IDLE; } - LOG_DEBUG("%s::isBatteryCharging %s volts: %.3f soc: %.3f rate: %.3f", sensorStr, chargeLabels[chargeState], volts, + LOG_TRACE("%s::isBatteryCharging %s volts: %.3f soc: %.3f rate: %.3f", sensorStr, chargeLabels[chargeState], volts, sample.cellPercent, sample.chargeRate); return chargeState == MAX17048ChargeState::IMPORT; } @@ -65,14 +65,14 @@ uint16_t MAX17048Singleton::getBusVoltageMv() LOG_DEBUG("%s::getBusVoltageMv is not connected", sensorStr); return 0; } - LOG_DEBUG("%s::getBusVoltageMv %.3fmV", sensorStr, volts); + LOG_TRACE("%s::getBusVoltageMv %.3fmV", sensorStr, volts); return (uint16_t)(volts * 1000.0f); } uint8_t MAX17048Singleton::getBusBatteryPercent() { float soc = cellPercent(); - LOG_DEBUG("%s::getBusBatteryPercent %.1f%%", sensorStr, soc); + LOG_TRACE("%s::getBusBatteryPercent %.1f%%", sensorStr, soc); return clamp(static_cast(round(soc)), static_cast(0), static_cast(100)); } @@ -82,7 +82,7 @@ uint16_t MAX17048Singleton::getTimeToGoSecs() float soc = cellPercent(); // state of charge in percent 0 to 100 soc = clamp(soc, 0.0f, 100.0f); // clamp soc between 0 and 100% float ttg = ((100.0f - soc) / rate) * 3600.0f; // calculate seconds to charge/discharge - LOG_DEBUG("%s::getTimeToGoSecs %.0f seconds", sensorStr, ttg); + LOG_TRACE("%s::getTimeToGoSecs %.0f seconds", sensorStr, ttg); return (uint16_t)ttg; } @@ -108,7 +108,7 @@ bool MAX17048Singleton::isExternallyPowered() } // if the bus voltage is over MAX17048_BUS_POWER_VOLTS, then the external power // is assumed to be connected - LOG_DEBUG("%s::isExternallyPowered %s connected", sensorStr, volts >= MAX17048_BUS_POWER_VOLTS ? "is" : "is not"); + LOG_TRACE("%s::isExternallyPowered %s connected", sensorStr, volts >= MAX17048_BUS_POWER_VOLTS ? "is" : "is not"); return volts >= MAX17048_BUS_POWER_VOLTS; } @@ -140,7 +140,7 @@ void MAX17048Sensor::setup() {} bool MAX17048Sensor::getMetrics(meshtastic_Telemetry *measurement) { - LOG_DEBUG("MAX17048 getMetrics id: %i", measurement->which_variant); + LOG_TRACE("MAX17048 getMetrics id: %i", measurement->which_variant); float volts = max17048->cellVoltage(); if (isnan(volts)) { diff --git a/src/modules/Telemetry/Sensor/PMSA003ISensor.cpp b/src/modules/Telemetry/Sensor/PMSA003ISensor.cpp index 7fae87b984..c366057735 100644 --- a/src/modules/Telemetry/Sensor/PMSA003ISensor.cpp +++ b/src/modules/Telemetry/Sensor/PMSA003ISensor.cpp @@ -24,8 +24,6 @@ bool PMSA003ISensor::initDevice(TwoWire *bus, ScanI2C::FoundDevice *dev) #ifdef PMSA003I_I2C_CLOCK_SPEED _port = dev->address.port; reClockI2C.setup(_bus, _port); - - LOG_INFO("%s: attempting to reclock speed to %uHz", sensorName, PMSA003I_I2C_CLOCK_SPEED); reClockI2C.setClock(PMSA003I_I2C_CLOCK_SPEED); #endif /* PMSA003I_I2C_CLOCK_SPEED */ @@ -33,7 +31,6 @@ bool PMSA003ISensor::initDevice(TwoWire *bus, ScanI2C::FoundDevice *dev) if (_bus->endTransmission() != 0) { LOG_WARN("%s not found on I2C at 0x12", sensorName); #ifdef PMSA003I_I2C_CLOCK_SPEED - LOG_INFO("%s: restoring clock speed", sensorName); reClockI2C.restoreClock(); #endif /* PMSA003I_I2C_CLOCK_SPEED */ sleep(); @@ -41,7 +38,6 @@ bool PMSA003ISensor::initDevice(TwoWire *bus, ScanI2C::FoundDevice *dev) } #ifdef PMSA003I_I2C_CLOCK_SPEED - LOG_INFO("%s: restoring clock speed", sensorName); reClockI2C.restoreClock(); #endif /* PMSA003I_I2C_CLOCK_SPEED */ @@ -61,7 +57,6 @@ bool PMSA003ISensor::getMetrics(meshtastic_Telemetry *measurement) } #ifdef PMSA003I_I2C_CLOCK_SPEED - LOG_DEBUG("%s: attempting to reclock speed to %uHz", sensorName, PMSA003I_I2C_CLOCK_SPEED); reClockI2C.setClock(PMSA003I_I2C_CLOCK_SPEED); #endif /* PMSA003I_I2C_CLOCK_SPEED */ @@ -69,7 +64,6 @@ bool PMSA003ISensor::getMetrics(meshtastic_Telemetry *measurement) if (_bus->available() < PMSA003I_FRAME_LENGTH) { LOG_WARN("%s: read failed: incomplete data (%d bytes)", sensorName, _bus->available()); #ifdef PMSA003I_I2C_CLOCK_SPEED - LOG_DEBUG("%s: restoring clock speed", sensorName); reClockI2C.restoreClock(); #endif /* PMSA003I_I2C_CLOCK_SPEED */ return false; @@ -80,7 +74,6 @@ bool PMSA003ISensor::getMetrics(meshtastic_Telemetry *measurement) } #ifdef PMSA003I_I2C_CLOCK_SPEED - LOG_DEBUG("%s: restoring clock speed", sensorName); reClockI2C.restoreClock(); #endif /* PMSA003I_I2C_CLOCK_SPEED */ @@ -199,7 +192,7 @@ void PMSA003ISensor::sleep() uint32_t PMSA003ISensor::wakeUp() { #ifdef PMSA003I_ENABLE_PIN - LOG_INFO("%s: Waking up", sensorName); + LOG_INFO("%s Waking", sensorName); digitalWrite(PMSA003I_ENABLE_PIN, HIGH); state = PMSA003I_ACTIVE; pmMeasureStarted = getTime(); diff --git a/src/modules/Telemetry/Sensor/SCD30Sensor.cpp b/src/modules/Telemetry/Sensor/SCD30Sensor.cpp index 79819a9cee..c380f0f42e 100644 --- a/src/modules/Telemetry/Sensor/SCD30Sensor.cpp +++ b/src/modules/Telemetry/Sensor/SCD30Sensor.cpp @@ -18,8 +18,6 @@ bool SCD30Sensor::initDevice(TwoWire *bus, ScanI2C::FoundDevice *dev) #ifdef SCD30_I2C_CLOCK_SPEED _port = dev->address.port; reClockI2C.setup(_bus, _port); - - LOG_INFO("%s: reclock to %uHz", sensorName, SCD30_I2C_CLOCK_SPEED); reClockI2C.setClock(SCD30_I2C_CLOCK_SPEED); #endif /* SCD30_I2C_CLOCK_SPEED */ @@ -28,7 +26,6 @@ bool SCD30Sensor::initDevice(TwoWire *bus, ScanI2C::FoundDevice *dev) if (!startMeasurement()) { LOG_ERROR("%s: Periodic measurement start failed", sensorName); #ifdef SCD30_I2C_CLOCK_SPEED - LOG_INFO("%s: restoring clock speed", sensorName); reClockI2C.restoreClock(); #endif /* SCD30_I2C_CLOCK_SPEED */ return false; @@ -39,7 +36,6 @@ bool SCD30Sensor::initDevice(TwoWire *bus, ScanI2C::FoundDevice *dev) } #ifdef SCD30_I2C_CLOCK_SPEED - LOG_INFO("%s: restoring clock speed", sensorName); reClockI2C.restoreClock(); #endif /* SCD30_I2C_CLOCK_SPEED */ @@ -59,21 +55,18 @@ bool SCD30Sensor::getMetrics(meshtastic_Telemetry *measurement) float co2, temperature, humidity; #ifdef SCD30_I2C_CLOCK_SPEED - LOG_DEBUG("%s: reclock to %uHz", sensorName, SCD30_I2C_CLOCK_SPEED); reClockI2C.setClock(SCD30_I2C_CLOCK_SPEED); #endif /* SCD30_I2C_CLOCK_SPEED */ if (scd30.readMeasurementData(co2, temperature, humidity) != SCD30_NO_ERROR) { LOG_ERROR("%s: Measurement read failed", sensorName); #ifdef SCD30_I2C_CLOCK_SPEED - LOG_DEBUG("%s: restoring clock speed", sensorName); reClockI2C.restoreClock(); #endif /* SCD30_I2C_CLOCK_SPEED */ return false; } #ifdef SCD30_I2C_CLOCK_SPEED - LOG_DEBUG("%s: restoring clock speed", sensorName); reClockI2C.restoreClock(); #endif /* SCD30_I2C_CLOCK_SPEED */ @@ -366,14 +359,12 @@ bool SCD30Sensor::isActive() uint32_t SCD30Sensor::wakeUp() { #ifdef SCD30_I2C_CLOCK_SPEED - LOG_INFO("%s: reclock to %uHz", sensorName, SCD30_I2C_CLOCK_SPEED); reClockI2C.setClock(SCD30_I2C_CLOCK_SPEED); #endif /* SCD30_I2C_CLOCK_SPEED */ startMeasurement(); #ifdef SCD30_I2C_CLOCK_SPEED - LOG_INFO("%s: restoring clock speed", sensorName); reClockI2C.restoreClock(); #endif /* SCD30_I2C_CLOCK_SPEED */ @@ -387,14 +378,12 @@ uint32_t SCD30Sensor::wakeUp() void SCD30Sensor::sleep() { #ifdef SCD30_I2C_CLOCK_SPEED - LOG_INFO("%s: reclock to %uHz", sensorName, SCD30_I2C_CLOCK_SPEED); reClockI2C.setClock(SCD30_I2C_CLOCK_SPEED); #endif /* SCD30_I2C_CLOCK_SPEED */ stopMeasurement(); #ifdef SCD30_I2C_CLOCK_SPEED - LOG_INFO("%s: restoring clock speed", sensorName); reClockI2C.restoreClock(); #endif /* SCD30_I2C_CLOCK_SPEED */ } @@ -420,7 +409,6 @@ AdminMessageHandleResult SCD30Sensor::handleAdminMessage(const meshtastic_MeshPa AdminMessageHandleResult result; #ifdef SCD30_I2C_CLOCK_SPEED - LOG_INFO("%s: reclock to %uHz", sensorName, SCD30_I2C_CLOCK_SPEED); reClockI2C.setClock(SCD30_I2C_CLOCK_SPEED); #endif /* SCD30_I2C_CLOCK_SPEED */ @@ -478,7 +466,6 @@ AdminMessageHandleResult SCD30Sensor::handleAdminMessage(const meshtastic_MeshPa } #ifdef SCD30_I2C_CLOCK_SPEED - LOG_INFO("%s: restoring clock speed", sensorName); reClockI2C.restoreClock(); #endif /* SCD30_I2C_CLOCK_SPEED */ diff --git a/src/modules/Telemetry/Sensor/SCD4XSensor.cpp b/src/modules/Telemetry/Sensor/SCD4XSensor.cpp index 4a43881133..7c6bc3ecf7 100644 --- a/src/modules/Telemetry/Sensor/SCD4XSensor.cpp +++ b/src/modules/Telemetry/Sensor/SCD4XSensor.cpp @@ -19,8 +19,6 @@ bool SCD4XSensor::initDevice(TwoWire *bus, ScanI2C::FoundDevice *dev) #ifdef SCD4X_I2C_CLOCK_SPEED _port = dev->address.port; reClockI2C.setup(_bus, _port); - - LOG_INFO("%s: reclock to %uHz", sensorName, SCD4X_I2C_CLOCK_SPEED); reClockI2C.setClock(SCD4X_I2C_CLOCK_SPEED); #endif /* SCD4X_I2C_CLOCK_SPEED */ @@ -32,7 +30,6 @@ bool SCD4XSensor::initDevice(TwoWire *bus, ScanI2C::FoundDevice *dev) // Stop periodic measurement if (!stopMeasurement()) { #ifdef SCD4X_I2C_CLOCK_SPEED - LOG_INFO("%s: restoring clock speed", sensorName); reClockI2C.restoreClock(); #endif /* SCD4X_I2C_CLOCK_SPEED */ return false; @@ -46,7 +43,6 @@ bool SCD4XSensor::initDevice(TwoWire *bus, ScanI2C::FoundDevice *dev) if (!powerUp()) { LOG_ERROR("%s: powerUp() failed", sensorName); #ifdef SCD4X_I2C_CLOCK_SPEED - LOG_INFO("%s: restoring clock speed", sensorName); reClockI2C.restoreClock(); #endif /* SCD4X_I2C_CLOCK_SPEED */ return false; @@ -56,7 +52,6 @@ bool SCD4XSensor::initDevice(TwoWire *bus, ScanI2C::FoundDevice *dev) if (!getASC(ascActive)) { LOG_ERROR("%s: Can't check if ASC enabled", sensorName); #ifdef SCD4X_I2C_CLOCK_SPEED - LOG_INFO("%s: restoring clock speed", sensorName); reClockI2C.restoreClock(); #endif /* SCD4X_I2C_CLOCK_SPEED */ return false; @@ -66,14 +61,12 @@ bool SCD4XSensor::initDevice(TwoWire *bus, ScanI2C::FoundDevice *dev) if (!startMeasurement()) { LOG_ERROR("%s: Can't start measurement", sensorName); #ifdef SCD4X_I2C_CLOCK_SPEED - LOG_INFO("%s: restoring clock speed", sensorName); reClockI2C.restoreClock(); #endif /* SCD4X_I2C_CLOCK_SPEED */ return false; } #ifdef SCD4X_I2C_CLOCK_SPEED - LOG_INFO("%s: restoring clock speed", sensorName); reClockI2C.restoreClock(); #endif /* SCD4X_I2C_CLOCK_SPEED */ @@ -100,7 +93,6 @@ bool SCD4XSensor::getMetrics(meshtastic_Telemetry *measurement) float temperature, humidity; #ifdef SCD4X_I2C_CLOCK_SPEED - LOG_DEBUG("%s: reclock to %uHz", sensorName, SCD4X_I2C_CLOCK_SPEED); reClockI2C.setClock(SCD4X_I2C_CLOCK_SPEED); #endif /* SCD4X_I2C_CLOCK_SPEED */ @@ -118,7 +110,6 @@ bool SCD4XSensor::getMetrics(meshtastic_Telemetry *measurement) if (error != SCD4X_NO_ERROR || !dataReady) { #ifdef SCD4X_I2C_CLOCK_SPEED - LOG_DEBUG("%s: restoring clock speed", sensorName); reClockI2C.restoreClock(); #endif /* SCD4X_I2C_CLOCK_SPEED */ LOG_ERROR("SCD4X: Data is not ready"); @@ -128,7 +119,6 @@ bool SCD4XSensor::getMetrics(meshtastic_Telemetry *measurement) error = scd4x.readMeasurement(co2, temperature, humidity); #ifdef SCD4X_I2C_CLOCK_SPEED - LOG_DEBUG("%s: restoring clock speed", sensorName); reClockI2C.restoreClock(); #endif /* SCD4X_I2C_CLOCK_SPEED */ @@ -290,7 +280,7 @@ bool SCD4XSensor::getASC(uint16_t &_ascActive) return false; } - LOG_INFO("%s ASC is %s", sensorName, _ascActive ? "enabled" : "disabled"); + LOG_INFO("%s: ASC is %s", sensorName, _ascActive ? "enabled" : "disabled"); return true; } @@ -308,7 +298,7 @@ bool SCD4XSensor::setASC(bool ascEnabled) { uint16_t error; - LOG_INFO("%s %s ASC", sensorName, ascEnabled ? "Enabling" : "Disabling"); + LOG_INFO("%s: %s ASC", sensorName, ascEnabled ? "Enabling" : "Disabling"); if (!stopMeasurement()) { return false; @@ -644,13 +634,11 @@ bool SCD4XSensor::powerDown() } #ifdef SCD4X_I2C_CLOCK_SPEED - LOG_INFO("%s: reclock to %uHz", sensorName, SCD4X_I2C_CLOCK_SPEED); reClockI2C.setClock(SCD4X_I2C_CLOCK_SPEED); #endif /* SCD4X_I2C_CLOCK_SPEED */ if (!stopMeasurement()) { #ifdef SCD4X_I2C_CLOCK_SPEED - LOG_INFO("%s: restoring clock speed", sensorName); reClockI2C.restoreClock(); #endif /* SCD4X_I2C_CLOCK_SPEED */ return false; @@ -659,14 +647,12 @@ bool SCD4XSensor::powerDown() if (scd4x.powerDown() != SCD4X_NO_ERROR) { LOG_ERROR("%s: sleep() failed", sensorName); #ifdef SCD4X_I2C_CLOCK_SPEED - LOG_INFO("%s: restoring clock speed", sensorName); reClockI2C.restoreClock(); #endif /* SCD4X_I2C_CLOCK_SPEED */ return false; } #ifdef SCD4X_I2C_CLOCK_SPEED - LOG_INFO("%s: restoring clock speed", sensorName); reClockI2C.restoreClock(); #endif /* SCD4X_I2C_CLOCK_SPEED */ @@ -687,7 +673,7 @@ bool SCD4XSensor::powerDown() */ bool SCD4XSensor::powerUp() { - LOG_INFO("%s: Waking up", sensorName); + LOG_INFO("%s Waking", sensorName); if (scd4x.wakeUp() != SCD4X_NO_ERROR) { LOG_ERROR("%s: wakeUp() failed", sensorName); @@ -715,21 +701,18 @@ uint32_t SCD4XSensor::wakeUp() { #ifdef SCD4X_I2C_CLOCK_SPEED - LOG_INFO("%s: reclock to %uHz", sensorName, SCD4X_I2C_CLOCK_SPEED); reClockI2C.setClock(SCD4X_I2C_CLOCK_SPEED); #endif /* SCD4X_I2C_CLOCK_SPEED */ if (startMeasurement()) { co2MeasureStarted = getTime(); #ifdef SCD4X_I2C_CLOCK_SPEED - LOG_INFO("%s: restoring clock speed", sensorName); reClockI2C.restoreClock(); #endif /* SCD4X_I2C_CLOCK_SPEED */ return SCD4X_WARMUP_MS; } #ifdef SCD4X_I2C_CLOCK_SPEED - LOG_INFO("%s: restoring clock speed", sensorName); reClockI2C.restoreClock(); #endif /* SCD4X_I2C_CLOCK_SPEED */ @@ -743,14 +726,12 @@ uint32_t SCD4XSensor::wakeUp() void SCD4XSensor::sleep() { #ifdef SCD4X_I2C_CLOCK_SPEED - LOG_INFO("%s: reclock to %uHz", sensorName, SCD4X_I2C_CLOCK_SPEED); reClockI2C.setClock(SCD4X_I2C_CLOCK_SPEED); #endif /* SCD4X_I2C_CLOCK_SPEED */ stopMeasurement(); #ifdef SCD4X_I2C_CLOCK_SPEED - LOG_INFO("%s: restoring clock speed", sensorName); reClockI2C.restoreClock(); #endif /* SCD4X_I2C_CLOCK_SPEED */ } @@ -792,7 +773,6 @@ AdminMessageHandleResult SCD4XSensor::handleAdminMessage(const meshtastic_MeshPa AdminMessageHandleResult result; #ifdef SCD4X_I2C_CLOCK_SPEED - LOG_INFO("%s: reclock to %uHz", sensorName, SCD4X_I2C_CLOCK_SPEED); reClockI2C.setClock(SCD4X_I2C_CLOCK_SPEED); #endif /* SCD4X_I2C_CLOCK_SPEED */ @@ -897,7 +877,6 @@ AdminMessageHandleResult SCD4XSensor::handleAdminMessage(const meshtastic_MeshPa this->startMeasurement(); #ifdef SCD4X_I2C_CLOCK_SPEED - LOG_INFO("%s: restoring clock speed", sensorName); reClockI2C.restoreClock(); #endif /* SCD4X_I2C_CLOCK_SPEED */ diff --git a/src/modules/Telemetry/Sensor/SEN5XSensor.cpp b/src/modules/Telemetry/Sensor/SEN5XSensor.cpp index 02105e137d..7a721433c0 100644 --- a/src/modules/Telemetry/Sensor/SEN5XSensor.cpp +++ b/src/modules/Telemetry/Sensor/SEN5XSensor.cpp @@ -132,7 +132,6 @@ bool SEN5XSensor::sendCommand(uint16_t command, uint8_t *buffer, uint8_t byteNum } #ifdef SEN5X_I2C_CLOCK_SPEED - LOG_DEBUG("%s: Reclock to %uHz", sensorName, SEN5X_I2C_CLOCK_SPEED); reClockI2C.setClock(SEN5X_I2C_CLOCK_SPEED); #endif /* SEN5X_I2C_CLOCK_SPEED */ @@ -145,7 +144,6 @@ bool SEN5XSensor::sendCommand(uint16_t command, uint8_t *buffer, uint8_t byteNum uint8_t i2c_error = _bus->endTransmission(); #ifdef SEN5X_I2C_CLOCK_SPEED - LOG_DEBUG("%s: restoring clock speed", sensorName); reClockI2C.restoreClock(); #endif /* SEN5X_I2C_CLOCK_SPEED */ @@ -164,7 +162,6 @@ bool SEN5XSensor::sendCommand(uint16_t command, uint8_t *buffer, uint8_t byteNum uint8_t SEN5XSensor::readBuffer(uint8_t *buffer, uint8_t byteNumber) { #ifdef SEN5X_I2C_CLOCK_SPEED - LOG_DEBUG("%s: Reclock to %uHz", sensorName, SEN5X_I2C_CLOCK_SPEED); reClockI2C.setClock(SEN5X_I2C_CLOCK_SPEED); #endif /* SEN5X_I2C_CLOCK_SPEED */ @@ -172,7 +169,6 @@ uint8_t SEN5XSensor::readBuffer(uint8_t *buffer, uint8_t byteNumber) if (readBytes != byteNumber) { LOG_ERROR("%s: Error reading I2C bus", sensorName); #ifdef SEN5X_I2C_CLOCK_SPEED - LOG_DEBUG("%s: restoring clock speed", sensorName); reClockI2C.restoreClock(); #endif /* SEN5X_I2C_CLOCK_SPEED */ return 0; @@ -188,7 +184,6 @@ uint8_t SEN5XSensor::readBuffer(uint8_t *buffer, uint8_t byteNumber) if (recvCRC != calcCRC) { LOG_ERROR("%s: Checksum error receiving msg", sensorName); #ifdef SEN5X_I2C_CLOCK_SPEED - LOG_DEBUG("%s: restoring clock speed", sensorName); reClockI2C.restoreClock(); #endif /* SEN5X_I2C_CLOCK_SPEED */ return 0; @@ -198,7 +193,6 @@ uint8_t SEN5XSensor::readBuffer(uint8_t *buffer, uint8_t byteNumber) } #ifdef SEN5X_I2C_CLOCK_SPEED - LOG_DEBUG("%s: restoring clock speed", sensorName); reClockI2C.restoreClock(); #endif /* SEN5X_I2C_CLOCK_SPEED */ @@ -489,7 +483,7 @@ bool SEN5XSensor::isActive() uint32_t SEN5XSensor::wakeUp() { - LOG_DEBUG("%s: Waking up sensor", sensorName); + LOG_TRACE("%s Waking", sensorName); if (!sendCommand(SEN5X_START_MEASUREMENT)) { LOG_ERROR("%s: Error starting measurement", sensorName); @@ -513,7 +507,7 @@ bool SEN5XSensor::vocStateStable() uint32_t now; now = getTime(); uint32_t sinceFirstMeasureStarted = (now - rhtGasMeasureStarted); - LOG_DEBUG("%s: sinceFirstMeasureStarted: %us", sensorName, sinceFirstMeasureStarted); + LOG_TRACE("%s: sinceFirstMeasureStarted: %us", sensorName, sinceFirstMeasureStarted); return sinceFirstMeasureStarted > SEN5X_VOC_STATE_WARMUP_S; } @@ -661,7 +655,7 @@ bool SEN5XSensor::readValues() LOG_ERROR("%s: Error sending read command", sensorName); return false; } - LOG_DEBUG("%s: Reading PM Values", sensorName); + LOG_TRACE("%s: Reading PM Values", sensorName); delay(20); // From Sensirion Datasheet uint8_t dataBuffer[16]{}; @@ -692,16 +686,16 @@ bool SEN5XSensor::readValues() sen5xmeasurement.vocIndex = !isnan(int_vocIndex) ? int_vocIndex / 10.0f : FLT_MAX; sen5xmeasurement.noxIndex = !isnan(int_noxIndex) ? int_noxIndex / 10.0f : FLT_MAX; - LOG_DEBUG("%s: Got readings: pM1p0=%u, pM2p5=%u, pM4p0=%u, pM10p0=%u", sensorName, sen5xmeasurement.pM1p0, + LOG_TRACE("%s: Got readings: pM1p0=%u, pM2p5=%u, pM4p0=%u, pM10p0=%u", sensorName, sen5xmeasurement.pM1p0, sen5xmeasurement.pM2p5, sen5xmeasurement.pM4p0, sen5xmeasurement.pM10p0); if (model != SEN50) { - LOG_DEBUG("%s: Got readings: humidity=%.2f, temperature=%.2f, vocIndex=%.2f", sensorName, sen5xmeasurement.humidity, + LOG_TRACE("%s: Got readings: humidity=%.2f, temperature=%.2f, vocIndex=%.2f", sensorName, sen5xmeasurement.humidity, sen5xmeasurement.temperature, sen5xmeasurement.vocIndex); } if (model == SEN55) { - LOG_DEBUG("%s: Got readings: noxIndex=%.2f", sensorName, sen5xmeasurement.noxIndex); + LOG_TRACE("%s: Got readings: noxIndex=%.2f", sensorName, sen5xmeasurement.noxIndex); } return true; @@ -714,7 +708,7 @@ bool SEN5XSensor::readPNValues(bool cumulative) return false; } - LOG_DEBUG("%s: Reading PN Values", sensorName); + LOG_TRACE("%s: Reading PN Values", sensorName); delay(20); // From Sensirion Datasheet uint8_t dataBuffer[20]{}; @@ -754,7 +748,7 @@ bool SEN5XSensor::readPNValues(bool cumulative) sen5xmeasurement.pN1p0 -= sen5xmeasurement.pN0p5; } - LOG_DEBUG("%s: Got readings: pN0p5=%u, pN1p0=%u, pN2p5=%u, pN4p0=%u, pN10p0=%u, tSize=%.2f", sensorName, + LOG_TRACE("%s: Got readings: pN0p5=%u, pN1p0=%u, pN2p5=%u, pN4p0=%u, pN10p0=%u, tSize=%.2f", sensorName, sen5xmeasurement.pN0p5, sen5xmeasurement.pN1p0, sen5xmeasurement.pN2p5, sen5xmeasurement.pN4p0, sen5xmeasurement.pN10p0, sen5xmeasurement.tSize); @@ -813,7 +807,7 @@ int32_t SEN5XSensor::pendingForReadyMs() uint32_t now; now = getTime(); uint32_t sincePmMeasureStarted = (now - pmMeasureStarted) * 1000; - LOG_DEBUG("%s: Since measure started: %ums", sensorName, sincePmMeasureStarted); + LOG_TRACE("%s: Since measure started: %ums", sensorName, sincePmMeasureStarted); switch (state) { case SEN5X_MEASUREMENT: { @@ -857,7 +851,7 @@ bool SEN5XSensor::getMetrics(meshtastic_Telemetry *measurement) { LOG_INFO("%s: Get metrics", sensorName); if (!isActive()) { - LOG_INFO("%s: not in measurement mode", sensorName); + LOG_INFO("%s: Not in measurement mode", sensorName); return false; } diff --git a/src/modules/Telemetry/Sensor/SFA30Sensor.cpp b/src/modules/Telemetry/Sensor/SFA30Sensor.cpp index 5befb44748..aa19baf0fa 100644 --- a/src/modules/Telemetry/Sensor/SFA30Sensor.cpp +++ b/src/modules/Telemetry/Sensor/SFA30Sensor.cpp @@ -17,8 +17,6 @@ bool SFA30Sensor::initDevice(TwoWire *bus, ScanI2C::FoundDevice *dev) #ifdef SFA30_I2C_CLOCK_SPEED _port = dev->address.port; reClockI2C.setup(_bus, _port); - - LOG_INFO("%s attempting to reclock speed to %uHz", sensorName, SFA30_I2C_CLOCK_SPEED); reClockI2C.setClock(SFA30_I2C_CLOCK_SPEED); #endif /* SFA30_I2C_CLOCK_SPEED */ @@ -27,7 +25,6 @@ bool SFA30Sensor::initDevice(TwoWire *bus, ScanI2C::FoundDevice *dev) if (this->isError(sfa30.deviceReset())) { #ifdef SFA30_I2C_CLOCK_SPEED - LOG_INFO("%s restoring clock speed", sensorName); reClockI2C.restoreClock(); #endif /* SFA30_I2C_CLOCK_SPEED */ return false; @@ -36,7 +33,6 @@ bool SFA30Sensor::initDevice(TwoWire *bus, ScanI2C::FoundDevice *dev) state = State::IDLE; if (this->isError(sfa30.startContinuousMeasurement())) { #ifdef SFA30_I2C_CLOCK_SPEED - LOG_INFO("%s restoring clock speed", sensorName); reClockI2C.restoreClock(); #endif /* SFA30_I2C_CLOCK_SPEED */ return false; @@ -45,14 +41,13 @@ bool SFA30Sensor::initDevice(TwoWire *bus, ScanI2C::FoundDevice *dev) LOG_INFO("%s starting measurement", sensorName); #ifdef SFA30_I2C_CLOCK_SPEED - LOG_INFO("%s restoring clock speed", sensorName); reClockI2C.restoreClock(); #endif /* SFA30_I2C_CLOCK_SPEED */ status = 1; state = State::ACTIVE; measureStarted = getTime(); - LOG_INFO("%s Enabled", sensorName); + LOG_INFO("%s: Enabled", sensorName); initI2CSensor(); return true; @@ -71,17 +66,15 @@ bool SFA30Sensor::isError(uint16_t response) void SFA30Sensor::sleep() { #ifdef SFA30_I2C_CLOCK_SPEED - LOG_DEBUG("%s attempting to reclock speed to %uHz", sensorName, SFA30_I2C_CLOCK_SPEED); reClockI2C.setClock(SFA30_I2C_CLOCK_SPEED); #endif /* SFA30_I2C_CLOCK_SPEED */ // Note - not recommended for this sensor on a periodic basis if (this->isError(sfa30.stopMeasurement())) { - LOG_ERROR("%s: can't stop measurement", sensorName); + LOG_ERROR("%s: Can't stop measurement", sensorName); }; #ifdef SFA30_I2C_CLOCK_SPEED - LOG_DEBUG("%s restoring clock speed", sensorName); reClockI2C.restoreClock(); #endif /* SFA30_I2C_CLOCK_SPEED */ @@ -93,21 +86,18 @@ void SFA30Sensor::sleep() uint32_t SFA30Sensor::wakeUp() { #ifdef SFA30_I2C_CLOCK_SPEED - LOG_DEBUG("%s attempting to reclock speed to %uHz", sensorName, SFA30_I2C_CLOCK_SPEED); reClockI2C.setClock(SFA30_I2C_CLOCK_SPEED); #endif /* SFA30_I2C_CLOCK_SPEED */ - LOG_DEBUG("Waking up %s", sensorName); + LOG_DEBUG("Waking %s", sensorName); if (this->isError(sfa30.startContinuousMeasurement())) { #ifdef SFA30_I2C_CLOCK_SPEED - LOG_DEBUG("%s restoring clock speed", sensorName); reClockI2C.restoreClock(); #endif /* SFA30_I2C_CLOCK_SPEED */ return 0; } #ifdef SFA30_I2C_CLOCK_SPEED - LOG_DEBUG("%s restoring clock speed", sensorName); reClockI2C.restoreClock(); #endif /* SFA30_I2C_CLOCK_SPEED */ @@ -154,21 +144,18 @@ bool SFA30Sensor::getMetrics(meshtastic_Telemetry *measurement) float temperature = 0.0; #ifdef SFA30_I2C_CLOCK_SPEED - LOG_DEBUG("%s attempting to reclock speed to %uHz", sensorName, SFA30_I2C_CLOCK_SPEED); reClockI2C.setClock(SFA30_I2C_CLOCK_SPEED); #endif /* SFA30_I2C_CLOCK_SPEED */ if (this->isError(sfa30.readMeasuredValues(hcho, humidity, temperature))) { LOG_WARN("%s: No values", sensorName); #ifdef SFA30_I2C_CLOCK_SPEED - LOG_DEBUG("%s restoring clock speed", sensorName); reClockI2C.restoreClock(); #endif /* SFA30_I2C_CLOCK_SPEED */ return false; } #ifdef SFA30_I2C_CLOCK_SPEED - LOG_DEBUG("%s restoring clock speed", sensorName); reClockI2C.restoreClock(); #endif /* SFA30_I2C_CLOCK_SPEED */ diff --git a/src/modules/Telemetry/Sensor/SHTXXSensor.cpp b/src/modules/Telemetry/Sensor/SHTXXSensor.cpp index 92cac7f777..1512e7cc8c 100644 --- a/src/modules/Telemetry/Sensor/SHTXXSensor.cpp +++ b/src/modules/Telemetry/Sensor/SHTXXSensor.cpp @@ -50,12 +50,12 @@ bool SHTXXSensor::initDevice(TwoWire *bus, ScanI2C::FoundDevice *dev) _address = dev->address.address; if (sht.init(*_bus)) { - LOG_INFO("%s: init(): success", sensorName); + LOG_INFO("%s init success", sensorName); getSensorVariant(sht.mSensorType); LOG_INFO("%s Sensor detected: %s on 0x%x", sensorName, sensorVariant, _address); status = 1; } else { - LOG_ERROR("%s: init(): failed", sensorName); + LOG_ERROR("%s init failed", sensorName); } initI2CSensor(); diff --git a/src/modules/TrafficManagementModule.cpp b/src/modules/TrafficManagementModule.cpp index 5c8f86eb06..b4c5fae98e 100644 --- a/src/modules/TrafficManagementModule.cpp +++ b/src/modules/TrafficManagementModule.cpp @@ -19,6 +19,7 @@ #include #include +#define TM_LOG_TRACE(fmt, ...) LOG_TRACE("[TM] " fmt, ##__VA_ARGS__) #define TM_LOG_DEBUG(fmt, ...) LOG_DEBUG("[TM] " fmt, ##__VA_ARGS__) #define TM_LOG_INFO(fmt, ...) LOG_INFO("[TM] " fmt, ##__VA_ARGS__) #define TM_LOG_WARN(fmt, ...) LOG_WARN("[TM] " fmt, ##__VA_ARGS__) @@ -634,7 +635,7 @@ void TrafficManagementModule::maintainNodeInfoCacheLocked() // O(entries x members) every 60 s under cacheLock. The hourly reconcile pass // owns it (see reconcileNodeInfoFromNodeDBLocked). } - TM_LOG_DEBUG("NodeInfo cache: %u/%u (%u went stale)", static_cast(countNodeInfoEntriesLocked()), + TM_LOG_TRACE("NodeInfo cache: %u/%u (%u went stale)", static_cast(countNodeInfoEntriesLocked()), static_cast(nodeInfoTargetEntries()), static_cast(nodeInfoSaturated)); // Anti-entropy: seed identities NodeDB knows but this cache lacks - a full pass at @@ -1323,7 +1324,7 @@ int32_t TrafficManagementModule::runOnce() } } - TM_LOG_DEBUG("Maintenance: %u active, %u expired, %u/%u slots, %lums elapsed", activeEntries, expiredEntries, + TM_LOG_TRACE("Maintenance: %u active, %u expired, %u/%u slots, %lums elapsed", activeEntries, expiredEntries, static_cast(activeEntries), static_cast(cacheSize()), static_cast(TrafficManagementModule::clockMs() - sweepStartMs)); @@ -1400,7 +1401,7 @@ bool TrafficManagementModule::shouldDropPosition(const meshtastic_MeshPacket *p, const bool withinInterval = hasPositionState && (windowTicks != 0) && (static_cast(nowPosTick - entry->pos_time) < windowTicks); - TM_LOG_DEBUG("Position dedup 0x%08x: fp=0x%02x prev=0x%02x same=%d within=%d new=%d", p->from, fingerprint, + TM_LOG_TRACE("Position dedup 0x%08x: fp=0x%02x prev=0x%02x same=%d within=%d new=%d", p->from, fingerprint, entry->pos_fingerprint, samePosition, withinInterval, isNew); // Update cache entry (raw tick; 0 is a valid tick value) diff --git a/src/platform/portduino/SimRadio.cpp b/src/platform/portduino/SimRadio.cpp index c7aac40f3f..d60c34db07 100644 --- a/src/platform/portduino/SimRadio.cpp +++ b/src/platform/portduino/SimRadio.cpp @@ -27,7 +27,7 @@ ErrorCode SimRadio::send(meshtastic_MeshPacket *p) // set (random) transmit delay to let others reconfigure their radio, // to avoid collisions and implement timing-based flooding - LOG_DEBUG("Set random delay before tx"); + LOG_TRACE("Set random delay before tx"); setTransmitDelay(); return res; } @@ -47,7 +47,7 @@ void SimRadio::setTransmitDelay() startTransmitTimer(true); } else { // If there is a SNR, start a timer scaled based on that SNR. - LOG_DEBUG("rx_snr found. hop_limit:%d rx_snr:%f", p->hop_limit, p->rx_snr); + LOG_TRACE("rx_snr found. hop_limit:%d rx_snr:%f", p->hop_limit, p->rx_snr); startTransmitTimerRebroadcast(p); } } @@ -169,7 +169,7 @@ void SimRadio::onNotify(uint32_t notification) startTransmitTimer(); break; } - LOG_DEBUG("delay done"); + LOG_TRACE("delay done"); // If we are not currently in receive mode, then restart the random delay (this can happen if the main thread // has placed the unit into standby) FIXME, how will this work if the chipset is in sleep mode? @@ -363,7 +363,7 @@ void SimRadio::handleReceiveInterrupt() return; } - LOG_DEBUG("HANDLE RECEIVE INTERRUPT"); + LOG_TRACE("HANDLE RECEIVE INTERRUPT"); rxGood++; meshtastic_MeshPacket *mp = packetPool.allocCopy(*receivingPacket); // keep a copy in packetPool diff --git a/variants/esp32/chatter2/variant.h b/variants/esp32/chatter2/variant.h index d13db08c6a..0dc5cfaa95 100644 --- a/variants/esp32/chatter2/variant.h +++ b/variants/esp32/chatter2/variant.h @@ -5,7 +5,7 @@ ////////////////////////////////////////////////////////////////////////////////// // Debugging -// #define GPS_DEBUG +// #define GPS_DEBUG 1 // Lora #define USE_LLCC68 // Original Chatter2 with LLCC68 module diff --git a/variants/esp32/tbeam/variant.h b/variants/esp32/tbeam/variant.h index 1bab8c3c3d..3d13f9cbdb 100644 --- a/variants/esp32/tbeam/variant.h +++ b/variants/esp32/tbeam/variant.h @@ -43,7 +43,7 @@ #define GPS_UBLOX #define GPS_RX_PIN 34 #define GPS_TX_PIN 12 -// #define GPS_DEBUG +// #define GPS_DEBUG 1 // Used when the display shield is chosen #ifdef USE_ST7796 diff --git a/variants/nrf52840/diy/nrf52_promicro_diy_tcxo/variant.h b/variants/nrf52840/diy/nrf52_promicro_diy_tcxo/variant.h index 323873660b..5a6f0074e5 100644 --- a/variants/nrf52840/diy/nrf52_promicro_diy_tcxo/variant.h +++ b/variants/nrf52840/diy/nrf52_promicro_diy_tcxo/variant.h @@ -135,7 +135,7 @@ https://github.com/brad112358/easy_E22 #endif #define GPS_UBLOX -// define GPS_DEBUG +// #define GPS_DEBUG 1 // UART interfaces #define PIN_SERIAL1_TX GPS_TX_PIN diff --git a/variants/nrf52840/dls_Minimesh_Lite/variant.h b/variants/nrf52840/dls_Minimesh_Lite/variant.h index 32c16f06df..47c6727dd5 100644 --- a/variants/nrf52840/dls_Minimesh_Lite/variant.h +++ b/variants/nrf52840/dls_Minimesh_Lite/variant.h @@ -57,7 +57,7 @@ extern "C" { #define PIN_GPS_EN (0 + 24) #define GPS_UBLOX -// define GPS_DEBUG +// #define GPS_DEBUG 1 // UART interfaces #define PIN_SERIAL1_TX GPS_TX_PIN diff --git a/variants/nrf52840/seeed_wio_tracker_L1/variant.h b/variants/nrf52840/seeed_wio_tracker_L1/variant.h index 9e1df0fa34..aeaa8f44af 100644 --- a/variants/nrf52840/seeed_wio_tracker_L1/variant.h +++ b/variants/nrf52840/seeed_wio_tracker_L1/variant.h @@ -129,7 +129,7 @@ static const uint8_t SCL = PIN_WIRE_SCL; #define PIN_GPS_STANDBY D0 -// #define GPS_DEBUG +// #define GPS_DEBUG 1 // #define GPS_EN D18 // P1.05 #endif diff --git a/variants/nrf52840/seeed_wio_tracker_L1_eink/variant.h b/variants/nrf52840/seeed_wio_tracker_L1_eink/variant.h index 1ff18ec2fa..9dd92a5f5d 100644 --- a/variants/nrf52840/seeed_wio_tracker_L1_eink/variant.h +++ b/variants/nrf52840/seeed_wio_tracker_L1_eink/variant.h @@ -137,7 +137,7 @@ static const uint8_t SCL = PIN_WIRE_SCL; #define PIN_GPS_STANDBY D0 -// #define GPS_DEBUG +// #define GPS_DEBUG 1 // #define GPS_EN D18 // P1.05 #endif diff --git a/variants/nrf52840/t-echo-lite/variant.h b/variants/nrf52840/t-echo-lite/variant.h index 54c7bdfb51..fe2c3076c8 100644 --- a/variants/nrf52840/t-echo-lite/variant.h +++ b/variants/nrf52840/t-echo-lite/variant.h @@ -131,7 +131,7 @@ static const uint8_t A0 = PIN_A0; #define PIN_SPI1_SCK PIN_EINK_SCLK // GPS pins -// #define GPS_DEBUG +// #define GPS_DEBUG 1 #define GPS_L76K #define GPS_BAUDRATE 9600 #define HAS_GPS 1