Azure / Azure/iotedge

Setting AuthenticationMode to Cloud fails on mcr.microsoft.com/azureiotedge-hub:1.2

Open
#6,284 13 comments 0 reactions 1 assignee Claimed by @nyanzebra View on GitHub
customer-reported iotedge no-issue-activity
Dominant language
C#
Stars
1.5k
Forks
473
Avg merge
2d 17h
Merged PRs (30d)
7

Description

## Expected Behavior
When using the URI mcr.microsoft.com/azureiotedge-hub:1.1, I can set the AuthenticationMode to Cloud with no issue.

When I use mcr.microsoft.com/azureiotedge-hub:1.2, I get the error:
```
System.InvalidOperationException: Could not obtain twin neither from local store nor from cloud. This happens when there is no upstream connection and this is the first EdgeHub startup, or there is no persistent store to save a previous twin configuration. EdgeHub cannot start without basic configuration stored in twin. Stopping now.
```

## Current Behavior
When I use mcr.microsoft.com/azureiotedge-hub:1.2, I get the error:
```
System.InvalidOperationException: Could not obtain twin neither from local store nor from cloud. This happens when there is no upstream connection and this is the first EdgeHub startup, or there is no persistent store to save a previous twin configuration. EdgeHub cannot start without basic configuration stored in twin. Stopping now.
```

## Steps to Reproduce
Provide a detailed set of steps to reproduce the bug.
1. Deploy IoT Edge 1.2 using the URI mcr.microsoft.com/azureiotedge-hub:1.1
2. On EdgeHub set the environment variable AuthenticationMode to Cloud
3. Note it behaves as expected
4. Change the URI of edgeHub to mcr.microsoft.com/azureiotedge-hub:1.2 and watch it fail

## Context (Environment)

### Output of `iotedge check`

Click here

```
iotedge check

Configuration checks (aziot-identity-service)
---------------------------------------------
√ keyd configuration is well-formed - OK
√ certd configuration is well-formed - OK
√ tpmd configuration is well-formed - OK
√ identityd configuration is well-formed - OK
√ daemon configurations up-to-date with config.toml - OK
× identityd config toml file specifies a valid hostname - Error
identityd config has hostname edgehubha.saye.org but device reports hostname host2.
Hostname in identityd config must either be identical to the device hostname or be a fully-qualified domain name that has the device hostname as the first component.
√ aziot-identity-service package is up-to-date - OK
√ host time is close to reference time - OK
√ preloaded certificates are valid - OK
√ keyd is running - OK
√ certd is running - OK
√ identityd is running - OK
√ read all preloaded certificates from the Certificates Service - OK
√ read all preloaded key pairs from the Keys Service - OK
√ ensure all preloaded certificates match preloaded private keys with the same ID - OK

Connectivity checks (aziot-identity-service)
--------------------------------------------
√ host can connect to and perform TLS handshake with iothub AMQP port - OK
√ host can connect to and perform TLS handshake with iothub HTTPS / WebSockets port - OK
√ host can connect to and perform TLS handshake with iothub MQTT port - OK

Configuration checks
--------------------
√ aziot-edged configuration is well-formed - OK
√ configuration up-to-date with config.toml - OK
√ container engine is installed and functional - OK
√ configuration has correct URIs for daemon mgmt endpoint - OK
√ aziot-edge package is up-to-date - OK
√ container time is close to host time - OK
‼ DNS server - Warning
Container engine is not configured with DNS server setting, which may impact connectivity to IoT Hub.
Please see https://aka.ms/iotedge-prod-checklist-dns for best practices.
You can ignore this warning if you are setting DNS server per module in the Edge deployment.
‼ production readiness: logs policy - Warning
Container engine is not configured to rotate module logs which may cause it run out of disk space.
Please see https://aka.ms/iotedge-prod-checklist-logs for best practices.
You can ignore this warning if you are setting log policy per module in the Edge deployment.
‼ production readiness: Edge Agent's storage directory is persisted on the host filesystem - Warning
The edgeAgent module is not configured to persist its /tmp/edgeAgent directory on the host filesystem.
Data might be lost if the module is deleted or updated.
Please see https://aka.ms/iotedge-storage-host for best practices.
‼ production readiness: Edge Hub's storage directory is persisted on the host filesystem - Warning
The edgeHub module is not configured to persist its /tmp/edgeHub directory on the host filesystem.
Data might be lost if the module is deleted or updated.
Please see https://aka.ms/iotedge-storage-host for best practices.
√ Agent image is valid and can be pulled from upstream - OK
√ proxy settings are consistent in aziot-edged, aziot-identityd, moby daemon and config.toml - OK

Connectivity checks
-------------------
√ container on the default network can connect to upstream AMQP port - OK
√ container on the default network can connect to upstream HTTPS / WebSockets port - OK
√ container on the default network can connect to upstream MQTT port - OK
√ container on the IoT Edge module network can connect to upstream AMQP port - OK
√ container on the IoT Edge module network can connect to upstream HTTPS / WebSockets port - OK
√ container on the IoT Edge module network can connect to upstream MQTT port - OK
31 check(s) succeeded.
4 check(s) raised warnings. Re-run with --verbose for more details.
1 check(s) raised errors. Re-run with --verbose for more details.
```

