Often unable to see container logs due to "error from daemon in stream: Error grabbing logs: log message is too large" #7177

bhjertaas · 2023-12-18T11:54:13Z

Expected Behavior

When running
sudo iotedge logs edgeAgent or the identical sudo docker logs edgeAgent I expect the log file being printed.

Current Behavior

Instead the output is error from daemon in stream: Error grabbing logs: log message is too large (108229732 > 1000000) or the slightly shorter version Error grabbing logs: log message is too large (1937007727 > 1000000).

The first number in brackets are not always the same, but it is still larger than 1000000.
How can this be possible. Local logging driver is supposed to rotate the log files.
When we look at the /var/lib/docker/containers//local-logs/container.log is is only 896K. Far smaller than the configured limit.

Is this related to moby/moby#46699 ?

We have also seen Error grabbing logs: error unmarshalling log entry (size=126): proto: LogEntry: illegal tag 0 (wire type 0) but that is less commonly seen than the too large error.

Steps to Reproduce

Provide a detailed set of steps to reproduce the bug.

Install EFLOW on Windows 10 or 11 and set logging driver to 'local' by making /etc/docker/daemon.json like this. (yes I know those log-opts contain default values, but I added them to remove 'iotedge check' warnings. That check seems unaware that local logging driver has log rotation by default).

{
  "log-driver": "local",
  "log-opts": {
    "max-size": "20m",
    "max-file": "5"
  }
}

sudo systemctl daemon-reload && sudo systemctl restart docker
provision device to DPS which is linked to an IoT Hub
The modules that are then automatically deployed to the Edge is confirmed to have local logging driver by running docker inspect
After some time running (a couple of days I reckon), you are unable to run the sudo iotedge logs edgeHub (or most other component) command and instead see the mentioned error message

Context (Environment)

Output of `iotedge check`

Click here


Configuration checks (aziot-identity-service)
---------------------------------------------
√ keyd configuration is well-formed - OK
√ certd configuration is well-formed - OK
√ tpmd configuration is well-formed - OK
√ identityd configuration is well-formed - OK
√ daemon configurations up-to-date with config.toml - OK
√ identityd config toml file specifies a valid hostname - OK
‼ aziot-identity-service package is up-to-date - Warning
    Installed aziot-identity-service package has version 1.4.6 but 1.4.7 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
√ preloaded certificates are valid - OK
√ keyd is running - OK
√ certd is running - OK
√ identityd is running - OK
√ read all preloaded certificates from the Certificates Service - OK
√ read all preloaded key pairs from the Keys Service - OK
√ check all EST server URLs utilize HTTPS - OK
√ ensure all preloaded certificates match preloaded private keys with the same ID - OK

Connectivity checks (aziot-identity-service)
--------------------------------------------
‼ host can connect to and perform TLS handshake with iothub AMQP port - 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 - OK
‼ aziot-edge package is up-to-date - Warning
    Installed IoT Edge daemon has version 1.4.20 but 1.4.27 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 - OK
√ production readiness: Edge Agent's storage directory is persisted on the host filesystem - OK
√ production readiness: Edge Hub's storage directory is persisted on the host filesystem - OK
√ proxy settings are consistent in aziot-edged, aziot-identityd, moby daemon and config.toml - OK

Connectivity checks
-------------------
25 check(s) succeeded.
6 check(s) raised warnings. 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 [e.g. Ubuntu 22.04, Windows Server IoT 2019]: EFLOW 1.4.10.25103 on Windows 11
Architecture [e.g. amd64, arm32, arm64]: x64
Container OS [e.g. Linux containers, Windows containers]: Mariner Linux (in Eflow)

Runtime Versions

aziot-edged [run iotedge version]: 1.4.20
Edge Agent [image tag (e.g. 1.0.0)]: 1.4.25.82955152
Edge Hub [image tag (e.g. 1.0.0)]:
Docker/Moby [run docker version]: 20.10.25

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

Logs

aziot-edged logs


