Mantis Bug Tracker

View Issue Details Jump to Notes ] Issue History ] Print ]
IDProjectCategoryView StatusDate SubmittedLast Update
0007110opensim[REGION] OpenSim Corepublic2014-04-14 07:182015-02-28 12:09
Reporteraiaustin 
Assigned To 
PrioritynormalSeveritymajorReproducibilitysometimes
StatusnewResolutionopen 
PlatformPCOSWindowsOS Version8.1
Product Versionmaster (dev code) 
Target VersionFixed in Version 
Summary0007110: Cloud avatar forever on login on OSGrid add-on regions
DescriptionOn my own add-on regions using the standard add-on region distribution from osgrid.org for recent versions of 0.8.0 dev master I have avatars which always appeared as a cloud (using Firestorm 4.6.1 if that is relevant).

The outfit worn was not loading properly also and no alternative outfit could be worn as a replacement as the system thought the avatar had no outfit set. It reported:

      "Could not put on outfit. The outfit folder contains
       no clothing, body parts, or attachments"

I found that replacing the basic body parts then let the avatar rez.. but then the clothing and attachments that should have been worn were also added and they were not detachable.

I found that teleporting to OSGrid Wright Plaza (for example) allowed the avatar to rez, and logging in there initially was okay each time.

I tried turning off the default xbakes setup for OSGrid add on regions, but on or off made no difference.

I am posting this issue to see if anyone else can report similar problems or start to pin down what might be happening.


TagsNo tags attached.
Git Revision or version numberr/24620
Run Mode Grid (Multiple Regions per Sim)
Physics EngineBulletSim
Script Engine
Environment.NET / Windows64
Mono VersionNone
ViewerFirestorm 4.6.1
Attached Files

- Relationships
related to 0007054closedjustincc Initial inventory fetch seems to hang occasionally 

-  Notes
(0025784)
danbanner (manager)
2014-04-14 14:29

Sounds like a bad attachment or something, perhaps try another copy of the item?
That uuid is not from any local osgrid account most likely its the uuid of a user from another grid.
(0025785)
aiaustin (developer)
2014-04-15 03:25
edited on: 2014-04-15 08:51

Its odd.. the avatar shows as a cloud and no outfits can be loaded. But if I "wear" the 4 basic body parts the avatar rezzes but still shows ALL the attachments and HUD items at that stage even though they cannot then be removed. The outfits each show "loading" forever.

BUT if I teleport to Wright Plaza then the items do rez there.

I tried removing the obvious potential problem AO HUD itself, resaving the outfit and then logging back into the add-on OSGrid region, but I get the same problem until I return again to Wright Plaza. Except for speed what might be different about Wright Plaza which lets the avatar and rez and attachments be normal I wonder?

I completely rebuilt the OpenSim.ini using the OSGrid distribution base, which is almost identical except for a few osFunctionThreatLevel changes.

Clearing the Firestorm 4.6.1 cache and making sure the inventory completely updated before doing anything still left the avatar as a cloud.

But oddly testing on CtrlAltStudio viewer 1.2.0, which is based on Firestorm 4.6.1, did rez the avatar when I first entered. But on the SECOND login with that viewer it also failed to rez and just stayed as a cloud again, until I TPed to Wright Plaza then the avatar was instantly rezzed. By the way, after the avatar is rezzed simply TPing back to the original add-on OSGrid location leave the avatar rezzed fine, but not on next login.

The problem by the way occurs on 3 different systems for add-on regions, all very lightly loaded, and all ones that have work well for a few years.

Anyone else seeing anything like this?

(0025786)
aiaustin (developer)
2014-04-15 09:36

I think the AO/HUD item issue was a red herring and is not a factor. It is the same without it being used at all.. indeed without ANY HUDs in use. The basic body items appear not even to be loaded, which seems to be the reason that wearing 4 new body parts allows the avatar to appear.

I do notice some slow handling of items for the avatar in the console logs...

17:33:03 - [LOGHTTP]: Slow handling of 1931 POST /CAPS/9943a15e-c3f9-4725-b1bb-5
dbb93128f5f FetchInventory2 61b7cfc7-ca16-46d8-881a-a1d445f7e5ee from 92.237.199
.112:50834 took 5616ms

This just before it seem to stop loading other inventory items all together.

On a test, when I cleared the cache for Firestorm 4.6.1 and then left the inventory recent items tab open... the items crawled in and stuck on 300 or so of the 2000 that should have been present and never went up even after some minutes... with avatar still a cloud. When I TPed to Wright Plaza, the incoming inventory items rocket up to be complete.
(0025787)
Mata Hari (reporter)
2014-04-15 15:26

So perhaps related to http://opensimulator.org/mantis/view.php?id=7054 [^] ?
(0025789)
aiaustin (developer)
2014-04-16 00:56
edited on: 2014-04-16 01:13

Yes, that looks like it could be related Mata Hari. Hence I will try some of the stats comments that JustinCC indicated.

Does the command stats show scene-inventory still exists? It gives "No such category" for me on r/24620.

I do see the inventory going up slowly and then jamming even though there is no other activity on the region. It may be that it jams in different places, and sometime there is enough there to rezz the avatar and sometimes not.

I only see this on my three hosts for OSGrid add on regions. On our own Grid and add on region servers we don't see a problem like that.

For Justin... do we still expect to see "Unknown UserUMMAU4" in the latest 0.8.0 releases.. it appears on OSGrid for the Creator of an item where the UUID is for a non-OSGrid avatar? If so I will create a Mantis entry of you need the specifics of that.

(0025790)
aiaustin (developer)
2014-04-16 01:25

Okay, I think this may be the (or a major) cause as you suggested Mata Hari.

I have an avatar with about 2000 inventory items on OSGrid. I logged in and was a cloud for about 2 minutes... inventory crawled up to 409 by which time the avatar did rezz. But the inventory never then went up higher. Even after 5 minutes.

I logged off and then back on and the inventory this time only got to 65 items and the avatar stayed as a cloud.

I will report this and give the saved stats in mantis http://opensimulator.org/mantis/view.php?id=7054 [^]
(0025792)
Mata Hari (reporter)
2014-04-16 02:35

I think something additional must be happening beyond the slow inventory fetch in your case.

I've almost never been stuck as a cloud avi except when I've done a cache clear of my viewer AND a purge appearance of my OSG account. If I then log in to a non-Plaza region I might get stuck as a cloud if the inventory fetch hangs somewhat early in the process.

The inventory fetch may be a contributing factor, though, but the root of the issue is whatever it is that is making the whole process grind to a halt. It seems to be tying up region simulator resources to the extreme because I've seen this happen when someone logs in to a region during a party with an empty viewer cache....suddenly *everyone* pretty much locks up for the next half hour.
(0025795)
aiaustin (developer)
2014-04-16 07:59

I should add that the console for the region server is not doing anything at all for all the time its jammed... everything looks to be idle.
(0025796)
Mata Hari (reporter)
2014-04-16 10:52

Worth testing when it next happens to you: try entering a console command of some sort that should have a direct impact on the sim (like raise and lower the terrain by 1m) and see if it actually responds immediately or whether the commands don't execute until much later. I've had instances where everything seems to lock up and console commands aren't executed until a timer of some sort expires.
(0025890)
aiaustin (developer)
2014-04-24 14:39
edited on: 2014-04-24 14:40

Is there a command you can suggest that is less disruptive on the live contents?

This is a real pain of an issue, and I am surprised others have not been reporting it. A few others I have spoken to when visiting the Plazas to get the avatar to rez have said they always log in at a plaza first as they come online as a cloud otherwise, so I think people have just assumed it is the norm.

I think it does relate to the inventory coming in being stuck and never continuing ahead of the outfit contents being updated.

But what seems odd is that even with a rezzed avatar and all the inventory cached, a simple log out and back in on an OSGrid and on region (not a plaza) fails and leaves the avatar as a cloud... So the system cannot simply be using the cache and xbakes in such a case as you might think it would.

(0025892)
Mata Hari (reporter)
2014-04-24 17:24

You could try >alert "Com check" to see if it sends out the region alert immediately.

I don't have any inventory that matches your conditions (or at least not that I'm aware of or wear on a regular basis so it's rare that I ever log in as a cloud other than after a viewer cache clear; but I almost always log in to plazas anyway because of the "stuck inventory fetch" bug (0007054) that will often lock me up if I log in to one of my own regions.
(0025894)
aiaustin (developer)
2014-04-25 05:36

Okay, I tried this Mata... I had the cloud avatar, and the usual [LOGHTTP]: Slow handling of ...POST...FetchInventory2 message and all was stuck. But I was able to do an openSim.exe OSGrid add on region console command alert "Test" fine and it came out immediately on the viewer region and the console log indicated it was sent straight away to the regions in the OpenSim.exe instance. So the simulator is not stuck, and the comms from the region simulator to the viewer works instantly.

It seems that the central inventory services have simply given up and will not update however long you leave things, even on an idling sim. Maybe some change is needed to make sure the robust server does not actually give up even if it takes a while.

