Repository: nats-io/nats-server (go)

Issue:
Connection between Leafnode and Core NATS over satellite link fails to get established
### Observed behavior

Siden is running into an odd issue with NATS Leafnode not being able to connect to our Core NATS server.
After TCP 3-way handshake Core NATS sends INFO message and then NATS Leafnode responds with INFO and 400+ms later sends closes connection (sends TCP FIN).
The latency of connection is 500ms.

Here are packets exchanged. Packets with P flag are INFO messages, followed by FIN packet
```
22:00:32.440826 IP 10.99.0.99.34786 > 3.136.10.169.7422: Flags [S], seq 1607668652, win 65535, options [mss 1460,sackOK,TS val 2932985413 ecr 0,nop,wscale 8], length 0
22:00:32.980351 IP 3.136.10.169.7422 > 10.99.0.99.34786: Flags [S.], seq 2383013068, ack 1607668653, win 65535, options [mss 1460,sackOK,TS val 1779976004 ecr 2932985413,nop,wscale 8], length 0
22:00:32.980410 IP 10.99.0.99.34786 > 3.136.10.169.7422: Flags [.], ack 1, win 256, options [nop,nop,TS val 2932985953 ecr 1779976004], length 0
22:00:33.520223 IP 3.136.10.169.7422 > 10.99.0.99.34786: Flags [P.], seq 1:468, ack 1, win 256, options [nop,nop,TS val 1779976544 ecr 2932985953], length 467
22:00:33.520276 IP 10.99.0.99.34786 > 3.136.10.169.7422: Flags [.], ack 468, win 261, options [nop,nop,TS val 2932986493 ecr 1779976544], length 0
22:00:33.520719 IP 10.99.0.99.34786 > 3.136.10.169.7422: Flags [P.], seq 1:164, ack 468, win 261, options [nop,nop,TS val 2932986493 ecr 1779976544], length 163
22:00:33.981008 IP 10.99.0.99.34786 > 3.136.10.169.7422: Flags [F.], seq 164, ack 468, win 261, options [nop,nop,TS val 2932986954 ecr 1779976544], length 0
```
in the console the NATS Leafnode outputs the following:
[7] [INF] 3.13.54.170:7422 - lid:53 - Leafnode connection closed: Read Error - Account: $G
[7] [INF] 3.13.54.170:7422 - lid:54 - Leafnode connection created for account: $G
[7] [INF] 3.13.54.170:7422 - lid:54 - Leafnode connection closed: Read Error - Account: $G


After investigation the issue is caused by too short timeout DEFAULT_LEAFNODE_INFO_WAIT, which is hardcoded to 1s.
Unfortunately it's a constant and not configurable,
We changed the timeout value in the vendor directory to 3s and that resolved the issue.

Please make this parameter configurable.


### Expected behavior

NATS connection can be established successfully

### Server and client version

v2.10.10

### Host environment

_No response_

### Steps to reproduce

Test NATS Leafnode - Server connection over high latency link.

Pull request:
[FIXED] LeafNode: connection may fail on slow link
Added the leafnode remote configuration parameter `first_info_timeout`
which is the amount of time that a server creating a leafnode
connection will wait for the initial INFO from the remote server.

Resolves #5417

Signed-off-by: Ivan Kozlovic <ivan@synadia.com>

Patch:
diff --git a/server/leafnode.go b/server/leafnode.go
index 72bd9f4c..23503c2b 100644
--- a/server/leafnode.go
+++ b/server/leafnode.go
@@ -982,6 +982,7 @@ func (s *Server) createLeafNode(conn net.Conn, rURL *url.URL, remote *leafNodeCf
 	c.Noticef("Leafnode connection created%s %s", remoteSuffix, c.opts.Name)
 
 	var tlsFirst bool
+	var infoTimeout time.Duration
 	if remote != nil {
 		solicited = true
 		remote.Lock()
@@ -991,6 +992,7 @@ func (s *Server) createLeafNode(conn net.Conn, rURL *url.URL, remote *leafNodeCf
 			c.leaf.isSpoke = true
 		}
 		tlsFirst = remote.TLSHandshakeFirst
+		infoTimeout = remote.FirstInfoTimeout
 		remote.Unlock()
 		c.acc = acc
 	} else {
@@ -1048,7 +1050,7 @@ func (s *Server) createLeafNode(conn net.Conn, rURL *url.URL, remote *leafNodeCf
 				}
 			}
 			// We need to wait for the info, but not for too long.
-			c.nc.SetReadDeadline(time.Now().Add(DEFAULT_LEAFNODE_INFO_WAIT))
+			c.nc.SetReadDeadline(time.Now().Add(infoTimeout))
 		}
 
 		// We will process the INFO from the readloop and finish by
@@ -2831,6 +2833,7 @@ func (c *client) leafNodeSolicitWSConnection(opts *Options, rURL *url.URL, remot
 	compress := remote.Websocket.Compression
 	// By default the server will mask outbound frames, but it can be disabled with this option.
 	noMasking := remote.Websocket.NoMasking
+	infoTimeout := remote.FirstInfoTimeout
 	remote.RUnlock()
 	// Will do the client-side TLS handshake if needed.
 	tlsRequired, err := c.leafClientHandshakeIfNeeded(remote, opts)
@@ -2883,6 +2886,7 @@ func (c *client) leafNodeSolicitWSConnection(opts *Options, rURL *url.URL, remot
 	if noMasking {
 		req.Header.Add(wsNoMaskingHeader, wsNoMaskingValue)
 	}
+	c.nc.SetDeadline(time.Now().Add(infoTimeout))
 	if err := req.Write(c.nc); err != nil {
 		return nil, WriteError, err
 	}
@@ -2890,7 +2894,6 @@ func (c *client) leafNodeSolicitWSConnection(opts *Options, rURL *url.URL, remot
 	var resp *http.Response
 
 	br := bufio.NewReaderSize(c.nc, MAX_CONTROL_LINE_SIZE)
-	c.nc.SetReadDeadline(time.Now().Add(DEFAULT_LEAFNODE_INFO_WAIT))
 	resp, err = http.ReadResponse(br, req)
 	if err == nil &&
 		(resp.StatusCode != 101 ||
diff --git a/server/opts.go b/server/opts.go
index 73564fe3..e717f26e 100644
--- a/server/opts.go
+++ b/server/opts.go
@@ -205,6 +205,11 @@ type RemoteLeafOpts struct {
 	DenyImports       []string         `json:"-"`
 	DenyExports       []string         `json:"-"`
 
+	// FirstInfoTimeout is the amount of time the server will wait for the
+	// initial INFO protocol from the remote server before closing the
+	// connection.
+	FirstInfoTimeout time.Duration `json:"-"`
+
 	// Compression options for this remote. Each remote could have a different
 	// setting and also be different from the LeafNode options.
 	Compression CompressionOpts `json:"-"`
@@ -2668,6 +2673,8 @@ func parseRemoteLeafNodes(v any, errors *[]error, warnings *[]error) ([]*RemoteL
 					*errors = append(*errors, err)
 					continue
 				}
+			case "first_info_timeout":
+				remote.FirstInfoTimeout = parseDuration(k, tk, v, errors, warnings)
 			default:
 				if !tk.IsUsedVariable() {
 					err := &unknownConfigFieldErr{
@@ -5376,6 +5383,10 @@ func setBaselineOptions(opts *Options) {
 					c.Mode = CompressionS2Auto
 				}
 			}
+			// Set default first info timeout value if not set.
+			if r.FirstInfoTimeout <= 0 {
+				r.FirstInfoTimeout = DEFAULT_LEAFNODE_INFO_WAIT
+			}
 		}
 	}
 


Test patch:
diff --git a/server/config_check_test.go b/server/config_check_test.go
index aefebc74..094fc7f7 100644
--- a/server/config_check_test.go
+++ b/server/config_check_test.go
@@ -2008,6 +2008,23 @@ func TestConfigCheck(t *testing.T) {
 			errorLine: 9,
 			errorPos:  9,
 		},
+		{
+			name: "invalid duration for remote leafnode first info timeout",
+			config: `
+				leafnodes {
+					port: -1
+					remotes [
+						{
+							url: "nats://127.0.0.1:123"
+							first_info_timeout: abc
+						}
+					]
+				}
+			`,
+			err:       fmt.Errorf("error parsing first_info_timeout: time: invalid duration %q", "abc"),
+			errorLine: 7,
+			errorPos:  8,
+		},
 		{
 			name:       "show warnings on empty configs without values",
 			config:     ``,
diff --git a/server/leafnode_test.go b/server/leafnode_test.go
index aaabb988..c46067ed 100644
--- a/server/leafnode_test.go
+++ b/server/leafnode_test.go
@@ -7607,3 +7607,147 @@ func TestLeafNodeLoopDetectionOnActualLoop(t *testing.T) {
 		t.Fatalf("Did not get any error regarding loop")
 	}
 }
+
+func TestLeafNodeConnectionSucceedsEvenWithDelayedFirstINFO(t *testing.T) {
+	for _, test := range []struct {
+		name      string
+		websocket bool
+	}{
+		{"regular", false},
+		{"websocket", true},
+	} {
+		t.Run(test.name, func(t *testing.T) {
+			ob := DefaultOptions()
+			ob.ServerName = "HUB"
+			ob.LeafNode.Host = "127.0.0.1"
+			ob.LeafNode.Port = -1
+			ob.LeafNode.AuthTimeout = 10
+			if test.websocket {
+				ob.Websocket.Host = "127.0.0.1"
+				ob.Websocket.Port = -1
+				ob.Websocket.HandshakeTimeout = 10 * time.Second
+				ob.Websocket.AuthTimeout = 10
+				ob.Websocket.NoTLS = true
+			}
+			sb := RunServer(ob)
+			defer sb.Shutdown()
+
+			var port int
+			var scheme string
+			if test.websocket {
+				port = ob.Websocket.Port
+				scheme = wsSchemePrefix
+			} else {
+				port = ob.LeafNode.Port
+				scheme = "nats"
+			}
+
+			urlStr := fmt.Sprintf("%s://127.0.0.1:%d", scheme, port)
+			proxy := createNetProxy(1100*time.Millisecond, 1024*1024*1024, 1024*1024*1024, urlStr, true)
+			defer proxy.stop()
+			proxyURL := proxy.clientURL()
+			_, proxyPort, err := net.SplitHostPort(proxyURL[len(scheme)+3:])
+			require_NoError(t, err)
+
+			lnBURL, err := url.Parse(fmt.Sprintf("%s://127.0.0.1:%s", scheme, proxyPort))
+			require_NoError(t, err)
+
+			oa := DefaultOptions()
+			oa.ServerName = "SPOKE"
+			oa.Cluster.Name = "xyz"
+			remote := &RemoteLeafOpts{
+				URLs:             []*url.URL{lnBURL},
+				FirstInfoTimeout: 3 * time.Second,
+			}
+			oa.LeafNode.Remotes = []*RemoteLeafOpts{remote}
+			sa := RunServer(oa)
+			defer sa.Shutdown()
+
+			checkLeafNodeConnected(t, sa)
+		})
+	}
+}
+
+type captureLeafConnClosed struct {
+	DummyLogger
+	ch chan struct{}
+}
+
+func (l *captureLeafConnClosed) Noticef(format string, v ...any) {
+	msg := fmt.Sprintf(format, v...)
+	if strings.Contains(msg, "Leafnode connection closed: Read Error") {
+		select {
+		case l.ch <- struct{}{}:
+		default:
+		}
+	}
+}
+
+func TestLeafNodeDetectsStaleConnectionIfNoInfo(t *testing.T) {
+	for _, test := range []struct {
+		name      string
+		websocket bool
+	}{
+		{"regular", false},
+		{"websocket", true},
+	} {
+		t.Run(test.name, func(t *testing.T) {
+			l, err := net.Listen("tcp", "127.0.0.1:0")
+			require_NoError(t, err)
+			defer l.Close()
+
+			ch := make(chan struct{})
+			wg := sync.WaitGroup{}
+			wg.Add(1)
+			go func() {
+				defer wg.Done()
+				c, err := l.Accept()
+				if err != nil {
+					return
+				}
+				defer c.Close()
+				<-ch
+			}()
+
+			var scheme string
+			if test.websocket {
+				scheme = wsSchemePrefix
+			} else {
+				scheme = "nats"
+			}
+			urlStr := fmt.Sprintf("%s://%s", scheme, l.Addr())
+			lnBURL, err := url.Parse(urlStr)
+			require_NoError(t, err)
+
+			oa := DefaultOptions()
+			oa.ServerName = "SPOKE"
+			oa.Cluster.Name = "xyz"
+			remote := &RemoteLeafOpts{
+				URLs:             []*url.URL{lnBURL},
+				FirstInfoTimeout: 250 * time.Millisecond,
+			}
+			oa.LeafNode.Remotes = []*RemoteLeafOpts{remote}
+			oa.DisableShortFirstPing = false
+			oa.NoLog = false
+			sa, err := NewServer(oa)
+			require_NoError(t, err)
+			defer sa.Shutdown()
+
+			log := &captureLeafConnClosed{ch: make(chan struct{}, 1)}
+			sa.SetLogger(log, false, false)
+			sa.Start()
+
+			select {
+			case <-log.ch:
+				// OK
+			case <-time.After(750 * time.Millisecond):
+				t.Fatalf("Connection was not closed")
+			}
+
+			sa.Shutdown()
+			close(ch)
+			wg.Wait()
+			sa.WaitForShutdown()
+		})
+	}
+}