Mantis Bug Tracker

View Issue Details Jump to Notes ] Issue History ] Print ]
IDProjectCategoryView StatusDate SubmittedLast Update
0006755opensim[REGION] OpenSim Corepublic2013-09-03 04:112015-12-01 05:41
Reporteraiaustin 
Assigned To 
PrioritynormalSeveritymajorReproducibilitysometimes
StatusnewResolutionopen 
PlatformPCOSWindowsOS Version8
Product Versionmaster (dev code) 
Target VersionFixed in Version 
Summary0006755: Failing teleports and avatar returned to original source region without attachments
DescriptionI am reporting this as I have noted this perhaps a dozen times in the last month or so, and in case it looks relevant to anyone testing recent TP changes and to see if HG V2 teleport changes may be effecting intra-grid and possibly hypergrid TPs.

Teleport attempts between regions on one grid can fail even on regions with no avatars already logged in. The viewer waits a long time and then returns the avatar to the original region... just as it seems the messages on the console are indicating a transfer is about to take place. The avatar returns with no attachments or HUDs at all, only base body items and clothing layers. A second attempt to teleport after that error usually crashes the viewer. Relogging in, the avatar shows fully intact and all attachments present again, and then a TP attempt again usually works. Throughout this the OpenSim.exe instances affected were not restarted.

I attach one example of teleporting between regions on OSGrid, but I have also seen it on Openvue grid.

I am teleporting between regions on a single grid. And in some cases the regions are newly updated (r/23560 on OSGrid and simlar on openvue grid) and have no load at all.

I teleport between regions running on different OpenSim.exe instances on different computers but all running on the same (fast University) sub-net. The consoles show immediate connections bewteen the viewer (Firestorm 4.4.2) and the OpenSim.exe instance but then there seem to be a lot (21 often?) messages like this...

013-09-02 17:22:28,490 DEBUG - OpenSim.Region.ClientStack.LindenUDP.LLUDPServer [LLUDPSERVER]: Received a CompleteMovementIntoRegion in Vue-6400 (not ready yet)

... repeated many times... then...

Found presence Ai Austin e858df02-a860-4b92-937a-2b87e4ebcd6d child in Vue-6400 after 21 waits

But just as the OpenSim.exe console logs seem to indicate a trbnsfer will be successful, the viewer places the avatar back to the source region without any attachments (hair, shoes, etc) and without any HUD items at all. All have been removed.

There is also an exception thrown in the process I note.. Object reference not set to an instance of an object. See log.
Steps To ReproduceI am posting this here as an initial report in case it looks familiar to anyone. I will try to gather more precise contextual information next time I see this, or to gather data that devs may feel would be helpful.
Additional InformationOSGrid addon region (r/23560) OpenSim.exe log extract for the target destination region for a TP attempt follows. Log file extract also attached in case its more useful in that form.

2013-09-02 17:22:23,607 DEBUG - OpenSim.Region.Framework.Scenes.Scene [SCENE]: Region Vue-6400 told of incoming child agent Ai Austin e858df02-a860-4b92-937a-2b87e4ebcd6d (circuit code 1457969686, IP 129.215.219.52, viewer Firestorm-Release 4.4.2.34167, teleportflags (ViaLocation), position <128, 128, 1.5>)
2013-09-02 17:22:23,966 INFO - OpenSim.Region.Framework.Scenes.Scene [SCENE]: Region Vue-6400 authenticated and authorized incoming child agent Ai Austin e858df02-a860-4b92-937a-2b87e4ebcd6d (circuit code 1457969686)
2013-09-02 17:22:23,966 DEBUG - OpenSim.Region.OptionalModules.Avatar.Voice.VivoxVoice.VivoxVoiceModule [VivoxVoice] OnRegisterCaps: agentID e858df02-a860-4b92-937a-2b87e4ebcd6d caps OpenSim.Framework.Capabilities.Caps
2013-09-02 17:22:23,981 DEBUG - OpenSim.Region.ClientStack.Linden.EventQueueGetModule [EVENTQUEUE]: Adding new queue for agent e858df02-a860-4b92-937a-2b87e4ebcd6d in region Vue-6400
2013-09-02 17:22:24,200 DEBUG - OpenSim.Region.Framework.Scenes.Scene [SCENE]: Incoming child agent update for e858df02-a860-4b92-937a-2b87e4ebcd6d in Vue-6400
2013-09-02 17:22:24,605 DEBUG - OpenSim.Region.ClientStack.Linden.BunchOfCaps [CAPS]: Received SEED caps request in Vue-6400 for agent e858df02-a860-4b92-937a-2b87e4ebcd6d
2013-09-02 17:22:24,605 DEBUG - OpenSim.Region.ClientStack.LindenUDP.LLUDPServer [LLUDPSERVER]: Received a CompleteMovementIntoRegion in Vue-6400 (not ready yet)
2013-09-02 17:22:24,808 DEBUG - OpenSim.Region.ClientStack.LindenUDP.LLUDPServer [LLUDPSERVER]: Received a CompleteMovementIntoRegion in Vue-6400 (not ready yet)
2013-09-02 17:22:25,011 DEBUG - OpenSim.Region.ClientStack.LindenUDP.LLUDPServer [LLUDPSERVER]: Received a CompleteMovementIntoRegion in Vue-6400 (not ready yet)
2013-09-02 17:22:25,214 DEBUG - OpenSim.Region.ClientStack.LindenUDP.LLUDPServer [LLUDPSERVER]: Received a CompleteMovementIntoRegion in Vue-6400 (not ready yet)
2013-09-02 17:22:25,416 DEBUG - OpenSim.Region.ClientStack.LindenUDP.LLUDPServer [LLUDPSERVER]: Received a CompleteMovementIntoRegion in Vue-6400 (not ready yet)
2013-09-02 17:22:25,619 DEBUG - OpenSim.Region.ClientStack.LindenUDP.LLUDPServer [LLUDPSERVER]: Received a CompleteMovementIntoRegion in Vue-6400 (not ready yet)
2013-09-02 17:22:25,822 DEBUG - OpenSim.Region.ClientStack.LindenUDP.LLUDPServer [LLUDPSERVER]: Received a CompleteMovementIntoRegion in Vue-6400 (not ready yet)
2013-09-02 17:22:26,025 DEBUG - OpenSim.Region.ClientStack.LindenUDP.LLUDPServer [LLUDPSERVER]: Received a CompleteMovementIntoRegion in Vue-6400 (not ready yet)
2013-09-02 17:22:26,228 DEBUG - OpenSim.Region.ClientStack.LindenUDP.LLUDPServer [LLUDPSERVER]: Received a CompleteMovementIntoRegion in Vue-6400 (not ready yet)
2013-09-02 17:22:26,430 DEBUG - OpenSim.Region.ClientStack.LindenUDP.LLUDPServer [LLUDPSERVER]: Received a CompleteMovementIntoRegion in Vue-6400 (not ready yet)
2013-09-02 17:22:26,633 DEBUG - OpenSim.Region.ClientStack.LindenUDP.LLUDPServer [LLUDPSERVER]: Received a CompleteMovementIntoRegion in Vue-6400 (not ready yet)
2013-09-02 17:22:26,836 DEBUG - OpenSim.Region.ClientStack.LindenUDP.LLUDPServer [LLUDPSERVER]: Received a CompleteMovementIntoRegion in Vue-6400 (not ready yet)
2013-09-02 17:22:27,039 DEBUG - OpenSim.Region.ClientStack.LindenUDP.LLUDPServer [LLUDPSERVER]: Received a CompleteMovementIntoRegion in Vue-6400 (not ready yet)
2013-09-02 17:22:27,242 DEBUG - OpenSim.Region.ClientStack.LindenUDP.LLUDPServer [LLUDPSERVER]: Received a CompleteMovementIntoRegion in Vue-6400 (not ready yet)
2013-09-02 17:22:27,444 DEBUG - OpenSim.Region.ClientStack.LindenUDP.LLUDPServer [LLUDPSERVER]: Received a CompleteMovementIntoRegion in Vue-6400 (not ready yet)
2013-09-02 17:22:27,647 DEBUG - OpenSim.Region.ClientStack.LindenUDP.LLUDPServer [LLUDPSERVER]: Received a CompleteMovementIntoRegion in Vue-6400 (not ready yet)
2013-09-02 17:22:27,881 DEBUG - OpenSim.Region.ClientStack.LindenUDP.LLUDPServer [LLUDPSERVER]: Received a CompleteMovementIntoRegion in Vue-6400 (not ready yet)
2013-09-02 17:22:28,084 DEBUG - OpenSim.Region.ClientStack.LindenUDP.LLUDPServer [LLUDPSERVER]: Received a CompleteMovementIntoRegion in Vue-6400 (not ready yet)
2013-09-02 17:22:28,287 DEBUG - OpenSim.Region.ClientStack.LindenUDP.LLUDPServer [LLUDPSERVER]: Received a CompleteMovementIntoRegion in Vue-6400 (not ready yet)
2013-09-02 17:22:28,490 DEBUG - OpenSim.Region.ClientStack.LindenUDP.LLUDPServer [LLUDPSERVER]: Received a CompleteMovementIntoRegion in Vue-6400 (not ready yet)
2013-09-02 17:22:29,301 DEBUG - OpenSim.Region.ClientStack.LindenUDP.LLUDPServer [LLUDPSERVER]: Handling UseCircuitCode request for circuit 1457969686 to Vue-6400 from IP 129.215.219.52:58068
2013-09-02 17:22:29,363 DEBUG - OpenSim.Region.Framework.Scenes.Scene [SCENE]: Adding new child scene presence Ai Austin e858df02-a860-4b92-937a-2b87e4ebcd6d to scene Vue-6400 at pos <128, 128, 1.5>
2013-09-02 17:22:30,159 DEBUG - OpenSim.Region.CoreModules.Avatar.Friends.HGFriendsModule [HGFRIENDS MODULE]: caching 4ab4afee-3863-4948-869a-169c0620cb62;http://gateway.bluewallvirtual.net:8002/;BlueWall [^] Slade;ee5a37db
2013-09-02 17:22:39,941 INFO - OpenSim.Framework.SynchronousRestObjectRequester [SynchronousRestObjectRequester]: Slow request 435 GET http://assets.osgrid.org/assets/1d325ea0-cf8b-4dcf-a1aa-b4c16d5292a9 [^] took 4851ms, 0ms writing,
2013-09-02 17:22:50,674 DEBUG - OpenSim.Region.Framework.Scenes.Scene [SCENE]: Found presence Ai Austin e858df02-a860-4b92-937a-2b87e4ebcd6d child in Vue-6400 after 21 waits
2013-09-02 17:22:50,674 INFO - OpenSim.Framework.Servers.HttpServer.BaseHttpServer [BASE HTTP SERVER]: Slow handling of 17 PUT /agent/e858df02-a860-4b92-937a-2b87e4ebcd6d/ from 129.215.219.138:51214 took 26582ms
2013-09-02 17:22:50,939 DEBUG - OpenSim.Region.Framework.Scenes.Scene [SCENE]: Incoming child agent update for e858df02-a860-4b92-937a-2b87e4ebcd6d in Vue-6400
2013-09-02 17:22:50,939 DEBUG - OpenSim.Region.Framework.Scenes.SceneGraph [SCENEGRAPH]: Scene graph for Vue-6400 already contains object cce13d71-8e27-499f-89b0-6baeb368ce97 in AddSceneObject()
2013-09-02 17:22:50,939 DEBUG - OpenSim.Region.Framework.Scenes.SceneGraph [SCENEGRAPH]: Scene graph for Vue-6400 already contains object 1436e121-9a51-447d-9d5f-9627ae75d6bb in AddSceneObject()
2013-09-02 17:22:50,939 DEBUG - OpenSim.Region.Framework.Scenes.SceneGraph [SCENEGRAPH]: Scene graph for Vue-6400 already contains object 940258fe-4073-4e2b-a2d7-235a078d49ab in AddSceneObject()
2013-09-02 17:22:50,955 DEBUG - OpenSim.Region.Framework.Scenes.SceneGraph [SCENEGRAPH]: Scene graph for Vue-6400 already contains object 06d631d1-afab-49d6-a621-dd3204bff69f in AddSceneObject()
2013-09-02 17:23:11,235 DEBUG - OpenSim.Region.Framework.Scenes.Scene [SCENE]: Found presence Ai Austin e858df02-a860-4b92-937a-2b87e4ebcd6d child in Vue-6400 after 21 waits
2013-09-02 17:23:11,235 INFO - OpenSim.Framework.Servers.HttpServer.BaseHttpServer [BASE HTTP SERVER]: Slow handling of 18 PUT /agent/e858df02-a860-4b92-937a-2b87e4ebcd6d/ from 129.215.219.138:51215 took 20483ms
2013-09-02 17:23:11,235 DEBUG - OpenSim.Server.Handlers.Simulation.AgentHandler [AGENT HANDLER]: >>> DELETE <<< RegionID: 2aa49e09-f1b1-4f20-8ae3-55e0399a674c; from: 129.215.219.138; auth_code: bca4bedc-1f4c-4005-b642-6289ba524569
2013-09-02 17:23:11,250 DEBUG - OpenSim.Region.ClientStack.LindenUDP.LLClientView [CLIENT]: Close has been called for Ai Austin attached to scene Vue-6400
2013-09-02 17:23:11,266 DEBUG - OpenSim.Region.Framework.Scenes.Scene [SCENE]: Removing child agent Ai Austin e858df02-a860-4b92-937a-2b87e4ebcd6d from Vue-6400
2013-09-02 17:23:11,266 DEBUG - OpenSim.Region.CoreModules.Framework.CapabilitiesModule [CAPS]: Remove caps for agent e858df02-a860-4b92-937a-2b87e4ebcd6d in region Vue-6400
2013-09-02 17:23:17,818 DEBUG - OpenSim.Region.Framework.Scenes.Scene [SCENE]: Region Vue-6400 told of incoming child agent Ai Austin e858df02-a860-4b92-937a-2b87e4ebcd6d (circuit code 1457969686, IP 129.215.219.52, viewer Firestorm-Release 4.4.2.34167, teleportflags (ViaLocation), position <128, 128, 1.5>)
2013-09-02 17:23:18,052 INFO - OpenSim.Region.Framework.Scenes.Scene [SCENE]: Region Vue-6400 authenticated and authorized incoming child agent Ai Austin e858df02-a860-4b92-937a-2b87e4ebcd6d (circuit code 1457969686)
2013-09-02 17:23:18,052 DEBUG - OpenSim.Region.OptionalModules.Avatar.Voice.VivoxVoice.VivoxVoiceModule [VivoxVoice] OnRegisterCaps: agentID e858df02-a860-4b92-937a-2b87e4ebcd6d caps OpenSim.Framework.Capabilities.Caps
2013-09-02 17:23:18,067 DEBUG - OpenSim.Region.ClientStack.Linden.EventQueueGetModule [EVENTQUEUE]: Adding new queue for agent e858df02-a860-4b92-937a-2b87e4ebcd6d in region Vue-6400
2013-09-02 17:23:18,317 DEBUG - OpenSim.Region.ClientStack.LindenUDP.LLUDPServer [LLUDPSERVER]: Received a CompleteMovementIntoRegion in Vue-6400 (not ready yet)
2013-09-02 17:23:18,317 DEBUG - OpenSim.Region.Framework.Scenes.Scene [SCENE]: Incoming child agent update for e858df02-a860-4b92-937a-2b87e4ebcd6d in Vue-6400
2013-09-02 17:23:18,317 DEBUG - OpenSim.Region.ClientStack.LindenUDP.LLUDPServer [LLUDPSERVER]: Handling UseCircuitCode request for circuit 1457969686 to Vue-6400 from IP 129.215.219.52:58068
2013-09-02 17:23:18,333 DEBUG - OpenSim.Region.Framework.Scenes.Scene [SCENE]: Adding new child scene presence Ai Austin e858df02-a860-4b92-937a-2b87e4ebcd6d to scene Vue-6400 at pos <128, 128, 1.5>
2013-09-02 17:23:18,333 DEBUG - OpenSim.Region.ClientStack.Linden.BunchOfCaps [CAPS]: Received SEED caps request in Vue-6400 for agent e858df02-a860-4b92-937a-2b87e4ebcd6d
2013-09-02 17:23:18,520 DEBUG - OpenSim.Region.Framework.Scenes.ScenePresence [SCENE PRESENCE]: Completing movement of Ai Austin into region Vue-6400 in position <128, 128, 1.5>
2013-09-02 17:23:18,520 DEBUG - OpenSim.Region.Framework.Scenes.ScenePresence [SCENE PRESENCE]: Agent Ai Austin waiting for update in Vue-6400
2013-09-02 17:23:18,567 DEBUG - OpenSim.Region.CoreModules.Avatar.Friends.HGFriendsModule [HGFRIENDS MODULE]: caching 4ab4afee-3863-4948-869a-169c0620cb62;http://gateway.bluewallvirtual.net:8002/;BlueWall [^] Slade;ee5a37db
2013-09-02 17:23:18,723 DEBUG - OpenSim.Region.Framework.Scenes.ScenePresence [SCENE PRESENCE]: Agent Ai Austin waiting for update in Vue-6400
2013-09-02 17:23:18,925 DEBUG - OpenSim.Region.Framework.Scenes.ScenePresence [SCENE PRESENCE]: Agent Ai Austin waiting for update in Vue-6400
2013-09-02 17:23:19,128 DEBUG - OpenSim.Region.Framework.Scenes.ScenePresence [SCENE PRESENCE]: Agent Ai Austin waiting for update in Vue-6400
2013-09-02 17:23:19,331 DEBUG - OpenSim.Region.Framework.Scenes.ScenePresence [SCENE PRESENCE]: Agent Ai Austin waiting for update in Vue-6400
2013-09-02 17:23:19,347 DEBUG - OpenSim.Region.Framework.Scenes.SceneGraph [SCENEGRAPH]: Scene graph for Vue-6400 already contains object cce13d71-8e27-499f-89b0-6baeb368ce97 in AddSceneObject()
2013-09-02 17:23:19,347 DEBUG - OpenSim.Region.Framework.Scenes.SceneGraph [SCENEGRAPH]: Scene graph for Vue-6400 already contains object 1436e121-9a51-447d-9d5f-9627ae75d6bb in AddSceneObject()
2013-09-02 17:23:19,347 DEBUG - OpenSim.Region.Framework.Scenes.SceneGraph [SCENEGRAPH]: Scene graph for Vue-6400 already contains object 940258fe-4073-4e2b-a2d7-235a078d49ab in AddSceneObject()
2013-09-02 17:23:19,347 DEBUG - OpenSim.Region.Framework.Scenes.SceneGraph [SCENEGRAPH]: Scene graph for Vue-6400 already contains object 06d631d1-afab-49d6-a621-dd3204bff69f in AddSceneObject()
2013-09-02 17:23:19,534 INFO - OpenSim.Region.Framework.Scenes.ScenePresence [SCENE]: Upgrading child to root agent for Ai Austin in Vue-6400
2013-09-02 17:23:19,549 DEBUG - OpenSim.Region.Framework.Scenes.ScenePresence [SCENE PRESENCE]: Restarting scripts in attachments for Ai Austin in Vue-6400
2013-09-02 17:23:19,549 DEBUG - OpenSim.Region.Framework.Scenes.SceneObjectGroup [PRIM INVENTORY]: m_scene is null. Unable to create script instances
2013-09-02 17:23:19,581 ERROR - OpenSim.Region.ClientStack.LindenUDP.LLClientView [LLCLIENTVIEW]: Caught exception while processing OpenMetaverse.Packets.CompleteAgentMovementPacket for Ai Austin, Object reference not set to an instance of an object. at OpenSim.Region.Framework.Scenes.SceneObjectPartInventory.ResumeScripts() in k:\OSGRID\opensim-56f565b\OpenSim\Region\Framework\Scenes\SceneObjectPartInventory.cs:line 1347
   at OpenSim.Region.Framework.Scenes.SceneObjectGroup.ResumeScripts() in k:\OSGRID\opensim-56f565b\OpenSim\Region\Framework\Scenes\SceneObjectGroup.Inventory.cs:line 412
   at OpenSim.Region.Framework.Scenes.ScenePresence.MakeRootAgent(Vector3 pos, Boolean isFlying) in k:\OSGRID\opensim-56f565b\OpenSim\Region\Framework\Scenes\ScenePresence.cs:line 1039
   at OpenSim.Region.Framework.Scenes.ScenePresence.CompleteMovement(IClientAPI client, Boolean openChildAgents) in k:\OSGRID\opensim-56f565b\OpenSim\Region\Framework\Scenes\ScenePresence.cs:line 1420
   at OpenSim.Region.ClientStack.LindenUDP.LLClientView.HandleCompleteAgentMovement(IClientAPI sender, Packet Pack) in k:\OSGRID\opensim-56f565b\OpenSim\Region\ClientStack\Linden\UDP\LLClientView.cs:line 6594
   at OpenSim.Region.ClientStack.LindenUDP.LLClientView.ProcessSpecificPacketAsync(Object state) in k:\OSGRID\opensim-56f565b\OpenSim\Region\ClientStack\Linden\UDP\LLClientView.cs:line 736
2013-09-02 17:23:20,376 DEBUG - OpenSim.Region.Framework.Scenes.Scene [SCENE]: Found presence Ai Austin e858df02-a860-4b92-937a-2b87e4ebcd6d root in Vue-6400 after 1 waits
2013-09-02 17:23:42,390 INFO - OpenSim.Framework.SynchronousRestObjectRequester [SynchronousRestObjectRequester]: Slow request 551 GET http://assets.osgrid.org/assets/578ddd08-0d15-4117-ad59-4147ea3f1148 [^] took 4836ms, 0ms writing,
2013-09-02 17:24:05,979 DEBUG - OpenSim.Region.Framework.Scenes.Scene [SCENE]: Region Vue-6400 told of incoming root agent Ai Austin e858df02-a860-4b92-937a-2b87e4ebcd6d (circuit code 104981825, IP 129.215.219.52, viewer Firestorm-Release 4.4.2.34167, teleportflags (ViaLogin, ViaRegionID), position <128, 128, 0>)
2013-09-02 17:24:05,995 WARN - OpenSim.Region.Framework.Scenes.Scene [SCENE]: Existing root scene presence detected for Ai Austin e858df02-a860-4b92-937a-2b87e4ebcd6d in Vue-6400 when connecting. Removing existing presence.
2013-09-02 17:24:05,995 DEBUG - OpenSim.Region.ClientStack.LindenUDP.LLClientView [CLIENT]: Close has been called for Ai Austin attached to scene Vue-6400
2013-09-02 17:24:06,837 DEBUG - OpenSim.Region.Framework.Scenes.Scene [SCENE]: Removing root agent Ai Austin e858df02-a860-4b92-937a-2b87e4ebcd6d from Vue-6400
2013-09-02 17:24:06,837 DEBUG - OpenSim.Region.CoreModules.Framework.CapabilitiesModule [CAPS]: Remove caps for agent e858df02-a860-4b92-937a-2b87e4ebcd6d in region Vue-6400
2013-09-02 17:24:06,837 DEBUG - OpenSim.Region.Framework.Scenes.SceneCommunicationService [SCENE COMMUNICATION SERVICE]: Sending close agent ID e858df02-a860-4b92-937a-2b87e4ebcd6d to Vue-Rig
2013-09-02 17:24:06,853 ERROR - OpenSim.Region.Framework.Scenes.Scene [SCENE]: Exception removing Ai Austin from Vue-6400. Cleaning up. Exception
System.NullReferenceException: Object reference not set to an instance of an object.
   at OpenSim.Region.Framework.Scenes.SceneObjectGroup.DeleteGroupFromScene(Boolean silent) in k:\OSGRID\opensim-56f565b\OpenSim\Region\Framework\Scenes\SceneObjectGroup.cs:line 1247
   at OpenSim.Region.Framework.Scenes.Scene.DeleteSceneObject(SceneObjectGroup group, Boolean silent, Boolean removeScripts) in k:\OSGRID\opensim-56f565b\OpenSim\Region\Framework\Scenes\Scene.cs:line 2393
   at OpenSim.Region.CoreModules.Avatar.Attachments.AttachmentsModule.UpdateDetachedObject(IScenePresence sp, SceneObjectGroup so, String scriptedState) in k:\OSGRID\opensim-56f565b\OpenSim\Region\CoreModules\Avatar\Attachments\AttachmentsModule.cs:line 932
   at OpenSim.Region.CoreModules.Avatar.Attachments.AttachmentsModule.DeRezAttachments(IScenePresence sp) in k:\OSGRID\opensim-56f565b\OpenSim\Region\CoreModules\Avatar\Attachments\AttachmentsModule.cs:line 359
   at OpenSim.Region.Framework.Scenes.Scene.RemoveClient(UUID agentID, Boolean closeChildAgents) in k:\OSGRID\opensim-56f565b\OpenSim\Region\Framework\Scenes\Scene.cs:line 3479
2013-09-02 17:24:06,837 DEBUG - OpenSim.Region.Framework.Scenes.SceneCommunicationService [SCENE COMMUNICATION SERVICE]: Sending close agent ID e858df02-a860-4b92-937a-2b87e4ebcd6d to Sea-Vue
2013-09-02 17:24:06,853 DEBUG - OpenSim.Services.Connectors.Simulation.SimulationServiceConnector [REMOTE SIMULATION CONNECTOR]: CloseAgent http://virtual1.aiai.ed.ac.uk:9000/agent/e858df02-a860-4b92-937a-2b87e4ebcd6d/e9d193ea-1e82-4f35-a6b3-3745c758eb84/?auth=bca4bedc-1f4c-4005-b642-6289ba524569 [^]
2013-09-02 17:24:06,868 DEBUG - OpenSim.Services.Connectors.Simulation.SimulationServiceConnector [REMOTE SIMULATION CONNECTOR]: CloseAgent http://virtual1.aiai.ed.ac.uk:9000/agent/e858df02-a860-4b92-937a-2b87e4ebcd6d/942b6318-f11f-4a18-b362-b878574297cc/?auth=bca4bedc-1f4c-4005-b642-6289ba524569 [^]
2013-09-02 17:24:07,087 DEBUG - OpenSim.Region.CoreModules.Avatar.Friends.HGStatusNotifier [HG STATUS NOTIFIER]: Notifying 1 friends in http://gateway.bluewallvirtual.net:8002/ [^]
2013-09-02 17:24:07,321 INFO - OpenSim.Region.Framework.Scenes.Scene [SCENE]: Region Vue-6400 authenticated and authorized incoming root agent Ai Austin e858df02-a860-4b92-937a-2b87e4ebcd6d (circuit code 104981825)
2013-09-02 17:24:07,321 DEBUG - OpenSim.Region.OptionalModules.Avatar.Voice.VivoxVoice.VivoxVoiceModule [VivoxVoice] OnRegisterCaps: agentID e858df02-a860-4b92-937a-2b87e4ebcd6d caps OpenSim.Framework.Capabilities.Caps
2013-09-02 17:24:07,321 DEBUG - OpenSim.Region.ClientStack.Linden.EventQueueGetModule [EVENTQUEUE]: Adding new queue for agent e858df02-a860-4b92-937a-2b87e4ebcd6d in region Vue-6400
2013-09-02 17:24:07,492 DEBUG - OpenSim.Services.Connectors.Hypergrid.UserAgentServiceConnector [USER AGENT CONNECTOR]: new connector to http://gateway.bluewallvirtual.net:8002/ [^] (http://74.237.137.28:8002/ [^])
2013-09-02 17:24:12,126 DEBUG - OpenSim.Region.ClientStack.Linden.BunchOfCaps [CAPS]: Received SEED caps request in Vue-6400 for agent e858df02-a860-4b92-937a-2b87e4ebcd6d
2013-09-02 17:24:12,126 DEBUG - OpenSim.Region.Framework.Scenes.Scene [SCENE]: Incoming client Ai Austin in region Vue-6400 via regular login. Client IP verification not performed.
2013-09-02 17:24:15,621 DEBUG - OpenSim.Region.ClientStack.LindenUDP.LLUDPServer [LLUDPSERVER]: Handling UseCircuitCode request for circuit 104981825 to Vue-6400 from IP 129.215.219.52:49541
2013-09-02 17:24:15,621 DEBUG - OpenSim.Region.Framework.Scenes.Scene [SCENE]: Adding new child scene presence Ai Austin e858df02-a860-4b92-937a-2b87e4ebcd6d to scene Vue-6400 at pos <127.643, 128.363, 26.0577>
2013-09-02 17:24:15,855 DEBUG - OpenSim.Region.CoreModules.Avatar.Friends.HGFriendsModule [HGFRIENDS MODULE]: caching 4ab4afee-3863-4948-869a-169c0620cb62;http://gateway.bluewallvirtual.net:8002/;BlueWall [^] Slade;ee5a37db
2013-09-02 17:24:15,886 DEBUG - OpenSim.Region.Framework.Scenes.ScenePresence [SCENE PRESENCE]: Completing movement of Ai Austin into region Vue-6400 in position <127.643, 128.363, 26.0577>
2013-09-02 17:24:15,902 INFO - OpenSim.Region.Framework.Scenes.ScenePresence [SCENE]: Upgrading child to root agent for Ai Austin in Vue-6400
2013-09-02 17:24:15,902 DEBUG - OpenSim.Region.CoreModules.Framework.InventoryAccess.HGInventoryAccessModule [HGScene]: RezObject itemID=60024e35-cf7b-4b21-b30c-6b33f341861f fromTaskID=e858df02-a860-4b92-937a-2b87e4ebcd6d
2013-09-02 17:24:16,104 DEBUG - OpenSim.Region.CoreModules.Avatar.Friends.HGStatusNotifier [HG STATUS NOTIFIER]: Notifying 1 friends in http://gateway.bluewallvirtual.net:8002/ [^]
2013-09-02 17:24:16,619 DEBUG - OpenSim.Region.CoreModules.World.LightShare.LightShareModule [WINDLIGHT]: Sending windlight scene to new client
2013-09-02 17:24:16,650 DEBUG - OpenSim.Region.CoreModules.Avatar.InstantMessage.MuteListModule [MUTE LIST] Got mute list request for crc 0
2013-09-02 17:24:17,540 DEBUG - OpenSim.Region.CoreModules.Framework.EntityTransfer.EntityTransferModule [ENTITY TRANSFER MODULE]: Informing Ai Austin e858df02-a860-4b92-937a-2b87e4ebcd6d about neighbour OpenVCE 129.215.219.78:9002 at (6400,6399)
2013-09-02 17:24:17,540 DEBUG - OpenSim.Region.Framework.Scenes.Scene [SCENE]: Region OpenVCE told of incoming child agent Ai Austin e858df02-a860-4b92-937a-2b87e4ebcd6d (circuit code 104981825, IP 129.215.219.52, viewer Firestorm-Release 4.4.2.34167, teleportflags (Default), position <127.6428, 384.3631, 25.98225>)
2013-09-02 17:24:17,774 INFO - OpenSim.Region.Framework.Scenes.Scene [SCENE]: Region OpenVCE authenticated and authorized incoming child agent Ai Austin e858df02-a860-4b92-937a-2b87e4ebcd6d (circuit code 104981825)
2013-09-02 17:24:17,774 DEBUG - OpenSim.Region.OptionalModules.Avatar.Voice.VivoxVoice.VivoxVoiceModule [VivoxVoice] OnRegisterCaps: agentID e858df02-a860-4b92-937a-2b87e4ebcd6d caps OpenSim.Framework.Capabilities.Caps
2013-09-02 17:24:17,789 DEBUG - OpenSim.Region.ClientStack.Linden.EventQueueGetModule [EVENTQUEUE]: Adding new queue for agent e858df02-a860-4b92-937a-2b87e4ebcd6d in region OpenVCE
2013-09-02 17:24:17,789 DEBUG - OpenSim.Region.CoreModules.Framework.EntityTransfer.EntityTransferModule [ENTITY TRANSFER MODULE]: Vue-6400 is sending Ai Austin EnableSimulator for neighbour region OpenVCE @ 7036874419404544 and EstablishAgentCommunication with seed cap http://virtual4.aiai.ed.ac.uk:9000/CAPS/12d2982d-892d-45d3-adcc-e269bd5463900000/ [^]
2013-09-02 17:24:17,789 DEBUG - OpenSim.Region.CoreModules.Framework.EntityTransfer.EntityTransferModule [ENTITY TRANSFER MODULE]: Completed inform Ai Austin e858df02-a860-4b92-937a-2b87e4ebcd6d about neighbour 129.215.219.78:9002
2013-09-02 17:24:18,148 DEBUG - OpenSim.Region.ClientStack.LindenUDP.LLUDPServer [LLUDPSERVER]: Handling UseCircuitCode request for circuit 104981825 to OpenVCE from IP 129.215.219.52:49541
2013-09-02 17:24:18,148 DEBUG - OpenSim.Region.Framework.Scenes.Scene [SCENE]: Adding new child scene presence Ai Austin e858df02-a860-4b92-937a-2b87e4ebcd6d to scene OpenVCE at pos <127.6428, 384.3631, 25.98225>
2013-09-02 17:24:18,304 DEBUG - OpenSim.Region.CoreModules.Framework.EntityTransfer.EntityTransferModule [ENTITY TRANSFER MODULE]: Informing Ai Austin e858df02-a860-4b92-937a-2b87e4ebcd6d about neighbour Edinburgh 129.215.219.138:9010 at (6400,6401)
2013-09-02 17:24:18,304 DEBUG - OpenSim.Services.Connectors.Simulation.SimulationServiceConnector [REMOTE SIMULATION CONNECTOR]: Creating agent at http://virtual1.aiai.ed.ac.uk:9000/ [^]
2013-09-02 17:24:18,320 DEBUG - OpenSim.Region.ClientStack.Linden.BunchOfCaps [CAPS]: Received SEED caps request in OpenVCE for agent e858df02-a860-4b92-937a-2b87e4ebcd6d
2013-09-02 17:24:18,351 DEBUG - OpenSim.Region.CoreModules.Avatar.InstantMessage.OfflineMessageModule [OFFLINE MESSAGING]: Retrieving stored messages for e858df02-a860-4b92-937a-2b87e4ebcd6d
2013-09-02 17:24:18,694 DEBUG - OpenSim.Region.CoreModules.Framework.EntityTransfer.EntityTransferModule [ENTITY TRANSFER MODULE]: Vue-6400 is sending Ai Austin EnableSimulator for neighbour region Edinburgh @ 7036874419405056 and EstablishAgentCommunication with seed cap http://virtual1.aiai.ed.ac.uk:9000/CAPS/6be13494-8ecb-46a3-bb78-d1b85830fb980000/ [^]
2013-09-02 17:24:18,694 DEBUG - OpenSim.Region.CoreModules.Framework.EntityTransfer.EntityTransferModule [ENTITY TRANSFER MODULE]: Completed inform Ai Austin e858df02-a860-4b92-937a-2b87e4ebcd6d about neighbour 129.215.219.138:9010
2013-09-02 17:24:19,209 DEBUG - OpenSim.Region.CoreModules.Framework.EntityTransfer.EntityTransferModule [ENTITY TRANSFER MODULE]: Informing Ai Austin e858df02-a860-4b92-937a-2b87e4ebcd6d about neighbour Sea-Vue 129.215.219.138:9009 at (6401,6399)
2013-09-02 17:24:19,209 DEBUG - OpenSim.Services.Connectors.Simulation.SimulationServiceConnector [REMOTE SIMULATION CONNECTOR]: Creating agent at http://virtual1.aiai.ed.ac.uk:9000/ [^]
2013-09-02 17:24:19,458 DEBUG - OpenSim.Region.CoreModules.Framework.EntityTransfer.EntityTransferModule [ENTITY TRANSFER MODULE]: Vue-6400 is sending Ai Austin EnableSimulator for neighbour region Sea-Vue @ 7037973931032320 and EstablishAgentCommunication with seed cap http://virtual1.aiai.ed.ac.uk:9000/CAPS/ed4e6562-1d01-4aaa-a77a-e055c753feda0000/ [^]
2013-09-02 17:24:19,458 DEBUG - OpenSim.Region.CoreModules.Framework.EntityTransfer.EntityTransferModule [ENTITY TRANSFER MODULE]: Completed inform Ai Austin e858df02-a860-4b92-937a-2b87e4ebcd6d about neighbour 129.215.219.138:9009
2013-09-02 17:24:19,677 DEBUG - OpenSim.Region.CoreModules.Framework.InventoryAccess.HGInventoryAccessModule [HGScene]: RezObject itemID=761cc059-a095-40d7-b263-e032bb268e28 fromTaskID=e858df02-a860-4b92-937a-2b87e4ebcd6d
2013-09-02 17:24:19,973 DEBUG - OpenSim.Region.CoreModules.Framework.EntityTransfer.EntityTransferModule [ENTITY TRANSFER MODULE]: Informing Ai Austin e858df02-a860-4b92-937a-2b87e4ebcd6d about neighbour Vue-Rig 129.215.219.138:9001 at (6401,6400)
2013-09-02 17:24:19,973 DEBUG - OpenSim.Services.Connectors.Simulation.SimulationServiceConnector [REMOTE SIMULATION CONNECTOR]: Creating agent at http://virtual1.aiai.ed.ac.uk:9000/ [^]
2013-09-02 17:24:20,223 DEBUG - OpenSim.Region.CoreModules.Framework.EntityTransfer.EntityTransferModule [ENTITY TRANSFER MODULE]: Vue-6400 is sending Ai Austin EnableSimulator for neighbour region Vue-Rig @ 7037973931032576 and EstablishAgentCommunication with seed cap http://virtual1.aiai.ed.ac.uk:9000/CAPS/e2d3d960-0ba7-4f99-87b2-fc19f8201a4d0000/ [^]
2013-09-02 17:24:20,223 DEBUG - OpenSim.Region.CoreModules.Framework.EntityTransfer.EntityTransferModule [ENTITY TRANSFER MODULE]: Completed inform Ai Austin e858df02-a860-4b92-937a-2b87e4ebcd6d about neighbour 129.215.219.138:9001
2013-09-02 17:24:21,408 INFO - OpenSim.Framework.SynchronousRestObjectRequester [SynchronousRestObjectRequester]: Slow request 606 GET http://assets.osgrid.org/assets/75d90bb0-20da-4c77-9e93-b1a396c14e7f [^] took 3354ms, 0ms writing,
2013-09-02 17:24:22,360 DEBUG - OpenSim.Region.CoreModules.Framework.InventoryAccess.HGInventoryAccessModule [HGScene]: RezObject itemID=6a47e611-5fc9-4ef1-8e53-a4112fb6e1df fromTaskID=e858df02-a860-4b92-937a-2b87e4ebcd6d
2013-09-02 17:24:26,603 INFO - OpenSim.Framework.SynchronousRestObjectRequester [SynchronousRestObjectRequester]: Slow request 624 GET http://assets.osgrid.org/assets/dd28dcd6-73d9-4d20-a315-1fa3bf7c3a78 [^] took 5195ms, 0ms writing,
2013-09-02 17:24:27,914 INFO - OpenSim.Framework.SynchronousRestObjectRequester [SynchronousRestObjectRequester]: Slow request 636 GET http://assets.osgrid.org/assets/85b7f602-2ed0-4863-bd2b-c011599dc60b [^] took 5086ms, 0ms writing,
2013-09-02 17:24:28,350 DEBUG - OpenSim.Region.CoreModules.Framework.InventoryAccess.HGInventoryAccessModule [HGScene]: RezObject itemID=97f0db3b-37de-4a61-9493-5747e28d790d fromTaskID=e858df02-a860-4b92-937a-2b87e4ebcd6d
2013-09-02 17:24:29,708 INFO - OpenSim.Framework.SynchronousRestObjectRequester [SynchronousRestObjectRequester]: Slow request 637 GET http://assets.osgrid.org/assets/eca14fc7-41f4-4fa5-be13-f1fd8944eda4 [^] took 6740ms, 0ms writing,
2013-09-02 17:24:30,098 INFO - OpenSim.Framework.SynchronousRestObjectRequester [SynchronousRestObjectRequester]: Slow request 645 GET http://assets.osgrid.org/assets/107ad854-3cc9-422b-90ac-20a5bdb22c70 [^] took 6802ms, 0ms writing,
2013-09-02 17:24:30,176 INFO - OpenSim.Framework.SynchronousRestObjectRequester [SynchronousRestObjectRequester]: Slow request 652 GET http://assets.osgrid.org/assets/62229295-7acd-48c9-b215-086e5175d7e9 [^] took 6240ms, 0ms writing,
2013-09-02 17:24:31,392 INFO - OpenSim.Framework.SynchronousRestObjectRequester [SynchronousRestObjectRequester]: Slow request 654 GET http://assets.osgrid.org/assets/88418bcb-af24-4436-a9a6-b71c607eb478 [^] took 7004ms, 0ms writing,
2013-09-02 17:24:31,736 INFO - OpenSim.Framework.SynchronousRestObjectRequester [SynchronousRestObjectRequester]: Slow request 663 GET http://assets.osgrid.org/assets/d0737050-6dc8-4c97-a99b-3a41bdc61d92 [^] took 6100ms, 0ms writing,
2013-09-02 17:24:31,876 INFO - OpenSim.Framework.SynchronousRestObjectRequester [SynchronousRestObjectRequester]: Slow request 655 GET http://assets.osgrid.org/assets/8957684a-838c-407d-bd52-b964c3b602b8 [^] took 7457ms, 0ms writing,
2013-09-02 17:24:32,952 INFO - OpenSim.Framework.SynchronousRestObjectRequester [SynchronousRestObjectRequester]: Slow request 666 GET http://assets.osgrid.org/assets/70a8b364-0119-46b7-96fa-aa47b9b884fa [^] took 6349ms, 0ms writing,
2013-09-02 17:24:33,077 INFO - OpenSim.Framework.SynchronousRestObjectRequester [SynchronousRestObjectRequester]: Slow request 665 GET http://assets.osgrid.org/assets/7f23e7b2-1e59-4a62-9464-3a0aae13733a [^] took 6786ms, 0ms writing,
2013-09-02 17:24:35,620 INFO - OpenSim.Framework.SynchronousRestObjectRequester [SynchronousRestObjectRequester]: Slow request 684 GET http://assets.osgrid.org/assets/ce1bfa1f-459e-4bd9-90e3-255c324d6228 [^] took 5944ms, 0ms writing,
2013-09-02 17:24:38,662 INFO - OpenSim.Framework.SynchronousRestObjectRequester [SynchronousRestObjectRequester]: Slow request 705 GET http://assets.osgrid.org/assets/254e4159-595d-4b90-9f6c-e41ef8ca8873 [^] took 5413ms, 0ms writing,
2013-09-02 17:24:39,270 INFO - OpenSim.Framework.SynchronousRestObjectRequester [SynchronousRestObjectRequester]: Slow request 704 GET http://assets.osgrid.org/assets/201aa8c0-9cf3-49fc-af5f-9562e70ae9b3 [^] took 6302ms, 0ms writing,
2013-09-02 17:24:45,011 INFO - OpenSim.Framework.SynchronousRestObjectRequester [SynchronousRestObjectRequester]: Slow request 723 GET http://assets.osgrid.org/assets/834b9c11-b37b-4f5d-8385-d32e8299032b [^] took 5741ms, 0ms writing,
2013-09-02 17:24:50,721 INFO - OpenSim.Framework.SynchronousRestObjectRequester [SynchronousRestObjectRequester]: Slow request 738 GET http://assets.osgrid.org/assets/c7dd5973-271d-4a30-8ae0-bc49b76fdfdb [^] took 5694ms, 0ms writing,
2013-09-02 17:24:57,054 INFO - OpenSim.Framework.SynchronousRestObjectRequester [SynchronousRestObjectRequester]: Slow request 758 GET http://assets.osgrid.org/assets/e5c88da2-ce28-48e3-8e22-2f2c6f03e0b3 [^] took 3838ms, 0ms writing,
2013-09-02 17:25:18,287 INFO - OpenSim.Framework.SynchronousRestObjectRequester [SynchronousRestObjectRequester]: Slow request 819 GET http://assets.osgrid.org/assets/995f34c7-5f27-430a-8def-6d0185803a26 [^] took 3073ms, 0ms writing,
2013-09-02 17:25:19,301 INFO - OpenSim.Framework.SynchronousRestObjectRequester [SynchronousRestObjectRequester]: Slow request 821 GET http://assets.osgrid.org/assets/0513e849-8231-4f91-a972-d2b143ca0c20 [^] took 3603ms, 0ms writing,
2013-09-02 17:25:19,519 INFO - OpenSim.Framework.SynchronousRestObjectRequester [SynchronousRestObjectRequester]: Slow request 822 GET http://assets.osgrid.org/assets/27ca2fa3-1ad6-44fe-8eda-50a40be38d7f [^] took 3604ms, 0ms writing,
2013-09-02 17:25:19,800 INFO - OpenSim.Framework.SynchronousRestObjectRequester [SynchronousRestObjectRequester]: Slow request 825 GET http://assets.osgrid.org/assets/71d025bd-5d0e-4138-bb1c-6d349b18873f [^] took 3432ms, 0ms writing,
2013-09-02 17:25:20,081 INFO - OpenSim.Framework.SynchronousRestObjectRequester [SynchronousRestObjectRequester]: Slow request 823 GET http://assets.osgrid.org/assets/5dba3804-5bfb-4048-b5bf-b3170fc58d37 [^] took 3822ms, 0ms writing,
2013-09-02 17:25:20,097 INFO - OpenSim.Framework.SynchronousRestObjectRequester [SynchronousRestObjectRequester]: Slow request 826 GET http://assets.osgrid.org/assets/152921df-b545-49c3-8886-851e2d4c4520 [^] took 3073ms, 0ms writing,
2013-09-02 17:25:20,721 INFO - OpenSim.Framework.SynchronousRestObjectRequester [SynchronousRestObjectRequester]: Slow request 827 GET http://assets.osgrid.org/assets/3a60e36b-41e1-4354-a241-09b14ac85011 [^] took 3323ms, 0ms writing,
2013-09-02 17:25:21,735 INFO - OpenSim.Framework.SynchronousRestObjectRequester [SynchronousRestObjectRequester]: Slow request 824 GET http://assets.osgrid.org/assets/81abf7dc-11e2-49d3-b8b0-1840f6afdce6 [^] took 5367ms, 0ms writing,
2013-09-02 17:25:24,231 INFO - OpenSim.Framework.SynchronousRestObjectRequester [SynchronousRestObjectRequester]: Slow request 832 GET http://assets.osgrid.org/assets/df057b1b-e22c-4dfa-89bf-0ee811f0f832 [^] took 3307ms, 0ms writing,
2013-09-02 17:25:30,190 INFO - OpenSim.Region.ClientStack.LindenUDP.LLClientView [CLIENT]: Got a logout request for Ai Austin in Vue-6400
2013-09-02 17:25:30,205 DEBUG - OpenSim.Region.ClientStack.LindenUDP.LLClientView [CLIENT]: Close has been called for Ai Austin attached to scene Vue-6400
2013-09-02 17:25:30,939 DEBUG - OpenSim.Region.Framework.Scenes.Scene [SCENE]: Removing root agent Ai Austin e858df02-a860-4b92-937a-2b87e4ebcd6d from Vue-6400
2013-09-02 17:25:30,954 DEBUG - OpenSim.Region.CoreModules.Framework.CapabilitiesModule [CAPS]: Remove caps for agent e858df02-a860-4b92-937a-2b87e4ebcd6d in region Vue-6400
2013-09-02 17:25:30,954 DEBUG - OpenSim.Region.Framework.Scenes.SceneCommunicationService [SCENE COMMUNICATION SERVICE]: Sending close agent ID e858df02-a860-4b92-937a-2b87e4ebcd6d to OpenVCE
2013-09-02 17:25:30,954 DEBUG - OpenSim.Region.ClientStack.LindenUDP.LLClientView [CLIENT]: Close has been called for Ai Austin attached to scene OpenVCE
2013-09-02 17:25:30,954 DEBUG - OpenSim.Region.Framework.Scenes.Scene [SCENE]: Removing child agent Ai Austin e858df02-a860-4b92-937a-2b87e4ebcd6d from OpenVCE
2013-09-02 17:25:30,970 DEBUG - OpenSim.Region.CoreModules.Framework.CapabilitiesModule [CAPS]: Remove caps for agent e858df02-a860-4b92-937a-2b87e4ebcd6d in region OpenVCE
2013-09-02 17:25:30,985 DEBUG - OpenSim.Region.Framework.Scenes.SceneCommunicationService [SCENE COMMUNICATION SERVICE]: Sending close agent ID e858df02-a860-4b92-937a-2b87e4ebcd6d to Vue-Rig
2013-09-02 17:25:31,001 DEBUG - OpenSim.Services.Connectors.Simulation.SimulationServiceConnector [REMOTE SIMULATION CONNECTOR]: CloseAgent http://virtual1.aiai.ed.ac.uk:9000/agent/e858df02-a860-4b92-937a-2b87e4ebcd6d/e9d193ea-1e82-4f35-a6b3-3745c758eb84/?auth=66789b15-46e1-4903-b00b-3a5bd4a16940 [^]
2013-09-02 17:25:30,985 DEBUG - OpenSim.Region.Framework.Scenes.SceneCommunicationService [SCENE COMMUNICATION SERVICE]: Sending close agent ID e858df02-a860-4b92-937a-2b87e4ebcd6d to Sea-Vue
2013-09-02 17:25:31,001 DEBUG - OpenSim.Services.Connectors.Simulation.SimulationServiceConnector [REMOTE SIMULATION CONNECTOR]: CloseAgent http://virtual1.aiai.ed.ac.uk:9000/agent/e858df02-a860-4b92-937a-2b87e4ebcd6d/942b6318-f11f-4a18-b362-b878574297cc/?auth=66789b15-46e1-4903-b00b-3a5bd4a16940 [^]
2013-09-02 17:25:30,954 DEBUG - OpenSim.Region.Framework.Scenes.SceneCommunicationService [SCENE COMMUNICATION SERVICE]: Sending close agent ID e858df02-a860-4b92-937a-2b87e4ebcd6d to Edinburgh
2013-09-02 17:25:31,017 DEBUG - OpenSim.Services.Connectors.Simulation.SimulationServiceConnector [REMOTE SIMULATION CONNECTOR]: CloseAgent http://virtual1.aiai.ed.ac.uk:9000/agent/e858df02-a860-4b92-937a-2b87e4ebcd6d/98b848b4-64c0-4f07-a4a2-9e92b75cb106/?auth=66789b15-46e1-4903-b00b-3a5bd4a16940 [^]
2013-09-02 17:25:31,188 DEBUG - OpenSim.Region.CoreModules.Avatar.Friends.HGStatusNotifier [HG STATUS NOTIFIER]: Notifying 1 friends in http://gateway.bluewallvirtual.net:8002/ [^]

TagsNo tags attached.
Git Revision or version numberr/23560
Run Mode Grid (Multiple Regions per Sim)
Physics EngineODE
Script Engine
Environment.NET / Windows64
Mono VersionNone
ViewerFirestorm 4.4.2 OS
Attached Filestxt file icon 2013-09-02-OpenSim-Log-OSGrid-TP-Failing.txt [^] (35,408 bytes) 2013-09-03 04:11 [Show Content]
jpg file icon Teleport Failed.jpg [^] (20,718 bytes) 2013-09-19 21:34


zip file icon Kens_Log_Files.zip [^] (35,250 bytes) 2013-09-20 11:45
txt file icon log Aine tp tests 2013-09-20.txt [^] (58,337 bytes) 2013-09-20 19:03 [Show Content]
jpg file icon Windows-Vista-Firewall-for-OpenSim.jpg [^] (146,134 bytes) 2013-09-23 05:07

- Relationships
related to 0007774new Complex avatar with mesh parts fails to complete HG teleport 

-  Notes
(0024317)
Robert Adams (administrator)
2013-09-08 15:53

I have seen this a lot while debugging hypergrid and DSG. The tp will start but does not complete. The result is the avatar is in the original region but the attachements have been removed. A relog is required.
(0024318)
Mata Hari (reporter)
2013-09-08 17:34

I have been experiencing this issue as well for every HG teleport I have attempted for perhaps the last 2 weeks or so. I am getting it with my current build (r/23611 opensim-08874d6) and also had it with my previous one (r/23560 opensim-56f565b). I do not recall if I also had it with the build prior to that one (r/23546 opensim-5cd7bc2) but it hasn't been an issue for me for much longer than that.

Currently: any tp I make to regions within my own grid (a HG standalone with multiple regions) works flawlessly and very fast. Any attempt I make to HG tp to another grid will *always* fail regardless of whether I link via map search and then tp or whether I use a landmark.

Further, when the tp attempt fails and times out, I reappear on the region with all of my attachments missing. They are not listed as "worn" items. When I locate them in my inventory they are not highlighted and if I attempt to re-wear them the attempt is completely ignored (no message in the viewer or on the console). I can change to a different outfit and wear any other attachments, but the only way to be able to wear one of the missing attachments is to relog.

Once the original HG tp fails, I can then immediately re-attempt the exact same HG tp and so far it will always succeed (rapidly) and a rebake at the destination will cause the missing attachments to reappear.

I can also attempt a tp to another region inside my own grid and there seems to be about a 50:50 chance of it succeeded (the longer I wait after the failed attempt, the more likely it seems that the in-grid attempt will succeed)

I finally made a little time tonight do a test (sorry it took so long) and pull the relevant lines from my console log:

This is the log from my attempt to HGtp via landmark from my home region to OSG's Sandbox Plaza. This landmark has been working flawlessly for months until the last couple of weeks. Viewer is Firestorm (current Opensim release of 4.2.2)


#####################################
1st attempt which fails and times out
#####################################

