Timestamps on messages

Details

Description

With current and/or moving forward with M2, I would like an option for timestamped messages.

We have a somewhat long nightly process. I regularly wish for timestamps on the log messages from the Maven build. The two primary reasons for this are duration calculation - how long did something take, and an occasional correlation with an outside event.

Issue Links

is related to

Improvement - An improvement or enhancement to an existing feature or task. MNG-4859 Console output pattern should be customizable

  • Major - Major loss of function.
  • Open - The issue is open and ready for the assignee to start work on it.

Activity

Ascending order - Click to sort in descending order
Hide
Permalink
Brett Porter added a comment -

sounds like a good optional enhancement to m2.

For m1, we won't be changing the logging - it currently uses log4j so you can customise the log4j settings built into maven.jar so that a timestamp is output.

Show
Brett Porter added a comment - sounds like a good optional enhancement to m2. For m1, we won't be changing the logging - it currently uses log4j so you can customise the log4j settings built into maven.jar so that a timestamp is output.
Hide
Permalink
Brett Porter added a comment -

on the wishlist

Show
Brett Porter added a comment - on the wishlist
Hide
Permalink
Jerome Lacoste added a comment -

As a work-around it is possible to pipe the output to a script that will add the timestamp for you. On Linux, you can use the ts perl script.

Show
Jerome Lacoste added a comment - As a work-around it is possible to pipe the output to a script that will add the timestamp for you. On Linux, you can use the ts perl script.
Hide
Permalink
Julien HENRY added a comment -

I second this request. I want to find what part of the build is consuming time. And the work-around seems not possible with Continuum.

Show
Julien HENRY added a comment - I second this request. I want to find what part of the build is consuming time. And the work-around seems not possible with Continuum.
Hide
Permalink
Julien HENRY added a comment -

I think I have a better workaround.

1) Edit $MAVEN_HOME/lib/maven-2.2.1-uber.jar!org/codehaus/plexus/plexus-bootstrap.xml
Replace:

<component>
  <role>org.codehaus.plexus.logging.LoggerManager</role>
  <implementation>org.codehaus.plexus.logging.console.ConsoleLoggerManager</implementation>
  <lifecycle-handler>basic</lifecycle-handler>
  <configuration>
    <threshold>info</threshold>
  </configuration>
</component>

by

<component>
  <role>org.codehaus.plexus.logging.LoggerManager</role>
  <implementation>
    org.codehaus.plexus.logging.slf4j.Slf4jLoggerManager
  </implementation>
</component>

2) Download and move into $MAVEN_HOME/lib:
plexus-slf4j-logging-1.1-alpha-1.jar
slf4j-api-1.5.8.jar
And also the slf4j implementation you want to use (in my case it is logback):
logback-core-0.9.15.jar
logback-classic-0.9.15.jar

3) To configure logback you can use a logback.xml file. The only trick is that Maven loader will only pick JAR file in /lib folder so you can simply create a new JAR containing only logback.xml

For example here is my logback.xml:

<?xml version="1.0" encoding="UTF-8" ?>
    <!-- Logback configuration file -->
<configuration>

    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
      <layout class="ch.qos.logback.classic.PatternLayout">
          <!--Pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</Pattern-->
          <Pattern>%-5level %d{HH:mm:ss.SSS} %msg%n</Pattern>
      </layout>
    </appender>
  
    <root>
        <level value="INFO" />
        <appender-ref ref="STDOUT" />
    </root>
</configuration>

And finally:

>mvn clean
INFO  15:01:32.785 Scanning for projects...
INFO  15:01:32.972 Reactor build order:
...
...
INFO  15:01:34.082 ------------------------------------------------------------------------
INFO  15:01:34.082 BUILD SUCCESSFUL
INFO  15:01:34.082 ------------------------------------------------------------------------
INFO  15:01:34.097 Total time: 1 second
INFO  15:01:34.097 Finished at: Fri Aug 14 15:01:34 CEST 2009
INFO  15:01:34.160 Final Memory: 7M/13M
INFO  15:01:34.160 ------------------------------------------------------------------------
There was no such logger 'org.apache.maven.artifact.metadata.ArtifactMetadataSource:maven' 18061339.
There was no such logger 'org.apache.maven.plugin.PluginMappingManager' 18061339.
There was no such logger 'org.apache.maven.artifact.resolver.ArtifactResolver' 18061339.
There was no such logger 'org.apache.maven.artifact.transform.ArtifactTransformation:snapshot' 18061339.
There was no such logger 'org.apache.maven.profiles.MavenProfilesBuilder' 18061339.

There are two issues with this solution:
1) The -X flag does nothing. You have to manually update logback.xml to change INFO to DEBUG.
2) I don't know why there is the lines:

There was no such logger 'org.apache.maven.profiles.MavenProfilesBuilder' 18061339.

at the end...

Hope that help.

Show
Julien HENRY added a comment - I think I have a better workaround. 1) Edit $MAVEN_HOME/lib/maven-2.2.1-uber.jar!org/codehaus/plexus/plexus-bootstrap.xml Replace: 
<component>
  <role>org.codehaus.plexus.logging.LoggerManager</role>
  <implementation>org.codehaus.plexus.logging.console.ConsoleLoggerManager</implementation>
  <lifecycle-handler>basic</lifecycle-handler>
  <configuration>
    <threshold>info</threshold>
  </configuration>
</component>
by 
<component>
  <role>org.codehaus.plexus.logging.LoggerManager</role>
  <implementation>
    org.codehaus.plexus.logging.slf4j.Slf4jLoggerManager
  </implementation>
</component>
2) Download and move into $MAVEN_HOME/lib: plexus-slf4j-logging-1.1-alpha-1.jar slf4j-api-1.5.8.jar And also the slf4j implementation you want to use (in my case it is logback): logback-core-0.9.15.jar logback-classic-0.9.15.jar 3) To configure logback you can use a logback.xml file. The only trick is that Maven loader will only pick JAR file in /lib folder so you can simply create a new JAR containing only logback.xml For example here is my logback.xml: 
<?xml version="1.0" encoding="UTF-8" ?>
    <!-- Logback configuration file -->
<configuration>

    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
      <layout class="ch.qos.logback.classic.PatternLayout">
          <!--Pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</Pattern-->
          <Pattern>%-5level %d{HH:mm:ss.SSS} %msg%n</Pattern>
      </layout>
    </appender>
  
    <root>
        <level value="INFO" />
        <appender-ref ref="STDOUT" />
    </root>
</configuration>
And finally: 
>mvn clean
INFO  15:01:32.785 Scanning for projects...
INFO  15:01:32.972 Reactor build order:
...
...
INFO  15:01:34.082 ------------------------------------------------------------------------
INFO  15:01:34.082 BUILD SUCCESSFUL
INFO  15:01:34.082 ------------------------------------------------------------------------
INFO  15:01:34.097 Total time: 1 second
INFO  15:01:34.097 Finished at: Fri Aug 14 15:01:34 CEST 2009
INFO  15:01:34.160 Final Memory: 7M/13M
INFO  15:01:34.160 ------------------------------------------------------------------------
There was no such logger 'org.apache.maven.artifact.metadata.ArtifactMetadataSource:maven' 18061339.
There was no such logger 'org.apache.maven.plugin.PluginMappingManager' 18061339.
There was no such logger 'org.apache.maven.artifact.resolver.ArtifactResolver' 18061339.
There was no such logger 'org.apache.maven.artifact.transform.ArtifactTransformation:snapshot' 18061339.
There was no such logger 'org.apache.maven.profiles.MavenProfilesBuilder' 18061339.
There are two issues with this solution: 1) The -X flag does nothing. You have to manually update logback.xml to change INFO to DEBUG. 2) I don't know why there is the lines: 
There was no such logger 'org.apache.maven.profiles.MavenProfilesBuilder' 18061339.
at the end... Hope that help.
Hide
Permalink
Jeff Jensen added a comment -

