Sporadic connection timeout after 2 hours 10 minutes / Error 23790

[olegpank]

Hi,
Please help to identify the cause of the following issue:
The part of end users (not everyone) gets sporadic nc connection timeout with the error 23790. The issue occurs after ca. 2 hours after the connection has been established. Disconnection takes place sporadic, it means it can occur once a day, twice a day or every two hours. The end users have Windows 7 x64 Ent and VPN SSL is used. Host Checker evaluates the policies every 2 hours.
The session and idle timeouts for the user role have been checked – more than 150 minutes.
DHCP lease time has been checked for the end users’ clients/routers – it’s not the cause.

In the local user’s logs the following has been found:


#########################################################################################################################
00147,09 2016/06/23 10:30:41.125 3 username dsHostChecker.exe salib_OSSL p6860 t2170 saCert.cpp:156 - 'validateCertChain' number of certs in the chain = 4
00214,09 2016/06/23 10:30:41.160 3 username dsHostChecker.exe salib_OSSL p6860 t2170 win_ssl.cpp:265 - 'win_ssl_connect' SSL connect ssl=0227E628/sd=2072 connection using cipher AES128-SHA256
00141,09 2016/06/23 10:30:41.168 3 username dsHostChecker.exe salib_OSSL p6860 t2170 win_ssl.cpp:657 - 'getToken' found Process dsNetworkConnect.exe
00147,09 2016/06/23 10:30:41.169 3 username dsHostChecker.exe salib_OSSL p6860 t2170 saCert.cpp:373 - 'validateCommonName' start verifying cert using CAPI
00180,09 2016/06/23 10:30:41.246 3 username dsHostChecker.exe salib_OSSL p6860 t2170 saCert.cpp:396 - 'validateCommonName' Server->gateway.examplegateway.examplegateway.exampleonCheckHttpStatus() failed
00147,09 2016/06/23 10:30:41.266 1 username dsHostChecker.exe dsWinClient p6860 t2170 dsHttpImpl.cpp:316 - 'DSHttpImpl::recvResponse()' sendRequest failed
00166,09 2016/06/23 10:30:41.266 1 username dsHostChecker.exe dsWinClient p6860 t2170 dsHttpRequest.cpp:56 - 'DSHttpRequest::httpRequest()' m_http->recvResponse() failed: 16
00145,09 2016/06/23 10:30:41.266 1 username dsHostChecker.exe dsWinClient p6860 t2170 dsHttpThread.cpp:148 - 'DSHttpThread::run()' openConnection failed
00270,09 2016/06/23 10:30:41.273 3 username dsHostChecker.exe dsHostChecker p6860 t1B44 DspreauthCookieHelper.cpp:54 - 'SetDspreauthCookie' Wrote cookie `DSPREAUTH= ; path=/dana-na/; expires=Thu, 31-Dec-2037 00:00:00 GMT; secure' for URL `https://gateway.example/dana-na/'
00146,09 2016/06/23 10:30:41.273 3 username dsHostChecker.exe dsHostChecker p6860 t1B44 dsQuerySession.cpp:210 - 'httpSendStatus' status: HTTP_SEND_ERROR
00133,09 2016/06/23 10:30:41.273 3 username dsHostChecker.exe dsWinClient p6860 t1B44 dsThread.cpp:187 - 'DSThreadMonitor::release()' called
00159,09 2016/06/23 10:30:41.273 3 username dsHostChecker.exe dsWinClient p6860 t1B44 dsThread.cpp:212 - 'DSThreadMonitor::release()' release thread 22c8360, size = 1
00132,09 2016/06/23 10:30:41.275 3 username dsHostChecker.exe dsWinClient p6860 t1B44 dsThread.cpp:221 - 'DSThreadMonitor::release()' ended
00132,09 2016/06/23 10:30:41.275 3 username dsHostChecker.exe dsHostChecker p6860 t1B44 dsQuerySession.cpp:114 - 'run' Check http status...
00153,09 2016/06/23 10:30:41.275 3 username dsHostChecker.exe dsHostChecker p6860 t1B44 dsQuerySession.cpp:118 - 'run' HTTP_SEND_ERROR, Host Checker quitting...
00170,09 2016/06/23 10:30:41.275 3 username dsHostChecker.exe dsHostChecker p6860 t1B44 dsQuerySession.cpp:135 - 'run' ********************Query Session ended*******************
00141,09 2016/06/23 10:30:41.276 1 username dsHostChecker.exe dsHostChecker p6860 t1B40 HttpNAR.cpp:204 - 'TncHandshake' External break, quitting...
00158,09 2016/06/23 10:30:41.277 3 username dsHostChecker.exe dsHostChecker p6860 t1B3C dsWinClient/dsSignout.h:118 - 'ThreadFunction' Receive exit event, quiting...
00185,09 2016/06/23 10:30:41.277 3 username dsHostChecker.exe ShavlikIMC p6860 t1AD0 ShavlikIMC.cpp:290 - 'overrideNotifyConnectionChange' Enter overrideNotifyConnectionChange [cid=1], state=5
00170,09 2016/06/23 10:30:41.277 3 username dsHostChecker.exe dsHostChecker p6860 t1AD0 TNCCnars.c:271 - 'TNCCN_ReleaseConnectionId' Connection ID 0x1 closed for NAR 0xbb5c0e99.
00158,09 2016/06/23 10:30:41.278 3 username dsHostChecker.exe hcUtils p6860 t1AD0 dsPolicyMonitor.cpp:128 - 'stopMonitoring' Signalling Policy Monitor thread to exit
00171,09 2016/06/23 10:30:41.278 3 username dsHostChecker.exe hcUtils p6860 t1B28 dsPolicyMonitor.cpp:88 - 'runPolicyMonitor' Policy monitoring is exiting. So break from the loop
00147,09 2016/06/23 10:30:41.278 3 username dsHostChecker.exe hcUtils p6860 t1AD0 dsPolicyMonitor.cpp:147 - 'stopMonitoring' Policy Monitor thread stopped
00137,09 2016/06/23 10:30:41.278 3 username dsHostChecker.exe hcUtils p6860 t1AD0 dsActionExecuter.cpp:48 - 'stop' Stopping the DSActionExecuter
00158,09 2016/06/23 10:30:41.278 3 username dsHostChecker.exe hcUtils p6860 t1AD0 dsPolicyMonitor.cpp:128 - 'stopMonitoring' Signalling Policy Monitor thread to exit
00137,09 2016/06/23 10:30:41.278 3 username dsHostChecker.exe hcUtils p6860 t1AD0 dsActionExecuter.cpp:48 - 'stop' Stopping the DSActionExecuter
00158,09 2016/06/23 10:30:41.280 3 username dsHostChecker.exe hcUtils p6860 t1AD0 dsPolicyMonitor.cpp:128 - 'stopMonitoring' Signalling Policy Monitor thread to exit
00137,09 2016/06/23 10:30:41.280 3 username dsHostChecker.exe hcUtils p6860 t1AD0 dsActionExecuter.cpp:48 - 'stop' Stopping the DSActionExecuter
00206,09 2016/06/23 10:40:40.277 0 username IEXPLORE.EXE DSInvokeSetupClient p8440 t2014 dsWinLogserviceApiLib.cpp:863 - '***' **************************************************************************************

