[Checkins] SVN: zc.zk/trunk/src/zc/zk/ The ZooKeeper C library is excessively chatty about something that

[Jim Fulton]

Log message for revision 123977:
  The ZooKeeper C library is excessively chatty about something that
  people don't know how to care about it:
  
  https://issues.apache.org/jira/browse/ZOOKEEPER-642
  
  Until this is fixed, the log level for these messages is converted
  to DEBUG.
  

Changed:
  U   zc.zk/trunk/src/zc/zk/README.txt
  U   zc.zk/trunk/src/zc/zk/__init__.py
  U   zc.zk/trunk/src/zc/zk/tests.py

-=-
Modified: zc.zk/trunk/src/zc/zk/README.txt
===================================================================
--- zc.zk/trunk/src/zc/zk/README.txt	2012-01-06 22:41:52 UTC (rev 123976)
+++ zc.zk/trunk/src/zc/zk/README.txt	2012-01-06 22:44:00 UTC (rev 123977)
@@ -989,15 +989,21 @@
 Change History
 ==============
 
-0.5.1 (2012-01-06)
+0.5.2 (2012-01-06)
 ------------------
 
-- Fixed bug:
+- ZooKeeper node data and child watchers are called on session
+  expiry.  This was unexpected.  The data and child handler
+  functions now handle these events more gracefully.
 
-  - ZooKeeper node data and child watchers are called on session
-    expiry.  This was unexpected.  The data and child handler
-    functions now handle these events more gracefully.
+- The ZooKeeper C library is excessively chatty about something that
+  people don't know how to care about it:
 
+    https://issues.apache.org/jira/browse/ZOOKEEPER-642
+
+  Until this is fixed, the log level for these messages is converted
+  to DEBUG.
+
 0.5.1 (2012-01-04)
 ------------------
 

Modified: zc.zk/trunk/src/zc/zk/__init__.py
===================================================================
--- zc.zk/trunk/src/zc/zk/__init__.py	2012-01-06 22:41:52 UTC (rev 123976)
+++ zc.zk/trunk/src/zc/zk/__init__.py	2012-01-06 22:44:00 UTC (rev 123977)
@@ -46,6 +46,10 @@
             if '@' in line:
                 level, message = line.split('@', 1)
                 level = levels.get(level.split(':')[-1])
+
+                if 'Exceeded deadline by' in line and level == logging.WARNING:
+                    level = logging.DEBUG
+
             else:
                 level = None
 

Modified: zc.zk/trunk/src/zc/zk/tests.py
===================================================================
--- zc.zk/trunk/src/zc/zk/tests.py	2012-01-06 22:41:52 UTC (rev 123976)
+++ zc.zk/trunk/src/zc/zk/tests.py	2012-01-06 22:44:00 UTC (rev 123977)
@@ -36,20 +36,39 @@
 class LoggingTests(unittest.TestCase):
 
     def test_logging(self):
-        logger = logging.getLogger('ZooKeeper')
-        f = StringIO.StringIO()
-        h = logging.StreamHandler(f)
-        logger.addHandler(h)
-        logger.setLevel(logging.DEBUG)
+        handler = zope.testing.loggingsupport.InstalledHandler(
+            'ZooKeeper')
         try:
             handle = zookeeper.init('zookeeper.example.com:2181')
             zookeeper.close(handle)
         except:
             pass
-        zc.zk.testing.wait_until(lambda : 'environment' in f.getvalue())
-        logger.setLevel(logging.NOTSET)
-        logger.removeHandler(h)
 
+        zc.zk.testing.wait_until(
+            lambda : [r for r in handler.records
+                      if 'environment' in r.getMessage()]
+            )
+        handler.clear()
+
+        # Test that the filter for the "Exceeded deadline by" noise works.
+        # cheat and bypass zk by writing to the pipe directly.
+        os.write(zc.zk._logging_pipe[1],
+                 '2012-01-06 16:45:44,572:43673(0x1004f6000):ZOO_WARN@'
+                 'zookeeper_interest at 1461: Exceeded deadline by 27747ms\n')
+        zc.zk.testing.wait_until(
+            lambda : [r for r in handler.records
+                      if ('Exceeded deadline by' in r.getMessage()
+                          and r.levelno == logging.DEBUG)
+                      ]
+            )
+
+        self.assert_(not [r for r in handler.records
+                          if ('Exceeded deadline by' in r.getMessage()
+                              and r.levelno == logging.WARNING)
+                          ])
+
+        handler.uninstall()
+
 def side_effect(mock):
     return lambda func: setattr(mock, 'side_effect', func)