Re: multiple processing of the same python script by the handler

Hi Graham,

Thanks for the quick response.   I have implemented a module which I place 
in / (literally) for ensuring that the test works.   I then also wrote a 
small stress test app which would hit the script with a parameter which 
increments at each request to see so I can see if there is multiplicity of 
logging.   Unfortunately there was still multiple entries of the same log 
data.  I should  say that the data received by the server on the other end of 
the socket is now unique(seems to be so far anyway). So thank you for 
assisting :-)   The issue with the logging module still baffles me.  Perhaps 
somebody else on the list has input?

def handler(req):
    davelogger = apache.import_module("/davelogger.py")    
    request_data = util.FieldStorage(req)
    clientip = req.get_remote_host(apache.REMOTE_NOLOOKUP)
    geoip = 'NL'
    str_req_data = str(clientip) + "| CC: " + str(geoip) + "| "
    str_req_datadb = "ip: " + str(clientip) + "| CC: " + str(geoip) + "| "
    for key in request_data:
        str_req_datadb += "| " + str(key) + ": " + str(request_data[key])
        str_req_data += str(key) + ": " + str(request_data[key]) + "| "

    davelogger.logdata(str_req_data[:-2],str_req_datadb)
    return apache.OK

davelogger.py module:

def logdata(data,datadb):
    logger = logging.getLogger('mylogger.py')
    logging_handler = 
logging.FileHandler('/usr/local/apache2/htdocs/mylog.log')    
    formatter = logging.Formatter('%(asctime)s %(levelname)s %(message)s')
    logging_handler.setFormatter(formatter)
    logger.addHandler(logging_handler)
    logger.setLevel(logging.INFO)

    curtime = datetime.now().isoformat(' ')
    try: 
        s = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
        s.settimeout(0.5)
        s.connect(('10.0.0.2', 8199))
        message = "date: " + str(curtime[:-4] + "| " + datadb)
        len_sent = s.send(message)
        s.close()
        
    except:
        data += '| dbupdate: failed|'
        pass
    logger.info(data)
    
    
log data from the logger module
2009-03-29 23:28:48,452 INFO 10.0.0.2| CC: NL| x: 195
2009-03-29 23:28:48,452 INFO 10.0.0.2| CC: NL| x: 195
2009-03-29 23:28:48,452 INFO 10.0.0.2| CC: NL| x: 195
2009-03-29 23:28:48,452 INFO 10.0.0.2| CC: NL| x: 195
2009-03-29 23:28:48,452 INFO 10.0.0.2| CC: NL| x: 195
2009-03-29 23:28:48,452 INFO 10.0.0.2| CC: NL| x: 195
2009-03-29 23:28:48,452 INFO 10.0.0.2| CC: NL| x: 195
2009-03-29 23:28:48,500 INFO 10.0.0.2| CC: NL| x: 196
2009-03-29 23:28:48,500 INFO 10.0.0.2| CC: NL| x: 196
2009-03-29 23:28:48,500 INFO 10.0.0.2| CC: NL| x: 196
2009-03-29 23:28:48,500 INFO 10.0.0.2| CC: NL| x: 196
2009-03-29 23:28:48,500 INFO 10.0.0.2| CC: NL| x: 196
2009-03-29 23:28:48,500 INFO 10.0.0.2| CC: NL| x: 196

stdout from the socket server:
{'date': '2009-03-29 
23:28:48', 'ip': '10.0.0.2', 'CC': 'NL', 'eventid': '0de8b6b1b019d19bc3e7eb5ca986cdcade75e20587211569eebdfcc8', 'x': '194'}
{'date': '2009-03-29 
23:28:48', 'ip': '10.0.0.2', 'CC': 'NL', 'eventid': 'bc728c0113bb35d748bf2be0fae52a85242c87a0d41495aeee9d69c0', 'x': '195'}
{'date': '2009-03-29 
23:28:48', 'ip': '10.0.0.2', 'CC': 'NL', 'eventid': '9f946b3948d2f2b84b241e25f1a05f2260e53a98a7d1af5a61787f38', 'x': '196'}


On Sunday 29 March 2009 09:33:46 pm you wrote:


> 2009/3/30 David Sfiligoi <webmaster-HeWF603wDIhWk0Htik3J/[email protected]>:
> > Hi Graham,
> >
> > Yes I agree defining my logger outside the mod python handler was a bad
> > idea. Using the req.log_error works of course.  Obviously if I wanted
> > integrate this into all the other apps that revolve around those logs,
> > i'd have to write a converter or change each apps which parses the log
> > data.
> >
> > I'd like to understand this a bit better, perhaps I have the wrong basic
> > idea on how the python handler works in overall, but if I install the log
> > handler in the handler function and delete the log objects before ending,
> > shouldn't that take care of the multiple logging issue?
> >
> > Or are you saying that each piece of code that should not produce
> > multiple entries of the same thing should really be inside a module so I
> > can let import_module() take care of it?
>
> Put logging initialisation in a completely separate module outside of
> document tree and not inside of the handler code files. Setup
> PythonPath if need be where that separate module is located,  and then
> have handler code files import that module from that other location.
>
> This should ensure that the logging initialisation code is imported
> and run only once per process. If you intentionally then change the
> logging initialisation module code, you will need to restart Apache.
>
> > Im seeing the same 'multiplicity' issue when I open a socket while in
> > handler function. This is really what trigger the question.
>
> That I can't explain at this point. I was assuming that your
> duplicated logging may have been confusing the issue.
>
> > Thanks,
> >
> > David
> >
> > On Sunday 29 March 2009 05:45:01 am Graham Dumpleton wrote:
> >> If you change a mod_python handler script, it will be automatically
> >> reloaded. This would be a problem in your code as you installed a log
> >> handler each time it is loaded into the same process. Having multiple
> >> instances of the log handler installed would result in the same
> >> information possibly being logged multiple times.
> >>
> >> I would suggest you add inside your handler script:
> >>
> >>   req.log_error("I have been called")
> >>
> >> If that appears twice in the Apache error log file then I would be
> >> concerned, otherwise I would say the problem is with your use of the
> >> logging module.
> >>
> >> Also read about import_module() in:
> >>
> >>   http://www.modpython.org/live/current/doc-html/pyapi-apmeth.html
> >>
> >> as it explains a bit about module reloading and the way to preserve
> >> global data or avoid stuff which performs additive operations each
> >> time it is loaded.
> >>
> >> Graham