Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add opt-in support for outputing configureable HTTP access logs to loggregator #57

Closed
gberche-orange opened this issue Jun 5, 2014 · 9 comments

Comments

@gberche-orange
Copy link

Following up #30 (comment)

The gorouter currently generates non configureable http access traces of the following format (see access_log_record.go for desc of each field)

2014-05-16T14:10:10.80+0200 [RTR]     OUT php-info-gberche.cfapps.io - [16/05/2014:12:10:10 +0000] "GET /info.php?=PHPE9568F35-D428-11d2-A769-00AA001ACF42 HTTP/1.1" 200 2146 "http://php-info-gberche.cfapps.io/info.php" "Mozilla/5.0 (Windows NT 6.1; WOW64; rv:29.0) Gecko/20100101 Firefox/29.0" 10.10.2.122:62465 vcap_request_id:c8a81f5e-77d7-4d6e-7f99-288f07ee0345 response_time:0.004421576 app_id:65b6cb42-10b1-48f5-9722-e79df58c34ec

This has the following limitations for app-dev or app-ops:

  • when trying to troubleshoot rooter to buildpack issues (e.g. timeouts, hanging connections, latencies ...) app-ops need to ask both actors for their truth. Currently, they only have the gorouter version.
  • the verbosity of the log can not be controlled. For example, some apps implementing some REST APIs might be quite sensitive to HTTP headers that are not currently logged.
  • inability to temporary enabling verbose logs on a app (all instances or a subset) to perform some debugging
  • the format can not be controlled, and since it does not currently map to standard format, this may forces log archiving tools to parse it explicitely (e.g. https://github.com/logsearch/logsearch-filters-cf if I understand it correctly)

Fortunately, the gorouter now generates a X-Vcap-Request-Id (may be ultimately X-Request-Id see cloudfoundry/gorouter#29 ) in the HTTP header of requests send to apps and logs this request in the router access logs. This enables correlation with more detailed access logging that can be done in apps themselves or with support from the java-buildpack.

This is consistent with the heroku approach documented at https://devcenter.heroku.com/articles/http-request-id

Currently, the java-buildpack allows to tune the tomcat configuration files (e.g. server.xml and to turn on the access valve ) by forking the buildpack and placing customized file into the resources/tomcat directory.

To make it easier for java-buildpack users, I'm suggesting to offer the configuration by default in the javabuildpack and limit the amount of configuration work in required by app-ops.

I'm therefore suggesting the java-buildpack to allow ops to opt-in access logs:

  • dumped to stdout to be collected by the loggregator,
  • with a default sensible format:
    • with a [ACCESS] prefix to differentiate access logs from app logs ([STDOUT]) or container logs ([CONTAINER])
    • with the X-Vcap-Request-Id=<value>
    • with remaining standards fields in one of the standard format (e.g. apache access logs)
  • opt-in controlled by config/tomcat.yml with new property such as access_login.enabled=true (and ideally in the future ENV var controlled opt-in as to avoid most forks for turning on access logs)

App-ops can then still fork the buildpack to tune the access logs format (or ideally control it with an env var in the future)

App-ops that require to dynamically turn the access logs can embed JMX remoting app such as jolokia ( related discussion into the tracker 46897105 ) to control the RemoveValve bean

Ideally in the future, the following details would be added to the gorouter, to fully enable debugging the router/app http chain (feature parity with heroku router log format ):

  • router adds connect: amount of time spent establishing a connection to the backend web process
  • router adds service: amount of time spent proxying data between the backend web process and the client (if that's different from r.ResponseTime())
@nebhale
Copy link
Member

nebhale commented Jun 9, 2014

@gberche-orange Looks like a good set of requirements to me. Issue opened.

@gberche-orange
Copy link
Author

Thanks @nebhale

@cgfrost
Copy link
Contributor

cgfrost commented Jul 9, 2014

@gberche-orange
We have a change ready for this but could you look at the output and let us know if you are happy with the default pattern going in logs.

2014-07-09T13:34:51.32+0100 [App/0] OUT [ACCESS] 10.10.80.15 - - [09/Jul/2014:12:34:51 +0000] "GET / HTTP/1.1" 200 2 a5004a27-a7f3-4fc2-4453-c4a144658856

This is created with a default pattern specified in valves config in the Buildpack with this pattern. pattern='[ACCESS] %h %l %u %t "%r" %s %b %{X-Vcap-Request-Id}i'

The valve will be disabled by default and can be enabled with a configuration property in tomcat.yml.

@gberche-orange
Copy link
Author

Thanks @cgfrost for working on this enhancement.

The default format seems to match the Common Log Format (CLF). While tempting to rely on a default log format, I fear this duplicates too much the data already present in the RTR logs.

Reproducing below the access log valve format for ease of reading:

    %a - Remote IP address
    %A - Local IP address
    %b - Bytes sent, excluding HTTP headers, or '-' if zero
    %B - Bytes sent, excluding HTTP headers
    %h - Remote host name (or IP address if enableLookups for the connector is false)
    %H - Request protocol
    %l - Remote logical username from identd (always returns '-')
    %m - Request method (GET, POST, etc.)
    %p - Local port on which this request was received
    %q - Query string (prepended with a '?' if it exists)
    %r - First line of the request (method and request URI)
    %s - HTTP status code of the response
    %S - User session ID
    %t - Date and time, in Common Log Format
    %u - Remote user that was authenticated (if any), else '-'
    %U - Requested URL path
    %v - Local server name
    %D - Time taken to process the request, in millis
    %T - Time taken to process the request, in seconds
    %F - Time taken to commit the response, in millis
    %I - Current request thread name (can compare later with stacktraces)

The router log format approx matches the pattern %{Host}i %t "%r" %{Referer}i %{User-Agent}i %h

I rather believe the tomcat default access format should complete the RTR logs with information not present there instead of duplicating them. Users that would rather use this feature to specify a more standard logging format could still override the default format.

From the available fields, I would favor the following ones:

%t - Date and time, in Common Log Format
%h - Remote host name (or IP address if enableLookups for the connector is false)
%D - Time taken to process the request, in millis
%F - Time taken to commit the response, in millis
%B - Bytes sent, excluding HTTP headers
%I - Current request thread name (can compare later with stacktraces)
%S - User session ID

The %h would indicate the IP address of a faulty/slow router component which would be useful in troubleshooting slow responses. It would be interesting to dig onto the definition of %t to understand at that time this date is recorded.

I believe the X-Vcap-Request-Id header should be prefixed by its name as in the router logs vcap_request_id: While wasting few bytes, this allows automatic binding into fields by log processors such as splunk or pivotal analytics.

As a summary, I would suggest:

pattern='[ACCESS] %h %l %t %D %F %B %S vcap_request_id:%{X-Vcap-Request-Id}i'

@cgfrost
Copy link
Contributor

cgfrost commented Jul 11, 2014

Hi @gberche-orange this has now gone out in release 2.4. I have raised a new issue to cover changing the log format. I agree with your reasoning and it's a small change but will have to wait for the next release now. Prefixing the X-Vcap-Request-Id header is also good as hopefully it will be more obvious when/if that headers name changes.

@gberche-orange
Copy link
Author

Thanks @cgfrost.

To ease others willing to follow details, here are:

nebhale pushed a commit that referenced this issue Jul 16, 2014
From GitHub issue #57. The current access logging pattern isn't as useful as it
could be. The logs will often be viewed alongside with the Router logs and
should provide complementing information and not overlap with it.

[#74837854]
@cgfrost
Copy link
Contributor

cgfrost commented Jul 16, 2014

This change has now been commited.
0fab02b

@nebhale nebhale closed this as completed Jul 17, 2014
@gberche-orange
Copy link
Author

great, thanks a lot @cgfrost for this work !

@imod
Copy link
Contributor

imod commented Feb 12, 2018

I have read the whole thread on the ML, but I don't understand why this has been implemented in a way that obnly operators can use/configure it. This makes this feature pretty much useless for all hosted environments like 'run.pivotal.io' or 'swissom'. Or do you expect the hosters to do such a configuration for each app on request?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

4 participants