Bug - Fixed r17214 debug log when breaking the prism

Magus_Prime · Sep 20, 2016

Code:

[878] Freeing King Ralph
Retrieving character data...
Updating display case...
Retrieving familiar data...
Requests complete.

Familiar data retrieved.
Unexpected error, debug log printed.

Here's the log: View attachment DEBUG_20160920.txt

Darzil · Sep 20, 2016

From which path ?

lostcalpolydude · Sep 20, 2016

I got a similar debug log when freeing the king at the end of Nuclear Autumn.

Code:

Unexpected error, debug log printed.
class java.util.ConcurrentModificationException: null
java.util.ConcurrentModificationException
	at java.util.HashMap$HashIterator.nextNode(HashMap.java:1429)
	at java.util.HashMap$KeyIterator.next(HashMap.java:1453)
	at net.sourceforge.kolmafia.listener.ListenerRegistry.deferListeners(ListenerRegistry.java:99)
	at net.sourceforge.kolmafia.listener.PreferenceListenerRegistry.deferPreferenceListeners(PreferenceListenerRegistry.java:44)
	at net.sourceforge.kolmafia.request.GenericRequest.retrieveServerReply(GenericRequest.java:2392)
	at net.sourceforge.kolmafia.request.GenericRequest.retrieveServerReply(GenericRequest.java:1998)
	at net.sourceforge.kolmafia.request.GenericRequest.externalExecute(GenericRequest.java:1565)
	at net.sourceforge.kolmafia.request.GenericRequest.execute(GenericRequest.java:1548)
	at net.sourceforge.kolmafia.request.GenericRequest.run(GenericRequest.java:1310)
	at net.sourceforge.kolmafia.request.RelayRequest.run(RelayRequest.java:3073)
	at net.sourceforge.kolmafia.RequestThread.postRequest(RequestThread.java:286)
	at net.sourceforge.kolmafia.RequestThread.postRequest(RequestThread.java:249)
	at net.sourceforge.kolmafia.webui.RelayAgent.readServerResponse(RelayAgent.java:567)
	at net.sourceforge.kolmafia.webui.RelayAgent.performRelay(RelayAgent.java:161)
	at net.sourceforge.kolmafia.webui.RelayAgent.run(RelayAgent.java:134)

Magus_Prime · Sep 20, 2016

Sorry. Nuclear Autumn.

heeheehee · Sep 20, 2016

Interesting. Isn't that already inside a synchronized block?

heeheehee · Sep 20, 2016

Hm, I see. HashMap.iterator() requires that the keyset for the HashMap be unchanged throughout the iteration, since rebalancing could mean that all the elements move. The synchronized block doesn't affect that in particular.

edit: I think we moved to Java 7, which has https://docs.oracle.com/javase/7/docs/api/java/util/concurrent/ConcurrentHashMap.html

fronobulax · Sep 20, 2016

heeheehee said:
edit: I think we moved to Java 7, which has https://docs.oracle.com/javase/7/docs/api/java/util/concurrent/ConcurrentHashMap.html

We did?

On the debug log, I have one too, probably from a NA ascension. However since the hp and mp thresholds now have a listener attached to the GUI panel, I have been looking at this and seeing if there is any way my adding of the listeners was the source of the problem. No resolution but that just means it does not happen ascending after Ed runs.

heeheehee · Sep 20, 2016

fronobulax said:
We did?

Thought we did. Quick search for posts about "Java 7" by Veracity turned up this thread, which at least indicates that Java 7 is needed to compile as of 2 years ago.

Either way, ConcurrentHashMap was present in Java 6, although Oracle's taken down those docs by now*.

* edit: maybe not explicitly, but they've added a line to their robots.txt disallowing web crawlers...

edit 2: http://kolmafia.us/showthread.php?16087 as well.

lostcalpolydude · Sep 21, 2016

I'm pretty sure the current requirement to run mafia is Java 5.

heeheehee · Sep 21, 2016

lostcalpolydude said:
I'm pretty sure the current requirement to run mafia is Java 5.

That sure seems to be the case, although I'm not particularly inclined to download a Java 5 runtime for the purposes of testing. Same URL manipulation indicates that Java 5 also had ConcurrentHashMap, and Oracle's Java 5 docs are probably also disallowed by their robots.txt.