Very small inventories may always work, but even avatars with only a few thousand items in them cause this problem most times. If I log into an OSGrid plaza the avatar rezzs instantly, but a direct login to an add-on region (using latest 0.8.0 OSGrid release) is nearly always problematic and leaves the avatar as a cloud until body parts and basic clothing items are changed or I TP to a plaza.
(0025899)
aiaustin (developer)
2014-04-25 07:17

I notice that even after a viewer cache clear (on Firestorm) if using Second Life, that the avatar appears fully well ahead of all the inventory items coming in... maybe some sort of server side prioritisation of the appearance, current outfit and worn items is possible?
(0025909)
aiaustin (developer)
2014-04-26 09:05
edited on: 2014-04-26 09:08

I wonder if this might offer a clue.... while the avatar was still a cloud and it had been idling like that for some time. I log off from the single viewer that is connected to the region... nothing else is running. I then do the proper "shutdown" on the OpenSim.exe instance the avatar was on and I get a red error .. this may give us a clue as to the place where its all stuck?

OpenSim.Services.Connectors.XInventoryServicesConnector [XINVENTORY SERVICES CONNECTOR]: Exception in GetItem:
System.Threading.ThreadAbortException: Thread was being aborted.

----

More of the OpenSim.log from the shutdown command being issued is here... Note I added the line spacing to better show the problematic area in the middle..


2014-04-26 16:58:50,570 INFO - OpenSim.OpenSimBase [SHUTDOWN]: Closing all threads
2014-04-26 16:58:50,570 INFO - OpenSim.OpenSimBase [SHUTDOWN]: Killing listener thread
2014-04-26 16:58:50,585 INFO - OpenSim.OpenSimBase [SHUTDOWN]: Killing clients
2014-04-26 16:58:50,585 INFO - OpenSim.OpenSimBase [SHUTDOWN]: Closing console and terminating
2014-04-26 16:58:50,585 INFO - OpenSim.Region.Framework.Scenes.Scene [SCENE]: Closing down the single simulator: Vue-Port
2014-04-26 16:58:50,664 DEBUG - OpenSim.Framework.Monitoring.Watchdog [WATCHDOG]: Removing thread Heartbeat (Vue-Port), ID 56
2014-04-26 16:58:50,867 DEBUG - OpenSim.Framework.Monitoring.Watchdog [WATCHDOG]: Removing thread Maintenance (Vue-Port), ID 40
2014-04-26 16:58:51,101 DEBUG - OpenSim.Region.Framework.Scenes.Scene [SCENE]: Persisting changed objects
2014-04-26 16:58:51,101 DEBUG - OpenSim.Services.GridService.GridService [GRID SERVICE]: Deregistering region Vue-Port (2aa49e09-f1b1-4f20-8ae3-55e0399a674c) at 6400-6400
2014-04-26 16:58:51,429 DEBUG - OpenSim.OpenSimBase [SHUTDOWN]: Shutting down region Vue-Port
2014-04-26 16:58:51,726 INFO - OpenSim.Region.DataSnapshot.DataSnapshotManager [DATASNAPSHOT]: Region Vue-Port is being removed, removing from indexing
2014-04-26 16:58:51,804 DEBUG - OpenSim.Framework.Monitoring.Watchdog [WATCHDOG]: Removing thread InventoryWorkerThread0, ID 29
2014-04-26 16:58:51,820 DEBUG - OpenSim.Framework.Monitoring.Watchdog [WATCHDOG]: Removing thread InventoryWorkerThread1, ID 30

2014-04-26 16:58:51,820 WARN - OpenSim.Services.Connectors.XInventoryServicesConnector [XINVENTORY SERVICES CONNECTOR]: Exception in GetFolderContent: Thread was being aborted.

2014-04-26 16:58:51,820 INFO - OpenSim.Region.ScriptEngine.XEngine.XEngine [XEngine]: Shutting down 49 scripts in Vue-Port
2014-04-26 16:58:51,867 INFO - OpenSim.Region.Framework.Scenes.Scene [SCENE]: Closing down the single simulator: OpenVCE

2014-04-26 16:58:51,867 INFO - OpenSim.Framework.SynchronousRestFormsRequester [FORMS]: Error receiving response from http://inventory.osgrid.org/xinventory: [^] Thread was being aborted.. Request: ID=ee759b86-e03a-492c-b7d4-6ca2f428993d&METHOD=GETITEM

