Profile selection logging example

logback.xml

<?xml version="1.0" encoding="UTF-8"?>
<!-- This file redacted down to the configuration of the new appender and loggers to produce the above. -->
...
<configuration scan="true" scanPeriod="30 seconds">
  <contextName>uPortal</contextName>
 
  <contextListener class="ch.qos.logback.classic.jul.LevelChangePropagator">
    <resetJUL>true</resetJUL>
  </contextListener>
  
  <jmxConfigurator />
  
  <appender name="PORTAL" class="ch.qos.logback.core.rolling.RollingFileAppender">
    ...
  </appender>
  
  <!-- Example of adding appender to produce the log. -->
    <appender name="BRANCHING" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <!--See http://logback.qos.ch/manual/appenders.html#RollingFileAppender-->
    <!--and http://logback.qos.ch/manual/appenders.html#TimeBasedRollingPolicy-->
    <!--for further documentation-->
    <File>${catalina.base}/logs/portal/branching.log</File>
    <encoder>
      <pattern>%-5level [%thread] %logger{36} %d{ISO8601} - %msg%n</pattern>
    </encoder>
    <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
      <fileNamePattern>${catalina.base}/logs/portal/branching.log.%d{yyyy-MM-dd-HH}</fileNamePattern>
    </rollingPolicy>
  </appender>

  <appender name="EVENT" class="ch.qos.logback.core.rolling.RollingFileAppender">
    ...
  </appender>
  
  ...
  
  <root level="INFO">
    <appender-ref ref="PORTAL"/>
  </root>
  
  ...
  
  <logger name="org.jasig.portal.rendering.BranchingRenderingPipeline" level="TRACE">
    <appender-ref ref="BRANCHING"/>
  </logger>
  
  <logger name="org.jasig.portal.rendering.RedirectRenderingPipelineTerminator" level="TRACE">
    <appender-ref ref="BRANCHING"/>
  </logger>
  
  <logger name="org.jasig.portal.rendering.predicates" level="TRACE">
    <appender-ref ref="BRANCHING"/>
  </logger>
  
      <logger name="org.jasig.portal.url.UrlCanonicalizingFilter" additivity="false" level="TRACE">
        <appender-ref ref="BRANCHING"/>
    </logger>

    <logger name="org.jasig.portal.layout.ChainingProfileMapperImpl" additivity="false" level="TRACE">
        <appender-ref ref="BRANCHING"/>
    </logger>

    <logger name="org.jasig.portal.layout.SessionAttributeProfileMapperImpl" additivity="false" level="TRACE">
        <appender-ref ref="BRANCHING"/>
    </logger>
    
        <logger name="org.jasig.portal.spring.security.preauth" level="TRACE">
        <appender-ref ref="BRANCHING" />
    </logger>

    <logger name="org.jasig.portal.security.mvc" level="TRACE">
        <appender-ref ref="BRANCHING" />
    </logger>
  
</configuration>

output.log

# 
# This logging example no longer exactly represents the logging produced 
# by the logging changes in https://github.com/Jasig/uPortal/pull/437 
# since some of the toString()s relied upon have changed to use 
# ToStringBuilder's more terse representation.


DEBUG [http-bio-8080-exec-9-admin] o.j.p.s.s.p.PortalPreAuthenticatedProcessingFilter 2014-10-14 11:53:27,229 - Path [/Login] is loginPath, so cleared security context so we can re-establish it once the new session is established.
DEBUG [http-bio-8080-exec-9-admin] o.j.p.s.s.p.PortalPreAuthenticatedProcessingFilter 2014-10-14 11:53:27,229 - doPortalAuthentication for valid requested session id 9BEBF79C677D4A75E72E55613EC12979
DEBUG [http-bio-8080-exec-9-admin] o.j.p.s.s.p.PortalPreAuthenticatedProcessingFilter 2014-10-14 11:53:27,229 - Invalidating the impersonated session in un-swapping.
TRACE [http-bio-8080-exec-9-admin] o.j.p.l.SessionAttributeProfileMapperImpl 2014-10-14 11:53:27,231 - Stored desired profile key [respondr] into session (at attribute [profileKey]).
TRACE [http-bio-8080-exec-9-admin] o.j.p.l.ChainingProfileMapperImpl 2014-10-14 11:53:27,236 - Choosing profile for user 'guest';  stickySelection=false
DEBUG [http-bio-8080-exec-9-admin] o.j.p.l.SessionAttributeProfileMapperImpl 2014-10-14 11:53:27,236 - The stored requested profile key respondr mapped to profile fname respondr.
DEBUG [http-bio-8080-exec-9-admin] o.j.p.l.ChainingProfileMapperImpl 2014-10-14 11:53:27,236 - Profile mapper SessionAttributeProfileMapper which considers session attribute [profileKey] as key to mappings [{desktop=default, mobile=mobileDefault, universality=universality, respondr=respondr}], falling back on default [null] . found profile fname=respondr
DEBUG [http-bio-8080-exec-9-admin] o.j.p.security.mvc.LoginController 2014-10-14 11:53:27,345 - Redirecting to /uPortal/f/welcome/normal/render.uP
TRACE [http-bio-8080-exec-9-guest] o.j.p.s.s.p.PortalPreAuthenticatedProcessingFilter 2014-10-14 11:53:27,349 - Path [/f] is neither a login nor a logout path, so no uPortal-custom filtering.
DEBUG [http-bio-8080-exec-9-guest] o.j.p.s.s.p.PortalPreAuthenticatedProcessingFilter 2014-10-14 11:53:27,349 - Checking secure context token: null
DEBUG [http-bio-8080-exec-9-guest] o.j.p.s.s.p.PortalPreAuthenticatedProcessingFilter 2014-10-14 11:53:27,349 - preAuthenticatedPrincipal = UserDetails for user guest, trying to authenticate
DEBUG [http-bio-8080-exec-9-guest] o.j.p.s.s.p.PortalPreAuthenticatedProcessingFilter 2014-10-14 11:53:27,349 - Authentication success: org.springframework.security.web.authentication.preauth.PreAuthenticatedAuthenticationToken@56e5c318: Principal: UserDetails for user guest; Credentials: [PROTECTED]; Authenticated: true; Details: org.springframework.security.web.authentication.WebAuthenticationDetails@fffe9938: RemoteIpAddress: 0:0:0:0:0:0:0:1; SessionId: 9BEBF79C677D4A75E72E55613EC12979; Not granted any authorities
TRACE [http-bio-8080-exec-9-guest] o.j.p.url.UrlCanonicalizingFilter 2014-10-14 11:53:27,351 - Requested URI /uPortal/f/welcome/normal/render.uP is the canonical URL /uPortal/f/welcome/normal/render.uP, so no (further?) redirect is necessary (after 0 redirects).
TRACE [http-bio-8080-exec-9-guest] o.j.p.s.s.p.PortalPreAuthenticatedProcessingFilter 2014-10-14 11:53:28,353 - Path [/f] is neither a login nor a logout path, so no uPortal-custom filtering.
DEBUG [http-bio-8080-exec-9-guest] o.j.p.s.s.p.PortalPreAuthenticatedProcessingFilter 2014-10-14 11:53:28,353 - Checking secure context token: org.springframework.security.web.authentication.preauth.PreAuthenticatedAuthenticationToken@56e5c318: Principal: UserDetails for user guest; Credentials: [PROTECTED]; Authenticated: true; Details: org.springframework.security.web.authentication.WebAuthenticationDetails@fffe9938: RemoteIpAddress: 0:0:0:0:0:0:0:1; SessionId: 9BEBF79C677D4A75E72E55613EC12979; Not granted any authorities
TRACE [http-bio-8080-exec-9-guest] o.j.p.s.s.p.PortalPreAuthenticatedProcessingFilter 2014-10-14 11:53:28,384 - Path [/f] is neither a login nor a logout path, so no uPortal-custom filtering.
DEBUG [http-bio-8080-exec-9-guest] o.j.p.s.s.p.PortalPreAuthenticatedProcessingFilter 2014-10-14 11:53:28,385 - Checking secure context token: org.springframework.security.web.authentication.preauth.PreAuthenticatedAuthenticationToken@56e5c318: Principal: UserDetails for user guest; Credentials: [PROTECTED]; Authenticated: true; Details: org.springframework.security.web.authentication.WebAuthenticationDetails@fffe9938: RemoteIpAddress: 0:0:0:0:0:0:0:1; SessionId: 9BEBF79C677D4A75E72E55613EC12979; Not granted any authorities
 Marker - Oct 14, 2014, 11:53:36 AM
DEBUG [http-bio-8080-exec-1-guest] o.j.p.s.s.p.PortalPreAuthenticatedProcessingFilter 2014-10-14 11:53:48,095 - Path [/Login] is loginPath, so cleared security context so we can re-establish it once the new session is established.
DEBUG [http-bio-8080-exec-1-guest] o.j.p.s.s.p.PortalPreAuthenticatedProcessingFilter 2014-10-14 11:53:48,095 - doPortalAuthentication for valid requested session id 9BEBF79C677D4A75E72E55613EC12979
DEBUG [http-bio-8080-exec-1-guest] o.j.p.s.s.p.PortalPreAuthenticatedProcessingFilter 2014-10-14 11:53:48,095 - Invalidating the impersonated session in un-swapping.
TRACE [http-bio-8080-exec-1-guest] o.j.p.l.SessionAttributeProfileMapperImpl 2014-10-14 11:53:48,096 - Stored desired profile key [universality] into session (at attribute [profileKey]).
TRACE [http-bio-8080-exec-1-guest] o.j.p.l.ChainingProfileMapperImpl 2014-10-14 11:53:48,104 - Choosing profile for user 'guest';  stickySelection=false
DEBUG [http-bio-8080-exec-1-guest] o.j.p.l.SessionAttributeProfileMapperImpl 2014-10-14 11:53:48,104 - The stored requested profile key universality mapped to profile fname universality.
DEBUG [http-bio-8080-exec-1-guest] o.j.p.l.ChainingProfileMapperImpl 2014-10-14 11:53:48,104 - Profile mapper SessionAttributeProfileMapper which considers session attribute [profileKey] as key to mappings [{desktop=default, mobile=mobileDefault, universality=universality, respondr=respondr}], falling back on default [null] . found profile fname=universality
DEBUG [http-bio-8080-exec-1-guest] o.j.p.security.mvc.LoginController 2014-10-14 11:53:48,183 - Redirecting to /uPortal/f/welcome/normal/render.uP
TRACE [http-bio-8080-exec-1-guest] o.j.p.s.s.p.PortalPreAuthenticatedProcessingFilter 2014-10-14 11:53:48,187 - Path [/f] is neither a login nor a logout path, so no uPortal-custom filtering.
DEBUG [http-bio-8080-exec-1-guest] o.j.p.s.s.p.PortalPreAuthenticatedProcessingFilter 2014-10-14 11:53:48,187 - Checking secure context token: null
DEBUG [http-bio-8080-exec-1-guest] o.j.p.s.s.p.PortalPreAuthenticatedProcessingFilter 2014-10-14 11:53:48,187 - preAuthenticatedPrincipal = UserDetails for user guest, trying to authenticate
DEBUG [http-bio-8080-exec-1-guest] o.j.p.s.s.p.PortalPreAuthenticatedProcessingFilter 2014-10-14 11:53:48,187 - Authentication success: org.springframework.security.web.authentication.preauth.PreAuthenticatedAuthenticationToken@7cf71139: Principal: UserDetails for user guest; Credentials: [PROTECTED]; Authenticated: true; Details: org.springframework.security.web.authentication.WebAuthenticationDetails@fffe9938: RemoteIpAddress: 0:0:0:0:0:0:0:1; SessionId: 9BEBF79C677D4A75E72E55613EC12979; Not granted any authorities
TRACE [http-bio-8080-exec-1-guest] o.j.p.url.UrlCanonicalizingFilter 2014-10-14 11:53:48,189 - Requested URI /uPortal/f/welcome/normal/render.uP is the canonical URL /uPortal/f/welcome/normal/render.uP, so no (further?) redirect is necessary (after 0 redirects).
TRACE [http-bio-8080-exec-5-guest] o.j.p.s.s.p.PortalPreAuthenticatedProcessingFilter 2014-10-14 11:53:48,699 - Path [/media/skins/universality/common/css/D0hrM4yyd63czb_-GWgBrw.aggr.min.css] is neither a login nor a logout path, so no uPortal-custom filtering.
DEBUG [http-bio-8080-exec-5-guest] o.j.p.s.s.p.PortalPreAuthenticatedProcessingFilter 2014-10-14 11:53:48,700 - Checking secure context token: org.springframework.security.web.authentication.preauth.PreAuthenticatedAuthenticationToken@7cf71139: Principal: UserDetails for user guest; Credentials: [PROTECTED]; Authenticated: true; Details: org.springframework.security.web.authentication.WebAuthenticationDetails@fffe9938: RemoteIpAddress: 0:0:0:0:0:0:0:1; SessionId: 9BEBF79C677D4A75E72E55613EC12979; Not granted any authorities
TRACE [http-bio-8080-exec-8-guest] o.j.p.s.s.p.PortalPreAuthenticatedProcessingFilter 2014-10-14 11:53:48,711 - Path [/media/skins/universality/uportal3/zrELrFhXfrreRierud3Qdg.aggr.min.css] is neither a login nor a logout path, so no uPortal-custom filtering.
DEBUG [http-bio-8080-exec-8-guest] o.j.p.s.s.p.PortalPreAuthenticatedProcessingFilter 2014-10-14 11:53:48,711 - Checking secure context token: org.springframework.security.web.authentication.preauth.PreAuthenticatedAuthenticationToken@7cf71139: Principal: UserDetails for user guest; Credentials: [PROTECTED]; Authenticated: true; Details: org.springframework.security.web.authentication.WebAuthenticationDetails@fffe9938: RemoteIpAddress: 0:0:0:0:0:0:0:1; SessionId: 9BEBF79C677D4A75E72E55613EC12979; Not granted any authorities
TRACE [http-bio-8080-exec-9-guest] o.j.p.s.s.p.PortalPreAuthenticatedProcessingFilter 2014-10-14 11:53:48,711 - Path [/media/skins/universality/common/javascript/LS5PMt3NEOSwqTv834RKWA.aggr.min.js] is neither a login nor a logout path, so no uPortal-custom filtering.
DEBUG [http-bio-8080-exec-9-guest] o.j.p.s.s.p.PortalPreAuthenticatedProcessingFilter 2014-10-14 11:53:48,711 - Checking secure context token: org.springframework.security.web.authentication.preauth.PreAuthenticatedAuthenticationToken@7cf71139: Principal: UserDetails for user guest; Credentials: [PROTECTED]; Authenticated: true; Details: org.springframework.security.web.authentication.WebAuthenticationDetails@fffe9938: RemoteIpAddress: 0:0:0:0:0:0:0:1; SessionId: 9BEBF79C677D4A75E72E55613EC12979; Not granted any authorities
TRACE [http-bio-8080-exec-8-guest] o.j.p.s.s.p.PortalPreAuthenticatedProcessingFilter 2014-10-14 11:53:48,727 - Path [/media/skins/universality/uportal3/images/portal_logo.png] is neither a login nor a logout path, so no uPortal-custom filtering.
DEBUG [http-bio-8080-exec-8-guest] o.j.p.s.s.p.PortalPreAuthenticatedProcessingFilter 2014-10-14 11:53:48,727 - Checking secure context token: org.springframework.security.web.authentication.preauth.PreAuthenticatedAuthenticationToken@7cf71139: Principal: UserDetails for user guest; Credentials: [PROTECTED]; Authenticated: true; Details: org.springframework.security.web.authentication.WebAuthenticationDetails@fffe9938: RemoteIpAddress: 0:0:0:0:0:0:0:1; SessionId: 9BEBF79C677D4A75E72E55613EC12979; Not granted any authorities
TRACE [http-bio-8080-exec-8-guest] o.j.p.s.s.p.PortalPreAuthenticatedProcessingFilter 2014-10-14 11:53:49,255 - Path [/media/skins/universality/uportal3/images/portal_poweredby.png] is neither a login nor a logout path, so no uPortal-custom filtering.
DEBUG [http-bio-8080-exec-8-guest] o.j.p.s.s.p.PortalPreAuthenticatedProcessingFilter 2014-10-14 11:53:49,255 - Checking secure context token: org.springframework.security.web.authentication.preauth.PreAuthenticatedAuthenticationToken@7cf71139: Principal: UserDetails for user guest; Credentials: [PROTECTED]; Authenticated: true; Details: org.springframework.security.web.authentication.WebAuthenticationDetails@fffe9938: RemoteIpAddress: 0:0:0:0:0:0:0:1; SessionId: 9BEBF79C677D4A75E72E55613EC12979; Not granted any authorities
TRACE [http-bio-8080-exec-9-guest] o.j.p.s.s.p.PortalPreAuthenticatedProcessingFilter 2014-10-14 11:53:49,258 - Path [/media/skins/universality/common/images/portlet_icons_flat.png] is neither a login nor a logout path, so no uPortal-custom filtering.
DEBUG [http-bio-8080-exec-9-guest] o.j.p.s.s.p.PortalPreAuthenticatedProcessingFilter 2014-10-14 11:53:49,258 - Checking secure context token: org.springframework.security.web.authentication.preauth.PreAuthenticatedAuthenticationToken@7cf71139: Principal: UserDetails for user guest; Credentials: [PROTECTED]; Authenticated: true; Details: org.springframework.security.web.authentication.WebAuthenticationDetails@fffe9938: RemoteIpAddress: 0:0:0:0:0:0:0:1; SessionId: 9BEBF79C677D4A75E72E55613EC12979; Not granted any authorities
TRACE [http-bio-8080-exec-9-guest] o.j.p.s.s.p.PortalPreAuthenticatedProcessingFilter 2014-10-14 11:53:49,343 - Path [/f] is neither a login nor a logout path, so no uPortal-custom filtering.
DEBUG [http-bio-8080-exec-9-guest] o.j.p.s.s.p.PortalPreAuthenticatedProcessingFilter 2014-10-14 11:53:49,343 - Checking secure context token: org.springframework.security.web.authentication.preauth.PreAuthenticatedAuthenticationToken@7cf71139: Principal: UserDetails for user guest; Credentials: [PROTECTED]; Authenticated: true; Details: org.springframework.security.web.authentication.WebAuthenticationDetails@fffe9938: RemoteIpAddress: 0:0:0:0:0:0:0:1; SessionId: 9BEBF79C677D4A75E72E55613EC12979; Not granted any authorities