Debug logs beginning on 20210914

[Ethelred]

On 9/14 after rollover, I got a bunch of debug logs when logging in my chars. Since I hadn't updated my mafia in a while (was running KoLmafia-20913M.jar), I figured it was just time to build a new version. Yesterday I updated to KoLmafia_20933M.jar, and after rollover I tried it. The "Unexpected error, debug log printed." msgs were still printed during login, about 34 per char. All the logs seemed to be written into the same file, so it got quite big. I've cut and pasted the first 5 and include them here.

System Info:
OS: Mac OS X El Capitan, Version 10.11.6
Java: Java(TM) SE Runtime Environment (build 1.8.0_201-b09)
Mafia: KoLmafia_20933M.jar

Not sure what my next step should be. My scripts seem to run ok and nothing is failing, as far as I can see. But I get the "Unexpected error, debug log printed." message 30-some times near the beginning of each login. Thanks for any help you can provide and for all the work you do to keep mafia working so well.

 

[fronobulax]

I think this is caused by trying to update scripts from repositories. So turning off the update automatically flag might stop it.

It is probably failing when trying to read data/svnrepo.json.

Save your version, just in case, since if none of the following work I am going to want to look at it.

If you are using your own version of it then it probably has some ill-formed JSON. If you are using the version KoLmafia downloaded, perhaps is is corrupt. You might try deleting it and rerunning.

I changed how we handled JSON and the change made our parsing more rigid. Maybe I have a bug to fix?

Might be a Mac issue this Windows dev didn't anticipate.

Also possibly that your local build and mods (KoLmafia_20933M.jar) are in issue in which case please try something you download from https://ci.kolmafia.us/

Please try some of these and report back. I own this if it is a bug and so will try and fix it.

 

[Ethelred]

I think this is caused by trying to update scripts from repositories. So turning off the update automatically flag might stop it.

It is probably failing when trying to read data/svnrepo.json.

Save your version, just in case, since if none of the following work I am going to want to look at it.

If you are using your own version of it then it probably has some ill-formed JSON. If you are using the version KoLmafia downloaded, perhaps is is corrupt. You might try deleting it and rerunning.

I changed how we handled JSON and the change made our parsing more rigid. Maybe I have a bug to fix?

Might be a Mac issue this Windows dev didn't anticipate.

Also possibly that your local build and mods (KoLmafia_20933M.jar) are in issue in which case please try something you download from https://ci.kolmafia.us/

Please try some of these and report back. I own this if it is a bug and so will try and fix it.

Thanks for your reply. Based on your tip, I checked my version of data/svnrepo.json. Sure enough, it had been updated on 09/14/2021 to the attached file. I had to change the file type from .json to .txt to get the kolmafia.us software to upload it. I should note that I have to use two different systems to run, one to build my .jar files, and another to execute them. The problems were discussed last year in this forum, but I was never able to solve them. Anyhow, I copied data/svnrepo.json from my build system to my run system and the problem went away.

Now the questions I have are:

1. What caused the data/svnrepo.json file to be updated on my run computer on 09/14/2021?
2. Why wasn't it updated after the problems were detected?
3. How do I know when it needs to be updated and force the update to happen?
4. What is this "update automatically flag" of which you speak?

Thanks again for the help.

 

[heeheehee]

1. ScriptManager has some logic to download svnrepo.json from sourceforge. (This is relevant to ~everything else.)

The file you uploaded is very clearly an error from sourceforge. I wonder if we had gotten a 500 or other error HTTP status that we ignored.

2. The download occurs when loading the ScriptManager class, in a couple of scenarios: either you don't have the file, or _svnRepoFileFetched is false. (There's also a boolean `force` parameter to always update, but that's set to false in the static block.)

(In your case, this gets loaded when accessing the Item Manager GUI element.)

The awkward thing is that we then throw an exception, which I think may interfere with Java's understanding that the static block has already been run (since it never completed). Hence the repeated debug log entries.

I wonder if your (daily global) preferences just aren't getting reset properly? and so it's always true?

3. In this case, the debug log points to a particular line (ScriptManager trying + failing to parse json from svnrepo.json). Easiest way to force the update is to delete the existing (bad) file.

