22:22:26,965 INFO  <Thread-21> [u] User vdiuser connected to the VDM Secure Gateway - session ID: 65CC04495E62DF8E2F46762CDC4083A6
22:22:26,965 DEBUG <Tunnel#1> [ah] (65CC04495E62DF8E2F46762CDC4083A6) Tunnel reader starting.
22:22:26,965 DEBUG <Tunnel#1> [a] (65CC04495E62DF8E2F46762CDC4083A6) Tunnel registered: session = (Session capID = 65CC04495E62DF8E2F46762CDC4083A6, userID = vdiuser, userDN = cn=s-1-5-21-1229272821-73586283-725345543-9302,cn=foreignsecurityprincipals,dc=vdi,dc=vmware,dc=int, locationID = 00-1A-6B-42-63-35), connected = Tue Sep 09 22:22:26 BST 2008
22:22:41,527 DEBUG <SessionHandler> [a] (65CC04495E62DF8E2F46762CDC4083A6) hasSessionLostContact(): threshold = Tue Sep 09 22:21:41 BST 2008, lastSeen = Thu Jan 01 00:59:59 GMT 1970
22:22:42,402 DEBUG <VirtualCenterDriver-9a075b95-260c-4879-8403-a7f3130e475c> [VirtualCenterDriver] 3 VMs took 172ms to query
22:22:42,402 DEBUG <VirtualCenterDriver-9a075b95-260c-4879-8403-a7f3130e475c> [VirtualCenterDriver] (RePropagate cn=vdi-pool1,ou=server groups,dc=vdi,dc=vmware,dc=int) onVmEvent: null in pool: cn=vdi-pool1,ou=server groups,dc=vdi,dc=vmware,dc=int
22:22:42,480 DEBUG <DesktopControlSessions> [SDMessageManager] finished waiting, was waiting for 10000ms
22:22:42,480 DEBUG <DesktopControlSessions> [SDMessageManager] No response from cn=6eb39eec-26ff-485b-88c1-27d331e6ee38,ou=servers,dc=vdi,dc=vmware,dc=int;cn=4edcee70-bc20-464d-83f6-f8e6d299bf46,ou=servers,dc=vdi,dc=vmware,dc=int;
22:22:42,496 DEBUG <DesktopControlSessions> [DesktopTracker] Received:{MAXSESSIONS=1, SERVERPOOLDN=cn=vdi-pool1,ou=server groups,dc=vdi,dc=vmware,dc=int, CONNECTEDSESSIONCOUNT=0, PENDINGSESSIONCOUNT=0, SESSIONCOUNT=0, PLATFORM=WINDOWS, DOMAINS=[mydomain, myotherdomain, VDIPOOL2], ACCEPTINGCONNECTIONS=TRUE, OSVERMINOR=1, PROTOCOLS=[{NAME=RDP, PORT=3389}], LISTENERS=[MMR:9427], OSVERMAJOR=5, SERVERDNSNAME=vdipool2.mydomain.pt, DYNAMICIPADDRESS=172.20.70.1, DISCONNECTEDSESSIONCOUNT=0, SERVERDN=cn=fbc97a7c-c304-40a0-b903-6941a28f432c,ou=servers,dc=vdi,dc=vmware,dc=int}
22:22:42,496 DEBUG <DesktopControlSessions> [VmInformation] vdi-wks1.mydomain.pt offline - unassigned
22:22:42,496 DEBUG <DesktopControlSessions> [VmInformation] vdipool1 offline - unassigned
22:22:42,496 DEBUG <DesktopControlSessions> [VmInformation] vdipool2 online - unassigned
22:22:42,777 DEBUG <VirtualCenterDriver-9a075b95-260c-4879-8403-a7f3130e475c> [VirtualCenterDriver] (RePropagate cn=vdi-pool1,ou=server groups,dc=vdi,dc=vmware,dc=int) Determine actions for cn=vdi-pool1,ou=server groups,dc=vdi,dc=vmware,dc=int: totalVMs=2, availableVMs=1, zombieVMs=0, busyVMs=0, poweredOffVMs=0, suspendedVMs=1, vmMaximumCount=2, vmMinimumCount=2, vmHeadroomCount=1, customizingVMs=0
22:22:42,777 DEBUG <VirtualCenterDriver-9a075b95-260c-4879-8403-a7f3130e475c> [VirtualCenterDriver] (RePropagate cn=vdi-wks1,ou=server groups,dc=vdi,dc=vmware,dc=int) onVmEvent: null in pool: cn=vdi-wks1,ou=server groups,dc=vdi,dc=vmware,dc=int
22:22:42,777 DEBUG <VirtualCenterDriver-9a075b95-260c-4879-8403-a7f3130e475c> [VirtualCenterDriver] (RePropagate cn=vdi-wks1,ou=server groups,dc=vdi,dc=vmware,dc=int) Determine actions for cn=vdi-wks1,ou=server groups,dc=vdi,dc=vmware,dc=int: totalVMs=1, availableVMs=0, zombieVMs=0, busyVMs=0, poweredOffVMs=1, suspendedVMs=0, vmMaximumCount=0, vmMinimumCount=0, vmHeadroomCount=0, customizingVMs=0
22:22:55,590 DEBUG <VirtualCenterDriver-9a075b95-260c-4879-8403-a7f3130e475c> [VirtualCenterDriver] 3 VMs took 219ms to query
22:22:55,590 DEBUG <VirtualCenterDriver-9a075b95-260c-4879-8403-a7f3130e475c> [VirtualCenterDriver] (RePropagate cn=vdi-pool1,ou=server groups,dc=vdi,dc=vmware,dc=int) onVmEvent: null in pool: cn=vdi-pool1,ou=server groups,dc=vdi,dc=vmware,dc=int
22:22:55,980 DEBUG <VirtualCenterDriver-9a075b95-260c-4879-8403-a7f3130e475c> [VirtualCenterDriver] (RePropagate cn=vdi-pool1,ou=server groups,dc=vdi,dc=vmware,dc=int) Determine actions for cn=vdi-pool1,ou=server groups,dc=vdi,dc=vmware,dc=int: totalVMs=2, availableVMs=1, zombieVMs=0, busyVMs=0, poweredOffVMs=0, suspendedVMs=1, vmMaximumCount=2, vmMinimumCount=2, vmHeadroomCount=1, customizingVMs=0
22:22:55,980 DEBUG <VirtualCenterDriver-9a075b95-260c-4879-8403-a7f3130e475c> [VirtualCenterDriver] (RePropagate cn=vdi-wks1,ou=server groups,dc=vdi,dc=vmware,dc=int) onVmEvent: null in pool: cn=vdi-wks1,ou=server groups,dc=vdi,dc=vmware,dc=int
22:22:55,980 DEBUG <VirtualCenterDriver-9a075b95-260c-4879-8403-a7f3130e475c> [VirtualCenterDriver] (RePropagate cn=vdi-wks1,ou=server groups,dc=vdi,dc=vmware,dc=int) Determine actions for cn=vdi-wks1,ou=server groups,dc=vdi,dc=vmware,dc=int: totalVMs=1, availableVMs=0, zombieVMs=0, busyVMs=0, poweredOffVMs=1, suspendedVMs=0, vmMaximumCount=0, vmMinimumCount=0, vmHeadroomCount=0, customizingVMs=0
22:23:08,746 DEBUG <VirtualCenterDriver-9a075b95-260c-4879-8403-a7f3130e475c> [VirtualCenterDriver] 3 VMs took 250ms to query
22:23:08,746 DEBUG <VirtualCenterDriver-9a075b95-260c-4879-8403-a7f3130e475c> [VirtualCenterDriver] (RePropagate cn=vdi-pool1,ou=server groups,dc=vdi,dc=vmware,dc=int) onVmEvent: null in pool: cn=vdi-pool1,ou=server groups,dc=vdi,dc=vmware,dc=int
22:23:09,137 DEBUG <VirtualCenterDriver-9a075b95-260c-4879-8403-a7f3130e475c> [VirtualCenterDriver] (RePropagate cn=vdi-pool1,ou=server groups,dc=vdi,dc=vmware,dc=int) Determine actions for cn=vdi-pool1,ou=server groups,dc=vdi,dc=vmware,dc=int: totalVMs=2, availableVMs=1, zombieVMs=0, busyVMs=0, poweredOffVMs=0, suspendedVMs=1, vmMaximumCount=2, vmMinimumCount=2, vmHeadroomCount=1, customizingVMs=0
22:23:09,137 DEBUG <VirtualCenterDriver-9a075b95-260c-4879-8403-a7f3130e475c> [VirtualCenterDriver] (RePropagate cn=vdi-wks1,ou=server groups,dc=vdi,dc=vmware,dc=int) onVmEvent: null in pool: cn=vdi-wks1,ou=server groups,dc=vdi,dc=vmware,dc=int
22:23:09,137 DEBUG <VirtualCenterDriver-9a075b95-260c-4879-8403-a7f3130e475c> [VirtualCenterDriver] (RePropagate cn=vdi-wks1,ou=server groups,dc=vdi,dc=vmware,dc=int) Determine actions for cn=vdi-wks1,ou=server groups,dc=vdi,dc=vmware,dc=int: totalVMs=1, availableVMs=0, zombieVMs=0, busyVMs=0, poweredOffVMs=1, suspendedVMs=0, vmMaximumCount=0, vmMinimumCount=0, vmHeadroomCount=0, customizingVMs=0
22:23:11,527 DEBUG <SessionHandler> [a] (65CC04495E62DF8E2F46762CDC4083A6) hasSessionLostContact(): threshold = Tue Sep 09 22:22:11 BST 2008, lastSeen = Thu Jan 01 00:59:59 GMT 1970
22:23:22,496 DEBUG <DesktopControlSessions> [SDMessageManager] finished waiting, was waiting for 9984ms
22:23:22,496 DEBUG <DesktopControlSessions> [SDMessageManager] No response from cn=6eb39eec-26ff-485b-88c1-27d331e6ee38,ou=servers,dc=vdi,dc=vmware,dc=int;cn=4edcee70-bc20-464d-83f6-f8e6d299bf46,ou=servers,dc=vdi,dc=vmware,dc=int;
22:23:22,512 DEBUG <DesktopControlSessions> [DesktopTracker] Received:{MAXSESSIONS=1, SERVERPOOLDN=cn=vdi-pool1,ou=server groups,dc=vdi,dc=vmware,dc=int, CONNECTEDSESSIONCOUNT=0, PENDINGSESSIONCOUNT=0, SESSIONCOUNT=0, PLATFORM=WINDOWS, DOMAINS=[mydomain, myotherdomain, VDIPOOL2], ACCEPTINGCONNECTIONS=TRUE, OSVERMINOR=1, PROTOCOLS=[{NAME=RDP, PORT=3389}], LISTENERS=[MMR:9427], OSVERMAJOR=5, SERVERDNSNAME=vdipool2.mydomain.pt, DYNAMICIPADDRESS=172.20.70.1, DISCONNECTEDSESSIONCOUNT=0, SERVERDN=cn=fbc97a7c-c304-40a0-b903-6941a28f432c,ou=servers,dc=vdi,dc=vmware,dc=int}
22:23:22,512 DEBUG <DesktopControlSessions> [VmInformation] vdi-wks1.mydomain.pt offline - unassigned
22:23:22,512 DEBUG <DesktopControlSessions> [VmInformation] vdipool1 offline - unassigned
22:23:22,512 DEBUG <DesktopControlSessions> [VmInformation] vdipool2 online - unassigned
22:23:26,465 DEBUG <VirtualCenterDriver-9a075b95-260c-4879-8403-a7f3130e475c> [VirtualCenterDriver] 3 VMs took 188ms to query
22:23:26,465 DEBUG <VirtualCenterDriver-9a075b95-260c-4879-8403-a7f3130e475c> [VirtualCenterDriver] (RePropagate cn=vdi-pool1,ou=server groups,dc=vdi,dc=vmware,dc=int) onVmEvent: null in pool: cn=vdi-pool1,ou=server groups,dc=vdi,dc=vmware,dc=int
22:23:26,965 DEBUG <VirtualCenterDriver-9a075b95-260c-4879-8403-a7f3130e475c> [VirtualCenterDriver] (RePropagate cn=vdi-pool1,ou=server groups,dc=vdi,dc=vmware,dc=int) Determine actions for cn=vdi-pool1,ou=server groups,dc=vdi,dc=vmware,dc=int: totalVMs=2, availableVMs=1, zombieVMs=0, busyVMs=0, poweredOffVMs=0, suspendedVMs=1, vmMaximumCount=2, vmMinimumCount=2, vmHeadroomCount=1, customizingVMs=0
22:23:26,965 DEBUG <VirtualCenterDriver-9a075b95-260c-4879-8403-a7f3130e475c> [VirtualCenterDriver] (RePropagate cn=vdi-wks1,ou=server groups,dc=vdi,dc=vmware,dc=int) onVmEvent: null in pool: cn=vdi-wks1,ou=server groups,dc=vdi,dc=vmware,dc=int
22:23:26,965 DEBUG <VirtualCenterDriver-9a075b95-260c-4879-8403-a7f3130e475c> [VirtualCenterDriver] (RePropagate cn=vdi-wks1,ou=server groups,dc=vdi,dc=vmware,dc=int) Determine actions for cn=vdi-wks1,ou=server groups,dc=vdi,dc=vmware,dc=int: totalVMs=1, availableVMs=0, zombieVMs=0, busyVMs=0, poweredOffVMs=1, suspendedVMs=0, vmMaximumCount=0, vmMinimumCount=0, vmHeadroomCount=0, customizingVMs=0
22:23:27,512 DEBUG <Tunnel#1> [ah] (65CC04495E62DF8E2F46762CDC4083A6) Tunnel IO problem: java.io.IOException: Broken pipe com.vmware.vdi.ob.tunnelservice.ah.run(SourceFile:610)
java.io.IOException: Broken pipe
	at simple.http.MonitoredInputStream.destroy(Unknown Source)
	at simple.http.MonitoredInputStream.read(Unknown Source)
	at java.io.DataInputStream.read(Unknown Source)
	at java.io.BufferedInputStream.fill(Unknown Source)
	at java.io.BufferedInputStream.read(Unknown Source)
	at com.vmware.vdi.ob.tunnelservice.bb.b(SourceFile:944)
	at com.vmware.vdi.ob.tunnelservice.ah.run(SourceFile:465)
	at java.lang.Thread.run(Unknown Source)
22:23:27,512 DEBUG <Tunnel#1> [a] (65CC04495E62DF8E2F46762CDC4083A6) Tunnel reported as disconnected
22:23:27,512 INFO  <Tunnel#1> [f] (65CC04495E62DF8E2F46762CDC4083A6) User vdiuser disconnected from the VDM Secure Gateway - session ID: 65CC04495E62DF8E2F46762CDC4083A6
22:23:27,512 DEBUG <Tunnel#1> [ah] (65CC04495E62DF8E2F46762CDC4083A6) lostConnection done
22:23:27,512 DEBUG <Tunnel#1> [ah] (65CC04495E62DF8E2F46762CDC4083A6) Connection lost and session does not allow reconnection, terminating.
22:23:27,512 DEBUG <Tunnel#1> [a] (65CC04495E62DF8E2F46762CDC4083A6) Session.stop
22:23:27,512 DEBUG <Tunnel#1> [a] (65CC04495E62DF8E2F46762CDC4083A6) Session stop: Listeners stopped
22:23:27,527 DEBUG <Tunnel#1> [a] (65CC04495E62DF8E2F46762CDC4083A6) Session stop: Conveyors stopped
22:23:27,527 DEBUG <Tunnel#1> [r] (65CC04495E62DF8E2F46762CDC4083A6) Stop server-side conveyor state.
22:23:27,527 DEBUG <PooledIO#1> [ac] (65CC04495E62DF8E2F46762CDC4083A6) Closing selector
22:23:27,527 DEBUG <PooledIO#1> [ac] (65CC04495E62DF8E2F46762CDC4083A6) Thread stopping.
22:23:27,527 DEBUG <Tunnel#1> [a] (65CC04495E62DF8E2F46762CDC4083A6) Stop requested: Connection lost and no reconnection allowed.
22:23:27,527 DEBUG <Tunnel#1> [ah] (65CC04495E62DF8E2F46762CDC4083A6) Tunnel.stop()
22:23:27,527 DEBUG <Tunnel#1> [ah] (65CC04495E62DF8E2F46762CDC4083A6) Problem whilst stopping connection: java.lang.InterruptedException com.vmware.vdi.ob.tunnelservice.ah.a(SourceFile:419)
java.lang.InterruptedException
	at java.lang.Object.wait(Native Method)
	at java.lang.Thread.join(Unknown Source)
	at java.lang.Thread.join(Unknown Source)
	at com.vmware.vdi.ob.tunnelservice.ah.a(SourceFile:416)
	at com.vmware.vdi.ob.tunnelservice.a.a(SourceFile:508)
	at com.vmware.vdi.ice.server.r.a(SourceFile:1148)
	at com.vmware.vdi.ob.tunnelservice.ah.run(SourceFile:713)
	at java.lang.Thread.run(Unknown Source)
