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

FTPS via GnuTLS slow #1711

Open
regnisier opened this issue Jan 20, 2025 · 7 comments
Open

FTPS via GnuTLS slow #1711

regnisier opened this issue Jan 20, 2025 · 7 comments

Comments

@regnisier
Copy link

regnisier commented Jan 20, 2025

Environment

FTP Server OS: Linux (Ubuntu)

FTP Server Type: FileZilla server

Client Computer OS: Linux (Alpine docker image on Yocto OS)

FluentFTP Version: 52.0.0

Framework: .NET 8

Summary

Hello, we have a problem when using FTPS with FluentFTP. After encountering the same issues as in #1270
we followed the advice and started to use GnuTLS streams. The FTPS connection works and the files are transferred correctly.

However, it is very slow. Transferring a 250KB file takes around 15 seconds overall on the first connection and around 7 seconds on consecutive attempts. It seems that not only the actual file transfer is slow, but also the things done before like the TLS handshake.

When using FTP instead of FTPS the same files usually get transferred in under 0.2 seconds in comparison.

FileZilla Server is configured to require explicit FTP over TLS with a minimum allowed TLS version of 1.3.

Is this a known issue? Or do we maybe have our FtpClient misconfigured?

Thanks in advance for any help.
Regards

FTP Client Configuration

ftpClient.Config.EncryptionMode = FtpEncryptionMode.Explicit;
ftpClient.Config.CustomStream = typeof(GnuTlsStream);
ftpClient.Config.LocalFileBufferSize = 1024 * 1024;
        
ftpClient.Config.CustomStreamConfig = new GnuConfig()
{ 
  SetALPNControlConnection = string.Empty,
  SetALPNDataConnection = string.Empty,
};
ftpClient.Config.LogToConsole = true;
ftpClient.Config.ValidateAnyCertificate = true;

FluentFTP logs

2025-01-20T14:25:32.931963942Z # Connect(False)
2025-01-20T14:25:32.934327513Z Status:   FluentFTP 52.0.0.0(.NET 7.0) AsyncFtpClient
2025-01-20T14:25:32.946154535Z Status:   Connecting(async) AsyncFtpClient.FtpSocketStream(control) IP #1 = ***:21
2025-01-20T14:25:32.979029682Z Status:   Waiting for a response
2025-01-20T14:25:32.998529455Z Response: 220-FileZilla Server 1.9.4
2025-01-20T14:25:33.002163198Z Response: 220 Please visit https://filezilla-project.org/ [739270.601d]
2025-01-20T14:25:33.013836312Z Status:   Detected FTP server: FileZilla
2025-01-20T14:25:33.021282134Z Command:  AUTH TLS
2025-01-20T14:25:33.025195568Z Status:   Waiting for response to: AUTH TLS
2025-01-20T14:25:33.042078486Z Response: 234 Using authentication type TLS. [16ms]
2025-01-20T14:25:33.112003052Z Status:   GnuTLS: 0   FluentFTP.GnuTLS 1.0.31.0(Unix/.NET 6.0) / GnuTLS 3.8.5
2025-01-20T14:25:33.242265034Z Status:   FTPS authentication successful, lib = FluentFTP.GnuTLS.GnuTlsStream, cipher suite = (TLS1.3)-(ECDHE-SECP256R1)-(ECDSA-SECP256R1-SHA256)-(AES-256-GCM) [188ms]
2025-01-20T14:25:33.248097450Z Command:  USER ***
2025-01-20T14:25:33.257311106Z Status:   Waiting for response to: USER ***
2025-01-20T14:25:33.270640334Z Response: 331 Please, specify the password. [13ms]
2025-01-20T14:25:33.272862289Z Command:  PASS ***
2025-01-20T14:25:33.273713810Z Status:   Waiting for response to: PASS ***
2025-01-20T14:25:34.275494482Z Response: 230 Login successful. [1.002s]
2025-01-20T14:25:34.282440037Z Command:  PBSZ 0
2025-01-20T14:25:34.282987752Z Status:   Waiting for response to: PBSZ 0
2025-01-20T14:25:35.285446050Z Response: 200 PBSZ=0 [1.002s]
2025-01-20T14:25:35.285661678Z Command:  PROT P
2025-01-20T14:25:35.287121487Z Status:   Waiting for response to: PROT P
2025-01-20T14:25:36.298827570Z Response: 200 Protection level set to P [1.012s]
2025-01-20T14:25:36.302367302Z Command:  FEAT
2025-01-20T14:25:36.302487251Z Status:   Waiting for response to: FEAT
2025-01-20T14:25:37.310102202Z Response: 211-Features:
2025-01-20T14:25:37.310219496Z Response: MDTM
2025-01-20T14:25:37.310267569Z Response: REST STREAM
2025-01-20T14:25:37.310309549Z Response: SIZE
2025-01-20T14:25:37.310351424Z Response: MLST type*;size*;modify*;perm*;
2025-01-20T14:25:37.310397987Z Response: MLSD
2025-01-20T14:25:37.310442988Z Response: AUTH SSL
2025-01-20T14:25:37.310489655Z Response: AUTH TLS
2025-01-20T14:25:37.310536114Z Response: PROT
2025-01-20T14:25:37.310583094Z Response: PBSZ
2025-01-20T14:25:37.310630855Z Response: UTF8
2025-01-20T14:25:37.310678772Z Response: TVFS
2025-01-20T14:25:37.310726794Z Response: EPSV
2025-01-20T14:25:37.313279690Z Response: EPRT
2025-01-20T14:25:37.313380108Z Response: MFMT
2025-01-20T14:25:37.314233660Z Response: 211 End [1.012s]
2025-01-20T14:25:37.322790173Z Status:   Text encoding: System.Text.UTF8Encoding+UTF8EncodingSealed
2025-01-20T14:25:37.322905643Z Command:  OPTS UTF8 ON
2025-01-20T14:25:37.323381274Z Status:   Waiting for response to: OPTS UTF8 ON
2025-01-20T14:25:38.332143077Z Response: 202 UTF8 mode is always enabled. No need to send this command [1.008s]
2025-01-20T14:25:38.335774632Z Command:  SYST
2025-01-20T14:25:38.337073711Z Status:   Waiting for response to: SYST
2025-01-20T14:25:39.340698223Z Response: 215 UNIX emulated by FileZilla. [1.003s]
2025-01-20T14:25:39.346197406Z Status:   Active ServerHandler is: FileZilla
2025-01-20T14:25:39.349186298Z Status:   Listing parser set to: Machine
2025-01-20T14:25:39.356178989Z Command:  PWD
2025-01-20T14:25:39.356848997Z Status:   Waiting for response to: PWD
2025-01-20T14:25:40.361274731Z Response: 257 "/" is current directory. [1.004s]
2025-01-20T14:25:40.383704543Z 
2025-01-20T14:25:40.383711626Z # DirectoryExists("/home/ftp/pic")
2025-01-20T14:25:40.384862578Z Command:  CWD /home/ftp/pic
2025-01-20T14:25:40.384961746Z Status:   Waiting for response to: CWD /home/ftp/pic
2025-01-20T14:25:41.394263855Z Response: 250 CWD command successful [1.009s]
2025-01-20T14:25:41.399438556Z Command:  CWD /
2025-01-20T14:25:41.400528100Z Status:   Waiting for response to: CWD /
2025-01-20T14:25:42.403790460Z Response: 250 CWD command successful [1.003s]
2025-01-20T14:25:42.414163246Z 
2025-01-20T14:25:42.414182517Z # UploadStream("/home/ftp/pic/test", NoCheck, False)
2025-01-20T14:25:42.439320124Z 
2025-01-20T14:25:42.439336322Z # OpenWrite("/home/ftp/pic/test", Binary, -1, False)
2025-01-20T14:25:42.443307570Z Command:  TYPE I
2025-01-20T14:25:42.443693929Z Status:   Waiting for response to: TYPE I
2025-01-20T14:25:43.450340772Z Response: 200 Type set to I [1.006s]
2025-01-20T14:25:43.462981608Z 
2025-01-20T14:25:43.462989629Z # OpenDataStreamAsync("STOR /home/ftp/pic/test", 0)
2025-01-20T14:25:43.471931564Z 
2025-01-20T14:25:43.471948335Z # OpenPassiveDataStreamAsync(AutoPassive, "STOR /home/ftp/pic/test", 0)
2025-01-20T14:25:43.472333235Z Command:  EPSV
2025-01-20T14:25:43.472992619Z Status:   Waiting for response to: EPSV
2025-01-20T14:25:45.483179690Z Response: 229 Entering Extended Passive Mode (|||38329|) [2.01s]
2025-01-20T14:25:45.497804718Z Status:   Connecting(async) AsyncFtpClient.FtpSocketStream(data) IP #1 = ***:38329
2025-01-20T14:25:45.500677983Z Command:  STOR /home/ftp/pic/test
2025-01-20T14:25:45.501096635Z Status:   Waiting for response to: STOR /home/ftp/pic/test
2025-01-20T14:25:46.508781708Z Response: 150 Starting data transfer. [1.007s]
2025-01-20T14:25:46.613411045Z Status:   FTPS authentication successful, lib = FluentFTP.GnuTLS.GnuTlsStream, cipher suite = (TLS1.3)-(ECDHE-PSK-SECP256R1)-(AES-256-GCM) [100ms]
2025-01-20T14:25:46.647637726Z Status:   Uploaded 262803 bytes, 26ms, 9.6 MB/s
2025-01-20T14:25:46.652334244Z Status:   Disposing(async) AsyncFtpClient.FtpSocketStream(data)
2025-01-20T14:25:47.685204128Z Status:   Waiting for response to: STOR /home/ftp/pic/test
2025-01-20T14:25:47.685816688Z Response: 226 Operation successful [2.185s]

FileZilla Server logs

