Edge module with "ExposedPorts" create option fails to start

[Time0o]

I'm trying to start an IoT edge module (an MQTT broker) with the following create options:

{
  "ExposedPorts": {
    "1883/tcp": {}
  },
  "HostConfig": {
    "PortBindings": {
      "1883/tcp": [
        {
          "HostPort": "1883"
        }
      ]
    }
  }
}

Expected Behavior

The module starts and runs normally.

Current Behavior

The module does not start, edgeAgent logs show:

Microsoft.Azure.Devices.Edge.Agent.Edgelet.EdgeletCommunicationException- Message:Error calling start module MqttBroker: runtime operation error: start module "MqttBroker", StatusCode:500

And iotedge list shows the module's status as "stopped".

Note that when I do not specify "ExposedPorts", the broker runs as expected.

Steps to Reproduce

I cannot share the source code or image of my module but in deployment.template.json I have the following (leaving out "image"):

        "modules": {
          "MqttBroker": {
            "version": "1.0",
            "type": "docker",
            "status": "running",
            "restartPolicy": "always",
            "settings": {
              "image": "...",
              "createOptions": "{\"ExposedPorts\":{\"1883/tcp\": {}},\"HostConfig\":{\"PortBindings\":{\"1883/tcp\":[{\"HostPort\":\"1883\"}]}}}"
            }
          }
        }

When I deploy this to my edge device with az iot edge set-modules the problem manifests.

Context (Environment)

Output of iotedge check

Click 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
√ identityd is running - OK
√ read all preloaded certificates from the Certificates Service - OK
√ read all preloaded key pairs from the Keys Service - OK
√ check all EST server URLs utilize HTTPS - 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 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
31 check(s) succeeded.
4 check(s) raised warnings. Re-run with --verbose for more details.
2 check(s) were skipped due to errors from other checks. Re-run with --verbose for more details.

Device Information

• Host OS: Ubuntu 22.04.3 LTS
• Architecture: amd64
• Container OS: Linux Containers

Runtime Versions

• aziot-edged: 1.4.20
• Edge Agent: 1.2
• Edge Hub: 1.2
• Docker/Moby; 23.0.7+azure-1

Logs