2014-04-26 16:58:51,882 ERROR - OpenSim.Services.Connectors.XInventoryServicesConnector [XINVENTORY SERVICES CONNECTOR]: Exception in GetItem:
System.Threading.ThreadAbortException: Thread was being aborted.
   at OpenSim.Framework.SynchronousRestFormsRequester.MakeRequest(String verb, String requestUrl, String obj, Int32 timeoutsecs) in k:\OSGRID\opensim-a893fd9\OpenSim\Framework\WebUtil.cs:line 1078
   at OpenSim.Framework.SynchronousRestFormsRequester.MakeRequest(String verb, String requestUrl, String obj) in k:\OSGRID\opensim-a893fd9\OpenSim\Framework\WebUtil.cs:line 1082
   at OpenSim.Services.Connectors.XInventoryServicesConnector.MakeRequest(String method, Dictionary`2 sendData) in k:\OSGRID\opensim-a893fd9\OpenSim\Services\Connectors\Inventory\XInventoryServicesConnector.cs:line 540
   at OpenSim.Services.Connectors.XInventoryServicesConnector.GetItem(InventoryItemBase item) in k:\OSGRID\opensim-a893fd9\OpenSim\Services\Connectors\Inventory\XInventoryServicesConnector.cs:line 403

2014-04-26 16:58:52,445 DEBUG - OpenSim.Framework.Monitoring.Watchdog [WATCHDOG]: Removing thread Heartbeat (OpenVCE), ID 51
2014-04-26 16:58:52,898 DEBUG - OpenSim.Framework.Monitoring.Watchdog [WATCHDOG]: Removing thread Maintenance (OpenVCE), ID 41
2014-04-26 16:58:52,914 DEBUG - OpenSim.Region.Framework.Scenes.Scene [SCENE]: Persisting changed objects
2014-04-26 16:58:54,460 DEBUG - OpenSim.Services.GridService.GridService [GRID SERVICE]: Deregistering region OpenVCE (2a2c51ed-7846-4536-8503-dc332c6c0804) at 6400-6399
2014-04-26 16:58:54,804 DEBUG - OpenSim.OpenSimBase [SHUTDOWN]: Shutting down region OpenVCE
2014-04-26 16:58:55,054 INFO - OpenSim.Region.DataSnapshot.DataSnapshotManager [DATASNAPSHOT]: Region OpenVCE is being removed, removing from indexing
2014-04-26 16:58:55,054 INFO - OpenSim.Region.ScriptEngine.XEngine.XEngine [XEngine]: Shutting down 391 scripts in OpenVCE
2014-04-26 16:58:55,101 INFO - OpenSim.Framework.Servers.BaseOpenSimServer [SHUTDOWN]: Shutdown processing on main thread complete. Exiting...

(0025911)
aiaustin (developer)
2014-04-26 09:23
edited on: 2014-04-26 09:23

I have been able to repeat and generate the error message by:

1. Logging in via (Firestorm 4.6.1) to an OSGrid add on region with latest OSGrid packaged release... cloud avatar persists for several minutes with usual Slow handling of ... FetchInventory2 as last message showing on OpenSim.exe console.

2. Log out of viewer and let things settle down on openSim.exe console.

3. After a minute or so of no activity shutdown the OpenSim.exe for the OSGrid add on region

4. Observer the red ERROR - OpenSim.Services.Connectors.XInventoryServicesConnector [XINVENTORY SERVICES CONNECTOR]: Exception in GetItem: System.Threading.ThreadAbortException: Thread was being aborted.

(0025912)
aiaustin (developer)
2014-04-26 09:27

I tried amending the Thread Pool mechanism from the usual SmartThreadPool used in the default OSGrid OpenSim.ini to UnsafeQueueUserWorkItem since I am using Windows 8.1 Pro. That had no effect... avatar still sticks as a cloud, and I still observed the red error on shutdown too.

I should add I am seeing this on 4 different desktops with the viewer some on a University very fast network and the slowest on a 50Mbps cable connection, and on 3 different OSGrid add-on servers with varying power and connected via gigabit Ethernet to the internet via high capacity pipes.
(0025914)
aiaustin (developer)
2014-04-26 12:19
edited on: 2014-04-26 12:19

Could a conclusion be that the GetItem call at this line locks up and does not accept whatever the OSGrid inventory service does...

OpenSim.Services.Connectors.XInventoryServicesConnector.GetItem(InventoryItemBase item) in k:\OSGRID\opensim-a893fd9\OpenSim\Services\Connectors\Inventory\XInventoryServicesConnector.cs:line 403

But should the inventory service be allowed to give up and leave the viewer hung forever?

(0025935)
aiaustin (developer)
2014-04-30 04:34

A couple of other observations to report..

a) altering the data base for the OSGrid add-on regions between SQLite and MySQL makes no difference. The issue appears to be the OSGrid inventory server(s).

b) Even though the avatar is a cloud... it seems inventory operations can still be performed, such as moving folders and renaming items (in Firestorm 4.6.1) and these show in the OpenSim.exe console as being completed. But Appearance is greyed out everywhere including the top menu bar, and the "Wearing" tab in Outfits tool should "loading..." and never resolved, even after idling for 15 minutes. A visit then to Wright Plaza allows the inventory check to complete and the avatar rezzes.

If specific logging is required just ask and I will try to get what is needed.
(0025942)
aiaustin (developer)
2014-05-01 02:45
edited on: 2014-07-26 03:30

I observe that even when an avatar is rezzed on an OSGrid add-on region, there might still be an issue with the inventory loading not completing... The Recent tab in Firestorm 4.6.1 indicates its still "Searching.." and the bottom Item count indicates its stuck on a number like "Fetching 3,400 Items... Since Logoff".

But if I repeatedly do show stats inventory in the OSGrid add -on region OpenSim.exe console.. I see the "QueuedFetchInventoryRequests" continuing to count upwards (occasionally going down by one) and not go to zero? Is that relevant? Following show stats are a few SECONDS apart...

Region (root) # show stats inventory
inventory.httpfetch.ProcessedFetchInventoryRequests : 151, 0/s, 0.05/s
inventory.httpfetch.QueuedFetchInventoryRequests : 7, 0.4/s, 0.12/s
Region (root) # show stats inventory
inventory.httpfetch.ProcessedFetchInventoryRequests : 151, 0/s, 0.05/s
inventory.httpfetch.QueuedFetchInventoryRequests : 9, 0/s, 0.03/s
Region (root) # show stats inventory
inventory.httpfetch.ProcessedFetchInventoryRequests : 151, 0/s, 0.05/s
inventory.httpfetch.QueuedFetchInventoryRequests : 13, 0/s, 0.1/s
Region (root) # show stats inventory
inventory.httpfetch.ProcessedFetchInventoryRequests : 152, 0/s, 0.05/s
inventory.httpfetch.QueuedFetchInventoryRequests : 12, 0/s, 0.1/s
Region (root) # show stats inventory
inventory.httpfetch.ProcessedFetchInventoryRequests : 152, 0.4/s, 0.07/s
inventory.httpfetch.QueuedFetchInventoryRequests : 12, -0.4/s, 0.09/s
Region (root) # show stats inventory
inventory.httpfetch.ProcessedFetchInventoryRequests : 153, 0/s, 0.03/s
inventory.httpfetch.QueuedFetchInventoryRequests : 11, 0/s, 0.12/s
Region (root) # show stats inventory
inventory.httpfetch.ProcessedFetchInventoryRequests : 153, 0.4/s, 0.05/s
inventory.httpfetch.QueuedFetchInventoryRequests : 13, -0.4/s, 0.07/s
Region (root) # show stats inventory
inventory.httpfetch.ProcessedFetchInventoryRequests : 153, 0/s, 0.05/s
inventory.httpfetch.QueuedFetchInventoryRequests : 13, 0.8/s, 0.1/s
Region (root) # show stats inventory
inventory.httpfetch.ProcessedFetchInventoryRequests : 153, 0/s, 0.05/s
inventory.httpfetch.QueuedFetchInventoryRequests : 13, 0/s, 0.1/s
Region (root) # show stats inventory
inventory.httpfetch.ProcessedFetchInventoryRequests : 153, 0/s, 0.03/s
inventory.httpfetch.QueuedFetchInventoryRequests : 13, 0/s, 0.12/s
Region (root) # show stats inventory
inventory.httpfetch.ProcessedFetchInventoryRequests : 153, 0/s, 0.03/s
inventory.httpfetch.QueuedFetchInventoryRequests : 14, 0/s, 0.1/s
Region (root) # show stats inventory
inventory.httpfetch.ProcessedFetchInventoryRequests : 153, 0/s, 0.03/s
inventory.httpfetch.QueuedFetchInventoryRequests : 14, 0.4/s, 0.12/s
Region (root) # show stats inventory
inventory.httpfetch.ProcessedFetchInventoryRequests : 153, 0/s, 0.03/s
inventory.httpfetch.QueuedFetchInventoryRequests : 19, 1.6/s, 0.09/s
Region (root) # show stats inventory
inventory.httpfetch.ProcessedFetchInventoryRequests : 154, 0/s, 0.03/s
inventory.httpfetch.QueuedFetchInventoryRequests : 19, 0.8/s, 0.12/s
Region (root) # show stats inventory
inventory.httpfetch.ProcessedFetchInventoryRequests : 154, 0.4/s, 0.05/s
inventory.httpfetch.QueuedFetchInventoryRequests : 19, -0.4/s, 0.1/s
Region (root) # show stats inventory
inventory.httpfetch.ProcessedFetchInventoryRequests : 155, 0.4/s, 0.07/s
inventory.httpfetch.QueuedFetchInventoryRequests : 18, -0.4/s, 0.09/s
Region (root) # show stats inventory
inventory.httpfetch.ProcessedFetchInventoryRequests : 155, 0.4/s, 0.07/s
inventory.httpfetch.QueuedFetchInventoryRequests : 18, -0.4/s, 0.09/s
Region (root) # show stats inventory
inventory.httpfetch.ProcessedFetchInventoryRequests : 155, 0/s, 0.07/s
inventory.httpfetch.QueuedFetchInventoryRequests : 18, 0/s, 0.09/s
Region (root) # show stats inventory
inventory.httpfetch.ProcessedFetchInventoryRequests : 155, 0/s, 0.07/s
inventory.httpfetch.QueuedFetchInventoryRequests : 18, 0/s, 0.09/s
Region (root) # show stats inventory
inventory.httpfetch.ProcessedFetchInventoryRequests : 155, 0/s, 0.05/s
inventory.httpfetch.QueuedFetchInventoryRequests : 18, 0/s, 0.1/s
Region (root) # show stats inventory
inventory.httpfetch.ProcessedFetchInventoryRequests : 155, 0/s, 0.03/s
inventory.httpfetch.QueuedFetchInventoryRequests : 20, 0/s, 0.09/s
Region (root) # show stats inventory
inventory.httpfetch.ProcessedFetchInventoryRequests : 155, 0/s, 0.03/s
inventory.httpfetch.QueuedFetchInventoryRequests : 20, 0.8/s, 0.12/s
Region (root) # show stats inventory
inventory.httpfetch.ProcessedFetchInventoryRequests : 155, 0/s, 0.03/s
inventory.httpfetch.QueuedFetchInventoryRequests : 20, 0.8/s, 0.12/s
Region (root) # show stats inventory
inventory.httpfetch.ProcessedFetchInventoryRequests : 155, 0/s, 0.03/s
inventory.httpfetch.QueuedFetchInventoryRequests : 20, 0/s, 0.12/s
Region (root) # show stats inventory
inventory.httpfetch.ProcessedFetchInventoryRequests : 155, 0/s, 0.03/s
inventory.httpfetch.QueuedFetchInventoryRequests : 21, 0/s, 0.1/s
Region (root) # show stats inventory
inventory.httpfetch.ProcessedFetchInventoryRequests : 155, 0/s, 0.03/s
inventory.httpfetch.QueuedFetchInventoryRequests : 21, 0/s, 0.1/s
Region (root) # show stats inventory
inventory.httpfetch.ProcessedFetchInventoryRequests : 156, 0/s, 0.03/s
inventory.httpfetch.QueuedFetchInventoryRequests : 20, 0.4/s, 0.12/s
Region (root) # show stats inventory
inventory.httpfetch.ProcessedFetchInventoryRequests : 156, 0.4/s, 0.05/s
inventory.httpfetch.QueuedFetchInventoryRequests : 20, -0.4/s, 0.1/s
Region (root) # show stats inventory
inventory.httpfetch.ProcessedFetchInventoryRequests : 159, 0/s, 0.05/s
inventory.httpfetch.QueuedFetchInventoryRequests : 23, 0/s, 0.1/s
Region (root) # show stats inventory
inventory.httpfetch.ProcessedFetchInventoryRequests : 159, 0.4/s, 0.07/s
inventory.httpfetch.QueuedFetchInventoryRequests : 23, -0.4/s, 0.09/s
Region (root) # show stats inventory
inventory.httpfetch.ProcessedFetchInventoryRequests : 160, 0/s, 0.09/s
inventory.httpfetch.QueuedFetchInventoryRequests : 24, 0.8/s, 0.07/s
Region (root) # show stats inventory
inventory.httpfetch.ProcessedFetchInventoryRequests : 160, 0/s, 0.09/s
inventory.httpfetch.QueuedFetchInventoryRequests : 24, 0/s, 0.07/s
Region (root) # show stats inventory
inventory.httpfetch.ProcessedFetchInventoryRequests : 160, 0/s, 0.09/s
inventory.httpfetch.QueuedFetchInventoryRequests : 24, 0/s, 0.07/s
Region (root) # show stats inventory
inventory.httpfetch.ProcessedFetchInventoryRequests : 160, 0/s, 0.09/s
inventory.httpfetch.QueuedFetchInventoryRequests : 24, 0/s, 0.07/s
Region (root) # show stats inventory
inventory.httpfetch.ProcessedFetchInventoryRequests : 162, 0/s, 0.05/s
inventory.httpfetch.QueuedFetchInventoryRequests : 29, 0/s, 0.1/s

THEN.. after maybe 5 minutes its risen to

Region (root) # show stats inventory
inventory.httpfetch.ProcessedFetchInventoryRequests : 183, 0/s, 0.03/s
inventory.httpfetch.QueuedFetchInventoryRequests : 62, 0/s, 0.12/s


AFTER another minute

Region (root) # show stats inventory
inventory.httpfetch.ProcessedFetchInventoryRequests : 200, 0/s, 0.05/s
inventory.httpfetch.QueuedFetchInventoryRequests : 90, 1.6/s, 0.07/s
Region (root) # show stats httpserver
httpserver.9000.HTTPRequestsServed : 679 requests, 0 requests/s, 0.21 requests/s
httpserver.9000.ProcessedPollResponses : 310, 0/s, 0.09/s
httpserver.9000.QueuedPollResponses : 0, 0.4/s, 0.02/s

I then logged the avatar off... and there is no console activity on OpenSim.exe... and did stats again...

Region (root) # show stats inventory
inventory.httpfetch.ProcessedFetchInventoryRequests : 205, 0/s, 0.07/s
inventory.httpfetch.QueuedFetchInventoryRequests : 94, 0/s, 0.05/s
Region (root) # show stats httpserver
httpserver.9000.HTTPRequestsServed : 690 requests, 0 requests/s, 0.16 requests/s
httpserver.9000.ProcessedPollResponses : 317, 0/s, 0.09/s
httpserver.9000.QueuedPollResponses : 0, 0/s, -1.22/s


I left things for a further 2 minutes and repeated the stats.... should there be ANY "QueuedFetchInventoryRequests" at this stage? There are... and they go down... VERY slowly (perhaps 2 queued request removed each minute) over some minutes. Following show stats are a few MINUTES apart...

Region (root) # show stats inventory
inventory.httpfetch.ProcessedFetchInventoryRequests : 211, 0/s, 0.07/s
inventory.httpfetch.QueuedFetchInventoryRequests : 88, 0/s, -0.07/s
Region (root) # show stats httpserver
httpserver.9000.HTTPRequestsServed : 690 requests, 0 requests/s, 0 requests/s
httpserver.9000.ProcessedPollResponses : 326, 0/s, 0.07/s
httpserver.9000.QueuedPollResponses : 0, 0/s, 0/s

Region (root) # show stats inventory
inventory.httpfetch.ProcessedFetchInventoryRequests : 225, 0/s, 0.03/s
inventory.httpfetch.QueuedFetchInventoryRequests : 74, 0/s, -0.03/s
Region (root) # show stats httpserver
httpserver.9000.HTTPRequestsServed : 690 requests, 0 requests/s, 0 requests/s
httpserver.9000.ProcessedPollResponses : 339, 0/s, 0.03/s
httpserver.9000.QueuedPollResponses : 0, 0/s, 0/s

Region (root) # show stats inventory
inventory.httpfetch.ProcessedFetchInventoryRequests : 231, 0/s, 0.07/s
inventory.httpfetch.QueuedFetchInventoryRequests : 68, 0/s, -0.07/s
Region (root) # show stats httpserver
httpserver.9000.HTTPRequestsServed : 690 requests, 0 requests/s, 0 requests/s
httpserver.9000.ProcessedPollResponses : 345, 0/s, 0.07/s
httpserver.9000.QueuedPollResponses : 0, 0/s, 0/s

After a VERY long time.. perhaps half an hour or more.. the QueuedFetchInventoryRequests did reach zero...

Region (root) # show stats inventory
inventory.httpfetch.ProcessedFetchInventoryRequests : 301, 0/s, 0/s
inventory.httpfetch.QueuedFetchInventoryRequests : 0, 0/s, 0/s
Region (root) # show stats httpserver
httpserver.9000.HTTPRequestsServed : 691 requests, 0 requests/s, 0 requests/s
httpserver.9000.ProcessedPollResponses : 415, 0/s, 0/s
httpserver.9000.QueuedPollResponses : 0, 0/s, 0/s

(0025944)
aiaustin (developer)
2014-05-01 08:45
edited on: 2014-05-01 08:48

If I shutdown while there are NO inventory.httpfetch.QueuedFetchInventoryRequests, the shutdown proceeds normally. If I shutdown while there are still perhaps 50 or so inventory.httpfetch.QueuedFetchInventoryRequests I get a red error in the OpenSim.exe console:

OpenSim.Services.Connectors.XInventoryServicesConnector [XINVENTORY SERVICES CONNECTOR]: Exception in GetItem:
 System.Threading.ThreadAbortException: Thread was being aborted.

Detailed entry from OpenSim.log is

2014-05-01 16:39:31,507 ERROR - OpenSim.Services.Connectors.XInventoryServicesConnector [XINVENTORY SERVICES CONNECTOR]: Exception in GetItem:
System.Threading.ThreadAbortException: Thread was being aborted.
   at System.Threading.Monitor.Enter(Object obj)
   at OpenSim.Services.Connectors.XInventoryServicesConnector.MakeRequest(String method, Dictionary`2 sendData) in k:\OSGRID\opensim-2e216aa\OpenSim\Services\Connectors\Inventory\XInventoryServicesConnector.cs:line 500
   at OpenSim.Services.Connectors.XInventoryServicesConnector.GetItem(InventoryItemBase item) in k:\OSGRID\opensim-2e216aa\OpenSim\Services\Connectors\Inventory\XInventoryServicesConnector.cs:line 403