2025-01-20T14:25:32.946Z DI [FTP Session 725 192.168.8.22] Session 0x5ac8b8375720 with ID 725 created.
2025-01-20T14:25:32.947Z << [FTP Session 725 192.168.8.22] 220-FileZilla Server 1.9.4
2025-01-20T14:25:32.947Z << [FTP Session 725 192.168.8.22] 220 Please visit https://filezilla-project.org/
2025-01-20T14:25:33.025Z >> [FTP Session 725 192.168.8.22] AUTH TLS
2025-01-20T14:25:33.025Z DD [FTP Session 725 192.168.8.22] securer(1) ENTERING state = 0
2025-01-20T14:25:33.025Z DD [FTP Session 725 192.168.8.22] calling tls_layer_->set_key_and_certs(<file:/opt/filezilla-server/etc/certificates/98574985e4e16cf152e28f31a4f431418e9d366c64422fe110d104b849fbafb7/key.pem>, <file:/opt/filezilla-server/etc/certificates/98574985e4e16cf152e28f31a4f431418e9d366c64422fe110d104b849fbafb7/cert.pem>, "****")
2025-01-20T14:25:33.027Z DD [FTP Session 725 192.168.8.22] securer(1) EXITING state = 1
2025-01-20T14:25:33.027Z << [FTP Session 725 192.168.8.22] 234 Using authentication type TLS.
2025-01-20T14:25:33.028Z DD [FTP Session 725 192.168.8.22] ~securer(1) ENTERING state = 1
2025-01-20T14:25:33.028Z DD [FTP Session 725 192.168.8.22] calling tls_layer_->set_alpn()
2025-01-20T14:25:33.028Z DV [FTP Session 725 192.168.8.22] tls_layer_impl::server_handshake()
2025-01-20T14:25:33.028Z DV [FTP Session 725 192.168.8.22] tls_layer_impl::continue_handshake()
2025-01-20T14:25:33.028Z DD [FTP Session 725 192.168.8.22] ~securer(1) EXITING state = 2
2025-01-20T14:25:33.028Z DD [FTP Session 725 192.168.8.22] tls_layer_impl::on_send()
2025-01-20T14:25:33.028Z DV [FTP Session 725 192.168.8.22] tls_layer_impl::continue_handshake()
2025-01-20T14:25:33.041Z !! [Administration Server] Couldn't bind on [::1]:14148. Reason: EAFNOSUPPORT - The specified address family is not supported. Retrying in 1 seconds.
2025-01-20T14:25:33.195Z DD [FTP Session 725 192.168.8.22] tls_layer_impl::on_read()
2025-01-20T14:25:33.195Z DV [FTP Session 725 192.168.8.22] tls_layer_impl::continue_handshake()
2025-01-20T14:25:33.195Z DD [FTP Session 725 192.168.8.22] TLS handshakep: Received CLIENT HELLO
2025-01-20T14:25:33.197Z DD [FTP Session 725 192.168.8.22] TLS handshakep: Processed CLIENT HELLO
2025-01-20T14:25:33.197Z DD [FTP Session 725 192.168.8.22] TLS handshakep: About to send SERVER HELLO
2025-01-20T14:25:33.197Z DD [FTP Session 725 192.168.8.22] TLS handshakep: Sent SERVER HELLO
2025-01-20T14:25:33.197Z DD [FTP Session 725 192.168.8.22] TLS handshakep: About to send ENCRYPTED EXTENSIONS
2025-01-20T14:25:33.197Z DD [FTP Session 725 192.168.8.22] TLS handshakep: Sent ENCRYPTED EXTENSIONS
2025-01-20T14:25:33.197Z DD [FTP Session 725 192.168.8.22] TLS handshakep: About to send CERTIFICATE
2025-01-20T14:25:33.197Z DD [FTP Session 725 192.168.8.22] TLS handshakep: Sent CERTIFICATE
2025-01-20T14:25:33.197Z DD [FTP Session 725 192.168.8.22] TLS handshakep: About to send CERTIFICATE VERIFY
2025-01-20T14:25:33.198Z DD [FTP Session 725 192.168.8.22] TLS handshakep: Sent CERTIFICATE VERIFY
2025-01-20T14:25:33.198Z DD [FTP Session 725 192.168.8.22] TLS handshakep: About to send FINISHED
2025-01-20T14:25:33.198Z DD [FTP Session 725 192.168.8.22] TLS handshakep: Sent FINISHED
2025-01-20T14:25:33.204Z DD [FTP Session 725 192.168.8.22] tls_layer_impl::on_read()
2025-01-20T14:25:33.204Z DV [FTP Session 725 192.168.8.22] tls_layer_impl::continue_handshake()
2025-01-20T14:25:33.204Z DD [FTP Session 725 192.168.8.22] TLS handshakep: Received FINISHED
2025-01-20T14:25:33.204Z DD [FTP Session 725 192.168.8.22] TLS handshakep: Processed FINISHED
2025-01-20T14:25:33.204Z DI [FTP Session 725 192.168.8.22] TLS Handshake successful
2025-01-20T14:25:33.204Z DI [FTP Session 725 192.168.8.22] Protocol: TLS1.3, Key exchange: ECDHE-SECP256R1-ECDSA-SECP256R1-SHA256, Cipher: AES-256-GCM, MAC: AEAD, ALPN: 
2025-01-20T14:25:33.255Z DD [FTP Session 725 192.168.8.22] tls_layer_impl::on_read()
2025-01-20T14:25:33.255Z >> [FTP Session 725 192.168.8.22] USER foo
2025-01-20T14:25:33.255Z DI [Throttled Authenticator, FTP Session: 725] Authenticating user foo from IP 192.168.8.22.
2025-01-20T14:25:33.256Z DD [File-based Authenticator, FTP Session: 725] Invoked authenticate(()) on worker 0x5ac8b833a930, with available methods = []
2025-01-20T14:25:33.256Z DD [File-based Authenticator, FTP Session: 725] Authentication for user 'foo' not complete. Remaning methods: [password]
2025-01-20T14:25:33.256Z DD [File-based Authenticator, FTP Session: 725] Worker 0x5ac8b833a930 created new operation 0x5ac8b8383840, with shared_user = 0x0, methods = [password], error = 0
2025-01-20T14:25:33.256Z DD [Throttled Authenticator, FTP Session: 725] Worker 0x7ffc682f84b0 created new operation 0x5ac8b830fbb0
2025-01-20T14:25:33.256Z << [FTP Session 725 192.168.8.22] 331 Please, specify the password.
2025-01-20T14:25:33.275Z DD [FTP Session 725 192.168.8.22] tls_layer_impl::on_read()
2025-01-20T14:25:33.275Z >> [FTP Session 725 192.168.8.22] PASS ****
2025-01-20T14:25:33.275Z DD [File-based Authenticator, FTP Session: 725] Invoked authenticate((password)) on worker 0x5ac8b833a930, with available methods = [password]
2025-01-20T14:25:33.275Z DV [File-based Authenticator, FTP Session: 725] Authenticating user 'foo'. Methods requested: (password). Available methods: [password].
2025-01-20T14:25:33.304Z DV [File-based Authenticator, FTP Session: 725] Auth method password passed for user 'foo'.
2025-01-20T14:25:33.304Z DV [File-based Authenticator, FTP Session: 725] impersonation_token: { username: "", home: "" }
2025-01-20T14:25:33.304Z DV [File-based Authenticator, FTP Session: 725] Authentication for user 'foo' is complete.
2025-01-20T14:25:33.304Z DV [File-based Authenticator, FTP Session: 725] User 'foo' has no filesystem impersonator of its own but a default one for system user 'ftp' has been defined.
2025-01-20T14:25:33.306Z DI [File-based Authenticator, user: foo] Effective mount points:
2025-01-20T14:25:33.306Z DI [File-based Authenticator, user: foo]   > "/" -> "" 
2025-01-20T14:25:33.306Z DI [File-based Authenticator, user: foo]   > "/home" -> "" 
2025-01-20T14:25:33.306Z DI [File-based Authenticator, user: foo]   > "/home/ftp" -> "" 
2025-01-20T14:25:33.306Z DI [File-based Authenticator, user: foo]   > "/home/ftp/pic" -> "/home/ftp/pic" 
2025-01-20T14:25:33.306Z DV [File-based Authenticator, FTP Session: 725] impersonation_token: { username: "ftp", home: "/srv/ftp" }
2025-01-20T14:25:33.306Z DD [File-based Authenticator, FTP Session: 725] Worker 0x5ac8b833a930 created new operation 0x5ac8b8367cc0, with shared_user = 0x5ac8b835d580, methods = [none], error = 0
2025-01-20T14:25:33.306Z DV [File-based Authenticator/impersonator client, user: ftp] call: no available callers. Let's create one.
2025-01-20T14:25:33.306Z DI [File-based Authenticator/impersonator client, user: ftp/impersonator process] Token is valid
2025-01-20T14:25:33.306Z DI [File-based Authenticator/impersonator client, user: ftp/impersonator process] Socket pair created.
2025-01-20T14:25:33.306Z DI [File-based Authenticator/impersonator client, user: ftp/impersonator process] Process "/opt/filezilla-server/bin/filezilla-server-impersonator" spawned. Ready to go.
2025-01-20T14:25:33.306Z DD [File-based Authenticator/impersonator client, user: ftp] caller::call: Enqueued reqres.
2025-01-20T14:25:33.306Z DD [File-based Authenticator/impersonator client, user: ftp] caller::call: sent channel::ready event.
2025-01-20T14:25:33.306Z DD [File-based Authenticator/impersonator client, user: ftp] caller::on_ready: ops: 1
2025-01-20T14:25:33.306Z DD [File-based Authenticator/impersonator client, user: ftp] Entering channel::send(11)
2025-01-20T14:25:33.306Z DD [File-based Authenticator/impersonator client, user: ftp] send: before on_write(): buf size: 30, out_fd = -1
2025-01-20T14:25:33.307Z DD [File-based Authenticator/impersonator client, user: ftp] send: after on_write(): buf size: 0, err = 0
2025-01-20T14:25:33.307Z DD [File-based Authenticator/impersonator client, user: ftp] Added timeout timer with id 1.
2025-01-20T14:25:33.309Z DD [File-based Authenticator/impersonator client, user: ftp/impersonator process] fz::impersonator::process::operator()(const fz::event_base&)::<lambda(fz::socket_event_source*, fz::socket_event_flag, int)>: flag: 4, err: 0, eh: 0x5ac8b8369c00
2025-01-20T14:25:33.309Z DD [File-based Authenticator/impersonator client, user: ftp] Channel event: flag = 4
2025-01-20T14:25:33.309Z DD [File-based Authenticator/impersonator client, user: ftp] Channel event: invoking on_read(): buf size: 0
2025-01-20T14:25:33.309Z DD [File-based Authenticator/impersonator client, user: ftp] channel::on_read()
2025-01-20T14:25:33.309Z DD [File-based Authenticator/impersonator client, user: ftp] channel::on_read: trying to deserialize: buf size: 0, fd buf size: 0
2025-01-20T14:25:33.309Z DD [File-based Authenticator/impersonator client, user: ftp] channel::on_read: tried to deserialize: err: 61, buf size: 0, fd buf size: 0
2025-01-20T14:25:33.309Z DD [File-based Authenticator/impersonator client, user: ftp] channel::on_read: trying to deserialize: buf size: 19, fd buf size: 0
2025-01-20T14:25:33.309Z DD [File-based Authenticator/impersonator client, user: ftp] channel::on_read: tried to deserialize: err: 0, buf size: 0, fd buf size: 0
2025-01-20T14:25:33.309Z DD [File-based Authenticator/impersonator client, user: ftp] Channel event: invoked on_read(): buf size: 0, err: 0, can_recv: 1, has_in_msg: 1, waiting_for_read_event: 0
2025-01-20T14:25:33.309Z DD [File-based Authenticator/impersonator client, user: ftp] caller::on_ready: ops: 2
2025-01-20T14:25:33.309Z DD [File-based Authenticator/impersonator client, user: ftp] entering channel::recv
2025-01-20T14:25:33.309Z DD [File-based Authenticator/impersonator client, user: ftp] channel::recv: deserialization: got message 12. Err: 0
2025-01-20T14:25:33.309Z DD [File-based Authenticator/impersonator client, user: ftp] sending socket read event: err: 0, can_recv: 0
2025-01-20T14:25:33.309Z DI [File-based Authenticator/impersonator client, user: ftp] on_can_recv: [fz::rmp::message<fz::tvfs::backend::mkdir_response_tag (fz::result)>] processing.
2025-01-20T14:25:33.309Z DD [File-based Authenticator/impersonator client, user: ftp] Stopping timeout timer with id 1.
2025-01-20T14:25:33.309Z DD [File-based Authenticator/impersonator client, user: ftp] Added new timeout timer with id 2.
2025-01-20T14:25:33.309Z DI [File-based Authenticator/impersonator client, user: ftp] [fz::rmp::message<fz::tvfs::backend::mkdir_response_tag (fz::result)>]: message contains result: 7 (raw = 17: File exists)
2025-01-20T14:25:33.309Z DI [File-based Authenticator/impersonator client, user: ftp] [fz::rmp::message<fz::tvfs::backend::mkdir_response_tag (fz::result)>]: dispatching message
2025-01-20T14:25:33.309Z DD [File-based Authenticator/impersonator client, user: ftp] entering channel::recv
2025-01-20T14:25:33.309Z DD [File-based Authenticator/impersonator client, user: ftp] channel::recv: deserialization: not enough data. Try again later.
2025-01-20T14:25:33.309Z DD [Throttled Authenticator, FTP Session: 725] Worker 0x7ffc682f84b0 created new operation 0x7437500011e0
2025-01-20T14:25:33.309Z DD [File-based Authenticator/impersonator client, user: ftp] on_can_recv: got EAGAIN, waiting for next event.
2025-01-20T14:25:33.309Z DD [File-based Authenticator/impersonator client, user: ftp] Channel event: flag = 4
2025-01-20T14:25:33.309Z DD [File-based Authenticator/impersonator client, user: ftp] Channel event: invoking on_read(): buf size: 0
2025-01-20T14:25:33.309Z DD [File-based Authenticator/impersonator client, user: ftp] channel::on_read()
2025-01-20T14:25:33.309Z DD [File-based Authenticator, FTP Session: 725] operation 0x5ac8b8367cc0 stop() erasing worker 0x5ac8b833a930
2025-01-20T14:25:33.309Z DD [File-based Authenticator/impersonator client, user: ftp] channel::on_read: trying to deserialize: buf size: 0, fd buf size: 0
2025-01-20T14:25:33.309Z DD [Throttled Authenticator, FTP Session: 725] operation 0x7437500011e0 stop() erasing worker 0x5ac8b83363b0
2025-01-20T14:25:33.309Z DD [File-based Authenticator/impersonator client, user: ftp] channel::on_read: tried to deserialize: err: 61, buf size: 0, fd buf size: 0
2025-01-20T14:25:33.309Z DD [File-based Authenticator/impersonator client, user: ftp] channel::recv: read_fd: EAGAIN.
2025-01-20T14:25:33.309Z << [FTP Session 725 192.168.8.22] 230 Login successful.
2025-01-20T14:25:33.309Z DD [File-based Authenticator/impersonator client, user: ftp] Channel event: invoked on_read(): buf size: 0, err: 0, can_recv: 1, has_in_msg: 0, waiting_for_read_event: 1
2025-01-20T14:25:34.046Z !! [Administration Server] Couldn't bind on [::1]:14148. Reason: EAFNOSUPPORT - The specified address family is not supported. Retrying in 1 seconds.
2025-01-20T14:25:34.285Z DD [FTP Session 725 192.168.8.22 foo] tls_layer_impl::on_read()
2025-01-20T14:25:34.285Z >> [FTP Session 725 192.168.8.22 foo] PBSZ 0
2025-01-20T14:25:34.285Z << [FTP Session 725 192.168.8.22 foo] 200 PBSZ=0
2025-01-20T14:25:35.052Z !! [Administration Server] Couldn't bind on [::1]:14148. Reason: EAFNOSUPPORT - The specified address family is not supported. Retrying in 1 seconds.
2025-01-20T14:25:35.287Z DD [FTP Session 725 192.168.8.22 foo] tls_layer_impl::on_read()
2025-01-20T14:25:35.287Z >> [FTP Session 725 192.168.8.22 foo] PROT P
2025-01-20T14:25:35.287Z << [FTP Session 725 192.168.8.22 foo] 200 Protection level set to P
2025-01-20T14:25:36.058Z !! [Administration Server] Couldn't bind on [::1]:14148. Reason: EAFNOSUPPORT - The specified address family is not supported. Retrying in 1 seconds.
2025-01-20T14:25:36.311Z DD [FTP Session 725 192.168.8.22 foo] tls_layer_impl::on_read()
2025-01-20T14:25:36.312Z >> [FTP Session 725 192.168.8.22 foo] FEAT
2025-01-20T14:25:36.312Z << [FTP Session 725 192.168.8.22 foo] 211-Features:
2025-01-20T14:25:36.312Z << [FTP Session 725 192.168.8.22 foo] 211 End
2025-01-20T14:25:37.064Z !! [Administration Server] Couldn't bind on [::1]:14148. Reason: EAFNOSUPPORT - The specified address family is not supported. Retrying in 1 seconds.
2025-01-20T14:25:37.336Z DD [FTP Session 725 192.168.8.22 foo] tls_layer_impl::on_read()
2025-01-20T14:25:37.336Z >> [FTP Session 725 192.168.8.22 foo] OPTS UTF8 ON
2025-01-20T14:25:37.336Z << [FTP Session 725 192.168.8.22 foo] 202 UTF8 mode is always enabled. No need to send this command
2025-01-20T14:25:38.070Z !! [Administration Server] Couldn't bind on [::1]:14148. Reason: EAFNOSUPPORT - The specified address family is not supported. Retrying in 1 seconds.
2025-01-20T14:25:38.359Z DD [FTP Session 725 192.168.8.22 foo] tls_layer_impl::on_read()
2025-01-20T14:25:38.359Z >> [FTP Session 725 192.168.8.22 foo] SYST
2025-01-20T14:25:38.359Z << [FTP Session 725 192.168.8.22 foo] 215 UNIX emulated by FileZilla.
2025-01-20T14:25:39.075Z !! [Administration Server] Couldn't bind on [::1]:14148. Reason: EAFNOSUPPORT - The specified address family is not supported. Retrying in 1 seconds.
2025-01-20T14:25:39.355Z DD [FTP Session 725 192.168.8.22 foo] tls_layer_impl::on_read()
2025-01-20T14:25:39.356Z >> [FTP Session 725 192.168.8.22 foo] PWD
2025-01-20T14:25:39.356Z << [FTP Session 725 192.168.8.22 foo] 257 "/" is current directory.
2025-01-20T14:25:40.081Z !! [Administration Server] Couldn't bind on [::1]:14148. Reason: EAFNOSUPPORT - The specified address family is not supported. Retrying in 1 seconds.
2025-01-20T14:25:40.407Z DD [FTP Session 725 192.168.8.22 foo] tls_layer_impl::on_read()
2025-01-20T14:25:40.407Z >> [FTP Session 725 192.168.8.22 foo] CWD /home/ftp/pic
2025-01-20T14:25:40.407Z DD [File-based Authenticator/impersonator client, user: ftp] caller::call: Enqueued reqres.
2025-01-20T14:25:40.407Z DD [File-based Authenticator/impersonator client, user: ftp] caller::call: sent channel::ready event.
2025-01-20T14:25:40.407Z DD [File-based Authenticator/impersonator client, user: ftp] caller::on_ready: ops: 1
2025-01-20T14:25:40.407Z DD [File-based Authenticator/impersonator client, user: ftp] Entering channel::send(9)
2025-01-20T14:25:40.408Z DD [File-based Authenticator/impersonator client, user: ftp] send: before on_write(): buf size: 26, out_fd = -1
2025-01-20T14:25:40.408Z DD [File-based Authenticator/impersonator client, user: ftp] send: after on_write(): buf size: 0, err = 0
2025-01-20T14:25:40.408Z DD [File-based Authenticator/impersonator client, user: ftp/impersonator process] fz::impersonator::process::operator()(const fz::event_base&)::<lambda(fz::socket_event_source*, fz::socket_event_flag, int)>: flag: 4, err: 0, eh: 0x5ac8b8369c00
2025-01-20T14:25:40.408Z DD [File-based Authenticator/impersonator client, user: ftp] Channel event: flag = 4
2025-01-20T14:25:40.408Z DD [File-based Authenticator/impersonator client, user: ftp] Channel event: invoking on_read(): buf size: 0
2025-01-20T14:25:40.408Z DD [File-based Authenticator/impersonator client, user: ftp] channel::on_read()
2025-01-20T14:25:40.409Z DD [File-based Authenticator/impersonator client, user: ftp] channel::on_read: trying to deserialize: buf size: 0, fd buf size: 0
2025-01-20T14:25:40.409Z DD [File-based Authenticator/impersonator client, user: ftp] channel::on_read: tried to deserialize: err: 61, buf size: 0, fd buf size: 0
2025-01-20T14:25:40.409Z DD [File-based Authenticator/impersonator client, user: ftp] channel::on_read: trying to deserialize: buf size: 44, fd buf size: 0
2025-01-20T14:25:40.409Z DD [File-based Authenticator/impersonator client, user: ftp] channel::on_read: tried to deserialize: err: 0, buf size: 0, fd buf size: 0
2025-01-20T14:25:40.409Z DD [File-based Authenticator/impersonator client, user: ftp] Channel event: invoked on_read(): buf size: 0, err: 0, can_recv: 1, has_in_msg: 1, waiting_for_read_event: 0
2025-01-20T14:25:40.409Z DD [File-based Authenticator/impersonator client, user: ftp] caller::on_ready: ops: 2
2025-01-20T14:25:40.410Z DD [File-based Authenticator/impersonator client, user: ftp] entering channel::recv
2025-01-20T14:25:40.410Z DD [File-based Authenticator/impersonator client, user: ftp] channel::recv: deserialization: got message 10. Err: 0
2025-01-20T14:25:40.410Z DD [File-based Authenticator/impersonator client, user: ftp] sending socket read event: err: 0, can_recv: 0
2025-01-20T14:25:40.410Z DI [File-based Authenticator/impersonator client, user: ftp] on_can_recv: [fz::rmp::message<fz::tvfs::backend::info_response_tag (fz::result, bool, fz::local_filesys::type, long, fz::datetime, int)>] processing.
2025-01-20T14:25:40.410Z DD [File-based Authenticator/impersonator client, user: ftp] Stopping timeout timer with id 2.
2025-01-20T14:25:40.410Z DD [File-based Authenticator/impersonator client, user: ftp] Added new timeout timer with id 3.
2025-01-20T14:25:40.410Z DI [File-based Authenticator/impersonator client, user: ftp] [fz::rmp::message<fz::tvfs::backend::info_response_tag (fz::result, bool, fz::local_filesys::type, long, fz::datetime, int)>]: message contains result: 0 (raw = 0: No error)
2025-01-20T14:25:40.410Z DI [File-based Authenticator/impersonator client, user: ftp] [fz::rmp::message<fz::tvfs::backend::info_response_tag (fz::result, bool, fz::local_filesys::type, long, fz::datetime, int)>]: dispatching message
2025-01-20T14:25:40.410Z DD [File-based Authenticator/impersonator client, user: ftp] entering channel::recv
2025-01-20T14:25:40.410Z DD [File-based Authenticator/impersonator client, user: ftp] channel::recv: deserialization: not enough data. Try again later.
2025-01-20T14:25:40.410Z DD [File-based Authenticator/impersonator client, user: ftp] on_can_recv: got EAGAIN, waiting for next event.
2025-01-20T14:25:40.410Z DD [File-based Authenticator/impersonator client, user: ftp] Channel event: flag = 4
2025-01-20T14:25:40.410Z DD [File-based Authenticator/impersonator client, user: ftp] Channel event: invoking on_read(): buf size: 0
2025-01-20T14:25:40.410Z DD [File-based Authenticator/impersonator client, user: ftp] channel::on_read()
2025-01-20T14:25:40.410Z DD [File-based Authenticator/impersonator client, user: ftp] channel::on_read: trying to deserialize: buf size: 0, fd buf size: 0
2025-01-20T14:25:40.410Z << [FTP Session 725 192.168.8.22 foo] 250 CWD command successful
2025-01-20T14:25:40.410Z DD [File-based Authenticator/impersonator client, user: ftp] channel::on_read: tried to deserialize: err: 61, buf size: 0, fd buf size: 0
2025-01-20T14:25:40.410Z DD [File-based Authenticator/impersonator client, user: ftp] channel::recv: read_fd: EAGAIN.
2025-01-20T14:25:40.410Z DD [File-based Authenticator/impersonator client, user: ftp] Channel event: invoked on_read(): buf size: 0, err: 0, can_recv: 1, has_in_msg: 0, waiting_for_read_event: 1
2025-01-20T14:25:41.087Z !! [Administration Server] Couldn't bind on [::1]:14148. Reason: EAFNOSUPPORT - The specified address family is not supported. Retrying in 1 seconds.
2025-01-20T14:25:41.431Z DD [FTP Session 725 192.168.8.22 foo] tls_layer_impl::on_read()
2025-01-20T14:25:41.432Z >> [FTP Session 725 192.168.8.22 foo] CWD /
2025-01-20T14:25:41.432Z << [FTP Session 725 192.168.8.22 foo] 250 CWD command successful
2025-01-20T14:25:42.092Z !! [Administration Server] Couldn't bind on [::1]:14148. Reason: EAFNOSUPPORT - The specified address family is not supported. Retrying in 1 seconds.
2025-01-20T14:25:42.460Z DD [FTP Session 725 192.168.8.22 foo] tls_layer_impl::on_read()
2025-01-20T14:25:42.460Z >> [FTP Session 725 192.168.8.22 foo] TYPE I
2025-01-20T14:25:42.461Z << [FTP Session 725 192.168.8.22 foo] 200 Type set to I
2025-01-20T14:25:43.098Z !! [Administration Server] Couldn't bind on [::1]:14148. Reason: EAFNOSUPPORT - The specified address family is not supported. Retrying in 1 seconds.
2025-01-20T14:25:43.479Z DD [FTP Session 725 192.168.8.22 foo] tls_layer_impl::on_read()
2025-01-20T14:25:43.480Z >> [FTP Session 725 192.168.8.22 foo] EPSV
2025-01-20T14:25:43.480Z DD [FTP Session 725 192.168.8.22 foo] TLS handshakep: About to send NEW SESSION TICKET
2025-01-20T14:25:43.480Z DD [FTP Session 725 192.168.8.22 foo] TLS handshakep: Sent NEW SESSION TICKET
2025-01-20T14:25:43.480Z DV [FTP Session 725 192.168.8.22 foo] Trying listen(1, 0) for data connection.
2025-01-20T14:25:43.480Z << [FTP Session 725 192.168.8.22 foo] 229 Entering Extended Passive Mode (|||38329|)
2025-01-20T14:25:44.103Z !! [Administration Server] Couldn't bind on [::1]:14148. Reason: EAFNOSUPPORT - The specified address family is not supported. Retrying in 1 seconds.
2025-01-20T14:25:45.108Z !! [Administration Server] Couldn't bind on [::1]:14148. Reason: EAFNOSUPPORT - The specified address family is not supported. Retrying in 1 seconds.
2025-01-20T14:25:45.493Z DV [FTP Session 725 192.168.8.22 foo] session::on_socket_event(): source = data listen, flag = 2, error = 0, state = -1
2025-01-20T14:25:45.493Z DD [FTP Session 725 192.168.8.22 foo] Client wants a secure data connection.
2025-01-20T14:25:45.493Z DD [FTP Session 725 192.168.8.22 foo] securer(1) ENTERING state = 0
2025-01-20T14:25:45.493Z DD [FTP Session 725 192.168.8.22 foo] calling tls_layer_->set_key_and_certs(<file:/opt/filezilla-server/etc/certificates/98574985e4e16cf152e28f31a4f431418e9d366c64422fe110d104b849fbafb7/key.pem>, <file:/opt/filezilla-server/etc/certificates/98574985e4e16cf152e28f31a4f431418e9d366c64422fe110d104b849fbafb7/cert.pem>, "****")
2025-01-20T14:25:45.495Z DD [FTP Session 725 192.168.8.22 foo] securer(1) EXITING state = 1
2025-01-20T14:25:45.495Z DD [FTP Session 725 192.168.8.22 foo] Making the data connection secure.
2025-01-20T14:25:45.495Z DD [FTP Session 725 192.168.8.22 foo] ~securer(1) ENTERING state = 1
2025-01-20T14:25:45.495Z DV [FTP Session 725 192.168.8.22 foo] tls_layer_impl::server_handshake()
2025-01-20T14:25:45.495Z DV [FTP Session 725 192.168.8.22 foo] tls_layer_impl::continue_handshake()
2025-01-20T14:25:45.495Z DD [FTP Session 725 192.168.8.22 foo] ~securer(1) EXITING state = 2
2025-01-20T14:25:45.495Z DD [FTP Session 725 192.168.8.22 foo] tls_layer_impl::on_send()
2025-01-20T14:25:45.495Z DV [FTP Session 725 192.168.8.22 foo] tls_layer_impl::continue_handshake()
2025-01-20T14:25:45.496Z DD [FTP Session 725 192.168.8.22 foo] tls_layer_impl::on_read()
2025-01-20T14:25:45.496Z >> [FTP Session 725 192.168.8.22 foo] STOR /home/ftp/pic/test
2025-01-20T14:25:45.496Z DD [File-based Authenticator/impersonator client, user: ftp] caller::call: Enqueued reqres.
2025-01-20T14:25:45.496Z DD [File-based Authenticator/impersonator client, user: ftp] caller::call: sent channel::ready event.
2025-01-20T14:25:45.496Z DD [File-based Authenticator/impersonator client, user: ftp] caller::on_ready: ops: 1
2025-01-20T14:25:45.496Z DD [File-based Authenticator/impersonator client, user: ftp] Entering channel::send(1)
2025-01-20T14:25:45.496Z DD [File-based Authenticator/impersonator client, user: ftp] send: before on_write(): buf size: 38, out_fd = -1
2025-01-20T14:25:45.496Z DD [File-based Authenticator/impersonator client, user: ftp] send: after on_write(): buf size: 0, err = 0
2025-01-20T14:25:45.497Z DD [File-based Authenticator/impersonator client, user: ftp/impersonator process] fz::impersonator::process::operator()(const fz::event_base&)::<lambda(fz::socket_event_source*, fz::socket_event_flag, int)>: flag: 4, err: 0, eh: 0x5ac8b8369c00
2025-01-20T14:25:45.497Z DD [File-based Authenticator/impersonator client, user: ftp] Channel event: flag = 4
2025-01-20T14:25:45.497Z DD [File-based Authenticator/impersonator client, user: ftp] Channel event: invoking on_read(): buf size: 0
2025-01-20T14:25:45.497Z DD [File-based Authenticator/impersonator client, user: ftp] channel::on_read()
2025-01-20T14:25:45.497Z DD [File-based Authenticator/impersonator client, user: ftp] channel::on_read: trying to deserialize: buf size: 0, fd buf size: 0
2025-01-20T14:25:45.497Z DD [File-based Authenticator/impersonator client, user: ftp] channel::on_read: tried to deserialize: err: 61, buf size: 0, fd buf size: 0
2025-01-20T14:25:45.497Z DD [File-based Authenticator/impersonator client, user: ftp] channel::on_read: trying to deserialize: buf size: 20, fd buf size: 1
2025-01-20T14:25:45.497Z DD [File-based Authenticator/impersonator client, user: ftp] channel::on_read: tried to deserialize: err: 0, buf size: 0, fd buf size: 0
2025-01-20T14:25:45.497Z DD [File-based Authenticator/impersonator client, user: ftp] Channel event: invoked on_read(): buf size: 0, err: 0, can_recv: 1, has_in_msg: 1, waiting_for_read_event: 0
2025-01-20T14:25:45.497Z DD [File-based Authenticator/impersonator client, user: ftp] caller::on_ready: ops: 2
2025-01-20T14:25:45.497Z DD [File-based Authenticator/impersonator client, user: ftp] entering channel::recv
2025-01-20T14:25:45.497Z DD [File-based Authenticator/impersonator client, user: ftp] channel::recv: deserialization: got message 3. Err: 0
2025-01-20T14:25:45.497Z DD [File-based Authenticator/impersonator client, user: ftp] sending socket read event: err: 0, can_recv: 0
2025-01-20T14:25:45.498Z DI [File-based Authenticator/impersonator client, user: ftp] on_can_recv: [fz::rmp::message<fz::tvfs::backend::open_response_tag (fz::result, fz::tvfs::fd_owner)>] processing.
2025-01-20T14:25:45.498Z DD [File-based Authenticator/impersonator client, user: ftp] Stopping timeout timer with id 3.
2025-01-20T14:25:45.498Z DD [File-based Authenticator/impersonator client, user: ftp] Added new timeout timer with id 4.
2025-01-20T14:25:45.498Z DI [File-based Authenticator/impersonator client, user: ftp] [fz::rmp::message<fz::tvfs::backend::open_response_tag (fz::result, fz::tvfs::fd_owner)>]: message contains result: 0 (raw = 0: No error)
2025-01-20T14:25:45.498Z DI [File-based Authenticator/impersonator client, user: ftp] [fz::rmp::message<fz::tvfs::backend::open_response_tag (fz::result, fz::tvfs::fd_owner)>]: dispatching message
2025-01-20T14:25:45.498Z DD [File-based Authenticator/impersonator client, user: ftp] entering channel::recv
2025-01-20T14:25:45.498Z DD [File-based Authenticator/impersonator client, user: ftp] channel::recv: deserialization: not enough data. Try again later.
2025-01-20T14:25:45.498Z DD [FTP Session 725 192.168.8.22 foo] Client wants a secure data connection.
2025-01-20T14:25:45.498Z DD [FTP Session 725 192.168.8.22 foo] securer(1) ENTERING state = 2
2025-01-20T14:25:45.498Z DD [FTP Session 725 192.168.8.22 foo] securer(1) EXITING state = 2
2025-01-20T14:25:45.498Z DD [FTP Session 725 192.168.8.22 foo] The data connection is not secure yet. Waiting for the related connection event.
2025-01-20T14:25:45.498Z DD [FTP Session 725 192.168.8.22 foo] ~securer(1) ENTERING state = 2
2025-01-20T14:25:45.498Z DD [FTP Session 725 192.168.8.22 foo] ~securer(1) EXITING state = 2
2025-01-20T14:25:45.498Z << [FTP Session 725 192.168.8.22 foo] 150 Starting data transfer.
2025-01-20T14:25:45.498Z DD [File-based Authenticator/impersonator client, user: ftp] on_can_recv: got EAGAIN, waiting for next event.
2025-01-20T14:25:45.498Z DD [File-based Authenticator/impersonator client, user: ftp] Channel event: flag = 4
2025-01-20T14:25:45.498Z DD [File-based Authenticator/impersonator client, user: ftp] Channel event: invoking on_read(): buf size: 0
2025-01-20T14:25:45.498Z DD [File-based Authenticator/impersonator client, user: ftp] channel::on_read()
2025-01-20T14:25:45.498Z DD [File-based Authenticator/impersonator client, user: ftp] channel::on_read: trying to deserialize: buf size: 0, fd buf size: 0
2025-01-20T14:25:45.498Z DD [File-based Authenticator/impersonator client, user: ftp] channel::on_read: tried to deserialize: err: 61, buf size: 0, fd buf size: 0
2025-01-20T14:25:45.498Z DD [File-based Authenticator/impersonator client, user: ftp] channel::recv: read_fd: EAGAIN.
2025-01-20T14:25:45.498Z DD [File-based Authenticator/impersonator client, user: ftp] Channel event: invoked on_read(): buf size: 0, err: 0, can_recv: 1, has_in_msg: 0, waiting_for_read_event: 1
2025-01-20T14:25:46.114Z !! [Administration Server] Couldn't bind on [::1]:14148. Reason: EAFNOSUPPORT - The specified address family is not supported. Retrying in 1 seconds.
2025-01-20T14:25:46.596Z DD [FTP Session 725 192.168.8.22 foo] tls_layer_impl::on_read()
2025-01-20T14:25:46.596Z DV [FTP Session 725 192.168.8.22 foo] tls_layer_impl::continue_handshake()
2025-01-20T14:25:46.597Z DD [FTP Session 725 192.168.8.22 foo] TLS handshakep: Received CLIENT HELLO
2025-01-20T14:25:46.598Z DD [FTP Session 725 192.168.8.22 foo] TLS handshakep: Processed CLIENT HELLO
2025-01-20T14:25:46.598Z DD [FTP Session 725 192.168.8.22 foo] TLS handshakep: About to send SERVER HELLO
2025-01-20T14:25:46.598Z DD [FTP Session 725 192.168.8.22 foo] TLS handshakep: Sent SERVER HELLO
2025-01-20T14:25:46.598Z DD [FTP Session 725 192.168.8.22 foo] TLS handshakep: About to send ENCRYPTED EXTENSIONS
2025-01-20T14:25:46.598Z DD [FTP Session 725 192.168.8.22 foo] TLS handshakep: Sent ENCRYPTED EXTENSIONS
2025-01-20T14:25:46.598Z DD [FTP Session 725 192.168.8.22 foo] TLS handshakep: About to send FINISHED
2025-01-20T14:25:46.598Z DD [FTP Session 725 192.168.8.22 foo] TLS handshakep: Sent FINISHED
2025-01-20T14:25:46.602Z DD [FTP Session 725 192.168.8.22 foo] tls_layer_impl::on_read()
2025-01-20T14:25:46.602Z DV [FTP Session 725 192.168.8.22 foo] tls_layer_impl::continue_handshake()
2025-01-20T14:25:46.602Z DD [FTP Session 725 192.168.8.22 foo] TLS handshakep: Received FINISHED
2025-01-20T14:25:46.602Z DD [FTP Session 725 192.168.8.22 foo] TLS handshakep: Processed FINISHED
2025-01-20T14:25:46.602Z DI [FTP Session 725 192.168.8.22 foo] TLS Handshake successful
2025-01-20T14:25:46.602Z DI [FTP Session 725 192.168.8.22 foo] TLS Session resumed
2025-01-20T14:25:46.602Z DI [FTP Session 725 192.168.8.22 foo] Protocol: TLS1.3, Key exchange: unknown, Cipher: AES-256-GCM, MAC: AEAD, ALPN: 
2025-01-20T14:25:46.602Z DV [FTP Session 725 192.168.8.22 foo] session::on_socket_event(): source = data, flag = 2, error = 0, state = 2
2025-01-20T14:25:46.602Z DD [FTP Session 725 192.168.8.22 foo] Client wants a secure data connection.
2025-01-20T14:25:46.602Z DD [FTP Session 725 192.168.8.22 foo] securer(1) ENTERING state = 2
2025-01-20T14:25:46.602Z DD [FTP Session 725 192.168.8.22 foo] securer(1) EXITING state = 3
2025-01-20T14:25:46.602Z DD [FTP Session 725 192.168.8.22 foo] The data connection is now secure.
2025-01-20T14:25:46.602Z DD [FTP Session 725 192.168.8.22 foo] ~securer(1) ENTERING state = 3
2025-01-20T14:25:46.602Z DD [FTP Session 725 192.168.8.22 foo] ~securer(1) EXITING state = 3
2025-01-20T14:25:46.602Z DD [FTP Session 725 192.168.8.22 foo] CHANNEL state is being dumped:
2025-01-20T14:25:46.602Z DD [FTP Session 725 192.168.8.22 foo] PIPE((IN)) {
2025-01-20T14:25:46.602Z DD [FTP Session 725 192.168.8.22 foo]     max_num_loops_           = 10
2025-01-20T14:25:46.602Z DD [FTP Session 725 192.168.8.22 foo]     thread_safe_             = 0
2025-01-20T14:25:46.602Z DD [FTP Session 725 192.168.8.22 foo]     variant_buffer_          = <2>
2025-01-20T14:25:46.602Z DD [FTP Session 725 192.168.8.22 foo]     variant_adder_           = <2>
2025-01-20T14:25:46.602Z DD [FTP Session 725 192.168.8.22 foo]     variant_consumer_        = <2>
2025-01-20T14:25:46.602Z DD [FTP Session 725 192.168.8.22 foo]     buffer_                  = 0x5ac8b8376710
2025-01-20T14:25:46.602Z DD [FTP Session 725 192.168.8.22 foo]     adder_                   = 0x0
2025-01-20T14:25:46.602Z DD [FTP Session 725 192.168.8.22 foo]     consumer_                = 0x0
2025-01-20T14:25:46.602Z DD [FTP Session 725 192.168.8.22 foo]     waiting_for_adder_event_ = 0
2025-01-20T14:25:46.602Z DD [FTP Session 725 192.168.8.22 foo]     consumer_error_          = 0
2025-01-20T14:25:46.602Z DD [FTP Session 725 192.168.8.22 foo]     adder_error_             = 0
2025-01-20T14:25:46.602Z DD [FTP Session 725 192.168.8.22 foo] }
2025-01-20T14:25:46.602Z DD [FTP Session 725 192.168.8.22 foo] PIPE((OUT)) {
2025-01-20T14:25:46.602Z DD [FTP Session 725 192.168.8.22 foo]     max_num_loops_           = 10
2025-01-20T14:25:46.602Z DD [FTP Session 725 192.168.8.22 foo]     thread_safe_             = 0
2025-01-20T14:25:46.602Z DD [FTP Session 725 192.168.8.22 foo]     variant_buffer_          = <2>
2025-01-20T14:25:46.602Z DD [FTP Session 725 192.168.8.22 foo]     variant_adder_           = <2>
2025-01-20T14:25:46.602Z DD [FTP Session 725 192.168.8.22 foo]     variant_consumer_        = <2>
2025-01-20T14:25:46.602Z DD [FTP Session 725 192.168.8.22 foo]     buffer_                  = 0x5ac8b83765d8
2025-01-20T14:25:46.602Z DD [FTP Session 725 192.168.8.22 foo]     adder_                   = 0x0
2025-01-20T14:25:46.602Z DD [FTP Session 725 192.168.8.22 foo]     consumer_                = 0x0
2025-01-20T14:25:46.602Z DD [FTP Session 725 192.168.8.22 foo]     waiting_for_adder_event_ = 0
2025-01-20T14:25:46.602Z DD [FTP Session 725 192.168.8.22 foo]     consumer_error_          = 0
2025-01-20T14:25:46.602Z DD [FTP Session 725 192.168.8.22 foo]     adder_error_             = 0
2025-01-20T14:25:46.602Z DD [FTP Session 725 192.168.8.22 foo] }
2025-01-20T14:25:46.616Z DD [FTP Session 725 192.168.8.22 foo] tls_layer_impl::on_read()
2025-01-20T14:25:46.617Z DD [FTP Session 725 192.168.8.22 foo] tls_layer_impl::on_read()
2025-01-20T14:25:46.618Z DD [FTP Session 725 192.168.8.22 foo] tls_layer_impl::on_read()
2025-01-20T14:25:46.619Z DD [FTP Session 725 192.168.8.22 foo] tls_layer_impl::on_read()
2025-01-20T14:25:46.619Z DD [FTP Session 725 192.168.8.22 foo] tls_layer_impl::on_read()
2025-01-20T14:25:46.620Z DD [FTP Session 725 192.168.8.22 foo] tls_layer_impl::on_read()
2025-01-20T14:25:46.622Z DD [FTP Session 725 192.168.8.22 foo] tls_layer_impl::on_read()
2025-01-20T14:25:46.623Z DD [FTP Session 725 192.168.8.22 foo] tls_layer_impl::on_read()
2025-01-20T14:25:46.623Z DD [FTP Session 725 192.168.8.22 foo] tls_layer_impl::on_read()
2025-01-20T14:25:46.625Z DD [FTP Session 725 192.168.8.22 foo] tls_layer_impl::on_read()
2025-01-20T14:25:46.626Z DD [FTP Session 725 192.168.8.22 foo] tls_layer_impl::on_read()
2025-01-20T14:25:46.627Z DD [FTP Session 725 192.168.8.22 foo] tls_layer_impl::on_read()
2025-01-20T14:25:46.627Z DD [FTP Session 725 192.168.8.22 foo] tls_layer_impl::on_read()
2025-01-20T14:25:46.628Z DD [FTP Session 725 192.168.8.22 foo] tls_layer_impl::on_read()
2025-01-20T14:25:46.628Z DD [FTP Session 725 192.168.8.22 foo] tls_layer_impl::on_read()
2025-01-20T14:25:46.629Z DD [FTP Session 725 192.168.8.22 foo] tls_layer_impl::on_read()
2025-01-20T14:25:46.630Z DD [FTP Session 725 192.168.8.22 foo] tls_layer_impl::on_read()
2025-01-20T14:25:46.630Z DD [FTP Session 725 192.168.8.22 foo] tls_layer_impl::on_read()
2025-01-20T14:25:46.633Z DD [FTP Session 725 192.168.8.22 foo] tls_layer_impl::on_read()
2025-01-20T14:25:46.633Z DD [FTP Session 725 192.168.8.22 foo] tls_layer_impl::on_read()
2025-01-20T14:25:46.634Z DD [FTP Session 725 192.168.8.22 foo] tls_layer_impl::on_read()
2025-01-20T14:25:46.634Z DD [FTP Session 725 192.168.8.22 foo] tls_layer_impl::on_read()
2025-01-20T14:25:46.635Z DD [FTP Session 725 192.168.8.22 foo] tls_layer_impl::on_read()
2025-01-20T14:25:46.635Z DD [FTP Session 725 192.168.8.22 foo] tls_layer_impl::on_read()
2025-01-20T14:25:46.636Z DD [FTP Session 725 192.168.8.22 foo] tls_layer_impl::on_read()
2025-01-20T14:25:46.637Z DD [FTP Session 725 192.168.8.22 foo] tls_layer_impl::on_read()
2025-01-20T14:25:46.638Z DD [FTP Session 725 192.168.8.22 foo] tls_layer_impl::on_read()
2025-01-20T14:25:46.638Z DD [FTP Session 725 192.168.8.22 foo] tls_layer_impl::on_read()
2025-01-20T14:25:46.639Z DD [FTP Session 725 192.168.8.22 foo] tls_layer_impl::on_read()
2025-01-20T14:25:46.639Z DD [FTP Session 725 192.168.8.22 foo] tls_layer_impl::on_read()
2025-01-20T14:25:46.640Z DD [FTP Session 725 192.168.8.22 foo] tls_layer_impl::on_read()
2025-01-20T14:25:46.642Z DD [FTP Session 725 192.168.8.22 foo] tls_layer_impl::on_read()
2025-01-20T14:25:46.643Z DD [FTP Session 725 192.168.8.22 foo] tls_layer_impl::on_read()
2025-01-20T14:25:46.643Z DD [FTP Session 725 192.168.8.22 foo] tls_layer_impl::on_read()
2025-01-20T14:25:46.649Z DD [FTP Session 725 192.168.8.22 foo] tls_layer_impl::on_read()
2025-01-20T14:25:46.655Z DD [FTP Session 725 192.168.8.22 foo] tls_layer_impl::on_read()
2025-01-20T14:25:46.656Z DV [FTP Session 725 192.168.8.22 foo] tls_layer_impl::shutdown()
2025-01-20T14:25:46.656Z DV [FTP Session 725 192.168.8.22 foo] tls_layer_impl::continue_shutdown()
2025-01-20T14:25:46.656Z DV [FTP Session 725 192.168.8.22 foo] data_socket_->shutdown() = 0
2025-01-20T14:25:46.656Z << [FTP Session 725 192.168.8.22 foo] 226 Operation successful
2025-01-20T14:25:46.656Z DD [FTP Session 725 192.168.8.22 foo] session::close_data_connection(): prev data_connection_status = 2
2025-01-20T14:25:46.656Z DD [FTP Session 725 192.168.8.22 foo] Removed done events: 0
2025-01-20T14:25:46.656Z DD [FTP Session 725 192.168.8.22 foo/Done Event] CHANNEL state is being dumped:
2025-01-20T14:25:46.657Z DD [FTP Session 725 192.168.8.22 foo/Done Event] PIPE((IN)) {
2025-01-20T14:25:46.657Z DD [FTP Session 725 192.168.8.22 foo/Done Event]     max_num_loops_           = 10
2025-01-20T14:25:46.657Z DD [FTP Session 725 192.168.8.22 foo/Done Event]     thread_safe_             = 0
2025-01-20T14:25:46.657Z DD [FTP Session 725 192.168.8.22 foo/Done Event]     variant_buffer_          = <2>
2025-01-20T14:25:46.657Z DD [FTP Session 725 192.168.8.22 foo/Done Event]     variant_adder_           = <2>
2025-01-20T14:25:46.657Z DD [FTP Session 725 192.168.8.22 foo/Done Event]     variant_consumer_        = <2>
2025-01-20T14:25:46.657Z DD [FTP Session 725 192.168.8.22 foo/Done Event]     buffer_                  = 0x5ac8b8376710
2025-01-20T14:25:46.657Z DD [FTP Session 725 192.168.8.22 foo/Done Event]     adder_                   = 0x0
2025-01-20T14:25:46.657Z DD [FTP Session 725 192.168.8.22 foo/Done Event]     consumer_                = 0x0
2025-01-20T14:25:46.657Z DD [FTP Session 725 192.168.8.22 foo/Done Event]     waiting_for_adder_event_ = 0
2025-01-20T14:25:46.657Z DD [FTP Session 725 192.168.8.22 foo/Done Event]     consumer_error_          = 0
2025-01-20T14:25:46.657Z DD [FTP Session 725 192.168.8.22 foo/Done Event]     adder_error_             = 0
2025-01-20T14:25:46.657Z DD [FTP Session 725 192.168.8.22 foo/Done Event] }
2025-01-20T14:25:46.657Z DD [FTP Session 725 192.168.8.22 foo/Done Event] PIPE((OUT)) {
2025-01-20T14:25:46.657Z DD [FTP Session 725 192.168.8.22 foo/Done Event]     max_num_loops_           = 10
2025-01-20T14:25:46.657Z DD [FTP Session 725 192.168.8.22 foo/Done Event]     thread_safe_             = 0
2025-01-20T14:25:46.657Z DD [FTP Session 725 192.168.8.22 foo/Done Event]     variant_buffer_          = <2>
2025-01-20T14:25:46.657Z DD [FTP Session 725 192.168.8.22 foo/Done Event]     variant_adder_           = <2>
2025-01-20T14:25:46.657Z DD [FTP Session 725 192.168.8.22 foo/Done Event]     variant_consumer_        = <2>
2025-01-20T14:25:46.657Z DD [FTP Session 725 192.168.8.22 foo/Done Event]     buffer_                  = 0x5ac8b83765d8
2025-01-20T14:25:46.657Z DD [FTP Session 725 192.168.8.22 foo/Done Event]     adder_                   = 0x0
2025-01-20T14:25:46.657Z DD [FTP Session 725 192.168.8.22 foo/Done Event]     consumer_                = 0x0
2025-01-20T14:25:46.657Z DD [FTP Session 725 192.168.8.22 foo/Done Event]     waiting_for_adder_event_ = 0
2025-01-20T14:25:46.657Z DD [FTP Session 725 192.168.8.22 foo/Done Event]     consumer_error_          = 0
2025-01-20T14:25:46.657Z DD [FTP Session 725 192.168.8.22 foo/Done Event]     adder_error_             = 0
2025-01-20T14:25:46.657Z DD [FTP Session 725 192.168.8.22 foo/Done Event] }
@FanDjango
Copy link
Collaborator

