Python: logging comments printed to console before other outputs

Question

I have been trying to understand logging in python. I have an init module, two other modules and a main module. For some reason, when I run my module, log details jump the code flow and are printed first before the other outputs

Could someone tell me why this is happening

this is in __init__.py

from dir1.mod1 import FirstClass
from dir1.mod2 import SecondClass

logger = logging.getLogger(__name__)

logger.setLevel(logging.DEBUG)
f_handler=logging.FileHandler('python_logs.log')
f_handler.setLevel(logging.DEBUG)
c_handler = logging.StreamHandler()
c_handler.setLevel(logging.ERROR)

f_formatter = logging.Formatter('%(name)s - %(levelname)s - %(message)s')
c_formatter = logging.Formatter('%(name)s - %(levelname)s - %(message)s')

f_handler.setFormatter(f_formatter)
c_handler.setFormatter(c_formatter)

logger.addHandler(f_handler)
logger.addHandler(c_handler)

This is in other two modules(written inside __init__() of the resp class

self.logger = logging.getLogger(__name__)

snippet of addn() function defined inside one of the module

def addn(self):
    z=self.x +self.y
    print('sum is '+z)
    self.logger.error('incrementing number!')
    self.logger.info('Still incrementing number!!')
    return z

And my main modules(which I run) has this:

from dir1.mod1 import FirstClass
from dir1.mod2 import SecondClass

number = FirstClass(2,2)
print('addition results')
number.addn()

I was expecting a output as below

addition results

sum is 3

dir1.mod1 - ERROR - incrementing number!

But what I got was

dir1.mod1 - ERROR - incrementing number!

dir1.mod1 - ERROR - incrementing number!

addition results:

sum is 3

Why is the log message printed first jumping out of code flow? And also could someone tell me why log message gets printed twice??

Answer 1

Python StreamHandler will log to stderr by default while you print statements goes to stdout. Those are two different pipelines and the ordering isn't guaranteed between them.

To ensure proper ordering start by sending all output to the same pipe. For example you could add the file=sys.stderr argument to your print statements.