Failing to parse log timestamps

[tobias]

While trying to build https://github.com/debezium/debezium, the plugin fails when waiting for a mysql container to fully start:

INFO] DOCKER> ... Trying to pull repository docker.io/mysql/mysql-server ...
[INFO] DOCKER> ... 5.7 Pulling from mysql/mysql-server
[INFO] DOCKER> ... Digest: sha256:8df5b9e5a87a423c47311ec4b7142d2aa8ae31ca334080c2e957c3cbae76ed4c
[INFO] DOCKER> ... Status: Image is up to date for docker.io/mysql/mysql-server:5.7
[INFO] DOCKER> [mysql/mysql-server:5.7] "database": Start container 62de4215123b
[ERROR] DOCKER> IO Error while requesting logs: org.apache.http.impl.execchain.RequestAbortedException: Request aborted
[ERROR] DOCKER> [mysql/mysql-server:5.7] "database": Timeout after 33535 ms while waiting on log out 'MySQL init process done. Ready for start up.'
[ERROR] DOCKER> Error occurred during container startup, shutting down...
Exception in thread "Thread-7" java.lang.IllegalArgumentException: Invalid format: "2016-03-16T17:05:18.880080000-04:00.000" is malformed at ".000"
    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:142)
    at io.fabric8.maven.docker.access.log.LogRequestor.parseResponse(LogRequestor.java:121)
    at io.fabric8.maven.docker.access.log.LogRequestor.run(LogRequestor.java:97)
[INFO] DOCKER> [mysql/mysql-server:5.7] "database": Stop and remove container 62de4215123b

From looking at it in the debugger, the timestamp from the log line is 2016-03-16T17:06:30.714387000-04:00, which fails to match all the groups in https://github.com/fabric8io/docker-maven-plugin/blob/master/src/main/java/io/fabric8/maven/docker/util/Timestamp.java#L35, and the full string is returned from matcher.group(1) here: https://github.com/fabric8io/docker-maven-plugin/blob/master/src/main/java/io/fabric8/maven/docker/util/Timestamp.java#L61 (groups 2-4 are [null, null, ""]).

Since I don't have access to a working setup, I'm not sure what the expected timestamp format from docker is supposed to be. I also don't know enough about docker to know why my environment would be different from others.

I'm running this with:

$ mvn -version
Apache Maven 3.3.3 (7994120775791599e205a5524ec3e0dfe41d4a06; 2015-04-22T07:57:37-04:00)
Maven home: /opt/tools/maven
Java version: 1.8.0_72, vendor: Oracle Corporation
Java home: /usr/lib/jvm/java-1.8.0-openjdk-1.8.0.72-9.b16.fc23.x86_64/jre
Default locale: en_US, platform encoding: UTF-8
OS name: "linux", version: "4.4.3-300.fc23.x86_64", arch: "amd64", family: "unix"
$ docker version
Client:
 Version:         1.9.1
 API version:     1.21
 Package version: docker-1.9.1-6.git6ec29ef.fc23.x86_64
 Go version:      go1.5.3
 Git commit:      7206621
 Built:           Mon Jan 25 20:52:22 UTC 2016
 OS/Arch:         linux/amd64

Server:
 Version:         1.9.1
 API version:     1.21
 Package version: docker-1.9.1-6.git6ec29ef.fc23.x86_64
 Go version:      go1.5.3
 Git commit:      7206621
 Built:           Mon Jan 25 20:52:22 UTC 2016
 OS/Arch:         linux/amd64

Let me know if I can provide any other information.

[rhauch]

This is the output of docker logs --follow -t database on OS X (on which the plugin works fine):

2016-03-16T21:50:48.949423377Z Initializing database
2016-03-16T21:50:52.143363444Z Database initialized
2016-03-16T21:50:52.158930834Z MySQL init process in progress...
2016-03-16T21:50:53.622607357Z Warning: Unable to load '/usr/share/zoneinfo/iso3166.tab' as time zone. Skipping it.
2016-03-16T21:50:54.543288588Z Warning: Unable to load '/usr/share/zoneinfo/zone.tab' as time zone. Skipping it.
2016-03-16T21:50:54.593162120Z mysql: [Warning] Using a password on the command line interface can be insecure.
2016-03-16T21:50:54.602620586Z mysql: [Warning] Using a password on the command line interface can be insecure.
2016-03-16T21:50:54.613296652Z mysql: [Warning] Using a password on the command line interface can be insecure.
2016-03-16T21:50:54.619072634Z mysql: [Warning] Using a password on the command line interface can be insecure.
2016-03-16T21:50:54.623387512Z 
2016-03-16T21:50:54.625087037Z /entrypoint.sh: running /docker-entrypoint-initdb.d/connector-test-db.sql
2016-03-16T21:50:54.630190486Z mysql: [Warning] Using a password on the command line interface can be insecure.
2016-03-16T21:50:54.677179998Z 
2016-03-16T21:50:54.677208736Z 
2016-03-16T21:50:54.677213593Z /entrypoint.sh: running /docker-entrypoint-initdb.d/empty-db.sql
2016-03-16T21:50:54.683729666Z mysql: [Warning] Using a password on the command line interface can be insecure.
2016-03-16T21:50:54.687541573Z 
2016-03-16T21:50:54.687560123Z 
2016-03-16T21:50:54.687564826Z /entrypoint.sh: running /docker-entrypoint-initdb.d/readbinlog.sql
2016-03-16T21:50:54.692472465Z mysql: [Warning] Using a password on the command line interface can be insecure.
2016-03-16T21:50:54.697990344Z 
2016-03-16T21:50:54.698010103Z 
2016-03-16T21:50:54.698014774Z /entrypoint.sh: running /docker-entrypoint-initdb.d/say-hello.sh
2016-03-16T21:50:54.701098322Z Hello, test!
2016-03-16T21:50:54.701117062Z 
2016-03-16T21:50:56.393555228Z 
2016-03-16T21:50:56.393657961Z MySQL init process done. Ready for start up.
2016-03-16T21:50:56.394369403Z 

Notice the two variations in timestamps:

• 2016-03-16T21:50:56.394369403Z on OS X
• 2016-03-16T17:06:30.714387000-04:00 on Fedora

BTW, on OS X:

$ mvn -version
Apache Maven 3.3.3 (7994120775791599e205a5524ec3e0dfe41d4a06; 2015-04-22T06:57:37-05:00)
Maven home: /usr/local/maven
Java version: 1.8.0_74, vendor: Oracle Corporation
Java home: /Library/Java/JavaVirtualMachines/jdk1.8.0_74.jdk/Contents/Home/jre
Default locale: en_US, platform encoding: UTF-8
OS name: "mac os x", version: "10.11.3", arch: "x86_64", family: "mac"

$ docker version
Client:
 Version:      1.10.1
 API version:  1.22
 Go version:   go1.5.3
 Git commit:   9e83765
 Built:        Thu Feb 11 19:14:21 2016
 OS/Arch:      darwin/amd64

Server:
 Version:      1.10.1
 API version:  1.22
 Go version:   go1.5.3
 Git commit:   9e83765
 Built:        Thu Feb 11 20:39:58 2016
 OS/Arch:      linux/amd64

[tobias]

My output from docker logs --follow -t database, for a full comparison:

2016-03-17T09:18:38.924342000-04:00 Initializing database
2016-03-17T09:18:44.934079000-04:00 Database initialized
2016-03-17T09:18:44.948957000-04:00 MySQL init process in progress...
2016-03-17T09:18:46.995085000-04:00 Warning: Unable to load '/usr/share/zoneinfo/iso3166.tab' as time zone. Skipping it.
2016-03-17T09:18:48.978583000-04:00 Warning: Unable to load '/usr/share/zoneinfo/zone.tab' as time zone. Skipping it.
2016-03-17T09:18:49.053402000-04:00 mysql: [Warning] Using a password on the command line interface can be insecure.
2016-03-17T09:18:49.069207000-04:00 mysql: [Warning] Using a password on the command line interface can be insecure.
2016-03-17T09:18:49.080276000-04:00 mysql: [Warning] Using a password on the command line interface can be insecure.
2016-03-17T09:18:49.090560000-04:00 mysql: [Warning] Using a password on the command line interface can be insecure.
2016-03-17T09:18:49.099773000-04:00 /entrypoint.sh: running /docker-entrypoint-initdb.d/connector-test-db.sql
2016-03-17T09:18:49.101729000-04:00 mysql: [Warning] Using a password on the command line interface can be insecure.
2016-03-17T09:18:49.435479000-04:00 /entrypoint.sh: running /docker-entrypoint-initdb.d/empty-db.sql
2016-03-17T09:18:49.438464000-04:00 mysql: [Warning] Using a password on the command line interface can be insecure.
2016-03-17T09:18:49.457440000-04:00 /entrypoint.sh: running /docker-entrypoint-initdb.d/readbinlog.sql
2016-03-17T09:18:49.459853000-04:00 mysql: [Warning] Using a password on the command line interface can be insecure.
2016-03-17T09:18:49.478212000-04:00 /entrypoint.sh: running /docker-entrypoint-initdb.d/say-hello.sh
2016-03-17T09:18:49.478586000-04:00 Hello, test!
2016-03-17T09:18:51.164997000-04:00 MySQL init process done. Ready for start up.

[goldmann]

This should help: https://docs.docker.com/engine/reference/commandline/logs/

The local timezone on the client will be used if you do not provide either a Z or a +-00:00 timezone offset at the end of the timestamp.

[tobias]

@goldmann I read that as the client TZ will only be used when parsing the --since flag. But that made me realize the difference - Z represents GMT, and -04:00 is my TZ offset from GMT. I don't know why docker is using my local time instead of GMT, but I think the regex in Timestamp.java just needs to be adjusted to account for numeric TZ offsets.

I'd be happy to provide a PR for this, assuming the maintainers agree with this assessment.

[goldmann]

Right, the problem is that it may be an undocumented "feature"...

[rhuss]

Thanks for reporting this and for the analysis ! Indeed, the regexp was a bit sloppy in not capturing a numeric timezone. Unfortunately the timeformat used in the REST API is not really well documented.

I adapted the regexp and pushed a 0.14.3-SNAPSHOT release to Maven central. @tobias maybe you could try this whether it works for you ?

[tobias]

@rhuss that did the trick, thanks!

However, I noticed your regex only handles negative offsets - if I set my TZ to somewhere on the other side of UTC (in this case, Europe/Amsterdam), I get a + prefix for the offset, which breaks the plugin.

From docker logs --follow -t database:

2016-03-18T18:06:13.674352000+01:00 Initializing database
2016-03-18T18:06:19.346911000+01:00 Database initialized 
2016-03-18T18:06:19.356696000+01:00 MySQL init process in progress...

From the plugin:

Exception in thread "Thread-7" java.lang.IllegalArgumentException: Invalid format: "2016-03-18T18:06:13.674352000+01:00.000null" is malformed at ".000null"
    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:142)
    at io.fabric8.maven.docker.access.log.LogRequestor.parseResponse(LogRequestor.java:121)
    at io.fabric8.maven.docker.access.log.LogRequestor.run(LogRequestor.java:97)

[rhuss]

of course, you are right (sorry, was too fast ans looked to be too easy to fix :)

Fixed it (and also for time offsets without minutes), deployed a next shapshot, too.

thx ...

[tobias]

Thanks @rhuss. Do you have an estimate of when this will be in a release?

[rhauch]

@rhuss Might this go into a release soon?

[christian-posta]

+1 would love to have this released soon :)

[rhuss]

@rhauch @christian-posta @tobias will do a release today or tomorrow. Sorry for the delay ...

[rhauch]

@rhuss, will this be included in the 0.15.0 release, or are you planning a 0.14.x fix release?

[rhuss]

Just building a 0.15.0 release, will be available in some minutes. So the answer is yes :)

[rhauch]

@rhuss, sweet. Thanks for fixing these issues. Love the plugin.

[rhuss]

thanks :) 0.15.0 is out, should bubble to Maven central soon. Let me know whether it works for you ...