Have posted some recent patches that I thought would help resolve this issue, but still having the same problems.

When loading a page that has not been visited in a while, it will request JavaScript files that do not exist in S3. After some time passes, new JavaScript files are loaded that do exist in S3, and the page works.

However, this is not a matter of caching -- if I visit the page again a little while later, it returns to the same state. As an example, here are the JS files requested the first few times a given page is loaded (and fails):

/s3fs-js/advagg_js/js__Li7v1YF9lEbIvK3za9RRxCmHJ0YFtTMVhGlk_4X3BYc__gPE5qgf5C1MYNZC_wejpP0_wDv1f0jCdW2iAl_QndCk__BnaddM1d0_Vxx6gPx5Kv7Ke6Klx40k62BA3pbd0Tkpw.js

/s3fs-js/advagg_js/js__zkpioVtqkvev74hko0sDdz5Sev-Fj9ZwZt0h1Jz3gjo__wdbkgtG_FGidQkTywE2bLFDI66htCxyYby-_t0GoVbk__BnaddM1d0_Vxx6gPx5Kv7Ke6Klx40k62BA3pbd0Tkpw.js

/s3fs-js/advagg_js/js__0YMrAP55K1J0I3R84eTCJgfZT6YRIXWOcD20ydlyybU__M9i0OZhAQM9FaL2j_EWHl2WZ0IQ_q4DnfkiCuSKjNGE__BnaddM1d0_Vxx6gPx5Kv7Ke6Klx40k62BA3pbd0Tkpw.js

And then after a certain period of time, the page successfully loads with these JS files, even though no changes have been made to files to be aggregated or AdvAgg settings:

/s3fs-js/advagg_js/js__Li7v1YF9lEbIvK3za9RRxCmHJ0YFtTMVhGlk_4X3BYc__gPE5qgf5C1MYNZC_wejpP0_wDv1f0jCdW2iAl_QndCk__BnaddM1d0_Vxx6gPx5Kv7Ke6Klx40k62BA3pbd0Tkpw.js

/s3fs-js/advagg_js/js__GM3GJPR36rRIz0TRkjC5OQwrioSyN9aoYRivDhCO_AM__qAl84FcCv2jyN22yFGS5Oc85cjd9zKX6p_cFNLGhe-M__BnaddM1d0_Vxx6gPx5Kv7Ke6Klx40k62BA3pbd0Tkpw.js

/s3fs-js/advagg_js/js__3LuYkqUjZCBoSLlHr2m61kSbmsCSqUKFXy8HcWtx3W4__fjMmdyFoQfs65a7ohq9q0rrTzQSedREzEOJ7PEgkNE8__BnaddM1d0_Vxx6gPx5Kv7Ke6Klx40k62BA3pbd0Tkpw.js

I also added some watchdog statements in advagg_build_aggregate_plans, and noticing that the $files_to_aggregate array almost always has values for JS files. Why would this code be running so frequently?

I would think once it is built, it should not change that often.

Comments

ron_s created an issue. See original summary.

sgdev’s picture

sgdev commented
Title: Requested JavaScript files not available in S3 » HTTPRL-generated aggregates causing database to be out of sync with S3 files
Related issues: +#2969512: Big Perfomance Problem with SSL

This is my current setup:
* HTTPRL 7.x-1.x-dev
* AdvAgg 7.x-2.x-dev
* s3fs 7.x-2.10
* Nginx 1.13.12
* HTTPS enabled via port 443

I've spent a lot of time running traces and stepping through AdvAgg code. I have found HTTPRL is running endlessly without receiving a response, causing a situation where a record exists in the database for the AdvAgg aggregate, but no file has been saved to S3 via the s3fs module.

The result is pages are loaded with no CSS or JS, because AdvAgg is referencing aggregates that don't actually exist.

These problems did not occur prior to switching to s3fs and moving our test environment to run everything through https. Could there be a server configuration issue? Maybe it's possible, but everything in the Status Report is telling us HTTPRL is configured correctly (using -1, etc.).

If I disable aggregates from being generated by HTTPRL, everything works without issue.

The HTTPRL code gets stuck in a loop and eventually Nginx reaches timeout after running for about 5 minutes. Here is the part of the trace where AdvAgg hands off to HTTPRL:

   11.9064  -> drupal_is_cli() /sites/all/modules/advagg/advagg_js_compress/advagg_js_compress.advagg.inc:743
   11.9065  -> ini_get() /sites/all/modules/advagg/advagg_js_compress/advagg_js_compress.advagg.inc:747
   11.9065  -> is_callable() /sites/all/modules/advagg/advagg_js_compress/advagg_js_compress.advagg.inc:750
   11.9065  -> getrusage() /sites/all/modules/advagg/advagg_js_compress/advagg_js_compress.advagg.inc:751
   11.9065  -> ini_get() /sites/all/modules/advagg/advagg_js_compress/advagg_js_compress.advagg.inc:754
   11.9065  -> max() /sites/all/modules/advagg/advagg_js_compress/advagg_js_compress.advagg.inc:754
   11.9065  -> count() /sites/all/modules/advagg/advagg_js_compress/advagg_js_compress.advagg.inc:757
   11.9065  -> drupal_set_time_limit() /sites/all/modules/advagg/advagg_js_compress/advagg_js_compress.advagg.inc:7$
   11.9065  -> function_exists() /includes/common.inc:2925
   11.9065  -> ini_get() /includes/common.inc:2926
   11.9065  -> set_time_limit() /includes/common.inc:2929
   11.9065  -> module_exists() /sites/all/modules/advagg/advagg_js_compress/advagg_js_compress.advagg.inc:764
   11.9065  -> module_list() /includes/module.inc:279
   11.9066  -> httprl_is_background_callback_capable() /sites/all/modules/advagg/advagg_js_compress/advagg_js_compress.advagg.inc:764
   11.9066  -> defined() /sites/all/modules/httprl/httprl.module:3306
   11.9066  -> substr() /sites/all/modules/httprl/httprl.module:3306
   11.9066  -> httprl_variable_get() /sites/all/modules/httprl/httprl.module:3306
   11.9066  -> httprl_variable_get() /sites/all/modules/httprl/httprl.module:3306

Once this is done, there are thousands of lines repeating the same HTTPRL tasks over and over. I'm assuming this is HTTPRL waiting for a response and never getting one.

   12.3136  -> usleep() /sites/all/modules/httprl/httprl.module:1736
   12.3187  -> microtime() /sites/all/modules/httprl/httprl.module:1347
   12.3187  -> floor() /sites/all/modules/httprl/httprl.module:1355
   12.3188  -> substr() /sites/all/modules/httprl/httprl.module:1526
   12.3188  -> strtoupper() /sites/all/modules/httprl/httprl.module:1526
   12.3188  -> stream_select() /sites/all/modules/httprl/httprl.module:1531
   12.3189  -> usleep() /sites/all/modules/httprl/httprl.module:1736
   12.3239  -> microtime() /sites/all/modules/httprl/httprl.module:1347
   12.3240  -> floor() /sites/all/modules/httprl/httprl.module:1355
   12.3241  -> substr() /sites/all/modules/httprl/httprl.module:1526
   12.3241  -> strtoupper() /sites/all/modules/httprl/httprl.module:1526
   12.3241  -> stream_select() /sites/all/modules/httprl/httprl.module:1531
   12.3241  -> usleep() /sites/all/modules/httprl/httprl.module:1736
   12.3292  -> microtime() /sites/all/modules/httprl/httprl.module:1347
   12.3292  -> floor() /sites/all/modules/httprl/httprl.module:1355
   12.3293  -> substr() /sites/all/modules/httprl/httprl.module:1526
   12.3293  -> strtoupper() /sites/all/modules/httprl/httprl.module:1526
   12.3294  -> stream_select() /sites/all/modules/httprl/httprl.module:1531
   12.3294  -> usleep() /sites/all/modules/httprl/httprl.module:1736

I notice it also loops through acquiring a lock many times. Maybe a conflict, but could also just be that a new lock is needed given the amount of time it is taking.

   59.9426  -> microtime() /sites/all/modules/contrib/httprl/httprl.module:1347
   59.9426  -> floor() /sites/all/modules/contrib/httprl/httprl.module:1355
   59.9426  -> httprl_establish_stream_connection() /sites/all/modules/contrib/httprl/httprl.module:1481
   59.9426  => microtime() /sites/all/modules/contrib/httprl/httprl.module:991
   59.9426  -> stream_socket_client() /sites/all/modules/contrib/httprl/httprl.module:1023
   59.9454  -> stream_set_blocking() /sites/all/modules/contrib/httprl/httprl.module:1045
   59.9454  -> microtime() /sites/all/modules/contrib/httprl/httprl.module:1049
   59.9454  -> httprl_acquire_lock() /sites/all/modules/contrib/httprl/httprl.module:1488
   59.9454  -> httprl_variable_get() /sites/all/modules/contrib/httprl/httprl.module:2347
   59.9454  -> httprl_variable_get() /sites/all/modules/contrib/httprl/httprl.module:2348
   59.9454  -> max() /sites/all/modules/contrib/httprl/httprl.module:2357
   59.9454  -> httprl_acquire_headless_lock() /sites/all/modules/contrib/httprl/httprl.module:2359
   59.9454  -> lock_acquire() /sites/all/modules/contrib/httprl/httprl.module:2376
   59.9454  -> max() /includes/lock.inc:106
   59.9455  -> microtime() /includes/lock.inc:107
   59.9455  -> db_insert() /includes/lock.inc:128
   59.9455  -> Database::getConnection() /includes/database/database.inc:2486
   59.9455  -> DatabaseConnection->insert() /includes/database/database.inc:2486
   59.9455  -> DatabaseConnection->getDriverClass() /includes/database/database.inc:842
   59.9455  -> InsertQuery->__construct() /includes/database/database.inc:843
   59.9455  -> Query->__construct() /includes/database/query.inc:502
   59.9455  -> uniqid() /includes/database/query.inc:331
   59.9455  -> DatabaseConnection->getKey() /includes/database/query.inc:334
   59.9455  -> DatabaseConnection->getTarget() /includes/database/query.inc:335
   59.9456  -> _lock_id() /includes/lock.inc:131
   59.9456  -> InsertQuery->fields() /includes/lock.inc:133
   59.9456  -> key() /includes/database/query.inc:529
   59.9456  -> is_numeric() /includes/database/query.inc:529
   59.9456  -> array_values() /includes/database/query.inc:530
   59.9456  -> array_keys() /includes/database/query.inc:531
   59.9456  -> InsertQuery_mysql->execute() /includes/lock.inc:134
   59.9456  -> InsertQuery->preExecute() /includes/database/mysql/query.inc:17
   59.9456  -> array_intersect() /includes/database/query.inc:701
   59.9456  -> count() /includes/database/query.inc:715
   59.9456  -> count() /includes/database/query.inc:715
   59.9457  -> InsertQuery_mysql->__toString() /includes/lock.inc:36

I have a file of 325MB worth of trace data, all of this repeating multiple times before I killed the process.

As of right now, I have HTTPRL completely disabled, and using cURL HTTP Request (https://www.drupal.org/project/chr) as a replacement for drupal_http_request. This works without issue.