Podman: When running podman-remote build, all output comes at the end

[afbjorklund]

Is this a BUG REPORT or FEATURE REQUEST? (leave only one on its own line)

/kind bug

Description

When running podman-remote build, all the output comes in one big chunk at the end.

As opposed to local podman build, where it comes out more gradually - for each stage.

Steps to reproduce the issue:

1. (echo '# start'; podman-remote build . ) | ts '[%Y-%m-%d %H:%M:%.S]'

2.

3.

Describe the results you received:

[2020-09-15 19:39:46.105055] # start
[2020-09-15 19:39:52.087354] Getting image source signatures
[2020-09-15 19:39:52.087471] Copying blob sha256:df8698476c65c2ee7ca0e9dbc2b1c8b1c91bce555819a9aaab724ac64241ba67
[2020-09-15 19:39:52.087502] Copying config sha256:6858809bf669cc5da7cb6af83d0fae838284d12e1be0182f92f6bd96559873e3
[2020-09-15 19:39:52.087523] Writing manifest to image destination
[2020-09-15 19:39:52.087541] Storing signatures
[2020-09-15 19:39:52.087563] Getting image source signatures
[2020-09-15 19:39:52.087582] Copying blob sha256:be8b8b42328a15af9dd6af4cba85821aad30adde28d249d1ea03c74690530d1c
[2020-09-15 19:39:52.087600] Copying blob sha256:c4d6d0da5500e9037a93cf1737acefb3df85c051778bf1feda7e1f1d9737f5cb
[2020-09-15 19:39:52.087620] Copying config sha256:2d2aefb51997604b7130cb5f7c5fe1470ba7c013093783711a3973338c00e703
[2020-09-15 19:39:52.087639] Writing manifest to image destination
[2020-09-15 19:39:52.087660] Storing signatures
[2020-09-15 19:39:52.087686] --> 2d2aefb5199
[2020-09-15 19:39:52.087706] 2d2aefb51997604b7130cb5f7c5fe1470ba7c013093783711a3973338c00e703
[2020-09-15 19:39:52.087726] 
[2020-09-15 19:39:52.087749] FROM busybox
[2020-09-15 19:39:52.087772] RUN true
[2020-09-15 19:39:52.087795] COMMIT
[2020-09-15 19:39:52.087818] Successfully built 2d2aefb51997604b7130cb5f7c5fe1470ba7c013093783711a3973338c00e703

Describe the results you expected:

[2020-09-15 19:41:25.676427] # start
[2020-09-15 19:41:25.690161] STEP 1: FROM busybox
Getting image source signatures
Copying blob df8698476c65 [--------------------------------------] 0.0b / 0.0b
Copying config 6858809bf6 done  
Writing manifest to image destination
Storing signatures
[2020-09-15 19:41:29.396010] STEP 2: RUN true
[2020-09-15 19:41:29.814488] STEP 3: COMMIT
[2020-09-15 19:41:30.141805] --> 6aaae219341
[2020-09-15 19:41:30.148419] 6aaae2193410e4eacb61f04a5d3aa2fbfd445ab33fa9c4c644c04d10f0db66a9

Additional information you deem important (e.g. issue happens only occasionally):

Possibly due to different buffering and flushing being used ?

Output of podman version:

Version:      2.1.0-dev
API Version:  1
Go Version:   go1.14.6
Git Commit:   0be5836e49da38b156951639b7e19eaec6a6e593
Built:        Tue Sep 15 19:26:40 2020
OS/Arch:      linux/amd64

Output of podman info --debug:

(paste your output here)

Package info (e.g. output of rpm -q podman or apt list podman):

(paste your output here)

Have you tested with the latest version of Podman and have you checked the Podman Troubleshooting Guide?

Yes/No

Additional environment details (AWS, VirtualBox, physical, etc.):

[afbjorklund]

I did try without the pipe too, but then you need to see it to understand what happens.

Throwing in some more statements (or a more complex Dockerfile) also works for that.

FROM busybox
RUN sleep 10
RUN sleep 10
RUN sleep 10
RUN true

[afbjorklund]

Swedish word of the day: "ketchupeffekt" (i.e. Heinz Ketchup glass bottle)

https://www.thelocal.se/20181211/swedish-word-of-the-day-ketchupeffekt

[jwhonce]

@afbjorklund Using podman built from master

$ (echo '# start'; ../bin/podman-remote build . ) | ts '[%Y-%m-%d %H:%M:%.S]'
[2020-09-15 12:12:19.243437] # start
[2020-09-15 12:12:19.286528] STEP 1: FROM busybox
[2020-09-15 12:12:19.293103] STEP 2: RUN sleep 30
[2020-09-15 12:12:49.508558] STEP 3: RUN sleep 20
[2020-09-15 12:13:09.756154] STEP 4: RUN sleep 10
[2020-09-15 12:13:19.969284] STEP 5: RUN true
[2020-09-15 12:13:20.185935] STEP 6: COMMIT
[2020-09-15 12:13:20.185985] STEP 7: COMMIT
[2020-09-15 12:13:21.000597] Getting image source signatures
[2020-09-15 12:13:21.000744] Copying blob sha256:be8b8b42328a15af9dd6af4cba85821aad30adde28d249d1ea03c74690530d1c
[2020-09-15 12:13:21.001026] Copying blob sha256:1361150dca60c349edebf9d2267393955c27c7ab7bc496ff40ba5090d6f3ddcd
[2020-09-15 12:13:21.011716] Copying config sha256:8a9605f375715771b6e45726bf0e91230876acce26cd384bbcb90594a92bbcf8
[2020-09-15 12:13:21.013743] Writing manifest to image destination
[2020-09-15 12:13:21.013777] Storing signatures
[2020-09-15 12:13:21.063245] --> 8a9605f3757
[2020-09-15 12:13:21.065916] 8a9605f375715771b6e45726bf0e91230876acce26cd384bbcb90594a92bbcf8

I see the sleep delays in the ts output and on the screen progress. Here is my environment.

• running podman under bash.
• podman version
  $ ../bin/podman-remote version
  Client:
  Version: 2.1.0-dev
  API Version: 1
  Go Version: go1.14.7
  Git Commit: 0be5836e49da38b156951639b7e19eaec6a6e593-dirty
  Built: Tue Sep 15 10:32:28 2020
  OS/Arch: linux/amd64

Server:
Version: 2.1.0-dev
API Version: 1
Go Version: go1.14.7
Git Commit: 0be5836e49da38b156951639b7e19eaec6a6e593-dirty
Built: Tue Sep 15 10:32:23 2020
OS/Arch: linux/amd64

[afbjorklund]

Maybe I need to upgrade the server as well, for everything to work ?

Server:
Version:      2.0.6
API Version:  0
Go Version:   go1.14.6
Built:        Tue Sep  1 21:26:51 2020
OS/Arch:      linux/amd64

[rhatdan]

Since this PR just went in, I am going to close this issue.
Fix should be available in podman 2.1.

[afbjorklund]

@jwhonce, @mheon : I can confirm that this issue with output buffering goes away after _also_ upgrading the server.

It manifested itself when using 2.0.1-dev/2.0.6, rather than 2.0.1-dev/2.01-dev (2.0.6/2.0.1-dev was still broken/dead)