Uploaded image for project: 'Islandora'
  1. Islandora
  2. ISLANDORA-1631

PHP stat cache is inconsistent, causing failures in Tuque

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Blocker
    • Resolution: Fixed
    • Affects Version/s: 7.x-1.6
    • Fix Version/s: 7.x-1.7
    • Component/s: Tuque API
    • Labels:
      None

      Description

      PHP stat cache becomes inconsistent, leading to Tuque failures.

      This long-standing bug appears to have been uncovered with the Drupal 7.42 release, in which static caching was added to module_load_include().

      The general flow of code necessary to make this happen, is:

      1. fopen() a file
      2. Perform an operation which performs a "stat" on the file (filesize(), among others).
      3. Change the content of the file, which will change the previously stat'd value (deleting from the file, reducing its length).
      4. Stat the file again; the value will match that from before.

      A small test script, to see the error happen: https://gist.github.com/adam-vessey/386494830670a19e0f97

      It so happens this flow would occur when generating HOCR, when we strip out the HTML DOCTYPE declarations; however, it appears that the is_file() check which would always be performed prior to the static caching in module_load_include() would result in a general wipe of the stat cache, masking the issue.

      With HOCR in particular:

      1. fopen() a file: https://github.com/Islandora/islandora_ocr/blob/8c1248bdc29324cee7863d835b22832085763d1d/includes/hocr.inc#L584-L585
      2. Perform an operation which performs a "stat" on the file: https://github.com/Islandora/islandora_ocr/blob/8c1248bdc29324cee7863d835b22832085763d1d/includes/hocr.inc#L587 (the filesize() call)
      3. Change the content of the file, which will change the previously stat'd value: https://github.com/Islandora/islandora_ocr/blob/8c1248bdc29324cee7863d835b22832085763d1d/includes/hocr.inc#L588-L591
      4. Stat the file again; the value will match that from before: https://github.com/Islandora/tuque/blob/5c6bb1c831f52d9bc014729e325a7f731d772d0f/HttpConnection.php#L657

      This caused Tuque to tell Fedora that it would be sending more bytes then Tuque had to send, so it would end up with errors as Fedora waits for the rest of the bytes to come in:

      WARN 2016-03-08 08:49:48.807 [http-bio-8080-exec-29] (DatastreamResource) Error writing temp stream
      org.fcrepo.server.errors.StreamWriteException: Error writing temp stream
              at org.fcrepo.server.management.DefaultManagement.putTempStream(DefaultManagement.java:1344) ~[fcrepo-server-3.8.1.jar:na]
              at sun.reflect.GeneratedMethodAccessor206.invoke(Unknown Source) ~[na:na]
              at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_60]
              at java.lang.reflect.Method.invoke(Method.java:497) ~[na:1.8.0_60]
              at org.fcrepo.server.messaging.NotificationInvocationHandler.invoke(NotificationInvocationHandler.java:71) ~[fcrepo-server-3.8.1.jar:na]
              at com.sun.proxy.$Proxy11.putTempStream(Unknown Source) ~[na:na]
              at org.fcrepo.server.management.ManagementModule.putTempStream(ManagementModule.java:536) ~[fcrepo-server-3.8.1.jar:na]
              at org.fcrepo.server.rest.DatastreamResource.addOrUpdateDatastream(DatastreamResource.java:572) [fcrepo-server-3.8.1.jar:na]
              at org.fcrepo.server.rest.DatastreamResource.modifyDatastream(DatastreamResource.java:351) [fcrepo-server-3.8.1.jar:na]
              at sun.reflect.GeneratedMethodAccessor205.invoke(Unknown Source) ~[na:na]
              at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_60]
              at java.lang.reflect.Method.invoke(Method.java:497) ~[na:1.8.0_60]
              at org.apache.cxf.service.invoker.AbstractInvoker.performInvocation(AbstractInvoker.java:180) [cxf-api-2.7.7.jar:2.7.7]
              at org.apache.cxf.service.invoker.AbstractInvoker.invoke(AbstractInvoker.java:96) [cxf-api-2.7.7.jar:2.7.7]
              at org.apache.cxf.jaxrs.JAXRSInvoker.invoke(JAXRSInvoker.java:192) [cxf-rt-frontend-jaxrs-2.7.7.jar:2.7.7]
              at org.apache.cxf.jaxrs.JAXRSInvoker.invoke(JAXRSInvoker.java:100) [cxf-rt-frontend-jaxrs-2.7.7.jar:2.7.7]
              at org.apache.cxf.interceptor.ServiceInvokerInterceptor$1.run(ServiceInvokerInterceptor.java:57) [cxf-api-2.7.7.jar:2.7.7]
              at org.apache.cxf.interceptor.ServiceInvokerInterceptor.handleMessage(ServiceInvokerInterceptor.java:93) [cxf-api-2.7.7.jar:2.7.7]
              at org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:272) [cxf-api-2.7.7.jar:2.7.7]
              at org.apache.cxf.transport.ChainInitiationObserver.onMessage(ChainInitiationObserver.java:121) [cxf-api-2.7.7.jar:2.7.7]
              at org.apache.cxf.transport.http.AbstractHTTPDestination.invoke(AbstractHTTPDestination.java:239) [cxf-rt-transports-http-2.7.7.jar:2.7.7]
              at org.apache.cxf.transport.servlet.ServletController.invokeDestination(ServletController.java:248) [cxf-rt-transports-http-2.7.7.jar:2.7.7]
              at org.apache.cxf.transport.servlet.ServletController.invoke(ServletController.java:222) [cxf-rt-transports-http-2.7.7.jar:2.7.7]
              at org.apache.cxf.transport.servlet.ServletController.invoke(ServletController.java:153) [cxf-rt-transports-http-2.7.7.jar:2.7.7]
              at org.apache.cxf.transport.servlet.CXFNonSpringServlet.invoke(CXFNonSpringServlet.java:167) [cxf-rt-transports-http-2.7.7.jar:2.7.7]
              at org.apache.cxf.transport.servlet.AbstractHTTPServlet.handleRequest(AbstractHTTPServlet.java:286) [cxf-rt-transports-http-2.7.7.jar:2.7.7]
              at org.apache.cxf.transport.servlet.AbstractHTTPServlet.doPut(AbstractHTTPServlet.java:223) [cxf-rt-transports-http-2.7.7.jar:2.7.7]
              at javax.servlet.http.HttpServlet.service(HttpServlet.java:653) [tomcat-servlet-3.0-api.jar:na]
              at org.apache.cxf.transport.servlet.AbstractHTTPServlet.service(AbstractHTTPServlet.java:262) [cxf-rt-transports-http-2.7.7.jar:2.7.7]
              at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:303) [catalina.jar:7.0.65]
              at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208) [catalina.jar:7.0.65]
              at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52) [tomcat7-websocket.jar:7.0.65]
              at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241) [catalina.jar:7.0.65]
              at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208) [catalina.jar:7.0.65]
              at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:369) [spring-security-web-3.0.7.RELEASE.jar:3.0.7.RELEASE]
              at org.fcrepo.server.security.jaas.AuthFilterJAAS.doFilter(AuthFilterJAAS.java:329) [fcrepo-security-jaas-3.8.1.jar:na]
              at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:381) [spring-security-web-3.0.7.RELEASE.jar:3.0.7.RELEASE]
              at org.springframework.security.web.access.channel.ChannelProcessingFilter.doFilter(ChannelProcessingFilter.java:109) [spring-security-web-3.0.7.RELEASE.jar:3.0.7.RELEASE]
              at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:381) [spring-security-web-3.0.7.RELEASE.jar:3.0.7.RELEASE]
              at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:168) [spring-security-web-3.0.7.RELEASE.jar:3.0.7.RELEASE]
              at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:237) [spring-web-3.0.7.RELEASE.jar:3.0.7.RELEASE]
              at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:167) [spring-web-3.0.7.RELEASE.jar:3.0.7.RELEASE]
              at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241) [catalina.jar:7.0.65]
              at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208) [catalina.jar:7.0.65]
              at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:220) [catalina.jar:7.0.65]
              at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:122) [catalina.jar:7.0.65]
              at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:505) [catalina.jar:7.0.65]
              at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:170) [catalina.jar:7.0.65]
              at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:103) [catalina.jar:7.0.65]
              at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:956) [catalina.jar:7.0.65]
              at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116) [catalina.jar:7.0.65]
              at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:423) [catalina.jar:7.0.65]
              at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1079) [tomcat-coyote.jar:7.0.65]
              at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:625) [tomcat-coyote.jar:7.0.65]
              at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:318) [tomcat-coyote.jar:7.0.65]
              at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [na:1.8.0_60]
              at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [na:1.8.0_60]
              at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) [tomcat-coyote.jar:7.0.65]
              at java.lang.Thread.run(Thread.java:745) [na:1.8.0_60]
      Caused by: java.net.SocketTimeoutException: Read timed out
              at java.net.SocketInputStream.socketRead0(Native Method) ~[na:1.8.0_60]
              at java.net.SocketInputStream.socketRead(SocketInputStream.java:116) ~[na:1.8.0_60]
              at java.net.SocketInputStream.read(SocketInputStream.java:170) ~[na:1.8.0_60]
              at java.net.SocketInputStream.read(SocketInputStream.java:141) ~[na:1.8.0_60]
              at org.apache.coyote.http11.InternalInputBuffer.fill(InternalInputBuffer.java:535) ~[tomcat-coyote.jar:7.0.65]
              at org.apache.coyote.http11.InternalInputBuffer.fill(InternalInputBuffer.java:504) ~[tomcat-coyote.jar:7.0.65]
              at org.apache.coyote.http11.InternalInputBuffer$InputStreamInputBuffer.doRead(InternalInputBuffer.java:566) ~[tomcat-coyote.jar:7.0.65]
              at org.apache.coyote.http11.filters.IdentityInputFilter.doRead(IdentityInputFilter.java:137) ~[tomcat-coyote.jar:7.0.65]
              at org.apache.coyote.http11.AbstractInputBuffer.doRead(AbstractInputBuffer.java:341) ~[tomcat-coyote.jar:7.0.65]
              at org.apache.coyote.Request.doRead(Request.java:431) ~[tomcat-coyote.jar:7.0.65]
              at org.apache.catalina.connector.InputBuffer.realReadBytes(InputBuffer.java:290) ~[catalina.jar:7.0.65]
              at org.apache.tomcat.util.buf.ByteChunk.substract(ByteChunk.java:449) ~[tomcat-coyote.jar:7.0.65]
              at org.apache.catalina.connector.InputBuffer.read(InputBuffer.java:315) ~[catalina.jar:7.0.65]
              at org.apache.catalina.connector.CoyoteInputStream.read(CoyoteInputStream.java:167) ~[catalina.jar:7.0.65]
              at org.fcrepo.server.utilities.StreamUtility.pipeStream(StreamUtility.java:255) ~[fcrepo-server-3.8.1.jar:na]
              at org.fcrepo.server.management.DefaultManagement.putTempStream(DefaultManagement.java:1335) ~[fcrepo-server-3.8.1.jar:na]
              ... 58 common frames omitted
      

      Steps to Reproduce

      Attempt to regenerate HOCR on an object, running Drupal 7.42 (or a newer 7).

      Test Case

      HOCR is regenerated successfully.


      Adam Vessey
      Developer
      discoverygarden inc. | Managing Digital Content

        Attachments

          Activity

            People

            • Assignee:
              Unassigned
              Reporter:
              adam.vessey Adam Vessey
            • Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved: