Improve debug logging in Cabal/cabal-install

[ezyang]

I spent some time with debug logging in other console applications and it gave me some thoughts about how I would go about improving debug logging in Cabal/cabal-install. One big thing about working in this space is that it is very feasible for someone new to the project to make a big difference here (this is compared to adding new features to the Cabal file format, which require much more rigor--easy to YOLO debug loggin changes!) Some thoughts here:

Design intentional output formats for internal data structures. In #6835 @danidiaz spent a lot of time going through the internal representations to look for where things "went wrong", and had to make modifications to get out the information they needed (e.g., #6835 (comment)). This shouldn't be necessary. We should aim for:

• Completeness. At a high enough debug level, it should be possible to view ALL information from the data structures, including all intermediate stages of the elaboration process. In many cases, no outputting mechanism exists for this, and you have to manually add print information. Making matters worse is when data structures have no way of printing themselves in complete form.
• Selectivity. But complete logs can be a punishingly large amount of information, so there should be clear mechanisms for selectively saying what you want the to turn the hose for, and omit everything you don't want. Cabal's integer verbosity levels do a poor job at this; for example, -v3 triggers verbose GHC output, which is rarely what you want if you're only debugging Cabal.
• Relevance. Orthogonal to completeness is giving relevant information. The default higher log levels should be designed to give you information that is likely to help you solve whatever Cabal problem you are looking at. For example, currently InstallPlan printing prints out information about all packages, both those from Hackage and those that are inplace. But you're likely to only care about the inplace packages (as those are the ones that are likely to have caused the bugs); a lower verbosity install plan view should tell you only about inplace packages. Similarly, you may not want to print out every field of an elaborated plan package; maybe only some of the fields are relevant most of the time; there should be another output format which is abridged. What to keep and what to toss out is a difficult question, and should be driven by actual bugfixes in Cabal (what would have been helpful to see to solve a bug?)

Make the log output more indexable. In many cases, debug output dumps out some data structure without any information about what the output is about. This makes it difficult to grep logs to find the debug output associated with. It should be easy to tell what code in Cabal produced any given log line. (This is made more difficult by the fact that a lot of output in the logs are multi-lined).

Add a rage mechanism. If you don't know what rage is, read my blog post http://blog.ezyang.com/2021/04/rage-bug-reporting/ When people submit bug reports, if we can make it as easy as possible for them to report verbose debug logs, even if they hadn't initially run the command with -v.

[danidiaz]

I was curious about how to implement something like this in a Haskell application, cabal-install in particular. Other desirable properties would be:

• It should not require big changes to the current internal structure and implementation of the main functions.
• It should not force a "big-bang" global change; functions should be able to opt into the "instrumentation" system one by one.
• It should not force functions to take large numbers of additional positional parameters (they have a good amount of them already!)
• The structure of import dependencies between modules should stay largely unchanged. Modules should not depend on some "central composition module" that imports everything else. (Such a "central composition module" might exist, it's just that most other modules shouldn't be aware of its existence.)
• Functions shouldn't care about the way their direct dependencies (let alone transitive ones) have been instrumented. For example, if a function f calls a function g, and g has been instrumented to send their arguments to a separate logging file, f should be completely ignorant about that file, and should not have to pass around the file handle to g.
• It should not force programmers to manually add logging statements for each function parameter.
• We should be able to instrument auxiliary functions defined in let and where clauses, not only top-level functions.

I have a working experiment in this branch. Here's the diff. I did not make a pull request because this is mostly a proof-of-concept.

After compiling cabal-install, we can activate a sample "debugger" instrumentation through an environment variable:

$ CABAL_INSTALL_INSTRUMENTATIONS=debugger cabal build

So, how does it work? There are three main new modules:

• Inspectable. A typeclass for getting a JSON representation from pretty much anything Generic. Most of the files changes are just instance Inspectable SomeType. Perhaps it could be folded into the already-existing Structured?

• Instrumentation. Functionality for intercepting and instrumenting function calls in the program logic.

• CompositionContext. It collects all the functions we want to instrument throughout the codebase, applies the instrumentations, and then wires them together with a bit of knot-tying magic.

There's also an example Debugger instrumentation. The connection with Main is done here.

Things that work well in this approach:

• Instrumented functions don't need to care about transitive dependencies. For example RebuildInstallPlan has an Instrumentator dependency, but RunProjectPreBuildPhase, which depends on it, isn't aware of Instrumentator.

• We can instrument local functions with the help of the Instrumentator newtype. An example.

• Instrumented functions have to be wrapped in newtypes, but their internal structure doesn't change very much. They don't need to add extra logging statements, either.

• No need for a big number of extra positional parameters. Only one, from which particular dependencies are extracted using the Has typeclass.

Things that don't work so well:

• Only monadic functions that end in IO actions can be instrumented right now. That will cause problems with functions that work inside LogProgress and other monads. Perhaps the functionality of LogProgress could be folded into the new approach, as just another instrumented function?

• Polymorphic functions can't be instrumented, although they can pass the composition context downwards.

• Instrumenting the pre-build phase required instrumenting all the commands that used it, so sometimes the changes aren't localized, even if we are interested in only one function.