Metrics policy backed service

[Philippe Brand]

We want to offload metrics handling to Splunk.

For this, we defined a Policy of type 'Policy-Backed Service', as documented in Configure Gateway for External Metrics.
We then have access to the 'metrics' message. Fine.
We can then route a message to Splunk. Also Fine.

Now what if we want to send more information, such as response status, request source IP or else ?
Trying to access 'request.http.status' doesn't work.
Then we assumed maybe this policy could work as other global policies.
We then exported a variable from a 'message-completed' policy (private.response.status) but we can't access it from this metrics processing policy using ${request.shared.private.response.status}

Is there a way to access something else than 'metrics' message in this policy?

Or is the only way something like what is describe here on this doc and then, use a 'message-completed' global policy fragment to enrich metrics sent ?

[Philippe Brand]

Responding to myself :)

Using now message-received + messages-completed + scheduled task to send accumulate data over time to Splunk.

[Philippe Brand]

Another bunch of questions:

Our first version was using ${metrics} message and thus was using Policy Backed Service Operation.
Our new version is using global policies.

Frontend times are different.

1st: as reported by global ${metrics}
"totalFrontendLatency":26
"totalBackendLatency":1

2nd: computed latencies in "completed-message" Global Policy
"elapsedTime":"5"   = ${request.shared.sanofi.metrics.start.time} - ${gateway.time.millis}
"totalBackendLatency":"1"

${request.shared.sanofi.metrics.start.time} is set in message-received = ${gateway.time.millis}
It is as if we lack communication time from/to originating client.
What is strange is that:
${request.shared.sanofi.metrics.start.time}= 1587644659350
${request.time.millis} = 1587644659349
so basically equals.


From doc:

- message-received: A policy of this type will run when a message is received, but before the service is resolved.

- message-completed: A policy of this type will run when processing for a message completes. It will run even if the service policy fails, an exception occurs, the service could not be resolved, or any other condition that prevents the service policy from being completed.

Thus I understand:
 - when I'm in "message-received", actual message content has not yet been read
- when I'm in "message-completed", message is "completed" thus response has been sent back to client.

So why do I get such a difference 5 versus 26 millis ? Where did my 21 milliseconds go ?
Or... who's right on this ? ${metrics} or our own computation ?

Note that for a given service, if the actual "Route to HTTPS" is contained in an distinct encap, totalBackendLatency is = 0. Don't know if it's a "feature" or a "bug".
  my_service
      do_the_routing   (encap)
         Route To HTTPS        <--- won't be tracked by global ${metrics}

For our 2nd method, we add a request.shared.whatever.routingLatency=${httpRouting.latency} in order to keep value when in completed-message global policy.

[Barry Stern]

Hello Philippe

There are a a few things I wanted to point out that may help explain this:

- using global policies will add a small amount of latency 
-message completed  processing occurs before sending response to client so the processing in this fragment will add latency to your request frontend.
- you don't need to use message-received policy to capture request start time and set as a shared variable  that is available at message-completed as ${request.time.millis}
-for routing statistics from encapsulated assertion ensure you have checked the  "Update routing statistics in parent policy" box

hope this helps explain your findings
Barry

[Philippe Brand]

Hi Barry,

You nearly saved the day :)

-for routing statistics from encapsulated assertion ensure you have checked the  "Update routing statistics in parent policy" box

Yes!! Shame on me I didn't see this option :)

- you don't need to use message-received policy to capture request start time and set as a shared variable  that is available at message-completed as ${request.time.millis}

Correct. We now even use "${request.elapsedTime}", which saves us from computing $now-$then.

- using global policies will add a small amount of latency

In fact problem was on my side. Fixed the latency differences.
I now get for the 2 methods:

New one:

2020-04-23T19:13:14.492+0200 INFO 6582 com.l7tech.server.policy.assertion.ServerAuditDetailAssertion: -4: Metrics: {"time":1587661994,"sourcetype":"_json","index":"gateway_metrics","event":{"dc":"EMEA","env":"ref","loc":"lan","time":"1587661994440","formattedTime":"2020-04-23T19:13:14.440+02:00","nodeId":"111eb41796514904bb6f4babee150006","nodeName":"apiref-eu-int","nodeIp":"168.124.44.206","serviceId":"e325178b4619c90fb22f99a4af2e65b3","serviceName":"Test-routing-to-external-HELLO","serviceUri":"/helloext","remoteIp":"7.28.74.97","httpMethod":"GET","routingCode":"200","responseStatus":"200","psecFailCode":"","requestSize":"0","responseSize":"560","elapsedTime":"52","totalBackendLatency":"26","isPolicySuccessful":true,"isPolicyAuthorized":true,"isPolicyViolation":false,"isRoutingFailure":false}}

Policy Backed Metrics:

2020-04-23T19:13:14.495+0200 INFO 125698 com.l7tech.server.policy.assertion.ServerAuditDetailAssertion: -4: Metrics int: {"time":1587661994,"sourcetype":"_json","index":"gateway_metrics","event":{"dc":"EMEA","env":"ref","loc":"lan","time":1587661994440,"formattedTime":"2020-04-23T19:13:14.440+02:00","nodeId":"111eb41796514904bb6f4babee150006","nodeName":"apiref-eu-int","nodeIp":"168.124.44.206","serviceId":"e325178b4619c90fb22f99a4af2e65b3","serviceName":"Test-routing-to-external-HELLO","serviceUri":"/helloext","totalFrontendLatency":53,"totalBackendLatency":28,"isPolicySuccessful":true,"isPolicyViolation":false,"isRoutingFailure":false}}

This does the trick.

-message completed  processing occurs before sending response to client so the processing in this fragment will add latency to your request frontend.

Is there a way to get actual time it took for the request to *read* from client
And after processing, if not possible on "message-completed", how to get time it took to *send* response back to client.

Overall what we need is *total* time for the request:
- time to read payload from client
- time to process (we have: elapsedTime-totalBackendLatency)
- time to send and receive response from backend (we have: totalBackendLatency)
- time to send back response to client

Many thanks for your help.

And last one:
Whenever we send data to Splunk (task sched every one minute), Route to HTTPS adds in log:

2020-04-24T00:28:00.027+0200 WARNING 217 com.l7tech.common.http.prov.apache.IdentityBindingHttpConnectionManager: Attempt to bind with no id set

Any idea ?

[Philippe Brand]

Hi,

re-uping my previous questions regarding timings:

-message completed  processing occurs before sending response to client so the processing in this fragment will add latency to your request frontend.

Is there a way to get actual time it took for the request to *read* from client
And after processing, if not possible on "message-completed", how to get time it took to *send* response back to client.

Overall what we need is *total* time for the request:
- time to read payload from client
- time to process (we have: elapsedTime-totalBackendLatency)
- time to send and receive response from backend (we have: totalBackendLatency)
- time to send back response to client

[Barry Stern]

Hello Philippe,

Recording ${request.elapsedTime} in your message completed policy will be the total time the request took in the gateway to process. If  performing any kind of performance testing the difference between this time and the time recorded by the client would be the in network latency that is outside the gateway. 

Hope this answers your inquiry. 

[Akshat Aranya]

Hi Barry & Philippe,

This thread is very useful, I will like to understand how are we able to get metrics data to message-completed policy or custom logging data to backend metric data.

I think i am missing something, please help.

Regards
Akshat