Graham,
On Fri, Mar 13, 2015 at 4:43 PM, Graham Leggett <minf...@sharp.fm> wrote:
> On 13 Mar 2015, at 9:58 PM, Neven Cvetkovic <neven.cvetko...@gmail.com>
> wrote:
>
> > Just to confirm, the 403 Forbidden page was rendered by Tomcat, not
> Apache
> > HTTPD?
>
> Yes, it is branded tomcat and appears in the tomcat access log.
Great. We know it is Tomcat rendering this page.
> >
> > Next thing I would probably increase the verbosity of the Realm logging,
> by
> > updating your conf/logging.properties, e.g.
> > org.apache.catalina.realm.level = ALL
> > org.apache.catalina.realm.useParentHandlers = true
> > org.apache.catalina.authenticator.level = ALL
> > org.apache.catalina.authenticator.useParentHandlers = true
> >
> >
> > You might want to disable buffering as well, e.g.
> > 1catalina.org.apache.juli.FileHandler.bufferSize = -1
>
> None of these changes to logging.properties have any effect on my test
> system of tomcat v7.0.59 deployed to RHEL6. I get no changes to
> catalina.out at all, it stays completely silent.
>
> Sorry, I think we forgot to include the ConsoleHandler and FileHandlers to
collect ALL logs, not just FINE level (out-of-box level), e.g.
1catalina.org.apache.juli.FileHandler.level = ALL
1catalina.org.apache.juli.FileHandler.directory = ${catalina.base}/logs
1catalina.org.apache.juli.FileHandler.prefix = catalina.
1catalina.org.apache.juli.FileHandler.bufferSize = -1
java.util.logging.ConsoleHandler.level = ALL
java.util.logging.ConsoleHandler.formatter =
java.util.logging.SimpleFormatter
Also, try to switch over to the old system quickly (where things were
working properly), and try to input a wrong username, or a user that has
proper password, but not the appropriate role. Let's see if the
authorization error (403) shows up now in the logs.
I will test this on my Tomcat with DataSourceRealm. I've got it to log with
my out-of-box UserDatabaseRealm, e.g.
Mar 13, 2015 5:36:56 PM org.apache.catalina.authenticator.AuthenticatorBase
invoke
FINE: Security checking request GET /SimpleAppAuth/time
Mar 13, 2015 5:36:56 PM org.apache.catalina.realm.RealmBase
findSecurityConstraints
FINE: Checking constraint 'SecurityConstraint[SecurePages]' against GET
/time --> true
Mar 13, 2015 5:36:56 PM org.apache.catalina.authenticator.AuthenticatorBase
invoke
FINE: Calling hasUserDataPermission()
Mar 13, 2015 5:36:56 PM org.apache.catalina.realm.RealmBase
hasUserDataPermission
FINE: User data constraint has no restrictions
Mar 13, 2015 5:36:56 PM org.apache.catalina.authenticator.AuthenticatorBase
invoke
FINE: Calling authenticate()
Mar 13, 2015 5:36:56 PM org.apache.catalina.realm.CombinedRealm authenticate
FINE: Attempting to authenticate user "john" with realm
"org.apache.catalina.realm.UserDatabaseRealm/1.0"
Mar 13, 2015 5:36:56 PM org.apache.catalina.realm.CombinedRealm authenticate
FINE: Authenticated user "john" with realm
"org.apache.catalina.realm.UserDatabaseRealm/1.0"
Mar 13, 2015 5:36:56 PM org.apache.catalina.authenticator.AuthenticatorBase
register
FINE: Authenticated 'john' with type 'BASIC'
Mar 13, 2015 5:36:56 PM org.apache.catalina.authenticator.AuthenticatorBase
invoke
FINE: Calling accessControl()
Mar 13, 2015 5:36:56 PM org.apache.catalina.realm.RealmBase
hasResourcePermission
FINE: Checking roles GenericPrincipal[john(APP_USER,)]
Mar 13, 2015 5:36:56 PM org.apache.catalina.realm.RealmBase hasRole
FINE: Username john does NOT have role APP_ADMIN
Mar 13, 2015 5:36:56 PM org.apache.catalina.realm.RealmBase
hasResourcePermission
FINE: No role found: APP_ADMIN
Mar 13, 2015 5:36:56 PM org.apache.catalina.authenticator.AuthenticatorBase
invoke
FINE: Failed accessControl() test
Hopefully, once we get the logging working - it will give us ideas why you
got 403.
I tried to make the same changes to a tomcat v7.0.59 running within
> Eclipse, and in this case I get the following:
>
> Can't load log handler "2localhost.org.apache.juli.FileHandler"
> java.lang.ClassNotFoundException: 2localhost.org.apache.juli.FileHandler
> java.lang.ClassNotFoundException: 2localhost.org.apache.juli.FileHandler
> at java.net.URLClassLoader$1.run(URLClassLoader.java:366)
> at java.net.URLClassLoader$1.run(URLClassLoader.java:355)
> at java.security.AccessController.doPrivileged(Native Method)
> at java.net.URLClassLoader.findClass(URLClassLoader.java:354)
> at java.lang.ClassLoader.loadClass(ClassLoader.java:423)
> at sun.misc.Launcher$AppClassLoader.loadClass(Launcher.java:308)
> at java.lang.ClassLoader.loadClass(ClassLoader.java:356)
> at java.util.logging.LogManager$3.run(LogManager.java:418)
> at java.security.AccessController.doPrivileged(Native Method)
> at
> java.util.logging.LogManager.loadLoggerHandlers(LogManager.java:405)
> at java.util.logging.LogManager.addLogger(LogManager.java:609)
> at java.util.logging.LogManager.demandLogger(LogManager.java:355)
> at java.util.logging.Logger.getLogger(Logger.java:328)
> at
> org.apache.juli.logging.DirectJDKLog.<init>(DirectJDKLog.java:71)
> at
> org.apache.juli.logging.DirectJDKLog.getInstance(DirectJDKLog.java:196)
> at
> org.apache.juli.logging.LogFactory.getInstance(LogFactory.java:170)
> at org.apache.juli.logging.LogFactory.getLog(LogFactory.java:311)
> at
> org.apache.catalina.core.ContainerBase.getLogger(ContainerBase.java:452)
> at
> org.apache.catalina.core.ContainerBase.startInternal(ContainerBase.java:1102)
> at
> org.apache.catalina.core.StandardHost.startInternal(StandardHost.java:816)
> at
> org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:150)
> at
> org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1575)
> at
> org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1565)
> at
> java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
> at java.util.concurrent.FutureTask.run(FutureTask.java:166)
> at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
> at java.lang.Thread.run(Thread.java:722)
>
That's strange. Which logging.properties file did you change? What specific
changes did you make to the logging.properties file? How did you configure
Tomcat logging? Getting it to work with Eclipse is a bit tricky, you need
to configure the launch configuration.
You can always look at jvisualvm or jconsole (programs that come with JDK),
to see exactly the JVM arguments that were passed in, and other useful
stuff (MBeans, runtime configuration, threads, etc...)
For example,
If you were running Tomcat as a standalone, it would be something along the
lines:
-Djava.util.logging.config.file=/d/servers/apache-tomcat-7.0.59/conf/logging.properties
-Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager
-Djava.endorsed.dirs=/d/servers/apache-tomcat-7.0.59/endorsed
-Dcatalina.base=/d/servers/apache-tomcat-7.0.59
-Dcatalina.home=/d/servers/apache-tomcat-7.0.59
-Djava.io.tmpdir=/d/servers/apache-tomcat-7.0.59/temp
If you were running it from Eclipse, it would be something along the lines:
-Dcatalina.base=/d/servers/apache-tomcat-7.0.59
-Dcatalina.home=/d/servers/apache-tomcat-7.0.59
-Dwtp.deploy=/d/servers/apache-tomcat-7.0.59/wtpwebapps
-Djava.endorsed.dirs=/d/servers/apache-tomcat-7.0.59/endorsed
-Dfile.encoding=UTF-8
Notice, Eclipse launch configuration doesn't have
java.util.logging.config.file defined out of box, so the only out-of-box
log file created - would be the AccessLogValve
localhost_access_log.xxxx-xx-xx.txt file. That might differ on different
platforms.
- Remove all log files - or better yet - place them in a new directory.
- Do a fresh start of Tomcat from Eclipse, and see if your
catalina.XXXX-XX-XX.log gets generated. Just to make sure it is Eclipse
startup that generates them, not the other server.
- Even better, if you have them installed in different folders, so you are
not mixing the two :)
Further on, the following is logged, which suggests that there is no roles
> defined at all:
>
> Mar 13, 2015 10:13:12 PM
> org.apache.catalina.authenticator.AuthenticatorBase invoke
> FINE: Security checking request GET /
> Mar 13, 2015 10:13:12 PM
> org.apache.catalina.authenticator.AuthenticatorBase invoke
> FINE: Security checking request GET /
> Mar 13, 2015 10:13:12 PM org.apache.catalina.realm.RealmBase
> findSecurityConstraints
> FINE: No applicable constraints defined
> Mar 13, 2015 10:13:12 PM org.apache.catalina.realm.RealmBase
> findSecurityConstraints
> FINE: No applicable constraints defined
> Mar 13, 2015 10:13:12 PM
> org.apache.catalina.authenticator.AuthenticatorBase invoke
> FINE: Not subject to any constraint
> Mar 13, 2015 10:13:12 PM
> org.apache.catalina.authenticator.AuthenticatorBase invoke
> FINE: Not subject to any constraint
>
>
Did this log show up before you made a change or after you made a change to
logging.properties?
It seems you do have some logging setup, e.g.
"org.apache.catalina.realm.RealmBase" and
"org.apache.catalina.authenticator.AuthenticatorBase".
What these messages are telling you is that "/" (default page) is not
subject to any constraints. Your web.xml does not require the
authentication/authorization. See my examples below.
None of this is making any sense. Is there no simply way of switching on
> realm debugging as we used to with the “debug” attribute?
>
>
I know, it is a bit cryptic. But we will get to the bottom of it.
About logging - the idea is to change logging levels in the
logging.properties, so we would know more about what's going on in the
background.
I would probably get the logging done first, move it to the old
DataSourceRealm, make sure you get AuthenticatorBase and RealmBase to log
stuff, both errors and successes.
Here are type of things I would expect to see in the logfile:
(1) When requesting a non-secured page, e.g.
http://localhost:8080/SimpleAppAuth/
Mar 13, 2015 6:30:03 PM org.apache.catalina.authenticator.AuthenticatorBase
invoke
FINE: Security checking request GET /SimpleAppAuth/
Mar 13, 2015 6:30:03 PM org.apache.catalina.realm.RealmBase
findSecurityConstraints
FINE: Checking constraint 'SecurityConstraint[SecurePages]' against GET
//WEB-INF/views/home.jsp --> false
Mar 13, 2015 6:30:03 PM org.apache.catalina.realm.RealmBase
findSecurityConstraints
FINE: Checking constraint 'SecurityConstraint[SecurePages]' against GET
//WEB-INF/views/home.jsp --> false
Mar 13, 2015 6:30:03 PM org.apache.catalina.realm.RealmBase
findSecurityConstraints
FINE: Checking constraint 'SecurityConstraint[SecurePages]' against GET
//WEB-INF/views/home.jsp --> false
Mar 13, 2015 6:30:03 PM org.apache.catalina.realm.RealmBase
findSecurityConstraints
FINE: Checking constraint 'SecurityConstraint[SecurePages]' against GET
//WEB-INF/views/home.jsp --> false
Mar 13, 2015 6:30:03 PM org.apache.catalina.realm.RealmBase
findSecurityConstraints
FINE: No applicable constraint located
Mar 13, 2015 6:30:03 PM org.apache.catalina.authenticator.AuthenticatorBase
invoke
FINE: Not subject to any constraint
(2) When requesting a secured page, e.g.
http://localhost:8080/SimpleAppAuth/time
Mar 13, 2015 6:30:19 PM org.apache.catalina.authenticator.AuthenticatorBase
invoke
FINE: Security checking request GET /SimpleAppAuth/time
Mar 13, 2015 6:30:19 PM org.apache.catalina.realm.RealmBase
findSecurityConstraints
FINE: Checking constraint 'SecurityConstraint[SecurePages]' against GET
/time --> true
Mar 13, 2015 6:30:19 PM org.apache.catalina.authenticator.AuthenticatorBase
invoke
FINE: Calling hasUserDataPermission()
Mar 13, 2015 6:30:19 PM org.apache.catalina.realm.RealmBase
hasUserDataPermission
FINE: User data constraint has no restrictions
Mar 13, 2015 6:30:19 PM org.apache.catalina.authenticator.AuthenticatorBase
invoke
FINE: Calling authenticate()
Mar 13, 2015 6:30:19 PM org.apache.catalina.authenticator.AuthenticatorBase
invoke
FINE: Failed authenticate() test
(3) When trying to login user with their incorrect password, e.g.
john/incorrectpassword
Mar 13, 2015 6:30:26 PM org.apache.catalina.authenticator.AuthenticatorBase
invoke
FINE: Security checking request GET /SimpleAppAuth/time
Mar 13, 2015 6:30:26 PM org.apache.catalina.realm.RealmBase
findSecurityConstraints
FINE: Checking constraint 'SecurityConstraint[SecurePages]' against GET
/time --> true
Mar 13, 2015 6:30:26 PM org.apache.catalina.authenticator.AuthenticatorBase
invoke
FINE: Calling hasUserDataPermission()
Mar 13, 2015 6:30:26 PM org.apache.catalina.realm.RealmBase
hasUserDataPermission
FINE: User data constraint has no restrictions
Mar 13, 2015 6:30:26 PM org.apache.catalina.authenticator.AuthenticatorBase
invoke
FINE: Calling authenticate()
Mar 13, 2015 6:30:26 PM org.apache.catalina.realm.CombinedRealm authenticate
FINE: Attempting to authenticate user "john" with realm
"org.apache.catalina.realm.UserDatabaseRealm/1.0"
Mar 13, 2015 6:30:26 PM org.apache.catalina.realm.CombinedRealm authenticate
FINE: combinedRealm.authFail
Mar 13, 2015 6:30:26 PM org.apache.catalina.authenticator.AuthenticatorBase
invoke
FINE: Failed authenticate() test
(4) When trying to login user with their proper password, e.g.
jane/correctpassword (200)
Mar 13, 2015 6:31:28 PM org.apache.catalina.authenticator.AuthenticatorBase
invoke
FINE: Security checking request GET /SimpleAppAuth/time
Mar 13, 2015 6:31:28 PM org.apache.catalina.realm.RealmBase
findSecurityConstraints
FINE: Checking constraint 'SecurityConstraint[SecurePages]' against GET
/time --> true
Mar 13, 2015 6:31:28 PM org.apache.catalina.authenticator.AuthenticatorBase
invoke
FINE: Calling hasUserDataPermission()
Mar 13, 2015 6:31:28 PM org.apache.catalina.realm.RealmBase
hasUserDataPermission
FINE: User data constraint has no restrictions
Mar 13, 2015 6:31:28 PM org.apache.catalina.authenticator.AuthenticatorBase
invoke
FINE: Calling authenticate()
Mar 13, 2015 6:31:28 PM org.apache.catalina.realm.CombinedRealm authenticate
FINE: Attempting to authenticate user "jane" with realm
"org.apache.catalina.realm.UserDatabaseRealm/1.0"
Mar 13, 2015 6:31:28 PM org.apache.catalina.realm.CombinedRealm authenticate
FINE: Authenticated user "jane" with realm
"org.apache.catalina.realm.UserDatabaseRealm/1.0"
Mar 13, 2015 6:31:28 PM org.apache.catalina.authenticator.AuthenticatorBase
register
FINE: Authenticated 'jane' with type 'BASIC'
Mar 13, 2015 6:31:28 PM org.apache.catalina.authenticator.AuthenticatorBase
invoke
FINE: Calling accessControl()
Mar 13, 2015 6:31:28 PM org.apache.catalina.realm.RealmBase
hasResourcePermission
FINE: Checking roles GenericPrincipal[jane(APP_ADMIN,APP_USER,)]
Mar 13, 2015 6:31:28 PM org.apache.catalina.realm.RealmBase hasRole
FINE: Username jane has role APP_ADMIN
Mar 13, 2015 6:31:28 PM org.apache.catalina.realm.RealmBase
hasResourcePermission
FINE: Role found: APP_ADMIN
Mar 13, 2015 6:31:28 PM org.apache.catalina.authenticator.AuthenticatorBase
invoke
FINE: Successfully passed all security constraints
Hope that gives you some ammunition.
I will see to setup a quick DataSourceRealm on my box, so I can get to the
bottom of it.
It is a very interesting problem to solve!
Thanks,
Neven
