koajs / generic-session

koa session store with memory, redis or others.
MIT License
414 stars 65 forks source link

Issue with Redis Store and terser #135

Closed vicb closed 4 years ago

vicb commented 4 years ago

I have an issue when deploying my app to Google App Engine. Here is what I have found. Any pointers would be appreciated to help debug this further.

I set up my session as

app
  .use(
    session({
      store: (redisStore({
        host: redisUrl.hostname,
        port: Number(redisUrl.port),
        password: redisUrl.password,
      }) as unknown) as SessionStore,
      cookie: {
        path: '/',
        httpOnly: true,
        maxAge: null,
        signed: true,
        secure: process.env.NODE_ENV != 'development',
      },
    }),
  )
  .use(...);

I have a GET route:

router.get('/ses', async (ctx: RouterContext) => {
  const session = ctx.session;
  if (session) {
    session.counter = (session.counter ?? 0) + 1;
    ctx.set('Content-Type', 'text/plain');
    ctx.body = `${session.counter} views\n
    ${JSON.stringify(ctx.session, null, 2)}
    ${JSON.stringify(ctx.headers, null, 2)}
    env = ${process.env.NODE_ENV}
    cookies = ${ctx.cookies.get('koa.sid')} / ${ctx.cookies.get('koa.sid.sig')}
    `;
  }
});

On my dev server, evevrything works as expected. I can see the counter incrementing at each request.

14 views { "cookie": { "path": "/", "httpOnly": true, "maxAge": null, "signed": true, "secure": false, "overwrite": true }, "counter": 14 } { "host": "localhost:8080", "connection": "keep-alive", "cache-control": "max-age=0", "dnt": "1", "upgrade-insecure-requests": "1", "user-agent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/85.0.4183.121 Safari/537.36", "accept": "text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9", [...] "cookie": "[...]; koa.sid=FbqVvV5UERRoIAhmX_yYEGOI0bSO8etn; koa.sid.sig=MJaJQUx64E0OXtmdAXs1f27h1KI" } env = development cookies = FbqVvV5UERRoIAhmX_yYEGOI0bSO8etn / MJaJQUx64E0OXtmdAXs1f27h1KI

When I deploy this on Google app engine the session doesn't work.

It would look ok the first time:

1 views

    {
  "cookie": {
    "path": "/",
    "httpOnly": true,
    "maxAge": null,
    "signed": true,
    "secure": true,
    "overwrite": true
  },
  "counter": 1
}

but then the sessions looks weird no reload:

1 views

    {
  "counter": 1
}

(The cookie entry has disappeared)

1st requests

1 views { "cookie": { "path": "/", "httpOnly": true, "maxAge": null, "signed": true, "secure": true, "overwrite": true }, "counter": 1 } { "host": "[..]..r.appspot.com", "x-forwarded-for": "2601:647:4e01:1de0:5cde:327:e5e7:fff6, 169.254.1.1", "x-forwarded-proto": "https", "forwarded": "for=\"2601:647:4e01:1de0:5cde:327:e5e7:fff6\";proto=https", "dnt": "1", "upgrade-insecure-requests": "1", "user-agent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/85.0.4183.121 Safari/537.36", "accept": "text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9", [...] } env = production cookies = undefined / undefined

subsequent requests

1 views { "counter": 1 } { "host": "20201006t162821-dot-fly-xc.uc.r.appspot.com", "x-forwarded-for": "2601:647:4e01:1de0:5cde:327:e5e7:fff6, 169.254.1.1", "x-forwarded-proto": "https", "forwarded": "for=\"2601:647:4e01:1de0:5cde:327:e5e7:fff6\";proto=https", "cache-control": "max-age=0", "dnt": "1", "upgrade-insecure-requests": "1", "user-agent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/85.0.4183.121 Safari/537.36", "accept": "text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9", [...] "cookie": "koa.sid=6pErY7MpOPNgPopgiL9nq7viPFJARwnZ; koa.sid.sig=hCbfgFYJMMICUIf_PlGMXU4R8x4", } env = production cookies = 6pErY7MpOPNgPopgiL9nq7viPFJARwnZ / hCbfgFYJMMICUIf_PlGMXU4R8x4

