[error] "Shutting down mod_pagespeed child" after binary upgrade

[GoogleCodeExporter]

What steps will reproduce the problem?
1. upgrade to 1.1.23.1-r2169 binary

What is the expected output?

No [error]'s in the Apache logs.

What do you see instead?

[Tue Nov 13 10:51:34 2012] [error] [mod_pagespeed 1.1.23.1-2169 @29929] 
Shutting down mod_pagespeed child
[Tue Nov 13 10:51:35 2012] [error] [mod_pagespeed 1.1.23.1-2169 @32135] 
Shutting down mod_pagespeed child
[Tue Nov 13 10:51:36 2012] [error] [mod_pagespeed 1.1.23.1-2169 @30753] 
Shutting down mod_pagespeed child
[Tue Nov 13 10:51:37 2012] [error] [mod_pagespeed 1.1.23.1-2169 @32114] 
Shutting down mod_pagespeed child
[Tue Nov 13 10:51:38 2012] [error] [mod_pagespeed 1.1.23.1-2169 @32389] 
Shutting down mod_pagespeed child

What version of the product are you using (please check X-Mod-Pagespeed header)?

- ModPagespeed 1.1.23.1-r2169
- Debian GNU/Linux 6.0.6
- Apache 2.2.16-6

Three (3) separate servers are logging the same errors, proportionate to 
load/traffic.

Creating a 'cache.flush' file results in [warn] level errors:

[Tue Nov 13 11:08:07 2012] [warn] [mod_pagespeed 1.1.23.1-2169 @5177] Cache 
Flush 0
[Tue Nov 13 11:08:08 2012] [warn] [mod_pagespeed 1.1.23.1-2169 @3209] Cache 
Flush 0
[Tue Nov 13 11:08:08 2012] [warn] [mod_pagespeed 1.1.23.1-2169 @5841] Cache 
Flush 0
[Tue Nov 13 11:08:09 2012] [warn] [mod_pagespeed 1.1.23.1-2169 @5087] Cache 
Flush 0
[Tue Nov 13 11:08:09 2012] [warn] [mod_pagespeed 1.1.23.1-2169 @5801] Cache 
Flush 0
...
[Tue Nov 13 11:12:27 2012] [warn] [mod_pagespeed 1.1.23.1-2169 @8107] Cache 
Flush 0
[Tue Nov 13 11:12:28 2012] [warn] [mod_pagespeed 1.1.23.1-2169 @8110] Cache 
Flush 0
[Tue Nov 13 11:12:28 2012] [warn] [mod_pagespeed 1.1.23.1-2169 @8111] Cache 
Flush 0
[Tue Nov 13 11:12:29 2012] [error] [mod_pagespeed 1.1.23.1-2169 @8112] Shutting 
down mod_pagespeed child
[Tue Nov 13 11:12:30 2012] [error] [mod_pagespeed 1.1.23.1-2169 @8113] Shutting 
down mod_pagespeed child
[Tue Nov 13 11:12:31 2012] [error] [mod_pagespeed 1.1.23.1-2169 @7746] Shutting 
down mod_pagespeed child
[Tue Nov 13 11:12:31 2012] [warn] [mod_pagespeed 1.1.23.1-2169 @7725] Cache 
Flush 0
[Tue Nov 13 11:12:32 2012] [error] [mod_pagespeed 1.1.23.1-2169 @7425] Shutting 
down mod_pagespeed child
[Tue Nov 13 11:12:33 2012] [error] [mod_pagespeed 1.1.23.1-2169 @8109] Shutting 
down mod_pagespeed child
[Tue Nov 13 11:12:34 2012] [warn] [mod_pagespeed 1.1.23.1-2169 @8017] Cache 
Flush 0

Which MPM?

prefork

URL of broken page: N/A all appear to be working normally

Original issue reported on code.google.com by dun...@chirp.com.au on 13 Nov 2012 at 9:18

[GoogleCodeExporter]

While our main server is repeating "Cache Flush 0" ad infinitum (600+ already), 
another (VPS) server is counting up:

[Tue Nov 13 11:26:14 2012] [warn] [mod_pagespeed 1.1.23.1-2169 @19810] Cache 
Flush 21
[Tue Nov 13 11:26:17 2012] [warn] [mod_pagespeed 1.1.23.1-2169 @19813] Cache 
Flush 22
[Tue Nov 13 11:26:18 2012] [warn] [mod_pagespeed 1.1.23.1-2169 @19814] Cache 
Flush 23
[Tue Nov 13 11:26:28 2012] [error] [mod_pagespeed 1.1.23.1-2169 @19813] 
Shutting down mod_pagespeed child
[Tue Nov 13 11:26:32 2012] [error] [mod_pagespeed 1.1.23.1-2169 @19809] 
Shutting down mod_pagespeed child
[Tue Nov 13 11:26:33 2012] [error] [mod_pagespeed 1.1.23.1-2169 @19672] 
Shutting down mod_pagespeed child
[Tue Nov 13 11:26:34 2012] [error] [mod_pagespeed 1.1.23.1-2169 @19792] 
Shutting down mod_pagespeed child
[Tue Nov 13 11:26:35 2012] [error] [mod_pagespeed 1.1.23.1-2169 @19528] 
Shutting down mod_pagespeed child
[Tue Nov 13 11:26:38 2012] [warn] [mod_pagespeed 1.1.23.1-2169 @19807] Cache 
Flush 24
...
[Tue Nov 13 11:27:47 2012] [notice] caught SIGTERM, shutting down
[Tue Nov 13 11:27:48 2012] [notice] Apache/2.2.16 (Debian) configured -- 
resuming normal operations
[Tue Nov 13 11:27:53 2012] [warn] [mod_pagespeed 1.1.23.1-2169 @19864] Cache 
Flush 1
[Tue Nov 13 11:27:54 2012] [warn] [mod_pagespeed 1.1.23.1-2169 @19866] Cache 
Flush 2
[Tue Nov 13 11:28:01 2012] [warn] [mod_pagespeed 1.1.23.1-2169 @19867] Cache 
Flush 3

Original comment by dun...@chirp.com.au on 13 Nov 2012 at 9:31

[GoogleCodeExporter]

RE "shutting down mod_pagespeed child": we will downgrade that to 'info' in a 
patch release prior to marking this stable.  I agree; we should not have been 
reporting an error for that as it happens frequently.

I'm going to split off the 'cache flush' issue as a separate bug.

Original comment by jmara...@google.com on 13 Nov 2012 at 1:44

[GoogleCodeExporter]

Original comment by jmara...@google.com on 13 Nov 2012 at 1:46

• Changed state: Started

[GoogleCodeExporter]

cache-flush issue is in Issue 568

Original comment by jmara...@google.com on 13 Nov 2012 at 1:48

[GoogleCodeExporter]

Original comment by jmara...@google.com on 13 Nov 2012 at 2:26

• Added labels: Milestone-v23, release-note

[GoogleCodeExporter]

Hey Duncan, do you also see warnings like this:

[Tue Nov 13 14:04:21 2012] [warn] [mod_pagespeed  @14164] 
[1113/140421:WARNING:queued_worker_pool.cc(425)] Canceling 10 functions on 
sequence Shutdown

And if so, do they annoy you?  Or are they OK?  Although in my working copy 
I've eliminated the child-shutdown error (made it an Info) we still print 
warnings if mod_pagespeed was in the middle of optimizing resources when it was 
told by Apache to shut down.

My guess is that these happen much less often, and are less likely to fill your 
logs, but I thought I'd check with you before closing this issue.

Original comment by jmara...@google.com on 13 Nov 2012 at 7:07

[GoogleCodeExporter]

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

Duncan -- if you are seeing too many those queued_worker_pool warnings I 
described above, please open another bug.  But it'd be useful to know that you 
are.  I admit I do see a few of them in my load tests, though not nearly as 
many as I saw the message about "child shutdown" and I think in a more normal 
site there should not be so many of those messages.

Original comment by jmara...@google.com on 14 Nov 2012 at 12:33

• Changed state: Fixed

[GoogleCodeExporter]

Here is a tally of for the current error.log (last 14 hours):

14,972 x [error] Shutting down mod_pagespeed child
4,405 x [warn] Cache Flush 0
30 x [warn] Fetch failed...
6 x [error] Failed to opendir...
3 x [warn] Fetch timed out...
3 x [error] Failed to rmdir...
1 x [error] Rejected absolute url reference...

There are also some issues with ICO files which I'll report separately.  
Otherwise nothing else is being reported at Apache LogLevel warn.

Original comment by dun...@chirp.com.au on 14 Nov 2012 at 7:12