Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Azure IoT Edge runtime does not handle DPS based provisioning correctly when device is initially rejected - Failed to clear provisioning cache before reprovision #7411

Open
aleupo opened this issue Jan 16, 2025 · 2 comments
Assignees

Comments

@aleupo
Copy link

aleupo commented Jan 16, 2025

We are using Azure IoT Edge on an Embedded Linux device. For the provisioning of the devices, we are using DPS with X.509 based bootstrap certificates and group enrolments. For our application, the device has to be registered in our backend before it is allowed to connect to the IoT Hub. Depending on the registration state, the DPS will either accept the device (status code 200) or reject it (status code 400). To check the registration state of the devices, we are using the DPS custom allocation function. Rejected devices will try again endlessly until they have been registered and are accepted by the DPS.

For the case that the device is accepted upon first attempt at the DPS, everything works as intended. (I.e. it has been registered in the backend before the first connection attempt)

For the case that the device is first rejected and then accepted later, we are observing faulty behaviour in some cases (seemingly random). After being rejected initially, and then receiving 200 from the DPS, the Edge runtime will go into a faulty state where it does not recover. It mainly revolves around the edged reporting the error Failed to clear provisioning cache before reprovision: No such file or directory. From our understanding, edged triggers a reprovisioning at identityd, when it should not. Then identityd cannot recover from this.

Expected Behavior

  • The device attempts to connect to the DPS, gets rejected with status code 400
  • The device will retry every 10 seconds until it gets status code 200 from the DPS
  • Once the DPS replies with 200, the device is provisioned correctly, can connect to the assigned IoT Hub and receive a deployment manifest.

Current Behavior

  • The device attempts to connect to the DPS, gets rejected with status code 400
  • At a later point in time, the DPS responds with status code 200
  • Sometimes the provisioning is successful und correctly applied at the device
  • Sometimes the provisioning is successful but the Edge runtime fails to apply it correctly
    • After receiving 200 from the DPS, provisioning seems to be successful
    • However, the identityd starts to reprovision
    • identityd enters a state that it can not recover from

So, after receiving 200 from the DPS, provisioning is triggered again.

Note 1: We can see that the provisioning was successfully initially, because the device will show up in the IoT Hub with the registration id we have provided.

Note 2: After the "200" reply from the DPS, the DPS will respond to further requests with "400" again. You can see it in the logs below. We are currently not sure if this behaviour is correct, it may be the result of how our custom allocation function is implemented. We are investigating this separately. However, it should not be the case that provisioning is re-triggered immediately on the device.

Context

Configuration File

Click here
# ==============================================================================
# Provisioning
# ==============================================================================
[provisioning]
global_endpoint = "https://global.azure-devices-provisioning.net/"
id_scope = "0neXXXXX"
source = "dps"

payload = { uri = "file:///etc/aziot/payload.json" }

[provisioning.attestation]
method = "x509"
registration_id = "XXXXXXXX-XXXX-XXXX-XXXX-XXXXXXXX_3002114328"

[provisioning.attestation.identity_cert]
common_name = "bootstrap" # Needs to be changed once production PKI is in place.
method = "est"

[provisioning.attestation.identity_cert.auto_renew]
retry = "4%"
rotate_key = false
threshold = "80%"

# ==============================================================================
# Cert issuance
# ==============================================================================

[cert_issuance.est]
trusted_certs = [ "file:///var/lib/aziot/certd/certs/cacert.crt.pem" ]

[cert_issuance.est.auth]
bootstrap_identity_cert = "file:///var/lib/aziot/certd/certs/est_bootstrap_id_cert.pem"
bootstrap_identity_pk = "pkcs11:token=azure-keys;object=bootstrap-id?pin-value=XXXX"

[cert_issuance.est.urls]
default = "https://est-server.XXXXX.com:443/.well-known/est"

# ==============================================================================
# PKCS#11
# ==============================================================================

[aziot_keys]
pkcs11_base_slot = "pkcs11:token=azure-keys?pin-value=XXXX"
pkcs11_lib_path = "/usr/lib/pkcs11/libtpm2_pkcs11.so"

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 - Warning
    Installed aziot-identity-service package has version 1.5.0 but 1.5.4 is the latest stable version available.
    Please see https://aka.ms/aziot-update-runtime for update instructions.
√ host time is close to reference time - OK
√ production readiness: identity certificates expiry - OK
√ production readiness: EST identity and bootstrap certificates expiry - 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 - Error
    could not load cert with ID "aziot-edged-trust-bundle"

    Caused by:
        parameter "id" has an invalid value
        caused by: not found
√ 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 - 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.5.5' locally
    1.5.5: Pulling from azureiotedge-diagnostics
    690e87867337: Pulling fs layer
    70c31a4d62b2: Pulling fs layer
    758379060b9e: Pulling fs layer
    a7f84bd7cae8: Pulling fs layer
    3f4b5df2ce96: Pulling fs layer
    4af25baa950c: Pulling fs layer
    3f4b5df2ce96: Waiting
    a7f84bd7cae8: Waiting
    4af25baa950c: Waiting
    758379060b9e: Download complete
    70c31a4d62b2: Verifying Checksum
    70c31a4d62b2: Download complete
    690e87867337: Verifying Checksum
    690e87867337: Download complete
    3f4b5df2ce96: Verifying Checksum
    3f4b5df2ce96: Download complete
    4af25baa950c: Verifying Checksum
    4af25baa950c: Download complete
    a7f84bd7cae8: Verifying Checksum
    a7f84bd7cae8: Download complete
    690e87867337: Pull complete
    70c31a4d62b2: Pull complete
    758379060b9e: Pull complete
    a7f84bd7cae8: Pull complete
    3f4b5df2ce96: Pull complete
    4af25baa950c: Pull complete
    Digest: sha256:4586732e1a12401c6b7d2b60a13e1969623bd99cecb12becedbbe2bceb541ae6
    Status: Downloaded newer image for mcr.microsoft.com/azureiotedge-diagnostics:1.5.5
    SocketError - SocketErrorCode (TimedOut) : Operation timed out
    One or more errors occurred. (Got bad response: )
‼ aziot-edge package is up-to-date - Warning
    Installed IoT Edge daemon has version 1.5.5 but 1.5.4 is the latest stable version available.
    Please see https://aka.ms/iotedge-update-runtime for update instructions.
√ 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 - Error
    Could not check current state of edgeAgent container
× production readiness: Edge Hub's storage directory is persisted on the host filesystem - Error
    Could not check current state of edgeHub container
√ proxy settings are consistent in aziot-edged, aziot-identityd, moby daemon and config.toml - OK

Connectivity checks
-------------------
22 check(s) succeeded.
7 check(s) raised warnings. Re-run with --verbose for more details.
4 check(s) raised errors. Re-run with --verbose for more details.
7 check(s) were skipped due to errors from other checks. Re-run with --verbose for more details.

Device Information

  • Host OS: Yocto Based Embedded Linux (Kirkstone)
  • Architecture: arm64
  • Container OS: Linux containers

Runtime Versions

  • aziot-edged [run iotedge version]: iotedge 1.5.5
  • Edge Agent [image tag]: 1.4 (needs to be updated)
  • Edge Hub [image tag]: 1.4 (needs to be updated)
  • Docker/Moby [run docker version]: 20.10.21

Logs

