Correlating Kerberos Authentication Across the Wire and on the Systems

by J. Edward Durrett

It is possible to use, and even to some extent administer, networks with only a cursory knowledge of what is actually going on
in the background. However, in order to manage and monitor complex networks a thorough understanding of all the processes is
required. Without knowing what things are supposed to look like it is impossible to know when they are not right or how to fix
them when they stop working. In this article, I plan to explore Kerberos authentication and the various events that happen on
the network or are written to system logs. The first section is an examination the process of Kerberos authentication on the
packet level. Then, armed with information gathered from an examination of network traffic, we will bore down into the various
systems to investigates the traces of Kerberos authentication in various logs. Finally, we will look at organized data derived
by Bro IDS from the network traffic of the authentication process.

This document assumes the reader has a basic understanding of Kerberos, DNS, and SSH. To replicate this in a test an
environment, a good working knowledge of standard network protocols, system tools, logging, *NIX commands and intrusion
detection is required.

The test network used in this example is made up of a DNS machine, a KDC, a ssh client and a ssh server configured to allow
Kerberos login through GSSAPI Authentication. The complete configuration of such an environment is beyond the scope of this
article.

Below is a detailed explanation with output from tcpdump of what is going in. I had tcpdump resolve the names of the hosts so
it is easier to follow. The explanation is long and tedious, but essential knowledge.

First, the client asks the DNS for the SRV record containing the host and port of the KDC for the realm:

 
17:46:39.270309 IP ssh-client.testing.mi.example.com.21537 > ns1.dns.mi.example.com.domain: 37544+ SRV?
_kerberos._udp.TESTING.MI.EXAMPLE.COM. (56)


The DNS server answers with the host name and the port:

 
17:46:39.293231 IP ns1.dns.mi.example.com.domain > ssh-client.testing.mi.example.com.21537: 37544* 1/1/2 SRV
kerberos.testing.mi.example.com.:88 1 0 (200)


Now, the client asks the DNS for the numeric address for the KDC:

 
17:46:39.321630 IP ssh-client.testing.mi.example.com.56226 > ns1.dns.mi.example.com.domain: 1013+ A?
kerberos.testing.mi.example.com. (50)


The DNS responds with the A record:

 
17:46:39.322314 IP ns1.dns.mi.example.com.domain > ssh-client.testing.mi.example.com.56226: 1013* 1/1/1 A 192.168.40.10 (104)


The client then asks the DNS if there is an ipv6 address:

 
17:46:39.322802 IP ssh-client.testing.mi.example.com.33722 > ns1.dns.mi.example.com.domain: 33314+ AAAA?
kerberos.testing.mi.example.com. (50)


Since we are not using ipv6 here, the DNS responds with a no name answer:

 
17:46:39.323437 IP ns1.dns.mi.example.com.domain > ssh-client.testing.mi.example.com.33722: 33314* 0/1/0 (98)


Now, the client is ready to authenticate to the KDC and ask for an authentication ticket:

 
17:46:39.323757 IP ssh-client.testing.mi.example.com.59705 > kerberos.testing.mi.example.com.kerberos-sec: v5


The KDC sends the ticket to the client:

 
17:46:39.384913 IP kerberos.testing.mi.example.com.kerberos-sec > ssh-client.testing.mi.example.com.59705:


The above transaction might be repeated if the client does not send the correct initial pre auth. It will start over at the
very beginning with the client asking for the name of the KDC. I excluded an example of this here as when just recording the
hosts and direction of traffic, the repeated process looks exactly the same. A full packet dump will show a difference, namely
that the initial request for a ticket is rejected by the KDC with an error message.

Also, this is only an initial ticket. When the client attempts to contact host, it will ask for a ticket for that host. The
KDC server will issue one with a start time and an end time. That ticket can then be used again and again until the end time
without contacting the KDC. Since the traffic is similar to the above transactions, I have admitted that second request. The
traffic that follows is assuming that the client has already gotten the ticket earlier in the day.

Now, the client is ready to log into the SSH server. Note, at this point the KDC is no longer involved. As you will see on the
time stamps, I waited a bit before collecting traffic while using the ticket from KDC to authenticate to the ssh server. In
the case where the ticket has been authenticated but not used, the client will contact the KDC again. The example below is
using a ticket during the period between the start time and end time.

First the client needs to know where the SSH server is, asking the DNS for the address:

 
21:09:54.598890 IP ssh-client.testing.mi.example.com.60865 > ns1.dns.mi.example.com.domain: 30108+ A?
ssh-server.testing.mi.example.com. (52)


The DNS returns with the A record:

 
21:09:54.670856 IP ns1.dns.mi.example.com.domain > ssh-client.testing.mi.example.com.60865: 30108* 1/1/1 A 192.168.40.20 (106)


The client also checks the DNS for an AAAA record:

 
21:09:54.671289 IP ssh-client.testing.mi.example.com.44421 > ns1.dns.mi.example.com.domain: 51280+ AAAA?
ssh-server.testing.mi.example.com. (52)


Since we are still not using ipv6, the DNS returns no name:

 
21:09:54.672113 IP ns1.dns.mi.example.com.domain > ssh-client.testing.mi.example.com.44421: 51280* 0/1/0 (100)


