Trouble connecting to VM's after 5.1.1 upgrade

[murben]

Having a strange issue when we try to connect to our VM's after our upgrade to 5.1.1.  Keep in mind, the VM's show "Available" in View Manager this entire time.  On the first attempt to connect to a VM, the client will eventually time-out with the error "All Available desktop sources for this desktop are currently busy..."  If I click "Try Again", I get "The display protocol for this desktop is currently not available".  Then, if I click "Try Again", It connects and everything works perfectly.  I can reproduce this over and over all day long.  If I log off of the desktop and log back on, all works fine, however, if I restart the view agent, reboot the desktop, or re-compose the desktop, I have to go through the cycle of "Try Again" 3 times before I can get back in.  This happens on all desktops in all pools and only started after our upgrade to 5.1.1.  We are set up to use the PCoIP protocol and have 2 connection servers.  Same results from both connection servers.  Makes no difference if we enable PCoIP secure gateway or not.  I'm really stumped...

This is from the connection server log on the first connection attempt, nothing show's up in the agent's log:

2012-09-26T10:01:57.832-04:00 INFO  (12D8-0E98) <TP-Processor2> [AuthorizationFilter] (SESSION:cc9b-***-e377) User PMINSCO\obem1 has successfully authenticated to VDM
2012-09-26T10:01:57.842-04:00 INFO  (12D8-0E98) <TP-Processor2> [Audit] (SESSION:cc9b-***-e377) BROKER_LOGON:USER:PMINSCO\obem1;USERSID:S-1-5-21-2149947737-4086579574-1125231066-5508;USERDN:CN=S-1-5-21-2149947737-4086579574-1125231066-5508,CN=ForeignSecurityPrincipals,DC=vdi,DC=vmware,DC=int;
2012-09-26T10:02:00.675-04:00 INFO  (0DC8-0CE8) <Thread-32> [g] (Request3) User obem1 connected to the Secure Gateway Server - session ID: 28B4-***-14B0
2012-09-26T10:02:04.182-04:00 INFO  (12D8-1620) <CEIP:ConfigurationMonitor> [CEIP] CEIP: Disabled
2012-09-26T10:03:03.123-04:00 INFO  (12D8-0E98) <TP-Processor2> [SessionLaunchContext] (SESSION:cc9b-***-e377) PMINSCO\obem1, App = SBS-Windows7-x32-LC: Session request failed.
(SESSION:cc9b-***-e377:) [PMINSCO\obem1, App = SBS-Windows7-x32-LC] (11ms): Attempted to start new managed session.
(SESSION:cc9b-***-e377:) [PMINSCO\obem1, App = SBS-Windows7-x32-LC] (60035ms): 1 server(s) were rejected because StartSession failure. Possible session clash. [d771aa6f-0f57-4efd-be55-dd4731da37e4]
(SESSION:cc9b-***-e377:) [PMINSCO\obem1, App = SBS-Windows7-x32-LC] (60037ms): Application launch failed, exception was: All available desktop sources for this desktop are currently busy. Please try again later.

The second attempt to connect gives me this in the connection servers log:

2012-09-26T10:24:04.203-04:00 INFO  (12D8-1620) <CEIP:ConfigurationMonitor> [CEIP] CEIP: Disabled

2012-09-26T10:24:05.651-04:00 ERROR (12D8-0E98) <TP-Processor2> [FarmImp] (SESSION:ff5f-***-3e44) User PMINSCO\obem1 could not be connected to existing session for desktop "SBS-Windows7-x32-LC". Machine cn=d771aa6f-0f57-4efd-be55-dd4731da37e4,ou=servers,dc=vdi,dc=vmware,dc=int does not support protocols [PCOIP]: The requested protocol is unavailable at this time

2012-09-26T10:24:05.651-04:00 INFO  (12D8-0E98) <TP-Processor2> [SessionLaunchContext] (SESSION:ff5f-***-3e44) PMINSCO\obem1, App = SBS-Windows7-x32-LC: Session request failed.

(SESSION:ff5f-***-3e44:) [PMINSCO\obem1, App = SBS-Windows7-x32-LC] (10ms): User has 1 possible sessions to analyze.

