Enhance Logging for Workflow

[RyanLettieri]

In what area(s)?

/area runtime

/area operator

/area placement

/area docs

/area test-and-release

Describe the feature

Currently, it is rather difficult to diagnose an issue that occurs when a user is using dapr workflow, and due to dapr workflow being a new feature, issues occur more frequently than hoped. By adding in additional logging, diagnosing the issue will be a much easier process. I am proposing the following logs to be added to the runtime:

1. Creation of a Workflow
   c.logger.Infof("Created workflow %s with instanceID '%s'", <workflowName>, <instanceID>)

• Include the Instance ID for the workflow
• Include the name of the workflow

2. Scheduling of an Activity
   c.logger.Infof("Scheduling activity '%s' for workflow %s with instanceID %s", <activityName>, <workflowName>, <instanceID>)

• Include the name of the activity
• Include the name of the workflow
• Include the instanceID for the workflow

3. Execution of an Activity
   c.logger.Infof("Executing activity '%s' for workflow %s with instanceID %s", <activityName>, <workflowName>, <instanceID>)

• Include the name of the activity
• Include the name of the workflow
• Include the instanceID for the workflow

4. Completion of an Activity
   c.logger.Infof("Activity '%s' completed with status: '%s' for workflow %s with instanceID %s", <activityName>, <activityStatus>, <workflowName>, <instanceID>)

• Include the name of the activity
• Include the name of the workflow
• Include the instanceID for the workflow
• Include the status of the activity (pass/fail)

5. Completion of a Workflow
   c.logger.Infof("Workflow %s with instanceID %s completed with status: '%s'", <workflowName>, <instanceID>, <workflowStatus>)

• Include the Instance ID for the workflow
• Include the name of the workflow
• Include the status of the workflow (pass/fail)

In addition to the proposed logs for the runtime, I am also proposing that we add logs to the various SDKs which will provide information that the runtime does not have access to. These logs are as follows:

1. Registration of a Workflow
   log("Workflow <workflowName> has been successfully registered")

• Include the name of the workflow

2. Registration of an Activity
   log("Activity <activityName> has been successfully registered to workflow <workflowName>")

• Include the name of the activity
• Include the parent workflow of the activity

Additional Thoughts

1. Timestamps could also be added to the beginning of the various log statements to help create a timeline for the workflow execution. One downside would be that the logs may get too cluttered.
2. The current proposal is to have the log statements as a level of "info". Again, to avoid cluttering the output, the log level could (and quite possibly should) be toned down to "debug"
3. If/when more logs are added to the various SDKs, we should first determine if they can be added to the runtime, and if so, add them there. If not, we must ensure that the logs across all SKDKs are of a consistent format.

Release Note

RELEASE NOTE:

[ItalyPaleAle]

👍

1. Timestamps are already included in all logs by default, so we're good there
2. How about we add an option in the Configuration CRD to determine the log level for workflow? We already have a section for logging in there. This way we can determine if the wf logs are debug or info

[philliphoff]

Tiny nit: consider being consistent in use of quotes around names/IDs.

[cgillum]

Have we considered whether some of this information could be added to the log schema? For example, instead of making the workflow ID part of the log message, could it just be a first-class property on the log record itself (i.e., structured logging)?

[olitomlinson]

Can I make a super minor suggestion that you tweak the message format for 4 and 5 (and the registration messages) so that they follow the same pattern as 1, 2 3.

i.e. Activity '%s' completed with status: '%s' for workflow %s with instanceID %s"
becomes
Activity completed...

Workflow %s with instanceID %s completed with status: '%s'", <workflowName>, <instanceID>, <workflowStatus>
becomes
Workflow completed...

This format helps when doing searches across logs as I can easily search for the phrase Workflow completed rather than searching for workflow and then filtering that list of results further by searching for completed (which still may give too many unwanted matches)

[rabollin]

For logging the Completion of a Workflow details, if the status is Fail, consider adding the source of the error(DTF/ Workflow Client/ DAPR Client) in the message. Also the errors should not log confidential details like Apps hostname/ IP Address/ subscription ID ..etc.

[lilyjma]

Something that came up in interviews with DF customers is that being able to see the input and output of activity functions would be helpful. Not sure if this is something to be exposed on the logging side, but exposing this info would be useful for debugging.

[famarting]

This two comments:

• Enhance Logging for Workflow #7065 (comment)
• Enhance Logging for Workflow #7065 (comment)

are really valid points and have not been addressed on the PR #7222 . Taking the most out of structured logging is crucial IMO to make the workflow logging useful for debugging, once structured logging is put in place it can more easily enable log processing and allows for more easily querying for the inputs and outputs of activities

I can create a PR if you are happy with it

[cgillum]

@famarting I'm supportive of this, and would be happy to provide feedback and/or guidance.

[shivamkm07]

This two comments:

• Enhance Logging for Workflow #7065 (comment)
• Enhance Logging for Workflow #7065 (comment)

are really valid points and have not been addressed on the PR #7222 . Taking the most out of structured logging is crucial IMO to make the workflow logging useful for debugging, once structured logging is put in place it can more easily enable log processing and allows for more easily querying for the inputs and outputs of activities

I can create a PR if you are happy with it

@famarting @cgillum As per comment #7065 (comment), I was adding Workflow ID as part of the logger field, similar to other fields like time, level etc. But that would require a separate logger Object for every workflow instance, unlike currently where there is a single global wfLogger object. Also for consistency across logs, I added the prefix Workflow Actor: <WorkflowID> as part of Message which would help querying all logs from a specific workflow instance. Is there any advantage of adding this as part of logger field? Or do we have other fields as well that we want to add other than WorkflowID? (The current format does require all workflow instance logs to follow the specific format, but helps us in having a single object).

For querying activity inputs/outputs, do we want to add these as well in logs? Won't these be user information and can potentially be quite large in size?

For the other comment, yeah it makes sense to add Workflow Completed and Activity completed as prefix which would help in searching logs. Creating a quick PR to add this.