7.2.3. Error Log Content for Other Log Levels(他のログレベルのエラーコンテンツ)

異なるログレベルは異なるレベルの詳細だけでなく、異なるタイプのサーバー操作に関する情報も返します。これらの一部はここでは要約されていますが、さらに多くのロギングレベルを組み合わせることができます。

レプリケーションロギングは、実装する最も重要な診断レベルの 1 つです。このロギングレベルは、サプライヤーの変更や changelog への書き込み、更新送信、レプリカ合意の変更など、レプリケーションと Windows 同期に関連するすべての操作を記録します。

レプリケーションの更新の準備または送信されるたびに、エラーログは、指定されているレプリケーションまたは同期合意、コンシューマーホストおよびポート、および現在のレプリケーションタスクを特定します。

[timestamp] NSMMReplicationPlugin - agmt="name" (consumer_host:consumer_port): current_task

以下に例を示します。

[09/Jan/2020:13:44:48 -0500] NSMMReplicationPlugin - agmt="cn=example2" (alt:13864): {replicageneration} 4949df6e000000010000

{replicageneration} は新規情報が送信され、4 949df6e000000010000 がレプリケートされるエントリーの変更イベントであることを意味します。

例7.3「レプリケーションエラーログエントリー」 は、changelog へのエントリーの追加からレプリケーションの完了後のコンシューマの解放まで、単一エントリーをコンシューマに送信する完全なプロセスを示しています。

例7.3 レプリケーションエラーログエントリー

[29/May/2017:14:15:30.539817639 +0200] - DEBUG - _csngen_adjust_local_time - gen state before 592c103d0000:1496059964:0:1
[29/May/2017:14:15:30.562983285 +0200] - DEBUG - _csngen_adjust_local_time - gen state after 592c10e20000:1496060129:0:1
[29/May/2017:14:15:30.578828393 +0200] - DEBUG - NSMMReplicationPlugin - ruv_add_csn_inprogress - Successfully inserted csn 592c10e2000000020000 into pending list
[29/May/2017:14:15:30.589917123 +0200] - DEBUG - NSMMReplicationPlugin - changelog program - _cl5GetDBFileByReplicaName - found DB object 0x558ddfe1f720 for database /var/lib/dirsrv/slapd-supplier_2/changelogdb/d3de3e8d-446611e7-a89886da-6a37442d_592c0e0b000000010000.db
[29/May/2017:14:15:30.600044236 +0200] - DEBUG - NSMMReplicationPlugin - changelog program - cl5WriteOperationTxn - Successfully written entry with csn (592c10e2000000020000)
[29/May/2017:14:15:30.615923352 +0200] - DEBUG - NSMMReplicationPlugin - changelog program - _cl5GetDBFileByReplicaName - found DB object 0x558ddfe1f720 for database /var/lib/dirsrv/slapd-supplier_2/changelogdb/d3de3e8d-446611e7-a89886da-6a37442d_592c0e0b000000010000.db
[29/May/2017:14:15:30.627443305 +0200] - DEBUG - NSMMReplicationPlugin - csnplCommitALL: committing all csns for csn 592c10e2000000020000
[29/May/2017:14:15:30.632713657 +0200] - DEBUG - NSMMReplicationPlugin - csnplCommitALL: processing data csn 592c10e2000000020000
[29/May/2017:14:15:30.652621188 +0200] - DEBUG - NSMMReplicationPlugin - ruv_update_ruv - Successfully committed csn 592c10e2000000020000
[29/May/2017:14:15:30.669666453 +0200] - DEBUG - NSMMReplicationPlugin - repl5_inc_run - agmt="cn=meTo_localhost:39001" (localhost:39001): State: wait_for_changes -> wait_for_changes
[29/May/2017:14:15:30.685259483 +0200] - DEBUG - NSMMReplicationPlugin - repl5_inc_run - agmt="cn=meTo_localhost:39001" (localhost:39001): State: wait_for_changes -> ready_to_acquire_replica
[29/May/2017:14:15:30.689906327 +0200] - DEBUG - NSMMReplicationPlugin - conn_connect - agmt="cn=meTo_localhost:39001" (localhost:39001) - Trying non-secure slapi_ldap_init_ext
[29/May/2017:14:15:30.700259799 +0200] - DEBUG - NSMMReplicationPlugin - conn_connect - agmt="cn=meTo_localhost:39001" (localhost:39001) - binddn = cn=replrepl,cn=config,  passwd = {AES-TUhNR0NTcUdTSWIzRFFFRkRUQm1NRVVHQ1NxR1NJYjNEUUVGRERBNEJDUmlZVFUzTnpRMk55MDBaR1ZtTXpobQ0KTWkxaE9XTTRPREpoTlMwME1EaGpabVUxWmdBQ0FRSUNBU0F3Q2dZSUtvWklodmNOQWdjd0hRWUpZSVpJQVdVRA0KQkFFcUJCRGhwMnNLcEZ2ZWE2RzEwWG10OU41Tg==}+36owaI7oTmvWhxRzUqX5w==
[29/May/2017:14:15:30.712287531 +0200] - DEBUG - NSMMReplicationPlugin - conn_cancel_linger - agmt="cn=meTo_localhost:39001" (localhost:39001) - No linger to cancel on the connection
[29/May/2017:14:15:30.736779494 +0200] - DEBUG - _csngen_adjust_local_time - gen state before 592c10e20001:1496060129:0:1
[29/May/2017:14:15:30.741909244 +0200] - DEBUG - _csngen_adjust_local_time - gen state after 592c10e30000:1496060130:0:1
[29/May/2017:14:15:30.880287041 +0200] - DEBUG - NSMMReplicationPlugin - acquire_replica - agmt="cn=meTo_localhost:39001" (localhost:39001): Replica was successfully acquired.
[29/May/2017:14:15:30.897500049 +0200] - DEBUG - NSMMReplicationPlugin - repl5_inc_run - agmt="cn=meTo_localhost:39001" (localhost:39001): State: ready_to_acquire_replica -> sending_updates
[29/May/2017:14:15:30.914417773 +0200] - DEBUG - csngen_adjust_time - gen state before 592c10e30001:1496060130:0:1
[29/May/2017:14:15:30.926341721 +0200] - DEBUG - NSMMReplicationPlugin - changelog program - _cl5GetDBFile - found DB object 0x558ddfe1f720 for database /var/lib/dirsrv/slapd-supplier_2/changelogdb/d3de3e8d-446611e7-a89886da-6a37442d_592c0e0b000000010000.db
[29/May/2017:14:15:30.943094471 +0200] - DEBUG - NSMMReplicationPlugin - changelog program - _cl5PositionCursorForReplay - (agmt="cn=meTo_localhost:39001" (localhost:39001)): Consumer RUV:
[29/May/2017:14:15:30.949395331 +0200] - DEBUG - NSMMReplicationPlugin - agmt="cn=meTo_localhost:39001" (localhost:39001): {replicageneration} 592c0e0b000000010000
[29/May/2017:14:15:30.961118175 +0200] - DEBUG - NSMMReplicationPlugin - agmt="cn=meTo_localhost:39001" (localhost:39001): {replica 1 ldap://localhost:39001} 592c0e17000000010000 592c0e1a000100010000 00000000
[29/May/2017:14:15:30.976680025 +0200] - DEBUG - NSMMReplicationPlugin - agmt="cn=meTo_localhost:39001" (localhost:39001): {replica 2 ldap://localhost:39002} 592c103c000000020000 592c103c000000020000 00000000
[29/May/2017:14:15:30.990404183 +0200] - DEBUG - NSMMReplicationPlugin - changelog program - _cl5PositionCursorForReplay - (agmt="cn=meTo_localhost:39001" (localhost:39001)): Supplier RUV:
[29/May/2017:14:15:31.001242624 +0200] - DEBUG - NSMMReplicationPlugin - agmt="cn=meTo_localhost:39001" (localhost:39001): {replicageneration} 592c0e0b000000010000
[29/May/2017:14:15:31.017406105 +0200] - DEBUG - NSMMReplicationPlugin - agmt="cn=meTo_localhost:39001" (localhost:39001): {replica 2 ldap://localhost:39002} 592c103c000000020000 592c10e2000000020000 592c10e1
[29/May/2017:14:15:31.028803190 +0200] - DEBUG - NSMMReplicationPlugin - agmt="cn=meTo_localhost:39001" (localhost:39001): {replica 1 ldap://localhost:39001} 592c0e1a000100010000 592c0e1a000100010000 00000000
[29/May/2017:14:15:31.040172464 +0200] - DEBUG - agmt="cn=meTo_localhost:39001" (localhost:39001) - clcache_get_buffer - found thread private buffer cache 0x558ddf870f00
[29/May/2017:14:15:31.057495165 +0200] - DEBUG - agmt="cn=meTo_localhost:39001" (localhost:39001) - clcache_get_buffer - _pool is 0x558ddfe294d0 _pool->pl_busy_lists is 0x558ddfab84c0 _pool->pl_busy_lists->bl_buffers is 0x558ddf870f00
[29/May/2017:14:15:31.063015498 +0200] - DEBUG - agmt="cn=meTo_localhost:39001" (localhost:39001) - clcache_initial_anchorcsn - agmt="cn=meTo_localhost:39001" (localhost:39001) - (cscb 0 - state 0) - csnPrevMax () csnMax (592c10e2000000020000) csnBuf (592c103c000000020000) csnConsumerMax (592c103c000000020000)
[29/May/2017:14:15:31.073252305 +0200] - DEBUG - clcache_initial_anchorcsn - anchor is now: 592c103c000000020000
[29/May/2017:14:15:31.089915209 +0200] - DEBUG - NSMMReplicationPlugin - changelog program - agmt="cn=meTo_localhost:39001" (localhost:39001): CSN 592c103c000000020000 found, position set for replay
[29/May/2017:14:15:31.095825439 +0200] - DEBUG - agmt="cn=meTo_localhost:39001" (localhost:39001) - clcache_get_next_change - load=1 rec=1 csn=592c10e2000000020000
[29/May/2017:14:15:31.100123762 +0200] - DEBUG - NSMMReplicationPlugin - repl5_inc_result_threadmain - Starting
[29/May/2017:14:15:31.115749709 +0200] - DEBUG - NSMMReplicationPlugin - repl5_inc_result_threadmain - Read result for message_id 0
[29/May/2017:14:15:31.125866330 +0200] - DEBUG - NSMMReplicationPlugin - replay_update - agmt="cn=meTo_localhost:39001" (localhost:39001): Sending add operation (dn="cn=user,ou=People,dc=example,dc=com" csn=592c10e2000000020000)
[29/May/2017:14:15:31.142339398 +0200] - DEBUG - NSMMReplicationPlugin - repl5_inc_result_threadmain - Read result for message_id 0
[29/May/2017:14:15:31.160456597 +0200] - DEBUG - NSMMReplicationPlugin - replay_update - agmt="cn=meTo_localhost:39001" (localhost:39001): Consumer successfully sent operation with csn 592c10e2000000020000
[29/May/2017:14:15:31.172399536 +0200] - DEBUG - NSMMReplicationPlugin - repl5_inc_result_threadmain - Read result for message_id 0
[29/May/2017:14:15:31.188857336 +0200] - DEBUG - agmt="cn=meTo_localhost:39001" (localhost:39001) - clcache_adjust_anchorcsn - agmt="cn=meTo_localhost:39001" (localhost:39001) - (cscb 0 - state 1) - csnPrevMax (592c10e2000000020000) csnMax (592c10e2000000020000) csnBuf (592c10e2000000020000) csnConsumerMax (592c10e2000000020000)
[29/May/2017:14:15:31.199605024 +0200] - DEBUG - agmt="cn=meTo_localhost:39001" (localhost:39001) - clcache_load_buffer - rc=-30988
[29/May/2017:14:15:31.210800816 +0200] - DEBUG - NSMMReplicationPlugin - send_updates - agmt="cn=meTo_localhost:39001" (localhost:39001): No more updates to send (cl5GetNextOperationToReplay)
[29/May/2017:14:15:31.236214134 +0200] - DEBUG - NSMMReplicationPlugin - repl5_inc_waitfor_async_results - 0 5
[29/May/2017:14:15:31.246755544 +0200] - DEBUG - NSMMReplicationPlugin - repl5_inc_result_threadmain - Read result for message_id 0
[29/May/2017:14:15:31.277705986 +0200] - DEBUG - NSMMReplicationPlugin - repl5_inc_result_threadmain - Read result for message_id 0
[29/May/2017:14:15:31.303530336 +0200] - DEBUG - NSMMReplicationPlugin - repl5_inc_result_threadmain - Read result for message_id 5
[29/May/2017:14:15:31.318259308 +0200] - DEBUG - NSMMReplicationPlugin - repl5_inc_result_threadmain - Result 1, 0, 0, 5, (null)
[29/May/2017:14:15:31.335263462 +0200] - DEBUG - NSMMReplicationPlugin - repl5_inc_result_threadmain - Read result for message_id 5
[29/May/2017:14:15:31.364551307 +0200] - DEBUG - NSMMReplicationPlugin - repl5_inc_waitfor_async_results - 5 5
[29/May/2017:14:15:31.376301820 +0200] - DEBUG - NSMMReplicationPlugin - repl5_inc_result_threadmain exiting
[29/May/2017:14:15:31.393707037 +0200] - DEBUG - agmt="cn=meTo_localhost:39001" (localhost:39001) - clcache_return_buffer - session end: state=5 load=1 sent=1 skipped=0 skipped_new_rid=0 skipped_csn_gt_cons_maxcsn=0 skipped_up_to_date=0 skipped_csn_gt_ruv=0 skipped_csn_covered=0
[29/May/2017:14:15:31.398134114 +0200] - DEBUG - NSMMReplicationPlugin - consumer_connection_extension_acquire_exclusive_access - conn=4 op=3 Acquired consumer connection extension
[29/May/2017:14:15:31.423099625 +0200] - DEBUG - NSMMReplicationPlugin - multimaster_extop_StartNSDS50ReplicationRequest - conn=4 op=3 repl="dc=example,dc=com": Begin incremental protocol
[29/May/2017:14:15:31.438899389 +0200] - DEBUG - csngen_adjust_time - gen state before 592c10e30001:1496060130:0:1
[29/May/2017:14:15:31.443800884 +0200] - DEBUG - csngen_adjust_time - gen state after 592c10e40001:1496060130:1:1
[29/May/2017:14:15:31.454123488 +0200] - DEBUG - NSMMReplicationPlugin - replica_get_exclusive_access - conn=4 op=3 repl="dc=example,dc=com": Acquired replica
[29/May/2017:14:15:31.469698781 +0200] - DEBUG - NSMMReplicationPlugin - release_replica - agmt="cn=meTo_localhost:39001" (localhost:39001): Successfully released consumer
[29/May/2017:14:15:31.475096195 +0200] - DEBUG - NSMMReplicationPlugin - conn_start_linger -agmt="cn=meTo_localhost:39001" (localhost:39001) - Beginning linger on the connection
[29/May/2017:14:15:31.485281588 +0200] - DEBUG - NSMMReplicationPlugin - repl5_inc_run - agmt="cn=meTo_localhost:39001" (localhost:39001): State: sending_updates -> wait_for_changes
[29/May/2017:14:15:31.495865065 +0200] - DEBUG - NSMMReplicationPlugin - multimaster_extop_StartNSDS50ReplicationRequest - conn=4 op=3 repl="dc=example,dc=com": StartNSDS90ReplicationRequest: response=0 rc=0
[29/May/2017:14:15:31.501617765 +0200] - DEBUG - NSMMReplicationPlugin - consumer_connection_extension_relinquish_exclusive_access - conn=4 op=3 Relinquishing consumer connection extension
[29/May/2017:14:15:31.716627741 +0200] - DEBUG - NSMMReplicationPlugin - consumer_connection_extension_acquire_exclusive_access - conn=4 op=4 Acquired consumer connection extension
[29/May/2017:14:15:31.735431913 +0200] - DEBUG - NSMMReplicationPlugin - replica_relinquish_exclusive_access - conn=4 op=4 repl="dc=example,dc=com": Released replica held by locking_purl=conn=4 id=3
[29/May/2017:14:15:31.745841821 +0200] - DEBUG - NSMMReplicationPlugin - consumer_connection_extension_relinquish_exclusive_access - conn=4 op=4 Relinquishing consumer connection extension

プラグインは、プラグインの名前と、プラグインによって呼び出されるすべての関数を記録します。これには単純な形式があります。

[timestamp] Plugin_name - message
[timestamp] - function - message

返された情報は、すべてのステップが処理されている限り数百行になります。記録された正確な情報は、プラグイン自体によって異なります。たとえば、ACL プラグインには、例7.4「ACL プラグインの例(プラグインロギングを含むログエントリー)」 に示されるように接続および操作番号が含まれます。

例7.4 ACL プラグインの例(プラグインロギングを含むログエントリー)

[29/May/2017:14:38:19.133878244 +0200] - DEBUG - get_filter_internal - ==>
[29/May/2017:14:38:19.153942547 +0200] - DEBUG - get_filter_internal - PRESENT
[29/May/2017:14:38:19.177908064 +0200] - DEBUG - get_filter_internal - <= 0
[29/May/2017:14:38:19.193547449 +0200] - DEBUG - slapi_vattr_filter_test_ext_internal - =>
[29/May/2017:14:38:19.198121765 +0200] - DEBUG - slapi_vattr_filter_test_ext_internal - <=
[29/May/2017:14:38:19.214342752 +0200] - DEBUG - slapi_vattr_filter_test_ext_internal - PRESENT
[29/May/2017:14:38:19.219886104 +0200] - DEBUG - NSACLPlugin - acl_access_allowed - conn=15 op=1 (main): Allow search on entry(cn=replication,cn=config): root user
[29/May/2017:14:38:19.230152526 +0200] - DEBUG - slapi_vattr_filter_test_ext_internal - <= 0
[29/May/2017:14:38:19.240971955 +0200] - DEBUG - NSACLPlugin - acl_read_access_allowed_on_entry - Root access (read) allowed on entry(cn=replication,cn=config)
[29/May/2017:14:38:19.246456160 +0200] - DEBUG - cos-plugin - cos_cache_vattr_types - Failed to get class of service reference
[29/May/2017:14:38:19.257200851 +0200] - DEBUG - NSACLPlugin - Root access (read) allowed on entry(cn=replication,cn=config)
[29/May/2017:14:38:19.273534025 +0200] - DEBUG - NSACLPlugin - Root access (read) allowed on entry(cn=replication,cn=config)
[29/May/2017:14:38:19.289474926 +0200] - DEBUG - slapi_filter_free - type 0x87
注記

例7.4「ACL プラグインの例(プラグインロギングを含むログエントリー)」 プラグインロギングと検索フィルター処理(ログレベル 65696)を示しています。

多くの他のロギングには、プラグインロギングレベルと同様の出力があり、これは各種の内部操作用のみです。負荷のトレース出力(4)、アクセス制御リスト処理(128)、スキーマ解析(2048)、およびハウスキーピング(4096)はすべて、さまざまな操作によって呼び出される関数を記録します。この場合、相違点は記録されるものの形式ではありませんが、記録されている操作は何ですか。

設定ファイルの処理は any .conf ファイルを通過し、サーバーの起動時にすべての行を出力します。これは、サーバーの通常の設定外のファイルの問題をデバッグするために使用できます。デフォルトでは、国際化言語セットの設定を含む slapd-collations.conf ファイルのみが利用できます。

例7.5 設定ファイル処理ログエントリー

[29/May/2017:15:26:48.897935879 +0200] - DEBUG - collation_read_config - Reading config file /etc/dirsrv/slapd-supplier_1/slapd-collations.conf
[29/May/2017:15:26:48.902606586 +0200] - DEBUG - collation-plugin - collation_read_config - line 16: collation "" "" "" 1 3	2.16.840.1.113730.3.3.2.0.1	default
[29/May/2017:15:26:48.918493657 +0200] - DEBUG - collation-plugin - collation_read_config - line 17: collation ar "" "" 1 3	2.16.840.1.113730.3.3.2.1.1	ar
[29/May/2017:15:26:48.932550086 +0200] - DEBUG - collation-plugin - collation_read_config - line 18: collation be "" "" 1 3	2.16.840.1.113730.3.3.2.2.1	be	be-BY
...

ACI のロギングには 2 つのレベルがあります。1 つはデバッグ情報用で、もう 1 つはサマリーです。これらの ACI ロギングレベルはいずれも、接続番号操作番号 情報など、他のタイプのプラグインやエラーロギングに含まれていない追加情報を記録します。プラグインの名前、ユーザーのバインド DN、操作の実行または試行、および適用された ACI を表示します。デバッグレベルには、バインドなどの操作にも呼び出される一連の関数が表示されます。

例7.6「アクセス制御の概要ロギング」 には、アクセス制御ログエントリーの概要を表示します。

例7.6 アクセス制御の概要ロギング

[29/May/2017:15:34:52.742034888 +0200] - DEBUG - NSACLPlugin - acllist_init_scan - Failed to find root for base: cn=features,cn=config
[29/May/2017:15:34:52.761702767 +0200] - DEBUG - NSACLPlugin - acllist_init_scan - Failed to find root for base: cn=config
[29/May/2017:15:34:52.771907825 +0200] - DEBUG - NSACLPlugin - acl_access_allowed - #### conn=6 op=1 binddn="cn=user,ou=people,dc=example,dc=com"
[29/May/2017:15:34:52.776327012 +0200] - DEBUG - NSACLPlugin -     ************ RESOURCE INFO STARTS *********
[29/May/2017:15:34:52.786397852 +0200] - DEBUG - NSACLPlugin -     Client DN: cn=user,ou=people,dc=example,dc=com
[29/May/2017:15:34:52.797004451 +0200] - DEBUG - NSACLPlugin -     resource type:256(search target_DN )
[29/May/2017:15:34:52.807135945 +0200] - DEBUG - NSACLPlugin -     Slapi_Entry DN: cn=features,cn=config
[29/May/2017:15:34:52.822877838 +0200] - DEBUG - NSACLPlugin -     ATTR: objectClass
[29/May/2017:15:34:52.827250828 +0200] - DEBUG - NSACLPlugin -     rights:search
[29/May/2017:15:34:52.831603634 +0200] - DEBUG - NSACLPlugin -     ************ RESOURCE INFO ENDS   *********
[29/May/2017:15:34:52.847183276 +0200] - DEBUG - NSACLPlugin - acl__scan_for_acis - Num of ALLOW Handles:0, DENY handles:0
[29/May/2017:15:34:52.857857195 +0200] - DEBUG - NSACLPlugin - print_access_control_summary - conn=6 op=1 (main): Deny search on entry(cn=features,cn=config).attr(objectClass) to cn=user,ou=people,dc=example,dc=com: no aci matched the resource