Switch to logging

[lakesare]

Fixes #619

To whomever will be reviewing this PR (Joe?) - please go through it line by line, these are the kind of changes where we need some fresh eyes.

---

What this PR will do

The default logging level (user doesn't set anything):

Users sets logging.getLogger('netpyne').setLevel(logging.DEBUG):

Users sets logging.getLogger('netpyne').setLevel(logging.WARNING):

Changes

• All standard print() statements are changed to logger.info().
• Netpyne used to have print("Warning: hi"), print("WARNING: hi") and print("NOTE: hi"). All of these are logger.warning("hi") (without the "Warning/Note/etc." text) now.
• All if sim.cfg.verbose: print() are changed to logger.debug(). The cfg.verbose option is removed.
• All if sim.cfg.timing: print() are changed to logger.timing().
• Removed double parentheses in print(()) [must have appeared when netpyne was moving from python2 to python3].
• Removed all from __future__ import print_function, we don't need these as we don't use print statements anymore.

Notes

• Netpyne used to have a lot of print("Error: ..."). All of these are logger.warning("Error: ...") now - I didn't want to change the way netpyne handles errors.
  You can ctrl+f logger.warnings, and change some of those to logger.exception so that the stack trace is logged (or you could throw an actual error!).
• Every logger.info(' ...') can be changed to logger.infoS('...') (where S stands for 2 spaces). Search for offset = ' ' * 4 for previous attempts at space standardisation.
• Search for sim.rank == 0 and sim.rank==0
  1. Notice we have a lot of if sim.rank == 0: logger.timing(' Done; cell stims creation time = %0.2f s.' % sim.timingData['stimsTime']). Would it make sense to check whether the rank is 0 in def timing()?
  2. What's the meaning of sim.rank == 0? Does it maybe check whether we run a number of simulations concurrently? Would it make sense to simply set logging.getLogger('netpyne').setLevel(logging.WARNING) if we run a lot of simulations at a time, and remove all if sim.rank==0: logger.info('Adding stims...') conditionals?
• Tests still use the print statement - we could use the logger in tests too (say change if self.verboseFlag: print(" *** Finish loading tests *** ") to logger.info(" *** Finish loading tests *** ")).
• Newlines don't look good with the new logger, see the Running simulation for 500.0 ms... example:

We can either change all logger.info('\nHi') to logger.info(''); logger.info('Hi'), or remove the newlines completely. It looks good to me without the newlines, but you should know better - will the debugging be any harder without the newlines?

[lakesare]

@salvadord / @joewgraham, from the PR description:

All if sim.cfg.timing: print() are changed to logger.timing().

This change made the code like logger.timing('\nTotal time = %0.2f s' % sim.timingData['totalTime']) fail when we have sim.cfg.timing set to False.

We can either always track time (this is what this commit does, though we'd have to remove hasattr(sim.cfg, 'timing') too and do a couple of other things - I stopped in the middle here to ask for your opinion), or I can revert all timing statements to if sim.cfg.timing: ...log stuff....

However - have we considered using a higher order function, say in this fashion https://stackoverflow.com/a/15136422/3192470?
Then we'd have it all in a single place:

import time

def timeit(f, message):
    def timed(*args, **kw):
        if sim.cfg.timing and sim.rank == 0:
          ts = time.time()
          result = f(*args, **kw)
          te = time.time()

          logger.info(message % (te-ts))
          return result
    return timed

@timeit(message="  Done; cells modification time =")
def modifyCells(self, params, updateMasterAllCells=False):
  ...

(Instead of https://github.com/Neurosim-lab/netpyne/blob/development/netpyne/network/modify.py)

[joewgraham]

It's looking impressive, but I think we should discuss details at the dev meeting tomorrow. I've added notes to the agenda.

[lakesare]

Hi @joewgraham!
My time with GSOC ended, but I'd still like to finish this up.
I think the easiest path for us is to disable logger.timing()s for now (converting them to vanilla logger.info()) and to rereview the PR with fresh eyes (I can do this now that it's been 2 months).
Does this sound good?

[joewgraham]

Hey @lakesare , that's awesome you'd like to wrap this up! Yeah, let's not worry about the timing right now and just get the basic functionality working. Whenever you're ready, I'm glad to give it a thorough review.

[lakesare]

@joewgraham, I reviewed it myself & fixed the remaining issues, it looks good to merge 👍
The tests run fine locally, but please approve the github workflow run (github won't let me do it cause I'm a first-time contributor).

[vvbragin]

consider also an ability to use only the root MPI node for some of logs