Python 多進程與 logging

這篇是新系列的第一篇文張，這系列是想分享上班中遇到有趣好玩的事情；那我開這個部落格是以分享開發心得和筆記為目的的，所以不會分享今天午餐很難吃或是又被同事坑了之類的閒話家常。而這篇文章是想分享我這周 debug 的思路和用到的工具或指令等等。

一個沒什麼影響業務的 BUG

這事情要先從 logging 說起，該套件是 Python 用於記錄日誌的標準函式庫，他有多種的 handler 讓開發者決定要如何處理他們的日誌，例如直接打印在 terminal、每隔一天做一個備份或是達到多少容量就做一個備份等等，而今天遇到 BUG 的是採用 RotatingFileHandler 也就是剛剛提到達到多少容量就做備分的方式。

這天巡檢的同事在查閱 log 確認先前發現的告警是否有重大影響時，他截了一張圖到群組讓大家確認，每個人看了一眼 log 內容覺得沒有什麼異常也就回頭繼續處理手邊的事；不過就在這時，大概是做主管的眼光比較敏銳吧，他就發現了點不一樣的問題: "為什麼備份的日誌也包含了今日最新的日誌呢?" 更近一步調查日誌大小也發現 "備份檔案大小遠不到設定的上限"。既然發現問題了就需要有人來處理，而不知道算是幸運還是衰的我剛好完成手邊工作，因此這問題就變成由我來接手了；說幸運是因為它讓我有寫這篇文章的素材，說衰是感覺我就像個接盤俠。

在主管把問題交給我的時候也順帶跟我說可能是多進程的問題；確實是有道理但是在我印象中，這個程式雖然會將註冊的功能用子進程運行，但也只在啟動的時候會做這動作，且每個子進程都會將日誌內容分開寫在不同名稱的日誌，另外，他是個守護進程(daemon)，所以基本上也不會同時多開才對；官方文件確實有說多進程打印 log 要使用其他 Handler，但沒有多進程的話不就沒這種問題才對嗎?

開始抓蟲

不論如何，我覺得還是需要重現一下情境才能確認問題所在，因此我先在自己的電腦寫了一小段腳本用於驗證是否為多進程，同時也想驗證看看比較常用到的多協程會不會有這問題。

python

import asyncio
import logging
import multiprocessing
import os
import time
from logging.handlers import RotatingFileHandler


def config_logger():
    logger = logging.getLogger('beep')
    logger.setLevel(logging.INFO)
    handler = RotatingFileHandler('beep.log',
                                  maxBytes=100 * 1024,
                                  backupCount=2,
                                  delay=True)
    handler.setFormatter(logging.Formatter('%(asctime)s %(levelname)s %(message)s'))
    logger.addHandler(handler)
    return logger


def log_forever():
    logger = config_logger()
    while True:
        logger.info(f'Beep from {os.getpid()}')
        time.sleep(0.01)


def do_multiprocess_log():
    process = [multiprocessing.Process(target=log_forever) for _ in range(5)]
    for p in process:
        p.start()

    for p in process:
        p.join()


async def aio_log_forever(_id):
    logger = config_logger()
    while True:
        logger.info(f'Beep from {_id}')
        await asyncio.sleep(0.01)


async def do_async_log():
    task = [aio_log_forever(1), aio_log_forever(2), aio_log_forever(3)]
    await asyncio.gather(*task)

if __name__ == '__main__':
    # do_multiprocess_log()
    asyncio.run(do_async_log())

稍微運行後，不論是多進程還是多協程在檔案大小達到上限要更換日誌檔案時都會出現圖中的問題

但是這個問題出現時也只是擋住當下的日誌而已，後續他們仍可以正常打印日誌到 beep.log 中，更沒有出現打印最新日誌到備份檔案內的問題，後續重新嘗試幾次也都是相同結果。到這裡實在沒什麼頭緒了，所以我就想乾脆換個環境再試一次吧? 結果還真的在 Linux 測試多進程時重現問題了。

shell

watch -d -n 0.5 ls -lh

此為示意圖，非當事伺服器

找到蟲的足跡

既然重現問題也確認發生原因了，那還是要知道問題是從哪裡來的，因此又有兩個問題 1. 真的有重複的進程出現了? 2. 又是怎麼出現的?

第一個問題的話倒是好解決，只要下個指令就能確認了 ps aux

此為示意圖，非當事伺服器

第二個怎麼出現的就有點沒頭緒了，而就在這時候運維部門回報一個也和這個守護進程有關的小問題；不知道算是幸運還是衰的我因為正好在看這東西就順帶一起處理了，但我想應該還是幸運占大多數，因為他們回報的功能竟然剛好就是造成多進程出現的來源!

真相大白

話說剛剛運維部門回報的問題只是某台伺服器的守護進程和 RabbitMQ 斷線導致收不到 Message 而已，而那個功能是配置一些設定後透過 Message 通知守護進程要重啟並重新載入新配置，但就是這個重啟的過程被我發現:

他的進程變多了!
因為啟動時他又次將註冊的功能用子進程運行了!

用指令查看 systemctl status {守護進程}.service 或是 head /proc/{pid}/status 發現 3. 甚至連守護進程的名稱也變了!

接著進一步檢查他如何實現重啟進程時，終於抓到問題點了

python

def restart():
    python = sys.executable
    os.execl(python, python, *sys.argv)

在程式碼中可以看到他用 execl 透過 python 去運行 python 把主程序本身給替換掉，所以原本的進程並沒有被關掉且也保留了原本的 pid，但啟動時又再次把一些已經成為子進程的功能在重新起一次子進程，所以就算最一開始的開發者有實作檢查 pid 和名稱確認程序是否已啟動，但名字都被改了怎麼檢查都是未啟動了啊!

到這裡問題就好解決了，我直接把重啟的那段程式碼改一下就沒事了

os.execlp(python, {守護進程}, *sys.argv)

後來又考量到可能會有傳參需求又改成

os.execlp({守護進程}, *sys.argv)

修改後就變成主程序重新啟動時會一併將子程序帶走，啟動時再把功能重新起為子進程。

Python 多進程與 logging

一個沒什麼影響業務的 BUG ​

開始抓蟲 ​

找到蟲的足跡 ​

真相大白 ​

一個沒什麼影響業務的 BUG

開始抓蟲

找到蟲的足跡

真相大白