Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

update comms logs with new logging API #1169

Merged
merged 9 commits into from
Dec 10, 2016
Merged

update comms logs with new logging API #1169

Show file tree
Hide file tree
Changes from 1 commit
Commits
Show all changes
9 commits
Select commit Hold shift + click to select a range
21d419c
update comms logs with new logging API
technobly Nov 14, 2016
31737b7
Merge branch 'develop' into feature/comms-logging
technobly Dec 1, 2016
50a290d
remove extra \r\n, add parent logging category, include new protocol …
technobly Dec 1, 2016
da14848
simplify and align a few more logging categories
technobly Dec 2, 2016
18f1490
removed hanshake (aka herobrine)
technobly Dec 5, 2016
d42d8d9
switch Travis CI to use gcc 5.3.1 20160307
technobly Dec 5, 2016
21ae9d3
Revert "switch Travis CI to use gcc 5.3.1 20160307"
technobly Dec 6, 2016
22fcadd
abbreviate logging to reduce system part 1 binary
technobly Dec 7, 2016
6fd81fe
Merge branch 'develop' into feature/comms-logging
technobly Dec 10, 2016
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
27 changes: 14 additions & 13 deletions communication/lib/mbedtls/library/debug.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -70,7 +70,7 @@ static inline void debug_send_line( const mbedtls_ssl_context *ssl, int level,
*/
#if defined(MBEDTLS_THREADING_C)
char idstr[20 + DEBUG_BUF_SIZE]; /* 0x + 16 nibbles + ': ' */
mbedtls_snprintf( idstr, sizeof( idstr ), "%p: %s", ssl, str );
mbedtls_snprintf( idstr, sizeof( idstr ), "%p: %s\r\n", ssl, str );
Copy link
Member

@sergeuz sergeuz Dec 1, 2016 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Can we just add single "\r\n" sequence to my_debug callback which all mbedtls debugging output is being forwarded to?

As I side note, I think we should avoid making non-critical changes in our third party dependencies whenever possible, since it complicates merging. Ideally, when we know that we didn't make any changes in some library, we should be able to just replace its sources with newer version.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I did originally do that via debug_send_line, but there are some cases where it's not appropriate, like a buffer dump. So the higher level API needed modification instead. The above change to line 73 I believe was residual testing that should have been removed (MBEDTLS_THREADING_C is not currently defined). If we add \r\n to my_debug most of the log messages would end with \n\r\n adding a bunch of space to the log output. I agree we should try to minimize changes to 3rd party libraries, but we also need to have effective logs. I think these changes should merge with upstream MBEDTLS library changes without conflict. I'll revert the change on line 73.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ideally, new line sequence should be specific to a log handler, as "\r\n", for example, makes sense only for serial logging. We can make the logging framework perform new line conversions on the fly, but, surely, that's not something that needs to be discussed in the scope of this PR.

ssl->conf->f_dbg( ssl->conf->p_dbg, level, file, line, idstr );
#else
ssl->conf->f_dbg( ssl->conf->p_dbg, level, file, line, str );
Expand Down Expand Up @@ -105,10 +105,11 @@ void mbedtls_debug_print_msg( const mbedtls_ssl_context *ssl, int level,
#endif
va_end( argp );

if( ret >= 0 && ret < DEBUG_BUF_SIZE - 1 )
if( ret >= 0 && ret < DEBUG_BUF_SIZE - 2 )
{
str[ret] = '\n';
str[ret + 1] = '\0';
str[ret] = '\r';
str[ret + 1] = '\n';
str[ret + 2] = '\0';
}

debug_send_line( ssl, level, file, line, str );
Expand All @@ -131,7 +132,7 @@ void mbedtls_debug_print_ret( const mbedtls_ssl_context *ssl, int level,
if( ret == MBEDTLS_ERR_SSL_WANT_READ )
return;

mbedtls_snprintf( str, sizeof( str ), "%s() returned %d (-0x%04x)\n",
mbedtls_snprintf( str, sizeof( str ), "%s() returned %d (-0x%04x)\r\n",
text, ret, -ret );

debug_send_line( ssl, level, file, line, str );
Expand All @@ -148,7 +149,7 @@ void mbedtls_debug_print_buf( const mbedtls_ssl_context *ssl, int level,
if( ssl->conf == NULL || ssl->conf->f_dbg == NULL || level > debug_threshold )
return;

mbedtls_snprintf( str + idx, sizeof( str ) - idx, "dumping '%s' (%u bytes)\n",
mbedtls_snprintf( str + idx, sizeof( str ) - idx, "dumping '%s' (%u bytes)\r\n",
text, (unsigned int) len );

debug_send_line( ssl, level, file, line, str );
Expand All @@ -164,7 +165,7 @@ void mbedtls_debug_print_buf( const mbedtls_ssl_context *ssl, int level,
{
if( i > 0 )
{
mbedtls_snprintf( str + idx, sizeof( str ) - idx, " %s\n", txt );
mbedtls_snprintf( str + idx, sizeof( str ) - idx, " %s\r\n", txt );
debug_send_line( ssl, level, file, line, str );

idx = 0;
Expand All @@ -186,7 +187,7 @@ void mbedtls_debug_print_buf( const mbedtls_ssl_context *ssl, int level,
for( /* i = i */; i % 16 != 0; i++ )
idx += mbedtls_snprintf( str + idx, sizeof( str ) - idx, " " );

mbedtls_snprintf( str + idx, sizeof( str ) - idx, " %s\n", txt );
mbedtls_snprintf( str + idx, sizeof( str ) - idx, " %s\r\n", txt );
debug_send_line( ssl, level, file, line, str );
}
}
Expand Down Expand Up @@ -229,7 +230,7 @@ void mbedtls_debug_print_mpi( const mbedtls_ssl_context *ssl, int level,
if( ( ( X->p[n] >> j ) & 1 ) != 0 )
break;

mbedtls_snprintf( str + idx, sizeof( str ) - idx, "value of '%s' (%d bits) is:\n",
mbedtls_snprintf( str + idx, sizeof( str ) - idx, "value of '%s' (%d bits) is:\r\n",
text, (int) ( ( n * ( sizeof(mbedtls_mpi_uint) << 3 ) ) + j + 1 ) );

debug_send_line( ssl, level, file, line, str );
Expand All @@ -251,7 +252,7 @@ void mbedtls_debug_print_mpi( const mbedtls_ssl_context *ssl, int level,
{
if( j > 0 )
{
mbedtls_snprintf( str + idx, sizeof( str ) - idx, "\n" );
mbedtls_snprintf( str + idx, sizeof( str ) - idx, "\r\n" );
debug_send_line( ssl, level, file, line, str );
idx = 0;
}
Expand All @@ -268,7 +269,7 @@ void mbedtls_debug_print_mpi( const mbedtls_ssl_context *ssl, int level,
if( zeros == 1 )
idx += mbedtls_snprintf( str + idx, sizeof( str ) - idx, " 00" );

mbedtls_snprintf( str + idx, sizeof( str ) - idx, "\n" );
mbedtls_snprintf( str + idx, sizeof( str ) - idx, "\r\n" );
debug_send_line( ssl, level, file, line, str );
}
#endif /* MBEDTLS_BIGNUM_C */
Expand All @@ -287,7 +288,7 @@ static void debug_print_pk( const mbedtls_ssl_context *ssl, int level,
if( mbedtls_pk_debug( pk, items ) != 0 )
{
debug_send_line( ssl, level, file, line,
"invalid PK context\n" );
"invalid PK context\r\n" );
return;
}

Expand All @@ -308,7 +309,7 @@ static void debug_print_pk( const mbedtls_ssl_context *ssl, int level,
else
#endif
debug_send_line( ssl, level, file, line,
"should not happen\n" );
"should not happen\r\n" );
}
}

Expand Down
3 changes: 2 additions & 1 deletion communication/src/coap_channel.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -85,6 +85,7 @@ ProtocolError CoAPMessageStore::send(Message& msg, system_tick_t time)
if (!msg.has_id())
return MISSING_MESSAGE_ID;

DEBUG("sending message id=%x", msg.get_id());
CoAPType::Enum coapType = CoAP::type(msg.buf());
if (coapType==CoAPType::CON || coapType==CoAPType::ACK || coapType==CoAPType::RESET)
{
Expand Down Expand Up @@ -118,7 +119,7 @@ ProtocolError CoAPMessageStore::receive(Message& msg, Channel& channel, system_t
}
channel.command(Channel::DISCARD_SESSION, nullptr);
}
DEBUG("recieved ACK for message %x", id);
DEBUG("recieved ACK for message id=%x", id);
if (!clear_message(id)) { // message didn't exist, means it's already been acknoweldged or is unknown.
msg.set_length(0);
}
Expand Down
6 changes: 3 additions & 3 deletions communication/src/coap_channel.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -245,7 +245,7 @@ class __attribute__((packed)) CoAPMessage
ProtocolError set_data(const uint8_t* data, size_t data_len)
{
if (data_len>1500)
return IO_ERROR;
return IO_ERROR_SET_DATA_MAX_EXCEEDED;
memcpy(this->data, data, data_len);
this->data_len = data_len;
return NO_ERROR;
Expand Down Expand Up @@ -427,7 +427,7 @@ class CoAPMessageStore
ProtocolError send_synchronous(Message& msg, Channel& channel, Time& time)
{
message_id_t id = msg.get_id();
DEBUG("sending message id %s synchronously", id);
DEBUG("sending message id=%x synchronously", id);
CoAPType::Enum coapType = CoAP::type(msg.buf());
ProtocolError error = send(msg, time());
if (!error)
Expand All @@ -444,7 +444,7 @@ class CoAPMessageStore
if (coapmsg)
coapmsg->set_delivered_handler(&flag_delivered);
else
ERROR("no coapmessage for msg %x", id);
ERROR("no coapmessage for msg id=%x", id);
while (from_id(id)!=nullptr && !error)
{
msg.clear();
Expand Down
54 changes: 28 additions & 26 deletions communication/src/dtls_message_channel.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -17,17 +17,19 @@
******************************************************************************
*/

#include "logging.h"
LOG_SOURCE_CATEGORY("message_channel.dtls")
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LOG_SOURCE_CATEGORY() (and all other macros which define log categories) cannot automatically make a category passed to it to be a subcategory of a category defined at module level ("comm" in this case). It's necessary to specify full name for all defined categories, e.g. "comm.message_channel.dtls".

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I was hoping to not have to hard code the parent category, but I do like the idea of knowing the logs are a sub category of the communication library. Is it fair to say all files within the communication/ folder will have a default parent category of "comm" ? That's probably a better way of keeping log messages filterable by "comm" as well ;-) I'll make this change in a couple places.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yes, if category name is not defined explicitly for a log statement's scope, upper level category name is used, up to category specified at module level (which is "comm" for communication/ directory). I didn't find a way to make categories easy to define and override, and also maintain nesting automatically at compile time.


#include "dtls_message_channel.h"
#include "protocol.h"
#include "service_debug.h"
#include "rng_hal.h"
#include "mbedtls/error.h"
#include "mbedtls/ssl_internal.h"
#include "timer_hal.h"
#include <stdio.h>
#include <string.h>
#include "dtls_session_persist.h"
#include "service_debug.h"


#if HAL_PLATFORM_CLOUD_UDP

Expand Down Expand Up @@ -86,7 +88,7 @@ auto SessionPersist::restore(mbedtls_ssl_context* context, bool renegotiate, uin
}

if (!is_valid() || keys_checksum!=this->keys_checksum) {
DEBUG("discarding session: valid %d, keys_sum: %d/%d", is_valid(), keys_checksum, this->keys_checksum);
LOG(WARN,"discarding session: valid %d, keys_sum: %d/%d", is_valid(), keys_checksum, this->keys_checksum);
return NO_SESSION;
}

Expand All @@ -113,14 +115,14 @@ auto SessionPersist::restore(mbedtls_ssl_context* context, bool renegotiate, uin
context->transform_negotiate->ciphersuite_info = mbedtls_ssl_ciphersuite_from_id(ciphersuite);
if (!context->transform_negotiate->ciphersuite_info)
{
DEBUG("unknown ciphersuite with id %d", ciphersuite);
LOG(ERROR,"unknown ciphersuite with id %d", ciphersuite);
return ERROR;
}

int err = mbedtls_ssl_derive_keys(context);
if (err)
{
DEBUG("derive keys failed with %d", err);
LOG(ERROR,"derive keys failed with %d", err);
return ERROR;
}

Expand Down Expand Up @@ -159,11 +161,11 @@ SessionPersist sessionPersist;

#define EXIT_ERROR(x, msg) \
if (x) { \
WARN("DTLS initialization failure: " #msg ": %c%04X",(x<0)?'-':' ',(x<0)?-x:x);\
LOG(WARN,"DTLS initialization failure: " #msg ": %c%04X",(x<0)?'-':' ',(x<0)?-x:x);\
return UNKNOWN; \
}

static void my_debug( void *ctx, int level,
static void my_debug(void *ctx, int level,
const char *file, int line,
const char *str )
{
Expand Down Expand Up @@ -327,15 +329,15 @@ ProtocolError DTLSMessageChannel::setup_context()

if ((ssl_context.session_negotiate->peer_cert = (mbedtls_x509_crt*)calloc(1, sizeof(mbedtls_x509_crt))) == NULL)
{
ERROR("unable to allocate certificate storage");
LOG(ERROR,"unable to allocate certificate storage");
return INSUFFICIENT_STORAGE;
}

mbedtls_x509_crt_init(ssl_context.session_negotiate->peer_cert);
ret = mbedtls_pk_parse_public_key(&ssl_context.session_negotiate->peer_cert->pk, server_public, server_public_len);
if (ret) {
WARN("unable to parse negotiated public key: -%x", -ret);
return IO_ERROR;
LOG(WARN,"unable to parse negotiated public key: -%x", -ret);
return IO_ERROR_PARSING_SERVER_PUBLIC_KEY;
}

return NO_ERROR;
Expand All @@ -344,30 +346,30 @@ ProtocolError DTLSMessageChannel::setup_context()
ProtocolError DTLSMessageChannel::establish(uint32_t& flags, uint32_t app_state_crc)
{
int ret = 0;
INFO("establish");
LOG(INFO,"setup context");
ProtocolError error = setup_context();
if (error) {
INFO("setup_contex error %x", error);
LOG(ERROR,"setup_contex error %x", error);
return error;
}
bool renegotiate = false;

SessionPersist::RestoreStatus restoreStatus = sessionPersist.restore(&ssl_context, renegotiate, keys_checksum, coap_state, callbacks.restore);
DEBUG("restoreStatus = %d", restoreStatus);
LOG(INFO,"(CMPL,RENEG,NO_SESS,ERR) restoreStatus=%d", restoreStatus);
if (restoreStatus==SessionPersist::COMPLETE)
{
DEBUG("out_ctr %d,%d,%d,%d,%d,%d,%d,%d, next_coap_id=%d", sessionPersist.out_ctr[0],
LOG(INFO,"out_ctr %d,%d,%d,%d,%d,%d,%d,%d, next_coap_id=%x", sessionPersist.out_ctr[0],
sessionPersist.out_ctr[1],sessionPersist.out_ctr[2],sessionPersist.out_ctr[3],
sessionPersist.out_ctr[4],sessionPersist.out_ctr[5],sessionPersist.out_ctr[6],
sessionPersist.out_ctr[7], sessionPersist.next_coap_id);
sessionPersist.make_persistent();
uint32_t actual = sessionPersist.application_state_checksum(this->callbacks.calculate_crc);
DEBUG("application state checksum: %x, expected: %x", actual, app_state_crc);
LOG(INFO,"application state checksum: %x, expected: %x", actual, app_state_crc);
if (actual==app_state_crc) {
DEBUG("skipping sending hello message");
LOG(WARN,"skipping sending hello message");
flags |= Protocol::SKIP_SESSION_RESUME_HELLO;
}
DEBUG("restored session from persisted session data. next_msg_id=%d", *coap_state);
LOG(INFO,"restored session from persisted session data. next_msg_id=%d", *coap_state);
return SESSION_RESUMED;
}
else if (restoreStatus==SessionPersist::RENEGOTIATE)
Expand Down Expand Up @@ -405,14 +407,14 @@ ProtocolError DTLSMessageChannel::establish(uint32_t& flags, uint32_t app_state_

if (ret)
{
DEBUG("handshake failed -%x", -ret);
LOG(ERROR,"handshake failed -%x", -ret);
reset_session();
}
else
{
sessionPersist.prepare_save(random, keys_checksum, &ssl_context, 0);
}
return ret==0 ? NO_ERROR : IO_ERROR;
return ret==0 ? NO_ERROR : IO_ERROR_GENERIC_ESTABLISH;
}

ProtocolError DTLSMessageChannel::notify_established()
Expand Down Expand Up @@ -445,7 +447,7 @@ ProtocolError DTLSMessageChannel::receive(Message& message)
break;
default:
reset_session();
return IO_ERROR;
return IO_ERROR_GENERIC_RECEIVE;
}
}
message.set_length(ret);
Expand All @@ -461,7 +463,7 @@ ProtocolError DTLSMessageChannel::receive(Message& message)
sprintf(buf, "%02x", c);
LOG_PRINT(TRACE, buf);
}
LOG_PRINT(TRACE, "\n");
LOG_PRINT(TRACE, "\r\n");
}
#endif
}
Expand All @@ -477,7 +479,7 @@ ProtocolError DTLSMessageChannel::send(Message& message)
{
// send unencrypted
int bytes = this->send(message.buf(), message.length());
return bytes < 0 ? IO_ERROR : NO_ERROR;
return bytes < 0 ? IO_ERROR_GENERIC_SEND : NO_ERROR;
}

#ifdef DEBUG_BUILD
Expand All @@ -489,14 +491,14 @@ ProtocolError DTLSMessageChannel::send(Message& message)
sprintf(buf, "%02x", c);
LOG_PRINT(TRACE, buf);
}
LOG_PRINT(TRACE, "\n");
LOG_PRINT(TRACE, "\r\n");
#endif

int ret = mbedtls_ssl_write(&ssl_context, message.buf(), message.length());
if (ret < 0 && ret != MBEDTLS_ERR_SSL_WANT_WRITE)
{
reset_session();
return IO_ERROR;
return IO_ERROR_GENERIC_MBEDTLS_SSL_WRITE;
}
sessionPersist.update(&ssl_context, callbacks.save, coap_state ? *coap_state : 0);
return NO_ERROR;
Expand All @@ -509,7 +511,7 @@ bool DTLSMessageChannel::is_unreliable()

ProtocolError DTLSMessageChannel::command(Command command, void* arg)
{
DEBUG("session command: %d", command);
LOG(INFO,"session command (CLS,DIS,MOV,LOD,SAV): %d", command);
switch (command)
{
case CLOSE:
Expand All @@ -518,7 +520,7 @@ ProtocolError DTLSMessageChannel::command(Command command, void* arg)

case DISCARD_SESSION:
reset_session();
return IO_ERROR; //force re-establish
return IO_ERROR_DISCARD_SESSION; //force re-establish

case MOVE_SESSION:
move_session = true;
Expand Down
2 changes: 1 addition & 1 deletion communication/src/dtls_session_persist.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -161,7 +161,7 @@ class __attribute__((packed)) SessionPersist : public SessionPersistOpaque
return false;
}
if (size!=sizeof(*this)) {
DEBUG("restore size mismatch %d/%d", size, sizeof(*this));
DEBUG("restore size mismatch 2: %d/%d", size, sizeof(*this));
return false;
}
}
Expand Down
Loading