Skip to content
This repository has been archived by the owner on Apr 21, 2023. It is now read-only.

Demote error.log messages "Deadline exceeded for rewrite" from 'error' to 'info' #386

Closed
GoogleCodeExporter opened this issue Apr 6, 2015 · 19 comments
Closed

Demote error.log messages "Deadline exceeded for rewrite" from 'error' to 'info' #386

GoogleCodeExporter opened this issue Apr 6, 2015 · 19 comments
Labels
auto-migrated Milestone-v22 Priority-Medium release-note Type-Defect

Comments

@GoogleCodeExporter
Copy link 

Since installing the latest version, I notice in my logfiles, that I keep 
seeing the error:

[mod_pagespeed 0.10.21.2-1381 @31237] Deadline exceeded for rewrite of resource 
http://www.sellmyretro.com/themes/enuukGreen/img/box1.png with ic

Oddly it only seems to affect three images:
http://www.sellmyretro.com/themes/enuukGreen/img/box1.png
http://www.sellmyretro.com/themes/enuukGreen/img/box2.png
http://www.sellmyretro.com/themes/enuukGreen/img/box3.png

They are not large images and I cannot see why modpagespeed is struggling...

Original issue reported on code.google.com by rwap.services on 18 Feb 2012 at 8:35
@GoogleCodeExporter
Copy link
Author 

It also reports the same for:
http://www.sellmyretro.com/uploaded/img/site-logo.gif

What I do not understand is that if you look at these images (they appear in 
the header of www.sellmyretro.com), image info suggests that they have been 
rewritten...

Original comment by rwap.services on 18 Feb 2012 at 8:38

@GoogleCodeExporter
Copy link
Author 

Hi... Do you have any ModPagespeed*Domain type directives in use?

(There is also a related thread on mod-pagespeed-discuss).

Original comment by morlov...@google.com on 21 Feb 2012 at 2:41

  • Changed state: Started

@GoogleCodeExporter
Copy link
Author 

Yes I do - though they point to the same server - maybe I don't actually need 
them...

    ModPagespeedDomain www.sellmyretro.com
    ModPagespeedDomain sellmyretro.com

    ModPagespeedMapOriginDomain http://www.sellmyretro.com https://www.sellmyretro.com

Original comment by rwap.services on 21 Feb 2012 at 3:48

@GoogleCodeExporter
Copy link
Author 

Very weird. Do you get any accesses in access_log at about the same time that 
seem to be to some variant of site-log.gif but don't match the one in the 
rewritten frontpage?

Original comment by morlov...@google.com on 21 Feb 2012 at 4:46

@GoogleCodeExporter
Copy link
Author 

Hmm - taking an example when this happened at 08:40:33 today.. the access_log 
extract is attached - I can't see anything amiss

Original comment by rwap.services on 21 Feb 2012 at 5:12

Attachments:

@GoogleCodeExporter
Copy link
Author 

It looks like it's just rewriting it on demand (in which case the deadline 
warning isn't too unexpected) but it's very odd that it happens. Any warnings 
about the cache --- and what's your setup like?

How frequently do you get these warnings?

Original comment by morlov...@google.com on 21 Feb 2012 at 6:32

@GoogleCodeExporter
Copy link
Author 

Hmm plenty of warnings given in my logs - as below:

[Tue Feb 21 05:32:47 2012] [error] [mod_pagespeed 0.10.21.2-1381 @10262] Fetch 
failed for 
http://www.sellmyretro.com/themes/enuukGreen/js/themes/enuukGreen/js/animatedcol
lapse.js.pagespeed.jm.RFVt1caA3j.js, status=404
[Tue Feb 21 05:33:03 2012] [error] [client 66.249.71.23] File does not exist: 
/var/www/html/cache
[Tue Feb 21 05:33:04 2012] [error] [client 66.249.71.23] File does not exist: 
/var/www/html/cache
[Tue Feb 21 06:20:20 2012] [error] [mod_pagespeed 0.10.21.2-1381 @18901] 
/var/www/mod_pagespeed/cache/!clean!time!:0: set permission (code=1 Operation 
not permitted)
[Tue Feb 21 06:20:20 2012] [error] [mod_pagespeed 0.10.21.2-1381 @18901] 
/var/www/mod_pagespeed/cache/UxoTFWcNHN8RE0WRJvHC.outputlock:0: failed to stat 
(code=2 No such file or directory)
[Tue Feb 21 06:53:50 2012] [error] [client 193.105.210.118] File does not 
exist: /var/www/html/offer, referer: 
http://www.sellmyretro.com/uploaded/img/1563_9_faceplate_before_after_22f_334_ee
_bfe_24_ad_14.jpg
[Tue Feb 21 06:53:50 2012] [error] [client 193.105.210.118] File does not 
exist: /var/www/html/details, referer: 
http://www.sellmyretro.com/details/uploaded/img/1563_9_faceplate_before_after_22
f_334_ee_bfe_24_ad_14.jpg
[Tue Feb 21 06:54:05 2012] [error] [client 193.105.210.118] File does not 
exist: /var/www/html/offer, referer: 
http://www.sellmyretro.com/uploaded/img/2119_3_ZX81KBMembrane2008_8dcea_a8d_505_
efaa2_55_d8_3a70_dca4_90cec_3f_6dd02_f5a02_c0_7f1.jpg
[Tue Feb 21 06:54:05 2012] [error] [client 193.105.210.118] File does not 
exist: /var/www/html/details, referer: 
http://www.sellmyretro.com/details/uploaded/img/2119_3_ZX81KBMembrane2008_8dcea_
a8d_505_efaa2_55_d8_3a70_dca4_90cec_3f_6dd02_f5a02_c0_7f1.jpg
[Tue Feb 21 07:28:22 2012] [error] [mod_pagespeed 0.10.21.2-1381 @10256] 
/var/www/mod_pagespeed/cache/!clean!time!:0: set permission (code=1 Operation 
not permitted)
[Tue Feb 21 07:28:22 2012] [error] [mod_pagespeed 0.10.21.2-1381 @10256] 
/var/www/mod_pagespeed/cache/QvJQYaEMXUSlaKUIBzbw.outputlock:0: failed to stat 
(code=2 No such file or directory)
[Tue Feb 21 08:31:20 2012] [error] [mod_pagespeed 0.10.21.2-1381 @20182] 
/var/www/mod_pagespeed/cache/!clean!time!:0: set permission (code=1 Operation 
not permitted)
[Tue Feb 21 08:40:33 2012] [error] [mod_pagespeed 0.10.21.2-1381 @10253] 
Deadline exceeded for rewrite of resource 
http://www.sellmyretro.com/themes/enuukGreen/img/box1.png with ic.
[Tue Feb 21 08:40:33 2012] [error] [mod_pagespeed 0.10.21.2-1381 @10262] 
Deadline exceeded for rewrite of resource 
http://www.sellmyretro.com/uploaded/img/site-logo.gif with ic.
[Tue Feb 21 08:40:33 2012] [error] [mod_pagespeed 0.10.21.2-1381 @20171] 
Deadline exceeded for rewrite of resource 
http://www.sellmyretro.com/themes/enuukGreen/img/box2.png with ic.
[Tue Feb 21 08:40:33 2012] [error] [mod_pagespeed 0.10.21.2-1381 @10009] 
Deadline exceeded for rewrite of resource 
http://www.sellmyretro.com/themes/enuukGreen/img/box3.png with ic.
[Tue Feb 21 08:50:41 2012] [error] [client 140.203.154.11] File does not exist: 
/var/www/html/sitemap.xml.gz
[Tue Feb 21 09:14:08 2012] [error] [client 180.76.5.56] File does not exist: 
/var/www/html/message
[Tue Feb 21 09:14:23 2012] [error] [client 180.76.5.100] File does not exist: 
/var/www/html/message
[Tue Feb 21 09:19:22 2012] [error] [client 46.23.70.163] File does not exist: 
/var/www/html/offer
[Tue Feb 21 09:19:22 2012] [error] [mod_pagespeed 0.10.21.2-1381 @10076] 
xbox2.png:0: Resource based on 
http://www.sellmyretro.com/offer/details/themes/enuukGreen/img/box2.png but 
cannot access the original
[Tue Feb 21 09:19:22 2012] [error] [mod_pagespeed 0.10.21.2-1381 @10076] Fetch 
failed for 
http://www.sellmyretro.com/offer/details/themes/enuukGreen/img/xbox2.png.pagespe
ed.ic.zCLBdh32Vx.png, status=404
[Tue Feb 21 09:37:33 2012] [error] [mod_pagespeed 0.10.21.2-1381 @10104] 
/var/www/mod_pagespeed/cache/!clean!time!:0: set permission (code=1 Operation 
not permitted)
[Tue Feb 21 09:37:42 2012] [error] [mod_pagespeed 0.10.21.2-1381 @10253] 
Deadline exceeded for rewrite of resource 
http://www.sellmyretro.com/themes/enuukGreen/img/featuredBackground.gif with ic.
[Tue Feb 21 10:04:19 2012] [error] [client 220.181.108.110] File does not 
exist: /var/www/html/offer
[Tue Feb 21 10:07:35 2012] [error] [client 50.56.64.228] client sent HTTP/1.1 
request without hostname (see RFC2616 section 14.23): 
/w00tw00t.at.ISC.SANS.DFind:)
[Tue Feb 21 10:15:17 2012] [error] [client 123.125.71.74] File does not exist: 
/var/www/html/offer
[Tue Feb 21 10:22:34 2012] [error] [client 123.125.71.87] File does not exist: 
/var/www/html/offer
[Tue Feb 21 10:33:28 2012] [error] [client 123.125.71.56] File does not exist: 
/var/www/html/offer
[Tue Feb 21 10:40:43 2012] [error] [client 123.125.71.13] File does not exist: 
/var/www/html/offer
[Tue Feb 21 10:43:38 2012] [error] [mod_pagespeed 0.10.21.2-1381 @10104] 
/var/www/mod_pagespeed/cache/!clean!time!:0: set permission (code=1 Operation 
not permitted)
[Tue Feb 21 10:51:35 2012] [error] [client 220.181.108.107] File does not 
exist: /var/www/html/offer