Dec 18 11:28:41 DESKTOP-5SO2V9I-EFLOW aziot-edged[1582]: 2023-12-18T11:28:41Z [INFO] - <-- GET /modules?api-version=2022-08-03 {"accept": "application/json", "host": "mgmt.sock:80", "connection": "close"}
Dec 18 11:28:41 DESKTOP-5SO2V9I-EFLOW aziot-edged[1582]: 2023-12-18T11:28:41Z [INFO] - --> 200 {"content-type": "application/json"}
Dec 18 11:28:46 DESKTOP-5SO2V9I-EFLOW aziot-edged[1582]: 2023-12-18T11:28:46Z [INFO] - <-- GET /modules?api-version=2022-08-03 {"accept": "application/json", "host": "mgmt.sock:80", "connection": "close"}
Dec 18 11:28:46 DESKTOP-5SO2V9I-EFLOW aziot-edged[1582]: 2023-12-18T11:28:46Z [INFO] - --> 200 {"content-type": "application/json"}
Dec 18 11:28:51 DESKTOP-5SO2V9I-EFLOW aziot-edged[1582]: 2023-12-18T11:28:51Z [INFO] - <-- GET /modules?api-version=2022-08-03 {"accept": "application/json", "host": "mgmt.sock:80", "connection": "close"}
Dec 18 11:28:51 DESKTOP-5SO2V9I-EFLOW aziot-edged[1582]: 2023-12-18T11:28:51Z [INFO] - --> 200 {"content-type": "application/json"}
Dec 18 11:28:56 DESKTOP-5SO2V9I-EFLOW aziot-edged[1582]: 2023-12-18T11:28:56Z [INFO] - <-- GET /modules?api-version=2022-08-03 {"accept": "application/json", "host": "mgmt.sock:80", "connection": "close"}
Dec 18 11:28:56 DESKTOP-5SO2V9I-EFLOW aziot-edged[1582]: 2023-12-18T11:28:56Z [INFO] - --> 200 {"content-type": "application/json"}
Dec 18 11:29:01 DESKTOP-5SO2V9I-EFLOW aziot-edged[1582]: 2023-12-18T11:29:01Z [INFO] - <-- GET /modules?api-version=2022-08-03 {"accept": "application/json", "host": "mgmt.sock:80", "connection": "close"}
Dec 18 11:29:01 DESKTOP-5SO2V9I-EFLOW aziot-edged[1582]: 2023-12-18T11:29:01Z [INFO] - --> 200 {"content-type": "application/json"}
Dec 18 11:29:06 DESKTOP-5SO2V9I-EFLOW aziot-edged[1582]: 2023-12-18T11:29:06Z [INFO] - <-- GET /modules?api-version=2022-08-03 {"accept": "application/json", "host": "mgmt.sock:80", "connection": "close"}
Dec 18 11:29:06 DESKTOP-5SO2V9I-EFLOW aziot-edged[1582]: 2023-12-18T11:29:06Z [INFO] - --> 200 {"content-type": "application/json"}
Dec 18 11:29:11 DESKTOP-5SO2V9I-EFLOW aziot-edged[1582]: 2023-12-18T11:29:11Z [INFO] - <-- GET /modules?api-version=2022-08-03 {"accept": "application/json", "host": "mgmt.sock:80", "connection": "close"}
Dec 18 11:29:11 DESKTOP-5SO2V9I-EFLOW aziot-edged[1582]: 2023-12-18T11:29:11Z [INFO] - --> 200 {"content-type": "application/json"}
Dec 18 11:29:13 DESKTOP-5SO2V9I-EFLOW aziot-edged[1582]: 2023-12-18T11:29:13Z [INFO] - Watchdog checking Edge runtime status
Dec 18 11:29:13 DESKTOP-5SO2V9I-EFLOW aziot-edged[1582]: 2023-12-18T11:29:13Z [INFO] - Edge runtime is running
Dec 18 11:29:16 DESKTOP-5SO2V9I-EFLOW aziot-edged[1582]: 2023-12-18T11:29:16Z [INFO] - <-- GET /modules?api-version=2022-08-03 {"accept": "application/json", "host": "mgmt.sock:80", "connection": "close"}
Dec 18 11:29:16 DESKTOP-5SO2V9I-EFLOW aziot-edged[1582]: 2023-12-18T11:29:16Z [INFO] - --> 200 {"content-type": "application/json"}
Dec 18 11:29:16 DESKTOP-5SO2V9I-EFLOW aziot-edged[1582]: 2023-12-18T11:29:16Z [INFO] - <-- POST /modules/%24edgeAgent/genid/638359810750134474/encrypt?api-version=2022-08-03 {"accept": "application/json", "host": "workload.sock:80", "connection": "close", "content-type": "application/json", "content-length": "4142"}
Dec 18 11:29:16 DESKTOP-5SO2V9I-EFLOW aziot-keyd[1586]: 2023-12-18T11:29:16Z [INFO] - <-- POST /key?api-version=2020-09-01 {"content-type": "application/json", "host": "keyd.sock", "content-length": "74"}
Dec 18 11:29:16 DESKTOP-5SO2V9I-EFLOW aziot-keyd[1586]: 2023-12-18T11:29:16Z [INFO] - --> 200 {"content-type": "application/json"}
Dec 18 11:29:16 DESKTOP-5SO2V9I-EFLOW aziot-keyd[1586]: 2023-12-18T11:29:16Z [INFO] - <-- POST /encrypt?api-version=2020-09-01 {"content-type": "application/json", "host": "keyd.sock", "content-length": "4474"}
Dec 18 11:29:16 DESKTOP-5SO2V9I-EFLOW aziot-keyd[1586]: 2023-12-18T11:29:16Z [INFO] - --> 200 {"content-type": "application/json"}
Dec 18 11:29:16 DESKTOP-5SO2V9I-EFLOW aziot-edged[1582]: 2023-12-18T11:29:16Z [INFO] - --> 200 {"content-type": "application/json"}
Dec 18 11:29:21 DESKTOP-5SO2V9I-EFLOW aziot-edged[1582]: 2023-12-18T11:29:21Z [INFO] - <-- GET /modules?api-version=2022-08-03 {"accept": "application/json", "host": "mgmt.sock:80", "connection": "close"}
Dec 18 11:29:21 DESKTOP-5SO2V9I-EFLOW aziot-edged[1582]: 2023-12-18T11:29:21Z [INFO] - --> 200 {"content-type": "application/json"}
Dec 18 11:29:21 DESKTOP-5SO2V9I-EFLOW aziot-edged[1582]: 2023-12-18T11:29:21Z [INFO] - <-- POST /modules/%24edgeAgent/genid/638359810750134474/encrypt?api-version=2022-08-03 {"accept": "application/json", "host": "workload.sock:80", "connection": "close", "content-type": "application/json", "content-length": "4142"}
Dec 18 11:29:21 DESKTOP-5SO2V9I-EFLOW aziot-keyd[1586]: 2023-12-18T11:29:21Z [INFO] - <-- POST /key?api-version=2020-09-01 {"content-type": "application/json", "host": "keyd.sock", "content-length": "74"}
Dec 18 11:29:21 DESKTOP-5SO2V9I-EFLOW aziot-keyd[1586]: 2023-12-18T11:29:21Z [INFO] - --> 200 {"content-type": "application/json"}
Dec 18 11:29:21 DESKTOP-5SO2V9I-EFLOW aziot-keyd[1586]: 2023-12-18T11:29:21Z [INFO] - <-- POST /encrypt?api-version=2020-09-01 {"content-type": "application/json", "host": "keyd.sock", "content-length": "4474"}
Dec 18 11:29:21 DESKTOP-5SO2V9I-EFLOW aziot-keyd[1586]: 2023-12-18T11:29:21Z [INFO] - --> 200 {"content-type": "application/json"}
Dec 18 11:29:21 DESKTOP-5SO2V9I-EFLOW aziot-edged[1582]: 2023-12-18T11:29:21Z [INFO] - --> 200 {"content-type": "application/json"}
Dec 18 11:29:26 DESKTOP-5SO2V9I-EFLOW aziot-edged[1582]: 2023-12-18T11:29:26Z [INFO] - <-- GET /modules?api-version=2022-08-03 {"accept": "application/json", "host": "mgmt.sock:80", "connection": "close"}
Dec 18 11:29:26 DESKTOP-5SO2V9I-EFLOW aziot-edged[1582]: 2023-12-18T11:29:26Z [INFO] - --> 200 {"content-type": "application/json"}
Dec 18 11:29:31 DESKTOP-5SO2V9I-EFLOW aziot-edged[1582]: 2023-12-18T11:29:31Z [INFO] - <-- GET /modules?api-version=2022-08-03 {"accept": "application/json", "host": "mgmt.sock:80", "connection": "close"}
Dec 18 11:29:31 DESKTOP-5SO2V9I-EFLOW aziot-edged[1582]: 2023-12-18T11:29:31Z [INFO] - --> 200 {"content-type": "application/json"}
Dec 18 11:29:36 DESKTOP-5SO2V9I-EFLOW aziot-edged[1582]: 2023-12-18T11:29:36Z [INFO] - <-- GET /modules?api-version=2022-08-03 {"accept": "application/json", "host": "mgmt.sock:80", "connection": "close"}
Dec 18 11:29:36 DESKTOP-5SO2V9I-EFLOW aziot-edged[1582]: 2023-12-18T11:29:36Z [INFO] - --> 200 {"content-type": "application/json"}
Dec 18 11:29:41 DESKTOP-5SO2V9I-EFLOW aziot-edged[1582]: 2023-12-18T11:29:41Z [INFO] - <-- GET /modules?api-version=2022-08-03 {"accept": "application/json", "host": "mgmt.sock:80", "connection": "close"}
Dec 18 11:29:41 DESKTOP-5SO2V9I-EFLOW aziot-edged[1582]: 2023-12-18T11:29:41Z [INFO] - --> 200 {"content-type": "application/json"}
Dec 18 11:29:46 DESKTOP-5SO2V9I-EFLOW aziot-edged[1582]: 2023-12-18T11:29:46Z [INFO] - <-- GET /modules?api-version=2022-08-03 {"accept": "application/json", "host": "mgmt.sock:80", "connection": "close"}
Dec 18 11:29:46 DESKTOP-5SO2V9I-EFLOW aziot-edged[1582]: 2023-12-18T11:29:46Z [INFO] - --> 200 {"content-type": "application/json"}