2013-09-08 20:06:41,851 DEBUG - OpenSim.Region.CoreModules.Framework.EntityTransfer.HGEntityTransferModule [HG ENTITY TRANSFER MODULE]: Teleporting agent via landmark to http://hg.osgrid.org:80 [^] region e675e480-f2f8-11dd-87af-0800200c9a66 position <134.5, 117.5, 4953.516>
2013-09-08 20:06:41,851 DEBUG - OpenSim.Services.Connectors.Hypergrid.GatekeeperServiceConnector [GATEKEEPER SERVICE CONNECTOR]: contacting http://hg.osgrid.org:80/ [^]
2013-09-08 20:06:42,001 DEBUG - OpenSim.Region.CoreModules.Framework.EntityTransfer.EntityTransferModule [ENTITY TRANSFER MODULE]: Teleporting Aine Caoimhe ce40214d-7737-47f5-af49-b685bfbb5dec from Paramour to http://hg.osgrid.org:80/ [^] (http://plaza08.osgrid.org:9303/ [^]) Sandbox Plaza/<134.5, 117.5, 4953.516>
2013-09-08 20:06:42,241 DEBUG - OpenSim.Services.Connectors.Simulation.SimulationServiceConnector [REMOTE SIMULATION CONNECTOR]: QueryAccess to http://plaza08.osgrid.org:9303/agent/ce40214d-7737-47f5-af49-b685bfbb5dec/e675e480-f2f8-11dd-87af-0800200c9a66/ [^] returned True, reason , version SIMULATION/0.2 (SIMULATION/0.2)
2013-09-08 20:06:42,251 DEBUG - OpenSim.Region.CoreModules.Framework.EntityTransfer.EntityTransferModule [ENTITY TRANSFER MODULE]: Destination is running version SIMULATION/0.2
2013-09-08 20:06:42,251 DEBUG - OpenSim.Region.CoreModules.Framework.EntityTransfer.HGEntityTransferModule [HG ENTITY TRANSFER MODULE]: CreateAgent http://hg.osgrid.org:80/ [^] http://plaza08.osgrid.org:9303/ [^]
2013-09-08 20:06:42,251 DEBUG - OpenSim.Services.HypergridService.UserAgentService [USER AGENT SERVICE]: Request to login user Aine Caoimhe (@stored IP) to grid http://hg.osgrid.org:80/ [^]
2013-09-08 20:06:42,261 DEBUG - OpenSim.Services.HypergridService.UserAgentService [USER AGENT SERVICE]: this grid: http://aine.x64.me:9000/, [^] desired grid: http://hg.osgrid.org:80/, [^] desired region: e675e480-f2f8-11dd-87af-0800200c9a66
2013-09-08 20:06:42,271 DEBUG - OpenSim.Services.Connectors.Simulation.SimulationServiceConnector [REMOTE SIMULATION CONNECTOR]: Creating agent at http://hg.osgrid.org:80/ [^]
2013-09-08 20:06:42,721 DEBUG - OpenSim.Services.HypergridService.UserAgentService [USER AGENT SERVICE]: Verifying agent token http://hg.osgrid.org:80/;bdec737a-ea4b-44ff-bc6c-639024124fc6 [^] against http://hg.osgrid.org:80/;bdec737a-ea4b-44ff-bc6c-639024124fc6 [^]
2013-09-08 20:06:42,851 DEBUG - OpenSim.Services.HypergridService.UserAgentService [USER AGENT SERVICE]: Gatekeeper sees me as 99.225.68.153
2013-09-08 20:06:42,861 DEBUG - OpenSim.Region.CoreModules.Framework.InventoryAccess.HGInventoryAccessModule [HG INVENTORY ACCESS MODULE]: Changing root inventory for user Aine Caoimhe
2013-09-08 20:06:42,871 DEBUG - OpenSim.Region.CoreModules.Framework.EntityTransfer.EntityTransferModule [ENTITY TRANSFER MODULE]: Determined that region Sandbox Plaza at 0,0 needs new child agent for agent Aine Caoimhe from Paramour
2013-09-08 20:06:42,871 DEBUG - OpenSim.Region.CoreModules.Framework.EntityTransfer.EntityTransferModule [ENTITY TRANSFER MODULE]: Sending new CAPS seed url http://plaza08.osgrid.org:9303/CAPS/934b97bb-6f18-4a7f-b895-7466e907c0860000/ [^] from Paramour to Aine Caoimhe
2013-09-08 20:06:43,621 DEBUG - OpenSim.Services.HypergridService.UserAgentService [USER AGENT SERVICE]: Verifying Client session f506084b-533b-4317-9af4-f123a2ebdeec with reported IP 99.225.68.153.
2013-09-08 20:06:43,621 DEBUG - OpenSim.Services.HypergridService.UserAgentService [USER AGENT SERVICE]: Comparing 99.225.68.153 with login IP 99.225.68.153 and MyIP 99.225.68.153; result is True
2013-09-08 20:06:47,581 DEBUG - OpenSim.Region.CoreModules.Framework.UserManagement.UserManagementModule [USER MANAGEMENT MODULE]: No grid user found for 0402b37e-3c2f-cd89-2851-977c2877bdf2
2013-09-08 20:06:47,851 DEBUG - OpenSim.Region.CoreModules.Framework.UserManagement.UserManagementModule [USER MANAGEMENT MODULE]: No grid user found for 0402b37e-3c2f-cd89-2851-977c2877bdf2
2013-09-08 20:06:47,851 DEBUG - OpenSim.Region.CoreModules.Framework.UserManagement.UserManagementModule [USER MANAGEMENT MODULE]: Sending Unknown UserUMMTGUN8 for 0402b37e-3c2f-cd89-2851-977c2877bdf2 to Aine Caoimhe since no bound name found
2013-09-08 20:07:14,791 INFO - OpenSim.Framework.WebUtil [WEB UTIL]: Slow ServiceOSD request 15 PUT http://plaza08.osgrid.org:9303/agent/ce40214d-7737-47f5-af49-b685bfbb5dec/ [^] took 31825ms, 765ms writing, {"message_type":"AgentData","region_id":"f3c6f1b0-b5d1-11e2-9e96-0800200c9a66","circuit_code":"0","a
2013-09-08 20:07:46,701 INFO - OpenSim.Framework.WebUtil [WEB UTIL]: Slow ServiceOSD request 16 PUT http://plaza08.osgrid.org:9303/agent/ce40214d-7737-47f5-af49-b685bfbb5dec/ [^] took 31902ms, 280ms writing, {"message_type":"AgentData","region_id":"f3c6f1b0-b5d1-11e2-9e96-0800200c9a66","circuit_code":"0","a
2013-09-08 20:07:46,711 WARN - OpenSim.Region.CoreModules.Framework.EntityTransfer.EntityTransferModule [ENTITY TRANSFER MODULE]: UpdateAgent failed on teleport of Aine Caoimhe to Sandbox Plaza. Keeping avatar in Paramour
2013-09-08 20:07:46,721 DEBUG - OpenSim.Services.Connectors.Simulation.SimulationServiceConnector [REMOTE SIMULATION CONNECTOR]: CloseAgent http://plaza08.osgrid.org:9303/agent/ce40214d-7737-47f5-af49-b685bfbb5dec/e675e480-f2f8-11dd-87af-0800200c9a66/?auth=f506084b-533b-4317-9af4-f123a2ebdeec [^]
2013-09-08 20:07:46,861 DEBUG - OpenSim.Region.CoreModules.Framework.InventoryAccess.HGInventoryAccessModule [HG INVENTORY ACCESS MODULE]: Restoring root folder for local user Aine Caoimhe
2013-09-08 20:07:46,871 DEBUG - OpenSim.Region.CoreModules.Framework.EntityTransfer.EntityTransferStateMachine [ENTITY TRANSFER STATE MACHINE]: Agent ce40214d-7737-47f5-af49-b685bfbb5dec cleared from transit in Paramour

#######################################################################
Attempt has now timed out. All attachments I was wearing have disappeared. I now make the second attempt to tp to the same location using the same landmark
#######################################################################

2013-09-08 20:08:10,591 DEBUG - OpenSim.Region.CoreModules.Framework.EntityTransfer.HGEntityTransferModule [HG ENTITY TRANSFER MODULE]: Teleporting agent via landmark to http://hg.osgrid.org:80 [^] region e675e480-f2f8-11dd-87af-0800200c9a66 position <134.5, 117.5, 4953.516>
2013-09-08 20:08:10,601 DEBUG - OpenSim.Services.Connectors.Hypergrid.GatekeeperServiceConnector [GATEKEEPER SERVICE CONNECTOR]: contacting http://hg.osgrid.org:80/ [^]
2013-09-08 20:08:10,801 DEBUG - OpenSim.Region.CoreModules.Framework.EntityTransfer.EntityTransferModule [ENTITY TRANSFER MODULE]: Teleporting Aine Caoimhe ce40214d-7737-47f5-af49-b685bfbb5dec from Paramour to http://hg.osgrid.org:80/ [^] (http://plaza08.osgrid.org:9303/ [^]) Sandbox Plaza/<134.5, 117.5, 4953.516>
2013-09-08 20:08:11,011 DEBUG - OpenSim.Services.Connectors.Simulation.SimulationServiceConnector [REMOTE SIMULATION CONNECTOR]: QueryAccess to http://plaza08.osgrid.org:9303/agent/ce40214d-7737-47f5-af49-b685bfbb5dec/e675e480-f2f8-11dd-87af-0800200c9a66/ [^] returned True, reason , version SIMULATION/0.2 (SIMULATION/0.2)
2013-09-08 20:08:11,011 DEBUG - OpenSim.Region.CoreModules.Framework.EntityTransfer.EntityTransferModule [ENTITY TRANSFER MODULE]: Destination is running version SIMULATION/0.2
2013-09-08 20:08:11,011 DEBUG - OpenSim.Region.CoreModules.Framework.EntityTransfer.HGEntityTransferModule [HG ENTITY TRANSFER MODULE]: CreateAgent http://hg.osgrid.org:80/ [^] http://plaza08.osgrid.org:9303/ [^]
2013-09-08 20:08:11,021 DEBUG - OpenSim.Services.HypergridService.UserAgentService [USER AGENT SERVICE]: Request to login user Aine Caoimhe (@stored IP) to grid http://hg.osgrid.org:80/ [^]
2013-09-08 20:08:11,021 DEBUG - OpenSim.Services.HypergridService.UserAgentService [USER AGENT SERVICE]: this grid: http://aine.x64.me:9000/, [^] desired grid: http://hg.osgrid.org:80/, [^] desired region: e675e480-f2f8-11dd-87af-0800200c9a66
2013-09-08 20:08:11,021 DEBUG - OpenSim.Services.Connectors.Simulation.SimulationServiceConnector [REMOTE SIMULATION CONNECTOR]: Creating agent at http://hg.osgrid.org:80/ [^]
2013-09-08 20:08:11,351 DEBUG - OpenSim.Services.HypergridService.UserAgentService [USER AGENT SERVICE]: Verifying agent token http://hg.osgrid.org:80/;3ae16d12-5892-4c6d-90a9-7b0b191e932d [^] against http://hg.osgrid.org:80/;3ae16d12-5892-4c6d-90a9-7b0b191e932d [^]
2013-09-08 20:08:11,451 DEBUG - OpenSim.Services.HypergridService.UserAgentService [USER AGENT SERVICE]: Gatekeeper sees me as 99.225.68.153
2013-09-08 20:08:11,461 DEBUG - OpenSim.Region.CoreModules.Framework.InventoryAccess.HGInventoryAccessModule [HG INVENTORY ACCESS MODULE]: Changing root inventory for user Aine Caoimhe
2013-09-08 20:08:11,461 DEBUG - OpenSim.Region.CoreModules.Framework.EntityTransfer.EntityTransferModule [ENTITY TRANSFER MODULE]: Determined that region Sandbox Plaza at 0,0 needs new child agent for agent Aine Caoimhe from Paramour
2013-09-08 20:08:11,471 DEBUG - OpenSim.Region.CoreModules.Framework.EntityTransfer.EntityTransferModule [ENTITY TRANSFER MODULE]: Sending new CAPS seed url http://plaza08.osgrid.org:9303/CAPS/da25f47c-beda-4138-bc98-1b95ebec43790000/ [^] from Paramour to Aine Caoimhe
2013-09-08 20:08:21,241 DEBUG - OpenSim.Services.HypergridService.HGSuitcaseInventoryService [HG SUITCASE INVENTORY SERVICE]: GetRootFolder for ce40214d-7737-47f5-af49-b685bfbb5dec
2013-09-08 20:08:26,711 INFO - OpenSim.Framework.WebUtil [WEB UTIL]: Slow ServiceOSD request 20 PUT http://plaza08.osgrid.org:9303/agent/ce40214d-7737-47f5-af49-b685bfbb5dec/ [^] took 15179ms, 702ms writing, {"message_type":"AgentData","region_id":"f3c6f1b0-b5d1-11e2-9e96-0800200c9a66","circuit_code":"0","a
2013-09-08 20:08:26,721 DEBUG - OpenSim.Region.Framework.Scenes.ScenePresence [SCENE PRESENCE]: Closing child agents. Checking 1 regions in Paramour
2013-09-08 20:08:26,721 DEBUG - OpenSim.Services.PresenceService.PresenceService [PRESENCE SERVICE]: Session f506084b-533b-4317-9af4-f123a2ebdeec logout
2013-09-08 20:08:26,721 DEBUG - OpenSim.Services.UserAccountService.GridUserService [GRID USER SERVICE]: User ce40214d-7737-47f5-af49-b685bfbb5dec is offline
2013-09-08 20:08:26,741 DEBUG - OpenSim.Region.Framework.Scenes.ScenePresence [SCENE PRESENCE]: Making Aine Caoimhe a child agent in Paramour
2013-09-08 20:08:41,741 DEBUG - OpenSim.Region.CoreModules.Framework.EntityTransfer.EntityTransferModule [ENTITY TRANSFER MODULE]: Closing agent Aine Caoimhe in Paramour after teleport
2013-09-08 20:08:41,741 DEBUG - OpenSim.Region.ClientStack.LindenUDP.LLClientView [CLIENT]: Close has been called for Aine Caoimhe attached to scene Paramour
2013-09-08 20:08:41,741 DEBUG - OpenSim.Region.Framework.Scenes.Scene [SCENE]: Removing child agent Aine Caoimhe ce40214d-7737-47f5-af49-b685bfbb5dec from Paramour
2013-09-08 20:08:41,741 DEBUG - OpenSim.Region.CoreModules.Framework.CapabilitiesModule [CAPS]: Remove caps for agent ce40214d-7737-47f5-af49-b685bfbb5dec in region Paramour
2013-09-08 20:08:41,751 DEBUG - OpenSim.Region.CoreModules.Framework.EntityTransfer.EntityTransferStateMachine [ENTITY TRANSFER STATE MACHINE]: Agent ce40214d-7737-47f5-af49-b685bfbb5dec cleared from transit in Paramour

#################################################################
I am now in Sandbox Plaza and the missing attachments are rezzing
#################################################################
(0024321)
aiaustin (developer)
2013-09-09 02:01

It definitely occurs for TPs between regions on the same grid too.. in my case seen on TPs between our own add on regions (on different servers) on OSGrid.
(0024359)
justincc (administrator)
2013-09-18 15:54

As of git master 3ce46ab I have doubled the waiting period where the CompleteMovementIntoRegion UDP processing waits for UseCircuitCode UDP processing.

From looking at your log Ai, it looks like the UseCircuitCode (UCC) UDP message (as triggered by the source simulator telling the viewer to complete the teleport) is somehow lost. The CompleteAgentMovement UDP message which follows immediately behind doesn't wait long enough for the UCC retry send from the viewer to kick in.

So what I did by git master 3ce46ab is double this period to see if this helps. Please try this. Either way, there should be no harm to anything else from a longer wait here. I have also made it clearer that the "Found presence Ai Austin e858df02-a860-4b92-937a-2b87e4ebcd6d child in Vue-6400 after 21 waits" message is unexpected - the agent should always be root here.

This might ultimately be a network issue of some kind - it's curious that the UCC (which is the very first message by the viewer to a new region with no existing child agent) is lost the first time but some subsequent teleports are ok. So this might help or it might just reveal some other underlying network issue. I'm not a network expert, but perhaps the router is delaying the very first packet for some reason (analysis, firewall checking?) but subsequent packets do not require this processing and so a second teleport (whether after login or not) tends to work.

@Mata Hari - Unfortunately, it's harder to tell what's happening from your log since it's missing the destination side of the conversation. But it might be the same thing as Ai. Unfortunately, it requires the destination to be updated.

@All - I tried to replicate the issue where a failure of the UpdateAgent step causes attachments to disappear. However, this did not happen on my local LAN two machine setup. It might be something that only happens on HG, so it would be very good to see a test comparison on non-HG simulators and HG ones.

Another interesting debug thing to try would be setting ConnectorProtocolVersion = "SIMULATION/0.1" in the [SimulationService] setting of your GridCommon.ini/StandaloneCommon.ini as appropriate. This should make the source and destination simulators use the older SIMULATION/0.1 protocol when teleporting to another simulator. This has different network characteristics so it would be interesting to know if behaviour is different.
(0024360)
kenvc (reporter)
2013-09-18 21:16
edited on: 2013-09-19 09:44

I am also seeing failed teleports within the same grid or with HG even with the new code change Justin just checked in today. It most often happens when trying to teleport within the same grid to a mega regions with quite a few sims but has also happened with instances with only 2-3 sims in them.

The teleport sits on the message "Contacting new region..." for quite a while then appears to timeout. The odd thing is that I can often (but not always) login to the grid directly to these regions, but sometimes it gets stuck at the "Requesting Region Capabilities..." message.

The log file at the destination sim looks normal, but the source sim seems to think it did not receive a teleport confirmation message from the destination sim. Just guessing, but it appears to be a timing issue when the 2 sims are trying to establish the connection.

Even on the sims that have no teleport issues, it seems there is a lot longer than normal pause at the "Contacting Region..." message compared to what it used to do.

(0024361)
Mata Hari (reporter)
2013-09-19 07:33

I updated this morning to r/23665 opensim-997700c, cleared my viewer cache and attempted a tp via landmark to Sandbox Plaza in OSG. It failed with timeout, much as it has been for the last month+. My console from that attempt"

09:48:18 - [HG ENTITY TRANSFER MODULE]: Teleporting agent via landmark to http://hg.osgrid.org:80 [^] region e675e480-f2f8-11dd-87af-0800200c9a66 position <134.5, 117.5, 4953.516>
09:48:18 - [GATEKEEPER SERVICE CONNECTOR]: contacting http://hg.osgrid.org:80/ [^]
09:48:18 - [ENTITY TRANSFER MODULE]: Teleporting Aine Caoimhe ce40214d-7737-47f5-af49-b685bfbb5dec from Paramour to http://hg.osgrid.org:80/ [^] (http://plaza08.osgrid.org:9303/ [^]) Sandbox Plaza/<134.5, 117.5, 4953.516>
09:48:18 - [REMOTE SIMULATION CONNECTOR]: QueryAccess to http://plaza08.osgrid.org:9303/agent/ce40214d-7737-47f5-af49-b685bfbb5dec/e675e480-f2f8-11dd-87af-0800200c9a66/ [^] returned True, reason , version SIMULATION/0.2 (SIMULATION/0.2)
09:48:18 - [ENTITY TRANSFER MODULE]: Destination is running version SIMULATION/0.2
09:48:18 - [HG ENTITY TRANSFER MODULE]: CreateAgent http://hg.osgrid.org:80/ [^] http://plaza08.osgrid.org:9303/ [^]
09:48:18 - [USER AGENT SERVICE]: Request to login user Aine Caoimhe (@stored IP) to grid http://hg.osgrid.org:80/ [^]
09:48:18 - [USER AGENT SERVICE]: this grid: http://aine.x64.me:9000/, [^] desired grid: http://hg.osgrid.org:80/, [^] desired region: e675e480-f2f8-11dd-87af-0800200c9a66
09:48:18 - [REMOTE SIMULATION CONNECTOR]: Creating agent at http://hg.osgrid.org:80/ [^]
09:48:18 - [USER AGENT SERVICE]: Verifying agent token http://hg.osgrid.org:80/;c448be2a-41cf-4252-9373-d12f456d4d4e [^] against http://hg.osgrid.org:80/;c448be2a-41cf-4252-9373-d12f456d4d4e [^]
09:48:19 - [USER AGENT SERVICE]: Gatekeeper sees me as 99.225.68.153
09:48:19 - [HG INVENTORY ACCESS MODULE]: Changing root inventory for user Aine Caoimhe
09:48:19 - [ENTITY TRANSFER MODULE]: Determined that region Sandbox Plaza at 0,0 needs new child agent for agent Aine Caoimhe from Paramour
09:48:19 - [ENTITY TRANSFER MODULE]: Sending new CAPS seed url http://plaza08.osgrid.org:9303/CAPS/7d514cbd-424e-40ea-8580-9e353b2d53490000/ [^] from Paramour to Aine Caoimhe
09:48:19 - [USER AGENT SERVICE]: Verifying Client session af4e13bd-cc0b-4203-ab69-01a682c056f5 with reported IP 99.225.68.153.
09:48:19 - [USER AGENT SERVICE]: Comparing 99.225.68.153 with login IP 99.225.68.153 and MyIP 99.225.68.153; result is True
09:48:53 - [WEB UTIL]: Slow ServiceOSD request 5 PUT http://plaza08.osgrid.org:9303/agent/ce40214d-7737-47f5-af49-b685bfbb5dec/ [^] took 33681ms, 624ms writing, {"message_type":"AgentData","region_id":"f3c6f1b0-b5d1-11e2-9e96-0800200c9a66","circuit_code":"0","a
09:49:24 - [WEB UTIL]: Slow ServiceOSD request 6 PUT http://plaza08.osgrid.org:9303/agent/ce40214d-7737-47f5-af49-b685bfbb5dec/ [^] took 31
200ms, 343ms writing, {"message_type":"AgentData","region_id":"f3c6f1b0-b5d1-11e2-9e96-0800200c9a66","circuit_code":"0","a
09:49:24 - [ENTITY TRANSFER MODULE]: UpdateAgent failed on teleport of Aine Caoimhe to Sandbox Plaza. Keeping avatar in Paramour
09:49:24 - [REMOTE SIMULATION CONNECTOR]: CloseAgent http://plaza08.osgrid.org:9303/agent/ce40214d-7737-47f5-af49-b685bfbb5dec/e675e480-f2f8-11dd-87af-0800200c9a66/?auth=af4e13bd-cc0b-4203-ab69-01a682c056f5 [^]
09:49:24 - [HG INVENTORY ACCESS MODULE]: Restoring root folder for local user Aine Caoimhe
09:49:24 - [ENTITY TRANSFER STATE MACHINE]: Agent ce40214d-7737-47f5-af49-b685bfbb5dec cleared from transit in Paramour

#######

After this failed attempt, I changed my StandaloneCommon.ini to use SIMULATION/0.1 as per your request, restarted my simulator, cleared viewer cache again, then logged in and repeated the attempt. Once again it failed, although it seemed to progress slightly further before the time-out (see the extra 4 lines in the console log below where [USER MANAGEMENT MODULE] is reporting no grid user found for various OSG friends UUIDs I have). Perhaps this will help to isolate where in the code the problem is occuring.

10:00:25 - [HG ENTITY TRANSFER MODULE]: Teleporting agent via landmark to http://hg.osgrid.org:80 [^] region e675e480-f2f8-11dd-87af-0800200c9a66 position <134.5, 117.5, 4953.516>
10:00:25 - [GATEKEEPER SERVICE CONNECTOR]: contacting http://hg.osgrid.org:80/ [^]
10:00:25 - [ENTITY TRANSFER MODULE]: Teleporting Aine Caoimhe ce40214d-7737-47f5-af49-b685bfbb5dec from Paramour to http://hg.osgrid.org:80/ [^] (http://plaza08.osgrid.org:9303/ [^]) Sandbox Plaza/<134.5, 117.5, 4953.516>
10:00:25 - [REMOTE SIMULATION CONNECTOR]: QueryAccess to http://plaza08.osgrid.org:9303/agent/ce40214d-7737-47f5-af49-b685bfbb5dec/e675e480-f2f8-11dd-87af-0800200c9a66/ [^] returned True, reason , version SIMULATION/0.2 (SIMULATION/0.2)
10:00:25 - [ENTITY TRANSFER MODULE]: Destination is running version SIMULATION/0.2
10:00:25 - [HG ENTITY TRANSFER MODULE]: CreateAgent http://hg.osgrid.org:80/ [^] http://plaza08.osgrid.org:9303/ [^]
10:00:25 - [USER AGENT SERVICE]: Request to login user Aine Caoimhe (@stored IP) to grid http://hg.osgrid.org:80/ [^]
10:00:25 - [USER AGENT SERVICE]: this grid: http://aine.x64.me:9000/, [^] desired grid: http://hg.osgrid.org:80/, [^] desired region: e675e480-f2f8-11dd-87af-0800200c9a66
10:00:25 - [REMOTE SIMULATION CONNECTOR]: Creating agent at http://hg.osgrid.org:80/ [^]
10:00:25 - [USER AGENT SERVICE]: Verifying agent token http://hg.osgrid.org:80/;2865cf98-8dd8-4dd5-a9d7-a7b9b58f02c3 [^] against http://hg.osgrid.org:80/;2865cf98-8dd8-4dd5-a9d7-a7b9b58f02c3 [^]
10:00:26 - [USER AGENT SERVICE]: Gatekeeper sees me as 99.225.68.153
10:00:26 - [HG INVENTORY ACCESS MODULE]: Changing root inventory for user Aine Caoimhe
10:00:26 - [ENTITY TRANSFER MODULE]: Determined that region Sandbox Plaza at 0,0 needs new child agent for agent Aine Caoimhe from Paramour
10:00:26 - [ENTITY TRANSFER MODULE]: Sending new CAPS seed url http://plaza08.osgrid.org:9303/CAPS/73aaf519-92a7-477a-86a3-797b8a3851090000/ [^] from Paramour to Aine Caoimhe
10:00:26 - [USER AGENT SERVICE]: Verifying Client session 360a7d65-f8d1-4618-b18a-8b38cef4070a with reported IP 99.225.68.153.
10:00:26 - [USER AGENT SERVICE]: Comparing 99.225.68.153 with login IP 99.225.68.153 and MyIP 99.225.68.153; result is True
10:00:30 - [USER MANAGEMENT MODULE]: No grid user found for 81ed494b-9e03-4828-83ed-1198b4d57b63
10:00:30 - [USER MANAGEMENT MODULE]: No grid user found for 187d42f1-67df-4ed2-a04d-1daa5d3891da
10:00:30 - [USER MANAGEMENT MODULE]: No grid user found for 187d42f1-67df-4ed2-a04d-1daa5d3891da
10:00:30 - [USER MANAGEMENT MODULE]: No grid user found for 81ed494b-9e03-4828-83ed-1198b4d57b63
10:00:57 - [WEB UTIL]: Slow ServiceOSD request 5 PUT http://plaza08.osgrid.org:9303/agent/ce40214d-7737-47f5-af49-b685bfbb5dec/ [^] took 30810ms, 655ms writing, {"message_type":"AgentData","region_id":"f3c6f1b0-b5d1-11e2-9e96-0800200c9a66","circuit_code":"0","a
10:01:28 - [WEB UTIL]: Slow ServiceOSD request 6 PUT http://plaza08.osgrid.org:9303/agent/ce40214d-7737-47f5-af49-b685bfbb5dec/ [^] took 30967ms, 359ms writing, {"message_type":"AgentData","region_id":"f3c6f1b0-b5d1-11e2-9e96-0800200c9a66","circuit_code":"0","a
10:01:28 - [ENTITY TRANSFER MODULE]: UpdateAgent failed on teleport of Aine Caoimhe to Sandbox Plaza. Keeping avatar in Paramour10:01:28 - [REMOTE SIMULATION CONNECTOR]: CloseAgent http://plaza08.osgrid.org:9303/agent/ce40214d-7737-47f5-af49-b685bfbb5dec/e675e480-f2f8-11dd-87af-0800200c9a66/?auth=360a7d65-f8d1-4618-b18a-8b38cef4070a [^]
10:01:28 - [HG INVENTORY ACCESS MODULE]: Restoring root folder for local user Aine Caoimhe
10:01:28 - [ENTITY TRANSFER STATE MACHINE]: Agent ce40214d-7737-47f5-af49-b685bfbb5dec cleared from transit in Paramour

Unlike aiaustin and kenvc, I have never yet had a failed attempt to tp between regions within my own simulator, although I usually only have 3 or 4 regions active at a time, none are megas, and none have any significant traffic. If the issue was a "globally random" one that wasn't dependent on one of those, I would have expected to encounter it at some point since I do tp very frequently between my own regions (sometimes as often as a dozen or more tps per hour for 8-10 consecutive hours when I'm working on something). I can't even remember the last time I had a crash or failed tp within my own sim.

