Why do I get duplicate new_connection event?

Zeek
1

Hi,
   
  I am quite new in Bro. I have been experimenting
with it for a couple of days by now, and couldn't
figure out the reason for the problem below (I went
through the archives as much as I can but nothing
popped up).
   
  I am running the following simple bro script on the
test data using the steps below:
   
  $cat a.bro
@load weird
  
event new_connection(c: connection)
{
   print fmt("new connection=%s",c);
}
   
  $tcpdump -r test.1 -n -tt
reading from file test.1, link-type EN10MB (Ethernet)
1007672739.741946 IP 190.84.172.89.2278 >
222.37.1.55.80: S 3585205640:3585205640(0) win 5840
<mss 1460,sackOK,timestamp 4795498 0,nop,wscale 0>
1007672740.081079 IP 222.37.1.55.80 >
190.84.172.89.2278: S 3552369456:3552369456(0) ack
3585205641 win 1460 <mss 1460,sackOK,timestamp
658637388 4795498,nop,wscale 0>
1007672740.083354 IP 190.84.172.89.2278 >
222.37.1.55.80: . ack 1 win 5840 <nop,nop,timestamp
4795532 658637388>
1007672740.090794 IP 190.84.172.89.2278 >
222.37.1.55.80: P 1:626(625) ack 1 win 5840
<nop,nop,timestamp 4795532 658637388>
1007672740.443563 IP 222.37.1.55.80 >
190.84.172.89.2278: . ack 626 win 31856
<nop,nop,timestamp 658637423 4795532>
1007672743.331707 IP 222.37.1.55.80 >
190.84.172.89.2278: P 1:206(205) ack 626 win 31856
<nop,nop,timestamp 658637723 4795532>
1007672743.334165 IP 190.84.172.89.2278 >
222.37.1.55.80: . ack 206 win 6432 <nop,nop,timestamp
4795857 658637723>
1007672743.478567 IP 190.84.172.89.2278 >
222.37.1.55.80: P 626:1262(636) ack 206 win 6432
<nop,nop,timestamp 4795871 658637723>
1007672743.692464 IP 222.37.1.55.80 >
190.84.172.89.2278: P 206:410(204) ack 1262 win 31856
<nop,nop,timestamp 658637762 4795871>
1007672743.694853 IP 190.84.172.89.2278 >
222.37.1.55.80: . ack 410 win 7504 <nop,nop,timestamp
4795893 658637762>
1007672743.838441 IP 190.84.172.89.2278 >
222.37.1.55.80: P 1262:1895(633) ack 410 win 7504
<nop,nop,timestamp 4795907 658637762>
1007672744.048642 IP 222.37.1.55.80 >
190.84.172.89.2278: P 410:614(204) ack 1895 win 31856
<nop,nop,timestamp 658637799 4795907>
1007672744.051076 IP 190.84.172.89.2278 >
222.37.1.55.80: . ack 614 win 8576 <nop,nop,timestamp
4795929 658637799>
1007672751.518485 IP 190.84.172.89.2278 >
222.37.1.55.80: F 1895:1895(0) ack 614 win 8576
<nop,nop,timestamp 4796676 658637799>
1007672751.835071 IP 222.37.1.55.80 >
190.84.172.89.2278: . ack 1896 win 31856
<nop,nop,timestamp 658638566 4796676>
1007672751.835299 IP 222.37.1.55.80 >
190.84.172.89.2278: F 614:614(0) ack 1896 win 31856
<nop,nop,timestamp 658638566 4796676>
1007672751.839189 IP 190.84.172.89.2278 >
222.37.1.55.80: . ack 615 win 8576 <nop,nop,timestamp
4796708 658638566>

  $bro -r test.1 ./a.bro
new connection=[id=[orig_h=190.84.172.89,
orig_p=2278/tcp, resp_h=222.37.1.55, resp_p=80/tcp],
orig=[size=0, state=1], resp=[size=0, state=0],
start_time=1007672739.74195, duration=0.0, service=,
addl=cc=1, hot=0, history=]

(I REMOVED HTTP CONTENT GAP EVENTS FOR CONCISENESS)

new connection=[id=[orig_h=190.84.172.89,
orig_p=2278/tcp, resp_h=222.37.1.55, resp_p=80/tcp],
orig=[size=0, state=0], resp=[size=0, state=0],
start_time=1007672751.83919, duration=0.0, service=,
addl=, hot=0, history=]
$

  From the timestamp, it looks to me that the second
