feat: use Zap for logging

caddy/caddy.go

@@ -4,7 +4,6 @@
 package caddy
 
 import (
-	"log"
 	"net/http"
 	"strconv"
 
@@ -33,7 +32,6 @@ var phpInterpreter = caddy.NewUsagePool()
 type phpInterpreterDestructor struct{}
 
 func (phpInterpreterDestructor) Destruct() error {
-	log.Print("Destructor called")
 	frankenphp.Shutdown()
 
 	return nil
@@ -59,8 +57,9 @@ func (a *FrankenPHPApp) CaddyModule() caddy.ModuleInfo {
 
 func (f *FrankenPHPApp) Start() error {
 	repl := caddy.NewReplacer()
+	logger := caddy.Log()
 
-	var opts []frankenphp.Option
+	opts := []frankenphp.Option{frankenphp.WithLogger(logger)}
 	if f.NumThreads != 0 {
 		opts = append(opts, frankenphp.WithNumThreads(f.NumThreads))
 	}
@@ -92,13 +91,13 @@ func (f *FrankenPHPApp) Start() error {
 		}
 	}
 
-	log.Print("FrankenPHP started")
+	logger.Info("FrankenPHP started 🐘")
 
 	return nil
 }
 
 func (*FrankenPHPApp) Stop() error {
-	log.Print("FrankenPHP stopped")
+	caddy.Log().Info("FrankenPHP stopped 🐘")
 
 	return nil
 }
@@ -193,7 +192,7 @@ func (f FrankenPHPModule) ServeHTTP(w http.ResponseWriter, r *http.Request, next
 	repl := r.Context().Value(caddy.ReplacerCtxKey).(*caddy.Replacer)
 
 	documentRoot := repl.ReplaceKnown(f.Root, "")
-	fr := frankenphp.NewRequestWithContext(r, documentRoot)
+	fr := frankenphp.NewRequestWithContext(r, documentRoot, f.logger)
 	fc, _ := frankenphp.FromContext(fr.Context())
 	fc.ResolveRootSymlink = f.ResolveRootSymlink
 	fc.SplitPath = f.SplitPath

frankenphp.go

@@ -10,11 +10,11 @@ package frankenphp
 // #include "frankenphp.h"
 import "C"
 import (
+	"bytes"
 	"context"
 	"errors"
 	"fmt"
 	"io"
-	"log"
 	"net/http"
 	"runtime"
 	"runtime/cgo"
@@ -22,6 +22,8 @@ import (
 	"strings"
 	"sync"
 	"unsafe"
+
+	"go.uber.org/zap"
 	// debug on Linux
 	//_ "github.com/ianlancetaylor/cgosymbolizer"
 )
@@ -41,11 +43,10 @@ var (
 
 	requestChan chan *http.Request
 	shutdownWG  sync.WaitGroup
-)
 
-func init() {
-	log.SetFlags(log.LstdFlags | log.Lshortfile) // TODO: switch to Zap
-}
+	loggerMu sync.RWMutex
+	logger   *zap.Logger
+)
 
 // FrankenPHP executes PHP scripts.
 type FrankenPHPContext struct {
@@ -74,6 +75,8 @@ type FrankenPHPContext struct {
 	// This map is populated automatically, exisiting key are never replaced.
 	Env map[string]string
 
+	Logger *zap.Logger
+
 	populated    bool
 	authPassword string
 
@@ -81,11 +84,16 @@ type FrankenPHPContext struct {
 	done           chan interface{}
 }
 
-func NewRequestWithContext(r *http.Request, documentRoot string) *http.Request {
+func NewRequestWithContext(r *http.Request, documentRoot string, l *zap.Logger) *http.Request {
+	if l == nil {
+		l = getLogger()
+	}
+
 	ctx := context.WithValue(r.Context(), contextKey, &FrankenPHPContext{
 		DocumentRoot: documentRoot,
 		SplitPath:    []string{".php"},
 		Env:          make(map[string]string),
+		Logger:       l,
 	})
 
 	return r.WithContext(ctx)
@@ -108,6 +116,21 @@ func Init(options ...Option) error {
 		}
 	}
 
+	if opt.logger == nil {
+		l, err := zap.NewDevelopment()
+		if err != nil {
+			return err
+		}
+
+		loggerMu.Lock()
+		logger = l
+		loggerMu.Unlock()
+	} else {
+		loggerMu.Lock()
+		logger = opt.logger
+		loggerMu.Unlock()
+	}
+
 	if opt.numThreads == 0 {
 		opt.numThreads = 1
 	}
@@ -116,7 +139,7 @@ func Init(options ...Option) error {
 	case -1:
 		if opt.numThreads != 1 {
 			opt.numThreads = 1
-			log.Print(`ZTS is not enabled, only 1 thread will be available, recompile PHP using the "--enable-zts" configuration option or performance will be degraded`)
+			logger.Warn(`ZTS is not enabled, only 1 thread will be available, recompile PHP using the "--enable-zts" configuration option or performance will be degraded`)
 		}
 
 	case -2:
@@ -141,7 +164,7 @@ func Init(options ...Option) error {
 }
 
 func Shutdown() {
-	log.Printf("Shutdown called ")
+	logger.Debug("FrankenPHP shutting down")
 	stopWorkers()
 	close(requestChan)
 	shutdownWG.Wait()
@@ -153,6 +176,13 @@ func go_shutdown() {
 	shutdownWG.Done()
 }
 
+func getLogger() *zap.Logger {
+	loggerMu.RLock()
+	defer loggerMu.RUnlock()
+
+	return logger
+}
+
 func updateServerContext(request *http.Request) error {
 	fc, ok := FromContext(request.Context())
 	if !ok {
@@ -301,14 +331,19 @@ func go_ub_write(rh C.uintptr_t, cString *C.char, length C.int) C.size_t {
 
 	var writer io.Writer
 	if fc.responseWriter == nil {
+		var b bytes.Buffer
 		// log the output of the
-		writer = log.Writer()
+		writer = &b
 	} else {
 		writer = fc.responseWriter
 	}
 
 	i, _ := writer.Write([]byte(C.GoStringN(cString, length)))
 
+	if fc.responseWriter == nil {
+		fc.Logger.Info(writer.(*bytes.Buffer).String())
+	}
+
 	return C.size_t(i)
 }
 
@@ -339,7 +374,7 @@ func go_add_header(rh C.uintptr_t, cString *C.char, length C.int) {
 
 	parts := strings.SplitN(C.GoStringN(cString, length), ": ", 2)
 	if len(parts) != 2 {
-		log.Printf(`invalid header "%s"`+"\n", parts[0])
+		fc.Logger.Debug("invalid header", zap.String("header", parts[0]))
 
 		return
 	}

frankenphp_test.go

@@ -49,7 +49,7 @@ func runTest(t *testing.T, test func(func(http.ResponseWriter, *http.Request), *
 	defer frankenphp.Shutdown()
 
 	handler := func(w http.ResponseWriter, r *http.Request) {
-		req := frankenphp.NewRequestWithContext(r, testDataDir)
+		req := frankenphp.NewRequestWithContext(r, testDataDir, nil)
 		if err := frankenphp.ServeHTTP(w, req); err != nil {
 			panic(err)
 		}
@@ -142,7 +142,7 @@ func testPathInfo(t *testing.T, opts *testOptions) {
 			testDataDir := cwd + "/testdata/"
 
 			requestURI := r.URL.RequestURI()
-			rewriteRequest := frankenphp.NewRequestWithContext(r, testDataDir)
+			rewriteRequest := frankenphp.NewRequestWithContext(r, testDataDir, nil)
 			rewriteRequest.URL.Path = "/server-variable.php/pathinfo"
 			fc, _ := frankenphp.FromContext(rewriteRequest.Context())
 			fc.Env["REQUEST_URI"] = requestURI
@@ -301,7 +301,7 @@ func ExampleExecuteScript() {
 	defer frankenphp.Shutdown()
 
 	http.HandleFunc("/", func(w http.ResponseWriter, r *http.Request) {
-		req := frankenphp.NewRequestWithContext(r, "/path/to/document/root")
+		req := frankenphp.NewRequestWithContext(r, "/path/to/document/root", nil)
 		if err := frankenphp.ServeHTTP(w, req); err != nil {
 			panic(err)
 		}

go.mod

@@ -4,7 +4,8 @@ go 1.19
 
 require (
 	github.com/ianlancetaylor/cgosymbolizer v0.0.0-20220405231054-a1ae3e4bba26
-	github.com/stretchr/testify v1.7.1
+	github.com/stretchr/testify v1.8.0
+	go.uber.org/zap v1.23.0
 )
 
 require (
@@ -12,6 +13,8 @@ require (
 	github.com/kr/pretty v0.2.1 // indirect
 	github.com/kr/text v0.2.0 // indirect
 	github.com/pmezard/go-difflib v1.0.0 // indirect
+	go.uber.org/atomic v1.7.0 // indirect
+	go.uber.org/multierr v1.6.0 // indirect
 	gopkg.in/check.v1 v1.0.0-20190902080502-41f04d3bba15 // indirect
-	gopkg.in/yaml.v3 v3.0.0-20220512140231-539c8e751b99 // indirect
+	gopkg.in/yaml.v3 v3.0.1 // indirect
 )

go.sum

@@ -13,11 +13,23 @@ github.com/kr/text v0.2.0/go.mod h1:eLer722TekiGuMkidMxC/pM04lWEeraHUUmBw8l2grE=
 github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZbAQM=
 github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4=
 github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME=
+github.com/stretchr/objx v0.4.0/go.mod h1:YvHI0jy2hoMjB+UWwv71VJQ9isScKT/TqJzVSSt89Yw=
+github.com/stretchr/testify v1.3.0/go.mod h1:M5WIy9Dh21IEIfnGCwXGc5bZfKNJtfHm1UVUgZn+9EI=
 github.com/stretchr/testify v1.7.1 h1:5TQK59W5E3v0r2duFAb7P95B6hEeOyEnHRa8MjYSMTY=
 github.com/stretchr/testify v1.7.1/go.mod h1:6Fq8oRcR53rry900zMqJjRRixrwX3KX962/h/Wwjteg=
+github.com/stretchr/testify v1.8.0 h1:pSgiaMZlXftHpm5L7V1+rVB+AZJydKsMxsQBIJw4PKk=
+github.com/stretchr/testify v1.8.0/go.mod h1:yNjHg4UonilssWZ8iaSj1OCr/vHnekPRkoO+kdMU+MU=
+go.uber.org/atomic v1.7.0 h1:ADUqmZGgLDDfbSL9ZmPxKTybcoEYHgpYfELNoN+7hsw=
+go.uber.org/atomic v1.7.0/go.mod h1:fEN4uk6kAWBTFdckzkM89CLk9XfWZrxpCo0nPH17wJc=
+go.uber.org/multierr v1.6.0 h1:y6IPFStTAIT5Ytl7/XYmHvzXQ7S3g/IeZW9hyZ5thw4=
+go.uber.org/multierr v1.6.0/go.mod h1:cdWPpRnG4AhwMwsgIHip0KRBQjJy5kYEpYjJxpXp9iU=
+go.uber.org/zap v1.23.0 h1:OjGQ5KQDEUawVHxNwQgPpiypGHOxo2mNZsOqTak4fFY=
+go.uber.org/zap v1.23.0/go.mod h1:D+nX8jyLsMHMYrln8A0rJjFt/T/9/bGgIhAqxv5URuY=
 gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0=
 gopkg.in/check.v1 v1.0.0-20190902080502-41f04d3bba15 h1:YR8cESwS4TdDjEe65xsg0ogRM/Nc3DYOhEAlW+xobZo=
 gopkg.in/check.v1 v1.0.0-20190902080502-41f04d3bba15/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0=
 gopkg.in/yaml.v3 v3.0.0-20200313102051-9f266ea9e77c/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM=
 gopkg.in/yaml.v3 v3.0.0-20220512140231-539c8e751b99 h1:dbuHpmKjkDzSOMKAWl10QNlgaZUd3V1q99xc81tt2Kc=
 gopkg.in/yaml.v3 v3.0.0-20220512140231-539c8e751b99/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM=
+gopkg.in/yaml.v3 v3.0.1 h1:fxVm/GzAzEWqLHuvctI91KS9hhNmmWOoWu0XTYJS7CA=
+gopkg.in/yaml.v3 v3.0.1/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM=

internal/testserver/main.go

@@ -1,15 +1,20 @@
 package main
 
 import (
-	"log"
 	"net/http"
 	"os"
 
 	"github.com/dunglas/frankenphp"
+	"go.uber.org/zap"
 )
 
 func main() {
-	if err := frankenphp.Init(); err != nil {
+	logger, err := zap.NewDevelopment()
+	if err != nil {
+		panic(err)
+	}
+
+	if err := frankenphp.Init(frankenphp.WithLogger(logger)); err != nil {
 		panic(err)
 	}
 	defer frankenphp.Shutdown()
@@ -20,7 +25,7 @@ func main() {
 			panic(err)
 		}
 
-		req := frankenphp.NewRequestWithContext(r, cwd)
+		req := frankenphp.NewRequestWithContext(r, cwd, nil)
 		if err := frankenphp.ServeHTTP(w, req); err != nil {
 			panic(err)
 		}
@@ -31,5 +36,5 @@ func main() {
 		port = "8080"
 	}
 
-	log.Fatal(http.ListenAndServe(":"+port, nil))
+	logger.Fatal("server error", zap.Error(http.ListenAndServe(":"+port, nil)))
 }

options.go

@@ -1,6 +1,10 @@
 package frankenphp
 
-import "runtime"
+import (
+	"runtime"
+
+	"go.uber.org/zap"
+)
 
 // Option instances allow to configure the SAP.
 type Option func(h *opt) error
@@ -11,6 +15,7 @@ type Option func(h *opt) error
 type opt struct {
 	numThreads int
 	workers    []workerOpt
+	logger     *zap.Logger
 }
 
 type workerOpt struct {
@@ -36,3 +41,12 @@ func WithWorkers(fileName string, num int) Option {
 		return nil
 	}
 }
+
+// WithLogger sets the global logger to use
+func WithLogger(l *zap.Logger) Option {
+	return func(o *opt) error {
+		o.logger = l
+
+		return nil
+	}
+}

worker.go

@@ -6,10 +6,11 @@ import "C"
 import (
 	"context"
 	"fmt"
-	"log"
 	"net/http"
 	"runtime/cgo"
 	"sync"
+
+	"go.uber.org/zap"
 )
 
 var (
@@ -31,6 +32,8 @@ func startWorkers(fileName string, nbWorkers int) error {
 		m      sync.Mutex
 		errors []error
 	)
+
+	l := getLogger()
 	for i := 0; i < nbWorkers; i++ {
 		go func() {
 			defer shutdownWG.Done()
@@ -53,7 +56,7 @@ func startWorkers(fileName string, nbWorkers int) error {
 				},
 			)
 
-			log.Printf("worker %q: starting", fileName)
+			l.Debug("starting", zap.String("worker", fileName))
 			if err := ServeHTTP(nil, r.WithContext(ctx)); err != nil {
 				m.Lock()
 				defer m.Unlock()
@@ -61,7 +64,7 @@ func startWorkers(fileName string, nbWorkers int) error {
 
 				return
 			}
-			log.Printf("worker %q: terminated", fileName)
+			l.Debug("terminated", zap.String("worker", fileName))
 		}()
 	}
 
@@ -104,19 +107,21 @@ func go_frankenphp_worker_handle_request_start(rh C.uintptr_t) C.uintptr_t {
 
 	rc := v.(chan *http.Request)
 
-	log.Printf("worker %q: waiting for request", previousFc.Env["SCRIPT_FILENAME"])
+	l := getLogger()
+
+	l.Debug("waiting for request", zap.String("worker", previousFc.Env["SCRIPT_FILENAME"]))
 	r, ok := <-rc
 	if !ok {
 		// channel closed, server is shutting down
-		log.Printf("worker %q: shutting down", previousFc.Env["SCRIPT_FILENAME"])
+		l.Debug("shutting down", zap.String("worker", previousFc.Env["SCRIPT_FILENAME"]))
 
 		return 0
 	}
 
-	log.Printf("worker %q: handling request %#v", previousFc.Env["SCRIPT_FILENAME"], r)
+	l.Debug("request handling started", zap.String("worker", previousFc.Env["SCRIPT_FILENAME"]), zap.String("url", r.RequestURI))
 	if err := updateServerContext(r); err != nil {
 		// Unexpected error
-		log.Printf("worker %q: unexpected error: %s", previousFc.Env["SCRIPT_FILENAME"], err)
+		l.Debug("unexpected error", zap.String("worker", previousFc.Env["SCRIPT_FILENAME"]), zap.String("url", r.RequestURI), zap.Error(err))
 
 		return 0
 	}
@@ -134,5 +139,5 @@ func go_frankenphp_worker_handle_request_end(rh C.uintptr_t) {
 
 	close(fc.done)
 
-	log.Printf("worker %q: finished handling request %#v", fc.Env["SCRIPT_FILENAME"], r)
+	fc.Logger.Debug("request handling finished", zap.String("worker", fc.Env["SCRIPT_FILENAME"]), zap.String("url", r.RequestURI))
 }

worker_test.go

@@ -51,7 +51,7 @@ func ExampleWorkerHandleRequest() {
 	defer frankenphp.Shutdown()
 
 	http.HandleFunc("/", func(w http.ResponseWriter, r *http.Request) {
-		req := frankenphp.NewRequestWithContext(r, "/path/to/document/root")
+		req := frankenphp.NewRequestWithContext(r, "/path/to/document/root", nil)
 		if err := frankenphp.ServeHTTP(w, req); err != nil {
 			panic(err)
 		}