2014-05-01 16:39:31,629 INFO - OpenSim.Framework.SynchronousRestFormsRequester [FORMS]: Error sending request to http://inventory.osgrid.org/xinventory: [^] Thread was being aborted.. Request: ID=bb1e41fe-1399-4378-a2c8-c815ceff00a6&METHOD=GETITEM

2014-05-01 16:39:31,631 ERROR - OpenSim.Services.Connectors.XInventoryServicesConnector [XINVENTORY SERVICES CONNECTOR]: Exception in GetItem:
System.Threading.ThreadAbortException: Thread was being aborted.
   at OpenSim.Framework.SynchronousRestFormsRequester.MakeRequest(String verb, String requestUrl, String obj, Int32 timeoutsecs) in k:\OSGRID\opensim-2e216aa\OpenSim\Framework\WebUtil.cs:line 1070
   at OpenSim.Framework.SynchronousRestFormsRequester.MakeRequest(String verb, String requestUrl, String obj) in k:\OSGRID\opensim-2e216aa\OpenSim\Framework\WebUtil.cs:line 1074
   at OpenSim.Services.Connectors.XInventoryServicesConnector.MakeRequest(String method, Dictionary`2 sendData) in k:\OSGRID\opensim-2e216aa\OpenSim\Services\Connectors\Inventory\XInventoryServicesConnector.cs:line 501
   at OpenSim.Services.Connectors.XInventoryServicesConnector.GetItem(InventoryItemBase item) in k:\OSGRID\opensim-2e216aa\OpenSim\Services\Connectors\Inventory\XInventoryServicesConnector.cs:line 403

(0025945)
aiaustin (developer)
2014-05-01 14:09
edited on: 2014-05-01 14:18

Logging on via Singularity 1.8.5 rather than Firestorm 4.6.1 (and CtrlAltStude which is based on Firestorm) gives the same cloud problem for a direct log in to an OSGrid addon region. The Singularity inventory tool shows all inventory entries with a black "(Loading...)" on every folder and item. The My Outfits folder has the correct outfit top level folders, but opening each indicates they are empty.

When the avatar is TPed to Wright Plaza everything resolves and all outfits then are visible.

But TP back to the OSGrid addon region log off and log back on and the avatar remains a cloud again in most cases.

Even when avatar rezzes I see that My Outfits entries remain unresolved. The Outfits tool in Firestorm does not indicate than any outfit can be "replaced"... those options are al greyed out, and the Inventory tool "Worn" tab shows attachments and HUDs work but not any body parts of normal clothing layers. All mighty odd.

(0025946)
Mata Hari (reporter)
2014-05-01 14:21

I am not having the cloud issue that you are (except rarely and possibly related to some other issue that I haven't pinned down yet) but I can definitely confirm your observations about the fetching continuing for a long time after the avi has logged out and sometimes generating the red error message.

The folders that usually seem to remain unresolved for me are My Outfits and/or my "#Firestorm" folder (where the AOs are stored). Sometimes the trash folder is also empty even though it shouldn't be.
(0025953)
aiaustin (developer)
2014-05-02 00:52

Mata... the "My Outfits" folder contents does seem to be the one taking the longest to resolve, and that may in turn contribute to the appearance and cloud problems. Thanks for your notes.
(0025955)
aiaustin (developer)
2014-05-02 07:30
edited on: 2014-05-02 07:34

JustinCC.. did you mean the fix in r/24687 could address this avatar rez issue as well as the NPC appearance issue the commit related to?

No.. I see now you referenced issue 7110 in the commit but meant

http://opensimulator.org/mantis/view.php?id=7011 [^]

(0025966)
aiaustin (developer)
2014-05-06 05:28
edited on: 2014-05-06 05:30

Tests on OSGrid between Mata Hari, Dan Banner and Ai Austin teleporting between various fast and slower server OSGrid add-on regions all led to the avatars rezzing even after a delay, so we could not establish a situation where the avatar was completely stuck as a cloud and inventory checks were incomplete and stuck.

But shortly afterwards that problem re-appeared on the same regions for my testing. This must be a timing and load issue, but my observation is that once things are stuck they never resolve... so one end is giving up even on idling sims and leaving one end in limbo and stuck. The queued inventory requests show strange behaviour with the thread aborting errors with the connections to inventory.osgrid.org showing on shutdown of a region server when they are not at zero at the region sim end, and taking up to half an hour to return from 120 or so to zero even on an idling sim.

(0025986)
aiaustin (developer)
2014-05-08 09:53
edited on: 2014-05-13 14:03

Since there are exception errors being thrown on shutdown of OpenSim.exe LONG after an avatar with a cloud appearance and/or stuck incoming inventory has logged off... there must be something jamming up with the OpenSim.Framework.SynchronousRestFormsRequester.MakeRequest that is called within the InventoryItemBase GetItem function in OpenSim\Services\Connectors\Inventory\XInventoryServicesConnector.cs

Can someone with knowledge of how such a sync request is meant to work take a look to see if there is an obvious problem here when the server end gives up as it appears to be doing for inventory.osgrid.org? It seems that this must be jammed and can throw the exception at the end of that function on region shutdown.

Full shutdown error example shown again below (copied from a comment above)- which can be thrown even 20 minutes after a stuck avatar is logged off - and always if the show stats inventory shows a non-zero count for inventory.httpfetch.QueuedFetchInventoryRequests

INFO - OpenSim.Framework.SynchronousRestFormsRequester [FORMS]: Error receiving response from http://inventory.osgrid.org/xinventory: [^] [^] Thread was being aborted.. Request: ID=ee759b86-e03a-492c-b7d4-6ca2f428993d&METHOD=GETITEM

ERROR - OpenSim.Services.Connectors.XInventoryServicesConnector [XINVENTORY SERVICES CONNECTOR]: Exception in GetItem:
 System.Threading.ThreadAbortException: Thread was being aborted.
    at OpenSim.Framework.SynchronousRestFormsRequester.MakeRequest(String verb, String requestUrl, String obj, Int32 timeoutsecs) in k:\OSGRID\opensim-a893fd9\OpenSim\Framework\WebUtil.cs:line 1078
    at OpenSim.Framework.SynchronousRestFormsRequester.MakeRequest(String verb, String requestUrl, String obj) in k:\OSGRID\opensim-a893fd9\OpenSim\Framework\WebUtil.cs:line 1082
    at OpenSim.Services.Connectors.XInventoryServicesConnector.MakeRequest(String method, Dictionary`2 sendData) in k:\OSGRID\opensim-a893fd9\OpenSim\Services\Connectors\Inventory\XInventoryServicesConnector.cs:line 540
    at OpenSim.Services.Connectors.XInventoryServicesConnector.GetItem(InventoryItemBase item) in k:\OSGRID\opensim-a893fd9\OpenSim\Services\Connectors\Inventory\XInventoryServicesConnector.cs:line 403

(0025987)
aiaustin (developer)
2014-05-08 09:58
edited on: 2014-08-10 02:38

Could this even be a difference between .net 3.5 and .net 4.0.. something observed by others on memorystream operations... as this just MIGHT have started to be a problem around the time we moved to .net 4.0?

Looking at the code around OpenSim\Framework\WebUtil.cs:line 1007
with the construct "using (MemoryStream buffer = new MemoryStream())"

See http://stackoverflow.com/questions/9452802/clipboard-behaves-differently-in-net-3-5-and-4-but-why [^]

(0025998)
aiaustin (developer)
2014-05-09 08:15
edited on: 2014-05-09 12:12

Logs of a test to see how long the QueuedFetchInventoryRequests takes to return to 0 when an avatar has been a cloud and incoming inventory was stuck.

Using Firestorm 4.6.1. Viewer distance set to 120m to avoid neighbouring region being shown. OSGrid as at 9-May-2014, add-on region ("OpenVCE") on Windows 8.1 Pro (64bit). Intel Core 2 CPU 6600 @2.40GHz, 4.0 GB. OSGrid add-on region release 1-May-2014 r/24687. Serving 2 regions, no voice enabled.

Avatar logged in to OSGrid Wright Plaza and fully rezzed with inventory stable, 2,232 items in total.

Teleport to OSGrid add-on region (OpenVCE)

Region (root) # show stats inventory
inventory.httpfetch.ProcessedFetchInventoryRequests : 751, 0/s, 0/s
inventory.httpfetch.QueuedFetchInventoryRequests : 0, 0/s, 0/s
Region (root) # show stats httpserver
httpserver.9000.HTTPRequestsServed : 6448 requests, 3.2 requests/s, 9.3 requests/s
httpserver.9000.ProcessedPollResponses : 1497, 0/s, 0.16/s
httpserver.9000.QueuedPollResponses : 0, 0/s, 0/s

Log off and back on at OSGrid add-on region (OpenVCE, no voice enabled)

Avatar is a cloud and inventory stuck on "Fetching 2,110..."

15:45

inventory.httpfetch.ProcessedFetchInventoryRequests : 902, 0/s, 0.07/s
inventory.httpfetch.QueuedFetchInventoryRequests : 249, 0/s, -0.07/s
Region (root) # show stats httpserver
httpserver.9000.HTTPRequestsServed : 8618 requests, 0 requests/s, 0 requests/s
httpserver.9000.ProcessedPollResponses : 1997, 0/s, 0.09/s
httpserver.9000.QueuedPollResponses : 0, 8.4/s, 4.35/s

Logoff from region.. region idle with no further avatars loggin on to it.... monitor QueuedFetchInventoryRequests dropping VERY slowly.

15:50

Region (root) # show stats inventory
inventory.httpfetch.ProcessedFetchInventoryRequests : 911, 0/s, 0.05/s
inventory.httpfetch.QueuedFetchInventoryRequests : 240, 0/s, -0.05/s
Region (root) # show stats httpserver
httpserver.9000.HTTPRequestsServed : 8618 requests, 0 requests/s, 0 requests/s
httpserver.9000.ProcessedPollResponses : 2005, 0.4/s, 0.07/s
httpserver.9000.QueuedPollResponses : 0, 0/s, -3.9/s

15:55

Region (root) # show stats inventory
inventory.httpfetch.ProcessedFetchInventoryRequests : 923, 0/s, 0.05/s
inventory.httpfetch.QueuedFetchInventoryRequests : 228, 0/s, -0.05/s
Region (root) # show stats httpserver
httpserver.9000.HTTPRequestsServed : 8618 requests, 0 requests/s, 0 requests/s
httpserver.9000.ProcessedPollResponses : 2017, 0/s, 0.05/s
httpserver.9000.QueuedPollResponses : 0, 0/s, -1.13/s

16:00

Region (root) # show stats inventory
inventory.httpfetch.ProcessedFetchInventoryRequests : 954, 0/s, 0.05/s
inventory.httpfetch.QueuedFetchInventoryRequests : 197, 0/s, -0.05/s
Region (root) # show stats httpserver
httpserver.9000.HTTPRequestsServed : 8649 requests, 0 requests/s, 0 requests/s
httpserver.9000.ProcessedPollResponses : 2058, 0/s, 0.03/s
httpserver.9000.QueuedPollResponses : 0, 0/s, -3.5/s

16:05

Region (root) # show stats inventory
inventory.httpfetch.ProcessedFetchInventoryRequests : 972, 0/s, 0.14/s
inventory.httpfetch.QueuedFetchInventoryRequests : 179, 0/s, -0.14/s
Region (root) # show stats httpserver
httpserver.9000.HTTPRequestsServed : 8649 requests, 0 requests/s, 0 requests/s
httpserver.9000.ProcessedPollResponses : 2075, 0/s, 0.16/s
httpserver.9000.QueuedPollResponses : 0, -62.8/s, 0/s

16:10 - suddenly drops away to 0. I have observed this before... it drops slowly and then suddenly to zero.

Region (root) # show stats inventory
inventory.httpfetch.ProcessedFetchInventoryRequests : 1002, 0/s, 0.07/s
inventory.httpfetch.QueuedFetchInventoryRequests : 149, 0/s, -0.07/s
Region (root) # show stats httpserver
httpserver.9000.HTTPRequestsServed : 8649 requests, 0 requests/s, 0 requests/s
httpserver.9000.ProcessedPollResponses : 2107, 0/s, 0.07/s
httpserver.9000.QueuedPollResponses : 0, 0/s, 0/s

16:10 - show stats

CONNECTION STATISTICS
Client logouts due to no data receive timeout: 0

