Go Web Server - Why Two Log Outputs?

Sat 1 Nov 2014

The Go Program

Create a very simple Go web server as follows, by saving the following Go code into a file called server.go:

package main

import (
	"io"
	"log"
	"net/http"
)

// Function Home - that handles a web server request for a page
func Home(w http.ResponseWriter, req *http.Request) {
	// write some text to the calling web browser
	io.WriteString(w, "Hello World!")
	// output to the console that we did something
	log.Println("served a web page")
}

// Function: MAIN
func main() {
	// start up output - to let us know the web server is starting
	log.Println("Starting server...")
	// handler registered for requests to the root of our web server - send them to the function 'Home'
	http.HandleFunc("/", Home)
	// start a web server on localhost port 8000 grabbing any errors that occur
	err := http.ListenAndServe(":8000",nil)
	// check for any errors from the above web server start-up
	if err != nil {
		log.Fatal("ListenAndServer: ", err)
	}
}

Assuming you already have Go installed on your computer and configured correctly, the above can be run with:

go run server.go

The Strange Output?

So what’s the point?

Well we now have a simple web server that displays “Hello World!” in you browser window, which is very cool for so little code! You need to send browser to the URL: http://localhost:8000

But the curious thing (to me) was whenever I visit the page or just refreshed it, I was seeing two outputs on the console window as follows:

2014/11/01 07:31:02 served a web page
2014/11/01 07:31:02 served a web page

The time stamp is the same for both outputs—and I only visited the page once. So why two outputs??

The outputs are being provided by the code that runs each time the handler function called ‘Home’ to serve a web page is run, the output is generated by the log.Println("served a web page") instruction. But why is it output twice?

The Investigation

So a quick search on Google to find out! Nothing obvious to explain it. Time to figure it out…

Reasons I thought of:

  1. A bug in Go? I doubt it very much—the log.Println is used by lots of people’s programs, so I hardly think I am the first person to notice something as simple as this - so probably not a bug!
  2. Maybe it is outputting a log entry for both stdout and stderr? Possible—but unlikely for a default setting.
  3. I have done something dumb (again!) and the output is getting called twice due to some programming logic error—quite possible—but checking the code logic, nothing stands out!
  4. So—must be some other issue causing it I guess—time to find out more…

We need to isolate why we are getting two log outputs for one page visit. So some way to see if the two log outputs are for the same reason (ie duplicates)—or in fact they are generated correctly for two different reasons. But how?

Well, if the Home function is being call twice (as the log output indicates), then there must be two requests being handled by the web server?

Ok, so how can I differentiate between the two log outputs?

Looking at the Home function I see it requires two parameters when it is called to serve a web page:

func Home(w http.ResponseWriter, req *http.Request)

The parameters are:

  1. 1st function parameter : w http.ResponseWriter
  2. 2nd function parameter : req *http.Request

The 2nd is the http.Request—so the Hyper Text Transfer Protocol (HTTP) request to serve some content. This is the request sent by our web browser asking for something to be provided by our web server!

So if we are genuinely getting two requests (hence to log output)—we should be able to see them by checking the requests themselves!

The Re-Code to Find the Problem

Quick change to the code—so the log output also provides the http.Request we get from the browser—so we can examine them:

package main

import (
	"io"
	"log"
	"net/http"
)

// Function Home - that handles a web server request for a page
func Home(w http.ResponseWriter, req *http.Request) {
	io.WriteString(w, "Hello World!")
	log.Print("served a web page:\n",req,"\n\n")
}

// Function: MAIN
func main() {
	// start up output - to let us know the web server is starting
	log.Println("Starting server...")
	// handler registered for requests to the root of our web server - send them to the function 'Home'
	http.HandleFunc("/", Home)
	// start a web server on localhost port 8000 grabbing any errors that occur
	err := http.ListenAndServe(":8000",nil)
	// check for any errors from the above web server start-up
	if err != nil {
		log.Fatal("ListenAndServer: ", err)
	}
}

In the code, we have altered the request to the log package—asking it now also to provide a copy of the http.Request it received (ie information held in the variable: req) as well as a few newlines (ie \n) to improve the output formatting to the console. The new line of code is:

log.Print("served a web page\n",req,"\n\n")

The output we see when now when re-running the server and requesting a page is as follows:

2014/11/01 07:51:02 Starting server...
2014/11/01 07:51:06 served a web page:
&{GET / HTTP/1.1 1 1 map[Accept:[text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8] User-Agent:[Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Ubuntu Chromium/37.0.2062.94 Chrome/37.0.2062.94 Safari/537.36] Dnt:[1] Accept-Encoding:[gzip,deflate,sdch] Accept-Language:[en-US,en;q=0.8] Connection:[keep-alive] Cache-Control:[max-age=0]] 0x7eb1c0 0 [] false localhost:8000 map[] map[] <nil> map[] 127.0.0.1:54933 / <nil>}

2014/11/01 07:51:06 served a web page:
&{GET /favicon.ico HTTP/1.1 1 1 map[Dnt:[1] User-Agent:[Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Ubuntu Chromium/37.0.2062.94 Chrome/37.0.2062.94 Safari/537.36] Accept-Encoding:[gzip,deflate,sdch] Accept-Language:[en-US,en;q=0.8] Connection:[keep-alive] Accept:[*/*]] 0x7eb1c0 0 [] false localhost:8000 map[] map[] <nil> map[] 127.0.0.1:54933 /favicon.ico <nil>}

Looking at the two outputs again—we can now see they are both different requests!! But why?

The first request starts with:

&{GET / HTTP/1.1

Which is a GET for / —so asking (ie GETting) a copy of the web page located on the web server at the location / —which is the root of the web site. That is is fine—and what we would expect—a request to provide a web page…

The second request then—this starts with:

&{GET /favicon.ico HTTP/1.1

Which is a GET for /favicon.ico - so asking (ie GETting) a copy of a file called favicon.ico located on the web server. Ok—so the browser issues a second request to our web server—asking for a copy of the icon our web site uses—the little icon you see for the site in your bookmarks, to help identify the site.

Now it makes sense why we are getting two request for every single web page served. No bug, no coding error, no weird log options—just a simple double request each time a page is served—once for the page content, and a second for any fav icon our site might have.

The tin foil hat can go back into the cupboard—this is normal.

What Next?

Well—now we have this logging facility, we might as well keep it, and add an option to our code to turn it on and off. We need to add another package to provide this functionality called io/ioutil and add another line to manage the output to our main function: log.SetOutput(ioutil.Discard)

This discards (ie throws away) the log output if we wish. To re-enable it—change this line to: log.SetOutput(io.Stderr) —or just comment the line out to go back to the default behaviour. If you do comment it out though—you will also need to comment out the io/ioutil package as well—as you wont be using it any more in the program, and the Go compiler will spot this and complain to you!

The final code looks like this:

package main

import (
	"io"
	"io/ioutil"
	"log"
	"net/http"
)

// Function that handles a web server request for a page
func Home(w http.ResponseWriter, req *http.Request) {
	io.WriteString(w, "Hello World!")
	log.Print("served a web page\n",req,"\n\n")
}

// Function: MAIN
func main() {
	// control log output: 'ioutil.discard' == throw away  or  'os.Stderr' == output to Stderr (console)
	log.SetOutput(ioutil.Discard)
	// start up output
	log.Println("Starting server...")
	// handler registered for requests to the root of our web server - send them to the function 'Home'
	http.HandleFunc("/", Home)
	// start a web server on localhost port 8000 grabbing any errors that occur
	err := http.ListenAndServe(":8000",nil)
	// check for any errors from the above web server start-up
	if err != nil {
		log.Fatal("ListenAndServer: ", err)
	}
}

Further Information

As an exercise—the flags package could be used to control the log output (ie turn logging output on or off) when the web server is started up.

Further resources and information used in-conjunction with the above can be found here:



  « Previous: