Feature optional machine-readable logging

[bleary]

Since the parsing of Mafia session logs is a non-trivial task, and the re-calculation of turn-by-turn state is duplicative of tasks Mafia is already doing, I'd like to see an option to dump easily parsed machine-readable data into the session log. Here's a suggestion:

@@JSONSTATUS
{"hp":83,"maxhp":84,"mp":11,"maxmp":84,"daysthisrun":2,"turnsthisrun":6,"adventures":74,"meat":2514,
"muscle":6,"rawmuscle":4,"mysticality":14,"rawmysticality":3,"moxie":8,"rawmoxie":6,"level":2,"full":0,"drunk":0,"spleen":0,
"modifiers":{"ml":10,"init":50,"combat":21,"meat":10,"item":21,"dr":0,"da":240,"famlevel":10},
"effects":{"80224f21d262123e7e370d440ce36937":["The Magical Mojomuscular Melody",10,"mojomusc.gif",
"not implemented",64],"846b5d2c960c2a6bd19ed296425fc41e":["Gaze of the Trickster God",2147483647,"gaze_t.gif","not implemented",771]},
"equipment":{"hat":6002,"weapon":5558,"offhand":6005,"container":5556,"shirt":0,"pants":6006,
"acc1":4644,"acc2":4402,"acc3":6007,"familiarequip":4135,"crownofthrones":0,"fakehands":0,"card sleeve":0},
"stickers":[0,0,0],"folder_holder":[0,0,0,0,0]}
JSON@@