### Device Information
* Host OS [e.g. Ubuntu 18.04, Windows Server IoT 2019]: Ubuntu 18.04
* Architecture [e.g. amd64, arm32, arm64]: amd64
* Container OS [e.g. Linux containers, Windows containers]: Linux

### Runtime Versions
* aziot-edged [run `iotedge version`]: 1.2.9
* Edge Agent [image tag (e.g. 1.0.0)]: 1.2
* Edge Hub [image tag (e.g. 1.0.0)]: 1.2
* Docker/Moby [run `docker version`]: 20.10.14+azure-1

Note: when using Windows containers on Windows, run `docker -H npipe:////./pipe/iotedge_moby_engine version` instead

## Logs

aziot-edged logs

```

```

edge-agent logs

```

```

edge-hub logs

```
root@host1:~# docker logs -f edgeHub
2022-04-12 21:21:59 Starting Edge Hub
Apr 12 21:21:59.332 INFO watchdog: Starting Watchdog
Apr 12 21:21:59.332 INFO watchdog: Registering shutdown signal listener
Apr 12 21:21:59.332 INFO watchdog: MQTT broker is disabled
Apr 12 21:21:59.339 INFO watchdog::child: Launched Edge Hub process with pid 9
2022-04-12 21:21:59.402 +00:00 Edge Hub Main()
<6> 2022-04-12 21:22:00.168 +00:00 [INF] - Installing certificates [CN=IoT Edge Root CA Host1:10/09/2022 17:22:39],[CN=Issuing CA for IoT Edge:10/09/2022 17:22:39],[CN=Root CA for IoT Edge:04/09/2032 17:22:38] to Root
<6> 2022-04-12 21:22:00.215 +00:00 [INF] - Installing certificates [CN=IoT Edge Root CA Host1:10/09/2022 17:22:39],[CN=Issuing CA for IoT Edge:10/09/2022 17:22:39],[CN=Root CA for IoT Edge:04/09/2032 17:22:38] to Root
<6> 2022-04-12 21:22:00.227 +00:00 [INF] - Enabling SSL protocols: Tls, Tls11, Tls12
<6> 2022-04-12 21:22:00.343 +00:00 [INF] - Experimental features configuration: {"Enabled":false,"DisableCloudSubscriptions":false,"DisableConnectivityCheck":false,"EnableMqttBroker":false}
<6> 2022-04-12 21:22:00.460 +00:00 [INF] - Initializing Edge Hub
<6> 2022-04-12 21:22:00.460 +00:00 [INF] -
█████╗ ███████╗██╗ ██╗██████╗ ███████╗
██╔══██╗╚══███╔╝██║ ██║██╔══██╗██╔════╝
███████║ ███╔╝ ██║ ██║██████╔╝█████╗
██╔══██║ ███╔╝ ██║ ██║██╔══██╗██╔══╝
██║ ██║███████╗╚██████╔╝██║ ██║███████╗
╚═╝ ╚═╝╚══════╝ ╚═════╝ ╚═╝ ╚═╝╚══════╝

██╗ ██████╗ ████████╗ ███████╗██████╗ ██████╗ ███████╗
██║██╔═══██╗╚══██╔══╝ ██╔════╝██╔══██╗██╔════╝ ██╔════╝
██║██║ ██║ ██║ █████╗ ██║ ██║██║ ███╗█████╗
██║██║ ██║ ██║ ██╔══╝ ██║ ██║██║ ██║██╔══╝
██║╚██████╔╝ ██║ ███████╗██████╔╝╚██████╔╝███████╗
╚═╝ ╚═════╝ ╚═╝ ╚══════╝╚═════╝ ╚═════╝ ╚══════╝

<6> 2022-04-12 21:22:00.462 +00:00 [INF] - Version - 1.2.9.53764592 (4bbfdb99cf7afb16f23d6177865942cc22e197ce)
<6> 2022-04-12 21:22:00.462 +00:00 [INF] - OptimizeForPerformance=True
<6> 2022-04-12 21:22:00.462 +00:00 [INF] - MessageAckTimeoutSecs=30
<6> 2022-04-12 21:22:00.464 +00:00 [INF] - Loaded server certificate with expiration date of "2022-05-12T21:22:00.0000000+00:00"
<6> 2022-04-12 21:22:00.470 +00:00 [INF] - Using Asp Net server for metrics
<6> 2022-04-12 21:22:01.610 +00:00 [INF] - Created persistent store at /tmp/edgeHub
<6> 2022-04-12 21:22:01.642 +00:00 [INF] - Started task to cleanup processed and stale messages
<6> 2022-04-12 21:22:01.647 +00:00 [INF] - Created new message store
<6> 2022-04-12 21:22:01.699 +00:00 [INF] - Created DeviceConnectivityManager with connected check frequency 00:05:00 and disconnected check frequency 00:02:00
<6> 2022-04-12 21:22:02.046 +00:00 [INF] - Initialized storing twin manager
<6> 2022-04-12 21:22:02.065 +00:00 [INF] - Add node: host1/$edgeHub
<6> 2022-04-12 21:22:02.066 +00:00 [INF] - Initializing configuration
<6> 2022-04-12 21:22:02.090 +00:00 [INF] - New device connection for device host1/$edgeHub
<6> 2022-04-12 21:22:02.100 +00:00 [INF] - Client host1/$edgeHub connected to edgeHub, processing existing subscriptions.
<4> 2022-04-12 21:22:02.115 +00:00 [WRN] - Error creating cloud connection for client host1/$edgeHub
System.InvalidOperationException: No auth chain for the client identity: host1/$edgeHub
at Microsoft.Azure.Devices.Edge.Util.Option`1.Expect[TException](Func`1 exception) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/Option.cs:line 117
at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnectionProvider.ConnectInternal(IIdentity identity, Action`2 connectionStatusChangedHandler) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudConnectionProvider.cs:line 183
<6> 2022-04-12 21:22:02.133 +00:00 [INF] - Error getting cloud connection for device host1/$edgeHub
System.InvalidOperationException: No auth chain for the client identity: host1/$edgeHub
at Microsoft.Azure.Devices.Edge.Util.Option`1.Expect[TException](Func`1 exception) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/Option.cs:line 117
at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnectionProvider.ConnectInternal(IIdentity identity, Action`2 connectionStatusChangedHandler) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudConnectionProvider.cs:line 183
<6> 2022-04-12 21:22:02.148 +00:00 [INF] - Processing pending subscriptions for host1/$edgeHub
<4> 2022-04-12 21:22:02.149 +00:00 [WRN] - Error creating cloud connection for client host1/$edgeHub
System.InvalidOperationException: No auth chain for the client identity: host1/$edgeHub
at Microsoft.Azure.Devices.Edge.Util.Option`1.Expect[TException](Func`1 exception) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/Option.cs:line 117
at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnectionProvider.ConnectInternal(IIdentity identity, Action`2 connectionStatusChangedHandler) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudConnectionProvider.cs:line 183
<6> 2022-04-12 21:22:02.151 +00:00 [INF] - Error getting cloud connection for device host1/$edgeHub
System.InvalidOperationException: No auth chain for the client identity: host1/$edgeHub
at Microsoft.Azure.Devices.Edge.Util.Option`1.Expect[TException](Func`1 exception) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/Option.cs:line 117
at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnectionProvider.ConnectInternal(IIdentity identity, Action`2 connectionStatusChangedHandler) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudConnectionProvider.cs:line 183
<6> 2022-04-12 21:22:02.153 +00:00 [INF] - Processing pending subscriptions for host1/$edgeHub, but no cloud proxy was found
<6> 2022-04-12 21:22:02.216 +00:00 [INF] - Processing pending subscriptions for host1/$edgeHub
<6> 2022-04-12 21:22:02.458 +00:00 [INF] - Experimental features configuration: {"Enabled":false,"DisableCloudSubscriptions":false,"DisableConnectivityCheck":false,"EnableMqttBroker":false}
<4> 2022-04-12 21:22:02.519 +00:00 [WRN] - Empty edge hub configuration received. Ignoring...
<4> 2022-04-12 21:22:02.524 +00:00 [WRN] - Error creating cloud connection for client host1/$edgeHub
System.InvalidOperationException: No auth chain for the client identity: host1/$edgeHub
at Microsoft.Azure.Devices.Edge.Util.Option`1.Expect[TException](Func`1 exception) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/Option.cs:line 117
at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnectionProvider.ConnectInternal(IIdentity identity, Action`2 connectionStatusChangedHandler) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudConnectionProvider.cs:line 183
<6> 2022-04-12 21:22:02.525 +00:00 [INF] - Error getting cloud connection for device host1/$edgeHub
System.InvalidOperationException: No auth chain for the client identity: host1/$edgeHub
at Microsoft.Azure.Devices.Edge.Util.Option`1.Expect[TException](Func`1 exception) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/Option.cs:line 117
at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnectionProvider.ConnectInternal(IIdentity identity, Action`2 connectionStatusChangedHandler) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudConnectionProvider.cs:line 183
<6> 2022-04-12 21:22:02.765 +00:00 [INF] - Scheduling server certificate renewal for "2022-05-12T21:19:30.0000782Z".
<3> 2022-04-12 21:22:02.777 +00:00 [ERR] - Error getting edge hub config from twin desired properties
Microsoft.Azure.Devices.Edge.Util.InvalidSchemaVersionException: EdgeHub config missing SchemaVersion
at Microsoft.Azure.Devices.Edge.Hub.Core.Config.EdgeHubConfigParser.GetEdgeHubConfig(String twinJson) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/config/EdgeHubConfigParser.cs:line 83
at Microsoft.Azure.Devices.Edge.Hub.Core.Config.TwinConfigSource.GetConfigInternal() in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/config/TwinConfigSource.cs:line 102
at Microsoft.Azure.Devices.Edge.Hub.Core.Config.TwinConfigSource.GetConfigInternal() in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/config/TwinConfigSource.cs:line 109
<4> 2022-04-12 21:22:02.779 +00:00 [WRN] - Empty edge hub configuration received. Ignoring...
<3> 2022-04-12 21:22:02.780 +00:00 [ERR] - Error initializing edge hub configuration
System.InvalidOperationException: Could not obtain twin neither from local store nor from cloud. This happens when there is no upstream connection and this is the first EdgeHub startup, or there is no persistent store to save a previous twin configuration. EdgeHub cannot start without basic configuration stored in twin. Stopping now.
at Microsoft.Azure.Devices.Edge.Hub.Core.Config.ConfigUpdater.<>c.b__9_6() in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/config/ConfigUpdater.cs:line 67
at Microsoft.Azure.Devices.Edge.Util.Option`1.Expect[TException](Func`1 exception) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/Option.cs:line 117
at Microsoft.Azure.Devices.Edge.Hub.Core.Config.ConfigUpdater.<>c__DisplayClass9_0.<b__4>d.MoveNext() in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/config/ConfigUpdater.cs:line 73
--- End of stack trace from previous location where exception was thrown ---
at Microsoft.Azure.Devices.Edge.Hub.Core.Config.ConfigUpdater.Init(IConfigSource configProvider) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/config/ConfigUpdater.cs:line 56
<3> 2022-04-12 21:22:02.781 +00:00 [ERR] - Error starting protocol heads: Could not obtain twin neither from local store nor from cloud. This happens when there is no upstream connection and this is the first EdgeHub startup, or there is no persistent store to save a previous twin configuration. EdgeHub cannot start without basic configuration stored in twin. Stopping now.
<6> 2022-04-12 21:22:02.781 +00:00 [INF] - Stopping the protocol heads...
<6> 2022-04-12 21:22:02.782 +00:00 [INF] - Closing protocol heads - (MQTT, AMQP, HTTP)
<6> 2022-04-12 21:22:02.784 +00:00 [INF] - Stopping MQTT protocol head
<6> 2022-04-12 21:22:02.785 +00:00 [INF] - Stopped MQTT protocol head
<6> 2022-04-12 21:22:02.789 +00:00 [INF] - Closing HTTP head
<6> 2022-04-12 21:22:02.790 +00:00 [INF] - Closed HTTP head
<6> 2022-04-12 21:22:02.790 +00:00 [INF] - Protocol heads stopped.
<6> 2022-04-12 21:22:02.799 +00:00 [INF] - Shutdown complete.
<6> 2022-04-12 21:22:02.800 +00:00 [INF] - Termination requested, initiating shutdown.
<6> 2022-04-12 21:22:02.800 +00:00 [INF] - Waiting for cleanup to finish
<6> 2022-04-12 21:22:02.800 +00:00 [INF] - Done with cleanup. Shutting down.
Apr 12 21:22:03.340 INFO watchdog::child: Edge Hub process has stopped
Apr 12 21:22:03.340 INFO watchdog: Successfully stopped Edge Hub process
Apr 12 21:22:03.340 INFO watchdog: Stopped Watchdog process
```

## Additional Information
Please provide any additional information that may be helpful in understanding the issue.

Contributor guide

No contributing guide indexed for this repository

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.