[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]
[AG-TECH] Loss of Jabber service prevents VIC and RAT launching (possibly).
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.green@xxxxxxxxxxxxxxxx |
| 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.green@xxxxxxxxxxxxxxxx
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.green@xxxxxxxxxxxxxxxx
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.green@xxxxxxxxxxxxxxxx
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.green@xxxxxxxxxxxxxxxx', '-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.green@xxxxxxxxxxxxxxxx -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