Covering J2EE Security and WebLogic Topics

RoleManager Audit Events in WebLogic

Want to fill up your audit logs quickly? Set the auditor’s severity to INFORMATION and you’re well on your way. In this post we’ll take a closer look and see if the information gained is worthy of the disk space and processing time.

More is Better, Right?

It’s natural to expect that audit logs won’t be as "chatty" as application logging. After all, you’d typically only expect one or a handful of authorization events for each accessed resource. Application logging, on the other hand, might spew dozens of lines per request depending upon the logging level.

With this in mind, your security officer or well-meaning admin might see that the WebLogic DefaultAuditor is initially set to a severity of ERROR leaving not one but TWO severity levels untapped. More security data has to be good, right?

Not necessarily. Besides INFORMATION, the other severity level below ERROR is WARNING. I’ve never seen a WARNING event from the out-of-the-box providers. That’s not to say they don’t exist — just that I’ve never seen one. The INFORMATION severity is the lowest level which only seems to include a certain class of Role Manager events.

Role Manager audit events can be sourced from a Role Mapping provider or an Authorization provider. Useful Role Manager events can happen at the SUCCESS and FAILURE levels, but the INFORMATION-level events are highly repetitive and provide little bang for buck. Here are a couple of examples:

#### Audit Record Begin <Jun 26, 2007 9:20:01 PM> <Severity =INFORMATION> <<<Event Type = RoleManager Audit Event ><Subject: 2
Principal = class weblogic.security.principal.WLSUserImpl("weblogic")
Principal = class weblogic.security.principal.WLSGroupImpl("Administrators")
><<adm>><type=<adm>, category=Configuration><>>> Audit Record End ####

#### Audit Record Begin <Jun 26, 2007 9:20:01 PM> <Severity =INFORMATION> <<<Event Type = RoleManager Audit Event ><Subject: 2
Principal = class weblogic.security.principal.WLSUserImpl("weblogic")
Principal = class weblogic.security.principal.WLSGroupImpl("Administrators")
><<adm>><type=<adm>, category=Configuration><||Anonymous||Admin>>> Audit Record End ####

As you can see, there’s very little actionable information here. Yes, user "weblogic" did something but we’re not quite sure what.

Crunch the Numbers

To give you an idea of the volume of Role Manager events at the INFORMATION severity, I started up a WebLogic 8.1 domain which includes five custom applications. I then logged into console but went no further than the initial page. Here’s the breakdown of audit events (note that I’ve enabled configuration auditing):

Authentication: 2
Authorization: 6
AuthorizationPolicy Deploy: 25
Invoke Configuration: 1
RoleManager: 772
RoleManager Deploy: 3
Set Attribute: 10

As you can see, the RoleManager events account for 94%(!) of all events for my scenario. Hitting Refresh on the console caused approximately the same number of Role Manager events. I haven’t timed it, but writing all of those events to disk is probably quite measurable.

Console makes heavy use of JMX so I suspect a lot of the Role Manager events are caused by that. I tested a "normal" web app with just a protected page. Here are the results:

Authentication: 1
Authorization: 1
RoleManager: 14

Thus, for one request, the Role Manager events comprise 88% of the total number of events. The information is slightly different (and maybe even a little useful) as long as you don’t mind seeing it a bunch of times. Here are a couple events:

#### Audit Record Begin <Jun 26, 2007 10:44:08 PM> <Severity =INFORMATION> <<<Event Type = RoleManager Audit Event ><Subject: 2
Principal = class weblogic.security.principal.WLSUserImpl("weblogic")
Principal = class weblogic.security.principal.WLSGroupImpl("Administrators")
><<url>><type=<url>, application=ImplicitGroupsApp, contextPath=/implicitgroupsapp, uri=/users/users.jsp, httpMethod=GET><>>> Audit Record End ####

