`LOGOUT` user if detected `NAMESPACE not allowed now`

[titanism]

@andris9 Clients such as Thunderbird that have inconsistent state with the server (e.g. if a WildDuck server is restarted and LOGOUT is not invoked quickly enough to the client - or the client doesn't receive the command) – then the client itself will not be in a correct state.

If a command such as NAMESPACE requires 'Authenticated' state, then perhaps we should write the LOGOUT command to the client?

❯ rg "'Authenticated'"
imap-core/lib/commands/compress.js
7:    state: ['Authenticated', 'Selected'],

imap-core/lib/commands/unsubscribe.js
8:    state: ['Authenticated', 'Selected'],

imap-core/lib/commands/lsub.js
9:    state: ['Authenticated', 'Selected'],

imap-core/lib/commands/status.js
9:    state: ['Authenticated', 'Selected'],

imap-core/lib/commands/select.js
10:    state: ['Authenticated', 'Selected'],
70:                this.state = 'Authenticated';
84:                this.state = 'Authenticated';

imap-core/lib/commands/login.js
124:                this.state = 'Authenticated';

imap-core/lib/commands/enable.js
4:    state: ['Authenticated'],

imap-core/lib/commands/append.js
6:    state: ['Authenticated', 'Selected'],

imap-core/lib/commands/namespace.js
4:    state: ['Authenticated', 'Selected'],

imap-core/lib/commands/idle.js
4:    state: ['Authenticated', 'Selected'],

imap-core/lib/commands/xapplepushservice.js
13:    state: ['Authenticated', 'Selected'],

imap-core/lib/commands/subscribe.js
8:    state: ['Authenticated', 'Selected'],

imap-core/lib/commands/getquotaroot.js
9:    state: ['Authenticated', 'Selected'],

imap-core/lib/commands/setquota.js
4:    state: ['Authenticated', 'Selected'],

imap-core/lib/commands/getquota.js
8:    state: ['Authenticated', 'Selected'],

imap-core/lib/commands/authenticate-plain.js
133:            connection.state = 'Authenticated';

imap-core/lib/commands/rename.js
8:    state: ['Authenticated', 'Selected'],

imap-core/lib/commands/close.js
18:            this.state = 'Authenticated';
27:        this.state = 'Authenticated';

imap-core/lib/commands/unselect.js
8:        this.state = 'Authenticated';

imap-core/lib/commands/delete.js
8:    state: ['Authenticated', 'Selected'],

imap-core/lib/commands/create.js
8:    state: ['Authenticated', 'Selected'],

imap-core/lib/commands/list.js
19:    state: ['Authenticated', 'Selected'],

[titanism]

        // Check if the command can be run in current state
+        const states = handler.state && [].concat(handler.state || []);
+        if (states && !states.includes(this.connection.state)) {
-        if (handler.state && [].concat(handler.state || []).indexOf(this.connection.state) < 0) {
            let err = new Error(parsed.command.toUpperCase() + ' not allowed now');
            err.responseCode = 500;
            err.code = 'InvalidState';
+            // <https://github.com/nodemailer/wildduck/issues/726>
+            if (states.includes('Authenticated')) {
+              this.connection.clearNotificationListener();
+              this.connection.send('* BYE Logout requested');
+              setImmediate(() => this.connection.close());
+            }
            return callback(err);
        }

[andris9]

How does this even happen? If Wildduck is restarted then the TCP connection gets closed as well. Thunderbird initiates a new TCP connection but thinks its still the previous one?

[titanism]

I'm thinking there's an edge case I don't know of, and an obvious edge case is if something like out of memory error occurs and the process gets killed, then the state of the client will not match server.

But regardless I think we should dummy-proof this for clients somehow, the client clearly thinks it's logged in when it's not.

[andris9]

I think it is better to figure out why the client thinks they are still connected. For example, they re-use a TLS session and think they are still on the same session even if TCP was reconnected. Or there is a proxy in between that fails to handle the lost connection or whatever.

[titanism]

Users are continuously reporting this issue in Thunderbird with our service. I haven't pinpointed the underlying issue yet though.

[titanism]

I've managed to turn on some rudimentary debug logging and can see this happening in real-time for dozens of commands from Thunderbird mail clients.

For example:

• Error message is SELECT not allowed now
• session.clientId has value { name: 'Thunderbird', version: '128.1.0' }
• session.commandCounters has value { CAPABILITY: 2, 'AUTHENTICATE PLAIN': 1, ID: 1, SELECT: 1 }
• Current connection.state is "Not Authenticated"
• parsed value is { tag: '73', command: 'select', attributes: [ { type: 'STRING', value: 'INBOX' } ] }

I think that sometimes connections don't close, as mentioned ENOMEM could be such a case. In any regard, I think we should dummy-proof this and instruct the client to logout somehow.

[titanism]

@andris9 see https://github.com/nodemailer/wildduck/pull/727

[andris9]

Having AUTHENTICATE PLAIN in command counters should indicate that the client did authenticate. So maybe the issue really is on wildduck side somehow 🤔

[titanism]

@andris9 on all of these errors the this.connection.session.user property is not set. Occurs on Thunderbird and also a quite a few other clients such as Android:

5|imap-993  |   clientId: {
5|imap-993  |     name: 'com.google.android.gm',
5|imap-993  |     os: 'android',
5|imap-993  |     'os-version': '14; UP1A.231005.007',
5|imap-993  |     vendor: 'Xiaomi'
5|imap-993  |   },

[titanism]

We're using PM2, not using setImmediate before invoking our command callbacks, and not setting custom UV_THREADPOOL_SIZE, but I don't think any of that makes a difference since these are long-lived socket connections.

[andris9]

Do you log IMAP commands? Can you check what was the result of AUTHENTICATE PLAIN in the same session before SELECT?

[titanism]

I don't log IMAP commands, but we return early, e.g. callback(err) if auth failed with an error such as:

const err = new Error('Auth failed');
err.responseCode = 535;
err.imapResponse = 'AUTHENTICATIONFAILED';

However we also set err.response equal to err.message, so that's probably the culprit:

                    let payload = imapHandler.compiler(this.parsed, false, true);
                    errors.notifyConnection(this.connection, err, {
                        payload: payload ? (payload.length < 256 ? payload : payload.toString().substr(0, 150) + '...') : false
                    });
                    this.connection.send(this.tag + ' ' + (err.response || 'BAD') + ' ' + err.message);

You can see it's going to send the connection a super long message that contains err.response twice basically.

[titanism]

Not sure if this is going to fix it:

https://github.com/forwardemail/forwardemail.net/commit/665eb9fbbdc569f063c5bac585aea2641f2aa339#diff-61e712c78cab6addd480a2cfe8d9d74444754aefb62c9e511f1b32f4217ba354R686-L697

As you can see we don't set error.response anymore. Do you think this was the issue @andris9?

[titanism]

I reproduced the same issue locally, trying to figure this out now.

[titanism]

We simply were responding incorrectly to IMAP protocol command. The err.response other than "BAD" or "NO" will make the client think that authentication succeeded (e.g. err.response = "AUTHENTICATIONFAILED" is incorrect).