11 posts categorized "logging"


How To Log Client IP AND X-Forwarded-For IP in Apache

When you utilize a device like a BigIP LTM to load-balance your web servers, a typical configuration masks the client IP address.  The BigIP essentially proxies requests on behalf of the browser, so the only thing your web server sees is the IP address of the BigIP itself.  The BigIP utilizes an industry-standard (but not HTTP standard) mechanism for storing the customer IP address into an HTTP Request Header called the X-Forwarded-For header.  Typically, you configure your Apache servers to log the value from the X-Forwarded-For header instead of logging the client IP.  

This all works great except when you access the web server directly, bypassing the BigIP.  Since the BigIP (or other proxy) is inserting the X-Forwarded-For header and your browser is not, nothing gets logged in the Apache access logs so you have no simple way to determine which internal user or monitor just took your site down with that vulnerability scan.  You can still figure it out based on user-agent and communication with your peers but we sysadmins are like the police on TV—we like to have all the damning evidence at hand before "interviewing" the perp.

The following HOWTO details a mechanism for logging both, depending upon whether an X-Forwarded-For value exists or not.  HOWTO: Log Client IP AND X-Forwarded-For IP in Apache. It also includes a basic groovy script for validating.


Configuring "Wire" Logging in Groovy HTTPBuilder

Enabling Debug mode in log4j within HTTPBuilder gives me the ability to, as a novice, figure out what the heck I was thinking when I constructed an http request the way I did.  Take this script for example, which makes use of the FeedBurner Awareness API and its intention is to display the number of subscribers to my blog (thank you all, by the way!) based on a specified date:

!/usr/bin/env groovy

import groovyx.net.http.RESTClient
import groovy.util.slurpersupport.GPathResult
import static groovyx.net.http.ContentType.URLENC

def stats = new RESTClient( 'https://feedburner.google.com/api/awareness/1.0/GetFeedData?uri=BloggingTechstacks' )
def resp = stats.get( dates: '2009-11-01' )
 resp.data instanceof GPathResult

println "${resp.data.feed.@uri}"
println "${resp.data.feed.entry.@circulation}"

Every time I execute this script and specify a date range of 11/01 through 11/30, instead of getting what I wanted, I get the number of subscribers from yesterday. Clearly, there is something wrong. I can't inspect the request and response with wireshark because it is ssl encrypted and I do not think that Google would provide me a copy of their key so I can decrypt that traffic. Log4J, though, can give me most of what I need to figure out what is wrong.

The documentation link makes it sound so simple yet with every new release of Groovy I install, I always forget to do something and it takes me a while to remember how to get it all working again.  The Groovy module HTTPBuilder supports log4j and even provides a sample configuration file to get started. This file should go to the ${groovy.home}/conf/ directory and this is the part that I always overlook. To enable debug logging, change the values of categories org.apache.http.headers and org.apache.http.wire from INFO to DEBUG. When I re-execute the script, I get the following:

2009-12-03 09:39:23,142 DEBUG RESTClient - GET https://feedburner.google.com/api/awareness/1.0/GetFeedData?uri=BloggingTechstacks
2009-12-03 09:39:25,019 DEBUG wire - >> "GET /api/awareness/1.0/GetFeedData?uri=BloggingTechstacks HTTP/1.1[EOL]"
2009-12-03 09:39:25,021 DEBUG wire - >> "Accept: */*[EOL]"
2009-12-03 09:39:25,022 DEBUG wire - >> "Host: feedburner.google.com[EOL]"
2009-12-03 09:39:25,022 DEBUG wire - >> "Connection: Keep-Alive[EOL]"
2009-12-03 09:39:25,022 DEBUG wire - >> "User-Agent: Apache-HttpClient/4.0-beta1 (java 1.4)[EOL]"
2009-12-03 09:39:25,022 DEBUG wire - >> "Accept-Encoding: gzip,deflate[EOL]"
2009-12-03 09:39:25,023 DEBUG wire - >> "[EOL]"
2009-12-03 09:39:25,023 DEBUG headers - >> GET /api/awareness/1.0/GetFeedData?uri=BloggingTechstacks HTTP/1.1
2009-12-03 09:39:25,023 DEBUG headers - >> Accept: */*
2009-12-03 09:39:25,023 DEBUG headers - >> Host: feedburner.google.com
2009-12-03 09:39:25,024 DEBUG headers - >> Connection: Keep-Alive
2009-12-03 09:39:25,024 DEBUG headers - >> User-Agent: Apache-HttpClient/4.0-beta1 (java 1.4)
2009-12-03 09:39:25,024 DEBUG headers - >> Accept-Encoding: gzip,deflate
2009-12-03 09:39:25,084 DEBUG wire - << "HTTP/1.1 200 OK[EOL]"
2009-12-03 09:39:25,087 DEBUG wire - << "Content-Type: application/xml; charset=utf-8[EOL]"
2009-12-03 09:39:25,087 DEBUG wire - << "Date: Thu, 03 Dec 2009 14:39:24 GMT[EOL]"
2009-12-03 09:39:25,087 DEBUG wire - << "Expires: Thu, 03 Dec 2009 14:39:24 GMT[EOL]"
2009-12-03 09:39:25,087 DEBUG wire - << "Cache-Control: private, max-age=0[EOL]"
2009-12-03 09:39:25,087 DEBUG wire - << "X-Content-Type-Options: nosniff[EOL]"
2009-12-03 09:39:25,087 DEBUG wire - << "X-XSS-Protection: 0[EOL]"
2009-12-03 09:39:25,087 DEBUG wire - << "X-Frame-Options: SAMEORIGIN[EOL]"
2009-12-03 09:39:25,087 DEBUG wire - << "Content-Length: 366[EOL]"
2009-12-03 09:39:25,087 DEBUG wire - << "Server: GFE/2.0[EOL]"
2009-12-03 09:39:25,088 DEBUG headers - << HTTP/1.1 200 OK
2009-12-03 09:39:25,088 DEBUG headers - << Content-Type: application/xml; charset=utf-8
2009-12-03 09:39:25,088 DEBUG headers - << Date: Thu, 03 Dec 2009 14:39:24 GMT
2009-12-03 09:39:25,088 DEBUG headers - << Expires: Thu, 03 Dec 2009 14:39:24 GMT
2009-12-03 09:39:25,088 DEBUG headers - << Cache-Control: private, max-age=0
2009-12-03 09:39:25,088 DEBUG headers - << X-Content-Type-Options: nosniff
2009-12-03 09:39:25,088 DEBUG headers - << X-XSS-Protection: 0
2009-12-03 09:39:25,089 DEBUG headers - << X-Frame-Options: SAMEORIGIN
2009-12-03 09:39:25,089 DEBUG headers - << Content-Length: 366
2009-12-03 09:39:25,089 DEBUG headers - << Server: GFE/2.0
2009-12-03 09:39:25,094 DEBUG RESTClient - Response code: 200; found handler: org.codehaus.groovy.runtime.MethodClosure@24bb6086
2009-12-03 09:39:25,096 DEBUG RESTClient - Parsing response as: application/xml
2009-12-03 09:39:25,104 DEBUG wire - << "[\r][\n]"
2009-12-03 09:39:25,104 DEBUG wire - << "[\r][\n]"
2009-12-03 09:39:25,105 DEBUG wire - << " [\r][\n]"
2009-12-03 09:39:25,105 DEBUG wire - << " [\r][\n]"
2009-12-03 09:39:25,105 DEBUG wire - << "  [\r][\n]"
2009-12-03 09:39:25,106 DEBUG wire - << " [\r][\n]"
2009-12-03 09:39:25,106 DEBUG wire - << "[\r][\n]"
2009-12-03 09:39:25,106 DEBUG wire - << "[\r][\n]"
2009-12-03 09:39:25,129 DEBUG RESTClient - Parsed data to instance of: class groovy.util.slurpersupport.NodeChild

My problem is right there in the first line of the log output. My dates argument is not getting passed in the request URI.

As an aside, to include SSL debug output within the console log, (in order to troubleshoot those "unrecognized certificate" issues, for example), add the -Djava.net.debug=ssl statement to the script's startup properties, right after the shebang.


Dynamically Updating Log Levels in JBoss

One of the nice things in JBoss that I find useful is that logging is all based around Log4J. One of the nice things about Log4J is that logging levels can be set dynamically without requiring a restart of the JBoss container. If you are having troubles with your app server and need to get some more information out of your logs while a problem is going on, you have a couple of options available to update your logging levels.

The "edit in vim" option

"Out of the box", the Log4J Service built into the JBoss app server periodically checks the log4j.xml file for changes. If you have access to this file, one way to update the logging level is to directly edit the file. By default, the jboss-log4j.xml is checked every 60 seconds so if you change the logging level for a particular logger to "DEBUG", you only have to wait, at most, 60 seconds for your logs to start dumping a ton of info. (Just don't forget to change it back when you're done or you risk running out of disk space). Just for laughs, tail your server.log and then open up jboss-log4j.xml on a test box from within your jboss server instances's conf directory. Move down to the org.apache logger, which is set to "INFO" by default. Change that to "DEBUG", save (but don't quit) jboss-log4j.xml, and watch what happens in your server.log. After some period of time, the following messages will show up in your server.log:

2009-03-22 10:13:32,193 DEBUG [org.jboss.logging.Log4jService$URLWatchTimerTask] (Timer-Log4jService) Configuring from URL: resource:jboss-log4j.xml
2009-03-22 10:13:32,193 DEBUG [org.jboss.logging.Log4jService] (Timer-Log4jService) Removed System.out adapter
2009-03-22 10:13:32,193 DEBUG [org.jboss.logging.Log4jService] (Timer-Log4jService) Removed System.err adapter
2009-03-22 10:13:32,202 DEBUG [org.jboss.logging.Log4jService] (Timer-Log4jService) Installed System.out adapter
2009-03-22 10:13:32,202 DEBUG [org.jboss.logging.Log4jService] (Timer-Log4jService) Installed System.err adapter

Send a request off to the root of your jboss app server and you'll see information related to set up and tearing down of sessions. Set your logging level for org.apache back to "INFO", send another request off to the jboss app server root, and nothing is logged.

Using the "edit in VIM" approach to setting log levels has one advantage over the jmx-console approach for new or intermediate level jboss administrators: You can see what loggers are already configured and you can create new loggers very easily—just add them. The disadvantage here is that you need to wait from 1 to 60 seconds for JBoss to reconfigure. If you're using a test or a development box, waiting isn't all that big a deal but if you are trying to troubleshoot a production problem during conference calls with your peers and management, 60 seconds can be an eternity.

This approach also has the disadvantage that you are actually modifying one of your production server's configuration files, which you then need to remember to back out unless you want all your changes to be permanent.

The "change it in the jmx-console" option

If you use the JMX-Console, which is also built into JBoss, you can also change the logging level at runtime by invoking the setLoggerLevel() operation, plug in the logger and level you want to modify, and you're off and running. You can reach it by accessing your jmx-console, then clicking jboss.system. The first entry in a default jboss installation is: service=Logging,type=Log4jService Click that link and you will be given a page that lists current settings for your log4j installation and methods you can invoke to get or set logger levels. getLoggerLevel will return the current level for the logger you are interested in. Enter 'org.apache' in the text box for the getLoggerLevel operation, click the Invoke button and you should see "INFO" returned in the browser. Click the "Back to MBean" button. In the text box for setLoggerLevel, enter 'org.apache' for the logger and enter DEBUG for the level and click Invoke. You are now in Debug logging mode for all org.apache.* components. Return to the MBean if you want to change the logging level back to INFO. If you do not want to wait up to 60 seconds for jboss to re-read the configuration, simply invoke the reconfigure operation and you will commit those changes right away.

The jmx-console approach's main disadvantage, in my opinion, is that you can't list the current loggers so if you don't know the name of the logger you want to modify, you have to open jboss-log4j.xml. Another disadvantage to the jmx-console approach is that if your app server is out of threads, memory, etc., then you aren't going to be able to invoke any jmx operations either. One advantage outside of 'script-ability' is that any changes you make in the jmx-console are retained only for as long as this jboss instance is running. If you stop jboss, then restart, you will begin fresh with your standard settings.

As I am just delving into this, if anyone else out there has additional information or other options that they would like to share, that would be great!