Bug null string in net.sourceforge.kolmafia.persistence.DebugDatabase.parseStandardEnchantments (r26114)

Y

Your.Master

New member
I just got back from one month of travelling and kolmafia no longer works on my home machine. It does still work on the machine I took on vacation, which makes me think maybe some sort of migration occurred only on that device. Both the working machine and the not working machine have the same version. I actually tried to copy paste the exact same kolmafia directory into the same named directory structure and ensuring I was launching from the same method and directory, and that copy still failed the same way, so whatever the difference is appears to be outside of kolmafia's own config data somehow (or else kolmafia is keeping some config in an unexpected directory / registry location). But I don't know what could be causing such a problem.

The debug log on load is pasted below. From reading the github code, I think a null description is coming out of net.sourceforge.kolmafia.persistence.readEffectDescriptionText, but I don't have a Java dev environment to dive further into which descid is the problem (or if it's just the first), and I don't know.


Error during session initialization
class java.lang.NullPointerException: Cannot invoke "java.lang.CharSequence.length()" because "this.text" is null
java.lang.NullPointerException: Cannot invoke "java.lang.CharSequence.length()" because "this.text" is null
at java.base/java.util.regex.Matcher.getTextLength(Matcher.java:1769)
at java.base/java.util.regex.Matcher.reset(Matcher.java:415)
at java.base/java.util.regex.Matcher.<init>(Matcher.java:252)
at java.base/java.util.regex.Pattern.matcher(Pattern.java:1134)
at net.sourceforge.kolmafia.persistence.DebugDatabase.parseStandardEnchantments(DebugDatabase.java:1412)
at net.sourceforge.kolmafia.persistence.DebugDatabase.parseEffectEnchantments(DebugDatabase.java:1976)
at net.sourceforge.kolmafia.persistence.DebugDatabase.parseEffectEnchantments(DebugDatabase.java:1983)
at net.sourceforge.kolmafia.persistence.DebugDatabase.parseEffectEnchantments(DebugDatabase.java:1989)
at net.sourceforge.kolmafia.Modifiers.overrideEffectModifiers(Modifiers.java:1197)
at net.sourceforge.kolmafia.session.ResultProcessor.updateEntauntauned(ResultProcessor.java:324)
at net.sourceforge.kolmafia.KoLmafia.refreshSessionData(KoLmafia.java:825)
at net.sourceforge.kolmafia.KoLmafia.refreshSession(KoLmafia.java:656)
at net.sourceforge.kolmafia.session.LoginManager.initialize(LoginManager.java:196)
at net.sourceforge.kolmafia.session.LoginManager.doLogin(LoginManager.java:87)
at net.sourceforge.kolmafia.session.LoginManager.login(LoginManager.java:39)
at net.sourceforge.kolmafia.request.LoginRequest.processLoginRequest(LoginRequest.java:326)
at net.sourceforge.kolmafia.request.GenericRequest.handleServerRedirect(GenericRequest.java:1870)
at net.sourceforge.kolmafia.request.GenericRequest.retrieveServerReply(GenericRequest.java:1772)
at net.sourceforge.kolmafia.request.GenericRequest.externalExecute(GenericRequest.java:1372)
at net.sourceforge.kolmafia.request.GenericRequest.execute(GenericRequest.java:1359)
at net.sourceforge.kolmafia.request.GenericRequest.run(GenericRequest.java:1114)
at net.sourceforge.kolmafia.request.LoginRequest.run(LoginRequest.java:202)
at net.sourceforge.kolmafia.RequestThread.postRequest(RequestThread.java:241)
at net.sourceforge.kolmafia.RequestThread.postRequest(RequestThread.java:206)
at net.sourceforge.kolmafia.swingui.LoginFrame$LoginPanel.doLogin(LoginFrame.java:266)
at net.sourceforge.kolmafia.swingui.LoginFrame$LoginPanel.actionConfirmed(LoginFrame.java:230)
at net.sourceforge.kolmafia.swingui.panel.GenericPanel$ConfirmedListener.execute(GenericPanel.java:503)
at net.sourceforge.kolmafia.swingui.listener.ThreadedListener.run(ThreadedListener.java:162)
at net.sourceforge.kolmafia.RequestThread$SequencedRunnable.run(RequestThread.java:348)
at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
at java.base/java.lang.Thread.run(Thread.java:833)
Error during session initialization
 
fronobulax

fronobulax

Developer
Staff member
Do both machines have the same version of KoLmafia?

Does one system have overrides in data/ that the other doesnt?
 
Y

Your.Master

New member
Hi, thanks for responding so quickly, I lost Internet yesterday with the weather.

Yes, both machines are using the same version of kolmafia. I'm unfamiliar with overrides in data/, but since I cut and paste the entire directory into a fresh structure I don't think one can have overrides that the other didn't.

