BLE based logging (#4146)

* WIP log characteristic

* Bluetooth logging plumbing

* Characteristic

* Callback

* Check for nullptr

* Esp32 bluetooth impl

* Formatting

* Add thread name and log level

* Add settings guard

* Remove comments

* Field name

* Fixes esp32

* Open it up

* Whoops

* Move va_end past our logic

src/BluetoothCommon.cpp

@@ -11,3 +11,5 @@ const uint8_t FROMRADIO_UUID_16[16u] = {0x02, 0x00, 0x12, 0xac, 0x42, 0x02, 0x78
                                         0xed, 0x11, 0x93, 0x49, 0x9e, 0xe6, 0x55, 0x2c};
 const uint8_t FROMNUM_UUID_16[16u] = {0x53, 0x44, 0xe3, 0x47, 0x75, 0xaa, 0x70, 0xa6,
                                       0x66, 0x4f, 0x00, 0xa8, 0x8c, 0xa1, 0x9d, 0xed};
+const uint8_t LOGRADIO_UUID_16[16u] = {0xe2, 0xf2, 0x1e, 0xbe, 0xc5, 0x15, 0xcf, 0xaa,
+                                       0x6b, 0x43, 0xfa, 0x78, 0x38, 0xd2, 0x6f, 0x6c};

src/BluetoothCommon.h

@@ -11,10 +11,11 @@
 #define TORADIO_UUID "f75c76d2-129e-4dad-a1dd-7866124401e7"
 #define FROMRADIO_UUID "2c55e69e-4993-11ed-b878-0242ac120002"
 #define FROMNUM_UUID "ed9da18c-a800-4f66-a670-aa7547e34453"
+#define LOGRADIO_UUID "6c6fd238-78fa-436b-aacf-15c5be1ef2e2"
 
 // NRF52 wants these constants as byte arrays
 // Generated here https://yupana-engineering.com/online-uuid-to-c-array-converter - but in REVERSE BYTE ORDER
-extern const uint8_t MESH_SERVICE_UUID_16[], TORADIO_UUID_16[16u], FROMRADIO_UUID_16[], FROMNUM_UUID_16[];
+extern const uint8_t MESH_SERVICE_UUID_16[], TORADIO_UUID_16[16u], FROMRADIO_UUID_16[], FROMNUM_UUID_16[], LOGRADIO_UUID_16[];
 
 /// Given a level between 0-100, update the BLE attribute
 void updateBatteryLevel(uint8_t level);
@@ -27,4 +28,5 @@ class BluetoothApi
     virtual void clearBonds();
     virtual bool isConnected();
     virtual int getRssi() = 0;
+    virtual void sendLog(const char *logMessage);
 };

src/RedirectablePrint.cpp

@@ -3,6 +3,7 @@
 #include "RTC.h"
 #include "concurrency/OSThread.h"
 #include "configuration.h"
+#include "main.h"
 #include <assert.h>
 #include <cstring>
 #include <memory>
@@ -166,9 +167,43 @@ size_t RedirectablePrint::log(const char *logLevel, const char *format, ...)
         }
 #endif
 
-        va_end(arg);
-
         isContinuationMessage = !hasNewline;
+
+        if (config.bluetooth.device_logging_enabled) {
+            bool isBleConnected = false;
+#ifdef ARCH_ESP32
+            isBleConnected = nimbleBluetooth && nimbleBluetooth->isActive() && nimbleBluetooth->isConnected();
+#elif defined(ARCH_NRF52)
+            isBleConnected = nrf52Bluetooth != nullptr && nrf52Bluetooth->isConnected();
+#endif
+            if (isBleConnected) {
+                char *message;
+                size_t initialLen;
+                size_t len;
+                initialLen = strlen(format);
+                message = new char[initialLen + 1];
+                len = vsnprintf(message, initialLen + 1, format, arg);
+                if (len > initialLen) {
+                    delete[] message;
+                    message = new char[len + 1];
+                    vsnprintf(message, len + 1, format, arg);
+                }
+                auto thread = concurrency::OSThread::currentThread;
+#ifdef ARCH_ESP32
+                if (thread)
+                    nimbleBluetooth->sendLog(mt_sprintf("%s | [%s] %s", logLevel, thread->ThreadName.c_str(), message).c_str());
+                else
+                    nimbleBluetooth->sendLog(mt_sprintf("%s | %s", logLevel, message).c_str());
+#elif defined(ARCH_NRF52)
+                if (thread)
+                    nrf52Bluetooth->sendLog(mt_sprintf("%s | [%s] %s", logLevel, thread->ThreadName.c_str(), message).c_str());
+                else
+                    nrf52Bluetooth->sendLog(mt_sprintf("%s | %s", logLevel, message).c_str());
+#endif
+                delete[] message;
+            }
+        }
+        va_end(arg);
 #ifdef HAS_FREE_RTOS
         xSemaphoreGive(inDebugPrint);
 #else