#########################################################################################################################

[Filbert]

What do the server side logs show for the connection?

[zanyterp]

If you are in an active/active cluster, that could cause it (depending on how you are load balancing).
Something is causing the session to be removed on the server (23790 == session timeout); if you remove the periodic update, does the issue resolve?

[olegpank]

Hi, thanks for response.
Periodic update cannot be removed or disabled due to security policies.
Unfortunately I have personally no access to server logs, but I have got the following information from Access-Server engineer:

##############################
In log I see that he is logged in, session o.k.,
than after 2 hrs we check the login and security credentials again -
this is not true by client
than te session will be logged off
Radius Accounting: Successfully sent radius accounting USER session stop request for
user(client) send the disconnect request
##############################

If I’ll get the extract from server logs, I’ll paste it here.

Can you advise smth.

Thanks.

[zanyterp · Accepted solution]

Thank you for the update; if you can get the server extract, that would be great
Symptomatically the issue is that something is blocking the connection (load balancer, proxy, firewall) for the Host Checker update; however, there are some versions that this happens due to software issues on the client/server. Can you confirm what releases you are using?

[olegpank]

Hi,

thanks for response.

Here are the versions of client software:
################################
dsNetworkConnect.exe: 8, 0, 14, 41869
dsNcAdmin.dll: 8, 0, 14, 41869
dsNcService.exe: 8, 0, 14, 41869
dsNcAdpt.sys: 7.2.0
################################

[olegpank]

[b]Hi,

I have updated logs, which point to error 'DSSSL_recv' returned 0x2746 error .

Remark: The real IPs and Hostnames are changed. [/b]