iotedge system logs (info level)
Jan 16 10:05:27 gateway-3002114328 systemd[1]: Started Azure IoT Edge daemon.
Jan 16 10:05:27 gateway-3002114328 aziot-edged[4834]: 2025-01-16T10:05:27Z [INFO] - Starting Azure IoT Edge Daemon
Jan 16 10:05:27 gateway-3002114328 aziot-edged[4834]: 2025-01-16T10:05:27Z [INFO] - Version - 1.5.5
Jan 16 10:05:27 gateway-3002114328 aziot-edged[4834]: 2025-01-16T10:05:27Z [INFO] - Obtaining Edge device provisioning data...
Jan 16 10:05:27 gateway-3002114328 systemd[1]: Started Azure IoT Identity Service.
Jan 16 10:05:27 gateway-3002114328 aziot-identityd[4839]: 2025-01-16T10:05:27Z [INFO] - Starting service...
Jan 16 10:05:27 gateway-3002114328 aziot-identityd[4839]: 2025-01-16T10:05:27Z [INFO] - Version - dev build
Jan 16 10:05:27 gateway-3002114328 aziot-identityd[4839]: 2025-01-16T10:05:27Z [INFO] - Loaded openssl'd Default provider
Jan 16 10:05:27 gateway-3002114328 systemd[1]: Started Azure IoT Certificates Service.
Jan 16 10:05:27 gateway-3002114328 aziot-certd[4844]: 2025-01-16T10:05:27Z [INFO] - Starting service...
Jan 16 10:05:27 gateway-3002114328 aziot-certd[4844]: 2025-01-16T10:05:27Z [INFO] - Version - dev build
Jan 16 10:05:27 gateway-3002114328 aziot-certd[4844]: 2025-01-16T10:05:27Z [INFO] - Starting server...
Jan 16 10:05:27 gateway-3002114328 aziot-certd[4844]: 2025-01-16T10:05:27Z [INFO] - <-- GET /certificates/device-id?api-version=2020-09-01 {"host": "certd.sock"}
Jan 16 10:05:27 gateway-3002114328 aziot-certd[4844]: 2025-01-16T10:05:27Z [INFO] - !!! parameter "id" has an invalid value
Jan 16 10:05:27 gateway-3002114328 aziot-certd[4844]: 2025-01-16T10:05:27Z [INFO] - !!! caused by: not found
Jan 16 10:05:27 gateway-3002114328 aziot-certd[4844]: 2025-01-16T10:05:27Z [INFO] - --> 400 {"content-type": "application/json"}
Jan 16 10:05:27 gateway-3002114328 systemd[1]: Started Azure IoT Keys Service.
Jan 16 10:05:27 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:27Z [INFO] - Starting service...
Jan 16 10:05:27 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:27Z [INFO] - Version - dev build
Jan 16 10:05:27 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:27Z [INFO] - Loaded libaziot-keys with version 0x02010000
Jan 16 10:05:27 gateway-3002114328 aziot-keyd[4854]: WARNING: Getting tokens from fapi backend failed.
Jan 16 10:05:28 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:28Z [INFO] - Starting server...
Jan 16 10:05:28 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:28Z [INFO] - <-- GET /keypair/device-id?api-version=2021-05-01 {"host": "keyd.sock"}
Jan 16 10:05:28 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:28Z [ERR!] - invalid parameter "id": not found
Jan 16 10:05:28 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:28Z [INFO] - !!! a parameter has an invalid value
Jan 16 10:05:29 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:28Z [INFO] - --> 400 {"content-type": "application/json"}
Jan 16 10:05:29 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:29Z [INFO] - <-- POST /keypair?api-version=2021-05-01 {"content-type": "application/json", "host": "keyd.sock", "content-length": "56"}
Jan 16 10:05:29 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:29Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:05:29 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:29Z [INFO] - <-- POST /parameters/algorithm?api-version=2021-05-01 {"content-length": "248", "content-type": "application/json"}
Jan 16 10:05:29 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:29Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:05:29 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:29Z [INFO] - <-- POST /parameters/rsa-modulus?api-version=2021-05-01 {"content-length": "248", "content-type": "application/json"}
Jan 16 10:05:29 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:29Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:05:29 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:29Z [INFO] - <-- POST /parameters/rsa-exponent?api-version=2021-05-01 {"content-length": "248", "content-type": "application/json"}
Jan 16 10:05:29 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:29Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:05:29 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:29Z [INFO] - <-- POST /parameters/algorithm?api-version=2021-05-01 {"content-length": "248", "content-type": "application/json"}
Jan 16 10:05:29 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:29Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:05:29 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:29Z [INFO] - <-- POST /parameters/rsa-modulus?api-version=2021-05-01 {"content-length": "248", "content-type": "application/json"}
Jan 16 10:05:29 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:29Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:05:29 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:29Z [INFO] - <-- POST /parameters/rsa-exponent?api-version=2021-05-01 {"content-length": "248", "content-type": "application/json"}
Jan 16 10:05:29 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:29Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:05:29 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:29Z [INFO] - <-- POST /encrypt?api-version=2021-05-01 {"content-length": "355", "content-type": "application/json"}
Jan 16 10:05:31 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:31Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:05:31 gateway-3002114328 aziot-certd[4844]: 2025-01-16T10:05:31Z [INFO] - <-- POST /certificates?api-version=2020-09-01 {"content-type": "application/json", "host": "certd.sock", "content-length": "1005"}
Jan 16 10:05:31 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:31Z [INFO] - <-- GET /keypair/est-bootstrap-id?api-version=2021-05-01 {"host": "keyd.sock"}
Jan 16 10:05:31 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:31Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:05:31 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:31Z [INFO] - <-- POST /parameters/algorithm?api-version=2021-05-01 {"content-length": "256", "content-type": "application/json"}
Jan 16 10:05:31 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:31Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:05:31 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:31Z [INFO] - <-- POST /parameters/rsa-modulus?api-version=2021-05-01 {"content-length": "256", "content-type": "application/json"}
Jan 16 10:05:31 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:31Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:05:31 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:31Z [INFO] - <-- POST /parameters/rsa-exponent?api-version=2021-05-01 {"content-length": "256", "content-type": "application/json"}
Jan 16 10:05:31 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:31Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:05:31 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:31Z [INFO] - <-- GET /keypair/est-id?api-version=2021-05-01 {"host": "keyd.sock"}
Jan 16 10:05:31 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:31Z [ERR!] - invalid parameter "id": not found
Jan 16 10:05:31 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:31Z [INFO] - !!! a parameter has an invalid value
Jan 16 10:05:31 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:31Z [INFO] - --> 400 {"content-type": "application/json"}
Jan 16 10:05:31 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:31Z [INFO] - <-- POST /keypair?api-version=2021-05-01 {"content-type": "application/json", "host": "keyd.sock", "content-length": "61"}
Jan 16 10:05:31 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:31Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:05:31 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:31Z [INFO] - <-- POST /parameters/algorithm?api-version=2021-05-01 {"content-length": "244", "content-type": "application/json"}
Jan 16 10:05:31 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:31Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:05:31 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:31Z [INFO] - <-- POST /parameters/ec-curve-oid?api-version=2021-05-01 {"content-length": "244", "content-type": "application/json"}
Jan 16 10:05:31 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:31Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:05:31 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:31Z [INFO] - <-- POST /parameters/ec-point?api-version=2021-05-01 {"content-length": "244", "content-type": "application/json"}
Jan 16 10:05:31 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:31Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:05:31 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:31Z [INFO] - <-- POST /parameters/algorithm?api-version=2021-05-01 {"content-length": "244", "content-type": "application/json"}
Jan 16 10:05:31 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:31Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:05:31 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:31Z [INFO] - <-- POST /parameters/ec-curve-oid?api-version=2021-05-01 {"content-length": "244", "content-type": "application/json"}
Jan 16 10:05:31 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:31Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:05:31 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:31Z [INFO] - <-- POST /parameters/ec-point?api-version=2021-05-01 {"content-length": "244", "content-type": "application/json"}
Jan 16 10:05:31 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:31Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:05:31 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:31Z [INFO] - <-- POST /sign?api-version=2021-05-01 {"content-length": "335", "content-type": "application/json"}
Jan 16 10:05:32 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:32Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:05:32 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:32Z [INFO] - <-- POST /encrypt?api-version=2021-05-01 {"content-length": "644", "content-type": "application/json"}
Jan 16 10:05:34 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:34Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:05:34 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:34Z [INFO] - <-- POST /encrypt?api-version=2021-05-01 {"content-length": "644", "content-type": "application/json"}
Jan 16 10:05:35 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:35Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:05:35 gateway-3002114328 aziot-certd[4844]: 2025-01-16T10:05:35Z [INFO] - Certificate est-id will be auto-renewed. Next renewal at 2025-11-04T10:05:35+00:00.
Jan 16 10:05:35 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:35Z [INFO] - <-- POST /sign?api-version=2021-05-01 {"content-length": "335", "content-type": "application/json"}
Jan 16 10:05:36 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:36Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:05:36 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:36Z [INFO] - <-- POST /sign?api-version=2021-05-01 {"content-length": "335", "content-type": "application/json"}
Jan 16 10:05:37 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:37Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:05:37 gateway-3002114328 aziot-certd[4844]: 2025-01-16T10:05:37Z [INFO] - --> 201 {"content-type": "application/json"}
Jan 16 10:05:37 gateway-3002114328 aziot-identityd[4839]: 2025-01-16T10:05:37Z [INFO] - Generated initial device identity certificate.
Jan 16 10:05:37 gateway-3002114328 aziot-certd[4844]: 2025-01-16T10:05:37Z [INFO] - <-- GET /certificates/device-id?api-version=2020-09-01 {"host": "certd.sock"}
Jan 16 10:05:37 gateway-3002114328 aziot-certd[4844]: 2025-01-16T10:05:37Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:05:37 gateway-3002114328 aziot-identityd[4839]: 2025-01-16T10:05:37Z [INFO] - Certificate device-id will be auto-renewed. Next renewal at 2025-11-04T10:05:37+00:00.
Jan 16 10:05:37 gateway-3002114328 aziot-identityd[4839]: 2025-01-16T10:05:37Z [INFO] - Provisioning starting. Reason: Startup
Jan 16 10:05:37 gateway-3002114328 aziot-certd[4844]: 2025-01-16T10:05:37Z [INFO] - <-- GET /certificates/device-id?api-version=2020-09-01 {"host": "certd.sock"}
Jan 16 10:05:37 gateway-3002114328 aziot-certd[4844]: 2025-01-16T10:05:37Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:05:37 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:37Z [INFO] - <-- GET /keypair/device-id?api-version=2021-05-01 {"host": "keyd.sock"}
Jan 16 10:05:37 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:37Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:05:37 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:37Z [INFO] - <-- POST /parameters/algorithm?api-version=2021-05-01 {"content-length": "248", "content-type": "application/json"}
Jan 16 10:05:37 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:37Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:05:37 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:37Z [INFO] - <-- POST /parameters/rsa-modulus?api-version=2021-05-01 {"content-length": "248", "content-type": "application/json"}
Jan 16 10:05:37 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:37Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:05:37 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:37Z [INFO] - <-- POST /parameters/rsa-exponent?api-version=2021-05-01 {"content-length": "248", "content-type": "application/json"}
Jan 16 10:05:37 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:37Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:05:37 gateway-3002114328 aziot-identityd[4839]: 2025-01-16T10:05:37Z [INFO] - Sending DPS registration request.
Jan 16 10:05:37 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:37Z [INFO] - <-- POST /encrypt?api-version=2021-05-01 {"content-length": "636", "content-type": "application/json"}
Jan 16 10:05:38 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:38Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:05:43 gateway-3002114328 aziot-identityd[4839]: 2025-01-16T10:05:43Z [INFO] - Checking DPS registration status.
Jan 16 10:05:43 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:43Z [INFO] - <-- POST /encrypt?api-version=2021-05-01 {"content-length": "636", "content-type": "application/json"}
Jan 16 10:05:44 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:44Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:05:44 gateway-3002114328 aziot-identityd[4839]: 2025-01-16T10:05:44Z [ERR!] - Failed to provision with IoT Hub, and no valid device backup was found: DPS client error
Jan 16 10:05:44 gateway-3002114328 aziot-identityd[4839]: 2025-01-16T10:05:44Z [ERR!] - service encountered an error
Jan 16 10:05:44 gateway-3002114328 aziot-identityd[4839]: 2025-01-16T10:05:44Z [ERR!] - caused by: DPS client error
Jan 16 10:05:44 gateway-3002114328 aziot-identityd[4839]: 2025-01-16T10:05:44Z [ERR!] - caused by: Custom allocation failed with status code: 400
Jan 16 10:05:44 gateway-3002114328 aziot-identityd[4839]: 2025-01-16T10:05:44Z [ERR!] -    0: <unknown>
Jan 16 10:05:44 gateway-3002114328 aziot-identityd[4839]:    1: <unknown>
Jan 16 10:05:44 gateway-3002114328 aziot-identityd[4839]:    2: <unknown>
Jan 16 10:05:44 gateway-3002114328 aziot-identityd[4839]:    3: <unknown>
Jan 16 10:05:44 gateway-3002114328 aziot-identityd[4839]:    4: <unknown>
Jan 16 10:05:44 gateway-3002114328 aziot-identityd[4839]:    5: <unknown>
Jan 16 10:05:44 gateway-3002114328 aziot-identityd[4839]:    6: <unknown>
Jan 16 10:05:44 gateway-3002114328 aziot-identityd[4839]:    7: <unknown>
Jan 16 10:05:44 gateway-3002114328 aziot-identityd[4839]:    8: <unknown>
Jan 16 10:05:44 gateway-3002114328 aziot-identityd[4839]:    9: <unknown>
Jan 16 10:05:44 gateway-3002114328 aziot-identityd[4839]:   10: __libc_start_call_main
Jan 16 10:05:44 gateway-3002114328 aziot-identityd[4839]:              at usr/src/debug/glibc/2.35-r0/git/csu/../sysdeps/nptl/libc_start_call_main.h:58:16
Jan 16 10:05:44 gateway-3002114328 aziot-identityd[4839]:   11: __libc_start_main_impl
Jan 16 10:05:44 gateway-3002114328 aziot-identityd[4839]:              at usr/src/debug/glibc/2.35-r0/git/csu/../csu/libc-start.c:389:3
Jan 16 10:05:44 gateway-3002114328 aziot-identityd[4839]:   12: <unknown>
Jan 16 10:05:44 gateway-3002114328 systemd[1]: aziot-identityd.service: Main process exited, code=exited, status=1/FAILURE
Jan 16 10:05:44 gateway-3002114328 systemd[1]: aziot-identityd.service: Failed with result 'exit-code'.
Jan 16 10:05:50 gateway-3002114328 systemd[1]: aziot-identityd.service: Scheduled restart job, restart counter is at 18.
Jan 16 10:05:50 gateway-3002114328 systemd[1]: Stopped Azure IoT Identity Service.
Jan 16 10:05:50 gateway-3002114328 aziot-edged[4834]: 2025-01-16T10:05:50Z [WARN] - Failed to send HTTP request (attempt 1 of 2): connection error: Connection reset by peer (os error 104)
Jan 16 10:05:50 gateway-3002114328 systemd[1]: Started Azure IoT Identity Service.
Jan 16 10:05:50 gateway-3002114328 aziot-identityd[4869]: 2025-01-16T10:05:50Z [INFO] - Starting service...
Jan 16 10:05:50 gateway-3002114328 aziot-identityd[4869]: 2025-01-16T10:05:50Z [INFO] - Version - dev build
Jan 16 10:05:50 gateway-3002114328 aziot-identityd[4869]: 2025-01-16T10:05:50Z [INFO] - Loaded openssl'd Default provider
Jan 16 10:05:50 gateway-3002114328 aziot-certd[4844]: 2025-01-16T10:05:50Z [INFO] - <-- GET /certificates/device-id?api-version=2020-09-01 {"host": "certd.sock"}
Jan 16 10:05:50 gateway-3002114328 aziot-certd[4844]: 2025-01-16T10:05:50Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:05:50 gateway-3002114328 aziot-certd[4844]: 2025-01-16T10:05:50Z [INFO] - <-- GET /certificates/device-id?api-version=2020-09-01 {"host": "certd.sock"}
Jan 16 10:05:50 gateway-3002114328 aziot-certd[4844]: 2025-01-16T10:05:50Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:05:50 gateway-3002114328 aziot-identityd[4869]: 2025-01-16T10:05:50Z [INFO] - Certificate device-id will be auto-renewed. Next renewal at 2025-11-04T10:05:37+00:00.
Jan 16 10:05:50 gateway-3002114328 aziot-identityd[4869]: 2025-01-16T10:05:50Z [INFO] - Provisioning starting. Reason: Startup
Jan 16 10:05:50 gateway-3002114328 aziot-certd[4844]: 2025-01-16T10:05:50Z [INFO] - <-- GET /certificates/device-id?api-version=2020-09-01 {"host": "certd.sock"}
Jan 16 10:05:50 gateway-3002114328 aziot-certd[4844]: 2025-01-16T10:05:50Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:05:50 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:50Z [INFO] - <-- GET /keypair/device-id?api-version=2021-05-01 {"host": "keyd.sock"}
Jan 16 10:05:50 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:50Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:05:50 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:50Z [INFO] - <-- POST /parameters/algorithm?api-version=2021-05-01 {"content-length": "248", "content-type": "application/json"}
Jan 16 10:05:50 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:50Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:05:50 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:50Z [INFO] - <-- POST /parameters/rsa-modulus?api-version=2021-05-01 {"content-length": "248", "content-type": "application/json"}
Jan 16 10:05:50 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:50Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:05:50 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:50Z [INFO] - <-- POST /parameters/rsa-exponent?api-version=2021-05-01 {"content-length": "248", "content-type": "application/json"}
Jan 16 10:05:50 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:50Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:05:50 gateway-3002114328 aziot-identityd[4869]: 2025-01-16T10:05:50Z [INFO] - Sending DPS registration request.
Jan 16 10:05:50 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:50Z [INFO] - <-- POST /encrypt?api-version=2021-05-01 {"content-length": "636", "content-type": "application/json"}
Jan 16 10:05:51 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:51Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:05:56 gateway-3002114328 aziot-identityd[4869]: 2025-01-16T10:05:56Z [INFO] - Checking DPS registration status.
Jan 16 10:05:56 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:56Z [INFO] - <-- POST /encrypt?api-version=2021-05-01 {"content-length": "636", "content-type": "application/json"}
Jan 16 10:05:57 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:05:57Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:05:57 gateway-3002114328 aziot-identityd[4869]: 2025-01-16T10:05:57Z [ERR!] - Failed to provision with IoT Hub, and no valid device backup was found: DPS client error
Jan 16 10:05:57 gateway-3002114328 aziot-identityd[4869]: 2025-01-16T10:05:57Z [ERR!] - service encountered an error
Jan 16 10:05:57 gateway-3002114328 aziot-identityd[4869]: 2025-01-16T10:05:57Z [ERR!] - caused by: DPS client error
Jan 16 10:05:57 gateway-3002114328 aziot-identityd[4869]: 2025-01-16T10:05:57Z [ERR!] - caused by: Custom allocation failed with status code: 400
Jan 16 10:05:57 gateway-3002114328 aziot-identityd[4869]: 2025-01-16T10:05:57Z [ERR!] -    0: <unknown>
Jan 16 10:05:57 gateway-3002114328 aziot-identityd[4869]:    1: <unknown>
Jan 16 10:05:57 gateway-3002114328 aziot-identityd[4869]:    2: <unknown>
Jan 16 10:05:57 gateway-3002114328 aziot-identityd[4869]:    3: <unknown>
Jan 16 10:05:57 gateway-3002114328 aziot-identityd[4869]:    4: <unknown>
Jan 16 10:05:57 gateway-3002114328 aziot-identityd[4869]:    5: <unknown>
Jan 16 10:05:57 gateway-3002114328 aziot-identityd[4869]:    6: <unknown>
Jan 16 10:05:57 gateway-3002114328 aziot-identityd[4869]:    7: <unknown>
Jan 16 10:05:57 gateway-3002114328 aziot-identityd[4869]:    8: <unknown>
Jan 16 10:05:57 gateway-3002114328 aziot-identityd[4869]:    9: <unknown>
Jan 16 10:05:57 gateway-3002114328 aziot-identityd[4869]:   10: __libc_start_call_main
Jan 16 10:05:57 gateway-3002114328 aziot-identityd[4869]:              at usr/src/debug/glibc/2.35-r0/git/csu/../sysdeps/nptl/libc_start_call_main.h:58:16
Jan 16 10:05:57 gateway-3002114328 aziot-identityd[4869]:   11: __libc_start_main_impl
Jan 16 10:05:57 gateway-3002114328 aziot-identityd[4869]:              at usr/src/debug/glibc/2.35-r0/git/csu/../csu/libc-start.c:389:3
Jan 16 10:05:57 gateway-3002114328 aziot-identityd[4869]:   12: <unknown>
Jan 16 10:05:57 gateway-3002114328 systemd[1]: aziot-identityd.service: Main process exited, code=exited, status=1/FAILURE
Jan 16 10:05:57 gateway-3002114328 systemd[1]: aziot-identityd.service: Failed with result 'exit-code'.
Jan 16 10:06:02 gateway-3002114328 systemd[1]: aziot-identityd.service: Scheduled restart job, restart counter is at 19.
Jan 16 10:06:02 gateway-3002114328 systemd[1]: Stopped Azure IoT Identity Service.
Jan 16 10:06:02 gateway-3002114328 aziot-edged[4834]: 2025-01-16T10:06:02Z [WARN] - Failed to send HTTP request (attempt 2 of 2): connection error: Connection reset by peer (os error 104)
Jan 16 10:06:02 gateway-3002114328 aziot-edged[4834]: 2025-01-16T10:06:02Z [WARN] - Failed to obtain device identity: connection error: Connection reset by peer (os error 104)
Jan 16 10:06:02 gateway-3002114328 aziot-edged[4834]: 2025-01-16T10:06:02Z [INFO] - Requesting device reprovision
Jan 16 10:06:02 gateway-3002114328 aziot-edged[4834]: 2025-01-16T10:06:02Z [WARN] - Failed to send HTTP request (attempt 1 of 2): error trying to connect: Connection refused (os error 111)
Jan 16 10:06:02 gateway-3002114328 systemd[1]: Started Azure IoT Identity Service.
Jan 16 10:06:02 gateway-3002114328 aziot-identityd[4878]: 2025-01-16T10:06:02Z [INFO] - Starting service...
Jan 16 10:06:02 gateway-3002114328 aziot-identityd[4878]: 2025-01-16T10:06:02Z [INFO] - Version - dev build
Jan 16 10:06:02 gateway-3002114328 aziot-identityd[4878]: 2025-01-16T10:06:02Z [INFO] - Loaded openssl'd Default provider
Jan 16 10:06:02 gateway-3002114328 aziot-certd[4844]: 2025-01-16T10:06:02Z [INFO] - <-- GET /certificates/device-id?api-version=2020-09-01 {"host": "certd.sock"}
Jan 16 10:06:02 gateway-3002114328 aziot-certd[4844]: 2025-01-16T10:06:02Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:06:02 gateway-3002114328 aziot-certd[4844]: 2025-01-16T10:06:02Z [INFO] - <-- GET /certificates/device-id?api-version=2020-09-01 {"host": "certd.sock"}
Jan 16 10:06:02 gateway-3002114328 aziot-certd[4844]: 2025-01-16T10:06:02Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:06:02 gateway-3002114328 aziot-identityd[4878]: 2025-01-16T10:06:02Z [INFO] - Certificate device-id will be auto-renewed. Next renewal at 2025-11-04T10:05:37+00:00.
Jan 16 10:06:02 gateway-3002114328 aziot-identityd[4878]: 2025-01-16T10:06:02Z [INFO] - Provisioning starting. Reason: Startup
Jan 16 10:06:02 gateway-3002114328 aziot-certd[4844]: 2025-01-16T10:06:02Z [INFO] - <-- GET /certificates/device-id?api-version=2020-09-01 {"host": "certd.sock"}
Jan 16 10:06:02 gateway-3002114328 aziot-certd[4844]: 2025-01-16T10:06:02Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:06:02 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:06:02Z [INFO] - <-- GET /keypair/device-id?api-version=2021-05-01 {"host": "keyd.sock"}
Jan 16 10:06:02 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:06:02Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:06:02 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:06:02Z [INFO] - <-- POST /parameters/algorithm?api-version=2021-05-01 {"content-length": "248", "content-type": "application/json"}
Jan 16 10:06:02 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:06:02Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:06:02 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:06:02Z [INFO] - <-- POST /parameters/rsa-modulus?api-version=2021-05-01 {"content-length": "248", "content-type": "application/json"}
Jan 16 10:06:02 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:06:02Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:06:02 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:06:02Z [INFO] - <-- POST /parameters/rsa-exponent?api-version=2021-05-01 {"content-length": "248", "content-type": "application/json"}
Jan 16 10:06:02 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:06:02Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:06:02 gateway-3002114328 aziot-identityd[4878]: 2025-01-16T10:06:02Z [INFO] - Sending DPS registration request.
Jan 16 10:06:02 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:06:02Z [INFO] - <-- POST /encrypt?api-version=2021-05-01 {"content-length": "636", "content-type": "application/json"}
Jan 16 10:06:03 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:06:03Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:06:08 gateway-3002114328 aziot-identityd[4878]: 2025-01-16T10:06:08Z [INFO] - Checking DPS registration status.
Jan 16 10:06:08 gateway-3002114328 aziot-identityd[4878]: 2025-01-16T10:06:08Z [INFO] - Assigned to IoT hub: iot-XXX-01.azure-devices.net
Jan 16 10:06:08 gateway-3002114328 aziot-identityd[4878]: 2025-01-16T10:06:08Z [INFO] - DPS registration complete.
Jan 16 10:06:08 gateway-3002114328 aziot-identityd[4878]: 2025-01-16T10:06:08Z [INFO] - Successfully provisioned with DPS.
Jan 16 10:06:08 gateway-3002114328 aziot-identityd[4878]: 2025-01-16T10:06:08Z [INFO] - Provisioning complete.
Jan 16 10:06:08 gateway-3002114328 aziot-identityd[4878]: 2025-01-16T10:06:08Z [INFO] - Identity reconciliation started. Reason: Startup
Jan 16 10:06:09 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:06:09Z [INFO] - <-- POST /encrypt?api-version=2021-05-01 {"content-length": "636", "content-type": "application/json"}
Jan 16 10:06:10 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:06:10Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:06:10 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:06:10Z [INFO] - <-- POST /encrypt?api-version=2021-05-01 {"content-length": "636", "content-type": "application/json"}
Jan 16 10:06:11 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:06:11Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:06:11 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:06:11Z [INFO] - <-- GET /key/aziot_identityd_master_id?api-version=2021-05-01 {"host": "keyd.sock"}
Jan 16 10:06:11 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:06:11Z [ERR!] - invalid parameter "id": not found
Jan 16 10:06:11 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:06:11Z [INFO] - !!! a parameter has an invalid value
Jan 16 10:06:11 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:06:11Z [INFO] - --> 400 {"content-type": "application/json"}
Jan 16 10:06:11 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:06:11Z [INFO] - <-- POST /key?api-version=2021-05-01 {"content-type": "application/json", "host": "keyd.sock", "content-length": "75"}
Jan 16 10:06:11 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:06:11Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:06:11 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:06:11Z [INFO] - <-- POST /derivedkey?api-version=2021-05-01 {"content-type": "application/json", "host": "keyd.sock", "content-length": "348"}
Jan 16 10:06:11 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:06:11Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:06:11 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:06:11Z [INFO] - <-- POST /derivedkey/export?api-version=2021-05-01 {"content-type": "application/json", "host": "keyd.sock", "content-length": "772"}
Jan 16 10:06:11 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:06:11Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:06:11 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:06:11Z [INFO] - <-- POST /derivedkey?api-version=2021-05-01 {"content-type": "application/json", "host": "keyd.sock", "content-length": "352"}
Jan 16 10:06:11 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:06:11Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:06:11 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:06:11Z [INFO] - <-- POST /derivedkey/export?api-version=2021-05-01 {"content-type": "application/json", "host": "keyd.sock", "content-length": "780"}
Jan 16 10:06:11 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:06:11Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:06:11 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:06:11Z [INFO] - <-- POST /encrypt?api-version=2021-05-01 {"content-length": "636", "content-type": "application/json"}
Jan 16 10:06:12 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:06:12Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:06:12 gateway-3002114328 aziot-identityd[4878]: 2025-01-16T10:06:12Z [INFO] - Hub identity "IoTHubDeviceUpdate" added
Jan 16 10:06:12 gateway-3002114328 aziot-identityd[4878]: 2025-01-16T10:06:12Z [INFO] - Identity reconciliation complete.
Jan 16 10:06:12 gateway-3002114328 aziot-identityd[4878]: 2025-01-16T10:06:12Z [INFO] - Starting server...
Jan 16 10:06:12 gateway-3002114328 aziot-identityd[4878]: 2025-01-16T10:06:12Z [INFO] - <-- POST /identities/device/reprovision?api-version=2020-09-01 {"content-type": "application/json", "host": "identityd.sock", "content-length": "16"}
Jan 16 10:06:12 gateway-3002114328 aziot-identityd[4878]: 2025-01-16T10:06:12Z [INFO] - Provisioning starting. Reason: Api
Jan 16 10:06:12 gateway-3002114328 aziot-certd[4844]: 2025-01-16T10:06:12Z [INFO] - <-- GET /certificates/device-id?api-version=2020-09-01 {"host": "certd.sock"}
Jan 16 10:06:12 gateway-3002114328 aziot-certd[4844]: 2025-01-16T10:06:12Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:06:12 gateway-3002114328 aziot-identityd[4878]: 2025-01-16T10:06:12Z [INFO] - <-- GET http://foo/identities/identity?api-version=2020-09-01 {"host": "/run/aziot/identityd.sock:0", "content-length": "0"}
Jan 16 10:06:12 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:06:12Z [INFO] - <-- GET /keypair/device-id?api-version=2021-05-01 {"host": "keyd.sock"}
Jan 16 10:06:12 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:06:12Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:06:12 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:06:12Z [INFO] - <-- POST /parameters/algorithm?api-version=2021-05-01 {"content-length": "248", "content-type": "application/json"}
Jan 16 10:06:12 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:06:12Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:06:12 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:06:12Z [INFO] - <-- POST /parameters/rsa-modulus?api-version=2021-05-01 {"content-length": "248", "content-type": "application/json"}
Jan 16 10:06:12 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:06:12Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:06:12 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:06:12Z [INFO] - <-- POST /parameters/rsa-exponent?api-version=2021-05-01 {"content-length": "248", "content-type": "application/json"}
Jan 16 10:06:12 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:06:12Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:06:12 gateway-3002114328 aziot-identityd[4878]: 2025-01-16T10:06:12Z [INFO] - Sending DPS registration request.
Jan 16 10:06:12 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:06:12Z [INFO] - <-- POST /encrypt?api-version=2021-05-01 {"content-length": "636", "content-type": "application/json"}
Jan 16 10:06:13 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:06:13Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:06:18 gateway-3002114328 aziot-identityd[4878]: 2025-01-16T10:06:18Z [INFO] - Checking DPS registration status.
Jan 16 10:06:18 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:06:18Z [INFO] - <-- POST /encrypt?api-version=2021-05-01 {"content-length": "636", "content-type": "application/json"}
Jan 16 10:06:19 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:06:19Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:06:19 gateway-3002114328 aziot-identityd[4878]: 2025-01-16T10:06:19Z [INFO] - !!! DPS client error
Jan 16 10:06:19 gateway-3002114328 aziot-identityd[4878]: 2025-01-16T10:06:19Z [INFO] - !!! caused by: Custom allocation failed with status code: 400
Jan 16 10:06:19 gateway-3002114328 aziot-identityd[4878]: 2025-01-16T10:06:19Z [INFO] - --> 404 {"content-type": "application/json"}
Jan 16 10:06:19 gateway-3002114328 aziot-identityd[4878]: 2025-01-16T10:06:19Z [INFO] - !!! device identity not found
Jan 16 10:06:19 gateway-3002114328 aziot-identityd[4878]: 2025-01-16T10:06:19Z [INFO] - --> 400 {"content-type": "application/json"}
Jan 16 10:06:19 gateway-3002114328 aziot-edged[4834]: 2025-01-16T10:06:19Z [WARN] - Failed to reprovision: invalid HTTP status code
Jan 16 10:06:24 gateway-3002114328 aziot-edged[4834]: 2025-01-16T10:06:24Z [INFO] - Obtaining Edge device provisioning data...
Jan 16 10:06:24 gateway-3002114328 aziot-identityd[4878]: 2025-01-16T10:06:24Z [INFO] - <-- POST /identities/device?api-version=2020-09-01 {"content-type": "application/json", "host": "identityd.sock", "content-length": "16"}
Jan 16 10:06:24 gateway-3002114328 aziot-identityd[4878]: 2025-01-16T10:06:24Z [INFO] - !!! device identity not found
Jan 16 10:06:24 gateway-3002114328 aziot-identityd[4878]: 2025-01-16T10:06:24Z [INFO] - --> 400 {"content-type": "application/json"}
Jan 16 10:06:24 gateway-3002114328 aziot-edged[4834]: 2025-01-16T10:06:24Z [WARN] - Failed to obtain device identity: device identity not found
Jan 16 10:06:24 gateway-3002114328 aziot-edged[4834]: 2025-01-16T10:06:24Z [INFO] - Requesting device reprovision
Jan 16 10:06:24 gateway-3002114328 aziot-edged[4834]: 2025-01-16T10:06:24Z [WARN] - Failed to clear provisioning cache before reprovision: No such file or directory (os error 2)
Jan 16 10:06:24 gateway-3002114328 aziot-identityd[4878]: 2025-01-16T10:06:24Z [INFO] - <-- POST /identities/device/reprovision?api-version=2020-09-01 {"content-type": "application/json", "host": "identityd.sock", "content-length": "16"}
Jan 16 10:06:24 gateway-3002114328 aziot-identityd[4878]: 2025-01-16T10:06:24Z [INFO] - Provisioning starting. Reason: Api
Jan 16 10:06:24 gateway-3002114328 aziot-certd[4844]: 2025-01-16T10:06:24Z [INFO] - <-- GET /certificates/device-id?api-version=2020-09-01 {"host": "certd.sock"}
Jan 16 10:06:24 gateway-3002114328 aziot-certd[4844]: 2025-01-16T10:06:24Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:06:24 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:06:24Z [INFO] - <-- GET /keypair/device-id?api-version=2021-05-01 {"host": "keyd.sock"}
Jan 16 10:06:24 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:06:24Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:06:24 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:06:24Z [INFO] - <-- POST /parameters/algorithm?api-version=2021-05-01 {"content-length": "248", "content-type": "application/json"}
Jan 16 10:06:24 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:06:24Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:06:24 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:06:24Z [INFO] - <-- POST /parameters/rsa-modulus?api-version=2021-05-01 {"content-length": "248", "content-type": "application/json"}
Jan 16 10:06:24 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:06:24Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:06:24 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:06:24Z [INFO] - <-- POST /parameters/rsa-exponent?api-version=2021-05-01 {"content-length": "248", "content-type": "application/json"}
Jan 16 10:06:24 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:06:24Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:06:24 gateway-3002114328 aziot-identityd[4878]: 2025-01-16T10:06:24Z [INFO] - Sending DPS registration request.
Jan 16 10:06:25 gateway-3002114328 aziot-identityd[4878]: 2025-01-16T10:06:25Z [INFO] - <-- GET http://foo/identities/identity?api-version=2020-09-01 {"host": "/run/aziot/identityd.sock:0", "content-length": "0"}
Jan 16 10:06:25 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:06:25Z [INFO] - <-- POST /encrypt?api-version=2021-05-01 {"content-length": "636", "content-type": "application/json"}
Jan 16 10:06:26 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:06:26Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:06:31 gateway-3002114328 aziot-identityd[4878]: 2025-01-16T10:06:31Z [INFO] - Checking DPS registration status.
Jan 16 10:06:31 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:06:31Z [INFO] - <-- POST /encrypt?api-version=2021-05-01 {"content-length": "636", "content-type": "application/json"}
Jan 16 10:06:32 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:06:32Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:06:32 gateway-3002114328 aziot-identityd[4878]: 2025-01-16T10:06:32Z [INFO] - !!! DPS client error
Jan 16 10:06:32 gateway-3002114328 aziot-identityd[4878]: 2025-01-16T10:06:32Z [INFO] - !!! caused by: Custom allocation failed with status code: 400
Jan 16 10:06:32 gateway-3002114328 aziot-identityd[4878]: 2025-01-16T10:06:32Z [INFO] - --> 404 {"content-type": "application/json"}
Jan 16 10:06:32 gateway-3002114328 aziot-identityd[4878]: 2025-01-16T10:06:32Z [INFO] - !!! device identity not found
Jan 16 10:06:32 gateway-3002114328 aziot-identityd[4878]: 2025-01-16T10:06:32Z [INFO] - --> 400 {"content-type": "application/json"}
Jan 16 10:06:32 gateway-3002114328 aziot-edged[4834]: 2025-01-16T10:06:32Z [WARN] - Failed to reprovision: invalid HTTP status code
Jan 16 10:06:37 gateway-3002114328 aziot-edged[4834]: 2025-01-16T10:06:37Z [INFO] - Obtaining Edge device provisioning data...
Jan 16 10:06:37 gateway-3002114328 aziot-edged[4834]: 2025-01-16T10:06:37Z [WARN] - Failed to obtain device identity: device identity not found
Jan 16 10:06:37 gateway-3002114328 aziot-edged[4834]: 2025-01-16T10:06:37Z [INFO] - Requesting device reprovision
Jan 16 10:06:37 gateway-3002114328 aziot-edged[4834]: 2025-01-16T10:06:37Z [WARN] - Failed to clear provisioning cache before reprovision: No such file or directory (os error 2)
Jan 16 10:06:37 gateway-3002114328 aziot-identityd[4878]: 2025-01-16T10:06:37Z [INFO] - <-- POST /identities/device?api-version=2020-09-01 {"content-type": "application/json", "host": "identityd.sock", "content-length": "16"}
Jan 16 10:06:37 gateway-3002114328 aziot-identityd[4878]: 2025-01-16T10:06:37Z [INFO] - !!! device identity not found
Jan 16 10:06:37 gateway-3002114328 aziot-identityd[4878]: 2025-01-16T10:06:37Z [INFO] - --> 400 {"content-type": "application/json"}
Jan 16 10:06:37 gateway-3002114328 aziot-identityd[4878]: 2025-01-16T10:06:37Z [INFO] - <-- POST /identities/device/reprovision?api-version=2020-09-01 {"content-type": "application/json", "host": "identityd.sock", "content-length": "16"}
Jan 16 10:06:37 gateway-3002114328 aziot-identityd[4878]: 2025-01-16T10:06:37Z [INFO] - Provisioning starting. Reason: Api
Jan 16 10:06:37 gateway-3002114328 aziot-certd[4844]: 2025-01-16T10:06:37Z [INFO] - <-- GET /certificates/device-id?api-version=2020-09-01 {"host": "certd.sock"}
Jan 16 10:06:37 gateway-3002114328 aziot-certd[4844]: 2025-01-16T10:06:37Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:06:37 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:06:37Z [INFO] - <-- GET /keypair/device-id?api-version=2021-05-01 {"host": "keyd.sock"}
Jan 16 10:06:37 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:06:37Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:06:37 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:06:37Z [INFO] - <-- POST /parameters/algorithm?api-version=2021-05-01 {"content-length": "248", "content-type": "application/json"}
Jan 16 10:06:37 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:06:37Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:06:37 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:06:37Z [INFO] - <-- POST /parameters/rsa-modulus?api-version=2021-05-01 {"content-length": "248", "content-type": "application/json"}
Jan 16 10:06:37 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:06:37Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:06:37 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:06:37Z [INFO] - <-- POST /parameters/rsa-exponent?api-version=2021-05-01 {"content-length": "248", "content-type": "application/json"}
Jan 16 10:06:37 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:06:37Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:06:37 gateway-3002114328 aziot-identityd[4878]: 2025-01-16T10:06:37Z [INFO] - Sending DPS registration request.
Jan 16 10:06:37 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:06:37Z [INFO] - <-- POST /encrypt?api-version=2021-05-01 {"content-length": "636", "content-type": "application/json"}
Jan 16 10:06:38 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:06:38Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:06:38 gateway-3002114328 aziot-identityd[4878]: 2025-01-16T10:06:38Z [INFO] - <-- GET http://foo/identities/identity?api-version=2020-09-01 {"host": "/run/aziot/identityd.sock:0", "content-length": "0"}
Jan 16 10:06:43 gateway-3002114328 aziot-identityd[4878]: 2025-01-16T10:06:43Z [INFO] - Checking DPS registration status.
Jan 16 10:06:43 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:06:43Z [INFO] - <-- POST /encrypt?api-version=2021-05-01 {"content-length": "636", "content-type": "application/json"}
Jan 16 10:06:44 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:06:44Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:06:44 gateway-3002114328 aziot-identityd[4878]: 2025-01-16T10:06:44Z [INFO] - !!! DPS client error
Jan 16 10:06:44 gateway-3002114328 aziot-identityd[4878]: 2025-01-16T10:06:44Z [INFO] - !!! caused by: Custom allocation failed with status code: 400
Jan 16 10:06:44 gateway-3002114328 aziot-identityd[4878]: 2025-01-16T10:06:44Z [INFO] - --> 404 {"content-type": "application/json"}
Jan 16 10:06:44 gateway-3002114328 aziot-identityd[4878]: 2025-01-16T10:06:44Z [INFO] - !!! device identity not found
Jan 16 10:06:44 gateway-3002114328 aziot-identityd[4878]: 2025-01-16T10:06:44Z [INFO] - --> 400 {"content-type": "application/json"}
Jan 16 10:06:44 gateway-3002114328 aziot-edged[4834]: 2025-01-16T10:06:44Z [WARN] - Failed to reprovision: invalid HTTP status code
Jan 16 10:06:49 gateway-3002114328 aziot-edged[4834]: 2025-01-16T10:06:49Z [INFO] - Obtaining Edge device provisioning data...
Jan 16 10:06:49 gateway-3002114328 aziot-edged[4834]: 2025-01-16T10:06:49Z [WARN] - Failed to obtain device identity: device identity not found
Jan 16 10:06:49 gateway-3002114328 aziot-edged[4834]: 2025-01-16T10:06:49Z [INFO] - Requesting device reprovision
Jan 16 10:06:49 gateway-3002114328 aziot-edged[4834]: 2025-01-16T10:06:49Z [WARN] - Failed to clear provisioning cache before reprovision: No such file or directory (os error 2)
Jan 16 10:06:49 gateway-3002114328 aziot-identityd[4878]: 2025-01-16T10:06:49Z [INFO] - <-- POST /identities/device?api-version=2020-09-01 {"content-type": "application/json", "host": "identityd.sock", "content-length": "16"}
Jan 16 10:06:49 gateway-3002114328 aziot-identityd[4878]: 2025-01-16T10:06:49Z [INFO] - !!! device identity not found
Jan 16 10:06:49 gateway-3002114328 aziot-identityd[4878]: 2025-01-16T10:06:49Z [INFO] - --> 400 {"content-type": "application/json"}
Jan 16 10:06:49 gateway-3002114328 aziot-identityd[4878]: 2025-01-16T10:06:49Z [INFO] - <-- POST /identities/device/reprovision?api-version=2020-09-01 {"content-type": "application/json", "host": "identityd.sock", "content-length": "16"}
Jan 16 10:06:49 gateway-3002114328 aziot-identityd[4878]: 2025-01-16T10:06:49Z [INFO] - Provisioning starting. Reason: Api
Jan 16 10:06:49 gateway-3002114328 aziot-certd[4844]: 2025-01-16T10:06:49Z [INFO] - <-- GET /certificates/device-id?api-version=2020-09-01 {"host": "certd.sock"}
Jan 16 10:06:49 gateway-3002114328 aziot-certd[4844]: 2025-01-16T10:06:49Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:06:49 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:06:49Z [INFO] - <-- GET /keypair/device-id?api-version=2021-05-01 {"host": "keyd.sock"}
Jan 16 10:06:49 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:06:49Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:06:49 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:06:49Z [INFO] - <-- POST /parameters/algorithm?api-version=2021-05-01 {"content-length": "248", "content-type": "application/json"}
Jan 16 10:06:49 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:06:49Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:06:49 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:06:49Z [INFO] - <-- POST /parameters/rsa-modulus?api-version=2021-05-01 {"content-length": "248", "content-type": "application/json"}
Jan 16 10:06:49 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:06:49Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:06:49 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:06:49Z [INFO] - <-- POST /parameters/rsa-exponent?api-version=2021-05-01 {"content-length": "248", "content-type": "application/json"}
Jan 16 10:06:49 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:06:49Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:06:49 gateway-3002114328 aziot-identityd[4878]: 2025-01-16T10:06:49Z [INFO] - Sending DPS registration request.
Jan 16 10:06:49 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:06:49Z [INFO] - <-- POST /encrypt?api-version=2021-05-01 {"content-length": "636", "content-type": "application/json"}
Jan 16 10:06:50 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:06:50Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:06:50 gateway-3002114328 aziot-identityd[4878]: 2025-01-16T10:06:50Z [INFO] - <-- GET http://foo/identities/identity?api-version=2020-09-01 {"host": "/run/aziot/identityd.sock:0", "content-length": "0"}
Jan 16 10:06:55 gateway-3002114328 aziot-identityd[4878]: 2025-01-16T10:06:55Z [INFO] - Checking DPS registration status.
Jan 16 10:06:55 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:06:55Z [INFO] - <-- POST /encrypt?api-version=2021-05-01 {"content-length": "636", "content-type": "application/json"}
Jan 16 10:06:56 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:06:56Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:06:56 gateway-3002114328 aziot-identityd[4878]: 2025-01-16T10:06:56Z [INFO] - !!! DPS client error
Jan 16 10:06:56 gateway-3002114328 aziot-identityd[4878]: 2025-01-16T10:06:56Z [INFO] - !!! caused by: Custom allocation failed with status code: 400
Jan 16 10:06:56 gateway-3002114328 aziot-identityd[4878]: 2025-01-16T10:06:56Z [INFO] - --> 404 {"content-type": "application/json"}
Jan 16 10:06:56 gateway-3002114328 aziot-identityd[4878]: 2025-01-16T10:06:56Z [INFO] - !!! device identity not found
Jan 16 10:06:56 gateway-3002114328 aziot-identityd[4878]: 2025-01-16T10:06:56Z [INFO] - --> 400 {"content-type": "application/json"}
Jan 16 10:06:56 gateway-3002114328 aziot-edged[4834]: 2025-01-16T10:06:56Z [WARN] - Failed to reprovision: invalid HTTP status code
Jan 16 10:07:01 gateway-3002114328 aziot-edged[4834]: 2025-01-16T10:07:01Z [INFO] - Obtaining Edge device provisioning data...
Jan 16 10:07:01 gateway-3002114328 aziot-edged[4834]: 2025-01-16T10:07:01Z [WARN] - Failed to obtain device identity: device identity not found
Jan 16 10:07:01 gateway-3002114328 aziot-edged[4834]: 2025-01-16T10:07:01Z [INFO] - Requesting device reprovision
Jan 16 10:07:01 gateway-3002114328 aziot-edged[4834]: 2025-01-16T10:07:01Z [WARN] - Failed to clear provisioning cache before reprovision: No such file or directory (os error 2)
Jan 16 10:07:01 gateway-3002114328 aziot-identityd[4878]: 2025-01-16T10:07:01Z [INFO] - <-- POST /identities/device?api-version=2020-09-01 {"content-type": "application/json", "host": "identityd.sock", "content-length": "16"}
Jan 16 10:07:01 gateway-3002114328 aziot-identityd[4878]: 2025-01-16T10:07:01Z [INFO] - !!! device identity not found
Jan 16 10:07:01 gateway-3002114328 aziot-identityd[4878]: 2025-01-16T10:07:01Z [INFO] - --> 400 {"content-type": "application/json"}
Jan 16 10:07:01 gateway-3002114328 aziot-identityd[4878]: 2025-01-16T10:07:01Z [INFO] - <-- POST /identities/device/reprovision?api-version=2020-09-01 {"content-type": "application/json", "host": "identityd.sock", "content-length": "16"}
Jan 16 10:07:01 gateway-3002114328 aziot-identityd[4878]: 2025-01-16T10:07:01Z [INFO] - Provisioning starting. Reason: Api
Jan 16 10:07:01 gateway-3002114328 aziot-certd[4844]: 2025-01-16T10:07:01Z [INFO] - <-- GET /certificates/device-id?api-version=2020-09-01 {"host": "certd.sock"}
Jan 16 10:07:01 gateway-3002114328 aziot-certd[4844]: 2025-01-16T10:07:01Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:07:01 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:07:01Z [INFO] - <-- GET /keypair/device-id?api-version=2021-05-01 {"host": "keyd.sock"}
Jan 16 10:07:01 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:07:01Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:07:01 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:07:01Z [INFO] - <-- POST /parameters/algorithm?api-version=2021-05-01 {"content-length": "248", "content-type": "application/json"}
Jan 16 10:07:01 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:07:01Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:07:01 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:07:01Z [INFO] - <-- POST /parameters/rsa-modulus?api-version=2021-05-01 {"content-length": "248", "content-type": "application/json"}
Jan 16 10:07:01 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:07:01Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:07:01 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:07:01Z [INFO] - <-- POST /parameters/rsa-exponent?api-version=2021-05-01 {"content-length": "248", "content-type": "application/json"}
Jan 16 10:07:01 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:07:01Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 10:07:01 gateway-3002114328 aziot-identityd[4878]: 2025-01-16T10:07:01Z [INFO] - Sending DPS registration request.
Jan 16 10:07:01 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:07:01Z [INFO] - <-- POST /encrypt?api-version=2021-05-01 {"content-length": "636", "content-type": "application/json"}
Jan 16 10:07:02 gateway-3002114328 aziot-keyd[4854]: 2025-01-16T10:07:02Z [INFO] - --> 200 {"content-type": "application/json"}

Summary:

  • At 10:05:27 Azure IoT Edge runtime starts with a valid config
  • At 10:05:44 the device gets rejected from the DPS (as intended)
  • At 10:06:08 the DPS accepts the gateway
  • At 10:06:12 identityd starts reprovisioning and then enters a state that it does not recover from

Additional Information

A colleague has already created a patch wich apparently fixed the issue. He will post here later. However, i want to clarify if this behaviour is actually a bug, or if we have some misconfiguration etc.

I have also attached a log file with debug level: iotedge log debug level.txt

@nyanzebra nyanzebra self-assigned this Jan 21, 2025
@janpfer
Copy link

janpfer commented Jan 22, 2025

As @aleupo mentioned, I was working on this issue recently.
I believe 6f61f95 was intended to fix this issue. However, since I am not familiar with Rust, I am not entirely certain about that.

We receive a Connection reset by peer (os error 104), which is not a std::io::ErrorKind::ConnectionReset but rather a std::io::ErrorKind::Other. This leads to a reprovision being triggered by the aziot-edged. However, as aziot-identityd is currently unprovisioned and starting it triggers a (re-)provisioning via its startup logic. After that (Identity reconciliation complete. and the subsequent Starting server...), the reprovisioning triggered by aziot-edged is performed.

As a result, the runtime performs a reprovision immediately after a successful provisioning, which the DPS then rejects with a 400 error.
Additionally, the error (400 from DPS) triggered by a reprovisioning via the API is handled differently from the 400 error triggered during startup. I am not sure if this is correct, but it doesn't seem to be, as it leads to an "unrepairable state" of the device/runtime.

This behavior (os error instead of a simple network error) could be different due to the fact that we implement the runtime using https://github.com/Azure/meta-iotedge for Yocto-Linux.

Here is a log showing this behviour:

Log
Jan 16 08:32:59 uptime-plus-3001842402 aziot-identityd[8877]: 2025-01-16T08:32:59Z [ERR!] - Failed to provision with IoT Hub, and no valid device backup was found: DPS client error
Jan 16 08:32:59 uptime-plus-3001842402 aziot-identityd[8877]: 2025-01-16T08:32:59Z [ERR!] - service encountered an error
Jan 16 08:32:59 uptime-plus-3001842402 aziot-identityd[8877]: 2025-01-16T08:32:59Z [ERR!] - caused by: DPS client error
Jan 16 08:32:59 uptime-plus-3001842402 aziot-identityd[8877]: 2025-01-16T08:32:59Z [ERR!] - caused by: Custom allocation failed with status code: 400
Jan 16 08:32:59 uptime-plus-3001842402 aziot-identityd[8877]: 2025-01-16T08:32:59Z [ERR!] -    0: <unknown>
Jan 16 08:32:59 uptime-plus-3001842402 aziot-identityd[8877]:    1: <unknown>
Jan 16 08:32:59 uptime-plus-3001842402 aziot-identityd[8877]:    2: <unknown>
Jan 16 08:32:59 uptime-plus-3001842402 aziot-identityd[8877]:    3: <unknown>
Jan 16 08:32:59 uptime-plus-3001842402 aziot-identityd[8877]:    4: <unknown>
Jan 16 08:32:59 uptime-plus-3001842402 aziot-identityd[8877]:    5: <unknown>
Jan 16 08:32:59 uptime-plus-3001842402 aziot-identityd[8877]:    6: <unknown>
Jan 16 08:32:59 uptime-plus-3001842402 aziot-identityd[8877]:    7: <unknown>
Jan 16 08:32:59 uptime-plus-3001842402 aziot-identityd[8877]:    8: <unknown>
Jan 16 08:32:59 uptime-plus-3001842402 aziot-identityd[8877]:    9: <unknown>
Jan 16 08:32:59 uptime-plus-3001842402 aziot-identityd[8877]:   10: __libc_start_call_main
Jan 16 08:32:59 uptime-plus-3001842402 aziot-identityd[8877]:              at usr/src/debug/glibc/2.35-r0/git/csu/../sysdeps/nptl/libc_start_call_main.h:58:16
Jan 16 08:32:59 uptime-plus-3001842402 aziot-identityd[8877]:   11: __libc_start_main_impl
Jan 16 08:32:59 uptime-plus-3001842402 aziot-identityd[8877]:              at usr/src/debug/glibc/2.35-r0/git/csu/../csu/libc-start.c:389:3
Jan 16 08:32:59 uptime-plus-3001842402 aziot-identityd[8877]:   12: <unknown>
Jan 16 08:32:59 uptime-plus-3001842402 systemd[1]: aziot-identityd.service: Main process exited, code=exited, status=1/FAILURE
Jan 16 08:32:59 uptime-plus-3001842402 systemd[1]: aziot-identityd.service: Failed with result 'exit-code'.
Jan 16 08:33:04 uptime-plus-3001842402 systemd[1]: aziot-identityd.service: Scheduled restart job, restart counter is at 105.
Jan 16 08:33:04 uptime-plus-3001842402 systemd[1]: Stopped Azure IoT Identity Service.
Jan 16 08:33:04 uptime-plus-3001842402 aziot-edged[8810]: 2025-01-16T08:33:04Z [WARN] - Failed to send HTTP request (attempt 2 of 2): connection error: Connection reset by peer (os error 104)
Jan 16 08:33:04 uptime-plus-3001842402 aziot-edged[8810]: 2025-01-16T08:33:04Z [WARN] - Failed to obtain device identity: connection error: Connection reset by peer (os error 104)
Jan 16 08:33:04 uptime-plus-3001842402 aziot-edged[8810]: 2025-01-16T08:33:04Z [INFO] - Requesting device reprovision
Jan 16 08:33:04 uptime-plus-3001842402 aziot-edged[8810]: 2025-01-16T08:33:04Z [WARN] - Failed to clear provisioning cache before reprovision: No such file or directory (os error 2)
Jan 16 08:33:04 uptime-plus-3001842402 aziot-edged[8810]: 2025-01-16T08:33:04Z [WARN] - Failed to send HTTP request (attempt 1 of 2): error trying to connect: Connection refused (os error 111)
Jan 16 08:33:04 uptime-plus-3001842402 systemd[1]: Started Azure IoT Identity Service.
Jan 16 08:33:04 uptime-plus-3001842402 aziot-identityd[8886]: 2025-01-16T08:33:04Z [INFO] - Starting service...
Jan 16 08:33:04 uptime-plus-3001842402 aziot-identityd[8886]: 2025-01-16T08:33:04Z [INFO] - Version - dev build
Jan 16 08:33:04 uptime-plus-3001842402 aziot-identityd[8886]: 2025-01-16T08:33:04Z [INFO] - Loaded openssl'd Default provider
Jan 16 08:33:04 uptime-plus-3001842402 aziot-certd[8823]: 2025-01-16T08:33:04Z [INFO] - <-- GET /certificates/device-id?api-version=2020-09-01 {"host": "certd.sock"}
Jan 16 08:33:04 uptime-plus-3001842402 aziot-certd[8823]: 2025-01-16T08:33:04Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 08:33:04 uptime-plus-3001842402 aziot-certd[8823]: 2025-01-16T08:33:04Z [INFO] - <-- GET /certificates/device-id?api-version=2020-09-01 {"host": "certd.sock"}
Jan 16 08:33:04 uptime-plus-3001842402 aziot-certd[8823]: 2025-01-16T08:33:04Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 08:33:04 uptime-plus-3001842402 aziot-identityd[8886]: 2025-01-16T08:33:04Z [INFO] - Certificate device-id will be auto-renewed. Next renewal at 2025-11-04T08:32:02+00:00.
Jan 16 08:33:04 uptime-plus-3001842402 aziot-identityd[8886]: 2025-01-16T08:33:04Z [INFO] - Provisioning starting. Reason: Startup
Jan 16 08:33:04 uptime-plus-3001842402 aziot-certd[8823]: 2025-01-16T08:33:04Z [INFO] - <-- GET /certificates/device-id?api-version=2020-09-01 {"host": "certd.sock"}
Jan 16 08:33:04 uptime-plus-3001842402 aziot-certd[8823]: 2025-01-16T08:33:04Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 08:33:04 uptime-plus-3001842402 aziot-keyd[8831]: 2025-01-16T08:33:04Z [INFO] - <-- GET /keypair/device-id?api-version=2021-05-01 {"host": "keyd.sock"}
Jan 16 08:33:04 uptime-plus-3001842402 aziot-keyd[8831]: 2025-01-16T08:33:04Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 08:33:04 uptime-plus-3001842402 aziot-keyd[8831]: 2025-01-16T08:33:04Z [INFO] - <-- POST /parameters/algorithm?api-version=2021-05-01 {"content-length": "248", "content-type": "application/json"}
Jan 16 08:33:04 uptime-plus-3001842402 aziot-keyd[8831]: 2025-01-16T08:33:04Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 08:33:04 uptime-plus-3001842402 aziot-keyd[8831]: 2025-01-16T08:33:04Z [INFO] - <-- POST /parameters/rsa-modulus?api-version=2021-05-01 {"content-length": "248", "content-type": "application/json"}
Jan 16 08:33:04 uptime-plus-3001842402 aziot-keyd[8831]: 2025-01-16T08:33:04Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 08:33:04 uptime-plus-3001842402 aziot-keyd[8831]: 2025-01-16T08:33:04Z [INFO] - <-- POST /parameters/rsa-exponent?api-version=2021-05-01 {"content-length": "248", "content-type": "application/json"}
Jan 16 08:33:04 uptime-plus-3001842402 aziot-keyd[8831]: 2025-01-16T08:33:04Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 08:33:04 uptime-plus-3001842402 aziot-identityd[8886]: 2025-01-16T08:33:04Z [INFO] - Sending DPS registration request.
Jan 16 08:33:05 uptime-plus-3001842402 aziot-keyd[8831]: 2025-01-16T08:33:05Z [INFO] - <-- POST /encrypt?api-version=2021-05-01 {"content-length": "636", "content-type": "application/json"}
Jan 16 08:33:05 uptime-plus-3001842402 aziot-keyd[8831]: 2025-01-16T08:33:05Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 08:33:11 uptime-plus-3001842402 aziot-identityd[8886]: 2025-01-16T08:33:11Z [INFO] - Checking DPS registration status.
Jan 16 08:33:11 uptime-plus-3001842402 aziot-keyd[8831]: 2025-01-16T08:33:11Z [INFO] - <-- POST /encrypt?api-version=2021-05-01 {"content-length": "636", "content-type": "application/json"}
Jan 16 08:33:12 uptime-plus-3001842402 aziot-keyd[8831]: 2025-01-16T08:33:12Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 08:33:12 uptime-plus-3001842402 aziot-identityd[8886]: 2025-01-16T08:33:12Z [INFO] - DPS registration is still in progress.
Jan 16 08:33:17 uptime-plus-3001842402 aziot-identityd[8886]: 2025-01-16T08:33:17Z [INFO] - Checking DPS registration status.
Jan 16 08:33:17 uptime-plus-3001842402 aziot-keyd[8831]: 2025-01-16T08:33:17Z [INFO] - <-- POST /encrypt?api-version=2021-05-01 {"content-length": "636", "content-type": "application/json"}
Jan 16 08:33:18 uptime-plus-3001842402 aziot-keyd[8831]: 2025-01-16T08:33:18Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 08:33:18 uptime-plus-3001842402 aziot-identityd[8886]: 2025-01-16T08:33:18Z [INFO] - Assigned to IoT hub: xyz.azure-devices.net
Jan 16 08:33:18 uptime-plus-3001842402 aziot-identityd[8886]: 2025-01-16T08:33:18Z [INFO] - DPS registration complete.
Jan 16 08:33:18 uptime-plus-3001842402 aziot-identityd[8886]: 2025-01-16T08:33:18Z [INFO] - Successfully provisioned with DPS.
Jan 16 08:33:18 uptime-plus-3001842402 aziot-identityd[8886]: 2025-01-16T08:33:18Z [INFO] - Provisioning complete.
Jan 16 08:33:18 uptime-plus-3001842402 aziot-identityd[8886]: 2025-01-16T08:33:18Z [INFO] - Identity reconciliation started. Reason: Startup
Jan 16 08:33:18 uptime-plus-3001842402 aziot-keyd[8831]: 2025-01-16T08:33:18Z [INFO] - <-- POST /encrypt?api-version=2021-05-01 {"content-length": "636", "content-type": "application/json"}
Jan 16 08:33:19 uptime-plus-3001842402 aziot-keyd[8831]: 2025-01-16T08:33:19Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 08:33:19 uptime-plus-3001842402 aziot-keyd[8831]: 2025-01-16T08:33:19Z [INFO] - <-- POST /encrypt?api-version=2021-05-01 {"content-length": "636", "content-type": "application/json"}
Jan 16 08:33:20 uptime-plus-3001842402 aziot-keyd[8831]: 2025-01-16T08:33:20Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 08:33:20 uptime-plus-3001842402 aziot-keyd[8831]: 2025-01-16T08:33:20Z [INFO] - <-- GET /key/aziot_identityd_master_id?api-version=2021-05-01 {"host": "keyd.sock"}
Jan 16 08:33:20 uptime-plus-3001842402 aziot-keyd[8831]: 2025-01-16T08:33:20Z [ERR!] - invalid parameter "id": not found
Jan 16 08:33:20 uptime-plus-3001842402 aziot-keyd[8831]: 2025-01-16T08:33:20Z [INFO] - !!! a parameter has an invalid value
Jan 16 08:33:20 uptime-plus-3001842402 aziot-keyd[8831]: 2025-01-16T08:33:20Z [INFO] - --> 400 {"content-type": "application/json"}
Jan 16 08:33:20 uptime-plus-3001842402 aziot-keyd[8831]: 2025-01-16T08:33:20Z [INFO] - <-- POST /key?api-version=2021-05-01 {"content-type": "application/json", "host": "keyd.sock", "content-length": "75"}
Jan 16 08:33:20 uptime-plus-3001842402 aziot-keyd[8831]: 2025-01-16T08:33:20Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 08:33:20 uptime-plus-3001842402 aziot-keyd[8831]: 2025-01-16T08:33:20Z [INFO] - <-- POST /derivedkey?api-version=2021-05-01 {"content-type": "application/json", "host": "keyd.sock", "content-length": "348"}
Jan 16 08:33:20 uptime-plus-3001842402 aziot-keyd[8831]: 2025-01-16T08:33:20Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 08:33:20 uptime-plus-3001842402 aziot-keyd[8831]: 2025-01-16T08:33:20Z [INFO] - <-- POST /derivedkey/export?api-version=2021-05-01 {"content-type": "application/json", "host": "keyd.sock", "content-length": "772"}
Jan 16 08:33:20 uptime-plus-3001842402 aziot-keyd[8831]: 2025-01-16T08:33:20Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 08:33:20 uptime-plus-3001842402 aziot-keyd[8831]: 2025-01-16T08:33:20Z [INFO] - <-- POST /derivedkey?api-version=2021-05-01 {"content-type": "application/json", "host": "keyd.sock", "content-length": "352"}
Jan 16 08:33:20 uptime-plus-3001842402 aziot-keyd[8831]: 2025-01-16T08:33:20Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 08:33:20 uptime-plus-3001842402 aziot-keyd[8831]: 2025-01-16T08:33:20Z [INFO] - <-- POST /derivedkey/export?api-version=2021-05-01 {"content-type": "application/json", "host": "keyd.sock", "content-length": "780"}
Jan 16 08:33:20 uptime-plus-3001842402 aziot-keyd[8831]: 2025-01-16T08:33:20Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 08:33:20 uptime-plus-3001842402 aziot-keyd[8831]: 2025-01-16T08:33:20Z [INFO] - <-- POST /encrypt?api-version=2021-05-01 {"content-length": "636", "content-type": "application/json"}
Jan 16 08:33:21 uptime-plus-3001842402 aziot-keyd[8831]: 2025-01-16T08:33:21Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 08:33:21 uptime-plus-3001842402 aziot-identityd[8886]: 2025-01-16T08:33:21Z [INFO] - Hub identity "IoTHubDeviceUpdate" added
Jan 16 08:33:21 uptime-plus-3001842402 aziot-identityd[8886]: 2025-01-16T08:33:21Z [INFO] - Identity reconciliation complete.
Jan 16 08:33:21 uptime-plus-3001842402 aziot-identityd[8886]: 2025-01-16T08:33:21Z [INFO] - Starting server...
Jan 16 08:33:21 uptime-plus-3001842402 aziot-identityd[8886]: 2025-01-16T08:33:21Z [INFO] - <-- POST /identities/device/reprovision?api-version=2020-09-01 {"content-type": "application/json", "host": "identityd.sock", "content-length": "16"}
Jan 16 08:33:21 uptime-plus-3001842402 aziot-identityd[8886]: 2025-01-16T08:33:21Z [INFO] - Provisioning starting. Reason: Api
Jan 16 08:33:21 uptime-plus-3001842402 aziot-certd[8823]: 2025-01-16T08:33:21Z [INFO] - <-- GET /certificates/device-id?api-version=2020-09-01 {"host": "certd.sock"}
Jan 16 08:33:21 uptime-plus-3001842402 aziot-certd[8823]: 2025-01-16T08:33:21Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 08:33:21 uptime-plus-3001842402 aziot-identityd[8886]: 2025-01-16T08:33:21Z [INFO] - <-- GET http://foo/identities/identity?api-version=2020-09-01 {"host": "/run/aziot/identityd.sock:0", "content-length": "0"}
Jan 16 08:33:21 uptime-plus-3001842402 aziot-keyd[8831]: 2025-01-16T08:33:21Z [INFO] - <-- GET /keypair/device-id?api-version=2021-05-01 {"host": "keyd.sock"}
Jan 16 08:33:21 uptime-plus-3001842402 aziot-keyd[8831]: 2025-01-16T08:33:21Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 08:33:21 uptime-plus-3001842402 aziot-keyd[8831]: 2025-01-16T08:33:21Z [INFO] - <-- POST /parameters/algorithm?api-version=2021-05-01 {"content-length": "248", "content-type": "application/json"}
Jan 16 08:33:21 uptime-plus-3001842402 aziot-keyd[8831]: 2025-01-16T08:33:21Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 08:33:21 uptime-plus-3001842402 aziot-keyd[8831]: 2025-01-16T08:33:21Z [INFO] - <-- POST /parameters/rsa-modulus?api-version=2021-05-01 {"content-length": "248", "content-type": "application/json"}
Jan 16 08:33:21 uptime-plus-3001842402 aziot-keyd[8831]: 2025-01-16T08:33:21Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 08:33:21 uptime-plus-3001842402 aziot-keyd[8831]: 2025-01-16T08:33:21Z [INFO] - <-- POST /parameters/rsa-exponent?api-version=2021-05-01 {"content-length": "248", "content-type": "application/json"}
Jan 16 08:33:21 uptime-plus-3001842402 aziot-keyd[8831]: 2025-01-16T08:33:21Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 08:33:21 uptime-plus-3001842402 aziot-identityd[8886]: 2025-01-16T08:33:21Z [INFO] - Sending DPS registration request.
Jan 16 08:33:21 uptime-plus-3001842402 aziot-keyd[8831]: 2025-01-16T08:33:21Z [INFO] - <-- POST /encrypt?api-version=2021-05-01 {"content-length": "636", "content-type": "application/json"}
Jan 16 08:33:22 uptime-plus-3001842402 aziot-keyd[8831]: 2025-01-16T08:33:22Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 08:33:27 uptime-plus-3001842402 aziot-identityd[8886]: 2025-01-16T08:33:27Z [INFO] - Checking DPS registration status.
Jan 16 08:33:27 uptime-plus-3001842402 aziot-keyd[8831]: 2025-01-16T08:33:27Z [INFO] - <-- POST /encrypt?api-version=2021-05-01 {"content-length": "636", "content-type": "application/json"}
Jan 16 08:33:28 uptime-plus-3001842402 aziot-keyd[8831]: 2025-01-16T08:33:28Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 08:33:28 uptime-plus-3001842402 aziot-identityd[8886]: 2025-01-16T08:33:28Z [INFO] - !!! DPS client error
Jan 16 08:33:28 uptime-plus-3001842402 aziot-identityd[8886]: 2025-01-16T08:33:28Z [INFO] - !!! caused by: Custom allocation failed with status code: 400
Jan 16 08:33:28 uptime-plus-3001842402 aziot-identityd[8886]: 2025-01-16T08:33:28Z [INFO] - --> 404 {"content-type": "application/json"}
Jan 16 08:33:28 uptime-plus-3001842402 aziot-identityd[8886]: 2025-01-16T08:33:28Z [INFO] - !!! device identity not found
Jan 16 08:33:28 uptime-plus-3001842402 aziot-identityd[8886]: 2025-01-16T08:33:28Z [INFO] - --> 400 {"content-type": "application/json"}
Jan 16 08:33:28 uptime-plus-3001842402 aziot-edged[8810]: 2025-01-16T08:33:28Z [WARN] - Failed to reprovision: invalid HTTP status code
Jan 16 08:33:33 uptime-plus-3001842402 aziot-edged[8810]: 2025-01-16T08:33:33Z [INFO] - Obtaining Edge device provisioning data...
Jan 16 08:33:33 uptime-plus-3001842402 aziot-identityd[8886]: 2025-01-16T08:33:33Z [INFO] - <-- POST /identities/device?api-version=2020-09-01 {"content-type": "application/json", "host": "identityd.sock", "content-length": "16"}
Jan 16 08:33:33 uptime-plus-3001842402 aziot-identityd[8886]: 2025-01-16T08:33:33Z [INFO] - !!! device identity not found
Jan 16 08:33:33 uptime-plus-3001842402 aziot-identityd[8886]: 2025-01-16T08:33:33Z [INFO] - --> 400 {"content-type": "application/json"}
Jan 16 08:33:33 uptime-plus-3001842402 aziot-edged[8810]: 2025-01-16T08:33:33Z [WARN] - Failed to obtain device identity: device identity not found
Jan 16 08:33:33 uptime-plus-3001842402 aziot-edged[8810]: 2025-01-16T08:33:33Z [INFO] - Requesting device reprovision
Jan 16 08:33:33 uptime-plus-3001842402 aziot-edged[8810]: 2025-01-16T08:33:33Z [WARN] - Failed to clear provisioning cache before reprovision: No such file or directory (os error 2)
Jan 16 08:33:33 uptime-plus-3001842402 aziot-identityd[8886]: 2025-01-16T08:33:33Z [INFO] - <-- POST /identities/device/reprovision?api-version=2020-09-01 {"content-type": "application/json", "host": "identityd.sock", "content-length": "16"}
Jan 16 08:33:33 uptime-plus-3001842402 aziot-identityd[8886]: 2025-01-16T08:33:33Z [INFO] - API called by user: Uid(700)
Jan 16 08:33:33 uptime-plus-3001842402 aziot-identityd[8886]: 2025-01-16T08:33:33Z [INFO] - Provisioning starting. Reason: Api
Jan 16 08:33:33 uptime-plus-3001842402 aziot-certd[8823]: 2025-01-16T08:33:33Z [INFO] - <-- GET /certificates/device-id?api-version=2020-09-01 {"host": "certd.sock"}
Jan 16 08:33:33 uptime-plus-3001842402 aziot-certd[8823]: 2025-01-16T08:33:33Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 08:33:33 uptime-plus-3001842402 aziot-keyd[8831]: 2025-01-16T08:33:33Z [INFO] - <-- GET /keypair/device-id?api-version=2021-05-01 {"host": "keyd.sock"}
Jan 16 08:33:33 uptime-plus-3001842402 aziot-keyd[8831]: 2025-01-16T08:33:33Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 08:33:33 uptime-plus-3001842402 aziot-keyd[8831]: 2025-01-16T08:33:33Z [INFO] - <-- POST /parameters/algorithm?api-version=2021-05-01 {"content-length": "248", "content-type": "application/json"}
Jan 16 08:33:33 uptime-plus-3001842402 aziot-keyd[8831]: 2025-01-16T08:33:33Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 08:33:33 uptime-plus-3001842402 aziot-keyd[8831]: 2025-01-16T08:33:33Z [INFO] - <-- POST /parameters/rsa-modulus?api-version=2021-05-01 {"content-length": "248", "content-type": "application/json"}
Jan 16 08:33:33 uptime-plus-3001842402 aziot-keyd[8831]: 2025-01-16T08:33:33Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 08:33:33 uptime-plus-3001842402 aziot-keyd[8831]: 2025-01-16T08:33:33Z [INFO] - <-- POST /parameters/rsa-exponent?api-version=2021-05-01 {"content-length": "248", "content-type": "application/json"}
Jan 16 08:33:33 uptime-plus-3001842402 aziot-keyd[8831]: 2025-01-16T08:33:33Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 08:33:33 uptime-plus-3001842402 aziot-identityd[8886]: 2025-01-16T08:33:33Z [INFO] - Sending DPS registration request.
Jan 16 08:33:33 uptime-plus-3001842402 aziot-keyd[8831]: 2025-01-16T08:33:33Z [INFO] - <-- POST /encrypt?api-version=2021-05-01 {"content-length": "636", "content-type": "application/json"}
Jan 16 08:33:34 uptime-plus-3001842402 aziot-keyd[8831]: 2025-01-16T08:33:34Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 08:33:34 uptime-plus-3001842402 aziot-identityd[8886]: 2025-01-16T08:33:34Z [INFO] - <-- GET http://foo/identities/identity?api-version=2020-09-01 {"host": "/run/aziot/identityd.sock:0", "content-length": "0"}
Jan 16 08:33:39 uptime-plus-3001842402 aziot-identityd[8886]: 2025-01-16T08:33:39Z [INFO] - Checking DPS registration status.
Jan 16 08:33:39 uptime-plus-3001842402 aziot-keyd[8831]: 2025-01-16T08:33:39Z [INFO] - <-- POST /encrypt?api-version=2021-05-01 {"content-length": "636", "content-type": "application/json"}
Jan 16 08:33:40 uptime-plus-3001842402 aziot-keyd[8831]: 2025-01-16T08:33:40Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 08:33:41 uptime-plus-3001842402 aziot-identityd[8886]: 2025-01-16T08:33:41Z [INFO] - !!! DPS client error
Jan 16 08:33:41 uptime-plus-3001842402 aziot-identityd[8886]: 2025-01-16T08:33:41Z [INFO] - !!! caused by: Custom allocation failed with status code: 400
Jan 16 08:33:41 uptime-plus-3001842402 aziot-identityd[8886]: 2025-01-16T08:33:41Z [INFO] - --> 404 {"content-type": "application/json"}
Jan 16 08:33:41 uptime-plus-3001842402 aziot-identityd[8886]: 2025-01-16T08:33:41Z [INFO] - !!! device identity not found
Jan 16 08:33:41 uptime-plus-3001842402 aziot-identityd[8886]: 2025-01-16T08:33:41Z [INFO] - --> 400 {"content-type": "application/json"}
Jan 16 08:33:41 uptime-plus-3001842402 aziot-edged[8810]: 2025-01-16T08:33:41Z [WARN] - Failed to reprovision: invalid HTTP status code
Jan 16 08:33:46 uptime-plus-3001842402 aziot-edged[8810]: 2025-01-16T08:33:46Z [INFO] - Obtaining Edge device provisioning data...
Jan 16 08:33:46 uptime-plus-3001842402 aziot-edged[8810]: 2025-01-16T08:33:46Z [WARN] - Failed to obtain device identity: device identity not found
Jan 16 08:33:46 uptime-plus-3001842402 aziot-edged[8810]: 2025-01-16T08:33:46Z [INFO] - Requesting device reprovision
Jan 16 08:33:46 uptime-plus-3001842402 aziot-edged[8810]: 2025-01-16T08:33:46Z [WARN] - Failed to clear provisioning cache before reprovision: No such file or directory (os error 2)
Jan 16 08:33:46 uptime-plus-3001842402 aziot-identityd[8886]: 2025-01-16T08:33:46Z [INFO] - <-- POST /identities/device?api-version=2020-09-01 {"content-type": "application/json", "host": "identityd.sock", "content-length": "16"}
Jan 16 08:33:46 uptime-plus-3001842402 aziot-identityd[8886]: 2025-01-16T08:33:46Z [INFO] - !!! device identity not found
Jan 16 08:33:46 uptime-plus-3001842402 aziot-identityd[8886]: 2025-01-16T08:33:46Z [INFO] - --> 400 {"content-type": "application/json"}
Jan 16 08:33:46 uptime-plus-3001842402 aziot-identityd[8886]: 2025-01-16T08:33:46Z [INFO] - <-- POST /identities/device/reprovision?api-version=2020-09-01 {"content-type": "application/json", "host": "identityd.sock", "content-length": "16"}
Jan 16 08:33:46 uptime-plus-3001842402 aziot-identityd[8886]: 2025-01-16T08:33:46Z [INFO] - API called by user: Uid(700)
Jan 16 08:33:46 uptime-plus-3001842402 aziot-identityd[8886]: 2025-01-16T08:33:46Z [INFO] - Provisioning starting. Reason: Api
Jan 16 08:33:46 uptime-plus-3001842402 aziot-certd[8823]: 2025-01-16T08:33:46Z [INFO] - <-- GET /certificates/device-id?api-version=2020-09-01 {"host": "certd.sock"}
Jan 16 08:33:46 uptime-plus-3001842402 aziot-certd[8823]: 2025-01-16T08:33:46Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 08:33:46 uptime-plus-3001842402 aziot-keyd[8831]: 2025-01-16T08:33:46Z [INFO] - <-- GET /keypair/device-id?api-version=2021-05-01 {"host": "keyd.sock"}
Jan 16 08:33:46 uptime-plus-3001842402 aziot-keyd[8831]: 2025-01-16T08:33:46Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 08:33:46 uptime-plus-3001842402 aziot-keyd[8831]: 2025-01-16T08:33:46Z [INFO] - <-- POST /parameters/algorithm?api-version=2021-05-01 {"content-length": "248", "content-type": "application/json"}
Jan 16 08:33:46 uptime-plus-3001842402 aziot-keyd[8831]: 2025-01-16T08:33:46Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 08:33:46 uptime-plus-3001842402 aziot-keyd[8831]: 2025-01-16T08:33:46Z [INFO] - <-- POST /parameters/rsa-modulus?api-version=2021-05-01 {"content-length": "248", "content-type": "application/json"}
Jan 16 08:33:46 uptime-plus-3001842402 aziot-keyd[8831]: 2025-01-16T08:33:46Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 08:33:46 uptime-plus-3001842402 aziot-keyd[8831]: 2025-01-16T08:33:46Z [INFO] - <-- POST /parameters/rsa-exponent?api-version=2021-05-01 {"content-length": "248", "content-type": "application/json"}
Jan 16 08:33:46 uptime-plus-3001842402 aziot-keyd[8831]: 2025-01-16T08:33:46Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 08:33:46 uptime-plus-3001842402 aziot-identityd[8886]: 2025-01-16T08:33:46Z [INFO] - Sending DPS registration request.
Jan 16 08:33:46 uptime-plus-3001842402 aziot-keyd[8831]: 2025-01-16T08:33:46Z [INFO] - <-- POST /encrypt?api-version=2021-05-01 {"content-length": "636", "content-type": "application/json"}
Jan 16 08:33:46 uptime-plus-3001842402 aziot-keyd[8831]: 2025-01-16T08:33:46Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 08:33:46 uptime-plus-3001842402 aziot-identityd[8886]: 2025-01-16T08:33:46Z [INFO] - <-- GET http://foo/identities/identity?api-version=2020-09-01 {"host": "/run/aziot/identityd.sock:0", "content-length": "0"}
Jan 16 08:33:52 uptime-plus-3001842402 aziot-identityd[8886]: 2025-01-16T08:33:52Z [INFO] - Checking DPS registration status.
Jan 16 08:33:52 uptime-plus-3001842402 aziot-keyd[8831]: 2025-01-16T08:33:52Z [INFO] - <-- POST /encrypt?api-version=2021-05-01 {"content-length": "636", "content-type": "application/json"}
Jan 16 08:33:53 uptime-plus-3001842402 aziot-keyd[8831]: 2025-01-16T08:33:53Z [INFO] - --> 200 {"content-type": "application/json"}
Jan 16 08:33:53 uptime-plus-3001842402 aziot-identityd[8886]: 2025-01-16T08:33:53Z [INFO] - !!! DPS client error
Jan 16 08:33:53 uptime-plus-3001842402 aziot-identityd[8886]: 2025-01-16T08:33:53Z [INFO] - !!! caused by: Custom allocation failed with status code: 400
Jan 16 08:33:53 uptime-plus-3001842402 aziot-identityd[8886]: 2025-01-16T08:33:53Z [INFO] - --> 404 {"content-type": "application/json"}
Jan 16 08:33:53 uptime-plus-3001842402 aziot-identityd[8886]: 2025-01-16T08:33:53Z [INFO] - !!! device identity not found
Jan 16 08:33:53 uptime-plus-3001842402 aziot-identityd[8886]: 2025-01-16T08:33:53Z [INFO] - --> 400 {"content-type": "application/json"}
Jan 16 08:33:53 uptime-plus-3001842402 aziot-edged[8810]: 2025-01-16T08:33:53Z [WARN] - Failed to reprovision: invalid HTTP status code

