[bug] pebble "enter" keeps logging, with unexpected indentation, when combined with "exec"

[cjdcordeiro]

Description

When using pebble enter (which is the case for all rocks), Pebble will keep logging to STDOUT, regardless of the provided subcommand.

Not only that, but it appears that there's also a flushing problem, as the logs come out with a weird indentation.

Reproduce

1. create a noisy check

summary: test
description: test

checks:
  foo:
    override: replace
    period: 2s
    exec:
      command: fail

2. run pebble enter --verbose exec -it bash

Here's the problem:

cris@cris-laptop:~ $ pebble enter --verbose exec -it bash
2023-12-07T15:22:32.934Z [pebble] Started daemon.
2023-12-07T15:22:32.939Z [pebble] POST /v1/exec 4.734384ms 202
                                                              2023-12-07T15:22:32.943Z [pebble] GET /v1/tasks/36/websocket/control 3.656673ms 200
                                                                                                                                                 2023-12-07T15:22:32.943Z [pebble] GET /v1/tasks/36/websocket/stdio 29.98µs 200
                                                                                                                                                                                                                               cris@cris-laptop:~ $ 2023-12-07T15:22:34.935Z [pebble] Check "foo" failure 1 (threshold 3): exec: "fail": executable file not found in $PATH
                                                                                 2023-12-07T15:22:36.935Z [pebble] Check "foo" failure 2 (threshold 3): exec: "fail": executable file not found in $PATH

cris@cris-laptop:~ $ 
cris@cris-laptop:~ $ 
cris@cris-laptop:~ $ 
cris@cris-laptop:~ $ 2023-12-07T15:22:38.935Z [pebble] Check "foo" failure 3 (threshold 3): exec: "fail": executable file not found in $PATH
                                                                                                                                            2023-12-07T15:22:38.935Z [pebble] Check "foo" failure threshold 3 hit, triggering action

cris@cris-laptop:~ $ 
cris@cris-laptop:~ $ 
cris@cris-laptop:~ $ date
Thu Dec  7 04:22:40 PM CET 2023
cris@cris-laptop:~ $ 2023-12-07T15:22:40.936Z [pebble] Check "foo" failure 4 (threshold 3): exec: "fail": executable file not found in $PATH
                                                                                                                                            2023-12-07T15:22:42.935Z [pebble] Check "foo" failure 5 (threshold 3): exec: "fail": executable file not found in $PATH
                                                                                                                                                                                                                                                                   ^C
cris@cris-laptop:~ $ 2023-12-07T15:22:44.936Z [pebble] Check "foo" failure 6 (threshold 3): exec: "fail": executable file not found in $PATH

exit
2023-12-07T15:22:45.277Z [pebble] GET /v1/changes/36/wait 12.333227355s 200
                                                                           cris@cris-laptop:~ $ 

Proposal

Do not print logs when pebble enter exec (especially if exec is running in interactive mode)

[cjdcordeiro]

(fyi @rebornplusplus )

[benhoyt]

The indentation thing is interesting. It has something to do with how the terminal device driver automatically injects CR before LF when output is written (and we're using a PTY / pseudo-terminal here). I haven't figured out the details yet, but see more at https://unix.stackexchange.com/a/151963

Not also that logs go to stderr, not stdout (I'll change that in the issue description).

I'm not sure just disabling logs is what we want here, or what the fix for the CR/LF issue is. Do you have time to investigate further? I think there's enough subtlety here that it's worth writing a one-pager spec on your findings and a proposed fix so we can discuss further.

[cjdcordeiro]

thanks for the stderr fix.

I think disabling the logs is the expected UX. Especially if the user is interacting with the exec command. the CR/LF fix could be acceptable if one is doing docker run <img> exec <cmd>. However, with docker run -it <img> --run exec -it <cmd> I'd like not to have the underlying logs pollute the interactive terminal.

[benhoyt]

Closing this issue, as this is being addressed by removing --verbose as the default in Rock entrypoints: https://github.com/canonical/rockcraft/pull/495

[cjdcordeiro]

@benhoyt this is still gonna be addressed as https://github.com/canonical/rockcraft/pull/495 just makes this issue harder to notice, but it is still there. The idea is to completely disallow --verbose to be used with enter exec

[benhoyt]

Got it -- in that case, re-opening.

[benhoyt]

Closing this Pebble issue as it's not really a Pebble problem as such, and will be addressed when https://github.com/canonical/rockcraft/pull/495 is merged.

[cjdcordeiro]

You should re-open @benhoyt , given the reason mentioned above https://github.com/canonical/pebble/issues/339#issuecomment-1993739443

[benhoyt]

Oops, re-opening until #394 is merged.