entire rooms of players being disconnected

[Drew Cranford]

Hi Stephano,

I am having a strange error I was hoping to get your insight on.

In my game, there are groups of up to 10 players. I recently came across an error where the entire group is being disconnected from the game at the same time. I only encountered this error recently after I made the game live on mturk. It did not show up in any of our previous pilot testing. There is not much logged in the console to give me a better idea what is going on. But the sequence of events (in the log) are:

1) All players start a round and are presented stimuli.

2) Players are disconnected one at a time when, what seems to be, they submit their response.

3) The game, listening for a player disconnection in the stager.setOnInit() function, creates bots to replace the disconnected humans.

4) There is an error in the callback function of the disconnected stage, when listening for node.on.done() which indicates the player's choice is 'undefined'.

5) The bots do not continue the game. It seems to be stuck or dead at this point.

I am currently trying to replicate this error and gather more logging details to hopefully identify what is going on. Once I have more data, I will be happy to share it with you. But I just wanted to lay out the general problem now to see if you had any insight or guidance about debugging this error. Or to see if you have encountered anything similar in the past.

Please let me know if you have any questions, and I am happy to provide any more details if you like. Thanks very much for any help you can provide.

Best,

Drew

[Drew Cranford]

Hi Stefano,

I wanted to provide some more information. I tried replicating the error yesterday while logging more info. I changed setup.verbosity to 100 to log all debugger info.

1) It seems the problem only occurs when I have multiple groups of players. I tested once with only 1 group of 10 players, connecting remotely through my host computer's IP address, and everything ran fine. I only encountered the error when testing with 2 groups of players. I didn't test with more than 2 groups of players.

2) I wasn't able to exactly replicate the error. I tested the game by playing as 4 players on one computer, connecting remotely through my host computer's IP address, and as another 4 players on the host computer, connecting via localhost. The game has 3 levels, and is only multiplayer in level 2. I got the 4 remote players to the waiting room of level 2, where they were to wait for 15 minutes, afterwhich the game would start by filling the remaining players with bots. I started getting the other 4 players to the waitingroom of level 2 trying to time it so they would arrive at the waiting room after the first 4 players moved into level 2. After approximately 10 minutes in the waiting room, all 4 players were disconnected simultaneously. This happened exactly the same way twice in a row. The server console did not show any errors or logging info. The players were just disconnected. On the client-side browser console, I only see some errors that the connection was interrupted while the page was loading, nodegame stopped the timer, removed a bunch of listeners, destroyed a widget, and closed the socket.

I can't seem to figure out why the connection is being lost to entire groups of players. If it helps I can try to replicate the error once more and provide any logging details from the server console and the client browser console. And here is a link to the repo where you can see the code for my game:

https://github.com/ecranfor/Personalized-Phishing-Training-Game/tree/8f19906cebe7e9d09c91597e60dca00a89c761a6/Personalized_Phishing_Training_random_v1

Thanks for any insight and help.

Best,

Drew

--

Edward 'Drew' Cranford
Special Faculty Researcher
Dept of Psychology, ACT-R FMS group
Carnegie Mellon University
cran...@cmu.edu
edward.a...@gmail.com
601-329-6280

[shakty]

Hi Drew,

Sorry to hear about this issue. Seems indeed complex to debug. Let me see if I understand it correctly.

1) The disconnection happens in the waiting room of Phase2 

2) if there some players connected, and when some others arrive

3) the total number of players at 2) is less than the requested number to start the game

Is this right?

Cheers,
Stefano

[shakty]

I cloned the game and tried to repeat the steps I listed above, but I wasn't able to trigger the disconnections.

Do all players get disconnected, or just those already connected? If so, it looks like perhaps it has to do with the cookie stored in the same browser/s ? How many browsers did you use?

[Drew Cranford]

Hi Stefano,

Not quite right. There are more conditions. The main error, of entire groups being disconnected simultaneously, has occurred under the following conditions:

1) Only when there are multiple different groups. The game seems to run fine when there is only 1 group of players.

2) When the disconnected group is in the waiting room of level 2 (the only multiplayer level), and the other group are in level 1 (a single player level).

3) Also, when both groups are in level 2, and when the members of the disconnected group submits a response to end a round (the round number seems random).

4) Both when the disconnected group total is less than requested number to start the game (have observed this when they are in the waiting room), or when the group is full (have observed this when they are in the gameroom of level 2).

Happy to provide more details as needed.

Best,

Drew

--

Edward 'Drew' Cranford
Special Faculty Researcher
Dept of Psychology, ACT-R FMS group
Carnegie Mellon University
cran...@cmu.edu
edward.a...@gmail.com
601-329-6280

--
You received this message because you are subscribed to a topic in the Google Groups "nodeGame" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/nodegame/yyaqL9-E6qE/unsubscribe.
To unsubscribe from this group and all its topics, send an email to nodegame+u...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/nodegame/ab67bda7-7810-4652-9ae0-09592e9d93aan%40googlegroups.com.

[shakty]

Thanks for the quick clarification! I will do more testing and get back to you asap, but probably not today.

[shakty]

Sorry Drew, I couldn't work on this until now, but I booked time to investigate this tomorrow. Thanks for your patience.

[shakty]

Hi Drew,

I could replicate the strange behavior, but not consistently. In a some occasions (3 out of 10/15) all players have been disconnected when another group joined Phase 2. I am still unsure what causes this, did you gather more insights in the meantime?

Best,
Stefano

[Drew Cranford]

Hi Stefano,

