Iotedge: Calling direct method throws unexpected IotHubCommunicationExceptions

[mill5james]

I was trying to measure the maximum throughput I could expect using direct messages vs messages with routing.

I have two simple edge modules:

• Producer - Registers a direct method handler
• Consumer - Calls the direct method on the producer in a tight loop

All code is available in my GitHub repo here:
mill5james/IoTEdgeMethodVsMessage

And the images are published in Docker Hub at mill5james

Expected Behavior

I would expect that I could call direct methods between modules as often as I needed bounded only by the constraints of the deployment environment.

Current Behavior

Intermittently I see an IotHubCommunicationException with the message "The SSL connection could not be established, see inner exception." when calling ModuleClient.InvokeMethodAsync. The module recovers and subsequent calls succeed.

IotHubCommunicationException - The SSL connection could not be established, see inner exception.
Inner exception HttpRequestException - The SSL connection could not be established, see inner exception.
   at Microsoft.Azure.Devices.Client.Transport.HttpClientHelper.ExecuteAsync(HttpMethod httpMethod, Uri requestUri, Func`3 modifyRequestMessageAsync, Func`2 isSuccessful, Func`3 processResponseMessageAsync, IDictionary`2 errorMappingOverrides, CancellationToken cancellationToken)
   at Microsoft.Azure.Devices.Client.Transport.HttpClientHelper.PostAsync[T1,T2](Uri requestUri, T1 entity, IDictionary`2 errorMappingOverrides, IDictionary`2 customHeaders, CancellationToken cancellationToken)
   at Microsoft.Azure.Devices.Client.ModuleClient.InvokeMethodAsync(Uri uri, MethodRequest methodRequest, CancellationToken cancellationToken)
   at IoTEdge.Consumer.GetTimeMethod(ModuleClient moduleClient, CancellationToken cancellationToken) in /src/Consumer/Consumer.cs:line 64

After running for some time, I eventually see an IotHubCommunicationException with the message "Address already in use" when calling ModuleClient.InvokeMethodAsync. Once we receive this exception, the module never recovers and every subsequent call returns the same exception. The module need to be restarted with iotedge restart consumer to return to operation.

IotHubCommunicationException - Address already in use
Inner exception HttpRequestException - Address already in use
   at Microsoft.Azure.Devices.Client.Transport.HttpClientHelper.ExecuteAsync(HttpMethod httpMethod, Uri requestUri, Func`3 modifyRequestMessageAsync, Func`2 isSuccessful, Func`3 processResponseMessageAsync, IDictionary`2 errorMappingOverrides, CancellationToken cancellationToken)
   at Microsoft.Azure.Devices.Client.Transport.HttpClientHelper.PostAsync[T1,T2](Uri requestUri, T1 entity, IDictionary`2 errorMappingOverrides, IDictionary`2 customHeaders, CancellationToken cancellationToken)
   at Microsoft.Azure.Devices.Client.ModuleClient.InvokeMethodAsync(Uri uri, MethodRequest methodRequest, CancellationToken cancellationToken)
   at IoTEdge.Consumer.GetTimeMethod(ModuleClient moduleClient, CancellationToken cancellationToken) in /src/Consumer/Consumer.cs:line 64

Steps to Reproduce

1. Download the deployment.json from my IoTEdgeMethodVsMessage GitHub repo
2. Modify the deployment.json for the consumer to only enable direct methods by setting the EnableMethod to true and the EnableMessage to false

    "consumer": {
        "settings": {
            "image": "mill5james/consumer:latest",
            "createOptions": "{}"
        },
        "type": "docker",
        "env": {
            "EnableMethod": {
                "value": "true"
            },
            "EnableMessage": {
                "value": "false"
            }
        },
        "version": "1.0",
        "status": "running",
        "restartPolicy": "always"
    }

1. Use the modified deployment.json to deploy to an IoT Edge device
2. Observe the logs for the consumer module on the edge to see the exceptions being thrown in the module

Context (Environment)

Output of iotedge check

iotedge check

Configuration checks
--------------------
√ config.yaml is well-formed
√ config.yaml has well-formed connection string
√ container engine is installed and functional
√ config.yaml has correct hostname
√ config.yaml has correct URIs for daemon mgmt endpoint
√ latest security daemon
√ host time is close to real time
√ container time is close to host time
‼ DNS server
    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: certificates
    Device is using self-signed, automatically generated certs.
    Please see https://aka.ms/iotedge-prod-checklist-certs for best practices.
√ production readiness: certificates expiry
√ production readiness: container engine
‼ production readiness: logs policy
    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.

Connectivity checks
-------------------
√ host can connect to and perform TLS handshake with IoT Hub AMQP port
√ host can connect to and perform TLS handshake with IoT Hub HTTPS port
√ host can connect to and perform TLS handshake with IoT Hub MQTT port
√ container on the default network can connect to IoT Hub AMQP port
√ container on the default network can connect to IoT Hub HTTPS port
√ container on the default network can connect to IoT Hub MQTT port
√ container on the IoT Edge module network can connect to IoT Hub AMQP port
√ container on the IoT Edge module network can connect to IoT Hub HTTPS port
√ container on the IoT Edge module network can connect to IoT Hub MQTT port
√ Edge Hub can bind to ports on host```

Device (Host) Operating System

Ubuntu 18.04 LTS

Architecture

amd64

Container Operating System

Linux containers

Runtime Versions

iotedged

iotedge 1.0.7.1 (f7c51d92be8336bc6be042e1f1f2505ba01679f3)

Edge Agent

mcr.microsoft.com/azureiotedge-agent:1.0
Version - 1.0.7.1.22377503 (f7c51d92be8336bc6be042e1f1f2505ba01679f3)

Edge Hub

mcr.microsoft.com/azureiotedge-hub:1.0
Version - 1.0.7.1.22377503 (f7c51d92be8336bc6be042e1f1f2505ba01679f3)

Docker

Docker version

Client:
 Version:           3.0.5
 API version:       1.40
 Go version:        go1.12.1
 Git commit:        ba9934d4
 Built:             Thu Apr 18 22:01:41 2019
 OS/Arch:           linux/amd64
 Experimental:      false

Server:
 Engine:
  Version:          3.0.5
  API version:      1.40 (minimum version 1.12)
  Go version:       go1.12.1
  Git commit:       dbe4a30
  Built:            Thu Apr 18 22:07:58 2019
  OS/Arch:          linux/amd64
  Experimental:     false
 containerd:
  Version:          v1.2.5
  GitCommit:        bb71b10fd8f58240ca47fbb579b9d1028eea7c84
 runc:
  Version:          1.0.0-rc6+dev
  GitCommit:        2b18fe1d885ee5083ef9f0838fee39b62d653e30
 docker-init:
  Version:          0.18.0
  GitCommit:        fec3683

Logs

iotedged logs

<Paste here>

edge-agent logs

<Paste here>

edge-hub logs

<Paste here>

Additional Information

[ancaantochi]

Thanks for reporting this issue, I will investigate and update here.

I think "Address already in use" is because that a new HttpClient is created with every direct method call and is exhausting available sockets.

[github-actions[bot]]

This issue is being marked as stale because it has been open for 30 days with no activity.

[lt72]

@mill5james we fixed a similar issue with latest 1.0.8 release. Can you please give it a try and re-open this issue as needed?