You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@perl.apache.org by Steve Hay <st...@uk.radan.com> on 2003/09/19 18:58:20 UTC
[mp2] Tracing doesn't seem to work on Win32
[Starting a new thread again...]
Stas Bekman wrote:
> Steve Hay wrote:
>
>>> You need to poke in xs/APR/PerlIO/apr_perlio.c
>>> most likely inside: PerlIOAPR_read
>>>
>>> however there is also the tracing option, before you try to step
>>> through with debugger. Try running the test with the 'o' option (o
>>> == IO):
>>>
>>> env MOD_PERL_TRACE=o t/TEST -v apr/perlio
>>>
>>> also you probably want to comment out the rest of the sub-tests in
>>> that file so they won't stand on your way.
>>
>>
>>
>> [After rebuilding mp2 with MP_TRACE=1, which I didn't at first
>> realise I needed to do!...]
>
>
>> This doesn't seem to produce any debug at all, other than a short
>> dump of what the trace options are (confirming that I/O is selected).
>>
>> Weird. There is an MP_TRACE_o() call in PerlIOAPR_read(). I can
>> walk through it in the debugger -- it *does* call modperl_trace() and
>> apparently write stuff out, but it never appears in the error_log.
>
>
> Can you step through to the write and see why it doesn't show up in
> the error_log file?
I've stepped into apr_file_write(). This calls a Win32 API function
called WriteFile() (readwrite.c, line 328), which fails: rv is 0. The
last OS error (GetLastError()) is retrieved via apr_get_os_error(),
which returns a horribly munged value via apr_errno.h. The value is
720,006, which I think corresponds to the GetLastError() value of 6 if
I've waded through all the #define's in apr_errno.h correctly. That
error number corresponds to the message "The handle is invalid".
So apr_file_write() does indeed fail, and reason is that the handle is
invalid. (The value of thefile->filehand is 0x00000170.)
>
>
>> Do other folks have any success using MOD_PERL_TRACE=o on Win32?
>
>
> May be the whole tracing is not working on win32? Can you trace other
> things? e.g. =f for filters? See:
> http://perl.apache.org/docs/2.0/user/config/config.html#C_PerlTrace_
> I think Randy has reported successful tracing before.
I can't get any trace information appearing in the error_log other than
a dump of the trace flags and a few other bits before the server starts
up. I just ran the whole testsuite (except filter, hooks and modules)
with MOD_PERL_TRACE set to "fmo" (filters, memory, I/O) and all I got in
the error_log was this:
=====
[Fri Sep 19 17:50:27 2003] [info] mod_perl: using Perl HASH_SEED: 3907032503
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 On (memory allocations)
o On (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
[Fri Sep 19 17:50:28 2003] [info] 22 Apache:: modules loaded
[Fri Sep 19 17:50:28 2003] [info] 5 APR:: modules loaded
[Fri Sep 19 17:50:28 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
[Fri Sep 19 17:50:31 2003] [info] mod_perl: using Perl HASH_SEED: 3954079015
[Fri Sep 19 17:50:31 2003] [notice] Child 3496: Child process is running
[Fri Sep 19 17:50:31 2003] [notice] Child 3496: Acquired the start mutex.
[Fri Sep 19 17:50:31 2003] [notice] Child 3496: Starting 20 worker threads.
[Fri Sep 19 17:50:31 2003] [debug] child.c(695): Child 3496: Worker
thread 0 starting.
[Fri Sep 19 17:50:31 2003] [debug] child.c(695): Child 3496: Worker
thread 1 starting.
[Fri Sep 19 17:50:31 2003] [debug] child.c(695): Child 3496: Worker
thread 2 starting.
[Fri Sep 19 17:50:31 2003] [debug] child.c(695): Child 3496: Worker
thread 3 starting.
[Fri Sep 19 17:50:31 2003] [debug] child.c(695): Child 3496: Worker
thread 4 starting.
[Fri Sep 19 17:50:31 2003] [debug] child.c(695): Child 3496: Worker
thread 5 starting.
[Fri Sep 19 17:50:31 2003] [debug] child.c(695): Child 3496: Worker
thread 6 starting.
[Fri Sep 19 17:50:31 2003] [debug] child.c(695): Child 3496: Worker
thread 7 starting.
[Fri Sep 19 17:50:31 2003] [debug] child.c(695): Child 3496: Worker
thread 8 starting.
[Fri Sep 19 17:50:31 2003] [debug] child.c(695): Child 3496: Worker
thread 9 starting.
[Fri Sep 19 17:50:31 2003] [debug] child.c(695): Child 3496: Worker
thread 10 starting.
[Fri Sep 19 17:50:31 2003] [debug] child.c(695): Child 3496: Worker
thread 11 starting.
[Fri Sep 19 17:50:31 2003] [debug] child.c(695): Child 3496: Worker
thread 12 starting.
[Fri Sep 19 17:50:31 2003] [debug] child.c(695): Child 3496: Worker
thread 13 starting.
[Fri Sep 19 17:50:31 2003] [debug] child.c(695): Child 3496: Worker
thread 14 starting.
[Fri Sep 19 17:50:31 2003] [debug] child.c(695): Child 3496: Worker
thread 15 starting.
[Fri Sep 19 17:50:31 2003] [debug] child.c(695): Child 3496: Worker
thread 16 starting.
[Fri Sep 19 17:50:31 2003] [debug] child.c(695): Child 3496: Worker
thread 17 starting.
[Fri Sep 19 17:50:31 2003] [debug] child.c(695): Child 3496: Worker
thread 18 starting.
[Fri Sep 19 17:50:31 2003] [debug] child.c(695): Child 3496: Worker
thread 19 starting.
[Fri Sep 19 17:50:47 2003] [info] [client 127.0.0.1] TestAPI::aplog test
in progress
This log message comes with no header
[Fri Sep 19 17:50:47 2003] [debug] aplog.pm(48): log_serror test ok
[Fri Sep 19 17:50:47 2003] [debug] aplog.pm(52): (20014)Error string not
specified yet: log_serror test 2 ok
[Fri Sep 19 17:50:47 2003] [crit] [client 127.0.0.1] (20007)No time was
provided and one was required.: log_rerror test ok
[Fri Sep 19 17:50:47 2003] [error] $r->log_error test ok
[Fri Sep 19 17:50:47 2003] [error] $s->log_error test ok
[Fri Sep 19 17:50:47 2003] [debug] aplog.pm(73): TestAPI::aplog test done
[Fri Sep 19 17:50:47 2003] [warn] ApacheApache->warn test ok
[Fri Sep 19 17:50:47 2003] [warn] $s->warn test ok
[Fri Sep 19 17:51:44 2003] [error] Apache::log_error test ok
[Fri Sep 19 17:52:07 2003] [error] [client 127.0.0.1] Undefined
subroutine &TestError::runtime::no_such_func called at
C:\Temp\modperl-2.0\t\response/TestError/runtime.pm line 19.
[Fri Sep 19 17:52:08 2003] [error] failed to resolve handler
`TestError::syntax'
[Fri Sep 19 17:52:08 2003] [error] [client 127.0.0.1] syntax error at
C:\Temp\modperl-2.0\t\response/TestError/syntax.pm line 22, near "\;"
Compilation failed in require at (eval 128) line 3.
[Fri Sep 19 17:52:25 2003] [error] [client 127.0.0.1] need AuthName:
/TestModperl__setauth
=====
I assume there should have been loads more than that!
Does your tracing work, Randy?
- Steve
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@perl.apache.org
For additional commands, e-mail: dev-help@perl.apache.org
Re: [mp2] Tracing doesn't seem to work on Win32
Posted by Stas Bekman <st...@stason.org>.
Steve Hay wrote:
> Stas Bekman wrote:
>
>> It was a proof of concept hack, so it doesn't matter where you put it,
>> it't not the way to go since you don't want to call
>> modperl_global_get_server_rec() on each trace, even while debugging.
>>
>> Please try this patch (of course first reverting the previous attempt ;)
>
>
> Yup - your "real" patch (below) also fixes the tarcing problem for me.
Coolio, now committed.
Thanks for the debugging help, Steve and Randy!
__________________________________________________________________
Stas Bekman JAm_pH ------> Just Another mod_perl Hacker
http://stason.org/ mod_perl Guide ---> http://perl.apache.org
mailto:stas@stason.org http://use.perl.org http://apacheweek.com
http://modperlbook.org http://apache.org http://ticketmaster.com
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@perl.apache.org
For additional commands, e-mail: dev-help@perl.apache.org
Re: [mp2] Tracing doesn't seem to work on Win32
Posted by Steve Hay <st...@uk.radan.com>.
Stas Bekman wrote:
> It was a proof of concept hack, so it doesn't matter where you put it,
> it't not the way to go since you don't want to call
> modperl_global_get_server_rec() on each trace, even while debugging.
>
> Please try this patch (of course first reverting the previous attempt ;)
Yup - your "real" patch (below) also fixes the tarcing problem for me.
- Steve
>
>
> Index: src/modules/perl/mod_perl.c
> ===================================================================
> RCS file: /home/cvs/modperl-2.0/src/modules/perl/mod_perl.c,v
> retrieving revision 1.185
> diff -u -r1.185 mod_perl.c
> --- src/modules/perl/mod_perl.c 16 Sep 2003 18:47:53 -0000 1.185
> +++ src/modules/perl/mod_perl.c 23 Sep 2003 00:57:24 -0000
> @@ -598,6 +598,12 @@
> MP_dSCFG(s);
> dTHXa(scfg->mip->parent->perl);
> #endif
> +
> + /* httpd core open_logs handler re-opens s->error_log, which
> + * might get a different value on OSes which don't talk
> + * filedescriptors, reset the logfile */
> + modperl_trace_logfile_set(s->error_log);
> +
> ap_add_version_component(pconf, MP_VERSION_STRING);
> ap_add_version_component(pconf,
> Perl_form(aTHX_ "Perl/v%vd",
> PL_patchlevel));
> Index: src/modules/perl/modperl_log.c
> ===================================================================
> RCS file: /home/cvs/modperl-2.0/src/modules/perl/modperl_log.c,v
> retrieving revision 1.8
> diff -u -r1.8 modperl_log.c
> --- src/modules/perl/modperl_log.c 3 Apr 2003 06:25:26 -0000 1.8
> +++ src/modules/perl/modperl_log.c 23 Sep 2003 00:57:24 -0000
> @@ -19,6 +19,11 @@
> return debug_level;
> }
>
> +void modperl_trace_logfile_set(apr_file_t *logfile_new)
> +{
> + logfile = logfile_new;
> +}
> +
> void modperl_trace(const char *func, const char *fmt, ...)
> {
> char vstr[8192];
> @@ -67,7 +72,7 @@
>
> debug_level |= 0x80000000;
>
> - logfile = s->error_log; /* XXX */
> + modperl_trace_logfile_set(s->error_log);
>
> MP_TRACE_a_do(MP_TRACE_dump_flags());
> }
> Index: src/modules/perl/modperl_log.h
> ===================================================================
> RCS file: /home/cvs/modperl-2.0/src/modules/perl/modperl_log.h,v
> retrieving revision 1.10
> diff -u -r1.10 modperl_log.h
> --- src/modules/perl/modperl_log.h 14 Aug 2002 14:54:47 -0000 1.10
> +++ src/modules/perl/modperl_log.h 23 Sep 2003 00:57:24 -0000
> @@ -26,6 +26,8 @@
> #define MP_TIDF \
> (unsigned long)modperl_thread_self()
>
> +void modperl_trace_logfile_set(apr_file_t *logfile_new);
> +
> unsigned long modperl_debug_level(void);
>
> #ifdef WIN32
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@perl.apache.org
For additional commands, e-mail: dev-help@perl.apache.org
Re: [mp2] Tracing doesn't seem to work on Win32
Posted by Stas Bekman <st...@stason.org>.
Steve Hay wrote:
[...]
> Works for me too. I've now got 700kB+ in the error_log from running the
> testsuite. That looks better!
>
> I changed the patch that I applied very slightly to the attached, which
> seems to make a little more sense to me.
>
> - Steve
>
>
> ------------------------------------------------------------------------
>
> --- modperl_log.c.orig 2003-04-03 07:25:26.000000000 +0100
> +++ modperl_log.c 2003-09-22 09:05:17.081033600 +0100
> @@ -2,6 +2,7 @@
> #include "apr_lib.h"
> #include "modperl_trace.h"
> #include "modperl_log.h"
> +#include "mod_perl.h"
>
> #undef getenv /* from XSUB.h */
>
> @@ -25,6 +26,8 @@
> apr_size_t vstr_len = 0;
> va_list args;
>
> + logfile = modperl_global_get_server_rec()->error_log;
> +
> if (!logfile) {
> return;
> }
> @@ -67,7 +70,5 @@
>
> debug_level |= 0x80000000;
>
> - logfile = s->error_log; /* XXX */
> -
> MP_TRACE_a_do(MP_TRACE_dump_flags());
> }
It was a proof of concept hack, so it doesn't matter where you put it, it't
not the way to go since you don't want to call modperl_global_get_server_rec()
on each trace, even while debugging.
Please try this patch (of course first reverting the previous attempt ;)
Index: src/modules/perl/mod_perl.c
===================================================================
RCS file: /home/cvs/modperl-2.0/src/modules/perl/mod_perl.c,v
retrieving revision 1.185
diff -u -r1.185 mod_perl.c
--- src/modules/perl/mod_perl.c 16 Sep 2003 18:47:53 -0000 1.185
+++ src/modules/perl/mod_perl.c 23 Sep 2003 00:57:24 -0000
@@ -598,6 +598,12 @@
MP_dSCFG(s);
dTHXa(scfg->mip->parent->perl);
#endif
+
+ /* httpd core open_logs handler re-opens s->error_log, which
+ * might get a different value on OSes which don't talk
+ * filedescriptors, reset the logfile */
+ modperl_trace_logfile_set(s->error_log);
+
ap_add_version_component(pconf, MP_VERSION_STRING);
ap_add_version_component(pconf,
Perl_form(aTHX_ "Perl/v%vd", PL_patchlevel));
Index: src/modules/perl/modperl_log.c
===================================================================
RCS file: /home/cvs/modperl-2.0/src/modules/perl/modperl_log.c,v
retrieving revision 1.8
diff -u -r1.8 modperl_log.c
--- src/modules/perl/modperl_log.c 3 Apr 2003 06:25:26 -0000 1.8
+++ src/modules/perl/modperl_log.c 23 Sep 2003 00:57:24 -0000
@@ -19,6 +19,11 @@
return debug_level;
}
+void modperl_trace_logfile_set(apr_file_t *logfile_new)
+{
+ logfile = logfile_new;
+}
+
void modperl_trace(const char *func, const char *fmt, ...)
{
char vstr[8192];
@@ -67,7 +72,7 @@
debug_level |= 0x80000000;
- logfile = s->error_log; /* XXX */
+ modperl_trace_logfile_set(s->error_log);
MP_TRACE_a_do(MP_TRACE_dump_flags());
}
Index: src/modules/perl/modperl_log.h
===================================================================
RCS file: /home/cvs/modperl-2.0/src/modules/perl/modperl_log.h,v
retrieving revision 1.10
diff -u -r1.10 modperl_log.h
--- src/modules/perl/modperl_log.h 14 Aug 2002 14:54:47 -0000 1.10
+++ src/modules/perl/modperl_log.h 23 Sep 2003 00:57:24 -0000
@@ -26,6 +26,8 @@
#define MP_TIDF \
(unsigned long)modperl_thread_self()
+void modperl_trace_logfile_set(apr_file_t *logfile_new);
+
unsigned long modperl_debug_level(void);
#ifdef WIN32
__________________________________________________________________
Stas Bekman JAm_pH ------> Just Another mod_perl Hacker
http://stason.org/ mod_perl Guide ---> http://perl.apache.org
mailto:stas@stason.org http://use.perl.org http://apacheweek.com
http://modperlbook.org http://apache.org http://ticketmaster.com
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@perl.apache.org
For additional commands, e-mail: dev-help@perl.apache.org
Re: [mp2] Tracing doesn't seem to work on Win32
Posted by Steve Hay <st...@uk.radan.com>.
Randy Kobes wrote:
>On Fri, 19 Sep 2003, Stas Bekman wrote:
>[ .. ]
>
>
>>It's possible that logfile contains a seemingly valid
>>apr_file_t, but if for some reason s->error_log is
>>closed/reopened, leaving invalid pointer in logfile.
>>
>>remember that modperl_trace_level_set will be called at least twice
>>(start+restart).
>>
>>But may be first try this temp patch:
>>
>>Index: src/modules/perl/modperl_log.c
>>===================================================================
>>RCS file: /home/cvs/modperl-2.0/src/modules/perl/modperl_log.c,v
>>retrieving revision 1.8
>>diff -u -r1.8 modperl_log.c
>>--- src/modules/perl/modperl_log.c 3 Apr 2003 06:25:26 -0000 1.8
>>+++ src/modules/perl/modperl_log.c 19 Sep 2003 17:47:58 -0000
>>@@ -2,6 +2,7 @@
>> #include "apr_lib.h"
>> #include "modperl_trace.h"
>> #include "modperl_log.h"
>>+#include "mod_perl.h"
>>
>> #undef getenv /* from XSUB.h */
>>
>>@@ -28,6 +29,8 @@
>> if (!logfile) {
>> return;
>> }
>>+
>>+ logfile = modperl_global_get_server_rec()->error_log;
>>
>> if (func) {
>> apr_file_printf(logfile, "%s: ", func);
>>
>>
>>
>
>That works for me - thanks, Stas!
>
>
Works for me too. I've now got 700kB+ in the error_log from running the
testsuite. That looks better!
I changed the patch that I applied very slightly to the attached, which
seems to make a little more sense to me.
- Steve
Re: [mp2] Tracing doesn't seem to work on Win32
Posted by Randy Kobes <ra...@theoryx5.uwinnipeg.ca>.
On Fri, 19 Sep 2003, Stas Bekman wrote:
[ .. ]
> It's possible that logfile contains a seemingly valid
> apr_file_t, but if for some reason s->error_log is
> closed/reopened, leaving invalid pointer in logfile.
>
> remember that modperl_trace_level_set will be called at least twice
> (start+restart).
>
> But may be first try this temp patch:
>
> Index: src/modules/perl/modperl_log.c
> ===================================================================
> RCS file: /home/cvs/modperl-2.0/src/modules/perl/modperl_log.c,v
> retrieving revision 1.8
> diff -u -r1.8 modperl_log.c
> --- src/modules/perl/modperl_log.c 3 Apr 2003 06:25:26 -0000 1.8
> +++ src/modules/perl/modperl_log.c 19 Sep 2003 17:47:58 -0000
> @@ -2,6 +2,7 @@
> #include "apr_lib.h"
> #include "modperl_trace.h"
> #include "modperl_log.h"
> +#include "mod_perl.h"
>
> #undef getenv /* from XSUB.h */
>
> @@ -28,6 +29,8 @@
> if (!logfile) {
> return;
> }
> +
> + logfile = modperl_global_get_server_rec()->error_log;
>
> if (func) {
> apr_file_printf(logfile, "%s: ", func);
>
That works for me - thanks, Stas!
--
best regards,
randy
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@perl.apache.org
For additional commands, e-mail: dev-help@perl.apache.org
Re: [mp2] Tracing doesn't seem to work on Win32
Posted by Stas Bekman <st...@stason.org>.
Steve Hay wrote:
[...]
>> Can you step through to the write and see why it doesn't show up in
>> the error_log file?
>
>
> I've stepped into apr_file_write(). This calls a Win32 API function
> called WriteFile() (readwrite.c, line 328), which fails: rv is 0. The
> last OS error (GetLastError()) is retrieved via apr_get_os_error(),
> which returns a horribly munged value via apr_errno.h. The value is
> 720,006, which I think corresponds to the GetLastError() value of 6 if
> I've waded through all the #define's in apr_errno.h correctly. That
> error number corresponds to the message "The handle is invalid".
>
> So apr_file_write() does indeed fail, and reason is that the handle is
> invalid. (The value of thefile->filehand is 0x00000170.)
This could be a problem in mod_perl, please break at modperl_trace_level_set.
It has this code:
logfile = s->error_log; /* XXX */
notice XXX, which probably indicates that it could be wrong. That logfile is a
static variable, I'd start checking from this place to see if it's a valid
apr_file_t variable and then looking inside (using some accessor e.g. you can
get the handle via:
{
apr_status_t rc;
apr_os_file_t os_file;
rc = apr_os_file_get(&os_file, logfile);
if (rc != APR_SUCCESS) {
Perl_croak(aTHX_ "filehandle retrieval failed!");
}
}
It's possible that logfile contains a seemingly valid apr_file_t, but if for
some reason s->error_log is closed/reopened, leaving invalid pointer in logfile.
remember that modperl_trace_level_set will be called at least twice
(start+restart).
But may be first try this temp patch:
Index: src/modules/perl/modperl_log.c
===================================================================
RCS file: /home/cvs/modperl-2.0/src/modules/perl/modperl_log.c,v
retrieving revision 1.8
diff -u -r1.8 modperl_log.c
--- src/modules/perl/modperl_log.c 3 Apr 2003 06:25:26 -0000 1.8
+++ src/modules/perl/modperl_log.c 19 Sep 2003 17:47:58 -0000
@@ -2,6 +2,7 @@
#include "apr_lib.h"
#include "modperl_trace.h"
#include "modperl_log.h"
+#include "mod_perl.h"
#undef getenv /* from XSUB.h */
@@ -28,6 +29,8 @@
if (!logfile) {
return;
}
+
+ logfile = modperl_global_get_server_rec()->error_log;
if (func) {
apr_file_printf(logfile, "%s: ", func);
>>> Do other folks have any success using MOD_PERL_TRACE=o on Win32?
>>
>>
>>
>> May be the whole tracing is not working on win32? Can you trace other
>> things? e.g. =f for filters? See:
>> http://perl.apache.org/docs/2.0/user/config/config.html#C_PerlTrace_
>> I think Randy has reported successful tracing before.
>
>
> I can't get any trace information appearing in the error_log other than
> a dump of the trace flags and a few other bits before the server starts
> up. I just ran the whole testsuite (except filter, hooks and modules)
> with MOD_PERL_TRACE set to "fmo" (filters, memory, I/O) and all I got in
> the error_log was this:
[...]
> I assume there should have been loads more than that!
Indeed.
__________________________________________________________________
Stas Bekman JAm_pH ------> Just Another mod_perl Hacker
http://stason.org/ mod_perl Guide ---> http://perl.apache.org
mailto:stas@stason.org http://use.perl.org http://apacheweek.com
http://modperlbook.org http://apache.org http://ticketmaster.com
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@perl.apache.org
For additional commands, e-mail: dev-help@perl.apache.org