Updated logging of unsolicited status and unexpected (primarily responses for... (f618fd56) · Commits · kinetic-archive / kinetic-c

src/lib/kinetic_controller.c

+30 −14

Original line number	Diff line number	Diff line
		@@ -194,16 +194,13 @@ void KineticController_HandleUnexpectedResponse(void *msg,
		KineticResponse * response = msg;
		KineticConnection* connection = socket_udata;
		bool connetionInfoReceived = false;
		char const * statusTag = "[PDU RX STATUS]";
		char const * unexpectedTag = "[PDU RX UNEXPECTED]";
		char const * logTag = unexpectedTag;
		int logAtLevel, protoLogAtLevel;

		(void)seq_id;
		(void)bus_udata;

		LOGF2("[PDU RX UNSOLICITED] pdu: 0x%0llX, session: 0x%llX, bus: 0x%llX, "
		"fd: %6d, protoLen: %u, valueLen: %u, seq_id: %08llx",
		response, connection->pSession, connection->messageBus, connection->socket,
		response->header.protobufLength, response->header.valueLength,
		(long long)seq_id);

		// Handle unsolicited status PDUs
		if (response->proto->authType == KINETIC_PROTO_MESSAGE_AUTH_TYPE_UNSOLICITEDSTATUS) {
		if (response->command != NULL &&
		@@ -215,17 +212,33 @@ void KineticController_HandleUnexpectedResponse(void *msg,
		LOGF2("Extracted connection ID from unsolicited status PDU (id=%lld)",
		connection->connectionID);
		connetionInfoReceived = true;
		logTag = statusTag;
		logAtLevel = 2;
		protoLogAtLevel = 2;
		}
		else {
		LOG0("WARNING: Unsolicited PDU received after session initialized!");
		LOG0("WARNING: Unsolicited status received. Connection being terminated by remote!");
		logTag = statusTag;
		logAtLevel = 0;
		protoLogAtLevel = 0;
		}
		}
		else
		{
		LOG0("WARNING: Received unexpected response that was not an unsolicited status.");
		LOG0("WARNING: Received unexpected response!");
		logTag = unexpectedTag;
		logAtLevel = 0;
		protoLogAtLevel = 0;
		}

		KineticLogger_LogProtobuf(2, response->proto);
		KineticLogger_LogPrintf(logAtLevel, "%s pdu: %p, session: %p, bus: %p, "
		"fd: %6d, seq: %8lld, protoLen: %8u, valueLen: %8u",
		logTag,
		(void)response, (void)connection->pSession,
		(void*)connection->messageBus,
		connection->socket, (long long)seq_id,
		response->header.protobufLength, response->header.valueLength);
		KineticLogger_LogProtobuf(protoLogAtLevel, response->proto);

		KineticAllocator_FreeKineticResponse(response);

		@@ -256,10 +269,13 @@ void KineticController_HandleResult(bus_msg_result_t res, void udata)
		status = KINETIC_STATUS_INVALID;
		}

		LOGF2("[PDU RX] pdu: 0x%0llX, op: 0x%llX, session: 0x%llX, bus: 0x%llX, fd: %6d, "
		"seq: %5lld, protoLen: %4u, valueLen: %u, status: %s",
		response, op, op->connection->pSession, op->connection->messageBus, op->connection->socket,
		response->command->header->ackSequence, response->header.protobufLength, response->header.valueLength,
		LOGF2("[PDU RX] pdu: %p, session: %p, bus: %p, "
		"fd: %6d, seq: %8lld, protoLen: %8u, valueLen: %8u, op: %p, status: %s",
		(void*)response,
		(void)op->connection->pSession, (void)op->connection->messageBus,
		op->connection->socket, response->command->header->ackSequence,
		response->header.protobufLength, response->header.valueLength,
		(void*)op,
		Kinetic_GetStatusDescription(status));
		}
		else

src/lib/kinetic_logger.c

+5 −5

Original line number	Diff line number	Diff line
		@@ -186,23 +186,23 @@ static int indent_overflow = 0;
		indent_overflow = 0;

		#define LOG_PROTO_LEVEL_START(__name) \
		KineticLogger_LogPrintf(2, "%s%s {", indent, __name); \
		KineticLogger_LogPrintf(0, "%s%s {", indent, __name); \
		if (strlen(indent) < max_indent) { strcat(indent, LOG_INDENT); } \
		else { indent_overflow++; }
		#define LOG_PROTO_LEVEL_END() \
		if (indent_overflow == 0) { indent[strlen(indent) - 2] = '\0'; } \
		else { indent_overflow--; } \
		KineticLogger_LogPrintf(2, "%s}", indent);
		KineticLogger_LogPrintf(0, "%s}", indent);

		#define LOG_PROTO_LEVEL_START_ARRAY(__name, __quantity) \
		KineticLogger_LogPrintf(2, "%s%s: (%u elements)", (indent), (__name), (__quantity)); \
		KineticLogger_LogPrintf(2, "%s[", (indent)); \
		KineticLogger_LogPrintf(0, "%s%s: (%u elements)", (indent), (__name), (__quantity)); \
		KineticLogger_LogPrintf(0, "%s[", (indent)); \
		if (strlen(indent) < max_indent) { strcat(indent, LOG_INDENT); } \
		else { indent_overflow++; }
		#define LOG_PROTO_LEVEL_END_ARRAY() \
		if (indent_overflow == 0) { indent[strlen(indent) - 2] = '\0'; } \
		else { indent_overflow--; } \
		KineticLogger_LogPrintf(2, "%s]", (indent));
		KineticLogger_LogPrintf(0, "%s]", (indent));

		static int KineticLogger_u8toa(char* p_buf, uint8_t val)
		{

src/lib/kinetic_operation.c

+6 −3

Original line number	Diff line number	Diff line
		@@ -162,11 +162,14 @@ static KineticStatus KineticOperation_SendRequestInner(KineticOperation* const o
		assert(operation->request);
		assert(operation->connection);
		assert(request);
		LOGF2("[PDU TX] pdu: %p, op: %p, session: %p, bus: %p, fd: %6d, seq: %5lld, protoLen: %4u, valueLen: %u",
		(void)operation->request, (void)operation,

		LOGF2("[PDU TX] pdu: %p, session: %p, bus: %p, "
		"fd: %6d, seq: %8lld, protoLen: %8u, valueLen: %8u, op: %p",
		(void*)operation->request,
		(void)operation->connection->pSession, (void)operation->connection->messageBus,
		operation->connection->socket, request->message.header.sequence,
		header.protobufLength, header.valueLength);
		header.protobufLength, header.valueLength,
		(void*)operation);
		KineticLogger_LogHeader(3, &header);
		KineticLogger_LogProtobuf(3, proto);

test/system/test_system_async_throughput.c

+1 −1

Original line number	Diff line number	Diff line
		@@ -58,7 +58,7 @@ void run_throghput_tests(size_t num_ops, size_t value_size)
		};
		KineticClientConfig config = {
		.logFile = "stdout",
		.logLevel = 0,
		.logLevel = 1,
		};
		KineticClient * client = KineticClient_Init(&config);

test/system/test_system_noop.c

+1 −1

Original line number	Diff line number	Diff line
		@@ -24,7 +24,7 @@ static SystemTestFixture Fixture;

		void setUp(void)
		{
		SystemTestSetup(&Fixture, 1);
		SystemTestSetup(&Fixture, 3);
		}

		void tearDown(void)