Opened 9 years ago

Closed 9 years ago

#267 closed defect (fixed)

python log shouldn't die with OSError

Reported by: jinmei Owned by: zzchen_pku
Priority: medium Milestone: 06. 4th Incremental Release
Component: logging Version:
Keywords: Cc:
CVSS Scoring: Parent Tickets:
Sensitive: no Defect Severity:
Sub-Project: Feature Depending on Ticket:
Estimated Difficulty: 0.0 Add Hours to Ticket:
Total Hours: Internal?: no

Description

If the log file directory can't be created due to a permission problem, log.py propagates OSError to the application, and the app could die. xfrout suffers from this problem:

[bind10] Resurrected b10-xfrout (PID 51110)
Traceback (most recent call last):
  File "/Users/jinmei/src/isc/bind10/trunk/src/bin/xfrout/b10-xfrout", line 497, in <module>
    xfrout_server = XfroutServer()
  File "/Users/jinmei/src/isc/bind10/trunk/src/bin/xfrout/b10-xfrout", line 409, in __init__
    self._config_data.get('log_max_bytes'), True)
  File "/Users/jinmei/src/isc/bind10/trunk/src/lib/python/isc/log/log.py", line 146, in __init__
    self._add_rotate_handler(self._log_file, self._versions, self._max_bytes)
  File "/Users/jinmei/src/isc/bind10/trunk/src/lib/python/isc/log/log.py", line 164, in _add_rotate_handler
    maxBytes = max_bytes, backupCount = backup_count)
  File "/Users/jinmei/src/isc/bind10/trunk/src/lib/python/isc/log/log.py", line 45, in __init__
    os.makedirs(dir[0])
  File "/opt/local/Library/Frameworks/Python.framework/Versions/3.1/lib/python3.1/os.py", line 143, in makedirs
    mkdir(name, mode)

Since logging is an optional feature in many cases, it doesn't make much sense to have the application expect and handle such exceptions or die.

The attached patch solves this particular problem, but os.makedirs() could be called via a different path, so I think it's better to revisit the entire failure mode in this module.

I'm giving this ticket to Jerry.

Subtickets

Attachments (2)

log.diff (459 bytes) - added by jinmei 9 years ago.
log_patch.diff (6.9 KB) - added by zzchen_pku 9 years ago.

Download all attachments as: .zip

Change History (21)

Changed 9 years ago by jinmei

comment:1 Changed 9 years ago by zzchen_pku

  • Status changed from new to accepted

Thanks, Jinmei.
I'll look through it.

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

  • Owner changed from zzchen_pku to jinmei
  • Status changed from accepted to reviewing

I think this patch should be ok.
Jinmei, can you review it?
Thanks.

comment:3 in reply to: ↑ 2 ; follow-up: Changed 9 years ago by jinmei

Replying to zzchen_pku:

I think this patch should be ok.
Jinmei, can you review it?

First off, add tests please:-)

Comments on the patch:

  • I'm not sure why the second chunk of patch performs various tests (e.g., whether the file is writable). if we need them here, shouldn't we need them in other places including the constructor? Also, update_config() itself doesn't seem to perform system level operations, so I'm not sure if we need to create the directory here.
  • for that matter, I'm not even sure if we need to bother to create the directory beforehand. It may or may not be a good thing, but since it's an extension to python's library behavior, I'd like to see documentation about which policy is adopted and why. Then that policy should be applied consistently throughout this module (see the first bullet about consistency)
  • not necessarily about the patch, but relevant to the issue of this ticket: NSFileLogHandler.shouldRollover() can also call os.makedirs(), and it can raise an exception, right? What should we do with this?
  • since the underlying logging facility can raise an exception, I'm not sure if it makese sense to try catching exceptions one by one. We should probably catch exceptions in a wider context, e.g., on initialization and in NSLogger.log_message(), and perhaps when updating the configuration.

comment:4 Changed 9 years ago by jinmei

  • Owner changed from jinmei to zzchen_pku

comment:5 follow-up: Changed 9 years ago by jinmei

One more thing: while I believe it's better to keep running even if a systm level error (file is non writable, etc) occurs with logging, it would also be nice if we could report the error in some way. In particular, if stderr is writable, reporting it there at initialization time would be helpful (an error that happens in writing logs may not be effectively reportable, but I think we can live with that).

