2-phase logging

classic Classic list List threaded Threaded
11 messages Options
Reply | Threaded
Open this post in threaded view
|

2-phase logging

hans_d
Administrator
I'm not happy with the logging behavior of Gradle, Ant or Maven.

I think there is too much information printed out to the console,  
making it hard to figure out the important bits (for example an  
unusual warning).

I would like to improve this and have the following idea:

A log of a successful build would look roughly like this:

-- resources (0 sec)
-- compile (2 sec)
-- test (13 sec)
-- libs (35 sec)
-- integTest (40 sec)
Build Successful: Total time 60 sec

We only show the task names that get executed.

If there are log messages with a level higher than info we write them  
to the console:

-- resources (0 sec)
[warning] some message
-- compile (2 sec)
-- test (13 sec)
-- libs (35 sec)
-- integTest (40 sec)
Build Successful: Total time 60 sec

This leaves us with three problems.

1.) If there is an exception, just showing the stacktrace and the  
exception message is not necessarily enough to figure out the reason  
for the exception. For example the ant javac task throws an exception  
if the code does not compile, but this exception points to the  
earlier log output to learn about the details. The solution I have in  
mind would be to record all the logging. In case of an exception we  
print the log of the complete build to the console. The user can  
configure which log level should be recorded. The default is INFO.

2.) There has to be some kind of progress indicator, to inform the  
user whether there is a stall and to make it more exciting to look at  
the log (psychological acceleration ;) ).
I 'm not sure what is the best solution here. One solution would be  
to print dots according to a certain algorithm which is based on  
incoming log statements. The other solution would require more  
console magic. Gradle would show only for example three log  
statements. If a new log statement comes in the first one disappears.  
This log statement 'window' would move down if a new task is getting  
executed. At the end of the build no normal log statement would be  
visible.

3.) If the build is stalled you want to interrupt it and learn about  
the reasons. Therefore we would implement a shutdown hook for the  
JVM. This hook would print the complete recorded log to the console  
(similar to the exception case).

Additionally, the log can be written to a file. This will always be  
the normal log, not the reduced form of the console. The log level of  
the file log can be chosen independently. Of course if people don't  
like the reduced form they can always switch to normal logging. The  
Gradle logging behavior is either configurable via the command line  
or by properties set in the gradle.properties file (either in the  
project or in the gradle user home dir).

I use the term 2-phase logging for this. If you have other ideas for  
the terminology please let us know.

What do you think about all this?

- Hans

--
Hans Dockter
Gradle Project lead
http://www.gradle.org

---------------------------------------------------------------------
To unsubscribe from this list, please visit:

    http://xircles.codehaus.org/manage_email


Reply | Threaded
Open this post in threaded view
|

Re: 2-phase logging

kkrugler
Hi Hans,

In general I think this would be a nice improvement over Ant/Maven build output.

See below for some short inline comments.

-- Ken

hdockter wrote
I'm not happy with the logging behavior of Gradle, Ant or Maven.

I think there is too much information printed out to the console,  
making it hard to figure out the important bits (for example an  
unusual warning).

I would like to improve this and have the following idea:

A log of a successful build would look roughly like this:

-- resources (0 sec)
-- compile (2 sec)
-- test (13 sec)
-- libs (35 sec)
-- integTest (40 sec)
Build Successful: Total time 60 sec

We only show the task names that get executed.

If there are log messages with a level higher than info we write them  
to the console:

-- resources (0 sec)
[warning] some message
-- compile (2 sec)
-- test (13 sec)
-- libs (35 sec)
-- integTest (40 sec)
Build Successful: Total time 60 sec

This leaves us with three problems.

1.) If there is an exception, just showing the stacktrace and the  
exception message is not necessarily enough to figure out the reason  
for the exception. For example the ant javac task throws an exception  
if the code does not compile, but this exception points to the  
earlier log output to learn about the details. The solution I have in  
mind would be to record all the logging. In case of an exception we  
print the log of the complete build to the console. The user can  
configure which log level should be recorded. The default is INFO.

KK: Yes, definitely

2.) There has to be some kind of progress indicator, to inform the  
user whether there is a stall and to make it more exciting to look at  
the log (psychological acceleration ;) ).
I 'm not sure what is the best solution here. One solution would be  
to print dots according to a certain algorithm which is based on  
incoming log statements. The other solution would require more  
console magic. Gradle would show only for example three log  
statements. If a new log statement comes in the first one disappears.  
This log statement 'window' would move down if a new task is getting  
executed. At the end of the build no normal log statement would be  
visible.

KK: I would do something simple - e.g. print a dot for each logging call

3.) If the build is stalled you want to interrupt it and learn about  
the reasons. Therefore we would implement a shutdown hook for the  
JVM. This hook would print the complete recorded log to the console  
(similar to the exception case).

KK: Good idea, yes

Additionally, the log can be written to a file. This will always be  
the normal log, not the reduced form of the console. The log level of  
the file log can be chosen independently. Of course if people don't  
like the reduced form they can always switch to normal logging. The  
Gradle logging behavior is either configurable via the command line  
or by properties set in the gradle.properties file (either in the  
project or in the gradle user home dir).

I use the term 2-phase logging for this. If you have other ideas for  
the terminology please let us know.

What do you think about all this?

- Hans

--
Hans Dockter
Gradle Project lead
http://www.gradle.org

---------------------------------------------------------------------
To unsubscribe from this list, please visit:

    http://xircles.codehaus.org/manage_email
Reply | Threaded
Open this post in threaded view
|

Re: 2-phase logging

Xavier Hanin
In reply to this post by hans_d
Overall I like this idea too. There's one thing which can become tricky is handling the processing of logs if you use the parallel ant task. removing the last log line when you have concurrent logging require good thought and good testing.

Xavier

