Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Use context aware logger for workflow service #5240

Merged
merged 1 commit into from Sep 21, 2023

Conversation

lkiesow
Copy link
Member

@lkiesow lkiesow commented Sep 5, 2023

The workflow service is using a special logger that supports units of work so that you can identify several logger statements belonging to a specific task.

However, with the new implementation, there is but one unit of work definition left, and it contains just a single logging statement. Nothing you actually still need this for.

logger.startUnitOfWork();
logger.warn(failureToFail, "Unable to update workflow to failed state");
logger.endUnitOfWork();

The downside to using this special logger is that you loose context information. With the normal logger you get information about the location where this has been logged. With the special logger this information is lost. That is really annoying when debugging based on logs:

2023-09-05 18:14:57,449 | INFO  | (ServiceRegistryJpaImpl:622) - Jobs with IDs '[8579450]' deleted
2023-09-05 18:14:57,450 | WARN  | (Log:213) - [>2ef22a08] No events for workflow instance 8579450 found in the Elasticsearch index.
2023-09-05 18:14:57,496 | DEBUG | (Log:213) - [>2ef22a08] Deleting workflow instance 8579614
2023-09-05 18:14:57,548 | INFO  | (Log:213) - [>2ef22a08] Removing temporary files for workflow 8579614
2023-09-05 18:14:57,548 | DEBUG | (Log:213) - [>2ef22a08] Removing temporary file https://oc-admin.virtuos.uni-osnabrueck.de/files/mediapackage/6a092362-56c4-46a9-b82d-f389d97ca19c/security-policy-series/xacml.xml for workflow Workflow {8579614}

Given that it is doing more harm than good, this patch switches the workflow service to the default logger. With this you also now get proper context information about logs:

2023-09-05 18:43:34,069 | INFO  | (ServiceRegistryJpaImpl:622) - Jobs with IDs '[9256488]' deleted
2023-09-05 18:43:34,073 | WARN  | (WorkflowServiceImpl:2260) - No events for workflow instance 9256488 found in the Elasticsearch index.
2023-09-05 18:43:34,082 | DEBUG | (WorkflowServiceImpl:2127) - Deleting workflow instance 9256489
2023-09-05 18:43:34,107 | INFO  | (WorkflowServiceImpl:881) - Removing temporary files for workflow 9256489

Your pull request should…

The workflow service is using a special logger that supports units of
work so that you can identify several logger statements belonging to a
specific task.

However, with the new implementation, there is but one unit of work
definition left, and it contains just a single logging statement.
Nothing you actually still need this for.

```
logger.startUnitOfWork();
logger.warn(failureToFail, "Unable to update workflow to failed state");
logger.endUnitOfWork();
```

The downside to using this special logger is that you loose context
information. With the normal logger you get information about the
location where this has been logged. With the special logger this
information is lost. That is really annoying when debugging based on
logs:

```
2023-09-05 18:14:57,449 | INFO  | (ServiceRegistryJpaImpl:622) - Jobs with IDs '[8579450]' deleted
2023-09-05 18:14:57,450 | WARN  | (Log:213) - [>2ef22a08] No events for workflow instance 8579450 found in the Elasticsearch index.
2023-09-05 18:14:57,496 | DEBUG | (Log:213) - [>2ef22a08] Deleting workflow instance 8579614
2023-09-05 18:14:57,548 | INFO  | (Log:213) - [>2ef22a08] Removing temporary files for workflow 8579614
2023-09-05 18:14:57,548 | DEBUG | (Log:213) - [>2ef22a08] Removing temporary file https://oc-admin.virtuos.uni-osnabrueck.de/files/mediapackage/6a092362-56c4-46a9-b82d-f389d97ca19c/security-policy-series/xacml.xml for workflow Workflow {8579614}
```

Given that it is doing more harm than good, this patch switches the
workflow service to the default logger. With this you also now get
proper context information about logs:

```
2023-09-05 18:43:34,069 | INFO  | (ServiceRegistryJpaImpl:622) - Jobs with IDs '[9256488]' deleted
2023-09-05 18:43:34,073 | WARN  | (WorkflowServiceImpl:2260) - No events for workflow instance 9256488 found in the Elasticsearch index.
2023-09-05 18:43:34,082 | DEBUG | (WorkflowServiceImpl:2127) - Deleting workflow instance 9256489
2023-09-05 18:43:34,107 | INFO  | (WorkflowServiceImpl:881) - Removing temporary files for workflow 9256489
```
Copy link
Member

@Arnei Arnei left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

More context information is good, approved.

If me IDE isn't lying to me, this PR removes the last file where the startUnitOfWork() and endUnitOfWork() methods were actually used. Does this mean we can get rid of the special logger since its special logging capabilities are no longer required, or is there a reason to keep it around? Not that this PR should do the removing, but it would be worth an issue/follow-up PR.

@lkiesow
Copy link
Member Author

lkiesow commented Sep 12, 2023

I think we can and should remove it.
But that's another PR.
I'll create an issue for Hacktoberfest for that :D

@@ -69,7 +69,6 @@
import org.opencastproject.serviceregistry.api.ServiceRegistry;
import org.opencastproject.serviceregistry.api.ServiceRegistryException;
import org.opencastproject.serviceregistry.api.UndispatchableJobException;
import org.opencastproject.util.Log;
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I haven't checked: Is this used anywhere else? Can this whole class be removed?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It's still used, so you can't "just" remove it. Shouldn't be too hard though. But as Lars said, that's another PR.

@gregorydlogan gregorydlogan merged commit 56be4e9 into opencast:r/14.x Sep 21, 2023
4 checks passed
@gregorydlogan gregorydlogan self-assigned this Sep 21, 2023
@lkiesow
Copy link
Member Author

lkiesow commented Sep 22, 2023

Filed #5261 about the removal of the logger

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

4 participants