How to Log Workflow Execution
Running a workflow generates logs with the information about the result of workflow execution and behavior of workflow tasks. In the server context, you can configure a single log for all workflows with custom logging settings.
This article covers the information about the logs contents, configuration options, and conditions for generating logs in different execution contexts. For the general logging reference, see Logging Configuration.
If there are syntax and other general configuration errors in the workflow that result in an invalid workflow configuration file, no logs are created when the workflow is started.
In the server context (workflows deployed via the Workflow Component), such workflows are marked with ERROR in the ONE Runtime Server Admin and cannot be started at all.
|
Workflow instance state
A workflow instance state log contains full information about the execution state of all tasks, links, and the entire workflow, as well as the configured variables and global settings.
The log can be stored either to a workflow instance state .wis
file or to a database.
WIS file
In the batch mode, the workflow state is always stored to a .wis
file.
In the server context, the workflow state information is stored to a .wis
file if State Storage Provider is set to File State Storage Provider in the Workflow Component.
Every workflow execution generates a new .wis
file.
The file contains information about the current state of the workflow and all included tasks and is updated every time the status of any part of the workflow changes (for example, a task is scheduled or executed).
The following information is included for each server with an executed workflow:
-
Hostname
-
IP address
-
Port
For database storage, the following columns are in the workflow instances table.
-
host_name
-
host_address
-
host_port
In the batch mode, there is no limit on the number of stored logs. To clean the log history, you have to manually delete the logs. In the server mode, set the |
The name and location of the generated file depend on the configuration and execution context. The following table summarizes the differences.
Execution context | Location | File name | ||
---|---|---|---|---|
IDE |
The same folder as the workflow. |
Overwritten each time, for example, |
||
Batch script |
As specified in the command. |
As specified in the command.
|
||
Server |
|
Serialized with unique ID assigned by the server, with the following naming convention: A common source separator character (colon) is replaced with the at sign (
|
For detailed information about the workflow execution options, see Execute Workflows. |
The following example shows the contents of a WIS file:
<?xml version='1.0' encoding='UTF-8'?>
<WorkflowInstanceState>
<hostInfo hostName="MACHINE" hostPort="7777" hostAddress="10.254.253.79"/>
<forcedResume>false</forcedResume> <!-- information about current state of the workflow -->
<id>1</id>
<linkEvaluations/>
<started>2017-03-01 13:50:51</started>
<state>FINISHED_OK</state>
<stopped>2017-03-01 13:50:51</stopped>
<taskVariables>
<taskVariableBean task="001_hello_world" name="SCRIPT_RESULT_CODE" type="INTEGER" value="0"/>
</taskVariables>
<tasks> <!-- contains current states of tasks -->
<workflowTaskPersistModelBean stopped="2017-03-01 13:50:51" started="2017-03-01 13:50:51" id="001_hello_world" state="FINISHED_OK">
<compensationStates/>
</workflowTaskPersistModelBean>
</tasks>
<wfTimestamp>2017-03-01 13:50:46</wfTimestamp>
<wfVariables> <!-- contains values of the variables the workflow was started with -->
<variableBean name="SALUTATION" type="STRING" value=""/>
<variableBean name="ewf_execution_id" type="STRING" value="2017-03-01_13-50-51_5101"/>
<variableBean name="ewf_workflow_id" type="STRING" value="00_01_Hello_World.ewf"/>
<variableBean name="ewf_private_folder" type="STRING" value="C:\Products\Ataccama-all-11.0.0.ga-2017-02-10-win-x86_64_2\workspace\Workflow Tutorials\00_Introduction\wfinst_2017-03-01_13-50-51_5101"/>
<variableBean name="ewf_user_name" type="STRING" value=""/>
</wfVariables>
<workflowId>00_01_Hello_World.ewf</workflowId>
</WorkflowInstanceState>
Database persistence
When used in the server context (with Workflow Component), the workflow state information can be stored in a database across several tables.
In this case, a .wis
file is not created.
To enable database persistence, set State Storage Provider to Database State Storage Provider.
The workflow state persister registers several tables with the wisp
prefix (Workflow Instance State Persister), the following being the most useful ones:
-
wisp_wf_instance
- Contains information about workflow instances. Every workflow execution inserts a row with a unique ID. Other tables use it as a foreign key in the INST_ID column. -
wisp_wf_tasks
- Contains states of the individual workflow tasks. -
wisp_wf_linkeval
- Contains states of links between tasks. For more information aboutwisp
tables, see Workflow and Scheduler Database Persistence Tables.
WFINST folder
A wfinst
folder contains subfolders with logs of individual tasks and temporary scripts.
Each workflow task creates one task.log
file.
Tasks that initiate other processes (Run DQC Process, Run Shell Script, Run Windows Command) log into two files: stdout.log`and `stderr.log
.
Every workflow execution generates a new wfinst
folder.
In the batch mode, there is no limit on the number of stored In the server mode, set the |
The name and location of the wfinst
folders depend on the configuration and execution context.
The following table summarizes the differences.
Execution context | Location | Unique folder per run | ||
---|---|---|---|---|
IDE |
The same folder as the workflow. |
Yes, in the datetime form, for example, |
||
Batch script |
* Resources folder specified in Runtime Configuration.
* Fallback: The same folder as the script that started the workflow, for example, |
Yes, in the datetime form, for example, |
||
Server |
* Resources folder specified in Workflow Component. * Fallback 1: Resources folder specified in Runtime Configuration. * Fallback 2: The folder containing Server Configuration. |
Yes, serialized with unique ID assigned by the server, for example,
|
For detailed information about the workflow execution options, see Execute Workflows.
Workflow logging as part of unified server logging
ONE lets you log the behavior of workflows executed in ONE Runtime Server into a single log, together with the other server components. Configuring workflow logging in the server context does not affect the workflow instance state and WFINST outputs described above.
What is logged?
Generally speaking, workflows log two types of activities:
-
Technical: Synchronization of the source directories that contain workflows and past execution logs. These are logged on the
DEBUG
level and can be logged to a separate text file for debugging purposes. -
Execution: Starting and finishing of workflows and tasks and execution details. These are logged on the
INFO
level.
The level of detail can be configured in the Workflow Component. For details, see Comparison of log levels.
Prepare custom logging configuration
Update logging configuration
This step is optional. |
Review your Logging Configuration and add new logging rules and appenders if necessary.
For example, it makes sense to limit the severity level of logs written to the console output to INFO
to capture the actual execution logs.
The following excerpt shows a possible configuration to achieve that: logs of the severity level INFO
and higher coming from the Workflow Server Component are written to the standard output (console).
<?xml version='1.0' encoding='UTF-8'?>
<loggingConfig>
<appenders>
...
<iLogAppenderFactory logMillis="false" name="console" class="com.ataccama.dqc.commons.logging.factories.StdOutLogAppenderFactory" useStdErr="false"/>
...
</appenders>
<loggingRules>
...
<loggingRule level="INFO" appender="console">
<trace>
<string>WorkflowServerComponent</string>
</trace>
</loggingRule>
...
</loggingRules>
</loggingConfig>
Set the log level
The log level setting influences how much detail is logged. Set it in the Workflow Component.
Comparison of log levels
This section provides examples of log records created after the execution of a sample workflow consisting of one Run DQC task that starts a plan with a Record Counter step.
Log records of severity level INFO
and higher are logged.
Note the effect of the Log Level setting on the resulting log.
Log Level 2 logs the starting and finishing of workflows and state changes of workflow tasks.
09.03.2017 12:17:13 [INFO] [WorkflowServerComponent][default:workflow.ewf_49] Workflow task Run DQC changed state: IN_QUEUE
09.03.2017 12:17:13 [INFO] [WorkflowServerComponent][default:workflow.ewf_49] Workflow started executing.
09.03.2017 12:17:13 [INFO] [WorkflowServerComponent][default:workflow.ewf_49] Workflow task Run DQC changed state: RUNNING
09.03.2017 12:17:13 [INFO] [WorkflowServerComponent][default:workflow.ewf_49] Workflow task Run DQC changed state: FINISHED_OK
09.03.2017 12:17:13 [INFO] [WorkflowServerComponent][default:workflow.ewf_49] Workflow finished with state FINISHED_OK.
Log Level 3 logs activities of workflow tasks. This is the maximum log level for most workflows.
09.03.2017 12:15:49 [INFO] [WorkflowServerComponent][default:workflow.ewf_48] Workflow task Run DQC changed state: IN_QUEUE
09.03.2017 12:15:49 [INFO] [WorkflowServerComponent][default:workflow.ewf_48] Workflow started executing.
09.03.2017 12:15:49 [INFO] [WorkflowServerComponent][default:workflow.ewf_48] Workflow task Run DQC changed state: RUNNING
09.03.2017 12:15:49 [INFO] [WorkflowServerComponent][default:workflow.ewf_48][Run DQC] Validating model...
09.03.2017 12:15:49 [INFO] [WorkflowServerComponent][default:workflow.ewf_48][Run DQC] Creating runtime...
09.03.2017 12:15:49 [INFO] [WorkflowServerComponent][default:workflow.ewf_48][Run DQC] Running runtime...
09.03.2017 12:15:49 [INFO] [WorkflowServerComponent][default:workflow.ewf_48][Run DQC] Finished! (Time spent: 0 s)
09.03.2017 12:15:49 [INFO] [WorkflowServerComponent][default:workflow.ewf_48] Workflow task Run DQC changed state: FINISHED_OK
09.03.2017 12:15:49 [INFO] [WorkflowServerComponent][default:workflow.ewf_48] Workflow finished with state FINISHED_OK.
Log Level 4 logs activities of other tasks started by workflows. In this example, it logs activities of the Record Counter step.
Log Level -1 logs everything. In this example, it generates the same log as Level 4 (which is the maximum level at which this workflow logs).
09.03.2017 12:13:02 [INFO] [WorkflowServerComponent][default:workflow.ewf_47] Workflow task Run DQC changed state: IN_QUEUE
09.03.2017 12:13:02 [INFO] [WorkflowServerComponent][default:workflow.ewf_47] Workflow started executing.
09.03.2017 12:13:02 [INFO] [WorkflowServerComponent][default:workflow.ewf_47] Workflow task Run DQC changed state: RUNNING
09.03.2017 12:13:02 [INFO] [WorkflowServerComponent][default:workflow.ewf_47][Run DQC] Validating model...
09.03.2017 12:13:02 [INFO] [WorkflowServerComponent][default:workflow.ewf_47][Run DQC] Creating runtime...
09.03.2017 12:13:02 [INFO] [WorkflowServerComponent][default:workflow.ewf_47][Run DQC] Running runtime...
09.03.2017 12:13:02 [INFO] [WorkflowServerComponent][default:workflow.ewf_47][Run DQC][Record Counter] Processing started.
09.03.2017 12:13:02 [INFO] [WorkflowServerComponent][default:workflow.ewf_47][Run DQC][Record Counter] 10 recs 10000 recs/s
09.03.2017 12:13:02 [INFO] [WorkflowServerComponent][default:workflow.ewf_47][Run DQC][Record Counter] 20 recs 10000 recs/s
09.03.2017 12:13:02 [INFO] [WorkflowServerComponent][default:workflow.ewf_47][Run DQC][Record Counter] 30 recs N/A
09.03.2017 12:13:02 [INFO] [WorkflowServerComponent][default:workflow.ewf_47][Run DQC][Record Counter] 40 recs N/A
09.03.2017 12:13:02 [INFO] [WorkflowServerComponent][default:workflow.ewf_47][Run DQC][Record Counter] 50 recs N/A
09.03.2017 12:13:02 [INFO] [WorkflowServerComponent][default:workflow.ewf_47][Run DQC][Record Counter] 60 recs N/A
09.03.2017 12:13:02 [INFO] [WorkflowServerComponent][default:workflow.ewf_47][Run DQC][Record Counter] 70 recs N/A
09.03.2017 12:13:02 [INFO] [WorkflowServerComponent][default:workflow.ewf_47][Run DQC][Record Counter] 80 recs N/A
09.03.2017 12:13:02 [INFO] [WorkflowServerComponent][default:workflow.ewf_47][Run DQC][Record Counter] 90 recs N/A
09.03.2017 12:13:02 [INFO] [WorkflowServerComponent][default:workflow.ewf_47][Run DQC][Record Counter] 100 recs 10000 recs/s
09.03.2017 12:13:02 [INFO] [WorkflowServerComponent][default:workflow.ewf_47][Run DQC][Record Counter] Processing finished. 20000 recs/s
09.03.2017 12:13:02 [INFO] [WorkflowServerComponent][default:workflow.ewf_47][Run DQC] Finished! (Time spent: 0 s)
09.03.2017 12:13:02 [INFO] [WorkflowServerComponent][default:workflow.ewf_47] Workflow task Run DQC changed state: FINISHED_OK
09.03.2017 12:13:02 [INFO] [WorkflowServerComponent][default:workflow.ewf_47] Workflow finished with state FINISHED_OK.
Was this page useful?