This is data in the format of the 'status' API call, which, if inserted into the session log at appropriate intervals, would greatly simply processing. Here's some code that does it. There are some missing data points.

        public static final void dumpJSONtoSessionLog()
        {

	    JSONStringer myString = new JSONStringer();
	    try {
	    myString.object()
		.key("hp")
		.value( KoLCharacter.getCurrentHP() )
		.key("maxhp")
		.value( KoLCharacter.getMaximumHP() )
		.key("mp")
		.value( KoLCharacter.getCurrentMP() )
		.key("maxmp")
		.value( KoLCharacter.getMaximumHP() )
		.key("daysthisrun")
		.value( KoLCharacter.getCurrentDays() )
		.key("turnsthisrun")
		.value( KoLCharacter.getCurrentRun() )
		.key("adventures")
		.value( KoLCharacter.getAdventuresLeft())
		.key("meat")
		.value( KoLCharacter.getAvailableMeat() )
		.key("muscle")
		.value(  KoLCharacter.getAdjustedMuscle() )
		.key("rawmuscle")
		.value( KoLCharacter.getBaseMuscle() )
		.key("mysticality")
		.value(  KoLCharacter.getAdjustedMysticality() )
		.key("rawmysticality")
		.value(  KoLCharacter.getBaseMysticality() )
		.key("moxie")
		.value(  KoLCharacter.getAdjustedMoxie() )
		.key("rawmoxie")
		.value(  KoLCharacter.getBaseMoxie() )
		.key("level")
		.value(  KoLCharacter.getLevel() )

		.key("full")
		.value(  KoLCharacter.getFullness() )
		.key("drunk")
		.value(  KoLCharacter.getInebriety() )
		.key("spleen")
		.value(  KoLCharacter.getSpleenUse() );

		
		// modifiers sub-object
	    myString.key("modifiers")
		.object()
		.key("ml")
		.value(  KoLCharacter.getMonsterLevelAdjustment() )
		.key("init")
		.value(  KoLCharacter.getInitiativeAdjustment() )
		.key("combat")
		.value(  KoLCharacter.getMeatDropPercentAdjustment()  )
		.key("meat")
		.value(  KoLCharacter.getMonsterLevelAdjustment() )
		.key("item")
		.value(  KoLCharacter.getItemDropPercentAdjustment()  )
		.key("dr")
		.value(  KoLCharacter.getDamageReduction() )
		.key("da")
		.value(  KoLCharacter.getDamageAbsorption()  )
		.key("famlevel")
		.value(  KoLCharacter.getFamiliarWeightAdjustment()  )
		.endObject();

	    int size = KoLConstants.activeEffects.size();
	    AdventureResult[] effectsArray = new AdventureResult[ size ];
	    KoLConstants.activeEffects.toArray( effectsArray );
	    
	    myString.key("effects")
		.object();

	    for ( int i = 0; i < size; i++ )
		{
		    AdventureResult effect = effectsArray[ i ];
		    int duration = effect.getCount();
		    int effectId = EffectDatabase.getEffectId(effect.name);
		    String descId = EffectDatabase.getDescriptionId(effectId);
		    myString.key(descId)
			.array()
			.value(effect.name)
			.value(duration)
			.value(EffectDatabase.getImageName(effectId))
			//.value(EffectDatabase.getDefaultAction(effect.name)) 
			.value("not implemented")
			.value(effectId)
			.endArray();
		}

	    myString.endObject();

	    // equipment list
	    myString.key("equipment")
		.object();

	    myString.key("hat")
		.value( EquipmentManager.getEquipment( EquipmentManager.HAT ).getItemId())
		.key("weapon")
		.value(EquipmentManager.getEquipment( EquipmentManager.WEAPON ).getItemId())
		.key("offhand")
		.value(EquipmentManager.getEquipment( EquipmentManager.OFFHAND ).getItemId())
		.key("container")
		.value(EquipmentManager.getEquipment( EquipmentManager.CONTAINER ).getItemId())
		.key("shirt")
		.value(EquipmentManager.getEquipment( EquipmentManager.SHIRT ).getItemId())
		.key("pants")
		.value(EquipmentManager.getEquipment( EquipmentManager.PANTS ).getItemId())
		.key("acc1")
		.value(EquipmentManager.getEquipment( EquipmentManager.ACCESSORY1 ).getItemId())
		.key("acc2")
		.value(EquipmentManager.getEquipment( EquipmentManager.ACCESSORY2 ).getItemId())
		.key("acc3")
		.value(EquipmentManager.getEquipment( EquipmentManager.ACCESSORY3 ).getItemId())
		.key("familiarequip")
		.value(EquipmentManager.getEquipment( EquipmentManager.FAMILIAR ).getItemId())
		.key("crownofthrones")
		.value(EquipmentManager.getEquipment( EquipmentManager.CROWN_OF_THRONES ).getItemId())
		.key("fakehands")
		.value(EquipmentManager.getEquipment( EquipmentManager.FAKEHAND ).getItemId())
		.key("card sleeve")
		.value(EquipmentManager.getEquipment( EquipmentManager.CARD_SLEEVE ).getItemId())
		.endObject();

	    //end equipment list

	    myString.key("stickers")
		.array()
		.value(EquipmentManager.getEquipment( EquipmentManager.STICKER1 ).getItemId())
		.value(EquipmentManager.getEquipment( EquipmentManager.STICKER2 ).getItemId())
		.value(EquipmentManager.getEquipment( EquipmentManager.STICKER3 ).getItemId())
		.endArray();
	    
	    myString.key("folder_holder")
		.array()
		.value(EquipmentManager.getEquipment( EquipmentManager.FOLDER1 ).getItemId())
		.value(EquipmentManager.getEquipment( EquipmentManager.FOLDER2 ).getItemId())
		.value(EquipmentManager.getEquipment( EquipmentManager.FOLDER3 ).getItemId())
		.value(EquipmentManager.getEquipment( EquipmentManager.FOLDER4 ).getItemId())
		.value(EquipmentManager.getEquipment( EquipmentManager.FOLDER5 ).getItemId())
		.endArray();

	    

	    /*
	    // intrinsics
	    myString.key("intrinsics")
		.value(0)
		.endObject();
	    

	    //effects list

	    .object();
	    .key("effects");
	    .value(0);
	    .endObject();
	    */
	    myString.endObject(); // close container
	    } catch (org.json.JSONException e) {
		StaticEntity.printStackTrace( e );
		}

	    RequestLogger.sessionStream.println("@@JSONSTATUS");
	    RequestLogger.sessionStream.println(myString.toString());
	    RequestLogger.sessionStream.println("JSON@@");	 

        }

If we could come up with something similar which rendered combat results into a JSON structure (along with out-of-combat item acquisition, consumption, and a bunch of other stuff), parsing Mafia session logs would become a whole lot easier.

 

[bleary]

Combat logging could take a combat like this:

[880] The "Fun" House
Encounter: scary clown
Round 0: bleary wins initiative!
Round 1: bleary executes a macro!
Round 1: bleary casts SAUCY SALVE!
You gain 14 hit points
Round 2: bleary casts CURSE OF WEAKSAUCE!
Round 3: scary clown drops 4 attack power.
Round 3: scary clown drops 2 defense.
Round 3: bleary casts SAUCEGEYSER!
Round 4: scary clown takes 410 damage.
Round 4: scary clown drops 2 attack power.
Round 4: scary clown drops 2 defense.
Round 4: bleary wins the fight!
You gain 50 Mana Points
After Battle: With adorable winks and yet still cuter grinning, / there's no doubt about it -- your Groose is quite winning!
You gain 56 Meat
You acquire an item: bloody clown pants
You acquire an item: long skinny balloon
You acquire an item: big red clown nose
You gain 4 Strongness
You gain 7 Mysteriousness
You gain 1 Smarm
You gain 2 Soulsauce