Just about everyone of the commands issued to the server takes about 1 second, regardless of complexity or what it may be for:

Response: 211 End [1.012s]

Let's take this sequence:

2025-01-20T14:25:41.399438556Z Command:  CWD /
2025-01-20T14:25:41.400528100Z Status:   Waiting for response to: CWD /
2025-01-20T14:25:42.403790460Z Response: 250 CWD command successful [1.003s]

So now if you look at the same place in the FileZilla log, you will find a clue:

2025-01-20T14:25:41.431Z DD [FTP Session 725 192.168.8.22 foo] tls_layer_impl::on_read()
2025-01-20T14:25:41.432Z >> [FTP Session 725 192.168.8.22 foo] CWD /
2025-01-20T14:25:41.432Z << [FTP Session 725 192.168.8.22 foo] 250 CWD command successful
2025-01-20T14:25:42.092Z !! [Administration Server] Couldn't bind on [::1]:14148. 
                                               Reason: EAFNOSUPPORT - The specified address family is not supported. Retrying in 1 seconds.

"Retrying in 1 seconds" sounds very very fishy.

Although FileZilla built the response practically immediately, it seems some configuration error causes it to block for a second.

I have no idea why but with this clue, you should be able to find out more. To prove the hypothesis you could activate heavy detailed logging in FluentFTP.GnuTLS - giving the same sort of detail as you see in FileZilla's GnuTLS log, and in the timestamps then you would see that we, the client, don't get the response until about one second has passed.

@regnisier
Copy link
Author

regnisier commented Jan 22, 2025

Thanks for the quick response. I looked into the EAFNOSUPPORT error and it seems that this was a filezilla server configuration issue regarding ipv6. I fixed it and the log 2025-01-20T14:25:42.092Z !! [Administration Server] Couldn't bind on [::1]:14148. Reason: EAFNOSUPPORT - The specified address family is not supported. Retrying in 1 seconds. no longer appears.

However the communication still experiences the 1 second delay. I couldn't find specific information online to one second delays in particular unfortunately. I did try to get more logs by adding client.Config.LogDurations. (Is there an config I missed to get even more detailled logging?)

The thing that makes me believe that it is not a server misconfiguration is that when I use standard dotnet ssl streams (removing the line ftpClient.Config.CustomStream = typeof(GnuTlsStream); I don't experience the delays. I get the 425 TLS session of data connection not resumed which is expected, but everything up to this error happens very fast without delays. Also I tested the behavior against vsftpd server to verify it is not on filezilla server and I see the same delay. Here is the logs - first for the the quick responses with standard dotnet streams, followed by the logs of the commuication with vsftpd server with using gnu tls streams:

Logs of using dotnet ssl streams instead of Gnu tls streams

FluentFtp Logs

2025-01-22T15:39:25.328528637Z    
2025-01-22T15:39:25.328530647Z # Connect(False)  
2025-01-22T15:39:25.328689693Z Status:   FluentFTP 52.0.0.0(.NET 7.0) AsyncFtpClient  
2025-01-22T15:39:25.330145287Z Status:   Connecting(async) AsyncFtpClient.FtpSocketStream(control) IP #1 = ***:21  
2025-01-22T15:39:25.332345343Z Status:   Waiting for a response  
2025-01-22T15:39:25.334497658Z Response: 220-FileZilla Server 1.9.4  
2025-01-22T15:39:25.334932447Z Response: 220 Please visit https://filezilla-project.org/ [739272.652d]  
2025-01-22T15:39:25.336183399Z Status:   Detected FTP server: FileZilla  
2025-01-22T15:39:25.336937727Z Command:  AUTH TLS  
2025-01-22T15:39:25.337422748Z Status:   Waiting for response to: AUTH TLS  
2025-01-22T15:39:25.339063457Z Response: 234 Using authentication type TLS. [1ms]  
2025-01-22T15:39:25.371547181Z Status:   FTPS authentication successful, lib = .NET SslStream, cipher suite = Tls12 (Aes256, TLS_ECDHE_ECDSA_WITH_AES_2  
56_GCM_SHA384, DiffieHellman, 0) [30ms]  
2025-01-22T15:39:25.372187358Z Command:  USER ***  
2025-01-22T15:39:25.372358615Z Status:   Waiting for response to: USER ***  
2025-01-22T15:39:25.373174757Z Response: 331 Please, specify the password. [<1ms]  
2025-01-22T15:39:25.373349627Z Command:  PASS ***  
2025-01-22T15:39:25.373450666Z Status:   Waiting for response to: PASS ***  
2025-01-22T15:39:25.386424730Z Response: 230 Login successful. [12ms]  
2025-01-22T15:39:25.387683996Z Command:  PBSZ 0  
2025-01-22T15:39:25.387745911Z Status:   Waiting for response to: PBSZ 0  
2025-01-22T15:39:25.387902131Z Response: 200 PBSZ=0 [<1ms]  
2025-01-22T15:39:25.387946712Z Command:  PROT P  
2025-01-22T15:39:25.387975742Z Status:   Waiting for response to: PROT P  
2025-01-22T15:39:25.388006382Z Response: 200 Protection level set to P [<1ms]  
2025-01-22T15:39:25.388246171Z Command:  FEAT  
2025-01-22T15:39:25.388374136Z Status:   Waiting for response to: FEAT  
2025-01-22T15:39:25.388458290Z Response: 211-Features:  
2025-01-22T15:39:25.388544713Z Response: MDTM  
2025-01-22T15:39:25.388614604Z Response: REST STREAM  
2025-01-22T15:39:25.388686013Z Response: SIZE  
2025-01-22T15:39:25.388756021Z Response: MLST type*;size*;modify*;perm*;  
2025-01-22T15:39:25.388823682Z Response: MLSD  
2025-01-22T15:39:25.388891557Z Response: AUTH SSL  
2025-01-22T15:39:25.388966769Z Response: AUTH TLS  
2025-01-22T15:39:25.389042441Z Response: PROT  
2025-01-22T15:39:25.389119259Z Response: PBSZ  
2025-01-22T15:39:25.389194820Z Response: UTF8  
2025-01-22T15:39:25.389273966Z Response: TVFS  
2025-01-22T15:39:25.389351608Z Response: EPSV  
2025-01-22T15:39:25.389423991Z Response: EPRT  
2025-01-22T15:39:25.389508513Z Response: MFMT  
2025-01-22T15:39:25.389587525Z Response: 211 End [<1ms]  
2025-01-22T15:39:25.389668610Z Status:   Text encoding: System.Text.UTF8Encoding+UTF8EncodingSealed  
2025-01-22T15:39:25.389746690Z Command:  OPTS UTF8 ON  
2025-01-22T15:39:25.389823775Z Status:   Waiting for response to: OPTS UTF8 ON  
2025-01-22T15:39:25.389897643Z Response: 202 UTF8 mode is always enabled. No need to send this command [<1ms]  
2025-01-22T15:39:25.389972281Z Command:  SYST  
2025-01-22T15:39:25.390042523Z Status:   Waiting for response to: SYST  
2025-01-22T15:39:25.390118262Z Response: 215 UNIX emulated by FileZilla. [<1ms]  
2025-01-22T15:39:25.390206828Z Status:   Active ServerHandler is: FileZilla  
2025-01-22T15:39:25.390436649Z Status:   Listing parser set to: Machine  
2025-01-22T15:39:25.391057626Z Command:  PWD  
2025-01-22T15:39:25.391149948Z Status:   Waiting for response to: PWD  
2025-01-22T15:39:25.391248672Z Response: 257 "/" is current directory. [<1ms]  
2025-01-22T15:39:25.392925773Z    
2025-01-22T15:39:25.392927019Z # DirectoryExists("/home/ftp/pic")  
2025-01-22T15:39:25.393019948Z Command:  CWD /home/ftp/pic  
2025-01-22T15:39:25.393088125Z Status:   Waiting for response to: CWD /home/ftp/pic  
2025-01-22T15:39:25.393705747Z Response: 250 CWD command successful [<1ms]  
2025-01-22T15:39:25.393847141Z Command:  CWD /  
2025-01-22T15:39:25.393895672Z Status:   Waiting for response to: CWD /  
2025-01-22T15:39:25.393956817Z Response: 250 CWD command successful [<1ms]  
2025-01-22T15:39:25.394806898Z    
2025-01-22T15:39:25.394807708Z # UploadStream("/home/ftp/pic/foo", NoCheck, False)  
2025-01-22T15:39:25.398414454Z    
2025-01-22T15:39:25.398416726Z # OpenWrite("/home/ftp/pic/foo", Binary, -1, False)  
2025-01-22T15:39:25.398804572Z Command:  TYPE I  
2025-01-22T15:39:25.398937136Z Status:   Waiting for response to: TYPE I  
2025-01-22T15:39:25.399127081Z Response: 200 Type set to I [<1ms]  
2025-01-22T15:39:25.400188785Z    
2025-01-22T15:39:25.400190538Z # OpenDataStreamAsync("STOR /home/ftp/pic/foo", 0)  
2025-01-22T15:39:25.401199334Z    
2025-01-22T15:39:25.401200763Z # OpenPassiveDataStreamAsync(AutoPassive, "STOR /home/ftp/pic/foo", 0)  
2025-01-22T15:39:25.401257581Z Command:  EPSV  
2025-01-22T15:39:25.401283660Z Status:   Waiting for response to: EPSV  
2025-01-22T15:39:25.401523542Z Response: 229 Entering Extended Passive Mode (|||44061|) [<1ms]  
2025-01-22T15:39:25.402631068Z Status:   Connecting(async) AsyncFtpClient.FtpSocketStream(data) IP #1 = ***:44061  
2025-01-22T15:39:25.403665922Z Command:  STOR /home/ftp/pic/foo  
2025-01-22T15:39:25.403700599Z Status:   Waiting for response to: STOR /home/ftp/pic/foo  
2025-01-22T15:39:25.404307359Z Response: 150 Starting data transfer. [<1ms]  
2025-01-22T15:39:25.406095129Z Status:   FTPS authentication successful, lib = .NET SslStream, cipher suite = Tls12 (Aes256, TLS_ECDHE_ECDSA_WITH_AES_2  
56_GCM_SHA384, DiffieHellman, 0) [1ms]  
2025-01-22T15:39:25.420210497Z Status:   Disposing(async) AsyncFtpClient.FtpSocketStream(data)  
2025-01-22T15:39:25.422354277Z Status:   Error encountered uploading file  
2025-01-22T15:39:25.422419614Z Status:   IOException for file  : Unable to write data to the transport connection: Broken pipe.

File Zilla Server logs

2025-01-22T15:39:25.330Z DI [FTP Session 46 172.25.0.2] Session 0x61fe53aedb70 with ID 46 created.
2025-01-22T15:39:25.330Z << [FTP Session 46 172.25.0.2] 220-FileZilla Server 1.9.4
2025-01-22T15:39:25.330Z << [FTP Session 46 172.25.0.2] 220 Please visit https://filezilla-project.org/
2025-01-22T15:39:25.337Z >> [FTP Session 46 172.25.0.2] AUTH TLS
2025-01-22T15:39:25.337Z DD [FTP Session 46 172.25.0.2] securer(1) ENTERING state = 0
2025-01-22T15:39:25.337Z DD [FTP Session 46 172.25.0.2] calling tls_layer_->set_key_and_certs(<file:/opt/filezilla-server/etc/certificates/98574985e4e16cf152e28f31a4f431418e9d366c64422fe110d104b849fbafb7/key.pem>, <file:/opt/filezilla-server/etc/certificates/98574985e4e16cf152e28f31a4f431418e9d366c64422fe110d104b849fbafb7/cert.pem>, "****")
2025-01-22T15:39:25.337Z DD [FTP Session 46 172.25.0.2] securer(1) EXITING state = 1
2025-01-22T15:39:25.337Z << [FTP Session 46 172.25.0.2] 234 Using authentication type TLS.
2025-01-22T15:39:25.337Z DD [FTP Session 46 172.25.0.2] ~securer(1) ENTERING state = 1
2025-01-22T15:39:25.337Z DD [FTP Session 46 172.25.0.2] calling tls_layer_->set_alpn()
2025-01-22T15:39:25.337Z DV [FTP Session 46 172.25.0.2] tls_layer_impl::server_handshake()
2025-01-22T15:39:25.337Z DV [FTP Session 46 172.25.0.2] tls_layer_impl::continue_handshake()
2025-01-22T15:39:25.337Z DD [FTP Session 46 172.25.0.2] ~securer(1) EXITING state = 2
2025-01-22T15:39:25.337Z DD [FTP Session 46 172.25.0.2] tls_layer_impl::on_send()
2025-01-22T15:39:25.337Z DV [FTP Session 46 172.25.0.2] tls_layer_impl::continue_handshake()
2025-01-22T15:39:25.346Z DD [FTP Session 46 172.25.0.2] tls_layer_impl::on_read()
2025-01-22T15:39:25.346Z DV [FTP Session 46 172.25.0.2] tls_layer_impl::continue_handshake()
2025-01-22T15:39:25.346Z DD [FTP Session 46 172.25.0.2] TLS handshakep: Received CLIENT HELLO
2025-01-22T15:39:25.346Z DD [FTP Session 46 172.25.0.2] TLS handshakep: Processed CLIENT HELLO
2025-01-22T15:39:25.346Z DD [FTP Session 46 172.25.0.2] TLS handshakep: About to send SERVER HELLO
2025-01-22T15:39:25.346Z DD [FTP Session 46 172.25.0.2] TLS handshakep: Sent SERVER HELLO
2025-01-22T15:39:25.346Z DD [FTP Session 46 172.25.0.2] TLS handshakep: About to send CERTIFICATE
2025-01-22T15:39:25.346Z DD [FTP Session 46 172.25.0.2] TLS handshakep: Sent CERTIFICATE
2025-01-22T15:39:25.346Z DD [FTP Session 46 172.25.0.2] TLS handshakep: About to send SERVER KEY EXCHANGE
2025-01-22T15:39:25.346Z DD [FTP Session 46 172.25.0.2] TLS handshakep: Sent SERVER KEY EXCHANGE
2025-01-22T15:39:25.346Z DD [FTP Session 46 172.25.0.2] TLS handshakep: About to send SERVER HELLO DONE
2025-01-22T15:39:25.346Z DD [FTP Session 46 172.25.0.2] TLS handshakep: Sent SERVER HELLO DONE
2025-01-22T15:39:25.347Z DD [FTP Session 46 172.25.0.2] tls_layer_impl::on_read()
2025-01-22T15:39:25.347Z DV [FTP Session 46 172.25.0.2] tls_layer_impl::continue_handshake()
2025-01-22T15:39:25.347Z DD [FTP Session 46 172.25.0.2] TLS handshakep: Received CLIENT KEY EXCHANGE
2025-01-22T15:39:25.347Z DD [FTP Session 46 172.25.0.2] TLS handshakep: Processed CLIENT KEY EXCHANGE
2025-01-22T15:39:25.347Z DD [FTP Session 46 172.25.0.2] TLS handshakep: Received FINISHED
2025-01-22T15:39:25.347Z DD [FTP Session 46 172.25.0.2] TLS handshakep: Processed FINISHED
2025-01-22T15:39:25.347Z DD [FTP Session 46 172.25.0.2] TLS handshakep: About to send NEW SESSION TICKET
2025-01-22T15:39:25.347Z DD [FTP Session 46 172.25.0.2] TLS handshakep: Sent NEW SESSION TICKET
2025-01-22T15:39:25.347Z DD [FTP Session 46 172.25.0.2] TLS handshakep: About to send FINISHED
2025-01-22T15:39:25.347Z DD [FTP Session 46 172.25.0.2] TLS handshakep: Sent FINISHED
2025-01-22T15:39:25.347Z DI [FTP Session 46 172.25.0.2] TLS Handshake successful
2025-01-22T15:39:25.347Z DI [FTP Session 46 172.25.0.2] Protocol: TLS1.2, Key exchange: ECDHE-X25519-ECDSA-SHA256, Cipher: AES-256-GCM, MAC: AEAD, ALPN: 
2025-01-22T15:39:25.372Z DD [FTP Session 46 172.25.0.2] tls_layer_impl::on_read()
2025-01-22T15:39:25.372Z >> [FTP Session 46 172.25.0.2] USER foo
2025-01-22T15:39:25.372Z DI [Throttled Authenticator, FTP Session: 46] Authenticating user foo from IP 172.25.0.2.
2025-01-22T15:39:25.372Z DD [File-based Authenticator, FTP Session: 46] Invoked authenticate(()) on worker 0x61fe53ab2ae0, with available methods = []
2025-01-22T15:39:25.372Z DD [File-based Authenticator, FTP Session: 46] Authentication for user 'foo' not complete. Remaning methods: [password]
2025-01-22T15:39:25.372Z DD [File-based Authenticator, FTP Session: 46] Worker 0x61fe53ab2ae0 created new operation 0x61fe53ac0ae0, with shared_user = 0x0, methods = [password], error = 0
2025-01-22T15:39:25.372Z DD [Throttled Authenticator, FTP Session: 46] Worker 0x7ffc7a57f820 created new operation 0x61fe53a7ef70
2025-01-22T15:39:25.372Z << [FTP Session 46 172.25.0.2] 331 Please, specify the password.
2025-01-22T15:39:25.373Z DD [FTP Session 46 172.25.0.2] tls_layer_impl::on_read()
2025-01-22T15:39:25.373Z >> [FTP Session 46 172.25.0.2] PASS ****
2025-01-22T15:39:25.373Z DD [File-based Authenticator, FTP Session: 46] Invoked authenticate((password)) on worker 0x61fe53ab2ae0, with available methods = [password]
2025-01-22T15:39:25.373Z DV [File-based Authenticator, FTP Session: 46] Authenticating user 'foo'. Methods requested: (password). Available methods: [password].
2025-01-22T15:39:25.382Z DV [File-based Authenticator, FTP Session: 46] Auth method password passed for user 'foo'.
2025-01-22T15:39:25.382Z DV [File-based Authenticator, FTP Session: 46] impersonation_token: { username: "", home: "" }
2025-01-22T15:39:25.382Z DV [File-based Authenticator, FTP Session: 46] Authentication for user 'foo' is complete.
2025-01-22T15:39:25.382Z DV [File-based Authenticator, FTP Session: 46] User 'foo' has no filesystem impersonator of its own but a default one for system user 'ftp' has been defined.
2025-01-22T15:39:25.382Z DI [File-based Authenticator, user: foo] Effective mount points:
2025-01-22T15:39:25.382Z DI [File-based Authenticator, user: foo]   > "/" -> "" 
2025-01-22T15:39:25.382Z DI [File-based Authenticator, user: foo]   > "/home" -> "" 
2025-01-22T15:39:25.382Z DI [File-based Authenticator, user: foo]   > "/home/ftp" -> "" 
2025-01-22T15:39:25.382Z DI [File-based Authenticator, user: foo]   > "/home/ftp/pic" -> "/home/ftp/pic" 
2025-01-22T15:39:25.382Z DV [File-based Authenticator, FTP Session: 46] impersonation_token: { username: "ftp", home: "/srv/ftp" }
2025-01-22T15:39:25.382Z DD [File-based Authenticator, FTP Session: 46] Worker 0x61fe53ab2ae0 created new operation 0x61fe53acfe00, with shared_user = 0x61fe53ad1ba0, methods = [none], error = 0
2025-01-22T15:39:25.382Z DV [File-based Authenticator/impersonator client, user: ftp] call: no available callers. Let's create one.
2025-01-22T15:39:25.382Z DI [File-based Authenticator/impersonator client, user: ftp/impersonator process] Token is valid
2025-01-22T15:39:25.382Z DI [File-based Authenticator/impersonator client, user: ftp/impersonator process] Socket pair created.
2025-01-22T15:39:25.383Z DI [File-based Authenticator/impersonator client, user: ftp/impersonator process] Process "/opt/filezilla-server/bin/filezilla-server-impersonator" spawned. Ready to go.
2025-01-22T15:39:25.383Z DD [File-based Authenticator/impersonator client, user: ftp] caller::call: Enqueued reqres.
2025-01-22T15:39:25.383Z DD [File-based Authenticator/impersonator client, user: ftp] caller::call: sent channel::ready event.
2025-01-22T15:39:25.383Z DD [File-based Authenticator/impersonator client, user: ftp] caller::on_ready: ops: 1
2025-01-22T15:39:25.383Z DD [File-based Authenticator/impersonator client, user: ftp] Entering channel::send(11)
2025-01-22T15:39:25.383Z DD [File-based Authenticator/impersonator client, user: ftp] send: before on_write(): buf size: 30, out_fd = -1
2025-01-22T15:39:25.383Z DD [File-based Authenticator/impersonator client, user: ftp] send: after on_write(): buf size: 0, err = 0
2025-01-22T15:39:25.383Z DD [File-based Authenticator/impersonator client, user: ftp] Added timeout timer with id 1.
2025-01-22T15:39:25.385Z DD [File-based Authenticator/impersonator client, user: ftp/impersonator process] fz::impersonator::process::operator()(const fz::event_base&)::<lambda(fz::socket_event_source*, fz::socket_event_flag, int)>: flag: 4, err: 0, eh: 0x61fe53ae6b20
2025-01-22T15:39:25.385Z DD [File-based Authenticator/impersonator client, user: ftp] Channel event: flag = 4
2025-01-22T15:39:25.385Z DD [File-based Authenticator/impersonator client, user: ftp] Channel event: invoking on_read(): buf size: 0
2025-01-22T15:39:25.385Z DD [File-based Authenticator/impersonator client, user: ftp] channel::on_read()
2025-01-22T15:39:25.385Z DD [File-based Authenticator/impersonator client, user: ftp] channel::on_read: trying to deserialize: buf size: 0, fd buf size: 0
2025-01-22T15:39:25.385Z DD [File-based Authenticator/impersonator client, user: ftp] channel::on_read: tried to deserialize: err: 61, buf size: 0, fd buf size: 0
2025-01-22T15:39:25.385Z DD [File-based Authenticator/impersonator client, user: ftp] channel::on_read: trying to deserialize: buf size: 19, fd buf size: 0
2025-01-22T15:39:25.385Z DD [File-based Authenticator/impersonator client, user: ftp] channel::on_read: tried to deserialize: err: 0, buf size: 0, fd buf size: 0
2025-01-22T15:39:25.385Z DD [File-based Authenticator/impersonator client, user: ftp] Channel event: invoked on_read(): buf size: 0, err: 0, can_recv: 1, has_in_msg: 1, waiting_for_read_event: 0
2025-01-22T15:39:25.385Z DD [File-based Authenticator/impersonator client, user: ftp] caller::on_ready: ops: 2
2025-01-22T15:39:25.385Z DD [File-based Authenticator/impersonator client, user: ftp] entering channel::recv
2025-01-22T15:39:25.385Z DD [File-based Authenticator/impersonator client, user: ftp] channel::recv: deserialization: got message 12. Err: 0
2025-01-22T15:39:25.385Z DD [File-based Authenticator/impersonator client, user: ftp] sending socket read event: err: 0, can_recv: 0
2025-01-22T15:39:25.385Z DI [File-based Authenticator/impersonator client, user: ftp] on_can_recv: [fz::rmp::message<fz::tvfs::backend::mkdir_response_tag (fz::result)>] processing.
2025-01-22T15:39:25.385Z DD [File-based Authenticator/impersonator client, user: ftp] Stopping timeout timer with id 1.
2025-01-22T15:39:25.385Z DD [File-based Authenticator/impersonator client, user: ftp] Added new timeout timer with id 2.
2025-01-22T15:39:25.385Z DI [File-based Authenticator/impersonator client, user: ftp] [fz::rmp::message<fz::tvfs::backend::mkdir_response_tag (fz::result)>]: message contains result: 7 (raw = 17: File exists)
2025-01-22T15:39:25.386Z DI [File-based Authenticator/impersonator client, user: ftp] [fz::rmp::message<fz::tvfs::backend::mkdir_response_tag (fz::result)>]: dispatching message
2025-01-22T15:39:25.386Z DD [File-based Authenticator/impersonator client, user: ftp] entering channel::recv
2025-01-22T15:39:25.386Z DD [File-based Authenticator/impersonator client, user: ftp] channel::recv: deserialization: not enough data. Try again later.
2025-01-22T15:39:25.386Z DD [Throttled Authenticator, FTP Session: 46] Worker 0x7ffc7a57f820 created new operation 0x7d5788000bd0
2025-01-22T15:39:25.386Z DD [File-based Authenticator/impersonator client, user: ftp] on_can_recv: got EAGAIN, waiting for next event.
2025-01-22T15:39:25.386Z DD [File-based Authenticator, FTP Session: 46] operation 0x61fe53acfe00 stop() erasing worker 0x61fe53ab2ae0
2025-01-22T15:39:25.386Z DD [File-based Authenticator/impersonator client, user: ftp] Channel event: flag = 4
2025-01-22T15:39:25.386Z DD [Throttled Authenticator, FTP Session: 46] operation 0x7d5788000bd0 stop() erasing worker 0x61fe53aba050
2025-01-22T15:39:25.386Z DD [File-based Authenticator/impersonator client, user: ftp] Channel event: invoking on_read(): buf size: 0
2025-01-22T15:39:25.386Z << [FTP Session 46 172.25.0.2] 230 Login successful.
2025-01-22T15:39:25.386Z DD [File-based Authenticator/impersonator client, user: ftp] channel::on_read()
2025-01-22T15:39:25.386Z DD [File-based Authenticator/impersonator client, user: ftp] channel::on_read: trying to deserialize: buf size: 0, fd buf size: 0
2025-01-22T15:39:25.386Z DD [File-based Authenticator/impersonator client, user: ftp] channel::on_read: tried to deserialize: err: 61, buf size: 0, fd buf size: 0
2025-01-22T15:39:25.386Z DD [File-based Authenticator/impersonator client, user: ftp] channel::recv: read_fd: EAGAIN.
2025-01-22T15:39:25.386Z DD [File-based Authenticator/impersonator client, user: ftp] Channel event: invoked on_read(): buf size: 0, err: 0, can_recv: 1, has_in_msg: 0, waiting_for_read_event: 1
2025-01-22T15:39:25.387Z DD [FTP Session 46 172.25.0.2 foo] tls_layer_impl::on_read()
2025-01-22T15:39:25.387Z >> [FTP Session 46 172.25.0.2 foo] PBSZ 0
2025-01-22T15:39:25.387Z << [FTP Session 46 172.25.0.2 foo] 200 PBSZ=0
2025-01-22T15:39:25.387Z DD [FTP Session 46 172.25.0.2 foo] tls_layer_impl::on_read()
2025-01-22T15:39:25.387Z >> [FTP Session 46 172.25.0.2 foo] PROT P
2025-01-22T15:39:25.387Z << [FTP Session 46 172.25.0.2 foo] 200 Protection level set to P
2025-01-22T15:39:25.388Z DD [FTP Session 46 172.25.0.2 foo] tls_layer_impl::on_read()
2025-01-22T15:39:25.388Z >> [FTP Session 46 172.25.0.2 foo] FEAT
2025-01-22T15:39:25.388Z << [FTP Session 46 172.25.0.2 foo] 211-Features:
2025-01-22T15:39:25.388Z << [FTP Session 46 172.25.0.2 foo] 211 End
2025-01-22T15:39:25.389Z DD [FTP Session 46 172.25.0.2 foo] tls_layer_impl::on_read()
2025-01-22T15:39:25.389Z >> [FTP Session 46 172.25.0.2 foo] OPTS UTF8 ON
2025-01-22T15:39:25.389Z << [FTP Session 46 172.25.0.2 foo] 202 UTF8 mode is always enabled. No need to send this command
2025-01-22T15:39:25.389Z DD [FTP Session 46 172.25.0.2 foo] tls_layer_impl::on_read()
2025-01-22T15:39:25.389Z >> [FTP Session 46 172.25.0.2 foo] SYST
2025-01-22T15:39:25.389Z << [FTP Session 46 172.25.0.2 foo] 215 UNIX emulated by FileZilla.
2025-01-22T15:39:25.391Z DD [FTP Session 46 172.25.0.2 foo] tls_layer_impl::on_read()
2025-01-22T15:39:25.391Z >> [FTP Session 46 172.25.0.2 foo] PWD
2025-01-22T15:39:25.391Z << [FTP Session 46 172.25.0.2 foo] 257 "/" is current directory.
2025-01-22T15:39:25.393Z DD [FTP Session 46 172.25.0.2 foo] tls_layer_impl::on_read()
2025-01-22T15:39:25.393Z >> [FTP Session 46 172.25.0.2 foo] CWD /home/ftp/pic
2025-01-22T15:39:25.393Z DD [File-based Authenticator/impersonator client, user: ftp] caller::call: Enqueued reqres.
2025-01-22T15:39:25.393Z DD [File-based Authenticator/impersonator client, user: ftp] caller::call: sent channel::ready event.
2025-01-22T15:39:25.393Z DD [File-based Authenticator/impersonator client, user: ftp] caller::on_ready: ops: 1
2025-01-22T15:39:25.393Z DD [File-based Authenticator/impersonator client, user: ftp] Entering channel::send(9)
2025-01-22T15:39:25.393Z DD [File-based Authenticator/impersonator client, user: ftp] send: before on_write(): buf size: 26, out_fd = -1
2025-01-22T15:39:25.393Z DD [File-based Authenticator/impersonator client, user: ftp] send: after on_write(): buf size: 0, err = 0
2025-01-22T15:39:25.393Z DD [File-based Authenticator/impersonator client, user: ftp/impersonator process] fz::impersonator::process::operator()(const fz::event_base&)::<lambda(fz::socket_event_source*, fz::socket_event_flag, int)>: flag: 4, err: 0, eh: 0x61fe53ae6b20
2025-01-22T15:39:25.393Z DD [File-based Authenticator/impersonator client, user: ftp] Channel event: flag = 4
2025-01-22T15:39:25.393Z DD [File-based Authenticator/impersonator client, user: ftp] Channel event: invoking on_read(): buf size: 0
2025-01-22T15:39:25.393Z DD [File-based Authenticator/impersonator client, user: ftp] channel::on_read()
2025-01-22T15:39:25.393Z DD [File-based Authenticator/impersonator client, user: ftp] channel::on_read: trying to deserialize: buf size: 0, fd buf size: 0
2025-01-22T15:39:25.393Z DD [File-based Authenticator/impersonator client, user: ftp] channel::on_read: tried to deserialize: err: 61, buf size: 0, fd buf size: 0
2025-01-22T15:39:25.393Z DD [File-based Authenticator/impersonator client, user: ftp] channel::on_read: trying to deserialize: buf size: 44, fd buf size: 0
2025-01-22T15:39:25.393Z DD [File-based Authenticator/impersonator client, user: ftp] channel::on_read: tried to deserialize: err: 0, buf size: 0, fd buf size: 0
2025-01-22T15:39:25.393Z DD [File-based Authenticator/impersonator client, user: ftp] Channel event: invoked on_read(): buf size: 0, err: 0, can_recv: 1, has_in_msg: 1, waiting_for_read_event: 0
2025-01-22T15:39:25.393Z DD [File-based Authenticator/impersonator client, user: ftp] caller::on_ready: ops: 2
2025-01-22T15:39:25.393Z DD [File-based Authenticator/impersonator client, user: ftp] entering channel::recv
2025-01-22T15:39:25.393Z DD [File-based Authenticator/impersonator client, user: ftp] channel::recv: deserialization: got message 10. Err: 0
2025-01-22T15:39:25.393Z DD [File-based Authenticator/impersonator client, user: ftp] sending socket read event: err: 0, can_recv: 0
2025-01-22T15:39:25.393Z DI [File-based Authenticator/impersonator client, user: ftp] on_can_recv: [fz::rmp::message<fz::tvfs::backend::info_response_tag (fz::result, bool, fz::local_filesys::type, long, fz::datetime, int)>] processing.
2025-01-22T15:39:25.393Z DD [File-based Authenticator/impersonator client, user: ftp] Stopping timeout timer with id 2.
2025-01-22T15:39:25.393Z DD [File-based Authenticator/impersonator client, user: ftp] Added new timeout timer with id 3.
2025-01-22T15:39:25.393Z DI [File-based Authenticator/impersonator client, user: ftp] [fz::rmp::message<fz::tvfs::backend::info_response_tag (fz::result, bool, fz::local_filesys::type, long, fz::datetime, int)>]: message contains result: 0 (raw = 0: No error)
2025-01-22T15:39:25.393Z DI [File-based Authenticator/impersonator client, user: ftp] [fz::rmp::message<fz::tvfs::backend::info_response_tag (fz::result, bool, fz::local_filesys::type, long, fz::datetime, int)>]: dispatching message
2025-01-22T15:39:25.393Z DD [File-based Authenticator/impersonator client, user: ftp] entering channel::recv
2025-01-22T15:39:25.393Z << [FTP Session 46 172.25.0.2 foo] 250 CWD command successful
2025-01-22T15:39:25.393Z DD [File-based Authenticator/impersonator client, user: ftp] channel::recv: deserialization: not enough data. Try again later.
2025-01-22T15:39:25.393Z DD [File-based Authenticator/impersonator client, user: ftp] on_can_recv: got EAGAIN, waiting for next event.
2025-01-22T15:39:25.393Z DD [File-based Authenticator/impersonator client, user: ftp] Channel event: flag = 4
2025-01-22T15:39:25.393Z DD [File-based Authenticator/impersonator client, user: ftp] Channel event: invoking on_read(): buf size: 0
2025-01-22T15:39:25.393Z DD [File-based Authenticator/impersonator client, user: ftp] channel::on_read()
2025-01-22T15:39:25.393Z DD [File-based Authenticator/impersonator client, user: ftp] channel::on_read: trying to deserialize: buf size: 0, fd buf size: 0
2025-01-22T15:39:25.393Z DD [File-based Authenticator/impersonator client, user: ftp] channel::on_read: tried to deserialize: err: 61, buf size: 0, fd buf size: 0
2025-01-22T15:39:25.393Z DD [File-based Authenticator/impersonator client, user: ftp] channel::recv: read_fd: EAGAIN.
2025-01-22T15:39:25.393Z DD [File-based Authenticator/impersonator client, user: ftp] Channel event: invoked on_read(): buf size: 0, err: 0, can_recv: 1, has_in_msg: 0, waiting_for_read_event: 1
2025-01-22T15:39:25.393Z DD [FTP Session 46 172.25.0.2 foo] tls_layer_impl::on_read()
2025-01-22T15:39:25.393Z >> [FTP Session 46 172.25.0.2 foo] CWD /
2025-01-22T15:39:25.393Z << [FTP Session 46 172.25.0.2 foo] 250 CWD command successful
2025-01-22T15:39:25.398Z DD [FTP Session 46 172.25.0.2 foo] tls_layer_impl::on_read()
2025-01-22T15:39:25.398Z >> [FTP Session 46 172.25.0.2 foo] TYPE I
2025-01-22T15:39:25.398Z << [FTP Session 46 172.25.0.2 foo] 200 Type set to I
2025-01-22T15:39:25.401Z DD [FTP Session 46 172.25.0.2 foo] tls_layer_impl::on_read()
2025-01-22T15:39:25.401Z >> [FTP Session 46 172.25.0.2 foo] EPSV
2025-01-22T15:39:25.401Z DV [FTP Session 46 172.25.0.2 foo] Trying listen(1, 0) for data connection.
2025-01-22T15:39:25.401Z << [FTP Session 46 172.25.0.2 foo] 229 Entering Extended Passive Mode (|||44061|)
2025-01-22T15:39:25.402Z DV [FTP Session 46 172.25.0.2 foo] session::on_socket_event(): source = data listen, flag = 2, error = 0, state = -1
2025-01-22T15:39:25.402Z DD [FTP Session 46 172.25.0.2 foo] Client wants a secure data connection.
2025-01-22T15:39:25.402Z DD [FTP Session 46 172.25.0.2 foo] securer(1) ENTERING state = 0
2025-01-22T15:39:25.402Z DD [FTP Session 46 172.25.0.2 foo] calling tls_layer_->set_key_and_certs(<file:/opt/filezilla-server/etc/certificates/98574985e4e16cf152e28f31a4f431418e9d366c64422fe110d104b849fbafb7/key.pem>, <file:/opt/filezilla-server/etc/certificates/98574985e4e16cf152e28f31a4f431418e9d366c64422fe110d104b849fbafb7/cert.pem>, "****")
2025-01-22T15:39:25.403Z DD [FTP Session 46 172.25.0.2 foo] securer(1) EXITING state = 1
2025-01-22T15:39:25.403Z DD [FTP Session 46 172.25.0.2 foo] Making the data connection secure.
2025-01-22T15:39:25.403Z DD [FTP Session 46 172.25.0.2 foo] ~securer(1) ENTERING state = 1
2025-01-22T15:39:25.403Z DV [FTP Session 46 172.25.0.2 foo] tls_layer_impl::server_handshake()
2025-01-22T15:39:25.403Z DV [FTP Session 46 172.25.0.2 foo] tls_layer_impl::continue_handshake()
2025-01-22T15:39:25.403Z DD [FTP Session 46 172.25.0.2 foo] ~securer(1) EXITING state = 2
2025-01-22T15:39:25.403Z DD [FTP Session 46 172.25.0.2 foo] tls_layer_impl::on_send()
2025-01-22T15:39:25.403Z DV [FTP Session 46 172.25.0.2 foo] tls_layer_impl::continue_handshake()
2025-01-22T15:39:25.403Z DD [FTP Session 46 172.25.0.2 foo] tls_layer_impl::on_read()
2025-01-22T15:39:25.403Z >> [FTP Session 46 172.25.0.2 foo] STOR /home/ftp/pic/foo
2025-01-22T15:39:25.403Z DD [File-based Authenticator/impersonator client, user: ftp] caller::call: Enqueued reqres.
2025-01-22T15:39:25.403Z DD [File-based Authenticator/impersonator client, user: ftp] caller::call: sent channel::ready event.
2025-01-22T15:39:25.403Z DD [File-based Authenticator/impersonator client, user: ftp] caller::on_ready: ops: 1
2025-01-22T15:39:25.403Z DD [File-based Authenticator/impersonator client, user: ftp] Entering channel::send(1)
2025-01-22T15:39:25.403Z DD [File-based Authenticator/impersonator client, user: ftp] send: before on_write(): buf size: 37, out_fd = -1
2025-01-22T15:39:25.403Z DD [File-based Authenticator/impersonator client, user: ftp] send: after on_write(): buf size: 0, err = 0
2025-01-22T15:39:25.403Z DD [File-based Authenticator/impersonator client, user: ftp/impersonator process] fz::impersonator::process::operator()(const fz::event_base&)::<lambda(fz::socket_event_source*, fz::socket_event_flag, int)>: flag: 4, err: 0, eh: 0x61fe53ae6b20
2025-01-22T15:39:25.403Z DD [File-based Authenticator/impersonator client, user: ftp] Channel event: flag = 4
2025-01-22T15:39:25.403Z DD [File-based Authenticator/impersonator client, user: ftp] Channel event: invoking on_read(): buf size: 0
2025-01-22T15:39:25.403Z DD [File-based Authenticator/impersonator client, user: ftp] channel::on_read()
2025-01-22T15:39:25.403Z DD [File-based Authenticator/impersonator client, user: ftp] channel::on_read: trying to deserialize: buf size: 0, fd buf size: 0
2025-01-22T15:39:25.403Z DD [File-based Authenticator/impersonator client, user: ftp] channel::on_read: tried to deserialize: err: 61, buf size: 0, fd buf size: 0
2025-01-22T15:39:25.403Z DD [File-based Authenticator/impersonator client, user: ftp] channel::on_read: trying to deserialize: buf size: 20, fd buf size: 1
2025-01-22T15:39:25.403Z DD [File-based Authenticator/impersonator client, user: ftp] channel::on_read: tried to deserialize: err: 0, buf size: 0, fd buf size: 0
2025-01-22T15:39:25.403Z DD [File-based Authenticator/impersonator client, user: ftp] Channel event: invoked on_read(): buf size: 0, err: 0, can_recv: 1, has_in_msg: 1, waiting_for_read_event: 0
2025-01-22T15:39:25.404Z DD [File-based Authenticator/impersonator client, user: ftp] caller::on_ready: ops: 2
2025-01-22T15:39:25.404Z DD [File-based Authenticator/impersonator client, user: ftp] entering channel::recv
2025-01-22T15:39:25.404Z DD [File-based Authenticator/impersonator client, user: ftp] channel::recv: deserialization: got message 3. Err: 0
2025-01-22T15:39:25.404Z DD [File-based Authenticator/impersonator client, user: ftp] sending socket read event: err: 0, can_recv: 0
2025-01-22T15:39:25.404Z DI [File-based Authenticator/impersonator client, user: ftp] on_can_recv: [fz::rmp::message<fz::tvfs::backend::open_response_tag (fz::result, fz::tvfs::fd_owner)>] processing.
2025-01-22T15:39:25.404Z DD [File-based Authenticator/impersonator client, user: ftp] Stopping timeout timer with id 3.
2025-01-22T15:39:25.404Z DD [File-based Authenticator/impersonator client, user: ftp] Added new timeout timer with id 4.
2025-01-22T15:39:25.404Z DI [File-based Authenticator/impersonator client, user: ftp] [fz::rmp::message<fz::tvfs::backend::open_response_tag (fz::result, fz::tvfs::fd_owner)>]: message contains result: 0 (raw = 0: No error)
2025-01-22T15:39:25.404Z DI [File-based Authenticator/impersonator client, user: ftp] [fz::rmp::message<fz::tvfs::backend::open_response_tag (fz::result, fz::tvfs::fd_owner)>]: dispatching message
2025-01-22T15:39:25.404Z DD [File-based Authenticator/impersonator client, user: ftp] entering channel::recv
2025-01-22T15:39:25.404Z DD [File-based Authenticator/impersonator client, user: ftp] channel::recv: deserialization: not enough data. Try again later.
2025-01-22T15:39:25.404Z DD [FTP Session 46 172.25.0.2 foo] Client wants a secure data connection.
2025-01-22T15:39:25.404Z DD [File-based Authenticator/impersonator client, user: ftp] on_can_recv: got EAGAIN, waiting for next event.
2025-01-22T15:39:25.404Z DD [FTP Session 46 172.25.0.2 foo] securer(1) ENTERING state = 2
2025-01-22T15:39:25.404Z DD [File-based Authenticator/impersonator client, user: ftp] Channel event: flag = 4
2025-01-22T15:39:25.404Z DD [FTP Session 46 172.25.0.2 foo] securer(1) EXITING state = 2
2025-01-22T15:39:25.404Z DD [File-based Authenticator/impersonator client, user: ftp] Channel event: invoking on_read(): buf size: 0
2025-01-22T15:39:25.404Z DD [FTP Session 46 172.25.0.2 foo] The data connection is not secure yet. Waiting for the related connection event.
2025-01-22T15:39:25.404Z DD [File-based Authenticator/impersonator client, user: ftp] channel::on_read()
2025-01-22T15:39:25.404Z DD [FTP Session 46 172.25.0.2 foo] ~securer(1) ENTERING state = 2
2025-01-22T15:39:25.404Z DD [File-based Authenticator/impersonator client, user: ftp] channel::on_read: trying to deserialize: buf size: 0, fd buf size: 0
2025-01-22T15:39:25.404Z DD [FTP Session 46 172.25.0.2 foo] ~securer(1) EXITING state = 2
2025-01-22T15:39:25.404Z DD [File-based Authenticator/impersonator client, user: ftp] channel::on_read: tried to deserialize: err: 61, buf size: 0, fd buf size: 0
2025-01-22T15:39:25.404Z << [FTP Session 46 172.25.0.2 foo] 150 Starting data transfer.
2025-01-22T15:39:25.404Z DD [File-based Authenticator/impersonator client, user: ftp] channel::recv: read_fd: EAGAIN.
2025-01-22T15:39:25.404Z DD [File-based Authenticator/impersonator client, user: ftp] Channel event: invoked on_read(): buf size: 0, err: 0, can_recv: 1, has_in_msg: 0, waiting_for_read_event: 1
2025-01-22T15:39:25.404Z DD [FTP Session 46 172.25.0.2 foo] tls_layer_impl::on_read()
2025-01-22T15:39:25.404Z DV [FTP Session 46 172.25.0.2 foo] tls_layer_impl::continue_handshake()
2025-01-22T15:39:25.404Z DD [FTP Session 46 172.25.0.2 foo] TLS handshakep: Received CLIENT HELLO
2025-01-22T15:39:25.404Z DD [FTP Session 46 172.25.0.2 foo] TLS handshakep: Processed CLIENT HELLO
2025-01-22T15:39:25.404Z DD [FTP Session 46 172.25.0.2 foo] TLS handshakep: About to send SERVER HELLO
2025-01-22T15:39:25.404Z DD [FTP Session 46 172.25.0.2 foo] TLS handshakep: Sent SERVER HELLO
2025-01-22T15:39:25.404Z DD [FTP Session 46 172.25.0.2 foo] TLS handshakep: About to send CERTIFICATE
2025-01-22T15:39:25.404Z DD [FTP Session 46 172.25.0.2 foo] TLS handshakep: Sent CERTIFICATE
2025-01-22T15:39:25.404Z DD [FTP Session 46 172.25.0.2 foo] TLS handshakep: About to send SERVER KEY EXCHANGE
2025-01-22T15:39:25.404Z DD [FTP Session 46 172.25.0.2 foo] TLS handshakep: Sent SERVER KEY EXCHANGE
2025-01-22T15:39:25.404Z DD [FTP Session 46 172.25.0.2 foo] TLS handshakep: About to send SERVER HELLO DONE
2025-01-22T15:39:25.404Z DD [FTP Session 46 172.25.0.2 foo] TLS handshakep: Sent SERVER HELLO DONE
2025-01-22T15:39:25.405Z DD [FTP Session 46 172.25.0.2 foo] tls_layer_impl::on_read()
2025-01-22T15:39:25.405Z DV [FTP Session 46 172.25.0.2 foo] tls_layer_impl::continue_handshake()
2025-01-22T15:39:25.405Z DD [FTP Session 46 172.25.0.2 foo] TLS handshakep: Received CLIENT KEY EXCHANGE
2025-01-22T15:39:25.405Z DD [FTP Session 46 172.25.0.2 foo] TLS handshakep: Processed CLIENT KEY EXCHANGE
2025-01-22T15:39:25.405Z DD [FTP Session 46 172.25.0.2 foo] TLS handshakep: Received FINISHED
2025-01-22T15:39:25.405Z DD [FTP Session 46 172.25.0.2 foo] TLS handshakep: Processed FINISHED
2025-01-22T15:39:25.405Z DD [FTP Session 46 172.25.0.2 foo] TLS handshakep: About to send NEW SESSION TICKET
2025-01-22T15:39:25.405Z DD [FTP Session 46 172.25.0.2 foo] TLS handshakep: Sent NEW SESSION TICKET
2025-01-22T15:39:25.405Z DD [FTP Session 46 172.25.0.2 foo] TLS handshakep: About to send FINISHED
2025-01-22T15:39:25.405Z DD [FTP Session 46 172.25.0.2 foo] TLS handshakep: Sent FINISHED
2025-01-22T15:39:25.405Z DI [FTP Session 46 172.25.0.2 foo] TLS Handshake successful
2025-01-22T15:39:25.405Z DI [FTP Session 46 172.25.0.2 foo] Protocol: TLS1.2, Key exchange: ECDHE-X25519-ECDSA-SHA256, Cipher: AES-256-GCM, MAC: AEAD, ALPN: 
2025-01-22T15:39:25.405Z DV [FTP Session 46 172.25.0.2 foo] session::on_socket_event(): source = data, flag = 2, error = 0, state = 2
2025-01-22T15:39:25.405Z DD [FTP Session 46 172.25.0.2 foo] Client wants a secure data connection.
2025-01-22T15:39:25.405Z DD [FTP Session 46 172.25.0.2 foo] securer(1) ENTERING state = 2
2025-01-22T15:39:25.405Z DD [FTP Session 46 172.25.0.2 foo] securer(1) EXITING state = -1
2025-01-22T15:39:25.405Z DD [FTP Session 46 172.25.0.2 foo] ~securer(1) ENTERING state = -1
2025-01-22T15:39:25.405Z DD [FTP Session 46 172.25.0.2 foo] ~securer(1) EXITING state = -1
2025-01-22T15:39:25.405Z !! [FTP Session 46 172.25.0.2 foo] TLS session of data connection not resumed.
2025-01-22T15:39:25.405Z << [FTP Session 46 172.25.0.2 foo] 425 Unable to build data connection: TLS session of data connection not resumed.
2025-01-22T15:39:25.405Z DD [FTP Session 46 172.25.0.2 foo] session::close_data_connection(): prev data_connection_status = 2
2025-01-22T15:39:25.405Z DD [FTP Session 46 172.25.0.2 foo] Removed done events: 0

Logs with Gnu tls streams against vsftpd

FluentFtpLogs

2025-01-22T10:24:43.098203059Z # Connect(False)  
2025-01-22T10:24:43.098420563Z Status:   FluentFTP 52.0.0.0(.NET 7.0) AsyncFtpClient  
2025-01-22T10:24:43.099810988Z Status:   Connecting(async) AsyncFtpClient.FtpSocketStream(control) IP #1 = ***:21  
2025-01-22T10:24:43.102452652Z Status:   Waiting for a response  
2025-01-22T10:24:43.105082678Z Response: 220 (vsFTPd 3.0.5) [739272.434d]  
2025-01-22T10:24:43.106281163Z Status:   Detected FTP server: VsFTPd  
2025-01-22T10:24:43.107015978Z Command:  AUTH TLS  
2025-01-22T10:24:43.107542016Z Status:   Waiting for response to: AUTH TLS  
2025-01-22T10:24:43.107658549Z Response: 234 Proceed with negotiation. [<1ms]  
2025-01-22T10:24:43.123343952Z Status:   GnuTLS: 0   FluentFTP.GnuTLS 1.0.31.0(Unix/.NET 6.0) / GnuTLS 3.8.5  
2025-01-22T10:24:43.156933220Z Status:   FTPS authentication successful, lib = FluentFTP.GnuTLS.GnuTlsStream, cipher suite = (TLS1.3)-(ECDHE-SECP256R1)  
-(RSA-PSS-RSAE-SHA256)-(AES-256-GCM) [47ms]  
2025-01-22T10:24:43.157774315Z Command:  USER ***  
2025-01-22T10:24:43.159446933Z Status:   Waiting for response to: USER ***  
2025-01-22T10:24:43.162404563Z Response: 331 Please specify the password. [3ms]  
2025-01-22T10:24:43.162890507Z Command:  PASS ***  
2025-01-22T10:24:43.162992490Z Status:   Waiting for response to: PASS ***  
2025-01-22T10:24:44.165547558Z Response: 230 Login successful. [1.002s]  
2025-01-22T10:24:44.170045873Z Command:  PBSZ 0  
2025-01-22T10:24:44.170563128Z Status:   Waiting for response to: PBSZ 0  
2025-01-22T10:24:45.172555716Z Response: 200 PBSZ set to 0. [1.002s]  
2025-01-22T10:24:45.173245198Z Command:  PROT P  
2025-01-22T10:24:45.173620844Z Status:   Waiting for response to: PROT P  
2025-01-22T10:24:46.175448294Z Response: 200 PROT now Private. [1.002s]  
2025-01-22T10:24:46.176488955Z Command:  FEAT  
2025-01-22T10:24:46.176902856Z Status:   Waiting for response to: FEAT  
2025-01-22T10:24:47.182778823Z Response: 211-Features:  
2025-01-22T10:24:47.183419163Z Response: EPRT  
2025-01-22T10:24:47.183678703Z Response: EPSV  
2025-01-22T10:24:47.183871101Z Response: MDTM  
2025-01-22T10:24:47.184049796Z Response: PASV  
2025-01-22T10:24:47.184210182Z Response: PBSZ  
2025-01-22T10:24:47.184400325Z Response: PROT  
2025-01-22T10:24:47.184583331Z Response: REST STREAM  
2025-01-22T10:24:47.184767452Z Response: SIZE  
2025-01-22T10:24:47.184946759Z Response: TVFS  
2025-01-22T10:24:47.185122849Z Response: 211 End [1.006s]  
2025-01-22T10:24:47.186640343Z Status:   Text encoding: System.Text.ASCIIEncoding+ASCIIEncodingSealed  
2025-01-22T10:24:47.186987530Z Command:  SYST  
2025-01-22T10:24:47.187214248Z Status:   Waiting for response to: SYST  
2025-01-22T10:24:48.188210659Z Response: 215 UNIX Type: L8 [1.001s]  
2025-01-22T10:24:48.190700310Z Status:   Active ServerHandler is: VsFTPd  
2025-01-22T10:24:48.191825946Z Status:   Listing parser set to: Unix  
2025-01-22T10:24:48.194134302Z Command:  PWD  
2025-01-22T10:24:48.194596380Z Status:   Waiting for response to: PWD  
2025-01-22T10:24:49.195727996Z Response: 257 "/home/vsftp" is the current directory [1.001s]  
2025-01-22T10:24:49.204780920Z    
2025-01-22T10:24:49.204787873Z # DirectoryExists("/home/vsftp/ftp/pics")  
2025-01-22T10:24:49.205283578Z Command:  CWD /home/vsftp/ftp/pics  
2025-01-22T10:24:49.205487063Z Status:   Waiting for response to: CWD /home/vsftp/ftp/pics  
2025-01-22T10:24:50.208747699Z Response: 250 Directory successfully changed. [1.003s]  
2025-01-22T10:24:50.209560479Z Command:  CWD /home/vsftp  
2025-01-22T10:24:50.210158203Z Status:   Waiting for response to: CWD /home/vsftp  
2025-01-22T10:24:51.211510954Z Response: 250 Directory successfully changed. [1.001s]  
2025-01-22T10:24:51.215415727Z    
2025-01-22T10:24:51.215422602Z # UploadStream("/home/vsftp/ftp/pics/testing.txt", NoCheck, False)  
2025-01-22T10:24:51.224832587Z    
2025-01-22T10:24:51.224836658Z # OpenWrite("/home/vsftp/ftp/pics/testing.txt", Binary, -1, False)  
2025-01-22T10:24:51.226624006Z Command:  TYPE I  
2025-01-22T10:24:51.226919445Z Status:   Waiting for response to: TYPE I  
2025-01-22T10:24:52.228278569Z Response: 200 Switching to Binary mode. [1.001s]  
2025-01-22T10:24:52.232186746Z    
2025-01-22T10:24:52.232189853Z # OpenDataStreamAsync("STOR /home/vsftp/ftp/pics/testing.txt", 0)  
2025-01-22T10:24:52.236256552Z    
2025-01-22T10:24:52.236261312Z # OpenPassiveDataStreamAsync(AutoPassive, "STOR /home/vsftp/ftp/pics/testing.txt", 0)  
2025-01-22T10:24:52.236621129Z Command:  EPSV  
2025-01-22T10:24:52.236857170Z Status:   Waiting for response to: EPSV  
2025-01-22T10:24:53.238198501Z Response: 229 Entering Extended Passive Mode (|||10441|) [1.001s]  
2025-01-22T10:24:53.244216360Z Status:   Connecting(async) AsyncFtpClient.FtpSocketStream(data) IP #1 = ***:10441  
2025-01-22T10:24:53.249269828Z Command:  STOR /home/vsftp/ftp/pics/testing.txt  
2025-01-22T10:24:53.249533084Z Status:   Waiting for response to: STOR /home/vsftp/ftp/pics/testing.txt  
2025-01-22T10:24:54.250842485Z Response: 150 Ok to send data. [1.001s]  
2025-01-22T10:24:54.289559797Z Status:   FTPS authentication successful, lib = FluentFTP.GnuTLS.GnuTlsStream, cipher suite = (TLS1.3)-(ECDHE-PSK-SECP25  
6R1)-(AES-256-GCM) [38ms]  
2025-01-22T10:24:54.292643092Z Status:   Uploaded 20 bytes, 1ms, 19.5 KB/s  
2025-01-22T10:24:54.293430444Z Status:   Disposing(async) AsyncFtpClient.FtpSocketStream(data)  
2025-01-22T10:24:55.306202829Z Status:   Waiting for response to: STOR /home/vsftp/ftp/pics/testing.txt  
2025-01-22T10:24:55.306715705Z Response: 226 Transfer complete. [2.057s]  
2025-01-22T10:24:55.309344486Z [INF] [Thread-24 |FtpService                    |116] [File was successfully sent over FTP]  
2025-01-22T10:24:55.310676147Z [INF] [Thread-24 |FtpService                    |119] [FTP SendFileAsync Runtime 12.2152273s]  
2025-01-22T10:24:55.316540848Z [INF] [Thread-24 |FileSavedRequestHandler       | 39] [Sending FileSavedIntegrationEvent]  
2025-01-22T10:24:55.352792611Z    
2025-01-22T10:24:55.352799694Z # DirectoryExists("/home/vsftp/ftp/pics")  
2025-01-22T10:24:55.353298604Z Command:  CWD /home/vsftp/ftp/pics  
2025-01-22T10:24:55.353550139Z Status:   Waiting for response to: CWD /home/vsftp/ftp/pics  
2025-01-22T10:24:56.354709237Z Response: 250 Directory successfully changed. [1.001s]  
2025-01-22T10:24:56.355445322Z Command:  CWD /home/vsftp  
2025-01-22T10:24:56.355968654Z Status:   Waiting for response to: CWD /home/vsftp  
2025-01-22T10:24:57.357332361Z Response: 250 Directory successfully changed. [1.002s]  
2025-01-22T10:24:57.360450148Z    
2025-01-22T10:24:57.360457598Z # DeleteFile("/home/vsftp/ftp/pics/testing.txt")  
2025-01-22T10:24:57.361085630Z Command:  DELE /home/vsftp/ftp/pics/testing.txt  
2025-01-22T10:24:57.361456601Z Status:   Waiting for response to: DELE /home/vsftp/ftp/pics/testing.txt  
2025-01-22T10:24:58.362787944Z Response: 250 Delete operation successful. [1.002s]

vsftpd server logs

Wed Jan 22 11:24:43 2025 [pid 31257] CONNECT: Client "172.25.0.2"  
Wed Jan 22 11:24:43 2025 [pid 31257] FTP response: Client "172.25.0.2", "220 (vsFTPd 3.0.5)"  
Wed Jan 22 11:24:43 2025 [pid 31257] FTP command: Client "172.25.0.2", "AUTH TLS"  
Wed Jan 22 11:24:43 2025 [pid 31257] FTP response: Client "172.25.0.2", "234 Proceed with negotiation."  
Wed Jan 22 11:24:43 2025 [pid 31257] FTP command: Client "172.25.0.2", "USER vsftp"  
Wed Jan 22 11:24:43 2025 [pid 31257] [vsftp] FTP response: Client "172.25.0.2", "331 Please specify the password."  
Wed Jan 22 11:24:43 2025 [pid 31257] [vsftp] FTP command: Client "172.25.0.2", "PASS <password>"  
Wed Jan 22 11:24:43 2025 [pid 31256] [vsftp] OK LOGIN: Client "172.25.0.2"  
Wed Jan 22 11:24:43 2025 [pid 31259] [vsftp] FTP response: Client "172.25.0.2", "230 Login successful."  
Wed Jan 22 11:24:44 2025 [pid 31259] [vsftp] FTP command: Client "172.25.0.2", "PBSZ 0"  
Wed Jan 22 11:24:44 2025 [pid 31259] [vsftp] FTP response: Client "172.25.0.2", "200 PBSZ set to 0."  
Wed Jan 22 11:24:45 2025 [pid 31259] [vsftp] FTP command: Client "172.25.0.2", "PROT P"  
Wed Jan 22 11:24:45 2025 [pid 31259] [vsftp] FTP response: Client "172.25.0.2", "200 PROT now Private."  
Wed Jan 22 11:24:46 2025 [pid 31259] [vsftp] FTP command: Client "172.25.0.2", "FEAT"  
Wed Jan 22 11:24:46 2025 [pid 31259] [vsftp] FTP response: Client "172.25.0.2", "211-Features:"  
Wed Jan 22 11:24:46 2025 [pid 31259] [vsftp] FTP response: Client "172.25.0.2", " EPRT??"  
Wed Jan 22 11:24:46 2025 [pid 31259] [vsftp] FTP response: Client "172.25.0.2", " EPSV??"  
Wed Jan 22 11:24:46 2025 [pid 31259] [vsftp] FTP response: Client "172.25.0.2", " MDTM??"  
Wed Jan 22 11:24:46 2025 [pid 31259] [vsftp] FTP response: Client "172.25.0.2", " PASV??"  
Wed Jan 22 11:24:46 2025 [pid 31259] [vsftp] FTP response: Client "172.25.0.2", " PBSZ??"  
Wed Jan 22 11:24:46 2025 [pid 31259] [vsftp] FTP response: Client "172.25.0.2", " PROT??"  
Wed Jan 22 11:24:46 2025 [pid 31259] [vsftp] FTP response: Client "172.25.0.2", " REST STREAM??"  
Wed Jan 22 11:24:46 2025 [pid 31259] [vsftp] FTP response: Client "172.25.0.2", " SIZE??"  
Wed Jan 22 11:24:46 2025 [pid 31259] [vsftp] FTP response: Client "172.25.0.2", " TVFS??"  
Wed Jan 22 11:24:46 2025 [pid 31259] [vsftp] FTP response: Client "172.25.0.2", "211 End"  
Wed Jan 22 11:24:47 2025 [pid 31259] [vsftp] FTP command: Client "172.25.0.2", "SYST"  
Wed Jan 22 11:24:47 2025 [pid 31259] [vsftp] FTP response: Client "172.25.0.2", "215 UNIX Type: L8"  
Wed Jan 22 11:24:48 2025 [pid 31259] [vsftp] FTP command: Client "172.25.0.2", "PWD"  
Wed Jan 22 11:24:48 2025 [pid 31259] [vsftp] FTP response: Client "172.25.0.2", "257 "/home/vsftp" is the current directory"  
Wed Jan 22 11:24:49 2025 [pid 31259] [vsftp] FTP command: Client "172.25.0.2", "CWD /home/vsftp/ftp/pics"  
Wed Jan 22 11:24:49 2025 [pid 31259] [vsftp] FTP response: Client "172.25.0.2", "250 Directory successfully changed."  
Wed Jan 22 11:24:50 2025 [pid 31259] [vsftp] FTP command: Client "172.25.0.2", "CWD /home/vsftp"  
Wed Jan 22 11:24:50 2025 [pid 31259] [vsftp] FTP response: Client "172.25.0.2", "250 Directory successfully changed."  
Wed Jan 22 11:24:51 2025 [pid 31259] [vsftp] FTP command: Client "172.25.0.2", "TYPE I"  
Wed Jan 22 11:24:51 2025 [pid 31259] [vsftp] FTP response: Client "172.25.0.2", "200 Switching to Binary mode."  
Wed Jan 22 11:24:52 2025 [pid 31259] [vsftp] FTP command: Client "172.25.0.2", "EPSV"  
Wed Jan 22 11:24:52 2025 [pid 31259] [vsftp] FTP response: Client "172.25.0.2", "229 Entering Extended Passive Mode (|||10441|)"  
Wed Jan 22 11:24:53 2025 [pid 31259] [vsftp] FTP command: Client "172.25.0.2", "STOR /home/vsftp/ftp/pics/testing.txt"  
Wed Jan 22 11:24:53 2025 [pid 31259] [vsftp] FTP response: Client "172.25.0.2", "150 Ok to send data."  
Wed Jan 22 11:24:54 2025 [pid 31259] [vsftp] OK UPLOAD: Client "172.25.0.2", "/home/vsftp/ftp/pics/testing.txt", 20 bytes, 0.02Kbyte/sec  
Wed Jan 22 11:24:54 2025 [pid 31259] [vsftp] FTP response: Client "172.25.0.2", "226 Transfer complete."  
Wed Jan 22 11:24:55 2025 [pid 31259] [vsftp] FTP command: Client "172.25.0.2", "CWD /home/vsftp/ftp/pics"  
Wed Jan 22 11:24:55 2025 [pid 31259] [vsftp] FTP response: Client "172.25.0.2", "250 Directory successfully changed."  
Wed Jan 22 11:24:56 2025 [pid 31259] [vsftp] FTP command: Client "172.25.0.2", "CWD /home/vsftp"  
Wed Jan 22 11:24:56 2025 [pid 31259] [vsftp] FTP response: Client "172.25.0.2", "250 Directory successfully changed."  
Wed Jan 22 11:24:57 2025 [pid 31259] [vsftp] FTP command: Client "172.25.0.2", "DELE /home/vsftp/ftp/pics/testing.txt"  
Wed Jan 22 11:24:57 2025 [pid 31259] [vsftp] OK DELETE: Client "172.25.0.2", "/home/vsftp/ftp/pics/testing.txt"  
Wed Jan 22 11:24:57 2025 [pid 31259] [vsftp] FTP response: Client "172.25.0.2", "250 Delete operation successful."

Thanks & any further ideas are much appreciated.

@FanDjango
Copy link
Collaborator

FanDjango commented Jan 22, 2025

I think I have found out what is happening.

The stream read and write methods pause for 1 second on a non-success return code.

With detailed logging, we would see the associated error message.

Here is how to increase the logging verbosity:

			client.Config.CustomStream = typeof(GnuTlsStream);
			client.Config.CustomStreamConfig = new GnuConfig() {
				SetALPNControlConnection = string.Empty,
				SetALPNDataConnection = string.Empty,
				LogLevel = 1,
				LogMessages = GnuMessage.All | GnuMessage.ReadControl | GnuMessage.WriteControl,
			};

There is definitely something going wrong - funny that is seems to be only on your build.

So let's check the error message.

It should be of the form: *GnuTlsRecordRecv(...) repeat due to ... or *GnuTlsRecordSend(...) repeat due to ...

@FanDjango
Copy link
Collaborator

Please note that I have edited the config code snippet in the previous post after some testing here locally.

@regnisier
Copy link
Author

Thanks for the code for increasing the log output. I tried with additional logs and it seems your assumption is correct. Before the 1 sec delays occur I can see following errors:

2025-01-23T13:04:00.359788297Z Status:   Waiting for response to: OPTS UTF8 ON  
2025-01-23T13:04:00.359815577Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.359854087Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(...) repeat due to GNUTLS_E_AGAIN  
2025-01-23T13:04:00.359880456Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(...) repeat due to GNUTLS_E_AGAIN  
2025-01-23T13:04:00.359907020Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(...) repeat due to GNUTLS_E_AGAIN  
2025-01-23T13:04:01.340457362Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(...) 3 repeats overall  
2025-01-23T13:04:01.341195911Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1) 

Do I understand it correctly that GNUTLS_E_AGAIN are not bad per se? It seems to me that GnuTLS waits for response and raisese the GNUTLS_E_AGAIN very quickly. On the third try it seems to add one second delay. It looks like the delay is started before filezilla server responds and when it responds GnuTLS is already in the 1 second sleep. Like here:

2025-01-23T13:04:03.357475387Z    
2025-01-23T13:04:03.357480077Z # DirectoryExists("/home/ftp/pic")  
2025-01-23T13:04:03.357790964Z Command:  CWD /home/ftp/pic  
2025-01-23T13:04:03.358000948Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordSend(..., 0, 19)  
2025-01-23T13:04:03.358179279Z Status:   Waiting for response to: CWD /home/ftp/pic  
2025-01-23T13:04:03.358361119Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:03.358546956Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(...) repeat due to GNUTLS_E_AGAIN  
2025-01-23T13:04:03.358715063Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(...) repeat due to GNUTLS_E_AGAIN  
2025-01-23T13:04:03.358877404Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(...) repeat due to GNUTLS_E_AGAIN  
2025-01-23T13:04:04.358955594Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(...) 3 repeats overall  
2025-01-23T13:04:04.359801937Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  

Client sends a CWD and after waiting only 1 ms. Server needs more time though to answer:

2025-01-23T13:04:04.362Z DD [FTP Session 73 172.25.0.2 foo] tls_layer_impl::on_read()
2025-01-23T13:04:04.362Z >> [FTP Session 73 172.25.0.2 foo] CWD /
2025-01-23T13:04:04.362Z << [FTP Session 73 172.25.0.2 foo] 250 CWD command successful
2025-01-23T13:04:05.374Z DD [FTP Session 73 172.25.0.2 foo] tls_layer_impl::on_read()

When it sends CWD command successful 5ms later the client seems to be in sleep mode already.

I am also very curious why this only happens on my versions. I am using FluentFtp.GnuTLS Version 1.0.31 with FluentFtp Version 52.0.0.

How long does GnuTLS usually wait until it sends GNUTLS_E_AGAIN? Can it be configured how many repeats of the error can happen before it blocks? Or can maybe the time inbetween the repeats be configured?

Here are the full logs:

FluentFtp logs

2025-01-23T13:03:56.241780736Z    
2025-01-23T13:03:56.241792286Z # Connect(False)  
2025-01-23T13:03:56.241933904Z Status:   FluentFTP 52.0.0.0(.NET 7.0) AsyncFtpClient  
2025-01-23T13:03:56.243442365Z Status:   Connecting(async) AsyncFtpClient.FtpSocketStream(control) IP #1 = ***:21  
2025-01-23T13:03:56.246048439Z Status:   Waiting for a response  
2025-01-23T13:03:56.248048733Z Response: 220-FileZilla Server 1.9.4  
2025-01-23T13:03:56.248415017Z Response: 220 Please visit https://filezilla-project.org/ [739273.544d]  
2025-01-23T13:03:56.249578279Z Status:   Detected FTP server: FileZilla  
2025-01-23T13:03:56.250342831Z Command:  AUTH TLS  
2025-01-23T13:03:56.250834749Z Status:   Waiting for response to: AUTH TLS  
2025-01-23T13:03:56.252424936Z Response: 234 Using authentication type TLS. [1ms]  
2025-01-23T13:03:56.256021480Z Status:   GnuTLS: 1   Interop : *GnuTlsCheckVersion(...)  
2025-01-23T13:03:56.256668525Z Status:   GnuTLS: 1   Interop : *Load (Load.dll libraries)  
2025-01-23T13:03:56.258404879Z Status:   GnuTLS: 1   Interop : *Load (Loaded: libgnutls.so.30)  
2025-01-23T13:03:56.258760547Z Status:   GnuTLS: 1   Interop : *LoadFunction (Found entry 'gnutls_check_version')  
2025-01-23T13:03:56.258977175Z Status:   GnuTLS: 1   Interop : *LoadFunction (Found entry 'gnutls_global_set_log_function')  
2025-01-23T13:03:56.259199973Z Status:   GnuTLS: 1   Interop : *LoadFunction (Found entry 'gnutls_global_set_log_level')  
2025-01-23T13:03:56.259323169Z Status:   GnuTLS: 1   Interop : *LoadFunction (Found entry 'gnutls_global_init')  
2025-01-23T13:03:56.259450681Z Status:   GnuTLS: 1   Interop : *LoadFunction (Found entry 'gnutls_global_deinit')  
2025-01-23T13:03:56.259555592Z Status:   GnuTLS: 1   Interop : *LoadFunction (Found entry 'gnutls_free')  
2025-01-23T13:03:56.259612254Z Status:   GnuTLS: 1   Interop : *LoadFunction (Found entry 'gnutls_init')  
2025-01-23T13:03:56.259758704Z Status:   GnuTLS: 1   Interop : *LoadFunction (Found entry 'gnutls_deinit')  
2025-01-23T13:03:56.259834590Z Status:   GnuTLS: 1   Interop : *LoadFunction (Found entry 'gnutls_db_set_cache_expiration')  
2025-01-23T13:03:56.259865681Z Status:   GnuTLS: 1   Interop : *LoadFunction (Found entry 'gnutls_session_get_desc')  
2025-01-23T13:03:56.259891697Z Status:   GnuTLS: 1   Interop : *LoadFunction (Found entry 'gnutls_protocol_get_name')  
2025-01-23T13:03:56.259945295Z Status:   GnuTLS: 1   Interop : *LoadFunction (Found entry 'gnutls_protocol_get_version')  
2025-01-23T13:03:56.260018622Z Status:   GnuTLS: 1   Interop : *LoadFunction (Found entry 'gnutls_record_get_max_size')  
2025-01-23T13:03:56.260077575Z Status:   GnuTLS: 1   Interop : *LoadFunction (Found entry 'gnutls_alert_get')  
2025-01-23T13:03:56.260152160Z Status:   GnuTLS: 1   Interop : *LoadFunction (Found entry 'gnutls_alert_get_name')  
2025-01-23T13:03:56.260185699Z Status:   GnuTLS: 1   Interop : *LoadFunction (Found entry 'gnutls_error_is_fatal')  
2025-01-23T13:03:56.260209244Z Status:   GnuTLS: 1   Interop : *LoadFunction (Found entry 'gnutls_handshake')  
2025-01-23T13:03:56.260231719Z Status:   GnuTLS: 1   Interop : *LoadFunction (Found entry 'gnutls_handshake_set_hook_function')  
2025-01-23T13:03:56.260343145Z Status:   GnuTLS: 1   Interop : *LoadFunction (Found entry 'gnutls_bye')  
2025-01-23T13:03:56.260424406Z Status:   GnuTLS: 1   Interop : *LoadFunction (Found entry 'gnutls_handshake_set_timeout')  
2025-01-23T13:03:56.260466348Z Status:   GnuTLS: 1   Interop : *LoadFunction (Found entry 'gnutls_record_check_pending')  
2025-01-23T13:03:56.260498454Z Status:   GnuTLS: 1   Interop : *LoadFunction (Found entry 'gnutls_set_default_priority')  
2025-01-23T13:03:56.260529767Z Status:   GnuTLS: 1   Interop : *LoadFunction (Found entry 'gnutls_priority_set_direct')  
2025-01-23T13:03:56.260677463Z Status:   GnuTLS: 1   Interop : *LoadFunction (Found entry 'gnutls_set_default_priority_append')  
2025-01-23T13:03:56.260892104Z Status:   GnuTLS: 1   Interop : *LoadFunction (Found entry 'gnutls_dh_set_prime_bits')  
2025-01-23T13:03:56.260979420Z Status:   GnuTLS: 1   Interop : *LoadFunction (Found entry 'gnutls_transport_set_ptr')  
2025-01-23T13:03:56.261038130Z Status:   GnuTLS: 1   Interop : *LoadFunction (Found entry 'gnutls_record_recv')  
2025-01-23T13:03:56.261082845Z Status:   GnuTLS: 1   Interop : *LoadFunction (Found entry 'gnutls_record_send')  
2025-01-23T13:03:56.261142533Z Status:   GnuTLS: 1   Interop : *LoadFunction (Found entry 'gnutls_session_is_resumed')  
2025-01-23T13:03:56.261188131Z Status:   GnuTLS: 1   Interop : *LoadFunction (Found entry 'gnutls_session_get_data2')  
2025-01-23T13:03:56.261253035Z Status:   GnuTLS: 1   Interop : *LoadFunction (Found entry 'gnutls_session_set_data')  
2025-01-23T13:03:56.261302013Z Status:   GnuTLS: 1   Interop : *LoadFunction (Found entry 'gnutls_session_get_flags')  
2025-01-23T13:03:56.261352067Z Status:   GnuTLS: 1   Interop : *LoadFunction (Found entry 'gnutls_alpn_set_protocols')  
2025-01-23T13:03:56.261426273Z Status:   GnuTLS: 1   Interop : *LoadFunction (Found entry 'gnutls_alpn_get_selected_protocol')  
2025-01-23T13:03:56.261479788Z Status:   GnuTLS: 1   Interop : *LoadFunction (Found entry 'gnutls_certificate_allocate_credentials')  
2025-01-23T13:03:56.261531475Z Status:   GnuTLS: 1   Interop : *LoadFunction (Found entry 'gnutls_certificate_free_credentials')  
2025-01-23T13:03:56.261584048Z Status:   GnuTLS: 1   Interop : *LoadFunction (Found entry 'gnutls_credentials_set')  
2025-01-23T13:03:56.261609421Z Status:   GnuTLS: 1   Interop : *LoadFunction (Found entry 'gnutls_certificate_client_get_request_status')  
2025-01-23T13:03:56.261636787Z Status:   GnuTLS: 1   Interop : *LoadFunction (Found entry 'gnutls_certificate_verify_peers3')  
2025-01-23T13:03:56.261811880Z Status:   GnuTLS: 1   Interop : *LoadFunction (Found entry 'gnutls_certificate_type_get2')  
2025-01-23T13:03:56.261900698Z Status:   GnuTLS: 1   Interop : *LoadFunction (Found entry 'gnutls_certificate_get_peers')  
2025-01-23T13:03:56.261975154Z Status:   GnuTLS: 1   Interop : *LoadFunction (Found entry 'gnutls_certificate_set_x509_system_trust')  
2025-01-23T13:03:56.262013087Z Status:   GnuTLS: 1   Interop : *LoadFunction (Found entry 'gnutls_certificate_set_x509_key_mem2')  
2025-01-23T13:03:56.262198390Z Status:   GnuTLS: 1   Interop : *LoadFunction (Found entry 'gnutls_x509_crt_init')  
2025-01-23T13:03:56.262230829Z Status:   GnuTLS: 1   Interop : *LoadFunction (Found entry 'gnutls_x509_crt_deinit')  
2025-01-23T13:03:56.262252102Z Status:   GnuTLS: 1   Interop : *LoadFunction (Found entry 'gnutls_x509_crt_import')  
2025-01-23T13:03:56.262306832Z Status:   GnuTLS: 1   Interop : *LoadFunction (Found entry 'gnutls_x509_crt_print')  
2025-01-23T13:03:56.262408109Z Status:   GnuTLS: 1   Interop : *LoadFunction (Found entry 'gnutls_x509_crt_export2')  
2025-01-23T13:03:56.262481878Z Status:   GnuTLS: 1   Interop : *LoadFunction (Found entry 'gnutls_pcert_import_rawpk_raw')  
2025-01-23T13:03:56.262588508Z Status:   GnuTLS: 0   FluentFTP.GnuTLS 1.0.31.0(Unix/.NET 6.0) / GnuTLS 3.8.5  
2025-01-23T13:03:56.262625100Z Status:   GnuTLS: 1   Interop : *GnuTlsGlobalSetLogFunction(...)  
2025-01-23T13:03:56.262666405Z Status:   GnuTLS: 1   Interop : *GnuTlsGlobalSetLogLevel(...)  
2025-01-23T13:03:56.262707659Z Status:   GnuTLS: 1   Interop : *GnuTlsGlobalInit(...)  
2025-01-23T13:03:56.262982416Z Status:   GnuTLS: 1   Interop : *.ctor(...):CertificateCredentials  
2025-01-23T13:03:56.263018711Z Status:   GnuTLS: 1   Interop : *GnuTlsCertificateSetX509SystemTrust(...)  
2025-01-23T13:03:56.274035282Z Status:   GnuTLS: 1   Interop : Processed 149 certificates in system X509 trust list  
2025-01-23T13:03:56.274169018Z Status:   GnuTLS: 1   Interop : *SetupClientCertificates(...) - currently being implemented  
2025-01-23T13:03:56.274300752Z Status:   GnuTLS: 1   Interop : *.ctor(...):Session  
2025-01-23T13:03:56.274647421Z Status:   GnuTLS: 1   Interop : *GnuTlsDbSetCacheExpiration(...)  
2025-01-23T13:03:56.274723026Z Status:   GnuTLS: 1   Interop : *GnuTlsPrioritySetDirect(...)(NORMAL)  
2025-01-23T13:03:56.274758148Z Status:   GnuTLS: 1   Interop : *GnuTlsDhSetPrimeBits(...)  
2025-01-23T13:03:56.274782278Z Status:   GnuTLS: 1   Interop : *GnuTlsCredentialsSet(...)  
2025-01-23T13:03:56.274882576Z Status:   GnuTLS: 1   Interop : *GnuTlsTransportSetPtr(...)  
2025-01-23T13:03:56.274972931Z Status:   GnuTLS: 1   Interop : *GnuTlsHandshakeSetTimeout(...)  
2025-01-23T13:03:56.275048366Z Status:   GnuTLS: 1   Interop : *GnuTlsHandshakeSetHookFunction(...)  
2025-01-23T13:03:56.275209089Z Status:   GnuTLS: 1   Interop : *GnuTlsHandShake(...)  
2025-01-23T13:03:56.276067267Z Status:   GnuTLS: 1   Interop : Handshake about to send GNUTLS_HANDSHAKE_CLIENT_HELLO  
2025-01-23T13:03:56.276151337Z Status:   GnuTLS: 1   Interop : Handshake sent GNUTLS_HANDSHAKE_CLIENT_HELLO  
2025-01-23T13:03:56.276736653Z Status:   GnuTLS: 1   Interop : Handshake received GNUTLS_HANDSHAKE_SERVER_HELLO  
2025-01-23T13:03:56.276828169Z Status:   GnuTLS: 1   Interop : Handshake processed GNUTLS_HANDSHAKE_SERVER_HELLO  
2025-01-23T13:03:56.276969091Z Status:   GnuTLS: 1   Interop : Handshake received GNUTLS_HANDSHAKE_ENCRYPTED_EXTENSIONS  
2025-01-23T13:03:56.277034807Z Status:   GnuTLS: 1   Interop : Handshake processed GNUTLS_HANDSHAKE_ENCRYPTED_EXTENSIONS  
2025-01-23T13:03:56.277064403Z Status:   GnuTLS: 1   Interop : Handshake received GNUTLS_HANDSHAKE_CERTIFICATE_PKT  
2025-01-23T13:03:56.277086838Z Status:   GnuTLS: 1   Interop : Handshake processed GNUTLS_HANDSHAKE_CERTIFICATE_PKT  
2025-01-23T13:03:56.277110796Z Status:   GnuTLS: 1   Interop : Handshake received GNUTLS_HANDSHAKE_CERTIFICATE_VERIFY  
2025-01-23T13:03:56.277134919Z Status:   GnuTLS: 1   Interop : Handshake processed GNUTLS_HANDSHAKE_CERTIFICATE_VERIFY  
2025-01-23T13:03:56.277314658Z Status:   GnuTLS: 1   Interop : Handshake received GNUTLS_HANDSHAKE_FINISHED  
2025-01-23T13:03:56.277352672Z Status:   GnuTLS: 1   Interop : Handshake processed GNUTLS_HANDSHAKE_FINISHED  
2025-01-23T13:03:56.277375721Z Status:   GnuTLS: 1   Interop : Handshake about to send GNUTLS_HANDSHAKE_FINISHED  
2025-01-23T13:03:56.277396159Z Status:   GnuTLS: 1   Interop : Handshake sent GNUTLS_HANDSHAKE_FINISHED  
2025-01-23T13:03:56.277644163Z Status:   GnuTLS: 1   Interop : *GnuTlsProtocolGetVersion(...)  
2025-01-23T13:03:56.277672131Z Status:   GnuTLS: 1   Interop : *GnuTlsProtocolGetName(...)  
2025-01-23T13:03:56.277741286Z Status:   GnuTLS: 1   Interop : *GnuTlsSessionGetDesc(...)  
2025-01-23T13:03:56.277825603Z Status:   GnuTLS: 1   Interop : *GnuTlsAlpnGetSelectedProtocol(...)  
2025-01-23T13:03:56.278019537Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordGetMaxSize(...)  
2025-01-23T13:03:56.278111483Z Status:   GnuTLS: 1   Interop : Maximum record size: 16384  
2025-01-23T13:03:56.278174588Z Status:   GnuTLS: 1   Interop : *GnuTlsCertificateClientGetRequestStatus(...)  
2025-01-23T13:03:56.278229314Z Status:   GnuTLS: 1   Interop : Server did not request client certificate  
2025-01-23T13:03:56.278288092Z Status:   GnuTLS: 1   Interop : *GnuTlsCertificateVerifyPeers3(...)  
2025-01-23T13:03:56.278960288Z Status:   GnuTLS: 1   Interop : Internal server certificate validation function reports:  
2025-01-23T13:03:56.279003440Z Status:   GnuTLS: 1   Interop : INVALID, SIGNER_NOT_FOUND, UNEXPECTED_OWNER  
2025-01-23T13:03:56.279027273Z Status:   GnuTLS: 1   Interop : *GnuTlsCertificateTypeGet2(...)  
2025-01-23T13:03:56.279181431Z Status:   GnuTLS: 1   Interop : *GnuTlsCertificateGetPeers(...)  
2025-01-23T13:03:56.279254408Z Status:   GnuTLS: 1   Interop : Certificate type: X.509, list contains 1 certificate  
2025-01-23T13:03:56.279311781Z Status:   GnuTLS: 1   Interop : Certificate #1  
2025-01-23T13:03:56.279369298Z Status:   GnuTLS: 1   Interop : *GnuTlsX509CrtInit(...)  
2025-01-23T13:03:56.279426394Z Status:   GnuTLS: 1   Interop : *GnuTlsX509CrtImport(...)  
2025-01-23T13:03:56.279483164Z Status:   GnuTLS: 1   Interop : *GnuTlsX509CrtPrint(...)  
2025-01-23T13:03:56.280080425Z Status:   GnuTLS: 1   Interop : X.509 Certificate Information:  
2025-01-23T13:03:56.280114206Z  Version: 3  
[censored] 
2025-01-23T13:03:56.281294217Z Status:   GnuTLS: 1   Interop : *GnuTlsFree(...)  
2025-01-23T13:03:56.281314629Z Status:   GnuTLS: 1   Interop : *GnuTlsX509CrtDeinit(...)  
2025-01-23T13:03:56.308440264Z Status:   FTPS authentication successful, lib = FluentFTP.GnuTLS.GnuTlsStream, cipher suite = (TLS1.3)-(ECDHE-SECP256R1)-(ECDSA-SECP256R1-SHA256)-(AES-256-GCM) [54ms]  
2025-01-23T13:03:56.310584135Z Command:  USER ***  
2025-01-23T13:03:56.312091996Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordSend(..., 0, 10)  
2025-01-23T13:03:56.313982563Z Status:   Waiting for response to: USER ***  
2025-01-23T13:03:56.315039199Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:56.315394520Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:56.315642889Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:56.315857120Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:56.316054257Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:56.316242320Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:56.316420454Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:56.316611483Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:56.316784937Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:56.316947075Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:56.317118562Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:56.317283113Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:56.317445923Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:56.317623887Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:56.317794560Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:56.317966648Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:56.318135883Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:56.318341984Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:56.318520404Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:56.318600607Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:56.318666839Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:56.318737377Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:56.318811923Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:56.318874895Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:56.318938271Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:56.319004570Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:56.319065119Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:56.319137413Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:56.319198698Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:56.319265162Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:56.319326099Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:56.319386914Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:56.319448966Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:56.319508996Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:56.319577882Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:56.319643237Z Response: 331 Please, specify the password. [2ms]  
2025-01-23T13:03:56.319710757Z Command:  PASS ***  
2025-01-23T13:03:56.319783036Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordSend(..., 0, 10)  
2025-01-23T13:03:56.319848278Z Status:   Waiting for response to: PASS ***  
2025-01-23T13:03:56.319904391Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:56.321318669Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(...) repeat due to GNUTLS_E_AGAIN  
2025-01-23T13:03:56.321620324Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(...) repeat due to GNUTLS_E_AGAIN  
2025-01-23T13:03:56.321770073Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(...) repeat due to GNUTLS_E_AGAIN  
2025-01-23T13:03:57.321881335Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(...) 3 repeats overall  
2025-01-23T13:03:57.322093535Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:57.322159884Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:57.322218797Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:57.322276811Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:57.322330373Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:57.322379661Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:57.322432963Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:57.322484363Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:57.322543734Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:57.322598504Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:57.322654875Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:57.322713973Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:57.322766488Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:57.322829798Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:57.322885731Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:57.322954492Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:57.323031967Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:57.323093120Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:57.323156206Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:57.323221810Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:57.323283874Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:57.323345383Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:57.323407319Z Response: 230 Login successful. [1.004s]  
2025-01-23T13:03:57.323469027Z Command:  PBSZ 0  
2025-01-23T13:03:57.323533338Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordSend(..., 0, 8)  
2025-01-23T13:03:57.323587683Z Status:   Waiting for response to: PBSZ 0  
2025-01-23T13:03:57.323639391Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:57.323707801Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(...) repeat due to GNUTLS_E_AGAIN  
2025-01-23T13:03:57.323763312Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(...) repeat due to GNUTLS_E_AGAIN  
2025-01-23T13:03:57.323821373Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(...) repeat due to GNUTLS_E_AGAIN  
2025-01-23T13:03:58.323857056Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(...) 3 repeats overall  
2025-01-23T13:03:58.324489450Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:58.324706708Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:58.324841582Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:58.324980094Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:58.325106022Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:58.325222013Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:58.325345859Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:58.325482572Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:58.325624884Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:58.325737938Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:58.325844810Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:58.325948690Z Response: 200 PBSZ=0 [1.002s]  
2025-01-23T13:03:58.326056568Z Command:  PROT P  
2025-01-23T13:03:58.326162611Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordSend(..., 0, 8)  
2025-01-23T13:03:58.326265866Z Status:   Waiting for response to: PROT P  
2025-01-23T13:03:58.326368094Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:58.326468572Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(...) repeat due to GNUTLS_E_AGAIN  
2025-01-23T13:03:58.326605459Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(...) repeat due to GNUTLS_E_AGAIN  
2025-01-23T13:03:58.326718185Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(...) repeat due to GNUTLS_E_AGAIN  
2025-01-23T13:03:59.326380314Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(...) 3 repeats overall  
2025-01-23T13:03:59.327153380Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:59.327475217Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:59.327793062Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:59.328031185Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:59.328247904Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:59.328457742Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:59.328758922Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:59.328996043Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:59.329244802Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:59.329503200Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:59.329768594Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:59.329984817Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:59.330178808Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:59.330377628Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:59.330581927Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:59.331002037Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:59.331211012Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:59.331322843Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:59.331413433Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:59.331500650Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:59.331627765Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:59.331716094Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:59.331798336Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:59.331910589Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:59.331985989Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:59.332067463Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:59.332139875Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:59.332226802Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:59.332305126Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:59.332380909Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:59.332453490Z Response: 200 Protection level set to P [1.003s]  
2025-01-23T13:03:59.332548822Z Command:  FEAT  
2025-01-23T13:03:59.332633867Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordSend(..., 0, 6)  
2025-01-23T13:03:59.332707097Z Status:   Waiting for response to: FEAT  
2025-01-23T13:03:59.332802386Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:03:59.332879875Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(...) repeat due to GNUTLS_E_AGAIN  
2025-01-23T13:03:59.332956537Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(...) repeat due to GNUTLS_E_AGAIN  
2025-01-23T13:03:59.333052408Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(...) repeat due to GNUTLS_E_AGAIN  
2025-01-23T13:04:00.330393406Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(...) 3 repeats overall  
2025-01-23T13:04:00.331149276Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.331967381Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.332422782Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.332799592Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.333128145Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.333453621Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.333755066Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.334002816Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.334243665Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.334473556Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.334737835Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.334969540Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.335199489Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.335421604Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.335745127Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.336100178Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.336254406Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.336371728Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.336481732Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.336619108Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.336727525Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.336834053Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.336942424Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.337042649Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.337128479Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.337222458Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.337307388Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.337399767Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.337497228Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.337603886Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.337696490Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.337790240Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.337879984Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.337973403Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.338057535Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.338150602Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.338240440Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.338349222Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.338448486Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.338548866Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.338671189Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.338775170Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.338873303Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.338970857Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.339076755Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.339165774Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.339264520Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.339355068Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.339447472Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.339556682Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.339977026Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.340279243Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.340547486Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.340773368Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.340967760Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.341143534Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.341323403Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.341498777Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.341701400Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.341882517Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.342057266Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.342230571Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.342406057Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.342597846Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.342775784Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.342951503Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.343133612Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.343310648Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.343527778Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.343796674Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.343975906Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.344149682Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.344322949Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.344555083Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.344748820Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.344913422Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.345082584Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.345252402Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.345424761Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.345639607Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.345813171Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.345983913Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.346155632Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.346325038Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.346549633Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.346810664Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.346997315Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.347182393Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.347363236Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.347560577Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.347746442Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.347928502Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.348113215Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.348295737Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.348475853Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.348670977Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.348856063Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.349041173Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.349219026Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.349407057Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.349603028Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.349791872Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.349976391Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.350152637Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.350314340Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.350481800Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.350678855Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.350862657Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.351036802Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.351212286Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.351383711Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.351572133Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.351744693Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.351917055Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.352083721Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.352262366Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.352438572Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.352629336Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.352802831Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.352974905Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.353150340Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.353320696Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.353484336Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.353667894Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.353834440Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.353997630Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.354152633Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.354305399Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.354457081Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.354614715Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.354773093Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.354923141Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.355072422Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.355222809Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.355377050Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.355538936Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.355681223Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.355809259Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.355931258Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.356055686Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.356182629Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.356306248Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.356426048Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.356556639Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.356678546Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.356804607Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.356934313Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.357057727Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.357174923Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.357297509Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.357418236Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.357531856Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.357636557Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.357736216Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.357837522Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.357938430Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.358041636Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.358148388Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.358252958Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.358358355Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.358460695Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.358571986Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.358678190Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.358787800Z Response: 211-Features:  
2025-01-23T13:04:00.358893709Z Response: MDTM  
2025-01-23T13:04:00.359015166Z Response: REST STREAM  
2025-01-23T13:04:00.359163754Z Response: SIZE  
2025-01-23T13:04:00.359222958Z Response: MLST type*;size*;modify*;perm*;  
2025-01-23T13:04:00.359268479Z Response: MLSD  
2025-01-23T13:04:00.359311125Z Response: AUTH SSL  
2025-01-23T13:04:00.359347649Z Response: AUTH TLS  
2025-01-23T13:04:00.359382877Z Response: PROT  
2025-01-23T13:04:00.359421701Z Response: PBSZ  
2025-01-23T13:04:00.359457491Z Response: UTF8  
2025-01-23T13:04:00.359496132Z Response: TVFS  
2025-01-23T13:04:00.359544490Z Response: EPSV  
2025-01-23T13:04:00.359585801Z Response: EPRT  
2025-01-23T13:04:00.359623209Z Response: MFMT  
2025-01-23T13:04:00.359662183Z Response: 211 End [1.005s]  
2025-01-23T13:04:00.359703435Z Status:   Text encoding: System.Text.UTF8Encoding+UTF8EncodingSealed  
2025-01-23T13:04:00.359730673Z Command:  OPTS UTF8 ON  
2025-01-23T13:04:00.359758810Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordSend(..., 0, 14)  
2025-01-23T13:04:00.359788297Z Status:   Waiting for response to: OPTS UTF8 ON  
2025-01-23T13:04:00.359815577Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:00.359854087Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(...) repeat due to GNUTLS_E_AGAIN  
2025-01-23T13:04:00.359880456Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(...) repeat due to GNUTLS_E_AGAIN  
2025-01-23T13:04:00.359907020Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(...) repeat due to GNUTLS_E_AGAIN  
2025-01-23T13:04:01.340457362Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(...) 3 repeats overall  
2025-01-23T13:04:01.341195911Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:01.341378680Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:01.341497367Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:01.341669067Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:01.341851957Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:01.342030276Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:01.342164521Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:01.342297557Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:01.342436754Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:01.342946124Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:01.343363125Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:01.343660958Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:01.343925370Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:01.344154455Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:01.344386524Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:01.344660822Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:01.344907398Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:01.345167322Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:01.345397389Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:01.345709048Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:01.346177376Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:01.346329705Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:01.346434645Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:01.346551352Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:01.346660347Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:01.346766021Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:01.346879759Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:01.346976683Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:01.347080746Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:01.347203869Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:01.347296623Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:01.347396644Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:01.347490920Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:01.347603072Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:01.347685616Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:01.347771665Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:01.347861883Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:01.347957357Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:01.348066813Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:01.348149253Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:01.348236908Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:01.348330436Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:01.348417672Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:01.348504705Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:01.348611580Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:01.348695757Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:01.348787559Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:01.348874006Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:01.348991013Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:01.349090348Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:01.349177837Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:01.349273903Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:01.349368591Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:01.349455376Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:01.349554855Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:01.349641105Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:01.349723492Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:01.349809621Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:01.349887023Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:01.349967258Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:01.350043546Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:01.350125854Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:01.350204366Z Response: 202 UTF8 mode is always enabled. No need to send this command [1.002s]  
2025-01-23T13:04:01.350292302Z Command:  SYST  
2025-01-23T13:04:01.350375821Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordSend(..., 0, 6)  
2025-01-23T13:04:01.350453122Z Status:   Waiting for response to: SYST  
2025-01-23T13:04:01.350546533Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:01.350628900Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(...) repeat due to GNUTLS_E_AGAIN  
2025-01-23T13:04:01.350703219Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(...) repeat due to GNUTLS_E_AGAIN  
2025-01-23T13:04:01.350780238Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(...) repeat due to GNUTLS_E_AGAIN  
2025-01-23T13:04:02.342568679Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(...) 3 repeats overall  
2025-01-23T13:04:02.343192753Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:02.343375661Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:02.343506251Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:02.343672804Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:02.343802231Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:02.343914042Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:02.344033235Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:02.344156651Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:02.344272638Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:02.344403085Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:02.344543074Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:02.344687264Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:02.344826508Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:02.344965151Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:02.345087898Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:02.345192376Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:02.345306849Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:02.345418280Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:02.345534203Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:02.345644533Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:02.345749982Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:02.345853524Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:02.345967324Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:02.346073189Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:02.346186908Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:02.346330769Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:02.346442332Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:02.346568940Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:02.346683434Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:02.346782871Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:02.346883841Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:02.346979027Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:02.347077922Z Response: 215 UNIX emulated by FileZilla. [1.001s]  
2025-01-23T13:04:02.347180225Z Status:   Active ServerHandler is: FileZilla  
2025-01-23T13:04:02.347279308Z Status:   Listing parser set to: Machine  
2025-01-23T13:04:02.348863070Z Command:  PWD  
2025-01-23T13:04:02.349347935Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordSend(..., 0, 5)  
2025-01-23T13:04:02.349625698Z Status:   Waiting for response to: PWD  
2025-01-23T13:04:02.349833636Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:02.350021461Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(...) repeat due to GNUTLS_E_AGAIN  
2025-01-23T13:04:02.350198094Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(...) repeat due to GNUTLS_E_AGAIN  
2025-01-23T13:04:02.350249769Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(...) repeat due to GNUTLS_E_AGAIN  
2025-01-23T13:04:03.350122857Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(...) 3 repeats overall  
2025-01-23T13:04:03.350712276Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:03.350906632Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:03.351033693Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:03.351136405Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:03.351249630Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:03.351358979Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:03.351457745Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:03.351577348Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:03.351680729Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:03.351781554Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:03.351876924Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:03.351991164Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:03.352095255Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:03.352181924Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:03.352271593Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:03.352363745Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:03.352449585Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:03.352550235Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:03.352775942Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:03.353298658Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:03.353616980Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:03.353950930Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:03.354096875Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:03.354200350Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:03.354286135Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:03.354376997Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:03.354456469Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:03.354563232Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:03.354650437Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:03.354729336Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:03.354813656Z Response: 257 "/" is current directory. [1.001s]  
2025-01-23T13:04:03.357475387Z    
2025-01-23T13:04:03.357480077Z # DirectoryExists("/home/ftp/pic")  
2025-01-23T13:04:03.357790964Z Command:  CWD /home/ftp/pic  
2025-01-23T13:04:03.358000948Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordSend(..., 0, 19)  
2025-01-23T13:04:03.358179279Z Status:   Waiting for response to: CWD /home/ftp/pic  
2025-01-23T13:04:03.358361119Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:03.358546956Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(...) repeat due to GNUTLS_E_AGAIN  
2025-01-23T13:04:03.358715063Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(...) repeat due to GNUTLS_E_AGAIN  
2025-01-23T13:04:03.358877404Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(...) repeat due to GNUTLS_E_AGAIN  
2025-01-23T13:04:04.358955594Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(...) 3 repeats overall  
2025-01-23T13:04:04.359801937Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:04.360170443Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:04.360438562Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:04.360713994Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:04.360975671Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:04.361219906Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:04.361459088Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:04.361728138Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:04.361948125Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:04.362167502Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:04.362413322Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:04.362653446Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:04.362886146Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:04.363110008Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:04.363330242Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:04.363553887Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:04.364040068Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:04.364280421Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:04.364399233Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:04.364486368Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:04.364611467Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:04.364732406Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:04.364819483Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:04.364903624Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:04.364983618Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:04.365071852Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:04.365154333Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:04.365235785Z Response: 250 CWD command successful [1.003s]  
2025-01-23T13:04:04.365314182Z Command:  CWD /  
2025-01-23T13:04:04.365394147Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordSend(..., 0, 7)  
2025-01-23T13:04:04.365473059Z Status:   Waiting for response to: CWD /  
2025-01-23T13:04:04.365583794Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:04.365656418Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(...) repeat due to GNUTLS_E_AGAIN  
2025-01-23T13:04:04.365736590Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(...) repeat due to GNUTLS_E_AGAIN  
2025-01-23T13:04:04.365816118Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(...) repeat due to GNUTLS_E_AGAIN  
2025-01-23T13:04:05.363199234Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(...) 3 repeats overall  
2025-01-23T13:04:05.363888805Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:05.364120820Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:05.364270070Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:05.364405975Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:05.364568683Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:05.364692840Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:05.364859454Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:05.364988505Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:05.365113510Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:05.365251233Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:05.365391983Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:05.365534185Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:05.365661684Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:05.365793438Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:05.365918379Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:05.366044619Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:05.366162708Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:05.366281796Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:05.366392908Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:05.366504287Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:05.366625403Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:05.366747720Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:05.366860908Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:05.366971909Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:05.367076862Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:05.367186555Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:05.367299411Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:05.367408220Z Response: 250 CWD command successful [1.001s]  
2025-01-23T13:04:05.368854841Z    
2025-01-23T13:04:05.368860635Z # UploadStream("/home/ftp/pic/foo", NoCheck, False)  
2025-01-23T13:04:05.373527911Z    
2025-01-23T13:04:05.373529007Z # OpenWrite("/home/ftp/pic/foo", Binary, -1, False)  
2025-01-23T13:04:05.374073173Z Command:  TYPE I  
2025-01-23T13:04:05.374189522Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordSend(..., 0, 8)  
2025-01-23T13:04:05.374258212Z Status:   Waiting for response to: TYPE I  
2025-01-23T13:04:05.374321239Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:05.374379484Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(...) repeat due to GNUTLS_E_AGAIN  
2025-01-23T13:04:05.374440956Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(...) repeat due to GNUTLS_E_AGAIN  
2025-01-23T13:04:05.374501940Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(...) repeat due to GNUTLS_E_AGAIN  
2025-01-23T13:04:06.375100459Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(...) 3 repeats overall  
2025-01-23T13:04:06.375984341Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:06.376339497Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:06.376708743Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:06.376998068Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:06.377292576Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:06.377607394Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:06.377870116Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:06.378116917Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:06.378359821Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:06.378619117Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:06.378873502Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:06.379133858Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:06.379371805Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:06.379594856Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:06.379826186Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:06.380051186Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:06.380263342Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:06.380475956Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:06.381043053Z Response: 200 Type set to I [1.001s]  
2025-01-23T13:04:06.381378196Z    
2025-01-23T13:04:06.381382918Z # OpenDataStreamAsync("STOR /home/ftp/pic/foo", 0)  
2025-01-23T13:04:06.385350810Z    
2025-01-23T13:04:06.385354745Z # OpenPassiveDataStreamAsync(AutoPassive, "STOR /home/ftp/pic/foo", 0)  
2025-01-23T13:04:06.385627958Z Command:  EPSV  
2025-01-23T13:04:06.385794033Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordSend(..., 0, 6)  
2025-01-23T13:04:06.385937457Z Status:   Waiting for response to: EPSV  
2025-01-23T13:04:06.386296839Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:06.386546401Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(...) repeat due to GNUTLS_E_AGAIN  
2025-01-23T13:04:06.386734947Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(...) repeat due to GNUTLS_E_AGAIN  
2025-01-23T13:04:06.386791819Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(...) repeat due to GNUTLS_E_AGAIN  
2025-01-23T13:04:07.387103696Z Status:   GnuTLS: 1   Interop : Handshake received GNUTLS_HANDSHAKE_NEW_SESSION_TICKET  
2025-01-23T13:04:07.387918539Z Status:   GnuTLS: 1   Interop : Handshake processed GNUTLS_HANDSHAKE_NEW_SESSION_TICKET  
2025-01-23T13:04:07.388262778Z Status:   GnuTLS: 1   Interop : *GnuTlsSessionGetFlags(...)  
2025-01-23T13:04:07.388606232Z Status:   GnuTLS: 1   Interop : Session resume: use received session ticket  
2025-01-23T13:04:07.388911164Z Status:   GnuTLS: 1   Interop : *GnuTlsSessionGetData2(...)  
2025-01-23T13:04:07.389214617Z Status:   GnuTLS: 1   Interop : *GnuTlsSessionSetData(...)  
2025-01-23T13:04:07.389479438Z Status:   GnuTLS: 1   Interop : *GnuTlsFree(...)  
2025-01-23T13:04:07.390263236Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(...) repeat due to GNUTLS_E_AGAIN  
2025-01-23T13:04:08.388750495Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(...) 4 repeats overall  
2025-01-23T13:04:08.389477978Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:08.389736579Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:08.389891449Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:08.390017313Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:08.390130944Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:08.390245819Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:08.390362899Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:08.390485165Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:08.390624500Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:08.390752619Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:08.390859190Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:08.390973394Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:08.391090256Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:08.391207567Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:08.391314936Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:08.391416216Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:08.391535414Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:08.391640808Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:08.391748577Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:08.391872584Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:08.391989417Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:08.392107511Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:08.392205690Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:08.392310506Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:08.392399534Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:08.392521291Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:08.392622919Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:08.392731331Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:08.392834013Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:08.392939065Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:08.393047663Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:08.393198502Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:08.393289419Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:08.393389442Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:08.393488533Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:08.393616575Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:08.393709404Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:08.393805357Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:08.393895647Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:08.393989362Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:08.394074145Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:08.394162628Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:08.394252660Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:08.394338273Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:08.394419769Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:08.394501044Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:08.394600783Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:08.394684806Z Response: 229 Entering Extended Passive Mode (|||35917|) [2.004s]  
2025-01-23T13:04:08.395803511Z Status:   Connecting(async) AsyncFtpClient.FtpSocketStream(data) IP #1 = ***:35917  
2025-01-23T13:04:08.398273639Z Command:  STOR /home/ftp/pic/foo  
2025-01-23T13:04:08.398371951Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordSend(..., 0, 24)  
2025-01-23T13:04:08.398439750Z Status:   Waiting for response to: STOR /home/ftp/pic/foo  
2025-01-23T13:04:08.398501596Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:08.398590423Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(...) repeat due to GNUTLS_E_AGAIN  
2025-01-23T13:04:08.398630895Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(...) repeat due to GNUTLS_E_AGAIN  
2025-01-23T13:04:08.398665514Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(...) repeat due to GNUTLS_E_AGAIN  
2025-01-23T13:04:09.399320238Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(...) 3 repeats overall  
2025-01-23T13:04:09.400187527Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:09.400551478Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:09.400872786Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:09.401183057Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:09.401428262Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:09.401693589Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:09.401928654Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:09.402163164Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:09.402403033Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:09.402676548Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:09.402910109Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:09.403122523Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:09.403329935Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:09.403557295Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:09.403774169Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:09.404005229Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:09.404221021Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:09.404439153Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:09.404913116Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:09.405173994Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:09.405294366Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:09.405400906Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:09.405487628Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:09.405615312Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:09.405706069Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:09.405792267Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:09.405884014Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:09.405958269Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:09.406045294Z Response: 150 Starting data transfer. [1.001s]  
2025-01-23T13:04:09.406121028Z Status:   GnuTLS: 1   Interop : *.ctor(...):CertificateCredentials  
2025-01-23T13:04:09.406207623Z Status:   GnuTLS: 1   Interop : *GnuTlsCertificateSetX509SystemTrust(...)  
2025-01-23T13:04:09.416887295Z Status:   GnuTLS: 1   Interop : Processed 149 certificates in system X509 trust list  
2025-01-23T13:04:09.416987268Z Status:   GnuTLS: 1   Interop : *SetupClientCertificates(...) - currently being implemented  
2025-01-23T13:04:09.417016416Z Status:   GnuTLS: 1   Interop : *.ctor(...):Session  
2025-01-23T13:04:09.417037639Z Status:   GnuTLS: 1   Interop : *GnuTlsDbSetCacheExpiration(...)  
2025-01-23T13:04:09.417058500Z Status:   GnuTLS: 1   Interop : *GnuTlsPrioritySetDirect(...)(NORMAL)  
2025-01-23T13:04:09.417078203Z Status:   GnuTLS: 1   Interop : *GnuTlsDhSetPrimeBits(...)  
2025-01-23T13:04:09.417099985Z Status:   GnuTLS: 1   Interop : *GnuTlsCredentialsSet(...)  
2025-01-23T13:04:09.417119356Z Status:   GnuTLS: 1   Interop : *GnuTlsTransportSetPtr(...)  
2025-01-23T13:04:09.417138753Z Status:   GnuTLS: 1   Interop : *GnuTlsHandshakeSetTimeout(...)  
2025-01-23T13:04:09.417160151Z Status:   GnuTLS: 1   Interop : *GnuTlsHandshakeSetHookFunction(...)  
2025-01-23T13:04:09.417180280Z Status:   GnuTLS: 1   Interop : Session resume: Use session data from control connection  
2025-01-23T13:04:09.417205176Z Status:   GnuTLS: 1   Interop : *GnuTlsSessionGetData2(...)  
2025-01-23T13:04:09.417226905Z Status:   GnuTLS: 1   Interop : *GnuTlsSessionSetData(...)  
2025-01-23T13:04:09.417249428Z Status:   GnuTLS: 1   Interop : *GnuTlsFree(...)  
2025-01-23T13:04:09.417270540Z Status:   GnuTLS: 1   Interop : *GnuTlsHandShake(...)  
2025-01-23T13:04:09.417439323Z Status:   GnuTLS: 1   Interop : Handshake about to send GNUTLS_HANDSHAKE_CLIENT_HELLO  
2025-01-23T13:04:09.417475360Z Status:   GnuTLS: 1   Interop : Handshake sent GNUTLS_HANDSHAKE_CLIENT_HELLO  
2025-01-23T13:04:09.418063895Z Status:   GnuTLS: 1   Interop : Handshake received GNUTLS_HANDSHAKE_SERVER_HELLO  
2025-01-23T13:04:09.418153374Z Status:   GnuTLS: 1   Interop : Handshake processed GNUTLS_HANDSHAKE_SERVER_HELLO  
2025-01-23T13:04:09.418268332Z Status:   GnuTLS: 1   Interop : Handshake received GNUTLS_HANDSHAKE_ENCRYPTED_EXTENSIONS  
2025-01-23T13:04:09.418302677Z Status:   GnuTLS: 1   Interop : Handshake processed GNUTLS_HANDSHAKE_ENCRYPTED_EXTENSIONS  
2025-01-23T13:04:09.418337008Z Status:   GnuTLS: 1   Interop : Handshake received GNUTLS_HANDSHAKE_FINISHED  
2025-01-23T13:04:09.418356961Z Status:   GnuTLS: 1   Interop : Handshake processed GNUTLS_HANDSHAKE_FINISHED  
2025-01-23T13:04:09.418378572Z Status:   GnuTLS: 1   Interop : Handshake about to send GNUTLS_HANDSHAKE_FINISHED  
2025-01-23T13:04:09.418400488Z Status:   GnuTLS: 1   Interop : Handshake sent GNUTLS_HANDSHAKE_FINISHED  
2025-01-23T13:04:09.418430497Z Status:   GnuTLS: 1   Interop : *GnuTlsProtocolGetVersion(...)  
2025-01-23T13:04:09.418452525Z Status:   GnuTLS: 1   Interop : *GnuTlsProtocolGetName(...)  
2025-01-23T13:04:09.418473231Z Status:   GnuTLS: 1   Interop : *GnuTlsSessionGetDesc(...)  
2025-01-23T13:04:09.418498623Z Status:   GnuTLS: 1   Interop : *GnuTlsAlpnGetSelectedProtocol(...)  
2025-01-23T13:04:09.418526696Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordGetMaxSize(...)  
2025-01-23T13:04:09.418548571Z Status:   GnuTLS: 1   Interop : Maximum record size: 16384  
2025-01-23T13:04:09.418570145Z Status:   GnuTLS: 1   Interop : Session is resumed from control connection  
2025-01-23T13:04:09.418592202Z Status:   GnuTLS: 1   Interop : *GnuTlsCertificateClientGetRequestStatus(...)  
2025-01-23T13:04:09.418615530Z Status:   GnuTLS: 1   Interop : Server did not request client certificate  
2025-01-23T13:04:09.418635115Z Status:   GnuTLS: 1   Interop : *GnuTlsCertificateVerifyPeers3(...)  
2025-01-23T13:04:09.418674601Z Status:   GnuTLS: 1   Interop : Internal server certificate validation function reports:  
2025-01-23T13:04:09.418700166Z Status:   GnuTLS: 1   Interop : INVALID, SIGNER_NOT_FOUND, UNEXPECTED_OWNER  
2025-01-23T13:04:09.418719986Z Status:   GnuTLS: 1   Interop : *GnuTlsCertificateTypeGet2(...)  
2025-01-23T13:04:09.418738962Z Status:   GnuTLS: 1   Interop : *GnuTlsCertificateGetPeers(...)  
2025-01-23T13:04:09.418761882Z Status:   GnuTLS: 1   Interop : Certificate type: X.509, list contains 1 certificate  
2025-01-23T13:04:09.418781183Z Status:   GnuTLS: 1   Interop : *GnuTlsX509CrtInit(...)  
2025-01-23T13:04:09.418801536Z Status:   GnuTLS: 1   Interop : *GnuTlsX509CrtImport(...)  
2025-01-23T13:04:09.418821053Z Status:   GnuTLS: 1   Interop : *GnuTlsX509CrtPrint(...)  
2025-01-23T13:04:09.419045386Z Status:   GnuTLS: 1   Interop : *GnuTlsFree(...)  
2025-01-23T13:04:09.419105821Z Status:   GnuTLS: 1   Interop : *GnuTlsX509CrtExport2(...)  
2025-01-23T13:04:09.419132676Z Status:   GnuTLS: 1   Interop : *GnuTlsFree(...)  
2025-01-23T13:04:09.419153565Z Status:   GnuTLS: 1   Interop : *GnuTlsX509CrtDeinit(...)  
2025-01-23T13:04:09.419414984Z Status:   FTPS authentication successful, lib = FluentFTP.GnuTLS.GnuTlsStream, cipher suite = (TLS1.3)-(ECDHE-PSK-SECP256R1)-(AES-256-GCM) [19ms]  
2025-01-23T13:04:09.422653047Z Status:   Uploaded 216922 bytes, 2ms, 103.4 MB/s  
2025-01-23T13:04:09.423338554Z Status:   Disposing(async) AsyncFtpClient.FtpSocketStream(data)  
2025-01-23T13:04:09.423600785Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordCheckPending(...)  
2025-01-23T13:04:09.423759476Z Status:   GnuTLS: 1   Interop : *GnuTlsBye(...)  
2025-01-23T13:04:09.423816000Z Status:   GnuTLS: 1   Interop : *GnuTlsBye(...) repeat due to GNUTLS_E_AGAIN  
2025-01-23T13:04:09.423853944Z Status:   GnuTLS: 1   Interop : *GnuTlsBye(...) repeat due to GNUTLS_E_AGAIN  
2025-01-23T13:04:09.423889332Z Status:   GnuTLS: 1   Interop : *GnuTlsBye(...) repeat due to GNUTLS_E_AGAIN  
2025-01-23T13:04:10.424707344Z Status:   GnuTLS: 1   Interop : *GnuTlsBye(...) 3 repeats overall  
2025-01-23T13:04:10.425375425Z Status:   GnuTLS: 1   Interop : *Dispose(...):Session  
2025-01-23T13:04:10.425593083Z Status:   GnuTLS: 1   Interop : *Dispose(...):CertificateCredentials  
2025-01-23T13:04:10.433109864Z Status:   Waiting for response to: STOR /home/ftp/pic/foo  
2025-01-23T13:04:10.433274457Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:10.433340946Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:10.433398994Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:10.433457192Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:10.433525575Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:10.433581323Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:10.433641181Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:10.433706542Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:10.433770281Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:10.433838848Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:10.433888143Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:10.433939163Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:10.434012426Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:10.434061973Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:10.434113768Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:10.434166390Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:10.434225673Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:10.434277042Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:10.434331509Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:10.434385567Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:10.434436661Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:10.434487556Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:10.434543814Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:10.434610595Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:10.434665272Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:10.434724009Z Status:   GnuTLS: 1   Interop : *GnuTlsRecordRecv(..., 0, 1)  
2025-01-23T13:04:10.434775711Z Response: 226 Operation successful [2.035s]

