Virtual host logging

[Sk8board Kid]

I have mod_wsgi working with virtual hosts, as you know apache as a
"main" log and then a log for each vhost (configured). normal http
problems get written to the vhost log but wsgi/python errors get
written to the main log.

i have increased my log level to "debug" but still nothing in the
vhost log, but all the "correct" info in the main apache log.

here is an example of my config:

<VirtualHost www.x:8080>
ServerName www.x
CustomLog "|/usr/local/apache2/bin/rotatelogs /x/logs/
access_log 10M" combined
ErrorLog /x/wsgi_error_log
DocumentRoot /x/htdocs
<Directory /x/htdocs>
AllowOverride All
</Directory>
WSGIScriptAlias /wsgi/ /x/wsgi/
<Directory /x/wsgi>
WSGIApplicationGroup wsgi-x
</Directory>
WSGIDaemonProcess www.x user=x group=x processes=2 threads=25
WSGIProcessGroup www.x
</VirtualHost>

any ideas?

info such as the following appears in the main log:

[Wed Apr 30 01:15:36 2008] [error] [client x] mod_wsgi (pid=17388):
Target WSGI script '/x/run_wsgi.py' cannot be loaded as Python module.
[Wed Apr 30 01:15:36 2008] [error] [client x] mod_wsgi (pid=17388):
Exception occurred processing WSGI script '/x/run_wsgi.py'.
[Wed Apr 30 01:15:36 2008] [error] [client x] Traceback (most recent
call last):
[Wed Apr 30 01:15:36 2008] [error] [client x] File "/x/run_wsgi.py",
line 54, in <module>
[Wed Apr 30 01:15:36 2008] [error] [client x] from lib import
dblib
[Wed Apr 30 01:15:36 2008] [error] [client x] ImportError: No module
named lib

which is what i would like to get in the vhost log.

[Graham Dumpleton]

2008/4/30 Sk8board Kid <sk8bo...@gmail.com>:

Were you just monitoring separate discussion where this issue was
being talked about and thus decided to post about your own problem, or
was it just coincidence? Anyway, now that this thread exists and has
appropriate subject line I can use it. If you weren't watching other
thread, this problem has an issue at:

http://code.google.com/p/modwsgi/issues/detail?id=79

The other thread where it was mentioned is:

http://groups.google.com/group/modwsgi/browse_frm/thread/e56854857756d151

Previously I only knew of only one reported case, now I have two more
pop up, so hopefully this time can get enough details back to work out
what is going on. :-)

A few quick questions below, but I'll have more later when have a
chance, plus some actual examples to run to test a few different
things out about the problem.

First question is, does it still not work as expected when daemon mode
is not run as a distinct user and instead allowed to run as Apache
user.

Second question is, can you confirm that when you say 'Target WSGI
script '/x/run_wsgi.py' cannot be loaded as Python module' appears in
main Apache error log, that that is occurring now even when ErrorLog
directive is defined inside VirtualHost.

Final questions for now are, what operating system platform are you
using, what version of Apache and is Apache prefork or worker MPM? Is
this Apache compiled from source code or a binary which comes with the
operating system?

Thanks.

Graham

[Graham Dumpleton]

2008/4/30 Graham Dumpleton <graham.d...@gmail.com>:

Next question. Can you run:

httpd -t -D DUMP_MODULES

Replace 'httpd' with actual name of Apache executable, if different,
eg. 'apache2'.

Send the output, it should be a list of Apache modules that would be
loaded for your Apache configuration. This will help me to work out
whether there are any specific Apache modules being loaded that
feasibly could be causing the problems.

Thanks.

Graham

[Graham Dumpleton]

Sorry, another request. Hopefully Alberto can also try this one when
he as woken up.

Can you possibly check out source from subversion repository trunk and
compile/run it instead. For details see:

http://code.google.com/p/modwsgi/source/checkout

If you don't have subversion client handy, then at least download the file:

http://modwsgi.googlecode.com/svn/trunk/mod_wsgi/mod_wsgi.c

and use it instead of mod_wsgi.c file from your existing source code.
Existing makefiles should still work.

Can you run this version with LogLevel of 'debug' specified in main
part of Apache configuration, outside of any VirtualHost.

What I am after are certain startup messages from the main Apache
error log file (not VirtualHost). In particular, look for messages of
the form:

[Wed Apr 30 21:23:38 2008] [info] mod_wsgi (pid=3944): Starting
process 'dummy1' with uid=501, gid=20 and threads=15.
[Wed Apr 30 21:23:38 2008] [debug] mod_wsgi.c(8953): mod_wsgi
(pid=3944): Process 'dummy1' logging to 'dummy-host.example.com' with
log level 7.

The process ID, daemon process name and host name obviously will be
specific to your system and that run of Apache. Note that these lines
may not be adjacent to each other in the error log file for the
process ID in question, so hunt through and see if you can find both.

Instead of the second line, if code picks up something strange has
happened, it may instead say:

[Wed Apr 30 21:23:38 2008] [debug] mod_wsgi.c(8953): mod_wsgi
(pid=3944): Process 'dummy1' forced to log to
'graham-dumpletons-imac.local' with log level 7.

Being able to see if these log messages are present will serve two
purposes. The first is that the 'Starting process' message is the
first message logged after the daemon process has been forked, it is
logged while the daemon process it still running as 'root'. If this
message appears in the log file, then it at least says that the open
file for main Apache error log file has survived the fork.

The second is that the latter log message shows what server context
mod_wsgi believes it is logging via. That is, via VirtualHost or main
server context. In practice this should just show whether
WSGIDaemonProcess was used inside of VirtualHost or not.

As well as above, can you also go looking in the VirtualHost specific
error log file and see if you can find any error messages for the same
process ID as being looked for in main Apache error log file. In this
case am wanting to know if the following line appears:

[Wed Apr 30 21:23:38 2008] [info] mod_wsgi (pid=3944): Attach interpreter ''.

