[8.0.x] NCSA log does not contain authenticated user

Question

[8.0.x] NCSA log does not contain authenticated user

f2par0 opened this issue a year ago · 9 comments

When used in karaf with the following configuration :

org.ops4j.pax.web.log.ncsa.enabled=true
org.ops4j.pax.web.log.ncsa.format=yyyy_mm_dd.request.log
org.ops4j.pax.web.log.ncsa.retaindays=7
org.ops4j.pax.web.log.ncsa.append=true
org.ops4j.pax.web.log.ncsa.extended=true
org.ops4j.pax.web.log.ncsa.dispatch=false
org.ops4j.pax.web.log.ncsa.logtimezone=GMT
org.ops4j.pax.web.log.ncsa.directory=log
org.ops4j.pax.web.log.ncsa.latency=true
org.ops4j.pax.web.log.ncsa.cookies=false
org.ops4j.pax.web.log.ncsa.server=false

The authenticated user is not logged when accessing http://localhost:8040/system/console/bundles
the log file contains :

[0:0:0:0:0:0:0:1] - - [17/Oct/2023:13:48:06 +0000] "GET /system/console/bundles HTTP/1.1" 200 100128

instead of

[0:0:0:0:0:0:0:1] - karaf [18/Oct/2023:08:50:32 +0000] "GET /system/console/bundles HTTP/1.1" 200 91560 "-" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/118.0.0.0 Safari/537.36" 1106

Previously, the class https://github.com/Talend/org.ops4j.pax.web/blob/13814a9d365cdd3014257ea5e1e63676fb058bc6/pax-web-jetty/src/main/java/org/ops4j/pax/web/service/jetty/internal/HttpServiceRequestWrapper.java#L158
was setting the Authentication User in the main request, so the Jetty org/eclipse/jetty/server/CustomRequestLog.java can log the User
The HttpServiceRequestWrapper does not exist anymore, and the replacement org/ops4j/pax/web/service/spi/servlet/OsgiHttpServletRequestWrapper.java does not set the Auth part in the main request, so the logger cannot find it.

Is it the intended behavior ?

I also noted that the latency cannot be appended anymore, the config key is not read

Answer 1 · 2023-10-18T14:57:05.000Z

I checked:

mvn:org.ops4j.pax.web.samples/auth-config-fragment-jetty/8.0.23-SNAPSHOT
webbundle:mvn:org.ops4j.pax.web.samples/war-authentication/8.0.23-SNAPSHOT/war?Web-ContextPath=/war-authentication

With this realm.properties:

# admin/admin
admin: MD5:21232f297a57a5a743894a0e4a801fc3,server-administrator,content-administrator,admin,paxweb-admin
# admin2/admin
admin2: MD5:21232f297a57a5a743894a0e4a801fc3,role-admin
# manager/manager
manager: MD5:1d0258c2440a8d19e716292b231e3190,role-manager
# am/am
am: MD5:c04cd38aeb30f3ad1f8ab4e64a0ded7b,role-admin,role-manager
# viewer/viewer
viewer: MD5:4b2a1529867b8d697685b1722ccd0149,paxweb-viewer

The fragment contains:

<!DOCTYPE Configure PUBLIC "-//Jetty//Configure//EN" "http://www.eclipse.org/jetty/configure_9_3.dtd">
<Configure id="Server" class="org.eclipse.jetty.server.Server">

	<Call name="addBean">
		<Arg>
			<New class="org.eclipse.jetty.security.HashLoginService">
				<Set name="name">Test Realm</Set>
				<!-- File will be loaded relatively to pax-web-itest-jetty module -->
				<Set name="config">target/test-classes/realm.properties</Set>
			</New>
		</Arg>
	</Call>

	<Call name="addBean">
		<Arg>
			<New class="org.eclipse.jetty.security.HashLoginService">
				<Set name="name">default</Set>
				<!-- File will be loaded relatively to pax-web-itest-jetty module -->
				<Set name="config">target/test-classes/realm.properties</Set>
			</New>
		</Arg>
	</Call>

</Configure>

And with this configuration:

org.ops4j.pax.web.log.ncsa.enabled = true
org.ops4j.pax.web.log.ncsa.directory = ${karaf.data}/log
org.ops4j.pax.web.log.ncsa.extended = true

I saw:

127.0.0.1 - admin [18/Oct/2023:14:52:01 +0000] "GET /war-authentication/wc/example HTTP/1.1" 200 240 "-" "Mozilla/5.0 (X11; Linux x86_64; rv:109.0) Gecko/20100101 Firefox/118.0"
127.0.0.1 - - [18/Oct/2023:14:52:01 +0000] "GET /war-authentication/images/logo.png HTTP/1.1" 200 126 "http://127.0.0.1:8181/war-authentication/wc/example" "Mozilla/5.0 (X11; Linux x86_64; rv:109.0) Gecko/20100101 Firefox/118.0"

