search

cfdp / opeka

Counseling chat service, built for providing anonymous help to young people at risk
https://curachat.com
GNU General Public License v3.0
10 stars 6 forks source link

Session not found #47

Closed benjamin-dk closed 7 years ago

benjamin-dk commented 8 years ago

The following bug crashes the chat - I don't know what user action causes it.

2015-11-17T07:53:04.220Z - info: Incorrect access code given.

/home/chat/opeka/nodejs/lib/opeka.js:236
        throw err;
              ^
Session not found
error: Forever detected script exited with code: 8
cfdp commented 7 years ago

This bug is still present on the production server setup (nginx reverse proxy) that runs the latest code on the develop branch:

I haven't found a way to reliably reproduce the bug, but it typically (always?) occurs when an authenticated user tries to log into the chat for the first time.

For the authenticated user the bug presents itself as a popup window saying "incorrect access code given". And then the node process crashes. On the production server the node process is restarted with forever and after the restart the user can login to the chat.

The "Incorrect access code given" message is misleading - the access code feature is not enabled. So it might be related to a wrong implementation of this feature.

2017-03-03T09:05:46.938Z - info: Drupal user ID: 30
3 Mar 09:05:46 - clientUser.sid: LaQy_m8AMNcWwtru-oNczKZNMD1eBV5-ihSYcqb8oVs
3 Mar 09:05:46 - clientUser.uid: 30
2017-03-03T09:05:46.946Z - info: Incorrect access code given.
/home/demo/domains/demo-node.curachat.com/opeka/nodejs/lib/opeka.js:242
        throw err;
        ^

Error: Cannot enqueue Query after fatal error.
    at Protocol._validateEnqueue (/home/demo/domains/demo-node.curachat.com/opeka/nodejs/node_modules/mysql/lib/protocol/Protocol.js:199:16)
    at Protocol._enqueue (/home/demo/domains/demo-node.curachat.com/opeka/nodejs/node_modules/mysql/lib/protocol/Protocol.js:135:13)
    at Connection.query (/home/demo/domains/demo-node.curachat.com/opeka/nodejs/node_modules/mysql/lib/Connection.js:208:25)
    at runQuery (/home/demo/domains/demo-node.curachat.com/opeka/nodejs/node_modules/drupal/lib/db.js:87:10)
    at /home/demo/domains/demo-node.curachat.com/opeka/nodejs/node_modules/drupal/lib/db.js:74:7
    at getClient (/home/demo/domains/demo-node.curachat.com/opeka/nodejs/node_modules/drupal/lib/db.js:51:14)
    at Object.query (/home/demo/domains/demo-node.curachat.com/opeka/nodejs/node_modules/drupal/lib/db.js:67:3)
    at Object.session_load (/home/demo/domains/demo-node.curachat.com/opeka/nodejs/node_modules/drupal/lib/user.js:142:6)
    at Object.module.exports.authenticate (/home/demo/domains/demo-node.curachat.com/opeka/nodejs/lib/user.js:17:17)
    at Client.<anonymous> (/home/demo/domains/demo-node.curachat.com/opeka/nodejs/lib/opeka.js:238:16)
error: Forever detected script exited with code: 1
cfdp commented 7 years ago

With the logging improvements the bug looks like this and points out that the issue is related to drupal.user.session_load(): (We have some double logging going on I know).

It seems to be the database query that fails.

2017-03-08T09:33:06.343Z - info: Drupal user ID: 30
8 Mar 09:33:06 - clientUser.sid: lAJx7VTbp40xdgHs4PY_hG8Hy8_zlNZdZz29el4_K9w
8 Mar 09:33:06 - clientUser.uid: 30
8 Mar 09:33:06 - User authenticating, Drupal sid: lAJx7VTbp40xdgHs4PY_hG8Hy8_zlNZdZz29el4_K9w
8 Mar 09:33:06 - User authenticating, Drupal uid: 30
8 Mar 09:33:06 - Error: Could not load user session.
2017-03-08T09:33:06.348Z - info: Authentication failed. Try reloading the page.
/home/demo/domains/demo-node.curachat.com/opeka/nodejs/lib/opeka.js:242
        throw err;
        ^