SAMPLE FRAME STATISTICS
Dilatn SimFPS PhyFPS AgntUp RootAg ChldAg Prims AtvPrm AtvScr ScrLPS
  1.00 52 52.3 0.0 0 0 118 0 49 0

PktsIn PktOut PendDl PendUl UnackB TotlFt NetFt PhysFt OthrFt AgntFt
ImgsFt
     1 70 0 0 0 19.2 0.0 0.0 0.0 0.0
   0.0

MEMORY STATISTICS
Heap allocated to OpenSim : 88 MB
Last heap allocation rate : 1.027 MB/s
Average heap allocation rate: 1.014 MB/s
Process memory : 385 MB

(0025999)
aiaustin (developer)
2014-05-09 09:02
edited on: 2014-05-09 12:11

Some new messages have appeared on the OpenSim.exe console for the OSGrid addon region (using r/24687) that was being used for tests on Mantis 7110 by various OSGrid native avatars today (no HG visitors involved)... these messages appeared some 5 minutes after the last avatar logged off from the region... so it had no avatars on it at the time...

16:59:59 - [FORMS]: Error receiving response from http://inventory.osgrid.org/xinventory: [^] The remote server returned an error: (502) Bad Gateway.. Request: METHOD=GETITEM&ID=6a47e611-5fc9-4ef1-8e53-a4112fb6e1df
16:59:59 - [XINVENTORY SERVICES CONNECTOR]: Exception in GetItem: System.Net.Web
Exception: The remote server returned an error: (502) Bad Gateway.
16:59:59 - [FORMS]: Error receiving response from http://inventory.osgrid.org/xinventory: [^] The remote server returned an error: (502) Bad Gateway.. Request: METHOD=GETITEM&ID=8e169d1b-6eae-4671-9d04-f38f8e99bf53
16:59:59 - [XINVENTORY SERVICES CONNECTOR]: Exception in GetItem: System.Net.Web
Exception: The remote server returned an error: (502) Bad Gateway.
16:59:59 - [FORMS]: Error receiving response from http://inventory.osgrid.org/xinventory: [^] The remote server returned an error: (502) Bad Gateway.. Request: METHOD=GETITEM&ID=97f0db3b-37de-4a61-9493-5747e28d790d
16:59:59 - [XINVENTORY SERVICES CONNECTOR]: Exception in GetItem: System.Net.Web
Exception: The remote server returned an error: (502) Bad Gateway.
16:59:59 - [FORMS]: Error receiving response from http://inventory.osgrid.org/xinventory: [^] The remote server returned an error: (502) Bad Gateway.. Request: METHOD=GETFOLDERCONTENT&PRINCIPAL=e858df02-a860-4b92-937a-2b87e4ebcd6d&FOLDER=d4d3a7
1a-35af-f7c8-5a1e-1125ada1015e
16:59:59 - [XINVENTORY SERVICES CONNECTOR]: Exception in GetFolderContent: The remote server returned an error: (502) Bad Gateway.
17:00:00 - [FORMS]: Error receiving response from http://inventory.osgrid.org/xinventory: [^] The remote server returned an error: (502) Bad Gateway.. Request: METHOD=GETITEM&ID=407feb86-b750-405f-9913-62382251f53d
17:00:00 - [XINVENTORY SERVICES CONNECTOR]: Exception in GetItem: System.Net.Web
Exception: The remote server returned an error: (502) Bad Gateway.
17:00:00 - [FORMS]: Error receiving response from http://inventory.osgrid.org/xinventory: [^] The remote server returned an error: (502) Bad Gateway.. Request: METHOD=GETFOLDERCONTENT&PRINCIPAL=e858df02-a860-4b92-937a-2b87e4ebcd6d&FOLDER=ae3d94fa-122e-f1d7-7773-29ce654e7144
17:00:00 - [XINVENTORY SERVICES CONNECTOR]: Exception in GetFolderContent: The remote server returned an error: (502) Bad Gateway.
17:00:00 - [XINVENTORY SERVICES CONNECTOR]: Exception in GetItem: System.Xml.Xml
Exception: Root element is missing.

(0026002)
aiaustin (developer)
2014-05-09 12:38
edited on: 2014-05-09 14:07

Note that one avatar in tests just before the 502 error above showed up said they were using a proxy, which might explain why the errors showed up differently.

The 502 Bad Gateway error is an HTTP status code that means that one server received an invalid response from another server that it was accessing while attempting to load the web page or fill another request.

(0026014)
aiaustin (developer)
2014-05-10 07:35
edited on: 2014-05-10 13:40

Login, avatar is a cloud, inventory recent tab indicates the inventory is stuck on fetching 2,902 (full inventory is 3,518)

inventory.httpfetch.QueuedFetchInventoryRequests numbers are checked via show stats inventory every few seconds at each of these times

in 5 minutes time slices... the inventory.httpfetch.ProcessedFetchInventoryRequests also rises slowly.. sometimes rising by 1 when the

requests reduces by 1... other times going up by 2 or 3 even as the request rise... so that is not completely stuck.

14:58 14 17 18 19 22

15:03 49 53 56 59 67

15:08 88 89 92 100 98 102 102
     (note this is first time the number reduced from 100 to 98)

15:13 110 111 112 118 120

15:18 123 122 123 127 130 (note another reduction by one from 123 to 122)

15:20 136 141 145 150 148 150 152 (another reduction)

15:23 159 160 159 159 161 159 163 (up and down a bit)

15:25 174 173 177 179 178 182 184

