Home | Site Map | Cisco How To |  Net How To | Wireless |Search | Forums | Services | Donations | Careers | About Us | Contact Us|

RRAS - VPN Randomly Disconnecting

RRAS, VPN, TS/RDP, Routing and remote Access.
Post a reply

RRAS - VPN Randomly Disconnecting

Postby tobias » Sat Apr 21, 2012 9:53 pm

Hi.

I am having a big problem with my VPN. The connection eventually disconnect. The max time i can stay connected is 48 h, but, sometimes it disconnect with only few hours.

My VPN server is Microsoft Windows Server 2003 (RRAS).

My VPN client is one TP-LINK WR-841ND router with DD-WRT firmware.

This is my VPN server Interfaces for local network, internet and remote:

Adaptador Ethernet REDE LOCAL:

Sufixo DNS específico de conexão . :
Descrição. . . . . . . . . . . . . : Realtek PCIe GBE Family Controller
Endereço físico. . . . . . . . . . : 00-E0-4C-68-16-42
DHCP ativado . . . . . . . . . . . : não
Endereço IP. . . . . . . . . . . . : 10.0.0.1
Máscara de sub-rede. . . . . . . . : 255.255.255.0
Gateway padrão . . . . . . . . . . :
Servidores DNS . . . . . . . . . . : 10.0.0.1

Adaptador Ethernet INTERNET:

Sufixo DNS específico de conexão . :
Descrição. . . . . . . . . . . . . : Intel(R) 82578DC Gigabit Network Connect
ion
Endereço físico. . . . . . . . . . : 44-87-FC-BD-D1-1D
DHCP ativado . . . . . . . . . . . : não
Endereço IP. . . . . . . . . . . . : 192.168.0.4
Máscara de sub-rede. . . . . . . . : 255.255.255.0
Gateway padrão . . . . . . . . . . : 192.168.0.1
Servidores DNS . . . . . . . . . . : 10.0.0.1
192.168.0.1

This is one tracert to one device at the other side of the tunnel.

Rastreando a rota para 192.168.2.2 com no máximo 30 saltos

1 56 ms 60 ms 64 ms 10.0.1.2
2 60 ms 60 ms 60 ms 192.168.2.2

Already try:

- Downgrade MTU to 1300.
- Buy new router and connect directly to my local network and VPN still disconnect.
- Confirm settings with http://support.microsoft.com/kb/948496

Windows Event Viwer: The reason for disconnecting was administrative settings or explicit req."

When the problem occur all vpn are killed (remote DD-WRT and local contec directly to my local network).
Last edited by tobias on Sat Apr 21, 2012 10:11 pm, edited 1 time in total.
tobias
 
Posts: 29
Joined: Sat Apr 21, 2012 9:23 pm
Top

Re: RRAS - VPN Randomly Disconnecting

Postby tobias » Sat Apr 21, 2012 9:56 pm

Please ask me for any thing you need to help me with that.

This is my tracing (20:01 h -> one off disconnect time):

[tapisrv.log]
[5320] 20:01:12:000: [TRACE] LineProlog: -- enter
[5320] 20:01:12:000: [INFO ] LineProlog: dwArg 10123
[5320] 20:01:12:000: [INFO ] LineProlog: ANY_RT_HCALL
[5320] 20:01:12:000: [INFO ] LineProlog: ReferenceObject returned ptCallClient 005668E4
[5320] 20:01:12:000: [INFO ] LineProlog: OpenContext 800003CC
[5320] 20:01:12:000: [TRACE] LienProlog: exit, result = x100f0
[5320] 20:01:12:000: [TRACE] LineEpilogAsyc: exit, result=x100f0
[5424] 20:01:13:390: [INFO ] LineEventProcSP: HTapiLine=000102CC, HTapiCall=00010134, msg=2, P1=x1, P2=x0, P3=x0
[5300] 20:01:13:390: [INFO ] Got a line spevent, htLine = 0x102cc, htCall = 0x10134, dwMsg = 0x2
[5424] 20:01:13:390: [TRACE] CompletionProcSP: enter, dwReqID=x100f0, lResult=x0
[5300] 20:01:13:390: [TRACE] LineEventProc
[5300] 20:01:13:390: [EVENT] LineEventProc: LINE_CALLSTATE event x1
[5300] 20:01:13:390: [INFO ] LineEventProc: i = [0] corresponding ptCallClient [005668E4]
[5300] 20:01:13:390: [INFO ] LineEventProc: ptCallClient->ptLineClient[00566008]
[5300] 20:01:13:390: [INFO ] LineEventProc: ptLineClient->ptLineApp[00562D08]
[5300] 20:01:13:390: [INFO ] LineEventProc: setting msg->InitContext to ptLineApp[00562D08]->InitContext of [800003FF]
[5300] 20:01:13:390: [INFO ] LineEventProc: setting msg->OpenContext to [800003CC]
[5300] 20:01:13:390: [INFO ] FMsgDisbled: dwAPIVersion<= TAPI_VERSION3_0, msg will be enabled
[5300] 20:01:13:390: [TRACE] FMsgDisabled return 0
[5300] 20:01:13:390: [TRACE] WriteEventBuffer - enter
[5300] 20:01:13:390: [TRACE] WriteEventBuffer: SetEvent 0000017C for local client
[5300] 20:01:13:390: [INFO ] Got an async completion event, requestID = 0x100f0, htXxx = 0x102cc, lResult = 0x0
[5300] 20:01:13:390: [TRACE] CompletionProc: enter, dwReqID=x100f0, lResult=x0
[5300] 20:01:13:390: [TRACE] WriteEventBuffer - enter
[5300] 20:01:13:390: [TRACE] WriteEventBuffer: SetEvent 0000017C for local client
[5784] 20:01:13:390: [TRACE] GetAsyncEvents: enter (TID=5784)
[5784] 20:01:13:390: [INFO ] M ebfused:x54 pEvtBuf: 0x00562808 pDataOut:0x00562808 pDataIn:0x0056285C
[5784] 20:01:13:390: [TRACE] GetAsyncEvents: return dwUsedBufferSize:x54
[5320] 20:01:13:406: [TRACE] LineProlog: -- enter
[5320] 20:01:13:406: [INFO ] LineProlog: dwArg 10123
[5320] 20:01:13:406: [INFO ] LineProlog: ANY_RT_HCALL
[5320] 20:01:13:406: [INFO ] LineProlog: ReferenceObject returned ptCallClient 005668E4
[5320] 20:01:13:406: [TRACE] LienProlog: exit, result = x0
[5320] 20:01:13:406: [TRACE] DestroytCallClient: enter, ptCallCli=x005668E4
[5320] 20:01:13:406: [TRACE] DestroytCall: enter, ptCall=x00566868
[5320] 20:01:13:406: [TRACE] LineEpilogSync: exit, result=x0
[5424] 20:01:58:234: [INFO ] LineEventProcSP: HTapiLine=000102CC, HTapiCall=00000000, msg=1f4, P1=x2a0006, P2=xbfea0, P3=x0
[5424] 20:01:58:234: [TRACE] LineEventProc
[5424] 20:01:58:234: [TRACE] CreatetCall: enter, ptLine=005660F0
[5424] 20:01:58:234: [INFO ] CreatetCall: calling NewObject ptCall 00566868
[5424] 20:01:58:234: [TRACE] CreatetCall: NewObject returned 0x100ef
[5424] 20:01:58:234: [TRACE] CreatetCall: exit, new ptCall=00566868
[5424] 20:01:58:234: [INFO ] LineEventProcSP: HTapiLine=000102CC, HTapiCall=000100EF, msg=2, P1=x2, P2=x0, P3=x100
[5300] 20:01:58:234: [INFO ] Got a line spevent, htLine = 0x102cc, htCall = 0x100ef, dwMsg = 0x2
[5300] 20:01:58:234: [TRACE] LineEventProc
[5300] 20:01:58:234: [EVENT] LineEventProc: LINE_CALLSTATE event x2
[5300] 20:01:58:234: [TRACE] CreatetCallClient: enter, ptCall=00566868,
[5300] 20:01:58:234: [INFO ] CreatetCallClient: calling NewObject, ptCallClient = [005668E4]
[5300] 20:01:58:234: [TRACE] CreatetCallClient: exit, new ptCallClient=005668E4
[5300] 20:01:58:234: [INFO ] LineEventProc: i = [0] corresponding ptCallClient [005668E4]
[5300] 20:01:58:234: [INFO ] LineEventProc: ptCallClient->ptLineClient[00566008]
[5300] 20:01:58:234: [INFO ] LineEventProc: ptLineClient->ptLineApp[00562D08]
[5300] 20:01:58:234: [INFO ] LineEventProc: setting msg->InitContext to ptLineApp[00562D08]->InitContext of [800003FF]
[5300] 20:01:58:234: [INFO ] LineEventProc: setting msg->OpenContext to [800003CC]
[5300] 20:01:58:234: [INFO ] FMsgDisbled: dwAPIVersion<= TAPI_VERSION3_0, msg will be enabled
[5300] 20:01:58:234: [TRACE] FMsgDisabled return 0
[5300] 20:01:58:234: [INFO ] LineEventProc: sending LINE_APPNEWCALL, ptClient[005626F8]
[5300] 20:01:58:234: [TRACE] WriteEventBuffer - enter
[5300] 20:01:58:234: [TRACE] WriteEventBuffer: SetEvent 0000017C for local client
[5300] 20:01:58:234: [INFO ] FMsgDisbled: dwAPIVersion<= TAPI_VERSION3_0, msg will be enabled
[5300] 20:01:58:234: [TRACE] FMsgDisabled return 0
[5300] 20:01:58:234: [TRACE] WriteEventBuffer - enter
[5300] 20:01:58:234: [TRACE] WriteEventBuffer: SetEvent 0000017C for local client
[5784] 20:01:58:234: [TRACE] GetAsyncEvents: enter (TID=5784)
[5784] 20:01:58:234: [INFO ] M ebfused:x60 pEvtBuf: 0x00562808 pDataOut:0x00562808 pDataIn:0x00562868
[5784] 20:01:58:234: [TRACE] GetAsyncEvents: return dwUsedBufferSize:x60
[5320] 20:01:58:234: [TRACE] LineProlog: -- enter
[5320] 20:01:58:234: [INFO ] LineProlog: dwArg 100de
[5320] 20:01:58:234: [INFO ] LineProlog: ANY_RT_HCALL
[5320] 20:01:58:234: [INFO ] LineProlog: ReferenceObject returned ptCallClient 005668E4
[5320] 20:01:58:234: [TRACE] LienProlog: exit, result = x0
[5320] 20:01:58:234: [TRACE] LineEpilogSync: exit, result=x0
[5320] 20:01:58:234: [TRACE] LineProlog: -- enter
[5320] 20:01:58:234: [INFO ] LineProlog: dwArg 100de
[5320] 20:01:58:234: [INFO ] LineProlog: ANY_RT_HCALL
[5320] 20:01:58:234: [INFO ] LineProlog: ReferenceObject returned ptCallClient 005668E4
[5320] 20:01:58:234: [INFO ] LineProlog: OpenContext 800003CC
[5320] 20:01:58:234: [TRACE] LienProlog: exit, result = x10112
[5320] 20:01:58:234: [TRACE] LineEpilogAsyc: exit, result=x10112
[5424] 20:01:58:250: [TRACE] CompletionProcSP: enter, dwReqID=x10112, lResult=x80000048
[5300] 20:01:58:250: [INFO ] Got an async completion event, requestID = 0x10112, htXxx = 0x102cc, lResult = 0x80000048
[5300] 20:01:58:250: [TRACE] CompletionProc: enter, dwReqID=x10112, lResult=x80000048
[5300] 20:01:58:250: [TRACE] WriteEventBuffer - enter
[5300] 20:01:58:250: [TRACE] WriteEventBuffer: SetEvent 0000017C for local client
[5784] 20:01:58:250: [TRACE] GetAsyncEvents: enter (TID=5784)
[5784] 20:01:58:250: [INFO ] M ebfused:x28 pEvtBuf: 0x00562808 pDataOut:0x00562808 pDataIn:0x00562830
[5784] 20:01:58:250: [TRACE] GetAsyncEvents: return dwUsedBufferSize:x28
[5320] 20:01:58:250: [TRACE] LineProlog: -- enter
[5320] 20:01:58:250: [INFO ] LineProlog: dwArg 100de
[5320] 20:01:58:250: [INFO ] LineProlog: ANY_RT_HCALL
[5320] 20:01:58:250: [INFO ] LineProlog: ReferenceObject returned ptCallClient 005668E4
[5320] 20:01:58:250: [INFO ] LineProlog: OpenContext 800003CC
[5320] 20:01:58:250: [TRACE] LienProlog: exit, result = x10101
[5320] 20:01:58:250: [TRACE] LineEpilogAsyc: exit, result=x10101
[5424] 20:01:58:250: [INFO ] LineEventProcSP: HTapiLine=000102CC, HTapiCall=000100EF, msg=2, P1=x100, P2=x0, P3=x100
[5300] 20:01:58:250: [INFO ] Got a line spevent, htLine = 0x102cc, htCall = 0x100ef, dwMsg = 0x2
[5300] 20:01:58:250: [TRACE] LineEventProc
[5300] 20:01:58:250: [EVENT] LineEventProc: LINE_CALLSTATE event x100
[5424] 20:01:58:250: [TRACE] CompletionProcSP: enter, dwReqID=x10101, lResult=x0
[5300] 20:01:58:250: [INFO ] LineEventProc: i = [0] corresponding ptCallClient [005668E4]
[5300] 20:01:58:250: [INFO ] LineEventProc: ptCallClient->ptLineClient[00566008]
[5300] 20:01:58:250: [INFO ] LineEventProc: ptLineClient->ptLineApp[00562D08]
[5300] 20:01:58:250: [INFO ] LineEventProc: setting msg->InitContext to ptLineApp[00562D08]->InitContext of [800003FF]
[5300] 20:01:58:250: [INFO ] LineEventProc: setting msg->OpenContext to [800003CC]
[5300] 20:01:58:250: [INFO ] FMsgDisbled: dwAPIVersion<= TAPI_VERSION3_0, msg will be enabled
[5300] 20:01:58:250: [TRACE] FMsgDisabled return 0
[5300] 20:01:58:250: [TRACE] WriteEventBuffer - enter
[5300] 20:01:58:250: [TRACE] WriteEventBuffer: SetEvent 0000017C for local client
[5300] 20:01:58:250: [INFO ] Got an async completion event, requestID = 0x10101, htXxx = 0x102cc, lResult = 0x0
[5784] 20:01:58:250: [TRACE] GetAsyncEvents: enter (TID=5784)
[5300] 20:01:58:250: [TRACE] CompletionProc: enter, dwReqID=x10101, lResult=x0
[5784] 20:01:58:250: [INFO ] M ebfused:x2c pEvtBuf: 0x00562808 pDataOut:0x00562808 pDataIn:0x00562834
[5300] 20:01:58:250: [TRACE] WriteEventBuffer - enter
[5784] 20:01:58:250: [TRACE] GetAsyncEvents: return dwUsedBufferSize:x2c
[5300] 20:01:58:250: [TRACE] WriteEventBuffer: SetEvent 0000017C for local client
[5320] 20:01:58:250: [TRACE] GetAsyncEvents: enter (TID=5320)
[5320] 20:01:58:250: [INFO ] M ebfused:x28 pEvtBuf: 0x00562808 pDataOut:0x00562808 pDataIn:0x00562830
[5320] 20:01:58:250: [TRACE] GetAsyncEvents: return dwUsedBufferSize:x28
[5784] 20:01:58:250: [TRACE] LineProlog: -- enter
[5784] 20:01:58:250: [INFO ] LineProlog: dwArg 100de
[5784] 20:01:58:250: [INFO ] LineProlog: ANY_RT_HCALL
[5784] 20:01:58:250: [INFO ] LineProlog: ReferenceObject returned ptCallClient 005668E4
[5784] 20:01:58:250: [TRACE] LienProlog: exit, result = x0
[5784] 20:01:58:250: [TRACE] LineEpilogSync: exit, result=x0
[5784] 20:01:58:250: [TRACE] LineProlog: -- enter
[5784] 20:01:58:250: [INFO ] LineProlog: dwArg 100de
[5784] 20:01:58:250: [INFO ] LineProlog: ANY_RT_HCALL
[5784] 20:01:58:250: [INFO ] LineProlog: ReferenceObject returned ptCallClient 005668E4
[5784] 20:01:58:250: [TRACE] LienProlog: exit, result = x0
[5784] 20:01:58:250: [TRACE] LineEpilogSync: exit, result=x0
[5784] 20:01:58:250: [TRACE] LineProlog: -- enter
[5784] 20:01:58:250: [INFO ] LineProlog: dwArg 100de
[5784] 20:01:58:250: [INFO ] LineProlog: ANY_RT_HCALL
[5784] 20:01:58:250: [INFO ] LineProlog: ReferenceObject returned ptCallClient 005668E4
[5784] 20:01:58:250: [TRACE] LienProlog: exit, result = x0
[5784] 20:01:58:250: [TRACE] LineEpilogSync: exit, result=x0
[5424] 20:02:12:859: [INFO ] LineEventProcSP: HTapiLine=000102CC, HTapiCall=000100EF, msg=2, P1=x4000, P2=x0, P3=x100
[5300] 20:02:12:859: [INFO ] Got a line spevent, htLine = 0x102cc, htCall = 0x100ef, dwMsg = 0x2
[5424] 20:02:12:859: [INFO ] LineEventProcSP: HTapiLine=000102CC, HTapiCall=000100EF, msg=2, P1=x1, P2=x0, P3=x100
[5300] 20:02:12:859: [TRACE] LineEventProc
[5300] 20:02:12:859: [EVENT] LineEventProc: LINE_CALLSTATE event x4000
[5300] 20:02:12:859: [INFO ] LineEventProc: i = [0] corresponding ptCallClient [005668E4]
[5300] 20:02:12:859: [INFO ] LineEventProc: ptCallClient->ptLineClient[00566008]
[5300] 20:02:12:859: [INFO ] LineEventProc: ptLineClient->ptLineApp[00562D08]
[5300] 20:02:12:859: [INFO ] LineEventProc: setting msg->InitContext to ptLineApp[00562D08]->InitContext of [800003FF]
[5300] 20:02:12:859: [INFO ] LineEventProc: setting msg->OpenContext to [800003CC]
[5300] 20:02:12:859: [INFO ] FMsgDisbled: dwAPIVersion<= TAPI_VERSION3_0, msg will be enabled
[5300] 20:02:12:859: [TRACE] FMsgDisabled return 0
[5300] 20:02:12:859: [TRACE] WriteEventBuffer - enter
[5300] 20:02:12:859: [TRACE] WriteEventBuffer: SetEvent 0000017C for local client
[5300] 20:02:12:859: [INFO ] Got a line spevent, htLine = 0x102cc, htCall = 0x100ef, dwMsg = 0x2
[5300] 20:02:12:859: [TRACE] LineEventProc
[5300] 20:02:12:859: [EVENT] LineEventProc: LINE_CALLSTATE event x1
[5300] 20:02:12:859: [INFO ] LineEventProc: i = [0] corresponding ptCallClient [005668E4]
[5300] 20:02:12:859: [INFO ] LineEventProc: ptCallClient->ptLineClient[00566008]
[5300] 20:02:12:859: [INFO ] LineEventProc: ptLineClient->ptLineApp[00562D08]
[5300] 20:02:12:859: [INFO ] LineEventProc: setting msg->InitContext to ptLineApp[00562D08]->InitContext of [800003FF]
[5300] 20:02:12:859: [INFO ] LineEventProc: setting msg->OpenContext to [800003CC]
[5300] 20:02:12:859: [INFO ] FMsgDisbled: dwAPIVersion<= TAPI_VERSION3_0, msg will be enabled
[5300] 20:02:12:859: [TRACE] FMsgDisabled return 0
[5300] 20:02:12:859: [TRACE] WriteEventBuffer - enter
[5300] 20:02:12:859: [TRACE] WriteEventBuffer: SetEvent 0000017C for local client
[5320] 20:02:12:859: [TRACE] GetAsyncEvents: enter (TID=5320)
[5320] 20:02:12:859: [INFO ] M ebfused:x58 pEvtBuf: 0x00562808 pDataOut:0x00562808 pDataIn:0x00562860
[5320] 20:02:12:859: [TRACE] GetAsyncEvents: return dwUsedBufferSize:x58
[5784] 20:02:12:859: [TRACE] LineProlog: -- enter
[5784] 20:02:12:859: [INFO ] LineProlog: dwArg 100de
[5784] 20:02:12:859: [INFO ] LineProlog: ANY_RT_HCALL
[5784] 20:02:12:859: [INFO ] LineProlog: ReferenceObject returned ptCallClient 005668E4
[5784] 20:02:12:859: [TRACE] LienProlog: exit, result = x0
[5784] 20:02:12:859: [TRACE] LineEpilogSync: exit, result=x0
[5320] 20:02:12:859: [TRACE] LineProlog: -- enter
[5320] 20:02:12:859: [INFO ] LineProlog: dwArg 100de
[5320] 20:02:12:859: [INFO ] LineProlog: ANY_RT_HCALL
[5320] 20:02:12:859: [INFO ] LineProlog: ReferenceObject returned ptCallClient 005668E4
[5320] 20:02:12:859: [INFO ] LineProlog: OpenContext 800003CC
[5320] 20:02:12:859: [TRACE] LienProlog: exit, result = x100cd
[5320] 20:02:12:859: [TRACE] LineEpilogAsyc: exit, result=x100cd
[5424] 20:02:12:859: [TRACE] CompletionProcSP: enter, dwReqID=x100cd, lResult=x80000048
[5300] 20:02:12:859: [INFO ] Got an async completion event, requestID = 0x100cd, htXxx = 0x102cc, lResult = 0x80000048
[5300] 20:02:12:859: [TRACE] CompletionProc: enter, dwReqID=x100cd, lResult=x80000048
[5300] 20:02:12:859: [TRACE] WriteEventBuffer - enter
[5300] 20:02:12:859: [TRACE] WriteEventBuffer: SetEvent 0000017C for local client
[5784] 20:02:12:859: [TRACE] GetAsyncEvents: enter (TID=5784)
[5784] 20:02:12:859: [INFO ] M ebfused:x28 pEvtBuf: 0x00562808 pDataOut:0x00562808 pDataIn:0x00562830
[5784] 20:02:12:859: [TRACE] GetAsyncEvents: return dwUsedBufferSize:x28
[5320] 20:02:12:859: [TRACE] LineProlog: -- enter
[5320] 20:02:12:859: [INFO ] LineProlog: dwArg 100de
[5320] 20:02:12:859: [INFO ] LineProlog: ANY_RT_HCALL
[5320] 20:02:12:859: [INFO ] LineProlog: ReferenceObject returned ptCallClient 005668E4
[5320] 20:02:12:859: [TRACE] LienProlog: exit, result = x0
[5320] 20:02:12:859: [TRACE] DestroytCallClient: enter, ptCallCli=x005668E4
[5320] 20:02:12:859: [TRACE] DestroytCall: enter, ptCall=x00566868
[5320] 20:02:12:859: [TRACE] LineEpilogSync: exit, result=x0
[5424] 20:02:30:234: [INFO ] LineEventProcSP: HTapiLine=000102CC, HTapiCall=00000000, msg=1f4, P1=x2c0006, P2=xbfea0, P3=x0
[5424] 20:02:30:234: [TRACE] LineEventProc
[5424] 20:02:30:234: [TRACE] CreatetCall: enter, ptLine=005660F0
[5424] 20:02:30:234: [INFO ] CreatetCall: calling NewObject ptCall 00566868
[5424] 20:02:30:234: [TRACE] CreatetCall: NewObject returned 0x100bc
[5424] 20:02:30:234: [TRACE] CreatetCall: exit, new ptCall=00566868
[5424] 20:02:30:234: [INFO ] LineEventProcSP: HTapiLine=000102CC, HTapiCall=000100BC, msg=2, P1=x2, P2=x0, P3=x100
[5300] 20:02:30:234: [INFO ] Got a line spevent, htLine = 0x102cc, htCall = 0x100bc, dwMsg = 0x2
[5300] 20:02:30:234: [TRACE] LineEventProc
[5300] 20:02:30:234: [EVENT] LineEventProc: LINE_CALLSTATE event x2
[5300] 20:02:30:234: [TRACE] CreatetCallClient: enter, ptCall=00566868,
[5300] 20:02:30:234: [INFO ] CreatetCallClient: calling NewObject, ptCallClient = [005668E4]
[5300] 20:02:30:234: [TRACE] CreatetCallClient: exit, new ptCallClient=005668E4
[5300] 20:02:30:234: [INFO ] LineEventProc: i = [0] corresponding ptCallClient [005668E4]
[5300] 20:02:30:234: [INFO ] LineEventProc: ptCallClient->ptLineClient[00566008]
[5300] 20:02:30:234: [INFO ] LineEventProc: ptLineClient->ptLineApp[00562D08]
[5300] 20:02:30:234: [INFO ] LineEventProc: setting msg->InitContext to ptLineApp[00562D08]->InitContext of [800003FF]
[5300] 20:02:30:234: [INFO ] LineEventProc: setting msg->OpenContext to [800003CC]
[5300] 20:02:30:234: [INFO ] FMsgDisbled: dwAPIVersion<= TAPI_VERSION3_0, msg will be enabled
[5300] 20:02:30:234: [TRACE] FMsgDisabled return 0
[5300] 20:02:30:234: [INFO ] LineEventProc: sending LINE_APPNEWCALL, ptClient[005626F8]
[5300] 20:02:30:234: [TRACE] WriteEventBuffer - enter
[5300] 20:02:30:234: [TRACE] WriteEventBuffer: SetEvent 0000017C for local client
[5300] 20:02:30:234: [INFO ] FMsgDisbled: dwAPIVersion<= TAPI_VERSION3_0, msg will be enabled
[5300] 20:02:30:234: [TRACE] FMsgDisabled return 0
[5300] 20:02:30:234: [TRACE] WriteEventBuffer - enter
[5300] 20:02:30:234: [TRACE] WriteEventBuffer: SetEvent 0000017C for local client
[5784] 20:02:30:234: [TRACE] GetAsyncEvents: enter (TID=5784)
[5784] 20:02:30:234: [INFO ] M ebfused:x60 pEvtBuf: 0x00562808 pDataOut:0x00562808 pDataIn:0x00562868
[5784] 20:02:30:234: [TRACE] GetAsyncEvents: return dwUsedBufferSize:x60
[5320] 20:02:30:234: [TRACE] LineProlog: -- enter
[5320] 20:02:30:234: [INFO ] LineProlog: dwArg 101cd
[5320] 20:02:30:234: [INFO ] LineProlog: ANY_RT_HCALL
[5320] 20:02:30:234: [INFO ] LineProlog: ReferenceObject returned ptCallClient 005668E4
[5320] 20:02:30:234: [TRACE] LienProlog: exit, result = x0
[5320] 20:02:30:234: [TRACE] LineEpilogSync: exit, result=x0
[5320] 20:02:30:234: [TRACE] LineProlog: -- enter
[5320] 20:02:30:234: [INFO ] LineProlog: dwArg 101cd
[5320] 20:02:30:234: [INFO ] LineProlog: ANY_RT_HCALL
[5320] 20:02:30:234: [INFO ] LineProlog: ReferenceObject returned ptCallClient 005668E4
[5320] 20:02:30:234: [INFO ] LineProlog: OpenContext 800003CC
[5320] 20:02:30:234: [TRACE] LienProlog: exit, result = x101bc
[5320] 20:02:30:234: [TRACE] LineEpilogAsyc: exit, result=x101bc
[5424] 20:02:30:234: [TRACE] CompletionProcSP: enter, dwReqID=x101bc, lResult=x80000048
[5300] 20:02:30:234: [INFO ] Got an async completion event, requestID = 0x101bc, htXxx = 0x102cc, lResult = 0x80000048
[5300] 20:02:30:234: [TRACE] CompletionProc: enter, dwReqID=x101bc, lResult=x80000048
[5300] 20:02:30:234: [TRACE] WriteEventBuffer - enter
[5300] 20:02:30:234: [TRACE] WriteEventBuffer: SetEvent 0000017C for local client
[5784] 20:02:30:234: [TRACE] GetAsyncEvents: enter (TID=5784)
[5784] 20:02:30:234: [INFO ] M ebfused:x28 pEvtBuf: 0x00562808 pDataOut:0x00562808 pDataIn:0x00562830
[5784] 20:02:30:234: [TRACE] GetAsyncEvents: return dwUsedBufferSize:x28
[5320] 20:02:30:234: [TRACE] LineProlog: -- enter
[5320] 20:02:30:234: [INFO ] LineProlog: dwArg 101cd
[5320] 20:02:30:234: [INFO ] LineProlog: ANY_RT_HCALL
[5320] 20:02:30:234: [INFO ] LineProlog: ReferenceObject returned ptCallClient 005668E4
[5320] 20:02:30:234: [INFO ] LineProlog: OpenContext 800003CC
[5320] 20:02:30:234: [TRACE] LienProlog: exit, result = x10089
[5320] 20:02:30:234: [TRACE] LineEpilogAsyc: exit, result=x10089
[5424] 20:02:30:234: [INFO ] LineEventProcSP: HTapiLine=000102CC, HTapiCall=000100BC, msg=2, P1=x100, P2=x0, P3=x100
[5300] 20:02:30:234: [INFO ] Got a line spevent, htLine = 0x102cc, htCall = 0x100bc, dwMsg = 0x2
[5300] 20:02:30:234: [TRACE] LineEventProc
[5300] 20:02:30:234: [EVENT] LineEventProc: LINE_CALLSTATE event x100
[5300] 20:02:30:234: [INFO ] LineEventProc: i = [0] corresponding ptCallClient [005668E4]
[5424] 20:02:30:234: [TRACE] CompletionProcSP: enter, dwReqID=x10089, lResult=x0
[5300] 20:02:30:234: [INFO ] LineEventProc: ptCallClient->ptLineClient[00566008]
[5300] 20:02:30:234: [INFO ] LineEventProc: ptLineClient->ptLineApp[00562D08]
[5300] 20:02:30:234: [INFO ] LineEventProc: setting msg->InitContext to ptLineApp[00562D08]->InitContext of [800003FF]
[5300] 20:02:30:234: [INFO ] LineEventProc: setting msg->OpenContext to [800003CC]
[5300] 20:02:30:234: [INFO ] FMsgDisbled: dwAPIVersion<= TAPI_VERSION3_0, msg will be enabled
[5300] 20:02:30:234: [TRACE] FMsgDisabled return 0
[5300] 20:02:30:234: [TRACE] WriteEventBuffer - enter
[5300] 20:02:30:234: [TRACE] WriteEventBuffer: SetEvent 0000017C for local client
[5300] 20:02:30:234: [INFO ] Got an async completion event, requestID = 0x10089, htXxx = 0x102cc, lResult = 0x0
[5300] 20:02:30:234: [TRACE] CompletionProc: enter, dwReqID=x10089, lResult=x0
[5784] 20:02:30:234: [TRACE] GetAsyncEvents: enter (TID=5784)
[5300] 20:02:30:234: [TRACE] WriteEventBuffer - enter
[5784] 20:02:30:234: [INFO ] M ebfused:x2c pEvtBuf: 0x00562808 pDataOut:0x00562808 pDataIn:0x00562834
[5300] 20:02:30:234: [TRACE] WriteEventBuffer: SetEvent 0000017C for local client
[5784] 20:02:30:234: [TRACE] GetAsyncEvents: return dwUsedBufferSize:x54
[5320] 20:02:30:234: [TRACE] LineProlog: -- enter
[5320] 20:02:30:234: [INFO ] LineProlog: dwArg 101cd
[5320] 20:02:30:234: [INFO ] LineProlog: ANY_RT_HCALL
[5320] 20:02:30:234: [INFO ] LineProlog: ReferenceObject returned ptCallClient 005668E4
[5320] 20:02:30:234: [TRACE] LienProlog: exit, result = x0
[5320] 20:02:30:234: [TRACE] LineEpilogSync: exit, result=x0
[5320] 20:02:30:234: [TRACE] LineProlog: -- enter
[5320] 20:02:30:234: [INFO ] LineProlog: dwArg 101cd
[5320] 20:02:30:234: [INFO ] LineProlog: ANY_RT_HCALL
[5320] 20:02:30:234: [INFO ] LineProlog: ReferenceObject returned ptCallClient 005668E4
[5320] 20:02:30:234: [TRACE] LienProlog: exit, result = x0
[5320] 20:02:30:234: [TRACE] LineEpilogSync: exit, result=x0
[5320] 20:02:30:234: [TRACE] LineProlog: -- enter
[5320] 20:02:30:234: [INFO ] LineProlog: dwArg 101cd
[5320] 20:02:30:234: [INFO ] LineProlog: ANY_RT_HCALL
[5320] 20:02:30:234: [INFO ] LineProlog: ReferenceObject returned ptCallClient 005668E4
[5320] 20:02:30:234: [TRACE] LienProlog: exit, result = x0
[5320] 20:02:30:234: [TRACE] LineEpilogSync: exit, result=x0

