Splunk Search

help working with radius data (transactions)

Builder

I'm trying to work with data from Juniper's Steel-Belted Radius servers and am struggling with it. I'm not sure I'm approaching this properly, but would like to generate reports on successful authentications, failed authentications, types of users attempting these types of authentications, etc. Also to exclude some event "chunks" where the authentication is really something done by a load balancer to check if the node is alive rather than a real person.

The approach I assumed was the right one was to try to use the "transaction" command to build transactions, then pare off each authentication attempt's info and filter from there. Aside from dealing with the slowness of the transaction command (there's lots of events), I'm finding that I cannot get Splunk to correctly identify a transaction.

Here's a sample of what an actual transaction might look like with elements randomized for safety. Note that A lot of the stuff in the middle could vary depending on the authentication type, but I'm trying to focus on this one common case first.

08/23/2011 16:01:58 (74c)-----------------------------------------------------------
08/23/2011 16:01:58 (74c)Authentication Request
08/23/2011 16:01:58 (74c)Received from: ip=1.2.3.4 port=12345
08/23/2011 16:01:58 (74c)
08/23/2011 16:01:58 (74c)Raw Packet :
08/23/2011 16:01:58 (74c)000: 0136004b 1f9da8d9 7ad4b701 8bf22849 |.6.K....z.....(I|
08/23/2011 16:01:58 (74c)010: 6a7d6e13 010d6466 776c627a 2d757365 |j}n...sanlbz-use|
08/23/2011 16:01:58 (74c)020: 720212dc 3af804d2 f1ac1f8f 90bfab2d |r...:..........-|
08/23/2011 16:01:58 (74c)030: f4b9f604 06c02e23 2b201264 66776c62 |.......#+ .sanlb|
08/23/2011 16:01:58 (74c)040: 31612e70 6273672e 707674 |1a.sal.pvt |
08/23/2011 16:01:58 (74c)
08/23/2011 16:01:58 (74c)-----------------------------------------------------------
08/23/2011 16:01:58 F:\build\zMhtHo68zI\SBR\xradius\radauthd.c radAuthHandleRequest() 3022 (92c)Entering
08/23/2011 16:01:58 (92c)Looking up shared secret
08/23/2011 16:01:58 (92c)Looking for RAS client 1.2.3.4 in DB
08/23/2011 16:01:58 (92c)Matched 1.2.3.4 to RAS client SANLBZ1C
08/23/2011 16:01:58 (92c)Parsing request
08/23/2011 16:01:58 (92c)Initializing cache entry
08/23/2011 16:01:58 (92c)Doing inventory check on request
08/23/2011 16:01:58 (92c)Getting info on requesting client
08/23/2011 16:01:58 (92c)NAS-IP-Address in request: 2.3.4.5
08/23/2011 16:01:58 (92c)Looking for RAS client 2.3.4.5 in DB
08/23/2011 16:01:58 (92c)NAS-ID in request: "sanlb1a.sal.pvt"
08/23/2011 16:01:58 (92c)-----------------------------------------------------------
08/23/2011 16:01:58 (92c)Authentication Request
08/23/2011 16:01:58 (92c)Received From: ip=1.2.3.4 port=12345
08/23/2011 16:01:58 (92c)Packet : Code = 0x1 ID = 0x36
08/23/2011 16:01:58 (92c)Client Name = SANLB1A.SAL.PVT Dictionary Name = Radius.dct
08/23/2011 16:01:58 (92c)Vector =
08/23/2011 16:01:58 (92c)000: 1f9da8d9 7ad4b701 8bf22849 6a7d6e13 |....z.....(Ij}n.|
08/23/2011 16:01:58 (92c)Parsed Packet =
08/23/2011 16:01:58 (92c)User-Name : String Value = sanlbz-user
08/23/2011 16:01:58 (92c)User-Password : Value =
08/23/2011 16:01:58 (92c)000: dc3af804 d2f1ac1f 8f90bfab 2df4b9f6 |.:..........-...|
08/23/2011 16:01:58 (92c)NAS-IP-Address : IPAddress = 2.3.4.5
08/23/2011 16:01:58 (92c)NAS-Identifier : String Value = sanlb1a.sal.pvt
08/23/2011 16:01:58 (92c)Funk-Source-IP-Address : IPAddress = 1.2.3.4
08/23/2011 16:01:58 (92c)-----------------------------------------------------------
08/23/2011 16:01:58 (92c)Determining if request is for a tunnel
08/23/2011 16:01:58 (92c)Determining if this radius should act as a proxy
08/23/2011 16:01:58 (92c)CreateRequestEx: using virtual realm RETRealm for authentication.
08/23/2011 16:01:58 (92c)Determining user class
08/23/2011 16:01:58 (92c)Authenticating user SANLBZ-USER with authentication method Native User
08/23/2011 16:01:58 (92c)Determined that SANLBZ-USER of class Native-User is the user
08/23/2011 16:01:58 (92c)Getting attribute info on requesting user
08/23/2011 16:01:58 (92c)Getting profile info for requesting user
08/23/2011 16:01:58 (92c)Merging saved attributes with user info
08/23/2011 16:01:58 (92c)Merging profile info with user info
08/23/2011 16:01:58 (92c)Comparing checklist items with user/profile items
08/23/2011 16:01:58 (92c)Appending echo values, if any
08/23/2011 16:01:58 (92c)User SANLBZ-USER being passed to attribute editing authentication methods
08/23/2011 16:01:58 (92c)Class subattribute: DistName : String Value = SANLBZ-USER
08/23/2011 16:01:58 (92c)Class subattribute: AuthType : String Value = 0
08/23/2011 16:01:58 (92c)Class subattribute: TransactionId : Value =
08/23/2011 16:01:58 (92c)000: 47c56dd3 cd1344ef 0000701a |G.m...D...p. |
08/23/2011 16:01:58 (92c)Class subattribute: VirtualRealm : String Value = RETRealm
08/23/2011 16:01:58 (92c)Sent accept response for user SANLBZ-USER to client SANLB1A.SAL.PVT
08/23/2011 16:01:58 (92c)-----------------------------------------------------------
08/23/2011 16:01:58 (92c)Authentication Response
08/23/2011 16:01:58 (92c)Packet : Code = 0x2 ID = 0x36
08/23/2011 16:01:58 (92c)Vector =
08/23/2011 16:01:58 (92c)000: 50f735a0 f2f07130 76f872ae 55c95701 |P.5...q0v.r.U.W.|
08/23/2011 16:01:58 (92c)Class : Value =
08/23/2011 16:01:58 (92c)000: 53425232 434ca3f1 addd9eb4 a6c4f7c0 |SBR2CL..........|
08/23/2011 16:01:58 (92c)010: 11803701 80028198 8002800d 81a291ca |..7.............|
08/23/2011 16:01:58 (92c)020: f4e289b4 adaad4e8 d5900880 0a81a794 |................|
08/23/2011 16:01:58 (92c)030: 89c59395 c2ecb6c0 12800e81 a3f1addd |................|
08/23/2011 16:01:58 (92c)040: 9eb4a6c4 f7c08087 80e8 |.......... |
08/23/2011 16:01:58 (92c)-----------------------------------------------------------
08/23/2011 16:01:58 (92c)-----------------------------------------------------------
08/23/2011 16:01:58 (92c)Authentication Response
08/23/2011 16:01:58 (92c)Sent to: ip=1.2.3.4 port=12345
08/23/2011 16:01:58 (92c)
08/23/2011 16:01:58 (92c)Raw Packet :
08/23/2011 16:01:58 (92c)000: 02360060 50f735a0 f2f07130 76f872ae |.6.`P.5...q0v.r.|
08/23/2011 16:01:58 (92c)010: 55c95701 194c5342 5232434c a3f1addd |U.W..LSBR2CL....|
08/23/2011 16:01:58 (92c)020: 9eb4a6c4 f7c01180 37018002 81988002 |........7.......|
08/23/2011 16:01:58 (92c)030: 800d81a2 91caf4e2 89b4adaa d4e8d590 |................|
08/23/2011 16:01:58 (92c)040: 08800a81 a79489c5 9395c2ec b6c01280 |................|
08/23/2011 16:01:58 (92c)050: 0e81a3f1 addd9eb4 a6c4f7c0 808780e8 |................|
08/23/2011 16:01:58 (92c)
08/23/2011 16:01:58 (92c)-----------------------------------------------------------
08/23/2011 16:01:58 (92c)Packet containing 96 bytes successfully sent
08/23/2011 16:01:58 F:\build\zMhtHo68zI\SBR\xradius\radauthd.c radAuthHandleRequest() 3777 (92c)Exiting

My most recent attempts have been with

* | transaction maxspan=15s keepevicted=t host endswith="Packet containing"

The 15 seconds are arbitrary (I'm not certain how long an auth attempt might be, but I believe it's usually pretty quick) and I know that an auth attempt usually will not span multiple radius hosts. Identifying the transaction using the lines of dashes isn't really correct as those lines exist within a real transaction. When I run the command above, it identifies the section starting with the "(92c)" lines ending with the "Packet containing" line as a transaction, but then orphans the first 13 lines instead of including it in the transaction. I only see those because of the "keepevicted" parameter. Note that the line line that precedes the first event listed here is also a "Packet containing ..." line.

That number right after the date is called the LogThreadID, but it's not particularly useful here as from what I can see it's reused for multiple transactions (i.e. not unique per transaction) and from the example above, there are 2 different LogThreadIDs in just this one authentication attempt.

While I thought doing a transaction based solely on time might work better, I can't really be certain those parameters ("maxspan=1s"?) would really be correct all the time. Maybe a barrage of requests would come in all at once or maybe an auth session could take 2 seconds.

So is my approach here right given the quite unstructured format of this data? Any suggestions about how I might want to handle this differently?

Thanks

Tags (1)

Communicator

Transaction does seem like the right thing to use here, and I think we can make it work with a little fiddling around. I've noticed two things here:

1) Since you know each authentication (except the first in the log) will be preceded by "exiting", you COULD do something like | transaction host startswith="Exiting" endswith="Packet containing". Then you would just need to get the first authentication. That might get tricky though.

2) I tried a slight variant on your recent attempt, and it seems to be working for me.

I don't have any Juniper Steel-Belted Radius logs. What I did was take your data, throw it in a text file, and upload it to Splunk. Then I punched in the query source="juniper test log" | transaction host endswith="Packet containing"

The transaction worked as expected, giving only 1 event with all the data in it and no lines lost. I tried another quick test to confirm, adding some bogus data and a "Packet containing" line before your provided sample. This gave me 2 events...the new transaction I added, followed by your original.

I'm not sure if this is because I'm using a text file instead of a "real" log, if there is some subtle difference between our two transactions, or if you have something before the pipe to transaction causing things to behave unexpectedly.

Builder

I should clarify. It seems to not matter whether or not I have startswith= specified (it can only apparently do harm). I would like to define it as startswith=")Entering" but no valid string works there. The results I get back, while correct, are all marked with closed_txn=0. Typical transactions appear to be combinations of 70-150 events which should, if I'm reading this correctly, be way less than the default memory and transaction limits in limits.conf of 5,000 (maxopentxn) and 100,000 (maxopenevents).

0 Karma

Builder

I've created a perfectly inverted transaction where according to Splunk nothing matches, but all evicted transactions look right. Works the same if I say startswith="foo".

Searching by essentially saying "show me all the rejects and that's my answer" here doesn't really seem right. What I have that works inversely is

index=sbr sourcetype=radius_log | transaction startswith="foo" endswith="Exiting" keepevicted=true host LogThreadID

0 Karma

Builder

I kind of backed into a semi-solution. I was originally going to go with startswith="Entering" endswith="Exiting" but I discovered that there were 2 forms of "Entering" one I wanted and one I didn't.

I thought I'd made it work with startswith="radAuthHandleRequest*Entering" endswith="Exiting" keepevicted=true. It was almost perfect. Except I discovered that it was perfectly evicting every transaction, but they were all seemingly correct. Problem is you can't regex the startswith so that effectively never matches. But if I have no startswith=, it's always wrong. So somehow (continued)

0 Karma

Communicator

That is a little weird; it seems to always keep the "Packet containing" when I run the query. If those lines are important you could try using a different string, such as endswith="Exiting" which also seems to appear at the end of each transaction.

If all the formats have a "Packet containing" or an "Exiting" at the end, there shouldn't be a problem.

0 Karma

Builder

Thanks. I'd tried that particular endswith once before, but I think I'd paired it with something else for startswith. I've been evaluation the success of a transaction statement by using keepevicted=t and seeing if I get any closed_txn=0 results. (I don't get any closed_txn=0 results when using endswith="Packet containing".) However, what's weird is that when I look at the resulting transactions that Splunk built, some of them actually show that "Packet containing" and some of them don't which doesn't make sense to me.

I didn't show some of the many other formats contained in these events

0 Karma

Builder

Yes, I forgot to mention that I'd tried using various combinations of the "Exiting" and "Entering" lines to break the transaction on (startswith and/or endswith). It seemed to work in many cases, but not all. Ultimately, I'm thinking this data just might not break well into transactions and I was wondering if my strategy here of using 'transaction' might not be the right strategy.

0 Karma

Communicator

You mention that the line before the first event listed here is another "Packet Containing" line. Does this previous "Packet Containing" line also contain an "Exiting" statement, like your final event listed here?

0 Karma