Client side: assertion failure on secure channel disconnection
Description
On connection failure (socket closed by peer) the following assertion failed: SOPC_SecureConnectionStateMgr_OnTimerEvent at sopc_secure_connection_state_mgr.c:2967:
case TIMER_SC_REQUEST_TIMEOUT:
{
assert(auxParam <= UINT32_MAX);
SOPC_Logger_TraceDebug("ScStateMgr: TIMER_SC_REQUEST_TIMEOUT scIdx=%" PRIu32 " reqId=%" PRIuPTR, eltId,
auxParam);
SOPC_SecureConnection* scConnection = SC_GetConnection(eltId);
if (scConnection == NULL)
{
return;
}
assert(scConnection->state != SECURE_CONNECTION_STATE_SC_CLOSED);
The last lines of the log traces are the following:
[2019/10/19 12:14:41.546] Toolkit (Debug) SocketEvent: INT_SOCKET_READY_TO_READ socketIdx=3
[2019/10/19 12:14:41.546] Toolkit (Debug) ScStateMgr: SOCKET_FAILURE scIdx=6 socketIdx=3
[2019/10/19 12:14:41.546] Toolkit (Debug) ServicesMgr: SC_REQUEST_TIMEOUT scIdx=6 reqHandle=15
[2019/10/19 12:14:41.546] Toolkit (Debug) ServicesMgr: SC_SC_DISCONNECTED scIdx=6
[2019/10/19 12:14:41.546] Toolkit (Debug) ServicesMgr: SE_TO_SE_ACTIVATE_ORPHANED_SESSION session=19 scCfgIdx=3
[2019/10/19 12:14:41.546] Toolkit (Debug) App: SE_SND_REQUEST_FAILED retStatus=6 msgTyp=PublishRequest context=139808502157904
[2019/10/19 12:14:41.548] Toolkit (Debug) ServicesMgr: APP_TO_SE_CLOSE_SESSION session=19
[2019/10/19 12:14:41.548] Toolkit (Error) ServicesMgr: APP_TO_SE_CLOSE_SESSION failed session=19
[2019/10/19 12:14:41.549] Toolkit (Debug) App: SE_SESSION_REACTIVATING session=19 context=102597
[2019/10/19 12:14:41.551] Toolkit (Debug) App: SE_SESSION_ACTIVATION_FAILURE session=19 context=102597
[2019/10/19 12:14:42.416] Toolkit (Debug) ScStateMgr: TIMER_SC_REQUEST_TIMEOUT scIdx=6 reqId=17133
Analysis
- It is observable that socket (socketIdx=3) was closed by peer due to events INT_SOCKET_READY_TO_READ and then SOCKET_FAILURE. Those events indicate a 0 bytes
read()
which means socket has been closed when bytes were indicated available on the socket prior to read call. - The associated secure channel (scIdx=6) is internally closed as a consequence: a. Event SC_REQUEST_TIMEOUT is fired to the services layer (and then application code with SE_ND_REQUEST_FAILED) to indicate that a pending request has failed to be responded due to disconnection b. Event SC_SC_DISCONNECTED is fired to the services layer to indicate channel disconnection
- Other events *SESSION* are direct consequence of the channel disconnection and are expected
- Event TIMER_SC_REQUEST_TIMEOUT is received by secure channel (scIdx=6)
This is the step 4. which causes the assertion to fail. It should be the timeout set for the request we already sent a SC_REQUEST_TIMEOUT to services layer. Before sending it the timer has been cancelled but the TIMER_SC_REQUEST_TIMEOUT should have been fired just before or during the treatment of the SOCKET_FAILURE event.
Fix
This event shall be ignored because it is possible to receive it just after a connection is closed due to asynchronism.
Edited by Vincent Monfort