BIND 10 #1704: log output mixed

BIND 10 Development do-not-reply at isc.org
Thu May 24 07:57:17 UTC 2012


#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      |
-------------------------------------+-------------------------------------
Changes (by muks):

 * owner:  muks => jinmei


Comment:

 Replying to [comment:50 jinmei]:
 > '''General'''
 >
 > - The new version still needed editorial nits.  I made them directly
 >   to the branch.  Please check.  Maybe we need a common checker script
 >   because some conventions seem to be so difficult to follow for new
 >   developers (but that's not a topic of this branch).

 I've tried to be more careful about it, but I may still make the odd
 mistakes.

 > - (not specific to this version; sorry I forgot to mention this
 >   before) How does it work for multi-thread components?  Right now, some
 >   python daemons use multiple threads.  Although we'll probably get rid
 >   of them according to the previous f2f discussions, but I guess
 >   b10-resolver will eventually be multi-threaded.

 IIRC, trying to acquire a constesting lock from another thread will block,
 but I have to check this. We may have to remove the flag inside
 InterprocessSync this case, if a single logger object is used.

 > - About the design: it now looks much better, but I don't see why we
 >   need the separate class hierarchy for `InterprocessSync`.  If I were
 >   to implement it, I'd simply include all file-related logic in
 >   `InterprocessSyncFile` (which I'd call `InterprocessSyncFileLock`)
 >   and make `InterprocessSyncLocker` a value  (i.e., not a base) class:
 > {{{#!cpp
 > class InterprocessSyncLocker {
 > public:
 >     InterprocessSyncLocker(InterprocessLock& lock) :
 >         locked_(false), lock_(lock) {}
 >     ~InterprocessSyncLocker() {
 >         unlock();
 >     }
 >     void lock() {
 >         if (locked_) {
 >             lock_.lock();
 >             locked_ = true;
 >         }
 >     }
 >     void unlock() {
 >         if (locked_) {
 >             lock_.unlock();
 >             locked_ = false;
 >         }
 >     }
 > private:
 >     bool locked_;
 >     InterprocessLock& lock_;
 > };
 > }}}
 >   This way we can avoid newing the locker, avoid using friend, and
 >   avoid using dynamic_cast.  With this approach
 >   `LoggerImpl::outputRaw()` would look like this:
 > {{{#!cpp
 > void
 > LoggerImpl::outputRaw(const Severity& severity, const string& message) {
 >     InterprocessSyncLocker locker(*sync_);
 >     locker.lock();
 >
 >     LOG4CPLUS_DEBUG(logger_, message);  //, and so on
 >
 >     // Lock will be automatically released.
 > }
 > }}}
 >

 Something similar is now implemented. :)

 > '''logger implementation'''
 >
 > Maybe you're planning it, but we'll still need to test the logger
 > behavior.  As I suggested, I'd use some mock lock class.  Also, in
 > that case, we'll probably not have to set the magic B10_FROM variable
 > for tests.
 >

 This test is written now. Due to this test and the API in general, we now
 lazily open the lock file (when it is actually required). This allows us
 to replace the sync object with a mock object or a NULL object (in the
 case of command line utilites).

 > '''log_messages'''
 >
 > - I don't like to include test specific log message
 >   (LOG_LOCK_TEST_MESSAGE) in the main source.
 >

 It's moved to a separate file now in tests/.

 > '''interprocess_sync_file'''
 >
 > - it's better to make component_name `const string&` (cppcheck will
 >   even fail due to that):
 > {{{#!cpp
 >     /// \brief Constructor
 >     InterprocessSyncFile(const std::string component_name);
 > }}}
 >

 I think you've made this change. :)

 > - lock/unlock/tryLock share almost the same code pattern.  I'd somehow
 >   combine them (note, however, that we might not need tryLock in the
 >   first place; see below)

 This is reduced to a utility function now. It also became a place to put
 the lazy open code. On the topic of tryLock(), see below.

 >
 > - top source dir may not be writable, so we should use somewhere
 >   always writable e.g., top_builddir:
 > {{{#!cpp
 >     const char* const env = getenv("B10_FROM_SOURCE");
 >     if (env != NULL) {
 >         lockfile_path = env;
 >     }
 > }}}
 >

 Done.


 > '''interprocess_sync_file_unittest'''
 >
 > - As far as I can see `InterprocessSyncFileTest` doesn't have to be a
 >   fixture (i.e. no class for it, replace TEST_F with TEST)

 This is changed now.

 > - Overall the code is not exception safe wrt dynamic allocation, e.g.:
 > {{{#!cpp
 >   InterprocessSync* sync = new InterprocessSyncFile("test");
 >   InterprocessSyncLocker* locker = sync->getLocker();
 > }}}
 >   Although in tests it may not a big deal in practice, I'd generally
 >   like to keep any code in our tree as clean as possible.  In these
 >   cases we should be easily able to make it safe with
 >   boost::scoped_ptr.

 Due to the change in design (above) the code doesn't look like this
 anymore.

 > - I'd rather specify the full path than relying on the B10_FROM_ trick
 >   with setting in main() globally:
 > {{{#!cpp
 >   InterprocessSync* sync = new InterprocessSyncFile("test");
 > }}}
 >   Setting this environment variable could affect other tests, and the
 >   full path is in fact closer to what would be used in the actual
 >   deployment.  Note that if we do this we can/should remove setenv
 >   from main().

 I don't follow completely here. The constructor accepts just the component
 name, and builds a path according to the runtime/test environment. It has
 to be able to accept different paths as the install prefix may not be
 writable or even exist. I would not prefer allowing to specify the full
 pathname to the lock file by the caller, as the lockfile locations can be
 managed by us, or may not even
 be an actual file.

 > - TestLock: pipe(2) can fail.  I'd explicitly check the return value
 >   either by assert or ASSERT_NE, or by throwing an exception on
 >   failure.
 > - same for fork(), read(), write() (and technically, close(), although
 >   we can probably say it should be so unlikely that it's not worth
 >   checking in this context)

 It is an unlikely situation (though not impossible). In case they fail, a
 lot of other things will similarly fail and it's best the test crashes and
 burns then. The test is written such that any such failure will cause the
 test to fail.

 I felt similarly about the read() below and was going to group it into
 this list, but a blocked process will stop testing which felt uneasy. So
 I've addressed that one.

 > - Testing tryLock() is suboptimal because in the real logger code we
 >   don't use it.  Since we are now free from the logging context, I'd
 >   suggest using lock() for actually writing something to the file.
 >   Both the parent and child would write something to the file, in that
 >   order ensured by the lock, and we can check what is written.  (Of
 >   course, though, this test could incorrectly pass depending on the
 >   timing).  Note also that if we take this approach, we can probably
 >   just remove tryLock(), at least until we really need it in an
 >   application.

 tryLock() is a utility function written to test lock() and unlock(). It's
 not used otherwise. I think the current code is good as-is, because we are
 only testing lock()/unlock() and the test only passes if tryLock() finds a
 contesting lock. As you've noted, we can't rely on the order of writes
 without actually testing the lock.

 > - read() at the parent could block if there's an unexpected bug in the
 >   child part, and in the worst case the whole test could hang.  I'd
 >   try avoiding that scenario as much as possible.  For example, we can
 >   introduce a timeout for read(); we can also make sure the child
 >   really dies in some way.

 I agree with this reasoning now. I've put in a select() that waits for 5
 seconds and only reads if there's data available (1 byte).

 > - this can be simplified:
 > {{{#!cpp
 >       if (locked == 1) {
 >         was_locked = true;
 >       } else {
 >         was_locked = false;
 >       }
 > ...
 >   EXPECT_TRUE(was_locked);
 > }}}
 >   as:
 > {{{#!cpp
 >       EXPECT_EQ(1, locked);
 > }}}
 >   and we can remove was_locked completely.  Same for
 >   TestMultipleFilesForked with was_not_locked.

 This is also updated accordingly. :)

 Thank you for the review jinmei :) I think the redesigned code looks
 pretty clean compared to what we had before.

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


More information about the bind10-tickets mailing list