Uploaded image for project: 'PUBLIC - Liferay Portal Community Edition'
  1. PUBLIC - Liferay Portal Community Edition
  2. LPS-64741

S3Store leaks HTTP connections when serving files from cache

    Details

      Description

      When all connections are leaked, S3Store stops working as connection pool keeps all threads waiting. As a result, Document Library stops working.

      Steps to reproduce

      Master

      1. Configure S3 store by specifying some valid credentials and bucket
      2. Upload a document from the documents & media portlet (from control panel, no need to prepare a page)
      3. Go to the DB and get the fileEntryId for that document. Following SQL query will give that piece of data:
        select fileEntryId, createdate from DLFileEntry order by createdate desc limit 1;
      4. From the scripting console, run the following groovy script. Make sure to change the first line with the fileEntryId you got in previous step:
        long dlFileEntryId=//<put here the file entry Id>;
        
        import com.liferay.document.library.kernel.service.DLFileEntryLocalServiceUtil
        import com.liferay.document.library.kernel.model.DLFileEntry;
        import com.liferay.portal.kernel.log.Log;
        import com.liferay.portal.kernel.log.LogFactoryUtil;
        
        Log _log = LogFactoryUtil.getLog("Test S3Store http connections");
        DLFileEntry dlfe = DLFileEntryLocalServiceUtil.getDLFileEntry(dlFileEntryId);
        for (int i = 0; i < 220; i++) {
          try {
            _log.error("Getting S3 file " + i + " times");
            DLFileEntryLocalServiceUtil.getFile(dlFileEntryId, dlfe.getVersion(), false, 0);  
          }
          catch(Exception e) {
            e.printStackTrace()
          }
          Thread.sleep(10);
        }

      Observed result

      • After 51 iterations (i=50) script can't get more connections (master configures S3Store "Http client max connections" parameter to 50)
      • Portal is unable to access document library. This is the exception you get:
        11:23:18,326 ERROR [http-nio-8080-exec-8]
        [DLPreviewableProcessor:926] com.liferay.portal.kernel.exception.SystemException: Unable to execute HTTP request: Timeout waiting for connection from pool
        com.liferay.portal.kernel.exception.SystemException: Unable to execute HTTP request: Timeout waiting for connection from pool
                at com.liferay.portal.store.s3.S3Store.transform(S3Store.java:672)
                at com.liferay.portal.store.s3.S3Store.getS3Object(S3Store.java:535)
                at com.liferay.portal.store.s3.S3Store.hasFile(S3Store.java:271)
                at com.liferay.document.library.kernel.store.BaseStore.hasFile(BaseStore.java:418)
                at com.liferay.portlet.documentlibrary.store.DLStoreImpl.hasFile(DLStoreImpl.java:354)
                at com.liferay.document.library.kernel.store.DLStoreUtil.hasFile(DLStoreUtil.java:491)
                at com.liferay.document.library.kernel.util.DLPreviewableProcessor.hasThumbnail(DLPreviewableProcessor.java:921)
                at com.liferay.document.library.kernel.util.DLPreviewableProcessor.hasThumbnails(DLPreviewableProcessor.java:933)
                at com.liferay.portlet.documentlibrary.util.ImageProcessorImpl.hasImages(ImageProcessorImpl.java:159)
                at com.liferay.document.library.kernel.util.ImageProcessorUtil.hasImages(ImageProcessorUtil.java:149)
                at com.liferay.portlet.documentlibrary.util.DLImpl.getThumbnailSrc(DLImpl.java:734)
                at com.liferay.document.library.kernel.util.DLUtil.getThumbnailSrc(DLUtil.java:250)
                at org.apache.jsp.document_005flibrary.view_005fentries_jsp._jspService(view_005fentries_jsp:969)
        
      • Thread dump shows that portal is waiting to get a free connection when showing document library page:
        "http-nio-8080-exec-10" daemon prio=10 tid=0x00007f3fb000b000 nid=0x6928 waiting on condition [0x00007f3f670ea000]
           java.lang.Thread.State: TIMED_WAITING (parking)
                at sun.misc.Unsafe.park(Native Method)
                - parking to wait for  <0x00000000ec8b48b8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
                at java.util.concurrent.locks.LockSupport.parkUntil(LockSupport.java:267)
                at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitUntil(AbstractQueuedSynchronizer.java:2130)
                at org.apache.http.pool.PoolEntryFuture.await(PoolEntryFuture.java:131)
                at org.apache.http.pool.AbstractConnPool.getPoolEntryBlocking(AbstractConnPool.java:282)
                at org.apache.http.pool.AbstractConnPool.access$000(AbstractConnPool.java:64)
                at org.apache.http.pool.AbstractConnPool$2.getPoolEntry(AbstractConnPool.java:177)
                at org.apache.http.pool.AbstractConnPool$2.getPoolEntry(AbstractConnPool.java:170)
                at org.apache.http.pool.PoolEntryFuture.get(PoolEntryFuture.java:102)
                at org.apache.http.impl.conn.PoolingClientConnectionManager.leaseConnection(PoolingClientConnectionManager.java:208)
                at org.apache.http.impl.conn.PoolingClientConnectionManager$1.getConnection(PoolingClientConnectionManager.java:195)
                at sun.reflect.GeneratedMethodAccessor582.invoke(Unknown Source)
                at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
                at java.lang.reflect.Method.invoke(Method.java:606)
                at com.amazonaws.http.conn.ClientConnectionRequestFactory$Handler.invoke(ClientConnectionRequestFactory.java:70)
                at com.amazonaws.http.conn.$Proxy741.getConnection(Unknown Source)
                at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:423)
                at org.apache.http.impl.client.AbstractHttpClient.doExecute(AbstractHttpClient.java:863)
                at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:82)
                at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:57)
                at com.amazonaws.http.AmazonHttpClient.executeOneRequest(AmazonHttpClient.java:728)
                at com.amazonaws.http.AmazonHttpClient.executeHelper(AmazonHttpClient.java:489)
                at com.amazonaws.http.AmazonHttpClient.execute(AmazonHttpClient.java:310)
                at com.amazonaws.services.s3.AmazonS3Client.invoke(AmazonS3Client.java:3608)
                at com.amazonaws.services.s3.AmazonS3Client.getObject(AmazonS3Client.java:1135)
                at com.liferay.portal.store.s3.S3Store.getS3Object(S3Store.java:519)
                at com.liferay.portal.store.s3.S3Store.hasFile(S3Store.java:271)
                at com.liferay.document.library.kernel.store.BaseStore.hasFile(BaseStore.java:418)
                at com.liferay.portlet.documentlibrary.store.DLStoreImpl.hasFile(DLStoreImpl.java:354)
                at com.liferay.document.library.kernel.store.DLStoreUtil.hasFile(DLStoreUtil.java:491)
                at com.liferay.document.library.kernel.util.DLPreviewableProcessor.hasThumbnail(DLPreviewableProcessor.java:921)
                at com.liferay.document.library.kernel.util.DLPreviewableProcessor.hasThumbnails(DLPreviewableProcessor.java:933)
                at com.liferay.portlet.documentlibrary.util.ImageProcessorImpl.hasImages(ImageProcessorImpl.java:159)
                at com.liferay.document.library.kernel.util.ImageProcessorUtil.hasImages(ImageProcessorUtil.java:149)
                at com.liferay.portlet.documentlibrary.util.DLImpl.getThumbnailSrc(DLImpl.java:734)
                at com.liferay.document.library.kernel.util.DLUtil.getThumbnailSrc(DLUtil.java:250)
                at org.apache.jsp.document_005flibrary.view_005fentries_jsp._jspService(view_005fentries_jsp:969)
        

      Expected result

      • Portal operates normally
      • No connection starvation
      • No exceptions

      6.2.x

      Same steps depicted for master apply here, with the exception of the script to execute, which is sligthly different:

      long dlFileEntryId=//<put here the file entry Id>;
      
      import com.liferay.portlet.documentlibrary.service.DLFileEntryLocalServiceUtil
      import com.liferay.portlet.documentlibrary.model.DLFileEntry;
      import com.liferay.portal.kernel.log.Log;
      import com.liferay.portal.kernel.log.LogFactoryUtil;
      
      Log _log = LogFactoryUtil.getLog("Test S3 store http connections");
      
      DLFileEntry dlfe = DLFileEntryLocalServiceUtil.getDLFileEntry(dlFileEntryId);
      for (int i = 0; i < 220; i++) {
        try {
          _log.error("Getting S3 file " + i + " times");
          DLFileEntryLocalServiceUtil.getFile(dlfe.getUserId(), dlFileEntryId, dlfe.getVersion(), false, 0);  
        }
        catch(Exception e) {
          e.printStackTrace()
        }
        Thread.sleep(10);
      }
      

      For ee-6.2.x, the connection limit is set by the httpclient library pool max connections (defaults to 20)

      Root cause (valid for master and 6.2.x)

      S3Store maintains a File cache so that there is no need to download the file from S3 on each request if last modification time did not change. When calling S3Store.getFile() we get the S3Object from S3 service to compare last modification time.

      Whenever we get an S3Object from the S3Service, the input stream to that object is opened, even if we don't download it.

      Usually, Store callers will close that input stream after consuming it. But this can be done only if Store callers retrieve the inputStream from the Store. When callers retrieve a File object from the Store, then it's the Store who has to deal with stream closing.

      When managing File cache, S3Store closes the stream when adding the file to the cache. Subsequent accesses will retrieve the file from cache but forget to close the stream from the S3Object retrieved to compare timestamps.

      All these considerations are valid for 6.2.x even though we use jets3t library to access S3: fetching the S3Object implies that input stream is opened.

        Attachments

          Issue Links

            Activity

              People

              • Assignee:
                haoliang.wu Haoliang Wu (Inactive)
                Reporter:
                daniel.sanz Daniel Sanz
                Participants of an Issue:
                Recent user:
                Brian Wulbern
              • Votes:
                0 Vote for this issue
                Watchers:
                2 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved:
                  Days since last comment:
                  3 years, 39 weeks, 2 days ago

                  Packages

                  Version Package
                  6.2.X EE
                  7.0.0 CE GA1