Bro behind a TLS reverse proxy

Zeek
1

Brandon,

The systems I tested are on are listed below. I also asked my Systems team to run the test on a datacenter hypervisor CentOS 7 server. Looks like they got a “normal” response as well.

Physical Server (Old IBM System x3650 server):
$ sudo uname -a
Linux <hostname> 3.10.0-693.2.2.el7.x86_64 #1 SMP Tue Sep 12 22:26:13 UTC 2017 x86_64 x86_64 x86_64 GNU/Linux
$

VirtualBox (5.2.8 r121009) VM (MacBook Pro Retina 15-inch, Mid 2015):
$ sudo uname -a
Linux <hostname> 3.10.0-693.21.1.el7.x86_64 #1 SMP Wed Mar 7 19:03:37 UTC 2018 x86_64 x86_64 x86_64 GNU/Linux
$

VM test from Overt 4.1 hypervisor:
kernel - 3.10.0-693.5.2.el7.x86_64
2018-04-10 11:14:11.996559 IP6 ::1.57652 > ::1.80: Flags [S], seq 579221221, win 43690, options [mss 65476,sackOK,TS val 1190091725 ecr 0,nop,wscale 7], length 0
2018-04-10 11:14:11.996579 IP6 ::1.80 > ::1.57652: Flags [R.], seq 0, ack 579221222, win 0, length 0
2018-04-10 11:14:11.996699 IP 127.0.0.1.43500 > 127.0.0.1.80: Flags [S], seq 2884971053, win 43690, options [mss 65495,sackOK,TS val 1190091725 ecr 0,nop,wscale 7], length 0
2018-04-10 11:14:11.996715 IP 127.0.0.1.80 > 127.0.0.1.43500: Flags [R.], seq 0, ack 2884971054, win 0, length 0

2

Hi Philip,

What sequence of commands are you using to test? On all C7 instances I have tested, virtual and bare metal, when capturing of the lo interface with tcpdump, and analyzing the pcaps with tshark, I’m seeing 100% of SYN, ACK packets as having the bogus timestamp.

Are you confident using tcpdump to both capture and replay the packets to look at field values? Isn’t it possible that tcpdump is writing to and reading from the pcap in the same incorrect way?

Thanks,

Brandon

3

You might check what virtual network adapter is being used. If it’s a network driver bug then switching adapters would prove that.

https://www.virtualbox.org/manual/ch06.html

4

I’ve observed the bad timestamp for loopback captures on three different virtualization platforms (VirtualBox, OpenStack, Hyper-V), as well as bare metal.

Thanks,

Brandon

5

Still could be a network driver issue. What kind of card is eth0 ?

Your original problem looks like Bro is inline or on the same network instead of behind the nginx proxy. Maybe even running on the nginx proxy ?

6

Thank you for responding. I have a simplified testcase that doesn’t require nginx:

[shell1]$ sudo tcpdump -s 0 -i lo -w lo-port-80.pcap “port 80”

[shell2]$ sudo python -m SimpleHTTPServer 80

[shell3]$ curl localhost

[shell1]$ ^C

[shell1]$ tshark -t ud -r lo-port-80.pcap

Note the timestamps for any SYN-ACK packets in the captured streams.

Cheers,

Brandon

7

Brandon,

Success…? Both my VirtualBox VM and physical server show the wrong date/time on the SYN/ACK using the updated testing script you sent. This was just a confirmation for what you had already confirmed as a reproducible issue though. I don’t have any next steps suggestions, sorry.

