Friday Dec 07, 2012

Selective Suppression of Log Messages

Those of you who regularly read this blog will probably have noticed that I have a strange predilection for logging related topics, so why break this habit I ask? 

Anyway here's an issue which came up recently that I thought was a good one to mention in a brief post.  The scenario really applies to production applications where you are seeing entries in the log files which are harmless, you know why they are there and are happy to ignore them, but at the same time you either can't or don't want to risk changing the deployed code to "fix" it to remove the underlying cause. (I'm not judging here). The good news is that the logging mechanism provides a filtering capability which can be applied to a particular logger to selectively "let a message through" or suppress it. This is the technique outlined below.

First Create Your Filter 

You create a logging filter by implementing the java.util.logging.Filter interface. This is a very simple interface and basically defines one method isLoggable() which simply has to return a boolean value. A return of false will suppress that particular log message and not pass it onto the handler.

The method is passed the log record of type java.util.logging.LogRecord which provides you with access to everything you need to decide if you want to let this log message pass through or not, for example  getLoggerName(), getMessage() and so on.

So an example implementation might look like this if we wanted to filter out all the log messages that start with the string "DEBUG" when the logging level is not set to FINEST:

 public class MyLoggingFilter implements Filter {
    public boolean isLoggable(LogRecord record) {
        if (  !record.getLevel().equals(Level.FINEST) 
            && record.getMessage().startsWith("DEBUG")){
         return false;   
        }
        return true;
    }
}

Deploying  

This code needs to be put into a JAR and added to your WebLogic classpath.  It's too late to load it as part of an application, so instead you need to put the JAR file into the WebLogic classpath using a mechanism such as the PRE_CLASSPATH setting in your domain setDomainEnv script. Then restart WLS of course.

Using

The final piece if to actually assign the filter.  The simplest way to do this is to add the filter attribute to the logger definition in the logging.xml file. For example, you may choose to define a logger for a specific class that is raising these messages and only apply the filter in that case. 

<logger name="some.vendor.adf.ClassICantChange"
        filter="oracle.demo.MyLoggingFilter"/>

You can also apply the filter using WLST if you want a more script-y solution.

Thursday Oct 18, 2012

ADF Logging In Deployed Apps

Harking back to my series on using the ADF logger and the related  ADF Insider Video, I've had a couple of queries this week about using the logger from Enterprise Manager (EM). I've alluded in those previous materials to how EM can be used but it's evident that folks need a little help.  So in this article, I'll quickly look at how you can switch logging on from the EM console for an application and how you can view the output. 

Before we start I'm assuming that you have EM up and running, in my case I have a small test install of Fusion Middleware Patchset 5 with an ADF application deployed to a managed server.

Step 1 - Select your Application

In the EM navigator select the app you're interested in:


At this point you can actually bring up the context ( right mouse click) menu to jump to the logging, but let's do it another way. 

Step 2 - Open the Application Deployment Menu

At the top of the screen, underneath the application name, you'll find a drop down menu which will take you to the options to view log messages and configure logging, thus:


Step 3 - Set your Logging Levels 

Just like the log configuration within JDeveloper, we can set up transient or permanent (not recommended!) loggers here.


In this case I've filtered the class list down to just oracle.demo, and set the log level to config. You can now go away and do stuff in the app to generate log entries.

Step 4 - View the Output 

Again from the Application Deployment menu we can jump to the log viewer screen and, as I have here, start to filter down the logging output to the stuff you're interested in. 


In this case I've filtered by module name. You'll notice here that you can again look at related log messages.

Importantly, you'll also see the name of the log file that holds this message, so it you'd rather analyse the log in more detail offline, through the ODL log analyser in JDeveloper, then you can see which log to download.

Saturday Jun 11, 2011

Adventures in ADF Logging - Part 5

Unleashing the True Power of the ADFLogger

