Jump to content
McKay Development

webSession sometimes not called after automatic relogin

3urobeat

By 3urobeat
in node-steam-user

 Share

Recommended Posts

3urobeat Apprentice

3urobeat

Posted
Posted (edited)

Hey! 

I'm facing an issue since a few weeks now regarding the automatic relogin after NoConnection.

My router resets the connection every morning and changes the IP which results in the 'disconnected' event getting called with the msg 'NoConnection'. In the past all accounts connected to my bot would relogin fine, set their webSession and work as expected. 

Since a few weeks now however some of my 10 accounts will appear offline after loosing connection and throw an error when trying to use them to comment (The settings on this account do not allow you to add comments) which is only solved by restarting the bot.

 

So now it gets a bit weird which is the reason why I am writing this as I have no idea what to do next anymore. 

By looking at the log I can see that the accounts in question get their 'disconnected' event with the message 'NoConnection' fired, after a few seconds the event 'loggedOn' is fired but the 'webSession' event gets never called. Thats probably why no cookies are being set/refreshed and the accounts fail trying to comment.

But why do they appear offline when `bot.gamesPlayed(...)` is executed in the 'loggedOn' event? And why only sometimes?

I have tried listening for the community 'sessionExpired' event to maybe execute a bot.webLogOn() manually but that doesn't seem to get fired.

 

While writing I just had the idea of maybe disabling autoRelogin and doing a bot.relog() with a delay myself (2500ms) in the 'disconnected' event because maybe the 10 accounts are logging in too fast after eachother? (But shouldn't the 'error' event then get called(?))

Sorry for not trying that before posting but I wanted to see if you maybe have an idea what to try next/what I am doing wrong.

 

Thanks for even reading this ^^

 

Additional information (not sure if it helps):

Installed versions:

steam-user: 4.19.4
steamcommunity: 3.42.0
node.js: 14.16.1

 

File containing all steam-user related functionality and events:


https://github.com/HerrEurobeat/steam-comment-service-bot/blob/master/src/bot.js
Sorry for the mess and having most of the code in one long file but it was easier for me back then to write an updater for it. It is on my list to improve.

 

Log from this morning showing connection loss & reconnect of my 10 accs

  Reveal hidden contents
Edited by 3urobeat
Added logindelay info
Dr. McKay Grand Master

Dr. McKay

Posted
Posted

How frequently does this happen? If it happens fairly frequently, can you add this so I can see the debug output? 

client.on('debug', (msg) => console.log(msg));

It sounds plausible to me that something is preventing the API request from going through, but having the debug output would confirm this.

3urobeat Apprentice

3urobeat

Posted
  • Author
Posted

This happens every morning now when my router does a conenction reset. The affected accounts are different every time, probably because of the order in which they loose connection. 

I'm starting to think more that they fail logging in again because the requests are just too close to each other. This would also explain why I hadn't the issue with less accounts. But I'm still wondering why the loggedOn event is called and no error is shown then.

 

I have added the debug event listener and will try to cause a manual connection reset.

3urobeat Apprentice

3urobeat

Posted
  • Author
Posted (edited)

Disregard what this message said, after waiting 15 minutes the bot finally tried to reconnect and I got more useful information in the comment below

 

  Reveal hidden contents
Edited by 3urobeat
3urobeat Apprentice

3urobeat

Posted
  • Author
Posted (edited)

So after causing a connection reset on the webpage of my router and waiting 15 minutes the bot finally decided to let me know that he was disconnected. (A bit too long for my taste but whatever)

5/10 accounts relogged successfully, the rest is offline again. 

Failed accs: Bot 1, Bot 3, Bot 5, Bot 7, Bot 8

 

I hope you can figure something out from these 1300 lines of debug messages xd

It starts with the last message before the route reconnected and ends with the last useful message (after that only ClientPersonaState was shown)

  Reveal hidden contents
Edited by 3urobeat
added which accs failed
3urobeat Apprentice

3urobeat

Posted
  • Author
Posted (edited)

I ran a quick  cat log.txt | grep 'Bot 1' >> filtered.txt  over the log posted above to make analyzing what happens to one account a bit easier.

(And sorry for the spam)

  Reveal hidden contents
Edited by 3urobeat
Dr. McKay Grand Master

Dr. McKay

Posted
Posted

Thanks, that's a little helpful but I'm still having trouble tracking down exactly what's happening. Please update to steam-user v4.19.5 and also log the debug-verbose event in the same manner as the debug event.

3urobeat Apprentice

3urobeat

Posted
  • Author
Posted (edited)

Sorry it took a bit longer to make this reply because trying to post a really long log here messes up your cookies when it tries to save what you previously wrote inside the reply box...

So - I updated steam-user and reconnected again. Interestingly this time two accounts instantly recieved the disconected event and relogged after I reset the connection. The other accounts took their time as usual. Two accounts didn't make it again (I think Bot 2 and Bot 4).

 

I hosted the log myself real quick: (8300 lines)

https://3urobeat.com/log.txt

Edited by 3urobeat
Remove emoji
3urobeat Apprentice

3urobeat

Posted
  • Author
Posted

Just another note on the idea to handle a delayed relog myself:

It would technically be easier for me to relog all accounts with a delay between them than for your library because your library only knows of the one account it is connected to and not the whole picture like my controller file. I could just call a function in my controller file from the disconnected event which then does a normal logOn again for that bot, saves the last login timestamp and if another call is made within the cooldown period it queues that account and performs a login when the cooldown is over.

Running many accounts with multiple steam-user instances is probably an edge case which the user should handle themselves (and I can't see how it should be able to handle that).

The only thing that probably needs to be investigated is why no error event is called when the webLogOn failes (403), why it takes so long for the bots to realise they have been disconnected and why the logOn event is called even though the accounts still appear offline.

 

Filtered again for Bot 4 this time:

  Reveal hidden contents

3urobeat Apprentice

3urobeat

Posted
  • Author
Posted (edited)

Alright, I made an update containing a custom relog function which queues each account loosing connection and relogs each one after another. 

I tested it yesterday and overnight and all accounts survived the connection reset of my router. This should confirm that the accounts indeed failed to relog because of too many login requests in a short timespan. I have yet to test how my implementation behaves when Steam is down and the bot can't reconnect on the first try (but it should retry through the error event until sucessful).

GitHub commit (if you are interested): https://github.com/HerrEurobeat/steam-comment-service-bot/commit/fafad59

 

Another thought regarding the 15 minutes delay before emitting disconnected:

I found this answer which you made in a post from 2017. Is this still relevant and might be the reason for this behaviour? I haven't tested my bot on Windows since a few months now after fully switching to Linux in the beginning of this year and therefore can't compare right now.

 

Log to prove that the accounts still lost connection very close to each other:

  Reveal hidden contents
Edited by 3urobeat
Replaced GitHub beta branch commit link with master branch commit
Dr. McKay Grand Master

Dr. McKay

Posted
Posted (edited)

Okay, this is interesting. Are you running your app on slow hardware, maybe a Raspberry Pi? It looks like Steam is sending back gzipped responses, and for some reason some of these responses are taking multiple seconds to ungzip. This is resulting in the timer for ClientLogOnResponse elapsing while ungzipping, resulting in a relog. But once the account gets relogged, the old ClientLogOnResponse comes in and it thinks it's logged on when it isn't.

log.txtFetching info...

Edited by Dr. McKay
3urobeat Apprentice

3urobeat

Posted
  • Author
Posted (edited)

Yes I am indeed using a Raspberry Pi (3B) for hosting the bot. I haven't tested if the original issue of this post is also present on my main machine.

 

I have just updated to v4.19.6 and I see you implemented queueing for multi msg processing because it absolutely obliterates the log (you should maybe think of another way of logging "Enqueued incoming message" because I just got 1970 lines of that message in one second).

However I am sadly not able to test/use the version because logging in now uses 85% CPU which results in my bot not being able to log in all accounts (maybe but I would need to wait 10+ minutes instead of 40 seconds).

My desktop machine has no problem with the update. (Ryzen 5 2600)

 

I have just rolled back to v4.19.5 and logging in works fine again with just 25% CPU usage.

 

Last few lines before only printing "[2021-05-11 14:55:49] debug: Enqueued incoming message; queue size is now 5" 2k times per second (seems like it got stuck trying to process a msg):

  Reveal hidden contents
Edited by 3urobeat
added last lines of log
3urobeat Apprentice

3urobeat

Posted
  • Author
Posted (edited)

I have updated steam-user to v4.19.7 and downgraded my bot to 2.10.4 in order to test relogging without my relog queue update.

CPU usage looks fine again (spikes up to ~40% but is mostly at ~25%) during startup so thats good. During login (regular login, before causing a connection reset) there are a lot of WebSocket timed out debug messages, not sure if those were present before too.

 

After causing a connection reset it took 15 minutes again before they realized they had lost connection. For some odd reason I recieved multiple Unhandled Rejection "Already logged on, cannot log on again" errors (I sadly can't track down from which account they come but I guess from one of the failed accs(?)), the bot was definitely running only once and the accounts were not logged in somewhere else. This never happened before.

 

I have attached the full log below. It contains all messages starting with the first login and ending ~10 minutes after the accounts realized they had lost connection. The connection reset was at 12:29:10. 4/10 accounts did fail to log back on (Main (Bot 0), Bot 7, Bot 8 and Bot 9). I have also attached a filtered log that only contains messages from the main account (Bot 0).

filtered.txtFetching info... steamtestoutput.txtFetching info...

Edited by 3urobeat

Join the conversation

You can post now and register later. If you have an account, sign in now to post with your account.
Note: Your post will require moderator approval before it will be visible.

Guest
Reply to this topic...

×   Pasted as rich text.   Paste as plain text instead

  Only 75 emoji are allowed.

×   Your link has been automatically embedded.   Display as a link instead

×   Your previous content has been restored.   Clear editor

×   You cannot paste images directly. Upload or insert images from URL.

×
 Share
Go to topic listing
×
×
  • Create New...