From 085449bc1bb5ceb38ce26679b9bbcb142cd95fbd Mon Sep 17 00:00:00 2001 From: "Zachary J. Fields" Date: Thu, 22 Feb 2024 20:24:29 +0000 Subject: [PATCH 1/3] bug: Undefined behavior regression Previously we had allowed strings to be sent via `note-c` without a newline-terminator. Subsequently, we decided this was undefined behavior that should not be supported. This caused a regression in downstream testing, and we have restored the original behavior (although undefined by the Notecard communication specification). --- n_request.c | 56 +++++++++--- test/src/NoteRequestResponseJSON_test.cpp | 100 ++++++++++++++++++++-- 2 files changed, 139 insertions(+), 17 deletions(-) diff --git a/n_request.c b/n_request.c index 3f7af28b..b92ceacd 100644 --- a/n_request.c +++ b/n_request.c @@ -287,8 +287,9 @@ J *NoteRequestResponseWithRetry(J *req, uint32_t timeoutSeconds) @brief Send a request to the Notecard and return the response. Unlike `NoteRequestResponse`, this function expects the request to be a valid - JSON C-string, rather than a `J` object. This string MUST be newline-terminated. - The response is returned as a dynamically allocated JSON C-string. The response + JSON C-string, rather than a `J` object. The string is expected to be + newline-terminated, otherwise the call results in undefined behavior. The + response is returned as a dynamically allocated JSON C-string. The response string is verbatim what was sent by the Notecard, which IS newline-terminated. The caller is responsible for freeing the response string. If the request was a command (i.e. it uses "cmd" instead of "req"), this function returns NULL, @@ -319,11 +320,32 @@ char * NoteRequestResponseJSON(const char *reqJSON) // Manually tokenize the string to search for multiple embedded commands (cannot use strtok) for (;;) { - const char * const endPtr = strchr(reqJSON, '\n'); + const char *endPtr; + const char * const newlinePtr = strchr(reqJSON, '\n'); + + // If string is not newline-terminated, then allocate a new string and terminate it + if (NULL == newlinePtr) { + // All JSON strings should be newline-terminated to meet the specification, however + // this is required to ensure backward compatibility with the previous implementation. + const size_t tempLen = strlen(reqJSON); + if (0 == tempLen) { + NOTE_C_LOG_ERROR(ERRSTR("request: jsonbuf zero length", c_bad)); + break; + } - // If string is not newline-terminated, then do not process - if (endPtr == NULL) { - break; + NOTE_C_LOG_WARN(ERRSTR("Memory allocation due to malformed request (not newline-terminated)", c_bad)); + char * const temp = _Malloc(tempLen + 1); + if (temp == NULL) { + NOTE_C_LOG_ERROR(ERRSTR("request: jsonbuf malloc failed", c_mem)); + break; + } + + memcpy(temp, reqJSON, tempLen); + temp[tempLen] = '\n'; + reqJSON = temp; + endPtr = &reqJSON[tempLen]; + } else { + endPtr = newlinePtr; } const size_t reqLen = ((endPtr - reqJSON) + 1); @@ -334,25 +356,35 @@ char * NoteRequestResponseJSON(const char *reqJSON) J *jsonObj = JParse(reqJSON); if (!jsonObj) { // Invalid JSON. - return NULL; + if (NULL == newlinePtr) { + _Free((void *)reqJSON); + } + break; } isCmd = JIsPresent(jsonObj, "cmd"); JDelete(jsonObj); } - if (isCmd) { + if (!isCmd) { + _Transaction(reqJSON, reqLen, &rspJSON, transactionTimeoutMs); + if (NULL == newlinePtr) { + _Free((void *)reqJSON); + } + break; + } else { // If it's a command, the Notecard will not respond, so we pass NULL for // the response parameter. _Transaction(reqJSON, reqLen, NULL, transactionTimeoutMs); reqJSON = (endPtr + 1); - } else { - _Transaction(reqJSON, reqLen, &rspJSON, transactionTimeoutMs); - break; + } + + // Clean up if we allocated a new string + if (NULL == newlinePtr) { + _Free((void *)reqJSON); } } _UnlockNote(); - _TransactionStop(); return rspJSON; diff --git a/test/src/NoteRequestResponseJSON_test.cpp b/test/src/NoteRequestResponseJSON_test.cpp index abac9dd7..cb7d161f 100644 --- a/test/src/NoteRequestResponseJSON_test.cpp +++ b/test/src/NoteRequestResponseJSON_test.cpp @@ -19,9 +19,12 @@ #include "n_lib.h" DEFINE_FFF_GLOBALS +FAKE_VALUE_FUNC(N_CJSON_PUBLIC(J *), JParse, const char *) FAKE_VALUE_FUNC(bool, noteTransactionStart, uint32_t) FAKE_VOID_FUNC(noteTransactionStop) FAKE_VOID_FUNC(noteLockNote) +FAKE_VALUE_FUNC(void *, NoteMalloc, size_t) +FAKE_VOID_FUNC(NoteFree, void *) FAKE_VOID_FUNC(noteUnlockNote) FAKE_VALUE_FUNC(const char *, noteJSONTransaction, const char *, size_t, char **, uint32_t) @@ -32,19 +35,42 @@ SCENARIO("NoteRequestResponseJSON") { NoteSetFnDefault(malloc, free, NULL, NULL); + JParse_fake.custom_fake = [](const char *value) -> J * { + return JParseWithOpts(value,0,0); + }; + NoteMalloc_fake.custom_fake = malloc; + NoteFree_fake.custom_fake = free; noteTransactionStart_fake.return_val = true; GIVEN("The request is NULL") { WHEN("NoteRequestResponseJSON is called") { char *rsp = NoteRequestResponseJSON(NULL); + THEN("noteJSONTransaction is not called") { + CHECK(noteJSONTransaction_fake.call_count == 0); + } + THEN("The response is NULL") { CHECK(rsp == NULL); } } } - GIVEN("The request is a command") { + GIVEN("The request length is zero (0)") { + WHEN("NoteRequestResponseJSON is called") { + char *rsp = NoteRequestResponseJSON(""); + + THEN("noteJSONTransaction is not called") { + CHECK(noteJSONTransaction_fake.call_count == 0); + } + + THEN("The response is NULL") { + CHECK(rsp == NULL); + } + } + } + + GIVEN("The request is a command (cmd)") { char req[] = "{\"cmd\":\"card.sleep\"}\n"; WHEN("NoteRequestResponseJSON is called") { @@ -87,7 +113,7 @@ SCENARIO("NoteRequestResponseJSON") } } - GIVEN("The request is not a command") { + GIVEN("The request is not a command (req)") { char req[] = "{\"req\":\"card.version\"}\n"; WHEN("NoteRequestResponseJSON is called") { @@ -121,14 +147,65 @@ SCENARIO("NoteRequestResponseJSON") GIVEN("The request doesn't have a terminating newline") { char req[] = "{\"req\":\"card.version\"}"; - WHEN("NoteRequestResponseJSON is called") { + WHEN("NoteMalloc fails to duplicate the request") { + NoteMalloc_fake.custom_fake = nullptr; + NoteMalloc_fake.return_val = NULL; char *rsp = NoteRequestResponseJSON(req); - THEN("noteJSONTransaction isn't called") { + THEN("noteJSONTransaction is not called") { + REQUIRE(NoteMalloc_fake.call_count > 0); CHECK(noteJSONTransaction_fake.call_count == 0); } - THEN("NULL is returned") { + THEN("NoteFree is not called") { + REQUIRE(NoteMalloc_fake.call_count > 0); + CHECK(NoteFree_fake.call_count == 0); + } + + THEN("NoteRequestResponseJSON returns NULL") { + REQUIRE(NoteMalloc_fake.call_count > 0); + CHECK(rsp == NULL); + } + } + + WHEN("NoteMalloc is able to duplicate the request") { + char *rsp = NoteRequestResponseJSON(req); + + THEN("NoteMalloc is called") { + REQUIRE(noteJSONTransaction_fake.call_count > 0); + CHECK(NoteMalloc_fake.call_count > 0); + } + + THEN("noteJSONTransaction is called with the newline appended") { + REQUIRE(noteJSONTransaction_fake.call_count > 0); + REQUIRE(noteJSONTransaction_fake.arg0_history[0] != NULL); + CHECK(noteJSONTransaction_fake.arg0_history[0][(sizeof(req) - 1)] == '\n'); + CHECK(noteJSONTransaction_fake.arg1_history[0] == sizeof(req)); + } + + THEN("NoteFree is called to free the memory allocated by malloc") { + REQUIRE(noteJSONTransaction_fake.call_count > 0); + CHECK(NoteFree_fake.call_count == NoteMalloc_fake.call_count); + } + } + + WHEN("The request fails to parse") { + char cmd[] = "{\"cmd\":\"card.version\"}"; + JParse_fake.custom_fake = nullptr; + JParse_fake.return_val = NULL; + char *rsp = NoteRequestResponseJSON(cmd); + + THEN("noteJSONTransaction is not called") { + REQUIRE(NoteMalloc_fake.call_count > 0); + CHECK(noteJSONTransaction_fake.call_count == 0); + } + + THEN("NoteFree is called") { + REQUIRE(NoteMalloc_fake.call_count > 0); + CHECK(NoteFree_fake.call_count == NoteMalloc_fake.call_count); + } + + THEN("NoteRequestResponseJSON returns NULL") { CHECK(rsp == NULL); } } @@ -152,6 +229,16 @@ SCENARIO("NoteRequestResponseJSON") CHECK(noteTransactionStart_fake.call_count == 1); CHECK(noteTransactionStop_fake.call_count == 1); } + + THEN("NoteMalloc is not called") { + REQUIRE(noteJSONTransaction_fake.call_count > 0); + CHECK(NoteMalloc_fake.call_count == 0); + } + + THEN("NoteFree is not called") { + REQUIRE(noteJSONTransaction_fake.call_count > 0); + CHECK(NoteFree_fake.call_count == 0); + } } AND_GIVEN("The transaction with the Notecard fails to start") { @@ -168,6 +255,9 @@ SCENARIO("NoteRequestResponseJSON") } } + RESET_FAKE(JParse); + RESET_FAKE(NoteMalloc); + RESET_FAKE(NoteFree); RESET_FAKE(noteTransactionStart); RESET_FAKE(noteTransactionStop); RESET_FAKE(noteLockNote); From 20d921b46fe80bb0c065101d7af1384bf7475554 Mon Sep 17 00:00:00 2001 From: "Zachary J. Fields" Date: Fri, 23 Feb 2024 00:29:52 +0000 Subject: [PATCH 2/3] bug: fix memory access Allocated string did NOT have a NULL-terminator required by `strstr`. Fake Function Framework (FFF) does not make copies of strings for testing mocks, so it was instead accessing released memory which was triggering valgrind errors. --- n_request.c | 7 ++++--- test/src/NoteRequestResponseJSON_test.cpp | 9 ++++++--- 2 files changed, 10 insertions(+), 6 deletions(-) diff --git a/n_request.c b/n_request.c index b92ceacd..554196fd 100644 --- a/n_request.c +++ b/n_request.c @@ -288,7 +288,7 @@ J *NoteRequestResponseWithRetry(J *req, uint32_t timeoutSeconds) Unlike `NoteRequestResponse`, this function expects the request to be a valid JSON C-string, rather than a `J` object. The string is expected to be - newline-terminated, otherwise the call results in undefined behavior. The + newline-terminated, otherwise the call produces undefined behavior. The response is returned as a dynamically allocated JSON C-string. The response string is verbatim what was sent by the Notecard, which IS newline-terminated. The caller is responsible for freeing the response string. If the request was a @@ -334,7 +334,7 @@ char * NoteRequestResponseJSON(const char *reqJSON) } NOTE_C_LOG_WARN(ERRSTR("Memory allocation due to malformed request (not newline-terminated)", c_bad)); - char * const temp = _Malloc(tempLen + 1); + char * const temp = _Malloc(tempLen + 2); // +2 for newline and null-terminator if (temp == NULL) { NOTE_C_LOG_ERROR(ERRSTR("request: jsonbuf malloc failed", c_mem)); break; @@ -342,8 +342,9 @@ char * NoteRequestResponseJSON(const char *reqJSON) memcpy(temp, reqJSON, tempLen); temp[tempLen] = '\n'; + temp[tempLen + 1] = '\0'; reqJSON = temp; - endPtr = &reqJSON[tempLen]; + endPtr = &temp[tempLen]; } else { endPtr = newlinePtr; } diff --git a/test/src/NoteRequestResponseJSON_test.cpp b/test/src/NoteRequestResponseJSON_test.cpp index cb7d161f..50eb4b62 100644 --- a/test/src/NoteRequestResponseJSON_test.cpp +++ b/test/src/NoteRequestResponseJSON_test.cpp @@ -178,9 +178,12 @@ SCENARIO("NoteRequestResponseJSON") THEN("noteJSONTransaction is called with the newline appended") { REQUIRE(noteJSONTransaction_fake.call_count > 0); - REQUIRE(noteJSONTransaction_fake.arg0_history[0] != NULL); - CHECK(noteJSONTransaction_fake.arg0_history[0][(sizeof(req) - 1)] == '\n'); - CHECK(noteJSONTransaction_fake.arg1_history[0] == sizeof(req)); + REQUIRE(noteJSONTransaction_fake.arg0_val != NULL); + // We cannot test the value of the string passed to + // `noteJSONTransaction` because it is a pointer to a string + // freed by `NoteFree`. We can only check that the length + // of the string is one longer than would normally be expected. + CHECK(noteJSONTransaction_fake.arg1_val == sizeof(req)); } THEN("NoteFree is called to free the memory allocated by malloc") { From f686aea29172769274658714626f6fb1b7c2e6eb Mon Sep 17 00:00:00 2001 From: "Zachary J. Fields" Date: Fri, 23 Feb 2024 01:22:29 +0000 Subject: [PATCH 3/3] chore: remove deprecated calls from HIL tests --- .../lib/notecard_binary/NotecardBinary.h | 237 +++++++++++++----- .../lib/notecard_binary/NotecardComms.cpp | 26 +- .../lib/notecard_binary/NotecardComms.h | 7 +- .../card.binary/test/test_card_binary.cpp | 10 +- 4 files changed, 201 insertions(+), 79 deletions(-) diff --git a/test/hitl/card.binary/lib/notecard_binary/NotecardBinary.h b/test/hitl/card.binary/lib/notecard_binary/NotecardBinary.h index dc2b6ba4..703a7af5 100644 --- a/test/hitl/card.binary/lib/notecard_binary/NotecardBinary.h +++ b/test/hitl/card.binary/lib/notecard_binary/NotecardBinary.h @@ -307,12 +307,9 @@ class NotecardBinary void notecardDebugStreamInitialize() { #if defined(NOTECARD_DEBUG_STLINK) - static HardwareSerial stlinkSerial(PIN_VCP_RX, PIN_VCP_TX); - stlinkSerial.begin(115200); - notecard.setDebugOutputStream(stlinkSerial); -#else - notecard.setDebugOutputStream(Serial); + dbgSerial.begin(115200); #endif + notecard.setDebugOutputStream(dbgSerial); } bool notecardConnectionMode() @@ -450,7 +447,7 @@ class NotecardBinary { const size_t totalSize = image.length(); if (totalSize==0) { - notecard.logDebugf("Image length is 0!"); + dbgSerial.println("Image length is 0!"); return false; } @@ -458,7 +455,12 @@ class NotecardBinary return false; } - notecard.logDebugf("Sending image of size %u, in transport chunks of size %u, with a maximum Notecard binary size of %u\n", totalSize, chunkSize, maxBinarySize); + dbgSerial.print("Sending image of size "); + dbgSerial.print(totalSize, DEC); + dbgSerial.print(", in transport chunks of size "); + dbgSerial.print(chunkSize, DEC); + dbgSerial.print(", with a maximum Notecard binary size of "); + dbgSerial.println(maxBinarySize, DEC); image.reset(); size_t totalTransferred = 0; @@ -481,11 +483,20 @@ class NotecardBinary while (bytesToTransfer) { const size_t thisChunk = bytesToTransfer >= chunkSize ? chunkSize : bytesToTransfer; const size_t offset = chunkSize * chunkIndex; - notecard.logDebugf("Sending transport chunk %d, offset: %d, length: %d...\n", chunkIndex, offset, thisChunk); + dbgSerial.print("Sending transport chunk "); + dbgSerial.print(chunkIndex, DEC); + dbgSerial.print(", offset: "); + dbgSerial.print(offset, DEC); + dbgSerial.print(", length: "); + dbgSerial.print(thisChunk, DEC); + dbgSerial.println("..."); size_t bytesRead = transferImage.read(buffer, thisChunk); if (bytesRead != thisChunk) { - notecard.logDebugf("Insufficient data from image: expected %u, got %u\n", thisChunk, bytesRead); + dbgSerial.print("Insufficient data from image: expected "); + dbgSerial.print(thisChunk, DEC); + dbgSerial.print(", got "); + dbgSerial.println(bytesRead, DEC); return false; } @@ -508,14 +519,29 @@ class NotecardBinary outer: const size_t actualTransferSize = binaryTransferSize-bytesToTransfer; if (bytesToTransfer) { - notecard.logDebugf("TRANSFER FAILED: %s - transferred %d(0x%x) bytes of %d(0x%x)", imageName, actualTransferSize, actualTransferSize, binaryTransferSize, binaryTransferSize); + dbgSerial.print("TRANSFER FAILED: "); + dbgSerial.print(imageName); + dbgSerial.print(" - transferred "); + dbgSerial.print(actualTransferSize, DEC); + dbgSerial.print("(0x"); + dbgSerial.print(actualTransferSize, HEX); + dbgSerial.print(") bytes of "); + dbgSerial.print(binaryTransferSize, DEC); + dbgSerial.print("(0x"); + dbgSerial.print(binaryTransferSize, HEX); + dbgSerial.println(")"); return false; } NoteMD5Final(currentMD5, ¤tMD5Context); - notecard.logDebugf("%s: Successfully transferred %d(0x%x) bytes.\n", imageName, binaryTransferSize, binaryTransferSize); - notecard.logDebug("Validating received binary data...\n"); + dbgSerial.print(imageName); + dbgSerial.print(": Successfully transferred "); + dbgSerial.print(binaryTransferSize, DEC); + dbgSerial.print("(0x"); + dbgSerial.print(binaryTransferSize, HEX); + dbgSerial.println(") bytes."); + dbgSerial.println("Validating received binary data..."); TransferDetails tx = { .name = imageName, @@ -547,9 +573,17 @@ class NotecardBinary if (actualChunkSize<=0) { actualChunkSize += tx.currentTransferImage.length(); } - notecard.logDebugf("Validating buffer contents with length given=%d(actual=%d)\n", validateChunkSize, actualChunkSize); + dbgSerial.print("Validating buffer contents with length given="); + dbgSerial.print(validateChunkSize, DEC); + dbgSerial.print(" (actual="); + dbgSerial.print(actualChunkSize, DEC); + dbgSerial.println(")"); if (!validateBinaryReceived(tx, buffer, bufferLength, actualChunkSize)) { - notecard.logDebugf("FAIL: validation failed with chunk size given=%d(actual=%d)\n", validateChunkSize, actualChunkSize); + dbgSerial.print("FAIL: validation failed with chunk size given="); + dbgSerial.print(validateChunkSize, DEC); + dbgSerial.print(" (actual="); + dbgSerial.print(actualChunkSize, DEC); + dbgSerial.println(")"); return false; } } @@ -559,13 +593,21 @@ class NotecardBinary TransferHandlerContext ctx = { .tries = 0 }; while (++ctx.tries <= 5) { if (!transfer_cb(tx, ctx)) { - notecard.logDebugf("FAIL: (try %d) %s - Validation cancelled by transfer handler\n", ctx.tries, imageName); + dbgSerial.print("FAIL: (try "); + dbgSerial.print(ctx.tries, DEC); + dbgSerial.print(") "); + dbgSerial.print(imageName); + dbgSerial.println(" - Validation cancelled by transfer handler"); if (ctx.tries<0) { - notecard.logDebugf("Handler is not idempotent, giving up.\n"); + dbgSerial.println("Handler is not idempotent, giving up."); } } else { if (tries>1) { - notecard.logDebugf("SUCCESS: (try %d) %s - transfer handler successful\n", ctx.tries, imageName); + dbgSerial.print("SUCCESS: (try "); + dbgSerial.print(ctx.tries, DEC); + dbgSerial.print(") "); + dbgSerial.print(imageName); + dbgSerial.println(" - transfer handler successful"); } ctx.tries = 0; // say we're good break; @@ -616,10 +658,17 @@ class NotecardBinary uint8_t* rxBuffer = nullptr; const char* err; - notecard.logDebugf("Validating card binary, %u/%u size %u\n", tx.transferred, tx.total, tx.currentTransferSize); + dbgSerial.print("Validating card binary, "); + dbgSerial.print(tx.transferred, DEC); + dbgSerial.print("/"); + dbgSerial.print(tx.total, DEC); + dbgSerial.print(" size "); + dbgSerial.println(tx.currentTransferSize, DEC); if (nullptr==(rxBuffer=(uint8_t*)malloc(rxBufferSize))) { - notecard.logDebugf("Unable to allocate %d bytes for receive buffer.\n", rxBufferSize); + dbgSerial.print("Unable to allocate "); + dbgSerial.print(rxBufferSize, DEC); + dbgSerial.println(" bytes for receive buffer."); } else { size_t offset = 0; size_t totalBytesRead = 0; @@ -628,10 +677,16 @@ class NotecardBinary ok = false; const size_t chunkLength = std::min(tx.currentTransferImage.remaining(), validateChunkSize); if ((err = NoteBinaryStoreReceive(rxBuffer, rxBufferSize, offset, chunkLength))!=nullptr) { - notecard.logDebugf("Error receiving binary: %s\n", err); + dbgSerial.print("Error receiving binary: "); + dbgSerial.println(err); } else { - notecard.logDebugf("card.binary.get Receive buffer size requested: %d\n", rxBufferSize); - notecard.logDebugf("Validating received data, length %d (0x%x)...\n", chunkLength, chunkLength); + dbgSerial.print("card.binary.get Receive buffer size requested: "); + dbgSerial.println(rxBufferSize, DEC); + dbgSerial.print("Validating received data, length "); + dbgSerial.print(chunkLength, DEC); + dbgSerial.print("(0x"); + dbgSerial.print(chunkLength, HEX); + dbgSerial.println(")..."); size_t chunkBytesRead = 0; // read and validate the image against the buffer in chunks. BinaryGenerator& image = tx.currentTransferImage; // alias @@ -644,7 +699,14 @@ class NotecardBinary const uint8_t* src = rxBuffer+chunkBytesRead; if (src[i]!=buffer[i]) { size_t offset = chunkBytesRead + i; - notecard.logDebugf("Received buffer differs from image at offset %d(0x%x): %d != %d", offset, offset, buffer[i], src[i]); + dbgSerial.print("Received buffer differs from image at offset "); + dbgSerial.print(offset, DEC); + dbgSerial.print("(0x"); + dbgSerial.print(offset, HEX); + dbgSerial.print("): "); + dbgSerial.print(buffer[i], DEC); + dbgSerial.print(" != "); + dbgSerial.println(src[i], DEC); goto cancel; } } @@ -656,7 +718,7 @@ class NotecardBinary } cancel: if (totalBytesRead==tx.currentTransferImage.length()) { - notecard.logDebug("Validated received data.\n"); + dbgSerial.println("Validated received data."); #if defined(NOTE_BINARY_CHECK_EXTRA_DATA_TIMEOUT) // This is not necessary to catch the error, since other requests afterwards will fail. @@ -665,7 +727,13 @@ class NotecardBinary size_t duration = 0; size_t size = readDataUntilTimeout(Serial1, NOTE_BINARY_CHECK_EXTRA_DATA_TIMEOUT, rxBuffer, rxBufferSize, receivedLength, duration); if (size) { - notecard.logDebugf("additional data after binary: %d (0x%x) bytes read in %dms\n", size, size, duration); + dbgSerial.print("additional data after binary: "); + dbgSerial.print(size, DEC); + dbgSerial.print("(0x"); + dbgSerial.print(size, HEX); + dbgSerial.print(") bytes read in "); + dbgSerial.print(duration, DEC); + dbgSerial.println("ms"); } else #endif success = true; @@ -681,7 +749,8 @@ class NotecardBinary const char *err = NoteBinaryStoreTransmit(chunk, chunkLength, bufferLength, offset); if (err) { - NoteDebugf("Error transferring binary chunk: %s\n", err); + dbgSerial.print("Error transferring binary chunk: "); + dbgSerial.println(err); if (!strstr(err, "exceeds available memory")) { return binaryBufferFull(); } @@ -777,11 +846,11 @@ class FileHandler J* response = nullptr; const char* err = NoteBinaryStoreReceive(rxBuf, rxSize, 0, dataLen); if (err) { - notecard.logDebugf("error retrieving payload: %s\n", err); + dbgSerial.print("error retrieving payload: "); + dbgSerial.println(err); } else { - notecard.logDebug("response content from card.binary: "); - notecard.logDebug((const char*)rxBuf); - notecard.logDebug("\n"); + dbgSerial.print("response content from card.binary: "); + dbgSerial.println((const char*)rxBuf); response = JParse((char*)rxBuf); } return response; @@ -812,7 +881,7 @@ class FileHandler JAddBoolToObject(req, "binary", true); J* rsp = notecard.requestAndResponse(req); if (!rsp) { - notecard.logDebug("NULL response to `web.get`\n"); + dbgSerial.println("NULL response to `web.get`"); } else { int result = JGetNumber(rsp, "result"); J* body = JGetObject(rsp, "body"); @@ -822,17 +891,23 @@ class FileHandler const char* err = JGetString(rsp, "err"); retry = result==404 || result==503 || result==504; if (err && err[0]) { - notecard.logDebugf("web.get failed with error: %s\n", err); + dbgSerial.print("web.get failed with error: "); + dbgSerial.println(err); } else if (result<200 || result>=300) { - notecard.logDebugf("web.get result was %d\n", result); + dbgSerial.print("web.get result was: "); + dbgSerial.println(result, DEC); } else if (!body) { - notecard.logDebugf("web.get body is not present\n"); + dbgSerial.println("web.get body is not present"); } else if (!cobs) { - notecard.logDebugf("web.get expected response property 'cobs' is not present\n"); + dbgSerial.println("web.get expected response property 'cobs' is not present"); } else if (!length) { - notecard.logDebugf("web.get expected response property 'length' is not present\n"); + dbgSerial.println("web.get expected response property 'length' is not present"); } else if (length!=int(tx.currentTransferSize)) { - notecard.logDebugf("web.get length!=chunkTransferSize (%d!=%d)\n", length, tx.currentTransferSize); + dbgSerial.print("web.get length!=chunkTransferSize ("); + dbgSerial.print(length, DEC); + dbgSerial.print("!="); + dbgSerial.print(tx.currentTransferSize, DEC); + dbgSerial.println(")"); } else { // validate the binary buffer against the last chunk sent size_t bufferLength = 4097; // just to be nasty ;-) @@ -842,7 +917,7 @@ class FileHandler success = NotecardBinary::validateBinaryReceived(tx, buffer, bufferLength, length); free(buffer); } else { - notecard.logDebugf("Unable to allocate 4k buffer to verify content\n"); + dbgSerial.println("Unable to allocate 4k buffer to verify content"); } } if (!success && length && length<1024) { @@ -875,20 +950,22 @@ class FileHandler } J* rsp = notecard.requestAndResponse(req); if (!rsp) { - notecard.logDebug("NULL response to `web.get`\n"); + dbgSerial.println("NULL response to `web.get`"); } else { int result = JGetNumber(rsp, "result"); J* body = JGetObject(rsp, "body"); int cobs = JGetNumber(rsp, "cobs"); const char* err = JGetString(rsp, "err"); if (err && err[0]) { - notecard.logDebugf("web.get failed with error: %s\n", err); + dbgSerial.print("web.get failed with error: "); + dbgSerial.println(err); } else if (result<200 || result>=300) { - notecard.logDebugf("web.get result was %d\n", result); + dbgSerial.print("web.get result was: "); + dbgSerial.println(result, DEC); } else if (!body) { - notecard.logDebugf("web.get body is not present\n"); + dbgSerial.println("web.get body is not present"); } else if (cobs) { - notecard.logDebugf("web.get unexpected response property 'cobs' is present\n"); + dbgSerial.println("web.get unexpected response property 'cobs' is present"); } else { size_t expectedChunks = chunked ? tx.totalChunks : 1; size_t actualLength = JGetNumber(body, "length"); @@ -900,13 +977,27 @@ class FileHandler actualMD5String = "not a string"; } if (strcmp(actualMD5String, expectedMD5String)) { - notecard.logDebugf("web.get MD5 actual!=expected: %s!=%s\n", actualMD5String, expectedMD5String); + dbgSerial.print("web.get MD5 actual!=expected: "); + dbgSerial.print(actualMD5String); + dbgSerial.print(" != "); + dbgSerial.println(expectedMD5String); } else if (actualLength!=tx.total) { - notecard.logDebugf("web.get total length: actual!=expected: %d!=%d\n", actualLength, tx.total); + dbgSerial.print("web.get total length: actual != expected: "); + dbgSerial.print(actualLength, DEC); + dbgSerial.print(" != "); + dbgSerial.println(tx.total, DEC); } else if (actualChunks!=expectedChunks) { - notecard.logDebugf("web.get total chunks: actual!=expected: %d!=%d\n", actualChunks, expectedChunks); + dbgSerial.print("web.get total chunks: actual != expected: "); + dbgSerial.print(actualChunks, DEC); + dbgSerial.print(" != "); + dbgSerial.println(expectedChunks, DEC); } else { - notecard.logDebugf("web.get response validated: md5=%s, chunks=%d, length=%d.\n", actualMD5String, actualChunks, actualLength); + dbgSerial.print("web.get response validated: md5="); + dbgSerial.print(actualMD5String); + dbgSerial.print(", chunks="); + dbgSerial.print(actualChunks, DEC); + dbgSerial.print(", length="); + dbgSerial.println(actualLength, DEC); success = true; } } @@ -931,16 +1022,19 @@ class FileHandler if (rsp) { int result = JGetNumber(rsp, "result"); if (result != 200) { - notecard.logDebugf("HTTP status %d trying to delete %s\n", result, name); + dbgSerial.print("HTTP status ("); + dbgSerial.print(result, DEC); + dbgSerial.print(") trying to delete "); + dbgSerial.println(name); } else { success = true; } JDelete(rsp); } else { - notecard.logDebugf("NULL response received to `web.delete`.\n"); + dbgSerial.println("NULL response received to `web.delete`."); } } else { - notecard.logDebugf("Could not create request.\n"); + dbgSerial.println("Could not create request."); } return success; } @@ -992,7 +1086,7 @@ class WebPostHandler : public FileHandler bool success = false; if (!NotecardBinary::waitForNotecardConnected(NOT_CONNECTED_TIMEOUT)) { - notecard.logDebug("Cannot perform web.* request, Notecard not connected."); + dbgSerial.println("Cannot perform web.* request, Notecard not connected."); return false; } @@ -1041,24 +1135,27 @@ class WebPostHandler : public FileHandler err = JGetString(rsp, "err"); if (err && err[0]) { - notecard.logDebugf("web.post failed with error: %s\n", err); + dbgSerial.print("web.post failed with error: "); + dbgSerial.println(err); } // Notehub returns 100: Continue for all web.post with offset apart from the last else if (!chunked && !tx.isComplete && result!=100) { - notecard.logDebugf("expected web.post result of 100 for all fragments apart from the last, but was %d\n", result); + dbgSerial.print("expected web.post result of 100 for all fragments apart from the last, but was: "); + dbgSerial.println(result, DEC); } else if ((chunked || tx.isComplete) && (result!=200)) { - notecard.logDebugf("web.post result of 200 expected, but was %d\n", result); + dbgSerial.print("web.post result of 200 expected, but was: "); + dbgSerial.println(result, DEC); } // only get a "real" response from the endpoint when chunking, or when the final fragment is sent to notehub else if (!chunked && !tx.isComplete) { success = true; } else { if (!body) { - notecard.logDebugf("web.post body is not present\n"); + dbgSerial.println("web.post body is not present"); } else if (!cobs) { - notecard.logDebugf("web.post response 'cobs' not present\n"); + dbgSerial.println("web.post response 'cobs' not present"); } else if (!length) { - notecard.logDebugf("web.post response 'length' not present\n"); + dbgSerial.println("web.post response 'length' not present"); } else { char expectedMD5String[NOTE_MD5_HASH_STRING_SIZE]; // need to tighten up the note-c APIs with respect to const @@ -1071,13 +1168,22 @@ class WebPostHandler : public FileHandler receivedMD5string = "not a string"; } if (strcmp(receivedMD5string, expectedMD5String)) { - notecard.logDebugf("web.post MD5 actual!=expected: %s!=%s\n", receivedMD5string, expectedMD5String); + dbgSerial.print("web.post MD5 actual != expected: "); + dbgSerial.print(receivedMD5string); + dbgSerial.print(" != "); + dbgSerial.println(expectedMD5String); } else if (content && (!contentType || strcmp(contentType, content))) { - notecard.logDebugf("web.post Content-Type actual!=expected: %s!=%s\n", contentType, content); + dbgSerial.print("web.post Content-Type actual != expected: "); + dbgSerial.print(contentType); + dbgSerial.print(" != "); + dbgSerial.println(content); } else if (!contentLength || (contentLength!=expectedLength)) { - notecard.logDebugf("web.post Content-Length actual!=expected: %s!=%s\n", contentLength, expectedLength); + dbgSerial.print("web.post Content-Length actual != expected: "); + dbgSerial.print(contentLength); + dbgSerial.print(" != "); + dbgSerial.println(expectedLength); } else { - notecard.logDebug("web.post response validated.\n"); + dbgSerial.println("web.post response validated."); success = true; } } @@ -1126,7 +1232,7 @@ class NoteAddHandler : public FileHandler bool chunked = (tx.currentTransferSize!=tx.total); // only one chunk equal to the total if (!NotecardBinary::waitForNotecardConnected(NOT_CONNECTED_TIMEOUT)) { - notecard.logDebug("Cannot perform note.add request, Notecard not connected."); + dbgSerial.println("Cannot perform note.add request, Notecard not connected."); return false; } @@ -1152,16 +1258,17 @@ class NoteAddHandler : public FileHandler if (rsp) { const char* err = JGetString(rsp, "err"); if (err && err[0]) { - notecard.logDebugf("note.add error: %s\n", err); + dbgSerial.print("note.add error: "); + dbgSerial.println(err); } else { success = true; } JDelete(rsp); } else { - notecard.logDebugf("no response from Notecard\n"); + dbgSerial.println("no response from Notecard"); } } else { - notecard.logDebugf("Could not allocate request\n"); + dbgSerial.println("Could not allocate request"); } if (success) { diff --git a/test/hitl/card.binary/lib/notecard_binary/NotecardComms.cpp b/test/hitl/card.binary/lib/notecard_binary/NotecardComms.cpp index 83db95e5..cff063f5 100644 --- a/test/hitl/card.binary/lib/notecard_binary/NotecardComms.cpp +++ b/test/hitl/card.binary/lib/notecard_binary/NotecardComms.cpp @@ -14,7 +14,7 @@ bool set_aux_serial_baudrate(size_t baudrate, NotecardInterface nif) digitalWrite(FEATHER_AUX_EN_PIN, HIGH); if (nif==NOTECARD_IF_AUX_SERIAL) { - notecard.logDebug("WARNING: trying to change aux serial baudrate over aux serial.\n"); + dbgSerial.println("WARNING: trying to change aux serial baudrate over aux serial."); } initialize_notecard_interface(nif); @@ -24,17 +24,21 @@ bool set_aux_serial_baudrate(size_t baudrate, NotecardInterface nif) J* rsp = NoteRequestResponseWithRetry(req, 10); bool success = false; if (rsp==nullptr) { - notecard.logDebug("No response to `card.aux.serial`.\n"); + dbgSerial.println("No response to `card.aux.serial`."); } else if (!JIsNullString(rsp, "err")) { - notecard.logDebugf("Error response to `card.aux.serial`\n"); + dbgSerial.println("Error response to `card.aux.serial`."); } const char* mode = JGetString(rsp, "mode"); size_t rate = JGetNumber(rsp, "rate"); if (strcmp(mode, "req")) { - notecard.logDebugf("expected 'mode':'req', got %s\n", mode); + dbgSerial.print("expected 'mode':'req', got "); + dbgSerial.println(mode); } else if (rate != baudrate) { - notecard.logDebugf("expected 'rate':%d, got %d\n", baudrate, rate); + dbgSerial.print("expected 'rate':"); + dbgSerial.print(baudrate); + dbgSerial.print(", got "); + dbgSerial.println(rate); } else { aux_serial_baudrate = baudrate; success = true; @@ -48,7 +52,7 @@ bool initialize_notecard_interface(NotecardInterface iface) // Initialize the hardware I/O channel to the Notecard switch (iface) { default: - notecard.logDebug("Unknown Notecard interface given."); + dbgSerial.println("Unknown Notecard interface given."); return false; case NOTECARD_IF_AUX_SERIAL: @@ -75,7 +79,7 @@ bool uninitialize_notecard_interface(NotecardInterface iface) // Initialize the hardware I/O channel to the Notecard switch (iface) { default: - notecard.logDebug("Unknown Notecard interface given."); + dbgSerial.println("Unknown Notecard interface given."); return false; case NOTECARD_IF_AUX_SERIAL: @@ -126,11 +130,15 @@ size_t readDataUntilTimeout(Stream& serial, size_t timeout, uint8_t* buf, size_t if (buf[matchIndex]==ch) { matchIndex++; if (matchIndex>=bufLen) { - notecard.logDebugf("matched the complete image at offset %d\n", count); + dbgSerial.print("matched the complete image at offset "); + dbgSerial.println(count, DEC); } } else { if (matchIndex>10) { - notecard.logDebugf("matched %d bytes at offset %d\n", matchIndex, count); + dbgSerial.print("matched "); + dbgSerial.print(matchIndex, DEC); + dbgSerial.print(" bytes at offset "); + dbgSerial.println(count, DEC); } matchIndex = 0; } diff --git a/test/hitl/card.binary/lib/notecard_binary/NotecardComms.h b/test/hitl/card.binary/lib/notecard_binary/NotecardComms.h index 0765fa74..ba4c0e84 100644 --- a/test/hitl/card.binary/lib/notecard_binary/NotecardComms.h +++ b/test/hitl/card.binary/lib/notecard_binary/NotecardComms.h @@ -29,7 +29,12 @@ enum NotecardInterface { #define NOTECARD_IF_I2C_ADDRESS NOTE_I2C_ADDR_DEFAULT #endif - +#if defined(NOTECARD_DEBUG_STLINK) + HardwareSerial stlinkSerial(PIN_VCP_RX, PIN_VCP_TX); + #define dbgSerial stlinkSerial +#else + #define dbgSerial Serial +#endif bool initialize_notecard_interface(NotecardInterface iface); size_t readDataUntilTimeout(Stream& serial, size_t timeout, uint8_t* buf, size_t bufLen, size_t dataLen, size_t& duration); diff --git a/test/hitl/card.binary/test/test_card_binary.cpp b/test/hitl/card.binary/test/test_card_binary.cpp index 2a3fc960..7d97fc6e 100644 --- a/test/hitl/card.binary/test/test_card_binary.cpp +++ b/test/hitl/card.binary/test/test_card_binary.cpp @@ -54,7 +54,8 @@ void AssertNoteBinaryReset() { const char* err = NoteBinaryStoreReset(); if (err) { - notecard.logDebugf("Error calling NoteBinaryReset %s\n", err); + dbgSerial.print("Error calling NoteBinaryReset: "); + dbgSerial.println(err); TEST_FAIL_MESSAGE("NoteBinaryReset failed."); } } @@ -309,18 +310,19 @@ size_t get_expected_max_binary_length() size_t ret = 0; J* rsp = NoteRequestResponseWithRetry(NoteNewRequest("card.version"), 10); if (rsp == nullptr) { - notecard.logDebug("No response to card.version."); + dbgSerial.println("No response to card.version."); } else { char *target = JGetString(JGetObject(rsp, "body"), "target"); if (target == nullptr) { - notecard.logDebug("Failed to get target from card.version body."); + dbgSerial.println("Failed to get target from card.version body."); } else { if (strcmp(target, "r5") == 0) { ret = R5_MAX_BINARY_LENGTH; } else if (strcmp(target, "u5") == 0) { ret = U5_MAX_BINARY_LENGTH; } else { - notecard.logDebugf("Unrecognized target: %s.", target); + dbgSerial.print("Unrecognized target: "); + dbgSerial.println(target); } } }