As an operator of Cloud Foundry, I want to enable logging of specified headers for all applications.

[simonjohansson]

This PR implements the use case

As an operator of Cloud Foundry, 
I want to enable logging of specified headers for all applications.

It is based on the discussion on the mailing list.

If you specify the following in your gorouter config

extra_headers_to_log:
  - Span-Id
  - Trace-Id
  - Cache-Control

your access log line will look like

FakeRequestHost - [01/01/2000:00:00:00 +0000] "FakeRequestMethod http://example.com/request FakeRequestProto" MissingResponseStatusCode 0 0 "-" "-" FakeRemoteAddr x_forwarded_for:"-" vcap_request_id:- response_time:MissingFinishedAt app_id:FakeApplicationId headers:{"Cache-Control":"private","Span-Id":"3888dcb6-34f4-11e5-a151-feff819cdc9f","Trace-Id":"7b28f886-fe5f-41af-8182-f88c8fec9e1c"}

[cfdreddbot]

Hey simonjohansson!

Thanks for submitting this pull request! I'm here to inform the recipients of the pull request that you've already signed the CLA.

[cf-gitbot]

We have created an issue in Pivotal Tracker to manage this. You can view the current status of your issue at: https://www.pivotaltracker.com/story/show/99988708.

[simonjohansson]

We are globally exposing a list of headers we want to log. It works but is a bit ugly.

This is because we don't have access to the config struct when calling MakeRecord() and we did not want to refactor the world without guidance.

[mmb]

Hi

Thanks for the PR, reviewed and here are our comments:

1. We agree with @shinji62 that performance should not be impacted if these extra headers to log
   are NOT configured. Since the majority of users will not configure this and this
   code is executed for every request, do as little work as possible.
2. Handle the error response from json.Marshal. Only print the json to the
   buffer if err is nil. Potentially add some tests around cases where json.Marshal would return an error.
3. Configuration and AccessLogRecord

This new configuration entry will have to be optional and operators will need
to opt-in. If there are no headers configured to log, the access logs will NOT have the new
headers element in the log entry.

Instead of using a global variable in config.go, we'd suggest

• Add the list of header names to the Proxy and ProxyArgs structs
• Update proxy.NewProxy and main.buildProxy to pass along the arguments from the config struct
• Add a new field to the AccessLogRecord struct called OptionalHeaders that holds a map of the extra headers to log
• Create a new NewAccessLogRecord function in access_log_record.go that creates the AccessLogRecord and populates the OptionalHeaders map

For example:

type AccessLogRecord struct {
    Request              *http.Request
    StatusCode           int
    RouteEndpoint        *route.Endpoint
    StartedAt            time.Time
    FirstByteAt          time.Time
    FinishedAt           time.Time
    BodyBytesSent        int
    RequestBytesReceived int
    OptionalHeaders      map[string]string
}

func NewAccessLogRecord(request *http.Request, startedAt time.Time, logHeaders []string) *AccessLogRecord {
    accessLog := &AccessLogRecord{
        Request:   request,
        StartedAt: startedAt,
    }

    accessLog.setOptionalHeaders(logHeaders)

    return accessLog
}

func (r *AccessLogRecord) setOptionalHeaders(logHeaders []string) {

    if len(logHeaders) > 0 {
        r.OptionalHeaders = make(map[string]string)
        for _, header := range logHeaders {
            r.OptionalHeaders[header] = r.FormatRequestHeader(header)
        }
    }
}

• Update AccessLogRecord makeRecord func to log the OptionalHeaders if present
  For example:

if r.OptionalHeaders != nil {
  marshalledExtraHeadersToLog, _ := json.Marshal(r.OptionalHeaders)
  fmt.Fprintf(b, `headers:%s`, string(marshalledExtraHeadersToLog))
}

@markstgodard and @mmb

Thanks for the PR, let us know if you have any questions.

[shinji62]

+1 for the @mmb idea.
@simonjohansson you know what to do now :)

[simonjohansson]

@mmb @shinji62

I took a slightly different approach, rather than passing in a list of headers I want to (a new func) NewAccessLogRecord and adding the lookup results to AccessLogRecord.OptionalHeaders I added AccessLogRecord.ExtraHeadersToLog which contains the list of the headers I want, and populate it ServeHTTP, as this require less refactoring of the codebase/tests.

I have yet to write tests cases for when marshalling fails, but will look into that.

I will also write some gatling tests to verify the performance impact of using the new feature.

[crhino]

@simonjohansson That approach looks fine to us. Let us known when you have everything ready to go.

[simonjohansson]

@shinji62 @mmb @crhino @mrdavidlaing

So, some JMeter tests.

Running these on a VM with 8gigs of ram, 4 cpus in the same network as the CF installation.
On on of the router machines(4cpu, 4gb ram) I run 3 gorouters. The one that comes with 212, and two instances of the fork at HEAD, each with the same config as the 212 router, but one of the fork routers have

extra_headers_to_log:
  - Span-Id
  - Trace-Id
  - Cache-Control

The app Im targeting

package main

import (
    "fmt"
    "io"
    "net/http"
    "os"
)

func hello(w http.ResponseWriter, r *http.Request) {
    io.WriteString(w, "Hello world!")
}

func main() {
    http.HandleFunc("/", hello)
    http.ListenAndServe(fmt.Sprintf(":%v", os.Getenv("PORT")), nil)
}

JMeter tests.

require 'ruby-jmeter'
test serialize_threadgroups: "true" do

  # We use F5 instead of HAProxy for entrypoint to routing layer.
  threads ramp_time: 0, count: 10, loops: 10000, ramp: 0 do
    visit name: 'F5->[Gorouter(212)]->[App]', url: 'perf.test.cf.springer-sbm.com'
  end

  threads ramp_time: 0, count: 10, loops: 10000, ramp: 0 do
    header [{ name: 'Host', value: 'perf.test.cf.springer-sbm.com' }]
    visit name: 'Gorouter(212)->[App]', url: '10.230.18.70'
  end

  threads ramp_time: 0, count: 10, loops: 10000, ramp: 0 do
    visit name: 'App', url: '10.230.18.99', port: '61032'
  end

  threads ramp_time: 0, count: 10, loops: 10000, ramp: 0 do
    header [{ name: 'Host', value: 'perf.test.cf.springer-sbm.com' }]
    visit name: 'Gorouter(fork-no-headers)->[App]', url: '10.230.18.70', port: '9000'
  end

  threads ramp_time: 0, count: 10, loops: 10000, ramp: 0 do
    header [{ name: 'Host', value: 'perf.test.cf.springer-sbm.com' }]
    visit name: 'Gorouter(fork-with-headers)->[App]', url: '10.230.18.70', port: '9001'
  end

end.jmx

Ive run two test cases, one with 10 threads and 1000 loops, and one with 10 threads and 10000 loops. Ie 10k vs 100k requests in each test case and I get slightly different results.

10k requests

Label	# Samples	Average	Min	Max	Std. Dev.	Error %	Throughput	KB/sec	Avg. Bytes
F5->[Gorouter(212)]->[App]	10000	2	1	109	3.51	0.00%	3653.6	652.94	183.0
Gorouter(212)->[App]	10000	2	1	15	1.25	0.00%	3731.3	666.83	183.0
App	10000	0	0	14	0.62	0.00%	24630.5	3102.87	129.0
Gorouter(fork-no-headers)->[App]	10000	2	1	20	1.40	0.00%	4135.6	739.09	183.0
Gorouter(fork-with-headers)->[App]	10000	2	1	18	1.23	0.00%	3946.3	705.25	183.0
TOTAL	50000	1	0	109	2.05	0.00%	4625.3	777.82	172.2

100k requests

