SSH heuristic

I had a question about the SSH analyzer and how it determines a successful connection. I have a bro notification for a successful SSH login to a system on my network for a connection originating from outside US. Log entry:
conn.log 2013-09-01 10:04:31 KIDipWlFWSi y.y.y.y 40014 x.x.x.x 22 tcp ssh 147.140508 1160 2377 S3 F 0 ShAadDf 21 2664 48 8221
ssh.log 2013-09-01 10:04:33 KIDipWlFWSi y.y.y.y 40014 x.x.x.x 22 success INBOUND SSH-2.0-libssh-0.2 SSH-2.0-OpenSSH_5.9 5725 CN - - - -

The log entry is dated on the 1st and my client side logs have rolled over, so I can’t valid this with syslog on the client.

I wanted to check if there’s a chance this could be a false positive. Also, the switch providing the feed itself is dropping packets and I see alerts for CaptureLoss::Too_Much_Loss and PacketFilter::Dropped_Packets.

Would this loss cause Bro to misinterpret a brute forcing/scan attempt to a successful login?

I’m running Bro 2.0.

For the first part, that "5725" is the number of response bytes. The
threshold for what is considered successful is: const
authentication_data_size, which can be found in:
/bro/share/bro/base/protocols/ssh and I believe it's default value was
either 5000 or 5500 on 2.0. Though if you want to redef this you'll want
to do it elsewhere such as your local.bro. Seth spent lots of time
figuring out the best threshold, but it is still only a guess based on
bytes, so there will be false positives. We find that many of them just
around 5000 bytes were false positives.

I don't know about your second part off the top of my head.

-Sam

Right, if the ssh connection’s response bytes are above this threshold it’ll log the session as having a successful login. If you have a large pre-auth login banner (usually for compliance reasons) it will very likely report as a false positive.

Hey all,

Topic says it...it's very strange..new install on a different box..I see the below:

[12:08:56 gateway:~/current$] ls -l
total 64
-rw-r--r-- 1 root root 3914 Sep 13 12:08 communication.log
-rw-r--r-- 1 root root 4082 Sep 13 12:08 conn.log
-rw-r--r-- 1 root root 12521 Sep 13 12:08 dns.log
-rw-r--r-- 1 root root 396 Sep 13 12:08 dpd.log
-rw-r--r-- 1 root root 8691 Sep 13 12:05 loaded_scripts.log
-rw-r--r-- 1 root root 1101 Sep 13 12:05 notice_policy.log
-rw-r--r-- 1 root root 224 Sep 13 12:05 packet_filter.log
-rw-r--r-- 1 root root 699 Sep 13 12:08 ssl.log
-rw-r--r-- 1 root root 46 Sep 13 12:05 stderr.log
-rw-r--r-- 1 root root 30 Sep 13 12:05 stdout.log
-rw-r--r-- 1 root root 717 Sep 13 12:07 weird.log

I even see:

2013-09-13T12:05:46-0600 8GxbB0zXe0g x.x.x.x 53547 74.125.129.99 80 tcp - - - - OTH F 0 C 0 0 0 0 (empty)

2013-09-13T12:05:46-0600 HQym3XmcURj x.x.x.x 36086 205.171.2.25 53 udp 59556 www.google.com 1 C_INTERNET 1 A 0 NOERROR F F T T 0 74.125.129.99,74.125.129.104,74.125.129.105,74.125.129.147,74.125.129.103,74.125.129.106 297.000000,297.000000,297.000000,297.000000,297.000000,297.000000

loaded_scripts.log shows:

[12:10:26 gateway:~/current$] grep http loaded_scripts.log
   /usr/local/bro/share/bro/base/protocols/http/__load__.bro
     /usr/local/bro/share/bro/base/protocols/http/./main.bro
     /usr/local/bro/share/bro/base/protocols/http/./utils.bro
     /usr/local/bro/share/bro/base/protocols/http/./file-ident.bro
     /usr/local/bro/share/bro/base/protocols/http/./file-hash.bro
     /usr/local/bro/share/bro/base/protocols/http/./file-extract.bro
   /usr/local/bro/share/bro/policy/protocols/http/software.bro
   /usr/local/bro/share/bro/policy/protocols/http/detect-MHR.bro

But http.log is still not created. Anything I'm missing here or something I can do to troubleshoot on this end? This is running on ppp0. Thank you.

James

Well...it IS being created...however, certain things don't seem to be logged. Example:

[12:27:34 gateway:~$] wget www.amazon.com
--2013-09-13 12:30:59-- http://www.amazon.com/
Resolving www.amazon.com (www.amazon.com)... 72.21.194.212
Connecting to www.amazon.com (www.amazon.com)|72.21.194.212|:80... connected.
HTTP request sent, awaiting response... 200 OK
Length: unspecified [text/html]
Saving to: `index.html.1'

     [ <=> ] 233,456 271K/s in 0.8s
2013-09-13 12:31:01 (271 KB/s) - `index.html' saved [233456]

And bro shows the below:

2013-09-13T12:30:59-0600 51V4hVkz1le x.x.x.x 36471 72.21.194.212 80 tcp - - - - OTH F 0 C 0 0 0 0 (empty)
2013-09-13T12:30:59-0600 gSRjffzGzGj x.x.x.x 52571 205.171.2.25 53 udp 311 www.amazon.com 1 C_INTERNET 1 A 0 NOERROR F F T T 0 72.21.194.212 34.000000
2013-09-13T12:31:00-0600 51V4hVkz1le x.x.x.x 36471 72.21.194.212 80 active_connection_reuse - F bro

Not sure why it's telling me it's an active connection reuse instead of logging the http traffic.

James

Hi James,

Is it possible you're seeing the effects of NIC offloading features?
http://securityonion.blogspot.com/2011/10/when-is-full-packet-capture-not-full.html

Let’s enable your capture loss and see what happens:

Add the following to your local.bro; on security onion it will be located at /opt/bro/share/bro/site/

count the ACKs, tell me the # and % I am missing

@load misc/capture-loss.bro

By default capture-loss reports every 15 minutes, let’s turn it up

redef CaptureLoss::watch_interval = 1 min;

Give it a couple of minutes and see what the log says under:

/nsm/bro/logs/capture_loss.log

You will see per worker statistics written every minute.

Let us know.

Thanks,

Liam Randall

Thanks Liam...here's what I got:
#fields ts ts_delta peer gaps acks percent_lost
#types time interval string count count string
2013-09-13T13:34:59-0600 60.000084 bro 0 16 0.000%
2013-09-13T13:35:59-0600 60.000044 bro 0 0 0.000%
2013-09-13T13:36:59-0600 60.000048 bro 0 14 0.000%
2013-09-13T13:37:59-0600 60.000048 bro 1 1 100.000%
2013-09-13T13:38:59-0600 60.000038 bro 0 0 0.000%
2013-09-13T13:39:59-0600 60.000050 bro 0 0 0.000%
2013-09-13T13:40:59-0600 60.000093 bro 0 0 0.000%
2013-09-13T13:41:59-0600 60.000023 bro 0 0 0.000%
2013-09-13T13:42:59-0600 60.000022 bro 0 0 0.000%
2013-09-13T13:43:59-0600 60.000023 bro 0 0 0.000%
2013-09-13T13:44:59-0600 60.000089 bro 0 0 0.000%
2013-09-13T13:45:59-0600 60.000073 bro 0 0 0.000%
2013-09-13T13:46:59-0600 60.000011 bro 0 0 0.000%

