Apigee X only saving "GET" verb logs in GCP Cloud Logging

[fcasteluber]

Hello all,

I´m trying to save apigee runtime information regarding the calls to my proxies. In order to do that,  I´m using service callout policy following the example from https://github.com/apigee/devrel/blob/main/references/cloud-logging-shared-flow/sharedflowbundle/pol... 

However, it only works if the http verb is GET. While debugging my proxy call using Apigee UI, I do not see any error in the policy, however when I open GCP console to check the logs in Cloud Logging, I don´t see any information regarding my POST call, only GET calls logging information is being created. As a reference, my cloud logging  filter is as per below:

severity=INFO

resource.type="api"

log_name="projects/abc/logs/apigee-runtime"

Could you please kindly advise?

[dchiesa1]

You're using JUST the service callout policy?  Or are you using the entire sharedflow from that repo?

And how do you have it attached?

Apigee proxies have this concept of "attachment point" for policies.  You can attach a policy so that it executes for every inbound request, or for every outbound response.  Or, for a subset of requests.  Or, only for cases in which the proxy encounters a fault.  There are numerous options. Read about this concept here.

One possible explanation for the fact that you see log records only for GET calls, is that you have your policy (or sharedflow) attached to a point that gets executed only for GET calls.  

[fcasteluber]

Hi Dino,

To give you more details, I've tested two simple mock proxies:

1) with no target endpoint. I could see log records for GET and POST calls.

2) with target endpoint. I've used httpbin.org/get and httpbin.org/post . Again, I could see log records only for GET calls.

