第11章 ログファイルのリファレンス

アクセスログのレベルに応じて、Directory Server が実行するさまざまな種類の操作が記録されます。

アクセスログには次のログレベルがあります。

nsslapd-accesslog-level 属性を使用して、アクセスログのレベルを設定します。属性値は加算されます。ログレベル値を 260 に設定すると、この値にはレベル 256 と 4 が含まれます。

デフォルトでは、Directory Server のログレベルは 256 です。このレベルでは、エントリーへのアクセスに加えて、以下の情報が記録されます。

[time_stamp] conn=13 fd=608 slot=608 connection from 172.17.0.2 to 172.17.0.2

Directory Server は、デフォルトでは内部 LDAP 要求を記録しません。内部アクセス操作のロギングを有効にするには、nsslapd-accesslog-level 設定属性を使用します。

[time_stamp] conn=11 fd=608 slot=608 connection from 172.17.0.2 to 172.17.0.2

[time_stamp] conn=11 fd=608 slot=608 connection from 172.17.0.2 to 172.17.0.2.

[time_stamp] conn=14 op=0 BIND dn="cn=Directory Manager" method=128 version=3
[time_stamp] conn=14 op=0 RESULT err=0 tag=97 nentries=0 wtime=0.000076581 optime=0.000082736 etime=0.000158680
[time_stamp] conn=14 op=1 SRCH base="dc=example,dc=com" scope=2 filter="(uid=bjensen)"
[time_stamp] conn=14 op=2 ABANDON targetop=2 msgid=3 nentries=0 etime=0.0000113702
[time_stamp] conn=14 op=3 UNBIND
[time_stamp] conn=14 op=3 fd=634 closed - U1

上記の例では、以下のようになります。

[time_stamp] conn=11 op=0 BIND dn="cn=Directory Manager" method=128 version=3

メソッドのタイプには、次の 3 つの値があります。

[time_stamp] conn=11 op=0 BIND dn="cn=Directory Manager" method=128 version=3

[time_stamp] conn=2 op=0 RESULT err=0 tag=97 nentries=0 wtime=0.000076581 optime=0.000082736 etime=0.000158680

[time_stamp] conn=11 op=0 RESULT err=0 tag=97 nentries=0 wtime=0.000076581 optime=0.000082736 etime=0.000158680

次の表に、一般的に使用されるタグを示します。

[time_stamp] conn=11 op=0 RESULT err=0 tag=97 nentries=0 wtime=0.000076581 optime=0.000082736 etime=0.000158680

この例では nentries=0 です。つまり、Directory Server は一致するエントリーを検出しませんでした。

[time_stamp] conn=11 op=1 RESULT err=0 tag=101 nentries=1 wtime=0.000076581 optime=0.000082736 etime=0.000158680 notes=U

この例では、Directory Server は操作の実行に 0.000158680 秒かかりました。

etime 値が 0 の場合は、操作の実行に実際には 0 ナノ秒かかったことを意味します。

[time_stamp] conn=114 op=68 SORT serialno (1)

この例の括弧で囲まれた数字は、LDAP 要求によって 1 つの候補エントリーがソートされたことを示しています。

RESULT メッセージには、以下のパフォーマンス関連のレコードが含まれます。

[time_stamp] conn=11 op=1 RESULT err=0 tag=101 nentries=1 wtime=0.000076581 optime=0.000082736 etime=0.000158680 notes=U

Directory Server は、次の検索インジケーターをサポートしています。

note レコードには、notes=P,A や notes=U,P など、値の組み合わせが含まれることがあります。

属性がインデックス化されていない場合、Directory Server はそれらを直接データベースで検索する必要があります。この手順では、インデックスファイルを検索する場合よりも多くのリソースが消費されます。

インデックス化されていない検索は、以下のシナリオで発生します。

今後の検索を最適化するには、インデックスに頻繁に検索されるインデックス化されていない属性を追加します。

