Feature - Implemented Request: Add Note to Debug Log

MCroft

MCroft

Developer
Staff member
Would it be useful to you all to have a command on the help menu that would let users (like me) add text to the debug log?

I am about to start a debug log to capture an event for an upcoming bug report and it occurred to me that it would be useful to be able to add comments like "I turned on Skip Pickpocketing here." and "now I turned it off."

Something like
Add Note to Debug Log:_____________

------
MCroft note (logdate): "Whatever I entered above."
------
 
Well, I've got 90% of it done, which was figuring out how to add a menu item, how to call an input dialog, how to send the message to the log, how to start with the menu disabled.

Now I want to figure out how to enable the menu when the debug log is started and turn it off when the debug log is stopped. We'll see how long that takes... :)

Still interested in feedback if this is valuable, could be improved, or if I'm just teaching myself stuff...
 
I spent a portion of my career where the original log files were made read only and archived as soon as possible. This suggestion makes me cringe although there is no reason for me to do so.

Question? How is the insertion point determined? If I am running one adventure at a time that is obvious, but if I am auto-adventuring for a few turns is this going to give any more than a leading or trailing comment?

Tangentially I have often wondered about recording the commands typed into the gCLI and (optionally) merging those with log. That might be an alternative way to provide similar functionality if this doesn't work as hoped.
 
I've spent a lot of my career dealing with log files that rotate daily or when they reach 4m characters, so these logs seem nice and compact.

Log files are (to my mind) streams, so the insertion is immediate. There are definitely cases that aren't the one I thought of that I should understand. I'm not sure what you'd want in terms of the insertion point, and I can't test until rollover (story of my life...). My reasonably naive implementation just gets a string from user input and calls RequestLogger.updateDebugLog(userNote);. Obviously other options could be looked into if there's a more helpful way to do it.


So, things to test:
Menu item, between commands
Menu item, auto-adventuring
Menu item, gCLI queued commands
Menu item, ash script running

Ways to extend this that I've considered after reading your thoughts:
1: add a gCLI command to do the same as the menu item. Same tests needed.
2: add an ASH function, to allow scripts to log things.
3: add an optional parameter to itrace/ptrace to allow criteria-based logging (e.g. "itrace -note 'this is where I lost my TPS!' tiny plastic sword"). I'm not sure if that's the ideal command, but something trigger/change based.
 
I just realized I am guilty of conflating the debug log and the session log so take my previous comments with a shaker of salt.

My comment was rooted in the idea that there are two asynchronous things going on. Any comment that, for example, is inserted into a verbose debug log which is logging all HTML to and from KoL is probably not going to be relevant to the lines in the immediate vicinity. I can construct scenarios where the comment doesn't end up in a useful place. What I have not done is any experimentation to prove or disprove the existence of those scenarios.

On several occasions I have seen something in the gCLI, not found it in the session log and changed KoLmafia to write the information in both places. An obvious solution would be to make the gCLI output and the session log mirrors. That let's a scripter insert using print, for example. Buy the gCLI supports and renders HTML and the session log is deliberately kept to be plain, human readable text. So HTML in the gCLI is deprecated, something renders the HTML before writing to the session log or the session log is allowed to contain HTML. The benefits of any of these, minus the cost of implementing them, have not seemed to exceed the benefits of the status quo.
 
For what it's worth, it inserts the comment in the middle of the sequence when auto-adventuring or maximizing. That makes sense: it calls updateDebugLog(), which writes out what it gets.

And of course it may not be useful information or in the right place, but that's true of anything in bug reports. That's true of my own bug reports in this forum and I am a supposedly-trained tester. I just had one where Veracity had to tell me what I was seeing was a red herring (it was two different issues).

In terms of merging gCLI and session, Would you want to add a HTML-to-plaintext library, like jsoup or Jericho? Is it valuable to mark which lines come from which source?

