python多进程/线程抢占stdoutput总是在固定位置截断上个输出？

Question

自己写的爬虫包里面有个简单的日志输出函数logging，没做任何线程安全方面的处理，其核心如下：

log = "%s %s\t%s-%s\t%s  |  %s" % (time.strftime("%Y-%m-%d %X"), logtypeName, pname, tname, workName, log)
print log.decode("utf-8")

显然，正常输出一般为下面形式：

2017-01-12 09:51:01 INFO        PoolWorker2-MT download 1 subject

碰到的问题就是，不论我用multithreading、multiprocessing包进行多线程/多进程的并发操作，当线程/进程密集度稍大，就经常出现如下输出：

22017-01-12 09:51:05 INFO       PoolWorker5-MT download 1 subject 
017-01-12 10:05:59       INFO PoolWorker-3-MT download 1 subject（被截断的行）
……
22017-01-12 09:51:06 INFO       PoolWorker5-MT download 1 subject 
……
22017-01-12 09:51:13 INFO       PoolWorker2-MT download 1 subject 
（这个输出是简单编辑过的，删除了中间一些无冲突的行，实际不大会连续多个这样冲突）

也就是下面一行在上一行要输出2017...时，基本都是在它刚输出第一个2时就插队了，而不是在上一行的随机位置插队。
我很纳闷为什么“抢占输出的冲突点”不是随机的，而高频（不是总是）发生在特定位置呢？

Answer 1

多线程/进程运行输出日志乱序很正常，毕竟A线程输出日志的时候，B线程可能也在输出。这就会造成乱序了。解决方法可以在日志函数上加个锁。保证日志输出的正确性。不要纠结为什么高频发生特定位置，你也说了毕竟不是总是。什么时候截断完全是线程自己运行的结果。