This being present will confirm whether any output to VirtualHost
specific error log file is working and also that it is working after
the daemon process has swapped to running as non 'root' user.

Depending on how that goes, I'll make further changes to code to
verify that error_log attribute of server context being used is in
fact non zero as it should be and possibly attempt to log to
VirtualHost specific error log file in daemon process when still
running as 'root'.

If you can delete existing error log files before starting, you could
also just send both main and VirtualHost error logs to me as
attachments after having started/stopped Apache once, no need to do
request at this point. Being able to see all the other messages might
give me other ideas of what the problem is.

Hopefully you can try and work through this for me and provide
feedback on each part I have asked about. I am really going to need to
understand exactly what happens at each point with this since I can't
duplicate it myself.

Thanks.

Graham

[Sk8board Kid]

I'll try to answer all your questions:

1) i haven't tried running with daemon mode under the same user as
apache as we need this extra security.

2) yes the python script errors still output to the "main" log even
with the error logs defined in the vhost.

3) Linux www 2.6.21.5 #3 SMP i386
Server version: Apache/2.0.61
prefork MPM used
compiled from source

4) cant find DUMP_MODULES:

httpd -f wsgi_httpd.conf -t -D DUMP_MODULES
Syntax OK

./httpd -h
Usage: ./httpd [-D name] [-d directory] [-f file]
[-C "directive"] [-c "directive"]
[-k start|restart|graceful|stop]
[-v] [-V] [-h] [-l] [-L] [-t] [-S]
Options:
-D name : define a name for use in <IfDefine name>
directives
-d directory : specify an alternate initial ServerRoot
-f file : specify an alternate ServerConfigFile
-C "directive" : process directive before reading config files
-c "directive" : process directive after reading config files
-e level : show startup errors of level (see LogLevel)
-E file : log startup errors to file
-v : show version number
-V : show compile settings
-h : list available command line options (this page)
-l : list compiled in modules
-L : list available configuration directives
-t -D DUMP_VHOSTS : show parsed settings (currently only vhost
settings)
-S : a synonym for -t -D DUMP_VHOSTS
-t : run syntax check for config files

Compiled in modules:
core.c
mod_access.c
mod_auth.c
mod_include.c
mod_log_config.c
mod_env.c
mod_setenvif.c
prefork.c
http_core.c
mod_mime.c
mod_status.c
mod_autoindex.c
mod_asis.c
mod_suexec.c
mod_cgi.c
mod_negotiation.c
mod_dir.c
mod_imap.c
mod_actions.c
mod_userdir.c
mod_alias.c
mod_so.c

modules loaded:

LoadModule info_module modules/mod_info.so
LoadModule rewrite_module modules/mod_rewrite.so
LoadModule headers_module modules/mod_headers.so
LoadModule wsgi_module modules/mod_wsgi.so

5) we are currently using mod_wsgi-2.0c4.tar.gz how much has changed
since this release?

6) We are running with debug logging on this server already here is
our current output:

in the main log:

[Wed Apr 30 22:43:10 2008] [info] mod_wsgi (pid=19473): Cleanup
interpreter ''.
[Wed Apr 30 22:43:10 2008] [info] mod_wsgi (pid=19473): Terminating
Python.
[Wed Apr 30 22:43:10 2008] [info] mod_wsgi (pid=19604): Cleanup
interpreter ''.
[Wed Apr 30 22:43:10 2008] [info] mod_wsgi (pid=22860): Cleanup
interpreter ''.
[Wed Apr 30 22:43:10 2008] [info] mod_wsgi (pid=19604): Terminating
Python.
[Wed Apr 30 22:43:10 2008] [info] mod_wsgi (pid=22860): Terminating
Python.
[Wed Apr 30 22:43:10 2008] [info] removed PID file /x/wsgi_httpd.pid
(pid=17348)
[Wed Apr 30 22:43:10 2008] [notice] caught SIGTERM, shutting down
[Wed Apr 30 22:43:18 2008] [notice] suEXEC mechanism enabled
(wrapper: /x/suexec)
[Wed Apr 30 22:43:18 2008] [info] mod_wsgi: Initializing Python.
[Wed Apr 30 22:43:19 2008] [debug] mod_wsgi.c(7259): mod_wsgi
(pid=23992): Socket for 'www.x' is '/x/wsgi.23988.0.1.sock'.
[Wed Apr 30 22:43:19 2008] [info] mod_wsgi (pid=23996): Starting
process 'www.x' with uid=511, gid=102 and threads=25.
[Wed Apr 30 22:43:19 2008] [info] mod_wsgi (pid=23999): Starting
process 'www.x' with uid=511, gid=102 and threads=25.
[Wed Apr 30 22:43:19 2008] [debug] mod_wsgi.c(7259): mod_wsgi
(pid=23992): Socket for 'www.y' is '/y/wsgi.23988.0.2.sock'.
[Wed Apr 30 22:43:19 2008] [info] mod_wsgi (pid=24004): Starting
process 'www.y' with uid=3966, gid=102 and threads=25.
[Wed Apr 30 22:43:19 2008] [info] mod_wsgi (pid=24008): Starting
process 'www.y' with uid=3966, gid=102 and threads=25.
[Wed Apr 30 22:43:19 2008] [debug] mod_wsgi.c(7259): mod_wsgi
(pid=23992): Socket for 'www.z' is '/z/wsgi.23988.0.3.sock'.
[Wed Apr 30 22:43:19 2008] [info] mod_wsgi (pid=24059): Starting
process 'www.z' with uid=3937, gid=102 and threads=25.
[Wed Apr 30 22:43:19 2008] [info] mod_wsgi (pid=24073): Starting
process 'www.z' with uid=3937, gid=102 and threads=25.
[Wed Apr 30 22:43:19 2008] [info] mod_wsgi (pid=24090): Attach
interpreter ''.
[Wed Apr 30 22:43:19 2008] [notice] Apache configured -- resuming
normal operations
[Wed Apr 30 22:43:19 2008] [info] Server built: Oct 25 2007 23:49:08
[Wed Apr 30 22:43:19 2008] [debug] prefork.c(956): AcceptMutex:
sysvsem (default: sysvsem)
[Wed Apr 30 22:43:20 2008] [info] mod_wsgi (pid=24236): Attach
interpreter ''.

in one of the vhost logs:

[Wed Apr 30 22:43:19 2008] [debug] mod_wsgi.c(7816): mod_wsgi
(pid=24059): Starting thread 7 in daemon process
'www.ssbg.devisland.net'.
[Wed Apr 30 22:43:19 2008] [debug] mod_wsgi.c(7816): mod_wsgi
(pid=24059): Starting thread 8 in daemon process
'www.ssbg.devisland.net'.
[Wed Apr 30 22:43:19 2008] [debug] mod_wsgi.c(7816): mod_wsgi
(pid=24059): Starting thread 9 in daemon process
'www.ssbg.devisland.net'.
[Wed Apr 30 22:43:19 2008] [debug] mod_wsgi.c(7816): mod_wsgi
(pid=24073): Starting thread 5 in daemon process
'www.ssbg.devisland.net'.
[Wed Apr 30 22:43:19 2008] [debug] mod_wsgi.c(7816): mod_wsgi
(pid=24073): Starting thread 6 in daemon process
'www.ssbg.devisland.net'.
[Wed Apr 30 22:43:19 2008] [debug] mod_wsgi.c(7816): mod_wsgi
(pid=24073): Starting thread 7 in daemon process
'www.ssbg.devisland.net'.
[Wed Apr 30 22:43:19 2008] [debug] mod_wsgi.c(7816): mod_wsgi
(pid=24073): Starting thread 8 in daemon process
'www.ssbg.devisland.net'.
[Wed Apr 30 22:43:19 2008] [debug] mod_wsgi.c(7816): mod_wsgi
(pid=24073): Starting thread 9 in daemon process
'www.ssbg.devisland.net'.
[Wed Apr 30 22:43:19 2008] [debug] mod_wsgi.c(7816): mod_wsgi
(pid=24073): Starting thread 10 in daemon process
'www.ssbg.devisland.net'.
[Wed Apr 30 22:43:19 2008] [debug] mod_wsgi.c(7816): mod_wsgi
(pid=24073): Starting thread 11 in daemon process
'www.ssbg.devisland.net'.
[Wed Apr 30 22:43:19 2008] [debug] mod_wsgi.c(7816): mod_wsgi
(pid=24073): Starting thread 12 in daemon process
'www.ssbg.devisland.net'.
[Wed Apr 30 22:43:19 2008] [debug] mod_wsgi.c(7816): mod_wsgi
(pid=24073): Starting thread 13 in daemon process
'www.ssbg.devisland.net'.
[Wed Apr 30 22:43:19 2008] [debug] mod_wsgi.c(7816): mod_wsgi
(pid=24073): Starting thread 14 in daemon process
'www.ssbg.devisland.net'.
[Wed Apr 30 22:43:19 2008] [debug] mod_wsgi.c(7816): mod_wsgi
(pid=24059): Starting thread 10 in daemon process
'www.ssbg.devisland.net'.
[Wed Apr 30 22:43:19 2008] [debug] mod_wsgi.c(7816): mod_wsgi
(pid=24059): Starting thread 11 in daemon process
'www.ssbg.devisland.net'.
[Wed Apr 30 22:43:19 2008] [debug] mod_wsgi.c(7816): mod_wsgi
(pid=24059): Starting thread 12 in daemon process
'www.ssbg.devisland.net'.
[Wed Apr 30 22:43:19 2008] [debug] mod_wsgi.c(7816): mod_wsgi
(pid=24059): Starting thread 13 in daemon process
'www.ssbg.devisland.net'.
[Wed Apr 30 22:43:19 2008] [debug] mod_wsgi.c(7816): mod_wsgi
(pid=24059): Starting thread 14 in daemon process
'www.ssbg.devisland.net'.
[Wed Apr 30 22:43:19 2008] [debug] mod_wsgi.c(7816): mod_wsgi
(pid=24059): Starting thread 15 in daemon process
'www.ssbg.devisland.net'.
[Wed Apr 30 22:43:19 2008] [debug] mod_wsgi.c(7816): mod_wsgi
(pid=24059): Starting thread 16 in daemon process
'www.ssbg.devisland.net'.
[Wed Apr 30 22:43:19 2008] [debug] mod_wsgi.c(7816): mod_wsgi
(pid=24059): Starting thread 17 in daemon process
'www.ssbg.devisland.net'.
[Wed Apr 30 22:43:19 2008] [debug] mod_wsgi.c(7816): mod_wsgi
(pid=24073): Starting thread 15 in daemon process
'www.ssbg.devisland.net'.
[Wed Apr 30 22:43:19 2008] [debug] mod_wsgi.c(7816): mod_wsgi
(pid=24059): Starting thread 18 in daemon process
'www.ssbg.devisland.net'.
[Wed Apr 30 22:43:19 2008] [debug] mod_wsgi.c(7816): mod_wsgi
(pid=24059): Starting thread 19 in daemon process
'www.ssbg.devisland.net'.
[Wed Apr 30 22:43:19 2008] [debug] mod_wsgi.c(7816): mod_wsgi
(pid=24073): Starting thread 16 in daemon process
'www.ssbg.devisland.net'.
[Wed Apr 30 22:43:19 2008] [debug] mod_wsgi.c(7816): mod_wsgi
(pid=24059): Starting thread 20 in daemon process
'www.ssbg.devisland.net'.
[Wed Apr 30 22:43:19 2008] [debug] mod_wsgi.c(7816): mod_wsgi
(pid=24059): Starting thread 21 in daemon process
'www.ssbg.devisland.net'.
[Wed Apr 30 22:43:19 2008] [debug] mod_wsgi.c(7816): mod_wsgi
(pid=24059): Starting thread 22 in daemon process
'www.ssbg.devisland.net'.
[Wed Apr 30 22:43:19 2008] [debug] mod_wsgi.c(7816): mod_wsgi
(pid=24059): Starting thread 23 in daemon process
'www.ssbg.devisland.net'.
[Wed Apr 30 22:43:19 2008] [debug] mod_wsgi.c(7816): mod_wsgi
(pid=24059): Starting thread 24 in daemon process
'www.ssbg.devisland.net'.
[Wed Apr 30 22:43:19 2008] [debug] mod_wsgi.c(7816): mod_wsgi
(pid=24059): Starting thread 25 in daemon process
'www.ssbg.devisland.net'.
[Wed Apr 30 22:43:19 2008] [debug] mod_wsgi.c(7816): mod_wsgi
(pid=24073): Starting thread 17 in daemon process
'www.ssbg.devisland.net'.
[Wed Apr 30 22:43:19 2008] [debug] mod_wsgi.c(7816): mod_wsgi
(pid=24073): Starting thread 18 in daemon process
'www.ssbg.devisland.net'.
[Wed Apr 30 22:43:19 2008] [debug] mod_wsgi.c(7816): mod_wsgi
(pid=24073): Starting thread 19 in daemon process
'www.ssbg.devisland.net'.
[Wed Apr 30 22:43:19 2008] [debug] mod_wsgi.c(7816): mod_wsgi
(pid=24073): Starting thread 20 in daemon process
'www.ssbg.devisland.net'.
[Wed Apr 30 22:43:19 2008] [debug] mod_wsgi.c(7816): mod_wsgi
(pid=24073): Starting thread 21 in daemon process
'www.ssbg.devisland.net'.
[Wed Apr 30 22:43:19 2008] [debug] mod_wsgi.c(7816): mod_wsgi
(pid=24073): Starting thread 22 in daemon process
'www.ssbg.devisland.net'.
[Wed Apr 30 22:43:19 2008] [debug] mod_wsgi.c(7816): mod_wsgi
(pid=24073): Starting thread 23 in daemon process
'www.ssbg.devisland.net'.
[Wed Apr 30 22:43:19 2008] [debug] mod_wsgi.c(7816): mod_wsgi
(pid=24073): Starting thread 24 in daemon process
'www.ssbg.devisland.net'.
[Wed Apr 30 22:43:19 2008] [debug] mod_wsgi.c(7816): mod_wsgi
(pid=24073): Starting thread 25 in daemon process
'www.ssbg.devisland.net'.

hope this helps.


On Apr 30, 12:48 pm, "Graham Dumpleton" <graham.dumple...@gmail.com>
wrote:
> 2008/4/30 Graham Dumpleton <graham.dumple...@gmail.com>:
>
>
>
> > 2008/4/30 Graham Dumpleton <graham.dumple...@gmail.com>:
>
> > > 2008/4/30 Sk8board Kid <sk8board...@gmail.com>:

>
> > > > I have mod_wsgi working with virtual hosts, as you know apache as a
> > > > "main" log and then a log for each vhost (configured). normal http
> > > > problems get written to the vhost log but wsgi/python errors get
> > > > written to the main log.
>
> > > > i have increased my log level to "debug" but still nothing in the
> > > > vhost log, but all the "correct" info in the main apache log.
>
> > > > here is an example of my config:
>

> > > > <VirtualHostwww.x:8080>

> > > http://groups.google.com/group/modwsgi/browse_frm/thread/e56854857756...

[Graham Dumpleton]

Lots of useful information, thanks.

I'll trim most and comment on just one thing at this point.

From main Apache error log:

> [Wed Apr 30 22:43:19 2008] [info] mod_wsgi (pid=24073): Starting
> process 'www.z' with uid=3937, gid=102 and threads=25.

This shows the first thing I wanted to check, which was whether any
logging was occurring in mod_wsgi daemon process. As mentioned in
prior message, this would have been logged at point that daemon
process was still running as 'root'.

> [Wed Apr 30 22:43:19 2008] [info] mod_wsgi (pid=24090): Attach
> interpreter ''.

This is from main Apache error log, so am assuming it is actually from
an Apache child process rather than one of the mod_wsgi daemon
processes.

And from virtual host specific log file.

> [Wed Apr 30 22:43:19 2008] [debug] mod_wsgi.c(7816): mod_wsgi
> (pid=24059): Starting thread 7 in daemon process
> 'www.ssbg.devisland.net'.

I was actually hoping to see the "Attach interpreter ''" from the
virtual host log file, but presume you just sent a subset of what was
in the file and didn't capture it.

The above message is still okay though, it is just from a later point
in startup of the mod_wsgi daemon process. At this point the daemon
process is not running as 'root' and has changed identity.

So far this is all good. It at least shows me that logging from
mod_wsgi daemon process is working for global setup code. Thus it
would appear to only be code which is being executed in response to a
specific request is the problem.

I'd already sort of guessed this may be the case but having hard
confirmation helps me to narrow the search.

There is an odd bit of code in mod_wsgi which takes information passed
across from the Apache child process about the target virtual host and
then gets Apache to resolve that to the internal structure for that
virtual host. My guess is that Apache's routine which does this isn't
working for all configurations, or mod_wsgi isn't passing it the
correct information in the first place, with it working most of the
time, but not with all configurations. It doesn't appear to be related
to specific Apache versions as has affected Apache 2.0 and 2.2.

Thanks for going to the trouble of generating this for me. I'll go off
and have a good look at the code which I think might be the problem
and hopefully find the problem, but at worst come up with patched
mod_wsgi that does extra logging in crucial places that someone with
this problem can run for me to gather more specific information.

Thanks again.

Graham

[William Dode]

Hi,

I could see the same problem, i don't know if you notice like me that
this happend only when the error is raised *before* `application` is
instancied ?

mywsgi.wsgi

import blabla <- here
application = MyApp...

after that, with exactly the same configuration the log will go in the
right place for me.

bye

