Docker: `eb local run` tries to pass last word of `docker build` STDOUT as docker image name to `docker run` #53

rowedonalde · 2020-11-06T06:20:49Z

Description

I am following the "Using the Docker Platform" tutorial, and I am encountering a bug during the "Test a container locally" step. It appears that ebcli is treating the last word of the log output as the name of a Docker image that needs to be pulled.

Steps to reproduce

Follow "Using the Docker Platform" up through the eb local run --port 5000 step.

Observed result

When I run the eb local run --port 5000 command after following the preceding instructions in the tutorial, the image appears to build correctly, but then ultimately ends with something like this:

#9 writing image sha256:25f391927f92e8e7be6edd518ab9b94f9a65ac884faba0286ec6fb61b805ae77 done
#9 DONE 2.2s
Unable to find image '2.2s:latest' locally
docker: Error response from daemon: pull access denied for 2.2s, repository does not exist or may require 'docker login': denied: requested access to the resource is denied.
See 'docker run --help'.
ERROR: CommandError - None

Full output using the --debug flag is as follows: https://pastebin.com/GJMPKZJv. Note lines 101-107 from the paste where the script is trying to invoke docker run with the elapsed time 0.0s as the name of a docker image:

#9 DONE 0.0s
2020-11-05 22:09:43,082 (DEBUG) ebcli.core.fileoperations : Project root found at: /Users/don/docker_flask
2020-11-05 22:09:43,083 (DEBUG) ebcli.core.fileoperations : Project root found at: /Users/don/docker_flask
2020-11-05 22:09:43,083 (DEBUG) ebcli.core.fileoperations : Project root found at: /Users/don/docker_flask
2020-11-05 22:09:43,083 (DEBUG) ebcli.core.fileoperations : Project root found at: /Users/don/docker_flask
2020-11-05 22:09:43,084 (DEBUG) ebcli.core.fileoperations : Project root found at: /Users/don/docker_flask
2020-11-05 22:09:43,085 (DEBUG) ebcli.lib.utils : docker run -i -t --rm -p 5000:5000 --name d0ccf434eea8a92119299b695d27872dc19adf5a 0.0s

Expected result

I expect the docker image to successfully build and run locally.

Additional environment details (Ex: Windows, Mac, Amazon Linux etc)

OS: macOS Mojave 10.14.6, Python 3.9
EBCLI version: Python awsebcli==3.19.2

The text was updated successfully, but these errors were encountered:

marin-h · 2020-11-09T23:08:38Z

Same issue, using Ubuntu 20.04 and EB CLI 3.19.2 (Python 3.7.2)

sagrimson · 2020-11-18T20:00:02Z

Same here, anyone figure this one out?
macOS 10.15.7
EB CLI 3.19.2 (Python 2.7.1)

Palakpatel67 · 2020-11-18T22:00:27Z

@rowedonalde thanks for reporting this issue. We will look into this and post any updates to this issue.

jonathanhooker · 2020-11-19T00:44:47Z

Same issue. MacOS 10.15.7

EB CLI 3.19.2 (Python 2.7.1)
Also in virtual environment with EB CLI 3.19.2 (Python 3.9.0)

remvst · 2020-11-20T16:20:55Z

Same issue here

OSX 10.15.7 (Catalina)
EB CLI 3.19.2 (Python 3.9.0)

tuhinadasgupta · 2020-11-22T20:54:23Z

same issue here!
OSX 10.15.7 (Catalina)
EB CLI 3.19.2 (Python 3.9.0)

ramoncisternas · 2020-11-27T10:00:32Z

Same issue here

Microsoft Windows [Version 10.0.17763.1577]
WSL Version 1 running Ubuntu 18.04.4 LTS
EB CLI 3.19.2 (Python 2.7.1)

minheekangg · 2020-12-02T15:30:01Z

Same issue!

OSX 10.15.7 (Catalina)
EB CLI 3.19.2 (Python 3.9.0)

Palakpatel67 · 2020-12-03T17:14:25Z

Hi @rowedonalde , thanks for your patience. I have not been able to reproduce this issue. If possible can you confirm that your docker image is build successfully by running docker image ls?

minheekangg · 2020-12-03T22:32:18Z

EB Debug log:

2020-12-03 17:26:17,742 (DEBUG) ebcli.lib.utils : docker run -i -t --rm -p 1337:1337 --env NAME=test --name fb0995ac4c542be7708a0c6e825c76be9e3ee203 0.0s
Unable to find image '0.0s:latest' locally