Dying due to an error for an optional feature isn't good, but silently ignoring errors is not good either.

comment:6 in reply to: ↑ 3 Changed 9 years ago by zzchen_pku

Replying to jinmei:

First of all, thank you very much for your specific suggestions.

First off, add tests please:-)

Ok.

Comments on the patch:

  • I'm not sure why the second chunk of patch performs various tests (e.g., whether the file is writable). if we need them here, shouldn't we need them in other places including the constructor? Also, update_config() itself doesn't seem to perform system level operations, so I'm not sure if we need to create the directory here.
  • for that matter, I'm not even sure if we need to bother to create the directory beforehand. It may or may not be a good thing, but since it's an extension to python's library behavior, I'd like to see documentation about which policy is adopted and why. Then that policy should be applied consistently throughout this module (see the first bullet about consistency)

OK, I'll update the document and consider about consistency.

  • not necessarily about the patch, but relevant to the issue of this ticket: NSFileLogHandler.shouldRollover() can also call os.makedirs(), and it can raise an exception, right? What should we do with this?
  • since the underlying logging facility can raise an exception, I'm not sure if it makese sense to try catching exceptions one by one. We should probably catch exceptions in a wider context, e.g., on initialization and in NSLogger.log_message(), and perhaps when updating the configuration.

Agree. It is make sense to catch exceptions in a wider context.

comment:7 in reply to: ↑ 5 ; follow-up: Changed 9 years ago by zzchen_pku

Replying to jinmei:

One more thing: while I believe it's better to keep running even if a systm level error (file is non writable, etc) occurs with logging, it would also be nice if we could report the error in some way. In particular, if stderr is writable, reporting it there at initialization time would be helpful (an error that happens in writing logs may not be effectively reportable, but I think we can live with that).

Dying due to an error for an optional feature isn't good, but silently ignoring errors is not good either.

Because I think most users will not care about errors in the logging system, they are more interested in application errors.
Maybe you are right, we could report the error to stderr.

comment:8 in reply to: ↑ 7 Changed 9 years ago by jinmei

  • billable set to 1
  • Internal? unset

Replying to zzchen_pku:

Replying to jinmei:

One more thing: while I believe it's better to keep running even if a systm level error (file is non writable, etc) occurs with logging, it would also be nice if we could report the error in some way. In particular, if stderr is writable, reporting it there at initialization time would be helpful (an error that happens in writing logs may not be effectively reportable, but I think we can live with that).

Dying due to an error for an optional feature isn't good, but silently ignoring errors is not good either.

Because I think most users will not care about errors in the logging system, they are more interested in application errors.
Maybe you are right, we could report the error to stderr.

I agree people don't care about the log system much *compared to*
application level errors, but I, for one, would like to know it if I
misconfigure the operational environment (e.g. not adjusting directory
permission) and logging doesn't work as expected sooner than later.

Changed 9 years ago by zzchen_pku

comment:9 follow-up: Changed 9 years ago by zzchen_pku

  • Owner changed from zzchen_pku to jinmei

Patch has been updated.
Exception raised by ShouldRollover?() will be handled by handleError() and logging errors will be reported to stderr.
Appreciate your opinions.

comment:10 in reply to: ↑ 9 ; follow-up: Changed 9 years ago by jinmei

  • Owner changed from jinmei to zzchen_pku

Replying to zzchen_pku:

Patch has been updated.
Exception raised by ShouldRollover?() will be handled by handleError() and logging errors will be reported to stderr.
Appreciate your opinions.

Sorry for the very long delay. I've finally found time for reviewing this stuff.

First, I've created a branch (branches/trac267) for the convenience of update/review cycles. Please check the branch, and commit any subsequent changes to the branch instead of attachments.

