[
https://issues.apache.org/jira/browse/KNOX-757?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15632800#comment-15632800
]
John McParland commented on KNOX-757:
-------------------------------------
== Changes ==
Made the changes on my fork of Knox, branch KNOX-757:
* [Fork|https://github.com/mcparlandjcgi/knox]
* [KNOX-757 Branch|https://github.com/mcparlandjcgi/knox/tree/KNOX-757]
* [Main
commit|https://github.com/mcparlandjcgi/knox/commit/8f6d21c57118a358abcf7ad0bd15cc0d5aee67fa]
== Testing ==
* The gateway-log4j.properties file as installed by default
{code}[knox@sandbox conf]$ pwd
/usr/hdp/current/knox-server/conf
[knox@sandbox conf]$ cat gateway-log4j.properties
# ... License removed for brevity
app.log.dir=${launcher.dir}/../logs
app.log.file=${launcher.name}.log
app.audit.file=${launcher.name}-audit.log
log4j.rootLogger=ERROR, drfa
log4j.logger.org.apache.hadoop.gateway=INFO
#log4j.logger.org.apache.hadoop.gateway=DEBUG
#log4j.logger.org.eclipse.jetty=DEBUG
#log4j.logger.org.apache.shiro=DEBUG
#log4j.logger.org.apache.http=DEBUG
#log4j.logger.org.apache.http.client=DEBUG
#log4j.logger.org.apache.http.headers=DEBUG
#log4j.logger.org.apache.http.wire=DEBUG
# ... Some content removed for brevity
# Apache Shiro Related logging - KNOX-757
#log4j.logger.org.springframework=DEBUG
#log4j.logger.net.sf.ehcache=DEBUG
#log4j.logger.org.apache.shiro.util.ThreadContext=DEBUG{code}
* log output after gateway/sandbox/webhdfs/v1/?op=LISTSTATUS request
{code}2016-11-03 11:50:58,182 INFO hadoop.gateway
(KnoxLdapRealm.java:getUserDn(691)) - Computed userDn:
uid=guest,ou=people,dc=hadoop,dc=apache,dc=org using dnTemplate for principal:
guest{code}
* Gateway log config after enabling shiro properties
{code}# ... License removed for brevity
app.log.dir=${launcher.dir}/../logs
app.log.file=${launcher.name}.log
app.audit.file=${launcher.name}-audit.log
log4j.rootLogger=ERROR, drfa
log4j.logger.org.apache.hadoop.gateway=INFO
#log4j.logger.org.apache.hadoop.gateway=DEBUG
#log4j.logger.org.eclipse.jetty=DEBUG
log4j.logger.org.apache.shiro=DEBUG
#log4j.logger.org.apache.http=DEBUG
#log4j.logger.org.apache.http.client=DEBUG
#log4j.logger.org.apache.http.headers=DEBUG
#log4j.logger.org.apache.http.wire=DEBUG
# .. Content removed for brevity
# Apache Shiro Related logging - KNOX-757
log4j.logger.org.springframework=DEBUG
log4j.logger.net.sf.ehcache=DEBUG
log4j.logger.org.apache.shiro.util.ThreadContext=DEBUG{code}
* Log output after gateway/sandbox/webhdfs/v1/?op=LISTSTATUS request (also
includes some start-up logging)
{code}2016-11-03 13:58:40,483 INFO env.EnvironmentLoader
(EnvironmentLoader.java:initEnvironment(128)) - Starting Shiro environment
initialization.
2016-11-03 13:58:40,514 DEBUG env.IniWebEnvironment
(IniWebEnvironment.java:init(76)) - Checking any specified config locations.
2016-11-03 13:58:40,515 DEBUG env.IniWebEnvironment
(IniWebEnvironment.java:init(81)) - No INI instance or config locations
specified. Trying default config locations.
2016-11-03 13:58:40,534 DEBUG config.Ini (Ini.java:load(342)) - Parsing [main]
2016-11-03 13:58:40,543 DEBUG config.Ini (Ini.java:load(342)) - Parsing [urls]
2016-11-03 13:58:40,545 DEBUG env.IniWebEnvironment
(IniWebEnvironment.java:getDefaultIni(136)) - Discovered non-empty INI
configuration at location '/WEB-INF/shiro.ini'. Using for configuration.
2016-11-03 13:58:40,555 DEBUG config.IniFactorySupport
(IniFactorySupport.java:createInstance(122)) - Creating instance from Ini
[sections=main,urls]
2016-11-03 13:58:40,981 DEBUG config.ReflectionBuilder
(ReflectionBuilder.java:resolveReference(238)) - Encountered object reference
'$ldapContextFactory'. Looking up object with id 'ldapContextFactory'
2016-11-03 13:58:41,019 DEBUG realm.AuthorizingRealm
(AuthorizingRealm.java:getAuthorizationCacheLazy(234)) - No authorizationCache
instance set. Checking for a cacheManager...
2016-11-03 13:58:41,019 INFO realm.AuthorizingRealm
(AuthorizingRealm.java:getAuthorizationCacheLazy(248)) - No cache or
cacheManager properties have been set. Authorization cache cannot be obtained.
2016-11-03 13:58:41,027 DEBUG config.IniFactorySupport
(IniFactorySupport.java:createInstance(122)) - Creating instance from Ini
[sections=main,urls]
2016-11-03 13:58:41,037 DEBUG mgt.DefaultFilterChainManager
(DefaultFilterChainManager.java:createChain(127)) - Creating chain [/**] from
String definition [authcBasic]
2016-11-03 13:58:41,037 DEBUG mgt.DefaultFilterChainManager
(DefaultFilterChainManager.java:applyChainConfig(278)) - Attempting to apply
path [/**] to filter [authcBasic] with config [null]
2016-11-03 13:58:41,038 DEBUG env.EnvironmentLoader
(EnvironmentLoader.java:initEnvironment(136)) - Published WebEnvironment as
ServletContext attribute with name
[org.apache.shiro.web.env.EnvironmentLoader.ENVIRONMENT_ATTRIBUTE_KEY]
2016-11-03 13:58:41,038 INFO env.EnvironmentLoader
(EnvironmentLoader.java:initEnvironment(141)) - Shiro environment initialized
in 554 ms.
2016-11-03 13:58:41,922 INFO env.EnvironmentLoader
(EnvironmentLoader.java:initEnvironment(128)) - Starting Shiro environment
initialization.
2016-11-03 13:58:41,923 DEBUG env.IniWebEnvironment
(IniWebEnvironment.java:init(76)) - Checking any specified config locations.
2016-11-03 13:58:41,924 DEBUG env.IniWebEnvironment
(IniWebEnvironment.java:init(81)) - No INI instance or config locations
specified. Trying default config locations.
2016-11-03 13:58:41,924 DEBUG config.Ini (Ini.java:load(342)) - Parsing [main]
2016-11-03 13:58:41,925 DEBUG config.Ini (Ini.java:load(342)) - Parsing [urls]
2016-11-03 13:58:41,925 DEBUG env.IniWebEnvironment
(IniWebEnvironment.java:getDefaultIni(136)) - Discovered non-empty INI
configuration at location '/WEB-INF/shiro.ini'. Using for configuration.
2016-11-03 13:58:41,925 DEBUG config.IniFactorySupport
(IniFactorySupport.java:createInstance(122)) - Creating instance from Ini
[sections=main,urls]
2016-11-03 13:58:41,933 DEBUG config.ReflectionBuilder
(ReflectionBuilder.java:resolveReference(238)) - Encountered object reference
'$ldapContextFactory'. Looking up object with id 'ldapContextFactory'
2016-11-03 13:58:41,934 DEBUG realm.AuthorizingRealm
(AuthorizingRealm.java:getAuthorizationCacheLazy(234)) - No authorizationCache
instance set. Checking for a cacheManager...
2016-11-03 13:58:41,935 INFO realm.AuthorizingRealm
(AuthorizingRealm.java:getAuthorizationCacheLazy(248)) - No cache or
cacheManager properties have been set. Authorization cache cannot be obtained.
2016-11-03 13:58:41,935 DEBUG config.IniFactorySupport
(IniFactorySupport.java:createInstance(122)) - Creating instance from Ini
[sections=main,urls]
2016-11-03 13:58:41,935 DEBUG mgt.DefaultFilterChainManager
(DefaultFilterChainManager.java:createChain(127)) - Creating chain [/**] from
String definition [authcBasic]
2016-11-03 13:58:41,941 DEBUG mgt.DefaultFilterChainManager
(DefaultFilterChainManager.java:applyChainConfig(278)) - Attempting to apply
path [/**] to filter [authcBasic] with config [null]
2016-11-03 13:58:41,942 DEBUG env.EnvironmentLoader
(EnvironmentLoader.java:initEnvironment(136)) - Published WebEnvironment as
ServletContext attribute with name
[org.apache.shiro.web.env.EnvironmentLoader.ENVIRONMENT_ATTRIBUTE_KEY]
2016-11-03 13:58:41,942 INFO env.EnvironmentLoader
(EnvironmentLoader.java:initEnvironment(141)) - Shiro environment initialized
in 19 ms.
2016-11-03 13:58:42,494 INFO env.EnvironmentLoader
(EnvironmentLoader.java:initEnvironment(128)) - Starting Shiro environment
initialization.
2016-11-03 13:58:42,495 DEBUG env.IniWebEnvironment
(IniWebEnvironment.java:init(76)) - Checking any specified config locations.
2016-11-03 13:58:42,495 DEBUG env.IniWebEnvironment
(IniWebEnvironment.java:init(81)) - No INI instance or config locations
specified. Trying default config locations.
2016-11-03 13:58:42,502 DEBUG config.Ini (Ini.java:load(342)) - Parsing [main]
2016-11-03 13:58:42,502 DEBUG config.Ini (Ini.java:load(342)) - Parsing [urls]
2016-11-03 13:58:42,503 DEBUG env.IniWebEnvironment
(IniWebEnvironment.java:getDefaultIni(136)) - Discovered non-empty INI
configuration at location '/WEB-INF/shiro.ini'. Using for configuration.
2016-11-03 13:58:42,503 DEBUG config.IniFactorySupport
(IniFactorySupport.java:createInstance(122)) - Creating instance from Ini
[sections=main,urls]
2016-11-03 13:58:42,504 DEBUG config.ReflectionBuilder
(ReflectionBuilder.java:resolveReference(238)) - Encountered object reference
'$ldapContextFactory'. Looking up object with id 'ldapContextFactory'
2016-11-03 13:58:42,505 DEBUG realm.AuthorizingRealm
(AuthorizingRealm.java:getAuthorizationCacheLazy(234)) - No authorizationCache
instance set. Checking for a cacheManager...
2016-11-03 13:58:42,521 INFO realm.AuthorizingRealm
(AuthorizingRealm.java:getAuthorizationCacheLazy(248)) - No cache or
cacheManager properties have been set. Authorization cache cannot be obtained.
2016-11-03 13:58:42,522 DEBUG config.IniFactorySupport
(IniFactorySupport.java:createInstance(122)) - Creating instance from Ini
[sections=main,urls]
2016-11-03 13:58:42,522 DEBUG mgt.DefaultFilterChainManager
(DefaultFilterChainManager.java:createChain(127)) - Creating chain [/**] from
String definition [authcBasic]
2016-11-03 13:58:42,522 DEBUG mgt.DefaultFilterChainManager
(DefaultFilterChainManager.java:applyChainConfig(278)) - Attempting to apply
path [/**] to filter [authcBasic] with config [null]
2016-11-03 13:58:42,523 DEBUG env.EnvironmentLoader
(EnvironmentLoader.java:initEnvironment(136)) - Published WebEnvironment as
ServletContext attribute with name
[org.apache.shiro.web.env.EnvironmentLoader.ENVIRONMENT_ATTRIBUTE_KEY]
2016-11-03 13:58:42,523 INFO env.EnvironmentLoader
(EnvironmentLoader.java:initEnvironment(141)) - Shiro environment initialized
in 28 ms.
2016-11-03 13:58:43,218 INFO env.EnvironmentLoader
(EnvironmentLoader.java:initEnvironment(128)) - Starting Shiro environment
initialization.
2016-11-03 13:58:43,218 DEBUG env.IniWebEnvironment
(IniWebEnvironment.java:init(76)) - Checking any specified config locations.
2016-11-03 13:58:43,219 DEBUG env.IniWebEnvironment
(IniWebEnvironment.java:init(81)) - No INI instance or config locations
specified. Trying default config locations.
2016-11-03 13:58:43,219 DEBUG config.Ini (Ini.java:load(342)) - Parsing [main]
2016-11-03 13:58:43,226 DEBUG config.Ini (Ini.java:load(342)) - Parsing [urls]
2016-11-03 13:58:43,227 DEBUG env.IniWebEnvironment
(IniWebEnvironment.java:getDefaultIni(136)) - Discovered non-empty INI
configuration at location '/WEB-INF/shiro.ini'. Using for configuration.
2016-11-03 13:58:43,227 DEBUG config.IniFactorySupport
(IniFactorySupport.java:createInstance(122)) - Creating instance from Ini
[sections=main,urls]
2016-11-03 13:58:43,228 DEBUG config.ReflectionBuilder
(ReflectionBuilder.java:resolveReference(238)) - Encountered object reference
'$ldapContextFactory'. Looking up object with id 'ldapContextFactory'
2016-11-03 13:58:43,229 DEBUG realm.AuthorizingRealm
(AuthorizingRealm.java:getAuthorizationCacheLazy(234)) - No authorizationCache
instance set. Checking for a cacheManager...
2016-11-03 13:58:43,229 INFO realm.AuthorizingRealm
(AuthorizingRealm.java:getAuthorizationCacheLazy(248)) - No cache or
cacheManager properties have been set. Authorization cache cannot be obtained.
2016-11-03 13:58:43,229 DEBUG config.IniFactorySupport
(IniFactorySupport.java:createInstance(122)) - Creating instance from Ini
[sections=main,urls]
2016-11-03 13:58:43,230 DEBUG mgt.DefaultFilterChainManager
(DefaultFilterChainManager.java:createChain(127)) - Creating chain [/**] from
String definition [authcBasic]
2016-11-03 13:58:43,236 DEBUG mgt.DefaultFilterChainManager
(DefaultFilterChainManager.java:applyChainConfig(278)) - Attempting to apply
path [/**] to filter [authcBasic] with config [null]
2016-11-03 13:58:43,236 DEBUG env.EnvironmentLoader
(EnvironmentLoader.java:initEnvironment(136)) - Published WebEnvironment as
ServletContext attribute with name
[org.apache.shiro.web.env.EnvironmentLoader.ENVIRONMENT_ATTRIBUTE_KEY]
2016-11-03 13:58:43,236 INFO env.EnvironmentLoader
(EnvironmentLoader.java:initEnvironment(141)) - Shiro environment initialized
in 18 ms.
2016-11-03 13:58:43,481 INFO hadoop.gateway (GatewayServer.java:start(425)) -
Monitoring topologies in directory:
/usr/hdp/0.11.0-SNAPSHOT/knox/bin/../conf/topologies
2016-11-03 13:58:43,482 INFO hadoop.gateway
(GatewayServer.java:startGateway(296)) - Started gateway on port 8,443.
2016-11-03 13:59:04,271 DEBUG authc.BasicHttpAuthenticationFilter
(BasicHttpAuthenticationFilter.java:createToken(308)) - Attempting to execute
login with headers [Basic Z3Vlc3Q6Z3Vlc3QtcGFzc3dvcmQ=]
2016-11-03 13:59:04,272 DEBUG ldap.JndiLdapRealm
(JndiLdapRealm.java:queryForAuthenticationInfo(369)) - Authenticating user
'guest' through LDAP
2016-11-03 13:59:04,272 INFO hadoop.gateway
(KnoxLdapRealm.java:getUserDn(691)) - Computed userDn:
uid=guest,ou=people,dc=hadoop,dc=apache,dc=org using dnTemplate for principal:
guest
2016-11-03 13:59:04,273 DEBUG ldap.JndiLdapContextFactory
(JndiLdapContextFactory.java:getLdapContext(488)) - Initializing LDAP context
using URL [ldap://sandbox.hortonworks.com:33389] and principal
[uid=guest,ou=people,dc=hadoop,dc=apache,dc=org] with pooling disabled
2016-11-03 13:59:04,370 DEBUG realm.AuthenticatingRealm
(AuthenticatingRealm.java:getAuthenticationInfo(569)) - Looked up
AuthenticationInfo [guest] from doGetAuthenticationInfo
2016-11-03 13:59:04,371 DEBUG realm.AuthenticatingRealm
(AuthenticatingRealm.java:cacheAuthenticationInfoIfPossible(507)) -
AuthenticationInfo caching is disabled for info [guest]. Submitted token:
[org.apache.shiro.authc.UsernamePasswordToken - guest, rememberMe=false
(158.234.220.18)].
2016-11-03 13:59:04,371 DEBUG credential.SimpleCredentialsMatcher
(SimpleCredentialsMatcher.java:equals(95)) - Performing credentials equality
check for tokenCredentials of type [org.apache.shiro.crypto.hash.SimpleHash and
accountCredentials of type [org.apache.shiro.crypto.hash.SimpleHash]
2016-11-03 13:59:04,372 DEBUG credential.SimpleCredentialsMatcher
(SimpleCredentialsMatcher.java:equals(101)) - Both credentials arguments can be
easily converted to byte arrays. Performing array equals comparison
2016-11-03 13:59:04,372 DEBUG authc.AbstractAuthenticator
(AbstractAuthenticator.java:authenticate(231)) - Authentication successful for
token [org.apache.shiro.authc.UsernamePasswordToken - guest, rememberMe=false
(158.234.220.18)]. Returned account [guest]
2016-11-03 13:59:04,372 DEBUG support.DefaultSubjectContext
(DefaultSubjectContext.java:resolveSecurityManager(102)) - No SecurityManager
available in subject context map. Falling back to
SecurityUtils.getSecurityManager() lookup.
2016-11-03 13:59:04,372 DEBUG support.DefaultSubjectContext
(DefaultSubjectContext.java:resolveSecurityManager(102)) - No SecurityManager
available in subject context map. Falling back to
SecurityUtils.getSecurityManager() lookup.
2016-11-03 13:59:04,401 DEBUG servlet.SimpleCookie
(SimpleCookie.java:addCookieHeader(226)) - Added HttpServletResponse Cookie
[rememberMe=deleteMe; Path=/gateway/sandbox; Max-Age=0; Expires=Wed,
02-Nov-2016 13:59:04 GMT]
2016-11-03 13:59:04,401 DEBUG mgt.AbstractRememberMeManager
(AbstractRememberMeManager.java:onSuccessfulLogin(300)) - AuthenticationToken
did not indicate RememberMe is requested. RememberMe functionality will not be
executed for corresponding account.
2016-11-03 13:59:04,402 DEBUG realm.AuthorizingRealm
(AuthorizingRealm.java:getAuthorizationCacheLazy(234)) - No authorizationCache
instance set. Checking for a cacheManager...
2016-11-03 13:59:04,402 INFO realm.AuthorizingRealm
(AuthorizingRealm.java:getAuthorizationCacheLazy(248)) - No cache or
cacheManager properties have been set. Authorization cache cannot be
obtained.{code}
* Thus I believe this ticket is complete - just submit a pull request.
> Add log4j properties for shiro related logs to the gateway log4j file
> ---------------------------------------------------------------------
>
> Key: KNOX-757
> URL: https://issues.apache.org/jira/browse/KNOX-757
> Project: Apache Knox
> Issue Type: Bug
> Reporter: Sumit Gupta
>
> Properties for controlling logging for shiro functionality should be made
> easier to switch on/off in the gateway log4j file.
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