[time_stamp] conn=1 op=0 BIND dn=“uid=jdoe,ou=people,dc=example,dc=com” method=128 version=3
[time_stamp] conn=1 op=0 RESULT err=0 tag=97 nentries=0 wtime=0.000111632 optime=0.006612223 etime=0.006722325 notes=M details=“Multi-factor Authentication” dn=“uid=jdoe,ou=people,dc=example,dc=com”

[time_stamp] conn=67 op=8530 VLV 0:5:0210 10:5397 (0)

この例では、要求情報は 0:5:0210 で、形式は beforeCount:afterCount:index:contentCount です。応答情報は 10:5397 (0) で、形式は targetPosition:contentCount (resultCode) です。

クライアントが position-by-value VLV 要求を使用する場合、要求情報の形式は beforeCount: afterCount: value となります。

[time_stamp] conn=13 op=1 EXT oid="2.16.840.1.113730.3.5.3"
...
[time_stamp] conn=15 op=3 EXT oid="2.16.840.1.113730.3.5.5"

Directory Server は、以下の LDAPv3 拡張操作とその OID をサポートしています。

以下は、破棄メッセージを含むログレコードの例です。

[time_stamp] conn=12 op=1 SRCH base="dc=example,dc=com" scope=2 filter="(uid=bjensen)"
[time_stamp] conn=12 op=2 ABANDON targetop=2 msgid=3 nentries=0 etime=0.0000113980

nentries=0 値は、操作が終了する前に Directory Server が送信したエントリーの数を示します。etime=0.0000113980 値は、経過時間 (秒単位) を示します。targetop =2 は、Directory Server が以前に開始した操作番号 (opt =2) に対応します。

Directory Server が破棄する操作を見つけられない場合、ログレコードには targetop=NOTFOUND メッセージが含まれます。

[time_stamp] conn=12 op=2 ABANDON targetop=NOTFOUND msgid=2

このメッセージ例は、Directory Server が操作を以前に完了したか、不明な操作であることを意味します。

[time_stamp] conn=12 op=2 ABANDON targetop=NOTFOUND msgid=2

[time_stamp] conn=16 op=0 BIND dn="" method=sasl version=3 mech=DIGEST-MD5
[time_stamp] conn=16 op=0 RESULT err=14 tag=97 nentries=0 wtime=0.000076581 optime=0.000082736 etime=0.000158680, SASL bind in progress

このレコード例は、SASL バインドが現在進行中 (SASL bind in progress) であり、戻りコード err=14 があることを示しています。これは、接続がまだ開いていることを意味します。Directory Server は、LDAP バージョン番号 (version=3) および使用された SASL メカニズム (mech=DIGEST-MD5) とともに SASL バインド情報をログに記録します。

[time_stamp] conn=14 op=1 RESULT err=0 tag=97 nentries=0 wtime=0.000076581 optime=0.000082736 etime=0.000158680 dn="uid=jdoe,dc=example,dc=com"

デフォルト以外のログレベルを設定するか、特定のログ設定を適用すると、Directory Server はアクセスログファイルへの追加情報の記録を開始します。

次の例は、サーバーが開始する内部操作のログ形式を示しています。

[time_stamp] conn=Internal(0) op=0(0)(0) MOD dn="cn=uniqueid generator,cn=config"
[time_stamp] conn=Internal(0) op=0(0)(0) RESULT err=0 tag=48 nentries=0 wtime=0.0003979676 optime=0.0003989250 etime=0.0007968796

この例のレコードには conn=Internal があり、その後に (0) と op=0(0)(nesting_level) が続いています。操作 ID と内部操作 ID は常に 0 です。ネストされていないログレコードの場合、ネストレベルは 0 です。

