search

empiricaly / empirica

Open source project to tackle the problem of long development cycles required to produce software to conduct multi-participant and real-time human experiments online.
https://empirica.ly/
Apache License 2.0
44 stars 8 forks source link

Callbacks can trigger multiple times #453

Closed JamesPHoughton closed 5 months ago

JamesPHoughton commented 9 months ago

Is there an existing issue for this?

What happened?

I initialize a number of things in my game start callback, and in the most recent version, I'm finding that these are occasionally being called twice. I put in a log statement at the top of the function as below:

Empirica.on("game", "start", async (ctx, { game, start }) => {
  if (!start) return;
  warn(
    `Game ${game.id} on game start callback. Now: ${new Date(
      Date.now()
    ).toISOString()}, started: ${game.get("timeStarted")}`
  );
...
  // last steps in check
  game.set("timeStarted", new Date(Date.now()).toISOString());
  info(`Game is now starting with players: ${identifiers}`);
});

This shows the callback getting called a second time, about 50 ms after the first, and the initialization tasks running twice:

[server] 01:56:15.483 WRN Game 01HH0ZTSYYP0Q7J79DV32BJCCN on game start callback. Now: 2023-12-07T01:56:15.483Z, started: undefined
[server] 01:56:15.483 INF Player 01HH0ZTGNJKKACX2X4BH09DTJ3 assigned position 0 and title undefined
[server] 01:56:15.483 INF Player 01HH0ZTHAYWBNWQQ2GCP9BMRQX assigned position 1 and title undefined
[server] 01:56:15.487 INF Creating daily room for game 01HH0ZTSYYP0Q7J79DV32BJCCN
[server] 01:56:15.528 WRN Game 01HH0ZTSYYP0Q7J79DV32BJCCN on game start callback. Now: 2023-12-07T01:56:15.528Z, started: undefined
[server] 01:56:15.528 INF Player 01HH0ZTGNJKKACX2X4BH09DTJ3 assigned position 1 and title undefined
[server] 01:56:15.528 INF Player 01HH0ZTHAYWBNWQQ2GCP9BMRQX assigned position 0 and title undefined
[server] 01:56:15.529 INF Creating daily room for game 01HH0ZTSYYP0Q7J79DV32BJCCN

[server] 01:56:16.456 ERR Requested creation of existing room 20231207_0155_cytest2BJCCN. Returning existing room details

Steps To Reproduce

This is unfortunately a bit intermittent, but it seems to come up at least once each time I run my test suite.

Empirica Version

Version: v1.8.9
SHA:     254e004
Branch:  main
Time:    2023-12-06T01:17:31Z

Client:  1.8.9
Server:  1.8.9

What OS are you seeing the problem on?

Linux

What browser are you seeing the problem on?

Does not apply

Relevant log output

No response

Anything else?

I'm not sure if it is just the game start callback where this happens. Unfortunately the second fire happens before the first is complete, making idempotency checking awkward.

Code of Conduct

npaton commented 9 months ago

So the game start callback is fairly slow, right? I see "Game is now starting with players" is not reached on the first call. The callback does eventually go through, right? No errors?

I am not sure why it's called twice. It really shouldn't. The value for "start" on game, if it hasn't changed, shouldn't allow to be set again. Though there could be some race condition. I looked into adding deduping, but it's hard to simulate, and know if it would work. If you get a chance, you can try to run with --log.level trace. It might get pretty noisy. But when happens again, it might provide some more info.

empirica --log.level trace
JamesPHoughton commented 9 months ago

Here's an example with the trace level logs. (this is a continuous log, that I've broken into chunks to narrate)

This is from a test case where I launch 4 games all at once: 

[server] 11:32:34.468 INF dispatch: 0 in intro steps, 8 in lobby, 0 in games
[server] 11:32:34.469 TRC SET assigned = true (01HHCVHJEQVFV6AMKCD8TWQ3A8)
[server] 11:32:34.469 TRC SET assigned = true (01HHCVHH1RKZ4BQCE6KFG37Q4E)
[server] 11:32:34.469 INF Adding game with treatment cypress2_simple, players 01HHCVHJEQVFV6AMKCD8TWQ3A8,01HHCVHH1RKZ4BQCE6KFG37Q4E
[server] 11:32:34.469 TRC SET assigned = true (01HHCVHG8RXTTKW7VW252G7NJ7)
[server] 11:32:34.469 TRC SET assigned = true (01HHCVHFJ284E4N2K0J1H3ARXH)
[server] 11:32:34.469 INF Adding game with treatment cypress2_simple, players 01HHCVHG8RXTTKW7VW252G7NJ7,01HHCVHFJ284E4N2K0J1H3ARXH
[server] 11:32:34.470 TRC SET assigned = true (01HHCVHEVV6K8P97DCF0PMBQ55)
[server] 11:32:34.470 TRC SET assigned = true (01HHCVHK55W5BH2T6D2GW4005C)
[server] 11:32:34.470 INF Adding game with treatment cypress2_simple, players 01HHCVHEVV6K8P97DCF0PMBQ55,01HHCVHK55W5BH2T6D2GW4005C
[server] 11:32:34.470 TRC SET assigned = true (01HHCVHE59STWDGHKF2T8FDRCS)
[server] 11:32:34.470 TRC SET assigned = true (01HHCVHHR6KH7EVM9YSWV9FC5B)
[server] 11:32:34.470 INF Adding game with treatment cypress2_simple, players 01HHCVHE59STWDGHKF2T8FDRCS,01HHCVHHR6KH7EVM9YSWV9FC5B

This creates four different games:

The first game (ending in TAGR) is the one that will have it's callback called twice.

When the game is created we set a bunch of stuff, and then start the game. There are also some logs for other games interspersed