edge-agent logs (retrieved by sudo cat /var/lib/docker/containers//local-logs/container.log

THE FILE HAD MORE HISTORIC DATA, BUT I CONSIDERED IT TO MUCH TO POST HERE

stdout�ȳ����⸮S<6> 2023-12-12 20:30:53.246 +00:00 [INF] - Executing command: "Stop module edgeHub"gh
stdout��؞���⸮T<6> 2023-12-12 20:30:53.247 +00:00 [INF] - Executing command: "Start module edgeHub"hk
stdout����⸮W<6> 2023-12-12 20:30:53.884 +00:00 [INF] - Executing command: "Saving edgeHub to store"k�
stdout�Ѥ����⸮�<6> 2023-12-12 20:30:53.884 +00:00 [INF] - Executing command: "Command Group: (\n  [Stop module IoTEdgeMetricsCollector]\n  [Start module IoTEdgeMetricsCollector]\n  [Saving IoTEdgeMetricsCollector to store]\n)"�w
stdout�ܤ����⸮c<6> 2023-12-12 20:30:53.884 +00:00 [INF] - Executing command: "Stop module IoTEdgeMetricsCollector"wx
stdout������⸮d<6> 2023-12-12 20:30:53.886 +00:00 [INF] - Executing command: "Start module IoTEdgeMetricsCollector"x{
stdoutø׫���⸮g<6> 2023-12-12 20:30:54.615 +00:00 [INF] - Executing command: "Saving IoTEdgeMetricsCollector to store"{e
stdout�������⸮Q<6> 2023-12-12 20:30:54.618 +00:00 [INF] - Plan execution ended for deployment 45eZ
stdout��Ѣ����⸮F<6> 2023-12-12 20:30:59.967 +00:00 [INF] - Updated reported propertiesZ<
stdout�����ĩ�⸮(2023-12-14 08:42:06  Starting Edge Agent<p
stdout��π�ĩ�⸮\2023-12-14 08:42:06  Changing ownership of storage folder: /tmp/edgeAgent/edgeAgent to 13622pl
stdout�瞁�ĩ�⸮X2023-12-14 08:42:06  Changing ownership of backup folder: /tmp/edgeAgent_backup to 13622ll
stdout��ځ�ĩ�⸮X2023-12-14 08:42:06  Changing ownership of management socket: /var/run/iotedge/mgmt.socklX
stdout��Ȃ�ĩ�⸮D2023-12-14 08:42:06  Completed necessary setup. Starting Edge Agent.XD
stdout��뾨ĩ�⸮02023-12-14 08:42:06.369 +00:00 Edge Agent Main()DW
stdout�����ĩ�⸮C<6> 2023-12-14 08:42:06.554 +00:00 [INF] - Initializing Edge Agent.W�
stdout���٩ĩ�⸮o<6> 2023-12-14 08:42:06.708 +00:00 [INF] - Version - 1.4.25.82955152 (8846287bfff028b19016e7d69f988d4dce3a802a)�?
stdout���٩ĩ�⸮+<6> 2023-12-14 08:42:06.709 +00:00 [INF] - ?�
stdout���٩ĩ�⸮v        █████╗ ███████╗██╗   ██╗██████╗ ███████╗��
stdout���٩ĩ�⸮|       ██╔══██╗╚══███╔╝██║   ██║██╔══██╗██╔════╝��
stdout���٩ĩ�⸮p       ███████║  ███╔╝ ██║   ██║██████╔╝█████╗��
stdout��٩ĩ�⸮p       ██╔══██║ ███╔╝  ██║   ██║██╔══██╗██╔══╝��
stdout���٩ĩ�⸮z       ██║  ██║███████╗╚██████╔╝██║  ██║███████╗��
stdout���٩ĩ�⸮v       ╚═╝  ╚═╝╚══════╝ ╚═════╝ ╚═╝  ╚═╝╚══════╝�
stdout���٩ĩ��
stdout��٩ĩ�⸮� ██╗ ██████╗ ████████╗    ███████╗██████╗  ██████╗ ███████╗��
stdout���٩ĩ�⸮� ██║██╔═══██╗╚══██╔══╝    ██╔════╝██╔══██╗██╔════╝ ██╔════╝��
stdout���٩ĩ�⸮� ██║██║   ██║   ██║       █████╗  ██║  ██║██║  ███╗█████╗��
stdout���٩ĩ�⸮� ██║██║   ██║   ██║       ██╔══╝  ██║  ██║██║   ██║██╔══╝��
stdout���٩ĩ�⸮� ██║╚██████╔╝   ██║       ███████╗██████╔╝╚██████╔╝███████╗��
stdout���٩ĩ�⸮� ╚═╝ ╚═════╝    ╚═╝       ╚══════╝╚═════╝  ╚═════╝ ╚══════╝�
stdout���٩ĩ�\
stdout�ŋ۩ĩ�⸮H<6> 2023-12-14 08:42:06.711 +00:00 [INF] - ModuleUpdateMode: NonBlocking\�
stdout�����ĩ�⸮�<6> 2023-12-14 08:42:06.767 +00:00 [INF] - Experimental features configuration: {"Enabled":false,"DisableCloudSubscriptions":false}��
stdoutȳ���ĩ�⸮�<6> 2023-12-14 08:42:06.924 +00:00 [INF] - Installing certificates [CN=aziot-edge CA 2D430238-E772-416A-A44A-0B37B2E591FD:02/18/2024 10:05:58] to Root��
stdout�����ĩ�⸮l<6> 2023-12-14 08:42:07.085 +00:00 [INF] - Starting metrics listener on Host: *, Port: 9600, Suffix: metrics�i
stdout����ĩ�⸮U<6> 2023-12-14 08:42:07.106 +00:00 [INF] - Updating performance metrics every 05m:00sie
stdout�����ĩ�⸮Q<6> 2023-12-14 08:42:07.113 +00:00 [INF] - Started operation Get system resourceseZ
stdout͊���ĩ�⸮F<6> 2023-12-14 08:42:07.114 +00:00 [INF] - Collecting metadata metricsZ'
stdout�ǁ��ĩ�⸮�<6> 2023-12-14 08:42:07.185 +00:00 [INF] - Set metadata metrics: 1.4.25.82955152 (8846287bfff028b19016e7d69f988d4dce3a802a), {"Enabled":false,"DisableCloudSubscriptions":false}, {"OperatingSystemType":"Linux","Architecture":"x86_64","Version":"1.4.20","Provisioning":{"Type":"ProvisioningType","DynamicReprovisioning":false,"AlwaysReprovisionOnStartup":false},"ServerVersion":"20.10.25","KernelVersion":"#1 SMP Wed Oct 4 21:29:50 UTC 2023","OperatingSystem":"mariner","NumCpus":1,"TotalMemory":937254912,"Virtualized":"yes"}, True'h
stdout拫ȫĩ�⸮T<6> 2023-12-14 08:42:07.209 +00:00 [INF] - Started operation Checkpoint Availabilityhd
stdout���˫ĩ�⸮P<6> 2023-12-14 08:42:07.215 +00:00 [INF] - Started operation refresh twin configd
stdoutޝ�׫ĩ�⸮k<6> 2023-12-14 08:42:07.241 +00:00 [INF] - Edge agent attempting to connect to IoT Hub via Amqp_Tcp_Only...s
stdout�����ĩ�⸮_<6> 2023-12-14 08:42:07.589 +00:00 [INF] - Created persistent store at /tmp/edgeAgent/edgeAgents_
stdout��紭ĩ�⸮K<6> 2023-12-14 08:42:07.705 +00:00 [INF] - Started operation Metrics Scrape__
stdout�����ĩ�⸮K<6> 2023-12-14 08:42:07.712 +00:00 [INF] - Started operation Metrics Upload_0
stdout�����ĩ�⸮Scraping frequency: 01:00:0000
stdout�ɬ��ĩ�⸮Upload Frequency: 1.00:00:000k
stdout�ͧ�ĩ�⸮W<6> 2023-12-14 08:42:08.346 +00:00 [INF] - Registering request handler UploadModuleLogskh
stdout����ĩ�⸮T<6> 2023-12-14 08:42:08.346 +00:00 [INF] - Registering request handler GetModuleLogshn
stdout����ĩ�⸮Z<6> 2023-12-14 08:42:08.346 +00:00 [INF] - Registering request handler UploadSupportBundlenh
stdout����ĩ�⸮T<6> 2023-12-14 08:42:08.346 +00:00 [INF] - Registering request handler RestartModuleh�
stdout�����ĩ�⸮�<4> 2023-12-14 08:42:13.584 +00:00 [WRN] - Empty edge agent config was received. Attempting to read config from backup (/tmp/edgeAgent/edgeAgent/backup.json) instead��
stdout��˱�ĩ�⸮�<6> 2023-12-14 08:42:13.603 +00:00 [INF] - Obtained edge agent config from backup config file - /tmp/edgeAgent/edgeAgent/backup.json��
stdout����ĩ�⸮o<6> 2023-12-14 08:42:13.733 +00:00 [INF] - Module 'cloudSyncStorage' scheduled to restart after 20s (09s left).��
stdout۵���ĩ�⸮{<6> 2023-12-14 08:42:13.733 +00:00 [INF] - Module 'cloudToDeviceMessageReceiver' scheduled to restart after 20s (09s left).�z
stdout�����ĩ�⸮f<6> 2023-12-14 08:42:13.733 +00:00 [INF] - Module 'edgeHub' scheduled to restart after 20s (09s left).z�
stdout�����ĩ�⸮v<6> 2023-12-14 08:42:13.733 +00:00 [INF] - Module 'IoTEdgeMetricsCollector' scheduled to restart after 20s (09s left).��
stdout�����ĩ�⸮q<6> 2023-12-14 08:42:13.734 +00:00 [INF] - Module 'moduleClientBridge' scheduled to restart after 20s (09s left).�q
stdoutŋ��ĩ�⸮]<6> 2023-12-14 08:42:14.063 +00:00 [INF] - Edge agent connected to IoT Hub via Amqp_Tcp_Only.qw
stdout����ĩ�⸮c<6> 2023-12-14 08:42:14.152 +00:00 [INF] - Initialized new module client with subscriptions enabledw�
stdout���ĩ�⸮�<6> 2023-12-14 08:42:14.200 +00:00 [INF] - Obtained Edge agent twin from IoTHub with desired properties version 45 and reported properties version 138.��
stdout����ĩ�⸮o<6> 2023-12-14 08:42:18.761 +00:00 [INF] - Module 'cloudSyncStorage' scheduled to restart after 20s (04s left).��
stdout����ĩ�⸮{<6> 2023-12-14 08:42:18.762 +00:00 [INF] - Module 'cloudToDeviceMessageReceiver' scheduled to restart after 20s (04s left).�z
stdout�����ĩ�⸮f<6> 2023-12-14 08:42:18.762 +00:00 [INF] - Module 'edgeHub' scheduled to restart after 20s (04s left).z�
stdout�����ĩ�⸮v<6> 2023-12-14 08:42:18.762 +00:00 [INF] - Module 'IoTEdgeMetricsCollector' scheduled to restart after 20s (04s left).��
stdout�ӯ��ĩ�⸮q<6> 2023-12-14 08:42:18.762 +00:00 [INF] - Module 'moduleClientBridge' scheduled to restart after 20s (04s left).�Z
stdout჻��ĩ�⸮F<6> 2023-12-14 08:42:19.008 +00:00 [INF] - Updated reported propertiesZg
stdout��ܟ�ĩ�⸮S<6> 2023-12-14 08:42:24.035 +00:00 [INF] - Plan execution started for deployment 45g�
stdoutԻ���ĩ�⸮�<6> 2023-12-14 08:42:24.038 +00:00 [INF] - Executing command: "Command Group: (\n  [Stop module cloudSyncStorage]\n  [Start module cloudSyncStorage]\n  [Saving cloudSyncStorage to store]\n)"�p
stdoutХ��ĩ�⸮\<6> 2023-12-14 08:42:24.042 +00:00 [INF] - Executing command: "Stop module cloudSyncStorage"pq
stdoutȨΨ�ĩ�⸮]<6> 2023-12-14 08:42:24.054 +00:00 [INF] - Executing command: "Start module cloudSyncStorage"qt
stdout�Ե��ĩ�⸮`<6> 2023-12-14 08:42:24.301 +00:00 [INF] - Executing command: "Saving cloudSyncStorage to store"t�
stdout�����ĩ�⸮�<6> 2023-12-14 08:42:24.304 +00:00 [INF] - Executing command: "Command Group: (\n  [Stop module cloudToDeviceMessageReceiver]\n  [Start module cloudToDeviceMessageReceiver]\n  [Saving cloudToDeviceMessageReceiver to store]\n)"�|
stdoutޱ���ĩ�⸮h<6> 2023-12-14 08:42:24.305 +00:00 [INF] - Executing command: "Stop module cloudToDeviceMessageReceiver"|}
stdout��Ҡ�ĩ�⸮i<6> 2023-12-14 08:42:24.306 +00:00 [INF] - Executing command: "Start module cloudToDeviceMessageReceiver"}�
stdout�����ĩ�⸮l<6> 2023-12-14 08:42:24.604 +00:00 [INF] - Executing command: "Saving cloudToDeviceMessageReceiver to store"��
stdout�׾��ĩ�⸮�<6> 2023-12-14 08:42:24.604 +00:00 [INF] - Executing command: "Command Group: (\n  [Stop module edgeHub]\n  [Start module edgeHub]\n  [Saving edgeHub to store]\n)"�g
stdout�ƿ��ĩ�⸮S<6> 2023-12-14 08:42:24.604 +00:00 [INF] - Executing command: "Stop module edgeHub"gh
stdout���ĩ�⸮T<6> 2023-12-14 08:42:24.606 +00:00 [INF] - Executing command: "Start module edgeHub"hk
stdout���ĩ�⸮W<6> 2023-12-14 08:42:25.090 +00:00 [INF] - Executing command: "Saving edgeHub to store"k�
stdout�����ĩ�⸮�<6> 2023-12-14 08:42:25.090 +00:00 [INF] - Executing command: "Command Group: (\n  [Stop module IoTEdgeMetricsCollector]\n  [Start module IoTEdgeMetricsCollector]\n  [Saving IoTEdgeMetricsCollector to store]\n)"�w
stdout�����ĩ�⸮c<6> 2023-12-14 08:42:25.090 +00:00 [INF] - Executing command: "Stop module IoTEdgeMetricsCollector"wx
stdout�����ĩ�⸮d<6> 2023-12-14 08:42:25.091 +00:00 [INF] - Executing command: "Start module IoTEdgeMetricsCollector"x{
stdout���ĩ�⸮g<6> 2023-12-14 08:42:25.694 +00:00 [INF] - Executing command: "Saving IoTEdgeMetricsCollector to store"{�
stdoutʷ���ĩ�⸮�<6> 2023-12-14 08:42:25.694 +00:00 [INF] - Executing command: "Command Group: (\n  [Stop module moduleClientBridge]\n  [Start module moduleClientBridge]\n  [Saving moduleClientBridge to store]\n)"�r
stdout�½��ĩ�⸮^<6> 2023-12-14 08:42:25.694 +00:00 [INF] - Executing command: "Stop module moduleClientBridge"rs
stdout�����ĩ�⸮_<6> 2023-12-14 08:42:25.701 +00:00 [INF] - Executing command: "Start module moduleClientBridge"sv
stdout�����ĩ�⸮b<6> 2023-12-14 08:42:26.410 +00:00 [INF] - Executing command: "Saving moduleClientBridge to store"ve
stdout�����ĩ�⸮Q<6> 2023-12-14 08:42:26.411 +00:00 [INF] - Plan execution ended for deployment 45eZ
stdout�Ǯ�ũ�⸮F<6> 2023-12-14 08:42:31.710 +00:00 [INF] - Updated reported propertiesZ�
stdout��Ë�֩�⸮�<6> 2023-12-14 08:52:24.751 +00:00 [INF] - HealthRestartPlanner is clearing restart stats for module 'cloudSyncStorage' as it has been running healthy for 00:10:00.��
stdout��ڋ�֩�⸮�<6> 2023-12-14 08:52:24.751 +00:00 [INF] - HealthRestartPlanner is clearing restart stats for module 'cloudToDeviceMessageReceiver' as it has been running healthy for 00:10:00.�g
stdoutɌ���֩�⸮S<6> 2023-12-14 08:52:24.752 +00:00 [INF] - Plan execution started for deployment 45gt
stdoutݯ���֩�⸮`<6> 2023-12-14 08:52:24.752 +00:00 [INF] - Executing command: "Saving cloudSyncStorage to store"t�
stdout�ߏ��֩�⸮l<6> 2023-12-14 08:52:24.759 +00:00 [INF] - Executing command: "Saving cloudToDeviceMessageReceiver to store"�e
stdout�����֩�⸮Q<6> 2023-12-14 08:52:24.759 +00:00 [INF] - Plan execution ended for deployment 45e�
stdout����֩�⸮�<6> 2023-12-14 08:52:29.785 +00:00 [INF] - HealthRestartPlanner is clearing restart stats for module 'edgeHub' as it has been running healthy for 00:10:00.��
stdout����֩�⸮�<6> 2023-12-14 08:52:29.785 +00:00 [INF] - HealthRestartPlanner is clearing restart stats for module 'IoTEdgeMetricsCollector' as it has been running healthy for 00:10:00.��
stdoutʆ��֩�⸮�<6> 2023-12-14 08:52:29.785 +00:00 [INF] - HealthRestartPlanner is clearing restart stats for module 'moduleClientBridge' as it has been running healthy for 00:10:00.�g
stdout����֩�⸮S<6> 2023-12-14 08:52:29.786 +00:00 [INF] - Plan execution started for deployment 45gk
stdout����֩�⸮W<6> 2023-12-14 08:52:29.786 +00:00 [INF] - Executing command: "Saving edgeHub to store"k{
stdoutλ��֩�⸮g<6> 2023-12-14 08:52:29.786 +00:00 [INF] - Executing command: "Saving IoTEdgeMetricsCollector to store"{v
stdout�؅�֩�⸮b<6> 2023-12-14 08:52:29.786 +00:00 [INF] - Executing command: "Saving moduleClientBridge to store"ve
stdout���֩�⸮Q<6> 2023-12-14 08:52:29.786 +00:00 [INF] - Plan execution ended for deployment 45eZ
stdout��Ի�֩�⸮F<6> 2023-12-14 08:52:29.953 +00:00 [INF] - Updated reported propertiesZZ
stdout����֩�⸮F<6> 2023-12-14 08:52:35.109 +00:00 [INF] - Updated reported propertiesZq
stdout���Ў���⸮]<6> 2023-12-14 09:42:07.214 +00:00 [INF] - Starting periodic operation refresh twin config...q�
stdout��ߎ���⸮�<6> 2023-12-14 09:42:07.245 +00:00 [INF] - Obtained Edge agent twin from IoTHub with desired properties version 45 and reported properties version 142.�|
stdout���ߎ���⸮h<6> 2023-12-14 09:42:07.246 +00:00 [INF] - Successfully completed periodic operation refresh twin config|l
stdout�֒�����⸮X<6> 2023-12-14 09:42:07.704 +00:00 [INF] - Starting periodic operation Metrics Scrape...lO
stdout��鼐���⸮;<6> 2023-12-14 09:42:07.710 +00:00 [INF] - Scraping MetricsOl
stdout��������⸮X<6> 2023-12-14 09:42:07.717 +00:00 [INF] - Scraping endpoint http://edgeHub:9600/metricsln
stdout���ِ���⸮Z<6> 2023-12-14 09:42:07.770 +00:00 [INF] - Scraping endpoint http://edgeAgent:9600/metricsnN
stdout��ᐭ��⸮:<6> 2023-12-14 09:42:07.786 +00:00 [INF] - Storing MetricsNY
stdout��������⸮E<6> 2023-12-14 09:42:07.850 +00:00 [INF] - Scraped and Stored MetricsYw
stdout��������⸮c<6> 2023-12-14 09:42:07.850 +00:00 [INF] - Successfully completed periodic operation Metrics Scrapew�
stdout�ŭ����⸮�<6> 2023-12-15 06:58:22.667 +00:00 [INF] - Obtained Edge agent twin from IoTHub with desired properties version 45 and reported properties version 142.�q
stdout���Ԗü�⸮]<6> 2023-12-15 07:54:10.120 +00:00 [INF] - Starting periodic operation refresh twin config...q�
stdout����ü�⸮�<6> 2023-12-15 07:54:10.163 +00:00 [INF] - Obtained Edge agent twin from IoTHub with desired properties version 45 and reported properties version 142.�|
stdout����ü�⸮h<6> 2023-12-15 07:54:10.164 +00:00 [INF] - Successfully completed periodic operation refresh twin config|\
stdout�ߓ��ü�⸮H<6> 2023-12-15 07:54:10.475 +00:00 [INF] - Starting compaction of stores\c
stdoutԽ���ü�⸮O<6> 2023-12-15 07:54:10.475 +00:00 [INF] - Starting compaction of store Metricscc
stdout�����ü�⸮O<6> 2023-12-15 07:54:10.486 +00:00 [INF] - Starting compaction of store defaultcg
stdout�į��ü�⸮S<6> 2023-12-15 07:54:10.486 +00:00 [INF] - Starting compaction of store moduleStategl
stdout�����ü�⸮X<6> 2023-12-15 07:54:10.486 +00:00 [INF] - Starting compaction of store deploymentConfigll
stdout����ü�⸮X<6> 2023-12-15 07:54:10.722 +00:00 [INF] - Starting periodic operation Metrics Scrape...lO
stdout����ü�⸮;<6> 2023-12-15 07:54:10.722 +00:00 [INF] - Scraping MetricsOl
stdout����ü�⸮X<6> 2023-12-15 07:54:10.722 +00:00 [INF] - Scraping endpoint http://edgeHub:9600/metricsln
stdoutȖ���ü�⸮Z<6> 2023-12-15 07:54:10.737 +00:00 [INF] - Scraping endpoint http://edgeAgent:9600/metricsnN
stdoutō���ü�⸮:<6> 2023-12-15 07:54:10.756 +00:00 [INF] - Storing MetricsNY
stdout��ü�⸮E<6> 2023-12-15 07:54:10.766 +00:00 [INF] - Scraped and Stored MetricsYw
stdout���ü�⸮c<6> 2023-12-15 07:54:10.766 +00:00 [INF] - Successfully completed periodic operation Metrics Scrapewq
stdout�ݵ�����⸮]<6> 2023-12-15 08:54:10.164 +00:00 [INF] - Starting periodic operation refresh twin config...q�
stdout��������⸮�<6> 2023-12-15 08:54:10.196 +00:00 [INF] - Obtained Edge agent twin from IoTHub with desired properties version 45 and reported properties version 142.�|
stdout��������⸮h<6> 2023-12-15 08:54:10.198 +00:00 [INF] - Successfully completed periodic operation refresh twin config|l
stdout�涍����⸮X<6> 2023-12-15 08:54:10.766 +00:00 [INF] - Starting periodic operation Metrics Scrape...lO
stdoutӌ������⸮;<6> 2023-12-15 08:54:10.766 +00:00 [INF] - Scraping MetricsOl
stdoutǼ������⸮X<6> 2023-12-15 08:54:10.766 +00:00 [INF] - Scraping endpoint http://edgeHub:9600/metricsln
stdout�������⸮Z<6> 2023-12-15 08:54:10.773 +00:00 [INF] - Scraping endpoint http://edgeAgent:9600/metricsnN
stdout��������⸮:<6> 2023-12-15 08:54:10.789 +00:00 [INF] - Storing MetricsNY
stdout�睟����⸮E<6> 2023-12-15 08:54:10.803 +00:00 [INF] - Scraped and Stored MetricsYw
stdout��������⸮c<6> 2023-12-15 08:54:10.803 +00:00 [INF] - Successfully completed periodic operation Metrics Scrapew�
stdout�������⸮�<6> 2023-12-18 07:02:28.741 +00:00 [INF] - Obtained Edge agent twin from IoTHub with desired properties version 45 and reported properties version 142.�q
stdout��������⸮]<6> 2023-12-18 07:26:45.772 +00:00 [INF] - Starting periodic operation refresh twin config...q�
stdout��έ����⸮�<6> 2023-12-18 07:26:45.807 +00:00 [INF] - Obtained Edge agent twin from IoTHub with desired properties version 45 and reported properties version 142.�|
stdout��������⸮h<6> 2023-12-18 07:26:45.808 +00:00 [INF] - Successfully completed periodic operation refresh twin config|\
stdout�ƻ�����⸮H<6> 2023-12-18 07:26:46.033 +00:00 [INF] - Starting compaction of stores\c
stdout�Ù����⸮O<6> 2023-12-18 07:26:46.033 +00:00 [INF] - Starting compaction of store Metricscc
stdout̬Ӟ����⸮O<6> 2023-12-18 07:26:46.044 +00:00 [INF] - Starting compaction of store defaultcg
stdout��מ����⸮S<6> 2023-12-18 07:26:46.044 +00:00 [INF] - Starting compaction of store moduleStategl
stdout��ច���⸮X<6> 2023-12-18 07:26:46.044 +00:00 [INF] - Starting compaction of store deploymentConfigll
stdout��ʼ����⸮X<6> 2023-12-18 07:26:46.375 +00:00 [INF] - Starting periodic operation Metrics Scrape...lO
stdout��ϼ����⸮;<6> 2023-12-18 07:26:46.375 +00:00 [INF] - Scraping MetricsOl
stdout��Ҽ����⸮X<6> 2023-12-18 07:26:46.375 +00:00 [INF] - Scraping endpoint http://edgeHub:9600/metricsln
stdout�Ā�����⸮Z<6> 2023-12-18 07:26:46.384 +00:00 [INF] - Scraping endpoint http://edgeAgent:9600/metricsnN
stdout�֫ǆ���⸮:<6> 2023-12-18 07:26:46.398 +00:00 [INF] - Storing MetricsNY
stdout���ʆ���⸮E<6> 2023-12-18 07:26:46.405 +00:00 [INF] - Scraped and Stored MetricsYw
stdout���ʆ���⸮c<6> 2023-12-18 07:26:46.405 +00:00 [INF] - Successfully completed periodic operation Metrics Scrapew�
stdout��������⸮�<6> 2023-12-18 07:58:34.128 +00:00 [INF] - Obtained Edge agent twin from IoTHub with desired properties version 45 and reported properties version 142.��
stdout�޺����⸮�<6> 2023-12-18 08:12:03.743 +00:00 [INF] - Obtained Edge agent twin from IoTHub with desired properties version 45 and reported properties version 142.��
stdout��������⸮�<6> 2023-12-18 08:17:08.168 +00:00 [INF] - Obtained Edge agent twin from IoTHub with desired properties version 45 and reported properties version 142.�q
stdout��ݶ����⸮]<6> 2023-12-18 08:26:45.811 +00:00 [INF] - Starting periodic operation refresh twin config...q�
stdout��������⸮�<6> 2023-12-18 08:26:45.849 +00:00 [INF] - Obtained Edge agent twin from IoTHub with desired properties version 45 and reported properties version 142.�|
stdout��������⸮h<6> 2023-12-18 08:26:45.851 +00:00 [INF] - Successfully completed periodic operation refresh twin config|l
stdout��������⸮X<6> 2023-12-18 08:26:46.403 +00:00 [INF] - Starting periodic operation Metrics Scrape...lO
stdout��������⸮;<6> 2023-12-18 08:26:46.404 +00:00 [INF] - Scraping MetricsOl
stdout��������⸮X<6> 2023-12-18 08:26:46.404 +00:00 [INF] - Scraping endpoint http://edgeHub:9600/metricsln
stdout��������⸮Z<6> 2023-12-18 08:26:46.428 +00:00 [INF] - Scraping endpoint http://edgeAgent:9600/metricsnN
stdout�ʖ�����⸮:<6> 2023-12-18 08:26:46.438 +00:00 [INF] - Storing MetricsNY
stdout�Ս�����⸮E<6> 2023-12-18 08:26:46.452 +00:00 [INF] - Scraped and Stored MetricsYw
stdout�������⸮c<6> 2023-12-18 08:26:46.452 +00:00 [INF] - Successfully completed periodic operation Metrics Scrape

edge-hub logs


stdoutԶ������⸮V<6> 2023-12-18 11:19:21.266 +00:00 [INF] - Updated message store TTL to 259200 secondsjs
stdout�������⸮_<6> 2023-12-18 11:19:21.266 +00:00 [INF] - Updated the edge hub store and forward configurationsc
stdout���՘���⸮O<6> 2023-12-18 11:19:21.314 +00:00 [INF] - Started operation Get EdgeHub configca
stdout���՘���⸮M<6> 2023-12-18 11:19:21.314 +00:00 [INF] - Initialized edge hub configurationae
stdout���ט���⸮Q<6> 2023-12-18 11:19:21.318 +00:00 [INF] - Starting protocol heads - (AMQP, HTTP)eQ
stdout���ژ���⸮=<6> 2023-12-18 11:19:21.324 +00:00 [INF] - Starting AMQP headQP
stdoutň������⸮<<6> 2023-12-18 11:19:21.525 +00:00 [INF] - Started AMQP headPQ
stdoutꩂ�����⸮=<6> 2023-12-18 11:19:21.528 +00:00 [INF] - Starting HTTP headQu
stdout��������⸮a<6> 2023-12-18 11:19:21.791 +00:00 [INF] - Not changed node: 2D430238-E772-416A-A44A-0B37B2E591FDu�
stdout�脾����⸮l<6> 2023-12-18 11:19:21.798 +00:00 [INF] - Not changed node: 2D430238-E772-416A-A44A-0B37B2E591FD/$edgeAgent�z
stdout��������⸮f<6> 2023-12-18 11:19:21.798 +00:00 [INF] - Updated node: 2D430238-E772-416A-A44A-0B37B2E591FD/$edgeHubz�
stdout�֐�����⸮�<6> 2023-12-18 11:19:21.969 +00:00 [INF] - Service identity for 2D430238-E772-416A-A44A-0B37B2E591FD/$edgeHub in device scope was updated.��
stdout�Ξ�����⸮r<6> 2023-12-18 11:19:21.969 +00:00 [INF] - Not changed node: 2D430238-E772-416A-A44A-0B37B2E591FD/cloudSyncStorage��
stdout��������⸮t<6> 2023-12-18 11:19:21.969 +00:00 [INF] - Not changed node: 2D430238-E772-416A-A44A-0B37B2E591FD/moduleClientBridge��
stdout�穎����⸮~<6> 2023-12-18 11:19:21.969 +00:00 [INF] - Not changed node: 2D430238-E772-416A-A44A-0B37B2E591FD/cloudToDeviceMessageReceiver��
stdout��������⸮y<6> 2023-12-18 11:19:21.969 +00:00 [INF] - Not changed node: 2D430238-E772-416A-A44A-0B37B2E591FD/IoTEdgeMetricsCollector��
stdout�а�����⸮w<6> 2023-12-18 11:19:21.969 +00:00 [INF] - Not changed node: 2D430238-E772-416A-A44A-0B37B2E591FD/DefenderIotMicroAgent��
stdoutґА����⸮q<6> 2023-12-18 11:19:21.974 +00:00 [INF] - Done refreshing device scope identities cache. Waiting for 60 minutes.�Y
stdout�؉�����⸮E<6> 2023-12-18 11:19:22.061 +00:00 [INF] - Exiting disconnected stateYa
stdout���ϛ���⸮M<6> 2023-12-18 11:19:22.107 +00:00 [INF] - Received device connected callbacka�
stdout��⛡��⸮u<6> 2023-12-18 11:19:22.143 +00:00 [INF] - Device connected to cloud, processing subscriptions for connected clients.��
stdout���⛡��⸮�<6> 2023-12-18 11:19:22.143 +00:00 [INF] - Processing subscriptions for client 2D430238-E772-416A-A44A-0B37B2E591FD/$edgeHub on device connected to cloud.��
stdout���⛡��⸮�<6> 2023-12-18 11:19:22.143 +00:00 [INF] - Skipping 2D430238-E772-416A-A44A-0B37B2E591FD/$edgeHub for subscription processing, as it is currently being processed.��
stdout���⛡��⸮n<6> 2023-12-18 11:19:22.144 +00:00 [INF] - Skipping cache refresh, waiting 119 seconds until refreshing again.�W
stdout�����⸮C<6> 2023-12-18 11:19:22.173 +00:00 [INF] - Entering connected stateW�
stdout�����⸮u<6> 2023-12-18 11:19:22.179 +00:00 [INF] - Cloud connection for 2D430238-E772-416A-A44A-0B37B2E591FD/$edgeHub is True��
stdout��������⸮�<6> 2023-12-18 11:19:22.185 +00:00 [INF] - Connection status for 2D430238-E772-416A-A44A-0B37B2E591FD/$edgeHub changed to ConnectionEstablished��
stdout��������⸮�<4> 2023-12-18 11:19:22.184 +00:00 [WRN] - Overriding address(es) '"http://+:80"'. Binding to endpoints defined via IConfiguration and/or UseKestrel() instead.��
stdout�Ų�����⸮�<6> 2023-12-18 11:19:22.207 +00:00 [INF] - Client 2D430238-E772-416A-A44A-0B37B2E591FD/$edgeHub connected to cloud, processing existing subscriptions.��
stdout��������⸮�<6> 2023-12-18 11:19:22.207 +00:00 [INF] - Skipping 2D430238-E772-416A-A44A-0B37B2E591FD/$edgeHub for subscription processing, as it is currently being processed.��
stdout��ӈ����⸮�<6> 2023-12-18 11:19:22.223 +00:00 [INF] - Created cloud proxy for client 2D430238-E772-416A-A44A-0B37B2E591FD/$edgeHub via AMQP, with client operation timeout 20 seconds.��
stdout��ӈ����⸮�<6> 2023-12-18 11:19:22.225 +00:00 [INF] - Initialized cloud proxy 399147b2-29e4-452a-8e4f-78a8160d1557 for 2D430238-E772-416A-A44A-0B37B2E591FD/$edgeHub��
stdout܈������⸮|<6> 2023-12-18 11:19:22.230 +00:00 [INF] - Created cloud connection for client 2D430238-E772-416A-A44A-0B37B2E591FD/$edgeHub�P
stdoutո������⸮<<6> 2023-12-18 11:19:22.240 +00:00 [INF] - Started HTTP headP�
stdout��������⸮}<6> 2023-12-18 11:19:22.518 +00:00 [INF] - Processing pending subscriptions for 2D430238-E772-416A-A44A-0B37B2E591FD/$edgeHub��
stdout�𠤝���⸮x<6> 2023-12-18 11:19:22.552 +00:00 [INF] - Updated reported properties for 2D430238-E772-416A-A44A-0B37B2E591FD/$edgeHub�h
stdout޹������⸮T<6> 2023-12-18 11:19:22.809 +00:00 [INF] - Obtained edge hub config from module twinhg
stdout���ݞ���⸮S<6> 2023-12-18 11:19:22.940 +00:00 [INF] - Set the following 3 route(s) in edge hubg�
stdout���ߞ���⸮�<6> 2023-12-18 11:19:22.944 +00:00 [INF] - bridgeMachineData2upstream: FROM /messages/modules/moduleClientBridge/outputs/package into $upstream��
stdout��ߞ���⸮�<6> 2023-12-18 11:19:22.944 +00:00 [INF] - bridgeNotificationTask2upstream: FROM /messages/modules/moduleClientBridge/outputs/notificationTask INTO $upstream��
stdout�ζߞ���⸮�<6> 2023-12-18 11:19:22.944 +00:00 [INF] - messageFromCloud2downstream: FROM /messages/modules/cloudToDeviceMessageReceiver/outputs/C2D INTO BrokeredEndpoint("/modules/moduleClientBridge/inputs/C2D")�j
stdout���ߞ���⸮V<6> 2023-12-18 11:19:22.945 +00:00 [INF] - Updated message store TTL to 259200 secondsjs
stdout֐�ߞ���⸮_<6> 2023-12-18 11:19:22.945 +00:00 [INF] - Updated the edge hub store and forward configurationsa
stdout�߹�����⸮M<6> 2023-12-18 11:19:23.611 +00:00 [INF] - New token received on the Cbs linkaa
stdout���̡���⸮M<6> 2023-12-18 11:19:23.709 +00:00 [INF] - New token received on the Cbs linka�
stdout���ۡ���⸮�<6> 2023-12-18 11:19:23.742 +00:00 [INF] - Client 2D430238-E772-416A-A44A-0B37B2E591FD/cloudSyncStorage in device scope authenticated locally.��
stdout���⡡��⸮�<6> 2023-12-18 11:19:23.756 +00:00 [INF] - New device connection for device 2D430238-E772-416A-A44A-0B37B2E591FD/cloudSyncStorage��
stdout���㡡��⸮�<6> 2023-12-18 11:19:23.757 +00:00 [INF] - Client 2D430238-E772-416A-A44A-0B37B2E591FD/cloudSyncStorage connected to edgeHub, processing existing subscriptions.��
stdout���䡡��⸮�<6> 2023-12-18 11:19:23.760 +00:00 [INF] - Client 2D430238-E772-416A-A44A-0B37B2E591FD/moduleClientBridge in device scope authenticated locally.��
stdout���塡��⸮�<6> 2023-12-18 11:19:23.763 +00:00 [INF] - New device connection for device 2D430238-E772-416A-A44A-0B37B2E591FD/moduleClientBridge��
stdout���塡��⸮�<6> 2023-12-18 11:19:23.763 +00:00 [INF] - Client 2D430238-E772-416A-A44A-0B37B2E591FD/moduleClientBridge connected to edgeHub, processing existing subscriptions.��
stdout���桡��⸮�<6> 2023-12-18 11:19:23.765 +00:00 [INF] - Attempting to connect to IoT Hub for client 2D430238-E772-416A-A44A-0B37B2E591FD/moduleClientBridge via AMQP...��
stdout���桡��⸮�<6> 2023-12-18 11:19:23.765 +00:00 [INF] - Attempting to connect to IoT Hub for client 2D430238-E772-416A-A44A-0B37B2E591FD/cloudSyncStorage via AMQP...��
stdout���顡��⸮<6> 2023-12-18 11:19:23.771 +00:00 [INF] - Bind device proxy for device 2D430238-E772-416A-A44A-0B37B2E591FD/moduleClientBridge��
stdout���顡��⸮�<6> 2023-12-18 11:19:23.771 +00:00 [INF] - Initialized device listener in the AMQP protocol head for 2D430238-E772-416A-A44A-0B37B2E591FD/moduleClientBridge��
stdout��롡��⸮y<6> 2023-12-18 11:19:23.774 +00:00 [INF] - Opened link Events for 2D430238-E772-416A-A44A-0B37B2E591FD/moduleClientBridge��
stdout�����⸮}<6> 2023-12-18 11:19:23.779 +00:00 [INF] - Bind device proxy for device 2D430238-E772-416A-A44A-0B37B2E591FD/cloudSyncStorage��
stdout�����⸮�<6> 2023-12-18 11:19:23.779 +00:00 [INF] - Initialized device listener in the AMQP protocol head for 2D430238-E772-416A-A44A-0B37B2E591FD/cloudSyncStorage��
stdout�����⸮w<6> 2023-12-18 11:19:23.779 +00:00 [INF] - Opened link Events for 2D430238-E772-416A-A44A-0B37B2E591FD/cloudSyncStorage��
stdout��������⸮�<6> 2023-12-18 11:19:23.812 +00:00 [INF] - Processing pending subscriptions for 2D430238-E772-416A-A44A-0B37B2E591FD/moduleClientBridge��
stdout��݁����⸮�<6> 2023-12-18 11:19:23.818 +00:00 [INF] - Opened link ModuleMessages for 2D430238-E772-416A-A44A-0B37B2E591FD/moduleClientBridge��
stdout��Ĝ����⸮|<6> 2023-12-18 11:19:23.878 +00:00 [INF] - Opened link TwinSending for 2D430238-E772-416A-A44A-0B37B2E591FD/cloudSyncStorage��
stdout┓�����⸮~<6> 2023-12-18 11:19:23.881 +00:00 [INF] - Opened link TwinReceiving for 2D430238-E772-416A-A44A-0B37B2E591FD/cloudSyncStorage��
stdout��̠����⸮}<6> 2023-12-18 11:19:23.886 +00:00 [INF] - Cloud connection for 2D430238-E772-416A-A44A-0B37B2E591FD/cloudSyncStorage is True��
stdout��נ����⸮�<6> 2023-12-18 11:19:23.887 +00:00 [INF] - Connection status for 2D430238-E772-416A-A44A-0B37B2E591FD/cloudSyncStorage changed to ConnectionEstablished��
stdout��ݠ����⸮�<6> 2023-12-18 11:19:23.887 +00:00 [INF] - Client 2D430238-E772-416A-A44A-0B37B2E591FD/cloudSyncStorage connected to cloud, processing existing subscriptions.��
stdout�ᠢ���⸮�<6> 2023-12-18 11:19:23.887 +00:00 [INF] - Skipping 2D430238-E772-416A-A44A-0B37B2E591FD/cloudSyncStorage for subscription processing, as it is currently being processed.��
stdoutҡ砢���⸮�<6> 2023-12-18 11:19:23.887 +00:00 [INF] - Created cloud proxy for client 2D430238-E772-416A-A44A-0B37B2E591FD/cloudSyncStorage via AMQP, with client operation timeout 20 seconds.��
stdout�����⸮�<6> 2023-12-18 11:19:23.887 +00:00 [INF] - Initialized cloud proxy f97347d1-76b1-44dc-8f06-fc4c9afbdf7e for 2D430238-E772-416A-A44A-0B37B2E591FD/cloudSyncStorage��
stdout��󠢡��⸮�<6> 2023-12-18 11:19:23.887 +00:00 [INF] - Created cloud connection for client 2D430238-E772-416A-A44A-0B37B2E591FD/cloudSyncStorage��
stdout��������⸮<6> 2023-12-18 11:19:23.888 +00:00 [INF] - Cloud connection for 2D430238-E772-416A-A44A-0B37B2E591FD/moduleClientBridge is True��
stdout��ơ����⸮�<6> 2023-12-18 11:19:23.888 +00:00 [INF] - Connection status for 2D430238-E772-416A-A44A-0B37B2E591FD/moduleClientBridge changed to ConnectionEstablished��
stdout��̡����⸮�<6> 2023-12-18 11:19:23.888 +00:00 [INF] - Client 2D430238-E772-416A-A44A-0B37B2E591FD/moduleClientBridge connected to cloud, processing existing subscriptions.��
stdoutܠС����⸮�<6> 2023-12-18 11:19:23.889 +00:00 [INF] - Skipping 2D430238-E772-416A-A44A-0B37B2E591FD/moduleClientBridge for subscription processing, as it is currently being processed.��
stdout�ʂ�����⸮�<6> 2023-12-18 11:19:23.894 +00:00 [INF] - Created cloud proxy for client 2D430238-E772-416A-A44A-0B37B2E591FD/moduleClientBridge via AMQP, with client operation timeout 20 seconds.��
stdout𤊤����⸮�<6> 2023-12-18 11:19:23.894 +00:00 [INF] - Initialized cloud proxy 78748ab9-7e89-4e2e-8c08-9f2daf30c65d for 2D430238-E772-416A-A44A-0B37B2E591FD/moduleClientBridge��
stdout��������⸮�<6> 2023-12-18 11:19:23.894 +00:00 [INF] - Created cloud connection for client 2D430238-E772-416A-A44A-0B37B2E591FD/moduleClientBridge��
stdout��̤����⸮~<6> 2023-12-18 11:19:23.895 +00:00 [INF] - Opened link TwinSending for 2D430238-E772-416A-A44A-0B37B2E591FD/moduleClientBridge��
stdout��ᥢ���⸮�<6> 2023-12-18 11:19:23.897 +00:00 [INF] - Opened link TwinReceiving for 2D430238-E772-416A-A44A-0B37B2E591FD/moduleClientBridge��
stdout���Ƣ���⸮�<6> 2023-12-18 11:19:23.965 +00:00 [INF] - Processing pending subscriptions for 2D430238-E772-416A-A44A-0B37B2E591FD/cloudSyncStorage��
stdout���Ƣ���⸮�<6> 2023-12-18 11:19:23.965 +00:00 [INF] - Processing pending subscriptions for 2D430238-E772-416A-A44A-0B37B2E591FD/moduleClientBridge��
stdout���ߥ���⸮x<6> 2023-12-18 11:19:24.823 +00:00 [INF] - Updated reported properties for 2D430238-E772-416A-A44A-0B37B2E591FD/$edgeHub��
stdout��������⸮�<6> 2023-12-18 11:19:25.010 +00:00 [INF] - Updated reported properties for 2D430238-E772-416A-A44A-0B37B2E591FD/moduleClientBridge�~
stdout�ؽ����⸮j<6> 2023-12-18 11:20:19.331 +00:00 [INF] - "Request starting HTTP/1.1 GET http://edgehub:9600/metrics - -"~�
stdout�������⸮�<6> 2023-12-18 11:20:19.391 +00:00 [INF] - "Request finished HTTP/1.1 GET http://edgehub:9600/metrics - - - 200 - text/plain;+version=0.0.4;+charset=utf-8 61.8813ms"�a
stdout�������⸮M<6> 2023-12-18 11:20:20.174 +00:00 [INF] - New token received on the Cbs linka�
stdout�꧇���⸮�<6> 2023-12-18 11:20:20.205 +00:00 [INF] - Client 2D430238-E772-416A-A44A-0B37B2E591FD/IoTEdgeMetricsCollector in device scope authenticated locally.��
stdout������⸮�<6> 2023-12-18 11:20:20.205 +00:00 [INF] - New device connection for device 2D430238-E772-416A-A44A-0B37B2E591FD/IoTEdgeMetricsCollector��
stdout������⸮�<6> 2023-12-18 11:20:20.205 +00:00 [INF] - Client 2D430238-E772-416A-A44A-0B37B2E591FD/IoTEdgeMetricsCollector connected to edgeHub, processing existing subscriptions.��
stdout�ǻ����⸮�<6> 2023-12-18 11:20:20.207 +00:00 [INF] - Bind device proxy for device 2D430238-E772-416A-A44A-0B37B2E591FD/IoTEdgeMetricsCollector��
stdout�ɾ����⸮�<6> 2023-12-18 11:20:20.207 +00:00 [INF] - Initialized device listener in the AMQP protocol head for 2D430238-E772-416A-A44A-0B37B2E591FD/IoTEdgeMetricsCollector��
stdoutܓÈ���⸮~<6> 2023-12-18 11:20:20.207 +00:00 [INF] - Opened link Events for 2D430238-E772-416A-A44A-0B37B2E591FD/IoTEdgeMetricsCollector��
stdout�����⸮�<6> 2023-12-18 11:20:20.217 +00:00 [INF] - Attempting to connect to IoT Hub for client 2D430238-E772-416A-A44A-0B37B2E591FD/IoTEdgeMetricsCollector via AMQP...��
stdout�������⸮�<6> 2023-12-18 11:20:20.316 +00:00 [INF] - Cloud connection for 2D430238-E772-416A-A44A-0B37B2E591FD/IoTEdgeMetricsCollector is True��
stdout�ټ���⸮�<6> 2023-12-18 11:20:20.316 +00:00 [INF] - Connection status for 2D430238-E772-416A-A44A-0B37B2E591FD/IoTEdgeMetricsCollector changed to ConnectionEstablished��
stdout��ټ���⸮�<6> 2023-12-18 11:20:20.316 +00:00 [INF] - Client 2D430238-E772-416A-A44A-0B37B2E591FD/IoTEdgeMetricsCollector connected to cloud, processing existing subscriptions.��
stdout��ټ���⸮�<6> 2023-12-18 11:20:20.316 +00:00 [INF] - Skipping 2D430238-E772-416A-A44A-0B37B2E591FD/IoTEdgeMetricsCollector for subscription processing, as it is currently being processed.��
stdout��ټ���⸮�<6> 2023-12-18 11:20:20.317 +00:00 [INF] - Created cloud proxy for client 2D430238-E772-416A-A44A-0B37B2E591FD/IoTEdgeMetricsCollector via AMQP, with client operation timeout 20 seconds.��
stdout��ټ���⸮�<6> 2023-12-18 11:20:20.317 +00:00 [INF] - Initialized cloud proxy c930c323-757e-4c4f-b900-9ae10774f296 for 2D430238-E772-416A-A44A-0B37B2E591FD/IoTEdgeMetricsCollector��
stdout��ټ���⸮�<6> 2023-12-18 11:20:20.317 +00:00 [INF] - Created cloud connection for client 2D430238-E772-416A-A44A-0B37B2E591FD/IoTEdgeMetricsCollector��
stdout�������⸮x<6> 2023-12-18 11:20:20.452 +00:00 [INF] - Updated reported properties for 2D430238-E772-416A-A44A-0B37B2E591FD/$edgeHub�y
stdout�������⸮e<6> 2023-12-18 11:24:20.276 +00:00 [INF] - Entering periodic task to reauthenticate connected clientsy~
stdout����ӫ��⸮j<6> 2023-12-18 11:25:20.815 +00:00 [INF] - "Request starting HTTP/1.1 GET http://edgehub:9600/metrics - -"~�
stdout����ӫ��⸮�<6> 2023-12-18 11:25:20.816 +00:00 [INF] - "Request finished HTTP/1.1 GET http://edgehub:9600/metrics - - - 200 - text/plain;+version=0.0.4;+charset=utf-8 1.4325ms"�y
stdout�З�ϲ��⸮e<6> 2023-12-18 11:29:20.273 +00:00 [INF] - Entering periodic task to reauthenticate connected clientsy~
stdout�ЋƳ���⸮j<6> 2023-12-18 11:30:21.363 +00:00 [INF] - "Request starting HTTP/1.1 GET http://edgehub:9600/metrics - -"~�
stdout�ӹƳ���⸮�<6> 2023-12-18 11:30:21.363 +00:00 [INF] - "Request finished HTTP/1.1 GET http://edgehub:9600/metrics - - - 200 - text/plain;+version=0.0.4;+charset=utf-8 0.3625ms"�y
stdout���ǭ���⸮e<6> 2023-12-18 11:34:20.275 +00:00 [INF] - Entering periodic task to reauthenticate connected clientsy~
stdout���ϒ���⸮j<6> 2023-12-18 11:35:21.762 +00:00 [INF] - "Request starting HTTP/1.1 GET http://edgehub:9600/metrics - -"~�
stdout���ϒ���⸮�<6> 2023-12-18 11:35:21.762 +00:00 [INF] - "Request finished HTTP/1.1 GET http://edgehub:9600/metrics - - - 200 - text/plain;+version=0.0.4;+charset=utf-8 2.1543ms"�y
stdout��������⸮e<6> 2023-12-18 11:39:20.278 +00:00 [INF] - Entering periodic task to reauthenticate connected clientsy~
stdout�ƿ�����⸮j<6> 2023-12-18 11:40:22.108 +00:00 [INF] - "Request starting HTTP/1.1 GET http://edgehub:9600/metrics - -"~�
stdoutؔ������⸮�<6> 2023-12-18 11:40:22.110 +00:00 [INF] - "Request finished HTTP/1.1 GET http://edgehub:9600/metrics - - - 200 - text/plain;+version=0.0.4;+charset=utf-8 1.8366ms"�

Additional Information

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

The text was updated successfully, but these errors were encountered:

ggjjj · 2023-12-18T18:40:29Z

looks like similar scenarios are seen here #7074 . Could be an issue in Docker.

bhjertaas · 2023-12-18T21:16:18Z

As mentioned in #7074 I did a sudo journalctl -f -u aziot-edged while executing iotedge logs edgeAgent in another terminal window. No errors were shown, only: Dec 18 20:55:53 DESKTOP-5SO2V9I-EFLOW aziot-edged[1582]: 2023-12-18T20:55:53Z [INFO] - Getting logs for module edgeAgent...

In Azure Portal > IoT Hub > devices > troubleshoot module it appears as indicated by screenshot

It may very well be an issue in Docker, but we are seeing this problem mostly with edgeAgent and edgeHub (perhaps because they generate more logs than our custom modules?).

Starting end of last week (roughly December 15th) I feel we see this problem much more frequent on our devices. Also on devices that ran fine for many days prior.

bhjertaas · 2024-01-04T12:30:06Z

Regarding the "log message is too large" issue, we have noticed it is possible to largely overcome this problem by using tail.
For example:
sudo iotedge logs edgeHub --tail 100
Hence, it is no longer a top priority issue for us.

bhjertaas · 2024-01-05T13:39:15Z