A gCLI print (or similar log note) could still be"in the wrong place", because the gCLI queues commands to run after auto-adventuring, but that gets into "we can probably find a way to make it do something wrong for some circumstances".

If the session log and debug log are easy to compare and gCLI entries and responses go into session log, then I can already do what I want with ashq print("this is my user note"). It might be better to separate out an explicit log command, but there are already a lot of commands.
 
Sorry. Used a "DRINK ME" potion and wandered about looking at the differences between the session log and the debug log and asking why? I got an answer I can live with but I asked.

If your experiments put the comment in a useful place in the debug log then it is worth continuing.

I will expend a lot of effort to avoid dealing with Swing. There's a lot I never really understood and when I had to write it anyway I had access to both in house UI standards and a third party library that handled the fiddly bits.

So I wonder about a (new?) ash command boolean write_to_debug_log(userNote). All it really does is RequestLogger.updateDebugLog(userNote). The return value is true if the string was written and false otherwise. For 99.44% of the cases I can think of (and easily check for) false is equivalent to "debugging is not turned on".

void main(String userNote) {
boolean ok = write_to_debug_log(userNote);
}

as a script can be invoked several ways and if the user doesn't specific the note, they will be asked for it.

This needs a little more thought since turning on debugging will create a new file or append to an existing file AND set a flag that enables additional information to be logged. I can see cases where I want to write a note to a debug log even if the extra logging for debugging is off. I would also want to think about whether this introduces a new threat vector (as compared to using map_to_file, for example) and make sure the implementation dealt with that.

One argument reducing my motivation for aligning the gCLI and session log is the existence of the mirror command. Turn it on in the login script and off in the logout script. Have a filename convention and then use OS scripting to rename and/or remove mirror files as necessary. A diff between the session log and the mirror log would be interesting and identify places where mafia could be changed.

As far as the session log goes I would also investigate the cli commands logecho and logprint.
 
Hey, no worries. We're discussing something that users will be a producer of and devs are the consumers of, and which I've got mostly implemented, but which I want to understand what would be most useful to you all, so I can either make a patch that works or which devs can review, fix, and I can compare to mine and learn something from.

So, time is not of the essence here. :). Anyway, apologies that this is sorta long.

It occurred to me that there were (at least!) three ways to handle debug commands with debug off
  1. Error/Return False/Disable the menu item
  2. Turn on Debug log and log as requested (implicit activation)
  3. Turn on Debug Log, write entry, turn off debug log (temporary activation)

