BIND 10 #1704: log output mixed

[BIND 10 Development]

#1704: log output mixed
-------------------------------------+-------------------------------------
                   Reporter:  jreed  |                 Owner:  jinmei
                       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 jinmei):

 Sorry, on even a closer look, I still found a substantial issue:
 We need to tweak the lock file path for all test.  Otherwise a test
 could crash like this if the path isn't writable for the test:
 {{{
 [ RUN      ] DataSrcTest.Query
 *** Exception derived from isc::exception thrown:
     file: interprocess_sync_file.cc
     line: 67
     what: Unable to use interprocess sync lockfile:
 /usr/var/bind10-devel/logger_lockfile
 terminate called throwing an exception/bin/sh: line 1: 73461 Abort trap: 6
 }}}

 So, I suggest this:
 - first, use a separate environment variable than B10_FROM_BUILD, e.g.
   B10_LOCKFILE_DIR_FROM_BUILD.  The former is generic and can be used
   for a different purpose only for some selected situations.  Now we
   are going to set it (almost) always for all tests, it could break
   something if we use the generic variable.
 - second, set the variable in logger_unittest_support.cc:initLogger().
   rather than in each test's run_unittests.  The latter approach is a
   duplicate and would be easy to miss.
 - btw, as far as I can see log/tests/run_initializer_unittests doesn't
   need to set this variable.  That should be same for
   init_logger_test.sh or tests/run_unittests if we add this trick in
   initLogger().  Or even any other of them.  Please check.

 '''styles'''

 there are still some issues.  I've fixed them.

 '''documentation'''

 I originally planned to defer or ignore this, but now we still need to
 do some more ting...I'd explain a bit more about
 `InterprocessSyncLocker`:
   - describe parameters
   - describe return value (and for false on lock/unlock, whether it
     can normally happen or not, and what the caller would have
     to do with it)
   - any possible exceptions (and requirement on this point for derived
     classes)

 '''bind10_test'''

 - not a big deal, but since this is already auto generated, you could
   embed @abs_top_builddir@ in the py.in file rather than set it via
   the Makefile.  But that's a minor point, so I'd leave it to you.
 - I think it's safe to create/delete the dir in setup/teardown
   methods.  please also check this doesn't break distcheck.
 - isn't it better to use os.path.exists than os.path.isfile?
 - what's the purpose of the explicit close?
 {{{#!python
                 open(fname, "w").close()
 }}}
   If it's for the false positive about open file like due to the
   stupidity of Python as we discussed #1828, I'd avoid making our own
   code look counter intuitive due to that (besides, my python
   interpreter doesn't complain about it without close() even if it
   barks for other false positive cases).  If we really want to keep
   it, please add a comment about why we bother to do that.
 - I'd confirm the file exists after the possible open:
 {{{#!python
             if not os.path.isfile(fname):
                 open(fname, "w").close()
             self.assertTrue(os.path.isfile(fname))
 }}}

 Replying to [comment:55 muks]:

 > > '''interprocess_sync.h'''
 > >
 > > - Why did you make lock() variants protected and use `friend` to allow
 > >  `InterprocessSyncLocker` to call them (from a quick look and check
 > >  that seems to be the only purpose of the friend)?
 >
 > It's done to somewhat force the use of InterprocessSyncLocker rather
 than
 > InterprocessSync for locking (so that any locks are cleared up when the
 > basic block is quit). This needs the friend as the lock methods in the
 > InterprocessSync class are protected. I've described it in the class
 > documentation now.

 Hmm, okay.  I'm not still convinced if it's a reasonable use of
 friend, but I see the advantage of restricting the lock usage.  So
 this part is okay.

 > > '''interprocess_sync_file_unittest'''
 > >
 > > - We might want to simplify timeval initialization:
 > > {{{#!cpp
 > >       struct timeval tv = { 5, 0 };
 > > }}}
 > >   but it may not be a big deal as we cannot make it const with that
 due
 > >   to the select(2) interface.
 >
 > I was not sure from the posix definition of struct timeval if it can
 allow
 > other members. This is why the members were set individually.

 Okay.

 > > '''logger.h'''
 > >
 > > - What happens if we pass NULL to `setInterprocessSync`?  (it may
 > >   depend on that, but) I'd clarify this method is exception free,
 > >   and that when non NULL the pointer must be delete-able and the
 > >   ownership is transferred to `Logger` (so the caller doesn't have to
 > >   / shouldn't delete it)
 >
 > A valid sync object always has to be present. I've made NULL do no
 change
 > now.

 Hmm, frankly, I don't like this behavior: if NULL isn't expected I'd
 throw; otherwise I'd use it somewhat useful, like "disabling lock".
 But at this stage for this ticket I won't argue.

 > > - a minor point, but I'd place `setInterprocessSync` in logger.h
 > >   somewhere separated from the log level/severity, etc related
 > >   methods.  the current position seems a bit awkward.
 >
 > I've moved it to the end of the list now. Please see if it's ok.

 Yes, that looks better.

 > > '''log test'''
 > >
 > > - I suspect we don't have the chicken-egg problem here.

 What about this?  I believe we can just auto generate .cc and .h.  But
 again, we should probably prioritize completing this ticket than
 trying to solve all small problems...

 > > - technically, we should test the lock is acquired before the log
 > >   output and released after that.  The Lock test doesn't actually
 > >   confirm it.  But now that we've spent too much time on this ticket,
 if
 > >   it's not easy to achieve, the current test is probably okay as a
 > >   compromise.
 >
 > This will require something similar to the last design. It would
 > need a wrapper around log4cplus so that logging calls are
 > intercepted by a mock object *between* the lock/unlock. It would
 > result in the same sort of ugliness as before.

 I don't necessarily think so; I can imagine having the mock
 lock/unlock produce additional logs, then check the ordering of the
 resulting logged message some way.  This approach shouldn't require a
 change to the base and main (non test) classes.  But that probably
 requires an additional setup like a checker script, and due to the
 excessive time we've spent for this ticket, I should probably live
 with the current test.

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