How to get the nicer logs when running limactl from another program?

[nirs]

Looks like limactl (logrus?) automatically disable timestamps and levels and show only the message, and does not quote " in the message when logging to a terminal, but when redirecting to file we get to much info we don't need in machine unfriendly format, and extra quoting in messages.

Example log when using the terminal:

$ limactl start --vm-type vz --plain --tty=false
INFO[0000] Terminal is not available, proceeding without opening an editor 
WARN[0000] `vmType: vz` is experimental                 
INFO[0000] Starting the instance "default" with VM driver "vz" 
INFO[0000] Attempting to download the image              arch=aarch64 digest="sha256:5ecac6447be66a164626744a87a27fd4e6c6606dc683e0a233870af63df4276a" location="https://cloud-images.ubuntu.com/releases/24.04/release-20240821/ubuntu-24.04-server-cloudimg-arm64.img"
INFO[0000] Using cache "/Users/nsoffer/Library/Caches/lima/download/by-url-sha256/346ee1ff9e381b78ba08e2a29445960b5cd31c51f896fc346b82e26e345a5b9a/data" 
INFO[0000] Converting "/Users/nsoffer/.lima/default/basedisk" (qcow2) to a raw disk "/Users/nsoffer/.lima/default/diffdisk" 
...

Same when redirecting to file:

$ limactl start --vm-type vz --plain --tty=false 2>file.log
time="2024-09-01T22:03:03+03:00" level=warning msg="`vmType: vz` is experimental"
time="2024-09-01T22:03:03+03:00" level=info msg="Starting the instance \"default\" with VM driver \"vz\""
time="2024-09-01T22:03:03+03:00" level=info msg="Attempting to download the image" arch=aarch64 digest="sha256:5ecac6447be66a164626744a87a27fd4e6c6606dc683e0a233870af63df4276a" location="https://cloud-images.ubuntu.com/releases/24.04/release-20240821/ubuntu-24.04-server-cloudimg-arm64.img"
time="2024-09-01T22:03:03+03:00" level=info msg="Using cache \"/Users/nsoffer/Library/Caches/lima/download/by-url-sha256/346ee1ff9e381b78ba08e2a29445960b5cd31c51f896fc346b82e26e345a5b9a/data\""
time="2024-09-01T22:03:03+03:00" level=info msg="Converting \"/Users/nsoffer/.lima/default/basedisk\" (qcow2) to a raw disk \"/Users/nsoffer/.lima/default/diffdisk\""
...

My use case - running limactl from another tool, adding its own timestamps and log levels. Here is example logs from the tool:

% drenv start envs/vm.yaml -v
2024-09-01 21:49:16,582 INFO    [vm] Starting environment
2024-09-01 21:49:16,583 DEBUG   [main] Add executor profiles
2024-09-01 21:49:16,584 DEBUG   [cluster] Running ('/Users/nsoffer/src/lima/_output/bin/limactl', 'list', '--format', '{{.Name}}')
2024-09-01 21:49:16,603 INFO    [cluster] Starting lima cluster
2024-09-01 21:49:16,603 DEBUG   [cluster] Running ('/Users/nsoffer/src/lima/_output/bin/limactl', 'list', '--format', '{{.Name}}')
2024-09-01 21:49:16,633 DEBUG   [cluster] Running ('/Users/nsoffer/src/lima/_output/bin/limactl', 'create', '--name', 'cluster', '/var/folders/qs/_z10qgxn3gsfw8vmkr9b3s4w0000gn/T/drenv.lima.cluster.tmpe37ne8tn')
2024-09-01 21:49:16,647 DEBUG   [cluster] time="2024-09-01T21:49:16+03:00" level=info msg="Terminal is not available, proceeding without opening an editor"
2024-09-01 21:49:16,661 DEBUG   [cluster] time="2024-09-01T21:49:16+03:00" level=info msg="Attempting to download the image" arch=aarch64 digest= location="https://cloud-images.ubuntu.com/releases/24.04/release/ubuntu-24.04-server-cloudimg-arm64.img"
2024-09-01 21:49:16,661 DEBUG   [cluster] time="2024-09-01T21:49:16+03:00" level=info msg="Using cache \"/Users/nsoffer/Library/Caches/lima/download/by-url-sha256/002fbe468673695a2206b26723b1a077a71629001a5b94efd8ea1580e1c3dd06/data\""
2024-09-01 21:49:16,662 DEBUG   [cluster] time="2024-09-01T21:49:16+03:00" level=info msg="Converting \"/Users/nsoffer/.lima/cluster/basedisk\" (qcow2) to a raw disk \"/Users/nsoffer/.lima/cluster/diffdisk\""
...

