前回まででpysmbを使った一通りの操作はできるようになったと思います。
ここではログ出力について設定方法を確認したいと思います。

インデックス

pysmbの使い方（接続・切断）
pysmbの使い方（ファイル受信）
pysmbの使い方（ファイル送信）
pysmbの使い方（ロギング）
pysmbの使い方（匿名接続）

実行環境

クライアント

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は結構大量にログを吐きます。

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

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()の結果をログに出力してみましょう。
結果、このようなログが生成されます。

# 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を使うパターンです。

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()

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

# 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>]

# 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で設定してあげるとルートロガーへのログの伝播を抑制できます。

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

fileConfig

fileConfigを使うパターンです。

# 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

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です。¹

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

SMBConnectionしか使ってないのでそりゃそうなんですけど… ↩