[Panel] Session expirery

[nilshoerrmann]

I'm getting logged out of the panel multiple times a day. It doesn't matter, if I check the "Keep me logged in" option or not. The behaviour is not isochronous: sometimes it takes 10 minutes, sometimes a few hours. So far, I haven't understood the pattern why this happens.

---

Kirby 3 Alpha 10, lastet Firefox for Mac.

[lukasbestle]

That absolutely should not happen. The main goal of our new session implementation was to make it very robust.

Two possible explanations:

• Do you use multiple sites on the same hostname (e.g. http://localhost/<your-site>)? This is a bug that will be fixed once https://github.com/k-next/kirby/pull/84 is merged.
• Have you maybe configured your browser to delete cookies in some situations or do you use a browser extension to do that? Could you please test it in a different browser to verify that it's not your browser's configuration?

[nilshoerrmann]

Yes, it's an install on localhost, and yes, I do have multiple sites running side-by-side, see #454. But there should be no site interferences in this case because I worked in the panel of one site only.

Regarding cookies: The browser is set to accept cookies and I don't have any add-ons to automatically clean-up cookies. It's Firefox 60.0.1 on Mac OS 10.13.4 (17E202).

As a background information, I encountered the issue twice without any interaction: After logging into the panel I left the computer to get some tea and was logged out again after returning to the computer.

[nilshoerrmann]

I will check if there are any logs in the console in case this happens again.

[lukasbestle]

Have you kept the Panel open? If you didn't, that behavior is expected (at least if you don't use "keep me logged in") as there is an inactivity timeout. If you did keep the Panel open, that shouldn't happen however.

[nilshoerrmann]

Yes, I did keep the Panel open.

[nilshoerrmann]

And I did check the "keep me logged in" option.

[lukasbestle]

Strange. It would be very helpful to get the following information the next time this happens:

• Is the session cookie still set if you check in the developer tools?
• Does the respective session file still exist in site/sessions?
• If it exists, when was the last modification of that session file?

[nilshoerrmann]

So far this issue has not yet occured again. Not sure what's different today compared to yesterday. I will check your list as soon as it happens again.

[nilshoerrmann]

So, it happend again: I left the tab open and after getting back from lunch I was logged out. My computer was in standby.

I see this error multiple times in my console:

{
  "status": "error",
  "exception": "Exception",
  "message": "Unauthenticated",
  "file": "test.k3/kirby/config/api/authentication.php",
  "line": 8,
  "code": 500
}

The request to http://localhost:8888/test.k3/api/auth that resulted in that error returned a 500 Internal Server Error code.

I also still have the session cookie:

[nilshoerrmann]

To get the times correctly: the LastAccessed date more or less equals the time of the screenshot. I'm at GMT+02:00, Berlin time, so it was 14:15 here actually.

[nilshoerrmann]

Is the session cookie still set if you check in the developer tools?

Yes, see above.

Does the respective session file still exist in site/sessions?

There are three session files (timestamp.hash.sess). How do I identify the correct one? The latest one (13:23) matches the session stored in the browser.

If it exists, when was the last modification of that session file?

The modifications dates of the three files are 11:26, 12:28 and 13:23. The last one is around the time I left for lunch.

[lukasbestle]

Was that a "keep me logged in" session?

[jenstornell]

Not sure if it has anything to do with it but...

• Maybe you can check if the internet connection changed IP.
• Look up if something happends to the session when a computer goes to standby?

[lukasbestle]

Maybe you can check if the internet connection changed IP.

Can't be the issue as the session implementation in Kirby 3 doesn't have a fingerprint anymore. :)

[nilshoerrmann]

Was that a "keep me logged in" session?

Should have been, yes.

[lukasbestle]

I just took a look at your screenshot again. It says that the cookie would have expired today. The modification times of the session files also indicate that the session only has a duration of two hours (as the sessions get automatically renewed once half of the session duration is over, meaning each hour for a duration of two hours).

So the issue is that your session was not a "keep me logged in" session but just a "normal" session. And for normal sessions the described behavior is expected because of the inactivity timeout. You have kept the tab open, but because your computer was in standby, the Panel couldn't keep the session active.

However it's not your fault. 🙂 I just tested the login form in Alpha 10 myself and found out that the "keep me logged in" checkbox is broken, so if you selected "keep me logged in", it didn't have any effect. I have opened an issue here: #485

