Feature: more logging variables available for the access log

[magnusvage]

At the moment, the log format of the access log in APICast is the following:

APIcast/gateway/http.d/apicast.conf.liquid

Line 1 in bfa3ac9

log_format time '[$time_local] $host:$server_port $remote_addr:$remote_port "$request" $status $body_bytes_sent ($request_time) $post_action_impact';

There is a variable there called $post_action_impact, which is a variable created by the APICast Lua extensions. It would be great if more variables are set, so that I can set up a log format most suitable for me. Right now, the use case would be to see which service was called, and which method of that service. With that data, working with the logs in ELK or similar would become much easier (filtering on service and method names instead of paths matching a particular regex etc.)

The change could be completely backwards compatible by just making the variables available but leaving the default logging format as it is.

[eloycoto]

Hi @magnusvage

Some work has been done over the last weeks to address this, I'll keep you posted in the following days.

Regards.

[magnusvage]

@eloycoto great news! Look forward to seeing the results :)

[eloycoto]

Hi @magnusvage

I sent the PR, need to be reviewed, but mostly address your behaviour, the example policy configuration will be something like this:

{
  "name": "apicast.policy.logging",
  "configuration": {
    "enable_access_logs": false,
    "custom_logging": "[{{time_local}}] {{host}}:{{server_port}} {{remote_addr}}:{{remote_port}} \"{{request}}\" {{status}} {{body_bytes_sent}} ({{request_time}}) {{post_action_impact}}",
  }
}

This is the PR:
#1089

I will love your input here, and be able to provide to you the right solution that fixes your use case. :-)

[magnusvage]

Hi @eloycoto

Looks good!

So, this policy would completely override the access log format set at the NGINX level? And without this policy on a service, the access logs would be formatted according to the configured NGINX format?

My biggest concern here is that we would in our case consume the access logs with Logstash, and we would need a predictable format so that our parsing pipeline can parse every line of the access log, regardless of whether the new policy is there or not. Therefore I was hoping to be able to control the logging format at the gateway level. If (for example) the 3scale base policy set a bunch of variables (basically everything you could think of), then we could pick and choose from them in the nginx.conf and every log entry would look exactly the same.

Perhaps this is achievable with the policy approach as well? Can I bulk add/change policies on all services within a given 3scale domain?

[eloycoto]

Hi @magnusvage

I'll think about your use case

Thanks

[magnusvage]

@eloycoto thanks

The important thing regardless of the technical solution is that every access log row is parseable with the same logic, regardless of the configuration applied to any services. That could very well be achieved in a policy approach, but then I think that the custom logging info configured in the policy would have to be placed within some sort of delimiters in the access log row. Example:

log_format time '[$time_local] $host:$server_port $remote_addr:$remote_port "$request" $status $body_bytes_sent ($request_time) $post_action_impact <$custom_logging_policy_data>';

Then we could parse everything within the <> as a single entity.

But, then we wouldn't be able to parse the inside of the <>, since that format would be a service specific string. If we wanted to visualise the logs of a single service (or even a single method within a service), then we would have to know where to get the method name from the log row, every time.

[eloycoto]

Hi @magnusvage

We have some discussion about your proposal in the PR#1089. New changes will be addressed this week.

Thanks.

[magnusvage]

Hi @eloycoto
We want to try this policy out today, using the master branch. We see your example of a custom_env.lua, and intend to put our own logging format in the "custom_logging" attribute of the policy config.

However, when looking at your new nginx config, you seem to have hardcoded some stuff that disables this new feature:

APIcast/gateway/http.d/apicast.conf.liquid

Line 52 in fc75276

set $access_logs_enabled '1';

Do we have to remove these set commands in order to try out the custom logging policy today?

[eloycoto]

Hi @magnusvage

That variable is needed to be initialised on Nginx config due to some Openresty limitations; both logs have a condition to display if you enable custom logging policy is taking care of that.

APIcast/gateway/http.d/apicast.conf.liquid

Lines 52 to 56 in fc75276

	set $access_logs_enabled '1';
	access_log {{ access_log_file | default: "/dev/stdout" }} time if=$access_logs_enabled;
	set $extended_access_logs_enabled '0';
	access_log {{ access_log_file | default: "/dev/stdout" }} extended if=$extended_access_logs_enabled;

[magnusvage]

@eloycoto ah OK,

So by just using your custom_env.lua and injecting that into our Apicast container using your example, we should be fine?

[eloycoto]

Yes!

[magnusvage]

@eloycoto it worked great!

