Missing inventory (repetitively) in latest Firestorm

[Rick Nightingale]

I have often done quick relogs too... I did wonder if that was also a cause since I noticed inventory loss issues on alts at times other than powering off/on the PC (but it could be that I had already had the loss on that alt and only just logged it in since it happened). I never put that to the test once I figured out the powering off issue but it seems likely. If the viewer is relogged on the same alt, trying to unpack and load a cache file before the previous viewer's thread has finished writing it... I can see that happening now I know the viewer's exit code is poor.

In my case I usually relog like that because I've had several alts logged in together, testing something or other. Eventually the viewers can get a bit flaky when doing that, depending on what I'm up to and the graphics loads on them, so I'll log them all out and relog once they've all closed.

I've not done recently because my work pattern is a bit different right now, and since making sure I don't power off for a few minutes (I watch the cache files being written if I'm just waiting) I haven't had any loss. On occasion though muscle-memory has kicked in and I've shut down after the viewer closes and, yep, sure-fire way to get cache loss every time.

My annoyance with all of this is that it is, and should be, simply avoided in the exit code even with the pretended quick exit. Just use the same "No, Windows, you can't shut down just yet" response when Windows sends the shutdown query that a simple notepad application with an unsaved file uses. Likewise for the rapid relog issue, try restarting something like Firefox (the web browser, not a typo) quickly... "sorry, Firefox is still running" - and no doubt doing its housekeeping in the background, having only apparently closed. Instead, the response to it all seems to be "This is intended behaviour and it's a layer 8 problem".*

* Edit: For those who aren't network nerds like me, layer 8 means the user is the problem

Edited November 16, 2022 by Rick Daylight

[Kyrie Deka]

12 hours ago, Rick Daylight said:

layer 8 means the user is the problem

Smilessss - I am at-one with layer 8 conditions.  I filed a FS Jira 32417 a few days back on this issue when I got my most-bored with reloading inventory over and over, and then found this discussion.  I haven't yet found the quick shutdown info to read again, so lacking in a clear understanding if that was a FS or SL etc change...  And if it was already included in the current FS Release, I never had any too-soon issue at all on that one.

[OptimoMaximo]

19 hours ago, Rick Daylight said:

Edit: For those who aren't network nerds like me, layer 8 means the user is the problem

It's a PEBCAK bug

Problem Exists Between Chair And Keyboard

I don't know who came up with this first, but it's a well known programmers' punchline against inept users 😂

[Rick Nightingale]

LOL - it's years since I've heard that one! But then it's years since I did serious (i.e. paid) programming.

[Jaylinbridges]

8 hours ago, Kyrie Deka said:

Smilessss - I am at-one with layer 8 conditions.  I filed a FS Jira 32417 a few days back on this issue when I got my most-bored with reloading inventory over and over, and then found this discussion.  I haven't yet found the quick shutdown info to read again, so lacking in a clear understanding if that was a FS or SL etc change...  And if it was already included in the current FS Release, I never had any too-soon issue at all on that one.

The reports of missing inventory increased when the rapid fake shutdown was first added to Firestorm.  The rapid shutdown was an LL "feature" that came with their enhanced performance viewer, weeks before FS released the same code.  It has been difficult to convince the developers this is a problem, because, like Rowan, they don't shut down windows, or relog back in instantly like ordinary users often do.  It is much easier to just blame the user than actually fix the problem. 

I have never had this lost inventory problem myself either, which means ABSOLUTELY NOTHING, when it is a problem for others.  I never shut down my computers.  I usually wait at least 1 min before re-logging.  But when FS still had the shutdown page visible, of course I was forced to wait.  My inventory on my main alt is around 80K, and not  flat, although it needs work since all the free gifts have become a way of life.  Before the rapid shutdown, I would wait about 15 seconds for windows desktop to return.  Now they removed the clock, so I guess I have to count, one thousand one, one thousand two...   But if your job requires a quick relog, and you have no clue about the real shut down time, you might lose inventory.

Main problem is most users have no idea about shutdowns.  They are shoppers, clubbers, artists, lovers, or small animals , and think if they tried to open their computer case it will explode; besides their nail file makes a poor screwdriver. 

Kyrie, I hope your FS Jira 32417 gets some action.  So far they told you to whitelist your anti-virus, and seem unconcerned, the same as the FS Help group.

Edited November 16, 2022 by Jaylinbridges

[Rick Nightingale]

My Jira got closed as 'intended behaviour' after jumping through the usual hoops.

https://jira.firestormviewer.org/browse/SUP-27008

[Jaylinbridges]

2 hours ago, Rick Daylight said:

My Jira got closed as 'intended behaviour' after jumping through the usual hoops.

https://jira.firestormviewer.org/browse/SUP-27008

I get this for your SUP-27008:

The FS Jira 32417 is still there.  But not surprised they think it is intended behaviour, and ignore the fact that a user cannot tell anymore when FS is safe to restart.

Guess it's time to ping the FS team to explain the issue here in this forum.

@Whirly Fizzle @Beq Janus @panterapolnocy @Jessica Lyon

Edited November 17, 2022 by Jaylinbridges

[Kyrie Deka]

22 minutes ago, Rick Daylight said:

wse/SUP-27008

You mean we could have had this worked out much sooner than the weeks I've dealt with it at every login?! 

[Jaylinbridges]

21 minutes ago, Kyrie Deka said:

You mean we could have had this worked out much sooner than the weeks I've dealt with it at every login?! 

Only if they listen...

[Rick Nightingale]

Yep - I was quite explicit as to the cause once I figured it out, as I have been in this thread. I basically got told I shouldn't be turning my PC off until it was ready (never mind about how should I know when that is? Or why a program isn't doing the obvious, simple thing of pausing shutdown while it saves its data) and it was my own fault (or I should talk to Microsoft about it, lol).