My (as yet unimplemented plan) for the GUI was to disable the note command unless the log was active. I am naively convinced I can figure out how to modify the Debug menu item to also toggle the enabled/disabled field of the DebugNote menu item. I could also leave it enabled and check for isDebugging() and respond with an error if false. I might want to do that anyway, incase the debug command is invoked/disabled outside of the menu. (Aside: I noticed that I can start the debug log in the gCLI, but it doesn't toggle the Help menu from Start to Stop. Probably nobody ever starts in the gCLI and stops from the menu, but it does seem inconsistent.)

updateDebugLog() seems to write to a predictable but not user-selectable file, and inserts a lot of header info, so I don't see a way to get it to do something nefarious at the OS level, like write a preference, script, or . We could have a truncate function to keep it to a maximum length or any other filtering effect we thought was needed (URLEncoding?). From prior log experience, we might want to make sure the log couldn't have the user credentials in them, but I'm not sure that the debug log doesn't already have them and I'm not sure if ash has the password as a variable anyway.

As far as an ash command, boolean write_to_debug_log(userNote) sounds right to me.
Code: 
All it really does is RequestLogger.updateDebugLog(userNote). The return value is true if the string was written and false otherwise. For 99.44% of the cases I can think of (and easily check for) false is equivalent to "debugging is not turned on".
isDebugging() lets you test for that fast and return early, 99.44% of the time. You could also try to aggressively turn on the log, depending on the design philosophy. Same options as listed above, but ash gets its own thinking/consideration...

Other (hard to test) cases are file deleted/partition full/out of file handles/drive dismounted/any of the normal log writing failure causes, but other things are probably failing by that point.

updateDebugLog has 4 method signatures:
public static final void updateDebugLog()
public static final void updateDebugLog( final String line )
public static final void updateDebugLog( final Throwable t )
public static final void updateDebugLog( final Object o )

If you want to skip the blank and instead prompt for a String (or something else that will give a string via o.toString()), that's reasonable and Ash only really has to support methods 2 and 4. And 2 may reasonably collapse into 4, because java supports String.toString() (probably for just this case).

For my menu-based command, I was sending "-----\n${UserNote}\n-----", but I don't think you'd want that from the ash command.

Anything else you think I should consider?
 
Still processing coffee so...

I really need to confirm that if the debug file already exists then toggling debug on will append. If so I can see a case where you want to stop debugging, insert a comment and start debugging again. That means the proposed ash command should save the value of the debugging flag, set it to true (implicitly creating or opening the file as needed), write to the log and then set the flag to the original value (implicitly closing the file if needed).

Upon further consideration I don't see a new threat from a user controlled write to the debug file.

If we use existing code to open, close and write I am not concerned about all the stuff that could happen at the OS level that would make the process fail. We will protect and detect however we did before and that is OK with me, in spite of my personal tendency to over-engineer things in response to low probability situations.

I'm not sure (at least for v1.0) there is much of a case for passing anything but a string to updateDebugLog. Since the goal is human readable info in a file and the initial approach was to get a string from the user that should be fine. ASH can work around the limitation by using toString on any thing it has access to. If you are proposing a GUI element that lets a user select an arbitrary object and send it to the log (where it will be toString'ed anyway) then maybe we step back and focus on the requirements - what is needed as opposed to what could be done :-)

Remember that this is your project. No one else seems to be interested enough to ask for it or ask that it not be done. So whenever you get a patch I will review and submit. To the extent that I can help write it you may certainly ask but...

:-)
 
Thanks, it's been helpful to just talk about it. I think I'd want to restrict the ash function to strings, on the grounds that scripters can do their own type conversions in ash.

testing updateDebugLog() when debug is off:
in either case does nothing. It returns void, so the ash version will need to check isDebugging() itself. That's fine.

testing DebugNoteMenuItem (my menu item) when debug is off:
If no log file, create debug log file, append header and note, then turn debugging back off.
If existing log file, append header and note to existing debug file, then turn debugging back off.