@ggjjj Why was this issue closed? It has not been fixed yet. I simply suggested a workaround that can be handy for other users who encounter this problem.

bhjertaas · 2024-01-10T08:01:36Z

FYI: Today we experienced the issue, also with the tail flag. See screenshot (I hide some of our module names), highlighted the error in red.

damonbarry · 2024-01-16T23:39:27Z

@bhjertaas The "Error grabbing logs" output is coming from docker. We engaged someone with expertise on the other issue (#7074), and that person has started looking into the original docker issue. We'll be following that issue to see how it progresses.

github-actions bot added customer-reported iotedge labels Dec 18, 2023

vadim-kovalyov assigned ggjjj Jan 2, 2024

ggjjj closed this as completed Jan 4, 2024

ggjjj reopened this Jan 5, 2024

jlian mentioned this issue Jan 30, 2024

Docker logs crashes every couple of hours moby/moby#46699

Open

bhjertaas mentioned this issue Feb 26, 2024

Unable to communicate with Edge modules (in EFLOW) from the host OS #7220

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Often unable to see container logs due to "error from daemon in stream: Error grabbing logs: log message is too large" #7177

Often unable to see container logs due to "error from daemon in stream: Error grabbing logs: log message is too large" #7177

bhjertaas commented Dec 18, 2023 •

edited

ggjjj commented Dec 18, 2023

bhjertaas commented Dec 18, 2023

bhjertaas commented Jan 4, 2024 •

edited

bhjertaas commented Jan 5, 2024

bhjertaas commented Jan 10, 2024

damonbarry commented Jan 16, 2024

Often unable to see container logs due to "error from daemon in stream: Error grabbing logs: log message is too large" #7177

Often unable to see container logs due to "error from daemon in stream: Error grabbing logs: log message is too large" #7177

Comments

bhjertaas commented Dec 18, 2023 • edited

Expected Behavior

Current Behavior

Steps to Reproduce

Context (Environment)

Output of iotedge check

Device Information

Runtime Versions

Logs

Additional Information

ggjjj commented Dec 18, 2023

bhjertaas commented Dec 18, 2023

bhjertaas commented Jan 4, 2024 • edited

bhjertaas commented Jan 5, 2024

bhjertaas commented Jan 10, 2024

damonbarry commented Jan 16, 2024

bhjertaas commented Dec 18, 2023 •

edited

Output of `iotedge check`

bhjertaas commented Jan 4, 2024 •

edited