[time_stamp] conn=5 (Internal) op=15(1)(0) SRCH base="cn=config,cn=userroot,cn=ldbm database,cn=plugins,cn=config" scope=1 filter="objectclass=vlvsearch" attrs=ALL
[time_stamp] conn=5 (Internal) op=15(1)(0) RESULT err=0 tag=48 nentries=0 wtime=0.0000143989 optime=0.0000151450 etime=0.0000295419
[time_stamp] conn=5 (Internal) op=15(2)(0) SRCH base="cn=config,cn=example,cn=ldbm database,cn=plugins,cn=config" scope=1 filter="objectclass=vlvsearch" attrs=ALL
[time_stamp] conn=5 (Internal) op=15(2)(0) RESULT err=0

この例のレコードには、クライアント接続 ID に設定された conn レコードがあり、その後に文字列 (Internal) が続いています。op レコードには、操作 ID と (internal_operation_ID)(nesting_level) が含まれています。内部操作 ID は異なる場合があります。ネストされていないログエントリーの場合、ネストレベルは 0 です。

たとえば、uid=user,dc=example,dc=com エントリーを削除し、Referential Integrity プラグインがこのエントリーを example グループから自動的に削除すると、サーバーは次の内容をログに記録します。

[time_stamp] conn=2 op=37 DEL dn="uid=user,dc=example,dc=com"
[time_stamp] conn=2 (Internal) op=37(1) SRCH base="uid=user,dc=example,dc=com" scope=0 filter="(|(objectclass=*)(objectclass=ldapsubentry))" attrs=ALL
[time_stamp] conn=2 (Internal) op=37(1) RESULT err=0 tag=48 nentries=1 wtime=0.0000062569 optime=0.0000067203 etime=0.0000129148
[time_stamp] conn=2 (Internal) op=37(2) SRCH base="dc=example,dc=com" scope=2 filter="(member=uid=user,dc=example,dc=com)" attrs="member"
[time_stamp] conn=2 (Internal) op=37(2) RESULT err=0 tag=48 nentries=0 wtime=0.0000058002 optime=0.0000065198 etime=0.0000123162
[time_stamp] conn=2 (Internal) op=37(3) SRCH base="dc=example,dc=com" scope=2 filter="(uniquemember=uid=user,dc=example,dc=com)" attrs="uniquemember"
[time_stamp] conn=2 (Internal) op=37(3) RESULT err=0 tag=48 nentries=1 wtime=0.0000062123 optime=0.0000066022 etime=0.0000128104
[time_stamp] conn=2 (Internal) op=37(4) MOD dn="cn=example,dc=example,dc=com"
[time_stamp] conn=2 (Internal) op=37(5) SRCH base="cn=example,dc=example,dc=com" scope=0 filter="(|(objectclass=\*)(objectclass=ldapsubentry))" attrs=ALL
[time_stamp] conn=2 (Internal) op=37(5) RESULT err=0 tag=48 nentries=1 wtime=0.0000061994 optime=0.0000068742 etime=0.0000130685
[time_stamp] conn=2 (Internal) op=37(4) RESULT err=0 tag=48 nentries=0 wtime=0.0002600573 optime=0.0002617786 etime=0.0005217545
[time_stamp] conn=2 (Internal) op=37(6) SRCH base="dc=example,dc=com" scope=2 filter="(owner=uid=user,dc=example,dc=com)" attrs="owner"
[time_stamp] conn=2 (Internal) op=37(6) RESULT err=0 tag=48 nentries=0 wtime=0.000061678 optime=0.000076107 etime=0.0000137656
[time_stamp] conn=2 (Internal) op=37(7) SRCH base="dc=example,dc=com" scope=2 filter="(seeAlso=uid=user,dc=example,dc=com)" attrs="seeAlso"
[time_stamp] conn=2 (Internal) op=37(7) RESULT err=0 tag=48 nentries=0 wtime=0.0000031789 optime=0.0000035354 etime=0.0000066978
[time_stamp] conn=2 (Internal) op=37(8) SRCH base="o=example" scope=2 filter="(member=uid=user,dc=example,dc=com)" attrs="member"
[time_stamp] conn=2 (Internal) op=37(8) RESULT err=0 tag=48 nentries=0 wtime=0.0000030987 optime=0.0000032456 etime=0.0000063316
[time_stamp] conn=2 (Internal) op=37(9) SRCH base="o=example" scope=2 filter="(uniquemember=uid=user,dc=example,dc=com)" attrs="uniquemember"
[time_stamp] conn=2 (Internal) op=37(9) RESULT err=0 tag=48 nentries=0 wtime=0.0000021958 optime=0.0000026676 etime=0.0000048634
[time_stamp] conn=2 (Internal) op=37(10) SRCH base="o=example" scope=2 filter="(owner=uid=user,dc=example,dc=com)" attrs="owner"
[time_stamp] conn=2 (Internal) op=37(10) RESULT err=0 tag=48 nentries=0 wtime=0.0000022109 optime=0.00000268003 etime=00000048854
[time_stamp] conn=2 (Internal) op=37(11) SRCH base="o=example" scope=2 filter="(seeAlso=uid=user,dc=example,dc=com)" attrs="seeAlso"
[time_stamp] conn=2 (Internal) op=37(11) RESULT err=0 tag=48 nentries=0 wtime=0.0000021786 optime=0.0000024867 etime=0.0000046522
[time_stamp] conn=2 op=37 RESULT err=0 tag=107 nentries=0 wtime=0.005147365 optime=0.005150798 etime=0.0010297858

[time_stamp] conn=306 fd=60 slot=60 connection from 127.0.0.1 to 127.0.0.1
[time_stamp] conn=306 op=0 SRCH base="dc=example,dc=com" scope=2 filter="(description=*)" attrs=ALL
[time_stamp] conn=306 op=0 ENTRY dn="ou=Special
[time_stamp] conn=306 op=0 ENTRY dn="cn=Accounting Managers,ou=groups,dc=example,dc=com"
[time_stamp] conn=306 op=0 ENTRY dn="cn=HR Managers,ou=groups,dc=example,dc=com"
[time_stamp] conn=306 op=0 ENTRY dn="cn=QA Managers,ou=groups,dc=example,dc=com"
[time_stamp] conn=306 op=0 ENTRY dn="cn=PD Managers,ou=groups,dc=example,dc=com"
[time_stamp] conn=306 op=0 ENTRY dn="ou=Red Hat Servers,dc=example,dc=com"
[time_stamp0] conn=306 op=0 REFERRAL

この例は、ロギングレベルが 768 (512 + 256) であり、検索要求の応答として返される 6 つのエントリーと 1 つの参照を示しています。

次の例は、オプションの説明を含む 512 および 4 のログレベルを示しています。

[time_stamps] conn=1 (Internal) op=2(1)(0) SRCH base="cn=\22dc=example,dc=com\22,cn=mapping tree,cn=config"scope=0 filter="objectclass=nsMappingTree"attrs="nsslapd-referral" options=persistent

[time_stamps] conn=1 op=73 SRCH base="dc=example,dc=com" scope=2 filter="(cn=user_*)" attrs=ALL
[time_stamps] conn=1 op=73 STAT read index: attribute=objectclass key(eq)=referral --> count 0
[time_stamps] conn=1 op=73 STAT read index: attribute=cn key(sub)=er_ --> count 24
[time_stamps] conn=1 op=73 STAT read index: attribute=cn key(sub)=ser --> count 25
[time_stamps] conn=1 op=73 STAT read index: attribute=cn key(sub)=use --> count 25
[time_stamps] conn=1 op=73 STAT read index: attribute=cn key(sub)=^us --> count 24
[time_stamps] conn=1 op=73 STAT read index: duration 0.000010276
[time_stamps] conn=1 op=73 RESULT err=0 tag=101 nentries=24 wtime=0.00007841

このログレコードの例は、フィルター (cn=user_*) を使用した検索中に、Directory Server が次の数のデータベース検索を実行したことを示しています。

Directory Server は、接続の終了に関連する追加情報を含む接続コードを終了ログメッセージに追加します。