Label	# Samples	Average	Min	Max	Std. Dev.	Error %	Throughput	KB/sec	Avg. Bytes
F5->[Gorouter(212)]->[App]	61062	7	0	15005	247.92	0.02%	943.5	168.63	183.0
Gorouter(212)->[App]	98904	5	0	10003	138.48	0.00%	1649.7	294.81	183.0
App	100000	0	0	17	0.55	0.00%	22686.0	2857.91	129.0
Gorouter(fork-no-headers)->[App]	100000	2	0	118	1.86	0.00%	4108.1	734.17	183.0
Gorouter(fork-with-headers)->[App]	100000	2	1	21	1.24	0.00%	4006.6	716.02	183.0
TOTAL	459966	3	0	15005	110.86	0.00%	2577.4	431.06	171.3

Some takeaways

• Gorouter add substantial overhead vs going directly to the app. No biggie since its horizontally scalable.
• Head of gorouter seems to be slightly faster then packaged 212 version, even when my fork is checking if r.ExtraHeadersToLog is nil for every request.
• When logging with extra headers there is a noticeable loss of throughput, but not big enough for us not to use it in our installation.
• Our F5 config seems to need some TLC since the performance is pretty lousy :)

All in all, Im happy with the performance.

[shinji62]

Nice seems no different when not enabled.
Default behavior is respected ;)

Just a question did you try to compile with go 1.5 ?
I am just curious ..

Envoyé de mon iPhone

Le 30 juil. 2015 à 18:55, Simon Johansson notifications@github.com a écrit :

@shinji62 @mmb @crhino @mrdavidlaing

So, some JMeter tests.

Running these on a VM with 8gigs of ram, 4 cpus in the same network as the CF installation.
On on of the router machines(4cpu, 4gb ram) I run 3 gorouters. The one that comes with 212, and two instances of the fork at master, each with the same config as the 212 router, but one of the fork routers have

extra_headers_to_log:

• Span-Id
• Trace-Id
• Cache-Control
  The app Im targeting

package main

import (
"fmt"
"io"
"net/http"
"os"
)

func hello(w http.ResponseWriter, r *http.Request) {
io.WriteString(w, "Hello world!")
}

func main() {
http.HandleFunc("/", hello)
http.ListenAndServe(fmt.Sprintf(":%v", os.Getenv("PORT")), nil)
}
JMeter tests.

require 'ruby-jmeter'
test serialize_threadgroups: "true" do

We use F5 instead of HAProxy for entrypoint to routing layer.

threads ramp_time: 0, count: 10, loops: 10000, ramp: 0 do
visit name: 'F5->[Gorouter(212)]->[App]', url: 'perf.test.cf.springer-sbm.com'
end

threads ramp_time: 0, count: 10, loops: 10000, ramp: 0 do
header [{ name: 'Host', value: 'perf.test.cf.springer-sbm.com' }]
visit name: 'Gorouter(212)->[App]', url: '10.230.18.70'
end

threads ramp_time: 0, count: 10, loops: 10000, ramp: 0 do
visit name: 'App', url: '10.230.18.99', port: '61032'
end

threads ramp_time: 0, count: 10, loops: 10000, ramp: 0 do
header [{ name: 'Host', value: 'perf.test.cf.springer-sbm.com' }]
visit name: 'Gorouter(fork-no-headers)->[App]', url: '10.230.18.70', port: '9000'
end

threads ramp_time: 0, count: 10, loops: 10000, ramp: 0 do
header [{ name: 'Host', value: 'perf.test.cf.springer-sbm.com' }]
visit name: 'Gorouter(fork-with-headers)->[App]', url: '10.230.18.70', port: '9001'
end

end.jmx
Ive run two test cases, one with 10 threads and 1000 loops, and one with 10 threads and 10000 loops. Ie 10k vs 100k requests in each test case and I get slightly different results.

10k requests

Label # Samples Average Min Max Std. Dev. Error % Throughput KB/sec Avg. Bytes
F5->[Gorouter(212)]->[App] 10000 2 1 109 3.51 0.00% 3653.6 652.94 183.0
Gorouter(212)->[App] 10000 2 1 15 1.25 0.00% 3731.3 666.83 183.0
App 10000 0 0 14 0.62 0.00% 24630.5 3102.87 129.0
Gorouter(fork-no-headers)->[App] 10000 2 1 20 1.40 0.00% 4135.6 739.09 183.0
Gorouter(fork-with-headers)->[App] 10000 2 1 18 1.23 0.00% 3946.3 705.25 183.0
TOTAL 50000 1 0 109 2.05 0.00% 4625.3 777.82 172.2
100k requests

Label # Samples Average Min Max Std. Dev. Error % Throughput KB/sec Avg. Bytes
F5->[Gorouter(212)]->[App] 61062 7 0 15005 247.92 0.02% 943.5 168.63 183.0
Gorouter(212)->[App] 98904 5 0 10003 138.48 0.00% 1649.7 294.81 183.0
App 100000 0 0 17 0.55 0.00% 22686.0 2857.91 129.0
Gorouter(fork-no-headers)->[App] 100000 2 0 118 1.86 0.00% 4108.1 734.17 183.0
Gorouter(fork-with-headers)->[App] 100000 2 1 21 1.24 0.00% 4006.6 716.02 183.0
TOTAL 459966 3 0 15005 110.86 0.00% 2577.4 431.06 171.3
Some takeaways

Head of gorouter seems to be slightly faster then packaged 212 version, even when my fork is checking if r.ExtraHeadersToLog is nil for every request.
When logging with extra headers there is a noticeable loss of throughput, but not big enough to disable it in our installation.
Our F5 config seems to need some TLC since the performance there is pretty lousy.
All in all, Im happy with the performance.

—
Reply to this email directly or view it on GitHub.

[simonjohansson]

@shinji62

Nope, compiled with go1.4.2 darwin/amd64, gorouter compiled with 1.5 in CF release?

Edit: had a peak, 1.4.2 in CF Release.

[shinji62]

No no I was just wondering if perf improve ;)

Envoyé de mon iPhone

Le 30 juil. 2015 à 19:35, Simon Johansson notifications@github.com a écrit :

@shinji62

Nope, compiled with go1.4.2 darwin/amd64, gorouter compiled with 1.5 in CF release?

—
Reply to this email directly or view it on GitHub.

[simonjohansson]

@shinji62 @mmb @crhino

Anything else I need to sort for a merge?

[crhino]

@simonjohansson I think we might want to return something to the effect of "UnableToMarshalJson" instead of an empty hash here, in keeping with some of the other fields. That way a developer/operator would no something is wrong with their logging instead of being confused as to why the extra headers did not show up.

[crhino]

Commented inline, if you could make that change and add a test case for it that would be great. Otherwise looks good to go. We have this PR prioritized in our backlog here.

[markstgodard]

Also might want to rebase / squash the commits

Cheers

[simonjohansson]

@crhino Ive made the returned value from ExtraHeaders() a bit more clear.

But I have a hard time creating a test case as ExtraHeadersToLog[1] is typed as []string, FormatRequestHeader[2] returns a string, extraHeadersToLog[3](which we marshal) is typed map[string]string, http.Headers used by the tests[4] is typed map[string][]string so everywhere where we deal with the headers we are dealing with strings, and thus would not compile if I try to add a int somewhere for instance. Do you have any pointers as how to create a failing test case?

[1] https://github.com/simonjohansson/gorouter/blob/add-extra-headers-to-log/access_log/access_log_record.go#L23
[2] https://github.com/simonjohansson/gorouter/blob/add-extra-headers-to-log/access_log/access_log_record.go#L30
[3] https://github.com/simonjohansson/gorouter/blob/add-extra-headers-to-log/access_log/access_log_record.go#L105
[4] http://golang.org/src/net/http/header.go?s=350:381#L9

