Hi
I have an L2TP connection that is failing and I started the netsh ras logging to try and diagnose it. I am not sure if it is something on my system that is causing the tunnel to close or something from the server side. If you could, please look over the attached logs and let me know what all of this means
I am connecting through a L2TP tunnel using the following procedure
- Disable the client logging
-- netsh ras set tracing * disabled
- Save old log files
- Restart logging
-- netsh ras set tracing * enabled
- Initiate my tunnel
= Send various network traffic through the tunnel
= Intermittently the tunnel closes and I need to log back on
Here are a few excerpts from \Windows\tracing. See my contents after the logs noted with *
Specifically:
[1560] 10:35:37:265: DeviceConnect: Changing state for VPN4-1 from 1 -> 4
* What are the state values associated to?
* What is state 1 and/or 4
[596] 10:35:42:671: PortDisconnect: VPN4-1
[596] 10:35:42:671:
[596] 10:35:42:671: PortClose: VPN4-1
[596] 10:35:42:671: PortClose: Changing state for VPN4-1 from 1 -> 0
[596] 10:35:42:671:
[1560] 10:36:46:125: PortOpen: VPN4-1
[1560] 10:36:46:125: PortOpen: successfully opened VPN4-1
* Who is issuing the disconnect? The PC I am connecting from or the server that I am going through to get to the other end of the tunnel?
[1664] 11:36:52: NhpDeletePrivateInterface
[1664] 11:36:52: AlgRmDeleteInterface
[1664] 11:36:52: NatpProcessConnectionNotify
[1664] 11:36:52: NhMapAddressToAdapter
[1664] 11:36:52: NhMapGuidToAdapter
[1664] 11:36:52: NhMapGuidToAdapter
[1664] 11:36:52: NatLookupInterfaceByAdapterIndex
[1664] 11:36:52: NatLookupInterfaceByAdapterIndex
[1624] 11:41:52: Denying dynamic port
Process ID: 1292
RPC port: False
Application name:
Process image filename: C:\WINDOWS\system32\svchost.exe
IP Version: IPv4
IP Protocol: UDP
Port number: 68
Local subnet only: False
[1624] 11:41:52: FwNotifyOnDeny: image = C:\WINDOWS\system32\svchost.exe; proto = UDP; port = 68
[1624] 11:41:52: FwNotifyOnDeny: Application already seen.
[1296] 11:41:52: FwServiceHandler: Received control: 132.
[356] 11:41:52: FwProfileMgrOnUpdatePolicyControl: Received notification.
[356] 11:41:52: NatGetSharingPolicy: NhPolicyAllowsSharing = True
[920] 11:41:52: NatpConfigurationChangedCallbackRoutine
[920] 11:41:52: NatpProcessConfigurationChanged
[920] 11:41:52: NatpFreeConnectionEntry
[920] 11:41:52: NatpBuildPortMappingList
[920] 11:41:52: NatpFreeConnectionEntry
[1972] 11:41:52: Removing dynamic port
Process ID: 1292
RPC port: False
Application name:
Process image filename: C:\WINDOWS\system32\svchost.exe
IP Version: IPv4
IP Protocol: UDP
Port number: 68
Local subnet only: False
[920] 11:41:52: NatpBuildPortMappingList
[920] 11:41:52: NatpFreeConnectionEntry
* Exactly what here is being denied and removed?
[1312] 10:34:43:406: GetHconnFromEntry. L2TP
[1312] 10:34:43:406: GetHconnFromEntry done. 668
[1460] 10:34:43:484: GetHconnFromEntry. L2TP
[1460] 10:34:43:484: GetHconnFromEntry done. 668
[1560] 10:35:36:734: SetEntryDialParams: UID=65859953, setmask=80000007, clearmask=0
[1560] 10:35:36:734: SetEntryDialParams: Writing to fDefault=0
[1560] 10:35:36:781: GetParamsListFromLsa Default=0
[1560] 10:35:36:781: GetParamsListFromLsa. 0x0
[1560] 10:35:36:781: CreateConnection: entry=L2TP, pbk=C:\Documents and Settings\All Users\Application Data\Microsoft\Network\Connections\Pbk\rasphone.pbk
[1560] 10:35:36:781: CreateConnection: Created new connection. hconn=0x10000, ref=1, pConn=0x2ec2fd8
[1560] 10:35:36:796: PortOpenEx: WAN Miniport (L2TP)
[1560] 10:35:36:812: PortOpen (1, VPN4-1) OpenInstances = (0)
[1560] 10:35:36:812: d:\nt\net\rras\ras\rasman\rasman\request.c: 2852: port 1 state chg: prev=0, new=4
[1560] 10:35:36:812: PortOpenEx (1) : OpenInstances = 1
[1560] 10:35:36:812: PortOpenEx: rc=0x0. DeviceFound=1
[1560] 10:35:36:812: AddConnectionPort: pConn=0x2ec2fd8, pConn->CB_Ports=1, port=1, dwSubEntry=1
[1560] 10:35:36:828: DisableAutoAddress done. 0
[1560] 10:35:36:843: DisableAutoAddress done. 0
[1560] 10:35:36:843: Adding filters for port=1, destaddr=0x102a8c0, eEncryption=2
[1560] 10:35:36:843: AddIpSecFilter, port=1, fServer=0, encryption=2
[1560] 10:35:36:843: DwAddClientIpSecFilter, port=1
[1560] 10:35:36:875: DwAddClientIpSecFilter: rc=0x0
[1560] 10:35:36:875: AddIpSecFilter: rc=0x0
[1560] 10:35:36:875: EnableIpSec: port=VPN4-1, fServer=0, fEnable = 1, rc=0x0
[1560] 10:35:36:875: DwDoIke: port=VPN4-1, hEvent=0x1230
[1560] 10:35:36:875: DwGetBestInterface: done. rc=0x0, address=0x1302a8c0, mask=0xffffff
[1560] 10:35:36:875: DwDoIke: done. 0x0
[1560] 10:35:36:875: DwDoIke for port VPN4-1 returned 0x0
[1560] 10:35:36:875: DoIke done. 0x0
[1560] 10:35:36:984: DwQueryIkeStatus: VPN4-1
[1560] 10:35:36:984: DwQueryIkeStatus: Closing Negotiation handle 0x2ed0500
[1560] 10:35:36:984: DwQueryIkeStatus: retcode=0x0, status=0x0
[1560] 10:35:37:265: d:\nt\net\rras\ras\rasman\rasman\util.c: 2605: port 1 state chg: prev=4, new=0
[1560] 10:35:37:265: d:\nt\net\rras\ras\rasman\rasman\util.c: 2656: port 1 async reqtype chg: prev=0, new=15
[1560] 10:35:37:265: Adding timeout of 120 for listen
[1560] 10:35:37:265: DwSendNotificationInternal(ENTRY_CONNECTING) rc=0x00000000
[1560] 10:35:37:265: Connect request on port: VPN4-1, error code 600
[596] 10:35:37:281: OVEVT_RASMAN_ADJUST_TIMER
[596] 10:35:39:093: WorkerThread: Async work event signaled on port: VPN4-1
[596] 10:35:39:093: OVEVT_DEV_ASYNCOP. pOverlapped = 0x160c58
[596] 10:35:39:093: CompleteAsyncRequest: pOverlapped=0x175de4
[596] 10:35:39:093: d:\nt\net\rras\ras\rasman\rasman\worker.c: 2350: port 1 async reqtype chg: prev=15, new=0
[596] 10:35:39:093: ServiceWorkRequest: Async op event 15 for port VPN4-1 returned 0
[1560] 10:35:39:109: ConnectCompleteRequest: entered for port 1
[1560] 10:35:39:125: d:\nt\net\rras\ras\rasman\rasman\request.c: 7656: port 1 state chg: prev=0, new=2
[1560] 10:35:39:125: AllocBundle: pBundle=0x31ca220
[1560] 10:35:39:125: d:\nt\net\rras\ras\rasman\rasman\request.c 9184: Mapping Cookie to handle. port = VPN4-1(0x161ea0), Bundlehandle = 0x1, linkhandle = 0x1
[596] 10:35:39:125: OVEVT_RASMAN_POST_RECV_PKT
[1560] 10:35:39:125: DwQueryAssociations
[1560] 10:35:39:125: DwQueryAssociation, rc=0x0
[1560] 10:35:39:125: ulEncryptionAlgo = 3
[1560] 10:35:39:125: ConnectCompleteRequest: DwSaveIpsecInfo returned 0x0
[1560] 10:35:39:125: Connection Completed on port: VPN4-1, error code: 0
[596] 10:35:39:125: PostReceivePacket returned 0x3e5
[1560] 10:35:39:140: SetRasdialInfo: port VPN4-1
[1560] 10:35:39:140: SetRasdialInfo: PbkPath: C:\Documents and Settings\All Users\Application Data\Microsoft\Network\Connections\Pbk\rasphone.pbk
[1560] 10:35:39:140: SetRasdialInfo: EntryName: L2TP
[1560] 10:35:39:140: SetRasdialInfo: PhoneNum: vpn.wireless..edu
[1560] 10:35:39:140: SetRasdialInfo: done 0
[1560] 10:35:39:140: GetParamsListFromLsa Default=0
[1560] 10:35:39:140: GetParamsListFromLsa. 0x0
[1560] 10:35:39:140: DwCacheCredentials
[1560] 10:35:39:140: DwCacheCredMgrCredentials: 0x0
[736] 10:35:39:156: PppStarted...VPN4-1
[736] 10:35:39:156: d:\nt\net\rras\ras\rasman\rasman\request.c: 6827: port 1 async reqtype chg: prev=0, new=26
[736] 10:35:42:578: sendpppmessagetorasman: msgid=2
[736] 10:35:42:578: SetPppEvent: pOverlapped=0x175e04
[736] 10:35:42:640: sendpppmessagetorasman: msgid=1
[736] 10:35:42:640: Setting last error for port VPN4-1 to ppp error 0x2de
[736] 10:35:42:640: SetPppEvent: pOverlapped=0x175e04
[596] 10:35:42:671: WorkerThread: Disconnect event signaled on port: VPN4-1
[596] 10:35:42:671: OVEVT_DEV_STATECHANGE. pOverlapped = 0x160c98
[596] 10:35:42:671: d:\nt\net\rras\ras\rasman\rasman\worker.c, 1936: Disconnecting port 1, connection 0x2ec2fd8, reason 1
[596] 10:35:42:671: Disconnecting Port 0xVPN4-1, reason 1
[596] 10:35:42:671: DisconnectPort: Saving Bundle stats for port VPN4-1
[596] 10:35:42:671: QueueCloseConnections: no dependent connections
[596] 10:35:42:671: 10. Throwing away handle 0x0!
* Again what is VPN4-1? Who is issuing this disconnect?
Thanks!
I have an L2TP connection that is failing and I started the netsh ras logging to try and diagnose it. I am not sure if it is something on my system that is causing the tunnel to close or something from the server side. If you could, please look over the attached logs and let me know what all of this means
I am connecting through a L2TP tunnel using the following procedure
- Disable the client logging
-- netsh ras set tracing * disabled
- Save old log files
- Restart logging
-- netsh ras set tracing * enabled
- Initiate my tunnel
= Send various network traffic through the tunnel
= Intermittently the tunnel closes and I need to log back on
Here are a few excerpts from \Windows\tracing. See my contents after the logs noted with *
Specifically:
[1560] 10:35:37:265: DeviceConnect: Changing state for VPN4-1 from 1 -> 4
* What are the state values associated to?
* What is state 1 and/or 4
[596] 10:35:42:671: PortDisconnect: VPN4-1
[596] 10:35:42:671:
[596] 10:35:42:671: PortClose: VPN4-1
[596] 10:35:42:671: PortClose: Changing state for VPN4-1 from 1 -> 0
[596] 10:35:42:671:
[1560] 10:36:46:125: PortOpen: VPN4-1
[1560] 10:36:46:125: PortOpen: successfully opened VPN4-1
* Who is issuing the disconnect? The PC I am connecting from or the server that I am going through to get to the other end of the tunnel?
[1664] 11:36:52: NhpDeletePrivateInterface
[1664] 11:36:52: AlgRmDeleteInterface
[1664] 11:36:52: NatpProcessConnectionNotify
[1664] 11:36:52: NhMapAddressToAdapter
[1664] 11:36:52: NhMapGuidToAdapter
[1664] 11:36:52: NhMapGuidToAdapter
[1664] 11:36:52: NatLookupInterfaceByAdapterIndex
[1664] 11:36:52: NatLookupInterfaceByAdapterIndex
[1624] 11:41:52: Denying dynamic port
Process ID: 1292
RPC port: False
Application name:
Process image filename: C:\WINDOWS\system32\svchost.exe
IP Version: IPv4
IP Protocol: UDP
Port number: 68
Local subnet only: False
[1624] 11:41:52: FwNotifyOnDeny: image = C:\WINDOWS\system32\svchost.exe; proto = UDP; port = 68
[1624] 11:41:52: FwNotifyOnDeny: Application already seen.
[1296] 11:41:52: FwServiceHandler: Received control: 132.
[356] 11:41:52: FwProfileMgrOnUpdatePolicyControl: Received notification.
[356] 11:41:52: NatGetSharingPolicy: NhPolicyAllowsSharing = True
[920] 11:41:52: NatpConfigurationChangedCallbackRoutine
[920] 11:41:52: NatpProcessConfigurationChanged
[920] 11:41:52: NatpFreeConnectionEntry
[920] 11:41:52: NatpBuildPortMappingList
[920] 11:41:52: NatpFreeConnectionEntry
[1972] 11:41:52: Removing dynamic port
Process ID: 1292
RPC port: False
Application name:
Process image filename: C:\WINDOWS\system32\svchost.exe
IP Version: IPv4
IP Protocol: UDP
Port number: 68
Local subnet only: False
[920] 11:41:52: NatpBuildPortMappingList
[920] 11:41:52: NatpFreeConnectionEntry
* Exactly what here is being denied and removed?
[1312] 10:34:43:406: GetHconnFromEntry. L2TP
[1312] 10:34:43:406: GetHconnFromEntry done. 668
[1460] 10:34:43:484: GetHconnFromEntry. L2TP
[1460] 10:34:43:484: GetHconnFromEntry done. 668
[1560] 10:35:36:734: SetEntryDialParams: UID=65859953, setmask=80000007, clearmask=0
[1560] 10:35:36:734: SetEntryDialParams: Writing to fDefault=0
[1560] 10:35:36:781: GetParamsListFromLsa Default=0
[1560] 10:35:36:781: GetParamsListFromLsa. 0x0
[1560] 10:35:36:781: CreateConnection: entry=L2TP, pbk=C:\Documents and Settings\All Users\Application Data\Microsoft\Network\Connections\Pbk\rasphone.pbk
[1560] 10:35:36:781: CreateConnection: Created new connection. hconn=0x10000, ref=1, pConn=0x2ec2fd8
[1560] 10:35:36:796: PortOpenEx: WAN Miniport (L2TP)
[1560] 10:35:36:812: PortOpen (1, VPN4-1) OpenInstances = (0)
[1560] 10:35:36:812: d:\nt\net\rras\ras\rasman\rasman\request.c: 2852: port 1 state chg: prev=0, new=4
[1560] 10:35:36:812: PortOpenEx (1) : OpenInstances = 1
[1560] 10:35:36:812: PortOpenEx: rc=0x0. DeviceFound=1
[1560] 10:35:36:812: AddConnectionPort: pConn=0x2ec2fd8, pConn->CB_Ports=1, port=1, dwSubEntry=1
[1560] 10:35:36:828: DisableAutoAddress done. 0
[1560] 10:35:36:843: DisableAutoAddress done. 0
[1560] 10:35:36:843: Adding filters for port=1, destaddr=0x102a8c0, eEncryption=2
[1560] 10:35:36:843: AddIpSecFilter, port=1, fServer=0, encryption=2
[1560] 10:35:36:843: DwAddClientIpSecFilter, port=1
[1560] 10:35:36:875: DwAddClientIpSecFilter: rc=0x0
[1560] 10:35:36:875: AddIpSecFilter: rc=0x0
[1560] 10:35:36:875: EnableIpSec: port=VPN4-1, fServer=0, fEnable = 1, rc=0x0
[1560] 10:35:36:875: DwDoIke: port=VPN4-1, hEvent=0x1230
[1560] 10:35:36:875: DwGetBestInterface: done. rc=0x0, address=0x1302a8c0, mask=0xffffff
[1560] 10:35:36:875: DwDoIke: done. 0x0
[1560] 10:35:36:875: DwDoIke for port VPN4-1 returned 0x0
[1560] 10:35:36:875: DoIke done. 0x0
[1560] 10:35:36:984: DwQueryIkeStatus: VPN4-1
[1560] 10:35:36:984: DwQueryIkeStatus: Closing Negotiation handle 0x2ed0500
[1560] 10:35:36:984: DwQueryIkeStatus: retcode=0x0, status=0x0
[1560] 10:35:37:265: d:\nt\net\rras\ras\rasman\rasman\util.c: 2605: port 1 state chg: prev=4, new=0
[1560] 10:35:37:265: d:\nt\net\rras\ras\rasman\rasman\util.c: 2656: port 1 async reqtype chg: prev=0, new=15
[1560] 10:35:37:265: Adding timeout of 120 for listen
[1560] 10:35:37:265: DwSendNotificationInternal(ENTRY_CONNECTING) rc=0x00000000
[1560] 10:35:37:265: Connect request on port: VPN4-1, error code 600
[596] 10:35:37:281: OVEVT_RASMAN_ADJUST_TIMER
[596] 10:35:39:093: WorkerThread: Async work event signaled on port: VPN4-1
[596] 10:35:39:093: OVEVT_DEV_ASYNCOP. pOverlapped = 0x160c58
[596] 10:35:39:093: CompleteAsyncRequest: pOverlapped=0x175de4
[596] 10:35:39:093: d:\nt\net\rras\ras\rasman\rasman\worker.c: 2350: port 1 async reqtype chg: prev=15, new=0
[596] 10:35:39:093: ServiceWorkRequest: Async op event 15 for port VPN4-1 returned 0
[1560] 10:35:39:109: ConnectCompleteRequest: entered for port 1
[1560] 10:35:39:125: d:\nt\net\rras\ras\rasman\rasman\request.c: 7656: port 1 state chg: prev=0, new=2
[1560] 10:35:39:125: AllocBundle: pBundle=0x31ca220
[1560] 10:35:39:125: d:\nt\net\rras\ras\rasman\rasman\request.c 9184: Mapping Cookie to handle. port = VPN4-1(0x161ea0), Bundlehandle = 0x1, linkhandle = 0x1
[596] 10:35:39:125: OVEVT_RASMAN_POST_RECV_PKT
[1560] 10:35:39:125: DwQueryAssociations
[1560] 10:35:39:125: DwQueryAssociation, rc=0x0
[1560] 10:35:39:125: ulEncryptionAlgo = 3
[1560] 10:35:39:125: ConnectCompleteRequest: DwSaveIpsecInfo returned 0x0
[1560] 10:35:39:125: Connection Completed on port: VPN4-1, error code: 0
[596] 10:35:39:125: PostReceivePacket returned 0x3e5
[1560] 10:35:39:140: SetRasdialInfo: port VPN4-1
[1560] 10:35:39:140: SetRasdialInfo: PbkPath: C:\Documents and Settings\All Users\Application Data\Microsoft\Network\Connections\Pbk\rasphone.pbk
[1560] 10:35:39:140: SetRasdialInfo: EntryName: L2TP
[1560] 10:35:39:140: SetRasdialInfo: PhoneNum: vpn.wireless..edu
[1560] 10:35:39:140: SetRasdialInfo: done 0
[1560] 10:35:39:140: GetParamsListFromLsa Default=0
[1560] 10:35:39:140: GetParamsListFromLsa. 0x0
[1560] 10:35:39:140: DwCacheCredentials
[1560] 10:35:39:140: DwCacheCredMgrCredentials: 0x0
[736] 10:35:39:156: PppStarted...VPN4-1
[736] 10:35:39:156: d:\nt\net\rras\ras\rasman\rasman\request.c: 6827: port 1 async reqtype chg: prev=0, new=26
[736] 10:35:42:578: sendpppmessagetorasman: msgid=2
[736] 10:35:42:578: SetPppEvent: pOverlapped=0x175e04
[736] 10:35:42:640: sendpppmessagetorasman: msgid=1
[736] 10:35:42:640: Setting last error for port VPN4-1 to ppp error 0x2de
[736] 10:35:42:640: SetPppEvent: pOverlapped=0x175e04
[596] 10:35:42:671: WorkerThread: Disconnect event signaled on port: VPN4-1
[596] 10:35:42:671: OVEVT_DEV_STATECHANGE. pOverlapped = 0x160c98
[596] 10:35:42:671: d:\nt\net\rras\ras\rasman\rasman\worker.c, 1936: Disconnecting port 1, connection 0x2ec2fd8, reason 1
[596] 10:35:42:671: Disconnecting Port 0xVPN4-1, reason 1
[596] 10:35:42:671: DisconnectPort: Saving Bundle stats for port VPN4-1
[596] 10:35:42:671: QueueCloseConnections: no dependent connections
[596] 10:35:42:671: 10. Throwing away handle 0x0!
* Again what is VPN4-1? Who is issuing this disconnect?
Thanks!