[IGMPv2.log]
[924] 20:00:56: Entering _WF_TimerProcessing
[924] 20:00:56: Timer fired leads to General-query being sent on If(10004)Group(0.0.0.0)
[924] 20:00:56: Entering _SendPacket()
[924] 20:00:56: sent general query to ras client: 10.0.1.3
[924] 20:00:56: sent general query to ras client: 10.0.1.2
[924] 20:00:56: Sent GenQuery on IfIndex(10004) IpAddr(10.0.1.1)
[976] 20:01:02: entering GetGlobalInfo(): pvConfig(00000000) pdwSize(017bf8e0)
[976] 20:01:02: entering GetGlobalInfo(): pvConfig(00000000) pdwSize(017bf8e0)
[976] 20:01:02: entering GetGlobalInfo(): pvConfig(058a7ad0) pdwSize(017bf8d0)
[976] 20:01:13: entering GetGlobalInfo(): pvConfig(00000000) pdwSize(017bf8e0)
[976] 20:01:13: entering GetGlobalInfo(): pvConfig(00000000) pdwSize(017bf8e0)
[976] 20:01:13: entering GetGlobalInfo(): pvConfig(058a7ad0) pdwSize(017bf8d0)
[2084] 20:01:32: entering GetGlobalInfo(): pvConfig(00000000) pdwSize(01d7f8e0)
[2084] 20:01:32: entering GetGlobalInfo(): pvConfig(00000000) pdwSize(01d7f8e0)
[2084] 20:01:32: entering GetGlobalInfo(): pvConfig(058a7ad0) pdwSize(01d7f8d0)
[5944] 20:01:39: Entering DisconnectRasClient for IfIndex(10004), NextHop(10.0.1.3)
[5944] 20:01:39: entering _DeleteAllTimers()
[5944] 20:01:39: Leaving _DisconnectRasClient(0) for IfIndex(10004), NextHop(10.0.1.3)

[5944] 20:01:39: Entering DisconnectRasClient for IfIndex(10004), NextHop(10.0.1.2)
[5944] 20:01:39: entering _DeleteAllTimers()
[5944] 20:01:39: Leaving _DisconnectRasClient(0) for IfIndex(10004), NextHop(10.0.1.2)

[2084] 20:01:43: entering GetGlobalInfo(): pvConfig(00000000) pdwSize(01d7f8e0)
[2084] 20:01:43: entering GetGlobalInfo(): pvConfig(00000000) pdwSize(01d7f8e0)
[2084] 20:01:43: entering GetGlobalInfo(): pvConfig(0d65aad8) pdwSize(01d7f8d0)
[2084] 20:01:54: entering GetGlobalInfo(): pvConfig(00000000) pdwSize(01d7f8e0)
[2084] 20:01:54: entering GetGlobalInfo(): pvConfig(00000000) pdwSize(01d7f8e0)
[2084] 20:01:54: entering GetGlobalInfo(): pvConfig(0d65aad8) pdwSize(01d7f8d0)
[2084] 20:02:05: entering GetGlobalInfo(): pvConfig(00000000) pdwSize(01d7f8e0)
[2084] 20:02:05: entering GetGlobalInfo(): pvConfig(00000000) pdwSize(01d7f8e0)
[2084] 20:02:05: entering GetGlobalInfo(): pvConfig(0d65aad8) pdwSize(01d7f8d0)
[2084] 20:02:18: entering GetGlobalInfo(): pvConfig(00000000) pdwSize(01d7f8e0)
[2084] 20:02:18: entering GetGlobalInfo(): pvConfig(00000000) pdwSize(01d7f8e0)
[2084] 20:02:18: entering GetGlobalInfo(): pvConfig(0d65aad8) pdwSize(01d7f8d0)
[5944] 20:02:25: Entering ConnectRasClient(10.0.1.3):IfIndex(10004)

[5944] 20:02:25: Leaving _ConnectRasClient(10.0.1.3):0

[2084] 20:02:29: entering GetGlobalInfo(): pvConfig(00000000) pdwSize(01d7f8e0)
[2084] 20:02:29: entering GetGlobalInfo(): pvConfig(00000000) pdwSize(01d7f8e0)
[2084] 20:02:29: entering GetGlobalInfo(): pvConfig(0d65aad8) pdwSize(01d7f8d0)
[5944] 20:02:35: Entering ConnectRasClient(10.0.1.2):IfIndex(10004)

[5944] 20:02:35: Leaving _ConnectRasClient(10.0.1.2):0

[2084] 20:02:40: entering GetGlobalInfo(): pvConfig(00000000) pdwSize(01d7f8e0)
[2084] 20:02:40: entering GetGlobalInfo(): pvConfig(00000000) pdwSize(01d7f8e0)
[2084] 20:02:40: entering GetGlobalInfo(): pvConfig(0d674e28) pdwSize(01d7f8d0)
[2084] 20:02:51: entering GetGlobalInfo(): pvConfig(00000000) pdwSize(01d7f8e0)
[2084] 20:02:51: entering GetGlobalInfo(): pvConfig(00000000) pdwSize(01d7f8e0)
[2084] 20:02:51: entering GetGlobalInfo(): pvConfig(0d674e28) pdwSize(01d7f8d0)
[4144] 20:03:01: Entering _WT_ProcessTimerEvent()
[4144] 20:03:01: Entering _WF_ProcessTimerEvent
[4144] 20:03:01: In _DebugCheckLowTimer
[4144] 20:03:01: Entering _T_QueryTimer()
[4144] 20:03:01: Processing T_QueryTimer() for IfIndex(10004), IfType(3)
[4144] 20:03:01: In _DebugCheckLowTimer
[4144] 20:03:01: _InsertTimer()
[4144] 20:03:01: In _DebugCheckLowTimer
[4144] 20:03:01: entering _ResyncTimerBuckets()
[4144] 20:03:01: In _DebugCheckLowTimer
[4144] 20:03:01: In _DebugCheckLowTimer
[4144] 20:03:01: entering _ResyncTimerBuckets()
[4144] 20:03:01: In _DebugCheckLowTimer
[4144] 20:03:01: In _DebugCheckLowTimer
[4144] 20:03:01: In _DebugCheckLowTimer
[4144] 20:03:01: Entering _WF_TimerProcessing
[4144] 20:03:01: Timer fired leads to General-query being sent on If(10004)Group(0.0.0.0)
[4144] 20:03:01: Entering _SendPacket()
[4144] 20:03:01: sent general query to ras client: 10.0.1.3
[4144] 20:03:01: sent general query to ras client: 10.0.1.2
[4144] 20:03:01: Sent GenQuery on IfIndex(10004) IpAddr(10.0.1.1)
[2084] 20:03:02: entering GetGlobalInfo(): pvConfig(00000000) pdwSize(01d7f8e0)
[2084] 20:03:02: entering GetGlobalInfo(): pvConfig(00000000) pdwSize(01d7f8e0)
[2084] 20:03:02: entering GetGlobalInfo(): pvConfig(0d674e28) pdwSize(01d7f8d0)
[2084] 20:03:13: entering GetGlobalInfo(): pvConfig(00000000) pdwSize(01d7f8e0)
[2084] 20:03:13: entering GetGlobalInfo(): pvConfig(00000000) pdwSize(01d7f8e0)
[2084] 20:03:13: entering GetGlobalInfo(): pvConfig(0d674e28) pdwSize(01d7f8d0)
[2084] 20:03:24: entering GetGlobalInfo(): pvConfig(00000000) pdwSize(01d7f8e0)
[2084] 20:03:24: entering GetGlobalInfo(): pvConfig(00000000) pdwSize(01d7f8e0)
[2084] 20:03:24: entering GetGlobalInfo(): pvConfig(0d66f778) pdwSize(01d7f8d0)
[2084] 20:03:35: entering GetGlobalInfo(): pvConfig(00000000) pdwSize(01d7f8e0)
[2084] 20:03:35: entering GetGlobalInfo(): pvConfig(00000000) pdwSize(01d7f8e0)
[2084] 20:03:35: entering GetGlobalInfo(): pvConfig(0d65aad8) pdwSize(01d7f8d0)
[2084] 20:03:46: entering GetGlobalInfo(): pvConfig(00000000) pdwSize(01d7f8e0)
[2084] 20:03:46: entering GetGlobalInfo(): pvConfig(00000000) pdwSize(01d7f8e0)
[2084] 20:03:46: entering GetGlobalInfo(): pvConfig(0d65aad8) pdwSize(01d7f8d0)
[2084] 20:03:57: entering GetGlobalInfo(): pvConfig(00000000) pdwSize(01d7f8e0)
[2084] 20:03:57: entering GetGlobalInfo(): pvConfig(00000000) pdwSize(01d7f8e0)
[2084] 20:03:57: entering GetGlobalInfo(): pvConfig(0d65aad8) pdwSize(01d7f8d0)
[2084] 20:04:08: entering GetGlobalInfo(): pvConfig(00000000) pdwSize(01d7f8e0)
[2084] 20:04:08: entering GetGlobalInfo(): pvConfig(00000000) pdwSize(01d7f8e0)
[2084] 20:04:08: entering GetGlobalInfo(): pvConfig(058a7ad0) pdwSize(01d7f8d0)
[2084] 20:04:19: entering GetGlobalInfo(): pvConfig(00000000) pdwSize(01d7f8e0)
[2084] 20:04:19: entering GetGlobalInfo(): pvConfig(00000000) pdwSize(01d7f8e0)
[2084] 20:04:19: entering GetGlobalInfo(): pvConfig(058a7ad0) pdwSize(01d7f8d0)
[2084] 20:04:30: entering GetGlobalInfo(): pvConfig(00000000) pdwSize(01d7f8e0)
[2084] 20:04:30: entering GetGlobalInfo(): pvConfig(00000000) pdwSize(01d7f8e0)
[2084] 20:04:30: entering GetGlobalInfo(): pvConfig(058a7ad0) pdwSize(01d7f8d0)
[2084] 20:04:41: entering GetGlobalInfo(): pvConfig(00000000) pdwSize(01d7f8e0)
[2084] 20:04:41: entering GetGlobalInfo(): pvConfig(00000000) pdwSize(01d7f8e0)
[2084] 20:04:41: entering GetGlobalInfo(): pvConfig(058a7ad0) pdwSize(01d7f8d0)
[2084] 20:04:52: entering GetGlobalInfo(): pvConfig(00000000) pdwSize(01d7f8e0)
[2084] 20:04:52: entering GetGlobalInfo(): pvConfig(00000000) pdwSize(01d7f8e0)
[2084] 20:04:52: entering GetGlobalInfo(): pvConfig(058a7ad0) pdwSize(01d7f8d0)
[2084] 20:05:03: entering GetGlobalInfo(): pvConfig(00000000) pdwSize(01d7f8e0)
[2084] 20:05:03: entering GetGlobalInfo(): pvConfig(00000000) pdwSize(01d7f8e0)
[2084] 20:05:03: entering GetGlobalInfo(): pvConfig(0d674e28) pdwSize(01d7f8d0)
[924] 20:05:06: Entering _WT_ProcessTimerEvent()
[924] 20:05:06: Entering _WF_ProcessTimerEvent
[924] 20:05:06: In _DebugCheckLowTimer
[924] 20:05:06: Entering _T_QueryTimer()
[924] 20:05:06: Processing T_QueryTimer() for IfIndex(10004), IfType(3)
[924] 20:05:06: In _DebugCheckLowTimer
[924] 20:05:06: _InsertTimer()
[924] 20:05:06: In _DebugCheckLowTimer
[924] 20:05:06: entering _ResyncTimerBuckets()
[924] 20:05:06: In _DebugCheckLowTimer
[924] 20:05:06: In _DebugCheckLowTimer
[924] 20:05:06: entering _ResyncTimerBuckets()
[924] 20:05:06: In _DebugCheckLowTimer
[924] 20:05:06: In _DebugCheckLowTimer
[924] 20:05:06: In _DebugCheckLowTimer
[924] 20:05:06: Entering _WF_TimerProcessing
[924] 20:05:06: Timer fired leads to General-query being sent on If(10004)Group(0.0.0.0)
[924] 20:05:06: Entering _SendPacket()
[924] 20:05:06: sent general query to ras client: 10.0.1.3
[924] 20:05:06: sent general query to ras client: 10.0.1.2
[924] 20:05:06: Sent GenQuery on IfIndex(10004) IpAddr(10.0.1.1)

[IASNAP.log]
[4144] 04-19 20:02:24:500: Auto-generation of Session-Timeout is disabled.
[4144] 04-19 20:02:34:375: Auto-generation of Session-Timeout is disabled.

