Mantis Bug Tracker

View Issue Details Jump to Notes ] Issue History ] Print ]
IDProjectCategoryView StatusDate SubmittedLast Update
0008382opensim[GRID] Grid Servicepublic2018-09-26 13:042018-12-14 18:16
Reportermac4kent 
Assigned To 
PriorityurgentSeverityblockReproducibilitysometimes
StatusconfirmedResolutionopen 
PlatformOSOS Version
Product Versionmaster (dev code) 
Target Versionmaster (dev code)Fixed in Version 
Summary0008382: TP some time fail
DescriptionI am show you on youtube about TP some time fail.

https://www.youtube.com/watch?v=yGMe7NWteLs&feature=youtu.be [^]

I am use Macintosh.
MacOS 10.14
Firestorm version 5.1.7.55786 (5.1.7.55786)

Additional InformationAlso on Windows 10 winver 1803. Firestorm version 5.1.7.55786 (5.1.7.55786).
TagsNo tags attached.
Git Revision or version number
Run Mode Standalone (Multiple Regions)
Physics EngineOther
EnvironmentUnknown
Mono VersionNone
ViewerFirestorm 5.1.7.55786
Attached Filestxt file icon 2018-10-09-ailand-teleport-issue-logs.txt [^] (24,031 bytes) 2018-10-09 09:41 [Show Content]
png file icon 2018-10-29-Firestorm-Console-OpenSim-507-TP-Issue-1.png [^] (308,409 bytes) 2018-10-29 02:46
png file icon 2018-10-29-Firestorm-Console-OpenSim-507-TP-Issue-2.png [^] (266,757 bytes) 2018-10-29 02:46

- Relationships

-  Notes
(0033099)
mewtwo0641 (reporter)
2018-09-28 09:11

I see this issue quite often on my own server and I'm not sure why. There seems to be roughly a 50/50 chance (By my completely unscientific estimate lol) of it working or not and once it decides not to work, nothing except a re-log fixes it, but only very temporarily.

Symptoms of it happening include drifting off into the void when region crossing, eternally black teleport screens, no feed back in the OpenSim console except for the initial message stating a crossing/teleport was initiated, etc. and about 30 seconds later you're either returned to the originating region or disconnected with an error message that connection was lost.

It happens so often that it's actually almost just easier to re-log first before even attempting a region cross/teleport.

It's a perplexing issue because it happens on both LAN (OS is running local to my network) and on WAN.
(0033106)
aiaustin (developer)
2018-10-01 02:27
edited on: 2018-10-09 10:50

I have been seeing something like this between Windows 10 grids (Openvue and AiLand) and to and from my OSGrid addon regions (also on a windows 10 system) for a while now and I can't pin things down yet. So just making a note here in case others are spotting something amiss.

Sometimes even on idling grids/region servers my first attempt to teleport fails after 30 seconds or so and leaves me in the original region and then a second attempt works. Sometimes on second attempt it says I am logged in already in destination (when I clearly aren't there) and then works on the third attempt, other times it crashes the viewer (Firestorm 5.1.7.55786). Destination grid console logs indicate it sees the connection attempt but then not much else happens before the viewer fails. So I am assuming its getting a timeout and not syncing up correctly even on servers that are otherwise idle. @Ubit did recently amend the number of connection attempts and shortened the time between them, but this problem occurs with the original and modified attempts timings.

But as I say I have not pinned anything specific down yet even though its been happening for a few months with latest dev 0.9.1 master (and the httptests branch before that was merged in).

(0033155)
aiaustin (developer)
2018-10-09 09:41
edited on: 2018-10-09 12:09

To try to get a start on pinning down what might be happening.. I am attaching a log file with a few examples of what the OpenSim.exe logs look like on my experimental AiLand grid setup which has one server with Robust.exe, the MySQL 5.7 data base and one OpenSim.exe instance running three regions, including the "home" default region. The second server runs one OpenSim,.exe instance with a number of regions. I have issues for some months and cannot pin things down. All using dev master latest as it gets released.

I get MANY problems TPing between regions, back to the home region, etc.. even without any Hypergrid jumps. Sometimes it fails on the first attempt and then a second attempt immediately works. Sometimes the avatar seems to get stuck and does not show as logged into the origin or destination region and may not be able to move.

User in Firestorm 5.1.7.55786 Windows 10 64 bit viewer sees a message that there are problems connecting between viewer and server each time. I am using a viewer on the same local network as the servers and also over the Internet from home and that does not seem to matter.

Attached log file (2018-10-09-ailand-teleport-issue-logs.txt) with some of the OpenSim.exe logs showing a number of connection problems... these are on idling servers and its not clear why timeouts are occurring or attempts do not work always.

I do see a couple of exceptions on teleport such as

[ENTITY TRANSFER MODULE]: Exception on teleport of Ai Austin from <128.9578, 127.8008, 26.06984>@AiLand to <213, 146, 103.5>@Castle: Object reference not set to an instance of an object.

and

[BASE HTTP SERVER]: HandleRequest() threw exception System.NullReferenceException: Object reference not set to an instance of an object.

(0033156)
BillBlight (developer)
2018-10-10 23:02
edited on: 2018-10-10 23:03

Been testing those a lot, those errors are not the cause but are a symptom, when you start the TP, you sort of get there, and it fails but it immediately tries again it seems, but some of your attachments are already/still in the scene and it blows right up ..

Been chasing this error and I have something mitigates the error but does not solve the underlying issue ... So very hesitant to share it ..

Just out of curiosity are you running Gloebits on the region?

(0033157)
BillBlight (developer)
2018-10-10 23:05
edited on: 2018-10-10 23:06

@aiaustin, you can see what I was talking about in the previous post in one line of the log ..

[SCENEGRAPH]: Scene graph for AiLand already contains object 611f510e-b0d3-4e18-9a1d-2dc47d71cb1f in AddSceneObject()
BASE HTTP SERVER]: HandleRequest() threw exception System.NullReferenceException: Object reference not set to an instance of an object.
   at OpenSim.Region.Framework.Scenes.SceneObjectPart.get_GroupPosition() in d:\Temp\opensim-0.9.0.1-468-g235dd37\OpenSim\Region\Framework\Scenes\SceneObjectPart.cs:line 817
   at OpenSim.Region.Framework.Scenes.SceneObjectGroup.set_AbsolutePosition(Vector3 value) in d:\Temp\opensim-0.9.0.1-468-g235dd37\OpenSim\Region\Framework\Scenes\SceneObjectGroup.cs:line 582
   at OpenSim.Region.CoreModules.Avatar.Attachments.AttachmentsModule.AttachToAgent(IScenePresence sp, SceneObjectGroup so, UInt32 attachmentpoint, Vector3 attachOffset, Boolean silent) in d:\Temp\opensim-0.9.0.1-468-g235dd37\OpenSim\Region\CoreModules\Avatar\Attachments\AttachmentsModule.cs:line 990
   at OpenSim.Region.CoreModules.Avatar.Attachments.AttachmentsModule.AttachObjectInternal(IScenePresence sp, SceneObjectGroup group, UInt32 attachmentPt, Boolean silent, Boolean addToInventory, Boolean resumeScripts, Boolean append) in d:\Temp\opensim-0.9.0.1-468-g235dd37\OpenSim\Region\CoreModules\Avatar\Attachments\AttachmentsModule.cs:line 578
   at OpenSim.Region.CoreModules.Avatar.Attachments.AttachmentsModule.AttachObject(IScenePresence sp, SceneObjectGroup group, UInt32 attachmentPt, Boolean silent, Boolean addToInventory, Boolean append) in d:\Temp\opensim-0.9.0.1-468-g235dd37\OpenSim\Region\CoreModules\Avatar\Attachments\AttachmentsModule.cs:line 465
   at OpenSim.Region.Framework.Scenes.Scene.AddSceneObject(SceneObjectGroup sceneObject) in d:\Temp\opensim-0.9.0.1-468-g235dd37\OpenSim\Region\Framework\Scenes\Scene.cs:line 2965
   at OpenSim.Region.CoreModules.Framework.EntityTransfer.EntityTransferModule.HandleIncomingSceneObject(SceneObjectGroup so, Vector3 newPosition) in d:\Temp\opensim-0.9.0.1-468-g235dd37\OpenSim\Region\CoreModules\Framework\EntityTransfer\EntityTransferModule.cs:line 2649
   at OpenSim.Region.CoreModules.Framework.EntityTransfer.HGEntityTransferModule.HandleIncomingSceneObject(SceneObjectGroup so, Vector3 newPosition) in d:\Temp\opensim-0.9.0.1-468-g235dd37\OpenSim\Region\CoreModules\Framework\EntityTransfer\HGEntityTransferModule.cs:line 598
   at OpenSim.Region.Framework.Scenes.Scene.IncomingCreateObject(Vector3 newPosition, ISceneObject sog) in d:\Temp\opensim-0.9.0.1-468-g235dd37\OpenSim\Region\Framework\Scenes\Scene.cs:line 2894
   at OpenSim.Region.CoreModules.Avatar.Attachments.AttachmentsModule.CopyAttachments(AgentData ad, IScenePresence sp) in d:\Temp\opensim-0.9.0.1-468-g235dd37\OpenSim\Region\CoreModules\Avatar\Attachments\AttachmentsModule.cs:line 278
   at OpenSim.Region.Framework.Scenes.ScenePresence.CopyFrom(AgentData cAgent) in d:\Temp\opensim-0.9.0.1-468-g235dd37\OpenSim\Region\Framework\Scenes\ScenePresence.cs:line 4856
   at OpenSim.Region.Framework.Scenes.ScenePresence.UpdateChildAgent(AgentData cAgentData) in d:\Temp\opensim-0.9.0.1-468-g235dd37\OpenSim\Region\Framework\Scenes\ScenePresence.cs:line 4635
   at OpenSim.Region.Framework.Scenes.Scene.IncomingUpdateChildAgent(AgentData cAgentData) in d:\Temp\opensim-0.9.0.1-468-g235dd37\OpenSim\Region\Framework\Scenes\Scene.cs:line 4558
   at OpenSim.Region.CoreModules.ServiceConnectorsOut.Simulation.LocalSimulationConnectorModule.UpdateAgent(GridRegion destination, AgentData cAgentData, EntityTransferContext ctx) in d:\Temp\opensim-0.9.0.1-468-g235dd37\OpenSim\Region\CoreModules\ServiceConnectorsOut\Simulation\LocalSimulationConnector.cs:line 218
   at OpenSim.Server.Handlers.Simulation.AgentPutHandler.UpdateAgent(GridRegion destination, AgentData agent) in d:\Temp\opensim-0.9.0.1-468-g235dd37\OpenSim\Server\Handlers\Simulation\AgentHandlers.cs:line 766
   at OpenSim.Server.Handlers.Simulation.AgentPutHandler.DoAgentPut(Hashtable request, Hashtable responsedata) in d:\Temp\opensim-0.9.0.1-468-g235dd37\OpenSim\Server\Handlers\Simulation\AgentHandlers.cs:line 735
   at OpenSim.Server.Handlers.Simulation.AgentPutHandler.ProcessRequest(String path, Stream request, IOSHttpRequest httpRequest, IOSHttpResponse httpResponse) in d:\Temp\opensim-0.9.0.1-468-g235dd37\OpenSim\Server\Handlers\Simulation\AgentHandlers.cs:line 668
   at OpenSim.Framework.Servers.HttpServer.BaseStreamHandler.Handle(String path, Stream request, IOSHttpRequest httpRequest, IOSHttpResponse httpResponse) in d:\Temp\opensim-0.9.0.1-468-g235dd37\OpenSim\Framework\Servers\HttpServer\BaseStreamHandler.cs:line 72
   at OpenSim.Framework.Servers.HttpServer.BaseHttpServer.HandleRequest(OSHttpRequest request, OSHttpResponse response) in d:\Temp\opensim-0.9.0.1-468-g235dd37\OpenSim\Framework\Servers\HttpServer\BaseHttpServer.cs:line 706

(0033160)
aiaustin (developer)
2018-10-11 01:25
edited on: 2018-10-11 01:30

My grids are not using Gloebits.

My normal, non region owning, users also report the TP problems, with sometimes the second attempt working, and also report significantly slower region contents download to what they experienced previously. I see very slow loading of region content too, even when the regions have been up a while to let any startup tasks, map tile creation, etc, complete. And slow even when nothing else is happening on the server side.

Not sure when this started but I have a niggling worry it may have been when the last major Windows 10 update to winver 1803 was installed. I cannot be sure about that though, and I am reluctant to downgrade to test if that is a factor. This also coincided with the time we moved to .net4.6 (initially on the httptests branch which I adopted in April) and other changes.

(0033161)
aiaustin (developer)
2018-10-11 02:06
edited on: 2018-10-11 02:06

@watcher64, compared to what you were seeing in say February/March 2018 do you see slow down in loading of region content (prims, meshes and textures) along with the TP failures.. or am I perhaps looking at a separate problem there?

(0033163)
BillBlight (developer)
2018-10-11 09:20

I mainly run linux regions but , I did notice my windows connected test regions were running a bit slower ..

(as far object loading there was a big change to master regarding this a few days ago, but it does not seem to affect this sporadic tp issue)

I have suspected a Windows Update / Anti-virus combo causing issues for a while but the idea did not get much traction .
(0033164)
aiaustin (developer)
2018-10-11 10:20
edited on: 2018-10-23 04:25

I am only using standard Windows Defender and no third party anti-virus package. Problem did start some months ago... April 2018 or so, and latest update from dev master has no effect on issue.

Slow load I note is for region content, rather than inventory. But lets focus in this issue on the failed TP problems and if necessary I will start a separate Mantis issue for slow content load once that is fixed or settles down.

(0033245)
aiaustin (developer)
2018-10-23 03:47
edited on: 2018-10-23 03:51

On AiLand grid again (my experimental grid for OpenSim development testing on the (almost usually) latest dev master code). Windows 10 servers, BulletSim physics, servers have fast connections (500Mbps download AND upload reported by speedtest.net).

I am on a region (Black Rock in this instance) on one server and try to go back to the home region (AiLand) which is on another server on same subnet running Robust.exe and one OpenSim.exe instance. I frequently fail to get back to that region with the viewer saying it cannot establish a connection between the viewer and region server... here are the logs as seen at the receiving region ("AiLand")