On Mon, Apr 28, 2008 at 8:34 PM, Hans Dockter <[hidden email]> wrote:
I'm not happy with the logging behavior of Gradle, Ant or Maven.

I think there is too much information printed out to the console, making it hard to figure out the important bits (for example an unusual warning).

I would like to improve this and have the following idea:

A log of a successful build would look roughly like this:

-- resources (0 sec)
-- compile (2 sec)
-- test (13 sec)
-- libs (35 sec)
-- integTest (40 sec)
Build Successful: Total time 60 sec

We only show the task names that get executed.

If there are log messages with a level higher than info we write them to the console:

-- resources (0 sec)
[warning] some message
-- compile (2 sec)
-- test (13 sec)
-- libs (35 sec)
-- integTest (40 sec)
Build Successful: Total time 60 sec

This leaves us with three problems.

1.) If there is an exception, just showing the stacktrace and the exception message is not necessarily enough to figure out the reason for the exception. For example the ant javac task throws an exception if the code does not compile, but this exception points to the earlier log output to learn about the details. The solution I have in mind would be to record all the logging. In case of an exception we print the log of the complete build to the console. The user can configure which log level should be recorded. The default is INFO.

2.) There has to be some kind of progress indicator, to inform the user whether there is a stall and to make it more exciting to look at the log (psychological acceleration ;) ).
I 'm not sure what is the best solution here. One solution would be to print dots according to a certain algorithm which is based on incoming log statements. The other solution would require more console magic. Gradle would show only for example three log statements. If a new log statement comes in the first one disappears. This log statement 'window' would move down if a new task is getting executed. At the end of the build no normal log statement would be visible.

3.) If the build is stalled you want to interrupt it and learn about the reasons. Therefore we would implement a shutdown hook for the JVM. This hook would print the complete recorded log to the console (similar to the exception case).

Additionally, the log can be written to a file. This will always be the normal log, not the reduced form of the console. The log level of the file log can be chosen independently. Of course if people don't like the reduced form they can always switch to normal logging. The Gradle logging behavior is either configurable via the command line or by properties set in the gradle.properties file (either in the project or in the gradle user home dir).

I use the term 2-phase logging for this. If you have other ideas for the terminology please let us know.

What do you think about all this?

- Hans

--
Hans Dockter
Gradle Project lead
http://www.gradle.org

---------------------------------------------------------------------
To unsubscribe from this list, please visit:

  http://xircles.codehaus.org/manage_email





--
Xavier Hanin - Independent Java Consultant
http://xhab.blogspot.com/
http://ant.apache.org/ivy/
http://www.xoocode.org/
Reply | Threaded
Open this post in threaded view
|

Re: 2-phase logging

hans_d
Administrator
Hi Xavier,

great to see you on the list :)

On May 5, 2008, at 1:57 PM, Xavier Hanin wrote:
Overall I like this idea too. There's one thing which can become tricky is handling the processing of logs if you use the parallel ant task. removing the last log line when you have concurrent logging require good thought and good testing.

I'm not sure if I understand. Therefore a stupid question. The problem you mention here would occur if Gradle would go for the approach of having a 'command-line window' of the last three or whatever log statements? It would be no problem if we would use dots, right?

- Hans



Xavier

On Mon, Apr 28, 2008 at 8:34 PM, Hans Dockter <[hidden email]> wrote:
I'm not happy with the logging behavior of Gradle, Ant or Maven.

I think there is too much information printed out to the console, making it hard to figure out the important bits (for example an unusual warning).

I would like to improve this and have the following idea:

A log of a successful build would look roughly like this:

-- resources (0 sec)
-- compile (2 sec)
-- test (13 sec)
-- libs (35 sec)
-- integTest (40 sec)
Build Successful: Total time 60 sec

We only show the task names that get executed.

If there are log messages with a level higher than info we write them to the console:

-- resources (0 sec)
[warning] some message
-- compile (2 sec)
-- test (13 sec)
-- libs (35 sec)
-- integTest (40 sec)
Build Successful: Total time 60 sec

This leaves us with three problems.

1.) If there is an exception, just showing the stacktrace and the exception message is not necessarily enough to figure out the reason for the exception. For example the ant javac task throws an exception if the code does not compile, but this exception points to the earlier log output to learn about the details. The solution I have in mind would be to record all the logging. In case of an exception we print the log of the complete build to the console. The user can configure which log level should be recorded. The default is INFO.

2.) There has to be some kind of progress indicator, to inform the user whether there is a stall and to make it more exciting to look at the log (psychological acceleration ;) ).
I 'm not sure what is the best solution here. One solution would be to print dots according to a certain algorithm which is based on incoming log statements. The other solution would require more console magic. Gradle would show only for example three log statements. If a new log statement comes in the first one disappears. This log statement 'window' would move down if a new task is getting executed. At the end of the build no normal log statement would be visible.

3.) If the build is stalled you want to interrupt it and learn about the reasons. Therefore we would implement a shutdown hook for the JVM. This hook would print the complete recorded log to the console (similar to the exception case).

Additionally, the log can be written to a file. This will always be the normal log, not the reduced form of the console. The log level of the file log can be chosen independently. Of course if people don't like the reduced form they can always switch to normal logging. The Gradle logging behavior is either configurable via the command line or by properties set in the gradle.properties file (either in the project or in the gradle user home dir).

I use the term 2-phase logging for this. If you have other ideas for the terminology please let us know.

What do you think about all this?

- Hans

--
Hans Dockter
Gradle Project lead
http://www.gradle.org

---------------------------------------------------------------------
To unsubscribe from this list, please visit:

  http://xircles.codehaus.org/manage_email





--
Xavier Hanin - Independent Java Consultant
http://xhab.blogspot.com/
http://ant.apache.org/ivy/
http://www.xoocode.org/

