[10.1.x] Fascinating IO error with Jetty 12 EE8

[grgrzybek]

Besides:

• [10.1.x] PaxWebSessionIdManager.getSessionIdSuffix misbehavior #2123
• [10.1.x] Invalidate session doesn't remove it from jetty cache #2124

I have another problem with Jetty 12 used in Pax Web 10 in EE8 flavor:

 - OSGi - 13:47:40.524 [qtp1791035325-54] WARN  (HttpChannel.java:659) org.eclipse.jetty.ee8.nested.HttpChannel - handleException /documentation/ java.io.IOException: written 872337 < 872817 content-length
 - OSGi - 13:47:40.526 [qtp1791035325-54] WARN  (Response.java:652) org.eclipse.jetty.server.Response - writeError: status=500, message=java.io.IOException: written 872337 < 872817 content-length, response=oejsi.HttpChannelState$ErrorResponse@6d8fd6b7{500,GET@6a85c2db http://127.0.0.1:8181/documentation/ HTTP/1.1}
java.io.IOException: written 872337 < 872817 content-length
	at org.eclipse.jetty.server.internal.HttpChannelState$ChannelResponse.write(HttpChannelState.java:1385)
	at org.eclipse.jetty.server.Response$Wrapper.write(Response.java:841)
	at org.eclipse.jetty.server.handler.ContextResponse.write(ContextResponse.java:56)
	at org.eclipse.jetty.ee8.nested.HttpChannel.send(HttpChannel.java:851)
	at org.eclipse.jetty.ee8.nested.HttpChannel.sendResponse(HttpChannel.java:831)
	at org.eclipse.jetty.ee8.nested.HttpChannel.write(HttpChannel.java:905)
	at org.eclipse.jetty.ee8.nested.HttpOutput.channelWrite(HttpOutput.java:298)
	at org.eclipse.jetty.ee8.nested.HttpOutput.lambda$sendContent$1(HttpOutput.java:1140)
	at org.eclipse.jetty.http.content.CachingHttpContentFactory$CachedHttpContent.writeTo(CachingHttpContentFactory.java:391)
	at org.eclipse.jetty.ee8.nested.HttpOutput.sendContent(HttpOutput.java:1142)
	at org.eclipse.jetty.ee8.nested.HttpOutput.sendContent(HttpOutput.java:1033)
	at org.eclipse.jetty.ee8.nested.ResourceService.sendData(ResourceService.java:612)
	at org.eclipse.jetty.ee8.nested.ResourceService.doGet(ResourceService.java:281)
	at org.ops4j.pax.web.service.jetty.internal.web.DefaultServlet.doGet(DefaultServlet.java:478)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:497)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:584)
	at org.ops4j.pax.web.service.spi.servlet.OsgiInitializedServlet.service(OsgiInitializedServlet.java:102)
	at org.eclipse.jetty.ee8.servlet.ServletHolder$NotAsync.service(ServletHolder.java:1165)
	at org.eclipse.jetty.ee8.servlet.ServletHolder.handle(ServletHolder.java:654)
	at org.eclipse.jetty.ee8.servlet.ServletHandler$ChainEnd.doFilter(ServletHandler.java:1376)
	at org.ops4j.pax.web.service.spi.servlet.OsgiFilterChain.doFilter(OsgiFilterChain.java:113)
	at org.ops4j.pax.web.service.jetty.internal.PaxWebServletHandler.doHandle(PaxWebServletHandler.java:359)
	at org.eclipse.jetty.ee8.nested.ScopedHandler.handle(ScopedHandler.java:117)
	at org.eclipse.jetty.ee8.security.SecurityHandler.handle(SecurityHandler.java:509)
	at org.eclipse.jetty.ee8.nested.HandlerWrapper.handle(HandlerWrapper.java:108)
	at org.eclipse.jetty.ee8.nested.ScopedHandler.nextHandle(ScopedHandler.java:181)
	at org.eclipse.jetty.ee8.nested.SessionHandler.doHandle(SessionHandler.java:519)
	at org.eclipse.jetty.ee8.nested.ScopedHandler.nextHandle(ScopedHandler.java:179)
	at org.eclipse.jetty.ee8.nested.ContextHandler.doHandle(ContextHandler.java:887)
	at org.ops4j.pax.web.service.jetty.internal.PaxWebServletContextHandler.doHandle(PaxWebServletContextHandler.java:126)
	at org.eclipse.jetty.ee8.nested.ScopedHandler.nextScope(ScopedHandler.java:150)
	at org.eclipse.jetty.ee8.servlet.ServletHandler.doScope(ServletHandler.java:423)
	at org.eclipse.jetty.ee8.nested.ScopedHandler.nextScope(ScopedHandler.java:148)
	at org.eclipse.jetty.ee8.nested.SessionHandler.doScope(SessionHandler.java:503)
	at org.eclipse.jetty.ee8.nested.ScopedHandler.nextScope(ScopedHandler.java:148)
	at org.eclipse.jetty.ee8.nested.ContextHandler.doScope(ContextHandler.java:826)
	at org.eclipse.jetty.ee8.nested.ScopedHandler.handle(ScopedHandler.java:115)
	at org.eclipse.jetty.ee8.nested.Dispatcher.forward(Dispatcher.java:178)
	at org.eclipse.jetty.ee8.nested.Dispatcher.forward(Dispatcher.java:121)
	at org.eclipse.jetty.ee8.nested.ResourceService.sendWelcome(ResourceService.java:380)
	at org.eclipse.jetty.ee8.nested.ResourceService.doGet(ResourceService.java:241)
	at org.ops4j.pax.web.service.jetty.internal.web.DefaultServlet.doGet(DefaultServlet.java:478)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:497)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:584)
	at org.ops4j.pax.web.service.spi.servlet.OsgiInitializedServlet.service(OsgiInitializedServlet.java:102)
	at org.eclipse.jetty.ee8.servlet.ServletHolder$NotAsync.service(ServletHolder.java:1160)
	at org.eclipse.jetty.ee8.servlet.ServletHolder.handle(ServletHolder.java:654)
	at org.eclipse.jetty.ee8.servlet.ServletHandler$ChainEnd.doFilter(ServletHandler.java:1376)
	at org.ops4j.pax.web.service.spi.servlet.OsgiFilterChain.doFilter(OsgiFilterChain.java:113)
	at org.ops4j.pax.web.service.jetty.internal.PaxWebServletHandler.doHandle(PaxWebServletHandler.java:359)
	at org.eclipse.jetty.ee8.nested.ScopedHandler.handle(ScopedHandler.java:117)
	at org.eclipse.jetty.ee8.security.SecurityHandler.handle(SecurityHandler.java:497)
	at org.eclipse.jetty.ee8.nested.HandlerWrapper.handle(HandlerWrapper.java:108)
	at org.eclipse.jetty.ee8.nested.ScopedHandler.nextHandle(ScopedHandler.java:181)
	at org.eclipse.jetty.ee8.nested.SessionHandler.doHandle(SessionHandler.java:519)
	at org.eclipse.jetty.ee8.nested.ScopedHandler.nextHandle(ScopedHandler.java:179)
	at org.eclipse.jetty.ee8.nested.ContextHandler.doHandle(ContextHandler.java:887)
	at org.ops4j.pax.web.service.jetty.internal.PaxWebServletContextHandler.doHandle(PaxWebServletContextHandler.java:126)
	at org.eclipse.jetty.ee8.nested.ScopedHandler.nextScope(ScopedHandler.java:150)
	at org.eclipse.jetty.ee8.servlet.ServletHandler.doScope(ServletHandler.java:423)
	at org.eclipse.jetty.ee8.nested.ScopedHandler.nextScope(ScopedHandler.java:148)
	at org.eclipse.jetty.ee8.nested.SessionHandler.doScope(SessionHandler.java:503)
	at org.eclipse.jetty.ee8.nested.ScopedHandler.nextScope(ScopedHandler.java:148)
	at org.eclipse.jetty.ee8.nested.ContextHandler.doScope(ContextHandler.java:826)
	at org.eclipse.jetty.ee8.nested.ScopedHandler.handle(ScopedHandler.java:115)
	at org.eclipse.jetty.ee8.nested.ContextHandler.handle(ContextHandler.java:1455)
	at org.eclipse.jetty.ee8.nested.HttpChannel$RequestDispatchable.dispatch(HttpChannel.java:1307)
	at org.eclipse.jetty.ee8.nested.HttpChannel.dispatch(HttpChannel.java:628)
	at org.eclipse.jetty.ee8.nested.HttpChannel.handle(HttpChannel.java:468)
	at org.eclipse.jetty.ee8.nested.ContextHandler$CoreContextHandler$CoreToNestedHandler.handle(ContextHandler.java:2540)
	at org.eclipse.jetty.server.handler.ContextHandler.handle(ContextHandler.java:1250)
	at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:148)
	at org.ops4j.pax.web.service.jetty.internal.PrioritizedHandlerCollection.handle(PrioritizedHandlerCollection.java:97)
	at org.eclipse.jetty.server.Server.handle(Server.java:197)
	at org.eclipse.jetty.server.internal.HttpChannelState$HandlerInvoker.run(HttpChannelState.java:793)
	at org.eclipse.jetty.server.internal.HttpConnection.onFillable(HttpConnection.java:419)
	at org.eclipse.jetty.server.internal.HttpConnection$FillableCallback.succeeded(HttpConnection.java:1780)
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105)
	at org.eclipse.jetty.io.SelectableChannelEndPoint$1.run(SelectableChannelEndPoint.java:54)
	at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.runTask(AdaptiveExecutionStrategy.java:492)
	at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.epcRunTask(AdaptiveExecutionStrategy.java:428)
	at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.consumeTask(AdaptiveExecutionStrategy.java:401)
	at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.tryProduce(AdaptiveExecutionStrategy.java:255)
	at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.produce(AdaptiveExecutionStrategy.java:196)
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:1009)
	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.doRunJob(QueuedThreadPool.java:1240)
	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1194)
	at java.base/java.lang.Thread.run(Thread.java:840)

This is a deterministic failure when serving Karaf doc pages...

[grgrzybek]

First difference with unit, plain Jetty test is that org.eclipse.jetty.io.IOResources#toRetainableByteBuffer() uses:

resource = {org.eclipse.jetty.util.resource.PathResource@4362} "file:///data/sources/github.com/ops4j/org.ops4j.pax.web/pax-web-jetty/target/test-classes/index.html"
 alias: java.lang.Boolean  = null
 path: java.nio.file.Path  = {sun.nio.fs.UnixPath@4365} "/data/sources/github.com/ops4j/org.ops4j.pax.web/pax-web-jetty/target/test-classes/index.html"
 realPath: java.nio.file.Path  = null
 SUPPORTED_SCHEMES: org.eclipse.jetty.util.Index  = {org.eclipse.jetty.util.EmptyTrie@4374} 
 uri: java.net.URI  = {java.net.URI@4375} "file:///data/sources/github.com/ops4j/org.ops4j.pax.web/pax-web-jetty/target/test-classes/index.html"

while in OSGi we have:

resource = {org.eclipse.jetty.util.resource.URLResourceFactory$URLResource@7079} "(URL) bundle://11ff231c-94fa-422a-ad13-5455a62dd1bd_47.0:0/index.html"
 connection: java.net.URLConnection  = {org.apache.felix.framework.URLHandlersBundleURLConnection@7145} "org.apache.felix.framework.URLHandlersBundleURLConnection:bundle://11ff231c-94fa-422a-ad13-5455a62dd1bd_47.0:0/index.html"
  allowUserInteraction: boolean  = false
  connected: boolean  = true
  connectTimeout: int  = 0
  defaultAllowUserInteraction: boolean  = false
  defaultUseCaches: boolean  = true
  doInput: boolean  = true
  doOutput: boolean  = false
  factory: java.net.ContentHandlerFactory  = {org.apache.felix.framework.URLHandlers@7159} 
  fileNameMap: java.net.FileNameMap  = {java.net.URLConnection$1@7158} 
  ifModifiedSince: long  = 0
  m_classPathIdx: int  = 0
  m_contentLength: long  = 872817
  m_contentTime: long  = 318207600000
  m_contentType: java.lang.String  = {@7162} "text/html"
  m_framework: org.apache.felix.framework.Felix  = {org.apache.felix.framework.Felix@7160} "org.apache.felix.framework [0]"
  m_is: java.io.InputStream  = {java.util.zip.ZipFile$ZipFileInflaterInputStream@7163} 
  m_path: java.lang.String  = {@7164} "/index.html"
  m_targetRevision: org.osgi.framework.wiring.BundleRevision  = {org.apache.felix.framework.BundleRevisionImpl@7161} "org.apache.karaf.manual [47](R 47.0)"
  readTimeout: int  = 0
  requests: sun.net.www.MessageHeader  = null
  url: java.net.URL  = {java.net.URL@7144} "bundle://11ff231c-94fa-422a-ad13-5455a62dd1bd_47.0:0/index.html"
  useCaches: boolean  = true
 connectTimeout: int  = 0
 inputStreamReference: org.eclipse.jetty.util.resource.URLResourceFactory$URLResource$InputStreamReference  = {org.eclipse.jetty.util.resource.URLResourceFactory$URLResource$InputStreamReference@7146} "java.util.zip.ZipFile$ZipFileInflaterInputStream@1afbd3e0"
 lock: org.eclipse.jetty.util.thread.AutoLock  = {org.eclipse.jetty.util.thread.AutoLock@7142} 
 readTimeout: int  = 0
 uri: java.net.URI  = {java.net.URI@7143} "bundle://11ff231c-94fa-422a-ad13-5455a62dd1bd_47.0:0/index.html"
 url: java.net.URL  = {java.net.URL@7144} "bundle://11ff231c-94fa-422a-ad13-5455a62dd1bd_47.0:0/index.html"
 useCaches: boolean  = true

and org.eclipse.jetty.util.resource.Resource#getPath() returns null in OSGi (should return some path IMO).

[grgrzybek]

Pax Web 11 with Jetty 12.1.x with EE10 sends the data here:

"qtp641175380-71@6398" prio=5 tid=0x47 nid=NA runnable
  java.lang.Thread.State: RUNNABLE
	at org.eclipse.jetty.http.content.ResourceHttpContent.writeTo(ResourceHttpContent.java:130)
	at org.eclipse.jetty.http.content.HttpContent$Wrapper.writeTo(HttpContent.java:250)
	at org.eclipse.jetty.server.ResourceService.sendData(ResourceService.java:687)
	at org.eclipse.jetty.server.ResourceService.doGet(ResourceService.java:210)
	at org.eclipse.jetty.ee10.servlet.ResourceServlet.doGet(ResourceServlet.java:620)
	at jakarta.servlet.http.HttpServlet.service(HttpServlet.java:633)
	at jakarta.servlet.http.HttpServlet.service(HttpServlet.java:723)
	at org.ops4j.pax.web.service.spi.servlet.OsgiInitializedServlet.service(OsgiInitializedServlet.java:119)
	at org.eclipse.jetty.ee10.servlet.ServletHolder$NotAsync.service(ServletHolder.java:1388)
	at org.eclipse.jetty.ee10.servlet.ServletHolder.handle(ServletHolder.java:754)
	at org.eclipse.jetty.ee10.servlet.ServletHandler$ChainEnd.doFilter(ServletHandler.java:1622)
	at org.ops4j.pax.web.service.spi.servlet.OsgiFilterChain.doFilter(OsgiFilterChain.java:114)
	at org.eclipse.jetty.ee10.servlet.ServletHandler$MappedServlet.handle(ServletHandler.java:1556)
	at org.eclipse.jetty.ee10.servlet.ServletChannel.dispatch(ServletChannel.java:871)
	at org.eclipse.jetty.ee10.servlet.ServletChannel.handle(ServletChannel.java:449)
	at org.eclipse.jetty.ee10.servlet.ServletHandler.handle(ServletHandler.java:469)
	at org.ops4j.pax.web.service.jetty.internal.PaxWebServletHandler.handle(PaxWebServletHandler.java:322)
	at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:546)
	at org.eclipse.jetty.ee10.servlet.SessionHandler.handle(SessionHandler.java:719)
	at org.ops4j.pax.web.service.jetty.internal.PaxWebSessionHandler.handle(PaxWebSessionHandler.java:54)
	at org.eclipse.jetty.server.handler.ContextHandler.handle(ContextHandler.java:1250)
	at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:148)
	at org.ops4j.pax.web.service.jetty.internal.PrioritizedHandlerCollection.handle(PrioritizedHandlerCollection.java:103)
	at org.eclipse.jetty.server.Server.handle(Server.java:197)
	at org.eclipse.jetty.server.internal.HttpChannelState$HandlerInvoker.run(HttpChannelState.java:793)
	at org.eclipse.jetty.server.internal.HttpConnection.onFillable(HttpConnection.java:419)
	at org.eclipse.jetty.server.internal.HttpConnection$FillableCallback.succeeded(HttpConnection.java:1780)
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105)
	at org.eclipse.jetty.io.SelectableChannelEndPoint$1.run(SelectableChannelEndPoint.java:54)
	at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.runTask(AdaptiveExecutionStrategy.java:492)
	at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.epcRunTask(AdaptiveExecutionStrategy.java:428)
	at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.consumeTask(AdaptiveExecutionStrategy.java:401)
	at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.tryProduce(AdaptiveExecutionStrategy.java:255)
	at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.run(AdaptiveExecutionStrategy.java:204)
	at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:317)
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:1009)
	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.doRunJob(QueuedThreadPool.java:1240)
	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1194)
	at java.lang.Thread.run(Thread.java:840)

[grgrzybek]

Pax Web 11 (Jetty 12.1.x EE10) uses:

• org.eclipse.jetty.io.IOResources#copy()
• length is 872817 (correct)
• this url resource:

resource: org.eclipse.jetty.util.resource.Resource  = {org.eclipse.jetty.util.resource.URLResourceFactory$URLResource@6712} "(URL) bundle://12d8aec9-ea65-42ac-9b70-e06d577fa70d_47.0:0/index.html"
 connection: java.net.URLConnection  = null
 connectTimeout: int  = 0
 inputStreamReference: org.eclipse.jetty.util.resource.URLResourceFactory$URLResource$InputStreamReference  = null
 lock: org.eclipse.jetty.util.thread.AutoLock  = {org.eclipse.jetty.util.thread.AutoLock@6869} 
 readTimeout: int  = 0
 uri: java.net.URI  = {java.net.URI@6870} "bundle://12d8aec9-ea65-42ac-9b70-e06d577fa70d_47.0:0/index.html"
 url: java.net.URL  = {java.net.URL@6871} "bundle://12d8aec9-ea65-42ac-9b70-e06d577fa70d_47.0:0/index.html"
 useCaches: boolean  = true

The problem with Pax Web 11 was that the caching for default/resource servlet was misconfigured and not enabled, so org.eclipse.jetty.http.content.CachingHttpContentFactory.CachedHttpContent was not used!
However instead of getting HTTP 500, curl got:

curl: (18) end of response with 480 bytes missing

[grgrzybek]

Found the issue in Jetty:

• IOResources#toRetainableByteBuffer data loss when using resources without path jetty/jetty.project#15031