File copy can fail with jetty timeout

Steps to reproduce

Seen on worker node:

2017-07-24 13:44:52,079 | WARN | pool-43-thread-6 | (WorkspaceImpl:438) - Could not copy http://media.uct.ac.za/archive/archive/mediapackage/68f49e48-a480-4a8c-abca-5b098447fda7/track-0/8/track.flv to /data/opencast/work/shared/workspace/http_media.uct.ac.za/archive/archive/mediapackage/68f49e48-a480-4a8c-abca-5b098447fda7/track-0/8/track.flv: Premature end of Content-Length delimited message body (expected: 7287453637; received: 3409150214

On the admin node, the get request fails with:

2017-07-24 13:44:21,912 | ERROR | qtp393562586-9429 | (JAXRSUtils:1811) - Problem with writing the data, class java.io.FileInputStream, ContentType: video/x-flv

2017-07-24 13:44:21,914 | WARN | qtp393562586-9429 | (LogUtils:449) - Interceptor for
{http://endpoint.adminui.opencastproject.org/}
PresetsEndpoint has thrown exception, unwinding now
org.apache.cxf.interceptor.Fault: java.util.concurrent.TimeoutException: Idle timeout expired: 30000/30000 ms
at org.apache.cxf.jaxrs.interceptor.JAXRSOutInterceptor.handleWriteException(JAXRSOutInterceptor.java:391)[207:org.apache.cxf.cxf-rt-frontend-jaxrs:3.1.7]

Caused by: java.io.IOException: java.util.concurrent.TimeoutException: Idle timeout expired: 30000/30000 ms
at org.eclipse.jetty.util.SharedBlockingCallback$Blocker.block(SharedBlockingCallback.java:213)[294:org.eclipse.jetty.util:9.2.19.v20160908]
at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:141)[291:org.eclipse.jetty.server:9.2.19.v20160908]
at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:383)[291:org.eclipse.jetty.server:9.2.19.v20160908]
at org.apache.cxf.io.AbstractWrappedOutputStream.write(AbstractWrappedOutputStream.java:51)[206:org.apache.cxf.cxf-core:3.1.7]
at org.apache.cxf.helpers.IOUtils.copy(IOUtils.java:207)[206:org.apache.cxf.cxf-core:3.1.7]
at org.apache.cxf.helpers.IOUtils.copyAndCloseInput(IOUtils.java:166)[206:org.apache.cxf.cxf-core:3.1.7]
at org.apache.cxf.jaxrs.provider.BinaryDataProvider.copyInputToOutput(BinaryDataProvider.java:194)[207:org.apache.cxf.cxf-rt-frontend-jaxrs:3.1.7]
at org.apache.cxf.jaxrs.provider.BinaryDataProvider.writeTo(BinaryDataProvider.java:154)[207:org.apache.cxf.cxf-rt-frontend-jaxrs:3.1.7]
at org.apache.cxf.jaxrs.utils.JAXRSUtils.writeMessageBody(JAXRSUtils.java:1404)[207:org.apache.cxf.cxf-rt-frontend-jaxrs:3.1.7]
at org.apache.cxf.jaxrs.interceptor.JAXRSOutInterceptor.serializeMessage(JAXRSOutInterceptor.java:244)[207:org.apache.cxf.cxf-rt-frontend-jaxrs:3.1.7]
... 92 more
Caused by: java.util.concurrent.TimeoutException: Idle timeout expired: 30000/30000 ms
at org.eclipse.jetty.io.IdleTimeout.checkIdleTimeout(IdleTimeout.java:161)[283:org.eclipse.jetty.io:9.2.19.v20160908]
at org.eclipse.jetty.io.IdleTimeout$1.run(IdleTimeout.java:50)[283:org.eclipse.jetty.io:9.2.19.v20160908]

It seems like this idleTimeout value has changed in jetty https://stackoverflow.com/questions/25548341/jetty-idletimeout and it seems worth increasing it, but it's not totally clear how to do that.

There is an etc/jetty.xml file created at runtime that has connector
settings.

According to: https://ops4j1.jira.com/wiki/display/paxweb/Advanced+Jetty+Configuration it may be possible to specify a jetty.xml that pax web should use.

Activity

Show:
Stephen Marquard
July 27, 2017, 10:39 PM

We are testing the attached jetty-custom.xml file with this setting in etc/org.ops4j.pax.web.cfg

org.ops4j.pax.web.config.file=/opt/opencast/etc/jetty-custom.xml

(not sure whether a full path name is required or a relative name is ok).

Stephen Marquard
July 27, 2017, 10:42 PM

To test the effect of this change, upload a mediapackage which has a very large file (say 5G+) that is archived.

Then start a curl request for the file, e.g.:

curl -i --digest -u opencast_system_account:CHANGEME -H 'X-Requested-Auth: Digest' --output tmp.flv http://opencast.domain/archive/archive/mediapackage/2731173735678392320/track-0/2/track.flv

Once curl has started, interrupt with Ctrl-Z from the shell so the process is paused. Wait 30s.

The opencast logs should then show the TimeoutException as above.

With the change (in the attached example, the timeout is 600000 = 10min), interrupt the curl process, wait 60s, resume it with "fg" and verify that the download continues and ends normally.

Christian Greweling
July 31, 2017, 10:12 PM

To get some more debugging output, and see the timeout.

add to "etc/org.ops4j.pax.logging.cfg"

log4j.logger.org.ops4j.pax.web=DEBUG
log4j.logger.org.eclipse.jetty.server=DEBUG

Karen Dolan
October 10, 2018, 11:36 PM

@smarquard , we're seeing this issue in our slightly modified r/5.x. Did you solve this by using the custom jetty config? Are you still employing that custom config at your site?

Stephen Marquard
October 10, 2018, 11:38 PM
Fixed and reviewed

Assignee

Stephen Marquard

Reporter

Stephen Marquard

Severity

Incorrectly Functioning With Workaround

Tags (folksonomy)

None

Components

Fix versions

Affects versions

Priority

Major