home

My First Crash

The second part of exercise 2 in Chapter 1 Basics of Software Engineering for Internet Applications.

Go won't let you write a divide-by-zero. When I tried y := 1/0, it would not compile:

./reqproc.go:121:9: division by zero

So, I used panic:

fmt.Println("About to panic ...")
panic("Hello Crash")
  

The log output was not what I expected.

The start command is:

./hacs 2>&,1 | multilog /var/log/hacs s1048576 n50 &

so I expected each line of the log output would have a timestamp on it, as that is one feature of multilog.

In this case, neither the line before the panic nor the panic message itself has timestamps.

About to panic ...
2021/04/18 00:28:55 http: panic serving 127.0.0.1:59178: Hello Crash
goroutine 7 [running]:
net/http.(*conn).serve.func1(0xc4200a2dc0)
	/usr/local/go/src/net/http/server.go:1726 +0xd0
panic(0x13025e0, 0x13c5620)
	/usr/local/go/src/runtime/panic.go:502 +0x229
main.(*ReqProc).ServeHTTP(0xc420010be0, 0x13ca120, 0xc42013c0e0, 0xc42013a100)
	/Users/mark/src/mycode/gardening/hacs/reqproc.go:122 +0x332
net/http.(*ServeMux).ServeHTTP(0x15738c0, 0x13ca120, 0xc42013c0e0, 0xc42013a100)
	/usr/local/go/src/net/http/server.go:2340 +0x130
net/http.serverHandler.ServeHTTP(0xc4200972b0, 0x13ca120, 0xc42013c0e0, 0xc42013a100)
	/usr/local/go/src/net/http/server.go:2697 +0xbc
net/http.(*conn).serve(0xc4200a2dc0, 0x13ca3e0, 0xc420020500)
	/usr/local/go/src/net/http/server.go:1830 +0x651
created by net/http.(*Server).Serve
	/usr/local/go/src/net/http/server.go:2798 +0x27b

Note that the nginx proxy log output was a 502, not a 500.

garden:~$ grep crashme /var/log/nginx/access.log 
24.34.192.135 - - [18/Apr/2021:07:36:47 -0400] "GET /basics/my-first-program.crashme HTTP/1.1" 502 150 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/14.0.3 Safari/605.1.15" "-"


garden:~$ grep crashme /var/log/nginx/error.log 
2021/04/18 07:36:47 [error] 16814#16814: *15124 upstream prematurely closed connection while reading response header from upstream, client: 24.34.192.135, server: garden.markbucciarelli.com, request: "GET /basics/my-first-program.crashme HTTP/1.1", upstream: "http://127.0.0.1:8100/basics/my-first-program.crashme", host: "garden.markbucciarelli.com"
  

The fix

I was wrong about multilog. D.J. Bernsten's daemontools has another utility tai64n that does the timestamping.

I want any panic to be stamped with the current time, so I'll update the start script to be:

./hacs 2>&1 | tai64n | ./hacs 2>&1 | multilog /var/log/hacs s1048576 n50 &

change all my log statements in the golang code from log.Print* to fmt.Print*, and

and add a helper script to convert the TAI64N timestamps to local time.

garden:~$ cat seelog.sh 
#! /bin/sh -e
# Convert TAI64N labels in log to local time.
# April 18, 2021

tai64nlocal < /var/log/hacs/current
garden:~$ 

-- Mark Bucciarelli, April 18, 2021