#### Audit Record Begin <Jun 26, 2007 10:44:08 PM> <Severity =INFORMATION> <<<Event Type = RoleManager Audit Event ><Subject: 2
Principal = class weblogic.security.principal.WLSUserImpl("weblogic")
Principal = class weblogic.security.principal.WLSGroupImpl("Administrators")
><<url>><type=<url>, application=ImplicitGroupsApp, contextPath=/implicitgroupsapp, uri=/users/users.jsp, httpMethod=GET><||user||Anonymous||everyone||Admin>>> Audit Record End ####

I suspect these are sourced by the authorization provider given that it’s showing the requested resource information. The list of roles is barely useful — which one is required?

Quantum Logging

If you decide to not use the INFORMATION severity you can still get the equivalent information from the audit log if you had to. The first thing to consider is the Authorization event. Here’s the event that accompanied the RoleManager event above:

#### Audit Record Begin <Jun 26, 2007 10:44:08 PM> <Severity =SUCCESS> <<<Event Type = Authorization Audit Event ><Subject: 2
Principal = class weblogic.security.principal.WLSUserImpl("weblogic")
Principal = class weblogic.security.principal.WLSGroupImpl("Administrators")
><ONCE><<url>><type=<url>, application=ImplicitGroupsApp, contextPath=/implicitgroupsapp, uri=/users/users.jsp, httpMethod=GET>>> Audit Record End ####

Notice that the resource information is identical to the equivalent RoleManager event.

How can you know which role was required for "/users/users.jsp?" One way is to check that application’s web.xml. However, that data could be newer than what was in place when the event was logged (e.g., web.xml was updated and the app was redeployed after the event).

A better way to do it is to find the most recent corresponding Authorization Policy Deploy event prior to the authorization event in question. For example,