edge-agent logs

  [Start module MqttBroker]
  [Saving MqttBroker to store]
). Will retry in 00s.
<6> 2023-10-24 14:09:42.895 +00:00 [INF] - Plan execution ended for deployment 12
<3> 2023-10-24 14:09:42.895 +00:00 [ERR] - Edge agent plan execution failed.
System.AggregateException: One or more errors occurred. (Error calling start module MqttBroker: runtime operation error: start module "MqttBroker")
 ---> Microsoft.Azure.Devices.Edge.Agent.Edgelet.EdgeletCommunicationException- Message:Error calling start module MqttBroker: runtime operation error: start module "MqttBroker", StatusCode:500, at:   at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Version_2021_12_07.ModuleManagementHttpClient.HandleException(Exception exception, String operation) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/version_2021_12_07/ModuleManagementHttpClient.cs:line 232
   at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Versioning.ModuleManagementHttpClientVersioned.Execute[T](Func`1 func, String operation) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/versioning/ModuleManagementHttpClientVersioned.cs:line 155
   at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Version_2021_12_07.ModuleManagementHttpClient.StartModuleAsync(String name) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/version_2021_12_07/ModuleManagementHttpClient.cs:line 180
   at Microsoft.Azure.Devices.Edge.Agent.Edgelet.ModuleManagementHttpClient.<>c__DisplayClass26_0.<<Throttle>b__0>d.MoveNext() in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/ModuleManagementHttpClient.cs:line 140
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.Azure.Devices.Edge.Agent.Edgelet.ModuleManagementHttpClient.Throttle[T](Func`1 identityOperation) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/ModuleManagementHttpClient.cs:line 159
   at Microsoft.Azure.Devices.Edge.Agent.Core.LoggingCommandFactory.LoggingCommand.ExecuteAsync(CancellationToken token) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Core/LoggingCommandFactory.cs:line 67
   at Microsoft.Azure.Devices.Edge.Agent.Core.Commands.GroupCommand.ExecuteAsync(CancellationToken token) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Core/commands/GroupCommand.cs:line 35
   at Microsoft.Azure.Devices.Edge.Agent.Core.LoggingCommandFactory.LoggingCommand.ExecuteAsync(CancellationToken token) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Core/LoggingCommandFactory.cs:line 67
   at Microsoft.Azure.Devices.Edge.Agent.Core.PlanRunners.OrderedRetryPlanRunner.ExecuteAsync(Int64 deploymentId, Plan plan, CancellationToken token) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Core/planrunners/OrdererdRetryPlanRunner.cs:line 87
   --- End of inner exception stack trace ---
   at Microsoft.Azure.Devices.Edge.Agent.Core.PlanRunners.OrderedRetryPlanRunner.<>c.<ExecuteAsync>b__7_0(List`1 f) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Core/planrunners/OrdererdRetryPlanRunner.cs:line 115
   at Microsoft.Azure.Devices.Edge.Agent.Core.PlanRunners.OrderedRetryPlanRunner.ExecuteAsync(Int64 deploymentId, Plan plan, CancellationToken token) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Core/planrunners/OrdererdRetryPlanRunner.cs:line 116
   at Microsoft.Azure.Devices.Edge.Agent.Core.Agent.ReconcileAsync(CancellationToken token) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Core/Agent.cs:line 208
<4> 2023-10-24 14:09:42.908 +00:00 [WRN] - Reconcile failed because of the an exception
System.AggregateException: One or more errors occurred. (Error calling start module MqttBroker: runtime operation error: start module "MqttBroker")
 ---> Microsoft.Azure.Devices.Edge.Agent.Edgelet.EdgeletCommunicationException- Message:Error calling start module MqttBroker: runtime operation error: start module "MqttBroker", StatusCode:500, at:   at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Version_2021_12_07.ModuleManagementHttpClient.HandleException(Exception exception, String operation) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/version_2021_12_07/ModuleManagementHttpClient.cs:line 232
   at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Versioning.ModuleManagementHttpClientVersioned.Execute[T](Func`1 func, String operation) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/versioning/ModuleManagementHttpClientVersioned.cs:line 155
   at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Version_2021_12_07.ModuleManagementHttpClient.StartModuleAsync(String name) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/version_2021_12_07/ModuleManagementHttpClient.cs:line 180
   at Microsoft.Azure.Devices.Edge.Agent.Edgelet.ModuleManagementHttpClient.<>c__DisplayClass26_0.<<Throttle>b__0>d.MoveNext() in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/ModuleManagementHttpClient.cs:line 140
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.Azure.Devices.Edge.Agent.Edgelet.ModuleManagementHttpClient.Throttle[T](Func`1 identityOperation) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/ModuleManagementHttpClient.cs:line 159
   at Microsoft.Azure.Devices.Edge.Agent.Core.LoggingCommandFactory.LoggingCommand.ExecuteAsync(CancellationToken token) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Core/LoggingCommandFactory.cs:line 67
   at Microsoft.Azure.Devices.Edge.Agent.Core.Commands.GroupCommand.ExecuteAsync(CancellationToken token) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Core/commands/GroupCommand.cs:line 35
   at Microsoft.Azure.Devices.Edge.Agent.Core.LoggingCommandFactory.LoggingCommand.ExecuteAsync(CancellationToken token) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Core/LoggingCommandFactory.cs:line 67
   at Microsoft.Azure.Devices.Edge.Agent.Core.PlanRunners.OrderedRetryPlanRunner.ExecuteAsync(Int64 deploymentId, Plan plan, CancellationToken token) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Core/planrunners/OrdererdRetryPlanRunner.cs:line 87
   --- End of inner exception stack trace ---
   at Microsoft.Azure.Devices.Edge.Agent.Core.PlanRunners.OrderedRetryPlanRunner.<>c.<ExecuteAsync>b__7_0(List`1 f) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Core/planrunners/OrdererdRetryPlanRunner.cs:line 115
   at Microsoft.Azure.Devices.Edge.Agent.Core.PlanRunners.OrderedRetryPlanRunner.ExecuteAsync(Int64 deploymentId, Plan plan, CancellationToken token) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Core/planrunners/OrdererdRetryPlanRunner.cs:line 116
   at Microsoft.Azure.Devices.Edge.Agent.Core.Agent.ReconcileAsync(CancellationToken token) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Core/Agent.cs:line 208
   at Microsoft.Azure.Devices.Edge.Agent.Core.Agent.ReconcileAsync(CancellationToken token) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Core/Agent.cs:line 208
<6> 2023-10-24 14:09:47.922 +00:00 [INF] - Plan execution started for deployment 12
<6> 2023-10-24 14:09:47.922 +00:00 [INF] - Executing command: "Command Group: (\n  [Stop module MqttBroker]\n  [Start module MqttBroker]\n  [Saving MqttBroker to store]\n)"
<6> 2023-10-24 14:09:47.922 +00:00 [INF] - Executing command: "Stop module MqttBroker"
<6> 2023-10-24 14:09:47.923 +00:00 [INF] - Executing command: "Start module MqttBroker"

[ggjjj]

"This error can happen for example if the host machine already uses 1883. You can double check this looking at the docker logs, if the port is used on the host, you would see a similar error message:

journalctl -u docker.service

ct 25 11:10:21 srv1 dockerd[1699]: time="2023-10-25T11:10:21.742171007-07:00" level=error msg="Handler for POST /containers/SimulatedTemperatureSensor/start returned error: driver failed programming external connectivity on endpoint SimulatedTemperatureSensor (9a0a27144c66348477d881d19777645f2fa7a1994aa18bdda1f5>
Oct 25 11:10:26 srv1 dockerd[1699]: time="2023-10-25T11:10:26.812625942-07:00" level=warning msg="Failed to allocate and map port 1883-1883: Error starting userland proxy: listen tcp4 0.0.0.0:1883: bind: address already in use"

You can try stopping the service on the host that listens on 1883 (e.g. a mosquitto instance running as a service), or use an available port, e.g. 1884"

[Time0o]

@ggjjj I did indeed have an instance of mosquitto running, after stopping it everything works as expected. Thank you very much.