So far we've seen that the logging facility  provided by the ADFLogger and the attendant tools in JDeveloper is all pretty useful and provides a powerful way of implementing and examining your logs. However, lets's take it to the next level (here's where it gets really interesting). 

You are, I'm sure, familiar with the -Djbo.debugoutput=console switch which is a command line argument to WebLogic or the ADF/BC tester which provides a bunch of useful trace information such as when bindings are constructed and ADF/BC queries and bind variables are manipulated.  It's generally regarded as a key tool in any ADF Hackers toolbox.  However, you may have thought to yourself: This is great but it's a pain having to re-run the application (and restart WLS) just to switch this diagnostic on... And you'd be right, it is a pain and certainly not something you would entertain on a production system. But guess what, we can use the logging capabilities to do the same thing without a restart.

Debugoutput Without the Pain

 To work this magic, just run your application without the -Djbo.debugoutput flag and once it's running bring up the ODL Configuration Screen (Refer back to Part 3 in this series if you've not already read up on how to do that).

Now switch on FINEST for the following packages:

  • oracle.adf
  • oracle.adfinternal
  • oracle.jbo 

Here's what it should look like:

Switching on Logging for ADF

Now go back to the web browser and carry out the activity that you're trying to trace (remember - no need to restart, the logging kicks in immediately). Once you're done open up the ODL Analyzer (refer to Part 4 in this series). The main thing that you'll observe is an awful lot of logging has happened. In this case I happen to have added my own logging call into an Entity Object accessor method so I can search the log for the call that is part of the transaction I'm interested in:

Search for an interesting record

Now I can use that Related By Request option that we looked at last time to see all the log messages associated with this one:

Filter By Request

Which leads to this more constrained list: 

Filtered List of results

Now scroll down this list of messages and I'll start to encounter useful messages such as this set:

Interesting ADF Actions

In this case it's the SQL that is being generated to get the rowcount on a VO and I can look at the key information such as the actual count returned, the SQL and the bind variable substitution.

But Wait, There's More

The final piece in the jigsaw  is that mysterious Related By ADF Request option that I skipped over last time. Now that we have a full-fat diagnostic log let's use that option instead of plain Related by Request. When you do this you're taken to that By ADF Request tab in the analyzer. This is what you'll see:

ADF Request View

What you're seeing here is a complete breakdown of the ADF Request by phase with elapsed times and a really simple to understand view of what happened when, and how log it took. You can view the details of each message in the bottom pane, and in this case again we're looking at an Estimated Row Count call.

At this point I should probably shut up and let you drool. Enjoy!

Friday Jun 10, 2011

Adventures in ADF Logging - Part 4

Viewing The Results of Your Hard Work

Previously in this series we've seen how you can instrument your code and then subsequently switch logging on using the configuration editor for logging.xml. However, so far we've just looked at that output in the console / log window of JDeveloper which is OK in the simple debugging scenario but really is a pale comparison with what we could be doing here.

Recall from the previous installment of this series, that the root logger defines several handlers for the log output and that console was on that list. Well another handler on that list is the odl-hander - the Oracle Diagnostic Logging (ODL) utility. Let's look at how we can use that to get a bit more information out of the logging that we've painstakingly added to our code.

JDeveloper  has a build in viewer for the ODL logs which you can simply get to from the Tools > Oracle Diagnostic Log Analyzer menu option, or from the drop down menu in the log window:

Starting ODL Analyzer

 You'll see that in the case of the Action Menu we have a shortcut to just open the log for the current session which is what you need most of the time, however, you can also select any ODL diagnostic log (from any WebLogic instance, not just the integrated WLS) and diagnose that.

Now The Power is Yours

The ODL Analyzer will now appear and you can start to play. Note that once the ODL Analyzer is open you can click the magnifying glass icon at the top of the screen to browse the file system for other logs.  The file dialog that comes up already has a shortcut for you pointing to the WLS log directory of the integrated container:

ODL Log file selection

In this case I'm viewing the current log and I've filtered it to just show me logging generated in the last hour and coming from the oracle.demo.whippet package. However, you can see that there is a lot of filtering that you can do to slice and dice your logs:

Filtered ODL Screen

Notice that there are two tabs in the ODL Analyzer, make sure the one labelled By Log Message is selected at this stage.

This window actually has a detail view which in this case is collapsed below the table of log entries. That will give you more information about the selected log entry such as the authenticated user and more detail such as the stack trace if you logged a Throwable.

You can control the columns displayed in the table using the small downwards facing arrow above the right hand scrollbar. Next have a play with the Related pulldown . Click this for a particular log entry and this will present 3 options:

  • Related By Request - will filter the view to just show the logging entries that came out of the same HTTP Request 
  • Related By Time  - will filter the view to a specified timeslice (you'll get a pull-down to allow you to define how long back in time you want to look before the specified entry. The default is 30 seconds). This can be really handy when other things are happening on the system which may well be part of a separate request but impact the thing you are trying to diagnose - for example, an af:poll kicks off a PPR request that you were not expecting.
  • Related By ADF Request  - This one we'll cover in the next article in this series

So as you can see, the ODL analyzer gives you a lot of power to both filter your logging output and start to logically trace what's happening within your application. Next time though I'll look at what happens when we incorporate that information into the context of the ADF Lifecyle. That's when things get extremely exciting.

Friday Jun 03, 2011

Adventures in ADF Logging - Part 3

Controlling Logging Output

So far in this series I've just been concentrating on how to add logging calls to your code. That's all very well but frankly, not a lot of use without some way to switch all that on.

When using a logging framework such as java.util.Logging you generally have some external configuration file which you would use to define which loggers are active at what level and for what class / package. In the case of the basic java logging this is accomplished with the logging.properties file that lives in the JRE /lib directory (or can be passed as a -D parameter as you start up the JVM). When using the ADFLogger the idea is similar except this time logging is controlled using an XML congiguration file - logging.xml which lives in the WLS servers directory structure, it turns out that you don't need to know the exact location, so only look for it if you are really curious at this stage.

Making it All Too Easy

Editing the logging.xml file would be OK, however, we like to make life easier than that and so JDeveloper actually supplies a really simple to use graphical interface to edit this configuration. In fact, as we'll see it does a bit more than that as well. Let's step through that now:

Step 1 - Start Your Engines

Or rather start your embedded WebLogic instance. We can configure logging before the WLS is running but if we wait until it is actually running and your application is initially deployed it we'll actually get visibility into all of the packages that are durrently deployed into the running server. This will come in handy later on when we come to look at some of the really cool things that we can do with extisting instrumentation but I'll cover that in a later episode! For now just run your application.

Step 2 - Open the Logging Editor

There are two ways to get to the logging configuration screen.

  1. Open the Application Server Navigator (Ctrl + Shift + G), right mouse click on the IntegratedWeblogicServer and select  Configure Oracle Diagnostic Logging for "IntegratedWeblogicServer".
  2. From the Log window (usually docked underneath your editor) pull down the Actions menu  and select Configure Oracle diagnostic Logging.

Both approaches open the same editor on top of the logging.xml file. Here it is, I've expanded the first couple of levels in the tree to make it interesting:

Image of the Logging configuration Screen

 So what we see here is a hierarchy of all the packages in the running app server. Notice that some of the icons are green, these are packages or classes that have a presence in the logging.xml already and some are yellow. This latter group are transient, that is, we can temporarily set up logging on that package or class for the duration of the application server, but once the application server shuts down all the logging configuration will be reverted.. You'll notice the checkbox at the top of this screen that is labeled Hide Transient Loggers, well you can guess what that does now.

Step 3 - Configure Some Logging

 The rest is all fairly self explanatory. To configure logging at any level you click on the level column and from the pull down select the level you want to look at.  In the image above you can see that I've set the logging for the Root Logger to the INFO level. This implicitly means that any child of that node (everything in this case because it's the root) will also be logging at the INFO level unless it explicitly overrides.  Normally your root logger would log at WARNING or SEVERE, you just want to keep an eye out for any and all problems at that level.

So perhaps we wanted to switch on CONFIG level logging for everything under the oracle.demo root we would just set that in the level column. Of course with Config level Info messages would still be printed out as well. So you can be as fine grained about this as you want, controlling the logging level on a class by class or package by package basis.

