Feat/better logging #1555

pattivacek · 2020-02-12T16:25:02Z

Requested by @koshelev to speed up debugging, particularly when all we have is a log with the default loglevel. This is approximately how it will look:

Adding Secondary with ECU serial: 2c1644ed995acb07bebc4f0b1d0d3ad4865a7c3cb8eeb6de6f58bb543cd4c188 with hardware ID: virtualsec-demo
Primary ECU serial: 6d0a57cc949f6eaa1f0fb9e08984cdbc9a7328c66990290a7e5b5408061bce70 with hardware ID: local-fake
Device ID: grand-apfelkuchen-701
Device Gateway URL: https://3c877e1a-c969-4b71-9ba9-16b909a88c44.device-gateway.ota.api.here.com:443
Certificate subject: CN=grand-apfelkuchen-701, OU=Devices
Certificate issuer: CN=Device Registration
Certificate valid from: Jan  9 09:51:35 2020 GMT until Dec  4 09:38:36 2028 GMT

Some basic information is not included by default in our logs. They can be seen with aktualizr-info or loglevel 0, but this should make it easier to figure out what's going on when all we have is a "standard" log. Suggested-by: Vladimir Koshelev <vladimir.koshelev@here.com> Signed-off-by: Patrick Vacek <patrickvacek@gmail.com>

lbonn · 2020-02-12T16:34:18Z

src/libaktualizr/crypto/keymanager.cc

  return cn;
 }

