Bogus HTTP response status code stats

[falzm]

Hi

I'm observing what looks to be a bogus behavior of your middleware regarding the counting of HTTP responses status code. Given the following implementation with Negroni:

package main

import (
	"encoding/json"
	"fmt"
	"net/http"
	"time"

	"github.com/gorilla/mux"
	"github.com/thoas/stats"
	"github.com/urfave/negroni"
)

func main() {
	router := mux.NewRouter()
	httpStats := stats.New()

	router.HandleFunc("/a", handleA).
		Methods("GET", "POST", "PUT")

	router.HandleFunc("/b", handleB).
		Methods("GET")

	router.HandleFunc("/c", handleC).
		Methods("GET")

	router.HandleFunc("/stats", func(w http.ResponseWriter, r *http.Request) {
		w.Header().Set("Content-Type", "application/json")
		stats := httpStats.Data()
		b, _ := json.Marshal(stats)
		w.Write(b)
	})

	n := negroni.New()

	n.UseHandler(router)
	n.Use(httpStats)

	http.ListenAndServe(":8000", n)
}

func handleA(rw http.ResponseWriter, r *http.Request) {
	switch r.Method {
	case "POST", "PUT":
		time.Sleep(100 * time.Millisecond)
		rw.WriteHeader(http.StatusCreated)

	case "GET":
		time.Sleep(10 * time.Millisecond)
	}

	fmt.Fprintf(rw, "A\n")
}

func handleB(rw http.ResponseWriter, r *http.Request) {
	time.Sleep(50 * time.Millisecond)
	fmt.Fprintf(rw, "B\n")
}

func handleC(rw http.ResponseWriter, r *http.Request) {
	time.Sleep(10 * time.Millisecond)
	fmt.Fprintf(rw, "C\n")
}

Sending the following HTTP requests...

$ curl -i -X POST localhost:8000/a
HTTP/1.1 201 Created
Date: Mon, 18 Dec 2017 15:16:25 GMT
Content-Length: 2
Content-Type: text/plain; charset=utf-8

A

$ curl -i -X POST localhost:8000/b
HTTP/1.1 405 Method Not Allowed
Date: Mon, 18 Dec 2017 15:16:32 GMT
Content-Length: 0
Content-Type: text/plain; charset=utf-8

$ curl -i localhost:8000/c
HTTP/1.1 200 OK
Date: Mon, 18 Dec 2017 15:16:40 GMT
Content-Length: 2
Content-Type: text/plain; charset=utf-8

C

$ curl -i localhost:8000/z
HTTP/1.1 404 Not Found
Content-Type: text/plain; charset=utf-8
X-Content-Type-Options: nosniff
Date: Mon, 18 Dec 2017 15:16:42 GMT
Content-Length: 19

404 page not found

...I expected the /stats response total_status_code_count value to be {"200":1,"201":1,"404":1,"405":1}, but it's not:

$ curl localhost:8000/stats | jq .
{
  "pid": 7201,
  "uptime": "46.962268141s",
  "uptime_sec": 46.962268141,
  "time": "2017-12-18 16:16:55.098574 +0100 CET m=+46.963702150",
  "unixtime": 1513610215,
  "status_code_count": {},
  "total_status_code_count": {
    "200": 4
  },
  "count": 0,
  "total_count": 4,
  "total_response_time": "13.083µs",
  "total_response_time_sec": 1.3083e-05,
  "average_response_time": "3.27µs",
  "average_response_time_sec": 3.27e-06
}

Am I doing something wrong?

[lrstanley]

See #22, as it looks related. specifically:

stats/stats.go

Line 73 in 3782902

writer := NewRecorderResponseWriter(w, 200)

[falzm]

My bad, it's a stupid mistake from me: I've registered the HTTP router before registering the middleware. Correct code should be:

...

	n := negroni.New()

	n.Use(httpStats)
	n.UseHandler(router)

	http.ListenAndServe(":8000", n)
...

Middleware works as intended this way.