--
William Dodé - http://flibuste.net
Informaticien indépendant

[Graham Dumpleton]

2008/5/1 William Dode <wi...@flibuste.net>:

>
> Hi,
>
> I could see the same problem, i don't know if you notice like me that
> this happend only when the error is raised *before* `application` is
> instancied ?
>
> mywsgi.wsgi
>
> import blabla <- here
> application = MyApp...
>
> after that, with exactly the same configuration the log will go in the
> right place for me.

The first person to raise the problem with me initially encountered it
because of failed code on importing the WSGI script as well. I had
them run a test to discover the extent of the problem and based on
what they were telling me, stuff logged from within the executing
application when handling the request also wasn't working as intended.

I did have trouble getting complete details from them though, so never
knew whether to completely trust the results. It was because of this
that I had to simply park the issue until saw that someone else was
having it.

Can you run the following test application for me:

import sys

print >> sys.stderr, 'STDERR 1'

def application(environ, start_response):

print >> sys.stderr, 'STDERR 2'
print >> environ['wsgi.errors'], 'WSGI 1'

status = '200 OK'
output = 'Hello World!'

response_headers = [('Content-type', 'text/plain'),
('Content-Length', str(len(output)))]
start_response(status, response_headers)

return [output]

Do all three debug lines output using 'print' end up in the Apache
error logs? If they appear, which Apache error logs do they appear in
(main or virtual host) and what does the line output look like?

If this works for the three of you who now believe they aren't getting
logging, then it might just be an issue with logging when exception
occurs when first importing WSGI script file.

Thing is though, that I thought I had well and truly fixed this back
in the 1.0 release candidates as it wasn't working back then because
of a simple mistake. Thus maybe a another problem in that code still.
I had theorised about one possibility in the issue I created but
hadn't actually tried a code change yet since I couldn't replicate it.

Graham

[William Dode]

On 01-05-2008, Graham Dumpleton wrote:
>
> 2008/5/1 William Dode <wi...@flibuste.net>:
>>
>> Hi,
>>
>> I could see the same problem, i don't know if you notice like me that
>> this happend only when the error is raised *before* `application` is
>> instancied ?
>>
>> mywsgi.wsgi
>>
>> import blabla <- here
>> application = MyApp...
>>
>> after that, with exactly the same configuration the log will go in the
>> right place for me.

Finaly not true, i misled...

>
> The first person to raise the problem with me initially encountered it
> because of failed code on importing the WSGI script as well. I had
> them run a test to discover the extent of the problem and based on
> what they were telling me, stuff logged from within the executing
> application when handling the request also wasn't working as intended.
>
> I did have trouble getting complete details from them though, so never
> knew whether to completely trust the results. It was because of this
> that I had to simply park the issue until saw that someone else was
> having it.
>
> Can you run the following test application for me:
>
> import sys
>
> print >> sys.stderr, 'STDERR 1'
>
> def application(environ, start_response):
>
> print >> sys.stderr, 'STDERR 2'
> print >> environ['wsgi.errors'], 'WSGI 1'
>
> status = '200 OK'
> output = 'Hello World!'
>
> response_headers = [('Content-type', 'text/plain'),
> ('Content-Length', str(len(output)))]
> start_response(status, response_headers)
>
> return [output]

in apache error log (/var/log/apache2/error.log)
WSGI 1

in virtual host error log (/home/wilk/...)
STDERR 1
STDERR 2

in the browser
Hello World!

apache2 Debian/Etch mod_wsgi 2.0 daemon mode

I misled before because i catched the exception in my application. If
i raise an exception in your exemple, it will go everytime in apache
error log.

[Alberto Valverde]

Hi,