Now the client is ready to start talking to the server and negotiating a connection (for a good overview of what ssh is doing
here, connect to a host with -v or -vv):

 
21:09:54.674102 IP ssh-client.testing.mi.example.com.16267 > ssh-server.testing.mi.example.com.ssh: Flags [S], seq 3809351958,
win 65535, options [mss 16344,nop,wscale 6,sackOK,TS val 4243463194 ecr 0], length 0
21:09:54.674172 IP ssh-server.testing.mi.example.com.ssh > ssh-client.testing.mi.example.com.16267: Flags [S.], seq
3651601198, ack 3809351959, win 65535, options [mss 16344,nop,wscale 6,sackOK,TS val 1706848421 ecr 4243463194], length 0
21:09:54.674260 IP ssh-client.testing.mi.example.com.16267 > ssh-server.testing.mi.example.com.ssh: Flags [.], ack 1, win
1276, options [nop,nop,TS val 4243463194 ecr 1706848421], length 0
21:09:54.744313 IP ssh-client.testing.mi.example.com.16267 > ssh-server.testing.mi.example.com.ssh: Flags [P.], seq 1:39, ack
1, win 1276, options [nop,nop,TS val 4243463264 ecr 1706848421], length 38
21:09:54.844102 IP ssh-server.testing.mi.example.com.ssh > ssh-client.testing.mi.example.com.16267: Flags [.], ack 39, win
1276, options [nop,nop,TS val 1706848591 ecr 4243463264], length 0
21:09:55.004680 IP ssh-server.testing.mi.example.com.ssh > ssh-client.testing.mi.example.com.16267: Flags [P.], seq 1:39, ack
39, win 1276, options [nop,nop,TS val 1706848751 ecr 4243463264], length 38
21:09:55.031813 IP ssh-client.testing.mi.example.com.16267 > ssh-server.testing.mi.example.com.ssh: Flags [P.], seq 39:1375,
ack 39, win 1276, options [nop,nop,TS val 4243463551 ecr 1706848751], length 1336
21:09:55.037609 IP ssh-server.testing.mi.example.com.ssh > ssh-client.testing.mi.example.com.16267: Flags [P.], seq 39:1079,
ack 1375, win 1256, options [nop,nop,TS val 1706848784 ecr 4243463551], length 1040
21:09:55.060515 IP ssh-client.testing.mi.example.com.16267 > ssh-server.testing.mi.example.com.ssh: Flags [P.], seq 1375:1423,
ack 1079, win 1276, options [nop,nop,TS val 4243463580 ecr 1706848784], length 48
21:09:55.113685 IP ssh-server.testing.mi.example.com.ssh > ssh-client.testing.mi.example.com.16267: Flags [P.], seq 1079:1443,
ack 1423, win 1276, options [nop,nop,TS val 1706848860 ecr 4243463580], length 364


The client then checks the DNS for a host key of the ssh server in an SSHFP record:

 
21:09:55.130640 IP ssh-client.testing.mi.example.com.16566 > ns1.dns.mi.example.com.domain: 30081+ [1au] SSHFP?
ssh-server.testing.mi.example.com. (63)


This host does not have a host key published in the DNS so the DNS returns a no name response:

 
21:09:55.131438 IP ns1.dns.mi.example.com.domain > ssh-client.testing.mi.example.com.16566: 30081* 0/1/1 (111)


The client and server continue negotiating:

 
21:09:55.171761 IP ssh-client.testing.mi.example.com.16267 > ssh-server.testing.mi.example.com.ssh: Flags [P.], seq 1423:1439,
ack 1443, win 1276, options [nop,nop,TS val 4243463691 ecr 1706848860], length 16
21:09:55.271097 IP ssh-server.testing.mi.example.com.ssh > ssh-client.testing.mi.example.com.16267: Flags [.], ack 1439, win
1276, options [nop,nop,TS val 1706849018 ecr 4243463691], length 0
21:09:55.271163 IP ssh-client.testing.mi.example.com.16267 > ssh-server.testing.mi.example.com.ssh: Flags [P.], seq 1439:1483,
ack 1443, win 1276, options [nop,nop,TS val 4243463791 ecr 1706849018], length 44
21:09:55.271452 IP ssh-server.testing.mi.example.com.ssh > ssh-client.testing.mi.example.com.16267: Flags [P.], seq 1443:1487,
ack 1483, win 1276, options [nop,nop,TS val 1706849018 ecr 4243463791], length 44
21:09:55.271814 IP ssh-client.testing.mi.example.com.16267 > ssh-server.testing.mi.example.com.ssh: Flags [P.], seq 1483:1543,
ack 1487, win 1276, options [nop,nop,TS val 4243463791 ecr 1706849018], length 60
21:09:55.371109 IP ssh-server.testing.mi.example.com.ssh > ssh-client.testing.mi.example.com.16267: Flags [.], ack 1543, win
1276, options [nop,nop,TS val 1706849118 ecr 4243463791], length 0


The server then checks the reverse address, PTR, of the client:

 
21:09:55.382763 IP ssh-server.testing.mi.example.com.23809 > ns1.dns.mi.example.com.domain: 57854+ PTR?
30.40.168.192.in-addr.arpa. (44)