No, I have not been able to gather more insights. The console logs are not giving me any info about why the players are being disconnected (there are no errors being thrown). I can try to replicate it again and save the browser logs (I had them open, but didn't copy them somewhere before the browser restarted itself and the logs were lost). They aren't telling me much, but it might mean something more to you.

For me, sometimes the error has occurred when both groups are already in Phase 2, and the round number seems to be random. Other times, when one group was disconnected from the waiting room before Phase 2, it always occurred after waiting for about 10 minutes (these were smaller groups that were forced to keep waiting). For those groups that were able to get into Phase 2, they were full teams and the longest wait time in the waiting room was only about 1 minute. Not sure if the wait time has anything to do with it, but it only matters if there are other groups of players.

One thing I have noticed is that when the players are disconnected in Phase 2, they are supposed to be replaced by bots, and the experiment should continue with the bots. However, this is not happening either. My console logs say that the bots are created, but the game room gets stuck. It looks like it is trying to save the data of the human players after they give their responses, but that data is missing or lost (i.e.,  message.data.forms.classification.choice from node.on.done() is undefined), and so the game doesn't continue. For example, this is what I see in the logs for one of the players (same thing happens for all players in the group):

Disconnection: 660255062123742 (server stage: 1.1.47)
****COMPUTED BONUS PER PLAYER****
{
  basePay: 5,
  bonus: 3.3,
  total: 8.3,
  exit: 'IWvVgi',
  totalRaw: 33,
  exchangeRate: 0.1,
  id: '660255062123742',
  access: 'NA'
}
Bonus data saved for player 660255062123742
---------Player 660255062123742 replaced with bot 132225947422708---------

2023-05-19T20:14:41.158Z error: ServerNode caught an exception:
TypeError: Cannot read properties of undefined (reading 'classification')
    at Game.<anonymous> (C:\home\nodegame-v7.1.0\games_available\Personalized_Phishing_Training_random_v1\levels\Phase2\game\client_types\logic.js:294:41)
    at Game.<anonymous> (C:\home\nodegame-v7.1.0\node_modules\nodegame-client\listeners\aliases.js:62:20)
    at Game.<anonymous> (C:\home\nodegame-v7.1.0\node_modules\nodegame-client\lib\modules\alias.js:91:26)
    at EventEmitter.emit (C:\home\nodegame-v7.1.0\node_modules\nodegame-client\lib\core\EventEmitter.js:207:31)
    at EventEmitterManager.emit (C:\home\nodegame-v7.1.0\node_modules\nodegame-client\lib\core\EventEmitter.js:743:31)
    at Socket.onMessageFull (C:\home\nodegame-v7.1.0\node_modules\nodegame-client\lib\core\Socket.js:566:23)
    at SocketDirect.message (C:\home\nodegame-v7.1.0\node_modules\nodegame-client\lib\sockets\SocketDirect.js:100:26)
    at SocketDirect.send (C:\home\nodegame-v7.1.0\node_modules\nodegame-server\lib\sockets\SocketDirect.js:210:24)
    at SocketManager.send2client (C:\home\nodegame-v7.1.0\node_modules\nodegame-server\lib\SocketManager.js:495:18)
    at SocketManager.send2group (C:\home\nodegame-v7.1.0\node_modules\nodegame-server\lib\SocketManager.js:449:27)

Let me know if I can help gather any more info for you.

Best,

Drew

--

Edward 'Drew' Cranford
Special Faculty Researcher
Dept of Psychology, ACT-R FMS group
Carnegie Mellon University
cran...@cmu.edu
edward.a...@gmail.com
601-329-6280

To view this discussion on the web visit https://groups.google.com/d/msgid/nodegame/9dcd59b9-9ded-4c73-bd73-9ec49a1f5adcn%40googlegroups.com.

[shakty]

Thanks for additional info. 

Players are being redirected (hence disconnected), therefore the conditions that in logic trigger the redirect must be satisfied somehow:

 if (player.total_timeout >= 5 || player.consec_timeout >= 3) {

Under which conditions could those variables be erroneously updated?

[Drew Cranford]

Hi Stefano,

I cannot see how those variables could be erroneously updated. In my testing, and in the disconnection errors I am having problems with, I have not observed that any players have been disconnected due to (player.total_timeout >= 5 || player.consec_timeout >= 3). If so, I would have seen console.log(p.id+" was removed");, but I never did.

Also, in my testing, I never let a player timeout. I also print to the console, and the data file, the player's timeout counts. In both, I am not seeing that the total_timeout or consec_timeout variables are ever greater than 0.
Additionally, instead of being redirected to disconnected.htm, as would be done if a player was disconnected due to timeouts, they only see a "resuming soon" message. They are also being disconnected before getting to the feedback stage, which is where the conditional exists to disconnect players if they have timed out 3 consecutive times, or 5 total times.

Is there a reason you suspect the timeout conditional to redirect players is the culprit? I can certainly take a closer look with our research programmer if that would help.

Best,

Drew

--

Edward 'Drew' Cranford
Special Faculty Researcher
Dept of Psychology, ACT-R FMS group
Carnegie Mellon University
cran...@cmu.edu
edward.a...@gmail.com
601-329-6280

To view this discussion on the web visit https://groups.google.com/d/msgid/nodegame/4cf3dbd2-233d-4aca-9647-0179edc2f17en%40googlegroups.com.

[shakty]

Hi,

In my case the players were being redirected and not blocked in "Resuming soon," that's why I thought those variables might have been the culprit. 

Perhaps we could have a chat to understand the problem and debug it together next week? You know the game codebase better, I know the backend better, we can find where the problem is coming from faster.

 

For me Wednesday would be ideal. Let me know.

Cheers,

Stefano

[Drew Cranford]

Ah I see. You may have experienced "normal" disconnections. 

Wenesday will work for me as of now. I will be out of town for a family reunion next week, and I'm not sure if anyone has any all-day events planned on that day yet. But meeting in the morning my time will probably work. My time zone is CDT (GMT-5).

Best,

Drew

To view this discussion on the web visit https://groups.google.com/d/msgid/nodegame/dcf6e94b-bfab-468f-8e15-94dc76fe69ban%40googlegroups.com.

[Drew Cranford]

Hi Stefano,

I just wanted to readdress this issue a bit. Even with the fix of moving my code from the init to the cb, and wrapping it in a short delay, I am still seeing this error from time to time. After further investigating, it seems that the error is that one player is being disconnected, and it then hangs the game for the rest of the players. The disconnected player is sending a node.done message on timeout, but the forms field is empty, which results in a type error when trying to access data from the message in my node.on.done() function. I think I can get around this issue with some error handling conditions. The good news is that, after applying the error handling, if one player disconnects, it won't hang the rest of the group.

The issue of why the player is being disconnected is still a mystery. The error I see in the browser console is "The connection to [ws] was interrupted while the page was loading. socket.io.js:4522:104"

Seems to be some issue with the browser, almost like it is "refreshing" the page. When I have multiple autoplay players playing on the same browser, in multiple tabs, this error will occur for all of those players at the same time, so it is a browser-wide error. This only occurs when I am connecting remotely to the game from another computer. The error never occurs on localhost. I've only tested this using Firefox, so I am not sure if it is a Firefox specific issue, or if this problem would occur on other browsers. Hopefully this info is helpful to you. Let me know if you have any other questions, or if I can clarify anything for you.

Best,

Drew

[shakty]

The message below was erroneously sent to Drew only, so I am copying it here for future reference. Drew said he has implemented solution one and it is working now.

---

Hi Drew,

I have seen this error in the past, and it is web-socket error generated somehow by the browser. If you google that error msg you will find that it is common mostly on Firefox, it has been there for a long time. 

You could try a couple of things:

a- catch the error and try to trigger a refresh of the page to establish a new clean connection,

b- switch the socket.io transport to 'polling' on Firefox

c-update socket.io and socket.io-client inside node_modules

a) I am not clear how to catch it. Here it says that error is not coming from socket.io:

https://socket.io/docs/v4/logging-and-debugging/#error-logs-in-the-browser-console

So perhaps you need to overwrite nodegame window.onerror listener.

// Original code:

window.onerror = function(msg, url, lineno, colno, error) {
                var str;
                msg = node.game.getCurrentGameStage().toString() +
                    '@' + J.getTime() + '> ' +
                    url + ' ' + lineno + ',' + colno + ': ' + msg;
                if (error) msg + ' - ' + JSON.stringify(error);
                that.lastError = msg;
                node.err(msg);
                if (node.debug) {
                    W.init({ waitScreen: true });
                    str = '<strong>DEBUG mode: client-side error ' +
                          'detected.</strong><br/><br/>';
                    str += msg;
                    str += '</br></br>Open the DevTools in your browser ' +
                    'for details.</br><em style="font-size: smaller">' +
                    'This message will not be shown in production mode.</em>';
                    W.lockScreen(str);
                }
                return !node.debug;
            };

// A possible modification.

window.onerror = function(msg, url, lineno, colno, error) {
                var str;

                // Modification.

                if (msg.indexOf('The connection to [ws] was interrupted') !== -1) {

                       location.reload();

                       return;

                 }

                msg = node.game.getCurrentGameStage().toString() +
                    '@' + J.getTime() + '> ' +
                    url + ' ' + lineno + ',' + colno + ': ' + msg;
                if (error) msg + ' - ' + JSON.stringify(error);
                that.lastError = msg;
                node.err(msg);
                if (node.debug) {
                    W.init({ waitScreen: true });
                    str = '<strong>DEBUG mode: client-side error ' +
                          'detected.</strong><br/><br/>';
                    str += msg;
                    str += '</br></br>Open the DevTools in your browser ' +
                    'for details.</br><em style="font-size: smaller">' +
                    'This message will not be shown in production mode.</em>';
                    W.lockScreen(str);
                }
                return !node.debug;
            };

You could add that code at the bottom of public/js/index.js

b) You can pass specific socket.io options in the file public/js/index.js under the socket option of the setup method:

