Re: Problems using logging in Velocity 1.6.2

[Nathan Bubna <nb...@gmail.com>]

On Mon, Aug 24, 2009 at 4:12 PM, Dr. Matthias Laux<ma...@web.de> wrote:
> Hi Nathan,
>
> thanks a lot!
>
> So indeed most messages are at the FINE level, just as suspected.
>
> The problem I'm trying to solve is to identify actual template problems
> such as
>
> FINE: Null reference [template 'release_main.vm', line 18, column 9] : $yyy
> cannot be resolved.
>
> (taken from a JDK log output based on JdkLogChute).
>
> This originates in ASTReference line 404-406, where log.debug()
> is called -> as expected a FINE log message.
>
> One problem I see is that this message is hidden between zillions
> of other messages offering status information - but no indication
> of real problems. The message above shows a real problem I need to fix.
> If this came at a WARNING or SEVERE level, I could find it.

This is a debated issue and more involved than you might think.
Velocity's original creators designed it to ignore "schmoo" (defined
as anything not intended to be replaced by Velocity).  I believe the
idea was to have Velocity be very unobtrusive and only replace things
it clearly understood and had values for.  The imagined workflow was
that people would take content and insert VTL into it.  In such a
view, syntax "errors" and missing values are minor things to be
expected and easy to ignore.

Other template engines reverse that and assume that anything that
looks like their particular syntax are intended to be so.  Thus, any
missing values or syntax errors are treated severely and must be made
impossible to ignore.  The imagined workflow here is that the template
language is primary and the content inserted into it, rather than vice
versa.

The Velocity community has never been at one mind (to my knowledge)
about which approach was better, leading to a variety of inconsistent
escaping patterns and configuration options to bend it one way or the
other.  There was enough other work and debates going on that this one
never gained clear consensus or careful control, but the "ignore
schmoo" view has largely prevailed as the default, leaving stricter
controls as config options.

My early contributions to the Velocity Engine project were largely
about enhancing and cleaning up the log system and output.  At the
time, consensus was that it was much too noisy for a library.  So i
lowered the levels on many things, including this one you are
concerned with.   I stand by that choice as fitting the default
pattern of Velocity.

If you wish to treat missing references more harshly, you are free to
configure ReferenceInsertionEventHandlers to do so, or turn on the
"strict mode" that Byron Foster added in 1.6 (see the "Strict
Reference" section of
http://velocity.apache.org/engine/releases/velocity-1.6.2/developer-guide.html
) .  These features allow you to push Velocity into more of a "content
inserted into template syntax" paradigm.

But unfortunately there is no option that will only raise the log
level of that message.  Different LogChute implementations may map the
level differently, but all should map it to something that indicates
"debug" level, not "error" or "warn".

