263613 - Unexpected behaviour when max number of cookies per domain is exceeded

Status: RESOLVED DUPLICATE of bug 348008

(Core :: Networking: Cookies, defect)

Description

[Hadrien Nilsson]

User-Agent:       Mozilla/5.0 (Windows; U; Windows NT 5.0; rv:1.7.3) Gecko/20040913 Firefox/0.10.1
Build Identifier: Mozilla/5.0 (Windows; U; Windows NT 5.0; rv:1.7.3) Gecko/20040913 Firefox/0.10.1

On the forum located at http://sky.servermms.org/forum.php?config=trancegoa,
sometimes Firefox loses a cookie after you logged in, which prevents you to use
the forum.

Reproducible: Always
Steps to Reproduce:
1.Close Firefox and restart it
2.Check that you don't have any cookie set for sky.servermms.org. If you have
any, delete them.
3.Go to : http://sky.servermms.org/forum.php?config=trancegoa
   The background is dark blue, you're not logged in.
4.Log with : test-red 123
5.When the message box asks you if the password manager should remember the
password, click "NO"
6.You are now logged as the "test-red" user, the background is red
7.Unlog yourself by clicking on "Se déconnecter" in the bottom right of the
page. The background becomes dark blue again, you're not logged anymore.
8.Log with : test-yellow 123
9.When the message box asks you if the password manager should remember the
password, click "NO".
10.You're now logged as user "test-yellow", the background is yellow.
11.Unlog yourself by clicking on "Se déconnecter" in the bottom right of the
page. The background becomes dark blue again, you're not logged anymore.
12.Log again with: test-red 123
Actual Results:  
The login does not work anymore. You stay unlogged. This is because the forum
expects three cookies to be correctly set:

id_forum (the user id in the forum database)
pseudo_forum (the nickname)
password_forum

But id_forum is not set by Firefox after test-red logged in the second time.

Expected Results:  
Firefox should not lose cookies, so test-red could login correctly the second time.

I made two logs which illustrate the steps to reproduce the bug and to help
debugging.
---
The first log is made with the LiveHTTPHeaders extension. On line 897, you can
see the id_forum cookie set for the second log-in of user "test-red".

On line 918, you can see that id_forum is not sent in the "Cookie: " line of the
HTTP header, though other cookies are sent.
---
The second log is the Gecko cookie log (with "set NSPR_LOG_MODULES=cookie:4").
On line 10733 the second "test-red" login occurs, and the three main cookies
(id_forum, pseudo_forum and password_forum) are set. 

On line 10772 the cookies are sent. Note that the line is trunkated in regards
of the LiveHTTPHeaders log file. None of the main cookies are present. I don't
know if it's a limitation of the cookie log code, or if this is the real line
sent to the server. Anyway in the LiveHTTPHeaders log one of the main cookie was
already missing.
--
Note that this bug could be related to other cookie bugs, like bug 246451, but
here is presented a complete and clean procedure to reproduce the bug, with
debug log files.

Comment 1

[Hadrien Nilsson]

Attachment: HTTP log

Comment 2

[Hadrien Nilsson]

Attachment: Cookie log

Comment 3

[Vincent Robert]

Confirming with :
Mozilla/5.0 (Windows; U; Windows NT 5.1; rv:1.7.3) Gecko/20040913 Firefox/0.10.1

Comment 4

[Hadrien Nilsson]

Confirming with my own Seamonkey build with the latest Mozilla source tarball.

Mozilla/5.0 (Windows; U; Windows NT 5.0; en-US; rv:1.8a5) Gecko/20041013

I am going to try to understand what is happening at the source level.

Comment 5

[Hadrien Nilsson]

I've got a clue :

I'm currently looking into nsCookieService.cpp, nsCookieService::AddInternal
mMaxCookiesPerHost (which is set to 50 by default) is reached when you try to
connect the second time with test-red.

What's happening is that Gecko wants to delete some old cookies in order to make
room for the 3 new login cookies (id_forum, pseudo_forum and password_forum).

Unfortunately the candidate cookies for deletion are one of those 3 freshly
added cookies, instead of the old ones. I sill have to understand why this is
happening.

Comment 6

[Hadrien Nilsson]

I added some trace functions into the code, in the nsCookieService::AddInternal
function. The traces inside this function occur in 3 steps :

- a dump of the internal cookie list before adding the new cookie ;
- a dump of the internal cookie list after a possible remove of the last
accessed cookie ;
- a dump of the internal cookie list after adding the new cookie.

Here are pieces of traces :

Context : id_forum has just been set, now pseudo_forum is about to be set.

Adding this cookie :
pseudo_forum=test-red on sky.servermms.org path=/
    LastAccessed=1097778225 Creation=0 Expiry=177, 

nsCookieService::AddInternal BEFORE REMOVE
--------------------
////////////////// CookieDump at 1097778225
id_forum=2844 on sky.servermms.org path=/
    LastAccessed=1097778225 Creation=0 Expiry=176, 
pass_cat_9399_5= on sky.servermms.org path=/
    LastAccessed=1097778225 Creation=0 Expiry=171, 
pass_cat_9399_4= on sky.servermms.org path=/
    LastAccessed=1097778225 Creation=0 Expiry=170, 
pass_cat_9399_3= on sky.servermms.org path=/
    LastAccessed=1097778225 Creation=0 Expiry=169, 
pass_cat_9399_2= on sky.servermms.org path=/
    LastAccessed=1097778225 Creation=0 Expiry=168, 
... and so one

nsCookieService::AddInternal AFTER REMOVE
////////////////// CookieDump at 1097778225
pass_cat_9399_5= on sky.servermms.org path=/
    LastAccessed=1097778225 Creation=0 Expiry=171, 
pass_cat_9399_4= on sky.servermms.org path=/
    LastAccessed=1097778225 Creation=0 Expiry=170, 
pass_cat_9399_3= on sky.servermms.org path=/
    LastAccessed=1097778225 Creation=0 Expiry=169, 
pass_cat_9399_2= on sky.servermms.org path=/
    LastAccessed=1097778225 Creation=0 Expiry=168, 
pass_cat_9399_1= on sky.servermms.org path=/
    LastAccessed=1097778225 Creation=0 Expiry=167, 
pass_cat_iut_1= on sky.servermms.org path=/
    LastAccessed=1097778225 Creation=0 Expiry=166, 
pass_cat_f_1= on sky.servermms.org path=/
... and so on

Here you can see that the cookie "id_forum" has been chosen for deletion. The
access time for id_forum is the same than older cookies maybe because they were
sent just before those requested to be set by the server (check line 878 in the
http log).

The goal would be to choose better candidates for deletion, like the latest
pass_cat_* cookie.

The change may occur in nsCookieService::CountCookiesFromHost, where the last
accessed cookie is searched. Here are some ideas for a correct behaviour, I mean
a way to chose a better candidate for deletion (no thoughts yet about the best
solution) :
- make the comparison with the last accessed time AND the expiry time. If two
cookies have the same LastAccess time, choose the one whose expiry time is the
smallest. Not sure that is a sensible choice though.
- if several cookies have the same access time, chose the last one in the list.
I'm not sure of the creation order in the list.
- add an int to the cookie structure which tells if the cookie has just been
created, and the order of creation. This int would be set to 0 after it is sent
back to the server. So if this int is not 0, it should not be a candidate for
deletion. If the number of freshly created cookies exceeds mMaxCookiesPerHost,
this int could be use to choose the oldest cookie freshly created.
- an int as in the solution before, but it would not be set to 0 when sent. This
int would be incremented for each cookie whenever a new cookie is added. If room
is needed, this "creation time int" would be used to choose a candidate for
deletion.

Maybe one have more solutions... For those I'm thinking about I've not decided
which is the best suitable.

Comment 7

[Hadrien Nilsson]

I chose the second solution. The change is minor and the bug does not appear
anymore as far as I tested. I'll attach a patch.

Comment 8

[Hadrien Nilsson]

Attachment: patch implementing the second solution

Comment 9

[Hadrien Nilsson]

By the way, I think it would be a good idea to warn the user/developer about the
max cookie number reached in the JavaScript console. I'm thinking about opening
a new bug for this suggestion.

Comment 10

[Hadrien Nilsson]

I tested with the latest nightly and the bug is still there.
Mozilla/5.0 (Windows; U; Windows NT 5.0; en-US; rv:1.8b2) Gecko/20050517

Meanwhile, the forum deleted the test users. Moreover, the test was a bit tough
to execute there. So I created a simple and lean test which shows the problem :

http://psydk.org/gecko-bugs/too-much-cookies/

In IE and Opera, no problem. In Gecko, old cookies are not replaced by newer
ones when many cookies are set in a row.

Comment 11

[Hadrien Nilsson]

Changing the Product type to "Core" as this bug appears to be more general.
Changing the summary too and the URL for the testcase.

Here is a summary of the test case :

Let the limit of cookies set per domain be 5. Let the number of cookies set by a
domain be 10.

The cookies stored we expect to have are :
- cookie06
- cookie07
- cookie08
- cookie09
- cookie10

Current result :
- cookie01
- cookie02
- cookie03
- cookie04
- cookie10

When we trace into the code, one can discover that the behaviour goes like that
as the cookies are stored :

TIME ----->
- cookie01 - cookie01 - cookie01 - cookie01 - cookie01 - cookie01
- cookie02 - cookie02 - cookie02 - cookie02 - cookie02 - cookie02
- cookie03 - cookie03 - cookie03 - cookie03 - cookie03 - cookie03
- cookie04 - cookie04 - cookie04 - cookie04 - cookie04 - cookie04
- cookie05 - cookie06 - cookie07 - cookie08 - cookie09 - cookie10

We expect a roll-over as in other browsers :

TIME ----->
- cookie01 - cookie06 - cookie06 - cookie06 - cookie06 - cookie06
- cookie02 - cookie02 - cookie07 - cookie07 - cookie07 - cookie07
- cookie03 - cookie03 - cookie03 - cookie08 - cookie08 - cookie08
- cookie04 - cookie04 - cookie04 - cookie04 - cookie09 - cookie09
- cookie05 - cookie05 - cookie05 - cookie05 - cookie05 - cookie10

Note that we are talking about a behaviour when the 10 cookies are set at the
same time.

Comment 12

[[e-mail]]

thanks for the detective work and the patch here! i'm duping this against bug 348008 which is the same issue; this was actually fixed by the checkin for bug 230933, which added a creation time field to each cookie and now evicts based on that.