--
Hans Dockter
Gradle Project lead




Reply | Threaded
Open this post in threaded view
|

Re: 2-phase logging

Stefan Groschupf
In reply to this post by kkrugler
Just my 2 cents...
Mercurial style - as less as better. Also beeing able to configure it  
easily in user properties would be nice. I might like it more noisy  
than other users.
I saw tools that have more log level than just info, warn, error,  
debug. For example those tools had loglevel 0 to 10. Zero mean  
actually zero output - and 10 would be very verbose. Maybe overhead  
maybe difficult to decide which msg is which level.
The best of course would be make things easy pluggable. Than over time  
if people feel very emotional they can implement there own - one star  
instead of point for each executed task  - logging tool.
I mean right now you can do only the best guess but over time with  
more users requirements will adjust anyhow...
Again just my 2 cents.

Thanks for all your good work Hans!

Stefan

On Apr 28, 2008, at 4:03 PM, kkrugler wrote:

>
> Hi Hans,
>
> In general I think this would be a nice improvement over Ant/Maven  
> build
> output.
>
> See below for some short inline comments.
>
> -- Ken
>
>
> hdockter wrote:
>>
>> I'm not happy with the logging behavior of Gradle, Ant or Maven.
>>
>> I think there is too much information printed out to the console,
>> making it hard to figure out the important bits (for example an
>> unusual warning).
>>
>> I would like to improve this and have the following idea:
>>
>> A log of a successful build would look roughly like this:
>>
>> -- resources (0 sec)
>> -- compile (2 sec)
>> -- test (13 sec)
>> -- libs (35 sec)
>> -- integTest (40 sec)
>> Build Successful: Total time 60 sec
>>
>> We only show the task names that get executed.
>>
>> If there are log messages with a level higher than info we write them
>> to the console:
>>
>> -- resources (0 sec)
>> [warning] some message
>> -- compile (2 sec)
>> -- test (13 sec)
>> -- libs (35 sec)
>> -- integTest (40 sec)
>> Build Successful: Total time 60 sec
>>
>> This leaves us with three problems.
>>
>> 1.) If there is an exception, just showing the stacktrace and the
>> exception message is not necessarily enough to figure out the reason
>> for the exception. For example the ant javac task throws an exception
>> if the code does not compile, but this exception points to the
>> earlier log output to learn about the details. The solution I have in
>> mind would be to record all the logging. In case of an exception we
>> print the log of the complete build to the console. The user can
>> configure which log level should be recorded. The default is INFO.
>>
>> KK: Yes, definitely
>>
>> 2.) There has to be some kind of progress indicator, to inform the
>> user whether there is a stall and to make it more exciting to look at
>> the log (psychological acceleration ;) ).
>> I 'm not sure what is the best solution here. One solution would be
>> to print dots according to a certain algorithm which is based on
>> incoming log statements. The other solution would require more
>> console magic. Gradle would show only for example three log
>> statements. If a new log statement comes in the first one disappears.
>> This log statement 'window' would move down if a new task is getting
>> executed. At the end of the build no normal log statement would be
>> visible.
>>
>> KK: I would do something simple - e.g. print a dot for each logging  
>> call
>> :-)
>>
>> 3.) If the build is stalled you want to interrupt it and learn about
>> the reasons. Therefore we would implement a shutdown hook for the
>> JVM. This hook would print the complete recorded log to the console
>> (similar to the exception case).
>>
>> KK: Good idea, yes
>>
>> Additionally, the log can be written to a file. This will always be
>> the normal log, not the reduced form of the console. The log level of
>> the file log can be chosen independently. Of course if people don't
>> like the reduced form they can always switch to normal logging. The
>> Gradle logging behavior is either configurable via the command line
>> or by properties set in the gradle.properties file (either in the
>> project or in the gradle user home dir).
>>
>> I use the term 2-phase logging for this. If you have other ideas for
>> the terminology please let us know.
>>
>> What do you think about all this?
>>
>> - Hans
>>
>> --
>> Hans Dockter
>> Gradle Project lead
>> http://www.gradle.org
>>
>> ---------------------------------------------------------------------
>> To unsubscribe from this list, please visit:
>>
>>    http://xircles.codehaus.org/manage_email
>>
>>
>
> --
> View this message in context: http://www.nabble.com/2-phase-logging-tp16945248p16945976.html
> Sent from the gradle-user mailing list archive at Nabble.com.
>
>
> ---------------------------------------------------------------------
> To unsubscribe from this list, please visit:
>
>    http://xircles.codehaus.org/manage_email
>
>
>

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
101tec Inc.
Menlo Park, California, USA
http://www.101tec.com



---------------------------------------------------------------------
To unsubscribe from this list, please visit:

    http://xircles.codehaus.org/manage_email


Reply | Threaded
Open this post in threaded view
|

Re: 2-phase logging

hans_d
Administrator
In reply to this post by hans_d
Hi Xavier,

On May 6, 2008, at 1:16 AM, Hans Dockter wrote:
Hi Xavier,

great to see you on the list :)

On May 5, 2008, at 1:57 PM, Xavier Hanin wrote:
Overall I like this idea too. There's one thing which can become tricky is handling the processing of logs if you use the parallel ant task. removing the last log line when you have concurrent logging require good thought and good testing.

I'm not sure if I understand. Therefore a stupid question. The problem you mention here would occur if Gradle would go for the approach of having a 'command-line window' of the last three or whatever log statements? It would be no problem if we would use dots, right?


I was pretty tired when I did not understand.

For multi-threaded builds I see two problems. One is what we show when an exception occurs. My idea would be to group the log output by thread. The last group that is shown would be the group where the exception occurred. We could this grouping either via thread-id or ThreadLocal appenders. It is another question if the build should always stop in case of an exception. If not we could do the same grouping, but the log for the failing thread wouldn't be at the end then.

