import error after logrotate

[William Dode]

Hi,

I found something strange on an app wich run under deamon process

[Mon Dec 22 06:45:27 2008] [info] mod_wsgi (pid=14608): Create interpreter 'xxx.flibuste.net|/cde/serv_cde.wsgi'.
[Mon Dec 22 06:45:27 2008] [info] mod_wsgi (pid=14608): Adding '/home/web/xxx/pynclude' to path.
[Mon Dec 22 06:45:27 2008] [info] mod_wsgi (pid=14608): Adding '/home/web/xxx/xxx.flibuste.net/pynclude' to path.
[Mon Dec 22 06:45:27 2008] [info] [client 67.202.43.229] mod_wsgi (pid=14608, process='xxx.flibuste.net', application='xxx.flibuste.net|/cde/serv_cde.wsgi'): Loading WSGI script '/home/web/xxx/xxx.flibuste.net/www/cde/serv_cde.wsgi'.
[Mon Dec 22 07:04:06 2008] [info] mod_wsgi (pid=14608): Daemon process inactivity timer expired, stopping process 'xxx.flibuste.net'.
[Mon Dec 22 07:04:06 2008] [info] mod_wsgi (pid=14608): Shutdown requested 'xxx.flibuste.net'.
[Mon Dec 22 07:04:06 2008] [info] mod_wsgi (pid=14608): Stopping process 'xxx.flibuste.net'.
[Mon Dec 22 07:04:06 2008] [info] mod_wsgi (pid=14608): Destroy interpreter 'xxx.flibuste.net|/cde/serv_cde.wsgi'.
[Mon Dec 22 07:04:06 2008] [info] mod_wsgi (pid=14608): Cleanup interpreter ''.
[Mon Dec 22 07:04:06 2008] [info] mod_wsgi (pid=14608): Terminating Python.
[Mon Dec 22 07:04:06 2008] [info] mod_wsgi (pid=12221): Attach interpreter ''.
[Mon Dec 22 07:04:06 2008] [info] mod_wsgi (pid=12221): Adding '\x957Q\xb7`\xb51\b\xff\xff\xff\xff\xb8\xb61\b\x02' to path.

Of course after that i've an ImportError.

I had to restart apache, killing the wsgi process was not enough.

What's append at 6:45 ? a stupid log rotation wich was replacing the
logfile without restarting apache... My fault of course.

I replaced it by a piped cronolog now and wait to see if this error will
come back.

I couldn't reproduce it manualy, it's the third times in one month it
append but last times i had not the debugs. Généraly i've no problem
with this app wich have very few trafic (1500 hits/day).

Do you think it can be that ?

modwsgi 2.3-1 (debian lenny)
apache2 Version: 2.2.9-10+lenny1

bye

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

[William Dode]

On 22-12-2008, William Dode wrote:
k

>
> Hi,
>
> I found something strange on an app wich run under deamon process
>
> [Mon Dec 22 06:45:27 2008] [info] mod_wsgi (pid=14608): Create interpreter 'xxx.flibuste.net|/cde/serv_cde.wsgi'.
> [Mon Dec 22 06:45:27 2008] [info] mod_wsgi (pid=14608): Adding '/home/web/xxx/pynclude' to path.
> [Mon Dec 22 06:45:27 2008] [info] mod_wsgi (pid=14608): Adding '/home/web/xxx/xxx.flibuste.net/pynclude' to path.
> [Mon Dec 22 06:45:27 2008] [info] [client 67.202.43.229] mod_wsgi (pid=14608, process='xxx.flibuste.net', application='xxx.flibuste.net|/cde/serv_cde.wsgi'): Loading WSGI script '/home/web/xxx/xxx.flibuste.net/www/cde/serv_cde.wsgi'.
> [Mon Dec 22 07:04:06 2008] [info] mod_wsgi (pid=14608): Daemon process inactivity timer expired, stopping process 'xxx.flibuste.net'.
> [Mon Dec 22 07:04:06 2008] [info] mod_wsgi (pid=14608): Shutdown requested 'xxx.flibuste.net'.
> [Mon Dec 22 07:04:06 2008] [info] mod_wsgi (pid=14608): Stopping process 'xxx.flibuste.net'.
> [Mon Dec 22 07:04:06 2008] [info] mod_wsgi (pid=14608): Destroy interpreter 'xxx.flibuste.net|/cde/serv_cde.wsgi'.
> [Mon Dec 22 07:04:06 2008] [info] mod_wsgi (pid=14608): Cleanup interpreter ''.
> [Mon Dec 22 07:04:06 2008] [info] mod_wsgi (pid=14608): Terminating Python.
> [Mon Dec 22 07:04:06 2008] [info] mod_wsgi (pid=12221): Attach interpreter ''.
> [Mon Dec 22 07:04:06 2008] [info] mod_wsgi (pid=12221): Adding '\x957Q\xb7`\xb51\b\xff\xff\xff\xff\xb8\xb61\b\x02' to path.

Also in apache error log :
[Mon Dec 22 07:04:06 2008] [alert] (2)No such file or directory: mod_wsgi (pid=12221): Unable to change working directory to '7Q\xb7\xb8\xb41\b\xff\xff\xff\xff\xa0\xbc1\b\x02'.

[Graham Dumpleton]

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

May be a similar case of configuration corruption which has caused:

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

The fix, if you can compile from source, is to change all references
to 'temp_pool' to 'pool'.

Graham

[William Dode]

But do you see a link with the log rotation ?

>
> The fix, if you can compile from source, is to change all references
> to 'temp_pool' to 'pool'.

I prefer to keep the distrib version and eventualy report the bug...

Anyway i will wait to see if it come back with my change of the log
rotation.

[William Dode]

On 22-12-2008, Graham Dumpleton wrote:
>

The problem came back today, so it was not related to my log rotation
mystake like i thought. But now i've my logs... I notice a difference
not usual :

[Tue Dec 30 10:26:52 2008] [debug] mod_deflate.c(619): [client 82.127.20.132] Zlib: Compressed 2045 to 609 : URL /cde/serv_cde.wsgi/commande, r
eferer: http://xxx.flibuste.net/cde/commande
[Tue Dec 30 10:36:52 2008] [info] mod_wsgi (pid=29518): Daemon process inactivity timer expired, stopping process 'xxx.flibuste.net'.
[Tue Dec 30 10:36:52 2008] [info] mod_wsgi (pid=29518): Shutdown requested 'xxx.flibuste.net'.
[Tue Dec 30 10:36:52 2008] [info] mod_wsgi (pid=29518): Stopping process 'xxx.flibuste.net'.
[Tue Dec 30 10:36:52 2008] [info] mod_wsgi (pid=29518): Destroy interpreter 'xxx.flibuste.net|/cde/serv_cde.wsgi'.
[Tue Dec 30 10:36:52 2008] [info] mod_wsgi (pid=29518): Cleanup interpreter ''.
[Tue Dec 30 10:36:52 2008] [info] mod_wsgi (pid=29518): Terminating Python.
[Tue Dec 30 10:36:52 2008] [info] mod_wsgi (pid=369): Attach interpreter ''.
[Tue Dec 30 10:36:52 2008] [info] mod_wsgi (pid=369): Adding '/home/web/xxx/pynclude' to path.
[Tue Dec 30 10:36:52 2008] [info] mod_wsgi (pid=369): Adding '/home/web/xxx/xxx.flibuste.net/pynclude' to path.
[Tue Dec 30 10:36:52 2008] [debug] mod_wsgi.c(8449): mod_wsgi (pid=369): Starting 1 threads in daemon process 'xxx.flibuste.net'.
[Tue Dec 30 10:36:52 2008] [debug] mod_wsgi.c(8455): mod_wsgi (pid=369): Starting thread 1 in daemon process 'xxx.flibuste.net'.
[Tue Dec 30 10:36:52 2008] [info] mod_wsgi (pid=369): Enable monitor thread in process 'xxx.flibuste.net'.
[Tue Dec 30 10:36:52 2008] [debug] mod_wsgi.c(8301): mod_wsgi (pid=369): Deadlock timeout is 300.
[Tue Dec 30 10:36:52 2008] [debug] mod_wsgi.c(8304): mod_wsgi (pid=369): Inactivity timeout is 600.
[Tue Dec 30 10:36:52 2008] [info] mod_wsgi (pid=369): Enable deadlock thread in process 'xxx.flibuste.net'.
[Tue Dec 30 10:54:36 2008] [info] mod_wsgi (pid=369): Create interpreter 'xxx.flibuste.net|/cde/serv_cde.wsgi'.
[Tue Dec 30 10:54:36 2008] [info] mod_wsgi (pid=369): Adding '' to path.
[Tue Dec 30 10:54:36 2008] [info] [client 195.101.14.207] mod_wsgi (pid=369, process='xxx.flibuste.net', application='xxx.flibuste.net|/c

de/serv_cde.wsgi'): Loading WSGI script '/home/web/xxx/xxx.flibuste.net/www/cde/serv_cde.wsgi'.

[Tue Dec 30 10:54:36 2008] [error] [client 195.101.14.207] mod_wsgi (pid=369): Target WSGI script '/home/web/xxx/xxx.flibuste.net/www/cde
/serv_cde.wsgi' cannot be loaded as Python module.
[Tue Dec 30 10:54:36 2008] [error] [client 195.101.14.207] mod_wsgi (pid=369): Exception occurred processing WSGI script '/home/web/xxx/espa
ce.flibuste.net/www/cde/serv_cde.wsgi'.
[Tue Dec 30 10:54:36 2008] [error] [client 195.101.14.207] Traceback (most recent call last):
[Tue Dec 30 10:54:36 2008] [error] [client 195.101.14.207] File "/home/web/xxx/xxx.flibuste.net/www/cde/serv_cde.wsgi", line 3, in <mod
ule>
[Tue Dec 30 10:54:36 2008] [error] [client 195.101.14.207] import host_cde
[Tue Dec 30 10:54:36 2008] [error] [client 195.101.14.207] ImportError: No module named host_cde

At 10:26, the request was ok (i could see that a commande was created in
my database)
Between 10:26 and 10:54 there was no activity

At 10:54, we cannot see 'Deamon process inactivity timer expired...'
strange isn't it ?

What is very strange is that i've exactly the same app (since months)
under an other virtualhost and only one has this problem... On this
server 16 mod_wsgi apps run, no one has this problem.

So, today i hacked the code like you said me, changing temp_pool to
pool. If you've no other idea we'll see like that.

bye

[Graham Dumpleton]

Sorry for the delayed reply.

Where is the package/module called 'host_cde' installed?

If not on standard Python module search path and you have set sys.path
explicitly to add parent directory, or used python-path option to
WSGIDaemonProcess, clearly state which was used.

The logs show:

[Tue Dec 30 10:36:52 2008] [info] mod_wsgi (pid=369): Adding
'/home/web/xxx/pynclude' to path.
[Tue Dec 30 10:36:52 2008] [info] mod_wsgi (pid=369): Adding
'/home/web/xxx/xxx.flibuste.net/pynclude' to path.

This suggests to me that using python-path option. These first entries
though are for main interpreter instance, ie., %{GLOBAL}.

Look down further and you will see:

[Tue Dec 30 10:54:36 2008] [info] mod_wsgi (pid=369): Create
interpreter 'xxx.flibuste.net|/cde/serv_cde.wsgi'.
[Tue Dec 30 10:54:36 2008] [info] mod_wsgi (pid=369): Adding '' to path.

Thus, when it later creates sub interpreter, the path seems to have
been mangled in stored configuration and thus only empty path added
and not the two directories above where your package/module possibly
is. Thus can't find module.

Graham

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

[William Dode]

On 01-01-2009, Graham Dumpleton wrote:
>
> Sorry for the delayed reply.
>
> Where is the package/module called 'host_cde' installed?
>
> If not on standard Python module search path and you have set sys.path
> explicitly to add parent directory, or used python-path option to
> WSGIDaemonProcess, clearly state which was used.

It's set with python-path of the deamonprocess directive.

>
> The logs show:
>
> [Tue Dec 30 10:36:52 2008] [info] mod_wsgi (pid=369): Adding
> '/home/web/xxx/pynclude' to path.
> [Tue Dec 30 10:36:52 2008] [info] mod_wsgi (pid=369): Adding
> '/home/web/xxx/xxx.flibuste.net/pynclude' to path.
>
> This suggests to me that using python-path option. These first entries
> though are for main interpreter instance, ie., %{GLOBAL}.
>
> Look down further and you will see:
>
> [Tue Dec 30 10:54:36 2008] [info] mod_wsgi (pid=369): Create
> interpreter 'xxx.flibuste.net|/cde/serv_cde.wsgi'.
> [Tue Dec 30 10:54:36 2008] [info] mod_wsgi (pid=369): Adding '' to path.
>
> Thus, when it later creates sub interpreter, the path seems to have
> been mangled in stored configuration and thus only empty path added
> and not the two directories above where your package/module possibly
> is. Thus can't find module.

I see, but the question is why the python-path configuration is
corrupted (one time it's empty but another time it's
\x957Q\xb7`\xb51\b\xff\xff\xff...).
Nothing was changed in the configuration, the app was restarted because
of timeout inactivity. Indeed, if i restart apache it start again
without problem.

thx

[Graham Dumpleton]

2009/1/2 William Dode <wi...@flibuste.net>:

The bug with which memory pool was used, potentially meant that stuff
like the value of the python-path option was stored in memory which
had been released. When that memory would be reused would be a bit
random and depend on history of how memory is used by the application.

Anyway, best answer I have at the moment as to what the cause of the
problem may be.

Graham

[William Dode]

You mean pool vs temp_pool ?

[Graham Dumpleton]

2009/1/2 William Dode <wi...@flibuste.net>:

>> The bug with which memory pool was used, potentially meant that stuff
>> like the value of the python-path option was stored in memory which
>> had been released. When that memory would be reused would be a bit
>> random and depend on history of how memory is used by the application.
>
> You mean pool vs temp_pool ?

Yes, I am not sure about the lifetime of the temp_pool, but it
possibly is valid only for the configuration phase. So, any memory
from it retained after the initial configuration phase of Apache would
have been released and so subject to be used for something else and
overwritten, thus screwing up the retained values.

Graham

[William Dode]

On 02-01-2009, Graham Dumpleton wrote:
>

Then, i did the change, and wait now...

thx

[William Dode]

Hi,

I just confirm that since i changed all references of 'temp_pool' to
'pool' i've no more corruption of the daemon configuration.
However i could'nt find why it affected only one of my app...

Do you plan a bugfix release ?

thx

[Graham Dumpleton]

2009/1/27 William Dode <wi...@flibuste.net>:

>
> Hi,
>
> I just confirm that since i changed all references of 'temp_pool' to
> 'pool' i've no more corruption of the daemon configuration.
> However i could'nt find why it affected only one of my app...
>
> Do you plan a bugfix release ?

There will be a mod_wsgi 2.4, I just don't know the timing of it yet
as time to do stuff on mod_wsgi is quite restricted at the moment.
Things should improve come March.

Graham