[IASSAM.log]
[4144] 04-19 20:02:21:968: NT-SAM Names handler received request with user identity TROMM\tobias.
[4144] 04-19 20:02:21:968: Username is already an NT4 account name.
[4144] 04-19 20:02:21:968: SAM-Account-Name is "TROMM\tobias".
[4144] 04-19 20:02:21:968: NT-SAM Authentication handler received request for TROMM\tobias.
[4144] 04-19 20:02:21:968: Processing MS-CHAP v2 authentication.
[4144] 04-19 20:02:23:671: LogonUser succeeded.
[4144] 04-19 20:02:23:671: NT-SAM User Authorization handler received request for TROMM\tobias.
[4144] 04-19 20:02:23:671: Using native-mode dial-in parameters.
[4144] 04-19 20:02:23:671: Sending LDAP search to servidor.TROMM.local.
[4144] 04-19 20:02:23:671: LDAP ERROR in ldap_search_ext_sW. Code = 81
[4144] 04-19 20:02:23:671: Extended error string: (null)
[4144] 04-19 20:02:23:671: Retrying LDAP search.
[4144] 04-19 20:02:23:671: Opening LDAP connection to servidor.TROMM.local.
[4144] 04-19 20:02:23:671: The registry value DisableLdapEncryption does not exist. Using default 0
[4144] 04-19 20:02:23:671: Trying to set LDAP encryption = 1
[4144] 04-19 20:02:23:937: LDAP connect succeeded.
[4144] 04-19 20:02:23:937: Sending LDAP search to servidor.TROMM.local.
[4144] 04-19 20:02:24:500: Inserting attribute msNPAllowDialin.
[4144] 04-19 20:02:24:500: Inserting attribute msRADIUSFramedIPAddress.
[4144] 04-19 20:02:24:500: Successfully retrieved per-user attributes.
[4144] 04-19 20:02:33:859: NT-SAM Names handler received request with user identity TROMM\vpnuser.
[4144] 04-19 20:02:33:859: Username is already an NT4 account name.
[4144] 04-19 20:02:33:859: SAM-Account-Name is "TROMM\vpnuser".
[4144] 04-19 20:02:33:859: NT-SAM Authentication handler received request for TROMM\vpnuser.
[4144] 04-19 20:02:33:859: Processing MS-CHAP v2 authentication.
[4144] 04-19 20:02:34:078: LogonUser succeeded.
[4144] 04-19 20:02:34:078: NT-SAM User Authorization handler received request for TROMM\vpnuser.
[4144] 04-19 20:02:34:078: Using native-mode dial-in parameters.
[4144] 04-19 20:02:34:078: Sending LDAP search to servidor.TROMM.local.
[4144] 04-19 20:02:34:375: Inserting attribute msNPAllowDialin.
[4144] 04-19 20:02:34:375: Inserting attribute msRADIUSFramedIPAddress.
[4144] 04-19 20:02:34:375: Inserting attribute msRADIUSFramedRoute.
[4144] 04-19 20:02:34:375: Successfully retrieved per-user attributes.

[IPBOOTP.log]
[976] 20:01:02: entering GetGlobalInfo: 0x00000000 0x017bf8e0
[976] 20:01:02: leaving GetGlobalInfo: 122
[976] 20:01:02: entering GetGlobalInfo: 0x00000000 0x017bf8e0
[976] 20:01:02: leaving GetGlobalInfo: 122
[976] 20:01:02: entering GetGlobalInfo: 0x058a7ae0 0x017bf8d0
[976] 20:01:02: leaving GetGlobalInfo: 0
[976] 20:01:13: entering GetGlobalInfo: 0x00000000 0x017bf8e0
[976] 20:01:13: leaving GetGlobalInfo: 122
[976] 20:01:13: entering GetGlobalInfo: 0x00000000 0x017bf8e0
[976] 20:01:13: leaving GetGlobalInfo: 122
[976] 20:01:13: entering GetGlobalInfo: 0x058a7ae0 0x017bf8d0

[IPMGM.LOG]
[5944] 20:01:39: ENTERED MgmReleaseInterfaceOwnership : Interface 10004, 301000a
[5944] 20:01:39: LEAVING MgmReleaseInterfaceOwnership 0

[5944] 20:01:39: ENTERED MgmReleaseInterfaceOwnership : Interface 10004, 201000a
[5944] 20:01:39: LEAVING MgmReleaseInterfaceOwnership 0

[5944] 20:02:25: ENTERED MgmTakeInterfaceOwnership : Interface 10004, 301000a
[5944] 20:02:25: LEAVING MgmTakeInterfaceOwnership 0

[5944] 20:02:35: ENTERED MgmTakeInterfaceOwnership : Interface 10004, 201000a
[5944] 20:02:35: LEAVING MgmTakeInterfaceOwnership 0


[IPRouterManager.log]
[5944] 20:01:39: DeleteInterface: Deleting tobias,
[5944] 20:01:39: DeleteFilterInterface: No context, assuming interface tobias not added to filter driver
[5944] 20:01:39: DeleteInterface: Deleting vpnuser,
[5944] 20:01:39: DeleteFilterInterface: No context, assuming interface vpnuser not added to filter driver
[4144] 20:01:40: ChangeRouteWithForwarder: Deleting all routes to 192.168.1.0/255.255.255.0
[4144] 20:01:40: ChangeRouteWithForwarder: Deleting all routes to 192.168.3.0/255.255.255.0
[4144] 20:01:40: ChangeRouteWithForwarder: Deleting all routes to 192.168.2.0/255.255.255.0
[4144] 20:02:19: Error adding route, Stack bit == 0
[5944] 20:02:24: AddInterface: Adding tobias
[5944] 20:02:24: ICB number for tobias is 20


[5944] 20:02:24: ENTERED SetMcastLimitInfo for If ffffffff
[5944] 20:02:24: LEFT SetMcastLimitInfo
[5944] 20:02:24: ENTERED SetBoundaryInfo for If ffffffff
[5944] 20:02:24: LEFT SetBoundaryInfo
[5944] 20:02:24: AddInterfaceToAllProtocols: No interface info for tobias. Not adding to any protocols
[5944] 20:02:24: SetInterfaceFilterInfo: Both filters info are NULL for tobias, so leaving
[5944] 20:02:24: AddInterface: Added tobias: Type- 0, Index- -1, ICB 0x1f94a28
[5944] 20:02:25: InterfaceConnected: InterfaceConnected called for tobias. State is 3
[5944] 20:02:25: BindFilterInterface: No context, assuming interface tobias not added to filter driver
[4144] 20:02:27: Error adding route, Stack bit == 0
[4144] 20:02:31: Error adding route, Stack bit == 0
[4144] 20:02:31: ProcessDefaultRouteChanges: Not default route 187.55.236.168/32
[5944] 20:02:34: AddInterface: Adding vpnuser
[5944] 20:02:34: ICB number for vpnuser is 21


[5944] 20:02:34: ENTERED SetMcastLimitInfo for If ffffffff
[5944] 20:02:34: LEFT SetMcastLimitInfo
[5944] 20:02:34: ENTERED SetBoundaryInfo for If ffffffff
[5944] 20:02:34: LEFT SetBoundaryInfo
[5944] 20:02:34: SetInterfaceFilterInfo: Both filters info are NULL for vpnuser, so leaving
[5944] 20:02:34: AddInterface: Added vpnuser: Type- 0, Index- -1, ICB 0x1f94040
[5944] 20:02:35: InterfaceConnected: InterfaceConnected called for vpnuser. State is 3
[5944] 20:02:35: BindFilterInterface: No context, assuming interface vpnuser not added to filter driver
[4144] 20:02:36: Error adding route, Stack bit == 0
[4144] 20:02:36: Route addition succeeded for
[4144] 20:02:36: 192.168.1.0/255.255.255.0 Proto: 10007 Metric 1
[4144] 20:02:36: Via 10.0.1.2/0x10004 Type 4 Context 0x0
[4144] 20:02:36: Route addition succeeded for
[4144] 20:02:36: 192.168.3.0/255.255.255.0 Proto: 10007 Metric 1
[4144] 20:02:36: Via 10.0.1.2/0x10004 Type 4 Context 0x0
[4144] 20:02:36: Route addition succeeded for
[4144] 20:02:36: 192.168.2.0/255.255.255.0 Proto: 10007 Metric 1
[4144] 20:02:36: Via 10.0.1.2/0x10004 Type 4 Context 0x0
[4144] 20:02:36: ProcessDefaultRouteChanges: Not default route 192.168.1.0/24
[4144] 20:02:36: ProcessDefaultRouteChanges: Not default route 192.168.3.0/24
[4144] 20:02:36: ProcessDefaultRouteChanges: Not default route 192.168.2.0/24
[2744] 20:06:48: WorkerThread: RasAdv Timer event received

[KMDDSP.log]
[7536] 20:01:35:515: lineDrop(24): reqID(10335), call(001A0004)
[7536] 20:01:35:515: ! AsyncDriverRequest: oid(Drop), devID(1), ReqID(10335), reqID(cb), hdCall(c13f)
[6540] 20:01:36:453: lineDrop(25): reqID(10279), call(00320006)
[6540] 20:01:36:453: ! AsyncDriverRequest: oid(Drop), devID(1), ReqID(10279), reqID(cc), hdCall(f58d)
[5424] 20:01:36:562: ! AsyncEventsThread: got a completed req
[5424] 20:01:36:562: ! AsyncEventsThread: req(000A0ED0) with reqID(10335) returned lRes(0)
[5424] 20:01:36:562: lineDrop_post: lRes(0)
[5424] 20:01:36:562: ! postDrop::fnLineEvent(CALLSTATE_IDLE): htline(000102CC), htcall(00010066)
[5424] 20:01:36:562: AsyncEventsThread: call compproc with ReqID(10335), lRes(0)
[5424] 20:01:36:562: ! AsyncEventsThread: got a line event
[5424] 20:01:36:562: ! ProcessEvent: event(000A6290), msg(2), ht_line(00060000), ht_call(80000011), p1(00004000), p2(00000000), p3(00000100)
[7536] 20:01:36:781: lineCloseCall(20): call(001A0004)
[7536] 20:01:36:781: ! SyncDriverRequest: oid(CloseCall), devID(1), reqID(cd), hdCall(0000C13F)
[5424] 20:01:37:515: ! AsyncEventsThread: got a line event
[5424] 20:01:37:515: ! ProcessEvent: event(000A6290), msg(2), ht_line(00060000), ht_call(80000029), p1(00004000), p2(00000000), p3(00000100)
[5424] 20:01:37:515: ! PE::fnLineEvent(CALLSTATE): htline(000102CC), htcall(0001039B), p1(00004000), p2(00000000), p3(00000100)
[5424] 20:01:37:515: ! PE::fnLineEvent(CALLSTATE_IDLE): htline(000102CC), htcall(0001039B), p3(00000100)
[5424] 20:01:37:515: ! AsyncEventsThread: got a completed req
[5424] 20:01:37:515: ! AsyncEventsThread: req(000AB0D8) with reqID(10279) returned lRes(0)
[5424] 20:01:37:515: lineDrop_post: lRes(0)
[5424] 20:01:37:515: AsyncEventsThread: call compproc with ReqID(10279), lRes(0)
[6540] 20:01:37:515: lineDrop(26): reqID(103bd), call(00320006)
[6540] 20:01:37:515: ! AsyncDriverRequest: oid(Drop), devID(1), ReqID(103bd), reqID(ce), hdCall(f58d)
[5424] 20:01:37:515: ! AsyncEventsThread: got a completed req
[5424] 20:01:37:515: ! AsyncEventsThread: req(000A0ED0) with reqID(103bd) returned lRes(80000048)
[5424] 20:01:37:515: lineDrop_post: lRes(80000048)
[5424] 20:01:37:515: AsyncEventsThread: call compproc with ReqID(103bd), lRes(80000048)
[6540] 20:01:37:578: lineCloseCall(21): call(00320006)
[6540] 20:01:37:578: ! SyncDriverRequest: oid(CloseCall), devID(1), reqID(cf), hdCall(0000F58D)
[5424] 20:02:19:875: ! AsyncEventsThread: got a line event
[5424] 20:02:19:875: ! ProcessEvent: event(000A6290), msg(1f4), ht_line(00060000), ht_call(00000000), p1(0000BC5C), p2(8000002B), p3(00000000)
[5424] 20:02:19:875: ! PE::fnLineEvent(NEWCALL): htline(000102CC), call(00340006)
[5424] 20:02:19:875: ! AsyncEventsThread: got a line event
[5424] 20:02:19:875: ! ProcessEvent: event(000A6290), msg(2), ht_line(00060000), ht_call(8000002B), p1(00000002), p2(00000000), p3(00000100)
[5424] 20:02:19:875: ! PE::fnLineEvent(CALLSTATE): htline(000102CC), htcall(0001038A), p1(00000002), p2(00000000), p3(00000100)
[5300] 20:02:19:875: lineGetCallInfo(79): call(00340006)
[5300] 20:02:19:875: ! SyncDriverRequest: oid(GetCallInfo), devID(1), reqID(d0), hdCall(0000BC5C)
[6540] 20:02:19:875: lineGetCallInfo(80): call(00340006)
[6540] 20:02:19:875: ! SyncDriverRequest: oid(GetCallInfo), devID(1), reqID(d1), hdCall(0000BC5C)
[6540] 20:02:19:875: lineAccept(19): reqID(10268), call(00340006)
[6540] 20:02:19:875: ! AsyncDriverRequest: oid(Accept), devID(1), ReqID(10268), reqID(d2), hdCall(bc5c)
[5424] 20:02:19:875: ! AsyncEventsThread: got a completed req
[5424] 20:02:19:875: ! AsyncEventsThread: req(000A0ED0) with reqID(10268) returned lRes(80000048)
[5424] 20:02:19:875: AsyncEventsThread: call compproc with ReqID(10268), lRes(80000048)
[6540] 20:02:19:875: lineAnswer(19): reqID(10257), call(00340006)
[6540] 20:02:19:875: ! AsyncDriverRequest: oid(Answer), devID(1), ReqID(10257), reqID(d3), hdCall(bc5c)
[5424] 20:02:19:875: ! AsyncEventsThread: got a line event
[5424] 20:02:19:875: ! ProcessEvent: event(000A6290), msg(2), ht_line(00060000), ht_call(8000002B), p1(00000100), p2(00000000), p3(00000100)
[5424] 20:02:19:875: ! PE::fnLineEvent(CALLSTATE): htline(000102CC), htcall(0001038A), p1(00000100), p2(00000000), p3(00000100)
[5424] 20:02:19:875: ! AsyncEventsThread: got a completed req
[5424] 20:02:19:875: ! AsyncEventsThread: req(000A0ED0) with reqID(10257) returned lRes(0)
[5424] 20:02:19:875: AsyncEventsThread: call compproc with ReqID(10257), lRes(0)
[6540] 20:02:19:875: lineGetCallInfo(81): call(00340006)
[6540] 20:02:19:875: ! SyncDriverRequest: oid(GetCallInfo), devID(1), reqID(d4), hdCall(0000BC5C)
[6540] 20:02:19:875: lineGetCallInfo(82): call(00340006)
[6540] 20:02:19:875: ! SyncDriverRequest: oid(GetCallInfo), devID(1), reqID(d5), hdCall(0000BC5C)
[6540] 20:02:19:875: lineGetID(21): line(00000000), call(00340006), addressID(0), select(4)
[6540] 20:02:19:875: ! SyncDriverRequest: oid(GetID), devID(1), reqID(d6), hdLine(00000000)
[5424] 20:02:31:562: ! AsyncEventsThread: got a line event
[5424] 20:02:31:562: ! ProcessEvent: event(000A6290), msg(1f4), ht_line(00060000), ht_call(00000000), p1(0000483C), p2(8000002D), p3(00000000)
[5424] 20:02:31:562: ! PE::fnLineEvent(NEWCALL): htline(000102CC), call(00360004)
[5424] 20:02:31:562: ! AsyncEventsThread: got a line event
[5424] 20:02:31:562: ! ProcessEvent: event(000A6290), msg(2), ht_line(00060000), ht_call(8000002D), p1(00000002), p2(00000000), p3(00000100)
[5424] 20:02:31:562: ! PE::fnLineEvent(CALLSTATE): htline(000102CC), htcall(00010379), p1(00000002), p2(00000000), p3(00000100)
[5300] 20:02:31:562: lineGetCallInfo(83): call(00360004)
[5300] 20:02:31:562: ! SyncDriverRequest: oid(GetCallInfo), devID(1), reqID(d7), hdCall(0000483C)
[6540] 20:02:31:562: lineGetCallInfo(84): call(00360004)
[6540] 20:02:31:562: ! SyncDriverRequest: oid(GetCallInfo), devID(1), reqID(d8), hdCall(0000483C)
[6540] 20:02:31:562: lineAccept(20): reqID(10224), call(00360004)
[6540] 20:02:31:562: ! AsyncDriverRequest: oid(Accept), devID(1), ReqID(10224), reqID(d9), hdCall(483c)
[5424] 20:02:31:562: ! AsyncEventsThread: got a completed req
[5424] 20:02:31:562: ! AsyncEventsThread: req(000A0ED0) with reqID(10224) returned lRes(80000048)
[5424] 20:02:31:562: AsyncEventsThread: call compproc with ReqID(10224), lRes(80000048)
[6540] 20:02:31:562: lineAnswer(20): reqID(101e0), call(00360004)
[6540] 20:02:31:562: ! AsyncDriverRequest: oid(Answer), devID(1), ReqID(101e0), reqID(da), hdCall(483c)
[5424] 20:02:31:562: ! AsyncEventsThread: got a line event
[5424] 20:02:31:562: ! ProcessEvent: event(000A6290), msg(2), ht_line(00060000), ht_call(8000002D), p1(00000100), p2(00000000), p3(00000100)
[5424] 20:02:31:562: ! PE::fnLineEvent(CALLSTATE): htline(000102CC), htcall(00010379), p1(00000100), p2(00000000), p3(00000100)
[5424] 20:02:31:562: ! AsyncEventsThread: got a completed req
[5424] 20:02:31:562: ! AsyncEventsThread: req(000A0ED0) with reqID(101e0) returned lRes(0)
[5424] 20:02:31:562: AsyncEventsThread: call compproc with ReqID(101e0), lRes(0)
[6540] 20:02:31:562: lineGetCallInfo(85): call(00360004)
[6540] 20:02:31:562: ! SyncDriverRequest: oid(GetCallInfo), devID(1), reqID(db), hdCall(0000483C)
[6540] 20:02:31:562: lineGetCallInfo(86): call(00360004)
[6540] 20:02:31:562: ! SyncDriverRequest: oid(GetCallInfo), devID(1), reqID(dc), hdCall(0000483C)
[6540] 20:02:31:562: lineGetID(22): line(00000000), call(00360004), addressID(0), select(4)
[6540] 20:02:31:562: ! SyncDriverRequest: oid(GetID), devID(1), reqID(dd), hdLine(00000000)

[RASAPI32.log]
[1504] 20:01:14: RasEnumEntriesW
[1504] 20:02:14: RasEnumEntriesW
tobias
 
Posts: 29
Joined: Sat Apr 21, 2012 9:23 pm
Top

Re: RRAS - VPN Randomly Disconnecting

Postby tobias » Sat Apr 21, 2012 9:57 pm

