Python logging with multiple modules
Question: I have got various modules in which I use Python logging heavily. When I
import them into the main module like in the Python documentation and try to
run it, I don't get any output from the logging. Has anyone got any idea what
is happening?

Logging is called in the module imported by the `public` module imported below
(the piece of code is too large to be put up here). The piece of code below is
where the whole program is run and the logging is initialized:

    
    
    import logging
    from bottle import run, debug
    import public
    
    logging.basicConfig(level=logging.DEBUG)
    
    if __name__ == '__main__':
       logging.info('Started')
       debug(mode=True)
       run(host='localhost', port = 8080, reloader=True)
       logging.info('Finished')
    


Answer: Your problem is probably being caused by the `import public` statement making
a call to `logging.debug(...)` or similar. What then happens is this:

  1. You `import public`. As a side-effect, this calls e.g. `logging.debug` or similar, which automatically calls `basicConfig`, which adds a `StreamHandler` to the root logger, but doesn't change the level.
  2. You then call `basicConfig`, but as the root logger already has a handler, it does nothing (as documented).
  3. Since the default logging level is `WARNING`, your `info` and `debug` calls produce no output.

You really should avoid side-effects on import: for example, your call to
`basicConfig` should be in the `if __name__ == '__main__'` clause. With this
`public.py`:

    
    
    import logging
    
    def main():
        logging.debug('Hello from public')
    

and this `main.py`:

    
    
    import logging
    from bottle import run, debug
    import public
    
    def main():
        logging.basicConfig(level=logging.DEBUG)
        logging.info('Started')
        debug(mode=True)
        public.main()
        run(host='localhost', port = 8080, reloader=True)
        logging.info('Finished')
    
    if __name__ == '__main__':
        main()
    

You get the following output:

    
    
    $ python main.py
    INFO:root:Started
    DEBUG:root:Hello from public
    INFO:root:Started
    DEBUG:root:Hello from public
    Bottle server starting up (using WSGIRefServer())...
    Listening on http://localhost:8080/
    Hit Ctrl-C to quit.
    
    ^CINFO:root:Finished
    $ Shutdown...
    INFO:root:Finished
    

You'll see from this that Bottle actually re-runs the script in a separate
process, which accounts for the doubling up of messages. You can illustrate
this by using a format string which shows the process ID: if you use

    
    
    logging.basicConfig(level=logging.DEBUG,
                        format='%(process)s %(levelname)s %(message)s')
    

then you get output like

    
    
    $ python main.py
    13839 INFO Started
    13839 DEBUG Hello from public
    13840 INFO Started
    13840 DEBUG Hello from public
    Bottle server starting up (using WSGIRefServer())...
    Listening on http://localhost:8080/
    Hit Ctrl-C to quit.
    
    ^C13839 INFO Finished
    $ Shutdown...
    13840 INFO Finished
    

Note that if you add a side-effect producing statement to `public.py` like
this:

    
    
    logging.debug('Side-effect from public')
    

at the module level, then you get no logging output at all:

    
    
    $ python main.py
    Bottle server starting up (using WSGIRefServer())...
    Listening on http://localhost:8080/
    Hit Ctrl-C to quit.
    
    ^C$ Shutdown...
    

which appears to confirm the above analysis.

