Error: Too late to set another cookie

[dagolden]

Reported by @knutov

After updating to the new version (0.17 after 0.15) I've got Too late to set another cookie, headers already built at /usr/local/share/perl/5.14.2/Dancer/Response.pm line 170. in most of my projects. After downgrading to 0.15 everything is fine again, so it looks like something broken in new version.

[dagolden]

@knutov, what version of Dancer are you running?

[knutov]

for history: https://gist.github.com/knutov/4957111

the problem looks solved (but not well tested) after changing

$data->{loginErrorAuth} = 1 if session('login') == 1;

to

$data->{loginErrorAuth} = 1 if session('login') and session('login') == 1;

In my test case session('login') is not defined: return Dumper(session); returns

$VAR1 = bless( { 'id' => '630082380279428981007578217773082184', 'login' => undef }, 'Dancer::Session::Cookie' );

return Dumper(session('login')); returns

$VAR1 = undef;

I have no idea why D:S:Cookie trying to write something in this case.

[dagolden]

I'm confused. "solved" in your code? I don't see how that example should affect anything. Even with login equal to undef, it should be writing that out in the session. But I can't see how that affects order.

Do you have some serialization engine running? I'm trying to think of anything that would build the headers and I'm stumped.

[dagolden]

Diving through code, this seems like it could be something to do with continuations, but my simple testing with 'forward' hasn't provoked the same issue. I also can't really see why the prohibition on cookies being added "too late" -- or at least, I'm pretty sure an after hook is never too late and whenever an after hook is called, there's a new request anyway.

In Dancer::Response, build_cookie_headers always runs on demand and there's no caching, so there's no reason stop accepting cookies.

It's possible that Dancer::Session::Cookie will have to do some other monkeypatching but I don't want to start hacking on it until I have a test case I can replicated.

[knutov]

Yes, the problem was solved after changing my code. And I don't understand why this change affect this way either.

I created minimal code to test by deleting all other code from project - http://f2.knutov.com/satestcookie.tgz

mkdir ~/testcookie && cd ~/testcookie
wget http://f2.knutov.com/satestcookie.tgz
tar xzf satestcookie.tgz
cd satestcookie
./run.sh

and go to http://localhost:5027

May be important (or may be another bug) - when testing some other projects with nearly the same code (my authorization code usually copy-pasted to every new project) I didn't see the error "Too late to set another cookie, headers already built" but had redirection loops instead in some different places. This happens after upgrading from D:S:Cookie from 0.15 to 0.17 and without any other changes. In all cases everything works fine after downgrading to 0.15. Still trying to find the clear way to reproduce this bug.

[knutov]

Btw, this can be a bug not in D:S:Cookie but in Dancer. I can upgrade D:S:Cookie and downgrade Dancer to some old version, but have no ideas on which version to try.

[knutov]

@dagolden, can you confirm reproducing the problem with my minimal code?

[dagolden]

On Fri, Feb 15, 2013 at 12:59 PM, Nick S. Knutov notifications@github.comwrote:

@dagolden https://github.com/dagolden, can you confirm reproducing the problem with my minimal code?

I haven't had a chance yet, sorry.

David Golden dagolden@cpan.org Take back your inbox! → http://www.bunchmail.com/ Twitter/IRC: @xdg

[dagolden]

Yes, I can reproduce it. I'm going to try to adapt that into a test file and explore a fix.

[dagolden]

I've released a fix. It's an awful hack, but appears to work. Let me know if that fixes your issues.

[knutov]

Big thanks, this issue looks solved, but module behavior still breaks old code.

change to the old example:

any '/login/?' => sub {
    return redirect '/' if session('uid');

    return 'ok' if session('login') == 1;

    debug 123 if session('login') ==123;
    my $loginErrorAuth = 1 if session('login') == 1;
    my $loginErrorUser = 1 if session('login') == 2;

    session 'login' => undef;
    return 'login page';
};

and I have

Warning caught during route execution: Use of uninitialized value in numeric eq (==) at .../satestcookie/lib/sandbox.pm line 27.

Line 27 is my $loginErrorUser = 1 if session('login') == 2;. Strange are two things: 1) with 0.15 there was no error at all. 2) error points on 4th string with session('login') while it's ==undef in all 3 previous calls too. Can't understand it.

[dagolden]

That's pretty strange.

Other than giving a warning, I'm not sure how that's broken. If you're checking an undef value, you get a warning.

David

[knutov]

I rewrote code to always check defines before and after a lot of tests it looks like the problem solved.

Loop redirects can happen in code with redirects after authorization when different apps runned with the same session name on one domain (localhost) but different ports. So I looked at the code and found session_name in changelog for 0.15. This param is not mentioned at documentation, but making unique session names solves the problem. It is a little bit strange - I thought dancer should just replace cookie if it can't decode it (and everything works for me with 0.15 without changing session names).

[dagolden]

Were the different apps using different secret keys?

I hadn't thought about forcing cookie deletion if the decoding fails. Generally, I've been trying to avoid creating empty sessions by default, so possibly that optimization meant that bad cookies weren't forceably expired.

I'll have to think about that more.

David

[knutov]

although, even with one app and not changing session_name I some times got redirect to /login/ after this code in hook before

    if ( !session('uid') 
        && request->path_info !~ m{^/login} 
        && request->path_info !~ m{^/api} 
    ) {
        session 'requested_path' => request->path_info;
        return redirect '/login/';
    }

It's hard to reproduce. In get '/login/' I do session 'uid' => 123; after authorization and check it in hook before as sign of logged user. Later I can refresh one page multiple times or go between different pages (non of them are clearing uid) and periodically I have no session('uid'). I can refresh the same page again after it and everything can be ok - session('uid') exists again.

Can it be because of using Sereal in new versions of D:S:Cookie?

[knutov]

Did minimal example to reproduce.

mkdir ~/testcookie && cd ~/testcookie
wget http://f2.knutov.com/satestcookie2.tgz
tar xzf satestcookie2.tgz
cd satestcookie2
./run.sh

go to http://localhost:5027/login. Will be redirect to /ok after. Now hit F5 (or ctrl+r) multiple times and usually everything will be ok, but some times you will see something like

runtime error
$VAR1 = bless( {
                 'id' => '142569256822871765099591968615720122'
               }, 'Dancer::Session::Cookie' );

Number of refreshes can be different. If it do not comes long time - you can /logout and /login again.

After die occurs you can refresh the page again. Some times die will happen again, some times all will be ok.

Have no ideas how it can be connected, but in my projects it usually happens every 3-4-5 refreshes. In this minimal examples it can happen only after 10 or 20 or even more refreshes.

[knutov]

Even better:

change to the last archive (and for human readable preview):

hook 'before' => sub { 
    die Dumper(session) if not session('uid') and not request->path_info =~ m{^/log} ;
};

get '/' => sub {
    return redirect '/login' unless session('uid');
    # return Dumper(session) if not session('uid');
    # return 'root';
};

get '/ok' => sub {
    return session('id')."
        ok, <br>
        may be you want to <a href='/logout'>logout</a>
    ";
};

get '/login' => sub {
    session 'uid' => 123;
    return redirect '/ok';
};

get '/logout/?' => sub {
    session 'uid'     => undef;
    session->destroy;
    return redirect '/';
};

So it is possible to see session id-s for all cases.

When ok I'm getting 333899998582388695312458877727539952 ok, may be you want to logout When not - session id usually is different. For all page refreshes there only two id's. One shows when ok and both can be showed when die occurs.

[knutov]

Were the different apps using different secret keys?

Yes, apps uses different session_cookie_key

[dagolden]

If you had session_expiration set, there was a bug that was fixed in 0.19.

[knutov]

The problem still exists with the last code example ( http://f2.knutov.com/satestcookie3.tgz ) and 0.19.

And I'm not using session_expiration as previous versions (before 0.15 I think) did not have this feature.

[knutov]

@dagolden , did you try to reproduce bug with my latest code example? Have you any ideas on what to do with it?

[dagolden]

Sorry Nick. I haven't had chance to look at it yet.

David On Mar 3, 2013 1:49 PM, "Nick S. Knutov" notifications@github.com wrote:

@dagolden https://github.com/dagolden , did you try to reproduce bug with my latest code example? Have you any ideas on what to do with it?

— Reply to this email directly or view it on GitHubhttps://github.com/dagolden/Dancer-Session-Cookie/issues/1#issuecomment-14352250 .

[knutov]

Are you able to reproduce this at least?

[dagolden]

Thanks for the reminder. I've still be really overloaded with work and family stuff and haven't had a chance to get to my bug tickets. Sorry.

[knutov]

The problem still exists with the latest Dancer 1.3112, so I think it's definitely because of some changes in Dancer::Session::Cookie after 0.15.

[dagolden]

This might have been fixed with #5 -- there was a bug when route handlers die. Try the latest release please.

[knutov]

I'm not absolutely sure, but the problem looks solved. I will try to install 0.20 on our production servers.