// Default:

socket : {
            type : 'SocketIo',
            reconnection : false
        }

// Mod1:

socket : {
            type : 'SocketIo',
            reconnection : true
        }

// Mod2:

Catch Firefox users and set the transport option as explained here:

https://stackoverflow.com/questions/13616960/how-do-i-catch-a-websocket-connection-interruption

Let me know if any solution works.

Cheers,

Stefano

[Drew Cranford]

Hi Stefano,

It seems our last fix worked well for Firefox, but I think it caused an issue with Chrome.

The game is not able to initialize the game step. And the browser console is showing an error in index.js. A problem with the window.onerror listener that we updated (see previous message in this thread).

Below are the errors from the browser console. The game itself is just grayed out and says "Initializing game step, will be ready soon...". And it hangs up the game for all other players.

I was running the game with 10 autoplay bots. If you want to test it out yourself, I will send you a link to the game in a private message. Or I can send you a link to the source code on github.

Thanks,

Drew

nodegame-full.min.js:1 Uncaught (in promise) DOMException: play() failed because the user didn't interact with the document first. https://goo.gl/xX8pDD
nodegame-full.min.js:1 auto...@0.0.0 - 10:57:01:269 > warn - "NODEGAME_GAMECOMMAND_stop": game cannot be stopped now.
nodegame-full.min.js:1 Uncaught TypeError: Cannot read properties of undefined (reading 'destroy')
    at Game.widgetExit (nodegame-full.min.js:1:247575)
    at Game.gotoStep (nodegame-full.min.js:1:242213)
    at Game.step (nodegame-full.min.js:1:240452)
    at nodegame-full.min.js:1:313194
index.js:53 Uncaught ReferenceError: that is not defined
    at window.onerror (index.js:53:5)

[Drew Cranford]