Monitoring closely around 20-25 minutes (avatar still logged on and a cloud and inventory still staying at "Fetching 2,902 Items... -

Since Logoff") but still seems to be rising...

Avatar logged off and messages on console stable.

15:25 184 184 183 182 181 (dropping at a rate of roughly one every 10 to 20 seconds)

Region (root) # show stats inventory
inventory.httpfetch.ProcessedFetchInventoryRequests : 96, 0/s, 0.03/s
inventory.httpfetch.QueuedFetchInventoryRequests : 177, 0/s, -0.03/s
Region (root) # show stats httpserver
httpserver.9000.HTTPRequestsServed : 326 requests, 0 requests/s, 0.02 requests/s
httpserver.9000.ProcessedPollResponses : 135, 0/s, 0.03/s
httpserver.9000.QueuedPollResponses : 0, 0/s, 0/s

15:30 Processed: 100 Queued: 173
       Processed: 101 Queued: 172
       Processed: 103 Queued: 170
       Processed: 105 Queued: 168

15:35 Processed: 112 Queued: 161
       Processed: 113 Queued: 160
       Processed: 114 Queued: 159
       Processed: 116 Queued: 157

Still monitoring to see how long it takes to go to zero.. prediction roughly 20 minutes with sudden drop to zero near that time.

15:40 Processed: 128 Queued: 145
       Processed: 130 Queued: 143
       Processed: 131 Queued: 142
       Processed: 132 Queued: 141

15:45 Processed: 54 Queued: 0
(Sudden drop to zero after about 20 minutes of inactivity as observed before) (54 processed?)

Region (root) # show stats inventory
inventory.httpfetch.ProcessedFetchInventoryRequests : 54, 0/s, 0/s
inventory.httpfetch.QueuedFetchInventoryRequests : 0, 0/s, 0/s
Region (root) # show stats httpserver
httpserver.9000.HTTPRequestsServed : 237 requests, 0 requests/s, 0 requests/s
httpserver.9000.ProcessedPollResponses : 146, 0/s, 0/s
httpserver.9000.QueuedPollResponses : 0, 0/s, 0/s

(0026109)
aiaustin (developer)
2014-05-15 03:12

Typical ping times from host for OSGrid add-on region

ping inventory.osgrid.org = 117ms
ping assets.osgrid.org = 122ms
(0026111)
aiaustin (developer)
2014-05-15 04:17

A test of running an OSGrid region, on a MySQL DB, newly created region with almost no content on it on a new fast Xeon 6 core processor with 32GB memory and a fast internet connection showed identical symptoms and cloud avatar stuck forever. Using OSGrid add-on region release r/24722 (9-May-2014)
(0026306)
aiaustin (developer)
2014-06-19 03:26
edited on: 2014-06-19 03:27

Just to confirm this issue is still present after the 0.8 release and in 0.8.1 dev as at the very latest OSGrid add-on region update (r/24885).

A visit to an OSGrid Plaza (e.g. Wright Plaza) is necessary to allow the avatar to rez and the inventory check to complete on most occasions for a range of avatars before going onto an OSGrid add-on region.

(0026485)
aiaustin (developer)
2014-07-15 07:09

Just again to note that problems related to this error still persist on add-on regions for OSGrid run on my own server using the current standard OSGrid add-on region release r/24921 (for example). Even when the avatar is rezzed, if the inventory coming in is in its "stuck" state... when a region shutdown is done, I still get the read errors and exceptions that relate to a stuck thread being in an aborted state... e.g.

2014-07-15 15:02:22,557 INFO - OpenSim.OpenSimBase [SHUTDOWN]: Closing all threads
2014-07-15 15:02:22,558 INFO - OpenSim.OpenSimBase [SHUTDOWN]: Killing listener thread
2014-07-15 15:02:22,558 INFO - OpenSim.OpenSimBase [SHUTDOWN]: Killing clients
2014-07-15 15:02:22,559 INFO - OpenSim.OpenSimBase [SHUTDOWN]: Closing console and terminating
2014-07-15 15:02:22,560 INFO - OpenSim.Region.Framework.Scenes.Scene [SCENE]: Closing down the single simulator: Vue-Winter
2014-07-15 15:02:22,571 DEBUG - OpenSim.Framework.Monitoring.Watchdog [WATCHDOG]: Removing thread Heartbeat (Vue-Winter), ID 8
2014-07-15 15:02:23,016 DEBUG - OpenSim.Framework.Monitoring.Watchdog [WATCHDOG]: Removing thread Maintenance (Vue-Winter), ID 57
2014-07-15 15:02:23,061 DEBUG - OpenSim.Region.Framework.Scenes.Scene [SCENE]: Persisting changed objects
2014-07-15 15:02:23,066 DEBUG - OpenSim.Services.GridService.GridService [GRID SERVICE]: Deregistering region Vue-Winter (e8378d4c-b374-4edd-b625-e629bc548400) at 6380-6381
2014-07-15 15:02:23,333 DEBUG - OpenSim.OpenSimBase [SHUTDOWN]: Shutting down region Vue-Winter
2014-07-15 15:02:23,606 INFO - OpenSim.Region.DataSnapshot.DataSnapshotManager [DATASNAPSHOT]: Region Vue-Winter is being removed, removing from indexing
2014-07-15 15:02:23,613 DEBUG - OpenSim.Framework.Monitoring.Watchdog [WATCHDOG]: Removing thread InventoryWorkerThread0, ID 40
2014-07-15 15:02:23,615 ERROR - OpenSim.Services.Connectors.XInventoryServicesConnector [XINVENTORY SERVICES CONNECTOR]: Exception in GetItem:
System.Threading.ThreadAbortException: Thread was being aborted.
   at System.Threading.Monitor.Enter(Object obj)
   at OpenSim.Services.Connectors.XInventoryServicesConnector.MakeRequest(String method, Dictionary`2 sendData) in k:\OSGRID\opensim-219d273\OpenSim\Services\Connectors\Inventory\XInventoryServicesConnector.cs:line 506
   at OpenSim.Services.Connectors.XInventoryServicesConnector.GetItem(InventoryItemBase item) in k:\OSGRID\opensim-219d273\OpenSim\Services\Connectors\Inventory\XInventoryServicesConnector.cs:line 404
2014-07-15 15:02:23,621 ERROR - OpenSim.Region.ClientStack.Linden.WebFetchInvDescModule [INVENTORY]: Failed to process queued inventory request f0bb0a02-e981-4962-b5ea-d06f3625ade1 for Ai Austin in Vue-Winter. Exception System.Threading.ThreadAbortException: Thread was being aborted.
   at OpenSim.Services.Connectors.XInventoryServicesConnector.GetItem(InventoryItemBase item) in k:\OSGRID\opensim-219d273\OpenSim\Services\Connectors\Inventory\XInventoryServicesConnector.cs:line 412
   at OpenSim.Region.CoreModules.ServiceConnectorsOut.Inventory.RemoteXInventoryServicesConnector.GetItem(InventoryItemBase item) in k:\OSGRID\opensim-219d273\OpenSim\Region\CoreModules\ServiceConnectorsOut\Inventory\RemoteXInventoryServiceConnector.cs:line 298
   at OpenSim.Region.CoreModules.ServiceConnectorsOut.Inventory.HGInventoryBroker.GetItem(InventoryItemBase item) in k:\OSGRID\opensim-219d273\OpenSim\Region\CoreModules\ServiceConnectorsOut\Inventory\HGInventoryBroker.cs:line 571
   at OpenSim.Capabilities.Handlers.WebFetchInvDescHandler.Fetch(UUID agentID, UUID folderID, UUID ownerID, Boolean fetchFolders, Boolean fetchItems, Int32 sortOrder, Int32& version, Int32& descendents) in k:\OSGRID\opensim-219d273\OpenSim\Capabilities\Handlers\WebFetchInventoryDescendents\WebFetchInvDescHandler.cs:line 276
   at OpenSim.Capabilities.Handlers.WebFetchInvDescHandler.FetchInventoryReply(LLSDFetchInventoryDescendents invFetch) in k:\OSGRID\opensim-219d273\OpenSim\Capabilities\Handlers\WebFetchInventoryDescendents\WebFetchInvDescHandler.cs:line 161
   at OpenSim.Capabilities.Handlers.WebFetchInvDescHandler.FetchInventoryDescendentsRequest(String request, String path, String param, IOSHttpRequest httpRequest, IOSHttpResponse httpResponse) in k:\OSGRID\opensim-219d273\OpenSim\Capabilities\Handlers\WebFetchInventoryDescendents\WebFetchInvDescHandler.cs:line 111
   at OpenSim.Region.ClientStack.Linden.WebFetchInvDescModule.PollServiceInventoryEventArgs.Process(aPollRequest requestinfo) in k:\OSGRID\opensim-219d273\OpenSim\Region\ClientStack\Linden\Caps\WebFetchInvDescModule.cs:line 363
   at OpenSim.Region.ClientStack.Linden.WebFetchInvDescModule.WaitProcessQueuedInventoryRequest() in k:\OSGRID\opensim-219d273\OpenSim\Region\ClientStack\Linden\Caps\WebFetchInvDescModule.cs:line 443
2014-07-15 15:02:23,624 DEBUG - OpenSim.Framework.Monitoring.Watchdog [WATCHDOG]: Removing thread InventoryWorkerThread1, ID 41
2014-07-15 15:02:23,635 INFO - OpenSim.Region.ScriptEngine.XEngine.XEngine [XEngine]: Shutting down 153 scripts in Vue-Winter
2014-07-15 15:02:23,679 INFO - OpenSim.Region.Framework.Scenes.Scene [SCENE]: Closing down the single simulator: Vue-Summer
2014-07-15 15:02:23,703 INFO - OpenSim.Framework.SynchronousRestFormsRequester [FORMS]: Error sending request to http://inventory.osgrid.org/xinventory: [^] Thread was being aborted.. Request: METHOD=GETITEM&ID=8e169d1b-6eae-4671-9d04-f38f8e99bf53
2014-07-15 15:02:23,705 ERROR - OpenSim.Services.Connectors.XInventoryServicesConnector [XINVENTORY SERVICES CONNECTOR]: Exception in GetItem:
System.Threading.ThreadAbortException: Thread was being aborted.
   at OpenSim.Framework.SynchronousRestFormsRequester.MakeRequest(String verb, String requestUrl, String obj, Int32 timeoutsecs, IServiceAuth auth) in k:\OSGRID\opensim-219d273\OpenSim\Framework\WebUtil.cs:line 1086
   at OpenSim.Framework.SynchronousRestFormsRequester.MakeRequest(String verb, String requestUrl, String obj, IServiceAuth auth) in k:\OSGRID\opensim-219d273\OpenSim\Framework\WebUtil.cs:line 1100
   at OpenSim.Services.Connectors.XInventoryServicesConnector.MakeRequest(String method, Dictionary`2 sendData) in k:\OSGRID\opensim-219d273\OpenSim\Services\Connectors\Inventory\XInventoryServicesConnector.cs:line 507
   at OpenSim.Services.Connectors.XInventoryServicesConnector.GetItem(InventoryItemBase item) in k:\OSGRID\opensim-219d273\OpenSim\Services\Connectors\Inventory\XInventoryServicesConnector.cs:line 404
2014-07-15 15:02:23,712 ERROR - OpenSim.Application [APPLICATION]:
APPLICATION EXCEPTION DETECTED: System.UnhandledExceptionEventArgs

Exception: System.NullReferenceException: Object reference not set to an instance of an object.
   at OpenSim.Region.ClientStack.Linden.WebFetchInvDescModule.WaitProcessQueuedInventoryRequest() in k:\OSGRID\opensim-219d273\OpenSim\Region\ClientStack\Linden\Caps\WebFetchInvDescModule.cs:line 447
   at OpenSim.Region.ClientStack.Linden.WebFetchInvDescModule.DoInventoryRequests() in k:\OSGRID\opensim-219d273\OpenSim\Region\ClientStack\Linden\Caps\WebFetchInvDescModule.cs:line 431
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
   at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
   at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state)
   at System.Threading.ThreadHelper.ThreadStart()

Application is terminating: True

