Make httpd logger closer to Common Log Format #6812

sparrc · 2016-06-08T17:33:59Z

Required for all non-trivial PRs

Tests pass
CHANGELOG.md updated

changes the httpd log lines from this:

[httpd] 2016/06/08 14:06:39 ::1 - - [08/Jun/2016:14:06:39 +0100] POST /write?consistency=any&db=telegraf&precision=s&rp= HTTP/1.1 204 0 - InfluxDBClient d6aa01fc-2d79-11e6-8024-000000000000 2.751391ms

to this:

[httpd] ::1 - - [08/Jun/2016:14:06:39 +0100] "POST /write?consistency=any&db=telegraf&precision=s&rp= HTTP/1.1" 204 0 "-" "InfluxDBClient" d6aa01fc-2d79-11e6-8024-000000000000 2751

So it changes a few things:

Remove the logger timestamp at the beginning which isn't very relevant anyways
adds quotes around "METHOD URI PROTOCOL", because this is part of the
common log format.
adds quotes around "AGENT" and "REFERRER" because this is part of the
"combined" log format.
Puts the response time in integer microseconds, because this is
consistent with apache's %D config mod option.

Compared with CLF, our logs now look like this:

[httpd] %{COMMON_LOG_FORMAT} "<agent>" "<referrer>" <request_uuid> <response_time_µs>

For reference, see:
https://en.wikipedia.org/wiki/Common_Log_Format
http://httpd.apache.org/docs/current/mod/mod_log_config.html

sparrc · 2016-06-08T17:49:34Z

cc @nathanielc

nathanielc · 2016-06-08T17:51:32Z

services/httpd/handler.go

@@ -913,8 +913,7 @@ func (h *Handler) logging(inner http.Handler, name string) http.Handler {
 		start := time.Now()
 		l := &responseLogger{w: w}
 		inner.ServeHTTP(l, r)
-		logLine := buildLogLine(l, r, start)
-		h.Logger.Println(logLine)
+		fmt.Println("[httpd] " + buildLogLine(l, r, start))


Why the switch to use STDOUT instead of STDERR?

Ah, I should read the PR first ;)

We should probably just create a logger without the log.Ldate flag if we just need to remove the date from the log. This way it will end up with the rest of the logs and not in STDOUT or something else.

good point, fixed it so it doesn't change to STDOUT

sparrc · 2016-06-08T18:18:54Z

marking as a WIP because it's not clear to me why it was logging with the [httpd] prefix when the logger of the handler is getting set to [http]. Need to investigate.

jsternberg · 2016-06-08T21:59:51Z

@sparrc look inside of services/httpd/service.go. The SetLogOutput(io.Writer) method sets the logger of the handler to the same logger as the service so the initial logger created by the handler never gets used. This happens in a few places and the best way to go about things is just to make sure they agree with each other.

toni-moreno · 2016-06-09T04:25:56Z

Hi @sparrc

I like this idea but I can't take response time with my log analyzer because it expect as response time an integer with fixed unit ( Apache %D parameter prints response time in "ms" ). Instead you are logging a variable string with variable unit, "1.25ms" , "1.45s" . This response time format is too difficult to parse with any log analyzer or a simple awk script.

Could you change the response time to an integer number with fixed unit please?

sparrc · 2016-06-09T08:06:28Z

Sure, I can make it always log in ms

sparrc · 2016-06-09T09:37:00Z

@toni-moreno according to mod_log_config, %D is actually in microseconds: http://httpd.apache.org/docs/current/mod/mod_log_config.html

sparrc · 2016-06-09T09:41:17Z

mod_log_config appears to provide 3 options:

%D              The time taken to serve the request, in microseconds.
%T              The time taken to serve the request, in seconds.
%{UNIT}T        The time taken to serve the request, in a time unit given by UNIT. 
Valid units are ms for milliseconds, us for microseconds, and s for seconds. 
Using s gives the same result as %T without any format; 
using us gives the same result as %D.
Combining %T with a unit is available in 2.4.13 and later.

I'm not sure what to go with, but I think we should pick a unit and stick with it. @toni-moreno are you OK with it having the unit appended? It doesn't seem overly hard to parse to me, makes it immediately clear to all users what the unit is, and the regex (if we went with ms) is as simple as this:

([0-9]+\.[0-9]+)ms

toni-moreno · 2016-06-09T14:11:09Z

Hi @sparrc .

This kind of regex if just what we are trying to avoid. A single integer (not floating point and not text ) is the same as apache does and would be perfect for anybody how needs parse time or look for something in a easy way ( awk scripts by example )

For awk this:

" .... 7543 ms ...."

is better than:

"...... 7543ms ....."

With %D in apache we will see that:

"....... 7543000 ....."

In microseconds as you know.

If you show time in microseconds (without unit) all apache analizers will be able to analize influx logs !!!

sparrc · 2016-06-09T15:41:39Z

fair enough @toni-moreno.....I've changed it to look more like the "Combined log format" with ID and response_time (in microseconds) at the end.

%h %l %u %t \"%r\" %>s %b \"%{Referer}i\" \"%{User-agent}i\"" %L %D

(see example section at end of http://httpd.apache.org/docs/current/mod/mod_log_config.html)

ready for review again @nathanielc

jwilder · 2016-06-09T15:47:33Z

@joelegasse @jsternberg Can you take look?

nathanielc · 2016-06-09T15:54:45Z

LGTM and +1 to matching apache %D exactly using microseconds.

nathanielc · 2016-06-10T16:53:14Z

services/httpd/response_logger.go

-		fmt.Sprintf("%s", time.Since(start)),
+		// response time, report in microseconds because this is consistent
+		// with apache's %D parameter in mod_log_config
+		fmt.Sprintf("%d", time.Since(start).Nanoseconds()/1000),


In implementing this for Kapacitor I noticed that we should probably change this to strcnv.FormatInt to be consistent and probably faster.

strconv.FormatInt(time.Since(start).Nanoseconds()/1000, 10)

joelegasse · 2016-06-10T17:16:47Z

I'm not a big fan of all the string creation and concatenation that's being done. I know it was already there before, but since we're here updating the format, can we switch to a fmt.Sprintf call, rather than creating a list of strings and calling strings.Join?

joelegasse · 2016-06-10T17:18:01Z

services/httpd/response_logger.go

-		fmt.Sprintf("%s", time.Since(start)),
+		// response time, report in microseconds because this is consistent
+		// with apache's %D parameter in mod_log_config
+		strconv.FormatInt(time.Since(start).Nanoseconds()/1000, 10),


the 1000 should probably be replaced with time.Microsecond to make it clear, and prevent reviewers from having to count zeros :-)

personally I think .Nanoseconds()/1000 is more readable than .Nanoseconds()/time.Duration(time.Microsecond))

you would only need time.Since(start)/time.Microsecond. No need for the double-conversion :-)

sparrc · 2016-06-10T17:28:51Z

I'll make the change to just use fmt.Sprintf

joelegasse · 2016-06-10T17:46:49Z

services/httpd/response_logger.go

@@ -99,7 +101,7 @@ func buildLogLine(l *responseLogger, r *http.Request, start time.Time) string {

 	userAgent := r.UserAgent()

-	fields := []string{
+	return fmt.Sprintf("%s %s %s [%s] \"%s %s %s\" %s %s \"%s\" \"%s\" %s %s",


The second '%s' is a static "-", so that can be included directly. The start time is still being sent in as a result of fmt.Sprintf itself... making the actual output double-bracketed. The strconv calls are now unnecessary, and should be replaced with %d verbs.

Since you have a lot of double-quotes, I would recommend a backtick string here

sparrc · 2016-06-13T11:46:28Z

alright I've made all the changes, please review again @joelegasse

cc @nathanielc

joelegasse · 2016-06-13T17:37:04Z

LGTM

e-dard · 2016-06-14T12:12:42Z

LGMT 👍

changes the httpd log lines from this: [httpd] 2016/06/08 14:06:39 ::1 - - [08/Jun/2016:14:06:39 +0100] POST /write?consistency=any&db=telegraf&precision=s&rp= HTTP/1.1 204 0 - InfluxDBClient d6aa01fc-2d79-11e6-8024-000000000000 2.751391ms to this: [httpd] ::1 - - [08/Jun/2016:14:06:39 +0100] "POST /write?consistency=any&db=telegraf&precision=s&rp= HTTP/1.1" 204 0 "-" "InfluxDBClient" d6aa01fc-2d79-11e6-8024-000000000000 2751 So it changes a few things: 1. Remove the logger timestamp at the beginning which isn't very relevant anyways 2. adds quotes around "METHOD URI PROTOCOL", because this is part of the common log format. 3. adds quotes around "AGENT" and "REFERRER" because this is part of the "combined" log format. 4. Puts the response time in integer microseconds, because this is consistent with apache's %D config mod option. Compared with CLF, our logs now look like this: [httpd] %{COMMON_LOG_FORMAT} "<agent>" "<referrer>" <request_uuid> <response_time_µs> For reference, see: https://en.wikipedia.org/wiki/Common_Log_Format http://httpd.apache.org/docs/current/mod/mod_log_config.html

nathanielc reviewed Jun 8, 2016
View reviewed changes

sparrc force-pushed the httpd-log-line-clf branch from ca9b0d4 to e087bdc Compare June 8, 2016 18:15

sparrc changed the title ~~Make httpd logger closer to Common Log Format~~ WIP Make httpd logger closer to Common Log Format Jun 8, 2016

sparrc force-pushed the httpd-log-line-clf branch 2 times, most recently from 0d46b9c to b311131 Compare June 8, 2016 21:02

sparrc changed the title ~~WIP Make httpd logger closer to Common Log Format~~ Make httpd logger closer to Common Log Format Jun 8, 2016

sparrc force-pushed the httpd-log-line-clf branch from b311131 to 2bece37 Compare June 9, 2016 10:07

sparrc force-pushed the httpd-log-line-clf branch from 2bece37 to ce698b0 Compare June 9, 2016 15:39

nathanielc reviewed Jun 10, 2016
View reviewed changes

sparrc force-pushed the httpd-log-line-clf branch 2 times, most recently from 7d0d349 to 4f6e854 Compare June 10, 2016 17:05

joelegasse reviewed Jun 10, 2016
View reviewed changes

sparrc force-pushed the httpd-log-line-clf branch from 4f6e854 to 2c8e3c3 Compare June 10, 2016 17:32

joelegasse reviewed Jun 10, 2016
View reviewed changes

sparrc force-pushed the httpd-log-line-clf branch from 2c8e3c3 to 672edc5 Compare June 13, 2016 11:41

sparrc force-pushed the httpd-log-line-clf branch from 672edc5 to ba05c97 Compare June 13, 2016 11:44

sparrc force-pushed the httpd-log-line-clf branch 2 times, most recently from 6fc4cf1 to 38d54c8 Compare June 14, 2016 12:54

sparrc force-pushed the httpd-log-line-clf branch from 38d54c8 to b9a3f2e Compare June 14, 2016 13:48

sparrc merged commit b9a3f2e into master Jun 14, 2016

mark-rushakoff deleted the httpd-log-line-clf branch July 6, 2016 17:08

timhallinflux added this to the 1.0.0 milestone Dec 19, 2016

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Make httpd logger closer to Common Log Format #6812

Make httpd logger closer to Common Log Format #6812

sparrc commented Jun 8, 2016 •

edited

Loading

sparrc commented Jun 8, 2016

nathanielc Jun 8, 2016

nathanielc Jun 8, 2016

sparrc Jun 8, 2016

sparrc commented Jun 8, 2016

jsternberg commented Jun 8, 2016

toni-moreno commented Jun 9, 2016

sparrc commented Jun 9, 2016

sparrc commented Jun 9, 2016 •

edited

Loading

sparrc commented Jun 9, 2016 •

edited

Loading

toni-moreno commented Jun 9, 2016

sparrc commented Jun 9, 2016 •

edited

Loading

jwilder commented Jun 9, 2016

nathanielc commented Jun 9, 2016

nathanielc Jun 10, 2016 •

edited

Loading

sparrc Jun 10, 2016

joelegasse commented Jun 10, 2016

joelegasse Jun 10, 2016

sparrc Jun 10, 2016

joelegasse Jun 10, 2016

sparrc commented Jun 10, 2016

joelegasse Jun 10, 2016

joelegasse Jun 10, 2016

sparrc commented Jun 13, 2016

joelegasse commented Jun 13, 2016

e-dard commented Jun 14, 2016

Make httpd logger closer to Common Log Format #6812

Make httpd logger closer to Common Log Format #6812

Conversation

sparrc commented Jun 8, 2016 • edited Loading

Required for all non-trivial PRs

sparrc commented Jun 8, 2016

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

sparrc commented Jun 8, 2016

jsternberg commented Jun 8, 2016

toni-moreno commented Jun 9, 2016

sparrc commented Jun 9, 2016

sparrc commented Jun 9, 2016 • edited Loading

sparrc commented Jun 9, 2016 • edited Loading

toni-moreno commented Jun 9, 2016

sparrc commented Jun 9, 2016 • edited Loading

jwilder commented Jun 9, 2016

nathanielc commented Jun 9, 2016

nathanielc Jun 10, 2016 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

joelegasse commented Jun 10, 2016

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

sparrc commented Jun 10, 2016

Choose a reason for hiding this comment

Choose a reason for hiding this comment

sparrc commented Jun 13, 2016

joelegasse commented Jun 13, 2016

e-dard commented Jun 14, 2016

sparrc commented Jun 8, 2016 •

edited

Loading

sparrc commented Jun 9, 2016 •

edited

Loading

sparrc commented Jun 9, 2016 •

edited

Loading

sparrc commented Jun 9, 2016 •

edited

Loading

nathanielc Jun 10, 2016 •

edited

Loading