Steve Hay wrote: [...]
OK, so you have t/filter/in_str_consume.t failing with and without LWP and it happens randomly and it's not affected by the PERL_HASH_SEED variable. You didn't tell me what's the error that you get. Or do you get that silent failure as before? If so try with -v and look for error message on the client side, not error_log. This test is special, since the server underreads data sent by the client, it's possible that neither LWP nor TestClient are good at handling that condition.
Here's what I (sometimes!) get running "perl t/TEST -verbose t/filter/in_str_consume.t":
=====
filter/in_str_consume....1..1
# Running under perl version 5.008001 for MSWin32
# Current time local: Mon Sep 22 11:23:46 2003
# Current time GMT: Mon Sep 22 10:23:46 2003
# Using Test.pm version 1.24
# sent 80000B, expecting 105B to make through
# Failed test 1 in filter/in_str_consume.t at line 21
# testing : input stream filter partial consume
# expected: 105
# received:
not ok 1
FAILED test 1
Failed 1/1 tests, 0.00% okay
Failed Test Stat Wstat Total Fail Failed List of Failed
-------------------------------------------------------------------------------
filter/in_str_consume.t 1 1 100.00% 1
=====The error_log contains nothing of interest (only the stuff about the server starting up).
Another thing that will help debuggiing is looking at the trace with MOD_PERL_TRACE=f and -trace=debug. I bet that it fails the moment the filter stops its reading:
env MOD_PERL_TRACE=f t/TEST -verbose -trace=debug t/filter/in_str_consume.t
This should tell you all the story.
It doesn't tell me anything, I'm afraid.
I've attached the complete error_log from a successful run (error_log_ok) and from an unsuccessful run (error_log_nok). I'm not sure it'll tell you much either, to be honest -- there's very little difference :-(
The only shred of interesting behaviour that I've noticed is that I don't seem to be able to make it fail if I use the "-trace=debug" option as you suggested above. I just ran it 24 times on the trot without a single failure! If I take the "-trace=debug" option out then it typically fails at least 2 or 3 times out of 6.
- Steve
[Mon Sep 22 11:15:58 2003] [info] mod_perl: using Perl HASH_SEED: 2221037202 mod_perl trace flags dump:
c Off (configuration for directive handlers)
d Off (directive processing)
f On (filters)
g Off (Perl runtime interaction)
h Off (handlers)
i Off (interpreter pool management)
m Off (memory allocations)
o Off (I/O)
s Off (perl sections)
t Off (benchmark-ish timings)
applied FilterConnectionHandler attribute to ModPerl::TestFilterDebug handler
applied FilterRequestHandler attribute to ModPerl::TestFilterDebug handler
[Mon Sep 22 11:16:00 2003] [info] 22 Apache:: modules loaded
[Mon Sep 22 11:16:00 2003] [info] 5 APR:: modules loaded
[Mon Sep 22 11:16:00 2003] [info] base server + 11 vhosts ready to run tests
applied FilterRequestHandler attribute to TestFilter::in_bbs_body handler
applied FilterInitHandler attribute to TestFilter::in_init_basic handler
applied FilterRequestHandler attribute to TestFilter::in_init_basic handler
applied FilterHasInitHandler(\&transparent_init) attribute to
TestFilter::in_init_basic handler
applied FilterInitHandler attribute to TestFilter::in_init_basic handler
applied FilterHasInitHandler(\&suicide_init) attribute to TestFilter::in_init_basic
handler
applied FilterInitHandler attribute to TestFilter::out_init_basic handler
applied FilterRequestHandler attribute to TestFilter::out_init_basic handler
applied FilterHasInitHandler(get_pre_handler()) attribute to
TestFilter::out_init_basic handler
applied FilterConnectionHandler attribute to TestFilter::in_str_msg handler
applied FilterConnectionHandler attribute to TestFilter::in_bbs_msg handler
[Mon Sep 22 11:16:21 2003] [info] mod_perl: using Perl HASH_SEED: 733671455
[Mon Sep 22 11:16:21 2003] [notice] Child 2000: Child process is running
[Mon Sep 22 11:16:21 2003] [notice] Child 2000: Acquired the start mutex.
[Mon Sep 22 11:16:21 2003] [notice] Child 2000: Starting 20 worker threads.
[Mon Sep 22 11:16:21 2003] [debug] child.c(695): Child 2000: Worker thread 0 starting.
[Mon Sep 22 11:16:21 2003] [debug] child.c(695): Child 2000: Worker thread 1 starting.
[Mon Sep 22 11:16:21 2003] [debug] child.c(695): Child 2000: Worker thread 2 starting.
[Mon Sep 22 11:16:21 2003] [debug] child.c(695): Child 2000: Worker thread 3 starting.
[Mon Sep 22 11:16:21 2003] [debug] child.c(695): Child 2000: Worker thread 4 starting.
[Mon Sep 22 11:16:21 2003] [debug] child.c(695): Child 2000: Worker thread 5 starting.
[Mon Sep 22 11:16:21 2003] [debug] child.c(695): Child 2000: Worker thread 6 starting.
[Mon Sep 22 11:16:21 2003] [debug] child.c(695): Child 2000: Worker thread 7 starting.
[Mon Sep 22 11:16:21 2003] [debug] child.c(695): Child 2000: Worker thread 8 starting.
[Mon Sep 22 11:16:21 2003] [debug] child.c(695): Child 2000: Worker thread 9 starting.
[Mon Sep 22 11:16:21 2003] [debug] child.c(695): Child 2000: Worker thread 10 starting.
[Mon Sep 22 11:16:21 2003] [debug] child.c(695): Child 2000: Worker thread 11 starting.
[Mon Sep 22 11:16:21 2003] [debug] child.c(695): Child 2000: Worker thread 12 starting.
[Mon Sep 22 11:16:21 2003] [debug] child.c(695): Child 2000: Worker thread 13 starting.
[Mon Sep 22 11:16:21 2003] [debug] child.c(695): Child 2000: Worker thread 14 starting.
[Mon Sep 22 11:16:21 2003] [debug] child.c(695): Child 2000: Worker thread 15 starting.
[Mon Sep 22 11:16:21 2003] [debug] child.c(695): Child 2000: Worker thread 16 starting.
[Mon Sep 22 11:16:21 2003] [debug] child.c(695): Child 2000: Worker thread 17 starting.
[Mon Sep 22 11:16:21 2003] [debug] child.c(695): Child 2000: Worker thread 18 starting.
[Mon Sep 22 11:16:21 2003] [debug] child.c(695): Child 2000: Worker thread 19 starting.
TestFilter::in_str_consume::handler
new: request input filter (0x335b198)
TestFilter::in_str_consume::handler::read
TestFilter::in_str_consume::handler
retrieving bb: 0x335d1f0
TestFilter::in_str_consume::handler
wanted: 23 bytes
TestFilter::in_str_consume::handler
read in: HEAP bucket with 8000 bytes (0x91d9d8)
TestFilter::in_str_consume::handler
return: 23 bytes from 1 bucket (7977 bytes leftover)
TestFilter::in_str_consume::handler
return: 0
TestFilter::in_str_consume::handler
new: request input filter (0x335e1d0)
TestFilter::in_str_consume::handler::read
TestFilter::in_str_consume::handler
retrieving bb: 0x3360228
TestFilter::in_str_consume::handler
wanted: 23 bytes
TestFilter::in_str_consume::handler
read in: HEAP bucket with 760 bytes (0x91d978)
TestFilter::in_str_consume::handler
return: 23 bytes from 1 bucket (737 bytes leftover)
TestFilter::in_str_consume::handler
return: 0
TestFilter::in_str_consume::handler
new: request input filter (0x3361208)
TestFilter::in_str_consume::handler::read
TestFilter::in_str_consume::handler
retrieving bb: 0x3363260
TestFilter::in_str_consume::handler
wanted: 23 bytes
TestFilter::in_str_consume::handler
read in: HEAP bucket with 8000 bytes (0x91d918)
TestFilter::in_str_consume::handler
return: 23 bytes from 1 bucket (7977 bytes leftover)
TestFilter::in_str_consume::handler
return: 0
TestFilter::in_str_consume::handler
new: request input filter (0x3364240)
TestFilter::in_str_consume::handler::read
TestFilter::in_str_consume::handler
retrieving bb: 0x3366298
TestFilter::in_str_consume::handler
wanted: 23 bytes
TestFilter::in_str_consume::handler
read in: HEAP bucket with 8000 bytes (0x91d9d8)
TestFilter::in_str_consume::handler
return: 23 bytes from 1 bucket (7977 bytes leftover)
TestFilter::in_str_consume::handler
return: 0
TestFilter::in_str_consume::handler
new: request input filter (0x3367278)
TestFilter::in_str_consume::handler::read
TestFilter::in_str_consume::handler
retrieving bb: 0x33692d0
TestFilter::in_str_consume::handler
wanted: 13 bytes
TestFilter::in_str_consume::handler
read in: HEAP bucket with 8000 bytes (0x91d978)
TestFilter::in_str_consume::handler
return: 13 bytes from 1 bucket (7987 bytes leftover)
TestFilter::in_str_consume::handler::print
TestFilter::in_str_consume::handler
write out: 105 bytes:
TestFilter::in_str_consume::handler
write out: EOS bucket
TestFilter::in_str_consume::handler
return: 0
write out: 3 bytes
from response handler
to byterange filter handler
[Mon Sep 22 11:23:41 2003] [info] mod_perl: using Perl HASH_SEED: 1493328179
mod_perl trace flags dump:
c Off (configuration for directive handlers)
d Off (directive processing)
f On (filters)
g Off (Perl runtime interaction)
h Off (handlers)
i Off (interpreter pool management)
m Off (memory allocations)
o Off (I/O)
s Off (perl sections)
t Off (benchmark-ish timings)
applied FilterConnectionHandler attribute to ModPerl::TestFilterDebug handler
applied FilterRequestHandler attribute to ModPerl::TestFilterDebug handler
[Mon Sep 22 11:23:42 2003] [info] 22 Apache:: modules loaded
[Mon Sep 22 11:23:42 2003] [info] 5 APR:: modules loaded
[Mon Sep 22 11:23:43 2003] [info] base server + 11 vhosts ready to run tests
applied FilterRequestHandler attribute to TestFilter::in_bbs_body handler
applied FilterInitHandler attribute to TestFilter::in_init_basic handler
applied FilterRequestHandler attribute to TestFilter::in_init_basic handler
applied FilterHasInitHandler(\&transparent_init) attribute to
TestFilter::in_init_basic handler
applied FilterInitHandler attribute to TestFilter::in_init_basic handler
applied FilterHasInitHandler(\&suicide_init) attribute to TestFilter::in_init_basic
handler
applied FilterInitHandler attribute to TestFilter::out_init_basic handler
applied FilterRequestHandler attribute to TestFilter::out_init_basic handler
applied FilterHasInitHandler(get_pre_handler()) attribute to
TestFilter::out_init_basic handler
applied FilterConnectionHandler attribute to TestFilter::in_str_msg handler
applied FilterConnectionHandler attribute to TestFilter::in_bbs_msg handler
[Mon Sep 22 11:23:46 2003] [info] mod_perl: using Perl HASH_SEED: 1941371532
[Mon Sep 22 11:23:46 2003] [notice] Child 3740: Child process is running
[Mon Sep 22 11:23:46 2003] [notice] Child 3740: Acquired the start mutex.
[Mon Sep 22 11:23:46 2003] [notice] Child 3740: Starting 20 worker threads.
[Mon Sep 22 11:23:46 2003] [debug] child.c(695): Child 3740: Worker thread 0 starting.
[Mon Sep 22 11:23:46 2003] [debug] child.c(695): Child 3740: Worker thread 1 starting.
[Mon Sep 22 11:23:46 2003] [debug] child.c(695): Child 3740: Worker thread 2 starting.
[Mon Sep 22 11:23:46 2003] [debug] child.c(695): Child 3740: Worker thread 3 starting.
[Mon Sep 22 11:23:46 2003] [debug] child.c(695): Child 3740: Worker thread 4 starting.
[Mon Sep 22 11:23:46 2003] [debug] child.c(695): Child 3740: Worker thread 5 starting.
[Mon Sep 22 11:23:46 2003] [debug] child.c(695): Child 3740: Worker thread 6 starting.
[Mon Sep 22 11:23:46 2003] [debug] child.c(695): Child 3740: Worker thread 7 starting.
[Mon Sep 22 11:23:46 2003] [debug] child.c(695): Child 3740: Worker thread 8 starting.
[Mon Sep 22 11:23:46 2003] [debug] child.c(695): Child 3740: Worker thread 9 starting.
[Mon Sep 22 11:23:46 2003] [debug] child.c(695): Child 3740: Worker thread 10 starting.
[Mon Sep 22 11:23:46 2003] [debug] child.c(695): Child 3740: Worker thread 11 starting.
[Mon Sep 22 11:23:46 2003] [debug] child.c(695): Child 3740: Worker thread 12 starting.
[Mon Sep 22 11:23:46 2003] [debug] child.c(695): Child 3740: Worker thread 13 starting.
[Mon Sep 22 11:23:46 2003] [debug] child.c(695): Child 3740: Worker thread 14 starting.
[Mon Sep 22 11:23:46 2003] [debug] child.c(695): Child 3740: Worker thread 15 starting.
[Mon Sep 22 11:23:46 2003] [debug] child.c(695): Child 3740: Worker thread 16 starting.
[Mon Sep 22 11:23:46 2003] [debug] child.c(695): Child 3740: Worker thread 17 starting.
[Mon Sep 22 11:23:46 2003] [debug] child.c(695): Child 3740: Worker thread 18 starting.
[Mon Sep 22 11:23:46 2003] [debug] child.c(695): Child 3740: Worker thread 19 starting.
TestFilter::in_str_consume::handler
new: request input filter (0x335b198)
TestFilter::in_str_consume::handler::read
TestFilter::in_str_consume::handler
retrieving bb: 0x335d1f0
TestFilter::in_str_consume::handler
wanted: 23 bytes
TestFilter::in_str_consume::handler
read in: HEAP bucket with 7831 bytes (0x91d870)
TestFilter::in_str_consume::handler
return: 23 bytes from 1 bucket (7808 bytes leftover)
TestFilter::in_str_consume::handler
return: 0
TestFilter::in_str_consume::handler
new: request input filter (0x335e1d0)
TestFilter::in_str_consume::handler::read
TestFilter::in_str_consume::handler
retrieving bb: 0x3360228
TestFilter::in_str_consume::handler
wanted: 23 bytes
TestFilter::in_str_consume::handler
read in: HEAP bucket with 8000 bytes (0x91d930)
TestFilter::in_str_consume::handler
return: 23 bytes from 1 bucket (7977 bytes leftover)
TestFilter::in_str_consume::handler
return: 0
TestFilter::in_str_consume::handler
new: request input filter (0x3361208)
TestFilter::in_str_consume::handler::read
TestFilter::in_str_consume::handler
retrieving bb: 0x3363260
TestFilter::in_str_consume::handler
wanted: 23 bytes
TestFilter::in_str_consume::handler
read in: HEAP bucket with 8000 bytes (0x91d8d0)
TestFilter::in_str_consume::handler
return: 23 bytes from 1 bucket (7977 bytes leftover)
TestFilter::in_str_consume::handler
return: 0
TestFilter::in_str_consume::handler
new: request input filter (0x3364240)
TestFilter::in_str_consume::handler::read
TestFilter::in_str_consume::handler
retrieving bb: 0x3366298
TestFilter::in_str_consume::handler
wanted: 23 bytes
TestFilter::in_str_consume::handler
read in: HEAP bucket with 8000 bytes (0x91d870)
TestFilter::in_str_consume::handler
return: 23 bytes from 1 bucket (7977 bytes leftover)
TestFilter::in_str_consume::handler
return: 0
TestFilter::in_str_consume::handler
new: request input filter (0x3367278)
TestFilter::in_str_consume::handler::read
TestFilter::in_str_consume::handler
retrieving bb: 0x33692d0
TestFilter::in_str_consume::handler
wanted: 13 bytes
TestFilter::in_str_consume::handler
read in: HEAP bucket with 8000 bytes (0x91d930)
TestFilter::in_str_consume::handler
return: 13 bytes from 1 bucket (7987 bytes leftover)
TestFilter::in_str_consume::handler::print
TestFilter::in_str_consume::handler
write out: 105 bytes:
TestFilter::in_str_consume::handler
write out: EOS bucket
TestFilter::in_str_consume::handler
return: 0
write out: 3 bytes
from response handler
to byterange filter handler
--------------------------------------------------------------------- To unsubscribe, e-mail: [EMAIL PROTECTED] For additional commands, e-mail: [EMAIL PROTECTED]