I am also using in my app:

  .use(mount(/oauth', grant({...}),),)
  .use(bodyParser({ formLimit: '32mb' }))
  .use(router.routes())
  .use(router.allowedMethods())
  .use(serve('frontend/static'));

Notes:

Thanks !

vicb commented 4 years ago

For some reason it seems like a problem with the REDIS store

I have enabled the logs with DEBUG=koa-generic-session:*

On the server:

request 1

2020-10-07T03:16:01.170Z koa-generic-session:session session id not exist, generate a new one
2020-10-07T03:16:01.177Z koa-generic-session:session session modified
2020-10-07T03:16:01.177Z koa-generic-session:store SET key: koa:sess:XqqnfE3X-XDAHJ41dlI2DR4aHeKwjg8T, value: { cookie: [Object], counter: 1 }, ttl: NaN
2020-10-07T03:16:01.180Z koa-generic-session:store SET complete
2020-10-07T03:16:01.182Z koa-generic-session:session saved

request 2 and next....

2020-10-07T03:16:01.673Z koa-generic-session:store GET koa:sess:XqqnfE3X-XDAHJ41dlI2DR4aHeKwjg8T
2020-10-07T03:16:01.674Z koa-generic-session:store GOT {}
2020-10-07T03:16:01.674Z koa-generic-session:session get session {} with key XqqnfE3X-XDAHJ41dlI2DR4aHeKwjg8T
2020-10-07T03:16:01.674Z koa-generic-session:session session not modified

I am using a strip down server:

import Koa from 'koa';
import session, { SessionStore } from 'koa-generic-session';
import redisStore from 'koa-redis';

import Router, { RouterContext } from '@koa/router';

import { Keys } from './keys';

process.env.DEBUG = 'koa-generic-session:*';

const app = new Koa();
app.keys = [Keys.KOA_KEY];
// Needed for secure cookies.
app.proxy = process.env.NODE_ENV != 'development';
const router = new Router();

// Logout.
router.get('/ses', async (ctx: RouterContext) => {
  const session = ctx.session;
  if (session) {
    session.counter = (session.counter ?? 0) + 1;
    ctx.set('Content-Type', 'text/plain');
    ctx.body = `${session.counter} views\n
    ${JSON.stringify(ctx.session, null, 2)}
    ${JSON.stringify(ctx.headers, null, 2)}
    env = ${process.env.NODE_ENV}
    cookies = ${ctx.cookies.get('koa.sid')} / ${ctx.cookies.get('koa.sid.sig')}
    `;
  }
});

router.get('/logout', async (ctx: RouterContext) => {
  ctx.session = null;
  ctx.redirect('/');
});

const redisUrl = new URL(Keys.REDIS_URL);

app
  .use(
    session({
      store: (redisStore({
        host: redisUrl.hostname,
        port: Number(redisUrl.port),
        password: redisUrl.password,
      }) as unknown) as SessionStore,
      cookie: {
        path: '/',
        httpOnly: true,
        // maxAge = null to delete the cookie when the browser is closed.
        maxAge: null,
        signed: true,
        secure: process.env.NODE_ENV != 'development',
      },
    }),
  )
  .use(router.routes())
  .use(router.allowedMethods());

const port = process.env.PORT || 8080;
app.listen(port);
vicb commented 4 years ago

Adding ioredis debug is interesting.

On the server:


2020-10-07T03:35:03.005Z koa-generic-session:session session id not exist, generate a new one
2020-10-07T03:35:03.008Z koa-generic-session:session new session and do not modified
2020-10-07T03:35:03.045Z ioredis:redis status[35.224.153.24:18918]: connecting -> connect
2020-10-07T03:35:03.048Z ioredis:redis write command[35.224.153.24:18918]: 0 -> auth([ '...' ])
2020-10-07T03:35:03.049Z ioredis:redis write command[35.224.153.24:18918]: 0 -> info([])
2020-10-07T03:35:03.426Z ioredis:redis status[35.224.153.24:18918]: connect -> ready

2020-10-07T03:35:03.553Z koa-generic-session:session session id not exist, generate a new one
2020-10-07T03:35:03.554Z koa-generic-session:session new session and do not modified
2020-10-07T03:35:09.232Z koa-generic-session:session session id not exist, generate a new one
2020-10-07T03:35:09.235Z koa-generic-session:session session modified
2020-10-07T03:35:09.235Z koa-generic-session:store SET key: koa:sess:CaTfRc-qz4uf4X3IBxdGd-kxuTmfCN3O, value: { cookie: [Object], counter: 1 }, ttl: 60000
2020-10-07T03:35:09.236Z koa-generic-session:store SET complete
2020-10-07T03:35:09.237Z koa-generic-session:session saved

2020-10-07T03:35:12.432Z koa-generic-session:store GET koa:sess:CaTfRc-qz4uf4X3IBxdGd-kxuTmfCN3O
2020-10-07T03:35:12.433Z koa-generic-session:store GOT {}
[...]

on localhost:

  ioredis:redis status[redis-18918.c124.us-central1-1.gce.cloud.redislabs.com:18918]: [empty] -> connecting +0ms
  ioredis:redis status[35.224.153.24:18918]: connecting -> connect +157ms
  ioredis:redis write command[35.224.153.24:18918]: 0 -> auth([ '...' ]) +2ms
  ioredis:redis write command[35.224.153.24:18918]: 0 -> info([]) +8ms
  ioredis:redis status[35.224.153.24:18918]: connect -> ready +197ms

  koa-generic-session:session session id not exist, generate a new one +0ms
  koa-generic-session:session session modified +5ms
  koa-generic-session:store SET key: koa:sess:6w9dBJWwoomc1bK0hirTCz3aeCkh_I3o, value: [object Object], ttl: 60000 +0ms

  ioredis:redis write command[35.224.153.24:18918]: 0 -> setex([ 'koa:sess:6w9dBJWwoomc1bK0hirTCz3aeCkh_I3o', '60', '{"cookie":{"path":"/","httpOnly":true,"maxAge":60000,"signed":true,"secure":false,"overwrite":true},"counter":1}' ]) +21s

  koa-generic-session:store SET complete +57ms
  koa-generic-session:session saved +62ms

  koa-generic-session:store GET koa:sess:6w9dBJWwoomc1bK0hirTCz3aeCkh_I3o +22s
  ioredis:redis write command[35.224.153.24:18918]: 0 -> get([ 'koa:sess:6w9dBJWwoomc1bK0hirTCz3aeCkh_I3o' ]) +23s
  koa-generic-session:store GOT {"cookie":{"path":"/","httpOnly":true,"maxAge":60000,"signed":true,"secure":false,"overwrite":true},"counter":1} +61ms
 [...]

The ioredis:redis write command[35.224.153.24:18918]: 0 -> setex(...) command is missing on the server side. This matches the observed behavior (the session object is empty).

Now why ?

vicb commented 4 years ago

Ahah... I just found something.

One difference between my prod and dev env is that my prod env use terser to minify the output. When I run terser on my dev env, I get the same error: the redis store doesn't get called !

vicb commented 4 years ago

I have narrowed down the issue to the redis store:

The minified code looks like:

RedisStore.prototype.set = _regenerator.default.mark((function e(t, n, s) {
    return _regenerator.default.wrap((function (e) {
        console.log(`RedisStore.prototype.set`);
        for (;;) switch (e.prev = e.next) {
        case 0:
            if ("number" == typeof s && (s = Math.ceil(s / 1e3)), n = this.serialize(n), !s) {
                e.next = 8;
                break
            }
            return debug$8("SETEX %s %s %s", t, s, n), e.next = 6, this.client.setex(t, s, n);
        case 6:
            e.next = 11;
            break;
        case 8:
            return debug$8("SET %s %s", t, n), e.next = 11, this.client.set(t, n);
        case 11:
            debug$8("SET %s complete", t);
        case 12:
        case "end":
            return e.stop()
        }
    }), e, this)
}));

and doesn't work !

If I replace this code with the untransformed redis store source code:

RedisStore.prototype.set = function*(sid, sess, ttl) {
  if (typeof ttl === 'number') {
    ttl = Math.ceil(ttl / 1000);
  }

  sess = this.serialize(sess);
  if (ttl) {
    debug('SETEX %s %s %s', sid, ttl, sess);
    yield this.client.setex(sid, ttl, sess);
  } else {
    debug('SET %s %s', sid, sess);
    yield this.client.set(sid, sess);
  }

  debug('SET %s complete', sid);
};

The session is saved correctly (the app still doesn't work as other methods would also need to have the same treatment).

While I was looking into this, I realized that Koa session are a little bit of a mess:

ATM I am wondering if I should continue debugging this or switch to an other server ?

vicb commented 4 years ago

Closing this issue. With my small app it was easier to migrate to express than try to debug this.