【Scrapyクローラログ】Scrapyにおけるログ出力 ~ログはMiddlewareに実装すべし~【後編】

本記事はシリーズとなっております。前編と中編は以下。

【前編】
[【Scrapyクローラログ】クローリングにおけるログ出力の考え方【前編】](https://qiita.com/realmadridmarcelo/items/b4a8a183682efcf68d13)
【中編】
[【Scrapyクローラログ】クローラログ設計ベストプラクティス【中編】](https://qiita.com/realmadridmarcelo/items/56db8e5acab682e1a2ef)
# 目次
1. こんにちは!
1. ログ出力は```middleware.py```に実装すべし!
1. ログの実装方法概観
    1. 【悪手1】 都度ログ
    1. 【悪手2】 ログ用ラッパー関数を用いる
1. middleware.pyの役割

# こんにちは！
株式会社 Panta Rhei CEOのかずです。[Pandasista](https://x.com/sotsogprinciple)というハンネでツイッターをやっています。pandas大好きです。データも好き。

![IMG_0587.JPG](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/540865/4df3af57-b0b2-6061-682e-68e174192f26.jpeg)

[Qiita Engineer Festa 2024](https://qiita.com/official-campaigns/engineer-festa/2024)という素敵なイベントに参加して、景品目指して記事投稿を頑張っています！
本日は<B>5報目</B>となります！

# ログ出力は```middleware.py```に実装すべし！
本記事を読んでいる方はScrapyに興味があるか、もしくは実際に実装に携わる方だと思います。
Scrapyに関する入門は「[10分で理解するScrapy](https://qiita.com/Chanmoro/items/f4df85eb73b18d902739)」に解説を譲るとします。(本記事はScrapyバイブルです(個人の感想)。Scrapy version 2.0系の公式日本語ドキュメントがない今(2024-07-06現在)、多くのScrapy入門者の方がこれを参照すると思います。)

結論から言うと、ログ実装はScrapyの

<B><font color='Gree'>```Middleware.py```に記述すべき</font></B>
です。

# ログの実装方法概観
ログにはさまざまな実装方法があります。
- 都度ログを吐き出したいところに```logger.error("hoge")```する
- ログをラッパー関数に記述し、各関数やクラスでデコレータとして実装する
などがあると思います。
ことScrapyにおいては上記2種類は悪手と言えます。

## 【悪手1】 都度ログ
これはどんな場所でもアンチパターンになりますね。
```
logger.info("hoge")
```
をScrapyの至る所に打っとくイメージです。
保守性最悪ですし再現性も最悪です。
## 【悪手2】 ログ用ラッパー関数を用いる
これは結構いろんなアプリケーションに採用される実装で、
アプリケーションとかオレオレ関数やクラスがたくさんある環境であればこれは採用候補に上がります。

```Python
from logging import getLogger
def logger(f):
    def _wrapper(*args, **keywords):
        logger = getLogger(f.__name__)
        logging.basicConfig(filename='scrape.log', level=logging.INFO)
        logger.info(f'{f.__name__} starts.')
        logger.info(f'OPEN: %(asctime)s')
        v = f(*args, **keywords)
        logger.info(f'CLOSE: %(asctime)s')
        logger.info(f'CLOSE: {v}')
        return v
    return _wrapper
```

といった形でデコレータ関数を作って、実行したいクローラクラスにつけていきます。

```Python
class Crawl(scrapy.Spider):
    name = 'crawl'
    @logger
    def parse(self):
        yield scrapy.Request(url="https://example.com")
```

みたいな使い方です。
デコレータ関数を作ってしまえばさまざまな関数やクラスに```@logger```とするだけで同様の処理が期待できるので再現性(≒再利用可能性)があって良きです。
ただ、このデコレータ関数によるログ実装、Scrapyとは非常に相性が悪いです。
というのも、Scrapyはクローリングフレームワークであり、各関数が高度にモジュール化されています。
そのため、<B>そのモジュール内の各処理にログをつけるということはデコレータでは実現しにくい</B>のです。

例えば「```example.com```にGETリクエストを送った際のレスポンスをログとして出したい」といった際、Scrapyの実装ではそれが実装できません。
結局各リクエストやパースを関数化してデコレータを付与することになりますが、それだと【悪手1】で記したアンチパターンと同じになってしまいます。

ちなみに、クローラの実装においてログを付けるべき場所について、[【Scrapyクローラログ】クローラログ設計ベストプラクティス【中編】](https://qiita.com/realmadridmarcelo/items/56db8e5acab682e1a2ef)に記載しています。

ここまで来て、
- <B><font color='Gree'>一つの変更で全てをログを反映</font></B>
- <B><font color='Gree'>リクエストやパースそれぞれにログをつけたい</font></B>

という要件が見えてきます。

# middleware.pyの役割

その要件を満たすのが、
<B><font color='Gree'>Scrapyのmiddleware.py</font></B>です。

![scrapy_architecture_02.jpeg](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/540865/b549a0e8-7e98-d2aa-656f-fd64a807002c.jpeg)
*[Scrapyのアーキテクチャ概観](https://doc-ja-scrapy.readthedocs.io/ja/latest/topics/architecture.html)*

この図はScrapy公式ドキュメントに載っているScrapyのアーキテクチャ概観です。
図中の青紫の部分にMIDDLEWAREが見えるかと思います。
2つあります。
- SPIDERの入出力にいっちょ噛みするMIDDLEWARE
- DOWNLOADERの入出力にいっちょ噛みするMIDDLEWARE

それぞれはクラスとしてScrapy上で事前定義されており、以下のメソッドを持ちます。

|クラス|関数名|種別|処理の概要|引数|
|---|---|---|---|---|
|SpiderMiddleware|from_crawler|クラスメソッド||crawler|
|SpiderMiddleware|process_spider_input|メソッド||response, spider|
|SpiderMiddleware|process_spider_output|メソッド||response, result, spider|
|SpiderMiddleware|process_spider_exception|メソッド||response, exception, spider|
|SpiderMiddleware|process_start_requests|メソッド||start_requests, spider|
|SpiderMiddleware|spider_opened|メソッド||spider_opened|
|DownloaderMiddleware|from_crawler|クラスメソッド||crawler|
|DownloaderMiddleware|process_request|メソッド||response, spider|
|DownloaderMiddleware|process_response|メソッド||request, response, spider|
|DownloaderMiddleware|process_exception|メソッド||request, exception, spider|
|DownloaderMiddleware|spider_opened|メソッド||spiderspider|

この中で
- <B>SpiderMiddleware</B>は<font color="Gree">パースしたHTML要素に関するログ出力</font>
- <B>DownloaderMiddleware</B>は<font color="Gree">リクエストに関するログ出力</font>
が最適です。

# 実装例
本記事では「DownloaderMiddlewareにリクエストログ」を例に、実装例を紹介します。
ここで、ログを実装すべきメソッドは```from_crawler```です。
```from_crawler```は、

```bash
scrapy crawl {媒体名}
```
を実行した時に、一番最初に実行されるメソッドです。
従って、ここにログの出力を記述しておかないと、
- ログの出力漏れ
- クロールのそれぞれのステップでの面倒なログ実装
を引き起こしてしまいます。


```Python
class DownloaderMiddleware:
    # Not all methods need to be defined. If a method is not defined,
    # scrapy acts as if the downloader middleware does not modify the
    # passed objects.
    log_level_by_status_code = {   
        "log_level_by_status_code": {
            "INFO": [
                100, 101, 102,
                200, 201, 202, 203, 204, 205, 206, 207,
                300, 301, 302, 303, 304, 305, 307, 308
            ],
            "WARNING": [
                500, 501, 502, 503, 504, 505,
                506, 507, 508, 510, 511
            ],
            "ERROR": [
                400, 401, 402, 403, 404, 405, 406, 407,
                408, 409, 410, 411, 412, 413, 414, 415,
                416, 417, 418, 421, 422, 423, 424, 425,
                426, 428, 429, 431, 451
            ]
        }
    }
    @classmethod
    def from_crawler(cls, crawler):
        s = cls()
        current_time = datetime.now(timezone('Asia/Tokyo')).strftime('%Y-%m-%d_%H:%M:%S_%Z%z')
        log_directory = f"/var/log/scrapy/{crawler.spider.name}"
        if not os.path.exists(log_directory):
            os.makedirs(log_directory)
        logfile_name = log_directory + "/" + f"{current_time}.log"
        log_settings = {
            "LOG_FILE"          : logfile_name,
            "LOG_FILE_APPEND"   : True,
            "LOG_ENABLED"       : True,
            "LOG_LEVEL"         : logging.INFO,
            # "LOG_FORMAT"        : ,
            "LOG_STDOUT"        : True,
            }
        configure_logging(
            settings=log_settings,
            install_root_handler=True)
        crawler.signals.connect(s.spider_opened, signal=signals.spider_opened)
        return s

```

上から解説をしていきます。

```Python
class DownloaderMiddleware:
    # Not all methods need to be defined. If a method is not defined,
    # scrapy acts as if the downloader middleware does not modify the
    # passed objects.
    log_level_by_status_code = {   
        "log_level_by_status_code": {
            "INFO": [
                100, 101, 102,
                200, 201, 202, 203, 204, 205, 206, 207,
                300, 301, 302, 303, 304, 305, 307, 308
            ],
            "WARNING": [
                500, 501, 502, 503, 504, 505,
                506, 507, 508, 510, 511
            ],
            "ERROR": [
                400, 401, 402, 403, 404, 405, 406, 407,
                408, 409, 410, 411, 412, 413, 414, 415,
                416, 417, 418, 421, 422, 423, 424, 425,
                426, 428, 429, 431, 451
            ]
        }
    }
```
```DownloaderMiddleware```クラスを定義して、どんなステータスコードにどんなログステータスを付与するかを決めています。

```
    @classmethod
    def from_crawler(cls, crawler):
        s = cls()
```
```@classmethod```は「クラスメソッド」と呼ばれるPython標準のデコレータです。
クラスに引っ付いたメソッドをクラスメソッド化します。
詳しくは[こちら](https://blog.pyq.jp/entry/Python_kaiketsu_190205)をご覧ください。

クラスメソッドなので、```cls```は自前のクラス、すなわち```DownloaderMiddleware```そのものです。```crawler```引数は、その名の通りクローラオブジェクトで、[さまざまなメソッド](https://docs.scrapy.org/en/latest/topics/api.html#scrapy.crawler.Crawler)を持っています。

```Python
        current_time = datetime.now(timezone('Asia/Tokyo')).strftime('%Y-%m-%d_%H:%M:%S_%Z%z')
        log_directory = f"/var/log/scrapy/{crawler.spider.name}"
        if not os.path.exists(log_directory):
            os.makedirs(log_directory)
        logfile_name = log_directory + "/" + f"{current_time}.log"
```
1行目は、クロールの時間をログファイル名にするため時間を取得しています。
2~5行目はログファイルのディレクトリ生成やファイル名を指定しています。

```Python
        log_settings = {
            "LOG_FILE"          : logfile_name,
            "LOG_FILE_APPEND"   : True,
            "LOG_ENABLED"       : True,
            "LOG_LEVEL"         : logging.INFO,
            # "LOG_FORMAT"        : ,
            "LOG_STDOUT"        : True,
            }
        configure_logging(
            settings=log_settings,
            install_root_handler=True)
```
ここはログの詳細の設定をする部分です。Scrapyで対応している設定変数は[こちら](https://docs.scrapy.org/en/latest/topics/logging.html#logging-settings)を参考にしてください。

~~ここで大事になってくるのが、「<B><font color="Red">LOG_DATEFORMATは用いない</font></B>」という部分です。~~

~~<B>Timezoneが設定できません。</B>~~

~~これはクローラログではなかなか最悪です。例えば海外のサイトをクロールする際、クローラを乗せるクラウドインスタンスのリージョンはその現地のものにすることがあります。これはクロール先が自国由来のIPしか許していない場合などが原因となります。~~

~~そうなると、どのタイムゾーンでクロールをしたかの情報は時間データに付随する形で欲しくなりますね。~~

取れました(2024/07/02)。([参考](https://docs.scrapy.org/en/latest/topics/settings.html#log-dateformat))

```configure_logging```は「デフォルトのScrapyのログ設定」をいじるための関数です。
```settings```の内容を反映しつつ、```settings```に無い設定項目はデフォルトを用いてくれるため、非常に使い勝手が良いです。

```
crawler.signals.connect(s.spider_opened, signal=signals.spider_opened)
```
```signals```は特定のイベントが発生した時にログ出力するようなメソッドとなっています。
ここでは、「```spider_opened```のMiddlewareを呼び出しながら、```signals.spider_opened```というイベントが発生したよ」とログ出力しています。

以下のようなログが出力されます。

```
2024-06-27 17:38:44 [scrapy.core.engine] INFO: Spider opened
```

# まとめ
- パースに関するログ出力は```middlewares.py```の```SpiderMiddleware```クラスの```process_spider_output```メソッドに実装しよう!
- リクエストに関するログ出力実装は```middlewares.py```の```DownloaderMiddleware```クラスの```from_crawler```クラスメソッドに実装しよう!

となります。

# 結言
[株式会社 Panta Rhei](https://www.pantarhei.co.jp/)では「Everything Analysable」を標榜とし、世の中にあるあらゆる定性的な対象をAIによって定量化する事業をおこなっております。
AIに召し上がっていただく綺麗なデータを作る、データフローを整形するなどの課題や、そもそものAIの内製化等、挑戦したい試みがあればぜひご一報ください！