22:23:27,527 DEBUG <Tunnel#1> [a] (65CC04495E62DF8E2F46762CDC4083A6) Session stop: Tunnel stopped
22:23:27,527 DEBUG <Tunnel#1> [a] (65CC04495E62DF8E2F46762CDC4083A6) Session stopped
22:23:27,527 DEBUG <Outbound JMS Worker Thread> [aj] Sending JMS message: Logout
22:23:27,527 DEBUG <PoolExecutor> [ManagementFilter] Filter received message: Type=Logout
22:23:27,527 DEBUG <PoolExecutor> [ManagementFilter] Received Logout message from tunnel server: [MapMessageImpl com.swiftmq.jms.MapMessageImpl@133219b
messageIndex = 5_1
messageId = [LazyUTF8String, s=null, buffer=[B@1e35b38]
userId = [LazyUTF8String, s=null, buffer=[B@179c0a7]
clientId = [LazyUTF8String, s=null, buffer=[B@5739a0]
timeStamp = 1220995407527
correlationId = null
replyTo = null
destination = IceTunnelTopic
deliveryMode = 2
redelivered = false
deliveryCount = 1
type = null
expiration = 0
priority = 4
props = {Server=https://isptvdm01.mydomain.pt:443, TunnelGeneration=4, TunnelVersion=4.0.2, Type=Logout, capID=65CC04495E62DF8E2F46762CDC4083A6}
readOnly = true
sourceRouter = null
destRouter = null
destQueue = null map=null mapBytes=null]
22:23:27,527 DEBUG <PoolExecutor> [ManagementFilter] Marking session for invalidation
22:23:27,527 DEBUG <PoolExecutor> [c] Successfully unbound UserSessionTracker (for userId=S-1-5-21-1229272821-73586283-725345543-9302)
22:23:27,527 DEBUG <PoolExecutor> [c] Successfully removed session
22:23:27,527 INFO  <PoolExecutor> [Audit] BROKER_LOGOFF:USER:mydomain\vdiuser;USERSID:S-1-5-21-1229272821-73586283-725345543-9302;
22:23:27,527 INFO  <PoolExecutor> [c] User USER:mydomain\vdiuser;USERSID:S-1-5-21-1229272821-73586283-725345543-9302; has logged out of VDM
22:23:27,543 DEBUG <PoolExecutor> [ManagementFilter] Invalidating session (time out = 1sec): 65CC04495E62DF8E2F46762CDC4083A6
22:23:27,543 DEBUG <PoolExecutor> [ManagementFilter] Session invalidated (time out): 65CC04495E62DF8E2F46762CDC4083A6
22:23:27,543 DEBUG <MsgWorker#2> [h] (65CC04495E62DF8E2F46762CDC4083A6) JMS message received: Logout
22:23:27,543 DEBUG <Tunnel#1> [ah] (65CC04495E62DF8E2F46762CDC4083A6) lostConnection done
22:23:27,543 INFO  <Tunnel#1> [f] (65CC04495E62DF8E2F46762CDC4083A6) User vdiuser VDM Secure Gateway session ended - session ID: 65CC04495E62DF8E2F46762CDC4083A6
22:23:27,543 DEBUG <Tunnel#1> [f] (65CC04495E62DF8E2F46762CDC4083A6) Session removed: 65CC04495E62DF8E2F46762CDC4083A6
22:23:27,543 DEBUG <Tunnel#1> [a] (65CC04495E62DF8E2F46762CDC4083A6) Session.emergencyStop
22:23:27,543 DEBUG <Tunnel#1> [a] (65CC04495E62DF8E2F46762CDC4083A6) Session stop: Listeners stopped
22:23:27,543 DEBUG <Tunnel#1> [a] (65CC04495E62DF8E2F46762CDC4083A6) Session stop: Conveyors stopped
22:23:27,543 DEBUG <Tunnel#1> [r] (65CC04495E62DF8E2F46762CDC4083A6) Stop server-side conveyor state.
22:23:27,543 DEBUG <Tunnel#1> [a] (65CC04495E62DF8E2F46762CDC4083A6) Session terminated
22:23:27,543 DEBUG <Outbound JMS Worker Thread> [aj] Sending JMS message: Logout
22:23:27,543 DEBUG <PoolExecutor> [ManagementFilter] Filter received message: Type=Logout
22:23:27,543 DEBUG <PoolExecutor> [ManagementFilter] Received Logout message from tunnel server: [MapMessageImpl com.swiftmq.jms.MapMessageImpl@8a4156
messageIndex = 5_2
messageId = [LazyUTF8String, s=null, buffer=[B@c787d7]
userId = [LazyUTF8String, s=null, buffer=[B@1a76e19]
clientId = [LazyUTF8String, s=null, buffer=[B@12d49e7]
timeStamp = 1220995407543
correlationId = null
replyTo = null
destination = IceTunnelTopic
deliveryMode = 2
redelivered = false
deliveryCount = 1
type = null
expiration = 0
priority = 4
props = {Server=https://isptvdm01.mydomain.pt:443, TunnelGeneration=4, TunnelVersion=4.0.2, Type=Logout, capID=65CC04495E62DF8E2F46762CDC4083A6}
readOnly = true
sourceRouter = null
destRouter = null
destQueue = null map=null mapBytes=null]
22:23:27,543 DEBUG <PoolExecutor> [ManagementFilter] Session not found for CAP ID 65CC04495E62DF8E2F46762CDC4083A6
22:23:27,543 DEBUG <MsgWorker#3> [h] (65CC04495E62DF8E2F46762CDC4083A6) JMS message received: Logout
22:23:27,559 DEBUG <Tunnel#1> [ah] (65CC04495E62DF8E2F46762CDC4083A6) Tunnel thread finished