From my understanding, I think it's looking to the last thing on that line 0.0s and searching for that image when it should be using fb0995ac4c542be7708a0c6e825c76be9e3ee203:latest.

Please advise!

Palakpatel67 · 2020-12-04T21:06:04Z

Hi @minheekangg, If the docker image is build successfully, in debug log you can see Successfully built 8bbd82ae6425 and later we will use this docker image id in docker run command like this docker run -i -t --rm -p 5000:5000 --name e7e4915b988ebd8a9509aee688e589f25b59f0bf 8bbd82ae6425.

nirisarri · 2020-12-14T03:36:20Z

It seems that you are not removing the 0.0s (which seems to be a timestamp) ... I am not certain if this is because of a docker version mismatch or just because is not being parsed.

ranvirm · 2020-12-21T11:37:50Z

Same issue
OSX 11.0.1 (Big Sur)
EB CLI 3.19.2 (Python 3.8.2) (Latest)

As mentioned above, it does look like the time taken to run the last step (0.0s) is being added to the docker run command and this is causing the error - a quick fix would be to remove that last output maybe?

UPDATE
I managed to manually deploy the container via the ELB UI - so definitely not a container issue

#15 writing image sha256:04c46f9cca3ee3af00a4d609643be6c32a7ee70a394c7ad70f0887ff77beebdc done
#15 DONE 0.0s
2020-12-21 13:32:02,917 (DEBUG) ebcli.core.fileoperations : Project root found at: /Users/.../projects/shiny-server/shiny-server-app
2020-12-21 13:32:02,917 (DEBUG) ebcli.core.fileoperations : Project root found at: /Users/.../projects/shiny-server/shiny-server-app
2020-12-21 13:32:02,917 (DEBUG) ebcli.core.fileoperations : Project root found at: /Users/.../projects/shiny-server/shiny-server-app
2020-12-21 13:32:02,918 (DEBUG) ebcli.core.fileoperations : Project root found at: /Users/.../projects/shiny-server/shiny-server-app
2020-12-21 13:32:02,918 (DEBUG) ebcli.core.fileoperations : Project root found at: /Users/.../projects/shiny-server/shiny-server-app
2020-12-21 13:32:02,919 (DEBUG) ebcli.lib.utils : docker run -i -t --rm -p 80:3838 --name a9d3c4a560bc2b178e773d9fb32b938ad6345f78 0.0s
Unable to find image '0.0s:latest' locally

ranvirm · 2020-12-21T15:02:32Z

Hi @rowedonalde , thanks for your patience. I have not been able to reproduce this issue. If possible can you confirm that your docker image is build successfully by running docker image ls?

@Palakpatel67 I can help recreate the issue if it would help get this resolved faster

Palakpatel67 · 2020-12-21T18:47:58Z

@ranvirm thank you! Could you provide the output of eb local run --port 5000 --debug?

ranvirm · 2020-12-21T20:44:08Z

@Palakpatel67 Here's the log (stdout & stderr) from running
eb local run --port 3838 --debug > log.txt 2>&1

log.txt

ranvirm · 2020-12-21T21:12:53Z

@Palakpatel67 I was bored so I spent some time going through the logs and found the (most likely) error and possible fix.

In ebcli/containers/commands.py there is a function that grabs the image_id of the newly built container from the build output text
The function is on line 205 in ebcli/containers/commands.py

Current function:

def _grab_built_image_id(build_output):
    last_line = build_output.split()[-1]
    image_id = last_line.split()[-1]
    return image_id

If this function is changed to grab the 2nd to last line of build output as below then the issue should be resolved:
(the alternative solution would be to change the function that produces the build output and remove that last line which prints the time taken which is unnecessary in my opinion)

def _grab_built_image_id(build_output):
    last_line = build_output.split()[-2] # grab the 2nd to last line
    image_id = last_line.split()[-2] # grab the container id - its not the last text in this line
    return image_id

For reference, build output:

#1 [internal] load build definition from Dockerfile
#1 sha256:e47a00f897045581a64a7d957d0003e028f05a7e105fc0c55b19454f3502fab6
#1 transferring dockerfile: 37B 0.0s done
#1 DONE 0.0s
#2 [internal] load .dockerignore
#2 sha256:94196afc74874f9ede8096246e3ad93501d624ab21c74134d0af160fa2547d88
#2 transferring context: 34B done
#2 DONE 0.0s
#3 [internal] load metadata for docker.io/rocker/shiny:latest
#3 sha256:95aef63800a85de1f364b2c4991c5dd3717404c642010d411c8e05fb1a31b7a3
#3 DONE 0.0s
#4 [1/8] FROM docker.io/rocker/shiny
#4 sha256:414b55fc4e5f8747fe53a7a22aa13a1c0e7cb849b7dd94d5a6a3c254b3075811
#4 DONE 0.0s
#6 [internal] load build context
#6 sha256:0908c967e0d0ac222be89d1d935496a4852fb589fed4aec5b900bf8cddc6ec9a
#6 transferring context: 225B done
#6 DONE 0.0s
#10 [6/8] RUN chown shiny:shiny /var/lib/shiny-server
#10 sha256:233479fb65206031504f3757f41bb4c1b1c0f13e58eb5e31cd8a09fd4c8c5f49
#10 CACHED
#7 [3/8] COPY shiny-server.sh /usr/bin/shiny-server.sh
#7 sha256:d3ab04e799f9b28d5a198677c164ed662628e6e8dde931129c76e151dad52485
#7 CACHED
#9 [5/8] RUN chmod -R 755 /srv/shiny-server/
#9 sha256:81646e2cd6d8db3992b99c589b93f496ec327a600108f4e8efffd6b645df9690
#9 CACHED
#8 [4/8] COPY apps/ /srv/shiny-server/apps
#8 sha256:c3b55fa16d6653836b8dc6f3194ea64ddfe5c6154ac379586659f60c802e6b84
#8 CACHED
#11 [7/8] RUN chown shiny:shiny /usr/bin/shiny-server.sh
#11 sha256:8861cbec26b00344ce87760b4390d5237a2b0e6b7f3f9abd8793efcf9e550a8d
#11 CACHED
#5 [2/8] RUN R -e "install.packages(c('dplyr', 'pandas', 'shinySignals'))"
#5 sha256:ed86538e3ded567d41d35f4d3d1c2db645f4dfe3b7cf0cc4f18d7b63a08b0d7d
#5 CACHED
#12 [8/8] RUN chmod -R 755 /usr/bin/shiny-server.sh
#12 sha256:c0b8cedc20528168ae932e8be594d0c44051da15330ca137b8da333b4674eecc
#12 CACHED
#13 exporting to image
#13 sha256:e8c613e07b0b7ff33893b694f7759a10d42e180f2b4dc349fb57dc6b71dcab00
#13 exporting layers done
#13 writing image sha256:ac99d112c7aec61cceec8306addaad850d2d6c8a98efbb7195893f52792c54aa done
#13 DONE 0.0s

nirisarri · 2020-12-21T21:33:19Z

would this fix be dependent on the docker desktop version? It seems that different docker desktop versions are issuing different outputs. it seems the algorithmic solution is

counter = 1
found = false
While not found
grab line (-1 * counter)
if the line contains a sha256 hash [A-Fa-f0-9]{64}
grab the value and found = true
else
increment counter
end while

Or something like that...

ranvirm · 2020-12-21T22:03:49Z

I looked at the flow of getting the image ID to use in the container run command and found that this function is the one that builds the image and returns an image id (for use in the container run function):

ebcli/containers/commands.py line 49

def build_img(docker_path, file_path=None):
    """
    Builds a docker image using Dockerfile found in docker path.
    :param docker_path: str: path of dir containing the Dockerfile
    :param file_path: str: optional name of Dockerfile
    :return: str: id of the new image
    """

    opts = ['-f', file_path] if file_path else []
    args = ['docker', 'build'] + opts + [docker_path]
    output = _run_live(args)
    return _grab_built_image_id(output)

Now there are two possible sources of error (and solutions here) - one is to alter the _grab_built_image_id() function like I said above or alter the function that runs the actual docker build command (_run_live()) so that the output is formatted correctly.

The _run_live() function is called with args = ['docker', 'build'] + opts + [docker_path]
The function:

ebcli/containers/commands.py line 277

def _run_live(args):
    try:
        return utils.exec_cmd_live_output(args)
    except CommandError as e:
        _handle_command_error(e)

As you can see, it then calls exec_cmd_live() which is:

ebcli/lib/utils.py line 236
exec_cmd_live_output = exec_cmd

which is:

ebcli/lib/utils.py line 199

