From daba652223bd6e2244a162a5c482872c4a6cde4b Mon Sep 17 00:00:00 2001
From: Tudor Golubenco <tudor@packetbeat.com>
Date: Tue, 8 Sep 2015 11:05:29 +0200
Subject: [PATCH 1/2] Fix negative response times for MongoDB.

The message timestamp could have was accidentally reused from an
old message in the same stream. For example, in this sequence of
messages in the same stream:

* `REPLY1` (with no matching request)
* `REQUEST2`
* `REPLY2`

packetbeat was correctly matching the REQUEST2 with REPLY2 but was using
the timestamp of REPLY1 for computing the response time. The fix is to
simply through away the message and wait for it to be created with the
new message received.

Should fix most of the issues from #216.

This also removes parseOffset and bytesReceived from the stream struct as
they were not used.
---
 protos/mongodb/mongodb_structs.go            |   5 +----
 tests/pcaps/mongodb_reply_request_reply.pcap | Bin 0 -> 1281 bytes
 tests/test_0025_mongodb_basic.py             |  17 +++++++++++++++++
 3 files changed, 18 insertions(+), 4 deletions(-)
 create mode 100644 tests/pcaps/mongodb_reply_request_reply.pcap

diff --git a/protos/mongodb/mongodb_structs.go b/protos/mongodb/mongodb_structs.go
index 3d650cee73e..e945d0628fe 100644
--- a/protos/mongodb/mongodb_structs.go
+++ b/protos/mongodb/mongodb_structs.go
@@ -44,16 +44,13 @@ type MongodbStream struct {
 
 	data []byte
 
-	parseOffset   int
-	bytesReceived int
-
 	message *MongodbMessage
 }
 
 // Parser moves to next message in stream
 func (stream *MongodbStream) PrepareForNewMessage() {
 	stream.data = stream.data[stream.message.messageLength:]
-	stream.message = &MongodbMessage{Ts: stream.message.Ts}
+	stream.message = nil
 }
 
 // The private data of a parser instance
diff --git a/tests/pcaps/mongodb_reply_request_reply.pcap b/tests/pcaps/mongodb_reply_request_reply.pcap
new file mode 100644
index 0000000000000000000000000000000000000000..9f5ffb5555fd6416bb606bff8c612b8a39e6c662
GIT binary patch
literal 1281
zcmZ`(&x;&I6n@jY#K}fvST-0>mZ*n-)pYkvdS+L|b;GU>COa{+?p}nUrn{!MlJ2Tb
zRnKHc5a;3{i1_0o0VA%5z@8Kd<PXq`9)dq|5+TP;0)qGttgmKfNg_!>RrPzX-uGVj
z_f_Bi@rPXpX5nxg8~~KiP}RTR{rdb2e1wLb^LvA@zWZtZ=Cgmke6<X#P`cdtbs3hA
zH2;_bb$kw<{#jhPcI?iLyB~jfSARM>0l$C#CL)!}bNjpPeRyx-lhcT@zp%HqJDOA|
zAC{c%w(9e^IEEMNEaUJDI{K`j+~hP<GEq<#CS#`H8cJouBPC;|hXAwN$`l6Lc;4~g
zIBp`RzDGUk`#uf)rJ(Nlb#Q!`$C&TAp6mNn_dy_dI1oGtfRk&H*&0s<#YUePtYmCw
z#VFb8Uf@yD7VmSc4<+k9%Z*_Px4xBO!3{wAmvb~#5lc4&VqUuc+4UBFjgq=(b8!6g
z`k0haX%;>})6NMU6KX6epq5^-q~sr3LM$=Yj)^OlkUKZ--5Q;kdHW=pkb;C<wZy!N
zDBq57!EyVk$<E?TNcW{Ei^ui>js<+Gbo(NWh3u)ZK*r5n$7XIiFrNQch_l!E%{KGa
zH;*dh-YsnC7pssjkh`fu{<RJD5$QfE#5QEr@HmCMgJ+xp*G4D_NAOVK)?DN^5yj@z
zdlJ2#ANuubgLQje82Px=yQe}{3r}_HUdVfK*sFDW0b{7Pp=sK8x`bJ0gzWE-iFg7U
zEYg}s0yjiKxOE!1JPO=_?*?u!YV2@HUi3-(>^ZWg1zA@E5_rU~FVz}LL4&NeH_-ML
z$xb8egf+6#YPB~yXPPUW&DHbmW^4U5zf)TTCsi!wdM#y%f#<LT+B?@gO=w<hYtCXq
zbv%?T6A?I(%5sq&p8ejQ-I7YufzU;tr8F*-CUi^Tw;6-RhY>Qx>`6sUp+!_smI`Ks
zObAVqxcgAKEtaMTVniaTEyy%S6BGOLqEwe9%{5E#3ZhfU0m8&IkG9d`THEru$T7iI
zvSKNOq#4hmEGM*81qZ=V-`FP{#rBIR8#`cjO6MC|vmv~Ip^67cGgSQXkEs%XRc57%
r3l8T38!!`Tkr%5n5t73UdN&&=P=SAeWi-k$@AeZ+dHnr*<WBtuRo_&}

literal 0
HcmV?d00001

diff --git a/tests/test_0025_mongodb_basic.py b/tests/test_0025_mongodb_basic.py
index 8c834fd64bb..12b2a7e7043 100644
--- a/tests/test_0025_mongodb_basic.py
+++ b/tests/test_0025_mongodb_basic.py
@@ -202,3 +202,20 @@ def test_write_errors(self):
         assert o["method"] == "insert"
         assert o["status"] == "Error"
         assert len(o["mongodb.error"]) > 0
+
+    def test_request_after_reply(self):
+        """
+        Tests that the response time is correctly captured when a single
+        reply is seen before the request.
+        This is a regression test for bug #216.
+        """
+        self.render_config_template(
+            mongodb_ports=[27017]
+        )
+        self.run_packetbeat(pcap="mongodb_reply_request_reply.pcap",
+                            debug_selectors=["mongodb"])
+
+        objs = self.read_output()
+        o = objs[0]
+        assert o["type"] == "mongodb"
+        assert o["responsetime"] >= 0

From 61b5242f65a35f85fb1fa1a5db5f79282d18e04d Mon Sep 17 00:00:00 2001
From: Tudor Golubenco <tudor@packetbeat.com>
Date: Tue, 8 Sep 2015 13:11:54 +0200
Subject: [PATCH 2/2] Fixed clearing the old message

Same as for MongoDB, this can be a cause of negative response
times.
---
 protos/redis/redis.go | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/protos/redis/redis.go b/protos/redis/redis.go
index 50ad4f1a718..334b93bff6f 100644
--- a/protos/redis/redis.go
+++ b/protos/redis/redis.go
@@ -293,7 +293,7 @@ func (redis *Redis) Init(test_mode bool, results chan common.MapStr) error {
 func (stream *RedisStream) PrepareForNewMessage() {
 	stream.data = stream.data[stream.parseOffset:]
 	stream.parseOffset = 0
-	stream.message = &RedisMessage{Ts: stream.message.Ts}
+	stream.message = nil
 	stream.message.Bulks = []string{}
 }