The DNS responds with the FQDN of the client:

 
21:09:55.383620 IP ns1.dns.mi.example.com.domain > ssh-server.testing.mi.example.com.23809: 57854* 1/1/1 PTR
ssh-client.testing.mi.example.com. (130)


Now the server checks the FQDN of the client:

 
21:09:55.387676 IP ssh-server.testing.mi.example.com.63727 > ns1.dns.mi.example.com.domain: 13340+ A?
ssh-client.testing.mi.example.com. (52)


The DNS responds with the A record requested:

 
21:09:55.388435 IP ns1.dns.mi.example.com.domain > ssh-server.testing.mi.example.com.63727: 13340* 1/1/1 A 192.168.40.30 (106)



The client and server continue the negotiation:

 
21:09:55.438889 IP ssh-server.testing.mi.example.com.ssh > ssh-client.testing.mi.example.com.16267: Flags [P.], seq 1487:1571,
ack 1543, win 1276, options [nop,nop,TS val 1706849185 ecr 4243463791], length 84
21:09:55.538108 IP ssh-client.testing.mi.example.com.16267 > ssh-server.testing.mi.example.com.ssh: Flags [.], ack 1571, win
1276, options [nop,nop,TS val 4243464058 ecr 1706849185], length 0
21:09:55.557509 IP ssh-client.testing.mi.example.com.16267 > ssh-server.testing.mi.example.com.ssh: Flags [P.], seq 1543:1635,
ack 1571, win 1276, options [nop,nop,TS val 4243464077 ecr 1706849185], length 92
21:09:55.558266 IP ssh-server.testing.mi.example.com.ssh > ssh-client.testing.mi.example.com.16267: Flags [P.], seq 1571:1615,
ack 1635, win 1276, options [nop,nop,TS val 1706849305 ecr 4243464077], length 44
21:09:55.566417 IP ssh-client.testing.mi.example.com.16267 > ssh-server.testing.mi.example.com.ssh: Flags [P.], seq 1635:2375,
ack 1615, win 1276, options [nop,nop,TS val 4243464086 ecr 1706849305], length 740
21:09:55.617788 IP ssh-server.testing.mi.example.com.ssh > ssh-client.testing.mi.example.com.16267: Flags [P.], seq 1615:1803,
ack 2375, win 1276, options [nop,nop,TS val 1706849364 ecr 4243464086], length 188
21:09:55.618565 IP ssh-client.testing.mi.example.com.16267 > ssh-server.testing.mi.example.com.ssh: Flags [P.], seq 2375:2435,
ack 1803, win 1276, options [nop,nop,TS val 4243464138 ecr 1706849364], length 60
21:09:55.718099 IP ssh-server.testing.mi.example.com.ssh > ssh-client.testing.mi.example.com.16267: Flags [.], ack 2435, win
1276, options [nop,nop,TS val 1706849465 ecr 4243464138], length 0


The ssh server performs an additional DNS lookup:

 
21:09:55.885207 IP ssh-server.testing.mi.example.com.60873 > ns1.dns.mi.example.com.domain: 16826+ A?
ssh-client.testing.mi.example.com. (52)


The DNS responds with an A record:

 
21:09:55.885929 IP ns1.dns.mi.example.com.domain > ssh-server.testing.mi.example.com.60873: 16826* 1/1/1 A 192.168.40.30 (106)


The ssh server checks for an AAAA record:

 
21:09:55.886315 IP ssh-server.testing.mi.example.com.51131 > ns1.dns.mi.example.com.domain: 31499+ AAAA?
ssh-client.testing.mi.example.com. (52)


Since this is still not an ipv6 network, the DNS responds with no name:

 
21:09:55.887634 IP ns1.dns.mi.example.com.domain > ssh-server.testing.mi.example.com.51131: 31499* 0/1/0 (100)