As for the version of Java, I believe I'm on Java 17.

C:\Users\Ens>java --version
openjdk 17 2021-09-14
OpenJDK Runtime Environment Temurin-17+35 (build 17+35)
OpenJDK 64-Bit Server VM Temurin-17+35 (build 17+35, mixed mode, sharing)
 
MCroft

MCroft

Developer
Staff member
I'm not sure what's going on either, but I can think of things to rule out...

Sounds like it launches, but is failing on login. Does it happen for a different character (e.g. an alt?). does it happen if you archive your settings and let mafia start fresh? You can restore them or use a diff program to merge your settings after this test.

Do you have a login script on one but not the other system?
 
Veracity

Veracity

Developer
Staff member
Code: 
at net.sourceforge.kolmafia.persistence.DebugDatabase.parseStandardEnchantments(DebugDatabase.java:1412)
at net.sourceforge.kolmafia.persistence.DebugDatabase.parseEffectEnchantments(DebugDatabase.java:1976)
at net.sourceforge.kolmafia.persistence.DebugDatabase.parseEffectEnchantments(DebugDatabase.java:1983)
at net.sourceforge.kolmafia.persistence.DebugDatabase.parseEffectEnchantments(DebugDatabase.java:1989)
at net.sourceforge.kolmafia.Modifiers.overrideEffectModifiers(Modifiers.java:1197)
at net.sourceforge.kolmafia.session.ResultProcessor.updateEntauntauned(ResultProcessor.java:324)
It is looking at the description text of the "Entauntauned" effect to see how much cold resistance it currently has.

Apparently, it is getting a null, rather than a string, for the description text.

Code: 
  public static final String readEffectDescriptionText(final String descId) {
    DebugDatabase.DESC_EFFECT_REQUEST.clearDataFields();
    DebugDatabase.DESC_EFFECT_REQUEST.addFormField("whicheffect", descId);
    RequestThread.postRequest(DebugDatabase.DESC_EFFECT_REQUEST);
    return DebugDatabase.DESC_EFFECT_REQUEST.responseText;
  }

Using a global static like that is not thread safe. I wonder if, somehow, it's looking up multiple effects when you are logging in? I believe we used to do that for reading item description text but fixed it when we ran into problems. I'm not seeing how that can happen, but I can eliminate the global statics...

Edit: I have a PR in which fixes that for effects (and skills and outfits).
 
Y

Your.Master

New member
Veracity: Updated to 26125 but it still gives the same error, unfortunately.

MCroft: it is happening whether or not there is login script. I will try to create an alt later.
 
fronobulax

fronobulax

Developer
Staff member
mafia emits some messages during startup that often indicate an unusual condition. They are not captured anywhere. Launching mafia from a command prompt or console may allow the messages to be seen in the console's output. Worth a shot, IMO
 
Veracity

Veracity

Developer
Staff member
Also, start a debug log before you log in:

Run the jar file - from a console/terminal/command prompt (as suggested by frono)
When the Login window shows, open the Graphical CLI from the General menu
Type "debug on"
Dismiss the gCLI and attempt to log in.

Upload the DEBUG log (or, at least, the end of it that corresponds to your login attempt.)
 
Y

Your.Master

New member
I have it working now -- I can't tell what exactly fixed it, but I think I can give some clues.

What I did:

* Determined the same problem does reproduce when I use an alt. So it's not tied to my account.
* I attempted the steps Veracity gave.
* Before uploading the log, I examined it, and saw some network IO errors I hadn't seen before:

Code: 
IOException during data post (desc_effect.php?whicheffect=297ee9fadfb5560e5142e0b3a88456db): Address already in use: connect.
IOException during data post (desc_effect.php?whicheffect=297ee9fadfb5560e5142e0b3a88456db): Address already in use: connect.

And their position in the log makes perfect sense if the error is caught and converted to returning a null string. So I fiddled with some network troubleshooting and the error went away and I could log in again.

