Logging problem

[Anthony L]

Hi,

pagespeed generates a lot of message to /var/log/httpd/error_log for each page which is not cached. It is something like 

Q1.

[Thu Jan 14 17:34:09.606052 2016] [pagespeed:error] [pid 25408] [mod_pagespeed 1.9.32.11-7550 @25408] Serf status 4(Interrupted system call) polling for 1 threaded fetches for 0.05 seconds

[Thu Jan 14 17:20:30.022423 2016] [pagespeed:error] [pid 25206] [mod_pagespeed 1.9.32.11-7550 @25206] /var/cache/mod_pagespeed/rname/ic_6gGH_dDYrpUKj5uGtjL0/http,3A/,2Fwww.xxx.com/images/s_60203.jpg,40130x78x,40v_,.tempRHa0VT:0: opening temp file: Permission denied

These kind of messages wouldn't be generated again when I refresh the page.

I'm wondering if these kind of messages important? How can I trace down what makes the first line message? There are plenty of lines with "Interrupted system call" in log file.

If these messages are not important, can I set the log level to eliminate?

Q2.

[Thu Jan 14 18:01:50.691950 2016] [pagespeed:warn] [pid 25809] [mod_pagespeed 1.9.32.11-7550 @25809] Failed to read cache clean timestamp /var/cache/mod_pagespeed/!clean!time!.  Doing an extra cache clean to be safe.

The file permission is as the following:

-rw-------  1 admin admin    13 Jan 14 18:01 !clean!time!

This file was generated automatically, but is it with wrong permission? What makes the error log?

Q3, I found strange directory name,  /var/cache/mod_pagespeed/219.230.216.202/ or /var/cache/mod_pagespeed/v2/http,3A/xxxx/xxxxx. We don't have this IP 219.230.216.202 or the directory path, why this generated there?

Q4. Is it possible to isolate all pagespeed generated log to an individual file under /var/log/pagespeed/ ?

Thank you very much!

[Jeff Kaufman]

These do look important to me: PageSpeed needs to be able to work with
its cache, and it looks like the permissions don't allow that? What
are the permissions on /var/cache/mod_pagespeed/? Are they also
admin/admin?

It looks to me like pagespeed had sufficient permissions to create
some of these files, but now that it's running that's not working. Do
you have something that changes the uid that Apache operates under,
like mod_ruid2? Or did you change permissions recently, maybe by
migrating an existing filesystem to a new server?

I think Q1 and Q2 probably have the same root cause, which is
something fishy about the way permissions are changing over time.

For Q3, it's possible to get bogus directory names in the cache when
bots load your pages with weird Host headers. This shouldn't be a
problem, though, beyond looking messy. How big are those two
directories?

> --
> You received this message because you are subscribed to the Google Groups
> "mod-pagespeed-discuss" group.
> To unsubscribe from this group and stop receiving emails from it, send an
> email to mod-pagespeed-di...@googlegroups.com.
> To view this discussion on the web visit
> https://groups.google.com/d/msgid/mod-pagespeed-discuss/a44bd46f-5469-415f-b62a-e9832bc42f32%40googlegroups.com.
> For more options, visit https://groups.google.com/d/optout.

[Jeff Kaufman]

Sorry, missed your Q4. You can't specify a different log file for
pagespeed, but my guess is once the problems that are causing Q1/Q2
are resolved you won't need that?

[Anthony L]

Hi Jeff,

I have mod_ruid2 for Apache with the lines in configuration file:

<IfModule !mod_ruid2.c>

                SuexecUserGroup admin admin

        </IfModule>

        <IfModule mod_ruid2.c>

                RMode config

                RUidGid admin admin

                #RGroups apache access

                RGroups @none

        </IfModule>

The permission is as the following:

drwxrwxr-x 5 admin apache 4096 Jan 15 10:39 /var/cache/mod_pagespeed

The files under /mod_pagespeed:

-rw-------  1 admin admin    13 Jan 15 10:39 !clean!time!

drwxrwxr-x  4 admin apache 4096 Jan  8 12:57 prop_page

drwxrwxr-x 23 admin apache 4096 Jan 14 17:14 rname

