The Griffon Trove: peeking at the build

There are times when working with Griffon you'd like to know what's really happening during build process execution; for example, how much time does it take for a task to complete, or what are the different events you can react to using build event handlers.

There are two ways to know this. The first and easiest one is to define a value for the griffon.cli.verbose flag. This flag can be either set in the command line or written down in one of the two buildtime configuration files ($appHome/griffon-app/conf/BuildConfig.groovy or $USER_HOME/.griffon/settings.groovy). Take for example the invocation of the clean command right after a compilation step has been issued.
$ griffon clean Welcome to Griffon 0.9.5-rc1 - http://griffon.codehaus.org/ Licensed under Apache Standard License 2.0 Griffon home is set to: /usr/local/griffon-0.9.5-rc1 Base Directory: /private/tmp/sample Running script /usr/local/griffon-0.9.5-rc1/scripts/Clean.groovy Resolving dependencies... Dependencies resolved in 750ms. Environment set to development Resolving plugin dependencies ... Plugin dependencies resolved in 855 ms. [delete] Deleting directory /Users/aalmiray/.griffon/0.9.5-rc1/projects/sample/classes/cli [delete] Deleting directory /Users/aalmiray/.griffon/0.9.5-rc1/projects/sample/classes/main [delete] Deleting directory /Users/aalmiray/.griffon/0.9.5-rc1/projects/sample/classes/test [delete] Deleting directory /Users/aalmiray/.griffon/0.9.5-rc1/projects/sample/test-classes [delete] Deleting directory /Users/aalmiray/.griffon/0.9.5-rc1/projects/sample/test-resources [delete] Deleting directory /Users/aalmiray/.griffon/0.9.5-rc1/projects/sample/resourcesNow compare that to the output generated when the griffon.cli.verbose flag is enabled
$ griffon -Dgriffon.cli.verbose=true clean Welcome to Griffon 0.9.5-rc1 - http://griffon.codehaus.org/ Licensed under Apache Standard License 2.0 Griffon home is set to: /usr/local/griffon-0.9.5-rc1 Base Directory: /private/tmp/sample Running script /usr/local/griffon-0.9.5-rc1/scripts/Clean.groovy Resolving dependencies... Dependencies resolved in 679ms. Environment set to development [2/20/12 11:17:58 PM] ** [parseArguments, configureProxy, resolveDependencies, loadEventHooks] ** [2/20/12 11:17:58 PM] >>>> parseArguments [2/20/12 11:17:58 PM] <<<< parseArguments [25ms] [2/20/12 11:17:58 PM] >>>> configureProxy [2/20/12 11:17:58 PM] <<<< configureProxy [1ms] [2/20/12 11:17:58 PM] >>>> resolveDependencies Resolving plugin dependencies ... [2/20/12 11:17:58 PM] Resolving plugin swing-0.9.5 JAR dependencies [2/20/12 11:17:58 PM] Parsing dependencies from /Users/aalmiray/.griffon/0.9.5-rc1/projects/sample/plugins/swing-0.9.5/plugin-dependencies.groovy Plugin dependencies resolved in 914 ms. [2/20/12 11:17:59 PM] <<<< resolveDependencies [938ms] [2/20/12 11:17:59 PM] >>>> loadEventHooks [2/20/12 11:17:59 PM] <<<< loadEventHooks [91ms] [2/20/12 11:17:59 PM] >>>> cleanAll [2/20/12 11:17:59 PM] >>>> clean [2/20/12 11:17:59 PM] >>>> cleanCompiledSources [delete] Deleting directory /Users/aalmiray/.griffon/0.9.5-rc1/projects/sample/classes/cli [delete] Deleting directory /Users/aalmiray/.griffon/0.9.5-rc1/projects/sample/classes/main [delete] Deleting directory /Users/aalmiray/.griffon/0.9.5-rc1/projects/sample/classes/test [delete] Deleting directory /Users/aalmiray/.griffon/0.9.5-rc1/projects/sample/test-classes [delete] Deleting directory /Users/aalmiray/.griffon/0.9.5-rc1/projects/sample/test-resources [delete] Deleting directory /Users/aalmiray/.griffon/0.9.5-rc1/projects/sample/resources [2/20/12 11:17:59 PM] <<<< cleanCompiledSources [103ms] [2/20/12 11:17:59 PM] >>>> cleanPackaging [2/20/12 11:18:00 PM] <<<< cleanPackaging [498ms] [2/20/12 11:18:00 PM] <<<< clean [605ms] [2/20/12 11:18:00 PM] >>>> cleanTestReports [2/20/12 11:18:00 PM] <<<< cleanTestReports [15ms] [2/20/12 11:18:00 PM] <<<< cleanAll [625ms]Much different now. The first debug row tells us exactly which targets will be executed before the default one (defined by the Clean command) is called. For each target we can see when it began and finished, in milliseconds. What about the event name? Well it's a simple matter of capitalizing the target name and appending either Start or End, meaning that if you want to react to when the packaging has been cleaned then you must place an event handler named eventClearPackagingEnd on your event handler script (scripts/_Events.groovy). Bear in mind that the value specified at the command line for this flag will override any value set in the config files.

