Commit: cd6d3aafe314ab7565d
Implemented: Fri Aug 6 10:04:41 2010
Status: Mature
Branch: trunk-pg84, official-trunk (partially)
Again, with respect to logging, good methods of fine-tuning the loggers can save a developer quite a lot of time.
That patch has allowed setting individual loggers' level at runtime, as well as reading back the level into custom scripts. It uses the Pythonic infrastructure of logging, won't add any overhead to existing code.
The usage of that is that we can dump the level table of all the loggers of a running OpenERP server, and then restore it into another server. A typical usage scenario is when one of our customers reports a problem in their production machines. We can prepare for them a logging template that would hopefully catch the necessary informations (without bloating millions of log lines) and let us examine it. All that, without requiring any server downtime.
Another scenario is for developers, when they need a fine-tuned logging setup, in order to only debug a part of the system. Hide the cronjobs, enable debugging of document FTP, for example. This way we won't ever need explicit logging levels for DEBUG_FOO.
Showing posts with label logging. Show all posts
Showing posts with label logging. Show all posts
Thursday, February 17, 2011
Per-Model Debug (aka. orm._debug)
Original commit: 91c044df57d9e8cfb426e
Rebased commit: db5597aa5097d697ac37
Conceived: 27 Dec 2009
Implemented: Dec 2009
Status: Mature
Git Branch: trunk-xrg, trunk-pg84 (mainly)
Cons: Need explicit code in parts of framework
It is a common situation that we need to have verbose logging of some object operations, in order to trace some bug. But, if we enabled the full debug_rpc output, our needle would be lost in the haystack of million logging lines.
Adding and removing "print" statements in the code is one way, but would only work when we know where to put the "print" line.
Therefore, we define one attribute per ORM object, namely '_debug', which will control verbose logging of that object. If set (to true), the rest of the framework will log in detail the operations related to that model, typically with the DEBUG logging level.
Being formalised, we also have the ability to expose the flag through a special web-services call, so that debugging can conveniently be turned on and off at runtime, without any server restart.
Technically, this is implemented through a '_debug' attribute of the orm_template class. This means that every orm or orm_memory object will have its own _debug value, persistent for the life of a database session.
It is just a boolean flag (actually, other values would be permitted, too)
and can be used in various points where we need to decide if we need verbose logging.
In other words: when we suspect that model "account.brokeness" is doing something wrong, we send an RPC call to set _debug of "account.brokeness", on our live-running server[1][2]. Then, we observe the logging output and see in detail SQL calls, calls to read(), write(), read_flat() and browse() for that object.
Also, if we define some custom code for our model (in python), we can explicitly put debugging statements and leave them there (commit them) without bloating the logs:
Result: easier distinguish between models, have focused and detailed logs on the objects we are interested in.
Example logs:
----
[1] There is a custom Bash script to explicitly set debugging of a model in server/tools/set-obj_debug.sh . Feel free to call this method through any RPC client
[2] The BQI script is also adapted to easily set debug of orm models, see its interactive commands.
Rebased commit: db5597aa5097d697ac37
Conceived: 27 Dec 2009
Implemented: Dec 2009
Status: Mature
Git Branch: trunk-xrg, trunk-pg84 (mainly)
Cons: Need explicit code in parts of framework
It is a common situation that we need to have verbose logging of some object operations, in order to trace some bug. But, if we enabled the full debug_rpc output, our needle would be lost in the haystack of million logging lines.
Adding and removing "print" statements in the code is one way, but would only work when we know where to put the "print" line.
Therefore, we define one attribute per ORM object, namely '_debug', which will control verbose logging of that object. If set (to true), the rest of the framework will log in detail the operations related to that model, typically with the DEBUG logging level.
Being formalised, we also have the ability to expose the flag through a special web-services call, so that debugging can conveniently be turned on and off at runtime, without any server restart.
Technically, this is implemented through a '_debug' attribute of the orm_template class. This means that every orm or orm_memory object will have its own _debug value, persistent for the life of a database session.
It is just a boolean flag (actually, other values would be permitted, too)
and can be used in various points where we need to decide if we need verbose logging.
In other words: when we suspect that model "account.brokeness" is doing something wrong, we send an RPC call to set _debug of "account.brokeness", on our live-running server[1][2]. Then, we observe the logging output and see in detail SQL calls, calls to read(), write(), read_flat() and browse() for that object.
Also, if we define some custom code for our model (in python), we can explicitly put debugging statements and leave them there (commit them) without bloating the logs:
if Some-strange-condition:
. if self._debug:
. . logger.debug("Our object has %s" % self.strange_field)
Result: easier distinguish between models, have focused and detailed logs on the objects we are interested in.
Example logs:
BQI> orm ir.attachment
BQI ir.attachment> debug object on
BQI ir.attachment> do search([])
[...] DEBUG:http:MultiHttpHandler init for ('127.0.0.1', 34760)
[...] DEBUG:orm:Generate order from create_date desc and None
[...] DEBUG:db.cursor:Q: SELECT "ir_attachment".id FROM "ir_attachment" ORDER BY create_date desc
[...] DEBUG:orm:ir.attachment.read([5, 4], fields=['id', 'res_model'])
[...] DEBUG:orm:ir.attachment.read_flat: tables=['"ir_attachment"'], fields_pre=['res_model']
Command 'execute' returned from server
[...] DEBUG:db.cursor:Q: SELECT id,"res_model" FROM "ir_attachment" WHERE id = ANY(ARRAY[5, 4])ORDER BY create_date desc
[...] DEBUG:db.cursor:Q: SELECT id,"res_model" FROM "ir_attachment" WHERE id = ANY(ARRAY[5, 4])ORDER BY create_date desc
Res: [5, 4]
----
[1] There is a custom Bash script to explicitly set debugging of a model in server/tools/set-obj_debug.sh . Feel free to call this method through any RPC client
[2] The BQI script is also adapted to easily set debug of orm models, see its interactive commands.
Subscribe to:
Posts (Atom)