python logging日志模塊以及多進(jìn)程日志詳解
本篇文章主要對 python logging 的介紹加深理解。更主要是 討論在多進(jìn)程環(huán)境下如何使用logging 來輸出日志, 如何安全地切分日志文件。
1. logging日志模塊介紹
python的logging模塊提供了靈活的標(biāo)準(zhǔn)模塊,使得任何Python程序都可以使用這個(gè)第三方模塊來實(shí)現(xiàn)日志記錄。python logging 官方文檔
logging框架中主要由四個(gè)部分組成:
- Loggers: 可供程序直接調(diào)用的接口
- Handlers: 決定將日志記錄分配至正確的目的地
- Filters: 提供更細(xì)粒度的日志是否輸出的判斷
- Formatters: 制定最終記錄打印的格式布局
2. logging的組成
loggers
loggers 就是程序可以直接調(diào)用的一個(gè)日志接口,可以直接向logger寫入日志信息。logger并不是直接實(shí)例化使用的,而是通過logging.getLogger(name)來獲取對象,事實(shí)上logger對象是單例模式,logging是多線程安全的,也就是無論程序中哪里需要打日志獲取到的logger對象都是同一個(gè)。但是不幸的是logger并不支持多進(jìn)程,這個(gè)在后面的章節(jié)再解釋,并給出一些解決方案。
【注意】loggers對象是有父子關(guān)系的,當(dāng)沒有父logger對象時(shí)它的父對象是root,當(dāng)擁有父對象時(shí)父子關(guān)系會被修正。舉個(gè)例子logging.getLogger("abc.xyz")會創(chuàng)建兩個(gè)logger對象,一個(gè)是abc父對象,一個(gè)是xyz子對象,同時(shí)abc沒有父對象所以它的父對象是root。但是實(shí)際上abc是一個(gè)占位對象(虛的日志對象),可以沒有handler來處理日志。但是root不是占位對象,如果某一個(gè)日志對象打日志時(shí),它的父對象會同時(shí)收到日志,所以有些使用者發(fā)現(xiàn)創(chuàng)建了一個(gè)logger對象時(shí)會打兩遍日志,就是因?yàn)樗麆?chuàng)建的logger打了一遍日志,同時(shí)root對象也打了一遍日志。
每個(gè)logger都有一個(gè)日志的級別。logging中定義了如下級別
| Level | Numeric value |
|---|---|
| NOTSET | 0 |
| DEBUG | 10 |
| INFO | 20 |
| WARNING | 30 |
| ERROR | 40 |
| CRITICAL | 50 |
當(dāng)一個(gè)logger收到日志信息后先判斷是否符合level,如果決定要處理就將信息傳遞給Handlers進(jìn)行處理。
Handlers
Handlers 將logger發(fā)過來的信息進(jìn)行準(zhǔn)確地分配,送往正確的地方。舉個(gè)栗子,送往控制臺或者文件或者both或者其他地方(進(jìn)程管道之類的)。它決定了每個(gè)日志的行為,是之后需要配置的重點(diǎn)區(qū)域。
每個(gè)Handler同樣有一個(gè)日志級別,一個(gè)logger可以擁有多個(gè)handler也就是說logger可以根據(jù)不同的日志級別將日志傳遞給不同的handler。當(dāng)然也可以相同的級別傳遞給多個(gè)handlers這就根據(jù)需求來靈活的設(shè)置了。
Filters
Filters 提供了更細(xì)粒度的判斷,來決定日志是否需要打印。原則上handler獲得一個(gè)日志就必定會根據(jù)級別被統(tǒng)一處理,但是如果handler擁有一個(gè)Filter可以對日志進(jìn)行額外的處理和判斷。例如Filter能夠?qū)碜蕴囟ㄔ吹娜罩具M(jìn)行攔截or修改甚至修改其日志級別(修改后再進(jìn)行級別判斷)。
logger和handler都可以安裝filter甚至可以安裝多個(gè)filter串聯(lián)起來。
Formatters
Formatters 指定了最終某條記錄打印的格式布局。Formatter會將傳遞來的信息拼接成一條具體的字符串,默認(rèn)情況下Format只會將信息%(message)s直接打印出來。Format中有一些自帶的LogRecord屬性可以使用,如下表格:
| Attribute | Format | Description |
|---|---|---|
| asctime | %(asctime)s | 將日志的時(shí)間構(gòu)造成可讀的形式,默認(rèn)情況下是‘2016-02-08 12:00:00,123'精確到毫秒 |
| filename | %(filename)s | 包含path的文件名 |
| funcName | %(funcName)s | 由哪個(gè)function發(fā)出的log |
| levelname | %(levelname)s | 日志的最終等級(被filter修改后的) |
| message | %(message)s | 日志信息 |
| lineno | %(lineno)d | 當(dāng)前日志的行號 |
| pathname | %(pathname)s | 完整路徑 |
| process | %(process)s | 當(dāng)前進(jìn)程 |
| thread | %(thread)s | 當(dāng)前線程 |
一個(gè)Handler只能擁有一個(gè)Formatter 因此如果要實(shí)現(xiàn)多種格式的輸出只能用多個(gè)Handler來實(shí)現(xiàn)。<
3. logging 配置
簡易配置
首先在 loggers 章節(jié)里說明了一點(diǎn),我們擁有一個(gè)缺省的日志對象root,這個(gè)root日志對象的好處是我們直接可以使用logging來進(jìn)行配置和打日志。例如:
logging.basicConfig(level=logging.INFO,filename='logger.log')
logging.info("info message")
所以這里的簡易配置所指的就是root日志對象,隨拿隨用。每個(gè)logger都是單例對象所以配置過一遍之后程序內(nèi)任何地方調(diào)用都可以。我們只需要調(diào)用basicConfig就可以對root日志對象進(jìn)行簡易的配置,事實(shí)上這種方式相當(dāng)有效易用。它使得調(diào)用任何logger時(shí)保證至少一定會有一個(gè)Handler能夠處理日志。
簡易配置大致可以這么設(shè)置:
logging.basicConfig(level=logging.INFO,
format='%(asctime)s %(filename)s[line:%(lineno)d] %(levelname)s %(message)s',
datefmt='[%Y-%m_%d %H:%M:%S]',
filename='../log/my.log',
filemode='a')
代碼配置
另一種更加細(xì)致地設(shè)置方式是在代碼中配置,但這種設(shè)置方式是使用的最少的方式,畢竟誰也不希望把設(shè)置寫死到代碼里面去。但是這里也稍微介紹一下,雖然用的不多,在必要的時(shí)候也可以用一把。(以后補(bǔ)上)
配置文件配置
python中l(wèi)ogging的配置文件是基于ConfigParser的功能。也就是說配置文件的格式也是按照這種方式來編寫。先奉上一個(gè)比較一般的配置文件再細(xì)說
##############################################
[loggers]
keys=root, log02
[logger_root]
level=INFO
handlers=handler01
[logger_log02]
level=DEBUG
handler=handler02
qualname=log02
##############################################
[handlers]
keys=handler01,handler02
[handler_handler01]
class=FileHandler
level=INFO
formatter=form01
args=('../log/cv_parser_gm_server.log',"a")
[handler_handler02]
class=StreamHandler
level=NOTSET
formatter=form01
args=(sys.stdout,)
##############################################
[formatters]
keys=form01,form02
[formatter_form01]
format=%(asctime)s %(filename)s[line:%(lineno)d] %(levelname)s %(process)d %(message)s
datefmt=[%Y-%m-%d %H:%M:%S]
[formatter_form02]
format=(message)s
##############################################
相信看一遍以后,也找出規(guī)律了,我將幾個(gè)大塊用#分了出來。每一個(gè)logger或者h(yuǎn)andler或者formatter都有一個(gè)key名字。以logger為例,首先需要在[loggers]配置中加上key名字代表了這個(gè)logger。然后用[loggers_xxxx]其中xxxx為key名來具體配置這個(gè)logger,在log02中我配置了level和一個(gè)handler名,當(dāng)然你可以配置多個(gè)hander。根據(jù)這個(gè)handler名再去 [handlers]里面去找具體handler的配置,以此類推。
然后在代碼中,這樣加載配置文件即可:
logging.config.fileConfig(log_conf_file)
在handler中有一個(gè)class配置,可能有些讀者并不是很懂。其實(shí)這個(gè)是logging里面原先就寫好的一些handler類,你可以在這里直接調(diào)用。class指向的類相當(dāng)于具體處理的Handler的執(zhí)行者。在logging的文檔中可以知道這里所有的Handler類都是線程安全的,大家可以放心使用。那么問題就來了,如果多進(jìn)程怎么辦呢。在下一章我主要就是重寫Handler類,來實(shí)現(xiàn)在多進(jìn)程環(huán)境下使用logging。 我們自己重寫或者全部新建一個(gè)Handler類,然后將class配置指向自己的Handler類就可以加載自己重寫的Handler了。
4. logging遇到多進(jìn)程(important)
這部分其實(shí)是我寫這篇文章的初衷。python中由于某種歷史原因,多線程的性能基本可以無視。所以一般情況下python要實(shí)現(xiàn)并行操作或者并行計(jì)算的時(shí)候都是使用多進(jìn)程。但是 python 中l(wèi)ogging 并不支持多進(jìn)程,所以會遇到不少麻煩。
本次就以 TimedRotatingFileHandler 這個(gè)類的問題作為例子。這個(gè)Handler本來的作用是:按天切割日志文件。(當(dāng)天的文件是xxxx.log 昨天的文件是xxxx.log.2016-06-01)。這樣的好處是,一來可以按天來查找日志,二來可以讓日志文件不至于非常大, 過期日志也可以按天刪除。
但是問題來了,如果是用多進(jìn)程來輸出日志,則只有一個(gè)進(jìn)程會切換,其他進(jìn)程會在原來的文件中繼續(xù)打,還有可能某些進(jìn)程切換的時(shí)候早就有別的進(jìn)程在新的日志文件里打入東西了,那么他會無情刪掉之,再建立新的日志文件。反正將會很亂很亂,完全沒法開心的玩耍。
所以這里就想了幾個(gè)辦法來解決多進(jìn)程logging問題
原因
在解決之前,我們先看看為什么會導(dǎo)致這樣的原因。
先將 TimedRotatingFileHandler 的源代碼貼上來,這部分是切換時(shí)所作的操作:
def doRollover(self):
"""
do a rollover; in this case, a date/time stamp is appended to the filename
when the rollover happens. However, you want the file to be named for the
start of the interval, not the current time. If there is a backup count,
then we have to get a list of matching filenames, sort them and remove
the one with the oldest suffix.
"""
if self.stream:
self.stream.close()
self.stream = None
# get the time that this sequence started at and make it a TimeTuple
currentTime = int(time.time())
dstNow = time.localtime(currentTime)[-1]
t = self.rolloverAt - self.interval
if self.utc:
timeTuple = time.gmtime(t)
else:
timeTuple = time.localtime(t)
dstThen = timeTuple[-1]
if dstNow != dstThen:
if dstNow:
addend = 3600
else:
addend = -3600
timeTuple = time.localtime(t + addend)
dfn = self.baseFilename + "." + time.strftime(self.suffix, timeTuple)
if os.path.exists(dfn):
os.remove(dfn)
# Issue 18940: A file may not have been created if delay is True.
if os.path.exists(self.baseFilename):
os.rename(self.baseFilename, dfn)
if self.backupCount > 0:
for s in self.getFilesToDelete():
os.remove(s)
if not self.delay:
self.stream = self._open()
newRolloverAt = self.computeRollover(currentTime)
while newRolloverAt <= currentTime:
newRolloverAt = newRolloverAt + self.interval
#If DST changes and midnight or weekly rollover, adjust for this.
if (self.when == 'MIDNIGHT' or self.when.startswith('W')) and not self.utc:
dstAtRollover = time.localtime(newRolloverAt)[-1]
if dstNow != dstAtRollover:
if not dstNow: # DST kicks in before next rollover, so we need to deduct an hour
addend = -3600
else: # DST bows out before next rollover, so we need to add an hour
addend = 3600
newRolloverAt += addend
self.rolloverAt = newRolloverAt
我們觀察 if os.path.exists(dfn) 這一行開始,這里的邏輯是如果 dfn 這個(gè)文件存在,則要先刪除掉它,然后將 baseFilename 這個(gè)文件重命名為 dfn 文件。然后再重新打開 baseFilename這個(gè)文件開始寫入東西。那么這里的邏輯就很清楚了
- 假設(shè)當(dāng)前日志文件名為 current.log 切分后的文件名為 current.log.2016-06-01
- 判斷 current.log.2016-06-01 是否存在,如果存在就刪除
- 將當(dāng)前的日志文件名 改名為current.log.2016-06-01
- 重新打開新文件(我觀察到源代碼中默認(rèn)是"a" 模式打開,之前據(jù)說是"w")
于是在多進(jìn)程的情況下,一個(gè)進(jìn)程切換了,其他進(jìn)程的句柄還在 current.log.2016-06-01 還會繼續(xù)往里面寫東西。又或者一個(gè)進(jìn)程執(zhí)行切換了,會把之前別的進(jìn)程重命名的 current.log.2016-06-01 文件直接刪除。又或者還有一個(gè)情況,當(dāng)一個(gè)進(jìn)程在寫東西,另一個(gè)進(jìn)程已經(jīng)在切換了,會造成不可預(yù)估的情況發(fā)生。還有一種情況兩個(gè)進(jìn)程同時(shí)在切文件,第一個(gè)進(jìn)程正在執(zhí)行第3步,第二進(jìn)程剛執(zhí)行完第2步,然后第一個(gè)進(jìn)程 完成了重命名但還沒有新建一個(gè)新的 current.log 第二個(gè)進(jìn)程開始重命名,此時(shí)第二個(gè)進(jìn)程將會因?yàn)檎也坏?current 發(fā)生錯(cuò)誤。如果第一個(gè)進(jìn)程已經(jīng)成功創(chuàng)建了 current.log 第二個(gè)進(jìn)程會將這個(gè)空文件另存為 current.log.2016-06-01。那么不僅刪除了日志文件,而且,進(jìn)程一認(rèn)為已經(jīng)完成過切分了不會再切,而事實(shí)上他的句柄指向的是current.log.2016-06-01。
好了這里看上去很復(fù)雜,實(shí)際上就是因?yàn)閷τ谖募僮鲿r(shí),沒有對多進(jìn)程進(jìn)行一些約束,而導(dǎo)致的問題。
那么如何優(yōu)雅地解決這個(gè)問題呢。我提出了兩種方案,當(dāng)然我會在下面提出更多可行的方案供大家嘗試。
解決方案1
先前我們發(fā)現(xiàn) TimedRotatingFileHandler 中邏輯的缺陷。我們只需要稍微修改一下邏輯即可:
- 判斷切分后的文件 current.log.2016-06-01 是否存在,如果不存在則進(jìn)行重命名。(如果存在說明有其他進(jìn)程切過了,我不用切了,換一下句柄即可)
- 以"a"模式 打開 current.log
發(fā)現(xiàn)修改后就這么簡單~
talking is cheap show me the code:
class SafeRotatingFileHandler(TimedRotatingFileHandler):
def __init__(self, filename, when='h', interval=1, backupCount=0, encoding=None, delay=False, utc=False):
TimedRotatingFileHandler.__init__(self, filename, when, interval, backupCount, encoding, delay, utc)
"""
Override doRollover
lines commanded by "##" is changed by cc
"""
def doRollover(self):
"""
do a rollover; in this case, a date/time stamp is appended to the filename
when the rollover happens. However, you want the file to be named for the
start of the interval, not the current time. If there is a backup count,
then we have to get a list of matching filenames, sort them and remove
the one with the oldest suffix.
Override, 1. if dfn not exist then do rename
2. _open with "a" model
"""
if self.stream:
self.stream.close()
self.stream = None
# get the time that this sequence started at and make it a TimeTuple
currentTime = int(time.time())
dstNow = time.localtime(currentTime)[-1]
t = self.rolloverAt - self.interval
if self.utc:
timeTuple = time.gmtime(t)
else:
timeTuple = time.localtime(t)
dstThen = timeTuple[-1]
if dstNow != dstThen:
if dstNow:
addend = 3600
else:
addend = -3600
timeTuple = time.localtime(t + addend)
dfn = self.baseFilename + "." + time.strftime(self.suffix, timeTuple)
## if os.path.exists(dfn):
## os.remove(dfn)
# Issue 18940: A file may not have been created if delay is True.
## if os.path.exists(self.baseFilename):
if not os.path.exists(dfn) and os.path.exists(self.baseFilename):
os.rename(self.baseFilename, dfn)
if self.backupCount > 0:
for s in self.getFilesToDelete():
os.remove(s)
if not self.delay:
self.mode = "a"
self.stream = self._open()
newRolloverAt = self.computeRollover(currentTime)
while newRolloverAt <= currentTime:
newRolloverAt = newRolloverAt + self.interval
#If DST changes and midnight or weekly rollover, adjust for this.
if (self.when == 'MIDNIGHT' or self.when.startswith('W')) and not self.utc:
dstAtRollover = time.localtime(newRolloverAt)[-1]
if dstNow != dstAtRollover:
if not dstNow: # DST kicks in before next rollover, so we need to deduct an hour
addend = -3600
else: # DST bows out before next rollover, so we need to add an hour
addend = 3600
newRolloverAt += addend
self.rolloverAt = newRolloverAt
不要以為代碼那么長,其實(shí)修改部分就是 "##" 注釋的地方而已,其他都是照抄源代碼。這個(gè)類繼承了 TimedRotatingFileHandler 重寫了這個(gè)切分的過程。這個(gè)解決方案十分優(yōu)雅,改換的地方非常少,也十分有效。但有網(wǎng)友提出,這里有一處地方依然不完美,就是rename的那一步,如果就是這么巧,同時(shí)兩個(gè)或者多個(gè)進(jìn)程進(jìn)入了 if 語句,先后開始 rename 那么依然會發(fā)生刪除掉日志的情況。確實(shí)這種情況確實(shí)會發(fā)生,由于切分文件一天才一次,正好切分的時(shí)候同時(shí)有兩個(gè)Handler在操作,又正好同時(shí)走到這里,也是蠻巧的,但是為了完美,可以加上一個(gè)文件鎖,if 之后加鎖,得到鎖之后再判斷一次,再進(jìn)行rename這種方式就完美了。代碼就不貼了,涉及到鎖代碼,影響美觀。
解決方案2
我認(rèn)為最簡單有效的解決方案。重寫FileHandler類(這個(gè)類是所有寫入文件的Handler都需要繼承的TimedRotatingFileHandler 就是繼承的這個(gè)類;我們增加一些簡單的判斷和操作就可以。
我們的邏輯是這樣的:
- 判斷當(dāng)前時(shí)間戳是否與指向的文件名是同一個(gè)時(shí)間
- 如果不是,則切換 指向的文件即可
結(jié)束,是不是很簡單的邏輯。
talking is cheap show me the code:
class SafeFileHandler(FileHandler):
def __init__(self, filename, mode, encoding=None, delay=0):
"""
Use the specified filename for streamed logging
"""
if codecs is None:
encoding = None
FileHandler.__init__(self, filename, mode, encoding, delay)
self.mode = mode
self.encoding = encoding
self.suffix = "%Y-%m-%d"
self.suffix_time = ""
def emit(self, record):
"""
Emit a record.
Always check time
"""
try:
if self.check_baseFilename(record):
self.build_baseFilename()
FileHandler.emit(self, record)
except (KeyboardInterrupt, SystemExit):
raise
except:
self.handleError(record)
def check_baseFilename(self, record):
"""
Determine if builder should occur.
record is not used, as we are just comparing times,
but it is needed so the method signatures are the same
"""
timeTuple = time.localtime()
if self.suffix_time != time.strftime(self.suffix, timeTuple) or not os.path.exists(self.baseFilename+'.'+self.suffix_time):
return 1
else:
return 0
def build_baseFilename(self):
"""
do builder; in this case,
old time stamp is removed from filename and
a new time stamp is append to the filename
"""
if self.stream:
self.stream.close()
self.stream = None
# remove old suffix
if self.suffix_time != "":
index = self.baseFilename.find("."+self.suffix_time)
if index == -1:
index = self.baseFilename.rfind(".")
self.baseFilename = self.baseFilename[:index]
# add new suffix
currentTimeTuple = time.localtime()
self.suffix_time = time.strftime(self.suffix, currentTimeTuple)
self.baseFilename = self.baseFilename + "." + self.suffix_time
self.mode = 'a'
if not self.delay:
self.stream = self._open()
check_baseFilename 就是執(zhí)行邏輯1判斷;build_baseFilename 就是執(zhí)行邏輯2換句柄。就這么簡單完成了。
這種方案與之前不同的是,當(dāng)前文件就是 current.log.2016-06-01 ,到了明天當(dāng)前文件就是current.log.2016-06-02 沒有重命名的情況,也沒有刪除的情況。十分簡潔優(yōu)雅。也能解決多進(jìn)程的logging問題。
解決方案其他
當(dāng)然還有其他的解決方案,例如由一個(gè)logging進(jìn)程統(tǒng)一打日志,其他進(jìn)程將所有的日志內(nèi)容打入logging進(jìn)程管道由它來打理。還有將日志打入網(wǎng)絡(luò)socket當(dāng)中也是同樣的道理。
5. 參考資料
以上就是本文的全部內(nèi)容,希望對大家的學(xué)習(xí)有所幫助,也希望大家多多支持腳本之家。
- Python使用logging實(shí)現(xiàn)多進(jìn)程安全的日志模塊
- python?logging多進(jìn)程多線程輸出到同一個(gè)日志文件的實(shí)戰(zhàn)案例
- python 實(shí)現(xiàn)多進(jìn)程日志輪轉(zhuǎn)ConcurrentLogHandler
- python多進(jìn)程下實(shí)現(xiàn)日志記錄按時(shí)間分割
- python中日志logging模塊的性能及多進(jìn)程詳解
- 詳解Python中l(wèi)ogging日志模塊在多進(jìn)程環(huán)境下的使用
- python多進(jìn)程日志以及分布式日志的實(shí)現(xiàn)方式
相關(guān)文章
Django?url.py?path?name同一app下路由別名定義
這篇文章主要為大家介紹了Django?url.py?path?name同一app下路由別名定義詳解,有需要的朋友可以借鑒參考下,希望能夠有所幫助,祝大家多多進(jìn)步,早日升職加薪2022-07-07
matplotlib之Pyplot模塊繪制三維散點(diǎn)圖使用顏色表示數(shù)值大小
在撰寫論文時(shí)常常會用到matplotlib來繪制三維散點(diǎn)圖,下面這篇文章主要給大家介紹了關(guān)于matplotlib之Pyplot模塊繪制三維散點(diǎn)圖使用顏色表示數(shù)值大小的相關(guān)資料,文中通過圖文介紹的非常詳細(xì),需要的朋友可以參考下2022-08-08
python并發(fā)爬蟲實(shí)用工具tomorrow實(shí)用解析
這篇文章主要介紹了python并發(fā)爬蟲實(shí)用工具tomorrow實(shí)用解析,文中通過示例代碼介紹的非常詳細(xì),對大家的學(xué)習(xí)或者工作具有一定的參考學(xué)習(xí)價(jià)值,需要的朋友可以參考下2019-09-09
Python多進(jìn)程與服務(wù)器并發(fā)原理及用法實(shí)例分析
這篇文章主要介紹了Python多進(jìn)程與服務(wù)器并發(fā)原理及用法,深入淺出的介紹了進(jìn)程、并行、并發(fā)、同步、異步等相關(guān)概念與原理,并結(jié)合實(shí)例形式給出了Python多進(jìn)程編程相關(guān)操作技巧,需要的朋友可以參考下2018-08-08
Pandas操作兩個(gè)Excel實(shí)現(xiàn)數(shù)據(jù)對應(yīng)行的合并
本文主要介紹了Pandas操作兩個(gè)Excel實(shí)現(xiàn)數(shù)據(jù)對應(yīng)行的合并,文中通過示例代碼介紹的非常詳細(xì),對大家的學(xué)習(xí)或者工作具有一定的參考學(xué)習(xí)價(jià)值,需要的朋友們下面隨著小編來一起學(xué)習(xí)學(xué)習(xí)吧2023-01-01

