Feature Enhance "trace" debugging

Veracity

Veracity

Developer
Staff member
This may be an obscure feature, but KoLmafia can make a TRACE file which logs timestamped request/response transactions and ASH script execution.

Here's an example:

Code: 
debug trace on

Opens TRACE_20220124.txt in the same directory where DEBUG files go.

Code: 
closet put * seal tooth

1643052301102: Requesting: https://www.kingdomofloathing.com/inventory.php?action=closetpush&ajax=1&whichitem=2&qty=65&pwd
1643052301211: Retrieved: https://www.kingdomofloathing.com/inventory.php?action=closetpush&ajax=1&whichitem=2&qty=65&pwd (544 bytes)

acquire 1 seal tooth

1643052310550: Requesting: https://www.kingdomofloathing.com/shop.php?whichshop=generalstore&action=buyitem&whichrow=648&ajax=1&quantity=1
1643052310670: Retrieved: https://www.kingdomofloathing.com/shop.php?whichshop=generalstore&action=buyitem&whichrow=648&ajax=1&quantity=1 (1165 bytes)
1643052310673: Requesting: https://www.kingdomofloathing.com/api.php?what=status&for=KoLmafia
1643052310746: Retrieved: https://www.kingdomofloathing.com/api.php?what=status&for=KoLmafia (4063 bytes)
1643052310790: Requesting: https://www.kingdomofloathing.com/inv_use.php?whichitem=23&ajax=1
1643052310905: Retrieved: https://www.kingdomofloathing.com/inv_use.php?whichitem=23&ajax=1 (1269 bytes)
1643052310911: Requesting: https://www.kingdomofloathing.com/api.php?what=status&for=KoLmafia
1643052310979: Retrieved: https://www.kingdomofloathing.com/api.php?what=status&for=KoLmafia (4063 bytes)
1643052311050: Requesting: https://www.kingdomofloathing.com/hermit.php
1643052311092: Retrieved: https://www.kingdomofloathing.com/hermit.php (10353 bytes)
1643052311093: Requesting: https://www.kingdomofloathing.com/api.php?what=status&for=KoLmafia
1643052311177: Retrieved: https://www.kingdomofloathing.com/api.php?what=status&for=KoLmafia (4063 bytes)
1643052311212: Requesting: https://www.kingdomofloathing.com/hermit.php?action=trade&quantity=1&whichitem=2
1643052311287: Retrieved: https://www.kingdomofloathing.com/hermit.php?action=trade&quantity=1&whichitem=2 (10074 bytes)

(The trace file does not actually include the commands; I inserted them so you could see what I typed to generate the resulting lines.)
CLI commands log request/response, but not the command.

Code: 
closet put * seal tooth

1643052317944: Requesting: https://www.kingdomofloathing.com/inventory.php?action=closetpush&ajax=1&whichitem=2&qty=1&pwd
1643052318042: Retrieved: https://www.kingdomofloathing.com/inventory.php?action=closetpush&ajax=1&whichitem=2&qty=1&pwd (539 bytes)

call acquire-seal-tooth.txt

1643052376749: Requesting: https://www.kingdomofloathing.com/shop.php?whichshop=generalstore&action=buyitem&whichrow=648&ajax=1&quantity=1
1643052376927: Retrieved: https://www.kingdomofloathing.com/shop.php?whichshop=generalstore&action=buyitem&whichrow=648&ajax=1&quantity=1 (1165 bytes)
1643052376930: Requesting: https://www.kingdomofloathing.com/api.php?what=status&for=KoLmafia
1643052377012: Retrieved: https://www.kingdomofloathing.com/api.php?what=status&for=KoLmafia (4063 bytes)
1643052377065: Requesting: https://www.kingdomofloathing.com/inv_use.php?whichitem=23&ajax=1
1643052377183: Retrieved: https://www.kingdomofloathing.com/inv_use.php?whichitem=23&ajax=1 (1288 bytes)
1643052377188: Requesting: https://www.kingdomofloathing.com/api.php?what=status&for=KoLmafia
1643052377260: Retrieved: https://www.kingdomofloathing.com/api.php?what=status&for=KoLmafia (4063 bytes)
1643052377324: Requesting: https://www.kingdomofloathing.com/hermit.php?action=trade&quantity=1&whichitem=2
1643052377390: Retrieved: https://www.kingdomofloathing.com/hermit.php?action=trade&quantity=1&whichitem=2 (10117 bytes)
1643052377395: Requesting: https://www.kingdomofloathing.com/api.php?what=status&for=KoLmafia
1643052377467: Retrieved: https://www.kingdomofloathing.com/api.php?what=status&for=KoLmafia (4063 bytes)

Call a CLI script which has that same command. Logs request/response, but not the CLI script.

Code: 
closet put * seal tooth

1643052393103: Requesting: https://www.kingdomofloathing.com/inventory.php?action=closetpush&ajax=1&whichitem=2&qty=1&pwd
1643052393196: Retrieved: https://www.kingdomofloathing.com/inventory.php?action=closetpush&ajax=1&whichitem=2&qty=1&pwd (539 bytes)

call retrieve-seal-tooth.ash

1643052461328: Starting script: retrieve-seal-tooth.ash
1643052461333: Requesting: https://www.kingdomofloathing.com/shop.php?whichshop=generalstore&action=buyitem&whichrow=648&ajax=1&quantity=1
1643052461505: Retrieved: https://www.kingdomofloathing.com/shop.php?whichshop=generalstore&action=buyitem&whichrow=648&ajax=1&quantity=1 (1165 bytes)
1643052461509: Requesting: https://www.kingdomofloathing.com/api.php?what=status&for=KoLmafia
1643052461595: Retrieved: https://www.kingdomofloathing.com/api.php?what=status&for=KoLmafia (4063 bytes)
1643052461647: Requesting: https://www.kingdomofloathing.com/inv_use.php?whichitem=23&ajax=1
1643052461763: Retrieved: https://www.kingdomofloathing.com/inv_use.php?whichitem=23&ajax=1 (1288 bytes)
1643052461767: Requesting: https://www.kingdomofloathing.com/api.php?what=status&for=KoLmafia
1643052461840: Retrieved: https://www.kingdomofloathing.com/api.php?what=status&for=KoLmafia (4063 bytes)
1643052461916: Requesting: https://www.kingdomofloathing.com/hermit.php?action=trade&quantity=1&whichitem=2
1643052461985: Retrieved: https://www.kingdomofloathing.com/hermit.php?action=trade&quantity=1&whichitem=2 (10117 bytes)
1643052461989: Requesting: https://www.kingdomofloathing.com/api.php?what=status&for=KoLmafia
1643052462062: Retrieved: https://www.kingdomofloathing.com/api.php?what=status&for=KoLmafia (4063 bytes)
1643052462136: Finished script: retrieve-seal-tooth.ash

Call an ASH script and voila! It tells you which script is executing those requests.

Code: 
closet put * seal tooth

1643052466636: Requesting: https://www.kingdomofloathing.com/inventory.php?action=closetpush&ajax=1&whichitem=2&qty=1&pwd
1643052466696: Retrieved: https://www.kingdomofloathing.com/inventory.php?action=closetpush&ajax=1&whichitem=2&qty=1&pwd (539 bytes)

ash retrieve_item( 1, $item[ seal tooth ] );

1643052481378: Requesting: https://www.kingdomofloathing.com/shop.php?whichshop=generalstore&action=buyitem&whichrow=648&ajax=1&quantity=1
1643052481482: Retrieved: https://www.kingdomofloathing.com/shop.php?whichshop=generalstore&action=buyitem&whichrow=648&ajax=1&quantity=1 (1165 bytes)
1643052481485: Requesting: https://www.kingdomofloathing.com/api.php?what=status&for=KoLmafia
1643052481558: Retrieved: https://www.kingdomofloathing.com/api.php?what=status&for=KoLmafia (4063 bytes)
1643052481611: Requesting: https://www.kingdomofloathing.com/inv_use.php?whichitem=23&ajax=1
1643052481723: Retrieved: https://www.kingdomofloathing.com/inv_use.php?whichitem=23&ajax=1 (1273 bytes)
1643052481728: Requesting: https://www.kingdomofloathing.com/api.php?what=status&for=KoLmafia
1643052481799: Retrieved: https://www.kingdomofloathing.com/api.php?what=status&for=KoLmafia (4063 bytes)
1643052481873: Requesting: https://www.kingdomofloathing.com/hermit.php?action=trade&quantity=1&whichitem=2
1643052481938: Retrieved: https://www.kingdomofloathing.com/hermit.php?action=trade&quantity=1&whichitem=2 (10117 bytes)
1643052481942: Requesting: https://www.kingdomofloathing.com/api.php?what=status&for=KoLmafia
1643052482024: Retrieved: https://www.kingdomofloathing.com/api.php?what=status&for=KoLmafia (4063 bytes)

Well, it's an ASH command - using an ASH interpreter - but not a script.

Let's try some beefier scripts.

Code: 
BeachComber 1

1643053375730: Starting script: BeachComber.ash
1643053375738: Requesting: https://www.kingdomofloathing.com/main.php?comb=1
1643053375889: Retrieved: https://www.kingdomofloathing.com/main.php?comb=1
1643053375890: Requesting: https://www.kingdomofloathing.com/choice.php?forceoption=0
1643053375968: Retrieved: https://www.kingdomofloathing.com/choice.php?forceoption=0 (15619 bytes)
1643053375986: Requesting: https://www.kingdomofloathing.com/choice.php?whichchoice=1388&option=5&pwd
1643053376086: Retrieved: https://www.kingdomofloathing.com/choice.php?whichchoice=1388&option=5&pwd (7761 bytes)
1643053376091: Requesting: https://www.kingdomofloathing.com/main.php?comb=1
1643053376183: Retrieved: https://www.kingdomofloathing.com/main.php?comb=1
1643053376183: Requesting: https://www.kingdomofloathing.com/choice.php?forceoption=0
1643053376247: Retrieved: https://www.kingdomofloathing.com/choice.php?forceoption=0 (15619 bytes)
1643053376259: Requesting: https://www.kingdomofloathing.com/choice.php?whichchoice=1388&option=2&pwd
1643053376380: Retrieved: https://www.kingdomofloathing.com/choice.php?whichchoice=1388&option=2&pwd (29890 bytes)
1643053376402: Requesting: https://www.kingdomofloathing.com/api.php?what=status&for=KoLmafia
1643053376474: Retrieved: https://www.kingdomofloathing.com/api.php?what=status&for=KoLmafia (4052 bytes)
1643053376518: Requesting: https://www.kingdomofloathing.com/choice.php?whichchoice=1388&option=4&coords=10%2C52043
1643053376660: Retrieved: https://www.kingdomofloathing.com/choice.php?whichchoice=1388&option=4&coords=10%2C52043 (16499 bytes)
1643053376684: Requesting: https://www.kingdomofloathing.com/api.php?what=status&for=KoLmafia
1643053376751: Retrieved: https://www.kingdomofloathing.com/api.php?what=status&for=KoLmafia (4018 bytes)
1643053376791: Requesting: https://www.kingdomofloathing.com/choice.php?whichchoice=1388&option=5&pwd
1643053376857: Retrieved: https://www.kingdomofloathing.com/choice.php?whichchoice=1388&option=5&pwd (7761 bytes)
1643053376860: Finished script: BeachComber.ash

It's an ASH script. As expected, it logs the script execution. Huh. I wonder why it went to main.php twice? Right. It was checking to see how many free walks you have left today, since the argument "1" means "all free walks and 1 walk that costs a turn".

Code: 
combo 1

1643053461963: Starting script: combo.js
1643053462177: Requesting: https://www.kingdomofloathing.com/main.php?comb=1&pwd
1643053462345: Retrieved: https://www.kingdomofloathing.com/main.php?comb=1&pwd
1643053462345: Requesting: https://www.kingdomofloathing.com/choice.php?forceoption=0
1643053462502: Retrieved: https://www.kingdomofloathing.com/choice.php?forceoption=0 (15619 bytes)
1643053462510: Requesting: https://www.kingdomofloathing.com/choice.php?whichchoice=1388&option=1&minutes=9405
1643053462709: Retrieved: https://www.kingdomofloathing.com/choice.php?whichchoice=1388&option=1&minutes=9405 (29922 bytes)
1643053462728: Requesting: https://www.kingdomofloathing.com/api.php?what=status&for=KoLmafia
1643053462806: Retrieved: https://www.kingdomofloathing.com/api.php?what=status&for=KoLmafia (4018 bytes)
1643053462873: Requesting: https://www.kingdomofloathing.com/choice.php?whichchoice=1388&option=4&coords=10%2C94048
1643053463064: Retrieved: https://www.kingdomofloathing.com/choice.php?whichchoice=1388&option=4&coords=10%2C94048 (16466 bytes)
1643053463084: Requesting: https://www.kingdomofloathing.com/api.php?what=status&for=KoLmafia
1643053463164: Retrieved: https://www.kingdomofloathing.com/api.php?what=status&for=KoLmafia (4018 bytes)
1643053463239: Requesting: https://www.kingdomofloathing.com/choice.php?whichchoice=1388&option=5&pwd
1643053463343: Retrieved: https://www.kingdomofloathing.com/choice.php?whichchoice=1388&option=5&pwd (7761 bytes)
1643053463370: Finished script: combo.js

(combo, on the other hand treats the argument "1" as "1 walk whether or not it is free".)

Sweet! I actually didn't know until I tried that JavaScript scripts were also supported. Excellent.

I guess my question is this: Would it be useful to log entering/leaving a CLI script, too? As is, a CLI script is essentially just a series of CLI commands whose source is a file, rather than the CLI.

Except, Preferences/Automation has 17 different scripts that you can specify - On Login, Pre-Adventure, and so on - and those "scripts" can be CLI or ASH or JS. Even just a CLI command (or more than one, separated by ";"). "restore hp", for example.

If you are Tracing, it might be interesting to see exactly what scripts are called during automation or when logging in, even if the are CLI scripts.
I don't actually feel strongly about this, but am wondering if anybody else even knows about "debug trace on/off" and does care.
 
K

katyarn

Member
Oh, I've always been using debug on/off but it was a bit too heavy handed to do more careful inspection due to the size of files. Getting some context in lighter weight debug files would be really useful.
 
AlbinoRhino

AlbinoRhino

Active member
I use the trace logging fairly often. Can't say I ever ran into the issue described. I guess b/c when one uses it, one usually knows just what interaction that one is trying to capture?

On the other hand, a little extra clarification could never hurt the logging any. Especially when you're trying to help someone else figure something out.
 
MCroft

MCroft

Developer
Staff member
I've been thinking about how we might revamp logging.

My goal is to make sure we have the right information in the logs for debugging without sending a lot of extra information to the gCLI. Things scroll out of the gCLI really fast, especially when a script turns on preference change logging.

These are the ideas I've toyed with:
  • Separate log levels for the log and the gCLI.
    We'd need to revamp messages to support the new levels, but we can have a default for messages that aren't updated. I'd like to see something like the Log4J levels (we could define what our levels are, but error/warn/info/debug/trace might cover it).
  • A log viewer we can open and copy things out of
    This would tie in to log levels, so we can write debug or trace logs and then show just error or warn if we want to via filter/sort options.
But none of those are directly related to the trace command.

Would it be useful to script developers/debuggers to introduce ashdebug<scriptname> and ashtrace <scriptname>, as a way to allow developers and the users they support to specify that for this run of this script, turn on debugging or tracing.

If a script calls a subscript, is it useful to have it logged? I feel as if it might be, but I'm not a script author.
 
fronobulax

fronobulax

Developer
Staff member
I am greatly frustrated when something happens, gets noted in the gCLI and then I cannot find it in the session log. My frustration leads me to use the mirror command a lot if something is repeatable and to change the code to emit something to both the gCLI and the session log upon occasion.

Script authors who use zlib already have the option to assign a level to a print message and print it, or not, based upon the verbosity setting. Given how widespread adoption isn't, I think ashdebug or ashtrace might be different but not better.

If script A is running and calls script B then script B should inherit the tracing and debugging options of A, the parent. If a JavaScripter tells me that is not what they want I would defer to their alternative.

And this is a veer from trace...
 
M

Magus_Prime

Well-known member
fronobulax said:
I am greatly frustrated when something happens, gets noted in the gCLI and then I cannot find it in the session log. My frustration leads me to use the mirror command a lot if something is repeatable and to change the code to emit something to both the gCLI and the session log upon occasion.
Click to expand...
Agree, and second, the sentiment.
 
You must log in or register to reply here.
Top