src/main.cpp

@@ -48,7 +48,6 @@ NimbleBluetooth *nimbleBluetooth = nullptr;
 #ifdef ARCH_NRF52
 #include "NRF52Bluetooth.h"
 NRF52Bluetooth *nrf52Bluetooth = nullptr;
-;
 #endif
 
 #if HAS_WIFI

src/nimble/NimbleBluetooth.cpp

@@ -12,6 +12,7 @@
 
 NimBLECharacteristic *fromNumCharacteristic;
 NimBLECharacteristic *BatteryCharacteristic;
+NimBLECharacteristic *logRadioCharacteristic;
 NimBLEServer *bleServer;
 
 static bool passkeyShowing;
@@ -58,7 +59,6 @@ class NimbleBluetoothFromRadioCallback : public NimBLECharacteristicCallbacks
 {
     virtual void onRead(NimBLECharacteristic *pCharacteristic)
     {
-        LOG_INFO("From Radio onread\n");
         uint8_t fromRadioBytes[meshtastic_FromRadio_size];
         size_t numBytes = bluetoothPhoneAPI->getFromRadio(fromRadioBytes);
 
@@ -180,6 +180,7 @@ void NimbleBluetooth::setupService()
         ToRadioCharacteristic = bleService->createCharacteristic(TORADIO_UUID, NIMBLE_PROPERTY::WRITE);
         FromRadioCharacteristic = bleService->createCharacteristic(FROMRADIO_UUID, NIMBLE_PROPERTY::READ);
         fromNumCharacteristic = bleService->createCharacteristic(FROMNUM_UUID, NIMBLE_PROPERTY::NOTIFY | NIMBLE_PROPERTY::READ);
+        logRadioCharacteristic = bleService->createCharacteristic(LOGRADIO_UUID, NIMBLE_PROPERTY::NOTIFY | NIMBLE_PROPERTY::READ);
     } else {
         ToRadioCharacteristic = bleService->createCharacteristic(
             TORADIO_UUID, NIMBLE_PROPERTY::WRITE | NIMBLE_PROPERTY::WRITE_AUTHEN | NIMBLE_PROPERTY::WRITE_ENC);
@@ -188,6 +189,9 @@ void NimbleBluetooth::setupService()
         fromNumCharacteristic =
             bleService->createCharacteristic(FROMNUM_UUID, NIMBLE_PROPERTY::NOTIFY | NIMBLE_PROPERTY::READ |
                                                                NIMBLE_PROPERTY::READ_AUTHEN | NIMBLE_PROPERTY::READ_ENC);
+        logRadioCharacteristic =
+            bleService->createCharacteristic(LOGRADIO_UUID, NIMBLE_PROPERTY::NOTIFY | NIMBLE_PROPERTY::READ |
+                                                                NIMBLE_PROPERTY::READ_AUTHEN | NIMBLE_PROPERTY::READ_ENC);
     }
     bluetoothPhoneAPI = new BluetoothPhoneAPI();
 
@@ -236,6 +240,14 @@ void NimbleBluetooth::clearBonds()
     NimBLEDevice::deleteAllBonds();
 }
 
+void NimbleBluetooth::sendLog(const char *logMessage)
+{
+    if (!bleServer || !isConnected() || strlen(logMessage) > 512) {
+        return;
+    }
+    logRadioCharacteristic->notify((uint8_t *)logMessage, strlen(logMessage));
+}
+
 void clearNVS()
 {
     NimBLEDevice::deleteAllBonds();

src/nimble/NimbleBluetooth.h

@@ -11,6 +11,7 @@ class NimbleBluetooth : BluetoothApi
     bool isActive();
     bool isConnected();
     int getRssi();
+    void sendLog(const char *logMessage);
 
   private:
     void setupService();

src/platform/nrf52/NRF52Bluetooth.cpp

@@ -7,16 +7,16 @@
 #include "mesh/mesh-pb-constants.h"
 #include <bluefruit.h>
 #include <utility/bonding.h>
-
 static BLEService meshBleService = BLEService(BLEUuid(MESH_SERVICE_UUID_16));
 static BLECharacteristic fromNum = BLECharacteristic(BLEUuid(FROMNUM_UUID_16));
 static BLECharacteristic fromRadio = BLECharacteristic(BLEUuid(FROMRADIO_UUID_16));
 static BLECharacteristic toRadio = BLECharacteristic(BLEUuid(TORADIO_UUID_16));
+static BLECharacteristic logRadio = BLECharacteristic(BLEUuid(LOGRADIO_UUID_16));
 
 static BLEDis bledis; // DIS (Device Information Service) helper class instance
 static BLEBas blebas; // BAS (Battery Service) helper class instance
-static BLEDfu bledfu; // DFU software update helper service
 
+static BLEDfu bledfu; // DFU software update helper service
 // This scratch buffer is used for various bluetooth reads/writes - but it is safe because only one bt operation can be in
 // process at once
 // static uint8_t trBytes[_max(_max(_max(_max(ToRadio_size, RadioConfig_size), User_size), MyNodeInfo_size), FromRadio_size)];
@@ -50,16 +50,14 @@ static BluetoothPhoneAPI *bluetoothPhoneAPI;
 
 void onConnect(uint16_t conn_handle)
 {
+
     // Get the reference to current connection
     BLEConnection *connection = Bluefruit.Connection(conn_handle);
     connectionHandle = conn_handle;
-
     char central_name[32] = {0};
     connection->getPeerName(central_name, sizeof(central_name));
-
     LOG_INFO("BLE Connected to %s\n", central_name);
 }
-
 /**
  * Callback invoked when a connection is dropped
  * @param conn_handle connection where this event happens
@@ -70,15 +68,13 @@ void onDisconnect(uint16_t conn_handle, uint8_t reason)
     // FIXME - we currently assume only one active connection
     LOG_INFO("BLE Disconnected, reason = 0x%x\n", reason);
 }
-
 void onCccd(uint16_t conn_hdl, BLECharacteristic *chr, uint16_t cccd_value)
 {
     // Display the raw request packet
     LOG_INFO("CCCD Updated: %u\n", cccd_value);
-
     // Check the characteristic this CCCD update is associated with in case
     // this handler is used for multiple CCCD records.
-    if (chr->uuid == fromNum.uuid) {
+    if (chr->uuid == fromNum.uuid || chr->uuid == logRadio.uuid) {
         if (chr->notifyEnabled(conn_hdl)) {
             LOG_INFO("fromNum 'Notify' enabled\n");
         } else {
@@ -86,21 +82,17 @@ void onCccd(uint16_t conn_hdl, BLECharacteristic *chr, uint16_t cccd_value)
         }
     }
 }
-
 void startAdv(void)
 {
     // Advertising packet
     Bluefruit.Advertising.addFlags(BLE_GAP_ADV_FLAGS_LE_ONLY_GENERAL_DISC_MODE);
-
     // IncludeService UUID
     // Bluefruit.ScanResponse.addService(meshBleService);
     Bluefruit.ScanResponse.addTxPower();
     Bluefruit.ScanResponse.addName();
-
     // Include Name
     // Bluefruit.Advertising.addName();
     Bluefruit.Advertising.addService(meshBleService);
-
     /* Start Advertising
      * - Enable auto advertising if disconnected
      * - Interval:  fast mode = 20 ms, slow mode = 152.5 ms
@@ -115,7 +107,6 @@ void startAdv(void)
     Bluefruit.Advertising.setFastTimeout(30);   // number of seconds in fast mode
     Bluefruit.Advertising.start(0); // 0 = Don't stop advertising after n seconds.  FIXME, we should stop advertising after X
 }
-
 // Just ack that the caller is allowed to read
 static void authorizeRead(uint16_t conn_hdl)
 {
@@ -123,7 +114,6 @@ static void authorizeRead(uint16_t conn_hdl)
     reply.params.write.gatt_status = BLE_GATT_STATUS_SUCCESS;
     sd_ble_gatts_rw_authorize_reply(conn_hdl, &reply);
 }
-
 /**
  * client is starting read, pull the bytes from our API class
  */
@@ -132,7 +122,6 @@ void onFromRadioAuthorize(uint16_t conn_hdl, BLECharacteristic *chr, ble_gatts_e
     if (request->offset == 0) {
         // If the read is long, we will get multiple authorize invocations - we only populate data on the first
         size_t numBytes = bluetoothPhoneAPI->getFromRadio(fromRadioBytes);
-
         // Someone is going to read our value as soon as this callback returns.  So fill it with the next message in the queue
         // or make empty if the queue is empty
         fromRadio.write(fromRadioBytes, numBytes);
@@ -141,37 +130,22 @@ void onFromRadioAuthorize(uint16_t conn_hdl, BLECharacteristic *chr, ble_gatts_e
     }
     authorizeRead(conn_hdl);
 }
-
 void onToRadioWrite(uint16_t conn_hdl, BLECharacteristic *chr, uint8_t *data, uint16_t len)
 {
     LOG_INFO("toRadioWriteCb data %p, len %u\n", data, len);
-
     bluetoothPhoneAPI->handleToRadio(data, len);
 }
 
-/**
- * client is starting read, pull the bytes from our API class
- */
-void onFromNumAuthorize(uint16_t conn_hdl, BLECharacteristic *chr, ble_gatts_evt_read_t *request)
-{
-    LOG_INFO("fromNumAuthorizeCb\n");
-
-    authorizeRead(conn_hdl);
-}
-
 void setupMeshService(void)
 {
     bluetoothPhoneAPI = new BluetoothPhoneAPI();
-
     meshBleService.begin();
-
     // Note: You must call .begin() on the BLEService before calling .begin() on
     // any characteristic(s) within that service definition.. Calling .begin() on
     // a BLECharacteristic will cause it to be added to the last BLEService that
     // was 'begin()'ed!
     auto secMode =
         config.bluetooth.mode == meshtastic_Config_BluetoothConfig_PairingMode_NO_PIN ? SECMODE_OPEN : SECMODE_ENC_NO_MITM;
-
     fromNum.setProperties(CHR_PROPS_NOTIFY | CHR_PROPS_READ);
     fromNum.setPermission(secMode, SECMODE_NO_ACCESS); // FIXME, secure this!!!
     fromNum.setFixedLen(
@@ -201,10 +175,15 @@ void setupMeshService(void)
     // We don't call this callback via the adafruit queue, because we can safely run in the BLE context
     toRadio.setWriteCallback(onToRadioWrite, false);
     toRadio.begin();
+
+    logRadio.setProperties(CHR_PROPS_NOTIFY | CHR_PROPS_READ);
+    logRadio.setPermission(secMode, SECMODE_NO_ACCESS);
+    logRadio.setMaxLen(512);
+    logRadio.setCccdWriteCallback(onCccd);
+    logRadio.write32(0);
+    logRadio.begin();
 }
-
 static uint32_t configuredPasskey;
-
 void NRF52Bluetooth::shutdown()
 {
     // Shutdown bluetooth for minimum power draw
@@ -214,29 +193,23 @@ void NRF52Bluetooth::shutdown()
     }
     Bluefruit.Advertising.stop();
 }
-
 void NRF52Bluetooth::startDisabled()
 {
     // Setup Bluetooth
     nrf52Bluetooth->setup();
-
     // Shutdown bluetooth for minimum power draw
     Bluefruit.Advertising.stop();
     Bluefruit.setTxPower(-40); // Minimum power
-
     LOG_INFO("Disabling NRF52 Bluetooth. (Workaround: tx power min, advertising stopped)\n");
 }
-
 bool NRF52Bluetooth::isConnected()
 {
     return Bluefruit.connected(connectionHandle);
 }
-
 int NRF52Bluetooth::getRssi()
 {
     return 0; // FIXME figure out where to source this
 }
-
 void NRF52Bluetooth::setup()
 {
     // Initialise the Bluefruit module
@@ -244,12 +217,10 @@ void NRF52Bluetooth::setup()
     Bluefruit.autoConnLed(false);
     Bluefruit.configPrphBandwidth(BANDWIDTH_MAX);
     Bluefruit.begin();
-
     // Clear existing data.
     Bluefruit.Advertising.stop();
     Bluefruit.Advertising.clearData();
     Bluefruit.ScanResponse.clearData();
-
     if (config.bluetooth.mode != meshtastic_Config_BluetoothConfig_PairingMode_NO_PIN) {
         configuredPasskey = config.bluetooth.mode == meshtastic_Config_BluetoothConfig_PairingMode_FIXED_PIN
                                 ? config.bluetooth.fixed_pin
@@ -268,37 +239,29 @@ void NRF52Bluetooth::setup()
     }
     // Set the advertised device name (keep it short!)
     Bluefruit.setName(getDeviceName());
-
     // Set the connect/disconnect callback handlers
     Bluefruit.Periph.setConnectCallback(onConnect);
     Bluefruit.Periph.setDisconnectCallback(onDisconnect);
-
     bledfu.setPermission(SECMODE_ENC_WITH_MITM, SECMODE_ENC_WITH_MITM);
     bledfu.begin(); // Install the DFU helper
-
     // Configure and Start the Device Information Service
     LOG_INFO("Configuring the Device Information Service\n");
     bledis.setModel(optstr(HW_VERSION));
     bledis.setFirmwareRev(optstr(APP_VERSION));
     bledis.begin();
-
     // Start the BLE Battery Service and set it to 100%
     LOG_INFO("Configuring the Battery Service\n");
     blebas.begin();
     blebas.write(0); // Unknown battery level for now
-
     // Setup the Heart Rate Monitor service using
     // BLEService and BLECharacteristic classes
     LOG_INFO("Configuring the Mesh bluetooth service\n");
     setupMeshService();
-
     // Setup the advertising packet(s)
     LOG_INFO("Setting up the advertising payload(s)\n");
     startAdv();
-
     LOG_INFO("Advertising\n");
 }
-
 void NRF52Bluetooth::resumeAdvertising()
 {
     Bluefruit.Advertising.restartOnDisconnect(true);
@@ -306,34 +269,28 @@ void NRF52Bluetooth::resumeAdvertising()
     Bluefruit.Advertising.setFastTimeout(30);   // number of seconds in fast mode
     Bluefruit.Advertising.start(0);
 }
-
 /// Given a level between 0-100, update the BLE attribute
 void updateBatteryLevel(uint8_t level)
 {
     blebas.write(level);
 }
-
 void NRF52Bluetooth::clearBonds()
 {
     LOG_INFO("Clearing bluetooth bonds!\n");
     bond_print_list(BLE_GAP_ROLE_PERIPH);
     bond_print_list(BLE_GAP_ROLE_CENTRAL);
-
     Bluefruit.Periph.clearBonds();
     Bluefruit.Central.clearBonds();
 }
-
 void NRF52Bluetooth::onConnectionSecured(uint16_t conn_handle)
 {
     LOG_INFO("BLE connection secured\n");
 }
-
 bool NRF52Bluetooth::onPairingPasskey(uint16_t conn_handle, uint8_t const passkey[6], bool match_request)
 {
     LOG_INFO("BLE pairing process started with passkey %.3s %.3s\n", passkey, passkey + 3);
     powerFSM.trigger(EVENT_BLUETOOTH_PAIR);
     screen->startBluetoothPinScreen(configuredPasskey);
-
     if (match_request) {
         uint32_t start_time = millis();
         while (millis() < start_time + 30000) {
@@ -344,13 +301,18 @@ bool NRF52Bluetooth::onPairingPasskey(uint16_t conn_handle, uint8_t const passke
     LOG_INFO("BLE passkey pairing: match_request=%i\n", match_request);
     return true;
 }
-
 void NRF52Bluetooth::onPairingCompleted(uint16_t conn_handle, uint8_t auth_status)
 {
     if (auth_status == BLE_GAP_SEC_STATUS_SUCCESS)
         LOG_INFO("BLE pairing success\n");
     else
         LOG_INFO("BLE pairing failed\n");
-
     screen->stopBluetoothPinScreen();
 }
+
+void NRF52Bluetooth::sendLog(const char *logMessage)
+{
+    if (!isConnected() || strlen(logMessage) > 512)
+        return;
+    logRadio.notify(logMessage);
+}

src/platform/nrf52/NRF52Bluetooth.h

@@ -13,10 +13,10 @@ class NRF52Bluetooth : BluetoothApi
     void clearBonds();
     bool isConnected();
     int getRssi();
+    void sendLog(const char *logMessage);
 
   private:
     static void onConnectionSecured(uint16_t conn_handle);
-    void convertToUint8(uint8_t target[4], uint32_t source);
     static bool onPairingPasskey(uint16_t conn_handle, uint8_t const passkey[6], bool match_request);
     static void onPairingCompleted(uint16_t conn_handle, uint8_t auth_status);
 };