Bug - Waiting for Info 1952 Mickey mantle pick in Deck of Every Card crash

Code: 
=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=
              KoLmafia r27526-M, Linux, Java 17.0.8
=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=
 Please note: do not post this log in the KoLmafia thread of KoL's
 Gameplay-Discussion forum. If you would like the KoLmafia dev team
 to look at it, please write a bug report at kolmafia.us. Include
 specific information about what you were doing when you made this
 and include this log as an attachment.
=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=
 Timestamp: Tue Aug 08 19:34:09 EDT 2023
=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=
 User: heeheehee
 Current run: 1126572
 MRU Script: Unknown
=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=


Thread blocked waiting for java.lang.Object@36eb594f owned by CommandQueueHandler:
"AWT-EventQueue-0" prio=6 Id=26 BLOCKED on java.lang.Object@36eb594f owned by "CommandQueueHandler" Id=145
    at app//net.sourceforge.kolmafia.preferences.Preferences.getObject(Preferences.java:1180)
    -  blocked on java.lang.Object@36eb594f
    at app//net.sourceforge.kolmafia.preferences.Preferences.getBoolean(Preferences.java:1092)
    at app//net.sourceforge.kolmafia.preferences.Preferences.getBoolean(Preferences.java:989)
    at app//net.sourceforge.kolmafia.swingui.widget.RequestPane$WrappedHtmlEditorKit$WrappedHtmlFactory$WrapInlineView.getMinimumSpan(RequestPane.java:83)
    at java.desktop@17.0.8/javax.swing.text.ParagraphView.calculateMinorAxisRequirements(ParagraphView.java:717)
    at java.desktop@17.0.8/javax.swing.text.html.ParagraphView.calculateMinorAxisRequirements(ParagraphView.java:162)
    at java.desktop@17.0.8/javax.swing.text.BoxView.checkRequests(BoxView.java:936)
    at java.desktop@17.0.8/javax.swing.text.BoxView.getMinimumSpan(BoxView.java:569)
    ...



Thread blocked waiting for java.awt.Component$AWTTreeLock@26e5ac86 owned by AWT-EventQueue-0:
"CommandQueueHandler" prio=5 Id=145 BLOCKED on java.awt.Component$AWTTreeLock@26e5ac86 owned by "AWT-EventQueue-0" Id=26
    at java.desktop@17.0.8/java.awt.Component.setFont(Component.java:1944)
    -  blocked on java.awt.Component$AWTTreeLock@26e5ac86
    at java.desktop@17.0.8/java.awt.Container.setFont(Container.java:1780)
    at java.desktop@17.0.8/javax.swing.JComponent.setFont(JComponent.java:2814)
    at app//net.sourceforge.kolmafia.swingui.widget.DisabledItemsComboBox$DisabledItemsRenderer.getListCellRendererComponent(DisabledItemsComboBox.java:142)
    at java.desktop@17.0.8/javax.swing.plaf.basic.BasicListUI.updateLayoutState(BasicListUI.java:1444)
    at java.desktop@17.0.8/javax.swing.plaf.basic.BasicListUI.maybeUpdateLayoutState(BasicListUI.java:1394)
    at java.desktop@17.0.8/javax.swing.plaf.basic.BasicListUI$Handler.valueChanged(BasicListUI.java:2815)
    at java.desktop@17.0.8/javax.swing.DefaultListSelectionModel.fireValueChanged(DefaultListSelectionModel.java:224)
    ...
 
This was triggered simply by executing `timein` in the CLI. It silently prints a debug log, but it can't really notify the user about that because the GUI is stalled.
 
This reproduces even with saveSettingsOnSet set to false. It looks like we're doing UI processing off the Swing Event dispatch thread (CommandQueueHandler is updating models...) which is causing a deadlock between Swing UI updates and preference reads.

I made an edit that prints out the remainder of the stack trace. It turns out this failure mode is induced by AdventureFrame.updateFromPreferences(); within Preferences.reset().

Any reason why we need to hold Preferences.lock for all those other updates?
 
Okay. It turns out even if we move that out of the lock, we still run into issues, since LoginManager.timein() grabs the lock up the stack. I suppose I can make AdventureFrame.updateFromPreferences schedule on the event thread...
 
I got timein to succeed locally, although I'm still tweaking the code. I suspect that in general, we need to trigger listener updates on the Swing event dispatch thread, to avoid Swing synchronization from causing deadlocks with preference reads.
 
would it help to move from Synchronized to java.util.concurrent.locks.ReadWriteLock? They'd still be locked against writes, but they'd allow multiple reads.
 
I think this particular failure mode would, since I don't think any of these listeners are setting properties.
 
Does it make the problem more interesting that I encounter lockups without the Deck of Every Card? Recently I've had Garbo runs freeze once or twice, and my only way forward is to kill Mafia (I run Fedora 38) and restart it. I'm away from my laptop right now, but is there something I should try on my next run?
 
What version of KoLmafia are you using? The code which caused the freezeup was rolled back in r27536.
If you are experiencing freezes with that version or later, then, yes, it'd be "more interesting".
If you are not running that version or later, you should try upgrading.
 
Over a decade ago Hola shared the following things to do when KoLmafia seemed to hang or freeze. The last time I tried them they did what was expected for me. But I have a Java Development Environment from Oracle as opposed to a Java Runtime Environment, perhaps from another source so this might not work. For the record I am using a version with the "fix" that broke things and I have not seen any freezes which is somewhat frustrating.

Hola said:
The next time KoLmafia gets stuck on exit:

Code:

jps -l

Use that to figure out what the process id is for KoLmafia.

Code:

jstack {pid}

Use that to get a stack trace dumped to the console. I get the feeling there's some kind of weird locking going on still in the event dispatch thread, but it only occurs if certain conditions are met, and they don't get met by me logging on to do a bounty. =\
Click to expand...
 
Veracity said:
What version of KoLmafia are you using? The code which caused the freezeup was rolled back in r27536.
If you are experiencing freezes with that version or later, then, yes, it'd be "more interesting".
If you are not running that version or later, you should try upgrading.
Click to expand...

r2753...6? The most recent version I see right now is r27533.

1691970740903.png
 
27526, okay. I'm always using the latest. The last time this happened was 27533. I'll take Fronobulax's advice and see what info I can get from jstack if it happens again. Thanks!
 
You are literally the first and only person to report this since we rolled back the release that caused the initial report. I’ll be interested to see your followup.
 
Probably the only person running Fedora too (Java version: Build HEAD-d1ec422 17.0.7 (Eclipse Adoptium 17.0.7+7) Linux amd64 5.15.0-78-generic). Anyway, I've attached a jstack dump from when the freeze happened just now. What can y'all make of it?
 

Attachments

This looks very different from the deadlocks we were seeing. The only notable thread that I saw:

Code: 
"CommandQueueHandler" #138 prio=5 os_prio=0 cpu=196539.00ms elapsed=3659.80s tid=0x00007fbc5c499870 nid=0x28d2 waiting on condition  [0x00007fbb6abfc000]
   java.lang.Thread.State: WAITING (parking)
    at jdk.internal.misc.Unsafe.park(java.base@17.0.7/Native Method)
    - parking to wait for  <0x000000075f422c58> (a java.util.concurrent.CompletableFuture$Signaller)
    at java.util.concurrent.locks.LockSupport.park(java.base@17.0.7/LockSupport.java:211)
    at java.util.concurrent.CompletableFuture$Signaller.block(java.base@17.0.7/CompletableFuture.java:1864)
    at java.util.concurrent.ForkJoinPool.unmanagedBlock(java.base@17.0.7/ForkJoinPool.java:3463)
    at java.util.concurrent.ForkJoinPool.managedBlock(java.base@17.0.7/ForkJoinPool.java:3434)
    at java.util.concurrent.CompletableFuture.waitingGet(java.base@17.0.7/CompletableFuture.java:1898)
    at java.util.concurrent.CompletableFuture.get(java.base@17.0.7/CompletableFuture.java:2072)
    at jdk.internal.net.http.HttpClientImpl.send(java.net.http@17.0.7/HttpClientImpl.java:553)
    at jdk.internal.net.http.HttpClientFacade.send(java.net.http@17.0.7/HttpClientFacade.java:123)
    at net.sourceforge.kolmafia.utilities.ResettingHttpClient.send(ResettingHttpClient.java:34)
    at net.sourceforge.kolmafia.request.GenericRequest.sendRequest(GenericRequest.java:1581)
    at net.sourceforge.kolmafia.request.GenericRequest.externalExecute(GenericRequest.java:1400)
    at net.sourceforge.kolmafia.request.GenericRequest.execute(GenericRequest.java:1388)
    at net.sourceforge.kolmafia.request.GenericRequest.run(GenericRequest.java:1155)
    at net.sourceforge.kolmafia.request.ApiRequest.run(ApiRequest.java:157)
    at net.sourceforge.kolmafia.request.ApiRequest.updateStatus(ApiRequest.java:90)
    - locked <0x0000000749cfc2e0> (a java.lang.Class for net.sourceforge.kolmafia.request.ApiRequest)
    at net.sourceforge.kolmafia.request.GenericRequest.processResponse(GenericRequest.java:2261)
    at net.sourceforge.kolmafia.request.GenericRequest.retrieveServerReply(GenericRequest.java:2141)
    at net.sourceforge.kolmafia.request.GenericRequest.retrieveServerReply(GenericRequest.java:1734)
    at net.sourceforge.kolmafia.request.GenericRequest.externalExecute(GenericRequest.java:1401)
    at net.sourceforge.kolmafia.request.GenericRequest.execute(GenericRequest.java:1388)
    at net.sourceforge.kolmafia.request.GenericRequest.run(GenericRequest.java:1155)
    at net.sourceforge.kolmafia.request.FightRequest.run(FightRequest.java:1732)
    - locked <0x000000074c456498> (a net.sourceforge.kolmafia.request.FightRequest)
    at net.sourceforge.kolmafia.request.GenericRequest.handleServerRedirect(GenericRequest.java:2029)
    at net.sourceforge.kolmafia.request.GenericRequest.retrieveServerReply(GenericRequest.java:1763)
    at net.sourceforge.kolmafia.request.GenericRequest.externalExecute(GenericRequest.java:1401)
    at net.sourceforge.kolmafia.request.GenericRequest.execute(GenericRequest.java:1388)
    at net.sourceforge.kolmafia.request.GenericRequest.run(GenericRequest.java:1155)
    at net.sourceforge.kolmafia.request.AdventureRequest.run(AdventureRequest.java:339)
    at net.sourceforge.kolmafia.RequestThread.postRequest(RequestThread.java:242)
    at net.sourceforge.kolmafia.RequestThread.postRequest(RequestThread.java:207)
    at net.sourceforge.kolmafia.KoLAdventure.run(KoLAdventure.java:3251)
    at net.sourceforge.kolmafia.RequestThread.postRequest(RequestThread.java:242)
    at net.sourceforge.kolmafia.RequestThread.postRequest(RequestThread.java:222)
    at net.sourceforge.kolmafia.KoLmafia.executeAdventureOnce(KoLmafia.java:1423)
    at net.sourceforge.kolmafia.KoLmafia.executeRequestOnce(KoLmafia.java:1358)
    at net.sourceforge.kolmafia.KoLmafia.executeRequest(KoLmafia.java:1299)
    at net.sourceforge.kolmafia.KoLmafia.makeRequest(KoLmafia.java:1239)
    at net.sourceforge.kolmafia.textui.RuntimeLibrary.adv1(RuntimeLibrary.java:4159)
    at jdk.internal.reflect.GeneratedMethodAccessor339.invoke(Unknown Source)
    at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(java.base@17.0.7/DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(java.base@17.0.7/Method.java:568)
    at net.sourceforge.kolmafia.textui.parsetree.LibraryFunction.executeWithoutInterpreter(LibraryFunction.java:108)
...

It's interesting how many redirects there are, but I'm not seeing anything obviously wrong either way. Looks to me like the Java standard library's HttpClient isn't completing its request for some reason.
 
So there's a chance it has something to do with my environment? Hm. Well, it happened again yesterday and twice today. Let's see what happens now that I've upgraded from java-17-openjdk-17.0.7 to -17.0.8.
 
You must log in or register to reply here.
Back
Top