$ tshark -t ud -r lo-port-80.pcap
1 2018-04-10 22:07:21 ::1 → ::1 TCP 94 60782 > http [SYN] Seq=0 Win=43690 Len=0 MSS=65476 SACK_PERM=1 TSval=4294828850 TSecr=0 WS=128
2 2018-04-10 22:07:21 ::1 → ::1 TCP 74 http > 60782 [RST, ACK] Seq=1 Ack=1 Win=0 Len=0
3 2018-04-10 22:07:21 127.0.0.1 → 127.0.0.1 TCP 74 39762 > http [SYN] Seq=0 Win=43690 Len=0 MSS=65495 SACK_PERM=1 TSval=4294828850 TSecr=0 WS=128
4 2106-01-31 09:17:55 127.0.0.1 → 127.0.0.1 TCP 74 http > 39762 [SYN, ACK] Seq=0 Ack=1 Win=43690 Len=0 MSS=65495 SACK_PERM=1 TSval=4294828850 TSecr=4294828850 WS=128
5 2018-04-10 22:07:21 127.0.0.1 → 127.0.0.1 TCP 66 39762 > http [ACK] Seq=1 Ack=1 Win=43776 Len=0 TSval=4294828850 TSecr=4294828850
6 2018-04-10 22:07:21 127.0.0.1 → 127.0.0.1 HTTP 139 GET / HTTP/1.1
7 2018-04-10 22:07:21 127.0.0.1 → 127.0.0.1 TCP 66 http > 39762 [ACK] Seq=1 Ack=74 Win=43776 Len=0 TSval=4294828851 TSecr=4294828851
8 2018-04-10 22:07:21 127.0.0.1 → 127.0.0.1 TCP 83 [TCP segment of a reassembled PDU]
9 2018-04-10 22:07:21 127.0.0.1 → 127.0.0.1 TCP 66 39762 > http [ACK] Seq=74 Ack=18 Win=43776 Len=0 TSval=4294828856 TSecr=4294828856
10 2018-04-10 22:07:21 127.0.0.1 → 127.0.0.1 TCP 103 [TCP segment of a reassembled PDU]
11 2018-04-10 22:07:21 127.0.0.1 → 127.0.0.1 TCP 66 39762 > http [ACK] Seq=74 Ack=55 Win=43776 Len=0 TSval=4294828856 TSecr=4294828856
12 2018-04-10 22:07:21 127.0.0.1 → 127.0.0.1 TCP 103 [TCP segment of a reassembled PDU]
13 2018-04-10 22:07:21 127.0.0.1 → 127.0.0.1 TCP 66 39762 > http [ACK] Seq=74 Ack=92 Win=43776 Len=0 TSval=4294828856 TSecr=4294828856
14 2018-04-10 22:07:21 127.0.0.1 → 127.0.0.1 TCP 129 [TCP segment of a reassembled PDU]
15 2018-04-10 22:07:21 127.0.0.1 → 127.0.0.1 TCP 66 39762 > http [ACK] Seq=74 Ack=155 Win=43776 Len=0 TSval=4294828856 TSecr=4294828856
16 2018-04-10 22:07:21 127.0.0.1 → 127.0.0.1 HTTP 838 HTTP/1.0 200 OK (text/html)
17 2018-04-10 22:07:21 127.0.0.1 → 127.0.0.1 TCP 66 39762 > http [ACK] Seq=74 Ack=927 Win=45312 Len=0 TSval=4294828856 TSecr=4294828856
18 2018-04-10 22:07:21 127.0.0.1 → 127.0.0.1 TCP 66 http > 39762 [FIN, ACK] Seq=927 Ack=74 Win=43776 Len=0 TSval=4294828856 TSecr=4294828856
19 2018-04-10 22:07:21 127.0.0.1 → 127.0.0.1 TCP 66 39762 > http [FIN, ACK] Seq=74 Ack=928 Win=45312 Len=0 TSval=4294828856 TSecr=4294828856
20 2018-04-10 22:07:21 127.0.0.1 → 127.0.0.1 TCP 66 http > 39762 [ACK] Seq=928 Ack=75 Win=43776 Len=0 TSval=4294828856 TSecr=4294828856
$