You can the warnings happen several times a day, but not every time...

Setup is Centos 5.7 64 bit, running on cloud VPS - 6.5 Ghz processor, 5GB RAM.

Original comment by rwap.services on 22 Feb 2012 at 12:26

@GoogleCodeExporter
Copy link
Author 

There is an interesting entry today in the error.log for my site:

[Mon Feb 27 11:01:11 2012] [error] [mod_pagespeed 0.10.21.2-1381 @12698] 
/var/www/mod_pagespeed/cache/!clean!time!:0: set permission (code=1 Operation 
not permitted)
[Mon Feb 27 11:03:49 2012] [error] [mod_pagespeed 0.10.21.2-1381 @12694] 
Deadline exceeded for rewrite of resource 
https://www.sellmyretro.com/themes/enuukGreen/css,_style.css+css,_color.css+js,_
countdown,_jquery.countdown.css+js,_jquery-ui,_css,_jquery-ui-1.8.16.custom.css.
pagespeed.cc.SrMbFIBj5p.css with cf.
[Mon Feb 27 11:03:53 2012] [error] [mod_pagespeed 0.10.21.2-1381 @17255] 
Deadline exceeded for rewrite of resource 
http://www.sellmyretro.com/uploaded/img/site-logo.gif with ic.
[Mon Feb 27 11:03:54 2012] [error] [mod_pagespeed 0.10.21.2-1381 @4673] 
Deadline exceeded for rewrite of resource 
http://www.sellmyretro.com/themes/enuukGreen/img/box2.png with ic.
[Mon Feb 27 11:03:54 2012] [error] [mod_pagespeed 0.10.21.2-1381 @12052] 
Deadline exceeded for rewrite of resource 
http://www.sellmyretro.com/themes/enuukGreen/img/box3.png with ic.


In particular, why is there an entry:
[Mon Feb 27 11:03:49 2012] [error] [mod_pagespeed 0.10.21.2-1381 @12694] 
Deadline exceeded for rewrite of resource 
https://www.sellmyretro.com/themes/enuukGreen/css,_style.css+css,_color.css+js,_
countdown,_jquery.countdown.css+js,_jquery-ui,_css,_jquery-ui-1.8.16.custom.css.
pagespeed.cc.SrMbFIBj5p.css with cf.


