Closed Bug 1221480 Opened 9 years ago Closed 8 years ago

BMO login being reset for every browser session

Categories

(bugzilla.mozilla.org :: General, defect)

Product:
bugzilla.mozilla.org
Component:
General
Version:
Production
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

()

Status:
RESOLVED DUPLICATE of bug 1239671

People

(Reporter: Gijs, Assigned: dylan)

References

Details

Bug 1202281 does not seem fixed for me on my Windows machine. I keep having to re-login that session. My mac just goes to sleep overnight, so Firefox stays up, so that session keeps working. But the Windows one (where the machine is shut down overnight) is always dead the next day.
No longer blocks: 1202281
Depends on: 1202281
According to devtools' commandline "cookie list",


Bugzilla_logincookie: Expires: 25/01/1970, 21:05:16

that doesn't sound right? Like there's a multiplication factor of 1000 or something missing from the cookie expiry time.
It appears our session cookie is set to expire in 2038, which might be the 32bit time_t thing (https://en.wikipedia.org/wiki/Year_2038_problem).

The date in question is "01-Jan-2038 00:00:00 GMT" so it's probably not *precisely* that problem. I think it's safe to adjust the expirey date down to a more reasonable value.
Assignee: nobody → dylan
i hit this today, and grabbed some more data.  i was able to reproduce this problem for a brief period of time before the following STR stopped working (or, if you prefer, things started working again).

using firefox 45.0a2 (2016-01-05) on osx.

- logged in to bugzilla, with Bugzilla_logincookie:"jshS*" expires:"01/01/2038, 8:00:00 am"
- quit and reopened, 'restore previous session'
- the restored show_bug page's html was showning as logged in, however storage manager told me a different story
- the Bugzilla_logincookie value was gone, replaced with: Bugzilla_logincookie:"iqd9*" expires:"Session"
- this second cookie didn't exist in bmo's logincookies table (the first one still existed)

after a few iterations of quit/restore, the Bugzilla_logincookie's value and expire stopped being altered, and now i'm back with a non-expiring session again.

to me this smells like a session restore bug in firefox.
I've been hitting this for the last week or so with Nightly on OS X. I'm in a sec. group and therefore need to use 2FA. I have many pinned BMO tabs too. I initially thought this was an intentional change for people in a sec. group but after getting annoyed enough I was pointed here.
Marco, any idea why this would be? Is this just how we store things in the sqlite thing we use for cookies? Can we fix this on the Firefox side as well? (please feel free to forward the needinfo to someone more appropriate if you know of someone :-) )
Flags: needinfo?(mak77)
(In reply to :Gijs Kruitbosch from comment #5)
> Marco, any idea why this would be?

Sorry, but I honestly don't know off-hand.
Looks like something is storing different data through the cookies manager API, rather than the storage layer changing data by itself. Afaict everything on the storage layer is using int64_t and expiry is in seconds, so it seems unlikely to suffer from 2038 overflow. Also the API takes seconds, so we can likely exclude a js problem with representing 64bit integers.
I don't think there's someone specifically working on cookies nowadays, likely may try to ask someone in netwerk (Patrick McManus maybe?) or we should just figure this out by ourselves.

If someone can reproduce "easily", he may try to get some logging, NSPR_LOG_MODULES=cookie:5,mozStorage:5 (along with NSPR_LOG_FILE) may get the whole story, but it could be quite verbose. Probably worth starting with just cookie logging and then can be enlarged to storage if needed.
Flags: needinfo?(mak77)
Just an idea but perhaps bug 1244505 is related?
(In reply to Matthew N. [:MattN] from comment #7)
> Just an idea but perhaps bug 1244505 is related?

good to know, but bugzilla's cookies don't have spaces in them, and that doesn't explain why it's intermittent.
Seems drno has been hitting this as well; maybe he can provide some info too.
What I'd like to do Bugzilla-side is more logging of invalid logincookie events.

Things we'd like to be able to know:

- user sent a logincookie and does not exist
- user sent a logincookie and it used to exist, but doesn't now

the later part would require storing expired logincookies (at least for a time).
I have had this issue for quite some time now as well. Also though that might be a super secure feature, because I have 2FA turned on.
For me the problem always came up after hitting the "restart to update" button. I'm on Mac Fx 46 2016-02-10 right now. Not sure if I had the problem already on 45.

Based on the previous comments I took a look at the 'cookie list' as well, and noticed similar to :Gijs comment #1:
- all my BMO had an expiry value of 1/25/1970, 12:05:16 PM (day and time in January varied) set (FYI the about:preferences#privacy cookie removal page renders these dates all as 31st of December 2037 or later - so the 1970 is probably some kind of conversion bug in the developer console?). The only exception to that was the Bugzilla_login_request_cookie which was had its expiry set to 'At browser exit (session)'

In an attempt to repro the problem I just quit and restarted my Firefox (not through the 'About Firefox' dialog this time, because there was not new build available yet) and as everyone would guess: the problem did not repro this time.

But when checking my 'cookie list' after the restart suddenly all the 'Bugzilla_login*' cookies plus a few more have expiry set to 'At browser exit (session)'. A few probably not so important BMO cookies are still left with the 2037/1970 values, but non of the login related once.

My guess is that this manual quit and restart has somehow magically "fixed" the expiry values of the relevant cookies and the problem is now gone for me. I'll wait for the next DE build and report back if I repro the problem then again.
Looks like I claimed to early that the problem did not repro after the manual restart, which was based on the fact that the top of the BMO page stilled showed my bugzilla login. Where before after the update restart the upper right corner showed me the "New account/Login/..." thing.

But when I hit the "Save Changes" button I was in fact required to login again. As expected the Bugzilla_login cookie value has changed again after login. I have screen shots of all three cookies (before manual restart, after restart and after BMO login) if that helps anyone to figure out what is going on here.

Another thing maybe worth mentioning is that I have the option "Restrict login to this IP address" (or whatever the precise wording is) set on the login page. I remember seeing that option the first time I encountered the problem and after hitting enter on the login page regretting that I did not un-check that box, because I move with this laptop on a daily base between home and the office. So I expected that option to cause me pain.
But since that first login all further re-login where through the little login dialog in the upper right corner of show_bug page. As that dialog does not offer the IP restriction option I never unset the option since then.
Maybe that IP restriction option is causing the trouble for me?
I looked at your login cookies and they did not seem to have the IP restriction set. Thank you for the valuable debugging info!
Depends on: 1247584
So with today new build of DE I was able to repro the problem actually again:

- clicked on 'About Firefox' in my 46 on Mac
- clicked 'Restart to Update'
- once Firefox restart all my BMO tabs re-open with "New Account| Log In| Forgot Password" in the upper right corner

Now I took a snapshot of my BMO cookies before and after the restart:
- the Bugzilla_login cookie changed its expiry from 1970/2037 to 'At browser exit', but the content stayed the same
- the Bugzilla_logincookie also updated its expiry from 1970/2037 to 'At browser exit' and changed its content
I have not looked at all BMO cookie, but these are the only two cookie in my screen shot which have changed.
(In reply to Nils Ohlmeier [:drno] from comment #14)
> So with today new build of DE I was able to repro the problem actually again:

are you able to set the env vars as per comment 6 so we can capture what's going on?
(In reply to Byron Jones ‹:glob› from comment #15)
> are you able to set the env vars as per comment 6 so we can capture what's
> going on?

Sorry I must have overlooked that requests.

Yes I was able to get the NSPR log file. But I'm not keen on attaching it here, because it happens with my main profile with tons of open tabs. So the logs contain tons of cookies and sensitive information.

I guess the question is: how can I filter the logs down before sharing them?

From reading through the logs myself here are a couple of observations:

I see these lines shortly after startup:

46415872[12e151f50]: Initialized statement 'DELETE FROM moz_cookies WHERE name = :name AND host = :host AND path = :path' (0x1124b9a00)
46415872[12e151f50]: sqlite3_trace on 138de6030 for 'DELETE FROM moz_cookies WHERE name = 'Bugzilla_login' AND host = 'bugzilla.mozilla.org' AND path = '/''
46415872[12e151f50]: sqlite3_trace on 138de6030 for 'DELETE FROM moz_cookies WHERE name = 'Bugzilla_logincookie' AND host = 'bugzilla.mozilla.org' AND path = '/''
46415872[12e151f50]: sqlite3_trace on 138de6030 for 'DELETE FROM moz_cookies WHERE name = 'bc_pv_end' AND host = '.voip.ms' AND path = '/''

The first question from my side is: is that normal?
Because it looks like my Bugzilla_logincookie gets deleted there. Which then would explain why I'm no longer logged in.

The fun part though is that the log file shows that still a Bugzilla_login cookie with value 'uPJrG2...' gets send to BMO for my open tabs.
As a reload of an open BMO tab showed me as not logged in, I went ahead and logged back in. The log shows that 'github_secret=X' and 'Bugzilla_login_request_cookie=X' both get rejected because of expiry values in 1998. Are these ancient expired cookies expected?

After these two rejected cookie Fx then accepts a new 'Bugzilla_login' cookie, which it then claims replaces an existing cookie. And then it accepts a new 'Bugzilla_logincookie' with the value 'SdEn...' which apparently also replaces an existing cookie.

After this I closed Fx. Moved the log file out of the way and started Fx again. As you can guess the new log file also shows the same DELETE FROM moz_cookies lines as before. Which is then some time later followed by the real fun:
Fx sends for one of my BMO tabs the Bugzilla_logincookie with value 'uPJrG2...'.

So it looks to me like that whenever I start my Fx it keeps on re-using/re-offering an old (?) Bugzilla_logincookie, no matter if that should have gotten replaced by a fresh one in the last session.
mak - are you able to comment on drno's findings?
Flags: needinfo?(mak77)
Note, I'm not a peer of cookies, so I'm a little bit out of my water, but I will try to help with the knowledge I have.

The delete statement can only come from either:
a. PurgeCookies
b. RemoveCookieFromList (that means an explicit call to remove, or set cookie in case a previous one existed but was expired)

I'll first of all assume the purgecookies case, where we could end up expiring cookies that are still valid and not expired, if we hit a given cap (that cap looks very small and I'm not sure why, that's a question for a cookies peer).
Coul you please check:
1. do you have a network.cookie.maxNumber and network.cookie.purgeAge prefs set?
2. how many cookies you have in the moz_cookies table in cookies.sqlite
3. more important, check if the cookies log contains references to PurgeCookies() before the delete

(In reply to Nils Ohlmeier [:drno] from comment #16)
> The fun part though is that the log file shows that still a Bugzilla_login
> cookie with value 'uPJrG2...' gets send to BMO for my open tabs.

Cookie management is complex, having both memory and disk tables, plus child/parent in the e10s case. I can barely help figuring that, we need someone who actually worked on that.

> As a reload of an open BMO tab showed me as not logged in, I went ahead and
> logged back in. The log shows that 'github_secret=X' and
> 'Bugzilla_login_request_cookie=X' both get rejected because of expiry values
> in 1998. Are these ancient expired cookies expected?

Maybe it's more a question for :glob.

> Fx sends for one of my BMO tabs the Bugzilla_logincookie with value
> 'uPJrG2...'.

This would make me think something went wrong when the memory data was merged to disk... provided that happened at all.
Flags: needinfo?(mak77)
Flags: needinfo?(drno)
(In reply to Marco Bonardo [::mak] from comment #18)
> [snip]

thanks mak :)

> > As a reload of an open BMO tab showed me as not logged in, I went ahead and
> > logged back in. The log shows that 'github_secret=X' and
> > 'Bugzilla_login_request_cookie=X' both get rejected because of expiry values
> > in 1998. Are these ancient expired cookies expected?
> 
> Maybe it's more a question for :glob.

yes - both of those cookies are for unauthenticated users and iirc are created as session cookies.
the only cookie we need to pay attention to is Bugzilla_logincookie.
(In reply to Marco Bonardo [::mak] from comment #18)
> Coul you please check:
> 1. do you have a network.cookie.maxNumber and network.cookie.purgeAge prefs
> set?
Nope. None (neither user set nor default). The only user set value under network.cookie is network.cookie.prefsMigrated.

> 2. how many cookies you have in the moz_cookies table in cookies.sqlite
Looks like 2805 right now, after logging in to BMO again.

> 3. more important, check if the cookies log contains references to
> PurgeCookies() before the delete
Nope.
There are couple of lines like this:
  cookie rejected because stale cookie was purged
But they are all related to cookies from other open tabs, not related to BMO.
 
> Cookie management is complex, having both memory and disk tables, plus
> child/parent in the e10s case. I can barely help figuring that, we need
> someone who actually worked on that.

Not sure if it matters, but I don't use e10s right now. And haven't used it for quite some while.
Flags: needinfo?(drno)
Comparing copies of the cookies.sqlite DB from after a browser restart (due to DE daily update) where I'm not logged in and after re-loggin in to BMO confirms that Bugzilla_login and Bugzilla_logincookie are in fact are missing from the cookies.sqlite in the logged out state. So the DELETE query from the log file appears to successfully remove the needed cookie from my sqlite DB.

Which raises two questions from my side:
A) Why is Fx still sending an (invalid) Bugzilla_logincookie if there is no such cookie in the cookie.sqlite stored?
B) As it looks like it is not PurgeCookies which deletes the BMO cookie, what does? :-)
(In reply to Nils Ohlmeier [:drno] from comment #21)
> A) Why is Fx still sending an (invalid) Bugzilla_logincookie if there is no
> such cookie in the cookie.sqlite stored?

IIRC session restore can store session cookies.  Perhaps it still had the old value? You could see if the problem happens if you don't restore your session: "When Nightly Starts: Show my home page" and restart.
(In reply to Matthew N. [:MattN] from comment #22)
> IIRC session restore can store session cookies.  Perhaps it still had the
> old value? You could see if the problem happens if you don't restore your
> session: "When Nightly Starts: Show my home page" and restart.

Thanks for the suggestion. Yes if I disable session restore the problem disappears and I stay logged in after a Fx restart (manual restart as well as the version update restart).

So who can help me debug why session restore thinks it needs to delete my existing BMO login cookie from sqlite and replace it with a older version of its own?
We lost a few people in this area in the last year to other teams… I think Yoric may be one of the few left who has touched this stuff recently.

Perhaps try enable browser.sessionstore.debug and look in the Browser Console for more ideas?
Flags: needinfo?(dteller)
You can also look at the contents of your %profD%/sessionstore-backups/recovery.js file after shutdown.
I guess ttaubert is still reviewing patches
So that old BMO login cookie 'uPJrG2...' shows up in %profD%/sessionstore.js and all file in %profD%/sessionstore-backups/*.

Did not notice anything useful on the browser console after setting browser.sessionstore.debug.

Not sure, but I'm going to assume that it is normal/intended that cookie content from sessionstore.js super seeds the content of cookies.sqlite on startup (which would explain the DELETE query).
But then the real question is: why doesn't the new BMO login cookie (after I login again) overwrite the old cookie and gets written out to the next sessionstore.js?

Any advice on how to debug this further is highly appreciated :)
You could take a look at browser/components/sessionstore/SessionCookies.jsm and add a few dump() statements in the observers. This file listens for notifications from the cookie service and uses those to store cookies. Maybe we're ignoring a notification? Maybe we don't receive it?
This of course requires testing with a custom build. Should be easy to do if you just make a copy of your main profile and use that for testing.
The specialist of session cookies remains ttaubert. So if anyone can provide nuggets of wisdom, that's him.
Flags: needinfo?(dteller)
Looks like bug 1239671 has a patch.
Status: NEW → RESOLVED
Closed: 8 years ago
Resolution: --- → DUPLICATE
You need to log in before you can comment on or make changes to this bug.