The other problem is how to indicate progress. One way I can see right now would be to offer a little swing app for this. But I'm not too fond of this idea. 

Gradle plans to support multi-threaded builds in the future.

- Hans

- Hans



Xavier

On Mon, Apr 28, 2008 at 8:34 PM, Hans Dockter <[hidden email]> wrote:
I'm not happy with the logging behavior of Gradle, Ant or Maven.

I think there is too much information printed out to the console, making it hard to figure out the important bits (for example an unusual warning).

I would like to improve this and have the following idea:

A log of a successful build would look roughly like this:

-- resources (0 sec)
-- compile (2 sec)
-- test (13 sec)
-- libs (35 sec)
-- integTest (40 sec)
Build Successful: Total time 60 sec

We only show the task names that get executed.

If there are log messages with a level higher than info we write them to the console:

-- resources (0 sec)
[warning] some message
-- compile (2 sec)
-- test (13 sec)
-- libs (35 sec)
-- integTest (40 sec)
Build Successful: Total time 60 sec

This leaves us with three problems.

1.) If there is an exception, just showing the stacktrace and the exception message is not necessarily enough to figure out the reason for the exception. For example the ant javac task throws an exception if the code does not compile, but this exception points to the earlier log output to learn about the details. The solution I have in mind would be to record all the logging. In case of an exception we print the log of the complete build to the console. The user can configure which log level should be recorded. The default is INFO.

2.) There has to be some kind of progress indicator, to inform the user whether there is a stall and to make it more exciting to look at the log (psychological acceleration ;) ).
I 'm not sure what is the best solution here. One solution would be to print dots according to a certain algorithm which is based on incoming log statements. The other solution would require more console magic. Gradle would show only for example three log statements. If a new log statement comes in the first one disappears. This log statement 'window' would move down if a new task is getting executed. At the end of the build no normal log statement would be visible.

3.) If the build is stalled you want to interrupt it and learn about the reasons. Therefore we would implement a shutdown hook for the JVM. This hook would print the complete recorded log to the console (similar to the exception case).

Additionally, the log can be written to a file. This will always be the normal log, not the reduced form of the console. The log level of the file log can be chosen independently. Of course if people don't like the reduced form they can always switch to normal logging. The Gradle logging behavior is either configurable via the command line or by properties set in the gradle.properties file (either in the project or in the gradle user home dir).

I use the term 2-phase logging for this. If you have other ideas for the terminology please let us know.

What do you think about all this?

- Hans

--
Hans Dockter
Gradle Project lead
http://www.gradle.org

---------------------------------------------------------------------
To unsubscribe from this list, please visit:

  http://xircles.codehaus.org/manage_email





--
Xavier Hanin - Independent Java Consultant
http://xhab.blogspot.com/
http://ant.apache.org/ivy/
http://www.xoocode.org/

--
Hans Dockter
Gradle Project lead





--
Hans Dockter
Gradle Project lead




Reply | Threaded
Open this post in threaded view
|

Re: 2-phase logging

hans_d
Administrator
In reply to this post by Stefan Groschupf
Hi Stefan,

On May 6, 2008, at 9:21 AM, Stefan Groschupf wrote:
Just my 2 cents...
Mercurial style - as less as better.

I think just printing the executed tasks is more or less the least noisy level after quiet (which you can choose right now already via -q).

Also beeing able to configure it easily in user properties would be nice. I might like it more noisy than other users.

Definitely. We are going to offer configuration via project properties and/or user properties.

I saw tools that have more log level than just info, warn, error, debug. For example those tools had loglevel 0 to 10. Zero mean actually zero output - and 10 would be very verbose. Maybe overhead maybe difficult to decide which msg is which level.

Right

The best of course would be make things easy pluggable. Than over time if people feel very emotional they can implement there own - one star instead of point for each executed task  - logging tool.

Optional fine grained configuration would be cool.

I mean right now you can do only the best guess but over time with more users requirements will adjust anyhow...

Right.

Thanks for your feedback

- Hans

Again just my 2 cents.

Thanks for all your good work Hans!

Stefan

On Apr 28, 2008, at 4:03 PM, kkrugler wrote:


Hi Hans,

In general I think this would be a nice improvement over Ant/Maven build
output.

See below for some short inline comments.

-- Ken


hdockter wrote:

I'm not happy with the logging behavior of Gradle, Ant or Maven.

I think there is too much information printed out to the console,
making it hard to figure out the important bits (for example an
unusual warning).

I would like to improve this and have the following idea:

A log of a successful build would look roughly like this:

-- resources (0 sec)
-- compile (2 sec)
-- test (13 sec)
-- libs (35 sec)
-- integTest (40 sec)
Build Successful: Total time 60 sec

We only show the task names that get executed.

If there are log messages with a level higher than info we write them
to the console:

-- resources (0 sec)
[warning] some message
-- compile (2 sec)
-- test (13 sec)
-- libs (35 sec)
-- integTest (40 sec)
Build Successful: Total time 60 sec

This leaves us with three problems.

1.) If there is an exception, just showing the stacktrace and the
exception message is not necessarily enough to figure out the reason
for the exception. For example the ant javac task throws an exception
if the code does not compile, but this exception points to the
earlier log output to learn about the details. The solution I have in
mind would be to record all the logging. In case of an exception we
print the log of the complete build to the console. The user can
configure which log level should be recorded. The default is INFO.

KK: Yes, definitely

2.) There has to be some kind of progress indicator, to inform the
user whether there is a stall and to make it more exciting to look at
the log (psychological acceleration ;) ).
I 'm not sure what is the best solution here. One solution would be
to print dots according to a certain algorithm which is based on
incoming log statements. The other solution would require more
console magic. Gradle would show only for example three log
statements. If a new log statement comes in the first one disappears.
This log statement 'window' would move down if a new task is getting
executed. At the end of the build no normal log statement would be
visible.

