0002974: Reopen og bug 2420, unable to serve requests with certain versions of apache and mod_caucho

Viewing Issue Advanced Details [ Jump to Notes ]

[ View Simple ] [ Issue History ] [ Print ]

Category

Severity

Reproducibility

Date Submitted

Last Update

0002974

[Resin]

major

always

09-28-08 18:23

10-09-08 16:45

Reporter

ahoogerhuis

View Status

public

Assigned To

ferg

Priority

normal

Resolution

fixed

Platform

Status

closed

Projection

none

OS Version

ETA

none

Fixed in Version

3.1.8

Product Version

3.1.6

Product Build

Summary

0002974: Reopen og bug 2420, unable to serve requests with certain versions of apache and mod_caucho

Description

I've had some serious digging into this one, and the problem seems to be related to line 1068 in common/config.c. In read_all_config() the chain of calls further is cse_match_host_impl() -> cse_update_host() and ends up in cse_update_host() on line 1246, where exection will never get past.

Basically if now = 0, host->last_update = 0 and config->update_interval 15, then theexecution will never get past:

  if (now < host->last_update + config->update_interval) {
    /* If current value is still valid, return */
    return;
  }

and this is a bit chicken and egg:

- resin looks like is saves some of this in /tmp/*_6800 and if that file is not present then host->last_update is initialized to 0, i.e. it will never get in touch with resin to update.

The bug is completely reproducible on CentOS 4.x with httpd 2.0.54, Sun JDK 1.5.0_16, and on Gentoo with apache 2.2.9 and ditto JDK.

Steps To Reproduce

Additional Information

The problem seems to be related to line 1068 in common/config.c:

read_all_config(config_t *config)
{
  if (! read_all_config_impl(config)) {
    /* match all to ensure will not show source if can't connect. */
    resin_host_t *host = 0;
-> time_t now = 0;

    host = cse_match_host_impl(config, "", 0, now);
  }
}

Changing this line to "time_t now = time(&now);" looks to get is past the hurdle, and then into the next problem.

Before editing this /tmp/mod_caucho.log gives:

[09/Sep/2008:05:04:06 +0200] 12300_-1208211776: ../common/config.c:1159:cse_init_config(): initializing
[09/Sep/2008:05:04:06 +0200] 12300_-1208211776: memory.c:62:cse_create_pool(): memory lock 0x8389e18
[09/Sep/2008:05:04:06 +0200] 12300_-1208211776: memory.c:64:cse_create_pool(): create pool 0x838a828
[09/Sep/2008:05:04:06 +0200] 12300_-1208211776: ../common/config.c:1212:cse_init_config(): config lock 0x8389e48
[09/Sep/2008:05:04:06 +0200] 12300_-1208211776: ../common/config.c:1159:cse_init_config(): initializing
[09/Sep/2008:05:04:06 +0200] 12300_-1208211776: memory.c:62:cse_create_pool(): memory lock 0x838c410
[09/Sep/2008:05:04:06 +0200] 12300_-1208211776: memory.c:64:cse_create_pool(): create pool 0x838a838
[09/Sep/2008:05:04:06 +0200] 12300_-1208211776: ../common/config.c:1212:cse_init_config(): config lock 0x838c440
[09/Sep/2008:05:04:06 +0200] 12300_-1208211776: stream.c:926:cse_add_srun(): adding host x.x.x.x:6800 cluster=0x838c3d8
[09/Sep/2008:05:04:06 +0200] 12300_-1208211776: stream.c:981:cse_add_srun(): srun lock 839e370
[09/Sep/2008:05:04:06 +0200] 12300_-1208211776: memory.c:62:cse_create_pool(): memory lock 0x839e390
[09/Sep/2008:05:04:06 +0200] 12300_-1208211776: memory.c:64:cse_create_pool(): create pool 0x838a898
[09/Sep/2008:05:04:06 +0200] 12300_-1208211776: ../common/config.c:1159:cse_init_config(): initializing
[09/Sep/2008:05:04:06 +0200] 12300_-1208211776: memory.c:62:cse_create_pool(): memory lock 0x8389e18
[09/Sep/2008:05:04:06 +0200] 12300_-1208211776: memory.c:64:cse_create_pool(): create pool 0x8381be8
[09/Sep/2008:05:04:06 +0200] 12300_-1208211776: ../common/config.c:1212:cse_init_config(): config lock 0x8389e48
[09/Sep/2008:05:04:06 +0200] 12300_-1208211776: ../common/config.c:1159:cse_init_config(): initializing
[09/Sep/2008:05:04:06 +0200] 12300_-1208211776: memory.c:62:cse_create_pool(): memory lock 0x8397430
[09/Sep/2008:05:04:06 +0200] 12300_-1208211776: memory.c:64:cse_create_pool(): create pool 0x8381bf8
[09/Sep/2008:05:04:06 +0200] 12300_-1208211776: ../common/config.c:1212:cse_init_config(): config lock 0x8397460
[09/Sep/2008:05:04:06 +0200] 12303_-1208211776: stream.c:926:cse_add_srun(): adding host x.x.x.x:6800 cluster=0x83973f8
[09/Sep/2008:05:04:06 +0200] 12303_-1208211776: stream.c:981:cse_add_srun(): srun lock 83aee88
[09/Sep/2008:05:04:06 +0200] 12303_-1208211776: memory.c:62:cse_create_pool(): memory lock 0x83aeea8
[09/Sep/2008:05:04:06 +0200] 12303_-1208211776: memory.c:64:cse_create_pool(): create pool 0x837eb60

Changing the line makes it progress into this:

[09/Sep/2008:05:21:52 +0200] 12837_-1208428864: config.c:1159:cse_init_config(): initializing
[09/Sep/2008:05:21:52 +0200] 12837_-1208428864: memory.c:62:cse_create_pool(): memory lock 0x95bee18
[09/Sep/2008:05:21:52 +0200] 12837_-1208428864: memory.c:64:cse_create_pool(): create pool 0x95bf828
[09/Sep/2008:05:21:52 +0200] 12837_-1208428864: config.c:1212:cse_init_config(): config lock 0x95bee48
[09/Sep/2008:05:21:52 +0200] 12837_-1208428864: config.c:1159:cse_init_config(): initializing
[09/Sep/2008:05:21:52 +0200] 12837_-1208428864: memory.c:62:cse_create_pool(): memory lock 0x95c1410
[09/Sep/2008:05:21:52 +0200] 12837_-1208428864: memory.c:64:cse_create_pool(): create pool 0x95bf838
[09/Sep/2008:05:21:52 +0200] 12837_-1208428864: config.c:1212:cse_init_config(): config lock 0x95c1440
[09/Sep/2008:05:21:52 +0200] 12837_-1208428864: stream.c:926:cse_add_srun(): adding host x.x.x.x:6800 cluster=0x95c13d8
[09/Sep/2008:05:21:52 +0200] 12837_-1208428864: stream.c:981:cse_add_srun(): srun lock 95d3370
[09/Sep/2008:05:21:52 +0200] 12837_-1208428864: memory.c:62:cse_create_pool(): memory lock 0x95d3390
[09/Sep/2008:05:21:52 +0200] 12837_-1208428864: memory.c:64:cse_create_pool(): create pool 0x95bf898
[09/Sep/2008:05:21:52 +0200] 12837_-1208428864: config.c:1269:cse_update_host(): :0(0x95d7fd0) old:0 now:1222658512()
[09/Sep/2008:05:21:52 +0200] 12837_-1208428864: stream.c:1197:cse_reuse_socket(): reuse head:0 tail:0
[09/Sep/2008:05:21:52 +0200] 12837_-1208428864: stream.c:362:cse_connect(): connect 7cbed989:6800 -> 4
[09/Sep/2008:05:21:52 +0200] 12837_-1208428864: stream.c:465:cse_open(): send buffer size 15360
[09/Sep/2008:05:21:52 +0200] 12837_-1208428864: stream.c:470:cse_open(): open new connection 4 7cbed989:6800
[09/Sep/2008:05:21:52 +0200] 12837_-1208428864: stream.c:526:cse_fill_buffer(): write 4 17
[09/Sep/2008:05:21:52 +0200] 12837_-1208428864: memory.c:62:cse_create_pool(): memory lock 0x95d33b0
[09/Sep/2008:05:21:52 +0200] 12837_-1208428864: memory.c:64:cse_create_pool(): create pool 0x95bf8a8
[09/Sep/2008:05:21:52 +0200] 12837_-1208428864: config.c:513:read_config(): hmux config :0
[09/Sep/2008:05:21:52 +0200] 12837_-1208428864: config.c:645:read_config(): hmux header check-interval: 2
[09/Sep/2008:05:21:52 +0200] 12837_-1208428864: config.c:730:read_config(): host :0 exit without valid data
[09/Sep/2008:05:21:52 +0200] 12837_-1208428864: memory.c:119:cse_free_pool(): free pool 0x95bf8a8
[09/Sep/2008:05:21:52 +0200] 12837_-1208428864: stream.c:214:cse_close(): close 4 close
[09/Sep/2008:05:21:52 +0200] 12837_-1208428864: config.c:811:write_config(): writing cached config
[09/Sep/2008:05:21:52 +0200] 12837_-1208428864: config.c:882:write_config(): update :0 -> 0
[09/Sep/2008:05:21:52 +0200] 12837_-1208428864: config.c:1274:cse_update_host(): complete :0(0x95d7fd0) old:0 now:1222658512()
[09/Sep/2008:05:21:52 +0200] 12837_-1208428864: config.c:1159:cse_init_config(): initializing
[09/Sep/2008:05:21:52 +0200] 12837_-1208428864: memory.c:62:cse_create_pool(): memory lock 0x95bee18
[09/Sep/2008:05:21:52 +0200] 12837_-1208428864: memory.c:64:cse_create_pool(): create pool 0x95b6be8
[09/Sep/2008:05:21:52 +0200] 12837_-1208428864: config.c:1212:cse_init_config(): config lock 0x95bee48
[09/Sep/2008:05:21:52 +0200] 12837_-1208428864: config.c:1159:cse_init_config(): initializing
[09/Sep/2008:05:21:52 +0200] 12837_-1208428864: memory.c:62:cse_create_pool(): memory lock 0x95cc430
[09/Sep/2008:05:21:52 +0200] 12837_-1208428864: memory.c:64:cse_create_pool(): create pool 0x95b6bf8
[09/Sep/2008:05:21:52 +0200] 12837_-1208428864: config.c:1212:cse_init_config(): config lock 0x95cc460
[09/Sep/2008:05:21:52 +0200] 12840_-1208428864: stream.c:926:cse_add_srun(): adding host x.x.x.x:6800 cluster=0x95cc3f8
[09/Sep/2008:05:21:52 +0200] 12840_-1208428864: stream.c:981:cse_add_srun(): srun lock 95e3e98
[09/Sep/2008:05:21:52 +0200] 12840_-1208428864: config.c:1043:read_all_config_impl(): hmux header check-interval: 5
[09/Sep/2008:05:21:52 +0200] 12840_-1208428864: config.c:1043:read_all_config_impl(): hmux header cookie: JSESSIONID
[09/Sep/2008:05:21:52 +0200] 12840_-1208428864: config.c:1043:read_all_config_impl(): hmux header session-url-prefix: ;jsessionid=
[09/Sep/2008:05:21:52 +0200] 12840_-1208428864: config.c:1007:read_all_config_impl(): hmux host
[09/Sep/2008:05:21:52 +0200] 12840_-1208428864: memory.c:62:cse_create_pool(): memory lock 0x95e3eb8
[09/Sep/2008:05:21:52 +0200] 12840_-1208428864: memory.c:64:cse_create_pool(): create pool 0x95b3b60
[09/Sep/2008:05:21:52 +0200] 12840_-1208428864: memory.c:62:cse_create_pool(): memory lock 0x95e3ed8
[09/Sep/2008:05:21:52 +0200] 12840_-1208428864: memory.c:64:cse_create_pool(): create pool 0x95b3b70
[09/Sep/2008:05:21:52 +0200] 12840_-1208428864: config.c:513:read_config(): hmux config :0
[09/Sep/2008:05:21:52 +0200] 12840_-1208428864: config.c:645:read_config(): hmux header last-update: 0
[09/Sep/2008:05:21:52 +0200] 12840_-1208428864: config.c:678:read_config(): hmux cluster
[09/Sep/2008:05:21:52 +0200] 12840_-1208428864: config.c:588:read_config(): hmux etag
[09/Sep/2008:05:21:52 +0200] 12840_-1208428864: memory.c:119:cse_free_pool(): free pool 0x95b3b60
[09/Sep/2008:05:21:52 +0200] 12840_-1208428864: config.c:759:read_config(): updated host :0 etag=
[09/Sep/2008:05:21:52 +0200] 12840_-1208428864: stream.c:214:cse_close(): close 4 fill_buffer
[09/Sep/2008:05:21:52 +0200] 12840_-1208428864: config.c:1052:read_all_config_impl(): hmux value X:

Attached Files

Relationships

Notes
(0003478) ahoogerhuis 09-28-08 18:45	Forgot to add, this code behaves just fine on CentOS 5.x. -A

Issue History
Date Modified	Username	Field	Change
09-28-08 18:23	ahoogerhuis	New Issue
09-28-08 18:45	ahoogerhuis	Note Added: 0003478
10-09-08 16:45	ferg	Assigned To	=> ferg
10-09-08 16:45	ferg	Status	new => closed
10-09-08 16:45	ferg	Resolution	open => fixed
10-09-08 16:45	ferg	Fixed in Version	=> 3.1.8

Mantis 1.0.0rc3[^]

29 total queries executed.
26 unique queries executed.