11:38:24 - [AGENT HANDLER]: QueryAccess returned True (). Version=0, 0.6/0.6
11:38:24 - [SCENE]: Region AiLand told of incoming child agent Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb (circuit code 1823008730, IP 77.102.240.22, viewer Firestorm-Releasex64 5.1.7.55786, teleportflags (SetLastToTarget, ViaHome), position <126.6773, 128.218, 25.09347>. From region Black Rock (8d78c4ed-c99f-4894-81e1-8ab412619427) @ http://ai.vue.ed.ac.uk:8002/ [^]
11:38:24 - [SCENE]: Reusing existing child scene presence for Ai Austin, state Running in AiLand
11:38:24 - [SCENE]: Adjusting known seeds for existing agent ff0a6e25-15cf-4294-9374-4ce8cdec65eb in AiLand
11:38:24 - [CHILDAGENTDATAUPDATE]: got packed appearance
11:38:24 - [SCENE]: Incoming child agent update for ff0a6e25-15cf-4294-9374-4ce8cdec65eb in AiLand
11:38:51 - [SCENE]: Found presence Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb unexpectedly still child in AiLand
11:38:51 - [LOGHTTP]: Slow handling of 164 PUT /agent/ff0a6e25-15cf-4294-9374-4ce8cdec65eb/ from 129.215.219.52:62208 took 26703ms
11:38:51 - [AGENT HANDLER]: >>> DELETE <<< RegionID: 46d2006b-4531-4f77-a2bb-f785d416ae03; from: 129.215.219.52; auth_code: 5032e093-c843-410d-8f9f-2b3307e173bd
11:38:51 - [CLIENT]: Close has been called for Ai Austin attached to scene AiLand
11:38:51 - [JobEngine]: Stopping AsyncInUDP-ff0a6e25-15cf-4294-9374-4ce8cdec65eb
11:38:51 - [SCENE]: Removing child agent Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb from AiLand
11:38:51 - [CAPS]: Remove caps for agent ff0a6e25-15cf-4294-9374-4ce8cdec65eb in region AiLand
11:38:51 - [Scene]: The avatar has left the building
11:39:00 - [LLUDPSERVER]: Handling UseCircuitCode request for circuit 1823008730 to AiLand from IP 77.102.240.22:64756
11:39:00 - [LLUDPSERVER]: Ignoring connection request for ff0a6e25-15cf-4294-9374-4ce8cdec65eb to AiLand with unknown circuit code 1823008730 from IP 77.102.240.22:64756
11:39:08 - [LLUDPSERVER]: Handling UseCircuitCode request for circuit 1823008730 to AiLand from IP 77.102.240.22:64756
11:39:08 - [LLUDPSERVER]: Ignoring connection request for ff0a6e25-15cf-4294-9374-4ce8cdec65eb to AiLand with unknown circuit code 1823008730 from IP 77.102.240.22:64756
11:39:18 - [LLUDPSERVER]: Handling UseCircuitCode request for circuit 1823008730 to AiLand from IP 77.102.240.22:64756
11:39:18 - [LLUDPSERVER]: Ignoring connection request for ff0a6e25-15cf-4294-9374-4ce8cdec65eb to AiLand with unknown circuit code 1823008730 from IP 77.102.240.22:64756
11:39:28 - [LLUDPSERVER]: Handling UseCircuitCode request for circuit 1823008730 to AiLand from IP 77.102.240.22:64756
11:39:28 - [LLUDPSERVER]: Ignoring connection request for ff0a6e25-15cf-4294-9374-4ce8cdec65eb to AiLand with unknown circuit code 1823008730 from IP 77.102.240.22:64756
Region (root) #


SECOND ATTEMPT: Then on a second attempt I get a red error...reporting System.NullReferenceException: Object reference not set to an instance of an object. And viewer just seems to stay on black screen with teleport progress bar indicating "Contacting new region."

Region (root) #
11:45:26 - [AGENT HANDLER]: QueryAccess returned True (). Version=0, 0.6/0.6
11:45:26 - [SCENE]: Region AiLand told of incoming child agent Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb (circuit code 1823008730, IP 77.102.240.22, viewer Firestorm-Releasex64 5.1.7.55786, teleportflags (SetLastToTarget, ViaHome), position <126.6773, 128.218, 25.09347>. From region Black Rock (8d78c4ed-c99f-4894-81e1-8ab412619427) @ http://ai.vue.ed.ac.uk:8002/ [^]
11:45:26 - [SCENE]: Region AiLand authenticated and authorized incoming child agent Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb (circuit code 1823008730)
11:45:26 - [CreateCaps]: new caps agent ff0a6e25-15cf-4294-9374-4ce8cdec65eb, circuit 1823008730, path 1ecb8c66-823e-446a-8184-cd77db861c1a, time 0
11:45:26 - [VivoxVoice]: OnRegisterCaps: agentID ff0a6e25-15cf-4294-9374-4ce8cdec65eb caps OpenSim.Framework.Capabilities.Caps
11:45:26 - [CHILDAGENTDATAUPDATE]: got packed appearance
11:45:27 - [SCENE]: Incoming child agent update for ff0a6e25-15cf-4294-9374-4ce8cdec65eb in AiLand
11:45:27 - [LLUDPSERVER]: Handling UseCircuitCode request for circuit 1823008730 to AiLand from IP 77.102.240.22:64756
11:45:27 - [SCENE]: Adding new child scene presence Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb to scene AiLand at pos <126.6773, 128.218, 25.09347>, tpflags: SetLastToTarget, ViaHome
11:45:27 - [CAPS]: Received SEED caps request in AiLand for agent ff0a6e25-15cf-4294-9374-4ce8cdec65eb
11:45:27 - [LLUDPSERVER]: Client created, processing pending queue, 1 entries
11:45:27 - [LLClientView]: HandleCompleteAgentMovement
11:45:27 - [SCENE PRESENCE]: Completing movement of Ai Austin into region AiLand in position <126.6773, 128.218, 25.09347>
11:45:27 - [SCENEGRAPH]: Scene graph for AiLand already contains object 1e19e912-f0b7-4ab7-af25-71300c49e798 in AddSceneObject()
11:45:27 - [BASE HTTP SERVER]: HandleRequest() threw exception System.NullReferenceException: Object reference not set to an instance of an object.
   at OpenSim.Region.Framework.Scenes.SceneObjectPart.get_GroupPosition() in d:\Temp\opensim-0.9.0.1-495-g050d53f\OpenSim\Region\Framework\Scenes\SceneObjectPart.cs:line 817
   at OpenSim.Region.Framework.Scenes.SceneObjectGroup.set_AbsolutePosition(Vector3 value) in d:\Temp\opensim-0.9.0.1-495-g050d53f\OpenSim\Region\Framework\Scenes\SceneObjectGroup.cs:line 582
   at OpenSim.Region.CoreModules.Avatar.Attachments.AttachmentsModule.AttachToAgent(IScenePresence sp, SceneObjectGroup so, UInt32 attachmentpoint, Vector3 attachOffset, Boolean silent) in d:\Temp\opensim-0.9.0.1-495-g050d53f\OpenSim\Region\CoreModules\Avatar\Attachments\AttachmentsModule.cs:line 990
   at OpenSim.Region.CoreModules.Avatar.Attachments.AttachmentsModule.AttachObjectInternal(IScenePresence sp, SceneObjectGroup group, UInt32 attachmentPt, Boolean silent, Boolean addToInventory, Boolean resumeScripts, Boolean append) in d:\Temp\opensim-0.9.0.1-495-g050d53f\OpenSim\Region\CoreModules\Avatar\Attachments\AttachmentsModule.cs:line 578
   at OpenSim.Region.CoreModules.Avatar.Attachments.AttachmentsModule.AttachObject(IScenePresence sp, SceneObjectGroup group, UInt32 attachmentPt, Boolean silent, Boolean addToInventory, Boolean append) in d:\Temp\opensim-0.9.0.1-495-g050d53f\OpenSim\Region\CoreModules\Avatar\Attachments\AttachmentsModule.cs:line 465
   at OpenSim.Region.Framework.Scenes.Scene.AddSceneObject(SceneObjectGroup sceneObject) in d:\Temp\opensim-0.9.0.1-495-g050d53f\OpenSim\Region\Framework\Scenes\Scene.cs:line 2965
   at OpenSim.Region.CoreModules.Framework.EntityTransfer.EntityTransferModule.HandleIncomingSceneObject(SceneObjectGroup so, Vector3 newPosition) in d:\Temp\opensim-0.9.0.1-495-g050d53f\OpenSim\Region\CoreModules\Framework\EntityTransfer\EntityTransferModule.cs:line 2649
   at OpenSim.Region.CoreModules.Framework.EntityTransfer.HGEntityTransferModule.HandleIncomingSceneObject(SceneObjectGroup so, Vector3 newPosition) in d:\Temp\opensim-0.9.0.1-495-g050d53f\OpenSim\Region\CoreModules\Framework\EntityTransfer\HGEntityTransferModule.cs:line 598
   at OpenSim.Region.Framework.Scenes.Scene.IncomingCreateObject(Vector3 newPosition, ISceneObject sog) in d:\Temp\opensim-0.9.0.1-495-g050d53f\OpenSim\Region\Framework\Scenes\Scene.cs:line 2894
   at OpenSim.Region.CoreModules.Avatar.Attachments.AttachmentsModule.CopyAttachments(AgentData ad, IScenePresence sp) in d:\Temp\opensim-0.9.0.1-495-g050d53f\OpenSim\Region\CoreModules\Avatar\Attachments\AttachmentsModule.cs:line 278
   at OpenSim.Region.Framework.Scenes.ScenePresence.CopyFrom(AgentData cAgent) in d:\Temp\opensim-0.9.0.1-495-g050d53f\OpenSim\Region\Framework\Scenes\ScenePresence.cs:line 4856
   at OpenSim.Region.Framework.Scenes.ScenePresence.UpdateChildAgent(AgentData cAgentData) in d:\Temp\opensim-0.9.0.1-495-g050d53f\OpenSim\Region\Framework\Scenes\ScenePresence.cs:line 4635
   at OpenSim.Region.Framework.Scenes.Scene.IncomingUpdateChildAgent(AgentData cAgentData) in d:\Temp\opensim-0.9.0.1-495-g050d53f\OpenSim\Region\Framework\Scenes\Scene.cs:line 4558
   at OpenSim.Region.CoreModules.ServiceConnectorsOut.Simulation.LocalSimulationConnectorModule.UpdateAgent(GridRegion destination, AgentData cAgentData, EntityTransferContext ctx) in d:\Temp\opensim-0.9.0.1-495-g050d53f\OpenSim\Region\CoreModules\ServiceConnectorsOut\Simulation\LocalSimulationConnector.cs:line 218
   at OpenSim.Server.Handlers.Simulation.AgentPutHandler.UpdateAgent(GridRegion destination, AgentData agent) in d:\Temp\opensim-0.9.0.1-495-g050d53f\OpenSim\Server\Handlers\Simulation\AgentHandlers.cs:line 766
   at OpenSim.Server.Handlers.Simulation.AgentPutHandler.DoAgentPut(Hashtable request, Hashtable responsedata) in d:\Temp\opensim-0.9.0.1-495-g050d53f\OpenSim\Server\Handlers\Simulation\AgentHandlers.cs:line 735
   at OpenSim.Server.Handlers.Simulation.AgentPutHandler.ProcessRequest(String path, Stream request, IOSHttpRequest httpRequest, IOSHttpResponse httpResponse) in d:\Temp\opensim-0.9.0.1-495-g050d53f\OpenSim\Server\Handlers\Simulation\AgentHandlers.cs:line 668
   at OpenSim.Framework.Servers.HttpServer.BaseStreamHandler.Handle(String path, Stream request, IOSHttpRequest httpRequest, IOSHttpResponse httpResponse) in d:\Temp\opensim-0.9.0.1-495-g050d53f\OpenSim\Framework\Servers\HttpServer\BaseStreamHandler.cs:line 72
   at OpenSim.Framework.Servers.HttpServer.BaseHttpServer.HandleRequest(OSHttpRequest request, OSHttpResponse response) in d:\Temp\opensim-0.9.0.1-495-g050d53f\OpenSim\Framework\Servers\HttpServer\BaseHttpServer.cs:line 706

11:45:37 - [SCENE PRESENCE]: Update agent Ai Austin at AiLand did not receive agent update
Region (root) #

THIRD ATTEMPT: teleport worked straight away...

11:52:57 - [AGENT HANDLER]: QueryAccess returned True (). Version=0, 0.6/0.6
11:52:57 - [SCENE]: Region AiLand told of incoming child agent Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb (circuit code 1823008730, IP 77.102.240.22, viewer Firestorm-Releasex64 5.1.7.55786, teleportflags (SetLastToTarget, ViaHome), position <126.6773, 128.218, 25.09347>. From region Black Rock (8d78c4ed-c99f-4894-81e1-8ab412619427) @ http://ai.vue.ed.ac.uk:8002/ [^]
11:52:57 - [SCENE]: Reusing existing child scene presence for Ai Austin, state Running in AiLand
11:52:57 - [SCENE]: Adjusting known seeds for existing agent ff0a6e25-15cf-4294-9374-4ce8cdec65eb in AiLand
11:52:57 - [CHILDAGENTDATAUPDATE]: got packed appearance
11:52:57 - [SCENE]: Incoming child agent update for ff0a6e25-15cf-4294-9374-4ce8cdec65eb in AiLand
11:52:57 - [LLClientView]: HandleCompleteAgentMovement
11:52:57 - [SCENE PRESENCE]: Completing movement of Ai Austin into region AiLand in position <126.6773, 128.218, 25.09347>
11:52:57 - [CAPS]: Received SEED caps request in AiLand for agent ff0a6e25-15cf-4294-9374-4ce8cdec65eb
11:52:57 - [CompleteMovement]: Missing COF for ff0a6e25-15cf-4294-9374-4ce8cdec65eb is 01f15915-e6a3-4548-b62c-e39995c37b15
11:52:57 - [XBakes]: read 5 textures for user ff0a6e25-15cf-4294-9374-4ce8cdec65eb
11:52:57 - [ValidateBakedCache]: got bakedModule 5 cached textures
11:52:58 - [CompleteMovement]: end: 640ms
11:52:58 - [AVFACTORY]: Received texture update for Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb
11:52:58 - [UpdateBakedCache]: cache hits: 5 changed entries: 0 rebakes 0
11:52:58 - [ENTITY TRANSFER MODULE]: Informing Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb about neighbour Castle 129.215.219.52:9017 at (6398,6401)
11:52:58 - [REMOTE SIMULATION CONNECTOR]: Creating agent at http://tiree.aiai.ed.ac.uk:9000/ [^]
11:52:58 - [ENTITY TRANSFER MODULE]: AiLand is sending Ai Austin EnableSimulator for neighbour region Castle(loc=<1637888,1638656>,siz=<256,256>) and EstablishAgentCommunication with seed cap http://tiree.aiai.ed.ac.uk:9000/CAPS/997e02ce-82bd-4720-bdbd-b6f256d620600000/ [^]
11:52:58 - [ENTITY TRANSFER MODULE]: Completed inform Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb about neighbour 129.215.219.52:9017
11:52:58 - [ENTITY TRANSFER MODULE]: Informing Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb about neighbour Aisle 129.215.219.52:9012 at (6398,6399)
11:52:58 - [REMOTE SIMULATION CONNECTOR]: Creating agent at http://tiree.aiai.ed.ac.uk:9000/ [^]
11:52:59 - [ENTITY TRANSFER MODULE]: AiLand is sending Ai Austin EnableSimulator for neighbour region Aisle(loc=<1637888,1638144>,siz=<256,256>) and EstablishAgentCommunication with seed cap http://tiree.aiai.ed.ac.uk:9000/CAPS/dcd2ad52-54d8-4c6e-a7a5-816597772ea00000/ [^]
11:52:59 - [ENTITY TRANSFER MODULE]: Completed inform Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb about neighbour 129.215.219.52:9012
11:52:59 - [ENTITY TRANSFER MODULE]: Informing Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb about neighbour Black Rock 129.215.219.52:9007 at (6402,6400)
11:52:59 - [REMOTE SIMULATION CONNECTOR]: Creating agent at http://tiree.aiai.ed.ac.uk:9000/ [^]
11:52:59 - [ENTITY TRANSFER MODULE]: AiLand is sending Ai Austin EnableSimulator for neighbour region Black Rock(loc=<1638912,1638400>,siz=<256,256>) and EstablishAgentCommunication with seed cap http://tiree.aiai.ed.ac.uk:9000/CAPS/401306af-8fdd-4a1b-816b-01e7cb83b9080000/ [^]
11:52:59 - [ENTITY TRANSFER MODULE]: Completed inform Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb about neighbour 129.215.219.52:9007
11:52:59 - [ENTITY TRANSFER MODULE]: Informing Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb about neighbour AiAi 129.215.219.52:9011 at (6398,6398)
11:52:59 - [REMOTE SIMULATION CONNECTOR]: Creating agent at http://tiree.aiai.ed.ac.uk:9000/ [^]
11:53:00 - [ENTITY TRANSFER MODULE]: AiLand is sending Ai Austin EnableSimulator for neighbour region AiAi(loc=<1637888,1637888>,siz=<256,256>) and EstablishAgentCommunication with seed cap http://tiree.aiai.ed.ac.uk:9000/CAPS/3cf5ee08-3072-4bba-aabc-b47081a9998c0000/ [^]
11:53:00 - [ENTITY TRANSFER MODULE]: Completed inform Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb about neighbour 129.215.219.52:9011
Region (root) #

(0033246)
aiaustin (developer)
2018-10-23 04:12
edited on: 2018-10-23 04:14

I see (often) ALL the symptoms that @mewtwo0641 reported.

As @watcher64 indicated the red error reported on SECOND ATTEMPT above showed some traces of the error as involving attachments and there could be something weird about the attachments after the failure as I can't remove them without a relog.

But after a fresh login I tried my avatar without ANY attachments of any kind, no HUDs also and the same problems occur. There seems to be a login but then after a slow PUT of around 30 seconds things fail... and this is on an otherwise completely idling grid... I have got to suspect some sort of sync/timing issue here?

12:13:44 - [SCENE PRESENCE]: Did not find presence with id ff0a6e25-15cf-4294-9374-4ce8cdec65eb in AiLand before timeout
12:13:44 - [LOGHTTP]: Slow handling of 572 PUT /agent/ff0a6e25-15cf-4294-9374-4ce8cdec65eb/ from 129.215.219.52:62269 took 31860ms

Full trace of OpenSim.exe on AiLand (receiving end of transfer)...

12:12:33 - [SCENE]: Found presence Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb unexpectedly still child in AiLand
12:12:33 - [LOGHTTP]: Slow handling of 568 PUT /agent/ff0a6e25-15cf-4294-9374-4ce8cdec65eb/ from 129.215.219.52:62263 took 26562ms
12:12:33 - [AGENT HANDLER]: >>> DELETE <<< RegionID: 46d2006b-4531-4f77-a2bb-f785d416ae03; from: 129.215.219.52; auth_code: d2adff75-3b54-4ae2-966a-2adc261753dc
12:12:33 - [CLIENT]: Close has been called for Ai Austin attached to scene AiLand
12:12:33 - [JobEngine]: Stopping AsyncInUDP-ff0a6e25-15cf-4294-9374-4ce8cdec65eb
12:12:33 - [SCENE]: Removing child agent Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb from AiLand
12:12:33 - [CAPS]: Remove caps for agent ff0a6e25-15cf-4294-9374-4ce8cdec65eb in region AiLand
12:12:33 - [HG MAP]: Resetting 13 blocks
12:12:33 - [Scene]: The avatar has left the building
12:13:12 - [AGENT HANDLER]: QueryAccess returned True (). Version=0, 0.6/0.6
12:13:12 - [SCENE]: Region AiLand told of incoming child agent Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb (circuit code 491647068, IP 77.102.240.22, viewer Firestorm-Releasex64 5.1.7.55786, teleportflags (SetLastToTarget, ViaHome), position <126.6773, 128.218, 25.09347>. From region Space City (2fbab20f-b583-424a-a38b-e77895ebc1b6) @ http://ai.vue.ed.ac.uk:8002/ [^]
12:13:12 - [SCENE]: Region AiLand authenticated and authorized incoming child agent Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb (circuit code 491647068)
12:13:12 - [CreateCaps]: new caps agent ff0a6e25-15cf-4294-9374-4ce8cdec65eb, circuit 491647068, path 7bd12b6a-37cf-4a54-a7d9-d1eb55600252, time 0
12:13:12 - [VivoxVoice]: OnRegisterCaps: agentID ff0a6e25-15cf-4294-9374-4ce8cdec65eb caps OpenSim.Framework.Capabilities.Caps
12:13:12 - [CHILDAGENTDATAUPDATE]: got packed appearance
12:13:12 - [SCENE]: Incoming child agent update for ff0a6e25-15cf-4294-9374-4ce8cdec65eb in AiLand
12:13:44 - [SCENE PRESENCE]: Did not find presence with id ff0a6e25-15cf-4294-9374-4ce8cdec65eb in AiLand before timeout
12:13:44 - [LOGHTTP]: Slow handling of 572 PUT /agent/ff0a6e25-15cf-4294-9374-4ce8cdec65eb/ from 129.215.219.52:62269 took 31860ms
12:13:44 - [AGENT HANDLER]: >>> DELETE <<< RegionID: 46d2006b-4531-4f77-a2bb-f785d416ae03; from: 129.215.219.52; auth_code: d2adff75-3b54-4ae2-966a-2adc261753dc
12:13:44 - [SCENE]: Called CloseClient() with agent ID ff0a6e25-15cf-4294-9374-4ce8cdec65eb but no such presence is in AiLand
Region (root) #

(0033247)
aiaustin (developer)
2018-10-23 04:47
edited on: 2018-10-23 04:54

I have viewer and region max draw type settings at 511/512

DefaultDrawDistance = 511.0
; MaxDrawDistance = 512
MaxRegionsViewDistance = 511

So, just in case there was some issue with child agents I tested only teleporting between regions more than 3 standard regions apart and source and destination regions are the same OpenSim.exe instance on the Ailand grid, and I observe the same issues. So it does not seem to vary by crossing to different OpenSim.exe instances on other servers or jumping to regions where the avatar might already have a child agent.

And just to keep it simple the problems occur when sing only a single server running the Robust.exe and OpenSim.exe (with 3 regions on it) and teleporting from one region (Edinburgh) to another (AiLand) straight after a clean fresh login.

12:55:15 - [ENTITY TRANSFER MODULE]: Request to teleport Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb home
12:55:15 - [HG ENTITY TRANSFER MODULE]: User is local
12:55:15 - [ENTITY TRANSFER MODULE]: Request to teleport Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb home
12:55:15 - [ENTITY TRANSFER MODULE]: Home region of Ai Austin is AiLand (6400-6400)
12:55:15 - [HG ENTITY TRANSFER MODULE]: region AiLand flags: 4
12:55:15 - [ENTITY TRANSFER MODULE]: Teleporting Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb from Edinburgh to http://ai.vue.ed.ac.uk:9000/ [^] (http://ai.vue.ed.ac.uk:9000/ [^]) AiLand/<126.6773, 128.218, 25.09347>
12:55:15 - [ENTITY TRANSFER MODULE]: Edinburgh transfer protocol version to AiLand is 0.6 / 0.6
12:55:15 - [SCENE PRESENCE]: Closing child agents. Checking 7 regions in Edinburgh
12:55:15 - [HG ENTITY TRANSFER MODULE]: CreateAgent http://ai.vue.ed.ac.uk:9000/ [^] http://ai.vue.ed.ac.uk:9000/ [^]
12:55:15 - [SCENE]: Region AiLand told of incoming child agent Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb (circuit code 747859189, IP 77.102.240.22, viewer Firestorm-Releasex64 5.1.7.55786, teleportflags (SetLastToTarget, ViaHome), position <126.6773, 128.218, 25.09347>. From region Edinburgh (98b848b4-64c0-4f07-a4a2-9e92b75cb106) @ http://ai.vue.ed.ac.uk:8002/ [^]
12:55:15 - [SCENE]: Reusing existing child scene presence for Ai Austin, state Running in AiLand
12:55:15 - [SCENE]: Adjusting known seeds for existing agent ff0a6e25-15cf-4294-9374-4ce8cdec65eb in AiLand
12:55:15 - [ENTITY TRANSFER MODULE]: Sending new CAPS seed url http://ai.vue.ed.ac.uk:9000/CAPS/4293bb2c-20b4-49d1-a939-82142350aeb10000/ [^] from Edinburgh to Ai Austin
12:55:15 - [SCENE]: Incoming child agent update for ff0a6e25-15cf-4294-9374-4ce8cdec65eb in AiLand
12:55:42 - [SCENE]: Found presence Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb unexpectedly still child in AiLand
12:55:42 - [ENTITY TRANSFER MODULE]: UpdateAgent failed on teleport of Ai Austin to AiLand. Keeping avatar in Edinburgh
12:55:42 - [CLIENT]: Close has been called for Ai Austin attached to scene AiLand
12:55:42 - [JobEngine]: Stopping AsyncInUDP-ff0a6e25-15cf-4294-9374-4ce8cdec65eb
12:55:42 - [SCENE]: Removing child agent Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb from AiLand
12:55:42 - [CAPS]: Remove caps for agent ff0a6e25-15cf-4294-9374-4ce8cdec65eb in region AiLand
12:55:42 - [INVENTORY CACHE]: OnClientClosed in AiLand, but user ff0a6e25-15cf-4294-9374-4ce8cdec65eb still in sim. Keeping inventoryURL in cache
12:55:42 - [HG MAP]: Resetting 13 blocks
12:55:42 - [Scene]: The avatar has left the building
Region (root) #

(0033248)
aiaustin (developer)
2018-10-23 07:07
edited on: 2018-10-24 03:53

I have simplified the test setup and can now replicate this problem on a single Windows 10 (build 1803) machine with Xeon processor and 32GB memory on a very fast University network with 500mpbs uplink and downlink reported by speedtest.net and running Dev master opensim-0.9.0.1-498-g601d965.zip (2018-10-23 11:27) with the MySQL 5.7, Robust.exe and one OpenSim.exe instance with two adjacent 256x266 regions (Ailand and Edinburgh) all running on same server. I bring the servers up and let them settle for a few minutes. No apparent activity. Then I log in via Firestorm 5.1.7.55786 (64 bit SL/OpenSim version) and teleport between these two waiting about 30 seconds to a minute between attempts so things are settled down.

I get the viewer pop up that "Teleport failed. Problems connecting to destination Edinburgh, reason: Connection between viewer and destination region could not be established." This error occurs one in every two or three attempts... log from OpenSim.exe for a failed attempt is as follows...

15:01:20 - [LAND MANAGEMENT MODULE]: Got parcelinfo request for regionHandle 7036874419405056, x/y 181/100
15:01:20 - [LAND MANAGEMENT MODULE]: got parcelinfo for parcel Edinburgh on AiLand in region 7036874419405056; sending...
15:01:21 - [HG ENTITY TRANSFER MODULE]: region Edinburgh flags: 4
15:01:21 - [ENTITY TRANSFER MODULE]: Teleporting Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb from AiLand to http://ai.vue.ed.ac.uk:9000/ [^] (http://ai.vue.ed.ac.uk:9000/ [^]) Edinburgh/<181.023, 100.0835, 25.61288>
15:01:21 - [ENTITY TRANSFER MODULE]: AiLand transfer protocol version to Edinburgh is 0.6 / 0.6
15:01:21 - [SCENE PRESENCE]: Closing child agents. Checking 2 regions in AiLand
15:01:21 - [HG ENTITY TRANSFER MODULE]: CreateAgent http://ai.vue.ed.ac.uk:9000/ [^] http://ai.vue.ed.ac.uk:9000/ [^]
15:01:21 - [SCENE]: Region Edinburgh told of incoming child agent Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb (circuit code 152229608, IP 77.102.240.22, viewer Firestorm-Releasex64 5.1.7.55786, teleportflags (ViaLocation), position <181.023, 100.0835, 25.61288>. From region AiLand (46d2006b-4531-4f77-a2bb-f785d416ae03) @ http://ai.vue.ed.ac.uk:8002/ [^]
15:01:21 - [SCENE]: Reusing existing child scene presence for Ai Austin, state Running in Edinburgh
15:01:21 - [SCENE]: Adjusting known seeds for existing agent ff0a6e25-15cf-4294-9374-4ce8cdec65eb in Edinburgh
15:01:21 - [ENTITY TRANSFER MODULE]: Sending new CAPS seed url http://ai.vue.ed.ac.uk:9000/CAPS/27d06b7f-ded2-4eab-af7b-50e705a9a31f0000/ [^] from AiLand to Ai Austin
15:01:21 - [SCENE]: Incoming child agent update for ff0a6e25-15cf-4294-9374-4ce8cdec65eb in Edinburgh
15:01:48 - [SCENE]: Found presence Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb unexpectedly still child in Edinburgh
15:01:48 - [ENTITY TRANSFER MODULE]: UpdateAgent failed on teleport of Ai Austin to Edinburgh. Keeping avatar in AiLand
15:01:48 - [CLIENT]: Close has been called for Ai Austin attached to scene Edinburgh
15:01:48 - [JobEngine]: Stopping AsyncInUDP-ff0a6e25-15cf-4294-9374-4ce8cdec65eb
15:01:48 - [SCENE]: Removing child agent Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb from Edinburgh
15:01:48 - [CAPS]: Remove caps for agent ff0a6e25-15cf-4294-9374-4ce8cdec65eb in region Edinburgh
15:01:48 - [Scene]: The avatar has left the building
15:01:54 - [LLUDPSERVER]: Handling UseCircuitCode request for circuit 152229608 to Edinburgh from IP 77.102.240.22:56441
15:01:54 - [LLUDPSERVER]: Ignoring connection request for ff0a6e25-15cf-4294-9374-4ce8cdec65eb to Edinburgh with unknown circuit code 152229608 from IP 77.102.240.22:56441
15:02:02 - [LLUDPSERVER]: Handling UseCircuitCode request for circuit 152229608 to Edinburgh from IP 77.102.240.22:56441
15:02:02 - [LLUDPSERVER]: Ignoring connection request for ff0a6e25-15cf-4294-9374-4ce8cdec65eb to Edinburgh with unknown circuit code 152229608 from IP 77.102.240.22:56441
15:02:12 - [LLUDPSERVER]: Handling UseCircuitCode request for circuit 152229608 to Edinburgh from IP 77.102.240.22:56441
15:02:12 - [LLUDPSERVER]: Ignoring connection request for ff0a6e25-15cf-4294-9374-4ce8cdec65eb to Edinburgh with unknown circuit code 152229608 from IP 77.102.240.22:56441
15:02:22 - [LLUDPSERVER]: Handling UseCircuitCode request for circuit 152229608 to Edinburgh from IP 77.102.240.22:56441
15:02:22 - [LLUDPSERVER]: Ignoring connection request for ff0a6e25-15cf-4294-9374-4ce8cdec65eb to Edinburgh with unknown circuit code 152229608 from IP 77.102.240.22:56441
Region (root) #

Note I have tried this with the default Bullet (with and without separatephysicsthread) and ubODE physics and that appears not to have any effect.

(0033261)
aiaustin (developer)
2018-10-24 03:50
edited on: 2018-10-24 03:52

I am struggling to pin this down even though I can replicate this every few attempts to teleport between regions on a simple setup now on one grid with 2 regions all on same server.

I used the "debug attachment log 1" and "show attachment" console commands on source and destination regions but that does not seem to indicate anything odd I can see. In any case I can see the TO failure issue even with a really basic avatar without any attachments of HUDS attached and after a clean relog.

@watcher64... you mentioned you found a way to mitigate the issue. Can you (directly) share this idea with me in case it offers some clues? E-mail ai.ai.austin@gmail.com.

This issue, and one where I appear to have a big slow down in object and texture loading on otherwise idling regions, are on my top list of issues that I am now seeing - and I think have been seeing since April 2018 or so on dev master. Unfortunately Windows 10 update to winver 1803 and our move to .net4.6 all occurred around that time.

(0033265)
aiaustin (developer)
2018-10-26 04:11
edited on: 2018-10-26 04:47

Another observation to try to pin this down... at the time that the avatar is trying to teleport from a source to a destination region and it shows the black screen with "Contacing new region" and long after (1 minute or more?) the OpenSim.exe has given up and indicated "[SCENE PRESENCE]: Update agent Ai Austin at Openvue did not receive agent update"...

I did a "show users" in BOTY the OpenSim.exe of the source region (on the main computer with Robust.exe and the core OpenSim.exe region server) and on a second server the destination region and both indicated NO USERS. The avatar eventually LOOKED LIKE it was on the source region but I could not move it. Show users still showed no avatar anywhere. In such a stuck situation things are effectively frozen for that user until they relog.

I am changing the status of this bug to "blocker" . I am sure others must be having the issue... or I have something seriously wrong with all my setups on 4 separate servers (all on latest dev master). Its so serious that really the grids are no longer usable except for testing to identify the issues. Can we try to get some feedback from anyone seeing something like this to establish if its related to some specific type environment?

(0033266)
aiaustin (developer)
2018-10-26 04:51

To assist in testing and pinning this down Ailand grid ( http://ai.vue.ed.ac.uk:8002 [^] ) is now running only on a single server (Windows 10 winver 1803, Xeon, 32GB memory, 500mbps uplink and downlink to speedtest.net, MySQL 5.7) with Robust.exe and one OpenSim.exe instance with two 256x256 regions adjacent to one another: AiLand (default, fallback) and Edinburgh.
(0033267)
aiaustin (developer)
2018-10-26 05:01

With simple setup of Ailand grid and two standard 256x256 adjacent regions. Avatar with no attachments or HUDs of any kind (and no alpha layers/textures). "attachments show" shows no attachments in either region.

Log in to AiLand (home region). Teleport via map (to avoid scripts such as osTeleportAgent) to "Edinburgh" region. A delay of 10-20 seconds but the avatar does arrive on Edinburgh. "show users" shows it is there. Try a "teleport Home" and it fails with the viewer message "Teleport failed. Problems connecting to destination AiLand, reason: Connection between viewer and destination region could not be established"

Region (root) # attachments show
--- All attachments for region AiLand:
Attachments for Ai Austin

--- All attachments for region Edinburgh:

12:57:23 - [LAND MANAGEMENT MODULE]: Got parcelinfo request for regionHandle 7036874419405056, x/y 156/69
12:57:24 - [LAND MANAGEMENT MODULE]: got parcelinfo for parcel Edinburgh on AiLand in region 7036874419405056; sending...
12:57:25 - [HG ENTITY TRANSFER MODULE]: region Edinburgh flags: 4
12:57:25 - [ENTITY TRANSFER MODULE]: Teleporting Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb from AiLand to http://ai.vue.ed.ac.uk:9000/ [^] (http://ai.vue.ed.ac.uk:9000/ [^]) Edinburgh/<156.8857, 69.61977, 26.60698>
12:57:25 - [ENTITY TRANSFER MODULE]: AiLand transfer protocol version to Edinburgh is 0.6 / 0.6
12:57:25 - [SCENE PRESENCE]: Closing child agents. Checking 2 regions in AiLand
12:57:25 - [HG ENTITY TRANSFER MODULE]: CreateAgent http://ai.vue.ed.ac.uk:9000/ [^] http://ai.vue.ed.ac.uk:9000/ [^]
12:57:25 - [SCENE]: Region Edinburgh told of incoming child agent Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb (circuit code 1229006787, IP 77.102.240.22, viewer Firestorm-Releasex64 5.1.7.55786, teleportflags (ViaLocation), position <156.8857, 69.61977, 26.60698>. From region AiLand (46d2006b-4531-4f77-a2bb-f785d416ae03) @ http://ai.vue.ed.ac.uk:8002/ [^]
12:57:25 - [SCENE]: Reusing existing child scene presence for Ai Austin, state Running in Edinburgh
12:57:25 - [SCENE]: Adjusting known seeds for existing agent ff0a6e25-15cf-4294-9374-4ce8cdec65eb in Edinburgh
12:57:25 - [ENTITY TRANSFER MODULE]: Sending new CAPS seed url http://ai.vue.ed.ac.uk:9000/CAPS/f9ef8381-59aa-4b43-b3b3-7b792d1f996c0000/ [^] from AiLand to Ai Austin
12:57:25 - [SCENE]: Incoming child agent update for ff0a6e25-15cf-4294-9374-4ce8cdec65eb in Edinburgh
12:57:43 - [LLClientView]: HandleCompleteAgentMovement
12:57:43 - [CAPS]: Received SEED caps request in Edinburgh for agent ff0a6e25-15cf-4294-9374-4ce8cdec65eb
12:57:43 - [SCENE PRESENCE]: Completing movement of Ai Austin into region Edinburgh in position <156.8857, 69.61977, 26.60698>
12:57:43 - [CompleteMovement]: Missing COF for ff0a6e25-15cf-4294-9374-4ce8cdec65eb is 01f15915-e6a3-4548-b62c-e39995c37b15
12:57:43 - [SCENE PRESENCE]: Making Ai Austin a child agent in AiLand from root region 7036874419405056
12:57:43 - [CompleteMovement]: end: 547ms
12:57:43 - [AVFACTORY]: Received texture update for Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb
12:57:43 - [UpdateBakedCache]: cache hits: 5 changed entries: 0 rebakes 0
12:57:58 - [ENTITY TRANSFER MODULE]: Request to teleport Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb home
12:57:58 - [HG ENTITY TRANSFER MODULE]: User is local
12:57:58 - [ENTITY TRANSFER MODULE]: Request to teleport Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb home
12:57:58 - [ENTITY TRANSFER MODULE]: Home region of Ai Austin is AiLand (6400-6400)
12:57:58 - [HG ENTITY TRANSFER MODULE]: region AiLand flags: 4
12:57:58 - [ENTITY TRANSFER MODULE]: Teleporting Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb from Edinburgh to http://ai.vue.ed.ac.uk:9000/ [^] (http://ai.vue.ed.ac.uk:9000/ [^]) AiLand/<126.6773, 128.218, 25.09347>
12:57:58 - [ENTITY TRANSFER MODULE]: Edinburgh transfer protocol version to AiLand is 0.6 / 0.6
12:57:58 - [SCENE PRESENCE]: Closing child agents. Checking 2 regions in Edinburgh
12:57:58 - [HG ENTITY TRANSFER MODULE]: CreateAgent http://ai.vue.ed.ac.uk:9000/ [^] http://ai.vue.ed.ac.uk:9000/ [^]
12:57:58 - [SCENE]: Region AiLand told of incoming child agent Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb (circuit code 1229006787, IP 77.102.240.22, viewer Firestorm-Releasex64 5.1.7.55786, teleportflags (SetLastToTarget, ViaHome), position <126.6773, 128.218, 25.09347>. From region Edinburgh (98b848b4-64c0-4f07-a4a2-9e92b75cb106) @ http://ai.vue.ed.ac.uk:8002/ [^]
12:57:58 - [SCENE]: Reusing existing child scene presence for Ai Austin, state Running in AiLand
12:57:58 - [SCENE]: Adjusting known seeds for existing agent ff0a6e25-15cf-4294-9374-4ce8cdec65eb in AiLand
12:57:58 - [ENTITY TRANSFER MODULE]: Sending new CAPS seed url http://ai.vue.ed.ac.uk:9000/CAPS/cd69ef5f-d6cf-454f-bb7f-dd6c320539990000/ [^] from Edinburgh to Ai Austin
12:57:58 - [SCENE]: Incoming child agent update for ff0a6e25-15cf-4294-9374-4ce8cdec65eb in AiLand
12:58:25 - [SCENE]: Found presence Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb unexpectedly still child in AiLand
12:58:25 - [ENTITY TRANSFER MODULE]: UpdateAgent failed on teleport of Ai Austin to AiLand. Keeping avatar in Edinburgh
12:58:25 - [CLIENT]: Close has been called for Ai Austin attached to scene AiLand
12:58:25 - [JobEngine]: Stopping AsyncInUDP-ff0a6e25-15cf-4294-9374-4ce8cdec65eb
12:58:25 - [SCENE]: Removing child agent Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb from AiLand
12:58:25 - [CAPS]: Remove caps for agent ff0a6e25-15cf-4294-9374-4ce8cdec65eb in region AiLand
12:58:25 - [INVENTORY CACHE]: OnClientClosed in AiLand, but user ff0a6e25-15cf-4294-9374-4ce8cdec65eb still in sim. Keeping inventoryURL in cache
12:58:25 - [HG MAP]: Resetting 2 blocks
12:58:25 - [Scene]: The avatar has left the building
Region (root) #
Region (root) #


Region (root) # show users

Agents connected: 1

Firstname Lastname Agent ID Root/Child Region Position
Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb Root Edinburgh <124.5554, 121.4711, 32.08669>

12:59:43 - [LLUDPSERVER]: Handling UseCircuitCode request for circuit 1229006787 to AiLand from IP 77.102.240.22:55256
12:59:43 - [LLUDPSERVER]: Ignoring connection request for ff0a6e25-15cf-4294-9374-4ce8cdec65eb to AiLand with unknown circuit code 1229006787 from IP 77.102.240.22:55256
12:59:51 - [LLUDPSERVER]: Handling UseCircuitCode request for circuit 1229006787 to AiLand from IP 77.102.240.22:55256
12:59:51 - [LLUDPSERVER]: Ignoring connection request for ff0a6e25-15cf-4294-9374-4ce8cdec65eb to AiLand with unknown circuit code 1229006787 from IP 77.102.240.22:55256
13:00:01 - [LLUDPSERVER]: Handling UseCircuitCode request for circuit 1229006787 to AiLand from IP 77.102.240.22:55256
13:00:01 - [LLUDPSERVER]: Ignoring connection request for ff0a6e25-15cf-4294-9374-4ce8cdec65eb to AiLand with unknown circuit code 1229006787 from IP 77.102.240.22:55256
13:00:11 - [LLUDPSERVER]: Handling UseCircuitCode request for circuit 1229006787 to AiLand from IP 77.102.240.22:55256
13:00:11 - [LLUDPSERVER]: Ignoring connection request for ff0a6e25-15cf-4294-9374-4ce8cdec65eb to AiLand with unknown circuit code 1229006787 from IP 77.102.240.22:55256
(0033279)
UbitUmarov (administrator)
2018-10-28 09:03

made a small change on threading in master
plz let me know if any effect
(0033280)
aiaustin (developer)
2018-10-28 09:44
edited on: 2018-10-28 10:12

Thanks for trying something on this @Ubit... I installed opensim-0.9.0.1-507-gcf33e04.zip (latest dev master 2018-10-28 14:43 ) for AiLand grid core server: Xeon processor, 32GB memory, SSD drives, 500mbps uplink and downlink). Let things settle down for a minute or two.

Avatar has no attachments or HUDs and is wearing only system body parts and clothing, no mesh either, not even hair attachment.

Initial login of Ai Austin to region "AiLand" is at 16:35:59. As expected that works fine.

Then teleport attempt from AiLand to Edinburgh (an adjacent region) is at 16:36:22. Fault on TP occurs this time on FIRST attempt. Usual long delay and then (Firestorm 5.1.7.55786 64 bit SL+OS) viewer pops up the message "Teleport failed. Problems connecting to destination AiLand, reason: Connection between viewer and destination region could not be established".

Note the (almost exactly suspiciously?) 30 seconds gap between console log messages when nothing seems to be happening and viewer is stuck on black with "Requesting Teleport..." progress bar screen.. between 16:36:24 and 16:36:55

I tried a SECOND time and that failed... oddly.. I usually can get theer on second attempt... so maybe his change actually made things worse (if that helps diagnose the issue)… at 16:50:17

Then tried a THIRD time and that worked..l log starting at 16:50:55.

I added the gaps between the console log sections to help in readability.

 
Region (root) # show regions
Name ID Position Size Port Ready? Estate
AiLand 46d2006b-4531-4f77-a2bb-f785d416ae03 6400,6400 256x256 9000 Yes AiLand
OpenVCE 2a2c51ed-7846-4536-8503-dc332c6c0804 6400,6399 256x256 9001 Yes AiLand
Edinburgh 98b848b4-64c0-4f07-a4a2-9e92b75cb106 6400,6401 256x256 9005 Yes AiLand

16:35:59 - [AGENT HANDLER]: QueryAccess returned True (). Version=0, 0.6/0.6
16:35:59 - [SCENE]: Region AiLand told of incoming root agent Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb (circuit code 1436726102, IP 77.102.240.22, viewer Firestorm-Releasex64 5.1.7.55786, teleportflags (ViaHome, ViaLogin), position <126.6773, 128.218, 25.09347>.
16:35:59 - [SCENE]: Region AiLand authenticated and authorized incoming root agent Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb (circuit code 1436726102)
16:35:59 - [CreateCaps]: new caps agent ff0a6e25-15cf-4294-9374-4ce8cdec65eb, circuit 1436726102, path c043358e-7da8-4cc9-8fa6-68581ab7a1fe, time 0
16:35:59 - [VivoxVoice]: OnRegisterCaps: agentID ff0a6e25-15cf-4294-9374-4ce8cdec65eb caps OpenSim.Framework.Capabilities.Caps
16:36:04 - [CAPS]: Received SEED caps request in AiLand for agent ff0a6e25-15cf-4294-9374-4ce8cdec65eb
16:36:04 - [SCENE]: Incoming client Ai Austin in region AiLand via regular login. Client IP verification not performed.
16:36:05 - [LLUDPSERVER]: Handling UseCircuitCode request for circuit 1436726102 to AiLand from IP 77.102.240.22:51415
16:36:05 - [SCENE]: Adding new child scene presence Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb to scene AiLand at pos <126.6773, 128.218, 25.09347>, tpflags: ViaHome, ViaLogin
16:36:05 - [LLUDPSERVER]: Client created, processing pending queue, 2 entries
16:36:05 - [LLClientView]: HandleCompleteAgentMovement
16:36:05 - [SCENE PRESENCE]: Completing movement of Ai Austin into region AiLand in position <126.6773, 128.218, 25.09347>
16:36:05 - [CompleteMovement]: Missing COF for ff0a6e25-15cf-4294-9374-4ce8cdec65eb is 01f15915-e6a3-4548-b62c-e39995c37b15
16:36:05 - [XBakes]: read 5 textures for user ff0a6e25-15cf-4294-9374-4ce8cdec65eb
16:36:05 - [ValidateBakedCache]: got bakedModule 5 cached textures
16:36:05 - [AgentPrefs]: UpdateAgentPreferences for ff0a6e25-15cf-4294-9374-4ce8cdec65eb
16:36:06 - [CompleteMovement]: end: 641ms
16:36:06 - [ENTITY TRANSFER MODULE]: Informing Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb about neighbour OpenVCE 129.215.219.74:9001 at (6400,6399)
16:36:06 - [SCENE]: Region OpenVCE told of incoming child agent Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb (circuit code 1436726102, IP 77.102.240.22, viewer Firestorm-Releasex64 5.1.7.55786, teleportflags (Default), position <126.7199, 384.1743, 26.01395>. From region OpenVCE (2a2c51ed-7846-4536-8503-dc332c6c0804) @ http://ai.vue.ed.ac.uk:9000/ [^]
16:36:06 - [SCENE]: Region OpenVCE authenticated and authorized incoming child agent Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb (circuit code 1436726102)
16:36:06 - [CreateCaps]: new caps agent ff0a6e25-15cf-4294-9374-4ce8cdec65eb, circuit 1436726102, path d7555aa4-244f-47ba-a6db-7cb93c0d3e82, time 0
16:36:06 - [VivoxVoice]: OnRegisterCaps: agentID ff0a6e25-15cf-4294-9374-4ce8cdec65eb caps OpenSim.Framework.Capabilities.Caps
16:36:06 - [OfflineIM.V2]: Retrieving stored messages for ff0a6e25-15cf-4294-9374-4ce8cdec65eb
16:36:06 - [ENTITY TRANSFER MODULE]: AiLand is sending Ai Austin EnableSimulator for neighbour region OpenVCE(loc=<1638400,1638144>,siz=<256,256>) and EstablishAgentCommunication with seed cap http://ai.vue.ed.ac.uk:9000/CAPS/d7555aa4-244f-47ba-a6db-7cb93c0d3e820000/ [^]
16:36:06 - [ENTITY TRANSFER MODULE]: Completed inform Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb about neighbour 129.215.219.74:9001
16:36:06 - [ENTITY TRANSFER MODULE]: Informing Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb about neighbour Edinburgh 129.215.219.74:9005 at (6400,6401)
16:36:06 - [SCENE]: Region Edinburgh told of incoming child agent Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb (circuit code 1436726102, IP 77.102.240.22, viewer Firestorm-Releasex64 5.1.7.55786, teleportflags (Default), position <126.7199, -127.8257, 26.01395>. From region Edinburgh (98b848b4-64c0-4f07-a4a2-9e92b75cb106) @ http://ai.vue.ed.ac.uk:9000/ [^]
16:36:06 - [SCENE]: Region Edinburgh authenticated and authorized incoming child agent Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb (circuit code 1436726102)
16:36:06 - [CreateCaps]: new caps agent ff0a6e25-15cf-4294-9374-4ce8cdec65eb, circuit 1436726102, path 40587922-206a-4278-b538-13921c6384a3, time 0
16:36:06 - [VivoxVoice]: OnRegisterCaps: agentID ff0a6e25-15cf-4294-9374-4ce8cdec65eb caps OpenSim.Framework.Capabilities.Caps
16:36:07 - [AVFACTORY]: Received texture update for Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb
16:36:07 - [UpdateBakedCache]: cache hits: 5 changed entries: 0 rebakes 0
16:36:07 - [ENTITY TRANSFER MODULE]: AiLand is sending Ai Austin EnableSimulator for neighbour region Edinburgh(loc=<1638400,1638656>,siz=<256,256>) and EstablishAgentCommunication with seed cap http://ai.vue.ed.ac.uk:9000/CAPS/40587922-206a-4278-b538-13921c6384a30000/ [^]
16:36:07 - [ENTITY TRANSFER MODULE]: Completed inform Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb about neighbour 129.215.219.74:9005
16:36:12 - [AgentPrefs]: UpdateAgentPreferences for ff0a6e25-15cf-4294-9374-4ce8cdec65eb


16:36:22 - [LAND MANAGEMENT MODULE]: Got parcelinfo request for regionHandle 7036874419405056, x/y 173/85
16:36:22 - [LAND MANAGEMENT MODULE]: got parcelinfo for parcel Edinburgh on AiLand in region 7036874419405056; sending...
16:36:24 - [HG ENTITY TRANSFER MODULE]: region Edinburgh flags: 4
16:36:24 - [ENTITY TRANSFER MODULE]: Teleporting Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb from AiLand to http://ai.vue.ed.ac.uk:9000/ [^] (http://ai.vue.ed.ac.uk:9000/ [^]) Edinburgh/<173.572, 85.33777, 25.81265>
16:36:24 - [ENTITY TRANSFER MODULE]: AiLand transfer protocol version to Edinburgh is 0.6 / 0.6
16:36:24 - [SCENE PRESENCE]: Closing child agents. Checking 3 regions in AiLand
16:36:24 - [HG ENTITY TRANSFER MODULE]: CreateAgent http://ai.vue.ed.ac.uk:9000/ [^] http://ai.vue.ed.ac.uk:9000/ [^]
16:36:24 - [SCENE]: Region Edinburgh told of incoming child agent Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb (circuit code 1436726102, IP 77.102.240.22, viewer Firestorm-Releasex64 5.1.7.55786, teleportflags (ViaLocation), position <173.572, 85.33777, 25.81265>. From region AiLand (46d2006b-4531-4f77-a2bb-f785d416ae03) @ http://ai.vue.ed.ac.uk:8002/ [^]
16:36:24 - [SCENE]: Region Edinburgh authenticated and authorized incoming child agent Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb (circuit code 1436726102)
16:36:24 - [ENTITY TRANSFER MODULE]: Sending new CAPS seed url http://ai.vue.ed.ac.uk:9000/CAPS/40587922-206a-4278-b538-13921c6384a30000/ [^] from AiLand to Ai Austin
16:36:24 - [SCENE]: Incoming child agent update for ff0a6e25-15cf-4294-9374-4ce8cdec65eb in Edinburgh
16:36:55 - [SCENE PRESENCE]: Did not find presence with id ff0a6e25-15cf-4294-9374-4ce8cdec65eb in Edinburgh before timeout
16:36:55 - [ENTITY TRANSFER MODULE]: UpdateAgent failed on teleport of Ai Austin to Edinburgh. Keeping avatar in AiLand
16:36:55 - [SCENE]: Called CloseClient() with agent ID ff0a6e25-15cf-4294-9374-4ce8cdec65eb but no such presence is in Edinburgh
16:37:06 - [LLUDPSERVER]: Handling UseCircuitCode request for circuit 1436726102 to OpenVCE from IP 77.102.240.22:51415
16:37:06 - [LLUDPSERVER]: Handling UseCircuitCode request for circuit 1436726102 to Edinburgh from IP 77.102.240.22:51415
16:37:06 - [CAPS]: Received SEED caps request in OpenVCE for agent ff0a6e25-15cf-4294-9374-4ce8cdec65eb
16:37:06 - [SCENE]: Adding new child scene presence Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb to scene OpenVCE at pos <126.7199, 384.1743, 26.01395>, tpflags: Default
16:37:06 - [SCENE]: Adding new child scene presence Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb to scene Edinburgh at pos <173.572, 85.33777, 25.81265>, tpflags: ViaLocation
16:37:06 - [CAPS]: Received SEED caps request in Edinburgh for agent ff0a6e25-15cf-4294-9374-4ce8cdec65eb
16:37:06 - [CAPS]: Received SEED caps request in Edinburgh for agent ff0a6e25-15cf-4294-9374-4ce8cdec65eb
16:37:06 - [CAPS]: Received SEED caps request in Edinburgh for agent ff0a6e25-15cf-4294-9374-4ce8cdec65eb
16:37:06 - [LLUDPSERVER]: Client created, processing pending queue, 2 entries
16:37:06 - [LLUDPSERVER]: Client created, processing pending queue, 3 entries
16:37:06 - [LLClientView]: HandleCompleteAgentMovement
16:37:06 - [SCENE PRESENCE]: Completing movement of Ai Austin into region Edinburgh in position <173.572, 85.33777, 25.81265>
16:37:16 - [SCENE PRESENCE]: Update agent Ai Austin at Edinburgh did not receive agent update
Region (root) #

Region (root) # show users

Agents connected: 1

Firstname Lastname Agent ID Root/Child Region Position
Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb Root AiLand <124.8462, 132.4568, 25.81265>


16:50:17 - [LAND MANAGEMENT MODULE]: Got parcelinfo request for regionHandle 7036874419405056, x/y 177/98
16:50:17 - [LAND MANAGEMENT MODULE]: got parcelinfo for parcel Edinburgh on AiLand in region 7036874419405056; sending...
16:50:18 - [HG ENTITY TRANSFER MODULE]: region Edinburgh flags: 4
16:50:18 - [ENTITY TRANSFER MODULE]: Teleporting Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb from AiLand to http://ai.vue.ed.ac.uk:9000/ [^] (http://ai.vue.ed.ac.uk:9000/ [^]) Edinburgh/<177.572, 98.33777, 25.81265>
16:50:18 - [ENTITY TRANSFER MODULE]: AiLand transfer protocol version to Edinburgh is 0.6 / 0.6
16:50:18 - [SCENE PRESENCE]: Closing child agents. Checking 3 regions in AiLand
16:50:18 - [HG ENTITY TRANSFER MODULE]: CreateAgent http://ai.vue.ed.ac.uk:9000/ [^] http://ai.vue.ed.ac.uk:9000/ [^]
16:50:18 - [SCENE]: Region Edinburgh told of incoming child agent Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb (circuit code 1436726102, IP 77.102.240.22, viewer Firestorm-Releasex64 5.1.7.55786, teleportflags (ViaLocation), position <177.572, 98.33777, 25.81265>. From region AiLand (46d2006b-4531-4f77-a2bb-f785d416ae03) @ http://ai.vue.ed.ac.uk:8002/ [^]
16:50:18 - [SCENE]: Reusing existing child scene presence for Ai Austin, state Running in Edinburgh
16:50:18 - [SCENE]: Adjusting known seeds for existing agent ff0a6e25-15cf-4294-9374-4ce8cdec65eb in Edinburgh
16:50:18 - [ENTITY TRANSFER MODULE]: Sending new CAPS seed url http://ai.vue.ed.ac.uk:9000/CAPS/40587922-206a-4278-b538-13921c6384a30000/ [^] from AiLand to Ai Austin
16:50:18 - [SCENE]: Incoming child agent update for ff0a6e25-15cf-4294-9374-4ce8cdec65eb in Edinburgh
16:50:45 - [SCENE]: Found presence Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb unexpectedly still child in Edinburgh
16:50:45 - [ENTITY TRANSFER MODULE]: UpdateAgent failed on teleport of Ai Austin to Edinburgh. Keeping avatar in AiLand
16:50:45 - [CLIENT]: Close has been called for Ai Austin attached to scene Edinburgh
16:50:45 - [JobEngine]: Stopping AsyncInUDP-ff0a6e25-15cf-4294-9374-4ce8cdec65eb
16:50:45 - [SCENE]: Removing child agent Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb from Edinburgh
16:50:45 - [CAPS]: Remove caps for agent ff0a6e25-15cf-4294-9374-4ce8cdec65eb in region Edinburgh
16:50:45 - [Scene]: The avatar has left the building
16:50:47 - [LLUDPSERVER]: Handling UseCircuitCode request for circuit 1436726102 to Edinburgh from IP 77.102.240.22:51415
16:50:47 - [LLUDPSERVER]: Ignoring connection request for ff0a6e25-15cf-4294-9374-4ce8cdec65eb to Edinburgh with unknown circuit code 1436726102 from IP 77.102.240.22:51415


16:50:55 - [LLUDPSERVER]: Handling UseCircuitCode request for circuit 1436726102 to Edinburgh from IP 77.102.240.22:51415
16:50:55 - [LLUDPSERVER]: Ignoring connection request for ff0a6e25-15cf-4294-9374-4ce8cdec65eb to Edinburgh with unknown circuit code 1436726102 from IP 77.102.240.22:51415
16:50:58 - [LAND MANAGEMENT MODULE]: Got parcelinfo request for regionHandle 7036874419405056, x/y 152/112
16:50:58 - [LAND MANAGEMENT MODULE]: got parcelinfo for parcel Edinburgh on AiLand in region 7036874419405056; sending...
16:51:00 - [HG ENTITY TRANSFER MODULE]: region Edinburgh flags: 4
16:51:00 - [ENTITY TRANSFER MODULE]: Teleporting Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb from AiLand to http://ai.vue.ed.ac.uk:9000/ [^] (http://ai.vue.ed.ac.uk:9000/ [^]) Edinburgh/<152.572, 112.3378, 25.81265>
16:51:00 - [ENTITY TRANSFER MODULE]: AiLand transfer protocol version to Edinburgh is 0.6 / 0.6
16:51:00 - [SCENE PRESENCE]: Closing child agents. Checking 3 regions in AiLand
16:51:00 - [HG ENTITY TRANSFER MODULE]: CreateAgent http://ai.vue.ed.ac.uk:9000/ [^] http://ai.vue.ed.ac.uk:9000/ [^]
16:51:00 - [SCENE]: Region Edinburgh told of incoming child agent Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb (circuit code 1436726102, IP 77.102.240.22, viewer Firestorm-Releasex64 5.1.7.55786, teleportflags (ViaLocation), position <152.572, 112.3378, 25.81265>. From region AiLand (46d2006b-4531-4f77-a2bb-f785d416ae03) @ http://ai.vue.ed.ac.uk:8002/ [^]
16:51:00 - [SCENE]: Region Edinburgh authenticated and authorized incoming child agent Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb (circuit code 1436726102)
16:51:00 - [CreateCaps]: new caps agent ff0a6e25-15cf-4294-9374-4ce8cdec65eb, circuit 1436726102, path 40587922-206a-4278-b538-13921c6384a3, time 0
16:51:00 - [VivoxVoice]: OnRegisterCaps: agentID ff0a6e25-15cf-4294-9374-4ce8cdec65eb caps OpenSim.Framework.Capabilities.Caps
16:51:00 - [ENTITY TRANSFER MODULE]: Sending new CAPS seed url http://ai.vue.ed.ac.uk:9000/CAPS/40587922-206a-4278-b538-13921c6384a30000/ [^] from AiLand to Ai Austin
16:51:00 - [SCENE]: Incoming child agent update for ff0a6e25-15cf-4294-9374-4ce8cdec65eb in Edinburgh
16:51:00 - [LLUDPSERVER]: Handling UseCircuitCode request for circuit 1436726102 to Edinburgh from IP 77.102.240.22:51415
16:51:00 - [SCENE]: Adding new child scene presence Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb to scene Edinburgh at pos <152.572, 112.3378, 25.81265>, tpflags: ViaLocation
16:51:00 - [CAPS]: Received SEED caps request in Edinburgh for agent ff0a6e25-15cf-4294-9374-4ce8cdec65eb
16:51:00 - [LLUDPSERVER]: Client created, processing pending queue, 3 entries
16:51:00 - [LLClientView]: HandleCompleteAgentMovement
16:51:00 - [SCENE PRESENCE]: Completing movement of Ai Austin into region Edinburgh in position <152.572, 112.3378, 25.81265>
16:51:00 - [CompleteMovement]: Missing COF for ff0a6e25-15cf-4294-9374-4ce8cdec65eb is 01f15915-e6a3-4548-b62c-e39995c37b15
16:51:00 - [SCENE PRESENCE]: Closing 1 child agents
16:51:00 - [SCENE COMMUNICATION SERVICE]: Sending close agent ID ff0a6e25-15cf-4294-9374-4ce8cdec65eb to OpenVCE
16:51:00 - [CLIENT]: Close has been called for Ai Austin attached to scene OpenVCE
16:51:00 - [JobEngine]: Stopping AsyncInUDP-ff0a6e25-15cf-4294-9374-4ce8cdec65eb
16:51:00 - [SCENE PRESENCE]: Making Ai Austin a child agent in AiLand from root region 7036874419405056
16:51:00 - [SCENE]: Removing child agent Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb from OpenVCE
16:51:00 - [CAPS]: Remove caps for agent ff0a6e25-15cf-4294-9374-4ce8cdec65eb in region OpenVCE
16:51:00 - [Scene]: The avatar has left the building
16:51:01 - [CompleteMovement]: end: 547ms
16:51:01 - [AVFACTORY]: Received texture update for Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb
16:51:01 - [UpdateBakedCache]: cache hits: 5 changed entries: 0 rebakes 0
16:51:01 - [ENTITY TRANSFER MODULE]: Informing Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb about neighbour OpenVCE 129.215.219.74:9001 at (6400,6399)
16:51:01 - [SCENE]: Region OpenVCE told of incoming child agent Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb (circuit code 1436726102, IP 77.102.240.22, viewer Firestorm-Releasex64 5.1.7.55786, teleportflags (Default), position <128.746, 640.012, 32.05402>. From region OpenVCE (2a2c51ed-7846-4536-8503-dc332c6c0804) @ http://ai.vue.ed.ac.uk:9000/ [^]
16:51:01 - [SCENE]: Region OpenVCE authenticated and authorized incoming child agent Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb (circuit code 1436726102)
16:51:01 - [CreateCaps]: new caps agent ff0a6e25-15cf-4294-9374-4ce8cdec65eb, circuit 1436726102, path cefe5e63-9489-4fc5-ad2e-4273503836a0, time 0
16:51:01 - [VivoxVoice]: OnRegisterCaps: agentID ff0a6e25-15cf-4294-9374-4ce8cdec65eb caps OpenSim.Framework.Capabilities.Caps
16:51:01 - [ENTITY TRANSFER MODULE]: Edinburgh is sending Ai Austin EnableSimulator for neighbour region OpenVCE(loc=<1638400,1638144>,siz=<256,256>) and EstablishAgentCommunication with seed cap http://ai.vue.ed.ac.uk:9000/CAPS/cefe5e63-9489-4fc5-ad2e-4273503836a00000/ [^]
16:51:01 - [ENTITY TRANSFER MODULE]: Completed inform Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb about neighbour 129.215.219.74:9001
16:51:05 - [LLClientView]: HandleCompleteAgentMovement
16:51:05 - [SCENE PRESENCE]: Completing movement of Ai Austin into region Edinburgh in position <128.746, 128.012, 32.05402>
16:51:15 - [SCENE PRESENCE]: Update agent Ai Austin at Edinburgh did not receive agent update
Region (root) #

Region (root) # show users

Agents connected: 1

Firstname Lastname Agent ID Root/Child Region Position
Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb Root Edinburgh <132.5465, 130.2577, 32.08667>

(0033281)
aiaustin (developer)
2018-10-28 10:00
edited on: 2018-10-28 10:01

By the way, "show users" in OpenSim.exe only shows the avatar as being in the root 256x256 region it is on (AiLand).. not the two adjacent (256x256) regions (Edinburgh to North and OpenVCE to South) that the log indicates it should be a child in. Viewer is set for draw distances of 512m and OpenSim.ini settings accordingly. Odd? Or is the Root/Child column misleading and we only show avatars in the root regions they are on?

Region (root) # show users

Agents connected: 0

Firstname Lastname Agent ID Root/Child Region Position

16:59:42 - [AGENT HANDLER]: QueryAccess returned True (). Version=0, 0.6/0.6
16:59:42 - [SCENE]: Region AiLand told of incoming root agent Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb (circuit code 1683854160, IP 77.102.240.22, viewer Firestorm-Releasex64 5.1.7.55786, teleportflags (ViaHome, ViaLogin), position <126.6773, 128.218, 25.09347>.
16:59:42 - [SCENE]: Region AiLand authenticated and authorized incoming root agent Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb (circuit code 1683854160)
16:59:42 - [CreateCaps]: new caps agent ff0a6e25-15cf-4294-9374-4ce8cdec65eb, circuit 1683854160, path 850c8fe0-1a51-4d7a-b840-0fcf48ddb957, time 0
16:59:42 - [VivoxVoice]: OnRegisterCaps: agentID ff0a6e25-15cf-4294-9374-4ce8cdec65eb caps OpenSim.Framework.Capabilities.Caps
16:59:45 - [CAPS]: Received SEED caps request in AiLand for agent ff0a6e25-15cf-4294-9374-4ce8cdec65eb
16:59:45 - [SCENE]: Incoming client Ai Austin in region AiLand via regular login. Client IP verification not performed.
16:59:46 - [LLUDPSERVER]: Handling UseCircuitCode request for circuit 1683854160 to AiLand from IP 77.102.240.22:60606
16:59:46 - [SCENE]: Adding new child scene presence Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb to scene AiLand at pos <126.6773, 128.218, 25.09347>, tpflags: ViaHome, ViaLogin
16:59:46 - [LLUDPSERVER]: Client created, processing pending queue, 2 entries
16:59:46 - [LLClientView]: HandleCompleteAgentMovement
16:59:46 - [SCENE PRESENCE]: Completing movement of Ai Austin into region AiLand in position <126.6773, 128.218, 25.09347>
16:59:46 - [CompleteMovement]: Missing COF for ff0a6e25-15cf-4294-9374-4ce8cdec65eb is 01f15915-e6a3-4548-b62c-e39995c37b15
16:59:46 - [XBakes]: read 5 textures for user ff0a6e25-15cf-4294-9374-4ce8cdec65eb
16:59:46 - [ValidateBakedCache]: got bakedModule 5 cached textures
16:59:46 - [AgentPrefs]: UpdateAgentPreferences for ff0a6e25-15cf-4294-9374-4ce8cdec65eb
16:59:46 - [CompleteMovement]: end: 563ms
16:59:47 - [ENTITY TRANSFER MODULE]: Informing Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb about neighbour OpenVCE 129.215.219.74:9001 at (6400,6399)
16:59:47 - [SCENE]: Region OpenVCE told of incoming child agent Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb (circuit code 1683854160, IP 77.102.240.22, viewer Firestorm-Releasex64 5.1.7.55786, teleportflags (Default), position <126.7198, 384.1743, 26.0139>. From region OpenVCE (2a2c51ed-7846-4536-8503-dc332c6c0804) @ http://ai.vue.ed.ac.uk:9000/ [^]
16:59:47 - [SCENE]: Region OpenVCE authenticated and authorized incoming child agent Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb (circuit code 1683854160)
16:59:47 - [CreateCaps]: new caps agent ff0a6e25-15cf-4294-9374-4ce8cdec65eb, circuit 1683854160, path 38222751-5852-41ef-926a-96673eaa08e2, time 0
16:59:47 - [VivoxVoice]: OnRegisterCaps: agentID ff0a6e25-15cf-4294-9374-4ce8cdec65eb caps OpenSim.Framework.Capabilities.Caps
16:59:47 - [EVENTQUEUE]: Found Existing UUID!
16:59:47 - [OfflineIM.V2]: Retrieving stored messages for ff0a6e25-15cf-4294-9374-4ce8cdec65eb
16:59:47 - [AVFACTORY]: Received texture update for Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb
16:59:47 - [UpdateBakedCache]: cache hits: 5 changed entries: 0 rebakes 0
16:59:47 - [ENTITY TRANSFER MODULE]: AiLand is sending Ai Austin EnableSimulator for neighbour region OpenVCE(loc=<1638400,1638144>,siz=<256,256>) and EstablishAgentCommunication with seed cap http://ai.vue.ed.ac.uk:9000/CAPS/38222751-5852-41ef-926a-96673eaa08e20000/ [^]
16:59:47 - [ENTITY TRANSFER MODULE]: Completed inform Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb about neighbour 129.215.219.74:9001
16:59:47 - [ENTITY TRANSFER MODULE]: Informing Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb about neighbour Edinburgh 129.215.219.74:9005 at (6400,6401)
16:59:47 - [SCENE]: Region Edinburgh told of incoming child agent Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb (circuit code 1683854160, IP 77.102.240.22, viewer Firestorm-Releasex64 5.1.7.55786, teleportflags (Default), position <126.7198, -127.8257, 26.0139>. From region Edinburgh (98b848b4-64c0-4f07-a4a2-9e92b75cb106) @ http://ai.vue.ed.ac.uk:9000/ [^]
16:59:47 - [SCENE]: Region Edinburgh authenticated and authorized incoming child agent Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb (circuit code 1683854160)
16:59:47 - [CreateCaps]: new caps agent ff0a6e25-15cf-4294-9374-4ce8cdec65eb, circuit 1683854160, path 71837c81-bbe0-481a-8819-bcfd7462a584, time 0
16:59:47 - [VivoxVoice]: OnRegisterCaps: agentID ff0a6e25-15cf-4294-9374-4ce8cdec65eb caps OpenSim.Framework.Capabilities.Caps
16:59:48 - [ENTITY TRANSFER MODULE]: AiLand is sending Ai Austin EnableSimulator for neighbour region Edinburgh(loc=<1638400,1638656>,siz=<256,256>) and EstablishAgentCommunication with seed cap http://ai.vue.ed.ac.uk:9000/CAPS/71837c81-bbe0-481a-8819-bcfd7462a5840000/ [^]
16:59:48 - [ENTITY TRANSFER MODULE]: Completed inform Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb about neighbour 129.215.219.74:9005
16:59:52 - [AgentPrefs]: UpdateAgentPreferences for ff0a6e25-15cf-4294-9374-4ce8cdec65eb
Region (root) #
Region (root) #
Region (root) # show users

Agents connected: 1

Firstname Lastname Agent ID Root/Child Region Position
Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb Root AiLand <126.7198, 128.1743, 26.0139>

(0033282)
aiaustin (developer)
2018-10-28 10:05
edited on: 2018-10-28 10:13

On a few more tests on setup described above in 10 teleport attempts over two logins I only managed to teleport once. That is about 3 times worse than before. On 10th teleport attempt Firestorm viewer crashed - at the time OpenSim.exe log was showing its last entry as...

17:06:50 - [SCENE PRESENCE]: Update agent Ai Austin at AiLand did not receive agent update

OpenSim.exe log after viewer crash showed started up after about 38 seconds...

17:07:28 - [LLUDPSERVER]: No packets received from child agent of Ai Austin for 60000ms in OpenVCE. Disconnecting.
17:07:28 - [CLIENT]: Close has been called for Ai Austin attached to scene OpenVCE
17:07:28 - [JobEngine]: Stopping AsyncInUDP-ff0a6e25-15cf-4294-9374-4ce8cdec65eb
17:07:28 - [SCENE]: Removing child agent Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb from OpenVCE
17:07:28 - [CAPS]: Remove caps for agent ff0a6e25-15cf-4294-9374-4ce8cdec65eb in region OpenVCE
17:07:28 - [Scene]: The avatar has left the building
17:07:29 - [LLUDPSERVER]: No packets received from child agent of Ai Austin for 60000ms in Edinburgh. Disconnecting.
17:07:29 - [CLIENT]: Close has been called for Ai Austin attached to scene Edinburgh
17:07:29 - [JobEngine]: Stopping AsyncInUDP-ff0a6e25-15cf-4294-9374-4ce8cdec65eb
17:07:29 - [SCENE]: Removing child agent Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb from Edinburgh
17:07:29 - [CAPS]: Remove caps for agent ff0a6e25-15cf-4294-9374-4ce8cdec65eb in region Edinburgh
17:07:29 - [HG MAP]: Resetting 3 blocks
17:07:29 - [Scene]: The avatar has left the building
17:07:29 - [LLUDPSERVER]: No packets received from root agent of Ai Austin for 60000ms in AiLand. Disconnecting.
17:07:29 - [CLIENT]: Close has been called for Ai Austin attached to scene AiLand
17:07:30 - [JobEngine]: Stopping AsyncInUDP-ff0a6e25-15cf-4294-9374-4ce8cdec65eb
17:07:30 - [SCENE]: Removing root agent Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb from AiLand
17:07:30 - [CAPS]: Remove caps for agent ff0a6e25-15cf-4294-9374-4ce8cdec65eb in region AiLand
17:07:30 - [SCENE COMMUNICATION SERVICE]: Sending close agent ID ff0a6e25-15cf-4294-9374-4ce8cdec65eb to Edinburgh
17:07:30 - [SCENE]: Request to close agent ff0a6e25-15cf-4294-9374-4ce8cdec65eb but no such agent in scene Edinburgh. May have been closed previously.
17:07:30 - [SCENE COMMUNICATION SERVICE]: Sending close agent ID ff0a6e25-15cf-4294-9374-4ce8cdec65eb to OpenVCE
17:07:30 - [Scene]: The avatar has left the building
17:07:30 - [SCENE]: Request to close agent ff0a6e25-15cf-4294-9374-4ce8cdec65eb but no such agent in scene OpenVCE. May have been closed previously.
Region (root) #

(0033283)
UbitUmarov (administrator)
2018-10-28 10:11

in that case seems you did the tp with the login still going on
(0033284)
aiaustin (developer)
2018-10-28 10:14

Are you referring to comment (0033282) @Ubit? The viewer crash? If so the crash was a good 2 minutes after login.
(0033285)
UbitUmarov (administrator)
2018-10-28 10:25

to see child agents do "show users full"
(0033286)
UbitUmarov (administrator)
2018-10-28 10:49

I was referring to 33280

but valid on all... tp/login does go on for a while since we do see a region
any try during that period is most likely a fail.
this is not good, but a old issue.

in that log (and if im reading right):
16:37:06 - [LLUDPSERVER]: Handling UseCircuitCode request for circuit 1436726102 to OpenVCE from IP 77.102.240.22:51415
16:37:06 - [LLUDPSERVER]: Handling UseCircuitCode request for circuit 1436726102 to Edinburgh from IP 77.102.240.22:51415

are still part of the viewer side login at AiLand (making to nearby regions visible)
and it happened long after you tested the tp and it failed.
(0033287)
aiaustin (developer)
2018-10-28 11:20
edited on: 2018-10-28 14:50

Okay... note that I did give things 2 minutes after server startup before I even started the viiewer and LONG after LOGIN ENABLED was shown on all three regions that I had up on that server.

But I will try to do some more systematic testing tomorrow if you think the changes in commit 507 should have made things better, as it seemed to me it made things considerably worse (which itself might be useful if its consistent).

(0033288)
paela argus (reporter)
2018-10-28 22:18
edited on: 2018-10-28 22:19

Is that possible to start the firestorm viewer with console and see what happen in tp with the console Firestorm please, i think is more a problem with firestorm of OpenSimulator.
With my new network none of Tp go dead before with old network a lots of times dead tp without any reasons

(0033289)
mewtwo0641 (reporter)
2018-10-28 22:23

@paela argus - It isn't just Firestorm that I can tell; I have this happen frequently on Singularity as well.
(0033290)
aiaustin (developer)
2018-10-29 02:45
edited on: 2018-10-29 02:48

@paela Argus.. I have the Firestorm console running now with keyboard shortcut "ctrl+shift+4". I am seeing some potentially interesting HTTP policy issues (HTTP 502 errors with Bad gateway) and HTT pipeline out of sync errors. Attached snapshot shows some.. but they are coming on a stead state login every few seconds in the Firestorm Console.

See attached image 2018-10-29-Firestorm-Console-OpenSim-507-TP-Issue-1.png and 2018-10-29-Firestorm-Console-OpenSim-507-TP-Issue-1.png

About also to try other viewers to (re-) confirm the issue is across several. It definitely happens on Ctrl-Alt-Studio - which is Firestorm based anyway.. but on a very old version. I will clear all logs and start afresh to see what I can find. I can see now where to get text of logs rather than just screenshotting them.

P.S. is there a way to capture the Firestorm console log to a file?

(0033291)
aiaustin (developer)
2018-10-29 03:41
edited on: 2018-10-29 04:00

https://wiki.phoenixviewer.com/keyboard_shortcuts [^]

I have simplified my test setup so I am running all on one University subnet with one viewer machine (Ailsa) and one server (Coll). Coll (129.215.219.74) server running MySQL 5.7, Robust (port 8002) and OpenSim (http listener port 9000) . Running only two adjacent 256x256 regions, AiLand (129.215.219.74 on port 9000) and Edinburgh (no port 9005). We have no special firewalls when running on our own network and I will test with Windows Defender on and off. Both systems are Windows 10 winver 1803, Intel Xeon E5-1650 v4 @ 3.60GHz processor, 32GB memory, SSD drives. Avatar is basic body parts (and basic system shirt and pants (i.e. Ruth). No mesh, no attachments and no HUDs. Viewer with basic settings and lowish 128m draw distance.

Reports follow with this environment as context.

(0033292)
aiaustin (developer)
2018-10-29 03:53
edited on: 2018-10-29 04:17

Singularity Viewer 64 bit 1.8.7 (6861) Windows console logs follow. If someone can advise what I should look out for I can home in on that. But I do see some messages that ought to have an expert eyeball on them - even when the avatar is simply staying idle on one region. The textures are loading VERY VERY slowly on an otherwise idle network even after 20 minutes of waiting.

R.O.B.U.S.T.# show regions
Name ID Position Size Flags
AiLand 46d2006b-4531-4f77-a2bb-f785d416ae03 6400,6400 256x256 DefaultRegion, FallbackRegion, RegionOnline
Edinburgh 98b848b4-64c0-4f07-a4a2-9e92b75cb106 6400,6401 256x256 RegionOnline

Region (root) # show users full

Agents connected: 2

Firstname Lastname Agent ID Root/Child Region Position
Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb Root AiLand <123.7597, 1.253539, 0.4065968>
Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb Child Edinburgh <123.599, -254.8722, 22.57549>


Here are a couple of possibly relevant messages....

WARNING: LLTextureFetchWorker::doWork: trying to seek a non-default texture on the sim. Bad!

WARNING: BaseCapabilitiesCompleteTracker::httpSuccess: Sim sent duplicate base caps that differ in size from what we initially received - most likely content. mCapabilities == 33 mSecondCapabilitiesTracker == 32

WARNING: `anonymous-namespace'::LLEventPollResponder::httpFailure: Unexpected HTTP error. status: 498, reason:

INFO: AICurlPrivate::curlthread::HTTPTimeout::print_diagnostics: The socket was most likely already connected (or you connected to a proxy with a connect time of under (tilde)10 ms).

AICurlPrivate::curlthread::HTTPTimeout::print_diagnostics: The SSL/TLS handshake never occurred according to the timings!


Longer extract from Singularity.log with areas where I am not sure what might be a problem. One (successful) teleport was done in this period... its by no means the complete log of course... gaps are put in where lots of similar messages appears like the ones included here as examples...


2018-10-29T10:18:10Z INFO: LLNotificationChannelBase::updateItem: Inserting FirstTeleport
2018-10-29T10:18:11Z INFO: BGFolderHttpHandler::httpFailure: BGFolderHttpHandler::error 498:
2018-10-29T10:18:11Z WARNING: `anonymous-namespace'::LLEventPollResponder::httpFailure: Unexpected HTTP error. status: 498, reason:
2018-10-29T10:18:12Z WARNING: HTTPGetResponder::completedRaw: Worker not found: 769003e5-0177-4506-83f0-919af3498654
2018-10-29T10:18:12Z WARNING: HTTPGetResponder::completedRaw: Worker not found: 52939707-1ffd-4022-bc74-

2018-10-29T10:17:12Z INFO: LLVOAvatar::idleUpdateLoadingEffect: Avatar 'Ai Austin' textured self isFullyLoaded, mFirstFullyVisible
2018-10-29T10:17:13Z WARNING: LLTransferManager::processTransferInfo: 3175d192-b940-f52d-4332-193e904074da: Non-ok status, cleaning up
2018-10-29T10:17:13Z WARNING: LLTransferTargetVFile::completionCallback: Aborting vfile transfer for 1e506d0c-4811-bdf3-5ec7-d624284c9040
2018-10-29T10:17:13Z INFO: LLAudioEngine::assetCallback: Boom, error in audio file transfer: Asset request: asset not found in database (-4)
2018-10-29T10:17:14Z WARNING: LLTemplateMessageReader::decodeData: Message from 129.215.219.74:9005 with no handler function received: AgentWearablesUpdate
2018-10-29T10:17:14Z WARNING: LLTemplateMessageReader::decodeData: Message from 129.215.219.74:9005 with no handler function received: AgentWearablesUpdate


2018-10-29T10:18:12Z WARNING: HTTPGetResponder::completedRaw: Worker not found: 3f2ff8ed-00b8-469c-9249-2ccce24f0b53
2018-10-29T10:18:14Z WARNING: LLFunctorRegistry<class boost::function<void __cdecl(class LLSD const &,class LLSD const &)> >::getFunctor: tried to find 'FirstTeleport' in LLFunctorRegistry, but it wasn't there.


2018-10-29T10:19:12Z WARNING: LLViewerTextureList::getImage: Requested texture bb5f92db-dd85-4ab6-b731-38ebc5310f9c already exists with a different target host, requested: 129.215.219.74:9000 current: 129.215.219.74:9005
2018-10-29T10:19:12Z WARNING: LLViewerTextureList::getImage: FTType mismatch: requested 1 image has 2
2018-10-29T10:19:12Z WARNING: LLViewerTextureList::getImage: Requested texture 7d4e18de-cb88-44de-9338-ade9c82fa4b1 already exists with a different target host, requested: 129.215.219.74:9000 current: 129.215.219.74:9005

2018-10-29T10:19:13Z WARNING: BaseCapabilitiesCompleteTracker::httpSuccess: Sim sent duplicate base caps that differ in size from what we initially received - most likely content. mCapabilities == 33 mSecondCapabilitiesTracker == 32
2018-10-29T10:19:13Z WARNING: BaseCapabilitiesCompleteTracker::httpSuccess: Initial Base capabilities:

2018-10-29T10:22:21Z INFO: LLVOAvatar::onBakedTextureMasksLoaded: unexpected image id: bb5f92db-dd85-4ab6-b731-38ebc5310f9c
2018-10-29T10:22:21Z INFO: LLVOAvatar::onBakedTextureMasksLoaded: unexpected image id: bb5f92db-dd85-4ab6-b731-38ebc5310f9c

2018-10-29T10:24:27Z WARNING: LLTextureFetchWorker::doWork: trying to seek a non-default texture on the sim. Bad!

2018-10-29T10:36:30Z WARNING: AICurlPrivate::curlthread::HTTPTimeout::print_diagnostics: Request to "ai.vue.ed.ac.uk:9000" timed out for HTTPGetResponder
2018-10-29T10:36:30Z INFO: AICurlPrivate::curlthread::HTTPTimeout::print_diagnostics: Effective URL: "http://ai.vue.ed.ac.uk:9000/CAPS/aacd00ee-4d6f-46f6-a5e7-7a54c452697d//?texture_id=feee554b-6684-4417-bd0e-1753a1fb25f3". [^]
2018-10-29T10:36:30Z INFO: AICurlPrivate::curlthread::HTTPTimeout::print_diagnostics: Hostname seems to have been still in the DNS cache.
2018-10-29T10:36:30Z INFO: AICurlPrivate::curlthread::HTTPTimeout::print_diagnostics: The socket was most likely already connected (or you connected to a proxy with a connect time of under 0000006:0000010 ms).
2018-10-29T10:36:30Z WARNING: AICurlPrivate::curlthread::HTTPTimeout::print_diagnostics: The SSL/TLS handshake never occurred according to the timings!
2018-10-29T10:36:30Z WARNING: HTTPGetResponder::completedRaw: CURL GET FAILED, status:497 reason: Timeout was reached
2018-10-29T10:36:30Z WARNING: LLTextureFetchWorker::doWork: No response from server (HTTP_INTERNAL_ERROR_CURL_TIMEOUT): http://ai.vue.ed.ac.uk:9000/CAPS/aacd00ee-4d6f-46f6-a5e7-7a54c452697d//?texture_id=feee554b-6684-4417-bd0e-1753a1fb25f3 [^]
2018-10-29T10:36:30Z WARNING: SGHostBlackList::add: Requested adding to blacklist: http://ai.vue.ed.ac.uk:9000/CAPS/aacd00ee-4d6f-46f6-a5e7-7a54c452697d//?texture_id=feee554b-6684-4417-bd0e-1753a1fb25f3 [^]

(0033295)
aiaustin (developer)
2018-10-29 05:08
edited on: 2018-10-29 05:13

Now with Firestorm viewer... server has been running for a couple of hours, so all settled down. Avatar remember is now simple Ruth. Logged in and made sure inventory load and all textures on initial region are loaded (AiLand) and then attempt TP to Edinburgh (adjacent region on same server).. and teleport fails... console log indicates following...

2018-10-29T12:03:47Z INFO: #Teleport; newview/llagent.cpp(5619) : LLTeleportRequestViaLocation::LLTeleportRequestViaLocation: LLTeleportRequestViaLocation created
2018-10-29T12:03:47Z INFO: #Telport; newview/llagent.cpp(4594) : LLAgent::startTeleportRequest: Agent handling start teleport request.
2018-10-29T12:03:47Z INFO: #Teleport; newview/llagent.cpp(5635) : LLTeleportRequestViaLocation::startTeleport: LLTeleportRequestViaLocation::startTeleport
2018-10-29T12:03:47Z INFO: #Teleport; newview/llagent.cpp(4447) : LLAgent::teleportCore: In teleport core!
2018-10-29T12:03:47Z INFO: llui/llfloater.cpp(756) : LLFloater::closeFloater: Closing floater worldmap
2018-10-29T12:03:47Z INFO: newview/llviewermedia.cpp(2587) : LLViewerMediaImpl::navigateInternal: media id= 99f5f12f-bc69-14ad-e356-d9211b50ce77 url=about:blank, mime_type=
2018-10-29T12:03:47Z INFO: newview/llviewermedia.cpp(408) : LLViewerMedia::getCurrentUserAgent: SecondLife/5.1.7.55786 (Firestorm-Releasex64; firestorm skin)
2018-10-29T12:03:47Z INFO: newview/llviewermedia.cpp(408) : LLViewerMedia::getCurrentUserAgent: SecondLife/5.1.7.55786 (Firestorm-Releasex64; firestorm skin)
2018-10-29T12:03:47Z INFO: newview/llviewermedia.cpp(1965) : LLViewerMediaImpl::loadURI: Asking media source to load URI: about:blank
2018-10-29T12:03:47Z INFO: newview/llmediactrl.cpp(468) : LLMediaCtrl::onVisibilityChange: visibility changed to false
2018-10-29T12:03:47Z INFO: #; newview/llagent.cpp(4705) : LLAgent::teleportRequest: TeleportLocationRequest: '7036874419405056':{ 161.462204, 57.323685, 25.741970 }
2018-10-29T12:03:47Z INFO: #LLProcess; llcommon/llprocess.cpp(697) : LLProcess::LLProcess: SLPlugin.exe (13068): launched cd "C:\Program Files\FirestormOS-Releasex64\llplugin": "C:\Program Files\FirestormOS-Releasex64\SLPlugin.exe" 56908
2018-10-29T12:03:47Z INFO: #Plugin; llplugin/llpluginprocessparent.cpp(1021) : LLPluginProcessParent::receiveMessage: plugin version string: CEF plugin 1.1.412
2018-10-29T12:03:47Z INFO: #Plugin; llplugin/llpluginprocessparent.cpp(1030) : LLPluginProcessParent::receiveMessage: message class: base -> version: 1.0
2018-10-29T12:03:47Z INFO: #Plugin; llplugin/llpluginprocessparent.cpp(1030) : LLPluginProcessParent::receiveMessage: message class: media -> version: 1.0
2018-10-29T12:03:47Z INFO: #Plugin; llplugin/llpluginprocessparent.cpp(1030) : LLPluginProcessParent::receiveMessage: message class: media_browser -> version: 1.0
2018-10-29T12:03:48Z INFO: newview/llviewerdisplay.cpp(237) : display_stats: FPS: 197.40
2018-10-29T12:03:58Z INFO: newview/llviewerdisplay.cpp(237) : display_stats: FPS: 195.30
2018-10-29T12:04:02Z INFO: #Mesh; newview/llmeshrepository.cpp(5149) : LLMeshRepository::metricsUpdate: EventMarker {'fetches':i0,'reason':'Mesh Download Quiescent','scope':'Teleport','start':r385.358856,'stop':r385.358856,'sys_cpu':r0.000000,'teleports':i2,'user_cpu':r0.000000}
2018-10-29T12:04:08Z INFO: newview/llviewerdisplay.cpp(237) : display_stats: FPS: 195.40
2018-10-29T12:04:14Z INFO: newview/llworld.cpp(716) : LLWorld::removeRegion: Removing region 1638400.000000:1638656.000000
2018-10-29T12:04:14Z INFO: newview/lleventpoll.cpp(153) : LLEventPolling::Details::LLEventPollImpl::stop: requesting stop for event poll coroutine <2>
2018-10-29T12:04:14Z INFO: llmessage/llcorehttputil.cpp(1186) : LLCoreHttpUtil::HttpCoroutineAdapter::cancelSuspendedOperation: Canceling yielding request!
2018-10-29T12:04:14Z INFO: #Messaging; llmessage/message.cpp(1542) : LLMessageSystem::disableCircuit: LLMessageSystem::disableCircuit for 129.215.219.74:9005
2018-10-29T12:04:14Z WARNING: #Messaging; llmessage/message.cpp(1581) : LLMessageSystem::disableCircuit: Couldn't find circuit code for 129.215.219.74:9005
2018-10-29T12:04:14Z WARNING: #CoreHttp; llcorehttp/_httppolicy.cpp(434) : LLCore::HttpPolicy::stageAfterCompletion: HTTP request 0000024559DBDEF0 failed after 0 retries. Reason: Bad Gateway (Http_502)
2018-10-29T12:04:14Z WARNING: #CoreHTTP; llmessage/llcorehttputil.cpp(282) : LLCoreHttpUtil::HttpCoroHandler::onCompleted: Possible failure [Http_502] cannot POST url 'http://ai.vue.ed.ac.uk:9000/CAPS/EQG/61e3814a-d284-4157-9286-9827569e3bda/' [^] because Bad Gateway
2018-10-29T12:04:14Z WARNING: #Teleport; newview/llagent.cpp(4659) : LLAgent::handleTeleportFailed: Agent handling teleport failure!
2018-10-29T12:04:14Z INFO: newview/llviewermessage.cpp(7019) : process_teleport_failed: Teleport error, message_id=Problems connecting to destination Edinburgh, reason: Connection between viewer and destination region could not be established.
2018-10-29T12:04:14Z WARNING: newview/lltoastalertpanel.cpp(184) : LLToastAlertPanel::LLToastAlertPanel: Alert: Teleport failed.
Problems connecting to destination Edinburgh, reason: Connection between viewer and destination region could not be established.
2018-10-29T12:04:18Z INFO: newview/llviewerdisplay.cpp(237) : display_stats: FPS: 118.20
2018-10-29T12:04:18Z INFO: llui/llfloater.cpp(756) : LLFloater::closeFloater: Closing floater toast
2018-10-29T12:04:18Z WARNING: llui/llmodaldialog.cpp(129) : LLModalDialog::stopModal: LLModalDialog::stopModal not in list!
2018-10-29T12:04:22Z WARNING: #CoreHttp; llcorehttp/_httppolicy.cpp(434) : LLCore::HttpPolicy::stageAfterCompletion: HTTP request 0000024559DC01D0 failed after 0 retries. Reason: Timeout was reached (Easy_28)
2018-10-29T12:04:22Z WARNING: #CoreHTTP; llmessage/llcorehttputil.cpp(282) : LLCoreHttpUtil::HttpCoroHandler::onCompleted: Possible failure [Easy_28] cannot POST url 'http://ai.vue.ed.ac.uk:9000/CAPS/EQG/bc47066b-09f9-4af4-8b9e-8a577e1ebe16/' [^] because Timeout was reached

After login and before teleport attempt avatar is showed as root in "AiLand" and child in "Edinburgh"...

Region (root) # show users full

Agents connected: 2

Firstname Lastname Agent ID Root/Child Region Position
Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb Root AiLand <124.0707, 126.0659, 25.7422>
Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb Child Edinburgh <124.0707, -129.9341, 25.7422>

BUT... at end of this possibly incorrectly "show users full" only shows avatar as in AiLand (root) and not in Edinburgh (child) as I think it should.... its losing that connection in the failed TP attempt...

Region (root) # show users full

Agents connected: 1

Firstname Lastname Agent ID Root/Child Region Position
Ai Austin ff0a6e25-15cf-4294-9374-4ce8cdec65eb Root AiLand <124.0707, 126.0659, 25.74197>

(0033296)
aiaustin (developer)
2018-10-29 05:16
edited on: 2018-10-29 05:17

This sounds like we are getting somewhere as its failing in very obvious ways on a very simple setup now... I would not be surprised if it does not turn out to be some trivial issue as its just so obviously broken... but clearly its not just me that is seeing this.

I have a test setup that I can try things on or get logs from if someone can advise on what would be helpful.

The setup is actually still HG accessible via loginURI http://ai.vue.ed.ac.uk:8002 [^] (onlu Ailand and Edinburgh regions running at present) if anyone wants to look at it from their end.

(0033297)
aiaustin (developer)
2018-10-29 05:28

Test with Windows Defender Firewall turned off for public and private networks, and fully running on a single subnet for viewer and server... TP failures still occur. So unless anyone thinks that is a factor I will reenable Windows Firewall. Though in any case its set to allow connections through for Robust.exe and OpenSim.exe for both public and private networks.
(0033298)
paela argus (reporter)
2018-10-29 08:26

Can you just try disable http pipeline in debug mode and see if the tp work better ?
(0033299)
aiaustin (developer)
2018-10-29 08:36

Tried with imagePipelineUseHTTP = FALSE and that has no effect. Still get the same TP failures.
(0033300)
aiaustin (developer)
2018-10-29 09:17
edited on: 2018-10-29 09:34

@Ubit, you are on AiLand as we speak. but please note I just started that with the current 0.9.0.1 sources last formal release.. Going back to that appears to improve matters wrt TP issues. I have my full grid back up temporarily, normal avatars and am teleporting without issue between the regions. Though I still get bad gateway errors on Firestorm console log.

(0033301)
aiaustin (developer)
2018-10-29 09:36
edited on: 2018-10-29 09:38

Spoke too soon, TPs were faster and I did about 10 but problem is still there in 0.9.0.1.

I have reset Ailand to the very simple 2 region one server dev master (currently 507) setup and put Openvue on 0.9.0.1 stable release for further testing tomorrow!

(0033303)
UbitUmarov (administrator)
2018-10-29 10:02

just to complete specs
win box is a i7-8700k running the regions, robust, 2 FS viewers, VS with 2 open projects, several open web pages, one with a twich stream running.

Linux is Debian 9.5 on a i7-3770k, mono 5.14, doing nothing else
network is basic 100mb served by a old low cost local router (mostly working as switcher on this)
(0033304)
aiaustin (developer)
2018-10-29 13:47
edited on: 2018-10-29 13:59

@Ubit, AiLand grid is also running opensim-0.9.0.1-507-gcf33e04.zip and reporting Current simulator: OpenSim 0.9.1.0 Snail Dev (Win/.NET) and just running on single server as noted above.

Only AiLand and Edinburgh regions running... ignore OpenVCE which shows on the map but is not live.

When you dropped in this afternoon I had temporarily reverted to the last stable 0.9.0.1 release built from source.

Openvue grid is reverted to 0.9.0.1 last stable release for further testing... so lets just stick with AiLand to see if we can identify the issues.

(0033305)
UbitUmarov (administrator)
2018-10-30 02:47

Been there again with Bill and sure something very wrong on that box.
Http seems very slow, and does give odd errors possible denoting some kind of corruption, some on the logs you added here.
I also had fail tp when i was there on 0.9.0.1 And that is .net4.0 and old http server.
Think you did used 0.9.0.1 without any issues in past (it was master befeore the release), going a bit back to a version that did work cna be a sanity check.
so, what changed?
This issue maybe differente and a lot worse than the original report
(0033306)
UbitUmarov (administrator)
2018-10-30 02:56

the singularity logs in particular.
I no longer trust singularity code after seining very broken versions after 1.8.6.
(0033307)
aiaustin (developer)
2018-10-30 03:07
edited on: 2018-10-30 03:15

I agree, AiLand is in a very bad state and effectively unusable. And it started around April 2018. Unfortunately so many things changed just then... Windows updated to winver 1803, .net changes, httptests branch merge, etc. And the merge scatters in commits dated back some time in the dev master branch timeline. unfortunately.

I never ran the stable 0.9.0.1 package release. I have always been on dev master @Ubit.

Two separate grids are both showing the same issues, Openvue (our main grid) and AiLand which I use for experiments.

I will stick with Firestorm for reporting from now on as I don't suspect the viewer.

As I can get these errors with ONE server, two adjacent simple regions and a viewer machine on on the same subnet that gives us a simpler environment to try to pin down what the issues might be.

It COULD be several issues of course, as I am seeing TP failures, very slow content loading and ridiculously slow texture loading all on both my grids. And those issues have been there since April 2018 or so. The change to the priority of some threads appeared to make it worse if that helps.

If you have any suggestion as to what I could log or test with I would be happy to do that. Also, so long as the data base is not affected I can go back to a pre 0.9.0.1 stable commit if you have a suggestion as to which one to try. maybe one back in early March 2018?

I am not that keen to dump OARs, IARs and set up from scratch as its quite a rich environment what with groups, 5 starter avatars, etc.

(0033308)
UbitUmarov (administrator)
2018-10-30 03:36

0.9.0.1 release is just the master as it was at that release date.
my win10 is also 1803 with all recent updates.

TP fails as original reported may happen because of several reasons, mostly normal network issues, dns issues, etc, lag etc. a tp means communications between 2 regions, grid and viewer, databases, dns servers. Several things that can go wrong.

But I do see stranger things on AIland like those texture range errors with firestorm. Errors I never seen before (well the error text message is also a FS bug, it tells http pipeline when fs has http pipeline hardcode disabled for opensim )

testing a older version whould just help to see it its a opensim issue or a change on the machine or its network enviroment
(0033309)
aiaustin (developer)
2018-10-30 03:40
edited on: 2018-10-30 03:42

I can't work out a sensible point to revert to.. as there seem to be merge effects on the dev master commit timeline right back into mid 2017. And the problems started sometime around March/April 2018.

My grids were always on a reasonably recent dev master, but there was a big merge of the httptests branch into dev master and that has added in commits dated way back.

Any suggestion on what might be a starting point to return to something that is 0.9.x ish that will let us get back to a 2workign system to home in on where the bad effects started?

Anyone else with a grid (rather than just add on regions to a larger and more complex setup like OSGrid) that shows these effects could weigh in and help.

(0033310)
aiaustin (developer)
2018-10-30 03:41

I do suspect some machine or environment change... could it be that the system is too FAST? I.e. responding much FASTER than anticipated? I know its an odd things to ask!!
(0033311)
UbitUmarov (administrator)
2018-10-30 04:08

I added file http://opensimulator.org/dist/opensim0.9.1.0Testbin-300918.zip [^]
this is the bin folder of my test of compiling opensim-0.9.0.1-507-gcf33e04.zip
that worked fine for me as described above.
note that I did delete all the ini files.

yes it is a odd thing to ask, and no your system is not that fast :)

on git you can go back to the tag 0.9.0.1
or just get a older release version on http://opensimulator.org/dist/ [^]
or from viewgit
(0033312)
UbitUmarov (administrator)
2018-10-30 04:11

on git there is also the branch 0.9.0.1-postfixes with the release point
(0033313)
aiaustin (developer)
2018-10-30 05:30
edited on: 2018-10-30 05:37

A bit extreme, but I just reverted to stable release 0.8.2.1 (with minimal changes to my .ini files to allow that to work) using same setup, servers and data base and I can teleport with no problems between the two regions on AiLand grid on 20 attempts just now.

There are a few messages in the Firestorm console still... but none of those http pipeline sync and other texture issues... only these messages... which may be unrelated and possibly have been there for ages.. though it would be useful to try to work out what is causing those too!

I get the HTTP error 502 Bad Gateway messages on two specific POST ...CAPS/EQG/uuid URLs repeated every 60 seconds in the Firestorm console...

2018-10-30T12:19:23Z WARNING: #CoreHttp; llcorehttp/_httppolicy.cpp(434) : LLCore::HttpPolicy::stageAfterCompletion: HTTP request 0000028F0FF6D5B0 failed after 0 retries. Reason: Bad Gateway (Http_502)

2018-10-30T12:19:23Z WARNING: #CoreHTTP; llmessage/llcorehttputil.cpp(282) : LLCoreHttpUtil::HttpCoroHandler::onCompleted: Possible failure [Http_502] cannot POST url 'http://ai.vue.ed.ac.uk:9000/CAPS/EQG/6c530d6b-44d4-400d-b38c-ca63bf3eeb20/' [^] because Bad Gateway

2018-10-30T12:19:27Z WARNING: #CoreHttp; llcorehttp/_httppolicy.cpp(434) : LLCore::HttpPolicy::stageAfterCompletion: HTTP request 0000028F0FF6CC00 failed after 0 retries. Reason: Bad Gateway (Http_502)

2018-10-30T12:19:27Z WARNING: #CoreHTTP; llmessage/llcorehttputil.cpp(282) : LLCoreHttpUtil::HttpCoroHandler::onCompleted: Possible failure [Http_502] cannot POST url 'http://ai.vue.ed.ac.uk:9000/CAPS/EQG/3842ea81-bb06-44b9-ae70-951bb05c8074/' [^] because Bad Gateway
2018-10-30T12:19:31Z INFO: newview/llviewerdisplay.cpp(237) : display_stats: FPS: 20.60

NOTE 1: its a different pair of UUIDs after each login with same avatar and viewer... but always repeating a pair every 60 seconds.

NOTE 2: An earlier error I was seeing was removed by deleting all the landmarks in the user inventory. one might have been bad from HG landmark saves over the ages... llinventory/lllandmark.cpp(158) : LLLandmark::constructFromString: Bad Landmark Asset: bad _DATA_ block.

(0033314)
aiaustin (developer)
2018-10-30 05:54
edited on: 2018-10-30 05:57

Now trying with your precompiled binary @Ubit... i.e. file http://opensimulator.org/dist/opensim0.9.1.0Testbin-300918.zip [^] (i.e. based on current dev master 507). This immediately gives the same TP errors when moving about between the two test regions, So it looks like this has at least established that my runprebuild/compile environment is not the fault.

On the firestorm console I get the usual pair of bad gateways errors each 60 seconds... but then on a teleport attempt the failure we have been reporting... note TWO messages of form "LLTeleportRequestViaLocation::startTeleport". is that expected?

Reminder Robust is on port 8002 (public parts), OpenSim regions are AiLand on 9000 and Edinburgh on 9005 (which shows a long last ping timeout).

2018-10-30T12:49:33Z WARNING: #CoreHttp; llcorehttp/_httppolicy.cpp(434) : LLCore::HttpPolicy::stageAfterCompletion: HTTP request 0000026726D76210 failed after 0 retries. Reason: Bad Gateway (Http_502)
2018-10-30T12:49:33Z WARNING: #CoreHTTP; llmessage/llcorehttputil.cpp(282) : LLCoreHttpUtil::HttpCoroHandler::onCompleted: Possible failure [Http_502] cannot POST url 'http://ai.vue.ed.ac.uk:9000/CAPS/EQG/9e5a1a0f-901a-4546-b059-121b8b2b1529/' [^] because Bad Gateway
2018-10-30T12:49:33Z INFO: newview/llviewerdisplay.cpp(237) : display_stats: FPS: 85.40
2018-10-30T12:49:33Z INFO: #Teleport; newview/llagent.cpp(5619) : LLTeleportRequestViaLocation::LLTeleportRequestViaLocation: LLTeleportRequestViaLocation created
2018-10-30T12:49:33Z INFO: #Teleport; newview/llagent.cpp(5624) : LLTeleportRequestViaLocation::~LLTeleportRequestViaLocation: ~LLTeleportRequestViaLocation
2018-10-30T12:49:33Z INFO: #Telport; newview/llagent.cpp(4594) : LLAgent::startTeleportRequest: Agent handling start teleport request.
2018-10-30T12:49:33Z INFO: #Teleport; newview/llagent.cpp(5635) : LLTeleportRequestViaLocation::startTeleport: LLTeleportRequestViaLocation::startTeleport
2018-10-30T12:49:33Z INFO: #Teleport; newview/llagent.cpp(4447) : LLAgent::teleportCore: In teleport core!
2018-10-30T12:49:33Z INFO: llui/llfloater.cpp(756) : LLFloater::closeFloater: Closing floater worldmap
2018-10-30T12:49:33Z INFO: #; newview/llagent.cpp(4705) : LLAgent::teleportRequest: TeleportLocationRequest: '7036874419405056':{ 125.698738, 130.037033, 25.909164 }
2018-10-30T12:49:37Z WARNING: llmessage/llcircuit.cpp(1075) : LLCircuitData::checkCircuitTimeout: LLCircuitData::checkCircuitTimeout for 129.215.219.74:9005 last ping 104.790017s seconds ago.
2018-10-30T12:49:37Z WARNING: llmessage/llcircuit.cpp(1085) : LLCircuitData::checkCircuitTimeout: LLCircuitData::checkCircuitTimeout for 129.215.219.74:9005 still dead, dropping.
2018-10-30T12:49:37Z INFO: llmessage/llcircuit.cpp(468) : LLCircuit::removeCircuitData: LLCircuit::removeCircuitData for 129.215.219.74:9005
2018-10-30T12:49:43Z INFO: newview/llviewerdisplay.cpp(237) : display_stats: FPS: 189.80
2018-10-30T12:49:48Z INFO: #Mesh; newview/llmeshrepository.cpp(5149) : LLMeshRepository::metricsUpdate: EventMarker {'fetches':i0,'reason':'Mesh Download Quiescent','scope':'Teleport','start':r334.645858,'stop':r334.645858,'sys_cpu':r0.000000,'teleports':i4,'user_cpu':r0.000000}
2018-10-30T12:49:53Z INFO: newview/llviewerdisplay.cpp(237) : display_stats: FPS: 191.20
2018-10-30T12:49:58Z INFO: llcommon/llmemory.cpp(155) : LLMemory::logMemoryInfo: Current allocated physical memory(KB): 458160KB
2018-10-30T12:49:58Z INFO: llcommon/llmemory.cpp(156) : LLMemory::logMemoryInfo: Current allocated page size (KB): 733700KB
2018-10-30T12:49:58Z INFO: llcommon/llmemory.cpp(157) : LLMemory::logMemoryInfo: Current available physical memory(KB): 1219561KB
2018-10-30T12:49:58Z INFO: llcommon/llmemory.cpp(158) : LLMemory::logMemoryInfo: Current max usable memory(KB): 1677721KB
2018-10-30T12:49:58Z INFO: #AssetStorage; newview/llviewerassetstorage.cpp(612) : LLViewerAssetStorage::logAssetStorageInfo: Active coros 0
2018-10-30T12:49:58Z INFO: #AssetStorage; newview/llviewerassetstorage.cpp(613) : LLViewerAssetStorage::logAssetStorageInfo: mPendingDownloads size 0
2018-10-30T12:49:58Z INFO: #AssetStorage; newview/llviewerassetstorage.cpp(614) : LLViewerAssetStorage::logAssetStorageInfo: mCountStarted 0
2018-10-30T12:49:58Z INFO: #AssetStorage; newview/llviewerassetstorage.cpp(615) : LLViewerAssetStorage::logAssetStorageInfo: mCountCompleted 0
2018-10-30T12:49:58Z INFO: #AssetStorage; newview/llviewerassetstorage.cpp(616) : LLViewerAssetStorage::logAssetStorageInfo: mCountSucceeded 0
2018-10-30T12:49:58Z INFO: #AssetStorage; newview/llviewerassetstorage.cpp(617) : LLViewerAssetStorage::logAssetStorageInfo: mTotalBytesFetched 0
2018-10-30T12:50:03Z INFO: newview/llviewerdisplay.cpp(237) : display_stats: FPS: 191.90
2018-10-30T12:50:05Z WARNING: #Teleport; newview/llagent.cpp(4659) : LLAgent::handleTeleportFailed: Agent handling teleport failure!
2018-10-30T12:50:05Z INFO: newview/llviewermessage.cpp(7019) : process_teleport_failed: Teleport error, message_id=Problems connecting to destination Edinburgh, reason: Connection between viewer and destination region could not be established.
2018-10-30T12:50:05Z WARNING: newview/lltoastalertpanel.cpp(184) : LLToastAlertPanel::LLToastAlertPanel: Alert: Teleport failed.
Problems connecting to destination Edinburgh, reason: Connection between viewer and destination region could not be established.

(0033315)
aiaustin (developer)
2018-10-30 06:09

And with same precompile code from http://opensimulator.org/dist/opensim0.9.1.0Testbin-300918.zip, [^] a second teleport attempt back from Edinburgh region to (Home) AiLand region with a few messages that look a bit different... but TP failure message as seen in Viewer popup is same as before "Connection between viewer and destination region could not be established".

2018-10-30T13:02:53Z INFO: #Teleport; newview/llagent.cpp(5545) : LLTeleportRequestViaLandmark::LLTeleportRequestViaLandmark: LLTeleportRequestViaLandmark created.
2018-10-30T13:02:53Z INFO: #Telport; newview/llagent.cpp(4594) : LLAgent::startTeleportRequest: Agent handling start teleport request.
2018-10-30T13:02:53Z INFO: #Teleport; newview/llagent.cpp(5561) : LLTeleportRequestViaLandmark::startTeleport: LLTeleportRequestViaLandmark::startTeleport
2018-10-30T13:02:53Z INFO: #Teleport; newview/llagent.cpp(4447) : LLAgent::teleportCore: In teleport core!
2018-10-30T13:02:53Z INFO: llui/llfloater.cpp(756) : LLFloater::closeFloater: Closing floater worldmap


2018-10-30T13:03:08Z INFO: #Mesh; newview/llmeshrepository.cpp(5149) : LLMeshRepository::metricsUpdate: EventMarker {'fetches':i0,'reason':'Mesh Download Quiescent','scope':'Teleport','start':r114.959316,'stop':r114.959316,'sys_cpu':r0.000000,'teleports':i3,'user_cpu':r0.000000}
2018-10-30T13:03:13Z INFO: newview/llviewerdisplay.cpp(237) : display_stats: FPS: 19.90
2018-10-30T13:03:17Z WARNING: #CoreHttp; llcorehttp/_httppolicy.cpp(434) : LLCore::HttpPolicy::stageAfterCompletion: HTTP request 000001E68667BB70 failed after 0 retries. Reason: Bad Gateway (Http_502)
2018-10-30T13:03:17Z WARNING: #CoreHTTP; llmessage/llcorehttputil.cpp(282) : LLCoreHttpUtil::HttpCoroHandler::onCompleted: Possible failure [Http_502] cannot POST url 'http://ai.vue.ed.ac.uk:9000/CAPS/EQG/81206282-242a-46d8-8cef-852df1034a72/' [^] because Bad Gateway
2018-10-30T13:03:20Z INFO: newview/llworld.cpp(716) : LLWorld::removeRegion: Removing region 1638400.000000:1638400.000000
2018-10-30T13:03:20Z INFO: newview/lleventpoll.cpp(153) : LLEventPolling::Details::LLEventPollImpl::stop: requesting stop for event poll coroutine <1>
2018-10-30T13:03:20Z INFO: llmessage/llcorehttputil.cpp(1186) : LLCoreHttpUtil::HttpCoroutineAdapter::cancelSuspendedOperation: Canceling yielding request!
2018-10-30T13:03:20Z INFO: #Messaging; llmessage/message.cpp(1542) : LLMessageSystem::disableCircuit: LLMessageSystem::disableCircuit for 129.215.219.74:9000
2018-10-30T13:03:20Z WARNING: #Messaging; llmessage/message.cpp(1581) : LLMessageSystem::disableCircuit: Couldn't find circuit code for 129.215.219.74:9000
2018-10-30T13:03:20Z WARNING: newview/llworldmapmessage.cpp(163) : LLWorldMapMessage::processMapBlockReply: Invalid map image type returned! layer = 0
2018-10-30T13:03:20Z WARNING: #CoreHttp; llcorehttp/_httppolicy.cpp(434) : LLCore::HttpPolicy::stageAfterCompletion: HTTP request 000001E68667E610 failed after 0 retries. Reason: Bad Gateway (Http_502)
2018-10-30T13:03:20Z WARNING: #CoreHTTP; llmessage/llcorehttputil.cpp(282) : LLCoreHttpUtil::HttpCoroHandler::onCompleted: Possible failure [Http_502] cannot POST url 'http://ai.vue.ed.ac.uk:9000/CAPS/EQG/81206282-242a-46d8-8cef-852df1034a72/' [^] because Bad Gateway
2018-10-30T13:03:20Z WARNING: #Teleport; newview/llagent.cpp(4659) : LLAgent::handleTeleportFailed: Agent handling teleport failure!
2018-10-30T13:03:20Z INFO: newview/llviewermessage.cpp(7019) : process_teleport_failed: Teleport error, message_id=Problems connecting to destination AiLand, reason: Connection between viewer and destination region could not be established.
2018-10-30T13:03:20Z WARNING: newview/lltoastalertpanel.cpp(184) : LLToastAlertPanel::LLToastAlertPanel: Alert: Teleport failed.
Problems connecting to destination AiLand, reason: Connection between viewer and destination region could not be established.

2018-10-30T13:03:28Z WARNING: #CoreHttp; llcorehttp/_httppolicy.cpp(434) : LLCore::HttpPolicy::stageAfterCompletion: HTTP request 000001E68667DA70 failed after 0 retries. Reason: Timeout was reached (Easy_28)
2018-10-30T13:03:28Z WARNING: #CoreHTTP; llmessage/llcorehttputil.cpp(282) : LLCoreHttpUtil::HttpCoroHandler::onCompleted: Possible failure [Easy_28] cannot POST url 'http://ai.vue.ed.ac.uk:9000/CAPS/EQG/1887d090-6cec-487c-bacf-97ee1d3e7c3c/' [^] because Timeout was reached
(0033316)
aiaustin (developer)
2018-10-30 06:17

On trying teleport from Edinburgh to Ailand (and vice versa).. I note two things I had not spotted before.. but its more obvious now I am down to testing two adjacent regions on a simple setup

Before the failed teleport attempt, "show users full" shows the root and child agent presence and the next across region shows in the viewer.

AFTER I fail to teleport, the whole destination region disappears from the viewer, and "show regions full" only shows the avatar as in the root region, the adjacent region no longer shows as having a child presence for the agent.
(0033317)
aiaustin (developer)
2018-10-30 06:39
edited on: 2018-10-30 08:29

Short story of current status of testing..

** 0.8.2.1 stable release works

** 0.9.0.1 stable release (with HTTP server dll fix) appears to be working much better or allowing many more TPs before showing issues... but is displaying a range of the previously noted errors in the Firestorm console log (contrary to 0.8.2.1) . More testing needed. And I have seen the same error a few times.

** dev master up to 507 fails

** dev master 507 compiled by @Ubit fails

When working, the texture slow load and other issues also do not seem to be present.

(0033318)
aiaustin (developer)
2018-10-30 07:19

Bad gateway style errors showing in Firestorm console log seem to be each 60 seconds and are given one per nearby region that is within 2 regions of the region the avatar is on (all 256x256 regions and view distance .ini files usually 511/512)...

llcorehttp/_httppolicy.cpp(434) : LLCore::HttpPolicy::stageAfterCompletion: HTTP request 000001E68667E610 failed after 0 retries. Reason: Bad Gateway (Http_502)
(0033319)
aiaustin (developer)
2018-10-30 07:48
edited on: 2018-10-30 07:53

The texture loading problems and the TP failures must be linked. On a working 0.9.0.1 stable release version of AiLand grid, with all regions running and both servers up, and avatar back to normal state with attachments, HUDs, etc... I cleared the Firestorm viewer cache. relogged and on login back to AiLand the whole region, all objects and textures loaded and wee crisp within 20 seconds of login. On dev master it was taking over half an hour and some still had not gone crisp or were grey.

But even with this apparently working setup, and no errors noted in the OpenSim.exe consoles, the Firestorm viewer console shows the HTTP_502 bad gateway errors every 60 seconds. Like this example...

2018-10-30T14:52:48Z WARNING: #CoreHttp; llcorehttp/_httppolicy.cpp(434) : LLCore::HttpPolicy::stageAfterCompletion: HTTP request 0000029905AC24A0 failed after 0 retries. Reason: Bad Gateway (Http_502)
2018-10-30T14:52:48Z WARNING: #CoreHTTP; llmessage/llcorehttputil.cpp(282) : LLCoreHttpUtil::HttpCoroHandler::onCompleted: Possible failure [Http_502] cannot POST url 'http://ai.vue.ed.ac.uk:9000/CAPS/EQG/7043b1f1-4425-485e-9629-7ec9bb9f41fb/' [^] because Bad Gateway

(0033321)
aiaustin (developer)
2018-10-30 08:09
edited on: 2018-10-30 08:10

@Kent... the problem with using OSGrid to test this issue is the complexity and multiplicity of the environments used for the core servers, some of which are unique to OSGrid, and the region servers which are on very many different platforms.

Unfortunately @Ubit could not reproduce the issues with the latest dev master 507 when he compiled under Windows. But he gave me a version he made for the test and it fails all the time for me.

I am NOT saying this is not a local server or Windows environment issue at my end... but I am saying it is only with dev master and recently from about April 2018.

With 0.9.0.1 stable release the Openvue and AiLand grids appear to be working fine (on limited testing of 50 or so teleports) but now including HG jumps and grid to grid teleports with avatars with attachments.

(0033322)
mac4kent (reporter)
2018-10-30 08:23

I remember I meet @Ubit 1 time. dan banner is not friend on Mac.
Paela explain me everything and paela did create on his's own code is no error.
paela already upset at them who they made few mistake OpenSIM. but you may ignore me (Kent).

I had my experience and I talk to dan banner and paela last April yes you are right. I test everything on youtube screen record.
Now wait for OSGrid will open login soon.
(0033323)
UbitUmarov (administrator)
2018-10-30 10:15

that Bad Gateway every 60secs ( when there is no much other activity) is expected.
(0033325)
aiaustin (developer)
2018-10-30 12:54
edited on: 2018-10-30 13:59

@Ubit... thanks for confirming that the Bad Gateway every 60secs (when there is not much other activity) is expected. Good to know I can ignore that. It was essentially the only issue I see with 0.8.2.1 so at least we have a fully working baseline there. Any thought as to what a POST server/CAPS/EQG/uuid is trying to do and if we can absorb or suppress that at the server end one day?

0.9.0.1 works reasonably well, but definitely shows the TP errors once in a while and once it appears the destination region loses the child presence and disappears from the 3D viewer view... After that it appears to be broken until a relog. Even after log off the source region (and adjacent ones where avatar was a child) continue to show avatar as in root or child for nearby regions for some 30 seconds after the failed and stuck TP attempt. Then log out happens after that 30 second gap.. as if the OpenSim.exe instance was stuck somewhere for that period.

dev master is much much worse and I can hardly can get a TP at all and definitely fails 50% of time (507).. which seemed to me about twice as bad as 506 before the thread priority change which was still failing one in three times I would estimate... before I radically simplified the test setting.

(0033327)
BillBlight (developer)
2018-10-30 22:03
edited on: 2018-10-30 22:03

@mac4kent you need to stop the senseless bashing of 9x this is not the place.

I run a whole grid on it and no one has TP issues.

and I'm sure paela and dan can speak for themselves ..

(0033328)
BillBlight (developer)
2018-10-30 22:05

@aiaustin, Ubit pushed a new http server dll today, you might want to test with it ..

Thanks
(0033329)
aiaustin (developer)
2018-10-31 03:29
edited on: 2018-10-31 03:30

I saw that but was waiting in case @Ubit commented and felt it would help with this issue.

But in any case I built a system with 508 on Openvue grid including the new HTTP server dll and that fails the same way on TP attempts with the various http pipelining sync messages.

Example messages on one failed TP attempt (on Openvue grid - server virtual0.aiai.ed.ac.uk - from Vue-Port region to Openvue region) in the Firestorm console from the opening of the map to select a teleport to the final pop up viewer message:

2018-10-31T10:24:25Z INFO: llui/llfloater.cpp(688) : LLFloater::openFloater: Opening floater worldmap full path: /main_view/menu_stack/world_panel/Floater View/worldmap
2018-10-31T10:24:26Z WARNING: llcorehttp/_httplibcurl.cpp(435) : LLCore::HttpLibcurl::completeRequest: HTTP pipelining possibly out of sync, request wanted: 6143-19713 got: 0-18446744073709551615 url: http://virtual0.aiai.ed.ac.uk:9000/CAPS/01b974e6-8f8b-45d9-82d3-ead691c21844//?texture_id=76e7918f-babd-4014-95b4-53f0a03ec679 [^]
2018-10-31T10:24:27Z INFO: newview/llviewerdisplay.cpp(237) : display_stats: FPS: 154.80
2018-10-31T10:24:27Z WARNING: llcorehttp/_httplibcurl.cpp(435) : LLCore::HttpLibcurl::completeRequest: HTTP pipelining possibly out of sync, request wanted: 767-4609 got: 0-18446744073709551615 url: http://virtual0.aiai.ed.ac.uk:9000/CAPS/01b974e6-8f8b-45d9-82d3-ead691c21844//?texture_id=ab31f600-c82f-4434-bbe1-0bbbf6bfe9ef [^]
2018-10-31T10:24:28Z INFO: #Teleport; newview/llagent.cpp(5619) : LLTeleportRequestViaLocation::LLTeleportRequestViaLocation: LLTeleportRequestViaLocation created
2018-10-31T10:24:28Z INFO: #Telport; newview/llagent.cpp(4594) : LLAgent::startTeleportRequest: Agent handling start teleport request.
2018-10-31T10:24:28Z INFO: #Teleport; newview/llagent.cpp(5635) : LLTeleportRequestViaLocation::startTeleport: LLTeleportRequestViaLocation::startTeleport
2018-10-31T10:24:28Z INFO: #Teleport; newview/llagent.cpp(4447) : LLAgent::teleportCore: In teleport core!
2018-10-31T10:24:28Z INFO: llui/llfloater.cpp(756) : LLFloater::closeFloater: Closing floater worldmap
2018-10-31T10:24:28Z INFO: #; newview/llagent.cpp(4705) : LLAgent::teleportRequest: TeleportLocationRequest: '9951679745317632':{ 127.452744, 123.367477, 29.405107 }
2018-10-31T10:24:28Z INFO: #Cleanup; llcommon/llcleanup.cpp(26) : log_subsystem_cleanup: newview/pipeline.cpp(7531): calling LLVertexBuffer::cleanupClass() in void __cdecl LLPipeline::doResetVertexBuffers(bool)
2018-10-31T10:24:28Z INFO: newview/llworld.cpp(529) : LLWorld::addRegion: Add region with handle: 9951679745317632 on host 129.215.219.89:9004
2018-10-31T10:24:28Z INFO: newview/llworld.cpp(539) : LLWorld::addRegion: Region already exists and is alive, using existing region
2018-10-31T10:24:28Z INFO: #Messaging; newview/llviewermessage.cpp(3409) : process_teleport_finish: process_teleport_finish() Enabling 129.215.219.89:9004 with code 1410212702
2018-10-31T10:24:28Z WARNING: #CrossingCaps; newview/llviewerregion.cpp(3119) : LLViewerRegion::setSeedCapability: Received duplicate seed capability, posting to seed http://virtual0.aiai.ed.ac.uk:9000/CAPS/fe7d9ee6-eac1-447e-96e1-796be1791f6e0000/ [^]
2018-10-31T10:24:28Z INFO: #AppInit,#Capabilities; newview/llviewerregion.cpp(384) : LLViewerRegionImpl::requestBaseCapabilitiesCompleteCoro: Requesting second Seed from http://virtual0.aiai.ed.ac.uk:9000/CAPS/fe7d9ee6-eac1-447e-96e1-796be1791f6e0000/ [^]
2018-10-31T10:24:28Z INFO: newview/llvowlsky.cpp(360) : LLVOWLSky::updateGeometry: WL Skydome strips in 1 batches.
2018-10-31T10:24:28Z INFO: newview/llvowlsky.cpp(414) : LLVOWLSky::updateGeometry: completed in 0.00seconds
2018-10-31T10:24:28Z WARNING: llmessage/lldispatcher.cpp(79) : LLDispatcher::dispatch: Unable to find handler for Generic message: WindlightReset
2018-10-31T10:24:28Z WARNING: newview/llviewergenericmessage.cpp(101) : process_generic_message: GenericMessage WindlightReset failed to dispatch
2018-10-31T10:24:28Z INFO: #Messaging; newview/llviewermessage.cpp(3533) : process_agent_movement_complete: Changing home region to 2317056.000000:2317056.000000
2018-10-31T10:24:28Z INFO: #AgentLocation; newview/llagent.cpp(1007) : LLAgent::setRegion: Moving agent into region: Vue-Port located at 129.215.219.89:9004
2018-10-31T10:24:28Z INFO: newview/llagent.cpp(5698) : LLAgent::handleServerBakeRegionTransition: called
2018-10-31T10:24:28Z WARNING: newview/llpathfindingmanager.cpp(794) : LLPathfindingManager::getCapabilityURLForRegion: cannot find capability 'RetrieveNavMeshSrc' for current region 'Vue-Port'
2018-10-31T10:24:28Z WARNING: newview/llpathfindingmanager.cpp(794) : LLPathfindingManager::getCapabilityURLForRegion: cannot find capability 'RetrieveNavMeshSrc' for current region 'Vue-Port'
2018-10-31T10:24:28Z WARNING: newview/llpathfindingmanager.cpp(794) : LLPathfindingManager::getCapabilityURLForRegion: cannot find capability 'RetrieveNavMeshSrc' for current region 'Vue-Port'
2018-10-31T10:24:28Z INFO: newview/lfsimfeaturehandler.cpp(94) : LFSimFeatureHandler::setSupportedFeatures: Setting OpenSimExtras...
2018-10-31T10:24:28Z INFO: #WindlightCaps; newview/llwlhandlers.cpp(89) : LLEnvironmentRequest::doRequest: Requesting region windlight settings via http://virtual0.aiai.ed.ac.uk:9000/CAPS/0020/180a2afd-5cd6-45f5-b2ec-6160d840a429 [^]
2018-10-31T10:24:28Z INFO: newview/llviewerthrottle.cpp(149) : LLViewerThrottleGroup::sendToSim: Sending throttle settings, total BW 2250.000000
2018-10-31T10:24:28Z INFO: newview/llvoavatarself.cpp(3286) : LLVOAvatarSelf::sendAppearanceMessage: Setting clientTag
2018-10-31T10:24:28Z INFO: llui/llfloater.cpp(756) : LLFloater::closeFloater: Closing floater toolbox floater
2018-10-31T10:24:28Z INFO: newview/llvowlsky.cpp(360) : LLVOWLSky::updateGeometry: WL Skydome strips in 1 batches.
2018-10-31T10:24:28Z INFO: newview/llvowlsky.cpp(414) : LLVOWLSky::updateGeometry: completed in 0.00seconds
2018-10-31T10:24:28Z INFO: #Teleport; newview/llagent.cpp(4630) : LLAgent::handleTeleportFinished: Agent handling teleport finished.
2018-10-31T10:24:28Z INFO: #Teleport; newview/llagent.cpp(5624) : LLTeleportRequestViaLocation::~LLTeleportRequestViaLocation: ~LLTeleportRequestViaLocation
2018-10-31T10:24:28Z INFO: #Agent_GroupData; newview/llagent.cpp(4067) : LLAgentGroupDataUpdateViewerNode::post: GROUPDEBUG: Executing processAgentGroupDataUpdate
2018-10-31T10:24:28Z INFO: #WindlightCaps; newview/llwlhandlers.cpp(121) : LLEnvironmentRequest::environmentRequestCoro: Received region windlight settings
2018-10-31T10:24:28Z INFO: newview/kcwlinterface.cpp(667) : KCWindlightInterface::haveParcelOverride: Region environment settings received. Parcel WL settings will be overridden.
2018-10-31T10:24:28Z WARNING: llmessage/lltransfermanager.cpp(309) : LLTransferManager::processTransferInfo: 6b10d49f-5ded-7214-8883-36fe12791201: Non-ok status, cleaning up
2018-10-31T10:24:28Z WARNING: llmessage/lltransfertargetvfile.cpp(197) : LLTransferTargetVFile::completionCallback: Aborting vfile transfer for e8094e77-eb67-431a-ad3e-bf650576df06
2018-10-31T10:24:28Z WARNING: llvfs/llvfsthread.cpp(206) : LLVFSThread::Request::Request: LLVFSThread: Request with numbytes = 0 operation = 0 offset 0 file_type 3
2018-10-31T10:24:28Z INFO: llinventory/lllandmark.cpp(158) : LLLandmark::constructFromString: Bad Landmark Asset: bad _DATA_ block.
2018-10-31T10:24:28Z INFO: newview/llworld.cpp(716) : LLWorld::removeRegion: Removing region 2316800.000000:2316544.000000
2018-10-31T10:24:28Z INFO: newview/lleventpoll.cpp(153) : LLEventPolling::Details::LLEventPollImpl::stop: requesting stop for event poll coroutine <1>
2018-10-31T10:24:28Z INFO: llmessage/llcorehttputil.cpp(1186) : LLCoreHttpUtil::HttpCoroutineAdapter::cancelSuspendedOperation: Canceling yielding request!
2018-10-31T10:24:28Z INFO: #Messaging; llmessage/message.cpp(1542) : LLMessageSystem::disableCircuit: LLMessageSystem::disableCircuit for 129.215.219.89:9001
2018-10-31T10:24:28Z WARNING: #Messaging; llmessage/message.cpp(1581) : LLMessageSystem::disableCircuit: Couldn't find circuit code for 129.215.219.89:9001
2018-10-31T10:24:28Z WARNING: #CoreHttp; llcorehttp/_httppolicy.cpp(434) : LLCore::HttpPolicy::stageAfterCompletion: HTTP request 0000022D6EC89F60 failed after 0 retries. Reason: Bad Gateway (Http_502)
2018-10-31T10:24:28Z WARNING: #CoreHTTP; llmessage/llcorehttputil.cpp(282) : LLCoreHttpUtil::HttpCoroHandler::onCompleted: Possible failure [Http_502] cannot POST url 'http://virtual0.aiai.ed.ac.uk:9000/CAPS/EQG/d5c2f3ab-e044-45d1-9147-ca3e79fb3a18/' [^] because Bad Gateway
2018-10-31T10:24:28Z INFO: newview/llvoavatarself.cpp(1306) : LLVOAvatarSelf::updateRegion: Region crossing took 34165.363281 ms
2018-10-31T10:24:28Z WARNING: #Avatar; newview/llvoavatar.cpp(8910) : LLVOAvatar::processAvatarAppearance: Stale appearance received #-1 attempt to roll back from #-1... dropping.
2018-10-31T10:24:31Z WARNING: #CoreHttp; llcorehttp/_httppolicy.cpp(434) : LLCore::HttpPolicy::stageAfterCompletion: HTTP request 0000022D6EC897A0 failed after 0 retries. Reason: Not Found (Http_404)
2018-10-31T10:24:31Z WARNING: #Texture; newview/lltexturefetch.cpp(2102) : LLTextureFetchWorker::onCompleted: CURL GET FAILED, status: Http_404 reason: Not Found
2018-10-31T10:24:31Z WARNING: #Texture; newview/lltexturefetch.cpp(1666) : LLTextureFetchWorker::doWork: Texture missing from server (404): http://virtual0.aiai.ed.ac.uk:9000/CAPS/3057f1d7-2697-4921-b329-4daeb2d951f8//?texture_id=c7723802-a270-4dc9-bcec-190308547cca [^]
2018-10-31T10:24:31Z WARNING: #CoreHttp; llcorehttp/_httppolicy.cpp(434) : LLCore::HttpPolicy::stageAfterCompletion: HTTP request 0000022D6B31DC10 failed after 0 retries. Reason: Not Found (Http_404)
2018-10-31T10:24:31Z WARNING: #Texture; newview/lltexturefetch.cpp(2102) : LLTextureFetchWorker::onCompleted: CURL GET FAILED, status: Http_404 reason: Not Found
2018-10-31T10:24:31Z WARNING: #Texture; newview/lltexturefetch.cpp(1666) : LLTextureFetchWorker::doWork: Texture missing from server (404): http://virtual0.aiai.ed.ac.uk:9000/CAPS/3057f1d7-2697-4921-b329-4daeb2d951f8//?texture_id=008376d7-e3f0-461d-848f-2d79b679b58b [^]
2018-10-31T10:24:37Z INFO: newview/llviewerdisplay.cpp(237) : display_stats: FPS: 121.70
2018-10-31T10:24:40Z INFO: llui/llfloater.cpp(756) : LLFloater::closeFloater: Closing floater toast
2018-10-31T10:24:43Z INFO: #Mesh; newview/llmeshrepository.cpp(5149) : LLMeshRepository::metricsUpdate: EventMarker {'fetches':i0,'reason':'Mesh Download Quiescent','scope':'Teleport','start':r545.881953,'stop':r545.881953,'sys_cpu':r0.000000,'teleports':i6,'user_cpu':r0.000000}
2018-10-31T10:24:47Z INFO: newview/llviewerdisplay.cpp(237) : display_stats: FPS: 117.50
2018-10-31T10:24:50Z INFO: #Teleport; newview/llagent.cpp(5545) : LLTeleportRequestViaLandmark::LLTeleportRequestViaLandmark: LLTeleportRequestViaLandmark created.
2018-10-31T10:24:50Z INFO: #Telport; newview/llagent.cpp(4594) : LLAgent::startTeleportRequest: Agent handling start teleport request.
2018-10-31T10:24:50Z INFO: #Teleport; newview/llagent.cpp(5561) : LLTeleportRequestViaLandmark::startTeleport: LLTeleportRequestViaLandmark::startTeleport
2018-10-31T10:24:50Z INFO: #Teleport; newview/llagent.cpp(4447) : LLAgent::teleportCore: In teleport core!
2018-10-31T10:24:50Z INFO: llui/llfloater.cpp(756) : LLFloater::closeFloater: Closing floater worldmap
2018-10-31T10:24:57Z INFO: newview/llviewerdisplay.cpp(237) : display_stats: FPS: 201.20
2018-10-31T10:25:00Z WARNING: llcorehttp/_httplibcurl.cpp(435) : LLCore::HttpLibcurl::completeRequest: HTTP pipelining possibly out of sync, request wanted: 599-1873 got: 0-18446744073709551615 url: http://virtual0.aiai.ed.ac.uk:9000/CAPS/3057f1d7-2697-4921-b329-4daeb2d951f8//?texture_id=372cd290-213a-48b1-9556-2fea6b032f8a [^]
2018-10-31T10:25:00Z WARNING: llcorehttp/_httplibcurl.cpp(435) : LLCore::HttpLibcurl::completeRequest: HTTP pipelining possibly out of sync, request wanted: 599-1873 got: 0-18446744073709551615 url: http://virtual0.aiai.ed.ac.uk:9000/CAPS/3057f1d7-2697-4921-b329-4daeb2d951f8//?texture_id=57922e43-ba62-43f2-b510-026b4b5044a6 [^]
2018-10-31T10:25:01Z WARNING: llcorehttp/_httplibcurl.cpp(435) : LLCore::HttpLibcurl::completeRequest: HTTP pipelining possibly out of sync, request wanted: 1535-7595 got: 0-18446744073709551615 url: http://virtual0.aiai.ed.ac.uk:9000/CAPS/3057f1d7-2697-4921-b329-4daeb2d951f8//?texture_id=badd0963-802c-4a4d-8c50-f805356f9d36 [^]
2018-10-31T10:25:01Z WARNING: llcorehttp/_httplibcurl.cpp(435) : LLCore::HttpLibcurl::completeRequest: HTTP pipelining possibly out of sync, request wanted: 599-9467 got: 0-18446744073709551615 url: http://virtual0.aiai.ed.ac.uk:9000/CAPS/3057f1d7-2697-4921-b329-4daeb2d951f8//?texture_id=c5b47d9a-d013-468d-ba55-614ce1fd5ffa [^]
2018-10-31T10:25:01Z WARNING: llcorehttp/_httplibcurl.cpp(435) : LLCore::HttpLibcurl::completeRequest: HTTP pipelining possibly out of sync, request wanted: 767-4121 got: 0-18446744073709551615 url: http://virtual0.aiai.ed.ac.uk:9000/CAPS/3057f1d7-2697-4921-b329-4daeb2d951f8//?texture_id=d8914f04-0b49-418e-9256-e77d98cfc4bf [^]
2018-10-31T10:25:01Z WARNING: llcorehttp/_httplibcurl.cpp(435) : LLCore::HttpLibcurl::completeRequest: HTTP pipelining possibly out of sync, request wanted: 1535-7595 got: 0-18446744073709551615 url: http://virtual0.aiai.ed.ac.uk:9000/CAPS/3057f1d7-2697-4921-b329-4daeb2d951f8//?texture_id=ec4d5c84-2c39-4d06-b2cc-c0ae8dbcc843 [^]
2018-10-31T10:25:01Z WARNING: llcorehttp/_httplibcurl.cpp(435) : LLCore::HttpLibcurl::completeRequest: HTTP pipelining possibly out of sync, request wanted: 599-1873 got: 0-18446744073709551615 url: http://virtual0.aiai.ed.ac.uk:9000/CAPS/3057f1d7-2697-4921-b329-4daeb2d951f8//?texture_id=1058428d-6fab-4e40-8913-00d6813854f7 [^]
2018-10-31T10:25:01Z WARNING: llcorehttp/_httplibcurl.cpp(435) : LLCore::HttpLibcurl::completeRequest: HTTP pipelining possibly out of sync, request wanted: 599-1873 got: 0-18446744073709551615 url: http://virtual0.aiai.ed.ac.uk:9000/CAPS/3057f1d7-2697-4921-b329-4daeb2d951f8//?texture_id=19403b7c-0cc5-4de5-b6dd-a4afd37c6b17 [^]
2018-10-31T10:25:05Z INFO: #Mesh; newview/llmeshrepository.cpp(5149) : LLMeshRepository::metricsUpdate: EventMarker {'fetches':i0,'reason':'Mesh Download Quiescent','scope':'Teleport','start':r567.865517,'stop':r567.865517,'sys_cpu':r0.000000,'teleports':i7,'user_cpu':r0.000000}
2018-10-31T10:25:07Z INFO: newview/llviewerdisplay.cpp(237) : display_stats: FPS: 20.90
2018-10-31T10:25:16Z INFO: newview/llworld.cpp(716) : LLWorld::removeRegion: Removing region 2316800.000000:2316800.000000
2018-10-31T10:25:16Z INFO: newview/lleventpoll.cpp(153) : LLEventPolling::Details::LLEventPollImpl::stop: requesting stop for event poll coroutine <2>
2018-10-31T10:25:16Z INFO: llmessage/llcorehttputil.cpp(1186) : LLCoreHttpUtil::HttpCoroutineAdapter::cancelSuspendedOperation: Canceling yielding request!
2018-10-31T10:25:16Z INFO: #Messaging; llmessage/message.cpp(1542) : LLMessageSystem::disableCircuit: LLMessageSystem::disableCircuit for 129.215.219.89:9000
2018-10-31T10:25:16Z WARNING: #Messaging; llmessage/message.cpp(1581) : LLMessageSystem::disableCircuit: Couldn't find circuit code for 129.215.219.89:9000
2018-10-31T10:25:16Z WARNING: newview/llworldmapmessage.cpp(163) : LLWorldMapMessage::processMapBlockReply: Invalid map image type returned! layer = 0
2018-10-31T10:25:16Z WARNING: #Teleport; newview/llagent.cpp(4659) : LLAgent::handleTeleportFailed: Agent handling teleport failure!
2018-10-31T10:25:16Z INFO: newview/llviewermessage.cpp(7019) : process_teleport_failed: Teleport error, message_id=Problems connecting to destination Openvue, reason: Connection between viewer and destination region could not be established.
2018-10-31T10:25:16Z WARNING: newview/lltoastalertpanel.cpp(184) : LLToastAlertPanel::LLToastAlertPanel: Alert: Teleport failed.
Problems connecting to destination Openvue, reason: Connection between viewer and destination region could not be established.

(0033330)
BillBlight (developer)
2018-10-31 03:39

This almost has to be something specific to the setup, or specific it certain setups .. I tested tonight on a windows standalone, on a linux standalone, on a osgrid connected region and my own grid,

I tp'd around endlessly for hours, just doing nothing but TP after TP and could not make it fail. You can make it fail first try, I can't make it fail after a hundred tries, a problem like that is going to make it very hard to track down ..
(0033331)
aiaustin (developer)
2018-10-31 03:48
edited on: 2018-10-31 03:49

Agreed... hopefully others will (eventually) spot the issue and we will work out what it is about the environment that differs.

@watcher64... let me check a couple of things.. forgetting OSGrid and Linux for now.. as those are quite different environments...

a) On the Windows 10 system, can you do a "winver" and check if it reports version 1803?

b) When you say Windows standalone, do you mean a simple setup with just OpenSim.exe running with a SQLite internal data base? I ask as all my grids have MySQL5.7 external data base, Robust.exe server and OpenSim.exe. We need to compare an environment something similar to that to pin this down, and then work out if it can affect other environments beyond the narrower one.

c) So, when you say your "own grid" is that a Windows 10 based one with Robust.exe and OpenSim.exe region server and does it use MySQL?

(c) would be the best comparison initially. I am still crossing my fingers and hoping all this mess is a trivial config issue or something simple in the Windows environment that I can correct. But its been a very serious issue for nearly 6 months now and its no fun at all.

(0033332)
BillBlight (developer)
2018-10-31 04:00
edited on: 2018-10-31 04:01

Yes simple standalone, tested both on win 10 and on linux winver 1803 NO FREAKING WINDOWS FIREWALL (burned that damn thing)

My entire grid runs on linux, and I only say this is relevant because it could be a MS change that is affecting the code as well, making it worse.

linux based firewall/router.
Gigabit networking.

The other things that I know have affected friends setups are , updates to anti-virus that include "network protection" , windows firewall rules getting reset(I would kill that thing , as a hardware router/firewall is better and makes it redundant).

Don't use SYSTEMIP in the region configs, I really wish they would remove that as even the wiki says to put the actual IP in there.

(0033333)
BillBlight (developer)
2018-10-31 04:06

Just a little network primer for people reading this that don't know ..


IF you are behind a nat router, all windows firewall does is slow your connection down, you are NAT'd only the ports you allow, if you have UPnP turned off, will be allowed in by your hardware firewall, and having a second "firewall" can cause very strange issues.

Also anti-virus with "network protection" can see the insane amount of UDP traffic that opensim puts out as a storm type attack and may throttle it or block it.

Now that http is more active in opensim this same protections can become a hindrance to opensimulator stable connections as they don't understand it.

*This is for the people that are not already aware of these things.
(0033334)
aiaustin (developer)
2018-10-31 04:45

Thanks for the notes @watcher64... as reported earlier I have tested with Windows Defender Firewall on and off. And the issues occur on a setup where we have the viewer machine and (single for tests) server (MySQL 5.7, Robust.exe and OpenSim.exe) both on same gigabit subnetwork with no external firewall involved.

As you note, in region.ini and all other .ini files we don't use SYSTEMIP and always use internally and externally resolvable DNS names or direct IP numbers.
(0033335)
BillBlight (developer)
2018-10-31 05:16
edited on: 2018-10-31 05:29

@aiaustin, is your region on 129.215.219.89:9004 up right now?

are any of the regions in that log up , 9001-9004

I can't find it in this mantis, is currently this running in grid mode? or Standalone?

Multiple regions per instance or single?

If multiple have you tested with each region in it's own instance?

I'm just puzzled because this is damn hard to replicate.

(0033336)
aiaustin (developer)
2018-10-31 05:50
edited on: 2018-10-31 06:39

@watcher.... yes, its our main grid "Openvue" and the region on 9004 is called "Vue-Port". It is running with dev master 508 as of today. That grid does show the same TP issues we are discussing here.

hop://virtual.aiai.ed.ac.uk:8002/Openvue/128/128/30 [^]
Try moving to and fro between just Vue-Port and Openvue regions

129.215.219.89 is rona.aiai.ed.ac.uk (aliases virtual.aiai.ed.ac.uk and virtual0.aiai.ed.ac.uk) and is the Openvue grid root server running MySQL5.7, Robust.exe and one OpenSim.exe instance with 4 regions

Region (root) # show regions
Name ID Position Size Port Ready? Estate
Openvue 9c8b6f8f-8178-4a69-92dc-9feba4646e6b 9050,9050 256x256 9000 Yes Vue
Sandbox 424a5f3f-ae96-4558-87b1-258575f9c1d2 9050,9049 256x256 9001 Yes Vue
Vue-Port bd09a792-eba5-11dc-95ff-0800200c9a66 9051,9051 256x256 9004 Yes Vue
OpenVCE e2017542-db2a-4d96-8380-59b5794c7b61 9050,9047 256x256 9005 Yes Vue

And for the errors that I have been reporting on I am using coll.aiai.ed.ac,.uk (alias ai.vue.ed.ac.uk) which is a Robust grid with MySQL5.7, Robust.exe and with a single instance of OpenSim.exe running two regions (AiLand and Edinburgh). I can test with separate instances for the two region if you really think that will make any difference.

(0033337)
aiaustin (developer)
2018-10-31 05:56
edited on: 2018-10-31 06:30

As a test I used the SAME SERVER that I have been testing AiLand grid with (coll.aiai.ed.ac.uk, alias ai.vue.ed.ac.uk, IP 129.215.219.74) and set up OSGrid an add-on region OpenSim.exe instance (using local SQLite data base with region content same as our normal AiLand grid) and latest 25-Oct-2018 dev master based OSGrid addon release.

That appears to work normally with no TP failures when I move between the test regions on the same server.. repeated about 20 times anyway.

Of course that is a VERY different setup and most of the non-region related services mostly come from hosts at osgrid.org rather than from our own servers. But it may help exclude some causes.

(0033339)
aiaustin (developer)
2018-10-31 06:02
edited on: 2018-10-31 07:39

Openvue grid now left running for a while with opensim-0.9.0.1-508-g292a9c9.zip (shows TP faults most of the time).

hop://virtual.aiai.ed.ac.uk:8002/Openvue/128/128/30 [^]
Try moving to and fro between just Vue-Port and Openvue regions

AiLand grid now set up with 0.9.0.1 stable release (shows TP faults but only occasionally)

hop://ai.vue.ed.ac.uk:8002/AiLand/128/128/25 [^]
Try moving to and fro between just Vue-Port and Edinburgh regions

(0033340)
BillBlight (developer)
2018-10-31 06:41

I have setup a test grid on my windows 10 machine, and can't make it fail as of yet, with latest master.
(0033343)
BillBlight (developer)
2018-10-31 06:52

spoke too soon, it worked for a while then started failing ..
(0033344)
aiaustin (developer)
2018-10-31 07:09
edited on: 2018-10-31 07:10

That's right.. good you have seen it too. Now what is it that is causing that issue compared to your working setups?

And as I observe, once it fails its in a real mess with child presence missing, etc.

I also just now tried AiLand grid using Robust.exe and TWO instances of OpenSim.exe each with a single region with all ports and host names in .ini file corrected and different http listeners, etc and it fails on first teleport attempt.

I will revert AiLand grid back now to a single OpenSim.exe instance 0.9.0.1 stable release now as that shows it well enough, it works fine on 0.8.2.1 stable and works better (but not all the time) with 0.9.0.1 stable. dev master shows the issue much more often (essentially most times).

I don't think its best to try to diagnose this on OSGrid avatars as OSGrid add on regions for me, even on the same server I have issues with, works for me.

(0033345)
Sheera Khan (reporter)
2018-10-31 07:10
edited on: 2018-10-31 10:21

@mac4kent: rest assured Watcher64 and aiaustin do know exactly how to contact Dan Banner and Ubit and presumably all the other people you mentioned ;-) You can well stop nagging and contributing some random noise without any new substantial information about the case. You are very well invited to report new findings though - Thank you for your understanding.

PS.: The comments I referred to are deleted by now. My comment was in no way directed against the original error report or any report of additional information you later provided :-)

(0033346)
aiaustin (developer)
2018-10-31 07:32
edited on: 2018-10-31 07:39

One more experiment.. belt and braces test really.. its never caused problems in a decade of running.. but you never know what might have changed in Windows 1803... so...

I converted one grid so ALL its .ini files, config files and region.ini files used the underlying external IP number rather than the registered DNS address or the properly registered aliases and that still fails on first teleport attempt on same server and with minimal config as used for other tests (using dev master 508).

P.S. @Sheera is correct :-) we are all in regular touch via these forums and issues and directly when it is helpful. We place things where possible in such Mantis issues so others can identify and resolve similar problems they have, even when issues like this are still open and causing some of us headaches. I tidied up the commentary a bit to remove time related status info as its already very long. Please continue to input if you have experienced this problem and can identify something about your configuration which helps.

(0033347)
BillBlight (developer)
2018-10-31 08:39

Well an update, back to not being able to make it fail, it fails if my viewer is on the same system as the server, but from an outside IP can't make it fail evidently...
(0033348)
UbitUmarov (administrator)
2018-10-31 08:55

Still can't make it fail.
Had a visit from bill and we seen a fail or tow, but my net is very bad and could explain it (I did lost con to irc during that )


meanwhile think I have a idea about those FS "desync" errors

2018-10-31T14:25:08Z WARNING: llcorehttp/_httplibcurl.cpp(435) : LLCore::HttpLibcurl::completeRequest: HTTP pipelining possibly out of sync, request wanted: 96590-577573 got: 0-18446744073709551615 url: http://ajld.dynip.sapo.pt:9000/CAPS/d18446f2-1738-49bf-9c5d-6b299c7dd1b9//?mesh_id=326c3528-a306-4ead-af32-a3a45a31015a [^]

looking a bit down:
2018-10-31T14:25:08Z WARNING: #CoreHttp; llcorehttp/_httppolicy.cpp(434) : LLCore::HttpPolicy::stageAfterCompletion: HTTP request 00000206E8055430 failed after 0 retries. Reason: Not Found (Http_404)

so FS did check the range of the reply before checking its error

see the same on textures (identical protocol)
this happened on HG, that mesh is a lbsa mesh, fs asked for it to my region.

i did log into lbsa, waited just a bit.
meanwhile fs did fecth that mesh header and decided it needed another LOD
when it finally asked for that LOD part, i was at my region, and it did asked it.
textures issue is identical.
(0033349)
aiaustin (developer)
2018-10-31 09:01
edited on: 2018-10-31 09:03

@watcher64.. I have failures if viewer is on a machine on same network.. I don't use the viewer on the server machine.

But I also see identical errors with same sort of frequency when I use a machine at home over a public network to the work (University) based server. I don't think that is a factor.. unless timing just happens to work in some cases and not others.

As noted elsewhere 0.8.2.1 stable release does not seem to have this issue at all using same servers and viewer arrangements. 0.9.0.1 stable works most of time, but does fail in same way if TPs are repeated enough. 0.9.1 dev master fails most of time.

@Ubit, thanks for those notes on the out of sync messages in Firestorm viewer.

(0033350)
UbitUmarov (administrator)
2018-10-31 12:03

AI what is your win 10 edition?
(0033352)
BillBlight (developer)
2018-10-31 20:39

@aiaustin, what edition though? There are significant differences in editions, home, pro, enterprise, yada yada ..
(0033354)
BillBlight (developer)
2018-11-01 01:42

Test server on windows http://173.24.58.40:8002/ [^] I'll leave it up for a while so others can test, but I can't make it fail .. This is on latest master code ..
(0033355)
aiaustin (developer)
2018-11-01 02:07

Microsoft Windows Pro version 1803 (OS Build 17134.376)

AiLand and Openvue grid, as well as our OSGrid addon regions are running on the same version and build of Windows.
(0033356)
BillBlight (developer)
2018-11-01 03:29
edited on: 2018-11-01 03:41

Tested for a while with aiaustin on clean windows, dev master, setup, could not make it fail, local or HG .. This seems to indicate it is not a systemic code issue but a "gotcha" somewhere in either config conversion, a particular update , or gremlins.

I'm leaving the test server up for a while as a "Proof of concept" .

(0033357)
tglion (reporter)
2018-11-01 07:15

Hi, on my grid (with suse-linux on Xeon-CPU, 128gb of ram) I have sometimes (but not often) TP issues like reported here. Most happen on VAR-Regions TP to normal sim and doing things on idle or sitting (while scripting, building etc.) after a while. Direct Tests after fresh login is always successfull with no tp-issues. Using last master on git.

If it can help, here the protocol of tp-fail:
(Source and destination-region are on different servers)

Source-Region:
2018-11-01 14:55:25,638 DEBUG [ENTITY TRANSFER MODULE]: Teleporting Thomas Goetz bc5ca947-c057-49f4-a9e3-fc2876b8d240 from Mining Desert to http://os2.gergrid.de:9013/ [^] (http://os2.gergrid.de:9013/ [^]) Dagoba/<116.9034, 51.17 78, 28.0511>
2018-11-01 14:55:25,640 DEBUG [REMOTE SIMULATION CONNECTOR]: QueryAccess to http://os2.gergrid.de:9013/agent/bc5ca947-c057-49f4-a9e3-fc2876b8d240/a56238ac-247c-6a15-5268-72394234621b/ [^] returned True, reason , version 0.6/0 .6
2018-11-01 14:55:25,640 DEBUG [ENTITY TRANSFER MODULE]: Mining Desert transfer protocol version to Dagoba is 0.6 / 0.6
2018-11-01 14:55:25,640 DEBUG [ENTITY TRANSFER MODULE]: Determined that region Dagoba at 7001,7003 size 256,256 needs new child agent for agent Thomas Goetz from Mining Desert
2018-11-01 14:55:25,640 DEBUG [SCENE PRESENCE]: Closing child agents. Checking 1 regions in Mining Desert
2018-11-01 14:55:25,640 DEBUG [HG ENTITY TRANSFER MODULE]: CreateAgent http://os2.gergrid.de:9013/ [^] http://os2.gergrid.de:9013/ [^]
2018-11-01 14:55:25,643 DEBUG [REMOTE SIMULATION CONNECTOR]: Creating agent at http://os2.gergrid.de:9013/ [^]
2018-11-01 14:55:25,659 DEBUG [ENTITY TRANSFER MODULE]: Sending new CAPS seed url http://os2.gergrid.de:9013/CAPS/a19a6259-886e-49de-8b9d-5c9f9ed60d3d0000/ [^] from Mining Desert to Thomas Goetz
2018-11-01 14:55:55,736 INFO [WEB UTIL]: Slow ServiceOSD request 290 PUT http://os2.gergrid.de:9013/agent/bc5ca947-c057-49f4-a9e3-fc2876b8d240/ [^] took 30065ms, 5ms writing(1 at Json; 4 at comp), 22813 bytes (219936 uncomp) : {"message_type":"AgentData","region_id":"d0d9b791-2d44-48db-a967-fe13b0ef3904","circuit_code":"0","agent_uuid":"bc5ca947-c057-49f4-a9e3-fc2876b8d240","session_uuid":"6e9a43df-4d1a-416f-aebf-1da8111018
2018-11-01 14:55:55,736 WARN [ENTITY TRANSFER MODULE]: UpdateAgent failed on teleport of Thomas Goetz to Dagoba. Keeping avatar in Mining Desert



Destination Region:
2018-11-01 14:56:39,199 DEBUG [SCENE]: Region Dagoba told of incoming child agent Thomas Goetz bc5ca947-c057-49f4-a9e3-fc2876b8d240 (circuit code 558350478, IP 37.201.192.142, viewer Singularity Alpha 64 1.8.7.6937, teleportflags (ViaLocation, Godlike), position <116.9034, 51.1778, 28.0511>. From region Mining Desert (d0d9b791-2d44-48db-a967-fe13b0ef3904) @ http://gergrid.de:8002/ [^]
2018-11-01 14:56:39,200 INFO [SCENE]: Region Dagoba authenticated and authorized incoming child agent Thomas Goetz bc5ca947-c057-49f4-a9e3-fc2876b8d240 (circuit code 558350478)
2018-11-01 14:56:39,201 DEBUG [CreateCaps]: new caps agent bc5ca947-c057-49f4-a9e3-fc2876b8d240, circuit 558350478, path a19a6259-886e-49de-8b9d-5c9f9ed60d3d, time 0
2018-11-01 14:56:39,201 DEBUG [VivoxVoice] OnRegisterCaps: agentID bc5ca947-c057-49f4-a9e3-fc2876b8d240 caps OpenSim.Framework.Capabilities.Caps
2018-11-01 14:56:39,225 WARN [CHILDAGENTDATAUPDATE] got packed appearance
2018-11-01 14:56:39,271 DEBUG [SCENE]: Incoming child agent update for bc5ca947-c057-49f4-a9e3-fc2876b8d240 in Dagoba
2018-11-01 14:57:09,280 WARN [SCENE PRESENCE]: Did not find presence with id bc5ca947-c057-49f4-a9e3-fc2876b8d240 in Dagoba before timeout
2018-11-01 14:57:09,280 INFO [LOGHTTP] Slow handling of 9967 PUT /agent/bc5ca947-c057-49f4-a9e3-fc2876b8d240/ from 94.130.140.177:55435 took 30060ms
2018-11-01 14:57:09,282 DEBUG [AGENT HANDLER]: >>> DELETE <<< RegionID: a56238ac-247c-6a15-5268-72394234621b; from: 94.130.140.177; auth_code: 6e9a43df-4d1a-416f-aebf-1da8111018f4
2018-11-01 14:57:09,283 DEBUG [SCENE]: Called CloseClient() with agent ID bc5ca947-c057-49f4-a9e3-fc2876b8d240 but no such presence is in Dagoba

Cheers!
(0033358)
mewtwo0641 (reporter)
2018-11-01 07:31

I can confirm tglion's observation about being idle for a while seems to be one of the key things with this issue. TP seems fine for a while directly after a fresh log in; but if you settle in for a while and build, hang out, script, etc or otherwise just don't try to leave the region that you're in for a while and then attempt to leave; it has a decent chance for failing. It seems random as to exactly how long one needs to wait though... I've had it happen in as little as 5 or 10 minutes idle after login or sometimes won't see the issue for as long as a couple hours.
(0033359)
mike.chase (reporter)
2018-11-01 09:42
edited on: 2018-11-01 09:42

I'm also experiencing this problem though not in as repeatable a way as Ai is. So this might be timing related. My setup is Ubuntu 18.04 Mono 5.16 running dev from mid October. 95% of the time teleports are relabiable and super fast. When it fails its exactly as described above. In general it appears that the transfer is amost entirely complete but never finishes and eventually the client times out and/or crashes.

(0033360)
aiaustin (developer)
2018-11-01 09:48

Just to let you know I have gone back to every .ini file and got a basic system working with minimal .ini change requirements and using same grid data base apparently without TP issues. I am gradually reintroducing the .ini changes to get my normal setup back. But I have managed to make changes that did immediately reintroduce the issue. I just need to work out which specific change. More when I can report.
(0033361)
mike.chase (reporter)
2018-11-01 09:53

Oh very interesting. Just to add since Bill asked early in the thread we do run the Gloebits module. I am also seeing cases with very slow attachments and mesh rezzing. Physics is ubOde with the ubOde Mesher. Ai if you do narrow down things to a config change I can check my environment also. And if I can supply any info on our config I'm happy to.
(0033362)
aiaustin (developer)
2018-11-01 10:05
edited on: 2018-11-01 10:06

Will do Mike, and thanks for feedback. I am not running Gloebits as I mentioned earlier.

Status of testing is throwing suspicion on OpenSim.ini [XMLRPC] section...

    ; XmlRpcRouterModule = "XmlRpcRouterModule"
    ; XmlRpcPort = 20800

works. But uncommenting those two lines... as I had in my usual configurations... seems to instantly reintroduce the issue. More to come.

(0033363)
BillBlight (developer)
2018-11-01 10:10

The idle thing does not seem to be an issue I let my avatar sit idle for over 2 hours and was able to TP without an issue ... So I can see how this issue is very vexing for some. But it seems to not be easily reproducible until you start having it for some yet unknown reason.
(0033364)
aiaustin (developer)
2018-11-01 10:15

I just made two changes to my OpenSim.ini on our main Openvue grid region servers... commenting out two lines which were uncommented before...

 [XMLRPC]

     ; XmlRpcRouterModule = "XmlRpcRouterModule"
     ; XmlRpcPort = 20800

and it works for TP instantly on 10 attempts. Put those lines back uncommented and it fails on first attempt.

Can someone look at their OpenSim.ini on a system that normally works and assuming the lines have been left commented please try to uncomment the two lines on their working setup (and ensure port 20800 is open through their firewall of course) and see if that has any effect.
(0033365)
BillBlight (developer)
2018-11-01 10:16

@aiaustin , now that is very interesting, as I don't use that, I have my scripts that need external access post via php to a DB where I track them there. so I don't use or need those concurrent calls ..
(0033366)
aiaustin (developer)
2018-11-01 10:17
edited on: 2018-11-01 10:17

I am not sure this is the only issue and I have more to reintroduce to get my grid back to its usual state, but if I can turn on and off this issue with these two lines being uncommented or left commented.

That would also explain why my OSGrid addon regions work on the same setup here... as those lines do not appear at all in the OSGrid OpenSim.ini file.

(0033367)
aiaustin (developer)
2018-11-01 10:18
edited on: 2018-11-01 10:30

XMLRPC on port 20800 is not a critical thing for me... we used to use this a lot when we had some intelligent systems and AI planners connected to our I-Room Intelligent Spaces... way before the time of more recent mechanisms for HTTP listeners in world.

I may run up the old configs with these 2 lines removed and leave that running as I have to knock off just now.

But I may persist with the fresh .ini refresh and only put back config changes I feel are necessary

(0033368)
mike.chase (reporter)
2018-11-01 10:23

FWIW, I have the XMLRPC module entirely commented out. So its not active. Though this still could be something with network config and/or timing.
(0033369)
aiaustin (developer)
2018-11-01 10:32
edited on: 2018-11-01 13:09

Mike.. (or perhaps watcher64?) if your test environment allows it without messing anything up are you able to uncomment those two lines and if it introduces the issue that would be good.

I just changed Openvue and AiLand grids to comment those two lines out in their OpenSim.ini files and I appear to be working fine on 20 TP attempts.

I need to stop today, but will do some texture loading speed tests with cleared caches with those lines in and out too to see if the slow texture loading issue is related later.

(0033370)
BillBlight (developer)
2018-11-01 11:17
edited on: 2018-11-01 11:19

Well we have at least one point to look enabling the XMLRPC router managed to give me TP timeouts on the test setup ..

I'm going to take the test grid down for a while, until a new direction to look comes up ..

(0033371)
UbitUmarov (administrator)
2018-11-01 13:37

Thanks for all this testing.
I will try to play with that xmlrpc and see..
(0033372)
UbitUmarov (administrator)
2018-11-01 15:26
edited on: 2018-11-01 15:29

Ok a I made a change on master
plz test with
    XmlRpcRouterModule = "XmlRpcRouterModule"
    XmlRpcPort = 20800

uncommented to return to the problem condition

(0033373)
BillBlight (developer)
2018-11-01 15:31
edited on: 2018-11-01 16:25

Tested on my test server with XmlRpcRouterModule enabled, and where it was failing, it is not now. Seems like progress ...

UPDATE: Well over 100 TP's now no fails in , out and between regions with the xml router enabled . No fails.

(0033374)
mewtwo0641 (reporter)
2018-11-01 17:38

Made the change suggested in OpenSim.ini and also tested with the latest master revision. It seems to be markedly improved (Or perhaps I just got lucky) but eventually after about an hour of testing I was able to make it fail again. My testing consisted of randomly changing attachments (Scripted and non-scripted), scripting, occasionally teleporting / region crossing back and forth between places, logging in and out with multiple different avs on multiple different computers, etc. Just normal everyday stuff.

Viewer Error Message:

[17:29] Could not teleport.
Problems connecting to destination Test Region, reason: Connection between viewer and destination region could not be established.

OpenSim Log:

19:28:52 - [SCENE]: Incoming child agent update for 5df367f6-50fb-4e4f-ad7a-b9c236083baf in Test Region
19:29:22 - [SCENE PRESENCE]: Did not find presence with id 5df367f6-50fb-4e4f-ad7a-b9c236083baf in Test Region before timeout
19:29:22 - [ENTITY TRANSFER MODULE]: UpdateAgent failed on teleport of Test User to Test Region. Keeping avatar in Test Region 2
19:29:22 - [SCENE]: Called CloseClient() with agent ID 5df367f6-50fb-4e4f-ad7a-b9c236083baf but no such presence is in Test Region
(0033375)
UbitUmarov (administrator)
2018-11-01 20:15

several reasons for tp fails still
just should not be 100% fails like AI has
(0033376)
mewtwo0641 (reporter)
2018-11-01 21:11

I hadn't noticed a 100% failure rate, but before the recent changes on master it had been still pretty high; I'd estimate 50-60% of the time. It does seem quite a bit better now; although I'm confused as to whether I should leave the XMLRPC module enabled or set back to its default of disabled. I've never had a reason to use it so I always left it at default setting.

As a side note to this issue, occasionally when doing a region cross, the agent will just fly off uncontrollably as if there were going to be an issue with crossing; But at least now it does seem that it eventually recovers although it can take a while; around 30 to 60 seconds. Sometimes it recovers successfully and the next region cross/teleport will work fine, but other times it will appear that it recovered successfully and the next region cross/teleport will completely fail and kick the user from the sim.

I agree that there should not be 100% fail rate with teleport but I am mentioning these things that I have observed because this mantis has been largely focused on the fact that the issue has been frequently intermittent (If I understood the mantis correctly that is).
(0033377)
BillBlight (developer)
2018-11-01 21:22

@mewtwo , you must have read wrong, failure rate is much higher with the XmlRpcRouter enabled ..

Testing current code we can't make it fail with it disabled ..
(0033378)
mewtwo0641 (reporter)
2018-11-01 21:28

@watcher64 - Oooh okay! Yes I was a bit confused with that lol. So I'll turn it back off and test again in a bit.
(0033379)
aiaustin (developer)
2018-11-02 03:01

@Ubit, thanks for identifying the changes for the XMLRPC port issue... I tested AiLand grid with latest dev master with your changes (512 - 0.9.1 snail dev master - downloading as opensim-0.9.0.1-512-g3e6342e.zip)... with these lines uncommented in OpenSim.ini [XMLRPC] section...
 
    XmlRpcRouterModule = "XmlRpcRouterModule"
    XmlRpcPort = 20800

I am pleased to report TPs now work quickly and reliably on a few dozen tests.

For everyone, please note that I did not report 100% TP failure rates on the cut down test setup I created to help identify the problem. Typically things failed on second attempt, and sometimes worked after the failed attempt, and other times that left the avatar unable to teleport. Sometimes it did fail on first attempt between the two regions on the test server. So I would say 60% or so failure rates.
(0033383)
UbitUmarov (administrator)
2018-11-02 05:14

the XmlRpcPort != 0 enables support for the lsl remote data functions like llOpenRemoteDataChannel etc.

This is no longer recommended at SL, replaced of lsl http features. We should possible follow this recomendation not using it on new scripts

XmlRpcRouterModule may additionally trigger a custom event on scripts with the opened full URI string

So you only need them if you do have old scripts using this features

AI sure, not 100% just 99.9% when i went there testing :)
(0033384)
mike.chase (reporter)
2018-11-02 05:17

Yeah I'm not comfortable with this just becoming "TP failures happen when you enable the XMLRPC module". There was some early discussion around the Gloebits module also causing it which I think I'm seeing and in that case I'm pretty sure its due to blocking or long running calls happening from the event handler in the UDP CompleteMovement call. I suspect there are other cases as well where the current code exhibits this behavior.
(0033385)
UbitUmarov (administrator)
2018-11-02 05:40

Far from "TP failures happen when you enable the XMLRPC module"
Original report may not even be related.
But it was found and was severe.
(0033386)
aiaustin (developer)
2018-11-02 05:42

Good point Mike. Hopefully identifying the cause here could open up a few avenues to consider for some of the remaining issues.
(0033387)
mike.chase (reporter)
2018-11-02 06:26

Sorry I wasn't try to downplay the testing efforts and the found issue with XMLRPC. Clearly it's a consistent failing case and was severe and I'm super happy its fixed. I just wanted to indicate that the root problem originally reported still exists though more intermittently. That is of course the harder case to run down since you can't easily reproduce it in a test environment.
(0033390)
aiaustin (developer)
2018-11-02 09:57

Understood and I did not take the comment as negative at all. You are right to point out we still have open issues in this area.
(0033391)
BillBlight (developer)
2018-11-02 10:04
edited on: 2018-11-02 10:11

I just want to point out that this is how you solve problems, you test, keep testing, provide info and more info, test some more. When you just keep screaming, "It's still broken" , that does not help anybody fix anything other than not fixing their blood pressure ...

Of course the status still needs to be reported, but does not help to constantly restate the problem.

(0033416)
aiaustin (developer)
2018-11-06 07:45

Even using dev master as at 2018-11-05 with TP fail improvements when some avatars log off and try to return to their home grids I do still see red exception error messages - is this something we might except to catch?

[ENTITY TRANSFER MODULE]: Exception on teleport of … Object reference not set to an instance of an object.

---

E.g.
20:37:58 - [REMOTE SIMULATION CONNECTOR]: Failed to create agent Alfie.Boy @misfitzgrid.com:8002 at remote simulator
20:37:58 - [ENTITY TRANSFER MODULE]: Teleport of Alfie.Boy @misfitzgrid.com:8002 from Vue-Port to Vue-Port was refused because Service request failed: The operation has timed out
20:37:58 - [ENTITY TRANSFER MODULE]: Exception on teleport of Alfie.Boy @misfitzgrid.com:8002 from <39.51586, 69.47474, 1.065703>@Vue-Port to <128, 128, 25>@Vue-Port: Object reference not set to an instance of an object. at OpenSim.Region.CoreModules.Framework.EntityTransfer.EntityTransferModule.TransferAgent_V2(ScenePresence sp, AgentCircuitData agentCircuit, GridRegion reg, GridRegion finalDestination, IPEndPoint endPoint, UInt32 teleportFlags, Boolean OutSideViewRange, EntityTransferContext ctx, String& reason) in d:\Temp\opensim-0.9.0.1-514-g9e274ce\OpenSim\Region\CoreModules\Framework\EntityTransfer\EntityTransferModule.cs:line 1124
   at OpenSim.Region.CoreModules.Framework.EntityTransfer.EntityTransferModule.DoTeleportInternal(ScenePresence sp, GridRegion reg, GridRegion finalDestination, Vector3 position, Vector3 lookAt, UInt32 teleportFlags) in d:\Temp\opensim-0.9.0.1-514-g9e274ce\OpenSim\Region\CoreModules\Framework\EntityTransfer\EntityTransferModule.cs:line 842
   at OpenSim.Region.CoreModules.Framework.EntityTransfer.EntityTransferModule.TeleportAgentToDifferentRegion(ScenePresence sp, UInt64 regionHandle, Vector3 position, Vector3 lookAt, UInt32 teleportFlags, GridRegion& finalDestination) in d:\Temp\opensim-0.9.0.1-514-g9e274ce\OpenSim\Region\CoreModules\Framework\EntityTransfer\EntityTransferModule.cs:line 571
   at OpenSim.Region.CoreModules.Framework.EntityTransfer.EntityTransferModule.Teleport(ScenePresence sp, UInt64 regionHandle, Vector3 position, Vector3 lookAt, UInt32 teleportFlags) in d:\Temp\opensim-0.9.0.1-514-g9e274ce\OpenSim\Region\CoreModules\Framework\EntityTransfer\EntityTransferModule.cs:line 418
(0033417)
BillBlight (developer)
2018-11-06 07:52
edited on: 2018-11-06 07:53

It is possible that is a transfer to an older version of opensim without the TP improvements, if only one end has the TP improvement you could still see things like this ...

(0033418)
aiaustin (developer)
2018-11-06 08:49
edited on: 2018-11-06 09:18

Noted Bill... Foreign user HG inbound is not allowed for the target grid in question at misfitzgrid.com:8002 so I can't check what version they are running.

But its always I feel worth noting red reported errors showing on my end.. i.e. the exception occurs on latest dev master code and it would be good to catch things where we can to give nicer messages.

Maybe I am just averse to red messages :-)

(0033424)
mike.chase (reporter)
2018-11-06 17:15

I have a fix for the Gloebit related issue that may also give a hint as to what's happening to others.

This is the updated OnMovementCompleted function in the Gloebit money Module. The change is to run the body of the function on a thread and return immediately. OnCompleteMovement is literally called from inside a UDP packet handler and if the function being called adds delay (as the Gloebit function does) the ack gets lost. There are a few other things hooking this function that could use some inspection. Upcalling to things that could block (i.e. do ANYTHING more than set a variable) from the UDP packet code is probably a recipe for teleport failure (and other things).


        private void OnCompleteMovementToRegion(IClientAPI client, bool blah) {
            System.Threading.ThreadPool.QueueUserWorkItem(delegate {
                // TODO: may now be albe to remove client from these funcs (since we moved this out of OnNewClient, but this still might be simpler.
                m_log.DebugFormat("[GLOEBITMONEYMODULE] OnCompleteMovementToRegion for {0} with bool {1}", client.AgentId, blah);
                m_log.DebugFormat("[GLOEBITMONEYMODULE] OnCompleteMovementToRegion SessionId:{0} SecureSessionId:{1}", client.SessionId, client.SecureSessionId);

                GloebitUser user = GloebitUser.Get(m_key, client.AgentId);
                // If authed, update balance immediately
                if (user.IsAuthed()) {
                    // Don't send Buy Gloebits messaging so that we don't spam
                    UpdateBalance(client.AgentId, client, 0);
                }
                if (user.IsNewSession(client.SessionId)) {
                    // Send welcome messaging and buy gloebits messaging or auth messaging
                    SendNewSessionMessaging(client, user);
                }
            }, null);
        }
(0033443)
UbitUmarov (administrator)
2018-11-07 10:54

Thanks Mike, that is in line with what already told Gloebit team.
Several "events" are very time critical and can only have very light operations, triggering delayed slower actions.

Most of the little improvements on 0.9x region crossings where just reducing load that did pile up on those events...
(0033512)
Balpien (reporter)
2018-11-17 13:19

Mike, WRT the Gloebit money module dll, which version did you find the blocking calls problem? I see GB is up to build 75, September 2018. Is that the one?

I too am seeing the problems reported in this mantis on Discovery Grid. Will add more details shortly.
(0033513)
BillBlight (developer)
2018-11-17 13:21

@Balpien, the current GB dll, has seen this issue for some people, but the issue , gloebit withstanding seems to be fixed ...

Mikes patch to the self compiled GB module I use seems to also correct the issue.
(0033514)
mike.chase (reporter)
2018-11-17 13:23

Yes, I'm running 0.9 dev. I commented the github repo for the Gloebit module as well. I'm building it now from source obviously. But I suspect the issue is in any version targeting 0.9 and probably earlier versions as well.
(0033515)
mike.chase (reporter)
2018-11-17 13:33

Note I'm pretty sure there are still some things being run on OnCompleteMovement that can cause this issue. But the Gloebit one is definitely a trouble spot.
(0033519)
colosi (reporter)
2018-11-19 11:30

We have opened two issues in our github repo regarding this issue and hope to get to them later this week
https://github.com/gloebit/opensim-moneymodule-gloebit/issues/73 [^]
https://github.com/gloebit/opensim-moneymodule-gloebit/issues/74 [^]

Please feel free to comment there to advise. Also, as our code is now open source, people can clone our repo, branch and patch, and submit a pull request via github for us to review and pull your fix in. That will help us get things like this fixed faster in the future.

Couple of questions I have with this issue:
- I had planned to create an asynchronous GetBalance web request and call that to fix this.
- Mike has fixed it by queuing our synchronous call on a separate thread
- Do we need to do both of these? If not, is one preferred to the other?

Considering the future architecture of OpenSim, it would be great to have an event for non-critical operations. There's no need for our update balance call to even be initiated while critical teleport operations are still completing. It would be great to have a separate event that is *truly* upon completion of entering a new region. That could either be achieved by moving the critical functionality to a new event which is called just before this one, or by creating a new post-completion even that is called right after the existing one and which we could move our call to.
(0033629)
colosi (reporter)
2018-12-14 18:16

We've followed Mike's suggestion and fixed this via the worker thread pool. Master on GitHub contains the fix and today we released new DLLs with the fix. Please give the update a try and let us know if there are still any teleport issues.

https://github.com/gloebit/opensim-moneymodule-gloebit/ [^]
http://dev.gloebit.com/opensim/downloads/ [^]

- Issue History
Date Modified Username Field Change
2018-09-26 13:04 mac4kent New Issue
2018-09-28 09:11 mewtwo0641 Note Added: 0033099
2018-10-01 02:27 aiaustin Note Added: 0033106
2018-10-01 02:28 aiaustin Note Edited: 0033106 View Revisions
2018-10-01 02:29 aiaustin Note Edited: 0033106 View Revisions
2018-10-01 03:02 aiaustin Note Edited: 0033106 View Revisions
2018-10-09 09:41 aiaustin Note Added: 0033155
2018-10-09 09:41 aiaustin File Added: 2018-10-09-ailand-teleport-issue-logs.txt
2018-10-09 09:43 aiaustin Note Edited: 0033155 View Revisions
2018-10-09 10:34 aiaustin Note Edited: 0033155 View Revisions
2018-10-09 10:50 aiaustin Note Edited: 0033106 View Revisions
2018-10-09 12:09 aiaustin Note Edited: 0033155 View Revisions
2018-10-10 23:02 BillBlight Note Added: 0033156
2018-10-10 23:03 BillBlight Note Edited: 0033156 View Revisions
2018-10-10 23:05 BillBlight Note Added: 0033157
2018-10-10 23:06 BillBlight Note Edited: 0033157 View Revisions
2018-10-11 01:25 aiaustin Note Added: 0033160
2018-10-11 01:27 aiaustin Note Edited: 0033160 View Revisions
2018-10-11 01:30 aiaustin Note Edited: 0033160 View Revisions
2018-10-11 02:06 aiaustin Note Added: 0033161
2018-10-11 02:06 aiaustin Note Edited: 0033161 View Revisions
2018-10-11 09:20 mac4kent Note Added: 0033162
2018-10-11 09:20 BillBlight Note Added: 0033163
2018-10-11 10:20 aiaustin Note Added: 0033164
2018-10-11 10:22 aiaustin Note Edited: 0033164 View Revisions
2018-10-11 10:24 aiaustin Note Edited: 0033164 View Revisions
2018-10-23 03:47 aiaustin Note Added: 0033245
2018-10-23 03:49 aiaustin Note Edited: 0033245 View Revisions
2018-10-23 03:51 aiaustin Note Edited: 0033245 View Revisions
2018-10-23 03:51 aiaustin Note Edited: 0033245 View Revisions
2018-10-23 04:12 aiaustin Note Added: 0033246
2018-10-23 04:13 aiaustin Note Edited: 0033246 View Revisions
2018-10-23 04:14 aiaustin Note Edited: 0033246 View Revisions
2018-10-23 04:14 aiaustin Note Edited: 0033246 View Revisions
2018-10-23 04:25 aiaustin Note Edited: 0033164 View Revisions
2018-10-23 04:47 aiaustin Note Added: 0033247
2018-10-23 04:48 aiaustin Note Edited: 0033247 View Revisions
2018-10-23 04:52 aiaustin Note Edited: 0033247 View Revisions
2018-10-23 04:54 aiaustin Note Edited: 0033247 View Revisions
2018-10-23 07:07 aiaustin Note Added: 0033248
2018-10-23 08:27 aiaustin Note Edited: 0033248 View Revisions
2018-10-23 09:04 aiaustin Note Edited: 0033248 View Revisions
2018-10-24 03:50 aiaustin Note Added: 0033261
2018-10-24 03:51 aiaustin Note Edited: 0033261 View Revisions
2018-10-24 03:52 aiaustin Note Edited: 0033261 View Revisions
2018-10-24 03:53 aiaustin Note Edited: 0033248 View Revisions
2018-10-24 04:25 mac4kent Note Added: 0033262
2018-10-26 04:11 aiaustin Note Added: 0033265
2018-10-26 04:13 aiaustin Priority normal => urgent
2018-10-26 04:13 aiaustin Severity minor => block
2018-10-26 04:13 aiaustin Status new => confirmed
2018-10-26 04:13 aiaustin Product Version 0.9.0.1 => master (dev code)
2018-10-26 04:13 aiaustin Target Version => master (dev code)
2018-10-26 04:13 aiaustin Additional Information Updated View Revisions
2018-10-26 04:13 aiaustin Note Edited: 0033265 View Revisions
2018-10-26 04:47 aiaustin Note Edited: 0033265 View Revisions
2018-10-26 04:51 aiaustin Note Added: 0033266
2018-10-26 05:01 aiaustin Note Added: 0033267
2018-10-28 09:03 UbitUmarov Note Added: 0033279
2018-10-28 09:44 aiaustin Note Added: 0033280
2018-10-28 09:54 aiaustin Note Edited: 0033280 View Revisions
2018-10-28 10:00 aiaustin Note Added: 0033281
2018-10-28 10:01 aiaustin Note Edited: 0033281 View Revisions
2018-10-28 10:05 aiaustin Note Added: 0033282
2018-10-28 10:09 aiaustin Note Edited: 0033282 View Revisions
2018-10-28 10:09 aiaustin Note Edited: 0033282 View Revisions
2018-10-28 10:11 UbitUmarov Note Added: 0033283
2018-10-28 10:12 aiaustin Note Edited: 0033280 View Revisions
2018-10-28 10:13 aiaustin Note Edited: 0033282 View Revisions
2018-10-28 10:14 aiaustin Note Added: 0033284
2018-10-28 10:25 UbitUmarov Note Added: 0033285
2018-10-28 10:49 UbitUmarov Note Added: 0033286
2018-10-28 11:20 aiaustin Note Added: 0033287
2018-10-28 14:50 aiaustin Note Edited: 0033287 View Revisions
2018-10-28 22:18 paela argus Note Added: 0033288
2018-10-28 22:19 paela argus Note Edited: 0033288 View Revisions
2018-10-28 22:23 mewtwo0641 Note Added: 0033289
2018-10-29 02:45 aiaustin Note Added: 0033290
2018-10-29 02:46 aiaustin File Added: 2018-10-29-Firestorm-Console-OpenSim-507-TP-Issue-1.png
2018-10-29 02:46 aiaustin File Added: 2018-10-29-Firestorm-Console-OpenSim-507-TP-Issue-2.png
2018-10-29 02:48 aiaustin Note Edited: 0033290 View Revisions
2018-10-29 03:41 aiaustin Note Added: 0033291
2018-10-29 03:53 aiaustin Note Added: 0033292
2018-10-29 03:53 aiaustin Note Edited: 0033292 View Revisions
2018-10-29 03:59 aiaustin Note Edited: 0033292 View Revisions
2018-10-29 03:59 aiaustin Note Edited: 0033291 View Revisions
2018-10-29 04:00 aiaustin Note Edited: 0033291 View Revisions
2018-10-29 04:10 aiaustin Note Edited: 0033292 View Revisions
2018-10-29 04:17 aiaustin Note Edited: 0033292 View Revisions
2018-10-29 04:34 aiaustin Relationship added related to 0008304
2018-10-29 05:08 aiaustin Note Added: 0033295
2018-10-29 05:13 aiaustin Note Edited: 0033295 View Revisions
2018-10-29 05:16 aiaustin Note Added: 0033296
2018-10-29 05:17 aiaustin Note Edited: 0033296 View Revisions
2018-10-29 05:28 aiaustin Note Added: 0033297
2018-10-29 08:26 paela argus Note Added: 0033298
2018-10-29 08:36 aiaustin Note Added: 0033299
2018-10-29 09:17 aiaustin Note Added: 0033300
2018-10-29 09:34 aiaustin Note Edited: 0033300 View Revisions
2018-10-29 09:36 aiaustin Note Added: 0033301
2018-10-29 09:38 aiaustin Note Edited: 0033301 View Revisions
2018-10-29 09:51 UbitUmarov Relationship deleted related to 0008304
2018-10-29 10:02 UbitUmarov Note Added: 0033303
2018-10-29 13:47 aiaustin Note Added: 0033304
2018-10-29 13:51 aiaustin Note Edited: 0033304 View Revisions
2018-10-29 13:53 aiaustin Note Edited: 0033304 View Revisions
2018-10-29 13:59 aiaustin Note Edited: 0033304 View Revisions
2018-10-29 13:59 aiaustin Note Edited: 0033304 View Revisions
2018-10-30 02:47 UbitUmarov Note Added: 0033305
2018-10-30 02:56 UbitUmarov Note Added: 0033306
2018-10-30 03:07 aiaustin Note Added: 0033307
2018-10-30 03:15 aiaustin Note Edited: 0033307 View Revisions
2018-10-30 03:36 UbitUmarov Note Added: 0033308
2018-10-30 03:40 aiaustin Note Added: 0033309
2018-10-30 03:41 aiaustin Note Added: 0033310
2018-10-30 03:42 aiaustin Note Edited: 0033309 View Revisions
2018-10-30 04:08 UbitUmarov Note Added: 0033311
2018-10-30 04:11 UbitUmarov Note Added: 0033312
2018-10-30 05:30 aiaustin Note Added: 0033313
2018-10-30 05:33 aiaustin Note Edited: 0033313 View Revisions
2018-10-30 05:37 aiaustin Note Edited: 0033313 View Revisions
2018-10-30 05:54 aiaustin Note Added: 0033314
2018-10-30 05:56 aiaustin Note Edited: 0033314 View Revisions
2018-10-30 05:57 aiaustin Note Edited: 0033314 View Revisions
2018-10-30 06:09 aiaustin Note Added: 0033315
2018-10-30 06:17 aiaustin Note Added: 0033316
2018-10-30 06:39 aiaustin Note Added: 0033317
2018-10-30 06:53 aiaustin Note Edited: 0033317 View Revisions
2018-10-30 07:13 aiaustin Note Edited: 0033317 View Revisions
2018-10-30 07:17 aiaustin Note Edited: 0033317 View Revisions
2018-10-30 07:19 aiaustin Note Added: 0033318
2018-10-30 07:39 aiaustin Note Edited: 0033317 View Revisions
2018-10-30 07:40 aiaustin Note Edited: 0033317 View Revisions
2018-10-30 07:48 aiaustin Note Added: 0033319
2018-10-30 07:50 aiaustin Note Edited: 0033319 View Revisions
2018-10-30 07:51 aiaustin Note Edited: 0033319 View Revisions
2018-10-30 07:53 aiaustin Note Edited: 0033319 View Revisions
2018-10-30 07:55 mac4kent Note Added: 0033320
2018-10-30 08:09 aiaustin Note Added: 0033321
2018-10-30 08:10 aiaustin Note Edited: 0033321 View Revisions
2018-10-30 08:10 aiaustin Note Edited: 0033321 View Revisions
2018-10-30 08:23 mac4kent Note Added: 0033322
2018-10-30 08:29 aiaustin Note Edited: 0033317 View Revisions
2018-10-30 10:15 UbitUmarov Note Added: 0033323
2018-10-30 10:17 mac4kent Note Added: 0033324
2018-10-30 12:54 aiaustin Note Added: 0033325
2018-10-30 12:54 aiaustin Note Edited: 0033325 View Revisions
2018-10-30 13:14 aiaustin Note Edited: 0033325 View Revisions
2018-10-30 13:15 aiaustin Note Edited: 0033325 View Revisions
2018-10-30 13:15 aiaustin Note Edited: 0033325 View Revisions
2018-10-30 13:59 aiaustin Note Edited: 0033325 View Revisions
2018-10-30 13:59 aiaustin Note Edited: 0033325 View Revisions
2018-10-30 21:58 mac4kent Note Added: 0033326
2018-10-30 22:03 BillBlight Note Added: 0033327
2018-10-30 22:03 BillBlight Note Edited: 0033327 View Revisions
2018-10-30 22:05 BillBlight Note Added: 0033328
2018-10-31 03:29 aiaustin Note Added: 0033329
2018-10-31 03:30 aiaustin Note Edited: 0033329 View Revisions
2018-10-31 03:39 BillBlight Note Added: 0033330
2018-10-31 03:48 aiaustin Note Added: 0033331
2018-10-31 03:49 aiaustin Note Edited: 0033331 View Revisions
2018-10-31 04:00 BillBlight Note Added: 0033332
2018-10-31 04:01 BillBlight Note Edited: 0033332 View Revisions
2018-10-31 04:06 BillBlight Note Added: 0033333
2018-10-31 04:45 aiaustin Note Added: 0033334
2018-10-31 05:16 BillBlight Note Added: 0033335
2018-10-31 05:23 BillBlight Note Edited: 0033335 View Revisions
2018-10-31 05:29 BillBlight Note Edited: 0033335 View Revisions
2018-10-31 05:50 aiaustin Note Added: 0033336
2018-10-31 05:52 aiaustin Note Edited: 0033336 View Revisions
2018-10-31 05:56 aiaustin Note Added: 0033337
2018-10-31 05:58 mac4kent Note Added: 0033338
2018-10-31 06:02 aiaustin Note Added: 0033339
2018-10-31 06:30 aiaustin Note Edited: 0033337 View Revisions
2018-10-31 06:30 aiaustin Note Edited: 0033336 View Revisions
2018-10-31 06:32 aiaustin Note Edited: 0033336 View Revisions
2018-10-31 06:37 aiaustin Note Edited: 0033336 View Revisions
2018-10-31 06:38 aiaustin Note Edited: 0033339 View Revisions
2018-10-31 06:39 aiaustin Note Edited: 0033336 View Revisions
2018-10-31 06:41 BillBlight Note Added: 0033340
2018-10-31 06:46 mac4kent Note Added: 0033341
2018-10-31 06:52 BillBlight Note Added: 0033343
2018-10-31 07:09 aiaustin Note Added: 0033344
2018-10-31 07:10 Sheera Khan Note Added: 0033345
2018-10-31 07:10 aiaustin Note Edited: 0033344 View Revisions
2018-10-31 07:11 Sheera Khan Note Edited: 0033345 View Revisions
2018-10-31 07:32 aiaustin Note Added: 0033346
2018-10-31 07:32 aiaustin Note Edited: 0033346 View Revisions
2018-10-31 07:34 aiaustin Note Deleted: 0033338
2018-10-31 07:34 aiaustin Note Deleted: 0033162
2018-10-31 07:34 aiaustin Note Deleted: 0033262
2018-10-31 07:35 aiaustin Note Deleted: 0033320
2018-10-31 07:35 aiaustin Note Deleted: 0033326
2018-10-31 07:36 aiaustin Note Deleted: 0033324
2018-10-31 07:37 aiaustin Note Deleted: 0033341
2018-10-31 07:39 aiaustin Note Edited: 0033346 View Revisions
2018-10-31 07:39 aiaustin Note Edited: 0033339 View Revisions
2018-10-31 08:39 BillBlight Note Added: 0033347
2018-10-31 08:55 UbitUmarov Note Added: 0033348
2018-10-31 09:01 aiaustin Note Added: 0033349
2018-10-31 09:02 aiaustin Note Edited: 0033349 View Revisions
2018-10-31 09:03 aiaustin Note Edited: 0033349 View Revisions
2018-10-31 10:21 Sheera Khan Note Edited: 0033345 View Revisions
2018-10-31 12:03 UbitUmarov Note Added: 0033350
2018-10-31 14:52 aiaustin Note Added: 0033351
2018-10-31 14:52 aiaustin Note Edited: 0033351 View Revisions
2018-10-31 14:53 aiaustin Note Edited: 0033351 View Revisions
2018-10-31 20:39 BillBlight Note Added: 0033352
2018-11-01 01:35 BillBlight Note Added: 0033353
2018-11-01 01:38 BillBlight Note Deleted: 0033353
2018-11-01 01:42 BillBlight Note Added: 0033354
2018-11-01 02:05 aiaustin Note Deleted: 0033351
2018-11-01 02:07 aiaustin Note Added: 0033355
2018-11-01 03:29 BillBlight Note Added: 0033356
2018-11-01 03:30 BillBlight Note Edited: 0033356 View Revisions
2018-11-01 03:30 BillBlight Note Edited: 0033356 View Revisions
2018-11-01 03:41 BillBlight Note Edited: 0033356 View Revisions
2018-11-01 07:15 tglion Note Added: 0033357
2018-11-01 07:31 mewtwo0641 Note Added: 0033358
2018-11-01 09:42 mike.chase Note Added: 0033359
2018-11-01 09:42 mike.chase Note Edited: 0033359 View Revisions
2018-11-01 09:48 aiaustin Note Added: 0033360
2018-11-01 09:53 mike.chase Note Added: 0033361
2018-11-01 10:05 aiaustin Note Added: 0033362
2018-11-01 10:06 aiaustin Note Edited: 0033362 View Revisions
2018-11-01 10:06 aiaustin Note Edited: 0033362 View Revisions
2018-11-01 10:10 BillBlight Note Added: 0033363
2018-11-01 10:15 aiaustin Note Added: 0033364
2018-11-01 10:16 BillBlight Note Added: 0033365
2018-11-01 10:17 aiaustin Note Added: 0033366
2018-11-01 10:17 aiaustin Note Edited: 0033366 View Revisions
2018-11-01 10:18 aiaustin Note Added: 0033367
2018-11-01 10:20 aiaustin Note Edited: 0033367 View Revisions
2018-11-01 10:23 mike.chase Note Added: 0033368
2018-11-01 10:30 aiaustin Note Edited: 0033367 View Revisions
2018-11-01 10:32 aiaustin Note Added: 0033369
2018-11-01 10:33 aiaustin Note Edited: 0033369 View Revisions
2018-11-01 11:11 aiaustin Note Edited: 0033369 View Revisions
2018-11-01 11:17 BillBlight Note Added: 0033370
2018-11-01 11:19 BillBlight Note Edited: 0033370 View Revisions
2018-11-01 13:09 aiaustin Note Edited: 0033369 View Revisions
2018-11-01 13:37 UbitUmarov Note Added: 0033371
2018-11-01 15:26 UbitUmarov Note Added: 0033372
2018-11-01 15:29 UbitUmarov Note Edited: 0033372 View Revisions
2018-11-01 15:31 BillBlight Note Added: 0033373
2018-11-01 16:25 BillBlight Note Edited: 0033373 View Revisions
2018-11-01 17:38 mewtwo0641 Note Added: 0033374
2018-11-01 20:15 UbitUmarov Note Added: 0033375
2018-11-01 21:11 mewtwo0641 Note Added: 0033376
2018-11-01 21:22 BillBlight Note Added: 0033377
2018-11-01 21:28 mewtwo0641 Note Added: 0033378
2018-11-02 03:01 aiaustin Note Added: 0033379
2018-11-02 05:14 UbitUmarov Note Added: 0033383
2018-11-02 05:17 mike.chase Note Added: 0033384
2018-11-02 05:40 UbitUmarov Note Added: 0033385
2018-11-02 05:42 aiaustin Note Added: 0033386
2018-11-02 06:26 mike.chase Note Added: 0033387
2018-11-02 09:57 aiaustin Note Added: 0033390
2018-11-02 10:04 BillBlight Note Added: 0033391
2018-11-02 10:11 BillBlight Note Edited: 0033391 View Revisions
2018-11-06 07:45 aiaustin Note Added: 0033416
2018-11-06 07:52 BillBlight Note Added: 0033417
2018-11-06 07:53 BillBlight Note Edited: 0033417 View Revisions
2018-11-06 08:49 aiaustin Note Added: 0033418
2018-11-06 08:52 aiaustin Note Edited: 0033418 View Revisions
2018-11-06 09:18 aiaustin Note Edited: 0033418 View Revisions
2018-11-06 17:15 mike.chase Note Added: 0033424
2018-11-07 10:54 UbitUmarov Note Added: 0033443
2018-11-17 13:19 Balpien Note Added: 0033512
2018-11-17 13:21 BillBlight Note Added: 0033513
2018-11-17 13:23 mike.chase Note Added: 0033514
2018-11-17 13:33 mike.chase Note Added: 0033515
2018-11-19 11:30 colosi Note Added: 0033519
2018-12-14 18:16 colosi Note Added: 0033629


Copyright © 2000 - 2012 MantisBT Group
Powered by Mantis Bugtracker