########################################################################
00124,09 2016/06/29 17:11:49.022 3 SYSTEM dsNcService.exe dsNcService p7940 t1BB0 ncp.cpp:922 - 'ncp' connect to CLIENT.example:443 svc 4
00130,09 2016/06/29 17:11:49.084 1 SYSTEM dsNcService.exe dsNcService p7940 t1CB4 ncp_dsssl.cpp:923 - 'DSSSL_recv' returned 0x2746 error.
00169,09 2016/06/29 17:11:49.084 3 SYSTEM dsNcService.exe dsNcService p7940 t1BB0 ncphandler.cpp:339 - 'ncphandler' control channel disconnected due to error 2746, reconnecting
00128,09 2016/06/29 17:11:49.084 3 SYSTEM dsNcService.exe dsNcService p7940 t1BB0 session.cpp:697 - 'session' reconnecting attempts = 2
00143,09 2016/06/29 17:11:49.084 3 SYSTEM dsNcService.exe dsNcService p7940 t1BB0 routemon.cpp:1469 - 'rmon' Collecting latest routes from the system
00148,09 2016/06/29 17:11:49.084 3 SYSTEM dsNcService.exe dsNcService p7940 t1BB0 routemon.cpp:1918 - 'rmon' interface 0x00000010 has address 111.111.111.111
00144,09 2016/06/29 17:11:49.084 3 SYSTEM dsNcService.exe dsNcService p7940 t1BB0 routemon.cpp:1918 - 'rmon' interface 0x00000001 has address 127.0.0.1
00150,09 2016/06/29 17:11:49.084 3 SYSTEM dsNcService.exe dsNcService p7940 t1BB0 routemon.cpp:1918 - 'rmon' interface 0x0000000B has address 192.168.178.153
00127,09 2016/06/29 17:11:49.100 3 SYSTEM dsNcService.exe dsNcService p7940 t1BB0 routemon.cpp:1838 - 'rmon' Found best route via ifc
00190,09 2016/06/29 17:11:49.100 3 SYSTEM dsNcService.exe dsNcService p7940 t1BB0 routemon.cpp:1490 - 'rmon' best route to 222.222.222.222 is 222.222.222.222/255.255.255.255 via 0x0000000B metric: 26
00169,09 2016/06/29 17:11:49.100 3 SYSTEM dsNcService.exe dsNcService p7940 t1BB0 routemon.cpp:1539 - 'rmon' Host route to 222.222.222.222 already exists, will not add a new one
00149,09 2016/06/29 17:11:49.100 1 SYSTEM dsNcService.exe dsNcService p7940 t1BB0 routemon.cpp:1543 - 'rmon' Setting Best route DEDEDEDE 1b2a8c0 ffffffff b
00124,09 2016/06/29 17:11:49.100 3 SYSTEM dsNcService.exe dsNcService p7940 t1BB0 ncp.cpp:922 - 'ncp' connect to CLIENT.example:443 svc 4
00138,09 2016/06/29 17:11:49.100 3 SYSTEM dsNcService.exe dsNcService p7940 t1BB0 ncp_dsssl.cpp:187 - 'connect' creating a new HTTP connection...
00202,09 2016/06/29 17:11:49.193 3 SYSTEM dsNcService.exe dsNcService p7940 t1CB4 DSSSLSock.cpp:3405 - 'dsssl' ive_cert_hash = 2472c225fcfd9d302a7994000fc9a875, computed_hash = 2472c225fcfd9d302a7994000fc9a875
00151,09 2016/06/29 17:11:49.224 1 SYSTEM dsNcService.exe dsNcService p7940 t1CB4 ncp_dsssl.cpp:421 - 'worker' Got a redirect, probably due to session timeout
00125,09 2016/06/29 17:11:49.224 3 SYSTEM dsNcService.exe dsNcService p7940 t1BB0 ncphandler.cpp:319 - 'ncphandler' session timedout

########################################################################

[b] Exactly 10 minutes before the following error has come: [/b]

########################################################################
00148,09 2016/06/29 17:01:41.674 3 USER dsHostChecker.exe dsHostChecker p7048 t2340 dsQuerySession.cpp:59 - 'onCheckHttpStatus' Failed http status: 404
00166,09 2016/06/29 17:01:41.674 1 USER dsHostChecker.exe dsWinClient p7048 t2340 dsHttpImpl.cpp:157 - 'DSHttpImpl::sendRequest()' m_listener->onCheckHttpStatus() failed
00147,09 2016/06/29 17:01:41.674 1 USER dsHostChecker.exe dsWinClient p7048 t2340 dsHttpImpl.cpp:316 - 'DSHttpImpl::recvResponse()' sendRequest failed
00166,09 2016/06/29 17:01:41.674 1 USER dsHostChecker.exe dsWinClient p7048 t2340 dsHttpRequest.cpp:56 - 'DSHttpRequest::httpRequest()' m_http->recvResponse() failed: 16
00145,09 2016/06/29 17:01:41.674 1 USER dsHostChecker.exe dsWinClient p7048 t2340 dsHttpThread.cpp:149 - 'DSHttpThread::run()' openConnection failed
00273,09 2016/06/29 17:01:41.674 3 USER dsHostChecker.exe dsHostChecker p7048 t404 DspreauthCookieHelper.cpp:54 - 'SetDspreauthCookie' Wrote cookie `DSPREAUTH= ; path=/dana-na/; expires=Thu, 31-Dec-2037 00:00:00 GMT; secure' for URL `https://gateway.example/dana-na/'
00145,09 2016/06/29 17:01:41.674 3 USER dsHostChecker.exe dsHostChecker p7048 t404 dsQuerySession.cpp:210 - 'httpSendStatus' status: HTTP_SEND_ERROR
#######################################################################

[b] Any ideas?

Thanks,
Oleg [/b]