Opened 9 years ago

Closed 9 years ago

#1025 closed defect (complete)

logging argument should be more carefully checked

Reported by: jinmei Owned by: stephen
Priority: medium Milestone: Sprint-20110712
Component: Unclassified Version:
Keywords: Cc:
CVSS Scoring: Parent Tickets:
Sensitive: no Defect Severity: N/A
Sub-Project: Core Feature Depending on Ticket:
Estimated Difficulty: 3.0 Add Hours to Ticket: 0
Total Hours: 0 Internal?: no

Description

See #1023.

This may have to be case-by-case basis. But we should perform
comprehensive check once, and (ideally) introduce safer interface.

Subtickets

Change History (12)

comment:1 Changed 9 years ago by stephen

  • Milestone changed from Next-Sprint-Proposed to Sprint-20110712

comment:2 follow-up: Changed 9 years ago by stephen

It will be difficult to catch the error in #1023 on a general basis - the problem lay in the evaluation of the argument to the logging call. It just happened to manifest itself in a call to the logging code, but could have happened anywhere else. Also, I don't see what sort of safer interface we could have - the argument was evaluated before the logging code was called, so the logging code could do nothing about it.

However, I note that the arg() method of the logging Formatter class calls boost::lexical_cast to convert the argument to a string but does not handle a bad_lexical_cast exception. I think it should catch the exception and use something like "INVALID_ARGUMENT" instead.

comment:3 in reply to: ↑ 2 Changed 9 years ago by jinmei

Replying to stephen:

It will be difficult to catch the error in #1023 on a general basis - the problem lay in the evaluation of the argument to the logging call. It just happened to manifest itself in a call to the logging code, but could have happened anywhere else. Also, I don't see what sort of safer interface we could have - the argument was evaluated before the logging code was called, so the logging code could do nothing about it.

However, I note that the arg() method of the logging Formatter class calls boost::lexical_cast to convert the argument to a string but does not handle a bad_lexical_cast exception. I think it should catch the exception and use something like "INVALID_ARGUMENT" instead.

Actually, what I meant (by "check") is to re-review all LOG_xxx's to
see whether they have this type of (mostly) trivial dangerous usage.
But if we complete #1024 that's perhaps sufficient.

As for the additional check in boost::lexical_cast, we should at least
catch boost exceptions within it and convert it. I'm not so sure if
obscuring it is a good idea in that IMO it's not a good idea if we
simply e.g. return from a function when it sees a parameter that should
not have a particular value in that context (e.g. a NULL pointer).

comment:4 Changed 9 years ago by stephen

As for the additional check in boost::lexical_cast, we should at least catch boost exceptions within it and convert it. I'm not so sure if obscuring it is a good idea in that IMO it's not a good idea if we simply e.g. return from a function when it sees a parameter that should not have a particular value in that context (e.g. a NULL pointer).

My thought was that if we encounter an unusual situation and we can continue, we should. Ideally we should log the problem, but here the error is in the logging code itself and I was trying to avoid any unforeseen problems of having the code log a message in the middle of logging a message. (There might be none at the moment, but allowing it may constrain us in the future. And in any case, if we do log a message, we are still left with the question of what to return to the calling function.)

As to the more general case of encountering a problem, I think we should try to log the condition but continue if possible. Of course, this depends on the problem. So if a configuration value is read that is above an allowed maximum (say), I think it would be permissible to log the error but continue as if the maximum had been specified.

Things get more awkward if the error occurs in a more critical area of the code. For example, if an error is detected in the data source structure whilst servicing a query, what should we do? Obviously log the error and quite probably abandon the query: but should we stop the server? On the one hand, such an error might imply that the data source can't be trusted. On the other hand, the corruption might be localised and the bulk of queries could continue. I don't think there is an absolute right answer, but perhaps we should try to develop some guidelines.

comment:5 Changed 9 years ago by stephen

  • Estimated Difficulty changed from 0.0 to 3

comment:6 Changed 9 years ago by stephen

  • Owner set to stephen
  • Status changed from new to assigned

comment:7 Changed 9 years ago by stephen

  • Owner changed from stephen to UnAssigned
  • Status changed from assigned to reviewing

I've done a bit more thinking about this, and realised that a conversion to a string is highly unlikely to fail with a bad_lexical_cast error as virtually every data type can be represented as a string. (Conversion from strings is another matter.) A failure when converting to a string is more likely to be due to a memory allocation failure or an object-specific exception raised in its operator<<() method, neither of which should be handled in the Formatter::arg() method.

As bad_lexical_cast exception in these circumstances is therefore a potentially serious error, on reflection I think Jinmei is right and that converting the exception to a BIND 10 one is the best solution.

comment:8 Changed 9 years ago by vorner

  • Owner changed from UnAssigned to vorner

comment:9 Changed 9 years ago by vorner

  • Owner changed from vorner to stephen

The code looks OK, but there's a fundamental question ‒ in what way is our own exception better than the bad_lexical_cast?

comment:10 Changed 9 years ago by stephen

  • Owner changed from stephen to vorner

An unhandled bad_lexical_cast exception gives the message:

terminate called after throwing an instance of 'boost::exception_detail::clone_impl<boost::exception_detail::error_info_injector<boost::bad_lexical_cast> >'
  what():  bad lexical cast: source type value could not be interpreted as target
Aborted

(That example is from Ubuntu.) Throwing an isc::Exception-derived exception allows more information to be given as to where the problem lies. The exception also includes the file and line (and the text of the message also includes the name of the method in which the exception arose.)

comment:11 Changed 9 years ago by vorner

  • Owner changed from vorner to stephen

Hmm, right. That is probably true, I'm living on a system when it gives me a core file with complete backtrace, so I didn't think of it. This might be nicer.

Ok, please merge.

comment:12 Changed 9 years ago by stephen

  • Resolution set to complete
  • Status changed from reviewing to closed

Merged in commit 616537c54eb13b434294342e1a0df06375134ec0

Note: See TracTickets for help on using tickets.