We are seeing one issue though. We want to use the NGINX variables $request_time $upstream_response_time to calculate how much time APICast is adding to the call by taking the difference between the 2 values. However, $upstream_response_time is always coming back as 0.000. Are we doing somwthing wrong? It's included in the custom logging format as {{upstream_response_time}}. $request_time works fine.

[eloycoto]

hi @magnusvage

I've just validated this, and it's works perfect:

{
  "services": [
    {
      "id": 200,
      "backend_version": 1,
      "backend_authentication_type": "service_token",
      "backend_authentication_value": "token-value",
      "proxy": {
        "hosts": [
          "one",
          "test.example.com",
          "172.18.0.3"
        ],
        "api_backend": "http://192.168.15.103:10000",
        "proxy_rules": [
          {
            "pattern": "/",
            "http_method": "GET",
            "metric_system_name": "hits",
            "delta": 1
          }
        ],
        "policy_chain": [

          {
            "name": "apicast.policy.logging",
            "configuration": {
              "enable_access_logs": false,
              "custom_logging": "[{{time_local}}] -- {{request}} RT:{{request_time}} URS: {{upstream_response_time}}"
            }
          },
          {
            "name": "apicast.policy.apicast"
          }
        ]
      }
    }
  ]
}

[12/Sep/2019:14:50:31 +0000] -- GET /sleep?user_key=123 HTTP/1.1 RT:1.800 URS: 1.000
[12/Sep/2019:14:50:35 +0000] -- GET /sleep?user_key=123 HTTP/1.1 RT:1.700 URS: 1.000

Maybe do you have a typo in any place?

[magnusvage]

@eloycoto hmm. Yeah that obviously looks like it works fine. I'll do some more digging, and I might get back to you (I don't think I have a typo)

[magnusvage]

@eloycoto I'm still investigating the upstream_response_time.

One other thing: {{host}} used to become the APICast hostname with the old log format, but now with the custom logging we see the backend hostname here instead. Should we use some other variable names to get the APICast value again?

[eloycoto]

Hi @magnusvage

Good catch, I made some changes in the code and a PR is already open. I'll try to get this in the new stable release.

#1116

Regards

[magnusvage]

@eloycoto do you have any suggestions on how we can get information into the access log identifying the consumer? Application identifier, identifier of the account owning the application or something along those lines?

[eloycoto]

Hi @magnusvage what information do you want? The only information that I can think that can be provided is the number of metrics that were increment. Oher information belongs to different components.

Regards.

[magnusvage]

@eloycoto we want the log entry to reflect which application made the call to the service. Application name (and preferably also application plan system name) would be perfect. I know that information is not stored in the spec.json configuration used by the gateway, so the only way I can think of is that, when APICast makes the auth/authrep call to the 3scale backend to authenticate the call, the response from the backend contains these pieces of information, which we then could put into the log entry using the custom logging policy.

[magnusvage]

Hi @eloycoto , is it possible to log the mapping rule that matched? We want to group log entries based on endpoints, and if the path contains path variables an access log entry containing /get/variable1 and /get/variable2 will be hard to match. But, if we could log "mappingrule: /get/{pathVariable}" or something similar, it would be a breeze to do analytics based on endpoints.

[magnusvage]

Hi @eloycoto we are still seeing the host name bug (backend host name instead of gateway host name) in the logs. Using image quay.io/3scale/apicast:v3.7.0. Did the fix make it into the release?

[eloycoto]

could you share your config?
Regards

[magnusvage]

@eloycoto

local logging_policy_config = cjson.decode([[
    {
      "enable_access_logs": false,
      "custom_logging": "[{{time_iso8601}}] [{{req.headers.X-Forwarded-For}}] {{host}}:{{server_port}} {{remote_addr}}:{{remote_port}} \"{{request}}\" {{status}} {{body_bytes_sent}} ({{request_time}}) ({{upstream_response_time}}) {{post_action_impact}} {{service.id}} {{service.system_name}}"
    }
]])

produces the log entry
[2019-12-18T08:54:25+00:00] [<REDACTED>] echo-api.3scale.net:8080 <REDACTED>:10380 "GET /echo/3scale HTTP/1.1" 200 832 (0.292) (0.292) 0 <REDACTED> <REDACTED>

echo-api.3scale.net is the backend host.

[eloycoto]

@magnusvage instead of {{host}}:{{server_port}}, please use: {{original_request.host}}:{{server_port}}

Regards

[magnusvage]

@eloycoto thanks, that solved it! Is this documented somewhere? Can't find the information on https://github.com/3scale/APIcast/tree/master/gateway/src/apicast/policy/logging