Bug - Fixed Debug log generated after some combats

M

Magus_Prime

Well-known member
I'm getting the following error after some combats:

Code: 
Unexpected error, debug log printed.
Script execution aborted (java.lang.NullPointerException): (relay_Guide.ash, line 1153)

Here's the log View attachment DEBUG_20140502.txt

I've already mentioned this in the thread for the Guide relay script.
 
Last edited:
xKiv

xKiv

Active member
What do you have equipped when it happens?
Include familiar equipment, stickers, enthroned/bjornified familiar, and anything else that occurs to you.
 
M

Magus_Prime

Well-known member
The debug error happens after combat is complete and, seemingly, before the mood check fires.

This is in a HC Sneaky Pete run.

Mood:
Code: 
When I run low on All Revved Up, cast 1 Rev Engine
When I run low on Muffled, cast 1 Rev Engine
When I run low on Of Course It Looks Great, cast 1 Check Hair

CCS:
Code: 
[ default ]
skill snap fingers
attack with weapon

Equipment:

Hat: double-ice cap
Weapon: Sneak Pete's basket
Off-Hand: Shield of Icy Fate
Back: Misty Cape
Shirt: Sneak Pete's leather jacket
Pants: snowboarder pants
Accessory slot 1: astral mask
Accessory slot 2: gold wedding ring
Accessory slot 3: Bonerdragon necklace

Here's the section of the session log where the debug happened:

Code: 
[512] The Haunted Wine Cellar (Southeast)
Encounter: skeletal sommelier
Round 0: Arbos wins initiative!
Round 1: Arbos executes a macro!
Round 1: Arbos casts SNAP FINGERS!
Round 2: Arbos attacks!
Round 3: skeletal sommelier takes 142 damage.
Round 3: Arbos attacks!
Round 4: skeletal sommelier takes 144 damage.
Round 4: Arbos wins the fight!
You gain 120 Meat
You acquire an item: dusty bottle of spooky Merlot
You acquire an item: dusty bottle of bad Marsala
You acquire an item: dusty bottle of glassy Muscat
You gain 16 Strongness
You gain a Muscle point!
You gain 14 Wizardliness
You gain 40 Cheek
Unexpected error, debug log printed.

cast 1 Check Hair
You acquire an effect: Of Course It Looks Great (duration: 10 Adventures)

[513] The Haunted Wine Cellar (Northeast)
Encounter: skeletal sommelier
Round 0: Arbos wins initiative!
Round 1: Arbos executes a macro!
Round 1: Arbos casts SNAP FINGERS!
Round 2: Arbos attacks!
Round 3: skeletal sommelier takes 144 damage.
Round 3: Arbos attacks!
Round 4: skeletal sommelier takes 152 damage.
Round 4: Arbos wins the fight!
You gain 122 Meat
You acquire an item: dusty bottle of spooky Merlot
You acquire an item: dusty bottle of great Port
You acquire an item: dusty bottle of average Pinot Noir
You gain 13 Muscleboundness
You gain 14 Magicalness
You gain 43 Sarcasm
pour dusty bottle of Marsala into goblet
Unexpected error, debug log printed.
pour dusty bottle of Pinot Noir into goblet
pour dusty bottle of Merlot into goblet
 
xKiv

xKiv

Active member
Magus_Prime said:
This is in a HC Sneaky Pete run.
Click to expand...

Which means no familiar - and no familiar equipment.

