On Sunday, June 24, 2012 9:51:52 PM UTC+2, Jonathan Lundell wrote: > > > I love this kind of bug, one where you'd be hard-pressed to get the result > by deliberate programming, but the bug seems to manage it with no effort > whatsoever. > > Suggestion for narrowing the scope of the problem: add a second log call > (important; don't extend the existing one) that prints a high-resolution > timestamp. time.time() ought to suffice, if you print enough of its digits. > > My immediate suspicion is the log logic itself, and I'm wondering whether > the multiple log entries will show the same timestamp, and whether the two > calls will show up as aabb or abab. > > Thanks to your suggestion, I have just swapped my log call with a print statement. I did not tried that before because the first time that I tried it did not work out - maybe bug in my code - and somehow I convinced myself that print statements were not useful for debugging in web2py controllers. Now I see that print statements can be used normally.
Anyway, I now see that my JSONRPC function is just being called once. Which brings me to my logging function. I have verified how I do my log system initialization, and it turns out that I am adding logger handlers each time that I request a logger. Normally this is not a problem, since I am requesting a logger per module, and each module is usually only loaded once. But the default.py controller is a web2py component, and thus it works diferently. Since the web2py controllers are being re-parsed with each requests, this is in fact increasing linearly the number of loggers, and thus I see repeated log entries. I wonder how many more surprises will bring the integration of my libraries with web2py ... The way in which web2py is using the python modules is unlike anything else I have come across. Thanks for your support, Daniel --