Bro entries:
2013-09-13T13:45:33-0600 dPCMEyJBiU7 x.x.x.x 47285 50.18.192.250 80 tcp - - - - OTH - 0 C 0 0 0 0 (empty)
2013-09-13T13:45:33-0600 PFUbImVSSZ2 x.x.x.x 35306 205.171.2.25 53 udp 63725 www.duckduckgo.com 1 C_INTERNET 1 A 0 NOERROR F F T T 0 duckduckgo.com,50.18.192.250,50.18.192.251 900.000000,25.000000,25.000000
2013-09-13T13:45:34-0600 8ZduhgTSjm6 x.x.x.x 37025 205.171.2.25 53 udp 35309 duckduckgo.com 1 C_INTERNET 1 A 0 NOERROR F F T T 0 50.18.192.251,50.18.192.250 24.000000,24.000000
2013-09-13T13:45:34-0600 dPCMEyJBiU7 x.x.x.x 47285 50.18.192.250 80 active_connection_reuse - F bro

Wget info:
[13:45:20 gateway:~$] wget www.duckduckgo.com
--2013-09-13 13:45:33-- http://www.duckduckgo.com/
Resolving www.duckduckgo.com (www.duckduckgo.com)... 50.18.192.250, 50.18.192.251
Connecting to www.duckduckgo.com (www.duckduckgo.com)|50.18.192.250|:80... connected.
HTTP request sent, awaiting response... 301 Moved Permanently
Location: https://duckduckgo.com/ [following]
--2013-09-13 13:45:34-- https://duckduckgo.com/
Resolving duckduckgo.com (duckduckgo.com)... 50.18.192.251, 50.18.192.250
Connecting to duckduckgo.com (duckduckgo.com)|50.18.192.251|:443... connected.
HTTP request sent, awaiting response... 200 OK
Length: 8646 (8.4K) [text/html]
Saving to: `index.html'

100%[=========================>] 8,646 --.-K/s in 0s

2013-09-13 13:45:34 (86.8 MB/s) - `index.html' saved [8646/8646]

Tshark info:
2013-09-13 13:45:33.991079 x.x.x.x -> 50.18.192.250 TCP 76 47285 > 80 [SYN] Seq=0 Win=14520 Len=0 MSS=1452 SACK_PERM=1 TSval=147157135 TSecr=0 WS=16
2013-09-13 13:45:34.035256 50.18.192.250 -> x.x.x.x TCP 76 80 > 47285 [SYN, ACK] Seq=0 Ack=1 Win=7240 Len=0 MSS=1460 SACK_PERM=1 TSval=23107600 TSecr=147157135 WS=1
2013-09-13 13:45:34.035375 x.x.x.x -> 50.18.192.250 TCP 68 47285 > 80 [ACK] Seq=1 Ack=1 Win=14528 Len=0 TSval=147157146 TSecr=23107600
2013-09-13 13:45:34.035595 x.x.x.x -> 50.18.192.250 HTTP 186 GET / HTTP/1.1
2013-09-13 13:45:34.082121 50.18.192.250 -> x.x.x.x TCP 68 80 > 47285 [ACK] Seq=1 Ack=119 Win=7122 Len=0 TSval=23107612 TSecr=147157146
2013-09-13 13:45:34.082132 50.18.192.250 -> x.x.x.x HTTP 503 HTTP/1.1 301 Moved Permanently (text/html)
2013-09-13 13:45:34.082241 x.x.x.x -> 50.18.192.250 TCP 68 47285 > 80 [ACK] Seq=119 Ack=436 Win=15600 Len=0 TSval=147157158 TSecr=23107612
2013-09-13 13:45:34.446981 x.x.x.x -> 50.18.192.250 TCP 68 47285 > 80 [FIN, ACK] Seq=119 Ack=436 Win=15600 Len=0 TSval=147157249 TSecr=23107612
2013-09-13 13:45:34.492112 50.18.192.250 -> x.x.x.x TCP 68 80 > 47285 [FIN, ACK] Seq=436 Ack=120 Win=7121 Len=0 TSval=23107714 TSecr=147157249
2013-09-13 13:45:34.492164 x.x.x.x -> 50.18.192.250 TCP 68 47285 > 80 [ACK] Seq=120 Ack=437 Win=15600 Len=0 TSval=147157260 TSecr=23107714

Not sure what to think...it's very strange. Thanks again.

James

How is the data getting to bro? Span port? Tap?

In line with Doug's suggestion, can you try a known good source of traffic? For example a packet trace from Bro Workshop:
The first exercise on the following page has an http.pcap file:
http://www.bro.org/bro-workshop-2011/exercises/logs/index.html

Here is the direct link:
http://www.bro.org/bro-workshop-2011/exercises/logs/http.pcap

Try running:
$ /path/to/your/bro -r http.pcap

and see what happens?

-kb

Liam,

The I have a DSL modem in dummy mode connecting direct to the machine running bro. That wget is seen running on that machine. Thank you.

James

Hi Keith,

Just ran that http.pcap…looked great in my http.log:

#fields ts uid id.orig_h id.orig_p id.resp_h id.resp_p trans_depth method host uri referrer user_agent request_body_len response_body_len status_code status_msg info_code info_msg filename tags username password proxied mime_type md5 extraction_file
#types time string addr port addr port count string string string string string count count count string count string string table[enum] string string table[string] string string file
1320279566.452687 JIDwiHjbv85 192.168.2.76 52026 132.235.215.119 80 1 GET www.reddit.com / - Mozilla/5.0 (Macintosh; Intel Mac OS X 10.6; rv:7.0.1) Gecko/20100101 Firefox/7.0.1 0 109978 200 OK - - - (empty) - - - text/html - -
1320279566.831619 VKdyryoPlil 192.168.2.76 52030 72.21.211.173 80 1 GET e.thumbs.redditmedia.com /E-pbDbmiBclPkDaX.jpg http://www.reddit.com/ Mozilla/5.0 (Macintosh; Intel Mac OS X 10.6; rv:7.0.1) Gecko/20100101 Firefox/7.0.1 0 2300 200 OK - - - (empty) - - - image/jpeg - -

Thank you.

James

I'd point out that the conn.log file lines included in his email indicate that the received and sent bytes are 0, and the connection state is borked -- I believe this would prevent it from being detected as http traffic, and therefore not create an http.log file.

-- KS

WELLL this is gonna hurt my head. So…here's my setup:

DSL modem (dummy mode) < -- > eth1/ppp0(Linuxbox)eth0 < -- > switch with everything else
        ext IP int IP

For giggles I decided to see if there was any difference with requests originating from the linuxbox, compared to originating behind it. I tsharked at ppp0, here's what I have

