Disconnect due to encryption error causes relog to break (Error: Already logged on)

[3urobeat]

Hey, I'm running into a weird situation and don't know where to go from here. 

It happens roughly once a month and causes my bot to "freeze" as the account gets stuck in the relog queue and prevents all other accounts from relogging.

 

The issue:

One of my accounts recieves the error event "Encrypted message authentication failed" (autoRelogin is false!) after being online already for quite some time (so the error doesn't happen on login) and an Unhandled Rejection "error:0606506D:digital envelope routines:EVP_DecryptFinal_ex:wrong final block length".

Well whatever, I'm just going to push the account to my relog queue system which should get the account back up after waiting 30 seconds. But now weird things happen: I call bot.logOff() just to be sure, wait a few more seconds, then call bot.logOn() again but another Unhandled Rejection fires: "Already logged on, cannot log on again".

Firstly, shouldn't that error trigger the error event instead of an unhandledRejection? But mainly - how is based on your comment here as well as on the check in the code the bot.steamID object defined when I specifically called bot.logOff()? (or does logOff() not handle that and I need to do something else?) I'm confused. Maybe the lib is unable to handle the logOff call after that error? 

 

Do you have an idea where to go from here? This problem is probably hard to troubleshoot as I don't know how one would replicate the error.

I am using proxies maybe that contributes to the error.

 

(Maybe) relevant stuff:

Log:

[2022-07-04 14:40:38 | INFO] [Bot 13] Lost connection to Steam. Reason: Error: Encrypted message authentication failed
[2022-07-04 14:40:38 | INFO] [Bot 13] Initiating a relog in 30 seconds.
[ERROR] Uncaught Exception Error! Reason: Error: error:0606506D:digital envelope routines:EVP_DecryptFinal_ex:wrong final block length
    at CipherBase.final (<anonymous>)
    at Decipheriv._flush (node:internal/crypto/cipher:160:29)
    at Decipheriv.final [as _final] (node:internal/streams/transform:112:25)
    at callFinal (node:internal/streams/writable:694:27)
    at prefinish (node:internal/streams/writable:719:7)
    at finishMaybe (node:internal/streams/writable:729:5)
    at Decipheriv.Writable.end (node:internal/streams/writable:631:5)
    at Object.exports.symmetricDecrypt (/steam-comment-service-bot/node_modules/@doctormckay/steam-crypto/index.js:80:10)
    at TCPConnection._readMessage (/steam-comment-service-bot/node_modules/steam-user/components/connection_protocols/tcp.js:185:27)
    at Socket.emit (node:events:390:28)

[2022-07-04 14:40:38 | WARN] If the bot doesn't work correctly anymore after this error then please restart it!
[2022-07-04 14:41:08 | INFO] [Bot 13] Queueing for a relog. 0 other accounts are waiting...
[2022-07-04 14:41:09 | INFO] [Bot 13] It is now my turn. Waiting 2.5 seconds before attempting to relog...
[2022-07-04 14:41:11 | INFO] [Bot 13] Trying to relog with proxy 2...
[ERROR] Unhandled Rejection Error! Reason: Error: Already logged on, cannot log on again
    at /steam-comment-service-bot/node_modules/steam-user/components/08-logon.js:28:11
    at processTicksAndRejections (node:internal/process/task_queues:78:11)
    at runNextTicks (node:internal/process/task_queues:65:3)
    at processTimers (node:internal/timers:497:9)

My error event handler

My relog system (Is there something to improve? Waiting, doing logOff(), waiting and then logOn() should be a clean relog, right?)

[Dr. McKay]

"Encrypted message authentication failed" should honestly never happen. If it does, either something is very broken in your setup, or else someone (e.g. your proxy) is modifying your network traffic in transit.

Could you please provide the versions of everything involved? steam-user, @doctormckay/steam-crypto, node.js, operating system, etc.

I'll try to make recovery from that error a little more gracious, but in the meantime you might be able to work around it by forcing the protocol to WebSocket:

let user = new SteamUser({
    protocol: SteamUser.EConnectionProtocol.WebSocket
});

 

Edited July 29, 2022 by Dr. McKay

[3urobeat]

Thanks for the quick response! 

Sure, these versions were used the last time the error occurred (2022-07-04):
OS: Arch Linux 5.15.55-1-lts
My bot: BETA 2.12 b8 (Repo at the point of commit)
node.js: 16.13.1
steam-user: 4.24.3
steam-crypto: 1.2.0
steamcommunity: 3.44.1

 

One more interesting thing I just noticed in my log:

There was one time (out of 5 since 2022-05-22) where an account recieved a second different error as well and actually managed to relog fine.
(So 4 times since 2022-05-22 the behaviour above happend, one time this happened)
Log excerpt from connection loss until webSession event:

[2022-05-24 15:37:51 | INFO] [Bot 32] Lost connection to Steam. Reason: Error: Encrypted message authentication failed
[2022-05-24 15:37:51 | INFO] [Bot 32] Initiating a relog in 30 seconds.
[ERROR] Uncaught Exception Error! Reason: RangeError: Illegal range: 0 <= 8 <= 1208313696 <= 148
    at ByteBuffer.module.exports.ByteBufferPrototype.slice (/steam-comment-service-bot/node_modules/bytebuffer/dist/bytebuffer-node.js:2764:23)
    at SteamUser._handleNetMessage (/steam-comment-service-bot/node_modules/steam-user/components/03-messages.js:529:81)
    at TCPConnection._readMessage (/steam-comment-service-bot/node_modules/steam-user/components/connection_protocols/tcp.js:194:13)
    at Socket.emit (node:events:390:28)
    at emitReadable_ (node:internal/streams/readable:578:12)
    at onEofChunk (node:internal/streams/readable:556:5)
    at readableAddChunk (node:internal/streams/readable:269:5)
    at Socket.Readable.push (node:internal/streams/readable:228:10)
    at TCP.onStreamRead (node:internal/stream_base_commons:249:12)

[2022-05-24 15:37:51 | WARN] If the bot doesn't work correctly anymore after this error then please restart it!
[ERROR] Uncaught Exception Error! Reason: Error: error:0606506D:digital envelope routines:EVP_DecryptFinal_ex:wrong final block length
    at CipherBase.final (<anonymous>)
    at Decipheriv._flush (node:internal/crypto/cipher:160:29)
    at Decipheriv.final [as _final] (node:internal/streams/transform:112:25)
    at callFinal (node:internal/streams/writable:694:27)
    at prefinish (node:internal/streams/writable:719:7)
    at finishMaybe (node:internal/streams/writable:729:5)
    at Decipheriv.Writable.end (node:internal/streams/writable:631:5)
    at Object.exports.symmetricDecrypt (/steam-comment-service-bot/node_modules/@doctormckay/steam-crypto/index.js:80:10)
    at TCPConnection._readMessage (/steam-comment-service-bot/node_modules/steam-user/components/connection_protocols/tcp.js:185:27)
    at Socket.emit (node:events:390:28)

[2022-05-24 15:37:51 | WARN] If the bot doesn't work correctly anymore after this error then please restart it!
[2022-05-24 15:38:21 | INFO] [Bot 32] Queueing for a relog. 0 other accounts are waiting...
[2022-05-24 15:38:22 | INFO] [Bot 32] It is now my turn. Waiting 2.5 seconds before attempting to relog...
[2022-05-24 15:38:25 | INFO] [Bot 32] Trying to relog with proxy 5...
[2022-05-24 15:38:26 | INFO] [Bot 32] Account logged in! Waiting for websession...
[2022-05-24 15:38:27 | INFO] [Bot 32] Got websession and set cookies.
[2022-05-24 15:38:27 | INFO] [Bot 32] Relog successful.
[2022-05-24 15:38:27 | INFO] [Bot 32] Accepting offline friend & group invites...

Maybe this helps in some way narrowing down the issue.

I'll try and force the protocol to WebSocket in the meantime as you suggested, however it's hard to see if it'll make a difference as the behaviour only occurrs roughly once a month.

Edited July 29, 2022 by 3urobeat
Added more versions

[Dr. McKay]

4.24.6 should improve this issue.

[3urobeat]

Thank you! Should I keep forcing the protocol to WebSocket?

[Dr. McKay]

It certainly won't hurt anything to keep forcing the protocol to WebSocket, and it might improve compatibility with your proxy.

[3urobeat]

Alright, thanks again!