Merge pull request #143 from fclairamb/feature/shutdown-logic-improve…

…ment

Stopping logic improvement

README.md

@@ -17,13 +17,13 @@ If you're interested in a fully featured FTP server, you should use [ftpserver](
  * File and directory deletion and renaming
  * TLS support (AUTH + PROT)
  * File download/upload resume support (REST)
- * Complete driver for all the above features
  * Passive socket connections (EPSV and PASV commands)
  * Active socket connections (PORT command)
  * Small memory footprint
- * Only relies on the standard library except for:
-   * [go-kit log](https://github.com/go-kit/kit/tree/master/log) for logging
+ * Clean code: No sync, no sleep, no panic
+ * Uses only the standard library except for:
    * [afero](https://github.com/spf13/afero) for generic file systems handling
+   * [go-kit log](https://github.com/go-kit/kit/tree/master/log) (optional) for logging
  * Supported extensions:
    * [AUTH](https://tools.ietf.org/html/rfc2228#page-6) - Control session protection
    * [AUTH TLS](https://tools.ietf.org/html/rfc4217#section-4.1) - TLS session

client_handler.go

@@ -48,16 +48,15 @@ func (server *FtpServer) newClientHandler(connection net.Conn, id uint32) *clien
 		logger:      server.Logger.With("clientId", id),
 	}
 
-	// Just respecting the existing logic here, this could be probably be dropped at some point
-
 	return p
 }
 
 func (c *clientHandler) disconnect() {
 	if err := c.conn.Close(); err != nil {
 		c.logger.Warn(
 			"Problem disconnecting a client",
-			"err", err)
+			"err", err,
+		)
 	}
 }
 
@@ -134,7 +133,7 @@ func (c *clientHandler) HandleCommands() {
 		if c.server.settings.IdleTimeout > 0 {
 			if err := c.conn.SetDeadline(
 				time.Now().Add(time.Duration(time.Second.Nanoseconds() * int64(c.server.settings.IdleTimeout)))); err != nil {
-				c.logger.Error("Network error", err)
+				c.logger.Error("Network error", "err", err)
 			}
 		}
 
@@ -160,7 +159,7 @@ func (c *clientHandler) handleCommandsStreamError(err error) {
 		if err.Timeout() {
 			// We have to extend the deadline now
 			if err := c.conn.SetDeadline(time.Now().Add(time.Minute)); err != nil {
-				c.logger.Error("Could not set read deadline", err)
+				c.logger.Error("Could not set read deadline", "err", err)
 			}
 
 			c.logger.Info("Client IDLE timeout", "err", err)
@@ -169,24 +168,24 @@ func (c *clientHandler) handleCommandsStreamError(err error) {
 				fmt.Sprintf("command timeout (%d seconds): closing control connection", c.server.settings.IdleTimeout))
 
 			if err := c.writer.Flush(); err != nil {
-				c.logger.Error("Flush error", err)
+				c.logger.Error("Flush error", "err", err)
 			}
 
 			if err := c.conn.Close(); err != nil {
-				c.logger.Error("Close error", err)
+				c.logger.Error("Close error", "err", err)
 			}
 
 			break
 		}
 
-		c.logger.Error("Network error", err)
+		c.logger.Error("Network error", "err", err)
 	default:
 		if err == io.EOF {
 			if c.debug {
 				c.logger.Debug("Client disconnected", "clean", false)
 			}
 		} else {
-			c.logger.Error("Read error", err)
+			c.logger.Error("Read error", "err", err)
 		}
 	}
 }
@@ -212,6 +211,12 @@ func (c *clientHandler) handleCommand(line string) {
 	defer func() {
 		if r := recover(); r != nil {
 			c.writeMessage(StatusSyntaxErrorNotRecognised, fmt.Sprintf("Unhandled internal error: %s", r))
+			c.logger.Warn(
+				"Internal command handling error",
+				"err", r,
+				"command", c.command,
+				"param", c.param,
+			)
 		}
 	}()
 
@@ -294,7 +299,6 @@ func parseLine(line string) (string, string) {
 	return params[0], params[1]
 }
 
-// For future use
 func (c *clientHandler) multilineAnswer(code int, message string) func() {
 	c.writeLine(fmt.Sprintf("%d-%s", code, message))
 

client_handler_test.go

@@ -10,7 +10,7 @@ import (
 
 func TestConcurrency(t *testing.T) {
 	s := NewTestServer(false)
-	defer s.Stop()
+	defer mustStopServer(s)
 
 	nbClients := 100
 

consts.go

@@ -2,7 +2,7 @@
 package ftpserver
 
 // from @stevenh's PR proposal
-// https://github.com/fclairamb/ftpserver/blob/becc125a0770e3b670c4ced7e7bd12594fb024ff/server/consts.go
+// https://github.com/fclairamb/ftpserverlib/blob/becc125a0770e3b670c4ced7e7bd12594fb024ff/server/consts.go
 
 // Status codes as documented by:
 // https://tools.ietf.org/html/rfc959

driver.go

@@ -86,7 +86,7 @@ type Settings struct {
 	ListenAddr               string           // Listening address
 	PublicHost               string           // Public IP to expose (only an IP address is accepted at this stage)
 	PublicIPResolver         PublicIPResolver // (Optional) To fetch a public IP lookup
-	PassiveTransferPortRange *PortRange       // Port Range for data connections. Random if not specified
+	PassiveTransferPortRange *PortRange       // (Optional) Port Range for data connections. Random if not specified
 	ActiveTransferPortNon20  bool             // Do not impose the port 20 for active data transfer (#88, RFC 1579)
 	IdleTimeout              int              // Maximum inactivity time before disconnecting (#58)
 	ConnectionTimeout        int              // Maximum time to establish passive or active transfer connections

driver_test.go

@@ -4,13 +4,14 @@ import (
 	"crypto/tls"
 	"errors"
 	"fmt"
+	"io"
 	"io/ioutil"
 	"os"
 
 	gklog "github.com/go-kit/kit/log"
 	"github.com/spf13/afero"
 
-	"github.com/fclairamb/ftpserverlib/log"
+	"github.com/fclairamb/ftpserverlib/log/gokit"
 )
 
 const (
@@ -38,17 +39,21 @@ func NewTestServerWithDriver(driver *TestServerDriver) *FtpServer {
 
 	// If we are in debug mode, we should log things
 	if driver.Debug {
-		s.Logger = log.NewGKLogger(gklog.NewLogfmtLogger(gklog.NewSyncWriter(os.Stdout))).With(
-			"ts", log.GKDefaultTimestampUTC,
-			"caller", log.GKDefaultCaller,
+		s.Logger = gokit.NewGKLogger(gklog.NewLogfmtLogger(gklog.NewSyncWriter(os.Stdout))).With(
+			"ts", gokit.GKDefaultTimestampUTC,
+			"caller", gokit.GKDefaultCaller,
 		)
 	}
 
 	if err := s.Listen(); err != nil {
 		return nil
 	}
 
-	go s.Serve()
+	go func() {
+		if err := s.Serve(); err != nil && err != io.EOF {
+			s.Logger.Error("problem serving", "err", err)
+		}
+	}()
 
 	return s
 }
@@ -81,6 +86,13 @@ func NewTestClientDriver() *TestClientDriver {
 	}
 }
 
+func mustStopServer(server *FtpServer) {
+	err := server.Stop()
+	if err != nil {
+		panic(err)
+	}
+}
+
 // ClientConnected is the very first message people will see
 func (driver *TestServerDriver) ClientConnected(cc ClientContext) (string, error) {
 	cc.SetDebug(driver.Debug)

handle_auth_test.go

@@ -22,7 +22,7 @@ func reportError(err error) {
 
 func TestLoginSuccess(t *testing.T) {
 	s := NewTestServer(true)
-	defer s.Stop()
+	defer mustStopServer(s)
 
 	var err error
 
@@ -55,7 +55,7 @@ func TestLoginSuccess(t *testing.T) {
 
 func TestLoginFailure(t *testing.T) {
 	s := NewTestServer(true)
-	defer s.Stop()
+	defer mustStopServer(s)
 
 	var err error
 
@@ -77,7 +77,7 @@ func TestAuthTLS(t *testing.T) {
 		Debug: true,
 		TLS:   true,
 	})
-	defer s.Stop()
+	defer mustStopServer(s)
 
 	ftp, err := goftp.Connect(s.Addr())
 	if err != nil {

handle_dirs.go

@@ -141,7 +141,7 @@ func (c *clientHandler) handleMLSD() error {
 	// TODO: We have a lot of copy/paste around directory listing, we should refactor this.
 	defer func() {
 		if errClose := directory.Close(); errClose != nil {
-			c.logger.Error("Couldn't close directory", errClose, "directory", directoryPath)
+			c.logger.Error("Couldn't close directory", "err", errClose, "directory", directoryPath)
 		}
 	}()
 

handle_dirs_test.go

@@ -13,7 +13,7 @@ const DirKnown = "known"
 // TestDirAccess relies on LIST of files listing
 func TestDirListing(t *testing.T) {
 	s := NewTestServerWithDriver(&TestServerDriver{Debug: true, Settings: &Settings{DisableMLSD: true}})
-	defer s.Stop()
+	defer mustStopServer(s)
 
 	var connErr error
 
@@ -59,7 +59,7 @@ func TestDirListing(t *testing.T) {
 
 func TestDirListingPathArg(t *testing.T) {
 	s := NewTestServerWithDriver(&TestServerDriver{Debug: true, Settings: &Settings{DisableMLSD: true}})
-	defer s.Stop()
+	defer mustStopServer(s)
 
 	var connErr error
 
@@ -123,7 +123,7 @@ func TestDirListingPathArg(t *testing.T) {
 // TestDirAccess relies on LIST of files listing
 func TestDirHandling(t *testing.T) {
 	s := NewTestServer(true)
-	defer s.Stop()
+	defer mustStopServer(s)
 
 	var connErr error
 
@@ -186,7 +186,7 @@ func TestDirHandling(t *testing.T) {
 // TestDirListingWithSpace uses the MLSD for files listing
 func TestDirListingWithSpace(t *testing.T) {
 	s := NewTestServer(true)
-	defer s.Stop()
+	defer mustStopServer(s)
 
 	var connErr error
 
@@ -237,7 +237,7 @@ func TestDirListingWithSpace(t *testing.T) {
 
 func TestCleanPath(t *testing.T) {
 	s := NewTestServer(true)
-	defer s.Stop()
+	defer mustStopServer(s)
 
 	var connErr error
 

handle_files.go

@@ -219,8 +219,8 @@ func (c *clientHandler) handleSTATFile() error {
 	path := c.absPath(c.param)
 
 	if info, err := c.driver.Stat(path); err == nil {
-		m := c.multilineAnswer(StatusSystemStatus, "System status")
-		defer m()
+		defer c.multilineAnswer(StatusSystemStatus, "System status")()
+
 		// c.writeLine(fmt.Sprintf("%d-Status follows:", StatusSystemStatus))
 		if info.IsDir() {
 			directory, errOpenFile := c.driver.Open(c.absPath(c.param))
@@ -254,8 +254,7 @@ func (c *clientHandler) handleMLST() error {
 	path := c.absPath(c.param)
 
 	if info, err := c.driver.Stat(path); err == nil {
-		m := c.multilineAnswer(StatusFileOK, "File details")
-		defer m()
+		defer c.multilineAnswer(StatusFileOK, "File details")()
 
 		if errWrite := c.writeMLSxOutput(c.writer, info); errWrite != nil {
 			return errWrite

handle_files_test.go

@@ -76,7 +76,7 @@ func TestMLSxEntryValidation(t *testing.T) {
 
 func TestALLO(t *testing.T) {
 	s := NewTestServer(true)
-	defer s.Stop()
+	defer mustStopServer(s)
 
 	conf := goftp.Config{
 		User:     "test",
@@ -112,7 +112,7 @@ func TestALLO(t *testing.T) {
 
 func TestCHOWN(t *testing.T) {
 	s := NewTestServer(true)
-	defer s.Stop()
+	defer mustStopServer(s)
 
 	conf := goftp.Config{
 		User:     "test",

handle_misc.go

@@ -68,8 +68,7 @@ func (c *clientHandler) handleSITE() error {
 }
 
 func (c *clientHandler) handleSTATServer() error {
-	m := c.multilineAnswer(StatusFileStatus, "Server status")
-	defer m()
+	defer c.multilineAnswer(StatusFileStatus, "Server status")()
 
 	duration := time.Now().UTC().Sub(c.connectedAt)
 	duration -= duration % time.Second

handle_misc_test.go

@@ -11,7 +11,7 @@ import (
 
 func TestSiteCommand(t *testing.T) {
 	s := NewTestServer(true)
-	defer s.Stop()
+	defer mustStopServer(s)
 
 	conf := goftp.Config{
 		User:     "test",
@@ -49,7 +49,7 @@ func TestSiteCommand(t *testing.T) {
 // florent(2018-01-14): #58: IDLE timeout: Testing timeout
 func TestIdleTimeout(t *testing.T) {
 	s := NewTestServerWithDriver(&TestServerDriver{Debug: true, Settings: &Settings{IdleTimeout: 2}})
-	defer s.Stop()
+	defer mustStopServer(s)
 
 	conf := goftp.Config{
 		User:     "test",
@@ -87,7 +87,7 @@ func TestIdleTimeout(t *testing.T) {
 
 func TestStat(t *testing.T) {
 	s := NewTestServer(true)
-	defer s.Stop()
+	defer mustStopServer(s)
 
 	conf := goftp.Config{
 		User:     "test",
@@ -125,7 +125,7 @@ func TestStat(t *testing.T) {
 
 func TestCLNT(t *testing.T) {
 	s := NewTestServer(true)
-	defer s.Stop()
+	defer mustStopServer(s)
 
 	conf := goftp.Config{
 		User:     "test",