native fetcher test flake in `inline_google_font_css Can inline Google Font API loader CSS`

[jeffkaufman]

TEST: inline_google_font_css Can inline Google Font API loader CSS
      Fetching http://localhost:8050/mod_pagespeed_example/inline_google_font_css.html?PageSpeedFilters=inline_google_font_css    -o /tmp/mod_pagespeed_test.jefftk/fetched_directory/wget_output.txt                                                   -O /tmp/mod_pagespeed_test.jefftk/fetched_directory/wget/fetch_until_output.22367 until $(grep -c @font-face) = 1
wget -q    -o /tmp/mod_pagespeed_test.jefftk/fetched_directory/wget_output.txt                                                   -O /tmp/mod_pagespeed_test.jefftk/fetched_directory/wget/fetch_until_output.22367 http://localhost:8050/mod_pagespeed_example/inline_google_font_css.html?PageSpeedFilters=inline_google_font_css and checking with grep -c @font-face
..
     check_from fgrep -qi format('woff')
     check_not_from fgrep -qi format('truetype')
     check_not_from fgrep -qi format('embedded-opentype')
try:
WGETRC=/tmp/mod_pagespeed_test.jefftk/wgetrc-ie curl -D- http://localhost:8050/mod_pagespeed_example/inline_google_font_css.html?PageSpeedFilters=inline_google_font_css
...

      Fetching http://localhost:8050/mod_pagespeed_example/inline_google_font_css.html?PageSpeedFilters=inline_google_font_css    -o /tmp/mod_pagespeed_test.jefftk/fetched_directory/wget_output.txt                                                   -O /tmp/mod_pagespeed_test.jefftk/fetched_directory/wget/fetch_until_output.22367 until $(grep -c @font-face) = 1
wget -q    -o /tmp/mod_pagespeed_test.jefftk/fetched_directory/wget_output.txt                                                   -O /tmp/mod_pagespeed_test.jefftk/fetched_directory/wget/fetch_until_output.22367 http://localhost:8050/mod_pagespeed_example/inline_google_font_css.html?PageSpeedFilters=inline_google_font_css and checking with grep -c @font-face

To reproduce faster:

echo 'user_agent = Mozilla/4.0 (compatible; MSIE 6.01; Windows NT 6.0)' > tmp.wgetrc
export WGETRC=tmp.wgetrc
while true ; do
    touch ngx_pagespeed/test/tmp/file-cache/cache.flush
    curl -s http://localhost:8050/mod_pagespeed_example/inline_google_font_css.html?PageSpeedFilters=inline_google_font_css \
         | grep '<style>'
    sleep .1
done

Observe:

    ...
    <style>
    <style>
    <style>
    <style>
    <style>
    <style>
    <style>
    <style>
    <style>
    <style>
    <style>
    <style>
    <style>
    <style>
    <style>
    <style>
    <style>
    <style>
    <style>
    <style>
    <style>
    <style>
    <style>
    <style>@font-face {
    <style>
    <style>@font-face {
    <style>
    <style>@font-face {
    <style>
    <style>@font-face {
    <style>
    <style>@font-face {
    <style>
    <style>@font-face {
    <style>
    <style>@font-face {
    <style>
    <style>@font-face {
    <style>
    <style>@font-face {
    <style>
    <style>@font-face {
    <style>
    <style>@font-face {
    <style>
    ...

EDIT: The trace shown above (first no @font-face included, then @font-face consistently included) is fine. The problem is that, at least on my system, we go back to no @font-face after a while.

[jeffkaufman]

It seems likely that #774 and #776 are related.

@dinic are you still up for debugging native fetcher issues?

[jeffkaufman]

I suspect #774 is easier to debug, because it's effectively synchronous: the initial request has to wait until the response gets passed all the way through.

The problem might be as simple as too low a timeout somewhere in the native fetcher.

[jeffkaufman]

The problem might be as simple as too low a timeout somewhere in the native fetcher.

I just did a quick check to make sure we haven't screwed up the units with the timer, and we haven't. It's milliseconds all the way down:

ngx_rewrite_driver_factory.cc:
    NgxUrlAsyncFetcher* fetcher = new NgxUrlAsyncFetcher(
        ...
        config->blocking_fetch_timeout_ms(),
        ...)

ngx_url_async_fetcher.cc:
    fetch_timeout_ = fetch_timeout;

ngx_fetch.cc:
    ngx_add_timer(timeout_event_, fetcher_->fetch_timeout_);

event/ngx_event.h:
    #define ngx_add_timer        ngx_event_add_timer

event/ngx_event_timer.h:
    ngx_event_add_timer(ngx_event_t *ev, ngx_msec_t timer)

[jeffkaufman]

Example output, also added to #774: www.jefftk.com/ngx_pagespeed_issue_776_test_output.txt