> In my previous approach messages like this were preceeded by
> [warn] or [error] and could be easily found in the velocity.log file. This
> was based on using the Velocity class directly rather that
> VelocityEngine.
>
> Is there some way to reproduce this behaviour in the new approach?
> Sounds like I should try to use the SystemLogChute or the
> AvalonLogChute since both use LogChute.WARN_PREFIX, which is what
> I had seen before in the output.
>
> Thanks again,
> Matthias
>
>
>
>
> Nathan Bubna wrote:
>>
>> Hi Matthias,
>>
>> Believe your eyes.  The cues you need are in the source of the
>> JdkLogChute.java file, lines 81-96.  debug->FINE, trace->FINEST,
>> warn->WARNING, error->SEVERE, info->INFO.
>>
>> And yeah, the overwhelming majority of Velocity log output happens at
>> the debug/FINE level.  You would only get a SEVERE if there were an
>> error and only in very unlikely circumstances will you get a WARNING
>> message.   There are certainly a few trace/FINEST messages out there,
>> but not many.   Most messages are debug/FINE because they're there for
>> debugging.  INFO is not really a relevant level for Velocity.  The
>> presence of a myriad of log levels doesn't necessitate the use of them
>> all.  Velocity is a utility library, not a framework and certainly not
>> an application.  Logging is pretty much just for debugging or error
>> reporting.  There is little other data that needs logging in Velocity,
>> and not much that users really need to ever see.
>>
>> It's my hope/plan to change things in the 2.x branch such that level
>> is not the primary categorization for log messages.  For Velocity,
>> it's more important to know what function a message relates to.  I'm
>> envisioning developers using it like getLog().resources(message) and
>> getLog().reflection(message, level)  or maybe even
>> getLog().users(message) to output things users need to see.  Of
>> course, i've been swamped with other work and haven't gotten to work
>> on this yet, though it's one of the things i'm more excited about
>> doing.
>>
>> On Sun, Aug 23, 2009 at 1:07 AM, Dr. Matthias Laux<ma...@web.de>
>> wrote:
>>>
>>> (aopolgies if this should appear twice - I don't
>>> see my first email on the mailing list archive so
>>> I gather the mail may not have made it)
>>>
>>>
>>>
>>> Hi,
>>>
>>> I'm lost getting Velocity logging to work the way I need it.
>>>
>>> In the past I used the Velocity directly such as
>>>
>>> Velocity.setProperty(RuntimeConstants.FILE_RESOURCE_LOADER_PATH,
>>> templateDir);
>>> Velocity.init();
>>>
>>> and got the expected output in the velocity.log file.
>>>
>>> Now I moved to using VelocityEngine instead because I had some issues
>>> with
>>> the output
>>> in a long running server app which performed the same tasks over and over
>>> again (the
>>> velocity.log file would grow and I did not know how to get Velocity to
>>> start
>>> a new file
>>> for every processing run).
>>>
>>> Anyway. Now the new code started to look like this:
>>>
>>> engine = new VelocityEngine();
>>> engine.setProperty(RuntimeConstants.FILE_RESOURCE_LOADER_PATH,
>>> templateDir);
>>> engine.init();
>>>
>>> and nothing happens other than an empty file "velocity.log" being
>>> created.
>>> Well.
>>>
>>> So I added a LogChute:
>>>
>>> engine = new VelocityEngine();
>>> engine.setProperty(RuntimeConstants.FILE_RESOURCE_LOADER_PATH,
>>> templateDir);
>>> engine.setProperty(RuntimeConstants.RUNTIME_LOG_LOGSYSTEM_CLASS,
>>> "org.apache.velocity.runtime.log.JdkLogChute");
>>> engine.init();
>>>
>>> because I'm using JDK logging in my app anyway. My own logging is based
>>> on a console handler with level INFO and a file handler with level FINE
>>> (at
>>> least right now).
>>>
>>> What happened now was that there was nothing related to Velocity on the
>>> console, and truckloads of FINE log entries in the file handler. That's
>>> not
>>> quite all of the expected results, but it's the best I got so far. As it
>>> seems,
>>> Velocity seems to pick up the settings of the JDK logging subsystem.
>>>
>>> It gets weird tho when I set the logging level for the file handler to
>>> INFO
>>> as
>>> well: all log entries to the file handler for the JdkLogChute are gone.
>>> The
>>> only
>>> way for me to understand these observations is that only log messages of
>>> level FINE are actually recorded. Even if I go to level FINEST and check
>>> out
>>> the log files afterwards, there's zillions of Velocity log entries, but
>>> all
>>> with level FINE. This works also for the
>>> java.util.logging.ConsoleHandler,
>>> i. e. setting the level to FINE there also gives me the log messages, but
>>> all of level FINE. In my original velocity.log there were - for the same
>>> set
>>> of
>>> data - "[error]" and "[debug]" entries which I would like to see again as
>>> corresponding log entries.
>>>
>>> Having only messages of level FINE can't be correct tho.
>>>
>>> When, for testing purposes, I add a manual log entry like this
>>>
>>> engine.getLog().info("Hello");
>>>
>>> right after the init(), it works on both console and file. So the loggers
>>> used inside Velocity also work correctly, but it seems that Velocity
>>> itself only creates log messages with level FINE - which I refuse to
>>> believe.
>>>
>>> I also tried the AvalonLogChute instead since that seems to be the
>>> default used in my previous implementation (velocity.log created
>>> by interacting with Velocity instead of VelocityEngine). Same result
>>> - an empty velocity.log file. Well, this is not too surprising since
>>> I presume that the AvalonLogChute is still the default - and I had
>>> not specified a LogChute in the first attempts.
>>>
>>> I'm kinda lost right now. I would like to be able to use JDK logging
>>> (since then I don't have to deal with different output files in analysis
>>> afterwards) and I would like to propagate the (configurable) log
>>> levels of my application to the Velocity logging.
>>>
>>> At the very least, I need a new velocity.log file to be created whenever
>>> my application starts a new iteration - whichever LogChute gives
>>> me that back. It does this effectively as listed above:
>>>
>>> Old version:
>>>
>>> Invoke
>>>
>>> Velocity.setProperty(RuntimeConstants.FILE_RESOURCE_LOADER_PATH,
>>> templateDir);
>>> Velocity.init();
>>>
>>> -> results in all output being appended to one velocity.log file. This
>>> will
>>> be a file system capacity issue in the long run.
>>>
>>> New Version:
>>>
>>> engine = new VelocityEngine();
>>> engine.setProperty(RuntimeConstants.FILE_RESOURCE_LOADER_PATH,
>>> templateDir);
>>> engine.init();
>>>
>>> -> results in an empty velocity.log. Not very helpful for finding
>>> problems.
>>>
>>> Any help would be very much appreciated. Studying the Velocity source
>>> code gave me some hints, but for now to no avail. Something must be
>>> wrong in the way I configure the VelocityEngine instance, I guess.
>>>
>>> Thanks,
>>> Matthias
>>>
>>>
>>> ---------------------------------------------------------------------
>>> To unsubscribe, e-mail: user-unsubscribe@velocity.apache.org
>>> For additional commands, e-mail: user-help@velocity.apache.org
>>>
>>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: user-unsubscribe@velocity.apache.org
>> For additional commands, e-mail: user-help@velocity.apache.org
>>
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: user-unsubscribe@velocity.apache.org
> For additional commands, e-mail: user-help@velocity.apache.org
>
>

---------------------------------------------------------------------
To unsubscribe, e-mail: user-unsubscribe@velocity.apache.org
For additional commands, e-mail: user-help@velocity.apache.org