From 6290c279b4b0d084dfb6a33526fa1263b0d7a2c0 Mon Sep 17 00:00:00 2001 From: Szczepan Zalega Date: Wed, 4 Oct 2017 09:36:09 +0200 Subject: Make additional retries for longer running commands Signed-off-by: Szczepan Zalega --- include/device_proto.h | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) (limited to 'include') diff --git a/include/device_proto.h b/include/device_proto.h index bb14b42..cfb7544 100644 --- a/include/device_proto.h +++ b/include/device_proto.h @@ -308,7 +308,7 @@ namespace nitrokey { } if (resp.device_status == static_cast(stick10::device_status::busy)) { dev->m_counters.busy++; - if (busy_counter++<3) { + if (busy_counter++<10) { receiving_retry_counter++; LOG("Status busy, not decreasing receiving_retry_counter counter: " + std::to_string(receiving_retry_counter), Loglevel::DEBUG_L2); -- cgit v1.2.3 From e0284726110bcdcccb6b8fe6c84466cd6c14c612 Mon Sep 17 00:00:00 2001 From: Szczepan Zalega Date: Tue, 10 Oct 2017 16:05:34 +0200 Subject: Skip checking packet's CRC Signed-off-by: Szczepan Zalega --- include/device_proto.h | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) (limited to 'include') diff --git a/include/device_proto.h b/include/device_proto.h index cfb7544..6944bdb 100644 --- a/include/device_proto.h +++ b/include/device_proto.h @@ -298,9 +298,9 @@ namespace nitrokey { }; } - //SENDPASSWORD gives wrong CRC , for now rely on !=0 (TODO report) -// if (resp.device_status == 0 && resp.last_command_crc == outp.crc && resp.isCRCcorrect()) break; - auto CRC_equal_awaited = resp.last_command_crc == outp.crc; + //Some of the commands return wrong CRC, for now skip checking it (TODO list and report) + //if (resp.device_status == 0 && resp.last_command_crc == outp.crc && resp.isCRCcorrect()) break; + auto CRC_equal_awaited = true; // resp.last_command_crc == outp.crc; if (resp.device_status == static_cast(stick10::device_status::ok) && CRC_equal_awaited && resp.isValid()){ successful_communication = true; -- cgit v1.2.3 From 1107681a2a8f53184ef7824fc8947eb88cfabf21 Mon Sep 17 00:00:00 2001 From: Szczepan Zalega Date: Tue, 10 Oct 2017 16:05:56 +0200 Subject: Code reformat Signed-off-by: Szczepan Zalega --- include/device_proto.h | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) (limited to 'include') diff --git a/include/device_proto.h b/include/device_proto.h index 6944bdb..34c68c3 100644 --- a/include/device_proto.h +++ b/include/device_proto.h @@ -328,8 +328,8 @@ namespace nitrokey { break; } LOG(std::string("Retry status - dev status, awaited cmd crc, correct packet CRC: ") - + std::to_string(resp.device_status) + " " + - std::to_string(CRC_equal_awaited) + + + std::to_string(resp.device_status) + + " " + std::to_string(CRC_equal_awaited) + " " + std::to_string(resp.isCRCcorrect()), Loglevel::DEBUG_L2); if (!resp.isCRCcorrect()) dev->m_counters.wrong_CRC++; -- cgit v1.2.3 From 7ca16405dd827f79b0c9f49f3b44774ce3553a85 Mon Sep 17 00:00:00 2001 From: Szczepan Zalega Date: Tue, 10 Oct 2017 15:53:29 +0200 Subject: Number exceptions for easy return code Signed-off-by: Szczepan Zalega --- include/DeviceCommunicationExceptions.h | 7 +++++++ 1 file changed, 7 insertions(+) (limited to 'include') diff --git a/include/DeviceCommunicationExceptions.h b/include/DeviceCommunicationExceptions.h index 2913975..4dbd35d 100644 --- a/include/DeviceCommunicationExceptions.h +++ b/include/DeviceCommunicationExceptions.h @@ -6,6 +6,7 @@ #include #include + class DeviceCommunicationException: public std::runtime_error { std::string message; @@ -14,6 +15,7 @@ public: DeviceCommunicationException(std::string _msg): std::runtime_error(_msg), message(_msg){ ++occurred; } + const uint8_t getType() const {return 1;}; // virtual const char* what() const throw() override { // return message.c_str(); // } @@ -24,21 +26,26 @@ public: class DeviceNotConnected: public DeviceCommunicationException { public: DeviceNotConnected(std::string msg) : DeviceCommunicationException(msg){} + const uint8_t getType(){return 2;}; + }; class DeviceSendingFailure: public DeviceCommunicationException { public: DeviceSendingFailure(std::string msg) : DeviceCommunicationException(msg){} + const uint8_t getType(){return 3;}; }; class DeviceReceivingFailure: public DeviceCommunicationException { public: DeviceReceivingFailure(std::string msg) : DeviceCommunicationException(msg){} + const uint8_t getType(){return 4;}; }; class InvalidCRCReceived: public DeviceReceivingFailure { public: InvalidCRCReceived(std::string msg) : DeviceReceivingFailure(msg){} + const uint8_t getType(){return 5;}; }; -- cgit v1.2.3 From cf7110f02f793c791b7227bf1579eaaa81d3fd30 Mon Sep 17 00:00:00 2001 From: Szczepan Zalega Date: Tue, 10 Oct 2017 15:54:43 +0200 Subject: Add DEBUG_L1 level and set it as default for Python tests Signed-off-by: Szczepan Zalega --- NK_C_API.cc | 6 ++++++ NK_C_API.h | 8 +++++++- include/log.h | 1 + log.cc | 2 ++ unittest/conftest.py | 8 ++++++-- 5 files changed, 22 insertions(+), 3 deletions(-) (limited to 'include') diff --git a/NK_C_API.cc b/NK_C_API.cc index 822c95d..e730bae 100644 --- a/NK_C_API.cc +++ b/NK_C_API.cc @@ -296,6 +296,12 @@ extern "C" { m->set_debug(state); } + + NK_C_API void NK_set_debug_level(const int level) { + auto m = NitrokeyManager::instance(); + m->set_loglevel(level); + } + NK_C_API int NK_totp_set_time(uint64_t time) { auto m = NitrokeyManager::instance(); return get_without_result([&]() { diff --git a/NK_C_API.h b/NK_C_API.h index 18f8d0a..3742b43 100644 --- a/NK_C_API.h +++ b/NK_C_API.h @@ -14,10 +14,16 @@ extern "C" { #endif /** * Set debug level of messages written on stderr - * @param state state=True - all messages, state=False - only errors level + * @param state state=True - most messages, state=False - only errors level */ NK_C_API void NK_set_debug(bool state); + /** + * Set debug level of messages written on stderr + * @param level (int) 0-lowest verbosity, 5-highest verbosity + */ + NK_C_API void NK_set_debug_level(const int level); + /** * Connect to device of given model. Currently library can be connected only to one device at once. * @param device_model char 'S': Nitrokey Storage, 'P': Nitrokey Pro diff --git a/include/log.h b/include/log.h index 80e5097..a97ff25 100644 --- a/include/log.h +++ b/include/log.h @@ -19,6 +19,7 @@ namespace nitrokey { ERROR, WARNING, INFO, + DEBUG_L1, DEBUG, DEBUG_L2 }; diff --git a/log.cc b/log.cc index 7d61a0d..c29b85b 100644 --- a/log.cc +++ b/log.cc @@ -14,6 +14,8 @@ namespace nitrokey { std::string LogHandler::loglevel_to_str(Loglevel lvl) { switch (lvl) { + case Loglevel::DEBUG_L1: + return std::string("DEBUG_L1"); case Loglevel::DEBUG_L2: return std::string("DEBUG_L2"); case Loglevel::DEBUG: diff --git a/unittest/conftest.py b/unittest/conftest.py index 8c9899c..ef4539c 100644 --- a/unittest/conftest.py +++ b/unittest/conftest.py @@ -20,14 +20,17 @@ def C(request): with open(fp, 'r') as f: declarations = f.readlines() + cnt = 0 a = iter(declarations) for declaration in a: if declaration.strip().startswith('NK_C_API'): declaration = declaration.replace('NK_C_API', '').strip() while ';' not in declaration: declaration += (next(a)).strip() - print(declaration) + # print(declaration) ffi.cdef(declaration, override=True) + cnt +=1 + print('Imported {} declarations'.format(cnt)) C = None import os, sys @@ -73,6 +76,7 @@ def C(request): print('Finished') request.addfinalizer(fin) - C.NK_set_debug(True) + # C.NK_set_debug(True) + C.NK_set_debug_level(3) return C -- cgit v1.2.3 From 69fc2ffcd32527c14c792cf4d3e30e4073a8f0fa Mon Sep 17 00:00:00 2001 From: Szczepan Zalega Date: Tue, 10 Oct 2017 15:58:56 +0200 Subject: Add DEBUG_L1 log messages Signed-off-by: Szczepan Zalega --- include/device_proto.h | 42 ++++++++++++++++++++++++++++++++++++++---- 1 file changed, 38 insertions(+), 4 deletions(-) (limited to 'include') diff --git a/include/device_proto.h b/include/device_proto.h index 34c68c3..d7edfe2 100644 --- a/include/device_proto.h +++ b/include/device_proto.h @@ -223,6 +223,7 @@ namespace nitrokey { LOG(__FUNCTION__, Loglevel::DEBUG_L2); if (dev == nullptr){ + LOG(std::string("Throw: Device not initialized"), Loglevel::DEBUG_L1); throw DeviceNotConnected("Device not initialized"); } dev->m_counters.total_comm_runs++; @@ -241,8 +242,13 @@ namespace nitrokey { LOG("-------------------", Loglevel::DEBUG); LOG("Outgoing HID packet:", Loglevel::DEBUG); LOG(static_cast(outp), Loglevel::DEBUG); + LOG(std::string("=> ") + std::string(commandid_to_string(static_cast(outp.command_id))), Loglevel::DEBUG_L1); - if (!outp.isValid()) throw DeviceSendingFailure("Invalid outgoing packet"); + + if (!outp.isValid()) { + LOG(std::string("Throw: Invalid outgoing packet"), Loglevel::DEBUG_L1); + throw DeviceSendingFailure("Invalid outgoing packet"); + } bool successful_communication = false; int receiving_retry_counter = 0; @@ -255,6 +261,7 @@ namespace nitrokey { // LOG("Encountered communication error, disconnecting device", Loglevel::DEBUG_L2); // dev->disconnect(); dev->m_counters.sending_error++; + LOG(std::string("Throw: Device error while sending command "), Loglevel::DEBUG_L1); throw DeviceSendingFailure( std::string("Device error while sending command ") + std::to_string(status)); @@ -267,6 +274,9 @@ 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); @@ -308,6 +318,13 @@ 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: " + @@ -358,32 +375,49 @@ namespace nitrokey { if (status <= 0) { dev->m_counters.receiving_error++; + LOG(std::string("Throw: Device error while executing command "), Loglevel::DEBUG_L1); throw DeviceReceivingFailure( //FIXME replace with CriticalErrorException std::string("Device error while executing command ") + std::to_string(status)); } + LOG(std::string("<= ") + + std::string( + commandid_to_string(static_cast(resp.command_id)) + + std::string(" ") + + std::to_string(resp.storage_status.device_status) +// + std::to_string( status_translate_command(resp.storage_status.device_status)) + ), Loglevel::DEBUG_L1); + 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_L2); + Loglevel::DEBUG_L1); if (resp.device_status == static_cast(stick10::device_status::busy) && static_cast(resp.storage_status.device_status) == stick20::device_status::busy_progressbar){ dev->m_counters.busy_progressbar++; + LOG(std::string("Throw: Long operation in progress exception"), Loglevel::DEBUG_L1); throw LongOperationInProgressException( resp.command_id, resp.device_status, resp.storage_status.progress_bar_value); } - if (!resp.isValid()) throw InvalidCRCReceived("Invalid incoming packet"); - if (receiving_retry_counter <= 0) + if (!resp.isValid()) { + LOG(std::string("Throw: Invalid incoming packet"), Loglevel::DEBUG_L1); + throw InvalidCRCReceived("Invalid incoming packet"); + } + if (receiving_retry_counter <= 0){ + LOG(std::string("Throw: \"Maximum receiving_retry_counter count reached for receiving response from the device!\"" + + std::to_string(receiving_retry_counter)), Loglevel::DEBUG_L1); throw DeviceReceivingFailure( "Maximum receiving_retry_counter count reached for receiving response from the device!"); + } dev->m_counters.communication_successful++; if (resp.last_command_status != static_cast(stick10::command_status::ok)){ dev->m_counters.command_result_not_equal_0_recv++; + LOG(std::string("Throw: CommandFailedException"), Loglevel::DEBUG_L1); throw CommandFailedException(resp.command_id, resp.last_command_status); } -- cgit v1.2.3 From a42e922507aa143868194508b976b4fd3ceac3d1 Mon Sep 17 00:00:00 2001 From: Szczepan Zalega Date: Tue, 10 Oct 2017 15:59:35 +0200 Subject: Translate properly Storage error on AES decoding fail Signed-off-by: Szczepan Zalega --- include/device_proto.h | 3 +++ 1 file changed, 3 insertions(+) (limited to 'include') diff --git a/include/device_proto.h b/include/device_proto.h index d7edfe2..0be40f8 100644 --- a/include/device_proto.h +++ b/include/device_proto.h @@ -300,6 +300,9 @@ namespace nitrokey { resp.last_command_status = static_cast(stick10::command_status::wrong_password); resp.device_status = static_cast(stick10::device_status::ok); break; + case stick20::device_status::no_user_password_unlock: + resp.last_command_status = static_cast(stick10::command_status::AES_dec_failed); + resp.device_status = static_cast(stick10::device_status::ok); default: LOG(std::string("Unknown storage device status, cannot translate: ") + std::to_string(resp.storage_status.device_status), Loglevel::DEBUG); -- cgit v1.2.3 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(-) (limited to 'include') 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.3