G
Guest
We have a Windows 2003 Server with ISA 2004 serving as a VPN server. Quite
freqently I have users report that they cannot connect to the server. At
other times there is no problem. When users cannot connect they report that
their VPN client "hangs" on "Verifying Username and Password".
There is no entry in the Enent Viewer corresponding to the connection
attempt (logging is set to Maximum)
The following is what is recorded in the various trace logs (all other logs
have no information corresponding to this connection attempt). In these logs
the call attempt started on 11/17/2005 at 11:18:14.
[2512] 11-17 11:18:14:899: Rasman state change received from port 41, 1->5
[2512] 11-17 11:18:14:899: Rasman state change received from port 41, 5->2
[2512] 11-17 11:18:14:899: SvDevConnected: Entered, hPort=41
[2512] 11-17 11:18:14:899: TimerQRemove called
[2512] 11-17 11:18:42:242: Rasman state change received from port 41, 2->4
[2512] 11-17 11:18:42:242: SvDevDisconnected:Entered, hPort=41
[2512] 11-17 11:18:42:242: DevStartClosing: Entered, hPort=41
[2512] 11-17 11:18:42:242: TimerQRemove called
[2512] 11-17 11:18:42:242: TimerQRemove called
[2512] 11-17 11:18:42:242: TimerQRemove called
[2512] 11-17 11:18:42:242: DevCloseComplete:hPort=41,Auth=0,Rcv=0,Conn=1
0,Sec=4 2,Ppp=0
[2512] 11-17 11:18:42:242: RmListen: Listen posted on port 41
[2512] 11-17 11:18:42:242: RasPortListen dwRetCode=600
[1836] 11-17 11:18:14:899: WorkerThread: Async work event signaled on port:
VPN4-26
[1836] 11-17 11:18:14:899: OVEVT_DEV_ASYNCOP. pOverlapped = 0x10f3b0
[1836] 11-17 11:18:14:899: ServiceWorkRequest: Async op event 27 for port
VPN4-26 returned 600
[1836] 11-17 11:18:14:899: WorkerThread: Async work event signaled on port:
VPN4-26
[1836] 11-17 11:18:14:899: OVEVT_DEV_ASYNCOP. pOverlapped = 0x10f3b0
[1836] 11-17 11:18:14:899: ServiceWorkRequest: Async op event 27 for port
VPN4-26 returned 600
[1836] 11-17 11:18:14:899: WorkerThread: Async work event signaled on port:
VPN4-26
[1836] 11-17 11:18:14:899: OVEVT_DEV_ASYNCOP. pOverlapped = 0x10f3b0
[1836] 11-17 11:18:14:899: d:\srv03rtm\net\rras\ras\rasman\rasman\request.c:
7507: port 41 state chg: prev=1, new=5
[1836] 11-17 11:18:14:899: RasmanReceiveFlags = 0x0
[1836] 11-17 11:18:14:899: d:\srv03rtm\net\rras\ras\rasman\rasman\worker.c:
2269: port 41 async reqtype chg: prev=27, new=0
[1836] 11-17 11:18:14:899: ServiceWorkRequest: Async op event 27 for port
VPN4-26 returned 0
[2512] 11-17 11:18:14:899: ConnectCompleteRequest: entered for port 41
[2512] 11-17 11:18:14:899: d:\srv03rtm\net\rras\ras\rasman\rasman\request.c:
7401: port 41 state chg: prev=5, new=2
[2512] 11-17 11:18:14:899: AllocBundle: pBundle=0x9544108
[2512] 11-17 11:18:14:899: d:\srv03rtm\net\rras\ras\rasman\rasman\request.c
8901: Mapping Cookie to handle. port = VPN4-26(0x12f6e0), Bundlehandle =
0xe6,
linkhandle = 0xe6
[2512] 11-17 11:18:14:899: Connection Completed on port: VPN4-26, error
code: 0
[2512] 11-17 11:18:14:899: d:\srv03rtm\net\rras\ras\rasman\rasman\request.c:
6654: port 41 async reqtype chg: prev=0, new=26
[1836] 11-17 11:18:42:242: WorkerThread: Disconnect event signaled on port:
VPN4-26
[1836] 11-17 11:18:42:242: OVEVT_DEV_STATECHANGE. pOverlapped = 0x10f3f0
[1836] 11-17 11:18:42:242: d:\srv03rtm\net\rras\ras\rasman\rasman\worker.c,
1908: Disconnecting port 41, connection 0x0, reason 1
[1836] 11-17 11:18:42:242: Disconnecting Port 0xVPN4-26, reason 1
[1836] 11-17 11:18:42:242: DisconnectPort: Saving Bundle stats for port
VPN4-26
[1836] 11-17 11:18:42:242: 10. Throwing away handle 0x18d0!
[1836] 11-17 11:18:42:242: d:\srv03rtm\net\rras\ras\rasman\rasman\util.c
1992: Disconnected Port 41, reason 1. rc=0x0
[1836] 11-17 11:18:42:242: FreeBundle: freeing pBundle=0x9544108
[1836] 11-17 11:18:42:242: d:\srv03rtm\net\rras\ras\rasman\rasman\util.c:
2213: port 41 state chg: prev=2, new=3
[1836] 11-17 11:18:42:242: d:\srv03rtm\net\rras\ras\rasman\rasman\util.c:
2229: port 41 state chg: prev=3, new=4
[1836] 11-17 11:18:42:242: 5. Notifying of disconnect on port 41
[1836] 11-17 11:18:42:242: d:\srv03rtm\net\rras\ras\rasman\rasman\util.c:
2340: port 41 async reqtype chg: prev=26, new=0
[1836] 11-17 11:18:42:242: *****
DisconnectReason=1,pConn=0x0,cbports=0,signaled=0,hEvent=0xffffffff,fRedial=0
[1836] 11-17 11:18:42:242: DisconnectPort Complete
[1836] 11-17 11:18:42:242: d:\srv03rtm\net\rras\ras\rasman\rasman\worker.c:
1946: port 41 state chg: prev=4, new=4
[1836] 11-17 11:18:42:242: d:\srv03rtm\net\rras\ras\rasman\rasman\worker.c:
1950: port 41 async reqtype chg: prev=0, new=0
[2512] 11-17 11:18:42:242: DeviceListenRequest: Clearing Autoclose flag on
port VPN4-26
[2512] 11-17 11:18:42:242: d:\srv03rtm\net\rras\ras\rasman\rasman\util.c:
2547: port 41 state chg: prev=4, new=1
[2512] 11-17 11:18:42:242: d:\srv03rtm\net\rras\ras\rasman\rasman\util.c:
2578: port 41 async reqtype chg: prev=0, new=27
[2512] 11-17 11:18:42:242: Listen posted on port: VPN4-26, error code 600
[452] 11:18:14:899: [INFO ] LineEventProcSP: HTapiLine=000102EE,
HTapiCall=00000000, msg=1f4, P1=x6040012, P2=xa5910, P3=x0
[452] 11:18:14:899: [TRACE] LineEventProc
[452] 11:18:14:899: [TRACE] CreatetCall: enter, ptLine=00555F38
[452] 11:18:14:899: [INFO ] CreatetCall: calling NewObject ptCall 00556858
[452] 11:18:14:899: [TRACE] CreatetCall: NewObject returned 0x100ef
[452] 11:18:14:899: [TRACE] CreatetCall: exit, new ptCall=00556858
[452] 11:18:14:899: [INFO ] LineEventProcSP: HTapiLine=000102EE,
HTapiCall=000100EF, msg=2, P1=x2, P2=x0, P3=x100
[1792] 11:18:14:899: [INFO ] Got a line spevent, htLine = 0x102ee, htCall =
0x100ef, dwMsg = 0x2
[1792] 11:18:14:899: [TRACE] LineEventProc
[1792] 11:18:14:899: [EVENT] LineEventProc: LINE_CALLSTATE event x2
[1792] 11:18:14:899: [TRACE] CreatetCallClient: enter, ptCall=00556858,
[1792] 11:18:14:899: [INFO ] CreatetCallClient: calling NewObject,
ptCallClient = [005568D4]
[1792] 11:18:14:899: [TRACE] CreatetCallClient: exit, new
ptCallClient=005568D4
[1792] 11:18:14:899: [INFO ] LineEventProc: i = [0] corresponding
ptCallClient [005568D4]
[1792] 11:18:14:899: [INFO ] LineEventProc:
ptCallClient->ptLineClient[00555E50]
[1792] 11:18:14:899: [INFO ] LineEventProc: ptLineClient->ptLineApp[00552CA0]
[1792] 11:18:14:899: [INFO ] LineEventProc: setting msg->InitContext to
ptLineApp[00552CA0]->InitContext of [800003FF]
[1792] 11:18:14:899: [INFO ] LineEventProc: setting msg->OpenContext to
[800003DD]
[1792] 11:18:14:899: [INFO ] FMsgDisbled: dwAPIVersion<= TAPI_VERSION3_0,
msg will be enabled
[1792] 11:18:14:899: [TRACE] FMsgDisabled return 0
[1792] 11:18:14:899: [INFO ] LineEventProc: sending LINE_APPNEWCALL,
ptClient[00552690]
[1792] 11:18:14:899: [TRACE] WriteEventBuffer - enter
[1792] 11:18:14:899: [TRACE] WriteEventBuffer: SetEvent 00000114 for local
client
[1792] 11:18:14:899: [INFO ] FMsgDisbled: dwAPIVersion<= TAPI_VERSION3_0,
msg will be enabled
[1792] 11:18:14:899: [TRACE] FMsgDisabled return 0
[1792] 11:18:14:899: [TRACE] WriteEventBuffer - enter
[1792] 11:18:14:899: [TRACE] WriteEventBuffer: SetEvent 00000114 for local
client
[2980] 11:18:14:899: [TRACE] GetAsyncEvents: enter (TID=2980)
[2980] 11:18:14:899: [INFO ] M ebfused:x60 pEvtBuf: 0x005527A0
pDataOut:0x005527A0 pDataIn:0x00552800
[2980] 11:18:14:899: [TRACE] GetAsyncEvents: return dwUsedBufferSize:x60
[4076] 11:18:14:899: [TRACE] LineProlog: -- enter
[4076] 11:18:14:899: [INFO ] LineProlog: dwArg 100be
[4076] 11:18:14:899: [INFO ] LineProlog: ANY_RT_HCALL
[4076] 11:18:14:899: [INFO ] LineProlog: ReferenceObject returned
ptCallClient 005568D4
[4076] 11:18:14:899: [TRACE] LienProlog: exit, result = x0
[4076] 11:18:14:899: [TRACE] LineEpilogSync: exit, result=x0
[2980] 11:18:14:899: [TRACE] LineProlog: -- enter
[2980] 11:18:14:899: [INFO ] LineProlog: dwArg 100be
[2980] 11:18:14:899: [INFO ] LineProlog: ANY_RT_HCALL
[2980] 11:18:14:899: [INFO ] LineProlog: ReferenceObject returned
ptCallClient 005568D4
[2980] 11:18:14:899: [INFO ] LineProlog: OpenContext 800003DD
[2980] 11:18:14:899: [TRACE] LienProlog: exit, result = x10163
[2980] 11:18:14:899: [TRACE] LineEpilogAsyc: exit, result=x10163
[452] 11:18:14:899: [TRACE] CompletionProcSP: enter, dwReqID=x10163,
lResult=x80000048
[1792] 11:18:14:899: [INFO ] Got an async completion event, requestID =
0x10163, htXxx = 0x102ee, lResult = 0x80000048
[1792] 11:18:14:899: [TRACE] CompletionProc: enter, dwReqID=x10163,
lResult=x80000048
[1792] 11:18:14:899: [TRACE] WriteEventBuffer - enter
[1792] 11:18:14:899: [TRACE] WriteEventBuffer: SetEvent 00000114 for local
client
[4076] 11:18:14:899: [TRACE] GetAsyncEvents: enter (TID=4076)
[4076] 11:18:14:899: [INFO ] M ebfused:x28 pEvtBuf: 0x005527A0
pDataOut:0x005527A0 pDataIn:0x005527C8
[4076] 11:18:14:899: [TRACE] GetAsyncEvents: return dwUsedBufferSize:x28
[3404] 11:18:14:899: [TRACE] LineProlog: -- enter
[3404] 11:18:14:899: [INFO ] LineProlog: dwArg 100be
[3404] 11:18:14:899: [INFO ] LineProlog: ANY_RT_HCALL
[3404] 11:18:14:899: [INFO ] LineProlog: ReferenceObject returned
ptCallClient 005568D4
[3404] 11:18:14:899: [INFO ] LineProlog: OpenContext 800003DD
[3404] 11:18:14:899: [TRACE] LienProlog: exit, result = x100d0
[3404] 11:18:14:899: [TRACE] LineEpilogAsyc: exit, result=x100d0
[452] 11:18:14:899: [TRACE] CompletionProcSP: enter, dwReqID=x100d0,
lResult=x0
[1792] 11:18:14:899: [INFO ] Got an async completion event, requestID =
0x100d0, htXxx = 0x102ee, lResult = 0x0
[1792] 11:18:14:899: [TRACE] CompletionProc: enter, dwReqID=x100d0, lResult=x0
[1792] 11:18:14:899: [TRACE] WriteEventBuffer - enter
[1792] 11:18:14:899: [TRACE] WriteEventBuffer: SetEvent 00000114 for local
client
[2980] 11:18:14:899: [TRACE] GetAsyncEvents: enter (TID=2980)
[2980] 11:18:14:899: [INFO ] M ebfused:x28 pEvtBuf: 0x005527A0
pDataOut:0x005527A0 pDataIn:0x005527C8
[2980] 11:18:14:899: [TRACE] GetAsyncEvents: return dwUsedBufferSize:x28
[452] 11:18:14:899: [INFO ] LineEventProcSP: HTapiLine=000102EE,
HTapiCall=000100EF, msg=2, P1=x100, P2=x0, P3=x100
[1792] 11:18:14:899: [INFO ] Got a line spevent, htLine = 0x102ee, htCall =
0x100ef, dwMsg = 0x2
[1792] 11:18:14:899: [TRACE] LineEventProc
[1792] 11:18:14:899: [EVENT] LineEventProc: LINE_CALLSTATE event x100
[1792] 11:18:14:899: [INFO ] LineEventProc: i = [0] corresponding
ptCallClient [005568D4]
[1792] 11:18:14:899: [INFO ] LineEventProc:
ptCallClient->ptLineClient[00555E50]
[1792] 11:18:14:899: [INFO ] LineEventProc: ptLineClient->ptLineApp[00552CA0]
[1792] 11:18:14:899: [INFO ] LineEventProc: setting msg->InitContext to
ptLineApp[00552CA0]->InitContext of [800003FF]
[1792] 11:18:14:899: [INFO ] LineEventProc: setting msg->OpenContext to
[800003DD]
[1792] 11:18:14:899: [INFO ] FMsgDisbled: dwAPIVersion<= TAPI_VERSION3_0,
msg will be enabled
[1792] 11:18:14:899: [TRACE] FMsgDisabled return 0
[1792] 11:18:14:899: [TRACE] WriteEventBuffer - enter
[1792] 11:18:14:899: [TRACE] WriteEventBuffer: SetEvent 00000114 for local
client
[4076] 11:18:14:899: [TRACE] GetAsyncEvents: enter (TID=4076)
[4076] 11:18:14:899: [INFO ] M ebfused:x2c pEvtBuf: 0x005527A0
pDataOut:0x005527A0 pDataIn:0x005527CC
[4076] 11:18:14:899: [TRACE] GetAsyncEvents: return dwUsedBufferSize:x2c
[3404] 11:18:14:899: [TRACE] LineProlog: -- enter
[3404] 11:18:14:899: [INFO ] LineProlog: dwArg 100be
[3404] 11:18:14:899: [INFO ] LineProlog: ANY_RT_HCALL
[3404] 11:18:14:899: [INFO ] LineProlog: ReferenceObject returned
ptCallClient 005568D4
[3404] 11:18:14:899: [TRACE] LienProlog: exit, result = x0
[3404] 11:18:14:899: [TRACE] LineEpilogSync: exit, result=x0
[4076] 11:18:14:899: [TRACE] LineProlog: -- enter
[4076] 11:18:14:899: [INFO ] LineProlog: dwArg 100be
[4076] 11:18:14:899: [INFO ] LineProlog: ANY_RT_HCALL
[4076] 11:18:14:899: [INFO ] LineProlog: ReferenceObject returned
ptCallClient 005568D4
[4076] 11:18:14:899: [TRACE] LienProlog: exit, result = x0
[4076] 11:18:14:899: [TRACE] LineEpilogSync: exit, result=x0
[2980] 11:18:14:899: [TRACE] LineProlog: -- enter
[2980] 11:18:14:899: [INFO ] LineProlog: dwArg 100be
[2980] 11:18:14:899: [INFO ] LineProlog: ANY_RT_HCALL
[2980] 11:18:14:899: [INFO ] LineProlog: ReferenceObject returned
ptCallClient 005568D4
[2980] 11:18:14:899: [TRACE] LienProlog: exit, result = x0
[2980] 11:18:14:899: [TRACE] LineEpilogSync: exit, result=x0
[452] 11:18:42:242: [INFO ] LineEventProcSP: HTapiLine=000102EE,
HTapiCall=000100EF, msg=2, P1=x4000, P2=x0, P3=x100
[1792] 11:18:42:242: [INFO ] Got a line spevent, htLine = 0x102ee, htCall =
0x100ef, dwMsg = 0x2
[1792] 11:18:42:242: [TRACE] LineEventProc
[1792] 11:18:42:242: [EVENT] LineEventProc: LINE_CALLSTATE event x4000
[1792] 11:18:42:242: [INFO ] LineEventProc: i = [0] corresponding
ptCallClient [005568D4]
[1792] 11:18:42:242: [INFO ] LineEventProc:
ptCallClient->ptLineClient[00555E50]
[1792] 11:18:42:242: [INFO ] LineEventProc: ptLineClient->ptLineApp[00552CA0]
[1792] 11:18:42:242: [INFO ] LineEventProc: setting msg->InitContext to
ptLineApp[00552CA0]->InitContext of [800003FF]
[1792] 11:18:42:242: [INFO ] LineEventProc: setting msg->OpenContext to
[800003DD]
[1792] 11:18:42:242: [INFO ] FMsgDisbled: dwAPIVersion<= TAPI_VERSION3_0,
msg will be enabled
[1792] 11:18:42:242: [TRACE] FMsgDisabled return 0
[1792] 11:18:42:242: [TRACE] WriteEventBuffer - enter
[1792] 11:18:42:242: [TRACE] WriteEventBuffer: SetEvent 00000114 for local
client
[4076] 11:18:42:242: [TRACE] GetAsyncEvents: enter (TID=4076)
[4076] 11:18:42:242: [INFO ] M ebfused:x2c pEvtBuf: 0x005527A0
pDataOut:0x005527A0 pDataIn:0x005527CC
[4076] 11:18:42:242: [TRACE] GetAsyncEvents: return dwUsedBufferSize:x2c
[3404] 11:18:42:242: [TRACE] LineProlog: -- enter
[3404] 11:18:42:242: [INFO ] LineProlog: dwArg 100be
[3404] 11:18:42:242: [INFO ] LineProlog: ANY_RT_HCALL
[3404] 11:18:42:242: [INFO ] LineProlog: ReferenceObject returned
ptCallClient 005568D4
[3404] 11:18:42:242: [TRACE] LienProlog: exit, result = x0
[452] 11:18:42:242: [INFO ] LineEventProcSP: HTapiLine=000102EE,
HTapiCall=000100EF, msg=2, P1=x1, P2=x0, P3=x100
[1792] 11:18:42:242: [INFO ] Got a line spevent, htLine = 0x102ee, htCall =
0x100ef, dwMsg = 0x2
[1792] 11:18:42:242: [TRACE] LineEventProc
[1792] 11:18:42:242: [EVENT] LineEventProc: LINE_CALLSTATE event x1
[1792] 11:18:42:242: [INFO ] LineEventProc: i = [0] corresponding
ptCallClient [005568D4]
[1792] 11:18:42:242: [INFO ] LineEventProc:
ptCallClient->ptLineClient[00555E50]
[1792] 11:18:42:242: [INFO ] LineEventProc: ptLineClient->ptLineApp[00552CA0]
[1792] 11:18:42:242: [INFO ] LineEventProc: setting msg->InitContext to
ptLineApp[00552CA0]->InitContext of [800003FF]
[1792] 11:18:42:242: [INFO ] LineEventProc: setting msg->OpenContext to
[800003DD]
[1792] 11:18:42:242: [INFO ] FMsgDisbled: dwAPIVersion<= TAPI_VERSION3_0,
msg will be enabled
[1792] 11:18:42:242: [TRACE] FMsgDisabled return 0
[1792] 11:18:42:242: [TRACE] WriteEventBuffer - enter
[1792] 11:18:42:242: [TRACE] WriteEventBuffer: SetEvent 00000114 for local
client
[3404] 11:18:42:242: [TRACE] LineEpilogSync: exit, result=x0
[2980] 11:18:42:242: [TRACE] GetAsyncEvents: enter (TID=2980)
[2980] 11:18:42:242: [INFO ] M ebfused:x2c pEvtBuf: 0x005527A0
pDataOut:0x005527A0 pDataIn:0x005527CC
[2980] 11:18:42:242: [TRACE] GetAsyncEvents: return dwUsedBufferSize:x2c
[4076] 11:18:42:242: [TRACE] LineProlog: -- enter
[4076] 11:18:42:242: [INFO ] LineProlog: dwArg 100be
[4076] 11:18:42:242: [INFO ] LineProlog: ANY_RT_HCALL
[4076] 11:18:42:242: [INFO ] LineProlog: ReferenceObject returned
ptCallClient 005568D4
[4076] 11:18:42:242: [INFO ] LineProlog: OpenContext 800003DD
[4076] 11:18:42:242: [TRACE] LienProlog: exit, result = x10356
[4076] 11:18:42:242: [TRACE] LineEpilogAsyc: exit, result=x10356
[452] 11:18:42:242: [TRACE] CompletionProcSP: enter, dwReqID=x10356,
lResult=x80000048
[1792] 11:18:42:242: [INFO ] Got an async completion event, requestID =
0x10356, htXxx = 0x102ee, lResult = 0x80000048
[1792] 11:18:42:242: [TRACE] CompletionProc: enter, dwReqID=x10356,
lResult=x80000048
[1792] 11:18:42:242: [TRACE] WriteEventBuffer - enter
[1792] 11:18:42:242: [TRACE] WriteEventBuffer: SetEvent 00000114 for local
client
[3404] 11:18:42:242: [TRACE] GetAsyncEvents: enter (TID=3404)
[3404] 11:18:42:242: [INFO ] M ebfused:x28 pEvtBuf: 0x005527A0
pDataOut:0x005527A0 pDataIn:0x005527C8
[3404] 11:18:42:242: [TRACE] GetAsyncEvents: return dwUsedBufferSize:x28
[2980] 11:18:42:242: [TRACE] LineProlog: -- enter
[2980] 11:18:42:242: [INFO ] LineProlog: dwArg 100be
[2980] 11:18:42:242: [INFO ] LineProlog: ANY_RT_HCALL
[2980] 11:18:42:242: [INFO ] LineProlog: ReferenceObject returned
ptCallClient 005568D4
[2980] 11:18:42:242: [TRACE] LienProlog: exit, result = x0
[2980] 11:18:42:242: [TRACE] DestroytCallClient: enter, ptCallCli=x005568D4
[2980] 11:18:42:242: [TRACE] DestroytCall: enter, ptCall=x00556858
[2980] 11:18:42:242: [TRACE] LineEpilogSync: exit, result=x0
[480] 11:18:14:899: [INFO ] AsyncEventsThread: msg=23, hDev=x102ff, p1=x0,
p2=x100be, p3=x4
[480] 11:18:14:899: [INFO ] AsyncEventsThread: posting msg, hwnd=x10032
[1896] 11:18:14:899: [TRACE] TAPIWndProc: received WM_ASYNCEVENT,
hwnd=x00010032
[1896] 11:18:14:899: [INFO ] Calling app's callback, hDev=x102ff, Msg=23,
dwInst=x10c368 P1=x0, P2=x100be P3=x4
[1896] 11:18:14:899: [TRACE] No entries - spurious entry.
[480] 11:18:14:899: [INFO ] AsyncEventsThread: msg=2, hDev=x100be, p1=x2,
p2=x0, p3=x0
[480] 11:18:14:899: [INFO ] AsyncEventsThread: posting msg, hwnd=x10032
[1896] 11:18:14:899: [TRACE] TAPIWndProc: received WM_ASYNCEVENT,
hwnd=x00010032
[1896] 11:18:14:899: [INFO ] Calling app's callback, hDev=x100be, Msg=2,
dwInst=x10c368 P1=x2, P2=x0 P3=x0
[1896] 11:18:14:899: [TRACE] DoFunc -- enter
[1896] 11:18:14:899: [TRACE] AllocClientResources: enter
[1896] 11:18:14:899: [TRACE] AllocClientResources: exit, returning x0
[1896] 11:18:14:899: [TRACE] DoFunc: back from srv- return code=0x00000000
[1896] 11:18:14:899: [TRACE] DoFunc: result = x0
[1836] 11:18:14:899: [TRACE] DoFunc -- enter
[1836] 11:18:14:899: [TRACE] AllocClientResources: enter
[1836] 11:18:14:899: [TRACE] AllocClientResources: exit, returning x0
[1896] 11:18:14:899: [TRACE] No entries - spurious entry.
[1836] 11:18:14:899: [TRACE] DoFunc: back from srv- return code=0x00010163
[1836] 11:18:14:899: [TRACE] DoFunc: result = x10163
[480] 11:18:14:899: [INFO ] AsyncEventsThread: msg=12, hDev=x0, p1=x10163,
p2=x80000048, p3=x0
[480] 11:18:14:899: [INFO ] AsyncEventsThread: posting msg, hwnd=x10032
[1896] 11:18:14:899: [TRACE] TAPIWndProc: received WM_ASYNCEVENT,
hwnd=x00010032
[1896] 11:18:14:899: [INFO ] Calling app's callback, hDev=x0, Msg=12,
dwInst=x10c368 P1=x10163, P2=x80000048 P3=x0
[1836] 11:18:14:899: [TRACE] DoFunc -- enter
[1836] 11:18:14:899: [TRACE] AllocClientResources: enter
[1836] 11:18:14:899: [TRACE] AllocClientResources: exit, returning x0
[1896] 11:18:14:899: [TRACE] No entries - spurious entry.
[1836] 11:18:14:899: [TRACE] DoFunc: back from srv- return code=0x000100d0
[1836] 11:18:14:899: [TRACE] DoFunc: result = x100d0
[480] 11:18:14:899: [INFO ] AsyncEventsThread: msg=12, hDev=x0, p1=x100d0,
p2=x0, p3=x0
[480] 11:18:14:899: [INFO ] AsyncEventsThread: posting msg, hwnd=x10032
[1896] 11:18:14:899: [TRACE] TAPIWndProc: received WM_ASYNCEVENT,
hwnd=x00010032
[1896] 11:18:14:899: [INFO ] Calling app's callback, hDev=x0, Msg=12,
dwInst=x10c368 P1=x100d0, P2=x0 P3=x0
[1896] 11:18:14:899: [TRACE] No entries - spurious entry.
[480] 11:18:14:899: [INFO ] AsyncEventsThread: msg=2, hDev=x100be, p1=x100,
p2=x0, p3=x0
[480] 11:18:14:899: [INFO ] AsyncEventsThread: posting msg, hwnd=x10032
[1896] 11:18:14:899: [TRACE] TAPIWndProc: received WM_ASYNCEVENT,
hwnd=x00010032
[1896] 11:18:14:899: [INFO ] Calling app's callback, hDev=x100be, Msg=2,
dwInst=x10c368 P1=x100, P2=x0 P3=x0
[1896] 11:18:14:899: [TRACE] DoFunc -- enter
[1896] 11:18:14:899: [TRACE] AllocClientResources: enter
[1896] 11:18:14:899: [TRACE] AllocClientResources: exit, returning x0
[1896] 11:18:14:899: [TRACE] DoFunc: back from srv- return code=0x00000000
[1896] 11:18:14:899: [TRACE] DoFunc: result = x0
[1896] 11:18:14:899: [TRACE] No entries - spurious entry.
[2512] 11:18:14:899: [TRACE] DoFunc -- enter
[2512] 11:18:14:899: [TRACE] AllocClientResources: enter
[2512] 11:18:14:899: [TRACE] AllocClientResources: exit, returning x0
[2512] 11:18:14:899: [TRACE] DoFunc: back from srv- return code=0x00000000
[2512] 11:18:14:899: [TRACE] DoFunc: result = x0
[2512] 11:18:14:899: [TRACE] DoFunc -- enter
[2512] 11:18:14:899: [TRACE] AllocClientResources: enter
[2512] 11:18:14:899: [TRACE] AllocClientResources: exit, returning x0
[2512] 11:18:14:899: [TRACE] DoFunc: back from srv- return code=0x00000000
[2512] 11:18:14:899: [TRACE] DoFunc: result = x0
[480] 11:18:42:242: [INFO ] AsyncEventsThread: msg=2, hDev=x100be, p1=x4000,
p2=x0, p3=x0
[480] 11:18:42:242: [INFO ] AsyncEventsThread: posting msg, hwnd=x10032
[1896] 11:18:42:242: [TRACE] TAPIWndProc: received WM_ASYNCEVENT,
hwnd=x00010032
[1896] 11:18:42:242: [INFO ] Calling app's callback, hDev=x100be, Msg=2,
dwInst=x10c368 P1=x4000, P2=x0 P3=x0
[1896] 11:18:42:242: [TRACE] DoFunc -- enter
[1896] 11:18:42:242: [TRACE] AllocClientResources: enter
[1896] 11:18:42:242: [TRACE] AllocClientResources: exit, returning x0
[1896] 11:18:42:242: [TRACE] DoFunc: back from srv- return code=0x00000000
[1896] 11:18:42:242: [TRACE] DoFunc: result = x0
[1896] 11:18:42:242: [TRACE] DoFunc -- enter
[1896] 11:18:42:242: [TRACE] AllocClientResources: enter
[1896] 11:18:42:242: [TRACE] AllocClientResources: exit, returning x0
[480] 11:18:42:242: [INFO ] AsyncEventsThread: msg=2, hDev=x100be, p1=x1,
p2=x0, p3=x0
[480] 11:18:42:242: [INFO ] AsyncEventsThread: posting msg, hwnd=x10032
[1896] 11:18:42:242: [TRACE] DoFunc: back from srv- return code=0x00010356
[1896] 11:18:42:242: [TRACE] DoFunc: result = x10356
[1896] 11:18:42:242: [INFO ] Calling app's callback, hDev=x100be, Msg=2,
dwInst=x10c368 P1=x1, P2=x0 P3=x0
[1896] 11:18:42:242: [TRACE] No entries - spurious entry.
[1896] 11:18:42:242: [TRACE] TAPIWndProc: received WM_ASYNCEVENT,
hwnd=x00010032
[1896] 11:18:42:242: [TRACE] No entries - spurious entry.
[480] 11:18:42:242: [INFO ] AsyncEventsThread: msg=12, hDev=x0, p1=x10356,
p2=x80000048, p3=x0
[480] 11:18:42:242: [INFO ] AsyncEventsThread: posting msg, hwnd=x10032
[1896] 11:18:42:242: [TRACE] TAPIWndProc: received WM_ASYNCEVENT,
hwnd=x00010032
[1896] 11:18:42:242: [INFO ] Calling app's callback, hDev=x0, Msg=12,
dwInst=x10c368 P1=x10356, P2=x80000048 P3=x0
[1896] 11:18:42:242: [TRACE] lineDeallocateCall: enter on thread: 0x00000768
[1896] 11:18:42:242: [INFO ] hCall = 0x000100be
[1896] 11:18:42:242: [TRACE] DoFunc -- enter
[1896] 11:18:42:242: [TRACE] AllocClientResources: enter
[1896] 11:18:42:242: [TRACE] AllocClientResources: exit, returning x0
[1896] 11:18:42:242: [TRACE] DoFunc: back from srv- return code=0x00000000
[1896] 11:18:42:242: [TRACE] DoFunc: result = x0
[1896] 11:18:42:242: [TRACE] No entries - spurious entry.
[1896] 11-17 11:18:14:899: RasTapicallback: msg=23 , param1=0l , param2=65726l
[1896] 11-17 11:18:14:899: RasTapicallback: msg=2 , param1=2l , param2=0l
[1896] 11-17 11:18:14:899: RasTapicallback: linecallstate=0x2
[1896] 11-17 11:18:14:899: DwProcessOfferEvent: hcall=0x100be
[1896] 11-17 11:18:14:899: DwProcessOfferEvent: Accepting call on VPN4-26
hcall = 0x100be
[1896] 11-17 11:18:14:899: WAN Miniport (PPTP) InClients=4,
TotalDialInClients=4
[1896] 11-17 11:18:14:899: DwProcessOfferEvent 0x0
[1836] 11-17 11:18:14:899: DeviceWork: VPN4-26. State = 2
[1836] 11-17 11:18:14:899: DeviceWork: VPN4-26. lineAccept returned 0x10163
[1896] 11-17 11:18:14:899: RasTapicallback: msg=12 , param1=65891l ,
param2=2147483720l
[1896] 11-17 11:18:14:899: LINE_REPLY. param1=0x10163
[1896] 11-17 11:18:14:899: RasTapiCallback: Changing Listen State for
VPN4-26 from 2 -> 3
[1836] 11-17 11:18:14:899: DeviceWork: VPN4-26. State = 2
[1836] 11-17 11:18:14:899: DeviceWork: VPN4-26. lineAnswer returned 0x100d0
[1896] 11-17 11:18:14:899: RasTapicallback: msg=12 , param1=65744l , param2=0l
[1896] 11-17 11:18:14:899: LINE_REPLY. param1=0x100d0
[1896] 11-17 11:18:14:899: RasTapiCallback: LINE_REPLY. Changing Listen
state for VPN4-26 from 3 -> 4
[1896] 11-17 11:18:14:899: **** Not posting completion for lineAnswer ***
[1896] 11-17 11:18:14:899: RasTapicallback: msg=2 , param1=256l , param2=0l
[1896] 11-17 11:18:14:899: RasTapicallback: linecallstate=0x100
[1896] 11-17 11:18:14:899: DwGetConnectInfo
[1896] 11-17 11:18:14:899: DwGetIDInformation
[1896] 11-17 11:18:14:899: DwGetIDInformation. 0
[1896] 11-17 11:18:14:899: SizeRequired for CallID=16
[1896] 11-17 11:18:14:899: DwGetIDInformation
[1896] 11-17 11:18:14:899: GetIDInformation: CallerID=65.126.159.238
[1896] 11-17 11:18:14:899: RasTapiCallback: called id info. not avail
[1896] 11-17 11:18:14:899: DwGetIDInformation. 0
[1896] 11-17 11:18:14:899: DwGetConnectInfo. 0x0
[1896] 11-17 11:18:14:899: RasTapiCallback: DwGetConnectInforeturned 0x0
[1896] 11-17 11:18:14:899: RasTapiCallback: Connected on VPN4-26
[1896] 11-17 11:18:14:899: RasTapiCallback: Incoming Call
[1836] 11-17 11:18:14:899: DeviceWork: VPN4-26. State = 2
[1836] 11-17 11:18:14:899: DeviceWork: Changing State for VPN4-26 from 2 -> 3
[2512] 11-17 11:18:14:899: PortConnect: VPN4-26
[2512] 11-17 11:18:14:899:
[1896] 11-17 11:18:42:242: RasTapicallback: msg=2 , param1=16384l , param2=0l
[1896] 11-17 11:18:42:242: RasTapicallback: linecallstate=0x4000
[1896] 11-17 11:18:42:242: RasTapiCallback: lineGetCallStatus for VPN4-26
returned 0x4000
[1896] 11-17 11:18:42:242: RasTapiCallback: DisconnectReason mapped to 2
[1896] 11-17 11:18:42:242: RasTapiCallback: LINECALLSTATE - initiating Port
Disconnect
[1896] 11-17 11:18:42:242: InitiatePortDisconnection: VPN4-26
[1896] 11-17 11:18:42:242: WAN Miniport (PPTP) InClients=3,
TotalDialInClients=3
[1896] 11-17 11:18:42:242: InitiatePortDisconnection: Changing state for
VPN4-26 from 3 -> 5, id=0x10356
[1896] 11-17 11:18:42:242:
[1896] 11-17 11:18:42:242: RasTapicallback: msg=2 , param1=1l , param2=0l
[1896] 11-17 11:18:42:242: RasTapicallback: linecallstate=0x1
[1896] 11-17 11:18:42:242: RasTapicallback: msg=12 , param1=66390l ,
param2=2147483720l
[1896] 11-17 11:18:42:242: LINE_REPLY. param1=0x10356
[1896] 11-17 11:18:42:242: RasTapiCallback: lineDropped. port VPN4-26,
id=0xffffffff
[1896] 11-17 11:18:42:242: RasTapiCallback: Idle Received for port VPN4-26
[1896] 11-17 11:18:42:242: RasTapiCallback: changing state of VPN4-26. 5 -> 1
[1896] 11-17 11:18:42:242: RasTapiCallback: lineDeallocateCall for
VPN4-26,hcall = 0x100be
[1836] 11-17 11:18:42:242: PortTestSignalState: DisconnectReason = 2
[1836] 11-17 11:18:42:242: PortDisconnect: VPN4-26
[1836] 11-17 11:18:42:242:
[2512] 11-17 11:18:42:242: DeviceListen: Changing State for VPN4-26 from 1
-> 2
[2512] 11-17 11:18:42:242: DeviceListen: Changing Listen State for VPN4-26
from 4 -> 2
[2512] 11-17 11:18:42:242:
A network Monitor Trace of this event shows the conenction start and end,
however I could not find anything in there that led me to an answer (I have
the trace results if needed).
While this connection was attempted there was another client VPN connection
active from the same location, in addition there were four or five Site-to
Site VPN connections active.
freqently I have users report that they cannot connect to the server. At
other times there is no problem. When users cannot connect they report that
their VPN client "hangs" on "Verifying Username and Password".
There is no entry in the Enent Viewer corresponding to the connection
attempt (logging is set to Maximum)
The following is what is recorded in the various trace logs (all other logs
have no information corresponding to this connection attempt). In these logs
the call attempt started on 11/17/2005 at 11:18:14.
[2512] 11-17 11:18:14:899: Rasman state change received from port 41, 1->5
[2512] 11-17 11:18:14:899: Rasman state change received from port 41, 5->2
[2512] 11-17 11:18:14:899: SvDevConnected: Entered, hPort=41
[2512] 11-17 11:18:14:899: TimerQRemove called
[2512] 11-17 11:18:42:242: Rasman state change received from port 41, 2->4
[2512] 11-17 11:18:42:242: SvDevDisconnected:Entered, hPort=41
[2512] 11-17 11:18:42:242: DevStartClosing: Entered, hPort=41
[2512] 11-17 11:18:42:242: TimerQRemove called
[2512] 11-17 11:18:42:242: TimerQRemove called
[2512] 11-17 11:18:42:242: TimerQRemove called
[2512] 11-17 11:18:42:242: DevCloseComplete:hPort=41,Auth=0,Rcv=0,Conn=1
0,Sec=4 2,Ppp=0
[2512] 11-17 11:18:42:242: RmListen: Listen posted on port 41
[2512] 11-17 11:18:42:242: RasPortListen dwRetCode=600
[1836] 11-17 11:18:14:899: WorkerThread: Async work event signaled on port:
VPN4-26
[1836] 11-17 11:18:14:899: OVEVT_DEV_ASYNCOP. pOverlapped = 0x10f3b0
[1836] 11-17 11:18:14:899: ServiceWorkRequest: Async op event 27 for port
VPN4-26 returned 600
[1836] 11-17 11:18:14:899: WorkerThread: Async work event signaled on port:
VPN4-26
[1836] 11-17 11:18:14:899: OVEVT_DEV_ASYNCOP. pOverlapped = 0x10f3b0
[1836] 11-17 11:18:14:899: ServiceWorkRequest: Async op event 27 for port
VPN4-26 returned 600
[1836] 11-17 11:18:14:899: WorkerThread: Async work event signaled on port:
VPN4-26
[1836] 11-17 11:18:14:899: OVEVT_DEV_ASYNCOP. pOverlapped = 0x10f3b0
[1836] 11-17 11:18:14:899: d:\srv03rtm\net\rras\ras\rasman\rasman\request.c:
7507: port 41 state chg: prev=1, new=5
[1836] 11-17 11:18:14:899: RasmanReceiveFlags = 0x0
[1836] 11-17 11:18:14:899: d:\srv03rtm\net\rras\ras\rasman\rasman\worker.c:
2269: port 41 async reqtype chg: prev=27, new=0
[1836] 11-17 11:18:14:899: ServiceWorkRequest: Async op event 27 for port
VPN4-26 returned 0
[2512] 11-17 11:18:14:899: ConnectCompleteRequest: entered for port 41
[2512] 11-17 11:18:14:899: d:\srv03rtm\net\rras\ras\rasman\rasman\request.c:
7401: port 41 state chg: prev=5, new=2
[2512] 11-17 11:18:14:899: AllocBundle: pBundle=0x9544108
[2512] 11-17 11:18:14:899: d:\srv03rtm\net\rras\ras\rasman\rasman\request.c
8901: Mapping Cookie to handle. port = VPN4-26(0x12f6e0), Bundlehandle =
0xe6,
linkhandle = 0xe6
[2512] 11-17 11:18:14:899: Connection Completed on port: VPN4-26, error
code: 0
[2512] 11-17 11:18:14:899: d:\srv03rtm\net\rras\ras\rasman\rasman\request.c:
6654: port 41 async reqtype chg: prev=0, new=26
[1836] 11-17 11:18:42:242: WorkerThread: Disconnect event signaled on port:
VPN4-26
[1836] 11-17 11:18:42:242: OVEVT_DEV_STATECHANGE. pOverlapped = 0x10f3f0
[1836] 11-17 11:18:42:242: d:\srv03rtm\net\rras\ras\rasman\rasman\worker.c,
1908: Disconnecting port 41, connection 0x0, reason 1
[1836] 11-17 11:18:42:242: Disconnecting Port 0xVPN4-26, reason 1
[1836] 11-17 11:18:42:242: DisconnectPort: Saving Bundle stats for port
VPN4-26
[1836] 11-17 11:18:42:242: 10. Throwing away handle 0x18d0!
[1836] 11-17 11:18:42:242: d:\srv03rtm\net\rras\ras\rasman\rasman\util.c
1992: Disconnected Port 41, reason 1. rc=0x0
[1836] 11-17 11:18:42:242: FreeBundle: freeing pBundle=0x9544108
[1836] 11-17 11:18:42:242: d:\srv03rtm\net\rras\ras\rasman\rasman\util.c:
2213: port 41 state chg: prev=2, new=3
[1836] 11-17 11:18:42:242: d:\srv03rtm\net\rras\ras\rasman\rasman\util.c:
2229: port 41 state chg: prev=3, new=4
[1836] 11-17 11:18:42:242: 5. Notifying of disconnect on port 41
[1836] 11-17 11:18:42:242: d:\srv03rtm\net\rras\ras\rasman\rasman\util.c:
2340: port 41 async reqtype chg: prev=26, new=0
[1836] 11-17 11:18:42:242: *****
DisconnectReason=1,pConn=0x0,cbports=0,signaled=0,hEvent=0xffffffff,fRedial=0
[1836] 11-17 11:18:42:242: DisconnectPort Complete
[1836] 11-17 11:18:42:242: d:\srv03rtm\net\rras\ras\rasman\rasman\worker.c:
1946: port 41 state chg: prev=4, new=4
[1836] 11-17 11:18:42:242: d:\srv03rtm\net\rras\ras\rasman\rasman\worker.c:
1950: port 41 async reqtype chg: prev=0, new=0
[2512] 11-17 11:18:42:242: DeviceListenRequest: Clearing Autoclose flag on
port VPN4-26
[2512] 11-17 11:18:42:242: d:\srv03rtm\net\rras\ras\rasman\rasman\util.c:
2547: port 41 state chg: prev=4, new=1
[2512] 11-17 11:18:42:242: d:\srv03rtm\net\rras\ras\rasman\rasman\util.c:
2578: port 41 async reqtype chg: prev=0, new=27
[2512] 11-17 11:18:42:242: Listen posted on port: VPN4-26, error code 600
[452] 11:18:14:899: [INFO ] LineEventProcSP: HTapiLine=000102EE,
HTapiCall=00000000, msg=1f4, P1=x6040012, P2=xa5910, P3=x0
[452] 11:18:14:899: [TRACE] LineEventProc
[452] 11:18:14:899: [TRACE] CreatetCall: enter, ptLine=00555F38
[452] 11:18:14:899: [INFO ] CreatetCall: calling NewObject ptCall 00556858
[452] 11:18:14:899: [TRACE] CreatetCall: NewObject returned 0x100ef
[452] 11:18:14:899: [TRACE] CreatetCall: exit, new ptCall=00556858
[452] 11:18:14:899: [INFO ] LineEventProcSP: HTapiLine=000102EE,
HTapiCall=000100EF, msg=2, P1=x2, P2=x0, P3=x100
[1792] 11:18:14:899: [INFO ] Got a line spevent, htLine = 0x102ee, htCall =
0x100ef, dwMsg = 0x2
[1792] 11:18:14:899: [TRACE] LineEventProc
[1792] 11:18:14:899: [EVENT] LineEventProc: LINE_CALLSTATE event x2
[1792] 11:18:14:899: [TRACE] CreatetCallClient: enter, ptCall=00556858,
[1792] 11:18:14:899: [INFO ] CreatetCallClient: calling NewObject,
ptCallClient = [005568D4]
[1792] 11:18:14:899: [TRACE] CreatetCallClient: exit, new
ptCallClient=005568D4
[1792] 11:18:14:899: [INFO ] LineEventProc: i = [0] corresponding
ptCallClient [005568D4]
[1792] 11:18:14:899: [INFO ] LineEventProc:
ptCallClient->ptLineClient[00555E50]
[1792] 11:18:14:899: [INFO ] LineEventProc: ptLineClient->ptLineApp[00552CA0]
[1792] 11:18:14:899: [INFO ] LineEventProc: setting msg->InitContext to
ptLineApp[00552CA0]->InitContext of [800003FF]
[1792] 11:18:14:899: [INFO ] LineEventProc: setting msg->OpenContext to
[800003DD]
[1792] 11:18:14:899: [INFO ] FMsgDisbled: dwAPIVersion<= TAPI_VERSION3_0,
msg will be enabled
[1792] 11:18:14:899: [TRACE] FMsgDisabled return 0
[1792] 11:18:14:899: [INFO ] LineEventProc: sending LINE_APPNEWCALL,
ptClient[00552690]
[1792] 11:18:14:899: [TRACE] WriteEventBuffer - enter
[1792] 11:18:14:899: [TRACE] WriteEventBuffer: SetEvent 00000114 for local
client
[1792] 11:18:14:899: [INFO ] FMsgDisbled: dwAPIVersion<= TAPI_VERSION3_0,
msg will be enabled
[1792] 11:18:14:899: [TRACE] FMsgDisabled return 0
[1792] 11:18:14:899: [TRACE] WriteEventBuffer - enter
[1792] 11:18:14:899: [TRACE] WriteEventBuffer: SetEvent 00000114 for local
client
[2980] 11:18:14:899: [TRACE] GetAsyncEvents: enter (TID=2980)
[2980] 11:18:14:899: [INFO ] M ebfused:x60 pEvtBuf: 0x005527A0
pDataOut:0x005527A0 pDataIn:0x00552800
[2980] 11:18:14:899: [TRACE] GetAsyncEvents: return dwUsedBufferSize:x60
[4076] 11:18:14:899: [TRACE] LineProlog: -- enter
[4076] 11:18:14:899: [INFO ] LineProlog: dwArg 100be
[4076] 11:18:14:899: [INFO ] LineProlog: ANY_RT_HCALL
[4076] 11:18:14:899: [INFO ] LineProlog: ReferenceObject returned
ptCallClient 005568D4
[4076] 11:18:14:899: [TRACE] LienProlog: exit, result = x0
[4076] 11:18:14:899: [TRACE] LineEpilogSync: exit, result=x0
[2980] 11:18:14:899: [TRACE] LineProlog: -- enter
[2980] 11:18:14:899: [INFO ] LineProlog: dwArg 100be
[2980] 11:18:14:899: [INFO ] LineProlog: ANY_RT_HCALL
[2980] 11:18:14:899: [INFO ] LineProlog: ReferenceObject returned
ptCallClient 005568D4
[2980] 11:18:14:899: [INFO ] LineProlog: OpenContext 800003DD
[2980] 11:18:14:899: [TRACE] LienProlog: exit, result = x10163
[2980] 11:18:14:899: [TRACE] LineEpilogAsyc: exit, result=x10163
[452] 11:18:14:899: [TRACE] CompletionProcSP: enter, dwReqID=x10163,
lResult=x80000048
[1792] 11:18:14:899: [INFO ] Got an async completion event, requestID =
0x10163, htXxx = 0x102ee, lResult = 0x80000048
[1792] 11:18:14:899: [TRACE] CompletionProc: enter, dwReqID=x10163,
lResult=x80000048
[1792] 11:18:14:899: [TRACE] WriteEventBuffer - enter
[1792] 11:18:14:899: [TRACE] WriteEventBuffer: SetEvent 00000114 for local
client
[4076] 11:18:14:899: [TRACE] GetAsyncEvents: enter (TID=4076)
[4076] 11:18:14:899: [INFO ] M ebfused:x28 pEvtBuf: 0x005527A0
pDataOut:0x005527A0 pDataIn:0x005527C8
[4076] 11:18:14:899: [TRACE] GetAsyncEvents: return dwUsedBufferSize:x28
[3404] 11:18:14:899: [TRACE] LineProlog: -- enter
[3404] 11:18:14:899: [INFO ] LineProlog: dwArg 100be
[3404] 11:18:14:899: [INFO ] LineProlog: ANY_RT_HCALL
[3404] 11:18:14:899: [INFO ] LineProlog: ReferenceObject returned
ptCallClient 005568D4
[3404] 11:18:14:899: [INFO ] LineProlog: OpenContext 800003DD
[3404] 11:18:14:899: [TRACE] LienProlog: exit, result = x100d0
[3404] 11:18:14:899: [TRACE] LineEpilogAsyc: exit, result=x100d0
[452] 11:18:14:899: [TRACE] CompletionProcSP: enter, dwReqID=x100d0,
lResult=x0
[1792] 11:18:14:899: [INFO ] Got an async completion event, requestID =
0x100d0, htXxx = 0x102ee, lResult = 0x0
[1792] 11:18:14:899: [TRACE] CompletionProc: enter, dwReqID=x100d0, lResult=x0
[1792] 11:18:14:899: [TRACE] WriteEventBuffer - enter
[1792] 11:18:14:899: [TRACE] WriteEventBuffer: SetEvent 00000114 for local
client
[2980] 11:18:14:899: [TRACE] GetAsyncEvents: enter (TID=2980)
[2980] 11:18:14:899: [INFO ] M ebfused:x28 pEvtBuf: 0x005527A0
pDataOut:0x005527A0 pDataIn:0x005527C8
[2980] 11:18:14:899: [TRACE] GetAsyncEvents: return dwUsedBufferSize:x28
[452] 11:18:14:899: [INFO ] LineEventProcSP: HTapiLine=000102EE,
HTapiCall=000100EF, msg=2, P1=x100, P2=x0, P3=x100
[1792] 11:18:14:899: [INFO ] Got a line spevent, htLine = 0x102ee, htCall =
0x100ef, dwMsg = 0x2
[1792] 11:18:14:899: [TRACE] LineEventProc
[1792] 11:18:14:899: [EVENT] LineEventProc: LINE_CALLSTATE event x100
[1792] 11:18:14:899: [INFO ] LineEventProc: i = [0] corresponding
ptCallClient [005568D4]
[1792] 11:18:14:899: [INFO ] LineEventProc:
ptCallClient->ptLineClient[00555E50]
[1792] 11:18:14:899: [INFO ] LineEventProc: ptLineClient->ptLineApp[00552CA0]
[1792] 11:18:14:899: [INFO ] LineEventProc: setting msg->InitContext to
ptLineApp[00552CA0]->InitContext of [800003FF]
[1792] 11:18:14:899: [INFO ] LineEventProc: setting msg->OpenContext to
[800003DD]
[1792] 11:18:14:899: [INFO ] FMsgDisbled: dwAPIVersion<= TAPI_VERSION3_0,
msg will be enabled
[1792] 11:18:14:899: [TRACE] FMsgDisabled return 0
[1792] 11:18:14:899: [TRACE] WriteEventBuffer - enter
[1792] 11:18:14:899: [TRACE] WriteEventBuffer: SetEvent 00000114 for local
client
[4076] 11:18:14:899: [TRACE] GetAsyncEvents: enter (TID=4076)
[4076] 11:18:14:899: [INFO ] M ebfused:x2c pEvtBuf: 0x005527A0
pDataOut:0x005527A0 pDataIn:0x005527CC
[4076] 11:18:14:899: [TRACE] GetAsyncEvents: return dwUsedBufferSize:x2c
[3404] 11:18:14:899: [TRACE] LineProlog: -- enter
[3404] 11:18:14:899: [INFO ] LineProlog: dwArg 100be
[3404] 11:18:14:899: [INFO ] LineProlog: ANY_RT_HCALL
[3404] 11:18:14:899: [INFO ] LineProlog: ReferenceObject returned
ptCallClient 005568D4
[3404] 11:18:14:899: [TRACE] LienProlog: exit, result = x0
[3404] 11:18:14:899: [TRACE] LineEpilogSync: exit, result=x0
[4076] 11:18:14:899: [TRACE] LineProlog: -- enter
[4076] 11:18:14:899: [INFO ] LineProlog: dwArg 100be
[4076] 11:18:14:899: [INFO ] LineProlog: ANY_RT_HCALL
[4076] 11:18:14:899: [INFO ] LineProlog: ReferenceObject returned
ptCallClient 005568D4
[4076] 11:18:14:899: [TRACE] LienProlog: exit, result = x0
[4076] 11:18:14:899: [TRACE] LineEpilogSync: exit, result=x0
[2980] 11:18:14:899: [TRACE] LineProlog: -- enter
[2980] 11:18:14:899: [INFO ] LineProlog: dwArg 100be
[2980] 11:18:14:899: [INFO ] LineProlog: ANY_RT_HCALL
[2980] 11:18:14:899: [INFO ] LineProlog: ReferenceObject returned
ptCallClient 005568D4
[2980] 11:18:14:899: [TRACE] LienProlog: exit, result = x0
[2980] 11:18:14:899: [TRACE] LineEpilogSync: exit, result=x0
[452] 11:18:42:242: [INFO ] LineEventProcSP: HTapiLine=000102EE,
HTapiCall=000100EF, msg=2, P1=x4000, P2=x0, P3=x100
[1792] 11:18:42:242: [INFO ] Got a line spevent, htLine = 0x102ee, htCall =
0x100ef, dwMsg = 0x2
[1792] 11:18:42:242: [TRACE] LineEventProc
[1792] 11:18:42:242: [EVENT] LineEventProc: LINE_CALLSTATE event x4000
[1792] 11:18:42:242: [INFO ] LineEventProc: i = [0] corresponding
ptCallClient [005568D4]
[1792] 11:18:42:242: [INFO ] LineEventProc:
ptCallClient->ptLineClient[00555E50]
[1792] 11:18:42:242: [INFO ] LineEventProc: ptLineClient->ptLineApp[00552CA0]
[1792] 11:18:42:242: [INFO ] LineEventProc: setting msg->InitContext to
ptLineApp[00552CA0]->InitContext of [800003FF]
[1792] 11:18:42:242: [INFO ] LineEventProc: setting msg->OpenContext to
[800003DD]
[1792] 11:18:42:242: [INFO ] FMsgDisbled: dwAPIVersion<= TAPI_VERSION3_0,
msg will be enabled
[1792] 11:18:42:242: [TRACE] FMsgDisabled return 0
[1792] 11:18:42:242: [TRACE] WriteEventBuffer - enter
[1792] 11:18:42:242: [TRACE] WriteEventBuffer: SetEvent 00000114 for local
client
[4076] 11:18:42:242: [TRACE] GetAsyncEvents: enter (TID=4076)
[4076] 11:18:42:242: [INFO ] M ebfused:x2c pEvtBuf: 0x005527A0
pDataOut:0x005527A0 pDataIn:0x005527CC
[4076] 11:18:42:242: [TRACE] GetAsyncEvents: return dwUsedBufferSize:x2c
[3404] 11:18:42:242: [TRACE] LineProlog: -- enter
[3404] 11:18:42:242: [INFO ] LineProlog: dwArg 100be
[3404] 11:18:42:242: [INFO ] LineProlog: ANY_RT_HCALL
[3404] 11:18:42:242: [INFO ] LineProlog: ReferenceObject returned
ptCallClient 005568D4
[3404] 11:18:42:242: [TRACE] LienProlog: exit, result = x0
[452] 11:18:42:242: [INFO ] LineEventProcSP: HTapiLine=000102EE,
HTapiCall=000100EF, msg=2, P1=x1, P2=x0, P3=x100
[1792] 11:18:42:242: [INFO ] Got a line spevent, htLine = 0x102ee, htCall =
0x100ef, dwMsg = 0x2
[1792] 11:18:42:242: [TRACE] LineEventProc
[1792] 11:18:42:242: [EVENT] LineEventProc: LINE_CALLSTATE event x1
[1792] 11:18:42:242: [INFO ] LineEventProc: i = [0] corresponding
ptCallClient [005568D4]
[1792] 11:18:42:242: [INFO ] LineEventProc:
ptCallClient->ptLineClient[00555E50]
[1792] 11:18:42:242: [INFO ] LineEventProc: ptLineClient->ptLineApp[00552CA0]
[1792] 11:18:42:242: [INFO ] LineEventProc: setting msg->InitContext to
ptLineApp[00552CA0]->InitContext of [800003FF]
[1792] 11:18:42:242: [INFO ] LineEventProc: setting msg->OpenContext to
[800003DD]
[1792] 11:18:42:242: [INFO ] FMsgDisbled: dwAPIVersion<= TAPI_VERSION3_0,
msg will be enabled
[1792] 11:18:42:242: [TRACE] FMsgDisabled return 0
[1792] 11:18:42:242: [TRACE] WriteEventBuffer - enter
[1792] 11:18:42:242: [TRACE] WriteEventBuffer: SetEvent 00000114 for local
client
[3404] 11:18:42:242: [TRACE] LineEpilogSync: exit, result=x0
[2980] 11:18:42:242: [TRACE] GetAsyncEvents: enter (TID=2980)
[2980] 11:18:42:242: [INFO ] M ebfused:x2c pEvtBuf: 0x005527A0
pDataOut:0x005527A0 pDataIn:0x005527CC
[2980] 11:18:42:242: [TRACE] GetAsyncEvents: return dwUsedBufferSize:x2c
[4076] 11:18:42:242: [TRACE] LineProlog: -- enter
[4076] 11:18:42:242: [INFO ] LineProlog: dwArg 100be
[4076] 11:18:42:242: [INFO ] LineProlog: ANY_RT_HCALL
[4076] 11:18:42:242: [INFO ] LineProlog: ReferenceObject returned
ptCallClient 005568D4
[4076] 11:18:42:242: [INFO ] LineProlog: OpenContext 800003DD
[4076] 11:18:42:242: [TRACE] LienProlog: exit, result = x10356
[4076] 11:18:42:242: [TRACE] LineEpilogAsyc: exit, result=x10356
[452] 11:18:42:242: [TRACE] CompletionProcSP: enter, dwReqID=x10356,
lResult=x80000048
[1792] 11:18:42:242: [INFO ] Got an async completion event, requestID =
0x10356, htXxx = 0x102ee, lResult = 0x80000048
[1792] 11:18:42:242: [TRACE] CompletionProc: enter, dwReqID=x10356,
lResult=x80000048
[1792] 11:18:42:242: [TRACE] WriteEventBuffer - enter
[1792] 11:18:42:242: [TRACE] WriteEventBuffer: SetEvent 00000114 for local
client
[3404] 11:18:42:242: [TRACE] GetAsyncEvents: enter (TID=3404)
[3404] 11:18:42:242: [INFO ] M ebfused:x28 pEvtBuf: 0x005527A0
pDataOut:0x005527A0 pDataIn:0x005527C8
[3404] 11:18:42:242: [TRACE] GetAsyncEvents: return dwUsedBufferSize:x28
[2980] 11:18:42:242: [TRACE] LineProlog: -- enter
[2980] 11:18:42:242: [INFO ] LineProlog: dwArg 100be
[2980] 11:18:42:242: [INFO ] LineProlog: ANY_RT_HCALL
[2980] 11:18:42:242: [INFO ] LineProlog: ReferenceObject returned
ptCallClient 005568D4
[2980] 11:18:42:242: [TRACE] LienProlog: exit, result = x0
[2980] 11:18:42:242: [TRACE] DestroytCallClient: enter, ptCallCli=x005568D4
[2980] 11:18:42:242: [TRACE] DestroytCall: enter, ptCall=x00556858
[2980] 11:18:42:242: [TRACE] LineEpilogSync: exit, result=x0
[480] 11:18:14:899: [INFO ] AsyncEventsThread: msg=23, hDev=x102ff, p1=x0,
p2=x100be, p3=x4
[480] 11:18:14:899: [INFO ] AsyncEventsThread: posting msg, hwnd=x10032
[1896] 11:18:14:899: [TRACE] TAPIWndProc: received WM_ASYNCEVENT,
hwnd=x00010032
[1896] 11:18:14:899: [INFO ] Calling app's callback, hDev=x102ff, Msg=23,
dwInst=x10c368 P1=x0, P2=x100be P3=x4
[1896] 11:18:14:899: [TRACE] No entries - spurious entry.
[480] 11:18:14:899: [INFO ] AsyncEventsThread: msg=2, hDev=x100be, p1=x2,
p2=x0, p3=x0
[480] 11:18:14:899: [INFO ] AsyncEventsThread: posting msg, hwnd=x10032
[1896] 11:18:14:899: [TRACE] TAPIWndProc: received WM_ASYNCEVENT,
hwnd=x00010032
[1896] 11:18:14:899: [INFO ] Calling app's callback, hDev=x100be, Msg=2,
dwInst=x10c368 P1=x2, P2=x0 P3=x0
[1896] 11:18:14:899: [TRACE] DoFunc -- enter
[1896] 11:18:14:899: [TRACE] AllocClientResources: enter
[1896] 11:18:14:899: [TRACE] AllocClientResources: exit, returning x0
[1896] 11:18:14:899: [TRACE] DoFunc: back from srv- return code=0x00000000
[1896] 11:18:14:899: [TRACE] DoFunc: result = x0
[1836] 11:18:14:899: [TRACE] DoFunc -- enter
[1836] 11:18:14:899: [TRACE] AllocClientResources: enter
[1836] 11:18:14:899: [TRACE] AllocClientResources: exit, returning x0
[1896] 11:18:14:899: [TRACE] No entries - spurious entry.
[1836] 11:18:14:899: [TRACE] DoFunc: back from srv- return code=0x00010163
[1836] 11:18:14:899: [TRACE] DoFunc: result = x10163
[480] 11:18:14:899: [INFO ] AsyncEventsThread: msg=12, hDev=x0, p1=x10163,
p2=x80000048, p3=x0
[480] 11:18:14:899: [INFO ] AsyncEventsThread: posting msg, hwnd=x10032
[1896] 11:18:14:899: [TRACE] TAPIWndProc: received WM_ASYNCEVENT,
hwnd=x00010032
[1896] 11:18:14:899: [INFO ] Calling app's callback, hDev=x0, Msg=12,
dwInst=x10c368 P1=x10163, P2=x80000048 P3=x0
[1836] 11:18:14:899: [TRACE] DoFunc -- enter
[1836] 11:18:14:899: [TRACE] AllocClientResources: enter
[1836] 11:18:14:899: [TRACE] AllocClientResources: exit, returning x0
[1896] 11:18:14:899: [TRACE] No entries - spurious entry.
[1836] 11:18:14:899: [TRACE] DoFunc: back from srv- return code=0x000100d0
[1836] 11:18:14:899: [TRACE] DoFunc: result = x100d0
[480] 11:18:14:899: [INFO ] AsyncEventsThread: msg=12, hDev=x0, p1=x100d0,
p2=x0, p3=x0
[480] 11:18:14:899: [INFO ] AsyncEventsThread: posting msg, hwnd=x10032
[1896] 11:18:14:899: [TRACE] TAPIWndProc: received WM_ASYNCEVENT,
hwnd=x00010032
[1896] 11:18:14:899: [INFO ] Calling app's callback, hDev=x0, Msg=12,
dwInst=x10c368 P1=x100d0, P2=x0 P3=x0
[1896] 11:18:14:899: [TRACE] No entries - spurious entry.
[480] 11:18:14:899: [INFO ] AsyncEventsThread: msg=2, hDev=x100be, p1=x100,
p2=x0, p3=x0
[480] 11:18:14:899: [INFO ] AsyncEventsThread: posting msg, hwnd=x10032
[1896] 11:18:14:899: [TRACE] TAPIWndProc: received WM_ASYNCEVENT,
hwnd=x00010032
[1896] 11:18:14:899: [INFO ] Calling app's callback, hDev=x100be, Msg=2,
dwInst=x10c368 P1=x100, P2=x0 P3=x0
[1896] 11:18:14:899: [TRACE] DoFunc -- enter
[1896] 11:18:14:899: [TRACE] AllocClientResources: enter
[1896] 11:18:14:899: [TRACE] AllocClientResources: exit, returning x0
[1896] 11:18:14:899: [TRACE] DoFunc: back from srv- return code=0x00000000
[1896] 11:18:14:899: [TRACE] DoFunc: result = x0
[1896] 11:18:14:899: [TRACE] No entries - spurious entry.
[2512] 11:18:14:899: [TRACE] DoFunc -- enter
[2512] 11:18:14:899: [TRACE] AllocClientResources: enter
[2512] 11:18:14:899: [TRACE] AllocClientResources: exit, returning x0
[2512] 11:18:14:899: [TRACE] DoFunc: back from srv- return code=0x00000000
[2512] 11:18:14:899: [TRACE] DoFunc: result = x0
[2512] 11:18:14:899: [TRACE] DoFunc -- enter
[2512] 11:18:14:899: [TRACE] AllocClientResources: enter
[2512] 11:18:14:899: [TRACE] AllocClientResources: exit, returning x0
[2512] 11:18:14:899: [TRACE] DoFunc: back from srv- return code=0x00000000
[2512] 11:18:14:899: [TRACE] DoFunc: result = x0
[480] 11:18:42:242: [INFO ] AsyncEventsThread: msg=2, hDev=x100be, p1=x4000,
p2=x0, p3=x0
[480] 11:18:42:242: [INFO ] AsyncEventsThread: posting msg, hwnd=x10032
[1896] 11:18:42:242: [TRACE] TAPIWndProc: received WM_ASYNCEVENT,
hwnd=x00010032
[1896] 11:18:42:242: [INFO ] Calling app's callback, hDev=x100be, Msg=2,
dwInst=x10c368 P1=x4000, P2=x0 P3=x0
[1896] 11:18:42:242: [TRACE] DoFunc -- enter
[1896] 11:18:42:242: [TRACE] AllocClientResources: enter
[1896] 11:18:42:242: [TRACE] AllocClientResources: exit, returning x0
[1896] 11:18:42:242: [TRACE] DoFunc: back from srv- return code=0x00000000
[1896] 11:18:42:242: [TRACE] DoFunc: result = x0
[1896] 11:18:42:242: [TRACE] DoFunc -- enter
[1896] 11:18:42:242: [TRACE] AllocClientResources: enter
[1896] 11:18:42:242: [TRACE] AllocClientResources: exit, returning x0
[480] 11:18:42:242: [INFO ] AsyncEventsThread: msg=2, hDev=x100be, p1=x1,
p2=x0, p3=x0
[480] 11:18:42:242: [INFO ] AsyncEventsThread: posting msg, hwnd=x10032
[1896] 11:18:42:242: [TRACE] DoFunc: back from srv- return code=0x00010356
[1896] 11:18:42:242: [TRACE] DoFunc: result = x10356
[1896] 11:18:42:242: [INFO ] Calling app's callback, hDev=x100be, Msg=2,
dwInst=x10c368 P1=x1, P2=x0 P3=x0
[1896] 11:18:42:242: [TRACE] No entries - spurious entry.
[1896] 11:18:42:242: [TRACE] TAPIWndProc: received WM_ASYNCEVENT,
hwnd=x00010032
[1896] 11:18:42:242: [TRACE] No entries - spurious entry.
[480] 11:18:42:242: [INFO ] AsyncEventsThread: msg=12, hDev=x0, p1=x10356,
p2=x80000048, p3=x0
[480] 11:18:42:242: [INFO ] AsyncEventsThread: posting msg, hwnd=x10032
[1896] 11:18:42:242: [TRACE] TAPIWndProc: received WM_ASYNCEVENT,
hwnd=x00010032
[1896] 11:18:42:242: [INFO ] Calling app's callback, hDev=x0, Msg=12,
dwInst=x10c368 P1=x10356, P2=x80000048 P3=x0
[1896] 11:18:42:242: [TRACE] lineDeallocateCall: enter on thread: 0x00000768
[1896] 11:18:42:242: [INFO ] hCall = 0x000100be
[1896] 11:18:42:242: [TRACE] DoFunc -- enter
[1896] 11:18:42:242: [TRACE] AllocClientResources: enter
[1896] 11:18:42:242: [TRACE] AllocClientResources: exit, returning x0
[1896] 11:18:42:242: [TRACE] DoFunc: back from srv- return code=0x00000000
[1896] 11:18:42:242: [TRACE] DoFunc: result = x0
[1896] 11:18:42:242: [TRACE] No entries - spurious entry.
[1896] 11-17 11:18:14:899: RasTapicallback: msg=23 , param1=0l , param2=65726l
[1896] 11-17 11:18:14:899: RasTapicallback: msg=2 , param1=2l , param2=0l
[1896] 11-17 11:18:14:899: RasTapicallback: linecallstate=0x2
[1896] 11-17 11:18:14:899: DwProcessOfferEvent: hcall=0x100be
[1896] 11-17 11:18:14:899: DwProcessOfferEvent: Accepting call on VPN4-26
hcall = 0x100be
[1896] 11-17 11:18:14:899: WAN Miniport (PPTP) InClients=4,
TotalDialInClients=4
[1896] 11-17 11:18:14:899: DwProcessOfferEvent 0x0
[1836] 11-17 11:18:14:899: DeviceWork: VPN4-26. State = 2
[1836] 11-17 11:18:14:899: DeviceWork: VPN4-26. lineAccept returned 0x10163
[1896] 11-17 11:18:14:899: RasTapicallback: msg=12 , param1=65891l ,
param2=2147483720l
[1896] 11-17 11:18:14:899: LINE_REPLY. param1=0x10163
[1896] 11-17 11:18:14:899: RasTapiCallback: Changing Listen State for
VPN4-26 from 2 -> 3
[1836] 11-17 11:18:14:899: DeviceWork: VPN4-26. State = 2
[1836] 11-17 11:18:14:899: DeviceWork: VPN4-26. lineAnswer returned 0x100d0
[1896] 11-17 11:18:14:899: RasTapicallback: msg=12 , param1=65744l , param2=0l
[1896] 11-17 11:18:14:899: LINE_REPLY. param1=0x100d0
[1896] 11-17 11:18:14:899: RasTapiCallback: LINE_REPLY. Changing Listen
state for VPN4-26 from 3 -> 4
[1896] 11-17 11:18:14:899: **** Not posting completion for lineAnswer ***
[1896] 11-17 11:18:14:899: RasTapicallback: msg=2 , param1=256l , param2=0l
[1896] 11-17 11:18:14:899: RasTapicallback: linecallstate=0x100
[1896] 11-17 11:18:14:899: DwGetConnectInfo
[1896] 11-17 11:18:14:899: DwGetIDInformation
[1896] 11-17 11:18:14:899: DwGetIDInformation. 0
[1896] 11-17 11:18:14:899: SizeRequired for CallID=16
[1896] 11-17 11:18:14:899: DwGetIDInformation
[1896] 11-17 11:18:14:899: GetIDInformation: CallerID=65.126.159.238
[1896] 11-17 11:18:14:899: RasTapiCallback: called id info. not avail
[1896] 11-17 11:18:14:899: DwGetIDInformation. 0
[1896] 11-17 11:18:14:899: DwGetConnectInfo. 0x0
[1896] 11-17 11:18:14:899: RasTapiCallback: DwGetConnectInforeturned 0x0
[1896] 11-17 11:18:14:899: RasTapiCallback: Connected on VPN4-26
[1896] 11-17 11:18:14:899: RasTapiCallback: Incoming Call
[1836] 11-17 11:18:14:899: DeviceWork: VPN4-26. State = 2
[1836] 11-17 11:18:14:899: DeviceWork: Changing State for VPN4-26 from 2 -> 3
[2512] 11-17 11:18:14:899: PortConnect: VPN4-26
[2512] 11-17 11:18:14:899:
[1896] 11-17 11:18:42:242: RasTapicallback: msg=2 , param1=16384l , param2=0l
[1896] 11-17 11:18:42:242: RasTapicallback: linecallstate=0x4000
[1896] 11-17 11:18:42:242: RasTapiCallback: lineGetCallStatus for VPN4-26
returned 0x4000
[1896] 11-17 11:18:42:242: RasTapiCallback: DisconnectReason mapped to 2
[1896] 11-17 11:18:42:242: RasTapiCallback: LINECALLSTATE - initiating Port
Disconnect
[1896] 11-17 11:18:42:242: InitiatePortDisconnection: VPN4-26
[1896] 11-17 11:18:42:242: WAN Miniport (PPTP) InClients=3,
TotalDialInClients=3
[1896] 11-17 11:18:42:242: InitiatePortDisconnection: Changing state for
VPN4-26 from 3 -> 5, id=0x10356
[1896] 11-17 11:18:42:242:
[1896] 11-17 11:18:42:242: RasTapicallback: msg=2 , param1=1l , param2=0l
[1896] 11-17 11:18:42:242: RasTapicallback: linecallstate=0x1
[1896] 11-17 11:18:42:242: RasTapicallback: msg=12 , param1=66390l ,
param2=2147483720l
[1896] 11-17 11:18:42:242: LINE_REPLY. param1=0x10356
[1896] 11-17 11:18:42:242: RasTapiCallback: lineDropped. port VPN4-26,
id=0xffffffff
[1896] 11-17 11:18:42:242: RasTapiCallback: Idle Received for port VPN4-26
[1896] 11-17 11:18:42:242: RasTapiCallback: changing state of VPN4-26. 5 -> 1
[1896] 11-17 11:18:42:242: RasTapiCallback: lineDeallocateCall for
VPN4-26,hcall = 0x100be
[1836] 11-17 11:18:42:242: PortTestSignalState: DisconnectReason = 2
[1836] 11-17 11:18:42:242: PortDisconnect: VPN4-26
[1836] 11-17 11:18:42:242:
[2512] 11-17 11:18:42:242: DeviceListen: Changing State for VPN4-26 from 1
-> 2
[2512] 11-17 11:18:42:242: DeviceListen: Changing Listen State for VPN4-26
from 4 -> 2
[2512] 11-17 11:18:42:242:
A network Monitor Trace of this event shows the conenction start and end,
however I could not find anything in there that led me to an answer (I have
the trace results if needed).
While this connection was attempted there was another client VPN connection
active from the same location, in addition there were four or five Site-to
Site VPN connections active.