Skip to Content.
Sympa Menu

ndt-users - Re: S2C Protocol Error with 1GB Connections

Subject: ndt-users list created

List archive

Re: S2C Protocol Error with 1GB Connections


Chronological Thread 
  • From:
  • To:
  • Subject: Re: S2C Protocol Error with 1GB Connections
  • Date: Thu, 4 Feb 2010 13:48:53 -0500 (EST)

I have more data for you. I had to run several bandwidth tests on the 1GB
machine to get a successful test.

I noticed when getting a successful run with the 1GB connection, the output
from the web100srv process still reports a Protocol Error.

Also, the data collected varies from the applet, depending on whether or not
the run is successful. If the run fails, no diagnostic data will be
collected by the applet. If it is successful, I will get diagnostic data.

Because I am already posting 400+ lines in these messages, I am not going to
provide the differences in the diagnostic output in the applet unless it's
requested of me. If it fails, it's simply not there, if its successful, I
get all of the data in the applet.

However...perhaps you can see a difference that I am not seeing between
successful/failed runs, so...

Here is the output from web100srv at debug level 6, when I have a successful
run:

--------------------------------------------------------------
New connection received, waiting for accept() to complete
New connection received from [155.138.8.12].

Parent process spawned child = 971

Parent thinks pipe() returned fd0=5, fd1=6

Incrementing waiting variable now = 1

Telling client 971 testing will begin now

>>> send_msg: type=1, len=1
>>>
Queue pointer = 971, testing = 1, waiting = 1

Waiting for new connection, timer runningChild thinks pipe() returned fd0=5,
fd1=6 for pid=0

Got 'go' signal from parent, ready to start testing
Child process 971 started
>>> send_msg: type=2, len=6
<<< recv_msg: type=2, len=1
>>> send_msg: type=2, len=7
Starting test suite:
> Middlebox test
> Simple firewall test
> C2S throughput test
> S2C throughput test
<-- Middlebox test -->
KillHung(): returned non-0 response, nothing to kill or kill failed
-- port: 3003
>>> send_msg: type=3, len=4
Middlebox test, Port 3003 waiting for incoming connection (fd=3)
Set MSS to 536, Receiving Window size set to 262142KB
Sending Window size set to 262142KB
Looking for Web100 data on socketid 5
Server: 155.138.1.49;3003 Client: 155.138.8.12;8160 1456;6;6;
Sending 1456 Byte packets over the network
Setting Cwnd Limit to 2912 octets
Signal 17 received by process 971
now = 1265308366 Process started at 1265308363, run time = 3
Timer expired while waiting for a new connection
Queue pointer = 971, testing = 1, waiting = 1
Waiting for new connection, timer running
now = 1265308369 Process started at 1265308363, run time = 6
Timer expired while waiting for a new connection
Queue pointer = 971, testing = 1, waiting = 1
Waiting for new connection, timer running
>>> send_msg: type=5, len=35
<<< recv_msg: type=5, len=17
CWND limited throughput = 95136 kbps (95136.45955280858)
>>> send_msg: type=6, len=0
<-------------------->
<-- Simple firewall test -->
-- port: 52286
-- time: 1
>>> send_msg: type=3, len=7
<<< recv_msg: type=5, len=4
-- oport: 8164
>>> send_msg: type=4, len=0
>>> send_msg: type=5, len=20
<<< recv_msg: type=5, len=20
>>> send_msg: type=5, len=1
>>> send_msg: type=6, len=0
<-------------------------->
<-- C2S throughput test -->
-- port: 3002
listening for Inet connection on testOptions->c2ssockfd, fd=3
Sending 'GO' signal, to tell client to head for the next test
>>> send_msg: type=3, len=4
C2S test Child thinks pipe() returned fd0=7, fd1=8
C2S test calling init_pkttrace() with pd=0xbfd97edc
Opening network interface 'eth0' for packet-pair timing
pcap_open_live() returned pointer 0x8084098
installing pkt filter for 'host 155.138.8.12 and port 8167'
Initial pkt src data = 8068484
C2S test Parent thinks pipe() returned fd0=7, fd1=8
now = 1265308372 Process started at 1265308363, run time = 9
Timer expired while waiting for a new connection
Queue pointer = 971, testing = 1, waiting = 1
Waiting for new connection, timer running
>>> send_msg: type=4, len=0
New packet trace started -- initializing counters
now = 1265308375 Process started at 1265308363, run time = 12
Timer expired while waiting for a new connection
Queue pointer = 971, testing = 1, waiting = 1
Waiting for new connection, timer running
now = 1265308378 Process started at 1265308363, run time = 15
Timer expired while waiting for a new connection
Queue pointer = 971, testing = 1, waiting = 1
Waiting for new connection, timer running
now = 1265308381 Process started at 1265308363, run time = 18
Timer expired while waiting for a new connection
Queue pointer = 971, testing = 1, waiting = 1
Waiting for new connection, timer running
933582 kbps outbound
>>> send_msg: type=5, len=6
Signal USR1(10) sent to child [974]
Signal 10 received by process 974
DEBUG, caught SIGUSR1, setting sig1 flag to force exit
Received SIGUSRx signal terminating data collection loop for pid=974
Sending pkt-pair data back to parent on pipe 7, 8
fwd.saddr = c088a9b:8167, rev.saddr = 31018a9b:3002
12:32:53.782460 155.138.8.12:8167 --> 155.138.1.49:3002 Collected pkt-pair
data max = 403424
wrote 128 bytes: link counters are ' 0 0 1 4 46 129 64214 403424 317049
16396 15 7 802.06 0 0 0 1 0'
#$#$#$#$ pcap routine says window increases = 0, decreases = 0, no change = 0

12:32:53.782460 155.138.1.49:3002 --> 155.138.8.12:8167 Collected pkt-pair
data max = 130113
wrote 128 bytes: link counters are ' 0 0 1 1 27 38 43115 117130 130113 18188
98 0 948.14 50415 37184 221112 0 98'
#$#$#$#$ pcap routine says window increases = 50415, decreases = 37184, no
change = 221112
128 bytes read ' 0 0 1 4 46 129 64214 403424 317049 16396 15 7 802.06 0 0 0
1 0' from monitor pipe
128 bytes read ' 0 0 1 1 27 38 43115 117130 130113 18188 98 0 948.14 50415
37184 221112 0 98' from monitor pipe
>>> send_msg: type=6, len=0
>>>
Finished reading pkt-pair data from network, process 974 should terminate now

Signal 11 received by process 974

DEBUG, caught SIGSEGV signal and terminated process (974)

Signal 17 received by process 971

<------------------------->

<-- S2C throughput test -->

-- port: 3003

>>> send_msg: type=3, len=4
>>>
waiting for data on testOptions->s2csockfd

S2C test Child thinks pipe() returned fd0=7, fd1=8

S2C test calling init_pkttrace() with pd=0xbfd97ed0

Opening network interface 'eth0' for packet-pair timing

pcap_open_live() returned pointer 0x8084d70

installing pkt filter for 'host 155.138.8.12 and port 8174'

Initial pkt src data = 8068484

Signal 17 received by process 971

>>> send_msg: type=4, len=0
>>>
New packet trace started -- initializing counters

now = 1265308384 Process started at 1265308363, run time = 21

Timer expired while waiting for a new connection

Queue pointer = 971, testing = 1, waiting = 1

Waiting for new connection, timer running

now = 1265308387 Process started at 1265308363, run time = 24

Timer expired while waiting for a new connection

Queue pointer = 971, testing = 1, waiting = 1

Waiting for new connection, timer running

now = 1265308390 Process started at 1265308363, run time = 27

Timer expired while waiting for a new connection

Queue pointer = 971, testing = 1, waiting = 1

Waiting for new connection, timer running

now = 1265308393 Process started at 1265308363, run time = 30

Timer expired while waiting for a new connection

Queue pointer = 971, testing = 1, waiting = 1

Waiting for new connection, timer running

>>> send_msg: type=5, len=24
>>>
sent 1023606784 bytes to client in 10.00 seconds

Buffer control counters Total = 124952, new data = 0, Draining Queue = 0

Signal USR2(12) sent to child [977]

Signal 12 received by process 977

DEBUG, caught SIGUSR2, setting sig2 flag to force exit

Received SIGUSRx signal terminating data collection loop for pid=977

Sending pkt-pair data back to parent on pipe 7, 8

fwd.saddr = 31018a9b:3003, rev.saddr = c088a9b:8174

12:33:04.061537 155.138.1.49:3003 --> 155.138.8.12:8174 Collected pkt-pair
data max = 29321
wrote 128 bytes: link counters are ' 0 0 2 0 5 45 21308 6277 6124 29321 1
728 5577.83 0 0 0 1 0'
#$#$#$#$ pcap routine says window increases = 0, decreases = 0, no change = 0

12:33:04.061537 155.138.8.12:8174 --> 155.138.1.49:3003 Collected pkt-pair
data max = 142172
wrote 128 bytes: link counters are ' 0 0 1 0 21 1519 20646 7534 142172 94321
1333 993 1804.07 2122 2182 264236 0 1333'
#$#$#$#$ pcap routine says window increases = 2122, decreases = 2182, no
change = 264236
Read ' 0 0 2 0 5 45 21308 6277 6124 29321 1 728 5577.83 0 0 0 1 0' from
monitor pipe
Read ' 0 0 1 0 21 1519 20646 7534 142172 94321 1333 993 1804.07 2122 2182
264236 0 1333' from monitor pipe
818793 kbps inbound

libweb100: warning: accessing depricated variable AckPktsIn

Variable 0 (AckPktsIn): web100_snap_read(): invalid arguments

libweb100: warning: accessing depricated variable AckPktsOut

Variable 1 (AckPktsOut): web100_snap_read(): invalid arguments

Variable 2 (BytesRetrans): web100_snap_read(): invalid arguments

Variable 3 (CongAvoid): web100_snap_read(): invalid arguments

Variable 4 (CongestionOverCount): web100_snap_read(): invalid arguments

Variable 5 (CongestionSignals): web100_snap_read(): invalid arguments

Variable 6 (CountRTT): web100_snap_read(): invalid arguments

Variable 7 (CurCwnd): web100_snap_read(): invalid arguments

>>> send_msg: type=5, len=13
>>>
CurMSS: 1460

Variable 9 (CurRTO): web100_snap_read(): invalid arguments

Variable 10 (CurRwinRcvd): web100_snap_read(): invalid arguments

Variable 11 (CurRwinSent): web100_snap_read(): invalid arguments

Variable 12 (CurSsthresh): web100_snap_read(): invalid arguments

Variable 13 (CwndRestores) not found in KIS

Variable 14 (DSACKDups): web100_snap_read(): invalid arguments

Variable 15 (DataBytesIn): web100_snap_read(): invalid arguments

Variable 16 (DataBytesOut): web100_snap_read(): invalid arguments

Variable 17 (DataPktsIn): web100_snap_read(): invalid arguments

Variable 18 (DataPktsOut): web100_snap_read(): invalid arguments

Variable 19 (DupAcksIn): web100_snap_read(): invalid arguments

Variable 20 (ECNEnabled): web100_snap_read(): invalid arguments

Variable 21 (FastRetran): web100_snap_read(): invalid arguments

Variable 22 (MaxCaCwnd) not found in KIS

Variable 23 (MaxCwnd): web100_snap_read(): invalid arguments

Variable 24 (MaxMSS): web100_snap_read(): invalid arguments

Variable 25 (MaxRTO): web100_snap_read(): invalid arguments

Variable 26 (MaxRTT): web100_snap_read(): invalid arguments

Variable 27 (MaxRwinRcvd): web100_snap_read(): invalid arguments

Variable 28 (MaxRwinSent): web100_snap_read(): invalid arguments

Variable 29 (MaxSsthresh): web100_snap_read(): invalid arguments

Variable 30 (MaxSaCwnd) not found in KIS

Variable 31 (MinMSS): web100_snap_read(): invalid arguments

Variable 32 (MinRTO): web100_snap_read(): invalid arguments

Variable 33 (MinRTT): web100_snap_read(): invalid arguments

Variable 34 (MinRwinRcvd): web100_snap_read(): invalid arguments

Variable 35 (MinRwinSent): web100_snap_read(): invalid arguments

Variable 36 (NagleEnabled): web100_snap_read(): invalid arguments

Variable 37 (OtherReductions): web100_snap_read(): invalid arguments

Variable 38 (PktsIn): web100_snap_read(): invalid arguments

Variable 39 (PktsOut): web100_snap_read(): invalid arguments

Variable 40 (PktsRetrans): web100_snap_read(): invalid arguments

>>> send_msg: type=5, len=17
>>>
X_Rcvbuf: 262142

Variable 42 (RcvWinScale): web100_snap_read(): invalid arguments

Variable 43 (SACKEnabled): web100_snap_read(): invalid arguments

Variable 44 (SACKsRcvd): web100_snap_read(): invalid arguments

Variable 45 (SendStall): web100_snap_read(): invalid arguments

Variable 46 (SlowStart): web100_snap_read(): invalid arguments

Variable 47 (SampleRTT): web100_snap_read(): invalid arguments

Variable 48 (SmoothedRTT): web100_snap_read(): invalid arguments

>>> send_msg: type=5, len=17
>>>
X_Sndbuf: 262142

Variable 50 (SndWinScale): web100_snap_read(): invalid arguments

Variable 51 (SndLimTimeRwin): web100_snap_read(): invalid arguments

Variable 52 (SndLimTimeCwnd): web100_snap_read(): invalid arguments

Variable 53 (SndLimTimeSender): web100_snap_read(): invalid arguments

Variable 54 (SndLimTransRwin): web100_snap_read(): invalid arguments

Variable 55 (SndLimTransCwnd): web100_snap_read(): invalid arguments

Variable 56 (SndLimTransSender): web100_snap_read(): invalid arguments

Variable 57 (SndLimBytesRwin): web100_snap_read(): invalid arguments

Variable 58 (SndLimBytesCwnd): web100_snap_read(): invalid arguments

Variable 59 (SndLimBytesSender): web100_snap_read(): invalid arguments

Variable 60 (SubsequentTimeouts): web100_snap_read(): invalid arguments

Variable 61 (SumRTT): web100_snap_read(): invalid arguments

Variable 62 (Timeouts): web100_snap_read(): invalid arguments

Variable 63 (TimestampsEnabled): web100_snap_read(): invalid arguments

Variable 64 (WinScaleRcvd): web100_snap_read(): invalid arguments

Variable 65 (WinScaleSent): web100_snap_read(): invalid arguments

Variable 66 (DupAcksOut): web100_snap_read(): invalid arguments

Variable 67 (StartTimeUsec): web100_snap_read(): invalid arguments

Variable 68 (Duration): web100_snap_read(): invalid arguments

>>> send_msg: type=5, len=18
>>>
AckPktsIn: 268534

>>> send_msg: type=5, len=14
>>>
AckPktsOut: 0

>>> send_msg: type=5, len=19
>>>
BytesRetrans: 2920

>>> send_msg: type=5, len=13
>>>
CongAvoid: 0

>>> send_msg: type=5, len=23
>>>
CongestionOverCount: 0

>>> send_msg: type=5, len=21
>>>
CongestionSignals: 1

>>> send_msg: type=5, len=17
>>>
CountRTT: 267199

>>> send_msg: type=5, len=15
>>>
CurCwnd: 99280

Variable 8 (CurMSS): web100_snap_read(): invalid arguments

>>> send_msg: type=5, len=12
>>>
CurRTO: 201

>>> send_msg: type=5, len=19
>>>
CurRwinRcvd: 65700

>>> send_msg: type=5, len=18
>>>
CurRwinSent: 5888

>>> send_msg: type=5, len=19
>>>
CurSsthresh: 43800

Variable 13 (CwndRestores) not found in KIS

>>> send_msg: type=5, len=13
>>>
DSACKDups: 0

>>> send_msg: type=5, len=15
>>>
DataBytesIn: 0

>>> send_msg: type=5, len=25
>>>
DataBytesOut: 1024851580

>>> send_msg: type=5, len=14
>>>
DataPktsIn: 0

>>> send_msg: type=5, len=20
>>>
DataPktsOut: 701079

>>> send_msg: type=5, len=16
>>>
DupAcksIn: 1239

>>> send_msg: type=5, len=14
>>>
ECNEnabled: 0

>>> send_msg: type=5, len=14
>>>
FastRetran: 1

Variable 22 (MaxCaCwnd) not found in KIS

>>> send_msg: type=5, len=15
>>>
MaxCwnd: 99280

>>> send_msg: type=5, len=13
>>>
MaxMSS: 1460

>>> send_msg: type=5, len=12
>>>
MaxRTO: 203

>>> send_msg: type=5, len=10
>>>
MaxRTT: 3

>>> send_msg: type=5, len=19
>>>
MaxRwinRcvd: 65700

>>> send_msg: type=5, len=18
>>>
MaxRwinSent: 5888

>>> send_msg: type=5, len=19
>>>
MaxSsthresh: 43800

Variable 30 (MaxSaCwnd) not found in KIS

>>> send_msg: type=5, len=13
>>>
MinMSS: 1460

