global logging to file

[Hans]

I tried to define a global logging for a web2py app. The problem with
that is that if I place the following code in my default.py controller
or db.py model then in both cases its executed more than
once...resulting into having every log line written multiple times
into the log file.

either starting the default.py or db.py with those lines is yielding
the same result
import logging, logging.handlers

# Make a global logging object.
lox = logging.getLogger("log")
lox.setLevel(logging.DEBUG)

# This handler writes everything to a file.
h1 = logging.FileHandler("/var/log/myapp.log")
f = logging.Formatter("%(levelname)s %(asctime)s %(funcName)s %
(lineno)d %(message)s")
h1.setFormatter(f)
h1.setLevel(logging.DEBUG)
lox.addHandler(h1)

# This handler emails me anything that is an error or worse.
h2 = logging.handlers.SMTPHandler('localhost', 'l...@test.com',
['tobeno...@test.com'], 'ERROR log')
h2.setLevel(logging.ERROR)
h2.setFormatter(f)
lox.addHandler(h2)

log usage example in controller...
def index():
log = logging.getLogger("log")
log.debug("starting...")
....do something
log.debug("finishing...")
return()

log file looks like:
DEBUG 2009-06-04 20:27:45,617 index 1 starting...
DEBUG 2009-06-04 20:27:45,617 index 1 starting...
DEBUG 2009-06-04 20:27:45,617 index 1 starting...
DEBUG 2009-06-04 20:27:50,617 index 1 finishing...
DEBUG 2009-06-04 20:27:50,617 index 1 finishing...
DEBUG 2009-06-04 20:27:50,617 index 1 finishing...

how can I fix the 'multiple problem' ?

[mdipierro]

Odd I think your controller is being called 3 times. Is that possible?
I would add a print statement to check.

On Jun 4, 2:29 pm, Hans <johann.scheibelho...@easytouch-edv.com>
wrote:

> I tried to define a global logging for a web2py app. The problem with
> that is that if I place the following code in my default.py controller
> or db.py model then in both cases its executed more than
> once...resulting into having every log line written multiple times
> into the log file.
>
> either starting the default.py or db.py with those lines is yielding
> the same result
> import logging, logging.handlers
>
> # Make a global logging object.
> lox = logging.getLogger("log")
> lox.setLevel(logging.DEBUG)
>
> # This handler writes everything to a file.
> h1 = logging.FileHandler("/var/log/myapp.log")
> f = logging.Formatter("%(levelname)s %(asctime)s %(funcName)s %
> (lineno)d %(message)s")
> h1.setFormatter(f)
> h1.setLevel(logging.DEBUG)
> lox.addHandler(h1)
>
> # This handler emails me anything that is an error or worse.

> h2 = logging.handlers.SMTPHandler('localhost', '...@test.com',
> ['tobenotif...@test.com'], 'ERROR log')

[Hans]

yes confirmed, the controller is called multiple times. the reason I
found is that the redirect() statements I use cause this. every
redirect() seems to call the controller, not only the redirection
target function.

for example my index is mainly a redirect function, based on settings
its for instance doing
redirect(URL(r=request,f='f1'))

then also in other functions I use redirects e.g. based on rights/
settings.

I'm using 1.63.5 on WinXP SP3.

Is there a better function than redirect() for avoiding to call the
general controller stuff multiple times?
Is redirect() supposed to also call the general controller stuff or
only directly the redirection target function ?

Thanks,
Hans

[Hans]

Correction: redirect() usage is NOT causing the problem. Every call of
a controller function also executes
1) general parts of the model (db.py)
2) general parts of the controller (default.py)
3) the requested function in controller

In my case every click to an menu function adds another multiple for
log entries.

Thinking about the response.menu example which gives you different
menu options depending on the user being logged in or not I'm
convinced that the general controller sections are executed before
each requested function. That's good for the dynamically changing menu
and other needs.

For a log file function which should be available for the entire
controller I need to make sure its executed only once. Is there a
simple way to do that or a different way to achieve a log file
function (similar like my example up in this thread) available for the
entire controller?

Thanks,
Hans
On Jun 5, 2:34 pm, Hans <johann.scheibelho...@easytouch-edv.com>
wrote:

[mdipierro]

Sorry Hans, I still do not understand the problem.

code outside function is executed when a function in the controller is
called (whatever the function) code in the function is executed only
when that function is called. A call to redirect causes the browser to
make another request thus the controller is executed again.

Massimo

On Jun 5, 8:08 am, Hans <johann.scheibelho...@easytouch-edv.com>
wrote:

[Hans]

The problem I have with my code for generating log files that the part
of the code (see first posting in this thread) which is outside any
function in the controller (because it should be available for all
functions in this controller) is executed every time a function is
called. I have not found a way to execute it only once intitially and
prevent multiple executions. Hence it registeres log handlers every
time the controller is executed which causes every log line to be

written multiple times into the log file.

The following did not work:

try:
done_once
except:
place code to be executed only once here
global done_once
done_once=true

because the variable done_once is undefined each time the controller
is executed again.

How can a code in the controller be executed only once?
Also completely different approach suggestions are welcome!

Thanks,
Hans

[Hans]

The problem I have with my code for generating log files that the part
of the code (see first posting in this thread) which is outside any
function in the controller (because it should be available for all
functions in this controller) is executed every time a function is
called. I have not found a way to execute it only once intitially and
prevent multiple executions. Hence it registeres log handlers every
time the controller is executed which causes every log line to be

written multiple times into the log file.

The following did not work:

try:
done_once
except:
place code to be executed only once here
global done_once
done_once=true

because the variable done_once is undefined each time the controller
is executed again.

How can a code in the controller be executed only once?
Also completely different approach suggestions are welcome!

Thanks,
Hans

On Jun 5, 4:36 pm, mdipierro <mdipie...@cs.depaul.edu> wrote:

[mdipierro]

can you store it into a session?

On Jun 5, 2:11 pm, Hans <johann.scheibelho...@easytouch-edv.com>
wrote:

[Hans]

The log file initialization code must be executed once when the
application starts and should not be executed multiple times (e.g. not
once per user and not once per controller execution).

I'm not aware that in a session I can store a application-wide global
variable - independent of the user.

Can you provide a link or example code for execution only once per
application (e.g. initialization function) ?

[mdipierro]

You are right. Not in session. You can store an application wide var
in cache but I would suggest using the db for this. Anyway, I will
post an example.


On Jun 8, 4:27 am, Hans <johann.scheibelho...@easytouch-edv.com>
wrote:

[Hans]

Sorry for being picky on this. I think the database is not a suitable
place either to store a 'application instance initialized flag'.
Reason:
1) the db can be used by more than one instance of the app
2) if the app stops execution without setting back the 'db record' to
'app not initialized' - like it happens when you remove the power -
then the application will not work any more because the code will
refer to objects which are not created yet because the one-time-
initialization per app was not executed.

I'm not aware how application wide vars in web2py cache are working,
but I assume it could be a viable option.

what do you think?

[mdipierro]

I agree about 1 and 2. I do not thing logging belongs to cache either.

i think we want something like

request.log(message)

which does something like.

open(os.path.join(request.folder,'app.log'),'w').write(message
+'\n')

Am I wrong? The problem is that this naive approach would bypass OS
logging and filtering capabilities supported by logging. we should
look into the logging module perhaps we can have a logger per app?

Massimo

On Jun 9, 8:32 am, Hans <johann.scheibelho...@easytouch-edv.com>
wrote:

[Iceberg]

request.log(message) would be nice, but all the advantages of standard
logging are too good to let go. So I came up with this little trick.

Add following codes inside model/log.py:

def _init_log():
import logging
logger=logging.getLogger(request.application)
logger.setLevel(logging.DEBUG)
handler=logging.FileHandler("%s.log"%request.application)
handler.setLevel(logging.DEBUG)
handler.setFormatter(logging.Formatter(

"%(levelname)s %(asctime)s %(funcName)s %(lineno)d %(message)

s"))
logger.addHandler(handler)
return logger
logging=cache.ram('once',lambda:_init_log(),time_expire=99999999)

Then, in any of your controller, you can just do the usual:
logging.warn('blah blah')
The only tricky point is you can not do this inside your controller:
import logging
otherwise you lose the magic. ;-)

Besides, thanks for Hans for bringing up all the issue, which inspires
me to find the solution (at least for me) for this problem haunting me
for long time.

[mdipierro]

I think you nailed it! I would change the file name so that it resides
inside the applicaitons folder:

handler=logging.FileHandler(os.path.join(request.folder,"system.log"))

we could also add a line in the admin to peek the log (like with
sql.log).

[Iceberg]

I am glad you like it. So every new app will have a models/log.py
soon?

BTW, I personally prefer this formatter, hope you do:
"%(asctime)s %(levelname)s %(funcName)s():%(lineno)d %(message)s"

[Iceberg]

Mmm, even after this log.py goes into models/log.py, I think the line:
logging=cache.ram(...)
should be replaced by:
import logging
# logging=cache.ram(...) # Uncomment me if you need app-logging

Because:
1. My log.py will cause the an incremental system.log which will
eventually cram up your disk, hence it is not good for production
site, unless you use RotatingFileHandler instead.
2. On GAE, you can not write to disk anyway, unless you use
SMTPHandler or HTTPHandler etc.

You get the idea. //shrug

[Hans]

WOW Iceberg! That should also work well for me. Thanks for sharing
your solution idea! I'm going to try it later today.
And I agree the 'uncomment me if you need app-logging' approach in
combination with the per-application-log-file seems also to me the
best (backward compatible, flexible).

Since I'm going to implement that for me anyway I'll send my code when
its finised...in case you want to improve it and/or Massimo wants to
incorporate it in future web2py versions.

[Iceberg]

After changing from FileHandler to RotatingFileHandler, now I think
the per-app log can be turned on by default (otherwise new comers
won't notice this good feature).

The only thing I am still not sure is whether one can use logging and
its FileHander (or RotatingFileHander) on GAE's readonly filesystem.
Tests are welcome.

Anyway, this is my latest code. Maybe it can help you.

import logging
def _init_log(level=logging.DEBUG):
import os,logging.handlers
logger=logging.getLogger(request.application)
logger.setLevel(level)
if request.env.web2py_runtime_gae: # if running on Google App
Engine
handler=logging.handlers.HTTPHandler(
request.env.http_host,URL(r=request,f='log')) # assuming there
is an optional log action
else:
handler=logging.handlers.RotatingFileHandler(
os.path.join
(request.folder,'app.log'),maxBytes=1024*1024,backupCount=2)
handler.setLevel(level)
handler.setFormatter(logging.Formatter(
"%(asctime)s %(levelname)s %(funcName)s():%(lineno)d %(message)

s"))
logger.addHandler(handler)
return logger

logging=cache.ram('mylog',lambda:_init_log(),time_expire=99999999)


OPTIONAL in controller:

def log():
if request.vars: # append
history=cache.ram('log_in_cache',lambda:[],time_expire=99999999)
history.append(request.vars)
cache.ram('log_in_cache',lambda h=history:h,time_expire=0)#set
else: # show
return {'':TABLE(*[TR(item) for item in
cache.ram('log_in_cache',lambda:None,time_expire=99999999)])}

On Jun10, 5:52pm, Hans <johann.scheibelho...@easytouch-edv.com> wrote:
> WOW Iceberg! That should also work well for me. Thanks for sharing
> your solution idea! I'm going to try it later today.
> And I agree the 'uncomment me if you need app-logging' approach in
> combination with the per-application-log-file seems also to me the
> best (backward compatible, flexible).
>
> Since I'm going to implement that for me anyway I'll send my code when
> its finised...in case you want to improve it and/or Massimo wants to
> incorporate it in future web2py versions.
>
> On Jun 9, 9:02 pm, Iceberg <iceb...@21cn.com> wrote:
>
> > Mmm, even after this log.py goes into models/log.py, I think the line:
> >   logging=cache.ram(...)
> > should be replaced by:
> >   import logging
> >   # logging=cache.ram(...) # Uncomment me if you need app-logging
>
> > Because:
> > 1. My log.py will cause the an incremental system.log which will
> > eventually cram up your disk, hence it is not good for production
> > site, unless you use RotatingFileHandler instead.
> > 2. On GAE, you can not write to disk anyway, unless you use
> > SMTPHandler or HTTPHandler etc.
>
> > You get the idea. //shrug
>
>

[mdipierro]

Why do you need to cache the logging module? Is this only for speed?

[Iceberg]

Not at all.

The cache.ram in log.py is to make sure the logger is inited only
once, otherwise we will see more and more duplicate log appearing in
the log file as Hans mentioned in his earlier posts. The only downside
is that you need to restart web2py if you change (but usually you
don't need to) log definition.

As to the "OPTIONAL in controller" part, you can ignore it. They are
just a rough demo and not necessary.

[Hans]

Log file usage in Web2py is now simpler than ever!
You want to monitor the activities of your cron-driven web2py
functions?

To use the per application log file with rotating file handler in
web2py you need to put log.py (below) into your models folder. The log
file itself is created in your_web2py_path/applications/
your_application/app.log

Writing into the log file from your controller works as follows:
def my_function():
logging.debug('my function abc is starting')
logging.error('huston we got a %s problem.' % 'major')
return ()

Viewing the log file through your application works as follows:
def show_log():
return get_log()

If required the GAE solution needs work.
A BIG thank you to Iceberg!
Feedback and usage is welcome ;-)

Hans



Here is the log.py model version I use to enable logging for web2py
apps.

import logging

def _init_log(level=logging.DEBUG,formatter="%(asctime)s %(levelname)s
%(funcName)s():%(lineno)d %(message)
s",filename='app.log',maxBytes=1024*1024,backupCount=2):

import os,logging.handlers
logger=logging.getLogger(request.application)
logger.setLevel(level)
if request.env.web2py_runtime_gae: # if running on Google App
Engine
handler=logging.handlers.HTTPHandler(request.env.http_host,URL
(r=request,f='log')) # assuming there is an optional log action
else:
handler=logging.handlers.RotatingFileHandler(os.path.join

(request.folder,filename),maxBytes=maxBytes,backupCount=backupCount)
handler.setLevel(level)
handler.setFormatter(logging.Formatter(formatter))
logger.addHandler(handler)
logger.debug("web2py application %s starting" %
request.application)
return logger

def get_log():
try:
f = open(logging.handlers[0].baseFilename, 'r')
c = f.readlines()
f.close()
return {'log':TABLE(*[TR(str(item)) for item in c])}
except:
return ()

logging=cache.ram('mylog',lambda:_init_log(),time_expire=99999999)

[Hans]

Important note: do *not* 'import logging' in your controller if you
use log.py. its done for all your controllers already in the log.py
model and it would break the log.py magic.

On Jun 15, 7:46 pm, Hans <johann.scheibelho...@easytouch-edv.com>
wrote:

[Richard]

this looks useful - thanks!


On Jun 16, 3:53 am, Hans <johann.scheibelho...@easytouch-edv.com>
wrote:

[Hans]

I'm glad that its useful also to you Richard.

Massimo, maybe you want to check if you want it in one of the next
versions.

[mdipierro]

Can you email it to me?

On Jun 17, 5:30 am, Hans <johann.scheibelho...@easytouch-edv.com>
wrote:

[Richard]

so will this be integrated into web2py?
cjparsons mentioned in another thread that he has used the logging
module without problems:
http://groups.google.com/group/web2py/browse_thread/thread/55be545503b03b6e/29f816b84d202ff2

[mdipierro]

I have not made my mind yet. The fact is, it works great without being
part of web2py.

On Jun 24, 9:05 pm, Richard <richar...@gmail.com> wrote:
> so will this be integrated into web2py?
> cjparsons mentioned in another thread that he has used the logging

> module without problems:http://groups.google.com/group/web2py/browse_thread/thread/55be545503...

[Hans]

Richard,

the following solution works for me in production without any
problems. I use it for periodic, unattended functions (cron). I've
send Massimo the code in case he wants to include it into web2py or
make it available as optional add-on download.

Hans


'''

To use the per application log file with rotating file handler in

web2py you need to put this file (log.py) into your models folder. The

log
file itself is created in your_web2py_path/applications/
your_application/app.log

Writing into the log file from your controller works as follows:
def my_function():
logging.debug('my function abc is starting')
logging.error('huston we got a %s problem.' % 'major')
return

Viewing the log file through your application works as follows:
def show_log():
return get_log()

If required the GAE solution needs work.
A BIG thank you to Iceberg!
Feedback and usage is welcome ;-)

Important note: do *not* 'import logging' in your controller if you
use log.py. its done for all your controllers already in the log.py
model and it would break the log.py magic.

'''

[Johann.Sch...@easytouch-edv.com]

Trying to attach the file in this posting.

Hans

[MikeEllis]

This looks really useful. Thanks for writing it. I'm trying to import
some existing python modules that have logging calls into a web2py
app. Just putting log.py into my models directory helps some, but I'm
not seeing any messages from my existing modules with level lower than
logging.ERROR. I am, however, getting lower level (down to
logging.DEBUG) from the web2py framework. I suspect it has something
to do with the customized logger my modules are using. I don't want
to go through and comment out all the calls to my version of getLogger
() because many of these modules are used by other code. I'm
wondering if there's a way for a python module to detect at runtime
whether it's being imported from the web2py framework. I might then be
able to make my customized logging setup do nothing when running under
web2py. Any suggestions?

Thanks,
Mike Ellus

On Jun 25, 8:29 am, Hans <johann.scheibelho...@easytouch-edv.com>
wrote:

> Richard,
>
> the following solution works for me in production without any
> problems. I use it for periodic, unattended functions (cron). I've
> send Massimo the code in case he wants to include it into  web2py or
> make it available as optional add-on download.
>
> Hans
>
> '''
> To use the per application log file with rotating file handler in
> web2py you need to put this file (log.py) into your models folder. The
> log
> file itself is created in your_web2py_path/applications/
> your_application/app.log
>
> Writing into the log file from your controller works as follows:
> def my_function():
>    logging.debug('my function abc is starting')
>    logging.error('huston we got a %s problem.' % 'major')
>     return
>
> Viewing the log file through your application works as follows:
> def show_log():
>     return get_log()
>
> If required the GAE solution needs work.
> A BIG thank you to Iceberg!
> Feedback and usage is welcome ;-)
>

> Important note: do *not* 'importlogging' in your controller if you

[Hans]

Mike,
instead of importing in your Web2py controller use
execfile('your_module.py')

In your module ...
try:
# this variable is available in Web2Py
# but raises an exception if run outside Web2Py
# since its not defined
request.env.web2py_version
# put here your web2py related code...
print 'code executed in Web2py %s' % request.env.web2py_version
except:
# put here your not Web2Py related code
print 'code NOT executed in Web2py environment'

#put here your general code
print 'this part is always executed'

Hans

[Francisco Barretto]

Hi There!

Sorry to resurrect this long time dead post but I'm really wondering what is the proper way to log actions, errors and warns in Web2Py. Tried Hans/Iceberg solution but the log file is not created... Read in other topic about some logging functionality integrated but found none in web2py book. So, any hints?

Thanks!

[Niphlod]

there's a full section on it http://web2py.com/books/default/chapter/29/04?search=logging#Logging