Invalid log format for ... Failed to' (expected: "<timestamp> <txt>")

[msn1444]

I'm sure you guys hate me by now :)

This is related to: https://github.com/rhuss/docker-maven-plugin/issues/242

I saw it happen in 0.13.3-SNAPSHOT and also 0.13.4-SNAPSHOT. I posted about this in another pull request that got closed(so maybe you guys didn't see it?) but it probably makes sense to make another issue. I was able to replicate the issue here: https://github.com/mason/mvn-docker-plugin-bug

just do mvn clean install and you should see. attached is a screenshot. Also this only occurs on ubuntu as well. I've never seen this happen on mac.

[rhuss]

No, no, we love bug reports ;-) (because it manifests that ppl are using the software :)

Seems to be a bug when parsing the streaming answers. Could you provide a little bit more context, i.e. the point in the stack trace where the plugin kicks in ?

[msn1444]

So I'm not sure if the stack trace in the image is related to the datetime bugs. If I run the same mvn clean install twice, I will always get a stacktrace due to failed tests, but the timestamp error doesn't always appear.

to provide some more context, I have the maven docker plugin hooked into the pre-integration-phase of maven. Once that phase hits, it starts the docker containers. After starting the docker containers I run the tests within one of the running images. The tests fail due to misconfiguration and I get an invalid log error.

I ran the clean install a few times and I was able to generate a stacktrace from within the plugin.

Exception in thread "Thread-5" java.lang.IllegalArgumentException: Invalid format: "
�
�2015-08-13T15:24..."
    at org.joda.time.format.DateTimeFormatter.parseDateTime(DateTimeFormatter.java:873)
    at org.jolokia.docker.maven.util.Timestamp.<init>(Timestamp.java:53)
    at org.jolokia.docker.maven.access.log.LogRequestor.callLogCallback(LogRequestor.java:142)
    at org.jolokia.docker.maven.access.log.LogRequestor.parseResponse(LogRequestor.java:121)
    at org.jolokia.docker.maven.access.log.LogRequestor.run(LogRequestor.java:97)

[msn1444]

I've been doing some debugging and I've narrowed it down to:

private void callLogCallback(int type, String txt) in LogRequestor class. I put a println in the plugin. There seems to be some extra characters in the string.

private void callLogCallback(int type, String txt) throws LogCallback.DoneException {
        Matcher matcher = LOG_LINE.matcher(txt);
        if (!matcher.matches()) {
            System.out.println("****"+txt);
            callback.error("Invalid log format for '" + txt + "' (expected: \"<timestamp> <txt>\")");
            throw new LogCallback.DoneException();
        }
        Timestamp ts = new Timestamp(matcher.group(1));
        String logTxt = matcher.group(2);
        callback.log(type, ts, logTxt);
    }

****2015-08-13T16:31:33.559938558Z  at org.apach8

�
c9
2015-08-13T16:31:33.563377769Z test service - [main] WARN  k.producer.async.DefaultEventHandler - Failed to
Invalid log format for '2015-08-13T16:31:33.559938558Z  at org.apach8

�
c9
2015-08-13T16:31:33.563377769Z test service - [main] WARN  k.producer.async.DefaultEventHandler - Failed to' (expected: "<timestamp> <txt>")

[msn1444]

Here is what my main application looks like when I run the images. It's actually pretty bad :(

[rhuss]