#### Audit Record Begin <Jun 26, 2007 9:12:12 PM> <Severity =SUCCESS> <<<Event Type = Authorization Policy Deploy Audit Event ><Subject: 1
Principal = class weblogic.security.principal.WLSKernelIdentity("<WLS Kernel>")
><<url>><type=<url>, application=ImplicitGroupsApp, contextPath=/implicitgroupsapp, uri=/users/*, httpMethod=GET><user>>> Audit Record End ####

shows one of the policies for the ImplicitGroupsApp. Note that the policy applies to "/users/*" and requires the "user" role for URIs with that pattern.

This concludes our little romp through an audit log. If you choose to not select the INFORMATION severity you can save yourself considerable disk space while still retaining the ability to get the data you need.

Troubleshooting Authentication Issues with Audit Logs

In Common Problems with Authentication Provider Configuration, I wrote some tips for troubleshooting authentication/authorization problems in WebLogic. This post is a continuation of that one and shows how to decipher an audit log for troubleshooting purposes.

Audit logs are truly a secret weapon. Sure, they allow you to do the normal audit log things like going back in time to see who did what and when, but that stuff is for your security guy. As a developer, audit logs shine for other reasons such as these uses that I wrote about previously:

While Common Problems with Authentication Provider Configuration discussed the relationship between authentication and authorization, this post will highlight each as a discrete step and make it clear as to why a user can’t access a resource.

Laying the Groundwork

We’re going to look at three authentication/authorization scenarios to compare the audit log output:

  • Successful Authentication and Authorization
  • Authentication Failure
  • Authorization Failure

You can run through the scenarios on your own WebLogic domain if you’d like. For this demonstration I started with a new domain and added a “Managers” group which will simply be an extraneous group that you’ll see in the output. I then added a user named “squidward” and added him to the the Administrators and Managers groups. I also added user “spongebob” but only included him in the Managers group.

We now have two users in the Managers group. Squidward is in the Administrators group and will be able to access the WebLogic Admin Console application. Spongebob is not an administrator and will not have access.

Finally, I created a new DefaultAuditor (see WebLogic Auditing for how to do this) and restarted WebLogic.

Now let’s try it out…

Successful Authentication and Authorization

I pulled up the Admin console and logged in as Squidward. Here’s the audit log output:

#### Audit Record Begin <Sep 16, 2006 10:24:23 AM> <Severity =SUCCESS> <<<Event Type = Authentication Audit Event><squidward><AUTHENTICATE>>> Audit Record End ####

#### Audit Record Begin <Sep 16, 2006 10:24:23 AM> <Severity =SUCCESS> <<<Event Type = Authorization Audit Event ><Subject: 3
Principal = class weblogic.security.principal.WLSUserImpl(“squidward”)
Principal = class weblogic.security.principal.WLSGroupImpl(“Administrators”)
Principal = class weblogic.security.principal.WLSGroupImpl(“Managers”)
><ONCE><<url>><type=<url>, application=console, contextPath=/console, uri=/, httpMethod=GET>>> Audit Record End ####

You can see that we have two events representing authentication and authorization. The Authentication event indicates that Squidward successfully established his identity. Furthermore, the Authorization event shows that he was permitted access because he’s in the Administrators group.

Note that the authorization event contains some useful extra information. First, we see that it’s Squidward who accessed the resource (/console). We also see that he is in the Administrators and Managers groups. Inclusion in the Administrators group is his ticket to the Console application, but you also now know that he happens to be in the Managers group even though the Console application does not care about that group.

We now know what the “happy path” looks like in the audit log. Now for the not-so-happy paths…

Authentication Failure

I logged Squidward out of the Console application. I then tried to log in as Squidward again but this time I supplied a wrong password. The audit log output is shown below:

#### Audit Record Begin <Sep 16, 2006 7:35:59 PM> <Severity =FAILURE> <<<Event Type = Authentication Audit Event><squidward><AUTHENTICATE>>> <FailureException =javax.security.auth.login.FailedLoginException: [Security:090304]Authentication Failed: User squidward javax.security.auth.login.FailedLoginException: [Security:090302]Authentication Failed: User squidward denied> Audit Record End ####

Note that this time there is only a failed authentication event. WebLogic did not attempt authorization because it could not establish the user’s identity. Naturally, you can only check a user’s permissions if you know who the user is.

In this example, I provided a correct username but an incorrect password. I could have gotten the exact same output if I had provided a username/password for a non-existent user. In each case, no identity could be established.

Authorization Failure

For this scenario, I logged in as Spongebob with the correct password. The resulting audit events are shown below:

#### Audit Record Begin <Sep 16, 2006 7:39:40 PM> <Severity =SUCCESS> <<<Event Type = Authentication Audit Event><spongebob><AUTHENTICATE>>> Audit Record End ####

#### Audit Record Begin <Sep 16, 2006 7:39:40 PM> <Severity =FAILURE> <<<Event Type = Authorization Audit Event ><Subject: 2
Principal = class weblogic.security.principal.WLSUserImpl(“spongebob”)
Principal = class weblogic.security.principal.WLSGroupImpl(“Managers”)
><ONCE><<url>><type=<url>, application=console, contextPath=/console, uri=/, httpMethod=GET>>> Audit Record End ####

The output here is very similar to the successful first scenario. Spongebob authenticated just fine but was not authorized to access the Console application. The reason is evident in the event itself — Spongebob is not a member of the Administrators group.

Conclusion

You can see that the audit log can help you track down access problems. Was it a bad username/password combination or simply an authorization error? Output from your application (or Console as used here) doesn’t help you make the determination. In fact, the two very different failure scenarios showed the exact same error message on the Console login page. Audit logs show the real reason.

The other nice thing about authorization events is that the output shows the groups for which the user is a member. That sometimes comes in handy.

If the tips here weren’t sufficient to solve your problem, your last resort is security debugging. By enabling security debugging you can get copious amounts of output from the security providers to see exactly what is going on. Here are some links to get you going:

Happy auditing!

Using Audit Logs to Make Scripting Easier

Scripting configuration settings in WebLogic is fairly straight-forward. You’d typically use the WebLogic Scripting Tool (WLST) or weblogic.Admin* to create and delete MBeans in the server. You can also set properties and invoke MBean methods. While the tools are easy to use, finding the MBeans and the properties you want to use can be time-consuming.

Here’s a little trick I discovered that makes the process a little easier. In WebLogic Auditing, I show how you can use auditing to track configuration changes in the server. That can be very handy. What I realized later was that this logging could be leveraged for MBean discovery. How? With Configuration by Example (CBE).

CBE is admittedly a lame attempt at humor, but it does seem to be an apt description. The reason is that CBE works by manually making the change in WebLogic console for what you want to script and then observing how it did it.

For example, let’s say you want to set the server to production mode in a script. It’s easy enough to do in the console but you might not know where to start looking for the MBean and applicable property. With configuration auditing enabled, simply make the change in the console and observe the entry in the audit log. Here’s an example of what it looks like in the log:

#### Audit Record Begin <Jul 20, 2006 10:01:03 PM> <Severity =SUCCESS> <<<Event Type = SetAttribute Configuration Audit Event><Subject = Subject: 3
Principal = class weblogic.security.principal.WLSUserImpl(“weblogic”)
Principal = class weblogic.security.principal.WLSGroupImpl(“Administrators”)
><Object = AppSec:Name=AppSec,Type=Domain><Attribute = ProductionModeEnabled><From = false><To = true>>> Audit Record End ####

From this entry, you can see that the MBean name is AppSec:Name=AppSec,Type=Domain and the property to set is ProductionModeEnabled. Scripting this change is now a breeze since you have the MBean’s name, property, and value to set it to.

Extra Tips

  • Set the auditing severity to SUCCESS to eliminate a lot of chaff
  • In Unix, tail the audit log for streamlined access
  • Use the Help (question mark) link on the console page for MBean types and property value ranges (not all pages have this data)
  • If you want to refer to the JavaDocs for the MBean, simply add "MBean" to the Type. In the example above, the MBean would be DomainMBean.

* The weblogic.Admin approach is deprecated in WebLogic 9.

Auditing Context Information in WebLogic 9

In WebLogic 8.1, the default audit provider came with two configuration settings:

  • Audit severity
  • Log rotation time

No muss, no fuss.

Even with this minimal configurability you still get most of what you need in the log file. (See my other recent post on WebLogic auditing for more things you can do.)

In WebLogic 9, however, BEA added the ability to selectively capture context information which accompanies certain events. Most of this information was available in 8.1 but you needed to write a custom audit provider to access it.

But in WebLogic 9, you can now choose from the following types of context information to include in the audit log:

  • servlet.HttpServletRequest
  • servlet.HttpServletResponse
  • wli.Message
  • channel.Port
  • channel.PublicPort
  • channel.RemotePort
  • channel.Protocol
  • channel.Address
  • channel.RemoteAddress
  • channel.ChannelName
  • channel.Secure
  • channel.PublicAddress
  • ejb20.Parameter
  • wsee.SOAPMessage
  • entitlement.EAuxiliaryID
  • security.ChainPrevailidatedBySSL
  • xml.SecurityToken
  • xml.SecurityTokenAssertion
  • webservice.Integrity
  • saml.SSLClientCertificateChain
  • saml.MessageSignerCertificate
  • saml.subject.ConfirmationMethod
  • saml.subject.dom.KeyInfo
  • jmx.OldAttributeValue
  • jmx.ObjectName
  • jmx.ShortName
  • jmx.Parameters
  • jmx.Signature
  • jmx.AuditProtectedArgInfo

    For example, if you choose to log the HttpServletRequest context information, you’ll see most of the data from that object in your log file. This means you’ll see header information, paths, cookies, etc.

    So, if you want to fatten up your audit log file, add some context!

    WebLogic Auditing

    According to the explanatory text in the WebLogic Console:

    "An Auditing provider collects, stores, and distributes information about operating requests and the outcome of those requests for the purposes of non-repudiation. You can configure multiple Auditing providers in a security realm, but none are required."

    This article will discuss how to configure WebLogic to audit security events and configuration changes.

    Auditing Security Events

    By default, WebLogic does not have auditing turned on. To enable auditing, configure an audit provider in WebLogic Console by navigating to the Auditing Providers section of the active security realm. In the WebLogic 8.1 Console applet, drill down to mydomain->Security->Realms->myrealm->Providers->Auditing.

    Add a new DefaultAuditor and click Create. You can set the auditing severity and log rotation time in the Details tab. The DefaultAuditor writes to a file called DefaultAuditRecorder.log in your server directory alongside access.log and myserver.log.

    The DefaultAuditor doesn’t have any settings other than severity and rotation time. To have auditing take effect you’ll have to restart WebLogic. Now, whenever auditable security actions such as authentication or authorization occur, a line describing the event and the outcome is recorded in the audit log. Be aware that the audit log can be very verbose so keep an eye on disk space and performance.

    Here’s an example authorization event from DefaultAuditRecorder.log:

    #### Audit Record Begin <Mar 9, 2006 6:38:48 PM> <Severity =SUCCESS> <<<Event Type = Authorization Audit Event ><Subject: 2
    Principal = class weblogic.security.principal.WLSUserImpl("weblogic")
    Principal = class weblogic.security.principal.WLSGroupImpl("Administrators")
    ><ONCE><<url>><type=<url>, application=console, contextPath=/console, uri=/actions/mbean/editmbeanaction, httpMethod=GET>>> Audit Record End ####

    Auditing Configuration Changes

    The auditing process typically only involves security events as they relate to the security providers. For example, events such as authentication, identity assertion, authorization, role mapping, etc., get audited. But what if you’d like to be able to audit any of the following actions:

    • Addition/deletion of configuration items
    • Modification of a setting
    • Addition/deletion of a user, group, etc.
    • Password resets
    • And so on

      These are things that a WebLogic administrator can do in WebLogic Console or via other forms of configuration MBean access such as scripting or weblogic.Admin. Logging these events is as simple as making one configuration change.

      In WebLogic Console, navigate to the domain screen. In WebLogic 8.1, simply click on the domain node in the applet. On the right hand side, set Configuration Auditing from None to one of the following

      • log
      • audit
      • logaudit

        and click Apply.

        Choosing "log" causes the configuration events to go to the server log (e.g., myserver.log). That’s right, you don’t have to have an audit provider configured to capture the data. Choosing "audit," on the other hand, causes the configuration events to be sent to the audit providers. Finally, "logaudit" causes the data to be sent to both places.

        This setting takes effect immediately, so after you clicked Apply configuration changes are logged.

        Here’s an example from the DefaultAuditRecorder.log of the "weblogic" user changing the SSL listen port from 443 to 444:

        #### Audit Record Begin <Mar 9, 2006 10:19:34 PM> <Severity =SUCCESS> <<<Event Type = SetAttribute Configuration Audit Event><Subject = Subject: 2
        Principal = class weblogic.security.principal.WLSUserImpl("weblogic")
        Principal = class weblogic.security.principal.WLSGroupImpl("Administrators")
        ><Object = AppSec:Name=myserver,Server=myserver,Type=SSL><Attribute = ListenPort><From = 443><To = 444>>> Audit Record End ####

        The corresponding entry from the server log file is a little more readable:

        ####<Mar 9, 2006 10:19:34 PM EST> <Info> <Configuration Audit> <Laptop> <myserver> <ExecuteThread: ‘1’ for queue: ‘weblogic.admin.HTTP’> <weblogic> <> <BEA-159904> <USER weblogic MODIFIED AppSec:Name=myserver,Server=myserver,Type=SSL ATTRIBUTE ListenPort FROM 443 TO 444>

        Advanced Auditing

        Clearly, all of these event types can find their way to the audit providers. The significance of this is that you can write your own auditor to process the events in any way you’d like. Have a look at a set of sample security providers (with source) from BEA for a quick start at building your own.

        Let me know when you’ve written an audit provider for emailing the boss when some bozo changes the SSL port to 444! 😉

         

        Bookmark this page on del.icio.us