def exec_cmd(args, live_output=True):
    """
    Execute a child program (args) in a new process. Displays
    live output by default.
    :param args: list: describes the command to be run
    :param live_output: bool: whether to print live output
    :return str: child program output
    """

    LOG.debug(' '.join(args))

    process = Popen(args, stdout=PIPE, stderr=STDOUT)
    output = []

    for line in iter(process.stdout.readline, b''):
        line = line.decode('utf-8')
        if line != os.linesep:
            if live_output:
                sys.stdout.write(line)
                sys.stdout.flush()
            else:
                LOG.debug(line)

        output.append(line)

    process.stdout.close()
    process.wait()

    returncode = process.returncode
    error_msg = 'Exited with return code {}'.format(returncode)
    output_str = ''.join(output)

    if returncode:
        raise CommandError(error_msg, output_str, returncode)
    return output_str

exec_cmd() actually executes the docker build command with:

process = Popen(args, stdout=PIPE, stderr=STDOUT)

This basically runs a system command and returns the running process so that the output logs can be read.

So I then tried to re-create the docker build command that generates the build logs we are seeing when running eb local run and found that this command does that:

docker build --progress plain -t tmp-image .

Note the progress plain param to the docker build call - this is what produces the build output we see. Last line of output from above docker build command:

#13 DONE 0.0s

And there's the 0.0s that's being used by the AWS eb cli as the image id.

So then solution 2: instead of instructing docker to produce those build logs, the docker build command could be run quietly as below:

docker build --quiet -t tmp-image .

Which will just write out the desired image id.

The issue with running the docker build quietly though is that we won't see the build logs from eb local run which could bother some people so I think that solution one (edit the function that grabs the image id from the build logs) is the best fix for this issue.

I like the solution @nirisarri proposed (vs my hard coded fix which could easily break again as the current one is doing)
What do you think @Palakpatel67 ?

ranvirm · 2020-12-21T22:53:26Z

I tested solution 2 proposed above, changing the docker build command by altering this function:

ebcli/containers/commands.py line 49

FROM

def build_img(docker_path, file_path=None):
    """
    Builds a docker image using Dockerfile found in docker path.
    :param docker_path: str: path of dir containing the Dockerfile
    :param file_path: str: optional name of Dockerfile
    :return: str: id of the new image
    """

    opts = ['-f', file_path] if file_path else []
    args = ['docker', 'build'] + opts + [docker_path]
    output = _run_live(args)
    return _grab_built_image_id(output)

TO

def build_img(docker_path, file_path=None):
    """
    Builds a docker image using Dockerfile found in docker path.
    :param docker_path: str: path of dir containing the Dockerfile
    :param file_path: str: optional name of Dockerfile
    :return: str: id of the new image
    """

    opts = ['-q', '-f', file_path] if file_path else ['-q']
    args = ['docker', 'build'] + opts + [docker_path]
    output = _run_live(args)
    return _grab_built_image_id(output)

Added -q to always run docker build quietly and thus only output the image id

The command eb local run --port 3838 then ran successfully

This fix works and should work on all platforms as I'm pretty sure that docker build quietly will always output the same (image id only) on all platforms (as documented here)

ranvirm · 2020-12-21T23:06:24Z

Should I create a pull request with above solution?

…ocal run' incorrectly parses last word of docker build stdout as image id to docker run - issue aws#53

Palakpatel67 · 2020-12-22T17:46:27Z

@ranvirm @nirisarri thanks for proposing different solutions, really appreciate it.
We will look into this and try to fix it asap. Will post any updates regarding to this issue here.
thank you!

proftom · 2021-01-27T03:29:58Z

did we ever get a fix for this?

AdiPat · 2021-01-27T09:11:36Z

I've been facing the same issue. Is there a way around this bug without modifying the source code?

YassinHajaj · 2021-02-13T14:15:37Z

Same issue here. We have an obvious solution proposed by @ranvirm , I don't know what's taking so long to fix it.

jjpr · 2021-03-05T17:21:07Z

