Reduce verbosity of zookeeper logging

[billonahill]

ZK logging is notoriously verbose so turning that down. The submit output is soooo much more bearable now...

[billonahill]

I'm inclined to set all of org.apache to INFO actually, but org.apache.zookeeper to WARN. There are other libraries that log a lot more than we need when in verbose mode. For example org.apache.curator does a lot of this:

15:23:17 [2016-11-09 23:23:17 +0000] org.apache.curator.utils.DefaultTracerDriver FINEST:  Trace: GetDataBuilderImpl-Background - 1 ms  
15:23:17 [2016-11-09 23:23:17 +0000] org.apache.curator.utils.DefaultTracerDriver FINEST:  Trace: DeleteBuilderImpl-Foreground - 2 ms  

And there's also httpUrlConnection which is really noisy:

15:23:17 [2016-11-09 23:23:17 +0000] sun.net.www.protocol.http.HttpURLConnection FINEST:  ProxySelector Request for http://smf1-euu-07-sr1.prod.twitter.com:31179/deactivate?topologyid=20161109230939_IntegrationTest_BasicTopologyOneTaskScaleUpAndDown_277d8b5d-d053-4741-9986-114cab9d5a3daa69677c-2071-4334-9218-1f23fabef221  
15:23:17 [2016-11-09 23:23:17 +0000] sun.net.www.protocol.http.HttpURLConnection FINEST:  Proxy used: DIRECT  
15:23:17 [2016-11-09 23:23:17 +0000] sun.net.www.protocol.http.HttpURLConnection FINE:  sun.net.www.MessageHeader@402bba4f5 pairs: {GET /deactivate?topologyid=20161109230939_IntegrationTest_BasicTopologyOneTaskScaleUpAndDown_277d8b5d-d053-4741-9986-114cab9d5a3daa69677c-2071-4334-9218-1f23fabef221 HTTP/1.1: null}{User-Agent: Java/1.8.0_102}{Host: xxx.yyy.twitter.com:31179}{Accept: text/html, image/gif, image/jpeg, *; q=.2, */*; q=.2}{Connection: keep-alive}  
15:23:17 [2016-11-09 23:23:17 +0000] sun.net.www.protocol.http.HttpURLConnection FINEST:  KeepAlive stream used: http://xxx.yyy.twitter.com:31179/deactivate?topologyid=20161109230939_IntegrationTest_BasicTopologyOneTaskScaleUpAndDown_277d8b5d-d053-4741-9986-114cab9d5a3daa69677c-2071-4334-9218-1f23fabef221  
15:23:17 [2016-11-09 23:23:17 +0000] sun.net.www.protocol.http.HttpURLConnection FINE:  sun.net.www.MessageHeader@795cd85e4 pairs: {null: HTTP/1.1 200}{Date: Wed, 09 Nov 2016 23:23:17 GMT}{Content-Length: 33}{Content-Type: text/html; charset=ISO-8859-1}  

Alternatively we could just set com.twitter to ALL when verbose is set.

Comments welcome.

[objmagic]

I'm OK with logging everything when in verbose, but we should specify what should not be omitted when logger is not in verbose mode. For ZK, I'd like to see some important information gets printed. For example, the ZK hostport that gets connected to.

+1 for not logging HttpURLConnection when not in verbose mode.

P.S.: I was fixing Python logging months ago and realized that carefully assigning proper logging level to every log is not an easy job. And that If you think some levels are fine, not everyone will agree... ("Why I have to add --verbose to get blah blah printed out!?")

[billonahill]

My main motivation is to reduce the verbosity of the zookeeper logs - when in verbose mode or not - since zookeeper is so log intensive with basic info that I is never used. Setting ZK to WARN is not uncommon. Having INFO appear, even in verbose mode, makes reading the logs harder IMO, especially when reading CI logs.

For example, these log lines get generated repeatedly:

11:02:36 [2016-11-09 19:02:30 +0000] org.apache.zookeeper.ZooKeeper INFO:  Client environment:zookeeper.version=xxxx, built on 02/20/2014 09:09 GMT  
11:02:36 [2016-11-09 19:02:30 +0000] org.apache.zookeeper.ZooKeeper INFO:  Client environment:host.name=xxxx  
11:02:36 [2016-11-09 19:02:30 +0000] org.apache.zookeeper.ZooKeeper INFO:  Client environment:java.version=xxxxx  
11:02:36 [2016-11-09 19:02:30 +0000] org.apache.zookeeper.ZooKeeper INFO:  Client environment:java.vendor=Twitter  
11:02:36 [2016-11-09 19:02:30 +0000] org.apache.zookeeper.ZooKeeper INFO:  Client environment:java.home=/usr/lib/jvm/java-xxxx/jre  
11:02:36 [2016-11-09 19:02:30 +0000] org.apache.zookeeper.ZooKeeper INFO:  Client environment:java.class.path=/var/lib/jenkins/.heron/lib/scheduler/heron-aurora-scheduler.jar:/var/lib/jenkins/.heron/lib/scheduler/heron-local-scheduler.jar:/var/lib/jenkins/.heron/lib/scheduler/heron-scheduler.jar:/var/lib/jenkins/.heron/lib/statemgr/heron-zookeeper-statemgr.jar:/var/lib/jenkins/.heron/lib/statemgr/heron-localfs-statemgr.jar:/var/lib/jenkins/.heron/lib/packing/heron-roundrobin-packing.jar:/var/lib/jenkins/.heron/lib/packing/heron-binpacking-packing.jar  
11:02:36 [2016-11-09 19:02:30 +0000] org.apache.zookeeper.ZooKeeper INFO:  Client environment:java.library.path=/usr/java/packages/lib/xxx:/usr/xxxx:/xxxx:/lib:/usr/lib  
11:02:36 [2016-11-09 19:02:30 +0000] org.apache.zookeeper.ZooKeeper INFO:  Client environment:java.io.tmpdir=/tmp  
11:02:36 [2016-11-09 19:02:30 +0000] org.apache.zookeeper.ZooKeeper INFO:  Client environment:java.compiler=<NA>  
11:02:36 [2016-11-09 19:02:30 +0000] org.apache.zookeeper.ZooKeeper INFO:  Client environment:os.name=Linux  
11:02:36 [2016-11-09 19:02:30 +0000] org.apache.zookeeper.ZooKeeper INFO:  Client environment:os.arch=xxxx  
11:02:36 [2016-11-09 19:02:30 +0000] org.apache.zookeeper.ZooKeeper INFO:  Client environment:os.version=xxxx 
11:02:36 [2016-11-09 19:02:30 +0000] org.apache.zookeeper.ZooKeeper INFO:  Client environment:user.name=jenkins  
11:02:36 [2016-11-09 19:02:30 +0000] org.apache.zookeeper.ZooKeeper INFO:  Client environment:user.home=/var/lib/jenkins  
11:02:36 [2016-11-09 19:02:30 +0000] org.apache.zookeeper.ZooKeeper INFO:  Client environment:user.dir=/data/jenkins/workspace/heron-mirror-release_1  
11:02:36 [2016-11-09 19:02:30 +0000] org.apache.zookeeper.ZooKeeper INFO:  Initiating client connection, connectString=xxxx:2181 sessionTimeout=30000 watcher=org.apache.curator.ConnectionState@50d0686  
11:02:36 [2016-11-09 19:02:30 +0000] org.apache.zookeeper.ClientCnxn FINE:  zookeeper.disableAutoWatchReset is false  
11:02:36 [2016-11-09 19:02:30 +0000] org.apache.zookeeper.ClientCnxn INFO:  Opening socket connection to server xxxxxxxxx:2181. Will not attempt to authenticate using SASL (unknown error)  
11:02:36 [2016-11-09 19:02:30 +0000] org.apache.zookeeper.ClientCnxn INFO:  Socket connection established to xxxxxxxxx:2181, initiating session  
11:02:36 [2016-11-09 19:02:30 +0000] org.apache.zookeeper.ClientCnxn FINE:  Session establishment request sent on xxxxxxxxx:2181  
11:02:36 [2016-11-09 19:02:30 +0000] org.apache.zookeeper.ClientCnxnSocket FINEST:  readConnectResult 36 0x[0,0,0,0,0,0,75,30,f,58,0,c,ffffffaf,5e,ffffff87,ffffff82,0,0,0,10,ffffff8a,ffffffe5,ffffffeb,ffffffa6,fffffffd,4f,ffffff82,ffffffdb,a,44,fffffff3,6e,fffffffb,67,34,ffffffe9,]  
11:02:36 [2016-11-09 19:02:30 +0000] org.apache.zookeeper.ClientCnxnSocket WARNING:  Connected to an old server; r-o mode will be unavailable  
11:02:36 [2016-11-09 19:02:30 +0000] org.apache.zookeeper.ClientCnxn INFO:  Session establishment complete on server xxxxxxxxx:2181, sessionid = 0xf58000caf5e8782, negotiated timeout = 30000  

@objmagic do you have examples of the ZK log lines that you'd like to still see? Also note that we access ZK through Curator which also logs heavily so we will still have plenty of output for each ZK interaction.

[objmagic]

ok make sense. 👍 for setting ZK to warning.

[objmagic]

• I'm inclined to set all of org.apache to INFO actually, but org.apache.zookeeper to WARN

Understood now. Agree 👍

• you should also remove --verbose flags in integration test in this PR so that those logs you don't want to see will actually be gone

integration-test//src/python/local_test_runner/main.py:75:  splitcmd = [tracker_path, '--verbose', '--port=%s' % tracker_port]
integration-test//src/python/local_test_runner/test_kill_tmaster.py:30:  splitcmd = [heron_cli_path, 'restart', '--verbose', test_cluster, topology_name, str(shard_num)]
integration-test//src/python/local_test_runner/test_scale_up.py:50:      heron_cli_path, 'update', '--verbose', test_cluster, topology_name,
integration-test//src/python/local_test_runner/test_template.py:301:      heron_cli_path, 'submit', '--verbose', '--', test_cluster, test_jar_path,
integration-test//src/python/local_test_runner/test_template.py:311:  splitcmd = [heron_cli_path, 'kill', '--verbose', test_cluster, topology_name]
integration-test//src/python/test_runner/main.py:277:  cmd = "%s update --config-path=%s %s %s %s --verbose" %\

[billonahill]

@objmagic I removed --verbose for the kill commands (I see I missed one, will update) but for the others for now I think we need to keep it. Because we use the log-and-return-false-upon-failure anti-pattern so extensively, I've seen issues where logging is FINE and we don't see what caused the issue. For example see this recent fix https://github.com/twitter/heron/pull/1543/files#diff-b40887a82a97dd9c6613d65e2b25f4cf.

Once we've fully abandoned that pattern in favor of throwing meaningful exceptions, then I think we can remove more --verbose flags with more confidence.

[billonahill]

Removed verbosity on kill as well as noisy pex logging that was necessary when we first introduced the pex build and needed to troubleshoot frequently, which is no longer the case. We can uncomment if we need move debug info. This is what we won't see lots of anymore:

10:45:50 pex options: {'use_wheel': False, 'inherit_path': False, 'script': None, 'python': '/usr/bin/python2.7', 'repos': [<pex.fetcher.Fetcher object at 0x7f9d35195790>, <pex.fetcher.Fetcher object at
 0x7f9d35195950>], 'pex_name': None, 'pypi': False, 'requirement_files': [], 'platform': 'linux-x86_64',
 'cache_dir': None, 'entry_point': 'heron.shell.src.python.main', 'verbosity': 0, 'pex_root': None, 'zip_safe': True, 'interpreter_cache_dir': '{pex_root}/interpreters', 'ignore_errors': False, 'cache_ttl': 
None, 'python_shebang': None, 'always_write_cache': False, 'disable_cache': True, 'find_links': 'http://science-binaries.local.twitter.com/home/third_party/python/dist/'}
10:45:50 pex requirements: ['requests==2.11.1', 'tornado==4.0.2']

[objmagic]

Yes those logs should be removed.