Code: 
IOException during data post (desc_effect.php?whicheffect=297ee9fadfb5560e5142e0b3a88456db): Address already in use: connect.
class java.net.BindException: Address already in use: connect
java.net.BindException: Address already in use: connect
    at java.base/sun.nio.ch.Net.connect0(Native Method)
    at java.base/sun.nio.ch.Net.connect(Net.java:579)
    at java.base/sun.nio.ch.Net.connect(Net.java:568)
    at java.base/sun.nio.ch.NioSocketImpl.connect(NioSocketImpl.java:588)
    at java.base/java.net.SocksSocketImpl.connect(SocksSocketImpl.java:327)
    at java.base/java.net.Socket.connect(Socket.java:633)
    at java.base/sun.security.ssl.SSLSocketImpl.connect(SSLSocketImpl.java:299)
    at java.base/sun.security.ssl.BaseSSLSocketImpl.connect(BaseSSLSocketImpl.java:174)
    at java.base/sun.net.NetworkClient.doConnect(NetworkClient.java:183)
    at java.base/sun.net.www.http.HttpClient.openServer(HttpClient.java:498)
    at java.base/sun.net.www.http.HttpClient.openServer(HttpClient.java:603)
    at java.base/sun.net.www.protocol.https.HttpsClient.<init>(HttpsClient.java:266)
    at java.base/sun.net.www.protocol.https.HttpsClient.New(HttpsClient.java:380)
    at java.base/sun.net.www.protocol.https.AbstractDelegateHttpsURLConnection.getNewHttpClient(AbstractDelegateHttpsURLConnection.java:189)
    at java.base/sun.net.www.protocol.http.HttpURLConnection.plainConnect0(HttpURLConnection.java:1242)
    at java.base/sun.net.www.protocol.http.HttpURLConnection.plainConnect(HttpURLConnection.java:1128)
    at java.base/sun.net.www.protocol.https.AbstractDelegateHttpsURLConnection.connect(AbstractDelegateHttpsURLConnection.java:175)
    at java.base/sun.net.www.protocol.http.HttpURLConnection.getOutputStream0(HttpURLConnection.java:1430)
    at java.base/sun.net.www.protocol.http.HttpURLConnection.getOutputStream(HttpURLConnection.java:1401)
    at java.base/sun.net.www.protocol.https.HttpsURLConnectionImpl.getOutputStream(HttpsURLConnectionImpl.java:220)
    at net.sourceforge.kolmafia.request.GenericRequest.postClientData(GenericRequest.java:1580)
    at net.sourceforge.kolmafia.request.GenericRequest.externalExecute(GenericRequest.java:1372)
    at net.sourceforge.kolmafia.request.GenericRequest.execute(GenericRequest.java:1360)
    at net.sourceforge.kolmafia.request.GenericRequest.run(GenericRequest.java:1115)
    at net.sourceforge.kolmafia.RequestThread.postRequest(RequestThread.java:244)
    at net.sourceforge.kolmafia.RequestThread.postRequest(RequestThread.java:209)
    at net.sourceforge.kolmafia.persistence.DebugDatabase.readEffectDescriptionText(DebugDatabase.java:1908)
    at net.sourceforge.kolmafia.Modifiers.overrideEffectModifiers(Modifiers.java:1195)
    at net.sourceforge.kolmafia.session.ResultProcessor.updateEntauntauned(ResultProcessor.java:324)
    at net.sourceforge.kolmafia.KoLmafia.refreshSessionData(KoLmafia.java:826)
    at net.sourceforge.kolmafia.KoLmafia.refreshSession(KoLmafia.java:656)
    at net.sourceforge.kolmafia.session.LoginManager.initialize(LoginManager.java:196)
    at net.sourceforge.kolmafia.session.LoginManager.doLogin(LoginManager.java:87)
    at net.sourceforge.kolmafia.session.LoginManager.login(LoginManager.java:39)
    at net.sourceforge.kolmafia.request.LoginRequest.processLoginRequest(LoginRequest.java:326)
    at net.sourceforge.kolmafia.request.GenericRequest.handleServerRedirect(GenericRequest.java:1871)
    at net.sourceforge.kolmafia.request.GenericRequest.retrieveServerReply(GenericRequest.java:1773)
    at net.sourceforge.kolmafia.request.GenericRequest.externalExecute(GenericRequest.java:1373)
    at net.sourceforge.kolmafia.request.GenericRequest.execute(GenericRequest.java:1360)
    at net.sourceforge.kolmafia.request.GenericRequest.run(GenericRequest.java:1115)
    at net.sourceforge.kolmafia.request.LoginRequest.run(LoginRequest.java:202)
    at net.sourceforge.kolmafia.RequestThread.postRequest(RequestThread.java:244)
    at net.sourceforge.kolmafia.RequestThread.postRequest(RequestThread.java:209)
    at net.sourceforge.kolmafia.swingui.LoginFrame$LoginPanel.doLogin(LoginFrame.java:266)
    at net.sourceforge.kolmafia.swingui.LoginFrame$LoginPanel.actionConfirmed(LoginFrame.java:230)
    at net.sourceforge.kolmafia.swingui.panel.GenericPanel$ConfirmedListener.execute(GenericPanel.java:506)
    at net.sourceforge.kolmafia.swingui.listener.ThreadedListener.run(ThreadedListener.java:176)
    at net.sourceforge.kolmafia.RequestThread$SequencedRunnable.run(RequestThread.java:352)
    at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
    at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
    at java.base/java.lang.Thread.run(Thread.java:833)
IOException during data post (desc_effect.php?whicheffect=297ee9fadfb5560e5142e0b3a88456db): Address already in use: connect.
IOException during data post (desc_effect.php?whicheffect=297ee9fadfb5560e5142e0b3a88456db): Address already in use: connect.
Error during session initialization
class java.lang.NullPointerException: Cannot invoke "java.lang.CharSequence.length()" because "this.text" is null
java.lang.NullPointerException: Cannot invoke "java.lang.CharSequence.length()" because "this.text" is null
    at java.base/java.util.regex.Matcher.getTextLength(Matcher.java:1769)
    at java.base/java.util.regex.Matcher.reset(Matcher.java:415)
    at java.base/java.util.regex.Matcher.<init>(Matcher.java:252)
    at java.base/java.util.regex.Pattern.matcher(Pattern.java:1134)
    at net.sourceforge.kolmafia.persistence.DebugDatabase.parseStandardEnchantments(DebugDatabase.java:1409)
    at net.sourceforge.kolmafia.persistence.DebugDatabase.parseEffectEnchantments(DebugDatabase.java:1975)
    at net.sourceforge.kolmafia.persistence.DebugDatabase.parseEffectEnchantments(DebugDatabase.java:1982)
    at net.sourceforge.kolmafia.persistence.DebugDatabase.parseEffectEnchantments(DebugDatabase.java:1988)
    at net.sourceforge.kolmafia.Modifiers.overrideEffectModifiers(Modifiers.java:1197)
    at net.sourceforge.kolmafia.session.ResultProcessor.updateEntauntauned(ResultProcessor.java:324)
    at net.sourceforge.kolmafia.KoLmafia.refreshSessionData(KoLmafia.java:826)
    at net.sourceforge.kolmafia.KoLmafia.refreshSession(KoLmafia.java:656)
    at net.sourceforge.kolmafia.session.LoginManager.initialize(LoginManager.java:196)
    at net.sourceforge.kolmafia.session.LoginManager.doLogin(LoginManager.java:87)
    at net.sourceforge.kolmafia.session.LoginManager.login(LoginManager.java:39)
    at net.sourceforge.kolmafia.request.LoginRequest.processLoginRequest(LoginRequest.java:326)
    at net.sourceforge.kolmafia.request.GenericRequest.handleServerRedirect(GenericRequest.java:1871)
    at net.sourceforge.kolmafia.request.GenericRequest.retrieveServerReply(GenericRequest.java:1773)
    at net.sourceforge.kolmafia.request.GenericRequest.externalExecute(GenericRequest.java:1373)
    at net.sourceforge.kolmafia.request.GenericRequest.execute(GenericRequest.java:1360)
    at net.sourceforge.kolmafia.request.GenericRequest.run(GenericRequest.java:1115)
    at net.sourceforge.kolmafia.request.LoginRequest.run(LoginRequest.java:202)
    at net.sourceforge.kolmafia.RequestThread.postRequest(RequestThread.java:244)
    at net.sourceforge.kolmafia.RequestThread.postRequest(RequestThread.java:209)
    at net.sourceforge.kolmafia.swingui.LoginFrame$LoginPanel.doLogin(LoginFrame.java:266)
    at net.sourceforge.kolmafia.swingui.LoginFrame$LoginPanel.actionConfirmed(LoginFrame.java:230)
    at net.sourceforge.kolmafia.swingui.panel.GenericPanel$ConfirmedListener.execute(GenericPanel.java:506)
    at net.sourceforge.kolmafia.swingui.listener.ThreadedListener.run(ThreadedListener.java:176)
    at net.sourceforge.kolmafia.RequestThread$SequencedRunnable.run(RequestThread.java:352)
    at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
    at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
    at java.base/java.lang.Thread.run(Thread.java:833)
Error during session initialization
 
fewyn

fewyn

Administrator
Staff member
I wonder did you reboot at all inbetween these issues? Kind of sounds like there was a zombie java process still running that had stuff tied up.
 
Y

Your.Master

New member
Several, and it wasn't fixed by the first reboot (tried that before going to the forums :)). I suppose it's possible that I was getting a new zombie every startup though until suddenly I wasn't.
 
Veracity

Veracity

Developer
Staff member
So… KoLmafia made a request and, because of an IO error, ended up with a null response text.

We have rejected the coding paradigm that all of the hundreds (thousands?) of places we make a request need to check for an IO failure (i.e. null response) because that is a KoL error. Or a system error.

What do you expect to see? We treat the response as “” and you end up with bogus state, or we get the error and abort, with feedback, or what?
 
You must log in or register to reply here.
Top