@Palakpatel67 Would it be possible to use docker-py (https://github.com/docker/docker-py) instead of the subprocess/Popen mechanism? The build function (https://docker-py.readthedocs.io/en/stable/images.html#docker.models.images.ImageCollection.build) returns an Image object, so there's no guesswork about where in the text output the image ID appears. Might simplify the solution.

Palakpatel67 · 2021-03-11T22:43:17Z

This ishould be fixed in awsebcli version 3.19.4.

rowedonalde changed the title ~~Docker: eb local run tries to pass last word of STDOUT as docker image name~~ Docker: eb local run tries to pass last word of docker build STDOUT as docker image name to docker run Nov 6, 2020

Palakpatel67 self-assigned this Dec 21, 2020

ranvirm pushed a commit to ranvirm/aws-elastic-beanstalk-cli that referenced this issue Dec 21, 2020

Added '-q' as a default docker build command to fix issue where 'eb l…

20d4f16

…ocal run' incorrectly parses last word of docker build stdout as image id to docker run - issue aws#53

ranvirm mentioned this issue Dec 21, 2020

Added '-q' as a default docker build command to fix issue #53 #59

Open

Palakpatel67 closed this as completed Mar 11, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Docker: `eb local run` tries to pass last word of `docker build` STDOUT as docker image name to `docker run` #53

Docker: `eb local run` tries to pass last word of `docker build` STDOUT as docker image name to `docker run` #53

rowedonalde commented Nov 6, 2020

marin-h commented Nov 9, 2020

sagrimson commented Nov 18, 2020

Palakpatel67 commented Nov 18, 2020

jonathanhooker commented Nov 19, 2020

remvst commented Nov 20, 2020

tuhinadasgupta commented Nov 22, 2020

ramoncisternas commented Nov 27, 2020

minheekangg commented Dec 2, 2020

Palakpatel67 commented Dec 3, 2020

minheekangg commented Dec 3, 2020

Palakpatel67 commented Dec 4, 2020

nirisarri commented Dec 14, 2020

ranvirm commented Dec 21, 2020 •

edited

Loading

ranvirm commented Dec 21, 2020

Palakpatel67 commented Dec 21, 2020

ranvirm commented Dec 21, 2020 •

edited

Loading

ranvirm commented Dec 21, 2020 •

edited

Loading

nirisarri commented Dec 21, 2020

ranvirm commented Dec 21, 2020 •

edited

Loading

ranvirm commented Dec 21, 2020

ranvirm commented Dec 21, 2020

Palakpatel67 commented Dec 22, 2020

proftom commented Jan 27, 2021

AdiPat commented Jan 27, 2021 •

edited

Loading

YassinHajaj commented Feb 13, 2021

jjpr commented Mar 5, 2021

Palakpatel67 commented Mar 11, 2021

Docker: eb local run tries to pass last word of docker build STDOUT as docker image name to docker run #53

Docker: eb local run tries to pass last word of docker build STDOUT as docker image name to docker run #53

Comments

rowedonalde commented Nov 6, 2020

Description

Steps to reproduce

Observed result

Expected result

Additional environment details (Ex: Windows, Mac, Amazon Linux etc)

marin-h commented Nov 9, 2020

sagrimson commented Nov 18, 2020

Palakpatel67 commented Nov 18, 2020

jonathanhooker commented Nov 19, 2020

remvst commented Nov 20, 2020

tuhinadasgupta commented Nov 22, 2020

ramoncisternas commented Nov 27, 2020

minheekangg commented Dec 2, 2020

Palakpatel67 commented Dec 3, 2020

minheekangg commented Dec 3, 2020

Palakpatel67 commented Dec 4, 2020

nirisarri commented Dec 14, 2020

ranvirm commented Dec 21, 2020 • edited Loading

ranvirm commented Dec 21, 2020

Palakpatel67 commented Dec 21, 2020

ranvirm commented Dec 21, 2020 • edited Loading

ranvirm commented Dec 21, 2020 • edited Loading

nirisarri commented Dec 21, 2020

ranvirm commented Dec 21, 2020 • edited Loading

ranvirm commented Dec 21, 2020

ranvirm commented Dec 21, 2020

Palakpatel67 commented Dec 22, 2020

proftom commented Jan 27, 2021

AdiPat commented Jan 27, 2021 • edited Loading

YassinHajaj commented Feb 13, 2021

jjpr commented Mar 5, 2021

Palakpatel67 commented Mar 11, 2021

Docker: `eb local run` tries to pass last word of `docker build` STDOUT as docker image name to `docker run` #53

Docker: `eb local run` tries to pass last word of `docker build` STDOUT as docker image name to `docker run` #53

ranvirm commented Dec 21, 2020 •

edited

Loading

ranvirm commented Dec 21, 2020 •

edited

Loading

ranvirm commented Dec 21, 2020 •

edited

Loading

ranvirm commented Dec 21, 2020 •

edited

Loading

AdiPat commented Jan 27, 2021 •

edited

Loading