[09:40:40] what the hell is happening on test? [09:40:49] I'm going to reboot it [09:51:09] ^ something weird so will shortly be killing the instance [09:53:38] ^ killed [10:18:26] .uptime [10:18:26] I've been sitting here for 0:10:09 and I keep going! [10:19:03] Reception123: I never saw ZppixBot die in the middle of that [10:21:18] Reception123: Oh, I did that. I dropped abuse.py and restarted it. I have stupid memory [10:21:31] ah... [10:22:56] 10Tool-Zppixbot, 10User-RhinosF1: Debug random ZppixBot(-test) restarts - https://phabricator.wikimedia.org/T248960 (10RhinosF1) a:03RhinosF1 The test instance seems to be having a memory issue, I think I've fixed that by rebooting it but if not, I'll do a full reset. Zppixbot's main instance seems to be mo... [10:23:32] 10Tool-Zppixbot, 10User-RhinosF1: ZppixBot-test restarting due to memory not saving ping/pong - not loaded? - https://phabricator.wikimedia.org/T248960 (10RhinosF1) [10:25:06] zhuyifei1999_: I think -test might have been broke [14:22:10] .commands [14:22:10] Hang on, I'm creating a list. [14:22:10] I've posted a list of my commands at https://clbin.com/vHKiT - You can see more info about any of these commands by doing .help (e.g. .help time) [14:38:16] .mangle [14:38:19] MacFan4000: MacFan4000 said "command." [14:38:30] .weather [14:38:31] MacFan4000: Weather API key missing. Please configure this module. [14:41:09] .uptime [14:41:09] I've been sitting here for 4:32:52 and I keep going! [14:42:14] .happy [14:42:14] ᕕ( ᐛ )ᕗ [14:43:20] hey MacFan4000 [14:43:31] .uptime [14:43:31] I've been sitting here for 4:35:14 and I keep going! [14:43:35] .crazy [14:43:35] ⊙_ʘ [14:43:50] [pid 22] 14:43:31 recvfrom(7, ":tolkien.freenode.net 404 ZppixBot-test #ZppixBot :Cannot send to nick/channel\r\n:ZppixBot!~ZppixBot@miraheze/bot/Zppix PRIVMSG #ZppixBot :I've been sitting here for 4:35:14 and I keep going!\r\n", 65536, 0, NULL, NULL) = 192 [14:43:51] I have never seen the sopel emoticons module before [14:44:51] zhuyifei1999_: ZppixBot-test is muted in here [14:44:54] ah [14:45:24] zhuyifei1999_: I restarted it earlier FYI because it’s memory was being weird [14:45:40] are you sure it's not the race we talked about? [14:46:08] what do you mean by memory being weird? [14:47:33] zhuyifei1999_: it wasn’t finding stuff in memory properly [14:48:07] meaning? [14:48:22] like, what is the behavior that leads you to suspect that? [14:50:08] so far I've never observed Python programs having memory corruption [14:50:13] zhuyifei1999_: the error log [14:50:29] zhuyifei1999_: https://github.com/sopel-irc/sopel/issues/1865 is the bug we filed [14:50:29] [ find_lines logspam after connection issues · Issue #1865 · sopel-irc/sopel · GitHub ] - github.com [14:51:11] which is https://github.com/sopel-irc/sopel/blob/master/sopel/modules/find.py#L43 [14:51:12] [ sopel/find.py at master · sopel-irc/sopel · GitHub ] - github.com [14:51:24] https://github.com/sopel-irc/sopel/blob/0ae1d8ad4b43d1200d7c0949f772eb9102277142/sopel/modules/find.py#L30 [14:51:24] [ sopel/find.py at 0ae1d8ad4b43d1200d7c0949f772eb9102277142 · sopel-irc/sopel · GitHub ] - github.com [14:51:30] it's deleted here [14:53:25] zhuyifei1999_: it should recreate on startup though [14:53:54] Something in the reconnect sequence was being weird so I’m hoping a hard reboot fixed it [14:54:16] https://github.com/sopel-irc/sopel/blob/0ae1d8ad4b43d1200d7c0949f772eb9102277142/sopel/modules/find.py#L25 [14:54:16] [ sopel/find.py at 0ae1d8ad4b43d1200d7c0949f772eb9102277142 · sopel-irc/sopel · GitHub ] - github.com [14:54:43] so you probably have a race somewhere :) [14:56:20] zhuyifei1999_: more likely it’s trying to access memory that doesn’t exist. Ideally, we need to do a full reboot of the pod everytime it disconnects [14:57:31] As on disconnect it wipes but startup seems different [14:58:07] 'more likely it’s trying to access memory that doesn’t exist' <= if you mean the system 'virtual memory', where 'doesn’t exist' means 'unmapped', then you have a segfault here. this isn't what we are seeing [14:58:30] all I'm seeing is sopel having races [14:58:49] causing undeterministic behavior on the python code [14:59:46] Ok [15:00:07] resulting in preconditions in the python code being unsatisfied after certain sequence of execution during a race [15:01:00] the trace you posted has the assumption that 'find_lines' is in 'bot.memory' [15:02:04] this is unsatisfied because shutdown must have executed before setup [15:02:17] s/before/after/ [15:02:17] zhuyifei1999_ meant to say: this is unsatisfied because shutdown must have executed after setup [15:02:28] Hmm [15:02:56] We’ll see if they can fix it but killing the bot should have repopulated ir [15:04:10] in the case of 2020-05-19 21:11:48,217 [15:04:28] that happens right after disconnect and before the new connection is established [15:05:06] disconnection happens at 2020-05-19 21:11:48,212 >> PRIVMSG #ZppixBot-logs :[2020-05-19 21:11:48,209] sopel.cli.run WARNING - Disconnected. Reconnecting in 20 seconds... [15:05:06] zhuyifei1999_: is there anyway we could make it delete its pod if it disconnects? [15:05:52] probably. you need to hook on its disconnect to change sopel's default behavior [15:06:13] reconnection happens at 2020-05-19 21:12:08,837 >> CAP LS 302 [15:06:20] * RhinosF1 will just ssh in and do it manually for now [15:07:00] assuming disconnection called shutdown(), reconnection called setup() [15:07:36] then it would be obvious that bot.memory['find_lines'] raises KeyError [15:08:43] since it happens in between `del bot.memory['find_lines']` and `bot.memory['find_lines'] = SopelMemory()` [15:09:14] Hmm [15:11:28] zhuyifei1999_: why would it happen though with reminders set before a shutdown() but that send once the bot’s reconnected [15:11:57] That’s as if bot.memory[‘find_lines’] = SopelMemory() never runs properly [15:12:47] what do you mean by 'reminders'? [15:13:02] zhuyifei1999_: remind.py [15:13:08] Using .in and .at [15:13:34] what does that trace have anything to do with reminders? [15:13:58] zhuyifei1999_: find_lines errors also happen then [15:14:14] ok? [15:14:34] the entire trace can fully be explained from find.py [15:14:53] zhuyifei1999_: ok [15:15:54] collectlines() was simply called in the 20 second window between shutdown() and setup() [15:16:23] zhuyifei1999_: hmm, that’s strange and utterly mental handling [15:16:29] But I’ll update the issue [15:18:46] And play with the reminders issue locally [15:21:27] ok [18:13:24] zhuyifei1999_: ^ [18:13:52] if you can delete the pod and let it recreate [18:14:09] * RhinosF1 will reboot it later [18:14:22] We need a proper fix for it [18:36:16] did you file a ticket under sopel? [18:53:46] zhuyifei1999_: the logging backend is broken [18:54:04] So it’s sending messages to a dead connection while it shuts down [18:54:10] yes [18:55:14] They are now working out when to stop which process [18:55:15] zhuyifei1999_: https://github.com/sopel-irc/sopel/issues/1865 [18:55:16] [ find_lines logspam after connection issues · Issue #1865 · sopel-irc/sopel · GitHub ] - github.com [18:56:25] did you file a bug regarding the timeout detection being racey? [18:57:02] zhuyifei1999_: not yet, that’s later in my plan. [18:57:10] k [18:57:37] zhuyifei1999_: I’m going to see what they come up with for this because if the backend is being dodgy in order, could it even link? [18:58:00] what do you mean by 'could it even link'? [18:58:48] zhuyifei1999_: if the backend is doing things in the wrong order, could the check for timeout be in the wrong order [18:59:28] if by 'backend' you mean sopel, then yes [19:00:04] zhuyifei1999_: yes I do [19:00:21] https://www.irccloud.com/pastebin/2j6UPSdD/ [19:00:22] [ Snippet | IRCCloud ] - www.irccloud.com [19:01:31] look, I'm not interested in figuring out what is going on until this is fixed. so far every restart I've looked at points to this [19:01:50] which has its root cause figured out [19:02:18] * RhinosF1 is raising it [19:03:05] so I prefer not to be pinged unless there is something new. I don't like explaining that 'there is a race' over and over [19:03:34] * RhinosF1 has just mentioned the race condition again to the devs