ValOlson
commented
3 years ago - @micahl
Open mlilien opened 3 years ago
ValOlson
commented
3 years ago 
varunpuranik
commented
3 years ago Hi @mlilien -
We don't currently support module identities on leaf (non-edge) devices. We will work on fixing this limitation, but I don't have a timeline yet on that yet.
Here are answers to your questions above: Re #1: Module identities are not provisioned automatically by IoT Hub, but you can use the device credentials to provision modules on the device. Are you creating the module identities on the device explicitly, using the device credentials? The log error you see is because the issue I mentioned above. Once that is fixed, the error should go away.
Re #2: EdgeHub does support a Registry API which allows downstream devices to create module identities, but currently it works only for IoT Edge devices. So you won't be able to create module identities for your leaf IoT Edge device via EdgeHub, yet.
Re #3: I am not sure what you mean here... one application uses device identity and is able to connect properly. Other application is not provisioned, and not able to connect (which seems expected). Am I missing something?
Hope this clarifies your questions.
mlilien
commented
3 years ago Hi @varunpuranik thank you for the clarification.
1) The module identities get created implicitly via iot-identity-service configuration.
2) That means explicitly iotedge modules, right? The module has to run in the container runtime then?
3) I meant that it is possible to provision via device identity behind a gateway, but not as module and also not if there is a mixed configuration with device and module identity. Your answer that there currently is no support for module identites on leaf (non-edge) devices confirmes my oberservation.
github-actions[bot]
commented
3 years ago This issue is being marked as stale because it has been open for 30 days with no activity.
JanZachmann
commented
3 years ago Hi @huguesBouvier
Since my colleague @mlilien is on holidays for another 2 weeks I try to give some feedback on your fix. From my understanding the fix focuses on the 1st scenario described by @mlilien with the corresponding logs: "suspicious edgehub logs".
The use case we are struggling with is scenario 2.) where two module identities on a leaf device (non-edge iot device) behind an edge gateway are not provisioned due to permission errors. After testing with a local build of the fixed edgehub module on our side this setup is still not running with the same logs already provided in the issue: "edgeHub logs scenario 2 - two module identities - unauthorized".
So my question is if the fix was supposed to fix 2nd scenario as well from your side?
huguesBouvier
commented
3 years ago Hi @JanZachmann,
This also should fix scenario 2. I was able to create a module trough edgeHub. This is the code I used in C#:
string connectionString = "HostName=xxx;DeviceId=leaf;SharedAccessKey=xxxx;GatewayHostname=xxxx";
string deviceName = "leaf";
var transportSettings = new AmqpTransportSettings(Microsoft.Azure.Devices.Client.TransportType.Amqp_Tcp_Only);
transportSettings.RemoteCertificateValidationCallback = (sender, certificate, chain, sslPolicyErrors) => { return true; };
transportSettings.OpenTimeout = TimeSpan.FromMinutes(60);
transportSettings.OperationTimeout = TimeSpan.FromMinutes(60);
transportSettings.IdleTimeout = TimeSpan.FromMinutes(60);
Console.WriteLine("Opening upstream connection...");
Console.Write(connectionString);
var client = DeviceClient.CreateFromConnectionString(connectionString, new[] { transportSettings });
Console.Write("Module Name: ");
string moduleName = Console.ReadLine();
await AddModuleAsync(connectionString, deviceName, moduleName);I was able to establish a connection through edgeHub and create a new module with this code. You are using IS to get the key but aside from that the process should be similar.
Could you please give me more details/code on what you are doing in #2?
JanZachmann
commented
3 years ago @huguesBouvier Thanks for your feedback!
Our setup on the leaf device is as follows:
What we tested today:
The following questions come to my mind:
huguesBouvier
commented
3 years ago Hello!
I think I understand the confusion. There are 2 connection strings:
The main connection string is the device connection string. This is what you will use to create new module. This connection string, you have to provision yourself:
Then you have the modules connection string:
Those you can create from your leaf using the device connection string.
This is how I was able to create new modules. The device connection string is used to authenticate.
Whether you use IS or connection string directly like I did is the same. IS is used as a mean to safely store connection string. You get back the connection string by doing first: GET /identities/identity?api-version=2020-09-01 Then use the key handle to generate a token and access iotHub (through edgeHub) to create new modules.
What the C# is doing is identical. It uses the Device Connection string to generate a token and access IoTHub.
JanZachmann
commented
3 years ago Thanks for explaining details regarding module creation.
Since we got leaf device modules working with connection string but not with IS we're pretty sure it must be sth. releated to the eis_utils of ADU: https://github.com/Azure/iot-hub-device-update/tree/main/src/utils/eis_utils
That's what I meant in my last comment when I asked if you can confirm that the adu agent was ever successfully running as module identity on a leaf device?
ValOlson
commented
3 years ago @JanZachmann I am adding members of the Device Update team here to verify if there is a reason eis_utils of ADU: https://github.com/Azure/iot-hub-device-update/tree/main/src/utils/eis_utils causing leaf modules not to connect for the AduIotAgent as module using the IoT Identity service. It should have just worked if it works with the connection string and the fix that @varunpuranik added to IoT Identity service.
huguesBouvier
commented
3 years ago "That's what I meant in my last comment when I asked if you can confirm that the adu agent was ever successfully running as module identity on a leaf device?" Not to my knowledge but I didn't work much with ADU, I see you added the ADU team. They would be ale to provide an answer, let's have them confirm first.
huguesBouvier
commented
3 years ago Should I close the ticket for now? Let's re-open it if there is a follow up.
JanZachmann
commented
3 years ago Please don't close yet. Next week @mlilien is back from holydays. Since he is the initiator of the issue and he is testing the setup with our yocto linux distribution (I just used ubuntu), I would like to wait for his analysis and feedback first.
@ValOlson Do you think you ADU guys could provide some feedback on testing our setup on your side next week?
huguesBouvier
commented
3 years ago Ok! I will be also on vacation next week, maybe someone else from the team will pick it up but otherwise it possible you'll get answers only when I get back
mlilien
commented
3 years ago Hi, I build the edge-hub 1.2.4 from release/1.2 branch for target aarch64.
I can verify that in case 1 I don't see the suspicious log entries in edge-Hub anymore. For case 2 I can not verify that it works.
Could you please give me more details/code on what you are doing in #2?
Basically the same as in case 1. The difference is that the leaf device never was connected directly to iothub before. I have an iot device with iot-identity-service and two applications configured with module identity behind an edge-gw. The authentication type is SaS.
What also doesnt work and is a simpler setup: An iot device with iot-identity-service and iothub-device-update configured as module identity behind an edge-gw. The authentication type is SaS.
huguesBouvier
commented
3 years ago The patch made for edgeHub now allows module identity to be created from leaf devices, even when never connected directly to iotHub. So case 2 should work. I tested case2 (create module identity while never connecting directly to iothub) with the C# SDK and by creating my own project.
If it still doesn't work, then there is probably an issue with how the tokens are generated, let's explore that. Did you get answers from ADU team? Otherwise, let's generate a token differently (with a script or C#) to isolate the issue.
mlilien
commented
3 years ago Hi Hugues,
I did not get any answers from ADU team yet.
I understand that you did not test a scenario with iotedge 1.2 and a leaf device which uses iot-identity-service with a module identity yet.
Can you please test such a szenario? Here are logs from iot-identity-service on our leaf client.
Both module applications are not running at time of this log. The log is captured after aziotctl config apply.
I tested case2 (create module identity while never connecting directly to iothub) with the C# SDK and by creating my own project.
Can you verify that iot-identity-service is supposed to do that in our described scenario?
Otherwise, let's generate a token differently (with a script or C#) to isolate the issue.
Is there an existing script/application which I can use for that?
huguesBouvier
commented
3 years ago Hi!
You're right, I didn't use IS but it doesn't matter, IS is just safe keeping the secret key. In using C# I just put the key directly in plain text using in the code (see the xxx below). The important part is the API call to edgeHub and that API call is identical. That's what I meant by "If it still doesn't work, then there is probably an issue with how the tokens are generated" The token is probably wrong, that's why it is not getting recognized by edgeHub.
Is there some piece of code that you can share, in how you use IS to generate token?
This is the code I used:
string connectionString = "HostName=xxxxx;DeviceId=leaf;SharedAccessKey=xxxxx;GatewayHostname=20.51.236.46";
string deviceName = "leaf";
var transportSettings = new AmqpTransportSettings(Microsoft.Azure.Devices.Client.TransportType.Amqp_Tcp_Only);
transportSettings.RemoteCertificateValidationCallback = (sender, certificate, chain, sslPolicyErrors) => { return true; };
transportSettings.OpenTimeout = TimeSpan.FromMinutes(60);
transportSettings.OperationTimeout = TimeSpan.FromMinutes(60);
transportSettings.IdleTimeout = TimeSpan.FromMinutes(60);
Console.WriteLine("Opening upstream connection...");
Console.Write(connectionString);
var client = DeviceClient.CreateFromConnectionString(connectionString, new[] { transportSettings });
client.SetConnectionStatusChangesHandler(ConnectionStatusChangedCallback);
await client.OpenAsync();
await client.SetMethodDefaultHandlerAsync(DirectMethodHandler, null);
await client.SetDesiredPropertyUpdateCallbackAsync(DesiredPropertyhandler, null);
Console.Write("Module Name: ");
string moduleName = Console.ReadLine();
string input = string.Empty;
await AddModuleAsync(connectionString, deviceName, moduleName);static async Task AddModuleAsync(string connectionString, string deviceName, string moduleName)
{
RegistryManager registryManager =
RegistryManager.CreateFromConnectionString(connectionString);
Microsoft.Azure.Devices.Module module;
try
{
module =
await registryManager.AddModuleAsync(new Microsoft.Azure.Devices.Module(deviceName, moduleName));
}
catch (ModuleAlreadyExistsException)
{
module = await registryManager.GetModuleAsync(deviceName, moduleName);
}
Console.WriteLine("Generated module key: {0}", module.Authentication.SymmetricKey.PrimaryKey);
}I'll test with IS. I'll post the code when I am done.
ValOlson
commented
3 years ago @JanZachmann / @huguesBouvier: Can you confirm if you have the ADU agent working on the downstream device? ADU use IS to retrieve or create the provisioning information for the agents connection to the IOT Hub, so if you are not using IS then did you manually update ADU's config.txt file with the connection string? Is there open question do you have for the ADU team?
JanZachmann
commented
3 years ago @ValOlson Yes I can confirm that our downstream/leaf device has ADU running as module identity using IS. This causes the same misbehaviour as described by @mlilien and what we also see with other module identities behind a gateway. We would now wait for @huguesBouvier to come back with some test results.
huguesBouvier
commented
3 years ago I am going to try with IS tomorrow. I'll let you know the result.
huguesBouvier
commented
3 years ago Hey!
So some results from the test. It looks like you are right, the SDK seems to be ignoring the gateway parameter and connecting to IoT Hub. This is the script I used:
# Call IS as the root user to skip the need to add my user to the requisite security groups for IS/KS/CS.
identity="$(sudo curl --unix-socket '/run/aziot/identityd.sock' 'http://identityd.sock/identities/identity?api-version=2020-09-01')"
# From the response, retrieve the hubName, gatewayHost, device and module identity, authentication type, and the key handle.
hub_name="$(<<< "$identity" jq -r '.spec.hubName')"
gateway_host="$(<<< "$identity" jq -r '.spec.gatewayHost')"
device_id="$(<<< "$identity" jq -r '.spec.deviceId')"
module_id="$(<<< "$identity" jq -r '.spec.moduleId // ""')"
auth_type="$(<<< "$identity" jq -r '.spec.auth.type')"
key_handle="$(<<< "$identity" jq -r '.spec.auth.keyHandle')"
module_id="mymodule"
# URL-encode the resource of hub + device + module
# If we were doing this for the device identity, the resource_uri wouldn't include the '/modules/%s'
resource_uri="$(printf '%s/devices/%s' "$hub_name" "$device_id" | jq -sRr @uri)"
# Expiry of 1 day from today in Unix epoch time
expiry="$(bc <<< "$(date +%s) + 60 * 60 * 24")"
# Full string to be signed is a base64-encoded string containing the URL-encoded resource URI and the expiry
signature_data="$(printf '%s\n%s' "$resource_uri" "$expiry" | base64 -w 0)"
# Parse and URL-decode the 'signature' from the response
signature="$(
sudo curl --unix-socket '/run/aziot/keyd.sock' \
-X POST -H 'content-type: application/json' --data-raw "$(
jq -cn --arg 'keyHandle' "$key_handle" --arg 'message' "$signature_data" '{
"keyHandle": $keyHandle,
"algorithm": "HMAC-SHA256",
"parameters": {
"message": $message,
},
}'
)" 'http://keyd.sock/sign?api-version=2020-09-01' |
jq '.signature' -r |
sed -e 's|+|%2b|g' -e 's|/|%2f|g' -e 's|=|%3d|g'
)"
# Construct the full SaS token
sas_token="$(printf 'sr=%s&se=%s&sig=%s' "$resource_uri" "$expiry" "$signature")"
# Note that the 'SharedAccessSignature' appears both in the connection string and in the value for it.
sas="SharedAccessSignature $sas_token"
body="{'moduleId':'${module_id}',"deviceId":'${device_id}'}"
echo "$(curl -v --insecure --request PUT --url "https://10.1.0.5/devices/${device_id}/modules/${module_id}?api-version=2017-11-08-preview" --header "Connection: close" --header "Host: edgehub" --header "Content-Type: application/json" --header "Authorization: $sas" -d "${body}")"
echo ${device_id}
body="{'moduleId':'${module_id}','deviceId':'${device_id}','authentication':{'symmetricKey':{'primaryKey':'xxxx','secondaryKey':'xxxxx'},'type':'sas'}}"
echo "$(curl -v --insecure --request PUT --url "https://10.1.0.5/devices/${device_id}/modules/${module_id}?api-version=2017-11-08-preview" --header "Connection: close" --header "Host: edgehub" --header "Content-Type: application/json" --header "if-match: *" --header "Authorization: $sas" -d "${body}")"
And the result I got was the edgeHub is ok with the token, but actually iothub is not:
Request starting HTTP/1.1 PUT https://edgehub/devices/leaf/modules/mymodule?api-version=2017-11-08-preview application/json 212
Executing endpoint '"Microsoft.Azure.Devices.Edge.Hub.Http.Controllers.RegistryController.CreateOrUpdateModuleAsync (Microsoft.Azure.Devices.Edge.Hub.Http)"'
Route matched with "{action = \"CreateOrUpdateModule\", controller = \"Registry\"}". Executing controller action with signature "System.Threading.Tasks.Task CreateOrUpdateModuleAsync(System.String, System.String, System.String, Microsoft.Azure.Devices.Module)" on controller "Microsoft.Azure.Devices.Edge.Hub.Http.Controllers.RegistryController" ("Microsoft.Azure.Devices.Edge.Hub.Http").
Received request in CreateOrUpdateModuleAsync: deviceId=leaf, moduleId=mymodule
Client leaf in device scope authenticated locally.
Authenticated: deviceId=leaf, moduleId=
CompleteRequest in CreateOrUpdateModuleAsync: deviceId=top-layer, authChain=leaf;top-layer, status=UnauthorizedCan you confirm that you observe the same thing (edgeHub is ok but iotHub return status=unauthorized?)
The "status=Unauthorized" seems to be the response from iotHub. The token is correctly validated by edgeHub though. I tried tampering the token and then edgeHub is unhappy:
Error authenticating token for leaf because the token did not match the primary or the secondary key. Error - The specified SAS token has an invalid signature. It does not match either the primary or secondary key
It looks like iothub doesn't like that edgeHub module on behalf of the leaf. I'll reach out to iotHub and let you know.
huguesBouvier
commented
3 years ago Using Kusto and looking at the IoTHub code we have confirmed that some changes needs to be made on IoTHub side:
I have created a ticket with the IoTHub though I don't have an ETA as to when it will be fixed.
FYI: I also have created a ticket with the IoT SDK team to request support for gateway hostname in the SDK too: https://github.com/Azure/azure-iot-sdk-csharp/issues/2175
JanZachmann
commented
3 years ago Hello @huguesBouvier I guess you don't have news about the state of the IoTHub ticket? Is there a way for us to track that ticket? We don't want to miss the fix (-; @ValOlson do you track the issue as well since ADU also depends on a fix? Regards Jan
huguesBouvier
commented
3 years ago @JanZachmann I can only say we are discussing with them. It might take a while.
shaeussler
commented
2 years ago I think I see the same error when I'm using AMQP in the following command line program with a module identity and no gateway:
./ConsoleApp23 "Amqp_Tcp_Only" "HostName=XXXXXXXXXXXX.azure-devices.net;DeviceId=testdevice;ModuleId=mymodule;SharedAccessSignature=SharedAccessSignature sr=XXXXXXXXXXXX.azure-devices.net%2fdevices%2ftestdevice&se=1639072929&sig=kAkcKWxdFVvm7ulVj8zaEhAhnPLiGaDEoqsRLy6zdnU%3d"
TransportType: Amqp_Tcp_Only
ConnectionString: HostName=XXXXXXXXXXXX.azure-devices.net;DeviceId=testdevice;ModuleId=mymodule;SharedAccessSignature=SharedAccessSignature sr=XXXXXXXXXXXX.azure-devices.net%2fdevices%2ftestdevice&se=1639072929&sig=kAkcKWxdFVvm7ulVj8zaEhAhnPLiGaDEoqsRLy6zdnU%3d
Unhandled exception. Microsoft.Azure.Devices.Client.Exceptions.UnauthorizedException: error(condition:amqp:unauthorized-access,description:Put token failed. status-code: 401, status-description: The specified SAS token has an invalid signature. It does not match either the primary or secondary key..)
---> Microsoft.Azure.Amqp.AmqpException: Put token failed. status-code: 401, status-description: The specified SAS token has an invalid signature. It does not match either the primary or secondary key..
at Microsoft.Azure.Amqp.ExceptionDispatcher.Throw(Exception exception)
at Microsoft.Azure.Amqp.AsyncResult.End[TAsyncResult](IAsyncResult result)
at Microsoft.Azure.Amqp.AsyncResult`1.End(IAsyncResult asyncResult)
at Microsoft.Azure.Amqp.AmqpCbsLink.EndSendToken(IAsyncResult result)
at Microsoft.Azure.Amqp.AmqpCbsLink.<>c__DisplayClass4_0.<SendTokenAsync>b__1(IAsyncResult a)
at System.Threading.Tasks.TaskFactory`1.FromAsyncCoreLogic(IAsyncResult , Func`2 , Action`1 , Task`1 , Boolean )
--- End of stack trace from previous location ---
at Microsoft.Azure.Devices.Client.Transport.AmqpIot.AmqpIotCbsLink.SendTokenAsync(ICbsTokenProvider tokenProvider, Uri namespaceAddress, String audience, String resource, String[] requiredClaims, TimeSpan timeout)
--- End of inner exception stack trace ---
at Microsoft.Azure.Devices.Client.Transport.AmqpIot.AmqpIotCbsLink.SendTokenAsync(ICbsTokenProvider tokenProvider, Uri namespaceAddress, String audience, String resource, String[] requiredClaims, TimeSpan timeout)
at Microsoft.Azure.Devices.Client.Transport.Amqp.AmqpAuthenticationRefresher.InitLoopAsync(TimeSpan timeout)
at Microsoft.Azure.Devices.Client.Transport.AmqpIot.AmqpIotConnection.CreateRefresherAsync(DeviceIdentity deviceIdentity, TimeSpan timeout)
at Microsoft.Azure.Devices.Client.Transport.Amqp.AmqpConnectionHolder.CreateRefresherAsync(DeviceIdentity deviceIdentity, TimeSpan timeout)
at Microsoft.Azure.Devices.Client.Transport.AmqpIot.AmqpUnit.EnsureSessionIsOpenAsync(TimeSpan timeout)
at Microsoft.Azure.Devices.Client.Transport.AmqpIot.AmqpUnit.OpenAsync(TimeSpan timeout)
at Microsoft.Azure.Devices.Client.Transport.Amqp.AmqpTransportHandler.OpenAsync(CancellationToken cancellationToken)
at Microsoft.Azure.Devices.Client.Transport.ProtocolRoutingDelegatingHandler.OpenAsync(CancellationToken cancellationToken)
at Microsoft.Azure.Devices.Client.Transport.ErrorDelegatingHandler.<>c__DisplayClass27_0.<<ExecuteWithErrorHandlingAsync>b__0>d.MoveNext()
--- End of stack trace from previous location ---
at Microsoft.Azure.Devices.Client.Transport.ErrorDelegatingHandler.ExecuteWithErrorHandlingAsync[T](Func`1 asyncOperation)
at Microsoft.Azure.Devices.Client.Transport.RetryDelegatingHandler.<>c__DisplayClass38_0.<<OpenInternalAsync>b__0>d.MoveNext()
--- End of stack trace from previous location ---
at Microsoft.Azure.Devices.Client.Transport.RetryDelegatingHandler.OpenInternalAsync(Boolean withRetry, CancellationToken cancellationToken)
at Microsoft.Azure.Devices.Client.Transport.RetryDelegatingHandler.EnsureOpenedAsync(Boolean withRetry, CancellationToken cancellationToken)
at Microsoft.Azure.Devices.Client.InternalClient.OpenAsync()
at echo.Program.Init(String connectionString, ITransportSettings settings)
at echo.Program.Main(String[] args)
at echo.Program.<Main>(String[] args)
Aborted (core dumped)
./ConsoleApp23 "Mqtt_Tcp_Only" "HostName=XXXXXXXXXXXX.azure-devices.net;DeviceId=testdevice;ModuleId=mymodule;SharedAccessSignature=SharedAccessSignature sr=XXXXXXXXXXXX.azure-devices.net%2fdevices%2ftestdevice&se=1639072929&sig=kAkcKWxdFVvm7ulVj8zaEhAhnPLiGaDEoqsRLy6zdnU%3d"
TransportType: Mqtt_Tcp_Only
ConnectionString: HostName=XXXXXXXXXXXX.azure-devices.net;DeviceId=testdevice;ModuleId=mymodule;SharedAccessSignature=SharedAccessSignature sr=XXXXXXXXXXXX.azure-devices.net%2fdevices%2ftestdevice&se=1639072929&sig=kAkcKWxdFVvm7ulVj8zaEhAhnPLiGaDEoqsRLy6zdnU%3d
IoT Hub module client initialized.using Microsoft.Azure.Devices.Client;
using Microsoft.Azure.Devices.Client.Transport.Mqtt;
using Microsoft.Azure.Devices.Shared;
using System.Runtime.Loader;
namespace echo
{
public static class Program
{
public static async Task Main(string[] args)
{
// Wait until the app unloads or is cancelled
using var cts = new CancellationTokenSource();
AssemblyLoadContext.Default.Unloading += (ctx) => cts.Cancel();
Console.CancelKeyPress += (sender, cpe) => cts.Cancel();
ITransportSettings settings;
if (args[0] == "Mqtt_Tcp_Only")
{
var mqttSetting = new MqttTransportSettings(TransportType.Mqtt_Tcp_Only);
mqttSetting.RemoteCertificateValidationCallback = (sender, certificate, chain, sslPolicyErrors) => true;
settings = mqttSetting;
}
else
{
var amqpSetting = new AmqpTransportSettings(TransportType.Amqp_Tcp_Only);
amqpSetting.RemoteCertificateValidationCallback = (sender, certificate, chain, sslPolicyErrors) => true;
settings = amqpSetting;
}
Console.WriteLine($"TransportType: { settings.GetTransportType()}");
var connectionString = args[1];
Console.WriteLine($"ConnectionString: {connectionString}");
await Init(connectionString, settings);
WhenCancelled(cts.Token).Wait();
}
/// <summary>
/// Handles cleanup operations when app is cancelled or unloads
/// </summary>
public static Task WhenCancelled(CancellationToken cancellationToken)
{
var tcs = new TaskCompletionSource<bool>();
_ = cancellationToken.Register(s => ((TaskCompletionSource<bool>)s).SetResult(true), tcs);
return tcs.Task;
}
/// <summary>
/// Initializes the ModuleClient and sets up the callback to receive
/// messages containing temperature information
/// </summary>
private static async Task Init(string connectionString, ITransportSettings settings)
{
// Open a connection to the Edge runtime
ModuleClient ioTHubModuleClient = ModuleClient.CreateFromConnectionString(connectionString, new ITransportSettings[] { settings });
await ioTHubModuleClient.OpenAsync();
Console.WriteLine("IoT Hub module client initialized.");
ioTHubModuleClient.SetConnectionStatusChangesHandler((status, reason) =>
{
Console.WriteLine($"Connection status change registered - status={status}, reason={reason}.");
});
_ = ioTHubModuleClient.SetMethodDefaultHandlerAsync((request, client) =>
{
Console.WriteLine($"{request.Name}: {request.DataAsJson}");
return Task.FromResult(new MethodResponse(Array.Empty<byte>(), 200));
}, ioTHubModuleClient);
await ioTHubModuleClient.SetDesiredPropertyUpdateCallbackAsync(DesiredPropertyUpdateCallback, null);
}
private async static Task DesiredPropertyUpdateCallback(TwinCollection desiredProperties, object userContext)
{
Console.WriteLine($"Received desired updates [{desiredProperties.ToJson()}]");
await Task.Delay(100);
}
}
}Are there any plan for a bug fix?
huguesBouvier
commented
2 years ago There is a plan but It will take a while. It is not a simple fix. This involves edge, SDK and IoTHub. It is not a bug, IoTEdge was designed originally to be the one to support module, this entails lot's of change to be done, especially on IoTHub side. This will months at least before a fix is out.
Expected Behavior
Hi, I'm trying to follow the transparent gateway documentation with iotedge 1.2 (https://docs.microsoft.com/en-us/azure/iot-edge/how-to-create-transparent-gateway?view=iotedge-2020-11).
1.) I have an iot device with iot-identity-service and two applications configured with module identity. The authentication type is SaS. If I connect this device directly with the iothub, the two module identities get provisioned. If I use this iot device afterwards as a downstream device behind a gateway the two module identites get provisioned as well. The edgehub log looks suspicous though. See in the log section below.
2.) If I use another iot device as a downstream device behind a gateway, that never was connected to the iothub, the provisioning of the module identites doesnt work. I get permission denied errors from the edgehub. The authentication type is Sas as well.
3.) If I use this device and configure one application as device identity. Only this application gets provisioned. The other application still gets an access denied error from the edgehub.
My goal is to achieve the provisioning of multiple module identities on a downstream iot device, without connecting this device directly to the iothub. The authentication type is Sas. Is that possible?
Output of
iotedge checkClick here
``` 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 - OK √ 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 √ tpmd 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 - Warning Could not retrieve iothub_hostname from provisioning file. Please specify the backing IoT Hub name using --iothub-hostname switch if you have that information. Since no hostname is provided, all hub connectivity tests will be skipped. ‼ host can connect to and perform TLS handshake with iothub HTTPS / WebSockets port - Warning Could not retrieve iothub_hostname from provisioning file. Please specify the backing IoT Hub name using --iothub-hostname switch if you have that information. Since no hostname is provided, all hub connectivity tests will be skipped. ‼ host can connect to and perform TLS handshake with iothub MQTT port - Warning Could not retrieve iothub_hostname from provisioning file. Please specify the backing IoT Hub name using --iothub-hostname switch if you have that information. Since no hostname is provided, all hub connectivity tests will be skipped. √ host can connect to and perform TLS handshake with DPS endpoint - 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 - Error Unable to find image 'mcr.microsoft.com/azureiotedge-diagnostics:1.2.2' locally docker: Error response from daemon: manifest for mcr.microsoft.com/azureiotedge-diagnostics:1.2.2 not found: manifest unknown: manifest tagged by "1.2.2" is not found. See 'docker run --help'. √ aziot-edge package is up-to-date - OK × container time is close to host time - Error Could not query local time inside container ‼ 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: container engine - Warning Device is not using a production-supported container engine (moby-engine). Please see https://aka.ms/iotedge-prod-checklist-moby for details. ‼ 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 Connectivity checks ------------------- 22 check(s) succeeded. 8 check(s) raised warnings. Re-run with --verbose for more details. 2 check(s) raised errors. Re-run with --verbose for more details. 6 check(s) were skipped due to errors from other checks. Re-run with --verbose for more details * The container engine seems to be misdetected. Is is indeed a moby-engine. ```Device Information
Runtime Versions
iotedge version]: iotedge 1.2.2 (git revision is 70bc14cb7884bda857688c93ff179821bb6c9061)docker version]: Client: Version: 19.03.15 API version: 1.40 Go version: go1.14.15 Git commit: eb310fca49 Built: Tue Jun 22 12:08:06 2021 OS/Arch: linux/arm64 Experimental: falseServer: Engine: Version: 19.03.15 API version: 1.40 (minimum version 1.12) Go version: go1.14.15 Git commit: 420b1d36250f9cfdc561f086f25a213ecb669b6f Built: Tue Jun 22 12:07:16 2021 OS/Arch: linux/arm64 Experimental: false containerd: Version: v1.2.14-3-g3b3e9d5f6.m GitCommit: 3b3e9d5f62a114153829f9fbe2781d27b0a2ddac.m runc: Version: 1.0.0-rc8 GitCommit: 425e105d5a03fabd737a126ad93d62a9eeede87f-dirty docker-init: Version: 0.18.0 GitCommit: fec3683-dirty
Logs
suspicous edgehub logs for working scenario 1.)
``` 2021-06-24 16:31:39 +00:00 Starting Edge Hub Jun 24 16:31:39.900 INFO watchdog: Starting Watchdog Jun 24 16:31:39.900 INFO watchdog: Registering shutdown signal listener Jun 24 16:31:40.198 INFO watchdog: MQTT broker is disabled Jun 24 16:31:40.198 INFO watchdog::child: Launched Edge Hub process with pid 9 2021-06-24 16:31:40.636 +00:00 Edge Hub Main() <6> 2021-06-24 16:31:46.848 +00:00 [INF] - Installing certificates [CN=damn.ca:07/10/2021 20:28:46],[CN=Azure_IoT_Hub_Intermediate_Cert_Test_Only:07/10/2021 06:14:27],[CN=Azure_IoT_Hub_CA_Cert_Test_Only:07/10/2021 06:14:26] to Root <6> 2021-06-24 16:31:47.095 +00:00 [INF] - Installing certificates [CN=damn.ca:07/10/2021 20:28:46],[CN=Azure_IoT_Hub_Intermediate_Cert_Test_Only:07/10/2021 06:14:27],[CN=Azure_IoT_Hub_CA_Cert_Test_Only:07/10/2021 06:14:26],[CN=Azure_IoT_Hub_CA_Cert_Test_Only:07/10/2021 06:14:26] to Root <6> 2021-06-24 16:31:47.149 +00:00 [INF] - Enabling SSL protocols: Tls, Tls11, Tls12 <6> 2021-06-24 16:31:47.989 +00:00 [INF] - Experimental features configuration: {"Enabled":false,"DisableCloudSubscriptions":false,"DisableConnectivityCheck":false,"EnableMqttBroker":false} <6> 2021-06-24 16:31:50.738 +00:00 [INF] - Created persistent store at /tmp/edgeHub <6> 2021-06-24 16:31:50.984 +00:00 [INF] - Initializing Edge Hub <6> 2021-06-24 16:31:50.986 +00:00 [INF] - █████╗ ███████╗██╗ ██╗██████╗ ███████╗ ██╔══██╗╚══███╔╝██║ ██║██╔══██╗██╔════╝ ███████║ ███╔╝ ██║ ██║██████╔╝█████╗ ██╔══██║ ███╔╝ ██║ ██║██╔══██╗██╔══╝ ██║ ██║███████╗╚██████╔╝██║ ██║███████╗ ╚═╝ ╚═╝╚══════╝ ╚═════╝ ╚═╝ ╚═╝╚══════╝ ██╗ ██████╗ ████████╗ ███████╗██████╗ ██████╗ ███████╗ ██║██╔═══██╗╚══██╔══╝ ██╔════╝██╔══██╗██╔════╝ ██╔════╝ ██║██║ ██║ ██║ █████╗ ██║ ██║██║ ███╗█████╗ ██║██║ ██║ ██║ ██╔══╝ ██║ ██║██║ ██║██╔══╝ ██║╚██████╔╝ ██║ ███████╗██████╔╝╚██████╔╝███████╗ ╚═╝ ╚═════╝ ╚═╝ ╚══════╝╚═════╝ ╚═════╝ ╚══════╝ <6> 2021-06-24 16:31:50.993 +00:00 [INF] - Version - 1.2.1.43175312 (f0e7486e3fd527515999b9449313e55b733516c9) <6> 2021-06-24 16:31:50.995 +00:00 [INF] - OptimizeForPerformance=False <6> 2021-06-24 16:31:50.996 +00:00 [INF] - MessageAckTimeoutSecs=30 <6> 2021-06-24 16:31:51.004 +00:00 [INF] - Loaded server certificate with expiration date of "2021-07-10T20:28:46.0000000+00:00" <6> 2021-06-24 16:31:51.061 +00:00 [INF] - Using Asp Net server for metrics <6> 2021-06-24 16:31:51.373 +00:00 [INF] - Started task to cleanup processed and stale messages <6> 2021-06-24 16:31:51.374 +00:00 [INF] - Created new message store <6> 2021-06-24 16:31:51.801 +00:00 [INF] - Created DeviceConnectivityManager with connected check frequency 00:05:00 and disconnected check frequency 00:02:00 <6> 2021-06-24 16:31:51.995 +00:00 [INF] - Add node: dc:a6:32:55:90:cb <6> 2021-06-24 16:31:52.010 +00:00 [INF] - Add node: dc:a6:32:55:90:cb/$edgeAgent <6> 2021-06-24 16:31:52.011 +00:00 [INF] - Add node: dc:a6:32:55:90:cb/$edgeHub <6> 2021-06-24 16:31:52.012 +00:00 [INF] - Add node: dc:a6:32:55:90:cb/AducIotAgent <6> 2021-06-24 16:31:52.012 +00:00 [INF] - Add node: dc:a6:32:55:90:cb/iot-module-template <6> 2021-06-24 16:31:52.021 +00:00 [INF] - Add node: mlilien-rpi3 <6> 2021-06-24 16:31:52.038 +00:00 [INF] - Created device scope identities cache <6> 2021-06-24 16:31:52.096 +00:00 [INF] - Starting refresh of device scope identities cache <6> 2021-06-24 16:31:52.125 +00:00 [INF] - Initialized storing twin manager <6> 2021-06-24 16:31:52.179 +00:00 [INF] - Updated node: dc:a6:32:55:90:cb/$edgeHub <6> 2021-06-24 16:31:52.197 +00:00 [INF] - Initializing configuration <6> 2021-06-24 16:31:52.285 +00:00 [INF] - New device connection for device dc:a6:32:55:90:cb/$edgeHub <6> 2021-06-24 16:31:52.358 +00:00 [INF] - Client dc:a6:32:55:90:cb/$edgeHub connected to edgeHub, processing existing subscriptions. <6> 2021-06-24 16:31:52.648 +00:00 [INF] - Attempting to connect to IoT Hub for client dc:a6:32:55:90:cb/$edgeHub via AMQP... <6> 2021-06-24 16:31:52.741 +00:00 [INF] - Processing pending subscriptions for dc:a6:32:55:90:cb/$edgeHub <6> 2021-06-24 16:31:54.022 +00:00 [INF] - Experimental features configuration: {"Enabled":false,"DisableCloudSubscriptions":false,"DisableConnectivityCheck":false,"EnableMqttBroker":false} <6> 2021-06-24 16:31:54.156 +00:00 [INF] - Starting timer to authenticate connections with a period of 300 seconds <6> 2021-06-24 16:31:54.537 +00:00 [INF] - Scheduling server certificate renewal for "2021-07-10T20:26:16.0006687Z". <6> 2021-06-24 16:31:54.605 +00:00 [INF] - Not changed node: dc:a6:32:55:90:cb <6> 2021-06-24 16:31:54.606 +00:00 [INF] - Not changed node: mlilien-rpi3 <6> 2021-06-24 16:31:54.607 +00:00 [INF] - Not changed node: dc:a6:32:55:90:cb/$edgeAgent <6> 2021-06-24 16:31:54.607 +00:00 [INF] - Updated node: dc:a6:32:55:90:cb/$edgeHub <6> 2021-06-24 16:31:54.807 +00:00 [INF] - Service identity for dc:a6:32:55:90:cb/$edgeHub in device scope was updated. <6> 2021-06-24 16:31:54.812 +00:00 [INF] - Not changed node: dc:a6:32:55:90:cb/AducIotAgent <6> 2021-06-24 16:31:54.814 +00:00 [INF] - Not changed node: dc:a6:32:55:90:cb/iot-module-template <6> 2021-06-24 16:31:54.837 +00:00 [INF] - Done refreshing device scope identities cache. Waiting for 60 minutes. <6> 2021-06-24 16:31:55.318 +00:00 [INF] - Created cloud endpoint iothub with max batch size 10 and fan-out factor of 10. <6> 2021-06-24 16:31:56.028 +00:00 [INF] - Set the following 1 route(s) in edge hub <6> 2021-06-24 16:31:56.029 +00:00 [INF] - route: FROM /messages/* INTO $upstream <6> 2021-06-24 16:31:56.039 +00:00 [INF] - Updated message store TTL to 60 seconds <6> 2021-06-24 16:31:56.041 +00:00 [INF] - Updated the edge hub store and forward configuration <6> 2021-06-24 16:31:56.136 +00:00 [INF] - Started operation Get EdgeHub config <6> 2021-06-24 16:31:56.139 +00:00 [INF] - Initialized edge hub configuration <6> 2021-06-24 16:31:56.147 +00:00 [INF] - Starting protocol heads - (MQTT, AMQP, HTTP) <6> 2021-06-24 16:31:56.168 +00:00 [INF] - Starting MQTT head <6> 2021-06-24 16:31:56.321 +00:00 [INF] - Initializing TLS endpoint on port 8883 for MQTT head. <6> 2021-06-24 16:31:56.365 +00:00 [INF] - Exiting disconnected state <6> 2021-06-24 16:31:56.487 +00:00 [INF] - Device connected to cloud, processing subscriptions for connected clients. <6> 2021-06-24 16:31:56.497 +00:00 [INF] - Processing subscriptions for client dc:a6:32:55:90:cb/$edgeHub on device connected to cloud. <6> 2021-06-24 16:31:56.499 +00:00 [INF] - Skipping dc:a6:32:55:90:cb/$edgeHub for subscription processing, as it is currently being processed. <6> 2021-06-24 16:31:56.522 +00:00 [INF] - Received device connected callback <6> 2021-06-24 16:31:56.562 +00:00 [INF] - Skipping cache refresh, waiting 118 seconds until refreshing again. <6> 2021-06-24 16:31:56.621 +00:00 [INF] - Entering connected state <6> 2021-06-24 16:31:56.649 +00:00 [INF] - Cloud connection for dc:a6:32:55:90:cb/$edgeHub is True <6> 2021-06-24 16:31:56.669 +00:00 [INF] - Connection status for dc:a6:32:55:90:cb/$edgeHub changed to ConnectionEstablished <6> 2021-06-24 16:31:56.677 +00:00 [INF] - Client dc:a6:32:55:90:cb/$edgeHub connected to cloud, processing existing subscriptions. <6> 2021-06-24 16:31:56.677 +00:00 [INF] - Skipping dc:a6:32:55:90:cb/$edgeHub for subscription processing, as it is currently being processed. <6> 2021-06-24 16:31:56.695 +00:00 [INF] - Created cloud proxy for client dc:a6:32:55:90:cb/$edgeHub via AMQP, with client operation timeout 20 seconds. <6> 2021-06-24 16:31:56.719 +00:00 [INF] - Initialized cloud proxy 95d76186-fd77-4651-b3a1-903341dd1fcd for dc:a6:32:55:90:cb/$edgeHub <6> 2021-06-24 16:31:56.729 +00:00 [INF] - Created cloud connection for client dc:a6:32:55:90:cb/$edgeHub <6> 2021-06-24 16:31:56.775 +00:00 [INF] - Starting AMQP head <6> 2021-06-24 16:31:56.879 +00:00 [INF] - Started MQTT head <6> 2021-06-24 16:31:57.332 +00:00 [INF] - Started AMQP head <6> 2021-06-24 16:31:57.341 +00:00 [INF] - Starting HTTP head <6> 2021-06-24 16:31:57.774 +00:00 [INF] - Processing pending subscriptions for dc:a6:32:55:90:cb/$edgeHub <6> 2021-06-24 16:31:57.801 +00:00 [INF] - Updated reported properties for dc:a6:32:55:90:cb/$edgeHub <6> 2021-06-24 16:31:58.540 +00:00 [INF] - Obtained edge hub config from module twin <4> 2021-06-24 16:31:58.671 +00:00 [WRN] - Overriding address(es) '"http://+:80"'. Binding to endpoints defined in "UseKestrel()" instead. <6> 2021-06-24 16:31:58.703 +00:00 [INF] - Started HTTP head <6> 2021-06-24 16:31:58.804 +00:00 [INF] - Set the following 1 route(s) in edge hub <6> 2021-06-24 16:31:58.805 +00:00 [INF] - route: FROM /messages/* INTO $upstream <6> 2021-06-24 16:31:58.805 +00:00 [INF] - Updated message store TTL to 60 seconds <6> 2021-06-24 16:31:58.806 +00:00 [INF] - Updated the edge hub store and forward configuration <6> 2021-06-24 16:32:03.730 +00:00 [INF] - Updated reported properties for dc:a6:32:55:90:cb/$edgeHub <6> 2021-06-24 16:32:21.011 +00:00 [INF] - Unable to authenticate client mlilien-rpi3/AducIotAgent with cached service identity mlilien-rpi3/AducIotAgent (Found: False). Resyncing service identity... <6> 2021-06-24 16:32:21.045 +00:00 [INF] - Refreshing service identity for mlilien-rpi3/AducIotAgent <6> 2021-06-24 16:32:21.080 +00:00 [INF] - Unable to authenticate client mlilien-rpi3/iot-module-template with cached service identity mlilien-rpi3/iot-module-template (Found: False). Resyncing service identity... <6> 2021-06-24 16:32:21.081 +00:00 [INF] - Refreshing service identity for mlilien-rpi3/iot-module-template <4> 2021-06-24 16:32:22.207 +00:00 [WRN] - Error while refreshing the service identity: mlilien-rpi3/iot-module-template OnBehalfOf: dc:a6:32:55:90:cb System.ArgumentException: mlilien-rpi3 is not an Edge device, only Edge devices can have children at Microsoft.Azure.Devices.Edge.Hub.Core.ServiceIdentityTree.ServiceIdentityTreeNode.AddChild(ServiceIdentityTreeNode childNode) in /home/vsts/work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/ServiceIdentityTree.cs:line 365 at Microsoft.Azure.Devices.Edge.Hub.Core.ServiceIdentityTree.InsertModuleIdentity(ServiceIdentity module) in /home/vsts/work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/ServiceIdentityTree.cs:line 244 at Microsoft.Azure.Devices.Edge.Hub.Core.ServiceIdentityTree.AddOrUpdate(ServiceIdentity identity) in /home/vsts/work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/ServiceIdentityTree.cs:line 59 at Microsoft.Azure.Devices.Edge.Hub.Core.DeviceScopeIdentitiesCache.HandleNewServiceIdentity(ServiceIdentity serviceIdentity) in /home/vsts/work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/DeviceScopeIdentitiesCache.cs:line 466 at Microsoft.Azure.Devices.Edge.Hub.Core.DeviceScopeIdentitiesCache.RefreshServiceIdentityInternal(String refreshTarget, String onBehalfOfDevice, Boolean invokeServiceIdentitiesUpdated) in /home/vsts/work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/DeviceScopeIdentitiesCache.cs:line 171 <4> 2021-06-24 16:32:22.190 +00:00 [WRN] - Error while refreshing the service identity: mlilien-rpi3/AducIotAgent OnBehalfOf: dc:a6:32:55:90:cb System.ArgumentException: mlilien-rpi3 is not an Edge device, only Edge devices can have children at Microsoft.Azure.Devices.Edge.Hub.Core.ServiceIdentityTree.ServiceIdentityTreeNode.AddChild(ServiceIdentityTreeNode childNode) in /home/vsts/work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/ServiceIdentityTree.cs:line 365 at Microsoft.Azure.Devices.Edge.Hub.Core.ServiceIdentityTree.InsertModuleIdentity(ServiceIdentity module) in /home/vsts/work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/ServiceIdentityTree.cs:line 244 at Microsoft.Azure.Devices.Edge.Hub.Core.ServiceIdentityTree.AddOrUpdate(ServiceIdentity identity) in /home/vsts/work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/ServiceIdentityTree.cs:line 59 at Microsoft.Azure.Devices.Edge.Hub.Core.DeviceScopeIdentitiesCache.HandleNewServiceIdentity(ServiceIdentity serviceIdentity) in /home/vsts/work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/DeviceScopeIdentitiesCache.cs:line 466 at Microsoft.Azure.Devices.Edge.Hub.Core.DeviceScopeIdentitiesCache.RefreshServiceIdentityInternal(String refreshTarget, String onBehalfOfDevice, Boolean invokeServiceIdentitiesUpdated) in /home/vsts/work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/DeviceScopeIdentitiesCache.cs:line 171 <6> 2021-06-24 16:32:22.462 +00:00 [INF] - Client mlilien-rpi3/iot-module-template in device scope authenticated locally. <6> 2021-06-24 16:32:22.462 +00:00 [INF] - Client mlilien-rpi3/AducIotAgent in device scope authenticated locally. <6> 2021-06-24 16:32:22.502 +00:00 [INF] - Successfully generated identity for clientId mlilien-rpi3/AducIotAgent and username my-iothub.azure-devices.net/mlilien-rpi3/AducIotAgent/?api-version=2020-09-30&DeviceClientType=iothubclient%2f1.6.0%20(native%3b%20Linux%3b%20armv7l)&model-id=dtmi%3aAzureDeviceUpdate%3b1 <6> 2021-06-24 16:32:22.502 +00:00 [INF] - Successfully generated identity for clientId mlilien-rpi3/iot-module-template and username my-iothub.azure-devices.net/mlilien-rpi3/iot-module-template/?api-version=2020-09-30&DeviceClientType=iothubclient%2f1.6.0%20(native%3b%20Linux%3b%20armv7l) <6> 2021-06-24 16:32:22.537 +00:00 [INF] - ClientAuthenticated, mlilien-rpi3/AducIotAgent, 78c27f86 <6> 2021-06-24 16:32:22.537 +00:00 [INF] - ClientAuthenticated, mlilien-rpi3/iot-module-template, 5a521d03 <6> 2021-06-24 16:32:22.766 +00:00 [INF] - New device connection for device mlilien-rpi3/AducIotAgent <6> 2021-06-24 16:32:22.768 +00:00 [INF] - New device connection for device mlilien-rpi3/iot-module-template <6> 2021-06-24 16:32:22.768 +00:00 [INF] - Client mlilien-rpi3/AducIotAgent connected to edgeHub, processing existing subscriptions. <6> 2021-06-24 16:32:22.769 +00:00 [INF] - Client mlilien-rpi3/iot-module-template connected to edgeHub, processing existing subscriptions. <4> 2021-06-24 16:32:22.785 +00:00 [WRN] - Error creating cloud connection for client mlilien-rpi3/AducIotAgent Microsoft.Azure.Devices.Edge.Hub.Core.DeviceInvalidStateException: Device is out of scope. at Microsoft.Azure.Devices.Edge.Util.Try`1.get_Value() in /home/vsts/work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/Try.cs:line 29 at Microsoft.Azure.Devices.Edge.Hub.Core.DeviceScopeIdentitiesCache.VerifyServiceIdentityAuthChainState(String id, Boolean refreshCachedIdentity) in /home/vsts/work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/DeviceScopeIdentitiesCache.cs:line 260 at Microsoft.Azure.Devices.Edge.Hub.Core.DeviceScopeIdentitiesCache.VerifyServiceIdentityAuthChainState(String id, Boolean isNestedEdgeEnabled, Boolean refreshCachedIdentity) in /home/vsts/work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/DeviceScopeIdentitiesCache.cs:line 224 at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnectionProvider.ConnectInternalWithDeviceStateTracking(IIdentity identity, Action`2 connectionStatusChangedHandler, Boolean refreshCachedIdentity) in /home/vsts/work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudConnectionProvider.cs:line 248 <6> 2021-06-24 16:32:22.798 +00:00 [INF] - Refreshing service identity for mlilien-rpi3/AducIotAgent <6> 2021-06-24 16:32:22.877 +00:00 [INF] - Bind device proxy for device mlilien-rpi3/iot-module-template <6> 2021-06-24 16:32:22.881 +00:00 [INF] - Binding message channel for device Id mlilien-rpi3/iot-module-template <6> 2021-06-24 16:32:22.890 +00:00 [INF] - Processing pending subscriptions for mlilien-rpi3/AducIotAgent <6> 2021-06-24 16:32:22.893 +00:00 [INF] - Bind device proxy for device mlilien-rpi3/AducIotAgent <6> 2021-06-24 16:32:22.893 +00:00 [INF] - Binding message channel for device Id mlilien-rpi3/AducIotAgent <6> 2021-06-24 16:32:22.914 +00:00 [INF] - Refreshing service identity for mlilien-rpi3/AducIotAgent <4> 2021-06-24 16:32:22.913 +00:00 [WRN] - Error creating cloud connection for client mlilien-rpi3/iot-module-template Microsoft.Azure.Devices.Edge.Hub.Core.DeviceInvalidStateException: Device is out of scope. at Microsoft.Azure.Devices.Edge.Util.Try`1.get_Value() in /home/vsts/work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/Try.cs:line 29 at Microsoft.Azure.Devices.Edge.Hub.Core.DeviceScopeIdentitiesCache.VerifyServiceIdentityAuthChainState(String id, Boolean refreshCachedIdentity) in /home/vsts/work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/DeviceScopeIdentitiesCache.cs:line 260 at Microsoft.Azure.Devices.Edge.Hub.Core.DeviceScopeIdentitiesCache.VerifyServiceIdentityAuthChainState(String id, Boolean isNestedEdgeEnabled, Boolean refreshCachedIdentity) in /home/vsts/work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/DeviceScopeIdentitiesCache.cs:line 224 at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnectionProvider.ConnectInternalWithDeviceStateTracking(IIdentity identity, Action`2 connectionStatusChangedHandler, Boolean refreshCachedIdentity) in /home/vsts/work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudConnectionProvider.cs:line 248 <6> 2021-06-24 16:32:22.917 +00:00 [INF] - Refreshing service identity for mlilien-rpi3/iot-module-template <6> 2021-06-24 16:32:22.917 +00:00 [INF] - Refreshing service identity for mlilien-rpi3/iot-module-template <6> 2021-06-24 16:32:23.082 +00:00 [INF] - Processing subscriptions TwinResponse, DesiredPropertyUpdates for client mlilien-rpi3/AducIotAgent. <6> 2021-06-24 16:32:23.132 +00:00 [INF] - Set subscriptions from session state for mlilien-rpi3/AducIotAgent <6> 2021-06-24 16:32:23.141 +00:00 [INF] - Processing subscriptions TwinResponse, DesiredPropertyUpdates for client mlilien-rpi3/iot-module-template. <6> 2021-06-24 16:32:23.150 +00:00 [INF] - Not changed node: mlilien-rpi3/iot-module-template <6> 2021-06-24 16:32:23.155 +00:00 [INF] - Not changed node: mlilien-rpi3/AducIotAgent ```edgeHub logs scenario 2 - two module identities - unauthorized
``` 2021-06-24 17:22:09 +00:00 Starting Edge Hub Jun 24 17:22:09.609 INFO watchdog: Starting Watchdog Jun 24 17:22:09.609 INFO watchdog: Registering shutdown signal listener Jun 24 17:22:09.611 INFO watchdog: MQTT broker is disabled Jun 24 17:22:09.611 INFO watchdog::child: Launched Edge Hub process with pid 9 2021-06-24 17:22:09.941 +00:00 Edge Hub Main() <6> 2021-06-24 17:22:14.679 +00:00 [INF] - Installing certificates [CN=damn.ca:07/10/2021 20:28:46],[CN=Azure_IoT_Hub_Intermediate_Cert_Test_Only:07/10/2021 06:14:27],[CN=Azure_IoT_Hub_CA_Cert_Test_Only:07/10/2021 06:14:26] to Root <6> 2021-06-24 17:22:14.964 +00:00 [INF] - Installing certificates [CN=damn.ca:07/10/2021 20:28:46],[CN=Azure_IoT_Hub_Intermediate_Cert_Test_Only:07/10/2021 06:14:27],[CN=Azure_IoT_Hub_CA_Cert_Test_Only:07/10/2021 06:14:26],[CN=Azure_IoT_Hub_CA_Cert_Test_Only:07/10/2021 06:14:26] to Root <6> 2021-06-24 17:22:15.058 +00:00 [INF] - Enabling SSL protocols: Tls, Tls11, Tls12 <6> 2021-06-24 17:22:15.686 +00:00 [INF] - Experimental features configuration: {"Enabled":false,"DisableCloudSubscriptions":false,"DisableConnectivityCheck":false,"EnableMqttBroker":false} <6> 2021-06-24 17:22:18.268 +00:00 [INF] - Created persistent store at /tmp/edgeHub <6> 2021-06-24 17:22:18.520 +00:00 [INF] - Initializing Edge Hub <6> 2021-06-24 17:22:18.521 +00:00 [INF] - █████╗ ███████╗██╗ ██╗██████╗ ███████╗ ██╔══██╗╚══███╔╝██║ ██║██╔══██╗██╔════╝ ███████║ ███╔╝ ██║ ██║██████╔╝█████╗ ██╔══██║ ███╔╝ ██║ ██║██╔══██╗██╔══╝ ██║ ██║███████╗╚██████╔╝██║ ██║███████╗ ╚═╝ ╚═╝╚══════╝ ╚═════╝ ╚═╝ ╚═╝╚══════╝ ██╗ ██████╗ ████████╗ ███████╗██████╗ ██████╗ ███████╗ ██║██╔═══██╗╚══██╔══╝ ██╔════╝██╔══██╗██╔════╝ ██╔════╝ ██║██║ ██║ ██║ █████╗ ██║ ██║██║ ███╗█████╗ ██║██║ ██║ ██║ ██╔══╝ ██║ ██║██║ ██║██╔══╝ ██║╚██████╔╝ ██║ ███████╗██████╔╝╚██████╔╝███████╗ ╚═╝ ╚═════╝ ╚═╝ ╚══════╝╚═════╝ ╚═════╝ ╚══════╝ <6> 2021-06-24 17:22:18.529 +00:00 [INF] - Version - 1.2.1.43175312 (f0e7486e3fd527515999b9449313e55b733516c9) <6> 2021-06-24 17:22:18.530 +00:00 [INF] - OptimizeForPerformance=False <6> 2021-06-24 17:22:18.531 +00:00 [INF] - MessageAckTimeoutSecs=30 <6> 2021-06-24 17:22:18.550 +00:00 [INF] - Created device scope identities cache <6> 2021-06-24 17:22:18.535 +00:00 [INF] - Loaded server certificate with expiration date of "2021-07-10T20:28:46.0000000+00:00" <6> 2021-06-24 17:22:18.584 +00:00 [INF] - Using Asp Net server for metrics <6> 2021-06-24 17:22:18.645 +00:00 [INF] - Starting refresh of device scope identities cache <6> 2021-06-24 17:22:18.840 +00:00 [INF] - Created new message store <6> 2021-06-24 17:22:18.849 +00:00 [INF] - Started task to cleanup processed and stale messages <6> 2021-06-24 17:22:19.193 +00:00 [INF] - Created DeviceConnectivityManager with connected check frequency 00:05:00 and disconnected check frequency 00:02:00 <6> 2021-06-24 17:22:19.353 +00:00 [INF] - Initialized storing twin manager <6> 2021-06-24 17:22:19.449 +00:00 [INF] - Add node: dc:a6:32:55:90:cb/$edgeHub <6> 2021-06-24 17:22:19.449 +00:00 [INF] - Initializing configuration <6> 2021-06-24 17:22:19.535 +00:00 [INF] - New device connection for device dc:a6:32:55:90:cb/$edgeHub <6> 2021-06-24 17:22:19.596 +00:00 [INF] - Client dc:a6:32:55:90:cb/$edgeHub connected to edgeHub, processing existing subscriptions. <6> 2021-06-24 17:22:19.847 +00:00 [INF] - Attempting to connect to IoT Hub for client dc:a6:32:55:90:cb/$edgeHub via AMQP... <6> 2021-06-24 17:22:19.941 +00:00 [INF] - Processing pending subscriptions for dc:a6:32:55:90:cb/$edgeHub <6> 2021-06-24 17:22:21.054 +00:00 [INF] - Add node: mlilien-rpi3-2 <6> 2021-06-24 17:22:21.278 +00:00 [INF] - Experimental features configuration: {"Enabled":false,"DisableCloudSubscriptions":false,"DisableConnectivityCheck":false,"EnableMqttBroker":false} <6> 2021-06-24 17:22:21.411 +00:00 [INF] - Starting timer to authenticate connections with a period of 300 seconds <6> 2021-06-24 17:22:21.463 +00:00 [INF] - Add node: dc:a6:32:55:90:cb <4> 2021-06-24 17:22:21.529 +00:00 [WRN] - Empty edge hub configuration received. Ignoring... <6> 2021-06-24 17:22:21.577 +00:00 [INF] - Add node: dc:a6:32:55:90:cb/$edgeAgent <6> 2021-06-24 17:22:21.713 +00:00 [INF] - Updated node: dc:a6:32:55:90:cb/$edgeHub <6> 2021-06-24 17:22:21.806 +00:00 [INF] - Scheduling server certificate renewal for "2021-07-10T20:26:16.0013538Z". <6> 2021-06-24 17:22:21.825 +00:00 [INF] - Service identity for dc:a6:32:55:90:cb/$edgeHub in device scope was updated. <6> 2021-06-24 17:22:21.826 +00:00 [INF] - Add node: dc:a6:32:55:90:cb/AducIotAgent <6> 2021-06-24 17:22:21.912 +00:00 [INF] - Add node: dc:a6:32:55:90:cb/iot-module-template <6> 2021-06-24 17:22:22.030 +00:00 [INF] - Done refreshing device scope identities cache. Waiting for 60 minutes. <6> 2021-06-24 17:22:23.006 +00:00 [INF] - Exiting disconnected state <6> 2021-06-24 17:22:23.092 +00:00 [INF] - Received device connected callback <6> 2021-06-24 17:22:23.125 +00:00 [INF] - Device connected to cloud, processing subscriptions for connected clients. <6> 2021-06-24 17:22:23.135 +00:00 [INF] - Processing subscriptions for client dc:a6:32:55:90:cb/$edgeHub on device connected to cloud. <6> 2021-06-24 17:22:23.137 +00:00 [INF] - Skipping dc:a6:32:55:90:cb/$edgeHub for subscription processing, as it is currently being processed. <6> 2021-06-24 17:22:23.143 +00:00 [INF] - Skipping cache refresh, waiting 118 seconds until refreshing again. <6> 2021-06-24 17:22:23.192 +00:00 [INF] - Entering connected state <6> 2021-06-24 17:22:23.216 +00:00 [INF] - Cloud connection for dc:a6:32:55:90:cb/$edgeHub is True <6> 2021-06-24 17:22:23.233 +00:00 [INF] - Connection status for dc:a6:32:55:90:cb/$edgeHub changed to ConnectionEstablished <6> 2021-06-24 17:22:23.240 +00:00 [INF] - Client dc:a6:32:55:90:cb/$edgeHub connected to cloud, processing existing subscriptions. <6> 2021-06-24 17:22:23.241 +00:00 [INF] - Skipping dc:a6:32:55:90:cb/$edgeHub for subscription processing, as it is currently being processed. <6> 2021-06-24 17:22:23.254 +00:00 [INF] - Created cloud proxy for client dc:a6:32:55:90:cb/$edgeHub via AMQP, with client operation timeout 20 seconds. <6> 2021-06-24 17:22:23.277 +00:00 [INF] - Initialized cloud proxy 7fc18cbb-b8d0-4469-86bc-aa9d0fbf263d for dc:a6:32:55:90:cb/$edgeHub <6> 2021-06-24 17:22:23.284 +00:00 [INF] - Created cloud connection for client dc:a6:32:55:90:cb/$edgeHub <6> 2021-06-24 17:22:23.989 +00:00 [INF] - Processing pending subscriptions for dc:a6:32:55:90:cb/$edgeHub <6> 2021-06-24 17:22:23.998 +00:00 [INF] - Updated reported properties for dc:a6:32:55:90:cb/$edgeHub <6> 2021-06-24 17:22:24.470 +00:00 [INF] - Done syncing reported properties for dc:a6:32:55:90:cb/$edgeHub <6> 2021-06-24 17:22:25.133 +00:00 [INF] - Created cloud endpoint iothub with max batch size 10 and fan-out factor of 10. <6> 2021-06-24 17:22:25.590 +00:00 [INF] - Obtained edge hub config from module twin <6> 2021-06-24 17:22:26.349 +00:00 [INF] - Set the following 1 route(s) in edge hub <6> 2021-06-24 17:22:26.350 +00:00 [INF] - route: FROM /messages/* INTO $upstream <6> 2021-06-24 17:22:26.361 +00:00 [INF] - Updated message store TTL to 60 seconds <6> 2021-06-24 17:22:26.363 +00:00 [INF] - Updated the edge hub store and forward configuration <6> 2021-06-24 17:22:26.402 +00:00 [INF] - Started operation Get EdgeHub config <6> 2021-06-24 17:22:26.404 +00:00 [INF] - Initialized edge hub configuration <6> 2021-06-24 17:22:26.412 +00:00 [INF] - Starting protocol heads - (MQTT, AMQP, HTTP) <6> 2021-06-24 17:22:26.426 +00:00 [INF] - Starting MQTT head <6> 2021-06-24 17:22:26.567 +00:00 [INF] - Initializing TLS endpoint on port 8883 for MQTT head. <6> 2021-06-24 17:22:26.875 +00:00 [INF] - Starting AMQP head <6> 2021-06-24 17:22:26.964 +00:00 [INF] - Started MQTT head <6> 2021-06-24 17:22:27.308 +00:00 [INF] - Started AMQP head <6> 2021-06-24 17:22:27.329 +00:00 [INF] - Starting HTTP head <4> 2021-06-24 17:22:28.334 +00:00 [WRN] - Overriding address(es) '"http://+:80"'. Binding to endpoints defined in "UseKestrel()" instead. <6> 2021-06-24 17:22:28.367 +00:00 [INF] - Started HTTP head <6> 2021-06-24 17:22:29.817 +00:00 [INF] - Updated reported properties for dc:a6:32:55:90:cb/$edgeHub <6> 2021-06-24 17:22:56.498 +00:00 [INF] - Request starting HTTP/2 GET https://mlilien-rpi4/devices/mlilien-rpi3-2/modules/iot-module-template?api-version=2017-11-08-preview <6> 2021-06-24 17:22:56.814 +00:00 [INF] - Executing endpoint '"Microsoft.Azure.Devices.Edge.Hub.Http.Controllers.RegistryController.GetModuleAsync (Microsoft.Azure.Devices.Edge.Hub.Http)"' <6> 2021-06-24 17:22:57.131 +00:00 [INF] - Route matched with "{action = \"GetModule\", controller = \"Registry\"}". Executing controller action with signature "System.Threading.Tasks.Task GetModuleAsync(System.String, System.String)" on controller "Microsoft.Azure.Devices.Edge.Hub.Http.Controllers.RegistryController" ("Microsoft.Azure.Devices.Edge.Hub.Http"). <6> 2021-06-24 17:22:57.245 +00:00 [INF] - Received request in GetModuleAsync: deviceId=mlilien-rpi3-2, moduleId=iot-module-template <6> 2021-06-24 17:22:57.484 +00:00 [INF] - Client mlilien-rpi3-2 in device scope authenticated locally. <6> 2021-06-24 17:22:57.503 +00:00 [INF] - Authenticated: deviceId=mlilien-rpi3-2, moduleId= <6> 2021-06-24 17:22:57.827 +00:00 [INF] - CompleteRequest in GetModuleAsync: deviceId=dc:a6:32:55:90:cb, authChain=mlilien-rpi3-2;dc:a6:32:55:90:cb, status=NotFound <6> 2021-06-24 17:22:57.895 +00:00 [INF] - Executed action "Microsoft.Azure.Devices.Edge.Hub.Http.Controllers.RegistryController.GetModuleAsync (Microsoft.Azure.Devices.Edge.Hub.Http)" in 721.0495ms <6> 2021-06-24 17:22:57.903 +00:00 [INF] - Executed endpoint '"Microsoft.Azure.Devices.Edge.Hub.Http.Controllers.RegistryController.GetModuleAsync (Microsoft.Azure.Devices.Edge.Hub.Http)"' <6> 2021-06-24 17:22:57.940 +00:00 [INF] - Request finished in 1462.4832ms 404 application/json; charset=utf-8 <6> 2021-06-24 17:22:58.020 +00:00 [INF] - Request starting HTTP/2 GET https://mlilien-rpi4/devices/mlilien-rpi3-2/modules/AducIotAgent?api-version=2017-11-08-preview <6> 2021-06-24 17:22:58.031 +00:00 [INF] - Executing endpoint '"Microsoft.Azure.Devices.Edge.Hub.Http.Controllers.RegistryController.GetModuleAsync (Microsoft.Azure.Devices.Edge.Hub.Http)"' <6> 2021-06-24 17:22:58.076 +00:00 [INF] - Route matched with "{action = \"GetModule\", controller = \"Registry\"}". Executing controller action with signature "System.Threading.Tasks.Task GetModuleAsync(System.String, System.String)" on controller "Microsoft.Azure.Devices.Edge.Hub.Http.Controllers.RegistryController" ("Microsoft.Azure.Devices.Edge.Hub.Http"). <6> 2021-06-24 17:22:58.080 +00:00 [INF] - Received request in GetModuleAsync: deviceId=mlilien-rpi3-2, moduleId=AducIotAgent <6> 2021-06-24 17:22:58.084 +00:00 [INF] - Client mlilien-rpi3-2 in device scope authenticated locally. <6> 2021-06-24 17:22:58.085 +00:00 [INF] - Authenticated: deviceId=mlilien-rpi3-2, moduleId= <6> 2021-06-24 17:22:58.318 +00:00 [INF] - CompleteRequest in GetModuleAsync: deviceId=dc:a6:32:55:90:cb, authChain=mlilien-rpi3-2;dc:a6:32:55:90:cb, status=NotFound <6> 2021-06-24 17:22:58.329 +00:00 [INF] - Executed action "Microsoft.Azure.Devices.Edge.Hub.Http.Controllers.RegistryController.GetModuleAsync (Microsoft.Azure.Devices.Edge.Hub.Http)" in 247.8985ms <6> 2021-06-24 17:22:58.333 +00:00 [INF] - Executed endpoint '"Microsoft.Azure.Devices.Edge.Hub.Http.Controllers.RegistryController.GetModuleAsync (Microsoft.Azure.Devices.Edge.Hub.Http)"' <6> 2021-06-24 17:22:58.343 +00:00 [INF] - Request finished in 322.3987ms 404 application/json; charset=utf-8 ```edge-hub logs szenario 3 - one device identity, one module identity - module unauthorized
``` 2021-06-24 17:29:10 +00:00 Starting Edge Hub Jun 24 17:29:10.062 INFO watchdog: Starting Watchdog Jun 24 17:29:10.062 INFO watchdog: Registering shutdown signal listener Jun 24 17:29:10.065 INFO watchdog: MQTT broker is disabled Jun 24 17:29:10.065 INFO watchdog::child: Launched Edge Hub process with pid 9 2021-06-24 17:29:10.384 +00:00 Edge Hub Main() <6> 2021-06-24 17:29:15.746 +00:00 [INF] - Installing certificates [CN=damn.ca:07/10/2021 20:28:46],[CN=Azure_IoT_Hub_Intermediate_Cert_Test_Only:07/10/2021 06:14:27],[CN=Azure_IoT_Hub_CA_Cert_Test_Only:07/10/2021 06:14:26] to Root <6> 2021-06-24 17:29:16.039 +00:00 [INF] - Installing certificates [CN=damn.ca:07/10/2021 20:28:46],[CN=Azure_IoT_Hub_Intermediate_Cert_Test_Only:07/10/2021 06:14:27],[CN=Azure_IoT_Hub_CA_Cert_Test_Only:07/10/2021 06:14:26],[CN=Azure_IoT_Hub_CA_Cert_Test_Only:07/10/2021 06:14:26] to Root <6> 2021-06-24 17:29:16.128 +00:00 [INF] - Enabling SSL protocols: Tls, Tls11, Tls12 <6> 2021-06-24 17:29:16.723 +00:00 [INF] - Experimental features configuration: {"Enabled":false,"DisableCloudSubscriptions":false,"DisableConnectivityCheck":false,"EnableMqttBroker":false} <6> 2021-06-24 17:29:19.124 +00:00 [INF] - Created persistent store at /tmp/edgeHub <6> 2021-06-24 17:29:19.378 +00:00 [INF] - Initializing Edge Hub <6> 2021-06-24 17:29:19.379 +00:00 [INF] - █████╗ ███████╗██╗ ██╗██████╗ ███████╗ ██╔══██╗╚══███╔╝██║ ██║██╔══██╗██╔════╝ ███████║ ███╔╝ ██║ ██║██████╔╝█████╗ ██╔══██║ ███╔╝ ██║ ██║██╔══██╗██╔══╝ ██║ ██║███████╗╚██████╔╝██║ ██║███████╗ ╚═╝ ╚═╝╚══════╝ ╚═════╝ ╚═╝ ╚═╝╚══════╝ ██╗ ██████╗ ████████╗ ███████╗██████╗ ██████╗ ███████╗ ██║██╔═══██╗╚══██╔══╝ ██╔════╝██╔══██╗██╔════╝ ██╔════╝ ██║██║ ██║ ██║ █████╗ ██║ ██║██║ ███╗█████╗ ██║██║ ██║ ██║ ██╔══╝ ██║ ██║██║ ██║██╔══╝ ██║╚██████╔╝ ██║ ███████╗██████╔╝╚██████╔╝███████╗ ╚═╝ ╚═════╝ ╚═╝ ╚══════╝╚═════╝ ╚═════╝ ╚══════╝ <6> 2021-06-24 17:29:19.388 +00:00 [INF] - Version - 1.2.1.43175312 (f0e7486e3fd527515999b9449313e55b733516c9) <6> 2021-06-24 17:29:19.389 +00:00 [INF] - OptimizeForPerformance=False <6> 2021-06-24 17:29:19.390 +00:00 [INF] - MessageAckTimeoutSecs=30 <6> 2021-06-24 17:29:19.397 +00:00 [INF] - Created device scope identities cache <6> 2021-06-24 17:29:19.394 +00:00 [INF] - Loaded server certificate with expiration date of "2021-07-10T20:28:46.0000000+00:00" <6> 2021-06-24 17:29:19.458 +00:00 [INF] - Using Asp Net server for metrics <6> 2021-06-24 17:29:19.476 +00:00 [INF] - Starting refresh of device scope identities cache <6> 2021-06-24 17:29:19.691 +00:00 [INF] - Started task to cleanup processed and stale messages <6> 2021-06-24 17:29:19.691 +00:00 [INF] - Created new message store <6> 2021-06-24 17:29:20.038 +00:00 [INF] - Created DeviceConnectivityManager with connected check frequency 00:05:00 and disconnected check frequency 00:02:00 <6> 2021-06-24 17:29:20.189 +00:00 [INF] - Initialized storing twin manager <6> 2021-06-24 17:29:20.281 +00:00 [INF] - Add node: dc:a6:32:55:90:cb/$edgeHub <6> 2021-06-24 17:29:20.282 +00:00 [INF] - Initializing configuration <6> 2021-06-24 17:29:20.365 +00:00 [INF] - New device connection for device dc:a6:32:55:90:cb/$edgeHub <6> 2021-06-24 17:29:20.422 +00:00 [INF] - Client dc:a6:32:55:90:cb/$edgeHub connected to edgeHub, processing existing subscriptions. <6> 2021-06-24 17:29:20.671 +00:00 [INF] - Attempting to connect to IoT Hub for client dc:a6:32:55:90:cb/$edgeHub via AMQP... <6> 2021-06-24 17:29:20.786 +00:00 [INF] - Processing pending subscriptions for dc:a6:32:55:90:cb/$edgeHub <6> 2021-06-24 17:29:22.015 +00:00 [INF] - Add node: mlilien-rpi3-2 <6> 2021-06-24 17:29:22.065 +00:00 [INF] - Experimental features configuration: {"Enabled":false,"DisableCloudSubscriptions":false,"DisableConnectivityCheck":false,"EnableMqttBroker":false} <6> 2021-06-24 17:29:22.206 +00:00 [INF] - Starting timer to authenticate connections with a period of 300 seconds <4> 2021-06-24 17:29:22.290 +00:00 [WRN] - Empty edge hub configuration received. Ignoring... <6> 2021-06-24 17:29:22.343 +00:00 [INF] - Add node: dc:a6:32:55:90:cb <6> 2021-06-24 17:29:22.461 +00:00 [INF] - Add node: dc:a6:32:55:90:cb/$edgeAgent <6> 2021-06-24 17:29:22.587 +00:00 [INF] - Updated node: dc:a6:32:55:90:cb/$edgeHub <6> 2021-06-24 17:29:22.590 +00:00 [INF] - Scheduling server certificate renewal for "2021-07-10T20:26:16.0008743Z". <6> 2021-06-24 17:29:22.709 +00:00 [INF] - Service identity for dc:a6:32:55:90:cb/$edgeHub in device scope was updated. <6> 2021-06-24 17:29:22.710 +00:00 [INF] - Add node: dc:a6:32:55:90:cb/AducIotAgent <6> 2021-06-24 17:29:22.823 +00:00 [INF] - Add node: dc:a6:32:55:90:cb/iot-module-template <6> 2021-06-24 17:29:22.934 +00:00 [INF] - Done refreshing device scope identities cache. Waiting for 60 minutes. <6> 2021-06-24 17:29:23.832 +00:00 [INF] - Exiting disconnected state <6> 2021-06-24 17:29:23.916 +00:00 [INF] - Received device connected callback <6> 2021-06-24 17:29:23.948 +00:00 [INF] - Device connected to cloud, processing subscriptions for connected clients. <6> 2021-06-24 17:29:23.958 +00:00 [INF] - Processing subscriptions for client dc:a6:32:55:90:cb/$edgeHub on device connected to cloud. <6> 2021-06-24 17:29:23.960 +00:00 [INF] - Skipping dc:a6:32:55:90:cb/$edgeHub for subscription processing, as it is currently being processed. <6> 2021-06-24 17:29:23.966 +00:00 [INF] - Skipping cache refresh, waiting 118 seconds until refreshing again. <6> 2021-06-24 17:29:24.015 +00:00 [INF] - Entering connected state <6> 2021-06-24 17:29:24.034 +00:00 [INF] - Cloud connection for dc:a6:32:55:90:cb/$edgeHub is True <6> 2021-06-24 17:29:24.050 +00:00 [INF] - Connection status for dc:a6:32:55:90:cb/$edgeHub changed to ConnectionEstablished <6> 2021-06-24 17:29:24.059 +00:00 [INF] - Client dc:a6:32:55:90:cb/$edgeHub connected to cloud, processing existing subscriptions. <6> 2021-06-24 17:29:24.060 +00:00 [INF] - Skipping dc:a6:32:55:90:cb/$edgeHub for subscription processing, as it is currently being processed. <6> 2021-06-24 17:29:24.071 +00:00 [INF] - Created cloud proxy for client dc:a6:32:55:90:cb/$edgeHub via AMQP, with client operation timeout 20 seconds. <6> 2021-06-24 17:29:24.094 +00:00 [INF] - Initialized cloud proxy caaa5fb7-de4d-4b1e-b519-2151c3d356ae for dc:a6:32:55:90:cb/$edgeHub <6> 2021-06-24 17:29:24.101 +00:00 [INF] - Created cloud connection for client dc:a6:32:55:90:cb/$edgeHub <6> 2021-06-24 17:29:24.788 +00:00 [INF] - Updated reported properties for dc:a6:32:55:90:cb/$edgeHub <6> 2021-06-24 17:29:24.789 +00:00 [INF] - Processing pending subscriptions for dc:a6:32:55:90:cb/$edgeHub <6> 2021-06-24 17:29:25.283 +00:00 [INF] - Done syncing reported properties for dc:a6:32:55:90:cb/$edgeHub <6> 2021-06-24 17:29:25.951 +00:00 [INF] - Created cloud endpoint iothub with max batch size 10 and fan-out factor of 10. <6> 2021-06-24 17:29:26.501 +00:00 [INF] - Obtained edge hub config from module twin <6> 2021-06-24 17:29:27.207 +00:00 [INF] - Set the following 1 route(s) in edge hub <6> 2021-06-24 17:29:27.208 +00:00 [INF] - route: FROM /messages/* INTO $upstream <6> 2021-06-24 17:29:27.217 +00:00 [INF] - Updated message store TTL to 60 seconds <6> 2021-06-24 17:29:27.220 +00:00 [INF] - Updated the edge hub store and forward configuration <6> 2021-06-24 17:29:27.260 +00:00 [INF] - Started operation Get EdgeHub config <6> 2021-06-24 17:29:27.261 +00:00 [INF] - Initialized edge hub configuration <6> 2021-06-24 17:29:27.268 +00:00 [INF] - Starting protocol heads - (MQTT, AMQP, HTTP) <6> 2021-06-24 17:29:27.283 +00:00 [INF] - Starting MQTT head <6> 2021-06-24 17:29:27.415 +00:00 [INF] - Initializing TLS endpoint on port 8883 for MQTT head. <6> 2021-06-24 17:29:27.721 +00:00 [INF] - Starting AMQP head <6> 2021-06-24 17:29:27.785 +00:00 [INF] - Started MQTT head <6> 2021-06-24 17:29:28.153 +00:00 [INF] - Started AMQP head <6> 2021-06-24 17:29:28.172 +00:00 [INF] - Starting HTTP head <4> 2021-06-24 17:29:29.166 +00:00 [WRN] - Overriding address(es) '"http://+:80"'. Binding to endpoints defined in "UseKestrel()" instead. <6> 2021-06-24 17:29:29.221 +00:00 [INF] - Started HTTP head <6> 2021-06-24 17:29:30.630 +00:00 [INF] - Updated reported properties for dc:a6:32:55:90:cb/$edgeHub <6> 2021-06-24 17:29:35.949 +00:00 [INF] - Client mlilien-rpi3-2 in device scope authenticated locally. <6> 2021-06-24 17:29:36.046 +00:00 [INF] - Successfully generated identity for clientId mlilien-rpi3-2 and username my-iothub.azure-devices.net/mlilien-rpi3-2/?api-version=2020-09-30&DeviceClientType=iothubclient%2f1.6.0%20(native%3b%20Linux%3b%20armv7l)&model-id=dtmi%3aAzureDeviceUpdate%3b1 <6> 2021-06-24 17:29:36.082 +00:00 [INF] - ClientAuthenticated, mlilien-rpi3-2, 5639586a <6> 2021-06-24 17:29:36.234 +00:00 [INF] - New device connection for device mlilien-rpi3-2 <6> 2021-06-24 17:29:36.238 +00:00 [INF] - Client mlilien-rpi3-2 connected to edgeHub, processing existing subscriptions. <6> 2021-06-24 17:29:36.325 +00:00 [INF] - Bind device proxy for device mlilien-rpi3-2 <6> 2021-06-24 17:29:36.329 +00:00 [INF] - Binding message channel for device Id mlilien-rpi3-2 <6> 2021-06-24 17:29:36.353 +00:00 [INF] - Attempting to connect to IoT Hub for client mlilien-rpi3-2 via AMQP with modelId dtmi:AzureDeviceUpdate;1... <6> 2021-06-24 17:29:36.578 +00:00 [INF] - Processing subscriptions TwinResponse for client mlilien-rpi3-2. <6> 2021-06-24 17:29:36.582 +00:00 [INF] - Processing pending subscriptions for mlilien-rpi3-2 <6> 2021-06-24 17:29:36.703 +00:00 [INF] - Set subscriptions from session state for mlilien-rpi3-2 <6> 2021-06-24 17:29:36.724 +00:00 [INF] - Cloud connection for mlilien-rpi3-2 is True <6> 2021-06-24 17:29:36.724 +00:00 [INF] - Connection status for mlilien-rpi3-2 changed to ConnectionEstablished <6> 2021-06-24 17:29:36.725 +00:00 [INF] - Client mlilien-rpi3-2 connected to cloud, processing existing subscriptions. <6> 2021-06-24 17:29:36.725 +00:00 [INF] - Skipping mlilien-rpi3-2 for subscription processing, as it is currently being processed. <6> 2021-06-24 17:29:36.725 +00:00 [INF] - Created cloud proxy for client mlilien-rpi3-2 via AMQP, with client operation timeout 20 seconds. <6> 2021-06-24 17:29:36.726 +00:00 [INF] - Initialized cloud proxy 8657fed4-6886-41a5-b670-a2e40686788b for mlilien-rpi3-2 <6> 2021-06-24 17:29:36.726 +00:00 [INF] - Created cloud connection for client mlilien-rpi3-2 <6> 2021-06-24 17:29:37.543 +00:00 [INF] - Processing subscriptions TwinResponse, DesiredPropertyUpdates for client mlilien-rpi3-2. <6> 2021-06-24 17:29:37.561 +00:00 [INF] - Processing pending subscriptions for mlilien-rpi3-2 <6> 2021-06-24 17:29:37.571 +00:00 [INF] - Set subscriptions from session state for mlilien-rpi3-2 <6> 2021-06-24 17:29:41.272 +00:00 [INF] - Updated reported properties for dc:a6:32:55:90:cb/$edgeHub <6> 2021-06-24 17:29:41.967 +00:00 [INF] - Updated reported properties for mlilien-rpi3-2 <6> 2021-06-24 17:30:27.154 +00:00 [INF] - Request starting HTTP/2 GET https://mlilien-rpi4/devices/mlilien-rpi3-2/modules?api-version=2017-11-08-preview <6> 2021-06-24 17:30:27.441 +00:00 [INF] - Executing endpoint '"Microsoft.Azure.Devices.Edge.Hub.Http.Controllers.RegistryController.ListModulesAsync (Microsoft.Azure.Devices.Edge.Hub.Http)"' <6> 2021-06-24 17:30:27.760 +00:00 [INF] - Route matched with "{action = \"ListModules\", controller = \"Registry\"}". Executing controller action with signature "System.Threading.Tasks.Task ListModulesAsync(System.String)" on controller "Microsoft.Azure.Devices.Edge.Hub.Http.Controllers.RegistryController" ("Microsoft.Azure.Devices.Edge.Hub.Http"). <6> 2021-06-24 17:30:27.868 +00:00 [INF] - Received request in ListModulesAsync: deviceId=mlilien-rpi3-2, moduleId= <6> 2021-06-24 17:30:27.945 +00:00 [INF] - Client mlilien-rpi3-2 in device scope authenticated locally. <6> 2021-06-24 17:30:27.963 +00:00 [INF] - Authenticated: deviceId=mlilien-rpi3-2, moduleId= <6> 2021-06-24 17:30:28.280 +00:00 [INF] - CompleteRequest in ListModulesAsync: deviceId=dc:a6:32:55:90:cb, authChain=mlilien-rpi3-2;dc:a6:32:55:90:cb, status=Unauthorized <6> 2021-06-24 17:30:28.348 +00:00 [INF] - Executed action "Microsoft.Azure.Devices.Edge.Hub.Http.Controllers.RegistryController.ListModulesAsync (Microsoft.Azure.Devices.Edge.Hub.Http)" in 545.4579ms <6> 2021-06-24 17:30:28.355 +00:00 [INF] - Executed endpoint '"Microsoft.Azure.Devices.Edge.Hub.Http.Controllers.RegistryController.ListModulesAsync (Microsoft.Azure.Devices.Edge.Hub.Http)"' <6> 2021-06-24 17:30:28.387 +00:00 [INF] - Request finished in 1238.0804ms 401 application/json; charset=utf-8 ```identity principal configuration
``` adu.toml: [[principal]] uid = 987 name = "AducIotAgent" idtype = ["module"] iot-module-template.toml: [[principal]] uid = 988 name = "iot-module-template" idtype = ["module"] ```