I've compiled mod_wsgi from svn rev. 906, configured apache as you
mentioned with the test WSGI app you posted in this thread and made one
request. Attached is what the main and vhost logs look like (along with
other info you might find useful. As you can see, "WSGI 1" is never printed.

Alberto

[Graham Dumpleton]

> > Sorry, another request. Hopefully Alberto can also try this one when
> > he as woken up.
> >
> > Can you possibly check out source from subversion repository trunk and
> > compile/run it instead. For details see:
> >
> > http://code.google.com/p/modwsgi/source/checkout
> >
> > If you don't have subversion client handy, then at least download the file:
> >
> > http://modwsgi.googlecode.com/svn/trunk/mod_wsgi/mod_wsgi.c
> >
> > and use it instead of mod_wsgi.c file from your existing source code.
> > Existing makefiles should still work.
> >
> > Can you run this version with LogLevel of 'debug' specified in main
> > part of Apache configuration, outside of any VirtualHost.
> Hi,
>
> I've compiled mod_wsgi from svn rev. 906, configured apache as you
> mentioned with the test WSGI app you posted in this thread and made one
> request. Attached is what the main and vhost logs look like (along with
> other info you might find useful. As you can see, "WSGI 1" is never printed.

Thanks, more useful information.

Your case is even more interesting as the logging output is completely
lost as opposed to just going to wrong log file. Your case mirrors the
initial one that was reported to me.

I have committed revision 907 to the source code repository. No extra
debugging in this, just a punt at a fix based on an educated guess.
Nothing to back up that this may work at this point, but could be
lucky. :-)

If you could try that new revision from source code repository and
tell me if it makes any difference at all, that would be great. If no
joy I have a backup plan as to how I could handle what I need to in
respect of passing across information to daemon process as to which
server context to use for logging.

Thanks for the help so far.

Graham

[Graham Dumpleton]

Alberto, or anyone else who had the original problem, have you been
able to try revision 907 from mod_wsgi subversion trunk to see if
problem still persists?

Graham

2008/5/2 Graham Dumpleton <graham.d...@gmail.com>:

[William Dode]

On 04-05-2008, Graham Dumpleton wrote:
>
> Alberto, or anyone else who had the original problem, have you been
> able to try revision 907 from mod_wsgi subversion trunk to see if
> problem still persists?

i just tried rev 910

with your example, WSGI1 go in apache error log

STDERR 1 & STDERR 2 go in virtual host log

if i raise an exception the traceback go to apache error log

wich system do you use to cannot reproduce it ?

[Graham Dumpleton]

2008/5/5 William Dode <wi...@flibuste.net>:

>
> On 04-05-2008, Graham Dumpleton wrote:
> >
> > Alberto, or anyone else who had the original problem, have you been
> > able to try revision 907 from mod_wsgi subversion trunk to see if
> > problem still persists?
>
> i just tried rev 910
>
> with your example, WSGI1 go in apache error log
>
> STDERR 1 & STDERR 2 go in virtual host log
>
> if i raise an exception the traceback go to apache error log
>
> wich system do you use to cannot reproduce it ?

All works fine on Mac OS X.

I'll have to try and find some time to try a Ubuntu box where I work. :-(

Thanks.

Graham

[Clodoaldo]

2008/5/1 Graham Dumpleton <graham.d...@gmail.com>:

For me all three end up in the virtual host error log using Fedora 8
and this config:

WSGISocketPrefix run/wsgi
<VirtualHost 10.1.1.106:80>

ServerName wsgi_test
ErrorLog logs/wsgi_test-error_log
CustomLog logs/wsgi_test-access_log combined
DocumentRoot /var/www/html/wsgi_test
WSGIScriptAlias / /var/www/html/wsgi_test/app.wsgi
<Directory /var/www/html/wsgi_test>
WSGIApplicationGroup wsgi_app_group
Order allow,deny
Allow from all
</Directory>
WSGIDaemonProcess wsgi_test user=cpn group=cpn processes=2 threads=25
WSGIProcessGroup wsgi_test

</VirtualHost>

> If this works for the three of you who now believe they aren't getting
> logging, then it might just be an issue with logging when exception
> occurs when first importing WSGI script file.

How could i reproduce it? In case you want to try yourself in that F8
machine I'm sending you the IP and root password. That is an old
retired machine so you can do whatever you need with it.

Regards, Clodoaldo

[Graham Dumpleton]

A quick update on this. I haven't been ignoring it, have just been
exceedingly busy as have got lots of work to do before I go on a long
holiday. On my holiday I will be sitting around a lot, so hopefully
will get some time then if haven't got to it earlier. :-)

I am probably going to rewrite the relevant code to do things a
different way, but would prefer to work out what is wrong with prior
code first so I don't use some other unpredictable bit of Apache
internals.

Anyway, keep hassling me and don't let me let it slide as this is an
important issue which needs fixing.

Graham

2008/5/8 Clodoaldo <clodoal...@gmail.com>:

[Graham Dumpleton]

A question for those with the vhost logging problem. In your Apache
configuration, what do you have for:

UseCanonicalName Off

Ie., is it Off or On. Alternatively, is it not defined at all.

You will need to search around through all the Apache configuration
files to find it. In a Apache configuration using original Apache
layout, it would be set in:

conf/extra/httpd-default.conf

Graham

2008/5/9 Graham Dumpleton <graham.d...@gmail.com>:

[William Dode]

On 08-05-2008, Graham Dumpleton wrote:
>
> A quick update on this. I haven't been ignoring it, have just been
> exceedingly busy as have got lots of work to do before I go on a long
> holiday. On my holiday I will be sitting around a lot, so hopefully
> will get some time then if haven't got to it earlier. :-)
>
> I am probably going to rewrite the relevant code to do things a
> different way, but would prefer to work out what is wrong with prior
> code first so I don't use some other unpredictable bit of Apache
> internals.
>
> Anyway, keep hassling me and don't let me let it slide as this is an
> important issue which needs fixing.

It's not urgent, anyway it's better to catch the errors in the
application...

Do you need some help to reproduce the problem ? I can also give you
a root access to an etch system, just ask me some days before.

[William Dode]

On 09-05-2008, Graham Dumpleton wrote:
>
> A question for those with the vhost logging problem. In your Apache
> configuration, what do you have for:
>
> UseCanonicalName Off

It was not defined, so Off by default. It doesn't change anything if
i set it to On

[Graham Dumpleton]

2008/5/9 William Dode <wi...@flibuste.net>:

It might come to that, certainly will make it quicker for me. So if
you can reproduce it on that particular system then let me know where
and when.

In the interim, can you check out latest mod_wsgi from subversion
repository and run it with the configuration which gives a problem.

When doing this though, ensure that you have set:

LogLevel debug

in main Apache server context, and also set the option:

WSGIVerboseDebugging On

This is something I just added to enable some extra debugging on every request.

Make request which causes problem, and then go look in main Apache
error log for output like:

[Fri May 09 20:28:07 2008] [debug] mod_wsgi.c(9490): mod_wsgi
(pid=1794): Request server was '127.0.0.1|0'.
[Fri May 09 20:28:07 2008] [debug] mod_wsgi.c(10108): mod_wsgi
(pid=1793): Server listener address '|8224'.
[Fri May 09 20:28:07 2008] [debug] mod_wsgi.c(10117): mod_wsgi
(pid=1793): Server listener address '|8224' was found.
[Fri May 09 20:28:07 2008] [debug] mod_wsgi.c(10129): mod_wsgi
(pid=1793): Connection server matched was '127.0.0.1|0'.
[Fri May 09 20:28:07 2008] [debug] mod_wsgi.c(10147): mod_wsgi
(pid=1793): Request server matched was '127.0.0.1|0'.

Send this too me. If needing to obscure host names, ensure you set the
names in different locations consistently as the point of this is for
me to see how they match up.

Thanks.

Graham

[Graham Dumpleton]

2008/5/9 Graham Dumpleton <graham.d...@gmail.com>:

Sorry, will not all be in main Apache error log. The first line
probably is, but rest would be in virtual host error log file.

Graham

[imgrey]

I have similar problem, but in my case apache not logging errors for
some virtualhosts at all.

But when I put

print >> sys.stderr, 'STDERR 2'

to my.wsgi file it logged "[error] STDERR 1"


/usr/sbin/apache2ctl -t -D DUMP_MODULES
Loaded Modules:
core_module (static)
log_config_module (static)
logio_module (static)
mpm_prefork_module (static)
http_module (static)
so_module (static)
alias_module (shared)
auth_basic_module (shared)
authn_file_module (shared)
authz_default_module (shared)
authz_groupfile_module (shared)
authz_host_module (shared)
authz_user_module (shared)
autoindex_module (shared)
cgi_module (shared)
dir_module (shared)
env_module (shared)
mime_module (shared)
chroot_module (shared)
negotiation_module (shared)
rewrite_module (shared)
setenvif_module (shared)
status_module (shared)
wsgi_module (shared)
Syntax OK


libapache2-mod-wsgi 2.0-1
apache2-mpm-prefork 2.2.8-3



P.S. sadly to see that there's no stable engine for running python on
apache2.
mod_python completely unusable for some cases and fastcgi even worse.

[Graham Dumpleton]

2008/5/11 imgrey <img...@gmail.com>:

> P.S. sadly to see that there's no stable engine for running python on
> apache2. mod_python completely unusable for some cases and fastcgi even worse.

Depends on your measure of stable, except for this problem with
ErrorLog inside VirtualHost, mod_wsgi is showing itself to be very
stable. :-)