[RASAUTH.log]
[2488] 20:01:39:515: RasStopAccounting called
[2488] 20:01:39:515: Type=4, Length=4, Value=0xa000001
[2488] 20:01:39:515: Type=6, Length=4, Value=0x2
[2488] 20:01:39:515: Type=7, Length=4, Value=0x1
[2488] 20:01:39:515: Type=5, Length=4, Value=0x82
[2488] 20:01:39:515: Type=26, Length=10, Value=
[2488] 20:01:39:515: 00 00 01 37 09 06 00 00 01 37 00 00 00 00 00 00 |...7.....7......|
[2488] 20:01:39:515: Type=26, Length=16, Value=
[2488] 20:01:39:515: 00 00 01 37 12 0C 4D 53 52 41 53 56 35 2E 32 30 |...7..MSRASV5.20|
[2488] 20:01:39:515: Type=61, Length=4, Value=0x5
[2488] 20:01:39:515: Type=64, Length=4, Value=0x1
[2488] 20:01:39:515: Type=65, Length=4, Value=0x1
[2488] 20:01:39:515: Type=31, Length=10, Value=
[2488] 20:01:39:515: 31 30 2E 30 2E 30 2E 31 39 39 00 00 00 00 00 00 |10.0.0.199......|
[2488] 20:01:39:515: Type=66, Length=10, Value=
[2488] 20:01:39:515: 31 30 2E 30 2E 30 2E 31 39 39 00 00 00 00 00 00 |10.0.0.199......|
[2488] 20:01:39:515: Type=25, Length=30, Value=
[2488] 20:01:39:515: 2D 1C 03 A2 00 00 01 37 00 01 0A 00 00 01 01 CD |-......7........|
[2488] 20:01:39:515: 1D 10 4A C6 E6 66 00 00 00 00 00 00 00 06 00 00 |..J..f..........|
[2488] 20:01:39:515: Type=26, Length=12, Value=
[2488] 20:01:39:515: 00 00 01 37 0A 08 00 54 52 4F 4D 4D 00 00 00 00 |...7...TROMM....|
[2488] 20:01:39:515: Type=44, Length=3, Value=
[2488] 20:01:39:515: 36 32 32 00 00 00 00 00 00 00 00 00 00 00 00 00 |622.............|
[2488] 20:01:39:515: Type=1, Length=12, Value=
[2488] 20:01:39:515: 54 52 4F 4D 4D 5C 74 6F 62 69 61 73 00 00 00 00 |TROMM\tobias....|
[2488] 20:01:39:515: Type=8, Length=4, Value=0xa000103
[2488] 20:01:39:515: Type=12, Length=4, Value=0x514
[2488] 20:01:39:515: Type=50, Length=2, Value=
[2488] 20:01:39:515: 31 31 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |11..............|
[2488] 20:01:39:515: Type=51, Length=4, Value=0x1
[2488] 20:01:39:515: Type=55, Length=4, Value=0x4f909951
[2488] 20:01:39:515: Type=45, Length=4, Value=0x2
[2488] 20:01:39:515: Type=26, Length=10, Value=
[2488] 20:01:39:515: 00 00 01 37 08 06 00 00 00 04 00 00 00 00 00 00 |...7............|
[2488] 20:01:39:515: Type=46, Length=4, Value=0x21fab
[2488] 20:01:39:515: Type=43, Length=4, Value=0xa12e5c
[2488] 20:01:39:515: Type=42, Length=4, Value=0x91e7ff
[2488] 20:01:39:515: Type=48, Length=4, Value=0x2a52d
[2488] 20:01:39:515: Type=47, Length=4, Value=0x2b0be
[2488] 20:01:39:515: Type=49, Length=4, Value=0x1
[2488] 20:01:39:515: Inserting attribute type 4
[2488] 20:01:39:515: Inserting attribute type 6
[2488] 20:01:39:515: Inserting attribute type 7
[2488] 20:01:39:515: Inserting attribute type 5
[2488] 20:01:39:515: Inserting attribute type 26
[2488] 20:01:39:515: Inserting attribute type 26
[2488] 20:01:39:515: Inserting attribute type 61
[2488] 20:01:39:515: Inserting attribute type 64
[2488] 20:01:39:515: Inserting attribute type 65
[2488] 20:01:39:515: Inserting attribute type 31
[2488] 20:01:39:515: Inserting attribute type 66
[2488] 20:01:39:515: Inserting attribute type 25
[2488] 20:01:39:515: Inserting attribute type 26
[2488] 20:01:39:515: Inserting attribute type 44
[2488] 20:01:39:515: Inserting attribute type 1
[2488] 20:01:39:515: Inserting attribute type 8
[2488] 20:01:39:515: Inserting attribute type 12
[2488] 20:01:39:515: Inserting attribute type 50
[2488] 20:01:39:515: Inserting attribute type 51
[2488] 20:01:39:515: Inserting attribute type 55
[2488] 20:01:39:515: Inserting attribute type 45
[2488] 20:01:39:515: Inserting attribute type 26
[2488] 20:01:39:515: Inserting attribute type 46
[2488] 20:01:39:515: Inserting attribute type 43
[2488] 20:01:39:515: Inserting attribute type 42
[2488] 20:01:39:515: Inserting attribute type 48
[2488] 20:01:39:515: Inserting attribute type 47
[2488] 20:01:39:515: Inserting attribute type 49
[2488] 20:01:39:515: Inserting attribute type 4108
[2488] 20:01:39:515: IASResponse = 4, FailureReason = 0x0
[4144] 20:01:39:578: RasStopAccounting called
[4144] 20:01:39:578: Type=4, Length=4, Value=0xa000001
[4144] 20:01:39:578: Type=6, Length=4, Value=0x2
[4144] 20:01:39:578: Type=7, Length=4, Value=0x1
[4144] 20:01:39:578: Type=5, Length=4, Value=0x81
[4144] 20:01:39:578: Type=26, Length=10, Value=
[4144] 20:01:39:578: 00 00 01 37 09 06 00 00 01 37 00 00 00 00 00 00 |...7.....7......|
[4144] 20:01:39:578: Type=26, Length=16, Value=
[4144] 20:01:39:578: 00 00 01 37 12 0C 4D 53 52 41 53 56 35 2E 32 30 |...7..MSRASV5.20|
[4144] 20:01:39:578: Type=61, Length=4, Value=0x5
[4144] 20:01:39:578: Type=64, Length=4, Value=0x1
[4144] 20:01:39:578: Type=65, Length=4, Value=0x1
[4144] 20:01:39:578: Type=31, Length=14, Value=
[4144] 20:01:39:578: 31 38 37 2E 35 35 2E 32 33 36 2E 31 36 38 00 00 |187.55.236.168..|
[4144] 20:01:39:578: Type=66, Length=14, Value=
[4144] 20:01:39:578: 31 38 37 2E 35 35 2E 32 33 36 2E 31 36 38 00 00 |187.55.236.168..|
[4144] 20:01:39:578: Type=25, Length=30, Value=
[4144] 20:01:39:578: 2D 25 03 AB 00 00 01 37 00 01 0A 00 00 01 01 CD |-%.....7........|
[4144] 20:01:39:578: 1D 10 4A C6 E6 66 00 00 00 00 00 00 00 0F 00 00 |..J..f..........|
[4144] 20:01:39:578: Type=22, Length=24, Value=
[4144] 20:01:39:578: 31 39 32 2E 31 36 38 2E 31 2E 30 2F 32 34 20 30 |192.168.1.0/24 0|
[4144] 20:01:39:578: 2E 30 2E 30 2E 30 20 31 00 00 00 00 00 00 00 00 |.0.0.0 1........|
[4144] 20:01:39:578: Type=22, Length=24, Value=
[4144] 20:01:39:578: 31 39 32 2E 31 36 38 2E 33 2E 30 2F 32 34 20 30 |192.168.3.0/24 0|
[4144] 20:01:39:578: 2E 30 2E 30 2E 30 20 31 00 00 00 00 00 00 00 00 |.0.0.0 1........|
[4144] 20:01:39:578: Type=22, Length=24, Value=
[4144] 20:01:39:578: 31 39 32 2E 31 36 38 2E 32 2E 30 2F 32 34 20 30 |192.168.2.0/24 0|
[4144] 20:01:39:578: 2E 30 2E 30 2E 30 20 31 00 00 00 00 00 00 00 00 |.0.0.0 1........|
[4144] 20:01:39:578: Type=26, Length=12, Value=
[4144] 20:01:39:578: 00 00 01 37 0A 08 00 54 52 4F 4D 4D 00 00 00 00 |...7...TROMM....|
[4144] 20:01:39:578: Type=44, Length=3, Value=
[4144] 20:01:39:578: 36 33 31 00 00 00 00 00 00 00 00 00 00 00 00 00 |631.............|
[4144] 20:01:39:578: Type=1, Length=13, Value=
[4144] 20:01:39:578: 54 52 4F 4D 4D 5C 76 70 6E 75 73 65 72 00 00 00 |TROMM\vpnuser...|
[4144] 20:01:39:578: Type=8, Length=4, Value=0xa000102
[4144] 20:01:39:578: Type=12, Length=4, Value=0x5dc
[4144] 20:01:39:578: Type=50, Length=2, Value=
[4144] 20:01:39:578: 32 39 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |29..............|
[4144] 20:01:39:578: Type=51, Length=4, Value=0x1
[4144] 20:01:39:578: Type=55, Length=4, Value=0x4f909951
[4144] 20:01:39:578: Type=45, Length=4, Value=0x2
[4144] 20:01:39:578: Type=26, Length=10, Value=
[4144] 20:01:39:578: 00 00 01 37 08 06 00 00 00 04 00 00 00 00 00 00 |...7............|
[4144] 20:01:39:578: Type=46, Length=4, Value=0x11c1
[4144] 20:01:39:578: Type=43, Length=4, Value=0x4c283
[4144] 20:01:39:578: Type=42, Length=4, Value=0x5c8b5
[4144] 20:01:39:578: Type=48, Length=4, Value=0x1282
[4144] 20:01:39:578: Type=47, Length=4, Value=0x14aa
[4144] 20:01:39:578: Type=49, Length=4, Value=0x1
[4144] 20:01:39:578: Inserting attribute type 4
[4144] 20:01:39:578: Inserting attribute type 6
[4144] 20:01:39:578: Inserting attribute type 7
[4144] 20:01:39:578: Inserting attribute type 5
[4144] 20:01:39:578: Inserting attribute type 26
[4144] 20:01:39:578: Inserting attribute type 26
[4144] 20:01:39:578: Inserting attribute type 61
[4144] 20:01:39:578: Inserting attribute type 64
[4144] 20:01:39:578: Inserting attribute type 65
[4144] 20:01:39:578: Inserting attribute type 31
[4144] 20:01:39:578: Inserting attribute type 66
[4144] 20:01:39:578: Inserting attribute type 25
[4144] 20:01:39:578: Inserting attribute type 22
[4144] 20:01:39:578: Inserting attribute type 22
[4144] 20:01:39:578: Inserting attribute type 22
[4144] 20:01:39:578: Inserting attribute type 26
[4144] 20:01:39:578: Inserting attribute type 44
[4144] 20:01:39:578: Inserting attribute type 1
[4144] 20:01:39:578: Inserting attribute type 8
[4144] 20:01:39:578: Inserting attribute type 12
[4144] 20:01:39:578: Inserting attribute type 50
[4144] 20:01:39:578: Inserting attribute type 51
[4144] 20:01:39:578: Inserting attribute type 55
[4144] 20:01:39:578: Inserting attribute type 45
[4144] 20:01:39:578: Inserting attribute type 26
[4144] 20:01:39:578: Inserting attribute type 46
[4144] 20:01:39:578: Inserting attribute type 43
[4144] 20:01:39:578: Inserting attribute type 42
[4144] 20:01:39:578: Inserting attribute type 48
[4144] 20:01:39:578: Inserting attribute type 47
[4144] 20:01:39:578: Inserting attribute type 49
[4144] 20:01:39:578: Inserting attribute type 4108
[4144] 20:01:39:578: IASResponse = 4, FailureReason = 0x0
[4144] 20:02:21:968: RasAuthProviderAuthenticateUser called
[4144] 20:02:21:968: Type=44, Length=3, Value=
[4144] 20:02:21:968: 36 33 32 00 00 00 00 00 00 00 00 00 00 00 00 00 |632.............|
[4144] 20:02:21:968: Type=4, Length=4, Value=0xa000001
[4144] 20:02:21:968: Type=6, Length=4, Value=0x2
[4144] 20:02:21:968: Type=7, Length=4, Value=0x1
[4144] 20:02:21:968: Type=5, Length=4, Value=0x81
[4144] 20:02:21:968: Type=26, Length=10, Value=
[4144] 20:02:21:968: 00 00 01 37 09 06 00 00 01 37 00 00 00 00 00 00 |...7.....7......|
[4144] 20:02:21:968: Type=26, Length=16, Value=
[4144] 20:02:21:968: 00 00 01 37 12 0C 4D 53 52 41 53 56 35 2E 32 30 |...7..MSRASV5.20|
[4144] 20:02:21:968: Type=61, Length=4, Value=0x5
[4144] 20:02:21:968: Type=64, Length=4, Value=0x1
[4144] 20:02:21:968: Type=65, Length=4, Value=0x1
[4144] 20:02:21:968: Type=31, Length=10, Value=
[4144] 20:02:21:968: 31 30 2E 30 2E 30 2E 31 39 39 00 00 00 00 00 00 |10.0.0.199......|
[4144] 20:02:21:968: Type=66, Length=10, Value=
[4144] 20:02:21:968: 31 30 2E 30 2E 30 2E 31 39 39 00 00 00 00 00 00 |10.0.0.199......|
[4144] 20:02:21:968: Type=1, Length=12, Value=
[4144] 20:02:21:968: 54 52 4F 4D 4D 5C 74 6F 62 69 61 73 00 00 00 00 |TROMM\tobias....|
[4144] 20:02:21:968: Type=26, Length=22, Value=
[4144] 20:02:21:968: 00 00 01 37 0B 12 3F CF 57 EE CF A5 69 B3 1B 86 |...7..?.W...i...|
[4144] 20:02:21:968: 2D 9C 64 DE 0E 36 00 00 00 00 00 00 00 00 00 00 |-.d..6..........|
[4144] 20:02:21:968: Type=26, Length=56, Value=
[4144] 20:02:21:968: 00 00 01 37 19 34 00 00 9E C0 01 3F DC 23 FE EA |...7.4.....?.#..|
[4144] 20:02:21:968: 99 67 47 D0 01 CD 19 9A 42 36 68 00 00 00 00 00 |.gG.....B6h.....|
[4144] 20:02:21:968: EB 84 CB 41 02 46 FC C7 36 44 E7 59 5A 5B AC 03 |...A.F..6D.YZ[..|
[4144] 20:02:21:968: AA EF F3 36 FE B7 15 40 00 00 00 00 00 00 00 00 |...6...@........|
[4144] 20:02:21:968: Inserting attribute type 44
[4144] 20:02:21:968: Inserting attribute type 4
[4144] 20:02:21:968: Inserting attribute type 6
[4144] 20:02:21:968: Inserting attribute type 7
[4144] 20:02:21:968: Inserting attribute type 5
[4144] 20:02:21:968: Inserting attribute type 26
[4144] 20:02:21:968: Inserting attribute type 26
[4144] 20:02:21:968: Inserting attribute type 61
[4144] 20:02:21:968: Inserting attribute type 64
[4144] 20:02:21:968: Inserting attribute type 65
[4144] 20:02:21:968: Inserting attribute type 31
[4144] 20:02:21:968: Inserting attribute type 66
[4144] 20:02:21:968: Inserting attribute type 1
[4144] 20:02:21:968: Inserting attribute type 26
[4144] 20:02:21:968: Inserting attribute type 26
[4144] 20:02:21:968: Inserting attribute type 4108
[4144] 20:02:24:515: IASResponse = ACCESS_ACCEPT
[4144] 20:02:24:515: Received attribute 4105
[4144] 20:02:24:515: Received attribute 4105
[4144] 20:02:24:515: Received attribute 4105
[4144] 20:02:24:515: Received attribute 4105
[4144] 20:02:24:515: Received attribute 7
[4144] 20:02:24:515: Received attribute 6
[4144] 20:02:24:515: Received attribute 8
[4144] 20:02:24:515: Received attribute 25
[4144] 20:02:24:515: Received attribute 26
[4144] 20:02:24:515: Received attribute 26
[4144] 20:02:24:515: Received attribute 26
[4144] 20:02:24:515: Received attribute 26
[4144] 20:02:24:515: Received attribute 26
[4144] 20:02:24:515: Received attribute 26
[4144] 20:02:24:515: Type=4105, Length=4, Value=0x4
[4144] 20:02:24:515: Type=4105, Length=4, Value=0x3
[4144] 20:02:24:515: Type=4105, Length=4, Value=0xa
[4144] 20:02:24:515: Type=4105, Length=4, Value=0x9
[4144] 20:02:24:515: Type=7, Length=4, Value=0x1
[4144] 20:02:24:515: Type=6, Length=4, Value=0x2
[4144] 20:02:24:515: Type=8, Length=4, Value=0xa000103
[4144] 20:02:24:515: Type=25, Length=30, Value=
[4144] 20:02:24:515: 2D 26 03 AC 00 00 01 37 00 01 0A 00 00 01 01 CD |-&.....7........|
[4144] 20:02:24:515: 1D 10 4A C6 E6 66 00 00 00 00 00 00 00 10 00 00 |..J..f..........|
[4144] 20:02:24:515: Type=26, Length=40, Value=
[4144] 20:02:24:515: MS vendor specific 17
[4144] 20:02:24:515: Type=26, Length=40, Value=
[4144] 20:02:24:515: MS vendor specific 16
[4144] 20:02:24:515: Type=26, Length=49, Value=
[4144] 20:02:24:515: 00 00 01 37 1A 2D 00 53 3D 31 33 37 32 39 30 41 |...7.-.S=137290A|
[4144] 20:02:24:515: 33 37 32 41 38 39 36 39 35 30 39 33 38 44 34 42 |372A896950938D4B|
[4144] 20:02:24:515: 42 33 30 34 35 45 41 46 33 36 34 45 39 36 36 41 |B3045EAF364E966A|
[4144] 20:02:24:515: 32 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |2...............|
[4144] 20:02:24:515: Type=26, Length=12, Value=
[4144] 20:02:24:515: 00 00 01 37 0A 08 00 54 52 4F 4D 4D 00 00 00 00 |...7...TROMM....|
[4144] 20:02:24:515: Type=26, Length=10, Value=
[4144] 20:02:24:515: 00 00 01 37 07 06 00 00 00 02 00 00 00 00 00 00 |...7............|
[4144] 20:02:24:515: Type=26, Length=10, Value=
[4144] 20:02:24:515: 00 00 01 37 08 06 00 00 00 0E 00 00 00 00 00 00 |...7............|
[4144] 20:02:25:906: RasStartAccounting called
[4144] 20:02:25:906: Type=4, Length=4, Value=0xa000001
[4144] 20:02:25:906: Type=6, Length=4, Value=0x2
[4144] 20:02:25:906: Type=7, Length=4, Value=0x1
[4144] 20:02:25:906: Type=5, Length=4, Value=0x81
[4144] 20:02:25:906: Type=26, Length=10, Value=
[4144] 20:02:25:906: 00 00 01 37 09 06 00 00 01 37 00 00 00 00 00 00 |...7.....7......|
[4144] 20:02:25:906: Type=26, Length=16, Value=
[4144] 20:02:25:906: 00 00 01 37 12 0C 4D 53 52 41 53 56 35 2E 32 30 |...7..MSRASV5.20|
[4144] 20:02:25:906: Type=61, Length=4, Value=0x5
[4144] 20:02:25:906: Type=64, Length=4, Value=0x1
[4144] 20:02:25:906: Type=65, Length=4, Value=0x1
[4144] 20:02:25:906: Type=31, Length=10, Value=
[4144] 20:02:25:906: 31 30 2E 30 2E 30 2E 31 39 39 00 00 00 00 00 00 |10.0.0.199......|
[4144] 20:02:25:906: Type=66, Length=10, Value=
[4144] 20:02:25:906: 31 30 2E 30 2E 30 2E 31 39 39 00 00 00 00 00 00 |10.0.0.199......|
[4144] 20:02:25:906: Type=25, Length=30, Value=
[4144] 20:02:25:906: 2D 26 03 AC 00 00 01 37 00 01 0A 00 00 01 01 CD |-&.....7........|
[4144] 20:02:25:906: 1D 10 4A C6 E6 66 00 00 00 00 00 00 00 10 00 00 |..J..f..........|
[4144] 20:02:25:906: Type=26, Length=12, Value=
[4144] 20:02:25:906: 00 00 01 37 0A 08 00 54 52 4F 4D 4D 00 00 00 00 |...7...TROMM....|
[4144] 20:02:25:906: Type=44, Length=3, Value=
[4144] 20:02:25:906: 36 33 32 00 00 00 00 00 00 00 00 00 00 00 00 00 |632.............|
[4144] 20:02:25:906: Type=1, Length=12, Value=
[4144] 20:02:25:906: 54 52 4F 4D 4D 5C 74 6F 62 69 61 73 00 00 00 00 |TROMM\tobias....|
[4144] 20:02:25:906: Type=8, Length=4, Value=0xa000103
[4144] 20:02:25:906: Type=12, Length=4, Value=0x514
[4144] 20:02:25:906: Type=50, Length=2, Value=
[4144] 20:02:25:906: 33 31 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |31..............|
[4144] 20:02:25:906: Type=51, Length=4, Value=0x1
[4144] 20:02:25:906: Type=55, Length=4, Value=0x4f909981
[4144] 20:02:25:906: Type=45, Length=4, Value=0x2
[4144] 20:02:25:906: Type=26, Length=10, Value=
[4144] 20:02:25:906: 00 00 01 37 08 06 00 00 00 04 00 00 00 00 00 00 |...7............|
[4144] 20:02:25:906: Inserting attribute type 4
[4144] 20:02:25:906: Inserting attribute type 6
[4144] 20:02:25:906: Inserting attribute type 7
[4144] 20:02:25:906: Inserting attribute type 5
[4144] 20:02:25:906: Inserting attribute type 26
[4144] 20:02:25:906: Inserting attribute type 26
[4144] 20:02:25:906: Inserting attribute type 61
[4144] 20:02:25:906: Inserting attribute type 64
[4144] 20:02:25:906: Inserting attribute type 65
[4144] 20:02:25:906: Inserting attribute type 31
[4144] 20:02:25:906: Inserting attribute type 66
[4144] 20:02:25:906: Inserting attribute type 25
[4144] 20:02:25:906: Inserting attribute type 26
[4144] 20:02:25:906: Inserting attribute type 44
[4144] 20:02:25:906: Inserting attribute type 1
[4144] 20:02:25:906: Inserting attribute type 8
[4144] 20:02:25:906: Inserting attribute type 12
[4144] 20:02:25:906: Inserting attribute type 50
[4144] 20:02:25:906: Inserting attribute type 51
[4144] 20:02:25:906: Inserting attribute type 55
[4144] 20:02:25:906: Inserting attribute type 45
[4144] 20:02:25:906: Inserting attribute type 26
[4144] 20:02:25:906: Inserting attribute type 4108
[4144] 20:02:25:906: IASResponse = 4, FailureReason = 0x0
[4144] 20:02:33:859: RasAuthProviderAuthenticateUser called
[4144] 20:02:33:859: Type=44, Length=3, Value=
[4144] 20:02:33:859: 36 33 33 00 00 00 00 00 00 00 00 00 00 00 00 00 |633.............|
[4144] 20:02:33:859: Type=4, Length=4, Value=0xa000001
[4144] 20:02:33:859: Type=6, Length=4, Value=0x2
[4144] 20:02:33:859: Type=7, Length=4, Value=0x1
[4144] 20:02:33:859: Type=5, Length=4, Value=0x82
[4144] 20:02:33:859: Type=26, Length=10, Value=
[4144] 20:02:33:859: 00 00 01 37 09 06 00 00 01 37 00 00 00 00 00 00 |...7.....7......|
[4144] 20:02:33:859: Type=26, Length=16, Value=
[4144] 20:02:33:859: 00 00 01 37 12 0C 4D 53 52 41 53 56 35 2E 32 30 |...7..MSRASV5.20|
[4144] 20:02:33:859: Type=61, Length=4, Value=0x5
[4144] 20:02:33:859: Type=64, Length=4, Value=0x1
[4144] 20:02:33:859: Type=65, Length=4, Value=0x1
[4144] 20:02:33:859: Type=31, Length=14, Value=
[4144] 20:02:33:859: 31 38 37 2E 35 35 2E 32 33 36 2E 31 36 38 00 00 |187.55.236.168..|
[4144] 20:02:33:859: Type=66, Length=14, Value=
[4144] 20:02:33:859: 31 38 37 2E 35 35 2E 32 33 36 2E 31 36 38 00 00 |187.55.236.168..|
[4144] 20:02:33:859: Type=1, Length=13, Value=
[4144] 20:02:33:859: 54 52 4F 4D 4D 5C 76 70 6E 75 73 65 72 00 00 00 |TROMM\vpnuser...|
[4144] 20:02:33:859: Type=26, Length=22, Value=
[4144] 20:02:33:859: 00 00 01 37 0B 12 4A E9 E4 C7 E9 7B 8E B6 7F 89 |...7..J....{...|
[4144] 20:02:33:859: FE 78 6F 4B EF 14 00 00 00 00 00 00 00 00 00 00 |.xoK............|
[4144] 20:02:33:859: Type=26, Length=56, Value=
[4144] 20:02:33:859: 00 00 01 37 19 34 00 00 6B 5F 93 DC B0 5D C2 51 |...7.4..k_...].Q|
[4144] 20:02:33:859: 51 2C 0C 9E 57 CD E4 B8 42 36 68 00 00 00 00 00 |Q,..W...B6h.....|
[4144] 20:02:33:859: 76 97 D8 61 94 C9 CB 3B 2C AB 91 C0 8B B5 48 12 |v..a...;,.....H.|
[4144] 20:02:33:859: AD B8 DF C4 62 38 6C 23 00 00 00 00 00 00 00 00 |....b8l#........|
[4144] 20:02:33:859: Inserting attribute type 44
[4144] 20:02:33:859: Inserting attribute type 4
[4144] 20:02:33:859: Inserting attribute type 6
[4144] 20:02:33:859: Inserting attribute type 7
[4144] 20:02:33:859: Inserting attribute type 5
[4144] 20:02:33:859: Inserting attribute type 26
[4144] 20:02:33:859: Inserting attribute type 26
[4144] 20:02:33:859: Inserting attribute type 61
[4144] 20:02:33:859: Inserting attribute type 64
[4144] 20:02:33:859: Inserting attribute type 65
[4144] 20:02:33:859: Inserting attribute type 31
[4144] 20:02:33:859: Inserting attribute type 66
[4144] 20:02:33:859: Inserting attribute type 1
[4144] 20:02:33:859: Inserting attribute type 26
[4144] 20:02:33:859: Inserting attribute type 26
[4144] 20:02:33:859: Inserting attribute type 4108
[4144] 20:02:34:375: IASResponse = ACCESS_ACCEPT
[4144] 20:02:34:375: Received attribute 4105
[4144] 20:02:34:375: Received attribute 4105
[4144] 20:02:34:375: Received attribute 4105
[4144] 20:02:34:375: Received attribute 4105
[4144] 20:02:34:375: Received attribute 7
[4144] 20:02:34:375: Received attribute 6
[4144] 20:02:34:375: Received attribute 8
[4144] 20:02:34:375: Received attribute 22
[4144] 20:02:34:375: Received attribute 22
[4144] 20:02:34:375: Received attribute 22
[4144] 20:02:34:375: Received attribute 25
[4144] 20:02:34:375: Received attribute 26
[4144] 20:02:34:375: Received attribute 26
[4144] 20:02:34:375: Received attribute 26
[4144] 20:02:34:375: Received attribute 26
[4144] 20:02:34:375: Received attribute 26
[4144] 20:02:34:375: Received attribute 26
[4144] 20:02:34:375: Type=4105, Length=4, Value=0x4
[4144] 20:02:34:375: Type=4105, Length=4, Value=0x3
[4144] 20:02:34:375: Type=4105, Length=4, Value=0xa
[4144] 20:02:34:375: Type=4105, Length=4, Value=0x9
[4144] 20:02:34:375: Type=7, Length=4, Value=0x1
[4144] 20:02:34:375: Type=6, Length=4, Value=0x2
[4144] 20:02:34:375: Type=8, Length=4, Value=0xa000102
[4144] 20:02:34:375: Type=22, Length=24, Value=
[4144] 20:02:34:375: 31 39 32 2E 31 36 38 2E 31 2E 30 2F 32 34 20 30 |192.168.1.0/24 0|
[4144] 20:02:34:375: 2E 30 2E 30 2E 30 20 31 00 00 00 00 00 00 00 00 |.0.0.0 1........|
[4144] 20:02:34:375: Type=22, Length=24, Value=
[4144] 20:02:34:375: 31 39 32 2E 31 36 38 2E 33 2E 30 2F 32 34 20 30 |192.168.3.0/24 0|
[4144] 20:02:34:375: 2E 30 2E 30 2E 30 20 31 00 00 00 00 00 00 00 00 |.0.0.0 1........|
[4144] 20:02:34:375: Type=22, Length=24, Value=
[4144] 20:02:34:375: 31 39 32 2E 31 36 38 2E 32 2E 30 2F 32 34 20 30 |192.168.2.0/24 0|
[4144] 20:02:34:375: 2E 30 2E 30 2E 30 20 31 00 00 00 00 00 00 00 00 |.0.0.0 1........|
[4144] 20:02:34:375: Type=25, Length=30, Value=
[4144] 20:02:34:375: 2D 27 03 AD 00 00 01 37 00 01 0A 00 00 01 01 CD |-'.....7........|
[4144] 20:02:34:375: 1D 10 4A C6 E6 66 00 00 00 00 00 00 00 11 00 00 |..J..f..........|
[4144] 20:02:34:375: Type=26, Length=40, Value=
[4144] 20:02:34:375: MS vendor specific 17
[4144] 20:02:34:375: Type=26, Length=40, Value=
[4144] 20:02:34:375: MS vendor specific 16
[4144] 20:02:34:375: Type=26, Length=49, Value=
[4144] 20:02:34:375: 00 00 01 37 1A 2D 00 53 3D 38 37 33 46 45 46 43 |...7.-.S=873FEFC|
[4144] 20:02:34:375: 39 31 37 30 45 45 37 43 38 41 32 31 32 34 31 30 |9170EE7C8A212410|
[4144] 20:02:34:375: 43 42 46 31 39 44 45 34 41 33 38 32 42 44 45 34 |CBF19DE4A382BDE4|
[4144] 20:02:34:375: 42 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |B...............|
[4144] 20:02:34:375: Type=26, Length=12, Value=
[4144] 20:02:34:375: 00 00 01 37 0A 08 00 54 52 4F 4D 4D 00 00 00 00 |...7...TROMM....|
[4144] 20:02:34:375: Type=26, Length=10, Value=
[4144] 20:02:34:375: 00 00 01 37 07 06 00 00 00 02 00 00 00 00 00 00 |...7..
tobias
 
Posts: 29
Joined: Sat Apr 21, 2012 9:23 pm
Top

Re: RRAS - VPN Randomly Disconnecting

Postby tobias » Sat Apr 21, 2012 9:58 pm

[RASCCP.log]
[3960] 04-18 20:01:13:406: CcpEnd Called
[3960] 04-18 20:02:05:218: Will force encryption
[3960] 04-18 20:02:05:218: EncryptionTypes: 0xf0
[3960] 04-18 20:02:05:218: Send capabilites from NDISWAN = 0x10000e1
[3960] 04-18 20:02:05:218: Receive capabilites from NDISWAN = 0x10000e1
[3960] 04-18 20:02:05:218: Send RCI_MacCompressionType = 0xff
[3960] 04-18 20:02:05:218: Receive RCI_MacCompressionType = 0xff
[3960] 04-18 20:02:05:218: Send Encryption is Forced 0x10000e1
[3960] 04-18 20:02:05:218: Receive Encryption is Forced 0x10000e1
[3960] 04-18 20:02:05:218: ForceEncryption
[3960] 04-18 20:02:06:359: CCP Send MSPPC bits negotiated = 0x1000040
[3960] 04-18 20:02:06:359: CCP Recv MSPPC bits negotiated = 0x1000040
[3960] 04-18 20:02:12:859: CcpEnd Called
[3960] 04-18 20:02:35:078: Will force encryption
[3960] 04-18 20:02:35:078: EncryptionTypes: 0xf0
[3960] 04-18 20:02:35:078: Send capabilites from NDISWAN = 0x10000e1
[3960] 04-18 20:02:35:078: Receive capabilites from NDISWAN = 0x10000e1
[3960] 04-18 20:02:35:078: Send RCI_MacCompressionType = 0xff
[3960] 04-18 20:02:35:078: Receive RCI_MacCompressionType = 0xff
[3960] 04-18 20:02:35:078: Send Encryption is Forced 0x10000e1
[3960] 04-18 20:02:35:078: Receive Encryption is Forced 0x10000e1
[3960] 04-18 20:02:35:078: ForceEncryption
[3960] 04-18 20:02:35:750: CCP Send MSPPC bits negotiated = 0x1000040
[3960] 04-18 20:02:35:750: CCP Recv MSPPC bits negotiated = 0x1000040

[RASCHAP.log]
[3960] 04-19 20:01:32:453: ChapEnd
[3960] 04-19 20:01:32:453: ChapEnd
[3960] 04-19 20:02:21:937: ChapBegin(fS=1,bA=0x81)
[3960] 04-19 20:02:21:937: ChapBegin done.
[3960] 04-19 20:02:21:937: ChapMakeMessage,RBuf=00000000
[3960] 04-19 20:02:21:937: CS_Initial...
[3960] 04-19 20:02:21:937: MakeChallengeMessage...
01 00 00 1D 10 3F CF 57 EE CF A5 69 B3 1B 86 2D |.....?.W...i...-|
9C 64 DE 0E 36 53 45 52 56 49 44 4F 52 00 00 00 |.d..6SERVIDOR...|
[3960] 04-19 20:02:21:968: ChapMakeMessage,RBuf=01E01ECA
[3960] 04-19 20:02:21:968: CS_ChallengeSent...
[3960] 04-19 20:02:24:515: ChapMakeMessage,RBuf=00000000
[3960] 04-19 20:02:24:515: Result=0,Tries=2
[3960] 04-19 20:02:24:515: CS_Done...
03 00 00 2E 53 3D 31 33 37 32 39 30 41 33 37 32 |....S=137290A372|
41 38 39 36 39 35 30 39 33 38 44 34 42 42 33 30 |A896950938D4BB30|
34 35 45 41 46 33 36 34 45 39 36 36 41 32 00 00 |45EAF364E966A2..|
[3960] 04-19 20:02:33:796: ChapBegin(fS=1,bA=0x81)
[3960] 04-19 20:02:33:796: ChapBegin done.
[3960] 04-19 20:02:33:796: ChapMakeMessage,RBuf=00000000
[3960] 04-19 20:02:33:796: CS_Initial...
[3960] 04-19 20:02:33:796: MakeChallengeMessage...
01 00 00 1D 10 4A E9 E4 C7 E9 7B 8E B6 7F 89 FE |.....J....{....|
78 6F 4B EF 14 53 45 52 56 49 44 4F 52 00 00 00 |xoK..SERVIDOR...|
[3960] 04-19 20:02:33:859: ChapMakeMessage,RBuf=01E01ECA
[3960] 04-19 20:02:33:859: CS_ChallengeSent...
[3960] 04-19 20:02:34:375: ChapMakeMessage,RBuf=00000000
[3960] 04-19 20:02:34:375: Result=0,Tries=2
[3960] 04-19 20:02:34:375: CS_Done...

[RASIPPCP.log]
[3960] 04-19 20:01:35:453: IPCP: IpcpThisLayerFinished...
[3960] 04-19 20:01:35:453: IPCP: RasSrvrReleaseAddress...
[3960] 04-19 20:01:35:453: IPCP: RasSrvrReleaseAddress done
[3960] 04-19 20:01:35:453: IPCP: RasDeAllocateRoute...
[3960] 04-19 20:01:35:453: IPCP: IpcpThisLayerFinished done(0)
[3960] 04-19 20:01:36:453: IPCP: IpcpThisLayerFinished...
[3960] 04-19 20:01:36:453: IPCP: RasSrvrReleaseAddress...
[3960] 04-19 20:01:36:453: IPCP: RasSrvrReleaseAddress done
[3960] 04-19 20:01:36:453: IPCP: RasDeAllocateRoute...
[3960] 04-19 20:01:36:453: IPCP: IpcpThisLayerFinished done(0)
[3960] 04-19 20:01:37:515: IPCP: IpcpEnd...
[3960] 04-19 20:01:37:515: IPCP: IpcpThisLayerFinished...
[3960] 04-19 20:01:37:515: IPCP: IpcpThisLayerFinished done(0)
[3960] 04-19 20:01:37:531: IPCP: IpcpEnd done(0)
[3960] 04-19 20:01:37:578: IPCP: IpcpEnd...
[3960] 04-19 20:01:37:578: IPCP: IpcpThisLayerFinished...
[3960] 04-19 20:01:37:578: IPCP: IpcpThisLayerFinished done(0)
[3960] 04-19 20:01:37:578: IPCP: IpcpEnd done(0)
[3960] 04-19 20:02:24:515: IPCP: IpcpBegin
[3960] 04-19 20:02:24:515: IPCP: Hard IP=0
[3960] 04-19 20:02:24:515: IPCP: Using IP address attribute 0x301000a
[3960] 04-19 20:02:24:515: IPCP: VJ disabled for VPN
[3960] 04-19 20:02:24:515: IPCP: Compress capabilities: s=$0,0,0 r=$0,15,1
[3960] 04-19 20:02:24:515: IPCP: Server address lookup...
[3960] 04-19 20:02:24:515: IPCP: RasSrvrQueryServerAddresses...
[3960] 04-19 20:02:24:671: IPCP: RasSrvrQueryServerAddresses done(0)
[3960] 04-19 20:02:24:671: IPCP:Dns=0100000a,Wins=00000000,DnsB=00000000,WinsB=00000000,Server=0101000a,Mask=ffffffff
[3960] 04-19 20:02:24:671: IPCP: IpcpMakeConfigRequest
[3960] 04-19 20:02:24:671: IPCP: ConfigRequest...
[3960] 20:02:24:671: 01 04 00 0A 03 06 0A 00 01 01 00 00 00 00 00 00 |................|
[3960] 04-19 20:02:24:703: IPCP: IpcpMakeConfigResult for...
[3960] 20:02:24:703: 01 01 00 1C 02 06 00 2D 0F 01 03 06 0A 00 00 C7 |.......-........|
[3960] 20:02:24:703: 81 06 00 00 00 00 83 06 00 00 00 00 00 00 00 00 |................|
[3960] 04-19 20:02:24:703: IPCP: RejectCheck
[3960] 04-19 20:02:24:703: IPCP: Rejecting IP compression
[3960] 04-19 20:02:24:703: IPCP: Rejecting $83
[3960] 04-19 20:02:24:718: IPCP: IpcpMakeConfigResult for...
[3960] 20:02:24:718: 01 02 00 10 03 06 0A 00 00 C7 81 06 00 00 00 00 |................|
[3960] 04-19 20:02:24:718: IPCP: RejectCheck
[3960] 04-19 20:02:24:718: IPCP: NakCheck
[3960] 04-19 20:02:24:718: IPCP: RasSrvrAcquireAddress(c700000a)...
[3960] 04-19 20:02:24:718: IPCP: RasSrvrAcquireAddress done(0)
[3960] 04-19 20:02:24:718: IPCP: Hard IP requested
[3960] 04-19 20:02:24:718: IPCP: 3rd party DLL changed IP
[3960] 04-19 20:02:24:718: IPCP: Naking IP
[3960] 04-19 20:02:24:718: IPCP: Naking $81
[3960] 04-19 20:02:24:734: IPCP: IpcpMakeConfigResult for...
[3960] 20:02:24:734: 01 03 00 10 03 06 0A 00 01 03 81 06 0A 00 00 01 |................|
[3960] 04-19 20:02:24:734: IPCP: RejectCheck
[3960] 04-19 20:02:24:734: IPCP: NakCheck
[3960] 04-19 20:02:24:734: IPCP: ConfigResult...
[3960] 20:02:24:734: 02 03 00 10 03 06 0A 00 01 03 81 06 0A 00 00 01 |................|
[3960] 04-19 20:02:25:890: IPCP: IpcpMakeConfigRequest
[3960] 04-19 20:02:25:890: IPCP: ConfigRequest...
[3960] 20:02:25:890: 01 03 00 0A 03 06 0A 00 01 01 00 00 00 00 00 00 |................|
[3960] 04-19 20:02:25:906: IPCP: IpcpConfigAckReceived...

[RASIPHLP.log]
[3960] 04-19 20:01:35:453: RasSrvrReleaseAddress(IP address: 0x301000a, UserName: tobias, PortName: VPN3-126)
[3960] 04-19 20:01:35:453: RasStatReleaseAddress
[3960] 04-19 20:01:35:453: Released 0x301000a
[3960] 04-19 20:01:35:453: RasTcpSetProxyArp(IP Addr: 0x301000a, fAddAddress: FALSE)
[3960] 04-19 20:01:35:453: rasSrvrGetAddressForServerAdapter
[3960] 04-19 20:01:35:453: RasTcpSetRoute(Dest: 0x301000a, Mask: 0xffffffff, NextHop: 0x301000a, Intf: 0x101000a, 1, Del, Stack)
[3960] 04-19 20:01:36:453: RasSrvrReleaseAddress(IP address: 0x201000a, UserName: vpnuser, PortName: VPN3-127)
[3960] 04-19 20:01:36:453: RasStatReleaseAddress
[3960] 04-19 20:01:36:453: IpAddress 0x201000a not present in alloc pool
[3960] 04-19 20:01:36:453: RasTcpSetProxyArp(IP Addr: 0x201000a, fAddAddress: FALSE)
[3960] 04-19 20:01:36:453: rasSrvrGetAddressForServerAdapter
[3960] 04-19 20:01:36:453: RasTcpSetRoute(Dest: 0x201000a, Mask: 0xffffffff, NextHop: 0x201000a, Intf: 0x101000a, 1, Del, Stack)
[3960] 04-19 20:02:24:515: RasSrvrQueryServerAddresses
[3960] 04-19 20:02:24:515: rasSrvrGetAddressForServerAdapter
[3960] 04-19 20:02:24:515: GetPreferredAdapterInfo
[3960] 04-19 20:02:24:515: GetAdapterInfo
[3960] 04-19 20:02:24:718: RasSrvrAcquireAddress(hPort: 0x81, IP address: 0x301000a, UserName: tobias, PortName: VPN3-127)
[3960] 04-19 20:02:24:718: rasSrvrGetAddressForServerAdapter
[3960] 04-19 20:02:25:906: RasSrvrActivateIp(IpAddr = 0x301000a, dwUsage = 0)
[3960] 04-19 20:02:25:906: RasTcpSetProxyArp(IP Addr: 0x301000a, fAddAddress: TRUE)
[3960] 04-19 20:02:25:906: rasSrvrGetAddressForServerAdapter
[3960] 04-19 20:02:25:906: RasTcpSetRoute(Dest: 0x301000a, Mask: 0xffffffff, NextHop: 0x301000a, Intf: 0x101000a, 1, Add, Stack)
[3960] 04-19 20:02:34:375: RasSrvrQueryServerAddresses
[3960] 04-19 20:02:34:375: rasSrvrGetAddressForServerAdapter
[3960] 04-19 20:02:34:375: GetPreferredAdapterInfo
[3960] 04-19 20:02:34:375: GetAdapterInfo
[3960] 04-19 20:02:34:578: RasSrvrAcquireAddress(hPort: 0x82, IP address: 0x201000a, UserName: vpnuser, PortName: VPN3-126)
[3960] 04-19 20:02:34:578: rasSrvrGetAddressForServerAdapter
[3960] 04-19 20:02:35:687: RasSrvrActivateIp(IpAddr = 0x201000a, dwUsage = 0)
[3960] 04-19 20:02:35:687: RasTcpSetProxyArp(IP Addr: 0x201000a, fAddAddress: TRUE)
[3960] 04-19 20:02:35:687: rasSrvrGetAddressForServerAdapter
[3960] 04-19 20:02:35:687: RasTcpSetRoute(Dest: 0x201000a, Mask: 0xffffffff, NextHop: 0x201000a, Intf: 0x101000a, 1, Add, Stack)
tobias
 
Posts: 29
Joined: Sat Apr 21, 2012 9:23 pm
Top

Re: RRAS - VPN Randomly Disconnecting

Postby tobias » Sat Apr 21, 2012 9:58 pm

[RASMAN.log]
[3960] 04-19 20:01:35:453: DeallocateRouteRequestCommon: pBundle=0xd15bd88, type=0x800
[3960] 04-19 20:01:35:453: DeActivated Route , bundlehandle 0x6, prottype = 2048
[3960] 04-19 20:01:35:453: DwSetTcpWindowSize: Failed to write window size. 0x2
[3960] 04-19 20:01:35:453: DeAllocateRoute: PI_Type=0x800, PI_AdapterName=\DEVICE\{0209563D-AD02-4963-AE44-A3AD58E9432A}, PI_Allocated=-1
[3960] 04-19 20:01:35:453: DeAlloc..: increasing the avail. count for IP
[3960] 04-19 20:01:35:453: NewInUse for IpOut = 1
[3960] 04-19 20:01:35:453: Ignoring removal request for 1
[3960] 04-19 20:01:35:453: Ignoring removal request for 2
[3960] 04-19 20:01:35:453: DwRemoveEndPointsifRequired: Nothing to remove
[5944] 04-19 20:01:35:453: PortDisconnectRequest on VPN3-126 Connection=0x0 ,RasmanReceiveFlags=0x4
[5944] 04-19 20:01:35:453: PortDisconnectRequest: Disconnecting VPN3-126
[5944] 04-19 20:01:35:453: Disconnecting Port 0xVPN3-126, reason 0
[5944] 04-19 20:01:35:453: DisconnectPort: Saving Bundle stats for port VPN3-126
[5944] 04-19 20:01:35:515: d:\nt\net\rras\ras\rasman\rasman\util.c 1997: Disconnected Port 130, reason 0. rc=0x258
[5944] 04-19 20:01:35:515: FreeBundle: freeing pBundle=0xd15bd88
[5944] 04-19 20:01:35:515: d:\nt\net\rras\ras\rasman\rasman\util.c: 2218: port 130 state chg: prev=2, new=3
[5944] 04-19 20:01:35:515: d:\nt\net\rras\ras\rasman\rasman\util.c: 2288: port 130 async reqtype chg: prev=26, new=9
[5944] 04-19 20:01:35:515: Disconnect request on port: VPN3-126
[5340] 04-19 20:01:35:515: OVEVT_RASMAN_ADJUST_TIMER
[5340] 04-19 20:01:35:515: OVEVT_RASMAN_ADJUST_TIMER
[3960] 04-19 20:01:36:453: DeallocateRouteRequestCommon: pBundle=0x136de0, type=0x800
[3960] 04-19 20:01:36:453: DeActivated Route , bundlehandle 0x12, prottype = 2048
[3960] 04-19 20:01:36:453: DwSetTcpWindowSize: Failed to write window size. 0x2
[3960] 04-19 20:01:36:453: DeAllocateRoute: PI_Type=0x800, PI_AdapterName=\DEVICE\{0209563D-AD02-4963-AE44-A3AD58E9432A}, PI_Allocated=-1
[3960] 04-19 20:01:36:453: DeAlloc..: increasing the avail. count for IP
[3960] 04-19 20:01:36:453: NewInUse for IpOut = 0
[3960] 04-19 20:01:36:453: DwAdjustEndPoints: successfully queued workitem - 0x758fdfb9
[5944] 04-19 20:01:36:453: PortDisconnectRequest on VPN3-127 Connection=0x0 ,RasmanReceiveFlags=0x4
[5944] 04-19 20:01:36:453: PortDisconnectRequest: Disconnecting VPN3-127
[5944] 04-19 20:01:36:453: Disconnecting Port 0xVPN3-127, reason 0
[5944] 04-19 20:01:36:453: DisconnectPort: Saving Bundle stats for port VPN3-127
[5944] 04-19 20:01:36:453: d:\nt\net\rras\ras\rasman\rasman\util.c 1997: Disconnected Port 129, reason 0. rc=0x258
[5944] 04-19 20:01:36:453: FreeBundle: freeing pBundle=0x136de0
[5944] 04-19 20:01:36:453: d:\nt\net\rras\ras\rasman\rasman\util.c: 2218: port 129 state chg: prev=2, new=3
[5944] 04-19 20:01:36:453: d:\nt\net\rras\ras\rasman\rasman\util.c: 2288: port 129 async reqtype chg: prev=26, new=9
[5944] 04-19 20:01:36:453: Disconnect request on port: VPN3-127
[5340] 04-19 20:01:36:453: OVEVT_RASMAN_ADJUST_TIMER
[5340] 04-19 20:01:36:453: OVEVT_RASMAN_ADJUST_TIMER
[924] 04-19 20:01:36:671: RemoveEndPoints: Ignoring ep removal for 1
[924] 04-19 20:01:36:671: RemoveEndPoints: Ignoring ep removal for 2
[924] 04-19 20:01:36:671: Removing 2 IpOut from wanarp
[5340] 04-19 20:01:37:515: WorkerThread: Disconnect event signaled on port: VPN3-126
[5340] 04-19 20:01:37:515: OVEVT_DEV_STATECHANGE. pOverlapped = 0x58f5150
[5340] 04-19 20:01:37:515: d:\nt\net\rras\ras\rasman\rasman\request.c: 4723: port 130 state chg: prev=3, new=4
[5340] 04-19 20:01:37:515: d:\nt\net\rras\ras\rasman\rasman\request.c: 4734: port 130 async reqtype chg: prev=9, new=0
[5340] 04-19 20:01:37:515: CompleteDisconnectRequest: signalling 0x2590 for VPN3-126
[5340] 04-19 20:01:37:515: Disconnect completed on port: VPN3-126
[5340] 04-19 20:01:37:578: WorkerThread: Disconnect event signaled on port: VPN3-127
[5340] 04-19 20:01:37:578: OVEVT_DEV_STATECHANGE. pOverlapped = 0x58f5550
[5340] 04-19 20:01:37:578: d:\nt\net\rras\ras\rasman\rasman\request.c: 4723: port 129 state chg: prev=3, new=4
[5340] 04-19 20:01:37:578: d:\nt\net\rras\ras\rasman\rasman\request.c: 4734: port 129 async reqtype chg: prev=9, new=0
[5340] 04-19 20:01:37:578: CompleteDisconnectRequest: signalling 0x2248 for VPN3-127
[5340] 04-19 20:01:37:578: Disconnect completed on port: VPN3-127
[5944] 04-19 20:01:39:515: SendNotificationRequest
[5944] 04-19 20:01:39:515: DwSendNotification returned 0x0
[5944] 04-19 20:01:39:515: DeviceListenRequest: Clearing Autoclose flag on port VPN3-126
[5944] 04-19 20:01:39:515: d:\nt\net\rras\ras\rasman\rasman\util.c: 2552: port 130 state chg: prev=4, new=1
[5944] 04-19 20:01:39:515: d:\nt\net\rras\ras\rasman\rasman\util.c: 2583: port 130 async reqtype chg: prev=0, new=27
[5944] 04-19 20:01:39:515: Listen posted on port: VPN3-126, error code 600
[5944] 04-19 20:01:39:578: SendNotificationRequest
[5944] 04-19 20:01:39:578: DwSendNotification returned 0x0
[5944] 04-19 20:01:39:578: DeviceListenRequest: Clearing Autoclose flag on port VPN3-127
[5944] 04-19 20:01:39:578: d:\nt\net\rras\ras\rasman\rasman\util.c: 2552: port 129 state chg: prev=4, new=1
[5944] 04-19 20:01:39:578: d:\nt\net\rras\ras\rasman\rasman\util.c: 2583: port 129 async reqtype chg: prev=0, new=27
[5944] 04-19 20:01:39:578: Listen posted on port: VPN3-127, error code 600
[5340] 04-19 20:02:19:875: WorkerThread: Async work event signaled on port: VPN3-127
[5340] 04-19 20:02:19:875: OVEVT_DEV_ASYNCOP. pOverlapped = 0x58f5510
[5340] 04-19 20:02:19:875: ServiceWorkRequest: Async op event 27 for port VPN3-127 returned 600
[5340] 04-19 20:02:19:875: WorkerThread: Async work event signaled on port: VPN3-127
[5340] 04-19 20:02:19:875: OVEVT_DEV_ASYNCOP. pOverlapped = 0x58f5510
[5340] 04-19 20:02:19:875: ServiceWorkRequest: Async op event 27 for port VPN3-127 returned 600
[5340] 04-19 20:02:19:875: WorkerThread: Async work event signaled on port: VPN3-127
[5340] 04-19 20:02:19:875: OVEVT_DEV_ASYNCOP. pOverlapped = 0x58f5510
[5340] 04-19 20:02:19:875: d:\nt\net\rras\ras\rasman\rasman\request.c: 7623: port 129 state chg: prev=1, new=5
[5340] 04-19 20:02:19:875: RasmanReceiveFlags = 0x0
[5340] 04-19 20:02:19:875: d:\nt\net\rras\ras\rasman\rasman\worker.c: 2356: port 129 async reqtype chg: prev=27, new=0
[5340] 04-19 20:02:19:875: ServiceWorkRequest: Async op event 27 for port VPN3-127 returned 0
[5944] 04-19 20:02:19:875: ConnectCompleteRequest: entered for port 129
[5944] 04-19 20:02:19:875: d:\nt\net\rras\ras\rasman\rasman\request.c: 7499: port 129 state chg: prev=5, new=2
[5944] 04-19 20:02:19:875: AllocBundle: pBundle=0xd0cc2b0

[5944] 04-19 20:02:19:875: d:\nt\net\rras\ras\rasman\rasman\request.c 9017: Mapping Cookie to handle. port = VPN3-127(0x594f270), Bundlehandle = 0x13, linkhandle = 0x13
[5944] 04-19 20:02:19:875: DwSaveIpAddressInfo: pszAddress=10.0.0.199
[5944] 04-19 20:02:19:875: ConnectCompleteRequest: DwSaveIpAddressInfo returned 0x0
[5944] 04-19 20:02:19:875: Connection Completed on port: VPN3-127, error code: 0
[5944] 04-19 20:02:19:875: d:\nt\net\rras\ras\rasman\rasman\request.c: 6691: port 129 async reqtype chg: prev=0, new=26
[5340] 04-19 20:02:21:890: Completed receive - First Frame on VPN3-127, handle=0x247c
[3960] 04-19 20:02:21:890: GetConnectInfo: port VPN3-127
[3960] 04-19 20:02:21:890: GetConnectInfo: size=52, rc=0xx0
[3960] 04-19 20:02:21:890: GetConnectInfo: port VPN3-127
[3960] 04-19 20:02:21:890: GetConnectInfo: size=52, rc=0xx0
[3960] 04-19 20:02:21:890: GetConnectInfo: port VPN3-127
[3960] 04-19 20:02:21:890: GetConnectInfo: size=52, rc=0xx0
[3960] 04-19 20:02:21:890: GetConnectInfo: port VPN3-127
[3960] 04-19 20:02:21:890: GetConnectInfo: size=52, rc=0xx0
[3960] 04-19 20:02:21:890: PppStarted...VPN3-127
[3960] 04-19 20:02:21:890: PortReceive: Invalid SendRcvBuffer passed
[3960] 04-19 20:02:25:906: Usage for the call on VPN3-127 is 0
[3960] 04-19 20:02:25:906: New InUse for IpOut=01

[3960] 04-19 20:02:25:906: d:\nt\net\rras\ras\rasman\rasman\request.c, 7061: Activated Route , port = VPN3-127(0x594f270), bundlehandle 0x13, prottype = 2048, dwErr = 0
[3960] 04-19 20:02:25:906: DwAddEndPointsIfRequired: WorkItem in progress..
[5944] 04-19 20:02:25:906: SendNotificationRequest
[5944] 04-19 20:02:25:906: DwSendNotification returned 0x0
[5340] 04-19 20:02:31:562: WorkerThread: Async work event signaled on port: VPN3-126
[5340] 04-19 20:02:31:562: OVEVT_DEV_ASYNCOP. pOverlapped = 0x58f5110
[5340] 04-19 20:02:31:562: ServiceWorkRequest: Async op event 27 for port VPN3-126 returned 600
[5340] 04-19 20:02:31:562: WorkerThread: Async work event signaled on port: VPN3-126
[5340] 04-19 20:02:31:562: OVEVT_DEV_ASYNCOP. pOverlapped = 0x58f5110
[5340] 04-19 20:02:31:562: ServiceWorkRequest: Async op event 27 for port VPN3-126 returned 600
[5340] 04-19 20:02:31:562: WorkerThread: Async work event signaled on port: VPN3-126
[5340] 04-19 20:02:31:562: OVEVT_DEV_ASYNCOP. pOverlapped = 0x58f5110
[5340] 04-19 20:02:31:562: d:\nt\net\rras\ras\rasman\rasman\request.c: 7623: port 130 state chg: prev=1, new=5
[5340] 04-19 20:02:31:562: RasmanReceiveFlags = 0x0
[5340] 04-19 20:02:31:562: d:\nt\net\rras\ras\rasman\rasman\worker.c: 2356: port 130 async reqtype chg: prev=27, new=0
[5340] 04-19 20:02:31:562: ServiceWorkRequest: Async op event 27 for port VPN3-126 returned 0
[5944] 04-19 20:02:31:562: ConnectCompleteRequest: entered for port 130
[5944] 04-19 20:02:31:562: d:\nt\net\rras\ras\rasman\rasman\request.c: 7499: port 130 state chg: prev=5, new=2
[5944] 04-19 20:02:31:562: AllocBundle: pBundle=0xd131150

[5944] 04-19 20:02:31:562: d:\nt\net\rras\ras\rasman\rasman\request.c 9017: Mapping Cookie to handle. port = VPN3-126(0x594f948), Bundlehandle = 0x14, linkhandle = 0x14
[5944] 04-19 20:02:31:562: DwSaveIpAddressInfo: pszAddress=187.55.236.168
[5944] 04-19 20:02:31:562: ConnectCompleteRequest: DwSaveIpAddressInfo returned 0x0
[5944] 04-19 20:02:31:562: Connection Completed on port: VPN3-126, error code: 0
[5944] 04-19 20:02:31:562: d:\nt\net\rras\ras\rasman\rasman\request.c: 6691: port 130 async reqtype chg: prev=0, new=26
[5340] 04-19 20:02:33:625: Completed receive - First Frame on VPN3-126, handle=0x2248
[3960] 04-19 20:02:33:625: GetConnectInfo: port VPN3-126
[3960] 04-19 20:02:33:625: GetConnectInfo: size=52, rc=0xx0
[3960] 04-19 20:02:33:625: GetConnectInfo: port VPN3-126
[3960] 04-19 20:02:33:625: GetConnectInfo: size=52, rc=0xx0
[3960] 04-19 20:02:33:625: GetConnectInfo: port VPN3-126
[3960] 04-19 20:02:33:625: GetConnectInfo: size=52, rc=0xx0
[3960] 04-19 20:02:33:625: GetConnectInfo: port VPN3-126
[3960] 04-19 20:02:33:625: GetConnectInfo: size=52, rc=0xx0
[3960] 04-19 20:02:33:625: PppStarted...VPN3-126
[3960] 04-19 20:02:33:625: PortReceive: Invalid SendRcvBuffer passed
[3960] 04-19 20:02:35:687: Usage for the call on VPN3-126 is 0
[3960] 04-19 20:02:35:687: New InUse for IpOut=02

[3960] 04-19 20:02:35:687: d:\nt\net\rras\ras\rasman\rasman\request.c, 7061: Activated Route , port = VPN3-126(0x594f948), bundlehandle 0x14, prottype = 2048, dwErr = 0
[3960] 04-19 20:02:35:687: DwAddEndPointsIfRequired: WorkItem in progress..
[5944] 04-19 20:02:35:687: SendNotificationRequest
[5944] 04-19 20:02:35:687: DwSendNotification returned 0x0

[tapi32.log]
[5944] 20:01:11:937: [TRACE] DoFunc -- enter
[5944] 20:01:11:937: [TRACE] AllocClientResources: enter
[5944] 20:01:11:937: [TRACE] AllocClientResources: exit, returning x0
[5944] 20:01:12:000: [TRACE] DoFunc: back from srv- return code=0x000100f0
[5944] 20:01:12:000: [TRACE] DoFunc: result = x100f0
[3844] 20:01:13:390: [INFO ] AsyncEventsThread: msg=2, hDev=x10123, p1=x1, p2=x0, p3=x0
[3844] 20:01:13:390: [INFO ] AsyncEventsThread: posting msg, hwnd=x1013a
[3844] 20:01:13:390: [INFO ] AsyncEventsThread: msg=12, hDev=x0, p1=x100f0, p2=x0, p3=x0
[5952] 20:01:13:406: [TRACE] TAPIWndProc: received WM_ASYNCEVENT, hwnd=x0001013A
[5952] 20:01:13:406: [INFO ] Calling app's callback, hDev=x10123, Msg=2, dwInst=x58c04e0 P1=x1, P2=x0 P3=x0
[5952] 20:01:13:406: [INFO ] Calling app's callback, hDev=x0, Msg=12, dwInst=x58c04e0 P1=x100f0, P2=x0 P3=x0
[5952] 20:01:13:406: [TRACE] lineDeallocateCall: enter on thread: 0x00001740
[5952] 20:01:13:406: [INFO ] hCall = 0x00010123
[5952] 20:01:13:406: [TRACE] DoFunc -- enter
[5952] 20:01:13:406: [TRACE] AllocClientResources: enter
[5952] 20:01:13:406: [TRACE] AllocClientResources: exit, returning x0
[5952] 20:01:13:406: [TRACE] DoFunc: back from srv- return code=0x00000000
[5952] 20:01:13:406: [TRACE] DoFunc: result = x0
[5952] 20:01:13:406: [TRACE] No entries - spurious entry.
[5952] 20:01:13:406: [TRACE] TAPIWndProc: received WM_ASYNCEVENT, hwnd=x0001013A
[5952] 20:01:13:406: [TRACE] No entries - spurious entry.
[5952] 20:01:13:406: [TRACE] TAPIWndProc: received WM_ASYNCEVENT, hwnd=x0001013A
[5952] 20:01:13:406: [TRACE] No entries - spurious entry.
[3844] 20:01:58:234: [INFO ] AsyncEventsThread: msg=23, hDev=x102dd, p1=x0, p2=x100de, p3=x4
[3844] 20:01:58:234: [INFO ] AsyncEventsThread: posting msg, hwnd=x1013a
[3844] 20:01:58:234: [INFO ] AsyncEventsThread: msg=2, hDev=x100de, p1=x2, p2=x0, p3=x0
[5952] 20:01:58:234: [TRACE] TAPIWndProc: received WM_ASYNCEVENT, hwnd=x0001013A
[5952] 20:01:58:234: [INFO ] Calling app's callback, hDev=x102dd, Msg=23, dwInst=x58c04e0 P1=x0, P2=x100de P3=x4
[5952] 20:01:58:234: [INFO ] Calling app's callback, hDev=x100de, Msg=2, dwInst=x58c04e0 P1=x2, P2=x0 P3=x0
[5952] 20:01:58:234: [TRACE] DoFunc -- enter
[5952] 20:01:58:234: [TRACE] AllocClientResources: enter
[5952] 20:01:58:234: [TRACE] AllocClientResources: exit, returning x0
[5952] 20:01:58:234: [TRACE] DoFunc: back from srv- return code=0x00000000
[5952] 20:01:58:234: [TRACE] DoFunc: result = x0
[5952] 20:01:58:234: [TRACE] No entries - spurious entry.
[5952] 20:01:58:234: [TRACE] TAPIWndProc: received WM_ASYNCEVENT, hwnd=x0001013A
[5952] 20:01:58:234: [TRACE] No entries - spurious entry.
[5952] 20:01:58:234: [TRACE] TAPIWndProc: received WM_ASYNCEVENT, hwnd=x0001013A
[5952] 20:01:58:234: [TRACE] No entries - spurious entry.
[5340] 20:01:58:234: [TRACE] DoFunc -- enter
[5340] 20:01:58:234: [TRACE] AllocClientResources: enter
[5340] 20:01:58:234: [TRACE] AllocClientResources: exit, returning x0
[5340] 20:01:58:234: [TRACE] DoFunc: back from srv- return code=0x00010112
[5340] 20:01:58:250: [TRACE] DoFunc: result = x10112
[3844] 20:01:58:250: [INFO ] AsyncEventsThread: msg=12, hDev=x0, p1=x10112, p2=x80000048, p3=x0
[3844] 20:01:58:250: [INFO ] AsyncEventsThread: posting msg, hwnd=x1013a
[5952] 20:01:58:250: [TRACE] TAPIWndProc: received WM_ASYNCEVENT, hwnd=x0001013A
[5952] 20:01:58:250: [INFO ] Calling app's callback, hDev=x0, Msg=12, dwInst=x58c04e0 P1=x10112, P2=x80000048 P3=x0
[5952] 20:01:58:250: [TRACE] No entries - spurious entry.
[5340] 20:01:58:250: [TRACE] DoFunc -- enter
[5340] 20:01:58:250: [TRACE] AllocClientResources: enter
[5340] 20:01:58:250: [TRACE] AllocClientResources: exit, returning x0
[5340] 20:01:58:250: [TRACE] DoFunc: back from srv- return code=0x00010101
[5340] 20:01:58:250: [TRACE] DoFunc: result = x10101
[3844] 20:01:58:250: [INFO ] AsyncEventsThread: msg=2, hDev=x100de, p1=x100, p2=x0, p3=x0
[3844] 20:01:58:250: [INFO ] AsyncEventsThread: posting msg, hwnd=x1013a
[5952] 20:01:58:250: [TRACE] TAPIWndProc: received WM_ASYNCEVENT, hwnd=x0001013A
[5952] 20:01:58:250: [INFO ] Calling app's callback, hDev=x100de, Msg=2, dwInst=x58c04e0 P1=x100, P2=x0 P3=x0
[5952] 20:01:58:250: [TRACE] DoFunc -- enter
[5952] 20:01:58:250: [TRACE] AllocClientResources: enter
[3844] 20:01:58:250: [INFO ] AsyncEventsThread: msg=12, hDev=x0, p1=x10101, p2=x0, p3=x0
[5952] 20:01:58:250: [TRACE] AllocClientResources: exit, returning x0
[3844] 20:01:58:250: [INFO ] AsyncEventsThread: posting msg, hwnd=x1013a
[5952] 20:01:58:250: [TRACE] DoFunc: back from srv- return code=0x00000000
[5952] 20:01:58:250: [TRACE] DoFunc: result = x0
[5952] 20:01:58:250: [INFO ] Calling app's callback, hDev=x0, Msg=12, dwInst=x58c04e0 P1=x10101, P2=x0 P3=x0
[5952] 20:01:58:250: [TRACE] No entries - spurious entry.
[5952] 20:01:58:250: [TRACE] TAPIWndProc: received WM_ASYNCEVENT, hwnd=x0001013A
[5952] 20:01:58:250: [TRACE] No entries - spurious entry.
[5944] 20:01:58:250: [TRACE] DoFunc -- enter
[5944] 20:01:58:250: [TRACE] AllocClientResources: enter
[5944] 20:01:58:250: [TRACE] AllocClientResources: exit, returning x0
[5944] 20:01:58:250: [TRACE] DoFunc: back from srv- return code=0x00000000
[5944] 20:01:58:250: [TRACE] DoFunc: result = x0
[5944] 20:01:58:250: [TRACE] DoFunc -- enter
[5944] 20:01:58:250: [TRACE] AllocClientResources: enter
[5944] 20:01:58:250: [TRACE] AllocClientResources: exit, returning x0
[5944] 20:01:58:250: [TRACE] DoFunc: back from srv- return code=0x00000000
[5944] 20:01:58:250: [TRACE] DoFunc: result = x0
[3844] 20:02:12:859: [INFO ] AsyncEventsThread: msg=2, hDev=x100de, p1=x4000, p2=x0, p3=x0
[3844] 20:02:12:859: [INFO ] AsyncEventsThread: posting msg, hwnd=x1013a
[3844] 20:02:12:859: [INFO ] AsyncEventsThread: msg=2, hDev=x100de, p1=x1, p2=x0, p3=x0
[5952] 20:02:12:859: [TRACE] TAPIWndProc: received WM_ASYNCEVENT, hwnd=x0001013A
[5952] 20:02:12:859: [INFO ] Calling app's callback, hDev=x100de, Msg=2, dwInst=x58c04e0 P1=x4000, P2=x0 P3=x0
[5952] 20:02:12:859: [TRACE] DoFunc -- enter
[5952] 20:02:12:859: [TRACE] AllocClientResources: enter
[5952] 20:02:12:859: [TRACE] AllocClientResources: exit, returning x0
[5952] 20:02:12:859: [TRACE] DoFunc: back from srv- return code=0x00000000
[5952] 20:02:12:859: [TRACE] DoFunc: result = x0
[5952] 20:02:12:859: [TRACE] DoFunc -- enter
[5952] 20:02:12:859: [TRACE] AllocClientResources: enter
[5952] 20:02:12:859: [TRACE] AllocClientResources: exit, returning x0
[5952] 20:02:12:859: [TRACE] DoFunc: back from srv- return code=0x000100cd
[5952] 20:02:12:859: [TRACE] DoFunc: result = x100cd
[5952] 20:02:12:859: [INFO ] Calling app's callback, hDev=x100de, Msg=2, dwInst=x58c04e0 P1=x1, P2=x0 P3=x0
[5952] 20:02:12:859: [TRACE] No entries - spurious entry.
[5952] 20:02:12:859: [TRACE] TAPIWndProc: received WM_ASYNCEVENT, hwnd=x0001013A
[5952] 20:02:12:859: [TRACE] No entries - spurious entry.
[5952] 20:02:12:859: [TRACE] TAPIWndProc: received WM_ASYNCEVENT, hwnd=x0001013A
[5952] 20:02:12:859: [TRACE] No entries - spurious entry.
[3844] 20:02:12:859: [INFO ] AsyncEventsThread: msg=12, hDev=x0, p1=x100cd, p2=x80000048, p3=x0
[3844] 20:02:12:859: [INFO ] AsyncEventsThread: posting msg, hwnd=x1013a
[5952] 20:02:12:859: [TRACE] TAPIWndProc: received WM_ASYNCEVENT, hwnd=x0001013A
[5952] 20:02:12:859: [INFO ] Calling app's callback, hDev=x0, Msg=12, dwInst=x58c04e0 P1=x100cd, P2=x80000048 P3=x0
[5952] 20:02:12:859: [TRACE] lineDeallocateCall: enter on thread: 0x00001740
[5952] 20:02:12:859: [INFO ] hCall = 0x000100de
[5952] 20:02:12:859: [TRACE] DoFunc -- enter
[5952] 20:02:12:859: [TRACE] AllocClientResources: enter
[5952] 20:02:12:859: [TRACE] AllocClientResources: exit, returning x0
[5952] 20:02:12:859: [TRACE] DoFunc: back from srv- return code=0x00000000
[5952] 20:02:12:859: [TRACE] DoFunc: result = x0
[5952] 20:02:12:859: [TRACE] No entries - spurious entry.
[3844] 20:02:30:234: [INFO ] AsyncEventsThread: msg=23, hDev=x102dd, p1=x0, p2=x101cd, p3=x4
[3844] 20:02:30:234: [INFO ] AsyncEventsThread: posting msg, hwnd=x1013a
[3844] 20:02:30:234: [INFO ] AsyncEventsThread: msg=2, hDev=x101cd, p1=x2, p2=x0, p3=x0
[5952] 20:02:30:234: [TRACE] TAPIWndProc: received WM_ASYNCEVENT, hwnd=x0001013A
[5952] 20:02:30:234: [INFO ] Calling app's callback, hDev=x102dd, Msg=23, dwInst=x58c04e0 P1=x0, P2=x101cd P3=x4
[5952] 20:02:30:234: [INFO ] Calling app's callback, hDev=x101cd, Msg=2, dwInst=x58c04e0 P1=x2, P2=x0 P3=x0
[5952] 20:02:30:234: [TRACE] DoFunc -- enter
[5952] 20:02:30:234: [TRACE] AllocClientResources: enter
[5952] 20:02:30:234: [TRACE] AllocClientResources: exit, returning x0
[5952] 20:02:30:234: [TRACE] DoFunc: back from srv- return code=0x00000000
[5952] 20:02:30:234: [TRACE] DoFunc: result = x0
[5952] 20:02:30:234: [TRACE] No entries - spurious entry.
[5952] 20:02:30:234: [TRACE] TAPIWndProc: received WM_ASYNCEVENT, hwnd=x0001013A
[5952] 20:02:30:234: [TRACE] No entries - spurious entry.
[5952] 20:02:30:234: [TRACE] TAPIWndProc: received WM_ASYNCEVENT, hwnd=x0001013A
[5952] 20:02:30:234: [TRACE] No entries - spurious entry.
[5340] 20:02:30:234: [TRACE] DoFunc -- enter
[5340] 20:02:30:234: [TRACE] AllocClientResources: enter
[5340] 20:02:30:234: [TRACE] AllocClientResources: exit, returning x0
[5340] 20:02:30:234: [TRACE] DoFunc: back from srv- return code=0x000101bc
[5340] 20:02:30:234: [TRACE] DoFunc: result = x101bc
[3844] 20:02:30:234: [INFO ] AsyncEventsThread: msg=12, hDev=x0, p1=x101bc, p2=x80000048, p3=x0
[3844] 20:02:30:234: [INFO ] AsyncEventsThread: posting msg, hwnd=x1013a
[5952] 20:02:30:234: [TRACE] TAPIWndProc: received WM_ASYNCEVENT, hwnd=x0001013A
[5952] 20:02:30:234: [INFO ] Calling app's callback, hDev=x0, Msg=12, dwInst=x58c04e0 P1=x101bc, P2=x80000048 P3=x0
[5952] 20:02:30:234: [TRACE] No entries - spurious entry.
[5340] 20:02:30:234: [TRACE] DoFunc -- enter
[5340] 20:02:30:234: [TRACE] AllocClientResources: enter
[5340] 20:02:30:234: [TRACE] AllocClientResources: exit, returning x0
[5340] 20:02:30:234: [TRACE] DoFunc: back from srv- return code=0x00010089
[5340] 20:02:30:234: [TRACE] DoFunc: result = x10089
[3844] 20:02:30:234: [INFO ] AsyncEventsThread: msg=2, hDev=x101cd, p1=x100, p2=x0, p3=x0
[3844] 20:02:30:234: [INFO ] AsyncEventsThread: posting msg, hwnd=x1013a
[3844] 20:02:30:234: [INFO ] AsyncEventsThread: msg=12, hDev=x0, p1=x10089, p2=x0, p3=x0
[5952] 20:02:30:234: [TRACE] TAPIWndProc: received WM_ASYNCEVENT, hwnd=x0001013A
[5952] 20:02:30:234: [INFO ] Calling app's callback, hDev=x101cd, Msg=2, dwInst=x58c04e0 P1=x100, P2=x0 P3=x0
[5952] 20:02:30:234: [TRACE] DoFunc -- enter
[5952] 20:02:30:234: [TRACE] AllocClientResources: enter
[5952] 20:02:30:234: [TRACE] AllocClientResources: exit, returning x0
[5952] 20:02:30:234: [TRACE] DoFunc: back from srv- return code=0x00000000
[5952] 20:02:30:234: [TRACE] DoFunc: result = x0
[5952] 20:02:30:234: [INFO ] Calling app's callback, hDev=x0, Msg=12, dwInst=x58c04e0 P1=x10089, P2=x0 P3=x0
[5952] 20:02:30:234: [TRACE] No entries - spurious entry.
[5952] 20:02:30:234: [TRACE] TAPIWndProc: received WM_ASYNCEVENT, hwnd=x0001013A
[5952] 20:02:30:234: [TRACE] No entries - spurious entry.
[5952] 20:02:30:234: [TRACE] TAPIWndProc: received WM_ASYNCEVENT, hwnd=x0001013A
[5952] 20:02:30:234: [TRACE] No entries - spurious entry.
[5944] 20:02:30:234: [TRACE] DoFunc -- enter
[5944] 20:02:30:234: [TRACE] AllocClientResources: enter
[5944] 20:02:30:234: [TRACE] AllocClientResources: exit, returning x0
[5944] 20:02:30:234: [TRACE] DoFunc: back from srv- return code=0x00000000
[5944] 20:02:30:234: [TRACE] DoFunc: result = x0
[5944] 20:02:30:234: [TRACE] DoFunc -- enter
[5944] 20:02:30:234: [TRACE] AllocClientResources: enter
[5944] 20:02:30:234: [TRACE] AllocClientResources: exit, returning x0
[5944] 20:02:30:234: [TRACE] DoFunc: back from srv- return code=0x00000000
[5944] 20:02:30:234: [TRACE] DoFunc: result = x0
tobias
 
Posts: 29
Joined: Sat Apr 21, 2012 9:23 pm
Top

Re: RRAS - VPN Randomly Disconnecting

Postby tobias » Sat Apr 21, 2012 9:59 pm

[RASTAPI.log]
[5944] 04-19 20:01:35:453: PortDisconnect: VPN3-126
[5944] 04-19 20:01:35:453: InitiatePortDisconnection: VPN3-126
[5944] 04-19 20:01:35:453: Miniporta de rede remota (PPTP) InClients=1, TotalDialInClients=1
[5944] 04-19 20:01:35:515: InitiatePortDisconnection: Changing state for VPN3-126 from 3 -> 5, id=0x10335
[5944] 04-19 20:01:35:515:
[5944] 04-19 20:01:35:515:
[5944] 04-19 20:01:36:453: PortDisconnect: VPN3-127
[5944] 04-19 20:01:36:453: InitiatePortDisconnection: VPN3-127
[5944] 04-19 20:01:36:453: Miniporta de rede remota (PPTP) InClients=0, TotalDialInClients=0
[5944] 04-19 20:01:36:453: InitiatePortDisconnection: Changing state for VPN3-127 from 3 -> 5, id=0x10279
[5944] 04-19 20:01:36:453:
[5944] 04-19 20:01:36:453:
[5952] 04-19 20:01:36:781: RasTapicallback: msg=2 , param1=1l , param2=0l
[5952] 04-19 20:01:36:781: RasTapicallback: linecallstate=0x1
[5952] 04-19 20:01:36:781: RasTapicallback: msg=12 , param1=66357l , param2=0l
[5952] 04-19 20:01:36:781: LINE_REPLY. param1=0x10335
[5952] 04-19 20:01:36:781: RasTapiCallback: lineDropped. port VPN3-126, id=0xffffffff
[5952] 04-19 20:01:36:781: RasTapiCallback: Idle Received for port VPN3-126
[5952] 04-19 20:01:36:781: RasTapiCallback: changing state of VPN3-126. 5 -> 1
[5952] 04-19 20:01:36:781: RasTapiCallback: lineDeallocateCall for VPN3-126,hcall = 0x10055
[5340] 04-19 20:01:37:515: PortTestSignalState: DeviceState = 0
[5952] 04-19 20:01:37:515: RasTapicallback: msg=2 , param1=16384l , param2=0l
[5952] 04-19 20:01:37:515: RasTapicallback: linecallstate=0x4000
[5952] 04-19 20:01:37:515: RasTapiCallback: LINECALLSTATE - initiating Port Disconnect
[5952] 04-19 20:01:37:515: InitiatePortDisconnection: VPN3-127
[5952] 04-19 20:01:37:515: InitiatePortDisconnection: Changing state for VPN3-127 from 5 -> 5, id=0x103bd
[5952] 04-19 20:01:37:515:
[5952] 04-19 20:01:37:515: RasTapicallback: msg=2 , param1=1l , param2=0l
[5952] 04-19 20:01:37:515: RasTapicallback: linecallstate=0x1
[5952] 04-19 20:01:37:515: RasTapicallback: msg=12 , param1=66169l , param2=0l
[5952] 04-19 20:01:37:515: LINE_REPLY. param1=0x10279
[5952] 04-19 20:01:37:515: PortByRequestId found
[5952] 04-19 20:01:37:531: RasTapicallback: msg=12 , param1=66493l , param2=2147483720l
[5952] 04-19 20:01:37:531: LINE_REPLY. param1=0x103bd
[5952] 04-19 20:01:37:531: RasTapiCallback: lineDropped. port VPN3-127, id=0xffffffff
[5952] 04-19 20:01:37:531: RasTapiCallback: Idle Received for port VPN3-127
[5952] 04-19 20:01:37:531: RasTapiCallback: changing state of VPN3-127. 5 -> 1
[5952] 04-19 20:01:37:531: RasTapiCallback: lineDeallocateCall for VPN3-127,hcall = 0x10368
[5340] 04-19 20:01:37:578: PortTestSignalState: DeviceState = 0
[5944] 04-19 20:01:39:515: DeviceListen: Changing State for VPN3-126 from 1 -> 2
[5944] 04-19 20:01:39:515: DeviceListen: Changing Listen State for VPN3-126 from 4 -> 2
[5944] 04-19 20:01:39:515:
[5944] 04-19 20:01:39:578: DeviceListen: Changing State for VPN3-127 from 1 -> 2
[5944] 04-19 20:01:39:578: DeviceListen: Changing Listen State for VPN3-127 from 4 -> 2
[5944] 04-19 20:01:39:578:
[5952] 04-19 20:02:19:875: RasTapicallback: msg=23 , param1=0l , param2=66118l
[5952] 04-19 20:02:19:875: RasTapicallback: msg=2 , param1=2l , param2=0l
[5952] 04-19 20:02:19:875: RasTapicallback: linecallstate=0x2
[5952] 04-19 20:02:19:875: DwProcessOfferEvent: hcall=0x10246
[5952] 04-19 20:02:19:875: DwProcessOfferEvent: Accepting call on VPN3-127 hcall = 0x10246
[5952] 04-19 20:02:19:875: Miniporta de rede remota (PPTP) InClients=1, TotalDialInClients=1
[5952] 04-19 20:02:19:875: DwProcessOfferEvent 0x0
[5340] 04-19 20:02:19:875: DeviceWork: VPN3-127. State = 2
[5340] 04-19 20:02:19:875: DeviceWork: VPN3-127. lineAccept returned 0x10268
[5952] 04-19 20:02:19:875: RasTapicallback: msg=12 , param1=66152l , param2=2147483720l
[5952] 04-19 20:02:19:875: LINE_REPLY. param1=0x10268
[5952] 04-19 20:02:19:875: RasTapiCallback: Changing Listen State for VPN3-127 from 2 -> 3
[5340] 04-19 20:02:19:875: DeviceWork: VPN3-127. State = 2
[5340] 04-19 20:02:19:875: DeviceWork: VPN3-127. lineAnswer returned 0x10257
[5952] 04-19 20:02:19:875: RasTapicallback: msg=2 , param1=256l , param2=0l
[5952] 04-19 20:02:19:875: RasTapicallback: linecallstate=0x100
[5952] 04-19 20:02:19:875: DwGetConnectInfo
[5952] 04-19 20:02:19:875: DwGetIDInformation
[5952] 04-19 20:02:19:875: DwGetIDInformation. 0
[5952] 04-19 20:02:19:875: SizeRequired for CallID=16
[5952] 04-19 20:02:19:875: DwGetIDInformation
[5952] 04-19 20:02:19:875: GetIDInformation: CallerID=10.0.0.199
[5952] 04-19 20:02:19:875: RasTapiCallback: called id info. not avail
[5952] 04-19 20:02:19:875: DwGetIDInformation. 0
[5952] 04-19 20:02:19:875: DwGetConnectInfo. 0x0
[5952] 04-19 20:02:19:875: RasTapiCallback: DwGetConnectInforeturned 0x0
[5952] 04-19 20:02:19:875: RasTapiCallback: Connected on VPN3-127
[5952] 04-19 20:02:19:875: RasTapiCallback: Incoming Call
[5952] 04-19 20:02:19:875: RasTapicallback: msg=12 , param1=66135l , param2=0l
[5952] 04-19 20:02:19:875: LINE_REPLY. param1=0x10257
[5340] 04-19 20:02:19:875: DeviceWork: VPN3-127. State = 2
[5340] 04-19 20:02:19:875: DeviceWork: Changing State for VPN3-127 from 2 -> 3
[5944] 04-19 20:02:19:875: PortConnect: VPN3-127
[5944] 04-19 20:02:19:875:
[5952] 04-19 20:02:31:562: RasTapicallback: msg=23 , param1=0l , param2=66374l
[5952] 04-19 20:02:31:562: RasTapicallback: msg=2 , param1=2l , param2=0l
[5952] 04-19 20:02:31:562: RasTapicallback: linecallstate=0x2
[5952] 04-19 20:02:31:562: DwProcessOfferEvent: hcall=0x10346
[5952] 04-19 20:02:31:562: DwProcessOfferEvent: Accepting call on VPN3-126 hcall = 0x10346
[5952] 04-19 20:02:31:562: Miniporta de rede remota (PPTP) InClients=2, TotalDialInClients=2
[5952] 04-19 20:02:31:562: DwProcessOfferEvent 0x0
[5340] 04-19 20:02:31:562: DeviceWork: VPN3-126. State = 2
[5340] 04-19 20:02:31:562: DeviceWork: VPN3-126. lineAccept returned 0x10224
[5952] 04-19 20:02:31:562: RasTapicallback: msg=12 , param1=66084l , param2=2147483720l
[5952] 04-19 20:02:31:562: LINE_REPLY. param1=0x10224
[5952] 04-19 20:02:31:562: RasTapiCallback: Changing Listen State for VPN3-126 from 2 -> 3
[5340] 04-19 20:02:31:562: DeviceWork: VPN3-126. State = 2
[5340] 04-19 20:02:31:562: DeviceWork: VPN3-126. lineAnswer returned 0x101e0
[5952] 04-19 20:02:31:562: RasTapicallback: msg=2 , param1=256l , param2=0l
[5952] 04-19 20:02:31:562: RasTapicallback: linecallstate=0x100
[5952] 04-19 20:02:31:562: DwGetConnectInfo
[5952] 04-19 20:02:31:562: DwGetIDInformation
[5952] 04-19 20:02:31:562: DwGetIDInformation. 0
[5952] 04-19 20:02:31:562: SizeRequired for CallID=16
[5952] 04-19 20:02:31:562: DwGetIDInformation
[5952] 04-19 20:02:31:562: GetIDInformation: CallerID=187.55.236.168
[5952] 04-19 20:02:31:562: RasTapiCallback: called id info. not avail
[5952] 04-19 20:02:31:562: DwGetIDInformation. 0
[5952] 04-19 20:02:31:562: DwGetConnectInfo. 0x0
[5952] 04-19 20:02:31:562: RasTapiCallback: DwGetConnectInforeturned 0x0
[5952] 04-19 20:02:31:562: RasTapiCallback: Connected on VPN3-126
[5952] 04-19 20:02:31:562: RasTapiCallback: Incoming Call
[5952] 04-19 20:02:31:562: RasTapicallback: msg=12 , param1=66016l , param2=0l
[5952] 04-19 20:02:31:562: LINE_REPLY. param1=0x101e0
[5340] 04-19 20:02:31:562: DeviceWork: VPN3-126. State = 2
[5340] 04-19 20:02:31:562: DeviceWork: Changing State for VPN3-126 from 2 -> 3
[5944] 04-19 20:02:31:562: PortConnect: VPN3-126
[5944] 04-19 20:02:31:562:

[RTM.log]
[2744] 20:01:35: Deleting Route with address:
[2744] 20:01:35: Dest: 10.0.1.3 Mask: 255.255.255.255
[2744] 20:01:35: Dest = 020F4790 and Route = 020F4740

[2744] 20:01:35: Adding dest 020F4790 to change list 0:
[2744] 20:01:35: Dest: 10.0.1.3 Mask: 255.255.255.255
[2744] 20:01:35:

[2744] 20:01:36: Deleting Route with address:
[2744] 20:01:36: Dest: 10.0.1.2 Mask: 255.255.255.255
[2744] 20:01:36: Dest = 020F43F8 and Route = 020F4848

[2744] 20:01:36: Adding dest 020F43F8 to change list 0:
[2744] 20:01:36: Dest: 10.0.1.2 Mask: 255.255.255.255
[2744] 20:01:36:

[2488] 20:01:36: Entering ProcessChangedDestLists: 2488
[2488] 20:01:36: ProcessChangedDestLists: Number of changed dests: 2
[2488] 20:01:36: Next dest 020F4790 in list 0:
[2488] 20:01:36: Dest: 10.0.1.3 Mask: 255.255.255.255
[2488] 20:01:36:

[2488] 20:01:36: Next dest 020F43F8 in list 0:
[2488] 20:01:36: Dest: 10.0.1.2 Mask: 255.255.255.255
[2488] 20:01:36:

[2488] 20:01:36: Notifying CN 0 BEGIN
[2488] 20:01:36: Returning dest 020F4790 to CN 0:
[2488] 20:01:36: Dest: 10.0.1.3 Mask: 255.255.255.255
[2488] 20:01:36:

[2488] 20:01:36: Returning dest 020F43F8 to CN 0:
[2488] 20:01:36: Dest: 10.0.1.2 Mask: 255.255.255.255
[2488] 20:01:36:

[2488] 20:01:36: Notifying CN 0 END

[2488] 20:01:36: ProcessChangedDestLists: Dests Removed: 2
[2488] 20:01:36: Leaving ProcessChangedDestLists: 2488
[5944] 20:01:39: Deleting Route with address:
[5944] 20:01:39: Dest: 192.168.1.0 Mask: 255.255.255.0
[5944] 20:01:39: Dest = 020F3DB0 and Route = 020F4530

[5944] 20:01:39: Adding dest 020F3DB0 to change list 8:
[5944] 20:01:39: Dest: 192.168.1.0 Mask: 255.255.255.0
[5944] 20:01:39:

[5944] 20:01:39: Deleting Route with address:
[5944] 20:01:39: Dest: 192.168.3.0 Mask: 255.255.255.0
[5944] 20:01:39: Dest = 020F4580 and Route = 020F3D60

[5944] 20:01:39: Adding dest 020F4580 to change list 8:
[5944] 20:01:39: Dest: 192.168.3.0 Mask: 255.255.255.0
[5944] 20:01:39:

[5944] 20:01:39: Deleting Route with address:
[5944] 20:01:39: Dest: 192.168.2.0 Mask: 255.255.255.0
[5944] 20:01:39: Dest = 020F49A0 and Route = 020F43A8

[5944] 20:01:39: Adding dest 020F49A0 to change list 8:
[5944] 20:01:39: Dest: 192.168.2.0 Mask: 255.255.255.0
[5944] 20:01:39:

[4144] 20:01:40: Entering ProcessChangedDestLists: 4144
[4144] 20:01:40: ProcessChangedDestLists: Number of changed dests: 3
[4144] 20:01:40: Next dest 020F3DB0 in list 8:
[4144] 20:01:40: Dest: 192.168.1.0 Mask: 255.255.255.0
[4144] 20:01:40:

[4144] 20:01:40: Next dest 020F4580 in list 8:
[4144] 20:01:40: Dest: 192.168.3.0 Mask: 255.255.255.0
[4144] 20:01:40:

[4144] 20:01:40: Next dest 020F49A0 in list 8:
[4144] 20:01:40: Dest: 192.168.2.0 Mask: 255.255.255.0
[4144] 20:01:40:

[4144] 20:01:40: Notifying CN 0 BEGIN
[4144] 20:01:40: Returning dest 020F3DB0 to CN 0:
[4144] 20:01:40: Dest: 192.168.1.0 Mask: 255.255.255.0
[4144] 20:01:40:

[4144] 20:01:40: Returning dest 020F4580 to CN 0:
[4144] 20:01:40: Dest: 192.168.3.0 Mask: 255.255.255.0
[4144] 20:01:40:

[4144] 20:01:40: Returning dest 020F49A0 to CN 0:
[4144] 20:01:40: Dest: 192.168.2.0 Mask: 255.255.255.0
[4144] 20:01:40:

[4144] 20:01:40: Notifying CN 0 END

[4144] 20:01:40: ProcessChangedDestLists: Dests Removed: 3
[4144] 20:01:40: Leaving ProcessChangedDestLists: 4144
[2744] 20:02:06: Deleting Route with address:
[2744] 20:02:06: Dest: 10.0.0.199 Mask: 255.255.255.255
[2744] 20:02:06: Dest = 020F34E8 and Route = 020F3498

[2744] 20:02:06: Adding dest 020F34E8 to change list 0:
[2744] 20:02:06: Dest: 10.0.0.199 Mask: 255.255.255.255
[2744] 20:02:06:

[4144] 20:02:07: Entering ProcessChangedDestLists: 4144
[4144] 20:02:07: ProcessChangedDestLists: Number of changed dests: 1
[4144] 20:02:07: Next dest 020F34E8 in list 0:
[4144] 20:02:07: Dest: 10.0.0.199 Mask: 255.255.255.255
[4144] 20:02:07:

[4144] 20:02:07: Notifying CN 0 BEGIN
[4144] 20:02:07: Returning dest 020F34E8 to CN 0:
[4144] 20:02:07: Dest: 10.0.0.199 Mask: 255.255.255.255
[4144] 20:02:07:

[4144] 20:02:07: Notifying CN 0 END

[4144] 20:02:07: ProcessChangedDestLists: Dests Removed: 1
[4144] 20:02:07: Leaving ProcessChangedDestLists: 4144
[2744] 20:02:07: Deleting Route with address:
[2744] 20:02:07: Dest: 187.55.236.168 Mask: 255.255.255.255
[2744] 20:02:07: Dest = 020F4898 and Route = 020F4950

[2744] 20:02:07: Adding dest 020F4898 to change list 7:
[2744] 20:02:07: Dest: 187.55.236.168 Mask: 255.255.255.255
[2744] 20:02:07:

[4144] 20:02:08: Entering ProcessChangedDestLists: 4144
[4144] 20:02:08: ProcessChangedDestLists: Number of changed dests: 1
[4144] 20:02:08: Next dest 020F4898 in list 7:
[4144] 20:02:08: Dest: 187.55.236.168 Mask: 255.255.255.255
[4144] 20:02:08:

[4144] 20:02:08: Notifying CN 0 BEGIN
[4144] 20:02:08: Returning dest 020F4898 to CN 0:
[4144] 20:02:08: Dest: 187.55.236.168 Mask: 255.255.255.255
[4144] 20:02:08:

[4144] 20:02:08: Notifying CN 0 END

[4144] 20:02:08: ProcessChangedDestLists: Dests Removed: 1
[4144] 20:02:08: Leaving ProcessChangedDestLists: 4144
[2744] 20:02:18: Adding dest 020F4580 to change list 0:
[2744] 20:02:18: Dest: 10.0.0.199 Mask: 255.255.255.255
[2744] 20:02:18:

[2744] 20:02:18: Adding Route with address:
[2744] 20:02:18: Dest: 10.0.0.199 Mask: 255.255.255.255
[2744] 20:02:18: Dest = 020F4580 and Route = 020F3D60

[4144] 20:02:19: Entering ProcessChangedDestLists: 4144
[4144] 20:02:19: ProcessChangedDestLists: Number of changed dests: 1
[4144] 20:02:19: Next dest 020F4580 in list 0:
[4144] 20:02:19: Dest: 10.0.0.199 Mask: 255.255.255.255
[4144] 20:02:19:

[4144] 20:02:19: Notifying CN 0 BEGIN
[4144] 20:02:19: Returning dest 020F4580 to CN 0:
[4144] 20:02:19: Dest: 10.0.0.199 Mask: 255.255.255.255
[4144] 20:02:19:

[4144] 20:02:19: Notifying CN 0 END

[4144] 20:02:19: ProcessChangedDestLists: Dests Removed: 1
[4144] 20:02:19: Leaving ProcessChangedDestLists: 4144
[2744] 20:02:25: Adding dest 020F3DB0 to change list 0:
[2744] 20:02:25: Dest: 10.0.1.3 Mask: 255.255.255.255
[2744] 20:02:25:

[2744] 20:02:25: Adding Route with address:
[2744] 20:02:25: Dest: 10.0.1.3 Mask: 255.255.255.255
[2744] 20:02:25: Dest = 020F3DB0 and Route = 020F4530

[4144] 20:02:26: Entering ProcessChangedDestLists: 4144
[4144] 20:02:27: ProcessChangedDestLists: Number of changed dests: 1
[4144] 20:02:27: Next dest 020F3DB0 in list 0:
[4144] 20:02:27: Dest: 10.0.1.3 Mask: 255.255.255.255
[4144] 20:02:27:

[4144] 20:02:27: Notifying CN 0 BEGIN
[4144] 20:02:27: Returning dest 020F3DB0 to CN 0:
[4144] 20:02:27: Dest: 10.0.1.3 Mask: 255.255.255.255
[4144] 20:02:27:

[4144] 20:02:27: Notifying CN 0 END

[4144] 20:02:27: ProcessChangedDestLists: Dests Removed: 1
[4144] 20:02:27: Leaving ProcessChangedDestLists: 4144
[2744] 20:02:30: Adding dest 020F43F8 to change list 7:
[2744] 20:02:30: Dest: 187.55.236.168 Mask: 255.255.255.255
[2744] 20:02:30:

[2744] 20:02:30: Adding Route with address:
[2744] 20:02:30: Dest: 187.55.236.168 Mask: 255.255.255.255
[2744] 20:02:30: Dest = 020F43F8 and Route = 020F4848

[4144] 20:02:31: Entering ProcessChangedDestLists: 4144
[4144] 20:02:31: ProcessChangedDestLists: Number of changed dests: 1
[4144] 20:02:31: Next dest 020F43F8 in list 7:
[4144] 20:02:31: Dest: 187.55.236.168 Mask: 255.255.255.255
[4144] 20:02:31:

[4144] 20:02:31: Notifying CN 0 BEGIN
[4144] 20:02:31: Returning dest 020F43F8 to CN 0:
[4144] 20:02:31: Dest: 187.55.236.168 Mask: 255.255.255.255
[4144] 20:02:31:

[4144] 20:02:31: Notifying CN 0 END

[4144] 20:02:31: Notifying CN 1 BEGIN
[4144] 20:02:31: Returning dest 020F43F8 to CN 1:
[4144] 20:02:31: Dest: 187.55.236.168 Mask: 255.255.255.255
[4144] 20:02:31:

[4144] 20:02:31: Notifying CN 1 END

[4144] 20:02:31: ProcessChangedDestLists: Dests Removed: 1
[4144] 20:02:31: Leaving ProcessChangedDestLists: 4144
[2744] 20:02:35: Adding dest 020F4790 to change list 0:
[2744] 20:02:35: Dest: 10.0.1.2 Mask: 255.255.255.255
[2744] 20:02:35:

[2744] 20:02:35: Adding Route with address:
[2744] 20:02:35: Dest: 10.0.1.2 Mask: 255.255.255.255
[2744] 20:02:35: Dest = 020F4790 and Route = 020F4740

[5944] 20:02:35: Adding dest 020F4898 to change list 8:
[5944] 20:02:35: Dest: 192.168.1.0 Mask: 255.255.255.0
[5944] 20:02:35:

[5944] 20:02:35: Adding Route with address:
[5944] 20:02:35: Dest: 192.168.1.0 Mask: 255.255.255.0
[5944] 20:02:35: Dest = 020F4898 and Route = 020F43A8

[5944] 20:02:35: Adding dest 020F49A0 to change list 8:
[5944] 20:02:35: Dest: 192.168.3.0 Mask: 255.255.255.0
[5944] 20:02:35:

[5944] 20:02:35: Adding Route with address:
[5944] 20:02:35: Dest: 192.168.3.0 Mask: 255.255.255.0
[5944] 20:02:35: Dest = 020F49A0 and Route = 020F4950

[5944] 20:02:35: Adding dest 020F34E8 to change list 8:
[5944] 20:02:35: Dest: 192.168.2.0 Mask: 255.255.255.0
[5944] 20:02:35:

[5944] 20:02:35: Adding Route with address:
[5944] 20:02:35: Dest: 192.168.2.0 Mask: 255.255.255.0
[5944] 20:02:35: Dest = 020F34E8 and Route = 020F3498

[4144] 20:02:36: Entering ProcessChangedDestLists: 4144
[4144] 20:02:36: ProcessChangedDestLists: Number of changed dests: 4
[4144] 20:02:36: Next dest 020F4790 in list 0:
[4144] 20:02:36: Dest: 10.0.1.2 Mask: 255.255.255.255
[4144] 20:02:36:

[4144] 20:02:36: Notifying CN 0 BEGIN
[4144] 20:02:36: Returning dest 020F4790 to CN 0:
[4144] 20:02:36: Dest: 10.0.1.2 Mask: 255.255.255.255
[4144] 20:02:36:

[4144] 20:02:36: Notifying CN 0 END

[4144] 20:02:36: Next dest 020F4898 in list 8:
[4144] 20:02:36: Dest: 192.168.1.0 Mask: 255.255.255.0
[4144] 20:02:36:

[4144] 20:02:36: Next dest 020F49A0 in list 8:
[4144] 20:02:36: Dest: 192.168.3.0 Mask: 255.255.255.0
[4144] 20:02:36:

[4144] 20:02:36: Next dest 020F34E8 in list 8:
[4144] 20:02:36: Dest: 192.168.2.0 Mask: 255.255.255.0
[4144] 20:02:36:

[4144] 20:02:36: Notifying CN 0 BEGIN
[4144] 20:02:36: Returning dest 020F4898 to CN 0:
[4144] 20:02:36: Dest: 192.168.1.0 Mask: 255.255.255.0
[4144] 20:02:36:

[4144] 20:02:36: Returning dest 020F49A0 to CN 0:
[4144] 20:02:36: Dest: 192.168.3.0 Mask: 255.255.255.0
[4144] 20:02:36:

[4144] 20:02:36: Returning dest 020F34E8 to CN 0:
[4144] 20:02:36: Dest: 192.168.2.0 Mask: 255.255.255.0
[4144] 20:02:36:

[4144] 20:02:36: Notifying CN 0 END

[4144] 20:02:36: Notifying CN 1 BEGIN
[4144] 20:02:36: Returning dest 020F4898 to CN 1:
[4144] 20:02:36: Dest: 192.168.1.0 Mask: 255.255.255.0
[4144] 20:02:36:

[4144] 20:02:36: Returning dest 020F49A0 to CN 1:
[4144] 20:02:36: Dest: 192.168.3.0 Mask: 255.255.255.0
[4144] 20:02:36:

[4144] 20:02:36: Returning dest 020F34E8 to CN 1:
[4144] 20:02:36: Dest: 192.168.2.0 Mask: 255.255.255.0
[4144] 20:02:36:

[4144] 20:02:36: Notifying CN 1 END

[4144] 20:02:36: ProcessChangedDestLists: Dests Removed: 4
[4144] 20:02:36: Leaving ProcessChangedDestLists: 4144

[3960] 04-19 20:01:35:453: ServerSendMessage on port/connection: 82 from: PPP Message: PPPDDMMSG_Stopped
[5944] 04-19 20:01:35:453: ServerReceiveMessage on port/connection: 82 from: PPP Message: PPPDDMMSG_Stopped
[5944] 04-19 20:01:35:453: DevStartClosing: Entered, hPort=130
[5944] 04-19 20:01:35:453: RmDisconnect:Disconnect posted on port 130
[5944] 04-19 20:01:35:515: RasPortDisconnect rc=600
[5944] 04-19 20:01:35:515: CLIENT ACTIVE FOR 139175 SECONDS
[5944] 04-19 20:01:35:515: TimerQRemove called
[5944] 04-19 20:01:35:515: TimerQRemove called
[5944] 04-19 20:01:35:515: TimerQRemove called
[5944] 04-19 20:01:35:515: DevCloseComplete:hPort=130,Auth=0,Rcv=0,Conn=0 1,Sec=3 2,Ppp=1
[3960] 04-19 20:01:36:453: ServerSendMessage on port/connection: 81 from: PPP Message: PPPDDMMSG_Stopped
[5944] 04-19 20:01:36:453: ServerReceiveMessage on port/connection: 81 from: PPP Message: PPPDDMMSG_Stopped
[5944] 04-19 20:01:36:453: DevStartClosing: Entered, hPort=129
[5944] 04-19 20:01:36:453: RmDisconnect:Disconnect posted on port 129
[5944] 04-19 20:01:36:453: RasPortDisconnect rc=600
[5944] 04-19 20:01:36:453: CLIENT ACTIVE FOR 4538 SECONDS
[5944] 04-19 20:01:36:593: TimerQRemove called
[5944] 04-19 20:01:36:593: TimerQRemove called
[5944] 04-19 20:01:36:593: TimerQRemove called
[5944] 04-19 20:01:36:593: DevCloseComplete:hPort=129,Auth=0,Rcv=0,Conn=0 1,Sec=3 2,Ppp=1
[5944] 04-19 20:01:37:515: Rasman state change received from port 130, 3->4
[5944] 04-19 20:01:37:515: SvDevDisconnected:Entered, hPort=130
[5944] 04-19 20:01:37:515: DevCloseComplete:hPort=130,Auth=0,Rcv=0,Conn=0 0,Sec=4 2,Ppp=1
[5944] 04-19 20:01:37:578: Rasman state change received from port 129, 3->4
[5944] 04-19 20:01:37:578: SvDevDisconnected:Entered, hPort=129
[5944] 04-19 20:01:37:578: DevCloseComplete:hPort=129,Auth=0,Rcv=0,Conn=0 0,Sec=4 2,Ppp=1
[3960] 04-19 20:01:39:515: ServerSendMessage on port/connection: 82 from: PPP Message: PPPDDMMSG_PortCleanedUp
[5944] 04-19 20:01:39:515: ServerReceiveMessage on port/connection: 82 from: PPP Message: PPPDDMMSG_PortCleanedUp
[5944] 04-19 20:01:39:515: DevCloseComplete:hPort=130,Auth=0,Rcv=0,Conn=0 0,Sec=4 2,Ppp=0
[5944] 04-19 20:01:39:515: RasSendNotification(INCOMING_DISCONNETED rc=0x0
[5944] 04-19 20:01:39:515: Added instance of VPN media to media table
[5944] 04-19 20:01:39:515: RmListen: Listen posted on port 130
[5944] 04-19 20:01:39:515: RasPortListen dwRetCode=600
[3960] 04-19 20:01:39:578: ServerSendMessage on port/connection: 81 from: PPP Message: PPPDDMMSG_PortCleanedUp
[5944] 04-19 20:01:39:578: ServerReceiveMessage on port/connection: 81 from: PPP Message: PPPDDMMSG_PortCleanedUp
[5944] 04-19 20:01:39:578: DevCloseComplete:hPort=129,Auth=0,Rcv=0,Conn=0 0,Sec=4 2,Ppp=0
[5944] 04-19 20:01:39:578: RasSendNotification(INCOMING_DISCONNETED rc=0x0
[5944] 04-19 20:01:39:578: Added instance of VPN media to media table
[5944] 04-19 20:01:39:578: RmListen: Listen posted on port 129
[5944] 04-19 20:01:39:578: RasPortListen dwRetCode=600
[5944] 04-19 20:02:19:875: Rasman state change received from port 129, 1->5
[5944] 04-19 20:02:19:875: Rasman state change received from port 129, 5->2
[5944] 04-19 20:02:19:875: SvDevConnected: Entered, hPort=129
[5944] 04-19 20:02:19:875: TimerQRemove called
[5944] 04-19 20:02:21:890: SvFrameReceived: Entered, hPort: 129
[5944] 04-19 20:02:21:890: SvFrameReceived: PPP frame on port 129
[3960] 04-19 20:02:24:515: ServerSendMessage on port/connection: 81 from: PPP Message: PPPDDMMSG_Authenticated
[5944] 04-19 20:02:24:515: ServerReceiveMessage on port/connection: 81 from: PPP Message: PPPDDMMSG_Authenticated
[5944] 04-19 20:02:24:515: SvPppUserOK: Entered, hPort=129
[5944] 04-19 20:02:24:515: TimerQRemove called
[3960] 04-19 20:02:24:515: ServerSendMessage on port/connection: 81 from: PPP Message: PPPDDMMSG_NewBundle
[5944] 04-19 20:02:24:515: ServerReceiveMessage on port/connection: 81 from: PPP Message: PPPDDMMSG_NewBundle
[5944] 04-19 20:02:24:515: SvPppNewLinkOrBundle: Entered, hPort=129
[5944] 04-19 20:02:24:515: SvPppSendInterfaceHandles: Entered, hPort=129
[3960] 04-19 20:02:25:906: ServerSendMessage on port/connection: 81 from: PPP Message: PPPDDMMSG_PppDone
[5944] 04-19 20:02:25:906: ServerReceiveMessage on port/connection: 81 from: PPP Message: PPPDDMMSG_PppDone
[5944] 04-19 20:02:25:906: SvPppDone: Entered, hPort=129
[5944] 04-19 20:02:25:906: TimerQRemove called
[5944] 04-19 20:02:25:906: TimerQRemove called
[5944] 04-19 20:02:25:906: Notifying Protocol = 0x21,Interface=tobias is Connected
[5944] 04-19 20:02:25:906: RasSendNotification(ENTRY_CONNECTED) rc=0x0
[5944] 04-19 20:02:25:906: Removed instance of VPN media from media table
[5944] 04-19 20:02:31:562: Rasman state change received from port 130, 1->5
[5944] 04-19 20:02:31:562: Rasman state change received from port 130, 5->2
[5944] 04-19 20:02:31:562: SvDevConnected: Entered, hPort=130
[5944] 04-19 20:02:31:562: TimerQRemove called
[5944] 04-19 20:02:33:625: SvFrameReceived: Entered, hPort: 130
[5944] 04-19 20:02:33:625: SvFrameReceived: PPP frame on port 130
[3960] 04-19 20:02:34:375: ServerSendMessage on port/connection: 82 from: PPP Message: PPPDDMMSG_Authenticated
[5944] 04-19 20:02:34:375: ServerReceiveMessage on port/connection: 82 from: PPP Message: PPPDDMMSG_Authenticated
[5944] 04-19 20:02:34:375: SvPppUserOK: Entered, hPort=130
[5944] 04-19 20:02:34:375: TimerQRemove called
[3960] 04-19 20:02:34:375: ServerSendMessage on port/connection: 82 from: PPP Message: PPPDDMMSG_NewBundle
[5944] 04-19 20:02:34:375: ServerReceiveMessage on port/connection: 82 from: PPP Message: PPPDDMMSG_NewBundle
[5944] 04-19 20:02:34:375: SvPppNewLinkOrBundle: Entered, hPort=130
[5944] 04-19 20:02:34:375: SvPppSendInterfaceHandles: Entered, hPort=130
[3960] 04-19 20:02:35:687: ServerSendMessage on port/connection: 82 from: PPP Message: PPPDDMMSG_PppDone
[5944] 04-19 20:02:35:687: ServerReceiveMessage on port/connection: 82 from: PPP Message: PPPDDMMSG_PppDone
[5944] 04-19 20:02:35:687: SvPppDone: Entered, hPort=130
[5944] 04-19 20:02:35:687: TimerQRemove called
[5944] 04-19 20:02:35:687: TimerQRemove called
[5944] 04-19 20:02:35:687: Notifying Protocol = 0x21,Interface=vpnuser is Connected
[5944] 04-19 20:02:35:718: RasSendNotification(ENTRY_CONNECTED) rc=0x0
[5944] 04-19 20:02:35:718: Removed instance of VPN media from media table
tobias
 
Posts: 29
Joined: Sat Apr 21, 2012 9:23 pm
Top

Re: RRAS - VPN Randomly Disconnecting

Postby chicagotech » Sun Apr 22, 2012 9:00 am

Is this Windows VPN server also DC?
Networking, Internet, Routing, VPN Troubleshooting on http://www.ChicagoTech.net
How to Setup Windows, Network, VPN & Remote Access on http://www.HowToNetworking.com
chicagotech
Site Admin
 
Posts: 6352
Joined: Mon Nov 27, 2006 1:24 pm
Location: Chicago USA
Top

Re: RRAS - VPN Randomly Disconnecting

Postby tobias » Sun Apr 22, 2012 10:52 am

Good Morning.

Yes, it is.

Windows 2003 Server + DC.

Thank You.
tobias
 
Posts: 29
Joined: Sat Apr 21, 2012 9:23 pm
Top

Re: RRAS - VPN Randomly Disconnecting

Postby guest » Mon Apr 23, 2012 8:07 am

I also want to share your some information on the issue.

We need to clarify the following two questions:

1. Can you reproduce the issue with Windows client?
2. Have you configured any connection policy on the VPN server?
2. What have you done before the issue occur?

If we can reproduce the issue with windows client, I suggest that you collect the following information to investigate the issue further.

1. Event Logging

a. Open Routing and Remote Access snap-in
b. Switch to Logging tab in the properties of a VPN server
c. Select Log all events, and then try the connection again.
d. After the connection fails, check the system event log for events logged during the connection process.

Note: After you are done viewing remote access events, select the Log errors and warnings option on the Logging tab to conserve system resources.

2. Enable tracing on the server and client with steps below:

a. Click Start->Run, type cmd and click OK.
b. On the two machines, run command “netsh ras set tracing * enabled” to enable RAS logging.
c. On the test VPN client machine, try to create a PPTP VPN connection to reproduce the issue.
d. Wait until the issue occurs, run command “netsh ras set tracing * disabled” to stop RAS logging on the two machines.
e. Zip all the logs in %SystemRoot%\tracing directory on the two machines and send them to me.

3. Collect the Network Monitor to capture and view the traffic sent between a VPN server and VPN client during the VPN connection process and during data transfer until the issue occur.

Note: Please record the time when the issue occur so we can compare the result between event logging, tracing and network monitor to find out the clues.
Tablet and Smartphone Setup Guide
http://www.quicksetupguide.com

Troubleshooting Vista Wireless
http://chicagotech.net/
guest
 
Posts: 9024
Joined: Mon Nov 27, 2006 1:10 pm
Top

Re: RRAS - VPN Randomly Disconnecting

Postby tobias » Mon Apr 23, 2012 11:28 am

Good afternoon!

These are answers:

1. Can you reproduce the issue with Windows client?
I have set now a Windows XP client to make the test connected directly to my network, enable tracing and configure ping -t to maintain connection alive.

2. Have you configured any connection policy on the VPN server?
Yes. Without this rule i can't access remote computers on the other side of the tunnel. Before this police only the tunnel side can access all computers on VPN Server side.

2. What have you done before the issue occur?
Can you be more specific about this question? The VPN setup is new and since it be configured never works 100%.


If we can reproduce the issue with windows client, I suggest that you collect the following information to investigate the issue further.

1. Event Logging

This is already enabled, I checked again.

The message on Windows Event Log is: The reason for disconnecting was administrative settings or explicit req.

2. Enable tracing on the server and client with steps below:

I will send you all the files after a disconnect.

3. Collect the Network Monitor to capture and view the traffic sent between a VPN server and VPN client during the VPN connection process and during data transfer until the issue occur.

Ok, the Network Monitor is collecting data now.

Thank You.
tobias
 
Posts: 29
Joined: Sat Apr 21, 2012 9:23 pm
Top

Re: RRAS - VPN Randomly Disconnecting

Postby tobias » Mon Apr 23, 2012 11:37 am

This is a DOC with my configuration:

https://skydrive.live.com/view.aspx?res ... b&app=Word

Please confirm if you can see it.
tobias
 
Posts: 29
Joined: Sat Apr 21, 2012 9:23 pm
Top

Re: RRAS - VPN Randomly Disconnecting

Postby chicagotech » Mon Apr 23, 2012 11:52 am

When I read your first post, I thought the RRAS is also DC because we have seen many cases like this one. It works for a while and then stops working. Basically, Microsoft doesn't recommend to install VPN server on the DC. If for some reasons you must do so, the option is re-configure the DNS excluding the second DNS A record from the DC. These links may help:

WAN dropped with RRAS enabled in DC - ChicagoTech.netJan 18, 2008 ... recommended to enable RRAS on a DC. If you do, you may have some name
resolution and connectivity issues. This link will give more details ...
www.chicagotech.net/netforums/viewtopic.php?f=3&t=3034

Windows server 2008 DC and VPN issue - ChicagoTech.netIs this server a multihomed DC ? I had similar problems on a multihomed DC (
Windows 2003) with RRAS. I fixed the DNS settings as it is ...
www.chicagotech.net/netforums/viewtopic.php?f=2&t=13665
Networking, Internet, Routing, VPN Troubleshooting on http://www.ChicagoTech.net
How to Setup Windows, Network, VPN & Remote Access on http://www.HowToNetworking.com
chicagotech
Site Admin
 
Posts: 6352
Joined: Mon Nov 27, 2006 1:24 pm
Location: Chicago USA
Top

Re: RRAS - VPN Randomly Disconnecting

Postby tobias » Mon Apr 23, 2012 12:14 pm

I did this yesterday: http://support.microsoft.com/kb/272294/pt-br

After 11 h (this morning) all VPN connections drop.
tobias
 
Posts: 29
Joined: Sat Apr 21, 2012 9:23 pm
Top

Re: RRAS - VPN Randomly Disconnecting

Postby tobias » Mon Apr 23, 2012 12:15 pm

After do http://support.microsoft.com/kb/272294/pt-br i don't reboot server.

Is that necessary?
tobias
 
Posts: 29
Joined: Sat Apr 21, 2012 9:23 pm
Top

Re: RRAS - VPN Randomly Disconnecting

Postby tobias » Mon Apr 23, 2012 12:24 pm

How to do that for RRAS interface?

"The resolution is to disable NetBIOS Over TCP/IP and DNS register on all interfaces including RRAS interfaces except the internal interface."
tobias
 
Posts: 29
Joined: Sat Apr 21, 2012 9:23 pm
Top
Next
Post a reply

Return to VPN, TS and Remote Access

Your Ad Here

Who is online

Users browsing this forum: No registered users and 5 guests

Powered by phpBB © 2000, 2002, 2005, 2007 phpBB Group