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 <szczepan@nitrokey.com>

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<uint8_t>(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<uint8_t>(stick10::device_status::busy) &&
@@ -362,6 +360,7 @@ namespace nitrokey {
                   LOG("Invalid incoming HID packet:", Loglevel::DEBUG_L2);
                   LOG(static_cast<std::string>(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<CommandID>(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<std::string>(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<uint8_t>(stick10::device_status::busy) &&
                   static_cast<stick20::device_status>(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();
     }