[server] 11:32:34.473 TRC SET ran-before-01HHCVJ8N8PTQC6R38XQ8ZAR1D = true (01HHCVJ8N8PTQC6R38XCB7TAGR)
[server] 11:32:34.473 TRC SET ran-on-01HHCVJ8N8PTQC6R38XTP7K4R7 = true (01HHCVJ8N8PTQC6R38XCB7TAGR)
[server] 11:32:34.474 TRC SET ran-after-01HHCVJ8N8PTQC6R38XTP7K4R7 = true (01HHCVJ8N8PTQC6R38XCB7TAGR)
[server] 11:32:34.475 TRC SET ran-before-01HHCVJ8N8PTQC6R38XAFEH3SP = true (01HHCVJ8N8PTQC6R38X3T1R53K)
[server] 11:32:34.475 TRC SET ran-on-01HHCVJ8N8PTQC6R38XBM6AYBZ = true (01HHCVJ8N8PTQC6R38X3T1R53K)
[server] 11:32:34.476 TRC SET ran-after-01HHCVJ8N8PTQC6R38XBM6AYBZ = true (01HHCVJ8N8PTQC6R38X3T1R53K)
[server] 11:32:34.477 TRC SET ran-before-01HHCVJ8N8PTQC6R38Y45HHGZS = true (01HHCVJ8N8PTQC6R38XWC99A4B)
[server] 11:32:34.477 TRC SET ran-on-01HHCVJ8N8PTQC6R38Y5QK5WE5 = true (01HHCVJ8N8PTQC6R38XWC99A4B)
[server] 11:32:34.477 TRC SET ran-after-01HHCVJ8N8PTQC6R38Y5QK5WE5 = true (01HHCVJ8N8PTQC6R38XWC99A4B)
[server] 11:32:34.478 TRC SET ran-before-01HHCVJ8N8PTQC6R38YKS45E8W = true (01HHCVJ8N8PTQC6R38Y6SM9GG0)
[server] 11:32:34.478 TRC SET ran-on-01HHCVJ8N8PTQC6R38YQ7S37QF = true (01HHCVJ8N8PTQC6R38Y6SM9GG0)
[server] 11:32:34.478 TRC SET ran-after-01HHCVJ8N8PTQC6R38YQ7S37QF = true (01HHCVJ8N8PTQC6R38Y6SM9GG0)
[server] 11:32:34.480 TRC SET groupID = 01HHCVJ8NF01433SJVV61D4YET (01HHCVJ8N8PTQC6R38XCB7TAGR)
[server] 11:32:34.481 TRC SET ran-after-01HHCVJ8N8PTQC6R38Y45HHGZS = true (01HHCVJ8N8PTQC6R38XWC99A4B)
[server] 11:32:34.482 TRC SET ran-after-01HHCVJ8N8PTQC6R38YKS45E8W = true (01HHCVJ8N8PTQC6R38Y6SM9GG0)
[server] 11:32:34.483 TRC SET ran-after-01HHCVJ8N8PTQC6R38XQ8ZAR1D = true (01HHCVJ8N8PTQC6R38XCB7TAGR)
[server] 11:32:34.485 TRC SET ran-after-01HHCVJ8N8PTQC6R38XAFEH3SP = true (01HHCVJ8N8PTQC6R38X3T1R53K)
[server] 11:32:34.487 TRC SET gameId = 01HHCVJ8N8PTQC6R38XCB7TAGR (01HHCVHJEQVFV6AMKCD8TWQ3A8)
[server] 11:32:34.487 TRC SET gameID = 01HHCVJ8N8PTQC6R38XCB7TAGR (01HHCVHJEQVFV6AMKCD8TWQ3A8)
[server] 11:32:34.487 TRC SET treatment = [object Object] (01HHCVHJEQVFV6AMKCD8TWQ3A8)
[server] 11:32:34.487 TRC SET treatmentName = cypress2_simple (01HHCVHJEQVFV6AMKCD8TWQ3A8)
[server] 11:32:34.490 TRC SET gameId = 01HHCVJ8N8PTQC6R38XCB7TAGR (01HHCVHH1RKZ4BQCE6KFG37Q4E)
[server] 11:32:34.490 TRC SET gameID = 01HHCVJ8N8PTQC6R38XCB7TAGR (01HHCVHH1RKZ4BQCE6KFG37Q4E)
[server] 11:32:34.490 TRC SET treatment = [object Object] (01HHCVHH1RKZ4BQCE6KFG37Q4E)
[server] 11:32:34.490 TRC SET treatmentName = cypress2_simple (01HHCVHH1RKZ4BQCE6KFG37Q4E)
[server] 11:32:34.492 TRC SET initialized = true (01HHCVJ8N8PTQC6R38XCB7TAGR)
[server] 11:32:34.492 TRC SET start = true (01HHCVJ8N8PTQC6R38XCB7TAGR)

The last line which sets the game start attribute fires the callback for the game start. This logs that it's been called and does a bunch of other stuff, ending with setting the time that the game was started.

[server] 11:32:34.494 WRN Game 01HHCVJ8N8PTQC6R38XCB7TAGR on game start callback. Now: 2023-12-11T16:32:34.494Z, started: undefined 
[server] 11:32:34.494 TRC SET sampleId = 4618947e-ed37-415b-85ba-259f11f0ce43 (01HHCVHH1RKZ4BQCE6KFG37Q4E)
[server] 11:32:34.495 INF Pushing preregistration to github in 60 seconds
[server] 11:32:34.495 TRC SET sampleId = 2e97e876-1c6c-4081-8e71-fda1a0627ec0 (01HHCVHJEQVFV6AMKCD8TWQ3A8)
[server] 11:32:34.495 TRC SET position = 0 (01HHCVHH1RKZ4BQCE6KFG37Q4E)
[server] 11:32:34.495 TRC SET title =  (01HHCVHH1RKZ4BQCE6KFG37Q4E)
[server] 11:32:34.495 INF Player 01HHCVHH1RKZ4BQCE6KFG37Q4E assigned position 0 and title undefined
[server] 11:32:34.495 TRC SET position = 1 (01HHCVHJEQVFV6AMKCD8TWQ3A8)
[server] 11:32:34.495 TRC SET title =  (01HHCVHJEQVFV6AMKCD8TWQ3A8)
[server] 11:32:34.495 INF Player 01HHCVHJEQVFV6AMKCD8TWQ3A8 assigned position 1 and title undefined
[server] 11:32:34.495 TRC SET roundIndex = 0 (01HHCVJ8N8PTQC6R38XCB7TAGR)
[server] 11:32:34.496 INF Creating daily room for game 01HHCVJ8N8PTQC6R38XCB7TAGR
[server] 11:32:34.496 TRC SET recordingsFolder = 20231211_1632_cytestB7TAGR (01HHCVJ8N8PTQC6R38XCB7TAGR)
[server] 11:32:34.500 TRC SET ran-before-01HHCVJ8P3HFS5WZY9FC8VW9PX = true (01HHCVJ8P3HFS5WZY9F1Q04YXS)
[server] 11:32:34.500 TRC SET ran-after-01HHCVJ8P3HFS5WZY9FDAWBS9E = true (01HHCVJ8P3HFS5WZY9F1Q04YXS)
[server] 11:32:34.505 TRC SET ran-after-01HHCVJ8P3HFS5WZY9FC8VW9PX = true (01HHCVJ8P3HFS5WZY9F1Q04YXS)
[server] 11:32:34.507 TRC SET groupID = 01HHCVJ8PAEJYJDH44CFKH3HNX (01HHCVJ8N8PTQC6R38X3T1R53K)
[server] 11:32:34.508 TRC SET stageIndex = 1 (01HHCVJ8P3HFS5WZY9F1Q04YXS)
[server] 11:32:34.515 TRC SET gameId = 01HHCVJ8N8PTQC6R38X3T1R53K (01HHCVHG8RXTTKW7VW252G7NJ7)
[server] 11:32:34.515 TRC SET gameID = 01HHCVJ8N8PTQC6R38X3T1R53K (01HHCVHG8RXTTKW7VW252G7NJ7)
[server] 11:32:34.515 TRC SET treatment = [object Object] (01HHCVHG8RXTTKW7VW252G7NJ7)
[server] 11:32:34.515 TRC SET treatmentName = cypress2_simple (01HHCVHG8RXTTKW7VW252G7NJ7)
[server] 11:32:34.517 TRC SET ran-before-01HHCVJ8PKCMCQG7K41WV3NP9X = true (01HHCVJ8PKCMCQG7K41CTJVP85)
[server] 11:32:34.518 TRC SET ran-after-01HHCVJ8PKCMCQG7K4201G4Z20 = true (01HHCVJ8PKCMCQG7K41CTJVP85)
[server] 11:32:34.518 TRC SET ran-after-01HHCVJ8PKCMCQG7K41WV3NP9X = true (01HHCVJ8PKCMCQG7K41CTJVP85)
[server] 11:32:34.521 TRC SET gameId = 01HHCVJ8N8PTQC6R38X3T1R53K (01HHCVHFJ284E4N2K0J1H3ARXH)
[server] 11:32:34.521 TRC SET gameID = 01HHCVJ8N8PTQC6R38X3T1R53K (01HHCVHFJ284E4N2K0J1H3ARXH)
[server] 11:32:34.521 TRC SET treatment = [object Object] (01HHCVHFJ284E4N2K0J1H3ARXH)
[server] 11:32:34.521 TRC SET treatmentName = cypress2_simple (01HHCVHFJ284E4N2K0J1H3ARXH)

While this is going on, the game creation callbacks for the other games are also running, and spewing logs. This includes setting start=true for two other games, presumably triggering their game start callbacks.

[server] 11:32:34.524 TRC SET initialized = true (01HHCVJ8N8PTQC6R38X3T1R53K)
[server] 11:32:34.524 TRC SET start = true (01HHCVJ8N8PTQC6R38X3T1R53K)
[server] 11:32:34.529 TRC SET groupID = 01HHCVJ8Q0M7GR4X6VK364XC9E (01HHCVJ8N8PTQC6R38XWC99A4B)
[server] 11:32:34.530 TRC SET gameId = 01HHCVJ8N8PTQC6R38XWC99A4B (01HHCVHEVV6K8P97DCF0PMBQ55)
[server] 11:32:34.530 TRC SET gameID = 01HHCVJ8N8PTQC6R38XWC99A4B (01HHCVHEVV6K8P97DCF0PMBQ55)
[server] 11:32:34.530 TRC SET treatment = [object Object] (01HHCVHEVV6K8P97DCF0PMBQ55)
[server] 11:32:34.530 TRC SET treatmentName = cypress2_simple (01HHCVHEVV6K8P97DCF0PMBQ55)
[server] 11:32:34.532 TRC SET gameId = 01HHCVJ8N8PTQC6R38XWC99A4B (01HHCVHK55W5BH2T6D2GW4005C)
[server] 11:32:34.532 TRC SET gameID = 01HHCVJ8N8PTQC6R38XWC99A4B (01HHCVHK55W5BH2T6D2GW4005C)
[server] 11:32:34.532 TRC SET treatment = [object Object] (01HHCVHK55W5BH2T6D2GW4005C)
[server] 11:32:34.532 TRC SET treatmentName = cypress2_simple (01HHCVHK55W5BH2T6D2GW4005C)
[server] 11:32:34.536 TRC SET initialized = true (01HHCVJ8N8PTQC6R38XWC99A4B)
[server] 11:32:34.536 TRC SET start = true (01HHCVJ8N8PTQC6R38XWC99A4B)
[server] 11:32:34.538 TRC SET playerGameID-01HHCVJ8N8PTQC6R38XCB7TAGR = 01HHCVJ8Q9N3DYYT90G6WKDVJN (01HHCVHH1RKZ4BQCE6KFG37Q4E)
[server] 11:32:34.541 TRC SET playerGameID-01HHCVJ8N8PTQC6R38XCB7TAGR = 01HHCVJ8QC24M7DQ04M4TRVPY9 (01HHCVHJEQVFV6AMKCD8TWQ3A8)
[server] 11:32:34.541 TRC SET ran-before-01HHCVJ8P3HFS5WZY9FS5GE69D = true (01HHCVJ8N8PTQC6R38XCB7TAGR)
[server] 11:32:34.544 TRC SET groupID = 01HHCVJ8QG6S4BT8AGR5EN52HC (01HHCVJ8N8PTQC6R38Y6SM9GG0)

Before the first callback can complete, instead of calling the callback for the next game, it starts the callback again for the first game:

[server] 11:32:34.546 WRN Game 01HHCVJ8N8PTQC6R38XCB7TAGR on game start callback. Now: 2023-12-11T16:32:34.546Z, started: undefined
[server] 11:32:34.546 TRC SET sampleId = 88e9022d-772b-40db-a51c-da55f3a126a2 (01HHCVHH1RKZ4BQCE6KFG37Q4E)
[server] 11:32:34.546 TRC SET sampleId = e1fb5c1c-f751-4c30-801d-e79442cae709 (01HHCVHJEQVFV6AMKCD8TWQ3A8)
[server] 11:32:34.547 TRC SET position = 0 (01HHCVHH1RKZ4BQCE6KFG37Q4E)
[server] 11:32:34.547 TRC SET title =  (01HHCVHH1RKZ4BQCE6KFG37Q4E)
[server] 11:32:34.547 INF Player 01HHCVHH1RKZ4BQCE6KFG37Q4E assigned position 0 and title undefined
[server] 11:32:34.547 TRC SET position = 1 (01HHCVHJEQVFV6AMKCD8TWQ3A8)
[server] 11:32:34.547 TRC SET title =  (01HHCVHJEQVFV6AMKCD8TWQ3A8)
[server] 11:32:34.547 INF Player 01HHCVHJEQVFV6AMKCD8TWQ3A8 assigned position 1 and title undefined
[server] 11:32:34.547 TRC SET roundIndex = 1 (01HHCVJ8N8PTQC6R38XCB7TAGR)
[server] 11:32:34.547 INF Creating daily room for game 01HHCVJ8N8PTQC6R38XCB7TAGR
[server] 11:32:34.547 TRC SET recordingsFolder = 20231211_1632_cytestB7TAGR (01HHCVJ8N8PTQC6R38XCB7TAGR)
[server] 11:32:34.551 TRC SET ran-before-01HHCVJ8QP69K011PW4862NFXE = true (01HHCVJ8QP69K011PW3SC2Z3Y8)
[server] 11:32:34.551 TRC SET ran-after-01HHCVJ8QP69K011PW4BCNT6YE = true (01HHCVJ8QP69K011PW3SC2Z3Y8)
[server] 11:32:34.557 TRC SET stageIndex = 1 (01HHCVJ8QP69K011PW3SC2Z3Y8)
[server] 11:32:34.557 TRC SET playerGameID-01HHCVJ8N8PTQC6R38X3T1R53K = 01HHCVJ8QW2ZYP0VAWHD945V4M (01HHCVHFJ284E4N2K0J1H3ARXH)
[server] 11:32:34.558 TRC SET playerGameID-01HHCVJ8N8PTQC6R38XWC99A4B = 01HHCVJ8QXA5BCDAKBJN1W9TJ7 (01HHCVHEVV6K8P97DCF0PMBQ55)
[server] 11:32:34.559 TRC SET ran-after-01HHCVJ8QP69K011PW4862NFXE = true (01HHCVJ8QP69K011PW3SC2Z3Y8)
[server] 11:32:34.561 TRC SET playerGameID-01HHCVJ8N8PTQC6R38XWC99A4B = 01HHCVJ8R0M14GVT8GN66RP4YY (01HHCVHK55W5BH2T6D2GW4005C)
[server] 11:32:34.561 TRC SET ran-before-01HHCVJ8QC24M7DQ04ME3JMCGX = true (01HHCVJ8N8PTQC6R38XWC99A4B)
[server] 11:32:34.563 TRC SET playerGameID-01HHCVJ8N8PTQC6R38X3T1R53K = 01HHCVJ8R0M14GVT8GMYYD2EB0 (01HHCVHG8RXTTKW7VW252G7NJ7)
[server] 11:32:34.563 TRC SET ran-before-01HHCVJ8PXPYGPASN11DNH9XE5 = true (01HHCVJ8N8PTQC6R38X3T1R53K)
[server] 11:32:34.564 TRC SET ran-before-01HHCVJ8R0M14GVT8GMPF73A8X = true (01HHCVJ8R0M14GVT8GMA1KXVFB)
[server] 11:32:34.564 TRC SET ran-after-01HHCVJ8R0M14GVT8GMRCA13X0 = true (01HHCVJ8R0M14GVT8GMA1KXVFB)
[server] 11:32:34.565 TRC SET gameId = 01HHCVJ8N8PTQC6R38Y6SM9GG0 (01HHCVHE59STWDGHKF2T8FDRCS)
[server] 11:32:34.565 TRC SET gameID = 01HHCVJ8N8PTQC6R38Y6SM9GG0 (01HHCVHE59STWDGHKF2T8FDRCS)
[server] 11:32:34.565 TRC SET treatment = [object Object] (01HHCVHE59STWDGHKF2T8FDRCS)
[server] 11:32:34.565 TRC SET treatmentName = cypress2_simple (01HHCVHE59STWDGHKF2T8FDRCS)
[server] 11:32:34.565 TRC SET ran-after-01HHCVJ8R0M14GVT8GMPF73A8X = true (01HHCVJ8R0M14GVT8GMA1KXVFB)

It does eventually run the callback for the remaining three games - game 3 next

[server] 11:32:34.568 WRN Game 01HHCVJ8N8PTQC6R38XWC99A4B on game start callback. Now: 2023-12-11T16:32:34.568Z, started: undefined
[server] 11:32:34.568 TRC SET sampleId = 23dde6a0-8858-4c19-baf2-01a088a4e3f7 (01HHCVHEVV6K8P97DCF0PMBQ55)
[server] 11:32:34.569 TRC SET sampleId = 2a07a9b3-b5de-482e-bdf4-e0d776b7ce6b (01HHCVHK55W5BH2T6D2GW4005C)
[server] 11:32:34.569 TRC SET position = 1 (01HHCVHEVV6K8P97DCF0PMBQ55)
[server] 11:32:34.569 TRC SET title =  (01HHCVHEVV6K8P97DCF0PMBQ55)
[server] 11:32:34.569 INF Player 01HHCVHEVV6K8P97DCF0PMBQ55 assigned position 1 and title undefined
[server] 11:32:34.569 TRC SET position = 0 (01HHCVHK55W5BH2T6D2GW4005C)
[server] 11:32:34.569 TRC SET title =  (01HHCVHK55W5BH2T6D2GW4005C)
[server] 11:32:34.569 INF Player 01HHCVHK55W5BH2T6D2GW4005C assigned position 0 and title undefined
[server] 11:32:34.569 TRC SET roundIndex = 0 (01HHCVJ8N8PTQC6R38XWC99A4B)
[server] 11:32:34.570 INF Creating daily room for game 01HHCVJ8N8PTQC6R38XWC99A4B
[server] 11:32:34.570 TRC SET recordingsFolder = 20231211_1632_cytestC99A4B (01HHCVJ8N8PTQC6R38XWC99A4B)
[server] 11:32:34.572 TRC SET gameId = 01HHCVJ8N8PTQC6R38Y6SM9GG0 (01HHCVHHR6KH7EVM9YSWV9FC5B)
[server] 11:32:34.572 TRC SET gameID = 01HHCVJ8N8PTQC6R38Y6SM9GG0 (01HHCVHHR6KH7EVM9YSWV9FC5B)
[server] 11:32:34.572 TRC SET treatment = [object Object] (01HHCVHHR6KH7EVM9YSWV9FC5B)
[server] 11:32:34.572 TRC SET treatmentName = cypress2_simple (01HHCVHHR6KH7EVM9YSWV9FC5B)
[server] 11:32:34.574 TRC SET ran-before-01HHCVJ8RDFB96ADCC7GJ24HFK = true (01HHCVJ8RDFB96ADCC735MPBWW)
[server] 11:32:34.574 TRC SET ran-after-01HHCVJ8RDFB96ADCC7J7651BC = true (01HHCVJ8RDFB96ADCC735MPBWW)
[server] 11:32:34.577 TRC SET initialized = true (01HHCVJ8N8PTQC6R38Y6SM9GG0)
[server] 11:32:34.577 TRC SET start = true (01HHCVJ8N8PTQC6R38Y6SM9GG0)
[server] 11:32:34.581 TRC SET stageIndex = 1 (01HHCVJ8RDFB96ADCC735MPBWW)
[server] 11:32:34.582 TRC SET ran-after-01HHCVJ8RDFB96ADCC7GJ24HFK = true (01HHCVJ8RDFB96ADCC735MPBWW)
[server] 11:32:34.585 TRC SET ran-before-01HHCVJ8RQZZHQ7DEECXVK57SG = true (01HHCVJ8RQZZHQ7DEECKTVA6TX)
[server] 11:32:34.585 TRC SET ran-after-01HHCVJ8RQZZHQ7DEED0SB082D = true (01HHCVJ8RQZZHQ7DEECKTVA6TX)

Then game 2:

[server] 11:32:34.586 WRN Game 01HHCVJ8N8PTQC6R38X3T1R53K on game start callback. Now: 2023-12-11T16:32:34.586Z, started: undefined
[server] 11:32:34.586 TRC SET sampleId = 9016159d-96d9-4a89-8a85-519c494003b3 (01HHCVHFJ284E4N2K0J1H3ARXH)
[server] 11:32:34.587 TRC SET sampleId = 1794d068-d64a-4f2e-9afe-c04dac8991b7 (01HHCVHG8RXTTKW7VW252G7NJ7)
[server] 11:32:34.587 TRC SET position = 1 (01HHCVHFJ284E4N2K0J1H3ARXH)
[server] 11:32:34.587 TRC SET title =  (01HHCVHFJ284E4N2K0J1H3ARXH)
[server] 11:32:34.587 INF Player 01HHCVHFJ284E4N2K0J1H3ARXH assigned position 1 and title undefined
[server] 11:32:34.587 TRC SET position = 0 (01HHCVHG8RXTTKW7VW252G7NJ7)
[server] 11:32:34.587 TRC SET title =  (01HHCVHG8RXTTKW7VW252G7NJ7)
[server] 11:32:34.587 INF Player 01HHCVHG8RXTTKW7VW252G7NJ7 assigned position 0 and title undefined
[server] 11:32:34.587 TRC SET roundIndex = 0 (01HHCVJ8N8PTQC6R38X3T1R53K)
[server] 11:32:34.587 INF Creating daily room for game 01HHCVJ8N8PTQC6R38X3T1R53K
[server] 11:32:34.587 TRC SET recordingsFolder = 20231211_1632_cytestT1R53K (01HHCVJ8N8PTQC6R38X3T1R53K)
[server] 11:32:34.588 TRC SET ran-after-01HHCVJ8RQZZHQ7DEECXVK57SG = true (01HHCVJ8RQZZHQ7DEECKTVA6TX)
[server] 11:32:34.591 TRC SET ran-before-01HHCVJ8RYRRYT42P6PGB46HW5 = true (01HHCVJ8RYRRYT42P6P55TYYVQ)
[server] 11:32:34.591 TRC SET ran-after-01HHCVJ8RYRRYT42P6PM448W2Z = true (01HHCVJ8RYRRYT42P6P55TYYVQ)
[server] 11:32:34.594 TRC SET stageIndex = 1 (01HHCVJ8RYRRYT42P6P55TYYVQ)
[server] 11:32:34.595 TRC SET ran-after-01HHCVJ8RYRRYT42P6PGB46HW5 = true (01HHCVJ8RYRRYT42P6P55TYYVQ)
[server] 11:32:34.599 TRC SET ran-before-01HHCVJ8S5NQZCEKKW0R24WPD5 = true (01HHCVJ8S5NQZCEKKW0ARJRRES)
[server] 11:32:34.599 TRC SET ran-after-01HHCVJ8S5NQZCEKKW0VCE664E = true (01HHCVJ8S5NQZCEKKW0ARJRRES)
[server] 11:32:34.600 TRC SET ran-after-01HHCVJ8S5NQZCEKKW0R24WPD5 = true (01HHCVJ8S5NQZCEKKW0ARJRRES)
[server] 11:32:34.611 TRC SET playerGameID-01HHCVJ8N8PTQC6R38Y6SM9GG0 = 01HHCVJ8SJRAYPVRJYD1D6QDFT (01HHCVHE59STWDGHKF2T8FDRCS)
[server] 11:32:34.614 TRC SET playerGameID-01HHCVJ8N8PTQC6R38Y6SM9GG0 = 01HHCVJ8SNA5941JC2EDRKS6X2 (01HHCVHHR6KH7EVM9YSWV9FC5B)
[server] 11:32:34.614 TRC SET ran-before-01HHCVJ8RNPT8A4G97JQ751EN5 = true (01HHCVJ8N8PTQC6R38Y6SM9GG0)

Then game 4

[server] 11:32:34.614 WRN Game 01HHCVJ8N8PTQC6R38Y6SM9GG0 on game start callback. Now: 2023-12-11T16:32:34.614Z, started: undefined
[server] 11:32:34.614 TRC SET sampleId = 2e9c682e-d252-41c9-ba1f-94b0ec9031d9 (01HHCVHE59STWDGHKF2T8FDRCS)
[server] 11:32:34.615 TRC SET sampleId = 0f2abb49-921b-4035-8199-cad8cb7ee960 (01HHCVHHR6KH7EVM9YSWV9FC5B)
[server] 11:32:34.615 TRC SET position = 0 (01HHCVHE59STWDGHKF2T8FDRCS)
[server] 11:32:34.615 TRC SET title =  (01HHCVHE59STWDGHKF2T8FDRCS)
[server] 11:32:34.615 INF Player 01HHCVHE59STWDGHKF2T8FDRCS assigned position 0 and title undefined
[server] 11:32:34.615 TRC SET position = 1 (01HHCVHHR6KH7EVM9YSWV9FC5B)
[server] 11:32:34.615 TRC SET title =  (01HHCVHHR6KH7EVM9YSWV9FC5B)
[server] 11:32:34.615 INF Player 01HHCVHHR6KH7EVM9YSWV9FC5B assigned position 1 and title undefined
[server] 11:32:34.615 TRC SET roundIndex = 0 (01HHCVJ8N8PTQC6R38Y6SM9GG0)
[server] 11:32:34.615 INF Creating daily room for game 01HHCVJ8N8PTQC6R38Y6SM9GG0
[server] 11:32:34.615 TRC SET recordingsFolder = 20231211_1632_cytestSM9GG0 (01HHCVJ8N8PTQC6R38Y6SM9GG0)
[server] 11:32:34.619 TRC SET ran-before-01HHCVJ8STMWEVR6AM65FHJDAF = true (01HHCVJ8STMWEVR6AM5V0045C4)
[server] 11:32:34.619 TRC SET ran-after-01HHCVJ8STMWEVR6AM67JK7SP2 = true (01HHCVJ8STMWEVR6AM5V0045C4)
[server] 11:32:34.621 TRC SET stageIndex = 1 (01HHCVJ8STMWEVR6AM5V0045C4)
[server] 11:32:34.621 TRC SET ran-after-01HHCVJ8STMWEVR6AM65FHJDAF = true (01HHCVJ8STMWEVR6AM5V0045C4)
[server] 11:32:34.625 TRC SET ran-before-01HHCVJ8SZPDWEYWDSCZ0C3BCM = true (01HHCVJ8SZPDWEYWDSCJ37X1QC)
[server] 11:32:34.626 TRC SET ran-after-01HHCVJ8SZPDWEYWDSCZHN3WV2 = true (01HHCVJ8SZPDWEYWDSCJ37X1QC)
[server] 11:32:34.626 TRC SET ran-after-01HHCVJ8SZPDWEYWDSCZ0C3BCM = true (01HHCVJ8SZPDWEYWDSCJ37X1QC)
[server] 11:32:35.427 INF Created room 20231211_1632_cytestB7TAGR with url https://deliberation.daily.co/20231211_1632_cytestB7TAGR
[server] 11:32:35.428 TRC SET dailyUrl = https://deliberation.daily.co/20231211_1632_cytestB7TAGR (01HHCVJ8N8PTQC6R38XCB7TAGR)
[server] 11:32:35.428 TRC SET dailyRoomName = 20231211_1632_cytestB7TAGR (01HHCVJ8N8PTQC6R38XCB7TAGR)
[server] 11:32:35.428 TRC SET timeStarted = 2023-12-11T16:32:35.428Z (01HHCVJ8N8PTQC6R38XCB7TAGR)
[server] 11:32:35.428 INF Game is now starting with players: 01HHCVHH1RKZ4BQCE6KFG37Q4E,01HHCVHJEQVFV6AMKCD8TWQ3A8
[server] 11:32:35.446 INF Created room 20231211_1632_cytestC99A4B with url https://deliberation.daily.co/20231211_1632_cytestC99A4B
[server] 11:32:35.446 TRC SET dailyUrl = https://deliberation.daily.co/20231211_1632_cytestC99A4B (01HHCVJ8N8PTQC6R38XWC99A4B)
[server] 11:32:35.446 TRC SET dailyRoomName = 20231211_1632_cytestC99A4B (01HHCVJ8N8PTQC6R38XWC99A4B)
[server] 11:32:35.446 TRC SET timeStarted = 2023-12-11T16:32:35.446Z (01HHCVJ8N8PTQC6R38XWC99A4B)
[server] 11:32:35.446 INF Game is now starting with players: 01HHCVHEVV6K8P97DCF0PMBQ55,01HHCVHK55W5BH2T6D2GW4005C
[server] 11:32:35.448 TRC SET status = running (01HHCVJ8N8PTQC6R38XWC99A4B)
[server] 11:32:35.448 TRC SET ran-after-01HHCVJ8QC24M7DQ04ME3JMCGX = true (01HHCVJ8N8PTQC6R38XWC99A4B)
[server] 11:32:35.452 TRC SET stageID = 01HHCVJ8RQZZHQ7DEECKTVA6TX (01HHCVJ8N8PTQC6R38XWC99A4B)
[server] 11:32:35.452 TRC SET start = true (01HHCVJ8RDFB96ADCC735MPBWW)
[server] 11:32:35.452 TRC SET ran-on-01HHCVJ9KTTVVKRRF3N69Z8TW1 = true (01HHCVJ8N8PTQC6R38XWC99A4B)
[server] 11:32:35.460 TRC SET playerRoundID-01HHCVJ8RDFB96ADCC735MPBWW = 01HHCVJ9M3ZXPHCGB6QMEG19RZ (01HHCVHEVV6K8P97DCF0PMBQ55)

Eventually the second time that the first game callback was run, it throws an error. The error is handled in the subroutine, so the redundant callback exits cleanly.

[server] 11:32:35.463 ERR Requested creation of existing room 20231211_1632_cytestB7TAGR. Returning existing room details
JamesPHoughton commented 9 months ago

It's not unreasonable to think this could happen in a case with actual participants (and not only be an artifact of testing) because I'm collecting a bunch of participants and then randomizing them to groups in a chunk.

JamesPHoughton commented 9 months ago

Workaround: Adding a check for the game being started already seems to work

const gamesStarted = new Set();

...

Empirica.on("game", "start", async (ctx, { game, start }) => {
  if (!start) return;
  // prevent this callback from running multiple times for the same batch
  if (gamesStarted.has(game.id)) {
    warn(
      `Game ${game.id} already started, skipping second game start callback`
    );
    return;
  }
  gamesStarted.add(game.id);
  warn(
    `Game ${game.id} on game start callback. Now: ${new Date(
      Date.now()

The first callback call seems to complete properly.

JamesPHoughton commented 9 months ago

I ran a test to see if it was just the game start callback, and found that it actually seems to get called every time the watched value is set, even if the value is set to the same thing.

This code reproduces the error:

// server/src/callbacks.js

var timesCalled = new Map();
Empirica.on("stage", "testMultiples", (ctx, { stage, testMultiples }) => {
  timesCalled.set(stage.id, (timesCalled.get(stage.id) || 0) + 1);
  info(
    `Stage number: ${stage.get("index")} id: ${stage.id} in game ${
      stage.currentGame.id
    } testMultiples callback called ${timesCalled.get(
      stage.id
    )} times with value ${testMultiples}`
  );
});
// client/src/stage.jsx

export function Stage() {
  const stage = useStage();

  stage.set("testMultiples", true);
  ...
}

This sets the value of testMultiples every time the page is rendered, in a gleefully malicious sort of way, and produces in the server log:

[server] 22:17:25.654 INF Stage number: 0 id: 01HHK58E4T40SV8YW68K3SKS35 in game 01HHK58E3C9TWK40C5MCQ7GC3M testMultiples callback called 3 times with value true
[server] 22:17:25.655 INF Stage number: 0 id: 01HHK58E4T40SV8YW68K3SKS35 in game 01HHK58E3C9TWK40C5MCQ7GC3M testMultiples callback called 4 times with value true
[server] 22:17:25.655 INF Stage number: 0 id: 01HHK58E4T40SV8YW68K3SKS35 in game 01HHK58E3C9TWK40C5MCQ7GC3M testMultiples callback called 5 times with value true
[server] 22:17:25.676 INF Stage number: 0 id: 01HHK58E4T40SV8YW68K3SKS35 in game 01HHK58E3C9TWK40C5MCQ7GC3M testMultiples callback called 6 times with value true
[server] 22:17:25.684 INF Stage number: 0 id: 01HHK58E4T40SV8YW68K3SKS35 in game 01HHK58E3C9TWK40C5MCQ7GC3M testMultiples callback called 7 times with value true
[server] 22:17:25.688 INF Stage number: 0 id: 01HHK58E4T40SV8YW68K3SKS35 in game 01HHK58E3C9TWK40C5MCQ7GC3M testMultiples callback called 8 times with value true
[server] 22:17:25.694 INF Stage number: 0 id: 01HHK58E4T40SV8YW68K3SKS35 in game 01HHK58E3C9TWK40C5MCQ7GC3M testMultiples callback called 9 times with value true
[server] 22:17:25.700 INF Stage number: 0 id: 01HHK58E4T40SV8YW68K3SKS35 in game 01HHK58E3C9TWK40C5MCQ7GC3M testMultiples callback called 10 times with value true
[server] 22:17:25.707 INF Stage number: 0 id: 01HHK58E4T40SV8YW68K3SKS35 in game 01HHK58E3C9TWK40C5MCQ7GC3M testMultiples callback called 11 times with value true
[server] 22:17:25.710 INF Stage number: 0 id: 01HHK58E4T40SV8YW68K3SKS35 in game 01HHK58E3C9TWK40C5MCQ7GC3M testMultiples callback called 12 times with value true
[server] 22:17:25.716 INF Stage number: 0 id: 01HHK58E4T40SV8YW68K3SKS35 in game 01HHK58E3C9TWK40C5MCQ7GC3M testMultiples callback called 13 times with value true
[server] 22:17:25.721 INF Stage number: 0 id: 01HHK58E4T40SV8YW68K3SKS35 in game 01HHK58E3C9TWK40C5MCQ7GC3M testMultiples callback called 14 times with value true
[server] 22:17:25.726 INF Stage number: 0 id: 01HHK58E4T40SV8YW68K3SKS35 in game 01HHK58E3C9TWK40C5MCQ7GC3M testMultiples callback called 15 times with value true
[server] 22:17:25.732 INF Stage number: 0 id: 01HHK58E4T40SV8YW68K3SKS35 in game 01HHK58E3C9TWK40C5MCQ7GC3M testMultiples callback called 16 times with value true
[server] 22:17:25.737 INF Stage number: 0 id: 01HHK58E4T40SV8YW68K3SKS35 in game 01HHK58E3C9TWK40C5MCQ7GC3M testMultiples callback called 17 times with value true
[server] 22:17:25.742 INF Stage number: 0 id: 01HHK58E4T40SV8YW68K3SKS35 in game 01HHK58E3C9TWK40C5MCQ7GC3M testMultiples callback called 18 times with value true
[server] 22:17:25.747 INF Stage number: 0 id: 01HHK58E4T40SV8YW68K3SKS35 in game 01HHK58E3C9TWK40C5MCQ7GC3M testMultiples callback called 19 times with value true
[server] 22:17:25.753 INF Stage number: 0 id: 01HHK58E4T40SV8YW68K3SKS35 in game 01HHK58E3C9TWK40C5MCQ7GC3M testMultiples callback called 20 times with value true
[server] 22:17:25.757 INF Stage number: 0 id: 01HHK58E4T40SV8YW68K3SKS35 in game 01HHK58E3C9TWK40C5MCQ7GC3M testMultiples callback called 21 times with value true
[server] 22:17:25.762 INF Stage number: 0 id: 01HHK58E4T40SV8YW68K3SKS35 in game 01HHK58E3C9TWK40C5MCQ7GC3M testMultiples callback called 22 times with value true
[server] 22:17:25.766 INF Stage number: 0 id: 01HHK58E4T40SV8YW68K3SKS35 in game 01HHK58E3C9TWK40C5MCQ7GC3M testMultiples callback called 23 times with value true
[server] 22:17:25.771 INF Stage number: 0 id: 01HHK58E4T40SV8YW68K3SKS35 in game 01HHK58E3C9TWK40C5MCQ7GC3M testMultiples callback called 24 times with value true
[server] 22:17:25.776 INF Stage number: 0 id: 01HHK58E4T40SV8YW68K3SKS35 in game 01HHK58E3C9TWK40C5MCQ7GC3M testMultiples callback called 25 times with value true
[server] 22:17:25.780 INF Stage number: 0 id: 01HHK58E4T40SV8YW68K3SKS35 in game 01HHK58E3C9TWK40C5MCQ7GC3M testMultiples callback called 26 times with value true
[server] 22:17:25.784 INF Stage number: 0 id: 01HHK58E4T40SV8YW68K3SKS35 in game 01HHK58E3C9TWK40C5MCQ7GC3M testMultiples callback called 27 times with value true
[server] 22:17:25.789 INF Stage number: 0 id: 01HHK58E4T40SV8YW68K3SKS35 in game 01HHK58E3C9TWK40C5MCQ7GC3M testMultiples callback called 28 times with value true
[server] 22:17:25.793 INF Stage number: 0 id: 01HHK58E4T40SV8YW68K3SKS35 in game 01HHK58E3C9TWK40C5MCQ7GC3M testMultiples callback called 29 times with value true
[server] 22:17:25.797 INF Stage number: 0 id: 01HHK58E4T40SV8YW68K3SKS35 in game 01HHK58E3C9TWK40C5MCQ7GC3M testMultiples callback called 30 times with value true
[server] 22:17:25.801 INF Stage number: 0 id: 01HHK58E4T40SV8YW68K3SKS35 in game 01HHK58E3C9TWK40C5MCQ7GC3M testMultiples callback called 31 times with value true
[server] 22:17:25.806 INF Stage number: 0 id: 01HHK58E4T40SV8YW68K3SKS35 in game 01HHK58E3C9TWK40C5MCQ7GC3M testMultiples callback called 32 times with value true
[server] 22:17:25.810 INF Stage number: 0 id: 01HHK58E4T40SV8YW68K3SKS35 in game 01HHK58E3C9TWK40C5MCQ7GC3M testMultiples callback called 33 times with value true
[server] 22:17:25.814 INF Stage number: 0 id: 01HHK58E4T40SV8YW68K3SKS35 in game 01HHK58E3C9TWK40C5MCQ7GC3M testMultiples callback called 34 times with value true
[server] 22:17:25.818 INF Stage number: 0 id: 01HHK58E4T40SV8YW68K3SKS35 in game 01HHK58E3C9TWK40C5MCQ7GC3M testMultiples callback called 35 times with value true
[server] 22:17:25.823 INF Stage number: 0 id: 01HHK58E4T40SV8YW68K3SKS35 in game 01HHK58E3C9TWK40C5MCQ7GC3M testMultiples callback called 36 times with value true
[server] 22:17:25.827 INF Stage number: 0 id: 01HHK58E4T40SV8YW68K3SKS35 in game 01HHK58E3C9TWK40C5MCQ7GC3M testMultiples callback called 37 times with value true
[server] 22:17:25.831 INF Stage number: 0 id: 01HHK58E4T40SV8YW68K3SKS35 in game 01HHK58E3C9TWK40C5MCQ7GC3M testMultiples callback called 38 times with value true
[server] 22:17:25.836 INF Stage number: 0 id: 01HHK58E4T40SV8YW68K3SKS35 in game 01HHK58E3C9TWK40C5MCQ7GC3M testMultiples callback called 39 times with value true
[server] 22:17:25.840 INF Stage number: 0 id: 01HHK58E4T40SV8YW68K3SKS35 in game 01HHK58E3C9TWK40C5MCQ7GC3M testMultiples callback called 40 times with value true
[server] 22:17:25.845 INF Stage number: 0 id: 01HHK58E4T40SV8YW68K3SKS35 in game 01HHK58E3C9TWK40C5MCQ7GC3M testMultiples callback called 41 times with value true
[server] 22:17:25.848 INF Stage number: 0 id: 01HHK58E4T40SV8YW68K3SKS35 in game 01HHK58E3C9TWK40C5MCQ7GC3M testMultiples callback called 42 times with value true
[server] 22:17:25.853 INF Stage number: 0 id: 01HHK58E4T40SV8YW68K3SKS35 in game 01HHK58E3C9TWK40C5MCQ7GC3M testMultiples callback called 43 times with value true

The tajriba.json looks like:

...
{"kind":"Attribute","obj":{"id":"01HHK58EZW18R57RW988KRDCSF","createdAt":"2023-12-13T22:17:25.628898-05:00","createdByID":"01HHK56KH3Z842FEVB4GDRX5T9","key":"batchID","val":"\"01HHK57H1B0FSBZKVZE1AH92ZY\"","nodeID":"01HHK58EZW18R57RW986TAMEHG","immutable":true}}
{"kind":"Attribute","obj":{"id":"01HHK58EZW18R57RW9893CVHQ9","createdAt":"2023-12-13T22:17:25.628898-05:00","createdByID":"01HHK56KH3Z842FEVB4GDRX5T9","key":"gameID","val":"\"01HHK58E3C9TWK40C5MCQ7GC3M\"","nodeID":"01HHK58EZW18R57RW986TAMEHG","immutable":true}}
{"kind":"Attribute","obj":{"id":"01HHK58EZW18R57RW98BHS163T","createdAt":"2023-12-13T22:17:25.628898-05:00","createdByID":"01HHK56KH3Z842FEVB4GDRX5T9","key":"roundID","val":"\"01HHK58E4FJ4V26SQ4KM77FTYS\"","nodeID":"01HHK58EZW18R57RW986TAMEHG","immutable":true}}
{"kind":"Attribute","obj":{"id":"01HHK58EZW18R57RW98FBMJCHC","createdAt":"2023-12-13T22:17:25.628898-05:00","createdByID":"01HHK56KH3Z842FEVB4GDRX5T9","key":"stageID","val":"\"01HHK58E4T40SV8YW68K3SKS35\"","nodeID":"01HHK58EZW18R57RW986TAMEHG","immutable":true}}
{"kind":"Attribute","obj":{"id":"01HHK58EZW18R57RW98GRSN6F6","createdAt":"2023-12-13T22:17:25.628898-05:00","createdByID":"01HHK56KH3Z842FEVB4GDRX5T9","key":"playerID","val":"\"01HHK588PCG0GZAVM80MSM7901\"","nodeID":"01HHK58EZW18R57RW986TAMEHG","immutable":true}}
{"kind":"Attribute","obj":{"id":"01HHK58EZZVF7XTP2GBR6DC1YM","createdAt":"2023-12-13T22:17:25.631607-05:00","createdByID":"01HHK56KH3Z842FEVB4GDRX5T9","key":"playerStageID-01HHK58E4T40SV8YW68K3SKS35","val":"\"01HHK58EZW18R57RW986TAMEHG\"","nodeID":"01HHK588PCG0GZAVM80MSM7901"}}
{"kind":"Attribute","obj":{"id":"01HHK58EZZVF7XTP2GBSEF7W3S","createdAt":"2023-12-13T22:17:25.631607-05:00","createdByID":"01HHK56KH3Z842FEVB4GDRX5T9","key":"initialized","val":"true","nodeID":"01HHK58E4T40SV8YW68K3SKS35","private":true,"immutable":true}}
{"kind":"Attribute","obj":{"id":"01HHK58EZZVF7XTP2GBVVX6NAN","createdAt":"2023-12-13T22:17:25.631607-05:00","createdByID":"01HHK56KH3Z842FEVB4GDRX5T9","key":"ran-before-01HHK58EZR8VCZ5NHQTPGKFFDZ","val":"true","nodeID":"01HHK58E4T40SV8YW68K3SKS35"}}
{"kind":"Attribute","obj":{"id":"01HHK58F02WAPJXV9F839SDRC1","createdAt":"2023-12-13T22:17:25.634394-05:00","createdByID":"01HHK56KH3Z842FEVB4GDRX5T9","key":"ran-on-01HHK58EZR8VCZ5NHQTPGKFFDZ","val":"true","nodeID":"01HHK58E4T40SV8YW68K3SKS35"}}
{"kind":"Transition","obj":{"id":"01HHK58F05R603DH193C5WEP0D","createdAt":"2023-12-13T22:17:25.637319-05:00","createdByID":"01HHK56KH3Z842FEVB4GDRX5T9","from":"CREATED","to":"RUNNING","cause":"stage start","nodeID":"01HHK58E4KSG4AF8NV718HGG8C"}}
{"kind":"Link","obj":{"id":"01HHK58F05R603DH193DM5Y58B","createdAt":"2023-12-13T22:17:25.637425-05:00","createdByID":"01HHK56KH3Z842FEVB4GDRX5T9","link":true,"participantID":"01HHK588P19ZD0T0VF5388G085","nodeID":"01HHK58E4T40SV8YW68K3SKS35"}}
{"kind":"Link","obj":{"id":"01HHK58F05R603DH193F7GKPA4","createdAt":"2023-12-13T22:17:25.637425-05:00","createdByID":"01HHK56KH3Z842FEVB4GDRX5T9","link":true,"participantID":"01HHK588P19ZD0T0VF5388G085","nodeID":"01HHK58E4KSG4AF8NV718HGG8C"}}
{"kind":"Link","obj":{"id":"01HHK58F05R603DH193GV903TG","createdAt":"2023-12-13T22:17:25.637425-05:00","createdByID":"01HHK56KH3Z842FEVB4GDRX5T9","link":true,"participantID":"01HHK588P19ZD0T0VF5388G085","nodeID":"01HHK58EZW18R57RW986TAMEHG"}}
{"kind":"Attribute","obj":{"id":"01HHK58F05R603DH193JP426KY","createdAt":"2023-12-13T22:17:25.637528-05:00","createdByID":"01HHK56KH3Z842FEVB4GDRX5T9","key":"started","val":"true","nodeID":"01HHK58E4T40SV8YW68K3SKS35","private":true,"immutable":true}}
{"kind":"Attribute","obj":{"id":"01HHK58F05R603DH193PCCJ74B","createdAt":"2023-12-13T22:17:25.637528-05:00","createdByID":"01HHK56KH3Z842FEVB4GDRX5T9","key":"ran-after-01HHK58EZR8VCZ5NHQTPGKFFDZ","val":"true","nodeID":"01HHK58E4T40SV8YW68K3SKS35"}}
{"kind":"Attribute","obj":{"id":"01HHK58F0F4Q348HMG2D4ZRG9H","createdAt":"2023-12-13T22:17:25.647661-05:00","createdByID":"01HHK56KH3Z842FEVB4GDRX5T9","key":"testMultiples","val":"true","nodeID":"01HHK58E4T40SV8YW68K3SKS35"}}
{"kind":"Attribute","obj":{"id":"01HHK58F0F4Q348HMG2FEXXVBP","createdAt":"2023-12-13T22:17:25.64774-05:00","createdByID":"01HHK56KH3Z842FEVB4GDRX5T9","key":"testMultiples","val":"true","nodeID":"01HHK58E4T40SV8YW68K3SKS35"}}
{"kind":"Attribute","obj":{"id":"01HHK58F0NF6S3TN8FZKKPWKYG","createdAt":"2023-12-13T22:17:25.653841-05:00","createdByID":"01HHK56KH3Z842FEVB4GDRX5T9","key":"testMultiples","val":"true","nodeID":"01HHK58E4T40SV8YW68K3SKS35"}}
{"kind":"Attribute","obj":{"id":"01HHK58F0NF6S3TN8FZKZ7KTE6","createdAt":"2023-12-13T22:17:25.653933-05:00","createdByID":"01HHK56KH3Z842FEVB4GDRX5T9","key":"testMultiples","val":"true","nodeID":"01HHK58E4T40SV8YW68K3SKS35"}}
{"kind":"Attribute","obj":{"id":"01HHK58F0QN46Y4QG427GAVMWP","createdAt":"2023-12-13T22:17:25.655395-05:00","createdByID":"01HHK56KH3Z842FEVB4GDRX5T9","key":"testMultiples","val":"true","nodeID":"01HHK58E4T40SV8YW68K3SKS35"}}
{"kind":"Attribute","obj":{"id":"01HHK58F1BABT0WH0KY4F5TQTD","createdAt":"2023-12-13T22:17:25.675617-05:00","createdByID":"01HHK56KH3Z842FEVB4GDRX5T9","key":"testMultiples","val":"true","nodeID":"01HHK58E4T40SV8YW68K3SKS35"}}
{"kind":"Attribute","obj":{"id":"01HHK58F1K457A27GYD318M3CV","createdAt":"2023-12-13T22:17:25.683728-05:00","createdByID":"01HHK56KH3Z842FEVB4GDRX5T9","key":"testMultiples","val":"true","nodeID":"01HHK58E4T40SV8YW68K3SKS35"}}
{"kind":"Attribute","obj":{"id":"01HHK58F1QDJKSJ08HG2DSN05Z","createdAt":"2023-12-13T22:17:25.68744-05:00","createdByID":"01HHK56KH3Z842FEVB4GDRX5T9","key":"testMultiples","val":"true","nodeID":"01HHK58E4T40SV8YW68K3SKS35"}}
{"kind":"Attribute","obj":{"id":"01HHK58F1YGX72Y73EQGFN9WFC","createdAt":"2023-12-13T22:17:25.694207-05:00","createdByID":"01HHK56KH3Z842FEVB4GDRX5T9","key":"testMultiples","val":"true","nodeID":"01HHK58E4T40SV8YW68K3SKS35"}}
{"kind":"Attribute","obj":{"id":"01HHK58F23WMQKSP4KY8D52P38","createdAt":"2023-12-13T22:17:25.699421-05:00","createdByID":"01HHK56KH3Z842FEVB4GDRX5T9","key":"testMultiples","val":"true","nodeID":"01HHK58E4T40SV8YW68K3SKS35"}}
{"kind":"Attribute","obj":{"id":"01HHK58F2AFMC4BAR54WR0F5HE","createdAt":"2023-12-13T22:17:25.706414-05:00","createdByID":"01HHK56KH3Z842FEVB4GDRX5T9","key":"testMultiples","val":"true","nodeID":"01HHK58E4T40SV8YW68K3SKS35"}}
{"kind":"Attribute","obj":{"id":"01HHK58F2EVEYBMNAFVEN0NTKC","createdAt":"2023-12-13T22:17:25.71017-05:00","createdByID":"01HHK56KH3Z842FEVB4GDRX5T9","key":"testMultiples","val":"true","nodeID":"01HHK58E4T40SV8YW68K3SKS35"}}
{"kind":"Attribute","obj":{"id":"01HHK58F2MSXG43D09TG997PF8","createdAt":"2023-12-13T22:17:25.716003-05:00","createdByID":"01HHK56KH3Z842FEVB4GDRX5T9","key":"testMultiples","val":"true","nodeID":"01HHK58E4T40SV8YW68K3SKS35"}}
...
npaton commented 5 months ago

This should be fixed in the latest releases. Please reopen if you still encounter this issue.