and additionally output (with whitespace added):

@@JSONCOMBAT
{
"location": "The \"Fun\" House",
"zone":"Plains",
"adventure":20,
"monster": "scary clown",
"turn": 880,
"rounds": [ { "player action": {},
	      "monster action": {}
  	      },
	    { "player action": {"skill":5, "player status": {"hp":14, "mp":-4}}
	      },
	    { "player action": {"skill":4034, "monster status": {"attack":-4,"defense":-2},
	      	      	        "player status":{"mp":-8}}
	      },
	    { "player action": {"skill":4012, "monster status": {"hp":-410}, "player status":{"mp":-24}},
	      "monster status": {"attack":-2, "defense":-2},
	      "player status": {"mp":50}
            } ]
"post combat": {
	      "player status": {"meat":56,"rawmuscle":4,"rawmysticality":7,"rawmoxie":1,"soulsauce": 2},
	      "item": [432, 433, 449]
	      },
}JSON@@

 

[bleary]

proof-of-concept

I've managed to cobble together some proof-of-concept code for combat logging. The key is creating a new JSONObject at the beginning of each combat, populating it as we parse, and then dumping it to the log when the combat is over. It'll do this (whitespace added):

[48] The Boss Bat's Lair
Encounter: beefy bodyguard bat
Round 0: Authority wins initiative!
Round 1: Authority casts DISSONANT RIFF!
Round 2: beefy bodyguard bat takes 5 damage.
Round 2: beefy bodyguard bat drops 4 attack power.
Round 2: beefy bodyguard bat drops 4 defense.
Round 2: Authority casts DISSONANT RIFF!
Round 3: beefy bodyguard bat takes 4 damage.
Round 3: beefy bodyguard bat drops 3 attack power.
Round 3: beefy bodyguard bat drops 3 defense.
Round 3: Authority casts SING!
Round 4: beefy bodyguard bat takes 3 damage.
Round 4: Vespasian tosses a grisly, eviscerated turkey carcass at him, dealing 5 damage.
Round 4: beefy bodyguard bat takes 5 damage.
Round 4: Authority attacks!
Round 5: beefy bodyguard bat takes 95 damage.
Round 5: Vespasian tosses a tureen of hot gravy at him, dealing 3 damage.
Round 5: beefy bodyguard bat takes 3 damage.
Round 5: beefy bodyguard bat takes 2 damage.
Round 5: Authority wins the fight!
Your familiar gains a pound: Vespasian, the 2 lb. Leprechaun
After Battle: Vespasian winks at you.
You gain 426 Meat
You gain 4 Strengthliness
You gain 6 Wizardliness
You gain 14 Chutzpah
@@JSONCOMBAT
{
  "adventure": 34,
  "monster": "beefy bodyguard bat",
  "rounds": [
    {"monster status": {
      "defense": 32,
      "hp": 35,
      "attack": 35
    }},
    {
      "monster status": {
        "defense": 32,
        "hp": 35,
        "attack": 35
      },
      "player action": [[
        "skill",
        6029
      ]]
    },
    {
      "monster status": {
        "defense": 28,
        "hp": 30,
        "attack": 31
      },
      "player action": [[
        "skill",
        6029
      ]],
      "monster change": {
        "monster attack": -4,
        "monster defense": -4,
        "monster hp": -5
      }
    },
    {
      "monster status": {
        "defense": 25,
        "hp": 26,
        "attack": 28
      },
      "player action": [[
        "skill",
        6025
      ]],
      "monster change": {
        "monster attack": -3,
        "monster defense": -3,
        "monster hp": -4
      }
    },
    {
      "monster status": {
        "defense": 25,
        "hp": 18,
        "attack": 28
      },
      "player action": ["attack"],
      "monster change": {"monster hp": [
        -3,
        -5
      ]}
    },
    {
      "monster change": {"monster hp": [
        -95,
        -3,
        -2
      ]},
      "meat": 426,
      "substats": [
        4,
        6,
        14
      ]
    }
  ]
}
JSON@@

I also have some code which will (using only libraries we're already including) zlib compress and base64 encode text strings, so longer bits of data (say, the current inventory) can be inserted into the log without completely spamming it:

@@JSONINV-B64Z
eJw9UUsWAzEIukvWXcRP1MzV+nr3pgG7glEC6ryHzGnjkfkamQdfQ9YG7vOdP4zx6A/11l3Z/svwrmQ8dlzciXLLMaHXKcnC
/JNAK2+A0a9AOqbmJWstRwVpifhsFT0xIlp4SN0CQCAGSenpxjXPTqlLrNywtnRjk0RXoicLa8ITBXPOitoEA2zYq/OMvhhnOJ9
vBqryDoIUKSHyMIUVlAOvwG/CMJ8vA3VXlQ==
JSON@@

 

[Lilac]

I'd like to contribute a strong +1 to this suggestion. I will probably be working with bleary on a new, robust parser for this data, and it's only possible with logging like this. In today's KoL environment, it's critical to know how much +item, +ML, and/or -combat you were running for a given quest.

 

[Darzil]

To be fair, you need more than that ideally. You'd want to know the exact +item you were running at the time the item drops (and maybe +pickpocket when pickpocketing).

What I'd suggest, however, is having something separate from the session log for this, effectively a machine readable log. The example given here makes a log a human can reasonably read into a mess so that a parser can look instead.

Have a think about what information you'd want for a machine parsable log, possibly one that can be used for spading as well as whatever you plan to use it for. I'd certainly like the possibilities opened up by a log that shows all +pickpocket on a pickpocketed item, all +items on an item drop, all +meat on a meat drop etc, which could be passed to a person/website who could then parse 100's of them and get a huge improvement to the accuracy of known drop rates. I don't think the current session log is the place for this.

 

[Veracity]

I agree. I like the session log as it is now for the way I personally use it: to go back and look up what I did and what happened, now and then. I think a machine-readable log is fine - and I think JSON is fine, since we have a JSON reader/writer from json.org built-in already - but it should go in a separate file. I think the sessions directory is OK for it, but how about <name>_<date>.json for the JSON file that corresponds to the human-readable <name>_<date>.txt?

 

[lostcalpolydude]

I don't really know much about compression... is that encoding and compression something that is obvious to most people that would want to use the information? If not, there should also be some documentation included with mafia for how to use that.

 

[bleary]

I agree. I like the session log as it is now for the way I personally use it: to go back and look up what I did and what happened, now and then. I think a machine-readable log is fine - and I think JSON is fine, since we have a JSON reader/writer from json.org built-in already - but it should go in a separate file. I think the sessions directory is OK for it, but how about <name>_<date>.json for the JSON file that corresponds to the human-readable <name>_<date>.txt?

I don't have any objection to it going in a separate file eventually, but for right now, I'm finding it very useful to keep it all in one for debugging purposes. Interspersing the JSON allows for fallback log parsing as well, so a legacy log parser like Flolle's (or others) can be gradually transitioned over. In my patchset I implemented a preference that toggles the machine-readable logging so that it doesn't clutter the logs by default. Since all the inserted JSON is delimited, a regex can filter it in or out: "@@JSON(\n|.)*?JSON@@"

I don't really know much about compression... is that encoding and compression something that is obvious to most people that would want to use the information? If not, there should also be some documentation included with mafia for how to use that.

It's Base 64 encoding (http://en.wikipedia.org/wiki/Base64) of zlib compression. Very standard, using java.util.zip and org.tmatesoft.svn.core.internal.util.SVNBase64 (since we're already including it). Decoding it in python is as simple as:

import json, zlib, base64 # all standard libraries
data = json.loads(zlib.decompress(base64.decodestring(encoded_string)))

And in php:

<?php
$data = json_decode(gzuncompress(base64_decode($encoded_string)));
?>

 

[Darzil]

I don't have any objection to it going in a separate file eventually, but for right now, I'm finding it very useful to keep it all in one for debugging purposes.

It isn't going to get added into Mafia in that form, as it would break the existing functionality of the session log, which is to be human readable.

 

[bleary]

So I have a new patch, which is here: http://introvert.net/2013/11/machinelog/MachineLogger.diff

Features:
- toggleable machine-readable logging preference (defaults to off)
- logs in a compressed (gzip) JSON format, very close to that used by other clients
- one logfile per ascension ("sessions/playername_12.txt.gz")
- stores API status before (cached) and after (fresh) every logged pageload, just like k*lpr*xy
- stores additional interesting and valuable data, like calculated modifiers, combat skill/item usage, etc.

What it doesn't do (yet):
- report on # of pirate insults
- reliably report noncombat names
- include zone/location information