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
Labels
FrozenDueToAge NeedsDecision Feedback is required from experts, contributors, and/or the community before a change can be made.
Milestone

Comments

@LarsFox
Copy link

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
Copy link
Member

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 the NeedsDecision Feedback is required from experts, contributors, and/or the community before a change can be made. label Mar 13, 2019
@odeke-em odeke-em added this to the Go1.13 milestone Mar 13, 2019
@cuonglm
Copy link
Member

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
Copy link
Author

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
Copy link
Member

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
Copy link

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
@odeke-em
Copy link
Member

@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?

@golang golang locked and limited conversation to collaborators Oct 20, 2020
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
FrozenDueToAge NeedsDecision Feedback is required from experts, contributors, and/or the community before a change can be made.
Projects
None yet
Development

No branches or pull requests

5 participants