[FL-2460] Rpc: debug request logging and cli log command (#1114)

* Rpc: debug request logging
* Furi, Cli: replace global thread callback with local ring buffers, fix log command

applications/cli/cli_commands.c

@@ -6,6 +6,7 @@
 #include <time.h>
 #include <notification/notification_messages.h>
 #include <loader/loader.h>
+#include <stream_buffer.h>
 
 // Close to ISO, `date +'%Y-%m-%d %H:%M:%S %u'`
 #define CLI_DATE_FORMAT "%.4d-%.2d-%.2d %.2d:%.2d:%.2d %d"
@@ -126,11 +127,28 @@ void cli_command_date(Cli* cli, string_t args, void* context) {
     }
 }
 
+#define CLI_COMMAND_LOG_RING_SIZE 2048
+#define CLI_COMMAND_LOG_BUFFER_SIZE 64
+
+void cli_command_log_tx_callback(const uint8_t* buffer, size_t size, void* context) {
+    xStreamBufferSend(context, buffer, size, 0);
+}
+
 void cli_command_log(Cli* cli, string_t args, void* context) {
-    furi_stdglue_set_global_stdout_callback(cli_stdout_callback);
-    printf("Press any key to stop...\r\n");
-    cli_getc(cli);
-    furi_stdglue_set_global_stdout_callback(NULL);
+    StreamBufferHandle_t ring = xStreamBufferCreate(CLI_COMMAND_LOG_RING_SIZE, 1);
+    uint8_t buffer[CLI_COMMAND_LOG_BUFFER_SIZE];
+
+    furi_hal_console_set_tx_callback(cli_command_log_tx_callback, ring);
+
+    printf("Press CTRL+C to stop...\r\n");
+    while(!cli_cmd_interrupt_received(cli)) {
+        size_t ret = xStreamBufferReceive(ring, buffer, CLI_COMMAND_LOG_BUFFER_SIZE, 50);
+        cli_write(cli, buffer, ret);
+    }
+
+    furi_hal_console_set_tx_callback(NULL, NULL);
+
+    vStreamBufferDelete(ring);
 }
 
 void cli_command_vibro(Cli* cli, string_t args, void* context) {

applications/rpc/rpc_app.c

@@ -4,12 +4,16 @@
 #include <furi.h>
 #include <loader/loader.h>
 
+#define TAG "RpcSystemApp"
+
 static void rpc_system_app_start_process(const PB_Main* request, void* context) {
     furi_assert(request);
     furi_assert(request->which_content == PB_Main_app_start_request_tag);
     RpcSession* session = (RpcSession*)context;
     furi_assert(session);
 
+    FURI_LOG_D(TAG, "Start");
+
     PB_CommandStatus result = PB_CommandStatus_ERROR_APP_CANT_START;
 
     Loader* loader = furi_record_open("loader");
@@ -43,6 +47,8 @@ static void rpc_system_app_lock_status_process(const PB_Main* request, void* con
     RpcSession* session = (RpcSession*)context;
     furi_assert(session);
 
+    FURI_LOG_D(TAG, "LockStatus");
+
     Loader* loader = furi_record_open("loader");
 
     PB_Main response = {

applications/rpc/rpc_gui.c

@@ -65,8 +65,10 @@ static int32_t rpc_system_gui_screen_stream_frame_transmit_thread(void* context)
 static void rpc_system_gui_start_screen_stream_process(const PB_Main* request, void* context) {
     furi_assert(request);
     furi_assert(context);
-    RpcGuiSystem* rpc_gui = context;
 
+    FURI_LOG_D(TAG, "StartScreenStream");
+
+    RpcGuiSystem* rpc_gui = context;
     RpcSession* session = rpc_gui->session;
     furi_assert(session);
 
@@ -103,6 +105,8 @@ static void rpc_system_gui_stop_screen_stream_process(const PB_Main* request, vo
     furi_assert(request);
     furi_assert(context);
 
+    FURI_LOG_D(TAG, "StopScreenStream");
+
     RpcGuiSystem* rpc_gui = context;
     RpcSession* session = rpc_gui->session;
     furi_assert(session);
@@ -132,6 +136,8 @@ static void
     furi_assert(request->which_content == PB_Main_gui_send_input_event_request_tag);
     furi_assert(context);
 
+    FURI_LOG_D(TAG, "SendInputEvent");
+
     RpcGuiSystem* rpc_gui = context;
     RpcSession* session = rpc_gui->session;
     furi_assert(session);
@@ -220,6 +226,8 @@ static void rpc_system_gui_start_virtual_display_process(const PB_Main* request,
     furi_assert(request);
     furi_assert(context);
 
+    FURI_LOG_D(TAG, "StartVirtualDisplay");
+
     RpcGuiSystem* rpc_gui = context;
     RpcSession* session = rpc_gui->session;
     furi_assert(session);
@@ -259,6 +267,8 @@ static void rpc_system_gui_stop_virtual_display_process(const PB_Main* request,
     furi_assert(request);
     furi_assert(context);
 
+    FURI_LOG_D(TAG, "StopVirtualDisplay");
+
     RpcGuiSystem* rpc_gui = context;
     RpcSession* session = rpc_gui->session;
     furi_assert(session);
@@ -282,6 +292,8 @@ static void rpc_system_gui_virtual_display_frame_process(const PB_Main* request,
     furi_assert(request);
     furi_assert(context);
 
+    FURI_LOG_D(TAG, "VirtualDisplayFrame");
+
     RpcGuiSystem* rpc_gui = context;
     RpcSession* session = rpc_gui->session;
     furi_assert(session);

applications/rpc/rpc_storage.c

@@ -12,7 +12,8 @@
 #include <lib/toolbox/md5.h>
 #include <update_util/lfs_backup.h>
 
-#define RPC_TAG "RPC_STORAGE"
+#define TAG "RpcStorage"
+
 #define MAX_NAME_LENGTH 255
 
 static const size_t MAX_DATA_SIZE = 512;
@@ -106,6 +107,8 @@ static void rpc_system_storage_info_process(const PB_Main* request, void* contex
     furi_assert(context);
     furi_assert(request->which_content == PB_Main_storage_info_request_tag);
 
+    FURI_LOG_D(TAG, "Info");
+
     RpcStorageSystem* rpc_storage = context;
     RpcSession* session = rpc_storage->session;
     furi_assert(session);
@@ -140,6 +143,8 @@ static void rpc_system_storage_stat_process(const PB_Main* request, void* contex
     furi_assert(context);
     furi_assert(request->which_content == PB_Main_storage_stat_request_tag);
 
+    FURI_LOG_D(TAG, "Stat");
+
     RpcStorageSystem* rpc_storage = context;
     RpcSession* session = rpc_storage->session;
     furi_assert(session);
@@ -205,6 +210,8 @@ static void rpc_system_storage_list_process(const PB_Main* request, void* contex
     furi_assert(context);
     furi_assert(request->which_content == PB_Main_storage_list_request_tag);
 
+    FURI_LOG_D(TAG, "List");
+
     RpcStorageSystem* rpc_storage = context;
     RpcSession* session = rpc_storage->session;
     furi_assert(session);
@@ -273,6 +280,8 @@ static void rpc_system_storage_read_process(const PB_Main* request, void* contex
     furi_assert(context);
     furi_assert(request->which_content == PB_Main_storage_read_request_tag);
 
+    FURI_LOG_D(TAG, "Read");
+
     RpcStorageSystem* rpc_storage = context;
     RpcSession* session = rpc_storage->session;
     furi_assert(session);
@@ -330,6 +339,8 @@ static void rpc_system_storage_write_process(const PB_Main* request, void* conte
     furi_assert(context);
     furi_assert(request->which_content == PB_Main_storage_write_request_tag);
 
+    FURI_LOG_D(TAG, "Write");
+
     RpcStorageSystem* rpc_storage = context;
     RpcSession* session = rpc_storage->session;
     furi_assert(session);
@@ -395,6 +406,9 @@ static void rpc_system_storage_delete_process(const PB_Main* request, void* cont
     furi_assert(request);
     furi_assert(request->which_content == PB_Main_storage_delete_request_tag);
     furi_assert(context);
+
+    FURI_LOG_D(TAG, "Delete");
+
     RpcStorageSystem* rpc_storage = context;
     RpcSession* session = rpc_storage->session;
     furi_assert(session);
@@ -433,6 +447,9 @@ static void rpc_system_storage_mkdir_process(const PB_Main* request, void* conte
     furi_assert(request);
     furi_assert(request->which_content == PB_Main_storage_mkdir_request_tag);
     furi_assert(context);
+
+    FURI_LOG_D(TAG, "Mkdir");
+
     RpcStorageSystem* rpc_storage = context;
     RpcSession* session = rpc_storage->session;
     furi_assert(session);
@@ -456,6 +473,9 @@ static void rpc_system_storage_md5sum_process(const PB_Main* request, void* cont
     furi_assert(request);
     furi_assert(request->which_content == PB_Main_storage_md5sum_request_tag);
     furi_assert(context);
+
+    FURI_LOG_D(TAG, "Md5sum");
+
     RpcStorageSystem* rpc_storage = context;
     RpcSession* session = rpc_storage->session;
     furi_assert(session);
@@ -521,6 +541,9 @@ static void rpc_system_storage_rename_process(const PB_Main* request, void* cont
     furi_assert(request);
     furi_assert(request->which_content == PB_Main_storage_rename_request_tag);
     furi_assert(context);
+
+    FURI_LOG_D(TAG, "Rename");
+
     RpcStorageSystem* rpc_storage = context;
     RpcSession* session = rpc_storage->session;
     furi_assert(session);
@@ -544,6 +567,8 @@ static void rpc_system_storage_backup_create_process(const PB_Main* request, voi
     furi_assert(request);
     furi_assert(request->which_content == PB_Main_storage_backup_create_request_tag);
 
+    FURI_LOG_D(TAG, "BackupCreate");
+
     RpcSession* session = (RpcSession*)context;
     furi_assert(session);
 
@@ -567,6 +592,8 @@ static void rpc_system_storage_backup_restore_process(const PB_Main* request, vo
     furi_assert(request);
     furi_assert(request->which_content == PB_Main_storage_backup_restore_request_tag);
 
+    FURI_LOG_D(TAG, "BackupRestore");
+
     RpcSession* session = (RpcSession*)context;
     furi_assert(session);
 

applications/rpc/rpc_system.c

@@ -7,6 +7,8 @@
 
 #include "rpc_i.h"
 
+#define TAG "RpcSystem"
+
 typedef struct {
     RpcSession* session;
     PB_Main* response;
@@ -16,6 +18,8 @@ static void rpc_system_system_ping_process(const PB_Main* request, void* context
     furi_assert(request);
     furi_assert(request->which_content == PB_Main_system_ping_request_tag);
 
+    FURI_LOG_D(TAG, "Ping");
+
     RpcSession* session = (RpcSession*)context;
     furi_assert(session);
 
@@ -46,6 +50,8 @@ static void rpc_system_system_reboot_process(const PB_Main* request, void* conte
     furi_assert(request);
     furi_assert(request->which_content == PB_Main_system_reboot_request_tag);
 
+    FURI_LOG_D(TAG, "Reboot");
+
     RpcSession* session = (RpcSession*)context;
     furi_assert(session);
 
@@ -84,6 +90,8 @@ static void rpc_system_system_device_info_process(const PB_Main* request, void*
     furi_assert(request);
     furi_assert(request->which_content == PB_Main_system_device_info_request_tag);
 
+    FURI_LOG_D(TAG, "DeviceInfo");
+
     RpcSession* session = (RpcSession*)context;
     furi_assert(session);
 
@@ -105,6 +113,8 @@ static void rpc_system_system_get_datetime_process(const PB_Main* request, void*
     furi_assert(request);
     furi_assert(request->which_content == PB_Main_system_get_datetime_request_tag);
 
+    FURI_LOG_D(TAG, "GetDatetime");
+
     RpcSession* session = (RpcSession*)context;
     furi_assert(session);
 
@@ -132,6 +142,8 @@ static void rpc_system_system_set_datetime_process(const PB_Main* request, void*
     furi_assert(request);
     furi_assert(request->which_content == PB_Main_system_set_datetime_request_tag);
 
+    FURI_LOG_D(TAG, "SetDatetime");
+
     RpcSession* session = (RpcSession*)context;
     furi_assert(session);
 
@@ -158,6 +170,8 @@ static void rpc_system_system_factory_reset_process(const PB_Main* request, void
     furi_assert(request);
     furi_assert(request->which_content == PB_Main_system_factory_reset_request_tag);
 
+    FURI_LOG_D(TAG, "Reset");
+
     RpcSession* session = (RpcSession*)context;
     furi_assert(session);
 
@@ -172,6 +186,8 @@ static void
     furi_assert(request);
     furi_assert(request->which_content == PB_Main_system_play_audiovisual_alert_request_tag);
 
+    FURI_LOG_D(TAG, "Alert");
+
     RpcSession* session = (RpcSession*)context;
     furi_assert(session);
 
@@ -186,6 +202,8 @@ static void rpc_system_system_protobuf_version_process(const PB_Main* request, v
     furi_assert(request);
     furi_assert(request->which_content == PB_Main_system_protobuf_version_request_tag);
 
+    FURI_LOG_D(TAG, "ProtobufVersion");
+
     RpcSession* session = (RpcSession*)context;
     furi_assert(session);
 
@@ -226,6 +244,8 @@ static void rpc_system_system_get_power_info_process(const PB_Main* request, voi
     furi_assert(request);
     furi_assert(request->which_content == PB_Main_system_power_info_request_tag);
 
+    FURI_LOG_D(TAG, "GetPowerInfo");
+
     RpcSession* session = (RpcSession*)context;
     furi_assert(session);
 
@@ -248,6 +268,8 @@ static void rpc_system_system_update_request_process(const PB_Main* request, voi
     furi_assert(request);
     furi_assert(request->which_content == PB_Main_system_update_request_tag);
 
+    FURI_LOG_D(TAG, "SystemUpdate");
+
     RpcSession* session = (RpcSession*)context;
     furi_assert(session);
 
@@ -305,4 +327,4 @@ void* rpc_system_system_alloc(RpcSession* session) {
 #endif
 
     return NULL;
-}
+}

core/furi/stdglue.c

@@ -17,7 +17,6 @@ DICT_DEF2(
 
 typedef struct {
     osMutexId_t mutex;
-    FuriStdglueCallbackDict_t global_outputs;
     FuriStdglueCallbackDict_t thread_outputs;
 } FuriStdglue;
 
@@ -31,17 +30,6 @@ static ssize_t stdout_write(void* _cookie, const char* data, size_t size) {
     if(state == osKernelRunning && thread_id &&
        osMutexAcquire(furi_stdglue->mutex, osWaitForever) == osOK) {
         // We are in the thread context
-        // Handle global callbacks
-        FuriStdglueCallbackDict_it_t it;
-        for(FuriStdglueCallbackDict_it(it, furi_stdglue->global_outputs);
-            !FuriStdglueCallbackDict_end_p(it);
-            FuriStdglueCallbackDict_next(it)) {
-            osThreadId_t it_thread = (osThreadId_t)FuriStdglueCallbackDict_ref(it)->key;
-            FuriStdglueWriteCallback it_callback = FuriStdglueCallbackDict_ref(it)->value;
-            if(thread_id != it_thread) {
-                it_callback(_cookie, data, size);
-            }
-        }
         // Handle thread callbacks
         FuriStdglueWriteCallback* callback_ptr =
             FuriStdglueCallbackDict_get(furi_stdglue->thread_outputs, (uint32_t)thread_id);
@@ -71,7 +59,6 @@ void furi_stdglue_init() {
     // Init outputs structures
     furi_stdglue->mutex = osMutexNew(NULL);
     furi_check(furi_stdglue->mutex);
-    FuriStdglueCallbackDict_init(furi_stdglue->global_outputs);
     FuriStdglueCallbackDict_init(furi_stdglue->thread_outputs);
     // Prepare and set stdout descriptor
     FILE* fp = fopencookie(
@@ -87,24 +74,6 @@ void furi_stdglue_init() {
     stdout = fp;
 }
 
-bool furi_stdglue_set_global_stdout_callback(FuriStdglueWriteCallback callback) {
-    furi_assert(furi_stdglue);
-    osThreadId_t thread_id = osThreadGetId();
-    if(thread_id) {
-        furi_check(osMutexAcquire(furi_stdglue->mutex, osWaitForever) == osOK);
-        if(callback) {
-            FuriStdglueCallbackDict_set_at(
-                furi_stdglue->global_outputs, (uint32_t)thread_id, callback);
-        } else {
-            FuriStdglueCallbackDict_erase(furi_stdglue->global_outputs, (uint32_t)thread_id);
-        }
-        furi_check(osMutexRelease(furi_stdglue->mutex) == osOK);
-        return true;
-    } else {
-        return false;
-    }
-}
-
 bool furi_stdglue_set_thread_stdout_callback(FuriStdglueWriteCallback callback) {
     furi_assert(furi_stdglue);
     osThreadId_t thread_id = osThreadGetId();

core/furi/stdglue.h

@@ -22,15 +22,6 @@ typedef void (*FuriStdglueWriteCallback)(void* _cookie, const char* data, size_t
 /** Initialized std library glue code */
 void furi_stdglue_init();
 
-/** Set global STDOUT callback
- *
- * @param      callback  callback or NULL to clear
- *
- * @return     true on success, otherwise fail
- * @warning    function is thread aware, use this API from the same thread
- */
-bool furi_stdglue_set_global_stdout_callback(FuriStdglueWriteCallback callback);
-
 /** Set STDOUT callback for your thread
  *
  * @param      callback  callback or NULL to clear

firmware/targets/f7/furi_hal/furi_hal_console.c

@@ -18,11 +18,21 @@
 #define CONSOLE_BAUDRATE 230400
 #endif
 
-volatile bool furi_hal_console_alive = false;
+typedef struct {
+    bool alive;
+    FuriHalConsoleTxCallback tx_callback;
+    void* tx_callback_context;
+} FuriHalConsole;
+
+FuriHalConsole furi_hal_console = {
+    .alive = false,
+    .tx_callback = NULL,
+    .tx_callback_context = NULL,
+};
 
 void furi_hal_console_init() {
     furi_hal_uart_init(FuriHalUartIdUSART1, CONSOLE_BAUDRATE);
-    furi_hal_console_alive = true;
+    furi_hal_console.alive = true;
 }
 
 void furi_hal_console_enable() {
@@ -30,20 +40,32 @@ void furi_hal_console_enable() {
     while(!LL_USART_IsActiveFlag_TC(USART1))
         ;
     furi_hal_uart_set_br(FuriHalUartIdUSART1, CONSOLE_BAUDRATE);
-    furi_hal_console_alive = true;
+    furi_hal_console.alive = true;
 }
 
 void furi_hal_console_disable() {
     while(!LL_USART_IsActiveFlag_TC(USART1))
         ;
-    furi_hal_console_alive = false;
+    furi_hal_console.alive = false;
+}
+
+void furi_hal_console_set_tx_callback(FuriHalConsoleTxCallback callback, void* context) {
+    FURI_CRITICAL_ENTER();
+    furi_hal_console.tx_callback = callback;
+    furi_hal_console.tx_callback_context = context;
+    FURI_CRITICAL_EXIT();
 }
 
 void furi_hal_console_tx(const uint8_t* buffer, size_t buffer_size) {
-    if(!furi_hal_console_alive) return;
+    if(!furi_hal_console.alive) return;
 
     FURI_CRITICAL_ENTER();
     // Transmit data
+
+    if(furi_hal_console.tx_callback) {
+        furi_hal_console.tx_callback(buffer, buffer_size, furi_hal_console.tx_callback_context);
+    }
+
     furi_hal_uart_tx(FuriHalUartIdUSART1, (uint8_t*)buffer, buffer_size);
     // Wait for TC flag to be raised for last char
     while(!LL_USART_IsActiveFlag_TC(USART1))
@@ -52,7 +74,7 @@ void furi_hal_console_tx(const uint8_t* buffer, size_t buffer_size) {
 }
 
 void furi_hal_console_tx_with_new_line(const uint8_t* buffer, size_t buffer_size) {
-    if(!furi_hal_console_alive) return;
+    if(!furi_hal_console.alive) return;
 
     FURI_CRITICAL_ENTER();
     // Transmit data

firmware/targets/f7/furi_hal/furi_hal_console.h

@@ -7,12 +7,16 @@
 extern "C" {
 #endif
 
+typedef void (*FuriHalConsoleTxCallback)(const uint8_t* buffer, size_t size, void* context);
+
 void furi_hal_console_init();
 
 void furi_hal_console_enable();
 
 void furi_hal_console_disable();
 
+void furi_hal_console_set_tx_callback(FuriHalConsoleTxCallback callback, void* context);
+
 void furi_hal_console_tx(const uint8_t* buffer, size_t buffer_size);
 
 void furi_hal_console_tx_with_new_line(const uint8_t* buffer, size_t buffer_size);