APIGEE Alternative for Message Logging Policy

Google Cloud Apigee
1

Current Setup

  • APIGEE private cloud Version 4.16.01.04

We found out that we have some problems with the Message Logging Policy which throws Broken Pipe Exception. For some reason it causes slowness to our servers up to instance that it returned http 502 bad gateway. Please note that even on higher version of APIGEE we are experiencing the same behavior.

Now we are trying to find alternative ways on how to do message logging (we will be fine for now if message will be sent to MP system.log). We already tried using JavaScript console.log but we are getting the below error.

{ “fault”: { “faultstring”: “Execution of JavaScript.SetRequestMessageLog failed with error: Javascript runtime error: "ReferenceError: "console" is not defined. (JavaScript_SetRequestMessageLog_js#90). at line 90 "”, “detail”: { “errorcode”: “steps.javascript.ScriptExecutionFailed” } } }

tried these variations but still same error that console is not defined.

console.log(“%s”,context.getVariable(“var.message”));

console.log(context.getVariable(“var.message”));

2

Not sure what specific problem you are getting with messagelogging.. but for javascript you need to follow as per below doc.

http://docs.apigee.com/api-services/reference/javascript-object-model

Eg: <>

var request = context.getVariable("request.content");
   if (request)
   {
  var logMessage = "###### REQUEST ###### :";
     logMessage += request;
  context.setVariable("logging.Reqmessage",logMessage);
   }else{
  var logMessage = "###### REQUEST ###### : ";
     request = context.getVariable("request.querystring");
     logMessage += request;
     context.setVariable("logging.Reqmessage",logMessage);
   }
3

This will set context variables, right? It doesn’t actually “log” messages anywhere, except in memory, in the message context.

4

Specifically how do you have the MessageLogging policy configured now?

Are you using the File destination? Can you show us?

What is your transaction rate , approximately?

Are you experiencing filesystem bottlenecks? Is the system IO bound? (Do you see excessive IO Waits?) Do you have filesystem space? Can you check your monitoring on the physical server to verify that you’re not experiencing any of those kinds of issues?

5

Hi @Dino,

Our message logging is configured like this.

<?xml version="1.0" encoding="UTF-8" standalone="yes"?> MessageLogging.SetMessageLog {var.message} APG-Log-Name-v1.log TIME_SIZE 10 0 1440 INFO

What is your transaction rate , approximately?

  • Not so sure about this but let us say about 50-100 per second now.

Are you experiencing filesystem bottlenecks?

  • Not that sure on how to check this on MP logs but see below logs that we see in or MP system.log

2017-10-13 23:39:34,069 Thread-92 INFO FILE_LOGGER - BufferedWriter.getSizeAtMessageBoundary() : file rotation due - detected
2017-10-13 23:39:34,078 Thread-92 INFO FILE_LOGGER - BufferedWriter.getSizeAtMessageBoundary() : file rotation due - detected
2017-10-13 23:39:34,568 Thread-78 INFO FILE_LOGGER - BufferedWriter.getSizeAtMessageBoundary() : file rotation due - detected
2017-10-13 23:39:34,578 Thread-78 INFO FILE_LOGGER - BufferedWriter.getSizeAtMessageBoundary() : file rotation due - detected
2017-10-13 23:40:27,794 Thread-92 INFO FILE_LOGGER -

main INFO FILE_LOGGER - BufferedWriter.start() : Starting logging thread
2017-10-13 11:23:59,809 main INFO FILE_LOGGER - TimeBasedFileRotator.() : Creating timeBased rotator with maxSeconds 86400
2017-10-13 11:23:59,810 Thread-135 INFO FILE_LOGGER - BufferedWriter.run() : Signalling threadInit completion
2017-10-13 11:24:00,244 main INFO FILE_LOGGER - BufferedWriter.start() : Starting logging thread
2017-10-13 11:24:00,244 main INFO FILE_LOGGER - TimeBasedFileRotator.() : Creating timeBased rotator with maxSeconds 86400
2017-10-13 11:24:00,250 Thread-136 INFO FILE_LOGGER - BufferedWriter.run() : Signalling threadInit completion
2017-10-13 11:28:45,600 Apigee-Main-9 INFO FILE_LOGGER - BufferedWriter.close() : Stopping logger thread
2017-10-13 11:28:45,600 Apigee-Main-9 INFO FILE_LOGGER - BufferedWriter.close() : Sending interrupt to logger thread
2017-10-13 11:28:45,600 Thread-37 INFO FILE_LOGGER - BufferedWriter.run() : logThread exiting
2017-10-13 11:28:45,601 Thread-37 INFO FILE_LOGGER - BufferedWriter.run() : logThread exited
2017-10-13 11:28:48,356 Apigee-Main-1 INFO FILE_LOGGER - BufferedWriter.start() : Starting logging thread
2017-10-13 11:28:48,356 Apigee-Main-1 INFO FILE_LOGGER - TimeBasedFileRotator.() : Creating timeBased rotator with maxSeconds 86400
2017-10-13 11:28:48,357 Thread-144 INFO FILE_LOGGER - BufferedWriter.run() : Signalling threadInit completion
2017-10-13 11:29:02,862 org:ORG env:prod api:ORG-API-Template-v1 rev:19 messageid:tx-apg-ap-dev.ORGsg.net-13703-282-1 policy:MessageLogging.SetMessageLog Apigee-Main-8 ERROR FILE_LOGGER - BufferedWriter.bufferMessage() : Failed to write to the buffer 0
2017-10-13 11:29:02,870 org:ORG env:prod api:ORG-API-Template-v1 rev:19 messageid:tx-apg-ap-dev.ORGsg.net-13703-279-1 policy:MessageLogging.SetMessageLog Apigee-Main-5