Surely, this resource does not need to be re-written unless any of the source 
files have changed (and they haven't).....

Original comment by rwap.services on 27 Feb 2012 at 11:15

@GoogleCodeExporter
Copy link
Author 

Do you actually have things inside /var/www/mod_pagespeed/cache/? 
Are permissions for this directory OK for mod_pagespeed? 
(Note: that might need an SELinux context as well, since CentOS seems to 
 use it).

It sounds an awful lot like we're cleaning the cache way too frequently for 
some reason --- if it's writing out !clean!time it means it tried to do cache 
cleaning.

Original comment by morlov...@google.com on 27 Feb 2012 at 12:53

@GoogleCodeExporter
Copy link
Author 

Yes /var/www/mod_pagespeed/cache/ is full of items (but also empty 
directories)...

The folder has permission 755 on them, with the user and group set to Apache

Original comment by rwap.services on 27 Feb 2012 at 1:46

@GoogleCodeExporter
Copy link
Author 

You may also need to use ls -lZ to see the security context if you have SELinux 
active. 

Could you tell me a bit more about what your cache configuration is like (e.g. 
cleaning frequency, max size?). One bug I may have just spotted is that we may 
be 
misinterpreting the cache size limit as in bytes and not in kilobytes (but that 
may only be trunk, not stable), which may cause us to delete too much stuff. It 
may be worth to set the LogLevel to info, and grep for "file cache" for a bit 
to see this.

Original comment by morlov...@google.com on 27 Feb 2012 at 3:31

@GoogleCodeExporter
Copy link
Author 

Ermm - not too sure that ls -LZ shows any more information...

> ls -l /var/www/mod_pagespeed/ -lZ
drwxr-xr-x  apache apache                                  cache
drwxrwxr-x  apache apache                                  files

The cache configuration is just the default settings for mod_pagespeed - I have 
not altered these at all (they are still commented out in the .conf file):

    # Other defaults (cache sizes and thresholds):
    # ModPagespeedFileCacheSizeKb          102400
    # ModPagespeedFileCacheCleanIntervalMs 3600000
    # ModPagespeedLRUCacheKbPerProcess     1024
    # ModPagespeedLRUCacheByteLimit        16384
    # ModPagespeedCssInlineMaxBytes        2048
    # ModPagespeedImgInlineMaxBytes        2048
    # ModPagespeedJsInlineMaxBytes         2048
    # ModPagespeedCssOutlineMinBytes       3000
    # ModPagespeedJsOutlineMinBytes        3000

Original comment by rwap.services on 27 Feb 2012 at 3:52

@GoogleCodeExporter
Copy link
Author 

Does the problem occur about every hour or so, then?
Anyway, if my analysis is right, I suggest putting in:

ModPagespeedFileCacheSizeKb          102400000
(note that the extra zeroes) as a workaround.

Original comment by morlov...@google.com on 27 Feb 2012 at 5:28

@GoogleCodeExporter
Copy link
Author 

Yes the notification:

[mod_pagespeed 0.10.21.2-1381 @12698] 
/var/www/mod_pagespeed/cache/!clean!time!:0: set permission (code=1 Operation 
not permitted)

Certainly seems to happen once an hour - I have extended the cache size as 
suggested

Original comment by rwap.services on 28 Feb 2012 at 3:05

@GoogleCodeExporter
Copy link
Author 

We feel the resolution to this is likely to be that we'll stop displaying these 
messages; they are not really problems.

Original comment by jmara...@google.com on 10 May 2012 at 8:10

@GoogleCodeExporter
Copy link
Author

Original comment by jmara...@google.com on 17 May 2012 at 7:40

  • Added labels: Milestone-v22

@GoogleCodeExporter
Copy link
Author

Original comment by jmara...@google.com on 17 May 2012 at 7:41

  • Added labels: release-note

@GoogleCodeExporter
Copy link
Author 

I demoted this 'deadline exceeded' message to Info.

http://code.google.com/p/modpagespeed/source/detail?r=1578

Original comment by jmara...@google.com on 17 May 2012 at 8:15

  • Changed state: Fixed

@GoogleCodeExporter
Copy link
Author 

Summary was: Deadline exceeded for rewrite

Original comment by jmara...@google.com on 25 May 2012 at 2:53

  • Changed title: Demote error.log messages "Deadline exceeded for rewrite" from 'error' to 'info'

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
auto-migrated Milestone-v22 Priority-Medium release-note Type-Defect
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
1 participant
@GoogleCodeExporter