The log format I would like to have is:

`vmType: vz` is experimental                 
Starting the instance "default" with VM driver "vz" 
...

Or even better, jsonlines format, so I can extract only what I need from the logs:

{"time":"2024-09-01T22:03:03+03:00","level":"warning","msg":"`vmType: vz` is experimental"}
{"time":"2024-09-01T22:03:03+03:00","level":"info","msg":"Starting the instance \"default\" with VM driver \"vz\""}

A program running limactl should be able to control the logs from limactl. Maybe we need a new option like --log-raw to just get the raw messages from limactl, or --log-format=json?

[jandubois]

This just requires a custom logrus.TextFormatter.

or --log-format=json?

Can be done with logrus.JSONFormatter.

So --log-format seems fine to me, with default, raw, and json being the options to implement, and it allows us to define additional formats, if necessary.

However, I think raw is the wrong name for something that shows only the messages. And then I wonder if you wouldn't still want to see the additional fields. E.g. your raw would turn

"Attempting to download the image" arch=aarch64 digest="sha256:5ecac6447be66a164626744a87a27fd4e6c6606dc683e0a233870af63df4276a" location="https://cloud-images.ubuntu.com/releases/24.04/release-20240821/ubuntu-24.04-server-cloudimg-arm64.img"

into

Attempting to download the image

as arch, digest, and location are separate fields and not part of the msg.

So maybe just supporting json and leaving the rest to the user is a better choice.

[nirs]

Good point - the extra fields may be wanted. So json is seems like the best way for consuming by a program.

I can try to add

--log-format  format logs in "text" or "json" formats (default "text")

[nirs]

I tried this change - it seem to work for start/stop/delete/list. I'll do more testing and send a PR later.

--- a/cmd/limactl/main.go
+++ b/cmd/limactl/main.go
@@ -60,6 +60,7 @@ func newApp() *cobra.Command {
                DisableAutoGenTag: true,
        }
        rootCmd.PersistentFlags().String("log-level", "", "Set the logging level [trace, debug, info, warn, error]")
+       rootCmd.PersistentFlags().String("log-format", "", "Set the logging format [text, json] (default text)")
        rootCmd.PersistentFlags().Bool("debug", false, "debug mode")
        // TODO: "survey" does not support using cygwin terminal on windows yet
        rootCmd.PersistentFlags().Bool("tty", isatty.IsTerminal(os.Stdout.Fd()), "Enable TUI interactions such as opening an editor. Defaults to true when stdout is a terminal. Set to false for automation.")
@@ -72,6 +73,18 @@ func newApp() *cobra.Command {
                        }
                        logrus.SetLevel(lvl)
                }
+
+               logFormat, _ := cmd.Flags().GetString("log-format")
+               switch logFormat {
+               case "json":
+                       formatter := new(logrus.JSONFormatter)
+                       logrus.StandardLogger().SetFormatter(formatter)
+               case "text", "":
+                       // logrus default
+               default:
+                       return fmt.Errorf("unsupported log-format: %q", logFormat)
+               }
+
                debug, _ := cmd.Flags().GetBool("debug")
                if debug {
                        logrus.SetLevel(logrus.DebugLevel)

One issue - the progress breaks the log: #2581

[nirs]

Resolved since #2584