Usage of Elastic causes Cassandra mismatches (read repairs)

[nvidgren]

Axway APIM-ELK version
4.1.0

API-Manager Version
7.7 august update

Question
Starting the Elastic cluster and Filebeats is causing the API GW Cassandra database to experience considerable amount of mismatches and read repairs (readrepairrepairedblocking). Is this phenomenon known and what could cause it?

What I've tried so far
The first idea was to reduce the calls API Builder does towards API GW by enabling the lookup cache with TTL 30 minutes. Then APM was enabled to see if something comes up in its monitoring.
This did not work and so tracing was enabled in Cassandra but even trace logs are not revealing any information that could be of use to analyze the root cause

Additional information
We are running a standard ELK cluster on 4 nodes. API Builder/Logstash is currently running only on one. Filebeats are installed on 6 API GW nodes but the issue occurs already when only one is started. If no Filebeats are running the mismatches are not occurring.
The ELK configuration is standard apart from the settings described above. Filebeats are stand-alone installations but the Axway configuration file is being used.

The issue only occurs in production where the amount of traffic is considerably more than in our integration environment. In our INT we cannot reproduce the issue.

[cwiechmann]

Thanks @nvidgren for reaching out to us. No, the issue is not known to us. Of course, the solution should have no impact on the API-Manager Cassandra-DB.

A few questions:

• with mismatches, you really man a query against the C* DB without a match?
• how many APIs do you have in your catalog?
  • with APIs I mean the API itself, not the individual operations
• how many Applications do you have in your catalog?
• can you please share the ap. number of requests you have in a 5-10 minutes time window?
  • I'm interested in the peak value you have at a typical day
• any idea why APM was not showing anything?
  • that would help us to see, if API-Lookup-Information is successfully cached or not

This is the expected behavior based on the caching in place. No Lookups in about 10 minutes:

In a real production environment, this might look a bit different, as API requests and applications are processed with a larger variance. Nevertheless, after a little bit of a warm-up phase, the requests should decrease significantly.

[cwiechmann]

Another interesting point came in my mind @nvidgren. When initially starting the solution, it sends all available Open-Traffic-Event Log-Files to catch-up and after some time, it's supposed to become real-time.
Obviously during that period, there is some extra-load, as it must process API-Requests from multiple days and API-Requests currently flying it.
This may result in a very high variance of different API-Requests and Applications causing more API-Lookups at API-Manager, as you may have a lot more Cache-Misses (for unknown APIs and Applications), than in normal real-time production mode.

I checked the configuration how Filebeat reads the OpenTraffic-Event Logs and there is actually no ignore older limit:

- type: log
  paths: ["/var/log/opentraffic/*_traffic*.log"]
  close_inactive: 5m # Close filehandlers, if the file has not changed anymore
  json.keys_under_root: true
  json.overwrite_keys: false
  json.add_error_key: true
  fields_under_root: true
  fields:
    logtype: openlog
    gatewayName: ${GATEWAY_NAME:"API-Gateway"}
    gatewayRegion: ${GATEWAY_REGION:"N/A"}
    filebeatVersion: "2"

I think it makes sense to have this limit also for the OpenTraffic-Event Log-Files in the same way as for Trace-Message (e.g. last 12 hours).
I'm going to create an issue for this to have this supported by default in the future. For now, feel free @nvidgren to add this to
your Filebeat-Configuration.

- type: log
  paths: ["/var/log/opentraffic/*_traffic*.log"]
  close_inactive: 5m # Close filehandlers, if the file has not changed anymore
  json.keys_under_root: true
  json.overwrite_keys: false
  json.add_error_key: true
  fields_under_root: true
  # Don't process data pretty old
  ignore_older: "12h" 
  fields:
    logtype: openlog
    gatewayName: ${GATEWAY_NAME:"API-Gateway"}
    gatewayRegion: ${GATEWAY_REGION:"N/A"}
    filebeatVersion: "2"

Don't set this value too small (e.g. 1-2 hours), as it also has an impact, when doing maintenance. If Filebeat cannot send Log-Messages for any reason longer than then the configured ignore_older period, you will have a data loss.

[nvidgren]

Hello Chris,

Thanks for the point about ignoring older logs. While this does decrease the load a bit it has not solved our issue with numerous and constant Cassandra read repairs. For the test we let the infrastructure run normally over the weekend and the read repairs occur constantly without any pause.

[cwiechmann]

Thanks for the update @nvidgren. I'm running out of ideas, why the solution, when running normally, should create a significant impact on the API-Management Cassandra-DB. Do you have time for a Web-Session? Perhaps, I can see what's going on and may cause this.

You can contact me directly via cwiechmann(at)axway.com

[nvidgren]

Hi Chris, sure we can have a web session (including Lucas who submitted issue 192 and who is working on this topic as well).

[cwiechmann]

For the record, the root cause were APIs natively exposed the API-Gateway using a policy AND having path parameters. This is the complete explanation:

Based on the API-Builder Logs on DEBUG it became very clear, that the constant lookups of API-Details causing an increased load on the API-Manager are because of the APIs like these, which are exposed by the API-Gateways directly using policies:

/api/rs/v4/vehicle/<SOME-ID>
/svds/vehicle/images/v3/<SOME-ID>
/rs-360/rs/v3/events/vehicle/<SOME-ID>
/ime/api/v1/customer/<SOME-ID>

The so called native APIs are exposed by the API-Gateway directly using a policy and they have by default “No service context” information. They just behave like a Webserver, returning an HTML-Page, but the WebServer itself doesn't know anything about the page it returned. The same applies to the API-Gateway using a technical policy to implement this API.

These kind of native API-Requests go into the Opentraffic-Event Log without any extra information. A good example is the /healthcheck API:

{
  "timestamp": 1594665615973,
  "correlationId": "8faa0c5f4da87df2ad8c394a",
  "processInfo": {
    "hostname": "ip-172-31-48-17.ec2.internal",
    "domainId": "e1ff3aab-3b11-4820-a1be-3763da2beda4",
    "groupId": "group-2",
    "groupName": "group-a",
    "serviceId": "instance-1",
    "serviceName": "instance-1",
    "version": "7.7.20200530"
  },
  "transactionSummary": {
    "path": "/healthcheck",
    "protocol": "http",
    "protocolSrc": "8080",
    "status": "success",
    "serviceContexts": []
  }
}

As there is no information in the serviceContext, the Logstash pipeline has to use the one and only information which is available, the API-Path, to lookup the API-Details. However, that works well, when not using “Path”-Parameters.

But in this case, every single API-Call has a different Vehicle-, or Customer-ID and that’s why Logstash cannot cache the information, because it doesn’t know which part of the API-Request (e.g. /api/rs/v4/vehicle/vehicle/312312313123/services) path is fixed and which is a variable, hence the cache lookup always fails.

Two things to do to solve this issue:

1. Give these APIs a name
   Add the Policy-Filter: “Set Service context” to the policies for these APIs and give all these native APIs, having a super dynamic path parameter, a logical name (e.g. Vehicle Image API). With that, the Logstash Pipeline, will use that name instead of the path to look up and cache the API-Details.
2. Setup local lookup
   As native APIs will never be found in API-Manager, because they are not managed there, I propose to configure a local lookup file to enrich the information you will see in Kibana. Check the following:
   https://github.com/Axway-API-Management-Plus/apigateway-openlogging-elk#setup-local-lookup

That will reduce the document ingest latency and will help Logstash & Filebeat to process more data into Elasticsearch and of course reduce the amount of lookups against the API-Manager. Perhaps, there are other things required to tune, but I recommend to do this first and then let’s see.