1

I recently using python, and the code I've been writing is starting to get large enough that I'm beginning to toggle on and off print statements, so I looked around to see what SO reccommended, and it every time the community votes that one should use logging, instead of print but discussions and documentation on how to configure it to be easy to use are confusing and hard to follow.

However, I'm finding the logger version of writing statments is more time consuming, and harder for a human to parse and just plain gross to look at:

print (‘First value is:‘, val1, ‘Second value is‘, val2)

vs

logger.info(‘value 1 is: %s , value 2 is: %s’, val1, val2)

Other than rolling my own debugging levels with something along the line of:

DEBUGGING = True

def debug (msg):
   if DEBUGGING:
      print (msg)

Is there something I can do to make logging statements simpler to read an write? or another package I should try?

virtualxtc
  • 390
  • 4
  • 21
  • 1
    In Python 3, `print` is a function, not a statement. `print msg` is a syntax error. – Kevin Aug 17 '18 at 01:20
  • Your print statement has a whole bunch of implicit spaces in it that you probably don't want and your log statement uses invalid syntax. – Mad Physicist Aug 17 '18 at 01:35
  • Formatted strings are preferable to printing the way you do anyway. The recommended way to print looks more like the logging rather than the other way around. – Mad Physicist Aug 17 '18 at 01:38
  • If you're looking for a quick hack to just make it work, you could write a wrapper for the print function to make it take an argument- `level`, that controls whether print actually gets called (referencing a global `debuglevel` variable). But as Mad Physicist says- formatted strings are really the way to go. – Dillon Davis Aug 17 '18 at 01:40
  • @DillonDavis Sad, I thought python was 'all about readability', formatted strings are so Java-esque. – virtualxtc Aug 17 '18 at 01:55
  • @virtualxtc. Python strives to be pragmatic above all. Your qualitative aesthetic judgements appear hasty at best, since it doesn't seem like you've taken the time to fully understand the benefits of doing things this way. – Mad Physicist Aug 17 '18 at 05:53
  • @virtualxtc. Since when are format strings more Javaesque than the print statement you wrote? – Mad Physicist Aug 17 '18 at 05:56
  • 1
    @virtualxtc. The advantage of the sort of formatting the logger does is that the arguments don't have to be evaluated if it's not necessary. Everything you pass in is just a cheap reference unless you really need to convert it for the log message. Not so for a pre-formatted string. – Mad Physicist Aug 17 '18 at 05:57
  • @MadPhysicist True, and I'm glad you brought it up as it adds to the discussion and reminded me that for printf style formatting if `s` might contain a `%` you have a problems; I'm working with spreadsheets where % is a pretty common table heading / key value. – virtualxtc Aug 17 '18 at 08:06
  • @virtualxtc you can fix that by escaping the `%`s as `%%`s. – Dillon Davis Aug 17 '18 at 21:55

2 Answers2

2

Two options.

1) stdlib logging is long in the tooth. Try a different library. I like structlog. This is key/value logging:

>>> import structlog
>>> log = structlog.get_logger()
>>> log.info('some event', val1='first value', val2='second value')
2018-08-16 21:01.02 some event                   val1=first value val2=second value

2) You can actually just continue using print calls, if you want. This is actually recommended best practice for the popular Twelve-Factor App methodology, where log events are just lines on stdout. Usually each line is a serialised json object, but that's not the only sensible choice.

A twelve-factor app never concerns itself with routing or storage of its output stream. It should not attempt to write to or manage logfiles. Instead, each running process writes its event stream, unbuffered, to stdout.

The idea here is that there are already powerful and flexible logging solutions available, at the OS level, and we should just leverage those rather than reinvent the wheel. For example, you can just run your app piped into syslog:

./myapp.py | logger -t myapp &
wim
  • 338,267
  • 99
  • 616
  • 750
  • The Twelve-Factor take is interesting, I agree that a fair amount of output should be part of a good script (I love watching my system boot up). However, sometimes you want to avoid the cost of calculating each print statement, especially at trace level debugging where the values may not otherwise be used & right now script efficiency is becoming an issue (large excel files where I'd like to avoid max.row() calcs inside for loops once in production). The only way to deal with this using print is to delete or comment out the line as false `if` statements are still evaluated. – virtualxtc Aug 17 '18 at 02:47
  • will try structlog and report back / accept answer by tomorrow. – virtualxtc Aug 17 '18 at 02:48
  • I really like the format / way I'm "not writing prose" with `structlog`, and it is really the type of thing I was unknowingly looking for. Once I figure out how get it to work with `verboselogs` or add some debugging levels below `debug` (trace) and just below and above `info` (verbose, notice) it will be my go-to. However, for this particular program, it doesn't seem worth it to reformat every print statement. – virtualxtc Aug 18 '18 at 11:27
2

If it's just syntax-sugar you want, something like

def info (logger, *args):
    logger.info("".join(str(item) for item in args))

will let you write it almost like print:

info(my_logger, 'First value is:', val1, 'Second value is', val2)

It would be possible to monkeypatch the logger methods to do this for you, but it's probably not a good idea -- changing the behavior stdlib objects tends to anger the next person who picks up your code. If you want to keep the general appearance of a regular logger but not earn bad karma you could add a simple shim class to do the assembly:

class LogShim (object):

    def __init__(self, logger):
        self.logger = logger

    def log(self, level, *msg):
        if self.logger.isEnabledFor(level):
            concatenated =  " ".join(str(a) for a in msg)
            self.logger.log(level, concatenated)

    def debug(self, *msg):
        self.logger.log(logging.DEBUG, *msg)

    def info(self, *msg):
        self.log(logging.INFO, *msg)

    def warning(self, *msg):
        self.log(logging.WARNING, *msg)

    def error(self, *msg):
        self.log(logging.ERROR, *msg)

    def critical(self, *msg):
        self.log(logging.CRITICAL, *msg)

And then use it like a logger:

my_logger = logging.getLogger()
my_shim = LogShim(my_logger)
my_shim.debug("here", "are", 4, "items")
theodox
  • 12,028
  • 3
  • 23
  • 36
  • You could probably use `logging.setLoggerClass(LogShim)` if you extended the built in `Logger` class instead of wrapping it. – Mad Physicist Aug 17 '18 at 06:03
  • Before asking this question I had written something like the 'syntax-sugar' method you provided, but got confused when Jupyter was executing my logger statements out of order with respect to my print statements. Just tried it in terminal and realized it's an Jupyter problem, not the reformatting. – virtualxtc Aug 17 '18 at 08:12
  • While I really like the effect provided by the shim, wouldn't it have the same preformatting performance cost problem that @MadPhysicist brought up above? – virtualxtc Aug 17 '18 at 08:28
  • -1 this will make the line numbers always come from where the log shim class was defined, instead of from where the log event was created. – wim Aug 17 '18 at 13:17
  • 1
    @virtualxtc if youre worried about the string concat costs, I updated with a trap for that... – theodox Aug 17 '18 at 23:25
  • Tried your shim, but couldn't figure out where my logs were going, finally figured out I should prepend `logging.basicConfig(filename='example.log',level=logging.DEBUG) ` before `my_logger = logging.getLogger()` – virtualxtc Aug 20 '18 at 12:16
  • yeah - I wasn't touching the config, so that makes sense. – theodox Aug 20 '18 at 19:23
  • Also, for your example debug statement `y_shim.debug("here", "are", 4, "items")` I'm getting an error `TypeError: not all arguments converted during string formatting` with some helpful info in the traceback: `self.logger.log(logging.DEBUG, *msg) Message: 'here' Arguments: ('are', 4, 'items')` – virtualxtc Aug 23 '18 at 00:58