Random freezes with View 5.1.3

[JKylePPG]

For quite a while, a customer we installed View 5.1.3 for has been experience seemingly random freezes, where a handful (just a few or nearly all) of the VMs will freeze (screen stays on, but is unresponsive) for 5-15 minutes. After a certain amount of time, they all begin working again, picking up where they were. Rebooting the client doesn't seem to help. This happens the same no matter what client is used. Most PCs are old XP systems running the 5.3.0 client but there are a few thin clients that experience the same problem.

The environment is a single connection server serving about 35 desktops. I turned on PCoIP Secure Gateway and that didn't help. Watching the performance of the VMs in vSphere Manager doesn't show any unusual high usage. The clients use kiosk mode to consistently get the same VM. When disconnected, the View client immediately begins attempts to reconnect. These are public-use PCs that are used for certain lengths of time (30-60 minutes or so) and then log off/disconnect from the VM.

Looking at the logs on the connection server, I have a couple concerns... such as these line:

2014-08-07T13:31:47.357-04:00 INFO  (0A70-0EE8) <Tracker:Heartbeat> [TrackerManager] (servername) Inbound queue stats: total=0, max=0, dropped=0

2014-08-07T13:31:47.357-04:00 INFO  (0A70-0EE8) <Tracker:Heartbeat> [TrackerManager] (servername) Outbound queue stats: total=36683, max=50, dropped=0

I couldn't find any explanation of this - the inbounds stay at 0 but the outbound just gets bigger and bigger as time goes by. This number was the server had been rebooted about four hours earlier. Should I be concerned that the total is much more than the max?

Looking farther into the logs, I see the following, about 30-40 minutes before the freezes began this day:

2014-08-07T16:04:21.149-04:00 WARN  (0CF4-0610) <Tunnel#12> [ca] (0663-***-37A7) Tunnel error: Socket closed

2014-08-07T16:04:21.493-04:00 WARN  (0CF4-1394) <Tunnel#5> [ca] (8D02-***-C45D) Tunnel error: Socket closed

2014-08-07T16:04:21.535-04:00 INFO  (0CF4-0F4C) <Thread-37> [g] (Request76) User cm-xx_fa_7d reconnected to the Secure Gateway Server - session ID: F470-***-4CBA

2014-08-07T16:04:22.022-04:00 INFO  (0CF4-0F74) <Thread-40> [g] (Request77) User cm-xx_a1_29 reconnected to the Secure Gateway Server - session ID: 8D02-***-C45D

2014-08-07T16:04:23.637-04:00 INFO  (0CF4-0348) <Thread-32> [g] (Request78) User cm-xx_00_ab reconnected to the Secure Gateway Server - session ID: 0663-***-37A7

2014-08-07T16:04:25.315-04:00 INFO  (0CF4-0D5C) <Thread-23> [g] (Request79) User cm-xx_ac_d4 reconnected to the Secure Gateway Server - session ID: 57A7-***-47EB

2014-08-07T16:04:26.458-04:00 INFO  (0CF4-0D50) <Thread-26> [g] (Request80) User cm-xx_a6_b0 reconnected to the Secure Gateway Server - session ID: 3537-***-CBC0

2014-08-07T16:04:26.705-04:00 WARN  (0CF4-0DC4) <wstunnel-PulseTimer> [PulseTimer] wstunnel-PulseTimer pulse 66758, wallclock delay 1152, elapsed delay 1151 DELAYED

2014-08-07T16:04:39.103-04:00 INFO  (0CF4-0D70) <Thread-24> [g] (Request81) User cm-xx_fa_7d reconnected to the Secure Gateway Server - session ID: F470-***-4CBA

2014-08-07T16:04:47.294-04:00 INFO  (0CF4-0E58) <Thread-28> [g] (Request82) User cm-xx_ac_d4 reconnected to the Secure Gateway Server - session ID: 57A7-***-47EB

2014-08-07T16:04:47.424-04:00 INFO  (0CF4-0E98) <Thread-34> [g] (Request83) User cm-xx_a6_b0 reconnected to the Secure Gateway Server - session ID: 3537-***-CBC0

2014-08-07T16:04:47.987-04:00 WARN  (0CF4-14F8) <Tunnel#8> [ca] (F470-***-4CBA) Tunnel error: Stream closed

2014-08-07T16:04:48.571-04:00 WARN  (0CF4-0F4C) <Thread-37> [g] (Request76) Fronted connection failed: java.lang.NullPointerException com.vmware.vdi.ice.server.g.<init>(SourceFile:204)

java.lang.NullPointerException

    at com.vmware.vdi.ob.tunnelservice.ca.a(SourceFile:634)

    at com.vmware.vdi.ice.server.g.<init>(SourceFile:172)

    at com.vmware.vdi.ice.server.e.a(SourceFile:169)

    at com.vmware.vdi.ice.server.TunnelService.process(SourceFile:59)

    at simple.http.serve.Component.handle(Component.java:103)

    at simple.http.serve.ResourceProcessor.handle(ResourceProcessor.java:69)

    at simple.http.Dispatcher.run(Dispatcher.java:83)

    at simple.util.process.Daemon.execute(Daemon.java:121)

    at simple.util.process.Daemon.run(Daemon.java:106)

