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

net/http: TimeoutHandler doesn't log superfluous WriteHeader calls #30803

Closed
LarsFox opened this issue Mar 13, 2019 · 6 comments
Closed

net/http: TimeoutHandler doesn't log superfluous WriteHeader calls #30803

LarsFox opened this issue Mar 13, 2019 · 6 comments
Assignees
Labels
Milestone

Comments

@LarsFox
Copy link

@LarsFox LarsFox commented Mar 13, 2019

What version of Go are you using (go version)?

$ go version
go version go1.12 darwin/amd64

What did you do?

Here is the program that listens and serves 2 ports with a buggy handler that calls WriteHeader twice. The second port, however, is also wrapped in a http.TimeoutHandler.

package main

import (
	"log"
	"net/http"
	"reflect"
	"time"
)

func h404() http.Handler {
	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
		log.Println(reflect.TypeOf(w))
		w.WriteHeader(404)
		w.WriteHeader(404)
	})
}

func main() {
	go func() {
		http.ListenAndServe(":8500", h404())
	}()
	http.ListenAndServe(":8501", http.TimeoutHandler(h404(), time.Second*10, "no logs here"))
}

Then I test the handlers with curl localhost:8500 && curl localhost:8501.

What did you expect to see?

Two warnings.

What did you see instead?

A single warning.

$ go run main.go
2019/03/13 14:41:02 *http.response
2019/03/13 14:41:02 http: superfluous response.WriteHeader call from main.h404.func1 (main.go:15)
2019/03/13 14:41:02 *http.timeoutWriter

Am I doing something terribly wrong?

System details

go version go1.12 darwin/amd64
GOARCH="amd64"
GOBIN=""
GOCACHE="/Users/leo/Library/Caches/go-build"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOOS="darwin"
GOPATH="/Users/leo/go"
GOPROXY=""
GORACE=""
GOROOT="/usr/local/go"
GOTMPDIR=""
GOTOOLDIR="/usr/local/go/pkg/tool/darwin_amd64"
GCCGO="gccgo"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
GOMOD=""
GOROOT/bin/go version: go version go1.12 darwin/amd64
GOROOT/bin/go tool compile -V: compile version go1.12
uname -v: Darwin Kernel Version 18.2.0: Thu Dec 20 20:46:53 PST 2018; root:xnu-4903.241.1~1/RELEASE_X86_64
ProductName:	Mac OS X
ProductVersion:	10.14.3
BuildVersion:	18D109
lldb --version: lldb-1000.0.38.2
  Swift-4.2
@odeke-em odeke-em changed the title http.timeoutWriter does not log superflous WriteHeader call net/http: TimeoutHandler doesn't log superfluous WriteHeader calls Mar 13, 2019
@odeke-em

This comment has been minimized.

Copy link
Member

@odeke-em odeke-em commented Mar 13, 2019

Thank you for reporting this issue @LarsFox and welcome to the Go project!

I am don't think that we have a guarantee that every handler provided by the
net/http package should log "superfluous WriteHeader call". However, this does seem inconsistent.

Here is a standalone repro that can be run on the Go playground https://play.golang.org/p/B-LBC3SyB47
or inlined below

package main

import (
	"log"
	"net/http"
	"net/http/httptest"
	"net/http/httputil"
	"reflect"
	"time"
)

func h404() http.Handler {
	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
		log.Println(reflect.TypeOf(w))
		w.WriteHeader(404)
		w.WriteHeader(404)
	})
}

func main() {
	cst := httptest.NewServer(http.TimeoutHandler(h404(), time.Second*10, "no logs here"))
	defer cst.Close()

	for i := 0; i < 100; i++ {
		res, err := cst.Client().Get(cst.URL)
		if err != nil {
			log.Printf("%d: error: %v", i, err)
			continue
		}

		blob, _ := httputil.DumpResponse(res, true)
		res.Body.Close()
		log.Printf("#%d:\n%s\n\n", i, blob)
	}
}

which produces

009/11/10 23:00:00 *http.timeoutWriter
2009/11/10 23:00:00 #0:
HTTP/1.1 404 Not Found
Date: Tue, 10 Nov 2009 23:00:00 GMT
Content-Length: 0



2009/11/10 23:00:00 *http.timeoutWriter
2009/11/10 23:00:00 #1:
HTTP/1.1 404 Not Found
Date: Tue, 10 Nov 2009 23:00:00 GMT
Content-Length: 0



2009/11/10 23:00:00 *http.timeoutWriter
2009/11/10 23:00:00 #2:
HTTP/1.1 404 Not Found
Date: Tue, 10 Nov 2009 23:00:00 GMT
Content-Length: 0

but no log to superfluous WriteHeader.

Kindly paging @bradfitz @tombergan

@odeke-em odeke-em added this to the Go1.13 milestone Mar 13, 2019
@cuonglm

This comment has been minimized.

Copy link
Contributor

@cuonglm cuonglm commented Mar 14, 2019

@LarsFox timeoutWriter.WriteHeader(code) just set the response code to code and wroteHeader to true, that's why no warnings is necessary.

@LarsFox

This comment has been minimized.

Copy link
Author

@LarsFox LarsFox commented Mar 14, 2019

@Gnouc, didn’t quite get the difference.

func (w *response) WriteHeader(code int) {
	if w.conn.hijacked() {
		caller := relevantCaller()
		w.conn.server.logf("http: response.WriteHeader on hijacked connection from %s (%s:%d)", caller.Function, path.Base(caller.File), caller.Line)
		return
	}
	if w.wroteHeader {
		caller := relevantCaller()
		w.conn.server.logf("http: superfluous response.WriteHeader call from %s (%s:%d)", caller.Function, path.Base(caller.File), caller.Line)
		return
	}
	checkWriteHeaderCode(code)
	w.wroteHeader = true
	w.status = code

	// more stuff goes on with the Content-Length header
func (tw *timeoutWriter) WriteHeader(code int) {
	checkWriteHeaderCode(code)
	tw.mu.Lock()
	defer tw.mu.Unlock()
	if tw.timedOut || tw.wroteHeader {
		return
	}
	tw.writeHeader(code)
}

func (tw *timeoutWriter) writeHeader(code int) {
	tw.wroteHeader = true
	tw.code = code
}

Also, I don’t know, but by looking through the source code I found out that if I try sending codes of 404 and then 1000 (which is very naughty), only timeoutWriter panics with invalid WriteHeader code 1000 as checkWriteHeaderCode is called before .wroteHeader check. Should I make another issue or is it fine to develop the idea of inconsistency here?

@cuonglm

This comment has been minimized.

Copy link
Contributor

@cuonglm cuonglm commented Mar 14, 2019

@LarsFox normal writer also modify the content length header in WriteHeader, timeoutWriter doesn't.

Also, I don’t know, but by looking through the source code I found out that if I try sending codes of 404 and then 1000 (which is very naughty), only timeoutWriter panics with invalid WriteHeader code 1000 as checkWriteHeaderCode is called before .wroteHeader check. Should I make another issue or is it fine to develop the idea of inconsistency here?

cc @bradfitz @odeke-em

@rsc rsc modified the milestones: Go1.13, Go1.14 May 1, 2019
@rsc rsc modified the milestones: Go1.14, Backlog Oct 9, 2019
@gopherbot

This comment has been minimized.

Copy link

@gopherbot gopherbot commented Oct 10, 2019

Change https://golang.org/cl/200518 mentions this issue: net/http: make TimeoutHandler log spurious WriteHeader calls

@odeke-em odeke-em self-assigned this Oct 10, 2019
@gopherbot gopherbot closed this in ff4e0e4 Oct 21, 2019
@odeke-em

This comment has been minimized.

Copy link
Member

@odeke-em odeke-em commented Oct 21, 2019

@cuonglm @LarsFox thanks for the comment in #30803 (comment), would you mind filing an issue highlighting that other inconsistency, if an issue doesn't exist already?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
5 participants
You can’t perform that action at this time.