Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Shell provisioner output all messed up #11047

Closed
rgl opened this issue Sep 1, 2019 · 5 comments · Fixed by #12437
Closed

Shell provisioner output all messed up #11047

rgl opened this issue Sep 1, 2019 · 5 comments · Fixed by #12437

Comments

@rgl
Copy link
Contributor

rgl commented Sep 1, 2019

Vagrant version

Vagrant 2.2.5

Host operating system

Ubuntu 18.04.3 LTS

Guest operating system

Ubuntu 18.04.3 LTS

Vagrantfile

You just need to add a normal config.vm.provision step, e.g.:

config.vm.provision 'shell', path: 'provision-kubernetes-master.sh'

The full Vagranfile is at https://github.com/rgl/kubernetes-ubuntu-vagrant/blob/master/Vagrantfile.

Expected behavior

==> km1: NAME                                                                   AGE
==> km1: admin                                                                  48m
==> km1: cluster-admin                                                          48m
==> km1: edit                                                                   48m
==> km1: kube-router                                                            48m
==> km1: kubernetes-dashboard                                                   48m
==> km1: system:aggregate-to-admin                                              48m
==> km1: system:aggregate-to-edit                                               48m
==> km1: system:aggregate-to-view                                               48m
==> km1: system:auth-delegator                                                  48m
==> km1: system:basic-user                                                      48m
==> km1: system:certificates.k8s.io:certificatesigningrequests:nodeclient       48m
==> km1: system:certificates.k8s.io:certificatesigningrequests:selfnodeclient   48m
==> km1: system:controller:attachdetach-controller                              48m
==> km1: system:controller:certificate-controller                               48m
==> km1: system:controller:clusterrole-aggregation-controller                   48m
==> km1: system:controller:cronjob-controller                                   48m
==> km1: system:controller:daemon-set-controller                                48m
==> km1: system:controller:deployment-controller                                48m
==> km1: system:controller:disruption-controller                                48m

Actual behavior

The output is all messed up, it seems that vagrant is not correctly interpreting the new lines or just dumps the whole output buffer when its full without regarding whether its tail has a new line or not, and thus, forces a new line. At least it seems that what is happening by looking at the garbled/messed output (the output should be two perfect columns of text like displayed in the Expected behavior section):

==> km1: NAME                                                                   AGE
==> km1: admin                                                                
==> km1:   48m
==> km1: cluster-admin                                                          48m
==> km1: edit                                                                   48m
==> km1: kube-router                                
==> km1:                             48m
==> km1: kubernetes-dashboard                                                   48m
==> km1: system:aggregate-to-admin                                              48m
==> km1: system:aggregate-to-edit                                               48m
==> km1: system:aggregate-to-view                                               48m
==> km1: system:auth-delegator                                                  48m
==> km1: system:basic-user                                                      48m
==> km1: system:certificates.k8s.io:certificatesigningrequests:nodeclient       48m
==> km1: system:certificates.k8s.io:certificatesigningrequests:selfnodeclient   48m
==> km1: system:controller:attachdetach-controller                              48m
==> km1: system:controller:certificate-controller                               48m
==> km1: system:controller:clusterrole-aggregation-controller                   48m
==> km1: system:controller:cronjob-controller                
==> km1:                    48m
==> km1: system:controller:daemon-set-controller                                48m
==> km1: system:controller:deployment-controller                                48m
==> km1: system:controller:disruption-controller                        
==> km1:         48m

This behavior practically makes the vagrant output useless and really hard to interpret.

Steps to reproduce

This can be easily reproducible with the execute plugin:

  1. vagrant plugin install vagrant-execute
  2. vagrant execute -c 'kubectl get clusterrole --all-namespaces' km1

Or by launching the whole environment with vagrant up.

@rgl
Copy link
Contributor Author

rgl commented Sep 12, 2019

As a workaround we need to wrap/buffer the command execution with something (which works most of the time, but not always) like:

# wrap commands in a way that their output is correctly (most of the time) displayed on the vagrant up output.
# see https://github.com/hashicorp/vagrant/issues/11047
function docker {
    set +x; echo "$(/usr/bin/docker "$@")"; set -x
}
function kubectl {
    set +x; echo "$(/usr/bin/kubectl "$@")"; set -x
}

@mchenryc
Copy link

mchenryc commented Sep 6, 2020

More workarounds:

stdbuf might work on GNU systems:

stdbuf -oL -eL <command>

Though as mentioned in the help:

If COMMAND adjusts the buffering of its standard streams ('tee' does
for example) then that will override corresponding changes by 'stdbuf'.

In that case, grep's --line-buffered flag, with pipefail for error handling might help:

linebuf () { ( set -o pipefail; "$@" | { grep --line-buffered '^' || true; } ); return $?; }

linebuf command && echo 'ok' || echo 'fail'

@rgl
Copy link
Contributor Author

rgl commented May 23, 2021

this is still happening in latest vagrant (2.2.16) and it makes the whole vagrant experience quite bad as the output is all messed up (even with things like vault).

there's a python script after these example that will by default flush stdout after each character. call this from a provisioner step or with vagrant-execute as vagrant execute -c 'python3 /vagrant/stdout-partial-lines.py'.

this is how the output looks:

rgl@rgl-desktop:~/Projects/vault-vagrant$ vagrant execute -c 'python3 /vagrant/stdout-partial-lines.py --flush'
==> default: #
==> default:  
==> default: l
==> default: i
==> default: n
==> default: e
==> default:  
==> default: 0
==> default: 0
==> default: 0
==> default: 1

And this is how it should have looked:

rgl@rgl-desktop:~/Projects/vault-vagrant$ vagrant execute -c 'python3 /vagrant/stdout-partial-lines.py --no-flush'
==> default: # line 0001 ############################################################################################################
==> default: 
==> default: 
==> default: 
==> default: 

Here's the python script to reproduce the problem:

#!/bin/python3

import sys
import argparse

parser = argparse.ArgumentParser(
    formatter_class=argparse.ArgumentDefaultsHelpFormatter,
    description='write partial lines to stdout to demonstrate vagrant broken output handling')
parser.add_argument(
    '--flush',
    default=True,
    action='store_true',
    help='flush after each written character')
parser.add_argument(
    '--no-flush',
    dest='flush',
    default=False,
    action='store_false',
    help='do not flush after each written character')
args = parser.parse_args()

for n in range(1, 26):
    prefix = '# line %04d #' % n
    line = '%s%s\n\n\n\n\n' % (prefix, '#' * (120 - len(prefix)))
    for c in line:
        sys.stdout.write(c)
        if args.flush:
            sys.stdout.flush()

rgl added a commit to rgl/vagrant that referenced this issue May 31, 2021
partial lines are buffered until they are complete (have a line ending)

see hashicorp#11047
rgl added a commit to rgl/vagrant that referenced this issue May 31, 2021
… the ui

partial lines are buffered until they are complete (have a line ending)

see hashicorp#11047
@rgl
Copy link
Contributor Author

rgl commented May 31, 2021

Please have a look at #12403! :-)

rgl added a commit to rgl/vagrant that referenced this issue Jun 27, 2021
… the ui

partial lines are buffered until they are complete (have a line ending)

see hashicorp#11047
chrisroberts pushed a commit to chrisroberts/vagrant that referenced this issue Jun 29, 2021
… the ui

partial lines are buffered until they are complete (have a line ending)

see hashicorp#11047
@github-actions
Copy link

I'm going to lock this issue because it has been closed for 30 days ⏳. This helps our maintainers find and focus on the active issues.
If you have found a problem that seems similar to this, please open a new issue and complete the issue template so we can capture all the details necessary to investigate further.

@github-actions github-actions bot locked as resolved and limited conversation to collaborators Jul 30, 2021
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
3 participants