new connection is triggered by the last ACK. But this
ACK is the ACK of the FIN packet from server, so we
should not receive a second new_connection event. Is
there anything I am missing here, or is it the
expected behavior?

Note: I am using bro-1.2.1 and did not change anything
in the policy directory.
   
  Thanks for all your time,

2

Hi,

it's not clear to me why you see an additional new_connection event, but
I also don't understand why you apparently encounter content gaps,
because (after just eyeballing) I don't see any. Would you mind sending
that trace?

ps: it's a good idea to turn off linewrapping in your mailer when
sending log output.

Cheers,
Christian

3

Thanks for quick response. I was believing (but I may
be wrong) this is because only the first 64 bytes of
the packets exist in this pcap file. Here is test.1
(uuencoded). I also attach it to this email.

regards,

begin 644 test.1
MU,.RH0(`!````````````)`````!````H]T//#I2"P!*````3@```"%,M\VB
MH``P9=5>"`@`10``/,GB0`!`!B;/OE2L6=XE`3<(Y@!0U;'EB`````"@`A;0
M]@@```($!;0$`@@*`$DL:@`````!`P,`I-T//+<\`0!*````3@```"%,M\VB
MH`@`*YZ(F0@`10``/"8K0``V!M2&WB4!-[Y4K%D`4`CFT[S;,-6QY8F@$@6T
M+I@```($!;0$`@@*)T("3`!)+&H!`P,`I-T//)I%`0!"````3@```"%,M\VB
MH``P9=5>"`@`10``-,GC0`!`!B;6OE2L6=XE`3<(Y@!0U;'EB=.\VS&`$!;0
M3!\```$!"`H`22R,)T("3*3=#SRJ8@$`0@```+<"```A3+?-HJ``,&757@@(
M`$4``J7)Y$``0`8D9+Y4K%G>)0$W".8`4-6QY8G3O-LQ@!@6T`+.```!`0@*
M`$DLC"="`DRDW0\\J\0&`$(```!&````(4RWS:*@"``KGHB9"`!%```T)DU`
M`#8&U&S>)0$WOE2L60!0".;3O-LQU;'G^H`0?'#CZ@```0$("B="`F\`22R,
MI]T//+L/!0!"````$P$``"%,M\VBH`@`*YZ(F0@`10`!`2;E0``V!M,'WB4!
M-[Y4K%D`4`CFT[S;,=6QY_J`&'QP/E(```$!"`HG0@.;`$DLC*?=#SQ5&04`
M0@```$X````A3+?-HJ``,&757@@(`$4``#3)Y4``0`8FU+Y4K%G>)0$W".8`
M4-6QY_K3O-O^@!`9($/]```!`0@*`$DMT2="`YNGW0\\9TT'`$(```#"`@``
M(4RWS:*@`#!EU5X("`!%``*PR>9``$`&)%>^5*Q9WB4!-PCF`%#5L>?ZT[S;
M_H`8&2!W20```0$("@!)+=\G0@.;I]T///"0"@!"````$@$``"%,M\VBH`@`
M*YZ(F0@`10`!`";[0``V!M+RWB4!-[Y4K%D`4`CFT[S;_M6QZG:`&'QP`*\`
M``$!"`HG0@/"`$DMWZ?=#SQ%F@H`0@```$X````A3+?-HJ``,&757@@(`$4`
M`#3)YT``0`8FTKY4K%G>)0$W".8`4-6QZG;3O-S*@!`=4#PZ```!`0@*`$DM
M]2="`\*GW0\\*<L,`$(```"_`@``(4RWS:*@`#!EU5X("`!%``*MR>A``$`&
M)%B^5*Q9WB4!-PCF`%#5L>IVT[S<RH`8'5!5(````0$("@!)+@,G0@/"J-T/
M/`*^``!"````$@$``"%,M\VBH`@`*YZ(F0@`10`!`"<50``V!M+8WB4!-[Y4
MK%D`4`CFT[S<RM6Q[.^`&'QPUDT```$!"`HG0@/G`$DN`ZC=#SR$QP``0@``
M`$X````A3+?-HJ``,&757@@(`$4``#3)Z4``0`8FT+Y4K%G>)0$W".8`4-6Q
M[._3O-V6@!`A@#1\```!`0@*`$DN&2="`^>OW0\\5>D'`$(```!.````(4RW
MS:*@`#!EU5X("`!%```TR>I``$`&)L^^5*Q9WB4!-PCF`%#5L>SOT[S=EH`1
M(8`QD````0$("@!),00G0@/GK]T///^]#`!"````1@```"%,M\VBH`@`*YZ(
MF0@`10``-"C@0``V!M'9WB4!-[Y4K%D`4`CFT[S=EM6Q[/"`$'QPTZ````$!
M"`HG0@;F`$DQ!*_=#SSCO@P`0@```$8````A3+?-HJ`(`"N>B)D(`$4``#0H
MX4``-@;1V-XE`3>^5*Q9`%`(YM.\W9;5L>SP@!%\<-.?```!`0@*)T(&Y@!)
M,02OW0\\%<X,`$(```!.````(4RWS:*@`#!EU5X("`!%```T``!``/\&,;F^
G5*Q9WB4!-PCF`%#5L>SPT[S=EX`0(8`N<````0$("@!),20G0@;F
`
end

test.1 (1.4 KB)

4

Hi Again,

I would like to post the pcap file (test.1) that caused double new_connection messages. My
previous email contained this file in uuencoded format, however, I have discovered that the email
system somehow substituted @ with `at` in message body.
Since I do not know how to work around this problem and/or post a binary file, I am posting the
fully decoded pcap file instead. I hope somebody can point the reason for double new connection
messages quickly.

Best regards,

$ tcpdump -r test.1 -XX -n
16:05:39.741946 IP 190.84.172.89.2278 > 222.37.1.55.80: S
3585205640:3585205640(0) win 5840 <mss 1460,sackOK,timestamp 4795498 0,nop,wscale 0>
  0x0000: 214c b7cd a2a0 0030 65d5 5e08 0800 4500 !L.....0e.^...E.
  0x0010: 003c c9e2 4000 4006 26cf be54 ac59 de25 .<..@.@.&..T.Y.%
  0x0020: 0137 08e6 0050 d5b1 e588 0000 0000 a002 .7...P..........
  0x0030: 16d0 f608 0000 0204 05b4 0402 080a 0049 ...............I
  0x0040: 2c6a 0000 0000 0103 0300 ,j........
16:05:40.081079 IP 222.37.1.55.80 > 190.84.172.89.2278: S
3552369456:3552369456(0) ack 3585205641 win 1460 <mss 1460,sackOK,timestamp
658637388 4795498,nop,wscale 0>
  0x0000: 214c b7cd a2a0 0800 2b9e 8899 0800 4500 !L......+.....E.
  0x0010: 003c 262b 4000 3606 d486 de25 0137 be54 .<&+@.6....%.7.T
  0x0020: ac59 0050 08e6 d3bc db30 d5b1 e589 a012 .Y.P.....0......
  0x0030: 05b4 2e98 0000 0204 05b4 0402 080a 2742 ..............'B
  0x0040: 024c 0049 2c6a 0103 0300 .L.I,j....
16:05:40.083354 IP 190.84.172.89.2278 > 222.37.1.55.80: . ack 1 win
5840 <nop,nop,timestamp 4795532 658637388>
  0x0000: 214c b7cd a2a0 0030 65d5 5e08 0800 4500 !L.....0e.^...E.
  0x0010: 0034 c9e3 4000 4006 26d6 be54 ac59 de25 .4..@.@.&..T.Y.%
  0x0020: 0137 08e6 0050 d5b1 e589 d3bc db31 8010 .7...P.......1..
  0x0030: 16d0 4c1f 0000 0101 080a 0049 2c8c 2742 ..L........I,.'B
  0x0040: 024c .L
16:05:40.090794 IP 190.84.172.89.2278 > 222.37.1.55.80: P 1:626(625)
ack 1 win 5840 <nop,nop,timestamp 4795532 658637388>
  0x0000: 214c b7cd a2a0 0030 65d5 5e08 0800 4500 !L.....0e.^...E.
  0x0010: 02a5 c9e4 4000 4006 2464 be54 ac59 de25 ....@.@.$d.T.Y.%
  0x0020: 0137 08e6 0050 d5b1 e589 d3bc db31 8018 .7...P.......1..
  0x0030: 16d0 02ce 0000 0101 080a 0049 2c8c 2742 ...........I,.'B
  0x0040: 024c .L
16:05:40.443563 IP 222.37.1.55.80 > 190.84.172.89.2278: . ack 626 win
31856 <nop,nop,timestamp 658637423 4795532>
  0x0000: 214c b7cd a2a0 0800 2b9e 8899 0800 4500 !L......+.....E.
  0x0010: 0034 264d 4000 3606 d46c de25 0137 be54 .4&M@.6..l.%.7.T
  0x0020: ac59 0050 08e6 d3bc db31 d5b1 e7fa 8010 .Y.P.....1......
  0x0030: 7c70 e3ea 0000 0101 080a 2742 026f 0049 |p........'B.o.I
  0x0040: 2c8c ,.
16:05:43.331707 IP 222.37.1.55.80 > 190.84.172.89.2278: P 1:206(205)
ack 626 win 31856 <nop,nop,timestamp 658637723 4795532>
  0x0000: 214c b7cd a2a0 0800 2b9e 8899 0800 4500 !L......+.....E.
  0x0010: 0101 26e5 4000 3606 d307 de25 0137 be54 ..&.@.6....%.7.T
  0x0020: ac59 0050 08e6 d3bc db31 d5b1 e7fa 8018 .Y.P.....1......
  0x0030: 7c70 3e52 0000 0101 080a 2742 039b 0049 |p>R......'B...I
  0x0040: 2c8c ,.
16:05:43.334165 IP 190.84.172.89.2278 > 222.37.1.55.80: . ack 206 win
6432 <nop,nop,timestamp 4795857 658637723>
  0x0000: 214c b7cd a2a0 0030 65d5 5e08 0800 4500 !L.....0e.^...E.
  0x0010: 0034 c9e5 4000 4006 26d4 be54 ac59 de25 .4..@.@.&..T.Y.%
  0x0020: 0137 08e6 0050 d5b1 e7fa d3bc dbfe 8010 .7...P..........
  0x0030: 1920 43fd 0000 0101 080a 0049 2dd1 2742 ..C........I-.'B
  0x0040: 039b ..
16:05:43.478567 IP 190.84.172.89.2278 > 222.37.1.55.80: P 626:1262(636)
ack 206 win 6432 <nop,nop,timestamp 4795871 658637723>
  0x0000: 214c b7cd a2a0 0030 65d5 5e08 0800 4500 !L.....0e.^...E.
  0x0010: 02b0 c9e6 4000 4006 2457 be54 ac59 de25 ....@.@.$W.T.Y.%
  0x0020: 0137 08e6 0050 d5b1 e7fa d3bc dbfe 8018 .7...P..........
  0x0030: 1920 7749 0000 0101 080a 0049 2ddf 2742 ..wI.......I-.'B
  0x0040: 039b ..
16:05:43.692464 IP 222.37.1.55.80 > 190.84.172.89.2278: P 206:410(204)
ack 1262 win 31856 <nop,nop,timestamp 658637762 4795871>
  0x0000: 214c b7cd a2a0 0800 2b9e 8899 0800 4500 !L......+.....E.
  0x0010: 0100 26fb 4000 3606 d2f2 de25 0137 be54 ..&.@.6....%.7.T
  0x0020: ac59 0050 08e6 d3bc dbfe d5b1 ea76 8018 .Y.P.........v..
  0x0030: 7c70 00af 0000 0101 080a 2742 03c2 0049 |p........'B...I
  0x0040: 2ddf -.
16:05:43.694853 IP 190.84.172.89.2278 > 222.37.1.55.80: . ack 410 win
7504 <nop,nop,timestamp 4795893 658637762>
  0x0000: 214c b7cd a2a0 0030 65d5 5e08 0800 4500 !L.....0e.^...E.
  0x0010: 0034 c9e7 4000 4006 26d2 be54 ac59 de25 .4..@.@.&..T.Y.%
  0x0020: 0137 08e6 0050 d5b1 ea76 d3bc dcca 8010 .7...P...v......
  0x0030: 1d50 3c3a 0000 0101 080a 0049 2df5 2742 .P<:.......I-.'B
  0x0040: 03c2 ..
16:05:43.838441 IP 190.84.172.89.2278 > 222.37.1.55.80: P
1262:1895(633) ack 410 win 7504 <nop,nop,timestamp 4795907 658637762>
  0x0000: 214c b7cd a2a0 0030 65d5 5e08 0800 4500 !L.....0e.^...E.
  0x0010: 02ad c9e8 4000 4006 2458 be54 ac59 de25 ....@.@.$X.T.Y.%
  0x0020: 0137 08e6 0050 d5b1 ea76 d3bc dcca 8018 .7...P...v......
  0x0030: 1d50 5520 0000 0101 080a 0049 2e03 2742 .PU........I..'B
  0x0040: 03c2 ..
16:05:44.048642 IP 222.37.1.55.80 > 190.84.172.89.2278: P 410:614(204)
ack 1895 win 31856 <nop,nop,timestamp 658637799 4795907>
  0x0000: 214c b7cd a2a0 0800 2b9e 8899 0800 4500 !L......+.....E.
  0x0010: 0100 2715 4000 3606 d2d8 de25 0137 be54 ..'.@.6....%.7.T
  0x0020: ac59 0050 08e6 d3bc dcca d5b1 ecef 8018 .Y.P............
  0x0030: 7c70 d64d 0000 0101 080a 2742 03e7 0049 |p.M......'B...I
  0x0040: 2e03 ..
16:05:44.051076 IP 190.84.172.89.2278 > 222.37.1.55.80: . ack 614 win
8576 <nop,nop,timestamp 4795929 658637799>
  0x0000: 214c b7cd a2a0 0030 65d5 5e08 0800 4500 !L.....0e.^...E.
  0x0010: 0034 c9e9 4000 4006 26d0 be54 ac59 de25 .4..@.@.&..T.Y.%
  0x0020: 0137 08e6 0050 d5b1 ecef d3bc dd96 8010 .7...P..........
  0x0030: 2180 347c 0000 0101 080a 0049 2e19 2742 !.4|.......I..'B
  0x0040: 03e7 ..
16:05:51.518485 IP 190.84.172.89.2278 > 222.37.1.55.80: F 1895:1895(0)
ack 614 win 8576 <nop,nop,timestamp 4796676 658637799>
  0x0000: 214c b7cd a2a0 0030 65d5 5e08 0800 4500 !L.....0e.^...E.
  0x0010: 0034 c9ea 4000 4006 26cf be54 ac59 de25 .4..@.@.&..T.Y.%
  0x0020: 0137 08e6 0050 d5b1 ecef d3bc dd96 8011 .7...P..........
  0x0030: 2180 3190 0000 0101 080a 0049 3104 2742 !.1........I1.'B
  0x0040: 03e7 ..
16:05:51.835071 IP 222.37.1.55.80 > 190.84.172.89.2278: . ack 1896 win
31856 <nop,nop,timestamp 658638566 4796676>
  0x0000: 214c b7cd a2a0 0800 2b9e 8899 0800 4500 !L......+.....E.
  0x0010: 0034 28e0 4000 3606 d1d9 de25 0137 be54 .4(.@.6....%.7.T
  0x0020: ac59 0050 08e6 d3bc dd96 d5b1 ecf0 8010 .Y.P............
  0x0030: 7c70 d3a0 0000 0101 080a 2742 06e6 0049 |p........'B...I
  0x0040: 3104 1.
16:05:51.835299 IP 222.37.1.55.80 > 190.84.172.89.2278: F 614:614(0)
ack 1896 win 31856 <nop,nop,timestamp 658638566 4796676>
  0x0000: 214c b7cd a2a0 0800 2b9e 8899 0800 4500 !L......+.....E.
  0x0010: 0034 28e1 4000 3606 d1d8 de25 0137 be54 .4(.@.6....%.7.T
  0x0020: ac59 0050 08e6 d3bc dd96 d5b1 ecf0 8011 .Y.P............
  0x0030: 7c70 d39f 0000 0101 080a 2742 06e6 0049 |p........'B...I
  0x0040: 3104 1.
16:05:51.839189 IP 190.84.172.89.2278 > 222.37.1.55.80: . ack 615 win
8576 <nop,nop,timestamp 4796708 658638566>
  0x0000: 214c b7cd a2a0 0030 65d5 5e08 0800 4500 !L.....0e.^...E.
  0x0010: 0034 0000 4000 ff06 31b9 be54 ac59 de25 .4..@...1..T.Y.%
  0x0020: 0137 08e6 0050 d5b1 ecf0 d3bc dd97 8010 .7...P..........
  0x0030: 2180 2e70 0000 0101 080a 0049 3124 2742 !..p.......I1$'B
  0x0040: 06e6 ..

5

Thanks for this. Robin and I just had a look, and you're indeed not
seeing the intended behavior. The problem is that currently
tcp_close_delay is set to 0 seconds and so Bro considers the connection
complete immediately after having seen both FINs. Either bump up
tcp_close_delay ...

  bro -r test.1 tcp_close_delay=1sec a.bro

... or load heavy-analysis.bro (which also bumps up the various
timeouts):

  bro -r test.1 a.bro heavy-analysis

In the next release, we'll likely set tcp_close_delay to a small but
non-zero timeout.

Cheers,
Christian