>>> send_msg: type=5, len=12
>>>
MinRTO: 201

>>> send_msg: type=5, len=10
>>>
MinRTT: 0

>>> send_msg: type=5, len=17
>>>
MinRwinRcvd: 204

>>> send_msg: type=5, len=18
>>>
MinRwinSent: 5840

>>> send_msg: type=5, len=16
>>>
NagleEnabled: 1

>>> send_msg: type=5, len=19
>>>
OtherReductions: 1

>>> send_msg: type=5, len=15
>>>
PktsIn: 268534

>>> send_msg: type=5, len=16
>>>
PktsOut: 701079

>>> send_msg: type=5, len=15
>>>
PktsRetrans: 2

Variable 41 (X_Rcvbuf): web100_snap_read(): invalid arguments

>>> send_msg: type=5, len=15
>>>
RcvWinScale: 6

>>> send_msg: type=5, len=15
>>>
SACKEnabled: 3

>>> send_msg: type=5, len=14
>>>
SACKsRcvd: 44

>>> send_msg: type=5, len=13
>>>
SendStall: 0

>>> send_msg: type=5, len=13
>>>
SlowStart: 0

>>> send_msg: type=5, len=13
>>>
SampleRTT: 0

>>> send_msg: type=5, len=15
>>>
SmoothedRTT: 1

Variable 49 (X_Sndbuf): web100_snap_read(): invalid arguments

>>> send_msg: type=5, len=15
>>>
SndWinScale: 2

>>> send_msg: type=5, len=24
>>>
SndLimTimeRwin: 1381730

>>> send_msg: type=5, len=22
>>>
SndLimTimeCwnd: 27784

>>> send_msg: type=5, len=26
>>>
SndLimTimeSender: 8664628

>>> send_msg: type=5, len=23
>>>
SndLimTransRwin: 39117

>>> send_msg: type=5, len=21
>>>
SndLimTransCwnd: 561

>>> send_msg: type=5, len=25
>>>
SndLimTransSender: 39674

>>> send_msg: type=5, len=27
>>>
SndLimBytesRwin: 794226740

>>> send_msg: type=5, len=25
>>>
SndLimBytesCwnd: 9183520

>>> send_msg: type=5, len=29
>>>
SndLimBytesSender: 221441320

>>> send_msg: type=5, len=22
SubsequentTimeouts: 0
>>> send_msg: type=5, len=15
SumRTT: 150838
>>> send_msg: type=5, len=12
Timeouts: 0
>>> send_msg: type=5, len=21
TimestampsEnabled: 0
>>> send_msg: type=5, len=16
WinScaleRcvd: 2
>>> send_msg: type=5, len=16
WinScaleSent: 6
>>> send_msg: type=5, len=14
DupAcksOut: 0
>>> send_msg: type=5, len=22
StartTimeUsec: 988970
>>> send_msg: type=5, len=19
Duration: 10074297
Finished reading pkt-pair data from network, process 977 should terminate now
Signal 11 received by process 977
DEBUG, caught SIGSEGV signal and terminated process (977)
Signal 17 received by process 971
Protocol error!
>>> send_msg: type=7, len=61
S2C throughput test FAILED!
Finished testing C2S = 933.58 Mbps, S2C = 0.00 Mbps
Client --> Server data detects link = Gigabit Ethernet
Client <-- Server Ack's detect link = OC-48
Server --> Client data detects link = 10 Gigabit Enet
Server <-- Client Ack's detect link = OC-48
CWND limited test = 95136.46 while unlimited = 0.00
Better throughput when CWND is limited, may be duplex mismatch
>>> send_msg: type=8, len=42
>>> send_msg: type=8, len=76
>>> send_msg: type=8, len=87
>>> send_msg: type=8, len=77
>>> send_msg: type=8, len=82
>>> send_msg: type=8, len=50
>>> send_msg: type=9, len=0
Successfully returned from run_test() routine
Signal 17 received by process 563
now = 1265308394 Process started at 1265308363, run time = 31
Select exited with rc = -1
Queue pointer = 971, testing = 1, waiting = 1
Received SIGCHLD signal for active web100srv process [563]
wait3() returned 0 for PID=971
wexitstatus = '0'
Attempting to clean up child 971, head pid = 971
Child process 971 causing head pointer modification
Removing Child from head, decrementing waiting now = 0
Timer not running, waiting for new connection



Archive powered by MHonArc 2.6.16.

Top of Page