Bug 1952 Mickey mantle pick in Deck of Every Card crash
- Thread starter Butts
- Start date
phreddrickk
Member
I encountered this today and wrote it off as just a cosmic ray/random event, but given that Butts encountered it twice in the same place, it's a little odd.
The code that triggered it just calls the cheat CLI command, which I don't see any recent changes to. This Could be a game bug, but the fact that it continues seamlessly after re-opening mafia suggests otherwise.
I don't see any recent changes to the code in the area here, but this only happened to me as of today.
EDIT: just hit it again, and a few notes:
I straight up cannot interact with the mafia window at all. I'll occasionally get bugs where trying to close it will print a debug log, but here, pressing literally any of the buttons does absolutely nothing.
It doesn't seem to be an issue with any other card in the deck, just the 1952 card
the relay browser is non-responsive, chat is non-responsive. I am able to switch tabs in tabbed kol chat, but chat doesn't update.
I was about to copy-and-paste a snippet from the CLI, but even that appears to not be an option.
I'm on Windows 10, using OpenJDK 17, mafia version 475424
The code that triggered it just calls the cheat CLI command, which I don't see any recent changes to. This Could be a game bug, but the fact that it continues seamlessly after re-opening mafia suggests otherwise.
I don't see any recent changes to the code in the area here, but this only happened to me as of today.
EDIT: just hit it again, and a few notes:
I straight up cannot interact with the mafia window at all. I'll occasionally get bugs where trying to close it will print a debug log, but here, pressing literally any of the buttons does absolutely nothing.
It doesn't seem to be an issue with any other card in the deck, just the 1952 card
the relay browser is non-responsive, chat is non-responsive. I am able to switch tabs in tabbed kol chat, but chat doesn't update.
I was about to copy-and-paste a snippet from the CLI, but even that appears to not be an option.
I'm on Windows 10, using OpenJDK 17, mafia version 475424
Last edited:
I cheat that card every day in my aftercore farming script. I have never had the slightest problem in many years of doing this.
Today's session log:
Today's session log:
Code:
use 1 Deck of Every Card
[16905] Deck of Every Card
play Island (35)
Encounter: Island
You acquire an item: blue mana
use 1 Deck of Every Card
[16905] Deck of Every Card
play Ancestral Recall (40)
Encounter: Ancestral Recall
You acquire an item: blue mana
use 1 Deck of Every Card
[16905] Deck of Every Card
play 1952 Mickey Mantle (58)
Encounter: 1952 Mickey Mantle
You acquire an item: 1952 Mickey Mantle card
How are you using this? I have never had a problem.
using
From today:
using
Code:
cli_execute("cheat 1952 Mickey Mantle");From today:
Code:
[1744] Deck of Every Card
Preference _deckCardsSeen changed from Island|Ancestral Recall to Ancestral Recall|Island
Preference _deckCardsDrawn changed from 10 to 14
play 1952 Mickey Mantle (58)
Preference _deckCardsSeen changed from Ancestral Recall|Island to Ancestral Recall|Island|1952 Mickey Mantle
Preference lastEncounter changed from Ancestral Recall to 1952 Mickey Mantle
Encounter: 1952 Mickey Mantle
Preference _deckCardsDrawn changed from 14 to 15
You acquire an item: 1952 Mickey Mantle cardphreddrickk
Member
Going into my session log, I see this before the crash:
I had to close mafia via the task manager, but doing so doesn't appear to have wiped or negatively impacted my preferences.
EDIT:
very weird thing happened as I logged back in:
That final line wasn't visible in the CLI during the crash, but does appear to have been written to the log.
I had to close mafia via the task manager, but doing so doesn't appear to have wiped or negatively impacted my preferences.
EDIT:
very weird thing happened as I logged back in:
Huh. I'd been away from my computer for a long time, so when I returned, it needed to time me in.
My aftercore script had finished a long time ago.
I was not have the Relay Browser open.
I was not in chat.
My session was completely idle.
I tried to initiate a search from Purchases.
It cleared the search string and did nothing.
(I've seen this before if it had to time in. I've never tracked it down.)
I hit the "refresh" button at the bottom of the green side pane, which submits api.php, which forces a timein.
The CLI said "Issuing login request..." and then I got the spinning beach ball of death.
Completely unresponsive. I had to ^Z and kill %1 from my shell.
I'm running r27522 - the revision that synchronizes the preference files, including on timein.
I bet it's failing to get a lock.
Worse, it appears that it's the Swing event task which is hung, thereby hanging the entire GUI.
My aftercore script had finished a long time ago.
I was not have the Relay Browser open.
I was not in chat.
My session was completely idle.
I tried to initiate a search from Purchases.
It cleared the search string and did nothing.
(I've seen this before if it had to time in. I've never tracked it down.)
I hit the "refresh" button at the bottom of the green side pane, which submits api.php, which forces a timein.
The CLI said "Issuing login request..." and then I got the spinning beach ball of death.
Completely unresponsive. I had to ^Z and kill %1 from my shell.
I'm running r27522 - the revision that synchronizes the preference files, including on timein.
I bet it's failing to get a lock.
Worse, it appears that it's the Swing event task which is hung, thereby hanging the entire GUI.
phreddrickk
Member
Just hit this as well. Can confirm that it looks like the same core issue as the Mickey Mantle card
It would be useful to know whether anyone who has seen the lockup has had saveSettingsOnSet=false ?
You might consider flipping it to false if it is currently true. That might make the Deck and similar locks less frequent.
Not sure what is going on with timein.
You might consider flipping it to false if it is currently true. That might make the Deck and similar locks less frequent.
Not sure what is going on with timein.
That's been a hard one to build good tests for. We worked mostly with Preference.increment(), because it exercised read and write and depended on the before-state.
But perhaps we need to move on from synchronized() to tryLock() , or better ReadLock()/WriteLock(). (or other lock methods if someone has a favorite).
Do we need to revert while we look at this? I thought all the errors we were seeing were test artifacts, but this seems to be failing for actual play.
But perhaps we need to move on from synchronized() to tryLock() , or better ReadLock()/WriteLock(). (or other lock methods if someone has a favorite).
Do we need to revert while we look at this? I thought all the errors we were seeing were test artifacts, but this seems to be failing for actual play.
My personal inclination is to let this percolate for maybe a day and see if we can gather more info.
My biggest concern is the timein but that might be easier to isolate or write a failing test.
My biggest concern is the timein but that might be easier to isolate or write a failing test.
I'll defer but the truth is this had passed enough non-automated testing that I don't know what to ask with out more failure reports.
reverkiller
Member
Just wanted to chime in to say I was having very similar issues - both the crashing on 1952 and something very similar to what veracity saw (mafia hanging entirely when I log in after an idle session)
Well. The usual questions I ask are more pedagogical to figure out what's going on.
Java synchronized sections should be reentrant, namely that if a single thread can acquire the same lock multiple times in a call stack.
For anyone who reproduced this: was Mafia pegging a full CPU core? That would suggest a livelock (e.g. busy loop) as opposed to a deadlock, although I'm inclined to suspect the latter. One of the threads we're tying up is the Swing event dispatch thread.
Java synchronized sections should be reentrant, namely that if a single thread can acquire the same lock multiple times in a call stack.
For anyone who reproduced this: was Mafia pegging a full CPU core? That would suggest a livelock (e.g. busy loop) as opposed to a deadlock, although I'm inclined to suspect the latter. One of the threads we're tying up is the Swing event dispatch thread.
One of the threads is most likely the timein. In Veracity's case, that sounds like it was blocking the Swing event dispatch thread (since it was triggered by clicking on a UI element).
ApiRequest.updateStatus(boolean) is a synchronized function. This calls ApiRequest.run(), which delegates to GenericRequest.run(), which may call LoginManager.executeTimeInRequest().
Pondering. It may be something as simple as "we grab a lock, and then Preferences.reset() dispatches some background request and waits for it to complete, which it can't because it can't grab the same lock by virtue of being a different thread."
ApiRequest.updateStatus(boolean) is a synchronized function. This calls ApiRequest.run(), which delegates to GenericRequest.run(), which may call LoginManager.executeTimeInRequest().
Pondering. It may be something as simple as "we grab a lock, and then Preferences.reset() dispatches some background request and waits for it to complete, which it can't because it can't grab the same lock by virtue of being a different thread."
One instance of deadlock potential:
resetDailies (holding userValues) calls Preferences.setString, which eventually dispatches to setObject.
If saveSettingsOnSet is true, this calls maybeSaveToFileAfterUpdating() which in turn calls saveToFile, which grabs lock.
Meanwhile, reset() will grab lock before grabbing userValues (both in its own body as well as in reinitializeEncodedValues()).
(A classic deadlock looks like: thread A grabs mutex A, waits on mutex B; meanwhile, thread B grabs mutex B, waits on mutex A. Since both threads are waiting for a mutex held by the other one, neither can make progress.)
We have a similar failure mode for resetGlobalDailies.
I haven't yet figured out the mechanism that would trigger these deadlocks, so it might be something else.
resetDailies (holding userValues) calls Preferences.setString, which eventually dispatches to setObject.
If saveSettingsOnSet is true, this calls maybeSaveToFileAfterUpdating() which in turn calls saveToFile, which grabs lock.
Meanwhile, reset() will grab lock before grabbing userValues (both in its own body as well as in reinitializeEncodedValues()).
(A classic deadlock looks like: thread A grabs mutex A, waits on mutex B; meanwhile, thread B grabs mutex B, waits on mutex A. Since both threads are waiting for a mutex held by the other one, neither can make progress.)
We have a similar failure mode for resetGlobalDailies.
I haven't yet figured out the mechanism that would trigger these deadlocks, so it might be something else.
This should be reverted as of r27526. Sorry for the breakage.
@fronobulax I've started tinkering in https://github.com/kolmafia/kolmafia/pull/1889 if you want to play around there.
@fronobulax I've started tinkering in https://github.com/kolmafia/kolmafia/pull/1889 if you want to play around there.
I've stared at the code some more, and I think this could only be problematic when timing in across rollover. That's not relevant here (even if it is a real bug, which I'm still not convinced of).
I don't see anything special about cheating for the Mickey Mantle card (in the code or otherwise). It does seem notable that it's the third card in Veracity's and phreddrickk's logs. But even that doesn't have special handling unless the issue is that string concatenation is slowing things down enough to trigger the race...?
My hypothesis was that it was not the card but just a card. DailyDeeds has a listener that fired when a preference changed. The listener checked a preference. I was going to go down that rabbit hole to confirm that my casual inspection was correct and then see if that set up a deadlock.