Debugging workflows

Flower collects a lot of information during the process execution. In most of the cases even without any custom line of logging code Flower provides enough information to localize an error (that is one of the advantages of using Flower).

By default, the processor is configured to log only informational messages, warnings and errors, so if everything goes well, you will get no logs at all. To get a full trace of a process, you need to set 'Trace' logging level in the logging configuration of the processor. Also, to get process dumps, make sure logging to the directory is enabled. So, your Flower.Processor.logging.config should look like this:

<objects xmlns="http://www.springframework.net">
  
  <object id="flowerClient" type="Flower.Client.FlowerClient, Flower.Client">
    <constructor-arg>
      <object type="Flower.Client.DirectoryClient, Flower.Client">
        <constructor-arg name="endpointConfigurationName" value="Directory" />
      </object>
    </constructor-arg>
  </object>

  <object id="logManager" type="Flower.Logging.LogManager">
    <constructor-arg>
      <object type="Flower.Logging.LogManagerSettings">
        <property name="LoggingLevel" value="Trace" />
        <property name="Sinks">
          <list element-type="Flower.Logging.ILogSink">
            <object type="Flower.Logging.NLog.LogSink, Flower.Logging.NLog" />
            <object type="Flower.Logging.Directory.LogSink, Flower.Logging.Directory">
              <constructor-arg name="flowerClient" ref="flowerClient" />
              <constructor-arg name="maxBatchSize" value="10" />
            </object>
          </list>
        </property>
      </object>
    </constructor-arg>
  </object>
  
</objects>


Notice the value of the 'LoggingLevel' and the 'Sinks' list of the log manager settings.

Process dumps

The simplest way to obtain a process debug information is to call dump() function in the management console:

dump('#1234567');


The function accepts a pid as an argument. By default, the function will create a file system directory named as the pid and will write the dump into it, but you can specify an alternative directory name as the second argument of the function.

dump('#1234567', 'Dump');


In the dump you will find the 'Log.txt' file containing the log of the process and the 'States' directory containing process states. Each state is saved in a separate human-readable XML file. The name of each file is a global state id prefixed with the state index, so if you sort the files by name, you will get them in the order they were created.

Getting logs from a processor host

Logs of each process go to a logging target named 'Process<pid>'. This convention allows to segregate logs of different processes. By default, the NLog sink is configured to write process logs to separate files in 'Processes' directory of the logging destination.

<nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd"
      xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance">

  <targets>
    <target name="logfile"
            xsi:type="File"
            fileName="..."
            layout="..." />
    <target name="processLog"
            xsi:type="File"
            fileName="..."
            layout="..." />
  </targets>

  <rules>
    <logger name="Process#*" minlevel="Trace" writeTo="processLog" />
    <logger name="*" minlevel="Trace" writeTo="logfile">
      <filters>
        <when condition="starts-with('${logger}', 'Process#')" action="Ignore"/>
      </filters>
    </logger>
  </rules>
</nlog>

Analyzing process logs

Process log normally looks like this:

TRACE 8/12/2013 12:55:14 PM: Executing activity If[1](ConditionalJump) on processor 35252761.
TRACE 8/12/2013 12:55:14 PM: Executing activity For[1](Execute) on processor 35252761.
TRACE 8/12/2013 12:55:14 PM: Executing activity For[1](ConditionalJump) on processor 35252761.
TRACE 8/12/2013 12:55:14 PM: Executing activity StartProcess[1](StartProcess`2) on processor 35252761.
TRACE 8/12/2013 12:55:14 PM: Transaction 2d190394-087f-47d4-beaa-f35cfbeb13df:1 started.
TRACE 8/12/2013 12:55:14 PM: State 2a10c607-682c-475a-8997-619c36cd20ab saved.
TRACE 8/12/2013 12:55:14 PM: Transaction 2d190394-087f-47d4-beaa-f35cfbeb13df:1 completed.
TRACE 8/12/2013 12:55:14 PM: Executing activity End[1](End) on processor 35252761.
TRACE 8/12/2013 12:55:14 PM: Executing activity End[1](Execute) on processor 35252761.
TRACE 8/12/2013 12:55:14 PM: Executing activity End[1](Jump) on processor 35252761.
TRACE 8/12/2013 12:55:14 PM: Executing activity For[1](ConditionalJump) on processor 35252761.
TRACE 8/12/2013 12:55:14 PM: Executing activity StartProcess[1](StartProcess`2) on processor 35252761.
TRACE 8/12/2013 12:55:14 PM: Transaction 2d190394-087f-47d4-beaa-f35cfbeb13df:3 started.
TRACE 8/12/2013 12:55:14 PM: State 6d8a3795-4e41-43dc-97ae-f8d48d9a4fa8 saved.
TRACE 8/12/2013 12:55:14 PM: Transaction 2d190394-087f-47d4-beaa-f35cfbeb13df:3 completed.
TRACE 8/12/2013 12:55:14 PM: Executing activity End[1](End) on processor 35252761.
TRACE 8/12/2013 12:55:14 PM: Executing activity End[1](Execute) on processor 35252761.
TRACE 8/12/2013 12:55:14 PM: Executing activity End[1](Jump) on processor 35252761.
TRACE 8/12/2013 12:55:14 PM: Executing activity For[1](ConditionalJump) on processor 35252761.


Each entry starts with a severity mark and timestamp, then goes the message. Each activity generates the following pattern of messages:
  1. Executing activity <statement>[<index>](<activity>) on processor <processor context id>.
  2. Transaction <transaction id> started.
  3. Custom messages or/and exception.
  4. State <state id>.
  5. Transaction <transaction id> completed.

In the "executing-activity" line an activity is identified by a statement which it is emitted by and the activity type. Each statement has an index which is the index of the statement of a particular type (so, if you see 'For2', this means: the second For in the process, not the second statement).

The processor context id is a hash-code of a loaded instance of a process. If it changes, this means that the process was unloaded between the activities. Analyzing the processor context changes may help to localize serialization errors when some part of a state get lost when a process is unloaded.

If you're using a state service, not all states that appear in the logs are propagated to the directory hence not all of them will be available in the process dumps. However, the last states before an exception are always propagated. If you need all states to be in the dumps for the debugging, comment out the state service definition in Flower.Processor.config. This will force the processor to save all states to the directory.

Writing custom messages to a process log

To write custom log messages from the activities, use the Log property of the context passed to the statements' lambdas.

Last edited Oct 26, 2013 at 11:28 AM by dbratus, version 2

Comments

No comments yet.