The debug log seems to say that this happens
- inside a relay script (don't know which script, or for which page)
- nested within a few function calls and a loop
- calling equipped_item (don't know for which slot)
- the slot is equipped with something, or getCanonicalName would exit (or throw an NPE) before it reaches getMathingNames
- and then binarySearch(ItemDatabase.canonicalNames, canonicalName) throws NPE, presumably because there's a null in ItemDatabase.canonicalNames? Which shouldn't happen unless it's somehow possible to get an item with non-empty name but no ID into ItemDatabase.itemIdByName?
I don't know how that would happen.
 
E

Ezandora

Member
This is the exact code that triggers the NPE, if you're curious:

Code: 
item [slot] equipped_items()
{
    item [slot] result;
    foreach s in $slots[]
    {
        item it = s.equipped_item();
        if (it == $item[none])
            continue;
        result[s] = it;
    }
    return result;
}

Relevant line:

Code: 
item it = s.equipped_item();

As used in Guide. Part of the design is it sends XMLHTTPRequests to itself, with POST data indicating it wants player state information, including what equipped_items() returns. These requests are sent often (up to half-second intervals if the user is active) and are responsible for calling equipped_item() at any time.

Maybe a race condition?
 
xKiv

xKiv

Active member
Ezandora said:
Maybe a race condition?
Click to expand...

You mean, Arrays.binarySearch isn't thread-safe?
Because the array it searches should be pre-initialized and not change, unless mafia finds an unknown item or something like that.

Is there a reliable way to reproduce this on anybody's instance of mafia?
 
M

Magus_Prime

Well-known member
Debug log and null pointer exception in r14296

I don't know whether the problem is with the relay_Guide script or KoLMafia so I'm reporting this in both places. I received the following while identifying bang potions in combat:

Code: 
Unexpected error, debug log printed.
All bang potions have been identified!
Script execution aborted (java.lang.NullPointerException): (relay_Guide.ash, line 1197)

Here's the section of the script noted in the error:

Code: 
item [slot] equipped_items()
{
    item [slot] result;
    foreach s in $slots[]
    {
        item it = s.equipped_item();
        if (it == $item[none])
            continue;
        result[s] = it;
    }
    return result;
}

and here is the actual line:

Code: 
        item it = s.equipped_item();

Lastly: the debug log View attachment DEBUG_20140801.txt
 
Veracity

Veracity

Developer
Staff member
The issue is that Guide is an ASH script which is periodically polled or refreshed by the browser. Since every browser request runs in its own thread, this can happen while KoLmafia is doing other things in response to actions in the Relay Browser or GUI or gCLI.

In this case, Guide was looking up an item by name. This looks at ItemDatabase.canonicalNames, an array of Strings.
"Simultaneously", bang potion identification was entering a new name into that array ("potion of detection", for example) and sorting it.

There are two ways to deal with this. Either change this:

Code: 
	private static final void saveCanonicalNames()
	{
		ItemDatabase.canonicalNames = new String[ ItemDatabase.itemIdByName.size() ];
		// *** right here, probably, is where Guide tried to look up the item in this array
		ItemDatabase.itemIdByName.keySet().toArray( ItemDatabase.canonicalNames );
		Arrays.sort( ItemDatabase.canonicalNames );
	}
to this:

Code: 
	private static final void saveCanonicalNames()
	{
		String newArray = new String[ ItemDatabase.itemIdByName.size() ];
		ItemDatabase.itemIdByName.keySet().toArray( newArray );
		Arrays.sort( newArray );
		ItemDatabase.canonicalNames = newArray;
	}
With this, Guide will look up the item in a table which does not include the just-added bang potion while the new array is being generated.

Or, change this:

Code: 
	private static final void saveCanonicalNames()
	{
		ItemDatabase.canonicalNames = new String[ ItemDatabase.itemIdByName.size() ];
		ItemDatabase.itemIdByName.keySet().toArray( ItemDatabase.canonicalNames );
		Arrays.sort( ItemDatabase.canonicalNames );
	}

	public static final List<String> getMatchingNames( final String substring )
	{
		return StringUtilities.getMatchingNames( ItemDatabase.canonicalNames, substring );
	}
to this:

Code: 
	private static final void saveCanonicalNames()
	{
		synchronized ( ItemDatabase.canonicalNames )
		{
			ItemDatabase.canonicalNames = new String[ ItemDatabase.itemIdByName.size() ];
			ItemDatabase.itemIdByName.keySet().toArray( ItemDatabase.canonicalNames );
			Arrays.sort( ItemDatabase.canonicalNames );
		}
	}

	public static final List<String> getMatchingNames( final String substring )
	{
		synchronized ( ItemDatabase.canonicalNames )
		{
			return StringUtilities.getMatchingNames( ItemDatabase.canonicalNames, substring );
		}
	}
To be honest, this is no better; the new bang potion could still have already been added to ItemDatabase.itemIdByName map but just not yet been added to the canonical name array.

I'm going to go with the first one.
 
Veracity

Veracity

Developer
Staff member
Yes, in that if it is important to us that the array be sorted, presumably there is code elsewhere that depends on doing a binary search in it, or something. So, even if we add an element and sort it in place, the contents can be temporarily unsorted, and the code that looks at it will not be happy while the sorting is happening.

This case was just especially egregious, since the array was temporarily completely empty (filled with nulls), not simply unsorted.
 
Veracity

Veracity

Developer
Staff member
Turns out there was an existing bug report for this. I've merged them and marking them fixed, again.
 
M

Magus_Prime

Well-known member
Veracity: I very much appreciate the detailed explanations you provide when explaining why and how thing happen with KoLMafia. I always learn something.
 
You must log in or register to reply here.
Top