Print statements in Python3 scripts only return when script finishes

When running python3 scripts with print statements, I am not seeing the messages in the task log until the script completes. Below illustrates this behavior with a simple example that can be run from the script console:

import time

print('Script started at {}'.format(time.ctime()))
time.sleep(10)
print('Script finished at {}'.format(time.ctime()))

This produces the following output. Note that I used the raw log to make the formatting easier on the eyes as well as to include info such as when the task was started and completed. I have removed unrelated logging from this example:

Task status:    Success
Task queued:    Thursday, 06 January 2022 10:57:10 AM -08:00
Task started:   Thursday, 06 January 2022 10:57:11 AM -08:00
Task completed: Thursday, 06 January 2022 10:57:23 AM -08:00
Task duration:  12 seconds

10:57:22   Info     |     Script started at Thu Jan  6 10:57:12 2022
10:57:22   Info     |     Script finished at Thu Jan  6 10:57:22 2022

You can see that the print statements are logged 10 seconds apart, but the actual return isn’t logged by Octopus until the script completes.

I do not encounter this behavior with PowerShell nor Bash scripts.

== PowerShell example ==

Write-Host "Script started at $(Get-Date)"
Start-Sleep 10
Write-Host "Script finished at $(Get-Date)"
Task status:    Success
Task queued:    Thursday, 06 January 2022 11:04:58 AM -08:00
Task started:   Thursday, 06 January 2022 11:04:58 AM -08:00
Task completed: Thursday, 06 January 2022 11:05:11 AM -08:00
Task duration:  13 seconds

11:05:00   Info     |     Script started at 01/06/2022 11:05:00
11:05:11   Info     |     Script finished at 01/06/2022 11:05:10

== Bash example ==

echo "Script started at $(date)"
sleep 10
echo "Script finished at $(date)"
Task status:    Success
Task queued:    Thursday, 06 January 2022 11:08:21 AM -08:00
Task started:   Thursday, 06 January 2022 11:08:21 AM -08:00
Task completed: Thursday, 06 January 2022 11:08:32 AM -08:00
Task duration:  12 seconds

11:08:22   Info     |     Script started at Thu Jan  6 11:08:22 EST 2022
11:08:32   Info     |     Script finished at Thu Jan  6 11:08:32 EST 2022

All 3 of these examples were run against the same Linux deployment target (it has PowerShell installed on it). Is there any way to work around this? For my use-case, it’s really important that I get logging as it occurs. We are running Octopus Server version 2020.6.4671+Branch.release-2020.6.Sha.b17bea4a7d246d77cf829cc8c35cdf1211ad719d

Hi @justinm89,

Thanks for posting your question, and sorry to hear you’re experiencing that behavior.

You should be able to configure python to run in unbuffered mode by setting an environment variable PYTHONUNBUFFERED to true. This should allow you to write to the console immediately, and not have to update any of your scripts.

It looks like you’re encountering a similar issue identified in one of our other tickets, and if the above doesn’t work for you then perhaps one of the other solutions proposed there might:

Let me know how it goes!

Best,
Patrick

Good timing, I hit on that same StackOverflow page right as you posted a reply. This does indeed seem to be the issue. Setting PYTHONUNBUFFERED as an environment variable didn’t work for me, but both of these did:

import functools

print = functools.partial(print, flush=True)

Not 100% what this does, but I’m guessing it’s some kind of on-the-fly method overload and it will work great for my use-case. The only thing that doesn’t seem to work is the modified print statements that Octopus supplies: printhighlight(), printwarning(), etc.

Hi @justinm89,

Thank you for getting back to me and letting me know you found a partial workaround.

The log level print functions all have their own print statements, as defined here: Calamari/Configuration.py at master · OctopusDeploy/Calamari · GitHub

From that, I think you may have to define your own statements to get the lines to flush from the buffer. So for example with highlighting:

def printhighlight-flush(message):
    print("##octopus[stdout-highlight]")
    print(message, flush=True)
    print("##octopus[stdout-default]")

Does that seem like a viable workaround for you? If so you might give it a try and let me know the result.

Best,
Patrick

Hey @patrick.smergut that worked perfectly. Thanks for your help once again.

Hi @justinm89,

You’re very welcome and glad to hear that worked for you.

Let me know if there’s anything else I can help with!

Best,
Patrick