The ErrorLog problem is only affecting a small number of people. It
may even be isolated to certain OS variants/versions. It is just
proving hard to track down as can't duplicate it on machines I have
access to. Have been given access to one host by someone else to work
it out, but on my quick test, it wasn't having the problem at the time
I did the test.

Made more difficult at the moment as am away from home and my Internet
connection is very spotty and can't maintain a SSH connection to other
sites for very long before modem decides to crap out. :-(

Graham

[Graham Dumpleton]

BTW, I should point out, that unless doing so is a problem, comment
out ErrorLog in VirtualHost and output will quite happily go to main
Apache error log :-)

2008/5/11 Graham Dumpleton <graham.d...@gmail.com>:

[Graham Dumpleton]

After some more thinking over a hearty dinner, a quick workaround,
albeit with caveats, for this issue should be to find line:

ap_update_vhost_from_headers(r);

in source code and immediately after that line add:

r->server = wsgi_server;

For the case where WSGIDaemonProcess appears inside of VirtualHost,
and ErrorLog is also specified inside of the VirtualHost, this should
see all logging correctly go to the VirtualHost error log.

The caveat though is that if WSGIDaemonProcess is defined outside of
VirtualHost context, because you wanted to be able to associate two
WSGI applications running under different VirtualHost contexts, with
the same Python interpreter instance in a specific daemon process,
then the logging from both WSGI applications will go to main Apache
error log rather than an error log associated with the VirtualHost the
request was being handled under.

In this latter case, it was a strange case anyway, as by having
WSGIDaemonProcess outside of all VirtualHosts, the output sent to
stderr/stdout would go to the main Apache error log, but output to
wsgi.errors and any uncaught errors from executing a request would go
to the VirtualHost error log if specified. Thus you had to look in two
different places.

Because of this split in where things went, it may actually be more
sensible to make the workaround the actual fix, meaning that all error
output from WSGIDaemonProcess when outside of VirtualHost would
consistently go to same place, ie. main Apache error log.

Note, the workaround is actually untested at this point. :-)

Please try this and let me know of the results. Will then think about
that split destination case and whether making it going to main Apache
error log would be sensible. In other words, the location of
WSGIDaemonProcess is dictating which log it goes to and for requests,
not the context the request is handled in.

Thanks.

Graham

2008/5/11 Graham Dumpleton <graham.d...@gmail.com>:

[Brian Smith]

Graham Dumpleton wrote:
> Please try this and let me know of the results. Will then think about
> that split destination case and whether making it going to main Apache
> error log would be sensible. In other words, the location of
> WSGIDaemonProcess is dictating which log it goes to and for requests,
> not the context the request is handled in.

If the daemon processes proxying their logging through the child processes
(like they proxy their output), then this issue would be avoided, wouldn't
it?

When we were discussing the (complete) solution to CGI-like deadlocks, we
had discussed some possible changes to the child<->daemon protocol. One side
effect of those changes would be that the daemon processes could interleave
control/logging messages with their output, and then the Apache child
process could do the actual write to the log file associated with its
request context. If you are interested in pursuing something like that, let
me know and I will try to factor out those changes from my prototype and
submit them to you.

Regards,
Brian

[Graham Dumpleton]

2008/5/12 Brian Smith <br...@briansmith.org>:

>
> Graham Dumpleton wrote:
> > Please try this and let me know of the results. Will then think about
> > that split destination case and whether making it going to main Apache
> > error log would be sensible. In other words, the location of
> > WSGIDaemonProcess is dictating which log it goes to and for requests,
> > not the context the request is handled in.
>
> If the daemon processes proxying their logging through the child processes
> (like they proxy their output), then this issue would be avoided, wouldn't
> it?

It depends.

To capture stdout/stderr, which can be used outside of context of a
request by a distinct thread, you would have to use a special purpose
socket just for proxying the error output. If you use this same socket
to interleave error output from wsgi.errors, you would have exactly
the same problem. That is, you need to pass some sort of token back
with a message to know which Apache server context to select and log
output through. In current code, it is this token, but effectively in
the other direction which in some cases is not being calculated
properly.

This becomes easier if you have multiple avenues of passing back error
output. That is, the separate socket above is only used for
stdout/stderr, with wsgi.errors and any other per request error
messages being interleaved with the response from an actual request,
with the client side separating it out. Because the client side
already has a handle on correct server_rec, it knows where to log that
already.

For per request logging, the latter multiple avenues approach also
make it easier in respect of fact that per request error output is
supposed to be logged via the request_rec. If only using the single
socket in first approach, there is no request_rec on client side. You
may though be able to fake things up the same by stuffing in client IP
details before you send it across the socket as part of the message.
In other words, emulate the difference between server_rec and
request_rec logging.