KK: I would do something simple - e.g. print a dot for each logging call
:-)

3.) If the build is stalled you want to interrupt it and learn about
the reasons. Therefore we would implement a shutdown hook for the
JVM. This hook would print the complete recorded log to the console
(similar to the exception case).

KK: Good idea, yes

Additionally, the log can be written to a file. This will always be
the normal log, not the reduced form of the console. The log level of
the file log can be chosen independently. Of course if people don't
like the reduced form they can always switch to normal logging. The
Gradle logging behavior is either configurable via the command line
or by properties set in the gradle.properties file (either in the
project or in the gradle user home dir).

I use the term 2-phase logging for this. If you have other ideas for
the terminology please let us know.

What do you think about all this?

- Hans

--
Hans Dockter
Gradle Project lead

---------------------------------------------------------------------
To unsubscribe from this list, please visit:




-- 
Sent from the gradle-user mailing list archive at Nabble.com.


---------------------------------------------------------------------
To unsubscribe from this list, please visit:





~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
101tec Inc.
Menlo Park, California, USA



---------------------------------------------------------------------
To unsubscribe from this list, please visit:




--
Hans Dockter
Gradle Project lead




Reply | Threaded
Open this post in threaded view
|

Re: 2-phase logging

Xavier Hanin
In reply to this post by hans_d
On Tue, May 6, 2008 at 10:49 AM, Hans Dockter <[hidden email]> wrote:
Hi Xavier,

On May 6, 2008, at 1:16 AM, Hans Dockter wrote:
Hi Xavier,

great to see you on the list :)

On May 5, 2008, at 1:57 PM, Xavier Hanin wrote:
Overall I like this idea too. There's one thing which can become tricky is handling the processing of logs if you use the parallel ant task. removing the last log line when you have concurrent logging require good thought and good testing.

I'm not sure if I understand. Therefore a stupid question. The problem you mention here would occur if Gradle would go for the approach of having a 'command-line window' of the last three or whatever log statements? It would be no problem if we would use dots, right?


I was pretty tired when I did not understand.

For multi-threaded builds I see two problems. One is what we show when an exception occurs. My idea would be to group the log output by thread. The last group that is shown would be the group where the exception occurred. We could this grouping either via thread-id or ThreadLocal appenders. It is another question if the build should always stop in case of an exception. If not we could do the same grouping, but the log for the failing thread wouldn't be at the end then.
Grouping by thread is nice. But this is only when a problem occurs. If the info level is enabled, you log statements as they come. But do you allow to log messages without an EOL? In Ant, System.out is captured, and actually sent to the console only when an EOL is reached. This makes reporting progress very difficult (you've probably seen the dots with strange breaking lines in Ivy).

The other problem is how to indicate progress. One way I can see right now would be to offer a little swing app for this. But I'm not too fond of this idea. 
Many people that I know really don't like this, including me. I often build stuff using an headless connection, in which case the swing app can't be displayed. So I think gradle need to have a good progress indicator mechanism on the console, pluggable when used from a rich client environment like an IDE. For the console progress, I really like what they do in Maven when downloading artifacts for instance, but this doesn't work in multi threaded environment, at least not easily. IMO it would be nice to have a progress indicator API independent from the implementation (the progress indicator API in eclipse can be a good source of inspiration IMO). Then you can start with a simple implementation, outputting dots for instance. Later when gradle will be used all over the world by billions of people you'll have zillions of contributions to provide a better implementation, with screen flashing and ascii art games to entertain build engineers during boring days :-)
 

Gradle plans to support multi-threaded builds in the future.
Nice. With multi core systems everywhere, I can't imagine a single threaded build system as a solution for the future.

Xavier

- Hans

- Hans



Xavier

On Mon, Apr 28, 2008 at 8:34 PM, Hans Dockter <[hidden email]> wrote:
I'm not happy with the logging behavior of Gradle, Ant or Maven.

I think there is too much information printed out to the console, making it hard to figure out the important bits (for example an unusual warning).

I would like to improve this and have the following idea:

A log of a successful build would look roughly like this:

-- resources (0 sec)
-- compile (2 sec)
-- test (13 sec)
-- libs (35 sec)
-- integTest (40 sec)
Build Successful: Total time 60 sec

We only show the task names that get executed.

If there are log messages with a level higher than info we write them to the console:

-- resources (0 sec)
[warning] some message
-- compile (2 sec)
-- test (13 sec)
-- libs (35 sec)
-- integTest (40 sec)
Build Successful: Total time 60 sec

This leaves us with three problems.

1.) If there is an exception, just showing the stacktrace and the exception message is not necessarily enough to figure out the reason for the exception. For example the ant javac task throws an exception if the code does not compile, but this exception points to the earlier log output to learn about the details. The solution I have in mind would be to record all the logging. In case of an exception we print the log of the complete build to the console. The user can configure which log level should be recorded. The default is INFO.

2.) There has to be some kind of progress indicator, to inform the user whether there is a stall and to make it more exciting to look at the log (psychological acceleration ;) ).
I 'm not sure what is the best solution here. One solution would be to print dots according to a certain algorithm which is based on incoming log statements. The other solution would require more console magic. Gradle would show only for example three log statements. If a new log statement comes in the first one disappears. This log statement 'window' would move down if a new task is getting executed. At the end of the build no normal log statement would be visible.

3.) If the build is stalled you want to interrupt it and learn about the reasons. Therefore we would implement a shutdown hook for the JVM. This hook would print the complete recorded log to the console (similar to the exception case).