The second approach is to tweak the logging configuration available at buildtime. For this we'll need to edit $appName/griffon-app/conf/BuildConfig.groovy. Right at the end we'll find the default logging configuration in the form of a Log4j DSL. Modify it so that the package org.codehaus.griffon is set to trace, like this
log4j = { // Example of changing the log pattern for the default console // appender: appenders { console name: 'stdout', layout: pattern(conversionPattern: '%d [%t] %-5p %c - %m%n') } trace 'org.codehaus.griffon' error 'org.springframework', 'org.apache.karaf', 'groovyx.net' warn 'griffon' }Calling the clean command again after a compilation has been executed yields the following output
$ griffon clean Welcome to Griffon 0.9.5-rc1 - http://griffon.codehaus.org/ Licensed under Apache Standard License 2.0 Griffon home is set to: /usr/local/griffon-0.9.5-rc1 Base Directory: /private/tmp/sample Running script /usr/local/griffon-0.9.5-rc1/scripts/Clean.groovy Resolving dependencies... Dependencies resolved in 648ms. Environment set to development 2012-02-20 23:25:30,734 [main] TRACE org.codehaus.griffon.cli.support.GriffonBuildEventListener - Triggering event ParseArgumentsStart 2012-02-20 23:25:30,756 [main] TRACE org.codehaus.griffon.cli.support.GriffonBuildEventListener - Triggering event ParseArgumentsEnd 2012-02-20 23:25:30,787 [main] TRACE org.codehaus.griffon.cli.support.GriffonBuildEventListener - Triggering event ConfigureProxyStart 2012-02-20 23:25:30,788 [main] TRACE org.codehaus.griffon.cli.support.GriffonBuildEventListener - Triggering event ConfigureProxyEnd 2012-02-20 23:25:30,799 [main] TRACE org.codehaus.griffon.cli.support.GriffonBuildEventListener - Triggering event ResolveDependenciesStart 2012-02-20 23:25:30,809 [main] TRACE org.codehaus.griffon.cli.support.GriffonBuildEventListener - Triggering event StatusUpdate Resolving plugin dependencies ... 2012-02-20 23:25:30,881 [main] DEBUG org.codehaus.griffon.artifacts.ArtifactInstallEngine - Registered plugins: swing-0.9.5 2012-02-20 23:25:30,884 [main] DEBUG org.codehaus.griffon.artifacts.ArtifactInstallEngine - Installed plugins: swing-0.9.5 2012-02-20 23:25:30,947 [main] DEBUG org.codehaus.griffon.artifacts.ArtifactInstallEngine - Installed plugins (confirmed): swing-0.9.5 2012-02-20 23:25:31,844 [main] TRACE org.codehaus.griffon.cli.support.GriffonBuildEventListener - Triggering event StatusFinal Plugin dependencies resolved in 1033 ms. 2012-02-20 23:25:31,866 [main] TRACE org.codehaus.griffon.cli.support.GriffonBuildEventListener - Triggering event ResolveDependenciesEnd 2012-02-20 23:25:31,870 [main] TRACE org.codehaus.griffon.cli.support.GriffonBuildEventListener - Triggering event LoadEventHooksStart 2012-02-20 23:25:31,908 [main] DEBUG org.codehaus.griffon.cli.support.GriffonBuildEventListener - Loading event handlers from /Users/aalmiray/.griffon/0.9.5-rc1/projects/sample/plugins/swing-0.9.5/scripts/_Events.groovy 2012-02-20 23:25:31,983 [main] TRACE org.codehaus.griffon.cli.support.GriffonBuildEventListener - Triggering event LoadEventHooksEnd 2012-02-20 23:25:32,005 [main] TRACE org.codehaus.griffon.cli.support.GriffonBuildEventListener - Triggering event CleanAllStart 2012-02-20 23:25:32,007 [main] TRACE org.codehaus.griffon.cli.support.GriffonBuildEventListener - Triggering event CleanStart 2012-02-20 23:25:32,009 [main] TRACE org.codehaus.griffon.cli.support.GriffonBuildEventListener - Triggering event CleanCompiledSourcesStart [delete] Deleting directory /Users/aalmiray/.griffon/0.9.5-rc1/projects/sample/classes/cli [delete] Deleting directory /Users/aalmiray/.griffon/0.9.5-rc1/projects/sample/classes/main [delete] Deleting directory /Users/aalmiray/.griffon/0.9.5-rc1/projects/sample/classes/test [delete] Deleting directory /Users/aalmiray/.griffon/0.9.5-rc1/projects/sample/test-classes [delete] Deleting directory /Users/aalmiray/.griffon/0.9.5-rc1/projects/sample/test-resources [delete] Deleting directory /Users/aalmiray/.griffon/0.9.5-rc1/projects/sample/resources 2012-02-20 23:25:32,137 [main] TRACE org.codehaus.griffon.cli.support.GriffonBuildEventListener - Triggering event CleanCompiledSourcesEnd 2012-02-20 23:25:32,141 [main] TRACE org.codehaus.griffon.cli.support.GriffonBuildEventListener - Triggering event CleanPackagingStart 2012-02-20 23:25:32,462 [main] TRACE org.codehaus.griffon.cli.support.GriffonBuildEventListener - Triggering event CleanPackagingEnd 2012-02-20 23:25:32,464 [main] TRACE org.codehaus.griffon.cli.support.GriffonBuildEventListener - Triggering event CleanEnd 2012-02-20 23:25:32,468 [main] TRACE org.codehaus.griffon.cli.support.GriffonBuildEventListener - Triggering event CleanTestReportsStart 2012-02-20 23:25:32,488 [main] TRACE org.codehaus.griffon.cli.support.GriffonBuildEventListener - Triggering event CleanTestReportsEnd 2012-02-20 23:25:32,514 [main] TRACE org.codehaus.griffon.cli.support.GriffonBuildEventListener - Triggering event CleanAllEnd Now we can appreciate exactly the event names that the build will trigger. Notice that custom event handlers are registered during the execution of the loadEventHooks target, which means you can't react to events triggered prior to LoadEventHooksEnd.

Keep on Groovying!