Curl from a Mac
2013-09-13 17:30:53.720063 x.x.x.x -> 23.63.227.171 TCP 80 51579 > 80 [SYN] Seq=0 Win=65535 Len=0 MSS=1452 WS=16 TSval=962401899 TSecr=0 SACK_PERM=1
2013-09-13 17:30:53.781038 23.63.227.171 -> x.x.x.x TCP 76 80 > 51579 [SYN, ACK] Seq=0 Ack=1 Win=14480 Len=0 MSS=1460 SACK_PERM=1 TSval=923336834 TSecr=962401899 WS=2
2013-09-13 17:30:53.781706 x.x.x.x -> 23.63.227.171 TCP 68 51579 > 80 [ACK] Seq=1 Ack=1 Win=131760 Len=0 TSval=962401960 TSecr=923336834
2013-09-13 17:30:53.781917 x.x.x.x -> 23.63.227.171 HTTP 214 GET / HTTP/1.1
2013-09-13 17:30:53.844280 23.63.227.171 -> x.x.x.x TCP 68 80 > 51579 [ACK] Seq=1 Ack=147 Win=15552 Len=0 TSval=923336896 TSecr=962401960
2013-09-13 17:30:54.058292 23.63.227.171 -> x.x.x.x TCP 1508 [TCP segment of a reassembled PDU]
2013-09-13 17:30:54.059011 23.63.227.171 -> x.x.x.x TCP 1508 [TCP segment of a reassembled PDU]
2013-09-13 17:30:54.059543 x.x.x.x -> 23.63.227.171 TCP 68 51579 > 80 [ACK] Seq=147 Ack=2881 Win=129632 Len=0 TSval=962402235 TSecr=923337110
2013-09-13 17:30:54.059571 23.63.227.171 -> x.x.x.x TCP 1508 [TCP segment of a reassembled PDU]
2013-09-13 17:30:54.060385 23.63.227.171 -> x.x.x.x TCP 1508 [TCP segment of a reassembled PDU]
2013-09-13 17:30:54.060387 23.63.227.171 -> x.x.x.x HTTP 97 HTTP/1.1 200 OK (text/html)
2013-09-13 17:30:54.060889 x.x.x.x -> 23.63.227.171 TCP 68 51579 > 80 [ACK] Seq=147 Ack=5761 Win=129632 Len=0 TSval=962402236 TSecr=923337110
2013-09-13 17:30:54.060923 x.x.x.x -> 23.63.227.171 TCP 68 51579 > 80 [ACK] Seq=147 Ack=5790 Win=131040 Len=0 TSval=962402236 TSecr=923337110
2013-09-13 17:30:54.136000 x.x.x.x -> 23.63.227.171 TCP 68 51579 > 80 [FIN, ACK] Seq=147 Ack=5790 Win=131072 Len=0 TSval=962402311 TSecr=923337110
2013-09-13 17:30:54.196402 23.614 2013-09-13 17:30:54.196402 23.614 2013-09-13 17:30:54.196402 23.614 2013-09-13 17:30:54.19=923337249 TSecr=962402311
2013-09-13 17:30:54.197075 x.x.x.x -> 23.63.227.171 TCP 68 51579 > 80 [ACK] Seq=148 Ack=5791 Win=131072 Len=0 TSval=962402371 TSecr=923337249

Wget from the linuxbox
2013-09-13 17:30:56.769223 x.x.x.x -> 207.108.220.146 TCP 76 46641 > 80 [SYN] Seq=0 Win=14520 Len=0 MSS=1452 SACK_PERM=1 TSval=150537829 TSecr=0 WS=16
2013-09-13 17:30:56.800179 207.108.220.146 -> x.x.x.x TCP 76 80 > 46641 [SYN, ACK] Seq=0 Ack=1 Win=14480 Len=0 MSS=1460 SACK_PERM=1 TSval=811267839 TSecr=150537829 WS=2
2013-09-13 17:30:56.800271 x.x.x.x -> 207.108.220.146 TCP 68 46641 > 80 [ACK] Seq=1 Ack=1 Win=14528 Len=0 TSval=150537837 TSecr=811267839
2013-09-13 17:30:56.800559 x.x.x.x -> 207.108.220.146 HTTP 183 GET / HTTP/1.1
2013-09-13 17:30:56.833172 207.108.220.146 -> x.x.x.x TCP 68 80 > 46641 [ACK] Seq=1 Ack=116 Win=14480 Len=0 TSval=811267872 TSecr=150537837
2013-09-13 17:30:56.898798 207.108.220.146 -> x.x.x.x TCP 1508 [TCP segment of a reassembled PDU]
2013-09-13 17:30:56.898890 x.x.x.x -> 207.108.220.146 TCP 68 46641 > 80 [ACK] Seq=116 Ack=1441 Win=17408 Len=0 TSval=150537862 TSecr=811267937
2013-09-13 17:30:56.899540 207.108.220.146 -> x.x.x.x TCP 1508 [TCP segment of a reassembled PDU]
2013-09-13 17:30:56.899597 x.x.x.x -> 207.108.220.146 TCP 68 46641 > 80 [ACK] Seq=116 Ack=2881 Win=20288 Len=0 TSval=150537862 TSecr=811267937
2013-09-13 17:30:56.900295 207.108.220.146 -> x.x.x.x TCP 1508 [TCP segment of a reassembled PDU]
2013-09-13 17:30:56.900355 x.x.x.x -> 207.108.220.146 TCP 68 46641 > 80 [ACK] Seq=116 Ack=4321 Win=23168 Len=0 TSval=150537862 TSecr=811267937
2013-09-13 17:30:56.901041 207.108.220.146 -> x.x.x.x TCP 1508 [TCP segment of a reassembled PDU]
2013-09-13 17:30:56.901097 x.x.x.x -> 207.108.220.146 TCP 68 46641 > 80 [ACK] Seq=116 Ack=5761 Win=26048 Len=0 TSval=150537862 TSecr=811267937
2013-09-13 17:30:56.901043 207.108.220.146 -> x.x.x.x HTTP 97 HTTP/1.1 200 OK (text/html)
2013-09-13 17:30:56.901141 x.x.x.x -> 207.108.220.146 TCP 68 46641 > 80 [ACK] Seq=116 Ack=5790 Win=26048 Len=0 TSval=150537862 TSecr=811267937
2013-09-13 17:30:56.901950 x.x.x.x -> 207.108.220.146 TCP 68 46641 > 80 [FIN, ACK] Seq=116 Ack=5790 Win=26048 Len=0 TSval=150537863 TSecr=811267937
2013-09-13 17:30:56.933443 207.108.220.146 -> x.x.x.x TCP 68 80 > 46641 [FIN, ACK] Seq=5790 Ack=117 Win=14480 Len=0 TSva2013-09-13 17:30:56.933443 207.108.220.146 -> 71.39.117.84 TCP 68 80 > 46641 [FIN, ACK] Seq=5790 Ac > 80 [ACK] Seq=117 Ack=5791 Win=26048 Len=0 TSval=150537871 TSecr=811267973

Mac
2013-09-13T17:30:53-0600 BnQTbzFqpae x.x.x.x 51579 23.63.227.171 80 tcp http 0.476339 146 5789 SF - 0 ShADadFf 8 574 8 6213 (empty)
2013-09-13T17:30:53-0600 BnQTbzFqpae x.x.x.x 51579 23.63.227.171 80 1 GET www.spamcop.net / - curl/7.24.0 (x86_64-apple-darwin12.0) libcurl/7.24.0 OpenSSL/0.9.8y zlib/1.2.5 0 5455 200 OK - - - (empty) - - - text/html - -

Linuxbox
2013-09-13T17:30:56-0600 aDSEGHvanZ1 x.x.x.x 46641 207.108.220.146 80 tcp - - - - OTH - 0 C 0 0 0 0 (empty)
2013-09-13T17:30:56-0600 aDSEGHvanZ1 x.x.x.x 46641 207.108.220.146 80 active_connection_reuse - F bro

When coming from the linuxbox, I get active_connection_reuse and no http logged. When routing(natting) internal traffic, it logs http and no active_connection_reuse. A puzzle to be sure.

James

Maybe tell Bro to ignore checksums?

http://www.bro.org/documentation/faq.html#why-isn-t-bro-producing-the-logs-i-expect-a-note-about-checksums

Option 1 would probably entail:

If you are using broctl, in your broctl.cfg file add the line (then install and restart in broctl)?
broargs = --no-checksums

Hey hey! I think that was just the ticket. Thanks so much Keith!

James

I want to chime in here quickly. Generally if you are running in BroControl it means that you are sniffing live traffic and probably in an environment where you want things to run correctly in which case you would *never* want to configure this option. If packet have bad checksums, they generally should be dropped.

  .Seth

I completely agree. In my case however, I believe it's a "feature" of PPPoE…those same packets captured on the physical eth1 NIC are flawless with zero issues. I tried having Bro listen to eth1, but I don't think it plays with the PPPoE. Thanks for the input Seth.

James

Hm, I think I have a patch around somewhere that adds PPPoE support to Bro… yep, found it.
  topic/seth/pppoe

I also went ahead and updated that branch to be only diffs against the current master branch. Let me know if you need any help if you decide to give it a try.

  .Seth

Oh sweet thanks Seth...I'll give that a go today and report my results.

James