Good idea. Additionally, if Maven could use a property for the pattern with a default, such as this example logback pattern,

<pattern>${maven.logger.pattern:-%date %contextName [%thread] %-5level %-40logger{40} %mdc: %marker: %msg%n}</pattern>

users can then easily set it.

Show
Jeff Jensen added a comment - Good idea. Additionally, if Maven could use a property for the pattern with a default, such as this example logback pattern, 
<pattern>${maven.logger.pattern:-%date %contextName [%thread] %-5level %-40logger{40} %mdc: %marker: %msg%n}</pattern>
users can then easily set it.
Hide
Permalink
Scott MacDonald added a comment -

I'm not sure what is more amazing...That maven does not support timestamped logs, or that I have been a maven user for so many years and only just noticed.

Show
Scott MacDonald added a comment - I'm not sure what is more amazing...That maven does not support timestamped logs, or that I have been a maven user for so many years and only just noticed.
Hide
Permalink
Alex Ioffe added a comment -

How do you perform the above workaround for maven 3.0.3???

Show
Alex Ioffe added a comment - How do you perform the above workaround for maven 3.0.3???
Hide
Permalink
Mark Michaelis added a comment -

I am quite satisfied with the shell script I am using. Unfortunately it works only on Linux – maybe with Cygwin, too:

#!/bin/bash
#
# Prepends a date string in front of the Maven output.
# A workaround for http://jira.codehaus.org/browse/MNG-519 "Timestamps on messages"

[ -z "${AWK}" ] && AWK="$(which gawk 2>/dev/null)" || AWK="$(which awk 2>/dev/null)" || { echo "Error: Could not find AWK tool."; exit 1; }
"${AWK}" 'BEGIN { print strftime("%Y-%m-%d %H:%M:%S"); }' 2>&1 > /dev/null || { echo "Error: your AWK version does not support strftime() function." && exit 1; }

mvn "${@}" 2>&1 |"${AWK}" '{ print strftime("%Y-%m-%d %H:%M:%S"), $0; fflush(); }'
# see comp.unix.shell FAQ: (http://cfajohnson.com/shell/cus-faq-2.html)
# "How do I get the exit code of cmd1 in cmd1|cmd2"
exit ${PIPESTATUS[0]}

Follow the link to my Gist for the most recent version.

Show
Mark Michaelis added a comment - I am quite satisfied with the shell script I am using. Unfortunately it works only on Linux – maybe with Cygwin, too: 
#!/bin/bash
#
# Prepends a date string in front of the Maven output.
# A workaround for http://jira.codehaus.org/browse/MNG-519 "Timestamps on messages"

[ -z "${AWK}" ] && AWK="$(which gawk 2>/dev/null)" || AWK="$(which awk 2>/dev/null)" || { echo "Error: Could not find AWK tool."; exit 1; }
"${AWK}" 'BEGIN { print strftime("%Y-%m-%d %H:%M:%S"); }' 2>&1 > /dev/null || { echo "Error: your AWK version does not support strftime() function." && exit 1; }

mvn "${@}" 2>&1 |"${AWK}" '{ print strftime("%Y-%m-%d %H:%M:%S"), $0; fflush(); }'
# see comp.unix.shell FAQ: (http://cfajohnson.com/shell/cus-faq-2.html)
# "How do I get the exit code of cmd1 in cmd1|cmd2"
exit ${PIPESTATUS[0]}
Follow the link to my Gist for the most recent version.

People

  • Assignee:
    Unassigned
    Reporter:
    Jeff Jensen
Vote (15)
Watch (13)

Dates

  • Created:
    Updated: