[ECOS] RedBoot sends continuous ACKS in TIME_WAIT state.

[ECOS] RedBoot sends continuous ACKS in TIME_WAIT state.

[Grant Edwards]

Following __tcp_close() on a socket, the RedBoot TCP stack
exchanges a continuous stream of ACKs with my Linux box.  The
RedBoot socket is in the TIME_WAIT state.  Do we really want to
send out ACKs in TIME_WAIT state?

The socket has a 120000 tick timer set (I presume a 2 minute
2MSL value).  But we're so busy sending ACKs that the system time
never advances.

The sequence of events:

 No. Time        Source     Destination   Protocol Info
   1 0.000000    10.0.0.2     10.0.0.5      TCP      1511 > 9000 [SYN] Seq=3272446793 Ack=0 Win=32120 Len=0
   2 0.000795    10.0.0.5     10.0.0.2      TCP      9000 > 1511 [SYN, ACK] Seq=0 Ack=3272446794 Win=1460 Len=0
   3 0.000878    10.0.0.2     10.0.0.5      TCP      1511 > 9000 [ACK] Seq=3272446794 Ack=1 Win=32120 Len=0
   4 0.011692    10.0.0.5     10.0.0.2      TCP      9000 > 1511 [PSH, ACK] Seq=1 Ack=3272446794 Win=1460 Len=10
   5 0.011763    10.0.0.2     10.0.0.5      TCP      1511 > 9000 [ACK] Seq=3272446794 Ack=11 Win=32120 Len=0
   6 2.285735    10.0.0.2     10.0.0.5      TCP      1511 > 9000 [PSH, ACK] Seq=3272446794 Ack=11 Win=32120 Len=6
   7 2.286991    10.0.0.5     10.0.0.2      TCP      9000 > 1511 [ACK] Seq=11 Ack=3272446800 Win=1460 Len=0
   8 3.303892    10.0.0.5     10.0.0.2      TCP      9000 > 1511 [FIN, ACK] Seq=11 Ack=3272446800 Win=1460 Len=0
   9 3.303974    10.0.0.2     10.0.0.5      TCP      1511 > 9000 [ACK] Seq=3272446800 Ack=12 Win=32120 Len=0
  10 3.304184    10.0.0.2     10.0.0.5      TCP      1511 > 9000 [FIN, ACK] Seq=3272446800 Ack=12 Win=32120 Len=0

Linux should be in the LAST_ACK state, and isn't supposed to
send anything in response to the next ACK.

  11 3.318369    10.0.0.5     10.0.0.2      TCP      9000 > 1511 [ACK] Seq=11 Ack=3272446801 Win=1460 Len=0

RedBoot stack is in the TIME_WAIT state.

Linux ACKs the ACK (why?)

  12 3.318424    10.0.0.2     10.0.0.5      TCP      1511 > 9000 [ACK] Seq=3272446801 Ack=12 Win=32120 Len=0
  13 3.319083    10.0.0.5     10.0.0.2      TCP      9000 > 1511 [ACK] Seq=11 Ack=3272446801 Win=1460 Len=0
  14 3.319116    10.0.0.2     10.0.0.5      TCP      1511 > 9000 [ACK] Seq=3272446801 Ack=12 Win=32120 Len=0
  15 3.319754    10.0.0.5     10.0.0.2      TCP      9000 > 1511 [ACK] Seq=11 Ack=3272446801 Win=1460 Len=0

This continues as fast as they can send ACKs back and forth.

I don't understand why the Linux stack is ACKing ACKs, but
there's not much I can do about that. Does RedBoot really need
to send ACKs in reponse to received ACKs while in the TIME_WAIT
state?

-- 
Grant Edwards
grante@visi.com

Re: [ECOS] RedBoot sends continuous ACKS in TIME_WAIT state.

[Mark Salter]

>>>>> Grant Edwards writes:

> Following __tcp_close() on a socket, the RedBoot TCP stack
> exchanges a continuous stream of ACKs with my Linux box.  The
> RedBoot socket is in the TIME_WAIT state.  Do we really want to
> send out ACKs in TIME_WAIT state?

For some reason, RedBoot is performing and active close. When I wrote
the tcp stack, it was for a gdb stub which was always going to keep
the connection open for as long as the other end wanted, so I don't
think active closes have ever been tested. There is probably a bug in
that part of the tcp stack. On the other hand, RedBoot should not be
doing an active close in the first place.

--Mark

Re: [ECOS] RedBoot sends continuous ACKS in TIME_WAIT state.

[Grant Edwards]

On Mon, Mar 26, 2001 at 09:57:15PM -0500, Mark Salter wrote:
> >>>>> Grant Edwards writes:

> > Following __tcp_close() on a socket, the RedBoot TCP stack
> > exchanges a continuous stream of ACKs with my Linux box.  The
> > RedBoot socket is in the TIME_WAIT state.  Do we really want to
> > send out ACKs in TIME_WAIT state?
> 
> For some reason, RedBoot is performing and active close. 

I should have mentioned that I've added password authentication
for incoming telnet connections.  If authentication fails,
RedBoot does an active close.  [At the last minute it was
decided that allowing unauthenticated telnet connections was
too big a security hole.]

> When I wrote the tcp stack, it was for a gdb stub which was
> always going to keep the connection open for as long as the
> other end wanted, so I don't think active closes have ever
> been tested.

My version of RedBoot is suffering from a moderate case of
feature creep.  What started out as a fairly straight-forward
port of RedBoot now supports the regular serial/telnet/TFTP
stuff (with not-quite-working password authentication on
telnet), an entirely unrelated TCP protocol used to download
applications, and an HDLC over MAC layer Ethernet protocol also
used to download applications. 

"They" have also decided that it has to support accessing a
non-local TFTP server (and therefore needs to use DHCP to get a
netmask).  I also need to impliment a "terse" mode so that
it's easier to do serial console commands programatically.

Perhaps RedBoot isn't the ideal choice with the current set
of requirements, but we're too far down the road to turn back
now.  :)

> There is probably a bug in that part of the tcp stack.

After I looked through the sources more I noticed that my
password hack was the only active close.

> On the other hand, RedBoot should not be doing an active close
> in the first place.

It didn't until today.  ;)

What I can't figure out is why the Linux stack is ACKing the
ACKs sent by RedBoot.  According to my copy of Stevens, the
Linux stack should be in the LAST_ACK state: upon receipt of an
ACK it is supposed to send nothing and transition to CLOSED.

I couldn't really tell from Stevens if a server in the
TIME_WAIT state is supposed to ACK incoming ACKs or not.

What's the down side of changing the RedBoot stack to not ACK
incoming ACKs?

-- 
Grant Edwards
grante@visi.com

Re: [ECOS] RedBoot sends continuous ACKS in TIME_WAIT state.

[Grant Edwards]

On Mon, Mar 26, 2001 at 07:49:32PM -0600, Grant Edwards wrote:

>    1 0.000000    10.0.0.2     10.0.0.5      TCP      1511 > 9000 [SYN] Seq=3272446793 Ack=0 Win=32120 Len=0
>    2 0.000795    10.0.0.5     10.0.0.2      TCP      9000 > 1511 [SYN, ACK] Seq=0 Ack=3272446794 Win=1460 Len=0
>    3 0.000878    10.0.0.2     10.0.0.5      TCP      1511 > 9000 [ACK] Seq=3272446794 Ack=1 Win=32120 Len=0
>    4 0.011692    10.0.0.5     10.0.0.2      TCP      9000 > 1511 [PSH, ACK] Seq=1 Ack=3272446794 Win=1460 Len=10
>    5 0.011763    10.0.0.2     10.0.0.5      TCP      1511 > 9000 [ACK] Seq=3272446794 Ack=11 Win=32120 Len=0
>    6 2.285735    10.0.0.2     10.0.0.5      TCP      1511 > 9000 [PSH, ACK] Seq=3272446794 Ack=11 Win=32120 Len=6
>    7 2.286991    10.0.0.5     10.0.0.2      TCP      9000 > 1511 [ACK] Seq=11 Ack=3272446800 Win=1460 Len=0
>    8 3.303892    10.0.0.5     10.0.0.2      TCP      9000 > 1511 [FIN, ACK] Seq=11 Ack=3272446800 Win=1460 Len=0
>    9 3.303974    10.0.0.2     10.0.0.5      TCP      1511 > 9000 [ACK] Seq=3272446800 Ack=12 Win=32120 Len=0
>   10 3.304184    10.0.0.2     10.0.0.5      TCP      1511 > 9000 [FIN, ACK] Seq=3272446800 Ack=12 Win=32120 Len=0
> 
> Linux should be in the LAST_ACK state, and isn't supposed to
> send anything in response to the next ACK.
> 
>   11 3.318369    10.0.0.5     10.0.0.2      TCP      9000 > 1511 [ACK] Seq=11 Ack=3272446801 Win=1460 Len=0
>   12 3.318424    10.0.0.2     10.0.0.5      TCP      1511 > 9000 [ACK] Seq=3272446801 Ack=12 Win=32120 Len=0
>   13 3.319083    10.0.0.5     10.0.0.2      TCP      9000 > 1511 [ACK] Seq=11 Ack=3272446801 Win=1460 Len=0
>   14 3.319116    10.0.0.2     10.0.0.5      TCP      1511 > 9000 [ACK] Seq=3272446801 Ack=12 Win=32120 Len=0
>   15 3.319754    10.0.0.5     10.0.0.2      TCP      9000 > 1511 [ACK] Seq=11 Ack=3272446801 Win=1460 Len=0

Based on comparisons to the same sequence of events when an
eCos server-app does an active close, the problem appears to be
that the sequence number in the ACKs sent by RedBoot in frames
11, 13, 15 should be 12 instead of 11.  One of the states in
the active close sequence isn't advancing the local sequence
number when it receives an ACK. I'm not sure which one should
be doing it.

-- 
Grant Edwards
grante@visi.com

Re: [ECOS] RedBoot sends continuous ACKS in TIME_WAIT state.

[Grant Edwards]

