干爬蟲(chóng)這些年我接手過(guò)的項(xiàng)目少說(shuō)也有十幾個(gè)其中九個(gè)的日志系統(tǒng)都是能跑就行的狀態(tài)。直到有一次凌晨?jī)牲c(diǎn)線上爬蟲(chóng)突然停擺解析規(guī)則沒(méi)問(wèn)題、數(shù)據(jù)庫(kù)連接正常、代理池也沒(méi)掛我硬是排查了三個(gè)小時(shí)才找到真兇——日志文件把磁盤(pán)寫(xiě)滿了進(jìn)程直接被系統(tǒng)干掉。從那之后我養(yǎng)成了一個(gè)習(xí)慣接到新項(xiàng)目第一件事就是把Scrapy日志系統(tǒng)和生產(chǎn)環(huán)境配置從頭到尾梳理一遍。這篇博文就把我積累的這些東西完整寫(xiě)出來(lái)包括日志系統(tǒng)的工作原理、settings里的各種開(kāi)關(guān)、擴(kuò)展機(jī)制、生產(chǎn)環(huán)境落地配置還有我踩過(guò)的坑。不管你是剛把本地爬蟲(chóng)腳本改成生產(chǎn)任務(wù)還是被日志問(wèn)題搞得焦頭爛額這篇內(nèi)容應(yīng)該能幫你節(jié)省不少排查時(shí)間。1. 先從一次線上事故說(shuō)起日志系統(tǒng)為什么值得認(rèn)真對(duì)待1.1 那個(gè)把磁盤(pán)寫(xiě)滿的日志文件那次事故的具體情況是這樣的項(xiàng)目大概每天爬取30萬(wàn)條商品數(shù)據(jù)跑了一個(gè)多月沒(méi)出過(guò)問(wèn)題。某個(gè)凌晨我的告警電話響了說(shuō)爬蟲(chóng)進(jìn)程消失了systemd把它標(biāo)記為failed。我登錄服務(wù)器一看磁盤(pán)使用率100%df -h顯示/目錄已經(jīng)被占滿再一看罪魁禍?zhǔn)资莑ogs/scrapy.log大小已經(jīng)是18GB了。為什么會(huì)這樣因?yàn)楫?dāng)時(shí)圖省事直接在settings.py里配置了LOG_FILE logs/scrapy.log這是Scrapy官方提供的最簡(jiǎn)單的文件日志方案。但這個(gè)方案的本質(zhì)就是用一個(gè)FileHandler往同一個(gè)文件里追加寫(xiě)入既不切割、不壓縮、也不清理舊文件。一個(gè)每天寫(xiě)入幾百M(fèi)B的爬蟲(chóng)項(xiàng)目跑一個(gè)月就是這個(gè)結(jié)果。這里需要特別說(shuō)明一個(gè)新手容易忽略的點(diǎn)Scrapy默認(rèn)是只在控制臺(tái)輸出日志的你配置了LOG_FILE之后控制臺(tái)就沒(méi)了全部寫(xiě)進(jìn)文件。但Scrapy不會(huì)幫你做任何輪轉(zhuǎn)log rotation。這不是Scrapy的疏漏因?yàn)槿罩据嗈D(zhuǎn)這件事本身就是部署層該負(fù)責(zé)的但在實(shí)際項(xiàng)目中大多數(shù)人不會(huì)單獨(dú)給爬蟲(chóng)配一個(gè)logrotate任務(wù)于是日志就成了定時(shí)炸彈。后面第4章我會(huì)給出完整的解決方案。1.2 Scrapy日志系統(tǒng)的基本工作原理要避開(kāi)這些坑先得搞清楚Scrapy日志系統(tǒng)到底是怎么運(yùn)轉(zhuǎn)的。簡(jiǎn)單說(shuō)Scrapy的日志建立在Python標(biāo)準(zhǔn)庫(kù)logging之上沒(méi)有自己另搞一套。它內(nèi)部維護(hù)了一組以scrapy開(kāi)頭的logger實(shí)例比如scrapy.core.engine、scrapy.core.scraper、scrapy.core.downloader、scrapy.middleware、scrapy.extensions.logstats等等。爬蟲(chóng)在運(yùn)行過(guò)程中引擎、下載器、中間件、擴(kuò)展這些組件都會(huì)往對(duì)應(yīng)的logger里寫(xiě)日志事件。這些日志事件本身只是一條條帶級(jí)別和上下文的消息真正決定它們?nèi)ツ睦锏氖莚oot logger上的handler。Scrapy啟動(dòng)時(shí)會(huì)調(diào)用configure_logging()做一次統(tǒng)一配置如果你設(shè)置了LOG_FILE就往root logger加一個(gè)FileHandler如果沒(méi)有就加一個(gè)StreamHandler輸出到控制臺(tái)。第三方庫(kù)比如requests、selenium、playwright打出來(lái)的日志只要是通過(guò)標(biāo)準(zhǔn)logging產(chǎn)生的也會(huì)被root logger一起捕獲。很多人在這個(gè)環(huán)節(jié)困惑的點(diǎn)是為什么我設(shè)置了LOG_FILE之后控制臺(tái)什么都沒(méi)有了因?yàn)槟J(rèn)的配置邏輯就是文件或控制臺(tái)二選一——設(shè)置了LOG_FILE就只寫(xiě)文件。要讓兩者同時(shí)輸出就得自己配多個(gè)handler。這一點(diǎn)我在第4章的統(tǒng)一方案里會(huì)解決。理解了日志的三個(gè)關(guān)鍵角色logger誰(shuí)產(chǎn)生消息、handler消息去哪里、formatter消息長(zhǎng)什么樣子后面所有配置你都能自己推出來(lái)。Scrapy給的settings項(xiàng)本質(zhì)上都是對(duì)這些角色的操作LOG_LEVEL控制logger的過(guò)濾級(jí)別LOG_FILE決定handler是文件還是屏幕LOG_FORMAT和LOG_DATEFORMAT控制formatter的模板。搞懂這層對(duì)應(yīng)關(guān)系你就不會(huì)被各種配置項(xiàng)繞暈了。2. settings.py 里的日志開(kāi)關(guān)最常用的配置方式2.1 核心配置項(xiàng)逐一拆解Scrapy的日志配置絕大部分都在settings.py里完成下面這幾個(gè)是必須掌握的。LOG_ENABLED默認(rèn)True。這個(gè)開(kāi)關(guān)控制是否啟用日志系統(tǒng)我建議永遠(yuǎn)別關(guān)。有些人為了讓爬蟲(chóng)跑得快一點(diǎn)會(huì)把它關(guān)掉一旦出問(wèn)題連排查依據(jù)都沒(méi)有得不償失。LOG_LEVEL默認(rèn)DEBUG。在生產(chǎn)環(huán)境我強(qiáng)烈建議改成INFO。別小看這個(gè)改動(dòng)DEBUG級(jí)別的日志量通常是INFO的好幾倍具體來(lái)說(shuō)scrapy.core.engine在DEBUG級(jí)別下幾乎每個(gè)請(qǐng)求的進(jìn)出都會(huì)打兩條日志高并發(fā)爬蟲(chóng)一天能多寫(xiě)幾個(gè)GB。LOG_FILE默認(rèn)None。不設(shè)置就是輸出到控制臺(tái)設(shè)置了就寫(xiě)入文件。注意一點(diǎn)這個(gè)配置本身不做切割和LOG_LEVEL配合使用進(jìn)生產(chǎn)環(huán)境前一定要先解決輪轉(zhuǎn)問(wèn)題。LOG_FILE_MODE默認(rèn)wb。這個(gè)很多人沒(méi)注意到它控制文件的寫(xiě)入模式wb會(huì)覆蓋舊文件。也就是說(shuō)每次啟動(dòng)爬蟲(chóng)同名日志文件會(huì)被清空重寫(xiě)。如果你想保留歷史日志需要改成ab追加模式。但更推薦的做法還是用第4章的滾動(dòng)handler。LOG_FORMAT默認(rèn)字符串是%(asctime)s [%(name)s] %(levelname)s: %(message)s。這里可用的是Python logging標(biāo)準(zhǔn)字段比如%(filename)s、%(lineno)d需要時(shí)自己拼。LOG_DATEFORMAT默認(rèn)%Y-%m-%d %H:%M:%S。按自己喜好調(diào)整我習(xí)慣加上毫秒%Y-%m-%d %H:%M:%S,%f排查對(duì)比兩個(gè)事件的先后順序時(shí)很有用。LOG_SHORT_NAMES默認(rèn)False。如果設(shè)為T(mén)rue日志里的[scrapy.core.engine]會(huì)被簡(jiǎn)寫(xiě)成[engine]。我建議保持False生產(chǎn)環(huán)境日志就是要信息全多幾個(gè)字符不算什么。LOG_STDOUT默認(rèn)False。如果設(shè)為T(mén)ruePython的print輸出也會(huì)被重定向到日志系統(tǒng)里。這個(gè)選項(xiàng)適合那種代碼里殘留了很多print的老項(xiàng)目臨時(shí)救急很好用但新代碼還是老老實(shí)實(shí)用logger。下面用一個(gè)表格把這些匯總配置項(xiàng)默認(rèn)值生產(chǎn)環(huán)境建議說(shuō)明LOG_ENABLEDTrueTrue總開(kāi)關(guān)LOG_LEVELDEBUGINFO控制日志量LOG_FILENone配合輪轉(zhuǎn)使用文件輸出LOG_FILE_MODEwbab覆蓋或追加LOG_FORMAT標(biāo)準(zhǔn)模板建議加時(shí)間毫秒日志格式LOG_DATEFORMAT日期默認(rèn)建議加毫秒時(shí)間格式LOG_SHORT_NAMESFalseFalse保留完整logger名LOG_STDOUTFalse看需求print重定向2.2 命令行和代碼里的覆蓋配置配置日志不一定非要寫(xiě)在settings.py里Scrapy支持多種覆蓋方式優(yōu)先級(jí)是命令行參數(shù) settings.py 代碼默認(rèn)值。命令行方面scrapy crawl myspider -L WARNING可以直接覆蓋日志級(jí)別scrapy crawl myspider -s LOG_FILExxx.log可以動(dòng)態(tài)指定日志文件。這個(gè)主要用于臨時(shí)排查問(wèn)題比如線上日志量太大不想全量記錄可以先用-L WARNING看一下有沒(méi)有錯(cuò)誤堆棧。代碼層面如果要在一個(gè)腳本里用CrawlerProcess跑多個(gè)爬蟲(chóng)并分別控制日志可以通過(guò)get_project_settings()拿到settings對(duì)象后修改它的值再傳給CrawlerProcess。注意修改必須發(fā)生在CrawlerProcess實(shí)例化之前。如果是用CrawlerRunner在Twisted reactor里跑多個(gè)爬蟲(chóng)同理必須在create_crawler之前改。我見(jiàn)過(guò)一些項(xiàng)目會(huì)在一個(gè)進(jìn)程里連續(xù)跑多個(gè)爬蟲(chóng)然后發(fā)現(xiàn)第二個(gè)爬蟲(chóng)的日志級(jí)別不對(duì)就是因?yàn)閟ettings對(duì)象在第一個(gè)爬蟲(chóng)啟動(dòng)時(shí)被改了沒(méi)有給第二個(gè)爬蟲(chóng)恢復(fù)。這種場(chǎng)景建議不要再改全局settings而是每個(gè)爬蟲(chóng)在自己的custom_settings里定義日志配置Scrapy會(huì)在創(chuàng)建該爬蟲(chóng)實(shí)例時(shí)合并這些配置。2.3 日志級(jí)別選擇的實(shí)戰(zhàn)建議一條經(jīng)驗(yàn)法則開(kāi)發(fā)用DEBUG預(yù)發(fā)布用INFO核心鏈路用WARNING兜底。生產(chǎn)環(huán)境全量開(kāi)DEBUG通常是不必要的。我們算一筆賬假設(shè)一個(gè)爬蟲(chóng)每秒處理50個(gè)請(qǐng)求DEBUG級(jí)別下引擎日志和下載器日志加起來(lái)每個(gè)請(qǐng)求大概3~4條每秒就是200條日志。如果每條平均100字節(jié)一天就是1.7GB。而INFO級(jí)別下同樣的爬蟲(chóng)一天的日志量通常在200MB以內(nèi)。差距是數(shù)量級(jí)的。但也不能只看數(shù)量。生產(chǎn)環(huán)境如果完全不開(kāi)INFO很多關(guān)鍵信息會(huì)丟失。比如spider_opened和spider_closed是INFO級(jí)別item_scraped如果是通過(guò)LogStats輸出的也是INFO級(jí)別這些是你判斷爬蟲(chóng)是否健康的核心依據(jù)。所以我的建議是生產(chǎn)環(huán)境默認(rèn)INFO頻繁出錯(cuò)的環(huán)節(jié)單獨(dú)用logger.warning或logger.error輸出既控制量又不丟關(guān)鍵信息。3. 理解Scrapy的擴(kuò)展機(jī)制日志系統(tǒng)背后的推手3.1 Scrapy擴(kuò)展是什么為什么日志要依賴(lài)擴(kuò)展很多人在熱詞里搜scrapy中extensions是什么其實(shí)就是沒(méi)搞懂Scrapy里那套插件機(jī)制。Scrapy擴(kuò)展Extension本質(zhì)上是普通的Python類(lèi)通過(guò)from_crawler類(lèi)方法獲得crawler實(shí)例然后借助crawler.signals.connect訂閱爬蟲(chóng)生命周期中的各種信號(hào)比如spider_opened、spider_closed、item_scraped、response_received等在這些事件發(fā)生時(shí)執(zhí)行自己的邏輯。日志和統(tǒng)計(jì)數(shù)據(jù)強(qiáng)相關(guān)而Scrapy的統(tǒng)計(jì)數(shù)據(jù)Stats Collector本身就是一個(gè)跨組件的狀態(tài)容器所以日志功能天然適合用擴(kuò)展來(lái)實(shí)現(xiàn)。最典型的例子是Scrapy內(nèi)置的LogStats擴(kuò)展它會(huì)在爬蟲(chóng)運(yùn)行期間每隔一段時(shí)間輸出一條類(lèi)似這樣的日志2024-06-18 10:30:00 [scrapy.extensions.logstats] INFO: Crawled 1200 pages (at 4 pages/min), scraped 850 items (at 3 items/min)這條日志不是引擎自動(dòng)打的就是LogStats這個(gè)擴(kuò)展在收到定時(shí)信號(hào)后從Stats Collector里取出數(shù)據(jù)通過(guò)logger輸出的一條INFO消息。理解這一點(diǎn)你在解決日志不輸出的問(wèn)題時(shí)就會(huì)多一個(gè)排查方向是不是自定義擴(kuò)展或默認(rèn)擴(kuò)展被禁用了Scrapy里有EXTENSIONS_BASE這個(gè)默認(rèn)擴(kuò)展集合里面包含了LogStats、CoreStats、Debugger等。你自己添加擴(kuò)展可以通過(guò)EXTENSIONS配置項(xiàng)而禁用默認(rèn)擴(kuò)展也可以在這個(gè)配置里顯式設(shè)為None。3.2 手寫(xiě)一個(gè)日志統(tǒng)計(jì)擴(kuò)展按站點(diǎn)和狀態(tài)碼輸出理解了機(jī)制我們就直接實(shí)操。下面這個(gè)擴(kuò)展解決的問(wèn)題很典型大型爬蟲(chóng)往往要跑多個(gè)站點(diǎn)你會(huì)非常需要知道每個(gè)站點(diǎn)的響應(yīng)狀態(tài)碼分布、Item產(chǎn)出速率。Scrapy標(biāo)準(zhǔn)LogStats只給總量不給細(xì)分維度所以我們自己寫(xiě)一個(gè)擴(kuò)展。import logging from collections import Counter, defaultdict from scrapy import signals logger logging.getLogger(crawler.site_health) class SiteStatsLogExtension: def __init__(self, crawler, log_every500): self.crawler crawler self.stats crawler.stats self.log_every log_every self.response_counter Counter() self.item_counter defaultdict(int) self.total_count 0 classmethod def from_crawler(cls, crawler): ext cls(crawler, crawler.settings.getint(SITE_STATS_LOG_EVERY, 500)) crawler.signals.connect(ext.spider_opened, signals.spider_opened) crawler.signals.connect(ext.response_received, signals.response_received) crawler.signals.connect(ext.item_scraped, signals.item_scraped) crawler.signals.connect(ext.spider_closed, signals.spider_closed) return ext def spider_opened(self, spider): logger.info(site stats module started, log every %d events, self.log_every) def response_received(self, response, **kwargs): site getattr(response, site_name, None) or response.url.split(/)[2] self.response_counter[(site, response.status)] 1 self.total_count 1 if self.total_count % self.log_every 0: self._emit_current_stats(spider_hint) def item_scraped(self, item, spider, **kwargs): site getattr(spider, site_name, None) or spider.name self.item_counter[site] 1 def _emit_current_stats(self, spider_hint): resp_summary { f{site}:{status}: cnt for (site, status), cnt in self.response_counter.items() } item_summary dict(self.item_counter) logger.info( site health snapshot responses%s items%s, resp_summary, item_summary, ) def spider_closed(self, spider, reason): self._emit_current_stats(spider_hintspider.name) logger.info(site stats module closed, total events %d, self.total_count)然后在settings.py里注冊(cè)這個(gè)擴(kuò)展EXTENSIONS { myproject.extensions.SiteStatsLogExtension: 500, }數(shù)字500表示優(yōu)先級(jí)數(shù)字越小越早執(zhí)行。這樣在爬蟲(chóng)跑起來(lái)后每處理500個(gè)響應(yīng)就會(huì)輸出一條包含狀態(tài)碼分布和item數(shù)量的JSON風(fēng)格日志配合第4章的結(jié)構(gòu)化輸出可以直接拿去喂給日志平臺(tái)做告警。注意事項(xiàng)有兩個(gè)。第一response_received信號(hào)攜帶的response在中間件里不一定有site_name屬性所以我在代碼里做了兜底——取URL的域名。這在實(shí)際運(yùn)行中很關(guān)鍵不然擴(kuò)展剛上線就會(huì)因?yàn)锳ttributeError導(dǎo)致整個(gè)爬蟲(chóng)掛掉。第二擴(kuò)展里的異常處理不能省略如果_emit_current_stats內(nèi)部出問(wèn)題也不能讓它影響主流程可以在方法體外面套一層try/except生產(chǎn)環(huán)境的擴(kuò)展代碼必須默認(rèn)日志系統(tǒng)不能拖垮爬蟲(chóng)主線。4. 生產(chǎn)環(huán)境日志配置結(jié)構(gòu)化、滾動(dòng)與集中采集4.1 文件無(wú)限增長(zhǎng)的坑滾動(dòng)策略與handler替換回到第一章那個(gè)事故上根治辦法就是給日志加滾動(dòng)。但Scrapy的LOG_FILE配置項(xiàng)只創(chuàng)建FileHandler并不提供滾動(dòng)能力所以需要自定義handler。這里有一個(gè)關(guān)鍵的實(shí)現(xiàn)前提Scrapy的configure_logging()會(huì)在crawler創(chuàng)建時(shí)運(yùn)行如果你只是在settings.py頂層直接往root logger加handler很可能被它清掉。我踩過(guò)這個(gè)坑最后采用的穩(wěn)妥方案是寫(xiě)一個(gè)擴(kuò)展監(jiān)聽(tīng)engine_started信號(hào)在日志系統(tǒng)初始化完成后替換root logger的handlers。import logging import os from logging.handlers import TimedRotatingFileHandler from scrapy import signals class LogRotationExtension: def __init__(self, log_dir, backup_days): self.log_dir log_dir self.backup_days backup_days classmethod def from_crawler(cls, crawler): ext cls( log_dircrawler.settings.get(LOG_DIR, logs), backup_dayscrawler.settings.getint(LOG_BACKUP_DAYS, 7), ) crawler.signals.connect(ext.engine_started, signals.engine_started) return ext def engine_started(self): root logging.getLogger() # 移除Scrapy默認(rèn)添加的handler避免重復(fù)輸出 for handler in root.handlers[:]: root.removeHandler(handler) os.makedirs(self.log_dir, exist_okTrue) formatter logging.Formatter( %(asctime)s [%(name)s] %(levelname)s: %(message)s, datefmt%Y-%m-%d %H:%M:%S,%f, ) file_handler TimedRotatingFileHandler( os.path.join(self.log_dir, scrapy.log), whenmidnight, backupCountself.backup_days, encodingutf-8, ) file_handler.setFormatter(formatter) root.addHandler(file_handler) console_handler logging.StreamHandler() console_handler.setFormatter(formatter) root.addHandler(console_handler)TimedRotatingFileHandler的whenmidnight表示每天零點(diǎn)切割backupCount7保留最近7個(gè)日志文件自動(dòng)刪除更早的。如果一臺(tái)機(jī)器上日志寫(xiě)入量很大也可以改用RotatingFileHandler按文件大小切割比如單文件超過(guò)500MB切一個(gè)。這兩種方案都能解決磁盤(pán)被寫(xiě)滿的問(wèn)題。替換handler時(shí)注意root.handlers[:]的切片復(fù)制是為了邊遍歷邊刪除直接遍歷原列表會(huì)出問(wèn)題。另外因?yàn)閿U(kuò)展的from_crawler在日志配置之后執(zhí)行engine_started在爬蟲(chóng)引擎啟動(dòng)時(shí)才觸發(fā)所以這個(gè)替換是安全的不會(huì)與Scrapy默認(rèn)handler的初始化邏輯產(chǎn)生競(jìng)態(tài)沖突。4.2 結(jié)構(gòu)化日志輸出讓每一條日志都能被程序解析生產(chǎn)環(huán)境的日志不應(yīng)該只是給人看的還要能被采集、檢索、統(tǒng)計(jì)。最強(qiáng)的做法是把日志輸出成JSON格式。這樣后續(xù)接入ELK或Loki時(shí)不需要寫(xiě)一堆grok解析規(guī)則直接按字段查就行。實(shí)現(xiàn)方式是用自定義Formatter。下面是我項(xiàng)目里在用的一個(gè)輕量實(shí)現(xiàn)不依賴(lài)第三方庫(kù)import json import logging class JsonFormatter(logging.Formatter): def format(self, record): data { timestamp: self.formatTime(record, self.datefmt), logger: record.name, level: record.levelname, message: record.getMessage(), } if record.exc_info: data[exc_info] self.formatException(record.exc_info) return json.dumps(data, ensure_asciiFalse)然后在上一節(jié)的擴(kuò)展里把file_handler.setFormatter(JsonFormatter())替換掉普通Formatter?？刂婆_(tái)仍然可以用人類(lèi)可讀的Formatter文件用JSON這樣兼顧排查和機(jī)器采集。這里有一個(gè)細(xì)節(jié)message里如果包含對(duì)象json.dumps會(huì)被類(lèi)型卡住。我在生產(chǎn)里只允許字符串、數(shù)字、字典和列表有一個(gè)簡(jiǎn)單的兜底辦法對(duì)message做str()強(qiáng)制轉(zhuǎn)換但這樣嵌套結(jié)構(gòu)就不好看了。更干凈的做法是在寫(xiě)入日志時(shí)統(tǒng)一用logger.info(xxx, extra{payload: {...}})然后在Formatter里拼裝?？傊罩酒脚_(tái)字段越多后續(xù)監(jiān)控告警越靈活。ensure_asciiFalse必須加上不然中文全變成\u轉(zhuǎn)義序列看起來(lái)非常痛苦。這是一行必須記住的代碼。4.3 敏感信息脫敏與記錄邊界爬蟲(chóng)日志經(jīng)常會(huì)把URL、Cookie、Token、請(qǐng)求參數(shù)一起打出來(lái)這在本地沒(méi)問(wèn)題但生產(chǎn)環(huán)境的日志往往會(huì)被采集到統(tǒng)一的日志平臺(tái)這就有信息泄露風(fēng)險(xiǎn)。我在日志系統(tǒng)中做了兩層防護(hù)。第一層在可能涉及敏感信息的日志位置不打印完整內(nèi)容。比如請(qǐng)求頭里的Cookie就用logger.debug(cookie: ***)或者只打前幾個(gè)字符。但代碼是很多人寫(xiě)的靠自覺(jué)不可靠。第二層更穩(wěn)妥的辦法是加Filter。Filter可以在日志事件到達(dá)handler之前修改或丟棄消息。下面這個(gè)Filter會(huì)把常見(jiàn)敏感字段的值替換成掩碼import re class SensitiveDataFilter(logging.Filter): def __init__(self, patternsNone): super().__init__() self.patterns patterns or [ (r(cookie[:]\s*)[^;\s], r\1***), (r(token[:]\s*)[^\s], r\1***), (r(password[:]\s*)[^\s], r\1***), ] def filter(self, record): msg record.getMessage() for pattern, repl in self.patterns: msg re.sub(pattern, repl, msg, flagsre.IGNORECASE) record.msg msg record.args () return True這個(gè)Filter要添加到所有輸出到外部的handler上而不是只加在root logger上。如果你只加在一個(gè)handler上控制臺(tái)能看到原始信息、日志平臺(tái)只能看到脫敏信息這在某些場(chǎng)景下是有意為之的但要注意統(tǒng)一不然排查問(wèn)題時(shí)會(huì)對(duì)著脫敏后的日志干瞪眼。4.4 日志分析工具選型日志采集和分析是生產(chǎn)環(huán)境繞不開(kāi)的一環(huán)。如果項(xiàng)目規(guī)模不大單機(jī)幾臺(tái)服務(wù)器我推薦輕量方案Filebeat Loki Grafana。Filebeat負(fù)責(zé)讀日志文件Loki負(fù)責(zé)存儲(chǔ)和索引Grafana做可視化。這套方案比ELK輕得多對(duì)內(nèi)存的占用只有ELK的幾分之一尤其適合小團(tuán)隊(duì)自己維護(hù)。如果公司已經(jīng)有ELKElasticsearch Logstash Kibana那就直接接入Filebeat把日志推到Logstash或者用Elastic Agent直接發(fā)到ES。因?yàn)槿罩疽呀?jīng)是JSON結(jié)構(gòu)化不需要再在Logstash里寫(xiě)grok解析整個(gè)鏈路會(huì)很流暢。關(guān)于AI工具精準(zhǔn)分析日志我的態(tài)度是AI適合做輔助排查、發(fā)現(xiàn)異常模式、解釋報(bào)錯(cuò)堆棧但前提是日志必須結(jié)構(gòu)和采集做得好。如果日志是一堆無(wú)規(guī)則的文本任何AI工具也很難榨出有效信息。所以第一步永遠(yuǎn)是先把日志結(jié)構(gòu)化和集中化然后再考慮讓AI幫你從海量日志里找線索。我自己用下來(lái)覺(jué)得AI在給出一段報(bào)錯(cuò)、讓它猜測(cè)可能原因這個(gè)場(chǎng)景效率很高但在實(shí)時(shí)監(jiān)控告警上還是規(guī)則和指標(biāo)更可靠。5. 生產(chǎn)環(huán)境實(shí)操一個(gè)可直接落地的完整配置5.1 完整配置包settings、擴(kuò)展、啟動(dòng)命令把前面幾章的東西串起來(lái)我現(xiàn)在給出一個(gè)可以直接抄的配置包。項(xiàng)目的目錄結(jié)構(gòu)大致是這樣myproject/ ├── scrapy.cfg ├── myproject/ │ ├── settings.py │ ├── extensions/ │ │ ├── __init__.py │ │ ├── log_rotation.py │ │ └── site_stats.py │ └── spiders/settings.py里這樣寫(xiě)LOG_ENABLED True LOG_LEVEL INFO LOG_FILE_MODE ab LOG_ENCODING utf-8 LOG_SHORT_NAMES False # 自定義日志擴(kuò)展 EXTENSIONS { myproject.extensions.log_rotation.LogRotationExtension: 100, myproject.extensions.site_stats.SiteStatsLogExtension: 500, } # 擴(kuò)展用到的自定義配置 LOG_DIR logs LOG_BACKUP_DAYS 7 SITE_STATS_LOG_EVERY 500這里的優(yōu)先級(jí)數(shù)字要注意LogRotationExtension的優(yōu)先級(jí)是100SiteStatsLogExtension是500數(shù)字小先執(zhí)行。滾動(dòng)日志的初始化在engine_started時(shí)執(zhí)行而SiteStats在spider_opened時(shí)才開(kāi)始統(tǒng)計(jì)兩者不會(huì)沖突。如果你還用了playwright抓動(dòng)態(tài)頁(yè)面尤其是帶iframe的復(fù)雜頁(yè)面記住一個(gè)經(jīng)驗(yàn)給每次iframe上下文切換和頁(yè)面加載的關(guān)鍵節(jié)點(diǎn)打上spider.info級(jí)別的日志但別在請(qǐng)求循環(huán)里打印完整DOM。我處理過(guò)一個(gè)案例爬蟲(chóng)在抓某個(gè)嵌套三層iframe的頁(yè)面時(shí)偶爾超時(shí)就是靠日志里記錄的iframe加載狀態(tài)才確認(rèn)是某個(gè)廣告iframe一直在刷接口導(dǎo)致的這種問(wèn)題靠肉眼是看不出來(lái)的。5.2 驗(yàn)證與性能壓測(cè)日志系統(tǒng)的瓶頸在哪里配置完之后不要直接上生產(chǎn)先做兩件驗(yàn)證日志是否按預(yù)期切分以及日志IO對(duì)爬蟲(chóng)吞吐的影響。切分驗(yàn)證很簡(jiǎn)單手動(dòng)改系統(tǒng)時(shí)間或者觸發(fā)一次midnight切割比較麻煩可以用whenS和interval3600臨時(shí)跑一小時(shí)驗(yàn)證或者干脆把when設(shè)成H每小時(shí)一切在生產(chǎn)上也夠用我更喜歡按小時(shí)切割便于按小時(shí)粒度去回溯問(wèn)題。驗(yàn)證輸出觀察logs/scrapy.log.2024-06-18這類(lèi)帶日期的歸檔文件是否生成以及scrapy.log本身是否被清空重建。性能方面我的實(shí)測(cè)經(jīng)驗(yàn)是單進(jìn)程500QPS以內(nèi)同步FileHandler沒(méi)有任何壓力超過(guò)1000QPS日志寫(xiě)入會(huì)開(kāi)始拖累主流程尤其是每個(gè)請(qǐng)求打多條DEBUG時(shí)更明顯。解決方案有兩個(gè)方向一是降低日志級(jí)別、減少日志事件數(shù)量二是用異步handler比如QueueHandler配合后臺(tái)線程消費(fèi)。簡(jiǎn)單可用的異步方案代碼import logging import queue from logging.handlers import QueueHandler, QueueListener log_queue queue.Queue(-1) queue_handler QueueHandler(log_queue) queue_listener QueueListener( queue_handler, file_handler, console_handler, respect_handler_levelTrue, ) queue_listener.start()把queue_listener.start()放在擴(kuò)展的engine_started里然后把queue_handler作為root logger的唯一handler。這樣主線程把日志事件丟進(jìn)隊(duì)列就立刻返回真正寫(xiě)文件的IO在后臺(tái)線程做。壓測(cè)下來(lái)在1200QPS的場(chǎng)景下異步方案讓爬蟲(chóng)吞吐幾乎沒(méi)有下降。但這個(gè)方案的代價(jià)是進(jìn)程退出時(shí)可能丟日志所以要在爬蟲(chóng)關(guān)閉時(shí)調(diào)用queue_listener.stop()確保隊(duì)列消費(fèi)完。這里就不展開(kāi)完整生命周期管理了生產(chǎn)使用務(wù)必在spider_closed或close_spider里處理。5.3 監(jiān)控告警日志不只是用來(lái)事后排查日志的最高級(jí)用法是變成實(shí)時(shí)監(jiān)控信號(hào)。我習(xí)慣在項(xiàng)目里實(shí)現(xiàn)一個(gè)爬蟲(chóng)心跳日志每隔固定時(shí)間如果爬蟲(chóng)還在正常產(chǎn)出item就輸出一條心跳日志如果連續(xù)多個(gè)心跳周期沒(méi)有產(chǎn)出監(jiān)控平臺(tái)就會(huì)告警。實(shí)現(xiàn)思路還是依賴(lài)Stats Collector。在上一節(jié)的SiteStats擴(kuò)展基礎(chǔ)上增加一個(gè)計(jì)時(shí)邏輯import time class HeartbeatMixin: def __init__(self, crawler, heartbeat_interval300): self.crawler crawler self.heartbeat_interval heartbeat_interval self.last_item_time time.time() def item_scraped(self, item, spider, **kwargs): self.last_item_time time.time() # 原有統(tǒng)計(jì)邏輯... def _check_heartbeat(self, spider): idle_seconds time.time() - self.last_item_time if idle_seconds self.heartbeat_interval: logger.warning( heartbeat missing: spider%s idle_seconds%s, spider.name, idle_seconds, )然后在settings里用extension連接一個(gè)定時(shí)信號(hào)或者更簡(jiǎn)單地在item_scraped里檢查時(shí)間差。因?yàn)榕老x(chóng)總是在處理item所以這個(gè)檢查不需要額外定時(shí)器。如果爬蟲(chóng)卡死item_scraped本身就不會(huì)觸發(fā)但heartbeat missing日志也會(huì)消失所以需要外部監(jiān)控配合——監(jiān)控平臺(tái)如果沒(méi)有在5分鐘內(nèi)收到該爬蟲(chóng)的任何日志就觸發(fā)告警。這套邏輯我在多個(gè)項(xiàng)目里都用屬于投資小、回報(bào)高的一類(lèi)監(jiān)控。另一類(lèi)告警是基于錯(cuò)誤率。我會(huì)讓擴(kuò)展維護(hù)一個(gè)錯(cuò)誤狀態(tài)碼統(tǒng)計(jì)比如在一個(gè)窗口內(nèi)5xx比例超過(guò)20%就通過(guò)logger.error輸出一條特定前綴的告警日志由監(jiān)控平臺(tái)直接截獲轉(zhuǎn)發(fā)。這樣做的好處是業(yè)務(wù)告警邏輯完全收斂在爬蟲(chóng)項(xiàng)目里運(yùn)維側(cè)只需要配置一條匹配規(guī)則。6. 常見(jiàn)問(wèn)題排查實(shí)錄8個(gè)真實(shí)Case速查日志系統(tǒng)出問(wèn)題翻文檔往往沒(méi)用因?yàn)榫W(wǎng)上都是照抄配置不講為什么。下面這8個(gè)Case是我這幾年實(shí)際遇到過(guò)的整理成速查表?，F(xiàn)象直接原因解決辦法設(shè)置了LOG_FILE但文件是空的LOG_ENABLED被改成False檢查settings和啟動(dòng)參數(shù)控制臺(tái)突然沒(méi)有日志設(shè)置了LOG_FILE后默認(rèn)只寫(xiě)文件按第4章方式自定義雙handler日志隔一段時(shí)間翻倍增長(zhǎng)自定義擴(kuò)展重復(fù)添加handler先remove再add做冪等處理磁盤(pán)被日志撐爆使用了LOG_FILE沒(méi)有輪轉(zhuǎn)用TimedRotatingFileHandler日志中文亂碼FileHandler默認(rèn)編碼不對(duì)LOG_ENCODINGutf-8 或創(chuàng)建handler時(shí)指定日志級(jí)別改了不生效命令行-L參數(shù)優(yōu)先級(jí)更高檢查crawl命令完整參數(shù)某些中間件的日志看不到該中間件用的是第三方logger確認(rèn)root logger級(jí)別必要時(shí)單獨(dú)設(shè)level爬蟲(chóng)崩了但日志里沒(méi)有堆棧異常發(fā)生在信號(hào)回調(diào)里被吞掉在擴(kuò)展和信號(hào)處理里增加try/except并logger.exception逐條展開(kāi)說(shuō)一些寶貴經(jīng)驗(yàn)。第一個(gè)設(shè)置LOG_FILE后文件為空我排查過(guò)好幾次最后發(fā)現(xiàn)是settings.py里某個(gè)環(huán)境判斷邏輯在這個(gè)環(huán)境下把LOG_ENABLED設(shè)成了False。不要覺(jué)得這個(gè)配置沒(méi)人動(dòng)生產(chǎn)環(huán)境經(jīng)常有多套配置互相覆蓋。第二個(gè)控制臺(tái)沒(méi)日志很多人以為是代碼問(wèn)題其實(shí)是Scrapy文件或控制臺(tái)二選一的默認(rèn)邏輯。如果你既想保留控制臺(tái)輸出又想寫(xiě)文件就別用LOG_FILE改用自定義handler。第三個(gè)日志翻倍增長(zhǎng)。這個(gè)最有隱蔽性因?yàn)椴皇菆?bào)錯(cuò)只是日志從某次上線后突然暴增。最后查到是一個(gè)監(jiān)控?cái)U(kuò)展重復(fù)執(zhí)行了root.addHandler每注冊(cè)一次就多一個(gè)handler同一條日志被寫(xiě)N遍。解決辦法是在addHandler之前先遍歷移除同類(lèi)handler或者維護(hù)一個(gè)標(biāo)志變量。第四個(gè)磁盤(pán)被日志撐爆就是第一章的場(chǎng)景。不重復(fù)了。第五個(gè)中文亂碼。Scrapy的LOG_FILE用的是系統(tǒng)默認(rèn)編碼在有些服務(wù)器上是ASCII中文直接變成問(wèn)號(hào)或拋異常。設(shè)置LOG_ENCODING utf-8即可。自定義handler時(shí)記得在FileHandler(..., encodingutf-8)里顯式指定。第六個(gè)日志級(jí)別不生效。有一回我一個(gè)爬蟲(chóng)里設(shè)置custom_settings {LOG_LEVEL: DEBUG}但跑起來(lái)還是INFO。原因是我在命令行用了-L INFO命令行優(yōu)先級(jí)高于custom_settings。所以要檢查完整啟動(dòng)命令別只盯著代碼。第七個(gè)第三方庫(kù)日志丟失。常見(jiàn)的比如selenium的webdriver_manager日志、requests的urllib3日志。Scrapy的root logger默認(rèn)會(huì)捕獲它們但有些庫(kù)創(chuàng)建了獨(dú)立的logger并設(shè)置了propagate False導(dǎo)致日志不會(huì)冒泡到root。處理辦法是顯式設(shè)置該logger的級(jí)別和handler比如logging.getLogger(urllib3).setLevel(logging.WARNING)。第八個(gè)爬蟲(chóng)崩了但沒(méi)堆棧。這個(gè)坑在自定義信號(hào)回調(diào)里最典型。信號(hào)回調(diào)如果拋出異常經(jīng)常會(huì)被Twisted的日志系統(tǒng)捕獲并打到一個(gè)獨(dú)立的logger里如果不仔細(xì)看你只會(huì)看到spider關(guān)閉不知道異常在哪。我在所有擴(kuò)展的公共方法里都加了兜底def _safe_log(self, func, *args, **kwargs): try: func(*args, **kwargs) except Exception: logger.exception(extension method failed: %s, func.__name__)日志系統(tǒng)本身的故障不能影響爬蟲(chóng)主流程這是生產(chǎn)環(huán)境的底線。最后再分享一個(gè)小技巧。排查日志問(wèn)題時(shí)我通常會(huì)先在本地用scrapy crawl myspider -L DEBUG -s LOG_ENABLEDTrue跑一小段把全部日志落到一個(gè)臨時(shí)文件里然后對(duì)比生產(chǎn)環(huán)境的差異。這比直接改生產(chǎn)配置快很多。生產(chǎn)環(huán)境配置日志是個(gè)慢功夫一次配好、持續(xù)觀察、逐步優(yōu)化比出問(wèn)題再救火舒服太多了。希望這篇內(nèi)容能讓你在配置Scrapy日志時(shí)少踩幾個(gè)坑。