Sadly it is not a simple question. I'll try and explain it here and hope I don't muddy the waters too much...
First I need to explain one of the key differences between "log" and "audit" with regard to service/message processing. Message processing triggers log events that are tagged as "Audit" or "Log" category. This is reflected in the "Add Audit Details" assertion's option to send the detail to Audit or Log. When a log event is tagged as "Log" then it will go directly to the log system via the log sink. When it is tagged as "Audit" then the event is buffered until the policy is completed. At policy completion, the value of ${auditLevel}, which starts as INFO but may be bumped to WARNING, is compared with the value of the audit.messageThreshold cluster wide property and, if it matches or exceeds the property (Default=WARNING) then an audit is triggered. When that happens all of the logs that were tagged as Audit are sent to the log sink and an audit entry is added to the database (by default) with all of the associated logs. Thus you should see all Log and Audit events in the main log (ssg_0_0.log) because the log sink is, by default, configured to filter both Gateway Log and Audit categories.
I'll use the following policy to illustrate what I just described. It triggers an audit event using the Audit Messages in Policy assertion to set ${AuditLevel} to WARNING then sends a log event to the Audit category followed by one sent to the Log category before returning a text/plain response:
<?xml version="1.0" encoding="UTF-8"?>
<wsp:Policy xmlns:L7p="http://www.layer7tech.com/ws/policy" xmlns:wsp="http://schemas.xmlsoap.org/ws/2002/12/policy">
<wsp:All wsp:Usage="Required">
<L7p:CommentAssertion>
<L7p:Comment stringValue="* Illustrate log correlation"/>
</L7p:CommentAssertion>
<L7p:AuditAssertion/>
<L7p:AuditDetailAssertion>
<L7p:Detail stringValue="This is an audit tagged log event"/>
</L7p:AuditDetailAssertion>
<L7p:AuditDetailAssertion>
<L7p:Detail stringValue="This is a log tagged log event"/>
<L7p:LoggingOnly booleanValue="true"/>
</L7p:AuditDetailAssertion>
<L7p:HardcodedResponse>
<L7p:Base64ResponseBody stringValue="SGkh"/>
<L7p:ResponseContentType stringValue="text/plain; charset=UTF-8"/>
</L7p:HardcodedResponse>
</wsp:All>
</wsp:Policy>
When I hit this policy with curl I see the following in ssg_0_0.log:
2020-05-13T16:32:49.768-0700 INFO 644 com.l7tech.server.policy.assertion.ServerAuditDetailAssertion: -4: This is a log tagged log event
2020-05-13T16:32:49.775-0700 INFO 644 com.l7tech.server.message: Processing request for service: Test Service [/test]
2020-05-13T16:32:49.782-0700 INFO 644 com.l7tech.server.policy.assertion.ServerAuditDetailAssertion: -4: This is an audit tagged log event
2020-05-13T16:32:49.786-0700 WARNING 644 com.l7tech.server.message: Message processed successfully
Notice that "This is a log tagged log event" is the first entry, even though it followed the "This is an audit tagged log event" in the policy. That is because the Audit entry was buffered until the end of the policy execution. If I disable the Audit Messages in Policy assertion then all I will see in ssg_0_0.log is the "This is a log tagged log event" entry, since an Audit is not triggered.
Now, when an audit is triggered, all of the associated Audit tagged log events are subjected to the audit.log.service.detailFormat cluster wide property. *This* is where things get interesting. You can add ${requestid} to that cluster wide property and now every Audit tagged log will have the request ID added for correlation. Note that any logs that were sent *directly* to the log (i.e. not through the Audit system) will NOT have the request ID in them. I also add it to audit.log.service.headerFormat and audit.log.service.footerFormat which control the "Processing request for service..." and "Message processed successfully" entries:
audit.log.service.detailFormat = [${requestId}] {0}: {1}
audit.log.service.headerFormat = [${requestId}] Processing request for service: {3}
audit.log.service.footerFormat = [${requestId}] {1}
Now when I hit the service with curl I get the following in ssg_0_0.log:
2020-05-13T16:46:55.957-0700 INFO 863 com.l7tech.server.policy.assertion.ServerAuditDetailAssertion: -4: This is a log tagged log event
2020-05-13T16:46:55.976-0700 INFO 863 com.l7tech.server.message: [0000017210444d92-13] Processing request for service: Test Service [/test]
2020-05-13T16:46:55.978-0700 INFO 863 com.l7tech.server.policy.assertion.ServerAuditDetailAssertion: [0000017210444d92-13] -4: This is an audit tagged log event
2020-05-13T16:46:55.978-0700 WARNING 863 com.l7tech.server.message: [0000017210444d92-13] Message processed successfully
This now has the request ID on all of the Audit tagged log events, but does NOT have it on the Log tagged event.
This is a very effective way to get correlation in the logs, however it does require passing everything through the audit system which has a fair amount of overhead. Since we always recommend not auditing to the database in production, this can be a bit tricky and requires the use of the Audit Sink Policy to simply return true every time and to disable auditing to the database, which then means that system and admin audits will get lost unless the audit Sink Policy is set to fail when those types of audits are detected (which can get noisy in the logs). Also, if you require request ID in entries going directly to the log then the only way I know to do it is to add ${requestid} to the Add Audit Details assertions.
I hope this helps.
------------------------------
Jay MacDonald - Adoption Architect - Broadcom API Management (Layer 7)
------------------------------
Original Message:
Sent: 05-13-2020 04:58 PM
From: Alejandro Calbazana
Subject: Request ID for ssg log statements
Hello,
Maybe a simple question...
Is it possible to modify the SSG log pattern to add some type of correlation id to ALL log statements? I ask because I can see how you could add a the request ID context variable to custom policy log statements, but I'd like to be able to correlate surrounding log statements when policy executes.
Thanks,
Alejandro