I just pushed some changes which are supposed to fix this issue (can't really reproduce it here).

Could you please try out 0.13.4-SNAPSHOT ? It has been pushed to Maven central or you can build it on you own from branch integration

[mason]

Hey it didn't seem to work. Sorry for the late response. I deleted my ~/.m2 and did mvn clean install. The data coming through is still malformed when it gets printed to the screen. I am going to have to use a custom solution to my problem. Once this issue is resolved I will take another look. In the meantime I can work with you to get it resolved, but it will be one of the last things on my list of things to do since I am very busy with work.

[CyborTronik]

Seems there are going some special symbols at the beggining of line in log: Using version 0.13.4.

 
�2015-09-23T09:33:17.073199835Z 2015-09-23 09:33:17.072  INFO 1 --- [           main] s.b.c.e.t.TomcatEmbeddedServletContainer : Tomcat started on port(s): 8080 (http)
' (expected: "<timestamp> <txt>")

Why the build should be broken because of such thing ? Why for searching log is not used simple String.contains or something similar to avoid such blockers? Why is so necessary to parse the date or log format? Can we skip that? These things sounds strange to me.

[andreasaronsson]

I agree it should not fail the build when a log statement is unparseable. The logger implementation as it looks now makes me think it is hard to avoid. It could be easier to simplify that part of the code at the price of some features. I get the impression that there is more that one thread writing to the logger. When I run two containers simultaneously I sometimes get one of the outputs and sometimes two. Is it thread safe? I did a small experiment trying to decode the log data and simply ignore the bytes that were impossible to decode in utf-8. Did not help.

[rhuss]

The problem is, that each log line sent by the Docker daemon has a fixed format:

<8 bytes: 0 == type, 4-7 == length> ' [' <time stamp in fixed format> '] ' <log message>

That's also the reason for the funny bytes in the beginning (also they should have been already consumed). That had been fixed a while ago, so I need to check why this fix doesn't work.

Unfortunately this format is not officially defined in the documentation so it has been found empirically.

It would help tremendously if I could get hands on a (minimal) example which reproducably exhibits this behaviour.

@CyborTronik @mason @andreasaronsson @sebastiankirsch could you help me here ?

[andreasaronsson]

I have started trying to reproduce in a minimal example but not succeeded yet. As I already indicated I currently suspect there might be some thread safeness that is missing. In the full setup I was working on before the error appeared intermittently and I was able to run many times without error in succession and then it would fail multiple times in a row without touching the setup. This makes it harder to reproduce reliably and predictably. I will post again if/when I find the time to make the error appear more often. At least there is some information in the repo at this time. Sorry for not being able to be more helpful right away. https://github.com/andreasaronsson/doubledockerlogs.git

[sebastiankirsch]

Similar for me, although I gave it a shot: https://github.com/sebastiankirsch/docker-maven-plugin-issue259 If our company decides to open-source the application we are working on, I'll get back with that. The thing is, I could not reproduce the exact same error, but: pumping stdout to the Maven environment seizes to work randomly; which may or may not have the same root cause.

To reproduce the problem:

• execute mvn package
• execute mvn docker:stop; mvn docker:start several times

Execution of the Maven build step should result in a "successful build" because the application logged a specific string. Maybe you end up experiencing an Invalid log format error or logging seizes to work.

I even added several threads and all, but the funny thing is that our problematic application is based on Spring Boot and the Invalid log format oftentimes occurs shortly after the splash screen (which sometimes is incomplete) is printed; and afaik that's when the the application is still "single-threaded"; or at least the problem sometimes occurs before any other than the main thread does log something.

[andreasaronsson]

I have updated my example. After several iterations with different values I am not able to provoke the same behaviour. However, I think it is acting in a surprising way. The log output seems to block on one of the images. Also hangs when I expect it to continue. It is as if only one of the containers can produce output at the same time. Maybe I don't understand what the expected behavour is but FWIW..

[sebastiankirsch]

That made me realize that we as well are running 3 containers in parallel, so I updated my example to reflect that: https://github.com/sebastiankirsch/docker-maven-plugin-issue259

First run produced an error with a bad/broken chunk message. Didn't record it, didn't occur again :/

What one can see (after understanding what is logged by the Worker class) though is that lines are missing or empty, and sometimes, pumping data stops working for one of the containers.

[rhuss]

Thans for all your feedback. It looks indeed like it is an concurrency issue, so I will try to provoke it here, too.

[arman1371]

when i set <showLogs>true</showLogs> the maven project works successfully, but when i remove it, application hangs on stopping container.

[brian98point6]

true seems to not fix my maven build in my environment. I've put more details about my environment in a possibly related issue: https://github.com/fabric8io/docker-maven-plugin/issues/344

[brian98point6]

@rhuss After upgrading to v0.15.1, I'm still getting "Invalid format" half the time. However, the hanging issue seems to be gone.

Exception in thread "Thread-10" java.lang.IllegalArgumentException: Invalid format: "�2016-05-03T22:54:02.668Z"
    at org.joda.time.format.DateTimeFormatter.parseDateTime(DateTimeFormatter.java:899)
    at io.fabric8.maven.docker.util.Timestamp.<init>(Timestamp.java:61)
    at io.fabric8.maven.docker.access.log.LogRequestor.callLogCallback(LogRequestor.java:143)
    at io.fabric8.maven.docker.access.log.LogRequestor.parseResponse(LogRequestor.java:121)
    at io.fabric8.maven.docker.access.log.LogRequestor.run(LogRequestor.java:97)

[andreasaronsson]

After upgrading to 0.15.2 I haven't seen the problem in a good while.

[jdcasey]

I've just run into this problem. My environment is starting a gogs container with a git repo in it, then using that container from another container to do a git clone. I've diverted the logs to files, and the output in that file looks like this:

indy-git-subpath> Cloning into '/opt/indy/etc/indy'...
indy-git-subpath> POST git-upload-pack (242 bytes)
indy-git-subpath> remote: Counting objects: 25, done.        
Invalid log format for '2016-07-15T20:34:06.024029849Z remote: Compressing objects:   4% (1/23)           
remote: Compressing objects:   8% (2/23)           
remote: Compressing objects:  13% (3/23)           
remote: Compressing objects:  17% (4/23)           
remote: Compressing objects:  21% (5/23)           
remote: Compressing objects:  26% (6/23)           
remote: Compressing objects:  30% (7/23)           
remote: Compressing objects:  34% (8/23)           
remote: Compressing objects:  39% (9/23)           
remote: Compressing objects:  43% (10/23)           
remote: Compressing objects:  47% (11/23)           
remote: Compressing objects:  52% (12/23)           
remote: Compressing objects:  56% (13/23)           
remote: Compressing objects:  60% (14/23)           
remote: Compressing objects:  65% (15/23)           
remote: Compressing objects:  69% (16/23)           
remote: Compressing objects:  73% (17/23)           
remote: Compressing objects:  78% (18/23)           
remote: Compressing objects:  82% (19/23)           
remote: Compressing objects:  86% (20/23)           
remote: Compressing objects:  91% (21/23)           
remote: Compressing objects:  95% (22/23)           
remote: Compressing objects: 100% (23/23)           
remote: Compressing objects: 100% (23/23), done.        
' (expected: "<timestamp> <txt>") [0032 0030]

If you want to see it reproduced, it's popping up in:

repo: https://github.com/jdcasey/indy branch: master commit: 521564b8416bc6cce7f0f37cdb78c5eea3f95261

This was using 0.15.9, FWIW.

[jdcasey]

setting showLogs == true made the problem disappear magically.

[rhuss]

@jdcasey : In fact this is a race condition within the unix socket library we are using (more details in #344) which is not so easy solvable. I'm still on it (however no ETA, though ..)

[rhuss]

@jdcasey @mason @andreasaronsson @CyborTronik @sebastiankirsch @arman1371 @brian98point6 : When this issue bit you, how did you access the Docker daemon ?

Via

• TCP by setting DOCKER_HOST=tcp://....
• Unix-Socket (by not setting DOCKER_HOST or pointing to the unix socket path)

??

[brian98point6]

@rhuss I was accessing via unix socket when the issue bit us, but have since switched to TCP.

[jdcasey]

It looks like I was using the unix socket. I changed the pom.xml configuration to use:

<dockerHost>tcp://localhost:2375</dockerHost>

But I'm still seeing the same error. Maybe I made this change in the wrong place, or using the wrong value format? I put it in the top-level configuration for the plugin. I should also mention that I've got four image sections in my build. One is a test appliance furnishing a gogs server to the others. Of the other three, only one builds the image, while the remaining two provide alternative <run> configurations. This arrangement allows me to use the gogs test appliance to verify that Indy will start with a variety of configuration options.

The log-parsing failures inevitably happen when doing a git clone, but it's random which version of the image will fail to start.

[rhuss]

@jdcasey That's interesting since the the concurrency issue is bound to the unix socket variant. Any chance that you can share your configuration ? (The dokerHost config looks fine).

[jdcasey]

@rhuss I'm probably not configuring things correctly, but I'm having some trouble finding examples to follow. My configuration is at:

https://github.com/jdcasey/indy/blob/master/deployments/docker/pom.xml

[rhuss]

Thanks, I will check that tomorrow.

[sebastiankirsch]

We've been using the Unix socket (by not setting DOCKER_HOST). However, since upgrading to version 0.15.2, we didn't experience the problem anymore...

[rhuss]

@sebastiankirsch then you are probably lucky ;-) I dont think its really fixed but might happen less frequently with newer version (btw we are 0.15.10 at the moment, with 0.15.11 coming soon).

The alternative which should always work is to switch to TCP as their are no raced conditions.

[sebastiankirsch]

Is there a possibility that an OS update fixed the race condition? I can't believe we're that lucky...

[Gengar003]

Just occurred for me on dmp:0.15.11 on OSX 10.11.5:

$ ./mvnw --version
Apache Maven 3.3.9 (bb52d8502b132ec0a5a3f4c09453c07478323dc5; 2015-11-10T10:41:47-06:00)
Maven home: /Users/user/.m2/wrapper/dists/apache-maven-3.3.9-bin/2609u9g41na2l7ogackmif6fj2/apache-maven-3.3.9
Java version: 1.8.0_91, vendor: Oracle Corporation
Java home: /Library/Java/JavaVirtualMachines/jdk1.8.0_91.jdk/Contents/Home/jre
Default locale: en_US, platform encoding: UTF-8
OS name: "mac os x", version: "10.11.5", arch: "x86_64", family: "mac"

./mvnw --batch-mode ....

...

[INFO] --- docker-maven-plugin:0.15.11:start (container-tests-start) @ project ---

...

container-tests> Downloading: <snip>
Downloaded: <snip> (14 KB at 15.8 KB/sec)
' (expected: "<timestamp> <txt>") [0032 0030]

[rhuss]

Are you using the docker Unix socket ?

Gengar003 notifications@github.com schrieb am Mi., 20. Juli 2016, 17:18:

Just occurred for me on dmp:0.15.11 on OSX 10.11.5:

$ ./mvnw --version Apache Maven 3.3.9 (bb52d8502b132ec0a5a3f4c09453c07478323dc5; 2015-11-10T10:41:47-06:00) Maven home: /Users/user/.m2/wrapper/dists/apache-maven-3.3.9-bin/2609u9g41na2l7ogackmif6fj2/apache-maven-3.3.9 Java version: 1.8.0_91, vendor: Oracle Corporation Java home: /Library/Java/JavaVirtualMachines/jdk1.8.0_91.jdk/Contents/Home/jre Default locale: en_US, platform encoding: UTF-8 OS name: "mac os x", version: "10.11.5", arch: "x86_64", family: "mac"

./mvnw --batch-mode ....

...

[INFO] --- docker-maven-plugin:0.15.11:start (container-tests-start) @ project ---

...

container-tests> Downloading: Downloaded: (14 KB at 15.8 KB/sec) ' (expected: " ") [0032 0030]

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/fabric8io/docker-maven-plugin/issues/259#issuecomment-233982279, or mute the thread https://github.com/notifications/unsubscribe-auth/AAGDCCojmInaIiPka4o_7jDjjLQMoN5Dks5qXjxJgaJpZM4Fq-_c .

[Gengar003]

@rhuss I believe so - no Docker connection info is specified in any pom.xml configuration and the DOCKER_HOST environment variable does not exist in the shell, so it should attempt to use the unix socket, correct?