Parsing SSH Logs - Basics

This is part two of four in a series of articles about security.

1. Text Processing Tools in UNIX
2. Parsing SSH Logs
   • Basics
   • Intermediate
3. Configuring fail2ban
4. Configuring mail (and Slack) for SSH Notifications

As a big fan of testing, I want to check whether or not adding additional security to EC2 instance is worth it or not. There is no point in adding anything if it will not be used. Hence, I started a experiment to see how much access a server on the Internet was really getting.

The test is: I am the only person accessing my EC2 instance.

In part one, I cover text processing tools in UNIX such as cat, |, grep, awk, wc, sort, uniq, and geoiplookup.

I will use these tools on an SSH log (/var/log/auth.log in Ubuntu) and found some interesting information about an openly accessible server on the Internet. This has made me rethink server security.

Openly Accessible Server

For my experiment, I configured an openly accessible server, which I define as: a server that allows a connection from any IP address.

• Host: AWS
• Operating System: Ubuntu 14.04
• Accessible port: 22 (default for SSH protocol)

The address was not attached to any DNS system (i.e. No-IP) or its address posted anywhere. The server is just a silent server on the Internet in an ocean of servers…

The SSH logs are available here. auth.log, it is also the same auth.log used in code samples in this article.

Items covered from the log in this article

• log stats
• successful logins
• login attempts

Log stats

The log started from Jan 11, 2017 and Feb 4, 2017, for a period of approximately 24 days.

Number of log entries

The number of log entries can be easily obtained using:

$ cat auth.log | wc -l

The total lines in the log: 52,357. As this is not an enormous amount of data, it is enough to be annoying to process by hand, but not enough to warrant writing (and testing!) a program, especially when there are excellent tools in UNIX.

The number of log entries generated from cron (a UNIX utility which performs commands a scheduled intervals):

$ cat auth.log | grep CRON | wc -l

cron generated 1,676 entries.

A sample:

Feb  4 13:17:01 ip-172-31-1-163 CRON[5469]: pam_unix(cron:session): session opened for user root by (uid=0)
Feb  4 13:17:01 ip-172-31-1-163 CRON[5469]: pam_unix(cron:session): session closed for user root
Feb  4 13:20:02 ip-172-31-1-163 CRON[5472]: pam_unix(cron:session): session opened for user smmsp by (uid=0)
Feb  4 13:20:02 ip-172-31-1-163 CRON[5472]: pam_unix(cron:session): session closed for user smmsp

The number of log entries generated by the ssh daemon (the main point of access to this server):

$ cat auth.log | grep sshd | wc -l

sshd generated 50,569 entries.

A sample:

Jan 11 01:54:31 ip-172-31-1-163 sshd[1106]: Server listening on 0.0.0.0 port 22.
Jan 11 01:54:31 ip-172-31-1-163 sshd[1106]: Server listening on :: port 22.
Jan 11 01:55:59 ip-172-31-1-163 sshd[1301]: Connection closed by 127.213.25.139 [preauth]
Jan 11 01:56:37 ip-172-31-1-163 sshd[1303]: Accepted publickey for ubuntu from 127.213.25.139 port 65087 ssh2: RSA 0a:78:92:3c:c8:27:13:d3:f7:ee:d5:ac:75:45:31:5c
Jan 11 01:56:37 ip-172-31-1-163 sshd[1303]: pam_unix(sshd:session): session opened for user ubuntu by (uid=0)

Number of log entries generated by sudo:

% cat auth.log | grep sudo | wc -l

sudo generated 98 entries, for every sudo action I performed while logged in.

A sample:

Feb  1 13:39:42 ip-172-31-1-163 sudo: pam_unix(sudo:session): session opened for user root by (uid=0)
Feb  1 13:39:42 ip-172-31-1-163 sudo: pam_unix(sudo:session): session closed for user root
Feb  1 13:40:19 ip-172-31-1-163 sudo:   ubuntu : TTY=pts/4 ; PWD=/home/ubuntu ; USER=root ; COMMAND=/bin/cat /var/log/auth.log
Feb  1 13:40:19 ip-172-31-1-163 sudo: pam_unix(sudo:session): session opened for user root by (uid=0)
Feb  1 13:40:19 ip-172-31-1-163 sudo: pam_unix(sudo:session): session closed for user root
Feb  1 13:40:35 ip-172-31-1-163 sudo:   ubuntu : TTY=pts/4 ; PWD=/home/ubuntu ; USER=root ; COMMAND=/bin/cat /var/log/auth.log

So, each time a normal user logged in, there was 98 sudo actions performed. This is interesting to see sudo actions are logged in ssh’s logs.

Logins

The next section there are some stats about logging in. This is important to understand how successful logins are recorded will help when understanding login attempts from others.

The number of successful logins:

$ cat auth.log | grep sshd | grep 'session opened' | wc -l

The server only had seven successful logins over 24 days. They are all from me as I did not create any other users for the system.

A sample:

Jan 11 01:56:37 ip-172-31-1-163 sshd[1303]: pam_unix(sshd:session): session opened for user ubuntu by (uid=0)
Jan 11 01:58:12 ip-172-31-1-163 sudo:   ubuntu : TTY=pts/0 ; PWD=/var/log ; USER=root ; COMMAND=/usr/bin/apt-get update
Jan 11 01:58:12 ip-172-31-1-163 sudo: pam_unix(sudo:session): session opened for user root by ubuntu(uid=0)
Jan 11 01:58:18 ip-172-31-1-163 sudo: pam_unix(sudo:session): session closed for user root

note: cron also opens a session for root to perform scheduled actions.

The number of different IP addresses which had successful logins:

$ cat auth.log | grep -oE '.*Accepted publickey.*' | awk '{ print $11 }' | sort | uniq

Port Scanners

Port scanning is a common method to check what system services are running by checking if a port is open. It can be used by system owners to check their server, or by attackers to find vulnerabilities.

Port scanners usually connect to a port and immediately disconnect. This connection type is recorded in the log as: ‘Received disconnect’, like so:

Jan 11 08:34:21 ip-172-31-1-163 sshd[2245]: Received disconnect from 221.194.44.195: 11:  [preauth]
Jan 11 08:34:21 ip-172-31-1-163 sshd[2243]: Received disconnect from 221.194.47.229: 11:  [preauth]
Jan 11 08:34:38 ip-172-31-1-163 sshd[2247]: Received disconnect from 221.194.47.229: 11:  [preauth]
Jan 11 08:35:52 ip-172-31-1-163 sshd[2249]: Received disconnect from 221.194.44.219: 11:  [preauth]
Jan 11 08:37:49 ip-172-31-1-163 sshd[2264]: Received disconnect from 121.18.238.104: 11:  [preauth]

The number of port scanning attempts detected:

$ cat auth.log | grep -oE 'Received disconnect.*' | wc -l

A total of 14,578 scans were performed in a period of 24 days. To put that in perspective, the system had 25 scans per hour (14,578 scans/(24 days * 24 hours/day)).

The number of individual IPs that did port scanning:

$ cat auth.log | grep -oE 'Received disconnect.*' | awk '{ print $4 }' | sort | uniq | wc -l

From this point, I will use ‘attacker’ as any IP address trying to access the server that were not successful.

A total of 156 different attackers performed port scanning on the server in 24 days, which means each attacker did approximately 93 scans each (14,578 scans/156 attackers).

The number of port scans done by each attacker:

$ cat auth.log | grep -oE 'Received disconnect.*' | awk '{ print $4 }' | sort | uniq -c | sort -n

The top 5 port scanning attacker:

It’s not that each attacker did 93 port scans each, it seems very few attackers performed a LOT of port scans. The top two attackers accounted for about 33% of the total port scans done.

Login Attempts

The number of login attempts made:

$ cat auth.log | grep 'Invalid user' | wc -l

11,657 login attempts were made in a period of 24 days, which is about 20 attempts per hour (11,657 attempts / (24 days * 24 hours per day)).

The number of different usernames used in login attempts;

$ cat auth.log | grep -oE 'Invalid user.*' | awk '{ print $3 }' | sort | uniq | wc -l

A total of 1,692 different usernames were used for attempted logins.

The most frequently used login name:

$ cat auth.log | grep -oE 'Invalid user.*' | awk '{ print $3 }' | sort | uniq -c | sort -n

These all seem like standard server user name for various services (i.e. postgres => postgresql database) while the most interesting is: ubnt. The standard login name for an Ubuntu system is ubuntu. I really wonder why there were so many attempts with ubnt…?

Interestingly, the number of times ubuntu was used as a username for an attempted login:

$ cat auth.log | grep -oE 'Invalid user.*ubuntu.*' | wc -l

Zero. I think the detected operating system may have thrown off a lot of attackers, as the online scanner detected the operating system to not be Ubuntu:

Device type: WAP|media device|specialized|general purpose|webcam|PBX
Running (JUST GUESSING): Netgear embedded (93%), Western Digital embedded (93%), Crestron 2-Series (92%), Linux 2.6.X|3.X|2.4.X (89%), AXIS Linux 2.6.X (88%), Vodavi embedded (87%)
OS CPE: cpe:/o:crestron:2_series cpe:/o:linux:kernel:2.6 cpe:/o:linux:kernel:3 cpe:/o:axis:linux:2.6 cpe:/o:linux:kernel:2.4.26

The scan was definitely right the operating system was Linux.

Conclusion

Test result: I am not the only one accessing my EC2 instance.

There have been an overwhelming amount of accesss found in ssh log. SSH login with PGP keys are very secure, but it’s unweildly to know how many attackers are even trying to access the server.

Next time, I will parse the log to find how many times SSH defended itself and physically find where the majority of attacks are coming from using geoiplookup.