From 49d41df98fbd3abe246a582a9169a8e7d137068d Mon Sep 17 00:00:00 2001 From: vipeller <51135538+vipeller@users.noreply.github.com> Date: Mon, 7 Feb 2022 19:16:00 -0800 Subject: [PATCH] added more logging to certificate import (#6085) In order to spot easier if any regression happened with removing bouncy castle, added some more logging. Also MainAsync() is not reports if it stops by exception. --- .../EdgeHubCertificates.cs | 4 +- .../Program.cs | 185 +++++++++--------- .../CertificateHelper.cs | 34 ++-- 3 files changed, 122 insertions(+), 101 deletions(-) diff --git a/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Service/EdgeHubCertificates.cs b/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Service/EdgeHubCertificates.cs index aac66cde3c4..8b9c1a3bbbc 100644 --- a/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Service/EdgeHubCertificates.cs +++ b/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Service/EdgeHubCertificates.cs @@ -54,7 +54,7 @@ public static async Task LoadAsync(IConfigurationRoot confi string edgeletApiVersion = configuration.GetValue(Constants.ConfigKey.WorkloadAPiVersion); DateTime expiration = DateTime.UtcNow.AddDays(Constants.CertificateValidityDays); - certificates = await CertificateHelper.GetServerCertificatesFromEdgelet(workloadUri, edgeletApiVersion, Constants.WorkloadApiVersion, moduleId, generationId, edgeHubHostname, expiration); + certificates = await CertificateHelper.GetServerCertificatesFromEdgelet(workloadUri, edgeletApiVersion, Constants.WorkloadApiVersion, moduleId, generationId, edgeHubHostname, expiration, logger); IEnumerable trustBundle = await CertificateHelper.GetTrustBundleFromEdgelet(workloadUri, edgeletApiVersion, Constants.WorkloadApiVersion, moduleId, generationId); Option manifestTrustBundle = await CertificateHelper.GetManifestTrustBundleFromEdgelet(workloadUri, edgeletApiVersion, Constants.WorkloadApiVersion, moduleId, generationId); @@ -71,7 +71,7 @@ public static async Task LoadAsync(IConfigurationRoot confi // If no connection string was set and we use iotedged workload style certificates for development (X509Certificate2 ServerCertificate, IEnumerable CertificateChain) certificates; - certificates = CertificateHelper.GetServerCertificateAndChainFromFile(edgeHubDevCertPath, edgeHubDevPrivateKeyPath); + certificates = CertificateHelper.GetServerCertificateAndChainFromFile(edgeHubDevCertPath, edgeHubDevPrivateKeyPath, logger); IEnumerable trustBundle = CertificateHelper.ParseTrustedBundleFromFile(edgeHubDevTrustBundlePath); result = new EdgeHubCertificates( diff --git a/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Service/Program.cs b/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Service/Program.cs index e54d331a518..2d8bd707443 100644 --- a/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Service/Program.cs +++ b/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Service/Program.cs @@ -54,102 +54,111 @@ static async Task MainAsync(IConfigurationRoot configuration) ILogger logger = Logger.Factory.CreateLogger("EdgeHub"); - EdgeHubCertificates certificates = await EdgeHubCertificates.LoadAsync(configuration, logger); - bool clientCertAuthEnabled = configuration.GetValue(Constants.ConfigKey.EdgeHubClientCertAuthEnabled, false); - - string sslProtocolsConfig = configuration.GetValue(Constants.ConfigKey.SslProtocols, string.Empty); - SslProtocols sslProtocols = SslProtocolsHelper.Parse(sslProtocolsConfig, DefaultSslProtocols, logger); - logger.LogInformation($"Enabling SSL protocols: {sslProtocols.Print()}"); - - IDependencyManager dependencyManager = new DependencyManager(configuration, certificates.ServerCertificate, certificates.TrustBundle, certificates.ManifestTrustBundle, sslProtocols); - Hosting hosting = Hosting.Initialize(configuration, certificates.ServerCertificate, dependencyManager, clientCertAuthEnabled, sslProtocols); - IContainer container = hosting.Container; - - logger.LogInformation("Initializing Edge Hub"); - LogLogo(logger); - LogVersionInfo(logger); - logger.LogInformation($"OptimizeForPerformance={configuration.GetValue("OptimizeForPerformance", true)}"); - logger.LogInformation($"MessageAckTimeoutSecs={configuration.GetValue("MessageAckTimeoutSecs", 30)}"); - logger.LogInformation("Loaded server certificate with expiration date of {0}", certificates.ServerCertificate.NotAfter.ToString("o")); - - var metricsProvider = container.Resolve(); - Metrics.InitWithAspNet(metricsProvider, logger); // Note this requires App.UseMetricServer() to be called in Startup.cs - - // EdgeHub and CloudConnectionProvider have a circular dependency. So need to Bind the EdgeHub to the CloudConnectionProvider. - IEdgeHub edgeHub = await container.Resolve>(); - ICloudConnectionProvider cloudConnectionProvider = await container.Resolve>(); - cloudConnectionProvider.BindEdgeHub(edgeHub); - - // EdgeHub cloud proxy and DeviceConnectivityManager have a circular dependency, - // so the cloud proxy has to be set on the DeviceConnectivityManager after both have been initialized. - var deviceConnectivityManager = container.Resolve(); - IConnectionManager connectionManager = await container.Resolve>(); - (deviceConnectivityManager as DeviceConnectivityManager)?.SetConnectionManager(connectionManager); - - // Register EdgeHub credentials - var edgeHubCredentials = container.ResolveNamed("EdgeHubCredentials"); - ICredentialsCache credentialsCache = await container.Resolve>(); - await credentialsCache.Add(edgeHubCredentials); - - // Register EdgeHub indentity in device scopes cache. - // When we connect upstream, we verify that identity is in scope. - // On a fresh start, we may not yet received the scopes from the upstream, so we need - // to force add edgeHub in the cache so it is able to connect upstream. - // Once we get the scopes from the upstream, this record is replaced. - ServiceIdentity edgeHubIdentity = container.ResolveNamed("EdgeHubIdentity"); - IServiceIdentityHierarchy identityScopes = container.Resolve(); - await identityScopes.AddOrUpdate(edgeHubIdentity); - - // Initializing configuration - logger.LogInformation("Initializing configuration"); - IConfigSource configSource = await container.Resolve>(); - ConfigUpdater configUpdater = await container.Resolve>(); - ExperimentalFeatures experimentalFeatures = CreateExperimentalFeatures(configuration); - var configUpdaterStartupFailed = new TaskCompletionSource(); - var configDownloadTask = configUpdater.Init(configSource); - - _ = configDownloadTask.ContinueWith( - _ => configUpdaterStartupFailed.SetResult(false), - TaskContinuationOptions.OnlyOnFaulted); - - if (!Enum.TryParse(configuration.GetValue("AuthenticationMode", string.Empty), true, out AuthenticationMode authenticationMode) - || authenticationMode != AuthenticationMode.Cloud) + try { - ConnectionReauthenticator connectionReauthenticator = await container.Resolve>(); - connectionReauthenticator.Init(); - } - - TimeSpan shutdownWaitPeriod = TimeSpan.FromSeconds(configuration.GetValue("ShutdownWaitPeriod", DefaultShutdownWaitPeriod)); - (CancellationTokenSource cts, ManualResetEventSlim completed, Option handler) = ShutdownHandler.Init(shutdownWaitPeriod, logger); - - double renewAfter = configuration.GetValue("ServerCertificateRenewAfterInMs", int.MaxValue); - renewAfter = renewAfter > int.MaxValue ? int.MaxValue : renewAfter; - TimeSpan maxRenewAfter = TimeSpan.FromMilliseconds(renewAfter); - using (IProtocolHead mqttBrokerProtocolHead = await GetMqttBrokerProtocolHeadAsync(experimentalFeatures, container)) - using (IProtocolHead edgeHubProtocolHead = await GetEdgeHubProtocolHeadAsync(logger, configuration, experimentalFeatures, container, hosting)) - using (var renewal = new CertificateRenewal(certificates, logger, maxRenewAfter)) - { - try + EdgeHubCertificates certificates = await EdgeHubCertificates.LoadAsync(configuration, logger); + bool clientCertAuthEnabled = configuration.GetValue(Constants.ConfigKey.EdgeHubClientCertAuthEnabled, false); + + string sslProtocolsConfig = configuration.GetValue(Constants.ConfigKey.SslProtocols, string.Empty); + SslProtocols sslProtocols = SslProtocolsHelper.Parse(sslProtocolsConfig, DefaultSslProtocols, logger); + logger.LogInformation($"Enabling SSL protocols: {sslProtocols.Print()}"); + + IDependencyManager dependencyManager = new DependencyManager(configuration, certificates.ServerCertificate, certificates.TrustBundle, certificates.ManifestTrustBundle, sslProtocols); + Hosting hosting = Hosting.Initialize(configuration, certificates.ServerCertificate, dependencyManager, clientCertAuthEnabled, sslProtocols); + IContainer container = hosting.Container; + + logger.LogInformation("Initializing Edge Hub"); + LogLogo(logger); + LogVersionInfo(logger); + logger.LogInformation($"OptimizeForPerformance={configuration.GetValue("OptimizeForPerformance", true)}"); + logger.LogInformation($"MessageAckTimeoutSecs={configuration.GetValue("MessageAckTimeoutSecs", 30)}"); + logger.LogInformation("Loaded server certificate with expiration date of {0}", certificates.ServerCertificate.NotAfter.ToString("o")); + + var metricsProvider = container.Resolve(); + Metrics.InitWithAspNet(metricsProvider, logger); // Note this requires App.UseMetricServer() to be called in Startup.cs + + // EdgeHub and CloudConnectionProvider have a circular dependency. So need to Bind the EdgeHub to the CloudConnectionProvider. + IEdgeHub edgeHub = await container.Resolve>(); + ICloudConnectionProvider cloudConnectionProvider = await container.Resolve>(); + cloudConnectionProvider.BindEdgeHub(edgeHub); + + // EdgeHub cloud proxy and DeviceConnectivityManager have a circular dependency, + // so the cloud proxy has to be set on the DeviceConnectivityManager after both have been initialized. + var deviceConnectivityManager = container.Resolve(); + IConnectionManager connectionManager = await container.Resolve>(); + (deviceConnectivityManager as DeviceConnectivityManager)?.SetConnectionManager(connectionManager); + + // Register EdgeHub credentials + var edgeHubCredentials = container.ResolveNamed("EdgeHubCredentials"); + ICredentialsCache credentialsCache = await container.Resolve>(); + await credentialsCache.Add(edgeHubCredentials); + + // Register EdgeHub indentity in device scopes cache. + // When we connect upstream, we verify that identity is in scope. + // On a fresh start, we may not yet received the scopes from the upstream, so we need + // to force add edgeHub in the cache so it is able to connect upstream. + // Once we get the scopes from the upstream, this record is replaced. + ServiceIdentity edgeHubIdentity = container.ResolveNamed("EdgeHubIdentity"); + IServiceIdentityHierarchy identityScopes = container.Resolve(); + await identityScopes.AddOrUpdate(edgeHubIdentity); + + // Initializing configuration + logger.LogInformation("Initializing configuration"); + IConfigSource configSource = await container.Resolve>(); + ConfigUpdater configUpdater = await container.Resolve>(); + ExperimentalFeatures experimentalFeatures = CreateExperimentalFeatures(configuration); + var configUpdaterStartupFailed = new TaskCompletionSource(); + var configDownloadTask = configUpdater.Init(configSource); + + _ = configDownloadTask.ContinueWith( + _ => configUpdaterStartupFailed.SetResult(false), + TaskContinuationOptions.OnlyOnFaulted); + + if (!Enum.TryParse(configuration.GetValue("AuthenticationMode", string.Empty), true, out AuthenticationMode authenticationMode) + || authenticationMode != AuthenticationMode.Cloud) { - await Task.WhenAll(mqttBrokerProtocolHead.StartAsync(), configDownloadTask); - await edgeHubProtocolHead.StartAsync(); - await Task.WhenAny(cts.Token.WhenCanceled(), renewal.Token.WhenCanceled(), configUpdaterStartupFailed.Task); + ConnectionReauthenticator connectionReauthenticator = await container.Resolve>(); + connectionReauthenticator.Init(); } - catch (Exception ex) + + TimeSpan shutdownWaitPeriod = TimeSpan.FromSeconds(configuration.GetValue("ShutdownWaitPeriod", DefaultShutdownWaitPeriod)); + (CancellationTokenSource cts, ManualResetEventSlim completed, Option handler) = ShutdownHandler.Init(shutdownWaitPeriod, logger); + + double renewAfter = configuration.GetValue("ServerCertificateRenewAfterInMs", int.MaxValue); + renewAfter = renewAfter > int.MaxValue ? int.MaxValue : renewAfter; + TimeSpan maxRenewAfter = TimeSpan.FromMilliseconds(renewAfter); + using (IProtocolHead mqttBrokerProtocolHead = await GetMqttBrokerProtocolHeadAsync(experimentalFeatures, container)) + using (IProtocolHead edgeHubProtocolHead = await GetEdgeHubProtocolHeadAsync(logger, configuration, experimentalFeatures, container, hosting)) + using (var renewal = new CertificateRenewal(certificates, logger, maxRenewAfter)) { - logger.LogError($"Error starting protocol heads: {ex.Message}"); + try + { + await Task.WhenAll(mqttBrokerProtocolHead.StartAsync(), configDownloadTask); + await edgeHubProtocolHead.StartAsync(); + await Task.WhenAny(cts.Token.WhenCanceled(), renewal.Token.WhenCanceled(), configUpdaterStartupFailed.Task); + } + catch (Exception ex) + { + logger.LogError($"Error starting protocol heads: {ex.Message}"); + } + + logger.LogInformation("Stopping the protocol heads..."); + await Task.WhenAll(mqttBrokerProtocolHead.CloseAsync(CancellationToken.None), edgeHubProtocolHead.CloseAsync(CancellationToken.None)); + logger.LogInformation("Protocol heads stopped."); + + await CloseDbStoreProviderAsync(container); } - logger.LogInformation("Stopping the protocol heads..."); - await Task.WhenAll(mqttBrokerProtocolHead.CloseAsync(CancellationToken.None), edgeHubProtocolHead.CloseAsync(CancellationToken.None)); - logger.LogInformation("Protocol heads stopped."); - - await CloseDbStoreProviderAsync(container); + completed.Set(); + handler.ForEach(h => GC.KeepAlive(h)); + logger.LogInformation("Shutdown complete."); + } + catch (Exception ex) + { + logger.LogError(ex, "Stopping with exception"); + throw; } - completed.Set(); - handler.ForEach(h => GC.KeepAlive(h)); - logger.LogInformation("Shutdown complete."); return 0; } diff --git a/edge-util/src/Microsoft.Azure.Devices.Edge.Util/CertificateHelper.cs b/edge-util/src/Microsoft.Azure.Devices.Edge.Util/CertificateHelper.cs index 0b861e5c155..7023e0ebf57 100644 --- a/edge-util/src/Microsoft.Azure.Devices.Edge.Util/CertificateHelper.cs +++ b/edge-util/src/Microsoft.Azure.Devices.Edge.Util/CertificateHelper.cs @@ -247,7 +247,7 @@ public static IEnumerable GetCertificatesFromPem(IEnumerable new X509Certificate2(c)) .ToList(); - public static async Task<(X509Certificate2 ServerCertificate, IEnumerable CertificateChain)> GetServerCertificatesFromEdgelet(Uri workloadUri, string workloadApiVersion, string workloadClientApiVersion, string moduleId, string moduleGenerationId, string edgeHubHostname, DateTime expiration) + public static async Task<(X509Certificate2 ServerCertificate, IEnumerable CertificateChain)> GetServerCertificatesFromEdgelet(Uri workloadUri, string workloadApiVersion, string workloadClientApiVersion, string moduleId, string moduleGenerationId, string edgeHubHostname, DateTime expiration, ILogger logger) { if (string.IsNullOrEmpty(edgeHubHostname)) { @@ -255,7 +255,7 @@ public static IEnumerable GetCertificatesFromPem(IEnumerable> GetTrustBundleFromEdgelet(Uri workloadUri, string workloadApiVersion, string workloadClientApiVersion, string moduleId, string moduleGenerationId) @@ -292,7 +292,7 @@ public static bool VerifyManifestTrustBunldeCertificateChaining(X509Certificate2 return chain.Build(signerCertificate); } - public static (X509Certificate2 ServerCertificate, IEnumerable CertificateChain) GetServerCertificateAndChainFromFile(string serverWithChainFilePath, string serverPrivateKeyFilePath) + public static (X509Certificate2 ServerCertificate, IEnumerable CertificateChain) GetServerCertificateAndChainFromFile(string serverWithChainFilePath, string serverPrivateKeyFilePath, ILogger logger = null) { string cert, privateKey; @@ -316,7 +316,7 @@ public static (X509Certificate2 ServerCertificate, IEnumerable privateKey = sr.ReadToEnd(); } - return ParseCertificateAndKey(cert, privateKey); + return ParseCertificateAndKey(cert, privateKey, logger); } public static IEnumerable GetServerCACertificatesFromFile(string chainPath) @@ -371,10 +371,10 @@ internal static X509Certificate2 ParseManifestTrustedBundleCerts(string manifest return GetCertificatesFromPem(ParsePemCerts(manifestTrustedCACerts)).FirstOrDefault(); } - internal static (X509Certificate2, IEnumerable) ParseCertificateResponse(ServerCertificateResponse response) => - ParseCertificateAndKey(response.Certificate, response.PrivateKey); + internal static (X509Certificate2, IEnumerable) ParseCertificateResponse(ServerCertificateResponse response, ILogger logger = null) => + ParseCertificateAndKey(response.Certificate, response.PrivateKey, logger); - internal static (X509Certificate2, IEnumerable) ParseCertificateAndKey(string certificateWithChain, string privateKey) + internal static (X509Certificate2, IEnumerable) ParseCertificateAndKey(string certificateWithChain, string privateKey, ILogger logger = null) { IEnumerable pemCerts = ParsePemCerts(certificateWithChain); @@ -386,7 +386,7 @@ internal static (X509Certificate2, IEnumerable) ParseCertifica IEnumerable certsChain = GetCertificatesFromPem(pemCerts.Skip(1)); var certWithNoKey = new X509Certificate2(Encoding.UTF8.GetBytes(pemCerts.First())); - var certWithPrivateKey = AttachPrivateKey(certWithNoKey, privateKey); + var certWithPrivateKey = AttachPrivateKey(certWithNoKey, privateKey, logger); return (certWithPrivateKey, certsChain); } @@ -418,7 +418,7 @@ static Option GetCommonNameFromSubject(string subject) return commonName; } - static X509Certificate2 AttachPrivateKey(X509Certificate2 certificate, string pemEncodedKey) + static X509Certificate2 AttachPrivateKey(X509Certificate2 certificate, string pemEncodedKey, ILogger logger) { var pkcs8Label = "PRIVATE KEY"; var rsaLabel = "RSA PRIVATE KEY"; @@ -432,6 +432,8 @@ static X509Certificate2 AttachPrivateKey(X509Certificate2 certificate, string pe { if (oidRsaEncryption.Value == keyAlgorithm) { + logger?.LogDebug("Importing RSA private key"); + var decodedKey = UnwrapPrivateKey(pemEncodedKey, isPkcs8 ? pkcs8Label : rsaLabel); var key = RSA.Create(); @@ -445,9 +447,13 @@ static X509Certificate2 AttachPrivateKey(X509Certificate2 certificate, string pe } result = certificate.CopyWithPrivateKey(key); + + logger?.LogDebug("RSA private key has been imported and assigned to certificate"); } else if (oidEcPublicKey.Value == keyAlgorithm) { + logger?.LogDebug("Importing ECC private key"); + var decodedKey = UnwrapPrivateKey(pemEncodedKey, isPkcs8 ? pkcs8Label : ecLabel); var key = ECDsa.Create(); @@ -461,16 +467,22 @@ static X509Certificate2 AttachPrivateKey(X509Certificate2 certificate, string pe } result = certificate.CopyWithPrivateKey(key); + + logger?.LogDebug("ECC private key has been imported and assigned to certificate"); } } catch (Exception ex) { - throw new InvalidOperationException("Cannot import private key", ex); + var errorMessage = "Cannot import private key"; + logger?.LogError(ex, errorMessage); + throw new InvalidOperationException(errorMessage, ex); } if (result == null) { - throw new InvalidOperationException($"Cannot use certificate, not supported key algorithm: ${keyAlgorithm}"); + var errorMessage = $"Cannot use certificate, not supported key algorithm: ${keyAlgorithm}"; + logger?.LogError(errorMessage); + throw new InvalidOperationException(errorMessage); } return result;