Turns out we would reset the TSN seq counter during

a colliding INIT. This if fine except when we have
data outstanding... we basically reset it to the
previous value it was.. so then we end up assigning
the same TSN to two different data chunks.
This patch:

1) Finds a missing lock for when we change the stream
   numbers during COOKIE and INIT-ACK processing.. we
   were NOT locking the send_buffer.. which COULD cause
   problems (found by inspection looking for <2>)

2) Fixes a case during a colliding INIT where we incorrectly
   reset the sending Sequence thus in some cases duplicately
   assigning a TSN.

3) Additional enhancments to logging so we can see strm/tsn in
   the receiver AND new tracking to watch what the sender
   is doing with TSN and STRM seq's.

Approved by:	gnn

7 files changed, 50 insertions, 20 deletions

diff --git a/sys/netinet/sctp_constants.h b/sys/netinet/sctp_constants.h
index 605e0ad..3e927bb 100644
--- a/sys/netinet/sctp_constants.h
+++ b/sys/netinet/sctp_constants.h
@@ -149,8 +149,10 @@ __FBSDID("$FreeBSD$");
 #define SCTP_UNKNOWN_MAX           101
 #define SCTP_RANDY_STUFF           102
 #define SCTP_RANDY_STUFF1          103
+#define SCTP_STRMOUT_LOG_ASSIGN	   104
+#define SCTP_STRMOUT_LOG_SEND	   105
 
-#define SCTP_LOG_MAX_TYPES 104
+#define SCTP_LOG_MAX_TYPES 106
 /*
  * To turn on various logging, you must first define SCTP_STAT_LOGGING. Then
  * to get something to log you define one of the logging defines i.e.
diff --git a/sys/netinet/sctp_indata.c b/sys/netinet/sctp_indata.c
index 2da8f8b..7b65964 100644
--- a/sys/netinet/sctp_indata.c
+++ b/sys/netinet/sctp_indata.c
@@ -1760,7 +1760,7 @@ sctp_process_a_data_chunk(struct sctp_tcb *stcb, struct sctp_association *asoc,
 		}
 		SCTP_STAT_INCR(sctps_recvexpress);
 #ifdef SCTP_STR_LOGGING
-		sctp_log_strm_del_alt(tsn, strmseq,
+		sctp_log_strm_del_alt(stcb, tsn, strmseq, strmno,
 		    SCTP_STR_LOG_FROM_EXPRS_DEL);
 #endif
 		control = NULL;
@@ -2088,7 +2088,7 @@ finish_express_del:
 	SCTP_STAT_INCR(sctps_recvdata);
 	/* Set it present please */
 #ifdef SCTP_STR_LOGGING
-	sctp_log_strm_del_alt(tsn, strmseq, SCTP_STR_LOG_FROM_MARK_TSN);
+	sctp_log_strm_del_alt(stcb, tsn, strmseq, strmno, SCTP_STR_LOG_FROM_MARK_TSN);
 #endif
 #ifdef SCTP_MAP_LOGGING
 	sctp_log_map(asoc->mapping_array_base_tsn, asoc->cumulative_tsn,
diff --git a/sys/netinet/sctp_input.c b/sys/netinet/sctp_input.c
index e724f52..86ed9f8 100644
--- a/sys/netinet/sctp_input.c
+++ b/sys/netinet/sctp_input.c
@@ -223,6 +223,7 @@ sctp_process_init(struct sctp_init_chunk *cp, struct sctp_tcb *stcb,
 
 		}
 	}
