Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Upload with lftp not working when TLS is used #470

Open
ale-rinaldi opened this issue Jul 14, 2024 · 11 comments
Open

Upload with lftp not working when TLS is used #470

ale-rinaldi opened this issue Jul 14, 2024 · 11 comments

Comments

@ale-rinaldi
Copy link

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"
  1. 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())
}
  1. Run go mod tidy

  2. Run with sudo go run .

  3. 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
Copy link
Collaborator

drakkan commented Jul 15, 2024

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 [email protected]:~> put /tmp/test.txt 
5 bytes transferred                               
lftp [email protected]:/> put /tmp/test.txt 
5 bytes transferred                                      
lftp [email protected]:/> put /tmp/test.txt 
5 bytes transferred                                      
lftp [email protected]:/> put /tmp/test.txt 
5 bytes transferred                                      
lftp [email protected]:/> put /tmp/test.txt 
5 bytes transferred                                      
lftp [email protected]:/> put /tmp/test.txt 
5 bytes transferred                                      
lftp [email protected]:/> put /tmp/test.txt 
5 bytes transferred                                      
lftp [email protected]:/> put /tmp/test.txt 
5 bytes transferred                           
lftp [email protected]:/> put /tmp/test.txt 
5 bytes transferred                                      
lftp [email protected]:/> put /tmp/test.txt 
5 bytes transferred                                      
lftp [email protected]:/> put /tmp/test.txt 
5 bytes transferred                                      
lftp [email protected]:/> put /tmp/test.txt 
5 bytes transferred                           
lftp [email protected]:/> put /tmp/test.txt 
5 bytes transferred                                      
lftp [email protected]:/> put /tmp/test.txt 
5 bytes transferred                                      
lftp [email protected]:/> put /tmp/test.txt 
5 bytes transferred                                      
lftp [email protected]:/> 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
Copy link
Author

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 [email protected]:~> put test.txt
5 bytes transferred                   
lftp [email protected]:/> put test.txt
5 bytes transferred
lftp [email protected]:/> put test.txt
5 bytes transferred
lftp [email protected]:/> put test.txt
5 bytes transferred
lftp [email protected]:/> 

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
Copy link
Author

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 [email protected]:~> set ssl:verify no
lftp [email protected]:~> put test.txt
5 bytes transferred                             
lftp [email protected]:/> put test.txt
5 bytes transferred
lftp [email protected]:/> put test.txt
5 bytes transferred
lftp [email protected]:/> put test.txt
5 bytes transferred
lftp [email protected]:/> put test.txt
5 bytes transferred
lftp [email protected]:/> put test.txt
5 bytes transferred
lftp [email protected]:/> put test.txt
5 bytes transferred
lftp [email protected]:/> put test.txt
5 bytes transferred
lftp [email protected]:/> put test.txt
5 bytes transferred
lftp [email protected]:/> put test.txt
5 bytes transferred
lftp [email protected]:/> put test.txt
5 bytes transferred
lftp [email protected]:/> put test.txt
5 bytes transferred
lftp [email protected]:/> put test.txt
5 bytes transferred
lftp [email protected]:/> put test.txt
5 bytes transferred
lftp [email protected]:/> put test.txt
5 bytes transferred
lftp [email protected]:/> 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
Copy link
Collaborator

drakkan commented Jul 15, 2024

@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
Copy link
Author

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 [email protected]:~> put test.txt
5 bytes transferred                   
lftp [email protected]:/> put test.txt
5 bytes transferred
lftp [email protected]:/> put test.txt
5 bytes transferred
lftp [email protected]:/> put test.txt
5 bytes transferred
lftp [email protected]:/> put test.txt
5 bytes transferred
lftp [email protected]:/> put test.txt
5 bytes transferred
lftp [email protected]:/> put test.txt
5 bytes transferred
lftp [email protected]:/> put test.txt
5 bytes transferred
lftp [email protected]:/> put test.txt
5 bytes transferred
lftp [email protected]:/> put test.txt
5 bytes transferred
lftp [email protected]:/> put test.txt
5 bytes transferred
lftp [email protected]:/> put test.txt
5 bytes transferred
lftp [email protected]:/> put test.txt
5 bytes transferred
lftp [email protected]:/> put test.txt
5 bytes transferred
lftp [email protected]:/> put test.txt
5 bytes transferred
lftp [email protected]:/> put test.txt
5 bytes transferred
lftp [email protected]:/> put test.txt
5 bytes transferred
lftp [email protected]:/> put test.txt
5 bytes transferred
lftp [email protected]:/> put test.txt
5 bytes transferred
lftp [email protected]:/> put test.txt
5 bytes transferred
lftp [email protected]:/> put test.txt
5 bytes transferred
lftp [email protected]:/> put test.txt
5 bytes transferred
lftp [email protected]:/> put test.txt
5 bytes transferred
lftp [email protected]:/> put test.txt
5 bytes transferred
lftp [email protected]:/> put test.txt
5 bytes transferred
lftp [email protected]:/> put test.txt
5 bytes transferred
lftp [email protected]:/> put test.txt
5 bytes transferred
lftp [email protected]:/> put test.txt
5 bytes transferred
lftp [email protected]:/> put test.txt
5 bytes transferred
lftp [email protected]:/> put test.txt
5 bytes transferred
lftp [email protected]:/> put test.txt
5 bytes transferred
lftp [email protected]:/>

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
Copy link
Collaborator

drakkan commented Jul 15, 2024

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
Copy link
Author

@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
Copy link
Owner

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
Copy link
Author

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

@drakkan
Copy link
Collaborator

drakkan commented Jul 18, 2024

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
Copy link
Author

ale-rinaldi commented Jul 18, 2024

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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants