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