Since this morning, it takes about 3 to 4 minutes for VIC and RAT to launch when we connect to a virtual venue with an AG3 client multicast connection. This obviously means there are no audio or video services running during this delay, effectively disabling the client.
This doesn't happen with a bridged connection, i.e. VIC and RAT launch straight away. And once a bridged connection has been established to a virtual venue, you can switch back to multicast and VIC and RAT launch as normal without delay. Luckily this last point has provided us with a workaround to offer the UK AG3 community, who would otherwise have been without a venue service all day! My guess is that it's related to the Jabber service failure, although as this hasn't happened before when Jabber has gone down, this could suggest a different type of Jabber failure. Of course, these issues may not be related (apologies for suggesting it, if this turns out to be the case), but we get the same effect when we connect to either of our AG3 venue servers, and also vv3.mcs.anl.gov. I've attached my four relevant client log files. You'll see that I started the client at 10:10:02 and it wasn't until 10:13:58 that VIC and RAT launched. The VenueClient.noJabber.log file shows a series of 36 second 'time-outs' following the attempted connection to the Jabber server. I hope this info proves to be useful. Once the Jabber service is resumed, I'll test everything again and confirm whether we're still experiencing this problem. I'd be interested to know if anyone else also sees this delay in the launch of VIC and RAT. Regards, Ben. |=============================| | Ben Green | | Access Grid Support Centre | | Room G49-H | | Research Computing Services | | Kilburn Building | | University of Manchester | | Oxford Road | | Manchester | | M13 9PL | |-----------------------------| | Tel. 0161 306 6621 | | Fax. 0161 275 0637 | | ben.gr...@manchester.ac.uk | | http://www.agsc.ja.net | |=============================|
11/15/07 10:10:05 908 Toolkit config.py:575 DEBUG retrieved local IP address 192.150.184.111 11/15/07 10:10:05 908 Toolkit toolkit.py:111 DEBUG Initializing AG Toolkit version 3.0.2 11/15/07 10:10:05 908 Toolkit toolkit.py:112 INFO Command and arguments: ['C:\\Documents and Settings\\zzalsbg3\\Application Data\\AccessGrid3\\local_services\\VideoProducerService\\VideoProducerService.py', '--port', '58641', '--serviceManagerUri', 'http://192.150.184.111:11000/ServiceManager', '--token', 'c096b86f1008537a8afb29d43c899372'] 11/15/07 10:10:05 908 Toolkit config.py:581 INFO Using vfwscan to get devices 11/15/07 10:10:05 908 Toolkit config.py:582 DEBUG vfwscanexe = C:\PROGRA~1\AGTk-3\bin\vfwscan.exe 11/15/07 10:10:05 908 Toolkit config.py:587 DEBUG vfwscan filelines = ['Microsoft WDM Image Capture (Win32)\n'] 11/15/07 10:10:05 908 Toolkit config.py:604 INFO Using wdmscan to get devices 11/15/07 10:10:05 908 Toolkit config.py:605 DEBUG wdmscanexe = C:\PROGRA~1\AGTk-3\bin\wdmscan.exe 11/15/07 10:10:05 908 Toolkit config.py:610 DEBUG wdmscan filelines = ['Logitech QuickCam Pro 4000\n'] 11/15/07 10:10:05 908 Toolkit config.py:642 INFO GetResources: ['Microsoft WDM Image Capture (Win32)', 'Logitech QuickCam Pro 4000'] 11/15/07 10:10:05 908 Toolkit config.py:562 INFO Found 2 processors; setting affinity 11/15/07 10:10:05 908 VenueClient preferences.py:180 DEBUG Preferences.LoadPreferences: open file 11/15/07 10:10:05 908 Toolkit toolkit.py:161 INFO Logfile Name: VideoProducerService.log 11/15/07 10:10:05 908 Toolkit toolkit.py:650 INFO Service init: have profile None 11/15/07 10:10:05 908 Toolkit toolkit.py:675 INFO Service Initialization Complete. 11/15/07 10:10:05 908 Toolkit agservice.py:363 INFO Starting Service URI: http://192.150.184.111:58641/Services/VideoProducerService.c096b86f1408537a8b60026f9a4b2267 11/15/07 10:10:05 908 Toolkit agservice.py:373 DEBUG Registering with service manager; url=http://192.150.184.111:11000/ServiceManager 11/15/07 10:10:05 5204 Toolkit videoproducerservice.py:350 INFO VideoProducerService.SetResource : Microsoft WDM Image Capture (Win32) 11/15/07 10:10:05 5204 Toolkit videoproducerservice.py:373 INFO port = external-in 11/15/07 10:10:05 5204 Toolkit videoproducerservice.py:389 INFO SetIdentity: Ben Green ben.gr...@manchester.ac.uk 11/15/07 10:10:06 4052 Toolkit agservice.py:214 INFO AGService.SetEnabled : enabled = 0 11/15/07 10:10:06 4052 Toolkit agservice.py:220 INFO Stopping service 11/15/07 10:13:59 5468 Toolkit videoproducerservice.py:325 INFO SetStream: StreamDescription: {'description': None, 'any': [], 'encryptionKey': None, 'uri': None, 'encryptionFlag': 0, 'capability': [consumer, video, c096b86f08d053764ff7019727816eaa, H261, 90000, 1], 'static': False, 'location': multicast 224.2.227.164 64328 127, 'id': u'c096b84d2d971bd376592e46acd34f3866', 'networkLocations': [multicast 224.2.227.164 64328 127], 'name': u'AGSC Venue Server Lobby'} 11/15/07 10:13:59 5468 Toolkit videoproducerservice.py:326 INFO enabled: 0 11/15/07 10:13:59 5468 Toolkit agservice.py:171 INFO SetStream: [consumer, video, c096b86f08d053764ff7019727816eaa, H261, 90000, 1] 224.2.227.164 64328
11/15/07 10:10:03 5612 Toolkit config.py:575 DEBUG retrieved local IP address 192.150.184.111 11/15/07 10:10:03 5612 Toolkit toolkit.py:111 DEBUG Initializing AG Toolkit version 3.0.2 11/15/07 10:10:03 5612 Toolkit toolkit.py:112 INFO Command and arguments: ['C:\\Documents and Settings\\zzalsbg3\\Application Data\\AccessGrid3\\local_services\\AudioService\\AudioService.py', '--port', '50474', '--serviceManagerUri', 'http://192.150.184.111:11000/ServiceManager', '--token', 'c096b86f1008537a8a1c2ff94b1b399f'] 11/15/07 10:10:03 5612 VenueClient preferences.py:180 DEBUG Preferences.LoadPreferences: open file 11/15/07 10:10:03 5612 Toolkit toolkit.py:161 INFO Logfile Name: AudioService.log 11/15/07 10:10:03 5612 Toolkit toolkit.py:650 INFO Service init: have profile None 11/15/07 10:10:03 5612 Toolkit toolkit.py:675 INFO Service Initialization Complete. 11/15/07 10:10:03 5612 Toolkit agservice.py:363 INFO Starting Service URI: http://192.150.184.111:50474/Services/AudioService.c096b86f1570537a8a6f003dd341ad28 11/15/07 10:10:03 5612 Toolkit agservice.py:373 DEBUG Registering with service manager; url=http://192.150.184.111:11000/ServiceManager 11/15/07 10:10:03 5304 Toolkit audioservice.py:355 INFO SetIdentity: Ben Green ben.gr...@manchester.ac.uk 11/15/07 10:10:06 5460 Toolkit agservice.py:214 INFO AGService.SetEnabled : enabled = 1 11/15/07 10:13:59 5584 Toolkit agservice.py:171 INFO SetStream: [consumer, audio, c0ab82dd06745379b39e059a9eebde2a, L16, 16000, 1, consumer, audio, c0ab82dd06745379b39e059a9eebde2a, L16, 8000, 1, consumer, audio, c0ab82dd06745379b39e059a9eebde2a, L8, 16000, 1, consumer, audio, c0ab82dd06745379b39e059a9eebde2a, L8, 8000, 1, consumer, audio, c0ab82dd06745379b39e059a9eebde2a, PCMU, 16000, 1, consumer, audio, c0ab82dd06745379b39e059a9eebde2a, PCMU, 8000, 1, consumer, audio, c0ab82dd06745379b39e059a9eebde2a, GSM, 16000, 1, consumer, audio, c0ab82dd06745379b39e059a9eebde2a, GSM, 8000, 1, producer, audio, c0ab82dd06745379b39e059a9eebde2a, L16, 16000, 1] 224.2.198.97 56870 11/15/07 10:13:59 5584 Toolkit audioservice.py:298 INFO Stop service 11/15/07 10:13:59 5584 Toolkit audioservice.py:309 INFO Executing rat-kill 11/15/07 10:13:59 5584 ProcessManager processmanager.py:62 DEBUG Creating process: .\rat-kill.exe 11/15/07 10:13:59 5584 ProcessManager processmanager.py:75 DEBUG Create process returns: (<PyHANDLE object at 0x016954CC>, <PyHANDLE object at 0x016A9F2C>, 5576, 5592) 11/15/07 10:13:59 5584 ProcessManager processmanager.py:138 ERROR couldn't shutdown process <PyHANDLE:728>: (1444, 'PostThreadMessage', 'Invalid thread identifier.') Traceback (most recent call last): File "C:\Python23\lib\site-packages\AccessGrid3\AccessGrid\Platform\win32\ProcessManager.py", line 131, in TerminateProcess win32api.PostThreadMessage(self.threadid[pid], 18, 0, 0) error: (1444, 'PostThreadMessage', 'Invalid thread identifier.') 11/15/07 10:13:59 5584 ProcessManager processmanager.py:145 ERROR couldn't terminate process <PyHANDLE:728>: (5, 'TerminateProcess', 'Access is denied.') Traceback (most recent call last): File "C:\Python23\lib\site-packages\AccessGrid3\AccessGrid\Platform\win32\ProcessManager.py", line 142, in TerminateProcess win32process.TerminateProcess(pid, 0) error: (5, 'TerminateProcess', 'Access is denied.') 11/15/07 10:13:59 5584 Toolkit audioservice.py:283 INFO Starting AudioService 11/15/07 10:13:59 5584 Toolkit audioservice.py:284 INFO executable = C:\Documents and Settings\zzalsbg3\Application Data\AccessGrid3\local_services\AudioService\rat.exe 11/15/07 10:13:59 5584 Toolkit audioservice.py:286 INFO options = ['-C', u'AGSC Venue Server Lobby', '-S', u'8258c9db0d1c3a94072166a91311749c', '-f', 'L16-16K-Mono', '-t', '127', u'224.2.198.97/56870'] 11/15/07 10:13:59 5584 ProcessManager processmanager.py:62 DEBUG Creating process: C:\Documents and Settings\zzalsbg3\Application Data\AccessGrid3\local_services\AudioService\rat.exe -C "AGSC Venue Server Lobby" -S 8258c9db0d1c3a94072166a91311749c -f L16-16K-Mono -t 127 224.2.198.97/56870 11/15/07 10:13:59 5584 ProcessManager processmanager.py:75 DEBUG Create process returns: (<PyHANDLE object at 0x00FF51D4>, <PyHANDLE object at 0x0169715C>, 5072, 5076)
11/15/07 10:10:02 5224 Toolkit config.py:575 DEBUG retrieved local IP address 192.150.184.111 11/15/07 10:10:02 5224 Toolkit toolkit.py:111 DEBUG Initializing AG Toolkit version 3.0.2 11/15/07 10:10:02 5224 Toolkit toolkit.py:112 INFO Command and arguments: ['C:\\Program Files\\AGTk-3\\bin\\VenueClient3.py'] 11/15/07 10:10:02 5224 VenueClient preferences.py:180 DEBUG Preferences.LoadPreferences: open file 11/15/07 10:10:02 5224 Toolkit toolkit.py:161 INFO Logfile Name: VenueClient.log 11/15/07 10:10:02 5224 Toolkit venueclient3.py:125 INFO wx version is: 2.6.2.1 11/15/07 10:10:02 5224 VenueClient venueclient.py:375 DEBUG __StartWebService: venueclient: http://192.150.184.111:11000/VenueClient 11/15/07 10:10:02 5224 VenueClient venueclient.py:386 DEBUG __StartWebService: service manager: http://192.150.184.111:11000/ServiceManager 11/15/07 10:10:02 5224 VenueClient venueclient.py:400 DEBUG __StartWebService: node service: http://192.150.184.111:11000/NodeService 11/15/07 10:10:02 5224 NodeService agnodeservice.py:635 INFO NodeService.GetConfigurations 11/15/07 10:10:02 5224 VenueClient venueclient.py:175 DEBUG Loading node configuration: <AccessGrid.Descriptions.NodeConfigDescription instance at 0x02EF9198> 11/15/07 10:10:02 5224 NodeService agnodeservice.py:375 INFO NodeService.LoadConfiguration 11/15/07 10:10:02 5224 NodeService agnodeservice.py:394 INFO Trying to load node configuration from: C:\Program Files\AGTk-3\Config\nodeConfig\default 11/15/07 10:10:02 5224 NodeService agnodeservice.py:402 DEBUG section: node 11/15/07 10:10:02 5224 NodeService agnodeservice.py:404 DEBUG servicemanagers : servicemanager0 11/15/07 10:10:02 5224 NodeService agnodeservice.py:402 DEBUG section: serviceconfig0 11/15/07 10:10:02 5224 NodeService agnodeservice.py:404 DEBUG Silence Suppression : Off 11/15/07 10:10:02 5224 NodeService agnodeservice.py:404 DEBUG Output Gain : 30 11/15/07 10:10:02 5224 NodeService agnodeservice.py:404 DEBUG Talk : Off 11/15/07 10:10:02 5224 NodeService agnodeservice.py:404 DEBUG Input Gain : 29 11/15/07 10:10:02 5224 NodeService agnodeservice.py:402 DEBUG section: servicemanager0 11/15/07 10:10:02 5224 NodeService agnodeservice.py:404 DEBUG services : service0 service1 service2 11/15/07 10:10:02 5224 NodeService agnodeservice.py:404 DEBUG builtin : 1 11/15/07 10:10:02 5224 NodeService agnodeservice.py:404 DEBUG name : 11/15/07 10:10:02 5224 NodeService agnodeservice.py:404 DEBUG url : 11/15/07 10:10:02 5224 NodeService agnodeservice.py:402 DEBUG section: service2 11/15/07 10:10:02 5224 NodeService agnodeservice.py:404 DEBUG resource : resource2 11/15/07 10:10:02 5224 NodeService agnodeservice.py:404 DEBUG serviceConfig : serviceconfig2 11/15/07 10:10:02 5224 NodeService agnodeservice.py:404 DEBUG packageName : VideoProducerService.zip 11/15/07 10:10:02 5224 NodeService agnodeservice.py:402 DEBUG section: service1 11/15/07 10:10:02 5224 NodeService agnodeservice.py:404 DEBUG packageName : VideoConsumerService.zip 11/15/07 10:10:02 5224 NodeService agnodeservice.py:402 DEBUG section: service0 11/15/07 10:10:02 5224 NodeService agnodeservice.py:404 DEBUG packageName : AudioService.zip 11/15/07 10:10:02 5224 NodeService agnodeservice.py:404 DEBUG serviceConfig : serviceconfig0 11/15/07 10:10:02 5224 NodeService agnodeservice.py:402 DEBUG section: serviceconfig2 11/15/07 10:10:02 5224 NodeService agnodeservice.py:404 DEBUG Frame Rate : 24 11/15/07 10:10:02 5224 NodeService agnodeservice.py:404 DEBUG Encoding : h261 11/15/07 10:10:02 5224 NodeService agnodeservice.py:404 DEBUG Stream Name : Microsoft WDM Image Capture (Win32) 11/15/07 10:10:02 5224 NodeService agnodeservice.py:404 DEBUG Standard : PAL 11/15/07 10:10:02 5224 NodeService agnodeservice.py:404 DEBUG Bandwidth : 214 11/15/07 10:10:02 5224 NodeService agnodeservice.py:404 DEBUG Quality : 75 11/15/07 10:10:02 5224 NodeService agnodeservice.py:404 DEBUG Port : external-in 11/15/07 10:10:02 5224 NodeService agnodeservice.py:402 DEBUG section: resource2 11/15/07 10:10:02 5224 NodeService agnodeservice.py:404 DEBUG name : Microsoft WDM Image Capture (Win32) 11/15/07 10:10:02 5224 NodeService agnodeservice.py:479 DEBUG using builtin service manager at http://192.150.184.111:11000/ServiceManager 11/15/07 10:10:02 5412 ServiceManager agservicemanager.py:208 INFO AGServiceManager.RemoveServices 11/15/07 10:10:02 5616 ServiceManager agservicemanager.py:102 INFO AGServiceManager.AddService 11/15/07 10:10:02 5616 ServiceManager agservicemanager.py:339 INFO Installed service version: 3.4, package version: 3.4 11/15/07 10:10:02 5616 ServiceManager agservicemanager.py:374 DEBUG Executing service AudioService 11/15/07 10:10:02 5616 ServiceManager agservicemanager.py:406 INFO Running Service; options: ['C:\\Documents and Settings\\zzalsbg3\\Application Data\\AccessGrid3\\local_services\\AudioService\\AudioService.py', '--port', 50474, '--serviceManagerUri', 'http://192.150.184.111:11000/ServiceManager', '--token', 'c096b86f1008537a8a1c2ff94b1b399f'] 11/15/07 10:10:02 5616 ProcessManager processmanager.py:62 DEBUG Creating process: C:\Python23\pythonw.exe "C:\Documents and Settings\zzalsbg3\Application Data\AccessGrid3\local_services\AudioService\AudioService.py" --port 50474 --serviceManagerUri http://192.150.184.111:11000/ServiceManager --token c096b86f1008537a8a1c2ff94b1b399f 11/15/07 10:10:02 5616 ProcessManager processmanager.py:75 DEBUG Create process returns: (<PyHANDLE object at 0x02EE17DC>, <PyHANDLE object at 0x02EE181C>, 5488, 5612) 11/15/07 10:10:03 5616 ServiceManager agservicemanager.py:418 INFO Service registered: http://192.150.184.111:50474/Services/AudioService.c096b86f1570537a8a6f003dd341ad28 c096b86f1008537a8a1c2ff94b1b399f 11/15/07 10:10:03 1208 ServiceManager agservicemanager.py:102 INFO AGServiceManager.AddService 11/15/07 10:10:03 1208 ServiceManager agservicemanager.py:339 INFO Installed service version: 3.02, package version: 3.02 11/15/07 10:10:03 1208 ServiceManager agservicemanager.py:374 DEBUG Executing service VideoConsumerService 11/15/07 10:10:03 1208 ServiceManager agservicemanager.py:406 INFO Running Service; options: ['C:\\Documents and Settings\\zzalsbg3\\Application Data\\AccessGrid3\\local_services\\VideoConsumerService\\VideoConsumerService.py', '--port', 58028, '--serviceManagerUri', 'http://192.150.184.111:11000/ServiceManager', '--token', 'c096b86f1008537a8a9044eff401a125'] 11/15/07 10:10:03 1208 ProcessManager processmanager.py:62 DEBUG Creating process: C:\Python23\pythonw.exe "C:\Documents and Settings\zzalsbg3\Application Data\AccessGrid3\local_services\VideoConsumerService\VideoConsumerService.py" --port 58028 --serviceManagerUri http://192.150.184.111:11000/ServiceManager --token c096b86f1008537a8a9044eff401a125 11/15/07 10:10:03 1208 ProcessManager processmanager.py:75 DEBUG Create process returns: (<PyHANDLE object at 0x02F55B3C>, <PyHANDLE object at 0x02F526DC>, 5420, 2024) 11/15/07 10:10:04 1208 ServiceManager agservicemanager.py:418 INFO Service registered: http://192.150.184.111:58028/Services/VideoConsumerService.c096b86f152c537a8ae3e6cdfc07d1ea c096b86f1008537a8a9044eff401a125 11/15/07 10:10:04 4764 ServiceManager agservicemanager.py:102 INFO AGServiceManager.AddService 11/15/07 10:10:04 4764 ServiceManager agservicemanager.py:339 INFO Installed service version: 3.3, package version: 3.3 11/15/07 10:10:04 4764 ServiceManager agservicemanager.py:374 DEBUG Executing service VideoProducerService 11/15/07 10:10:04 4764 ServiceManager agservicemanager.py:406 INFO Running Service; options: ['C:\\Documents and Settings\\zzalsbg3\\Application Data\\AccessGrid3\\local_services\\VideoProducerService\\VideoProducerService.py', '--port', 58641, '--serviceManagerUri', 'http://192.150.184.111:11000/ServiceManager', '--token', 'c096b86f1008537a8afb29d43c899372'] 11/15/07 10:10:04 4764 ProcessManager processmanager.py:62 DEBUG Creating process: C:\Python23\pythonw.exe "C:\Documents and Settings\zzalsbg3\Application Data\AccessGrid3\local_services\VideoProducerService\VideoProducerService.py" --port 58641 --serviceManagerUri http://192.150.184.111:11000/ServiceManager --token c096b86f1008537a8afb29d43c899372 11/15/07 10:10:04 4764 ProcessManager processmanager.py:75 DEBUG Create process returns: (<PyHANDLE object at 0x02F7774C>, <PyHANDLE object at 0x02F69404>, 5128, 908) 11/15/07 10:10:05 4764 ServiceManager agservicemanager.py:418 INFO Service registered: http://192.150.184.111:58641/Services/VideoProducerService.c096b86f1408537a8b60026f9a4b2267 c096b86f1008537a8afb29d43c899372 11/15/07 10:10:05 5224 VenueClient venueclient.py:242 DEBUG get bridges from registry 11/15/07 10:10:06 5224 VenueClient venueclient.py:256 DEBUG set bridges in prefs 11/15/07 10:10:06 5224 VenueClient venueclient.py:265 DEBUG connect to bridge 11/15/07 10:10:06 5224 VenueClient venueclient.py:269 DEBUG exiting loadbridges 11/15/07 10:10:06 5224 NodeService agnodeservice.py:289 INFO NodeService.SetServiceEnabledByMediaType 11/15/07 10:10:06 5224 NodeService agnodeservice.py:257 INFO NodeService.GetServices 11/15/07 10:10:06 1816 ServiceManager agservicemanager.py:218 INFO AGServiceManager.GetServices 11/15/07 10:10:06 5224 NodeService agnodeservice.py:275 INFO NodeService.SetServiceEnabled 11/15/07 10:10:06 5224 NodeService agnodeservice.py:695 INFO NodeService.__SendStreamsToService 11/15/07 10:10:06 5224 NodeService agnodeservice.py:699 DEBUG service capabilities: [consumer, audio, c096b86f1570537a8a5401dd5a1180cb, L16, 16000, 1, consumer, audio, c096b86f1570537a8a5401dd5a1180cb, L16, 8000, 1, consumer, audio, c096b86f1570537a8a5401dd5a1180cb, L8, 16000, 1, consumer, audio, c096b86f1570537a8a5401dd5a1180cb, L8, 8000, 1, consumer, audio, c096b86f1570537a8a5401dd5a1180cb, PCMU, 16000, 1, consumer, audio, c096b86f1570537a8a5401dd5a1180cb, PCMU, 8000, 1, consumer, audio, c096b86f1570537a8a5401dd5a1180cb, GSM, 16000, 1, consumer, audio, c096b86f1570537a8a5401dd5a1180cb, GSM, 8000, 1, producer, audio, c096b86f1570537a8a5401dd5a1180cb, L16, 16000, 1] 11/15/07 10:10:06 5224 NodeService agnodeservice.py:257 INFO NodeService.GetServices 11/15/07 10:10:06 2940 ServiceManager agservicemanager.py:218 INFO AGServiceManager.GetServices 11/15/07 10:10:06 5224 NodeService agnodeservice.py:257 INFO NodeService.GetServices 11/15/07 10:10:06 4888 ServiceManager agservicemanager.py:218 INFO AGServiceManager.GetServices 11/15/07 10:10:06 5224 NodeService agnodeservice.py:635 INFO NodeService.GetConfigurations 11/15/07 10:10:06 5224 NodeService agnodeservice.py:635 INFO NodeService.GetConfigurations 11/15/07 10:10:46 5224 VenueClientController venueclientcontroller.py:435 DEBUG VenueClientController calling Venue.EnterVenue 11/15/07 10:10:46 5224 VenueClient venueclient.py:1015 DEBUG EnterVenue; url=https://sam.ag.manchester.ac.uk:8000/Venues/default 11/15/07 10:10:46 5224 NodeService agnodeservice.py:658 INFO NodeService.GetCapabilities 11/15/07 10:10:46 5224 NodeService agnodeservice.py:257 INFO NodeService.GetServices 11/15/07 10:10:46 4532 ServiceManager agservicemanager.py:218 INFO AGServiceManager.GetServices 11/15/07 10:10:46 5224 VenueClient venueclient.py:1049 DEBUG calling __EnterVenue 11/15/07 10:10:46 5224 VenueClient venueclient.py:806 DEBUG EnterVenue: Invoke Venue.Enter 11/15/07 10:10:48 5224 VenueClient venueclient.py:808 DEBUG after Venue.Enter 11/15/07 10:10:48 5224 VenueClient venueclient.py:810 DEBUG EnterVenue: Invoke Venue.getstate 11/15/07 10:10:49 5224 VenueClient venueclient.py:812 DEBUG EnterVenue: done Venue.getstate 11/15/07 10:10:49 5224 VenueClient venueclient.py:835 DEBUG Setting isInVenue flag. 11/15/07 10:10:49 5224 VenueClient venueclient.py:1051 DEBUG after __EnterVenue 11/15/07 10:10:49 5224 VenueClient venueclientui.py:2586 DEBUG bin.VenueClient::EnterVenue: Enter venue with url: https://sam.ag.manchester.ac.uk:8000/Venues/default 11/15/07 10:10:49 2624 VenueClient venueclient.py:450 DEBUG Calling Heartbeat, time now: 1195121449 11/15/07 10:10:49 5224 VenueClient venueclientui.py:2699 DEBUG Entered venue 11/15/07 10:10:49 5224 VenueClientController venueclientcontroller.py:437 DEBUG VenueClientController after Venue.EnterVenue 11/15/07 10:10:49 2624 VenueClient venueclient.py:474 DEBUG Next Heartbeat needed within 36s 11/15/07 10:10:49 2624 JabberClient jabberclient.py:33 INFO Connecting to Jabber Server 'jabber.mcs.anl.gov' ... 11/15/07 10:10:49 5224 VenueClient venueclientui.py:3333 DEBUG ContentListPanel.AddParticipant:: AddParticipant Ben Green (called from ('C:\\Python23\\lib\\site-packages\\wx-2.6-msw-unicode\\wx\\_core.py', 13469, '<lambda>', 'lambda event: event.callable(*event.args, **event.kw) )')) 11/15/07 10:10:52 5224 GroupMsgClient groupmsgclient.py:112 INFO Connected. Connection ID: c096b84d2d971bd37aa4578bff92a5e16c 11/15/07 10:10:52 5224 EventClient insecurevenueeventclient.py:60 INFO BaseVenueEventClient made connection. 11/15/07 10:11:25 4876 VenueClient venueclient.py:450 DEBUG Calling Heartbeat, time now: 1195121485 11/15/07 10:11:25 4876 VenueClient venueclient.py:474 DEBUG Next Heartbeat needed within 36s 11/15/07 10:12:01 4700 VenueClient venueclient.py:450 DEBUG Calling Heartbeat, time now: 1195121521 11/15/07 10:12:01 4700 VenueClient venueclient.py:474 DEBUG Next Heartbeat needed within 36s 11/15/07 10:12:37 5452 VenueClient venueclient.py:450 DEBUG Calling Heartbeat, time now: 1195121557 11/15/07 10:12:37 5452 VenueClient venueclient.py:474 DEBUG Next Heartbeat needed within 36s 11/15/07 10:13:13 4580 VenueClient venueclient.py:450 DEBUG Calling Heartbeat, time now: 1195121593 11/15/07 10:13:13 4580 VenueClient venueclient.py:474 DEBUG Next Heartbeat needed within 36s 11/15/07 10:13:49 4052 VenueClient venueclient.py:450 DEBUG Calling Heartbeat, time now: 1195121629 11/15/07 10:13:49 4052 VenueClient venueclient.py:474 DEBUG Next Heartbeat needed within 36s 11/15/07 10:13:58 2624 VenueClient venueclient.py:885 ERROR EnterVenue.__StartJabber failed Traceback (most recent call last): File "C:\Python23\lib\site-packages\AccessGrid3\AccessGrid\VenueClient.py", line 883, in DoPostEnter self.__StartJabber(self.textLocation) File "C:\Python23\lib\site-packages\AccessGrid3\AccessGrid\VenueClient.py", line 976, in __StartJabber self.jabber.Connect(jabberHost, jabberPort) File "C:\Python23\lib\site-packages\AccessGrid3\AccessGrid\Jabber\JabberClient.py", line 34, in Connect self._stream = stream.JabberClientStream(host, port=port, use_ssl=True) File "C:\Python23\Lib\site-packages\gov\lbl\dsd\bajjer\stream.py", line 153, in __init__ self.open(host, port, use_ssl) File "C:\Python23\Lib\site-packages\gov\lbl\dsd\bajjer\stream.py", line 110, in open self._conn = io.Connection(host, port, use_ssl) File "C:\Python23\Lib\site-packages\gov\lbl\dsd\bajjer\io.py", line 92, in __init__ self._sock = ssl.NonBlockingSSL(host, port) File "C:\Python23\Lib\site-packages\gov\lbl\dsd\bajjer\ssl.py", line 34, in __init__ self._sock = DefaultSSL(host, port) File "C:\Python23\Lib\site-packages\gov\lbl\dsd\bajjer\ssl.py", line 58, in __init__ self._ssl = socket.ssl(self._sock) File "C:\Python23\lib\socket.py", line 73, in ssl return _realssl(sock, keyfile, certfile) sslerror: (8, 'EOF occurred in violation of protocol') 11/15/07 10:13:58 2624 VenueClient venueclient.py:959 INFO VenueClient.StartBeacon: Address 224.2.192.32/61300 11/15/07 10:13:58 2624 RTPBeacon rtpbeacon.py:278 DEBUG Called Start. 11/15/07 10:13:58 2624 VenueClient venueclient.py:1231 INFO In UpdateStream: transport=multicast 11/15/07 10:13:58 2624 VenueClient venueclient.py:1231 INFO In UpdateStream: transport=multicast 11/15/07 10:13:58 2624 VenueClient venueclient.py:1231 INFO In UpdateStream: transport=multicast 11/15/07 10:13:58 2624 RTPBeacon rtpbeacon.py:296 DEBUG Called Stop. 11/15/07 10:13:58 2624 VenueClient venueclient.py:951 INFO Beacon being reconfigured, stopping running beacon 11/15/07 10:13:58 2624 RTPBeacon rtpbeacon.py:296 DEBUG Called Stop. 11/15/07 10:13:58 2624 VenueClient venueclient.py:959 INFO VenueClient.StartBeacon: Address 224.2.192.32/61300 11/15/07 10:13:58 2624 RTPBeacon rtpbeacon.py:278 DEBUG Called Start. 11/15/07 10:13:58 2624 VenueClient venueclient.py:1190 DEBUG UpdateNodeService: Method UpdateNodeService called 11/15/07 10:13:58 2624 VenueClient venueclient.py:1195 DEBUG Setting node service streams 11/15/07 10:13:58 2624 NodeService agnodeservice.py:328 INFO NodeService.SetStreams 11/15/07 10:13:58 2624 NodeService agnodeservice.py:257 INFO NodeService.GetServices 11/15/07 10:13:58 5364 ServiceManager agservicemanager.py:218 INFO AGServiceManager.GetServices 11/15/07 10:13:58 2624 NodeService agnodeservice.py:695 INFO NodeService.__SendStreamsToService 11/15/07 10:13:58 2624 NodeService agnodeservice.py:699 DEBUG service capabilities: [consumer, audio, c096b86f1570537a8a5401dd5a1180cb, L16, 16000, 1, consumer, audio, c096b86f1570537a8a5401dd5a1180cb, L16, 8000, 1, consumer, audio, c096b86f1570537a8a5401dd5a1180cb, L8, 16000, 1, consumer, audio, c096b86f1570537a8a5401dd5a1180cb, L8, 8000, 1, consumer, audio, c096b86f1570537a8a5401dd5a1180cb, PCMU, 16000, 1, consumer, audio, c096b86f1570537a8a5401dd5a1180cb, PCMU, 8000, 1, consumer, audio, c096b86f1570537a8a5401dd5a1180cb, GSM, 16000, 1, consumer, audio, c096b86f1570537a8a5401dd5a1180cb, GSM, 8000, 1, producer, audio, c096b86f1570537a8a5401dd5a1180cb, L16, 16000, 1] 11/15/07 10:13:58 2624 NodeService agnodeservice.py:713 INFO Sending stream (type=[consumer, audio, c0ab82dd06745379b39e059a9eebde2a, L16, 16000, 1, consumer, audio, c0ab82dd06745379b39e059a9eebde2a, L16, 8000, 1, consumer, audio, c0ab82dd06745379b39e059a9eebde2a, L8, 16000, 1, consumer, audio, c0ab82dd06745379b39e059a9eebde2a, L8, 8000, 1, consumer, audio, c0ab82dd06745379b39e059a9eebde2a, PCMU, 16000, 1, consumer, audio, c0ab82dd06745379b39e059a9eebde2a, PCMU, 8000, 1, consumer, audio, c0ab82dd06745379b39e059a9eebde2a, GSM, 16000, 1, consumer, audio, c0ab82dd06745379b39e059a9eebde2a, GSM, 8000, 1, producer, audio, c0ab82dd06745379b39e059a9eebde2a, L16, 16000, 1]) to service: http://192.150.184.111:50474/Services/AudioService.c096b86f1570537a8a6f003dd341ad28 11/15/07 10:13:59 2624 NodeService agnodeservice.py:695 INFO NodeService.__SendStreamsToService 11/15/07 10:13:59 2624 NodeService agnodeservice.py:699 DEBUG service capabilities: [consumer, video, c096b86f152c537a8ac60202caa6c8da, H261, 90000, 1] 11/15/07 10:13:59 2624 NodeService agnodeservice.py:713 INFO Sending stream (type=[consumer, video, c096b86f08d053764ff7019727816eaa, H261, 90000, 1]) to service: http://192.150.184.111:58028/Services/VideoConsumerService.c096b86f152c537a8ae3e6cdfc07d1ea 11/15/07 10:13:59 2624 NodeService agnodeservice.py:695 INFO NodeService.__SendStreamsToService 11/15/07 10:13:59 2624 NodeService agnodeservice.py:699 DEBUG service capabilities: [producer, video, c096b86f1408537a8b2b01891dd50af8, H261, 90000, 1] 11/15/07 10:13:59 2624 NodeService agnodeservice.py:713 INFO Sending stream (type=[consumer, video, c096b86f08d053764ff7019727816eaa, H261, 90000, 1]) to service: http://192.150.184.111:58641/Services/VideoProducerService.c096b86f1408537a8b60026f9a4b2267 11/15/07 10:13:59 2624 VenueClient venueclient.py:914 DEBUG Updating client profile cache. 11/15/07 10:13:59 4164 RTPBeacon rtpbeacon.py:289 INFO RTPBeacon.UpdateThread exiting 11/15/07 10:14:14 5224 VenueClient venueclient.py:548 DEBUG AddUserEvent: Got Add User Event 11/15/07 10:14:14 5224 VenueClient venueclientui.py:2308 DEBUG add user: <Sarah Plum> 11/15/07 10:14:14 5224 VenueClient venueclientui.py:3333 DEBUG ContentListPanel.AddParticipant:: AddParticipant <Sarah Plum> (called from ('C:\\Python23\\lib\\site-packages\\wx-2.6-msw-unicode\\wx\\_core.py', 13469, '<lambda>', 'lambda event: event.callable(*event.args, **event.kw) )')) 11/15/07 10:14:24 5224 VenueClient venueclient.py:561 DEBUG RemoveUserEvent: Got Remove User Event 11/15/07 10:14:24 5224 VenueClient venueclientui.py:2322 DEBUG remove user: <Sarah Plum> 11/15/07 10:14:24 5224 VenueClient venueclient.py:580 DEBUG RemoveUserEvent: Got Remove User Event...done 11/15/07 10:14:24 5224 VenueClient venueclientui.py:3349 DEBUG ContentListPanel.RemoveParticipant: Remove participant 11/15/07 10:14:24 5224 VenueClient venueclientui.py:3352 DEBUG ContentListPanel.RemoveParticipant: Found participant in tree 11/15/07 10:14:24 5224 VenueClient venueclientui.py:3356 DEBUG ContentListPanel.RemoveParticipant: Removed participant from tree 11/15/07 10:14:24 5224 VenueClient venueclientui.py:3359 DEBUG ContentListPanel.RemoveParticipant: Delete participant from dictionary 11/15/07 10:14:25 5048 VenueClient venueclient.py:450 DEBUG Calling Heartbeat, time now: 1195121665 11/15/07 10:14:25 5048 VenueClient venueclient.py:474 DEBUG Next Heartbeat needed within 36s 11/15/07 10:15:01 5176 VenueClient venueclient.py:450 DEBUG Calling Heartbeat, time now: 1195121701 11/15/07 10:15:01 5176 VenueClient venueclient.py:474 DEBUG Next Heartbeat needed within 36s 11/15/07 10:15:37 5124 VenueClient venueclient.py:450 DEBUG Calling Heartbeat, time now: 1195121737 11/15/07 10:15:38 5124 VenueClient venueclient.py:474 DEBUG Next Heartbeat needed within 36s 11/15/07 10:16:14 5336 VenueClient venueclient.py:450 DEBUG Calling Heartbeat, time now: 1195121774 11/15/07 10:16:14 5336 VenueClient venueclient.py:474 DEBUG Next Heartbeat needed within 36s 11/15/07 10:16:50 4748 VenueClient venueclient.py:450 DEBUG Calling Heartbeat, time now: 1195121810 11/15/07 10:16:50 4748 VenueClient venueclient.py:474 DEBUG Next Heartbeat needed within 36s 11/15/07 10:17:26 6044 VenueClient venueclient.py:450 DEBUG Calling Heartbeat, time now: 1195121846 11/15/07 10:17:26 6044 VenueClient venueclient.py:474 DEBUG Next Heartbeat needed within 36s 11/15/07 10:18:02 5140 VenueClient venueclient.py:450 DEBUG Calling Heartbeat, time now: 1195121882 11/15/07 10:18:02 5140 VenueClient venueclient.py:474 DEBUG Next Heartbeat needed within 36s 11/15/07 10:18:38 4440 VenueClient venueclient.py:450 DEBUG Calling Heartbeat, time now: 1195121918 11/15/07 10:18:38 4440 VenueClient venueclient.py:474 DEBUG Next Heartbeat needed within 36s 11/15/07 10:19:14 4276 VenueClient venueclient.py:450 DEBUG Calling Heartbeat, time now: 1195121954 11/15/07 10:19:14 4276 VenueClient venueclient.py:474 DEBUG Next Heartbeat needed within 36s 11/15/07 10:19:28 5224 NodeService agnodeservice.py:257 INFO NodeService.GetServices 11/15/07 10:19:28 5160 ServiceManager agservicemanager.py:218 INFO AGServiceManager.GetServices 11/15/07 10:19:37 5224 VenueClient venueclientui.py:2209 INFO --------- END VenueClient 11/15/07 10:19:37 5224 VenueClient venueclient.py:1132 INFO ExitVenue 11/15/07 10:19:37 5224 VenueClient venueclient.py:1173 INFO ExitVenue: Stopping node services 11/15/07 10:19:37 5224 NodeService agnodeservice.py:301 INFO NodeService.StopServices 11/15/07 10:19:37 5832 ServiceManager agservicemanager.py:225 INFO AGServiceManager.StopServices 11/15/07 10:19:39 5224 NodeService agnodeservice.py:328 INFO NodeService.SetStreams 11/15/07 10:19:39 5224 NodeService agnodeservice.py:257 INFO NodeService.GetServices 11/15/07 10:19:39 4508 ServiceManager agservicemanager.py:218 INFO AGServiceManager.GetServices 11/15/07 10:19:39 5224 NodeService agnodeservice.py:695 INFO NodeService.__SendStreamsToService 11/15/07 10:19:39 5224 NodeService agnodeservice.py:699 DEBUG service capabilities: [consumer, audio, c096b86f1570537a8a5401dd5a1180cb, L16, 16000, 1, consumer, audio, c096b86f1570537a8a5401dd5a1180cb, L16, 8000, 1, consumer, audio, c096b86f1570537a8a5401dd5a1180cb, L8, 16000, 1, consumer, audio, c096b86f1570537a8a5401dd5a1180cb, L8, 8000, 1, consumer, audio, c096b86f1570537a8a5401dd5a1180cb, PCMU, 16000, 1, consumer, audio, c096b86f1570537a8a5401dd5a1180cb, PCMU, 8000, 1, consumer, audio, c096b86f1570537a8a5401dd5a1180cb, GSM, 16000, 1, consumer, audio, c096b86f1570537a8a5401dd5a1180cb, GSM, 8000, 1, producer, audio, c096b86f1570537a8a5401dd5a1180cb, L16, 16000, 1] 11/15/07 10:19:39 5224 NodeService agnodeservice.py:695 INFO NodeService.__SendStreamsToService 11/15/07 10:19:39 5224 NodeService agnodeservice.py:699 DEBUG service capabilities: [consumer, video, c096b86f152c537a8ac60202caa6c8da, H261, 90000, 1] 11/15/07 10:19:39 5224 NodeService agnodeservice.py:695 INFO NodeService.__SendStreamsToService 11/15/07 10:19:39 5224 NodeService agnodeservice.py:699 DEBUG service capabilities: [producer, video, c096b86f1408537a8b2b01891dd50af8, H261, 90000, 1] 11/15/07 10:19:39 5224 VenueClient venueclient.py:1103 DEBUG ExitVenue: Stop event client obj 11/15/07 10:19:39 5224 VenueClient venueclient.py:1105 DEBUG ExitVenue: Remove event client reference 11/15/07 10:19:39 5224 VenueClient venueclient.py:1110 INFO ExitVenue: Stopping text client 11/15/07 10:19:39 5224 VenueClient venueclient.py:1116 ERROR ExitVenue: Exit jabber failed Traceback (most recent call last): File "C:\Python23\lib\site-packages\AccessGrid3\AccessGrid\VenueClient.py", line 1113, in __ExitVenue self.jabber.SendPresence('unavailable') File "C:\Python23\lib\site-packages\AccessGrid3\AccessGrid\Jabber\JabberClient.py", line 73, in SendPresence log.debug("Sending the presence to '%s' of type '%s'..." % (self.to, type)) AttributeError: JabberClient instance has no attribute 'to' 11/15/07 10:19:39 5224 RTPBeacon rtpbeacon.py:296 DEBUG Called Stop. 11/15/07 10:19:39 5224 ServiceManager agservicemanager.py:70 INFO AGServiceManager.Shutdown 11/15/07 10:19:39 5224 ServiceManager agservicemanager.py:71 INFO Remove services 11/15/07 10:19:39 5224 ServiceManager agservicemanager.py:208 INFO AGServiceManager.RemoveServices 11/15/07 10:19:39 5224 ServiceManager agservicemanager.py:162 INFO AGServiceManager.RemoveService 11/15/07 10:19:40 2788 RTPBeacon rtpbeacon.py:289 INFO RTPBeacon.UpdateThread exiting 11/15/07 10:19:40 5224 ProcessManager processmanager.py:136 WARNING Couldn't terminate process <PyHANDLE:1124> cleanly (258) 11/15/07 10:19:40 5224 ServiceManager agservicemanager.py:162 INFO AGServiceManager.RemoveService 11/15/07 10:19:40 5224 ProcessManager processmanager.py:136 WARNING Couldn't terminate process <PyHANDLE:1144> cleanly (258) 11/15/07 10:19:40 5224 ServiceManager agservicemanager.py:162 INFO AGServiceManager.RemoveService 11/15/07 10:19:41 5224 ServiceManager agservicemanager.py:73 INFO Stop network interface 11/15/07 10:19:41 5224 RTPBeacon rtpbeacon.py:296 DEBUG Called Stop.
11/15/07 10:10:04 2024 Toolkit config.py:575 DEBUG retrieved local IP address 192.150.184.111 11/15/07 10:10:04 2024 Toolkit toolkit.py:111 DEBUG Initializing AG Toolkit version 3.0.2 11/15/07 10:10:04 2024 Toolkit toolkit.py:112 INFO Command and arguments: ['C:\\Documents and Settings\\zzalsbg3\\Application Data\\AccessGrid3\\local_services\\VideoConsumerService\\VideoConsumerService.py', '--port', '58028', '--serviceManagerUri', 'http://192.150.184.111:11000/ServiceManager', '--token', 'c096b86f1008537a8a9044eff401a125'] 11/15/07 10:10:04 2024 Toolkit config.py:562 INFO Found 2 processors; setting affinity 11/15/07 10:10:04 2024 VenueClient preferences.py:180 DEBUG Preferences.LoadPreferences: open file 11/15/07 10:10:04 2024 Toolkit toolkit.py:161 INFO Logfile Name: VideoConsumerService.log 11/15/07 10:10:04 2024 Toolkit toolkit.py:650 INFO Service init: have profile None 11/15/07 10:10:04 2024 Toolkit toolkit.py:675 INFO Service Initialization Complete. 11/15/07 10:10:04 2024 Toolkit agservice.py:363 INFO Starting Service URI: http://192.150.184.111:58028/Services/VideoConsumerService.c096b86f152c537a8ae3e6cdfc07d1ea 11/15/07 10:10:04 2024 Toolkit agservice.py:373 DEBUG Registering with service manager; url=http://192.150.184.111:11000/ServiceManager 11/15/07 10:10:04 5780 Toolkit videoconsumerservice.py:187 INFO SetIdentity: Ben Green ben.gr...@manchester.ac.uk 11/15/07 10:10:06 220 Toolkit agservice.py:214 INFO AGService.SetEnabled : enabled = 1 11/15/07 10:13:59 5248 Toolkit agservice.py:171 INFO SetStream: [consumer, video, c096b86f08d053764ff7019727816eaa, H261, 90000, 1] 224.2.227.164 64328 11/15/07 10:13:59 5248 Toolkit videoconsumerservice.py:150 INFO Starting VideoConsumerService 11/15/07 10:13:59 5248 Toolkit videoconsumerservice.py:151 INFO executable = C:\Documents and Settings\zzalsbg3\Application Data\AccessGrid3\local_services\VideoConsumerService\vic.exe 11/15/07 10:13:59 5248 Toolkit videoconsumerservice.py:152 INFO options = ['-C', u'AGSC Venue Server Lobby', '-t', '127', u'-XrtpName=Ben Green', u'-XrtpEmail=ben.gr...@manchester.ac.uk', '-XrecvOnly=1', '-XsiteDropTime=5', '-Xgeometry=500x500', '-Xtile=2', u'224.2.227.164/64328'] 11/15/07 10:13:59 5248 ProcessManager processmanager.py:62 DEBUG Creating process: C:\Documents and Settings\zzalsbg3\Application Data\AccessGrid3\local_services\VideoConsumerService\vic.exe -C "AGSC Venue Server Lobby" -t 127 "-XrtpName=Ben Green" -XrtpEmail=ben.gr...@manchester.ac.uk -XrecvOnly=1 -XsiteDropTime=5 -Xgeometry=500x500 -Xtile=2 224.2.227.164/64328 11/15/07 10:13:59 5248 ProcessManager processmanager.py:75 DEBUG Create process returns: (<PyHANDLE object at 0x0100DF04>, <PyHANDLE object at 0x01634F5C>, 1668, 2468) 11/15/07 10:19:38 5424 ProcessManager processmanager.py:136 WARNING Couldn't terminate process <PyHANDLE:728> cleanly (258) 11/15/07 10:19:40 5676 Toolkit agservice.py:238 INFO Shut service down
