[In progress] Use python logging framework consistently

[hamiltont]

This is basically a forward-looking commit. Currently some modules use logging, some dont, some use
print, etc. This just standardizes us on python's logging and provides enough logging code to allow
people to have an idea of what is expected from their additions

Replaces --verbose flag with --log flag

I'd propose some minimal guidelines for logging:

• Use info to report standard, expected system operation e.g. method entry
• Don't use info on methods you expect to be called more than 10 times (e.g. get_foo())
• avoid re-writing code just to add logs e.g. don't add else statements just to log

Obviously these are just some general thoughts, feedback welcome

[methane]

https://docs.python.org/2.7/library/logging.html#logging.Logger.exception

log.exception("Error loading %s", config_file_name)

[methane]

Uh, I've missed following raise.
Traceback will show after.
log.error("Error loading '%s'", config_file_name) is enough.

[hamiltont]

This now adds real-time console output from __run_test and any setup.py files, and stores info on uncaught exceptions into log files.

It needs some more testing before I'm sure work is done here, just wanted to share.

I may update again to add automatic per-framework generation of installation log files (idea from @stefanocasazza ), in addition to the current console output

[msmith-techempower]

How will the affect test output? Currently, we are just using a file and writing/flushing. If you look at the setup.py file for most tests, all their calls will pipe stdout and stderr to the appropriate log file, but I am not sure you can simply pass the python 'log' object around like that.

[hamiltont]

Mike,

As far as setup.py, this change is invisible. Start still gets stdout and
stderr handlers, and can either write them directly or pass them to other
stuff. As far as logs, this is invisible (sans that each message now has a
prefix indicating time, module, etc). As far as running tests, this now
prints everything that's going into the log file for the current test to
the console. Its a lot like the tee program
On Jul 15, 2014 10:19 AM, "Mike Smith" notifications@github.com wrote:

How will the affect test output? Currently, we are just using a file and
writing/flushing. If you look at the setup.py file for most tests, all
their calls will pipe stdout and stderr to the appropriate log file, but I
am not sure you can simply pass the python 'log' object around like that.

—
Reply to this email directly or view it on GitHub
#920 (comment)
.

[hamiltont]

Here's a big chunk of output so it's more clear what the new changes add. In general, moving us to the logging framework means 1) no more "add then remove print statements" when debugging, and 2) ability to use filters/log levels/etc to have very selective logging. For example, you could turn on DEBUG just for one method or just for one file, you could send logs to a file with a few lines of code, etc

PS - this is not merge-ready at the moment, I need to refine/test these changes

From Console, Running Default --log
Looks exactly the same

=====================================================
  Running Tests ...
=====================================================

-----------------------------------------------------
  Running Test: go ...
-----------------------------------------------------

From Console, Running --log DEBUG

=====================================================
  Running Tests ...
=====================================================

benchmarker : INFO     __run_tests
benchmarker : DEBUG    __run_tests with __name__ = benchmark.benchmarker
benchmarker : INFO     Executing __run_tests on Linux

-----------------------------------------------------
  Running Test: go ...
-----------------------------------------------------

benchmarker : INFO     __run_test
benchmarker : DEBUG    test.os.lower() = linux  test.database_os.lower() = linux
benchmarker : DEBUG    self.results['frameworks'] != None: True
benchmarker : DEBUG    test.name: go
benchmarker : DEBUG    self.results['completed']: {}
benchmarker : INFO
=====================================================
  Beginning go
-----------------------------------------------------

benchmarker : INFO
-----------------------------------------------------
  Starting go
-----------------------------------------------------

benchmarker : DEBUG    Restarting database
Welcome to Ubuntu 12.04.4 LTS (GNU/Linux 3.11.0-24-generic x86_64)

 * Documentation:  https://help.ubuntu.com/
mysql start/running, process 7135
mongodb start/running, process 7210
 * Restarting PostgreSQL 9.1 database server
   ...done.
framework_test: INFO     start
benchmarker : DEBUG    Sleeping for 60
benchmarker : INFO
-----------------------------------------------------
  VERIFYING JSON (/json)
-----------------------------------------------------

From ec2/latest/logs/go, Regardless of --log setting
I always write all output to the log. My Formatter may be a bit verbose here, we may not want the huge timestamp at the front. It's easy to change this stuff if someone wants a different format.

2014-07-15 12:36:32,495: benchmarker : DEBUG    test.os.lower() = linux  test.database_os.lower() = linux
2014-07-15 12:36:32,496: benchmarker : DEBUG    self.results['frameworks'] != None: True
2014-07-15 12:36:32,496: benchmarker : DEBUG    test.name: go
2014-07-15 12:36:32,496: benchmarker : DEBUG    self.results['completed']: {}
2014-07-15 12:36:32,496: benchmarker : INFO
=====================================================
  Beginning go
-----------------------------------------------------

2014-07-15 12:36:32,496: benchmarker : INFO
-----------------------------------------------------
  Starting go
-----------------------------------------------------

2014-07-15 12:36:32,498: benchmarker : DEBUG    Restarting database
2014-07-15 12:36:50,122: benchmarker : DEBUG    Sleeping for 60
2014-07-15 12:37:50,183: benchmarker : INFO
-----------------------------------------------------
  VERIFYING JSON (/json)
-----------------------------------------------------

[msmith-techempower]

The output from the verification step (json, in your example) is included still, correct? We are showing the response from the /json test still?

[hamiltont]

Yes, and not only in the logs but also on the console while the tests are running.

I've just truncated this so I don't paste huge log files.

[bhauer]

This is hot! Thanks again for another excellent contribution @hamiltont.

[hamiltont]

Ok, this is back to "good to merge" status (after your own tests, of course). See here for example output from a number of sources.

A few minor changes happened:

• validation failures cause the raw validation data to be printed to the output file
• we have a new utils.py file for...usefulties

Output from a normal run (e.g. no --log parameter) is very clean and can easily be bumped up. The log file for the test is very verbose.

[hamiltont]

This needs to be rebased on master and tested a bit more before it can be merged. Also, I should probably make sure my other logging improvement attempt branch and this work are in agreement.

Leaving open to remind me to circle around to this when I have time...

[msmith-techempower]

Ugh, this is over a year old and DEFINITELY needs to be rebased off master.

@ssmith-techempower See what you can do on a new branch with these changes... probably a lot of merge conflicts. Maybe it makes more sense to open a new PR with the ideas set forth here (using logging rather than file handles); though, if you do please close this in favor of your new one.

[msmith-techempower]

Okay, I'm closing this pull request. We are still using simple file handles for writing out/err logging, but this pull request is dead.