Looking more into the browser console logs and terminal output with additional logging information, it looks like the game is trying to advance a player to the next step before it has finished loading the page for the current step and well before the player pressed any buttons or submitted any answers via the 'done' button. The widget was never created before trying to go to the next step and therefore there is nothing available to destroy.

Here is the browser console log for the player that hangs:

auto...@0.0.0 - 11:52:05:600 > silly - Next step ---> 1.1.1
nodegame-full.min.js:1 auto...@0.0.0 - 11:52:05:601 > info - S: 2023-09-30T15:52:05.601Z, 88380, 2982508139938156, say, PLAYER_UPDATE, 498582893087014, ROOM, "stage", "[object O...", 0.0.0, 1, 0
nodegame-full.min.js:1 auto...@1.1.1 - 11:52:05:603 > info - R: 2023-09-30T15:52:05.603Z, 957167, 2982508139938156, say, GAMECOMMAND, Personalized_Phishing_Training_CogEV_v1, 498582893087014, "pause", ""Fetching...", 0.0.0, 1, 1
nodegame-full.min.js:1 auto...@1.1.1 - 11:52:05:604 > game paused.
nodegame-full.min.js:1 auto...@1.1.1 - 11:52:06:164 > info - R: 2023-09-30T15:52:06.164Z, 844086, 2982508139938156, say, GAMECOMMAND, Personalized_Phishing_Training_CogEV_v1, 498582893087014, "resume", "[object O...", 0.0.0, 1, 1
nodegame-full.min.js:1 auto...@1.1.1 - 11:52:06:165 > game resumed.
nodegame-full.min.js:1 auto...@1.1.1 - 11:52:06:169 > info - R: 2023-09-30T15:52:06.169Z, 14433, 2982508139938156, say, DATA, Personalized_Phishing_Training_CogEV_v1, 498582893087014, "phasedata", "Phase 2,1", 0.0.0, 1, 0
nodegame-full.min.js:1 auto...@1.1.1 - 11:52:06:170 > silly - B: 2023-09-30T15:52:06.169Z, 14433, 2982508139938156, say, DATA, Personalized_Phishing_Training_CogEV_v1, 498582893087014, "phasedata", "Phase 2,1", 0.0.0, 1, 0
nodegame-full.min.js:1 auto...@1.1.1 - 11:52:06:171 > info - R: 2023-09-30T15:52:06.171Z, 815110, 2982508139938156, say, DATA, Personalized_Phishing_Training_CogEV_v1, 498582893087014, "email", "[object O...", 0.0.0, 1, 0
nodegame-full.min.js:1 auto...@1.1.1 - 11:52:06:171 > silly - B: 2023-09-30T15:52:06.171Z, 815110, 2982508139938156, say, DATA, Personalized_Phishing_Training_CogEV_v1, 498582893087014, "email", "[object O...", 0.0.0, 1, 0
nodegame-full.min.js:1 auto...@1.1.1 - 11:52:06:171 > info - R: 2023-09-30T15:52:06.171Z, 886184, 2982508139938156, say, DATA, Personalized_Phishing_Training_CogEV_v1, 498582893087014, "averages", "HAM,0.559...", 0.0.0, 1, 0
nodegame-full.min.js:1 auto...@1.1.1 - 11:52:06:171 > silly - B: 2023-09-30T15:52:06.171Z, 886184, 2982508139938156, say, DATA, Personalized_Phishing_Training_CogEV_v1, 498582893087014, "averages", "HAM,0.559...", 0.0.0, 1, 0
nodegame-full.min.js:1 auto...@1.1.1 - 11:52:06:357 > silly - Next step ---> 1.2.1

nodegame-full.min.js:1 Uncaught TypeError: Cannot read properties of undefined (reading 'destroy')
    at Game.widgetExit (nodegame-full.min.js:1:247575)
    at Game.gotoStep (nodegame-full.min.js:1:242213)
    at Game.step (nodegame-full.min.js:1:240452)
    at nodegame-full.min.js:1:313194
index.js:53 Uncaught ReferenceError: that is not defined
    at window.onerror (index.js:53:5)

window.onerror @ index.js:53
nodegame-full.min.js:1 auto...@1.1.1 - 11:52:06:359 > info - creating widget ChoiceManager v.1.4.1
nodegame-full.min.js:1 auto...@1.1.1 - 11:52:06:359 > info - creating widget ChoiceTable v.1.8.1

And this is what the browser console looks like for a player when everything works correctly:

auto...@0.0.0 - 11:52:05:601 > silly - Next step ---> 1.1.1
nodegame-full.min.js:1 auto...@0.0.0 - 11:52:05:602 > info - S: 2023-09-30T15:52:05.602Z, 297461, 2982508139938156, say, PLAYER_UPDATE, 75524426706741, ROOM, "stage", "[object O...", 0.0.0, 1, 0
nodegame-full.min.js:1 auto...@1.1.1 - 11:52:05:604 > info - R: 2023-09-30T15:52:05.604Z, 957167, 2982508139938156, say, GAMECOMMAND, Personalized_Phishing_Training_CogEV_v1, 75524426706741, "pause", ""Fetching...", 0.0.0, 1, 1
nodegame-full.min.js:1 auto...@1.1.1 - 11:52:05:604 > game paused.
nodegame-full.min.js:1 auto...@1.1.1 - 11:52:06:163 > info - R: 2023-09-30T15:52:06.163Z, 844086, 2982508139938156, say, GAMECOMMAND, Personalized_Phishing_Training_CogEV_v1, 75524426706741, "resume", "[object O...", 0.0.0, 1, 1
nodegame-full.min.js:1 auto...@1.1.1 - 11:52:06:164 > game resumed.
nodegame-full.min.js:1 auto...@1.1.1 - 11:52:06:168 > info - R: 2023-09-30T15:52:06.168Z, 38847, 2982508139938156, say, DATA, Personalized_Phishing_Training_CogEV_v1, 75524426706741, "phasedata", "Phase 2,1", 0.0.0, 1, 0
nodegame-full.min.js:1 auto...@1.1.1 - 11:52:06:168 > silly - B: 2023-09-30T15:52:06.168Z, 38847, 2982508139938156, say, DATA, Personalized_Phishing_Training_CogEV_v1, 75524426706741, "phasedata", "Phase 2,1", 0.0.0, 1, 0
nodegame-full.min.js:1 auto...@1.1.1 - 11:52:06:168 > info - R: 2023-09-30T15:52:06.168Z, 600048, 2982508139938156, say, DATA, Personalized_Phishing_Training_CogEV_v1, 75524426706741, "email", "[object O...", 0.0.0, 1, 0
nodegame-full.min.js:1 auto...@1.1.1 - 11:52:06:168 > silly - B: 2023-09-30T15:52:06.168Z, 600048, 2982508139938156, say, DATA, Personalized_Phishing_Training_CogEV_v1, 75524426706741, "email", "[object O...", 0.0.0, 1, 0
nodegame-full.min.js:1 auto...@1.1.1 - 11:52:06:168 > info - R: 2023-09-30T15:52:06.168Z, 535171, 2982508139938156, say, DATA, Personalized_Phishing_Training_CogEV_v1, 75524426706741, "averages", "HAM,0.559...", 0.0.0, 1, 0
nodegame-full.min.js:1 auto...@1.1.1 - 11:52:06:169 > silly - B: 2023-09-30T15:52:06.168Z, 535171, 2982508139938156, say, DATA, Personalized_Phishing_Training_CogEV_v1, 75524426706741, "averages", "HAM,0.559...", 0.0.0, 1, 0
nodegame-full.min.js:1 auto...@1.1.1 - 11:52:06:358 > info - creating widget ChoiceManager v.1.4.1
nodegame-full.min.js:1 auto...@1.1.1 - 11:52:06:358 > info - creating widget ChoiceTable v.1.8.1

Best,

Drew

[shakty]

Hi Drew,

Sorry to hear about the new issue. I think perhaps it's two issues actually:

1-> Uncaught TypeError: Cannot read properties of undefined (reading 'destroy')
2-> Uncaught ReferenceError: that is not defined

2 is an easier fix, and we introduced with our last fix. The code I suggested (my bad), contains a reference to `that`, which is not defined. `that` should be instead `node.errorManager`. Replacing it, should take away 2. 

It seems that 2 is caused by 1, rather than the opposite, which would be nice so we would have fixed both now.

Looking at the output in console, it seems that 1 comes from the autoplay player, is that right? Does it happen _only_ from the autoplay? It could be that you have set a too quick node.done() in your code (something a human could not do). In this case, a small timeout for bots makes wonder. Still the error should not happen. If you could share the code, I can debug exactly why it happens and fix it in the core.

Cheers,
Stefano

[Drew Cranford]

Hi Stefano,

Thanks for the help with 2. Regarding 1, I can't figure out why the game is trying to step to the next step early. Yes, it seems to only happen with autoplay, and only seems to happen in Chrome. It works fine in Firefox, but I haven't tested it in other browsers yet.

The code can be found here.

https://github.com/ecranfor/Personalized-Phishing-Training-Game/tree/main/Personalized_Phishing_Training_CogEV_v1

If you need to run the game yourself, it may be a little tricky. To run the game successfully, you need to run CogLow_model.lisp found in the main directory of the game. For this you need sbcl installed, and quicklisp, and run "sbcl --load "CogLow_model.lisp"".

Alternatively, you could just replace the part of code in level Phase2 logic.js that determines which two players to send phishing emails to. Just need to set 'select_ids' to any two random player ids, and comment out this part of the code:

// send data to cog model and get back ids to send email to

                //collect player_data into json object

                let player_data = {'current_time': Date.now(), 'player_data': []};

                this.pl.each(function(p) {

                    let player = channel.registry.getClient(p.id);

                    player_data.player_data.push({['u'+p.id]: player.data});

                });

                //console.log(player_data);

                let msg = JSON.stringify(player_data);

                //console.log(msg);

                //send player_data

                socket.connect(port, host, function() {

                    console.log('[+] Connected.');

                    //on conection send message

                    socket.write(msg+'\r\n');

                }); //make connection

               

                //get response

                socket.once('data', function(message) {

                    node.remoteCommand('resume', ids);

                    selected_ids = JSON.parse(message.toString("utf-8"));

                    //console.log('The result is: '+selected_ids);

                    //console.log(typeof selected_ids);

                    console.log("[+] Selected players: "+selected_ids);

                    //console.log(typeof selected_ids[0]);

                    //console.log(typeof selected_ids[1]);

                   

                    // destroy socket

                    socket.destroy();

                    console.log("[-] Connection Closed");

And remove the closing brackets for the socket.once('data'... function.

And also comment out the line:

node.remoteCommand('pause', ids,"Fetching email...");

Here is the link I use to run the game for a single player...each player needs a unique ?workerId
http://localhost:8080/Personalized_Phishing_Training_CogEV_v1/?workerId=Drew02&assignmentId=1234&hitId=PPT&clientType=autoplay

Best,

Drew

[Stefano B]

Thanks for the quick iteration. I will take a deeper look later, but first I would try this: I would replace all timer.random(X) with timer.random(X,Y). The former is a random delay from 0 to X and it could happen to be close to zero. Even so, it should not happen, but at least we can eliminate this hypothesis.

Let me know. Cheers,

Stefano

You received this message because you are subscribed to the Google Groups "nodeGame" group.
To unsubscribe from this group and stop receiving emails from it, send an email to nodegame+u...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/nodegame/8f4537cb-5dea-4b7b-bc29-ce5393666f44n%40googlegroups.com.

[Drew Cranford]

Replacing all the timer.random(2000) with timer.random(2000,3000), and fixing the errorManager in index.js, seemed to do something. But still getting the cannot read properties of 'destroy' error, and the game is trying to step before it should be.

Instead of the game showing "Initializing game step, will be ready soon..." and getting stuck there, it now shows the error (when debugging verbosity is set to 100):

""

DEBUG mode: client-side error detected.
1.1.1@14:42:35> http://localhost:8080/javascripts/nodegame-full.min.js 1,247575: Uncaught TypeError: Cannot read properties of undefined (reading 'destroy')
Open the DevTools in your browser for details.

This message will not be shown in production mode.

""

Here is the browser console log now:

auto...@0.0.0 - 14:42:34:765 > game started.
auto...@0.0.0 - 14:42:34:765 > silly - Next step ---> 1.1.1
auto...@0.0.0 - 14:42:34:766 > info - S: 2023-10-02T18:42:34.766Z, 290006, 3007012219951817, say, PLAYER_UPDATE, 371716387723979, ROOM, "stage", "[object O...", 0.0.0, 1, 0
auto...@1.1.1 - 14:42:34:768 > info - R: 2023-10-02T18:42:34.768Z, 277519, 3007012219951817, say, GAMECOMMAND, Personalized_Phishing_Training_CogEV_v1, 371716387723979, "pause", ""Fetching...", 0.0.0, 1, 1
auto...@1.1.1 - 14:42:34:769 > game paused.
auto...@1.1.1 - 14:42:35:297 > info - R: 2023-10-02T18:42:35.297Z, 922979, 3007012219951817, say, GAMECOMMAND, Personalized_Phishing_Training_CogEV_v1, 371716387723979, "resume", "[object O...", 0.0.0, 1, 1
auto...@1.1.1 - 14:42:35:298 > game resumed.
auto...@1.1.1 - 14:42:35:301 > info - R: 2023-10-02T18:42:35.301Z, 274282, 3007012219951817, say, DATA, Personalized_Phishing_Training_CogEV_v1, 371716387723979, "phasedata", "Phase 2,1", 0.0.0, 1, 0
auto...@1.1.1 - 14:42:35:302 > silly - B: 2023-10-02T18:42:35.301Z, 274282, 3007012219951817, say, DATA, Personalized_Phishing_Training_CogEV_v1, 371716387723979, "phasedata", "Phase 2,1", 0.0.0, 1, 0
auto...@1.1.1 - 14:42:35:302 > info - R: 2023-10-02T18:42:35.302Z, 818638, 3007012219951817, say, DATA, Personalized_Phishing_Training_CogEV_v1, 371716387723979, "email", "[object O...", 0.0.0, 1, 0
auto...@1.1.1 - 14:42:35:302 > silly - B: 2023-10-02T18:42:35.302Z, 818638, 3007012219951817, say, DATA, Personalized_Phishing_Training_CogEV_v1, 371716387723979, "email", "[object O...", 0.0.0, 1, 0
auto...@1.1.1 - 14:42:35:302 > info - R: 2023-10-02T18:42:35.302Z, 187976, 3007012219951817, say, DATA, Personalized_Phishing_Training_CogEV_v1, 371716387723979, "averages", "HAM,0.53,...", 0.0.0, 1, 0
auto...@1.1.1 - 14:42:35:302 > silly - B: 2023-10-02T18:42:35.302Z, 187976, 3007012219951817, say, DATA, Personalized_Phishing_Training_CogEV_v1, 371716387723979, "averages", "HAM,0.53,...", 0.0.0, 1, 0
auto...@1.1.1 - 14:42:35:549 > silly - Next step ---> 1.2.1
auto...@1.1.1 - 14:42:35:550 > error - 1.1.1@14:42:35> http://localhost:8080/javascripts/nodegame-full.min.js 1,247575: Uncaught TypeError: Cannot read properties of undefined (reading 'destroy')
auto...@1.1.1 - 14:42:35:550 > info - S: 2023-10-02T18:42:35.550Z, 318862, 3007012219951817, say, LOG, 371716387723979, SERVER, "error", "1.1.1@14:...", 1.1.1, 1, 0
auto...@1.1.1 - 14:42:35:551 > silly - ee.game removed listener: REALLY_DONE
auto...@1.1.1 - 14:42:35:551 > silly - ee.game removed listener: STEPPING
auto...@1.1.1 - 14:42:35:551 > silly - ee.game removed listener: PLAYING
auto...@1.1.1 - 14:42:35:551 > silly - ee.game removed listener: PAUSED
auto...@1.1.1 - 14:42:35:551 > silly - ee.game removed listener: RESUMED
auto...@1.1.1 - 14:42:35:551 > silly - game.on: added: REALLY_DONE
auto...@1.1.1 - 14:42:35:551 > silly - game.on: added: STEPPING
auto...@1.1.1 - 14:42:35:551 > silly - game.on: added: PLAYING
auto...@1.1.1 - 14:42:35:551 > silly - game.on: added: PAUSED
auto...@1.1.1 - 14:42:35:551 > silly - game.on: added: RESUMED
auto...@1.1.1 - 14:42:35:554 > silly - node-window: inited.

Uncaught TypeError: Cannot read properties of undefined (reading 'destroy')
    at Game.widgetExit (nodegame-full.min.js:1:247575)
    at Game.gotoStep (nodegame-full.min.js:1:242213)
    at Game.step (nodegame-full.min.js:1:240452)
    at nodegame-full.min.js:1:313194

auto...@1.1.1 - 14:42:35:556 > info - creating widget ChoiceManager v.1.4.1
auto...@1.1.1 - 14:42:35:556 > info - creating widget ChoiceTable v.1.8.1

auto...@1.1.1 - 14:42:35:557 > silly - step.on: added: INPUT_DISABLE
auto...@1.1.1 - 14:42:35:557 > silly - step.on: added: INPUT_ENABLE
auto...@1.1.1 - 14:42:35:557 > info - creating widget Slider v.0.4.0
auto...@1.1.1 - 14:42:35:557 > silly - step.on: added: INPUT_DISABLE
auto...@1.1.1 - 14:42:35:557 > silly - step.on: added: INPUT_ENABLE
auto...@1.1.1 - 14:42:35:558 > silly - step.on: added: in.say.DATA
auto...@1.1.1 - 14:42:35:558 > silly - step.on: added: in.set.DATA
auto...@1.1.1 - 14:42:35:558 > silly - step.on: added: in.say.DATA
auto...@1.1.1 - 14:42:35:558 > silly - step.on: added: in.set.DATA

And here is what it looks like for a player that runs successfully:

auto...@0.0.0 - 14:42:34:755 > silly - Next step ---> 1.1.1
auto...@0.0.0 - 14:42:34:756 > info - S: 2023-10-02T18:42:34.756Z, 744000, 3007012219951817, say, PLAYER_UPDATE, 376971928752698, ROOM, "stage", "[object O...", 0.0.0, 1, 0
auto...@1.1.1 - 14:42:34:763 > info - R: 2023-10-02T18:42:34.763Z, 277519, 3007012219951817, say, GAMECOMMAND, Personalized_Phishing_Training_CogEV_v1, 376971928752698, "pause", ""Fetching...", 0.0.0, 1, 1
auto...@1.1.1 - 14:42:34:763 > game paused.
auto...@1.1.1 - 14:42:35:296 > info - R: 2023-10-02T18:42:35.295Z, 922979, 3007012219951817, say, GAMECOMMAND, Personalized_Phishing_Training_CogEV_v1, 376971928752698, "resume", "[object O...", 0.0.0, 1, 1
auto...@1.1.1 - 14:42:35:298 > game resumed.
auto...@1.1.1 - 14:42:35:299 > info - R: 2023-10-02T18:42:35.299Z, 780133, 3007012219951817, say, DATA, Personalized_Phishing_Training_CogEV_v1, 376971928752698, "phasedata", "Phase 2,1", 0.0.0, 1, 0
auto...@1.1.1 - 14:42:35:299 > silly - B: 2023-10-02T18:42:35.299Z, 780133, 3007012219951817, say, DATA, Personalized_Phishing_Training_CogEV_v1, 376971928752698, "phasedata", "Phase 2,1", 0.0.0, 1, 0
auto...@1.1.1 - 14:42:35:299 > info - R: 2023-10-02T18:42:35.299Z, 897374, 3007012219951817, say, DATA, Personalized_Phishing_Training_CogEV_v1, 376971928752698, "email", "[object O...", 0.0.0, 1, 0
auto...@1.1.1 - 14:42:35:299 > silly - B: 2023-10-02T18:42:35.299Z, 897374, 3007012219951817, say, DATA, Personalized_Phishing_Training_CogEV_v1, 376971928752698, "email", "[object O...", 0.0.0, 1, 0
auto...@1.1.1 - 14:42:35:299 > info - R: 2023-10-02T18:42:35.299Z, 306887, 3007012219951817, say, DATA, Personalized_Phishing_Training_CogEV_v1, 376971928752698, "averages", "HAM,0.53,...", 0.0.0, 1, 0
auto...@1.1.1 - 14:42:35:299 > silly - B: 2023-10-02T18:42:35.299Z, 306887, 3007012219951817, say, DATA, Personalized_Phishing_Training_CogEV_v1, 376971928752698, "averages", "HAM,0.53,...", 0.0.0, 1, 0
auto...@1.1.1 - 14:42:35:550 > info - creating widget ChoiceManager v.1.4.1
auto...@1.1.1 - 14:42:35:550 > info - creating widget ChoiceTable v.1.8.1
auto...@1.1.1 - 14:42:35:550 > silly - step.on: added: INPUT_DISABLE
auto...@1.1.1 - 14:42:35:550 > silly - step.on: added: INPUT_ENABLE
auto...@1.1.1 - 14:42:35:550 > info - creating widget Slider v.0.4.0
auto...@1.1.1 - 14:42:35:550 > silly - step.on: added: INPUT_DISABLE
auto...@1.1.1 - 14:42:35:550 > silly - step.on: added: INPUT_ENABLE
auto...@1.1.1 - 14:42:35:551 > silly - step.on: added: in.say.DATA
auto...@1.1.1 - 14:42:35:551 > silly - step.on: added: in.set.DATA
auto...@1.1.1 - 14:42:35:551 > silly - step.on: added: in.say.DATA
auto...@1.1.1 - 14:42:35:551 > silly - step.on: added: in.set.DATA
auto...@1.1.1 - 14:42:35:552 > silly - D: 2023-10-02T18:42:35.299Z, 780133, 3007012219951817, say, DATA, Personalized_Phishing_Training_CogEV_v1, 376971928752698, "phasedata", "Phase 2,1", 0.0.0, 1, 0
auto...@1.1.1 - 14:42:35:552 > silly - D: 2023-10-02T18:42:35.299Z, 897374, 3007012219951817, say, DATA, Personalized_Phishing_Training_CogEV_v1, 376971928752698, "email", "[object O...", 0.0.0, 1, 0
auto...@1.1.1 - 14:42:35:552 > silly - D: 2023-10-02T18:42:35.299Z, 306887, 3007012219951817, say, DATA, Personalized_Phishing_Training_CogEV_v1, 376971928752698, "averages", "HAM,0.53,...", 0.0.0, 1, 0
auto...@1.1.1 - 14:42:35:553 > info - S: 2023-10-02T18:42:35.552Z, 444101, 3007012219951817, say, PLAYER_UPDATE, 376971928752698, ROOM, "stageLevel", "[object O...", 1.1.1, 1, 0
auto...@1.1.1 - 14:42:35:553 > silly - step.on: added: PAUSED
auto...@1.1.1 - 14:42:35:553 > silly - step.on: added: RESUMED
auto...@1.1.1 - 14:42:37:561 > silly - step.on: added: PAUSED
auto...@1.1.1 - 14:42:37:562 > silly - step.on: added: RESUMED
auto...@1.1.1 - 14:42:42:543 > silly - ee.step removed listener: PAUSED
auto...@1.1.1 - 14:42:42:544 > silly - ee.step removed listener: RESUMED
auto...@1.1.1 - 14:42:42:545 > info - S: 2023-10-02T18:42:42.544Z, 139691, 3007012219951817, set, DATA, 376971928752698, SERVER, "done", "[object O...", 1.1.1, 1, 0
auto...@1.1.1 - 14:42:42:548 > info - S: 2023-10-02T18:42:42.547Z, 771400, 3007012219951817, say, PLAYER_UPDATE, 376971928752698, ROOM, "stageLevel", "[object O...", 1.1.1, 1, 0

Best,

Drew

[Drew Cranford]

Stefano,

Just testing something out, I increased the time for node.timer.setTimeout in the autoplay.js from 2000 to 5000 (see below), and the game ran through, although it took longer to make decisions and be 'done'. What does the value do in setTimeout? Does it mean the function does not execute until the time has elapsed? Is there anything cleaner we could do to get the same effect? Considering the problem occurs in Chrome but not Firefox, I noticed that the game runs much faster on autoplay in Firefox than it does in Chrome (i.e., the autoplay bot makes decisions much quicker in Firefox). This could be why the extra delay in the setTimeout function is helping in Chrome.

Best,

Drew

node.timer.setTimeout(function() {

                // Widget steps.

                if (id === 'phase 2') {                   

                    //timeout a portion of the time (default is no timeout "> 0.0")

                    if (Math.random() > 0.0) {

                        node.widgets.lastAppended.setValues({ correct: true });

                        node.timer.random(3000,5000).done();

                    }

                    else {

                        node.timer.random(3000,5000).timeup();

                    }                   

                }

                else if (id === 'terms and conditions' || id === 'demographics' || id === 'experience survey' || id === 'instruction quiz' || id === 'practice trial' || id === 'phase 1' || id === 'phase 3' ) {                   

                    //timeout a portion of the time (default is no timeout "> 0.0")

                    if (Math.random() > 0.0) {

                        node.widgets.lastAppended.setValues({ correct: true });

                        node.timer.random(2000,3000).done();

                    }

                    else {

                        node.timer.random(2000,3000).timeup();

                    }                   

                }

                else if (id === 'end') {

                    return null;

                }

                else {

                    node.timer.random(2000,3000).done();

                }

            }, 5000);

}

[Drew Cranford]

Hmm, well I think I was mistaken. It seems to still be a problem even with extending the setTimeout duration to 5000 ms.

The error only occurs for a few of the players, usually just one out of the 10 in the group, but sometimes 2, and I've even seen up to 4. And it seems that it doesn't occur for any players sometimes (maybe 1 out of 5 or 1 out of 10 games).

It is always, and only, on the very first trial of phase 2. And the game is trying to step to the next step before node.on('Playing'... is triggered for the player (i.e., before any autoplay bot makes a decision and issues a 'done' command -- before any node.timer.random(x,x).done() command fires).

-Drew

[shakty]

Hi,

I haven't tried to run it, but my hunch is the following.

There are some nested timers and I believe some timer that started in the previous step may terminate at the beginning of the next one forcing the game to advance when it should not. 

In fact, in autoplay.js, why is 

node.timer.setTimeout(function() { ... 

needed?

Anyway, one option would be to replace the calls 

random(...).done() 

with something like:

random(...).exec(function() {

  var stepIdNew = node.game.getStepId();

   if (stepIdNew !== stepId) return;

   node.done();

});

So we check if the stepId has changed when the timeout expires.

Let me know. Cheers,

Stefano

[Drew Cranford]

Okay, thanks for the tips. I'll try some things out.

The idea that "a timer that started in the previous step may be terminating at the beginning of the next one, forcing the game to advance", got me thinking. It looks like the game is trying to step a player when they enter the waitroom before Phase 2. For the first 9 players, an error is thrown, saying the game cannot be stepped. However, the error does not break the game. However, when the 10th player enters the waitroom, as soon as they enter the waitroom, the game is advanced to Phase 2, and the game doesn't try to step them until the first trial trial has started, which results in the game breaking error.

Given this info, it seems as though I don't have something correct in how I end the first level and/or how I move players to the waitroom. Perhaps you can take a look at the first level ./game/client_types/logic.js and ./player.js, in conjuction with ./autoplay.js, to check that I am ending the first level and moving players to the waitroom correctly?

Thanks,

Drew

[Drew Cranford]

Okay, so I think I found the problem. On the last step before gameover, when the player calls node.done(), I was trying to move the player to the next level by adding node.say('level_done'...) to the done cb. The game was catching a done message and trying to step the game to 'gameover' while already in the waitroom.

In player.js I added a stager.setOnGameover(function()...) and moved the node.say('level_done'...) here. In the logic.js, I added a listener for level_done in the stager.setOnInit() function and the game now successfully steps from the last step in Phase 1 to gameover before pushing the player into the waitroom of the next level, Phase 2.

Everything seems to be running fine now.

And the issue seemed to stem from me now properly moving players from the first level to the second level.

-Drew

[shakty]

Glad my solution inspired to find the real problem :)

It's also time to make moving players across levels easier... added to my todos.