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

msn1444 · 2015-08-13T14:22:58Z

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.

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

rhuss · 2015-08-13T15:07:18Z

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 · 2015-08-13T15:29:34Z

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 · 2015-08-13T16:34:28Z

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 · 2015-08-13T16:47:26Z

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

Now a proper JSONTokener wrapping the input stream is used.

rhuss · 2015-08-18T08:08:47Z

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 · 2015-08-24T23:32:15Z

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 · 2015-09-23T09:38:22Z

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 · 2015-11-04T21:08:33Z

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 · 2015-12-09T15:28:17Z

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 · 2015-12-10T06:02:03Z

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 · 2015-12-10T12:44:51Z

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 · 2015-12-10T19:05:12Z

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 · 2015-12-11T09:22:16Z

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 · 2015-12-11T09:39:55Z

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

arman1371 · 2016-02-17T12:46:02Z

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

brian98point6 · 2016-05-02T21:06:45Z

true seems to not fix my maven build in my environment. I've put more details about my environment in a possibly related issue: #344

There seems to be issues with long running HTTP request like fetching logs with chunked encodings and pooling connections. It seems that connections get released to soon and then reused in a different context when there is still log data to read. Now logging uses a non-pooled, single connection client for doing async log fetching which hopefully resolves the issues reported in #344 and #259.

brian98point6 · 2016-05-03T22:57:02Z

@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 · 2016-05-26T11:07:30Z

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

jdcasey · 2016-07-15T20:43:19Z

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 · 2016-07-19T16:37:47Z

setting showLogs == true made the problem disappear magically.

rhuss · 2016-07-19T16:56:57Z

@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 · 2016-07-19T17:03:49Z

@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 · 2016-07-19T17:47:26Z

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

jdcasey · 2016-07-19T19:49:39Z

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 · 2016-07-19T20:14:04Z

@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 · 2016-07-19T20:36:58Z

@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 · 2016-07-19T20:45:24Z

Thanks, I will check that tomorrow.

sebastiankirsch · 2016-07-20T07:17:51Z

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 · 2016-07-20T07:22:38Z

@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 · 2016-07-20T07:26:08Z

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

Gengar003 · 2016-07-20T15:18:33Z

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 · 2016-07-20T15:29:25Z

Are you using the docker Unix socket ?

Gengar003 [email protected] 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
#259 (comment),
or mute the thread
https://github.com/notifications/unsubscribe-auth/AAGDCCojmInaIiPka4o_7jDjjLQMoN5Dks5qXjxJgaJpZM4Fq-_c
.

Gengar003 · 2016-07-20T15:33:02Z

@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?

where the logline pattern was bogus, in the case a frames returns multiple lines at once. I.e. it fixes this issue #259 (comment)

rhuss added a commit that referenced this issue Aug 18, 2015

Fixed handling of splitted JSON object in responses (#259)

7a37adc

Now a proper JSONTokener wrapping the input stream is used.

rhuss mentioned this issue Aug 18, 2015

Parsing Http Chunked Encoding fails sometimes #183

Closed

rhuss mentioned this issue Dec 9, 2015

Problem with the log stream #354

Closed

rhuss mentioned this issue Jan 20, 2016

weird behavior during log wait condition on during container start #344

Open

thomasvandoren mentioned this issue May 4, 2016

Refactor stream parsing to ensure safety. #436

Merged

rhuss added a commit that referenced this issue Jul 29, 2016

Add a partial fix for #259

16ade30

where the logline pattern was bogus, in the case a frames returns multiple lines at once. I.e. it fixes this issue #259 (comment)

This was referenced Aug 2, 2016

- parallel StartMojo #531

Closed

Add support for "Docker for Windows" #532

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

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

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

msn1444 commented Aug 13, 2015

rhuss commented Aug 13, 2015

msn1444 commented Aug 13, 2015

msn1444 commented Aug 13, 2015

msn1444 commented Aug 13, 2015

rhuss commented Aug 18, 2015

mason commented Aug 24, 2015

CyborTronik commented Sep 23, 2015

andreasaronsson commented Nov 4, 2015

rhuss commented Dec 9, 2015

andreasaronsson commented Dec 10, 2015

sebastiankirsch commented Dec 10, 2015

andreasaronsson commented Dec 10, 2015

sebastiankirsch commented Dec 11, 2015

rhuss commented Dec 11, 2015

arman1371 commented Feb 17, 2016

brian98point6 commented May 2, 2016

brian98point6 commented May 3, 2016

andreasaronsson commented May 26, 2016

jdcasey commented Jul 15, 2016 •

edited

Loading

jdcasey commented Jul 19, 2016 •

edited

Loading

rhuss commented Jul 19, 2016

rhuss commented Jul 19, 2016

brian98point6 commented Jul 19, 2016

jdcasey commented Jul 19, 2016

rhuss commented Jul 19, 2016

jdcasey commented Jul 19, 2016

rhuss commented Jul 19, 2016

sebastiankirsch commented Jul 20, 2016

rhuss commented Jul 20, 2016

sebastiankirsch commented Jul 20, 2016

Gengar003 commented Jul 20, 2016

rhuss commented Jul 20, 2016

Gengar003 commented Jul 20, 2016

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

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

Comments

msn1444 commented Aug 13, 2015

rhuss commented Aug 13, 2015

msn1444 commented Aug 13, 2015

msn1444 commented Aug 13, 2015

msn1444 commented Aug 13, 2015

rhuss commented Aug 18, 2015

mason commented Aug 24, 2015

CyborTronik commented Sep 23, 2015

andreasaronsson commented Nov 4, 2015

rhuss commented Dec 9, 2015

andreasaronsson commented Dec 10, 2015

sebastiankirsch commented Dec 10, 2015

andreasaronsson commented Dec 10, 2015

sebastiankirsch commented Dec 11, 2015

rhuss commented Dec 11, 2015

arman1371 commented Feb 17, 2016

brian98point6 commented May 2, 2016

brian98point6 commented May 3, 2016

andreasaronsson commented May 26, 2016

jdcasey commented Jul 15, 2016 • edited Loading

jdcasey commented Jul 19, 2016 • edited Loading

rhuss commented Jul 19, 2016

rhuss commented Jul 19, 2016

brian98point6 commented Jul 19, 2016

jdcasey commented Jul 19, 2016

rhuss commented Jul 19, 2016

jdcasey commented Jul 19, 2016

rhuss commented Jul 19, 2016

sebastiankirsch commented Jul 20, 2016

rhuss commented Jul 20, 2016

sebastiankirsch commented Jul 20, 2016

Gengar003 commented Jul 20, 2016

rhuss commented Jul 20, 2016

Gengar003 commented Jul 20, 2016

jdcasey commented Jul 15, 2016 •

edited

Loading

jdcasey commented Jul 19, 2016 •

edited

Loading