Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

[BUG] Discord bot occasionally creates two portal sessions #3077

Closed
InspectorCaracal opened this issue Jan 8, 2023 · 10 comments · Fixed by #3094
Closed

[BUG] Discord bot occasionally creates two portal sessions #3077

InspectorCaracal opened this issue Jan 8, 2023 · 10 comments · Fixed by #3094
Labels
bug An actual error or unwanted behavior.

Comments

@InspectorCaracal
Copy link
Contributor

Describe the bug

Sometimes when starting up or reloading a game, the Discord bot appears to create two portal sessions instead of one. A reboot of the game (the restart which stops and restarts the portal as well) corrects the issue.

It's not entirely clear what conditions cause this yet, so I am opening this issue to collect additional information to track down the problem.

Environment, Evennia version, OS etc

Debian, evennia 1.0.2
@InspectorCaracal InspectorCaracal added bug An actual error or unwanted behavior. needs-triage Yet to be looked at and verified as an a real issue/feature that could be worked on labels Jan 8, 2023
@Antrare
Copy link
Contributor

Antrare commented Jan 14, 2023

Not just 2 sessions, it keeps going:
| DiscordBot | 3d 00:00 | 3d | None | None | 1 | discord | discord.gg |
| DiscordBot | 2d 21:12 | 2d | None | None | 1 | discord | discord.gg |
| DiscordBot | 2d 17:33 | 2d | None | None | 1 | discord | discord.gg |
| DiscordBot | 2d 15:47 | 2d | None | None | 1 | discord | discord.gg |
| DiscordBot | 1d 22:39 | 1d | None | None | 1 | discord | discord.gg |
| DiscordBot | 1d 21:27 | 1d | None | None | 1 | discord | discord.gg |
| DiscordBot | 1d 17:33 | 1d | None | None | 1 | discord | discord.gg |
| DiscordBot | 1d 10:52 | 1d | None | None | 1 | discord | discord.gg |
| DiscordBot | 18:23 | 18h | None | None | 1 | discord | discord.gg |

@Griatch Griatch added devel-implemented Already finished, usually in a branch not yet merged. and removed needs-triage Yet to be looked at and verified as an a real issue/feature that could be worked on devel-implemented Already finished, usually in a branch not yet merged. labels Jan 15, 2023
@Antrare
Copy link
Contributor

Antrare commented Jan 17, 2023

It doesn't appear to be limited to when reloading/restarting the game at all:

Accounts:
+-------------------------+----------+------+--------------+-----------------+------+-----------+-----------------------------+
| Account Name | On for | Idle | Puppeting | Room | Cmds | Protocol | Host |
+-------------------------+----------+------+--------------+-----------------+------+-----------+-----------------------------+
| Arithorn | 1d 23:35 | 2s | Arithorn(#1) | Home Sweet Home | 17 | telnet | 122.199.60.91 |
| DiscordBot | 01:05 | 1h | None | None | 1 | discord | discord.gg |
| grapewinebot-gvgos[...] | 1d 23:34 | 26m | None | None | 24 | grapevine | wss://grapevine.haus/socket |
| grapewinebot-gvtes[...] | 1d 23:35 | 1d | None | None | 0 | grapevine | wss://grapevine.haus/socket |
+-------------------------+----------+------+--------------+-----------------+------+-----------+-----------------------------+
4 unique accounts logged in.
[MudInfo] [2023-01-16(11:38)]: DiscordBot disconnected ()
[MudInfo] [2023-01-16(11:38)]: DiscordBot connected
[MudInfo] [2023-01-16(11:55)]: DiscordBot connected
[MudInfo] [2023-01-16(11:57)]: DiscordBot connected
[MudInfo] [2023-01-16(12:24)]: DiscordBot connected
[MudInfo] [2023-01-16(12:35)]: DiscordBot connected
[MudInfo] [2023-01-16(12:43)]: DiscordBot connected
[MudInfo] [2023-01-16(13:43)]: DiscordBot connected
[MudInfo] [2023-01-16(14:15)]: DiscordBot disconnected ()
[MudInfo] [2023-01-16(14:15)]: DiscordBot connected
[MudInfo] [2023-01-16(16:52)]: DiscordBot disconnected ()
[MudInfo] [2023-01-16(16:52)]: DiscordBot connected
[MudInfo] [2023-01-16(18:10)]: DiscordBot disconnected ()
[MudInfo] [2023-01-16(18:10)]: DiscordBot connected
[MudInfo] [2023-01-16(20:17)]: DiscordBot disconnected ()
[MudInfo] [2023-01-16(20:17)]: DiscordBot connected
[MudInfo] [2023-01-16(23:33)]: DiscordBot disconnected ()
[MudInfo] [2023-01-16(23:33)]: DiscordBot connected
[MudInfo] [2023-01-17(01:40)]: DiscordBot disconnected ()
[MudInfo] [2023-01-17(01:40)]: DiscordBot connected
[MudInfo] [2023-01-17(02:59)]: DiscordBot disconnected ()
[MudInfo] [2023-01-17(02:59)]: DiscordBot connected
[MudInfo] [2023-01-17(04:43)]: DiscordBot disconnected ()
[MudInfo] [2023-01-17(04:43)]: DiscordBot connected
[MudInfo] [2023-01-17(05:07)]: DiscordBot disconnected ()
[MudInfo] [2023-01-17(05:07)]: DiscordBot connected
who
Accounts:
+-------------------------+----------+------+--------------+-----------------+------+-----------+-----------------------------+
| Account Name | On for | Idle | Puppeting | Room | Cmds | Protocol | Host |
+-------------------------+----------+------+--------------+-----------------+------+-----------+-----------------------------+
| Arithorn | 2d 19:50 | 20h | Arithorn(#1) | Home Sweet Home | 18 | telnet | 122.199.60.91 |
| DiscordBot | 17:29 | 17h | None | None | 1 | discord | discord.gg |
| DiscordBot | 17:12 | 17h | None | None | 1 | discord | discord.gg |
| DiscordBot | 17:10 | 17h | None | None | 1 | discord | discord.gg |
| DiscordBot | 16:43 | 16h | None | None | 1 | discord | discord.gg |
| DiscordBot | 16:32 | 16h | None | None | 1 | discord | discord.gg |
| DiscordBot | 16:24 | 16h | None | None | 1 | discord | discord.gg |
| DiscordBot | 00:00 | 45s | None | None | 1 | discord | discord.gg |
| grapewinebot-gvgos[...] | 2d 19:50 | 20h | None | None | 24 | grapevine | wss://grapevine.haus/socket |
| grapewinebot-gvtes[...] | 2d 19:51 | 2d | None | None | 0 | grapevine | wss://grapevine.haus/socket |
+-------------------------+----------+------+--------------+-----------------+------+-----------+-----------------------------+

@Antrare
Copy link
Contributor

Antrare commented Jan 17, 2023

Here's the portal log where it appears the portal didn't drop the connection properly. Hope this helps!!

|Portal| 2023-01-16 11:55:11 [..] Discord connection lost.
|Portal| 2023-01-16 11:55:13 [..] Connecting to Discord...
|Portal| 2023-01-16 11:55:13 [..] Discord connection established.
|Portal| 2023-01-16 11:57:38 [..] Discord connection lost.
|Portal| 2023-01-16 11:57:40 [..] Connecting to Discord...
|Portal| 2023-01-16 11:57:40 [..] Discord connection established.
|Portal| 2023-01-16 12:24:02 [..] Discord connection lost.
|Portal| 2023-01-16 12:24:06 [..] Connecting to Discord...
|Portal| 2023-01-16 12:24:06 [..] Discord connection established.
|Portal| 2023-01-16 12:35:06 [..] Discord connection lost.
|Portal| 2023-01-16 12:35:12 [..] Connecting to Discord...
|Portal| 2023-01-16 12:35:12 [..] Discord connection established.
|Portal| 2023-01-16 12:43:32 [..] Discord connection lost.
|Portal| 2023-01-16 12:43:41 [..] Connecting to Discord...
|Portal| 2023-01-16 12:43:41 [..] Discord connection established.
|Portal| 2023-01-16 13:42:47 [..] Discord connection lost.
|Portal| 2023-01-16 13:43:00 [..] Connecting to Discord...
|Portal| 2023-01-16 13:43:00 [..] Discord connection established.

@InspectorCaracal
Copy link
Contributor Author

@Antrare can you share your version info?

@InspectorCaracal
Copy link
Contributor Author

Also, if you can find or track any information on the situation where a new session is created that would be really helpful.

@Antrare
Copy link
Contributor

Antrare commented Jan 17, 2023 

Evennia 1.1.0 (rev 74d470a4f6)
OS: posix
Python: 3.10.8
Twisted: 22.10.0
Django: 4.1.3

This is server log at same period, I'm not sure where else to get you the info you're asking for? It's interesting that the server knows there is more than enough sessions, could possibly check for that when reconnecting as well? I'm not going to get a chance to get back into coding for another week or so to have a go myself.

2023-01-16 11:38:36 [..] Logged out: DiscordBot(account 15) discord.gg (0 sessions(s) remaining)
2023-01-16 11:38:38 [..] Logged in: DiscordBot(account 15) discord.gg (1 session(s) total)
2023-01-16 11:55:13 [..] Logged in: DiscordBot(account 15) discord.gg (2 session(s) total)
2023-01-16 11:57:40 [..] Logged in: DiscordBot(account 15) discord.gg (3 session(s) total)
2023-01-16 12:24:06 [..] Logged in: DiscordBot(account 15) discord.gg (4 session(s) total)
2023-01-16 12:35:12 [..] Logged in: DiscordBot(account 15) discord.gg (5 session(s) total)
2023-01-16 12:43:41 [..] Logged in: DiscordBot(account 15) discord.gg (6 session(s) total)
2023-01-16 13:43:00 [..] Logged in: DiscordBot(account 15) discord.gg (7 session(s) total)
2023-01-16 14:15:26 [..] Logged out: DiscordBot(account 15) discord.gg (6 sessions(s) remaining)
2023-01-16 14:15:28 [..] Logged in: DiscordBot(account 15) discord.gg (7 session(s) total)

@Antrare
Copy link
Contributor

Antrare commented Jan 17, 2023

Just to add, there was nothing going on with the Discord channel (no messages at either end), no user activity and best I can tell there were no network dropouts/issues (as my telnet session to the server remained online throughout).

@FancysFancies
Copy link

logged on today with no discord activity messages on either end, and we may have @reloaded once or twice but not... alot. Came on to almost 20 discord bots connected https://pastebin.com/EDwBpC7g

@InspectorCaracal
Copy link
Contributor Author

InspectorCaracal commented Jan 24, 2023 •
edited

ALL RIGHT, I think I may finally have some useful information for this.

I rebooted my server a couple days ago to start from a clean slate on bot sessions and pulled out all the rest of my portal logging code so it's just errors and the Discord bot.

I currently have 3 sessions, which means an extra of two. In my logs, I have a lot of the standard "received reconnect opcode" disconnect/reconnects, but I also have two instances of the connection simply being lost.

My current tentative hypothesis is that the sessions aren't being closed properly when the connection is lost (as opposed to closed). Then, since the bot then creates a new session that re-establishes the remote connection, the "disconnected" ghost sessions can and do still communicate with the remote server, resulting in multiple active sessions.

I'll dig around into this over the next few days and see if I can find anywhere in the code that looks like it might be failing to clean up sessions.

@InspectorCaracal
Copy link
Contributor Author

I said "the next few days" but I am pretty sure I just found it. self.sessionhandler.disconnect(self) is called in the disconnect method instead of onClose - that would result in exactly the behavior I just described.

I'll test it for a couple days before I put in a PR but I think this will be an easy patch.

This was referenced Jan 25, 2023
Closed
Merged
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug An actual error or unwanted behavior.
Projects
None yet
Milestone
No milestone
4 participants
@Griatch @Antrare @InspectorCaracal @FancysFancies