From 2198d1b46d8bbfabc6e04b716ca89583044b277e Mon Sep 17 00:00:00 2001 From: Szczepan Zalega Date: Tue, 10 Oct 2017 17:12:41 +0200 Subject: Log update Show progress on busy retries as dots (.) Show warning when expected CRC is different than of received response Show busy retry stats only on delay change Signed-off-by: Szczepan Zalega --- include/device_proto.h | 35 +++++++++++++++++++++++------------ log.cc | 7 +++++++ 2 files changed, 30 insertions(+), 12 deletions(-) diff --git a/include/device_proto.h b/include/device_proto.h index 0be40f8..0be9ed1 100644 --- a/include/device_proto.h +++ b/include/device_proto.h @@ -274,9 +274,6 @@ namespace nitrokey { int busy_counter = 0; auto retry_timeout = dev->get_retry_timeout(); while (receiving_retry_counter-- > 0) { - LOG(std::string("receiving_retry_counter count: ") + std::to_string(receiving_retry_counter), - Loglevel::DEBUG_L1); - dev->m_counters.recv_executed++; status = dev->recv(&resp); @@ -321,13 +318,7 @@ namespace nitrokey { } if (resp.device_status == static_cast(stick10::device_status::busy)) { dev->m_counters.busy++; - LOG(std::string("Busy retry ") - + std::to_string(resp.storage_status.device_status) - + " " - + std::to_string(retry_timeout.count()) - + " " - + std::to_string(receiving_retry_counter) - , Loglevel::DEBUG_L1); + if (busy_counter++<10) { receiving_retry_counter++; LOG("Status busy, not decreasing receiving_retry_counter counter: " + @@ -339,6 +330,13 @@ namespace nitrokey { LOG("Status busy, decreasing receiving_retry_counter counter: " + std::to_string(receiving_retry_counter) + ", current delay:" + std::to_string(retry_timeout.count()), Loglevel::DEBUG); + LOG(std::string("Busy retry ") + + std::to_string(resp.storage_status.device_status) + + " " + + std::to_string(retry_timeout.count()) + + " " + + std::to_string(receiving_retry_counter) + , Loglevel::DEBUG_L1); } } if (resp.device_status == static_cast(stick10::device_status::busy) && @@ -362,6 +360,7 @@ namespace nitrokey { LOG("Invalid incoming HID packet:", Loglevel::DEBUG_L2); LOG(static_cast(resp), Loglevel::DEBUG_L2); dev->m_counters.total_retries++; + LOG(".", Loglevel::DEBUG_L1); std::this_thread::sleep_for(retry_timeout); continue; } @@ -371,6 +370,15 @@ namespace nitrokey { Loglevel::DEBUG); } + if(resp.last_command_crc != outp.crc){ + LOG(std::string("Accepting response with CRC other than expected ") + + "Command ID: " + std::to_string(resp.command_id) + " " + + commandid_to_string(static_cast(resp.command_id)) + " " + + "Reported by response and expected: " + std::to_string(resp.last_command_crc) + "!=" + std::to_string(outp.crc), + Loglevel::WARNING + ); + } + dev->set_last_command_status(resp.last_command_status); // FIXME should be handled on device.recv clear_packet(outp); @@ -394,8 +402,11 @@ namespace nitrokey { LOG("Incoming HID packet:", Loglevel::DEBUG); LOG(static_cast(resp), Loglevel::DEBUG); - LOG(std::string("receiving_retry_counter count: ") + std::to_string(receiving_retry_counter), - Loglevel::DEBUG_L1); + if (dev->get_retry_receiving_count() - receiving_retry_counter > 2) { + LOG(std::string("Packet received with receiving_retry_counter count: ") + + std::to_string(receiving_retry_counter), + Loglevel::DEBUG_L1); + } if (resp.device_status == static_cast(stick10::device_status::busy) && static_cast(resp.storage_status.device_status) diff --git a/log.cc b/log.cc index c29b85b..4a929aa 100644 --- a/log.cc +++ b/log.cc @@ -46,14 +46,21 @@ namespace nitrokey { } std::string LogHandler::format_message_to_string(const std::string &str, const Loglevel &lvl) { + static bool last_short = false; + if (str.length() == 1){ + last_short = true; + return str; + } time_t t = time(nullptr); tm tm = *localtime(&t); std::stringstream s; s + << (last_short? "\n" : "") << "[" << std::put_time(&tm, "%c") << "]" << "[" << loglevel_to_str(lvl) << "]\t" << str << std::endl; + last_short = false; return s.str(); } -- cgit v1.2.1