2014-08-07T16:04:48.580-04:00 WARN  (0CF4-0F4C) <Thread-37> [e] (Request76) Error while accepting tunnel connection: null

2014-08-07T16:04:48.590-04:00 ERROR (0CF4-14F8) <Tunnel#8> [bx] (F470-***-4CBA) No Conveyor for channel 0

2014-08-07T16:04:48.602-04:00 ERROR (0CF4-14F8) <Tunnel#8> [bx] (F470-***-4CBA) No Conveyor for channel 0

2014-08-07T16:04:49.792-04:00 WARN  (0CF4-0B84) <Tunnel#34> [ca] (3537-***-CBC0) Tunnel error: Stream closed

2014-08-07T16:04:50.041-04:00 WARN  (0CF4-0D50) <Thread-26> [g] (Request80) Fronted connection failed: java.lang.NullPointerException com.vmware.vdi.ice.server.g.<init>(SourceFile:204)

java.lang.NullPointerException

    at com.vmware.vdi.ob.tunnelservice.ca.a(SourceFile:634)

    at com.vmware.vdi.ice.server.g.<init>(SourceFile:172)

    at com.vmware.vdi.ice.server.e.a(SourceFile:169)

    at com.vmware.vdi.ice.server.TunnelService.process(SourceFile:59)

    at simple.http.serve.Component.handle(Component.java:103)

    at simple.http.serve.ResourceProcessor.handle(ResourceProcessor.java:69)

    at simple.http.Dispatcher.run(Dispatcher.java:83)

    at simple.util.process.Daemon.execute(Daemon.java:121)

    at simple.util.process.Daemon.run(Daemon.java:106)

2014-08-07T16:04:50.147-04:00 ERROR (0CF4-0B84) <Tunnel#34> [bx] (3537-***-CBC0) No Conveyor for channel 0

2014-08-07T16:04:50.147-04:00 ERROR (0CF4-0B84) <Tunnel#34> [bx] (3537-***-CBC0) No Conveyor for channel 0

2014-08-07T16:04:50.200-04:00 WARN  (0CF4-0D50) <Thread-26> [e] (Request80) Error while accepting tunnel connection: null

2014-08-07T16:04:50.281-04:00 WARN  (0CF4-17E0) <Tunnel#16> [ca] (57A7-***-47EB) Tunnel error: Stream closed

2014-08-07T16:04:50.386-04:00 WARN  (0CF4-0D5C) <Thread-23> [g] (Request79) Fronted connection failed: java.lang.NullPointerException com.vmware.vdi.ice.server.g.<init>(SourceFile:204)

java.lang.NullPointerException

    at com.vmware.vdi.ob.tunnelservice.ca.a(SourceFile:634)

    at com.vmware.vdi.ice.server.g.<init>(SourceFile:172)

    at com.vmware.vdi.ice.server.e.a(SourceFile:169)

    at com.vmware.vdi.ice.server.TunnelService.process(SourceFile:59)

    at simple.http.serve.Component.handle(Component.java:103)

    at simple.http.serve.ResourceProcessor.handle(ResourceProcessor.java:69)

    at simple.http.Dispatcher.run(Dispatcher.java:83)

    at simple.util.process.Daemon.execute(Daemon.java:121)

    at simple.util.process.Daemon.run(Daemon.java:106)

2014-08-07T16:04:50.392-04:00 WARN  (0CF4-0D5C) <Thread-23> [e] (Request79) Error while accepting tunnel connection: null

2014-08-07T16:04:50.454-04:00 ERROR (0CF4-17E0) <Tunnel#16> [bx] (57A7-***-47EB) No Conveyor for channel 0

2014-08-07T16:04:50.460-04:00 ERROR (0CF4-17E0) <Tunnel#16> [bx] (57A7-***-47EB) No Conveyor for channel 0

A little later:

2014-08-07T16:28:59.797-04:00 WARN  (0CF4-0DC4) <wstunnel-PulseTimer> [PulseTimer] wstunnel-PulseTimer pulse 68216, wallclock delay 3030, elapsed delay 3025 DELAYED

2014-08-07T16:28:59.901-04:00 INFO  (0CF4-1714) <Tunnel#1> [ay] (030F-***-8213) User cm-xx_4b_f2 Secure Gateway Server session ended - session ID: 030F-***-8213

2014-08-07T16:29:00.289-04:00 WARN  (0A70-0CD8) <wstomcat-PulseTimer> [PulseTimer] wstomcat-PulseTimer pulse 68203, wallclock delay 10824, elapsed delay 10823 DELAYED

2014-08-07T16:29:01.637-04:00 INFO  (0A70-0EE0) <SwiftMQ-SessionPool-4> [Audit] BROKER_LOGOFF:USER:DOMAIN\cm-xx_4b_f2;USERSID:S-1-5-21-23092430-485174-615583016-3587;USERDN:CN=S-1-5-21-23092430-485174-615583016-3587,CN=ForeignSecurityPrincipals,DC=vdi,DC=vmware,DC=int;

