refactor state logging to catch more transitions in BearSSL's state, revert change in previous commit, add SSL_DUMP log level for even more debugging.

This commit is contained in:
Noah Laptop 2020-10-05 11:32:42 -07:00
parent 9854b229f7
commit c19e7ba506
2 changed files with 99 additions and 78 deletions

View file

@ -33,7 +33,8 @@ SSLClient::SSLClient( Client& client,
, m_analog_pin(analog_pin) , m_analog_pin(analog_pin)
, m_debug(debug) , m_debug(debug)
, m_is_connected(false) , m_is_connected(false)
, m_write_idx(0) { , m_write_idx(0)
, m_br_last_state(0) {
setTimeout(30*1000); setTimeout(30*1000);
// zero the iobuf just in case it's still garbage // zero the iobuf just in case it's still garbage
@ -91,6 +92,8 @@ int SSLClient::connect(const char *host, uint16_t port) {
/* see SSLClient.h*/ /* see SSLClient.h*/
size_t SSLClient::write(const uint8_t *buf, size_t size) { size_t SSLClient::write(const uint8_t *buf, size_t size) {
const char* func_name = __func__; const char* func_name = __func__;
// super debug
if (m_debug >= DebugLevel::SSL_DUMP) Serial.write(buf, size);
// check if the socket is still open and such // check if the socket is still open and such
if (!m_soft_connected(func_name) || !buf || !size) return 0; if (!m_soft_connected(func_name) || !buf || !size) return 0;
// add to the bearssl io buffer, simply appending whatever we want to write // add to the bearssl io buffer, simply appending whatever we want to write
@ -143,7 +146,7 @@ int SSLClient::available() {
} }
else if (state == BR_SSL_CLOSED) m_info("Engine closed after update", func_name); else if (state == BR_SSL_CLOSED) m_info("Engine closed after update", func_name);
// flush the buffer if it's stuck in the SENDAPP state // flush the buffer if it's stuck in the SENDAPP state
// else if (state & BR_SSL_SENDAPP) br_ssl_engine_flush(&m_sslctx.eng, 0); else if (state & BR_SSL_SENDAPP) br_ssl_engine_flush(&m_sslctx.eng, 0);
// other state, or client is closed // other state, or client is closed
return 0; return 0;
} }
@ -389,17 +392,7 @@ int SSLClient::m_run_until(const unsigned target) {
if (state != lastState || lastState == 0) { if (state != lastState || lastState == 0) {
lastState = state; lastState = state;
m_info("m_run changed state:", func_name); m_info("m_run changed state:", func_name);
if(m_debug == DebugLevel::SSL_INFO) { m_print_br_state(state, DebugLevel::SSL_INFO);
m_info("State: ", func_name);
if(state == 0) Serial.println(" Invalid");
else if (state & BR_SSL_CLOSED) Serial.println(" Connection closed");
else {
if (state & BR_SSL_SENDREC) Serial.println(" SENDREC");
if (state & BR_SSL_RECVREC) Serial.println(" RECVREC");
if (state & BR_SSL_SENDAPP) Serial.println(" SENDAPP");
if (state & BR_SSL_RECVAPP) Serial.println(" RECVAPP");
}
}
} }
if (state & BR_SSL_RECVREC) { if (state & BR_SSL_RECVREC) {
size_t len; size_t len;
@ -457,6 +450,11 @@ unsigned SSLClient::m_update_engine() {
for(;;) { for(;;) {
// get the state // get the state
unsigned state = br_ssl_engine_current_state(&m_sslctx.eng); unsigned state = br_ssl_engine_current_state(&m_sslctx.eng);
// debug
if (m_br_last_state == 0 || state != m_br_last_state) {
m_br_last_state = state;
m_print_br_state(state, DebugLevel::SSL_INFO);
}
if (state & BR_SSL_CLOSED) return state; if (state & BR_SSL_CLOSED) return state;
/* /*
* If there is some record data to send, do it. This takes * If there is some record data to send, do it. This takes
@ -692,3 +690,19 @@ void SSLClient::m_print_br_error(const unsigned br_error_code, const DebugLevel
default: Serial.print("Unknown error code: "); Serial.println(br_error_code); break; default: Serial.print("Unknown error code: "); Serial.println(br_error_code); break;
} }
} }
void SSLClient::m_print_br_state(const unsigned state, const DebugLevel level) const {
const char* func_name = __func__;
if (level > m_debug) return;
m_print_prefix(func_name, level);
m_info("State: ", func_name);
if(state == 0) Serial.println(" Invalid");
else if (state & BR_SSL_CLOSED) Serial.println(" Connection closed");
else {
if (state & BR_SSL_SENDREC) Serial.println(" SENDREC");
if (state & BR_SSL_RECVREC) Serial.println(" RECVREC");
if (state & BR_SSL_SENDAPP) Serial.println(" SENDAPP");
if (state & BR_SSL_RECVAPP) Serial.println(" RECVAPP");
}
}

View file

@ -72,6 +72,8 @@ public:
SSL_WARN = 2, SSL_WARN = 2,
/** Output errors, warnings, and internal information (very verbose) */ /** Output errors, warnings, and internal information (very verbose) */
SSL_INFO = 3, SSL_INFO = 3,
/** In addition to the above logs, dumps every byte in SSLClient::write to the Serial monitor */
SSL_DUMP = 4,
}; };
/** /**
@ -394,6 +396,9 @@ private:
/** @brief Print the text string associated with a BearSSL error code */ /** @brief Print the text string associated with a BearSSL error code */
void m_print_br_error(const unsigned br_error_code, const DebugLevel level) const; void m_print_br_error(const unsigned br_error_code, const DebugLevel level) const;
/** @brief Print the text string associated with the BearSSL state */
void m_print_br_state(const unsigned br_state, const DebugLevel level) const;
/** @brief debugging print function, only prints if m_debug is true */ /** @brief debugging print function, only prints if m_debug is true */
template<typename T> template<typename T>
void m_print(const T str, const char* func_name, const DebugLevel level) const { void m_print(const T str, const char* func_name, const DebugLevel level) const {
@ -453,6 +458,8 @@ private:
// so we can send our records all at once to prevent // so we can send our records all at once to prevent
// weird timing issues // weird timing issues
size_t m_write_idx; size_t m_write_idx;
// store the last BearSSL state so we can print changes to the console
unsigned m_br_last_state;
}; };
#endif /** SSLClient_H_ */ #endif /** SSLClient_H_ */