Additionally, the log can be written to a file. This will always be the normal log, not the reduced form of the console. The log level of the file log can be chosen independently. Of course if people don't like the reduced form they can always switch to normal logging. The Gradle logging behavior is either configurable via the command line or by properties set in the gradle.properties file (either in the project or in the gradle user home dir).

I use the term 2-phase logging for this. If you have other ideas for the terminology please let us know.

What do you think about all this?

- Hans

--
Hans Dockter
Gradle Project lead
http://www.gradle.org

---------------------------------------------------------------------
To unsubscribe from this list, please visit:

  http://xircles.codehaus.org/manage_email





--
Xavier Hanin - Independent Java Consultant
http://xhab.blogspot.com/
http://ant.apache.org/ivy/
http://www.xoocode.org/

--
Hans Dockter
Gradle Project lead





--
Hans Dockter
Gradle Project lead







--
Xavier Hanin - Independent Java Consultant
http://xhab.blogspot.com/
http://ant.apache.org/ivy/
http://www.xoocode.org/
Reply | Threaded
Open this post in threaded view
|

Re: 2-phase logging

hans_d
Administrator

On May 6, 2008, at 7:28 PM, Xavier Hanin wrote:
On Tue, May 6, 2008 at 10:49 AM, Hans Dockter <[hidden email]> wrote:
Hi Xavier,

On May 6, 2008, at 1:16 AM, Hans Dockter wrote:
Hi Xavier,

great to see you on the list :)

On May 5, 2008, at 1:57 PM, Xavier Hanin wrote:
Overall I like this idea too. There's one thing which can become tricky is handling the processing of logs if you use the parallel ant task. removing the last log line when you have concurrent logging require good thought and good testing.

I'm not sure if I understand. Therefore a stupid question. The problem you mention here would occur if Gradle would go for the approach of having a 'command-line window' of the last three or whatever log statements? It would be no problem if we would use dots, right?


I was pretty tired when I did not understand.

For multi-threaded builds I see two problems. One is what we show when an exception occurs. My idea would be to group the log output by thread. The last group that is shown would be the group where the exception occurred. We could this grouping either via thread-id or ThreadLocal appenders. It is another question if the build should always stop in case of an exception. If not we could do the same grouping, but the log for the failing thread wouldn't be at the end then.
Grouping by thread is nice. But this is only when a problem occurs. If the info level is enabled, you log statements as they come.

Right, only if a problem occur. But otherwise the default way would not to print info, but to print only that a task is starting to get executed. INFO is more verbose. The user can choose whether Gradle should use 2 phase logging (Details are only shown in case of an error) or normal INFO(or DEBUG) logging.

But do you allow to log messages without an EOL? In Ant, System.out is captured, and actually sent to the console only when an EOL is reached. This makes reporting progress very difficult (you've probably seen the dots with strange breaking lines in Ivy).

Interesting to learn about this ant behavior. I haven't known this. Now I understand the dot handling of Ivy.

Gradle uses logback under the hood for its logging. We can create an appropriate appender.



The other problem is how to indicate progress. One way I can see right now would be to offer a little swing app for this. But I'm not too fond of this idea. 
Many people that I know really don't like this, including me. I often build stuff using an headless connection, in which case the swing app can't be displayed. So I think gradle need to have a good progress indicator mechanism on the console, pluggable when used from a rich client environment like an IDE. For the console progress, I really like what they do in Maven when downloading artifacts for instance, but this doesn't work in multi threaded environment, at least not easily. IMO it would be nice to have a progress indicator API independent from the implementation (the progress indicator API in eclipse can be a good source of inspiration IMO).

Very interesting idea.

Then you can start with a simple implementation, outputting dots for instance. Later when gradle will be used all over the world by billions of people you'll have zillions of contributions to provide a better implementation, with screen flashing and ascii art games to entertain build engineers during boring days :-)

And every Gradle user is an Ivy user. We have to spend the rest of our life responding to the mailing lists ;)

- Hans  


 

Gradle plans to support multi-threaded builds in the future.
Nice. With multi core systems everywhere, I can't imagine a single threaded build system as a solution for the future.

Xavier

- Hans

- Hans



Xavier

On Mon, Apr 28, 2008 at 8:34 PM, Hans Dockter <[hidden email]> wrote:
I'm not happy with the logging behavior of Gradle, Ant or Maven.

I think there is too much information printed out to the console, making it hard to figure out the important bits (for example an unusual warning).

I would like to improve this and have the following idea:

A log of a successful build would look roughly like this:

-- resources (0 sec)
-- compile (2 sec)
-- test (13 sec)
-- libs (35 sec)
-- integTest (40 sec)
Build Successful: Total time 60 sec

We only show the task names that get executed.

If there are log messages with a level higher than info we write them to the console:

-- resources (0 sec)
[warning] some message
-- compile (2 sec)
-- test (13 sec)
-- libs (35 sec)
-- integTest (40 sec)
Build Successful: Total time 60 sec

This leaves us with three problems.

1.) If there is an exception, just showing the stacktrace and the exception message is not necessarily enough to figure out the reason for the exception. For example the ant javac task throws an exception if the code does not compile, but this exception points to the earlier log output to learn about the details. The solution I have in mind would be to record all the logging. In case of an exception we print the log of the complete build to the console. The user can configure which log level should be recorded. The default is INFO.

2.) There has to be some kind of progress indicator, to inform the user whether there is a stall and to make it more exciting to look at the log (psychological acceleration ;) ).
I 'm not sure what is the best solution here. One solution would be to print dots according to a certain algorithm which is based on incoming log statements. The other solution would require more console magic. Gradle would show only for example three log statements. If a new log statement comes in the first one disappears. This log statement 'window' would move down if a new task is getting executed. At the end of the build no normal log statement would be visible.

