BIND 10 #1704: log output mixed

[BIND 10 Development]

#1704: log output mixed
-------------------------------------+-------------------------------------
                   Reporter:  jreed  |                 Owner:  muks
                       Type:         |                Status:  reviewing
  defect                             |             Milestone:
                   Priority:         |  Sprint-20120529
  medium                             |            Resolution:
                  Component:         |             Sensitive:  0
  logging                            |           Sub-Project:  Core
                   Keywords:         |  Estimated Difficulty:  15
            Defect Severity:  N/A    |           Total Hours:  0
Feature Depending on Ticket:         |
        Add Hours to Ticket:  0      |
                  Internal?:  0      |
-------------------------------------+-------------------------------------

Comment (by muks):

 Hi jinmei

 Thank you for a detailed review :)

 Replying to [comment:36 jinmei]:
 > I've not given the branch a full review, but have noticed a few
 > possibly substantial points.  So I'd like to discuss them first.
 >
 > - should we worry about performance impact of locking and unlocking?

 In normal use-case, log messages are generated perhaps every few hundred
 milliseconds at worst. So the impact of locking/locking (even if it is
 file based) should be negligible.

 In the branch currently, we `open()` in the constructor and not on every
 log message. The `open()` would be more costly as it would involve path
 operations and access checks.

 Overall we don't have to worry about it I think.

 > - As documented, we cannot do complicated things involving resource
 >   allocation in the `Logger` constructor.  In fact, this branch causes
 >   crash on my environment due to the static initialization fiasco.
 >   Not looking into it closely, but we should probably move this stuff
 >   to `LoggerImpl`.

 Will check this.

 > - I know it could be tricky, but I'd like to test this feature as much
 >   as possible.

 This would indeed be complicated, especially as the file lock would have
 to be tested from a different process between the lock and unlock. Not
 sure if the code can take a mock object. I'll check it too.

 > - We'll definitely need a changelog entry for this ticket.

 How about this:
 {{{
 XYZ.    [func]          muks
         The logger now uses a lockfile named `logger_lockfile' that is
         created in the local state directory to mutually separate
         individual logging operations from various processes. This is
         done so that log messages from different processes don't mix
         together in the middle of lines.
 }}}

 > - I'd like to see documentation about the lock file, and the
 >   relationship with the magic environment variables (including when we
 >   need to define them).

 Where shall I put this documentation? In the guide?

 The magic environment variables are the same as used for the rest of the
 codebase when shared resources are used and programs are run from the
 top srcdir (B10_FROM_SOURCE). It would be worth writing utility
 functions to get paths to files (bug #1979) and document that instead.

 > - Considering the bind10 process will often start as root and
 >   initially open the lock file, are others running as a non privileged
 >   user can get access to it?

 No they can't. Good catch. I'll check this too.

 > - I'm simply not sure, so just asking: is it a good idea to repeat the
 >   "unable to use lock file" log when the process fails to open it?

 Maybe not. I'll check it, but I can't log errors in the constructor
 anyway. Will see about changing this.

 > - I guess a single process can open multiple lock files.  Would that
 >   cause any problem?

 No it won't. Locks over already granted ranges in the same process will
 all apply without blocking. (I don't remember if the behavior is
 recursive, but it doesn't matter.)

 > - Maybe we should allow the bind10 process to delete the lock file at
 >   the very end of its process?

 I'll check this too.

 > - The else block of `Logger::output` is (possibly) not exception
 >   safe.  Consider the case where the main outputRaw throws.

 *nod*. Will fix.

 > - On a related note, isn't there a better primitive than the very low
 >   level system call?  From a quick look boost also has a similar (in
 >   addition to interprocess_mutex) API: file_lock.

 After using `interprocess_mutex` and reverting it, I side with `fcntl()`
 for this case. Its use here is very straightforward and any UNIX
 programmer can follow it. The behaviour is well defined (multiple locks
 are OK, and when process terminates, the locks are removed
 automatically).

 If it was a data structure or something complicated, then using boost
 would be worthwhile.

 > - If we want to log the event when locking/unlocking fails, I think
 >   it should be an ERROR, not a WARN.

 I'll change this. I thought that failure on locking is not a
 showstopper, so it can be WARN, but a failure to unlock would be a
 problem.

 > - for log_test.py, may be a matter of taste, but since we'd need to
 >   run it from Makefile in practice (due to other setups), we could
 >   just set B10_FROM_SOURCE in the Makefile before running the test
 >   script.  That way we don't have to auto-generate it from .in.

 I agree. Will change this too.

-- 
Ticket URL: <http://bind10.isc.org/ticket/1704#comment:38>
BIND 10 Development <http://bind10.isc.org>
BIND 10 Development