Mantis Bug Tracker

View Issue Details Jump to Notes ] Issue History ] Print ]
IDProjectCategoryView StatusDate SubmittedLast Update
0007054opensim[GRID] Inventory Servicepublic2014-03-11 12:552015-05-10 10:30
ReporterMata Hari 
Assigned Tojustincc 
PrioritynormalSeveritymajorReproducibilitysometimes
StatusclosedResolutionfixed 
PlatformIntel i7 930 quad coreOSWindows .NETOS VersionWin7 x64
Product Versionmaster (dev code) 
Target VersionFixed in Versionmaster (dev code) 
Summary0007054: Initial inventory fetch seems to hang occasionally
DescriptionThe initial inventory fetch on login seems to hang occasionally. It rarely occurs if you log in directly to an OSG plaza but is common if you log in to any other region. When it hangs, it will usually do so for about 600 seconds before finally completing, and usually it hangs on the final inventory number (so, if you have 1000 inventory items the viewer will hang on "Fetching....1000 items" before eventually clearing and saying "1000 items").

This does not seem to happen to me at all in my standalone and I only recall experiencing it once with my OSG avi when logging into a Plaza. It happens perhaps 50% of my logins to a non-plaza OSG region.
TagsNo tags attached.
Git Revision or version number
Run Mode Grid (Multiple Regions per Sim)
Physics EngineBulletSim
Environment.NET / Windows64
Mono VersionNone
ViewerFirestorm 4.5.1.38838 OS
Attached Filestxt file icon Mata_stats.txt [^] (345,583 bytes) 2014-03-19 07:26
txt file icon Mata_stats_test2.txt [^] (195,694 bytes) 2014-03-21 05:45 [Show Content]
txt file icon virtual1-aa-before-login.txt [^] (6,040 bytes) 2014-04-16 01:42 [Show Content]
txt file icon virtual1-aa-during-cloud-inv-at-64-a.txt [^] (6,086 bytes) 2014-04-16 01:42 [Show Content]
txt file icon virtual1-aa-during-cloud-inv-at-64-b.txt [^] (6,084 bytes) 2014-04-16 01:42 [Show Content]
txt file icon virtual1-aa-during-cloud-inv-at-64-c.txt [^] (6,061 bytes) 2014-04-16 01:44 [Show Content]
log file icon OpenSim-inventoryfetchhang20140719.log [^] (223,516 bytes) 2014-07-20 06:09
log file icon 2014-08-08-OSGrid-Openvue-OpenSim-Debug-Http-Out-4.log [^] (727,281 bytes) 2014-08-08 12:56
log file icon 2014-08-08-OSGrid-Openvue-OpenSim-Debug-Http-Out-5.log [^] (713,383 bytes) 2014-08-08 13:05
log file icon 2014-08-08-OSGrid-Openvue-OpenSim-Debug-Http-Out-5-Stuck.log [^] (1,156,366 bytes) 2014-08-08 13:15
rar file icon Mata2014-08-09Test1.rar [^] (101,926 bytes) 2014-08-08 21:40
rar file icon Mata2014-08-09Test2.rar [^] (157,933 bytes) 2014-08-09 04:54
rar file icon Mata2014-08-09Test3.rar [^] (431,279 bytes) 2014-08-09 05:59
txt file icon parse.txt [^] (7,652 bytes) 2014-08-09 07:31 [Show Content]
rar file icon empty_cachefetch_log_2015_05_06.rar [^] (302,365 bytes) 2015-05-06 09:22

- Relationships
related to 0007110new Cloud avatar forever on login on OSGrid add-on regions 
related to 0007564closedDiva Inventory download hangs temporarily or permanently 

-  Notes
(0025438)
Mata Hari (reporter)
2014-03-13 08:47

I should add that since I've been watching the fetch more closely it seems to hang part-way through the fetch more often than I'd thought. In fact is seems as though it hangs twice -- once part way through the fetch and then again at the end. Note that this isn't after a cache clear...this happens on pretty much every single non-plaza login.

(In my case it seems to have to fetch about 1000 items each time which seems a little unusual since I'm not wearing/changing to anywhere near that number of items while I'm online. How is it determining what needs fetching and what doesn't?)
(0025469)
justincc (administrator)
2014-03-18 18:04
edited on: 2014-03-18 18:05

Okay, in order to determine what's happening here, as of git master 52b7b40 I have added the following statistics.

scene-inventory.<scene-name>.QueuedFetchInventoryRequests - how many inventory fetch requests are queued for processing.
scene-inventory.<scene-name>.ProcessedFetchInventoryRequests - how many inventory fetch requests have been processed and sent to the poll manager.
httpserver.<port>.QueuedPollResponses - how many responses are queued in the poll manager waiting to be sent on to the viewer.
httpserver.<port>.ProcessedPollResponses - how many responses have been sent to viewers.

You can see the numbers if you run "stats show scene-inventory" and "stats show httpserver" along with a few other incidental numbers.

However, I have also added a "stats save" command which will dump all stats to a file. When your inventory fetch next freezes, please could you execute this and attach the results to this mantis. In fact, two executions a little while apart (say 30 seconds) would be nice to see if there's any change. You can write these reports to the same file since the command will append if the file is already present.

I'm particularly interested in whether the QueuedFetchInventoryRequests stays high and is not decreasing. At the moment, I suspect that one of the inventory service requests gets permanently dropped and we are not properly timing out on the simulator. This would freeze all further inventory requests until restart.

The ProcessedFetchInventoryRequests is also quite an interesting number in generals. On a cold simulator restart, it allows you to compare how many inventory requests a logged in viewer makes when it has had a cache clear and when it hasn't. On my (admittedly very low inventory) avatar, there are 21 requests after cache clear and only 4 requests when inventory data is cached viewer side (this is with Singularity 1.8.4 on Linux).

(0025479)
Mata Hari (reporter)
2014-03-19 07:28

Attached a file containing detailed tests conducted this morning using the latest git. See the file itself for details on overall test conditions and details of each of the 8 tests I did -- details of each test preceed the saves associated with that test. For each data point on the tables I supplied there is a corresponding save in the data that follows it
(0025507)
justincc (administrator)
2014-03-20 19:12

Hi Mata. It does seem a lot of detail but actually it's very helpful.

What it does reveal is that inventory processing never appears to actually block entirely (which was my first suspicion), since both

scene-inventory.Paramour Workshop.ProcessedFetchInventoryRequests
and
httpserver.9000.ProcessedPollResponses

keep increasing, even when your client no longer appears to be receiving objects.

However, at least in the first login, scene-inventory.Paramour Workshop.QueuedFetchInventoryRequests was also continually increasing towards the end, indicating that the simulator was receiving inventory requests quicker than it could handle them. However, it wasn't increasing in login 2, though it was still positive on the last sample.

It's still possible that one inventory thread is getting blocked whilst the other is still going. To monitor this, in git master 47e7feb I have added thread update information to stats. So please could you conduct the first login test again. You don't need to save at regular intervals but just sometime after updates appear to stop, though I wouldn't object to getting another batch of data.
(0025508)
justincc (administrator)
2014-03-20 19:13

You can see the same information with the "show threads" command. What I want to see is whether the time since last update for InventoryWorkerThread0 and InventoryWorkerThread1 are continually increasing or getting reset as requests are processed, and whether both are behaving in the same or whether one is increasing whilst the other is not.
(0025512)
Mata Hari (reporter)
2014-03-21 05:45

Decided to err on the side of giving you too much data so I conducted another batch of tests this morning with r/24462 (though not as many logins as yesterday :) )

Login 1 was a login immediately after the new sim build had finished loading so flotsam cache is empty, and I cleared my viewer cache prior to the login so it's empty 2. Fetch hung at approx 6k items of 7.8k total.

Login 2 was to Sandbox Plaza to finish fetching the rest (took 0000052:0000030-45 sec)

Login 3 was in my region again with total inventory fetch time of about 3.5 minutes (no idea why it might have thought I'd made any inventory changes since the previous one since I'd done absolutely nothing)

Complete details are in the attached file

I only did those 3 logins (and of course data is only from 2 since the middle one was to Sandbox Plaza) but if you want me to repeat any of these or do any other tests I'll happily do so -- just let me know what you'd like.
(0025791)
aiaustin (developer)
2014-04-16 01:40
edited on: 2015-03-04 14:13

During investigation of an avatar rezzing issue on Mantis ttp://opensimulator.org/mantis/view.php?id=7110, [^] Mata Hari suggested this issue may relate.. and I think it does seem to.

I am seeing this problem on add-on regions on our owns servers using the OSGrid add-on region release right up to r/24620. I do NOT see it when I move to or log on to OSGrid Plazas. I also do not see anything like this on our own Openvue grid or add on regions on essentially identical server hardware, OS and network environment. I think this is similar problematic behaviour to what Mata Hari reports.

It occurs in tests with several different avatars on OSGrid, and whether I clear the viewer cache or not. It occurs with Firestorm 4.6.1 and CtrlAltStudio.

I have an avatar with about 3,000 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 with the same viewer with cache intact and the inventory this time only got to 64 items and the avatar stayed as a cloud. Even leaving things for 10 minutes it stayed at 64 and avatar remained a cloud, with attachments in a stuck state not detachable, and the outfits folder entries showing "Loading..." with no current outfit selected.

Stats logs attached for the instance where it stuck at 64

Before login: virtual1-aa-before-login.txt
One minute in inventory at 64 avatar a cloud: virtual1-aa-during-cloud-inv-at-64-a.txt
Four minutes later: virtual1-aa-during-cloud-inv-at-64-b.txt
Four minutes more: virtual1-aa-during-cloud-inv-at-64-c.txt

Then I went to Wright Plaza and inventory immediately started to go up again and reached the total within 20 seconds. Avatar rezzed at some point in that period, indicating its an incoming inventory issue. Returning back to our add-on region the avatar worked fine then. But after logging out and back in the avatar was a cloud again and did not rez even after some minutes, with the inventory saying "Fetching xxx items... even though the number was at the FULL inventory level it had been on when all came in on Wright Plaza.

I left the avatar on the OSGrd add on region with no other activity and showing as a cloud and with inventory stuck fetching for a LONG time (over 15 minutes) and it seemed not to change at all.

(0025797)
aiaustin (developer)
2014-04-16 12:25
edited on: 2014-04-16 12:26

I am seeing this FetchInventory2 message on the OpenSim.exe console for all avatars that show as a cloud and stick like that. This message shows as the last one possibly just before the lockup...

20:21:01 - [LOGHTTP]: Slow handling of 3964 POST /CAPS/e04b6020-d12d-4f19-8b89-e
00551bd5349 FetchInventory2 e858df02-a860-4b92-937a-2b87e4ebcd6d from 92.237.199
.112:50878 took 5109ms

(0025895)
aiaustin (developer)
2014-04-25 06:05
edited on: 2014-04-25 06:06

In case it offers some clues... using Firestorm 4.6.1 on OSGrid...

I had the avatar fully rezzed on OSGrid Wright Plaza and all inventory cached.. (3400 items) all looks stable. The inventory "Recent" tab had gone through messages saying "Searching..." at the top and "Fetching 3,400 Items..." at the bottom and got to the finish where the top shows recent items or the "Didn't find what you're looking for?" message indicating all inventory is cached, and the bottom says "Fetching 3,400 Items... - Since logoff" and the avatar is rezzed.

I then teleported to an OSGrid add on region... all looks okay again.

I logged off and back on and the avatar is a cloud again... and the Recent tab in inventory says "Searching..." at the top but "Fetching 3,400 Items... - Since Logoff" and stays on that forever. the openSuim.exe console log as usual has the single [LOGHTTP]: Slow handling of ...POST...FetchInventory2 message as the last thing before it sticks.

Back to Wright Plaza and from the delay it seems that it is loading ALL the inventory again? Then the avatar rezzes and the Recent tab looks complete.

(0025910)
aiaustin (developer)
2014-04-26 09:11

More clues... an aborted thread error well after logout (still as a cloud) on OpenSim.exe shutdown. Reported over in http://opensimulator.org/mantis/view.php?id=7110 [^]

Can I assume those interested will see both comments attached to both issues? As I am mostly investigating the problem of avatars staying as a cloud on the majority of my logins to OSGrid add-on regions. Though it MAY be related to inventory coming in getting stuck forever.
(0025913)
Mata Hari (reporter)
2014-04-26 10:18

I think for the time being time constraints have forced Justin to put off addressing this bug (the hang on fetch) until after 0.8 is released so probably best to continue reporting primarily in your cloud-avi bug report. There's been no comment at all from the dev side as to whether the issues might be related to perhaps safest to assume that there are independent causes until a dev suggests otherwise. That said, it's possible the fix for both issues will involve the same piece of code.
(0025924)
aiaustin (developer)
2014-04-29 03:40

Noted folks. I would say though that this is my biggest usability issue in 0.8.0 now. On OSGrid essentially on the majority of cases none of my OSGRid avatars can log on to add on regions (all of mine on 3 separate servers). This means we have to ask people to log on at a Plaza and the TP to the add-on region. Not good.
(0025934)
aiaustin (developer)
2014-04-30 02:55
edited on: 2014-04-30 02:58

Mata.. I think the "hanging" on a specific number indicates a PREVIOUS login cache count reached - which might even be the compete set of inventory items. What seems to be happening is that the system is rechecking everything (on Firestorm 4.6.1 anyway) and the message is not showing an incremental count until it reaches the last number it got to. But I observe that it can jam and stop entirely BEFORE that number of reached... in which case it just seems never to change.

(0025936)
aiaustin (developer)
2014-04-30 04:49
edited on: 2014-04-30 04:56

Justin, for stats show scene-inventory did you mean those to be two separate commands...

stats show scene-inventory
No such category as scene-inventory

I see these stats on an OSGrid add on region using r/24670 when the avatar is a cloud... and after the [LOGHTTP]: Slow handling of 370 POST ... FetchInventory2 ... took 6125ms message

Region (root) # stats show list
Statistic categories available are:
  clientstack
  entitytransfer
  httpserver
  inventory
  scene
  server

Region (root) # stats show inventory
inventory.httpfetch.ProcessedFetchInventoryRequests : 113, 0.8/s, 0.07/s
inventory.httpfetch.QueuedFetchInventoryRequests : 24, -0.8/s, 0.09/s

Region (root) # stats show scene
scene.OpenVCE.ActivePrims : 0 objects
scene.OpenVCE.ActiveScripts : 400 scripts
scene.OpenVCE.AgentTime : 0 ms/sec
scene.OpenVCE.AgentUpdates : 0 updates/sec
scene.OpenVCE.ChildAgents : 0 avatars
scene.OpenVCE.FrameTime : 19.1521968841553 ms/sec
scene.OpenVCE.ImageTime : 0 ms/sec
scene.OpenVCE.NetTime : 0 ms/sec
scene.OpenVCE.OtherTime : 0 ms/sec
scene.OpenVCE.PhysicsFPS : 51.9444541931152 fps
scene.OpenVCE.PhysicsTime : 0 ms/sec
scene.OpenVCE.RootAgents : 1 avatars
scene.OpenVCE.ScriptLines : 36.3333320617676 lines/sec
scene.OpenVCE.SimFPS : 52 fps
scene.OpenVCE.SimSpareMS : 18.1818180084229 ms/sec
scene.OpenVCE.SlowFrames : 111 frames
scene.OpenVCE.TimeDilation : 1 sec/sec
scene.OpenVCE.TotalPrims : 4309 objects
scene.Vue-Port.ActivePrims : 0 objects
scene.Vue-Port.ActiveScripts : 49 scripts
scene.Vue-Port.AgentTime : 0 ms/sec
scene.Vue-Port.AgentUpdates : 0 updates/sec
scene.Vue-Port.ChildAgents : 1 avatars
scene.Vue-Port.FrameTime : 19.1521968841553 ms/sec
scene.Vue-Port.ImageTime : 0 ms/sec
scene.Vue-Port.NetTime : 0 ms/sec
scene.Vue-Port.OtherTime : 0 ms/sec
scene.Vue-Port.PhysicsFPS : 52.2500038146973 fps
scene.Vue-Port.PhysicsTime : 0 ms/sec
scene.Vue-Port.RootAgents : 0 avatars
scene.Vue-Port.ScriptLines : 0 lines/sec
scene.Vue-Port.SimFPS : 52 fps
scene.Vue-Port.SimSpareMS : 18.1818180084229 ms/sec
scene.Vue-Port.SlowFrames : 113 frames
scene.Vue-Port.TimeDilation : 1 sec/sec
scene.Vue-Port.TotalPrims : 118 objects

Region (root) # stats show httpserver
httpserver.9000.HTTPRequestsServed : 419 requests, 0 requests/s, 0.28 requests/s
httpserver.9000.ProcessedPollResponses : 167, 0/s, 0.12/s
httpserver.9000.QueuedPollResponses : 0, 0/s, -0.07/s

I then logged the avatar off (it was still a cloud) waited a few minutes with no activity on the OpenSim.exe console and repeated the stats again...

Region (root) # stats show inventory
inventory.httpfetch.ProcessedFetchInventoryRequests : 118, 0.4/s, 0.07/s
inventory.httpfetch.QueuedFetchInventoryRequests : 28, -0.4/s, -0.07/s

Region (root) # stats show scene
scene.OpenVCE.ActivePrims : 0 objects
scene.OpenVCE.ActiveScripts : 394 scripts
scene.OpenVCE.AgentTime : 0 ms/sec
scene.OpenVCE.AgentUpdates : 0 updates/sec
scene.OpenVCE.ChildAgents : 0 avatars
scene.OpenVCE.FrameTime : 19.1521968841553 ms/sec
scene.OpenVCE.ImageTime : 0 ms/sec
scene.OpenVCE.NetTime : 0 ms/sec
scene.OpenVCE.OtherTime : 0 ms/sec
scene.OpenVCE.PhysicsFPS : 52.2500114440918 fps
scene.OpenVCE.PhysicsTime : 0 ms/sec
scene.OpenVCE.RootAgents : 0 avatars
scene.OpenVCE.ScriptLines : 6 lines/sec
scene.OpenVCE.SimFPS : 52 fps
scene.OpenVCE.SimSpareMS : 18.1818180084229 ms/sec
scene.OpenVCE.SlowFrames : 115 frames
scene.OpenVCE.TimeDilation : 1 sec/sec
scene.OpenVCE.TotalPrims : 4022 objects
scene.Vue-Port.ActivePrims : 0 objects
scene.Vue-Port.ActiveScripts : 49 scripts
scene.Vue-Port.AgentTime : 0 ms/sec
scene.Vue-Port.AgentUpdates : 0 updates/sec
scene.Vue-Port.ChildAgents : 0 avatars
scene.Vue-Port.FrameTime : 19.1521968841553 ms/sec
scene.Vue-Port.ImageTime : 0 ms/sec
scene.Vue-Port.NetTime : 0 ms/sec
scene.Vue-Port.OtherTime : 0 ms/sec
scene.Vue-Port.PhysicsFPS : 52.2500038146973 fps
scene.Vue-Port.PhysicsTime : 0 ms/sec
scene.Vue-Port.RootAgents : 0 avatars
scene.Vue-Port.ScriptLines : 0 lines/sec
scene.Vue-Port.SimFPS : 52 fps
scene.Vue-Port.SimSpareMS : 18.1818180084229 ms/sec
scene.Vue-Port.SlowFrames : 116 frames
scene.Vue-Port.TimeDilation : 1 sec/sec
scene.Vue-Port.TotalPrims : 118 objects

Region (root) # stats show httpserver
httpserver.9000.HTTPRequestsServed : 423 requests, 0 requests/s, 0 requests/s
httpserver.9000.ProcessedPollResponses : 177, 0/s, 0.1/s
httpserver.9000.QueuedPollResponses : 0, 0/s, 0/s

(0025943)
aiaustin (developer)
2014-05-01 04:11
edited on: 2014-05-01 04:12

show stats inventory seems to indicate a VERY slow handling of inventory.httpfetch.QueuedFetchInventoryRequests even long after the avatar has logged off and the sim is idling.

See comments added to http://opensimulator.org/mantis/view.php?id=7110#c25942 [^]

(0025990)
aiaustin (developer)
2014-05-08 10:28

I think JustinCC is correct and a total block occurs ... when he said "At the moment, I suspect that one of the inventory service requests gets permanently dropped and we are not properly timing out on the simulator. This would freeze all further inventory requests until restart."

Some notes are in the comments in the linked issue 7110.

http://opensimulator.org/mantis/view.php?id=7110#c25986 [^]
(0026307)
aiaustin (developer)
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.
(0026308)
Mata Hari (reporter)
2014-06-19 06:34

Yes, still experiencing this as well as of 24885
(0026516)
Mata Hari (reporter)
2014-07-20 06:08

A friend of mine has been experiencing this bug for at least as long as I have however as of yesterday she now not able to complete her inventory fetch even if she logs in to an OGS plaza.

Last night I asked her to log in directly to my sim so we could watch the console and see if there were any unusual messages.

Prior to her login I restarted the instance and I went to a different region (different instance) so she would be the only avi that the instance was handling. Instance was running r/24931 opensim-2766bf3.

See attached log for complete log from the time of her arrival: OpenSim-inventoryfetchhang20140719.log

While I don't see anything in terms of error messages, you'll notice that after about 15 minutes the sim seems to get locked into an infinite loop where it:
- makes about a set of about a dozen reports of [LOGHTTP] Slow SynchronousRestForms all about the exact same folder,
- then it will rapidly spit out about 20 lines saying [USER MANAGEMENT MODULES] No grid user found (presumably relating items obtained while HGing)
- then it goes back to repeating the slow folder, etc

This loop continues without change for the next 0000015:0000045 minutes.

We were in constant IM communication during that time and up until that cycle started her inventory fetch was proceeding (slowly, but at least the count was climbing) but once that loop began her inventory count never changed.

She indicated that the count at the time of the "hang" is at about the same point that it now occurs when she logs into a OSG plaza (though of course it enters that loop more rapidly).

While I am not *certain*, we believe that the folder that is continually being fetched in that loop is her root level "Objects" folder. It's also worth noting that in the last day or two she has made a number of HG jumps and done some HG "shopping".

Eventually (after an hour or so and no signs at all that the inventory fetch would ever exit the loop) you will see that I entered the region. When I did so, it was much much laggier than I ever experience with two avi present there. Earlier in the day when we were both at another person's sim the same issue was happening -- to the point that if someone changed an item of clothing such as hair or a boot it would take between 20 minutes and an hour before the object finally rezzed in the viewers of other people on the region. My guess is that the region was locked in is in this infinite loop for her inventory and it was tying up a ton of resources for that and therefore wasn't getting around to fetching or delivering anyone else's stuff for a long time. That region was extremely laggy and attempts made by other users to tp into it often failed. I have seen this as a common occurrence in any regions where someone logs directly into it, particularly with an empty cache.

You will also see that the fetch loop still continued for her inventory in my region for some time *after* she had left the region! It wasn't until a few minutes later that it finally stopped.

Shortly after that, I logged out.

The particular instance we used for this test usually uses about 1GB of process memory and sits stable at that value. During that entire time from startup until midnight not a single new item was rezzed to the ground, deleted, or in any way changed.

You'll notice that it did an auto-report very shortly after she logged into the region and at that time the process memory was 1252MB (again, about normal when an avi is in the region) but then it started to climb drastically in spite of all that happened was my tp in, then her tp out, then my logout. Shortly after my logout the process memory usage was 2378 and over night it climbed by another 100k in spite of there being absolutely zero activity on the sim. The memory was never released...until I shut down the region.

I hope this new data might somehow help you track down the cause of the issue or at least perhaps suggest a way that you might be able to catch an infinite loop and somehow exit it...there are many users afflicted with this issue to varying degrees and it's extremely frustrating for all of us to have something as fundamental as logging into the grid be bugged, and even more so when it can also have a drastic effect on the performance that region. As it stands, the inventory fetch bug would be a great one for a griefer to exploit.
(0026517)
Mata Hari (reporter)
2014-07-20 07:54

An additional point of interest:

The same friend told me this morning that she was able to log to a OSG plaza, wait for the fetch to hit the infinite loop, then HG tp to Metro grid. Very shortly after her arrival at Metro her inventory fetch completed!

I believe Metro still runs 0.7.6 so that would tend to suggest/confirm that the issue is one that was introduced at some point during 0.8
(0026518)
Ken Grunke (reporter)
2014-07-20 08:50

On first login this morning to Osgrid's Sandbox Plaza, my inventory loaded completely. I tp'ed to one of my regions which had not been updated for about a month and noticed the inventory fetch hang, just short of the total count. I updated that region to the latest dev master and logged direct to it, but inventory was still hanging at same count.
On the console I noticed a few

"[UTIL]: An error occurred while resolving host name..."

that were pointing to hypergrid addresses which I guessed to be no longer active. I removed the hypergrid friends with the specific addresses and right after that was done, my inventory loaded completely. Not sure if it's just concidence, but I'm wondering if defunct hypergrid addresses can cause one's inventory to hang?
(0026519)
aiaustin (developer)
2014-07-20 09:48
edited on: 2014-07-20 09:49

Those observations by Mata Hari are entirely consistent with my own observations. Oncluding the oriblem persisting fir a while after the avatar eith the problem logs off, before things finally free up... after I think some sort of final timeout... but if I try to close dien the OpenSim.exe instance before that timeout occurs then I get the red aborted thread error I have reported before.. and which I have repeatedly seen as recent,y as r/24921 which ought to give a clue. See http://opensimulator.org/mantis/view.php?id=7110 [^]

It always seems to be OSGrid add on regions for this issue for my observations. The problems never occur on Openvue grid add on region servers on an almost identical server setup.

(0026521)
aiaustin (developer)
2014-07-20 10:01
edited on: 2014-07-20 10:02

We are likely to have many hypergrid related references in objects as creators, previous owners, as well as possibly friends calling cards. Inventory fetch needs to be absolutely reliable even if the servers are not available, or even if indeed the domain names used have long gone.

I have also previously reported that OSGrid does not appear to support HELO requests... and I note that here in case that is a possible relationship... See http://opensimulator.org/mantis/view.php?id=7127 [^]

(0026527)
aiaustin (developer)
2014-07-21 01:32
edited on: 2014-07-21 01:35

I should add that I can consistently force the "aborted thread" red error reported in http://opensimulator.org/mantis/view.php?id=7110#c25944 [^] if I shutdown the OSGrid add on regions OpenSim.exe instance just after logging out an avatar who has stuck inventory fetch and if I don't wait a few minutes for the timeouts to occur. Could hat help pin things down.

Mata... can you try the same on one of your problematic OSGrid add on region servers?

(0026546)
Mata Hari (reporter)
2014-07-22 05:02

@AiAustin

Just did a few tests with r/24978 and consistently when I log in my inventory fetch will hang after a while. If I then log out and wait the ~minute it takes for the region to attempt to notify HG friends of my offline status (which it appears to handle sequentially!) and then when that finally settles down I shut down the instance I consistently get 3 error messages and it terminates with Windows error (ie the proper shut down process never completes)

Error messages:

2014-07-22 07:56:20,760 INFO - OpenSim.Framework.SynchronousRestFormsRequester [FORMS]: Error receiving response from http://inventory.osgrid.org/xinventory: [^] Thread was being aborted.. Request: METHOD=GETITEM&ID=fb65bfe3-8861-4993-97a4-326d731dbbdd
2014-07-22 07:56:20,776 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 c:\opensim\OpenSim\Services\Connectors\Inventory\XInventoryServicesConnector.cs:line 506
   at OpenSim.Services.Connectors.XInventoryServicesConnector.GetItem(InventoryItemBase item) in c:\opensim\OpenSim\Services\Connectors\Inventory\XInventoryServicesConnector.cs:line 404
2014-07-22 07:56:20,791 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 c:\opensim\OpenSim\Framework\WebUtil.cs:line 1087
   at OpenSim.Framework.SynchronousRestFormsRequester.MakeRequest(String verb, String requestUrl, String obj, IServiceAuth auth) in c:\opensim\OpenSim\Framework\WebUtil.cs:line 1101
   at OpenSim.Services.Connectors.XInventoryServicesConnector.MakeRequest(String method, Dictionary`2 sendData) in c:\opensim\OpenSim\Services\Connectors\Inventory\XInventoryServicesConnector.cs:line 507
   at OpenSim.Services.Connectors.XInventoryServicesConnector.GetItem(InventoryItemBase item) in c:\opensim\OpenSim\Services\Connectors\Inventory\XInventoryServicesConnector.cs:line 404
2014-07-22 07:56:21,056 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 c:\opensim\OpenSim\Region\ClientStack\Linden\Caps\WebFetchInvDescModule.cs:line 447
   at OpenSim.Region.ClientStack.Linden.WebFetchInvDescModule.DoInventoryRequests() in c:\opensim\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
(0026549)
aiaustin (developer)
2014-07-22 06:04
edited on: 2014-07-22 06:10

My experience is that if you wait about 5 minutes, but sometimes as much as 20 minutes, the inventory.httpfetch.QueuedFetchInventoryRequests shown by "stats show inventory" gradually reduces to zero and you can then shut down the OpenSim.exe add on region server without the errors. But of "stats show inventory" shows any number but zero you will get the "Thread was being aborted" error on shutdown.

I think we have some sort of consistent behaviour across several hosts and add on region setups from different users.

It may relate to some items in inventories, so only show for certain users who have more inventory than others. but I have observed it on some test avatars with only very small and relatively simple inventories too.

I only see this problem on OSGrid add on regions in my setups and never on our own Openvue grid on near identical servers, so I have to suspect the issue may be in the way OSGrid handles inventory and what happens when threads may abort at the OSGrid central services end but the add on region server and the viewer client is never told.

Its a real pain and effectively makes it impossible to have users log on to region directly... Try telling users they must go via another location, wait until they are all in good shape and then go where you really intended them to arrive.

(0026584)
aiaustin (developer)
2014-07-25 07:37
edited on: 2014-07-25 07:38

A note for when this is investigated...from the linked issue 7110.. 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.

(0026589)
Mata Hari (reporter)
2014-07-25 16:07

@Justin

Saw your commit r/24985

Is this something you want us to try playing around with different values and report back results? If so, where/how is this value set?
(0026590)
justincc (administrator)
2014-07-25 16:10

That was the plan, but then I decided simply to set up a region from home connected to osgrid myself.

So far, I'm seeing what you see - inventory requests take a long time (some 20 to 25 seconds). Question now is to determine whether that's a some relatively simple issue on the osgrid end, and/or whether I need to implement an inventory cache on the simulator, which should be possible on the same principles as the viewer side one.
(0026591)
justincc (administrator)
2014-07-25 18:31

Alright, here's the situation.

I tested initially with a region attached to osgrid from my home, which has a pretty good network connection (152 mbit down). Initially, I saws similar problems, where some inventory requests would take 20 to 25 seconds.

However, on every subsequent run, I could not reproduce that issue.

Personally, I still suspect this is overloading on the OSGrid inventory service, though network factors can still come into play. To this end, I have inserted extra stats service-side to show how many requests it is receiving. When it's at high load again (probably >150 req/s) I hope to try reproducing this problem.

However, I'm also very surprised that you keep seeing this. The viewer should be caching inventory information and not request it all every time you log back in. This does not happen to me with my 38000 OSGrid inventory. Are you clearing cache every time when you are testing?

I have also added a new inventory.<remote-url>.RequestsMade stat to show how many requests are actually going to the inventory service. ProcessedFetchInventoryRequests does not capture them all as there can be multiple inv service calls per request and requests come from other sources (hg, archiving, etc.).

Also, there is now an undocumented RemoteRequestTimeout parameter in [InventoryService] which will reduce the timeout from the default 100 secs to a different number of seconds. I suggest trying with 10. You should see timeout messages on the console but I would be interested if it's just one or two that fail or whether there's consistent failure. It is true at the moment that just a single 'stuck' request will hold up every other request in the system.

Finally, even with a viewer that does cache inventory data properly, inventory requests can come from other sources such as archiving and these can be pretty heavy. The ultimate solution may be to implement inventory data caching on the simulator in the same way that the viewer caches inventory info. This would greatly reduce the number of requests to central inventory services. However, this is not a 5 minute job to implement.
(0026593)
aiaustin (developer)
2014-07-26 03:19
edited on: 2014-07-26 03:33

Will make all notes related to issue 7110 here now.

Definitely NOT inventory cache in viewer each time Justin. Problem occurs even immediately after going to a plaza, allowing the inventory to complete, logging off, then logging back onto an add-on region. And occurs on avatars with relatively small inventory too.

See the stats of inventory fetch request that are pending and not completed. I think the issue is that some get lost completely and NEVER complete... but the server is waiting for them and always leaves them pending. They only clear after the user logs out and then after a LONG tome presumably as some sort of log out triggered time out occur.

Please look also at my stats logs in issue 7110.

Which viewer are you using Justin? I usually use Firestorm 4.6.5 OS though I have tested other viewers such a Singularity and same problem occurs, so I am not anticipating this is a viewer issue.

(0026594)
aiaustin (developer)
2014-07-26 03:25
edited on: 2014-07-26 03:28

Justin, you say a single stuck requests will hold up every other request. But surely that is the problem. We have VERY many pending requests held up.... sometimes 100 even with one avatar logging in, no other activity at all, but inventory fetch stuck.. which never complete and may be in a "thread aborting" state after user log off and when sim is shutdown?

See my stats log of served and pending requests at

http://opensimulator.org/mantis/view.php?id=7110#c25942 [^]

(0026595)
aiaustin (developer)
2014-07-26 04:26

I assume default is still 100 secs in the current GIT master and you want us to test with a modified OSGrid add on release to include the new bits and set GridCommon.ini for the OSGrid add on to this...


[InventoryService]
    InventoryServerURI = "http://inventory.osgrid.org" [^]
    RemoteRequestTimeout = 10
(0026604)
Mata Hari (reporter)
2014-07-26 04:45

Like AiAustin I use Firestorm's latest release for Opensim (Win7 64). I only clear my cache when some other bug forces me to do so and when that happens I only ever log to a plaza because it's much faster. The vast majority of my logins are with full cache; and as Austin says I can log into a plaza, wait for fetch to finish (usually almost instantaneous) then log immediately back out again without doing anything. In theory I should have a completely up-to-date cache but if I log in to my own sim I will show as needing to fetch 1k-2k items and it will hang. I'm pretty thorough about archiving things I'm not using so my inventory is usually between 8k and 12k items total. While my connection isn't quite as fast as yours, it consistently gives me between 75mbit and 880mb down which ought to be more than sufficient.

It's worth remembering that this issue isn't an old one. Inventory fetch does not hang if I run a 0.7.6 instance instead and log into it. If I recall correctly fetch issues didn't start until sometime very late last year and prior to that, when my fetch was working perfectly, I was on my old ISP connection that was only 35mbit down. I would think those factors, combined, would tend to make the traffic hypothesis less likely.
(0026610)
Mata Hari (reporter)
2014-07-26 05:35

Did a clean, new build of r/24988 opensim-327632d and set the RemoteRequestTimeout to 10. Logged directly into my own sim. Viewer cache NOT cleared. Inventory fetch count started at just over 10k and for the first minute or so it gradually increased to 11,084 (iirc my total current inventory is about 11.4k) and then hung.

I left myself standing there for almost half an hour...not a single message in log or console about timeout or any other messages at all. Still sitting at 11,084.

Currently my AO (built-in Firestorm one) is non-functional so it hasn't been able to load that yet. When I attempt to expand all folders in my inventory I can see in the #Firestorm #AO folder it is missing (hasn't yet been able to fetch) my entries in Falling, Flying, Flying Up, Running, Standing, and Swimming Down. The rest are all there. (These are "links" entries to animations in other inventory folders). Scrolling down through the rest of my inventory I don't see any other folders that haven't yet loaded so it would seem likely that it's only the AO one that's the culprit of the fetch hangup.

When I've done the same in the past I have noticed that the outfits folder is another one that commonly fails to load -- another folder that contains only links to items elsewhere in inventory. When that folder fails to fully load (even partially) *all* outfits are unavailable and I am unable to change clothes at all.

After 45 minutes, still stuck at 11,084 and still without a single console or log message, I logged the avi out.
(0026611)
Mata Hari (reporter)
2014-07-26 05:47
edited on: 2014-07-26 05:49

I then logged to a plaza and by the time I was able to see my screen my inventory had fully loaded. I then turned off my AO, logged out, then logged back into my sim again. My inventory fetch stalled immediately at 10,612 and my entire Firestorm AO folder failed to fetch (so the ones that had loaded in my previous attempt and the ones added when I logged into the plaza were all gone). Turning AO back on did nothing.

I also notice that none of the OpenSim Library folders have any contents so it hasn't fetched any of those yet either.

I assume this means that the contents of at least those 2 main folders (and all of their subfolders) aren't kept in the viewer cache and have to be fetched freshly each time.

(0026612)
aiaustin (developer)
2014-07-26 05:55
edited on: 2014-07-26 08:35

r/24988 built over the OSGrid add on release for OpenVCE region on a quite fast Xeon 6 core server on Windows 8.1 Pro on University speed network with nothing else running. ping to inventory.osgrid.org = 117ms consistently.

Initially with no RemoteRequestTimeout set in config-include/GridCommon.ini

Using an avatar with a few hundreds of inventory items rather than a large inventory. Firestorm 4.6.5. Cache not cleared since last logoff. Cache counter on Inventory tool Recent tab starts about 200 (even when count was higher on last logoff) and cunt up to 364 and then sticks - apparently forever. Avatar has rezzed, but Outfits tool shows all outfits cannot yet be "replaced" - that option is greyed out.

show stats inventory shows the queued number going up and down around 10-16 items. No other activity for some time.

I log out of the viewer, no messages after logout. I leave things a few minutes more than 100 seconds. No more console messages. and a minute later shutdown the OpenSim.exe instance and I get the thread abort red error, etc as reported before.

I set the RemoteRequestTimeout to 10 and restart.

Log back on to same OpenVCE region on OSGrid with same avatar. Again it starts counting up inventory from 270 or so.. not the 364 it was at before... and again it sticks at 364 - not always sticking at the same number in previous runs, but today on 4 times it was 364 each time if that is any clue.

queued requests climb slowly... 55 after a few minutes.. and still rising...

Region (root) # show stats inventory
inventory.http://inventory.osgrid.org.RequestsMade [^] : 3051 requests, 4 requests/s, 4.1 requests/s
inventory.httpfetch.ProcessedFetchInventoryRequests : 63, 0/s, 0.07/s
inventory.httpfetch.QueuedFetchInventoryRequests : 55, 0/s, 0.09/s

I see no timeouts, etc. Inventory count still stuck in viewer at 364, and outfits still do not show that replace is allowed yet. I log out of viewer..

The show stats inventory command indicates that the queued inventory fetch requests fall slowly at a rate of about 2 queued requests every minute...

Region (root) # show stats inventory
inventory.http://inventory.osgrid.org.RequestsMade [^] : 3826 requests, 4.4 request
/s, 4.02 requests/s
inventory.httpfetch.ProcessedFetchInventoryRequests : 77, 0/s, 0.07/s
inventory.httpfetch.QueuedFetchInventoryRequests : 60, 0/s, -0.07/s
Region (root) #
13:54:21 - [LOGHTTP]: Slow SynchronousRestForms request 4084 POST to http://invntory.osgrid.org/xinventory [^] took 6235ms, 360ms writing, METHOD=GETITEM&ID=ff36e0c-95d6-4ba6-a4d3-40896177509d
Region (root) # show stats inventory
inventory.http://inventory.osgrid.org.RequestsMade [^] : 4251 requests, 4.4 request/s, 3.91 requests/s
inventory.httpfetch.ProcessedFetchInventoryRequests : 86, 0/s, 0.09/s
inventory.httpfetch.QueuedFetchInventoryRequests : 51, 0/s, -0.09/s

But even after 20 minutes by the time the queued requests had finally gone down at a rate of about 2 a minute there are no timeout messages at all. I am sure if I closed down the sim I would get the thread abort exception. But this time I let the queued request eventually go to 0 and then shutdown, and I get a clean shutdown in this situation as expected.

I wonder if RemoteRequestTimeout is working as expected? What messages should it show if there is a timeout?

(0026613)
Mata Hari (reporter)
2014-07-26 05:59
edited on: 2014-07-26 06:01

On shutting down my new instance it crashed to desktop with Windows error but did manage to write to log before doing so.

2014-07-26 08:54:07,222 INFO - OpenSim.OpenSimBase [SHUTDOWN]: Closing all threads
2014-07-26 08:54:07,223 INFO - OpenSim.OpenSimBase [SHUTDOWN]: Killing listener thread
2014-07-26 08:54:07,223 INFO - OpenSim.OpenSimBase [SHUTDOWN]: Killing clients
2014-07-26 08:54:07,224 INFO - OpenSim.OpenSimBase [SHUTDOWN]: Closing console and terminating
2014-07-26 08:54:07,225 INFO - OpenSim.Region.Framework.Scenes.Scene [SCENE]: Closing down the single simulator: Paramour
2014-07-26 08:54:07,272 DEBUG - OpenSim.Framework.Monitoring.Watchdog [WATCHDOG]: Removing thread Heartbeat (Paramour), ID 69
2014-07-26 08:54:07,713 DEBUG - OpenSim.Framework.Monitoring.Watchdog [WATCHDOG]: Removing thread Maintenance (Paramour), ID 84
2014-07-26 08:54:07,727 DEBUG - OpenSim.Region.Framework.Scenes.Scene [SCENE]: Persisting changed objects
2014-07-26 08:54:07,758 DEBUG - OpenSim.Services.GridService.GridService [GRID SERVICE]: Deregistering region Paramour (44763c19-a5e1-4164-924e-3ded3ad7b094) at 9870-9910
2014-07-26 08:54:07,931 DEBUG - OpenSim.OpenSimBase [SHUTDOWN]: Shutting down region Paramour
2014-07-26 08:54:07,938 DEBUG - OpenSim.Region.OptionalModules.Avatar.Voice.VivoxVoice.VivoxVoiceModule [VivoxVoice] Sending request <http://www.osp.vivox.com/api2/viv_chan_search.php?cond_channame=44763c19-a5e1-4164-924e-3ded3ad7b094D&auth_token=*****-admin:1456375224:860b16458713428350d8deefc0a2e6a0:174.113.18.157> [^]
2014-07-26 08:54:08,074 DEBUG - OpenSim.Region.OptionalModules.Avatar.Voice.VivoxVoice.VivoxVoiceModule [VivoxVoice]: region Paramour: uuid 44763c19-a5e1-4164-924e-3ded3ad7b094: located directory id 2490775
2014-07-26 08:54:08,074 DEBUG - OpenSim.Region.OptionalModules.Avatar.Voice.VivoxVoice.VivoxVoiceModule [VivoxVoice] Sending request <http://www.osp.vivox.com/api2/viv_chan_search.php?&cond_chanparent=2490775&auth_token=*****-admin:1456375224:860b16458713428350d8deefc0a2e6a0:174.113.18.157> [^]
2014-07-26 08:54:08,185 DEBUG - OpenSim.Region.OptionalModules.Avatar.Voice.VivoxVoice.VivoxVoiceModule [VivoxVoice] Sending request <http://www.osp.vivox.com/api2/viv_chan_mod.php?mode=delete&chan_id=2506042&auth_token=*****-admin:1456375224:860b16458713428350d8deefc0a2e6a0:174.113.18.157&chan_parent=2490775> [^]
2014-07-26 08:54:08,306 DEBUG - OpenSim.Region.OptionalModules.Avatar.Voice.VivoxVoice.VivoxVoiceModule [VivoxVoice] Sending request <http://www.osp.vivox.com/api2/viv_chan_mod.php?mode=delete&chan_id=2490775&auth_token=*****-admin:1456375224:860b16458713428350d8deefc0a2e6a0:174.113.18.157> [^]
2014-07-26 08:54:08,423 INFO - OpenSim.Region.DataSnapshot.DataSnapshotManager [DATASNAPSHOT]: Region Paramour is being removed, removing from indexing
2014-07-26 08:54:08,667 INFO - OpenSim.Region.ScriptEngine.XEngine.XEngine [XEngine]: Shutting down 106 scripts in Paramour
2014-07-26 08:54:08,734 DEBUG - OpenSim.Framework.Monitoring.Watchdog [WATCHDOG]: Removing thread InventoryWorkerThread0, ID 61
2014-07-26 08:54:08,735 DEBUG - OpenSim.Framework.Monitoring.Watchdog [WATCHDOG]: Removing thread InventoryWorkerThread1, ID 62
2014-07-26 08:54:08,749 INFO - OpenSim.Region.Framework.Scenes.Scene [SCENE]: Closing down the single simulator: Paramour Workshop
2014-07-26 08:54:08,749 ERROR - OpenSim.Services.Connectors.XInventoryServicesConnector [XINVENTORY SERVICES CONNECTOR]: Exception in GetFolder:
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 c:\opensim\OpenSim\Services\Connectors\Inventory\XInventoryServicesConnector.cs:line 537
   at OpenSim.Services.Connectors.XInventoryServicesConnector.GetFolder(InventoryFolderBase folder) in c:\opensim\OpenSim\Services\Connectors\Inventory\XInventoryServicesConnector.cs:line 455
2014-07-26 08:54:08,806 DEBUG - OpenSim.Framework.Monitoring.Watchdog [WATCHDOG]: Removing thread Heartbeat (Paramour Workshop), ID 79
2014-07-26 08:54:08,824 INFO - OpenSim.Framework.SynchronousRestFormsRequester [FORMS]: Error sending request to http://inventory.osgrid.org/xinventory: [^] Thread was being aborted.. Request: METHOD=GETFOLDERCONTENT&PRINCIPAL=40b437d8-3ba9-4dfe-c8eb-4826bb458433&FOLDER=2bd3f1d7-2188-29ad-3422-ea0928495591
2014-07-26 08:54:08,826 WARN - OpenSim.Services.Connectors.XInventoryServicesConnector [XINVENTORY SERVICES CONNECTOR]: Exception in GetFolderContent: Thread was being aborted.
2014-07-26 08:54:08,868 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 c:\opensim\OpenSim\Region\ClientStack\Linden\Caps\WebFetchInvDescModule.cs:line 447
   at OpenSim.Region.ClientStack.Linden.WebFetchInvDescModule.DoInventoryRequests() in c:\opensim\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-26 08:54:09,249 DEBUG - OpenSim.Region.Framework.Scenes.Scene [SCENE]: Persisting changed objects
2014-07-26 08:54:09,253 DEBUG - OpenSim.Services.GridService.GridService [GRID SERVICE]: Deregistering region Paramour Workshop (63c3eab3-fd6f-4fa7-b2c8-b136cadf3e3d) at 9869-9913
2014-07-26 08:54:09,458 DEBUG - OpenSim.OpenSimBase [SHUTDOWN]: Shutting down region Paramour Workshop
2014-07-26 08:54:09,459 DEBUG - OpenSim.Region.OptionalModules.Avatar.Voice.VivoxVoice.VivoxVoiceModule [VivoxVoice] Sending request <http://www.osp.vivox.com/api2/viv_chan_search.php?cond_channame=63c3eab3-fd6f-4fa7-b2c8-b136cadf3e3dD&auth_token=*****-admin:1456375224:860b16458713428350d8deefc0a2e6a0:174.113.18.157> [^]
2014-07-26 08:54:09,600 DEBUG - OpenSim.Region.OptionalModules.Avatar.Voice.VivoxVoice.VivoxVoiceModule [VivoxVoice]: region Paramour Workshop: uuid 63c3eab3-fd6f-4fa7-b2c8-b136cadf3e3d: located directory id 2490776
2014-07-26 08:54:09,601 DEBUG - OpenSim.Region.OptionalModules.Avatar.Voice.VivoxVoice.VivoxVoiceModule [VivoxVoice] Sending request <http://www.osp.vivox.com/api2/viv_chan_search.php?&cond_chanparent=2490776&auth_token=*****-admin:1456375224:860b16458713428350d8deefc0a2e6a0:174.113.18.157> [^]
2014-07-26 08:54:09,603 DEBUG - OpenSim.Framework.Monitoring.Watchdog [WATCHDOG]: Removing thread Maintenance (Paramour Workshop), ID 83
2014-07-26 08:54:09,705 DEBUG - OpenSim.Region.OptionalModules.Avatar.Voice.VivoxVoice.VivoxVoiceModule [VivoxVoice] Sending request <http://www.osp.vivox.com/api2/viv_chan_mod.php?mode=delete&chan_id=2490776&auth_token=*****-admin:1456375224:860b16458713428350d8deefc0a2e6a0:174.113.18.157> [^]
2014-07-26 08:54:09,826 INFO - OpenSim.Region.DataSnapshot.DataSnapshotManager [DATASNAPSHOT]: Region Paramour Workshop is being removed, removing from indexing
2014-07-26 08:54:09,937 INFO - OpenSim.Region.ScriptEngine.XEngine.XEngine [XEngine]: Shutting down 31 scripts in Paramour Workshop
2014-07-26 08:54:09,952 DEBUG - OpenSim.Region.OptionalModules.Avatar.Voice.VivoxVoice.VivoxVoiceModule [VivoxVoice] Sending request <http://www.osp.vivox.com/api2/viv_signout.php?auth_token=*****-admin:1456375224:860b16458713428350d8deefc0a2e6a0:174.113.18.157> [^]
2014-07-26 08:54:10,056 INFO - OpenSim.Region.OptionalModules.Avatar.XmlRpcGroups.SimianGroupsServicesConnectorModule [SIMIAN-GROUPS-CONNECTOR]: Closing SimianGroupsServicesConnector
2014-07-26 08:54:10,056 DEBUG - OpenSim.Region.OptionalModules.Avatar.XmlRpcGroups.XmlRpcGroupsServicesConnectorModule [XMLRPC-GROUPS-CONNECTOR]: Closing XmlRpcGroupsServicesConnector
2014-07-26 08:54:10,182 WARN - OpenSim.Region.DataSnapshot.DataSnapshotManager [DATASNAPSHOT]: Unable to decode reply from data service. Ignoring. at System.IO.MemoryStream.Read(Byte[] buffer, Int32 offset, Int32 count)
   at OpenSim.Region.DataSnapshot.DataSnapshotManager.NotifyDataServices(String servicesStr, String serviceName) in c:\opensim\OpenSim\Region\DataSnapshot\DataSnapshotManager.cs:line 402
2014-07-26 08:54:10,183 INFO - OpenSim.Region.DataSnapshot.DataSnapshotManager [DATASNAPSHOT]: data service http://search.osgrid.org/register.php [^] notified. Secret: 3e766d1e-642e-40bf-981c-7638258c6994
2014-07-26 08:54:10,195 INFO - OpenSim.Framework.Servers.BaseOpenSimServer [SHUTDOWN]: Shutdown processing on main thread complete. Exiting...

(0026614)
aiaustin (developer)
2014-07-26 06:02

I put the time down to roughly when we moved to .net4 but that may not be the actual cause.. just an indication of the rough time it started. And it started on all my OSGrid add on regions, but none of my other setups or our own grid.
(0026615)
aiaustin (developer)
2014-07-26 06:07
edited on: 2014-07-26 06:11

My windows level does not crash... but if I shutdown whenever there is a remaining queued inventory request I get the thread abort error. I.e. the key messages I think are of this form...


2014-07-26 08:54:08,824 INFO - OpenSim.Framework.SynchronousRestFormsRequester [FORMS]: Error sending request to http://inventory.osgrid.org/xinventory: [^] [^] Thread was being aborted.. Request: METHOD=GETFOLDERCONTENT&PRINCIPAL=40b437d8-3ba9-4dfe-c8eb-4826bb458433&FOLDER=2bd3f1d7-2188-29ad-3422-ea0928495591

2014-07-26 08:54:08,826 WARN - OpenSim.Services.Connectors.XInventoryServicesConnector [XINVENTORY SERVICES CONNECTOR]: Exception in GetFolderContent: Thread was being aborted.
 2014-07-26 08:54:08,868 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 ...

(0026620)
aiaustin (developer)
2014-07-27 05:36
edited on: 2014-07-27 05:47

I very rarely am on a single system/viewer and logging in with just a single avatar and to the exact same OSGrid add on region freshly restarted and with no other activity each time... but as I am travelling for these reports that has been the case for 2 days... and I note that on every log in via Firestorm 4.6.5 OS the inventory recent tab count starts at loading 250 or so every time and then counts up to 364 then sticks at that. Consistently, each time on about 6 consecutive logins. I have never noticed that same sticking point each time. though its often near the end of all inventory loading.

But I then left the add on OSGrid region sim running, logged off the avatar in its 364 item stuck state and logged back on it started at a lower number around 211 and only counted up a few to 214 before sticking again. After that the numbers where it stuck changed each time.

In the stuck state the show stats inventory command indicates queued requests grow gradually and the new stat that Justin added grows too..

Region (root) # show stats inventory
inventory.http://inventory.osgrid.org.RequestsMade [^] : 1221 requests, 4 requests/s, 3.27 requests/s
inventory.httpfetch.ProcessedFetchInventoryRequests : 38, 0.8/s, 0.07/s
inventory.httpfetch.QueuedFetchInventoryRequests : 17, -0.8/s, 0.09/s

Region (root) # show stats inventory
inventory.http://inventory.osgrid.org.RequestsMade [^] : 1362 requests, 4 requests/s, 4.03 requests/s
inventory.httpfetch.ProcessedFetchInventoryRequests : 43, 0/s, 0.14/s
inventory.httpfetch.QueuedFetchInventoryRequests : 12, 0/s, 0.02/s

Region (root) # show stats inventory
inventory.http://inventory.osgrid.org.RequestsMade [^] : 1418 requests, 4 requests/s, 4.05 requests/s
inventory.httpfetch.ProcessedFetchInventoryRequests : 44, 0/s, 0.16/s
inventory.httpfetch.QueuedFetchInventoryRequests : 13, 0.8/s, 0/s

After another couple of minutes with no other activity at all, and avatar still in inventory stuck state... actually still a cloud now as it stuck at a lower count...

Region (root) # show stats inventory
inventory.http://inventory.osgrid.org.RequestsMade [^] : 3407 requests, 4 requests/s, 4.07 requests/s
inventory.httpfetch.ProcessedFetchInventoryRequests : 106, 0/s, 0.14/s
inventory.httpfetch.QueuedFetchInventoryRequests : 22, 0/s, -0.12/s


I logged out and let the queued requests fall to zero.. then stats were

Region (root) # show stats inventory
inventory.http://inventory.osgrid.org.RequestsMade [^] : 4170 requests, 0 requests/s, 0 requests/s
inventory.httpfetch.ProcessedFetchInventoryRequests : 130, 0/s, 0/s
inventory.httpfetch.QueuedFetchInventoryRequests : 0, 0/s, 0/s

It then stayed at exactly those same stats as I check again over the next 3 or 4 minutes...

Region (root) # show stats inventory
inventory.http://inventory.osgrid.org.RequestsMade [^] : 4170 requests, 0 requests/s, 0 requests/s
inventory.httpfetch.ProcessedFetchInventoryRequests : 130, 0/s, 0/s
inventory.httpfetch.QueuedFetchInventoryRequests : 0, 0/s, 0/s

(0026621)
aiaustin (developer)
2014-07-27 05:56
edited on: 2014-07-28 01:56

For the record, I checked by logging the test avatar into Wright Plaza and the inventory there fully loaded almost instantly and the number of items in the inventory is 496. So the problem is definitely NOT just related to very large inventories.

(0026622)
Mata Hari (reporter)
2014-07-27 06:08

@Ai: Since your test avi inventory here is so small, can you isolate the folder(s) that is consistently failing to fetch? If so, can you potentially then isolate a single object that is failing to fetch (perhaps by making a subfolder for each item in the failing folder and seeing which one of those then fails to expand)?

For large inventories it isn't practical to try that sort of isolation but it might work in this case. Would be very interesting to pin it down to an object and see if there's something unusual about it.
(0026624)
aiaustin (developer)
2014-07-28 01:53
edited on: 2014-07-30 14:01

I had planned to see if I could isolate potentially iffy objects such as ones with non-OSGrid creatirs or last owners, HG calling cards abd so on. But I also did not want to alter the setup of the test avatar since it pretty consistently can throw up the issue.. and hence could be useful to give feedback as Justin adds any logging or isolates where the thread abort exception is coming from on shutdown.

I am travelling just now and on a mobile device, so will look at this on my return to base.

I am assuming this is not (or not just) an inventory server load issue but is some real dropping of a fetch request where the sim sever end dies not realise and gets locked up.

(0026644)
aiaustin (developer)
2014-07-30 12:55
edited on: 2015-05-07 08:46

To let you know, I read the dev meeting chat log from 29th July 2914 and the discussion between Justin, Mata and others.

It is definitely the case that the inventory fetch can stall "forever" way beyond any time out that might be in there. I have left it up to 40 minutes in the past completely stuck with no console, viewer or region activity and its still stuck once it gets stuck. Its not always same point. But occurs with most avatars with small (few hundred) and larger (10k) inventories.

I have not yet seen a single timeout since that info was added.

Logging out starts to let the queued fetch number start to go down VERY slowly and if you let it go completely to zero you can shutdown without error. But if any queued fetch is still outstanding and we shutdown the sim we always get a red error and the thread aborting from inventory.osgrid.org error.

I see it on Windows Vista , 7 and 8.1 systems... using MySQL and SQLite and using Firestorm and Singularity. Some recent fast Xeon severs with 32GB memory, SSD drives, fast University connection on a gigabit wire to our switches. Noted ping to inventory.osgrid.org consistently at 113msecs on a test.

Only ever seen on OSGrid add on regions, and never saw it at all until one specific time around the time as I recall that we went to .net4 though as I have said that might be coincidental. Started on all three of my OSGrid add on hosts at the same time.

Happy to do any further logging if you advise what to try.

(0026645)
aiaustin (developer)
2014-07-31 02:25
edited on: 2015-03-02 13:21

Just observed an inventory fetch hang on Wright Plaza for first time... it has not completed the inventory fetch, though the avatar was rezzed and the My Outfits tool allowed replace.... so it may have happened before and I just did not notice.

On return from Wright Plaza to OpenVCE addon region on OSGrid I noticed my first ever timeout with the timeout special parameter set to 10 seconds.

10:18:39 - [FORMS]: Error receiving response from http://inventory.osgrid.org/xinventory: [^] The operation has timed out. Request: METHOD=GETITEM&ID=8e169d1b-6eae-4671-9d04-f38f8e99bf53

10:18:39 - [XINVENTORY SERVICES CONNECTOR]: Exception in GetItem: System.Net.WebException: The operation has timed out
   at OpenSim.Framework.SynchronousRestFormsRequester.MakeRequest(String verb, String requestUrl, String obj, Int32 timeoutsecs, IServiceAuth auth) in d:\Temp\opensim-327632d\OpenSim\Framework\WebUtil.cs:line 1087
   at OpenSim.Services.Connectors.XInventoryServicesConnector.MakeRequest(String method, Dictionary`2 sendData) in d:\Temp\opensim-327632d\OpenSim\Services\Connectors\Inventory\XInventoryServicesConnector.cs:line 538
   at OpenSim.Services.Connectors.XInventoryServicesConnector.GetItem(InventoryItemBase item) in d:\Temp\opensim-327632d\OpenSim\Services\Connectors\Inventory\XInventoryServicesConnector.cs:line 433

10:18:49 - [LOGHTTP]: Slow SynchronousRestForms request 16101 POST to http://inventory.osgrid.org/xinventory [^] took 9906ms, 9266ms writing, METHOD=MOVEFOLDER&ParentID=7512d918-9c79-49b4-a22a-6b57ccaa0789&ID=f9f4c637-7d60-439c-ac66-179b51926780&PRINCIPAL=e858df02-a860-4b92-937a-2b87e4ebcd6d

(0026646)
aiaustin (developer)
2014-07-31 06:37
edited on: 2014-07-31 06:47

I set the following on a sample OSGrid add on region server...

debug lludp packet 1 --default

I logged in directly to the region and saw some traffic with packets in and out up to the end of the Xbakes... and then the inventory fetch in the viewer was stuck... this time at 401 of the 496 items...

I attach the end of the trace here... but there was NO lludp monitored traffic after the point where the inventory got stuck for some 5 minutes of waiting...

14:26:06 - [REMOTE SIMULATION CONNECTOR]: Creating agent at http://virtual1.aiai.ed.ac.uk:9000/ [^]
14:26:06 - [ENTITY TRANSFER MODULE]: OpenVCE is sending Be Austin EnableSimulator for neighbour region Vue-Rig(loc=<1638656,1638400>,siz=<256,256>) and EstablishAgentCommunication with seed cap http://virtual1.aiai.ed.ac.uk:9000/CAPS/423852bd-7f36-4e5b-9bfc-d1dd28363f3b0000/ [^]
14:26:06 - [EVENT QUEUE GET MODULE]: EnableSimulator. handle=7037973931032576, avatarID=3fa9574f-09b0-477c-b4f1-403bd30a7a02, regionSize=256,256>
14:26:06 - [EVENT QUEUE GET MODULE]: EstablishAgentCommunication. handle=7037973931032576, avatarID=3fa9574f-09b0-477c-b4f1-403bd30a7a02, regionSize=256,256>
14:26:06 - [ENTITY TRANSFER MODULE]: Completed inform Be Austin 3fa9574f-09b0-477c-b4f1-403bd30a7a02 about neighbour 129.215.219.138:9001
14:26:06 - [CLIENT]: PACKET IN from Be Austin (root ) in OpenVCE - UUIDNameRequest
14:26:07 - [CLIENT]: PACKET OUT to Be Austin (root ) in OpenVCE - ObjectProperties
14:26:07 - [CLIENT]: PACKET IN from Be Austin (root ) in OpenVCE - AvatarPropertiesRequest
14:26:07 - [CLIENT]: PACKET IN from Be Austin (root ) in OpenVCE - UUIDNameRequest
14:26:07 - [CLIENT]: PACKET OUT to Be Austin (root ) in OpenVCE - AvatarPropertiesReply
14:26:07 - [CLIENT]: PACKET OUT to Be Austin (root ) in OpenVCE - AvatarInterestsReply
14:26:08 - [HGScene]: RezObject itemID=c212226e-cb9c-4d60-96a8-b0bee6eef8ff fromTaskID=3fa9574f-09b0-477c-b4f1-403bd30a7a02
14:26:08 - [USER MANAGEMENT MODULE]: No grid user found for f8c819e1-f92f-4e7c-ad01-319e83205b63
14:26:08 - [CLIENT]: PACKET IN from Be Austin (root ) in OpenVCE - AvatarPropertiesRequest
14:26:08 - [CLIENT]: PACKET OUT to Be Austin (root ) in OpenVCE - AvatarPropertiesReply
14:26:08 - [CLIENT]: PACKET OUT to Be Austin (root ) in OpenVCE - AvatarInterestsReply
14:26:08 - [USER MANAGEMENT MODULE]: No grid user found for 3ecd71a7-96e0-4b17-b165-2b81244adf47
14:26:09 - [CLIENT]: PACKET OUT to Be Austin (root ) in OpenVCE - ObjectProperties
14:26:16 - [CLIENT]: PACKET IN from Be Austin (root ) in OpenVCE - GenericMessage
14:26:16 - [CLIENT]: PACKET OUT to Be Austin (root ) in OpenVCE - AvatarPicksReply
14:26:22 - [LOGHTTP]: Slow handling of 34 POST /CAPS/c2fa259a-d8a2-45ae-8f3c-53a31e4853e4 FetchInventory2 3fa9574f-09b0-477c-b4f1-403bd30a7a02 from 129.215.219.52:54633 took 6141ms
14:26:35 - [CLIENT]: PACKET IN from Be Austin (root ) in OpenVCE - AgentCachedTexture
14:26:36 - [XBakes]: read 5 textures for user 3fa9574f-09b0-477c-b4f1-403bd30a7a02
14:26:36 - [CLIENT]: PACKET OUT to Be Austin (root ) in OpenVCE - AgentCachedTextureResponse
14:26:36 - [CLIENT]: PACKET IN from Be Austin (root ) in OpenVCE - AgentIsNowWearing
14:26:36 - [CLIENT]: PACKET IN from Be Austin (root ) in OpenVCE - AgentSetAppearance
14:26:36 - [AVFACTORY]: Received texture update for Be Austin 3fa9574f-09b0-477c-b4f1-403bd30a7a02
14:26:37 - [CLIENT]: PACKET IN from Be Austin (root ) in OpenVCE - AgentSetAppearance
14:26:37 - [XBakes]: read 5 textures for user 3fa9574f-09b0-477c-b4f1-403bd30a7a02
14:26:37 - [AVFACTORY]: Received texture update for Be Austin 3fa9574f-09b0-477c-b4f1-403bd30a7a02
14:26:37 - [XBakes]: stored 5 textures for user 3fa9574f-09b0-477c-b4f1-403bd30a7a027a02
14:26:38 - [XBakes]: read 5 textures for user 3fa9574f-09b0-477c-b4f1-403bd30a7a02


******** Inventory Fetch is stuck about here *************************

Region (root) #
Region (root) #
Region (root) #
Region (root) #

Region (root) # show stats inventory
inventory.http://inventory.osgrid.org.RequestsMade [^] : 272 requests, 4 requests/s, 3.88 requests/s
inventory.httpfetch.ProcessedFetchInventoryRequests : 5, 0/s, 0.03/s
inventory.httpfetch.QueuedFetchInventoryRequests : 13, 0/s, 0.1/s

Region (root) # show stats inventory
inventory.http://inventory.osgrid.org.RequestsMade [^] : 371 requests, 4 requests/s, 3.79 requests/s
inventory.httpfetch.ProcessedFetchInventoryRequests : 8, 0/s, 0.07/s
inventory.httpfetch.QueuedFetchInventoryRequests : 11, 0/s, 0.05/s

Region (root) # show stats inventory
inventory.http://inventory.osgrid.org.RequestsMade [^] : 945 requests, 4 requests/s, 4.1 requests/s
inventory.httpfetch.ProcessedFetchInventoryRequests : 18, 0/s, 0.09/s
inventory.httpfetch.QueuedFetchInventoryRequests : 18, 0/s, 0.05/s

Then after 10 minutes of being inventory fetch stuck and NO activity at all... still no packets in or out messages... and...

Region (root) # show stats inventory
inventory.http://inventory.osgrid.org.RequestsMade [^] : 2969 requests, 4.4 requests/s, 4 requests/s
inventory.httpfetch.ProcessedFetchInventoryRequests : 57, 0/s, 0.07/s
inventory.httpfetch.QueuedFetchInventoryRequests : 49, 0/s, 0.07/s


On logout of the avatar when in the fetch inventory stuck situation I get...

14:40:00 - [CLIENT]: PACKET IN from Be Austin (root ) in OpenVCE - LogoutRequest
14:40:00 - [CLIENT]: Got a logout request for Be Austin in OpenVCE
14:40:00 - [CLIENT]: PACKET OUT to Be Austin (root ) in OpenVCE - LogoutReply
14:40:00 - [CLIENT]: Close has been called for Be Austin attached to scene OpenVCE
14:40:01 - [SCENE]: Removing root agent Be Austin 3fa9574f-09b0-477c-b4f1-403bd30a7a02 from OpenVCE
14:40:01 - [CAPS]: Remove caps for agent 3fa9574f-09b0-477c-b4f1-403bd30a7a02 in region OpenVCE
14:40:01 - [SCENE COMMUNICATION SERVICE]: Sending close agent ID 3fa9574f-09b0-477c-b4f1-403bd30a7a02 to Vue-Port
14:40:01 - [SCENE COMMUNICATION SERVICE]: Sending close agent ID 3fa9574f-09b0-477c-b4f1-403bd30a7a02 to Vue-Rig
14:40:01 - [SCENE COMMUNICATION SERVICE]: Sending close agent ID 3fa9574f-09b0-477c-b4f1-403bd30a7a02 to Sea-Vue
14:40:01 - [CLIENT]: Close has been called for Be Austin attached to scene Vue-Port
14:40:01 - [SCENE COMMUNICATION SERVICE]: Sending close agent ID 3fa9574f-09b0-477c-b4f1-403bd30a7a02 to AI
14:40:01 - [REMOTE SIMULATION CONNECTOR]: CloseAgent http://virtual1.aiai.ed.ac.uk:9000/agent/3fa9574f-09b0-477c-b4f1403bd30a7a02/e9d193ea-1e82-4f35-a6b3-3745c758eb84/?auth=453f23be-94b3-45a1-a8c5-dc53c2a0b2e1 [^]
14:40:01 - [REMOTE SIMULATION CONNECTOR]: CloseAgent http://virtual1.aiai.ed.ac.uk:9000/agent/3fa9574f-09b0-477c-b4f1403bd30a7a02/942b6318-f11f-4a18-b362-b8785 [^]
74297cc/?auth=453f23be-94b3-45a1-a8c5-dc53c2a0b2e1
14:40:01 - [REMOTE SIMULATION CONNECTOR]: CloseAgent http://virtual1.aiai.ed.ac.uk:9000/agent/3fa9574f-09b0-477c-b4f1403bd30a7a02/a2df9626-302a-4c4c-8e3a-fafd02955226/?auth=453f23be-94b3-45a1-a8c5-dc53c2a0b2e1 [^]
14:40:01 - [SCENE]: Removing child agent Be Austin 3fa9574f-09b0-477c-b4f1-403bd30a7a02 from Vue-Port
14:40:01 - [CLIENT]: PACKET OUT to Be Austin (child) in Vue-Port - DisableSimulator
14:40:01 - [CAPS]: Remove caps for agent 3fa9574f-09b0-477c-b4f1-403bd30a7a02 in region Vue-Port
14:40:01 - [CLIENT]: PACKET OUT to Be Austin (root ) in OpenVCE - KillObject
14:40:01 - [CLIENT]: PACKET OUT to Be Austin (root ) in OpenVCE - KillObject
14:40:01 - [ATTACHMENTS MODULE]: Updating asset for attachment 05dfe0d2-df93-4282-9412-66c1e040bded, attachpoint 12
14:40:03 - [CLIENT]: PACKET OUT to Be Austin (root ) in OpenVCE - UpdateCreateInventoryItem
14:40:03 - [CLIENT]: PACKET OUT to Be Austin (root ) in OpenVCE - KillObject
14:40:03 - [CLIENT]: PACKET OUT to Be Austin (root ) in OpenVCE - KillObject
14:40:03 - [CLIENT]: PACKET OUT to Be Austin (root ) in OpenVCE - KillObject
14:40:03 - [CLIENT]: PACKET OUT to Be Austin (root ) in OpenVCE - KillObject
14:40:03 - [CLIENT]: PACKET OUT to Be Austin (root ) in OpenVCE - KillObject


Then as usual, since there are queued fetch requests outstanding, I get the red errors on shutdown of the sim... but see now further packet in or out messages....

Region (root) # q
14:42:16 - [SHUTDOWN]: Closing all threads
14:42:16 - [SHUTDOWN]: Killing listener thread
14:42:16 - [SHUTDOWN]: Killing clients
14:42:16 - [SHUTDOWN]: Closing console and terminating
14:42:16 - [SCENE]: Closing down the single simulator: Vue-Port
14:42:16 - [WATCHDOG]: Removing thread Heartbeat (Vue-Port), ID 59
14:42:17 - [WATCHDOG]: Removing thread Maintenance (Vue-Port), ID 68
14:42:17 - [SCENE]: Persisting changed objects
14:42:17 - [GRID SERVICE]: Deregistering region Vue-Port (2aa49e09-f1b1-4f20-8ae
3-55e0399a674c) at 6400-6400
14:42:17 - [SHUTDOWN]: Shutting down region Vue-Port
14:42:18 - [XEngine]: Shutting down 49 scripts in Vue-Port
14:42:18 - [WATCHDOG]: Removing thread InventoryWorkerThread0, ID 47
14:42:18 - [XINVENTORY SERVICES CONNECTOR]: Exception in GetItem: System.Threadi
ng.ThreadAbortException: Thread was being aborted.
   at System.Threading.Monitor.Enter(Object obj)
   at OpenSim.Services.Connectors.XInventoryServicesConnector.MakeRequest(String
 method, Dictionary`2 sendData) in d:\Temp\opensim-327632d\OpenSim\Services\Conn
ectors\Inventory\XInventoryServicesConnector.cs:line 537
   at OpenSim.Services.Connectors.XInventoryServicesConnector.GetItem(InventoryI
temBase item) in d:\Temp\opensim-327632d\OpenSim\Services\Connectors\Inventory\X
InventoryServicesConnector.cs:line 433

14:42:18 - [INVENTORY]: Failed to process queued inventory request 0d7058d7-2ab6
-411c-881e-fddcf53fdba0 for Be Austin in Vue-Port. Exception System.Threading.T
hreadAbortException: Thread was being aborted.
   at OpenSim.Services.Connectors.XInventoryServicesConnector.GetItem(InventoryI
temBase item) in d:\Temp\opensim-327632d\OpenSim\Services\Connectors\Inventory\X
InventoryServicesConnector.cs:line 441
   at OpenSim.Region.CoreModules.ServiceConnectorsOut.Inventory.RemoteXInventory
ServicesConnector.GetItem(InventoryItemBase item) in d:\Temp\opensim-327632d\Ope
nSim\Region\CoreModules\ServiceConnectorsOut\Inventory\RemoteXInventoryServiceCo
nnector.cs:line 298
   at OpenSim.Region.CoreModules.ServiceConnectorsOut.Inventory.HGInventoryBroke
r.GetItem(InventoryItemBase item) in d:\Temp\opensim-327632d\OpenSim\Region\Core
Modules\ServiceConnectorsOut\Inventory\HGInventoryBroker.cs:line 571
   at OpenSim.Capabilities.Handlers.WebFetchInvDescHandler.Fetch(UUID agentID, U
UID folderID, UUID ownerID, Boolean fetchFolders, Boolean fetchItems, Int32 sort
Order, Int32& version, Int32& descendents) in d:\Temp\opensim-327632d\OpenSim\Ca
pabilities\Handlers\WebFetchInventoryDescendents\WebFetchInvDescHandler.cs:line
276
   at OpenSim.Capabilities.Handlers.WebFetchInvDescHandler.FetchInventoryReply(L
LSDFetchInventoryDescendents invFetch) in d:\Temp\opensim-327632d\OpenSim\Capabi
lities\Handlers\WebFetchInventoryDescendents\WebFetchInvDescHandler.cs:line 161
   at OpenSim.Capabilities.Handlers.WebFetchInvDescHandler.FetchInventoryDescend
entsRequest(String request, String path, String param, IOSHttpRequest httpReques
t, IOSHttpResponse httpResponse) in d:\Temp\opensim-327632d\OpenSim\Capabilities
\Handlers\WebFetchInventoryDescendents\WebFetchInvDescHandler.cs:line 111
   at OpenSim.Region.ClientStack.Linden.WebFetchInvDescModule.PollServiceInvento
ryEventArgs.Process(aPollRequest requestinfo) in d:\Temp\opensim-327632d\OpenSim
\Region\ClientStack\Linden\Caps\WebFetchInvDescModule.cs:line 363
   at OpenSim.Region.ClientStack.Linden.WebFetchInvDescModule.WaitProcessQueuedI
nventoryRequest() in d:\Temp\opensim-327632d\OpenSim\Region\ClientStack\Linden\C
aps\WebFetchInvDescModule.cs:line 443
14:42:18 - [WATCHDOG]: Removing thread InventoryWorkerThread1, ID 48
14:42:18 - [SCENE]: Closing down the single simulator: OpenVCE
14:42:18 - [FORMS]: Error sending request to http://inventory.osgrid.org/xinvent [^]
ory: Thread was being aborted.. Request: METHOD=GETITEM&ID=821c9434-f3dd-46cc-bd
3d-76ee8c783ff5
14:42:18 - [XINVENTORY SERVICES CONNECTOR]: Exception in GetItem: System.Threadi
ng.ThreadAbortException: Thread was being aborted.
   at OpenSim.Framework.SynchronousRestFormsRequester.MakeRequest(String verb, S
tring requestUrl, String obj, Int32 timeoutsecs, IServiceAuth auth) in d:\Temp\o
pensim-327632d\OpenSim\Framework\WebUtil.cs:line 1087
   at OpenSim.Services.Connectors.XInventoryServicesConnector.MakeRequest(String
 method, Dictionary`2 sendData) in d:\Temp\opensim-327632d\OpenSim\Services\Conn
ectors\Inventory\XInventoryServicesConnector.cs:line 538
   at OpenSim.Services.Connectors.XInventoryServicesConnector.GetItem(InventoryI
temBase item) in d:\Temp\opensim-327632d\OpenSim\Services\Connectors\Inventory\X
InventoryServicesConnector.cs:line 433

14:42:18 - [APPLICATION]:
APPLICATION EXCEPTION DETECTED: System.UnhandledExceptionEventArgs

Exception: System.NullReferenceException: Object reference not set to an instanc
e of an object.
   at OpenSim.Region.ClientStack.Linden.WebFetchInvDescModule.WaitProcessQueuedI
nventoryRequest() in d:\Temp\opensim-327632d\OpenSim\Region\ClientStack\Linden\C
aps\WebFetchInvDescModule.cs:line 447
   at OpenSim.Region.ClientStack.Linden.WebFetchInvDescModule.DoInventoryRequest
s() in d:\Temp\opensim-327632d\OpenSim\Region\ClientStack\Linden\Caps\WebFetchIn
vDescModule.cs:line 431
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionCo
ntext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
   at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, C
ontextCallback callback, Object state, Boolean preserveSyncCtx)
   at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, C
ontextCallback callback, Object state)
   at System.Threading.ThreadHelper.ThreadStart()

Application is terminating: True


Unhandled Exception: System.NullReferenceException: Object reference not set to
an instance of an object.
   at OpenSim.Region.ClientStack.Linden.WebFetchInvDescModule.WaitProcessQueuedI
nventoryRequest() in d:\Temp\opensim-327632d\OpenSim\Region\ClientStack\Linden\C
aps\WebFetchInvDescModule.cs:line 447
   at OpenSim.Region.ClientStack.Linden.WebFetchInvDescModule.DoInventoryRequest
s() in d:\Temp\opensim-327632d\OpenSim\Region\ClientStack\Linden\Caps\WebFetchIn
vDescModule.cs:line 431
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionCo
ntext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
   at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, C
ontextCallback callback, Object state, Boolean preserveSyncCtx)
   at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, C
ontextCallback callback, Object state)
   at System.Threading.ThreadHelper.ThreadStart()
14:42:18 - [WATCHDOG]: Removing thread Heartbeat (OpenVCE), ID 63
14:42:18 - [WATCHDOG]: Removing thread Maintenance (OpenVCE), ID 69

(0026647)
aiaustin (developer)
2014-07-31 07:15
edited on: 2014-07-31 07:17

[11:37] Nebadon Izumi: We throttle any single IP address to no more than 120 requests per second with nginx
[11:38] Nebadon Izumi: Could the simulators be exceeding that to Robust?
[11:38] Justin.Clark-Casey @hg.osgrid.org: None of this explains the complete lack of timeout for the requests
[11:38] Justin.Clark-Casey @hg.osgrid.org: Even without any setting changes, they should always timeout after 100 secs and report that fact to the console
[11:38] Nebadon Izumi: Ya nginx gives a clear error message when you are being throttled

Is it worth looking at this further given the problem is only (mostly?) seen on non-plaza OSGrid add-on regions as far as we are aware... could it be that some request are not just queued and delayed but actually thrown away and that OpenSim.exe cannot cope with any request that is not responded to? Or could it be that the form of the response that nginx gives to OpenSim.exe is in a form it does not recognise?

(0026677)
justincc (administrator)
2014-08-08 12:30
edited on: 2014-08-08 12:31

Ok, before you log in with an avatar, please execute

"debug http out 4"

on the console. This will log all outgoing requests (there will be a lot) but also the time they take. Please post the log. The ones we are interested in are in the form

20:22:59 - [LOGHTTP]: HTTP OUT 35 SynchronousRestForms POST to http://localhost:8003/xinventory [^]
20:22:59 - [LOGHTTP]: HTTP OUT 35 took 39ms, 0ms writing

(except that localhost:8003 will be the osgrid inventory service address). This will give an indication of whether requests are generally slow or not.

If a request 'sticks' you will see the HTTP OUT <req-num> but not the following line reporting how long it took.

This won't show the details of the request. If you do "debug http out 5" more will be logged which might show if it's always halting at a particular request, but this will be much noisier on the console.

Also,

1. The code here is the same as in 0.7.6. If you are sure that 0.7.6 was better then please try using that as a test and report the results - I believe it should still work with current ROBUST services.

2. The issue of viewers always re-requesting entire inventory even if cached has been associated with viewer-side AOs in the past. If you are using one, please try disabling it and re-test.

(0026678)
aiaustin (developer)
2014-08-08 12:55
edited on: 2014-08-08 13:21

Noted Justin. Firstly I am not using any viewer side AO such as the Firestorm in built AO. Any AOs are the default OSGrid "RUGGED" and "SWEETNESS" ones without any customisation. And I checked on one instance when all inventory was fetched (total of 495 items), and the specific test avatar was not wearing any AO at all. Also if its relevant not wearing any mesh items at all either.

I did a test on Openvue region of OSGrid... the timeout is set at 10 seconds. Avatar inventory fetch on this run stuck at 392 items with avatar a cloud. but the logs indicate fetches continuing for 5 or more minutes up to now afterwards and all looked paired fine... but nothing is happening at the viewer end at all. I am up to HTTP OUT 2000 and see no progress for the stuck fetch of inventory. I will have to just terminate things to get you the log. That's generates the usual red thread aborting error.

2014-08-08-OSGrid-Openvue-OpenSim-Debug-Http-Out-4.log
(Avatar inventory stuck at 392 out of 495)

Then I did a run and attach this for debug http out 5

2014-08-08-OSGrid-Openvue-OpenSim-Debug-Http-Out-5.log
(successful fetch on full inventory of 495 items note)

I tried to note what HTTP OUIT index number we were at roughly the time the inventory "recent" tab showed the fetch stuck... the inventory recent tab showed "332" when I was able to get in soon after login. It stuck at 478. I then looked ta the server side and it showed HTTP OUT index around 350.

Again I let it run still stuck.... BUT... this time it resolved eventually at the full inventory of 495 items and the avatar was rezzed. the HTTP OUT index number then was 898 and it stopped with no further activity on the console. maybe the extra logging slowed down something to let things complete?

Then a second run with debug http out 5 right afterwards, with same avatar. Inventory recent tab showed count started at 480 and it went up to 493 (two short of total in inventory) around HTTP OUT index 200 or so. Avatar fetch tab stuck on 493 and avatar still a cloud. But the HTTP out messages continue. I will let that go to around 1500 but expect there to be no difference between 300 or so and 1500! Thread abort exception is on end of log again when I quit the server.

2014-08-08-OSGrid-Openvue-OpenSim-Debug-Http-Out-5-Stuck.log
(Avatar inventory stuck at 493 out of 495)

(0026679)
Mata Hari (reporter)
2014-08-08 12:55

Would the level 5 log be more use to you or would you prefer the level 4 first?
(0026681)
justincc (administrator)
2014-08-08 17:11

Austin: So as you can see, each request takes 250 ms, so if you had an inventory of 10000 items and folders, total request time would be just under 42 minutes for all inventory details, assuming absolutely no other delays.

In fact, if you were to do

"debug http all 4"

you would also see HTTP requests incoming from your viewer. There will be a lot of these (e.g. texture requests), but you'll also see lines such as

21:17:11 - [LOGHTTP]: HTTP IN 14 :9000 stream handler POST /CAPS/c79214f9-8269-4503-ace2-5c4a0fce7ec2 FetchInventory2 f2f493c0-27d3-4cf2-be97-b44dfdad13b6 from 192.168.1.2:45694

where FetchInventory2 is a request for a specific folder's contents from the viewer.

You'll see that these requests are not one to one with xinventory requests - a single FetchInventory2 can translate into many inventory requests.

It is interesting that requests are still being made from the simulator even though the viewer does not appear to 'see' them. Maybe the viewer has a fairly low timeout and simply ignores late replies to requests. This is purely speculation, though.

Mata: A level 4 is useful first since it's less extra data to read. Level 5 is really so you can identify if it always stops on a particular item/request which we may then be able to look at further specifically in the OSgrid context.
(0026682)
justincc (administrator)
2014-08-08 17:13
edited on: 2014-08-08 17:16

Ok, please also try git master 8738445. This takes the step of moving a lock further down the stack so that both inventory request threads can be active at once rather than one having to wait for the other (or potentially requests from other sources).

It's quite possible this may improve things for you in the short term, though a full inventory pull down from a remote location (with greater round trip request time) may still be slow. A better long term solution may be to look at what local persistent inventory caching can be done though this requires significantly more development effort.

The trade off with more simultaneous requests is that they place greater short term stress on the inventory service (in this case osgrid). It's probably only an issue where there are already many requests but if the servers are at capacity, increasing simultaneous request won't help anyway. Though even in that situation, there may be some benefit just because of the round trip times.

(0026683)
Mata Hari (reporter)
2014-08-08 21:39
edited on: 2014-08-08 21:41

Did one test with the new git. This is logging in directly to my region immediately after it had finished its startup routine with debug http all 4. I was on FS current version with my built-in AO on.

See attached log Mata2014-08-09Test1.rar

As you'll see, the very last HTTP IN request occurs at around 00:09 which coincides approximately with the last time that the "fetching...." count in my viewer increased. After that it remained stuck at the same number. After about 13 minutes of no change, I logged out (approx 00:12:22 in the log) and you'll see several thousand more HTTP OUT requests go out over the next 5 minutes after which I shut down the sim (which of course crashed to desktop with Windows error message).


Tomorrow morning I will repeat this identical test with my AO turned off.

(0026686)
aiaustin (developer)
2014-08-09 01:22

Will set up and test ASAP.

But I just don't get the time per request equating linearly with the time the inventory takes to come in. When on an OSGrid Plaza I have 10K inventories that effectively come in instantly.. or quickly anyway. Are they really fully linearized?
(0026687)
aiaustin (developer)
2014-08-09 01:31
edited on: 2014-08-09 01:32

Mata's note of several thousand requests going out after a stuck avatar logs out is interesting and entirely consistent with the behaviour we have noted... this EVENTUALLY.. sometimes after 30 minutes ... reduces the queued requests to zero and then you can shutdown the sim without error. Shutdown while this process is going on and you get the red thread aborting errors. We may reduce the incidence of the problem by some means, and an inventory caching mechanism may hide it. But I suspect that there is still an issue lurking in there and we seem to be into the area now where issues may have arisen.

At the least surely we are making vey many thousands of irrelevant HTTP requests AFTER the avatar has logged out. That cannot be right and will be a very large burden on the OSGrid inventory service for no practical use. A way to kill off queued and now irrelevant and unneeded requests across a whole grid might boost performance really a lot.

(0026688)
aiaustin (developer)
2014-08-09 01:35

Justin, can you tell us the date and r/ number of git master a58152bd

I know you guys maybe just can compute that from the hash us lesser mortals need a date and r/ number to understand when the change was introduced to see if it fits our observations.
(0026689)
aiaustin (developer)
2014-08-09 04:32
edited on: 2014-08-09 04:52

I was running with the OpenSim.ini OSGrid add on regions release settings...

    async_call_method = SmartThreadPool
    MaxPoolThreads = 30
    MinPoolThreads = 10

I note that there is a MinPoolThreads = 10 in there, that I cannot see in the most recent dev master openSimDefaults.ini file. Should it be removed from the OSGrid's OpenSim.ini ?

Ah.. and I see that the latest OSGrid add on release based on r/25100 has amended its default openSim.ini file to have the following, which I will test with now...

    async_call_method = SmartThreadPool
    MaxPoolThreads = 300
    MinPoolThreads = 32

(0026690)
Mata Hari (reporter)
2014-08-09 04:54

Test 0000002 log file now attached (Mata2014-08-09Test2.rar)

This test identical to test 1 except I first logged into Sandbox II (where my inventory loaded in a 1/10th of a second as it always does) and then switched off my AO. I made a note of my slightly bloated inventory size (haven't done a purge recently) which currently sits at 13,152.

I then logged out and then back into my own sim.

At approx 07:20 in the log is where my inventory fetch stalled at 13,005 items which I believe is the same number it stalled at last night (I didn't write it down last night so it might be slightly different) after which I let it run for another 15 minutes of endless HTTP OUT requests. I then logged out an let it run for another while to confirm the same behaviour of continuing to fetch endlessly after logout. I then shut down the sim which hard-crashed to desktop (this time without the Windows error message though).
(0026691)
Mata Hari (reporter)
2014-08-09 05:18

I just now ran a third test by running a clean 0.7.6.1 and encountered the identical fetch lock-up at 13,005 items (AO disabled). I won't bother posting the log since it's effectively identical to my 2nd test log above.

As I've said earlier, I do not recall inventory fetch being an issue prior to around Christmastime 2013 so *something* changed *somewhere* that is affecting fetch. Perhaps something on the OSG ROBUST side of things (code or grid configuration)? I also seem to recall that FS had an update at around that time so it could be something there; however I've also encountered this bug when trying to login using Kokua and Singularity so it's not viewer-specific.

Since both of this morning's tests locked up at the exact same inventory number (and I think last night's did too) I will now do a test with your new git and log level set to 5.
(0026692)
aiaustin (developer)
2014-08-09 05:42
edited on: 2014-08-09 05:57

I ran with today's r/25100 and I am afraid and it looks like the problem is still there. On three log in attempts I got stuck inventory and even leaving things for 5 minutes there was no progress for the inventory fetch as seen by the viewer, and the avatar remained as a cloud. The fetches seem to stop for a while at 482 and then progress to 493 and then jam at that... with the total inventory at 495. At the stuck 493 the HTTP OUT messages continued for ages. And they continued for a while after the avatar logged out.. in fact as before until once it stopped the "show stats inventory" showed zero queued requests.

Now.. something interesting. While in the stuck state at 493 I happened to touch a give items box and the items (5 of them) all INSTANTLY came into inventory to show as 498 fetched. Yet the fetch was still stuck and the avatar was still a cloud. So its not really stuck and NEW incoming items seem to be served instantly.

Although I am usually testing in Firestorm, I can confirm what Mata said as I have also seen this in Singularity.

(0026693)
aiaustin (developer)
2014-08-09 05:55

Another observation.... in Firestorm 4.6.5 I was watching the Inventory Recent tab fetch... where it says Searching... at the top..
in one case where t did make it to the whole 495 items in, the avatar was rezzed and the outfits all showed and allowed replace. yet the inventory recent tab still said "searching..." and I noticed that with debug http out 4 on the fetches were still continuing. "show stats inventory" indicated a few still outstanding pending requests.. and this continued for a few hundred more of the HTTP OUT message for a couple of minutes

13:50:37 - [LOGHTTP]: HTTP OUT 5006 SynchronousRestForms POST to http://inventory.osgrid.org/xinventory [^]
13:50:37 - [LOGHTTP]: HTTP OUT 5006 took 235ms, 110ms writing


before finally the console HTTTP message stopped the pending requests was 0 and TNE, ONLYY THEN, dkd the "searching..." message in the Inventory recent tab go away and the final "Didn't find what you were looking for" line appear indicating all the inventory was really in.
(0026694)
Mata Hari (reporter)
2014-08-09 06:07
edited on: 2014-08-09 06:08

Attached: Mata2014-08-09Test3.rar

This is the log from my next test attempt where I went back to r/25100 and this time set debug http all 5. As per the previous 2 tests, my built-in FS AO was off.

When I logged in my inventory was at 12,928 and for a couple minutes thereafter it very slowly climbed until stalling completely at 13,006 (so 1 more items shown as fetched vs my previous 2 stall points). This means it should still be attempting to fetch 146 more items to reach my total inventory of 13,152.

I then let it run with me just standing there from 0000002:0000008:24 until 0000002:0000008:40 at which point I logged out. I then let it run for another 10+ minutes until finally shutting down the sim (hard crash to desktop complete with Windows error message this time).

Hopefully the additional data of the level 5 debug will shed some light on things.

Oh...and after that I logged into Sandbox II and complete inventory fetch was done before I could even see my screen.

(0026695)
aiaustin (developer)
2014-08-09 07:20

Any thoughts on what is being WRITTEN when in the stuck inventory fetch state Justin?

13:50:37 - [LOGHTTP]: HTTP OUT 5006 SynchronousRestForms POST to http://inventory.osgrid.org/xinventory [^] [^]
 13:50:37 - [LOGHTTP]: HTTP OUT 5006 took 235ms, 110ms writing
(0026696)
Mata Hari (reporter)
2014-08-09 07:31
edited on: 2014-08-09 07:43

I ran a parse of a block of data beginning just after my fetch count stalled until immediately prior to my avi logging out and it appears that it is simply cycling endlessly through the same set of calls. (EDIT: ie using the data supplied above in Test3)

Attached is "parse.txt" which lists the type of call (GET FOLDER or GET ITEM), the UUID of the item/folder, and the number of times that the identical call was repeated during that timeframe. Format is comma-delimited so easy to open in Excel or whatever you want.

7 Folders are called with 2 of them only 22 times, the others all in the 54-70 range.

With the exception of a couple of items, every single other one is either called 11 times or 27 times. Notice that the unique item call count corresponds perfectly with the 146 items that haven't yet been fetched according to my Firestorm item count.

EDIT AGAIN: Justin, if you have direct access to OSG asset database I grant full permission for you to go in and view and access that data for the purposes of solving this bug. That would tell you the names of the folders and objects that it's cycling through which, if you communicate that info privately to me, I can tell you if there's anything at all unusual about them in terms of where they came from, etc. If you can't directly access that data, I also grant Neb (or any other OSG admin) permission to access and supply that data to you for these purposes.

Sorry...one more edit: I should note that I stripped out all of the responses but as far as I could tell the OSG asset server responded with the requested data each and every time a call was made.

(0026697)
Nicky Perian (reporter)
2014-08-09 07:43

@aiaustin
tortoisegit has gitk -- may be available in other git packages.
it provides the numbers for all hashes.
https://dl.dropboxusercontent.com/u/7833186/gitk-hashes.JPG [^]
(0026698)
aiaustin (developer)
2014-08-09 07:53
edited on: 2014-08-09 10:09

As a test, I also tried Singularity Viewer 1.8.5 (5617)and that too has fetch stuck issues when trying to reach OSGrid region "OpenVCE" which is running r/25100. I left it over 30 minutes to see if the inventory resolved and it did not.

Yet on Wright Plaza, the same avatar with about 4,000 inventory items rezzed and completed its inventory fetch essentially immediately.

(0026699)
aiaustin (developer)
2014-08-09 09:37
edited on: 2014-08-09 09:38

Nicky.. remember you are dealing here with a person who tried GIT and gave up after two attempts that cost me a day of work. I don't even have GIT installed.. and don 't know where to find "tortoisegit". If you can translate the a58152bf to an r/....... number I would appreciate it.

(0026700)
Nicky Perian (reporter)
2014-08-09 10:48

@aiaustin
r/18286 -- 2012-03-09
https://dl.dropboxusercontent.com/u/7833186/Hash--a58152bf.JPG [^]
(0026701)
aiaustin (developer)
2014-08-09 11:47
edited on: 2014-08-09 11:57

Thanks Nicky.. wow thats a LONG time ago, 11K commits in between, and about two years before we started seeing this issue I think... not that it means it not related! There are some serious changes to inventory fetch, and especially HG ones, with fire and forgets added in three or four commits around that time. Maybe something changed earlier this year to make those come back and bite.

(0026702)
aiaustin (developer)
2014-08-09 13:56
edited on: 2014-08-09 13:57

Mata, is there a way to see if the affected items listed in parse.txt may all be ones that originated off OSGrid or have creators or last owners that might force HG lookups?

(0026704)
Mata Hari (reporter)
2014-08-09 14:25

@AiAustin without knowing what folders are involved it would be a monumental task to go through my 13k items to compare their UUIDs against the UUIDs in the items list. I don't know of any way to get the name of an inventory folder by UUID (on a standalone I could query it in MySQL but not on a gridded service) and anything I rez would have a new UUID so the only way to do it would be checking properties of each item in inventory until I happened across them.

I suppose I could try all of the item UUIDs in a script to apply them as textures and another script to use them as animations which would tell me if some/any are of that type. Can't think of any other way to test what they are.
(0026705)
aiaustin (developer)
2014-08-09 15:38

You are right... it was just a thought. Justin may be able to instrument relevant parts if he suspects its a HG asset issue. There does seem to be way more http out calls than necessary, they continue to build up when the inventory is in the stuck state and leave a growing queued requests number, and they continue long after they can be used by a user after that user logs out.
(0026706)
Nicky Perian (reporter)
2014-08-09 16:29

While trouble shooting Kokua I noticed that I got into a condition of the cached inventory folder have a uuid assigned that was not the logged on avatar's uuid.
Could someone test this when the inventory hangs?
1. clear the cache.
2. logon to osgrid.
3. look at the cached folders there should be two gzipped inv files one for the
library and one for the user.
4. Log on to a grid that has the inventory hang.
5. Let it hang.
6. exit the viewer
7. look at the server log for the avatar uuid.
8. look at the cache folder there should be a new user gzipped inv folder with
the avatar uuid matching the server logged on avatar uuid matching step 7 above.

If matched this problem is unrelated to the problems I'm experiencing.
The problem I'm experiencing has never happened on the osgrid regions that I normally log on to.
(0026707)
Mata Hari (reporter)
2014-08-09 17:26

Unfortunately I can't help you with that one Nicky because the only place I'm having trouble is logging into non-Plaza regions in OSGrid (and some non-plaza regions will usually complete the fetch while others won't...and those that do won't do so reliably).
(0026709)
aiaustin (developer)
2014-08-10 02:39
edited on: 2014-08-10 02:59

Here is a thought... I believe these issues started around the time we moved to .net4. Could it be that one of the changes made to handle serialization of inventory fetch requests some time ago (r/18277, r/18283 to r/18286 by Diva and and r/19296 by Mic Bowman) would work then with .net3.5, but the methods used be an issue in the Windows implementation of .net4 on some specific hosts.

The odd variances between .net3.5 and .net4 behaviour is something that others have commented on in web postings, where even longer host names have triggered variances in behaviour due to some clipping of requests and limitations on some implementations of .net4.

I am for example looking at the code introduced in the commits for linearizing the inventory fetches and look around OpenSim\Framework\WebUtil.cs:line 1007 with the use of the construct "using (MemoryStream buffer = new MemoryStream())"

And this is exactly the areas the shutdown crashes indicate is implicated as I have noted before in Issue 7110.

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

(0026710)
Mata Hari (reporter)
2014-08-10 06:56

I'm beginning to think AiAustin is on to something. A quick survey of the locations that seem to be login-friendly all appear to be running under linux-mono and everyone who seems to be having issues appears to be running under some flavour of Win/.NET
(0026711)
aiaustin (developer)
2014-08-10 07:10
edited on: 2015-05-07 10:04

I would like to try an experiment if we can work out how to do it... to go back to r/24021 at 2013-11-08 just before the change to .net 4 in dev master. I have been looking to see if I can find a .zip of the COMPILED release of the OSGrid add on just before that... and hence using .net 3.5 compile. I cannot find an archive that old in downloads.osgrid.org or elsewhere that I looked. And I don't know how to force a compile of r/24021 under .net 3.5 on my system.

Mata's test of 0.7.6 I assume recompiled it and may have used her default .net 4 framework since we all changed to that for post r/24021 versions?

The trouble with taking 0.7.6 and before now is that we are still (I assume) compiling with .net 4.

(0026712)
Mata Hari (reporter)
2014-08-10 07:28
edited on: 2014-08-10 07:30

The 0.7.6.1 that I used was pulled directly from Opensimulator.org and is pre-compiled (by Justin I assume) but iirc that's a build made after the switch to .NET 4.0

I did just do a test with thanks to Dan Banner who has 2 boxes in the same physical location...same network, same router, same ISP, etc. One is running linux-mono and the other is running Win-.NET.

I was able to log in to both of those regions and fetch completed successfully on both -- not as fast as the plazas, of course, but it took only a minute or so in both cases.

After that, I logged directly back into my own sim and the fetch hung.

Of interest: on both of Dan's machines my inventory fetch started at around 13.156 whereas on my own machine my fetch started at 12,986. Perhaps it had already fetched some on Dan's before my screen appeared and that's why I didn't see the earlier start number?

(0026713)
Mata Hari (reporter)
2014-08-10 07:37

Oh...but....

It doesn't seem to matter what environment it was compiled under. You can do a build on either Windows or Linux and use the compiled results on either system (hence why there is only 1 build to download for OSG as opposed to a Windows build and a separate Linux build).

What I didn't do is go back in the git and make a new build from an old master so it's possible that something in 0.7.6.1 is different than the original 0.7.6.0 that didn't cause problems. I'll try that....I'll pull a git from last summer and try it instead.
(0026714)
Ken Grunke (reporter)
2014-08-10 07:49
edited on: 2014-08-10 07:49

I've experienced the fetch hang on Linux more than once. I'm currently at Kanarch where I logged in direct about 10 minutes ago, with my inventory hung at 7901 out of 13K+, also waiting to uncloud. Kanarch runs Unix/Mono. This is in Firestorm 4.6.5.

Just before this, I logged in to my home region with Replex where my inventory loaded almost instantly. I have had the fetch hang there in the past. This runs Linux. It just seems so random and hard to replicate. (Key Gruin here)

(0026715)
BlueWall (administrator)
2014-08-10 07:56

I was able to do some testing on OSGrid last week, and this issue seems to be directly related to the quality of the network connection between the simulator and the OSGrid inventory service. It doesn't seem to be associated with particular inventory folders or items. My network connection is very bad here, and the sim is unusable. The OSG plaza regions are located in the same datacenter as the inventory service.
(0026716)
Nicky Perian (reporter)
2014-08-10 08:02

Could this be the result of Operating System(OS) updates to compensate for the heart bleed and other http/https failings that occurred last spring?

Does anyone have and old box with un-updated Operating System?

Then the question: "Is it the client OS or the host OS or is it a combo?"
(0026717)
BlueWall (administrator)
2014-08-10 08:06

The heart bleed updates focused on ssl and I think it wouldn't affect this at all, as it is not using ssl. I think we have a good mix of operating systems represented in the simulators and viewers reported, so probably not an operating system issue either.
(0026718)
Mata Hari (reporter)
2014-08-10 08:07

Further tests...

I pulled git eb14e5a r/23129 from mid-July of last year, compiled it and tried logging in...fetch hung.

Right now I am standing on a third sim that Dan has hosted on a linux box in New Jersey and it, too has hung on the fetch.

Combined with Key and BlueWall's observations this means the .NET/Mono hypothesis is dead.

The strange thing is there are sims where the server is located overseas and has much slower connection to the OSG asset server (almost certainly slower than my connection which consistently pings at <60ms whereas most trans-Atlantic connections are 100ms+) and yet they will allow me to login just fine.
(0026719)
aiaustin (developer)
2014-08-10 08:15
edited on: 2014-08-10 08:28

I have tested with the 0.7.6 (not 0.7.6.1) precompiled formal release. That is definitely .net3.5 as it asked me to install that as I am on a new Windows 8.1 box that only has .net4 onwards installed.

I now have an add on region with VERY simple content onto OSGrid and I logged on. I have inventory stuck issue and cloud avatar still after 15 minutes waiting.

Of course this does not definitively rule out a .net 3.5 to .net 4 issue since the problem may be OSGrid inventory server side and not at the region sim end... and the core services will still be .net4. But at least we know its not confined to the add on regions under .net 4.

(0026720)
aiaustin (developer)
2014-08-10 08:23
edited on: 2014-08-10 12:37

Bluewall, I wonder what a "bad" connection is though... My tests are on a server in the UK on a gigabit network and switches close to the academic backbone. We run really heavy traffic over these all the time.

The ping to inventory.osgrid.org is regularly 120ms to 125ms and does not vary all that much on all tests on weekend and weekdays. I just repeated that to check.

Mind you a ping from the same server to bbc.co.uk is 12ms and a ping to google.com is 6ms. I just tried Speedtest.net from the server to East Coast US sites and those were typically pings of 90-100ms and to West Coast US sites were pings of 150-160ms. So OSGrid is smack in the middle of that range and probably what we should expect.

OpenSim really should not be locking up like this just because things run slowly or no reply is given by an overloaded or dropping out host. Shorter than usual timeouts changed from 120 seconds to 10 seconds do not trigger which implies to me that there is something more seriously wrong. And indeed we are generating seemingly thousands of extra inventory request due to this... which is obviously making the server load HIGHER when it should just be handled properly once and be zero in some cases after logout.

Our sims by the way are perfectly usable and do not seem slow once you are on them... we just cannot ask users to log directly in to them. We have to go via a plaza, and then TP across.

(0026721)
BlueWall (administrator)
2014-08-10 08:47

Today my inventory completes. I will leave the region up for a while for testing: BlueWall on OSGrid. It would be good to have others login there to see if the results are the same. It is a slow connection, so give a little extra time for rezzing.
(0026722)
Mata Hari (reporter)
2014-08-10 09:10

@BlueWall

Tried logging in to your region and the fetch hung for me.
(0026723)
BlueWall (administrator)
2014-08-10 09:41

Ok, others are reporting that as well, so that is good. I want to do some packet captures to see if there are any clues.
(0026724)
BlueWall (administrator)
2014-08-10 10:14

@aiaustin, that is the big question. It seems that there is some threshold of time that triggers the issue. I'm hoping to capture some packets to see if there are any patterns or clues in them.
(0026725)
Mata Hari (reporter)
2014-08-10 11:20

Correct me if I'm wrong, but I thought that the log of my last test with logging set at 5 clearly shows that the data is being successfully requested and retrieved from the OSG asset server however it's the handling of that data *after* retrieval that is somehow getting locked into an infinite cycle. Instead of sending it on to the viewer for some reason it's re-requesting the exact same data again from the asset server....and will stay stuck in this loop for a very, very long time, which puts a ton of stress on the asset server as well as making the simulator highly unresponsive to anyone else in the region.

These requests aren't timing out...they're being mishandled on return.
(0026726)
BlueWall (administrator)
2014-08-10 18:07

I am finding that the simulator is requesting the same item many times. Checking several arbitrary item ids finds that they are requested 55 times. Early in the session, I see an item requested 5 times. Perhaps this is at a point before the inventory fetch hangs.
(0026727)
aiaustin (developer)
2014-08-11 01:12
edited on: 2014-08-11 01:15

I believe that both Mata and myself observe that the Inventory Recent tab seems to start at a reasonable high number (assuming cache has not been cleared). Sometimes by the time we can open the inventory tool and view the tab it is already at 380 for an avatar with 495 items, 3,000 for an avatar with 4,000 items and 10,000 for an avatar with 14,000 items.

It then tends to stick once for a while, then move up to another "final" stuck forever point short of the avatar inventory total.

Sometime the whole inventory does come in though. Perhaps one in 5 or 6 attempts.

On a Plaza it always comes in and very quickly.

The pending request shown by "show stats inventory" tend to grow while its in the stuck state. After log off the pending requests gradually and slowly (2 or 3 a minute) come down.. but if they were up in the hundreds that can take ages. If the pending request is not zero, as it usually is not after an avatar logs off or you have not left it running idle for an hour or so, if the sim is shutdown we always get the red thread aborting error.

Neither myself or Mata I believe have seen a timeout message though we have bot set the timeout period down from the default to 10 seconds as request by Justin.

(0026728)
aiaustin (developer)
2014-08-11 01:32
edited on: 2014-08-11 03:42

Just saw one timeout (set at 10 seconds) in the middle of a stuck inventory on OSGrid add on region OpenVCE after viewer was left with no activity and inventory recent tab open in Firestorm 4.6.5 after was left for 5 minutes... inventory was stuck (forever) at 3,142 for an avatar with just under 4,000 items if they all were fetched.

09:22:02 - [LOGHTTP]: HTTP OUT 63251 SynchronousRestForms POST to http://inventory.osgrid.org/xinventory [^]
09:22:03 - [LOGHTTP]: HTTP OUT 63251 took 235ms, 110ms writing
09:22:03 - [LOGHTTP]: HTTP OUT 63252 SynchronousRestForms POST to http://inventory.osgrid.org/xinventory [^]
09:22:03 - [LOGHTTP]: HTTP OUT 63252 took 234ms, 125ms writing
09:22:03 - [LOGHTTP]: HTTP OUT 63253 SynchronousRestForms POST to http://inventory.osgrid.org/xinventory [^]

Region (root) # show stats inventory
inventory.http://inventory.osgrid.org.RequestsMade [^] : 61398 requests, 0 requests/s, 3.22 requests/s
inventory.httpfetch.ProcessedFetchInventoryRequests : 702, 0/s, 0.07/s
inventory.httpfetch.QueuedFetchInventoryRequests : 37, 0/s, 0.09/s

09:22:13 - [FORMS]: Error receiving response from http://inventory.osgrid.org/xinventory: [^] The operation has timed out. Request: METHOD=GETITEM&ID=3041bde6-2140-40ef-87fe-50d04c46bd63
09:22:13 - [XINVENTORY SERVICES CONNECTOR]: Exception in GetItem: System.Net.Web
Exception: The operation has timed out
   at OpenSim.Framework.SynchronousRestFormsRequester.MakeRequest(String verb, String requestUrl, String obj, Int32 timeoutsecs, IServiceAuth auth) in k:\OSGRID\opensim-8738445\OpenSim\Framework\WebUtil.cs:line 1087
   at OpenSim.Services.Connectors.XInventoryServicesConnector.MakeRequest(String method, Dictionary`2 sendData) in k:\OSGRID\opensim-8738445\OpenSim\Services\Connectors\Inventory\XInventoryServicesConnector.cs:line 534
   at OpenSim.Services.Connectors.XInventoryServicesConnector.GetItem(InventoryItemBase item) in k:\OSGRID\opensim-873844\OpenSim\Services\Connectors\Inventory\XInventoryServicesConnector.cs:line 431

09:22:13 - [LOGHTTP]: HTTP OUT 63254 SynchronousRestForms POST to http://inventory.osgrid.org/xinventory [^]
09:22:19 - [LOGHTTP]: Slow SynchronousRestForms request 63254 POST to http://inventory.osgrid.org/xinventory [^] took 5641ms, 469ms writing, METHOD=GETITEM&ID=25a5e02d-e3e7-4937-9e4d-a7fe3c59fe9f
09:22:19 - [LOGHTTP]: HTTP OUT 63255 SynchronousRestForms POST to http://inventory.osgrid.org/xinventory [^]
09:22:19 - [LOGHTTP]: HTTP OUT 63255 took 235ms, 110ms writing
09:22:19 - [LOGHTTP]: HTTP OUT 63256 SynchronousRestForms POST to http://inventory.osgrid.org/xinventory [^]
09:22:19 - [LOGHTTP]: HTTP OUT 63256 took 234ms, 109ms writing

(0026753)
Radioactive Rosca (reporter)
2014-08-17 06:52
edited on: 2014-08-17 06:54

Hi all and only a comment, confirming what someone (I think it was aiaustin) already commented.

After the inventory stops fetching objects (90% of the logins) in one of my regions running OpenSim 0.8.1 Dev, OSgrid 0.8.1 (Dev) 3a643e2: 2014-08-15 (Win/.NET) and if my avatar goes to a neighbour SIM that runs OpenSim 0.8.1 Dev, OSgrid 0.8.1 (Dev) 219d273: 2014-07-05 (Unix/Mono), it restarts fetching the inventory and I stop being a cloud.

My OpenSIM's are running on a Windows 8.1 64 bits, .NET framework 4.5.1 (378675).

(0026755)
aiaustin (developer)
2014-08-17 08:58
edited on: 2014-08-17 08:59

Hi there Radioactive Rosca... it was not me that reported a behaviour where we could get the stuck inventory to finish loading when moving to another of our own OSGrid addon regions.

But since you mentioned it I did a test. All our Sims are on latest 0.8.1 dev master and on Windows 8.1 Pro.

Logged on with avatar with inventory total count of 495. It stuck at 471. pending requests was going up as usual and not dropping to zero.

Tried to TP another region on SAME OpenSim.exe instance. No change in inventory count in viewer at all. Inventory fetch still stuck.

Tried to TP to another of our addon regions on a SEPSARATE OpenSim.exe instance on a SEPARATE host. Again still stuck.

Then tried TP to Wright Plaza, and inventory fetch completed instantly.

(0026756)
aiaustin (developer)
2014-08-17 09:00

Anyone have a view on whether the Windows .net 4 "variances" to .net 3.5 could be an issue?

http://opensimulator.org/mantis/view.php?id=7054#c26709 [^]
(0026757)
Mata Hari (reporter)
2014-08-17 11:23

While the variances between .NET 3.5 and 4.0 could conceivably be an issue, I somewhat doubt it's at the root of this one because our testing has shown fetch to hang on Linux servers under assorted (but recent) versions of mono. If it were purely a .NET problem the Linux servers shouldn't be exhibiting the same symptoms.
(0026762)
Radioactive Rosca (reporter)
2014-08-18 01:17

Hi again, aiaustin and sorry for the change of names...

If you try any of the "Utopia Portugal" SIM's (using Unix/Mono OpenSIM version already referenced), it's the same reaction as going to "Wright Plaza"... the inventory fetch quickly restarts until complete.

I also upgraded the .NET framework of my Windows 8.1 to last version (4.5.2 release 379893) with no positive results.
(0026764)
Radioactive Rosca (reporter)
2014-08-18 06:48

Please do not laugh, but I tried last version of OpenSim in a Debian computer... my Raspberry Pi version B, 512 Mbytes.

After several tries, I could connect the region Radioactive 07 to OSGrid.

I can't comment all the timeouts, I only include some...

But the interesting thing is when I logged in to that SIM (via OSGrid):

My avatar with 3034 objects in inventory, could fetch 2825, before stopping the fetch.



13:07:40 - [SynchronousRestObjectRequester]: WebException for GET http://assets.osgrid.org/assets/50f056a7-cac5-4605-b00f-464bda93a1d7 [^] OpenSim.Framework.AssetBase System.Net.WebException: The request timed out
  at System.Net.HttpWebRequest.EndGetResponse (IAsyncResult asyncResult) [0x00000] in <filename unknown>:0
  at System.Net.HttpWebRequest.GetResponse () [0x00000] in <filename unknown>:0
  at OpenSim.Framework.SynchronousRestObjectRequester.MakeRequest[Int32,AssetBase] (System.String verb, System.String requestUrl, Int32 obj, Int32 pTimeout, Int32 maxConnections, IServiceAuth auth) [0x00000] in <filename unknown>:0

13:07:41 - [SynchronousRestObjectRequester]: WebException for GET http://assets.osgrid.org/assets/b75417cf-0827-43dd-89ed-5c09f4dc3b11 [^] OpenSim.Framework.AssetBase System.Net.WebException: The request timed out
  at System.Net.HttpWebRequest.EndGetResponse (IAsyncResult asyncResult) [0x00000] in <filename unknown>:0
  at System.Net.HttpWebRequest.GetResponse () [0x00000] in <filename unknown>:0
  at OpenSim.Framework.SynchronousRestObjectRequester.MakeRequest[Int32,AssetBase] (System.String verb, System.String requestUrl, Int32 obj, Int32 pTimeout, Int32 maxConnections, IServiceAuth auth) [0x00000] in <filename unknown>:0

13:07:39 - [LOGHTTP]: Slow SynchronousRestObject request 448 GET to http://assets.osgrid.org/assets/11dcc3a3-6b2c-4685-a141-b6a24842b434 [^] took 100915ms, 0ms writing,
13:07:45 - [LOGHTTP]: Slow SynchronousRestObject request 455 GET to http://assets.osgrid.org/assets/50f056a7-cac5-4605-b00f-464bda93a1d7 [^] took 104424ms, 0ms writing,
(0026765)
zadark (reporter)
2014-08-18 09:00

Some additional information.
Mata Hari kindly entered osgrid using a region hosted on our servers.

AS reported by Bluewall we observed repeated requests, eventually:

Data began to crawl and

Many of these
DEBUG - OpenSim.Region.ClientStack.LindenUDP.LLUDPServer [LLUDPSERVER]: Received a resend of already processed packet 0001529, type FetchInventoryDescendents from Mata Hari

Then
DEBUG - OpenSim.Framework.Util Threadfunc: enable overload mode (Queued 11, Running 128)
DEBUG - OpenSim.Framework.Util Queue threadfunc 5272 (Queued 11, Running 128) (UpdateInventoryItem) at OpenSim.Region.ClientStack.LindenUDP.LLClientView.ProcessPacketMethod(Packet packet) in c:\Projects\opensimdev\opensim-osgrid-master\OpenSim\Region\ClientStack\Linden\UDP\LLClientView.cs:line 700

Queue threadfunc messages continue until Queued exceeded 800+, at which time we disconnected the region

To be continued.
(0026766)
Mata Hari (reporter)
2014-08-18 09:58

An addendum to Zadark's above report: during the first 0000004:0000005 minutes I stood there my viewer's inventory fetch numbers slowly increased from login (0000025:0000012,500) until it reach 13,456 at which point it stalled. After standing there another 30 minutes it remained at this number. On subsequent login to a Plaza inventory fetch finished instantly at 13,467 so those 800+ queue requests Zadark had (not to mention many thousands more that had already been processed during the half hour) were for only 11 items.
(0026767)
Nicky Perian (reporter)
2014-08-18 10:01

DEBUG - OpenSim.Region.ClientStack.LindenUDP.LLUDPServer [LLUDPSERVER]: Received a resend of already processed packet 0001529, type FetchInventoryDescendents

Is it just an incomplete message?
Shouldn't that be type FetchInventoryDescendents2?
(0026768)
zadark (reporter)
2014-08-18 10:09

@Nicky Perian
For the test we disabled FetchInventoryDescendents2, using UDP FetchInventoryDescendents. Hopefully this removed HTTP server involvement.
(0026769)
aiaustin (developer)
2014-08-18 10:32
edited on: 2014-08-18 10:32

ah... interesting you disabled http fetch... and still saw the identical fetch stuck issue.

(0026770)
Mata Hari (reporter)
2014-08-18 11:17

Interesting, though not all that surprising. The data flow between simulator and inventory service appears to be working perfectly: each GET request is being responded to fairly promptly with a matching RESPONSE that contains the data requested. The hang appears to be that the simulator somehow loses track of what it's supposed to do with that data and never gets around to sending it along to the viewer and/or request any additional data from the inventory service that it lacks. It just sits there looping endlessly through the same group of items and will fill up the queue with them.
(0026771)
aiaustin (developer)
2014-08-19 14:20

I caught up with discussion on this between Justin, Mata and Bluewall on the dev meeting chat log.

Like Mata, I see no evidence at all of ANY communication between the viewer and sim when in stuck inventory fetch state.

But should I run with "debug http in 5" and does that show viewer traffic?
(0026782)
Mata Hari (reporter)
2014-08-26 21:21

Of possible relevance to tracking down the cause....with OSG down I've been on my standalone HG instead with an avi that has <600 items in inventory. On occasion the viewer will show fetching for a long time (>1 hour) but if you right-click trash and empty it (even if trash is already empty) the fetching will disappear. I haven't checked to see if there's any region activity going on during this time though so it may not be related. This is with FS 4.6.7 (42398) Aug 12 2014 02:06:18 (Firestorm-Releasex64) with OpenSimulator support
Release Notes
(0026783)
aiaustin (developer)
2014-08-27 01:23

OSGrid does have special handling of trash, in that it can only be emptied via the web site. I wonder if any special server side code is added for this that may be part of the problem?
(0027068)
Mata Hari (reporter)
2014-12-05 07:14

No...or at least I doubt it.

Refugegrid -- which is where I am now -- is running the lastest build of vanilla Opensim (db2a22e from Dec. 1st) and I have the identical behaviour. If I log in to one of the regions hosted directly on the grid's server my inventory never hangs. If I log in to one of the regions I host myself, inventory fetch hangs 100% of the time. The Refugegrid server is geographically very near me on a 150Mb in/out connection. My own service is now 100Mb down (only 6Mb up though) and a ping test of 50 pings typically yields 0 fails, average response time of 20ms and max of 60ms (usually less) so I don't think it can be attributed to latency either. I have never, ever had it happen when running on my standalone.
(0027623)
aiaustin (developer)
2015-02-27 04:23
edited on: 2015-02-27 04:34

Now we have the restarted OSGrid, I am seeing several instances of the following style of error we have noted in this issue... it does not seem to relate to inventory fetch hanging though... should I start a new issue to consider this?

09:58:54 - [FORMS]: Error receiving response from http://inventory.osgrid.org/xinventory: [^] The remote server returned an error: (502) Bad Gateway.. Request: METHOD=GETFOLDERCONTENT&PRINCIPAL=61b7cfc7-ca16-46d8-881a-a1d445f7e5ee&FOLDER=c4e1b3
4e-6599-b943-85cf-473979c4fde3
09:58:54 - [XINVENTORY SERVICES CONNECTOR]: Exception in GetFolderContent: The remote server returned an error: (502) Bad Gateway.
09:58:55 - [XINVENTORY SERVICES CONNECTOR]: Exception in GetItem: System.Xml.Xml
Exception: Root element is missing.
   at System.Xml.XmlTextReaderImpl.ThrowWithoutLineInfo(String res)
   at System.Xml.XmlTextReaderImpl.ParseDocumentContent()
   at System.Xml.XmlLoader.Load(XmlDocument doc, XmlReader reader, Boolean preserveWhitespace)
   at System.Xml.XmlDocument.Load(XmlReader reader)
   at System.Xml.XmlDocument.LoadXml(String xml)
   at OpenSim.Server.Base.ServerUtils.ParseXmlResponse(String data) in k:\OSGRID\opensim-7b9ad11\OpenSim\Server\Base\ServerUtils.cs:line 469
   at OpenSim.Services.Connectors.XInventoryServicesConnector.MakeRequest(String
 method, Dictionary`2 sendData) in k:\OSGRID\opensim-7b9ad11\OpenSim\Services\Connectors\Inventory\XInventoryServicesConnector.cs:line 539
   at OpenSim.Services.Connectors.XInventoryServicesConnector.GetItem(InventoryItemBase item) in k:\OSGRID\opensim-7b9ad1\OpenSim\Services\Connectors\Inventory\XInventoryServicesConnector.cs:line 431

(0027624)
aiaustin (developer)
2015-02-27 05:34

On shutdown on add o regions for OSGrid (restarted version using r/25806) I see the app crash again too.. perhaps due to inventory fetch hangs again...

12:49:08 - [WATCHDOG]: Removing thread InventoryWorkerThread0, ID 52
12:49:08 - [INVENTORY]: Failed to process queued inventory request ced7a24e-8a5b
-48e2-b2cd-f38e9c27fcdb for Ai Austin in Vue-Port. Exception System.Threading.T
hreadAbortException: Thread was being aborted.
   at System.Threading.Monitor.Enter(Object obj)
   at OpenSim.Region.CoreModules.ServiceConnectorsOut.Inventory.HGInventoryBroke
r.GetItem(InventoryItemBase item) in k:\OSGRID\opensim-7b9ad11\OpenSim\Region\Co
reModules\ServiceConnectorsOut\Inventory\HGInventoryBroker.cs:line 591
   at OpenSim.Capabilities.Handlers.FetchInvDescHandler.Fetch(UUID agentID, UUID
 folderID, UUID ownerID, Boolean fetchFolders, Boolean fetchItems, Int32 sortOrd
er, Int32& version, Int32& descendents) in k:\OSGRID\opensim-7b9ad11\OpenSim\Cap
abilities\Handlers\FetchInventoryDescendents\FetchInvDescHandler.cs:line 276
   at OpenSim.Capabilities.Handlers.FetchInvDescHandler.FetchInventoryReply(LLSD
FetchInventoryDescendents invFetch) in k:\OSGRID\opensim-7b9ad11\OpenSim\Capabil
ities\Handlers\FetchInventoryDescendents\FetchInvDescHandler.cs:line 161
   at OpenSim.Capabilities.Handlers.FetchInvDescHandler.FetchInventoryDescendent
sRequest(String request, String path, String param, IOSHttpRequest httpRequest,
IOSHttpResponse httpResponse) in k:\OSGRID\opensim-7b9ad11\OpenSim\Capabilities\
Handlers\FetchInventoryDescendents\FetchInvDescHandler.cs:line 111
   at OpenSim.Region.ClientStack.Linden.WebFetchInvDescModule.PollServiceInvento
ryEventArgs.Process(aPollRequest requestinfo) in k:\OSGRID\opensim-7b9ad11\OpenS
im\Region\ClientStack\Linden\Caps\WebFetchInvDescModule.cs:line 363
   at OpenSim.Region.ClientStack.Linden.WebFetchInvDescModule.WaitProcessQueuedI
nventoryRequest() in k:\OSGRID\opensim-7b9ad11\OpenSim\Region\ClientStack\Linden
\Caps\WebFetchInvDescModule.cs:line 443
12:49:08 - [WATCHDOG]: Removing thread InventoryWorkerThread1, ID 53
12:49:08 - [XEngine]: Shutting down 49 scripts in Vue-Port
12:49:08 - [FORMS]: Error receiving response from http://inventory.osgrid.org/xi [^]
nventory: Thread was being aborted.. Request: METHOD=GETITEM&ID=59dcdece-22df-45
23-8ae7-b17c61b03d8c
12:49:08 - [XINVENTORY SERVICES CONNECTOR]: Exception in GetItem: System.Threadi
ng.ThreadAbortException: Thread was being aborted.
   at OpenSim.Framework.SynchronousRestFormsRequester.MakeRequest(String verb, S
tring requestUrl, String obj, Int32 timeoutsecs, IServiceAuth auth) in k:\OSGRID
\opensim-7b9ad11\OpenSim\Framework\WebUtil.cs:line 1087
   at OpenSim.Services.Connectors.XInventoryServicesConnector.MakeRequest(String
 method, Dictionary`2 sendData) in k:\OSGRID\opensim-7b9ad11\OpenSim\Services\Co
nnectors\Inventory\XInventoryServicesConnector.cs:line 534
   at OpenSim.Services.Connectors.XInventoryServicesConnector.GetItem(InventoryI
temBase item) in k:\OSGRID\opensim-7b9ad11\OpenSim\Services\Connectors\Inventory
\XInventoryServicesConnector.cs:line 431

12:49:08 - [APPLICATION]:
APPLICATION EXCEPTION DETECTED: System.UnhandledExceptionEventArgs

Exception: System.NullReferenceException: Object reference not set to an instanc
e of an object.
   at OpenSim.Region.ClientStack.Linden.WebFetchInvDescModule.WaitProcessQueuedI
nventoryRequest() in k:\OSGRID\opensim-7b9ad11\OpenSim\Region\ClientStack\Linden
\Caps\WebFetchInvDescModule.cs:line 447
   at OpenSim.Region.ClientStack.Linden.WebFetchInvDescModule.DoInventoryRequest
s() in k:\OSGRID\opensim-7b9ad11\OpenSim\Region\ClientStack\Linden\Caps\WebFetch
InvDescModule.cs:line 431
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionCo
ntext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
   at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, C
ontextCallback callback, Object state, Boolean preserveSyncCtx)
   at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, C
ontextCallback callback, Object state)
   at System.Threading.ThreadHelper.ThreadStart()

Application is terminating: True

12:49:08 - [
Unhandled Exception: WATCHDOG]: Removing thread bulletunmanaged (Vue-Port), ID 4
9
System.NullReferenceException: Object reference not set to an instance of an obj
ect.
   at OpenSim.Region.ClientStack.Linden.WebFetchInvDescModule.WaitProcessQueuedI
nventoryRequest() in k:\OSGRID\opensim-7b9ad11\OpenSim\Region\ClientStack\Linden
\Caps\WebFetchInvDescModule.cs:line 447
   at OpenSim.Region.ClientStack.Linden.WebFetchInvDescModule.DoInventoryRequest
s() in k:\OSGRID\opensim-7b9ad11\OpenSim\Region\ClientStack\Linden\Caps\WebFetch
InvDescModule.cs:line 431
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionCo
ntext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
   at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, C
ontextCallback callback, Object state, Boolean preserveSyncCtx)
   at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, C
ontextCallback callback, Object state)
   at System.Threading.ThreadHelper.ThreadStart()
12:49:08 - [SCENE]: Closing down the single simulator: Edinburgh
12:49:08 - [WATCHDOG]: Removing thread Heartbeat-(Edinburgh), ID 87
12:49:08 - [WATCHDOG]: Removing thread Maintenance (Edinburgh), ID 90
(0027664)
aiaustin (developer)
2015-03-02 05:23
edited on: 2015-03-02 05:30

Now that OSGrid is back up I am seeing again the issues reported in this OSGrid addon release based on r/25806... only 1 avatar on the rergion, and inventory fetch sticks and never continues.... same kinds of stats show on the console with a gradual build up of requests that are never satisfied... e.g. three show stats a minute apart... but avatar viewer shows NO progress at all on a stuck inventory...

Region (root) # stats show inventory
inventory.http://inventory.osgrid.org.RequestsMade [^] : 5846 requests, 4 requests/s, 4.26 requests/s
inventory.httpfetch.ProcessedFetchInventoryRequests : 116, 0/s, 0.03/s
inventory.httpfetch.QueuedFetchInventoryRequests : 33, 0/s, 0.1/s

Region (root) # stats show inventory
inventory.http://inventory.osgrid.org.RequestsMade [^] : 6555 requests, 4.4 requests/s, 4.3 requests/s
inventory.httpfetch.ProcessedFetchInventoryRequests : 132, 0/s, 0.12/s
inventory.httpfetch.QueuedFetchInventoryRequests : 42, 0.4/s, 0.03/s

Region (root) # stats show inventory
inventory.http://inventory.osgrid.org.RequestsMade [^] : 6837 requests, 4.4 requests/s, 4.24 requests/s
inventory.httpfetch.ProcessedFetchInventoryRequests : 137, 0.8/s, 0.09/s
inventory.httpfetch.QueuedFetchInventoryRequests : 48, -0.8/s, 0.07/s


As before, after logout from the viewer for the avatar with the stuck inventory fetch, the stats start to go down gradually...

Region (root) # stats show inventory
inventory.http://inventory.osgrid.org.RequestsMade [^] : 7744 requests, 4.4 requests/s, 4.24 requests/s
inventory.httpfetch.ProcessedFetchInventoryRequests : 153, 0.4/s, 0.05/s
inventory.httpfetch.QueuedFetchInventoryRequests : 64, -0.4/s, 0.1/s
Region (root) # stats show inventory
inventory.http://inventory.osgrid.org.RequestsMade [^] : 7774 requests, 4 requests/s, 4.23 requests/s
inventory.httpfetch.ProcessedFetchInventoryRequests : 155, 0.4/s, 0.07/s
inventory.httpfetch.QueuedFetchInventoryRequests : 62, -0.4/s, 0.07/s
Region (root) # stats show inventory
inventory.http://inventory.osgrid.org.RequestsMade [^] : 7975 requests, 4.4 requests/s, 4.28 requests/s
inventory.httpfetch.ProcessedFetchInventoryRequests : 159, 0/s, 0.12/s
inventory.httpfetch.QueuedFetchInventoryRequests : 58, 0/s, -0.12/s


But if the OpenSim.exe involved is shutdown before this reaches 0 - which can take a long time if it has built up significantly.. we get the crash as before... e.g. this shutdown of OpenSim.exe a few minutes after the single avatar has logged out of their viewer...

13:26:44 - [SHUTDOWN]: Closing all threads
13:26:44 - [SHUTDOWN]: Killing listener thread
13:26:44 - [SHUTDOWN]: Killing clients
13:26:44 - [SHUTDOWN]: Closing console and terminating
13:26:44 - [SCENE]: Closing down the single simulator: Vue-Port
13:26:44 - [WATCHDOG]: Removing thread Heartbeat-(Vue-Port), ID 90
13:26:44 - [WATCHDOG]: Removing thread Maintenance (Vue-Port), ID 104
13:26:44 - [SCENE]: Persisting changed objects
13:26:44 - [GRID SERVICE]: Deregistering region Vue-Port (2b19b711-39e5-462f-bfd
2-a68ab05cebe5) at 6400-6400
13:26:45 - [SHUTDOWN]: Shutting down region Vue-Port
13:26:45 - [DATASNAPSHOT]: Region Vue-Port is being removed, removing from index
ing
13:26:45 - [WATCHDOG]: Removing thread InventoryWorkerThread0, ID 52
13:26:45 - [INVENTORY]: Failed to process queued inventory request 4cd6a93c-a76f
-4339-b7a3-33b1cd13aee0 for Ai Austin in Vue-Port. Exception System.Threading.T
hreadAbortException: Thread was being aborted.
   at System.Threading.Monitor.Enter(Object obj)
   at OpenSim.Region.CoreModules.ServiceConnectorsOut.Inventory.HGInventoryBroke
r.GetItem(InventoryItemBase item) in k:\OSGRID\opensim-7b9ad11\OpenSim\Region\Co
reModules\ServiceConnectorsOut\Inventory\HGInventoryBroker.cs:line 591
   at OpenSim.Capabilities.Handlers.FetchInvDescHandler.Fetch(UUID agentID, UUID
 folderID, UUID ownerID, Boolean fetchFolders, Boolean fetchItems, Int32 sortOrd
er, Int32& version, Int32& descendents) in k:\OSGRID\opensim-7b9ad11\OpenSim\Cap
abilities\Handlers\FetchInventoryDescendents\FetchInvDescHandler.cs:line 276
   at OpenSim.Capabilities.Handlers.FetchInvDescHandler.FetchInventoryReply(LLSD
FetchInventoryDescendents invFetch) in k:\OSGRID\opensim-7b9ad11\OpenSim\Capabil
ities\Handlers\FetchInventoryDescendents\FetchInvDescHandler.cs:line 161
   at OpenSim.Capabilities.Handlers.FetchInvDescHandler.FetchInventoryDescendent
sRequest(String request, String path, String param, IOSHttpRequest httpRequest,
IOSHttpResponse httpResponse) in k:\OSGRID\opensim-7b9ad11\OpenSim\Capabilities\
Handlers\FetchInventoryDescendents\FetchInvDescHandler.cs:line 111
   at OpenSim.Region.ClientStack.Linden.WebFetchInvDescModule.PollServiceInvento
ryEventArgs.Process(aPollRequest requestinfo) in k:\OSGRID\opensim-7b9ad11\OpenS
im\Region\ClientStack\Linden\Caps\WebFetchInvDescModule.cs:line 363
   at OpenSim.Region.ClientStack.Linden.WebFetchInvDescModule.WaitProcessQueuedI
nventoryRequest() in k:\OSGRID\opensim-7b9ad11\OpenSim\Region\ClientStack\Linden
\Caps\WebFetchInvDescModule.cs:line 443
13:26:45 - [FORMS]: Error receiving response from http://inventory.osgrid.org/xi [^]
nventory: Thread was being aborted.. Request: METHOD=GETITEM&ID=cbccdbbe-d1d6-49
c0-acf9-75593dcf2f74
13:26:45 - [WATCHDOG]: Removing thread InventoryWorkerThread1, ID 53
13:26:45 - [XINVENTORY SERVICES CONNECTOR]: Exception in GetItem: System.Threadi
ng.ThreadAbortException: Thread was being aborted.
   at OpenSim.Framework.SynchronousRestFormsRequester.MakeRequest(String verb, S
tring requestUrl, String obj, Int32 timeoutsecs, IServiceAuth auth) in k:\OSGRID
\opensim-7b9ad11\OpenSim\Framework\WebUtil.cs:line 1087
   at OpenSim.Services.Connectors.XInventoryServicesConnector.MakeRequest(String
 method, Dictionary`2 sendData) in k:\OSGRID\opensim-7b9ad11\OpenSim\Services\Co
nnectors\Inventory\XInventoryServicesConnector.cs:line 534
   at OpenSim.Services.Connectors.XInventoryServicesConnector.GetItem(InventoryI
temBase item) in k:\OSGRID\opensim-7b9ad11\OpenSim\Services\Connectors\Inventory
\XInventoryServicesConnector.cs:line 431

13:26:45 - [XEngine]: Shutting down 49 scripts in Vue-Port
13:26:45 - [APPLICATION]:
APPLICATION EXCEPTION DETECTED: System.UnhandledExceptionEventArgs

Exception: System.NullReferenceException: Object reference not set to an instanc
e of an object.
   at OpenSim.Region.ClientStack.Linden.WebFetchInvDescModule.WaitProcessQueuedI
nventoryRequest() in k:\OSGRID\opensim-7b9ad11\OpenSim\Region\ClientStack\Linden
\Caps\WebFetchInvDescModule.cs:line 447
   at OpenSim.Region.ClientStack.Linden.WebFetchInvDescModule.DoInventoryRequest
s() in k:\OSGRID\opensim-7b9ad11\OpenSim\Region\ClientStack\Linden\Caps\WebFetch
InvDescModule.cs:line 431
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionCo
ntext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
   at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, C
ontextCallback callback, Object state, Boolean preserveSyncCtx)
   at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, C
ontextCallback callback, Object state)
   at System.Threading.ThreadHelper.ThreadStart()

Application is terminating: True


Unhandled Exception: System.NullReferenceException: Object reference not set to
an instance of an object.
   at OpenSim.Region.ClientStack.Linden.WebFetchInvDescModule.WaitProcessQueuedI
nventoryRequest() in k:\OSGRID\opensim-7b9ad11\OpenSim\Region\ClientStack\Linden
\Caps\WebFetchInvDescModule.cs:line 447
   at OpenSim.Region.ClientStack.Linden.WebFetchInvDescModule.DoInventoryRequest
s() in k:\OSGRID\opensim-7b9ad11\OpenSim\Region\ClientStack\Linden\Caps\WebFetch
InvDescModule.cs:line 431
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionCo
ntext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
   at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, C
ontextCallback callback, Object state, Boolean preserveSyncCtx)
   at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, C
ontextCallback callback, Object state)
   at System.Threading.ThreadHelper.ThreadStart()

(0027665)
Mata Hari (reporter)
2015-03-02 06:13

@AiAustin, yes, this issue has been an ongoing one and I've brought it up as often as I dare at dev meetings. I can only log in to a grid-hosted region (at OSG or in Regfugegrid). If I log in to a region I host it will lock into the infinite fetch and never finish. If you turn on HTTP logging and parse it (as I show in "parse.txt" attached) you'll see that it's a small set of items being continually refetched.
(0027677)
Mata Hari (reporter)
2015-03-02 14:58

@AiAustin: it isn't timing out. The fetch is requested and shortly after that it is returned -- typically within 60ms in my detailed test with the OSG server which I supplied attached). The region then requests it again. And receives it again. And requests it again. And again. And this continues until the number of queued request has consumed all available RAM in the region server and will continue to do so until the user logs out and the entire (many GB!) of queued requests are finally processed, or the region is reset with a forced process stop.

I also my issues were tested between my server (Ontario) and the OSG server (Texas) as well as my server and the Refugegrid server (Quebec), neither of which is trans-atlantic and both of which have fast response times (60ms or less).
(0027681)
aiaustin (developer)
2015-03-03 01:42
edited on: 2015-03-03 01:44

Okay Mata... noted. And I have watched your attempts to raise this the Dev meetings and supported that behind the scenes when I can.

Is there anything in common with the small number of items that are continually refetched?

I think this is the single most serious usability issue affecting OpenSim today and very difficult to explain the workaround of logging in indirectly via a plaza and the going where you are meant to be to normal users.

(0027684)
Mata Hari (reporter)
2015-03-03 10:44

@AiAustin: there's no commonality of the items or folders that I've been able to discern. Bluewall and I spent a Sunday afternoon doing a series of tests on his sim, with highly detailed reporting, which he has posted to this Mantis in addition to the data I've supplied. Whether these have been looked at by a dev and any pattern detected, I couldn't say. I don't know if any of the reports have been looked at.

The devs haven't asked for any additional information (in fact Justin has said that there's too much information here to read) so other than bringing it up at dev meetings in the hopes that someone might be interested, I have no idea what else can be done to facilitate a fix.

I concur with you that it's probably the most serious outstanding usability issue but I guess that opinion isn't shared by the powers that be or it wouldn't be about to celebrate a birthday.
(0027695)
aiaustin (developer)
2015-03-03 14:24
edited on: 2015-03-05 06:46

Discussion between FreakyTech, BlueWall and JustinCC on
http://opensimulator.org/wiki/Chat_log_from_the_meeting_on_2015-03-03 [^]
about EndPointLock and WebUtil.DoServiceRequest looks potentially relevant

(0027744)
Mata Hari (reporter)
2015-03-04 12:19

After updating to opensim-0863772 r/25868 2015-03-04 I tried logging in directly to one of my self-hosted regions and for the first time in a year the initial inventory fetch did not hang (vs for the last 6+ months 100% of my login attempts there have hung).

I will test this repeatedly by logging in there each time for the next few days in case this one success was a fluke; but it's possible that one of the many patches Freaky donated has fixed this issue.
(0027745)
aiaustin (developer)
2015-03-05 07:22

I also have been testing OSGrid add on regions updated today to r/25870 by merging that release after compilation over the current r/25827 packaged add on release.. and I am sorry to report that the inventory stick problem, building up pending requests, and crash shortly after logoff while such pending requests still are outstanding.. so all the same issues are still present.
(0027800)
Mata Hari (reporter)
2015-03-07 20:13

@AiAustin

I've now logged into each of my self-host Refugegrid regions at least 5 times (20+ logins) running 08637772 (r/25868) under Win7-64 .NET and have not had a single one of those logins result in an inventory fetch hang. Prior to this, I would hang on 100% of my logins with the symptoms you described (although the regions would rarely crash...they'd simply be utterly unresponsive for very long periods of time as they slowly chewed their way through many GB of queued refetch requests). At this point it appears that for my own login issues something in the latest batch of patches has cleared up this problem.

I wonder if perhaps you should try a completely clean build and test that? Can't think why it would make a difference but one never knows. Or perhaps whatever was changed only fixed it for a Win install (if you're running under linux/mono)?
(0027801)
FreakyTech (reporter)
2015-03-08 01:25

@aiaustin

The invalid folder response that was before inside OpenSim for FetchInventory2Descendents falsified viewer inventory cache. So, hopefully you did a clear of that before retesting.

Yet, the EndpointLock is afaik still an open topic within opensim-git.
(0027802)
aiaustin (developer)
2015-03-08 01:50
edited on: 2015-03-08 01:56

Noted FreakyTech.. thanks. I had NOT cleared the cache. I will do that on my (rather a large number of) machines before observing again

Mata, the crash on Opensim.exe only occured (as always for this issue) when trying to "q"/"shutdown" the simulator while pending requests had not fallen (very slowly as you said) back to zero.

(0027803)
aiaustin (developer)
2015-03-08 07:23
edited on: 2015-03-09 04:42

I am on Windows for my add-on OSGrid regions, and my (Firestorm 4.6.9) viewer.

I have ensured my OSGrid add on regions are updated to r/25875 (latest) and overlaid that onto the current r/25827 OSGrid packaged release to ensure the various addons are accessible... which is my usual mechanism to update in between OSGrid releases. All restarted with no assetcache on the OpenSim.exe server side.

Firestorm 4.6.9 viewer cache cleared and restarted and then log in with a few OSGrid avatars to the OSGrid addon regions (not a Plaza) and I see the stuck inventory every time still. Whether avatar stays as a cloud depends on where it sticks. The stick point is not always the same, and can be EARLIER (for a 2,585 avatar inventory, can stick at 1,037 for example, whereas previous run got to a still far from complete 1,260). Usual issue with QueuedFetchInventoryRequests shown by "show stats inventory" that gradually rises... and I get the usual crash on "shutdown" of OpenSim.exe if the QueuedFetchInventoryRequests has not been allowed to (very slowly) fall all the way to zero.

As usual, if the avatar TPs to a plaza, the inventory fetch resumes and completes very quickly.

So, UNLESS an OSgrid core services side update is also required, the bug is still present.

(0027807)
FreakyTech (reporter)
2015-03-08 10:42

your description makes me feel that you might be experiencing the EndpointLock side of the problem.
(0027826)
aiaustin (developer)
2015-03-09 04:23
edited on: 2015-03-09 04:43

It would be GREAT to pin this down as I know you are looking at these or related issues with your recent excellent set of patches FreakyTech. Its been an outstanding and serious usability problem for over a year that some of us get - in my case solely on OSGrid add on (non-Plaza) regions hosted on Windows 8.1.

Extract, potentially relevant, of discussion between FreakyTech, BlueWall and JustinCC on http://opensimulator.org/wiki/Chat_log_from_the_meeting_on_2015-03-03 [^] about EndPointLock and WebUtil.DoServiceRequest ...

[11:49] Freaky Tech: actually that EndpointLock in WebUtils.cs is piling up threads like hell
[11:55] Freaky Tech: this endpoint lock thing is applied to inventory, asset, map and a few more services
[11:55] Freaky Tech: the asset cache is the only one that blocks mostly on file accesses
[11:56] Freaky Tech: but these changes maybe are a bit too heavy so I selected mostly bug fix patches that are clear and easy to review
[11:57] Freaky Tech: I know because that requires to fix quite a few things alongside

(0027828)
FreakyTech (reporter)
2015-03-09 11:10
edited on: 2015-03-09 11:11

Actually, in my fork I already did the work for that but it required quite an amount of changes. The moment when I removed that, other parts required to be dealt with.

The EndpointLock was hiding some other issues. That is why it is not an easy fix.

(0027829)
aiaustin (developer)
2015-03-09 13:01

But if its a bug it eventually does need attention... it is a critical failure at present, necessitating indirect arrival at locations on a grid like OSGrid... something that is not good for less experienced users.

But I understand the difficulty of introducing more extensive changes, especially if they are all needed at once. Thanks for your inputs which I can see already are making things work that have had niggles or failures before in terms of HG interworking.
(0027830)
Mata Hari (reporter)
2015-03-09 16:25

I now just had one of my login hang (under opensim-00b5b91). I switched to http logging level 5, left myself logged in for 10 minutes, then logged out. Now, another 10 minutes later, there is still an endless stream of http activity in and out relating to my logged-out avi's inventory. The log file is currently growing at a rate of approximately 1MB per minute and I'll let it run for another half hour or so before I force the sim to shut down.

I'll keep the log for a week or so just in case anyone actually wants to have a look at it (but I assume that's highly unlikely).
(0028230)
Diva (administrator)
2015-05-05 21:31

Hello everyone. I see this is a long-winding issue that has probably extended the original report substantially. I committed an attempt at fixing *the original report* -- large inventory sometimes stops loading upon login. Please report on the effect of this fix for that situation only (no HG teleports please).

[21:28] <cia-opensim> opensim: diva * r8676b017b240 OpenSim/Region/ClientStack/Linden/Caps (WebFetchInvDescModule.cs):
[21:28] <cia-opensim> Attempt at fixing mantis 0007054. The two inventory threads are stepping on each other's feet. This needs real-world testing, as I'm not sure of all the consequences of reducing the number of worker threads to 1.
(0028236)
aiaustin (developer)
2015-05-06 01:37
edited on: 2015-05-06 06:26

Openvue and AiLand grids now running on this update (r/25964, 6-May-2015) and I will feed back any issues I spit.

But, for me, this has only been observed on OSGrid... so we will await their update of the precompiled OSGrid add-on region download to a version which includes the fix. If its related to something in the core services though, we will need to know when the central services include the fix to give useful feedback... if someone from OSGrid can report that here to alert us it would be helpful.

(0028239)
nebadon (administrator)
2015-05-06 08:14

aiaustin I have new version running on my OSgrid regions, you could test there perhaps, at the region "Sisyphus" seems unlikely its anything with the core services, as I still can not experience this problem myself on OSgrid, it probably is something with high latency to simulators. Hopefully we can get a new release up soon, I will check with danbanner.
(0028242)
Mata Hari (reporter)
2015-05-06 09:21
edited on: 2015-05-06 09:41

@Diva: tested this morning using your supplied commit (opensim-8676b01 r/25964 2015-05-06)

First the good news: under all previous version login to my own self-hosted region connect to Refugegrid would hang the fetch and eventually crash the region. Using your new patch with a FULL CACHE is extremely fast, is completeed successfully, and doesn't cause any issues for the region. With the previous versions I had 100% fetch hang and I've now done 5 separate logins using your commit and all 5 worked flawlessly.

Now the bad news...

I also did a test of logging into the region after clearing my cache. In total I have 20,815 items in inventory that need to be fetched after a clear. Not a small number, not not out of control (I know a lot of users with 100k+ items in inventory).

When I did this test the intial fetch progress was incredibly slow. For the first 27 minutes it would appear to stop fetching for 3 or 4 minutes at a time (no change in the items Firestorm was reporting as having been fetched). Then suddenly, for no apparent reason and without me doing anything at all to trigger it (I just stood there the whole time) it suddenly started to fetch far more rapidly and the count slowly and regularly grew every 20 or 30 seconds until completeded.

My login notes:
@10 min: 3499 items had been fetched
@15 min: 3573
@17 min I switched the sim to "debug hhtp all 5" and confirmed that there was a continuous flow of fetch/response traffic happening
@20 min: 3725
@25 min: 3725 (unchanged!)
@27 min: suddenly jumped to 8757 and for the rest of the fetch would climb slowly but consistently at regular intervals
@30 min: 14k
@35 min: 19k
@37 min: 20,815 and stopped increasing half a minute ago
Viewer still reports fetching but fetch has actually completed.

The viewer never stopped displaying "fetching" and I logged out again at approx 45 minutes after initially starting the test.

Subsequent login showed 20,815 items in inventory at login.

In case it's of any interest or use, I've attached the simulator log although it was only recording debug 5 as of about 16 minutes into the fetch process.


EDIT: Seth just did an empty-cache test on a RG-sever-hosted region with his avatar that has a much smaller inventory and it hung. I suspect he will add his own report to this Mantis.

(0028243)
Mata Hari (reporter)
2015-05-06 09:29

@Nebadon: when I was testing this last year on my own simulator connected to OSG I did ping tests with the OSG server. Average response times were under 100ms and 0 packet loss




Additional information about the test I just ran:

My connection: 60/5Mbps reliably (max 80/6)
Ping test to RG server: avg 35ms response time 0% loss over 100 pings
Monitoring my router traffic: peak outbound 9.5kbps, avegage 4.1kbps
                              peak inbound 321kbps, average 216kbps
(I was listening to music while standing on the sim so that would account for 128kbps of the inbound. Skype was also active)
(0028244)
nebadon (administrator)
2015-05-06 09:33

yea I don't know what the difference is, but I have never been able to experience this problem on OSgrid, my inventory is roughly around 45k items and it completely downloads in about 90-120 seconds usually with a cache clear. it does however pause for a few seconds around 21k items, but doesn't stay paused for long I can try with Firestorm, for the most part I only use Replex viewer right now.
(0028245)
nebadon (administrator)
2015-05-06 09:39

wow the Latest Firestorm beta has downloaded my inventory faster than I have ever seen, logging into Sisyphus on OSGrid with cache cleared and region freshly restarted my 45k inventory items downloaded literally within 20-30 seconds. I have never seen it download so quickly before.
(0028254)
Diva (administrator)
2015-05-06 11:41

Mata Hari: inventory fetching after a cache clear is always slow. Did this fix make it slowER than it was before, when it tended to hang?
(0028255)
aiaustin (developer)
2015-05-06 12:10
edited on: 2015-05-06 12:11

Dan Banner also did some tests with us and could not replicate the issue. Possibly because his region servers were close to the inventory and asset servers. But for some of our addon OSGrid regions that Mata and myself run we saw it all the time. My addon regions are hosted on dedicated Univerisity of Edinburgh servers on gigabit ethernet connections, but in UK so a long ping from core OSGrid serves of course.

Anyway I will do tests as Neb suggested and, if OSGrid addon distribution is not update soon, I can compile a new build to merge into our test regins to give what feedback I can.

Mata and Neb, I also see MUCH better performance for latest Firestorm 4.7.1 in terms of FPS too.. possibily just because its been brought up to date with latest excellent work by Linden Labs.

(0028256)
Mata Hari (reporter)
2015-05-06 13:45

@Diva:

Under the old patch, inventory fetch of 20k items would normally take about 180 to 240 seconds on a grid-hosted region and (if it didn't hang) about 5 to at most 10 minutes on a region hosted somewhere outside the inventory server's network. A total fetch time of 36 minutes is 3 to 5 times slower than used to be the case; but if that's the way it has to be in order to let it work at all, so be it. Prior to applying your commit my inventory fetch from one of my own regions would hang 100% of the time and result in the eventual crash of the sim.
(0028262)
nebadon (administrator)
2015-05-06 17:48

new OSgrid release is posted > https://twitter.com/osgrid/status/596111668498706432 [^]
(0028265)
aiaustin (developer)
2015-05-07 01:24
edited on: 2015-05-07 08:42

Thanks Neb. Okay I updated the Vue regions on two Windows 8.1 servers run at University of Edinburgh that (only) host our OSGrid add on regions. One is a very recent system and other is a bit older but well configured.

I started the server and let everything settle down then logged in an avatar via Firestorm 4.7.1 OS. The initial inventory fetch stuck before it had completed. show stats inventory showed the inventory.httpfetch.QueuedFetchInventoryRequests as a non-zero value that did not reduce to zero even after a few minutes wait with no activity on the server or in the viewer.

I logged out from the viewer and did a "q(uit)/shutdown on the server and as usual I got the crash (see below for this instance) which we always get with this issue if inventory.httpfetch.QueuedFetchInventoryRequests is not zero.

So I can definitively say that with r/25965 (6-May-2015) that the issue is not fixed Diva. But thanks for trying something on this long running and very serious issue.

-----------------------------------------------
Typical slowly growing show stats inventory

show stats inventory
inventory.http://inventory.osgrid.org.RequestsMade [^] : 271 requests, 3.6 requests/s, 4.03 requests/s
inventory.httpfetch.ProcessedFetchInventoryRequests : 6, 0/s, 0.07/s
inventory.httpfetch.QueuedFetchInventoryRequests : 3, 0/s, 0/s

inventory.http://inventory.osgrid.org.RequestsMade [^] : 368 requests, 4.4 requests/s, 4.09 requests/s
inventory.httpfetch.ProcessedFetchInventoryRequests : 8, 0/s, 0.09/s
inventory.httpfetch.QueuedFetchInventoryRequests : 3, 0/s, 0/s

inventory.http://inventory.osgrid.org.RequestsMade [^] : 406 requests, 4 requests/s, 4.12 requests/s
inventory.httpfetch.ProcessedFetchInventoryRequests : 8, 0/s, 0.09/s
inventory.httpfetch.QueuedFetchInventoryRequests : 3, 0/s, 0/s

inventory.http://inventory.osgrid.org.RequestsMade [^] : 424 requests, 3.6 requests/s, 4.1 requests/s
inventory.httpfetch.ProcessedFetchInventoryRequests : 8, 0/s, 0.09/s
inventory.httpfetch.QueuedFetchInventoryRequests : 3, 0/s, 0/s

inventory.http://inventory.osgrid.org.RequestsMade [^] : 431 requests, 4 requests/s, 4.12 requests/s
inventory.httpfetch.ProcessedFetchInventoryRequests : 8, 0/s, 0.09/s
inventory.httpfetch.QueuedFetchInventoryRequests : 3, 0/s, 0/s

inventory.http://inventory.osgrid.org.RequestsMade [^] : 595 requests, 4.4 requests/s, 4.09 requests/s
inventory.httpfetch.ProcessedFetchInventoryRequests : 10, 0/s, 0.02/s
inventory.httpfetch.QueuedFetchInventoryRequests : 3, 0/s, 0/s

inventory.http://inventory.osgrid.org.RequestsMade [^] : 870 requests, 4.4 requests/s, 4.21 requests/s
inventory.httpfetch.ProcessedFetchInventoryRequests : 11, 0/s, 0.02/s
inventory.httpfetch.QueuedFetchInventoryRequests : 3, 0/s, 0/s

------------------------------------------------
There was just a single slow inventory HTTP warning in this test...

[LOGHTTP]: Slow handling of 63 POST /CAPS/a2d9dac7-5990-46e0-96be-339168757488 FetchInventory2 ce614657-a331-4c2e-9ddf-789ae647a3bc from 92.237.199.112:60343 took 11078ms

-----------------------------------------------
Crash on sim shutdown when any non-zero value (even 1) shows in inventory.httpfetch.QueuedFetchInventoryRequests.

2015-05-07 09:17:28,234 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-4bf62e1\OpenSim\Framework\WebUtil.cs:line 1087
   at OpenSim.Services.Connectors.XInventoryServicesConnector.MakeRequest(String method, Dictionary`2 sendData) in k:\OSGRID\opensim-4bf62e1\OpenSim\Services\Connectors\Inventory\XInventoryServicesConnector.cs:line 534
   at OpenSim.Services.Connectors.XInventoryServicesConnector.GetItem(InventoryItemBase item) in k:\OSGRID\opensim-4bf62e1\OpenSim\Services\Connectors\Inventory\XInventoryServicesConnector.cs:line 431
2015-05-07 09:17:28,374 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-4bf62e1\OpenSim\Region\ClientStack\Linden\Caps\WebFetchInvDescModule.cs:line 448
   at OpenSim.Region.ClientStack.Linden.WebFetchInvDescModule.DoInventoryRequests() in k:\OSGRID\opensim-4bf62e1\OpenSim\Region\ClientStack\Linden\Caps\WebFetchInvDescModule.cs:line 432
   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

(0028267)
nebadon (administrator)
2015-05-07 06:59

after some more testing, it appears to me that this problem is isolated to Windows based simulators I was able to make my inventory take much longer 2-3 times longer to load on one and also experienced a spew of these kind of messages

09:49:35 - [LOGHTTP]: Slow SynchronousRestForms request 2241 POST to http://inventory.osgrid.org/xinventory [^] took 4375ms, 47ms writing, METHOD=GETFOLDERCONTENT&PRINCIPAL=7b2022f0-5f19-488c-b7e5-829d8f96b448&FOLDER=4b71f522-6dd6-4065-87be-130da087dedb
(0028268)
Diva (administrator)
2015-05-07 07:30

Ai: this log line:
   at OpenSim.Framework.SynchronousRestFormsRequester.MakeRequest(String verb, String requestUrl, String obj, Int32 timeoutsecs, IServiceAuth auth) in k:\OSGRID\opensim-4bf62e1\OpenSim\Framework\WebUtil.cs:line 1087

As of now, there is nothing on that line, 1087. Are you sure your simulator is on a recent version?
(0028269)
nebadon (administrator)
2015-05-07 07:42

the path shows a git hash which is master git > k:\OSGRID\opensim-4bf62e1 I believe he is running the OSgrid release from the downloads page.
(0028270)
aiaustin (developer)
2015-05-07 08:39
edited on: 2015-05-07 08:41

Yes. Its based on latest version r/25965

Download: OSgrid OpenSimulator 0.8.2.dev.4bf62e1 - [zip] [31.9mb] 05-06-2015 built from OpenSimulator git hash : 4bf62e11b6a99c024e3dfa42db7425ea790009ee : [r/25965]

I never see this issue on our own grids by the way... just on OSGrid addon regions.

(0028271)
aiaustin (developer)
2015-05-07 08:50
edited on: 2015-05-07 08:53

Diva, can you take a look at this comment #c26709 above related to a thought about the change from .net 3.5 to.net4 which was around the time we first observed this issue.

http://opensimulator.org/mantis/view.php?id=7054#c26709 [^]

and look at the few comments after that between Mata, me and others.

(0028276)
Diva (administrator)
2015-05-07 20:49
edited on: 2015-05-07 20:50

I committed a more drastic change that may address a bunch of these issues:

[20:40] <cia-opensim> opensim: diva * rc74cef0f4261 OpenSim (14 files in 11 dirs):
[20:40] <cia-opensim> Major change in the way inventory is downloaded: added a method throughout IIventoryService that fetches sets of folders at once. Also added folder id in the InventoryCollection data structure, so that we don't need to go to inventory server again just for that. This reduces the chatter between sims and inventory server by... a lot. On my tests, this reduces initial inventory download down to 30% of what it currently is.

In order for the benefits to show, this requires both simulator and inventory service update. If the inventory service isn't updated, things should be functional, but nothing much is expected to change -- so if inventory download was slow, it should continue to be slow, if it hangs, it should continue to hang. Once simulator AND inventory service are both updated, though, I expect some of you will experience considerably reduced download times after a viewer cache clear. It may also get rid of the hanging problem, although that's not guaranteed.

Please report on how things run. Thanks.

(Again, I'm not looking at inventory issues after HG TPs for the time being)

(0028277)
nebadon (administrator)
2015-05-07 20:59

OSgrid Robust has been updated, no new release yet, I can say that my inventory went from taking 225 seconds to load to 80 seconds to load thats 35% of the time it took before, huge improvement considering it was already fast for me.
(0028278)
aiaustin (developer)
2015-05-08 02:50
edited on: 2015-05-08 02:51

Openvue and AiLand grids updated to r/25970 (8-May-2015).

Vue regions (e.g. Vue-Port and OpenVCE) updated by local compile of r/25970 overlaid onto current OSGrid precompiled download (r/25965) which is a process I use when we want quick test feedback on dev master versions.

One minor thing... the new commit has introduced 9 new compile warnings on Windows.

(0028279)
danbanner (manager)
2015-05-08 03:32

New build for OSgrid https://twitter.com/osgrid/status/596623325943607296 [^]
(0028280)
aiaustin (developer)
2015-05-08 04:14
edited on: 2015-05-08 04:18

Trying several OSGrid avatar logins on add-on regions to OSGrid using r/25970 OSGrid precompiled release...

The inventory count this time did go up and complete on my tests to date. But I note that the inventory.httpfetch.QueuedFetchInventoryRequests has a number 2 that seems not to rise, but seems to stick at 2 right up to when the inventory is fully loaded, then that drops to 1 and then 0.

Region (root) # show stats inventory
inventory.http://inventory.osgrid.org.RequestsMade [^] : 413 requests, 4.4 requests/s, 4.14 requests/s
inventory.httpfetch.ProcessedFetchInventoryRequests : 15, 0/s, 0.17/s
inventory.httpfetch.QueuedFetchInventoryRequests : 2, 0.4/s, 0/s

But then I have observed this red error near the end of the inventory load process...

[INVENTORY]: Failed to process queued inventory request 2918d25d-1777-434d-84cf-1852fae04b3a for Ai Austin in Vue-Port. Exception System.NullReferenceException: Object reference not set to an instance of an object.
   at OpenSim.Capabilities.Handlers.FetchInvDescHandler.Fetch(List`1 fetchFolders) in k:\OSGRID\opensim-c74cef0\OpenSim\Capabilities\Handlers\FetchInventoryDescendents\FetchInvDescHandler.cs:line 601
   at OpenSim.Capabilities.Handlers.FetchInvDescHandler.FetchInventoryDescendentsRequest(String request, String path, String param, IOSHttpRequest httpRequest, IOSHttpResponse httpResponse) in k:\OSGRID\opensim-c74cef0\OpenSim\Capabilities\Handlers\FetchInventoryDescendents\FetchInvDescHandler.cs:line 117
   at OpenSim.Region.ClientStack.Linden.WebFetchInvDescModule.PollServiceInventoryEventArgs.Process(aPollRequest requestinfo) in k:\OSGRID\opensim-c74cef0\OpenSim\Region\ClientStack\Linden\Caps\WebFetchInvDescModule.cs:line 364
   at OpenSim.Region.ClientStack.Linden.WebFetchInvDescModule.WaitProcessQueuedInventoryRequest() in k:\OSGRID\opensim-c74cef0\OpenSim\Region\ClientStack\Linden\Caps\WebFetchInvDescModule.cs:line 448

(0028281)
aiaustin (developer)
2015-05-08 04:39
edited on: 2015-05-08 04:40

The [INVENTORY] Failed to process queued inventory request was not a one off, I am seeing more of these with alternative avatars.. and this is a type of message I have not observed until this most recent update...

12:28:56 - [INVENTORY]: Failed to process queued inventory request 26712334-e0f8-499f-826d-72afeb43f0af for Venus Resident in Vue-Port. Exception System.NullReferenceException: Object reference not set to an instance of an object.
   at OpenSim.Capabilities.Handlers.FetchInvDescHandler.Fetch(List`1 fetchFolders) in k:\OSGRID\opensim-c74cef0\OpenSim\Capabilities\Handlers\FetchInventoryDescendents\FetchInvDescHandler.cs:line 601
   at OpenSim.Capabilities.Handlers.FetchInvDescHandler.FetchInventoryDescendentsRequest(String request, String path, String param, IOSHttpRequest httpRequest, IOSHttpResponse httpResponse) in k:\OSGRID\opensim-c74cef0\OpenSim\Capabilities\
Handlers\FetchInventoryDescendents\FetchInvDescHandler.cs:line 117
   at OpenSim.Region.ClientStack.Linden.WebFetchInvDescModule.PollServiceInventoryEventArgs.Process(aPollRequest requestinfo) in k:\OSGRID\opensim-c74cef0\OpenSim\Region\ClientStack\Linden\Caps\WebFetchInvDescModule.cs:line 364
   at OpenSim.Region.ClientStack.Linden.WebFetchInvDescModule.WaitProcessQueuedInventoryRequest() in k:\OSGRID\opensim-c74cef0\OpenSim\Region\ClientStack\Linden\Caps\WebFetchInvDescModule.cs:line 448

I am not sure if this is related yet..... but just before the exception instance above I observed the console log warnings below... though as this is on OSGrid and with an infrequently used avatar, and we know that there was an issue with assets not being saved recently.. it may be a temporary problem that will go away. Noted here in case it is relevant though...

12:28:56 - [XINVENTORY SERVICES CONNECTOR]: Folder id does not match. Expected 04ab1ec4-33cf-be9c-8574-1ce10f423e78 got 6732fcd8-38f0-4e4e-857e-b2f8627de61f
12:28:56 - [XINVENTORY SERVICES CONNECTOR]: Folder id does not match. Expected 6732fcd8-38f0-4e4e-857e-b2f8627de61f got 977746b8-66c4-8cf2-2987-fa57cef98306

(0028282)
aiaustin (developer)
2015-05-08 05:05
edited on: 2015-05-08 05:35

I am seeing increased numbers of the [XINVENTORY SERVICES CONNECTOR]: Folder id does not match and [INVENTORY]: Failed to process queued inventory request with that same avatar. Even after resaving the current outfit, deleting the old outfit folder and emptying OSGrid trash via the web page. I tried that just in case it was the outfits folder that was the issue.

12:51:00 - [XINVENTORY SERVICES CONNECTOR]: Folder id does not match. Expected 9
5c8c93c-a31a-6d28-fa35-2e4d62eeecfa got 26aaf121-1e5c-2049-d68a-8642218e36c9
12:51:00 - [XINVENTORY SERVICES CONNECTOR]: Folder id does not match. Expected 0
4ab1ec4-33cf-be9c-8574-1ce10f423e78 got 95c8c93c-a31a-6d28-fa35-2e4d62eeecfa
12:51:00 - [XINVENTORY SERVICES CONNECTOR]: Folder id does not match. Expected 9
5c8c93c-a31a-6d28-fa35-2e4d62eeecfa got 26aaf121-1e5c-2049-d68a-8642218e36c9

12:51:00 - [INVENTORY]: Failed to process queued inventory request ea7f5331-2c32
-4ac6-8c9e-e93c567109ed for Venus Resident in Vue-Port. Exception System.NullRe
ferenceException: Object reference not set to an instance of an object.
   at OpenSim.Capabilities.Handlers.FetchInvDescHandler.Fetch(List`1 fetchFolder
s) in k:\OSGRID\opensim-c74cef0\OpenSim\Capabilities\Handlers\FetchInventoryDesc
endents\FetchInvDescHandler.cs:line 601
   at OpenSim.Capabilities.Handlers.FetchInvDescHandler.FetchInventoryDescendent
sRequest(String request, String path, String param, IOSHttpRequest httpRequest,
IOSHttpResponse httpResponse) in k:\OSGRID\opensim-c74cef0\OpenSim\Capabilities\
Handlers\FetchInventoryDescendents\FetchInvDescHandler.cs:line 117
   at OpenSim.Region.ClientStack.Linden.WebFetchInvDescModule.PollServiceInvento
ryEventArgs.Process(aPollRequest requestinfo) in k:\OSGRID\opensim-c74cef0\OpenS
im\Region\ClientStack\Linden\Caps\WebFetchInvDescModule.cs:line 364
   at OpenSim.Region.ClientStack.Linden.WebFetchInvDescModule.WaitProcessQueuedI
nventoryRequest() in k:\OSGRID\opensim-c74cef0\OpenSim\Region\ClientStack\Linden
\Caps\WebFetchInvDescModule.cs:line 448

12:51:07 - [INVENTORY]: Failed to process queued inventory request 71b47692-cdec
-4ec8-a73a-0a86b8ed603c for Venus Resident in Vue-Port. Exception System.NullRe
ferenceException: Object reference not set to an instance of an object.
   at OpenSim.Capabilities.Handlers.FetchInvDescHandler.Fetch(List`1 fetchFolder
s) in k:\OSGRID\opensim-c74cef0\OpenSim\Capabilities\Handlers\FetchInventoryDesc
endents\FetchInvDescHandler.cs:line 601
   at OpenSim.Capabilities.Handlers.FetchInvDescHandler.FetchInventoryDescendent
sRequest(String request, String path, String param, IOSHttpRequest httpRequest,
IOSHttpResponse httpResponse) in k:\OSGRID\opensim-c74cef0\OpenSim\Capabilities\
Handlers\FetchInventoryDescendents\FetchInvDescHandler.cs:line 117
   at OpenSim.Region.ClientStack.Linden.WebFetchInvDescModule.PollServiceInvento
ryEventArgs.Process(aPollRequest requestinfo) in k:\OSGRID\opensim-c74cef0\OpenS
im\Region\ClientStack\Linden\Caps\WebFetchInvDescModule.cs:line 364
   at OpenSim.Region.ClientStack.Linden.WebFetchInvDescModule.WaitProcessQueuedI
nventoryRequest() in k:\OSGRID\opensim-c74cef0\OpenSim\Region\ClientStack\Linden
\Caps\WebFetchInvDescModule.cs:line 448

12:51:17 - [LOGHTTP]: Slow SynchronousRestForms request 9083 POST to http://avat [^]
ar.osgrid.org/avatar took 13172ms, 125ms writing, VERSIONMIN=0&VERSIONMAX=0&METH
OD=setavatar&UserID=9bfbf57c-0606-48ea-bbfd-2e3df2e531e8&AvatarType=1&Serial=0&A
vatarHeight=1.654476&Wearable+0%3a0=9bada1ec-bf0a-4555-9f15-860874bae652%3a1513a
d77-ab03-9

12:51:17 - [LOGHTTP]: Slow SynchronousRestForms request 9106 POST to http://avat [^]
ar.osgrid.org/avatar took 5891ms, 235ms writing, VERSIONMIN=0&VERSIONMAX=0&METHO
D=setavatar&UserID=9bfbf57c-0606-48ea-bbfd-2e3df2e531e8&AvatarType=1&Serial=0&Av
atarHeight=1.654476&Wearable+0%3a0=9bada1ec-bf0a-4555-9f15-860874bae652%3a1513ad
77-ab03-9

I am seeing this on several different OSGrid avatars by the way, and even trying to replace obvious recent folders with new ones, purging the trash on the OSGrid web site and logging back in I continue to see these (new) errors.

It might be helpful if wherever that message is coming from could print out the name of the folder in question top allow an attempt at a tidy up if it relates to the time OSGrid assets were not being correctly saved.

(0028283)
Mata Hari (reporter)
2015-05-08 05:14
edited on: 2015-05-08 05:36

@AiAustin: any chance that perhaps these are fetch requests for inventory items lost with the OSG asset losses in the last month?

(0028284)
nebadon (administrator)
2015-05-08 05:27

Inventory and Assets are completely different things, Inventory will not have been effected by the asset problems, this process of downloading inventory never touches asset server.
(0028285)
Seth Nygard (reporter)
2015-05-08 05:29

Initial testing with OpenSim 0.8.2.0 Dev c74cef0f42 7-May-2015 r/25970 shows the following;

08:17:00 - [XINVENTORY SERVICES CONNECTOR]: Folder id does not match. Expected 5cb3cbad-caa5-1b96-89ac-8b6cbe62b492 got 61a29850-9f38-f64a-2db6-7b1d81dcadb3
08:17:00 - [XINVENTORY SERVICES CONNECTOR]: Folder id does not match. Expected 61a29850-9f38-f64a-2db6-7b1d81dcadb3 got 8afdcc60-923c-44ea-8a4b-685bded4a554
08:17:00 - [XINVENTORY SERVICES CONNECTOR]: Folder id does not match. Expected 8afdcc60-923c-44ea-8a4b-685bded4a554 got a02c0bd2-6135-4fcb-bb80-cd942f0fccd7
08:17:00 - [XINVENTORY SERVICES CONNECTOR]: Folder id does not match. Expected a02c0bd2-6135-4fcb-bb80-cd942f0fccd7 got a44ea6e2-b9b2-4cfd-8e73-5091406b4ba5
08:17:00 - [XINVENTORY SERVICES CONNECTOR]: Folder id does not match. Expected a44ea6e2-b9b2-4cfd-8e73-5091406b4ba5 got ab06bc2b-7bf1-43a6-ac7d-e2f0806a7a01
08:17:00 - [XINVENTORY SERVICES CONNECTOR]: Folder id does not match. Expected ab06bc2b-7bf1-43a6-ac7d-e2f0806a7a01 got bdf911ea-2869-4e43-972a-c77649f98e0f
08:17:00 - [XINVENTORY SERVICES CONNECTOR]: Folder id does not match. Expected bdf911ea-2869-4e43-972a-c77649f98e0f got be61ab53-2279-42d0-84ce-4a5a47bddb65
08:17:00 - [INVENTORY]: Failed to process queued inventory request 0e41a6d3-db56-4df5-92d4-5bf9c9c84269 for Seth Nygard in Plaza. Exception System.NullReferenceException: Object reference not set to an instance of an object
  at OpenSim.Capabilities.Handlers.FetchInvDescHandler.Fetch (System.Collections.Generic.List`1 fetchFolders) [0x000dd] in /opt/opensim/src/opensim/OpenSim/Capabilities/Handlers/FetchInventoryDescendents/FetchInvDescHandler.cs:597
  at OpenSim.Capabilities.Handlers.FetchInvDescHandler.FetchInventoryDescendentsRequest (System.String request, System.String path, System.String param, IOSHttpRequest httpRequest, IOSHttpResponse httpResponse) [0x00133] in /opt/opensim/src/opensim/OpenSim/Capabilities/Handlers/FetchInventoryDescendents/FetchInvDescHandler.cs:117
  at OpenSim.Region.ClientStack.Linden.WebFetchInvDescModule+PollServiceInventoryEventArgs.Process (OpenSim.Region.ClientStack.Linden.aPollRequest requestinfo) [0x00081] in /opt/opensim/src/opensim/OpenSim/Region/ClientStack/Linden/Caps/WebFetchInvDescModule.cs:364
  at OpenSim.Region.ClientStack.Linden.WebFetchInvDescModule.WaitProcessQueuedInventoryRequest () [0x00026] in /opt/opensim/src/opensim/OpenSim/Region/ClientStack/Linden/Caps/WebFetchInvDescModule.cs:448
08:17:06 - [AVFACTORY]: Received texture update for Seth Nygard e671db06-152a-4d4e-883e-79315f49420d
08:17:06 - [XBakes]: stored 5 textures for user e671db06-152a-4d4e-883e-79315f49420d

Region (root) # show stats inventory
inventory.http://apollo.refugegrid.com:8005.RequestsMade [^] : 659 requests, 0 requests/s, 11.46 requests/s
inventory.httpfetch.ProcessedFetchInventoryRequests : 62, 0/s, 1.08/s
inventory.httpfetch.QueuedFetchInventoryRequests : 0, 0/s, 0/s

Viewer, Firestorm-Betax64 4.7.1.45325, still shows Fetching 7549 items 10 minutes later even though it should be finished.
(0028286)
nebadon (administrator)
2015-05-08 05:32

Ai and Seth, this looks potentially like broken inventory to me, let's see what diva thinks though.
(0028287)
aiaustin (developer)
2015-05-08 05:39

Could be Neb.

Mata.. it specifically says its a folder, so that's where I was looking. Also normally we get the failed to rez message if its an item rather than a folder issue. The error messages though could indeed be linked as I am sometimes getting paired messages about the folder id does not match and the exception noted earlier...

13:38:02 - [XINVENTORY SERVICES CONNECTOR]: Folder id does not match. Expected 3
ec59f7b-c637-24b3-902c-ec1ac7e52364 got 95c8c93c-a31a-6d28-fa35-2e4d62eeecfa
13:38:02 - [INVENTORY]: Failed to process queued inventory request c0ced972-d753
-45a7-9be0-7305b9d10ee5 for Venus Resident in Vue-Port. Exception System.NullRe
ferenceException: Object reference not set to an instance of an object.
   at OpenSim.Capabilities.Handlers.FetchInvDescHandler.Fetch(List`1 fetchFolder
s) in k:\OSGRID\opensim-c74cef0\OpenSim\Capabilities\Handlers\FetchInventoryDesc
endents\FetchInvDescHandler.cs:line 601
   at OpenSim.Capabilities.Handlers.FetchInvDescHandler.FetchInventoryDescendent
sRequest(String request, String path, String param, IOSHttpRequest httpRequest,
IOSHttpResponse httpResponse) in k:\OSGRID\opensim-c74cef0\OpenSim\Capabilities\
Handlers\FetchInventoryDescendents\FetchInvDescHandler.cs:line 117
   at OpenSim.Region.ClientStack.Linden.WebFetchInvDescModule.PollServiceInvento
ryEventArgs.Process(aPollRequest requestinfo) in k:\OSGRID\opensim-c74cef0\OpenS
im\Region\ClientStack\Linden\Caps\WebFetchInvDescModule.cs:line 364
   at OpenSim.Region.ClientStack.Linden.WebFetchInvDescModule.WaitProcessQueuedI
nventoryRequest() in k:\OSGRID\opensim-c74cef0\OpenSim\Region\ClientStack\Linden
\Caps\WebFetchInvDescModule.cs:line 448
(0028288)
aiaustin (developer)
2015-05-08 06:30

The good news is that with 20 or more logins with 5 different avatars on OSGrid add on regions using r/25970 on one fast and one slower server here I have not had a single inventory fetch hang up. I will keep testing and provide what feedback I can.
(0028289)
Diva (administrator)
2015-05-08 06:36

Despite of these error messages and exceptions -- are you seeing any functional and operational issues with inventory?

a) Are there any folders missing?

b) How long does it take to download initially?
(0028290)
aiaustin (developer)
2015-05-08 06:51

I am not seeing any issue with the OSGrid inventories on my tests to date Diva, even with those folder error messages.

Its tricky to say what is happening in my environment for speed of inventory download, as I have had hung inventory on initial fetch almost every time for months now.. and I have several systems on most of which I have cleared caches due to the recent upgrade to Firestorm 4.7.1 which I am using for all tests I reported. I can't be sure which have been used for logins since the cache clear and which have not in my environment.

I think its best to let others comment on inventory fetch speed. I will just watch for any hint of an initial inventory fetch hang which has been the most serious problem for me (and Mata I think) for some months.
(0028291)
aiaustin (developer)
2015-05-08 06:52
edited on: 2015-05-08 06:54

On one test OSGrid avatar that did not have much inventory which was giving the folder error, I replaced EVERY user created folder (but not the built in ones with icons), and every outfit was resaved, and then I cleared the trash via the OSGrid web site as usual. But I still get the folder error.

(0028292)
Diva (administrator)
2015-05-08 06:58

[06:57] <cia-opensim> opensim: diva * ra68aab14fa7c OpenSim (2 files in 2 dirs):
[06:57] <cia-opensim> Additional debug message to help diagnose a warning message and exception related to previous commit.
[06:57] <cia-opensim> See http://opensimulator.org/mantis/view.php?id=7054#c28282 [^]

If you can please update your sim that shows these warning messages, and report back.
(0028293)
aiaustin (developer)
2015-05-08 07:23
edited on: 2015-05-08 07:24

Okay, using r/25971 on Vue regions on OSGrid now (e.g. Vue-Port).

I do not see the red errors exception now on the console.. is that what you expected?

The yellow "Folder id does not match" warnings are now in pairs with your extra debugging line.. but nothing appears after the :

15:20:20 - [XINVENTORY SERVICES CONNECTOR]: Folder id does not match. Expected 38e1bd64-3c43-f4b7-32d4-e0d15b7b8e96 got 723566c9-21ee-9bbf-6af9-2188faa410b3
15:20:20 - [XINVENTORY SERVICES CONNECTOR]:
15:20:20 - [XINVENTORY SERVICES CONNECTOR]: Folder id does not match. Expected 723566c9-21ee-9bbf-6af9-2188faa410b3 got e83edb62-ea93-8f55-29da-62f270fc354b
15:20:20 - [XINVENTORY SERVICES CONNECTOR]:
15:20:20 - [XINVENTORY SERVICES CONNECTOR]: Folder id does not match. Expected e83edb62-ea93-8f55-29da-62f270fc354b got f8515242-fb2a-4b3d-8659-c721bc212ec5
15:20:20 - [XINVENTORY SERVICES CONNECTOR]:

(0028294)
Diva (administrator)
2015-05-08 07:32

The exception should be gone but the error message is not what I expected...
(0028295)
Diva (administrator)
2015-05-08 07:48

Sorry, my previous commit was missing an important part of the debug message. Can you please pull and try again?

I cannot reproduce this on my test environment.

I can see that Firestorm behaves differently than Singularity at least wrt the OpenSim Library.
(0028296)
Seth Nygard (reporter)
2015-05-08 07:57
edited on: 2015-05-08 08:21

Viewer: Firestorm-Release x64 4.6.9.42974
OpenSim 0.8.2.0 Dev a68aab14fa 8-May-2015 r/25971

I can confirm that with the latest pacth the error is no longer thrown.

Using a test avi with an almost empty, stock inventory I see the following behaviour.


Login, not clearing cache, viewer shows 136 Items
Console reports warnings:
10:44:38 - [WEB FETCH INV DESC HANDLER]: Unable to fetch folder 00000000-0000-0000-0000-000000000000


Clear cache and relog, viewer shows 137 Items
Console reports warings:
10:48:38 - [XINVENTORY SERVICES CONNECTOR]: Folder id does not match. Expected 35259926-c3d9-433a-8746-c6c317720f43 got 00000000-0000-0000-0000-000000000000
10:48:38 - [XINVENTORY SERVICES CONNECTOR]:

inventoryfolders.folderID='35259926-c3d9-433a-8746-c6c317720f43' is the Scripts folder which does exist in both Viewer inventory and in the table


Re-log, not clearing cache, viewer shows 136 items
Console reports warnings:
10:51:43 - [WEB FETCH INV DESC HANDLER]: Unable to fetch folder 00000000-0000-0000-0000-000000000000


This change in behaviour with empty cache vs not seems to be repeatable on subsequent attempts.

(Edit to fix typo)

(0028297)
Seth Nygard (reporter)
2015-05-08 08:07

Viewer: Firestorm-Release x64 4.6.9.42974
OpenSim 0.8.2.0 Dev 3548e39f9a 8-May-2015 r/25972

Using the same test avi with an almost empty, stock inventory I see the following behaviour.


Login, not clearing cache, viewer shows 136 Items
Console reports warnings:
11:01:16 - [WEB FETCH INV DESC HANDLER]: Unable to fetch folder 00000000-0000-0000-0000-000000000000

Clear cache and relog, viewer stalls showing Fetching 137 Items
Console reports warnings:
11:03:45 - [XINVENTORY SERVICES CONNECTOR]: Folder id does not match. Expected 35259926-c3d9-433a-8746-c6c317720f43 got 00000000-0000-0000-0000-000000000000
11:03:45 - [XINVENTORY SERVICES CONNECTOR]: 35259926-c3d9-433a-8746-c6c317720f43,34e15d85-7430-4ce4-9890-61c8176e1018,35259926-c3d9-433a-8746-c6c317720f43,34e15d85-7430-4ce4-9890-61c8176e1018,00000000-0000-0000-0000-000000000000 F_35259926-c3d9-433a-8746-c6c317720f43,F_34e15d85-7430-4ce4-9890-61c8176e1018,F_00000000-0000-0000-0000-000000000000

show stats inventory
inventory.http://apollo.refugegrid.com:8005.RequestsMade [^] : 39 requests, 0 requests/s, 0 requests/s
inventory.httpfetch.ProcessedFetchInventoryRequests : 15, 0/s, 0/s
inventory.httpfetch.QueuedFetchInventoryRequests : 0, 0/s, 0/s


Relog, not clearing cache, viewer shows 136 Items
Console repors warning:
11:06:29 - [WEB FETCH INV DESC HANDLER]: Unable to fetch folder 00000000-0000-0000-0000-000000000000
(0028298)
Diva (administrator)
2015-05-08 08:11

Great! This is just what I needed.
(0028299)
Diva (administrator)
2015-05-08 08:38

[08:37] <cia-opensim> opensim: diva * r3110b1661f04 OpenSim/Capabilities/Handlers/FetchInventoryDescendents (FetchInvDescHandler.cs):
[08:37] <cia-opensim> Apparently Firestorm sometimes sends duplicate folder ids on the same request (see http://opensimulator.org/mantis/view.php?id=7054#c28297 [^]). This was throwing the new inventory download code off.
[08:37] <cia-opensim> Firestorm also sends requests for folder UUID.Zero, which doesn't exist, but doesn't cause any problems either -- it just fails. I'm leaving the warning message for now, just to keep an eye on which folders can't be found, but may remove it in the future.
(0028301)
Seth Nygard (reporter)
2015-05-08 09:06

Viewer: Firestorm-Release x64 4.6.9.42974
OpenSim 0.8.2.0 Dev 3110b1661f 8-May-2015 r/25973

Using the same test avi with an almost empty, stock inventory I see the following behavior.


Login, not clearing cache, viewer shows 136 items
Console reports warning:
11:54:18 - [WEB FETCH INV DESC HANDLER]: Unable to fetch folder 00000000-0000-0000-0000-000000000000

Clear cache and relog, viewer show 137 items
Console reports warning:
11:56:32 - [WEB FETCH INV DESC HANDLER]: Unable to fetch folder 00000000-0000-0000-0000-000000000000

Relog, not clearing cache, viewer show 136 items
Console reports warning:
12:00:10 - [WEB FETCH INV DESC HANDLER]: Unable to fetch folder 00000000-0000-0000-0000-000000000000

Clear cache and relog, viewer show Fetching 137 Items
Console reports warning:
12:02:21 - [WEB FETCH INV DESC HANDLER]: Unable to fetch folder 00000000-0000-0000-0000-000000000000


It is somewhat concerning that there is a discrepancy with the number of inventory items between an empty cache and not. I am not seeing any way to reconcile what the difference may be.

It is however more concerning that I am still seeing the viewer stall and show Fetching ...
(0028302)
Diva (administrator)
2015-05-08 09:08

Is there anything missing?
(0028303)
Seth Nygard (reporter)
2015-05-08 09:19

Viewer: Firestorm-Release x64 4.6.9.42974
OpenSim 0.8.2.0 Dev 3110b1661f 8-May-2015 r/25973

Login with my main test avi, Viewer shows Fetching 7548 Items

show stats inventory
inventory.http://apollo.refugegrid.com:8005.RequestsMade [^] : 601 requests, 0 requests/s, 0 requests/s
inventory.httpfetch.ProcessedFetchInventoryRequests : 133, 0/s, 0/s
inventory.httpfetch.QueuedFetchInventoryRequests : 0, 0/s, 0/s


Relog, changing nothing, viewer again shows Fetching 7548 Items

show stats inventory
inventory.http://apollo.refugegrid.com:8005.RequestsMade [^] : 957 requests, 0 requests/s, 0 requests/s
inventory.httpfetch.ProcessedFetchInventoryRequests : 143, 0/s, 0/s
inventory.httpfetch.QueuedFetchInventoryRequests : 0, 0/s, 0/s


Relog, changing nothing, viewer again shows Fetching 7548 Items

show stats inventory
inventory.http://apollo.refugegrid.com:8005.RequestsMade [^] : 1313 requests, 0 requests/s, 0.1 requests/s
inventory.httpfetch.ProcessedFetchInventoryRequests : 153, 0/s, 0/s
inventory.httpfetch.QueuedFetchInventoryRequests : 0, 0/s, 0/s


Each time I saw one warning "Unable to fetch folder 00000000-0000-0000-0000-000000000000" but I think those can be ignored now.


The viewer still continues to show Fetching ... after waiting for a while, so I do not think these changes have entirely resolved that issue.
(0028304)
Seth Nygard (reporter)
2015-05-08 09:21

@Diva sadly simply looking at things and trying to use my memory does not do a great diff compare. That is what I rely on the tools for.

I don't see anything that jumps out so far however.
(0028305)
Diva (administrator)
2015-05-08 09:21

No, I think the reason why Firestorm shows "Fetching" is because of the 000 folder, which does't exist. I don't know why FS asks for that folder. Let me tell it to stop looking for that folder, and see if that solves the issue with FS.
(0028306)
Diva (administrator)
2015-05-08 09:38

If you still have access to a sim that is running yesterday's code (before my important commit last night) could you please login with that simple avatar on that sim and check whether FS also thinks inventory fetching is not finished after 136 items?

I'm starting to suspect that this issue has both a server-side and client-side part. Maybe the protocol has changed.
(0028307)
Mata Hari (reporter)
2015-05-08 09:52
edited on: 2015-05-08 09:53

@Diva

The very long/perma-*display* of "fetching..." seems to have been introduced with FS 4.6.9 (the just-released version) and does happen under Opensim versions prior to your commits of the last 24 hours. Under 4.6.8 it could occasionally do this as well but could be reliably cleared by right-clicking the trash folder and emptying it (even if it was already empty). That trick no longer works with 4.6.9 but it seems that it can usually now be cleared by expanding and collapsing it a few times. The previous experience makes me wonder whether the trash folder be tied into this in some way?

(0028309)
Diva (administrator)
2015-05-08 10:02

Well, I think it's the Zero folder that is causing all these issues. In the previous incarnation of the protocol, the server was supposed to send a "bad_folders" part in the response, but I don't see that documented anywhere anymore:
http://wiki.secondlife.com/wiki/Linden_Lab_Official:Inventory_API#Fetch_inventory_descendents [^]

I don't know where the Zero folder comes from, it doesn't happen in Singu with the same avie. Somehow FS is making that folder up, and the bad_folder response is being ignored. Let me see if I can make it understand that that's a bad folder.
(0028310)
Seth Nygard (reporter)
2015-05-08 10:10

I will repeat the test using that same (small inventory) avi on my test grid. I will revert it back to the code I was running previously and will report my findings. This will however not happen until later today.
(0028311)
Seth Nygard (reporter)
2015-05-08 10:59

Viewer: Firestorm-Release x64 4.6.9.42974
OpenSim 0.8.2.0 Dev da32512ea4 29-Apr-2015 r/25945

Using test avi with very small inventory, after reverting test grid and sim to previously running version of OpenSim

Login with previous cache, viewer shows 136 Items
Console shows no warnings or errors

Clear cache and relog, viewer shows Fetching 137 Items
Console shows no warnings or errors

show stats inventory
inventory.http://apollo.refugegrid.com:8005.RequestsMade [^] : 110 requests, 0 requests/s, 1.58 requests/s
inventory.httpfetch.ProcessedFetchInventoryRequests : 15, 0/s, 0.21/s
inventory.httpfetch.QueuedFetchInventoryRequests : 0, 0/s, 0/s

Relog, keeping cache, viewer shows 137 Items
Console shows no warnings or errors

Relog again, keeping cache, viewer shows 137 Items
Console shows no warnings or errors

Relog again, keeping cache, viewer shows 137 Items
Console shows no warnings or errors

Clear cache and relog, viewer shows Fetching 137 Items
Console shows no warnings or errors

show stats inventory
inventory.http://apollo.refugegrid.com:8005.RequestsMade [^] : 246 requests, 0 requests/s, 0 requests/s
inventory.httpfetch.ProcessedFetchInventoryRequests : 43, 0/s, 0/s
inventory.httpfetch.QueuedFetchInventoryRequests : 0, 0/s, 0/s

Relog again, keeping cache, viewer shows 137 Items
Console shows no warnings or errors


As can be seen from my tests, the viewer still stalled showing Fetching 1 out of 7 times

I see no discrepancy with the viewer reported Inventory count between clear cache and not when using the previous builds.
The count difference is only observed with the new patch.
(0028312)
Diva (administrator)
2015-05-08 11:06

So the eternal "Fetching..." with Firestorm is a common problem independent of these latest developments and independent of inventory size? If so, let's move that to a different mantis.

This mantis focuses on the real stall of inventory fetching that happened on large inventories. I hope that was a real problem, and not just a Firestorm problem...
(0028313)
Seth Nygard (reporter)
2015-05-08 11:11
edited on: 2015-05-08 11:38

@Diva The inventory fetch stalling and causing excessive HTTP traffic was indeed a valid issue and not purely viewer related. It was originally found by Mata and subsequently verified by others, and with other viewers. Firestorm may be a bit more likley to trigger it, but it is certainly not the only one to do so.

I am concerned that with the previous build my viewer reports 137 items regardless if the Fetching shows as stuck or not. The only time it showed 136 was the first start after running the new inventory patches. This leads me to believe there is indeed 1 item missing with the new inventory patches.

(0028314)
aiaustin (developer)
2015-05-08 11:16

Remember OSGrid does not allow the trash folder to be cleared in the viewer. It shows it as cleared in the viewer, but the contents come back on the next login. OSGrid trash can only be cleared via the web site.

I stress again that I have only ever seen these issues on OSGrid addon regions.
(0028315)
aiaustin (developer)
2015-05-08 11:18
edited on: 2015-05-08 11:44

Mata. Firestorm 4.6.9 has been out for many months. 4.7.1 is latest release from last week. Can you clarify what you meant in http://opensimulator.org/mantis/view.php?id=7054#c28307 [^] ?

(0028316)
Diva (administrator)
2015-05-08 12:10

Seth, please open a different mantis for 136 vs 137.
Also, as you report it, make sure that you know *exactly* how many items your inventory has. This could be done, for example, by creating a new account and counting the number of items there, verifying that number on a sim that's running a version before yesterday's. If something is missing today, it shouldn't be too hard to find what's missing in a collection of 137 items.

Again, when it comes to this mantis, all that matters is the real inventory download stall -- when you have 10K+ items and the download stalls way before that.

Everything else -- please move to different maintises (mantii?).
(0028317)
aiaustin (developer)
2015-05-08 12:17

Anyone have direct contact with Jessica Lyon and the Firestorm viewer folks to ask about where it gets the null UUID folders from and why its asking for them?

If not we can maybe try to compose a sensible and helpful Firestorm JIRA issue to raise this?
(0028318)
Diva (administrator)
2015-05-08 12:22

Also, one important aspect of this mantis is the time that it takes to download large inventories. I would like to hear reports about that, especially numbers comparing before and after this patch. Thanks.

So, within scope of this mantis:

- Real stall in large inventories. Is this fixed?
- Time it takes to download large inventories. Is it shorter now? How much shorter?

Everything else -- other mantis please.
(0028319)
Seth Nygard (reporter)
2015-05-08 12:43

@Diva the count discrepancy is/was directly related to findings regarding testing of the recent inventory patches, which are hopefully a resolution to the reported bug. The fact that a side effect may have been found is still IMHO applicable to this issue as it appears to be due to the patch.

When I can do more testing and have any other information that may change things I will then open a new Mantis specific to whatever new issue(s) are found.

We need a way to better and proper way to link issues findings as they related specific patch releases. Simply adding a reference to other related Mantis bug issues is not sufficient to keep things managed.
(0028320)
aiaustin (developer)
2015-05-08 12:44
edited on: 2015-05-08 12:55

I am doing a few logins with 5 different test OSGrid avatars from home to one OSGrid addon region Windows 8.1 server at the University of Edinburgh that is running r/25973. The avatars only have a few hundred to a few thousand inventory items.

In each case the inventory fetch completed, which is great news. Previously it would fail 2 out of 3 times (sometimes every time).

But the fetch for all avatars as shows in the inventory recent tool in Firestorm 4.7.1 did several times stop counting up for several minutes while the server show stats inventory showed the requested going up several hundred requests with no effect on the viewer shown count.

I did notice the odd "2" in QueuedFetchInventoryRequests I have noticed all the time when doing the show stats inventory all the time the inventory was incoming.

inventory.httpfetch.QueuedFetchInventoryRequests : 2, 0/s, 0/s

Region (root) # show stats inventory
inventory.http://inventory.osgrid.org.RequestsMade [^] : 581 requests, 4 requests/s, 3.76 requests/s
inventory.httpfetch.ProcessedFetchInventoryRequests : 16, 0/s, 0.09/s
inventory.httpfetch.QueuedFetchInventoryRequests : 2, 0/s, 0/s

The queued count does fall to 0 when the inventory fetch completes.

The processed requested sticks (e.g. at 50) at that point as the request rises, and the queued stays as 2. I deleted a lot of intermediate ones in the sample below here... but they all had processed as 50 and queued as 2.

Region (root) # show stats inventory
inventory.http://inventory.osgrid.org.RequestsMade [^] : 1709 requests, 4.4 requests/s, 3.9 requests/s
inventory.httpfetch.ProcessedFetchInventoryRequests : 50, 0/s, 0.19/s
inventory.httpfetch.QueuedFetchInventoryRequests : 2, 0/s, 0/s
...
Region (root) # show stats inventory
inventory.http://inventory.osgrid.org.RequestsMade [^] : 1759 requests, 4 requests/s, 3.88 requests/s
inventory.httpfetch.ProcessedFetchInventoryRequests : 50, 0/s, 0.19/s
inventory.httpfetch.QueuedFetchInventoryRequests : 2, 0/s, 0/s
...
Region (root) # show stats inventory
inventory.http://inventory.osgrid.org.RequestsMade [^] : 1778 requests, 4.4 requests/s, 3.88 requests/s
inventory.httpfetch.ProcessedFetchInventoryRequests : 50, 0/s, 0.19/s
inventory.httpfetch.QueuedFetchInventoryRequests : 2, 0/s, 0/s

The fetch starts to count up again in the viewer when this "temporary jam" changes... e.g.

Region (root) # show stats inventory
inventory.http://inventory.osgrid.org.RequestsMade [^] : 2153 requests, 0 requests/s, 0 requests/s
inventory.httpfetch.ProcessedFetchInventoryRequests : 79, 0/s, 0/s
inventory.httpfetch.QueuedFetchInventoryRequests : 0, 0/s, 0/s
Region (root) #

(0028321)
Diva (administrator)
2015-05-08 12:58

@Ai: please check if you have this in your logs:

[FETCH INVENTORY DESCENDENTS2 MODULE]: Caught in the act of loosing responses! Please report this on mantis 0007054
(0028322)
aiaustin (developer)
2015-05-08 13:03
edited on: 2015-05-08 13:19

I did not see this on the server console while doing any tests in the last hour @Diva... and I just looked at OpenSim.log on the server side and this line or any like it does not appear in all running with r/25973 in the OSGrid addon region server in the last few hours and while doing the tests where the incoming inventory sticks for a while several times. Bit n dpite of that, things are better than befire, as in all my tests the initial inventiry fetch when loggn on to the OSGrid addon region does eventually complete in all cases.

(0028323)
Mata Hari (reporter)
2015-05-08 14:11

@AI: senior's moment....I meant to refer to the 4.7.1 patch as being the new one with the issue where "fetching...." appears to have trouble clearing itself even when inventory is fully fetched and where expand/collapse a few times will usually clear it.

The previous version (4.6.9) would often show "fetching..." forever for me until I emptied trash, even if trash was empty and inventory had been fully fetched.
(0028324)
Seth Nygard (reporter)
2015-05-08 14:55

At the risk of adding another comment, I can confirm that I am seeing the same inventory count discrepancy with a newly created account and the current Singularity viewer. This only happens with the new inventory patch and not the older build. The new build consistently has a count 1 higher with an empty cache as it does on subsequent relogs with the cache intact.

This however makes me VERY reluctant to deploy the new inventory patches on the main gird where it could be tested on a more widespread basis and with larger inventories.

This leaves me in a deadlock when it comes to more testing/validation of the new fix and large inventories and how it relates to the original issue.
(0028325)
Diva (administrator)
2015-05-08 15:42

@Ai, @Mata: How many "link" items do your inventories have? I'm not just talking about appearance links, there may be others.
(0028326)
Mata Hari (reporter)
2015-05-08 16:25

@Diva:

Other than appearance/outfit links I have a number of different AO set-ups for various applications so those alone are 8 different main #AO folders plus their many associated subfolders that contain probably in the range of 300-400 links (total).
(0028327)
Diva (administrator)
2015-05-08 16:26

yep, Nebadon and I just confirmed (by reproduction) that links are the main cause of your partial (previously total) hanging. Fix coming soon.
(0028328)
wbalazic (reporter)
2015-05-08 17:03
edited on: 2015-05-08 17:04

Just because I'm the overly curious type. Why does the GITLOG say this is a Firestorm problem, when Seth is saying that he sees the same issue with Singularity above? And incidentally, I have the same issue (and have for quite a while) on Firestorm, Singularity, and Cool Viewer. I have not tested Kokua.

(0028329)
Mata Hari (reporter)
2015-05-08 18:12

Yes...while I use Firestorm for the most part, I had identical complete hangs when I tested it with all major TPVs. I use FS because it has the feature set that's the most useful to me, so when all of them failed I stuck with it rather than switching. Had there been a fully functional alternative I wouldn't have.
(0028330)
Nicky Perian (reporter)
2015-05-08 19:07

This long or seemly stuck inventory processing has come up in SL's Third Party Developers meeting several times. While not an answer, the folks at Linden explain that the server algorithm uses and expects recursive inventory folder processing and when there is no or little folder levels ( a large flat inventory structure) with no recursion in play it seems to cause inventory hanging. The recommendation for those with the problem is to add folder structure to the inventory. Could this be an issue with OS where this issue does not happen to all users?
(0028331)
Diva (administrator)
2015-05-08 21:33

[20:54] <cia-opensim> opensim: diva * r0bf1209f908b OpenSim (10 files in 8 dirs):
[20:54] <cia-opensim> Another major overhaul of inventory downloading, this time pertaining to inventory links. Added yet another function to IInventoryService to get multiple items at once, so that fetching collections of linked items is done once per folder instead of once per item.

@Ai, I think osgrid is updated. Please try now and report back. Thanks.
(0028332)
nebadon (administrator)
2015-05-08 21:54

OSgrid is updated and a new release has been posted > https://twitter.com/osgrid/status/596897026366771200 [^]
(0028337)
aiaustin (developer)
2015-05-09 01:44
edited on: 2015-05-09 01:45

Will test soon and report back later today.

I can note that my folders are very heavily hierarchical.. perhaps 3 deep commonly and more in places. I don't have large flat structures on the test avatars I have been using. I do have links though as I use outfits heavily. The inventory fetch hangs and lockups occured on even small inventories like 400 items in total.

(0028339)
aiaustin (developer)
2015-05-09 08:48
edited on: 2015-05-09 09:26

I am testing r/25975 via OSGrid addon region precompiled version. There seems to be something badly wrong.

Inventory load may be blocking the rezzing of all contents on the region until the inventory load completes. At least that what it looks like after testing with 3 or 4 test avatars on same region. On each login the contents on the region do not load until inventory load is (almost?) complete... avatar rezzs and each of its HUDs show and THEN the prims and content on the regions start to load.... ditto for a relog back in on same region for an avatar just used. Each time the region was empty of all prims until the inventory load completed I think. Only terrain and sea was in place. Note I could hear sounds played by a script in a prim long before the prims on the region showed up.

I also had no attachments (hair, clothing or HUDs) on a test avatar, but I could not repeat that.

Avatar fetch seems to get near the end - when it still says "Fetching" but does not increase afterwards... then the region contents rezz... and the inventory recent tab continues to say "Fetching" in the recent tab for several minutes before completing.

(0028342)
nebadon (administrator)
2015-05-09 09:17
edited on: 2015-05-09 09:17

Ai what do you have set for InterestManagement in OpenSim.ini ie:

[InterestManagement]
     UpdatePrioritizationScheme = FrontBack

(0028343)
aiaustin (developer)
2015-05-09 09:23
edited on: 2015-05-09 09:29

Exactly that...

[InterestManagement]
      ;; ... comments...
      UpdatePrioritizationScheme = FrontBack
 

unchanged and its been like that for some time Neb. This is a change in behaviour as far as I can see. I even tried it with a VERY short view range of less than 128m and its only a simple pimple island with a few simple items on it and no mesh. Previously it aperared essentially instantly and even as the avatar was rezzing... now only the terrain and sea appear and its completely empty until the inventory stall occurs, the the objects rezz and some minutes later the inventory shows its completed its initial fetch without counting up any further.

I am using Firestorm 4.7.1 and did not have this issue until today's tests I think. It does not even seem to be using a cache as the region is empty on relog on same viewer without any cache clearing and logging in with the very same avatar a minute later.

(0028344)
nebadon (administrator)
2015-05-09 09:24

ok I don't understand why you see things differently than I do, that is the setting I use as well and I did not have this problem.
(0028345)
aiaustin (developer)
2015-05-09 10:06

I restored r/25973 and that had the same issue. But when I went back to r/25970 that works as before. the region almost instantly rezzed and then the avatar appears as usual. It looks like the problem with the region contents showing issue occurred AFTER r/25970.

I am using the same OpenSim.ini settings and Firestorm 4.7.1 OS in all tests.
(0028346)
nebadon (administrator)
2015-05-09 10:15

Ai I am completely unable to recreate this, I suggest that a new Mantis be opened specific to this issue, this mantis should be set to resolved, it has gone on for far too long, and while this new problem is possibly a result of this fix, it should be considered a new bug.
(0028348)
aiaustin (developer)
2015-05-09 10:24

Could be... I am no longer sure that r/25970 does not have the issue either. It does need more testing and feedback from others. I am travelling a few days so I will catch up with state of play on my return.
(0028349)
Diva (administrator)
2015-05-09 10:24

FYI I will close this tab on my browser never to return.

Anyone having anything useful to add to the issue related to inventory download being stuck and taking a long time, please see new mantis 0007564. That mantis will be closely monitored for posts being in scope of the issue. I will delete all posts that are out of scope. For general chat, you can all continue to chat here. Without me.
(0028359)
aiaustin (developer)
2015-05-10 10:30

The core issue here appears to be resolved by chnges made by @Diva by r/25975 on 8-May-2015. Best to close this issue so people can now report any separate issues elsewhere.

- Issue History
Date Modified Username Field Change
2014-03-11 12:55 Mata Hari New Issue
2014-03-13 08:47 Mata Hari Note Added: 0025438
2014-03-18 18:04 justincc Note Added: 0025469
2014-03-18 18:04 justincc Assigned To => justincc
2014-03-18 18:04 justincc Status new => feedback
2014-03-18 18:05 justincc Note Edited: 0025469 View Revisions
2014-03-19 07:26 Mata Hari File Added: Mata_stats.txt
2014-03-19 07:28 Mata Hari Note Added: 0025479
2014-03-19 07:28 Mata Hari Status feedback => assigned
2014-03-20 19:12 justincc Note Added: 0025507
2014-03-20 19:13 justincc Note Added: 0025508
2014-03-21 05:45 Mata Hari Note Added: 0025512
2014-03-21 05:45 Mata Hari File Added: Mata_stats_test2.txt
2014-04-16 01:21 aiaustin Relationship added related to 0007110
2014-04-16 01:40 aiaustin Note Added: 0025791
2014-04-16 01:42 aiaustin File Added: virtual1-aa-before-login.txt
2014-04-16 01:42 aiaustin File Added: virtual1-aa-during-cloud-inv-at-64-a.txt
2014-04-16 01:42 aiaustin File Added: virtual1-aa-during-cloud-inv-at-64-b.txt
2014-04-16 01:43 aiaustin Note Edited: 0025791 View Revisions
2014-04-16 01:44 aiaustin File Added: virtual1-aa-during-cloud-inv-at-64-c.txt
2014-04-16 01:46 aiaustin Note Edited: 0025791 View Revisions
2014-04-16 02:10 aiaustin Note Edited: 0025791 View Revisions
2014-04-16 02:11 aiaustin Note Edited: 0025791 View Revisions
2014-04-16 02:16 aiaustin Note Edited: 0025791 View Revisions
2014-04-16 08:01 aiaustin Note Edited: 0025791 View Revisions
2014-04-16 12:25 aiaustin Note Added: 0025797
2014-04-16 12:26 aiaustin Note Edited: 0025797 View Revisions
2014-04-25 06:05 aiaustin Note Added: 0025895
2014-04-25 06:06 aiaustin Note Edited: 0025895 View Revisions
2014-04-26 09:11 aiaustin Note Added: 0025910
2014-04-26 10:18 Mata Hari Note Added: 0025913
2014-04-29 03:40 aiaustin Note Added: 0025924
2014-04-30 02:55 aiaustin Note Added: 0025934
2014-04-30 02:58 aiaustin Note Edited: 0025934 View Revisions
2014-04-30 04:49 aiaustin Note Added: 0025936
2014-04-30 04:50 aiaustin Note Edited: 0025936 View Revisions
2014-04-30 04:51 aiaustin Note Edited: 0025936 View Revisions
2014-04-30 04:54 aiaustin Note Edited: 0025936 View Revisions
2014-04-30 04:56 aiaustin Note Edited: 0025936 View Revisions
2014-05-01 04:11 aiaustin Note Added: 0025943
2014-05-01 04:12 aiaustin Note Edited: 0025943 View Revisions
2014-05-08 10:27 aiaustin Note Added: 0025989
2014-05-08 10:28 aiaustin Note Added: 0025990
2014-05-08 11:58 aiaustin Note Deleted: 0025989
2014-06-19 03:27 aiaustin Note Added: 0026307
2014-06-19 06:34 Mata Hari Note Added: 0026308
2014-07-20 06:08 Mata Hari Note Added: 0026516
2014-07-20 06:09 Mata Hari File Added: OpenSim-inventoryfetchhang20140719.log
2014-07-20 07:54 Mata Hari Note Added: 0026517
2014-07-20 08:50 Ken Grunke Note Added: 0026518
2014-07-20 09:48 aiaustin Note Added: 0026519
2014-07-20 09:49 aiaustin Note Edited: 0026519 View Revisions
2014-07-20 10:01 aiaustin Note Added: 0026521
2014-07-20 10:02 aiaustin Note Edited: 0026521 View Revisions
2014-07-21 01:32 aiaustin Note Added: 0026527
2014-07-21 01:35 aiaustin Note Edited: 0026527 View Revisions
2014-07-22 05:02 Mata Hari Note Added: 0026546
2014-07-22 06:04 aiaustin Note Added: 0026549
2014-07-22 06:04 aiaustin Note Edited: 0026549 View Revisions
2014-07-22 06:09 aiaustin Note Edited: 0026549 View Revisions
2014-07-22 06:09 aiaustin Note Edited: 0026549 View Revisions
2014-07-22 06:10 aiaustin Note Edited: 0026549 View Revisions
2014-07-25 07:37 aiaustin Note Added: 0026584
2014-07-25 07:37 aiaustin Note Edited: 0026584 View Revisions
2014-07-25 07:38 aiaustin Note Edited: 0026584 View Revisions
2014-07-25 16:07 Mata Hari Note Added: 0026589
2014-07-25 16:10 justincc Note Added: 0026590
2014-07-25 18:31 justincc Note Added: 0026591
2014-07-26 03:19 aiaustin Note Added: 0026593
2014-07-26 03:21 aiaustin Note Edited: 0026593 View Revisions
2014-07-26 03:25 aiaustin Note Added: 0026594
2014-07-26 03:25 aiaustin Note Edited: 0026594 View Revisions
2014-07-26 03:27 aiaustin Note Edited: 0026594 View Revisions
2014-07-26 03:28 aiaustin Note Edited: 0026594 View Revisions
2014-07-26 03:30 aiaustin Note Edited: 0026593 View Revisions
2014-07-26 03:33 aiaustin Note Edited: 0026593 View Revisions
2014-07-26 04:26 aiaustin Note Added: 0026595
2014-07-26 04:45 Mata Hari Note Added: 0026604
2014-07-26 05:35 Mata Hari Note Added: 0026610
2014-07-26 05:47 Mata Hari Note Added: 0026611
2014-07-26 05:48 Mata Hari Note Edited: 0026611 View Revisions
2014-07-26 05:49 Mata Hari Note Edited: 0026611 View Revisions
2014-07-26 05:55 aiaustin Note Added: 0026612
2014-07-26 05:59 aiaustin Note Edited: 0026612 View Revisions
2014-07-26 05:59 Mata Hari Note Added: 0026613
2014-07-26 06:01 Mata Hari Note Edited: 0026613 View Revisions
2014-07-26 06:02 aiaustin Note Added: 0026614
2014-07-26 06:07 aiaustin Note Added: 0026615
2014-07-26 06:09 aiaustin Note Edited: 0026612 View Revisions
2014-07-26 06:11 aiaustin Note Edited: 0026615 View Revisions
2014-07-26 06:13 aiaustin Note Edited: 0026612 View Revisions
2014-07-26 08:32 aiaustin Note Edited: 0026612 View Revisions
2014-07-26 08:35 aiaustin Note Edited: 0026612 View Revisions
2014-07-27 05:36 aiaustin Note Added: 0026620
2014-07-27 05:42 aiaustin Note Edited: 0026620 View Revisions
2014-07-27 05:47 aiaustin Note Edited: 0026620 View Revisions
2014-07-27 05:56 aiaustin Note Added: 0026621
2014-07-27 06:08 Mata Hari Note Added: 0026622
2014-07-28 01:53 aiaustin Note Added: 0026624
2014-07-28 01:55 aiaustin Note Edited: 0026624 View Revisions
2014-07-28 01:56 aiaustin Note Edited: 0026621 View Revisions
2014-07-30 12:55 aiaustin Note Added: 0026644
2014-07-30 12:58 aiaustin Note Edited: 0026644 View Revisions
2014-07-30 12:58 aiaustin Note Edited: 0026644 View Revisions
2014-07-30 13:00 aiaustin Note Edited: 0026644 View Revisions
2014-07-30 13:01 aiaustin Note Edited: 0026644 View Revisions
2014-07-30 14:01 aiaustin Note Edited: 0026624 View Revisions
2014-07-31 02:25 aiaustin Note Added: 0026645
2014-07-31 06:37 aiaustin Note Added: 0026646
2014-07-31 06:38 aiaustin Note Edited: 0026646 View Revisions
2014-07-31 06:40 aiaustin Note Edited: 0026646 View Revisions
2014-07-31 06:43 aiaustin Note Edited: 0026646 View Revisions
2014-07-31 06:46 aiaustin Note Edited: 0026646 View Revisions
2014-07-31 06:47 aiaustin Note Edited: 0026646 View Revisions
2014-07-31 07:15 aiaustin Note Added: 0026647
2014-07-31 07:15 aiaustin Note Edited: 0026647 View Revisions
2014-07-31 07:16 aiaustin Note Edited: 0026647 View Revisions
2014-07-31 07:17 aiaustin Note Edited: 0026647 View Revisions
2014-08-08 12:30 justincc Note Added: 0026677
2014-08-08 12:31 justincc Note Edited: 0026677 View Revisions
2014-08-08 12:55 aiaustin Note Added: 0026678
2014-08-08 12:55 Mata Hari Note Added: 0026679
2014-08-08 12:56 aiaustin File Added: 2014-08-08-OSGrid-Openvue-OpenSim-Debug-Http-Out-4.log
2014-08-08 13:04 aiaustin Note Edited: 0026678 View Revisions
2014-08-08 13:05 aiaustin File Added: 2014-08-08-OSGrid-Openvue-OpenSim-Debug-Http-Out-5.log
2014-08-08 13:14 aiaustin Note Edited: 0026678 View Revisions
2014-08-08 13:15 aiaustin File Added: 2014-08-08-OSGrid-Openvue-OpenSim-Debug-Http-Out-5-Stuck.log
2014-08-08 13:16 aiaustin Note Edited: 0026678 View Revisions
2014-08-08 13:21 aiaustin Note Edited: 0026678 View Revisions
2014-08-08 17:11 justincc Note Added: 0026681
2014-08-08 17:13 justincc Note Added: 0026682
2014-08-08 17:16 justincc Note Edited: 0026682 View Revisions
2014-08-08 21:39 Mata Hari Note Added: 0026683
2014-08-08 21:40 Mata Hari File Added: Mata2014-08-09Test1.rar
2014-08-08 21:41 Mata Hari Note Edited: 0026683 View Revisions
2014-08-09 01:22 aiaustin Note Added: 0026686
2014-08-09 01:31 aiaustin Note Added: 0026687
2014-08-09 01:32 aiaustin Note Edited: 0026687 View Revisions
2014-08-09 01:35 aiaustin Note Added: 0026688
2014-08-09 04:32 aiaustin Note Added: 0026689
2014-08-09 04:52 aiaustin Note Edited: 0026689 View Revisions
2014-08-09 04:54 Mata Hari Note Added: 0026690
2014-08-09 04:54 Mata Hari File Added: Mata2014-08-09Test2.rar
2014-08-09 05:18 Mata Hari Note Added: 0026691
2014-08-09 05:42 aiaustin Note Added: 0026692
2014-08-09 05:44 aiaustin Note Edited: 0026692 View Revisions
2014-08-09 05:55 aiaustin Note Added: 0026693
2014-08-09 05:57 aiaustin Note Edited: 0026692 View Revisions
2014-08-09 05:59 Mata Hari File Added: Mata2014-08-09Test3.rar
2014-08-09 06:07 Mata Hari Note Added: 0026694
2014-08-09 06:08 Mata Hari Note Edited: 0026694 View Revisions
2014-08-09 07:20 aiaustin Note Added: 0026695
2014-08-09 07:31 Mata Hari Note Added: 0026696
2014-08-09 07:31 Mata Hari File Added: parse.txt
2014-08-09 07:34 Mata Hari Note Edited: 0026696 View Revisions
2014-08-09 07:39 Mata Hari Note Edited: 0026696 View Revisions
2014-08-09 07:43 Mata Hari Note Edited: 0026696 View Revisions
2014-08-09 07:43 Nicky Perian Note Added: 0026697
2014-08-09 07:53 aiaustin Note Added: 0026698
2014-08-09 09:37 aiaustin Note Added: 0026699
2014-08-09 09:38 aiaustin Note Edited: 0026699 View Revisions
2014-08-09 10:09 aiaustin Note Edited: 0026698 View Revisions
2014-08-09 10:48 Nicky Perian Note Added: 0026700
2014-08-09 11:47 aiaustin Note Added: 0026701
2014-08-09 11:57 aiaustin Note Edited: 0026701 View Revisions
2014-08-09 11:57 aiaustin Note Edited: 0026701 View Revisions
2014-08-09 13:56 aiaustin Note Added: 0026702
2014-08-09 13:57 aiaustin Note Edited: 0026702 View Revisions
2014-08-09 14:25 Mata Hari Note Added: 0026704
2014-08-09 15:38 aiaustin Note Added: 0026705
2014-08-09 16:29 Nicky Perian Note Added: 0026706
2014-08-09 17:26 Mata Hari Note Added: 0026707
2014-08-10 02:39 aiaustin Note Added: 0026709
2014-08-10 02:49 aiaustin Note Edited: 0026709 View Revisions
2014-08-10 02:49 aiaustin Note Edited: 0026709 View Revisions
2014-08-10 02:57 aiaustin Note Edited: 0026709 View Revisions
2014-08-10 02:59 aiaustin Note Edited: 0026709 View Revisions
2014-08-10 06:56 Mata Hari Note Added: 0026710
2014-08-10 07:10 aiaustin Note Added: 0026711
2014-08-10 07:11 aiaustin Note Edited: 0026711 View Revisions
2014-08-10 07:28 Mata Hari Note Added: 0026712
2014-08-10 07:30 Mata Hari Note Edited: 0026712 View Revisions
2014-08-10 07:37 Mata Hari Note Added: 0026713
2014-08-10 07:49 Ken Grunke Note Added: 0026714
2014-08-10 07:49 Ken Grunke Note Edited: 0026714 View Revisions
2014-08-10 07:56 BlueWall Note Added: 0026715
2014-08-10 08:02 Nicky Perian Note Added: 0026716
2014-08-10 08:06 BlueWall Note Added: 0026717
2014-08-10 08:07 Mata Hari Note Added: 0026718
2014-08-10 08:15 aiaustin Note Added: 0026719
2014-08-10 08:23 aiaustin Note Added: 0026720
2014-08-10 08:25 aiaustin Note Edited: 0026719 View Revisions
2014-08-10 08:28 aiaustin Note Edited: 0026719 View Revisions
2014-08-10 08:29 aiaustin Note Edited: 0026720 View Revisions
2014-08-10 08:37 aiaustin Note Edited: 0026720 View Revisions
2014-08-10 08:37 aiaustin Note Edited: 0026720 View Revisions
2014-08-10 08:39 aiaustin Note Edited: 0026720 View Revisions
2014-08-10 08:39 aiaustin Note Edited: 0026720 View Revisions
2014-08-10 08:41 aiaustin Note Edited: 0026720 View Revisions
2014-08-10 08:47 BlueWall Note Added: 0026721
2014-08-10 09:10 Mata Hari Note Added: 0026722
2014-08-10 09:41 BlueWall Note Added: 0026723
2014-08-10 10:14 BlueWall Note Added: 0026724
2014-08-10 11:20 Mata Hari Note Added: 0026725
2014-08-10 12:37 aiaustin Note Edited: 0026720 View Revisions
2014-08-10 18:07 BlueWall Note Added: 0026726
2014-08-11 01:12 aiaustin Note Added: 0026727
2014-08-11 01:12 aiaustin Note Edited: 0026727 View Revisions
2014-08-11 01:13 aiaustin Note Edited: 0026727 View Revisions
2014-08-11 01:15 aiaustin Note Edited: 0026727 View Revisions
2014-08-11 01:32 aiaustin Note Added: 0026728
2014-08-11 03:40 aiaustin Note Edited: 0026728 View Revisions
2014-08-11 03:41 aiaustin Note Edited: 0026728 View Revisions
2014-08-11 03:42 aiaustin Note Edited: 0026728 View Revisions
2014-08-17 06:52 Radioactive Rosca Note Added: 0026753
2014-08-17 06:54 Radioactive Rosca Note Edited: 0026753 View Revisions
2014-08-17 08:58 aiaustin Note Added: 0026755
2014-08-17 08:59 aiaustin Note Edited: 0026755 View Revisions
2014-08-17 09:00 aiaustin Note Added: 0026756
2014-08-17 11:23 Mata Hari Note Added: 0026757
2014-08-18 01:17 Radioactive Rosca Note Added: 0026762
2014-08-18 06:48 Radioactive Rosca Note Added: 0026764
2014-08-18 09:00 zadark Note Added: 0026765
2014-08-18 09:58 Mata Hari Note Added: 0026766
2014-08-18 10:01 Nicky Perian Note Added: 0026767
2014-08-18 10:09 zadark Note Added: 0026768
2014-08-18 10:32 aiaustin Note Added: 0026769
2014-08-18 10:32 aiaustin Note Edited: 0026769 View Revisions
2014-08-18 11:17 Mata Hari Note Added: 0026770
2014-08-19 14:20 aiaustin Note Added: 0026771
2014-08-26 21:21 Mata Hari Note Added: 0026782
2014-08-27 01:23 aiaustin Note Added: 0026783
2014-12-05 07:14 Mata Hari Note Added: 0027068
2015-02-27 04:23 aiaustin Note Added: 0027623
2015-02-27 04:28 aiaustin Note Edited: 0027623 View Revisions
2015-02-27 04:30 aiaustin Note Edited: 0027623 View Revisions
2015-02-27 04:31 aiaustin Note Edited: 0027623 View Revisions
2015-02-27 04:34 aiaustin Note Edited: 0027623 View Revisions
2015-02-27 05:34 aiaustin Note Added: 0027624
2015-03-02 05:23 aiaustin Note Added: 0027664
2015-03-02 05:28 aiaustin Note Edited: 0027664 View Revisions
2015-03-02 05:30 aiaustin Note Edited: 0027664 View Revisions
2015-03-02 06:13 Mata Hari Note Added: 0027665
2015-03-02 13:16 aiaustin Note Added: 0027670
2015-03-02 13:21 aiaustin Note Edited: 0026645 View Revisions
2015-03-02 13:44 aiaustin Note Edited: 0027670 View Revisions
2015-03-02 13:45 aiaustin Note Edited: 0027670 View Revisions
2015-03-02 14:58 Mata Hari Note Added: 0027677
2015-03-03 01:42 aiaustin Note Added: 0027681
2015-03-03 01:42 aiaustin Note Edited: 0027681 View Revisions
2015-03-03 01:44 aiaustin Note Edited: 0027681 View Revisions
2015-03-03 01:45 aiaustin Note Deleted: 0027670
2015-03-03 10:44 Mata Hari Note Added: 0027684
2015-03-03 14:24 aiaustin Note Added: 0027695
2015-03-04 12:19 Mata Hari Note Added: 0027744
2015-03-04 14:10 aiaustin Note Edited: 0027695 View Revisions
2015-03-04 14:13 aiaustin Note Edited: 0025791 View Revisions
2015-03-05 06:46 aiaustin Note Edited: 0027695 View Revisions
2015-03-05 07:22 aiaustin Note Added: 0027745
2015-03-07 20:13 Mata Hari Note Added: 0027800
2015-03-08 01:25 FreakyTech Note Added: 0027801
2015-03-08 01:50 aiaustin Note Added: 0027802
2015-03-08 01:53 aiaustin Note Edited: 0027802 View Revisions
2015-03-08 01:56 aiaustin Note Edited: 0027802 View Revisions
2015-03-08 07:23 aiaustin Note Added: 0027803
2015-03-08 07:25 aiaustin Note Edited: 0027803 View Revisions
2015-03-08 07:28 aiaustin Note Edited: 0027803 View Revisions
2015-03-08 10:42 FreakyTech Note Added: 0027807
2015-03-09 04:23 aiaustin Note Added: 0027826
2015-03-09 04:30 aiaustin Note Edited: 0027826 View Revisions
2015-03-09 04:31 aiaustin Note Edited: 0027826 View Revisions
2015-03-09 04:31 aiaustin Note Edited: 0027826 View Revisions
2015-03-09 04:37 aiaustin Note Edited: 0027826 View Revisions
2015-03-09 04:41 aiaustin Note Edited: 0027803 View Revisions
2015-03-09 04:42 aiaustin Note Edited: 0027803 View Revisions
2015-03-09 04:43 aiaustin Note Edited: 0027826 View Revisions
2015-03-09 04:46 aiaustin Note Edited: 0026644 View Revisions
2015-03-09 11:10 FreakyTech Note Added: 0027828
2015-03-09 11:11 FreakyTech Note Edited: 0027828 View Revisions
2015-03-09 13:01 aiaustin Note Added: 0027829
2015-03-09 16:25 Mata Hari Note Added: 0027830
2015-05-05 21:31 Diva Note Added: 0028230
2015-05-06 01:37 aiaustin Note Added: 0028236
2015-05-06 06:26 aiaustin Note Edited: 0028236 View Revisions
2015-05-06 08:14 nebadon Note Added: 0028239
2015-05-06 09:21 Mata Hari Note Added: 0028242
2015-05-06 09:22 Mata Hari File Added: empty_cachefetch_log_2015_05_06.rar
2015-05-06 09:24 Mata Hari Note Edited: 0028242 View Revisions
2015-05-06 09:29 Mata Hari Note Added: 0028243
2015-05-06 09:33 nebadon Note Added: 0028244
2015-05-06 09:39 nebadon Note Added: 0028245
2015-05-06 09:41 Mata Hari Note Edited: 0028242 View Revisions
2015-05-06 11:41 Diva Note Added: 0028254
2015-05-06 12:10 aiaustin Note Added: 0028255
2015-05-06 12:11 aiaustin Note Edited: 0028255 View Revisions
2015-05-06 13:45 Mata Hari Note Added: 0028256
2015-05-06 17:48 nebadon Note Added: 0028262
2015-05-07 01:24 aiaustin Note Added: 0028265
2015-05-07 01:28 aiaustin Note Edited: 0028265 View Revisions
2015-05-07 01:35 aiaustin Note Edited: 0028265 View Revisions
2015-05-07 02:27 aiaustin Note Edited: 0028265 View Revisions
2015-05-07 03:27 aiaustin Note Edited: 0028265 View Revisions
2015-05-07 03:27 aiaustin Note Edited: 0028265 View Revisions
2015-05-07 06:59 nebadon Note Added: 0028267
2015-05-07 07:30 Diva Note Added: 0028268
2015-05-07 07:42 nebadon Note Added: 0028269
2015-05-07 08:39 aiaustin Note Added: 0028270
2015-05-07 08:41 aiaustin Note Edited: 0028270 View Revisions
2015-05-07 08:42 aiaustin Note Edited: 0028265 View Revisions
2015-05-07 08:46 aiaustin Note Edited: 0026644 View Revisions
2015-05-07 08:50 aiaustin Note Added: 0028271
2015-05-07 08:53 aiaustin Note Edited: 0028271 View Revisions
2015-05-07 10:04 aiaustin Note Edited: 0026711 View Revisions
2015-05-07 20:49 Diva Note Added: 0028276
2015-05-07 20:50 Diva Note Edited: 0028276 View Revisions
2015-05-07 20:59 nebadon Note Added: 0028277
2015-05-08 02:50 aiaustin Note Added: 0028278
2015-05-08 02:51 aiaustin Note Edited: 0028278 View Revisions
2015-05-08 03:32 danbanner Note Added: 0028279
2015-05-08 04:14 aiaustin Note Added: 0028280
2015-05-08 04:16 aiaustin Note Edited: 0028280 View Revisions
2015-05-08 04:16 aiaustin Note Edited: 0028280 View Revisions
2015-05-08 04:18 aiaustin Note Edited: 0028280 View Revisions
2015-05-08 04:39 aiaustin Note Added: 0028281
2015-05-08 04:40 aiaustin Note Edited: 0028281 View Revisions
2015-05-08 05:05 aiaustin Note Added: 0028282
2015-05-08 05:14 Mata Hari Note Added: 0028283
2015-05-08 05:27 nebadon Note Added: 0028284
2015-05-08 05:29 Seth Nygard Note Added: 0028285
2015-05-08 05:32 nebadon Note Added: 0028286
2015-05-08 05:35 aiaustin Note Edited: 0028282 View Revisions
2015-05-08 05:36 aiaustin Note Edited: 0028283 View Revisions
2015-05-08 05:36 aiaustin Note Edited: 0028283 View Revisions
2015-05-08 05:39 aiaustin Note Added: 0028287
2015-05-08 06:30 aiaustin Note Added: 0028288
2015-05-08 06:36 Diva Note Added: 0028289
2015-05-08 06:51 aiaustin Note Added: 0028290
2015-05-08 06:52 aiaustin Note Added: 0028291
2015-05-08 06:53 aiaustin Note Edited: 0028291 View Revisions
2015-05-08 06:54 aiaustin Note Edited: 0028291 View Revisions
2015-05-08 06:58 Diva Note Added: 0028292
2015-05-08 07:23 aiaustin Note Added: 0028293
2015-05-08 07:24 aiaustin Note Edited: 0028293 View Revisions
2015-05-08 07:32 Diva Note Added: 0028294
2015-05-08 07:48 Diva Note Added: 0028295
2015-05-08 07:57 Seth Nygard Note Added: 0028296
2015-05-08 08:07 Seth Nygard Note Added: 0028297
2015-05-08 08:11 Diva Note Added: 0028298
2015-05-08 08:21 Seth Nygard Note Edited: 0028296 View Revisions
2015-05-08 08:38 Diva Note Added: 0028299
2015-05-08 09:06 Seth Nygard Note Added: 0028301
2015-05-08 09:08 Diva Note Added: 0028302
2015-05-08 09:19 Seth Nygard Note Added: 0028303
2015-05-08 09:21 Seth Nygard Note Added: 0028304
2015-05-08 09:21 Diva Note Added: 0028305
2015-05-08 09:38 Diva Note Added: 0028306
2015-05-08 09:52 Mata Hari Note Added: 0028307
2015-05-08 09:53 Mata Hari Note Edited: 0028307 View Revisions
2015-05-08 10:02 Diva Note Added: 0028309
2015-05-08 10:10 Seth Nygard Note Added: 0028310
2015-05-08 10:59 Seth Nygard Note Added: 0028311
2015-05-08 11:06 Diva Note Added: 0028312
2015-05-08 11:11 Seth Nygard Note Added: 0028313
2015-05-08 11:16 aiaustin Note Added: 0028314
2015-05-08 11:18 aiaustin Note Added: 0028315
2015-05-08 11:38 aiaustin Note Edited: 0028313 View Revisions
2015-05-08 11:44 aiaustin Note Edited: 0028315 View Revisions
2015-05-08 12:10 Diva Note Added: 0028316
2015-05-08 12:17 aiaustin Note Added: 0028317
2015-05-08 12:22 Diva Note Added: 0028318
2015-05-08 12:43 Seth Nygard Note Added: 0028319
2015-05-08 12:44 aiaustin Note Added: 0028320
2015-05-08 12:48 aiaustin Note Edited: 0028320 View Revisions
2015-05-08 12:55 aiaustin Note Edited: 0028320 View Revisions
2015-05-08 12:55 aiaustin Note Edited: 0028320 View Revisions
2015-05-08 12:58 Diva Note Added: 0028321
2015-05-08 13:03 aiaustin Note Added: 0028322
2015-05-08 13:06 aiaustin Note Edited: 0028322 View Revisions
2015-05-08 13:19 aiaustin Note Edited: 0028322 View Revisions
2015-05-08 14:11 Mata Hari Note Added: 0028323
2015-05-08 14:55 Seth Nygard Note Added: 0028324
2015-05-08 15:42 Diva Note Added: 0028325
2015-05-08 16:25 Mata Hari Note Added: 0028326
2015-05-08 16:26 Diva Note Added: 0028327
2015-05-08 17:03 wbalazic Note Added: 0028328
2015-05-08 17:04 wbalazic Note Edited: 0028328 View Revisions
2015-05-08 18:12 Mata Hari Note Added: 0028329
2015-05-08 19:07 Nicky Perian Note Added: 0028330
2015-05-08 21:33 Diva Note Added: 0028331
2015-05-08 21:54 nebadon Note Added: 0028332
2015-05-09 01:44 aiaustin Note Added: 0028337
2015-05-09 01:45 aiaustin Note Edited: 0028337 View Revisions
2015-05-09 08:48 aiaustin Note Added: 0028339
2015-05-09 08:52 aiaustin Note Edited: 0028339 View Revisions
2015-05-09 08:58 aiaustin Note Edited: 0028339 View Revisions
2015-05-09 09:17 nebadon Note Added: 0028342
2015-05-09 09:17 nebadon Note Edited: 0028342 View Revisions
2015-05-09 09:23 aiaustin Note Added: 0028343
2015-05-09 09:24 aiaustin Note Edited: 0028343 View Revisions
2015-05-09 09:24 aiaustin Note Edited: 0028343 View Revisions
2015-05-09 09:24 nebadon Note Added: 0028344
2015-05-09 09:26 aiaustin Note Edited: 0028339 View Revisions
2015-05-09 09:27 aiaustin Note Edited: 0028343 View Revisions
2015-05-09 09:29 aiaustin Note Edited: 0028343 View Revisions
2015-05-09 10:06 aiaustin Note Added: 0028345
2015-05-09 10:15 nebadon Note Added: 0028346
2015-05-09 10:18 Diva Relationship added related to 0007564
2015-05-09 10:24 aiaustin Note Added: 0028348
2015-05-09 10:24 Diva Note Added: 0028349
2015-05-10 10:30 aiaustin Note Added: 0028359
2015-05-10 10:30 aiaustin Status assigned => resolved
2015-05-10 10:30 aiaustin Fixed in Version => master (dev code)
2015-05-10 10:30 aiaustin Resolution open => fixed
2015-05-10 10:30 aiaustin Status resolved => closed


Copyright © 2000 - 2012 MantisBT Group
Powered by Mantis Bugtracker