Error: Cannot enqueue Query after fatal error.
    at Protocol._validateEnqueue (/home/demo/domains/demo-node.curachat.com/opeka/nodejs/node_modules/mysql/lib/protocol/Protocol.js:199:16)
    at Protocol._enqueue (/home/demo/domains/demo-node.curachat.com/opeka/nodejs/node_modules/mysql/lib/protocol/Protocol.js:135:13)
    at Connection.query (/home/demo/domains/demo-node.curachat.com/opeka/nodejs/node_modules/mysql/lib/Connection.js:208:25)
    at runQuery (/home/demo/domains/demo-node.curachat.com/opeka/nodejs/node_modules/drupal/lib/db.js:87:10)
    at /home/demo/domains/demo-node.curachat.com/opeka/nodejs/node_modules/drupal/lib/db.js:74:7
    at getClient (/home/demo/domains/demo-node.curachat.com/opeka/nodejs/node_modules/drupal/lib/db.js:51:14)
    at Object.query (/home/demo/domains/demo-node.curachat.com/opeka/nodejs/node_modules/drupal/lib/db.js:67:3)
    at Object.session_load (/home/demo/domains/demo-node.curachat.com/opeka/nodejs/node_modules/drupal/lib/user.js:142:6)
    at Object.module.exports.authenticate (/home/demo/domains/demo-node.curachat.com/opeka/nodejs/lib/user.js:20:17)
    at Client.<anonymous> (/home/demo/domains/demo-node.curachat.com/opeka/nodejs/lib/opeka.js:238:16)
error: Forever detected script exited with code: 1
error: Script restart attempt #1
alex-bukach commented 7 years ago

@benjamin-dk I'm not able to reproduce the issue on the staging site. I regularly tried to log in during the day, but all went without an error, and the things ended up with 

/home/s/domains/s-node.curachat.com/opeka/nodejs/lib/opeka.js:242
        throw err;
        ^

Error: Connection lost: The server closed the connection.
    at Protocol.end (/home/s/domains/s-node.curachat.com/opeka/nodejs/node_modules/mysql/lib/protocol/Protocol.js:109:13)
    at Socket.<anonymous> (/home/s/domains/s-node.curachat.com/opeka/nodejs/node_modules/mysql/lib/Connection.js:109:28)
    at emitNone (events.js:91:20)
    at Socket.emit (events.js:185:7)
    at endReadableNT (_stream_readable.js:974:12)
    at _combinedTickCallback (internal/process/next_tick.js:74:11)
    at process._tickCallback (internal/process/next_tick.js:98:9)

I have made the modifications I mentioned to prevent the whole application crash in the case of authentication error, please see https://github.com/cfdp/opeka/pull/76.

To debug the original issue I would propose to modify Protocol.prototype._validateEnqueue method in opeka/nodejs/node_modules/mysql/lib/protocol/Protocol.js: replace err = new Error(prefixAfter + 'fatal error.'); with err = new Error(prefixAfter + 'fatal error: ' + this._fatalError.message);. This would allow to see the initial MySQL error.

cfdp commented 7 years ago

@alex-bukach The error mesage now looks like this:

21 Mar 12:12:37 - User authenticating, Drupal sid: B0AoM1xXpMFtJTQuCzP2MclvJof_yGGz-lzEGyu8qJE
21 Mar 12:12:37 - User authenticating, Drupal uid: 3
21 Mar 12:12:37 - Error: Could not load user session.
2017-03-21T12:12:37.904Z - info: Authentication failed. Try reloading the page.
/home/ch-group/domains/ch-group-node.curachat.com/opeka/nodejs/lib/opeka.js:240
        throw err;
        ^

Error: Cannot enqueue Query after fatal error: Connection lost: The server closed the connection.
    at Protocol._validateEnqueue (/home/ubuntu/.nvm/versions/node/v6.6.0/lib/node_modules/drupal/node_modules/mysql/lib/protocol/Protocol.js:199:11)
    at Protocol._enqueue (/home/ubuntu/.nvm/versions/node/v6.6.0/lib/node_modules/drupal/node_modules/mysql/lib/protocol/Protocol.js:135:13)
    at Connection.query (/home/ubuntu/.nvm/versions/node/v6.6.0/lib/node_modules/drupal/node_modules/mysql/lib/Connection.js:214:25)
    at runQuery (/home/ubuntu/.nvm/versions/node/v6.6.0/lib/node_modules/drupal/lib/db.js:87:10)
    at /home/ubuntu/.nvm/versions/node/v6.6.0/lib/node_modules/drupal/lib/db.js:74:7
    at getClient (/home/ubuntu/.nvm/versions/node/v6.6.0/lib/node_modules/drupal/lib/db.js:51:14)
    at Object.query (/home/ubuntu/.nvm/versions/node/v6.6.0/lib/node_modules/drupal/lib/db.js:67:3)
    at Object.session_load (/home/ubuntu/.nvm/versions/node/v6.6.0/lib/node_modules/drupal/lib/user.js:139:6)
    at Object.module.exports.authenticate (/home/ch-group/domains/ch-group-node.curachat.com/opeka/nodejs/lib/user.js:18:17)
    at Client.<anonymous> (/home/ch-group/domains/ch-group-node.curachat.com/opeka/nodejs/lib/opeka.js:236:16)
error: Forever detected script exited with code: 1
error: Script restart attempt #1