If need to set up a logger on a class / package that is not visible in the structure (yet) you can use the green add (+) button at the top left of the editor to add a new one in.  The loggers you add can be persistent (stored in the logging.xml) or transient (discarded at the end of the session) Note that transient loggers can only be created when you are actually running the internal WLS instance. 

As well as the logging levels it is also possible to configure the handlers.  In logging, the handler is the thing that takes your log message and does something with it - prints it to the console, writes it to a file etc. If you select the root logger in the editor here you will see that it defines three handlers listed in the Handler Declaration section of the screen at the bottom of the editor:

  • odl-handler
  • wls-domain
  • console

The first two would be the default for a standalone WLS instance, but the console we've automatically added for you in the case of the embedded WLS so that you will be able to see the output of your carefully placed logging commands in the log window of the IDE (Hint - Now is a good time to go to Tools > Preferences and increase the size of your logging buffer). I recommend that you do not change these handlers and just continue to inherit from the root. The reason for this will become evident in a later installment.

For example in the sample I'm running here  I have a few CONFIG and INFO level logging calls in the code and this generates the following output on the console:

<Library> <initSampleData> Setting up Library sample data
<MainPageBackingBean> <<init>> Creating a new Instance
<MainPageBackingBean> <handleSlotCartridgeMove> Dropping Module : 1 : Left-12
<MainPageBackingBean> <<init>> Creating a new Instance
<MainPageBackingBean> <handleSlotCartridgeMove> Dropping Module : 1 : Left-14
<TaskFlowUtils> <diagnosticInitializer> Key:"displaySlot" Value:"Module : 1 : Left-9" Type:[oracle.demo.whippet.model.Slot]

Cryptic yes - but I know what it all means in the context of this application and it's exactly the information that I need to monitor what's going on. It tells me that by backing bean classes are being created for every request, and in this case the drophander for some drag and drop processing has received the payload I expect.  Finally one of my standard pieces of instrumentation which I embed in my task flow initializer call is reporting all of the parameters passed to it. All good stuff. 

Next time we'll take a look at this output information  in more detail and explore some of the real power of this logging once you start to relate all of this information together into sequences of events.

Tuesday May 31, 2011

Adventures in ADF Logging - Part 2

Logging Templates

OK last time I said I'd tell you about how to look at the logging output next, but then I got all enthusiastic this morning and thought I'd create some code templates to help you use the ADFLogger. Code templates are a really neat feature of JDeveloper and if there is some bit of code (like logging) that you use a lot then 5 minutes spent building a template can save you a bunch of time in the long run.

Here are the templates I've created:

Shortcut Purpose
lgdef A basic static class logger definition
lgdefr A basic static class logger definition with resource bundle
lgdefp A basic static package logger definition
lgi Log statement for an informational message
lgc Log statement for configuration information
lgw Log statement for a warning message
lgs Log statement for an error message
lgig Guarded log statement for an informational message
lgcg Guarded log statement for configuration information
lgwg Guarded log statement for a warning message
lgsg Guarded log statement for an error message

Installing the Templates

I've made these templates available as an XML export that you can download from here: loggingTemplates.xml

To install these:

  1. Open  Tools > Preferences from the JDeveloper menu
  2. Expand the Code Editor  > Code Templates node in the preferences navigator
  3. Select the More Actions  > Import menu option as shown here and import the xml file.

Logging import

About

Hawaii, Yes! Duncan has been around Oracle technology way too long but occasionally has interesting things to say. He works in the Development Tools Division at Oracle, but you guessed that right? In his spare time he contributes to the Hudson CI Server Project at Eclipse
Follow DuncanMills on Twitter

Note that comments on this blog are moderated so (1) There may be a delay before it gets published (2) I reserve the right to ignore silly questions and comment spam is not tolerated - it gets deleted so don't even bother, we all have better things to do with our lives.
However, don't be put off, I want to hear what you have to say!

Search

Archives
« April 2014
MonTueWedThuFriSatSun
 
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
    
       
Today