fronobulax · Sep 21, 2016

Users need only have 1.5. Code builders must have 1.7. The build process must produce a 1.5 compatible jar file. I have been environments where the build process did not produce the compatible jar and as a result, Bad Things Happened in customer land. Being risk adverse, my solution is to keep source compatibility at 1.5. In practice that is probably pretty stupid because my environment is now 1.8 and I am not responsible for customer builds. If I do something that breaks them we will all know soon enough.

heeheehee · Sep 21, 2016

fronobulax said:
Users need only have 1.5. Code builders must have 1.7. The build process must produce a 1.5 compatible jar file. I have been environments where the build process did not produce the compatible jar and as a result, Bad Things Happened in customer land. Being risk adverse, my solution is to keep source compatibility at 1.5. In practice that is probably pretty stupid because my environment is now 1.8 and I am not responsible for customer builds. If I do something that breaks them we will all know soon enough.

In looking into backward compatibility, I noticed that there are two different types (which makes sense, for a compiled language): source and binary. We obviously haven't been 1.5-source-compliant in years (based on the inability to compile with anything lower than Java 7), but as far as I'm aware, we're still binary compatible.

Theraze · Sep 21, 2016

FYI, broke the prism today with r17216 as SC NA and no debug log. So might be a HC NA issue as new restores come available. Or not.

lostcalpolydude · Sep 21, 2016

Theraze said:
FYI, broke the prism today with r17216 as SC NA and no debug log. So might be a HC NA issue as new restores come available. Or not.

I got it at the end of a SC run.

Veracity · Sep 21, 2016

heeheehee said:
In looking into backward compatibility, I noticed that there are two different types (which makes sense, for a compiled language): source and binary. We obviously haven't been 1.5-source-compliant in years (based on the inability to compile with anything lower than Java 7), but as far as I'm aware, we're still binary compatible.

Well.... build.xml says this:

Code:

		<javac
			compiler="modern"
			source="1.5"
			target="1.5"
			srcdir="${lib}"
			destdir="${build}"
			failonerror="false"
			debug="on"
			debuglevel="lines,vars,source"
			deprecation="off"
			nowarn="on"
			includeantruntime="false"
			errorProperty="compile.failed">
			<classpath>
				<pathelement path="${classpath}"/>
				<fileset dir="${lib}/jar">
					<include name="**/*.jar"/>
				</fileset>
			</classpath>
		</javac>

Looks like we are declaring 1.5 source compatibility.

holatuwol also periodically comes in and makes backward compatibility submits. For example:

Code:

r15267 | shwei | 2015-01-24 00:07:37 -0500 (Sat, 24 Jan 2015) | 1 line

Fix compilation error in Java 5, where AbstractMap.SimpleEntry is not public API.

r15173 | shwei | 2015-01-12 00:33:54 -0500 (Mon, 12 Jan 2015) | 1 line

Since the build.xml declares Java 5 compatibility at the source level, ensure that LockableListModel still compiles under JDK5.

He also likes to keep the author list up-to-date:

Code:

r16336 | shwei | 2015-09-29 14:53:45 -0400 (Tue, 29 Sep 2015) | 1 line

Add heeheehee to authors.txt

r13549 | shwei | 2014-01-21 13:19:16 -0500 (Tue, 21 Jan 2014) | 1 line

Add Darzil to authors.txt to resolve git-svn fetch errors

He's never really let go of his baby.

Ensiferum · Sep 22, 2016

Theraze said:
FYI, broke the prism today with r17216 as SC NA and no debug log. So might be a HC NA issue as new restores come available. Or not.

I've done 8 SC NA runs and have 8 debug logs in the mafia folder, with the single difference being the timestamp and the mafia build. Latest one was just now with r17216. Java - 1.6.0_26.

Veracity · Sep 22, 2016

The exception is thrown while we are iterating over the "deferred" list of the PreferenceListenerRegistry and firing all the listeners on it. Presumably it happens because that list is changed during the iteration. This puzzles me; we only add to that list when we are deferring listeners, but we are firing the listeners because they are no longer deferred.

