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

Viewing Issue Simple Details [ Jump to Notes ]

[ View Advanced ] [ 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

Status

closed

Product Version

3.1.6

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.

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.