I will close this issue. Once the bug with the checkbox is fixed, this issue should be solved as well. Please just keep in mind that only "keep me logged in" sessions are expected to have a long duration, so you should use those once the bug is fixed.

Thanks for your help with debugging this!

[nilshoerrmann]

👍

[nilshoerrmann]

I'm experiencing this issue again using Alpha 11 on localhost with separate folders for different installs: I'm logged out multiple times a day.

What I can confirm:

• session cookies now contain the correct path
• there is a corresponding session file on the server
• using the "keep me logged in" feature results in an expiry date 14 days from now
• switching installs is not the cause of the problem because I didn't switch

Two things I noticed:

1. When being logged out during the day, I had the panel idle in a tab.
2. Restarting the computer results in a logout every time.

This is on macOS High Sierra 10.13.5 (17F77) using Firefox 61. I'm using MAMP 4.5 (3208) with PHP 7.2.1.

What can I do to help debugging this issue?

[lukasbestle]

Oh no! To be honest I have no idea where this might come from, especially the "restarting the computer results in a logout every time" part.

Could you please check what happens if you log in with "keep me logged in" and quit Firefox without rebooting your computer? Does that log you out too?

[nilshoerrmann]

Could you please check what happens if you log in with "keep me logged in" and quit Firefox without rebooting your computer? Does that log you out too?

No, it doesn't log me out.

Maybe I'm wrong with the perception that rebooting causes a logout and this is caused by something else? I don't know much about the inner workings of sessions: is it possible that MAMP is causing this issue?

[lukasbestle]

For normal PHP sessions that can be true because they are very much treated as temporary files and can be cleaned up by reboots. But as our session files are stored in our own session directory, I have no idea why reboots would log you out of sessions.

To be honest I don't know how to debug this. Let's see if anyone else has the same issue. Maybe we'll get a clue from any additional information.

[nilshoerrmann]

Yeah, that sounds like a plan.

I'll try to monitor the panel behaviour over the next days. Maybe I find a pattern.

[nilshoerrmann]

It happened again and I see the same messages in the console as before (3 times): https://github.com/k-next/starterkit/issues/472#issuecomment-393141222

Additionally, there are these logs:

Vtdi/vp.config.onError
http://localhost:8888/branchplant.k3/media/panel/ffef14da5bd7cbbaf5d8a3498864f99d/js/app.js:1:181782
request/<
http://localhost:8888/branchplant.k3/media/panel/ffef14da5bd7cbbaf5d8a3498864f99d/js/app.js:1:148342

There is a valid session in the browser matching the one on the server (expiring Thu, 12 Jul 2018 08:01:31 GMT).

[nilshoerrmann]

The browser sent the correct session with the request that resulted in the error. And there is a successful follow up request to http://localhost:8888/branchplant.k3/api/auth/logout.

[nilshoerrmann]

So the Panel first tries to connect to http://localhost:8888/branchplant.k3/api/auth which fails although the correct credentials were provided and then logs me out (due to this error I guess).

What I don't understand is:

• Why is the Panel trying to call the authorization endpoint when I have an existing session?
• Why does the authorization fail although the provided details are correct?
• Why does the Panel explicitly logs me out afterwards?
• Why does the session information still exist in the browser and on the server even after a successful logout?
• Why does this all happen three times in a row?

[lukasbestle]

Thank you for the insights, that helps a lot already!

Why is the Panel trying to call the authorization endpoint when I have an existing session?

That's an internal mechanism to keep the session fresh. Basically if you keep the tab open (and your computer doesn't go into standby), the Panel sends a ping request to the server ever so often to ensure that the session doesn't expire because of inactivity.

The GET auth endpoint just returns data about the current session, so it's not doing anything.

Why does the authorization fails although the provided details are correct?

That's a very good question.

Why does the Panel explicitly logs me out afterwards?

Same here. I am not 100 % familiar with the frontend logic of the Panel. @distantnative?

Why does the session information still exist in the browser and on the server even after a successful logout?

The session is only actually deleted if there is no remaining information. Do you use the session for anything else (for example in the frontend)?

Why does this all happen three times in a row?

What do you mean with "in a row"?

[distantnative]

I'd assume this here is triggered: https://github.com/k-next/kirby/blob/master/panel/src/config/auth.js#L13? If there is no current user due to invalid authorization (whysoever), then we should make sure to log him out of the panel, right?

[lukasbestle]