I would tend to agree with kenvc's observation that the pause at "Contacting Region..." may be a little longer than it used to be, although the overall time to tp between regions within my own sim is a lot faster than it used to be (ie the time from when I start the tp to the time I'm standing in the destination region).
(0024362)
Bruce (reporter)
2013-09-19 07:45
edited on: 2013-09-19 07:59

Confirming report by knvc of 19 Sep 13 at 04:16. Possible other workaround for HG enabled standalones running instances on r/23665 is to comment section [SimulationService] and line ConnectorProtocolVersion = "SIMULATOR/0.2" in StandaloneHypergrid.ini This resulted in improving time for HG teleports but did no entirely eliminated viewer crashes using latest version of Singularity and Firestorm.

(0024366)
justincc (administrator)
2013-09-19 15:00

I forgot that the ConnectorProtocolVersion line in [SimulationService] only affects inbound transfers not outbound.

Therefore, in git master 979b171, I added a MaxOutgoingTransferVersion attribute to the [EntityTransfer] section of OpenSim.ini. Specifying "SIMULATION/0.1" here will make the simulator use this earlier protocol for outgoing teleports even if the destination has SIMULATION/0.2 available (all such simulators should also have SIMULATION/0.1 available). See OpenSimDefaults.ini for more details.

@Mata - Please could you retest with this. Changing ConnectorProtocolVersion would have no effect for you

@Bruce - Commenting out ConnectorProtocolVersion should have no effect since the coded in default is also SIMULATION/0.2

@kenvc - It could be very useful if you could test inter-grid teleports with a non-HG configuration. With HG on, inter-grid teleports still filter through the HG code layer, which in theory should do nothing but in practice might have bugs.
(0024369)
kenvc (reporter)
2013-09-19 21:37

Justin, I disabled Hypergrid completely on my test grid and restarted everything and it made no difference. It probably won't help but after the teleport fails, the viewer displays the message attached as a jpg file to this mantis. This was using the latest dev master code from this evening: r/23673
(0024370)
aiaustin (developer)
2013-09-20 01:34
edited on: 2013-09-20 01:36

I am travelling so not able to test yet. But for Justin... I definitely first saw this problem within a single grid on OSGrid to OSGrid transfers on two servers which are on the same (gigabit) subnet at our own University with no active firewall. It was using the standard OSGrid add on region install. It all started when the changes were being made to slow down TPs for Opensim CC teleport issues. Before that TPs were fast and immediate for this type of transfer.

(0024371)
Mata Hari (reporter)
2013-09-20 05:01

Tested this morning with r/23673 opensim-c06a9ff (without clearing my viewer cache this time since it seems unlikely anything in my viewer cache is likely to be affecting this particular issue) by doing the same tp as my tests yesterday: from my own sim's home region to OSG's Sandbox Plaza.

With [Entity Transfer] MaxOutgoingTransferVersion set to SIMULATION/0.1 the teleport worked perfectly on the first attempt. I was also able to tp to another region, then home again without issues which reminds me that I hadn't mentioned before that with the problems I was experiencing with the previous version, once I was able to tp (by making the second attempt immediately after the first attempt failed) I was then later able to tp back to my own grid without any trouble at all -- successful tp on the first attempt -- even if I had made multiple tps to various regions in the grid I was visiting. So an HG tp going from "foreign region" to "native region" was always successful whereas going from "native region" to "foreign region" was always failing on 1st attempt.

Below is the log from the successful v/0.1 tp in case it's useful -- of possible interest is at 07:26:28 the Slow ServiceOSD request

07:26:16 - [HG ENTITY TRANSFER MODULE]: Teleporting agent via landmark to http://hg.osgrid.org:80 [^] region e675e480-f2f8-11dd-87af-0800200c9a66 position <134.5, 117.5, 4953.516>
07:26:16 - [GATEKEEPER SERVICE CONNECTOR]: contacting http://hg.osgrid.org:80/ [^]
07:26:16 - [ENTITY TRANSFER MODULE]: Teleporting Aine Caoimhe ce40214d-7737-47f5-af49-b685bfbb5dec from Paramour to http://hg.osgrid.org:80/ [^] (http://plaza08.osgrid.org:9303/ [^]) Sandbox Plaza/<134.5, 117.5, 4953.516>
07:26:17 - [REMOTE SIMULATION CONNECTOR]: QueryAccess to http://plaza08.osgrid.org:9303/agent/ce40214d-7737-47f5-af49-b685bfbb5dec/e675e480-f2f8-11dd-87af-0800200c9a66/ [^] returned True, reason , version SIMULATION/0.2 (SIMULATION/0.2)
07:26:17 - [ENTITY TRANSFER MODULE]: Paramour max transfer version is SIMULATION/0.1, Sandbox Plaza max version is SIMULATION/0.2
07:26:17 - [ENTITY TRANSFER MODULE]: Using TP V1 for Aine Caoimhe going from Paramour to Sandbox Plaza
07:26:17 - [HG ENTITY TRANSFER MODULE]: CreateAgent http://hg.osgrid.org:80/ [^] http://plaza08.osgrid.org:9303/ [^]
07:26:17 - [USER AGENT SERVICE]: Request to login user Aine Caoimhe (@stored IP) to grid http://hg.osgrid.org:80/ [^]
07:26:17 - [USER AGENT SERVICE]: this grid: http://aine.x64.me:9000/, [^] desired grid: http://hg.osgrid.org:80/, [^] desired region: e675e480-f2f8-11dd-87af-0800200c9a66
07:26:17 - [REMOTE SIMULATION CONNECTOR]: Creating agent at http://hg.osgrid.org:80/ [^]
07:26:17 - [USER AGENT SERVICE]: Verifying agent token http://hg.osgrid.org:80/;2749a806-8b21-4097-beeb-d71c1b1ba374 [^] against http://hg.osgrid.org:80/;2749a806-8b21-4097-beeb-d71c1b1ba374 [^]
07:26:17 - [USER AGENT SERVICE]: Gatekeeper sees me as 99.225.68.153
07:26:17 - [HG INVENTORY ACCESS MODULE]: Changing root inventory for user Aine Caoimhe
07:26:17 - [SCENE PRESENCE]: Closing child agents. Checking 1 regions in Paramour
07:26:17 - [ENTITY TRANSFER MODULE]: Determined that region Sandbox Plaza at 0,0 needs new child agent for incoming agent Aine Caoimhe from Paramour
07:26:17 - [ENTITY TRANSFER MODULE]: Set release callback URL to http://aine.x64.me:9000/agent/ce40214d-7737-47f5-af49-b685bfbb5dec/f3c6f1b0-b5d1-11e2-9e96-0800200c9a66/release/ [^] in Paramour
07:26:18 - [USER AGENT SERVICE]: Verifying Client session 5b3b3db4-e00f-4eb8-8aea-1cf9d3e3118d with reported IP 99.225.68.153.
07:26:18 - [USER AGENT SERVICE]: Comparing 99.225.68.153 with login IP 99.225.68.153 and MyIP 99.225.68.153; result is True
07:26:21 - [USER MANAGEMENT MODULE]: No grid user found for 2b293164-5a6d-bd1d-5cfc-7aad677544f1
07:26:22 - [USER MANAGEMENT MODULE]: No grid user found for 2b293164-5a6d-bd1d-5cfc-7aad677544f1
07:26:28 - [WEB UTIL]: Slow ServiceOSD request 5 PUT http://plaza08.osgrid.org:9303/agent/ce40214d-7737-47f5-af49-b685bfbb5dec/ [^] took 10998ms, 686ms writing, {"message_type":"AgentData","region_id":"f3c6f1b0-b5d1-11e2-9e96-0800200c9a66","circuit_code":"0","a
07:26:28 - [ENTITY TRANSFER MODULE]: Sending new CAPS seed url http://plaza08.osgrid.org:9303/CAPS/bd7f2c69-3b48-4196-bd8b-bda1333a65b00000/ [^] from Paramour to Aine Caoimhe
07:26:29 - [AGENT HANDLER]: Release ce40214d-7737-47f5-af49-b685bfbb5dec to RegionID: f3c6f1b0-b5d1-11e2-9e96-0800200c9a66
07:26:29 - [PRESENCE SERVICE]: Session 5b3b3db4-e00f-4eb8-8aea-1cf9d3e3118d logout
07:26:30 - [GRID USER SERVICE]: User ce40214d-7737-47f5-af49-b685bfbb5dec is offline
07:26:30 - [SCENE PRESENCE]: Making Aine Caoimhe a child agent in Paramour
07:26:30 - [USER AGENT SERVICE]: Verifying Client session 5b3b3db4-e00f-4eb8-8aea-1cf9d3e3118d with reported IP 99.225.68.153.
07:26:30 - [USER AGENT SERVICE]: Comparing 99.225.68.153 with login IP 99.225.68.153 and MyIP 99.225.68.153; result is True
07:26:32 - [CLIENT]: Close has been called for Aine Caoimhe attached to scene Paramour
07:26:32 - [SCENE]: Removing child agent Aine Caoimhe ce40214d-7737-47f5-af49-b685bfbb5dec from Paramour
07:26:32 - [CAPS]: Remove caps for agent ce40214d-7737-47f5-af49-b685bfbb5dec in region Paramour
07:26:32 - [ENTITY TRANSFER STATE MACHINE]: Agent ce40214d-7737-47f5-af49-b685bfbb5dec cleared from transit in Paramour
07:26:38 - [HG SUITCASE INVENTORY SERVICE]: GetRootFolder for ce40214d-7737-47f5-af49-b685bfbb5dec

Since I noticed in the git logs that you'd made a change to the console messaging to help debug this issue, I then set MaxOutgoingTransferVersion to 0.2 and retried. Not surprisingly, it failed via timeout and I remained in the source region and all my attachments were suddenly missing.

Log of failed v0.2 attempt:

07:41:28 - [HG ENTITY TRANSFER MODULE]: Teleporting agent via landmark to http://hg.osgrid.org:80 [^] region e675e480-f2f8-11dd-87af-0800200c9a66 position <134.5, 117.5, 4953.516>
07:41:28 - [GATEKEEPER SERVICE CONNECTOR]: contacting http://hg.osgrid.org:80/ [^]
07:41:28 - [ENTITY TRANSFER MODULE]: Teleporting Aine Caoimhe ce40214d-7737-47f5-af49-b685bfbb5dec from Paramour to http://hg.osgrid.org:80/ [^] (http://plaza08.osgrid.org:9303/ [^]) Sandbox Plaza/<134.5, 117.5, 4953.516>
07:41:28 - [REMOTE SIMULATION CONNECTOR]: QueryAccess to http://plaza08.osgrid.org:9303/agent/ce40214d-7737-47f5-af49-b685bfbb5dec/e675e480-f2f8-11dd-87af-0800200c9a66/ [^] returned True, reason , version SIMULATION/0.2 (SIMULATION/0.2)
07:41:28 - [ENTITY TRANSFER MODULE]: Paramour max transfer version is SIMULATION/0.2, Sandbox Plaza max version is SIMULATION/0.2
07:41:28 - [HG ENTITY TRANSFER MODULE]: CreateAgent http://hg.osgrid.org:80/ [^] http://plaza08.osgrid.org:9303/ [^]
07:41:28 - [USER AGENT SERVICE]: Request to login user Aine Caoimhe (@stored IP) to grid http://hg.osgrid.org:80/ [^]
07:41:28 - [USER AGENT SERVICE]: this grid: http://aine.x64.me:9000/, [^] desired grid: http://hg.osgrid.org:80/, [^] desired region: e675e480-f2f8-11dd-87af-0800200c9a66
07:41:28 - [REMOTE SIMULATION CONNECTOR]: Creating agent at http://hg.osgrid.org:80/ [^]
07:41:29 - [USER AGENT SERVICE]: Verifying agent token http://hg.osgrid.org:80/;5db296ed-e6bf-4571-9a2a-79d474686005 [^] against http://hg.osgrid.org:80/;5db296ed-e6bf-4571-9a2a-79d474686005 [^]
07:41:29 - [USER AGENT SERVICE]: Gatekeeper sees me as 99.225.68.153
07:41:29 - [HG INVENTORY ACCESS MODULE]: Changing root inventory for user Aine Caoimhe
07:41:29 - [ENTITY TRANSFER MODULE]: Determined that region Sandbox Plaza at 0,0 needs new child agent for agent Aine Caoimhe from Paramour
07:41:29 - [ENTITY TRANSFER MODULE]: Sending new CAPS seed url http://plaza08.osgrid.org:9303/CAPS/2e3ca154-3bce-4bf8-80b7-9f37de1c59410000/ [^] from Paramour to Aine Caoimhe
07:41:30 - [USER AGENT SERVICE]: Verifying Client session 65b9a77b-7d5c-48f9-8782-8c0edd8b7745 with reported IP 99.225.68.153.
07:41:30 - [USER AGENT SERVICE]: Comparing 99.225.68.153 with login IP 99.225.68.153 and MyIP 99.225.68.153; result is True
07:41:32 - [USER MANAGEMENT MODULE]: No grid user found for 2b293164-5a6d-bd1d-5cfc-7aad677544f1
07:41:32 - [USER MANAGEMENT MODULE]: No grid user found for 2b293164-5a6d-bd1d-5cfc-7aad677544f1
07:42:00 - [WEB UTIL]: Slow ServiceOSD request 5 PUT http://plaza08.osgrid.org:9303/agent/ce40214d-7737-47f5-af49-b685bfbb5dec/ [^] took 30967ms, 671ms writing, {"message_type":"AgentData","region_id":"f3c6f1b0-b5d1-11e2-9e96-0800200c9a66","circuit_code":"0","a
07:42:32 - [WEB UTIL]: Slow ServiceOSD request 6 PUT http://plaza08.osgrid.org:9303/agent/ce40214d-7737-47f5-af49-b685bfbb5dec/ [^] took 31871ms, 312ms writing, {"message_type":"AgentData","region_id":"f3c6f1b0-b5d1-11e2-9e96-0800200c9a66","circuit_code":"0","a
07:42:32 - [ENTITY TRANSFER MODULE]: UpdateAgent failed on teleport of Aine Caoimhe to Sandbox Plaza. Keeping avatar in Paramour
07:42:32 - [REMOTE SIMULATION CONNECTOR]: CloseAgent http://plaza08.osgrid.org:9303/agent/ce40214d-7737-47f5-af49-b685bfbb5dec/e675e480-f2f8-11dd-87af-0800200c9a66/?auth=65b9a77b-7d5c-48f9-8782-8c0edd8b7745 [^]
07:42:32 - [HG INVENTORY ACCESS MODULE]: Restoring root folder for local user Aine Caoimhe
07:42:32 - [ENTITY TRANSFER STATE MACHINE]: Agent ce40214d-7737-47f5-af49-b685bfbb5dec cleared from transit in Paramour

One other tidbit of information...when I was doing this second test I stopped after the failed attempt to copy the relevant part of my log and make the notations above. When I then attempted to repeat the tp it failed again but as soon as it failed I re-tried and it worked. The elapsed time between 1st fail and 2nd fail was approx. 6 minutes so whatever it was that allows an immediate 2nd attempt to succeed will be wiped out within that time frame (or else it's on a longer cycle and I just happened to be doing the test at a time when the sweep was scheduled).


For the time being I will switch my sim to run outbound 0.1 but I'm a little reluctant to do so for any length of time since I assume this means that all 0.2-related outbound permission settings for assets, etc are no longer being checked (I have content on my sim that is proprietary/copyright that I am legally obligated to prevent from being copied). If it turns out that the fix for this issue will take a while, could you possibly add a console command that would allow me to run the sim under 0.2, then when I need to tp I could use the console to switch to outbound 0.1 for a brief period of time, then switch it back? Or a script command would also be fine (I could script a button for me to touch before tping). Or else could the outbound version take a UUID as an argument so I can allow only my own UUID to use 0.1 outbound and any other visitor use 0.2.


I concur with aiaustin about the timing of when the tp issue first began to appear.
(0024372)
kenvc (reporter)
2013-09-20 11:44
edited on: 2013-09-20 11:47

Justin, attached is a zip file containing 4 clean log files that were created from the start of my tests to the logoff at the end of the tests. Tests were not started until ALL sims were fully started and CPU had settled back down to its normal idle level at 7%. HG is NOT currently enabled on this test grid. Here is what is included:

Robust.log (Log file from the test grid Robust from start to end of tests)
Universal Campus.log (Where my AV logged into the test grid: Login worked fine)
Moorea_B1.log (Where I teleported first from Universal Campus: TP worked fine)
Island_1.log (Where I teleported next from Moorea_B1: TP failed)

GridCommon.ini is identical on all sim instances. Opensim.ini is identical except they use different listening ports and the Universal Campus and Island_1 instances are mega regions. This does happen more often when trying to teleport into mega regions compared to non-megas, but it does happen on both.

At this point it appears something has changed that requires the destination sim or originating sim to need more CPU time to work than it used to. The Server running this test grid is also running all my sims on OSGrid, but at idle it uses only 7% CPU time (Dual Quad Core Xeon processors 32GB ram)

(0024373)
kenvc (reporter)
2013-09-20 13:50

Just discovered that at least some of these issues are present when using Singularity and are not always present when using Firestorm. The Sing Devs say it is something they are aware of and working on, but I do not think this will totally solve the issue because I have seen it happen with FS too, although not nearly as often.
(0024374)
Arielle (reporter)
2013-09-20 14:12

While reading Ken's last note I was in the middle of a tp to a friends region in Metro who are on .7.5 stable. The tp failed and i wound up in the originating region stripped of my attachments in my own view. To a friend who tp'ed in after the failed tp, i appeared fine with all attachments. The region where i attempted to tp to was restarted and another attempt to tp was made successfully. The attachments which had disappeared after my first attempt, appeared when i landed in the restarted region. This was without my avi being relogged or rewearing the attachments.
This was with a recent Singularity alpha 1.8.2 (4966)
(0024375)
justincc (administrator)
2013-09-20 15:54

@kenvc - Looking at your logs, it does appear you have a different problem from Mata. In your case, for some reason, the viewer does not contact the destination Simulator. In Mata's case, this step works fine but for some reason the CompleteMovement thread triggered by the viewer never sees the UpdateAgent sent from the source simulator to the destination, even though the source effectively tells us it was sent.

So could everyone please try different viewers with this problem to make sure that this isn't a viewer dependent issue.

Also Ken, I need to see logs at DEBUG level and preferably with the minimum number of regions and simulators required to trigger the problem.

@Mata - Teleport versions have no connection with Hypergrid versions, so under 'V1 teleport' your data is just as secure as it would be with 'V2'.

However, fallback is only meant as a debug measure so I don't want to make things more complex by introducing dynamic options for this. It's the V2 teleport that has to be improved if there are issues.

In git master c01db5f I have made a change which might relieve this problem, though I suspect it won't. This requires an update to the destination simulator - osgrid have just updated the plazas to this version. I have also added some extra logging to the destination so I can get more clues as to what is happening. So please try the V2 teleport again and paste the log and the date you did it (timestamps help me cross-check with messages on the destination side).

@Ai Austin - I don't know what you're referring to. It would be extremely helpful to me if you could identify through testing the exact OpenSimulator revision where the problem appeared for you.

@All - please also say which grid you are trying to teleport to and test with multiple grids or even your own multiple HG instances if possible. I don't know yet if one could rule out some osgrid specific network/software issue.

See [1] if anybody is interested in seeing the exact teleport process laid out in high detail.

[1] http://opensimulator.org/wiki/Teleports#Same_simulator.2C_Out-of-sight.2C_OpenSimulator_Development_Code_.28will_be_0.7.6.29. [^]
(0024377)
Mata Hari (reporter)
2013-09-20 19:05
edited on: 2013-09-20 19:07

Thanks for the assurances re security...glad I'm not exposing any assets that I don't have the right to.


I did some extensive tests this evening using your latest. Rather than make a huge post here I attach a txt log that details step by step what I did and includes console logs

http://opensimulator.org/mantis/file_download.php?file_id=3597&type=bug [^]

Edit: neglected to add at the end of the log that I made the return tp from Sandbox to my own grid with the usual rapid success.

(0024378)
kenvc (reporter)
2013-09-20 23:10
edited on: 2013-09-21 09:02

Justin, I switched all my OSGrid sims back to v.01 teleports, and now logins are much faster (especially when signing in with a slow connection) and there are no longer any TP issues.

I will try to activate debug mode and do tests tomorrow using the new v .02 teleports to help troubleshoot the TP issues with the new protocol.

How is the best way to activate the debug mode for this purpose?

(0024382)
Bruce (reporter)
2013-09-21 14:44

It appears that most if not all of the people who reported in this mantis are on windows 32 or 64 bit. I was therefore wondering if this is perhaps a windows related issue. Tested with Firestorm 4.4.2 (34167) and Singularity Viewer 1.8.3 (5003) using r23682. More than half of the HG teleports failed. Also received "ERROR: updateMoveDampedAsynch: updateMove called with NULL drawablep" from Singularity following one failed HG teleport attempt. Using MaxOutgoingTransferVersion = "SIMULATION/0.2" or "SIMULATION/0.1" did not appear to make any difference. Last commit that works fine for me is r/23611 . I have not tested with r/23651 (OSGs current recommended version). Standalone (multiple regions), HG 2.0 enabled, ODE, .NET/ Winows64.
(0024383)
aiaustin (developer)
2013-09-22 11:42
edited on: 2013-09-23 02:33

I can confirm all my own tests are on Windows Vista 32 bit, Windows 7 64 bit and Windows 8 64 bit all on 0.7.6 dev master releases either set up from new compiles or the OSGrid prebuilt versions.

All my own tests (and tp failures) have been in Firestorm 4.4.2 OS version.

(0024386)
aiaustin (developer)
2013-09-23 02:03
edited on: 2013-09-23 02:04

Updated Openvue grid to r/23852 and our OSGRid add on regions to the latest OSGrid distribution.

This now seems to be completely broken on my first tests between Openvue grid and OSGrid add-on regions, rather than ever so often.

I get this failure at the "Contacting new region" point in the transfer, and avatar left in origination region with no attachments left on at all on a test of a teleport from Openvue grid main "Openvue" region to "OpenVCE" add on region on OSGrid. Both regions with no other load and freshly installed, and I had waited until everything was quiet on all consoles before testing. I tried twice and it failed both times. Viewer is Firestorm 4.4.2 OS.

----------------------------

Origination region log... (on Openvue grid which has Robust on virtual.aiai.ed.ac.uk:8002 and the test origination region on the same server)...

09:55:47 - [HG ENTITY TRANSFER MODULE]: region http://hg.osgrid.org:80/ [^] OpenVCE
flags: 524
09:55:47 - [HG ENTITY TRANSFER MODULE]: Destination region is hyperlink
09:55:47 - [GATEKEEPER SERVICE CONNECTOR]: contacting http://hg.osgrid.org:80/ [^]
09:55:47 - [HG ENTITY TRANSFER MODULE]: GetFinalDestination serveruri -> http://
virtual4.aiai.ed.ac.uk:9000/
09:55:47 - [ENTITY TRANSFER MODULE]: Teleporting Ai Austin e24a9015-f5ca-452b-8c
95-d32e34cb9d64 from Openvue to http://hg.osgrid.org:80/ [^] (http://virtual4.aiai.e [^]
d.ac.uk:9000/) OpenVCE/<128, 128, 25>
09:55:47 - [REMOTE SIMULATION CONNECTOR]: QueryAccess to http://virtual4.aiai.ed [^]
.ac.uk:9000/agent/e24a9015-f5ca-452b-8c95-d32e34cb9d64/2a2c51ed-7846-4536-8503-d
c332c6c0804/ returned True, reason , version SIMULATION/0.2 (SIMULATION/0.2)
09:55:47 - [ENTITY TRANSFER MODULE]: Openvue max transfer version is SIMULATION/
0.2, OpenVCE max version is SIMULATION/0.2
09:55:47 - [HG ENTITY TRANSFER MODULE]: CreateAgent http://hg.osgrid.org:80/ [^] htt
p://virtual4.aiai.ed.ac.uk:9000/ [^]
Region (root) # >>> LoginAgentToGrid <<< http://129.215.219.86:8002/ [^]
09:55:47 - [REMOTE SIMULATION CONNECTOR]: Creating agent at http://129.215.219.8 [^]
6:8002/
09:55:49 - [HG INVENTORY ACCESS MODULE]: Changing root inventory for user Ai Aus
tin
09:55:49 - [ENTITY TRANSFER MODULE]: Determined that region OpenVCE at 13862,0 n
eeds new child agent for agent Ai Austin from Openvue
09:55:49 - [ENTITY TRANSFER MODULE]: Sending new CAPS seed url http://virtual4.a [^]
iai.ed.ac.uk:9000/CAPS/539f238d-d816-42a5-a17a-9a6cb1d8e91b0000/ from Openvue to
 Ai Austin
09:56:17 - [WEB UTIL]: Slow ServiceOSD request 557 PUT http://virtual4.aiai.ed.a [^]
c.uk:9000/agent/e24a9015-f5ca-452b-8c95-d32e34cb9d64/ took 28750ms, 78ms writing
, {"message_type":"AgentData","region_id":"9c8b6f8f-8178-4a69-92dc-9feba4646e6b"
,"circuit_code":"0","a
09:56:40 - [WEB UTIL]: Slow ServiceOSD request 558 PUT http://virtual4.aiai.ed.a [^]
c.uk:9000/agent/e24a9015-f5ca-452b-8c95-d32e34cb9d64/ took 22453ms, 0ms writing,
 {"message_type":"AgentData","region_id":"9c8b6f8f-8178-4a69-92dc-9feba4646e6b",
"circuit_code":"0","a
09:56:40 - [ENTITY TRANSFER MODULE]: UpdateAgent failed on teleport of Ai Austin
 to OpenVCE. Keeping avatar in Openvue
09:56:40 - [REMOTE SIMULATION CONNECTOR]: CloseAgent http://virtual4.aiai.ed.ac. [^]
uk:9000/agent/e24a9015-f5ca-452b-8c95-d32e34cb9d64/2a2c51ed-7846-4536-8503-dc332
c6c0804/?auth=808ffa58-98c8-4515-b64f-afdf9c2feb62
09:56:40 - [HG INVENTORY ACCESS MODULE]: Restoring root folder for local user Ai
 Austin
09:56:40 - [ENTITY TRANSFER STATE MACHINE]: Agent e24a9015-f5ca-452b-8c95-d32e34
cb9d64 cleared from transit in Openvue

-------------------------------

Destination region is an OSGrid add on region running on virtual4.aiaied.ac.uk

Region (root) #
09:56:55 - [SCENE]: Region OpenVCE told of incoming child agent Ai.Austin @virtu
al.aiai.ed.ac.uk e24a9015-f5ca-452b-8c95-d32e34cb9d64 (circuit code 1158178018,
IP 129.215.219.52, viewer Firestorm-Release 4.4.2.34167, teleportflags (ViaHGLog
in), position <128, 128, 25>)
09:56:55 - [SCENE]: Region OpenVCE authenticated and authorized incoming child a
gent Ai.Austin @virtual.aiai.ed.ac.uk e24a9015-f5ca-452b-8c95-d32e34cb9d64 (circ
uit code 1158178018)
09:56:55 - [VivoxVoice]: OnRegisterCaps: agentID e24a9015-f5ca-452b-8c95-d32e34c
b9d64 caps OpenSim.Framework.Capabilities.Caps
09:56:55 - [EVENTQUEUE]: Adding new queue for agent e24a9015-f5ca-452b-8c95-d32e
34cb9d64 in region OpenVCE
09:56:55 - [SCENE]: Incoming child agent update for e24a9015-f5ca-452b-8c95-d32e
34cb9d64 in OpenVCE
09:56:56 - [LLUDPSERVER]: Received a CompleteMovementIntoRegion in OpenVCE (not
ready yet)
09:56:56 - [CAPS]: Received SEED caps request in OpenVCE for agent e24a9015-f5ca
-452b-8c95-d32e34cb9d64
09:56:56 - [SCENE]: Incoming client Ai.Austin @virtual.aiai.ed.ac.uk in region O
penVCE via HG login
09:56:56 - [USER AGENT CONNECTOR]: new connector to http://virtual.aiai.ed.ac.uk [^]
:8002/ (http://129.215.219.86:8002/ [^])
09:56:56 - [SCENE]: User Client Verification for Ai.Austin @virtual.aiai.ed.ac.u
k in OpenVCE returned true
09:56:56 - [LLUDPSERVER]: Received a CompleteMovementIntoRegion in OpenVCE (not
ready yet)
09:56:56 - [LLUDPSERVER]: Received a CompleteMovementIntoRegion in OpenVCE (not
ready yet)
09:56:56 - [LLUDPSERVER]: Received a CompleteMovementIntoRegion in OpenVCE (not
ready yet)
09:56:57 - [LLUDPSERVER]: Received a CompleteMovementIntoRegion in OpenVCE (not
ready yet)
09:56:57 - [LLUDPSERVER]: Received a CompleteMovementIntoRegion in OpenVCE (not
ready yet)
09:56:57 - [LLUDPSERVER]: Received a CompleteMovementIntoRegion in OpenVCE (not
ready yet)
09:56:57 - [LLUDPSERVER]: Received a CompleteMovementIntoRegion in OpenVCE (not
ready yet)
09:56:57 - [LLUDPSERVER]: Received a CompleteMovementIntoRegion in OpenVCE (not
ready yet)
09:56:58 - [LLUDPSERVER]: Received a CompleteMovementIntoRegion in OpenVCE (not
ready yet)
09:56:58 - [LLUDPSERVER]: Received a CompleteMovementIntoRegion in OpenVCE (not
ready yet)
09:56:58 - [LLUDPSERVER]: Received a CompleteMovementIntoRegion in OpenVCE (not
ready yet)
09:56:58 - [LLUDPSERVER]: Received a CompleteMovementIntoRegion in OpenVCE (not
ready yet)
09:56:58 - [LLUDPSERVER]: Received a CompleteMovementIntoRegion in OpenVCE (not
ready yet)
09:56:59 - [LLUDPSERVER]: Received a CompleteMovementIntoRegion in OpenVCE (not
ready yet)
09:56:59 - [LLUDPSERVER]: Received a CompleteMovementIntoRegion in OpenVCE (not
ready yet)
09:56:59 - [LLUDPSERVER]: Received a CompleteMovementIntoRegion in OpenVCE (not
ready yet)
09:56:59 - [LLUDPSERVER]: Received a CompleteMovementIntoRegion in OpenVCE (not
ready yet)
09:56:59 - [LLUDPSERVER]: Received a CompleteMovementIntoRegion in OpenVCE (not
ready yet)
09:57:00 - [LLUDPSERVER]: Received a CompleteMovementIntoRegion in OpenVCE (not
ready yet)
09:57:00 - [LLUDPSERVER]: Handling UseCircuitCode request for circuit 1158178018
 to OpenVCE from IP 129.215.219.52:61954
09:57:00 - [SCENE]: Adding new child scene presence Ai.Austin @virtual.aiai.ed.a
c.uk e24a9015-f5ca-452b-8c95-d32e34cb9d64 to scene OpenVCE at pos <128, 128, 25>

09:57:00 - [HG ENTITY TRANSFER MODULE]: Incoming attachement Biker Hair Blonde f
or HG user e24a9015-f5ca-452b-8c95-d32e34cb9d64 with asset server http://virtual [^]
.aiai.ed.ac.uk:8002/
09:57:00 - [HG ENTITY TRANSFER MODULE]: Incoming attachement Ai Austin Glasses f
or HG user e24a9015-f5ca-452b-8c95-d32e34cb9d64 with asset server http://virtual [^]
.aiai.ed.ac.uk:8002/
09:57:00 - [HG ENTITY TRANSFER MODULE]: Incoming attachement Avatar Detector HUD
 for HG user e24a9015-f5ca-452b-8c95-d32e34cb9d64 with asset server http://virtu [^]
al.aiai.ed.ac.uk:8002/
09:57:00 - [HG ENTITY TRANSFER MODULE]: Incoming attachement RUGGED AO for HG us
er e24a9015-f5ca-452b-8c95-d32e34cb9d64 with asset server http://virtual.aiai.ed [^]
.ac.uk:8002/
09:57:01 - [HGUUIDGatherer]: Failed to fetch asset 3147d815-6338-b932-f011-16b56
d9ac18b from http://virtual.aiai.ed.ac.uk:8002/ [^]
09:57:01 - [HGFRIENDS MODULE]: Fetched 2 local friends for visitor e24a9015-f5ca
-452b-8c95-d32e34cb9d64
09:57:01 - [HGUUIDGatherer]: Failed to fetch asset ea633413-8006-180a-c3ba-96dd1
d756720 from http://virtual.aiai.ed.ac.uk:8002/ [^]
09:57:02 - [HGUUIDGatherer]: Failed to fetch asset b5b4a67d-0aee-30d2-72cd-77b33
3e932ef from http://virtual.aiai.ed.ac.uk:8002/ [^]
09:57:02 - [HGUUIDGatherer]: Failed to fetch asset 46bb4359-de38-4ed8-6a22-f1f52
fe8f506 from http://virtual.aiai.ed.ac.uk:8002/ [^]
09:57:02 - [HGUUIDGatherer]: Failed to fetch asset 9a728b41-4ba0-4729-4db7-14bc3
d3df741 from http://virtual.aiai.ed.ac.uk:8002/ [^]
09:57:03 - [HGUUIDGatherer]: Failed to fetch asset f3300ad9-3462-1d07-2044-0fef8
0062da0 from http://virtual.aiai.ed.ac.uk:8002/ [^]
09:57:03 - [HGUUIDGatherer]: Failed to fetch asset c8e42d32-7310-6906-c903-cab5d
4a34656 from http://virtual.aiai.ed.ac.uk:8002/ [^]
09:57:03 - [HGUUIDGatherer]: Failed to fetch asset 85428680-6bf9-3e64-b489-6f810
87c24bd from http://virtual.aiai.ed.ac.uk:8002/ [^]
09:57:03 - [HGUUIDGatherer]: Failed to fetch asset eefc79be-daae-a239-8c04-890f5
d23654a from http://virtual.aiai.ed.ac.uk:8002/ [^]
09:57:04 - [HGUUIDGatherer]: Failed to fetch asset c541c47f-e0c0-058b-ad1a-d6ae3
a4584d9 from http://virtual.aiai.ed.ac.uk:8002/ [^]
09:57:04 - [HG ENTITY TRANSFER MODULE]: Incoming attachement Musician Female Sho
e Left Enlarged for HG user e24a9015-f5ca-452b-8c95-d32e34cb9d64 with asset serv
er http://virtual.aiai.ed.ac.uk:8002/ [^]
09:57:04 - [HG ENTITY TRANSFER MODULE]: Incoming attachement Musician Female Sho
e Right Enlarged for HG user e24a9015-f5ca-452b-8c95-d32e34cb9d64 with asset ser
ver http://virtual.aiai.ed.ac.uk:8002/ [^]
09:57:24 - [SCENE]: Found presence Ai.Austin @virtual.aiai.ed.ac.uk e24a9015-f5c
a-452b-8c95-d32e34cb9d64 child in OpenVCE after 21 waits
09:57:24 - [BASE HTTP SERVER]: Slow handling of 28 PUT /agent/e24a9015-f5ca-452b
-8c95-d32e34cb9d64/ from 129.215.219.86:49916 took 28673ms
09:57:24 - [SCENE]: Incoming child agent update for e24a9015-f5ca-452b-8c95-d32e
34cb9d64 in OpenVCE
09:57:24 - [SCENEGRAPH]: Scene graph for OpenVCE already contains object b5123aa
2-12bd-4d34-9302-eaf27cad0ebd in AddSceneObject()
09:57:24 - [HG ENTITY TRANSFER MODULE]: Incoming attachement Biker Hair Blonde f
or HG user e24a9015-f5ca-452b-8c95-d32e34cb9d64 with asset server http://virtual [^]
.aiai.ed.ac.uk:8002/
09:57:24 - [SCENEGRAPH]: Scene graph for OpenVCE already contains object b793897
2-bf31-43b2-a635-31189f91a7ec in AddSceneObject()
09:57:24 - [HG ENTITY TRANSFER MODULE]: Incoming attachement Ai Austin Glasses f
or HG user e24a9015-f5ca-452b-8c95-d32e34cb9d64 with asset server http://virtual [^]
.aiai.ed.ac.uk:8002/
09:57:24 - [SCENEGRAPH]: Scene graph for OpenVCE already contains object bfcbd1c
d-734e-4739-89c1-5ae8b833926f in AddSceneObject()
09:57:24 - [HG ENTITY TRANSFER MODULE]: Incoming attachement Avatar Detector HUD
 for HG user e24a9015-f5ca-452b-8c95-d32e34cb9d64 with asset server http://virtu [^]
al.aiai.ed.ac.uk:8002/
09:57:24 - [SCENEGRAPH]: Scene graph for OpenVCE already contains object 394b1f4
5-12b2-41a6-91d8-b1a27224e626 in AddSceneObject()
09:57:24 - [HG ENTITY TRANSFER MODULE]: Incoming attachement RUGGED AO for HG us
er e24a9015-f5ca-452b-8c95-d32e34cb9d64 with asset server http://virtual.aiai.ed [^]
.ac.uk:8002/
09:57:24 - [HGUUIDGatherer]: Failed to fetch asset 3147d815-6338-b932-f011-16b56
d9ac18b from http://virtual.aiai.ed.ac.uk:8002/ [^]
09:57:24 - [HGUUIDGatherer]: Failed to fetch asset ea633413-8006-180a-c3ba-96dd1
d756720 from http://virtual.aiai.ed.ac.uk:8002/ [^]
09:57:25 - [HGUUIDGatherer]: Failed to fetch asset b5b4a67d-0aee-30d2-72cd-77b33
3e932ef from http://virtual.aiai.ed.ac.uk:8002/ [^]
09:57:25 - [HGUUIDGatherer]: Failed to fetch asset 46bb4359-de38-4ed8-6a22-f1f52
fe8f506 from http://virtual.aiai.ed.ac.uk:8002/ [^]
09:57:25 - [HGUUIDGatherer]: Failed to fetch asset 9a728b41-4ba0-4729-4db7-14bc3
d3df741 from http://virtual.aiai.ed.ac.uk:8002/ [^]
09:57:25 - [HGUUIDGatherer]: Failed to fetch asset f3300ad9-3462-1d07-2044-0fef8
0062da0 from http://virtual.aiai.ed.ac.uk:8002/ [^]
09:57:25 - [HGUUIDGatherer]: Failed to fetch asset c8e42d32-7310-6906-c903-cab5d
4a34656 from http://virtual.aiai.ed.ac.uk:8002/ [^]
09:57:25 - [HGUUIDGatherer]: Failed to fetch asset 85428680-6bf9-3e64-b489-6f810
87c24bd from http://virtual.aiai.ed.ac.uk:8002/ [^]
09:57:26 - [HGUUIDGatherer]: Failed to fetch asset eefc79be-daae-a239-8c04-890f5
d23654a from http://virtual.aiai.ed.ac.uk:8002/ [^]
09:57:26 - [HGUUIDGatherer]: Failed to fetch asset c541c47f-e0c0-058b-ad1a-d6ae3
a4584d9 from http://virtual.aiai.ed.ac.uk:8002/ [^]
09:57:26 - [SCENEGRAPH]: Scene graph for OpenVCE already contains object 47b07c1
1-2213-4a6e-b95b-897ad63391f1 in AddSceneObject()
09:57:26 - [HG ENTITY TRANSFER MODULE]: Incoming attachement Musician Female Sho
e Left Enlarged for HG user e24a9015-f5ca-452b-8c95-d32e34cb9d64 with asset serv
er http://virtual.aiai.ed.ac.uk:8002/ [^]
09:57:26 - [SCENEGRAPH]: Scene graph for OpenVCE already contains object 0a6a7b5
3-86b7-48b2-a5e1-c8afe6c984c7 in AddSceneObject()
09:57:26 - [HG ENTITY TRANSFER MODULE]: Incoming attachement Musician Female Sho
e Right Enlarged for HG user e24a9015-f5ca-452b-8c95-d32e34cb9d64 with asset ser
ver http://virtual.aiai.ed.ac.uk:8002/ [^]
09:57:46 - [SCENE]: Found presence Ai.Austin @virtual.aiai.ed.ac.uk e24a9015-f5c
a-452b-8c95-d32e34cb9d64 child in OpenVCE after 21 waits
09:57:46 - [BASE HTTP SERVER]: Slow handling of 29 PUT /agent/e24a9015-f5ca-452b
-8c95-d32e34cb9d64/ from 129.215.219.86:49921 took 22433ms
09:57:46 - [AGENT HANDLER]: >>> DELETE <<< RegionID: 2a2c51ed-7846-4536-8503-dc3
32c6c0804; from: 129.215.219.86; auth_code: 808ffa58-98c8-4515-b64f-afdf9c2feb62

09:57:46 - [CLIENT]: Close has been called for Ai.Austin @virtual.aiai.ed.ac.uk
attached to scene OpenVCE
09:57:46 - [SCENE]: Removing child agent Ai.Austin @virtual.aiai.ed.ac.uk e24a90
15-f5ca-452b-8c95-d32e34cb9d64 from OpenVCE
09:57:46 - [CAPS]: Remove caps for agent e24a9015-f5ca-452b-8c95-d32e34cb9d64 in
 region OpenVCE

(0024387)
aiaustin (developer)
2013-09-23 02:27

Small issue.. I notice a typo on one of the mesages.. attachment has an incorrectly spelling...

[HG ENTITY TRANSFER MODULE]: Incoming attachement
(0024388)
aiaustin (developer)
2013-09-23 02:32
edited on: 2013-09-23 02:35

Things seem to be MUCH worse now, and I cannot teleport at all between Openvue grid regions and OSGRid addon regions on two different hosts. And on return to the origination region each time my attachments are all missing but in a state where I cannot just re-attach them until I relog in the viewer.

I am testing with both map typed in HG destinations (such as "http://hg.osgrid.org:80/ [^] OpenVCE" without the quotes) and via objects with osteleportAgent scripts). Both fail the same way.

I CAN though instantly HG teleport from Openvue grid regions to OSGrid Wright Plaza and Sandbox Plaza! And thats seems to restore the missing attachments when I do so EXCEPT that I get the attached object (part of an AO HUD item in this case) in the middle HUD position issue then! So that may be helpful to pin something down.

(0024390)
Mata Hari (reporter)
2013-09-23 04:34
edited on: 2013-09-23 04:35

Another tidbit of information that may or may not be related...when making an HG tp (with fail>immediate retry) it does not appear that the destination region's region windlight or parcel audio stream (music) data is being sent to my viewer. Even if I toggle music off/on or toggle it off prior to tp and only toggle it on once I've arrived it will not update until I actually go into the parcel details menu (and even then sometimes I have to do this multiple times and/or toggle audio stream off/on multiple times after viewing parcel details) before it will finally pick up the new stream. Windlight settings are the same story...if I toggle through a few of my own stored windlight settings and then return to region and/or if I go into region environment settings it will eventually give me the correct ones for the destination but until then I'm stuck with the settings from the region I was in previously.

This only seems to happen with the HG tps (which are always fail/retry) and does not occur with tps inside my own simulator.


EDIT: note that all of my testing is on Win7 x64 for both sim and viewer

(0024391)
aiaustin (developer)
2013-09-23 05:07
edited on: 2013-09-23 05:15

After trying a range of things I found that completely turning off the WINDOWS level firewall on the Windows Vista system on which the OpenSim.exe for our OSGrid regions were running allowed me to HG teleport into those regions from the Openvue grid.

So I dug around further. I had a LOT of unnamed entries in the firewall exceptions list. All turned out to be OpenSim.exe or Robust.exe entries from a long history of trials and tests as well as the current locations. For some reason when OpenSim.exe or Robust.exe are run on Windows no program name given to the system. All my other firewall entries had names. See attached image "Windows-Vista-Firewall-for-OpenSim.jpg".

I deleted all of the unnamed fgirewall exception entries, turned back on the Windows Vista firewall and restarted OpenSim.exe and, as usual when a new program tries to use ports that need to go through the firewall, it asked me if I wished to unblock the program which I allowed.

After that I could teleport into the regions on that machine.

(0024392)
aiaustin (developer)
2013-09-23 05:41
edited on: 2013-09-23 06:02

Spoke a bit too soon... on the next restart of the OSGrid OpenSim.exe instance with the firewall still turned on.. it was failing again.

I had to toggle the firewall off and then it worked, and then I could turn it on an it STILL worked.

Then after it worked, just leaving it idle for 10 minutes and trying again having logged back in with Firestorm 4.4.2 it was failing once more with no other activity having taken place on the OpenSim.exe console!

I am trying to pin down exactly when it works and when it does not!

(0024393)
aiaustin (developer)
2013-09-23 06:05
edited on: 2013-09-23 06:11

Whe I did get back in on a TP to OSGRid region from openvue grid on one attempt, my hair attachment was missing, but I did arrive... but when I tried to teleport back home I got a red error and was not taken back to the home grid. I tried again and got the same error but I did arrive back in spite of that.. and my hair reappeared.... but I could not move. I had to relog.

Note the "Object reference not set to an instance of an object" exception and message "should not exit directly from state Transferring, should go to CleaningUp state first " below...

14:03:14 - [HG ENTITY TRANSFER MODULE]: CreateAgent http://virtual.aiai.ed.ac.uk [^]
:8002/ http://virtual0.aiai.ed.ac.uk:9000/ [^]
14:03:14 - [USER AGENT CONNECTOR]: new connector to http://virtual.aiai.ed.ac.uk [^]
:8002/ (http://129.215.219.86:8002/ [^])
Region (root) # >>> LoginAgentToGrid <<< http://129.215.219.86:8002/ [^]
14:03:14 - [REMOTE SIMULATION CONNECTOR]: Creating agent at http://129.215.219.8 [^]
6:8002/
14:03:14 - [ENTITY TRANSFER MODULE]: Determined that region Openvue at 0,0 needs
 new child agent for agent Ai.Austin @virtual.aiai.ed.ac.uk from OpenVCE
14:03:14 - [ENTITY TRANSFER MODULE]: Sending new CAPS seed url http://virtual0.a [^]
iai.ed.ac.uk:9000/CAPS/dd32d5f3-e4f0-4b63-9294-2e54e1369c5a0000/ from OpenVCE to
 Ai.Austin @virtual.aiai.ed.ac.uk
14:03:14 - [ENTITY TRANSFER MODULE]: Exception on teleport of Ai.Austin @virtual
.aiai.ed.ac.uk from <128.105, 128.4644, 23.26649>@OpenVCE to <130.2453, 129.0097
, 28.57001>@Openvue: Object reference not set to an instance of an object. at
OpenSim.Region.Framework.Scenes.SceneObjectGroup.CopyRootPart(SceneObjectPart pa
rt, UUID cAgentID, UUID cGroupID, Boolean userExposed) in k:\OSGRID\opensim-53de
6d9\OpenSim\Region\Framework\Scenes\SceneObjectGroup.cs:line 1588
14:03:14 - [ENTITY TRANSFER STATE MACHINE]: Agent with ID e24a9015-f5ca-452b-8c9
5-d32e34cb9d64 should not exit directly from state Transferring, should go to Cl
eaningUp state first in OpenVCE
14:03:14 - [ENTITY TRANSFER STATE MACHINE]: Agent e24a9015-f5ca-452b-8c95-d32e34
cb9d64 cleared from transit in OpenVCE


---------
Then in the OSGrid region openSim.exe console... after a LONG time, and long after the viewer had been closed on the stuck avatar on the home grid (Openvue grid)...

Region (root) #
14:09:16 - [LLUDPSERVER]: No packets received from child agent of Ai.Austin @vir
tual.aiai.ed.ac.uk for 60000ms in Vue-6400. Disconnecting.
14:09:16 - [CLIENT]: Close has been called for Ai.Austin @virtual.aiai.ed.ac.uk
attached to scene Vue-6400
14:09:16 - [SCENE]: Removing child agent Ai.Austin @virtual.aiai.ed.ac.uk e24a90
15-f5ca-452b-8c95-d32e34cb9d64 from Vue-6400
14:09:16 - [CAPS]: Remove caps for agent e24a9015-f5ca-452b-8c95-d32e34cb9d64 in
 region Vue-6400
14:09:19 - [LLUDPSERVER]: No packets received from root agent of Ai.Austin @virt
ual.aiai.ed.ac.uk for 60000ms in OpenVCE. Disconnecting.
14:09:19 - [CLIENT]: Close has been called for Ai.Austin @virtual.aiai.ed.ac.uk
attached to scene OpenVCE
14:09:20 - [USER AGENT CONNECTOR]: new connector to http://virtual.aiai.ed.ac.uk [^]
:8002/ (http://129.215.219.86:8002/ [^])
14:09:20 - [SCENE]: Removing root agent Ai.Austin @virtual.aiai.ed.ac.uk e24a901
5-f5ca-452b-8c95-d32e34cb9d64 from OpenVCE
14:09:20 - [CAPS]: Remove caps for agent e24a9015-f5ca-452b-8c95-d32e34cb9d64 in
 region OpenVCE
14:09:20 - [SCENE COMMUNICATION SERVICE]: Sending close agent ID e24a9015-f5ca-4
52b-8c95-d32e34cb9d64 to Vue-6400
14:09:20 - [SCENE]: Request to close agent e24a9015-f5ca-452b-8c95-d32e34cb9d64
but no such agent in scene Vue-6400. May have been closed previously.
14:09:20 - [SCENE COMMUNICATION SERVICE]: Sending close agent ID e24a9015-f5ca-4
52b-8c95-d32e34cb9d64 to Sea-Vue
14:09:20 - [REMOTE SIMULATION CONNECTOR]: CloseAgent http://virtual1.aiai.ed.ac. [^]
uk:9000/agent/e24a9015-f5ca-452b-8c95-d32e34cb9d64/942b6318-f11f-4a18-b362-b8785
74297cc/?auth=fa2c44fb-2ef4-46b1-8f0c-95ac0c1c8848
14:09:20 - [SCENE COMMUNICATION SERVICE]: Sending close agent ID e24a9015-f5ca-4
52b-8c95-d32e34cb9d64 to AI
14:09:20 - [REMOTE SIMULATION CONNECTOR]: CloseAgent http://virtual1.aiai.ed.ac. [^]
uk:9000/agent/e24a9015-f5ca-452b-8c95-d32e34cb9d64/a2df9626-302a-4c4c-8e3a-fafd0
2955226/?auth=fa2c44fb-2ef4-46b1-8f0c-95ac0c1c8848
14:09:20 - [SCENE COMMUNICATION SERVICE]: Sending close agent ID e24a9015-f5ca-4
52b-8c95-d32e34cb9d64 to Vue-Rig
14:09:20 - [REMOTE SIMULATION CONNECTOR]: CloseAgent http://virtual1.aiai.ed.ac. [^]
uk:9000/agent/e24a9015-f5ca-452b-8c95-d32e34cb9d64/e9d193ea-1e82-4f35-a6b3-3745c
758eb84/?auth=fa2c44fb-2ef4-46b1-8f0c-95ac0c1c8848
14:09:20 - [SCENE]: Exception removing Ai.Austin @virtual.aiai.ed.ac.uk from Ope
nVCE. Cleaning up. Exception System.NullReferenceException: Object reference n
ot set to an instance of an object.

(0024394)
kenvc (reporter)
2013-09-23 11:52

Neb confirmed to me that he was also having major TP issues at the plazas. He is not using Windows so it doesn't appear to be isolated just to the Windows OS.

He reverted to an earlier revision and the TP issues at the plazas cleared up, but have no idea what he reverted to.
(0024397)
justincc (administrator)
2013-09-25 11:49
edited on: 2013-09-25 11:51

Okay, it turns out that in commit 7dbc93c (Wed Sep 18 21:41:51 2013 +0100), I introduced a regression that greatly increased teleport failures, though the incidence is timing dependent (so some may see it occasionally, others may see it a lot).

This would have masked any improvement from lengthening the CompleteAgentMovement timeout or making sure threads weren't relying on cached copies of ScenePresence.m_originRegionID.

The regression is now fixed in git master 32ddfc2 so please retest. All these changes require the destination simulator to update. At the time of writing, "Recreation Plaza" and "Sandbox Plaza II" are running this latest code.

@kenvc - Logging levels are controlled in OpenSim.exe.config. See [1] for more details.

[1] http://opensimulator.org/wiki/Logging [^]

(0024398)
Mata Hari (reporter)
2013-09-25 14:28

An encouraging result on my first test of a HG tp to Plaza II...success on the first attempt. I'll continue to test that jump periodically over the next few days and see how reliable it is.
(0024399)
justincc (administrator)
2013-09-25 16:19

It's unclear at this point, but it's also possible that long jumps (>4096) are still problematic. So if you are long jumping, please try a shorter jump instead. Also, please try different viewers - there may be remaining bugs in recent Singularity alpha builds.
(0024400)
kenvc (reporter)
2013-09-25 19:06

I have updated to the latest code as of this evening. The changes appear to have resolved all in-grid teleports that I have tried, so great job Justin for finding and fixing this issue.

The only remaining issue I have found is that unless someone is on a pretty fast connection with their viewer, if they try to teleport from OSGrid sim with the latest code to my test grid also with the latest code, it fails. The destination grid complains that it does not detect the AV presence. Sometimes the viewer freezes 1/2 way through the TP and you even get to see part of the scene at the destination grid, and other times you end up back in OSG with a message that it was unable to establish a connection. Several other people with aslower connections have experienced the same thing. (up to 1.5mb down, and up to 1mb up)
(0024401)
aiaustin (developer)
2013-09-26 02:51

Openvue grid Robust services and all region servers now updated to 0.7.6 dev 25-Sep-2013 r/23693.

Initial tests between the various local regions on different servers and between Openvue regions and the two suggested updated OSGrid regions ("Recreation Plaza" and "Sandbox Plaza II") are working fast and smooth in initial tests - just like the "old days" :-)
(0024488)
Mata Hari (reporter)
2013-10-16 15:11

Just to follow up on this, after a couple weeks where HG tps to those two regions (Sandbox II and LBSA) were working smoothly, in the last 2 weeks it's gone back to always failing on the 1st tp attempt and only succeeding if you immediately re-attempt the tp as soon as the 1st attempt fails. If you want copies of the logs I can make some for you.
(0024558)
justincc (administrator)
2013-10-22 16:36

@Mata I would want to see a copy of those logs.
(0024559)
Mata Hari (reporter)
2013-10-22 17:05

@Justin: here's an attempt made to HGTP to Sandbox Plaza II a couple minutes ago. I'm currently running r/23962 opensim-a7e7bed.


20:00:53 - [HYPERGRID LINKER]: Link to hg.osgrid.org:80 sandbox plaza ii, in 30547-0
20:00:53 - [GATEKEEPER SERVICE CONNECTOR]: Linking to http://hg.osgrid.org:80/ [^]
20:00:54 - [HYPERGRID LINKER]: naming linked region http://hg.osgrid.org:80/ [^] sandbox plaza ii, handle 11245804931485440
20:00:54 - [GATEKEEPER SERVICE CONNECTOR]: Map image at http://plaza09.osgrid.org:9303/index.php?method=regionImage1703c400a3e311de8a390800200c9a66, [^] cached at maptiles\1703c400-a3e
3-11de-8a39-0800200c9a66.jpg
20:00:54 - [GATEKEEPER SERVICE CONNECTOR]: downloading...
20:00:54 - [HYPERGRID LINKER]: Successfully linked to region http://hg.osgrid.org:80/ [^] sandbox plaza ii with image e46feed5-b402-49b9-8d4f-c626de293aca
20:00:54 - [MAPSEARCHMODULE]: search hg.osgrid.org:80:sandbox plaza ii returned 1 regions. Flags=2
20:00:54 - [HYPERGRID LINKER]: Link to hg.osgrid.org:80 sandbox plaza ii, in 28945-0
20:00:54 - [GATEKEEPER SERVICE CONNECTOR]: Linking to http://hg.osgrid.org:80/ [^]
20:00:54 - [HYPERGRID LINKER]: Region already exists in coordinates 30547 0
20:00:54 - [MAPSEARCHMODULE]: search hg.osgrid.org:80:sandbox plaza ii returned 1 regions. Flags=2
20:00:57 - [HG ENTITY TRANSFER MODULE]: region http://hg.osgrid.org:80/ [^] sandbox plaza ii flags: 524
20:00:57 - [HG ENTITY TRANSFER MODULE]: Destination region is hyperlink
20:00:57 - [GATEKEEPER SERVICE CONNECTOR]: contacting http://hg.osgrid.org:80/ [^]
20:00:58 - [HG ENTITY TRANSFER MODULE]: GetFinalDestination serveruri -> http://plaza09.osgrid.org:9303/ [^]
20:00:58 - [ENTITY TRANSFER MODULE]: Teleporting Aine Caoimhe ce40214d-7737-47f5-af49-b685bfbb5dec from Paramour to http://hg.osgrid.org:80/ [^] (http://plaza09.osgrid.org:9303/ [^]) Sandb
ox Plaza II/<128, 128, 1.5>
20:00:58 - [REMOTE SIMULATION CONNECTOR]: QueryAccess to http://plaza09.osgrid.org:9303/agent/ce40214d-7737-47f5-af49-b685bfbb5dec/1703c400-a3e3-11de-8a39-0800200c9a66/ [^] returned Tr
ue, reason , version SIMULATION/0.2 (SIMULATION/0.2)
20:00:58 - [ENTITY TRANSFER MODULE]: Paramour max transfer version is SIMULATION/0.2, Sandbox Plaza II max version is SIMULATION/0.2
20:00:58 - [HG ENTITY TRANSFER MODULE]: CreateAgent http://hg.osgrid.org:80/ [^] http://plaza09.osgrid.org:9303/ [^]
20:00:58 - [USER AGENT SERVICE]: Request to login user Aine Caoimhe (@stored IP) to grid http://hg.osgrid.org:80/ [^]
20:00:58 - [USER AGENT SERVICE]: this grid: http://aine.x64.me:9000/, [^] desired grid: http://hg.osgrid.org:80/, [^] desired region: 1703c400-a3e3-11de-8a39-0800200c9a66
20:00:58 - [REMOTE SIMULATION CONNECTOR]: Creating agent at http://hg.osgrid.org:80/ [^]
20:00:58 - [USER AGENT SERVICE]: Verifying agent token http://hg.osgrid.org:80/;b0a8f7e0-e2cf-4626-9ac0-adf9f8465705 [^] against http://hg.osgrid.org:80/;b0a8f7e0-e2cf-4626-9ac0-adf9f8 [^]
465705
20:00:59 - [USER AGENT SERVICE]: Gatekeeper sees me as 99.225.68.153
20:00:59 - [HG INVENTORY ACCESS MODULE]: Changing root inventory for user Aine Caoimhe
20:00:59 - [ENTITY TRANSFER MODULE]: Determined that region Sandbox Plaza II at 30547,0 needs new child agent for agent Aine Caoimhe from Paramour
20:00:59 - [ENTITY TRANSFER MODULE]: Sending new CAPS seed url http://plaza09.osgrid.org:9303/CAPS/3362764a-0cf6-4802-babd-0c012e6b38740000/ [^] from Paramour to Aine Caoimhe
20:01:00 - [USER AGENT SERVICE]: Verifying Client session 5b73ba17-3d9c-40c8-ac3f-673907994386 with reported IP 99.225.68.153.
20:01:00 - [USER AGENT SERVICE]: Comparing 99.225.68.153 with login IP 99.225.68.153 and MyIP 99.225.68.153; result is True
20:01:02 - [USER MANAGEMENT MODULE]: No grid user found for 98dfb447-45ad-4eaf-9fdf-cd7db77b8ca9
20:01:02 - [USER MANAGEMENT MODULE]: No grid user found for 98dfb447-45ad-4eaf-9fdf-cd7db77b8ca9
20:01:38 - [WEB UTIL]: Slow ServiceOSD request 5 PUT http://plaza09.osgrid.org:9303/agent/ce40214d-7737-47f5-af49-b685bfbb5dec/ [^] took 39000ms, 765ms writing, {"message_type":"AgentD
ata","region_id":"f3c6f1b0-b5d1-11e2-9e96-0800200c9a66","circuit_code":"0","a
20:01:57 - [USER MANAGEMENT MODULE]: No grid user found for e21666b2-d7e2-40eb-8e97-2e6360fe4849
20:01:58 - [USER MANAGEMENT MODULE]: No grid user found for e21666b2-d7e2-40eb-8e97-2e6360fe4849
20:02:13 - [WEB UTIL]: Slow ServiceOSD request 6 PUT http://plaza09.osgrid.org:9303/agent/ce40214d-7737-47f5-af49-b685bfbb5dec/ [^] took 35647ms, 375ms writing, {"message_type":"AgentD
ata","region_id":"f3c6f1b0-b5d1-11e2-9e96-0800200c9a66","circuit_code":"0","a
20:02:13 - [ENTITY TRANSFER MODULE]: UpdateAgent failed on teleport of Aine Caoimhe to Sandbox Plaza II. Keeping avatar in Paramour
20:02:13 - [REMOTE SIMULATION CONNECTOR]: CloseAgent http://plaza09.osgrid.org:9303/agent/ce40214d-7737-47f5-af49-b685bfbb5dec/1703c400-a3e3-11de-8a39-0800200c9a66/?auth=5b73ba17-3 [^]
d9c-40c8-ac3f-673907994386
20:02:14 - [HG INVENTORY ACCESS MODULE]: Restoring root folder for local user Aine Caoimhe
20:02:14 - [ENTITY TRANSFER STATE MACHINE]: Agent ce40214d-7737-47f5-af49-b685bfbb5dec cleared from transit in Paramour
20:02:19 - [HG ENTITY TRANSFER MODULE]: region http://hg.osgrid.org:80/ [^] sandbox plaza ii flags: 524
20:02:19 - [HG ENTITY TRANSFER MODULE]: Destination region is hyperlink
20:02:19 - [GATEKEEPER SERVICE CONNECTOR]: contacting http://hg.osgrid.org:80/ [^]
20:02:20 - [HG ENTITY TRANSFER MODULE]: GetFinalDestination serveruri -> http://plaza09.osgrid.org:9303/ [^]
20:02:20 - [ENTITY TRANSFER MODULE]: Teleporting Aine Caoimhe ce40214d-7737-47f5-af49-b685bfbb5dec from Paramour to http://hg.osgrid.org:80/ [^] (http://plaza09.osgrid.org:9303/ [^]) Sandb
ox Plaza II/<128, 128, 1.5>
20:02:20 - [REMOTE SIMULATION CONNECTOR]: QueryAccess to http://plaza09.osgrid.org:9303/agent/ce40214d-7737-47f5-af49-b685bfbb5dec/1703c400-a3e3-11de-8a39-0800200c9a66/ [^] returned Tr
ue, reason , version SIMULATION/0.2 (SIMULATION/0.2)
20:02:20 - [ENTITY TRANSFER MODULE]: Paramour max transfer version is SIMULATION/0.2, Sandbox Plaza II max version is SIMULATION/0.2
20:02:20 - [HG ENTITY TRANSFER MODULE]: CreateAgent http://hg.osgrid.org:80/ [^] http://plaza09.osgrid.org:9303/ [^]
20:02:20 - [USER AGENT SERVICE]: Request to login user Aine Caoimhe (@stored IP) to grid http://hg.osgrid.org:80/ [^]
20:02:20 - [USER AGENT SERVICE]: this grid: http://aine.x64.me:9000/, [^] desired grid: http://hg.osgrid.org:80/, [^] desired region: 1703c400-a3e3-11de-8a39-0800200c9a66
20:02:20 - [REMOTE SIMULATION CONNECTOR]: Creating agent at http://hg.osgrid.org:80/ [^]
20:02:20 - [USER AGENT SERVICE]: Verifying agent token http://hg.osgrid.org:80/;61037cbe-f2b4-42a0-a6ae-f5cd5135d090 [^] against http://hg.osgrid.org:80/;61037cbe-f2b4-42a0-a6ae-f5cd51 [^]
35d090
20:02:21 - [USER AGENT SERVICE]: Gatekeeper sees me as 99.225.68.153
20:02:21 - [HG INVENTORY ACCESS MODULE]: Changing root inventory for user Aine Caoimhe
20:02:21 - [ENTITY TRANSFER MODULE]: Determined that region Sandbox Plaza II at 30547,0 needs new child agent for agent Aine Caoimhe from Paramour
20:02:21 - [ENTITY TRANSFER MODULE]: Sending new CAPS seed url http://plaza09.osgrid.org:9303/CAPS/4a89c427-252e-4782-ae72-7e7b5f12c7020000/ [^] from Paramour to Aine Caoimhe
20:02:22 - [HELO]: hi, GET was called
20:02:22 - [HELO]: hi, GET was called
20:02:30 - [HG SUITCASE INVENTORY SERVICE]: GetRootFolder for ce40214d-7737-47f5-af49-b685bfbb5dec
20:02:39 - [WEB UTIL]: Slow ServiceOSD request 10 PUT http://plaza09.osgrid.org:9303/agent/ce40214d-7737-47f5-af49-b685bfbb5dec/ [^] took 18408ms, 780ms writing, {"message_type":"Agent
Data","region_id":"f3c6f1b0-b5d1-11e2-9e96-0800200c9a66","circuit_code":"0","a
20:02:39 - [SCENE PRESENCE]: Closing child agents. Checking 1 regions in Paramour
20:02:39 - [PRESENCE SERVICE]: Session 5b73ba17-3d9c-40c8-ac3f-673907994386 logout
20:02:39 - [GRID USER SERVICE]: User ce40214d-7737-47f5-af49-b685bfbb5dec is offline
20:02:39 - [SCENE PRESENCE]: Making Aine Caoimhe a child agent in Paramour
20:02:54 - [ENTITY TRANSFER MODULE]: Closing agent Aine Caoimhe in Paramour after teleport
20:02:54 - [CLIENT]: Close has been called for Aine Caoimhe attached to scene Paramour
20:02:54 - [SCENE]: Removing child agent Aine Caoimhe ce40214d-7737-47f5-af49-b685bfbb5dec from Paramour
20:02:54 - [CAPS]: Remove caps for agent ce40214d-7737-47f5-af49-b685bfbb5dec in region Paramour
20:02:54 - [ENTITY TRANSFER STATE MACHINE]: Agent ce40214d-7737-47f5-af49-b685bfbb5dec cleared from transit in Paramour

As you can see, it failed after timeout after which I immediately initiated the tp again and it succeeded very rapidly
(0024560)
justincc (administrator)
2013-10-22 17:08

Okay, I'll try and dig out the osgrid side log soon and match the two.

I see this is using SIMULATION/0.2 teleport protocol. It would also be good if you could compare what happens when your simulator forces the older SIMULATION/0.1 to be used, with the instructions at [1]

[1] http://opensimulator.org/wiki/Teleports#Configuration [^]
(0024561)
Mata Hari (reporter)
2013-10-22 17:10

I should add a note that all return trips (even if hours later) to my own grid will succeed on the first attempt. It's only the outbound tp attempts that fail (and are currently always failing on attempt 0000001).

Viewer used is Firestorm 4.2.2 (34167) Opensim version
(0024562)
justincc (administrator)
2013-10-22 17:15

Have you tried newer versions of Firestorm or other viewers? There are reports that some people have seen this problem only on Firestorm.
(0024563)
Mata Hari (reporter)
2013-10-22 17:17

As per your request, changed to SIMULATION/0.1 and retried. Success on first attempt.

20:15:47 - [HYPERGRID LINKER]: Link to hg.osgrid.org:80 sandbox plaza ii, in 27420-0
20:15:47 - [GATEKEEPER SERVICE CONNECTOR]: Linking to http://hg.osgrid.org:80/ [^]
20:15:47 - [HYPERGRID LINKER]: naming linked region http://hg.osgrid.org:80/ [^] sandbox plaza ii, handle 11245804931485440
20:15:47 - [GATEKEEPER SERVICE CONNECTOR]: Map image at http://plaza09.osgrid.org:9303/index.php?method=regionImage1703c400a3e311de8a390800200c9a66, [^] cached at maptiles\1703c400-a3e
3-11de-8a39-0800200c9a66.jpg
20:15:47 - [GATEKEEPER SERVICE CONNECTOR]: using cached image
20:15:47 - [HYPERGRID LINKER]: Successfully linked to region http://hg.osgrid.org:80/ [^] sandbox plaza ii with image 6bfc5682-8bb1-40cf-b981-fc395091ef39
20:15:47 - [MAPSEARCHMODULE]: search hg.osgrid.org:80:sandbox plaza ii returned 1 regions. Flags=2
20:15:47 - [HYPERGRID LINKER]: Link to hg.osgrid.org:80 sandbox plaza ii, in 11380-0
20:15:47 - [GATEKEEPER SERVICE CONNECTOR]: Linking to http://hg.osgrid.org:80/ [^]
20:15:47 - [HYPERGRID LINKER]: Region already exists in coordinates 27420 0
20:15:47 - [MAPSEARCHMODULE]: search hg.osgrid.org:80:sandbox plaza ii returned 1 regions. Flags=2
20:15:51 - [HG ENTITY TRANSFER MODULE]: region http://hg.osgrid.org:80/ [^] sandbox plaza ii flags: 524
20:15:51 - [HG ENTITY TRANSFER MODULE]: Destination region is hyperlink
20:15:51 - [GATEKEEPER SERVICE CONNECTOR]: contacting http://hg.osgrid.org:80/ [^]
20:15:51 - [HG ENTITY TRANSFER MODULE]: GetFinalDestination serveruri -> http://plaza09.osgrid.org:9303/ [^]
20:15:51 - [ENTITY TRANSFER MODULE]: Teleporting Aine Caoimhe ce40214d-7737-47f5-af49-b685bfbb5dec from Paramour to http://hg.osgrid.org:80/ [^] (http://plaza09.osgrid.org:9303/ [^]) Sandb
ox Plaza II/<128, 128, 1.5>
20:15:51 - [REMOTE SIMULATION CONNECTOR]: QueryAccess to http://plaza09.osgrid.org:9303/agent/ce40214d-7737-47f5-af49-b685bfbb5dec/1703c400-a3e3-11de-8a39-0800200c9a66/ [^] returned Tr
ue, reason , version SIMULATION/0.2 (SIMULATION/0.2)
20:15:51 - [ENTITY TRANSFER MODULE]: Paramour max transfer version is SIMULATION/0.1, Sandbox Plaza II max version is SIMULATION/0.2
20:15:51 - [ENTITY TRANSFER MODULE]: Using TP V1 for Aine Caoimhe going from Paramour to Sandbox Plaza II
20:15:51 - [HG ENTITY TRANSFER MODULE]: CreateAgent http://hg.osgrid.org:80/ [^] http://plaza09.osgrid.org:9303/ [^]
20:15:51 - [USER AGENT SERVICE]: Request to login user Aine Caoimhe (@stored IP) to grid http://hg.osgrid.org:80/ [^]
20:15:51 - [USER AGENT SERVICE]: this grid: http://aine.x64.me:9000/, [^] desired grid: http://hg.osgrid.org:80/, [^] desired region: 1703c400-a3e3-11de-8a39-0800200c9a66
20:15:51 - [REMOTE SIMULATION CONNECTOR]: Creating agent at http://hg.osgrid.org:80/ [^]
20:15:52 - [USER AGENT SERVICE]: Verifying agent token http://hg.osgrid.org:80/;ba11ce86-385c-441e-b1bc-cf6e911fa1bd [^] against http://hg.osgrid.org:80/;ba11ce86-385c-441e-b1bc-cf6e91 [^]
1fa1bd
20:15:52 - [USER AGENT SERVICE]: Gatekeeper sees me as 99.225.68.153
20:15:52 - [HG INVENTORY ACCESS MODULE]: Changing root inventory for user Aine Caoimhe
20:15:52 - [SCENE PRESENCE]: Closing child agents. Checking 1 regions in Paramour
20:15:52 - [ENTITY TRANSFER MODULE]: Determined that region Sandbox Plaza II at 27420,0 needs new child agent for incoming agent Aine Caoimhe from Paramour
20:15:52 - [ENTITY TRANSFER MODULE]: Set release callback URL to http://aine.x64.me:9000/agent/ce40214d-7737-47f5-af49-b685bfbb5dec/f3c6f1b0-b5d1-11e2-9e96-0800200c9a66/release/ [^] in
 Paramour
20:15:53 - [USER AGENT SERVICE]: Verifying Client session c1a57444-a080-40a0-9f14-3f97876c46d3 with reported IP 99.225.68.153.
20:15:53 - [USER AGENT SERVICE]: Comparing 99.225.68.153 with login IP 99.225.68.153 and MyIP 99.225.68.153; result is True
20:15:56 - [USER MANAGEMENT MODULE]: No grid user found for 91687b8f-2fd9-4f71-91a7-2073dc592429
20:15:56 - [USER MANAGEMENT MODULE]: No grid user found for e21666b2-d7e2-40eb-8e97-2e6360fe4849
20:15:57 - [USER MANAGEMENT MODULE]: No grid user found for 91687b8f-2fd9-4f71-91a7-2073dc592429
20:15:57 - [USER MANAGEMENT MODULE]: No grid user found for e21666b2-d7e2-40eb-8e97-2e6360fe4849
20:16:06 - [WEB UTIL]: Slow ServiceOSD request 5 PUT http://plaza09.osgrid.org:9303/agent/ce40214d-7737-47f5-af49-b685bfbb5dec/ [^] took 13806ms, 780ms writing, {"message_type":"AgentD
ata","region_id":"f3c6f1b0-b5d1-11e2-9e96-0800200c9a66","circuit_code":"0","a
20:16:06 - [ENTITY TRANSFER MODULE]: Sending new CAPS seed url http://plaza09.osgrid.org:9303/CAPS/d8f20644-ae8b-43c9-96eb-3fa46b6ef9730000/ [^] from Paramour to Aine Caoimhe
20:16:07 - [AGENT HANDLER]: Release ce40214d-7737-47f5-af49-b685bfbb5dec to RegionID: f3c6f1b0-b5d1-11e2-9e96-0800200c9a66
20:16:07 - [PRESENCE SERVICE]: Session c1a57444-a080-40a0-9f14-3f97876c46d3 logout
20:16:07 - [GRID USER SERVICE]: User ce40214d-7737-47f5-af49-b685bfbb5dec is offline
20:16:07 - [SCENE PRESENCE]: Making Aine Caoimhe a child agent in Paramour
20:16:07 - [USER AGENT SERVICE]: Verifying Client session c1a57444-a080-40a0-9f14-3f97876c46d3 with reported IP 99.225.68.153.
20:16:07 - [USER AGENT SERVICE]: Comparing 99.225.68.153 with login IP 99.225.68.153 and MyIP 99.225.68.153; result is True
20:16:09 - [CLIENT]: Close has been called for Aine Caoimhe attached to scene Paramour
20:16:09 - [SCENE]: Removing child agent Aine Caoimhe ce40214d-7737-47f5-af49-b685bfbb5dec from Paramour
20:16:09 - [CAPS]: Remove caps for agent ce40214d-7737-47f5-af49-b685bfbb5dec in region Paramour
20:16:09 - [ENTITY TRANSFER STATE MACHINE]: Agent ce40214d-7737-47f5-af49-b685bfbb5dec cleared from transit in Paramour
(0024564)
Mata Hari (reporter)
2013-10-22 17:19

@Justin

I haven't tried any of the beta Firestorm builds...just the current "official" release version. I have also tried using Kokua (attempt made perhaps 2-3 weeks ago) with identical results.
(0024565)
smxy (reporter)
2013-10-22 17:20

Mata, you said Firestorm 4.2.2, but the current version is 4.4.2. Did you simply make a typo?
(0024566)
Mata Hari (reporter)
2013-10-22 17:23

Yes, apologies, that should be 4.4.2.

Full details:

Firestorm 4.4.2 (34167) Jul 2 2013 00:49:02 (Firestorm-Release) with OpenSimulator support
Release Notes

You are at 2,048,080.0, 2,048,130.0, 21.2 in Paramour located at CPE18593343574b-CM185933435748.cpe.net.cable.rogers.com (99.225.68.153:9000)
OpenSim 0.8.0 Dev (Win/.NET)
Error fetching server release notes URL.

CPU: Intel(R) Core(TM) i7 CPU 930 @ 2.80GHz (2800.02 MHz)
Memory: 12279 MB
OS Version: Microsoft Windows 7 64-bit Service Pack 1 (Build 7601)
Graphics Card Vendor: ATI Technologies Inc.
Graphics Card: ATI Radeon HD 5800 Series

Windows Graphics Driver Version: 8.17.0010.1172
OpenGL Version: 4.2.12002 Compatibility Profile Context 9.12.0.0

RestrainedLove API: (disabled)
libcurl Version: libcurl/7.21.1 OpenSSL/1.0.0d zlib/1.2.5 c-ares/1.7.1
J2C Decoder Version: KDU v7.1
Audio Driver Version: FMOD version 3.750000
Qt Webkit Version: 4.7.1 (version number hard-coded)
Voice Server Version: Vivox 2.1.3010.6270

Settings mode: Firestorm
Viewer Skin: Firestorm (Grey)
Font Used: Deja Vu (96)
Draw distance: 128
Bandwidth: 1250
LOD factor: 4
Render quality: Ultra (7/7)
Built with MSVC version 1600
Packets Lost: 0/7,913 (0.0%)
(0024567)
Mata Hari (reporter)
2013-10-22 17:40

Just to double-check, I downloaded the latest Singularity viewer version 1.8.3 (4998) Sept 18 2013 and switched my simulator back to use SIMULATION/0.2. As far as I can tell it was an identical result to using Firestorm...failed on 1st attempt and success on immediate retry.

20:36:12 - [HYPERGRID LINKER]: Link to hg.osgrid.org:80 sandbox plaza ii, in 4425-0
20:36:12 - [GATEKEEPER SERVICE CONNECTOR]: Linking to http://hg.osgrid.org:80/ [^]
20:36:12 - [HYPERGRID LINKER]: Region already exists in coordinates 24385 0
20:36:12 - [MAPSEARCHMODULE]: search hg.osgrid.org:80:sandbox plaza ii returned 1 regions. Flags=2
20:36:12 - [HYPERGRID LINKER]: Link to hg.osgrid.org:80 sandbox plaza ii, in 30057-0
20:36:12 - [GATEKEEPER SERVICE CONNECTOR]: Linking to http://hg.osgrid.org:80/ [^]
20:36:12 - [HYPERGRID LINKER]: Region already exists in coordinates 24385 0
20:36:12 - [MAPSEARCHMODULE]: search hg.osgrid.org:80:sandbox plaza ii returned 1 regions. Flags=2
20:36:14 - [HG ENTITY TRANSFER MODULE]: region http://hg.osgrid.org:80/ [^] sandbox plaza ii flags: 524
20:36:14 - [HG ENTITY TRANSFER MODULE]: Destination region is hyperlink
20:36:14 - [GATEKEEPER SERVICE CONNECTOR]: contacting http://hg.osgrid.org:80/ [^]
20:36:14 - [HG ENTITY TRANSFER MODULE]: GetFinalDestination serveruri -> http://plaza09.osgrid.org:9303/ [^]
20:36:14 - [ENTITY TRANSFER MODULE]: Teleporting Aine Caoimhe ce40214d-7737-47f5-af49-b685bfbb5dec from Paramour to http://hg.osgrid.org:80/ [^] (http://plaza09.osgrid.org:9303/ [^]) Sandb
ox Plaza II/<128, 128, 2.45>
20:36:14 - [REMOTE SIMULATION CONNECTOR]: QueryAccess to http://plaza09.osgrid.org:9303/agent/ce40214d-7737-47f5-af49-b685bfbb5dec/1703c400-a3e3-11de-8a39-0800200c9a66/ [^] returned Tr
ue, reason , version SIMULATION/0.2 (SIMULATION/0.2)
20:36:14 - [ENTITY TRANSFER MODULE]: Paramour max transfer version is SIMULATION/0.2, Sandbox Plaza II max version is SIMULATION/0.2
20:36:14 - [HG ENTITY TRANSFER MODULE]: CreateAgent http://hg.osgrid.org:80/ [^] http://plaza09.osgrid.org:9303/ [^]
20:36:14 - [USER AGENT SERVICE]: Request to login user Aine Caoimhe (@stored IP) to grid http://hg.osgrid.org:80/ [^]
20:36:14 - [USER AGENT SERVICE]: this grid: http://aine.x64.me:9000/, [^] desired grid: http://hg.osgrid.org:80/, [^] desired region: 1703c400-a3e3-11de-8a39-0800200c9a66
20:36:14 - [REMOTE SIMULATION CONNECTOR]: Creating agent at http://hg.osgrid.org:80/ [^]
20:36:15 - [USER AGENT SERVICE]: Verifying agent token http://hg.osgrid.org:80/;642b6bb0-d684-416f-b365-faa9e87e448c [^] against http://hg.osgrid.org:80/;642b6bb0-d684-416f-b365-faa9e8 [^]
7e448c
20:36:15 - [USER AGENT SERVICE]: Gatekeeper sees me as 99.225.68.153
20:36:15 - [HG INVENTORY ACCESS MODULE]: Changing root inventory for user Aine Caoimhe
20:36:15 - [ENTITY TRANSFER MODULE]: Determined that region Sandbox Plaza II at 24385,0 needs new child agent for agent Aine Caoimhe from Paramour
20:36:15 - [ENTITY TRANSFER MODULE]: Sending new CAPS seed url http://plaza09.osgrid.org:9303/CAPS/1ccc6939-4d0a-4cdd-aaf0-30f82cbd75fc0000/ [^] from Paramour to Aine Caoimhe
20:36:16 - [USER AGENT SERVICE]: Verifying Client session 874f2aba-20c1-46fb-b058-6f1e2ec1aaa0 with reported IP 99.225.68.153.
20:36:16 - [USER AGENT SERVICE]: Comparing 99.225.68.153 with login IP 99.225.68.153 and MyIP 99.225.68.153; result is True
20:36:49 - [WEB UTIL]: Slow ServiceOSD request 16 PUT http://plaza09.osgrid.org:9303/agent/ce40214d-7737-47f5-af49-b685bfbb5dec/ [^] took 33821ms, 811ms writing, {"message_type":"Agent
Data","region_id":"f3c6f1b0-b5d1-11e2-9e96-0800200c9a66","circuit_code":"0","a
20:37:22 - [WEB UTIL]: Slow ServiceOSD request 17 PUT http://plaza09.osgrid.org:9303/agent/ce40214d-7737-47f5-af49-b685bfbb5dec/ [^] took 33712ms, 328ms writing, {"message_type":"Agent
Data","region_id":"f3c6f1b0-b5d1-11e2-9e96-0800200c9a66","circuit_code":"0","a
20:37:22 - [ENTITY TRANSFER MODULE]: UpdateAgent failed on teleport of Aine Caoimhe to Sandbox Plaza II. Keeping avatar in Paramour
20:37:22 - [REMOTE SIMULATION CONNECTOR]: CloseAgent http://plaza09.osgrid.org:9303/agent/ce40214d-7737-47f5-af49-b685bfbb5dec/1703c400-a3e3-11de-8a39-0800200c9a66/?auth=874f2aba-2 [^]
0c1-46fb-b058-6f1e2ec1aaa0
20:37:23 - [HG INVENTORY ACCESS MODULE]: Restoring root folder for local user Aine Caoimhe
20:37:23 - [ENTITY TRANSFER STATE MACHINE]: Agent ce40214d-7737-47f5-af49-b685bfbb5dec cleared from transit in Paramour
20:37:27 - [HG ENTITY TRANSFER MODULE]: region http://hg.osgrid.org:80/ [^] sandbox plaza ii flags: 524
20:37:27 - [HG ENTITY TRANSFER MODULE]: Destination region is hyperlink
20:37:27 - [GATEKEEPER SERVICE CONNECTOR]: contacting http://hg.osgrid.org:80/ [^]
20:37:27 - [HG ENTITY TRANSFER MODULE]: GetFinalDestination serveruri -> http://plaza09.osgrid.org:9303/ [^]
20:37:27 - [ENTITY TRANSFER MODULE]: Teleporting Aine Caoimhe ce40214d-7737-47f5-af49-b685bfbb5dec from Paramour to http://hg.osgrid.org:80/ [^] (http://plaza09.osgrid.org:9303/ [^]) Sandb
ox Plaza II/<128, 128, 2.45>
20:37:27 - [REMOTE SIMULATION CONNECTOR]: QueryAccess to http://plaza09.osgrid.org:9303/agent/ce40214d-7737-47f5-af49-b685bfbb5dec/1703c400-a3e3-11de-8a39-0800200c9a66/ [^] returned Tr
ue, reason , version SIMULATION/0.2 (SIMULATION/0.2)
20:37:27 - [ENTITY TRANSFER MODULE]: Paramour max transfer version is SIMULATION/0.2, Sandbox Plaza II max version is SIMULATION/0.2
20:37:27 - [HG ENTITY TRANSFER MODULE]: CreateAgent http://hg.osgrid.org:80/ [^] http://plaza09.osgrid.org:9303/ [^]
20:37:27 - [USER AGENT SERVICE]: Request to login user Aine Caoimhe (@stored IP) to grid http://hg.osgrid.org:80/ [^]
20:37:27 - [USER AGENT SERVICE]: this grid: http://aine.x64.me:9000/, [^] desired grid: http://hg.osgrid.org:80/, [^] desired region: 1703c400-a3e3-11de-8a39-0800200c9a66
20:37:27 - [REMOTE SIMULATION CONNECTOR]: Creating agent at http://hg.osgrid.org:80/ [^]
20:37:28 - [USER AGENT SERVICE]: Verifying agent token http://hg.osgrid.org:80/;56fcfd23-ed41-4fed-bb3f-41e208801dd8 [^] against http://hg.osgrid.org:80/;56fcfd23-ed41-4fed-bb3f-41e208 [^]
801dd8
20:37:28 - [USER AGENT SERVICE]: Gatekeeper sees me as 99.225.68.153
20:37:28 - [HG INVENTORY ACCESS MODULE]: Changing root inventory for user Aine Caoimhe
20:37:28 - [ENTITY TRANSFER MODULE]: Determined that region Sandbox Plaza II at 24385,0 needs new child agent for agent Aine Caoimhe from Paramour
20:37:28 - [ENTITY TRANSFER MODULE]: Sending new CAPS seed url http://plaza09.osgrid.org:9303/CAPS/296e950e-4722-4ece-a1ec-5390fbc663290000/ [^] from Paramour to Aine Caoimhe
20:37:42 - [WEB UTIL]: Slow ServiceOSD request 21 PUT http://plaza09.osgrid.org:9303/agent/ce40214d-7737-47f5-af49-b685bfbb5dec/ [^] took 14461ms, 717ms writing, {"message_type":"Agent
Data","region_id":"f3c6f1b0-b5d1-11e2-9e96-0800200c9a66","circuit_code":"0","a
20:37:42 - [SCENE PRESENCE]: Closing child agents. Checking 1 regions in Paramour
20:37:42 - [PRESENCE SERVICE]: Session 874f2aba-20c1-46fb-b058-6f1e2ec1aaa0 logout
20:37:42 - [GRID USER SERVICE]: User ce40214d-7737-47f5-af49-b685bfbb5dec is offline
20:37:42 - [SCENE PRESENCE]: Making Aine Caoimhe a child agent in Paramour
(0024571)
kenvc (reporter)
2013-10-26 06:53

Teleports with the map currently seems to be working quite well using the dev master as of the date of this note, but teleport requests are often failing, usually resulting in the viewer crashing. I estimate this is happening about 25-50% of the time when I was recently working with someone to test this.
(0024573)
kenvc (reporter)
2013-10-26 11:47

This happens with the latest Singularity alpha code too.
(0024574)
Mata Hari (reporter)
2013-10-26 12:56
edited on: 2013-10-27 02:57

For no apparent reason at all (ie no changes at my end) today's attempt to tp to Sandbox Plaza II worked perfectly (and very fast!) with Firestorm, yet yesterday I made the exact same tp and it failed as usual.

EDIT: and then a couple hours later when returning after a sim crash it was back to "normal" with the first attempt failing

(0024614)
Mata Hari (reporter)
2013-11-07 03:12

All teleport attempts since the one anomalous success I reported last week have been the usual fail on first attempt and success on immediate retry. This is to several different grids, including yesterday's attempt made using r23991 at my end and tping to Sandbox II (which I assume is running OSG's Nov 2 build) using the latest Firestorm Beta for Opensim (4.5.1.38838)
(0024717)
Mata Hari (reporter)
2013-11-17 16:08

This morning I updated from r/24023 to r/24051 and now HG tp is completely non-functional.

Any attempt I make to tp from my standalone to OSG (example Sandbox Plaza II) will fail. Now, after timing out, the avi reappears in the original region with no "failed tp" message but it does still have all the attachments....however it is now impossible to tp anywhere (including other regions within my own grid!). Approximately 5 minutes later (total of about 7-8 minutes after the initial tp attempt) I finally received the "failed tp" message, my attachments all disappear.

The only way to clear the tp issue is to relog, at which point I can tp within my own grid without trouble.

I switched my outbound to use v0.1 and I get EXACTLY the same problem, so at the moment any off-grid tps are impossible.
(0024763)
Mata Hari (reporter)
2013-11-22 20:20

I just experienced this issue attempting to tp home after a lengthy stay on OSG (and had the usual issue getting there too). My console log of the failed attempt to HG TP home:


23:14:29 - [GATEKEEPER SERVICE]: Request to get hyperlink region f3c6f1b0-b5d1-11e2-9e96-0800200c9a66
23:14:30 - [USER AGENT SERVICE]: Request to login user Aine.Caoimhe @aine.x64.me (@stored IP) to grid http://aine.x64.me:9000/ [^]
23:14:30 - [USER AGENT SERVICE]: this grid: http://aine.x64.me:9000/, [^] desired grid: http://aine.x64.me:9000/, [^] desired region: f3c6f1b0-b5d1-11e2-9e96-0800200c9a66
23:14:30 - [GATEKEEPER SERVICE]: Login request for Aine.Caoimhe @aine.x64.me @ http://aine.x64.me:9000/ [^] (ce40214d-7737-47f5-af49-b685bfbb5dec) at using viewer 4.5.1.38838, channel
 Firestorm-Beta, IP 99.225.68.153, Mac f2801eb6edb1cf982cfb04852c5c5f81, Id0 15e54dd4412c0982bd793b716786f196 Teleport Flags 0
23:14:30 - [GATEKEEPER SERVICE]: Verifying http://aine.x64.me:9000 [^] against http://aine.x64.me:9000 [^]
23:14:30 - [USER AGENT SERVICE]: Verifying agent token http://aine.x64.me:9000/;3cc699c7-f3fe-48a8-8149-0420ecdbd0cb [^] against http://aine.x64.me:9000/;3cc699c7-f3fe-48a8-8149-0420ec [^]
dbd0cb
23:14:30 - [GATEKEEPER SERVICE]: Identity verified for Aine.Caoimhe @aine.x64.me @ http://aine.x64.me:9000/ [^]
23:14:30 - [GATEKEEPER SERVICE]: User Aine.Caoimhe @aine.x64.me is ok
23:14:30 - [PRESENCE SERVICE]: LoginAgent ce40214d-7737-47f5-af49-b685bfbb5dec with session 38e2b427-88ef-4215-b9a0-ef38ebb0abe8 and ssession db474c52-c47d-4cef-b882-d8f8e755624f
23:14:30 - [GATEKEEPER SERVICE]: Login presence Aine.Caoimhe @aine.x64.me is ok
23:14:30 - [GATEKEEPER SERVICE]: Destination Paramour is ok for Aine.Caoimhe @aine.x64.me
23:14:30 - [GATEKEEPER SERVICE]: Launching Aine Caoimhe ViaHGLogin
23:14:30 - [REMOTE SIMULATION CONNECTOR]: Creating agent at http://aine.x64.me:9000/ [^]
23:14:30 - [SCENE]: Region Paramour told of incoming child agent Aine Caoimhe ce40214d-7737-47f5-af49-b685bfbb5dec (circuit code 891270216, IP 99.225.68.153, viewer 4.5.1.38838, te
leportflags (ViaHGLogin), position <79.81419, 139.1298, 21.31633>)
23:14:30 - [SCENE]: Region Paramour authenticated and authorized incoming child agent Aine Caoimhe ce40214d-7737-47f5-af49-b685bfbb5dec (circuit code 891270216)
23:14:30 - [VivoxVoice]: OnRegisterCaps: agentID ce40214d-7737-47f5-af49-b685bfbb5dec caps OpenSim.Framework.Capabilities.Caps
23:14:30 - [EVENTQUEUE]: Adding new queue for agent ce40214d-7737-47f5-af49-b685bfbb5dec in region Paramour
23:14:30 - [USER AGENT SERVICE]: Gatekeeper sees me as
23:14:31 - [LLUDPSERVER]: Handling UseCircuitCode request for circuit 891270216 to Paramour from IP 99.225.68.153:64300
23:14:31 - [LLUDPSERVER]: Handling CompleteAgentMovement request from 99.225.68.153:64300 in Paramour
23:14:31 - [SCENE]: Adding new child scene presence Aine Caoimhe ce40214d-7737-47f5-af49-b685bfbb5dec to scene Paramour at pos <79.6781, 139.887, 22.7312>
23:14:31 - [LLUDPSERVER]: Received a CompleteAgentMovement from 99.225.68.153:64300 in Paramour but no client exists yet. Waiting.
23:14:31 - [HGFRIENDS MODULE]: caching 02e79eef-4ded-4c26-a1f8-a0bfc7c30ff5;http://hg.osgrid.org:80/;Aine [^] Caolmhe;be03794a
23:14:31 - [HGFRIENDS MODULE]: caching 06a38e91-a08e-442e-affb-677e2579bc25;http://hg.osgrid.org:80/;Inanna [^] Beaumont;050057f8
23:14:31 - [HGFRIENDS MODULE]: caching 0701885f-0aa7-4c4e-80c0-f91349921a51;http://lfgrid.com:8002/;Bubbles [^] Journey;a60b6703
23:14:31 - [HGFRIENDS MODULE]: caching 39508062-8358-4da5-88e9-5ce43992c071;http://hg.osgrid.org:80/;Dorothea [^] Lundquist;c350c4e9
23:14:31 - [HGFRIENDS MODULE]: caching 84dd4d60-811f-472b-8c4a-bea6f32c8b01;http://92.4.231.190:9000/;tom [^] camellian;e7f6139a
23:14:31 - [HGFRIENDS MODULE]: caching 9fab6223-9190-4237-8e4a-1f61950a6776;http://hg.osgrid.org:80/;LJ [^] Gibbs;5689c65c
23:14:31 - [HGFRIENDS MODULE]: caching a242ddd3-2eeb-4755-b9e7-7ea4618fb788;http://hg.osgrid.org:80/;Bubbles [^] Journey;c04bad8e
23:14:31 - [HG STATUS NOTIFIER]: Notifying 5 friends in http://hg.osgrid.org:80/ [^]
23:14:31 - [CAPS]: Received SEED caps request in Paramour for agent ce40214d-7737-47f5-af49-b685bfbb5dec
23:14:31 - [SCENE]: Incoming client Aine Caoimhe in region Paramour via HG login
23:14:31 - [USER AGENT CONNECTOR]: new connector to http://aine.x64.me:9000/ [^] (http://99.225.68.153:9000/ [^])
23:14:31 - [USER AGENT SERVICE]: Verifying Client session 38e2b427-88ef-4215-b9a0-ef38ebb0abe8 with reported IP 99.225.68.153.
23:14:31 - [USER AGENT SERVICE]: Comparing 99.225.68.153 with login IP 99.225.68.153 and MyIP 99.225.68.153; result is True
23:14:31 - [SCENE]: User Client Verification for Aine Caoimhe in Paramour returned true
23:14:31 - [SCENE PRESENCE]: Completing movement of Aine Caoimhe into region Paramour in position <79.6781, 139.887, 22.7312>
23:14:31 - [SCENE PRESENCE]: Agent Aine Caoimhe waiting for update in Paramour
23:14:31 - [HG STATUS NOTIFIER]: Notifying 1 friends in http://lfgrid.com:8002/ [^]
23:14:32 - [SCENE PRESENCE]: Agent Aine Caoimhe waiting for update in Paramour
23:14:32 - [SCENE PRESENCE]: Agent Aine Caoimhe waiting for update in Paramour
23:14:32 - [HGFRIENDS CONNECTOR]: Received empty reply from remote StatusNotify
23:14:32 - [HG STATUS NOTIFIER]: Notifying 1 friends in http://92.4.231.190:9000/ [^]
23:14:32 - [USER AGENT CONNECTOR]: new connector to http://92.4.231.190:9000/ [^] (http://92.4.231.190:9000/ [^])
23:14:32 - [SCENE PRESENCE]: Agent Aine Caoimhe waiting for update in Paramour
23:14:32 - [SCENE PRESENCE]: Agent Aine Caoimhe waiting for update in Paramour
23:14:32 - [SCENE PRESENCE]: Agent Aine Caoimhe waiting for update in Paramour
23:14:33 - [SCENE PRESENCE]: Agent Aine Caoimhe waiting for update in Paramour
23:14:33 - [SCENE PRESENCE]: Agent Aine Caoimhe waiting for update in Paramour
23:14:33 - [SCENE PRESENCE]: Agent Aine Caoimhe waiting for update in Paramour
23:14:33 - [SCENE PRESENCE]: Agent Aine Caoimhe waiting for update in Paramour
23:14:33 - [SCENE PRESENCE]: Agent Aine Caoimhe waiting for update in Paramour
23:14:34 - [SCENE PRESENCE]: Agent Aine Caoimhe waiting for update in Paramour
23:14:34 - [SCENE PRESENCE]: Agent Aine Caoimhe waiting for update in Paramour
23:14:34 - [SCENE PRESENCE]: Agent Aine Caoimhe waiting for update in Paramour
23:14:34 - [SCENE PRESENCE]: Agent Aine Caoimhe waiting for update in Paramour
23:14:34 - [SCENE PRESENCE]: Agent Aine Caoimhe waiting for update in Paramour
23:14:35 - [SCENE PRESENCE]: Agent Aine Caoimhe waiting for update in Paramour
23:14:35 - [SCENE PRESENCE]: Agent Aine Caoimhe waiting for update in Paramour
23:14:35 - [SCENE PRESENCE]: Agent Aine Caoimhe waiting for update in Paramour
23:14:35 - [SCENE PRESENCE]: Agent Aine Caoimhe waiting for update in Paramour
23:14:35 - [SCENE PRESENCE]: Agent Aine Caoimhe waiting for update in Paramour
23:14:36 - [SCENE PRESENCE]: Agent Aine Caoimhe waiting for update in Paramour
23:14:36 - [SCENE PRESENCE]: Agent Aine Caoimhe waiting for update in Paramour
23:14:36 - [SCENE PRESENCE]: Agent Aine Caoimhe waiting for update in Paramour
23:14:36 - [SCENE PRESENCE]: Agent Aine Caoimhe waiting for update in Paramour
23:14:36 - [SCENE PRESENCE]: Agent Aine Caoimhe waiting for update in Paramour
23:14:37 - [SCENE PRESENCE]: Agent Aine Caoimhe waiting for update in Paramour
23:14:37 - [SCENE PRESENCE]: Agent Aine Caoimhe waiting for update in Paramour
23:14:37 - [SCENE PRESENCE]: Agent Aine Caoimhe waiting for update in Paramour
23:14:37 - [SCENE PRESENCE]: Agent Aine Caoimhe waiting for update in Paramour
23:14:37 - [SCENE PRESENCE]: Agent Aine Caoimhe waiting for update in Paramour
23:14:38 - [SCENE PRESENCE]: Agent Aine Caoimhe waiting for update in Paramour
23:14:38 - [SCENE PRESENCE]: Agent Aine Caoimhe waiting for update in Paramour
23:14:38 - [SCENE PRESENCE]: Agent Aine Caoimhe waiting for update in Paramour
23:14:38 - [SCENE PRESENCE]: Agent Aine Caoimhe waiting for update in Paramour
23:14:38 - [SCENE PRESENCE]: Agent Aine Caoimhe waiting for update in Paramour
23:14:39 - [SCENE PRESENCE]: Agent Aine Caoimhe waiting for update in Paramour
23:14:39 - [SCENE PRESENCE]: Agent Aine Caoimhe waiting for update in Paramour
23:14:39 - [SCENE PRESENCE]: Agent Aine Caoimhe waiting for update in Paramour
23:14:39 - [SCENE PRESENCE]: Agent Aine Caoimhe waiting for update in Paramour
23:14:39 - [SCENE PRESENCE]: Agent Aine Caoimhe waiting for update in Paramour
23:14:40 - [SCENE PRESENCE]: Agent Aine Caoimhe waiting for update in Paramour
23:14:40 - [SCENE PRESENCE]: Agent Aine Caoimhe waiting for update in Paramour
23:14:40 - [SCENE PRESENCE]: Agent Aine Caoimhe waiting for update in Paramour
23:14:40 - [SCENE PRESENCE]: Agent Aine Caoimhe waiting for update in Paramour
23:14:40 - [SCENE PRESENCE]: Agent Aine Caoimhe waiting for update in Paramour
23:14:41 - [SCENE PRESENCE]: Agent Aine Caoimhe waiting for update in Paramour
23:14:41 - [SCENE PRESENCE]: Agent Aine Caoimhe waiting for update in Paramour
23:14:41 - [SCENE PRESENCE]: Agent Aine Caoimhe waiting for update in Paramour
23:14:41 - [SCENE PRESENCE]: Agent Aine Caoimhe waiting for update in Paramour
23:14:41 - [SCENE PRESENCE]: Update agent Aine Caoimhe never arrived in Paramour
23:14:41 - [HG INVENTORY ACCESS MODULE]: Restoring root folder for local user Aine Caoimhe
23:14:46 - [SCENE]: Incoming child agent update for ce40214d-7737-47f5-af49-b685bfbb5dec in Paramour
23:14:46 - [MaterialsDemoModule]: OSMaterials: [{"ID":"5b1119cf-0c2a-ec41-fba5-11e32a403fed","Material":{"NormRepeatX":10000,"NormRepeatY":10000,"SpecColor":[255,255,255,255],"Spec
Exp":51,"SpecMap":"6d1f5952-23fc-4704-912a-6200d567f292","SpecRepeatX":10000,"SpecRepeatY":10000}}]
23:14:46 - [MaterialsDemoModule]: OSMaterials: [{"ID":"5b1119cf-0c2a-ec41-fba5-11e32a403fed","Material":{"NormRepeatX":10000,"NormRepeatY":10000,"SpecColor":[255,255,255,255],"Spec
Exp":51,"SpecMap":"6d1f5952-23fc-4704-912a-6200d567f292","SpecRepeatX":10000,"SpecRepeatY":10000}}]
23:14:46 - [MaterialsDemoModule]: OSMaterials: [{"ID":"5b1119cf-0c2a-ec41-fba5-11e32a403fed","Material":{"NormRepeatX":10000,"NormRepeatY":10000,"SpecColor":[255,255,255,255],"Spec
Exp":51,"SpecMap":"6d1f5952-23fc-4704-912a-6200d567f292","SpecRepeatX":10000,"SpecRepeatY":10000}}]
23:14:46 - [MaterialsDemoModule]: OSMaterials: [{"ID":"4f413ca3-7bd2-090f-e5e1-8ccf6035c89b","Material":{"NormMap":"a343ab3c-c9bb-4643-9db4-8cc6af51340d","NormRepeatX":10000,"NormR
epeatY":10000,"SpecColor":[255,255,255,255],"SpecExp":51,"SpecRepeatX":10000,"SpecRepeatY":10000}}]
23:14:46 - [MaterialsDemoModule]: OSMaterials: [{"ID":"2f45a77f-010e-4e9e-14cb-da581a1cf60e","Material":{"NormMap":"7699621e-91a8-4b7b-b87f-c7f17f0a3823","NormRepeatX":10000,"NormR
epeatY":10000,"SpecColor":[255,255,255,255],"SpecExp":75,"SpecMap":"da45bafa-d1a3-4dac-b0a6-1c0abad5a019","SpecRepeatX":10000,"SpecRepeatY":10000}},{"ID":"753aca5c-fe10-83e0-b303-3
eb6f78a80e2","Material":{"DiffuseAlphaMode":1,"NormRepeatX":10000,"NormRepeatY":10000,"SpecColor":[255,255,255,255],"SpecExp":75,"SpecMap":"da45bafa-d1a3-4dac-b0a6-1c0abad5a019","S
pecRepeatX":10000,"SpecRepeatY":10000}}]
23:14:46 - [MaterialsDemoModule]: OSMaterials: [{"ID":"3602857a-4b82-de61-1e28-748b20e1cd15","Material":{"NormMap":"3c9785de-c2d9-420b-9229-0e6c7ac7f34a","NormRepeatX":10000,"NormR
epeatY":10000,"SpecColor":[255,255,255,255],"SpecExp":51,"SpecMap":"00c430fa-fbc9-4d22-88c5-520b89134c60","SpecRepeatX":10000,"SpecRepeatY":10000}},{"ID":"b4179848-62d0-3a30-0b22-4
627551035a9","Material":{"NormMap":"cc058a72-6fe2-48db-8281-98229292a0c6","NormRepeatX":10000,"NormRepeatY":10000,"SpecColor":[255,255,255,255],"SpecExp":33,"SpecMap":"a3e84524-f31
9-48c8-a88f-ecbd8fd4777c","SpecRepeatX":10000,"SpecRepeatY":10000}},{"ID":"8b78e371-8992-299e-e21e-5af1a14f4d73","Material":{"NormMap":"7699621e-91a8-4b7b-b87f-c7f17f0a3823","NormR
epeatX":10000,"NormRepeatY":10000,"SpecColor":[255,255,255,255],"SpecExp":33,"SpecMap":"da45bafa-d1a3-4dac-b0a6-1c0abad5a019","SpecRepeatX":10000,"SpecRepeatY":10000}}]
23:14:46 - [MaterialsDemoModule]: OSMaterials: [{"ID":"33da22e6-d68a-8c3a-1908-71308d265661","Material":{"EnvIntensity":40,"NormRepeatX":10000,"NormRepeatY":10000,"SpecColor":[255,
255,255,255],"SpecExp":51,"SpecMap":"ce6bbda2-936f-4bc9-80f0-f3d820bc18b3","SpecRepeatX":10000,"SpecRepeatY":10000}}]
23:14:46 - [MaterialsDemoModule]: OSMaterials: [{"ID":"4bad118b-f8b3-71a5-add7-49ef6575c23e","Material":{"EnvIntensity":5,"NormRepeatX":80000,"NormRepeatY":80000,"SpecColor":[255,2
55,255,255],"SpecExp":15,"SpecMap":"6d1f5952-23fc-4704-912a-6200d567f292","SpecRepeatX":80000,"SpecRepeatY":80000}},{"ID":"6746c2ff-c219-eedc-4800-8ba3cb31135c","Material":{"EnvInt
ensity":5,"NormRepeatX":80000,"NormRepeatY":80000,"SpecColor":[255,255,255,255],"SpecExp":20,"SpecMap":"6d1f5952-23fc-4704-912a-6200d567f292","SpecRepeatX":80000,"SpecRepeatY":8000
0}},{"ID":"dc3f81ee-75ef-b49c-440f-ba68a3955305","Material":{"EnvIntensity":10,"NormRepeatX":80000,"NormRepeatY":80000,"SpecColor":[255,255,255,255],"SpecExp":30,"SpecMap":"6d1f595
2-23fc-4704-912a-6200d567f292","SpecRepeatX":80000,"SpecRepeatY":80000}}]
23:14:53 - [USER AGENT CONNECTOR]: Unable to contact remote server http://92.4.231.190:9000/ [^] for GetServerURLs
23:15:06 - [SCENE]: Found presence Aine Caoimhe ce40214d-7737-47f5-af49-b685bfbb5dec unexpectedly still child in Paramour
23:15:06 - [BASE HTTP SERVER]: Slow handling of 2700 PUT /agent/ce40214d-7737-47f5-af49-b685bfbb5dec/ from 176.9.142.230:33575 took 21076ms
23:15:33 - [SCENE]: Incoming child agent update for ce40214d-7737-47f5-af49-b685bfbb5dec in Paramour
23:15:33 - [SCENEGRAPH]: Scene graph for Paramour already contains object de06b042-fb1c-4870-954f-7728c3f1217a in AddSceneObject()
23:15:33 - [SCENEGRAPH]: Scene graph for Paramour already contains object fb77cc85-3c32-4ba0-999f-27e97c4a2c16 in AddSceneObject()
23:15:33 - [SCENEGRAPH]: Scene graph for Paramour already contains object 1f634e2a-c6f9-44ba-ad6b-9977b00321a1 in AddSceneObject()
23:15:33 - [SCENEGRAPH]: Scene graph for Paramour already contains object 4ebe925b-eb03-4ab4-86d4-863ebfd025b2 in AddSceneObject()
23:15:33 - [SCENEGRAPH]: Scene graph for Paramour already contains object 4f85f767-cbc5-4b76-a01c-873e58736e3c in AddSceneObject()
23:15:33 - [SCENEGRAPH]: Scene graph for Paramour already contains object 5170ae34-b9bb-47b8-9823-3593841b3e76 in AddSceneObject()
23:15:33 - [SCENEGRAPH]: Scene graph for Paramour already contains object 8d42b2ec-76ef-4691-b6a1-1239d7cc0ea9 in AddSceneObject()
23:15:33 - [SCENEGRAPH]: Scene graph for Paramour already contains object c2139e92-c8b8-4d52-bd4f-8ccec3606eeb in AddSceneObject()
23:15:33 - [SCENEGRAPH]: Scene graph for Paramour already contains object 6bc01e66-49fe-4be0-9b28-831ae3e77446 in AddSceneObject()
23:15:33 - [SCENEGRAPH]: Scene graph for Paramour already contains object eae245b8-5b88-46fc-83ca-e463dab0259f in AddSceneObject()
23:15:33 - [SCENEGRAPH]: Scene graph for Paramour already contains object 2f1119c7-22c4-4250-8966-227937df3ebf in AddSceneObject()
23:15:33 - [SCENEGRAPH]: Scene graph for Paramour already contains object 3f9a19a7-10c9-46b0-b588-3839e6ae0b78 in AddSceneObject()
23:15:33 - [SCENEGRAPH]: Scene graph for Paramour already contains object 70fe2bbc-c4fb-44c9-8de6-b011f4cefb70 in AddSceneObject()
23:15:33 - [SCENEGRAPH]: Scene graph for Paramour already contains object 14838117-8cd2-4318-9800-9a4d1c060d17 in AddSceneObject()
Region (root) #
23:15:53 - [SCENE]: Found presence Aine Caoimhe ce40214d-7737-47f5-af49-b685bfbb5dec unexpectedly still child in Paramour
23:15:53 - [BASE HTTP SERVER]: Slow handling of 2702 PUT /agent/ce40214d-7737-47f5-af49-b685bfbb5dec/ from 176.9.142.230:33620 took 20686ms
23:16:15 - [AGENT HANDLER]: >>> DELETE <<< RegionID: f3c6f1b0-b5d1-11e2-9e96-0800200c9a66; from: 176.9.142.230; auth_code: 38e2b427-88ef-4215-b9a0-ef38ebb0abe8
23:16:15 - [CLIENT]: Close has been called for Aine Caoimhe attached to scene Paramour
23:16:15 - [SCENE]: Removing child agent Aine Caoimhe ce40214d-7737-47f5-af49-b685bfbb5dec from Paramour
23:16:15 - [CAPS]: Remove caps for agent ce40214d-7737-47f5-af49-b685bfbb5dec in region Paramour
(0024783)
Mata Hari (reporter)
2013-11-29 12:48

HG teleports now appear to be almost completely broken as of the November 29th update released by OSG.

It took me a dozen attempts over approximately 1.5 hours before I was finally able to get from my own sim to OSG's Sandbox II. All attempts failed until I downloaded and applied the same patch, at which point it reverted to the time-out/return home invisible/immediate re-attempt success.

I would be happy to supply logs, ini files, complete build....ANYTHING to get this incredibly frustrating problem solved.
(0024784)
danbanner (manager)
2013-11-29 13:19

thats strange, since i have not had any trouble with HG teleports with this build.
(0024786)
Mata Hari (reporter)
2013-11-29 17:20

maybe a Win64 issue? maybe some issue with having my opensim instance on the same computer as my viewer? I have no idea
(0024787)
justincc (administrator)
2013-11-29 18:17

Sorry, I just haven't had time again to look at this issue, been busy on other stuff.

However, I will say that the delta between the latest OSG release and the previous one contains no changes to hypergrid or teleport code, afaik. So why the issue would become worse is a bit of a mystery.

A long shot is that your simulator is running out of SmartThreadPool spare threads due to a poor OpenSimulator default configuration. If so, you can see this by look at data from server.threadpool.STPInUseThreads as detailed at [1]. You could try increasing MaxPoolThreads and see if that helps.

Otherwise, I would strongly suggest checking your network equipment and conducting connectivity, latency and packet drop tests. Are you seeing failures going to other grids or just OSGrid?

If everything appears fine I will try and look again when I can. Are other people are also continuing to suffer these issues?

[1] http://opensimulator.org/wiki/Show_stats [^]
(0024788)
Mata Hari (reporter)
2013-11-29 19:57
edited on: 2013-11-29 20:01

Interesting that you should point to the MaxPoolThreads which according to the OpenSimDefaults.ini is only used for async_call_metho=SmartThreadPool. As this machine is .NET/Win I've been using UnsafeQueueUserWorkItem instead (and my MaxPoolThreads was set to 200 so it's way above the default value of 15 even though it wasn't in use...I think that may be a legacy value from a Diva installation I tried when attempting to solve this problem).

I've done the assorted connectivity, latency and packet drop tests and everything seems to be pretty good. There are times when my daughter is also online which can strain the b/w a little, but for the most part it's purring along smoothly. The connection problems I've had have been for all grids (OSG, Littlefield, and Metro being the three I go to moderately often) and with all viewers (Firestorm, Singularity, Kokua are the three I've tested). Once I do finally manage to HG tp, all subsequent tps within the destination grid are quick and smooth, as is my tp home. It's only the initial outbound attempt that is the problem.

I noticed while watching the console during my multiple tp attempts today that during the 0000004:0000005-10 minutes it takes for the attempt to time out, my avi to be returned to my grid, for it to eventually get a message that the tp failed and then lose all its attachments -- at which point I can finally re-attempt the tp) there are repeated messages like "DEBUG - OpenSim.Region.CoreModules.Framework.UserManagement.UserManagementModule [USER MANAGEMENT MODULE]: No grid user found for 12902d9a-62ba-4bfb-b1ae-dab925eb5da0" for about 20 UUIDs and that they repeat periodically....and those UUID would seem to be all of the failed attempts to make HG friends (see my report 6769) so I wonder if that is somehow causing a problem?

Also today, there were several occasions that I was standing on my region waiting to be able to tp again and I could see messages in my viewer's local chat from the sim I had been attempting to tp to. I also see console messages about "unknown user" with the UUID of people who are nearby my destination point. When I do eventually get there sometimes those have resolved themselves and sometimes they won't do so for 5-10 minutes.

This evening I repurposed another computer I have and am in the process of installing linux on it and then moving my OpenSim installation over to it so I can have the sim server independent of this one (which I use for my viewer) in the hopes that if it's a Win64 issue it will resolve itself. I'll let you know how that goes

EDIT: I neglected to mention in this summary that until about mid May HG tp was working perfectly smoothly for me on the first attempt...crash free every time. Since then, I have made no hardware or software changes and to my knowledge my ISP hasn't either, so the cause is either Opensim code or one of the million regular Windows updates.

(0024789)
Mata Hari (reporter)
2013-11-29 20:09

As to others having trouble...

Kenvc reported high failure rate he was having a few weeks ago (see above) and I haven't seen any code revisions in the git log that look like they were related to fixes. Neb was also having issues as reported shortly prior to that. Another friend of mine (in LFG) also has the identical issue trying to HG from there (and continues to have those problems). At today's Close Encounter party, 2 visitors from Metro both had a very hard time (4-5 attempts to get there). When I returned home after the party, the tp was extremly fast and smooth...it was just the outbound one that failed so many times. It can't be horribly wide spread or more people would be reporting it, and obviously there are some who are having no problems at all; so I understand that it's one of those annoying bugs that is brutally difficult to track down and fix.
(0024790)
Mata Hari (reporter)
2013-11-29 21:08
edited on: 2013-11-30 06:25

Further to my previous...

I installed Opensim on the repurposed computer (just sent the entire installation over the network) and made only the one change to the ini file to use SmartThreadPool instead (since I put Ubuntu 13.10 on it). I used oars and an iar to "move" the databases so I could use linux's MySQL install rather than connecting to this computer over the network. Of course doing it this way means my friends list was wiped clean but that's probably a good thing since 90% of the entries were broken anyway -- I mention this because I then attempted a HG tp tp Sandbox II Plaza and it went perfectly...extremely fast arrival on the first attempt.


EDIT: UPDATE...and now this morning I attempt the identical tp and it's back to the time-out behaviour again...*sigh*

(0024858)
Mata Hari (reporter)
2013-12-11 16:14

currently taking 3 or 4 attempts to make 1 successful tp from my home regions to any of the OSG Plazas. Further, now I am getting the same behaviour when attempting to tp from an OSG Plaza (when I finally manage to get there) to any other region within OSG, and also when attempting to get home.

LyAvain of Metropolis also indicated experiencing the same issue today trying to tp, though not with the frequency that I have
(0024888)
Mata Hari (reporter)
2013-12-18 12:48
edited on: 2013-12-18 12:52

As of today, all HG attempts to get to OSG failed for me using the JCC master until I reverted my sims to the Nov 30th OSG build. Prior to that I also tried reverting to 24106 with the same result. Using the 241056 build I was able to HG tp to LFG and Metro (with the usual first-attempt-fail-and-arrive-back-without-attachments issue).

EDIT: I should add that I haven't attempted a HG tp to OSG since last Wednesday so it might not be something specific to today,

(0024922)
Mata Hari (reporter)
2013-12-27 12:41

Last week I was able to HG tp successfully to OSG a couple times (with the usual failure on first attempt) but today I have made a dozen attempts over the course of the last hour or two, all of which have failed. They take about 5-10 minutes after the viewer times out before the notice pops up in my viewer indicating the fail (until then any attempt to tp says that I'm already in transit) but now I don't lose all of my attachments.

My simulator is currently running the Nov 30 OSG build (24087?).
(0024927)
Mata Hari (reporter)
2013-12-27 14:09
edited on: 2013-12-27 15:13

I may have come up with a potential cause for this entire issue...

As an experiment, I created a new account in my sim and made an HG tp to Sandbox Plaza, surprisingly without any trouble at all (succeeded on first attempt!). Mystified as to why this might have worked while my own normal account didn't, I relogged into my normal account and Ruthed myself (since my successful attempt with the new account was as Ruth). Again, the HG tp worked perfectly.

I then returned to my sim, relogged, changed into a different outfit but still used the Ruth avatar, and tped back to Sandbox Plaza. Again, worked flawlessly.

I then returned to my sim, relogged, wore my normal mesh avi and attempted to HG tp.....FAILED. All subsequent attempts failed.

I then relogged, removed my mesh, and tped again....worked perfectly.

So...it would appear that the problem relates to wearing mesh attachments, and this would coincide fairly well with the time period that I began to experience serious issues with HG tps (that's roughly when I began working with mesh on a serious level).

It would seem that sometimes it will succeed, but usually only on the 2nd or 3rd attempt to tp while wearing mesh; and it isn't due to a faulty mesh encoding because it *will* succeed while wearing the same mesh....it jst takes multiple attempts.

(Edit...the likely cause for the increased frequency of my issues is that I am currently wearing more and more mesh items....complete avi, eyes, clothing, footwear, jewelry, etc....the only non-mesh item I normally wear is my hair.)

Edit 0000002: it would also explain why the issue has become a lot worse recently since I now typically also include a normal and/or specular map in addition to the texture for each face, so that's a lot more data that has to be transferred to the destination sim before the process times out.

I will conduct some tests in the next couple days to see if this guess is correct by wearing small qty of small mesh, trying to tp, then if that works repeat again with more mesh items. If this *does* end up being the culprit, is it feasible to alter the HG tp mechanics to allow the actual tp to complete even if all assets haven't yet been delivered?

(0024928)
Mata Hari (reporter)
2013-12-28 05:52
edited on: 2013-12-28 05:54

Did some testing of the above theory and it appears to be the most likely cause of the issue I've been experiencing and also explains why few others are complaining about it (although this will likely change over time as mesh becomes increasingly popular in Opensim -- it certainly is in SL).

I was able to consistently HG tp to any grid provided I was wearing very few (or no) mesh items. The time taken to make the teleport was rapid when I was "Ruthed" and gradually slowed down as I added progressively more (and more complex) mesh attachments until at a certain point it began to time out. Once this happened, I was sometimes able to immediately re-attempt the tp successfully and at others it would continue to time out and fail.

Different grids seemed to have different time-out thresholds which I assume is due to the connection speed between my grid and the destination grid (and possibly the destination grid's per-client throttle settings?). As an example, my attempts to OSG Sandbox Plaza II seemed to begin failing when the total combined attachment asset size of meshes, textures, normal maps, and specular maps was somewhere around 20MB (in addition to the base SL avatar's alpha mask, my non-mesh prim hair and shape). While this might seem large, it's quite easy to hit this limit when a mesh can easily be 15k-20k faces with 5 or 6 texture faces and matching normal and specular maps (just the image files at 512x512 is in excess of 1MB per surface if you're using all three). Even though they're worn as attachments and are therefore phantom, I assume the physics mesh also has to be transmitted (though I am in the habit of making an ultra-low-res one in Blender rather than having it generated on upload).

Of course the simple "fix" is to never HG tp while wearing any/much mesh, and/or to only make incredibly low res meshes with single texture and no normal or specular maps, but that kind of defeats the purpose...particularly since this only appears to affect HG teleports (I guess in-grid tp is handled differently from an asset standpoint?).

A second solution -- which I will probably go with for now -- is to revert my own simulator to use the V1.0 HG asset handler, wear a "Ruth" when making my HG tp, then wear my mesh items one by one once I'm at my destination (I could use suitcase and 1.5 or 2, I guess, but either way the assets are exposed so 1.0 is by far more convenient for my purposes).

From a development standpoint, however, I would suggest that it would be prudent to modify the handling of HG teleports (if possible) to allow a teleport to complete once a certain amount of very basic asset data has been transferred, perhaps by separating the handling of attachments from the handling of the base avi and clothing...send the base first, complete the tp so it doesn't time out, then bring in the attachments and associated assets.

The rationale behind making such a change is that I suspect over time mesh will become far more widely used, as will the "advanced" materials capabilities (since these result a huge improvement in appearance that is impossible to achieve with the conventional avi) and even though hypergrid (generally) does not currently appear to be a development priority, it is one of the most attractive and appealing differences that Opensim can boast of in comparison to SL so making HG unappealing would seem counterproductive.

If you require any further data, or would like me to supply some assorted test files (mesh/textures/etc) to do testing with, I would be happy to do so.


EDIT: incidentally, I did almost all of my testing on Firestorm 4.5.1 but I did switch to both Singularity and Kokua to confirm that the behavior is identical for them as well)

(0025359)
jozee tungsten (reporter)
2014-03-04 11:35

Further to this issue, I began to experience this after acquiring a several new attachments (shoes) from the Metropolis grid. I am running Ubuntu 12.04, mono-3.23, Simulator v0.8.0.cddf1ec, while using Firestorm 4.5.1 (38838) on Windows 8.1. Specifically, I could not successfully tp out of my region although I could tp into it after logging in elsewhere. The pertinent log entry is:
13:13:26 - [ENTITY TRANSFER MODULE]: UpdateAgent failed on teleport of Jozee Tungsten. This was a failed attempt to tp to Lbsa from within OSGRID.

The failure leaves me in situ with no attachments. The problem goes away if I remove the offending attachments. It is not mesh-specific as I can tp wearing mesh.
(0025366)
Mata Hari (reporter)
2014-03-04 20:35

Jozee: the issue is that there is a limited window of time for the destination server to have received ALL asset data for the inbound avatar. If it is still waiting for anything at all then the tp will fail and you end up back where you started and all your attachments are gone until relog. You don't experience this problem when tping home because many (or even all) of your stuff is probably already sitting in your home region's cache. If you were to purge your cache (via console: fcache clear) you'll find that your tp home attempts will fail again until enough of the data is cached again.

While it's not a "mesh breaks things" issue, it's one that is far more likely to occur with mesh because of the file sizes and transfer rates involved. It's also more likely to occur when the destination sim is on a slow connection or a remote (ie on a different continent) sever relative to the origination sim's asset server.

I can wear a huge number of mesh objects, log in to any OSG Plaza and then effortlessly make a tp to any other plaza because the destination server already has the cached data from my login. I can also tp home (as long as everything I'm wearing is already in my home's cache). Any other destination will definitely fail.

If the asset server is a home connection (as would be commonn in standalone HG sims) then it's a huge issue because most home connections have 5Mbit or lower up speeds (vs commercial connections at far, far higher rates).

Basically this means for mesh=wearer that you need to have a "Ruth TP outfit" which is just shape, skin, base hair and an alpha. Change into this "Ruth" prior to every tp; then make your tp (which will succeed because there's very little data to send); then once you arrive change into whatever you really want to wear. It's a pain in the rear end but it's the only way to be sure that you won't be forced to relog.
(0025580)
Mata Hari (reporter)
2014-03-25 06:33

Having thought about this issue for a while I have a potential solution to the problem from a coding end which may not be too excessively difficult to implement. The same solution would also address/resolve 0007038

It seems to me that the way mesh is currently stored is significantly different to other similar assets (prims or scultpies). For prims the geometry resides (presumably) in the viewer and doesn't have to be sent at all. For sculpties, the geometry is defined by the sculpt texture and base shape...I assume the base shape geometry resides in the viewer as well and then the texture is applied as a deform morph of some sort. Whatever the case, a tp can complete even when the sculpt texture has not yet been sent to the destination sim....the sculpt seems to take a generic shape until the texture is received and then updates itself to show the intended geometry.

With mesh, the entire geometry has to be received by the destination sim before the tp can even complete, and the window of time for this transfer is very short before it times out. If it does time out, not only does the tp fail but ALL attachments are rendered invisible and cannot be changed until a relog. Also, every single time a mesh is unworn the entire geometry is sent from the region server to the asset server which is a completely unnecessary waste of bandwidth since geometry doesn't change -- only the prim-like parameters can be changed without uploading the source .dae again.

If, instead of whatever current method is employed to store mesh assets, the mesh geometry was handled like a sculpt's texture it would probably resolve these problems. The geometry data could be stored (either as a texture or if that isn't feasible due to table field data type restrictions then a separate asset table of "mesh textures" could be created and maintained) and then assigned as a prim property exactly as a sculpt is stored: the UUID of the geometry data table entry. I believe this would then allow the tp to complete since all the destination region would require is the UUID instead of the geometry data, and it can be "filled in" and updated when the actual data arrives. People will understand and not object too much if it takes a while to rez once they get to the region since this will make tps reliable again instead of being an exercise in frustration to mesh-wearers. We know that the underlying infrastructure of Opensim can't replicate the performance of the integrated SL asset/region servers so this delay is just the nature of the beast and acceptable because of the many other benefits allowed by using Opensim.

Migration from the current method might be tricky (not sure exactly how that would be handled) but in the long term it might provide the simplest solution to an annoying issue.
(0025625)
Mata Hari (reporter)
2014-03-28 08:47

Using today's r/24555 I can now teleport while wearing mesh avi and clothing, etc and it's just almost as rapid as if I were fully Ruthed so it would appear that the thing that's been messing up tps all this time was related to saving the mesh (including full geometry) prior to the tp being able to complete and thus would time out if wearing any significant amount of mesh.

I haven't yet tested with HG travel so I won't mark this as closed, but for in-grid tp it now seems to be working perfectly if the sim you're tping from has r/24555.
(0025633)
jozee tungsten (reporter)
2014-03-28 20:45

The HG results are as before: the tp fails leaving the avi without attachments and in a failed tp state. In fact, the results are worse: the hg actually succeeds insofar as the avatar arrives intact in the new region and the viewer subsequently shows a failed connection message and strips all attachments. I picked up a copy of r24556 source; built it with mono-3.2.3 on a dual core acer running Ubuntu 12.04. I also added the new Xbake section to OpenSim.ini with identical results. IMO this has become a mess and I am sticking with the last stable release I can identify, which is dated January 24th, 2014.
(0028835)
Isis Ophelia (reporter)
2015-06-27 12:17

As I got my new PC windows 8.1 64 bit hat to install my viewers Singularity, Firestorm and Cool VL Viewer. And there was no way to teleport from a HG grid to another. I got all the troubles described above. What fixed it completely for me was to give all my viewers + SL voice permission for Private but also for Public networks. I am not a techie and know almost nothing about Opensim, what I know it's that since I made that change in the firewall I can teleport to any grid back and fort and all my attachments come with me. The TPs are very fast now too.

- Issue History
Date Modified Username Field Change
2013-09-03 04:11 aiaustin New Issue
2013-09-03 04:11 aiaustin File Added: 2013-09-02-OpenSim-Log-OSGrid-TP-Failing.txt
2013-09-03 04:13 aiaustin Description Updated View Revisions
2013-09-03 09:17 aiaustin Description Updated View Revisions
2013-09-03 09:17 aiaustin Additional Information Updated View Revisions
2013-09-03 13:52 aiaustin Additional Information Updated View Revisions
2013-09-03 13:54 aiaustin Additional Information Updated View Revisions
2013-09-08 15:26 aiaustin Summary Failing teleports on one grid and avatar returned to original source region without attachments => Failing teleports and avatar returned to original source region without attachments
2013-09-08 15:26 aiaustin Description Updated View Revisions
2013-09-08 15:53 Robert Adams Note Added: 0024317
2013-09-08 17:34 Mata Hari Note Added: 0024318
2013-09-09 02:01 aiaustin Note Added: 0024321
2013-09-09 02:03 aiaustin Description Updated View Revisions
2013-09-18 15:54 justincc Note Added: 0024359
2013-09-18 21:16 kenvc Note Added: 0024360
2013-09-19 01:37 kenvc Note Edited: 0024360 View Revisions
2013-09-19 07:33 Mata Hari Note Added: 0024361
2013-09-19 07:45 Bruce Note Added: 0024362
2013-09-19 07:59 Bruce Note Edited: 0024362 View Revisions
2013-09-19 09:44 kenvc Note Edited: 0024360 View Revisions
2013-09-19 15:00 justincc Note Added: 0024366
2013-09-19 21:34 kenvc File Added: Teleport Failed.jpg
2013-09-19 21:37 kenvc Note Added: 0024369
2013-09-20 01:34 aiaustin Note Added: 0024370
2013-09-20 01:36 aiaustin Note Edited: 0024370 View Revisions
2013-09-20 05:01 Mata Hari Note Added: 0024371
2013-09-20 11:44 kenvc Note Added: 0024372
2013-09-20 11:45 kenvc File Added: Kens_Log_Files.zip
2013-09-20 11:47 kenvc Note Edited: 0024372 View Revisions
2013-09-20 13:50 kenvc Note Added: 0024373
2013-09-20 14:12 Arielle Note Added: 0024374
2013-09-20 15:54 justincc Note Added: 0024375
2013-09-20 19:03 Mata Hari File Added: log Aine tp tests 2013-09-20.txt
2013-09-20 19:05 Mata Hari Note Added: 0024377
2013-09-20 19:07 Mata Hari Note Edited: 0024377 View Revisions
2013-09-20 23:10 kenvc Note Added: 0024378
2013-09-21 09:02 kenvc Note Edited: 0024378 View Revisions
2013-09-21 14:44 Bruce Note Added: 0024382
2013-09-22 11:42 aiaustin Note Added: 0024383
2013-09-22 11:43 aiaustin Note Edited: 0024383 View Revisions
2013-09-22 12:54 aiaustin Note Edited: 0024383 View Revisions
2013-09-23 02:03 aiaustin Note Added: 0024386
2013-09-23 02:04 aiaustin Note Edited: 0024386 View Revisions
2013-09-23 02:27 aiaustin Note Added: 0024387
2013-09-23 02:32 aiaustin Note Added: 0024388
2013-09-23 02:32 aiaustin Note Edited: 0024388 View Revisions
2013-09-23 02:33 aiaustin Note Edited: 0024388 View Revisions
2013-09-23 02:33 aiaustin Note Edited: 0024383 View Revisions
2013-09-23 02:35 aiaustin Note Edited: 0024388 View Revisions
2013-09-23 04:34 Mata Hari Note Added: 0024390
2013-09-23 04:35 Mata Hari Note Edited: 0024390 View Revisions
2013-09-23 05:07 aiaustin Note Added: 0024391
2013-09-23 05:07 aiaustin File Added: Windows-Vista-Firewall-for-OpenSim.jpg
2013-09-23 05:15 aiaustin Note Edited: 0024391 View Revisions
2013-09-23 05:41 aiaustin Note Added: 0024392
2013-09-23 05:41 aiaustin Note Edited: 0024392 View Revisions
2013-09-23 05:42 aiaustin Note Edited: 0024392 View Revisions
2013-09-23 06:02 aiaustin Note Edited: 0024392 View Revisions
2013-09-23 06:05 aiaustin Note Added: 0024393
2013-09-23 06:06 aiaustin Note Edited: 0024393 View Revisions
2013-09-23 06:08 aiaustin Note Edited: 0024393 View Revisions
2013-09-23 06:11 aiaustin Note Edited: 0024393 View Revisions
2013-09-23 11:52 kenvc Note Added: 0024394
2013-09-25 11:49 justincc Note Added: 0024397
2013-09-25 11:51 justincc Note Edited: 0024397 View Revisions
2013-09-25 14:28 Mata Hari Note Added: 0024398
2013-09-25 16:19 justincc Note Added: 0024399
2013-09-25 19:06 kenvc Note Added: 0024400
2013-09-26 02:51 aiaustin Note Added: 0024401
2013-10-16 15:11 Mata Hari Note Added: 0024488
2013-10-22 16:36 justincc Note Added: 0024558
2013-10-22 17:05 Mata Hari Note Added: 0024559
2013-10-22 17:08 justincc Note Added: 0024560
2013-10-22 17:10 Mata Hari Note Added: 0024561
2013-10-22 17:15 justincc Note Added: 0024562
2013-10-22 17:17 Mata Hari Note Added: 0024563
2013-10-22 17:19 Mata Hari Note Added: 0024564
2013-10-22 17:20 smxy Note Added: 0024565
2013-10-22 17:23 Mata Hari Note Added: 0024566
2013-10-22 17:40 Mata Hari Note Added: 0024567
2013-10-26 06:53 kenvc Note Added: 0024571
2013-10-26 11:11 hack13 Note Added: 0024572
2013-10-26 11:47 kenvc Note Added: 0024573
2013-10-26 12:56 Mata Hari Note Added: 0024574
2013-10-26 14:06 hack13 Note Deleted: 0024572
2013-10-27 02:57 Mata Hari Note Edited: 0024574 View Revisions
2013-11-07 03:12 Mata Hari Note Added: 0024614
2013-11-17 16:08 Mata Hari Note Added: 0024717
2013-11-22 20:20 Mata Hari Note Added: 0024763
2013-11-29 12:48 Mata Hari Note Added: 0024783
2013-11-29 13:19 danbanner Note Added: 0024784
2013-11-29 17:20 Mata Hari Note Added: 0024786
2013-11-29 18:17 justincc Note Added: 0024787
2013-11-29 19:57 Mata Hari Note Added: 0024788
2013-11-29 20:01 Mata Hari Note Edited: 0024788 View Revisions
2013-11-29 20:09 Mata Hari Note Added: 0024789
2013-11-29 21:08 Mata Hari Note Added: 0024790
2013-11-30 06:25 Mata Hari Note Edited: 0024790 View Revisions
2013-12-11 16:14 Mata Hari Note Added: 0024858
2013-12-18 12:48 Mata Hari Note Added: 0024888
2013-12-18 12:52 Mata Hari Note Edited: 0024888 View Revisions
2013-12-27 12:41 Mata Hari Note Added: 0024922
2013-12-27 14:09 Mata Hari Note Added: 0024927
2013-12-27 14:11 Mata Hari Note Edited: 0024927 View Revisions
2013-12-27 15:13 Mata Hari Note Edited: 0024927 View Revisions
2013-12-28 05:52 Mata Hari Note Added: 0024928
2013-12-28 05:54 Mata Hari Note Edited: 0024928 View Revisions
2014-03-04 11:35 jozee tungsten Note Added: 0025359
2014-03-04 20:35 Mata Hari Note Added: 0025366
2014-03-25 06:33 Mata Hari Note Added: 0025580
2014-03-28 08:47 Mata Hari Note Added: 0025625
2014-03-28 20:45 jozee tungsten Note Added: 0025633
2015-06-27 12:17 Isis Ophelia Note Added: 0028835
2015-12-01 05:41 Mata Hari Relationship added related to 0007774


Copyright © 2000 - 2012 MantisBT Group
Powered by Mantis Bugtracker