Specific comments:

  • NSFileLogHandler.handleError()
    • please describe the intent of this (overridden) method.
    • the log error doesn't seem to entirely correct: doesn't it cover other cases than "update"?
  • NSFileLogHandler.shouldRollover(): a minor issue, but the following line seems to make the close() call above it unnecessary.
                self.stream = None
    
  • regarding creating directories to the log file: my previous comment wasn't sufficiently addressed: Please describe the intent of this behavior as comments (including why you extended the original behavior of python logging this way).
  • NSFileLogHandler.update_config(): maybe I was confused in the previous comment. If we create a missing directory (or directories) to the log file on initialization, and if we want to be consistent (I do), it looks like we should create necessary directories here; otherwise the underlying logging framework won't create them on writing logs. This behaviour should be tested (updating the config with a different non existent directory for the new log file, and confirming the new file is created).
  • NSLogger.log_message(): please explain why you need to catch all exceptions here. I'd first avoid a catch-all catch by limiting possible exceptions. But if it's not feasible I'd explicitly explain why I catch all.
  • tests don't seem to be sufficient. There are no assertions in the added test code, and the intent of the test is not very clear.
  • now that tests are added, did you check the coverage, i.e, the code you added to log.py is covered by tests?

comment:11 in reply to: ↑ 10 Changed 9 years ago by zzchen_pku

First, I've created a branch (branches/trac267) for the convenience of update/review cycles. Please check the branch, and commit any subsequent changes to the branch instead of attachments.

Thanks.

Specific comments:

  • NSFileLogHandler.handleError()
    • please describe the intent of this (overridden) method.

Done. Have added comments.

  • the log error doesn't seem to entirely correct: doesn't it cover other cases than "update"?

Done.

  • NSFileLogHandler.shouldRollover(): a minor issue, but the following line seems to make the close() call above it unnecessary.
                self.stream = None
    

Done.

  • regarding creating directories to the log file: my previous comment wasn't sufficiently addressed: Please describe the intent of this behavior as comments (including why you extended the original behavior of python logging this way).
  • NSFileLogHandler.update_config(): maybe I was confused in the previous comment. If we create a missing directory (or directories) to the log file on initialization, and if we want to be consistent (I do), it looks like we should create necessary directories here; otherwise the underlying logging framework won't create them on writing logs.

Have added comments.

This behaviour should be tested (updating the config with a different non existent directory for the new log file, and confirming the new file is created).

The case has been covered by test_log_message().

  • NSLogger.log_message(): please explain why you need to catch all exceptions here. I'd first avoid a catch-all catch by limiting possible exceptions. But if it's not feasible I'd explicitly explain why I catch all.

logging.log(level, msg, *args, kwargs) may throw TypeError? and KeyError?, NSLogger.log_message() will catch these two specific exceptions.

  • tests don't seem to be sufficient. There are no assertions in the added test code, and the intent of the test is not very clear.
  • now that tests are added, did you check the coverage, i.e, the code you added to log.py is covered by tests?

unittest has been modified.
The code branch is trac267.

comment:12 Changed 9 years ago by zzchen_pku

coverage report:
---
Name Stmts Exec Cover


log 118 113 95%
log_test 138 137 99%


TOTAL 256 250 97%

comment:13 Changed 9 years ago by zzchen_pku

Sorry for bad format above.

coverage report:
-------------------------------
Name        Stmts  Exec   Cover
log         118    113    95%
log_test    138    137    99%
-------------------------------
TOTAL       256    250    97%

comment:14 Changed 9 years ago by zzchen_pku

  • Owner changed from zzchen_pku to jinmei

comment:15 Changed 9 years ago by stephen

  • Owner changed from jinmei to stephen

In absence of Jinmei, it's been assigned to me.

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

  • Owner changed from stephen to zzchen_pku

Branch created at: r2616
Code reviewed: r2932

All things raised by Jinmei have been addressed, apart from those listed below. There are also a couple of additional things that I have added.

src/lib/python/isc/log/log.py

__init__ and shouldRollover()
Are we absolutely sure that "filename" contains a directory component at this point? If given as just a bare filename (e.g. "log.txt"), then os.path.split() will return the empty string as its first element and the subsequent call to os.makedirs() will fail.

Remark: "dir" (used to hold the result of os.path.split()) is the name of a built-in Python function. Its use as a variable is OK, but it is highlighted when I look at the file with an editor that does syntax colouring.

  • regarding creating directories to the log file: my previous comment wasn't sufficiently addressed: Please

describe the intent of this behavior as comments (including why you extended the original behavior of python
logging this way).

I don't think that the comments have quite the level of detail that Jinmei wanted. I think the essence of the question is why create the directories? Most other applications will fail if the directory does not exist.

  • NSFileLogHandler.update_config(): maybe I was confused in the previous comment. If we create a missing

