container.logs().fetch() returning non-ASCII value

[kleash]

Hi Everyone,

I am running ubuntu image with command as date.

docker logs is showing correct output but my program is not able to print anything.

Program:

public class App {
    public static void main(String[] args) throws Exception {
        final Container container = new LocalDocker(new File("/var/run/docker.sock")).containers().create("ubuntutest",
                containerJsonObject());
        container.start();

        while (runningState(container)) {

        }
        final String logs = container.logs().fetch();
        logs.trim();
        System.out.println(logs);
        System.out.println(logs.length());
    }

    private static JsonObject containerJsonObject() {
        JsonObjectBuilder json = Json.createObjectBuilder();
        json.add("AttachStdout", true);
        json.add("AttachStderr", true);
        json.add("Image", "ubuntu");
        json.add("Tty", false);
        json.add("Cmd", "date");
        JsonArrayBuilder builder = Json.createArrayBuilder();
        builder.add("OUT=/scans/firstimg.jpg");
        json.add("Env", builder);
        JsonObjectBuilder hostConfig = Json.createObjectBuilder();
        JsonArrayBuilder binds = Json.createArrayBuilder();
        binds.add("/home/shubham/scans:/scans/");
        hostConfig.add("Binds", binds);
        hostConfig.add("Privileged", true);
        json.add("HostConfig", hostConfig);
        return json.build();
    }

    private static boolean runningState(final Container container) throws IOException {
        return container.inspect().getJsonObject("State").getBoolean("Running");
    }

}

Output of above is:

37

Thanks for any help!!

[0crat]

@amihaiemil/z please, pay attention to this issue

[0crat]

@kleash/z this project will fix the problem faster if you donate a few dollars to it; just click here and pay via Stripe, it's very fast, convenient and appreciated; thanks a lot!

[amihaiemil]

@kleash To be honest, I'm not sure why that happens. The method has both unit and integration tests (with the Docker "hello world" image).

Maybe your Ubuntu container starts and doesn't have any logs to display yet, at the time the method is called.

Try to do a Thread.sleep() between the moment the container starts and reading of the logs.

Anyway, I think your scenario would require to follow the logs, not just fetch them, since Ubuntu is running continuously. However, there is currently a bug in that method, it doesn't work properly.

Unfortunately, I cannot really help now. If you find the problem and have time to fix it, please consider opening a PR :)

[tuxji]

I just found the same problem, and I know what the problem is. When you call GET /containers/{id}/logs to get stdout and stderr logs from a container, the logs are returned using a binary stream format in the response body. The stream format is described in the documentation for the attach endpoint. Briefly summarizing, eight binary bytes are prepended to each line of logging output to tell you 1) whether the next line came from stdout or stderr, and 2) how many bytes long the next line is.

Here are two example lines taken from my Emacs buffer visiting a file saved by wget 'http://localhost:2375/v1.35/containers/{id}/logs?stdout=true&stderr=true':

^A^@^@^@^@^@^@,Info: STEM is running. Please be patient...
^B^@^@^@^@^@^@c[main] INFO kbaseRoot set to /app/STEM

The first byte is a ^A or ^B (1 or 2) followed by six zero (null) bytes, then followed by a byte which looks like an ordinary character but really is meant to be the size of the next line, and then the line itself is appended. I think it would be easier for callers if fetch() trimmed these eight bytes from the beginning of each line in the string output it reads from the logs API endpoint, but one could disagree, simply document the stream format in the javadoc, and make callers decode the stream format themselves.

[amihaiemil]

@tuxji I would prefer to trim the String response. But will String.trim() do the job? I don't think so. Maybe we need to write a custom Stream to handle this case.

Do you happen to have an integration test for this case? I've never seen this behaviour and that endpoint has both unit and integration tests in the library.

[tuxji]

Does your endpoint integration test get logs from a container on a real Docker server? I saw this behavior when using Docker on Windows configured to expose a TCP port (2375) without TLS so that API clients could talk to it:

$ printenv DOCKER_HOST && which docker
tcp://localhost:2375
/cygdrive/c/Program Files/Docker/Docker/resources/bin/docker

$ docker version
Client: Docker Engine - Community
 Version:           19.03.8
 API version:       1.40
 Go version:        go1.12.17
 Git commit:        afacb8b
 Built:             Wed Mar 11 01:23:10 2020
 OS/Arch:           windows/amd64
 Experimental:      false