2014-07-15 15:02:23,713 DEBUG - OpenSim.Framework.Monitoring.Watchdog [WATCHDOG]: Removing thread Heartbeat (Vue-Summer), ID 42
2014-07-15 15:02:24,010 DEBUG - OpenSim.Framework.Monitoring.Watchdog [WATCHDOG]: Removing thread Maintenance (Vue-Summer), ID 56
2014-07-15 15:02:34,280 DEBUG - OpenSim.Region.Framework.Scenes.Scene [SCENE]: Persisting changed objects
2014-07-15 15:02:34,281 DEBUG - OpenSim.Services.GridService.GridService [GRID SERVICE]: Deregistering region Vue-Summer (96a99077-b715-4951-8ee7-01ebab4c42e2) at 6380-6380
2014-07-15 15:02:34,281 WARN - OpenSim.Framework.Monitoring.Watchdog [WATCHDOG]: 10312 ms since Watchdog last ran. Interval should be approximately 2500 ms
(0026583)
aiaustin (developer)
2014-07-25 07:28
edited on: 2014-07-25 07:38

A note for when this is investigated... the cloud avatar problem, outfits not being available for change and so on are ALL specific potential side effects of the seeming underlying cause of a stuck inventory fetch that will NEVER complete. Its not just a matter of eventually completing... it is really stuck.

Going to an OSGrid Plaza immediately frees up the stuck inventory and it completes.

It occurs on avatar with even a few hundred items, as well as some with a few thousands of inventory items.

The regions are on relatively fast servers and good University speed internet connections, but are located away from the OSGrid core servers of course.

After logout the queued inventory fetches then do seem to clear very gradually one at a time slowly. If you shutdown a simulator that was where the avatar logged in/out it gives the red thread abort message. If you leave it until the queue requests go to zero, it can be closed without any red error message.

My suggestion is that an investigation looks initially at why OSGrid add on regions see this thread aborting message and seem to allow for stuck never completing inventory fetches.

(0026592)
justincc (administrator)
2014-07-25 18:36

As this is likely inventory related, please discuss on Mantis 7054.

- Issue History
Date Modified Username Field Change
2014-04-14 07:18 aiaustin New Issue
2014-04-14 07:29 aiaustin Description Updated View Revisions
2014-04-14 09:29 aiaustin Description Updated View Revisions
2014-04-14 12:37 aiaustin Description Updated View Revisions
2014-04-14 14:29 danbanner Note Added: 0025784
2014-04-15 03:25 aiaustin Note Added: 0025785
2014-04-15 07:14 aiaustin Note Edited: 0025785 View Revisions
2014-04-15 08:46 aiaustin Note Edited: 0025785 View Revisions
2014-04-15 08:47 aiaustin Note Edited: 0025785 View Revisions
2014-04-15 08:51 aiaustin Note Edited: 0025785 View Revisions
2014-04-15 08:59 aiaustin Description Updated View Revisions
2014-04-15 09:36 aiaustin Note Added: 0025786
2014-04-15 15:26 Mata Hari Note Added: 0025787
2014-04-16 00:56 aiaustin Note Added: 0025789
2014-04-16 01:13 aiaustin Note Edited: 0025789 View Revisions
2014-04-16 01:21 aiaustin Relationship added related to 0007054
2014-04-16 01:25 aiaustin Note Added: 0025790
2014-04-16 02:35 Mata Hari Note Added: 0025792
2014-04-16 07:59 aiaustin Note Added: 0025795
2014-04-16 10:52 Mata Hari Note Added: 0025796
2014-04-24 14:39 aiaustin Note Added: 0025890
2014-04-24 14:39 aiaustin Note Edited: 0025890 View Revisions
2014-04-24 14:40 aiaustin Note Edited: 0025890 View Revisions
2014-04-24 17:24 Mata Hari Note Added: 0025892
2014-04-25 05:36 aiaustin Note Added: 0025894
2014-04-25 06:24 aiaustin Summary Cloud avatar on login on OSGrid add-on regions - with difference in handling an attachment with unknown user creator => Cloud avatar forever on login on OSGrid add-on regions
2014-04-25 07:17 aiaustin Note Added: 0025899
2014-04-26 09:05 aiaustin Note Added: 0025909
2014-04-26 09:08 aiaustin Note Edited: 0025909 View Revisions
2014-04-26 09:08 aiaustin Note Edited: 0025909 View Revisions
2014-04-26 09:23 aiaustin Note Added: 0025911
2014-04-26 09:23 aiaustin Note Edited: 0025911 View Revisions
2014-04-26 09:27 aiaustin Note Added: 0025912
2014-04-26 12:19 aiaustin Note Added: 0025914
2014-04-26 12:19 aiaustin Note Edited: 0025914 View Revisions
2014-04-30 04:34 aiaustin Note Added: 0025935
2014-05-01 02:45 aiaustin Note Added: 0025942
2014-05-01 02:47 aiaustin Note Edited: 0025942 View Revisions
2014-05-01 02:48 aiaustin Note Edited: 0025942 View Revisions
2014-05-01 02:51 aiaustin Note Edited: 0025942 View Revisions
2014-05-01 02:55 aiaustin Note Edited: 0025942 View Revisions
2014-05-01 02:57 aiaustin Note Edited: 0025942 View Revisions
2014-05-01 04:09 aiaustin Note Edited: 0025942 View Revisions
2014-05-01 04:10 aiaustin Note Edited: 0025942 View Revisions
2014-05-01 08:45 aiaustin Note Added: 0025944
2014-05-01 08:47 aiaustin Note Edited: 0025944 View Revisions
2014-05-01 08:48 aiaustin Note Edited: 0025944 View Revisions
2014-05-01 14:09 aiaustin Note Added: 0025945
2014-05-01 14:18 aiaustin Note Edited: 0025945 View Revisions
2014-05-01 14:21 Mata Hari Note Added: 0025946
2014-05-02 00:52 aiaustin Note Added: 0025953
2014-05-02 07:30 aiaustin Note Added: 0025955
2014-05-02 07:34 aiaustin Note Edited: 0025955 View Revisions
2014-05-05 07:52 aiaustin Description Updated View Revisions
2014-05-05 07:53 aiaustin Description Updated View Revisions
2014-05-06 05:28 aiaustin Note Added: 0025966
2014-05-06 05:29 aiaustin Note Edited: 0025966 View Revisions
2014-05-06 05:30 aiaustin Note Edited: 0025966 View Revisions
2014-05-08 09:53 aiaustin Note Added: 0025986
2014-05-08 09:58 aiaustin Note Added: 0025987
2014-05-09 08:15 aiaustin Note Added: 0025998
2014-05-09 08:15 aiaustin Note Edited: 0025998 View Revisions
2014-05-09 08:17 aiaustin Note Edited: 0025998 View Revisions
2014-05-09 08:18 aiaustin Note Edited: 0025998 View Revisions
2014-05-09 09:02 aiaustin Note Added: 0025999
2014-05-09 11:38 aiaustin Note Edited: 0025998 View Revisions
2014-05-09 11:55 aiaustin Note Edited: 0025999 View Revisions
2014-05-09 11:56 aiaustin Note Edited: 0025999 View Revisions
2014-05-09 11:57 aiaustin Note Edited: 0025999 View Revisions
2014-05-09 11:58 aiaustin Note Edited: 0025999 View Revisions
2014-05-09 12:11 aiaustin Note Edited: 0025999 View Revisions
2014-05-09 12:12 aiaustin Note Edited: 0025998 View Revisions
2014-05-09 12:38 aiaustin Note Added: 0026002
2014-05-09 12:38 aiaustin Note Edited: 0026002 View Revisions
2014-05-09 14:06 aiaustin Note Edited: 0026002 View Revisions
2014-05-09 14:07 aiaustin Note Edited: 0026002 View Revisions
2014-05-10 07:35 aiaustin Note Added: 0026014
2014-05-10 07:50 aiaustin Note Edited: 0026014 View Revisions
2014-05-10 07:50 aiaustin Note Edited: 0026014 View Revisions
2014-05-10 08:29 aiaustin Note Edited: 0026014 View Revisions
2014-05-10 08:29 aiaustin Note Edited: 0026014 View Revisions
2014-05-10 09:06 aiaustin Note Edited: 0026014 View Revisions
2014-05-10 13:40 aiaustin Note Edited: 0026014 View Revisions
2014-05-13 14:00 aiaustin Note Edited: 0025986 View Revisions
2014-05-13 14:03 aiaustin Note Edited: 0025986 View Revisions
2014-05-15 03:12 aiaustin Note Added: 0026109
2014-05-15 04:17 aiaustin Note Added: 0026111
2014-06-19 03:26 aiaustin Note Added: 0026306
2014-06-19 03:27 aiaustin Note Edited: 0026306 View Revisions
2014-07-15 07:09 aiaustin Note Added: 0026485
2014-07-25 07:28 aiaustin Note Added: 0026583
2014-07-25 07:33 aiaustin Note Edited: 0026583 View Revisions
2014-07-25 07:35 aiaustin Note Edited: 0026583 View Revisions
2014-07-25 07:38 aiaustin Note Edited: 0026583 View Revisions
2014-07-25 18:36 justincc Note Added: 0026592
2014-07-26 03:30 aiaustin Note Edited: 0025942 View Revisions
2014-08-10 02:38 aiaustin Note Edited: 0025987 View Revisions
2014-09-04 04:55 aiaustin Note Added: 0026798
2015-03-02 05:32 aiaustin Note Deleted: 0026798


Copyright © 2000 - 2012 MantisBT Group
Powered by Mantis Bugtracker