[simonjohansson]

@markstgodard rebased and squashed.

[CAFxX]

Why are you using JSON here? The rest of the log line uses the header_name: "Header value" format, why not reusing the same format?
(I wouldn't mind using JSON for the whole log, mind you... it's just that having JSON embedded in a text log means you need not one but two parsers!)

[shinji62]

@CAFxX Maybe you should read the discussion here http://cf-dev.70369.x6.nabble.com/cf-dev-Allow-gorouter-to-log-random-headers-td800.html#a912

"The reason for a stringified JSON is to make it easy to parse with logstash or other loganalysis tools"

[CAFxX]

@shinji62 yup I read that discussion before posting, and the fact is that my point still stands: you need two parsers (custom text format, JSON) instead of one (custom text format) :)

[shalako]

I would ask that we keep the logging format consistent. If that format is not easily consumable, let's address that holistically as an independent issue.

[simonjohansson]

@CAFxX @shalako

I think that the json format is the easiest and least error prone to deal with.

Take these two examples

Say for instance that we care about two headers for all our application, Header-A, Header-B.

With json

{FakeRequestHost - ..... app_id:FakeApplicationId headers:{"Header-A":"value","Header-B":"value"}

With normal fields

{FakeRequestHost - ..... app_id:FakeApplicationId Header-A:value Header-B:value}

A Grok pattern for json

grok {
  match => {
    'msg' => '%{HOSTNAME:hostname} .... app_id:%{UUID:uuid} (?:%{EXTRA_HEADERS:headers}|{})'
  }
  json {
    source => "EXTRA_HEADERS"
  }
}

A grok pattern for normal fields.

grok {
  match => {
    'msg' => '%{HOSTNAME:hostname} .... app_id:%{UUID:uuid} (?Header-A:%{WORD:header-a}) (?Header-B:%{WORD:header-b})'
  }
}

I see two issues with a grok pattern for normal fields.

1. If we want to add another headers, we have to change config both for Gorouter and in our patterns, and then redeploy two systems. With json we never have to worry about the grok pattern since it will work for all permutations of headers.
2. What if the header sometimes consist of ints, sometimes of dates, sometimes of strings with a space in them etc. etc. Again, with json we never have to worry about the grok pattern since it will work for all permutations of headers.

In https://github.com/logsearch/logsearch-for-cloudfoundry which is a generic release for random peoples CF installations we don't know upfront what headers they want, if any. And I don't think the users are to keen to themselves have to create the Grok patterns, the beauty of the project is that you basically do a "bosh install" and magically gets all the logs from CF/Apps parsed and ready to go for free.

I hope this clears up the rational behind the json vs fields.

[mrdavidlaing]

@shalako; on the issue of consistancy; as you can see we've thought about this carefully, and decided that in this case usability of the logging the "user configured extra fields" as JSON outweighs the apparent difference in format.

Also, if you squint, the log format is consistent 😄 :

{FakeRequestHost - ..... app_id:FakeApplicationId headers:{extra-header-info-as-json} }

Note how the "value" of the headers: key is a string (which just happens JSON, cause that is the best way to encode a user configerable set of key/value pairs such that they can be easily parsed downstream)

[shinji62]

@mmb @crhino Should be ok to merge now ?

[shalako]

Not ok to merge yet. The introduction of a new format for admin-managed logged headers is a concern. We are considering and will reply.

[mrdavidlaing]

@shalako,

In the interests of getting this moving again, if we updated this PR to remove the JSON from the logging format, i.e.:

{FakeRequestHost - ..... app_id:FakeApplicationId Header-A:value Header-B:value}

would that get us back on track to getting this merged?

Thanks

David

[markstgodard]

@mrdavidlaing I was just re-reviewing this PR and we will finalize decision w/ @shalako... stay tuned.
An yes, we need to get this PR moving :)
Cheers

[shalako]

Thank you, @mrdavidlaing. Yes, this should get us on back on track. We'll likely review your latest changes tomorrow and merge if it looks good.

[shalako]

We'll need the new property extra_headers_to_log added to the gorouter job spec in cf-release. Will you be making that PR also?

Please confirm that:

• If the new property is specified in the cf-release manifest, specified headers are logged on deploy
• If the values of the property are modified in the cf-release manifest, only the specified headers are logged on deploy
• If the property is removed from the manifest, no additional headers are logged on deploy
• If the new property is specified in a spiff template stuff, the property is added to the cf-release manifest on running cf-release/generate_deployment_manifest

[simonjohansson]

@markstgodard @shalako

PR updated to revert to the current logging format.

Will you be making that PR also?

Yes, as soon as this is merged I will send a PR for cf-release spec/template/relevant spiff-templates

• If the new property is specified in the cf-release manifest, specified headers are logged on deploy
• If the values of the property are modified in the cf-release manifest, only the specified headers are logged on deploy
• If the property is removed from the manifest, no additional headers are logged on deploy

Extra headers to be logged is derived from the gorouter config. So if the config changes, and the goprocess is restarted all of the above will be true.

• If the new property is specified in a spiff template stuff, the property is added to the cf-release manifest on running cf-release/generate_deployment_manifest

This will be the case. The details on how this is to be done is a discussion better kept in the PR from cf-release I think

[markstgodard]

I think we should double quote the header values when we format to ensure we handle lists and so parsing of log files should be predictable (key:"value" or key:"value1, value2")

For example: If we wanted to log the X-Forwarded-Proto and X-Forwarded-For headers

X-Forwarded-Proto: https, http
X-Forwarded-For: 10.0.0.1, 10.0.0.2

We would want the access log elements to look like this:

x_forwarded_proto:"https, http" x_forwarded_for:"10.0.0.1, 10.0.0.2"

vs.

x_forwarded_proto:https, http x_forwarded_for:10.0.0.1, 10.0.0.2

Cheers

[markstgodard]

@shalako @simonjohansson Reviewed and provided my comments on last commit in PR
(See inline code comments)
Looks great, only concern I had was the missing double quotes around the header values, to account for headers that had a list of comma separated values.

Cheers

[simonjohansson]

@markstgodard

Good spot, altough now we break the original layout again... :P

Ill get cracking at it first thing monday,
Have a nice weekend.

[simonjohansson]

@markstgodard

Header values are now quoted. Updated test to take into when we want a header that doesnt exist, when a header has a quoted value in it and when the header have a list of values in it.

[crhino]

@simonjohansson Everything looks good, but we would prefer that the PR to cf-release at least be opened. Otherwise, we are not able to validate the feature from a user-facing perspective.

We could of course change the config on the router VM, but without the property being exposed in the manifest this PR has no real value.

Sorry for the run around here, we also want to get this PR merged! If you have thoughts about why merging this PR first is better, I would love to hear them.

[simonjohansson]

@crhino sure thang, Ill get cracking on it right away.

The reason why I would prefer this to be merged beforehand is because we would expose configuration in the release that does nothing, as the relevant code is not merged for the component it controls. Doesn't matter at the end of the day. :)

[simonjohansson]

cloudfoundry-attic/cf-release#773

[leochu]

Please check for empty slice. We do not want to log an space in case ExtraHeadersToLog is an empty slice, which is the default value.

cloudfoundry-attic/cf-release#773

[simonjohansson]

@leochu ah, good catch, thanks!

Pushed a fix.

[simonjohansson]

Could someone retrigger travis?
All that's changed since the last green build is simonjohansson@3b8006f

[simonjohansson]

These changes seems to have been merged/cherry-picked into master, so I will close the PR.

[shalako]

Thank you for working with us to get this in, @simonjohansson