Invalid invocation error caused by an update query

[fowled]

Hello!
I've been using your module for a bit and I must say it fulfils its mission perfectly.

But sometimes, a random error shows up, and I have no idea why:

set(): Error:
Invalid `this.prisma[this.sessionModelName].update()` invocation in
C:\Users\Maxan\OneDrive\Documents\Code\Mango\node_modules\.pnpm\@quixo3+prisma-session-store@3.1.5_ebc298f2cb1351102aeafce15c5f3d3f\node_modules\@quixo3\prisma-session-store\dist\lib\prisma-session-store.js:486:81

  483 case 3:
  484     _a.trys.push([3, 8, , 9]);
  485     if (!(existingSession !== null)) return [3 /*break*/, 5];
→ 486     return [4 /*yield*/, this.prisma[this.sessionModelName].update(
  Error occurred during query execution:
ConnectorError(ConnectorError { user_facing_error: None, kind: ConnectionError(Timed out during query execution.) })

I'm using @quixo3/prisma-session-store@3.1.5 with a SQLite database.

app.use([
    session({
	secret: process.env.SESSION_SECRET,
	cookie: { secure: !process.env.SECURE_COOKIE },
	resave: true,
	saveUninitialized: true,
	store: new PrismaSessionStore(database, { dbRecordIdIsSessionId: true }),
    }),
]);

Do you have an idea of what's causing it?
Thanks a lot!

[fowled]

Oh, forgot to say but it looks like it's not causing anything db-wise. All my records are still there after this error pops up and nothing seems to really change.

[kleydon]

Hey @fowled - glad you're finding this useful!

I've been seeing this error too sometimes; not entirely sure why.
(One of the most recent releases wrapped the logic above in a try/catch block and passes the error to a callback function, to prevent crashes.)

One going theory is that maybe this error is the result of a race condition: perhaps when there are multiple prisma clients talking to a database, they make requests that collide, yielding errors like this. I haven't had the bandwidth to consider this carefully, but - maybe?

If you have (or develop) any insight over time related to this, would love to know about it.

Cheers.

[fowled]

Thanks for your answer!

Do you know what's at the origin of that update query? It should help us in resolving the issue.

[fowled]

This might be related - prisma/prisma#2955

Though I don't really see, in our case, how the db would get 'locked'

[fowled]

I found something interesting, after having enabled logs.

This might be related - prisma/prisma#2955

Though I don't really see, in our case, how the db would get 'locked'

I think what's happening here is that the database gets locked after the first UPDATE query (red rectangle on my screenshot) and the SELECT query that follows (orange rectangle) fails and the error pops up. That's the only explanation I can think of as of the very right now.

Maybe the COMMIT statement (green rectangle) should be made before the SELECT query?

@kleydon - can you think of any way to fix that?

[kleydon]

@fowled Thanks for digging into this.

This might be related - prisma/prisma#2955
Though I don't really see, in our case, how the db would get 'locked'

I've experienced this error using Prisma with Postgres, so I'm pretty sure it isn't an sql-lite specific issue.

Unfortunately, my understanding of databases under-the-hood is fairly tenuous (a big part of why I'm leaning on prisma in the first place :)

What you're saying does seem plausible... Its not immediately clear to me, though, how to test out an alternative that would result in different SQL queries (or alternately-sequenced SQL queries)... My first guess is that this is mostly up to prisma.

Perhaps something related to transactions? Perhaps resorting to "raw" sql queries, made via prisma (though it doesn't seem like that should ever really be necessary...)?

[fowled]

I'm not sure either to be honest, I'm relying on Prisma to simplify CRUD operations as well 😅

I noticed one thing using Prisma Studio though, every time I refresh an API page (that uses express-session), the expiresAt record of the session changes... and the error appears.

Is that a normal behavior? I thought that the expiresAt column was supposed to contain dates that don't change over time, pointing to when a session expires.

Here's what I mean:

2022-05-22.15-22-06.mp4

[kleydon]

Hi @fowled - sorry for the late reply here...

I haven't checked the express session docs yet to be certain, but I'm pretty sure that there is a setting (possibly the default behavior?) governing whether or not expiresAt gets updated, each time the session is requested via express...

My hunch is that refreshing the page is causing a request to occur, via express, that automatically updates expiresAt.

Hope this helps...

[fowled]

Thanks for the update @kleydon.

I just changed several things in my configuration file:

app.use([
    session({
	secret: process.env.SESSION_SECRET,
	cookie: { secure: !process.env.SECURE_COOKIE, maxAge: 1000 * 60 * 60 * 24 * 7 },
	resave: false,
	saveUninitialized: false,
	store: new PrismaSessionStore(database, { loggerLevel: "log" }),
    }),
]);

and a new error shows up, pointing to this function:

{
  /**
   * Refresh the time-to-live for the session with the given `sid`.
   *
   * @param sid the id of the session to refresh
   * @param session the data of the session to resave
   * @param callback a callback notifying that the refresh was completed
   * or that an error occurred
   */
  public readonly touch = async (
    sid: string,
    session: PartialDeep<SessionData>,
    callback?: (err?: unknown) => void
  ) => {
    if (!(await this.validateConnection())) return callback?.();

    const ttl = getTTL(this.options, session, sid);
    const expiresAt = createExpiration(ttl, {
      rounding: this.options.roundTTL,
    });

    try {
      const existingSession = await this.prisma[
        this.sessionModelName
      ].findUnique({
        where: { sid },
      });

      if (existingSession !== null) {
        const existingSessionData = {
          ...this.serializer.parse(existingSession.data ?? '{}'),
          cookie: session.cookie,
        };

        await this.prisma[this.sessionModelName].update({
          where: { sid: existingSession.sid },
          data: {
            expiresAt,
            data: this.serializer.stringify(existingSessionData),
          },
        });
      }

      // *** If there is no found session, for some reason, should it be recreated from sess *** ?
      if (callback) defer(callback);
    } catch (e: unknown) {
      this.logger.error(`touch(): ${String(e)}`);
      if (callback) defer(callback, e);
    }
  };
}

I ended up deleting it in the node_modules source file, and two things happened:

• The error doesn't show up anymore.
• The expiresAt session value stays the same as when it was initialized.

I haven't checked the express session docs yet to be certain, but I'm pretty sure that there is a setting (possibly the default behavior?) governing whether or not expiresAt gets updated, each time the session is requested via express...

After some research, I couldn't find anything in the docs in that regard.
And that's what made me think the error was related to this session expiration value updating, as it wasn't the case when I was using the connect-session-sequelize module, before migrating to Prisma.

Of course, my hacky workaround isn't the best, and I'm probably missing a key feature of your module now. Do you know what is the purpose of that touch function, and at what moment is it called?

[fowled]

Hold up... I just noticed my issue was exactly what @lachezargrigorov reported here: #64

And I can confirm that the expiresAt value updates even with resave: true and rolling: false.

[kleydon]

Hi @fowled,

Do you know what is the purpose of that touch function, and at what moment is it called?

I believe that the purpose of touch is primarily to "update" the timestamp - like the way the touch command in unix/linux does for files.

I'm not sure when exactly touch is called though... (It could be that it isn't called directly within the prisma-session-store library, but that prisma-session-store supplies it in order for express session to be able to call it.

Unfortunately I don't have much time this week to drill into this... If I did though, I would probably first look through references to touch in express-session: open/closed issues, etc - particularly where expiresAt and/or resave and/or rolling are mentioned. I have a vague (perhaps imagined?) memory that there was a remaining ambiguity about the conditions under which expiresAt is/is not updated - but unfortunately I'm not remembering it here.)

And I can confirm that the expiresAt value updates even with resave: true and rolling: false.

Good to know; hopefully this will help in narrowing down what's happening / is expected to happen.

[TamirCode]

using nestjs prisma postgres

did exactly whats written in docs

console when i log out (destroy session)

Error:
Invalid `this.prisma[this.sessionModelName].update()` invocation in
C:\Users\<retracted>\Desktop\CLONES\<retracted>\backend\node_modules\@quixo3\prisma-session-store\dist\lib\prisma-session-store.js:547:81

   544 existingSession = _b.sent();
   545 if (!(existingSession !== null)) return [3 /*break*/, 5];
   546 existingSessionData = __assign(__assign({}, this.serializer.parse((_a = existingSession.data) !== null && _a !== void 0 ? _a : '{}')), { cookie: session.cookie });
→  547 return [4 /*yield*/, this.prisma[this.sessionModelName].update(
  An operation failed because it depends on one or more records that were required but not found. Record to update not found.
    at RequestHandler.handleRequestError (C:\Users\<retracted>\Desktop\CLONES\<retracted>\backend\node_modules\@prisma\client\runtime\index.js:28838:13)
    at RequestHandler.request (C:\Users\<retracted>\Desktop\CLONES\<retracted>\backend\node_modules\@prisma\client\runtime\index.js:28820:12)
    at PrismaClient._request (C:\Users\<retracted>\Desktop\CLONES\<retracted>\backend\node_modules\@prisma\client\runtime\index.js:29753:16)
    ```

[TamirCode]

it seems to be working for me now, not sure what I did, perhaps lots of restarts to server .. hopefully it wont return
for context here is my destroy session

logout(req: any) {
	if (!req.session.user) {
		return { err: "must be logged" }
	}
	req.session.destroy()
	return { msg: "Logged out successfully." }
}

[TamirCode]

yea unfortunately the error returns randomly when i try to log out. I can't use this package until it's fixed sadly

[kleydon]

Hi @TamirCode - Sorry to hear it. I'm a bit limited to work on this time-wise right now, but hopefully there are others who can investigate?

[msurdi]

I'm using v3.1.9 with prisma v4.3.0 and I was having the same problem.

I found out that if I reloaded my app quickly (CMD+R in the browser), the error was more likely to happen. And tracing back (and by some other explanations on this thread) the culprit seems to be the touch calls that express-session does for every request that goes through the session middleware.

So when my application loaded a view (html), parallel requests are triggered by the browser to download all the CSS/JS assets, and due to the middleware ordering I had a session was being set up even for static assets. This means in a very short amount of time, several concurrent request to my backend were made, all of them trying to touch the session. As far as I understand it (far from expert on this) SQLite has limited support for concurrent write, and I suspect it would be even worse if all those writes are to the same exact record. Here are some nice answers and explanations about this.

So after I inverted the order of the middlewares in my express application (so that first assets are served from express, and later if no asset is served, a session is setup and then my handlers take over) the problem stopped happening.

Given I was still concerned about multiple concurrent requests (by the same user) "touching" the same record in the database in a very limited period of time, I ended up writing my own "Prisma session store" for learning/understanding purposes (which you can find here) and I ended up doing the following workaround so no multiple "touches" happen to the same record concurrently. The specific part of the code that implements this protection is here for reference:

async touch(sid, session, cb) {
    if (this.isTouching[sid]) {
      return cb();
    }
    this.isTouching[sid] = true;
    try {
      await this.db.session.update({
        where: { sid },
        data: { data: JSON.stringify(session) },
      });
    } finally {
      delete this.isTouching[sid];
    }
    return cb();
 }

So, even if probably this is more like a "workaround" than a proper solution, I think for this specific library, one could create a child class of PrismaSessionStore and override the touch method, to include this protection against concurrent touches. I haven't done this myself as my own minimalistic implementation of this feature seems to be working fine so far (disclaimer: not tested in production, I'm only using it on a side/toy project of mine).

Hope this helps others with this problem 👍

[kleydon]

@msurdi Appreciate your notes / insight.

You mentioned that you fixed the problem by inverting the order of your middlewares, and then you added the set of isTouching flags, and so I'm curious: Did you happen to try the code above with the original ordering of the middlewares - to verify that it does in fact offer the same protection as inverting the middlewares ultimately did?

If not: Is there any chance you might be willing to try a quick test? For science :)?

I'm considering adding this "workaround" fix to the lib, but its hard for me to test/verify, because I've never seen this behavior... I'd dearly love to know whether the approach you offer above definitely fixed things (in the context of your side project), or whether this remains an unknown...

Thanks again for posting,

-K

[msurdi]

Hi @kleydon! I've just pushed this minimal example to reproduce the issue and the workarounds I've found so far. Instructions are in the readme and in the code comments.

Hope it helps to find a better solution to this problem.

[kleydon]

Appreciate it, @msurdi!

I'm pretty short on time these days - so I may end up temporarily adding just a work-around but - glad that there is a repro that will allow this to be explored properly at some point.

[kleydon]

Just posted PR #104, to help fix this issue, at least as a work-around for the moment; and would love to get eyes on it... @msurdi, any chance you might be willing to take a look, and see if there's anything obviously wrong with it?

[kleydon]

PR #104 merged.

[msurdi]

Sorry for my late answer, I've been travelling all over the weekend.

I've just looked at the changes and they look good to me. Thanks for addressing this.

[fowled]

I don't seem to be getting the error after having updated.

Thanks @kleydon!

[kleydon]

@msurdi - no worries; appreciate your being willing to take a look (and thanks for "cracking the case", earlier!) Its not 100% clear to me whether the issue you identified is the only one that people are experiencing / referencing here, but - glad that at least one part of the problem is clearer now, and has a work-around...

[kleydon]

@fowled - Glad to hear. Appreciate your taking a look!

[kleydon]

Going to go out on a limb here, and call this issue solved-for-the-moment (albeit with a work-around).
Of others experience the issue (or something that seems similar) going forward, please post what you are seeing.