with extended = false (after fixing #1906):

127.0.0.1 - admin [18/Oct/2023:14:47:47 +0000] "GET /war-authentication/wc/example HTTP/1.1" 200 240
127.0.0.1 - - [18/Oct/2023:14:47:47 +0000] "GET /war-authentication/images/logo.png HTTP/1.1" 200 126

I see that org.eclipse.jetty.server.CustomRequestLog#getAuthentication() is calling:

Authentication authentication = request.getAuthentication();

and org.eclipse.jetty.server.Request#_authentication is properly set to:

_authentication = {org.eclipse.jetty.security.UserAuthentication@10616} "{User,BASIC,DefaultUserIdentity('admin')}"
 _method: java.lang.String  = {@10630} "BASIC"
 _userIdentity: org.eclipse.jetty.server.UserIdentity  = {org.eclipse.jetty.security.DefaultUserIdentity@10631} "DefaultUserIdentity('admin')"

It may be an issue with the way Felix Web Console is authenticating users and I believe I know what's the problem (OSGi authentication).

Answer 2 · 2023-10-18T16:26:50.000Z

I see that Felix Web Console sets proper karaf user here:

"qtp1759420476-466@11443" prio=5 tid=0x1d2 nid=NA runnable
  java.lang.Thread.State: RUNNABLE
	  at org.ops4j.pax.web.service.spi.servlet.OsgiHttpServletRequestWrapper.setAttribute(OsgiHttpServletRequestWrapper.java:151)
	  at org.apache.felix.webconsole.internal.servlet.JaasSecurityProvider.authenticate(JaasSecurityProvider.java:207)
	  at org.apache.felix.webconsole.internal.servlet.OsgiManagerHttpContext.handleSecurity(OsgiManagerHttpContext.java:94)
	  at org.ops4j.pax.web.service.spi.context.WebContainerContextWrapper.handleSecurity(WebContainerContextWrapper.java:85)
	  at org.ops4j.pax.web.service.spi.servlet.OsgiFilterChain.doFilter(OsgiFilterChain.java:98)
	  at org.ops4j.pax.web.service.jetty.internal.PaxWebServletHandler.doHandle(PaxWebServletHandler.java:320)
	  at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
	  at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:600)
	  at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
	  at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235)
	  at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1624)
	  at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233)
	  at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1440)
	  at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188)
	  at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:505)
	  at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1594)
	  at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186)
	  at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1355)
	  at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
	  at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:234)
	  at org.ops4j.pax.web.service.jetty.internal.PrioritizedHandlerCollection.handle(PrioritizedHandlerCollection.java:96)
	  at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
	  at org.eclipse.jetty.server.Server.handle(Server.java:516)
	  at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:487)
	  at org.eclipse.jetty.server.HttpChannel$$Lambda$1070.1747016719.dispatch(Unknown Source:-1)
	  at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:732)
	  at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:479)
	  at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:277)
	  at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311)
	  at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105)
	  at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104)
	  at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:338)
	  at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:315)
	  at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:173)
	  at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:131)
	  at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:409)
	  at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:883)
	  at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1034)
	  at java.lang.Thread.run(Thread.java:834)

But when the logging happens, from the point of view of Jetty, the request is UNAUTHENTICATED:

"qtp1759420476-466@11443" prio=5 tid=0x1d2 nid=NA runnable
  java.lang.Thread.State: RUNNABLE
	  at org.eclipse.jetty.server.Request.getAuthentication(Request.java:685)
	  at org.eclipse.jetty.server.CustomRequestLog.getAuthentication(CustomRequestLog.java:356)
	  at org.eclipse.jetty.server.CustomRequestLog.logRequestAuthentication(CustomRequestLog.java:1199)
	  at java.lang.invoke.LambdaForm$DMH.829705789.invokeStatic(LambdaForm$DMH:-1)
	  at java.lang.invoke.LambdaForm$MH.855588747.invoke(LambdaForm$MH:-1)
	  at java.lang.invoke.LambdaForm$MH.944148181.invoke_MT(LambdaForm$MH:-1)
	  at org.eclipse.jetty.server.CustomRequestLog.log(CustomRequestLog.java:336)
	  at org.eclipse.jetty.server.HttpChannel.onCompleted(HttpChannel.java:911)
	  at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:467)
	  at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:277)
	  at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311)
	  at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105)
	  at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104)
	  at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:338)
	  at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:315)
	  at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:173)
	  at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:131)
	  at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:409)
	  at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:883)
	  at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1034)
	  at java.lang.Thread.run(Thread.java:834)

Answer 3 · 2023-10-18T16:34:50.000Z

I know how to fix it, but that's tomorrow.

Thanks @f2par0 for report!

Answer 4 · 2023-10-19T05:43:31.000Z

Yes good report @f2par0 .

I think it would be great to open an corresponding Jira at Karaf first (for the tracking). I will do that.

Answer 5 · 2023-10-19T05:57:48.000Z

When checking back in Pax Web 7, I see that only Jetty part has this implementation:

public void setAttribute(final String name, Object value) {
	if (HttpContext.AUTHENTICATION_TYPE.equals(name)) {
		handleAuthenticationType(value);
	} else if (HttpContext.REMOTE_USER.equals(name)) {
		handleRemoteUser(value);
	}
	super.setAttribute(name, value);
}

Pax Web 8 needs to handle it in all the runtimes.

Answer 6 · 2023-10-19T10:08:21.000Z

Fails also for Tomcat and Undertow.

Jetty uses: org.eclipse.jetty.server.Request#getAuthentication()
Tomcat uses: org.apache.catalina.connector.Request#getRemoteUser()
Undertow uses: io.undertow.security.idm.Account#getPrincipal()

Answer 7 · 2023-10-19T10:32:26.000Z

OK, works on Undertow:

127.0.0.1 - karaf [19/Oct/2023:12:32:12 +0200] "GET /system/console/services HTTP/1.1" 200 -

Answer 8 · 2023-10-19T11:23:11.000Z

Works with Tomcat:

127.0.0.1 - karaf [19/Oct/2023:13:22:40 +0200] "GET /system/console/services HTTP/1.1" 200 38046

Answer 9 · 2023-10-19T11:43:01.000Z

Works with Jetty:

127.0.0.1 - karaf [19/Oct/2023:11:42:49 +0000] "GET /system/console/bundles/0.json HTTP/1.1" 200 150558