2014-08-07T16:29:01.699-04:00 INFO  (0A70-0EE0) <SwiftMQ-SessionPool-4> [UserSessionTracker] User USER:DOMAIN\cm-xx_4b_f2;USERSID:S-1-5-21-23092430-485174-615583016-3587;USERDN:CN=S-1-5-21-23092430-485174-615583016-3587,CN=ForeignSecurityPrincipals,DC=vdi,DC=vmware,DC=int; has logged out of VDM

2014-08-07T16:29:18.046-04:00 WARN  (0A70-0CD8) <wstomcat-PulseTimer> [PulseTimer] wstomcat-PulseTimer pulse 68215, wallclock delay 5384, elapsed delay 5383 DELAYED

2014-08-07T16:29:20.506-04:00 WARN  (0A70-0EA4) <TrackerJMSPublisher> [JMSMessagePublisher] Outbond message delays started: 5819 queuesize: 1 (TrackerMessage SYNC {}: {v=1570, tn=TaskTracker, u=[{"type":"SET","item":{"name":"pae-TaskPercentag...

2014-08-07T16:29:20.516-04:00 INFO  (0A70-0EA4) <TrackerJMSPublisher> [JMSMessagePublisher] Outbound message delays cleared: 0 queuesize: 0 (TrackerMessage HEARTBEAT {}: {ns=ONLINE, nn=servername, hc=27285})

2014-08-07T16:29:44.506-04:00 WARN  (0A70-0CD8) <wstomcat-PulseTimer> [PulseTimer] wstomcat-PulseTimer pulse 68236, wallclock delay 5443, elapsed delay 5443 DELAYED

2014-08-07T16:29:48.324-04:00 WARN  (0A70-0CD8) <wstomcat-PulseTimer> [PulseTimer] wstomcat-PulseTimer pulse 68237, wallclock delay 2817, elapsed delay 2816 DELAYED

2014-08-07T16:29:55.486-04:00 INFO  (0A70-0F08) <DesktopControlJMS> [Audit] DISCONNECTED:Server:cn=4ac8974e-e0bd-4100-8212-3b48d33e1649,ou=servers,dc=vdi,dc=vmware,dc=int;Pool:cn=pool,ou=server groups,dc=vdi,dc=vmware,dc=int;DNS:VINT08.domain.int;IP:10.6.80.19;USER:DOMAIN\cm-xx_4b_f2;USERDN:cn=s-1-5-21-23092430-485174-615583016-3587,cn=foreignsecurityprincipals,dc=vdi,dc=vmware,dc=int;BROKERUSERSID:S-1-5-21-23092430-485174-615583016-3587;

2014-08-07T16:30:02.704-04:00 WARN  (0A70-0CD8) <wstomcat-PulseTimer> [PulseTimer] wstomcat-PulseTimer pulse 68247, wallclock delay 4284, elapsed delay 4284 DELAYED

2014-08-07T16:30:03.001-04:00 INFO  (0A70-0F08) <DesktopControlJMS> [DesktopTracker] User DOMAIN\cm-xx_4b_f2 disconnected from machine VInt08 for desktop pool - session allocated at August 7, 2014 12:02:42 AM EDT, connected for 988 mins 11 secs

2014-08-07T16:30:18.009-04:00 WARN  (0BA8-0A58) <wsmsgbus-PulseTimer> [PulseTimer] wsmsgbus-PulseTimer pulse 68292, wallclock delay 6645, elapsed delay 6644 DELAYED

2014-08-07T16:30:22.465-04:00 WARN  (0A70-0CD8) <wstomcat-PulseTimer> [PulseTimer] wstomcat-PulseTimer pulse 68265, wallclock delay 1752, elapsed delay 1752 DELAYED

Then a handful of PCs will start reconnecting every couple seconds, such as this:

2014-08-07T16:33:48.148-04:00 INFO  (0A70-0FF8) <TP-Processor1> [AuthorizationFilter] (SESSION:a31a-***-d862) User DOMAIN\cm-xx_a7_88 has successfully authenticated to VDM

2014-08-07T16:33:48.167-04:00 INFO  (0A70-0FF8) <TP-Processor1> [Audit] (SESSION:a31a-***-d862) BROKER_LOGON:USER:DOMAIN\cm-xx_a7_88;USERSID:S-1-5-21-23092430-485174-615583016-3035;USERDN:CN=S-1-5-21-23092430-485174-615583016-3035,CN=ForeignSecurityPrincipals,DC=vdi,DC=vmware,DC=int;

2014-08-07T16:33:48.794-04:00 INFO  (0A70-133C) <TP-Processor13> [Audit] (SESSION:a31a-***-d862) BROKER_LOGOFF:USER:DOMAIN\cm-xx_a7_88;USERSID:S-1-5-21-23092430-485174-615583016-3035;USERDN:CN=S-1-5-21-23092430-485174-615583016-3035,CN=ForeignSecurityPrincipals,DC=vdi,DC=vmware,DC=int;

2014-08-07T16:33:48.794-04:00 INFO  (0A70-133C) <TP-Processor13> [UserSessionTracker] (SESSION:a31a-***-d862) User USER:DOMAIN\cm-xx_a7_88;USERSID:S-1-5-21-23092430-485174-615583016-3035;USERDN:CN=S-1-5-21-23092430-485174-615583016-3035,CN=ForeignSecurityPrincipals,DC=vdi,DC=vmware,DC=int; has logged out of VDM

More errors:

2014-08-07T16:35:12.603-04:00 ERROR (0A70-131C) <TP-Processor5> [SDMessageManager] (SESSION:d89e-***-fbca) Server with DN: cn=117a4069-b880-4632-b639-7f8f4e6280f0,ou=servers,dc=vdi,dc=vmware,dc=int returned an error: NotAuthorized

2014-08-07T16:35:12.721-04:00 INFO  (0A70-131C) <TP-Processor5> [SessionLaunchContext] (SESSION:d89e-***-fbca) DOMAIN\cm-xx_a6_b0, App = Pool: Session request failed.

    (SESSION:d89e-***-fbca:) [DOMAIN\cm-xx_a6_b0, App = Pool] (9ms): Attempted to start new managed session.

    (SESSION:d89e-***-fbca:) [DOMAIN\cm-xx_a6_b0, App = Pool] (5422ms): 1 server(s) were rejected because StartSession failure. Possible session clash. [117a4069-b880-4632-b639-7f8f4e6280f0]

    (SESSION:d89e-***-fbca:) [DOMAIN\cm-xx_a6_b0, App = Pool] (5475ms): Application launch failed, exception was: All available desktop sources for this desktop are currently busy. Please try again later.

2014-08-07T16:35:12.885-04:00 INFO  (0A70-1344) <TP-Processor15> [Audit] (SESSION:d89e-***-fbca) BROKER_LOGOFF:USER:DOMAIN\cm-xx_a6_b0;USERSID:S-1-5-21-23092430-485174-615583016-3040;USERDN:CN=S-1-5-21-23092430-485174-615583016-3040,CN=ForeignSecurityPrincipals,DC=vdi,DC=vmware,DC=int;

2014-08-07T16:35:12.885-04:00 INFO  (0A70-1344) <TP-Processor15> [UserSessionTracker] (SESSION:d89e-***-fbca) User USER:DOMAIN\cm-xx_a6_b0;USERSID:S-1-5-21-23092430-485174-615583016-3040;USERDN:CN=S-1-5-21-23092430-485174-615583016-3040,CN=ForeignSecurityPrincipals,DC=vdi,DC=vmware,DC=int; has logged out of VDM

2014-08-07T16:35:12.894-04:00 INFO  (0CF4-16B4) <Tunnel#46> [ay] (CA14-***-EB0D) User cm-xx_a6_b0 Secure Gateway Server session ended - session ID: CA14-***-EB0D

Apparently the vCenter Server (an appliance VM, v5.1.0.20001, b1917404, the latest available) dies around here - or maybe the entire network lets go? .210 is the vCenter server, and .80 and 102 are two of the VMs.

2014-08-07T16:35:20.984-04:00 INFO  (0A70-16F4) <CBRC-Validate-VMs-86ea1681-e172-4ad3-8cfd-46d60d9adcef> [Audit] VC_OUTAGE:Url:https://x.x.x.210:443/sdk

2014-08-07T16:35:20.984-04:00 WARN  (0A70-16F4) <CBRC-Validate-VMs-86ea1681-e172-4ad3-8cfd-46d60d9adcef> [ServiceConnection25] VirtualCenter https://x.x.x.210:443/sdk is currently unavailable - attempting to reconnect

2014-08-07T16:35:22.590-04:00 INFO  (0CF4-0F74) <Thread-40> [g] (Request90) User cm-xx_a6_b0 connected to the Secure Gateway Server - session ID: 0BD3-***-87AB

2014-08-07T16:35:25.918-04:00 INFO  (0A70-0F08) <DesktopControlJMS> [Audit] SHUTDOWN:Server:cn=117a4069-b880-4632-b639-7f8f4e6280f0,ou=servers,dc=vdi,dc=vmware,dc=int;Pool:cn=pool,ou=server groups,dc=vdi,dc=vmware,dc=int;DNS:;IP:x.x.x.80;

2014-08-07T16:35:28.250-04:00 WARN  (0CF4-0DB0) <Tunnel#43> [al] (D63C-***-E8DB) Problem starting channel 1 for Port2: Failed to allocate onbound connection to x.x.x.102:32111: java.net.SocketTimeoutException: makeSocketConnection timed out com.vmware.vdi.ice.server.al.g(SourceFile:879)

com.vmware.vdi.ob.tunnelservice.bf: Failed to allocate onbound connection to x.x.x102:32111: java.net.SocketTimeoutException: makeSocketConnection timed out

    at com.vmware.vdi.ice.server.aa.<init>(SourceFile:85)

    at com.vmware.vdi.ice.server.al.g(SourceFile:850)

    at com.vmware.vdi.ice.server.al.c(SourceFile:680)

    at com.vmware.vdi.ob.tunnelservice.ca.run(SourceFile:829)

    at java.lang.Thread.run(Unknown Source)

After some similar Java errors, we get: (VInt12 is one of the VMs)

2014-08-07T16:35:41.090-04:00 INFO  (0A70-0FFC) <TP-Processor2> [Audit] (SESSION:fdb2-***-f3fc) BROKER_LOGOFF:USER:DOMAIN\cm-xx_a6_d6;USERSID:S-1-5-21-23092430-485174-615583016-3038;USERDN:CN=S-1-5-21-23092430-485174-615583016-3038,CN=ForeignSecurityPrincipals,DC=vdi,DC=vmware,DC=int;

2014-08-07T16:35:41.091-04:00 INFO  (0A70-0FFC) <TP-Processor2> [UserSessionTracker] (SESSION:fdb2-***-f3fc) User USER:DOMAIN\cm-xx_a6_d6;USERSID:S-1-5-21-23092430-485174-615583016-3038;USERDN:CN=S-1-5-21-23092430-485174-615583016-3038,CN=ForeignSecurityPrincipals,DC=vdi,DC=vmware,DC=int; has logged out of VDM

2014-08-07T16:35:41.100-04:00 INFO  (0CF4-0DB0) <Tunnel#43> [ay] (D63C-***-E8DB) User cm-xx_a6_d6 Secure Gateway Server session ended - session ID: D63C-***-E8DB

2014-08-07T16:35:42.365-04:00 INFO  (0A70-131C) <TP-Processor5> [AuthorizationFilter] (SESSION:7791-***-2ada) User DOMAIN\cm-xx_a6_d6 has successfully authenticated to VDM

2014-08-07T16:35:42.392-04:00 INFO  (0A70-131C) <TP-Processor5> [Audit] (SESSION:7791-***-2ada) BROKER_LOGON:USER:DOMAIN\cm-xx_a6_d6;USERSID:S-1-5-21-23092430-485174-615583016-3038;USERDN:CN=S-1-5-21-23092430-485174-615583016-3038,CN=ForeignSecurityPrincipals,DC=vdi,DC=vmware,DC=int;

2014-08-07T16:35:44.999-04:00 INFO  (0CF4-0D5C) <Thread-23> [g] (Request91) User cm-xx_a6_d6 connected to the Secure Gateway Server - session ID: 3F22-***-CA61

2014-08-07T16:35:45.713-04:00 INFO  (0A70-1340) <TP-Processor14> [PendingOperation] (SESSION:7791-***-2ada) Pool control for desktop pool is starting VM WINDOW #1 :VInt12

There's a lot of the logon/logoff behavior, mixed in is this line:

2014-08-07T16:36:39.121-04:00 INFO  (0A70-0F08) <DesktopControlJMS> [Audit] SHUTDOWN:Server:cn=9683853f-e4d3-4a29-97b5-aabe914c7da1,ou=servers,dc=vdi,dc=vmware,dc=int;Pool:cn=pool,ou=server groups,dc=vdi,dc=vmware,dc=int;DNS:VINT14.domain.int;IP:x.x.x.126;

More logon/logoff, and some of this:

2014-08-07T16:39:09.101-04:00 INFO  (0A70-0FFC) <TP-Processor2> [SessionLaunchContext] (SESSION:1b00-***-3c21) DOMAIN\cm-xx_a6_ab, App = Pool: Session request failed.

    (SESSION:1b00-***-3c21:) [DOMAIN\cm-xx_a6_ab, App = Pool] (8ms): User has 1 possible sessions to analyze.

    (SESSION:1b00-***-3c21:) [DOMAIN\cm-xx_a6_ab, App = Pool] (8ms): Possible session match found on server cn=0cad6ef4-60a3-42c5-baa7-7c72c0c8a8b1,ou=servers,dc=vdi,dc=vmware,dc=int.

    (SESSION:1b00-***-3c21:) [DOMAIN\cm-xx_a6_ab, App = Pool] (8ms): No matching capids, selected session on server 0cad6ef4-60a3-42c5-baa7-7c72c0c8a8b1

    (SESSION:1b00-***-3c21:) [DOMAIN\cm-xx_a6_ab, App = Pool] (8ms): Application launch failed, exception was: The display protocol for this desktop is currently not available. [NAME=PCOIP, ERROR-CODE=PROTOCOL_ERR_BUSY]

Some session clashes:

2014-08-07T16:39:10.993-04:00 INFO  (0A70-0FFC) <TP-Processor2> [SessionLaunchContext] (SESSION:40ca-***-254e) DOMAIN\cm-xx_a5_18, App = Pool: Session request failed.

    (SESSION:40ca-***-254e:) [DOMAIN\cm-xx_a5_18, App = Pool] (8ms): Attempted to start new managed session.

    (SESSION:40ca-***-254e:) [DOMAIN\cm-xx_a5_18, App = Pool] (100ms): 1 server(s) were rejected because StartSession failure. Possible session clash. [d1ad6237-7a5a-4193-884a-153085c210ab]

    (SESSION:40ca-***-254e:) [DOMAIN\cm-xx_a5_18, App = Pool] (100ms): Application launch failed, exception was: All available desktop sources for this desktop are currently busy. Please try again later.

Here's the last warn/error in this sequence, and the following lines are repeated several times as apparently some of the VMs restarted:

2014-08-07T16:46:03.685-04:00 WARN  (0A70-1524) <PendingOperation-vm-116> [MachineInformation] Agent not accepting connections in time: cn=9683853f-e4d3-4a29-97b5-aabe914c7da1,ou=servers,dc=vdi,dc=vmware,dc=int

2014-08-07T16:46:03.685-04:00 ERROR (0A70-1524) <PendingOperation-vm-116> [PendingOperation] Pool pool::Unable to start VM /domain/vm/WINDOW #4 :VInt14 - Failed to verify port for VM /domain/vm/WINDOW #4 :VInt14

2014-08-07T16:46:04.951-04:00 INFO  (0A70-1324) <TP-Processor7> [AuthorizationFilter] (SESSION:65a1-***-e1c7) User DOMAIN\cm-xx_a7_88 has successfully authenticated to VDM

2014-08-07T16:46:04.979-04:00 INFO  (0A70-1324) <TP-Processor7> [Audit] (SESSION:65a1-***-e1c7) BROKER_LOGON:USER:DOMAIN\cm-xx_a7_88;USERSID:S-1-5-21-23092430-485174-615583016-3035;USERDN:CN=S-1-5-21-23092430-485174-615583016-3035,CN=ForeignSecurityPrincipals,DC=vdi,DC=vmware,DC=int;

2014-08-07T16:46:06.186-04:00 INFO  (0CF4-0F70) <Thread-39> [g] (Request221) User cm-xx_a7_a0 connected to the Secure Gateway Server - session ID: 50DD-***-EB26

2014-08-07T16:46:06.962-04:00 INFO  (0A70-132C) <TP-Processor9> [SessionLaunchContext] (SESSION:1ae8-***-98db) DOMAIN\cm-xx_a7_a0, App = Pool: Session request failed.

    (SESSION:1ae8-***-98db:) [DOMAIN\cm-xx_a7_a0, App = Pool] (11ms): Attempted to start new managed session.

    (SESSION:1ae8-***-98db:) [DOMAIN\cm-xx_a7_a0, App = Pool] (11ms): 1 server(s) were rejected because Server has error code of AGENT_ERR_STARTUP_IN_PROGRESS. [cfc0318c-4f7a-4fab-95d3-b5b669957c6d]

    (SESSION:1ae8-***-98db:) [DOMAIN\cm-xx_a7_a0, App = Pool] (11ms): Application launch failed, exception was: The agent returned an error response [ERROR-CODE=AGENT_ERR_STARTUP_IN_PROGRESS]

After this, things appear to calm down the the VMs begin working again.

I am leaning towards blaming the Java NullPointerException, as it only happens once during this day's log file and is suspiciously close (about 30 minutes before) to when the freezes happened. I'm not sure what I can do about that, though - do I need a specific Java runtime or does View use its own? It's currently got Java 7u67 on the Connection Server.

Any assistance would be greatly appreciated! Thank you!

[JKylePPG]

Oh, I should also add - this really does seem to happen randomly - the environment can go for a few days or occasionally even as long as a couple weeks with no problems, but usually these problems happened every 1-3 days, occasionally multiple times in one day.

[JKylePPG]

One thing I found was that STP was enabled on the LAG connection that the ESXi server connected to. That was disabled this morning, we'll see if that makes any difference.

[JKylePPG]

No difference, VMs still freezing. The most recent outage took down every single VM leaving black screens on the clients, all reconnected at ctrl-alt-del screens five minutes or so later.

The logs show the following right at the beginning:

2014-08-14T12:41:18.160-04:00 WARN  (0D38-12E8) <Tunnel#13> [ca] (E381-***-B1C0) Tunnel error: Connection reset

2014-08-14T12:41:19.541-04:00 WARN  (0A2C-0AD4) <wsmsgbus-PulseTimer> [PulseTimer] wsmsgbus-PulseTimer pulse 30791, wallclock delay 1113, elapsed delay 1114 DELAYED

2014-08-14T12:41:21.920-04:00 WARN  (0A2C-0AD4) <wsmsgbus-PulseTimer> [PulseTimer] wsmsgbus-PulseTimer pulse 30792, wallclock delay 1375, elapsed delay 1375 DELAYED

Looks like uninstalling the Connection Manager, adding more memory to the VM, and reinstalling it to increase the Java heap size might be the next step.

[Gaurav_Baghla]

Just looking at the wallclock Delay Wanted to check if there is a time sync Issue between the Horizon view environment

?

[JKylePPG]

I can double-check but I don't believe that is an issue. We did a bit of NTP work when first setting up the environment to make sure that the ESXi servers, Windows servers, and VMs had consistently correct time. I would expect that with time issues, we'd see more consistent issues; these appear totally random, happening at any time during the day and affecting different quantities of VMs at once, while others usually stay the same.

[snonchev]

Hi,

In our View environment we are experiencing exactly the same symptoms. All VDI clients are located in a remote location. Examining the pcoip_server_... log files shows loss packets also. However checking the WAN connection doesn't show any extra latency, dropped packets, etc.. -> i think this means only pcoip tunnels are dropping packets when the issue occurs.

I wonder whether you have found the reason for that in your environment?

[JKylePPG]

Late reply!

This has been ongoing for a long time. It seems to get better then worse. We eventually found that the View Manager and vCenter Server VMs were losing network connection entirely occasionally. The two other VMs on the same machine had no problem. Memory was overallocated so we tossed more memory into the server and have not seen any more network outages that we can detect.

Since are better but there are still issues where the PCs freeze or go unresponsive for five minutes or so.

I am kind of frustrated that I can find zero information about these lines in the logs:

2015-07-16T10:14:24.269-04:00 INFO  (0C64-0FB4) <Tracker:Heartbeat> [TrackerManager] (server) Inbound queue stats: total=0, max=0, dropped=0

2015-07-16T10:14:24.269-04:00 INFO  (0C64-0FB4) <Tracker:Heartbeat> [TrackerManager] (server) Outbound queue stats: total=1597423, max=37, dropped=0

What is the deal with the outbound queue? Is it normal to have a large number there?

Then during the problems, the logs look like this:

2015-07-16T13:24:31.393-04:00 INFO  (0C64-1438) <TP-Processor35> [Audit] (SESSION:296f-***-0b10) BROKER_LOGOFF:USER:DOMAIN\cm-00_80_64_cb_a7_a0;USERSID:S-1-5-21-23092430-485174-615583016-3033;USERDN:CN=S-1-5-21-23092430-485174-615583016-3033,CN=ForeignSecurityPrincipals,DC=vdi,DC=vmware,DC=int;

2015-07-16T13:24:31.394-04:00 INFO  (0C64-1438) <TP-Processor35> [UserSessionTracker] (SESSION:296f-***-0b10) User USER:DOMAIN\cm-00_80_64_cb_a7_a0;USERSID:S-1-5-21-23092430-485174-615583016-3033;USERDN:CN=S-1-5-21-23092430-485174-615583016-3033,CN=ForeignSecurityPrincipals,DC=vdi,DC=vmware,DC=int; has logged out of VDM

2015-07-16T13:24:31.400-04:00 INFO  (0D94-2F14) <Tunnel#215819> [ay] (3759-***-62CA) User cm-00_80_64_cb_a7_a0 Secure Gateway Server session ended - session ID: 3759-***-62CA

2015-07-16T13:24:33.017-04:00 INFO  (0C64-12A0) <TP-Processor19> [AuthorizationFilter] (SESSION:abbc-***-324f) User DOMAIN\cm-00_80_64_cb_a7_a0 has successfully authenticated to VDM

2015-07-16T13:24:33.025-04:00 INFO  (0C64-12A0) <TP-Processor19> [Audit] (SESSION:abbc-***-324f) BROKER_LOGON:USER:DOMAIN\cm-00_80_64_cb_a7_a0;USERSID:S-1-5-21-23092430-485174-615583016-3033;USERDN:CN=S-1-5-21-23092430-485174-615583016-3033,CN=ForeignSecurityPrincipals,DC=vdi,DC=vmware,DC=int;

2015-07-16T13:24:33.494-04:00 INFO  (0C64-12A4) <TP-Processor20> [Audit] (SESSION:abbc-***-324f) BROKER_LOGOFF:USER:DOMAIN\cm-00_80_64_cb_a7_a0;USERSID:S-1-5-21-23092430-485174-615583016-3033;USERDN:CN=S-1-5-21-23092430-485174-615583016-3033,CN=ForeignSecurityPrincipals,DC=vdi,DC=vmware,DC=int;

2015-07-16T13:24:33.495-04:00 INFO  (0C64-12A4) <TP-Processor20> [UserSessionTracker] (SESSION:abbc-***-324f) User USER:DOMAIN\cm-00_80_64_cb_a7_a0;USERSID:S-1-5-21-23092430-485174-615583016-3033;USERDN:CN=S-1-5-21-23092430-485174-615583016-3033,CN=ForeignSecurityPrincipals,DC=vdi,DC=vmware,DC=int; has logged out of VDM

2015-07-16T13:24:33.945-04:00 INFO  (0C64-08D4) <DesktopControlJMS> [Audit] ENDED:Server:cn=cfc0318c-4f7a-4fab-95d3-b5b669957c6d,ou=servers,dc=vdi,dc=vmware,dc=int;Pool:cn=patronpool,ou=server groups,dc=vdi,dc=vmware,dc=int;DNS:VINT16.domain.int;IP:10.6.80.79;USER:DOMAIN\cm-00_80_64_cb_a7_a0;USERDN:cn=s-1-5-21-23092430-485174-615583016-3033,cn=foreignsecurityprincipals,dc=vdi,dc=vmware,dc=int;BROKERUSERSID:S-1-5-21-23092430-485174-615583016-3033;

2015-07-16T13:24:33.946-04:00 INFO  (0C64-08D4) <DesktopControlJMS> [DesktopTracker] User DOMAIN\cm-00_80_64_cb_a7_a0 logged off from machine VInt16 for desktop bml_patronpool - session allocated at July 16, 2015 12:01:29 AM EDT, connected for 803 mins 1 secs

2015-07-16T13:24:34.871-04:00 INFO  (0C64-1278) <TP-Processor9> [AuthorizationFilter] (SESSION:6371-***-d9c9) User DOMAIN\cm-00_80_64_cb_a7_a0 has successfully authenticated to VDM

2015-07-16T13:24:34.878-04:00 INFO  (0C64-1278) <TP-Processor9> [Audit] (SESSION:6371-***-d9c9) BROKER_LOGON:USER:DOMAIN\cm-00_80_64_cb_a7_a0;USERSID:S-1-5-21-23092430-485174-615583016-3033;USERDN:CN=S-1-5-21-23092430-485174-615583016-3033,CN=ForeignSecurityPrincipals,DC=vdi,DC=vmware,DC=int;

2015-07-16T13:24:37.628-04:00 INFO  (0D94-089C) <Thread-30> [g] (Request222734) User cm-00_80_64_cb_a7_a0 connected to the Secure Gateway Server - session ID: 2B9C-***-04EE

2015-07-16T13:24:39.697-04:00 INFO  (0C64-08D4) <DesktopControlJMS> [Audit] PENDING:Server:cn=cfc0318c-4f7a-4fab-95d3-b5b669957c6d,ou=servers,dc=vdi,dc=vmware,dc=int;Pool:cn=patronpool,ou=server groups,dc=vdi,dc=vmware,dc=int;DNS:VINT16.bml.int;IP:10.6.80.79;USER:DOMAIN\cm-00_80_64_cb_a7_a0;USERDN:cn=s-1-5-21-23092430-485174-615583016-3033,cn=foreignsecurityprincipals,dc=vdi,dc=vmware,dc=int;BROKERUSERSID:S-1-5-21-23092430-485174-615583016-3033;

2015-07-16T13:24:48.501-04:00 INFO  (0C64-08D4) <DesktopControlJMS> [Audit] CONNECTED:Server:cn=cfc0318c-4f7a-4fab-95d3-b5b669957c6d,ou=servers,dc=vdi,dc=vmware,dc=int;Pool:cn=patronpool,ou=server groups,dc=vdi,dc=vmware,dc=int;DNS:VINT16.bml.int;IP:10.6.80.79;USER:DOMAIN\cm-00_80_64_cb_a7_a0;USERDN:cn=s-1-5-21-23092430-485174-615583016-3033,cn=foreignsecurityprincipals,dc=vdi,dc=vmware,dc=int;BROKERUSERSID:S-1-5-21-23092430-485174-615583016-3033;

2015-07-16T13:24:48.501-04:00 INFO  (0C64-08D4) <DesktopControlJMS> [DesktopTracker] User DOMAIN\cm-00_80_64_cb_a7_a0 connected to machine VInt16 for desktop patronpool - session allocated at July 16, 2015 1:24:47 PM EDT, connected after 0 mins 0 secs

This is all that is logged during the problem and only shows a single desktop reconnecting, but while it happens, ALL desktops freeze. Ten minutes later, this is logged:

2015-07-16T13:37:55.924-04:00 INFO  (0D94-05BC) <Tunnel#215827> [ay] (68E1-***-BE40) User cm-00_80_64_cb_a6_4c Secure Gateway Server session ended - session ID: 68E1-***-BE40

2015-07-16T13:37:55.928-04:00 INFO  (0C64-14D8) <SwiftMQ-SessionPool-7> [Audit] BROKER_LOGOFF:USER:DOMAIN\cm-00_80_64_cb_a6_4c;USERSID:S-1-5-21-23092430-485174-615583016-3595;USERDN:CN=S-1-5-21-23092430-485174-615583016-3595,CN=ForeignSecurityPrincipals,DC=vdi,DC=vmware,DC=int;

2015-07-16T13:37:55.929-04:00 INFO  (0C64-14D8) <SwiftMQ-SessionPool-7> [UserSessionTracker] User USER:DOMAIN\cm-00_80_64_cb_a6_4c;USERSID:S-1-5-21-23092430-485174-615583016-3595;USERDN:CN=S-1-5-21-23092430-485174-615583016-3595,CN=ForeignSecurityPrincipals,DC=vdi,DC=vmware,DC=int; has logged out of VDM

2015-07-16T13:38:57.424-04:00 INFO  (0C64-08D4) <DesktopControlJMS> [Audit] DISCONNECTED:Server:cn=85adf311-8b42-47a8-b6ab-2a6359c9c17c,ou=servers,dc=vdi,dc=vmware,dc=int;Pool:cn=patronpool,ou=server groups,dc=vdi,dc=vmware,dc=int;DNS:VCH01.bml.int;IP:10.6.80.32;USER:DOMAIN\cm-00_80_64_cb_a6_4c;USERDN:cn=s-1-5-21-23092430-485174-615583016-3595,cn=foreignsecurityprincipals,dc=vdi,dc=vmware,dc=int;BROKERUSERSID:S-1-5-21-23092430-485174-615583016-3595;

2015-07-16T13:38:57.425-04:00 INFO  (0C64-08D4) <DesktopControlJMS> [DesktopTracker] User DOMAIN\cm-00_80_64_cb_a6_4c disconnected from machine VCh01 for desktop patronpool - session allocated at July 16, 2015 12:01:22 AM EDT, connected for 817 mins 34 secs

There are a few more another ten minutes later.

Does any of this make any sense to anyone?