The client and server continue negotiation:

 
21:09:55.888805 IP ssh-server.testing.mi.example.com.ssh > ssh-client.testing.mi.example.com.16267: Flags [P.], seq 1803:1831,
ack 2435, win 1276, options [nop,nop,TS val 1706849635 ecr 4243464138], length 28
21:09:55.890153 IP ssh-client.testing.mi.example.com.16267 > ssh-server.testing.mi.example.com.ssh: Flags [P.], seq 2435:2547,
ack 1831, win 1276, options [nop,nop,TS val 4243464410 ecr 1706849635], length 112
21:09:55.897821 IP ssh-server.testing.mi.example.com.ssh > ssh-client.testing.mi.example.com.16267: Flags [P.], seq 1831:2331,
ack 2547, win 1276, options [nop,nop,TS val 1706849644 ecr 4243464410], length 500
21:09:55.997104 IP ssh-client.testing.mi.example.com.16267 > ssh-server.testing.mi.example.com.ssh: Flags [.], ack 2331, win
1276, options [nop,nop,TS val 4243464517 ecr 1706849644], length 0
21:09:55.997174 IP ssh-server.testing.mi.example.com.ssh > ssh-client.testing.mi.example.com.16267: Flags [P.], seq 2331:2375,
ack 2547, win 1276, options [nop,nop,TS val 1706849744 ecr 4243464517], length 44
21:09:55.997635 IP ssh-client.testing.mi.example.com.16267 > ssh-server.testing.mi.example.com.ssh: Flags [P.], seq 2547:2915,
ack 2375, win 1276, options [nop,nop,TS val 4243464517 ecr 1706849744], length 368
21:09:56.001741 IP ssh-server.testing.mi.example.com.ssh > ssh-client.testing.mi.example.com.16267: Flags [P.], seq 2375:2483,
ack 2915, win 1276, options [nop,nop,TS val 1706849748 ecr 4243464517], length 108
21:09:56.101053 IP ssh-client.testing.mi.example.com.16267 > ssh-server.testing.mi.example.com.ssh: Flags [.], ack 2483, win
1276, options [nop,nop,TS val 4243464621 ecr 1706849748], length 0
21:09:56.119925 IP ssh-server.testing.mi.example.com.ssh > ssh-client.testing.mi.example.com.16267: Flags [P.], seq 2483:2599,
ack 2915, win 1276, options [nop,nop,TS val 1706849866 ecr 4243464621], length 116
21:09:56.143688 IP ssh-server.testing.mi.example.com.ssh > ssh-client.testing.mi.example.com.16267: Flags [P.], seq 2599:2907,
ack 2915, win 1276, options [nop,nop,TS val 1706849890 ecr 4243464621], length 308
21:09:56.143774 IP ssh-client.testing.mi.example.com.16267 > ssh-server.testing.mi.example.com.ssh: Flags [.], ack 2907, win
1272, options [nop,nop,TS val 4243464663 ecr 1706849866], length 0
21:09:56.144594 IP ssh-server.testing.mi.example.com.ssh > ssh-client.testing.mi.example.com.16267: Flags [P.], seq 2907:3631,
ack 2915, win 1276, options [nop,nop,TS val 1706849891 ecr 4243464663], length 724
21:09:56.244042 IP ssh-client.testing.mi.example.com.16267 > ssh-server.testing.mi.example.com.ssh: Flags [.], ack 3631, win
1276, options [nop,nop,TS val 4243464764 ecr 1706849891], length 0


The server requests, again, the A record for the client:

 
21:09:56.324328 IP ssh-server.testing.mi.example.com.52846 > ns1.dns.mi.example.com.domain: 38600+ A?
ssh-client.testing.mi.example.com. (52)


The DNS responds with the numeric address:

 
21:09:56.325148 IP ns1.dns.mi.example.com.domain > ssh-server.testing.mi.example.com.52846: 38600* 1/1/1 A 192.168.40.30 (106)


The server asks for an AAAA record from the DNS:

 
21:09:56.325687 IP ssh-server.testing.mi.example.com.34475 > ns1.dns.mi.example.com.domain: 49577+ AAAA?
ssh-client.testing.mi.example.com. (52)


The DNS responds with no name because this still isn’t an ipv6 network:

 
21:09:56.326456 IP ns1.dns.mi.example.com.domain > ssh-server.testing.mi.example.com.34475: 49577* 0/1/0 (100)



The ssh authentication completes and ssh traffic goes between the client and host.

 
21:09:56.719177 IP ssh-server.testing.mi.example.com.ssh > ssh-client.testing.mi.example.com.16267: Flags [P.], seq 3631:3691,
ack 2915, win 1276, options [nop,nop,TS val 1706850466 ecr 4243464764], length 60
21:09:56.819104 IP ssh-client.testing.mi.example.com.16267 > ssh-server.testing.mi.example.com.ssh: Flags [.], ack 3691, win
1276, options [nop,nop,TS val 4243465339 ecr 1706850466], length 0


DNS Logs

All of the network activity should have left some traces on the systems. First, lets check the DNS query log. Assuming NTP is
set up and and the network has very low latency, we can just grab the relevant records by the timestamp taken at from tcpdump
above.

 
$cat bind.log.0 | grep -A2 "17:46:39.270"


Sure enough, when the client first authenticates to the KDC, there are three DNS lookups, a SRV to know who the KDC is, an A
for where the KDC is, and an AAAA to see if the KDC has an ipv6 address:

 
15-Oct-2017 17:46:39.270 queries: info: client @0x28f4f600 192.168.40.30#21537 (_kerberos._udp.TESTING.MI.EXAMPLE.COM): query:
_kerberos._udp.TESTING.MI.EXAMPLE.COM IN SRV + (192.168.11.1)
15-Oct-2017 17:46:39.321 queries: info: client @0x28f4f600 192.168.40.30#56226 (kerberos.testing.mi.example.com): query:
kerberos.testing.mi.example.com IN A + (192.168.11.1)
15-Oct-2017 17:46:39.323 queries: info: client @0x28f4f600 192.168.40.30#33722 (kerberos.testing.mi.example.com): query:
kerberos.testing.mi.example.com IN AAAA + (192.168.11.1)


Remember that in the above traffic sample, authentication of the client to the SSH server happened at a later time. Again, we
can query by the timestamp. This time, though, there is an extra filter to ensure that we are getting just the DNS query
traffic on the test network:

 
$cat bind.log | grep -A7 "21:09:54." | grep "192.168.40"

15-Oct-2017 21:09:54.600 queries: info: client @0x28f4d300 192.168.40.30#60865 (ssh-server.testing.mi.example.com): query:
ssh-server.testing.mi.example.com IN A + (192.168.11.1)
15-Oct-2017 21:09:54.671 queries: info: client @0x28f4d300 192.168.40.30#44421 (ssh-server.testing.mi.example.com): query:
ssh-server.testing.mi.example.com IN AAAA + (192.168.11.1)
15-Oct-2017 21:09:55.130 queries: info: client @0x28f4d300 192.168.40.30#16566 (ssh-server.testing.mi.example.com): query:
ssh-server.testing.mi.example.com IN SSHFP +E(0)D (192.168.11.1)
15-Oct-2017 21:09:55.383 queries: info: client @0x28f4d300 192.168.40.20#23809 (30.40.168.192.in-addr.arpa): query:
30.40.168.192.in-addr.arpa IN PTR + (192.168.11.1)
15-Oct-2017 21:09:55.387 queries: info: client @0x28f4d300 192.168.40.20#63727 (ssh-client.testing.mi.example.com): query:
ssh-client.testing.mi.example.com IN A + (192.168.11.1)
15-Oct-2017 21:09:55.885 queries: info: client @0x28f4d300 192.168.40.20#60873 (ssh-client.testing.mi.example.com): query:
ssh-client.testing.mi.example.com IN A + (192.168.11.1)
15-Oct-2017 21:09:55.887 queries: info: client @0x28f4d300 192.168.40.20#51131 (ssh-client.testing.mi.example.com): query:
ssh-client.testing.mi.example.com IN AAAA + (192.168.11.1)


We can see all the DNS lookups described in the dissection of the network traffic. Tho filter it down to just the lookup
types, a bit of awk is useful:

 
$cat bind.log| grep -A7 "21:09:54." | grep "192.168.40" | awk '{print$12}'

A
AAAA
SSHFP
PTR
A
A
AAAA
A
AAAA


The above pattern is what is logged when a client authenticates using a pre-obtained ticket to an SSH server. Now, if the
client had not already gotten a ticket for the host it is trying to connect to, then there would also be a SRV, A, AAAA
pattern as described in the previous section.

Auth Logs

Another place to look to find information which correlates to the packet capture provided by tcpdump is in the auth.log on the
SSH server.

 
cat /var/log/auth.log |grep "21:09"

Oct 15 21:09:55 ssh-server sshd[77668]: Authorized to root, krb5 principal durrett@TESTING.MI.EXAMPLE.COM (krb5_kuserok)
Oct 15 21:09:55 ssh-server sshd[77668]: Accepted gssapi-with-mic for root from 192.168.40.30 port 16267 ssh2


Here there is a bit more information than what we could see in the tcpdump or the DNS query log. Namely, the user durrett was
able to log into the host using Kerberos mapped to root! Surely, that must be against policy. When logs are centralized, the
searching for the pattern “ Authorized to root, krb5 principal” can indicate when administrators have decided that
they should do something as insanely silly as this. With a lax sudo policy, it is quite easy to perform privilege escalation
by modifying the sshd_config file to allow root login which, when using Kerberos, will not check the local root password
before granting a shell.

KRB Logs

A third place to look for correlation of the network traffic is on the KDC itself. First, lets grab the records for the
initial authentication. First the client sends an authentication service request:

 
2017-10-15T17:46:39 AS-REQ durrett@TESTING.MI.EXAMPLE.COM from IPv4:192.168.40.30 for
krbtgt/TESTING.MI.EXAMPLE.COM@TESTING.MI.EXAMPLE.COM
2017-10-15T17:46:39 Client sent patypes: encrypted-timestamp


Then KDC performs authentication and creates a authentication ticket (notice the unset starttime):

 
2017-10-15T17:46:39 Looking for PKINIT pa-data -- durrett@TESTING.MI.EXAMPLE.COM
2017-10-15T17:46:39 Looking for ENC-TS pa-data -- durrett@TESTING.MI.EXAMPLE.COM
2017-10-15T17:46:39 ENC-TS Pre-authentication succeeded -- durrett@TESTING.MI.EXAMPLE.COM using aes256-cts-hmac-sha1-96
2017-10-15T17:46:39 AS-REQ authtime: 2017-10-15T17:46:39 starttime: unset endtime: 2017-10-16T03:46:39 renew till: unset
2017-10-15T17:46:39 Client supported enctypes: aes256-cts-hmac-sha1-96, aes128-cts-hmac-sha1-96, des3-cbc-sha1, des3-cbc-md5,
arcfour-hmac-md5, using aes256-cts-hmac-sha1-96/aes256-cts-hmac-sha1-96
2017-10-15T17:46:39 Requested flags: forwardable

And finally, the KDC send the authentication ticket back to the client:
 
2017-10-15T17:46:39 sending 735 bytes to IPv4:192.168.40.30


Before the client can log into the SSH server, it must get a ticket for the host. As I mentioned earlier, I skipped the
description of that network traffic in the discussion above as the pattern is the same as the initial request. However, here
is the log portion for the ticket granting service:

 
2017-10-15T20:55:48 TGS-REQ durrett@TESTING.MI.EXAMPLE.COM from IPv4:192.168.40.30 for
host/ssh-server.testing.mi.example.com@TESTING.MI.EXAMPLE.COM [canonicalize]
2017-10-15T20:55:48 TGS-REQ authtime: 2017-10-15T19:01:27 starttime: 2017-10-15T20:55:48 endtime: 2017-10-16T05:01:26 renew
till: unset
2017-10-15T20:55:48 sending 746 bytes to IPv4:192.168.40.30


The client asks for a ticket to the SSH server. The ticket is created and sent to the client. Notice the authtime on the
ticket is the the time of when the authentication ticket was generated and the starttime is the time when the ticket for this
host ssh-server was generated. The astute reader will notice something here. The authime is 19:01:27 but we pulled from the
Kerberos log an authentication service request at 17:46 because that matched our network traffic. This means that there must
have been another request after our traffic segment, and sure enough, the log reveals there was one at 19:01:27:

 
2017-10-15T19:01:27 AS-REQ durrett@TESTING.MI.EXAMPLE.COM from IPv4:192.168.40.30 for
krbtgt/TESTING.MI.EXAMPLE.COM@TESTING.MI.EXAMPLE.COM
2017-10-15T19:01:27 Client sent patypes: encrypted-timestamp
2017-10-15T19:01:27 Looking for PKINIT pa-data -- durrett@TESTING.MI.EXAMPLE.COM
2017-10-15T19:01:27 Looking for ENC-TS pa-data -- durrett@TESTING.MI.EXAMPLE.COM
2017-10-15T19:01:27 ENC-TS Pre-authentication succeeded -- durrett@TESTING.MI.EXAMPLE.COM using aes256-cts-hmac-sha1-96
2017-10-15T19:01:27 AS-REQ authtime: 2017-10-15T19:01:27 starttime: unset endtime: 2017-10-16T05:01:26 renew till: unset
2017-10-15T19:01:27 Client supported enctypes: aes256-cts-hmac-sha1-96, aes128-cts-hmac-sha1-96, des3-cbc-sha1, des3-cbc-md5,
arcfour-hmac-md5, using aes256-cts-hmac-sha1-96/aes256-cts-hmac-sha1-96
2017-10-15T19:01:27 Requested flags: forwardable


Bro Logs

To be sure that this is the right authentication request, we need some more information. Since we don’t have an active
packet sniffer running, we can’t go back in time and collect evidence from the wire. This whole time though, Bro has been
running and dutifully logging information on network activity.

The first log we are going to look in is the Bro DNS log. Remember we are looking for the pattern SRV, A, AAAA that should
have occurred at 19:01. The Bro stores time in seconds since the epoch, so we first must covert the time we gathered from the
other logs to seconds since the epoch:

 
$date -j -f "%Y-%m-%d %T" "2017-10-15 19:01:27" "+%s"

1508094087


Now we can check for DNS traffic at that time:

 
$zcat dns.19:00:00-20:00:00.log.gz | grep 1508094087

1508094087.119340 C8Vvno24QoDun6a7A1 192.168.40.30 16403 192.168.11.1 53 udp 10224 0.000817
_kerberos._udp.testing.mi.example.com 1 C_INTERNET 33 SRV 0 NOERROR T F T T
0 kerberos.testing.mi.example.com 1000.000000 F
1508094087.135537 CHVtO52Xm0jWmNvXT8 192.168.40.30 46411 192.168.11.1 53 udp 19611 0.000630
kerberos.testing.mi.example.com 1 C_INTERNET 1 A 0 NOERROR T F T T 0
192.168.40.10 1000.000000 F
1508094087.136610 CidFcG4NMH235WXXTa 192.168.40.30 23427 192.168.11.1 53 udp 61196 -
kerberos.testing.mi.example.com 1 C_INTERNET 28 AAAA 0 NOERROR F F T F 0
- - F


Sure enough, the pattern is there, but lets make it more readable:

 
$zcat dns.19:00:00-20:00:00.log.gz | ../../bin/orb-cut ts id.orig_h id.resp_h qtype_name answers | grep 1508094087 | awk
'{print$2 " asked " $3 " for record type " $4 " and the answer was " $5}'

192.168.40.30 asked 192.168.11.1 for record type SRV and the answer was kerberos.testing.mi.example.com
192.168.40.30 asked 192.168.11.1 for record type A and the answer was 192.168.40.10
192.168.40.30 asked 192.168.11.1 for record type AAAA and the answer was -


So that is what occurred on the wire when the client asked for the initial authentication token. For the DNS activity during
the actual SSH login, we can also look to the Bro logs. First we need to convert when the login occurred to epoch time:

 
$date -j -f "%Y-%m-%d %T" "2017-10-15 21:09:54" "+%s"
1508101794


And now we can get the detailed activity for that time:


 

$zcat dns.21:00:00-22:00:00.log.gz | grep -A7 1508101794

