Hi all,
We have ISA server which is working as firewall, proxy and vpn server.
Everything was working fine for year, but starting this monday our users are unable to connect to VPN. They are getting error 691 and there is event id 20014 on the server.
I tried to recreate RRAS and create new user with dial-in permission, but problem still the same.
Surfing the internet and this site didn't provide me solution. Please help!!!!
Here is some ISA log to clarify:
IPRouterManager.LOG
5052] 00:13:04: Error adding route, Stack bit == 0
[5052] 00:13:04: ProcessDefaultRouteChanges: Not default route 85.141.210.54/32
[4220] 00:13:07: HandleSolicitations: Received 60 bytes on 209.60.18.12
[4220] 00:13:37: HandleSolicitations: Received 60 bytes on 209.60.18.12
[4220] 00:14:07: HandleSolicitations: Received 60 bytes on 209.60.18.12
[4220] 00:14:28: HandleSolicitations: Received 28 bytes on 209.60.18.12
[4220] 00:14:36: HandleSolicitations: Received 60 bytes on 209.60.18.12
tapisrv.log
[2452] 00:13:04:089: [INFO ] LineEventProcSP: HTapiLine=00010346, HTapiCall=00000000, msg=1f4, P1=x7e0004, P2=x98770, P3=x0
[2452] 00:13:04:089: [TRACE] LineEventProc
[2452] 00:13:04:089: [TRACE] CreatetCall: enter, ptLine=009E7308
[2452] 00:13:04:089: [INFO ] CreatetCall: calling NewObject ptCall 009E74C0
[2452] 00:13:04:089: [TRACE] CreatetCall: NewObject returned 0x102f5
[2452] 00:13:04:089: [TRACE] CreatetCall: exit, new ptCall=009E74C0
[2452] 00:13:04:089: [INFO ] LineEventProcSP: HTapiLine=00010346, HTapiCall=000102F5, msg=2, P1=x2, P2=x0, P3=x100
[2276] 00:13:04:089: [INFO ] Got a line spevent, htLine = 0x10346, htCall = 0x102f5, dwMsg = 0x2
[2276] 00:13:04:089: [TRACE] LineEventProc
[2276] 00:13:04:089: [EVENT] LineEventProc: LINE_CALLSTATE event x2
[2276] 00:13:04:089: [TRACE] CreatetCallClient: enter, ptCall=009E74C0,
[2276] 00:13:04:089: [INFO ] CreatetCallClient: calling NewObject, ptCallClient = [009E753C]
[2276] 00:13:04:089: [TRACE] CreatetCallClient: exit, new ptCallClient=009E753C
[2276] 00:13:04:089: [INFO ] LineEventProc: i = [0] corresponding ptCallClient [009E753C]
[2276] 00:13:04:089: [INFO ] LineEventProc: ptCallClient->ptLineClient[009E7220]
[2276] 00:13:04:089: [INFO ] LineEventProc: ptLineClient->ptLineApp[00552CC0]
[2276] 00:13:04:089: [INFO ] LineEventProc: setting msg->InitContext to ptLineApp[00552CC0]->InitContext of [800003FF]
[2276] 00:13:04:089: [INFO ] LineEventProc: setting msg->OpenContext to [80000233]
[2276] 00:13:04:089: [INFO ] FMsgDisbled: dwAPIVersion<= TAPI_VERSION3_0, msg will be enabled
[2276] 00:13:04:089: [TRACE] FMsgDisabled return 0
[2276] 00:13:04:089: [INFO ] LineEventProc: sending LINE_APPNEWCALL, ptClient[00552690]
[2276] 00:13:04:089: [TRACE] WriteEventBuffer - enter
[2276] 00:13:04:089: [TRACE] WriteEventBuffer: SetEvent 0000011C for local client
[2276] 00:13:04:089: [INFO ] FMsgDisbled: dwAPIVersion<= TAPI_VERSION3_0, msg will be enabled
[2276] 00:13:04:089: [TRACE] FMsgDisabled return 0
[2276] 00:13:04:089: [TRACE] WriteEventBuffer - enter
[2276] 00:13:04:089: [TRACE] WriteEventBuffer: SetEvent 0000011C for local client
[5620] 00:13:04:089: [TRACE] GetAsyncEvents: enter (TID=5620)
[5620] 00:13:04:089: [INFO ] M ebfused:x60 pEvtBuf: 0x005527A0 pDataOut:0x005527A0 pDataIn:0x00552800
[5620] 00:13:04:089: [TRACE] GetAsyncEvents: return dwUsedBufferSize:x60
[5620] 00:13:04:089: [TRACE] LineProlog: -- enter
[5620] 00:13:04:089: [INFO ] LineProlog: dwArg 10106
[5620] 00:13:04:089: [INFO ] LineProlog: ANY_RT_HCALL
[5620] 00:13:04:089: [INFO ] LineProlog: ReferenceObject returned ptCallClient 009E753C
[5620] 00:13:04:089: [TRACE] LienProlog: exit, result = x0
[5620] 00:13:04:089: [TRACE] LineEpilogSync: exit, result=x0
[5620] 00:13:04:089: [TRACE] LineProlog: -- enter
[5620] 00:13:04:089: [INFO ] LineProlog: dwArg 10106
[5620] 00:13:04:089: [INFO ] LineProlog: ANY_RT_HCALL
[5620] 00:13:04:089: [INFO ] LineProlog: ReferenceObject returned ptCallClient 009E753C
[5620] 00:13:04:089: [INFO ] LineProlog: OpenContext 80000233
[5620] 00:13:04:089: [TRACE] LienProlog: exit, result = x103b2
[5620] 00:13:04:089: [TRACE] LineEpilogAsyc: exit, result=x103b2
[2452] 00:13:04:089: [TRACE] CompletionProcSP: enter, dwReqID=x103b2, lResult=x80000048
[2276] 00:13:04:089: [INFO ] Got an async completion event, requestID = 0x103b2, htXxx = 0x10346, lResult = 0x80000048
[2276] 00:13:04:089: [TRACE] CompletionProc: enter, dwReqID=x103b2, lResult=x80000048
[2276] 00:13:04:089: [TRACE] WriteEventBuffer - enter
[2276] 00:13:04:089: [TRACE] WriteEventBuffer: SetEvent 0000011C for local client
[5788] 00:13:04:089: [TRACE] GetAsyncEvents: enter (TID=5788)
[5788] 00:13:04:089: [INFO ] M ebfused:x28 pEvtBuf: 0x005527A0 pDataOut:0x005527A0 pDataIn:0x005527C8
[5788] 00:13:04:089: [TRACE] GetAsyncEvents: return dwUsedBufferSize:x28
[5620] 00:13:04:089: [TRACE] LineProlog: -- enter
[5620] 00:13:04:089: [INFO ] LineProlog: dwArg 10106
[5620] 00:13:04:089: [INFO ] LineProlog: ANY_RT_HCALL
[5620] 00:13:04:089: [INFO ] LineProlog: ReferenceObject returned ptCallClient 009E753C
[5620] 00:13:04:089: [INFO ] LineProlog: OpenContext 80000233
[5620] 00:13:04:089: [TRACE] LienProlog: exit, result = x103a1
[5620] 00:13:04:089: [TRACE] LineEpilogAsyc: exit, result=x103a1
[2452] 00:13:04:089: [INFO ] LineEventProcSP: HTapiLine=00010346, HTapiCall=000102F5, msg=2, P1=x100, P2=x0, P3=x100
[2276] 00:13:04:089: [INFO ] Got a line spevent, htLine = 0x10346, htCall = 0x102f5, dwMsg = 0x2
[2276] 00:13:04:089: [TRACE] LineEventProc
[2276] 00:13:04:089: [EVENT] LineEventProc: LINE_CALLSTATE event x100
[2276] 00:13:04:089: [INFO ] LineEventProc: i = [0] corresponding ptCallClient [009E753C]
[2276] 00:13:04:089: [INFO ] LineEventProc: ptCallClient->ptLineClient[009E7220]
[2276] 00:13:04:089: [INFO ] LineEventProc: ptLineClient->ptLineApp[00552CC0]
[2276] 00:13:04:089: [INFO ] LineEventProc: setting msg->InitContext to ptLineApp[00552CC0]->InitContext of [800003FF]
[2276] 00:13:04:089: [INFO ] LineEventProc: setting msg->OpenContext to [80000233]
[2276] 00:13:04:089: [INFO ] FMsgDisbled: dwAPIVersion<= TAPI_VERSION3_0, msg will be enabled
[2276] 00:13:04:089: [TRACE] FMsgDisabled return 0
[2276] 00:13:04:089: [TRACE] WriteEventBuffer - enter
[2276] 00:13:04:089: [TRACE] WriteEventBuffer: SetEvent 0000011C for local client
[5788] 00:13:04:089: [TRACE] GetAsyncEvents: enter (TID=5788)
[2452] 00:13:04:089: [TRACE] CompletionProcSP: enter, dwReqID=x103a1, lResult=x0
[5788] 00:13:04:089: [INFO ] M ebfused:x2c pEvtBuf: 0x005527A0 pDataOut:0x005527A0 pDataIn:0x005527CC
[2276] 00:13:04:089: [INFO ] Got an async completion event, requestID = 0x103a1, htXxx = 0x10346, lResult = 0x0
[5788] 00:13:04:089: [TRACE] GetAsyncEvents: return dwUsedBufferSize:x2c
[2276] 00:13:04:089: [TRACE] CompletionProc: enter, dwReqID=x103a1, lResult=x0
[2276] 00:13:04:089: [TRACE] WriteEventBuffer - enter
[2276] 00:13:04:089: [TRACE] WriteEventBuffer: SetEvent 0000011C for local client
[5620] 00:13:04:089: [TRACE] GetAsyncEvents: enter (TID=5620)
[5620] 00:13:04:089: [INFO ] M ebfused:x28 pEvtBuf: 0x005527A0 pDataOut:0x005527A0 pDataIn:0x005527C8
[5620] 00:13:04:089: [TRACE] GetAsyncEvents: return dwUsedBufferSize:x28
[5788] 00:13:04:089: [TRACE] LineProlog: -- enter
[5788] 00:13:04:089: [INFO ] LineProlog: dwArg 10106
[5788] 00:13:04:089: [INFO ] LineProlog: ANY_RT_HCALL
[5788] 00:13:04:089: [INFO ] LineProlog: ReferenceObject returned ptCallClient 009E753C
[5788] 00:13:04:089: [TRACE] LienProlog: exit, result = x0
[5788] 00:13:04:089: [TRACE] LineEpilogSync: exit, result=x0
[5788] 00:13:04:089: [TRACE] LineProlog: -- enter
[5788] 00:13:04:089: [INFO ] LineProlog: dwArg 10106
[5788] 00:13:04:089: [INFO ] LineProlog: ANY_RT_HCALL
[5788] 00:13:04:089: [INFO ] LineProlog: ReferenceObject returned ptCallClient 009E753C
[5788] 00:13:04:089: [TRACE] LienProlog: exit, result = x0
[5788] 00:13:04:089: [TRACE] LineEpilogSync: exit, result=x0
[5788] 00:13:04:089: [TRACE] LineProlog: -- enter
[5788] 00:13:04:089: [INFO ] LineProlog: dwArg 10106
[5788] 00:13:04:089: [INFO ] LineProlog: ANY_RT_HCALL
[5788] 00:13:04:089: [INFO ] LineProlog: ReferenceObject returned ptCallClient 009E753C
[5788] 00:13:04:089: [TRACE] LienProlog: exit, result = x0
[5788] 00:13:04:089: [TRACE] LineEpilogSync: exit, result=x0
[5620] 00:13:04:709: [TRACE] LineProlog: -- enter
[5620] 00:13:04:709: [INFO ] LineProlog: dwArg 10106
[5620] 00:13:04:709: [INFO ] LineProlog: ANY_RT_HCALL
[5620] 00:13:04:709: [INFO ] LineProlog: ReferenceObject returned ptCallClient 009E753C
[5620] 00:13:04:709: [INFO ] LineProlog: OpenContext 80000233
[5620] 00:13:04:709: [TRACE] LienProlog: exit, result = x10128
[5620] 00:13:04:709: [TRACE] LineEpilogAsyc: exit, result=x10128
[2452] 00:13:05:003: [INFO ] LineEventProcSP: HTapiLine=00010346, HTapiCall=000102F5, msg=2, P1=x1, P2=x0, P3=x0
[2276] 00:13:05:003: [INFO ] Got a line spevent, htLine = 0x10346, htCall = 0x102f5, dwMsg = 0x2
[2276] 00:13:05:003: [TRACE] LineEventProc
[2276] 00:13:05:003: [EVENT] LineEventProc: LINE_CALLSTATE event x1
[2276] 00:13:05:003: [INFO ] LineEventProc: i = [0] corresponding ptCallClient [009E753C]
[2276] 00:13:05:003: [INFO ] LineEventProc: ptCallClient->ptLineClient[009E7220]
[2452] 00:13:05:003: [TRACE] CompletionProcSP: enter, dwReqID=x10128, lResult=x0
[2276] 00:13:05:003: [INFO ] LineEventProc: ptLineClient->ptLineApp[00552CC0]
[2276] 00:13:05:003: [INFO ] LineEventProc: setting msg->InitContext to ptLineApp[00552CC0]->InitContext of [800003FF]
[2276] 00:13:05:003: [INFO ] LineEventProc: setting msg->OpenContext to [80000233]
[2276] 00:13:05:003: [INFO ] FMsgDisbled: dwAPIVersion<= TAPI_VERSION3_0, msg will be enabled
[2276] 00:13:05:003: [TRACE] FMsgDisabled return 0
[2276] 00:13:05:003: [TRACE] WriteEventBuffer - enter
[2276] 00:13:05:003: [TRACE] WriteEventBuffer: SetEvent 0000011C for local client
[2276] 00:13:05:003: [INFO ] Got an async completion event, requestID = 0x10128, htXxx = 0x10346, lResult = 0x0
[2276] 00:13:05:003: [TRACE] CompletionProc: enter, dwReqID=x10128, lResult=x0
[2276] 00:13:05:003: [TRACE] WriteEventBuffer - enter
[2276] 00:13:05:003: [TRACE] WriteEventBuffer: SetEvent 0000011C for local client
[5788] 00:13:05:003: [TRACE] GetAsyncEvents: enter (TID=5788)
[5788] 00:13:05:003: [INFO ] M ebfused:x54 pEvtBuf: 0x005527A0 pDataOut:0x005527A0 pDataIn:0x005527F4
[5788] 00:13:05:003: [TRACE] GetAsyncEvents: return dwUsedBufferSize:x54
[5620] 00:13:05:003: [TRACE] LineProlog: -- enter
[5620] 00:13:05:003: [INFO ] LineProlog: dwArg 10106
[5620] 00:13:05:003: [INFO ] LineProlog: ANY_RT_HCALL
[5620] 00:13:05:003: [INFO ] LineProlog: ReferenceObject returned ptCallClient 009E753C
[5620] 00:13:05:003: [TRACE] LienProlog: exit, result = x0
[5620] 00:13:05:003: [TRACE] DestroytCallClient: enter, ptCallCli=x009E753C
[5620] 00:13:05:003: [TRACE] DestroytCall: enter, ptCall=x009E74C0
[5620] 00:13:05:003: [TRACE] LineEpilogSync: exit, result=x0
RASMAN.LOG
[2356] 10-10 00:13:04:089: WorkerThread: Async work event signaled on port: VPN5-127
[2356] 10-10 00:13:04:089: OVEVT_DEV_ASYNCOP. pOverlapped = 0x27b0df0
[2356] 10-10 00:13:04:089: ServiceWorkRequest: Async op event 27 for port VPN5-127 returned 600
[2356] 10-10 00:13:04:089: WorkerThread: Async work event signaled on port: VPN5-127
[2356] 10-10 00:13:04:089: OVEVT_DEV_ASYNCOP. pOverlapped = 0x27b0df0
[2356] 10-10 00:13:04:089: ServiceWorkRequest: Async op event 27 for port VPN5-127 returned 600
[2356] 10-10 00:13:04:089: WorkerThread: Async work event signaled on port: VPN5-127
[2356] 10-10 00:13:04:089: OVEVT_DEV_ASYNCOP. pOverlapped = 0x27b0df0
[2356] 10-10 00:13:04:089: d:\srv03rtm\net\rras\ras\rasman\rasman\request.c: 7507: port 139 state chg: prev=1, new=5
[2356] 10-10 00:13:04:089: RasmanReceiveFlags = 0x0
[2356] 10-10 00:13:04:089: d:\srv03rtm\net\rras\ras\rasman\rasman\worker.c: 2269: port 139 async reqtype chg: prev=27, new=0
[2356] 10-10 00:13:04:089: ServiceWorkRequest: Async op event 27 for port VPN5-127 returned 0
[2748] 10-10 00:13:04:089: ConnectCompleteRequest: entered for port 139
[2748] 10-10 00:13:04:089: d:\srv03rtm\net\rras\ras\rasman\rasman\request.c: 7401: port 139 state chg: prev=5, new=2
[2748] 10-10 00:13:04:089: AllocBundle: pBundle=0x4f172c8
[2748] 10-10 00:13:04:089: d:\srv03rtm\net\rras\ras\rasman\rasman\request.c 8901: Mapping Cookie to handle. port = VPN5-127(0xbaaa7b8), Bundlehandle = 0x27, linkhandle = 0x27
[2748] 10-10 00:13:04:089: Connection Completed on port: VPN5-127, error code: 0
[2748] 10-10 00:13:04:089: d:\srv03rtm\net\rras\ras\rasman\rasman\request.c: 6654: port 139 async reqtype chg: prev=0, new=26
[2356] 10-10 00:13:04:430: Completed receive - First Frame on VPN5-127, handle=0x1240
[2548] 10-10 00:13:04:430: GetConnectInfo: port VPN5-127
[2548] 10-10 00:13:04:430: GetConnectInfo: size=52, rc=0xx0
[2548] 10-10 00:13:04:430: GetConnectInfo: port VPN5-127
[2548] 10-10 00:13:04:430: GetConnectInfo: size=52, rc=0xx0
[2548] 10-10 00:13:04:430: GetConnectInfo: port VPN5-127
[2548] 10-10 00:13:04:430: GetConnectInfo: size=52, rc=0xx0
[2548] 10-10 00:13:04:430: GetConnectInfo: port VPN5-127
[2548] 10-10 00:13:04:430: GetConnectInfo: size=52, rc=0xx0
[2548] 10-10 00:13:04:430: PppStarted...VPN5-127
[2748] 10-10 00:13:04:709: PortDisconnectRequest on VPN5-127 Connection=0x0 ,RasmanReceiveFlags=0x4
[2748] 10-10 00:13:04:709: PortDisconnectRequest: Disconnecting VPN5-127
[2748] 10-10 00:13:04:709: Disconnecting Port 0xVPN5-127, reason 0
[2748] 10-10 00:13:04:709: DisconnectPort: Saving Bundle stats for port VPN5-127
[2748] 10-10 00:13:04:709: d:\srv03rtm\net\rras\ras\rasman\rasman\util.c 1992: Disconnected Port 139, reason 0. rc=0x258
[2748] 10-10 00:13:04:709: FreeBundle: freeing pBundle=0x4f172c8
[2748] 10-10 00:13:04:709: d:\srv03rtm\net\rras\ras\rasman\rasman\util.c: 2213: port 139 state chg: prev=2, new=3
[2748] 10-10 00:13:04:709: d:\srv03rtm\net\rras\ras\rasman\rasman\util.c: 2283: port 139 async reqtype chg: prev=26, new=9
[2748] 10-10 00:13:04:709: Disconnect request on port: VPN5-127
[2356] 10-10 00:13:04:709: OVEVT_RASMAN_ADJUST_TIMER
[2356] 10-10 00:13:04:709: OVEVT_RASMAN_ADJUST_TIMER
[2356] 10-10 00:13:05:003: WorkerThread: Disconnect event signaled on port: VPN5-127
[2356] 10-10 00:13:05:003: OVEVT_DEV_STATECHANGE. pOverlapped = 0x27b0e30
[2356] 10-10 00:13:05:003: d:\srv03rtm\net\rras\ras\rasman\rasman\request.c: 4702: port 139 state chg: prev=3, new=4
[2356] 10-10 00:13:05:003: d:\srv03rtm\net\rras\ras\rasman\rasman\request.c: 4713: port 139 async reqtype chg: prev=9, new=0
[2356] 10-10 00:13:05:003: CompleteDisconnectRequest: signalling 0xde4 for VPN5-127
[2356] 10-10 00:13:05:003: Disconnect completed on port: VPN5-127
[2748] 10-10 00:13:05:003: DeviceListenRequest: Clearing Autoclose flag on port VPN5-127
[2748] 10-10 00:13:05:003: d:\srv03rtm\net\rras\ras\rasman\rasman\util.c: 2547: port 139 state chg: prev=4, new=1
[2748] 10-10 00:13:05:003: d:\srv03rtm\net\rras\ras\rasman\rasman\util.c: 2578: port 139 async reqtype chg: prev=0, new=27
[2748] 10-10 00:13:05:003: Listen posted on port: VPN5-127, error code 600
tapi32.log
[2484] 00:13:04:089: [INFO ] AsyncEventsThread: msg=23, hDev=x10357, p1=x0, p2=x10106, p3=x4
[2484] 00:13:04:089: [INFO ] AsyncEventsThread: posting msg, hwnd=x1003e
[2484] 00:13:04:089: [INFO ] AsyncEventsThread: msg=2, hDev=x10106, p1=x2, p2=x0, p3=x0
[2396] 00:13:04:089: [TRACE] TAPIWndProc: received WM_ASYNCEVENT, hwnd=x0001003E
[2396] 00:13:04:089: [INFO ] Calling app's callback, hDev=x10357, Msg=23, dwInst=xf1808 P1=x0, P2=x10106 P3=x4
[2396] 00:13:04:089: [INFO ] Calling app's callback, hDev=x10106, Msg=2, dwInst=xf1808 P1=x2, P2=x0 P3=x0
[2396] 00:13:04:089: [TRACE] DoFunc -- enter
[2396] 00:13:04:089: [TRACE] AllocClientResources: enter
[2396] 00:13:04:089: [TRACE] AllocClientResources: exit, returning x0
[2396] 00:13:04:089: [TRACE] DoFunc: back from srv- return code=0x00000000
[2396] 00:13:04:089: [TRACE] DoFunc: result = x0
[2396] 00:13:04:089: [TRACE] No entries - spurious entry.
[2396] 00:13:04:089: [TRACE] TAPIWndProc: received WM_ASYNCEVENT, hwnd=x0001003E
[2356] 00:13:04:089: [TRACE] DoFunc -- enter
[2396] 00:13:04:089: [TRACE] No entries - spurious entry.
[2356] 00:13:04:089: [TRACE] AllocClientResources: enter
[2396] 00:13:04:089: [TRACE] TAPIWndProc: received WM_ASYNCEVENT, hwnd=x0001003E
[2396] 00:13:04:089: [TRACE] No entries - spurious entry.
[2356] 00:13:04:089: [TRACE] AllocClientResources: exit, returning x0
[2356] 00:13:04:089: [TRACE] DoFunc: back from srv- return code=0x000103b2
[2356] 00:13:04:089: [TRACE] DoFunc: result = x103b2
[2484] 00:13:04:089: [INFO ] AsyncEventsThread: msg=12, hDev=x0, p1=x103b2, p2=x80000048, p3=x0
[2484] 00:13:04:089: [INFO ] AsyncEventsThread: posting msg, hwnd=x1003e
[2396] 00:13:04:089: [TRACE] TAPIWndProc: received WM_ASYNCEVENT, hwnd=x0001003E
[2396] 00:13:04:089: [INFO ] Calling app's callback, hDev=x0, Msg=12, dwInst=xf1808 P1=x103b2, P2=x80000048 P3=x0
[2396] 00:13:04:089: [TRACE] No entries - spurious entry.
[2356] 00:13:04:089: [TRACE] DoFunc -- enter
[2356] 00:13:04:089: [TRACE] AllocClientResources: enter
[2356] 00:13:04:089: [TRACE] AllocClientResources: exit, returning x0
[2356] 00:13:04:089: [TRACE] DoFunc: back from srv- return code=0x000103a1
[2356] 00:13:04:089: [TRACE] DoFunc: result = x103a1
[2484] 00:13:04:089: [INFO ] AsyncEventsThread: msg=2, hDev=x10106, p1=x100, p2=x0, p3=x0
[2484] 00:13:04:089: [INFO ] AsyncEventsThread: posting msg, hwnd=x1003e
[2396] 00:13:04:089: [TRACE] TAPIWndProc: received WM_ASYNCEVENT, hwnd=x0001003E
[2396] 00:13:04:089: [INFO ] Calling app's callback, hDev=x10106, Msg=2, dwInst=xf1808 P1=x100, P2=x0 P3=x0
[2484] 00:13:04:089: [INFO ] AsyncEventsThread: msg=12, hDev=x0, p1=x103a1, p2=x0, p3=x0
[2484] 00:13:04:089: [INFO ] AsyncEventsThread: posting msg, hwnd=x1003e
[2396] 00:13:04:089: [TRACE] DoFunc -- enter
[2396] 00:13:04:089: [TRACE] AllocClientResources: enter
[2396] 00:13:04:089: [TRACE] AllocClientResources: exit, returning x0
[2396] 00:13:04:089: [TRACE] DoFunc: back from srv- return code=0x00000000
[2396] 00:13:04:089: [TRACE] DoFunc: result = x0
[2396] 00:13:04:089: [INFO ] Calling app's callback, hDev=x0, Msg=12, dwInst=xf1808 P1=x103a1, P2=x0 P3=x0
[2396] 00:13:04:089: [TRACE] No entries - spurious entry.
[2396] 00:13:04:089: [TRACE] TAPIWndProc: received WM_ASYNCEVENT, hwnd=x0001003E
[2396] 00:13:04:089: [TRACE] No entries - spurious entry.
[2748] 00:13:04:089: [TRACE] DoFunc -- enter
[2748] 00:13:04:089: [TRACE] AllocClientResources: enter
[2748] 00:13:04:089: [TRACE] AllocClientResources: exit, returning x0
[2748] 00:13:04:089: [TRACE] DoFunc: back from srv- return code=0x00000000
[2748] 00:13:04:089: [TRACE] DoFunc: result = x0
[2748] 00:13:04:089: [TRACE] DoFunc -- enter
[2748] 00:13:04:089: [TRACE] AllocClientResources: enter
[2748] 00:13:04:089: [TRACE] AllocClientResources: exit, returning x0
[2748] 00:13:04:089: [TRACE] DoFunc: back from srv- return code=0x00000000
[2748] 00:13:04:089: [TRACE] DoFunc: result = x0
[2748] 00:13:04:709: [TRACE] DoFunc -- enter
[2748] 00:13:04:709: [TRACE] AllocClientResources: enter
[2748] 00:13:04:709: [TRACE] AllocClientResources: exit, returning x0
[2748] 00:13:04:709: [TRACE] DoFunc: back from srv- return code=0x00010128
[2748] 00:13:04:709: [TRACE] DoFunc: result = x10128
[2484] 00:13:05:003: [INFO ] AsyncEventsThread: msg=2, hDev=x10106, p1=x1, p2=x0, p3=x0
[2484] 00:13:05:003: [INFO ] AsyncEventsThread: posting msg, hwnd=x1003e
[2484] 00:13:05:003: [INFO ] AsyncEventsThread: msg=12, hDev=x0, p1=x10128, p2=x0, p3=x0
[2396] 00:13:05:003: [TRACE] TAPIWndProc: received WM_ASYNCEVENT, hwnd=x0001003E
[2396] 00:13:05:003: [INFO ] Calling app's callback, hDev=x10106, Msg=2, dwInst=xf1808 P1=x1, P2=x0 P3=x0
[2396] 00:13:05:003: [INFO ] Calling app's callback, hDev=x0, Msg=12, dwInst=xf1808 P1=x10128, P2=x0 P3=x0
[2396] 00:13:05:003: [TRACE] lineDeallocateCall: enter on thread: 0x0000095c
[2396] 00:13:05:003: [INFO ] hCall = 0x00010106
[2396] 00:13:05:003: [TRACE] DoFunc -- enter
[2396] 00:13:05:003: [TRACE] AllocClientResources: enter
[2396] 00:13:05:003: [TRACE] AllocClientResources: exit, returning x0
[2396] 00:13:05:003: [TRACE] DoFunc: back from srv- return code=0x00000000
[2396] 00:13:05:003: [TRACE] DoFunc: result = x0
[2396] 00:13:05:003: [TRACE] No entries - spurious entry.
[2396] 00:13:05:003: [TRACE] TAPIWndProc: received WM_ASYNCEVENT, hwnd=x0001003E
[2396] 00:13:05:003: [TRACE] No entries - spurious entry.
[2396] 00:13:05:003: [TRACE] TAPIWndProc: received WM_ASYNCEVENT, hwnd=x0001003E
[2396] 00:13:05:003: [TRACE] No entries - spurious entry.
RTM.log
[4220] 00:13:03: Dest: 85.141.210.54 Mask: 255.255.255.255
[4220] 00:13:03:
[4220] 00:13:03: Adding Route with address:
[4220] 00:13:03: Dest: 85.141.210.54 Mask: 255.255.255.255
[4220] 00:13:03: Dest = 01193ED8 and Route = 01193E88
[5052] 00:13:04: Entering ProcessChangedDestLists: 5052
[5052] 00:13:04: ProcessChangedDestLists: Number of changed dests: 1
[5052] 00:13:04: Next dest 01193ED8 in list 13:
[5052] 00:13:04: Dest: 85.141.210.54 Mask: 255.255.255.255
[5052] 00:13:04:
[5052] 00:13:04: Notifying CN 0 BEGIN
[5052] 00:13:04: Returning dest 01193ED8 to CN 0:
[5052] 00:13:04: Dest: 85.141.210.54 Mask: 255.255.255.255
[5052] 00:13:04:
[5052] 00:13:04: Notifying CN 0 END
[5052] 00:13:04: Notifying CN 1 BEGIN
[5052] 00:13:04: Returning dest 01193ED8 to CN 1:
[5052] 00:13:04: Dest: 85.141.210.54 Mask: 255.255.255.255
[5052] 00:13:04:
[5052] 00:13:04: Notifying CN 1 END
[5052] 00:13:04: ProcessChangedDestLists: Dests Removed: 1
[5052] 00:13:04: Leaving ProcessChangedDestLists: 5052
[4220] 00:13:05: Deleting Route with address:
[4220] 00:13:05: Dest: 85.141.210.54 Mask: 255.255.255.255
[4220] 00:13:05: Dest = 01193ED8 and Route = 01193E88
[4220] 00:13:05: Adding dest 01193ED8 to change list 13:
[4220] 00:13:05: Dest: 85.141.210.54 Mask: 255.255.255.255
[4220] 00:13:05:
[5052] 00:13:05: Entering ProcessChangedDestLists: 5052
[5052] 00:13:05: ProcessChangedDestLists: Number of changed dests: 1
[5052] 00:13:05: Next dest 01193ED8 in list 13:
[5052] 00:13:05: Dest: 85.141.210.54 Mask: 255.255.255.255
[5052] 00:13:05:
[5052] 00:13:05: Notifying CN 0 BEGIN
[5052] 00:13:05: Returning dest 01193ED8 to CN 0:
[5052] 00:13:05: Dest: 85.141.210.54 Mask: 255.255.255.255
[5052] 00:13:05:
[5052] 00:13:05: Notifying CN 0 END
[5052] 00:13:05: ProcessChangedDestLists: Dests Removed: 1
[5052] 00:13:05: Leaving ProcessChangedDestLists: 5052
RASCHAP.LOG
2548] 10-10 00:13:04:523: ChapBegin(fS=1,bA=0x81)
[2548] 10-10 00:13:04:523: ChapBegin done.
[2548] 10-10 00:13:04:523: ChapMakeMessage,RBuf=00000000
[2548] 10-10 00:13:04:523: CS_Initial...
[2548] 10-10 00:13:04:523: MakeChallengeMessage...
01 00 00 1C 10 39 B0 A9 F9 56 7F FE BE D9 26 5D |.....9...V...&]|
3B F1 56 9B FC 52 55 42 49 4B 4F 4E 00 00 00 00 |;.V..RUBIKON....|
[2548] 10-10 00:13:04:616: ChapMakeMessage,RBuf=01EF392A
[2548] 10-10 00:13:04:616: CS_ChallengeSent...
[2548] 10-10 00:13:04:647: ChapMakeMessage,RBuf=00000000
[2548] 10-10 00:13:04:647: ChapEnd
RASAUTH.LOG
[5052] 00:13:04:616: RasAuthProviderAuthenticateUser called
[5052] 00:13:04:616: Type=4, Length=4, Value=0xc3deba55
[5052] 00:13:04:616: Type=6, Length=4, Value=0x2
[5052] 00:13:04:616: Type=7, Length=4, Value=0x1
[5052] 00:13:04:616: Type=5, Length=4, Value=0x8b
[5052] 00:13:04:616: Type=26, Length=10, Value=
[5052] 00:13:04:616: 00 00 01 37 09 06 00 00 01 37 00 00 00 00 00 00 |...7.....7......|
[5052] 00:13:04:616: Type=26, Length=16, Value=
[5052] 00:13:04:616: 00 00 01 37 12 0C 4D 53 52 41 53 56 35 2E 32 30 |...7..MSRASV5.20|
[5052] 00:13:04:616: Type=61, Length=4, Value=0x5
[5052] 00:13:04:616: Type=64, Length=4, Value=0x1
[5052] 00:13:04:616: Type=65, Length=4, Value=0x1
[5052] 00:13:04:616: Type=31, Length=13, Value=
[5052] 00:13:04:616: 38 35 2E 31 34 31 2E 32 31 30 2E 35 34 00 00 00 |85.141.210.54...|
[5052] 00:13:04:616: Type=66, Length=13, Value=
[5052] 00:13:04:616: 38 35 2E 31 34 31 2E 32 31 30 2E 35 34 00 00 00 |85.141.210.54...|
[5052] 00:13:04:616: Type=1, Length=6, Value=
[5052] 00:13:04:616: 72 75 73 76 70 6E 00 00 00 00 00 00 00 00 00 00 |rusvpn..........|
[5052] 00:13:04:616: Type=26, Length=22, Value=
[5052] 00:13:04:616: 00 00 01 37 0B 12 39 B0 A9 F9 56 7F FE BE D9 26 |...7..9...V...&|
[5052] 00:13:04:616: 5D 3B F1 56 9B FC 00 00 00 00 00 00 00 00 00 00 |];.V............|
[5052] 00:13:04:616: Type=26, Length=56, Value=
[5052] 00:13:04:616: 00 00 01 37 19 34 00 00 92 97 F3 84 7D 0E B8 0E |...7.4......}...|
[5052] 00:13:04:616: E8 C4 D3 81 ED 74 87 A0 00 00 00 00 00 00 00 00 |.....t..........|
[5052] 00:13:04:616: 63 F7 5B D0 6E 08 84 15 14 87 EB A7 9D D8 35 D7 |c.[.n.........5.|
[5052] 00:13:04:616: 36 B8 39 9F B7 91 34 B9 00 00 00 00 00 00 00 00 |6.9...4.........|
[5052] 00:13:04:616: Inserting attribute type 4
[5052] 00:13:04:616: Inserting attribute type 6
[5052] 00:13:04:616: Inserting attribute type 7
[5052] 00:13:04:616: Inserting attribute type 5
[5052] 00:13:04:616: Inserting attribute type 26
[5052] 00:13:04:616: Inserting attribute type 26
[5052] 00:13:04:616: Inserting attribute type 61
[5052] 00:13:04:616: Inserting attribute type 64
[5052] 00:13:04:616: Inserting attribute type 65
[5052] 00:13:04:616: Inserting attribute type 31
[5052] 00:13:04:616: Inserting attribute type 66
[5052] 00:13:04:616: Inserting attribute type 1
[5052] 00:13:04:616: Inserting attribute type 26
[5052] 00:13:04:616: Inserting attribute type 26
[5052] 00:13:04:616: Inserting attribute type 4108
[5052] 00:13:04:647: IASResponse = DISCARD_PACKET. Failurereason=0x9
IASSAM.LOG
[5052] 10-10 00:13:04:616: NT-SAM Names handler received request with user identity rusvpn.
[5052] 10-10 00:13:04:616: Prepending default domain.
[5052] 10-10 00:13:04:616: NameMapper:
rependDefaultDomain
[5052] 10-10 00:13:04:616: SAM-Account-Name is "MASTER\rusvpn".
[5052] 10-10 00:13:04:616: NT-SAM Authentication handler received request for MASTER\rusvpn.
[5052] 10-10 00:13:04:616: Processing MS-CHAP v2 authentication.
[5052] 10-10 00:13:04:631: LogonUser succeeded.
[5052] 10-10 00:13:04:631: NT-SAM User Authorization handler received request for MASTER\rusvpn.
[5052] 10-10 00:13:04:631: Using downlevel dial-in parameters.
[5052] 10-10 00:13:04:631: Sending LDAP search to mars.master.rafinad.ru.
[5052] 10-10 00:13:04:631: LDAP ERROR in ldap_search_ext_sW. Code = 81
[5052] 10-10 00:13:04:631: Extended error string: (null)
[5052] 10-10 00:13:04:631: Retrying LDAP search.
[5052] 10-10 00:13:04:631: Opening LDAP connection to mars.master.rafinad.ru.
[5052] 10-10 00:13:04:647: LDAP connect succeeded.
[5052] 10-10 00:13:04:647: Sending LDAP search to mars.master.rafinad.ru.
[5052] 10-10 00:13:04:647: Inserting attribute msNPAllowDialin.
[5052] 10-10 00:13:04:647: Successfully retrieved per-user attributes.
[5052] 10-10 00:13:04:647: Invoking AuthorizationDLLs
[5052] 10-10 00:13:04:647: Invoking extension vpnplgin.dll
[5052] 10-10 00:13:04:647: RadiusExtensionProcess2 returned 5
[5052] 10-10 00:13:04:647: RADIUS_EXTENSION_CONTROL_BLOCK.SetResponseType(256)
Router.log
[2748] 10-10 00:13:04:089: Rasman state change received from port 139, 1->5
[2748] 10-10 00:13:04:089: Rasman state change received from port 139, 5->2
[2748] 10-10 00:13:04:089: SvDevConnected: Entered, hPort=139
[2748] 10-10 00:13:04:089: TimerQRemove called
[2748] 10-10 00:13:04:430: SvFrameReceived: Entered, hPort: 139
[2748] 10-10 00:13:04:430: SvFrameReceived: PPP frame on port 139
[2548] 10-10 00:13:04:647: ServerSendMessage on port/connection: 8b from: PPP Message: PPPDDMMSG_PppFailure
[2748] 10-10 00:13:04:647: ServerReceiveMessage on port/connection: 8b from: PPP Message: PPPDDMMSG_PppFailure
[2748] 10-10 00:13:04:647: SvPppFailure: Entered, hPort=139, Error=691
[2548] 10-10 00:13:04:709: ServerSendMessage on port/connection: 8b from: PPP Message: PPPDDMMSG_Stopped
[2748] 10-10 00:13:04:709: ServerReceiveMessage on port/connection: 8b from: PPP Message: PPPDDMMSG_Stopped
[2748] 10-10 00:13:04:709: DevStartClosing: Entered, hPort=139
[2748] 10-10 00:13:04:709: RmDisconnect
isconnect posted on port 139
[2748] 10-10 00:13:04:709: RasPortDisconnect rc=600
[2748] 10-10 00:13:04:709: TimerQRemove called
[2748] 10-10 00:13:04:709: TimerQRemove called
[2748] 10-10 00:13:04:709: TimerQRemove called
[2748] 10-10 00:13:04:709: DevCloseComplete:hPort=139,Auth=0,Rcv=0,Conn=1 1,Sec=3 2,Ppp=0
[2748] 10-10 00:13:05:003: Rasman state change received from port 139, 3->4
[2748] 10-10 00:13:05:003: SvDevDisconnected:Entered, hPort=139
[2748] 10-10 00:13:05:003: DevCloseComplete:hPort=139,Auth=0,Rcv=0,Conn=1 0,Sec=4 2,Ppp=0
[2748] 10-10 00:13:05:003: RmListen: Listen posted on port 139
[2548] 10-10 00:13:05:003: ServerSendMessage on port/connection: 8b from: PPP Message: PPPDDMMSG_PortCleanedUp
[2748] 10-10 00:13:05:003: RasPortListen dwRetCode=600
[2748] 10-10 00:13:05:003: ServerReceiveMessage on port/connection: 8b from: PPP Message: PPPDDMMSG_PortCleanedUp
RASTAPI.LOG
[2396] 10-10 00:13:04:089: RasTapicallback: msg=23 , param1=0l , param2=65798l
[2396] 10-10 00:13:04:089: RasTapicallback: msg=2 , param1=2l , param2=0l
[2396] 10-10 00:13:04:089: RasTapicallback: linecallstate=0x2
[2396] 10-10 00:13:04:089: DwProcessOfferEvent: hcall=0x10106
[2396] 10-10 00:13:04:089: DwProcessOfferEvent: Accepting call on VPN5-127 hcall = 0x10106
[2396] 10-10 00:13:04:089: WAN Miniport (PPTP) InClients=1, TotalDialInClients=1
[2396] 10-10 00:13:04:089: DwProcessOfferEvent 0x0
[2356] 10-10 00:13:04:089: DeviceWork: VPN5-127. State = 2
[2356] 10-10 00:13:04:089: DeviceWork: VPN5-127. lineAccept returned 0x103b2
[2396] 10-10 00:13:04:089: RasTapicallback: msg=12 , param1=66482l , param2=2147483720l
[2396] 10-10 00:13:04:089: LINE_REPLY. param1=0x103b2
[2396] 10-10 00:13:04:089: RasTapiCallback: Changing Listen State for VPN5-127 from 2 -> 3
[2356] 10-10 00:13:04:089: DeviceWork: VPN5-127. State = 2
[2356] 10-10 00:13:04:089: DeviceWork: VPN5-127. lineAnswer returned 0x103a1
[2396] 10-10 00:13:04:089: RasTapicallback: msg=2 , param1=256l , param2=0l
[2396] 10-10 00:13:04:089: RasTapicallback: linecallstate=0x100
[2396] 10-10 00:13:04:089: DwGetConnectInfo
[2396] 10-10 00:13:04:089: DwGetIDInformation
[2396] 10-10 00:13:04:089: DwGetIDInformation. 0
[2396] 10-10 00:13:04:089: SizeRequired for CallID=16
[2396] 10-10 00:13:04:089: DwGetIDInformation
[2396] 10-10 00:13:04:089: GetIDInformation: CallerID=85.141.210.54
[2396] 10-10 00:13:04:089: RasTapiCallback: called id info. not avail
[2396] 10-10 00:13:04:089: DwGetIDInformation. 0
[2396] 10-10 00:13:04:089: DwGetConnectInfo. 0x0
[2396] 10-10 00:13:04:089: RasTapiCallback: DwGetConnectInforeturned 0x0
[2396] 10-10 00:13:04:089: RasTapiCallback: Connected on VPN5-127
[2396] 10-10 00:13:04:089: RasTapiCallback: Incoming Call
[2356] 10-10 00:13:04:089: DeviceWork: VPN5-127. State = 2
[2356] 10-10 00:13:04:089: DeviceWork: Changing State for VPN5-127 from 2 -> 3
[2396] 10-10 00:13:04:089: RasTapicallback: msg=12 , param1=66465l , param2=0l
[2396] 10-10 00:13:04:089: LINE_REPLY. param1=0x103a1
[2748] 10-10 00:13:04:089: PortConnect: VPN5-127
[2748] 10-10 00:13:04:089:
[2748] 10-10 00:13:04:709: PortDisconnect: VPN5-127
[2748] 10-10 00:13:04:709: InitiatePortDisconnection: VPN5-127
[2748] 10-10 00:13:04:709: WAN Miniport (PPTP) InClients=0, TotalDialInClients=0
[2748] 10-10 00:13:04:709: InitiatePortDisconnection: Changing state for VPN5-127 from 3 -> 5, id=0x10128
[2748] 10-10 00:13:04:709:
[2748] 10-10 00:13:04:709:
[2396] 10-10 00:13:05:003: RasTapicallback: msg=2 , param1=1l , param2=0l
[2396] 10-10 00:13:05:003: RasTapicallback: linecallstate=0x1
[2396] 10-10 00:13:05:003: RasTapicallback: msg=12 , param1=65832l , param2=0l
[2396] 10-10 00:13:05:003: LINE_REPLY. param1=0x10128
[2396] 10-10 00:13:05:003: RasTapiCallback: lineDropped. port VPN5-127, id=0xffffffff
[2396] 10-10 00:13:05:003: RasTapiCallback: Idle Received for port VPN5-127
[2396] 10-10 00:13:05:003: RasTapiCallback: changing state of VPN5-127. 5 -> 1
[2396] 10-10 00:13:05:003: RasTapiCallback: lineDeallocateCall for VPN5-127,hcall = 0x10106
[2356] 10-10 00:13:05:003: PortTestSignalState: DeviceState = 0
[2748] 10-10 00:13:05:003: DeviceListen: Changing State for VPN5-127 from 1 -> 2
[2748] 10-10 00:13:05:003: DeviceListen: Changing Listen State for VPN5-127 from 4 -> 2
[2748] 10-10 00:13:05:003:
Hope that's enough to find the key.
Thanks in advanse
Basfa
We have ISA server which is working as firewall, proxy and vpn server.
Everything was working fine for year, but starting this monday our users are unable to connect to VPN. They are getting error 691 and there is event id 20014 on the server.
I tried to recreate RRAS and create new user with dial-in permission, but problem still the same.
Surfing the internet and this site didn't provide me solution. Please help!!!!
Here is some ISA log to clarify:
IPRouterManager.LOG
5052] 00:13:04: Error adding route, Stack bit == 0
[5052] 00:13:04: ProcessDefaultRouteChanges: Not default route 85.141.210.54/32
[4220] 00:13:07: HandleSolicitations: Received 60 bytes on 209.60.18.12
[4220] 00:13:37: HandleSolicitations: Received 60 bytes on 209.60.18.12
[4220] 00:14:07: HandleSolicitations: Received 60 bytes on 209.60.18.12
[4220] 00:14:28: HandleSolicitations: Received 28 bytes on 209.60.18.12
[4220] 00:14:36: HandleSolicitations: Received 60 bytes on 209.60.18.12
tapisrv.log
[2452] 00:13:04:089: [INFO ] LineEventProcSP: HTapiLine=00010346, HTapiCall=00000000, msg=1f4, P1=x7e0004, P2=x98770, P3=x0
[2452] 00:13:04:089: [TRACE] LineEventProc
[2452] 00:13:04:089: [TRACE] CreatetCall: enter, ptLine=009E7308
[2452] 00:13:04:089: [INFO ] CreatetCall: calling NewObject ptCall 009E74C0
[2452] 00:13:04:089: [TRACE] CreatetCall: NewObject returned 0x102f5
[2452] 00:13:04:089: [TRACE] CreatetCall: exit, new ptCall=009E74C0
[2452] 00:13:04:089: [INFO ] LineEventProcSP: HTapiLine=00010346, HTapiCall=000102F5, msg=2, P1=x2, P2=x0, P3=x100
[2276] 00:13:04:089: [INFO ] Got a line spevent, htLine = 0x10346, htCall = 0x102f5, dwMsg = 0x2
[2276] 00:13:04:089: [TRACE] LineEventProc
[2276] 00:13:04:089: [EVENT] LineEventProc: LINE_CALLSTATE event x2
[2276] 00:13:04:089: [TRACE] CreatetCallClient: enter, ptCall=009E74C0,
[2276] 00:13:04:089: [INFO ] CreatetCallClient: calling NewObject, ptCallClient = [009E753C]
[2276] 00:13:04:089: [TRACE] CreatetCallClient: exit, new ptCallClient=009E753C
[2276] 00:13:04:089: [INFO ] LineEventProc: i = [0] corresponding ptCallClient [009E753C]
[2276] 00:13:04:089: [INFO ] LineEventProc: ptCallClient->ptLineClient[009E7220]
[2276] 00:13:04:089: [INFO ] LineEventProc: ptLineClient->ptLineApp[00552CC0]
[2276] 00:13:04:089: [INFO ] LineEventProc: setting msg->InitContext to ptLineApp[00552CC0]->InitContext of [800003FF]
[2276] 00:13:04:089: [INFO ] LineEventProc: setting msg->OpenContext to [80000233]
[2276] 00:13:04:089: [INFO ] FMsgDisbled: dwAPIVersion<= TAPI_VERSION3_0, msg will be enabled
[2276] 00:13:04:089: [TRACE] FMsgDisabled return 0
[2276] 00:13:04:089: [INFO ] LineEventProc: sending LINE_APPNEWCALL, ptClient[00552690]
[2276] 00:13:04:089: [TRACE] WriteEventBuffer - enter
[2276] 00:13:04:089: [TRACE] WriteEventBuffer: SetEvent 0000011C for local client
[2276] 00:13:04:089: [INFO ] FMsgDisbled: dwAPIVersion<= TAPI_VERSION3_0, msg will be enabled
[2276] 00:13:04:089: [TRACE] FMsgDisabled return 0
[2276] 00:13:04:089: [TRACE] WriteEventBuffer - enter
[2276] 00:13:04:089: [TRACE] WriteEventBuffer: SetEvent 0000011C for local client
[5620] 00:13:04:089: [TRACE] GetAsyncEvents: enter (TID=5620)
[5620] 00:13:04:089: [INFO ] M ebfused:x60 pEvtBuf: 0x005527A0 pDataOut:0x005527A0 pDataIn:0x00552800
[5620] 00:13:04:089: [TRACE] GetAsyncEvents: return dwUsedBufferSize:x60
[5620] 00:13:04:089: [TRACE] LineProlog: -- enter
[5620] 00:13:04:089: [INFO ] LineProlog: dwArg 10106
[5620] 00:13:04:089: [INFO ] LineProlog: ANY_RT_HCALL
[5620] 00:13:04:089: [INFO ] LineProlog: ReferenceObject returned ptCallClient 009E753C
[5620] 00:13:04:089: [TRACE] LienProlog: exit, result = x0
[5620] 00:13:04:089: [TRACE] LineEpilogSync: exit, result=x0
[5620] 00:13:04:089: [TRACE] LineProlog: -- enter
[5620] 00:13:04:089: [INFO ] LineProlog: dwArg 10106
[5620] 00:13:04:089: [INFO ] LineProlog: ANY_RT_HCALL
[5620] 00:13:04:089: [INFO ] LineProlog: ReferenceObject returned ptCallClient 009E753C
[5620] 00:13:04:089: [INFO ] LineProlog: OpenContext 80000233
[5620] 00:13:04:089: [TRACE] LienProlog: exit, result = x103b2
[5620] 00:13:04:089: [TRACE] LineEpilogAsyc: exit, result=x103b2
[2452] 00:13:04:089: [TRACE] CompletionProcSP: enter, dwReqID=x103b2, lResult=x80000048
[2276] 00:13:04:089: [INFO ] Got an async completion event, requestID = 0x103b2, htXxx = 0x10346, lResult = 0x80000048
[2276] 00:13:04:089: [TRACE] CompletionProc: enter, dwReqID=x103b2, lResult=x80000048
[2276] 00:13:04:089: [TRACE] WriteEventBuffer - enter
[2276] 00:13:04:089: [TRACE] WriteEventBuffer: SetEvent 0000011C for local client
[5788] 00:13:04:089: [TRACE] GetAsyncEvents: enter (TID=5788)
[5788] 00:13:04:089: [INFO ] M ebfused:x28 pEvtBuf: 0x005527A0 pDataOut:0x005527A0 pDataIn:0x005527C8
[5788] 00:13:04:089: [TRACE] GetAsyncEvents: return dwUsedBufferSize:x28
[5620] 00:13:04:089: [TRACE] LineProlog: -- enter
[5620] 00:13:04:089: [INFO ] LineProlog: dwArg 10106
[5620] 00:13:04:089: [INFO ] LineProlog: ANY_RT_HCALL
[5620] 00:13:04:089: [INFO ] LineProlog: ReferenceObject returned ptCallClient 009E753C
[5620] 00:13:04:089: [INFO ] LineProlog: OpenContext 80000233
[5620] 00:13:04:089: [TRACE] LienProlog: exit, result = x103a1
[5620] 00:13:04:089: [TRACE] LineEpilogAsyc: exit, result=x103a1
[2452] 00:13:04:089: [INFO ] LineEventProcSP: HTapiLine=00010346, HTapiCall=000102F5, msg=2, P1=x100, P2=x0, P3=x100
[2276] 00:13:04:089: [INFO ] Got a line spevent, htLine = 0x10346, htCall = 0x102f5, dwMsg = 0x2
[2276] 00:13:04:089: [TRACE] LineEventProc
[2276] 00:13:04:089: [EVENT] LineEventProc: LINE_CALLSTATE event x100
[2276] 00:13:04:089: [INFO ] LineEventProc: i = [0] corresponding ptCallClient [009E753C]
[2276] 00:13:04:089: [INFO ] LineEventProc: ptCallClient->ptLineClient[009E7220]
[2276] 00:13:04:089: [INFO ] LineEventProc: ptLineClient->ptLineApp[00552CC0]
[2276] 00:13:04:089: [INFO ] LineEventProc: setting msg->InitContext to ptLineApp[00552CC0]->InitContext of [800003FF]
[2276] 00:13:04:089: [INFO ] LineEventProc: setting msg->OpenContext to [80000233]
[2276] 00:13:04:089: [INFO ] FMsgDisbled: dwAPIVersion<= TAPI_VERSION3_0, msg will be enabled
[2276] 00:13:04:089: [TRACE] FMsgDisabled return 0
[2276] 00:13:04:089: [TRACE] WriteEventBuffer - enter
[2276] 00:13:04:089: [TRACE] WriteEventBuffer: SetEvent 0000011C for local client
[5788] 00:13:04:089: [TRACE] GetAsyncEvents: enter (TID=5788)
[2452] 00:13:04:089: [TRACE] CompletionProcSP: enter, dwReqID=x103a1, lResult=x0
[5788] 00:13:04:089: [INFO ] M ebfused:x2c pEvtBuf: 0x005527A0 pDataOut:0x005527A0 pDataIn:0x005527CC
[2276] 00:13:04:089: [INFO ] Got an async completion event, requestID = 0x103a1, htXxx = 0x10346, lResult = 0x0
[5788] 00:13:04:089: [TRACE] GetAsyncEvents: return dwUsedBufferSize:x2c
[2276] 00:13:04:089: [TRACE] CompletionProc: enter, dwReqID=x103a1, lResult=x0
[2276] 00:13:04:089: [TRACE] WriteEventBuffer - enter
[2276] 00:13:04:089: [TRACE] WriteEventBuffer: SetEvent 0000011C for local client
[5620] 00:13:04:089: [TRACE] GetAsyncEvents: enter (TID=5620)
[5620] 00:13:04:089: [INFO ] M ebfused:x28 pEvtBuf: 0x005527A0 pDataOut:0x005527A0 pDataIn:0x005527C8
[5620] 00:13:04:089: [TRACE] GetAsyncEvents: return dwUsedBufferSize:x28
[5788] 00:13:04:089: [TRACE] LineProlog: -- enter
[5788] 00:13:04:089: [INFO ] LineProlog: dwArg 10106
[5788] 00:13:04:089: [INFO ] LineProlog: ANY_RT_HCALL
[5788] 00:13:04:089: [INFO ] LineProlog: ReferenceObject returned ptCallClient 009E753C
[5788] 00:13:04:089: [TRACE] LienProlog: exit, result = x0
[5788] 00:13:04:089: [TRACE] LineEpilogSync: exit, result=x0
[5788] 00:13:04:089: [TRACE] LineProlog: -- enter
[5788] 00:13:04:089: [INFO ] LineProlog: dwArg 10106
[5788] 00:13:04:089: [INFO ] LineProlog: ANY_RT_HCALL
[5788] 00:13:04:089: [INFO ] LineProlog: ReferenceObject returned ptCallClient 009E753C
[5788] 00:13:04:089: [TRACE] LienProlog: exit, result = x0
[5788] 00:13:04:089: [TRACE] LineEpilogSync: exit, result=x0
[5788] 00:13:04:089: [TRACE] LineProlog: -- enter
[5788] 00:13:04:089: [INFO ] LineProlog: dwArg 10106
[5788] 00:13:04:089: [INFO ] LineProlog: ANY_RT_HCALL
[5788] 00:13:04:089: [INFO ] LineProlog: ReferenceObject returned ptCallClient 009E753C
[5788] 00:13:04:089: [TRACE] LienProlog: exit, result = x0
[5788] 00:13:04:089: [TRACE] LineEpilogSync: exit, result=x0
[5620] 00:13:04:709: [TRACE] LineProlog: -- enter
[5620] 00:13:04:709: [INFO ] LineProlog: dwArg 10106
[5620] 00:13:04:709: [INFO ] LineProlog: ANY_RT_HCALL
[5620] 00:13:04:709: [INFO ] LineProlog: ReferenceObject returned ptCallClient 009E753C
[5620] 00:13:04:709: [INFO ] LineProlog: OpenContext 80000233
[5620] 00:13:04:709: [TRACE] LienProlog: exit, result = x10128
[5620] 00:13:04:709: [TRACE] LineEpilogAsyc: exit, result=x10128
[2452] 00:13:05:003: [INFO ] LineEventProcSP: HTapiLine=00010346, HTapiCall=000102F5, msg=2, P1=x1, P2=x0, P3=x0
[2276] 00:13:05:003: [INFO ] Got a line spevent, htLine = 0x10346, htCall = 0x102f5, dwMsg = 0x2
[2276] 00:13:05:003: [TRACE] LineEventProc
[2276] 00:13:05:003: [EVENT] LineEventProc: LINE_CALLSTATE event x1
[2276] 00:13:05:003: [INFO ] LineEventProc: i = [0] corresponding ptCallClient [009E753C]
[2276] 00:13:05:003: [INFO ] LineEventProc: ptCallClient->ptLineClient[009E7220]
[2452] 00:13:05:003: [TRACE] CompletionProcSP: enter, dwReqID=x10128, lResult=x0
[2276] 00:13:05:003: [INFO ] LineEventProc: ptLineClient->ptLineApp[00552CC0]
[2276] 00:13:05:003: [INFO ] LineEventProc: setting msg->InitContext to ptLineApp[00552CC0]->InitContext of [800003FF]
[2276] 00:13:05:003: [INFO ] LineEventProc: setting msg->OpenContext to [80000233]
[2276] 00:13:05:003: [INFO ] FMsgDisbled: dwAPIVersion<= TAPI_VERSION3_0, msg will be enabled
[2276] 00:13:05:003: [TRACE] FMsgDisabled return 0
[2276] 00:13:05:003: [TRACE] WriteEventBuffer - enter
[2276] 00:13:05:003: [TRACE] WriteEventBuffer: SetEvent 0000011C for local client
[2276] 00:13:05:003: [INFO ] Got an async completion event, requestID = 0x10128, htXxx = 0x10346, lResult = 0x0
[2276] 00:13:05:003: [TRACE] CompletionProc: enter, dwReqID=x10128, lResult=x0
[2276] 00:13:05:003: [TRACE] WriteEventBuffer - enter
[2276] 00:13:05:003: [TRACE] WriteEventBuffer: SetEvent 0000011C for local client
[5788] 00:13:05:003: [TRACE] GetAsyncEvents: enter (TID=5788)
[5788] 00:13:05:003: [INFO ] M ebfused:x54 pEvtBuf: 0x005527A0 pDataOut:0x005527A0 pDataIn:0x005527F4
[5788] 00:13:05:003: [TRACE] GetAsyncEvents: return dwUsedBufferSize:x54
[5620] 00:13:05:003: [TRACE] LineProlog: -- enter
[5620] 00:13:05:003: [INFO ] LineProlog: dwArg 10106
[5620] 00:13:05:003: [INFO ] LineProlog: ANY_RT_HCALL
[5620] 00:13:05:003: [INFO ] LineProlog: ReferenceObject returned ptCallClient 009E753C
[5620] 00:13:05:003: [TRACE] LienProlog: exit, result = x0
[5620] 00:13:05:003: [TRACE] DestroytCallClient: enter, ptCallCli=x009E753C
[5620] 00:13:05:003: [TRACE] DestroytCall: enter, ptCall=x009E74C0
[5620] 00:13:05:003: [TRACE] LineEpilogSync: exit, result=x0
RASMAN.LOG
[2356] 10-10 00:13:04:089: WorkerThread: Async work event signaled on port: VPN5-127
[2356] 10-10 00:13:04:089: OVEVT_DEV_ASYNCOP. pOverlapped = 0x27b0df0
[2356] 10-10 00:13:04:089: ServiceWorkRequest: Async op event 27 for port VPN5-127 returned 600
[2356] 10-10 00:13:04:089: WorkerThread: Async work event signaled on port: VPN5-127
[2356] 10-10 00:13:04:089: OVEVT_DEV_ASYNCOP. pOverlapped = 0x27b0df0
[2356] 10-10 00:13:04:089: ServiceWorkRequest: Async op event 27 for port VPN5-127 returned 600
[2356] 10-10 00:13:04:089: WorkerThread: Async work event signaled on port: VPN5-127
[2356] 10-10 00:13:04:089: OVEVT_DEV_ASYNCOP. pOverlapped = 0x27b0df0
[2356] 10-10 00:13:04:089: d:\srv03rtm\net\rras\ras\rasman\rasman\request.c: 7507: port 139 state chg: prev=1, new=5
[2356] 10-10 00:13:04:089: RasmanReceiveFlags = 0x0
[2356] 10-10 00:13:04:089: d:\srv03rtm\net\rras\ras\rasman\rasman\worker.c: 2269: port 139 async reqtype chg: prev=27, new=0
[2356] 10-10 00:13:04:089: ServiceWorkRequest: Async op event 27 for port VPN5-127 returned 0
[2748] 10-10 00:13:04:089: ConnectCompleteRequest: entered for port 139
[2748] 10-10 00:13:04:089: d:\srv03rtm\net\rras\ras\rasman\rasman\request.c: 7401: port 139 state chg: prev=5, new=2
[2748] 10-10 00:13:04:089: AllocBundle: pBundle=0x4f172c8
[2748] 10-10 00:13:04:089: d:\srv03rtm\net\rras\ras\rasman\rasman\request.c 8901: Mapping Cookie to handle. port = VPN5-127(0xbaaa7b8), Bundlehandle = 0x27, linkhandle = 0x27
[2748] 10-10 00:13:04:089: Connection Completed on port: VPN5-127, error code: 0
[2748] 10-10 00:13:04:089: d:\srv03rtm\net\rras\ras\rasman\rasman\request.c: 6654: port 139 async reqtype chg: prev=0, new=26
[2356] 10-10 00:13:04:430: Completed receive - First Frame on VPN5-127, handle=0x1240
[2548] 10-10 00:13:04:430: GetConnectInfo: port VPN5-127
[2548] 10-10 00:13:04:430: GetConnectInfo: size=52, rc=0xx0
[2548] 10-10 00:13:04:430: GetConnectInfo: port VPN5-127
[2548] 10-10 00:13:04:430: GetConnectInfo: size=52, rc=0xx0
[2548] 10-10 00:13:04:430: GetConnectInfo: port VPN5-127
[2548] 10-10 00:13:04:430: GetConnectInfo: size=52, rc=0xx0
[2548] 10-10 00:13:04:430: GetConnectInfo: port VPN5-127
[2548] 10-10 00:13:04:430: GetConnectInfo: size=52, rc=0xx0
[2548] 10-10 00:13:04:430: PppStarted...VPN5-127
[2748] 10-10 00:13:04:709: PortDisconnectRequest on VPN5-127 Connection=0x0 ,RasmanReceiveFlags=0x4
[2748] 10-10 00:13:04:709: PortDisconnectRequest: Disconnecting VPN5-127
[2748] 10-10 00:13:04:709: Disconnecting Port 0xVPN5-127, reason 0
[2748] 10-10 00:13:04:709: DisconnectPort: Saving Bundle stats for port VPN5-127
[2748] 10-10 00:13:04:709: d:\srv03rtm\net\rras\ras\rasman\rasman\util.c 1992: Disconnected Port 139, reason 0. rc=0x258
[2748] 10-10 00:13:04:709: FreeBundle: freeing pBundle=0x4f172c8
[2748] 10-10 00:13:04:709: d:\srv03rtm\net\rras\ras\rasman\rasman\util.c: 2213: port 139 state chg: prev=2, new=3
[2748] 10-10 00:13:04:709: d:\srv03rtm\net\rras\ras\rasman\rasman\util.c: 2283: port 139 async reqtype chg: prev=26, new=9
[2748] 10-10 00:13:04:709: Disconnect request on port: VPN5-127
[2356] 10-10 00:13:04:709: OVEVT_RASMAN_ADJUST_TIMER
[2356] 10-10 00:13:04:709: OVEVT_RASMAN_ADJUST_TIMER
[2356] 10-10 00:13:05:003: WorkerThread: Disconnect event signaled on port: VPN5-127
[2356] 10-10 00:13:05:003: OVEVT_DEV_STATECHANGE. pOverlapped = 0x27b0e30
[2356] 10-10 00:13:05:003: d:\srv03rtm\net\rras\ras\rasman\rasman\request.c: 4702: port 139 state chg: prev=3, new=4
[2356] 10-10 00:13:05:003: d:\srv03rtm\net\rras\ras\rasman\rasman\request.c: 4713: port 139 async reqtype chg: prev=9, new=0
[2356] 10-10 00:13:05:003: CompleteDisconnectRequest: signalling 0xde4 for VPN5-127
[2356] 10-10 00:13:05:003: Disconnect completed on port: VPN5-127
[2748] 10-10 00:13:05:003: DeviceListenRequest: Clearing Autoclose flag on port VPN5-127
[2748] 10-10 00:13:05:003: d:\srv03rtm\net\rras\ras\rasman\rasman\util.c: 2547: port 139 state chg: prev=4, new=1
[2748] 10-10 00:13:05:003: d:\srv03rtm\net\rras\ras\rasman\rasman\util.c: 2578: port 139 async reqtype chg: prev=0, new=27
[2748] 10-10 00:13:05:003: Listen posted on port: VPN5-127, error code 600
tapi32.log
[2484] 00:13:04:089: [INFO ] AsyncEventsThread: msg=23, hDev=x10357, p1=x0, p2=x10106, p3=x4
[2484] 00:13:04:089: [INFO ] AsyncEventsThread: posting msg, hwnd=x1003e
[2484] 00:13:04:089: [INFO ] AsyncEventsThread: msg=2, hDev=x10106, p1=x2, p2=x0, p3=x0
[2396] 00:13:04:089: [TRACE] TAPIWndProc: received WM_ASYNCEVENT, hwnd=x0001003E
[2396] 00:13:04:089: [INFO ] Calling app's callback, hDev=x10357, Msg=23, dwInst=xf1808 P1=x0, P2=x10106 P3=x4
[2396] 00:13:04:089: [INFO ] Calling app's callback, hDev=x10106, Msg=2, dwInst=xf1808 P1=x2, P2=x0 P3=x0
[2396] 00:13:04:089: [TRACE] DoFunc -- enter
[2396] 00:13:04:089: [TRACE] AllocClientResources: enter
[2396] 00:13:04:089: [TRACE] AllocClientResources: exit, returning x0
[2396] 00:13:04:089: [TRACE] DoFunc: back from srv- return code=0x00000000
[2396] 00:13:04:089: [TRACE] DoFunc: result = x0
[2396] 00:13:04:089: [TRACE] No entries - spurious entry.
[2396] 00:13:04:089: [TRACE] TAPIWndProc: received WM_ASYNCEVENT, hwnd=x0001003E
[2356] 00:13:04:089: [TRACE] DoFunc -- enter
[2396] 00:13:04:089: [TRACE] No entries - spurious entry.
[2356] 00:13:04:089: [TRACE] AllocClientResources: enter
[2396] 00:13:04:089: [TRACE] TAPIWndProc: received WM_ASYNCEVENT, hwnd=x0001003E
[2396] 00:13:04:089: [TRACE] No entries - spurious entry.
[2356] 00:13:04:089: [TRACE] AllocClientResources: exit, returning x0
[2356] 00:13:04:089: [TRACE] DoFunc: back from srv- return code=0x000103b2
[2356] 00:13:04:089: [TRACE] DoFunc: result = x103b2
[2484] 00:13:04:089: [INFO ] AsyncEventsThread: msg=12, hDev=x0, p1=x103b2, p2=x80000048, p3=x0
[2484] 00:13:04:089: [INFO ] AsyncEventsThread: posting msg, hwnd=x1003e
[2396] 00:13:04:089: [TRACE] TAPIWndProc: received WM_ASYNCEVENT, hwnd=x0001003E
[2396] 00:13:04:089: [INFO ] Calling app's callback, hDev=x0, Msg=12, dwInst=xf1808 P1=x103b2, P2=x80000048 P3=x0
[2396] 00:13:04:089: [TRACE] No entries - spurious entry.
[2356] 00:13:04:089: [TRACE] DoFunc -- enter
[2356] 00:13:04:089: [TRACE] AllocClientResources: enter
[2356] 00:13:04:089: [TRACE] AllocClientResources: exit, returning x0
[2356] 00:13:04:089: [TRACE] DoFunc: back from srv- return code=0x000103a1
[2356] 00:13:04:089: [TRACE] DoFunc: result = x103a1
[2484] 00:13:04:089: [INFO ] AsyncEventsThread: msg=2, hDev=x10106, p1=x100, p2=x0, p3=x0
[2484] 00:13:04:089: [INFO ] AsyncEventsThread: posting msg, hwnd=x1003e
[2396] 00:13:04:089: [TRACE] TAPIWndProc: received WM_ASYNCEVENT, hwnd=x0001003E
[2396] 00:13:04:089: [INFO ] Calling app's callback, hDev=x10106, Msg=2, dwInst=xf1808 P1=x100, P2=x0 P3=x0
[2484] 00:13:04:089: [INFO ] AsyncEventsThread: msg=12, hDev=x0, p1=x103a1, p2=x0, p3=x0
[2484] 00:13:04:089: [INFO ] AsyncEventsThread: posting msg, hwnd=x1003e
[2396] 00:13:04:089: [TRACE] DoFunc -- enter
[2396] 00:13:04:089: [TRACE] AllocClientResources: enter
[2396] 00:13:04:089: [TRACE] AllocClientResources: exit, returning x0
[2396] 00:13:04:089: [TRACE] DoFunc: back from srv- return code=0x00000000
[2396] 00:13:04:089: [TRACE] DoFunc: result = x0
[2396] 00:13:04:089: [INFO ] Calling app's callback, hDev=x0, Msg=12, dwInst=xf1808 P1=x103a1, P2=x0 P3=x0
[2396] 00:13:04:089: [TRACE] No entries - spurious entry.
[2396] 00:13:04:089: [TRACE] TAPIWndProc: received WM_ASYNCEVENT, hwnd=x0001003E
[2396] 00:13:04:089: [TRACE] No entries - spurious entry.
[2748] 00:13:04:089: [TRACE] DoFunc -- enter
[2748] 00:13:04:089: [TRACE] AllocClientResources: enter
[2748] 00:13:04:089: [TRACE] AllocClientResources: exit, returning x0
[2748] 00:13:04:089: [TRACE] DoFunc: back from srv- return code=0x00000000
[2748] 00:13:04:089: [TRACE] DoFunc: result = x0
[2748] 00:13:04:089: [TRACE] DoFunc -- enter
[2748] 00:13:04:089: [TRACE] AllocClientResources: enter
[2748] 00:13:04:089: [TRACE] AllocClientResources: exit, returning x0
[2748] 00:13:04:089: [TRACE] DoFunc: back from srv- return code=0x00000000
[2748] 00:13:04:089: [TRACE] DoFunc: result = x0
[2748] 00:13:04:709: [TRACE] DoFunc -- enter
[2748] 00:13:04:709: [TRACE] AllocClientResources: enter
[2748] 00:13:04:709: [TRACE] AllocClientResources: exit, returning x0
[2748] 00:13:04:709: [TRACE] DoFunc: back from srv- return code=0x00010128
[2748] 00:13:04:709: [TRACE] DoFunc: result = x10128
[2484] 00:13:05:003: [INFO ] AsyncEventsThread: msg=2, hDev=x10106, p1=x1, p2=x0, p3=x0
[2484] 00:13:05:003: [INFO ] AsyncEventsThread: posting msg, hwnd=x1003e
[2484] 00:13:05:003: [INFO ] AsyncEventsThread: msg=12, hDev=x0, p1=x10128, p2=x0, p3=x0
[2396] 00:13:05:003: [TRACE] TAPIWndProc: received WM_ASYNCEVENT, hwnd=x0001003E
[2396] 00:13:05:003: [INFO ] Calling app's callback, hDev=x10106, Msg=2, dwInst=xf1808 P1=x1, P2=x0 P3=x0
[2396] 00:13:05:003: [INFO ] Calling app's callback, hDev=x0, Msg=12, dwInst=xf1808 P1=x10128, P2=x0 P3=x0
[2396] 00:13:05:003: [TRACE] lineDeallocateCall: enter on thread: 0x0000095c
[2396] 00:13:05:003: [INFO ] hCall = 0x00010106
[2396] 00:13:05:003: [TRACE] DoFunc -- enter
[2396] 00:13:05:003: [TRACE] AllocClientResources: enter
[2396] 00:13:05:003: [TRACE] AllocClientResources: exit, returning x0
[2396] 00:13:05:003: [TRACE] DoFunc: back from srv- return code=0x00000000
[2396] 00:13:05:003: [TRACE] DoFunc: result = x0
[2396] 00:13:05:003: [TRACE] No entries - spurious entry.
[2396] 00:13:05:003: [TRACE] TAPIWndProc: received WM_ASYNCEVENT, hwnd=x0001003E
[2396] 00:13:05:003: [TRACE] No entries - spurious entry.
[2396] 00:13:05:003: [TRACE] TAPIWndProc: received WM_ASYNCEVENT, hwnd=x0001003E
[2396] 00:13:05:003: [TRACE] No entries - spurious entry.
RTM.log
[4220] 00:13:03: Dest: 85.141.210.54 Mask: 255.255.255.255
[4220] 00:13:03:
[4220] 00:13:03: Adding Route with address:
[4220] 00:13:03: Dest: 85.141.210.54 Mask: 255.255.255.255
[4220] 00:13:03: Dest = 01193ED8 and Route = 01193E88
[5052] 00:13:04: Entering ProcessChangedDestLists: 5052
[5052] 00:13:04: ProcessChangedDestLists: Number of changed dests: 1
[5052] 00:13:04: Next dest 01193ED8 in list 13:
[5052] 00:13:04: Dest: 85.141.210.54 Mask: 255.255.255.255
[5052] 00:13:04:
[5052] 00:13:04: Notifying CN 0 BEGIN
[5052] 00:13:04: Returning dest 01193ED8 to CN 0:
[5052] 00:13:04: Dest: 85.141.210.54 Mask: 255.255.255.255
[5052] 00:13:04:
[5052] 00:13:04: Notifying CN 0 END
[5052] 00:13:04: Notifying CN 1 BEGIN
[5052] 00:13:04: Returning dest 01193ED8 to CN 1:
[5052] 00:13:04: Dest: 85.141.210.54 Mask: 255.255.255.255
[5052] 00:13:04:
[5052] 00:13:04: Notifying CN 1 END
[5052] 00:13:04: ProcessChangedDestLists: Dests Removed: 1
[5052] 00:13:04: Leaving ProcessChangedDestLists: 5052
[4220] 00:13:05: Deleting Route with address:
[4220] 00:13:05: Dest: 85.141.210.54 Mask: 255.255.255.255
[4220] 00:13:05: Dest = 01193ED8 and Route = 01193E88
[4220] 00:13:05: Adding dest 01193ED8 to change list 13:
[4220] 00:13:05: Dest: 85.141.210.54 Mask: 255.255.255.255
[4220] 00:13:05:
[5052] 00:13:05: Entering ProcessChangedDestLists: 5052
[5052] 00:13:05: ProcessChangedDestLists: Number of changed dests: 1
[5052] 00:13:05: Next dest 01193ED8 in list 13:
[5052] 00:13:05: Dest: 85.141.210.54 Mask: 255.255.255.255
[5052] 00:13:05:
[5052] 00:13:05: Notifying CN 0 BEGIN
[5052] 00:13:05: Returning dest 01193ED8 to CN 0:
[5052] 00:13:05: Dest: 85.141.210.54 Mask: 255.255.255.255
[5052] 00:13:05:
[5052] 00:13:05: Notifying CN 0 END
[5052] 00:13:05: ProcessChangedDestLists: Dests Removed: 1
[5052] 00:13:05: Leaving ProcessChangedDestLists: 5052
RASCHAP.LOG
2548] 10-10 00:13:04:523: ChapBegin(fS=1,bA=0x81)
[2548] 10-10 00:13:04:523: ChapBegin done.
[2548] 10-10 00:13:04:523: ChapMakeMessage,RBuf=00000000
[2548] 10-10 00:13:04:523: CS_Initial...
[2548] 10-10 00:13:04:523: MakeChallengeMessage...
01 00 00 1C 10 39 B0 A9 F9 56 7F FE BE D9 26 5D |.....9...V...&]|
3B F1 56 9B FC 52 55 42 49 4B 4F 4E 00 00 00 00 |;.V..RUBIKON....|
[2548] 10-10 00:13:04:616: ChapMakeMessage,RBuf=01EF392A
[2548] 10-10 00:13:04:616: CS_ChallengeSent...
[2548] 10-10 00:13:04:647: ChapMakeMessage,RBuf=00000000
[2548] 10-10 00:13:04:647: ChapEnd
RASAUTH.LOG
[5052] 00:13:04:616: RasAuthProviderAuthenticateUser called
[5052] 00:13:04:616: Type=4, Length=4, Value=0xc3deba55
[5052] 00:13:04:616: Type=6, Length=4, Value=0x2
[5052] 00:13:04:616: Type=7, Length=4, Value=0x1
[5052] 00:13:04:616: Type=5, Length=4, Value=0x8b
[5052] 00:13:04:616: Type=26, Length=10, Value=
[5052] 00:13:04:616: 00 00 01 37 09 06 00 00 01 37 00 00 00 00 00 00 |...7.....7......|
[5052] 00:13:04:616: Type=26, Length=16, Value=
[5052] 00:13:04:616: 00 00 01 37 12 0C 4D 53 52 41 53 56 35 2E 32 30 |...7..MSRASV5.20|
[5052] 00:13:04:616: Type=61, Length=4, Value=0x5
[5052] 00:13:04:616: Type=64, Length=4, Value=0x1
[5052] 00:13:04:616: Type=65, Length=4, Value=0x1
[5052] 00:13:04:616: Type=31, Length=13, Value=
[5052] 00:13:04:616: 38 35 2E 31 34 31 2E 32 31 30 2E 35 34 00 00 00 |85.141.210.54...|
[5052] 00:13:04:616: Type=66, Length=13, Value=
[5052] 00:13:04:616: 38 35 2E 31 34 31 2E 32 31 30 2E 35 34 00 00 00 |85.141.210.54...|
[5052] 00:13:04:616: Type=1, Length=6, Value=
[5052] 00:13:04:616: 72 75 73 76 70 6E 00 00 00 00 00 00 00 00 00 00 |rusvpn..........|
[5052] 00:13:04:616: Type=26, Length=22, Value=
[5052] 00:13:04:616: 00 00 01 37 0B 12 39 B0 A9 F9 56 7F FE BE D9 26 |...7..9...V...&|
[5052] 00:13:04:616: 5D 3B F1 56 9B FC 00 00 00 00 00 00 00 00 00 00 |];.V............|
[5052] 00:13:04:616: Type=26, Length=56, Value=
[5052] 00:13:04:616: 00 00 01 37 19 34 00 00 92 97 F3 84 7D 0E B8 0E |...7.4......}...|
[5052] 00:13:04:616: E8 C4 D3 81 ED 74 87 A0 00 00 00 00 00 00 00 00 |.....t..........|
[5052] 00:13:04:616: 63 F7 5B D0 6E 08 84 15 14 87 EB A7 9D D8 35 D7 |c.[.n.........5.|
[5052] 00:13:04:616: 36 B8 39 9F B7 91 34 B9 00 00 00 00 00 00 00 00 |6.9...4.........|
[5052] 00:13:04:616: Inserting attribute type 4
[5052] 00:13:04:616: Inserting attribute type 6
[5052] 00:13:04:616: Inserting attribute type 7
[5052] 00:13:04:616: Inserting attribute type 5
[5052] 00:13:04:616: Inserting attribute type 26
[5052] 00:13:04:616: Inserting attribute type 26
[5052] 00:13:04:616: Inserting attribute type 61
[5052] 00:13:04:616: Inserting attribute type 64
[5052] 00:13:04:616: Inserting attribute type 65
[5052] 00:13:04:616: Inserting attribute type 31
[5052] 00:13:04:616: Inserting attribute type 66
[5052] 00:13:04:616: Inserting attribute type 1
[5052] 00:13:04:616: Inserting attribute type 26
[5052] 00:13:04:616: Inserting attribute type 26
[5052] 00:13:04:616: Inserting attribute type 4108
[5052] 00:13:04:647: IASResponse = DISCARD_PACKET. Failurereason=0x9
IASSAM.LOG
[5052] 10-10 00:13:04:616: NT-SAM Names handler received request with user identity rusvpn.
[5052] 10-10 00:13:04:616: Prepending default domain.
[5052] 10-10 00:13:04:616: NameMapper:
rependDefaultDomain[5052] 10-10 00:13:04:616: SAM-Account-Name is "MASTER\rusvpn".
[5052] 10-10 00:13:04:616: NT-SAM Authentication handler received request for MASTER\rusvpn.
[5052] 10-10 00:13:04:616: Processing MS-CHAP v2 authentication.
[5052] 10-10 00:13:04:631: LogonUser succeeded.
[5052] 10-10 00:13:04:631: NT-SAM User Authorization handler received request for MASTER\rusvpn.
[5052] 10-10 00:13:04:631: Using downlevel dial-in parameters.
[5052] 10-10 00:13:04:631: Sending LDAP search to mars.master.rafinad.ru.
[5052] 10-10 00:13:04:631: LDAP ERROR in ldap_search_ext_sW. Code = 81
[5052] 10-10 00:13:04:631: Extended error string: (null)
[5052] 10-10 00:13:04:631: Retrying LDAP search.
[5052] 10-10 00:13:04:631: Opening LDAP connection to mars.master.rafinad.ru.
[5052] 10-10 00:13:04:647: LDAP connect succeeded.
[5052] 10-10 00:13:04:647: Sending LDAP search to mars.master.rafinad.ru.
[5052] 10-10 00:13:04:647: Inserting attribute msNPAllowDialin.
[5052] 10-10 00:13:04:647: Successfully retrieved per-user attributes.
[5052] 10-10 00:13:04:647: Invoking AuthorizationDLLs
[5052] 10-10 00:13:04:647: Invoking extension vpnplgin.dll
[5052] 10-10 00:13:04:647: RadiusExtensionProcess2 returned 5
[5052] 10-10 00:13:04:647: RADIUS_EXTENSION_CONTROL_BLOCK.SetResponseType(256)
Router.log
[2748] 10-10 00:13:04:089: Rasman state change received from port 139, 1->5
[2748] 10-10 00:13:04:089: Rasman state change received from port 139, 5->2
[2748] 10-10 00:13:04:089: SvDevConnected: Entered, hPort=139
[2748] 10-10 00:13:04:089: TimerQRemove called
[2748] 10-10 00:13:04:430: SvFrameReceived: Entered, hPort: 139
[2748] 10-10 00:13:04:430: SvFrameReceived: PPP frame on port 139
[2548] 10-10 00:13:04:647: ServerSendMessage on port/connection: 8b from: PPP Message: PPPDDMMSG_PppFailure
[2748] 10-10 00:13:04:647: ServerReceiveMessage on port/connection: 8b from: PPP Message: PPPDDMMSG_PppFailure
[2748] 10-10 00:13:04:647: SvPppFailure: Entered, hPort=139, Error=691
[2548] 10-10 00:13:04:709: ServerSendMessage on port/connection: 8b from: PPP Message: PPPDDMMSG_Stopped
[2748] 10-10 00:13:04:709: ServerReceiveMessage on port/connection: 8b from: PPP Message: PPPDDMMSG_Stopped
[2748] 10-10 00:13:04:709: DevStartClosing: Entered, hPort=139
[2748] 10-10 00:13:04:709: RmDisconnect
isconnect posted on port 139[2748] 10-10 00:13:04:709: RasPortDisconnect rc=600
[2748] 10-10 00:13:04:709: TimerQRemove called
[2748] 10-10 00:13:04:709: TimerQRemove called
[2748] 10-10 00:13:04:709: TimerQRemove called
[2748] 10-10 00:13:04:709: DevCloseComplete:hPort=139,Auth=0,Rcv=0,Conn=1 1,Sec=3 2,Ppp=0
[2748] 10-10 00:13:05:003: Rasman state change received from port 139, 3->4
[2748] 10-10 00:13:05:003: SvDevDisconnected:Entered, hPort=139
[2748] 10-10 00:13:05:003: DevCloseComplete:hPort=139,Auth=0,Rcv=0,Conn=1 0,Sec=4 2,Ppp=0
[2748] 10-10 00:13:05:003: RmListen: Listen posted on port 139
[2548] 10-10 00:13:05:003: ServerSendMessage on port/connection: 8b from: PPP Message: PPPDDMMSG_PortCleanedUp
[2748] 10-10 00:13:05:003: RasPortListen dwRetCode=600
[2748] 10-10 00:13:05:003: ServerReceiveMessage on port/connection: 8b from: PPP Message: PPPDDMMSG_PortCleanedUp
RASTAPI.LOG
[2396] 10-10 00:13:04:089: RasTapicallback: msg=23 , param1=0l , param2=65798l
[2396] 10-10 00:13:04:089: RasTapicallback: msg=2 , param1=2l , param2=0l
[2396] 10-10 00:13:04:089: RasTapicallback: linecallstate=0x2
[2396] 10-10 00:13:04:089: DwProcessOfferEvent: hcall=0x10106
[2396] 10-10 00:13:04:089: DwProcessOfferEvent: Accepting call on VPN5-127 hcall = 0x10106
[2396] 10-10 00:13:04:089: WAN Miniport (PPTP) InClients=1, TotalDialInClients=1
[2396] 10-10 00:13:04:089: DwProcessOfferEvent 0x0
[2356] 10-10 00:13:04:089: DeviceWork: VPN5-127. State = 2
[2356] 10-10 00:13:04:089: DeviceWork: VPN5-127. lineAccept returned 0x103b2
[2396] 10-10 00:13:04:089: RasTapicallback: msg=12 , param1=66482l , param2=2147483720l
[2396] 10-10 00:13:04:089: LINE_REPLY. param1=0x103b2
[2396] 10-10 00:13:04:089: RasTapiCallback: Changing Listen State for VPN5-127 from 2 -> 3
[2356] 10-10 00:13:04:089: DeviceWork: VPN5-127. State = 2
[2356] 10-10 00:13:04:089: DeviceWork: VPN5-127. lineAnswer returned 0x103a1
[2396] 10-10 00:13:04:089: RasTapicallback: msg=2 , param1=256l , param2=0l
[2396] 10-10 00:13:04:089: RasTapicallback: linecallstate=0x100
[2396] 10-10 00:13:04:089: DwGetConnectInfo
[2396] 10-10 00:13:04:089: DwGetIDInformation
[2396] 10-10 00:13:04:089: DwGetIDInformation. 0
[2396] 10-10 00:13:04:089: SizeRequired for CallID=16
[2396] 10-10 00:13:04:089: DwGetIDInformation
[2396] 10-10 00:13:04:089: GetIDInformation: CallerID=85.141.210.54
[2396] 10-10 00:13:04:089: RasTapiCallback: called id info. not avail
[2396] 10-10 00:13:04:089: DwGetIDInformation. 0
[2396] 10-10 00:13:04:089: DwGetConnectInfo. 0x0
[2396] 10-10 00:13:04:089: RasTapiCallback: DwGetConnectInforeturned 0x0
[2396] 10-10 00:13:04:089: RasTapiCallback: Connected on VPN5-127
[2396] 10-10 00:13:04:089: RasTapiCallback: Incoming Call
[2356] 10-10 00:13:04:089: DeviceWork: VPN5-127. State = 2
[2356] 10-10 00:13:04:089: DeviceWork: Changing State for VPN5-127 from 2 -> 3
[2396] 10-10 00:13:04:089: RasTapicallback: msg=12 , param1=66465l , param2=0l
[2396] 10-10 00:13:04:089: LINE_REPLY. param1=0x103a1
[2748] 10-10 00:13:04:089: PortConnect: VPN5-127
[2748] 10-10 00:13:04:089:
[2748] 10-10 00:13:04:709: PortDisconnect: VPN5-127
[2748] 10-10 00:13:04:709: InitiatePortDisconnection: VPN5-127
[2748] 10-10 00:13:04:709: WAN Miniport (PPTP) InClients=0, TotalDialInClients=0
[2748] 10-10 00:13:04:709: InitiatePortDisconnection: Changing state for VPN5-127 from 3 -> 5, id=0x10128
[2748] 10-10 00:13:04:709:
[2748] 10-10 00:13:04:709:
[2396] 10-10 00:13:05:003: RasTapicallback: msg=2 , param1=1l , param2=0l
[2396] 10-10 00:13:05:003: RasTapicallback: linecallstate=0x1
[2396] 10-10 00:13:05:003: RasTapicallback: msg=12 , param1=65832l , param2=0l
[2396] 10-10 00:13:05:003: LINE_REPLY. param1=0x10128
[2396] 10-10 00:13:05:003: RasTapiCallback: lineDropped. port VPN5-127, id=0xffffffff
[2396] 10-10 00:13:05:003: RasTapiCallback: Idle Received for port VPN5-127
[2396] 10-10 00:13:05:003: RasTapiCallback: changing state of VPN5-127. 5 -> 1
[2396] 10-10 00:13:05:003: RasTapiCallback: lineDeallocateCall for VPN5-127,hcall = 0x10106
[2356] 10-10 00:13:05:003: PortTestSignalState: DeviceState = 0
[2748] 10-10 00:13:05:003: DeviceListen: Changing State for VPN5-127 from 1 -> 2
[2748] 10-10 00:13:05:003: DeviceListen: Changing Listen State for VPN5-127 from 4 -> 2
[2748] 10-10 00:13:05:003:
Hope that's enough to find the key.
Thanks in advanse
Basfa
Last edited: