Make logging better for pycbc_make_offline_workflow

[GarethCabournDavies]

We realised that the pegasus logging was getting a little out of hand in the pycbc_make_offline_workflow code. Here I fix this three ways:

• The log that was overbearing was specifically this one from pegasus, so I have added a line to grab the logger for this module, and set the logger level to be one level above the default pycbc logger (so, e.g., INFO would not be shown as default in this code)
• I also did the same trick for the scitokens warning here.
• I have reduced the level of this log to be logging.debug as this is called every time a new executable is set up, but this happens for every parallel instance of e.g. pycbc_coinc_findtrigs so was overloading the output as well.

After these three changes, the output is much more manageable (I actually noticed config warnings that I hadn't noticed before!).

HOWEVER we might want the info that I have silenced, so I added the call to pycbc.init_logging to pycbc_make_offline_search_workflow, so that the verbosity level can be increased if desired. It is at info by default, and will go to debug if --verbose is given

[GarethCabournDavies]

(The new-style --verbose output actually gives us information we were losing before as the logging level was hardcoded)

[spxiwh]

MInor changes requested, but I think the changes implemented make sense.

[spxiwh]

Does this move change anything?

[GarethCabournDavies]

Don't think it does - looks like the workflow log file is created correctly, and added to the results page as normal

The only difference I see is that we can now configure to use more verbosity by passing the option

[GarethCabournDavies]

Ahh - Ive just seen that there is the second call to the basicConfig to send to the log file

The change to init_logging also makes the default format change to use ISO standard time format including timezone and removes the level

[GarethCabournDavies]

I suppose the question is which format we want, using the logging level, or the updated timezone format (or neither or both)

I don't want to revert to the direct basicConfig call, as then we would be unable to run with logging.DEBUG and would just lose all of the information we are wanting to make quieter

[spxiwh]

As you only access this in one place, it doesn't need to be a global variable, just do this above line 325 (unless I'm missing something??)

[GarethCabournDavies]

moved - I had thought it would be needed elsewhere, but its just the once

[titodalcanton]

This will not do anything actually; if you want the warning to be printed, you need something like

import warnings

warnings.warn('Blah', DeprecationWarning)

[GarethCabournDavies]

There is an example of the workflow log file in https://ldas-jobs.ligo.caltech.edu/~gareth.cabourndavies/testoutput/pegasus_verbosity/output/results/9._workflow/H1L1-WORKFLOW-LOG-1368933107-679711.html

We should note that is not what is printed to the terminal due to two different loggers, but we see that it removes the super-loud stuff

[spxiwh]

@GarethCabournDavies a proposed patch, which I think allows the format to remain, while still updating verbose settings (also minor simplification):

diff --git a/bin/workflows/pycbc_make_offline_search_workflow b/bin/workflows/pycbc_make_offline_search_workflow
index 9b3a7da867..b6895314a8 100755
--- a/bin/workflows/pycbc_make_offline_search_workflow
+++ b/bin/workflows/pycbc_make_offline_search_workflow
@@ -59,15 +59,17 @@ def ifo_combos(ifos):
 
 parser = argparse.ArgumentParser(description=__doc__[1:])
 parser.add_argument('--version', action='version', version=__version__)
-parser.add_argument('--verbose', action='count',
+parser.add_argument('--verbose', action='count', default=0,
     help="Incrementally add more verbosity")
 wf.add_workflow_command_line_group(parser)
 wf.add_workflow_settings_cli(parser)
 args = parser.parse_args()
 
+# Set up logging to the screen
 # By default, we do logging.info, each --verbose adds a level of verbosity
-logging_level = args.verbose + 1 if args.verbose else logging.INFO
-pycbc.init_logging(logging_level)
+logging_level = args.verbose*10 + logging.INFO
+logging.basicConfig(format='%(asctime)s:%(levelname)s : %(message)s',
+                    level=logging_level)
 
 container = wf.Workflow(args, args.workflow_name)
 workflow = wf.Workflow(args, args.workflow_name + '-main')

[GarethCabournDavies]

Latest, with Ian's patch:

Standard output: here

output with --verbose here