Pythonのライブラリが出力するログを活用しよう

Posted by rhoboro on 2020-12-29

こちらはRevComm Advent Calendar 2020の20日目の記事の予備として書いていたものです。 実際の20日目の記事はたった1行から始めるPythonのAST(抽象構文木)入門が間に合ったのでそちらにしましたが、このまま眠らせるのはもったいないのでこちらの個人ブログで公開します。

この記事ではちょっと便利なPythonの小ネタとして、デバッグ時におけるloggingモジュールの使い方を紹介します。

loggingモジュール

普段からPythonを書いてる方でも、loggingモジュールについては何となく使っているという方も多いのではないでしょうか。 ログはとりあえず次のように書くと「おまじない」として覚えてる方も多いでしょう。

import logging

logger = logging.getLogger(__name__)
...
logger.info("it worked.")

実際のところ、この書き方はログを出力する方法としてはとても理にかなっています。

しかし、ログが真価を発揮するのは「ログを出力したとき」ではなく「出力されたログがそれを必要としている人に届いたとき」です。

特に慣れない外部ライブラリを使った開発では、loggingの仕組みを知っているのと知らないのとではデバッグ時の効率が大きく変わります。 Pythonのloggingの仕組みを知り、効率的なデバッグをしていきましょう。

この記事で扱うコード

この記事では次のコードを題材として使います。 AWS S3からオブジェクトを取得するだけの簡単なコードですが、Python向けAWS SDKのboto3という外部ライブラリを使っています。 手元で動かす場合は事前にpip3 install boto3を実行してください。

import boto3

def get_object(bucket: str, key: str):
    client = boto3.client("s3")
    response = client.get_object(
        Bucket=bucket,
        Key=key,
    )
    return response


def main():
    res = get_object("rhoboro-logging-and-debug", "somefile.txt")
    print(res["Body"].read())


if __name__ == "__main__":
    main()

なお、このコードが正しく動いたときの実行結果は次のようになります。

$ python3 s3.py
b'logging-and-debug\n'

さて、いま実際にコードを実行してみたところ、期待する結果とは異なりエラーが発生しました。

$ python3 s3.py
Traceback (most recent call last):
  File "/Users/rhoboro/go/src/github.com/rhoboro/blog/s3.py", line 23, in <module>
    main()
  File "/Users/rhoboro/go/src/github.com/rhoboro/blog/s3.py", line 18, in main
    res = get_object("rhoboro-logging-and-debug", "somefile.txt")
  File "/Users/rhoboro/go/src/github.com/rhoboro/blog/s3.py", line 10, in get_object
    response = client.get_object(
  File "/Users/rhoboro/go/src/github.com/rhoboro/blog/env/lib/python3.9/site-packages/botocore/client.py", line 357, in _api_call
    return self._make_api_call(operation_name, kwargs)
  File "/Users/rhoboro/go/src/github.com/rhoboro/blog/env/lib/python3.9/site-packages/botocore/client.py", line 676, in _make_api_call
    raise error_class(parsed_response, operation_name)
botocore.exceptions.ClientError: An error occurred (AccessDenied) when calling the GetObject operation: Access Denied

最後に「Access Denied」と出ているので権限周りに問題があるようです。

ログを表示してみる

権限周りの問題のようなので、意図した認証情報が使われているか調べるためにライブラリが出力しているログを利用できます。 次のように変更し、 ログを表示させて確認してみましょう。

+ import logging
  import boto3

+ root_logger = logging.getLogger()
+ root_logger.setLevel(logging.DEBUG)
+ root_logger.addHandler(logging.StreamHandler())

  ...

このコードを実行すると、次のように大量のログが表示されます。1 実はこれまで表示されていなかっただけで、実際にはたくさんのログが出力されていたのです。

$ python3 s3.py
Changing event name from creating-client-class.iot-data to creating-client-class.iot-data-plane
Changing event name from before-call.apigateway to before-call.api-gateway
Changing event name from request-created.machinelearning.Predict to request-created.machine-learning.Predict
Changing event name from before-parameter-build.autoscaling.CreateLaunchConfiguration to before-parameter-build.auto-scaling.CreateLaunchConfiguration
...
出力の全文はこちら 
$ python3 s3.py
Changing event name from creating-client-class.iot-data to creating-client-class.iot-data-plane
Changing event name from before-call.apigateway to before-call.api-gateway
Changing event name from request-created.machinelearning.Predict to request-created.machine-learning.Predict
Changing event name from before-parameter-build.autoscaling.CreateLaunchConfiguration to before-parameter-build.auto-scaling.CreateLaunchConfiguration
Changing event name from before-parameter-build.route53 to before-parameter-build.route-53
Changing event name from request-created.cloudsearchdomain.Search to request-created.cloudsearch-domain.Search
Changing event name from docs.*.autoscaling.CreateLaunchConfiguration.complete-section to docs.*.auto-scaling.CreateLaunchConfiguration.complete-section
Changing event name from before-parameter-build.logs.CreateExportTask to before-parameter-build.cloudwatch-logs.CreateExportTask
Changing event name from docs.*.logs.CreateExportTask.complete-section to docs.*.cloudwatch-logs.CreateExportTask.complete-section
Changing event name from before-parameter-build.cloudsearchdomain.Search to before-parameter-build.cloudsearch-domain.Search
Changing event name from docs.*.cloudsearchdomain.Search.complete-section to docs.*.cloudsearch-domain.Search.complete-section
IMDS ENDPOINT: http://169.254.169.254/
Looking for credentials via: env
Looking for credentials via: assume-role
Looking for credentials via: assume-role-with-web-identity
Looking for credentials via: sso
Looking for credentials via: shared-credentials-file
Found credentials in shared credentials file: ~/.aws/credentials
Loading JSON file: /Users/rhoboro/go/src/github.com/rhoboro/blog/env/lib/python3.9/site-packages/botocore/data/endpoints.json
Event choose-service-name: calling handler <function handle_service_name_alias at 0x7ff0c01f8310>
Loading JSON file: /Users/rhoboro/go/src/github.com/rhoboro/blog/env/lib/python3.9/site-packages/botocore/data/s3/2006-03-01/service-2.json
Event creating-client-class.s3: calling handler <function add_generate_presigned_post at 0x7ff0c01a3160>
Event creating-client-class.s3: calling handler <function lazy_call.<locals>._handler at 0x7ff0c02bf8b0>
Event creating-client-class.s3: calling handler <function add_generate_presigned_url at 0x7ff0c01a7ee0>
Setting s3 timeout as (60, 60)
Loading JSON file: /Users/rhoboro/go/src/github.com/rhoboro/blog/env/lib/python3.9/site-packages/botocore/data/_retry.json
Registering retry handlers for service: s3
Event before-parameter-build.s3.GetObject: calling handler <function sse_md5 at 0x7ff0c0220790>
Event before-parameter-build.s3.GetObject: calling handler <function validate_bucket_name at 0x7ff0c0220700>
Event before-parameter-build.s3.GetObject: calling handler <bound method S3RegionRedirector.redirect_from_cache of <botocore.utils.S3RegionRedirector object at 0x7ff0e06d56a0>>
Event before-parameter-build.s3.GetObject: calling handler <bound method S3ArnParamHandler.handle_arn of <botocore.utils.S3ArnParamHandler object at 0x7ff0e06d56d0>>
Event before-parameter-build.s3.GetObject: calling handler <function generate_idempotent_uuid at 0x7ff0c0220550>
Event before-call.s3.GetObject: calling handler <function add_expect_header at 0x7ff0c0220a60>
Event before-call.s3.GetObject: calling handler <bound method S3RegionRedirector.set_request_url of <botocore.utils.S3RegionRedirector object at 0x7ff0e06d56a0>>
Event before-call.s3.GetObject: calling handler <function inject_api_version_header_if_needed at 0x7ff0c0226dc0>
Making request for OperationModel(name=GetObject) with params: {'url_path': '/rhoboro-logging-and-debug/somefile.txt', 'query_string': {}, 'method': 'GET', 'headers': {'User-Agent': 'Boto3/1.16.25 Python/3.9.0 Darwin/19.6.0 Botocore/1.19.25'}, 'body': b'', 'url': 'https://s3.amazonaws.com/rhoboro-logging-and-debug/somefile.txt', 'context': {'client_region': 'us-east-1', 'client_config': <botocore.config.Config object at 0x7ff0e04d4a00>, 'has_streaming_input': False, 'auth_type': None, 'signing': {'bucket': 'rhoboro-logging-and-debug'}}}
Event request-created.s3.GetObject: calling handler <bound method RequestSigner.handler of <botocore.signers.RequestSigner object at 0x7ff0e04d4400>>
Event choose-signer.s3.GetObject: calling handler <bound method ClientCreator._default_s3_presign_to_sigv2 of <botocore.client.ClientCreator object at 0x7ff0c02bc220>>
Event choose-signer.s3.GetObject: calling handler <function set_operation_specific_signer at 0x7ff0c0220430>
Event before-sign.s3.GetObject: calling handler <bound method S3EndpointSetter.set_endpoint of <botocore.utils.S3EndpointSetter object at 0x7ff0e06d5790>>
Defaulting to S3 virtual host style addressing with path style addressing fallback.
Checking for DNS compatible bucket for: https://s3.amazonaws.com/rhoboro-logging-and-debug/somefile.txt
URI updated to: https://rhoboro-logging-and-debug.s3.amazonaws.com/somefile.txt
Calculating signature using v4 auth.
CanonicalRequest:
GET
/somefile.txt

host:rhoboro-logging-and-debug.s3.amazonaws.com
x-amz-content-sha256:e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
x-amz-date:20201127T142611Z

host;x-amz-content-sha256;x-amz-date
e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
StringToSign:
AWS4-HMAC-SHA256
20201127T142611Z
20201127/us-east-1/s3/aws4_request
2eef796df924232ab870fda2ca8b67d7ed263276896d2349b79f50c2634ba9d4
Signature:
d8f3faa7dc5b1f19879443ca5c0f0d8cdf36b3eefdb136bde117355de5cc112b
Sending http request: <AWSPreparedRequest stream_output=True, method=GET, url=https://rhoboro-logging-and-debug.s3.amazonaws.com/somefile.txt, headers={'User-Agent': b'Boto3/1.16.25 Python/3.9.0 Darwin/19.6.0 Botocore/1.19.25', 'X-Amz-Date': b'20201127T142611Z', 'X-Amz-Content-SHA256': b'e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855', 'Authorization': b'AWS4-HMAC-SHA256 Credential=AKIA5ZD7N73MBS6ZW7ZO/20201127/us-east-1/s3/aws4_request, SignedHeaders=host;x-amz-content-sha256;x-amz-date, Signature=d8f3faa7dc5b1f19879443ca5c0f0d8cdf36b3eefdb136bde117355de5cc112b'}>
Starting new HTTPS connection (1): rhoboro-logging-and-debug.s3.amazonaws.com:443
https://rhoboro-logging-and-debug.s3.amazonaws.com:443 "GET /somefile.txt HTTP/1.1" 403 None
Response headers: {'x-amz-request-id': '4EAC1FD477BCC564', 'x-amz-id-2': 'OKFGCBpytBDxfzzNTXH0UVjZEMVEK6WtTUMCVzkVoKy7nMAEBqXhZsCDIv6o1r4u69NfCzvWRAE=', 'Content-Type': 'application/xml', 'Transfer-Encoding': 'chunked', 'Date': 'Fri, 27 Nov 2020 14:26:12 GMT', 'Server': 'AmazonS3'}
Response body:
b'<?xml version="1.0" encoding="UTF-8"?>\n<Error><Code>AccessDenied</Code><Message>Access Denied</Message><RequestId>4EAC1FD477BCC564</RequestId><HostId>OKFGCBpytBDxfzzNTXH0UVjZEMVEK6WtTUMCVzkVoKy7nMAEBqXhZsCDIv6o1r4u69NfCzvWRAE=</HostId></Error>'
Event needs-retry.s3.GetObject: calling handler <botocore.retryhandler.RetryHandler object at 0x7ff0e06d5610>
No retry needed.
Event needs-retry.s3.GetObject: calling handler <bound method S3RegionRedirector.redirect_from_error of <botocore.utils.S3RegionRedirector object at 0x7ff0e06d56a0>>
Traceback (most recent call last):
  File "/Users/rhoboro/go/src/github.com/rhoboro/blog/s3.py", line 23, in <module>
    main()
  File "/Users/rhoboro/go/src/github.com/rhoboro/blog/s3.py", line 18, in main
    res = get_object("rhoboro-logging-and-debug", "somefile.txt")
  File "/Users/rhoboro/go/src/github.com/rhoboro/blog/s3.py", line 10, in get_object
    response = client.get_object(
  File "/Users/rhoboro/go/src/github.com/rhoboro/blog/env/lib/python3.9/site-packages/botocore/client.py", line 357, in _api_call
    return self._make_api_call(operation_name, kwargs)
  File "/Users/rhoboro/go/src/github.com/rhoboro/blog/env/lib/python3.9/site-packages/botocore/client.py", line 676, in _make_api_call
    raise error_class(parsed_response, operation_name)
botocore.exceptions.ClientError: An error occurred (AccessDenied) when calling the GetObject operation: Access Denied

必要なログのみ表示させる

ログの表示はできましたが、思っていた以上に大量のログが表示されています。 そこで、必要なログのみを表示させていきましょう。

ロガーの名前を調べる

まず、コードを次のように変更します。 このコードはログ出力時のフォーマットを変更しており、ログとともにそのログを出力しているロガーの名前を一緒に表示します。 これはつまり、ログを出力するロガーにはそれぞれ名前がついているということです。 なお、フォーマット内で使える変数は公式ドキュメントのLogRecord 属性に一覧があります。

  import logging
  import boto3

  root_logger = logging.getLogger()
  root_logger.setLevel(logging.DEBUG)
- root_logger.addHandler(logging.StreamHandler())
+ handler = logging.StreamHandler()
+ handler.setFormatter(logging.Formatter("%(name)s🍎 %(message)s"))
+ root_logger.addHandler(handler)

  ...

それでは実行してみましょう。 出力内容はさきほどとほぼ同じですが、🍎とともにロガーの名前が出力されています。

実際に表示された名前を見ていくと、botocore.hooks、botocore.utils、botocore.credentials...urllib3.connectionpoolなどがありました。 Pythonではこのようにロガーの名前はドット区切りの文字列となります。

$ python3 s3.py
botocore.hooks🍎 Changing event name from creating-client-class.iot-data to creating-client-class.iot-data-plane
botocore.hooks🍎 Changing event name from before-call.apigateway to before-call.api-gateway
botocore.hooks🍎 Changing event name from request-created.machinelearning.Predict to request-created.machine-learning.Predict
botocore.hooks🍎 Changing event name from before-parameter-build.autoscaling.CreateLaunchConfiguration to before-parameter-build.auto-scaling.CreateLaunchConfiguration
...
出力の全文はこちら 
$ python3 s3.py
botocore.hooks🍎 Changing event name from creating-client-class.iot-data to creating-client-class.iot-data-plane
botocore.hooks🍎 Changing event name from before-call.apigateway to before-call.api-gateway
botocore.hooks🍎 Changing event name from request-created.machinelearning.Predict to request-created.machine-learning.Predict
botocore.hooks🍎 Changing event name from before-parameter-build.autoscaling.CreateLaunchConfiguration to before-parameter-build.auto-scaling.CreateLaunchConfiguration
botocore.hooks🍎 Changing event name from before-parameter-build.route53 to before-parameter-build.route-53
botocore.hooks🍎 Changing event name from request-created.cloudsearchdomain.Search to request-created.cloudsearch-domain.Search
botocore.hooks🍎 Changing event name from docs.*.autoscaling.CreateLaunchConfiguration.complete-section to docs.*.auto-scaling.CreateLaunchConfiguration.complete-section
botocore.hooks🍎 Changing event name from before-parameter-build.logs.CreateExportTask to before-parameter-build.cloudwatch-logs.CreateExportTask
botocore.hooks🍎 Changing event name from docs.*.logs.CreateExportTask.complete-section to docs.*.cloudwatch-logs.CreateExportTask.complete-section
botocore.hooks🍎 Changing event name from before-parameter-build.cloudsearchdomain.Search to before-parameter-build.cloudsearch-domain.Search
botocore.hooks🍎 Changing event name from docs.*.cloudsearchdomain.Search.complete-section to docs.*.cloudsearch-domain.Search.complete-section
botocore.utils🍎 IMDS ENDPOINT: http://169.254.169.254/
botocore.credentials🍎 Looking for credentials via: env
botocore.credentials🍎 Looking for credentials via: assume-role
botocore.credentials🍎 Looking for credentials via: assume-role-with-web-identity
botocore.credentials🍎 Looking for credentials via: sso
botocore.credentials🍎 Looking for credentials via: shared-credentials-file
botocore.credentials🍎 Found credentials in shared credentials file: ~/.aws/credentials
botocore.loaders🍎 Loading JSON file: /Users/rhoboro/go/src/github.com/rhoboro/blog/env/lib/python3.9/site-packages/botocore/data/endpoints.json
botocore.hooks🍎 Event choose-service-name: calling handler <function handle_service_name_alias at 0x7fcdf01d9280>
botocore.loaders🍎 Loading JSON file: /Users/rhoboro/go/src/github.com/rhoboro/blog/env/lib/python3.9/site-packages/botocore/data/s3/2006-03-01/service-2.json
botocore.hooks🍎 Event creating-client-class.s3: calling handler <function add_generate_presigned_post at 0x7fcdd04e30d0>
botocore.hooks🍎 Event creating-client-class.s3: calling handler <function lazy_call.<locals>._handler at 0x7fcdc028f820>
botocore.hooks🍎 Event creating-client-class.s3: calling handler <function add_generate_presigned_url at 0x7fcdd04e7e50>
botocore.endpoint🍎 Setting s3 timeout as (60, 60)
botocore.loaders🍎 Loading JSON file: /Users/rhoboro/go/src/github.com/rhoboro/blog/env/lib/python3.9/site-packages/botocore/data/_retry.json
botocore.client🍎 Registering retry handlers for service: s3
botocore.hooks🍎 Event before-parameter-build.s3.GetObject: calling handler <function sse_md5 at 0x7fcdc0220700>
botocore.hooks🍎 Event before-parameter-build.s3.GetObject: calling handler <function validate_bucket_name at 0x7fcdc0220670>
botocore.hooks🍎 Event before-parameter-build.s3.GetObject: calling handler <bound method S3RegionRedirector.redirect_from_cache of <botocore.utils.S3RegionRedirector object at 0x7fce00366880>>
botocore.hooks🍎 Event before-parameter-build.s3.GetObject: calling handler <bound method S3ArnParamHandler.handle_arn of <botocore.utils.S3ArnParamHandler object at 0x7fce003668b0>>
botocore.hooks🍎 Event before-parameter-build.s3.GetObject: calling handler <function generate_idempotent_uuid at 0x7fcdc02204c0>
botocore.hooks🍎 Event before-call.s3.GetObject: calling handler <function add_expect_header at 0x7fcdc02209d0>
botocore.hooks🍎 Event before-call.s3.GetObject: calling handler <bound method S3RegionRedirector.set_request_url of <botocore.utils.S3RegionRedirector object at 0x7fce00366880>>
botocore.hooks🍎 Event before-call.s3.GetObject: calling handler <function inject_api_version_header_if_needed at 0x7fcdc0225d30>
botocore.endpoint🍎 Making request for OperationModel(name=GetObject) with params: {'url_path': '/rhoboro-logging-and-debug/somefile.txt', 'query_string': {}, 'method': 'GET', 'headers': {'User-Agent': 'Boto3/1.16.25 Python/3.9.0 Darwin/19.6.0 Botocore/1.19.25'}, 'body': b'', 'url': 'https://s3.amazonaws.com/rhoboro-logging-and-debug/somefile.txt', 'context': {'client_region': 'us-east-1', 'client_config': <botocore.config.Config object at 0x7fcdc056abe0>, 'has_streaming_input': False, 'auth_type': None, 'signing': {'bucket': 'rhoboro-logging-and-debug'}}}
botocore.hooks🍎 Event request-created.s3.GetObject: calling handler <bound method RequestSigner.handler of <botocore.signers.RequestSigner object at 0x7fcdc056a5e0>>
botocore.hooks🍎 Event choose-signer.s3.GetObject: calling handler <bound method ClientCreator._default_s3_presign_to_sigv2 of <botocore.client.ClientCreator object at 0x7fcdc028a400>>
botocore.hooks🍎 Event choose-signer.s3.GetObject: calling handler <function set_operation_specific_signer at 0x7fcdc02203a0>
botocore.hooks🍎 Event before-sign.s3.GetObject: calling handler <bound method S3EndpointSetter.set_endpoint of <botocore.utils.S3EndpointSetter object at 0x7fce00366970>>
botocore.utils🍎 Defaulting to S3 virtual host style addressing with path style addressing fallback.
botocore.utils🍎 Checking for DNS compatible bucket for: https://s3.amazonaws.com/rhoboro-logging-and-debug/somefile.txt
botocore.utils🍎 URI updated to: https://rhoboro-logging-and-debug.s3.amazonaws.com/somefile.txt
botocore.auth🍎 Calculating signature using v4 auth.
botocore.auth🍎 CanonicalRequest:
GET
/somefile.txt

host:rhoboro-logging-and-debug.s3.amazonaws.com
x-amz-content-sha256:e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
x-amz-date:20201127T145002Z

host;x-amz-content-sha256;x-amz-date
e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
botocore.auth🍎 StringToSign:
AWS4-HMAC-SHA256
20201127T145002Z
20201127/us-east-1/s3/aws4_request
029e701b71b982e276dfd61c86d3039da98da54f2185d08b8403b054a892151f
botocore.auth🍎 Signature:
39ab9d1b96d175e12d5db9091e501146539578bba9c92f46d2c5540ce6aeb5c1
botocore.endpoint🍎 Sending http request: <AWSPreparedRequest stream_output=True, method=GET, url=https://rhoboro-logging-and-debug.s3.amazonaws.com/somefile.txt, headers={'User-Agent': b'Boto3/1.16.25 Python/3.9.0 Darwin/19.6.0 Botocore/1.19.25', 'X-Amz-Date': b'20201127T145002Z', 'X-Amz-Content-SHA256': b'e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855', 'Authorization': b'AWS4-HMAC-SHA256 Credential=AKIA5ZD7N73MBS6ZW7ZO/20201127/us-east-1/s3/aws4_request, SignedHeaders=host;x-amz-content-sha256;x-amz-date, Signature=39ab9d1b96d175e12d5db9091e501146539578bba9c92f46d2c5540ce6aeb5c1'}>
urllib3.connectionpool🍎 Starting new HTTPS connection (1): rhoboro-logging-and-debug.s3.amazonaws.com:443
urllib3.connectionpool🍎 https://rhoboro-logging-and-debug.s3.amazonaws.com:443 "GET /somefile.txt HTTP/1.1" 403 None
botocore.parsers🍎 Response headers: {'x-amz-request-id': '633EF8A039962643', 'x-amz-id-2': 'vXfHcovHx50SxCOyjRY7LlflkwbZ1SDypTfm4zlaVJly/CTezYK4+8L21EX7wZLdL/Nj5qpQ9QU=', 'Content-Type': 'application/xml', 'Transfer-Encoding': 'chunked', 'Date': 'Fri, 27 Nov 2020 14:50:02 GMT', 'Server': 'AmazonS3'}
botocore.parsers🍎 Response body:
b'<?xml version="1.0" encoding="UTF-8"?>\n<Error><Code>AccessDenied</Code><Message>Access Denied</Message><RequestId>633EF8A039962643</RequestId><HostId>vXfHcovHx50SxCOyjRY7LlflkwbZ1SDypTfm4zlaVJly/CTezYK4+8L21EX7wZLdL/Nj5qpQ9QU=</HostId></Error>'
botocore.hooks🍎 Event needs-retry.s3.GetObject: calling handler <botocore.retryhandler.RetryHandler object at 0x7fce003667f0>
botocore.retryhandler🍎 No retry needed.
botocore.hooks🍎 Event needs-retry.s3.GetObject: calling handler <bound method S3RegionRedirector.redirect_from_error of <botocore.utils.S3RegionRedirector object at 0x7fce00366880>>
Traceback (most recent call last):
  File "/Users/rhoboro/go/src/github.com/rhoboro/blog/s3.py", line 25, in <module>
    main()
  File "/Users/rhoboro/go/src/github.com/rhoboro/blog/s3.py", line 20, in main
    res = get_object("rhoboro-logging-and-debug", "somefile.txt")
  File "/Users/rhoboro/go/src/github.com/rhoboro/blog/s3.py", line 12, in get_object
    response = client.get_object(
  File "/Users/rhoboro/go/src/github.com/rhoboro/blog/env/lib/python3.9/site-packages/botocore/client.py", line 357, in _api_call
    return self._make_api_call(operation_name, kwargs)
  File "/Users/rhoboro/go/src/github.com/rhoboro/blog/env/lib/python3.9/site-packages/botocore/client.py", line 676, in _make_api_call
    raise error_class(parsed_response, operation_name)
botocore.exceptions.ClientError: An error occurred (AccessDenied) when calling the GetObject operation: Access Denied

ロガーの名前を使った絞り込み

ロガーの名前がわかれば、そのロガーの出力だけを表示させることができます。 コードを次のように変更します。 ここではbotocore.endpointという名前のロガーが出力するログのみ表示するようにしています。

  import logging
  import boto3

- root_logger = logging.getLogger()
- root_logger.setLevel(logging.DEBUG)
+ logger = logging.getLogger("botocore.endpoint")
+ logger.setLevel(logging.DEBUG)
  handler = logging.StreamHandler()
  handler.setFormatter(logging.Formatter("%(name)s🍎 %(message)s"))
- root_logger.addHandler(handler)
  logger.addHandler(handler)

  ...

実際に動かしてみると、出力されるログが減って、botocore.endpointから始まるログだけが表示されました。

$ python3 s3.py
botocore.endpoint🍎 Setting s3 timeout as (60, 60)
botocore.endpoint🍎 Making request for OperationModel(name=GetObject) with params: {'url_path': '/rhoboro-logging-and-debug/somefile.txt', 'query_string': {}, 'method': 'GET', 'headers': {'User-Agent': 'Boto3/1.16.25 Python/3.9.0 Darwin/19.6.0 Botocore/1.19.25'}, 'body': b'', 'url': 'https://s3.amazonaws.com/rhoboro-logging-and-debug/somefile.txt', 'context': {'client_region': 'us-east-1', 'client_config': <botocore.config.Config object at 0x7f9d5044dbe0>, 'has_streaming_input': False, 'auth_type': None, 'signing': {'bucket': 'rhoboro-logging-and-debug'}}}
botocore.endpoint🍎 Sending http request: <AWSPreparedRequest stream_output=True, method=GET, url=https://rhoboro-logging-and-debug.s3.amazonaws.com/somefile.txt, headers={'User-Agent': b'Boto3/1.16.25 Python/3.9.0 Darwin/19.6.0 Botocore/1.19.25', 'X-Amz-Date': b'20201127T150411Z', 'X-Amz-Content-SHA256': b'e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855', 'Authorization': b'AWS4-HMAC-SHA256 Credential=AKIA5ZD7N73MBS6ZW7ZO/20201127/us-east-1/s3/aws4_request, SignedHeaders=host;x-amz-content-sha256;x-amz-date, Signature=cc5f046ff88c8257e5ec37e6096be95274656c717ae37efcc8f65c551b3a4112'}>
Traceback (most recent call last):
  File "/Users/rhoboro/go/src/github.com/rhoboro/blog/s3.py", line 25, in <module>
    main()
  File "/Users/rhoboro/go/src/github.com/rhoboro/blog/s3.py", line 20, in main
    res = get_object("rhoboro-logging-and-debug", "somefile.txt")
  File "/Users/rhoboro/go/src/github.com/rhoboro/blog/s3.py", line 12, in get_object
    response = client.get_object(
  File "/Users/rhoboro/go/src/github.com/rhoboro/blog/env/lib/python3.9/site-packages/botocore/client.py", line 357, in _api_call
    return self._make_api_call(operation_name, kwargs)
  File "/Users/rhoboro/go/src/github.com/rhoboro/blog/env/lib/python3.9/site-packages/botocore/client.py", line 676, in _make_api_call
    raise error_class(parsed_response, operation_name)
botocore.exceptions.ClientError: An error occurred (AccessDenied) when calling the GetObject operation: Access Denied

このログをよく見ていくことで、実際に使われたアクセスキーがわかり、意図していた認証情報とは違うものが使われていることが判明しました。 そこで、正しい認証情報が使われるように修正したところうまく動きました。

このように、loggingモジュールを使うと、デバッグが効率的になる場合があります。

ロガーの構造

Pythonのロガーはドット区切りを用いることで階層構造を表現しています。 そして、下位にあるロガーは自分の上位にいるロガーの指定を引き継ぐ仕組みになっています。

最初のログ出力ではlogging.getLogger()で取得したルートロガーに出力設定を行ったため、すべてのロガーのログが表示されました。 ロガーの名前を使った絞り込みでは、logging.getLogger("botocore.endpoint")で取得したbotocore.endpointと言う名前を持つロガーに対して出力設定を行ったため、このロガー（以下）のみのログが出力されています。

また、ロガーの名前がドット区切りであることは、Pythonのモジュール（パッケージ）名がドット区切りであることと相性が良いです。 つまり、冒頭の「おまじない」のようにlogger = logging.getLogger(__name__)としてログを出力することで、ロガーを利用する側はパッケージの階層に合わせた出力設定がしやすくなります。2

まとめ

Pythonでライブラリが出力しているログを表示する方法を紹介しました。
ログのような補助的な機能は身近に慣れている人がいないと詳しく知る機会が少ないものですが、Pythonを利用する分野を問わずに使えるとても有用な機能です。 Pythonのloggingモジュールの使い方についてもっと詳しく知りたくなった方は、公式ドキュメントのLogging HOWTOから読み始めてみてください。

  1. この記事で扱っているバケットや認証情報は削除済みです。 ↩

  2. ロガーの名前がパッケージ名と一致しているとログの出力元がわかりやすいという点もメリットです。 ↩

tags: Python, logging