$ tcpdump -ttttnnr lo-port-80.pcap
reading from file lo-port-80.pcap, link-type EN10MB (Ethernet)
2018-04-10 15:28:49.065635 IP6 ::1.49766 > ::1.80: Flags [S], seq 2880441537, win 43690, options [mss 65476,sackOK,TS val 1116497470 ecr 0,nop,wscale 7], length 0
2018-04-10 15:28:49.065668 IP6 ::1.80 > ::1.49766: Flags [R.], seq 0, ack 2880441538, win 0, length 0
2018-04-10 15:28:49.065840 IP 127.0.0.1.44468 > 127.0.0.1.80: Flags [S], seq 3964604917, win 43690, options [mss 65495,sackOK,TS val 1116497470 ecr 0,nop,wscale 7], length 0
1985-11-08 19:53:43.822714 IP 127.0.0.1.80 > 127.0.0.1.44468: Flags [S.], seq 3727387360, ack 3964604918, win 43690, options [mss 65495,sackOK,TS val 1116497470 ecr 1116497470,nop,wscale 7], length 0
2018-04-10 15:28:49.065886 IP 127.0.0.1.44468 > 127.0.0.1.80: Flags [.], ack 1, win 342, options [nop,nop,TS val 1116497470 ecr 1116497470], length 0
2018-04-10 15:28:49.065973 IP 127.0.0.1.44468 > 127.0.0.1.80: Flags [P.], seq 1:74, ack 1, win 342, options [nop,nop,TS val 1116497471 ecr 1116497470], length 73: HTTP: GET / HTTP/1.1
2018-04-10 15:28:49.065987 IP 127.0.0.1.80 > 127.0.0.1.44468: Flags [.], ack 74, win 342, options [nop,nop,TS val 1116497471 ecr 1116497471], length 0
2018-04-10 15:28:49.176734 IP 127.0.0.1.80 > 127.0.0.1.44468: Flags [P.], seq 1:18, ack 74, win 342, options [nop,nop,TS val 1116497581 ecr 1116497471], length 17: HTTP: HTTP/1.0 200 OK
2018-04-10 15:28:49.176760 IP 127.0.0.1.44468 > 127.0.0.1.80: Flags [.], ack 18, win 342, options [nop,nop,TS val 1116497581 ecr 1116497581], length 0
2018-04-10 15:28:49.176813 IP 127.0.0.1.80 > 127.0.0.1.44468: Flags [P.], seq 18:55, ack 74, win 342, options [nop,nop,TS val 1116497581 ecr 1116497581], length 37: HTTP
2018-04-10 15:28:49.176831 IP 127.0.0.1.44468 > 127.0.0.1.80: Flags [.], ack 55, win 342, options [nop,nop,TS val 1116497581 ecr 1116497581], length 0
2018-04-10 15:28:49.176886 IP 127.0.0.1.80 > 127.0.0.1.44468: Flags [P.], seq 55:92, ack 74, win 342, options [nop,nop,TS val 1116497581 ecr 1116497581], length 37: HTTP
2018-04-10 15:28:49.176900 IP 127.0.0.1.44468 > 127.0.0.1.80: Flags [.], ack 92, win 342, options [nop,nop,TS val 1116497581 ecr 1116497581], length 0
2018-04-10 15:28:49.176951 IP 127.0.0.1.80 > 127.0.0.1.44468: Flags [P.], seq 92:132, ack 74, win 342, options [nop,nop,TS val 1116497581 ecr 1116497581], length 40: HTTP
2018-04-10 15:28:49.176966 IP 127.0.0.1.44468 > 127.0.0.1.80: Flags [.], ack 132, win 342, options [nop,nop,TS val 1116497582 ecr 1116497581], length 0
2018-04-10 15:28:49.177003 IP 127.0.0.1.80 > 127.0.0.1.44468: Flags [P.], seq 132:154, ack 74, win 342, options [nop,nop,TS val 1116497582 ecr 1116497582], length 22: HTTP
2018-04-10 15:28:49.177016 IP 127.0.0.1.44468 > 127.0.0.1.80: Flags [.], ack 154, win 342, options [nop,nop,TS val 1116497582 ecr 1116497582], length 0
2018-04-10 15:28:49.177051 IP 127.0.0.1.80 > 127.0.0.1.44468: Flags [P.], seq 154:156, ack 74, win 342, options [nop,nop,TS val 1116497582 ecr 1116497582], length 2: HTTP
2018-04-10 15:28:49.177064 IP 127.0.0.1.44468 > 127.0.0.1.80: Flags [.], ack 156, win 342, options [nop,nop,TS val 1116497582 ecr 1116497582], length 0
2018-04-10 15:28:49.177124 IP 127.0.0.1.80 > 127.0.0.1.44468: Flags [P.], seq 156:5992, ack 74, win 342, options [nop,nop,TS val 1116497582 ecr 1116497582], length 5836: HTTP
2018-04-10 15:28:49.177142 IP 127.0.0.1.44468 > 127.0.0.1.80: Flags [.], ack 5992, win 1365, options [nop,nop,TS val 1116497582 ecr 1116497582], length 0
2018-04-10 15:28:49.177212 IP 127.0.0.1.80 > 127.0.0.1.44468: Flags [F.], seq 5992, ack 74, win 342, options [nop,nop,TS val 1116497582 ecr 1116497582], length 0
2018-04-10 15:28:49.178159 IP 127.0.0.1.44468 > 127.0.0.1.80: Flags [F.], seq 74, ack 5993, win 1365, options [nop,nop,TS val 1116497583 ecr 1116497582], length 0
2018-04-10 15:28:49.178176 IP 127.0.0.1.80 > 127.0.0.1.44468: Flags [.], ack 75, win 342, options [nop,nop,TS val 1116497583 ecr 1116497583], length 0
$

8

I'm not sure what the problem is here, but it most definitely does not have anything to do with physical/virtual or nic hardware..

The lo interface is handled 100% by the kernel and doesn't touch the hardware, so this looks like some odd kernel or libpcap bug. I don't think libpcap does anything with the timestamps other than to send them along, and the fact that this seems to only happen on the synack packet points more to a kernel issue.

It's probably related to some kind of optimization for completing connections faster over loopback.

If one has time, converting the test case into a reproducable script and using it with git bisect on the kernel could track this down.