I want to keep it off (on the principle of "do exactly what you're told". Also to save me changing the menu item

However, I do want to have the ability to set the Start/Stop Debug item in cases where ash or the gCLI has toggled debug, so I have to figure out how to change a menu item in response to a different command. That should be fun.

I'll be back when I've got further or stuck.
 
I'm working my way around Listener. It definitely seems like the right approach. I've registered and fired a listener, but it's not actually calling my update(). Still more looking around to do. I don't think I've successfully registered it, if what I see in the debugger is correct.

What I've got so far:
  1. Global Menu: new helper menu item that adds a note to the debug log. If Logging is Off, sets debug logging state on, updates with note, then sets logging state off.
  2. gCLI additions to existing debug command
    • debug note <User Note> If <User Note> is not empty, follow on/off logic for global menu item for adding note.
    • debug ? Responds with "Debugging is ON" if isDebugging() is true, else "Debugging is OFF"
    • debug trace ? Responds with "Tracing is ON" if isTracing() is true, else "Tracing is OFF"
  3. ash command debugprint(String log), parallel to logprint and traceprint. Returns silently if debug log is off.

So I've accomplished 3 of my 4 tasks, and am just working on changing the menu when the log starts for a reason other than the menu item was touched.

My eventual thoughts on the ash command was "do it like the others". Since there's an ash command, there's also a debug print in the gCLI that works like the ash command. We may not need "note", although I like the stronger "do what you were told" logic that I implemented.

In debugging the menu item, I found that GlobalMenuBar is created 10 times which isn't a problem unless you're registering a Listener in a menu item and maybe not then if you've done it right. :) It seems like if it is a global menu bar, maybe a singleton would make more sense? It's only called (AFAICT) from GenericFrame.java and CreateFrameRunnable.java
 
solved my listener problem.

patch and zip of src/net/sourceforge/kolmafia/swingui/menu/DebugLogNoteMenuItem.java are attached.
View attachment DebugMenuItem.patch and View attachment DebugLogNoteMenuItem.java.zip

embarrassingly, I can't figure out how to add a new file to a diff if I can't add the file to SVN, so it's separate.

I add a new listener to the NamedRegistryListener "(debug)". Debug is fired by RequestLogger and kicks off update() in the DebugMenuItem class. It fires when the debug log is stopped or started, and it reads RequestLogger.isDebugging() and sets the menu item accordingly. It doesn't matter how we get to RequestLogger, the menu item reflects the current debugging state at the last change.

There's some copied code and some places might be verbose, but it seems like it's working and resilient. Let me know if you have any changes you want me to make.


Code: 
=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=
              KoLmafia v20.7, Mac OS X, Java 13.0.2
=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=
 Please note: do not post this log in the KoLmafia thread of KoL's
 Gameplay-Discussion forum. If you would like the KoLmafia dev team
 to look at it, please write a bug report at kolmafia.us. Include
 specific information about what you were doing when you made this
 and include this log as an attachment.
=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=
 Timestamp: Tue Oct 06 21:58:58 CDT 2020
=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=
 User: Darwinlet
 Current run: 537
 MRU Script: Unknown
=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=


-----User Note: Tue Oct 06 21:58:58 CDT 2020-----
I am a note from the menu.
-----


=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=
              KoLmafia v20.7, Mac OS X, Java 13.0.2
=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=
 Please note: do not post this log in the KoLmafia thread of KoL's
 Gameplay-Discussion forum. If you would like the KoLmafia dev team
 to look at it, please write a bug report at kolmafia.us. Include
 specific information about what you were doing when you made this
 and include this log as an attachment.
=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=
 Timestamp: Tue Oct 06 21:59:24 CDT 2020
=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=
 User: Darwinlet
 Current run: 537
 MRU Script: Unknown
=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=


-----User Note: Tue Oct 06 21:59:24 CDT 2020-----
I am a note from the gCLI...
-----


=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=
              KoLmafia v20.7, Mac OS X, Java 13.0.2
=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=
 Please note: do not post this log in the KoLmafia thread of KoL's
 Gameplay-Discussion forum. If you would like the KoLmafia dev team
 to look at it, please write a bug report at kolmafia.us. Include
 specific information about what you were doing when you made this
 and include this log as an attachment.
=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=
 Timestamp: Tue Oct 06 21:59:38 CDT 2020
=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=
 User: Darwinlet
 Current run: 537
 MRU Script: Unknown
=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=


> debug note I am a note after debug has been turned on...

-----User Note: Tue Oct 06 21:59:53 CDT 2020-----
I am a note after debug has been turned on...
-----
> ash debugprint("and I am a note from ash...");

-----User Note: Tue Oct 06 22:00:14 CDT 2020-----
and I am a note from ash...
-----
Returned: void

=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=
              KoLmafia v20.7, Mac OS X, Java 13.0.2
=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=
 Please note: do not post this log in the KoLmafia thread of KoL's
 Gameplay-Discussion forum. If you would like the KoLmafia dev team
 to look at it, please write a bug report at kolmafia.us. Include
 specific information about what you were doing when you made this
 and include this log as an attachment.
=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=
 Timestamp: Tue Oct 06 22:18:45 CDT 2020
=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=
 User: Darwinlet
 Current run: 537
 MRU Script: Unknown
=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=


> help debug

debug [on] | off | ? | note | trace [ [on] | off | ? ] | ash [ [on] | off ] | listener [ [on] | off ] - start or stop logging of debugging data.
[...]
> debug off
 
Please review patch

this patch is complete if anyone is available to review it.

In addition to the feature I wanted, it also makes the debug menu item sync with the debug on/off state when you start it from the gCLI, so some improvements and some newness.
 
MCroft said:
this patch is complete if anyone is available to review it.

In addition to the feature I wanted, it also makes the debug menu item sync with the debug on/off state when you start it from the gCLI, so some improvements and some newness.
Click to expand...

Downloaded it. No promises. To maintain plausible deniability, you have tested this within an inch (no metric for me) of its life, right? So I can focus on code and style and minimal functionality?

I use TortoiseSVN. There is a command to add a new file. You use it when you want to include a previously non-existent file in the next commit. My recollection is that files so added are included when building a patch. Not sure what you are using but there has to be an equivalent command.
 
Patch doesn't apply and is taking more time than I want to give to force it.

Would you consider adding the new file and then recreating the patch. The root of my Kolmafia source tree is D:\kolmafia and people have had the best results with my patches if that is the directory I start from when I make the patch.
 
sure, I'll work on a better patch. I definitely don't want to make this hard, since you're doing me a favor by reviewing this.

I was thinking I can't add files because I don't have commit rights, but I may be overthinking things.
 
The "commit rights" only matter when you try to commit. Setting up a commit by editing files - and adding new ones - should be possible regardless.
 
and of course, now that I second-guess myself, it's obvious. You add file and it stages it locally and it appears in patches.
My test of the (new) patch: View attachment DebugNotes.patch
1: get a clean instance of KoLmafia ("instance3", in my case) & update it.
2: put the patch in the top level KoLmafia directory (next to src and build.xml).
3: patch -p0 <DebugNotes.patch
4: ant daily
5: java -jar dist/KoL*.jar

Then I could check out the ask, gCLI, and menu items.

Code: 
Michaels-MBP:projects mcroft$ cd instance3
Michaels-MBP:instance3 mcroft$ ls
bin                build.xml          default.properties kolmafia.iml       src                util
build.properties   data               devdoc             lib                test
Michaels-MBP:instance3 mcroft$ ant update
Buildfile: /Users/mcroft/projects/instance3/build.xml

update:
     [exec] Updating '.':
[...]
     [exec] Updated to revision 20471.

BUILD SUCCESSFUL
Total time: 1 second
Michaels-MBP:instance3 mcroft$ svn diff

Michaels-MBP:instance3 mcroft$ cp ../kolmafia/DebugNotes.patch DebugNotes.patch

Michaels-MBP:instance3 mcroft$ patch -p0 <DebugNotes.patch 
patching file src/net/sourceforge/kolmafia/swingui/menu/DebugLogMenuItem.java
patching file src/net/sourceforge/kolmafia/swingui/menu/DebugLogNoteMenuItem.java
patching file src/net/sourceforge/kolmafia/swingui/menu/GlobalMenuBar.java
patching file src/net/sourceforge/kolmafia/textui/command/DebugRequestCommand.java
patching file src/net/sourceforge/kolmafia/textui/RuntimeLibrary.java
patching file src/net/sourceforge/kolmafia/RequestLogger.java
Michaels-MBP:instance3 mcroft$ ant daily
Buildfile: /Users/mcroft/projects/instance3/build.xml

[...]

BUILD SUCCESSFUL
Total time: 24 seconds

Michaels-MBP:instance3 mcroft$ java -jar dist/KoLmafia-20471M.jar

KoLmafia v20.7 r20471
Released on July 30, 2020

Currently Running on Mac OS X
Local Directory is /Users/mcroft/Library/Application Support/KoLmafia
Using Java 13.0.2

Michaels-MBP:instance3 mcroft$
 
You must log in or register to reply here.
Back
Top