3.) If the build is stalled you want to interrupt it and learn about the reasons. Therefore we would implement a shutdown hook for the JVM. This hook would print the complete recorded log to the console (similar to the exception case).

Additionally, the log can be written to a file. This will always be the normal log, not the reduced form of the console. The log level of the file log can be chosen independently. Of course if people don't like the reduced form they can always switch to normal logging. The Gradle logging behavior is either configurable via the command line or by properties set in the gradle.properties file (either in the project or in the gradle user home dir).

I use the term 2-phase logging for this. If you have other ideas for the terminology please let us know.

What do you think about all this?

- Hans

--
Hans Dockter
Gradle Project lead
http://www.gradle.org

---------------------------------------------------------------------
To unsubscribe from this list, please visit:

  http://xircles.codehaus.org/manage_email





--
Xavier Hanin - Independent Java Consultant
http://xhab.blogspot.com/
http://ant.apache.org/ivy/
http://www.xoocode.org/

--
Hans Dockter
Gradle Project lead





--
Hans Dockter
Gradle Project lead







--
Xavier Hanin - Independent Java Consultant
http://xhab.blogspot.com/
http://ant.apache.org/ivy/
http://www.xoocode.org/

--
Hans Dockter
Gradle Project lead




Reply | Threaded
Open this post in threaded view
|

Re: 2-phase logging

Ittay Dror
In reply to this post by hans_d
My 2c:
* instead of saving log messages in memory to print them to the console in case of exception, why can't the user look at the log file? I think the log file can be in 'debug' level (but make sure 'debug' messages are not actually meaningless 'trace' messages). also, analysis tools such as printing the dag, will be good.
* i'm not sure how printing dots is a good solution. say i have some task that takes a long time and doesn't print anything (a compiler, copying a large file), either no dots appear - the user thinks the build is stalled, or, printing a dot periodically, in which case the task may actually be stalled and yet dots will appear. what i think is needed is a monitor of the system resources. this is commonly seen in downloading tools that tell you the rate of download. so for compilations, show the cpu usage and for copying, show the io activity. either show all indicators all the time (which i prefer), or allow each task to turn on the necessary indicator. this also solves the issue of multi-threading.
* if a task is stalled,  

ittay

 
hdockter wrote
I'm not happy with the logging behavior of Gradle, Ant or Maven.

I think there is too much information printed out to the console,  
making it hard to figure out the important bits (for example an  
unusual warning).

I would like to improve this and have the following idea:

A log of a successful build would look roughly like this:

-- resources (0 sec)
-- compile (2 sec)
-- test (13 sec)
-- libs (35 sec)
-- integTest (40 sec)
Build Successful: Total time 60 sec

We only show the task names that get executed.

If there are log messages with a level higher than info we write them  
to the console:

-- resources (0 sec)
[warning] some message
-- compile (2 sec)
-- test (13 sec)
-- libs (35 sec)
-- integTest (40 sec)
Build Successful: Total time 60 sec

This leaves us with three problems.

1.) If there is an exception, just showing the stacktrace and the  
exception message is not necessarily enough to figure out the reason  
for the exception. For example the ant javac task throws an exception  
if the code does not compile, but this exception points to the  
earlier log output to learn about the details. The solution I have in  
mind would be to record all the logging. In case of an exception we  
print the log of the complete build to the console. The user can  
configure which log level should be recorded. The default is INFO.

2.) There has to be some kind of progress indicator, to inform the  
user whether there is a stall and to make it more exciting to look at  
the log (psychological acceleration ;) ).
I 'm not sure what is the best solution here. One solution would be  
to print dots according to a certain algorithm which is based on  
incoming log statements. The other solution would require more  
console magic. Gradle would show only for example three log  
statements. If a new log statement comes in the first one disappears.  
This log statement 'window' would move down if a new task is getting  
executed. At the end of the build no normal log statement would be  
visible.

3.) If the build is stalled you want to interrupt it and learn about  
the reasons. Therefore we would implement a shutdown hook for the  
JVM. This hook would print the complete recorded log to the console  
(similar to the exception case).

Additionally, the log can be written to a file. This will always be  
the normal log, not the reduced form of the console. The log level of  
the file log can be chosen independently. Of course if people don't  
like the reduced form they can always switch to normal logging. The  
Gradle logging behavior is either configurable via the command line  
or by properties set in the gradle.properties file (either in the  
project or in the gradle user home dir).

I use the term 2-phase logging for this. If you have other ideas for  
the terminology please let us know.

What do you think about all this?

- Hans

--
Hans Dockter
Gradle Project lead
http://www.gradle.org

---------------------------------------------------------------------
To unsubscribe from this list, please visit:

    http://xircles.codehaus.org/manage_email

Reply | Threaded
Open this post in threaded view
|

Re: 2-phase logging

hans_d
Administrator

On Jun 17, 2008, at 5:07 PM, Ittay Dror wrote:

>
> My 2c:
> * instead of saving log messages in memory to print them to the  
> console in
> case of exception, why can't the user look at the log file?

This is for convenience. It saves a step to the user. Even a failing  
compile would make it necessary to look at the info log. So I think  
it is nice to print it directly to the console in case something goes  
wrong. The basic idea of 2-phase-logging (or any other name we want  
to give to it) is: We have two log streams. One is the one which is  
currently (Gradle 0.2) printed to the console (either info or debug  
when using -d). The new log stream is neither info nor debug nor any  
other standard log level. It gives high level information only about  
which tasks are executed and in which order. Additionally it serves  
as progress indicator. Once we have the two log streams it should be  
up to the user what to do with them.

Use cases:
High Level to Console. In case of error info to the console and debug  
to a file.
High Level to Console. In case of error debug to the console and no  
file logging.
Info to the console, debug to a file (high level is not used)
Etc ...