1508101794.598890 Cpfgs941Uq3duQS058 192.168.40.30 60865 192.168.11.1 53 udp 30108 0.071966
ssh-server.testing.mi.example.com 1 C_INTERNET 1 A 0 NOERROR T F T T
0 192.168.40.20 1000.000000 F
1508101794.671289 CRprQK2vGqn3BsHIOk 192.168.40.30 44421 192.168.11.1 53 udp 51280 -
ssh-server.testing.mi.example.com 1 C_INTERNET 28 AAAA 0 NOERROR F F T F
0 - - F
1508101795.130640 CiM2402sD7lR6dpMT6 192.168.40.30 16566 192.168.11.1 53 udp 30081 -
ssh-server.testing.mi.example.com 1 C_INTERNET 44 SINK 0 NOERROR F F T F
0 - - F
1508101795.382763 CJiIVL3GYnhGTNPfpg 192.168.40.20 23809 192.168.11.1 53 udp 57854 0.000857
30.40.168.192.in-addr.arpa 1 C_INTERNET 12 PTR 0 NOERROR T F T T 0
ssh-client.testing.mi.example.com 1000.000000 F
1508101795.389236 C7rFYncSRDhlQ5V7k 192.168.40.20 63727 192.168.11.1 53 udp 13340 -
ssh-client.testing.mi.example.com 1 C_INTERNET 1 A 0 NOERROR T F T T
0 192.168.40.301000.000000 F
1508101795.885207 CLOzqx49eQn6GumMOk 192.168.40.20 60873 192.168.11.1 53 udp 16826 0.000722
ssh-client.testing.mi.example.com 1 C_INTERNET 1 A 0 NOERROR T F T T
0 192.168.40.30 1000.000000 F
1508101795.886315 C77bUW3czcYo1Sv6O4 192.168.40.20 51131 192.168.11.1 53 udp 31499 -
ssh-client.testing.mi.example.com 1 C_INTERNET 28 AAAA 0 NOERROR F F T F
0 - - F
1508101796.324328 CPycc83zV35SRT2Xpj 192.168.40.20 52846 192.168.11.1 53 udp 38600 0.000820
ssh-client.testing.mi.example.com 1 C_INTERNET 1 A 0 NOERROR T F T T
0 192.168.40.30 1000.000000 F
1508101796.325687 C2x1Lu3FKlnWoygD41 192.168.40.20 34475 192.168.11.1 53 udp 49577 -
ssh-client.testing.mi.example.com 1 C_INTERNET 28 AAAA 0 NOERROR F F T F
0 - - F


It seems to match the expected pattern with one exception. Cleaning up a bit makes it easier to read:

 
zcat dns.21:00:00-22:00:00.log.gz | ../../bin/orb-cut ts id.orig_h id.resp_h qtype_name answers | grep -A7 1508101794 | awk
'{print$2 " asked " $3 " for record type " $4 " and the answer was " $5}'

192.168.40.30 asked 192.168.11.1 for record type A and the answer was 192.168.40.20
192.168.40.30 asked 192.168.11.1 for record type AAAA and the answer was -
192.168.40.30 asked 192.168.11.1 for record type SINK and the answer was -
192.168.40.20 asked 192.168.11.1 for record type PTR and the answer was ssh-client.testing.mi.example.com
192.168.40.20 asked 192.168.11.1 for record type A and the answer was 192.168.40.30
192.168.40.20 asked 192.168.11.1 for record type A and the answer was 192.168.40.30
192.168.40.20 asked 192.168.11.1 for record type AAAA and the answer was -
192.168.40.20 asked 192.168.11.1 for record type A and the answer was 192.168.40.30
192.168.40.20 asked 192.168.11.1 for record type AAAA and the answer was -


Now, the is an anomaly here. Where SSHFP was in the DNS query log, Bro recorded the same event as a SINK query. The SSH client
is looking for a host key in the DNS and that record type is SSHFP. So why would Bro record it as a record type SINK? The code
for that SSHFP record type is 44 [2]. Looking into the source code, I found a mapping error in
scripts/base/protocols/dns/consts.bro:

 
## Mapping of DNS query type codes to human readable string
## representation.
const query_types = {
[1] = "A", [2] = "NS", [3] = "MD", [4] = "MF",
[5] = "CNAME", [6] = "SOA", [7] = "MB", [8] = "MG",
[9] = "MR", [10] = "NULL", [11] = "WKS", [PTR] = "PTR",
[13] = "HINFO", [14] = "MINFO", [15] = "MX", [16] = "TXT",
[17] = "RP", [18] = "AFSDB", [19] = "X25", [20] = "ISDN",
[21] = "RT", [22] = "NSAP", [23] = "NSAP-PTR", [24] = "SIG",
[25] = "KEY", [26] = "PX" , [27] = "GPOS", [28] = "AAAA",
[29] = "LOC", [30] = "EID", [31] = "NIMLOC", [32] = "NB",
[33] = "SRV", [34] = "ATMA", [35] = "NAPTR", [36] = "KX",
[37] = "CERT", [38] = "A6", [39] = "DNAME", [40] = "SINK",
[EDNS] = "EDNS", [42] = "APL", [43] = "DS", [44] = "SINK",
[45] = "SSHFP", [46] = "RRSIG", [47] = "NSEC", [48] = "DNSKEY",
[49] = "DHCID", [99] = "SPF", [100] = "DINFO", [101] = "UID",
[102] = "GID", [103] = "UNSPEC", [249] = "TKEY", [250] = "TSIG",
[251] = "IXFR", [252] = "AXFR", [253] = "MAILB", [254] = "MAILA",
[257] = "CAA",
[32768] = "TA", [32769] = "DLV",
[ANY] = "*",


Type 44 is listed as SINK, whereas it should be SSHFP. So, that explains the difference between the DNS query log and the Bro
DNS log [3]. Now that we know that, there is correlation between the what is in the DNS query logs, what is in the Bro DNS
logs and partial correlation from the packet capture that started this article.

Bro also logs SSH connections. Using the same time stamp in epoch time from above, we can easily pull the record of the SSH
client connecting to the SSH server:


 
zcat ssh.21:00:00-22:00:00.log.gz | grep 1508101794

1508101794.744313 C5xGhKD4SlJzNZVll 192.168.40.30 16267 192.168.40.20 22 2 T 1 -
SSH-2.0-OpenSSH_7.2 FreeBSD-20160310 SSH-2.0-OpenSSH_7.2 FreeBSD-20160310 chacha20-poly1305@openssh.com
umac-64-etm@openssh.com none curve25519-sha256@libssh.org ssh-rsa f2:34:a8:49:ef:29:23:e4:f5:3c:82:77:9d:60:ed:d1 -
- - - -


To make that easier to read, we can add some awk:

 
$zcat ssh.21:00:00-22:00:00.log.gz | ../../bin/orb-cut ts id.orig_h id.orig_p id.resp_h id.resp_p cipher_alg | grep 1508101794
| awk '{print"Host "$2" using outgoing port "$3" established a SSH connection to "$4" on port "$5" using encryption algorithm
"$6}'

Host 192.168.40.30 using outgoing port 16267 established a SSH connection to 192.168.40.20 on port 22 using encryption
algorithm chacha20-poly1305@openssh.com


Now, we have correlation of the SSH connection between the packet capture, the auth.log on the SSH server and the Bro SSH log.
There is further evidence of the connection which includes the length of time in Bro connect log:

 
1508101794.674102 C5xGhKD4SlJzNZVll 192.168.40.30 16267 192.168.40.20 22 tcp ssh 42.527811
3190 4098 SF F F 0 ShADadFf 34 4966 31 5718 (empty)


We can clean that up and make a readable sentence with some of the data with awk:
 
$zcat conn.21:00:00-22:00:00.log.gz | ../../bin/orb-cut ts id.orig_h id.orig_h service duration | grep 1508101794.67 | awk
'{print"Host "$2" made a "$4" connection to "$2" that lasted for "$5 " seconds."}'

Host 192.168.40.30 made a ssh connection to 192.168.40.30 that lasted for 42.527811 seconds.


All of the traffic above is basic run of the mill traffic normally seen on production networks everyday. There isn’t
anything special about it, it is just the way thins work. Knowing how thing are supposed to work, however, is an aide to
seeing things that are out of place. Even though the traffic is normal and bland, some conclusions still can be drawn.

A good portion of the discussion was dominated with DNS traffic. Seemingly at every turn , DNS was involved somehow. That
means logging of DNS traffic both on the wire and in DNS logs, is an essential element in both network administration and
network security. Whatever is going on, there is probably a trace of it in the DNS logs and more than likely will fit a
pattern close enough to deduce what type of connections would cause that pattern.

It is also interesting to note the key role that DNS plays in our networks. From the getting the initial key to logging into
the the ssh server, DNS is essential. Something to keep in mind, and keep others in the technical vertical of your
organization appraised of, is that DNS is not just the “white pages of the Internet” so “your browser knows where
to go” but a crucial piece of infrastructure without which nothing would work. Losing control over DNS would bring an
organizations entire authentication and automation (assuming it is done via SSH) systems to a complete dead halt.
Misconfigured or maliciously configured DNS could compromise the authentication mechanisms.

Another conclusion to draw from the correlation of traffic and system logs is that there is more than one place to begin
investigating events. There is also more than one tool to use. Any of these places, logs or the wire, can be used maliciously
to gain intelligence on what an organization does and how it does it. Great care should be taken with logs to keep that
information private and out of the hands off actors who wish to do harm. Network traffic, even when encrypted as our Kerberos
and SSH traffic above was, can still provide significant intelligence like where and when a login occurred.

The last conclusion to be drawn is that there are many things going on under the hood in the daily life of networked system.
To administer or provide security to them, it is imperative to understand how each works and what the traces are on the
network and on the systems. It is currently, and has been for a while, to focus on the bad things that can happen. While that
is important, most sophisticated adversaries know how things work and for that reason understanding the basics this article
presented will help to foster better overall security of our systems.

References:

[1] https://www.bro.org/sphinx/scripts/base/protocols/krb/main.bro.html
[2] https://en.wikipedia.org/wiki/List_of_DNS_record_types
[3] https://jedwarddurrett.com/20171021163149.php







Copyright (c) 2019, Jason Edward Durrett - All content on this site, unless otherwise noted, is subject to this license.

Please contact me if any errors, such as erroneous / misleading content or missing / incomplete attribution, are found.