2017-10-13 06:11:36,343 org:ORG env:prod api:ORG-API-Template-v1 rev:18 messageid:tx-apg-ap-dev.ORGsg.net-14461-4350-1 NIOThread@1 ERROR ADAPTORS.HTTP.FLOW - ResponseWriteListener.onException() : ResponseWriteListener.onException(HTTPResponse@37d029d4, Broken pipe)
java.io.IOException: Broken pipe
Caused by: java.io.IOException: Broken pipe
2017-10-13 06:19:37,704 org:ORG env:prod api:APIProxy rev:20 messageid:b842d695-492e-4053-8939-145e493fb178 NIOThread@1 INFO HTTP.SERVICE - ExceptionHandler.handleException() : Exception java.io.IOException: Broken pipe occurred while writing to channel ClientOutputChannel(ClientChannel[A:127.0.0.1:8998 Remote host:127.0.0.1:44298]@2451 useCount=1 bytesRead=0 bytesWritten=140 age=55296ms lastIO=0ms )
java.io.IOException: Broken pipe
Caused by: java.io.IOException: Broken pipe
2017-10-13 06:19:37,705 org:ORG env:prod api:APIProxy rev:20 messageid:b842d695-492e-4053-8939-145e493fb178 NIOThread@1 INFO HTTP.SERVICE - ExceptionHandler.handleException() : Exception java.io.IOException: Broken pipe occurred while writing to channel ClientOutputChannel(ClientChannel[A:127.0.0.1:8998 Remote host:127.0.0.1:44298]@2451 useCount=1 bytesRead=0 bytesWritten=140 age=55297ms lastIO=0ms )

Is the system IO bound? (Do you see excessive IO Waits?) Do you have filesystem space? - File system space is fine as per checking

Can you check your monitoring on the physical server to verify that you’re not experiencing any of those kinds of issues?

  • Will check with our server side guys on how to do this.
6

Hi Harry,

According to your log file, the “java.io.IOException: Broken pipe” seems to indicate that the MP is not able to communicate its response with the router. I am concluding this because the client port is 8998 and the “remote host” is on the same machine, with a high port. This is likely to be a dynamically-assigned port used by the router.

Why is this happening?

As far as I know, the router in 4.16.01 is based on nginx. nginx should be able to handle 50-100 requests per second on a reasonable server.

Looking at the logs, it may be a timeout. The age is just over 55000ms in each case. As you may know, the default io timeout used when Message Processors communicate with targets is 55000ms. See this documentation page.

It’s possible the MP times out the connection and just responds back to the router with that information.

You seem to suspect that the MessageLogging policy is related to the broken pipe (which appears to be a timeout). Why do you think that? I don’t see anything in the logs that supports the idea.

How often does the broken pipe occur? Can you check your backend logs to see if there are requests that take longer than 55seconds?

You can also try raising the io.timeout on the Target to see if that alleviates the problem.

7

Hi @Dino,

Thank you for the inputs. The broken pipe occured mostly when we have a message logging to one of our Proxy Chained API (For some reason) which is why we removed the Message Logging on it.

As for the io.timeout it was initially 120 seconds (set on our callout) and MP timeout is still at default which is 57 seconds.

8

Hi @Harry Reynoso @Dino-at-Google

We have also observed similar kind of behavior in version 17.09 for Message Logging Policy but it has to be the below particular scenario:

“When Message Logging Policy is attached in a chained Proxy and variable in tag is null”

In this particular scenario, you see “Broken Pipe” errors in MP’s system log. Eventually, you start getting 502 Bad Gateway errors.

I believe, in this case also, variable {var.message} was null. Quick fix for me was to add a variable (such as messageid) which is always populated by Apigee.

{messageid}-{var.message}