vpn issue with vista
I have RRAS set up on Win2K8 R2. Authentication is EAP MSCHAP v2. It's working fine with XP and Windows 7. However none of the Vista clients can connect.
I set up Vista running in a VM here so I had a client I could test with. I disabled the firewall. It's a fresh, clean install. I have no firewall running on the parent OS (win 7 x64) and the parent can connect fine to the same VPN.
I'm looking thru the Vista client logs and have found a few things of interest that I've googled, but really haven't found any sort of solution.
From RASGCW log:
[3612] 11:52:23: CIncomingConnectionsTask::CanHostTask: returns hr = 0
[3700] 11:52:54: VAN:RasDialInternalCallBack:Connecting to tag...:Opening port...:Ret:1
[3700] 11:52:54: VAN:RasDialInternalCallBack:Connecting to tag...:Port opened.:Ret:1
[3700] 11:52:54: VAN:RasDialInternalCallBack:Connecting to tag...:Connecting to www.XXXXXXXXXX.com...:Ret:1
[3700] 11:52:54: VAN:RasDialInternalCallBack:Connecting to tag...:Device connected.:Ret:1
[3700] 11:52:54: VAN:RasDialInternalCallBack:Connecting to tag...:All devices connected.:Ret:1
[3700] 11:52:54: VAN:RasDialInternalCallBack:Connecting to tag...:Verifying user name and password...:Ret:1
[3700] 11:52:56: VAN:RasDialInternalCallBack:Connecting to tag...:Verifying user name and password...:Ret:1
[3700] 11:52:59: VAN:RasDialInternalCallBack:Connecting to tag...:Verifying user name and password...:Ret:1
[3700] 11:53:03: VAN:RasDialInternalCallBack:Connecting to tag...:Verifying user name and password...:Ret:1
[3700] 11:53:07: VAN:RasDialInternalCallBack:Connecting to tag...:Verifying user name and password...:Ret:1
[3700] 11:53:11: VAN:RasDialInternalCallBack:Connecting to tag...:Verifying user name and password...:Ret:1
[3700] 11:53:15: VAN:RasDialInternalCallBack:Connecting to tag...:Verifying user name and password...:Ret:1
[3700] 11:53:19: VAN:RasDialInternalCallBack:Connecting to tag...:Verifying user name and password...:Ret:1
[3700] 11:53:23: VAN:RasDialInternalCallBack:Connecting to tag...:Verifying user name and password...:Ret:1
[3700] 11:53:27: VAN:RasDialInternalCallBack:Connecting to tag...:Verifying user name and password...:Ret:1
[3188] 11:53:31: ConnectThread:RasDialDlg failed with error: 806
rasman log - note the GRE blocked. dunno what could be blocking it when it works fine from windows 7 and there is no firewall on the vista client.
[1240] 01-12 11:52:43:065: SendNotificationRequest
[1240] 01-12 11:52:43:105: DwSendNotification returned 0x0
[3592] 01-12 11:52:46:119: GetParamsListFromLsa Default=0
[3592] 01-12 11:52:46:119: GetParamsListFromLsa. 0x0
[3592] 01-12 11:52:46:139: GetParamsListFromLsa Default=1
[3592] 01-12 11:52:46:139: GetParamsListFromLsa. 0x2
[3592] 01-12 11:52:47:942: GetParamsListFromLsa Default=0
[3592] 01-12 11:52:47:942: GetParamsListFromLsa. 0x0
[3592] 01-12 11:52:53:900: SetEntryDialParams: Writing to fDefault=0
[3592] 01-12 11:52:53:990: GetParamsListFromLsa Default=0
[3592] 01-12 11:52:53:990: GetParamsListFromLsa. 0x0
[3592] 01-12 11:52:53:990: CreateConnection: entry=tag, pbk=C:\Users\rob\AppData\Roaming\Microsoft\Network\Connections\Pbk\rasphone.pbk
[3592] 01-12 11:52:53:990: Info: fSecureRoutingCompartment: 0 and dwConSessionId 1 old Compartment ID 1:
[3592] 01-12 11:52:53:990: SetRasmanServiceStopControl: Enabled 0
[3592] 01-12 11:52:54:010: CreateConnection: Created new connection. hconn=0x30000, ref=1, pConn=0x46bf380
[3592] 01-12 11:52:54:090: IsTrustedCustomDll: pwsz=, fTrusted=0, rc=0
[3592] 01-12 11:52:54:090: PortOpenEx: WAN Miniport (PPTP)
[3592] 01-12 11:52:54:100: SetRasmanServiceStopControl: Enabled 0
[3592] 01-12 11:52:54:100: PortOpen (2, VPN1-1) OpenInstances = (0)
[3592] 01-12 11:52:54:100: d:\vistartm\net\rras\ras\rasman\rasman\request.c: 2770: port 2 state chg: prev=4, new=4
[3592] 01-12 11:52:54:100: PortOpenEx (2) : OpenInstances = 1
[3592] 01-12 11:52:54:100: PortOpenEx: rc=0x0. DeviceFound=1
[3592] 01-12 11:52:54:201: CleanUpDeadClientProcessBlock
[3592] 01-12 11:52:54:201: SetDialMachineEventHandleCommon:
[3592] 01-12 11:52:54:201: Cleaning up process 1952
[3592] 01-12 11:52:54:201: CleanUpEventQueue:
[3592] 01-12 11:52:54:201: AddConnectionPort: pConn=0x46bf380, pConn->CB_Ports=1, port=2, dwSubEntry=1
[3592] 01-12 11:52:54:291: d:\vistartm\net\rras\ras\rasman\rasman\util.c: 2788: port 2 state chg: prev=4, new=0
[3592] 01-12 11:52:54:291: d:\vistartm\net\rras\ras\rasman\rasman\util.c: 2833: port 2 async reqtype chg: prev=0, new=15
[3592] 01-12 11:52:54:291: Adding timeout of 120 for listen
[2536] 01-12 11:52:54:291: OVEVT_RASMAN_ADJUST_TIMER
[3592] 01-12 11:52:54:341: DwSendNotificationInternal(ENTRY_CONNECTING) rc=0x00000000
[3592] 01-12 11:52:54:341: DwCacheRefInterface: setuserdata. Addr=0x9379ff47, rc=0x0
[3592] 01-12 11:52:54:341: Connect request on port: VPN1-1, error code 600
[2536] 01-12 11:52:54:541: WorkerThread: Async work event signaled on port: VPN1-1
[2536] 01-12 11:52:54:541: OVEVT_DEV_ASYNCOP. pOverlapped = 0x2392870
[2536] 01-12 11:52:54:541: CompleteAsyncRequest: pOverlapped=0x3b23ae4
[2536] 01-12 11:52:54:541: PostDialEventContext: for pid:0x7a0, client Event:0x2c0context pointer=0x3b23ae4, type=2
[2536] 01-12 11:52:54:541: AppendNewMsgToQueue:Set client Event:0x2c0
[2536] 01-12 11:52:54:541: d:\vistartm\net\rras\ras\rasman\rasman\worker.c: 2386: port 2 async reqtype chg: prev=15, new=0
[2536] 01-12 11:52:54:541: ServiceWorkRequest: Async op event 15 for port VPN1-1 returned 0
[3592] 01-12 11:52:54:541: PickOneMsgForAEvent:send context to Pid:0x7a0, clientEvent:0x2c0
[3592] 01-12 11:52:54:541: PickOneMsgFromQueueList:
[3592] 01-12 11:52:54:581: ConnectCompleteRequest: entered for port 2
[3592] 01-12 11:52:54:591: d:\vistartm\net\rras\ras\rasman\rasman\request.c: 7835: port 2 state chg: prev=0, new=2
[3592] 01-12 11:52:54:591: AllocBundle: pBundle=0x241b308
[3592] 01-12 11:52:54:591: d:\vistartm\net\rras\ras\rasman\rasman\request.c 9353: Mapping Cookie to handle. port = VPN1-1(0x2394d98), Bundlehandle = 0x3, linkhandle = 0x3
[3592] 01-12 11:52:54:591: ConnectCompleteRequest: DwSaveIpAddressInfo returned 0x0
[3592] 01-12 11:52:54:591: Connection Completed on port: VPN1-1, error code: 0
[3592] 01-12 11:52:54:601: SetRasdialInfo: port VPN1-1
[3592] 01-12 11:52:54:601: SetRasdialInfo: PbkPath: C:\Users\rob\AppData\Roaming\Microsoft\Network\Connections\Pbk\rasphone.pbk
[3592] 01-12 11:52:54:601: SetRasdialInfo: EntryName: tag
[3592] 01-12 11:52:54:601: SetRasdialInfo: PhoneNum: mail.theatomgroup.com
[3592] 01-12 11:52:54:601: SetRasdialInfo: cbCAD=55. pData=0x46ab740
[3592] 01-12 11:52:54:601: SetRasdialInfo: done 0
[3592] 01-12 11:52:54:601: SetEapLogonInfo. Port VPN1-1
[3592] 01-12 11:52:54:601: SetEapLogonInfo. cbInfo=607, fLogon=0
[3592] 01-12 11:52:54:601: PCB_pEapLogonInfo=0x46221a8
[3592] 01-12 11:52:54:601: SetEapLogonInfo. retcode=0x0
[3592] 01-12 11:52:54:611: GetParamsListFromLsa Default=0
[3592] 01-12 11:52:54:611: GetParamsListFromLsa. 0x0
[3592] 01-12 11:52:54:611: DwCacheCredentials
[3592] 01-12 11:52:54:611: DwCacheCredMgrCredentials: 0x0
[2576] 01-12 11:52:54:641: PppStarted...VPN1-1
[2576] 01-12 11:52:56:644: sendpppmessagetorasman: msgid=9
[2576] 01-12 11:52:56:644: SetPppEvent: pOverlapped=0x3b23b04
[2576] 01-12 11:52:56:644: PostDialEventContext: for pid:0x7a0, client Event:0x2c0context pointer=0x3b23b04, type=3
[2576] 01-12 11:52:56:644: AppendNewMsgToQueue:Set client Event:0x2c0
[3592] 01-12 11:52:56:644: PickOneMsgForAEvent:send context to Pid:0x7a0, clientEvent:0x2c0
[3592] 01-12 11:52:56:644: PickOneMsgFromQueueList:
[2576] 01-12 11:52:59:648: sendpppmessagetorasman: msgid=9
[2576] 01-12 11:52:59:648: SetPppEvent: pOverlapped=0x3b23b04
[2576] 01-12 11:52:59:648: PostDialEventContext: for pid:0x7a0, client Event:0x2c0context pointer=0x3b23b04, type=3
[2576] 01-12 11:52:59:648: AppendNewMsgToQueue:Set client Event:0x2c0
[3592] 01-12 11:52:59:648: PickOneMsgForAEvent:send context to Pid:0x7a0, clientEvent:0x2c0
[3592] 01-12 11:52:59:648: PickOneMsgFromQueueList:
[2576] 01-12 11:53:03:714: sendpppmessagetorasman: msgid=9
[2576] 01-12 11:53:03:714: SetPppEvent: pOverlapped=0x3b23b04
[2576] 01-12 11:53:03:714: PostDialEventContext: for pid:0x7a0, client Event:0x2c0context pointer=0x3b23b04, type=3
[2576] 01-12 11:53:03:714: AppendNewMsgToQueue:Set client Event:0x2c0
[3592] 01-12 11:53:03:714: PickOneMsgForAEvent:send context to Pid:0x7a0, clientEvent:0x2c0
[3592] 01-12 11:53:03:714: PickOneMsgFromQueueList:
[2576] 01-12 11:53:07:720: sendpppmessagetorasman: msgid=9
[2576] 01-12 11:53:07:720: SetPppEvent: pOverlapped=0x3b23b04
[2576] 01-12 11:53:07:720: PostDialEventContext: for pid:0x7a0, client Event:0x2c0context pointer=0x3b23b04, type=3
[2576] 01-12 11:53:07:720: AppendNewMsgToQueue:Set client Event:0x2c0
[3592] 01-12 11:53:07:720: PickOneMsgForAEvent:send context to Pid:0x7a0, clientEvent:0x2c0
[3592] 01-12 11:53:07:720: PickOneMsgFromQueueList:
[2576] 01-12 11:53:11:726: sendpppmessagetorasman: msgid=9
[2576] 01-12 11:53:11:726: SetPppEvent: pOverlapped=0x3b23b04
[2576] 01-12 11:53:11:726: PostDialEventContext: for pid:0x7a0, client Event:0x2c0context pointer=0x3b23b04, type=3
[2576] 01-12 11:53:11:726: AppendNewMsgToQueue:Set client Event:0x2c0
[3592] 01-12 11:53:11:726: PickOneMsgForAEvent:send context to Pid:0x7a0, clientEvent:0x2c0
[3592] 01-12 11:53:11:726: PickOneMsgFromQueueList:
[2576] 01-12 11:53:15:732: sendpppmessagetorasman: msgid=9
[2576] 01-12 11:53:15:732: SetPppEvent: pOverlapped=0x3b23b04
[2576] 01-12 11:53:15:732: PostDialEventContext: for pid:0x7a0, client Event:0x2c0context pointer=0x3b23b04, type=3
[2576] 01-12 11:53:15:732: AppendNewMsgToQueue:Set client Event:0x2c0
[3592] 01-12 11:53:15:732: PickOneMsgForAEvent:send context to Pid:0x7a0, clientEvent:0x2c0
[3592] 01-12 11:53:15:732: PickOneMsgFromQueueList:
[2576] 01-12 11:53:19:737: sendpppmessagetorasman: msgid=9
[2576] 01-12 11:53:19:737: SetPppEvent: pOverlapped=0x3b23b04
[2576] 01-12 11:53:19:737: PostDialEventContext: for pid:0x7a0, client Event:0x2c0context pointer=0x3b23b04, type=3
[2576] 01-12 11:53:19:737: AppendNewMsgToQueue:Set client Event:0x2c0
[3592] 01-12 11:53:19:737: PickOneMsgForAEvent:send context to Pid:0x7a0, clientEvent:0x2c0
[3592] 01-12 11:53:19:737: PickOneMsgFromQueueList:
[2576] 01-12 11:53:23:743: sendpppmessagetorasman: msgid=9
[2576] 01-12 11:53:23:743: SetPppEvent: pOverlapped=0x3b23b04
[2576] 01-12 11:53:23:743: PostDialEventContext: for pid:0x7a0, client Event:0x2c0context pointer=0x3b23b04, type=3
[2576] 01-12 11:53:23:743: AppendNewMsgToQueue:Set client Event:0x2c0
[1240] 01-12 11:53:23:743: PickOneMsgForAEvent:send context to Pid:0x7a0, clientEvent:0x2c0
[1240] 01-12 11:53:23:743: PickOneMsgFromQueueList:
[2576] 01-12 11:53:27:749: sendpppmessagetorasman: msgid=9
[2576] 01-12 11:53:27:749: SetPppEvent: pOverlapped=0x3b23b04
[2576] 01-12 11:53:27:749: PostDialEventContext: for pid:0x7a0, client Event:0x2c0context pointer=0x3b23b04, type=3
[2576] 01-12 11:53:27:749: AppendNewMsgToQueue:Set client Event:0x2c0
[3592] 01-12 11:53:27:759: PickOneMsgForAEvent:send context to Pid:0x7a0, clientEvent:0x2c0
[3592] 01-12 11:53:27:759: PickOneMsgFromQueueList:
[2576] 01-12 11:53:31:755: sendpppmessagetorasman: msgid=10
[2576] 01-12 11:53:31:755: PPPMSG_Stopped. dwError=0x2d1
[2576] 01-12 11:53:31:755: setting error to 721
[2576] 01-12 11:53:31:755: RASDiag: Mapping to new error code: 806 (ERROR_VPN_GRE_BLOCKED) instead of 721 (ERROR_PPP_NO_RESPONSE)
[2576] 01-12 11:53:31:755: DwProcessPppFailureMessage: disconnecting VPN1-1,hEventClientDisconnect=0xffffffff
[2576] 01-12 11:53:31:755: Disconnecting Port 0xVPN1-1, reason 0
[2576] 01-12 11:53:31:755: DisconnectPort: Saving Bundle stats for port VPN1-1
[2576] 01-12 11:53:31:755: DwDeleteCredentials
[2576] 01-12 11:53:31:755: RasImpersonateUser. 0x0
[2576] 01-12 11:53:31:765: RasRevertToSelf. 0x0
[2576] 01-12 11:53:31:765: DwDeleteCredentials: 0x46bf380
[2576] 01-12 11:53:31:765: DisconnectPort: DwDeleteCreds returned 0x0
[2576] 01-12 11:53:31:765: QueueCloseConnections: no dependent connections
[2576] 01-12 11:53:31:765: d:\vistartm\net\rras\ras\rasman\rasman\util.c 2355: Disconnected Port 2, reason 0. rc=0x258
[2576] 01-12 11:53:31:765: d:\vistartm\net\rras\ras\rasman\rasman\util.c: 2465: port 2 state chg: prev=2, new=3
[2576] 01-12 11:53:31:765: d:\vistartm\net\rras\ras\rasman\rasman\util.c: 2595: port 2 async reqtype chg: prev=0, new=0
[2576] 01-12 11:53:31:765: DisconnectPort Complete
[2536] 01-12 11:53:31:805: WorkerThread: Disconnect event signaled on port: VPN1-1
[2536] 01-12 11:53:31:805: OVEVT_DEV_STATECHANGE. pOverlapped = 0x23928b0
[2536] 01-12 11:53:31:805: d:\vistartm\net\rras\ras\rasman\rasman\request.c: 4904: port 2 state chg: prev=3, new=4
[2536] 01-12 11:53:31:805: d:\vistartm\net\rras\ras\rasman\rasman\request.c: 4915: port 2 async reqtype chg: prev=0, new=0
[2536] 01-12 11:53:31:805: CompleteDisconnectRequest: signalling 0xffffffff for VPN1-1
[2536] 01-12 11:53:31:805: SignalPortDisconnect: pOverlapped=0x3b23ac4
[2536] 01-12 11:53:31:805: PostDialEventContext: for pid:0x7a0, client Event:0x2c0context pointer=0x3b23ac4, type=1
[2536] 01-12 11:53:31:805: AppendNewMsgToQueue:Set client Event:0x2c0
[2536] 01-12 11:53:31:815: Disconnect completed on port: VPN1-1
[2536] 01-12 11:53:31:815: d:\vistartm\net\rras\ras\rasman\rasman\worker.c, 2268: Autoclosing port 2
[2536] 01-12 11:53:31:815: PortClose: port (2). OpenInstances = 1
[2536] 01-12 11:53:31:815: PortClose: going to clear the rasapi32 event handle
[2536] 01-12 11:53:31:815: SetDialMachineEventHandleCommon:
[2536] 01-12 11:53:31:815: SetDialEventHandleCommon: posting last event for port 2
[2536] 01-12 11:53:31:815: PostDialEventContext: for pid:0x7a0, client Event:0x2c0context pointer=0x3b23b24, type=4
[2536] 01-12 11:53:31:815: PostDialEventContext: going to put the OVEVT_DIAL_LAST message in the queue
[2536] 01-12 11:53:31:815: Freeing the notifier list for port 2
[2536] 01-12 11:53:31:815: PortClose (2). OpenInstances = 0
[2536] 01-12 11:53:31:815: d:\vistartm\net\rras\ras\rasman\rasman\request.c: 3588: port 2 async reqtype chg: prev=0, new=0
[2536] 01-12 11:53:31:815: d:\vistartm\net\rras\ras\rasman\rasman\request.c: 3591: port 2 state chg: prev=4, new=4
[2536] 01-12 11:53:31:815: RemoveConnectionPort: port 2, fOwnerClose=0, pConn=0x46bf380, pConn->CB_Ports=0
[2536] 01-12 11:53:31:815: Completely disconnected connection: Reason: ERROR_IDLE_TIMEOUT (828)
[2536] 01-12 11:53:31:815: SendSensNotification(_RAS_DISCONNECT) for 0x00030000 returns 0x00000000
[2536] 01-12 11:53:31:825: DwSendNotificationInternal(ENTRY_DISCONNECTED) rc=0x0
[2536] 01-12 11:53:31:825: RemoveConnectionPort: FreeConnection hconn=0x30000, pconn=0x46bf380, AutoClose=1
[2536] 01-12 11:53:31:825: FreeConnection: pConn=0x46bf380, 1
[2536] 01-12 11:53:31:825: d:\vistartm\net\rras\ras\rasman\rasman\request.c, 3680: Clearing the autoclose flag for port 2
[2536] 01-12 11:53:31:825: SetRasmanServiceStopControl: Enabled 1
[3592] 01-12 11:53:31:845: PickOneMsgForAEvent:send context to Pid:0x7a0, clientEvent:0x2c0
[3592] 01-12 11:53:31:845: PickOneMsgFromQueueList:
[3592] 01-12 11:53:31:845: PickOneMsgFromQueueList:Set client Event:0x2c0
[3592] 01-12 11:53:31:845: CleanUpDeadClientProcessBlock
[3592] 01-12 11:53:31:845: SetDialMachineEventHandleCommon:
[3592] 01-12 11:53:31:845: SetDialMachineEventHandleCommon:Error: meaningless operation
[3592] 01-12 11:53:31:855: PickOneMsgForAEvent:send context to Pid:0x7a0, clientEvent:0x2c0
[3592] 01-12 11:53:31:855: PickOneMsgFromQueueList:
[3592] 01-12 11:53:31:855: ReferenceCustomCount
[3592] 01-12 11:53:31:855: ReferenceCustomCount done. 668
[3592] 01-12 11:53:31:855: Connection 0x00030000 not found
[3592] 01-12 11:53:31:855: GetHportFromConnection: connection 0x00030000 not found.
[3592] 01-12 11:53:31:865: RefConnection: 0x30000
[3592] 01-12 11:53:31:865: RefConnection: pConn = NULL for 0x30000
odd that though I am using EAP, the RASEAP.LOG file is zero bytes
On the server side, the error I'm seeing is very vague: EventID 1006 - Negotiation failed. Requested EAP methods not available.
You can see in this screenshot of the server side, I do NOT have MS-CHAP v2 checked off, only EAP.
http://clip2net.com/clip/m29510/1294852696-clip-27kb.png
If I check off MS-CHAP v2 in addition, the win7 and xp clients can no longer connect.
This is a screenshot of a working win7 client config:
http://clip2net.com/clip/m29510/1294852785-clip-26kb.png
This is a screenshot of a non-working Vista client config:
http://clip2net.com/clip/m29510/1294852893-clip-64kb.png
If anyone has any ideas, it would be greatly appreciated. I've spent all day working on this. Trying things that I've read about in this forum like changing the registry on the client to allow weak encryption. I'm having zero luck.
Thanks very much.
January 12th, 2011 12:28pm
You will have a better chance to be answered here:
http://answers.microsoft.com/en-us/default.aspx I suggest you post your question without the log first.
Free Windows Admin Tool Kit Click here and download it now
February 14th, 2011 5:55pm
thanks, i ended up opening a ticket with MSFT and after 3 weeks of india working with me and telling me several times it would be escalated and hearing nothing back for days at a time, i ended up just buying two draytek routers and getting rid of the microsoft
solution. i finally got a call from an escalation engineer last week and just told him to credit back the incident to our account.
February 16th, 2011 8:12am