To fix this for our case, i simply patched edgelet/aziot-edged/src/provision.rs like 6f61f95 to also not trigger the reprovision on (os error 104).

Patch Again, i'm not familiar with Rust, so there are probably better ways to achive this.
From 549aacb61cde4959c42855ece633997863c495d1 Mon Sep 17 00:00:00 2001
From: *
Date: Thu, 16 Jan 2025 13:07:37 +0100
Subject: [PATCH] do not trigger reprovisioning at identityd on os error 104

---
 edgelet/aziot-edged/src/provision.rs | 26 ++++++++++++++++----------
 1 file changed, 16 insertions(+), 10 deletions(-)

diff --git a/edgelet/aziot-edged/src/provision.rs b/edgelet/aziot-edged/src/provision.rs
index 932ccd1f3d..a519110803 100644
--- a/edgelet/aziot-edged/src/provision.rs
+++ b/edgelet/aziot-edged/src/provision.rs
@@ -60,16 +60,22 @@ pub(crate) async fn get_device_info(
                 // returned by Identity Service itself. Errors such as connection timeouts and
                 // permission errors should not trigger a reprovision, as these generally mean
                 // that Identity Service has not yet fully started.
-                if err.kind() == std::io::ErrorKind::Other {
-                    log::info!("Requesting device reprovision");
-
-                    if let Err(err) = reprovision(identity_client, cache_dir).await {
-                        log::warn!("Failed to reprovision: {}", err);
-                    }
-                } else {
-                    log::warn!(
-                        "Identity Service was unreachable. Waiting for Identity Service startup."
-                    );
+
+                if err.kind() == std::io::ErrorKind::Other
+                    && !err.to_string().contains("os error 104") {
+                        log::info!("Requesting device reprovision");
+
+                        if let Err(err) = reprovision(identity_client, cache_dir).await {
+                            log::warn!("Failed to reprovision: {}", err);
+                        }
+                }
+                else {
+                    let reason = if err.to_string().contains("os error 104") {
+                        "(due to os error 104)"
+                    } else {
+                        ""
+                    };
+                    log::warn!("Identity Service was unreachable {reason}. Waiting for Identity Service startup.");
                 }
 
                 tokio::time::sleep(std::time::Duration::from_secs(5)).await;
-- 
2.34.1


@nyanzebra
Copy link
Contributor

@aleupo The fix mentioned is for offline scenarios. Which doesn't seem to be your case? From speaking with my colleague on this, it appears that what might be happening is a race condition between identityd on startup and edged on failure to provision. With DPS things just work because things respond with 200 in both cases, but that might not be the case with your custom DPS allocator...

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants