Feature - Implemented Improved tracing of ASH script execution

Veracity

Developer
Staff member
I was very pleased when I made ASH trace its execution in the DEBUG log, many years ago. I saw it as a debugging tool for scripters. I considered having it go to a separate trace file of some sort, but since ASH scripts can make requests, and requests are logged in the DEBUG log, I put it there. So, you can see visit_url(), followed by the request/response, and then the script continuing.

I think it's time to revisit this, now that we have extremely sophisticated between battle scripts and consult scripts and such. I recently asked somebody for a DEBUG log and he gave me a 1.5 MB file which consisted of:

99% was the between battle script (which one? Who knows? We don't log the script name)
adventure.php
fight.php
api.php

I have a number of ideas:

- ASH parse trees and execution traces should go to ASH_xxx.txt, in the same directory that DEBUG and TRACE files go. There should be a way to turn that on and off, just as you can turn DEBUG and TRACE logging on and off

- When we invoke an ASH script for any reason - CLI command, between battle script, counter script, consult script - log the name in both the DEBUG and ASH files:

Starting execution of <script>

Ending execution of <script>

- When we are executing an ASH script, do a small amount of extra logging to the ASH file:

Requesting URL
Response received for URL
Following redirection to URL

You want to look at the returned text? That's the return value of visit_url and is already there in the trace

- What about gigantic strings? relay scripts, especially, do a visit_url, getting back a 8000 character string, and then they do massive amounts of string manipulation on that string - and we log all 8000 characters every time. Perhaps we want to see the output of string manipulation functions, since you can end up with something different, but do we need to see the entire input string every time? I suspect that CHIT traces are ginormous. is the debug trace usable at all for debugging CHIT?

Thoughts?
 

Fluxxdog

Active member
Suggestion: where you mention ASH_xxx.txt, I'm assuming you mean ASH plus the date stamp. Perhaps it would be beneficial to also sort by script name, since you're going to log that anyway. So ASH_ChIT_21031119.txt would keep that info separate from just every other ASH script.
 

Veracity

Developer
Staff member
That would require having a trace files associated with each ASH interpreter. That is plausible, but it's a lot harder to control when tracing is on and when it is off. I.e., when do we close the file?

For now, I submitted "debug ash on" and "debug ash off" which open a single ASH_xxx.txt file. And I moved all the parse tree logging and execution tracing to go to that file.
 

Veracity

Developer
Staff member
This now works as I desire for the DEBUG log: Every ASH script you execute is marked like this:

Starting ASH script: BestBetweenBattle.ash
Finished ASH script: BestBetweenBattle.ash
Starting recovery script: Universal_recovery.ash
Finished recovery script: Universal_recovery.ash

Things that are tagged simply as "ASH script" are the various places that simply call CLI commands to execute, and if it is an ASH script, cool. Things that HAVE to be ASH, because they are called with specific parameters - counter, consult, recovery - are identified as such. I am happy with this. It is exactly what I need to see in a DEBUG log.

The only thing I originally suggested but have not done is to put some additional logging in the ASH trace file to tersely mark requests & responses between KoLmafia and KoL. Yes, if you see a "visit_url", you can tell what is happening - sort of. You can see the original request and you can see the final response, but the redirections in the middle will be hidden. Ditto for calling "cli_execute" on one of the many commands that makes requests of KoL. Considering that the ASH program will not have a chance to determine exactly what those requests are or look at their result, showing the transactions would be informational, although perhaps useful if you want to understand all the requests your ASH script is making.

Does anybody use the verbose ASH script tracing? Do you care about what I just suggested?
 

Fluxxdog

Active member
I don't trace often.
But when I do, it's verbose.

Seriously though, having the information available could only help. Heck, it may even show changes we are unaware of, like the redirects.3 pages of details about what went wrong is better than "Something went wrong."
 

Veracity

Developer
Staff member
Revision 13316 adds Requesting: and Retrieved: lines to the ASH trace log for every request/response to KoL - even if you are not currently inside an ASH script. I'm not concerned about that, since you had to proactively turn on the ASH trace, and presumably you will look at the things that are inside the script you are trying to debug.

Unless somebody needs more, I'm declaring this done. Even if somebody does want more, it might be done, since it does what _I_ need for the DEBUG log. ;)
 
Top