[cli] new config to log input command and the resulting output (#6827)

This commit adds `OPENTHREAD_CONFIG_CLI_LOG_INPUT_OUTPUT_ENABLE`
option which configures the CLI module to log its input command
string and the resulting output. This is done in addition to emitting
the output string to the console. By default this config is enabled
on all POSIX based platforms and when `LOG_OUTPUT` is not set to use
CLI console itself.

examples/apps/cli/cli_uart.cpp

@@ -199,34 +199,6 @@ static otError ProcessCommand(void)
         sRxBuffer[--sRxLength] = '\0';
     }
 
-#if OPENTHREAD_CONFIG_LOG_OUTPUT != OPENTHREAD_CONFIG_LOG_OUTPUT_NONE
-    /*
-     * Note this is here for this reason:
-     *
-     * TEXT (command) input ... in a test automation script occurs
-     * rapidly and often without gaps between the command and the
-     * terminal CR
-     *
-     * In contrast as a human is typing there is a delay between the
-     * last character of a command and the terminal CR which executes
-     * a command.
-     *
-     * During that human induced delay a tasklet may be scheduled and
-     * the LOG becomes confusing and it is hard to determine when
-     * something happened.  Which happened first? the command-CR or
-     * the tasklet.
-     *
-     * Yes, while rare it is a race condition that is hard to debug.
-     *
-     * Thus this is here to affirmatively LOG exactly when the CLI
-     * command is being executed.
-     */
-#if OPENTHREAD_CONFIG_MULTIPLE_INSTANCE_ENABLE
-    /* TODO: how exactly do we get the instance here? */
-#else
-    otLogInfoCli("execute command: %s", sRxBuffer);
-#endif
-#endif
     if (sRxLength > 0)
     {
         otCliInputLine(sRxBuffer);

src/cli/cli.cpp

@@ -82,6 +82,7 @@
 #include <openthread/platform/debug_uart.h>
 #endif
 
+#include "common/logging.hpp"
 #include "common/new.hpp"
 #include "common/string.hpp"
 #include "mac/channel_mask.hpp"
@@ -127,6 +128,10 @@ Interpreter::Interpreter(Instance *aInstance, otCliOutputCallback aCallback, voi
 #if OPENTHREAD_CONFIG_SRP_SERVER_ENABLE
     , mSrpServer(*this)
 #endif
+#if OPENTHREAD_CONFIG_CLI_LOG_INPUT_OUTPUT_ENABLE
+    , mOutputLength(0)
+    , mIsLogging(false)
+#endif
 {
 #if OPENTHREAD_FTD
     otThreadSetDiscoveryRequestCallback(mInstance, &Interpreter::HandleDiscoveryRequest, this);
@@ -4551,6 +4556,10 @@ void Interpreter::ProcessLine(char *aBuf)
 
     VerifyOrExit(StringLength(aBuf, kMaxLineLength) <= kMaxLineLength - 1, error = OT_ERROR_PARSE);
 
+#if OPENTHREAD_CONFIG_CLI_LOG_INPUT_OUTPUT_ENABLE
+    otLogNoteCli("Input: %s", aBuf);
+#endif
+
     error = Utils::CmdLineParser::ParseCmd(aBuf, args);
 
     if (error != OT_ERROR_NONE)
@@ -4918,7 +4927,98 @@ void Interpreter::OutputSpaces(uint8_t aCount)
 
 int Interpreter::OutputFormatV(const char *aFormat, va_list aArguments)
 {
-    return mOutputCallback(mOutputContext, aFormat, aArguments);
+    int rval;
+#if OPENTHREAD_CONFIG_CLI_LOG_INPUT_OUTPUT_ENABLE
+    va_list args;
+    int     charsWritten;
+    bool    truncated = false;
+
+    va_copy(args, aArguments);
+#endif
+
+    rval = mOutputCallback(mOutputContext, aFormat, aArguments);
+
+#if OPENTHREAD_CONFIG_CLI_LOG_INPUT_OUTPUT_ENABLE
+    VerifyOrExit(!IsLogging());
+
+    charsWritten = vsnprintf(&mOutputString[mOutputLength], sizeof(mOutputString) - mOutputLength, aFormat, args);
+
+    VerifyOrExit(charsWritten >= 0, mOutputLength = 0);
+
+    if (static_cast<uint32_t>(charsWritten) >= sizeof(mOutputString) - mOutputLength)
+    {
+        truncated     = true;
+        mOutputLength = sizeof(mOutputString) - 1;
+    }
+    else
+    {
+        mOutputLength += charsWritten;
+    }
+
+    while (true)
+    {
+        char *lineEnd = strchr(mOutputString, '\r');
+
+        if (lineEnd == nullptr)
+        {
+            break;
+        }
+
+        *lineEnd = '\0';
+
+        if (lineEnd > mOutputString)
+        {
+            otLogNoteCli("Output: %s", mOutputString);
+        }
+
+        lineEnd++;
+
+        while ((*lineEnd == '\n') || (*lineEnd == '\r'))
+        {
+            lineEnd++;
+        }
+
+        // Example of the pointers and lengths.
+        //
+        // - mOutputString = "hi\r\nmore"
+        // - mOutputLength = 8
+        // - lineEnd       = &mOutputString[4]
+        //
+        //
+        //   0    1    2    3    4    5    6    7    8    9
+        // +----+----+----+----+----+----+----+----+----+---
+        // | h  | i  | \r | \n | m  | o  | r  | e  | \0 |
+        // +----+----+----+----+----+----+----+----+----+---
+        //                       ^                   ^
+        //                       |                   |
+        //                    lineEnd    mOutputString[mOutputLength]
+        //
+        //
+        // New length is `&mOutputString[8] - &mOutputString[4] -> 4`.
+        //
+        // We move (newLen + 1 = 5) chars from `lineEnd` to start of
+        // `mOutputString` which will include the `\0` char.
+        //
+        // If `lineEnd` and `mOutputString[mOutputLength]` are the same
+        // the code works correctly as well  (new length set to zero and
+        // the `\0` is copied).
+
+        mOutputLength = static_cast<uint16_t>(&mOutputString[mOutputLength] - lineEnd);
+        memmove(mOutputString, lineEnd, mOutputLength + 1);
+    }
+
+    if (truncated)
+    {
+        otLogNoteCli("Output: %s ...", mOutputString);
+        mOutputLength = 0;
+    }
+
+exit:
+    va_end(args);
+
+#endif // OPENTHREAD_CONFIG_CLI_LOG_INPUT_OUTPUT_ENABLE
+
+    return rval;
 }
 
 void Interpreter::Initialize(otInstance *aInstance, otCliOutputCallback aCallback, void *aContext)
@@ -4968,8 +5068,20 @@ extern "C" void otCliPlatLogv(otLogLevel aLogLevel, otLogRegion aLogRegion, cons
 
     VerifyOrExit(Interpreter::IsInitialized());
 
+#if OPENTHREAD_CONFIG_CLI_LOG_INPUT_OUTPUT_ENABLE
+    // CLI output can be used for logging. The `IsLogging` flag is
+    // used to indicate whether it is being used for a CLI command
+    // output or for logging.
+    Interpreter::GetInterpreter().SetIsLogging(true);
+#endif
+
     Interpreter::GetInterpreter().OutputFormatV(aFormat, aArgs);
     Interpreter::GetInterpreter().OutputLine("");
+
+#if OPENTHREAD_CONFIG_CLI_LOG_INPUT_OUTPUT_ENABLE
+    Interpreter::GetInterpreter().SetIsLogging(false);
+#endif
+
 exit:
     return;
 }
@@ -4980,8 +5092,17 @@ extern "C" void otCliPlatLogLine(otLogLevel aLogLevel, otLogRegion aLogRegion, c
     OT_UNUSED_VARIABLE(aLogRegion);
 
     VerifyOrExit(Interpreter::IsInitialized());
+
+#if OPENTHREAD_CONFIG_CLI_LOG_INPUT_OUTPUT_ENABLE
+    Interpreter::GetInterpreter().SetIsLogging(true);
+#endif
+
     Interpreter::GetInterpreter().OutputLine(aLogLine);
 
+#if OPENTHREAD_CONFIG_CLI_LOG_INPUT_OUTPUT_ENABLE
+    Interpreter::GetInterpreter().SetIsLogging(false);
+#endif
+
 exit:
     return;
 }

src/cli/cli.hpp

@@ -87,6 +87,9 @@ namespace ot {
  */
 namespace Cli {
 
+extern "C" void otCliPlatLogv(otLogLevel, otLogRegion, const char *, va_list);
+extern "C" void otCliPlatLogLine(otLogLevel, otLogRegion, const char *);
+
 /**
  * This class implements the CLI interpreter.
  *
@@ -103,6 +106,8 @@ class Interpreter
     friend class SrpServer;
     friend class TcpExample;
     friend class UdpExample;
+    friend void otCliPlatLogv(otLogLevel, otLogRegion, const char *, va_list);
+    friend void otCliPlatLogLine(otLogLevel, otLogRegion, const char *);
 
 public:
     typedef Utils::CmdLineParser::Arg Arg;
@@ -721,6 +726,11 @@ private:
     }
     void HandleDiscoveryRequest(const otThreadDiscoveryRequestInfo &aInfo);
 
+#if OPENTHREAD_CONFIG_CLI_LOG_INPUT_OUTPUT_ENABLE
+    bool IsLogging(void) const { return mIsLogging; }
+    void SetIsLogging(bool aIsLogging) { mIsLogging = aIsLogging; }
+#endif
+
     static constexpr Command sCommands[] = {
 #if OPENTHREAD_CONFIG_BORDER_AGENT_ENABLE
         {"ba", &Interpreter::ProcessBorderAgent},
@@ -937,6 +947,12 @@ private:
 #if OPENTHREAD_CONFIG_SRP_SERVER_ENABLE
     SrpServer mSrpServer;
 #endif
+
+#if OPENTHREAD_CONFIG_CLI_LOG_INPUT_OUTPUT_ENABLE
+    char     mOutputString[OPENTHREAD_CONFIG_CLI_LOG_INPUT_OUTPUT_LOG_STRING_SIZE];
+    uint16_t mOutputLength;
+    bool     mIsLogging;
+#endif
 };
 
 // Specializations of `FormatStringFor<ValueType>()`

src/cli/cli_config.h

@@ -59,6 +59,7 @@
 #endif
 
 /**
+<<<<<<< HEAD
  * @def OPENTHREAD_CONFIG_CLI_TCP_ENABLE
  *
  * Indicates whether TCP should be enabled in the CLI tool.
@@ -87,4 +88,30 @@
 #define OPENTHREAD_CONFIG_CLI_TCP_RECEIVE_BUFFER_SIZE OT_TCP_RECEIVE_BUFFER_SIZE_FEW_HOPS
 #endif
 
+/**
+ * @def OPENTHREAD_CONFIG_CLI_LOG_INPUT_OUTPUT_ENABLE
+ *
+ * Define as 1 for CLI to emit its command input string and the resulting output to the logs.
+ *
+ * By default this is enabled on any POSIX based platform (`OPENTHREAD_POSIX`) and only when CLI itself is not being
+ * used for logging.
+ *
+ */
+#ifndef OPENTHREAD_CONFIG_CLI_LOG_INPUT_OUTPUT_ENABLE
+#define OPENTHREAD_CONFIG_CLI_LOG_INPUT_OUTPUT_ENABLE \
+    (OPENTHREAD_POSIX && (OPENTHREAD_CONFIG_LOG_OUTPUT != OPENTHREAD_CONFIG_LOG_OUTPUT_APP))
+#endif
+
+/**
+ * @def OPENTHREAD_CONFIG_CLI_LOG_INPUT_OUTPUT_LOG_STRING_SIZE
+ *
+ * The log string buffer size (in bytes).
+ *
+ * This is only used when `OPENTHREAD_CONFIG_CLI_LOG_INPUT_OUTPUT_ENABLE` is enabled.
+ *
+ */
+#ifndef OPENTHREAD_CONFIG_CLI_LOG_INPUT_OUTPUT_LOG_STRING_SIZE
+#define OPENTHREAD_CONFIG_CLI_LOG_INPUT_OUTPUT_LOG_STRING_SIZE OPENTHREAD_CONFIG_CLI_MAX_LINE_LENGTH
+#endif
+
 #endif // CONFIG_CLI_H_