Welcome Guest, Not a member yet? Register   Sign In
Session Failures
#21

[eluser]theshiftexchange[/eluser]
I've enabled log_threshold to 4 - and I dont see a "index.php" listed anywhere in the logs? Here is part of it:

Code:
DEBUG - 2010-11-06 21:16:27 --> XSS Filtering completed
DEBUG - 2010-11-06 21:16:27 --> Global POST and COOKIE data sanitized
DEBUG - 2010-11-06 21:16:27 --> Language Class Initialized
DEBUG - 2010-11-06 21:16:27 --> Loader Class Initialized
DEBUG - 2010-11-06 21:16:27 --> Helper loaded: url_helper
DEBUG - 2010-11-06 21:16:27 --> Helper loaded: form_helper
DEBUG - 2010-11-06 21:16:27 --> Language file loaded: language/english/tank_auth_lang.php
DEBUG - 2010-11-06 21:16:27 --> Database Driver Class Initialized
DEBUG - 2010-11-06 21:16:27 --> Form Validation Class Initialized
DEBUG - 2010-11-06 21:16:27 --> Session Class Initialized
DEBUG - 2010-11-06 21:16:27 --> Helper loaded: string_helper
DEBUG - 2010-11-06 21:16:27 --> Encrypt Class Initialized
DEBUG - 2010-11-06 21:16:27 --> Session routines successfully run
DEBUG - 2010-11-06 21:16:28 --> Model Class Initialized
DEBUG - 2010-11-06 21:16:28 --> Model Class Initialized
DEBUG - 2010-11-06 21:16:28 --> Config file loaded: config/tank_auth.php
DEBUG - 2010-11-06 21:16:28 --> Model Class Initialized
DEBUG - 2010-11-06 21:16:28 --> Model Class Initialized
DEBUG - 2010-11-06 21:16:28 --> Model Class Initialized
DEBUG - 2010-11-06 21:16:28 --> Model Class Initialized
DEBUG - 2010-11-06 21:16:28 --> Model Class Initialized
DEBUG - 2010-11-06 21:16:28 --> Controller Class Initialized
DEBUG - 2010-11-06 21:16:28 --> Helper loaded: cookie_helper
DEBUG - 2010-11-06 21:16:28 --> File loaded: application/views/forms/general_message.php
DEBUG - 2010-11-06 21:16:28 --> File loaded: application/views/menus/login.php
DEBUG - 2010-11-06 21:16:28 --> File loaded: application/views/layout.php
DEBUG - 2010-11-06 21:16:28 --> Final output sent to browser
DEBUG - 2010-11-06 21:16:28 --> Total execution time: 0.3035
DEBUG - 2010-11-06 21:18:12 --> Config Class Initialized
DEBUG - 2010-11-06 21:18:12 --> Hooks Class Initialized
DEBUG - 2010-11-06 21:18:12 --> URI Class Initialized
DEBUG - 2010-11-06 21:18:12 --> Router Class Initialized
DEBUG - 2010-11-06 21:18:12 --> Output Class Initialized
DEBUG - 2010-11-06 21:18:12 --> Input Class Initialized
DEBUG - 2010-11-06 21:18:12 --> XSS Filtering completed
DEBUG - 2010-11-06 21:18:12 --> Global POST and COOKIE data sanitized
DEBUG - 2010-11-06 21:18:12 --> Language Class Initialized
DEBUG - 2010-11-06 21:18:12 --> Loader Class Initialized
DEBUG - 2010-11-06 21:18:12 --> Helper loaded: url_helper
DEBUG - 2010-11-06 21:18:12 --> Helper loaded: form_helper
DEBUG - 2010-11-06 21:18:12 --> Language file loaded: language/english/tank_auth_lang.php
DEBUG - 2010-11-06 21:18:12 --> Database Driver Class Initialized
DEBUG - 2010-11-06 21:18:12 --> Form Validation Class Initialized
DEBUG - 2010-11-06 21:18:12 --> Session Class Initialized
DEBUG - 2010-11-06 21:18:12 --> Helper loaded: string_helper
DEBUG - 2010-11-06 21:18:12 --> Encrypt Class Initialized
DEBUG - 2010-11-06 21:18:12 --> A session cookie was not found.
DEBUG - 2010-11-06 21:18:12 --> Session routines successfully run
DEBUG - 2010-11-06 21:18:12 --> Model Class Initialized
DEBUG - 2010-11-06 21:18:12 --> Model Class Initialized
DEBUG - 2010-11-06 21:18:12 --> Config file loaded: config/tank_auth.php
DEBUG - 2010-11-06 21:18:12 --> Helper loaded: cookie_helper
DEBUG - 2010-11-06 21:18:12 --> Model Class Initialized
DEBUG - 2010-11-06 21:18:12 --> Model Class Initialized
DEBUG - 2010-11-06 21:18:12 --> Model Class Initialized
DEBUG - 2010-11-06 21:18:12 --> Model Class Initialized
DEBUG - 2010-11-06 21:18:12 --> Model Class Initialized
DEBUG - 2010-11-06 21:18:12 --> Controller Class Initialized
DEBUG - 2010-11-06 21:18:13 --> Config Class Initialized
DEBUG - 2010-11-06 21:18:13 --> Hooks Class Initialized
DEBUG - 2010-11-06 21:18:13 --> URI Class Initialized
DEBUG - 2010-11-06 21:18:13 --> Router Class Initialized
DEBUG - 2010-11-06 21:18:13 --> Output Class Initialized
DEBUG - 2010-11-06 21:18:13 --> Input Class Initialized
DEBUG - 2010-11-06 21:18:13 --> XSS Filtering completed
DEBUG - 2010-11-06 21:18:13 --> Global POST and COOKIE data sanitized
DEBUG - 2010-11-06 21:18:13 --> Language Class Initialized
DEBUG - 2010-11-06 21:18:13 --> Loader Class Initialized
DEBUG - 2010-11-06 21:18:13 --> Helper loaded: url_helper
DEBUG - 2010-11-06 21:18:13 --> Helper loaded: form_helper
DEBUG - 2010-11-06 21:18:13 --> Language file loaded: language/english/tank_auth_lang.php
DEBUG - 2010-11-06 21:18:13 --> Database Driver Class Initialized
DEBUG - 2010-11-06 21:18:13 --> Form Validation Class Initialized
DEBUG - 2010-11-06 21:18:13 --> Session Class Initialized
DEBUG - 2010-11-06 21:18:13 --> Helper loaded: string_helper
DEBUG - 2010-11-06 21:18:13 --> Encrypt Class Initialized
DEBUG - 2010-11-06 21:18:13 --> A session cookie was not found.
DEBUG - 2010-11-06 21:18:13 --> Session routines successfully run
DEBUG - 2010-11-06 21:18:13 --> Model Class Initialized
DEBUG - 2010-11-06 21:18:13 --> Model Class Initialized
DEBUG - 2010-11-06 21:18:13 --> Config file loaded: config/tank_auth.php
DEBUG - 2010-11-06 21:18:13 --> Helper loaded: cookie_helper
DEBUG - 2010-11-06 21:18:13 --> Model Class Initialized
DEBUG - 2010-11-06 21:18:13 --> Model Class Initialized
DEBUG - 2010-11-06 21:18:13 --> Model Class Initialized
DEBUG - 2010-11-06 21:18:13 --> Model Class Initialized
DEBUG - 2010-11-06 21:18:13 --> Model Class Initialized
DEBUG - 2010-11-06 21:18:13 --> Controller Class Initialized
DEBUG - 2010-11-06 21:21:51 --> Config Class Initialized
DEBUG - 2010-11-06 21:21:51 --> Hooks Class Initialized
DEBUG - 2010-11-06 21:21:51 --> URI Class Initialized
DEBUG - 2010-11-06 21:21:51 --> Router Class Initialized
DEBUG - 2010-11-06 21:21:51 --> Output Class Initialized
DEBUG - 2010-11-06 21:21:51 --> Input Class Initialized
DEBUG - 2010-11-06 21:21:51 --> XSS Filtering completed
DEBUG - 2010-11-06 21:21:51 --> Global POST and COOKIE data sanitized
#22

[eluser]WanWizard[/eluser]
Is this the log from a single page request?

If so, check in your webserver logs what exactly is requested, since the logs shows three times
Code:
XSS Filtering completed
Global POST and COOKIE data sanitized
...
which suggests multiple requests.

Often, this is caused by using 'simple' rewrite rules, which simply rewrites all requests for items that do not exist (the -f and -d tests). This means that a missing image would cause a second call to index.php...
#23

[eluser]theshiftexchange[/eluser]
No - the above code might have been multiple pages. But I did know of one page where the error seemed to occur more often. Below is the 'log_threshold=4' output for a SINGLE page request:

Code:
DEBUG - 2010-11-07 21:40:25 --> Config Class Initialized
DEBUG - 2010-11-07 21:40:25 --> Hooks Class Initialized
DEBUG - 2010-11-07 21:40:25 --> URI Class Initialized
DEBUG - 2010-11-07 21:40:25 --> Router Class Initialized
DEBUG - 2010-11-07 21:40:25 --> Output Class Initialized
DEBUG - 2010-11-07 21:40:25 --> Input Class Initialized
DEBUG - 2010-11-07 21:40:25 --> XSS Filtering completed
DEBUG - 2010-11-07 21:40:25 --> XSS Filtering completed
DEBUG - 2010-11-07 21:40:25 --> XSS Filtering completed
DEBUG - 2010-11-07 21:40:25 --> XSS Filtering completed
DEBUG - 2010-11-07 21:40:25 --> XSS Filtering completed
DEBUG - 2010-11-07 21:40:25 --> XSS Filtering completed
DEBUG - 2010-11-07 21:40:25 --> Global POST and COOKIE data sanitized
DEBUG - 2010-11-07 21:40:25 --> Language Class Initialized
DEBUG - 2010-11-07 21:40:25 --> Loader Class Initialized
DEBUG - 2010-11-07 21:40:25 --> Helper loaded: url_helper
DEBUG - 2010-11-07 21:40:25 --> Helper loaded: form_helper
DEBUG - 2010-11-07 21:40:25 --> Language file loaded: language/english/tank_auth_lang.php
DEBUG - 2010-11-07 21:40:25 --> Database Driver Class Initialized
DEBUG - 2010-11-07 21:40:25 --> Form Validation Class Initialized
DEBUG - 2010-11-07 21:40:25 --> Session Class Initialized
DEBUG - 2010-11-07 21:40:25 --> Helper loaded: string_helper
DEBUG - 2010-11-07 21:40:25 --> Encrypt Class Initialized
DEBUG - 2010-11-07 21:40:25 --> Session routines successfully run
DEBUG - 2010-11-07 21:40:25 --> Model Class Initialized
DEBUG - 2010-11-07 21:40:25 --> Model Class Initialized
DEBUG - 2010-11-07 21:40:25 --> Config file loaded: config/tank_auth.php
DEBUG - 2010-11-07 21:40:25 --> Model Class Initialized
DEBUG - 2010-11-07 21:40:25 --> Model Class Initialized
DEBUG - 2010-11-07 21:40:25 --> Model Class Initialized
DEBUG - 2010-11-07 21:40:25 --> Model Class Initialized
DEBUG - 2010-11-07 21:40:25 --> Model Class Initialized
DEBUG - 2010-11-07 21:40:25 --> Controller Class Initialized
DEBUG - 2010-11-07 21:40:25 --> Model Class Initialized
DEBUG - 2010-11-07 21:40:25 --> Model Class Initialized
DEBUG - 2010-11-07 21:40:25 --> Model Class Initialized
DEBUG - 2010-11-07 21:40:25 --> Language file loaded: language/english/form_validation_lang.php
DEBUG - 2010-11-07 21:40:25 --> XSS Filtering completed
DEBUG - 2010-11-07 21:40:25 --> XSS Filtering completed
DEBUG - 2010-11-07 21:40:25 --> XSS Filtering completed
DEBUG - 2010-11-07 21:40:25 --> Config Class Initialized
DEBUG - 2010-11-07 21:40:25 --> Hooks Class Initialized
DEBUG - 2010-11-07 21:40:25 --> URI Class Initialized
DEBUG - 2010-11-07 21:40:25 --> Router Class Initialized
DEBUG - 2010-11-07 21:40:25 --> Output Class Initialized
DEBUG - 2010-11-07 21:40:25 --> Input Class Initialized
DEBUG - 2010-11-07 21:40:25 --> XSS Filtering completed
DEBUG - 2010-11-07 21:40:25 --> XSS Filtering completed
DEBUG - 2010-11-07 21:40:25 --> Global POST and COOKIE data sanitized
DEBUG - 2010-11-07 21:40:25 --> Language Class Initialized
DEBUG - 2010-11-07 21:40:25 --> Loader Class Initialized
DEBUG - 2010-11-07 21:40:25 --> Helper loaded: url_helper
DEBUG - 2010-11-07 21:40:25 --> Helper loaded: form_helper
DEBUG - 2010-11-07 21:40:25 --> Language file loaded: language/english/tank_auth_lang.php
DEBUG - 2010-11-07 21:40:25 --> Database Driver Class Initialized
DEBUG - 2010-11-07 21:40:25 --> Form Validation Class Initialized
DEBUG - 2010-11-07 21:40:25 --> Session Class Initialized
DEBUG - 2010-11-07 21:40:25 --> Helper loaded: string_helper
DEBUG - 2010-11-07 21:40:25 --> Encrypt Class Initialized
DEBUG - 2010-11-07 21:40:25 --> Session routines successfully run
DEBUG - 2010-11-07 21:40:25 --> Model Class Initialized
DEBUG - 2010-11-07 21:40:25 --> Model Class Initialized
DEBUG - 2010-11-07 21:40:25 --> Config file loaded: config/tank_auth.php
DEBUG - 2010-11-07 21:40:25 --> Model Class Initialized
DEBUG - 2010-11-07 21:40:25 --> Model Class Initialized
DEBUG - 2010-11-07 21:40:25 --> File loaded: application/views//forms/list_printable.php
DEBUG - 2010-11-07 21:40:25 --> Final output sent to browser
DEBUG - 2010-11-07 21:40:25 --> Total execution time: 0.2592

So it looks like 2x calls to index.php? In the controller is a 'redirect' - would that cause 2x calls to index.php?

Quote:Often, this is caused by using ‘simple’ rewrite rules, which simply rewrites all requests for items that do not exist (the -f and -d tests). This means that a missing image would cause a second call to index.php…

Sorry - I dont understand this. What are the -f and -d tests?
#24

[eluser]theshiftexchange[/eluser]
p.s. WanWizard is it possible to get a copy of the updated session code you posted here? http://ellislab.com/forums/viewthread/149102/

The link doesnt seem to work anymore...
#25

[eluser]WanWizard[/eluser]
That version isn't online anymore. It was a quick hack, and I wasn't happy with it. I haven't had time to publish an updated version.

And I'm not sure that solves your problem. I think we first have to understand what happens, before we start fixing it. If you don't use ajax, and your rewrite rules are ok, and you only have sequential requests from any given user, than you shouldn't have an issue with sessions and id rotation.

Time for some debugging. Set the 'sess_time_to_update' to something small, like 15 seconds. Enable the profiler, so you can see the contents of the session after each page request. Disable session cookie encryption. Use firebug to see what cookie information is send to the browser, and try to determine what has happened when you seem to loose your session? Is there an ID mismatch? Did the ID rotate? When did this happen?

With regards to rewrites: some (most?) people use very simple rewrite rules, advocated by a lot of people here, that basically say "if it's not an existing directory or file that is requested, rewrite to index.php". Which means that requests for missing images (missing, misspelled, etc) causes a second CI request). It is better to have your assets in an /asset directory, and exclude that directory from rewriting using RewriteCond.
#26

[eluser]theshiftexchange[/eluser]
ok - I cleared firefox + database sessions - so there are none. Then I set 'sess_time_to_update' to 3 & turned off cookie encryption.

This is what firebug shows me:

Inital visit to website:
Cookie mydomainsession added - id A
Cookie mydomainsession added - id A

Page request:
Cookie mydomainsession changed - id B
Cookie mydomainsession changed - id B

{keep loading more pages here - sometimes 5, sometimes 50 - seems random}

Page request:
Cookie mydomainsession changed - id C
Cookie mydomainsession changed - id C

Page request:
Cookie mydomainsession deleted - id C
Cookie mydomainsession added - id E
Cookie mydomainsession deleted - id C
Cookie mydomainsession added - id E

and I am now logged out of the site. At the end of this there are 2 database sessions in the database:
id E - which is the new one (the 'user_data' is NULL)
and
id D - which is actually the old session (the 'user_data' is populated with what should have been the correct session)

So it seems to skip a session rotation or something?

Is it normal for 'duplicate' cookie changes on each single page load?

The error occurs on all pages - I can just 'reload' the same page over and over and it will eventually occur.
#27

[eluser]WanWizard[/eluser]
By default, every time you use $this->session->userdata(), the Session library does an automatic write, which creates a cookie.
So in itself it's not uncommon to have multiple entries for the same cookie (altough I don't like it, and I've changed that in my Session library).

What still points me in the direction of multiple requests is your last request.

Imagine you request a page, and in this page there's an image that doesn't exist, and causes a rewrite to index.php:
- browser requests the page, sends cookie with id C
- this request triggers an id rotation, C gets changed to D
- browser requests the page assets, one gets rewritten to index.php
- session C can't be found (because by now it's D), a new E is created
- browser now has a cookie with id E, D is overwritten by this new cookie.

So you really need to figure out where this second request is coming from. Check your webserver logs to see what exactly is requested. Alternatively, add a log_message('debug', $_SERVER['PHP_SELF']); to system/codeigniter/codeigniter.php, around line 162.
#28

[eluser]theshiftexchange[/eluser]
I got it!!!!!!

The issue is that regardless of the cause - two quick page requests occuring during a cookie update will kill the session.

The problem is that ANYTHING that causes two quick page requests will cause the problem - including someone who presses 'refresh' twice quickly, or someone who 'double clicks' a hyperlink your website, or 2 quick 'redirects' in the website - ANYTHING.

So the only solution I can think of is change the normal 'time_to_update' to 150 (from the default 300), then add another column in the database which is 'old_session_id' - and allow the session cookie to be checked against both and updated accordingly.



I can replicate the bug from a fresh CI install.

Steps:
1. Create a new blank database and put this single table in there:
Code:
CREATE TABLE IF NOT EXISTS  `ci_sessions` (
session_id varchar(40) DEFAULT '0' NOT NULL,
ip_address varchar(16) DEFAULT '0' NOT NULL,
user_agent varchar(50) NOT NULL,
last_activity int(10) unsigned DEFAULT 0 NOT NULL,
user_data text NULL,
PRIMARY KEY (session_id)
);
(this is the same code from the user guide except we allow null user_data)

2. Download a clean current version of 1.7.2 from website and install into directory

3. Configure config.php with base_url, cookie_domain settings, plus change the cookie settings to:
Code:
$config['sess_cookie_name']        = 'mytestsession';
$config['sess_expiration']        = 7200;
$config['sess_encrypt_cookie']    = FALSE;
$config['sess_use_database']    = TRUE;
$config['sess_table_name']        = 'ci_sessions';
$config['sess_match_ip']        = FALSE;
$config['sess_match_useragent']    = TRUE;
$config['sess_time_to_update']     = 3;

4. In database.php configure your database connection

5. Create an 'auth.php' controller and paste this in:
Code:
<?php

class Auth extends Controller {

    function Auth()
    {
        parent::Controller();
                   $this->load->library('session');
            $this->load->database();
    }

    function index()
    {
    }

        function login()
        {
                $newdata = array('logged_in' => TRUE);
                $this->session->set_userdata($newdata);
                echo "logged in now";
        }

        function is_logged_in()
        {
                echo $this->session->userdata('logged_in');
        }
}

6. Visit /auth/login - you will see 'logged in now on your screen'

7. Visit /auth/is_logged_in - you will see a "1" on the screen representing 'true' for logged in

8. Now press F5 a few times quickly. You might have to do it a couple of times, but eventually the 1 will disappar from the screen - you are now logged out due to the session change!


I dont know if this occurs in 2.0 - if someone who has that up and running could let me know that would be appreciated.

Any thoughts?

edit: I just found theses posts - turns out someone has exactly the same conclusion as me:
http://ellislab.com/forums/viewthread/170123/
http://ellislab.com/forums/viewthread/149102/
http://ellislab.com/forums/viewthread/147812/
#29

[eluser]rip_pit[/eluser]
i'm pleased to read that my coding is not the main cause for this to happen Wink

Sorry I have no fix but the problem still occurs in CI2
#30

[eluser]theshiftexchange[/eluser]
[quote author="rip_pit" date="1334188986"]i'm pleased to read that my coding is not the main cause for this to happen Wink

Sorry I have no fix but the problem still occurs in CI2
[/quote]

WanWizard posted a solution here which fixes the issue: http://ellislab.com/forums/viewthread/149102/




Theme © iAndrew 2016 - Forum software by © MyBB