From cbd96613082965813a525a21857da7052bf47de4 Mon Sep 17 00:00:00 2001 From: Abtin Keshavarzian Date: Tue, 20 Jul 2021 18:53:27 -0700 Subject: [PATCH] [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 | 28 -------- src/cli/cli.cpp | 123 ++++++++++++++++++++++++++++++++- src/cli/cli.hpp | 16 +++++ src/cli/cli_config.h | 27 ++++++++ 4 files changed, 165 insertions(+), 29 deletions(-) diff --git a/examples/apps/cli/cli_uart.cpp b/examples/apps/cli/cli_uart.cpp index b2d271dcc..38fb838b7 100644 --- a/examples/apps/cli/cli_uart.cpp +++ b/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); diff --git a/src/cli/cli.cpp b/src/cli/cli.cpp index 03f9b3d5a..ac54cb362 100644 --- a/src/cli/cli.cpp +++ b/src/cli/cli.cpp @@ -82,6 +82,7 @@ #include #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(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(&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; } diff --git a/src/cli/cli.hpp b/src/cli/cli.hpp index 9042dc122..47fe7e006 100644 --- a/src/cli/cli.hpp +++ b/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()` diff --git a/src/cli/cli_config.h b/src/cli/cli_config.h index e8d6758bb..edebf7feb 100644 --- a/src/cli/cli_config.h +++ b/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_