Introduction
SAP Sourcing supports scripting as a key feature in extending its default functionality. Scripting is also used to implement workflow approvals, which enable implementation of complex business rules. The scripting capability is a powerful feature used by many Sourcing customers, but mastering its use and monitoring its behavior can present some challenges.
Since the Sourcing product itself does not provide any development capabilities that might be found in a modern IDE, both SAP and customers alike rely heavily on the use of logging to know how scripts are behaving. This document describes some enhancements that have been made to improve Sourcing’s script related logging.
Original Logging
Sourcing has always made use of logging in an attempt to capture important scripting activity. To date, this has primarily been logging when a script is about to be executed, and the actual script itself. While this was a reasonable first step, it suffers from a couple problems. First, this logging is done at the DEBUG log level. Many systems, Production or otherwise, aren’t configured to log at this level. This makes troubleshooting errors or unexpected behavior difficult as the log level must be changed and the issue reproduced. Second, the amount of information captured in these log entries is not as comprehensive as it could be. For example, the log does not specify any of the system-set variables (otherDoc, current_phase, field, etc.) Further, by only logging when a script is about to execute, there is no indication of its completion.
The following is an example of the original logging output. In this case, the script itself simply uses the Logger API to create a log message.
08:55:46.31 - DEBUG - ScriptEnvironment.execute - sessionid=1b8rhq;username=ghrob;tenantid=#test#;thread=RequestHandler.RqThread: add - executing script:
import com.sap.odp.api.common.log.*;
LogMessageIfc lm = Logger.createLogMessage(session);
lm.setLogMessage("*** Project Created Script ***");
Logger.debug(lm);
08:55:46.32 - DEBUG - sessionid=1b8rhq;username=ghrob;tenantid=#test#;debug_scope=Logger;thread=RequestHandler.RqThread: add - *** Project Created Script ***
Note that this logging has not been changed and should still be available in DEBUG logs.
Enhanced Logging
Sourcing now provides enhanced script logging that addresses the issues specified above.
Log at the INFO level
Since the overhead is low and the value potentially high, all new scripting log entries are logged at the INFO level. This should make the information available on most systems (depending on actual the actual log configuration).
Log more comprehensive data
Whenever possible, the type of script, object against which it is being executed and any system-set variables is included in the log. The exact set of data depends on the specific type of script being executed. For example, the current_phase and other_phase are not applicable to a POST_CREATE lifecycle event.
Log start and end of script execution
Sourcing now makes two log entries for a script event, one prior to execution and one after execution completes. This second log entry makes it easier to tell that a script did in fact complete. It also contains information about the time it took to execute the script. This should provide insight into any performance implications of the script.
The following example shows a field validation script. It simply uses the Logger API to log a message. You can see the field (PROJECTXREF) and doc (PROCAT-001-BGNMX-2013) system-set variables as well as the elapsed time.
10:59:14.00 - INFO - ScriptManager.markLog(SessionContextIfc, String - sessionid=1b8rhq;username=ghrob;tenantid=#test#;debug_scope=scripting;thread=RequestHandler.RqThread: fullsave - begin: executeFieldScript for PROJECTXREF on PROCAT-001-BGNXM-2013
10:59:14.00 - DEBUG - ScriptEnvironment.execute - sessionid=1b8rhq;username=ghrob;tenantid=#test#;thread=RequestHandler.RqThread: fullsave - executing script:
import com.sap.odp.api.common.log.*;
LogMessageIfc lm = Logger.createLogMessage(session);
lm.setLogMessage("*** Project Field Validation Script ***");
Logger.debug(lm);
10:59:14.02 - DEBUG - sessionid=1b8rhq;username=ghrob;tenantid=#test#;debug_scope=Logger;thread=RequestHandler.RqThread: fullsave - *** Project Field Validation Script ***
10:59:14.02 - INFO - ScriptManager.markLog(SessionContextIfc, String - sessionid=1b8rhq;username=ghrob;tenantid=#test#;debug_scope=scripting;thread=RequestHandler.RqThread: fullsave - end: executeFieldScript for PROJECTXREF on PROCAT-001-BGNXM-2013 [ELAPSED TIME: 16 ms]
New Log Attribute
In order to provide support for filtering script related log lines, we have introduced a new log attribute. debug_scope will contain the value scripting for all Sourcing framework logging related to scripting.
10:59:14.02 - INFO - ScriptManager.markLog(SessionContextIfc, String - sessionid=1b8rhq;username=ghrob;tenantid=#test#;debug_scope=scripting;thread=RequestHandler.RqThread: fullsave - end: executeFieldScript for PROJECTXREF on PROCAT-001-BGNXM-2013 [ELAPSED TIME: 16 ms]
Since many customers use the Logger class from their scripts, LogMessage objects created via this class will have their debug_scope set to Logger. They are intentionally not set to debug_scope=scripting as the Logger APIs can be used in other contexts, such as an IAPI Task Execution.
The following example shows a prescript from a Workflow Process, which simply uses the Logger API to create a log message.
14:30:07.07 - DEBUG - ScriptEnvironment.execute - sessionid=1b8rhq;username=daemon;tenantid=#test#;thread=Daemon-0063: ODP_EVENT_WORKFLOW_ENGINE (0, -2147483548) - executing script: import com.sap.odp.api.common.log.*;
LogMessageIfc lm = Logger.createLogMessage(session);
lm.setLogMessage("*** HRG XPDL preScript ***");
Logger.debug(lm);
14:30:07.14 - DEBUG - sessionid=1b8rhq;username=daemon;tenantid=#test#;debug_scope=Logger;thread=Daemon-0063: ODP_EVENT_WORKFLOW_ENGINE (0, -2147483548) - *** HRG XPDL preScript ***
Log Configuration
As a reminder, the set of log attributes and their order in log files is configured in the fcisystem.properties file. Below is a sample showing the new attribute added in as the second column. Adjust to suit your needs.
system.log.logFields=timestamp;debug_scope;priority;class;method;thread;sessionid;tenantid;username;exception
Availability
This enhanced logging isavailable in W7 SP9, W9 SP14 and will be part of Version 10.