(SESSION:ff5f-***-3e44:) [PMINSCO\obem1, App = SBS-Windows7-x32-LC] (10ms): Possible session match found on server cn=d771aa6f-0f57-4efd-be55-dd4731da37e4,ou=servers,dc=vdi,dc=vmware,dc=int.

(SESSION:ff5f-***-3e44:) [PMINSCO\obem1, App = SBS-Windows7-x32-LC] (10ms): Found matching capid 8EF6-***-7E12 for server d771aa6f-0f57-4efd-be55-dd4731da37e4

(SESSION:ff5f-***-3e44:) [PMINSCO\obem1, App = SBS-Windows7-x32-LC] (1438ms): Application launch failed, exception was: The display protocol for this desktop is currently not available. [NAME=PCOIP, ERROR-CODE=PROTOCOL_ERR_FAILURE]

I get this in the agent log on the second attempt:

2012-09-26T10:24:04.299-04:00 WARN  (0184-0ED0) <MessageFrameWorkDispatch> [wsnm_desktop] Needed to disconnect existing PCoIP connection during requestConnection {SESSION:ff5f-***-3e44}

2012-09-26T10:24:04.299-04:00 WARN  (0184-0ED0) <MessageFrameWorkDispatch> [wsnm_desktop] PCoIP requested disconnect while busy! {SESSION:ff5f-***-3e44}

2012-09-26T10:24:04.408-04:00 WARN  (0184-0ED0) <MessageFrameWorkDispatch> [wsnm_desktop] Incomplete login for session 1 {SESSION:ff5f-***-3e44}

2012-09-26T10:24:05.126-04:00 INFO  (0144-0D40) <3392> [LogonUI] Program 'LogonUI - Windows Logon User Interface Host' started, version=6.1.7601.17514 (win7sp1_rtm.101119-1850), pid=0x144, buildtype=release, usethread=0, closeafterwrite=0

2012-09-26T10:24:05.250-04:00 INFO  (0FF4-0760) <1888> [VMwareView-RdeServer] Program 'VMwareView-RdeServer - VMware View RDE Server' started, version=8.0.2 build-697851, pid=0xFF4, buildtype=release, usethread=0, closeafterwrite=0

2012-09-26T10:24:05.594-04:00 WARN  (0184-0ED0) <MessageFrameWorkDispatch> [wsnm_desktop] PCoIP connection request failed: 14 {SESSION:ff5f-***-3e44}

And then everything works fine on the third attempt.

Any help with this issue is greatly appreciated.  Let me know if there is any addtional info I can provide.

Thanks,

Ben

[mpryor]

There is a one minute gap in your first connection attempt before the broker times out, waiting for the agent to respond. The second request shows an existing session match and the connect to the same VM results in a busy response, and the agent is likewise reporting that it had a previous PCoIP session that needed to be torn down.

I believe what is happening here, is that the first request is getting stuck. It is taking more than a minute to respond to and this in turn blocks the second, as the first is still being processed when it comes in, but the second request does at least cancel it. Have you looked at the VM performance metrics during this time? Logs from the agent covering the full period may give some more clues as well.

Mike

[etieseler]

I assume you have already updated VMTools first, then the hardware version of the VM, then finally updated the View Agent?

I had similar issues connecting after upgradeing to 5.1.1, not quite the same as you, but issues non-the-less. Connection Manager showed the desktop as available and it all looked OK, but the user would log on, see the desktop for a brief moment, then get a black screen, eventually returning to the login box. If they tried again it would say their desktop is currently unavailable.

I had to once again re-install the VMTools and then the View Agent. After doing this a second time, they could log in.... so far without any issues.

Ed

[murben]

I have found the problem and was able to correct the issue!!  It looks like it was the McAfee MOVE SVM that we are using with VShield.  Looking at the SVM logs in McAfee EPO, I noticed a lot of entries stating that the scan timed out on "C:\Program Files\VMware\VMware View\Agent\jre\lib\rt.jar" for each of the virtual desktops.  I shut down the SVM on one host and the problem went away immediately, so now I have put an exception in McAfee so that it doesn't scan inside "c:\program files\VMWare\" and it appears that everything is working as expected.

[Stcherkassov]

Ty for the info, will have it in mind when going to update my EPO to 5.1.1.

Regards!

[thegooddoctor]

Was getting very similar logs as OP in connection server and VM McAffee logs. Adding the exception worked for me.