End of story, lol.

Good luck with yours - I've voted and watched it. I'm wary of commenting in case they just link yours to mine and close yours too.

[Jaylinbridges]

Now that I have a few days off I will try to duplicate this issue with the default SL Viewer. So far the reports have come from Firestorm users, while it seems the problem became worse after FS added the improved performance code with the rapid shutdown from LL.  So, is this a FS issue, or an LL issue?  And thanks LL for approving and unhiding my posts here.

 

 

Edited November 21, 2022 by Jaylinbridges

[Beq Janus]

Hi @Rick Daylight

I've just seen this (the forums told me I'd be tagged but I cannot see where) [Added later, as I seemed to forget to hit submit! Apparently you get notified even if the post is held for moderation, how weird]

I've skimmed most of the thread, and the Jira. If I understand correctly you have concluded (so far) that the issue is that the OS is being terminated, before the writes complete. Is that a correct (if very compressed) summary?

I am unconvinced of that a premature termination is behind this, such a termination would result in a truncated zip file and that would then fail to unzip on restart and the entire cache would be flagged as invalid as it cannot be unzipped.

As you have noted, there are two stages, the writing of a temporary file (the '.t') which is then gzipped. The premature termination can of course happen to the temp file, but that makes matters rather more complicated because we are now looking for a situation where the temp file is patrially written due to some other event, but the gzip is then triggered correctly. Intriguing.

Can you try adding inventory logging to the viewer and then adding a log file for a failed run to a Jira, please.

In your settings folder you should find a logcontrol.xml file. Open that up in your code editor of choice. 

towards the end of the file you should see a section that looks like this.

                        <array>

                             

                        <!-- sample entry for debugging specific items

                             <string>AnimatedObjects</string>

                             <string>Avatar</string>

                             <string>Inventory</string>

                             <string>SceneLoadTiming</string>

                             <string>Voice</string>

                             <string>Avatar</string>                            

                        -->

                             <string>import</string>

                             <string>export</string>

                             <string>Outfit</string>

                        </array>

Simply move the line <string>Inventory</string> down so that it is out side of the comment block, place it between export and Outfit for example.

You'll want to revert that later as it will generate a lot more logging.

On 11/16/2022 at 11:19 PM, Jaylinbridges said:

I get this for your SUP-27008:

This is normal for support tickets as they are kept private as they can have more personal info in them. It's a bit of a fuzzy line really but that is how things are setup at the moment. 

[Rick Nightingale]

I'll get on that later @Beq Janus - maybe tomorrow when I can concentrate better on what I'm doing.

Your very compressed summary is correct. I concur regarding the 'truncated' gzip file being usable - being odd. I would have expected  it to be simply unusable if truly truncated. I did look inside a truncated gzip and inside was the (shorter than it should be) .inv.llsd file. Yes, if the .t file writing is truncated by the start of Window's shutdown process, but then somehow the gzip process is still started on that truncated file... that would answer that but be quite 'interesting' as you say.

Certainly it is related to Windows being shut down before the cache file is fully written, whatever the details of that are. I've run too many tests now without any deviation from what I have observed. Quick shutdown = 'truncated' cache file = missing inventory next time; 100% of the time. If I wait until I see the gzip file finish writing before shutting down... no problem.

 

[Rick Nightingale]

@Beq Janus I've done that.

https://jira.firestormviewer.org/browse/FIRE-32453

I added several logfiles as I noted in the Jira. The results of the tests were exactly as before, with the addition of testing logging my Windows user out instead of shutting down the PC (quickly after closing Firestorm). Same result of cache loss. There are two logs after cache loss from a quick shutdown, and one log from the Windows log out. Probably more than you need but better to have it, and not need it... lol.

Hope that helps.

[Rick Nightingale]

I can confirm the same cache loss in the official LL viewer with a quick shutdown after the viewer apparently closes.

Should have tested it before but I really dislike loading that viewer.

Edited November 22, 2022 by Rick Daylight

[Jaylinbridges]

1 hour ago, Rick Daylight said:

I can confirm the same cache loss in the official LL viewer with a quick shutdown after the viewer apparently closes.

Thanks, I won't do it then.  This is a behavioral issue also.  FS sends inventory loss victims to the FS Wiki, and if they follow all the steps, eventually clear their caches.  This removes the .gz shortened (or temp corrupted) file, and inventory loads fully in it's absence.  They report back to FS help that it is fixed. But not really of course.  They usually don't follow up later when loss occurs again, because they already tried everything they were told.  Some resort to clearing the cache as the "cure" for missing inventory, and don't care about the cause.

Others are told to try the SL Viewer and they do not see the inventory loss.  But they are not regular SL Viewer users, so they don't use it for rapid logins.  So they don't see the problem in the SL Viewer (low sampling) and report back that it only happens in FS.  But FS is what they use daily. Again, inadequate sampling data, misleading the FS Help team.  

 

Edited November 22, 2022 by Jaylinbridges

[Rick Nightingale]

1 hour ago, Jaylinbridges said:

...they are not regular SL Viewer users, so they don't use it for rapid logins.  So they don't see the problem in the SL Viewer...

 

Yeah, that's logical. A bit like me watching the viewer's logoff process like a hawk for a week but never catching it 'in the act' of corrupting that file. I never would, until I stopped watching it and went back to behaving normally 🤣

[Beq Janus]

So here's a very early feedback. The logs and the notes are excellent Rick, thank you.

The worrying thing is that the only conclusion I can draw at the moment is that the viewer is crashing on exit. Needless to say I need to look deeper into this.

Using your log A we can see that at the start we have 

Quote

Successfully loaded 8846 categories and 58142 items from cache.

Then right at the end we see.

Quote

2022-11-22T19:27:10Z DEBUG #Inventory# newview/llinventorymodel.cpp(2127) LLInventoryModel::cache : Caching 5b474010-daca-46a6-9b92-c57d7ba23b8b for 9ba9c2e2-8beb-4643-8936-38a178b1704d

2022-11-22T19:27:10Z INFO #Inventory# newview/llinventorymodel.cpp(3265) LLInventoryModel::saveToFile : saving inventory to: (E:\Firestorm\9ba9c2e2-8beb-4643-8936-38a178b1704d.inv.llsd)

These two lines are the very last in the log and to be blunt, that is not possible under normal operation.

Those lines are written out by the inventory model when it is told to cache itself by the "disconnectViewer" function.

It is not in a background thread. It should not have any route for a parallel exit (where some other thread decides to shut the process), and in fact the viewer window will not shut until this completes. 

To add to this, there is no obvious way for the saveToDisk function that does that logging to complete without logging at least one other line, either a success or a fail. All paths through the code are covered by an error handler. Yet we see no errors, no logging at all.

We can be pretty sure that the viewer does stop at that point, because immediately after the saveToDisk() we call gzip on the file. and that in turn has logging associated.

"But Beq," I hear you cry "if the logging is killed then that would explain it." 

It could...but, next time we start we find this mess...

