Extra newlines on prints for non interactive terminals (Jenkins)

[sodul]

We want to add alive-progress to scripts that we run as part of our pipelines. So far it seems to work well but any print we do while in the alive-progress context is getting an empty newline first. This is probably required for the interactive terminals but is distracting in the CI logs.

I wrote this snippet based on your examples:

import time
from alive_progress import alive_bar

print('Pure progress:')
with alive_bar(1000) as bar:
    for i in range(1000):
        time.sleep(0.01)
        bar()

print('With extra output:')
with alive_bar(1000) as bar:
    for i in range(1000):
        if i% 300 == 0:
            print('found')
        time.sleep(0.01)
        bar()

This is the output on our CI system (Jenkins with timestamps enabled):

01:07:58  + python alive.py
01:07:58  Pure progress:
01:08:08  |████████████████████████████████████████| 1000/1000 [100%] in 10.1s (99.39/s)
01:08:08  With extra output:
01:08:08  
on 0: found
01:08:12  
on 300: found
01:08:15  
on 600: found
01:08:17  
on 900: found
01:08:18  |████████████████████████████████████████| 1000/1000 [100%] in 10.1s (99.38/s)

Ideally it should be:

01:07:58  + python alive.py
01:07:58  Pure progress:
01:08:08  |████████████████████████████████████████| 1000/1000 [100%] in 10.1s (99.39/s)
01:08:08  With extra output:
01:08:08  on 0: found
01:08:12  on 300: found
01:08:15  on 600: found
01:08:17  on 900: found
01:08:18  |████████████████████████████████████████| 1000/1000 [100%] in 10.1s (99.38/s)

[TheTechRobo]

This might be because of no carriage return. Might I ask which version this is on, and if 1.x, could you test it in the #51 branch?

[rsalmei]

Hello @sodul, That's very very odd. It seems your CI when dynamically modifying the output to include those timestamps, is sending a return before the message...

Thanks @TheTechRobo, but 2.0 will not change anything for this.

Well, this snippet does print correctly alone:

Pure progress:
|████████████████████████████████████████| 1000/1000 [100%] in 11.1s (89.98/s)
With extra output:
on 0: found
on 300: found
on 600: found
on 900: found
|████████████████████████████████████████| 1000/1000 [100%] in 11.1s (90.24/s)

Looking at the code deeper, I never send a return before messages, it's only after them:

    sys.__stdout__.write('{}{}\n'.format(header, nested))

or in 2.0:

    stream.write(f'{header}{nested.strip()}\n')

I'm not sure how I could support that 🤔 But I'll try to figure it out.

[sodul]

This is our full jenkins file. We use jenkins on Kubernetes:

pipeline {
    agent none
    options {
        ansiColor('xterm')  // Color output in logs.
    }
    stages {
        stage ('Progress bar') {
            agent {
                kubernetes {
                    yamlMergeStrategy merge()
                    // TODO: change the memory settings to evidence based values
                    yaml """
apiVersion: v1
kind: Pod
metadata:
  annotations:
    cluster-autoscaler.kubernetes.io/safe-to-evict: "false"
  labels:
    pod-label: "alive_progress"
    pipeline-stage: "alive_progress"
spec:
  imagePullSecrets:
    - name: regsecret
  containers:
  - name: python
    image: python:3.9.5
    imagePullPolicy: Always
    resources:
      requests:
        cpu: 1
      limits:
        memory: 250Mi
    tty: true
"""
                }
            }
            steps {
                container('python') {
                    sh '''\
cat > alive.py << 'EOF'
import time
from alive_progress import alive_bar

print('Pure progress:')
with alive_bar(1000) as bar:
    for i in range(1000):
        time.sleep(0.01)
        bar()

print('With extra output:')
with alive_bar(1000) as bar:
    for i in range(1000):
        if i% 300 == 0:
            print('found')
        time.sleep(0.01)
        bar()
EOF
pip install alive_progress
python alive.py
'''
                }
            }
        }
    }
    post {
        always {
            chuckNorris()
        }
    }
}

For more details on the versions:

• alive-progress 1.6.2
• Python 3.9.5 (official docker image)
• Jenkins 2.277.4 LTS (latest)
• Jenkins timestamper-plugin 1.13

