Hi ,
I have a remote thing bound with Java SDK and the SDK calls the method updateSubscribedEvents to communicate with the remote thing.
The communication works well for about 2 months , but yesterday calling updateSubscribedEvents got errror "Timed out APIRequestMessage" logged , meanwhile, the remote thing become disconnected .
I tried the following code to wait and update , but pending event keep persistent as long as the timedout error occurs.
while (this.getPendingEvents().size() > 0) {
Thread.sleep(5000);
this.updateSubscribedEvents(2000);
}
The thingworx server doesn't has high CPU/Memory/Disk usage when the error occurs. I've also increase the thread number in the WSCommunication subsystem, but it doesn't help.
====================Trace log=====================
2019-12-25 15:32:38.512+0800 [L: DEBUG] [O: c.t.c.c.e.m.ConnectivityMonitorTask] [T: main] Initializing CommunicationEndpoint Connection Monitor...
2019-12-25 15:32:38.543+0800 [L: DEBUG] [O: c.t.c.c.e.m.ConnectivityMonitorTask] [T: Client-EndpointMonitor-1] Resetting duty cycle
2019-12-25 15:32:38.543+0800 [L: DEBUG] [O: c.t.c.c.e.m.ConnectivityMonitorTask] [T: Client-EndpointMonitor-1] Entering duty cycle ON
2019-12-25 15:32:38.543+0800 [L: INFO] [O: c.n.e.DeviceClient] [T: main] The client is now connected.
2019-12-25 15:32:38.543+0800 [L: INFO] [O: c.t.c.c.e.m.ConnectivityMonitorTask] [T: Client-EndpointMonitor-1] Endpoint not connected [name: EP_0, id: 0]. Attempting [re]connect in 0 seconds...
2019-12-25 15:32:38.543+0800 [L: DEBUG] [O: c.n.e.DeviceClient] [T: main] The connected thing is RemoteAgentThing
2019-12-25 15:32:38.543+0800 [L: DEBUG] [O: c.t.c.c.e.ClientCommunicationEndpoint] [T: Client-EndpointMonitor-1] Clearing endpoint authentication data [id: 0]
2019-12-25 15:32:38.543+0800 [L: INFO] [O: c.t.c.c.e.ClientCommunicationEndpoint] [T: Client-EndpointMonitor-1] Needed to refill connections on client endpoint [id: 0] : [active: 0, max: 1]
2019-12-25 15:32:38.887+0800 [L: INFO] [O: c.t.c.c.e.ClientCommunicationEndpoint] [T: Client-EndpointMonitor-1] Preparing new Connection Authentication Request: DispatchingClientEndpoint [id: 0, isConnected: false, open connections: 0, max connections: 1]
2019-12-25 15:32:38.887+0800 [L: DEBUG] [O: c.t.c.c.e.CommunicationEndpoint] [T: Client-EndpointMonitor-1] Sending connection authentication message, waiting for response [sync key: 1, message: AuthRequestMessage [requestId: 1, endpointId: -1, sessionId: -1, method: AUTHREQUEST]]
2019-12-25 15:32:38.934+0800 [L: DEBUG] [O: c.t.c.c.e.DispatchingClientEndpoint] [T: NettyClient-NIO-1] RESPONSE received [endpoint id: 0, duration: 47] ResponseMessage [requestId: 1, endpointId: 5, sessionId: 985993763, code: STATUS_SUCCESS, multipart: false, packet #: 0, total packets: 0]
2019-12-25 15:32:38.934+0800 [L: INFO] [O: c.t.c.c.e.ClientCommunicationEndpoint] [T: Client-EndpointMonitor-1] Authentication Request was SUCCESSFUL [tworx session id: 985993763, connection group id: 5]
2019-12-25 15:32:38.934+0800 [L: DEBUG] [O: c.t.c.c.e.CommunicationEndpoint] [T: Client-EndpointMonitor-1] [Endpoint id: 0, connection id: 0-0] added Connection
2019-12-25 15:32:38.934+0800 [L: INFO] [O: c.t.c.c.e.ClientCommunicationEndpoint] [T: Client-EndpointMonitor-1] Successfully reconnected client endpoint [id: 0] : [active: 1, max: 1]
2019-12-25 15:32:38.934+0800 [L: DEBUG] [O: c.t.c.c.e.CommunicationEndpoint] [T: Client-EndpointMonitor-1] Sending synchronous message, waiting for response [sync key: 2, message: BindRequestMessage [requestId: 2, method: BINDREQUEST, names: [RemoteAgentThing]]]
2019-12-25 15:32:38.934+0800 [L: DEBUG] [O: c.t.c.c.e.DispatchingClientEndpoint] [T: NettyClient-NIO-1] RESPONSE received [endpoint id: 0, duration: 0] ResponseMessage [requestId: 2, endpointId: -1, sessionId: -1, code: STATUS_SUCCESS, multipart: false, packet #: 0, total packets: 0]
2019-12-25 15:32:38.934+0800 [L: DEBUG] [O: c.t.c.c.e.CommunicationEndpoint] [T: Client-EndpointMonitor-1] Received synchronous message response [sync key: 2, message: BindRequestMessage [requestId: 2, method: BINDREQUEST, names: [RemoteAgentThing]], response: ResponseMessage [requestId: 2, endpointId: -1, sessionId: -1, code: STATUS_SUCCESS, multipart: false, packet #: 0, total packets: 0]]
2019-12-25 15:32:38.934+0800 [L: INFO] [O: c.t.c.c.e.m.ConnectivityMonitorTask] [T: Client-EndpointMonitor-1] Endpoint reconnected [name: EP_0, id: 0]
2019-12-25 15:32:39.949+0800 [L: DEBUG] [O: c.t.c.c.e.DispatchingClientEndpoint] [T: NettyClient-NIO-1] API REQUEST received [endpoint id: 0] APIRequestMessage [requestId: 9, endpointId: -1, sessionId: -1, method: POST, entityName: RemoteAgentThing, characteristic: Unknown, target: ]
2019-12-25 15:32:39.949+0800 [L: DEBUG] [O: c.t.c.c.e.CommunicationEndpoint] [T: ClientProcessor-1] Sending synchronous message, waiting for response [sync key: 3, message: APIRequestMessage [requestId: 3, endpointId: 0, sessionId: 985993763, method: POST, entityName: RemoteAgentThing, characteristic: Services, target: GetPropertySubscriptions]]
2019-12-25 15:32:39.949+0800 [L: DEBUG] [O: c.t.c.c.e.DispatchingClientEndpoint] [T: NettyClient-NIO-1] RESPONSE received [endpoint id: 0, duration: 0] ResponseMessage [requestId: 3, endpointId: 0, sessionId: -1, code: STATUS_SUCCESS, multipart: false, packet #: 0, total packets: 0]
2019-12-25 15:32:39.949+0800 [L: DEBUG] [O: c.t.c.c.e.CommunicationEndpoint] [T: ClientProcessor-1] Received synchronous message response [sync key: 3, message: APIRequestMessage [requestId: 3, endpointId: 0, sessionId: 985993763, method: POST, entityName: RemoteAgentThing, characteristic: Services, target: GetPropertySubscriptions], response: ResponseMessage [requestId: 3, endpointId: 0, sessionId: -1, code: STATUS_SUCCESS, multipart: false, packet #: 0, total packets: 0]]
2019-12-25 15:32:39.949+0800 [L: DEBUG] [O: c.t.c.c.e.CommunicationEndpoint] [T: ClientProcessor-1] Sending synchronous message, waiting for response [sync key: 4, message: APIRequestMessage [requestId: 4, endpointId: 0, sessionId: 985993763, method: POST, entityName: RemoteAgentThing, characteristic: Services, target: GetEventSubscriptions]]
2019-12-25 15:32:39.965+0800 [L: DEBUG] [O: c.t.c.c.e.DispatchingClientEndpoint] [T: NettyClient-NIO-1] RESPONSE received [endpoint id: 0, duration: 16] ResponseMessage [requestId: 4, endpointId: 0, sessionId: -1, code: STATUS_SUCCESS, multipart: false, packet #: 0, total packets: 0]
2019-12-25 15:32:39.965+0800 [L: DEBUG] [O: c.t.c.c.e.CommunicationEndpoint] [T: ClientProcessor-1] Received synchronous message response [sync key: 4, message: APIRequestMessage [requestId: 4, endpointId: 0, sessionId: 985993763, method: POST, entityName: RemoteAgentThing, characteristic: Services, target: GetEventSubscriptions], response: ResponseMessage [requestId: 4, endpointId: 0, sessionId: -1, code: STATUS_SUCCESS, multipart: false, packet #: 0, total packets: 0]]
2019-12-25 15:32:43.550+0800 [L: DEBUG] [O: c.t.c.c.e.CommunicationEndpoint] [T: main] Sending synchronous message, waiting for response [sync key: 5, message: APIRequestMessage [requestId: 5, endpointId: 0, sessionId: 985993763, method: POST, entityName: RemoteAgentThing, characteristic: Services, target: GetDataCollectorInfo]]
2019-12-25 15:32:43.768+0800 [L: TRACE] [O: c.t.c.c.c.ResponseSynchronizationContext] [T: NettyClient-NIO-1] START: receiving multipart message [total packets: 2, 1st packet index: 1, blocksize: 8188]
2019-12-25 15:32:43.768+0800 [L: TRACE] [O: c.t.c.c.p.PacketCollection] [T: NettyClient-NIO-1] adding message part [ResponseMessage [requestId: 5, endpointId: 0, sessionId: -1, code: STATUS_SUCCESS, multipart: true, packet #: 1, total packets: 2]]
2019-12-25 15:32:43.768+0800 [L: TRACE] [O: c.t.c.c.c.ResponseSynchronizationContext] [T: NettyClient-NIO-1] ------ multipart message [current packet: 1, message packet index: 1]
2019-12-25 15:32:43.768+0800 [L: DEBUG] [O: c.t.c.c.e.DispatchingClientEndpoint] [T: NettyClient-NIO-1] RESPONSE received [endpoint id: 0, duration: 0] ResponseMessage [requestId: 5, endpointId: 0, sessionId: -1, code: STATUS_SUCCESS, multipart: true, packet #: 1, total packets: 2]
2019-12-25 15:32:43.768+0800 [L: TRACE] [O: c.t.c.c.p.PacketCollection] [T: NettyClient-NIO-1] adding message part [ResponseMessage [requestId: 5, endpointId: 0, sessionId: -1, code: STATUS_SUCCESS, multipart: true, packet #: 2, total packets: 2]]
2019-12-25 15:32:43.768+0800 [L: TRACE] [O: c.t.c.c.c.ResponseSynchronizationContext] [T: NettyClient-NIO-1] ------ multipart message [current packet: 2, message packet index: 2]
2019-12-25 15:32:43.768+0800 [L: TRACE] [O: c.t.c.c.c.ResponseSynchronizationContext] [T: NettyClient-NIO-1] STOP: Multipart message complete [packets: 2, length: 11234]
2019-12-25 15:32:43.768+0800 [L: DEBUG] [O: c.t.c.c.e.DispatchingClientEndpoint] [T: NettyClient-NIO-1] RESPONSE received [endpoint id: 0, duration: 218] ResponseMessage [requestId: 5, endpointId: 0, sessionId: -1, code: STATUS_SUCCESS, multipart: true, packet #: 2, total packets: 2]
2019-12-25 15:32:43.987+0800 [L: DEBUG] [O: c.t.c.c.e.CommunicationEndpoint] [T: main] Received synchronous message response [sync key: 5, message: APIRequestMessage [requestId: 5, endpointId: 0, sessionId: 985993763, method: POST, entityName: RemoteAgentThing, characteristic: Services, target: GetDataCollectorInfo], response: ResponseMessage [requestId: 5, endpointId: 0, sessionId: -1, code: STATUS_SUCCESS, multipart: false, packet #: 0, total packets: 0]]
2019-12-25 15:32:52.130+0800 [L: DEBUG] [O: c.t.c.c.e.CommunicationEndpoint] [T: main] Sending synchronous message, waiting for response [sync key: 27, message: APIRequestMessage [requestId: 27, endpointId: 0, sessionId: 985993763, method: POST, entityName: RemoteAgentThing, characteristic: Services, target: ProcessRemoteEvents]]
2019-12-25 15:32:52.130+0800 [L: DEBUG] [O: c.t.c.c.e.DispatchingClientEndpoint] [T: NettyClient-NIO-1] RESPONSE received [endpoint id: 0, duration: 0] ResponseMessage [requestId: 27, endpointId: 0, sessionId: -1, code: STATUS_SUCCESS, multipart: false, packet #: 0, total packets: 0]
2019-12-25 15:32:52.130+0800 [L: DEBUG] [O: c.t.c.c.e.CommunicationEndpoint] [T: main] Received synchronous message response [sync key: 27, message: APIRequestMessage [requestId: 27, endpointId: 0, sessionId: 985993763, method: POST, entityName: RemoteAgentThing, characteristic: Services, target: ProcessRemoteEvents], response: ResponseMessage [requestId: 27, endpointId: 0, sessionId: -1, code: STATUS_SUCCESS, multipart: false, packet #: 0, total packets: 0]]
2019-12-25 15:32:52.162+0800 [L: DEBUG] [O: c.t.c.c.e.CommunicationEndpoint] [T: main] Sending synchronous message, waiting for response [sync key: 28, message: APIRequestMessage [requestId: 28, endpointId: 0, sessionId: 985993763, method: POST, entityName: RemoteAgentThing, characteristic: Services, target: ProcessRemoteEvents]]
2019-12-25 15:32:52.162+0800 [L: TRACE] [O: c.t.c.c.p.PacketCollection] [T: main] Created new multi-part message [original length: 29161, total packets: 4, header size: 33, data size: 29128, effective block size: 8149]
2019-12-25 15:32:52.162+0800 [L: TRACE] [O: c.t.c.c.p.PacketCollection] [T: main] Preparing to send multi-part message [request id: 28, endpoint id: 0, packets: 4]
2019-12-25 15:32:52.162+0800 [L: TRACE] [O: c.t.c.c.p.PacketCollection] [T: main] Message part [smbduration (ms): 0, packet index: 1, packet count: 4, request id: 28, endpoint id: 0, length: 8149]
2019-12-25 15:32:52.162+0800 [L: TRACE] [O: c.t.c.c.p.PacketCollection] [T: main] Message part [smbduration (ms): 0, packet index: 2, packet count: 4, request id: 28, endpoint id: 0, length: 8149]
2019-12-25 15:32:52.162+0800 [L: TRACE] [O: c.t.c.c.p.PacketCollection] [T: main] Message part [smbduration (ms): 0, packet index: 3, packet count: 4, request id: 28, endpoint id: 0, length: 8149]
2019-12-25 15:32:52.162+0800 [L: TRACE] [O: c.t.c.c.p.PacketCollection] [T: main] Message part [smbduration (ms): 0, packet index: 4, packet count: 4, request id: 28, endpoint id: 0, length: 4681]
2019-12-25 15:32:52.162+0800 [L: DEBUG] [O: c.t.c.c.e.DispatchingClientEndpoint] [T: NettyClient-NIO-1] RESPONSE received [endpoint id: 0, duration: 0] ResponseMessage [requestId: 28, endpointId: 0, sessionId: -1, code: STATUS_SUCCESS, multipart: false, packet #: 0, total packets: 0]
2019-12-25 15:32:52.162+0800 [L: DEBUG] [O: c.t.c.c.e.CommunicationEndpoint] [T: main] Received synchronous message response [sync key: 28, message: APIRequestMessage [requestId: 28, endpointId: 0, sessionId: 985993763, method: POST, entityName: RemoteAgentThing, characteristic: Services, target: ProcessRemoteEvents], response: ResponseMessage [requestId: 28, endpointId: 0, sessionId: -1, code: STATUS_SUCCESS, multipart: false, packet #: 0, total packets: 0]]
2019-12-25 15:32:52.193+0800 [L: DEBUG] [O: c.t.c.c.e.CommunicationEndpoint] [T: main] Sending synchronous message, waiting for response [sync key: 29, message: APIRequestMessage [requestId: 29, endpointId: 0, sessionId: 985993763, method: POST, entityName: RemoteAgentThing, characteristic: Services, target: ProcessRemoteEvents]]
2019-12-25 15:32:52.193+0800 [L: DEBUG] [O: c.t.c.c.e.CommunicationEndpoint] [T: NettyClient-NIO-1] [Endpoint id: 0, connection id: 0-0] removed Connection
2019-12-25 15:32:52.193+0800 [L: INFO] [O: c.t.c.c.e.CommunicationEndpoint] [T: NettyClient-NIO-1] All Connections are closed [endpoint id: 0]
2019-12-25 15:32:52.976+0800 [L: DEBUG] [O: c.t.c.c.e.m.ConnectivityMonitorTask] [T: Client-EndpointMonitor-1] Entering duty cycle ON
2019-12-25 15:32:52.976+0800 [L: INFO] [O: c.t.c.c.e.m.ConnectivityMonitorTask] [T: Client-EndpointMonitor-1] Endpoint not connected [name: EP_0, id: 0]. Attempting [re]connect in 60 seconds...
2019-12-25 15:33:00.196+0800 [L: DEBUG] [O: c.t.c.c.e.ClientCommunicationEndpoint] [T: main] Endpoint timeout counter [id: 0]: 1, max: 5
2019-12-25 15:33:00.196+0800 [L: ERROR] [O: c.t.c.c.t.VirtualThing] [T: main] Unable To Update Subscribed Events For RemoteAgentThing : Timed out APIRequestMessage [requestId: 29, endpointId: 0, sessionId: 985993763, method: POST, entityName: RemoteAgentThing, characteristic: Services, target: ProcessRemoteEvents]
2019-12-25 15:33:00.227+0800 [L: INFO] [O: c.n.e.DeviceAgentThing] [T: main] Find pending events, sleep 5 seconds for processing. size: 1
2019-12-25 15:33:05.227+0800 [L: DEBUG] [O: c.t.c.c.e.CommunicationEndpoint] [T: main] Sending synchronous message, waiting for response [sync key: 30, message: APIRequestMessage [requestId: 30, endpointId: 0, sessionId: 985993763, method: POST, entityName: RemoteAgentThing, characteristic: Services, target: ProcessRemoteEvents]]
2019-12-25 15:33:05.227+0800 [L: ERROR] [O: c.t.c.c.t.VirtualThing] [T: main] Unable To Update Subscribed Events For RemoteAgentThing : No open connections were available on endpoint 0