I'll free the king in my current NA run in a few days. Probably three. But somebody who gets there sooner could try this:

Just before you free the king in the Relay Browser, go to the gCLI.

debug on
debug listener on

free the king

debug listener off
debug off

And lets see what the DEBUG log says.

Huh. I should improve that logging so that it shows when we add a listener to deferred.

Or, perhaps, detect when we add to that list while we are iterating over it and force a stack trace, since that would seem to be the issue.

Stay tuned.

Veracity · Sep 22, 2016

Ha ha ha. During normal adventuring in the Relay Browser:

Code:

Deferring listeners while firing deferred listeners
class java.lang.Exception: Deferring listeners while firing deferred listeners
java.lang.Exception: Deferring listeners while firing deferred listeners
	at net.sourceforge.kolmafia.StaticEntity.printStackTrace(StaticEntity.java:387)
	at net.sourceforge.kolmafia.listener.ListenerRegistry.fireListener(ListenerRegistry.java:171)
	at net.sourceforge.kolmafia.listener.PreferenceListenerRegistry.firePreferenceChanged(PreferenceListenerRegistry.java:54)
	at net.sourceforge.kolmafia.KoLCharacter.updateStatus(KoLCharacter.java:5399)
	at net.sourceforge.kolmafia.KoLCharacter.setHP(KoLCharacter.java:1718)
	at net.sourceforge.kolmafia.request.CharPaneRequest.handleMiscPoints(CharPaneRequest.java:622)
	at net.sourceforge.kolmafia.request.CharPaneRequest.handleExpandedMode(CharPaneRequest.java:463)
	at net.sourceforge.kolmafia.request.CharPaneRequest.processResults(CharPaneRequest.java:263)
	at net.sourceforge.kolmafia.request.GenericRequest.processResponse(GenericRequest.java:2426)
	at net.sourceforge.kolmafia.request.GenericRequest.retrieveServerReply(GenericRequest.java:2384)
	at net.sourceforge.kolmafia.request.GenericRequest.retrieveServerReply(GenericRequest.java:1998)
	at net.sourceforge.kolmafia.request.GenericRequest.externalExecute(GenericRequest.java:1565)
	at net.sourceforge.kolmafia.request.GenericRequest.execute(GenericRequest.java:1548)
	at net.sourceforge.kolmafia.request.GenericRequest.run(GenericRequest.java:1310)
	at net.sourceforge.kolmafia.request.RelayRequest.run(RelayRequest.java:3073)
	at net.sourceforge.kolmafia.RequestThread.postRequest(RequestThread.java:286)
	at net.sourceforge.kolmafia.RequestThread.postRequest(RequestThread.java:249)
	at net.sourceforge.kolmafia.webui.RelayAgent.readServerResponse(RelayAgent.java:567)
	at net.sourceforge.kolmafia.webui.RelayAgent.performRelay(RelayAgent.java:161)
	at net.sourceforge.kolmafia.webui.RelayAgent.run(RelayAgent.java:134)

and

Code:

Deferring listeners while firing deferred listeners
class java.lang.Exception: Deferring listeners while firing deferred listeners
java.lang.Exception: Deferring listeners while firing deferred listeners
	at net.sourceforge.kolmafia.StaticEntity.printStackTrace(StaticEntity.java:387)
	at net.sourceforge.kolmafia.listener.ListenerRegistry.fireListener(ListenerRegistry.java:171)
	at net.sourceforge.kolmafia.listener.PreferenceListenerRegistry.firePreferenceChanged(PreferenceListenerRegistry.java:54)
	at net.sourceforge.kolmafia.KoLCharacter.updateStatus(KoLCharacter.java:5399)
	at net.sourceforge.kolmafia.KoLCharacter.setMP(KoLCharacter.java:1768)
	at net.sourceforge.kolmafia.request.CharPaneRequest.handleMiscPoints(CharPaneRequest.java:641)
	at net.sourceforge.kolmafia.request.CharPaneRequest.handleExpandedMode(CharPaneRequest.java:463)
	at net.sourceforge.kolmafia.request.CharPaneRequest.processResults(CharPaneRequest.java:263)
	at net.sourceforge.kolmafia.request.GenericRequest.processResponse(GenericRequest.java:2426)
	at net.sourceforge.kolmafia.request.GenericRequest.retrieveServerReply(GenericRequest.java:2384)
	at net.sourceforge.kolmafia.request.GenericRequest.retrieveServerReply(GenericRequest.java:1998)
	at net.sourceforge.kolmafia.request.GenericRequest.externalExecute(GenericRequest.java:1565)
	at net.sourceforge.kolmafia.request.GenericRequest.execute(GenericRequest.java:1548)
	at net.sourceforge.kolmafia.request.GenericRequest.run(GenericRequest.java:1310)
	at net.sourceforge.kolmafia.request.RelayRequest.run(RelayRequest.java:3073)
	at net.sourceforge.kolmafia.RequestThread.postRequest(RequestThread.java:286)
	at net.sourceforge.kolmafia.RequestThread.postRequest(RequestThread.java:249)
	at net.sourceforge.kolmafia.webui.RelayAgent.readServerResponse(RelayAgent.java:567)
	at net.sourceforge.kolmafia.webui.RelayAgent.performRelay(RelayAgent.java:161)
	at net.sourceforge.kolmafia.webui.RelayAgent.run(RelayAgent.java:134)

and

Code:

Deferring listeners while firing deferred listeners
class java.lang.Exception: Deferring listeners while firing deferred listeners
java.lang.Exception: Deferring listeners while firing deferred listeners
	at net.sourceforge.kolmafia.StaticEntity.printStackTrace(StaticEntity.java:387)
	at net.sourceforge.kolmafia.listener.ListenerRegistry.fireListener(ListenerRegistry.java:171)
	at net.sourceforge.kolmafia.listener.PreferenceListenerRegistry.firePreferenceChanged(PreferenceListenerRegistry.java:54)
	at net.sourceforge.kolmafia.KoLCharacter.updateStatus(KoLCharacter.java:5399)
	at net.sourceforge.kolmafia.request.CharPaneRequest.processResults(CharPaneRequest.java:266)
	at net.sourceforge.kolmafia.request.GenericRequest.processResponse(GenericRequest.java:2426)
	at net.sourceforge.kolmafia.request.GenericRequest.retrieveServerReply(GenericRequest.java:2384)
	at net.sourceforge.kolmafia.request.GenericRequest.retrieveServerReply(GenericRequest.java:1998)
	at net.sourceforge.kolmafia.request.GenericRequest.externalExecute(GenericRequest.java:1565)
	at net.sourceforge.kolmafia.request.GenericRequest.execute(GenericRequest.java:1548)
	at net.sourceforge.kolmafia.request.GenericRequest.run(GenericRequest.java:1310)
	at net.sourceforge.kolmafia.request.RelayRequest.run(RelayRequest.java:3073)
	at net.sourceforge.kolmafia.RequestThread.postRequest(RequestThread.java:286)
	at net.sourceforge.kolmafia.RequestThread.postRequest(RequestThread.java:249)
	at net.sourceforge.kolmafia.webui.RelayAgent.readServerResponse(RelayAgent.java:567)
	at net.sourceforge.kolmafia.webui.RelayAgent.performRelay(RelayAgent.java:161)
	at net.sourceforge.kolmafia.webui.RelayAgent.run(RelayAgent.java:134)

The Relay Browser handles each request in a new thread.

We submit a request which triggers a charpane refresh.
We fire deferred listeners while processing the response.
Meanwhile, the browser asks for charpane.php
We get the response and GenericRequest defers listeners before processing the response
CharPaneRequest wants to fire listeners, so they get deferred.

Seems like we should simply synchronize on the deferred list when adding to it, in addition to when we iterate over it.

Veracity · Sep 22, 2016

And sourceforge is not letting me complete the commit. Later.

Veracity · Sep 22, 2016

Revision 17218

Bug - Fixed r17214 debug log when breaking the prism

Well-known member

Developer

Developer

Well-known member

Developer

Developer

Developer

Developer

Developer

Developer

Developer

Developer

Active member

Developer

Developer

Member

Developer

Developer

Developer

Developer