+void KeyManager::getCertInfo(std::string *subject, std::string *issuer, std::string *not_before,
+                             std::string *not_after) const {
+  std::string not_found_cert_message = "Certificate is not found, can't extract device_id";


Suggested change

std::string not_found_cert_message = "Certificate is not found, can't extract device_id";

std::string not_found_cert_message = "Certificate is not found, can't extract device certificate";

lbonn · 2020-02-12T16:34:37Z

src/libaktualizr/crypto/keymanager.cc

+    }
+  } else {  // CryptoSource::kPkcs11
+    if (!built_with_p11) {
+      throw std::runtime_error("Aktualizr was built without PKCS#11 support, can't extract device_id");


Suggested change

throw std::runtime_error("Aktualizr was built without PKCS#11 support, can't extract device_id");

throw std::runtime_error("Aktualizr was built without PKCS#11 support, can't extract device certificate");

lbonn · 2020-02-12T16:47:18Z

src/libaktualizr/crypto/keymanager.cc

+  }
+
+  StructGuard<BIO> subj_bio(BIO_new(BIO_s_mem()), BIO_vfree);
+  X509_NAME_print_ex(subj_bio.get(), X509_get_subject_name(x.get()), 1, 0);


The docs I've found are not really helpful but are we sure that this call or the next (BIO_get_mem_data) can't fail and we end up creating a string from an uninitialized pointer (subj_buf).

Maybe a simple precaution:

char *subj_buf = nullptr; ... if (subj_buf == nullptr) { throw xxx; } *subject = std::string(subj_buf, ...);

Yeah I was annoyed that the SSL docs don't even mention the return value of X509_NAME_print_ex. However, https://manpages.debian.org/unstable/libssl-doc/X509_NAME_print_ex.3ssl.en.html says that "X509_NAME_print_ex() and X509_NAME_print_ex_fp() return 1 on success or 0 on error if the XN_FLAG_COMPAT is set, which is the same as X509_NAME_print(). Otherwise, it returns -1 on error or other values on success." Lovely. I'll play around with this a bit and try to be a bit more careful.

I'm a bit scared of the return value mess so I ended up just taking your advice literally.

lbonn · 2020-02-12T16:48:18Z

Looks like it's gonna actually be helpful in the future!

Suggested-by: Vladimir Koshelev <vladimir.koshelev@here.com> Signed-off-by: Patrick Vacek <patrickvacek@gmail.com>

Signed-off-by: Patrick Vacek <patrickvacek@gmail.com>

codecov-io · 2020-02-13T11:45:50Z

Codecov Report

Merging #1555 into master will increase coverage by 0.17%.
The diff coverage is 89.06%.

@@            Coverage Diff             @@
##           master    #1555      +/-   ##
==========================================
+ Coverage   82.07%   82.25%   +0.17%     
==========================================
  Files         186      186              
  Lines       11449    11494      +45     
==========================================
+ Hits         9397     9454      +57     
+ Misses       2052     2040      -12

Impacted Files	Coverage Δ
src/libaktualizr/crypto/keymanager.h	`100% <ø> (ø)`	⬆️
src/aktualizr_primary/secondary.cc	`86.84% <100%> (ø)`	⬆️
src/cert_provider/main.cc	`62.46% <100%> (ø)`	⬆️
src/libaktualizr/crypto/crypto.cc	`85.21% <100%> (ø)`	⬆️
src/libaktualizr/crypto/keymanager.cc	`87.76% <84.21%> (-0.98%)`	⬇️
src/libaktualizr/primary/sotauptaneclient.cc	`90.27% <94.11%> (+0.04%)`	⬆️
src/libaktualizr/package_manager/debianmanager.h	`60% <0%> (-6.67%)`	⬇️
src/aktualizr_lite/main.cc	`71.62% <0%> (-0.2%)`	⬇️
src/aktualizr_primary/main.cc	`83.18% <0%> (-0.15%)`	⬇️
.../libaktualizr/package_manager/packagemanagerfake.h	`100% <0%> (ø)`	⬆️
... and 13 more

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 6b9e5b3...c9cf301. Read the comment docs.

pattivacek · 2020-02-13T11:47:16Z

Judging by the previous CI run (https://main.gitlab.in.here.com/olp/edge/ota/connect/client/aktualizr/-/jobs/1577872) it looks like I may have some openssl version compatibility issues to confront. Cool...

mike-sul · 2020-02-13T11:55:55Z

Judging by the previous CI run (https://main.gitlab.in.here.com/olp/edge/ota/connect/client/aktualizr/-/jobs/1577872) it looks like I may have some openssl version compatibility issues to confront. Cool...

looks quite similar to what I've seen on macOS, I think, the problem is that our cmake wants 1.0.2 while our code actually relies/requires on 1.1.x since switching from 1.0.2t version to 1.1.1t on the mac helped me to resolve it.

mike-sul · 2020-02-13T12:07:07Z

src/aktualizr_primary/secondary.cc

@@ -51,8 +51,8 @@ void initSecondaries(Aktualizr& aktualizr, const boost::filesystem::path& config
      Secondaries secondaries = createSecondaries(*config);

      for (const auto& secondary : secondaries) {
-        LOG_INFO << "Adding Secondary to Aktualizr."
-                 << "HW_ID: " << secondary->getHwId() << " Serial: " << secondary->getSerial();
+        LOG_INFO << "Adding Secondary with ECU serial: " << secondary->getSerial()


mixing metadata/values with message text might not be optimal as you need to search for values between text. The best practice here is to separate a static part of a log message from its variable part. For example,
`
Adding Secondary:

serial: <serial> hardware ID: <hwid>

`

but it's not critical here as there are just two variable elements here, it's rather important when there are more of them

I'm not quite sure I follow. All I did was rephrase it and swap the serial and hardware ID.

mike-sul · 2020-02-13T12:08:29Z

good start, I think, it makes sense to review and improve logging in other places too.

pattivacek · 2020-02-13T12:58:22Z

Judging by the previous CI run (https://main.gitlab.in.here.com/olp/edge/ota/connect/client/aktualizr/-/jobs/1577872) it looks like I may have some openssl version compatibility issues to confront. Cool...

looks quite similar to what I've seen on macOS, I think, the problem is that our cmake wants 1.0.2 while our code actually relies/requires on 1.1.x since switching from 1.0.2t version to 1.1.1t on the mac helped me to resolve it.

I think we generally still want to support 1.0.2, so I have to work around that. The reason I didn't already, though, was that the website claims that "These functions are available in all versions of OpenSSL." Obviously that's not true.

Despite that the website claims that "these functions are available in all versions of OpenSSL." Signed-off-by: Patrick Vacek <patrickvacek@gmail.com>

pattivacek · 2020-02-13T14:06:03Z

Fixed the openssl compatibility issue and incorporated all of @lbonn's suggestions. Your reviews were auto-dismissed but I'm ready for another round now.

pattivacek requested review from koshelev, lbonn, eu-siemann, mike-sul, xcheng-here and kbushgit February 12, 2020 16:25

lbonn reviewed Feb 12, 2020

View reviewed changes

koshelev previously approved these changes Feb 13, 2020

View reviewed changes

pattivacek added 2 commits February 13, 2020 12:40

Also print basic device certificate information to the log.

b64fe4d

Suggested-by: Vladimir Koshelev <vladimir.koshelev@here.com> Signed-off-by: Patrick Vacek <patrickvacek@gmail.com>

Specify some NOLINTs to prevent masking other problems.

b7adc45

Signed-off-by: Patrick Vacek <patrickvacek@gmail.com>

pattivacek dismissed koshelev’s stale review via b7adc45 February 13, 2020 11:45

pattivacek force-pushed the feat/better-logging branch from 3adbedd to b7adc45 Compare February 13, 2020 11:45

mike-sul reviewed Feb 13, 2020

View reviewed changes

mike-sul previously approved these changes Feb 13, 2020

View reviewed changes

pattivacek dismissed mike-sul’s stale review via 115b298 February 13, 2020 13:17

Attempt to support pre-1.1.0 openssl.

c9cf301

Despite that the website claims that "these functions are available in all versions of OpenSSL." Signed-off-by: Patrick Vacek <patrickvacek@gmail.com>

pattivacek force-pushed the feat/better-logging branch from 115b298 to c9cf301 Compare February 13, 2020 13:24

lbonn approved these changes Feb 13, 2020

View reviewed changes

pattivacek merged commit ce42c5d into master Feb 13, 2020

pattivacek deleted the feat/better-logging branch February 13, 2020 14:39

pattivacek mentioned this pull request Apr 6, 2020

Read device ID #1630

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Feat/better logging #1555

Feat/better logging #1555

pattivacek commented Feb 12, 2020

lbonn Feb 12, 2020

lbonn Feb 12, 2020

lbonn Feb 12, 2020

pattivacek Feb 13, 2020

pattivacek Feb 13, 2020

lbonn commented Feb 12, 2020

codecov-io commented Feb 13, 2020 •

edited

Loading

pattivacek commented Feb 13, 2020

mike-sul commented Feb 13, 2020

mike-sul Feb 13, 2020 •

edited

Loading

pattivacek Feb 13, 2020

mike-sul commented Feb 13, 2020

pattivacek commented Feb 13, 2020

pattivacek commented Feb 13, 2020

	std::string not_found_cert_message = "Certificate is not found, can't extract device_id";
	std::string not_found_cert_message = "Certificate is not found, can't extract device certificate";

	throw std::runtime_error("Aktualizr was built without PKCS#11 support, can't extract device_id");
	throw std::runtime_error("Aktualizr was built without PKCS#11 support, can't extract device certificate");

Feat/better logging #1555

Feat/better logging #1555

Conversation

pattivacek commented Feb 12, 2020

lbonn Feb 12, 2020

Choose a reason for hiding this comment

lbonn Feb 12, 2020

Choose a reason for hiding this comment

lbonn Feb 12, 2020

Choose a reason for hiding this comment

pattivacek Feb 13, 2020

Choose a reason for hiding this comment

pattivacek Feb 13, 2020

Choose a reason for hiding this comment

lbonn commented Feb 12, 2020

codecov-io commented Feb 13, 2020 • edited Loading

Codecov Report

pattivacek commented Feb 13, 2020

mike-sul commented Feb 13, 2020

mike-sul Feb 13, 2020 • edited Loading

Choose a reason for hiding this comment

pattivacek Feb 13, 2020

Choose a reason for hiding this comment

mike-sul commented Feb 13, 2020

pattivacek commented Feb 13, 2020

pattivacek commented Feb 13, 2020

codecov-io commented Feb 13, 2020 •

edited

Loading

mike-sul Feb 13, 2020 •

edited

Loading