actions: run: Use argv[0] for label to reduce log spam

[obbardc]

If it's not provided by the user, a label is created from the
command or script parameter which in some cases can be quite
long and can make the output more difficult to read.

Instead of using the whole command/script for the autogenerated
label, use only argv[0] of the first command to be ran to
preserve log space.

Test recipe:

architecture: amd64
actions:
  - action: run
    command: |
        echo "Testing testing 1234567890"
        echo "Testing testing 0987654321"

Log output without patch applied:

2021/08/10 12:30:21 ==== run ====
2021/08/10 12:30:21 echo "Testing testing 1234567890"
echo "Testing testing 0987654321"
 | Testing testing 1234567890
2021/08/10 12:30:21 echo "Testing testing 1234567890"
echo "Testing testing 0987654321"
 | Testing testing 0987654321

Log output with patch applied:

2021/08/10 12:30:45 ==== run ====
2021/08/10 12:30:45 echo | Testing testing 1234567890
2021/08/10 12:30:45 echo | Testing testing 0987654321

Signed-off-by: Christopher Obbard [email protected]

[evelikov]

The "label" is is different from the description tag correct? Just double-checking, since I've seen similar thing even when description tag is present.

IMHO something like below (input/output) is much cleaner and useful. What do you think, am I biased, is it possible to implement?

architecture: amd64
actions:
  - action: run
    command: |
        echo "Testing testing 1234567890"
        echo "Testing testing 0987654321"

2021/08/10 12:30:45 ==== run ====
2021/08/10 12:30:45 echo "Testing testing 1234567890"
2021/08/10 12:30:45 echo "Testing testing 0987654321"

[obbardc]

The "label" is is different from the description tag correct? Just double-checking, since I've seen similar thing even when description tag is present.

Correct, the description tag is used for the title, the label is used to prefix the command's output.
Something like:

> 2021/08/10 12:30:45 ==== <description> ====
> 2021/08/10 12:30:45 <label> | echo "Testing testing 1234567890"

IMHO something like below (input/output) is much cleaner and useful. What do you think, am I biased, is it possible to implement?

2021/08/10 12:30:45 ==== run ====
2021/08/10 12:30:45 echo "Testing testing 1234567890"
2021/08/10 12:30:45 echo "Testing testing 0987654321"

I see your point, but there no stdout is printed?

but the standard flow in debos for running commands is to show the output of a command with a meaningful label to the LHS of the command output; to show what command is running in cases where a description is missing.

I had another think about this last night; rather than trimming the label to a fixed length, I think the label should just be argv[0] of the command/script ran, so:

architecture: amd64
actions:
  - action: run
    command: |
        echo "Testing testing 1234567890"
        echo "Testing testing 0987654321"

would result in:

2021/08/10 12:30:45 ==== run ====
2021/08/10 12:30:45 echo | Testing testing 1234567890
2021/08/10 12:30:45 echo | Testing testing 0987654321

What do you think?

[evelikov]

To be perfectly honest, I'm not sure what's the best option. So let me start with illustrative example and some confusion it brings, mind you I had interactions with debos on-and-off for a month or so.

So an example like this:

  - action: run
    description: Setup plymouth
    chroot: true
    command: plymouth-set-default-theme bgrt

  - action: run
    description: Enable systemd services
    chroot: true
    command: |
      systemctl enable sshd.service
      systemctl enable sddm.service
      systemctl enable NetworkManager.service
      systemctl enable systemd-timesyncd.service
      systemctl enable docker.service
      systemctl enable grub-recordfail.service

produces output like:

2021/08/03 16:01:33 ==== Setup plymouth ====
2021/08/03 16:01:33 ==== Enable systemd services ====
2021/08/03 16:01:34 systemctl enable sshd.service
systemctl enable sddm.service
systemctl enable NetworkManager.service
systemctl enable systemd-timesyncd.service
systemctl enable docker.service
systemctl enable grub-recordfail.service
2021/08/03 16:01:34 systemctl enable sshd.service
systemctl enable sddm.service
systemctl enable NetworkManager.service
systemctl enable systemd-timesyncd.service
systemctl enable docker.service
systemctl enable grub-recordfail.service
2021/08/03 16:01:34 systemctl enable sshd.service
systemctl enable sddm.service
systemctl enable NetworkManager.service
systemctl enable systemd-timesyncd.service
systemctl enable docker.service
systemctl enable grub-recordfail.service
2021/08/03 16:01:34 systemctl enable sshd.service
systemctl enable sddm.service
systemctl enable NetworkManager.service
systemctl enable systemd-timesyncd.service
systemctl enable docker.service
systemctl enable grub-recordfail.service
2021/08/03 16:01:34 systemctl enable sshd.service
systemctl enable sddm.service
systemctl enable NetworkManager.service
systemctl enable systemd-timesyncd.service
systemctl enable docker.service
systemctl enable grub-recordfail.service
2021/08/03 16:01:34 systemctl enable sshd.service
systemctl enable sddm.service
systemctl enable NetworkManager.service
systemctl enable systemd-timesyncd.service
systemctl enable docker.service
systemctl enable grub-recordfail.service
2021/08/03 16:01:34 systemctl enable sshd.service
systemctl enable sddm.service
systemctl enable NetworkManager.service
systemctl enable systemd-timesyncd.service
systemctl enable docker.service
systemctl enable grub-recordfail.service
2021/08/03 16:01:34 systemctl enable sshd.service
systemctl enable sddm.service
systemctl enable NetworkManager.service
systemctl enable systemd-timesyncd.service
systemctl enable docker.service
systemctl enable grub-recordfail.service
2021/08/03 16:01:34 systemctl enable sshd.service
systemctl enable sddm.service
systemctl enable NetworkManager.service
systemctl enable systemd-timesyncd.service
systemctl enable docker.service
systemctl enable grub-recordfail.service

As you can see

• multi-line command produce ridiculous amount of output
• single-line command produce no output at all - what, why :sadpanda:

Something vaguely like the following would be more consistent

2021/08/03 16:01:33 ==== Setup plymouth ====
2021/08/03 16:01:33 plymouth-set-default-theme bgrt
2021/08/03 16:01:33 ==== Enable systemd services ====
2021/08/03 16:01:34 systemctl enable sddm.service
2021/08/03 16:01:34 systemctl enable NetworkManager.service
2021/08/03 16:01:34 systemctl enable systemd-timesyncd.service
2021/08/03 16:01:34 systemctl enable docker.service
2021/08/03 16:01:34 systemctl enable grub-recordfail.service

I don't have a strong preference if the command (single or block) is echoed back.

The "label" is is different from the description tag correct? Just double-checking, since I've seen similar thing even when description tag is present.

Correct, the description tag is used for the title, the label is used to prefix the command's output.
Something like:

> 2021/08/10 12:30:45 ==== <description> ====
> 2021/08/10 12:30:45 <label> | echo "Testing testing 1234567890"

Right, that explains some of the crazy I've seen in above example. Yet I'm struggling to see the "value add" that labels bring.

I see your point, but there no stdout is printed?

I don't might stdout, as long as things are not repeated more than twice. Once for the original and second (optional) echo back.

but the standard flow in debos for running commands is to show the output of a command with a meaningful label to the LHS of the command output; to show what command is running in cases where a description is missing.

Sorry if I'm conflating the description vs description-less setup. Feel free to address the description-less first (this MR) and we can consider my example at later stage.

2021/08/10 12:30:45 ==== run ====
2021/08/10 12:30:45 echo | Testing testing 1234567890
2021/08/10 12:30:45 echo | Testing testing 0987654321

What do you think?

Nearly perfect - can we move the pipe at the start/end of the line all together (see below). Having it in the middle of the command is rather misleading/confusing.

2021/08/10 12:30:45 ==== run ====
2021/08/10 12:30:45 echo Testing testing 1234567890 |
// or
2021/08/10 12:30:45 | echo Testing testing 0987654321
// also feel free to quote the whole echo command
2021/08/10 12:30:45 | "echo Testing testing 0987654321"

[obbardc]

In hindsight I think that using echo in my example is very misleading tbh.

Let's use a more interesting example of what I am considering:

  - action: run
    description: Enable systemd services
    chroot: true
    command: |
      systemctl enable sshd_fail.service
      systemctl enable sddm_fail.service
      cat /etc/systemd/system/sshd.service

should produce an output like:

2021/08/03 16:01:33 ==== Enable systemd services ====
2021/08/03 16:01:33 systemctl | Failed to enable unit: Unit file sshd_fail.service does not exist.
2021/08/03 16:01:33 systemctl | Failed to enable unit: Unit file sddm_fail.service does not exist.
2021/08/03 16:01:33 cat | [Unit]
2021/08/03 16:01:33 cat | Description=OpenBSD Secure Shell server
...

[evelikov]

Thanks for the updated example, I like it. Doing this (print "argv[0] | output[line]") indiscriminately of the length sounds reasonable IMHO.

[evelikov]

Can we get this or variant thereof merged? Currently the spam is kind of ridiculous, especially when multi-line actions are used.

[obbardc]

Closing in favour of #321