[lxml-dev] Better error reporting
Hi, since we often have requests regarding better error reporting in lxml, I implemented a little error log. lxml now keeps a bounded list of output messages from libxml2/xslt (that normally appear on stdout) and provides access to the log entries through its exceptions. LxmlException objects now have an additional attribute "error_log" that contain the last log entries (up to 20 by default). So, if an exception is raised, whoever catches it can print out the error messages from libxml2/xslt to see where things went wrong. This behaviour can be switched on or off at compile time and defaults to off. If off, the attribute simply stores an empty tuple. I hope that comes close to what was asked for. Stefan
Stefan Behnel wrote:
Hi,
since we often have requests regarding better error reporting in lxml, I implemented a little error log. lxml now keeps a bounded list of output messages from libxml2/xslt (that normally appear on stdout) and provides access to the log entries through its exceptions.
LxmlException objects now have an additional attribute "error_log" that contain the last log entries (up to 20 by default). So, if an exception is raised, whoever catches it can print out the error messages from libxml2/xslt to see where things went wrong.
This behaviour can be switched on or off at compile time and defaults to off. If off, the attribute simply stores an empty tuple.
What's the motivation for defaulting this to 'off'?
I hope that comes close to what was asked for.
This sounds very useful! Great! How precise is this information? Do we see the last 5 lines for an XML parsing error that occured earlier in a later XSLT reception? We also have the case for RelaxNG/Schema reporting where no exception is raised if the XML is not valid according to the schema. Regards, Martijn
Martijn Faassen wrote:
Stefan Behnel wrote:
since we often have requests regarding better error reporting in lxml, I implemented a little error log. lxml now keeps a bounded list of output messages from libxml2/xslt (that normally appear on stdout) and provides access to the log entries through its exceptions.
LxmlException objects now have an additional attribute "error_log" that contain the last log entries (up to 20 by default). So, if an exception is raised, whoever catches it can print out the error messages from libxml2/xslt to see where things went wrong.
This behaviour can be switched on or off at compile time and defaults to off. If off, the attribute simply stores an empty tuple.
What's the motivation for defaulting this to 'off'?
I consider this more of a debug helper than something you'd use in production. It doesn't really help you in /handling/ errors as all you get is non computer readable strings with error messages. It /does/ help you when you read through them to see where the bugs in your applications are. It does not help your /program/ to handle errors. Since the log had to be copied at the moment of exception raising, I first thought that exception creation becomes somewhat faster if it's switched off. I changed the error_log attribute to a property now that accesses the *current* log. This means that it does no longer guarantee to conserve the exact state of the error log at exception creation time (which should not be a problem if you do not make any libxml calls before catching it), but it also means that there is no longer any performance penalty for creating exceptions. So now, I would also prefer the default to be "on".
How precise is this information? Do we see the last 5 lines for an XML parsing error that occured earlier in a later XSLT reception?
Well, you see the last 20 lines - if you explicitly print them. They are not (currently) shown in the exception message or the traceback. The code cannot really try to find the line that triggered the error, so it's really just 20 lines of messages. You /could/ extend this to incorporate more of the information provided by the libxml2/xslt error calls (like error types, etc.). On XML errors, for example, libxml2 gives you this: int domain : What part of the library raised this er int code : The error code, e.g. an xmlParserError char * message : human-readable informative error messag xmlErrorLevel level : how consequent is the error char * file : the filename int line : the line number if available char * str1 : extra string information char * str2 : extra string information char * str3 : extra string information int int1 : extra number information int int2 : column number of the error or 0 if N/A void * ctxt : the parser context if available void * node : the node in the tree The problem is: the more information you put into the log, the slower the application becomes. Providing the element that triggered the error, for example, would rather be out of scope. Note that you have to convert this information to Python representations in order to store it in the log.
We also have the case for RelaxNG/Schema reporting where no exception is raised if the XML is not valid according to the schema.
I added error_log properties to the RelaxNG and XMLSchema classes. That should solve that problem. Stefan
Stefan Behnel wrote:
Martijn Faassen wrote:
Stefan Behnel wrote:
since we often have requests regarding better error reporting in lxml, I implemented a little error log. lxml now keeps a bounded list of output messages from libxml2/xslt (that normally appear on stdout) and provides access to the log entries through its exceptions.
LxmlException objects now have an additional attribute "error_log" that contain the last log entries (up to 20 by default). So, if an exception is raised, whoever catches it can print out the error messages from libxml2/xslt to see where things went wrong.
This behaviour can be switched on or off at compile time and defaults to off. If off, the attribute simply stores an empty tuple.
What's the motivation for defaulting this to 'off'?
I consider this more of a debug helper than something you'd use in production. It doesn't really help you in /handling/ errors as all you get is non computer readable strings with error messages. It /does/ help you when you read through them to see where the bugs in your applications are. It does not help your /program/ to handle errors.
It depends on what your program does. If I for instance use lxml in a larger application where I want to allow developers to upload their XSLT stylesheets, I'd like my application to show the users what errors they had in their XSLT stylesheet if they upload the wrong one.
Since the log had to be copied at the moment of exception raising, I first thought that exception creation becomes somewhat faster if it's switched off. I changed the error_log attribute to a property now that accesses the *current* log. This means that it does no longer guarantee to conserve the exact state of the error log at exception creation time (which should not be a problem if you do not make any libxml calls before catching it), but it also means that there is no longer any performance penalty for creating exceptions. So now, I would also prefer the default to be "on".
Okay good. Another question: How does error logging work in combination with threads? I noticed that the code in lxml that turned off the talkativeness of libxml2 actually only worked for the main thread, and that new threads that use lxml do become talkative again.
How precise is this information? Do we see the last 5 lines for an XML parsing error that occured earlier in a later XSLT reception?
Well, you see the last 20 lines - if you explicitly print them. They are not (currently) shown in the exception message or the traceback. The code cannot really try to find the line that triggered the error, so it's really just 20 lines of messages.
You /could/ extend this to incorporate more of the information provided by the libxml2/xslt error calls (like error types, etc.). On XML errors, for example, libxml2 gives you this:
int domain : What part of the library raised this er int code : The error code, e.g. an xmlParserError char * message : human-readable informative error messag xmlErrorLevel level : how consequent is the error char * file : the filename int line : the line number if available char * str1 : extra string information char * str2 : extra string information char * str3 : extra string information int int1 : extra number information int int2 : column number of the error or 0 if N/A void * ctxt : the parser context if available void * node : the node in the tree
The problem is: the more information you put into the log, the slower the application becomes. Providing the element that triggered the error, for example, would rather be out of scope. Note that you have to convert this information to Python representations in order to store it in the log.
I'm not too concerned that slowing down exceptions somewhat is going to impact things that badly - these exceptions are typically not occuring very often. Since it's lxml's mission to make libxml2 usable by mortal python programmers with a nice API, I consider it part of our mission to make the error API as nice as possible too, providing as much information as we can, in an easy to understand way. That's all future music though. I think this is already a great step forward, I'm just pointing where I'd like to go.
We also have the case for RelaxNG/Schema reporting where no exception is raised if the XML is not valid according to the schema.
I added error_log properties to the RelaxNG and XMLSchema classes. That should solve that problem.
Another way that might be more consistent is to add new methods that either silently validate or, in case of validation errors, raise an exception. Regards, Martijn
Martijn Faassen wrote:
Another question: How does error logging work in combination with threads? I noticed that the code in lxml that turned off the talkativeness of libxml2 actually only worked for the main thread, and that new threads that use lxml do become talkative again.
According to the libxml2 docs, that's intentional. Each thread has to configure that for itself. Currently, there isn't that much in lxml anyway that takes care of threads. Everything that's module level will interfere. A way to get around this would be to set an error log in each sensible function. Hmm, I actually think that would be the right way. I'll code this up and see how it turns out.
libxml2 gives you this:
int domain : What part of the library raised this er int code : The error code, e.g. an xmlParserError char * message : human-readable informative error messag xmlErrorLevel level : how consequent is the error char * file : the filename int line : the line number if available char * str1 : extra string information char * str2 : extra string information char * str3 : extra string information int int1 : extra number information int int2 : column number of the error or 0 if N/A void * ctxt : the parser context if available void * node : the node in the tree
The problem is: the more information you put into the log, the slower the application becomes. Providing the element that triggered the error, for example, would rather be out of scope. Note that you have to convert this information to Python representations in order to store it in the log.
I'm not too concerned that slowing down exceptions somewhat is going to impact things that badly - these exceptions are typically not occuring very often. Since it's lxml's mission to make libxml2 usable by mortal python programmers with a nice API, I consider it part of our mission to make the error API as nice as possible too, providing as much information as we can, in an easy to understand way.
That's all future music though. I think this is already a great step forward, I'm just pointing where I'd like to go.
I also thought a bit more about this. It would be better to store more information and then allow filtering based on domain and error codes. RNG classes should only return RNG errors, for example (although earlier failures may have contributed to the current error...). Maybe use a dedicated log entry class rather than plain strings?
We also have the case for RelaxNG/Schema reporting where no exception is raised if the XML is not valid according to the schema.
I added error_log properties to the RelaxNG and XMLSchema classes. That should solve that problem.
Another way that might be more consistent is to add new methods that either silently validate or, in case of validation errors, raise an exception.
Hmmm, I don't know. If that's only for retrieving more precise error information... Maybe a method like "assert" could be meaningful here. Stefan
Stefan Behnel wrote:
Martijn Faassen wrote:
Another question: How does error logging work in combination with threads? I noticed that the code in lxml that turned off the talkativeness of libxml2 actually only worked for the main thread, and that new threads that use lxml do become talkative again.
According to the libxml2 docs, that's intentional. Each thread has to configure that for itself. Currently, there isn't that much in lxml anyway that takes care of threads. Everything that's module level will interfere.
A way to get around this would be to set an error log in each sensible function. Hmm, I actually think that would be the right way. I'll code this up and see how it turns out.
Great! It'd be nice if threads worked with lxml, of course. One would like to have it work in a web server... [snip]
That's all future music though. I think this is already a great step forward, I'm just pointing where I'd like to go.
I also thought a bit more about this. It would be better to store more information and then allow filtering based on domain and error codes. RNG classes should only return RNG errors, for example (although earlier failures may have contributed to the current error...).
Maybe use a dedicated log entry class rather than plain strings?
I haven't studied your new code, and the libxml2 error handling code was a maze of twisty passages I last looked at a long time ago, so I'm not sure I can say much that's sensible. :) If I understand you right, that sounds like the right direction though. Store more information and then in the particular exception filter out only the relevant information. You're right in that the earlier failures may have contributed to the current error, though one would expect another exception to be raised first anyway that case, right?
We also have the case for RelaxNG/Schema reporting where no exception is raised if the XML is not valid according to the schema.
I added error_log properties to the RelaxNG and XMLSchema classes. That should solve that problem.
Another way that might be more consistent is to add new methods that either silently validate or, in case of validation errors, raise an exception.
Hmmm, I don't know. If that's only for retrieving more precise error information... Maybe a method like "assert" could be meaningful here.
Yeah, calling it something like 'assert' would sense (of course that's a reserved word by itself; perhaps 'ensure' would be better as that avoids confusion with the built in assert and AssertionError). I think it makes a level of sense to write code like: relaxng.ensureValid(doc) ... do stuff with doc ... and then if it turns out your doc wasn't valid, you get an exception. It allows for writing quick and dirty code that ensures a document complies with the schema. Once you're ready for error handling, you add a try and except around it and handle the error. Regards, Martijn
Martijn Faassen wrote:
Stefan Behnel wrote:
A way to get around this would be to set an error log in each sensible function. Hmm, I actually think that would be the right way. I'll code this up and see how it turns out.
Great! It'd be nice if threads worked with lxml, of course. One would like to have it work in a web server...
There is now a branch called error-reporting that implements this. It is partially untested, but at least the global logging and exception handling seems to work. It should potentially also work at a thread level, although the global logging may be broken there. My SVN log entry: large rewrite of the error handling API - use named class attributes for error domain, type and level - _LogEntry class represents xmlError structure - _ErrorLog collects error entries - global log collects all errors, rotates at 100 entries - API functions can be wrapped in log.connect() and log.disconnect() to provide a local error log (exemplified in XMLSchema and RelaxNG - untested) The last line refers to a local log that can be created at object instantiation time (i.e. at the end of RelaxNG.__init__() etc.). Stefan
participants (2)
-
Martijn Faassen -
Stefan Behnel