Merge pull request #33 from fclairamb/switch-to-gokit

Replacing log15 by go-kit/log

Author: fclairamb

README.md

@@ -22,7 +22,7 @@ Note: this is a fork of [andrewarrow/paradise_ftp](https://github.com/andrewarro
  * Passive socket connections (EPSV and PASV commands)
  * Active socket connections (PORT command)
  * Small memory footprint
- * Only relies on the standard library except for logging which uses [log15](https://github.com/inconshreveable/log15) ([which could change](https://github.com/fclairamb/ftpserver/issues/7)).
+ * Only relies on the standard library except for logging which uses [go-kit log](https://github.com/go-kit/kit/tree/master/log).
  * Supported extensions:
    * [MDTM](https://tools.ietf.org/html/rfc3659#page-8) - File Modification Time
    * [MLST](https://tools.ietf.org/html/rfc3659#page-23) - Directory listing for maching processing

main.go

@@ -9,7 +9,8 @@ import (
 
 	"github.com/fclairamb/ftpserver/sample"
 	"github.com/fclairamb/ftpserver/server"
-	"gopkg.in/inconshreveable/log15.v2"
+	"github.com/go-kit/kit/log"
+	"github.com/go-kit/kit/log/level"
 )
 
 var (
@@ -18,13 +19,30 @@ var (
 
 func main() {
 	flag.Parse()
-	ftpServer = server.NewFtpServer(sample.NewSampleDriver())
+
+	logger := log.With(
+		log.NewLogfmtLogger(log.NewSyncWriter(os.Stdout)),
+		"ts", log.DefaultTimestampUTC,
+		"caller", log.DefaultCaller,
+	)
+
+	level.Info(logger).Log("msg", "Sample server")
+
+	driver, err := sample.NewSampleDriver()
+	if err != nil {
+		level.Error(logger).Log("msg", "Could not load the driver", "err", err)
+		return
+	}
+	driver.Logger = log.With(logger, "component", "driver")
+
+	ftpServer = server.NewFtpServer(driver)
+	ftpServer.Logger = log.With(logger, "component", "server")
 
 	go signalHandler()
 
-	err := ftpServer.ListenAndServe()
+	err = ftpServer.ListenAndServe()
 	if err != nil {
-		log15.Error("Problem listening", "err", err)
+		level.Error(logger).Log("msg", "Problem listening", "err", err)
 	}
 }
 

sample/sample_driver.go

@@ -13,12 +13,14 @@ import (
 	"time"
 
 	"github.com/fclairamb/ftpserver/server"
+	"github.com/go-kit/kit/log"
+	"github.com/go-kit/kit/log/level"
 	"github.com/naoina/toml"
-	"gopkg.in/inconshreveable/log15.v2"
 )
 
 // MainDriver defines a very basic serverftp driver
 type MainDriver struct {
+	Logger    log.Logger
 	baseDir   string
 	tlsConfig *tls.Config
 }
@@ -33,7 +35,7 @@ func (driver *MainDriver) WelcomeUser(cc server.ClientContext) (string, error) {
 // AuthUser authenticates the user and selects an handling driver
 func (driver *MainDriver) AuthUser(cc server.ClientContext, user, pass string) (server.ClientHandlingDriver, error) {
 	if user == "bad" || pass == "bad" {
-		return nil, errors.New("Bad username or password")
+		return nil, errors.New("bad username or password")
 	}
 
 	return driver, nil
@@ -42,7 +44,7 @@ func (driver *MainDriver) AuthUser(cc server.ClientContext, user, pass string) (
 // GetTLSConfig returns a TLS Certificate to use
 func (driver *MainDriver) GetTLSConfig() (*tls.Config, error) {
 	if driver.tlsConfig == nil {
-		log15.Info("Loading certificate")
+		level.Info(driver.Logger).Log("msg", "Loading certificate")
 		if cert, err := tls.LoadX509KeyPair("sample/certs/mycert.crt", "sample/certs/mycert.key"); err == nil {
 			driver.tlsConfig = &tls.Config{
 				NextProtos:   []string{"ftp"},
@@ -185,11 +187,11 @@ func (driver *MainDriver) GetSettings() *server.Settings {
 
 	// This is the new IP loading change coming from Ray
 	if config.PublicHost == "" {
-		log15.Debug("Fetching our external IP address...")
+		level.Debug(driver.Logger).Log("msg", "Fetching our external IP address...")
 		if config.PublicHost, err = externalIP(); err != nil {
-			log15.Warn("Couldn't fetch an external IP", "err", err)
+			level.Warn(driver.Logger).Log("msg", "Couldn't fetch an external IP", "err", err)
 		} else {
-			log15.Debug("Fetched our external IP address", "ipAddress", config.PublicHost)
+			level.Debug(driver.Logger).Log("msg", "Fetched our external IP address", "ipAddress", config.PublicHost)
 		}
 	}
 
@@ -199,17 +201,18 @@ func (driver *MainDriver) GetSettings() *server.Settings {
 // NewSampleDriver creates a sample driver
 // Note: This is not a mistake. Interface can be pointers. There seems to be a lot of confusion around this in the
 //       server_ftp original code.
-func NewSampleDriver() *MainDriver {
+func NewSampleDriver() (*MainDriver, error) {
 	dir, err := ioutil.TempDir("", "ftpserver")
 	if err != nil {
-		log15.Error("Could not find a temporary dir", "err", err)
+		return nil, fmt.Errorf("could not find a temporary dir, err: %v", err)
 	}
 
 	driver := &MainDriver{
 		baseDir: dir,
+		Logger:  log.NewNopLogger(),
 	}
 	os.MkdirAll(driver.baseDir, 0777)
-	return driver
+	return driver, nil
 }
 
 type virtualFile struct {

server/client_handler.go

@@ -9,7 +9,8 @@ import (
 	"strings"
 	"time"
 
-	"gopkg.in/inconshreveable/log15.v2"
+	"github.com/go-kit/kit/log"
+	"github.com/go-kit/kit/log/level"
 )
 
 type clientHandler struct {
@@ -29,21 +30,25 @@ type clientHandler struct {
 	debug       bool                 // Show debugging info on the server side
 	transfer    transferHandler      // Transfer connection (only passive is implemented at this stage)
 	transferTLS bool                 // Use TLS for transfer connection
+	logger      log.Logger           // Client handler logging
 }
 
 // newClientHandler initializes a client handler when someone connects
 func (server *FtpServer) newClientHandler(connection net.Conn) *clientHandler {
 
+	id := server.clientCounter
+
 	server.clientCounter++
 
 	p := &clientHandler{
 		daddy:       server,
 		conn:        connection,
-		ID:          server.clientCounter,
+		ID:          id,
 		writer:      bufio.NewWriter(connection),
 		reader:      bufio.NewReader(connection),
 		connectedAt: time.Now().UTC(),
 		path:        "/",
+		logger:      log.With(server.Logger, "clientId", id),
 	}
 
 	// Just respecting the existing logic here, this could be probably be dropped at some point
@@ -104,7 +109,7 @@ func (c *clientHandler) HandleCommands() {
 	for {
 		if c.reader == nil {
 			if c.debug {
-				log15.Debug("Clean disconnect", "action", "ftp.disconnect", "id", c.ID, "clean", true)
+				level.Debug(c.logger).Log(logKeyMsg, "Clean disconnect", logKeyAction, "ftp.disconnect", "clean", true)
 			}
 			return
 		}
@@ -114,16 +119,16 @@ func (c *clientHandler) HandleCommands() {
 		if err != nil {
 			if err == io.EOF {
 				if c.debug {
-					log15.Debug("TCP disconnect", "action", "ftp.disconnect", "id", c.ID, "clean", false)
+					level.Debug(c.logger).Log(logKeyMsg, "TCP disconnect", logKeyAction, "ftp.disconnect", "clean", false)
 				}
 			} else {
-				log15.Error("Read error", "action", "ftp.read_error", "id", c.ID, "err", err)
+				level.Error(c.logger).Log(logKeyMsg, "Read error", logKeyAction, "ftp.read_error", "err", err)
 			}
 			return
 		}
 
 		if c.debug {
-			log15.Debug("FTP RECV", "action", "ftp.cmd_recv", "id", c.ID, "line", line)
+			level.Debug(c.logger).Log(logKeyMsg, "FTP RECV", logKeyAction, "ftp.cmd_recv", "line", line)
 		}
 
 		c.handleCommand(line)
@@ -158,7 +163,7 @@ func (c *clientHandler) handleCommand(line string) {
 
 func (c *clientHandler) writeLine(line string) {
 	if c.debug {
-		log15.Debug("FTP SEND", "action", "ftp.cmd_send", "id", c.ID, "line", line)
+		level.Debug(c.logger).Log(logKeyMsg, "FTP SEND", logKeyAction, "ftp.cmd_send", "line", line)
 	}
 	c.writer.Write([]byte(line))
 	c.writer.Write([]byte("\r\n"))
@@ -177,7 +182,7 @@ func (c *clientHandler) TransferOpen() (net.Conn, error) {
 	c.writeMessage(150, "Using transfer connection")
 	conn, err := c.transfer.Open()
 	if err == nil && c.debug {
-		log15.Debug("FTP Transfer connection opened", "action", "ftp.transfer_open", "id", c.ID, "remoteAddr", conn.RemoteAddr().String(), "localAddr", conn.LocalAddr().String())
+		level.Debug(c.logger).Log(logKeyMsg, "FTP Transfer connection opened", logKeyAction, "ftp.transfer_open", "remoteAddr", conn.RemoteAddr().String(), "localAddr", conn.LocalAddr().String())
 	}
 	return conn, err
 }
@@ -188,7 +193,7 @@ func (c *clientHandler) TransferClose() {
 		c.transfer.Close()
 		c.transfer = nil
 		if c.debug {
-			log15.Debug("FTP Transfer connection closed", "action", "ftp.transfer_close", "id", c.ID)
+			level.Debug(c.logger).Log(logKeyMsg, "FTP Transfer connection closed", logKeyAction, "ftp.transfer_close")
 		}
 	}
 }

server/server.go

@@ -7,7 +7,15 @@ import (
 	"sync"
 	"time"
 
-	"gopkg.in/inconshreveable/log15.v2"
+	"github.com/go-kit/kit/log"
+	"github.com/go-kit/kit/log/level"
+)
+
+const (
+	// logKeyMsg is the human-readable part of the log
+	logKeyMsg = "msg"
+	// logKeyAction is the machine-readable part of the log
+	logKeyAction = "action"
 )
 
 // CommandDescription defines which function should be used and if it should be open to anyone or only logged in users
@@ -74,6 +82,7 @@ func init() {
 // FtpServer is where everything is stored
 // We want to keep it as simple as possible
 type FtpServer struct {
+	Logger           log.Logger                // Go-Kit logger
 	Settings         *Settings                 // General settings
 	Listener         net.Listener              // Listener used to receive files
 	StartTime        time.Time                 // Time when the server was started
@@ -114,11 +123,11 @@ func (server *FtpServer) Listen() error {
 	)
 
 	if err != nil {
-		log15.Error("Cannot listen", "err", err)
+		level.Error(server.Logger).Log(logKeyMsg, "Cannot listen", "err", err)
 		return err
 	}
 
-	log15.Info("Listening...", "address", server.Listener.Addr())
+	level.Info(server.Logger).Log(logKeyMsg, "Listening...", logKeyAction, "ftp.listening", "address", server.Listener.Addr())
 
 	return err
 }
@@ -129,7 +138,7 @@ func (server *FtpServer) Serve() {
 		connection, err := server.Listener.Accept()
 		if err != nil {
 			if server.Listener != nil {
-				log15.Error("Accept error", "err", err)
+				level.Error(server.Logger).Log(logKeyMsg, "Accept error", "err", err)
 			}
 			break
 		}
@@ -145,7 +154,7 @@ func (server *FtpServer) ListenAndServe() error {
 		return err
 	}
 
-	log15.Info("Starting...")
+	level.Info(server.Logger).Log(logKeyMsg, "Starting...", logKeyAction, "ftp.starting")
 
 	server.Serve()
 
@@ -160,6 +169,7 @@ func NewFtpServer(driver MainDriver) *FtpServer {
 		driver:          driver,
 		StartTime:       time.Now().UTC(), // Might make sense to put it in Start method
 		connectionsByID: make(map[uint32]*clientHandler),
+		Logger:          log.NewNopLogger(),
 	}
 }
 
@@ -180,10 +190,10 @@ func (server *FtpServer) clientArrival(c *clientHandler) error {
 	server.connectionsByID[c.ID] = c
 	nb := len(server.connectionsByID)
 
-	log15.Info("FTP Client connected", "action", "ftp.connected", "id", c.ID, "src", c.conn.RemoteAddr(), "total", nb)
+	level.Info(c.logger).Log(logKeyMsg, "FTP Client connected", logKeyAction, "ftp.connected", "clientIp", c.conn.RemoteAddr(), "total", nb)
 
 	if nb > server.Settings.MaxConnections {
-		return fmt.Errorf("Too many clients %d > %d", nb, server.Settings.MaxConnections)
+		return fmt.Errorf("too many clients %d > %d", nb, server.Settings.MaxConnections)
 	}
 
 	return nil
@@ -196,5 +206,5 @@ func (server *FtpServer) clientDeparture(c *clientHandler) {
 
 	delete(server.connectionsByID, c.ID)
 
-	log15.Info("FTP Client disconnected", "action", "ftp.disconnected", "id", c.ID, "src", c.conn.RemoteAddr(), "total", len(server.connectionsByID))
+	level.Info(c.logger).Log(logKeyMsg, "FTP Client disconnected", logKeyAction, "ftp.disconnected", "clientIp", c.conn.RemoteAddr(), "total", len(server.connectionsByID))
 }

server/transfer_active.go

@@ -69,7 +69,7 @@ func parseRemoteAddr(param string) (*net.TCPAddr, error) {
 	//TODO(mgenov): ensure that format of the params is valid
 	params := strings.Split(param, ",")
 	if len(params) != 6 {
-		return nil, errors.New("Bad number of args")
+		return nil, errors.New("bad number of args")
 	}
 	ip := strings.Join(params[0:4], ".")
 

server/transfer_pasv.go

@@ -8,7 +8,7 @@ import (
 	"strings"
 	"time"
 
-	"gopkg.in/inconshreveable/log15.v2"
+	"github.com/go-kit/kit/log/level"
 )
 
 // Active/Passive transfer connection handler
@@ -54,7 +54,7 @@ func (c *clientHandler) handlePASV() {
 	}
 
 	if err != nil {
-		log15.Error("Could not listen", "err", err)
+		level.Error(c.logger).Log(logKeyMsg, "Could not listen", "err", err)
 		return
 	}
 

tests/test_driver.go

@@ -54,7 +54,7 @@ func (driver *ServerDriver) AuthUser(cc server.ClientContext, user, pass string)
 	if user == "test" && pass == "test" {
 		return NewClientDriver(), nil
 	}
-	return nil, errors.New("Bad username or password")
+	return nil, errors.New("bad username or password")
 }
 
 // UserLeft is called when the user disconnects