diff --git a/README.md b/README.md index 1344f56a..9997f52f 100644 --- a/README.md +++ b/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 diff --git a/client_handler.go b/client_handler.go index 8e17b5cd..9cf7f9a8 100644 --- a/client_handler.go +++ b/client_handler.go @@ -48,8 +48,6 @@ 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 } @@ -57,7 +55,8 @@ 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)) diff --git a/client_handler_test.go b/client_handler_test.go index 628fb1e9..b3fc7c91 100644 --- a/client_handler_test.go +++ b/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 diff --git a/consts.go b/consts.go index 041e6024..73cd6c63 100644 --- a/consts.go +++ b/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 diff --git a/driver.go b/driver.go index 9e44ed96..3cad006f 100644 --- a/driver.go +++ b/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 diff --git a/driver_test.go b/driver_test.go index 386faa5f..0f4c091c 100644 --- a/driver_test.go +++ b/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,9 +39,9 @@ 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, ) } @@ -48,7 +49,11 @@ func NewTestServerWithDriver(driver *TestServerDriver) *FtpServer { 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) diff --git a/handle_auth_test.go b/handle_auth_test.go index 5e8b1c27..8626bd2a 100644 --- a/handle_auth_test.go +++ b/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 { diff --git a/handle_dirs.go b/handle_dirs.go index abae4c60..a2f781b5 100644 --- a/handle_dirs.go +++ b/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) } }() diff --git a/handle_dirs_test.go b/handle_dirs_test.go index a6f57413..b1f95650 100644 --- a/handle_dirs_test.go +++ b/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 diff --git a/handle_files.go b/handle_files.go index fb10a3a3..5935bf4f 100644 --- a/handle_files.go +++ b/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 diff --git a/handle_files_test.go b/handle_files_test.go index da77e3fd..a71c9b5a 100644 --- a/handle_files_test.go +++ b/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", diff --git a/handle_misc.go b/handle_misc.go index c7de80ed..b2bdea22 100644 --- a/handle_misc.go +++ b/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 diff --git a/handle_misc_test.go b/handle_misc_test.go index e63ec2e1..d4febb01 100644 --- a/handle_misc_test.go +++ b/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", diff --git a/log/go-kit.go b/log/gokit/go-kit.go similarity index 77% rename from log/go-kit.go rename to log/gokit/go-kit.go index 6a7d300f..3f5dfc35 100644 --- a/log/go-kit.go +++ b/log/gokit/go-kit.go @@ -1,11 +1,13 @@ -// Package log provides a simple interface to handle logging -package log +// Package gokit provides go-kit Logger implementation +package gokit import ( "fmt" gklog "github.com/go-kit/kit/log" gklevel "github.com/go-kit/kit/log/level" + + "github.com/fclairamb/ftpserverlib/log" ) func (logger *gKLogger) checkError(err error) { @@ -35,28 +37,22 @@ func (logger *gKLogger) Warn(event string, keyvals ...interface{}) { } // Error logs key-values at error level -func (logger *gKLogger) Error(event string, err error, keyvals ...interface{}) { - keyvals = append(keyvals, "err", err) +func (logger *gKLogger) Error(event string, keyvals ...interface{}) { logger.log(gklevel.Error(logger.logger), event, keyvals...) } // With adds key-values -func (logger *gKLogger) With(keyvals ...interface{}) Logger { +func (logger *gKLogger) With(keyvals ...interface{}) log.Logger { return NewGKLogger(gklog.With(logger.logger, keyvals...)) } // NewGKLogger creates a logger based on go-kit logs -func NewGKLogger(logger gklog.Logger) Logger { +func NewGKLogger(logger gklog.Logger) log.Logger { return &gKLogger{ logger: logger, } } -// NewNopGKLogger instantiates go-kit logger -func NewNopGKLogger() Logger { - return NewGKLogger(gklog.NewNopLogger()) -} - type gKLogger struct { logger gklog.Logger } diff --git a/log/log_test.go b/log/gokit/log_test.go similarity index 60% rename from log/log_test.go rename to log/gokit/log_test.go index 54fd874a..e9994317 100644 --- a/log/log_test.go +++ b/log/gokit/log_test.go @@ -1,17 +1,18 @@ -package log +package gokit import ( "os" "testing" - "github.com/go-kit/kit/log" gklog "github.com/go-kit/kit/log" + + "github.com/fclairamb/ftpserverlib/log" ) -func getLogger() Logger { +func getLogger() log.Logger { return NewGKLogger(gklog.NewLogfmtLogger(gklog.NewSyncWriter(os.Stdout))).With( - "ts", log.DefaultTimestampUTC, - "caller", log.DefaultCaller, + "ts", gklog.DefaultTimestampUTC, + "caller", gklog.DefaultCaller, ) } diff --git a/log/log.go b/log/log.go index c37aba6c..65a1df04 100644 --- a/log/log.go +++ b/log/log.go @@ -3,10 +3,42 @@ package log // Logger interface type Logger interface { - // log(keyvals ...interface{}) + + // Debug logging: Every details Debug(event string, keyvals ...interface{}) + + // Info logging: Core events Info(event string, keyvals ...interface{}) + + // Warning logging: Anything out of the ordinary but non-life threatening Warn(event string, keyvals ...interface{}) - Error(event string, err error, keyvals ...interface{}) + + // Error logging: Major issue + Error(event string, keyvals ...interface{}) + + // Context extending interface With(keyvals ...interface{}) Logger } + +// Nothing creates a no-op logger +func Nothing() Logger { + return &noLogger{} +} + +type noLogger struct{} + +func (nl *noLogger) Debug(string, ...interface{}) { +} + +func (nl *noLogger) Info(string, ...interface{}) { +} + +func (nl *noLogger) Warn(string, ...interface{}) { +} + +func (nl *noLogger) Error(string, ...interface{}) { +} + +func (nl *noLogger) With(...interface{}) Logger { + return nl +} diff --git a/server.go b/server.go index a6d81c0d..c87805c5 100644 --- a/server.go +++ b/server.go @@ -2,17 +2,16 @@ package ftpserver import ( + "errors" "fmt" "net" "github.com/fclairamb/ftpserverlib/log" ) -const ( -// logKeyMsg is the human-readable part of the log -// logKeyMsg = "msg" -// logKeyAction is the machine-readable part of the log -// logKeyAction = "action" +var ( + // ErrNotListening is returned when we are performing an action that is only valid while listening + ErrNotListening = errors.New("we aren't listening") ) // CommandDescription defines which function should be used and if it should be open to anyone or only logged in users @@ -118,13 +117,15 @@ func (server *FtpServer) Listen() error { return fmt.Errorf("could not load settings: %v", err) } + // The driver can provide its own listener implementation if server.settings.Listener != nil { server.listener = server.settings.Listener } else { + // Otherwise, it's what we currently use server.listener, err = net.Listen("tcp", server.settings.ListenAddr) if err != nil { - server.Logger.Error("Cannot listen", err) + server.Logger.Error("Cannot listen", "err", err) return err } } @@ -135,15 +136,22 @@ func (server *FtpServer) Listen() error { } // Serve accepts and processes any new incoming client -func (server *FtpServer) Serve() { +func (server *FtpServer) Serve() error { for { connection, err := server.listener.Accept() + if err != nil { - if server.listener != nil { - server.Logger.Error("Listener accept error", err) + if errOp, ok := err.(*net.OpError); ok { + // This means we just closed the connection and it's OK + if errOp.Err.Error() == "use of closed network connection" { + server.listener = nil + return nil + } } - break + server.Logger.Error("Listener accept error", "err", err) + + return err } server.clientArrival(connection) @@ -158,18 +166,14 @@ func (server *FtpServer) ListenAndServe() error { server.Logger.Info("Starting...") - server.Serve() - - // At this precise time, the clients are still connected. We are just not accepting clients anymore. - - return nil + return server.Serve() } // NewFtpServer creates a new FtpServer instance func NewFtpServer(driver MainDriver) *FtpServer { return &FtpServer{ driver: driver, - Logger: log.NewNopGKLogger(), + Logger: log.Nothing(), } } @@ -183,15 +187,20 @@ func (server *FtpServer) Addr() string { } // Stop closes the listener -func (server *FtpServer) Stop() { - if server.listener != nil { - if err := server.listener.Close(); err != nil { - server.Logger.Warn( - "Could not close listener", - "err", err, - ) - } +func (server *FtpServer) Stop() error { + if server.listener == nil { + return ErrNotListening + } + + err := server.listener.Close() + if err != nil { + server.Logger.Warn( + "Could not close listener", + "err", err, + ) } + + return err } // When a client connects, the server could refuse the connection diff --git a/transfer_pasv.go b/transfer_pasv.go index 01e23054..7a8da33b 100644 --- a/transfer_pasv.go +++ b/transfer_pasv.go @@ -68,7 +68,7 @@ func (c *clientHandler) findListenerWithinPortRange(portRange *PortRange) (*net. laddr, errResolve := net.ResolveTCPAddr("tcp", fmt.Sprintf("0.0.0.0:%d", port)) if errResolve != nil { - c.logger.Error("Problem resolving local port", errResolve, "port", port) + c.logger.Error("Problem resolving local port", "err", errResolve, "port", port) return nil, fmt.Errorf("could not resolve port: %d", port) } @@ -104,7 +104,7 @@ func (c *clientHandler) handlePASV() error { } if err != nil { - c.logger.Error("Could not listen for passive connection", err) + c.logger.Error("Could not listen for passive connection", "err", err) return nil } diff --git a/transfer_test.go b/transfer_test.go index 8acd7cbd..f61a9969 100644 --- a/transfer_test.go +++ b/transfer_test.go @@ -106,7 +106,7 @@ func ftpDelete(t *testing.T, ftp *goftp.Client, filename string) { // TestTransfer validates the upload of file in both active and passive mode func TestTransfer(t *testing.T) { s := NewTestServerWithDriver(&TestServerDriver{Debug: true, Settings: &Settings{ActiveTransferPortNon20: true}}) - defer s.Stop() + defer mustStopServer(s) testTransferOnConnection(t, s, false) testTransferOnConnection(t, s, true) @@ -150,7 +150,7 @@ func testTransferOnConnection(t *testing.T, server *FtpServer, active bool) { // TestFailedTransfer validates the handling of failed transfer caused by file access issues func TestFailedTransfer(t *testing.T) { s := NewTestServer(true) - defer s.Stop() + defer mustStopServer(s) conf := goftp.Config{ User: "test", @@ -185,7 +185,7 @@ func TestFailedFileClose(t *testing.T) { } s := NewTestServerWithDriver(driver) - defer s.Stop() + defer mustStopServer(s) conf := goftp.Config{ User: "test",