directory (or directories) to the log file on initialization, and if we want to be consistent (I do), it looks like we
should create necessary directories here; otherwise the underlying logging framework won't create them on writing logs.

Remark: I think that the location of the directory creation is OK - when the handler is initialized and whenever there is a possibility that the logging system will write to a different file. Changes made via a call to update_config() will be picked up in the next call to shouldRollover(). (Incidentally, a comment to that effect in update_config() would be useful.)

src/lib/python/isc/log/tests/log_test.py
General
File should include the standard header comments.

Class TestRotateFileHandler
To check the last point above (about the change to update_config() being picked up at the next call to shouldRollover()), a test should be added for the interaction of the two methods - update the configuration, log a record, and make sure that the log file has rolled.

test_handle_Error(): this is a no-op. I suggest that it could log a message, then read the log file and check that the logged message is as expected.

Class TestSysLogHandler
test_emit(): This only checks that the emit() call does not fail - it does not check that the record has been sent to the syslog stream.

Class TestLogger
test_logging_init(): Suggestion: This method has lines of the form

ret = ABC in AYZ
self.assertTrue(ret)

... which might be better expressed (and give more information on an error) as:

self.assertIn(ABC, XYZ, "<Reason why the assertion failed>")

However, the code as it stands does work so there is no urgent need to refactor.

comment:17 in reply to: ↑ 16 Changed 9 years ago by zzchen_pku

  • Owner changed from zzchen_pku to stephen

Replying to stephen:

src/lib/python/isc/log/log.py
__init__ and shouldRollover()
Are we absolutely sure that "filename" contains a directory component at this point? If given as just a bare filename (e.g. "log.txt"), then os.path.split() will return the empty string as its first element and the subsequent call to os.makedirs() will fail.

Added NSFileLogHandler._get_abs_file_path() to get absolute file path.

Remark: "dir" (used to hold the result of os.path.split()) is the name of a built-in Python function. Its use as a variable is OK, but it is highlighted when I look at the file with an editor that does syntax colouring.

Done, should avoid use build-in python fuction as variable name.

I don't think that the comments have quite the level of detail that Jinmei wanted. I think the essence of the question is why create the directories? Most other applications will fail if the directory does not exist.
Remark: I think that the location of the directory creation is OK - when the handler is initialized and whenever there is a possibility that the logging system will write to a different file. Changes made via a call to update_config() will be picked up in the next call to shouldRollover(). (Incidentally, a comment to that effect in update_config() would be useful.)

Updated.

src/lib/python/isc/log/tests/log_test.py
General

Done.

Class TestSysLogHandler
test_emit(): This only checks that the emit() call does not fail - it does not check that the record has been sent to the syslog stream.

The destination of syslog stream depends on OS type and syslog.conf, so it is difficult to trace and check the log message. Do you have any good suggestions?
Thank you for your comments.

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

  • Owner changed from stephen to zzchen_pku

Class TestSysLogHandler
test_emit(): This only checks that the emit() call does not fail - it does not check that
the record has been sent to the syslog stream.

The destination of syslog stream depends on OS type and syslog.conf, so it is difficult to
trace and check the log message. Do you have any good suggestions?

Not really. At the time of writing I had thought about generating a unique message in the test - possibly including the date/time the message was created so as to distinguish it from other runs of the test - then searching the syslog file for that string. However, the problem here is that the name of the syslog file is not standardised, e.g. by default it is "syslog" on Ubuntu and "system.log" on OS X. How we check that the modules in BIND-10 are logging correctly is a more generalised problem and something we should discuss further. I suggest that the code be left as it is for now.

All other changes checked and are OK.

Please go ahead and merge with trunk.

comment:19 in reply to: ↑ 18 Changed 9 years ago by zzchen_pku

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

Replying to stephen:

Not really. At the time of writing I had thought about generating a unique message in the test - possibly including the date/time the message was created so as to distinguish it from other runs of the test - then searching the syslog file for that string. However, the problem here is that the name of the syslog file is not standardised, e.g. by default it is "syslog" on Ubuntu and "system.log" on OS X. How we check that the modules in BIND-10 are logging correctly is a more generalised problem and something we should discuss further. I suggest that the code be left as it is for now.

Agree. Thank you for the review.
Commited. Closing it.

Note: See TracTickets for help on using tickets.