As our team continues to mature and utilize logging more, we are looking at logging the execution of all of Commands. We believe this will help give us insight into determining what’s happening, when, and why.
In fact, for Crescendo, we already did this somewhat by adding logging commands in sequence with the Commands that we wanted to trace, mostly in our autonomous routine commands. However, this muddies up the code, and we are looking for a way to do this cleanly, automatically, and consistently.
Last night we tested using CommandScheduler.onCommandInitialize and the liked to log commands. We really like how this allowed up to clean up our code. However, our testing helped us realize that such callbacks only allow us to log the commands that are actually going through the CommandScheduler; composed commands in parallel and sequential command groups won’t be logged with that approach. That doesn’t suffice for us, because we really want to be able to see the execution of pieces of our auto routines, for example.
We thought about extending Command to something like LoggedCommand, and using that in place of Command everywhere. Such a class would “self-log”, and we’d be able to see the full picture of what’s executing, regardless of how it is being triggered. However, we might also need to extend methods like alongWith, andThen and deadlineWith to produce LoggedCommands, and moreover replicate/wrap the functionality of the various Commands factories, lest they product unlogged commands.
I expect we are not the the only team that would like this implicit logging of Command scheduling/execution. Are there any other approaches that teams have used successfully, or maybe existing reference implementations of such logging?
So, in kotlin you could do an extension method that’s like Command.logged() that would add a logger call before and after it, this doesn’t help you though unfortunately, I’m assuming you’re a java team
The new best practices suggest using Triggers instead of composing big commands. That way you also have more commands scheduled by the scheduler and more commands will be logged by onCommandInitialize().
The challenge with making this useful is that the decorator-based approach creates lots of commands, many of which are nested, and all of which are unnamed. This poses a problem for both visualization (e.g. showing what commands are running in a useful way, particularly showing the current state within a more complex command sequence) and logging (it’s not terribly informative to just use the class name or a class instance reference/pointer). We’d love to have this as a standard feature but haven’t figured out a good way to make it useful without requiring people provide string names everywhere (including when calling decorators), which gets incredibly annoying very quickly. Java doesn’t provide a mechanism to e.g. get callsite line and column for method calls (it’s possible to get line numbers with some work, but not column numbers, which is important for method chaining).
FWIW, commandsv3 solves this by returning builder objects from the factory methods, instead of a command that can be wrapped to provide a name, and by having command compositions run all composed commands through the scheduler instead of managing them internally. This would be possible to backport to the current command framework if anyone wanted to give it a stab
FWIW, as part of the branch where we experimenting with this (i.e., using CommandScheduler.on*, prior to realizing the limitations), we added a decent amount of .withName() invocations to assign names where there were not ones implicitly. I personally didn’t really mine that much, and still felt it left the code pretty clean.
We were very disappointed that all the commands were not logged. I think the situation is another version of the 80-20 rule. Command-based gives you 80% of what you want with only 20% of your effort. Getting the last 20% is painful.
If you want to begin to explore using triggers to disjoint a sequence you are invited to jump into Group Disjoint Test. It’s not a tutorial but shows how to run a long sequence of commands disjointed by either proxy or triggers. It’s NOT a perfect solution and comments in the code describe some pitfalls.
Backporting some of the features from commandsv3, presumably. The only thing really unique to v3 is coroutines; everything else could be used just as easily with the current commands framework
This isn’t exactly what you want and I haven’t tested it but I thought of it on my drive to my parents for Thanksgiving and didn’t want to forget.
Create a LoggedCommand static method that returns a command and takes in a command as an argument.
The method just returns a new deadlineFor group with a command that logs the name of the command argument during its initialize and end, or something like that.
If you create most of your commands from methods in your subsystems, those methods could return the LoggedCommands and so then even when you combine them into command groups it’s still logging each of the subsystem generated command calls.
It’s breaks if you’re trying to add logging to instances of already composed commands I think.
You could also make a LoggedWaitCommand, or any other commands you needed to log.
As a heads up: Extension methods in kotlin are basically syntax sugar over static “util” methods. This means that command.logged() in kotlin can be accomplished by CommandUtil.logged(command) and the like.
So, i think there is a very easy intermediate solution here, which is to make the various decorators call withName with an appropriate generic command name (e.g. race, sequence, wait, etc) combined with the above-mentioned Sendable integration so that command groups report their component behavior over telemetry.
This should allow sensible reading of command telemetry so long as the user provides at least one sensible name at the outermost layer of their command definition. There’s no way to force users to do this, nor to really do it with reflection, but that’s…not an uncommon amount of inconvenience for a Java API.
No; the implementing components can have solution-space naming and that is fine. What is important is that the top level be named identifiably, and the components under that at worst match the declaration structure in code. Currently this latter condition is violated, because the decorators yield classnames by default that do not necessarily tell you which decorator was used.
If the components themselves have problem-space names, so much the better - and if you are also using them independently and following this convention, they will. But it is not necessary.
For some quick and dirty tracing output I’ve printed an object’s toString(). The hex digits while unique are a pain to recognize quickly the different objects by eye. Automatic names something like THIS could be very helpful. Still need a known “anchor” to the code for the group, though, such as a user specified name or line number.
I see Java has a column number but it is compiler dependent and our compiler doesn’t have it as Peter Johnson pointed out.