When developing and/or debugging BPEL processes, the Oracle BPEL Console is your best friend. Every change to every variable, every activity that was executed, everything is right there for you to inspect, whether the instance is still in-flight or already completed. But although this sounds like the ultimate debugging tool, Iâ€™m sure youâ€™ve noticed like me that when your processes get really big (which they tend to do rather quickly), thereâ€™s two reasons why debugging can be difficult. The first is plain and simple â€œinformation overloadâ€. If your audit flow contains hundreds of activities and possibly thousands of variable data changes, finding an individual piece of information is not trivial. I find the second reason, however, to be of even more profound impact: the BPEL console will not show you the execution path through your process flow (which would indicate which parts of the code got executed, and which didnâ€™t), but rather it displays a long, sequential list of Activities that were executed. Especially if you have a lot of switch and/or pick statements, and if your code contains loops (in which case each iteration will add all executed Activities to the list), determining â€œwhat happenedâ€ during execution of your instance from this long, long audit trail might prove a challenge.
In a â€œmini-seriesâ€ of Blog entries, I will share a number of techniques that I have used in situations like this, to extract logging/debug information from a BPEL process instance using BPEL Sensors. This first entry will focus on a simple, straightforward form of logging, using a â€œVariable Sensorâ€ to provide a sort of â€œmanagement summaryâ€ of the execution of a BPEL process instance.
Using Sensors for Logging and Debugging
BPEL Sensors can be very useful to extract information from the execution of a process. Basically, they come in three flavours: Activity Sensors, Fault Sensors and Variable Sensors. The first type is ideal to have a BPEL process trigger â€œeventsâ€, as you can configure them to â€œfireâ€ when individual Activities in your process get executed. You even get to specify if they need to fire on activation (i.e. before the Activity is executed), on completion, on faults, when compensation is invoked, or on all these events. Finally, you can pass any amount of process data along to it, allowing the â€œSensor Actionâ€ associated with the Sensor to use that information, for instance by posting it on a queue, storing it in the database, sending it to a BAM server, or invoking custom Java code with it.
Sometimes I use Activity Sensors for debugging purposes, by adding them to critical activities that determine process behavior, and adding process variables to them so that I can see those bits of information that were crucial at that particular moment in process execution. This is a very powerful method and I will show some examples in future Blog entries, but often, my needs are more simple, and all I really need is a BPEL equivalent of a good old Log4J statement in Java code:
log.debug(â€˜Entering Order line loop, with â€˜+orderlines.size()+â€™ order linesâ€™);
Simple logging using Variable Sensors
For simple logging like this, where the log messages are just simple strings, the â€œVariable Sensorâ€ comes in handy. This type of Sensor is triggered every time a change is made to a process variable. So, unlike Activity Sensors where you need to specify exactly where in the process flow you want that sensor to fire, with Variable Sensors you only define it once and it fires automatically each and every time in your process when changes are made to the process variable it is assigned to. So basically, to get some simple debug logging going, all you need is to create one â€œLogâ€ variable, add a Variable Sensor to it, and just by assigning a new value to it anywhere in the process where you need logging, the Sensor fires and processes the value of the variable.
So, how does this work? As an example, letâ€™s take the BPEL process flow below. This is a simple demo flow and, as mentioned before, for simple flows the BPEL Console works perfectly well all by itself. Just imagine this is part of a much bigger process, and you would need to figure out what happened in this part of the flow by inspecting hundreds of audit trail entries.
Configure Sensors for Logging purposes
To incorporate Sensor based logging in our process, there are two tasks to perform. The first part is configuration. You only need to do this once for the entire process. In terms of Log4J, it would compare to the code at the top of the class, defining the “log” variable that we can write to.
Log log = LogFactory.getLog(this.getClass());
In fact, this is incredibly similar to what we will do in BPEL! We also start by adding a variable, â€œLogMessageâ€, to the process, and then we add a Variable Sensor to it that will process all changes that are made to it. To get started, click on the â€œVariablesâ€ icon on the process diagram (x) (see screenshot below).
In the window that pops up, create a new Variable called â€œLogMessageâ€, of type xsd:string.
Click â€œOKâ€ to close this window, then select the newly created â€œLogMessageâ€ variable and click on the â€œEditâ€ button:.
Select the â€œSensorsâ€ tab, and press the â€œCreateâ€ button to create a Variable Sensor:.
Name the sensor â€œLogSensorâ€, and use the little icon on the right of the â€œTargetâ€ field to select the â€œLogMessageâ€ variable. Itâ€™s kinda weird you need to do this since you entered this window from the â€œEdit Variable â€“ LogMessageâ€ window, but oh wellâ€¦.
A Sensor is like a trigger definition that indicates _when_ it fires. But in order to make it _do_ something, youâ€™ll need to tie it to a â€œSensor Actionâ€. In PL/SQL terms, a â€œSensorâ€ is like a table trigger that invokes a PL/SQL procedure, and the â€œSensor Actionâ€ is the procedure that it invokes. The Sensor Action (procedure) can therefore be re-used by many Sensors (triggers).
You can create a Sensor Action within the current dialog, by clicking the â€œAddâ€ button in the â€œSensor Actionsâ€ section. In the â€œSensor Action Chooserâ€ you can pick previously defined Sensor Actions, but since we have not created one yet, weâ€™ll do that now. Notice that there are two flavors to choose from: BAM Sensor Actions, and regular â€œSensor Actionâ€. Choose the latter..
In the dialog that pops up, call the Sensor Action â€œLogActionâ€, and leave â€œPublish Typeâ€ to â€œDatabaseâ€. This means that the Sensor events (including their data) will be written to a pre-defined database tables in the BPEL dehydration store. In this case (this being a Variable Sensor), that table is â€œVARIABLE_SENSOR_VALUESâ€. Unfortunately, you can NOT define your own table. But for debug logging purposes like ours this is ideal, especially since the BPEL console has maintenance facilities to clean up this table. In fact, as youâ€™ll see later, there is not even any need to query this table, as its contents will be shown in the BPEL Console when inspecting the process instance..
Press OK, and see how the newly created LogAction is tied to the LogSensor on the LogMessage variable. Also notice you could have multiple Sensor Actions could be tied to a single LogSensor, allowing you, for instance, to write to the database AND post to a JMS queue..
OK this dialog, and see the summary: You have a LogMessage variable, with a sensor called â€œLogSensorâ€ on it, which is tied to the â€œLogActionâ€ Sensor Action (which will publish to the database).
This concluded the configuration part. Although it may seem like a lot of work the first time, I promise that this takes under a minute once you’ve done this a few times. And, remember, you only need to do this once for the entire process. The actual “log statements” are far simpler to create, as we’ll see next.
Adding “Log statements” to your Process
What we have now is a LogMessage variable which is â€œriggedâ€ so that every change to it will automatically be published to the database (and, as you will see later, is also automatically visible in the BPEL console). All we need to do now is start creating our “log statements” in the BPEL process. This simply means: assigning values to the â€œLogMessageâ€ variable at places in your process flow that currently interest you.
You can add new Assign activities to your process to do this, or just add Copy Operations to existing Assigns activities in your process. In the â€œAssignâ€ dialog, select the LogMessage variable on the right (notice the cool â€œsensorâ€ icon to the left of it), and (typically) the â€˜Expressionâ€™ type on the left. You could log simple strings by just typing something like â€˜Hello, this is debug loggingâ€™ (donâ€™t forget the single quotes), or use the Expression Builder to mix your log statements with dynamic values (typically with the â€˜concatâ€™ statement, with which you can concatenate an arbitrary number of strings, separated by commas).
Below is the result of adding a simple, static log statement to an existing Assign activity:.
Now Iâ€™m sure you are wondering where this logging turns up after initiating a process instance. Well, our â€œLogActionâ€ Sensor Action published to the database, but fortunately you wonâ€™t have to go to the database and query that table to retrieve the logging information. When looking at the Flow of an individual instance in the BPEL Console, one of the tabs reads â€œSensor Valuesâ€. Below, you can see the result from adding some log statements to the Process we started out with.
So there you have it. Simple, log4J style logging that requires just a little setting up at Process level, and then simply some Copy rules to a single â€œLogMessageâ€ variable to create logging that is conveniently accessible from the BPEL console.
To wrap things up: how to clean things up after youâ€™re done debugging. When you no longer need your log statements, thereâ€™s a couple of things to do. First, you can purge all sensor values from the BPEL tables, by going to the â€œInstancesâ€ tab in the BPEL Console and clicking the â€œPurge All Sensor Dataâ€ button. Then, in JDeveloper, have some options. You can:
- Disable logging for now (but you might want to turn it back on later)
To do this, simple delete the LogSensor from the LogMessage variable. The LogMessage variable and log statements remain in your code but will take hardly any time during execution, and no sensors will fire (and therefore no database activity to the sensor tables will take place). All you need to do to turn logging on again at a later point is recreate the LogSensor and assign it to the LogAction (which will still be there).
- Remove all trace of logging
- Delete the LogMessage variable from the BPEL process.
- Rebuild the process and notice the compilation errors. Clicking on them will lead you to all the Copy operations where you wrote to the LogMessage variable. If this is the only operation in the Assign, remove the assign, otherwise just remove the Copy operation.
- Rebuild the process to make sure youâ€™ve gotten rid of them all.
That it for now. In the next part, I will show how you can use Activity Sensors if using a simple xsd:string as log message does not suffice, and you need more information about the BPEL process state in your log. In the third (and probably final) part, I will show how you can use a custom Java SensorAction, to be able to use the Log4J logging framework to deal with your log messages.
6 thoughts on “Debug Logging in BPEL using Sensors – Part 1”
Hi Peter — do you ever think you’ll write up “Part 2” about Activity Sensors? Â I would be interested to see a write up on that.
Indeed it is possible to use Log4J to produce your own functional log streams, separate from the domain logs. Whereas in this article I use the “Database” Sensor Action, you would use a custom Java sensor action. In this Java class, you can write to a Log4J log just like you would in any other Java class. All you need to do is choose an appropriate log category (i.e. the “name” of the logger), and configure the log4j config file on the server to use a different “appender” for log messages written to this logger. I have done this in the past, works like a charm. I had a generic mechanism to create the “log category” based on process name, activity name, trigger moment etc. This way, we could change log levels per process, activity etc.
I might even be able to retrieve some source code. You can contact me at myfirstname dot mylastname at amis.nl
Very nice description of how useful sensor can be.
The client I am working at is requiring us to “log” to their LOG4J logs (seperate from the DOMAIN logs). Can we route this information to another log4j logs? According to the Oracle Manual you can route it to a JAVA Class. We thought that we could establish a seperate log4j logger using a Java Class that we route all of our sensor actions. Have you or anyone else done that?
Nice article. Would be useful after transformations and xpath fuctions to check the new values. I think i will use it for that.
It all depends on the reason why you need logging at that point. If it is to show that the process got to that point (as it is in this example) what you say it true. If it is to have (one of) the results of the Assign operation show up in the debug log, you’ll have to put it after the operation(s) in question.
That’s quite nice! We could have used that in our workshop.
Just one remark…when adding a log statement to an existing assign operation it might be wise to add it as the first assign operation in the list. So when one of the following assign operation fails, at least your log message has been processed.
Comments are closed.