Filezilla-Server logs

2025-01-23T13:03:56.244Z DI [FTP Session 73 172.25.0.2] Session 0x5d2c412925e0 with ID 73 created.
2025-01-23T13:03:56.244Z << [FTP Session 73 172.25.0.2] 220-FileZilla Server 1.9.4
2025-01-23T13:03:56.244Z << [FTP Session 73 172.25.0.2] 220 Please visit https://filezilla-project.org/
2025-01-23T13:03:56.250Z >> [FTP Session 73 172.25.0.2] AUTH TLS
2025-01-23T13:03:56.250Z DD [FTP Session 73 172.25.0.2] securer(1) ENTERING state = 0
2025-01-23T13:03:56.250Z DD [FTP Session 73 172.25.0.2] calling tls_layer_->set_key_and_certs(<file:/opt/filezilla-server/etc/certificates/98574985e4e16cf152e28f31a4f431418e9d366c64422fe110d104b849fbafb7/key.pem>, <file:/opt/filezilla-server/etc/certificates/98574985e4e16cf152e28f31a4f431418e9d366c64422fe110d104b849fbafb7/cert.pem>, "****")
2025-01-23T13:03:56.251Z DD [FTP Session 73 172.25.0.2] securer(1) EXITING state = 1
2025-01-23T13:03:56.251Z << [FTP Session 73 172.25.0.2] 234 Using authentication type TLS.
2025-01-23T13:03:56.251Z DD [FTP Session 73 172.25.0.2] ~securer(1) ENTERING state = 1
2025-01-23T13:03:56.251Z DD [FTP Session 73 172.25.0.2] calling tls_layer_->set_alpn()
2025-01-23T13:03:56.251Z DV [FTP Session 73 172.25.0.2] tls_layer_impl::server_handshake()
2025-01-23T13:03:56.251Z DV [FTP Session 73 172.25.0.2] tls_layer_impl::continue_handshake()
2025-01-23T13:03:56.251Z DD [FTP Session 73 172.25.0.2] ~securer(1) EXITING state = 2
2025-01-23T13:03:56.251Z DD [FTP Session 73 172.25.0.2] tls_layer_impl::on_send()
2025-01-23T13:03:56.251Z DV [FTP Session 73 172.25.0.2] tls_layer_impl::continue_handshake()
2025-01-23T13:03:56.276Z DD [FTP Session 73 172.25.0.2] tls_layer_impl::on_read()
2025-01-23T13:03:56.276Z DV [FTP Session 73 172.25.0.2] tls_layer_impl::continue_handshake()
2025-01-23T13:03:56.276Z DD [FTP Session 73 172.25.0.2] TLS handshakep: Received CLIENT HELLO
2025-01-23T13:03:56.276Z DD [FTP Session 73 172.25.0.2] TLS handshakep: Processed CLIENT HELLO
2025-01-23T13:03:56.276Z DD [FTP Session 73 172.25.0.2] TLS handshakep: About to send SERVER HELLO
2025-01-23T13:03:56.276Z DD [FTP Session 73 172.25.0.2] TLS handshakep: Sent SERVER HELLO
2025-01-23T13:03:56.276Z DD [FTP Session 73 172.25.0.2] TLS handshakep: About to send ENCRYPTED EXTENSIONS
2025-01-23T13:03:56.276Z DD [FTP Session 73 172.25.0.2] TLS handshakep: Sent ENCRYPTED EXTENSIONS
2025-01-23T13:03:56.276Z DD [FTP Session 73 172.25.0.2] TLS handshakep: About to send CERTIFICATE
2025-01-23T13:03:56.276Z DD [FTP Session 73 172.25.0.2] TLS handshakep: Sent CERTIFICATE
2025-01-23T13:03:56.276Z DD [FTP Session 73 172.25.0.2] TLS handshakep: About to send CERTIFICATE VERIFY
2025-01-23T13:03:56.276Z DD [FTP Session 73 172.25.0.2] TLS handshakep: Sent CERTIFICATE VERIFY
2025-01-23T13:03:56.276Z DD [FTP Session 73 172.25.0.2] TLS handshakep: About to send FINISHED
2025-01-23T13:03:56.276Z DD [FTP Session 73 172.25.0.2] TLS handshakep: Sent FINISHED
2025-01-23T13:03:56.277Z DD [FTP Session 73 172.25.0.2] tls_layer_impl::on_read()
2025-01-23T13:03:56.277Z DV [FTP Session 73 172.25.0.2] tls_layer_impl::continue_handshake()
2025-01-23T13:03:56.277Z DD [FTP Session 73 172.25.0.2] TLS handshakep: Received FINISHED
2025-01-23T13:03:56.277Z DD [FTP Session 73 172.25.0.2] TLS handshakep: Processed FINISHED
2025-01-23T13:03:56.277Z DI [FTP Session 73 172.25.0.2] TLS Handshake successful
2025-01-23T13:03:56.277Z DI [FTP Session 73 172.25.0.2] Protocol: TLS1.3, Key exchange: ECDHE-SECP256R1-ECDSA-SECP256R1-SHA256, Cipher: AES-256-GCM, MAC: AEAD, ALPN: 
2025-01-23T13:03:56.312Z DD [FTP Session 73 172.25.0.2] tls_layer_impl::on_read()
2025-01-23T13:03:56.312Z >> [FTP Session 73 172.25.0.2] USER foo
2025-01-23T13:03:56.312Z DI [Throttled Authenticator, FTP Session: 73] Authenticating user foo from IP 172.25.0.2.
2025-01-23T13:03:56.312Z DD [File-based Authenticator, FTP Session: 73] Invoked authenticate(()) on worker 0x5d2c41283ae0, with available methods = []
2025-01-23T13:03:56.312Z DD [File-based Authenticator, FTP Session: 73] Authentication for user 'foo' not complete. Remaning methods: [password]
2025-01-23T13:03:56.312Z DD [File-based Authenticator, FTP Session: 73] Worker 0x5d2c41283ae0 created new operation 0x5d2c41297140, with shared_user = 0x0, methods = [password], error = 0
2025-01-23T13:03:56.312Z DD [Throttled Authenticator, FTP Session: 73] Worker 0x7fff5ac49910 created new operation 0x72c3b4000b90
2025-01-23T13:03:56.312Z << [FTP Session 73 172.25.0.2] 331 Please, specify the password.
2025-01-23T13:03:56.317Z DD [FTP Session 73 172.25.0.2] tls_layer_impl::on_read()
2025-01-23T13:03:56.317Z >> [FTP Session 73 172.25.0.2] PASS ****
2025-01-23T13:03:56.317Z DD [File-based Authenticator, FTP Session: 73] 

