logging improvements; clearer TCP send-SYN logic

control.go

@@ -153,6 +153,7 @@ func (tcb *ControlBlock) PendingSegment(payloadLen int) (_ Segment, ok bool) {
 		Flags:   pending,
 		DATALEN: Size(payloadLen),
 	}
+	tcb.traceSeg("tcb:pending-out", seg)
 	return seg, true
 }
 
@@ -452,13 +453,15 @@ func (tcb *ControlBlock) traceRcv(msg string) {
 }
 
 func (tcb *ControlBlock) traceSeg(msg string, seg Segment) {
-	tcb.trace(msg,
-		slog.Uint64("seg.seq", uint64(seg.SEQ)),
-		slog.Uint64("seg.ack", uint64(seg.ACK)),
-		slog.Uint64("seg.wnd", uint64(seg.WND)),
-		slog.Uint64("seg.flags", uint64(seg.Flags)),
-		slog.Uint64("seg.data", uint64(seg.DATALEN)),
-	)
+	if tcb.logenabled(internal.LevelTrace) {
+		tcb.trace(msg,
+			slog.Uint64("seg.seq", uint64(seg.SEQ)),
+			slog.Uint64("seg.ack", uint64(seg.ACK)),
+			slog.Uint64("seg.wnd", uint64(seg.WND)),
+			slog.String("seg.flags", seg.Flags.String()),
+			slog.Uint64("seg.data", uint64(seg.DATALEN)),
+		)
+	}
 }
 
 // Flags is a TCP flags masked implementation i.e: SYN, FIN, ACK.
@@ -513,6 +516,8 @@ func (flags Flags) String() string {
 		return "[SYN]"
 	case FlagFIN:
 		return "[FIN]"
+	case FlagRST:
+		return "[RST]"
 	}
 	buf := make([]byte, 0, 2+3*bits.OnesCount16(uint16(flags)))
 	buf = append(buf, '[')

stacks/portstack.go

@@ -355,19 +355,16 @@ func (ps *PortStack) RecvEth(ethernetFrame []byte) (err error) {
 }
 
 func (ps *PortStack) HandleEth(dst []byte) (n int, err error) {
-	isSubTrace := ps.isLogEnabled(internal.LevelTrace - 1)
-	if isSubTrace {
-		// ps.trace("HandleEth:start", slog.Int("dstlen", len(dst)))
-	}
+	isTrace := ps.isLogEnabled(internal.LevelTrace)
 	n, err = ps.handleEth(dst)
 	if n > 0 && err == nil {
-		if isSubTrace {
-			ps.trace("HandleEth:send", slog.Int("plen", n))
+		if isTrace {
+			ps.trace("Stack:	HandleEth", slog.Int("plen", n))
 		}
 		ps.lastTx = ps.now()
 		ps.processedPackets++
 	} else if err != nil && ps.isLogEnabled(slog.LevelError) {
-		ps.error("HandleEth", slog.String("err", err.Error()))
+		ps.error("Stack:HandleEth", slog.String("err", err.Error()))
 	}
 	return n, err
 }

stacks/tcpconn.go

@@ -378,10 +378,15 @@ func (sock *TCPConn) send(response []byte) (n int, err error) {
 	if !sock.remote.IsValid() {
 		return 0, nil // No remote address yet, yield.
 	}
-	if sock.mustSendSyn() {
-		// Connection is still closed, we need to establish
-		return sock.handleInitSyn(response)
+	if sock.awaitingSyn() {
+		// Connection is still preestablished, we need to establish
+		if sock.mustSendSyn() {
+			return sock.handleInitSyn(response)
+		}
+		// We sent the initializing SYN less than N seconds ago, yield.
+		return 0, ErrFlagPending
 	}
+
 	// Advertise our receive window as the amount of space available in our receive buffer.
 	sock.scb.SetRecvWindow(seqs.Size(sock.rx.Free()))
 
@@ -414,7 +419,7 @@ func (sock *TCPConn) send(response []byte) (n int, err error) {
 		sock.info("TCP:tx-statechange", slog.Uint64("port", uint64(sock.localPort)), slog.String("old", prevState.String()), slog.String("new", sock.scb.State().String()), slog.String("txflags", seg.Flags.String()))
 	}
 	err = sock.stateCheck()
-	sock.onsend(sizeTCPNoOptions + n)
+	sock.onsend(response[:sizeTCPNoOptions+n])
 	return sizeTCPNoOptions + n, err
 }
 
@@ -433,7 +438,7 @@ func (sock *TCPConn) handleInitSyn(response []byte) (n int, err error) {
 	sock.setSrcDest(&sock.pkt)
 	sock.pkt.CalculateHeaders(sock.synsentSegment(), nil)
 	sock.pkt.PutHeaders(response)
-	sock.onsend(sizeTCPNoOptions)
+	sock.onsend(response[:sizeTCPNoOptions])
 	return sizeTCPNoOptions, nil
 }
 
@@ -442,11 +447,12 @@ func (sock *TCPConn) awaitingSyn() bool {
 }
 
 func (sock *TCPConn) mustSendSyn() bool {
+	// lastTx is zero-valued on init, so this will trigger on t=0 and every 3 seconds.
 	return sock.awaitingSyn() && time.Since(sock.lastTx) > 3*time.Second
 }
 
-func (sock *TCPConn) onsend(n int) {
-	if n > 0 {
+func (sock *TCPConn) onsend(b []byte) {
+	if len(b) > 0 {
 		sock.lastTx = sock.stack.now()
 	}
 }