On Tue, Mar 27, 2001 at 08:03:22AM -0600, Grant Edwards wrote:
> 
> Based on comparisons to the same sequence of events when an
> eCos server-app does an active close, the problem appears to be
> that the sequence number in the ACKs sent by RedBoot in frames
> 11, 13, 15 should be 12 instead of 11.  One of the states in
> the active close sequence isn't advancing the local sequence
> number when it receives an ACK. I'm not sure which one should
> be doing it.

RedBoot wasn't incrementing the sequence number for the FIN
that it sends when doing an active close.  (SYN and FIN both
use up a sequence number.) I've attached a patch for tcp.c to
fix the problem (only seen when RedBoot does an active close).

-- 
Grant Edwards
grante@visi.com

Re: [ECOS] RedBoot sends continuous ACKS in TIME_WAIT state.

[Hugo Tyson]

Grant Edwards <grante@visi.com> writes:

> RedBoot wasn't incrementing the sequence number for the FIN
> that it sends when doing an active close.  (SYN and FIN both
> use up a sequence number.) I've attached a patch for tcp.c to
> fix the problem (only seen when RedBoot does an active close).

Thank you!  I shall be sure to apply this when I've finished my current
little job - which I'm sure is unrelated.

	- Huge

> Index: ChangeLog
> ===================================================================
> 2000-03-27  Grant Edwards <grante@visi.com>
> 
>         * src/net/tcp.c: Fixed sequence number bug seen when
>         doing an active close.
> 
> Index: tcp.c
> ===================================================================
> RCS file: /cvs/ecos/ecos/packages/redboot/current/src/net/tcp.c,v
> retrieving revision 1.2
> diff -U9 -r1.2 tcp.c
> --- tcp.c	2000/12/08 03:30:09	1.2
> +++ tcp.c	2001/03/27 17:40:28
> @@ -498,18 +498,19 @@
>  		    }
>  		}
>  		break;
>  
>  	      case _FIN_WAIT_1:
>  		if (tcp->flags & TCP_FLAG_ACK) {
>  		    handle_ack(s, pkt);
>  		    if (ntohl(tcp->acknum) == (s->seq + 1)) {
>  			/* got ACK for FIN packet */
> +			s->seq++;
>  			if (tcp->flags & TCP_FLAG_FIN) {
>  			    BSPLOG(bsp_log("_FIN_WAIT_1 --> _TIME_WAIT\n"));
>  			    s->ack++;
>  			    s->state = _TIME_WAIT;
>  			    tcp_send(s, TCP_FLAG_ACK, 0);
>  			} else {
>  			    s->state = _FIN_WAIT_2;
>  			    BSPLOG(bsp_log("_FIN_WAIT_1 --> _FIN_WAIT_2\n"));
>  			}
> 

Re: [ECOS] RedBoot sends continuous ACKS in TIME_WAIT state.

[Mark Salter]

>>>>> Grant Edwards writes:

>> Based on comparisons to the same sequence of events when an
>> eCos server-app does an active close, the problem appears to be
>> that the sequence number in the ACKs sent by RedBoot in frames
>> 11, 13, 15 should be 12 instead of 11.  One of the states in
>> the active close sequence isn't advancing the local sequence
>> number when it receives an ACK. I'm not sure which one should
>> be doing it.

> RedBoot wasn't incrementing the sequence number for the FIN
> that it sends when doing an active close.  (SYN and FIN both
> use up a sequence number.) I've attached a patch for tcp.c to
> fix the problem (only seen when RedBoot does an active close).

Yes, thanks. I will apply this to the repository. Also, I am
including the following patch to prevent the spurious ACKs.

--Mark


Index: tcp.c
===================================================================
RCS file: /home/cvs/ecc/ecc/redboot/current/src/net/tcp.c,v
retrieving revision 1.5
diff -u -p -5 -c -r1.5 tcp.c
cvs server: conflicting specifications of output style
*** tcp.c	2001/01/18 20:04:22	1.5
--- tcp.c	2001/03/27 19:25:39
*************** __tcp_handler(pktbuf_t *pkt, ip_route_t 
*** 546,556 ****
  		}
  		break;
  
  	      case _TIME_WAIT:
  		BSPLOG(bsp_log("_TIME_WAIT resend.\n"));
! 		tcp_send(s, 0, 1); /* just resend ack */
  		break;
  	    }
  	} else {
  	    BSPLOG(bsp_log("Unexpected segment from: %d.%d.%d.%d:%d\n",
  			   r->ip_addr[0], r->ip_addr[1], r->ip_addr[3],
--- 546,557 ----
  		}
  		break;
  
  	      case _TIME_WAIT:
  		BSPLOG(bsp_log("_TIME_WAIT resend.\n"));
! 		if (tcp->flags & TCP_FLAG_FIN)
! 		    tcp_send(s, 0, 1); /* just resend ack */
  		break;
  	    }
  	} else {
  	    BSPLOG(bsp_log("Unexpected segment from: %d.%d.%d.%d:%d\n",
  			   r->ip_addr[0], r->ip_addr[1], r->ip_addr[3],