Quote

Couldn't rename to 'E:\Firestorm\9ba9c2e2-8beb-4643-8936-38a178b1704d.inv.llsd' from 'E:\Firestorm\9ba9c2e2-8beb-4643-8936-38a178b1704d.inv.llsd.t' (errno 17): File exists

Unable to gunzip E:\Firestorm\9ba9c2e2-8beb-4643-8936-38a178b1704d.inv.llsd.gz

I've not looked into those in depth yet, but the attempts to recover here seem to be tripping over themselves. The fact that the .t file is there at all implies that the gzip did not complete, which means that it was not JUST the logging that stopped.

I need to try to reproduce this in a debugger and work out what is going on. But that'll have to wait as I'm heading off to bed.

There is a chance that tomorrow or the next day , I completely recant all this when I find out that I overlooked something very obvious, but right now it does look like something peculiar is going on and my best guess is that the viewer is meeting an untimely demise and not at the hands of the operating system. 

If I cannot get this to repro for me I might need to get you to turn on more debug logging to work out if we are exiting early and unannounced. 

For now though, g'night.

[Jaylinbridges]

3 hours ago, Beq Janus said:

We can be pretty sure that the viewer does stop at that point, because immediately after the saveToDisk() we call gzip on the file. and that in turn has logging associated.

I hope debugging files gives you an answer.  Thanks for looking at the logout processes.  But from another simple view, why does the LL and FS viewers shutdown instantly and return to the Windows desktop?  We know the viewer is not really finished in less than 1 second after you hit that X to log out.  What about the code that removed the prior shutdown window?

And why was it removed after years of having a proper shutdown window?

 

[Rick Nightingale]

Yes, thank you Beq. Let me know if you need any more tests doing; I'm happy to help. I thought the end of the logs (I did look at them) seemed to end abruptly.

I imagine this one will be tricky to investigate, given that it only seems to happen during a Windows shutdown or user logoff.

I've tried but failed to get it to reproduce with quick relogs (no shutdown) this morning, even with multiple accounts relogging simultaneously to push the file system. That might be a red herring then, at least on my PC.

Edited November 23, 2022 by Rick Daylight

[Beq Janus]

10 hours ago, Jaylinbridges said:

I hope debugging files gives you an answer.  Thanks for looking at the logout processes.  But from another simple view, why does the LL and FS viewers shutdown instantly and return to the Windows desktop?  We know the viewer is not really finished in less than 1 second after you hit that X to log out.  What about the code that removed the prior shutdown window?

And why was it removed after years of having a proper shutdown window?

There is nothing that I can see that suggests that is how it is meant to behave at all. As I said in the response above, all the of cache writing should be happening on the main thread and there is is parallel activity that should cause early termination. IT is the case that a lot of non-critical (where critical means rendering and main game loop) activities have been moved to separate threads as part of the performance changes, so it could be that something is tripping over itself and hence my belief that somewhere something is causing the viewer to crash and burn without any trace. But as I said this is mostly speculation right now.

[Whirly Fizzle]

Reproduced on the LL Viewer & bug report filed

BUG-232971 - Faster viewer shutdown time since performance improvements can lead to perceived inventory loss due to cache corruption

[Rick Nightingale]

Thank you Whirly. I fully concur with the "this-app-is-preventing-shutdown" message (and actually do so while the cache is finished) that should be generated in this circumstance

 

Edited November 23, 2022 by Rick Daylight

[DemeraraGirl]

I have experiencing this problem has a while and the theory about the quick shutdown after the viewer closes makes sense to me.

I usually login Second Life at night and when I logoff, I tend to shutdown the computer right after. Coincidence or not, in most of the times I login the next day, I have this inventory issue (Firestorm or LL viewer) and have to clear the cache.

I'll try to wait a little more before shutdown to see how it goes.

 

 

[Jaylinbridges]

7 hours ago, Whirly Fizzle said:

Reproduced on the LL Viewer & bug report filed

BUG-232971 - Faster viewer shutdown time since performance improvements can lead to perceived inventory loss due to cache corruption

Thank You Whirly, and what a detailed JIRA  Bug report to LL.  It's been a battle to get the shutdown issue recognized as a real bug, and point out who created this problem (not FS).

 

Edited November 24, 2022 by Jaylinbridges