12

I spent hours to dig the behavior, first about those questions:

It seems if we use 'O_APPEND' flag when opening file, it will always be ok to logging to same file from multiple processes, on linux. And i believe python surely use 'O_APPEND' flag in its logging module.

And from a small test:

#!/bin/env python
import os
import logging

logger = logging.getLogger('spam_application')
logger.setLevel(logging.DEBUG)
# create file handler which logs even debug messages
fh = logging.FileHandler('spam.log')
logger.addHandler(fh)
formatter = logging.Formatter(
    '%(asctime)s - %(name)s - %(levelname)s - %(message)s')
fh.setFormatter(formatter)

for i in xrange(10000):
    p = os.getpid()
    logger.debug('Log line number %s in %s', i, p)

And i run it with:

./test.py & ./test.py & ./test.py & ./test.py &

I found there were nothing wrong in spam.log. This behavior may support the conclusion above.

But problems comming:

  • What does this mean here?
  • And what are the scenes to use this, just for file rotation?

At last, if two process are doing write on one same file, i mean they are invoking write(2) on the same file, who make sure the data from the two processes not interleave(kernel or filesystem?), and how.[NOTE: i just want to see in deep about the write syscall, any hit about this is welcome.]

EDIT1 :

Do this and this just exist there for compatibility between different os environments, like windows, linux, or mac?

EDIT2 :

One more test, feed 8KB strings to logging.debug each time. And this time i can see the "interleaving" behavior in spam.log. This behavior is just what specified about PIPE_BUF in one page above. So it seems the behavior is clear on linux, using O_APPEND is ok if the size to write(2) is less then PIPE_BUF.

Community
  • 1
  • 1
apporc
  • 870
  • 3
  • 11
  • 23
  • 1
    Some points after experiencing these kind of problems in both Perl and Python: in both cases, if you do multilines logging (for example in a loop) from multiple processes at once into same logfile, you may get lines mixed up together, that is you do not have guarantee that there are left as a block, one block per process following each other. In Perl it was worse as the split was sometimes even inside lines, and I resolved it using `syswrite` instead of `print`, that is going lowlevel and skipping buffers. In short, I think it is best to stay with one logfile per process. HTH. – Patrick Mevzek Jan 12 '18 at 19:58

3 Answers3

6

I digged deeper and deeper. Now I think it's clear about these facts:

  1. With O_APPEND, parallel write(2) from multiple processes is ok. It's just order of lines are undetermined, but lines don't interleave or overwrite each other. And the size of data is by any amount, according to Niall Douglas's answer for Understanding concurrent file writes from multiple processes. I have tested about this "by any amount" on linux and have not found the upper limit, so i guess it's right.

  2. Without O_APPEND, it will be a mess. Here is what POSIX says "This volume of POSIX.1-2008 does not specify behavior of concurrent writes to a file from multiple processes. Applications should use some form of concurrency control."

  3. Now we come into python. The test i did in EDIT3, that 8K, i found it's origin. Python's write() use fwrite(3) in fact， and my python set a BUFF_SIZE here which is 8192. According to an answer from abarnert in Default buffer size for a file on Linux. This 8192 has a long story.

However, more information is welcome.

Community
  • 1
  • 1
apporc
  • 870
  • 3
  • 11
  • 23
2

I would not rely on tests here. Weird things can only happen in race conditions, and exhibiting a race condition by test is almost non sense because the race condition is unlikely to occur. So it can work nicely for 1000 test runs and randomly break later in prod... The page you cite says:

logging to a single file from multiple processes is not supported, because there is no standard way to serialize access to a single file across multiple processes in Python

That does not means that it will break... it could even be safe in a particular implementation on a particular file system. It just means that it can break without any hope of fix on any other version of Python or on any other filesystem.

If you really want to make sure of it, you will have to dive into Python source code (for your version) to control how logging is actually implemented, and control whether is it safe on your file system. And you will always be threatened by the possibility that a later optimization in logging module breaks your assumptions.

IMHO that is the reason for the warning in Logging Cookbook, and the existence of a special module to allow concurrent logging to the same file. This last one does not rely on anything unspecified, but just uses explicit locking.

Serge Ballesta
  • 143,923
  • 11
  • 122
  • 252
  • 2
    Because i can totally control the os my programs will run on, just like one author said in one page i cited, if it's clear that "logging to one same file from multiple processes parallel" is ok on linux, then it's ok for me. Firstly i need to assure this. If the warning from Cookbook is for compability, i get it. – apporc Jul 06 '16 at 09:28
0

I have tried a similar code like this(I have tried in python 3)

import threading
for i in range(0,100000):
     t1 = threading.Thread(target= funtion_to_call_logger, args=(i,))
     t1.start()

This worked completely fine for me, similar issue is addressed here.

This took a lot of Cpu time but not memory.

EDIT:
Fine means all the requested things were logged but Order was missing.Hence Race condition still not fixed ,

yunus
  • 2,445
  • 1
  • 14
  • 12
  • Time passed. What i concerned first in this question is not "writing to one file from parallel threads", but "parallel processes", and this is a huge difference. There is no synchronization mechanism between those processes, no any form of lock. In the case of your test, python's builtin lock mechanism in logging module can affect the result, as is what discussed in the link you cited. – apporc Mar 05 '20 at 14:11