search

Azure / Industrial-IoT

Azure Industrial IoT Platform
MIT License
523 stars 214 forks source link

Publisher jobs failing intermittently #664

Closed barnstee closed 4 years ago

barnstee commented 4 years ago

Describe the bug Some OPC Publisher jobs appear to be failing due to intermitted network connectivity of the targeted OPC Publisher. Restarting or deleting and recreating the job didn't fix it, though. Logs below:

[15:12:52 INF Microsoft.Azure.IIoT.Module.Framework.Client.IoTSdkFactory] Connecting all clients to pegasusvirtualmachineedgejenkins using MqttOverTcp. [15:12:52 INF Root] Starting module OpcPublisher version 2.7.170.10628. [15:12:52 INF Root] Initiating prometheus at port 9702/metrics [15:12:52 INF Root] Prometheus metric server started. [15:12:52 DBG Microsoft.Azure.IIoT.Module.Framework.Hosting.ModuleHost] Starting Module Host... [15:12:52 WRN Microsoft.Azure.IIoT.Module.Framework.Client.IoTSdkFactory] Bypassing certificate validation for client. [15:12:52 INF Microsoft.Azure.IIoT.Module.Framework.Client.IoTSdkFactory] Running in iotedge context. [15:12:52 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: IotHubConnectionString#47063234 .ctor IAuthenticationMethod is AuthenticationWithTokenRefresh: ModuleAuthenticationWithHsm#27598869 [15:12:52 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: PipelineContext#58892473 Set ITransportSettings[] = Microsoft.Azure.Devices.Client.ITransportSettings[1] [15:12:52 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: PipelineContext#58892473 Set IotHubConnectionString = IotHubConnectionString#47063234 [15:12:52 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: PipelineContext#58892473 Set OnMethodCalledDelegate = OnMethodCalledDelegate#603735728 [15:12:52 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: PipelineContext#58892473 Set Action1 = System.Action1[Microsoft.Azure.Devices.Shared.TwinCollection] [15:12:52 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: PipelineContext#58892473 Set ConnectionStatusChangesHandler = ConnectionStatusChangesHandler#549026514 [15:12:52 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: PipelineContext#58892473 Set OnReceiveEventMessageCalledDelegate = OnReceiveEventMessageCalledDelegate#593514500 [15:12:52 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: PipelineContext#58892473 Set ProductInfo = .NET/1.26.0 (.NET Core 3.1.6; Linux 4.15.0-1092-azure #102~16.04.1-Ubuntu SMP Tue Jul 14 20:28:23 UTC 2020; X64) [15:12:52 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: PipelineContext#58892473 Set ClientOptions = (null) [15:12:52 DBG Microsoft.Azure.Devices.Device.Client] [CreateFromConnectionString] Informational: InternalClient#16468652 HostName=pegasusvirtualmachineedgejenkins;DeviceId=AzureIoTEdgeDeviceAT;ModuleId=publisher Mqtt_Tcp_Only [15:12:52 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: InternalClient#16468652 SetConnectionStatusChangesHandler ConnectionStatusChangesHandler#1797751332 [15:12:52 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: RetryDelegatingHandler#45596481 EnsureOpenedAsync Opening connection [15:12:52 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: ProtocolRoutingDelegatingHandler#47787675 ProtocolRoutingDelegatingHandler.OpenAsync Trying Mqtt_Tcp_Only [15:12:52 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: PipelineContext#58892473 Set ITransportSettings = MqttTransportSettings#36936550 [15:12:53 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: (null) GetEventLoopGroup EventLoopGroup threads count was not set. [15:12:53 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: MqttTransportHandler#63993496 CreateChannelFactory Connecting to 172.19.0.3 [15:12:53 DBG Microsoft.Azure.Devices.Device.Client] [GenerateToken] Informational: ModuleAuthenticationWithHsm#27598869 2020-08-06T15:12:53.2726789Z 2020-08-06T16:12:53.0000000Z [15:12:53 INF Microsoft.Azure.IIoT.Module.Framework.Client.IoTSdkFactory] 0: Module AzureIoTEdgeDeviceAT_publisher reconnected due to Connection_Ok. [15:12:53 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: MqttIotHubAdapter#14347911 SendMessageAsync id=0 qos=AtMostOnce topic=$iothub/twin/GET/?$rid=3e77d916-f2b6-4996-bcbb-e014bd551e2b [15:12:53 INF Microsoft.Azure.IIoT.Module.Framework.Hosting.ModuleHost] Initialize device twin for AzureIoTEdgeDeviceAT - publisher [15:12:53 INF Microsoft.Azure.IIoT.Module.Framework.Hosting.ModuleHost] Applying initial desired state. [15:12:53 DBG Microsoft.Azure.IIoT.Modules.OpcUa.Publisher.Controller.ConfigurationSettingsController] Updating agent configuration... [15:12:53 INF Microsoft.Azure.IIoT.Modules.OpcUa.Publisher.Controller.ConfigurationSettingsController] Agent configuration updated. [15:12:53 DBG Microsoft.Azure.IIoT.Module.Framework.Hosting.SettingsRouter] Applying new settings took 00:00:00.0085191... [15:12:53 INF Microsoft.Azure.IIoT.Module.Framework.Hosting.ModuleHost] Reporting currently initial state. [15:12:53 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: MqttIotHubAdapter#14347911 SendMessageAsync id=0 qos=AtMostOnce topic=$iothub/twin/PATCH/properties/reported/?$rid=55fb88ac-2cbc-4bfa-a1ac-39ddc97e7330 [15:12:53 INF Microsoft.Azure.IIoT.Module.Framework.Hosting.ModuleHost] Module Host started. [15:12:53 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.WorkerSupervisor] Creating new worker... [15:12:53 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.WorkerSupervisor] Creating new worker... [15:12:53 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.WorkerSupervisor] Creating new worker... [15:12:53 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.WorkerSupervisor] Creating new worker... [15:12:53 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.WorkerSupervisor] Creating new worker... [15:12:53 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.WorkerSupervisor] Starting worker 'AzureIoTEdgeDeviceAT_publisher_0'... [15:12:53 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker AzureIoTEdgeDeviceAT_publisher_0: {"Type": "publisher", "SiteId": "AzureIoTEdgeDeviceAT", "DeviceId": "AzureIoTEdgeDeviceAT", "ModuleId": "publisher"} [15:12:53 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.WorkerSupervisor] Starting worker 'AzureIoTEdgeDeviceAT_publisher_1'... [15:12:53 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker AzureIoTEdgeDeviceAT_publisher_1: {"Type": "publisher", "SiteId": "AzureIoTEdgeDeviceAT", "DeviceId": "AzureIoTEdgeDeviceAT", "ModuleId": "publisher"} [15:12:53 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.WorkerSupervisor] Starting worker 'AzureIoTEdgeDeviceAT_publisher_2'... [15:12:53 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker AzureIoTEdgeDeviceAT_publisher_2: {"Type": "publisher", "SiteId": "AzureIoTEdgeDeviceAT", "DeviceId": "AzureIoTEdgeDeviceAT", "ModuleId": "publisher"} [15:12:53 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.WorkerSupervisor] Starting worker 'AzureIoTEdgeDeviceAT_publisher_3'... [15:12:53 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker AzureIoTEdgeDeviceAT_publisher_3: {"Type": "publisher", "SiteId": "AzureIoTEdgeDeviceAT", "DeviceId": "AzureIoTEdgeDeviceAT", "ModuleId": "publisher"} [15:12:53 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.WorkerSupervisor] Starting worker 'AzureIoTEdgeDeviceAT_publisher_4'... [15:12:53 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker AzureIoTEdgeDeviceAT_publisher_4: {"Type": "publisher", "SiteId": "AzureIoTEdgeDeviceAT", "DeviceId": "AzureIoTEdgeDeviceAT", "ModuleId": "publisher"} [15:12:55 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Sending heartbeat... [15:12:55 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker starting... [15:12:55 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Try querying available job... [15:12:55 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker starting... [15:12:55 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Try querying available job... [15:12:55 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker starting... [15:12:55 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Try querying available job... [15:12:55 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker starting... [15:12:55 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Try querying available job... [15:12:55 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker starting... [15:12:55 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Try querying available job... [15:12:55 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Sending heartbeat... [15:12:55 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Sending heartbeat... [15:12:55 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Sending heartbeat... [15:12:55 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Sending heartbeat... [15:13:05 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Runner Keepalive reset due to checkAlive [15:13:15 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Runner Keepalive reset due to checkAlive [15:13:22 INF Root] Module exits... [15:13:22 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.WorkerSupervisor] Stopping worker supervisor [15:13:22 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Stopping worker... [15:13:22 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Stopping worker... [15:13:22 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Stopping worker... [15:13:22 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Stopping worker... [15:13:22 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Stopping worker... [15:13:45 INF Microsoft.Azure.IIoT.Module.Framework.Client.IoTSdkFactory] Connecting all clients to pegasusvirtualmachineedgejenkins using MqttOverTcp. [15:13:46 INF Root] Starting module OpcPublisher version 2.7.170.10628. [15:13:46 INF Root] Initiating prometheus at port 9702/metrics [15:13:46 INF Root] Prometheus metric server started. [15:13:46 DBG Microsoft.Azure.IIoT.Module.Framework.Hosting.ModuleHost] Starting Module Host... [15:13:46 WRN Microsoft.Azure.IIoT.Module.Framework.Client.IoTSdkFactory] Bypassing certificate validation for client. [15:13:46 INF Microsoft.Azure.IIoT.Module.Framework.Client.IoTSdkFactory] Running in iotedge context. [15:13:47 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: IotHubConnectionString#47063234 .ctor IAuthenticationMethod is AuthenticationWithTokenRefresh: ModuleAuthenticationWithHsm#27598869 [15:13:47 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: PipelineContext#58892473 Set ITransportSettings[] = Microsoft.Azure.Devices.Client.ITransportSettings[1] [15:13:47 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: PipelineContext#58892473 Set IotHubConnectionString = IotHubConnectionString#47063234 [15:13:47 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: PipelineContext#58892473 Set OnMethodCalledDelegate = OnMethodCalledDelegate#603735728 [15:13:47 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: PipelineContext#58892473 Set Action1 = System.Action1[Microsoft.Azure.Devices.Shared.TwinCollection] [15:13:47 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: PipelineContext#58892473 Set ConnectionStatusChangesHandler = ConnectionStatusChangesHandler#549026514 [15:13:47 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: PipelineContext#58892473 Set OnReceiveEventMessageCalledDelegate = OnReceiveEventMessageCalledDelegate#593514500 [15:13:47 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: PipelineContext#58892473 Set ProductInfo = .NET/1.26.0 (.NET Core 3.1.6; Linux 4.15.0-1092-azure #102~16.04.1-Ubuntu SMP Tue Jul 14 20:28:23 UTC 2020; X64) [15:13:47 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: PipelineContext#58892473 Set ClientOptions = (null) [15:13:47 DBG Microsoft.Azure.Devices.Device.Client] [CreateFromConnectionString] Informational: InternalClient#16468652 HostName=pegasusvirtualmachineedgejenkins;DeviceId=AzureIoTEdgeDeviceAT;ModuleId=publisher Mqtt_Tcp_Only [15:13:47 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: InternalClient#16468652 SetConnectionStatusChangesHandler ConnectionStatusChangesHandler#1797751332 [15:13:47 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: RetryDelegatingHandler#45596481 EnsureOpenedAsync Opening connection [15:13:47 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: ProtocolRoutingDelegatingHandler#47787675 ProtocolRoutingDelegatingHandler.OpenAsync Trying Mqtt_Tcp_Only [15:13:47 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: PipelineContext#58892473 Set ITransportSettings = MqttTransportSettings#36936550 [15:13:47 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: (null) GetEventLoopGroup EventLoopGroup threads count was not set. [15:13:47 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: MqttTransportHandler#63993496 CreateChannelFactory Connecting to 172.19.0.3 [15:13:48 DBG Microsoft.Azure.Devices.Device.Client] [ErrorMessage] Warning: MqttTransportHandler#63993496 CreateChannelFactory ConnectException trying to connect to 172.19.0.3: DotNetty.Transport.Channels.ConnectException: LogError connecting to 172.19.0.3:8883 ---> System.Net.Sockets.SocketException (107): Transport endpoint is not connected at System.Net.Sockets.Socket.UpdateStatusAfterSocketErrorAndThrowException(SocketError error, String callerName) at System.Net.Sockets.Socket.Shutdown(SocketShutdown how) at DotNetty.Transport.Channels.Sockets.TcpSocketChannel.DoClose() at DotNetty.Transport.Channels.Sockets.TcpSocketChannel.DoConnect(EndPoint remoteAddress, EndPoint localAddress) at DotNetty.Transport.Channels.Sockets.AbstractSocketChannel.AbstractSocketUnsafe.ConnectAsync(EndPoint remoteAddress, EndPoint localAddress) --- End of inner exception stack trace --- at DotNetty.Transport.Bootstrapping.Bootstrap.DoResolveAndConnectAsync(EndPoint remoteAddress, EndPoint localAddress) at Microsoft.Azure.Devices.Client.Transport.Mqtt.MqttTransportHandler.<>cDisplayClass93_0.<b0>d.MoveNext() [15:13:48 DBG Microsoft.Azure.Devices.Device.Client] [ErrorMessage] Warning: ErrorDelegatingHandler#27435897 ExecuteWithErrorHandlingAsync Exception caught: Microsoft.Azure.Devices.Client.Exceptions.IotHubCommunicationException: MQTT channel open failed. at Microsoft.Azure.Devices.Client.Transport.Mqtt.MqttTransportHandler.<>cDisplayClass93_0.<b0>d.MoveNext() --- End of stack trace from previous location where exception was thrown --- at Microsoft.Azure.Devices.Client.Transport.Mqtt.MqttTransportHandler.OpenAsyncInternal(CancellationToken cancellationToken) at Microsoft.Azure.Devices.Client.Transport.Mqtt.MqttTransportHandler.OpenAsync(CancellationToken cancellationToken) at Microsoft.Azure.Devices.Client.Transport.ProtocolRoutingDelegatingHandler.OpenAsync(CancellationToken cancellationToken) at Microsoft.Azure.Devices.Client.Transport.ErrorDelegatingHandler.<>cDisplayClass23_0.<b0>d.MoveNext() --- End of stack trace from previous location where exception was thrown --- at Microsoft.Azure.Devices.Client.Transport.ErrorDelegatingHandler.ExecuteWithErrorHandlingAsync[T](Func`1 asyncOperation) [15:13:48 INF Microsoft.Azure.IIoT.Module.Framework.Client.IoTSdkFactory] 0: Module AzureIoTEdgeDeviceAT_publisher disconnected due to Retry_Expired - now Disconnected... [15:13:49 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: ProtocolRoutingDelegatingHandler#47787675 ProtocolRoutingDelegatingHandler.OpenAsync Trying Mqtt_Tcp_Only [15:13:49 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: PipelineContext#58892473 Set ITransportSettings = MqttTransportSettings#36936550 [15:13:49 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: MqttTransportHandler#63993496 OnTransportClosedGracefully OnTransportClosedGracefully [15:13:49 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: MqttTransportHandler#47362231 CreateChannelFactory Connecting to 172.19.0.3 [15:13:49 DBG Microsoft.Azure.Devices.Device.Client] [ErrorMessage] Warning: MqttTransportHandler#47362231 CreateChannelFactory ConnectException trying to connect to 172.19.0.3: DotNetty.Transport.Channels.ConnectException: LogError connecting to 172.19.0.3:8883 ---> System.Net.Sockets.SocketException (111): Connection refused at DotNetty.Transport.Channels.Sockets.SocketChannelAsyncOperation.Validate() at DotNetty.Transport.Channels.Sockets.TcpSocketChannel.DoFinishConnect(SocketChannelAsyncOperation operation) at DotNetty.Transport.Channels.Sockets.AbstractSocketChannel.AbstractSocketUnsafe.FinishConnect(SocketChannelAsyncOperation operation) --- End of inner exception stack trace --- at DotNetty.Transport.Bootstrapping.Bootstrap.DoResolveAndConnectAsync(EndPoint remoteAddress, EndPoint localAddress) at Microsoft.Azure.Devices.Client.Transport.Mqtt.MqttTransportHandler.<>cDisplayClass93_0.<b0>d.MoveNext() [15:13:49 DBG Microsoft.Azure.Devices.Device.Client] [ErrorMessage] Warning: ErrorDelegatingHandler#27435897 ExecuteWithErrorHandlingAsync Exception caught: Microsoft.Azure.Devices.Client.Exceptions.IotHubCommunicationException: MQTT channel open failed. at Microsoft.Azure.Devices.Client.Transport.Mqtt.MqttTransportHandler.<>cDisplayClass93_0.<b0>d.MoveNext() --- End of stack trace from previous location where exception was thrown --- at Microsoft.Azure.Devices.Client.Transport.Mqtt.MqttTransportHandler.OpenAsyncInternal(CancellationToken cancellationToken) at Microsoft.Azure.Devices.Client.Transport.Mqtt.MqttTransportHandler.OpenAsync(CancellationToken cancellationToken) at Microsoft.Azure.Devices.Client.Transport.ProtocolRoutingDelegatingHandler.OpenAsync(CancellationToken cancellationToken) at Microsoft.Azure.Devices.Client.Transport.ErrorDelegatingHandler.<>cDisplayClass23_0.<b0>d.MoveNext() --- End of stack trace from previous location where exception was thrown --- at Microsoft.Azure.Devices.Client.Transport.ErrorDelegatingHandler.ExecuteWithErrorHandlingAsync[T](Func1 asyncOperation) [15:13:50 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: ProtocolRoutingDelegatingHandler#47787675 ProtocolRoutingDelegatingHandler.OpenAsync Trying Mqtt_Tcp_Only [15:13:50 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: PipelineContext#58892473 Set ITransportSettings = MqttTransportSettings#36936550 [15:13:50 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: MqttTransportHandler#47362231 OnTransportClosedGracefully OnTransportClosedGracefully [15:13:50 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: MqttTransportHandler#43205102 CreateChannelFactory Connecting to 172.19.0.3 [15:13:50 DBG Microsoft.Azure.Devices.Device.Client] [ErrorMessage] Warning: MqttTransportHandler#43205102 CreateChannelFactory ConnectException trying to connect to 172.19.0.3: DotNetty.Transport.Channels.ConnectException: LogError connecting to 172.19.0.3:8883 ---> System.Net.Sockets.SocketException (111): Connection refused at DotNetty.Transport.Channels.Sockets.SocketChannelAsyncOperation.Validate() at DotNetty.Transport.Channels.Sockets.TcpSocketChannel.DoFinishConnect(SocketChannelAsyncOperation operation) at DotNetty.Transport.Channels.Sockets.AbstractSocketChannel.AbstractSocketUnsafe.FinishConnect(SocketChannelAsyncOperation operation) --- End of inner exception stack trace --- at DotNetty.Transport.Bootstrapping.Bootstrap.DoResolveAndConnectAsync(EndPoint remoteAddress, EndPoint localAddress) at Microsoft.Azure.Devices.Client.Transport.Mqtt.MqttTransportHandler.<>c__DisplayClass93_0.<<CreateChannelFactory>b__0>d.MoveNext() [15:13:50 DBG Microsoft.Azure.Devices.Device.Client] [ErrorMessage] Warning: ErrorDelegatingHandler#27435897 ExecuteWithErrorHandlingAsync Exception caught: Microsoft.Azure.Devices.Client.Exceptions.IotHubCommunicationException: MQTT channel open failed. at Microsoft.Azure.Devices.Client.Transport.Mqtt.MqttTransportHandler.<>c__DisplayClass93_0.<<CreateChannelFactory>b__0>d.MoveNext() --- End of stack trace from previous location where exception was thrown --- at Microsoft.Azure.Devices.Client.Transport.Mqtt.MqttTransportHandler.OpenAsyncInternal(CancellationToken cancellationToken) at Microsoft.Azure.Devices.Client.Transport.Mqtt.MqttTransportHandler.OpenAsync(CancellationToken cancellationToken) at Microsoft.Azure.Devices.Client.Transport.ProtocolRoutingDelegatingHandler.OpenAsync(CancellationToken cancellationToken) at Microsoft.Azure.Devices.Client.Transport.ErrorDelegatingHandler.<>c__DisplayClass23_0.<<ExecuteWithErrorHandlingAsync>b__0>d.MoveNext() --- End of stack trace from previous location where exception was thrown --- at Microsoft.Azure.Devices.Client.Transport.ErrorDelegatingHandler.ExecuteWithErrorHandlingAsync[T](Func1 asyncOperation) [15:13:51 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: ProtocolRoutingDelegatingHandler#47787675 ProtocolRoutingDelegatingHandler.OpenAsync Trying Mqtt_Tcp_Only [15:13:51 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: PipelineContext#58892473 Set ITransportSettings = MqttTransportSettings#36936550 [15:13:51 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: MqttTransportHandler#43205102 OnTransportClosedGracefully OnTransportClosedGracefully [15:13:51 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: MqttTransportHandler#6385742 CreateChannelFactory Connecting to 172.19.0.3 [15:13:51 DBG Microsoft.Azure.Devices.Device.Client] [ErrorMessage] Warning: MqttTransportHandler#6385742 CreateChannelFactory ConnectException trying to connect to 172.19.0.3: DotNetty.Transport.Channels.ConnectException: LogError connecting to 172.19.0.3:8883 ---> System.Net.Sockets.SocketException (111): Connection refused at DotNetty.Transport.Channels.Sockets.SocketChannelAsyncOperation.Validate() at DotNetty.Transport.Channels.Sockets.TcpSocketChannel.DoFinishConnect(SocketChannelAsyncOperation operation) at DotNetty.Transport.Channels.Sockets.AbstractSocketChannel.AbstractSocketUnsafe.FinishConnect(SocketChannelAsyncOperation operation) --- End of inner exception stack trace --- at DotNetty.Transport.Bootstrapping.Bootstrap.DoResolveAndConnectAsync(EndPoint remoteAddress, EndPoint localAddress) at Microsoft.Azure.Devices.Client.Transport.Mqtt.MqttTransportHandler.<>cDisplayClass93_0.<b0>d.MoveNext() [15:13:51 DBG Microsoft.Azure.Devices.Device.Client] [ErrorMessage] Warning: ErrorDelegatingHandler#27435897 ExecuteWithErrorHandlingAsync Exception caught: Microsoft.Azure.Devices.Client.Exceptions.IotHubCommunicationException: MQTT channel open failed. at Microsoft.Azure.Devices.Client.Transport.Mqtt.MqttTransportHandler.<>cDisplayClass93_0.<b0>d.MoveNext() --- End of stack trace from previous location where exception was thrown --- at Microsoft.Azure.Devices.Client.Transport.Mqtt.MqttTransportHandler.OpenAsyncInternal(CancellationToken cancellationToken) at Microsoft.Azure.Devices.Client.Transport.Mqtt.MqttTransportHandler.OpenAsync(CancellationToken cancellationToken) at Microsoft.Azure.Devices.Client.Transport.ProtocolRoutingDelegatingHandler.OpenAsync(CancellationToken cancellationToken) at Microsoft.Azure.Devices.Client.Transport.ErrorDelegatingHandler.<>cDisplayClass23_0.<b0>d.MoveNext() --- End of stack trace from previous location where exception was thrown --- at Microsoft.Azure.Devices.Client.Transport.ErrorDelegatingHandler.ExecuteWithErrorHandlingAsync[T](Func`1 asyncOperation) [15:13:52 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: ProtocolRoutingDelegatingHandler#47787675 ProtocolRoutingDelegatingHandler.OpenAsync Trying Mqtt_Tcp_Only [15:13:52 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: PipelineContext#58892473 Set ITransportSettings = MqttTransportSettings#36936550 [15:13:52 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: MqttTransportHandler#6385742 OnTransportClosedGracefully OnTransportClosedGracefully [15:13:52 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: MqttTransportHandler#25425822 CreateChannelFactory Connecting to 172.19.0.3 [15:13:52 DBG Microsoft.Azure.Devices.Device.Client] [ErrorMessage] Warning: MqttTransportHandler#25425822 CreateChannelFactory ConnectException trying to connect to 172.19.0.3: DotNetty.Transport.Channels.ConnectException: LogError connecting to 172.19.0.3:8883 ---> System.Net.Sockets.SocketException (111): Connection refused at DotNetty.Transport.Channels.Sockets.SocketChannelAsyncOperation.Validate() at DotNetty.Transport.Channels.Sockets.TcpSocketChannel.DoFinishConnect(SocketChannelAsyncOperation operation) at DotNetty.Transport.Channels.Sockets.AbstractSocketChannel.AbstractSocketUnsafe.FinishConnect(SocketChannelAsyncOperation operation) --- End of inner exception stack trace --- at DotNetty.Transport.Bootstrapping.Bootstrap.DoResolveAndConnectAsync(EndPoint remoteAddress, EndPoint localAddress) at Microsoft.Azure.Devices.Client.Transport.Mqtt.MqttTransportHandler.<>cDisplayClass93_0.<b0>d.MoveNext() [15:13:52 DBG Microsoft.Azure.Devices.Device.Client] [ErrorMessage] Warning: ErrorDelegatingHandler#27435897 ExecuteWithErrorHandlingAsync Exception caught: Microsoft.Azure.Devices.Client.Exceptions.IotHubCommunicationException: MQTT channel open failed. at Microsoft.Azure.Devices.Client.Transport.Mqtt.MqttTransportHandler.<>cDisplayClass93_0.<b0>d.MoveNext() --- End of stack trace from previous location where exception was thrown --- at Microsoft.Azure.Devices.Client.Transport.Mqtt.MqttTransportHandler.OpenAsyncInternal(CancellationToken cancellationToken) at Microsoft.Azure.Devices.Client.Transport.Mqtt.MqttTransportHandler.OpenAsync(CancellationToken cancellationToken) at Microsoft.Azure.Devices.Client.Transport.ProtocolRoutingDelegatingHandler.OpenAsync(CancellationToken cancellationToken) at Microsoft.Azure.Devices.Client.Transport.ErrorDelegatingHandler.<>cDisplayClass23_0.<b0>d.MoveNext() --- End of stack trace from previous location where exception was thrown --- at Microsoft.Azure.Devices.Client.Transport.ErrorDelegatingHandler.ExecuteWithErrorHandlingAsync[T](Func1 asyncOperation) [15:13:53 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: ProtocolRoutingDelegatingHandler#47787675 ProtocolRoutingDelegatingHandler.OpenAsync Trying Mqtt_Tcp_Only [15:13:53 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: PipelineContext#58892473 Set ITransportSettings = MqttTransportSettings#36936550 [15:13:53 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: MqttTransportHandler#25425822 OnTransportClosedGracefully OnTransportClosedGracefully [15:13:53 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: MqttTransportHandler#31665793 CreateChannelFactory Connecting to 172.19.0.3 [15:13:53 DBG Microsoft.Azure.Devices.Device.Client] [GenerateToken] Informational: ModuleAuthenticationWithHsm#27598869 2020-08-06T15:13:53.8457426Z 2020-08-06T16:13:54.0000000Z [15:13:55 INF Microsoft.Azure.IIoT.Module.Framework.Client.IoTSdkFactory] 0: Module AzureIoTEdgeDeviceAT_publisher reconnected due to Connection_Ok. [15:13:55 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: MqttIotHubAdapter#25474675 SendMessageAsync id=0 qos=AtMostOnce topic=$iothub/twin/GET/?$rid=258838ee-1abf-4ec1-adff-9a1e4c4a8f3b [15:13:56 INF Microsoft.Azure.IIoT.Module.Framework.Hosting.ModuleHost] Initialize device twin for AzureIoTEdgeDeviceAT - publisher [15:13:57 INF Microsoft.Azure.IIoT.Module.Framework.Hosting.ModuleHost] Applying initial desired state. [15:13:57 DBG Microsoft.Azure.IIoT.Modules.OpcUa.Publisher.Controller.ConfigurationSettingsController] Updating agent configuration... [15:13:57 INF Microsoft.Azure.IIoT.Modules.OpcUa.Publisher.Controller.ConfigurationSettingsController] Agent configuration updated. [15:13:57 DBG Microsoft.Azure.IIoT.Module.Framework.Hosting.SettingsRouter] Applying new settings took 00:00:00.0490366... [15:13:57 INF Microsoft.Azure.IIoT.Module.Framework.Hosting.ModuleHost] Reporting currently initial state. [15:13:57 INF Microsoft.Azure.IIoT.Module.Framework.Hosting.ModuleHost] Module Host started. [15:13:57 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.WorkerSupervisor] Creating new worker... [15:13:57 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.WorkerSupervisor] Creating new worker... [15:13:57 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.WorkerSupervisor] Creating new worker... [15:13:57 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.WorkerSupervisor] Creating new worker... [15:13:57 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.WorkerSupervisor] Creating new worker... [15:13:57 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.WorkerSupervisor] Starting worker 'AzureIoTEdgeDeviceAT_publisher_0'... [15:13:57 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Sending heartbeat... [15:13:57 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker AzureIoTEdgeDeviceAT_publisher_0: {"Type": "publisher", "SiteId": "AzureIoTEdgeDeviceAT", "DeviceId": "AzureIoTEdgeDeviceAT", "ModuleId": "publisher"} [15:13:57 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.WorkerSupervisor] Starting worker 'AzureIoTEdgeDeviceAT_publisher_1'... [15:13:57 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker AzureIoTEdgeDeviceAT_publisher_1: {"Type": "publisher", "SiteId": "AzureIoTEdgeDeviceAT", "DeviceId": "AzureIoTEdgeDeviceAT", "ModuleId": "publisher"} [15:13:57 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.WorkerSupervisor] Starting worker 'AzureIoTEdgeDeviceAT_publisher_2'... [15:13:57 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker AzureIoTEdgeDeviceAT_publisher_2: {"Type": "publisher", "SiteId": "AzureIoTEdgeDeviceAT", "DeviceId": "AzureIoTEdgeDeviceAT", "ModuleId": "publisher"} [15:13:57 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.WorkerSupervisor] Starting worker 'AzureIoTEdgeDeviceAT_publisher_3'... [15:13:57 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker AzureIoTEdgeDeviceAT_publisher_3: {"Type": "publisher", "SiteId": "AzureIoTEdgeDeviceAT", "DeviceId": "AzureIoTEdgeDeviceAT", "ModuleId": "publisher"} [15:13:57 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker starting... [15:13:57 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.WorkerSupervisor] Starting worker 'AzureIoTEdgeDeviceAT_publisher_4'... [15:13:57 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker AzureIoTEdgeDeviceAT_publisher_4: {"Type": "publisher", "SiteId": "AzureIoTEdgeDeviceAT", "DeviceId": "AzureIoTEdgeDeviceAT", "ModuleId": "publisher"} [15:13:57 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Try querying available job... [15:13:58 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker starting... [15:13:58 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Try querying available job... [15:13:58 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Sending heartbeat... [15:13:58 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Sending heartbeat... [15:13:58 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Sending heartbeat... [15:13:58 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Sending heartbeat... [15:13:58 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker starting... [15:13:58 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Try querying available job... [15:13:58 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker starting... [15:13:58 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Try querying available job... [15:13:58 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker starting... [15:13:58 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Try querying available job... [15:13:58 INF Root] Module reset... [15:13:58 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.WorkerSupervisor] Stopping worker supervisor [15:13:58 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Stopping worker... [15:13:58 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Stopping worker... [15:13:58 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Stopping worker... [15:13:58 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Stopping worker... [15:13:58 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Stopping worker... [15:13:58 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker cancelled... [15:13:58 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker stopping... [15:13:58 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker stopped. [15:13:58 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker cancelled... [15:13:58 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker stopping... [15:13:58 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker stopped. [15:13:58 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker cancelled... [15:13:58 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker stopping... [15:13:58 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker stopped. [15:13:58 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker cancelled... [15:13:58 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker stopping... [15:13:58 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker stopped. [15:13:58 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker cancelled... [15:13:58 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker stopping... [15:13:58 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker stopped. [15:13:58 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.WorkerSupervisor] Worker supervisor successfully stopped [15:13:58 INF Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Stopping all sessions [15:13:58 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Runner Keepalive reset due to triggerKeepAlive [15:13:58 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Runner Keepalive reset due to checkAlive [15:13:58 INF Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Succesfully stopped all sessions [15:13:58 INF Microsoft.Azure.IIoT.Module.Framework.Hosting.ModuleHost] Stopping Module Host... [15:13:58 INF Microsoft.Azure.IIoT.Module.Framework.Hosting.ModuleHost] Module Host stopped. [15:13:58 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: MqttTransportHandler#31665793 OnTransportClosedGracefully OnTransportClosedGracefully [15:13:58 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: RetryDelegatingHandler#45596481 HandleDisconnectAsync Transport disconnected: closed by application. [15:13:58 INF Microsoft.Azure.IIoT.Module.Framework.Client.IoTSdkFactory] 1: Module AzureIoTEdgeDeviceAT_publisher disconnected due to Client_Close - now Disabled... [15:13:58 INF Root] Stopped prometheus metric server [15:13:58 INF Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Stopping all sessions [15:13:58 INF Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Succesfully stopped all sessions [15:13:58 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.WorkerSupervisor] Stopping worker supervisor [15:13:58 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.WorkerSupervisor] Worker supervisor successfully stopped [15:13:58 INF Microsoft.Azure.IIoT.Module.Framework.Client.IoTSdkFactory] Connecting all clients to pegasusvirtualmachineedgejenkins using MqttOverTcp. [15:13:58 INF Root] Starting module OpcPublisher version 2.7.170.10628. [15:13:58 INF Root] Initiating prometheus at port 9702/metrics [15:13:58 INF Root] Prometheus metric server started. [15:13:58 DBG Microsoft.Azure.IIoT.Module.Framework.Hosting.ModuleHost] Starting Module Host... [15:13:58 WRN Microsoft.Azure.IIoT.Module.Framework.Client.IoTSdkFactory] Bypassing certificate validation for client. [15:13:58 INF Microsoft.Azure.IIoT.Module.Framework.Client.IoTSdkFactory] Running in iotedge context. [15:13:58 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: IotHubConnectionString#60292967 .ctor IAuthenticationMethod is AuthenticationWithTokenRefresh: ModuleAuthenticationWithHsm#66784297 [15:13:58 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: PipelineContext#27420650 Set ITransportSettings[] = Microsoft.Azure.Devices.Client.ITransportSettings[1] [15:13:58 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: PipelineContext#27420650 Set IotHubConnectionString = IotHubConnectionString#60292967 [15:13:58 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: PipelineContext#27420650 Set OnMethodCalledDelegate = OnMethodCalledDelegate#1980631226 [15:13:58 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: PipelineContext#27420650 Set Action1 = System.Action1[Microsoft.Azure.Devices.Shared.TwinCollection] [15:13:58 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: PipelineContext#27420650 Set ConnectionStatusChangesHandler = ConnectionStatusChangesHandler#1925922012 [15:13:58 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: PipelineContext#27420650 Set OnReceiveEventMessageCalledDelegate = OnReceiveEventMessageCalledDelegate#1970409998 [15:13:58 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: PipelineContext#27420650 Set ProductInfo = .NET/1.26.0 (.NET Core 3.1.6; Linux 4.15.0-1092-azure #102~16.04.1-Ubuntu SMP Tue Jul 14 20:28:23 UTC 2020; X64) [15:13:58 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: PipelineContext#27420650 Set ClientOptions = (null) [15:13:58 DBG Microsoft.Azure.Devices.Device.Client] [CreateFromConnectionString] Informational: InternalClient#58192758 HostName=pegasusvirtualmachineedgejenkins;DeviceId=AzureIoTEdgeDeviceAT;ModuleId=publisher Mqtt_Tcp_Only [15:13:58 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: InternalClient#58192758 SetConnectionStatusChangesHandler ConnectionStatusChangesHandler#1403839935 [15:13:58 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: RetryDelegatingHandler#2704503 EnsureOpenedAsync Opening connection [15:13:58 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: ProtocolRoutingDelegatingHandler#38962752 ProtocolRoutingDelegatingHandler.OpenAsync Trying Mqtt_Tcp_Only [15:13:58 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: PipelineContext#27420650 Set ITransportSettings = MqttTransportSettings#29827457 [15:13:58 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: MqttTransportHandler#22396821 CreateChannelFactory Connecting to 172.19.0.3 [15:13:58 DBG Microsoft.Azure.Devices.Device.Client] [GenerateToken] Informational: ModuleAuthenticationWithHsm#66784297 2020-08-06T15:13:58.8446552Z 2020-08-06T16:13:59.0000000Z [15:13:58 INF Microsoft.Azure.IIoT.Module.Framework.Client.IoTSdkFactory] 0: Module AzureIoTEdgeDeviceAT_publisher reconnected due to Connection_Ok. [15:13:58 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: MqttIotHubAdapter#14303791 SendMessageAsync id=0 qos=AtMostOnce topic=$iothub/twin/GET/?$rid=d50d425e-d5ff-494e-a57e-90b3168b321f [15:13:58 INF Microsoft.Azure.IIoT.Module.Framework.Hosting.ModuleHost] Initialize device twin for AzureIoTEdgeDeviceAT - publisher [15:13:58 INF Microsoft.Azure.IIoT.Module.Framework.Hosting.ModuleHost] Applying initial desired state. [15:13:58 DBG Microsoft.Azure.IIoT.Modules.OpcUa.Publisher.Controller.ConfigurationSettingsController] Updating agent configuration... [15:13:58 INF Microsoft.Azure.IIoT.Modules.OpcUa.Publisher.Controller.ConfigurationSettingsController] Agent configuration updated. [15:13:58 DBG Microsoft.Azure.IIoT.Module.Framework.Hosting.SettingsRouter] Applying new settings took 00:00:00.0023051... [15:13:58 INF Microsoft.Azure.IIoT.Module.Framework.Hosting.ModuleHost] Reporting currently initial state. [15:13:58 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: MqttIotHubAdapter#14303791 SendMessageAsync id=0 qos=AtMostOnce topic=$iothub/twin/PATCH/properties/reported/?$rid=f1008949-fe23-4a0b-9690-95dcf192a40c [15:13:58 INF Microsoft.Azure.IIoT.Module.Framework.Hosting.ModuleHost] Module Host started. [15:13:58 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.WorkerSupervisor] Creating new worker... [15:13:58 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.WorkerSupervisor] Creating new worker... [15:13:58 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.WorkerSupervisor] Creating new worker... [15:13:58 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.WorkerSupervisor] Creating new worker... [15:13:58 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.WorkerSupervisor] Creating new worker... [15:13:58 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.WorkerSupervisor] Starting worker 'AzureIoTEdgeDeviceAT_publisher_0'... [15:13:58 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker AzureIoTEdgeDeviceAT_publisher_0: {"Type": "publisher", "SiteId": "AzureIoTEdgeDeviceAT", "DeviceId": "AzureIoTEdgeDeviceAT", "ModuleId": "publisher"} [15:13:58 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.WorkerSupervisor] Starting worker 'AzureIoTEdgeDeviceAT_publisher_1'... [15:13:58 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker AzureIoTEdgeDeviceAT_publisher_1: {"Type": "publisher", "SiteId": "AzureIoTEdgeDeviceAT", "DeviceId": "AzureIoTEdgeDeviceAT", "ModuleId": "publisher"} [15:13:58 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.WorkerSupervisor] Starting worker 'AzureIoTEdgeDeviceAT_publisher_2'... [15:13:58 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker AzureIoTEdgeDeviceAT_publisher_2: {"Type": "publisher", "SiteId": "AzureIoTEdgeDeviceAT", "DeviceId": "AzureIoTEdgeDeviceAT", "ModuleId": "publisher"} [15:13:58 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.WorkerSupervisor] Starting worker 'AzureIoTEdgeDeviceAT_publisher_3'... [15:13:58 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker AzureIoTEdgeDeviceAT_publisher_3: {"Type": "publisher", "SiteId": "AzureIoTEdgeDeviceAT", "DeviceId": "AzureIoTEdgeDeviceAT", "ModuleId": "publisher"} [15:13:58 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.WorkerSupervisor] Starting worker 'AzureIoTEdgeDeviceAT_publisher_4'... [15:13:58 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker AzureIoTEdgeDeviceAT_publisher_4: {"Type": "publisher", "SiteId": "AzureIoTEdgeDeviceAT", "DeviceId": "AzureIoTEdgeDeviceAT", "ModuleId": "publisher"} [15:13:58 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker starting... [15:13:58 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Try querying available job... [15:13:58 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Sending heartbeat... [15:13:59 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker starting... [15:13:59 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Try querying available job... [15:13:59 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker starting... [15:13:59 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Try querying available job... [15:13:59 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker starting... [15:13:59 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Try querying available job... [15:13:59 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker starting... [15:13:59 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Try querying available job... [15:13:59 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Sending heartbeat... [15:13:59 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Sending heartbeat... [15:13:59 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Sending heartbeat... [15:13:59 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Sending heartbeat... [15:14:08 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Runner Keepalive reset due to checkAlive [15:14:18 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Runner Keepalive reset due to checkAlive [15:14:28 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Runner Keepalive reset due to checkAlive [15:14:38 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Runner Keepalive reset due to checkAlive [15:14:40 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: InternalClient#58192758 OnReportedStatePatchReceived {"JobOrchestratorUrl":"https://pegasus-msai-connector-dev.nimbus.msai.devops.ptc.io/edge/publisher","IdentityToken":{"identity":"AzureIoTEdgeDeviceAT/publisher","key":"TDFEMmlMQjprL20kVEVGWFAzU3FIOzghWUx5RyxBcElqZz8pXzFRMTNEYSFHO0ZKeWUtVUllYk5vXyxod0M3Lg==","expires":"2020-08-06T15:29:40.2126101Z"},"$version":238} [15:14:40 DBG Microsoft.Azure.IIoT.Module.Framework.Hosting.ModuleHost] Processing new settings... [15:14:40 DBG Microsoft.Azure.IIoT.Modules.OpcUa.Publisher.Controller.ConfigurationSettingsController] Updating agent configuration... [15:14:40 INF Microsoft.Azure.IIoT.Modules.OpcUa.Publisher.Controller.ConfigurationSettingsController] Agent configuration updated. [15:14:40 DBG Microsoft.Azure.IIoT.Module.Framework.Hosting.SettingsRouter] Applying new settings took 00:00:00.0012280... [15:14:40 DBG Microsoft.Azure.IIoT.Module.Framework.Hosting.ModuleHost] Reporting setting results... [15:14:40 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: MqttIotHubAdapter#14303791 SendMessageAsync id=0 qos=AtMostOnce topic=$iothub/twin/PATCH/properties/reported/?$rid=b6d05c24-3b43-4c06-9bba-d71abe21af7c [15:14:40 INF Microsoft.Azure.IIoT.Module.Framework.Hosting.ModuleHost] New settings processed. [15:14:48 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Runner Keepalive reset due to checkAlive [15:14:58 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Runner Keepalive reset due to checkAlive [15:15:08 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Runner Keepalive reset due to checkAlive [15:15:18 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Runner Keepalive reset due to checkAlive [15:15:28 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Runner Keepalive reset due to checkAlive [15:15:38 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker: AzureIoTEdgeDeviceAT_publisher_4, no job received, wait 00:00:10 ... [15:15:39 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Runner Keepalive reset due to checkAlive [15:15:39 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker: AzureIoTEdgeDeviceAT_publisher_3, no job received, wait 00:00:10 ... [15:15:39 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker: AzureIoTEdgeDeviceAT_publisher_2, no job received, wait 00:00:10 ... [15:15:39 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker: AzureIoTEdgeDeviceAT_publisher_1, no job received, wait 00:00:10 ... [15:15:39 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker: AzureIoTEdgeDeviceAT_publisher_0, no job received, wait 00:00:10 ... [15:15:48 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Try querying available job... [15:15:49 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Runner Keepalive reset due to checkAlive [15:15:49 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Try querying available job... [15:15:49 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Try querying available job... [15:15:49 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Try querying available job... [15:15:49 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Try querying available job... [15:15:59 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Runner Keepalive reset due to checkAlive [15:16:09 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Runner Keepalive reset due to checkAlive [15:16:19 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Runner Keepalive reset due to checkAlive [15:16:29 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Runner Keepalive reset due to checkAlive [15:16:39 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Runner Keepalive reset due to checkAlive [15:16:49 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Runner Keepalive reset due to checkAlive [15:16:59 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Runner Keepalive reset due to checkAlive [15:17:09 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Runner Keepalive reset due to checkAlive [15:17:19 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Runner Keepalive reset due to checkAlive [15:17:29 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker: AzureIoTEdgeDeviceAT_publisher_4, no job received, wait 00:00:10 ... [15:17:29 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Runner Keepalive reset due to checkAlive [15:17:29 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker: AzureIoTEdgeDeviceAT_publisher_2, no job received, wait 00:00:10 ... [15:17:29 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker: AzureIoTEdgeDeviceAT_publisher_1, no job received, wait 00:00:10 ... [15:17:29 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker: AzureIoTEdgeDeviceAT_publisher_0, no job received, wait 00:00:10 ... [15:17:29 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker: AzureIoTEdgeDeviceAT_publisher_3, no job received, wait 00:00:10 ... [15:17:39 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Try querying available job... [15:17:39 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Runner Keepalive reset due to checkAlive [15:17:39 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Try querying available job... [15:17:39 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Try querying available job... [15:17:39 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Try querying available job... [15:17:39 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Try querying available job... [15:17:49 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Runner Keepalive reset due to checkAlive [15:17:59 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Runner Keepalive reset due to checkAlive [15:18:09 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Runner Keepalive reset due to checkAlive [15:18:19 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Runner Keepalive reset due to checkAlive [15:18:29 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Runner Keepalive reset due to checkAlive [15:18:39 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Runner Keepalive reset due to checkAlive [15:18:49 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Runner Keepalive reset due to checkAlive [15:18:59 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Runner Keepalive reset due to checkAlive [15:19:09 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Runner Keepalive reset due to checkAlive [15:19:19 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker: AzureIoTEdgeDeviceAT_publisher_4, no job received, wait 00:00:10 ... [15:19:19 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Runner Keepalive reset due to checkAlive [15:19:19 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker: AzureIoTEdgeDeviceAT_publisher_1, no job received, wait 00:00:10 ... [15:19:19 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker: AzureIoTEdgeDeviceAT_publisher_3, no job received, wait 00:00:10 ... [15:19:19 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker: AzureIoTEdgeDeviceAT_publisher_2, no job received, wait 00:00:10 ... [15:19:19 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker: AzureIoTEdgeDeviceAT_publisher_0, no job received, wait 00:00:10 ... [15:19:29 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Try querying available job... [15:19:29 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Runner Keepalive reset due to checkAlive [15:19:29 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Try querying available job... [15:19:29 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Try querying available job... [15:19:29 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Try querying available job... [15:19:29 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Try querying available job... [15:19:39 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Runner Keepalive reset due to checkAlive [15:19:46 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: InternalClient#58192758 OnReportedStatePatchReceived {"JobOrchestratorUrl":"https://pegasus-msai-connector-dev.nimbus.msai.devops.ptc.io/edge/publisher","IdentityToken":{"identity":"AzureIoTEdgeDeviceAT/publisher","key":"bz1MeEpOUVNJby54QjQvJEoxM3JQWSlpYk1JdT8ydkxRbXBnVS9JeUY0RG81cElEJEJSTUtHU05HcmdMWSE9Mg==","expires":"2020-08-06T15:34:46.0417778Z"},"$version":239} [15:19:46 DBG Microsoft.Azure.IIoT.Module.Framework.Hosting.ModuleHost] Processing new settings... [15:19:46 DBG Microsoft.Azure.IIoT.Modules.OpcUa.Publisher.Controller.ConfigurationSettingsController] Updating agent configuration... [15:19:46 INF Microsoft.Azure.IIoT.Modules.OpcUa.Publisher.Controller.ConfigurationSettingsController] Agent configuration updated. [15:19:46 DBG Microsoft.Azure.IIoT.Module.Framework.Hosting.SettingsRouter] Applying new settings took 00:00:00.0026157... [15:19:46 DBG Microsoft.Azure.IIoT.Module.Framework.Hosting.ModuleHost] Reporting setting results... [15:19:46 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: MqttIotHubAdapter#14303791 SendMessageAsync id=0 qos=AtMostOnce topic=$iothub/twin/PATCH/properties/reported/?$rid=41d8de42-488c-48f7-9885-372f7f42fff4 [15:19:46 INF Microsoft.Azure.IIoT.Module.Framework.Hosting.ModuleHost] New settings processed. [15:19:49 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Runner Keepalive reset due to checkAlive [15:19:59 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Runner Keepalive reset due to checkAlive [15:20:07 INF Root] Module exits... [15:20:07 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.WorkerSupervisor] Stopping worker supervisor [15:20:07 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Stopping worker... [15:20:07 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Stopping worker... [15:20:07 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Stopping worker... [15:20:07 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Stopping worker... [15:20:07 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Stopping worker... [15:20:07 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker cancelled... [15:20:07 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker stopping... [15:20:07 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker stopped. [15:20:07 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker cancelled... [15:20:07 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker stopping... [15:20:07 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker stopped. [15:20:07 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker cancelled... [15:20:07 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker stopping... [15:20:07 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker stopped. [15:20:07 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker cancelled... [15:20:07 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker stopping... [15:20:07 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker stopped. [15:20:07 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker cancelled... [15:20:07 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker stopping... [15:20:07 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker stopped. [15:20:07 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.WorkerSupervisor] Worker supervisor successfully stopped [15:20:07 INF Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Stopping all sessions [15:20:07 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Runner Keepalive reset due to triggerKeepAlive [15:20:07 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Runner Keepalive reset due to checkAlive [15:20:07 INF Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Succesfully stopped all sessions [15:20:07 INF Microsoft.Azure.IIoT.Module.Framework.Hosting.ModuleHost] Stopping Module Host... [15:20:07 INF Microsoft.Azure.IIoT.Module.Framework.Client.IoTSdkFactory] 1: Module AzureIoTEdgeDeviceAT_publisher disconnected due to Client_Close - now Disabled... [15:20:09 INF Microsoft.Azure.IIoT.Module.Framework.Client.IoTSdkFactory] Connecting all clients to pegasusvirtualmachineedgejenkins using MqttOverTcp. [15:20:09 INF Root] Starting module OpcPublisher version 2.7.170.10628. [15:20:09 INF Root] Initiating prometheus at port 9702/metrics [15:20:09 INF Root] Prometheus metric server started. [15:20:09 DBG Microsoft.Azure.IIoT.Module.Framework.Hosting.ModuleHost] Starting Module Host... [15:20:09 WRN Microsoft.Azure.IIoT.Module.Framework.Client.IoTSdkFactory] Bypassing certificate validation for client. [15:20:09 INF Microsoft.Azure.IIoT.Module.Framework.Client.IoTSdkFactory] Running in iotedge context. [15:20:09 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: IotHubConnectionString#47063234 .ctor IAuthenticationMethod is AuthenticationWithTokenRefresh: ModuleAuthenticationWithHsm#27598869 [15:20:09 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: PipelineContext#58892473 Set ITransportSettings[] = Microsoft.Azure.Devices.Client.ITransportSettings[1] [15:20:09 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: PipelineContext#58892473 Set IotHubConnectionString = IotHubConnectionString#47063234 [15:20:09 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: PipelineContext#58892473 Set OnMethodCalledDelegate = OnMethodCalledDelegate#603735728 [15:20:09 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: PipelineContext#58892473 Set Action1 = System.Action`1[Microsoft.Azure.Devices.Shared.TwinCollection] [15:20:09 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: PipelineContext#58892473 Set ConnectionStatusChangesHandler = ConnectionStatusChangesHandler#549026514 [15:20:09 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: PipelineContext#58892473 Set OnReceiveEventMessageCalledDelegate = OnReceiveEventMessageCalledDelegate#593514500 [15:20:09 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: PipelineContext#58892473 Set ProductInfo = .NET/1.26.0 (.NET Core 3.1.6; Linux 4.15.0-1092-azure #102~16.04.1-Ubuntu SMP Tue Jul 14 20:28:23 UTC 2020; X64) [15:20:09 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: PipelineContext#58892473 Set ClientOptions = (null) [15:20:09 DBG Microsoft.Azure.Devices.Device.Client] [CreateFromConnectionString] Informational: InternalClient#16468652 HostName=pegasusvirtualmachineedgejenkins;DeviceId=AzureIoTEdgeDeviceAT;ModuleId=publisher Mqtt_Tcp_Only [15:20:09 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: InternalClient#16468652 SetConnectionStatusChangesHandler ConnectionStatusChangesHandler#1797751332 [15:20:09 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: RetryDelegatingHandler#45596481 EnsureOpenedAsync Opening connection [15:20:09 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: ProtocolRoutingDelegatingHandler#47787675 ProtocolRoutingDelegatingHandler.OpenAsync Trying Mqtt_Tcp_Only [15:20:09 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: PipelineContext#58892473 Set ITransportSettings = MqttTransportSettings#36936550 [15:20:09 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: (null) GetEventLoopGroup EventLoopGroup threads count was not set. [15:20:09 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: MqttTransportHandler#63993496 CreateChannelFactory Connecting to 172.19.0.3 [15:20:09 DBG Microsoft.Azure.Devices.Device.Client] [GenerateToken] Informational: ModuleAuthenticationWithHsm#27598869 2020-08-06T15:20:09.8095124Z 2020-08-06T16:20:10.0000000Z [15:20:09 INF Microsoft.Azure.IIoT.Module.Framework.Client.IoTSdkFactory] 0: Module AzureIoTEdgeDeviceAT_publisher reconnected due to Connection_Ok. [15:20:10 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: MqttIotHubAdapter#14347911 SendMessageAsync id=0 qos=AtMostOnce topic=$iothub/twin/GET/?$rid=787d3ca1-d76f-4610-8451-884830eaf3f0 [15:20:10 INF Microsoft.Azure.IIoT.Module.Framework.Hosting.ModuleHost] Initialize device twin for AzureIoTEdgeDeviceAT - publisher [15:20:10 INF Microsoft.Azure.IIoT.Module.Framework.Hosting.ModuleHost] Applying initial desired state. [15:20:10 DBG Microsoft.Azure.IIoT.Modules.OpcUa.Publisher.Controller.ConfigurationSettingsController] Updating agent configuration... [15:20:10 INF Microsoft.Azure.IIoT.Modules.OpcUa.Publisher.Controller.ConfigurationSettingsController] Agent configuration updated. [15:20:10 DBG Microsoft.Azure.IIoT.Module.Framework.Hosting.SettingsRouter] Applying new settings took 00:00:00.0081103... [15:20:10 INF Microsoft.Azure.IIoT.Module.Framework.Hosting.ModuleHost] Reporting currently initial state. [15:20:10 DBG Microsoft.Azure.Devices.Device.Client] [Info] Informational: MqttIotHubAdapter#14347911 SendMessageAsync id=0 qos=AtMostOnce topic=$iothub/twin/PATCH/properties/reported/?$rid=3fa23b2f-b005-4146-a88a-46a0dd5ad79e [15:20:10 INF Microsoft.Azure.IIoT.Module.Framework.Hosting.ModuleHost] Module Host started. [15:20:10 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.WorkerSupervisor] Creating new worker... [15:20:10 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.WorkerSupervisor] Creating new worker... [15:20:10 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.WorkerSupervisor] Creating new worker... [15:20:10 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.WorkerSupervisor] Creating new worker... [15:20:10 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.WorkerSupervisor] Creating new worker... [15:20:10 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.WorkerSupervisor] Starting worker 'AzureIoTEdgeDeviceAT_publisher_0'... [15:20:10 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker AzureIoTEdgeDeviceAT_publisher_0: {"Type": "publisher", "SiteId": "AzureIoTEdgeDeviceAT", "DeviceId": "AzureIoTEdgeDeviceAT", "ModuleId": "publisher"} [15:20:10 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.WorkerSupervisor] Starting worker 'AzureIoTEdgeDeviceAT_publisher_1'... [15:20:10 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker AzureIoTEdgeDeviceAT_publisher_1: {"Type": "publisher", "SiteId": "AzureIoTEdgeDeviceAT", "DeviceId": "AzureIoTEdgeDeviceAT", "ModuleId": "publisher"} [15:20:10 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.WorkerSupervisor] Starting worker 'AzureIoTEdgeDeviceAT_publisher_2'... [15:20:10 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker AzureIoTEdgeDeviceAT_publisher_2: {"Type": "publisher", "SiteId": "AzureIoTEdgeDeviceAT", "DeviceId": "AzureIoTEdgeDeviceAT", "ModuleId": "publisher"} [15:20:10 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.WorkerSupervisor] Starting worker 'AzureIoTEdgeDeviceAT_publisher_3'... [15:20:10 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker AzureIoTEdgeDeviceAT_publisher_3: {"Type": "publisher", "SiteId": "AzureIoTEdgeDeviceAT", "DeviceId": "AzureIoTEdgeDeviceAT", "ModuleId": "publisher"} [15:20:10 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.WorkerSupervisor] Starting worker 'AzureIoTEdgeDeviceAT_publisher_4'... [15:20:10 INF Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker AzureIoTEdgeDeviceAT_publisher_4: {"Type": "publisher", "SiteId": "AzureIoTEdgeDeviceAT", "DeviceId": "AzureIoTEdgeDeviceAT", "ModuleId": "publisher"} [15:20:10 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Sending heartbeat... [15:20:10 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker starting... [15:20:10 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Try querying available job... [15:20:10 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker starting... [15:20:10 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Try querying available job... [15:20:10 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker starting... [15:20:10 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Try querying available job... [15:20:10 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker starting... [15:20:10 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Try querying available job... [15:20:10 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Worker starting... [15:20:10 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Try querying available job... [15:20:10 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Sending heartbeat... [15:20:10 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Sending heartbeat... [15:20:10 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Sending heartbeat... [15:20:10 DBG Microsoft.Azure.IIoT.Agent.Framework.Agent.Worker] Sending heartbeat... [15:20:20 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Runner Keepalive reset due to checkAlive [15:20:30 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Runner Keepalive reset due to checkAlive [15:20:40 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Runner Keepalive reset due to checkAlive [15:20:50 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Runner Keepalive reset due to checkAlive [15:21:00 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Runner Keepalive reset due to checkAlive [15:21:10 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Runner Keepalive reset due to checkAlive [15:21:20 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Runner Keepalive reset due to checkAlive [15:21:30 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Runner Keepalive reset due to checkAlive [15:21:40 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Runner Keepalive reset due to checkAlive [15:21:50 DBG Microsoft.Azure.IIoT.OpcUa.Protocol.Services.DefaultSessionManager] Runner Keepalive reset due to checkAlive

dacolgit commented 4 years ago

not reproducible