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.

Sign up for GitHub

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

Jump to bottom

no data transferred while simulating rtt/packet loss #54

Open
juztas opened this issue Mar 31, 2021 · 1 comment
Open

no data transferred while simulating rtt/packet loss #54

juztas opened this issue Mar 31, 2021 · 1 comment

Comments

@juztas
Copy link
Collaborator

juztas commented Mar 31, 2021

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

juztas commented Mar 31, 2021

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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
1 participant
@juztas