@FanDjango
Copy link
Collaborator

Do I understand it correctly that GNUTLS_E_AGAIN are not bad per se? It seems to me that GnuTLS waits for response and raisese the GNUTLS_E_AGAIN very quickly. On the third try it seems to add one second delay. It looks like the delay is started before filezilla server responds and when it responds GnuTLS is already in the 1 second sleep.

Yes. Absolutely correct. Never seen this happening before, that's why the simplistic approach to this.

I am also very curious why this only happens on my versions.

It seems logical to assume that this is a timing issue - dependant on client but also especially server time.

Due to the nature of what is happening, it only hits us on the control connection, happily not thousands of times on the data connection (there, only 2 times).

How long does GnuTLS usually wait until it sends GNUTLS_E_AGAIN? Can it be configured how many repeats of the error can happen before it blocks? Or can maybe the time inbetween the repeats be configured?

I am working on something more automatic. Please stand by, it'l be a new release this evening.

@FanDjango
Copy link
Collaborator

FanDjango commented Jan 23, 2025

Get Release 1.0.32. It should appear on Nuget any minute from now. Let's see if that gets you up to more speed.

I was testing this on my client machine (Core i9 1400k) to one of my FTP Servers in a VM on a Core i9 9900k machine. Rarely ever saw an E_AGAIN. I don't have any SLOW servers currently, such as a Raspberry PI or suchlike. But it is still funny no-one has reported this yet.

Total timeout can be configured with config ConnTimeout, by the way (default 15s).

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

No branches or pull requests

2 participants