Server: Docker Engine - Community
 Engine:
  Version:          19.03.8
  API version:      1.40 (minimum version 1.12)
  Go version:       go1.12.17
  Git commit:       afacb8b
  Built:            Wed Mar 11 01:29:16 2020
  OS/Arch:          linux/amd64
  Experimental:     false
 containerd:
  Version:          v1.2.13
  GitCommit:        7ad184331fa3e55e52b890ea95e65ba581ae3429
 runc:
  Version:          1.0.0-rc10
  GitCommit:        dc9208a3303feef5b3839f4323d9beb36df0a9dd
 docker-init:
  Version:          0.18.0
  GitCommit:        fec3683

My Java client program used RemoteDocker with http://localhost:2375 to start a container, wait for it to finish, and get the container's logs. However, you don't need to use Java at all. You can simply run a docker run hello-world command followed by a wget command to get that container's logs and you will see the binary characters in the file saved by wget.

$ docker run hello-world
Unable to find image 'hello-world:latest' locally
latest: Pulling from library/hello-world
1b930d010525: Pull complete
Digest: sha256:f9dfddf63636d84ef479d645ab5885156ae030f611a56f3a7ac7f2fdd86d7e4e
Status: Downloaded newer image for hello-world:latest

Hello from Docker!
This message shows that your installation appears to be working correctly.
...

$ docker container ls -a
CONTAINER ID        IMAGE               COMMAND             CREATED             STATUS                      PORTS               NAMES
388b9861f31c        hello-world         "/hello"            31 seconds ago      Exited (0) 22 seconds ago                       eager_mendeleev

$ wget 'http://localhost:2375/v1.35/containers/388b9861f31c/logs?stdout=true&stderr=true'
--2020-03-18 09:17:24--  http://localhost:2375/v1.35/containers/388b9861f31c/logs?stdout=true&stderr=true
Resolving localhost (localhost)... 127.0.0.1, ::1
Connecting to localhost (localhost)|127.0.0.1|:2375... connected.
HTTP request sent, awaiting response... 200 OK
Length: unspecified
Saving to: ‘logs@stdout=true&stderr=true’

logs@stdout=true&stderr=true                  [ <=>                                                                                  ]     983  --.-KB/s    in 0.001s

2020-03-18 09:17:25 (1.49 MB/s) - ‘logs@stdout=true&stderr=true’ saved [983]

$ cat -v logs\@stdout\=true\&stderr\=true | head -2
^A^@^@^@^@^@^@^A
^A^@^@^@^@^@^@^SHello from Docker!

String.trim() only removes whitespace characters, not binary characters, and the string will need to be split by newline characters to separate each line into its own string first. Then you chop off the first 8 characters from each line and concatenate all the lines back together into a string again. Or you can write a custom Stream to do that processing on the fly before a caller receives the string or Reader, although that wouldn't be a simple 30-minute fix.

[amihaiemil]

@tuxji Yes, the integration test calls a real Docker. However, it's on unix: https://github.com/amihaiemil/docker-java-api/blob/master/src/test/java/com/amihaiemil/docker/RtLogsITCase.java#L53

The test is simplistic however, only asserts the "startWith" case with the Docker "hello world" image.

I'll have a look on it and write a more complex test case. Maybe we should also set up a CI build on Windows.

Thank you for the details!

[tuxji]

Oh, I see that your test code calls logs.trim() before comparing it with "Hello from Docker!" I thought String.trim() removes only whitespace characters, but I found out I'm wrong; it has a loop which trims any characters less than or equal to a space character,

        while ((st < len) && (val[st] <= ' ')) {
            st++;
        }

That's why your test passed; the logs.trim() call indeed removed all the binary characters preceding the "Hello from Docker!" although it wouldn't have removed the following lines' binary characters.

I don't think you need to set up a CI build on Windows since Docker for Windows runs similar code in the backend server (the backend server even thinks it's running on Unix). A more complex test case (e.g., using StartsWith on the first two lines from the logs instead of only the first line) will catch the binary characters.

[amihaiemil]

@tuxji We just released a new version (0.0.12), with a fix for this problem, I believe. Can you check?

0.0.12 also contains the Container.wait() method :D

[tuxji]

Yes, the new 0.0.12 version fixes the problem really well and the new Container.wait() method is wonderful too! Thank you!

[amihaiemil]

@tuxji Glad it worked. Credits go to @lumimul :)

[0crat]

Job gh:amihaiemil/docker-java-api#302 is not assigned, can't get performer