The output is perfect on my laptop, the extra carriage return is annoying but not the end of the world on the Jenkins.

I looked at the raw output and I think the issue is with the control characters:

[2021-05-21T08:07:57.712Z] + pip install alive_progress
[2021-05-21T08:07:58.650Z] Collecting alive_progress
[2021-05-21T08:07:58.650Z]   Downloading alive_progress-1.6.2-py3-none-any.whl (38 kB)
[2021-05-21T08:07:58.650Z] Installing collected packages: alive-progress
[2021-05-21T08:07:58.651Z] Successfully installed alive-progress-1.6.2
[2021-05-21T08:07:58.651Z] WARNING: Running pip as root will break packages and permissions. You should install packages reliably by using venv: https://pip.pypa.io/warnings/venv
[2021-05-21T08:07:58.909Z] + python alive.py
[2021-05-21T08:07:58.909Z] Pure progress:
[2021-05-21T08:08:08.878Z] [?25l[?25h|████████████████████████████████████████| 1000/1000 [100%] in 10.1s (99.39/s)
[2021-05-21T08:08:08.878Z] With extra output:
[2021-05-21T08:08:08.878Z] [?25l
on 0: found
[2021-05-21T08:08:12.159Z] 
on 300: found
[2021-05-21T08:08:15.435Z] 
on 600: found
[2021-05-21T08:08:17.961Z] 
on 900: found
[2021-05-21T08:08:18.893Z] [?25h|████████████████████████████████████████| 1000/1000 [100%] in 10.1s (99.38/s)
[2021-05-21T08:08:18.919Z] [Pipeline] }

Screenshot since copy pasting is not ideal:

And the raw output itself: consoleText.txt

The timestamps are added by the timestamper plugin on Jenkins. consoleText.txt

[sodul]

Looking at the raw output with TextMate showing invisible characters:

I think the <CR> is doing it. I suppose it is here to put the cursor back to the left, which is required in interactive mode, but looks like a newline on Jenkins.

[sodul]

Tested with pip install git+https://github.com/rsalmei/alive-progress.git@rsa-refac which is the branch of #51 and got better results but this time the progress bar is the one with an empty line:

consoleText.txt

The <CR> seems to be the cause here as well.

[rsalmei]

Yeah, it seems it is the CR (carriage return), but if jenkins tty does interpret it as a LF (line feed), it seems a bug on it. Printing something and then carriage return the cursor is a common technique to animate things on a terminal, and it is important it both maintain the line and go to first column, look what happens without it:

Pure progress:
|████████████████████████████████████████| 1000/1000 [100%] in 1.3s (92.10/s)
With extra output:
                                                                                on 0: found
                                                                                     on 300: found
                                                                                     on 600: found
                                                                                      on 900: found
|████████████████████████████████████████| 1000/1000 [100%] in 11.2s (89.26/s)

Curiosity: when you look at jenkins console in real time, do you actually see the bar and the spinner moving? Does the widgets actually update themselves?

[sodul]

The bar is not animated in jenkins, it only shows up for the final update since it is not an interactive terminal.

That behavior is documented in the README.md:

it automatically detects if there's an allocated tty, and if there isn't (like in a pipe redirection), only the final receipt is printed, so you can safely include it in any code and rest assure your log file won't get thousands of progress lines;

Changing the behavior of Jenkins is not really an option, I'm quite convinced that the carriage returns are not desirable for non interactive outputs.

[rsalmei]

Yes, I did write that. And thanks for your analysis!

And also yes, I do think it is the <CR>, specially because you tested the 2.0, and the blank lines changed position... I'm trying to fix it at this moment, will comment when it is 👍

[rsalmei]

Ok @sodul, should be fixed now! Here it is the commit.

Could you please test again in the 2.0?

[sodul]

Perfect now :-)

https://user-images.githubusercontent.com/1504511/119917708-eca21700-bf1b-11eb-8faf-736a48e9553e.mp4

[rsalmei]

Great! Thank you for the report. So 2.0 will already ship with this! Don't forget to check often this repo, to switch to the oficial 2.0 version as soon as it is released! I'm just writing the new README now 👍