From 17a7d0d8660482fd6dab30ea697b0d77caae0b1b Mon Sep 17 00:00:00 2001 From: Ivan Kozlovic Date: Wed, 30 Oct 2019 14:24:57 -0600 Subject: [PATCH] [FIXED] Server should not send RTT PING before sending initial PONG As soon as server has processed a client CONNECT, it was possible that if Connz() or other was requested, the server will send a PING to compute the RTT. This would cause clients that expect the first PONG as part of synchronous CONNECT logic to fail. Make sure that we delay the first RTT ping to after sending the first PONG, or if client does not send PING as part of the CONNECT, after 2 seconds have elapsed since the tcp connection was accepted. Resolves #1174 Signed-off-by: Ivan Kozlovic --- server/client.go | 35 +++++++++++++++++++----- server/client_test.go | 63 +++++++++++++++++++++++++++++++++++++++++++ server/monitor.go | 4 +-- 3 files changed, 94 insertions(+), 8 deletions(-) diff --git a/server/client.go b/server/client.go index c1c76d0d..55bb0808 100644 --- a/server/client.go +++ b/server/client.go @@ -71,6 +71,12 @@ const ( shortsToShrink = 2 // Trigger to shrink dynamic buffers maxFlushPending = 10 // Max fsps to have in order to wait for writeLoop readLoopReport = 2 * time.Second + + // Server should not send a PING (for RTT) before the first PONG has + // been sent to the client. However, in case some client libs don't + // send CONNECT+PING, cap the maximum time before server can send + // the RTT PING. + maxNoRTTPingBeforeFirstPong = 2 * time.Second ) var readLoopReportThreshold = readLoopReport @@ -1524,12 +1530,29 @@ func (c *client) sendPong() { } // Used to kick off a RTT measurement for latency tracking. -func (c *client) sendRTTPing() { +func (c *client) sendRTTPing() bool { c.mu.Lock() - if c.flags.isSet(connectReceived) { - c.sendPing() - } + sent := c.sendRTTPingLocked() c.mu.Unlock() + return sent +} + +// Used to kick off a RTT measurement for latency tracking. +// This is normally called only when the caller has checked that +// the c.rtt is 0 and wants to force an update by sending a PING. +// Client lock held on entry. +func (c *client) sendRTTPingLocked() bool { + // Most client libs send a CONNECT+PING and wait for a PONG from the + // server. So if firstPongSent flag is set, it is ok for server to + // send the PING. But in case we have client libs that don't do that, + // allow the send of the PING if more than 2 secs have elapsed since + // the client TCP connection was accepted. + if !c.flags.isSet(clearConnection) && + (c.flags.isSet(firstPongSent) || time.Since(c.start) > maxNoRTTPingBeforeFirstPong) { + c.sendPing() + return true + } + return false } // Assume the lock is held upon entry. @@ -2321,8 +2344,8 @@ func (c *client) deliverMsg(sub *subscription, subject, mh, msg []byte) bool { // This needs to be from a non-client (otherwise tracking happens at requestor). if client.kind == CLIENT && len(c.pa.reply) > minReplyLen { // If we do not have a registered RTT queue that up now. - if client.rtt == 0 && client.flags.isSet(connectReceived) { - client.sendPing() + if client.rtt == 0 { + client.sendRTTPingLocked() } // FIXME(dlc) - We may need to optimize this. // We will have tagged this with a suffix ('.T') if we are tracking. This is diff --git a/server/client_test.go b/server/client_test.go index ac5bef83..d9f18fdc 100644 --- a/server/client_test.go +++ b/server/client_test.go @@ -1632,3 +1632,66 @@ func TestResponsePermissions(t *testing.T) { }) } } + +func TestPingNotSentTooSoon(t *testing.T) { + opts := DefaultOptions() + s := RunServer(opts) + defer s.Shutdown() + + doneCh := make(chan bool, 1) + wg := sync.WaitGroup{} + wg.Add(1) + go func() { + defer wg.Done() + for { + s.Connz(nil) + select { + case <-doneCh: + return + case <-time.After(time.Millisecond): + } + } + }() + + for i := 0; i < 100; i++ { + nc, err := nats.Connect(s.ClientURL()) + if err != nil { + t.Fatalf("Error on connect: %v", err) + } + nc.Close() + } + close(doneCh) + wg.Wait() + + c, br, _ := newClientForServer(s) + connectOp := []byte("CONNECT {\"user\":\"ivan\",\"pass\":\"bar\"}\r\n") + c.parse(connectOp) + + // Since client has not send PING, having server try to send RTT ping + // to client should not do anything + if c.sendRTTPing() { + t.Fatalf("RTT ping should not have been sent") + } + // Speed up detection of time elapsed by moving the c.start to more than + // 2 secs in the past. + c.mu.Lock() + c.start = time.Unix(0, c.start.UnixNano()-int64(maxNoRTTPingBeforeFirstPong+time.Second)) + c.mu.Unlock() + + errCh := make(chan error, 1) + go func() { + l, _ := br.ReadString('\n') + if l != "PING\r\n" { + errCh <- fmt.Errorf("expected to get PING, got %s", l) + return + } + errCh <- nil + }() + if !c.sendRTTPing() { + t.Fatalf("RTT ping should have been sent") + } + wg.Wait() + if e := <-errCh; e != nil { + t.Fatal(e.Error()) + } +} diff --git a/server/monitor.go b/server/monitor.go index 047e9ae1..bc0a4f4b 100644 --- a/server/monitor.go +++ b/server/monitor.go @@ -448,8 +448,8 @@ func (c *client) getRTT() string { if c.rtt == 0 { // If a real client, go ahead and send ping now to get a value // for RTT. For tests and telnet, or if client is closing, etc skip. - if !c.flags.isSet(clearConnection) && c.flags.isSet(connectReceived) && c.opts.Lang != "" { - c.sendPing() + if c.opts.Lang != "" { + c.sendRTTPingLocked() } return "" }