search

fast-data-transfer / fdt

FDT is an Application for Efficient Data Transfers which is capable of reading and writing at disk speed over wide area networks (with standard TCP). It is written in Java, runs an all major platforms and it is easy to use. FDT is based on an asynchronous, flexible multithreaded system and is using the capabilities of the Java NIO libraries.
https://fast-data-transfer.github.io/
Apache License 2.0
198 stars 45 forks source link

no data transferred while simulating rtt/packet loss #54

Open juztas opened 3 years ago

juztas commented 3 years ago

Have seen such cases in the past, but now we have a log file. client command: java -jar fdt.jar -v -c sdn-dtn-1-7.ultralight.org -P 14 -d /dev/null /storage/2M.root server command: java -jar fdt.jar

Delay command on client (mainly to simulate 1.5% of packet loss):

tc qdisc add dev enp143s0.43 root netem loss 1.5% 0

client output: stdout:

Mar 31, 2021 3:25:23 PM lia.util.net.common.Config <init>
INFO: Using lia.util.net.copy.PosixFSFileChannelProviderFactory as FileChannelProviderFactory
Mar 31, 2021 3:25:23 PM lia.util.net.common.Config <init>
INFO: FDT started in client mode
Mar 31, 2021 3:25:23 PM lia.util.net.common.Config <init>
FINE: Source file list --> remaped file list:
/storage/2M.root --->  default mapping: /storage/2M.root

Mar 31, 2021 3:25:23 PM lia.util.net.common.Config <init>
FINE: Remote destination directory: /dev/null
Remote host: sdn-dtn-1-7.ultralight.org port: 54,321
Mar 31, 2021 3:25:23 PM lia.util.net.copy.disk.DiskWriterManager <init>
FINE:

 --------> DiskWriterManager is instantiating <---------------

Mar 31, 2021 3:25:23 PM lia.util.net.copy.disk.DiskWriterManager <init>
FINE: DiskWriterManager will use: 1 writers per partition
Mar 31, 2021 3:25:23 PM lia.util.net.copy.disk.DiskWriterManager <init>
FINE:

 --------> DiskWriterManager is instantiatied <---------------

Mar 31, 2021 3:25:24 PM lia.util.net.copy.transport.ControlChannel sendMsgImpl
FINE:  [ ControlChannel ] sending message tag ( 1 ): PROTOCOL_VERSION msg: 0.24.0-2015-12-04
Mar 31, 2021 3:25:24 PM lia.util.net.copy.transport.ControlChannel sendMsgImpl
FINE:  [ ControlChannel ] sending message tag ( 4 ): INIT_FDT_CONF msg: {-P=14, -limit=-1, -ka=120, user.home=/root, user.dir=/root/tests, -v=, user.name=root, path.separator=:, -ss=-1, file.separator=/, file.encoding=UTF-8, -c=sdn-dtn-1-7.ultralight.org, -d=/dev/null, LastParams=[/storage/2M.root], -limitDelay=300, -bs=1048576}
Mar 31, 2021 3:25:24 PM lia.util.net.copy.transport.ControlChannel sendMsgImpl
FINE:  [ ControlChannel ] sending message tag ( 2 ): SESSION_ID msg: 8ad36211-3d31-4d15-b6d1-993064bfca16
Mar 31, 2021 3:25:24 PM lia.util.net.copy.transport.ControlChannel initStreams
INFO: NEW CONTROL stream for 8ad36211-3d31-4d15-b6d1-993064bfca16 initialized
Mar 31, 2021 3:25:24 PM lia.util.net.copy.transport.ControlChannel initStreams
INFO: App KeepAlive [ 120 second(s) ] enabled for control channel. Local FDTVersion [0.24.0-2015-12-04], Remote FDTVersion [0.24.0-2015-12-04]
Mar 31, 2021 3:25:24 PM lia.util.net.copy.transport.ControlChannel$ControlChannelPingerTask <init>
INFO: [ ControlChannelPingerTask ] initialized
Mar 31, 2021 3:25:24 PM lia.util.net.copy.FDTReaderSession internalInit
FINE: No FDT Preprocess Filters defined
Mar 31, 2021 3:25:24 PM lia.util.net.copy.FDTReaderSession internalInit
INFO: [ FDTReaderSession ] No pre processing filters defined/processed.
Mar 31, 2021 3:25:24 PM lia.util.net.copy.transport.ControlChannel sendMsgImpl
FINE:  [ ControlChannel ] sending message tag ( 7 ): FINAL_FDTSESSION_CONF msg:
 destinationDir: /dev/null recursive: false dirOffset: null
 UUID[]: [13c39bc9-8aa0-4148-b186-b153c1971ce9]
 fileList[]: [2M.root]
 remappedFileLists[]: [null]
 fileSizes[]: [2000000]
 lastModifTimes[]: [1616788422000]
Mar 31, 2021 3:25:25 PM lia.util.net.copy.transport.ControlChannel run
FINE:  [ ControlChannel ] received msg: tag ( 7 ): FINAL_FDTSESSION_CONF msg: [Ljava.util.UUID;@1bfd0729
Mar 31, 2021 3:25:25 PM lia.util.net.copy.transport.ControlChannel run
FINE:  [ ControlChannel ] received msg: tag ( 9 ): START_SESSION msg: null
Mar 31, 2021 3:25:25 PM lia.util.net.copy.transport.SpeedLimitManager addLimiter
INFO:  Adding SpeedLimiterTask for lia.util.net.copy.transport.TCPSessionWriter@5d2ec556 delay: 300 ms
Mar 31, 2021 3:25:25 PM lia.util.net.copy.FDTReaderSession startReading
FINE:  realReadersCount = 1 for partitionID: 2304
Mar 31, 2021 3:25:25 PM lia.util.net.copy.FDTReaderSession startReading
INFO:  Started DiskReaderTasks for the following partions [ 2304 ] for FDTSession: 8ad36211-3d31-4d15-b6d1-993064bfca16
Mar 31, 2021 3:25:25 PM lia.util.net.copy.disk.DiskReaderTask run
FINE: DiskReaderTask - partitionID: 2304 taskID: 0 - [ FDTSession ( 8ad36211-3d31-4d15-b6d1-993064bfca16 ) / Socket[addr=sdn-dtn-1-7.ultralight.org/198.32.43.13,port=54321,localport=46920] ] started
Mar 31, 2021 3:25:25 PM lia.util.net.copy.disk.DiskReaderTask run
FINE:  [ FileReaderTask ] for FileSession (13c39bc9-8aa0-4148-b186-b153c1971ce9) /storage/2M.root started
Mar 31, 2021 3:25:25 PM lia.util.net.copy.FDTSession finishFileSession
FINE:  [ FDTSession ] [ HANDLED ] The fileSession [ 13c39bc9-8aa0-4148-b186-b153c1971ce9 ] added to finised sessions list
Mar 31, 2021 3:25:25 PM lia.util.net.copy.disk.DiskReaderTask run
FINE: DiskReaderTask - partitionID: 2304 taskID: 0 Normal exit fdtSession.isClosed() = false
Mar 31, 2021 3:25:25 PM lia.util.net.copy.disk.DiskReaderTask run
FINE:

 DiskReaderTask - partitionID: 2304 taskID: 0 - [ FDTSession ( 8ad36211-3d31-4d15-b6d1-993064bfca16 ) / Socket[addr=sdn-dtn-1-7.ultralight.org/198.32.43.13,port=54321,localport=46920] ] finishes.
 fdtSession is open Processed FBS = 2

Mar 31, 2021 3:25:26 PM lia.util.net.copy.transport.ControlChannel sendMsgImpl
FINE:  [ ControlChannel ] sending message tag ( 9 ): START_SESSION msg: null
Mar 31, 2021 3:25:26 PM lia.util.net.copy.transport.ControlChannel sendMsgImpl
FINE:  [ ControlChannel ] sending message tag ( 10 ): END_SESSION msg: {}
Mar 31, 2021 3:25:26 PM lia.util.net.copy.transport.TCPTransportProvider tryToConnect
INFO: Requested window size -1. Using window size: 166400
Mar 31, 2021 3:25:28 PM lia.util.net.copy.monitoring.ConsoleReportingTask reportStatus
FINE:  [ ConsoleReportingTask ]  Adding tcpTransportProvider lia.util.net.copy.transport.TCPSessionWriter@5d2ec556 for session: 8ad36211-3d31-4d15-b6d1-993064bfca16
Mar 31, 2021 3:27:24 PM lia.util.net.copy.transport.ControlChannel run
FINE:  [ ControlChannel ] received msg: tag ( 0 ): KEEP_ALIVE_MSG msg: [B@36313c71
Mar 31, 2021 3:27:24 PM lia.util.net.copy.transport.ControlChannel run
FINE: Ctrl channel received app KEEP_ALIVE_MSG
Mar 31, 2021 3:27:24 PM lia.util.net.copy.transport.ControlChannel sendMsgImpl
FINE:  [ ControlChannel ] sending message tag ( 0 ): KEEP_ALIVE_MSG msg: [B@45010619
Mar 31, 2021 3:29:24 PM lia.util.net.copy.transport.ControlChannel run
FINE:  [ ControlChannel ] received msg: tag ( 0 ): KEEP_ALIVE_MSG msg: [B@1080c7e8
Mar 31, 2021 3:29:24 PM lia.util.net.copy.transport.ControlChannel run
FINE: Ctrl channel received app KEEP_ALIVE_MSG
Mar 31, 2021 3:29:24 PM lia.util.net.copy.transport.ControlChannel sendMsgImpl
FINE:  [ ControlChannel ] sending message tag ( 0 ): KEEP_ALIVE_MSG msg: [B@45010619
Mar 31, 2021 3:31:24 PM lia.util.net.copy.transport.ControlChannel run
FINE:  [ ControlChannel ] received msg: tag ( 0 ): KEEP_ALIVE_MSG msg: [B@5dfc2a2f
Mar 31, 2021 3:31:24 PM lia.util.net.copy.transport.ControlChannel run
FINE: Ctrl channel received app KEEP_ALIVE_MSG
Mar 31, 2021 3:31:24 PM lia.util.net.copy.transport.ControlChannel sendMsgImpl
FINE:  [ ControlChannel ] sending message tag ( 0 ): KEEP_ALIVE_MSG msg: [B@45010619
Mar 31, 2021 3:33:24 PM lia.util.net.copy.transport.ControlChannel run
FINE:  [ ControlChannel ] received msg: tag ( 0 ): KEEP_ALIVE_MSG msg: [B@29327058
Mar 31, 2021 3:33:24 PM lia.util.net.copy.transport.ControlChannel run
FINE: Ctrl channel received app KEEP_ALIVE_MSG
Mar 31, 2021 3:33:24 PM lia.util.net.copy.transport.ControlChannel sendMsgImpl
FINE:  [ ControlChannel ] sending message tag ( 0 ): KEEP_ALIVE_MSG msg: [B@45010619
Mar 31, 2021 3:35:24 PM lia.util.net.copy.transport.ControlChannel run
FINE:  [ ControlChannel ] received msg: tag ( 0 ): KEEP_ALIVE_MSG msg: [B@6b3b0a0a
Mar 31, 2021 3:35:24 PM lia.util.net.copy.transport.ControlChannel run
FINE: Ctrl channel received app KEEP_ALIVE_MSG
Mar 31, 2021 3:35:24 PM lia.util.net.copy.transport.ControlChannel sendMsgImpl
FINE:  [ ControlChannel ] sending message tag ( 0 ): KEEP_ALIVE_MSG msg: [B@45010619
Mar 31, 2021 3:37:24 PM lia.util.net.copy.transport.ControlChannel run
FINE:  [ ControlChannel ] received msg: tag ( 0 ): KEEP_ALIVE_MSG msg: [B@7d122f02
Mar 31, 2021 3:37:24 PM lia.util.net.copy.transport.ControlChannel run
FINE: Ctrl channel received app KEEP_ALIVE_MSG
Mar 31, 2021 3:37:24 PM lia.util.net.copy.transport.ControlChannel sendMsgImpl
FINE:  [ ControlChannel ] sending message tag ( 0 ): KEEP_ALIVE_MSG msg: [B@45010619
Mar 31, 2021 3:39:25 PM lia.util.net.copy.transport.ControlChannel run
FINE:  [ ControlChannel ] received msg: tag ( 0 ): KEEP_ALIVE_MSG msg: [B@4183dfdd
Mar 31, 2021 3:39:25 PM lia.util.net.copy.transport.ControlChannel run
FINE: Ctrl channel received app KEEP_ALIVE_MSG
Mar 31, 2021 3:39:25 PM lia.util.net.copy.transport.ControlChannel sendMsgImpl
FINE:  [ ControlChannel ] sending message tag ( 0 ): KEEP_ALIVE_MSG msg: [B@45010619
Mar 31, 2021 3:41:24 PM lia.util.net.copy.transport.ControlChannel run
FINE:  [ ControlChannel ] received msg: tag ( 0 ): KEEP_ALIVE_MSG msg: [B@7b89d705
Mar 31, 2021 3:41:24 PM lia.util.net.copy.transport.ControlChannel run
FINE: Ctrl channel received app KEEP_ALIVE_MSG
Mar 31, 2021 3:41:24 PM lia.util.net.copy.transport.ControlChannel sendMsgImpl
FINE:  [ ControlChannel ] sending message tag ( 0 ): KEEP_ALIVE_MSG msg: [B@45010619
Mar 31, 2021 3:43:24 PM lia.util.net.copy.transport.ControlChannel run
FINE:  [ ControlChannel ] received msg: tag ( 0 ): KEEP_ALIVE_MSG msg: [B@48d1f924
Mar 31, 2021 3:43:24 PM lia.util.net.copy.transport.ControlChannel run
FINE: Ctrl channel received app KEEP_ALIVE_MSG
Mar 31, 2021 3:43:24 PM lia.util.net.copy.transport.ControlChannel sendMsgImpl
FINE:  [ ControlChannel ] sending message tag ( 0 ): KEEP_ALIVE_MSG msg: [B@45010619

stderr:

LogLevel: FINE
Using local properties file: /root/.fdt/fdt.properties
No local properties defined

FDT [ 0.24.0-201512041353 ] STARTED ...

FDT uses *blocking* I/O mode.
31/03 15:25:33\tNet Out: 0.000 b/s\tAvg: 0.000 b/s
31/03 15:25:38\tNet Out: 0.000 b/s\tAvg: 0.000 b/s
31/03 15:25:43\tNet Out: 0.000 b/s\tAvg: 0.000 b/s
31/03 15:25:48\tNet Out: 0.000 b/s\tAvg: 0.000 b/s 100.00% ( 00s )
31/03 15:25:53\tNet Out: 0.000 b/s\tAvg: 0.000 b/s 100.00% ( 00s )
31/03 15:25:58\tNet Out: 0.000 b/s\tAvg: 0.000 b/s 100.00% ( 00s )
31/03 15:26:03\tNet Out: 0.000 b/s\tAvg: 0.000 b/s 100.00% ( 00s )
31/03 15:26:08\tNet Out: 0.000 b/s\tAvg: 0.000 b/s 100.00% ( 00s )
31/03 15:26:13\tNet Out: 0.000 b/s\tAvg: 0.000 b/s 100.00% ( 00s )
31/03 15:26:18\tNet Out: 0.000 b/s\tAvg: 0.000 b/s 100.00% ( 00s )
31/03 15:26:23\tNet Out: 0.000 b/s\tAvg: 0.000 b/s 100.00% ( 00s )
31/03 15:26:28\tNet Out: 0.000 b/s\tAvg: 0.000 b/s 100.00% ( 00s )
31/03 15:26:33\tNet Out: 0.000 b/s\tAvg: 0.000 b/s 100.00% ( 00s )
31/03 15:26:38\tNet Out: 0.000 b/s\tAvg: 0.000 b/s 100.00% ( 00s )
31/03 15:26:43\tNet Out: 0.000 b/s\tAvg: 0.000 b/s 100.00% ( 00s )
31/03 15:26:48\tNet Out: 0.000 b/s\tAvg: 0.000 b/s 100.00% ( 00s )
31/03 15:26:53\tNet Out: 0.000 b/s\tAvg: 0.000 b/s 100.00% ( 00s )
31/03 15:26:58\tNet Out: 0.000 b/s\tAvg: 0.000 b/s 100.00% ( 00s )
......

Server side:

Mar 31, 2021 3:25:24 PM lia.util.net.copy.transport.ControlChannel sendMsgImpl
FINE:  [ ControlChannel ] sending message tag ( 1 ): PROTOCOL_VERSION msg: 0.24.0-2015-12-04
Mar 31, 2021 3:25:24 PM lia.util.net.copy.transport.ControlChannel sendMsgImpl
FINE:  [ ControlChannel ] sending message tag ( 4 ): INIT_FDT_CONF msg: {-P=4, -limit=-1, -ka=120, user.home=/root, user.dir=/root, -v=, user.name=root, path.separator=
:, -ss=-1, file.separator=/, file.encoding=UTF-8, LastParams=[], -limitDelay=300, -bs=1048576}
Mar 31, 2021 3:25:24 PM lia.util.net.copy.transport.ControlChannel initStreams
INFO: NEW CONTROL stream for 8ad36211-3d31-4d15-b6d1-993064bfca16 initialized
Mar 31, 2021 3:25:24 PM lia.util.net.copy.transport.ControlChannel initStreams
INFO: App KeepAlive [ 120 second(s) ] enabled for control channel. Local FDTVersion [0.24.0-2015-12-04], Remote FDTVersion [0.24.0-2015-12-04]
Mar 31, 2021 3:25:24 PM lia.util.net.copy.transport.ControlChannel$ControlChannelPingerTask <init>
INFO: [ ControlChannelPingerTask ] initialized
Mar 31, 2021 3:25:24 PM lia.util.net.copy.transport.ControlChannel run
FINE:  [ ControlChannel ] received msg: tag ( 7 ): FINAL_FDTSESSION_CONF msg:
 destinationDir: /dev/null recursive: false dirOffset: null
 UUID[]: [13c39bc9-8aa0-4148-b186-b153c1971ce9]
 fileList[]: [2M.root]
 remappedFileLists[]: [null]
 fileSizes[]: [2000000]
 lastModifTimes[]: [1616788422000]
Mar 31, 2021 3:25:24 PM lia.util.net.copy.transport.SpeedLimitManager addLimiter
INFO:  Adding SpeedLimiterTask for lia.util.net.copy.transport.TCPSessionReader@4ddebe1e delay: 300 ms
Mar 31, 2021 3:25:24 PM lia.util.net.copy.transport.SocketReaderTask run
INFO:  SocketReaderTask for [ 1b84b93b-814e-4bf5-8bd8-73ff422b57ef ] FINISHED !
Mar 31, 2021 3:25:25 PM lia.util.net.copy.transport.ControlChannel sendMsgImpl
FINE:  [ ControlChannel ] sending message tag ( 7 ): FINAL_FDTSESSION_CONF msg: [Ljava.util.UUID;@e691ba6
Mar 31, 2021 3:25:25 PM lia.util.net.copy.transport.ControlChannel sendMsgImpl
FINE:  [ ControlChannel ] sending message tag ( 9 ): START_SESSION msg: null
Mar 31, 2021 3:25:26 PM lia.util.net.copy.transport.ControlChannel run
FINE:  [ ControlChannel ] received msg: tag ( 9 ): START_SESSION msg: null
Mar 31, 2021 3:25:26 PM lia.util.net.copy.transport.ControlChannel run
FINE:  [ ControlChannel ] received msg: tag ( 10 ): END_SESSION msg: {}
Mar 31, 2021 3:25:26 PM lia.util.net.copy.FDTServer$AcceptableTask run
FINE: [ FDTServer ] [ AcceptableTask ] New socket from clientID: 8ad36211-3d31-4d15-b6d1-993064bfca16
Mar 31, 2021 3:25:26 PM lia.util.net.copy.transport.SocketReaderTask run
FINE:  SocketReaderTask for [ 8ad36211-3d31-4d15-b6d1-993064bfca16 ] STARTED !
Mar 31, 2021 3:25:26 PM lia.util.net.copy.FileWriterSession getChannel
FINE: [ FileWriterSession ] Not using file lock for: /dev/null
Mar 31, 2021 3:25:28 PM lia.util.net.copy.monitoring.ConsoleReportingTask reportStatus
FINE:  [ ConsoleReportingTask ]  Adding tcpTransportProvider lia.util.net.copy.transport.TCPSessionReader@4ddebe1e for session: 8ad36211-3d31-4d15-b6d1-993064bfca16
31/03 15:25:33  Net In: 0.000 b/s       Avg: 0.000 b/s
31/03 15:25:38  Net In: 0.000 b/s       Avg: 0.000 b/s
31/03 15:25:43  Net In: 0.000 b/s       Avg: 0.000 b/s
31/03 15:25:48  Net In: 0.000 b/s       Avg: 0.000 b/s 52.43% ( 106751991167300d 15h  )
31/03 15:25:53  Net In: 0.000 b/s       Avg: 0.000 b/s 52.43% ( 106751991167300d 15h  )
31/03 15:25:58  Net In: 0.000 b/s       Avg: 0.000 b/s 52.43% ( 106751991167300d 15h  )
31/03 15:26:03  Net In: 0.000 b/s       Avg: 0.000 b/s 52.43% ( 106751991167300d 15h  )
31/03 15:26:08  Net In: 0.000 b/s       Avg: 0.000 b/s 52.43% ( 106751991167300d 15h  )
31/03 15:26:13  Net In: 0.000 b/s       Avg: 0.000 b/s 52.43% ( 106751991167300d 15h  )
juztas commented 3 years ago

This also happened while using: 0.2% packet loss and 7 streams, file size 2mb; 1% packet loss and 12 streams, file size 1mb; 1.5% packet loss and 14 streams, file size 2mb;

So far looks to happen for small files. tests continue to run, so will get more statistics later.