Makes sense. So the only open question is why the request to GET auth fails even though a valid session is passed.

[nilshoerrmann]

That makes sense indeed.

Do you use the session for anything else (for example in the frontend)?

No, we are not doing anything with the session actively – like changing data or adding to it. The only thing we do on the frontend that is session related in a way is that we check in our templates if there is an active user (kirby()->user()).

What do you mean with "in a row"?

The error is logged multiple times (the log is growing over time): there are repeating requests to the auth endpoint which always fail. And there is a follow-up logout request each time as well.

[nilshoerrmann]

I just noticed that there is also this warning in the logs:

i18n: i18n locale is not set when trying to access translations: upload.progress vendor.js:1:8849

Not sure how that might be related though. And the warning persists after logging in successfully and reloading the panel.

[nilshoerrmann]

Just for the records: the behaviour is not bound to localhost alone. It also happens on our project server. So it's either rooted in Kirby itself or in our install specifically.

We are working on and using a custom template renderer. So we are extending Kirby\Cms\Template as introduced in the latest Alpha:

use Kirby\Cms\App;
use Hananils\Xslt;

Kirby::plugin('hananils/xslt', [
    'components' => [
        'template' => function (App $kirby, string $name, array $data = [], string $appendix = null) {
            return new Hananils\Xslt($name, $data, $appendix);
        }
    ]
]);

Within this plugin we do the check for an active user as mentioned above. Everything else is content related: fetching page or site information using collections or controllers.

Questions

1. Are there any core classes or functions that might interfer with sessions without us knowing?
2. Is there a way to save logs server side when the auth request fails?

[bastianallgeier]

Is this still happening?

[nilshoerrmann]

Yes, it is regularly. On localhost as well as on our project server.

[lukasbestle]

I still can't reproduce this. Have you tested with a fresh copy of Beta 2 without custom modifications?

[nilshoerrmann]

Yes, this happens with plain beta versions as well – although I haven't tested that on our project server yet.

These are all subdirectory installs (e. g. example.com/install1/, example.com/install2/). Although on the project server there is only one folder with a Kirby install.

[nilshoerrmann]

(And I'm really sorry for not having any clues how you might reproduce this issue.)

[nilshoerrmann]

Hi, it's me again 👋 I was able to debug this a bit more:

I'm currently looking at why I'm logged out after starting the computer when I still have a valid session on the server and a related session cookie in the browser.

It seems like the panel is requesting the system information on load (/api/system?view=panel) and is looking for the current user in the returned object. If there is no user object, the panel performs a logout (I guess to make sure no one is able to access the panel who shouldn't):

https://github.com/k-next/kirby/blob/551a97b501c4116119ffb79487f894f43f5c01d4/panel/src/config/auth.js#L7-L15

While the panel is sending the correct session cookie with the request the returned user object is null in my case:

{
    "code": 200,
    "data": {
        "isInstalled": true,
        "isLocal": true,
        "isOk": true,
        "languages": [],
        "license": null,
        "requirements": {},
        "title": "Site title",
        "translation": {},
        "user": null
    },
    "status": "ok",
    "type": "model"
}

If I print the variables in AppUsers.php I can see that Kirby finds the correct session on the server which contains a data object with the user id (session id is correct, expirery dates as well):

https://github.com/k-next/kirby/blob/551a97b501c4116119ffb79487f894f43f5c01d4/src/Cms/AppUsers.php#L42-L71

But https://github.com/k-next/kirby/blob/master/src/Cms/AppUsers.php#L54 returns an empty value.

There are a few hash like value I don't understand (in the session cookie as well as in the first key of session data on the server). Is there anything I can check for inconsitencies?

[bastianallgeier]

@lukasbestle that looks very helpful to me, but I think you are faster with this kind of stuff.

[nilshoerrmann]

This is just a shoot in the dark but timestamp stored on the server need to be multiplied by 1000 in the browser in order to get the correct date. Is it possible that there is simple conversion issue at some point on the frontend and the panel thinks the session has expired already?

[nilshoerrmann]

Is there a documentation what the different hashes in the session cookie and in the cookie itself stand for? I'm interested to find out if there is some kind of mismatch where a match is required.

Session Cookie

hash1+expirytimestamp.sessionid.hash2

Session File

expirytimestamp.sessionid.ext

hash3: {
    "startTime": 123456678,
    "expiryTime": expirytimestamp,
    "duration": 1209600,
    "timeout": 1800,
    "lastActivity": 123456678,
    "renewable":true,
    "data":{
        "user.id": "hash4"
    }
}

I'm interested in the meaning of hash1, hash2, hash3 and hash4.

[nilshoerrmann]

This is just a shoot in the dark but timestamp stored on the server need to be multiplied by 1000 in the browser in order to get the correct date. Is it possible that there is simple conversion issue at some point on the frontend and the panel thinks the session has expired already?

I've absolutely no idea if the panel does check dates at all but if it did, the session expiry of 14 days would be reduced to around 30 minutes with this kind of error.

[lukasbestle]

Thank you for all your help with debugging this! I'm pretty sure we are onto something here.

This is just a shoot in the dark but timestamp stored on the server need to be multiplied by 1000 in the browser in order to get the correct date.

Hm, the timestamp that is stored on the server is a UNIX second timestamp generated with PHP's time() function. JS uses millisecond timestamps. But this shouldn't be the issue here because 1) the timestamp is never checked on the client and 2) already the API (which is written in PHP) returns an empty user property. The Session class should be the only one validating the expiry time.

I'm interested in the meaning of hash1, hash2, hash3 and hash4.

There is no documentation about this, but here is a short list:

• hash1 (at the beginning of the cookie value): HMAC of the cookie value (basically a hash of everything that follows after the + sign)
• hash2 (at the end of the cookie value): Token key, basically the proof of the client that it actually owns the session so that you can't just take a random filename from the site/sessions directory and instantly have a valid session; the token key is validated using another HMAC that is stored in the session file
• hash3 (session file hash) Exactly the hash I wrote about in the hash2 description above
• hash4 (user ID) Kirby internally uses a hash of the email address as the user ID, which is then stored in the session when logging in, this however is not for security reasons but just because of the way our User class works

---

BTW: I have been able to reproduce this issue, but wasn't able to catch exactly the request where it happened. Do you have any tips for me on how to catch that request?

[nilshoerrmann]

Thanks for all the information.

After a logout, is the session cookie supposed to be destroyed or should it be kept intact? Both, in the browser and on the server?

Do you have any tips for me on how to catch that request?

No, not really.

[lukasbestle]

After a logout, is the session cookie supposed to be destroyed or should it be kept intact? Both, in the browser and on the server?

It depends. If the session is otherwise empty, it is destroyed, otherwise only the user ID is removed and the session is kept (but with a new session ID).

[johannahoerrmann]

This regularly happens to me, too. (Like right now when I opened the panel of a project the first time today.) What helpful information could I share?

[lukasbestle]

As it's very difficult to catch the request where it happens, it's also difficult to get more information about the bug. But as several people have now reported this, I will dig into it some more, maybe I'll find something. :)

[johannahoerrmann]

I was logged out again and encountered a strange error when trying to log back in today: my login wasn't accepted. No errors were displayed in the interface, but there was this in the network responses:

{
    "status":"error",
    "exception":"Exception",
    "message":"Unauthenticated",
    "file":"by\/config\/api\/authentication.php",
    "line":8,
    "code":500
}

There was a short flickering in the interface that looked like a system message (with a tiny red warning triangle), but the login form was reloaded instantly.

I later noticed that I had two sessions in the browser for the same site:

Deleting those two entries allowed me to log in again. Might this be related?

[lukasbestle]

@johannahoerrmann That issue looks like a different issue as it is related to two cookies with different paths. However I have been able to reproduce the bug in this GitHub issue on a site at the root of the domain as well. I have moved your report to a new issue #1010 and commented over there.

---

Regarding this issue: To debug this, I have created a simple testing setup that doesn't depend on the Panel (which would introduce a lot of additional variables):

$session = $kirby->session(['long' => true]);
$session->set('updated', date('Y-m-d H:i:s'));
$session->increment('requests');

echo 'Token';
var_dump($session->token());

echo 'Start time';
var_dump(date('Y-m-d H:i:s', $session->startTime()));

echo 'Expiry time';
var_dump(date('Y-m-d H:i:s', $session->expiryTime()));

echo 'Session Data';
var_dump($session->data()->get());

So far it survived quitting the browser several times, restarting the web server and rebooting. I will load that page regularly in the next few days to see if it suddenly creates a new empty session. If so, it might give me some insights when and why this happens.

[lukasbestle]

Big fat checkmark ✅

(I hope)