4. There is a global preference svnUpdateOnLogin. I don't think that's relevant, since it only goes through SVNManager (and doesn't care about ScriptManager as far as I can tell).

 

[heeheehee]

Some other things that could be useful for debugging:

What's your lastGlobalCounterDay preference set to? When does Mafia think rollover is?

in the CLI:

> get lastGlobalCounterDay
> rollover

or you can access + print them from an ASH script:

print(get_property("lastGlobalCounterDay"));
print(rollover());

Either your preference isn't getting reset properly, or you're continuing to fetch a broken svnrepo.json from sourceforge.

 

[fronobulax]

I have previously seen corrupted svnrepo files that were caused either by a transmission error getting it from SourceForge or a local system error when writing to disk. KoLmafia could be better about checking and detecting such situations and trying to recover. The former pretty clearly applies to your case since the file content indicates SourceForge could not give you svnrepo

My memory was that preference svnUpdateOnLogin triggered a check for updates. If it was false there would be no automatic updates and hence no one would try and read svnrepo.

1. What caused the data/svnrepo.json file to be updated on my run computer on 09/14/2021?
2. Why wasn't it updated after the problems were detected?
3. How do I know when it needs to be updated and force the update to happen?
4. What is this "update automatically flag" of which you speak?

1. Most likely svnUpdateOnLogin was set to true. Other possibility is that you opened the Scripts Menu.
2. The problem wasn't detected in the sense that KoLmafia expected to be able to adjust to the detected error. In general KoLmafia is not robust when it comes to input/output errors. That is reasonable because the most common ones observed tend to be intermittent and the only safe response is to try again. Manually deleting the file caused KoLmafia to realize it wasn't there and thus try to fetch it.
3. It only needs to be updated when you have no local version or a corrupt local version or the Kolmafia devs have made new changes and committed them to the repository. If KoLmafia is allowed/enabled to check it will update automatically except in the case of a corrupt file. You can always force an update by deleting it and waiting until an action that needs it is triggered such as using the Scripts Menu or allowing daily updates.
4. svnUpdateOnLogin

 

[Ethelred]

Some other things that could be useful for debugging:

What's your lastGlobalCounterDay preference set to? When does Mafia think rollover is?

in the CLI:

> get lastGlobalCounterDay

1632108600

> rollover

1632108598

or you can access + print them from an ASH script:

print(get_property("lastGlobalCounterDay"));
print(rollover());

Either your preference isn't getting reset properly, or you're continuing to fetch a broken svnrepo.json from sourceforge.

Not sure what those numbers mean. Is it some kind of Unix coded date/time?

Sorry for the delay in replying. Things are working ok now after I copied svnrepo.json from my development system. And it looks like it has been updated since then as well. So maybe this was all just a Sourcfceforge glitch?

Thanks for your help.

 

[Ethelred]

I have previously seen corrupted svnrepo files that were caused either by a transmission error getting it from SourceForge or a local system error when writing to disk. KoLmafia could be better about checking and detecting such situations and trying to recover. The former pretty clearly applies to your case since the file content indicates SourceForge could not give you svnrepo

My memory was that preference svnUpdateOnLogin triggered a check for updates. If it was false there would be no automatic updates and hence no one would try and read svnrepo.

1. Most likely svnUpdateOnLogin was set to true. Other possibility is that you opened the Scripts Menu.
2. The problem wasn't detected in the sense that KoLmafia expected to be able to adjust to the detected error. In general KoLmafia is not robust when it comes to input/output errors. That is reasonable because the most common ones observed tend to be intermittent and the only safe response is to try again. Manually deleting the file caused KoLmafia to realize it wasn't there and thus try to fetch it.
3. It only needs to be updated when you have no local version or a corrupt local version or the Kolmafia devs have made new changes and committed them to the repository. If KoLmafia is allowed/enabled to check it will update automatically except in the case of a corrupt file. You can always force an update by deleting it and waiting until an action that needs it is triggered such as using the Scripts Menu or allowing daily updates.
4. svnUpdateOnLogin

In my mafia GLOBAL.prefs.txt file:

svnUpdateOnLogin=false

But one of the first things I do is open the scripts menu, so if that causes a check, that would do it. As I said in the previous post, everything is working fine now and I'm comfortable with considering it a Sourceforge glitch.

Thanks for the help.

 

[heeheehee]

Is it some kind of Unix coded date/time?

Yeah, these numbers are Unix timestamps (seconds since midnight, Jan 1, 1970 UTC).

I was concerned your daily _preferences weren't being properly cleared for some reason, but that looks correct.

Anyways, glad to hear this works for you now. On one hand, we hope this won't happen as often once we move off Sourceforge; on the other hand, we really should avoid clobbering the file if we get a non-OK response.

 

[Ethelred]

The debug logs started again a couple of days ago. I have not yet figured out how to do all the upgrades to build new mafia versions, so I'm stuck on KoLmafia-20947M.jar for the moment. When I log in my first char after rollover, I get about 35 stack traces in a debug log. Once again, svnrepo.json seems to be the culprit. A fresh version is downloaded in each case. Only this time, svnrepo.json looks to be a legimate file, not a failure message from Sourceforge. However, if I delete that downloaded file and restore the previous version, I can run without any further errors. I have included the first couple of stack traces from the debug log and the new svnrepo.json file. I have no clue what's going on and would greatly appreciate any help, suggestions, or advice. Thanks, in advance.

PS: I had to add .txt to the svnrepo.json file to get the forum software to upload it. Also, the file is vastly different than the previous version, which consists of descriptions of mafia scripts installed on my system, whereas the new one doesn't seem to be about that as all.

 

[fewyn]

According to the debug log you are still running Java 8. The new minimum required version is now Java 9 check out https://adoptium.net/index.html to get the latest version. I recommend you uninstall your existing JDK before you upgrade.

 

[heeheehee]

By a couple days ago, do you happen to mean Sep 26, when we archived the sourceforge repo?

Your svnrepo.json is apparently HTML for a sourceforge login page.

Out of curiosity, what local patches are you building with? At least some of them may make sense to merge upstream so you stop needing to build manually; I can work with you to resolve the eventual merge conflicts if you need help.

The easiest way to migrate to the new repository is to create a fresh checkout of https://github.com/kolmafia/kolmafia.git, with either a git client or svn. Since you also have some local changes, you'd also need to export your patches via `svn diff`, patch them back in prior to r25717, then deal with the resulting merge conflicts.

Additionally, as fewyn notes, you're using Java 8; you'll need to upgrade to at least Java 9 (we recommend 17, from Adoptium) in order to use the latest builds.

 

[fronobulax]

The svnrepo.json file in your post in not what KoLmafia is expecting. That causes the debug logs. As long as the file is incorrect the logs will continue.

So why is the file incorrect? The file you posted was returned by SourceForge and it looks to me like SourceForge wants "you" to log in.

I can come up with a lot of speculation as to why SourceForge doesn't want to send you the right file. Many of those are intermittent and there is nothing you or KoLmafia can do to address the problem except try again.

Less likely but there may be something about how your system accesses SourceForge that causes the problem. Using a proxy, a VPN, or coming from an ip address that SourceForge treats differently could be factors, but I am not sure how to identify those and address them.

It is possible that when @gausie froze SourceForge something happened so that (some) frozen files can only be accessed by logged in users.

You appear to be running a version that predates all of the "Thou Shalt Update Java" changes but if you are mixing and matching code in an effort to build your own then you certainly need to update Java.

You can eliminate a lot of possibilities by downloading a version built elsewhere and running it, provided you upgrade Java or grab a Jar that does not require newer Java.

If you want some handholding so you can build your own again, start a new thread and ask. But the first step will be making it so your system runs Java 9 or better.

KoLmafia is pretty bad about telling users everything KoLmafia knows about why an I/O operation fails. You might consider making a feature request for KoLmafia to display more information about certain operations, such as fetching this file and fetching from remote repositories.

Finally there is a pretty good chance that in a few months from now, the file will be hosted elsewhere.

Wish I had better answers.

 

[Ethelred]

Yes, I am still running Java version 8. I understand I need to upgrage to a new version of Java to incorporate new content as it is added. But in order to do that I need to install new tools and procedures and use a new build process that I do not yet understand. I'm hoping that https://wiki.kolmafia.us/index.php/Compiling_from_Source will be updated with more detailed info. Note that it still says that Java 1.8 or newer is required in the Mac OSX section. In the interim, I'm trying to get by using my last mafia build, KoLmafia-20947M.jar. For the most part that is working just fine. On Sept. 30, the svnrepo.json file got updated from SourceForge with an invalid file. Once I replace that invalid file with the previous file, I can run just fine. I don't understand what the new file is trying to do or wants or why it is being downloaded. The system I'm running on is not the system I build mafia on, where my mafia source files are located. I don't think I've ever had a login account at SourceForge, so I couldn't login in there even if I wanted to. I can live with restoring the svnrepo.json file every day until I can get my new build system installed and in place, if that's what is needed. I just didn't understand what that svnrepo.json file was trying to do or why it was being changed. If nobody else knows either, I'll just chalk it up to one of life's mysteries.

As for my local patches a couple of them are changing some mafia prefs from global to user (or perhaps vice versa, my memory is dim), some are local clan jokes involving some of my clanmates with whom I share my builds, and a couple are reversions or modifications of changes made by the mafia developers. In particular, I reverted the change that reduced the number of simutaneous sessions from 5 to 2. I regularly run 5 simultaneous sessions. I always restart an instance when I change users and have had no problems with that. At least none that I'm aware of. That fact that I'm posting here for help may be evidence that that is not the case, but I don't think the issues are related.

I'm going to try to find a preference that is controlling the svnrepo.json file replacement and see if I can bypass the problem by manually updating that as a temporary fix until I can get my new build system up and running.

Thanks for the help and any additional suggestions on how to bridge the gap are welcome.

 

[fewyn]

Basically when the script manager or the svn updater runs I think it checks if it has the latest svnrepo.json so it knows what repos/etc are.

 

[Ethelred]

Basically when the script manager or the svn updater runs I think it checks if it has the latest svnrepo.json so it knows what repos/etc are.

Ok, that's fine. But the file it downloaded isn't a valid svnrepo.json file. Is that some kind of bug?

 

[fewyn]

When we shut down the Sourceforge repo it seems to have locked down viewing of the repo itself. Since you are currently building for yourself you could always edit /src/net/sourceforge/kolmafia/persistence/ScriptManager.java to point to https://raw.githubusercontent.com/kolmafia/kolmafia/main/data/SVN/svnrepo.json instead of "https://sourceforge.net/p/kolmafia/code/HEAD/tree/data/SVN/svnrepo.json" + "?format=raw"

 

[Ethelred]

When we shut down the Sourceforge repo it seems to have locked down viewing of the repo itself. Since you are currently building for yourself you could always edit /src/net/sourceforge/kolmafia/persistence/ScriptManager.java to point to https://raw.githubusercontent.com/kolmafia/kolmafia/main/data/SVN/svnrepo.json instead of "https://sourceforge.net/p/kolmafia/code/HEAD/tree/data/SVN/svnrepo.json" + "?format=raw"

Thanks. I'll give that a try. Do I still need the ' +"?format=raw"' at the end of the line? Or is that to be deleted?

 

[fewyn]

Thanks. I'll give that a try. Do I still need the ' +"?format=raw"' at the end of the line? Or is that to be deleted?

That shouldn't be needed at all.

 

[fronobulax]

I am able to access https://svn.code.sf.net/p/kolmafia/code/data/SVN/svnrepo.json directly in a browser, without any SourceForge login or prompt for one. It is the correct file.

When I tried to do it with TortoiseSVN I got several errors about expired certificates. I don't know how to use that information to debug your problem.

If you can't, or choose not to, rebuild with the change noted above then as noted upstream you should continue with svnUpdateOnLogin set to false and do not use the Scripts Menu.

The https://wiki.kolmafia.us/index.php/Compiling_from_Source will be updated but at this moment it is a moving target. It is likely to get more attention when the devs stop learning things about the new build process.

You could update to Java 9 and continue to build things as you have done, at least for a short time. It is pretty clear that installing a version of Java greater than 8 will be the first step in the new process but the existing tools should do fine if you move from 8 to 9 or better yet 17.