Merge pull request #1555 from advancedtelematic/feat/better-logging

Feat/better logging

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()
+                 << " with hardware ID: " << secondary->getHwId();
         aktualizr.AddSecondary(secondary);
       }
     } catch (const std::exception& exc) {

src/cert_provider/main.cc

@@ -249,7 +249,8 @@ bool generateAndSign(const std::string& cacert_path, const std::string& capkey_p
     std::cerr << "PEM_write_RSAPrivateKey" << std::endl;
     return false;
   }
-  auto privkey_len = BIO_get_mem_data(privkey_file.get(), &privkey_buf);  // NOLINT
+  // NOLINTNEXTLINE(cppcoreguidelines-pro-type-cstyle-cast)
+  auto privkey_len = BIO_get_mem_data(privkey_file.get(), &privkey_buf);
   *pkey = std::string(privkey_buf, static_cast<size_t>(privkey_len));
 
   // serialize certificate
@@ -264,7 +265,8 @@ bool generateAndSign(const std::string& cacert_path, const std::string& capkey_p
     std::cerr << "PEM_write_X509" << std::endl;
     return false;
   }
-  auto cert_len = BIO_get_mem_data(cert_file.get(), &cert_buf);  // NOLINT
+  // NOLINTNEXTLINE(cppcoreguidelines-pro-type-cstyle-cast)
+  auto cert_len = BIO_get_mem_data(cert_file.get(), &cert_buf);
   *cert = std::string(cert_buf, static_cast<size_t>(cert_len));
 
   return true;

src/libaktualizr/crypto/crypto.cc

@@ -274,7 +274,7 @@ bool Crypto::parseP12(BIO *p12_bio, const std::string &p12_password, std::string
   PEM_write_bio_PrivateKey(pkey_pem_sink.get(), pkey.get(), nullptr, nullptr, 0, nullptr, nullptr);
 
   char *pkey_buf;
-  auto pkey_len = BIO_get_mem_data(pkey_pem_sink.get(), &pkey_buf);  // NOLINT
+  auto pkey_len = BIO_get_mem_data(pkey_pem_sink.get(), &pkey_buf);  // NOLINT(cppcoreguidelines-pro-type-cstyle-cast)
   *out_pkey = std::string(pkey_buf, static_cast<size_t>(pkey_len));
 
   char *cert_buf;
@@ -299,10 +299,12 @@ bool Crypto::parseP12(BIO *p12_bio, const std::string &p12_password, std::string
     PEM_write_bio_X509(ca_sink.get(), ca_cert);
     PEM_write_bio_X509(cert_sink.get(), ca_cert);
   }
-  ca_len = static_cast<size_t>(BIO_get_mem_data(ca_sink.get(), &ca_buf));  // NOLINT
+  // NOLINTNEXTLINE(cppcoreguidelines-pro-type-cstyle-cast)
+  ca_len = static_cast<size_t>(BIO_get_mem_data(ca_sink.get(), &ca_buf));
   *out_ca = std::string(ca_buf, ca_len);
 
-  cert_len = static_cast<size_t>(BIO_get_mem_data(cert_sink.get(), &cert_buf));  // NOLINT
+  // NOLINTNEXTLINE(cppcoreguidelines-pro-type-cstyle-cast)
+  cert_len = static_cast<size_t>(BIO_get_mem_data(cert_sink.get(), &cert_buf));
   *out_cert = std::string(cert_buf, cert_len);
 
   return true;
@@ -394,7 +396,7 @@ bool Crypto::generateRSAKeyPair(KeyType key_type, std::string *public_key, std::
   if (ret != 1) {
     return false;
   }
-  auto pubkey_len = BIO_get_mem_data(pubkey_sink.get(), &pubkey_buf);  // NOLINT
+  auto pubkey_len = BIO_get_mem_data(pubkey_sink.get(), &pubkey_buf);  // NOLINT(cppcoreguidelines-pro-type-cstyle-cast)
   *public_key = std::string(pubkey_buf, static_cast<size_t>(pubkey_len));
 
   char *privkey_buf;
@@ -408,7 +410,8 @@ bool Crypto::generateRSAKeyPair(KeyType key_type, std::string *public_key, std::
   if (ret != 1) {
     return false;
   }
-  auto privkey_len = BIO_get_mem_data(privkey_sink.get(), &privkey_buf);  // NOLINT
+  // NOLINTNEXTLINE(cppcoreguidelines-pro-type-cstyle-cast)
+  auto privkey_len = BIO_get_mem_data(privkey_sink.get(), &privkey_buf);
   *private_key = std::string(privkey_buf, static_cast<size_t>(privkey_len));
   return true;
 }

src/libaktualizr/crypto/keymanager.cc

@@ -1,10 +1,11 @@
 #include "keymanager.h"
 
 #include <stdexcept>
+#include <utility>
 
 #include <boost/scoped_array.hpp>
-#include <utility>
 
+#include "crypto/openssl_compat.h"
 #include "storage/invstorage.h"
 #include "utilities/types.h"
 
@@ -192,10 +193,74 @@ std::string KeyManager::getCN() const {
   }
   boost::scoped_array<char> buf(new char[len + 1]);
   X509_NAME_get_text_by_NID(X509_get_subject_name(x.get()), NID_commonName, buf.get(), len + 1);
-  std::string cn(buf.get());
+  const std::string cn(buf.get());
   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 certificate";
+  std::string cert;
+  if (config_.tls_cert_source == CryptoSource::kFile || config_.tls_cert_source == CryptoSource::kAndroid) {
+    if (!backend_->loadTlsCert(&cert)) {
+      throw std::runtime_error(not_found_cert_message);
+    }
+  } else {  // CryptoSource::kPkcs11
+    if (!built_with_p11) {
+      throw std::runtime_error("Aktualizr was built without PKCS#11 support, can't extract device certificate");
+    }
+    if (!(*p11_)->readTlsCert(&cert)) {
+      throw std::runtime_error(not_found_cert_message);
+    }
+  }
+
+  StructGuard<BIO> bio(BIO_new_mem_buf(const_cast<char *>(cert.c_str()), static_cast<int>(cert.size())), BIO_vfree);
+  StructGuard<X509> x(PEM_read_bio_X509(bio.get(), nullptr, nullptr, nullptr), X509_free);
+  if (x == nullptr) {
+    throw std::runtime_error("Could not parse certificate");
+  }
+
+  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);
+  char *subj_buf = nullptr;
+  auto subj_len = BIO_get_mem_data(subj_bio.get(), &subj_buf);  // NOLINT(cppcoreguidelines-pro-type-cstyle-cast)
+  if (subj_buf == nullptr) {
+    throw std::runtime_error("Could not parse certificate subject");
+  }
+  *subject = std::string(subj_buf, static_cast<size_t>(subj_len));
+
+  StructGuard<BIO> issuer_bio(BIO_new(BIO_s_mem()), BIO_vfree);
+  X509_NAME_print_ex(issuer_bio.get(), X509_get_issuer_name(x.get()), 1, 0);
+  char *issuer_buf = nullptr;
+  auto issuer_len = BIO_get_mem_data(issuer_bio.get(), &issuer_buf);  // NOLINT(cppcoreguidelines-pro-type-cstyle-cast)
+  if (issuer_buf == nullptr) {
+    throw std::runtime_error("Could not parse certificate issuer");
+  }
+  *issuer = std::string(issuer_buf, static_cast<size_t>(issuer_len));
+
+#if AKTUALIZR_OPENSSL_PRE_11
+  const ASN1_TIME *nb_asn1 = X509_get_notBefore(x.get());
+#else
+  const ASN1_TIME *nb_asn1 = X509_get0_notBefore(x.get());
+#endif
+  StructGuard<BIO> nb_bio(BIO_new(BIO_s_mem()), BIO_vfree);
+  ASN1_TIME_print(nb_bio.get(), nb_asn1);
+  char *nb_buf;
+  auto nb_len = BIO_get_mem_data(nb_bio.get(), &nb_buf);  // NOLINT(cppcoreguidelines-pro-type-cstyle-cast)
+  *not_before = std::string(nb_buf, static_cast<size_t>(nb_len));
+
+#if AKTUALIZR_OPENSSL_PRE_11
+  const ASN1_TIME *na_asn1 = X509_get_notAfter(x.get());
+#else
+  const ASN1_TIME *na_asn1 = X509_get0_notAfter(x.get());
+#endif
+  StructGuard<BIO> na_bio(BIO_new(BIO_s_mem()), BIO_vfree);
+  ASN1_TIME_print(na_bio.get(), na_asn1);
+  char *na_buf;
+  auto na_len = BIO_get_mem_data(na_bio.get(), &na_buf);  // NOLINT(cppcoreguidelines-pro-type-cstyle-cast)
+  *not_after = std::string(na_buf, static_cast<size_t>(na_len));
+}
+
 void KeyManager::copyCertsToCurl(HttpInterface &http) {
   std::string pkey = getPkey();
   std::string cert = getCert();

src/libaktualizr/crypto/keymanager.h

@@ -25,6 +25,7 @@ class KeyManager {
   std::string getCert() const;
   std::string getCa() const;
   std::string getCN() const;
+  void getCertInfo(std::string *subject, std::string *issuer, std::string *not_before, std::string *not_after) const;
   bool isOk() const { return ((getPkey().size() != 0u) && (getCert().size() != 0u) && (getCa().size() != 0u)); }
   std::string generateUptaneKeyPair();
   KeyType getUptaneKeyType() const { return config_.uptane_key_type; }

src/libaktualizr/primary/sotauptaneclient.cc

@@ -79,7 +79,7 @@ void SotaUptaneClient::finalizeAfterReboot() {
   // TODO: consider bringing checkAndUpdatePendingSecondaries and the following functionality
   // to the common denominator
   if (!hasPendingUpdates()) {
-    LOG_INFO << "No any pending update, continue with initialization";
+    LOG_DEBUG << "No pending updates, continuing with initialization";
     return;
   }
 
@@ -90,7 +90,7 @@ void SotaUptaneClient::finalizeAfterReboot() {
   storage->loadInstalledVersions(primary_ecu_serial.ToString(), nullptr, &pending_target);
 
   if (!pending_target) {
-    LOG_ERROR << "No any pending update for Primary ECU is found, continue with initialization";
+    LOG_ERROR << "No pending update for Primary ECU found, continuing with initialization";
     return;
   }
 
@@ -100,7 +100,7 @@ void SotaUptaneClient::finalizeAfterReboot() {
 
   if (install_res.result_code == data::ResultCode::Numeric::kNeedCompletion) {
     LOG_INFO << "Pending update for Primary ECU was not applied because reboot was not detected, "
-                "continue with initialization";
+                "continuing with initialization";
     return;
   }
 
@@ -279,10 +279,27 @@ void SotaUptaneClient::initialize() {
   uptane_manifest = std::make_shared<Uptane::ManifestIssuer>(keys, serials[0].first);
   primary_ecu_serial_ = serials[0].first;
   hw_ids.insert(serials[0]);
+  LOG_INFO << "Primary ECU serial: " << primary_ecu_serial_ << " with hardware ID: " << serials[0].second;
 
   verifySecondaries();
-  LOG_DEBUG << "... provisioned OK";
 
+  std::string device_id;
+  if (!storage->loadDeviceId(&device_id)) {
+    throw std::runtime_error("Unable to load device ID after device registration.");
+  }
+  LOG_INFO << "Device ID: " << device_id;
+  LOG_INFO << "Device Gateway URL: " << config.tls.server;
+
+  std::string subject;
+  std::string issuer;
+  std::string not_before;
+  std::string not_after;
+  keys->getCertInfo(&subject, &issuer, &not_before, &not_after);
+  LOG_INFO << "Certificate subject: " << subject;
+  LOG_INFO << "Certificate issuer: " << issuer;
+  LOG_INFO << "Certificate valid from: " << not_before << " until: " << not_after;
+
+  LOG_DEBUG << "... provisioned OK";
   finalizeAfterReboot();
 }