fclairamb / ftpserverlib

golang ftp server library
MIT License
416 stars 96 forks source link

Upload with lftp not working when TLS is used #470

Open ale-rinaldi opened 2 months ago

ale-rinaldi commented 2 months ago

Hello,

I recently used ftpserverlib to migrate an old setup based on PureFTP. Everything is good except some scripts based on lftp that began to upload 0-byte files without any error.

Doing some tests, I noticed that this happens only when TLS is involved, while there seems to be no issue on a plain connection.

I have a minimal reproducible step-by-step example:

  1. Create an empty folder and enter it

  2. Run go mod init test

  3. Create a self-signed certificate

    openssl req -x509 -newkey rsa:4096 -keyout key.pem -out cert.pem -sha256 -days 3650 -nodes -subj "/C=XX/ST=StateName/L=CityName/O=CompanyName/OU=CompanySectionName/CN=CommonNameOrHostname"
  4. Create this main.go file:

    
    package main

import ( "crypto/tls" "fmt" "github.com/fclairamb/ftpserverlib" adapter "github.com/fclairamb/go-log/slog" "github.com/spf13/afero" "log/slog" )

type ServerDriver struct{}

func (driver *ServerDriver) ClientConnected(cltContext ftpserver.ClientContext) (string, error) { return "Welcome", nil }

func (driver *ServerDriver) AuthUser(_ ftpserver.ClientContext, user, pass string) (ftpserver.ClientDriver, error) { return afero.NewBasePathFs(afero.NewOsFs(), "/tmp"), nil }

func (driver *ServerDriver) PostAuthMessage(_ ftpserver.ClientContext) (string, error) { return "Authenticated", nil }

func (driver *ServerDriver) QuitMessage() string { return "Disconnected from server" }

func (driver *ServerDriver) ClientDisconnected(cc ftpserver.ClientContext) { return }

func (driver ServerDriver) GetSettings() (ftpserver.Settings, error) { return &ftpserver.Settings{ DefaultTransferType: ftpserver.TransferTypeBinary, ListenAddr: fmt.Sprintf("127.0.0.1:21"), PassiveTransferPortRange: &ftpserver.PortRange{ Start: 30000, End: 50000, }, }, nil }

func (driver ServerDriver) GetTLSConfig() (tls.Config, error) { keypair, err := tls.LoadX509KeyPair("cert.pem", "key.pem") if err != nil { return nil, err }

return &tls.Config{
    MinVersion:   tls.VersionTLS12,
    Certificates: []tls.Certificate{keypair},
}, nil

}

func main() { srv := ftpserver.NewFtpServer(&ServerDriver{}) lvl := new(slog.LevelVar) lvl.Set(slog.LevelDebug) logger := slog.New(slog.NewTextHandler(os.Stderr, &slog.HandlerOptions{ Level: lvl, })) srv.Logger = adapter.NewWrap(logger) err := srv.Listen() if err != nil { panic(err) } panic(srv.Serve()) }


5. Run `go mod tidy`

6. Run with `sudo go run .`

7. Run a Docker container with Alpine, on host network so that 127.0.0.1 is reachable:

docker run -it --rm --network host alpine sh


8: Run those commands:

apk add --no-cache lftp

echo "Test" > test.txt

lftp 127.0.0.1

set ssl:verify no user test test put test.txt bye #

On lftp side I see: "5 bytes transferred".

On ftpserverlib I see: "level=DEBUG msg="Stream copy finished" clientId=1 writtenBytes=0".

The file /tmp/test.txt on the host has 0 bytes length.

This actually does not always happen, sometimes it fails on first attempt and sometimes after 4 or 5 attempts.

Unfortunately, I'm unable to track down what this depends on or debug it. I'm not blaming ftpserverlib, it may be an lftp problem. I hope someone may point me to the right direction.

Thank you

drakkan commented 2 months ago

Hi,

I just tested using lftp installed locally instead of in Docker and I cannot replicate

