X-Git-Url: https://git.r.bdr.sh/rbdr/mobius/blobdiff_plain/590974641fde819128297803a12cfd4c744283a8..a6216dd89252fa01dc176f98f1e4ecfd3f637566:/hotline/server.go diff --git a/hotline/server.go b/hotline/server.go index fd8bda6..f2a69ad 100644 --- a/hotline/server.go +++ b/hotline/server.go @@ -8,17 +8,18 @@ import ( "errors" "fmt" "github.com/go-playground/validator/v10" - "go.uber.org/zap" + "golang.org/x/text/encoding/charmap" "gopkg.in/yaml.v3" "io" "io/fs" - "io/ioutil" + "log" + "log/slog" "math/big" "math/rand" "net" "os" + "path" "path/filepath" - "runtime/debug" "strings" "sync" "time" @@ -30,40 +31,44 @@ var contextKeyReq = contextKey("req") type requestCtx struct { remoteAddr string - login string - name string } -const ( - userIdleSeconds = 300 // time in seconds before an inactive user is marked idle - idleCheckInterval = 10 // time in seconds to check for idle users - trackerUpdateFrequency = 300 // time in seconds between tracker re-registration -) +// Converts bytes from Mac Roman encoding to UTF-8 +var txtDecoder = charmap.Macintosh.NewDecoder() -var nostalgiaVersion = []byte{0, 0, 2, 0x2c} // version ID used by the Nostalgia client +// Converts bytes from UTF-8 to Mac Roman encoding +var txtEncoder = charmap.Macintosh.NewEncoder() type Server struct { - Port int - Accounts map[string]*Account - Agreement []byte - Clients map[uint16]*ClientConn - ThreadedNews *ThreadedNews - + NetInterface string + Port int + Accounts map[string]*Account + Agreement []byte + Clients map[uint16]*ClientConn fileTransfers map[[4]byte]*FileTransfer - Config *Config - ConfigDir string - Logger *zap.SugaredLogger - PrivateChats map[uint32]*PrivateChat + Config *Config + ConfigDir string + Logger *slog.Logger + banner []byte + + PrivateChatsMu sync.Mutex + PrivateChats map[uint32]*PrivateChat + NextGuestID *uint16 TrackerPassID [4]byte - Stats *Stats + + StatsMu sync.Mutex + Stats *Stats FS FileStore // Storage backend to use for File storage outbox chan Transaction mux sync.Mutex + threadedNewsMux sync.Mutex + ThreadedNews *ThreadedNews + flatNewsMux sync.Mutex FlatNews []byte @@ -71,39 +76,48 @@ type Server struct { banList map[string]*time.Time } +func (s *Server) CurrentStats() Stats { + s.StatsMu.Lock() + defer s.StatsMu.Unlock() + + stats := s.Stats + stats.CurrentlyConnected = len(s.Clients) + + return *stats +} + type PrivateChat struct { Subject string ClientConn map[uint16]*ClientConn } func (s *Server) ListenAndServe(ctx context.Context, cancelRoot context.CancelFunc) error { - s.Logger.Infow("Hotline server started", + s.Logger.Info("Hotline server started", "version", VERSION, - "API port", fmt.Sprintf(":%v", s.Port), - "Transfer port", fmt.Sprintf(":%v", s.Port+1), + "API port", fmt.Sprintf("%s:%v", s.NetInterface, s.Port), + "Transfer port", fmt.Sprintf("%s:%v", s.NetInterface, s.Port+1), ) var wg sync.WaitGroup wg.Add(1) go func() { - ln, err := net.Listen("tcp", fmt.Sprintf("%s:%v", "", s.Port)) + ln, err := net.Listen("tcp", fmt.Sprintf("%s:%v", s.NetInterface, s.Port)) if err != nil { - s.Logger.Fatal(err) + log.Fatal(err) } - s.Logger.Fatal(s.Serve(ctx, ln)) + log.Fatal(s.Serve(ctx, ln)) }() wg.Add(1) go func() { - ln, err := net.Listen("tcp", fmt.Sprintf("%s:%v", "", s.Port+1)) + ln, err := net.Listen("tcp", fmt.Sprintf("%s:%v", s.NetInterface, s.Port+1)) if err != nil { - s.Logger.Fatal(err) - + log.Fatal(err) } - s.Logger.Fatal(s.ServeFileTransfers(ctx, ln)) + log.Fatal(s.ServeFileTransfers(ctx, ln)) }() wg.Wait() @@ -129,7 +143,7 @@ func (s *Server) ServeFileTransfers(ctx context.Context, ln net.Listener) error ) if err != nil { - s.Logger.Errorw("file transfer error", "reason", err) + s.Logger.Error("file transfer error", "reason", err) } }() } @@ -143,18 +157,18 @@ func (s *Server) sendTransaction(t Transaction) error { s.mux.Lock() client := s.Clients[uint16(clientID)] + s.mux.Unlock() if client == nil { return fmt.Errorf("invalid client id %v", *t.clientID) } - s.mux.Unlock() - b, err := t.MarshalBinary() if err != nil { return err } - if _, err := client.Connection.Write(b); err != nil { + _, err = client.Connection.Write(b) + if err != nil { return err } @@ -166,7 +180,7 @@ func (s *Server) processOutbox() { t := <-s.outbox go func() { if err := s.sendTransaction(t); err != nil { - s.Logger.Errorw("error sending transaction", "err", err) + s.Logger.Error("error sending transaction", "err", err) } }() } @@ -178,21 +192,21 @@ func (s *Server) Serve(ctx context.Context, ln net.Listener) error { for { conn, err := ln.Accept() if err != nil { - s.Logger.Errorw("error accepting connection", "err", err) + s.Logger.Error("error accepting connection", "err", err) } connCtx := context.WithValue(ctx, contextKeyReq, requestCtx{ remoteAddr: conn.RemoteAddr().String(), }) go func() { - s.Logger.Infow("Connection established", "RemoteAddr", conn.RemoteAddr()) + s.Logger.Info("Connection established", "RemoteAddr", conn.RemoteAddr()) defer conn.Close() if err := s.handleNewConnection(connCtx, conn, conn.RemoteAddr().String()); err != nil { if err == io.EOF { - s.Logger.Infow("Client disconnected", "RemoteAddr", conn.RemoteAddr()) + s.Logger.Info("Client disconnected", "RemoteAddr", conn.RemoteAddr()) } else { - s.Logger.Errorw("error serving request", "RemoteAddr", conn.RemoteAddr(), "err", err) + s.Logger.Error("error serving request", "RemoteAddr", conn.RemoteAddr(), "err", err) } } }() @@ -204,8 +218,9 @@ const ( ) // NewServer constructs a new Server from a config dir -func NewServer(configDir string, netPort int, logger *zap.SugaredLogger, FS FileStore) (*Server, error) { +func NewServer(configDir, netInterface string, netPort int, logger *slog.Logger, fs FileStore) (*Server, error) { server := Server{ + NetInterface: netInterface, Port: netPort, Accounts: make(map[string]*Account), Config: new(Config), @@ -216,9 +231,9 @@ func NewServer(configDir string, netPort int, logger *zap.SugaredLogger, FS File Logger: logger, NextGuestID: new(uint16), outbox: make(chan Transaction), - Stats: &Stats{StartTime: time.Now()}, + Stats: &Stats{Since: time.Now()}, ThreadedNews: &ThreadedNews{}, - FS: FS, + FS: fs, banList: make(map[string]*time.Time), } @@ -253,12 +268,20 @@ func NewServer(configDir string, netPort int, logger *zap.SugaredLogger, FS File return nil, err } - server.Config.FileRoot = filepath.Join(configDir, "Files") + // If the FileRoot is an absolute path, use it, otherwise treat as a relative path to the config dir. + if !filepath.IsAbs(server.Config.FileRoot) { + server.Config.FileRoot = filepath.Join(configDir, server.Config.FileRoot) + } + + server.banner, err = os.ReadFile(filepath.Join(server.ConfigDir, server.Config.BannerFile)) + if err != nil { + return nil, fmt.Errorf("error opening banner: %w", err) + } *server.NextGuestID = 1 if server.Config.EnableTrackerRegistration { - server.Logger.Infow( + server.Logger.Info( "Tracker registration enabled", "frequency", fmt.Sprintf("%vs", trackerUpdateFrequency), "trackers", server.Config.Trackers, @@ -268,16 +291,16 @@ func NewServer(configDir string, netPort int, logger *zap.SugaredLogger, FS File for { tr := &TrackerRegistration{ UserCount: server.userCount(), - PassID: server.TrackerPassID[:], + PassID: server.TrackerPassID, Name: server.Config.Name, Description: server.Config.Description, } binary.BigEndian.PutUint16(tr.Port[:], uint16(server.Port)) for _, t := range server.Config.Trackers { if err := register(t, tr); err != nil { - server.Logger.Errorw("unable to register with tracker %v", "error", err) + server.Logger.Error("unable to register with tracker %v", "error", err) } - server.Logger.Infow("Sent Tracker registration", "data", tr) + server.Logger.Debug("Sent Tracker registration", "addr", t) } time.Sleep(trackerUpdateFrequency * time.Second) @@ -308,16 +331,16 @@ func (s *Server) keepaliveHandler() { if c.IdleTime > userIdleSeconds && !c.Idle { c.Idle = true - flagBitmap := big.NewInt(int64(binary.BigEndian.Uint16(*c.Flags))) - flagBitmap.SetBit(flagBitmap, userFlagAway, 1) - binary.BigEndian.PutUint16(*c.Flags, uint16(flagBitmap.Int64())) + flagBitmap := big.NewInt(int64(binary.BigEndian.Uint16(c.Flags))) + flagBitmap.SetBit(flagBitmap, UserFlagAway, 1) + binary.BigEndian.PutUint16(c.Flags, uint16(flagBitmap.Int64())) c.sendAll( - tranNotifyChangeUser, - NewField(fieldUserID, *c.ID), - NewField(fieldUserFlags, *c.Flags), - NewField(fieldUserName, c.UserName), - NewField(fieldUserIconID, *c.Icon), + TranNotifyChangeUser, + NewField(FieldUserID, *c.ID), + NewField(FieldUserFlags, c.Flags), + NewField(FieldUserName, c.UserName), + NewField(FieldUserIconID, c.Icon), ) } } @@ -333,7 +356,7 @@ func (s *Server) writeBanList() error { if err != nil { return err } - err = ioutil.WriteFile( + err = os.WriteFile( filepath.Join(s.ConfigDir, "Banlist.yaml"), out, 0666, @@ -342,14 +365,14 @@ func (s *Server) writeBanList() error { } func (s *Server) writeThreadedNews() error { - s.mux.Lock() - defer s.mux.Unlock() + s.threadedNewsMux.Lock() + defer s.threadedNewsMux.Unlock() out, err := yaml.Marshal(s.ThreadedNews) if err != nil { return err } - err = ioutil.WriteFile( + err = s.FS.WriteFile( filepath.Join(s.ConfigDir, "ThreadedNews.yaml"), out, 0666, @@ -363,23 +386,21 @@ func (s *Server) NewClientConn(conn io.ReadWriteCloser, remoteAddr string) *Clie clientConn := &ClientConn{ ID: &[]byte{0, 0}, - Icon: &[]byte{0, 0}, - Flags: &[]byte{0, 0}, + Icon: []byte{0, 0}, + Flags: []byte{0, 0}, UserName: []byte{}, Connection: conn, Server: s, - Version: &[]byte{}, + Version: []byte{}, AutoReply: []byte{}, - transfers: map[int]map[[4]byte]*FileTransfer{}, - Agreed: false, RemoteAddr: remoteAddr, - } - clientConn.transfers = map[int]map[[4]byte]*FileTransfer{ - FileDownload: {}, - FileUpload: {}, - FolderDownload: {}, - FolderUpload: {}, - bannerDownload: {}, + transfers: map[int]map[[4]byte]*FileTransfer{ + FileDownload: {}, + FileUpload: {}, + FolderDownload: {}, + FolderUpload: {}, + bannerDownload: {}, + }, } *s.NextGuestID++ @@ -392,7 +413,7 @@ func (s *Server) NewClientConn(conn io.ReadWriteCloser, remoteAddr string) *Clie } // NewUser creates a new user account entry in the server map and config file -func (s *Server) NewUser(login, name, password string, access []byte) error { +func (s *Server) NewUser(login, name, password string, access accessBitmap) error { s.mux.Lock() defer s.mux.Unlock() @@ -400,33 +421,51 @@ func (s *Server) NewUser(login, name, password string, access []byte) error { Login: login, Name: name, Password: hashAndSalt([]byte(password)), - Access: &access, + Access: access, } out, err := yaml.Marshal(&account) if err != nil { return err } + + // Create account file, returning an error if one already exists. + file, err := os.OpenFile( + filepath.Join(s.ConfigDir, "Users", path.Join("/", login)+".yaml"), + os.O_CREATE|os.O_EXCL|os.O_WRONLY, + 0644, + ) + if err != nil { + return err + } + defer file.Close() + + _, err = file.Write(out) + if err != nil { + return fmt.Errorf("error writing account file: %w", err) + } + s.Accounts[login] = &account - return s.FS.WriteFile(filepath.Join(s.ConfigDir, "Users", login+".yaml"), out, 0666) + return nil } -func (s *Server) UpdateUser(login, newLogin, name, password string, access []byte) error { +func (s *Server) UpdateUser(login, newLogin, name, password string, access accessBitmap) error { s.mux.Lock() defer s.mux.Unlock() // update renames the user login if login != newLogin { - err := os.Rename(filepath.Join(s.ConfigDir, "Users", login+".yaml"), filepath.Join(s.ConfigDir, "Users", newLogin+".yaml")) + err := os.Rename(filepath.Join(s.ConfigDir, "Users", path.Join("/", login)+".yaml"), filepath.Join(s.ConfigDir, "Users", path.Join("/", newLogin)+".yaml")) if err != nil { - return err + return fmt.Errorf("unable to rename account: %w", err) } s.Accounts[newLogin] = s.Accounts[login] + s.Accounts[newLogin].Login = newLogin delete(s.Accounts, login) } account := s.Accounts[newLogin] - account.Access = &access + account.Access = access account.Name = name account.Password = password @@ -447,9 +486,14 @@ func (s *Server) DeleteUser(login string) error { s.mux.Lock() defer s.mux.Unlock() + err := s.FS.Remove(filepath.Join(s.ConfigDir, "Users", path.Join("/", login)+".yaml")) + if err != nil { + return err + } + delete(s.Accounts, login) - return s.FS.Remove(filepath.Join(s.ConfigDir, "Users", login+".yaml")) + return nil } func (s *Server) connectedUsers() []Field { @@ -458,16 +502,16 @@ func (s *Server) connectedUsers() []Field { var connectedUsers []Field for _, c := range sortedClients(s.Clients) { - if !c.Agreed { - continue - } - user := User{ + b, err := io.ReadAll(&User{ ID: *c.ID, - Icon: *c.Icon, - Flags: *c.Flags, + Icon: c.Icon, + Flags: c.Flags, Name: string(c.UserName), + }) + if err != nil { + return nil } - connectedUsers = append(connectedUsers, NewField(fieldUsernameWithInfo, user.Payload())) + connectedUsers = append(connectedUsers, NewField(FieldUsernameWithInfo, b)) } return connectedUsers } @@ -512,8 +556,8 @@ func (s *Server) loadAccounts(userDir string) error { account := Account{} decoder := yaml.NewDecoder(fh) - if err := decoder.Decode(&account); err != nil { - return err + if err = decoder.Decode(&account); err != nil { + return fmt.Errorf("error loading account %s: %w", file, err) } s.Accounts[account.Login] = &account @@ -541,14 +585,6 @@ func (s *Server) loadConfig(path string) error { return nil } -// dontPanic logs panics instead of crashing -func dontPanic(logger *zap.SugaredLogger) { - if r := recover(); r != nil { - fmt.Println("stacktrace from panic: \n" + string(debug.Stack())) - logger.Errorw("PANIC", "err", r, "trace", string(debug.Stack())) - } -} - // handleNewConnection takes a new net.Conn and performs the initial login sequence func (s *Server) handleNewConnection(ctx context.Context, rwc io.ReadWriteCloser, remoteAddr string) error { defer dontPanic(s.Logger) @@ -563,42 +599,70 @@ func (s *Server) handleNewConnection(ctx context.Context, rwc io.ReadWriteCloser scanner.Scan() - clientLogin, _, err := ReadTransaction(scanner.Bytes()) - if err != nil { - panic(err) - } + // Make a new []byte slice and copy the scanner bytes to it. This is critical to avoid a data race as the + // scanner re-uses the buffer for subsequent scans. + buf := make([]byte, len(scanner.Bytes())) + copy(buf, scanner.Bytes()) - c := s.NewClientConn(rwc, remoteAddr) + var clientLogin Transaction + if _, err := clientLogin.Write(buf); err != nil { + return err + } // check if remoteAddr is present in the ban list if banUntil, ok := s.banList[strings.Split(remoteAddr, ":")[0]]; ok { // permaban if banUntil == nil { - s.outbox <- *NewTransaction( - tranServerMsg, - c.ID, - NewField(fieldData, []byte("You are permanently banned on this server")), - NewField(fieldChatOptions, []byte{0, 0}), + t := NewTransaction( + TranServerMsg, + &[]byte{0, 0}, + NewField(FieldData, []byte("You are permanently banned on this server")), + NewField(FieldChatOptions, []byte{0, 0}), ) + + b, err := t.MarshalBinary() + if err != nil { + return err + } + + _, err = rwc.Write(b) + if err != nil { + return err + } + time.Sleep(1 * time.Second) return nil - } else if time.Now().Before(*banUntil) { - s.outbox <- *NewTransaction( - tranServerMsg, - c.ID, - NewField(fieldData, []byte("You are temporarily banned on this server")), - NewField(fieldChatOptions, []byte{0, 0}), + } + + // temporary ban + if time.Now().Before(*banUntil) { + t := NewTransaction( + TranServerMsg, + &[]byte{0, 0}, + NewField(FieldData, []byte("You are temporarily banned on this server")), + NewField(FieldChatOptions, []byte{0, 0}), ) + b, err := t.MarshalBinary() + if err != nil { + return err + } + + _, err = rwc.Write(b) + if err != nil { + return err + } + time.Sleep(1 * time.Second) return nil } - } + + c := s.NewClientConn(rwc, remoteAddr) defer c.Disconnect() - encodedLogin := clientLogin.GetField(fieldUserLogin).Data - encodedPassword := clientLogin.GetField(fieldUserPassword).Data - *c.Version = clientLogin.GetField(fieldVersion).Data + encodedLogin := clientLogin.GetField(FieldUserLogin).Data + encodedPassword := clientLogin.GetField(FieldUserPassword).Data + c.Version = clientLogin.GetField(FieldVersion).Data var login string for _, char := range encodedLogin { @@ -612,7 +676,7 @@ func (s *Server) handleNewConnection(ctx context.Context, rwc io.ReadWriteCloser // If authentication fails, send error reply and close connection if !c.Authenticate(login, encodedPassword) { - t := c.NewErrReply(clientLogin, "Incorrect login.") + t := c.NewErrReply(&clientLogin, "Incorrect login.") b, err := t.MarshalBinary() if err != nil { return err @@ -621,61 +685,78 @@ func (s *Server) handleNewConnection(ctx context.Context, rwc io.ReadWriteCloser return err } - c.logger.Infow("Login failed", "clientVersion", fmt.Sprintf("%x", *c.Version)) + c.logger.Info("Login failed", "clientVersion", fmt.Sprintf("%x", c.Version)) return nil } - if clientLogin.GetField(fieldUserIconID).Data != nil { - *c.Icon = clientLogin.GetField(fieldUserIconID).Data + if clientLogin.GetField(FieldUserIconID).Data != nil { + c.Icon = clientLogin.GetField(FieldUserIconID).Data } c.Account = c.Server.Accounts[login] - if clientLogin.GetField(fieldUserName).Data != nil { + if clientLogin.GetField(FieldUserName).Data != nil { if c.Authorize(accessAnyName) { - c.UserName = clientLogin.GetField(fieldUserName).Data + c.UserName = clientLogin.GetField(FieldUserName).Data } else { c.UserName = []byte(c.Account.Name) } } if c.Authorize(accessDisconUser) { - *c.Flags = []byte{0, 2} + c.Flags = []byte{0, 2} } - s.outbox <- c.NewReply(clientLogin, - NewField(fieldVersion, []byte{0x00, 0xbe}), - NewField(fieldCommunityBannerID, []byte{0, 0}), - NewField(fieldServerName, []byte(s.Config.Name)), + s.outbox <- c.NewReply(&clientLogin, + NewField(FieldVersion, []byte{0x00, 0xbe}), + NewField(FieldCommunityBannerID, []byte{0, 0}), + NewField(FieldServerName, []byte(s.Config.Name)), ) // Send user access privs so client UI knows how to behave - c.Server.outbox <- *NewTransaction(tranUserAccess, c.ID, NewField(fieldUserAccess, *c.Account.Access)) - - // Show agreement to client - c.Server.outbox <- *NewTransaction(tranShowAgreement, c.ID, NewField(fieldData, s.Agreement)) + c.Server.outbox <- *NewTransaction(TranUserAccess, c.ID, NewField(FieldUserAccess, c.Account.Access[:])) + + // Accounts with accessNoAgreement do not receive the server agreement on login. The behavior is different between + // client versions. For 1.2.3 client, we do not send TranShowAgreement. For other client versions, we send + // TranShowAgreement but with the NoServerAgreement field set to 1. + if c.Authorize(accessNoAgreement) { + // If client version is nil, then the client uses the 1.2.3 login behavior + if c.Version != nil { + c.Server.outbox <- *NewTransaction(TranShowAgreement, c.ID, NewField(FieldNoServerAgreement, []byte{1})) + } + } else { + c.Server.outbox <- *NewTransaction(TranShowAgreement, c.ID, NewField(FieldData, s.Agreement)) + } - // Used simplified hotline v1.2.3 login flow for clients that do not send login info in tranAgreed - if *c.Version == nil || bytes.Equal(*c.Version, nostalgiaVersion) { - c.Agreed = true + // If the client has provided a username as part of the login, we can infer that it is using the 1.2.3 login + // flow and not the 1.5+ flow. + if len(c.UserName) != 0 { + // Add the client username to the logger. For 1.5+ clients, we don't have this information yet as it comes as + // part of TranAgreed c.logger = c.logger.With("name", string(c.UserName)) - c.logger.Infow("Login successful", "clientVersion", fmt.Sprintf("%x", *c.Version)) + c.logger.Info("Login successful", "clientVersion", "Not sent (probably 1.2.3)") + + // Notify other clients on the server that the new user has logged in. For 1.5+ clients we don't have this + // information yet, so we do it in TranAgreed instead for _, t := range c.notifyOthers( *NewTransaction( - tranNotifyChangeUser, nil, - NewField(fieldUserName, c.UserName), - NewField(fieldUserID, *c.ID), - NewField(fieldUserIconID, *c.Icon), - NewField(fieldUserFlags, *c.Flags), + TranNotifyChangeUser, nil, + NewField(FieldUserName, c.UserName), + NewField(FieldUserID, *c.ID), + NewField(FieldUserIconID, c.Icon), + NewField(FieldUserFlags, c.Flags), ), ) { c.Server.outbox <- t } } - c.Server.Stats.LoginCount += 1 + c.Server.Stats.ConnectionCounter += 1 + if len(s.Clients) > c.Server.Stats.ConnectionPeak { + c.Server.Stats.ConnectionPeak = len(s.Clients) + } // Scan for new transactions and handle them as they come in. for scanner.Scan() { @@ -684,27 +765,27 @@ func (s *Server) handleNewConnection(ctx context.Context, rwc io.ReadWriteCloser buf := make([]byte, len(scanner.Bytes())) copy(buf, scanner.Bytes()) - t, _, err := ReadTransaction(buf) - if err != nil { - panic(err) + var t Transaction + if _, err := t.Write(buf); err != nil { + return err } - if err := c.handleTransaction(*t); err != nil { - c.logger.Errorw("Error handling transaction", "err", err) + + if err := c.handleTransaction(t); err != nil { + c.logger.Error("Error handling transaction", "err", err) } } return nil } func (s *Server) NewPrivateChat(cc *ClientConn) []byte { - s.mux.Lock() - defer s.mux.Unlock() + s.PrivateChatsMu.Lock() + defer s.PrivateChatsMu.Unlock() randID := make([]byte, 4) rand.Read(randID) - data := binary.BigEndian.Uint32(randID[:]) + data := binary.BigEndian.Uint32(randID) s.PrivateChats[data] = &PrivateChat{ - Subject: "", ClientConn: make(map[uint16]*ClientConn), } s.PrivateChats[data].ClientConn[cc.uint16ID()] = cc @@ -735,6 +816,10 @@ func (s *Server) handleFileTransfer(ctx context.Context, rwc io.ReadWriter) erro delete(s.fileTransfers, t.ReferenceNumber) s.mux.Unlock() + // Wait a few seconds before closing the connection: this is a workaround for problems + // observed with Windows clients where the client must initiate close of the TCP connection before + // the server does. This is gross and seems unnecessary. TODO: Revisit? + time.Sleep(3 * time.Second) }() s.mux.Lock() @@ -763,12 +848,15 @@ func (s *Server) handleFileTransfer(ctx context.Context, rwc io.ReadWriter) erro switch fileTransfer.Type { case bannerDownload: - if err := s.bannerDownload(rwc); err != nil { - panic(err) - return err + if _, err := io.Copy(rwc, bytes.NewBuffer(s.banner)); err != nil { + return fmt.Errorf("error sending banner: %w", err) } case FileDownload: s.Stats.DownloadCounter += 1 + s.Stats.DownloadsInProgress += 1 + defer func() { + s.Stats.DownloadsInProgress -= 1 + }() var dataOffset int64 if fileTransfer.fileResumeData != nil { @@ -780,12 +868,12 @@ func (s *Server) handleFileTransfer(ctx context.Context, rwc io.ReadWriter) erro return err } - rLogger.Infow("File download started", "filePath", fullPath) + rLogger.Info("File download started", "filePath", fullPath) // if file transfer options are included, that means this is a "quick preview" request from a 1.5+ client if fileTransfer.options == nil { - // Start by sending flat file object to client - if _, err := rwc.Write(fw.ffo.BinaryMarshal()); err != nil { + _, err = io.Copy(rwc, fw.ffo) + if err != nil { return err } } @@ -823,6 +911,8 @@ func (s *Server) handleFileTransfer(ctx context.Context, rwc io.ReadWriter) erro case FileUpload: s.Stats.UploadCounter += 1 + s.Stats.UploadsInProgress += 1 + defer func() { s.Stats.UploadsInProgress -= 1 }() var file *os.File @@ -850,7 +940,7 @@ func (s *Server) handleFileTransfer(ctx context.Context, rwc io.ReadWriter) erro return err } - rLogger.Infow("File upload started", "dstFile", fullPath) + rLogger.Info("File upload started", "dstFile", fullPath) rForkWriter := io.Discard iForkWriter := io.Discard @@ -867,7 +957,7 @@ func (s *Server) handleFileTransfer(ctx context.Context, rwc io.ReadWriter) erro } if err := receiveFile(rwc, file, rForkWriter, iForkWriter, fileTransfer.bytesSentCounter); err != nil { - s.Logger.Error(err) + s.Logger.Error(err.Error()) } if err := file.Close(); err != nil { @@ -878,8 +968,13 @@ func (s *Server) handleFileTransfer(ctx context.Context, rwc io.ReadWriter) erro return err } - rLogger.Infow("File upload complete", "dstFile", fullPath) + rLogger.Info("File upload complete", "dstFile", fullPath) + case FolderDownload: + s.Stats.DownloadCounter += 1 + s.Stats.DownloadsInProgress += 1 + defer func() { s.Stats.DownloadsInProgress -= 1 }() + // Folder Download flow: // 1. Get filePath from the transfer // 2. Iterate over files @@ -909,7 +1004,7 @@ func (s *Server) handleFileTransfer(ctx context.Context, rwc io.ReadWriter) erro basePathLen := len(fullPath) - rLogger.Infow("Start folder download", "path", fullPath) + rLogger.Info("Start folder download", "path", fullPath) nextAction := make([]byte, 2) if _, err := io.ReadFull(rwc, nextAction); err != nil { @@ -936,18 +1031,15 @@ func (s *Server) handleFileTransfer(ctx context.Context, rwc io.ReadWriter) erro } subPath := path[basePathLen+1:] - rLogger.Debugw("Sending fileheader", "i", i, "path", path, "fullFilePath", fullPath, "subPath", subPath, "IsDir", info.IsDir()) + rLogger.Debug("Sending fileheader", "i", i, "path", path, "fullFilePath", fullPath, "subPath", subPath, "IsDir", info.IsDir()) if i == 1 { return nil } fileHeader := NewFileHeader(subPath, info.IsDir()) - - // Send the fileWrapper header to client - if _, err := rwc.Write(fileHeader.Payload()); err != nil { - s.Logger.Errorf("error sending file header: %v", err) - return err + if _, err := io.Copy(rwc, &fileHeader); err != nil { + return fmt.Errorf("error sending file header: %w", err) } // Read the client's Next Action request @@ -955,7 +1047,7 @@ func (s *Server) handleFileTransfer(ctx context.Context, rwc io.ReadWriter) erro return err } - rLogger.Debugw("Client folder download action", "action", fmt.Sprintf("%X", nextAction[0:2])) + rLogger.Debug("Client folder download action", "action", fmt.Sprintf("%X", nextAction[0:2])) var dataOffset int64 @@ -987,20 +1079,20 @@ func (s *Server) handleFileTransfer(ctx context.Context, rwc io.ReadWriter) erro return nil } - rLogger.Infow("File download started", + rLogger.Info("File download started", "fileName", info.Name(), "TransferSize", fmt.Sprintf("%x", hlFile.ffo.TransferSize(dataOffset)), ) // Send file size to client if _, err := rwc.Write(hlFile.ffo.TransferSize(dataOffset)); err != nil { - s.Logger.Error(err) + s.Logger.Error(err.Error()) return err } // Send ffo bytes to client - if _, err := rwc.Write(hlFile.ffo.BinaryMarshal()); err != nil { - s.Logger.Error(err) + _, err = io.Copy(rwc, hlFile.ffo) + if err != nil { return err } @@ -1043,7 +1135,10 @@ func (s *Server) handleFileTransfer(ctx context.Context, rwc io.ReadWriter) erro } case FolderUpload: - rLogger.Infow( + s.Stats.UploadCounter += 1 + s.Stats.UploadsInProgress += 1 + defer func() { s.Stats.UploadsInProgress -= 1 }() + rLogger.Info( "Folder upload started", "dstPath", fullPath, "TransferSize", binary.BigEndian.Uint32(fileTransfer.TransferSize), @@ -1084,7 +1179,7 @@ func (s *Server) handleFileTransfer(ctx context.Context, rwc io.ReadWriter) erro return err } - rLogger.Infow( + rLogger.Info( "Folder upload continued", "FormattedPath", fu.FormattedPath(), "IsFolder", fmt.Sprintf("%x", fu.IsFolder), @@ -1154,8 +1249,8 @@ func (s *Server) handleFileTransfer(ctx context.Context, rwc io.ReadWriter) erro return err } - if err := receiveFile(rwc, file, ioutil.Discard, ioutil.Discard, fileTransfer.bytesSentCounter); err != nil { - s.Logger.Error(err) + if err := receiveFile(rwc, file, io.Discard, io.Discard, fileTransfer.bytesSentCounter); err != nil { + s.Logger.Error(err.Error()) } err = os.Rename(fullPath+"/"+fu.FormattedPath()+".incomplete", fullPath+"/"+fu.FormattedPath()) @@ -1175,7 +1270,7 @@ func (s *Server) handleFileTransfer(ctx context.Context, rwc io.ReadWriter) erro return err } - rLogger.Infow("Starting file transfer", "path", filePath, "fileNum", i+1, "fileSize", binary.BigEndian.Uint32(fileSize)) + rLogger.Info("Starting file transfer", "path", filePath, "fileNum", i+1, "fileSize", binary.BigEndian.Uint32(fileSize)) incWriter, err := hlFile.incFileWriter() if err != nil { @@ -1210,7 +1305,7 @@ func (s *Server) handleFileTransfer(ctx context.Context, rwc io.ReadWriter) erro } } } - rLogger.Infof("Folder upload complete") + rLogger.Info("Folder upload complete") } return nil