This should be configurable via the command line or via the  
gradle.properties file. Once we have the two logstreams our logback  
logging engine makes it very easy to route the logstreams. In fact  
logback makes it also pretty easy to generate the two log streams, as  
it allows to create your own log levels (via Marker objects). It is a  
really good tool, written by the founder of log4j.

> I think the log
> file can be in 'debug' level (but make sure 'debug' messages are not
> actually meaningless 'trace' messages). also, analysis tools such as
> printing the dag, will be good.

What you can do right now is: gradle -t

This prints all the available tasks and there dependencies to the  
console. But you are right, this is not the specific DAG for a  
certain task. I think it's a good idea to print this out as well when  
in debug mode. http://jira.codehaus.org/browse/GRADLE-121

> * i'm not sure how printing dots is a good solution. say i have  
> some task
> that takes a long time and doesn't print anything (a compiler,  
> copying a
> large file), either no dots appear - the user thinks the build is  
> stalled,
> or, printing a dot periodically, in which case the task may  
> actually be
> stalled and yet dots will appear.

This is not a particular problem of our two phase logging but two  
phase logging might make it slightly worse.

For example:

INFO logging:
Executing: :compile
:: resolving dependencies :: org.gradle#buildSrc;SNAPSHOT
         confs: [compile]
         found #svnkit;1.1.6 in lib
         found #svnkit-javahl;1.1.6 in lib
   [groovyc] Compiling 13 source files to /Users/hans/IdeaProjects/
gradle/gradle-core/buildSrc/build/classes

If the last step takes long, the user gets no progress indication.

High Level logging:
Executing :compile

If this takes long we also offer no progress indication but the user  
does not know whether this is because the compile takes such a long  
time or if the remote repository is down when fetching the dependencies.

It depends on the kind of build if this really is a typical problem.  
It will be configurable, so you can switch high level logging of.

> what i think is needed is a monitor of the
> system resources. this is commonly seen in downloading tools that  
> tell you
> the rate of download. so for compilations, show the cpu usage and for
> copying, show the io activity.

That would be really cool. May be not for the first implementation  
but for the future.

> either show all indicators all the time
> (which i prefer), or allow each task to turn on the necessary  
> indicator.
> this also solves the issue of multi-threading.
> * if a task is stalled,

We would need a UI for this (which is fine). But it would be cool to  
have also a boiled down version for the command line display.

- Hans

>
> ittay
>
>
>
> hdockter wrote:
>>
>> I'm not happy with the logging behavior of Gradle, Ant or Maven.
>>
>> I think there is too much information printed out to the console,
>> making it hard to figure out the important bits (for example an
>> unusual warning).
>>
>> I would like to improve this and have the following idea:
>>
>> A log of a successful build would look roughly like this:
>>
>> -- resources (0 sec)
>> -- compile (2 sec)
>> -- test (13 sec)
>> -- libs (35 sec)
>> -- integTest (40 sec)
>> Build Successful: Total time 60 sec
>>
>> We only show the task names that get executed.
>>
>> If there are log messages with a level higher than info we write them
>> to the console:
>>
>> -- resources (0 sec)
>> [warning] some message
>> -- compile (2 sec)
>> -- test (13 sec)
>> -- libs (35 sec)
>> -- integTest (40 sec)
>> Build Successful: Total time 60 sec
>>
>> This leaves us with three problems.
>>
>> 1.) If there is an exception, just showing the stacktrace and the
>> exception message is not necessarily enough to figure out the reason
>> for the exception. For example the ant javac task throws an exception
>> if the code does not compile, but this exception points to the
>> earlier log output to learn about the details. The solution I have in
>> mind would be to record all the logging. In case of an exception we
>> print the log of the complete build to the console. The user can
>> configure which log level should be recorded. The default is INFO.
>>
>> 2.) There has to be some kind of progress indicator, to inform the
>> user whether there is a stall and to make it more exciting to look at
>> the log (psychological acceleration ;) ).
>> I 'm not sure what is the best solution here. One solution would be
>> to print dots according to a certain algorithm which is based on
>> incoming log statements. The other solution would require more
>> console magic. Gradle would show only for example three log
>> statements. If a new log statement comes in the first one disappears.
>> This log statement 'window' would move down if a new task is getting
>> executed. At the end of the build no normal log statement would be
>> visible.
>>
>> 3.) If the build is stalled you want to interrupt it and learn about
>> the reasons. Therefore we would implement a shutdown hook for the
>> JVM. This hook would print the complete recorded log to the console
>> (similar to the exception case).
>>
>> Additionally, the log can be written to a file. This will always be
>> the normal log, not the reduced form of the console. The log level of
>> the file log can be chosen independently. Of course if people don't
>> like the reduced form they can always switch to normal logging. The
>> Gradle logging behavior is either configurable via the command line
>> or by properties set in the gradle.properties file (either in the
>> project or in the gradle user home dir).
>>
>> I use the term 2-phase logging for this. If you have other ideas for
>> the terminology please let us know.
>>
>> What do you think about all this?
>>
>> - Hans
>>
>> --
>> Hans Dockter
>> Gradle Project lead
>> http://www.gradle.org
>>
>> ---------------------------------------------------------------------
>> To unsubscribe from this list, please visit:
>>
>>     http://xircles.codehaus.org/manage_email
>>
>>
>>
>>
>
> --
> View this message in context: http://www.nabble.com/2-phase-logging- 
> tp16945248p17913845.html
> Sent from the gradle-user mailing list archive at Nabble.com.
>
>
> ---------------------------------------------------------------------
> To unsubscribe from this list, please visit:
>
>     http://xircles.codehaus.org/manage_email
>
>

--
Hans Dockter
Gradle Project lead
http://www.gradle.org





---------------------------------------------------------------------
To unsubscribe from this list, please visit:

    http://xircles.codehaus.org/manage_email