$ lftp -p 2121 127.0.0.1
lftp 127.0.0.1:~> set ssl:verify no
lftp 127.0.0.1:~> user a password
lftp a@127.0.0.1:~> put /tmp/test.txt 
5 bytes transferred                               
lftp a@127.0.0.1:/> put /tmp/test.txt 
5 bytes transferred                                      
lftp a@127.0.0.1:/> put /tmp/test.txt 
5 bytes transferred                                      
lftp a@127.0.0.1:/> put /tmp/test.txt 
5 bytes transferred                                      
lftp a@127.0.0.1:/> put /tmp/test.txt 
5 bytes transferred                                      
lftp a@127.0.0.1:/> put /tmp/test.txt 
5 bytes transferred                                      
lftp a@127.0.0.1:/> put /tmp/test.txt 
5 bytes transferred                                      
lftp a@127.0.0.1:/> put /tmp/test.txt 
5 bytes transferred                           
lftp a@127.0.0.1:/> put /tmp/test.txt 
5 bytes transferred                                      
lftp a@127.0.0.1:/> put /tmp/test.txt 
5 bytes transferred                                      
lftp a@127.0.0.1:/> put /tmp/test.txt 
5 bytes transferred                                      
lftp a@127.0.0.1:/> put /tmp/test.txt 
5 bytes transferred                           
lftp a@127.0.0.1:/> put /tmp/test.txt 
5 bytes transferred                                      
lftp a@127.0.0.1:/> put /tmp/test.txt 
5 bytes transferred                                      
lftp a@127.0.0.1:/> put /tmp/test.txt 
5 bytes transferred                                      
lftp a@127.0.0.1:/> put /tmp/test.txt 
5 bytes transferred

In the logs I always have this

{"level":"debug","time":"2024-07-15T10:46:59.863","sender":"ftpserverlib","server_id":"FTP_0","clientId":"5","writtenBytes":"5","message":"Stream copy finished"}

P.S. I used SFTPGo instead of your reproducer

ale-rinaldi commented 2 months ago

Thank you @drakkan .

In my tests I always disconnected and re-connected between each attempt; however, I can reproduce it even without re-conencting:

$ docker run -it --rm --network host alpine sh
/ # apk add --no-cache lftp
fetch https://dl-cdn.alpinelinux.org/alpine/v3.19/main/x86_64/APKINDEX.tar.gz
fetch https://dl-cdn.alpinelinux.org/alpine/v3.19/community/x86_64/APKINDEX.tar.gz
(1/6) Installing ncurses-terminfo-base (6.4_p20231125-r0)
(2/6) Installing libncursesw (6.4_p20231125-r0)
(3/6) Installing readline (8.2.1-r2)
(4/6) Installing libgcc (13.2.1_git20231014-r0)
(5/6) Installing libstdc++ (13.2.1_git20231014-r0)
(6/6) Installing lftp (4.9.2-r6)
Executing busybox-1.36.1-r15.trigger
OK: 13 MiB in 21 packages
/ # echo "Test" > test.txt
/ #  lftp 127.0.0.1
lftp 127.0.0.1:~> set ssl:verify no
lftp 127.0.0.1:~> user test test
lftp test@127.0.0.1:~> put test.txt
5 bytes transferred                   
lftp test@127.0.0.1:/> put test.txt
5 bytes transferred
lftp test@127.0.0.1:/> put test.txt
5 bytes transferred
lftp test@127.0.0.1:/> put test.txt
5 bytes transferred
lftp test@127.0.0.1:/> 

On the server:

time=2024-07-15T11:43:26.896+02:00 level=DEBUG msg="Client connected" clientId=1 clientIp=127.0.0.1:55004
time=2024-07-15T11:43:26.956+02:00 level=DEBUG msg="Stream copy finished" clientId=1 writtenBytes=5
time=2024-07-15T11:43:30.808+02:00 level=DEBUG msg="Stream copy finished" clientId=1 writtenBytes=0
time=2024-07-15T11:43:31.427+02:00 level=DEBUG msg="Stream copy finished" clientId=1 writtenBytes=0
time=2024-07-15T11:43:32.141+02:00 level=DEBUG msg="Stream copy finished" clientId=1 writtenBytes=0

It did it correctly only the first time, then writtenBytes=0.

Maybe it's something wrong with my basic implementation? I did nothing fancy indeed 🤷‍♂️

ale-rinaldi commented 2 months ago

Just to be sure it was not something related to my FS, I changed this line:

return afero.NewBasePathFs(afero.NewOsFs(), "/tmp"), nil

to a more generic

return afero.NewMemMapFs(), nil

I can still reproduce it, even if it seems to be less frequent:

lftp test@127.0.0.1:~> set ssl:verify no
lftp test@127.0.0.1:~> put test.txt
5 bytes transferred                             
lftp test@127.0.0.1:/> put test.txt
5 bytes transferred
lftp test@127.0.0.1:/> put test.txt
5 bytes transferred
lftp test@127.0.0.1:/> put test.txt
5 bytes transferred
lftp test@127.0.0.1:/> put test.txt
5 bytes transferred
lftp test@127.0.0.1:/> put test.txt
5 bytes transferred
lftp test@127.0.0.1:/> put test.txt
5 bytes transferred
lftp test@127.0.0.1:/> put test.txt
5 bytes transferred
lftp test@127.0.0.1:/> put test.txt
5 bytes transferred
lftp test@127.0.0.1:/> put test.txt
5 bytes transferred
lftp test@127.0.0.1:/> put test.txt
5 bytes transferred
lftp test@127.0.0.1:/> put test.txt
5 bytes transferred
lftp test@127.0.0.1:/> put test.txt
5 bytes transferred
lftp test@127.0.0.1:/> put test.txt
5 bytes transferred
lftp test@127.0.0.1:/> put test.txt
5 bytes transferred
lftp test@127.0.0.1:/> put test.txt
5 bytes transferred

On the server:

time=2024-07-15T11:46:50.195+02:00 level=INFO msg=Listening... address=127.0.0.1:21
time=2024-07-15T11:46:56.467+02:00 level=DEBUG msg="Client connected" clientId=1 clientIp=127.0.0.1:55205
time=2024-07-15T11:46:56.510+02:00 level=DEBUG msg="Client disconnected" clientId=1 clientIp=127.0.0.1:55205
time=2024-07-15T11:47:02.228+02:00 level=DEBUG msg="Client connected" clientId=2 clientIp=127.0.0.1:55211
time=2024-07-15T11:47:02.260+02:00 level=DEBUG msg="Stream copy finished" clientId=2 writtenBytes=5
time=2024-07-15T11:47:04.190+02:00 level=DEBUG msg="Stream copy finished" clientId=2 writtenBytes=5
time=2024-07-15T11:47:05.477+02:00 level=DEBUG msg="Stream copy finished" clientId=2 writtenBytes=0
time=2024-07-15T11:47:06.901+02:00 level=DEBUG msg="Stream copy finished" clientId=2 writtenBytes=5
time=2024-07-15T11:47:11.347+02:00 level=DEBUG msg="Stream copy finished" clientId=2 writtenBytes=5
time=2024-07-15T11:47:12.779+02:00 level=DEBUG msg="Stream copy finished" clientId=2 writtenBytes=0
time=2024-07-15T11:47:13.335+02:00 level=DEBUG msg="Stream copy finished" clientId=2 writtenBytes=5
time=2024-07-15T11:47:14.869+02:00 level=DEBUG msg="Stream copy finished" clientId=2 writtenBytes=0
time=2024-07-15T11:47:15.324+02:00 level=DEBUG msg="Stream copy finished" clientId=2 writtenBytes=5
time=2024-07-15T11:47:17.051+02:00 level=DEBUG msg="Stream copy finished" clientId=2 writtenBytes=0
time=2024-07-15T11:47:17.498+02:00 level=DEBUG msg="Stream copy finished" clientId=2 writtenBytes=0
time=2024-07-15T11:47:20.020+02:00 level=DEBUG msg="Stream copy finished" clientId=2 writtenBytes=0
time=2024-07-15T11:47:21.914+02:00 level=DEBUG msg="Stream copy finished" clientId=2 writtenBytes=5
time=2024-07-15T11:47:23.971+02:00 level=DEBUG msg="Stream copy finished" clientId=2 writtenBytes=5
time=2024-07-15T11:47:25.690+02:00 level=DEBUG msg="Stream copy finished" clientId=2 writtenBytes=5
time=2024-07-15T11:47:27.261+02:00 level=DEBUG msg="Stream copy finished" clientId=2 writtenBytes=0
drakkan commented 2 months ago

@ale-rinaldi I'm not sure, in SFTPGo I don't use afero but a custom implementation. I'll try to find some time to test using afero with your reproducer but it might take a while, sorry. I think ftpserver uses afero, can you reproduce the reported issue also using this server? Thank you

ale-rinaldi commented 2 months ago

Hello, I can actually reproduce it with ftpserver, even if it's even more rare.

My ftpserver config:

{
  "version": 1,
  "listen_address": ":21",
  "tls": {
    "server_cert": {
      "cert": "cert.pem",
      "key": "key.pem"
    }
  },
  "accesses": [
    {
      "user": "test",
      "pass": "test",
      "fs": "os",
      "params": {
        "basePath": "/tmp"
      }
    }
  ],
  "passive_transfer_port_range": {
    "start": 2122,
    "end": 2130
  }
}

From lftp:

$ docker run -it --rm --network host alpine sh
/ # apk add --no-cache lftp
fetch https://dl-cdn.alpinelinux.org/alpine/v3.19/main/x86_64/APKINDEX.tar.gz
fetch https://dl-cdn.alpinelinux.org/alpine/v3.19/community/x86_64/APKINDEX.tar.gz
(1/6) Installing ncurses-terminfo-base (6.4_p20231125-r0)
(2/6) Installing libncursesw (6.4_p20231125-r0)
(3/6) Installing readline (8.2.1-r2)
(4/6) Installing libgcc (13.2.1_git20231014-r0)
(5/6) Installing libstdc++ (13.2.1_git20231014-r0)
(6/6) Installing lftp (4.9.2-r6)
Executing busybox-1.36.1-r15.trigger
OK: 13 MiB in 21 packages
/ # echo "Test" > test.txt
/ # lftp 127.0.0.1
lftp 127.0.0.1:~> set ssl:verify no
lftp 127.0.0.1:~> user test test
lftp test@127.0.0.1:~> put test.txt
5 bytes transferred                   
lftp test@127.0.0.1:/> put test.txt
5 bytes transferred
lftp test@127.0.0.1:/> put test.txt
5 bytes transferred
lftp test@127.0.0.1:/> put test.txt
5 bytes transferred
lftp test@127.0.0.1:/> put test.txt
5 bytes transferred
lftp test@127.0.0.1:/> put test.txt
5 bytes transferred
lftp test@127.0.0.1:/> put test.txt
5 bytes transferred
lftp test@127.0.0.1:/> put test.txt
5 bytes transferred
lftp test@127.0.0.1:/> put test.txt
5 bytes transferred
lftp test@127.0.0.1:/> put test.txt
5 bytes transferred
lftp test@127.0.0.1:/> put test.txt
5 bytes transferred
lftp test@127.0.0.1:/> put test.txt
5 bytes transferred
lftp test@127.0.0.1:/> put test.txt
5 bytes transferred
lftp test@127.0.0.1:/> put test.txt
5 bytes transferred
lftp test@127.0.0.1:/> put test.txt
5 bytes transferred
lftp test@127.0.0.1:/> put test.txt
5 bytes transferred
lftp test@127.0.0.1:/> put test.txt
5 bytes transferred
lftp test@127.0.0.1:/> put test.txt
5 bytes transferred
lftp test@127.0.0.1:/> put test.txt
5 bytes transferred
lftp test@127.0.0.1:/> put test.txt
5 bytes transferred
lftp test@127.0.0.1:/> put test.txt
5 bytes transferred
lftp test@127.0.0.1:/> put test.txt
5 bytes transferred
lftp test@127.0.0.1:/> put test.txt
5 bytes transferred
lftp test@127.0.0.1:/> put test.txt
5 bytes transferred
lftp test@127.0.0.1:/> put test.txt
5 bytes transferred
lftp test@127.0.0.1:/> put test.txt
5 bytes transferred
lftp test@127.0.0.1:/> put test.txt
5 bytes transferred
lftp test@127.0.0.1:/> put test.txt
5 bytes transferred
lftp test@127.0.0.1:/> put test.txt
5 bytes transferred
lftp test@127.0.0.1:/> put test.txt
5 bytes transferred
lftp test@127.0.0.1:/> put test.txt
5 bytes transferred
lftp test@127.0.0.1:/>

From ftpserver:

$ sudo ./ftpserver
level=info version=0.14.0 date=2024-05-29T00:10:13Z commit=0dfa6834c8359a743bd871a27298bbf8b06f4bdd event="FTP server"
level=info component=server address=[::]:21 event=Listening...
level=info component=server event=Starting...
level=debug component=server clientId=1 clientIp=127.0.0.1:59131 event="Client connected"
level=info component=driver clientId=1 remoteAddr=127.0.0.1:59131 nbClients=1 event="Client connected"
level=debug component=server clientId=1 writtenBytes=5 event="Stream copy finished"
level=debug component=server clientId=1 writtenBytes=5 event="Stream copy finished"
level=debug component=server clientId=1 writtenBytes=0 event="Stream copy finished"
level=debug component=server clientId=1 writtenBytes=5 event="Stream copy finished"
level=debug component=server clientId=1 writtenBytes=5 event="Stream copy finished"
level=debug component=server clientId=1 writtenBytes=5 event="Stream copy finished"
level=debug component=server clientId=1 writtenBytes=5 event="Stream copy finished"
level=debug component=server clientId=1 writtenBytes=5 event="Stream copy finished"
level=debug component=server clientId=1 writtenBytes=5 event="Stream copy finished"
level=debug component=server clientId=1 writtenBytes=5 event="Stream copy finished"
level=debug component=server clientId=1 writtenBytes=5 event="Stream copy finished"
level=debug component=server clientId=1 writtenBytes=5 event="Stream copy finished"
level=debug component=server clientId=1 writtenBytes=5 event="Stream copy finished"
level=debug component=server clientId=1 writtenBytes=5 event="Stream copy finished"
level=debug component=server clientId=1 writtenBytes=5 event="Stream copy finished"
level=debug component=server clientId=1 writtenBytes=5 event="Stream copy finished"
level=debug component=server clientId=1 writtenBytes=5 event="Stream copy finished"
level=debug component=server clientId=1 writtenBytes=5 event="Stream copy finished"
level=debug component=server clientId=1 writtenBytes=5 event="Stream copy finished"
level=debug component=server clientId=1 writtenBytes=5 event="Stream copy finished"
level=debug component=server clientId=1 writtenBytes=5 event="Stream copy finished"
level=debug component=server clientId=1 writtenBytes=5 event="Stream copy finished"
level=debug component=server clientId=1 writtenBytes=5 event="Stream copy finished"
level=debug component=server clientId=1 writtenBytes=5 event="Stream copy finished"
level=debug component=server clientId=1 writtenBytes=5 event="Stream copy finished"
level=debug component=server clientId=1 writtenBytes=5 event="Stream copy finished"
level=debug component=server clientId=1 writtenBytes=0 event="Stream copy finished"
level=debug component=server clientId=1 writtenBytes=5 event="Stream copy finished"
level=debug component=server clientId=1 writtenBytes=5 event="Stream copy finished"
level=debug component=server clientId=1 writtenBytes=5 event="Stream copy finished"
level=debug component=server clientId=1 writtenBytes=5 event="Stream copy finished"

It happened literally 2 times out of many attempts. I really can't understand...

drakkan commented 2 months ago

hmm weird, I should try harder to replicate the problem against SFTPGo too. Does it happen with other clients or is it specific to lftp?

ale-rinaldi commented 2 months ago

@drakkan I don't have this issue with any other client; I replaced lftp uploads with curl --upload-file and it works perfectly now. On the other side, I never had this issue with lftp with any other server. So I think that's some sort of protocol flaw on both ends.

fclairamb commented 2 months ago

This is definitely an odd behavior, which is worth looking into. I'll try to find some time in the next weeks to look into it.

ale-rinaldi commented 2 months ago

Thank you @fclairamb , if I can be of any help with further details or testing please let me know. Have a good day!

drakkan commented 2 months ago

I can't reproduce even with ftpserver:

level=debug component=server clientId=1 clientIp=127.0.0.1:58818 event="Client connected"
level=info component=driver clientId=1 remoteAddr=127.0.0.1:58818 nbClients=1 event="Client connected"
level=debug component=server clientId=1 writtenBytes=5 event="Stream copy finished"
level=debug component=server clientId=1 writtenBytes=5 event="Stream copy finished"
level=debug component=server clientId=1 writtenBytes=5 event="Stream copy finished"
level=debug component=server clientId=1 writtenBytes=5 event="Stream copy finished"
level=debug component=server clientId=1 writtenBytes=5 event="Stream copy finished"
level=debug component=server clientId=1 writtenBytes=5 event="Stream copy finished"
level=debug component=server clientId=1 writtenBytes=5 event="Stream copy finished"
level=debug component=server clientId=1 writtenBytes=5 event="Stream copy finished"
level=debug component=server clientId=1 writtenBytes=5 event="Stream copy finished"
level=debug component=server clientId=1 writtenBytes=5 event="Stream copy finished"
level=debug component=server clientId=1 writtenBytes=5 event="Stream copy finished"
level=debug component=server clientId=1 writtenBytes=5 event="Stream copy finished"
level=debug component=server clientId=1 writtenBytes=5 event="Stream copy finished"
level=debug component=server clientId=1 writtenBytes=5 event="Stream copy finished"
level=debug component=server clientId=1 writtenBytes=5 event="Stream copy finished"
level=debug component=server clientId=1 writtenBytes=5 event="Stream copy finished"
level=debug component=server clientId=1 writtenBytes=5 event="Stream copy finished"
level=debug component=server clientId=1 writtenBytes=5 event="Stream copy finished"
level=debug component=server clientId=1 writtenBytes=5 event="Stream copy finished"
level=debug component=server clientId=1 writtenBytes=5 event="Stream copy finished"
level=debug component=server clientId=1 writtenBytes=5 event="Stream copy finished"
level=debug component=server clientId=1 writtenBytes=5 event="Stream copy finished"
level=debug component=server clientId=1 writtenBytes=5 event="Stream copy finished"
level=debug component=server clientId=1 writtenBytes=5 event="Stream copy finished"
level=debug component=server clientId=1 writtenBytes=5 event="Stream copy finished"
level=debug component=server clientId=1 writtenBytes=5 event="Stream copy finished"
level=debug component=server clientId=1 writtenBytes=5 event="Stream copy finished"
level=debug component=server clientId=1 writtenBytes=5 event="Stream copy finished"
level=debug component=server clientId=1 writtenBytes=5 event="Stream copy finished"
level=debug component=server clientId=1 writtenBytes=5 event="Stream copy finished"
level=debug component=server clientId=1 writtenBytes=5 event="Stream copy finished"
level=debug component=server clientId=1 writtenBytes=5 event="Stream copy finished"
level=debug component=server clientId=1 writtenBytes=5 event="Stream copy finished"
level=debug component=server clientId=1 writtenBytes=5 event="Stream copy finished"
level=debug component=server clientId=1 writtenBytes=5 event="Stream copy finished"
level=debug component=server clientId=1 writtenBytes=5 event="Stream copy finished"
level=debug component=server clientId=1 writtenBytes=5 event="Stream copy finished"
level=info component=driver clientId=1 remoteAddr=127.0.0.1:58818 nbClients=0 event="Client disconnected"
level=debug component=server clientId=1 clientIp=127.0.0.1:58818 event="Client disconnected"
level=debug component=server clientId=1 err="use of closed network connection" event="Problem closing control connection"

I have lftp installed locally and not in Docker

pacman -Q | grep lftp
lftp 4.9.2-2

not sure if this makes any difference (it is compiled against glibc and not musl libc)

ale-rinaldi commented 2 months ago

I'm sorry it's so difficult to reproduce, I don't think it's related to musl.

In my production setup, when I noticed the issue, the Golang built executable is running directly on the server with Ubuntu 22.04, while the lftp client is on another physical machine on a Debian-based Docker container. The production executable does something more on file close than the example I posted (uploads it to S3 and writes some database entries). On this setup, the upload with lftp fails literally every time, with a 0-byte result.

For the test, I'm executing the simpler code I posted with go run . on my Macbook, and the Alpine container is running on Orbstack. I'm not sure how this can affect the results: maybe it depends on the quantity of time consumed by the code on file close, or on the network latency?

I will try to simplify my testing and do it on a physical PC with a clean setup, then I'll introduce some sleep to see how it affects. I'll keep you updated.

Meanwhile, thanks for your interest on this.