973750 - Since Firefox 27, simple-storage doesn't seem to save on browser close

Status: RESOLVED FIXED

(Add-on SDK Graveyard :: General, defect)

Description

[Steve Sobel]

User Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_8_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/32.0.1700.107 Safari/537.36

Steps to reproduce:

Since FF27 update, existing / previously working addons that use simple storage to save data are no longer reliably persisting it.

In my case, the addon is Reddit Enhancement Suite - a pretty large / complex addon that's not an ideal simple test case here.  However, if you install the latest version from AMO you can see this behavior in FF27.

https://addons.mozilla.org/en-US/firefox/addon/reddit-enhancement-suite/?src=search

1) Install the addon

2) browse to reddit.com - observe the little "alien" icon near the top right that is a part of the "account switcher" module.

3) roll over the settings cog (top right corner) to open the console

4) disable the "account switcher" module by clicking the on/off toggle.

5) close the console and refresh the page -- observe the little alien is gone...  browse to a few more pages on reddit.com and observe - he's still gone, the module is off.

6) quit firefox completely, and reopen it, browsing to Reddit.com - observe that unfortunately the alien is back / the module is no longer off!


I have not yet had the opportunity to verify, but a fellow developer has observed that store.json seems to be persisted only every 5 minutes, and it's not being persisted on/prior to Firefox closing, which may be the culprit of the setting not persisting after browser close.

If I can, I'll whip up a simple test case / addon that's nowhere near as complex as RES for a cleaner test, but I at least wanted to get the bug in the system ASAP.


Actual results:

the setting to turn off account switcher is not persisted in FF27 and above


Expected results:

the setting should persist across browser restarts.

Comment 1

[Steve Sobel]

I should add that if you test this with FF26 (e.g. using PortableApps), the issue does not seem to exist.

Comment 2

[Tomislav Jovanovic :zombie]

i think reports of this bug are not limited to OSX, Steve can you confirm this?

Comment 3

[Steve Sobel]

My apologies - OSX was selected for me by default but yes, I don't think this is OS specific.

Comment 4

[Steve Sobel]

I just received an update to Firefox in the middle of doing some testing, and this problem seems to have gone away.

The version I just got is 27.0.1 (formerly 27.0), but I don't see anything here that indicates this issue was addressed, so I'm curious if it might've gotten fixed but not documented?

http://www.mozilla.org/en-US/firefox/27.0.1/releasenotes/

Comment 5

[Matteo Ferretti [:zer0] [:matteo]]

I'm not sure. We have modified the simple-storage in this period, see by bug 893276 (https://github.com/mozilla/addon-sdk/commit/c382a85817c42685e23a6a7168e267ba60c4a010) that was reverted (https://github.com/mozilla/addon-sdk/commit/11344b27cc0a1632ab757fda3b43b320e8c6830d); but this operation seems never landed in Firefox release (comparing the simple-storage between 27 and 27.0.1).
Unless you have used Firefox Nightly, then it could be possible that you experienced this issue, but it doesn't seems your case.

However, I will close this bug considering that is resolved in 27.0.1.

Comment 6

[Steve Sobel]

I just tested this on Windows and can confirm it's still a problem in 27.0.1

I am not sure why it's no longer a problem for me on OSX 27.0.1 - not sure if OS specific or some other external factor, but I'm reopening this.

Comment 7

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

Matteo, can you manually verify that this is working?

Comment 8

[Steve Sobel]

for what it's worth: I tried to create a reduced test case for this, and the reduced test case doesn't exhibit the same problem.  However, I can't seem to isolate anything in my own addon that could be exacerbating this.  Maybe it has to do with the size or quantity of data already in the store, or of in the particular key being set?

It's literally doing ss.storage[keyName] = value -- that's it.

If I console.log out something like: console.log("setting key and value",key,value); -- the output is there in my addon, and yet when I close the browser and reopen it, data is often gone.

Here is my reduced test case just FYI, though it may not be all that informative since I can't get this reduced test case to exhibit the same problem...


main.js:


var widgets = require("sdk/widget");
var tabs = require("sdk/tabs");

let ss = require("simple-storage");

console.log('startup value of ss.storage.foo: ',ss.storage.foo);

var widget = widgets.Widget({
  id: "mozilla-link",
  label: "Mozilla website",
  contentURL: "http://www.mozilla.org/favicon.ico",
  onClick: function() {
    if (typeof ss.storage.foo === 'undefined') {
    	ss.storage.foo = false;
    }
    ss.storage.foo = !ss.storage.foo;
    console.log('ss.storage.foo changed to: ',ss.storage.foo);
  }
});

Comment 9

[Steve Sobel]

Quick update: I've tested in FF28 (beta channel at this time) and the problem exists there too.

It does seem consistent that if I wait ~5 minutes after data changes, the data does persist. There's got to be something going on here because nothing in the simple-storage API suggests that we developers have any direct control over when store.json is written, etc...

If there is anything more I can do to help isolate the bug, please let me know. I'd be happy to get on a screenshare or whatever else it takes.

Comment 10

[Tomislav Jovanovic :zombie]

there have been intermittent reports of this problem for several months, and possible causes were thought to be antiviruses or other similar software locking/deleting files in the profile folder, but it was difficult (impossible) to reproduce under controlled conditions were it could be investigated.

Steve, if you can reliably reproduce this behavior, that would mean a lot to getting to the root of this.

also, the fact it is written after 5 minutes rules out the antivirus, and points to Unload event not firing, or something else happening with it.

if you can post the addon code that actually does exhibit the behavior, that might give us some clues.

Comment 11

[Steve Sobel]

The addon code is here, in the XPI directory (you'll need to run makelinks.sh or the gruntfile to hardlink all of the stuff from /lib).  We've put in a temporary workaround that works fine on the master branch, so you'll want to get some older code e.g. this release tag:

The main repo is here, and you can see the workaround in XPI/lib/main.js on the latest master branch.  It's just manually writing store.json on its own and seems to alleviate the issue.

https://github.com/honestbleeps/Reddit-Enhancement-Suite/


To test, you'll need to revert to before that workaround.  You'll need to revert to this commit or just overwrite main.js with the contents from:

https://raw.github.com/honestbleeps/Reddit-Enhancement-Suite/9ef3a86fa121a41d20e397e35ef2bd1e519f621b/XPI/lib/main.js

Yes, the localStorage abstraction is mildly silly looking - but back when that was put in, it kept code looking consistent across browsers.

repro steps once you have the addon going with cfx run --profiledir=/some/profile/dir:

1) browse to reddit.com

2) at the top right, click the "+" button and type in a shortcut name, hit enter or click "Add"

3) observe the shortcut now shows up as a link on that top bar

4) quit Firefox and restart it in less than 5 minutes.

5) browse back to reddit.com - observe the shortcut is not present.


The same is true of essentially any data that gets saved.  Changing module settings in the console (roll over gear icon, click "settings console", enable/disable modules, etc) often has the same symptom / problem.

Comment 12

[Matteo Ferretti [:zer0] [:matteo]]

I didn't have time to test this bug properly, before I wasn't able to reproduce it. I will following the steps of comment 11 and trying to isolate the issue. I'm keeping the needinfo as reminder to myself.

Comment 13

[Matteo Ferretti [:zer0] [:matteo]]

(In reply to Steve Sobel from comment #11)

> The addon code is here, in the XPI directory (you'll need to run
> makelinks.sh or the gruntfile to hardlink all of the stuff from /lib). 

So, what I did to reproduce the issue was:

1. `git clone https://github.com/honestbleeps/Reddit-Enhancement-Suite.git`
2. enter in the RES folder, execute `./makelinks.sh`
3. overwrite `./XPI/lib/main.js` with `https://raw.github.com/honestbleeps/Reddit-Enhancement-Suite/9ef3a86fa121a41d20e397e35ef2bd1e519f621b/XPI/lib/main.js`
4. execute `cfx run -b /Applications/FirefoxNightly.app -o -p ../myprofile` from './XPI' folder
5. click the "+" button, added a shortcut ("foo" with "it's foo!" as label)
6. the shortcut now shows up as a link on the topbar
7. quit Firefox by pressing cmd+Q
8. execute `cfx run -b /Applications/FirefoxNightly.app -o -p ../myprofile` from './XPI' folder
9. browse back to reddit.com – the topbar shows "it's foo" as before

So, I'm not able to reproduce the error.
Please Steve, let me know if I missed something in the steps above, or we have done something different.
The version of Nightly I used: 31.0a1 (2014-04-06)

Comment 14

[Steve Sobel]

Hi Matteo, first of all thanks for taking some time out to test it!

The reason you're not seeing that issue replicated is likely due to the timing (assuming recently) of when you cloned RES from its github repo.  We put in a workaround to manually write store.json ourselves, and you've likely got that code in your clone!

you'll see XPI/lib/main.js has a fix provided by one of our contributors here:

https://github.com/honestbleeps/Reddit-Enhancement-Suite/commit/1c78c1d39ef825ac25591bf1ddca1a378d7f8d5c

if you roll back the file to any commit before that, or just revert that specific fix, you should see the issue. I should've updated this bug with a note to that effect, sorry!

Comment 15

[Matteo Ferretti [:zer0] [:matteo]]

(In reply to Steve Sobel from comment #14)

> Hi Matteo, first of all thanks for taking some time out to test it!

> The reason you're not seeing that issue replicated is likely due to the
> timing (assuming recently) of when you cloned RES from its github repo.  We
> put in a workaround to manually write store.json ourselves, and you've
> likely got that code in your clone!

Hi Steve, as described in step 3, I replace the main.js file with the one you mentioned in comment 11:

<https://raw.github.com/honestbleeps/Reddit-Enhancement-Suite/9ef3a86fa121a41d20e397e35ef2bd1e519f621b/XPI/lib/main.js>

Is it correct? It uses the proper `simple-storage`, so I assumed it was correct. But still, following the steps I listed, the `simple-storage` works as expected.

> 
> you'll see XPI/lib/main.js has a fix provided by one of our contributors
> here:
> 
> https://github.com/honestbleeps/Reddit-Enhancement-Suite/commit/
> 1c78c1d39ef825ac25591bf1ddca1a378d7f8d5c
> 
> if you roll back the file to any commit before that, or just revert that
> specific fix, you should see the issue. I should've updated this bug with a
> note to that effect, sorry!

Comment 16

[Steve Sobel]

my apologies, I skimmed too quickly... embarrassing.

what you did seems correct - I wonder if it's been fixed in 30.* at this point.  I will say that the issue seemed more common/prevalent on Windows than OSX, and I'm guessing based on your folder structure you're in OSX?

Comment 17

[Matteo Ferretti [:zer0] [:matteo]]

(In reply to Steve Sobel from comment #16)

> my apologies, I skimmed too quickly... embarrassing.
> 
> what you did seems correct - I wonder if it's been fixed in 30.* at this
> point.  I will say that the issue seemed more common/prevalent on Windows
> than OSX, and I'm guessing based on your folder structure you're in OSX?

Yes, I'm on OS X. I tried five times in different condition, but always under 5 minutes, without any results. If you have a way to reproduce it consistently, please let me know. The only way I was able to avoid the SDK to store the data in `simple-storage`, was quit the execution of cfx instead of Firefox (so, from the terminal where I had `cfx run` executed, press ctrl+c, instead of closing the browser properly with cmd+q).

Comment 18

[Matteo Ferretti [:zer0] [:matteo]]

Steve, if bug 893276 won't be reverted, could you try if you have the same issue now, on Windows, using the master repo?

Now we should write simple-storage data not every 5 mins, but when the data is actually changed.
That, as side effect, should fix your issue too.
Even if I wasn't able to reproduce the issue on OS X, I can imaging that the writing on disk is not guaranteed, if we write asynchronously: we could have some condition where the quitting of Firefox happens before the data is actually stored on the FS.

Let me know!

Comment 19

[Steve Sobel]

Thanks for the response, Matteo - I'll give it a try as soon as I'm able, might be a bit of time as I'm a little swamped with work!

Comment 20

[Matteo Ferretti [:zer0] [:matteo]]

Unfortunately it seems that bug 893276 was reverted, so you can't test that yet, Steve.
I made this bug depends of bug 893276 in the meantime.

Comment 21

[Tomislav Jovanovic :zombie]

hey Dave, see my bug 973750 comment 10. if my hunch is correct, i don't think recent changes to simple-storage in bug 893276 would affect this, as that only makes us write out *less* often, not more.

since this is a significant thing (data-loss) and since none of us is able to reproduce this, it might be a good idea to instrument some sdk code for Steve to test out for us, to detect what is happening. i'm volunteering to do it, but i'm not sure exactly what is the best way. 

agree? ideas?

Comment 22

[Matteo Ferretti [:zer0] [:matteo]]

(In reply to Tomislav Jovanovic [:zombie] from comment #21)
> hey Dave, see my bug 973750 comment 10. if my hunch is correct, i don't
> think recent changes to simple-storage in bug 893276 would affect this

Yeah, we discussed that on Tuesday. I misunderstanding the Mossop's patch there, I thought it was going to fix the flow too (see below).

> since this is a significant thing (data-loss) and since none of us is able
> to reproduce this, it might be a good idea to instrument some sdk code for
> Steve to test out for us, to detect what is happening.

As Irakli noted in bug 893276, our implementation has "maybe saves on shutdown" flow, so it seems not guaranteed in every circumstance.

> i'm volunteering to
> do it, but i'm not sure exactly what is the best way.

Do you have Windows? It seems that it's more reproducible on that OS. If it's the case, do you have already tried the full steps in comment 11 / comment 13? Any luck?

Comment 23

[Dave Townsend [:mossop]]

(In reply to Matteo Ferretti [:matteo] [:zer0] from comment #22)
> (In reply to Tomislav Jovanovic [:zombie] from comment #21)
> > hey Dave, see my bug 973750 comment 10. if my hunch is correct, i don't
> > think recent changes to simple-storage in bug 893276 would affect this
> 
> Yeah, we discussed that on Tuesday. I misunderstanding the Mossop's patch
> there, I thought it was going to fix the flow too (see below).
> 
> > since this is a significant thing (data-loss) and since none of us is able
> > to reproduce this, it might be a good idea to instrument some sdk code for
> > Steve to test out for us, to detect what is happening.
> 
> As Irakli noted in bug 893276, our implementation has "maybe saves on
> shutdown" flow, so it seems not guaranteed in every circumstance.

The only case I can see where we wouldn't save on shutdown is when we're over quota. And we'll never save in that case. Now if the application is crashing before shutdown completes that might explain what is going on here.

Comment 24

[Dave Townsend [:mossop]]

(In reply to Tomislav Jovanovic [:zombie] from comment #21)
> hey Dave, see my bug 973750 comment 10. if my hunch is correct, i don't
> think recent changes to simple-storage in bug 893276 would affect this, as
> that only makes us write out *less* often, not more.
> 
> since this is a significant thing (data-loss) and since none of us is able
> to reproduce this, it might be a good idea to instrument some sdk code for
> Steve to test out for us, to detect what is happening. i'm volunteering to
> do it, but i'm not sure exactly what is the best way. 
> 
> agree? ideas?

Just adding some logging messages to the various points in the attempt to write would at least indicate how far we're getting. This could be anything from a bad disk to faulty file permissions

Comment 25

[Matteo Ferretti [:zer0] [:matteo]]

(In reply to Dave Townsend [:mossop] from comment #23)

> > As Irakli noted in bug 893276, our implementation has "maybe saves on
> > shutdown" flow, so it seems not guaranteed in every circumstance.

> The only case I can see where we wouldn't save on shutdown is when we're
> over quota.

I thought the FS operations where async. If they're async, how they can be blocking? I thought that was what Irakli was talking about, but maybe I got it wrong.
Irakli, what do you meant with bug 893276 comment 24?

> crashing before shutdown completes that might explain what is going on here.

Mhm, in that case should be reported somewhere.

Steve, maybe you could also check if in the Event Viewer (on Windows) is there any anomalies when you quit Firefox, and the data is not saved. If it somehow crashes, it should be reported there.

Of course Firefox needs to quit normally. As mentioned in comment 17, if `cfx run` is terminated by press ctrl+c, the data it won't be saved.

Comment 26

[Dave Townsend [:mossop]]

(In reply to Matteo Ferretti [:matteo] [:zer0] from comment #25)
> (In reply to Dave Townsend [:mossop] from comment #23)
> 
> > > As Irakli noted in bug 893276, our implementation has "maybe saves on
> > > shutdown" flow, so it seems not guaranteed in every circumstance.
> 
> > The only case I can see where we wouldn't save on shutdown is when we're
> > over quota.
> 
> I thought the FS operations where async. If they're async, how they can be
> blocking? I thought that was what Irakli was talking about, but maybe I got
> it wrong.
> Irakli, what do you meant with bug 893276 comment 24?

We can double check but I believe that async operations keep the process alive until they complete.

Comment 27

[Irakli Gozalishvili [:irakli] [:gozala] [@gozala]]

(In reply to Dave Townsend [:mossop] from comment #26)
> (In reply to Matteo Ferretti [:matteo] [:zer0] from comment #25)
> > (In reply to Dave Townsend [:mossop] from comment #23)
> > 
> > > > As Irakli noted in bug 893276, our implementation has "maybe saves on
> > > > shutdown" flow, so it seems not guaranteed in every circumstance.
> > 
> > > The only case I can see where we wouldn't save on shutdown is when we're
> > > over quota.
> > 
> > I thought the FS operations where async. If they're async, how they can be
> > blocking? I thought that was what Irakli was talking about, but maybe I got
> > it wrong.
> > Irakli, what do you meant with bug 893276 comment 24?
> 
> We can double check but I believe that async operations keep the process
> alive until they complete.

Could it be that this is what has changed with Firefox 27 ?

Comment 28

[Tomislav Jovanovic :zombie]

(In reply to Matteo Ferretti [:matteo] [:zer0] from comment #22)
> Do you have Windows? It seems that it's more reproducible on that OS. If
> it's the case, do you have already tried the full steps in comment 11 /
> comment 13? Any luck?
i didn't try with those steps, but i tried to reproduce when it was first reported, without luck.

and there were other reports on irc, but only from addon developers reporting that addon _users_ are loosing data (less than 2% of them), so he being able to reproduce seems like a lucky break to me.


(In reply to Dave Townsend [:mossop] from comment #24)
> Just adding some logging messages to the various points in the attempt to
> write would at least indicate how far we're getting. 
sounds good, i'll do that.

> This could be anything from a bad disk to faulty file permissions
it's reproducible, and writes after a 5 minute wait, so i doubt this is that.


(In reply to Dave Townsend [:mossop] from comment #23)
> Now if the application is crashing before shutdown completes that might 
> explain what is going on here.

(In reply to Irakli Gozalishvili [:irakli] [:gozala] [@gozala] from comment #27)
> > We can double check but I believe that async operations keep the process
> > alive until they complete.
> 
> Could it be that this is what has changed with Firefox 27 ?

i'm pretty sure i've seen reports of not writing on addon disable/unload (not exit), so it doesn't look like this is the issue.

Comment 29

[Steve Sobel]

for what it's worth, I'm still having this same problem with FF29 and addon SDK 1.6.

I even tried using a fresh/new profile folder via cfx run -p C:\storagetest

A couple observations, though they've been made before already:

- data persists in my extension between page loads, etc, despite store.json not updating on disk (so it's being updated in memory just fine - it's just not being persisted)

- using a 5 minute timer, running "cfx run", and then simply watching the store.json file by typing "dir" now and then shows that right around the 5 minute mark, store.json does get updated.


Incidentally, not sure if it's related but I also can't seem to set javascript strict warnings to false in about config anymore. it doesn't persist.

I found nothing abnormal in the Windows event viewer under any of the above tests / circumstances.

Comment 30

[Steve Sobel]

apologies for 2 quick notes in a row here, but I just remembered to test in Aurora (currently 31.0a2) and the problem seems gone!

so, I downloaded and tried out beta (30.0 is what it reports), and the problem seems gone there as well.

I'm not sure what changed between 29 and 30, but something definitely has!

Comment 31

[Dave Townsend [:mossop]]

Bug 893276 landed in that timeframe. I wouldn't have expected it to help much here but apparently it has so great!

Comment 32

[fdsc]

I don't understand why this bug is assigned to the RESOLVED status. Its still is in FireFox 38.0.5.

Comment 33

[Steve Sobel]

It's true, this bug is not resolved.

I agree that Mozilla should mark it WONTFIX if they won't fix it, but it shouldn't be marked "RESOLVED FIXED"...

Comment 34

[Dave Townsend [:mossop]]

(In reply to Steve Sobel from comment #33)
> It's true, this bug is not resolved.
> 
> I agree that Mozilla should mark it WONTFIX if they won't fix it, but it
> shouldn't be marked "RESOLVED FIXED"...

Sorry but you yourself said it was fixed. I can reopen it but until an engineer is able to reproduce this I don't know that anything will change. A simple testcase that demonstrates it would help a lot.

Comment 35

[Steve Sobel]

my apologies, I've confused this with another bug that is related:

https://bugzilla.mozilla.org/show_bug.cgi?id=1091244

this particular one is fixed. that one is not.

Comment 36

[Dave Townsend [:mossop]]

(In reply to fdsc from comment #32)
> I don't understand why this bug is assigned to the RESOLVED status. Its
> still is in FireFox 38.0.5.

Ok so sounds like this is fixed. If you're still having problems please file a new bug (or look at the one Steve linked to) so it can be tracked. Again though, simple testcases would be much appreciated.