drwxrwxr-x 11 admin apache 4096 Jan 15 11:14 v2

And I found some directories under 'rname' and 'v2' are with webapps.webapps ownership and some others are admin.apache, not sure why they are not consistence under some location.

The server is a brand new system and my first trial to pagespeed, I ever changed the permission for /var/cache/mod_pagespeed/ in earlier time, because I found pagespeed couldn't write to the directory then I change the permission and deleted all files under it and finally it works, but I forget what the original permission was. 

[Jeff Kaufman]

Yes, PageSpeed has trouble working with mod_ruid2 because of the
different permissions. We should probably just say we're not
compatible with mod_ruid2, for the same reason mod_ruid2 isn't
compatible with any other caching modules (like mod_cache), but here
are two workarounds that should work:

* If you have mod_ruid2 configured on a per-VirtualHost basis, define
a separate FileCachePath for each VirtualHost, or
* Use https://developers.google.com/speed/pagespeed/module/system#memcached
instead of the File Cache

We're tracking this here: https://github.com/pagespeed/mod_pagespeed/issues/635

(It also looks like the mod_ruid2 project may have stopped? I don't
see any updates from them since 2013.)

> --
> You received this message because you are subscribed to the Google Groups
> "mod-pagespeed-discuss" group.
> To unsubscribe from this group and stop receiving emails from it, send an
> email to mod-pagespeed-di...@googlegroups.com.
> To view this discussion on the web visit

> https://groups.google.com/d/msgid/mod-pagespeed-discuss/b9ae311d-5fac-41b3-b03c-f88906cbb056%40googlegroups.com.

[Anthony L]

Hi Jeff,

I have tried all combinations of 

Set permission 777 to cache directory and sub-folder   +   mod_ruid2 per VirtualHost   +   disable mod_ruid2 

but gives the same results as previously. The "Serf status 4(Interrupted system call)" keep appear in log whenever pagespeed makes new cache file, despite cache files are created successfully. And the message will not show again when do page refresh. I was thinking if Apache and mod_ruid2 are using different permission for read/write, permission 777 should address out the problem, but actually not. 

[Anthony L]

Just tried to work with memcache,

The kind of message keep showing in log file, 

[Mon Jan 18 12:11:36.513598 2016] [pagespeed:error] [pid 18490] [mod_pagespeed 1.9.32.11-7550 @18569] AprMemCache::Put error: Could not find specified socket in poll list. (70015) on key rname/ic_1k0K4ulitL5-PRZzPx7X/http://xxxxxx.......gif@200x113x@v_, value-size 269

[Mon Jan 18 12:12:09.267220 2016] [pagespeed:error] [pid 18569] [mod_pagespeed 1.9.32.11-7550 @18608] AprMemCache::Put error: Interrupted system call (4) on key v2/zzz.com/http://xxxx........jpg, value-size 18490

These message show up in log when the corresponding cache file is not exist, but the cache file are actually created. When I refresh the page, since the cached file exist then these errors are not showing up again. This situation appear in both file cache and memcache cache.

[Jeff Kaufman]

I think those AprMemCache::Put errors may be unrelated to mod_ruid2;
how much load are you putting on the memcached? How often are these
errors showing up?

> --
> You received this message because you are subscribed to the Google Groups
> "mod-pagespeed-discuss" group.
> To unsubscribe from this group and stop receiving emails from it, send an
> email to mod-pagespeed-di...@googlegroups.com.
> To view this discussion on the web visit

> https://groups.google.com/d/msgid/mod-pagespeed-discuss/54d9652c-4ca6-435a-abe3-630eed97d1cc%40googlegroups.com.

[Joshua Marantz]

Hi -- I have two things to add:

1. You indicated earlier you tried configuring mod_ruid2 on a per-vhost basis, however, that is not the workaround we suggested.  We suggested having a separate file-cache for each vhost.   I don't think we made this clear, but we need the file-cache for each vhost should be a separate directory.  That way the file-permissions might work better.

2. memcached should be a good workaround for the file-permissions problems, but it looks like you might be getting timeout errors. I just want to verify one thing: are you using actual memcached, or something else that speaks the same protocol?  We have seen trouble with other users that have memcached-like implementations or proxies (e.g. HAProxy) interposed.

You said "messages keep showing up"....it's helpful to us to quantify that.  The system is designed so that if there are timeout or other errors communication with memcached more than 3 times in 30 seconds, we'll turn off our access to memcached for 30 seconds, and then try again.  If this happens (say) 5 or 6 times per day, that's probably fine.  It means that there were a few spikes of activity on your server causing timeouts, and the system recovered and continued working fine.

However, if you see those reports coming up 3 or 4 times every 30 seconds (the log messages are timestamped) then the system is really not working as intended.

-Josh

To view this discussion on the web visit https://groups.google.com/d/msgid/mod-pagespeed-discuss/CAMJ6YUtcHks94PtGiXOq4mmejX3_zHr7tDRb5GbRPfPewG-3sg%40mail.gmail.com.

[Anthony L]

I'm using latest version memcached and initial RAM is 512MB, since this is a testing machine so there is no traffic.

I just monitor the log frequency and give the following result:

With disk cache:

Refresh same page within 3 minutes, there is no error in log. Around 4 minutes, it gives Serf status 4(Interrupted system call)

With memcache:

Refresh same page within 4 minutes, there is no error in log. Around 5 minutes, it gives

  AprMemCache::Put error: Interrupted system call (4) on key.....

  AprMemCache::Put error: Could not find specified socket in poll list. (70015) on key...

  Serf status 4(Interrupted system call)...

each of the error types above appear 2-4 times when I did refresh and I guess it relates to the number of images on the page.

Since both methods has "Serf status 4(Interrupted system call)" in log when I do page refresh for every 6-7 minutes, so is it a normal behavior but not caused by mod_ruid2? is it possible to eliminate?

[Anthony L]

Compare both, memcache gives much lesser  "Serf status 4(Interrupted system call)" than disk cache to log

[Anthony L]

Hi Jeff and Josh,

As you suggested I should use separate file-cache for each vhost, do you mean I should put the line like the following to each of vhost?

   ModPagespeedFileCachePath            "/var/cache/mod_pagespeed/domainA.com"

[Joshua Marantz]

Yes, that way each of those subdirectories can have files owned exclusively by the user-id configured with that domain in mod_ruid2.  Please let us know how that turns out!

-Josh

--
You received this message because you are subscribed to the Google Groups "mod-pagespeed-discuss" group.
To unsubscribe from this group and stop receiving emails from it, send an email to mod-pagespeed-di...@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msgid/mod-pagespeed-discuss/3483e36d-b3bc-48d0-8d31-f599bedbbcbd%40googlegroups.com.

[Anthony L]

Just tested, it has created the corresponding vhost in cache directory, but keep showing "Serf status 4(Interrupted system call)" in log as previously.

[Joshua Marantz]

The Serf status thing sounds like something else.  But that should hopefully stop the log messages about file permissions.  Does it?

RE serf status: can you paste some statistics from /pagespeed_admin/statististics?  Put 'serf' in the filter box.

-Josh

On Thu, Jan 21, 2016 at 7:29 AM, Anthony L <nexplo...@gmail.com> wrote:

Just tested, it has created the corresponding vhost in cache directory, but keep showing "Serf status 4(Interrupted system call)" in log as previously.

--
You received this message because you are subscribed to the Google Groups "mod-pagespeed-discuss" group.
To unsubscribe from this group and stop receiving emails from it, send an email to mod-pagespeed-di...@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msgid/mod-pagespeed-discuss/fdcce9b2-6c72-4b7e-be9b-ad7408e13545%40googlegroups.com.

[Anthony L]

Yes, it is better now, but not completely gone, sometime it complain no permission to delete cached file.

All file with the permission like 

-rw-------   1 admin admin

As they were created by mod_pagespeed, it is weird unable to remove. I will keep monitor the log now.

The statistic likes the following

serf_fetch_active_count
0
0
serf_fetch_bytes_count
150339473
1
serf_fetch_cancel_count
1
1
serf_fetch_cert_errors
0
0
serf_fetch_failure_count
1
1
serf_fetch_request_count
17789
1
serf_fetch_time_duration_ms
718119
1
serf_fetch_timeout_count
0
0