> When we were discussing the (complete) solution to CGI-like deadlocks, we
> had discussed some possible changes to the child<->daemon protocol. One side
> effect of those changes would be that the daemon processes could interleave
> control/logging messages with their output, and then the Apache child
> process could do the actual write to the log file associated with its
> request context. If you are interested in pursuing something like that, let
> me know and I will try to factor out those changes from my prototype and
> submit them to you.

All comes down to time at the moment. In short I don't have any so
can't get around to any of the large list of things we discussed, so
throwing code my way to look at will not speed anything up right now.

Graham

[Graham Dumpleton]

Possible more permanent fix for this. In mod_wsg.c search for
REQUEST_NO_BODY. You will find code:

r->read_body = REQUEST_NO_BODY;

r->status = HTTP_INTERNAL_SERVER_ERROR;

Change the latter line so it reads:

r->read_body = REQUEST_NO_BODY;

r->status = HTTP_OK;

That is, change what r->status is initialised to, to HTTP_OK instead
of HTTP_INTERNAL_SERVER_ERROR.

Down in Apache code where it does vhost mapping to server_rec, it was
checking r->status and if it wasn't HTTP_OK was assuming an error had
occurred earlier and that it could stop and not bother doing what it
was meant to. :-(

Please try and indicate if it solves the problem for you.

[Graham Dumpleton]

Anyone who was having the virtual host logging problem been able to
test this fix yet?

Would like to know for sure it fixes problems for people before I
attempt a new release with it in it.

Note, only use the r->status change, not the overwriting of r->server.

Thanks.

Graham

2008/5/12 Graham Dumpleton <graham.d...@gmail.com>:

[William Dode]

On 15-05-2008, Graham Dumpleton wrote:
>
> Anyone who was having the virtual host logging problem been able to
> test this fix yet?
>
> Would like to know for sure it fixes problems for people before I
> attempt a new release with it in it.

quick test : it work for me !

ps: the server i opened for you had a crash disk !

[jhar...@harwoodspike.com]

I am having a similar issue. My issue is that the when I have the ErrorLog in my virtual host config it would log some things to the Virtual host log file and nothing to the main log file.
I did the def application defined above and it said STDERR 1 & STDERR 2 in the virtual host error log and nothing in the main log. WSGI 1 never go printed until I update to the latest version of mod_wsgi.
After the update I got STDERR 1 in the virtual host error log and still nothing in the main error log.

I am running apache 2.4.23 w/ mod_wsgi 4.5.3 until I update it to 4.5.6.
I tried the r->server = wsgi_sesrver; fix and it worked.
The r-> status fix obviously didn't fix my issue (as it is a part of the latest version already).

I am using cpanel so the httpd.conf is doing <VirtualHost 123.123.123.123:80> rather than <VirtualHost *:80>
I temporarily change it to <VirtualHost *:80> and it worked so I am thinking when logging apache my be getting confused on which domain it is logging for.

I turned on WGSIVerbosity and LogLevel debug and it said:

[Sun Sep 04 13:17:20.731390 2016] [wsgi:debug] [pid 28948:tid 140622976448256] src/server/mod_wsgi.c(12437): mod_wsgi (pid=28948): Server listener address '0.0.0.0|80'.
[Sun Sep 04 13:17:20.731447 2016] [wsgi:debug] [pid 28948:tid 140622976448256] src/server/mod_wsgi.c(12446): mod_wsgi (pid=28948): Server listener address '0.0.0.0|80' was found.
[Sun Sep 04 13:17:20.731468 2016] [wsgi:debug] [pid 28948:tid 140622976448256] src/server/mod_wsgi.c(12459): mod_wsgi (pid=28948): Connection server matched was 'excalibur.hspike.com|0'.
[Sun Sep 04 13:17:20.731485 2016] [wsgi:debug] [pid 28948:tid 140622976448256] src/server/mod_wsgi.c(12474): mod_wsgi (pid=28948): Request server matched was 'excalibur.hspike.com|0'.
[Sun Sep 04 13:17:20.761734 2016] [wsgi:info] [pid 28948:tid 140622976448256] mod_wsgi (pid=28948): Create interpreter 'fina.dev.harwoodspike.com|'.
[Sun Sep 04 13:17:20.792291 2016] [wsgi:info] [pid 28948:tid 140622976448256] mod_wsgi (pid=28948): Adding '/home/devharwoodspike/python-apps/fina/' to path.
[Sun Sep 04 13:17:20.792664 2016] [wsgi:info] [pid 28948:tid 140622976448256] mod_wsgi (pid=28948): Adding '/home/devharwoodspike/python-apps/virtpython/lib/python3.5/site-packages/' to path.
[Sun Sep 04 13:17:20.793820 2016] [wsgi:debug] [pid 28948:tid 140622976448256] src/server/wsgi_interp.c(1417): mod_wsgi (pid=28948): Bind thread state for thread 1 against interpreter 'fina.dev.harwoodspike.com|'.

[Graham Dumpleton]

Since the discussion you are referring to was from 8 years ago, can you start from scratch and state your problem over as if it was new so we don’t have to decipher what the past conversation was all about and whether it still relevant.  Explain whether you are using embedded mode or daemon mode, plus show how you have VirtualHost configured.

In general, if anything is happening in a context related to a VirtualHost it should be logged to the VirtualHost log file if defined. So not sure what/why you are expecting stuff to go to main log file. Can you be more specific about what you are expecting to go where and why? Also provide an example WSGI application you are using to test with, what you got and what you expected for that.

Thanks.

Graham

--
You received this message because you are subscribed to the Google Groups "modwsgi" group.
To unsubscribe from this group and stop receiving emails from it, send an email to modwsgi+u...@googlegroups.com.
To post to this group, send email to mod...@googlegroups.com.
Visit this group at https://groups.google.com/group/modwsgi.
For more options, visit https://groups.google.com/d/optout.