Answering your questions, I'm using the sharedflow from the repo, where I have the shared policy deployed with a service account and from the proxy itself I have attached to the proxy pre-flow (request) a flow callout policy. I've also attached a flow callout policy in every part of the flows (proxy pre flow (request and response); proxy post flow (request and response); target end point pre flow (request and response); target endpoint post flow (request and response).

Another thing that I've tried: add a conditional flow with the verb POST in the proxy pre flow request, but again the same result and no log records for POST. Here is my shared flow:

<?xml version="1.0" encoding="UTF-8" standalone="yes"?>

<SharedFlow name="default">
<Step>
<Name>SC.CloudLogging</Name>
</Step>
</SharedFlow>

<?xml version="1.0" encoding="UTF-8" standalone="yes"?>
<ServiceCallout name="SC.CloudLogging">
<Request>
<IgnoreUnresolvedVariables>true</IgnoreUnresolvedVariables>
<Set>
<Payload contentType="application/json">{
"logName": "projects/{organization.name}/logs/apigee-runtime",
"resource" : {
"type": "api",
"labels": {}
},
"labels": {
"application": "apigee"
},
"entries": [{
"severity": "INFO",
"jsonPayload": {
"organization": "{organization.name}",
"environment": "{environment.name}",
"apiProxy": "{apiproxy.name}",
"apiProxyRevision": "{apiproxy.revision}",
"apiProduct": "{apiproduct.name}",
"developerApp": "{apiproduct.name}",
"clientId": "{client_id}",
"developerId": "{developer.id}",
"requestUri": "{request.uri}",
"requestUrl": "{request.url}",
"messageContent": "{message.content}",
"requestContent": "{request.content}",
"requestFormParam": "{request.formstring}",
"requestQueryString": "{request.querystring}",
"responseContent": "{response.content}",
"request": "{request}",
"verb": "{request.verb}",
"correlationId": "{messageid}",
"proxyRequestReceived": "{client.received.end.timestamp}",
"proxyResponseSent": "{client.sent.end.timestamp}",
"targetResponseReceived": "{target.received.end.timestamp}",
"targetRequestSent": "{target.sent.end.timestamp}",
"targetResponseCode": "{message.status.code}",
"proxyResponseCode": "{response.status.code}",
"clientReceived": "{client.received.start.timestamp}",
"clientSent": "{client.sent.start.timestamp}",
"faultName":"{fault.name}"
}
}],
"partialSuccess": true
}
</Payload>
<Verb>POST</Verb>
</Set>
</Request>
<HTTPTargetConnection>
<Authentication>
<GoogleAccessToken>
<Scopes>
<Scope>https://www.googleapis.com/auth/logging.write</Scope>
</Scopes>
<LifetimeInSeconds>3600</LifetimeInSeconds>
</GoogleAccessToken>
</Authentication>
<URL>https://logging.googleapis.com/v2/entries:write</URL>
</HTTPTargetConnection>
</ServiceCallout>

My proxy:

<?xml version="1.0" encoding="UTF-8" standalone="yes"?>
<ProxyEndpoint name="default">
<RouteRule name="Flow-1">
<Condition>(proxy.pathsuffix MatchesPath "/post") and (request.verb = "POST")</Condition>
<TargetEndpoint>TargetEndpoint-1</TargetEndpoint>
</RouteRule>
<PreFlow name="PreFlow">
<Request>
<Step>
<Name>FC.CloudLogging</Name>
</Step>
</Request>
<Response/>
</PreFlow>
<Flows>
<Flow name="Flow-1">
<Description/>
<Request>
<Step>
<Name>Flow-Callout-1</Name>
</Step>
</Request>
<Response/>
<Condition>(proxy.pathsuffix MatchesPath "/post") and (request.verb = "POST")</Condition>
</Flow>
</Flows>
<PostFlow name="PostFlow">
<Request/>
<Response/>
</PostFlow>
<HTTPProxyConnection>
<BasePath>/logging-example</BasePath>
</HTTPProxyConnection>
<RouteRule name="TargetEndpoint-1">
<TargetEndpoint>TargetEndpoint-1</TargetEndpoint>
</RouteRule>
</ProxyEndpoint>

and my target endpoint:

<?xml version="1.0" encoding="UTF-8" standalone="yes"?>
<TargetEndpoint name="TargetEndpoint-1">
<Description/>
<FaultRules/>
<PreFlow name="PreFlow">
<Request/>
<Response/>
</PreFlow>
<PostFlow name="PostFlow">
<Request/>
<Response/>
</PostFlow>
<Flows/>
<HTTPTargetConnection>
<Properties/>
<URL>https://httpbin.org/</URL>
</HTTPTargetConnection>
</TargetEndpoint> 

I'm probably committing a mistake somewhere, just couldn't figure out where.

Thank you in advance for your attention and help!

[dchiesa1]

Thanks for the additional detail. Even with that detail it's hard to know exactly what's going on. I Can make some comments though.

There is a Preflow which includes a Step in the Request. That appears to be a FlowCallout to the cloud logging sharedflow. I cannot be sure though! In any case, if THAT is what you have deployed, then that logging should occur for every request, whether GET, POST or otherwise. So I agree that it is a puzzle that your log does not show POST calls.

I see two things that look like flow callouts in your proxy. FC-CloudLogging, and Flow-Callout-1. Which one of those is referring to the sharedflow that does logging? what does the other flow callout do?

I might suggest replacing your proxyendpoint configuration with this:

<ProxyEndpoint name="default">
  <HTTPProxyConnection>
    <BasePath>/logging-example</BasePath>
  </HTTPProxyConnection>
  <PreFlow name="PreFlow">
    <Request>
      <Step>
          <!-- This Flow Callout will refer to a SharedFlow. Is it the CLoud
               logging sharedflow? (it cannot be known except by looking within
               the policy with the name FC.CloudLogging)-->
        <Name>FC.CloudLogging</Name>
      </Step>
    </Request>
    <Response/>
  </PreFlow>
  <Flows>
    <Flow name="Flow-1">
      <Description/>
      <Request>
        <Step>
          <!-- This Flow Callout will refer to a SharedFlow.  What does it do? -->
          <Name>Flow-Callout-1</Name>
        </Step>
      </Request>
      <Response/>
      <!-- FYI this Flow will get executed if and only if, the path is
           /logging-example/post and the verb is POST -->

      <Condition>(proxy.pathsuffix MatchesPath "/post") and (request.verb = "POST")</Condition>
    </Flow>
  </Flows>
  <PostFlow name="PostFlow">
    <Request/>
    <Response/>
  </PostFlow>
  
  <!-- it's a good idea to keep all RouteRule elements together -->
  <!--
    Though this one is unnecessary because the following one is a "catch all"
    (having no Condition) and they route to the same target. 

  <RouteRule name="Flow-1">
    <Condition>(proxy.pathsuffix MatchesPath "/post") and (request.verb = "POST")</Condition>
    <TargetEndpoint>TargetEndpoint-1</TargetEndpoint>
  </RouteRule>
  -->
  <RouteRule name="TargetEndpoint-1">
    <TargetEndpoint>TargetEndpoint-1</TargetEndpoint>
  </RouteRule>
</ProxyEndpoint>

I've used httpbin.org/get and httpbin.org/post . Again, I could see log records only for GET calls.

Is there a reason you are varying both the path and the verb? You are saying "only for GET calls", by which I assumed you meant that the verb was GET. But now I am not so sure. You have "get" and "post" in the path, which is confusing to me. Can you confirm that by "only for GET" you mean when the verb is GET? The path should not matter at all, according to this proxy.

ahhh, just checking now, I see a possible problem.  More in a bit... I have a meeting right now. 

I'm back. OK, here are the details. 

When I invoke the httpbin.org/post with a GET, with curl, I get a 405 "Method not allowed" error from httpbin.  It looks like this: 

$ curl -i httpbin.org/post
HTTP/1.1 405 METHOD NOT ALLOWED
Date: Thu, 24 Feb 2022 15:01:34 GMT
Content-Type: text/html
Content-Length: 178
Connection: keep-alive
Server: gunicorn/19.9.0
Allow: OPTIONS, POST
Access-Control-Allow-Origin: *
Access-Control-Allow-Credentials: true

<!DOCTYPE HTML PUBLIC "-//W3C//DTD HTML 3.2 Final//EN">
<title>405 Method Not Allowed</title>
<h1>Method Not Allowed</h1>
<p>The method is not allowed for the requested URL.</p>

This is just an example of httpbin returning an error.  I don't know exactly which requests you are sending to httpbin, but ... if you have your Apigee API proxy sending requests to httpbin, which result in a 400 or 500 (4xx or 5xx) status response, then... the Apigee API proxy will enter "fault processing".  This means the regular processing of flows and steps is interrupted, and Apigee transfers control to the "Fault Rules".  This is described in detail here. 

It could be that a 4xx returned from the upstream system is leading to an expected sequence of policies within the API Proxy, which somehow skips your logging calls.  I am not sure, because I haven't tried it, but that could be the problem here. 

Anyway try the updated ProxyEndpoint I provided, and see if you can straighten out which FlowCallout does what. Also please make sure you have _deployed_ the updated proxy after you make changes. (Apigee does not auto-deploy updates that you make in the UI)

[fcasteluber]

Sorry about the confusion. The path and verb for the conditional flow was just for testing purposes, as it was not working, I thought that maybe the issue was because I didn't specify explicitly a condition (verb and/or path), and as mentioned before, it didn't work.

"I see two things that look like flow callouts in your proxy. FC-CloudLogging, and Flow-Callout-1. Which one of those is referring to the sharedflow that does logging? what does the other flow callout do?" Again, I was only testing, so I added a second callout which uses the same shared flow. It didn't work. You can consider "FC-CloudLogging" as the callout I was primarily using.

"Can you confirm that by "only for GET" you mean when the verb is GET? " Yes.

"I might suggest replacing your proxyendpoint configuration with this:" I´ve replaced and tested here. Same result: I can only get log records for GET calls.

"ahhh, just checking now, I see the problem.  More in a bit... I have a meeting right now." Please, let me know what I´m missing here. 🙂

[fcasteluber]

Hi Dino,

I've tried the updated proxyendpoint with only one callout, and yes, I've deployed before testing it. Still the same: no logs for POST requests. Debugging the session I can't see any error, only 200 status response. The same if I use curl:

Perhaps, I should change the approach and maybe use message logging policy instead of this callout? Could you please kindly let me know if there is any working proxy example using message logging for GCP Cloud logging that I could also give it a try?

And thank you once again for trying to help me.