From da7e9c67d8806fd42c57c2eee12ab64f5e8cb5d5 Mon Sep 17 00:00:00 2001 From: Sebastian Sdorra Date: Thu, 28 Jun 2012 10:55:55 +0200 Subject: [PATCH 1/5] improve trace logging for authentication --- .../web/filter/BasicAuthenticationFilter.java | 32 +++++++++++++++++++ .../scm/web/filter/PermissionFilter.java | 9 ++++++ .../web/security/BasicSecurityContext.java | 7 ++++ .../security/ChainAuthenticatonManager.java | 27 ++++++++++++++++ 4 files changed, 75 insertions(+) diff --git a/scm-core/src/main/java/sonia/scm/web/filter/BasicAuthenticationFilter.java b/scm-core/src/main/java/sonia/scm/web/filter/BasicAuthenticationFilter.java index db33f7f53c..b3fcd1f117 100644 --- a/scm-core/src/main/java/sonia/scm/web/filter/BasicAuthenticationFilter.java +++ b/scm-core/src/main/java/sonia/scm/web/filter/BasicAuthenticationFilter.java @@ -123,15 +123,42 @@ public class BasicAuthenticationFilter extends HttpFilter if (Util.isNotEmpty(authentication) && authentication.toUpperCase().startsWith(AUTHORIZATION_BASIC_PREFIX)) { + if (logger.isTraceEnabled()) + { + logger.trace("found basic authorization header, start authentication"); + } + user = authenticate(request, response, securityContext, authentication); + + if (logger.isTraceEnabled()) + { + if (user != null) + { + logger.trace("user {} successfully authenticated", user.getName()); + } + else + { + logger.trace("authentcation failed, user object is null"); + } + } } else if (securityContext.isAuthenticated()) { + if (logger.isTraceEnabled()) + { + logger.trace("user is allready authenticated"); + } + user = securityContext.getUser(); } if (user == null) { + if (logger.isTraceEnabled()) + { + logger.trace("could not find user send unauthorized"); + } + HttpUtil.sendUnauthorized(response); } else @@ -192,6 +219,11 @@ public class BasicAuthenticationFilter extends HttpFilter if (Util.isNotEmpty(username) && Util.isNotEmpty(password)) { + if (logger.isTraceEnabled()) + { + logger.trace("try to authenticate user {}", username); + } + user = securityContext.authenticate(request, response, username, password); } diff --git a/scm-core/src/main/java/sonia/scm/web/filter/PermissionFilter.java b/scm-core/src/main/java/sonia/scm/web/filter/PermissionFilter.java index a584c821e5..cb361d4437 100644 --- a/scm-core/src/main/java/sonia/scm/web/filter/PermissionFilter.java +++ b/scm-core/src/main/java/sonia/scm/web/filter/PermissionFilter.java @@ -150,6 +150,15 @@ public abstract class PermissionFilter extends HttpFilter if (hasPermission(repository, securityContext, writeRequest)) { + if (logger.isTraceEnabled()) + { + logger.trace("{} access to repository {} for user {} granted", + new Object[] { writeRequest + ? "write" + : "read", repository.getName(), + user.getName() }); + } + chain.doFilter(request, response); } else diff --git a/scm-webapp/src/main/java/sonia/scm/web/security/BasicSecurityContext.java b/scm-webapp/src/main/java/sonia/scm/web/security/BasicSecurityContext.java index f17bb67494..cf1c78f97c 100644 --- a/scm-webapp/src/main/java/sonia/scm/web/security/BasicSecurityContext.java +++ b/scm-webapp/src/main/java/sonia/scm/web/security/BasicSecurityContext.java @@ -124,9 +124,16 @@ public class BasicSecurityContext implements WebSecurityContext HttpServletResponse response, String username, String password) { + if ( logger.isTraceEnabled() ){ + logger.trace("start authentication for user {}", username); + } AuthenticationResult ar = authenticator.authenticate(request, response, username, password); + if ( logger.isTraceEnabled() ){ + logger.trace("authentication ends with {}", ar); + } + if ((ar != null) && (ar.getState() == AuthenticationState.SUCCESS)) { authenticate(request, password, ar); diff --git a/scm-webapp/src/main/java/sonia/scm/web/security/ChainAuthenticatonManager.java b/scm-webapp/src/main/java/sonia/scm/web/security/ChainAuthenticatonManager.java index fcdb2a4d06..2f51ef6cfe 100644 --- a/scm-webapp/src/main/java/sonia/scm/web/security/ChainAuthenticatonManager.java +++ b/scm-webapp/src/main/java/sonia/scm/web/security/ChainAuthenticatonManager.java @@ -130,6 +130,12 @@ public class ChainAuthenticatonManager extends AbstractAuthenticationManager if (ar == null) { + if (logger.isTraceEnabled()) + { + logger.trace("no authentication result for user {} found in cache", + username); + } + ar = doAuthentication(request, response, username, password); if ((ar != null) && ar.isCacheable()) @@ -157,6 +163,11 @@ public class ChainAuthenticatonManager extends AbstractAuthenticationManager { for (AuthenticationHandler authenticator : authenticationHandlerSet) { + if (logger.isTraceEnabled()) + { + logger.trace("close authenticator {}", authenticator.getClass()); + } + IOUtil.close(authenticator); } } @@ -172,6 +183,11 @@ public class ChainAuthenticatonManager extends AbstractAuthenticationManager { for (AuthenticationHandler authenticator : authenticationHandlerSet) { + if (logger.isTraceEnabled()) + { + logger.trace("initialize authenticator {}", authenticator.getClass()); + } + authenticator.init(context); } @@ -200,8 +216,19 @@ public class ChainAuthenticatonManager extends AbstractAuthenticationManager { AuthenticationResult ar = null; + if (logger.isTraceEnabled()) + { + logger.trace("start authentication chain for user {}", username); + } + for (AuthenticationHandler authenticator : authenticationHandlerSet) { + if (logger.isTraceEnabled()) + { + logger.trace("check authenticator {} for user {}", + authenticator.getClass(), username); + } + try { AuthenticationResult result = authenticator.authenticate(request, From 718938db776129c20d1caa42ca699df0f4e953a2 Mon Sep 17 00:00:00 2001 From: Sebastian Sdorra Date: Thu, 28 Jun 2012 12:28:06 +0200 Subject: [PATCH 2/5] added switch for http debug logging --- scm-webapp/src/main/java/sonia/scm/ScmServletModule.java | 9 +++++++++ 1 file changed, 9 insertions(+) diff --git a/scm-webapp/src/main/java/sonia/scm/ScmServletModule.java b/scm-webapp/src/main/java/sonia/scm/ScmServletModule.java index 8c9847746e..1da04efe6e 100644 --- a/scm-webapp/src/main/java/sonia/scm/ScmServletModule.java +++ b/scm-webapp/src/main/java/sonia/scm/ScmServletModule.java @@ -101,6 +101,7 @@ import sonia.scm.util.DebugServlet; import sonia.scm.util.ScmConfigurationUtil; import sonia.scm.web.cgi.CGIExecutorFactory; import sonia.scm.web.cgi.DefaultCGIExecutorFactory; +import sonia.scm.web.filter.LoggingFilter; import sonia.scm.web.security.AdministrationContext; import sonia.scm.web.security.ApiBasicAuthenticationFilter; import sonia.scm.web.security.AuthenticationManager; @@ -172,6 +173,9 @@ public class ScmServletModule extends ServletModule /** Field description */ public static final String REST_PACKAGE = "sonia.scm.api.rest"; + /** Field description */ + public static final String SYSTEM_PROPERTY_DEBUG_HTTP = "scm.debug.http"; + /** Field description */ public static final String[] PATTERN_STATIC_RESOURCES = new String[] { PATTERN_SCRIPT, @@ -299,6 +303,11 @@ public class ScmServletModule extends ServletModule Names.named(UrlProviderFactory.TYPE_WUI)).toProvider( WebUIUrlProvider.class); + if ("true".equalsIgnoreCase(System.getProperty(SYSTEM_PROPERTY_DEBUG_HTTP))) + { + filter(PATTERN_ALL).through(LoggingFilter.class); + } + /* * filter(PATTERN_PAGE, * PATTERN_STATIC_RESOURCES).through(StaticResourceFilter.class); From 1cdf666c718be7cdfafbb4a266c8870a5058cdd4 Mon Sep 17 00:00:00 2001 From: Sebastian Sdorra Date: Thu, 28 Jun 2012 12:49:09 +0200 Subject: [PATCH 3/5] log only text body --- .../sonia/scm/web/filter/LoggingFilter.java | 78 +++++++++++++++---- 1 file changed, 65 insertions(+), 13 deletions(-) diff --git a/scm-core/src/main/java/sonia/scm/web/filter/LoggingFilter.java b/scm-core/src/main/java/sonia/scm/web/filter/LoggingFilter.java index 6b3e62695e..ae7995a574 100644 --- a/scm-core/src/main/java/sonia/scm/web/filter/LoggingFilter.java +++ b/scm-core/src/main/java/sonia/scm/web/filter/LoggingFilter.java @@ -35,6 +35,7 @@ package sonia.scm.web.filter; //~--- non-JDK imports -------------------------------------------------------- +import com.google.common.base.Strings; import com.google.inject.Singleton; import org.slf4j.Logger; @@ -89,7 +90,7 @@ public class LoggingFilter extends HttpFilter { if (logger.isDebugEnabled()) { - boolean logBody = logger.isTraceEnabled(); + boolean logBody = logger.isTraceEnabled() && isTextRequest(request); BufferedHttpServletRequest bufferedRequest = new BufferedHttpServletRequest(request, logBody); BufferedHttpServletResponse bufferedResponse = @@ -189,7 +190,12 @@ public class LoggingFilter extends HttpFilter if (logger.isTraceEnabled()) { - logger.trace("Content: ".concat(new String(request.getContentBuffer()))); + byte[] contentBuffer = request.getContentBuffer(); + + if ((contentBuffer != null) && (contentBuffer.length > 0)) + { + logger.trace("Content: ".concat(new String(contentBuffer))); + } } } @@ -227,22 +233,68 @@ public class LoggingFilter extends HttpFilter logger.debug("Header: {} = {}", header.getKey(), header.getValue()); } - if (logger.isTraceEnabled()) + if (logger.isTraceEnabled() && isTextRequest(orgResponse)) { byte[] content = response.getContentBuffer(); - ServletOutputStream out = null; - try + if ((content != null) && (content.length > 0)) { - out = orgResponse.getOutputStream(); - out.write(content); - } - finally - { - out.close(); - } + ServletOutputStream out = null; - logger.trace("Content: ".concat(new String(content))); + try + { + out = orgResponse.getOutputStream(); + out.write(content); + } + finally + { + out.close(); + } + + logger.trace("Content: ".concat(new String(content))); + } } } + + //~--- get methods ---------------------------------------------------------- + + /** + * Method description + * + * + * @param request + * + * @return + */ + private boolean isTextRequest(HttpServletRequest request) + { + return isTextRequest(request.getContentType()); + } + + /** + * Method description + * + * + * @param response + * + * @return + */ + private boolean isTextRequest(HttpServletResponse response) + { + return isTextRequest(response.getContentType()); + } + + /** + * Method description + * + * + * @param contentType + * + * @return + */ + private boolean isTextRequest(String contentType) + { + return !Strings.isNullOrEmpty(contentType) + && contentType.toLowerCase().startsWith("text"); + } } From a8b3b3bb277fd7f9cdb989bd71a03f5beaa336cf Mon Sep 17 00:00:00 2001 From: Sebastian Sdorra Date: Thu, 28 Jun 2012 14:54:44 +0200 Subject: [PATCH 4/5] fix basic authentication for systems with turkish locale --- .../src/main/java/sonia/scm/util/Util.java | 18 ++++++++++++++++++ .../web/filter/BasicAuthenticationFilter.java | 3 +-- 2 files changed, 19 insertions(+), 2 deletions(-) diff --git a/scm-core/src/main/java/sonia/scm/util/Util.java b/scm-core/src/main/java/sonia/scm/util/Util.java index e8e9cadc3b..bfa109f4ec 100644 --- a/scm-core/src/main/java/sonia/scm/util/Util.java +++ b/scm-core/src/main/java/sonia/scm/util/Util.java @@ -47,6 +47,7 @@ import java.util.Comparator; import java.util.Date; import java.util.Iterator; import java.util.List; +import java.util.Locale; import java.util.Map; import java.util.TimeZone; @@ -398,6 +399,23 @@ public class Util return parseDate(dateString, null); } + /** + * Method description + * + * + * @param value + * @param start + * + * @return + * + * @since 1.17 + */ + public static boolean startWithIgnoreCase(String value, String start) + { + return (value != null) && (start != null) + && value.toUpperCase(Locale.ENGLISH).startsWith(start); + } + /** * Method description * diff --git a/scm-core/src/main/java/sonia/scm/web/filter/BasicAuthenticationFilter.java b/scm-core/src/main/java/sonia/scm/web/filter/BasicAuthenticationFilter.java index b3fcd1f117..386f27bcd3 100644 --- a/scm-core/src/main/java/sonia/scm/web/filter/BasicAuthenticationFilter.java +++ b/scm-core/src/main/java/sonia/scm/web/filter/BasicAuthenticationFilter.java @@ -120,8 +120,7 @@ public class BasicAuthenticationFilter extends HttpFilter User user = null; String authentication = request.getHeader(HEADER_AUTHORIZATION); - if (Util.isNotEmpty(authentication) - && authentication.toUpperCase().startsWith(AUTHORIZATION_BASIC_PREFIX)) + if (Util.startWithIgnoreCase(authentication, AUTHORIZATION_BASIC_PREFIX)) { if (logger.isTraceEnabled()) { From 161d45bdd24e89888f315e0ea19669a463dbae50 Mon Sep 17 00:00:00 2001 From: Sebastian Sdorra Date: Thu, 28 Jun 2012 15:28:43 +0200 Subject: [PATCH 5/5] close branch issue-195