pysmbの使い方（ロギング）

[前回](https://qiita.com/t2kojima/items/a6b81de771ac45c9948b)まででpysmbを使った一通りの操作はできるようになったと思います。
ここではログ出力について設定方法を確認したいと思います。

# インデックス
[pysmbの使い方（接続・切断）](https://qiita.com/t2kojima/items/5db8dadaa6e07321d25f)
[pysmbの使い方（ファイル受信）](https://qiita.com/t2kojima/items/6c20a7801467221470ac)
[pysmbの使い方（ファイル送信）](https://qiita.com/t2kojima/items/a6b81de771ac45c9948b)
pysmbの使い方（ロギング）
[pysmbの使い方（匿名接続）](https://qiita.com/t2kojima/items/c84a803c73daf043f053)

# 実行環境

#### クライアント
- Windows 10
- Python 3.6.3
- pysmb 1.1.22

#### サーバー
- Windows 7
    - User : IEUser
    - Pass : Passw0rd!
    - HostName : IEWIN7
    - Domain : WORKGROUP
    - IPAddress : 172.28.0.198

# ルートロガーに出力

pysmbは結構大量にログを吐きます。

なので全部ルートロガーにぶち込んでしまうと大変なことになります。

```python
import logging
import platform
from smb.SMBConnection import SMBConnection

logging.basicConfig(filename='example.log', level=logging.DEBUG)

conn = SMBConnection(
    'IEUser',
    'Passw0rd!',
    platform.uname().node,
    'IEWIN7')
conn.connect('172.28.0.198', 139)

logging.info(conn.listPath('Share', ''))

conn.close()
```

例えばこのように`listPath()`の結果をログに出力してみましょう。
結果、このようなログが生成されます。

```text
# example.log

INFO:SMB.SMBConnection:Authentication with remote machine "***" for user "***" will be using NTLM v2 authentication (with extended security)
INFO:SMB.SMBConnection:Now switching over to SMB2 protocol communication
DEBUG:SMB.SMBConnection:Received SMB2 message "SMB2_COM_NEGOTIATE" (command:0x0000 flags:0x0001)
INFO:SMB.SMBConnection:SMB2 dialect negotiation successful
DEBUG:SMB.SMBConnection:Received SMB2 message "SMB2_COM_SESSION_SETUP" (command:0x0001 flags:0x0001)
INFO:SMB.SMBConnection:Performing NTLMv2 authentication (on SMB2) with server challenge "b'8296f385d90608ca'"
INFO:SMB.SMBConnection:Performing NTLMv2 authentication (on SMB2) with server challenge "b'8296f385d90608ca'"
DEBUG:SMB.SMBConnection:NT challenge response is "b'23758afeba21ca0bfd4b0c2a75e6693901010000000000000000000000000000555a5779214fe437000000000200100048004f004b005500490043004800490001000a004800300033003400360004001c0068006f006b00750069006300680069002e006c006f00630061006c0003002800480030003300340036002e0068006f006b00750069006300680069002e006c006f00630061006c0005001c0068006f006b00750069006300680069002e006c006f00630061006c000700080039f71c70a6dad30100000000'" (202 bytes)
DEBUG:SMB.SMBConnection:LM challenge response is "b'8ebfc0e53e42557badda2f4e86b00d54555a5779214fe437'" (24 bytes)
INFO:SMB.SMBConnection:Server supports SMB signing
INFO:SMB.SMBConnection:SMB signing deactivated. SMB messages will NOT be signed.
DEBUG:SMB.SMBConnection:Received SMB2 message "SMB2_COM_SESSION_SETUP" (command:0x0001 flags:0x0009)
INFO:SMB.SMBConnection:Authentication (on SMB2) successful!
DEBUG:SMB.SMBConnection:Received SMB2 message "SMB2_COM_TREE_CONNECT" (command:0x0003 flags:0x0001)
DEBUG:SMB.SMBConnection:Received SMB2 message "SMB2_COM_CREATE" (command:0x0005 flags:0x0001)
DEBUG:SMB.SMBConnection:Received SMB2 message "SMB2_COM_QUERY_DIRECTORY" (command:0x000E flags:0x0001)
DEBUG:SMB.SMBConnection:Received SMB2 message "SMB2_COM_QUERY_DIRECTORY" (command:0x000E flags:0x0001)
DEBUG:SMB.SMBConnection:Received SMB2 message "SMB2_COM_CLOSE" (command:0x0006 flags:0x0001)
INFO:root:[<smb.base.SharedFile object at 0x036FD450>, <smb.base.SharedFile object at 0x036FD470>, <smb.base.SharedFile object at 0x036FD490>, <smb.base.SharedFile object at 0x036FD4D0>, <smb.base.SharedFile object at 0x036FD510>, <smb.base.SharedFile object at 0x036FD550>, <smb.base.SharedFile object at 0x036FD570>, <smb.base.SharedFile object at 0x036FD590>, <smb.base.SharedFile object at 0x036FD5B0>, <smb.base.SharedFile object at 0x036FD530>, <smb.base.SharedFile object at 0x036FD5D0>]
```

`connect()`でかなり大量のログが出力されていますが、`listPath()`の1メソッドだけでも4行のログが出力されています。コネクションを閉じたり開いたり、メソッドを再帰的に呼び出したりするなどで、ログ出力の収拾がつかなくなるのは想像に難くありません。

# ロガーを分けて出力

ルートロガーに全部ぶち込んでしまうと大変でした。なのでロガーをちゃんと分けて出力してみましょう。

pysmbは`SMB.SMBConnection`という名前でログを流してくるので、個別に出力するロガーを設定してあげます。`app_name`は自分のアプリで使うロガーです。

## dictConfig

dictConfigを使うパターンです。

```python
from logging import getLogger
from logging.config import dictConfig
import platform
from smb.SMBConnection import SMBConnection

dictConfig({
    "version": 1,
    "formatters": {
        "simple": {
            "format": "%(asctime)s %(name)s %(module)s.%(funcName)s [%(levelname)s] %(message)s"
        },
    },
    "handlers": {
        "app_name": {
            "class": "logging.FileHandler",
            "level": "DEBUG",
            "formatter": "simple",
            "filename": 'app_name.log',
        },
        "smb": {
            "class": "logging.FileHandler",
            "level": "DEBUG",
            "formatter": "simple",
            "filename": 'smb.log',
        }
    },
    "root": {
        "level": "DEBUG",
        "handlers": []
    },
    'loggers': {
        "app_name": {
            "level": "DEBUG",
            "handlers": ["app_name"]
        },
        "SMB.SMBConnection": {
            "level": "DEBUG",
            "handlers": ["smb"]
        }
    },
    "disable_existing_loggers": False,
})

logger = getLogger('app_name')

conn = SMBConnection(
    'IEUser',
    'Passw0rd!',
    platform.uname().node,
    'IEWIN7')
conn.connect('172.28.0.198', 139)

logger.info(conn.listPath('Share', ''))

conn.close()
```

実行してみると、以下のようにログが分かれて出力されます。

```text
# app_name.log

2018-04-23 11:13:59,912 app_name smbtest.<module> [INFO] [<smb.base.SharedFile object at 0x03D3B790>, <smb.base.SharedFile object at 0x03D3B7B0>, <smb.base.SharedFile object at 0x03D3B7D0>, <smb.base.SharedFile object at 0x03D3B810>, <smb.base.SharedFile object at 0x03D3B850>, <smb.base.SharedFile object at 0x03D3B890>, <smb.base.SharedFile object at 0x03D3B8B0>, <smb.base.SharedFile object at 0x03D3B8D0>, <smb.base.SharedFile object at 0x03D3B8F0>, <smb.base.SharedFile object at 0x03D3B870>, <smb.base.SharedFile object at 0x03D3B910>]
```

```text
# smb.log

2018-04-23 11:13:59,896 SMB.SMBConnection base.__init__ [INFO] Authentication with remote machine "***" for user "***" will be using NTLM v2 authentication (with extended security)
2018-04-23 11:13:59,901 SMB.SMBConnection base.onNMBSessionMessage [INFO] Now switching over to SMB2 protocol communication
2018-04-23 11:13:59,902 SMB.SMBConnection base.onNMBSessionMessage [DEBUG] Received SMB2 message "SMB2_COM_NEGOTIATE" (command:0x0000 flags:0x0001)
2018-04-23 11:13:59,902 SMB.SMBConnection base._updateState_SMB2 [INFO] SMB2 dialect negotiation successful
2018-04-23 11:13:59,902 SMB.SMBConnection base.onNMBSessionMessage [DEBUG] Received SMB2 message "SMB2_COM_SESSION_SETUP" (command:0x0001 flags:0x0001)
2018-04-23 11:13:59,903 SMB.SMBConnection base._handleSessionChallenge_SMB2 [INFO] Performing NTLMv2 authentication (on SMB2) with server challenge "b'4474a0703adc7440'"
2018-04-23 11:13:59,903 SMB.SMBConnection base._handleSessionChallenge_SMB2 [INFO] Performing NTLMv2 authentication (on SMB2) with server challenge "b'4474a0703adc7440'"
2018-04-23 11:13:59,904 SMB.SMBConnection base._handleSessionChallenge_SMB2 [DEBUG] NT challenge response is "b'8d597da1f0a1f237bd14d4f290138eec010100000000000000000000000000004e2868663b2ff45d000000000200100048004f004b005500490043004800490001000a004800300033003400360004001c0068006f006b00750069006300680069002e006c006f00630061006c0003002800480030003300340036002e0068006f006b00750069006300680069002e006c006f00630061006c0005001c0068006f006b00750069006300680069002e006c006f00630061006c0007000800cd53e3bda8dad30100000000'" (202 bytes)
2018-04-23 11:13:59,904 SMB.SMBConnection base._handleSessionChallenge_SMB2 [DEBUG] LM challenge response is "b'71fd1e7f51e0fa466066acd30678ce894e2868663b2ff45d'" (24 bytes)
2018-04-23 11:13:59,904 SMB.SMBConnection base._handleSessionChallenge_SMB2 [INFO] Server supports SMB signing
2018-04-23 11:13:59,905 SMB.SMBConnection base._handleSessionChallenge_SMB2 [INFO] SMB signing deactivated. SMB messages will NOT be signed.
2018-04-23 11:13:59,910 SMB.SMBConnection base.onNMBSessionMessage [DEBUG] Received SMB2 message "SMB2_COM_SESSION_SETUP" (command:0x0001 flags:0x0009)
2018-04-23 11:13:59,910 SMB.SMBConnection base._updateState_SMB2 [INFO] Authentication (on SMB2) successful!
2018-04-23 11:13:59,911 SMB.SMBConnection base.onNMBSessionMessage [DEBUG] Received SMB2 message "SMB2_COM_TREE_CONNECT" (command:0x0003 flags:0x0001)
2018-04-23 11:13:59,911 SMB.SMBConnection base.onNMBSessionMessage [DEBUG] Received SMB2 message "SMB2_COM_CREATE" (command:0x0005 flags:0x0001)
2018-04-23 11:13:59,912 SMB.SMBConnection base.onNMBSessionMessage [DEBUG] Received SMB2 message "SMB2_COM_QUERY_DIRECTORY" (command:0x000E flags:0x0001)
2018-04-23 11:13:59,912 SMB.SMBConnection base.onNMBSessionMessage [DEBUG] Received SMB2 message "SMB2_COM_QUERY_DIRECTORY" (command:0x000E flags:0x0001)
2018-04-23 11:13:59,912 SMB.SMBConnection base.onNMBSessionMessage [DEBUG] Received SMB2 message "SMB2_COM_CLOSE" (command:0x0006 flags:0x0001)
```

これで自分のアプリ用のログとpysmbのログが分離できたので、大分見通しが良くなったと思います。

### ルートロガーへの伝播を抑制

上記の例ではルートロガーの出力を設定していないので特に気にしていませんが、ルートロガーの出力を設定しつつpysmbのログをルートロガーに流したくない場合もあると思います。

その場合はロガーの`propagate`を`False`で設定してあげるとルートロガーへのログの伝播を抑制できます。

```python
        "SMB.SMBConnection": {
            "level": "DEBUG",
            "handlers": ["smb"],
            "propagate": False
        }
```

## fileConfig

fileConfigを使うパターンです。

```ini
# logging.conf

[loggers]
keys=root,app_name,smb

[handlers]
keys=app_name,smb

[formatters]
keys=simple

### logger ###

[logger_root]
level=DEBUG
handlers=

[logger_app_name]
level=DEBUG
handlers=app_name
qualname=app_name

[logger_smb]
level=DEBUG
handlers=smb
qualname=SMB.SMBConnection

### handler ###

[handler_app_name]
class=FileHandler
level=DEBUG
formatter=simple
args=('./app_name.log',)

[handler_smb]
class=FileHandler
level=DEBUG
formatter=simple
args=('./smb.log',)

### formatter ###

[formatter_simple]
format=%(asctime)s %(name)s %(module)s.%(funcName)s [%(levelname)s] %(message)s

```

```python
from logging import getLogger
from logging.config import fileConfig
import platform
from smb.SMBConnection import SMBConnection

fileConfig('logging.conf')
logger = getLogger('app_name')

conn = SMBConnection(
    'IEUser',
    'Passw0rd!',
    platform.uname().node,
    'IEWIN7')
conn.connect('172.28.0.198', 139)

logger.info(conn.listPath('Share', ''))

conn.close()
```

これでもdictConfigと同じ出力結果になります。

# 呼び出されるロガー

pysmbのソースコードを見ると、以下の名称のロガーが使われています。

- NMB.NMBSession
- NMB.NBNS
- NMB.NetBIOS
- NMB.NBNSProtocol
- SMB.SMB
- SMB.SMBMessage
- SMB.SMBConnection
- SMB.SMB2Message
- SMB.SMBFactory
- SMB.SMBProtocol

が、私が普段使っている分には出力されるログは全て`SMB.SMBConnection`です。[^1]

呼び出される経路によっては別のロガーで出力されると思いますが、そこまで追い切れていません…

[^1]: SMBConnectionしか使ってないのでそりゃそうなんですけど…