+	SCTP_TCB_SEND_LOCK(stcb);
 	if (asoc->pre_open_streams > ntohs(init->num_inbound_streams)) {
 		unsigned int newcnt;
 		struct sctp_stream_out *outs;
@@ -261,10 +262,7 @@ sctp_process_init(struct sctp_init_chunk *cp, struct sctp_tcb *stcb,
 		/* cut back the count and abandon the upper streams */
 		asoc->pre_open_streams = newcnt;
 	}
-	asoc->streamincnt = ntohs(init->num_outbound_streams);
-	if (asoc->streamincnt > MAX_SCTP_STREAMS) {
-		asoc->streamincnt = MAX_SCTP_STREAMS;
-	}
+	SCTP_TCB_SEND_UNLOCK(stcb);
 	asoc->streamoutcnt = asoc->pre_open_streams;
 	/* init tsn's */
 	asoc->highest_tsn_inside_map = asoc->asconf_seq_in = ntohl(init->initial_tsn) - 1;
@@ -281,8 +279,25 @@ sctp_process_init(struct sctp_init_chunk *cp, struct sctp_tcb *stcb,
 	/* open the requested streams */
 	if (asoc->strmin != NULL) {
 		/* Free the old ones */
+		struct sctp_queued_to_read *ctl;
+
+		for (i = 0; i < asoc->streamincnt; i++) {
+			ctl = TAILQ_FIRST(&asoc->strmin[i].inqueue);
+			while (ctl) {
+				TAILQ_REMOVE(&asoc->strmin[i].inqueue, ctl, next);
+				sctp_free_remote_addr(ctl->whoFrom);
+				sctp_m_freem(ctl->data);
+				ctl->data = NULL;
+				sctp_free_a_readq(stcb, ctl);
+				ctl = TAILQ_FIRST(&asoc->strmin[i].inqueue);
+			}
+		}
 		SCTP_FREE(asoc->strmin);
 	}
+	asoc->streamincnt = ntohs(init->num_outbound_streams);
+	if (asoc->streamincnt > MAX_SCTP_STREAMS) {
+		asoc->streamincnt = MAX_SCTP_STREAMS;
+	}
 	SCTP_MALLOC(asoc->strmin, struct sctp_stream_in *, asoc->streamincnt *
 	    sizeof(struct sctp_stream_in), "StreamsIn");
 	if (asoc->strmin == NULL) {
@@ -1256,12 +1271,13 @@ sctp_process_cookie_existing(struct mbuf *m, int iphlen, int offset,
 			sctp_timer_start(SCTP_TIMER_TYPE_AUTOCLOSE, inp, stcb,
 			    NULL);
 		}
+		/*
+		 * FIX? Should we go out, in this case (if the seq numbers
+		 * changed on the peer) and set any data to RETRANSMIT?
+		 */
 		asoc->my_rwnd = ntohl(initack_cp->init.a_rwnd);
 		asoc->pre_open_streams =
 		    ntohs(initack_cp->init.num_outbound_streams);
-		asoc->init_seq_number = ntohl(initack_cp->init.initial_tsn);
-		asoc->sending_seq = asoc->asconf_seq_out = asoc->str_reset_seq_out =
-		    asoc->init_seq_number;
 		asoc->last_cwr_tsn = asoc->init_seq_number - 1;
 		asoc->asconf_seq_in = asoc->last_acked_seq = asoc->init_seq_number - 1;
 		asoc->str_reset_seq_in = asoc->init_seq_number;
diff --git a/sys/netinet/sctp_output.c b/sys/netinet/sctp_output.c
index d8dd145..78b9a3e 100644
--- a/sys/netinet/sctp_output.c
+++ b/sys/netinet/sctp_output.c
@@ -4206,10 +4206,7 @@ sctp_msg_append(struct sctp_tcb *stcb,
 			sp->data = at;
 		}
 	}
-	if (holds_lock == 0) {
-		printf("Msg append gets a lock\n");
-		SCTP_TCB_LOCK(stcb);
-	}
+	SCTP_TCB_SEND_LOCK(stcb);
 	sctp_snd_sb_alloc(stcb, sp->length);
 	stcb->asoc.stream_queue_cnt++;
 	TAILQ_INSERT_TAIL(&strm->outqueue, sp, next);
@@ -4223,10 +4220,7 @@ sctp_msg_append(struct sctp_tcb *stcb,
 		sctp_insert_on_wheel(stcb, &stcb->asoc, strm, 0);
 	}
 	m = NULL;
-	if (hold_stcb_lock == 0) {
-		printf("msg append frees the lock\n");
-		SCTP_TCB_UNLOCK(stcb);
-	}
+	SCTP_TCB_SEND_UNLOCK(stcb);
 out_now:
 	if (m) {
 		sctp_m_freem(m);
@@ -5183,6 +5177,13 @@ out_gu:
 	atomic_add_int(&chk->whoTo->ref_count, 1);
 
 	chk->rec.data.TSN_seq = atomic_fetchadd_int(&asoc->sending_seq, 1);
+#ifdef SCTP_LOG_SENDING_STR
+	sctp_misc_ints(SCTP_STRMOUT_LOG_SEND,
+	    (uintptr_t) stcb, (uintptr_t) sp,
+	    (uint32_t) ((chk->rec.data.stream_number << 16) | chk->rec.data.stream_seq),
+	    chk->rec.data.TSN_seq);
+#endif
+
 	dchkh = mtod(chk->data, struct sctp_data_chunk *);
 	/*
 	 * Put the rest of the things in place now. Size was done earlier in
@@ -9844,6 +9845,11 @@ sctp_lower_sosend(struct socket *so,
 			TAILQ_INSERT_TAIL(&strm->outqueue, sp, next);
 			if ((srcv->sinfo_flags & SCTP_UNORDERED) == 0) {
 				sp->strseq = strm->next_sequence_sent;
+#ifdef SCTP_LOG_SENDING_STR
+				sctp_misc_ints(SCTP_STRMOUT_LOG_ASSIGN,
+				    (uintptr_t) stcb, (uintptr_t) sp,
+				    (uint32_t) ((srcv->sinfo_stream << 16) | sp->strseq), 0);
+#endif
 				strm->next_sequence_sent++;
 			}
 			if ((strm->next_spoke.tqe_next == NULL) &&
diff --git a/sys/netinet/sctp_uio.h b/sys/netinet/sctp_uio.h
index 6bd26b3..0c308ae 100644
--- a/sys/netinet/sctp_uio.h
+++ b/sys/netinet/sctp_uio.h
@@ -581,10 +581,12 @@ struct sctp_get_nonce_values {
 
 /* Debugging logs */
 struct sctp_str_log {
+	void *stcb;
 	uint32_t n_tsn;
 	uint32_t e_tsn;
 	uint16_t n_sseq;
 	uint16_t e_sseq;
+	uint16_t strm;
 };
 
 struct sctp_sb_log {
diff --git a/sys/netinet/sctputil.c b/sys/netinet/sctputil.c
index c0d6742..f98a81e 100644
--- a/sys/netinet/sctputil.c
+++ b/sys/netinet/sctputil.c
@@ -211,7 +211,7 @@ rto_logging(struct sctp_nets *net, int from)
 }
 
 void
-sctp_log_strm_del_alt(uint32_t tsn, uint16_t sseq, int from)
+sctp_log_strm_del_alt(struct sctp_tcb *stcb, uint32_t tsn, uint16_t sseq, uint16_t stream, int from)
 {
 	int sctp_cwnd_log_at;
 
@@ -219,10 +219,12 @@ sctp_log_strm_del_alt(uint32_t tsn, uint16_t sseq, int from)
 	sctp_clog[sctp_cwnd_log_at].time_event = sctp_get_time_of_event();
 	sctp_clog[sctp_cwnd_log_at].from = (uint8_t) from;
 	sctp_clog[sctp_cwnd_log_at].event_type = (uint8_t) SCTP_LOG_EVENT_STRM;
+	sctp_clog[sctp_cwnd_log_at].x.strlog.stcb = stcb;
 	sctp_clog[sctp_cwnd_log_at].x.strlog.n_tsn = tsn;
 	sctp_clog[sctp_cwnd_log_at].x.strlog.n_sseq = sseq;
 	sctp_clog[sctp_cwnd_log_at].x.strlog.e_tsn = 0;
 	sctp_clog[sctp_cwnd_log_at].x.strlog.e_sseq = 0;
+	sctp_clog[sctp_cwnd_log_at].x.strlog.strm = stream;
 }
 
 void
@@ -325,8 +327,10 @@ sctp_log_strm_del(struct sctp_queued_to_read *control, struct sctp_queued_to_rea
 	sctp_clog[sctp_cwnd_log_at].time_event = sctp_get_time_of_event();
 	sctp_clog[sctp_cwnd_log_at].from = (uint8_t) from;
 	sctp_clog[sctp_cwnd_log_at].event_type = (uint8_t) SCTP_LOG_EVENT_STRM;
+	sctp_clog[sctp_cwnd_log_at].x.strlog.stcb = control->stcb;
 	sctp_clog[sctp_cwnd_log_at].x.strlog.n_tsn = control->sinfo_tsn;
 	sctp_clog[sctp_cwnd_log_at].x.strlog.n_sseq = control->sinfo_ssn;
+	sctp_clog[sctp_cwnd_log_at].x.strlog.strm = control->sinfo_stream;
 	if (poschk != NULL) {
 		sctp_clog[sctp_cwnd_log_at].x.strlog.e_tsn = poschk->sinfo_tsn;
 		sctp_clog[sctp_cwnd_log_at].x.strlog.e_sseq = poschk->sinfo_ssn;
diff --git a/sys/netinet/sctputil.h b/sys/netinet/sctputil.h
index 7f0d429..ef0e9a4 100644
--- a/sys/netinet/sctputil.h
+++ b/sys/netinet/sctputil.h
@@ -265,7 +265,7 @@ sctp_wakeup_log(struct sctp_tcb *stcb,
     uint32_t cumtsn,
     uint32_t wake_cnt, int from);
 
-void sctp_log_strm_del_alt(uint32_t, uint16_t, int);
+void sctp_log_strm_del_alt(struct sctp_tcb *stcb, uint32_t, uint16_t, uint16_t, int);
 
 void sctp_log_nagle_event(struct sctp_tcb *stcb, int action);