search

389ds / 389-ds-base

The enterprise-class Open Source LDAP server for Linux
https://www.port389.org/
Other
200 stars 82 forks source link

Second memberOf fixup task overwrites task stats #6218

Open vashirov opened 3 weeks ago

vashirov commented 3 weeks ago

Issue Description While investigating failures in memberof_plugin/fixup_test.py::test_fixup_task_limit, I noticed that the logs look odd: inconsistent number of processed entries and really small process time.

First task is on dc=example,dc=com suffix, second is on ou=people,dc=example,dc=com, third is again on dc=example,dc=com. With 6000 entries total:

[10/Jun/2024:07:30:17.619788391 -0400] - INFO - memberof-plugin - memberof_fixup_task_thread - Memberof task finished (processed 6001 entries in 40 seconds)
[10/Jun/2024:07:30:17.791544224 -0400] - INFO - memberof-plugin - memberof_fixup_task_thread - Memberof task finished (processed 4 entries in 0 seconds)
[10/Jun/2024:07:30:17.794205057 -0400] - INFO - memberof-plugin - memberof_fixup_task_thread - Memberof task finished (processed 4 entries in 0 seconds)

With 5000 entries total:

[10/Jun/2024:07:33:49.171642325 -0400] - INFO - memberof-plugin - memberof_fixup_task_thread - Memberof task finished (processed 5005 entries in 1 seconds)
[10/Jun/2024:07:33:50.020074840 -0400] - INFO - memberof-plugin - memberof_fixup_task_thread - Memberof task finished (processed 10001 entries in 2 seconds)
[10/Jun/2024:07:33:50.334245942 -0400] - INFO - memberof-plugin - memberof_fixup_task_thread - Memberof task finished (processed 123 entries in 0 seconds)

I removed the condition to write to task log every 1000 entries and noticed that the counter restarts, when another task was added on a different suffix:

Memberof task starts (arg: (|(objectclass=inetuser)(objectclass=inetadmin)(objectclass=nsmemberof))) ...
Processed 1 entries in 0 seconds (+0 seconds)
Processed 2 entries in 0 seconds (+0 seconds)
Processed 3 entries in 0 seconds (+0 seconds)
Processed 4 entries in 0 seconds (+0 seconds)
Processed 5 entries in 0 seconds (+0 seconds)
Processed 6 entries in 0 seconds (+0 seconds)
Processed 1 entries in 0 seconds (+0 seconds)
Processed 2 entries in 0 seconds (+0 seconds)
Processed 3 entries in 0 seconds (+0 seconds)
Processed 4 entries in 0 seconds (+0 seconds)
Processed 5 entries in 0 seconds (+0 seconds)
Processed 6 entries in 0 seconds (+0 seconds)
Processed 7 entries in 0 seconds (+0 seconds)
Processed 8 entries in 0 seconds (+0 seconds)
Processed 9 entries in 0 seconds (+0 seconds)
...

And the log of the second task doesn't start from 0:

Memberof task starts (arg: (|(objectclass=inetuser)(objectclass=inetadmin)(objectclass=nsmemberof))) ...
Processed 103 entries in 0 seconds (+0 seconds)
Processed 104 entries in 0 seconds (+0 seconds)
Processed 105 entries in 0 seconds (+0 seconds)
Processed 106 entries in 0 seconds (+0 seconds)
Processed 107 entries in 0 seconds (+0 seconds)
Processed 108 entries in 0 seconds (+0 seconds)
Processed 109 entries in 0 seconds (+0 seconds)
Processed 110 entries in 0 seconds (+0 seconds)
Processed 111 entries in 0 seconds (+0 seconds)
Processed 112 entries in 0 seconds (+0 seconds)
Processed 113 entries in 0 seconds (+0 seconds)
Processed 114 entries in 0 seconds (+0 seconds)
Processed 115 entries in 0 seconds (+0 seconds)
Processed 116 entries in 0 seconds (+0 seconds)
...

Package Version and Platform:

Steps to Reproduce Steps to reproduce the behavior:

  1. Run memberof_plugin/fixup_test.py
  2. grep memberof /var/log/dirsrv/slapd-standalone1/errors
vashirov commented 3 weeks ago 
==================
WARNING: ThreadSanitizer: data race (pid=235446)
  Read of size 4 at 0xffffa8fa0114 by thread T24:
    #0 memberof_fixup_task_thread ldap/servers/plugins/memberof/memberof.c:2943 (libmemberof-plugin.so+0x1678c) (BuildId: 4a7a15a731983d62f6dc8f6cc55240745b12832d)
    #1 _pt_root <null> (libnspr4.so+0x30f3c) (BuildId: f104b07bc930c7bf01e241a2cb46ea281c73a21b)

  Previous write of size 4 at 0xffffa8fa0114 by thread T25 (mutexes: read M0, write M1, read M2):
    #0 memberof_fix_memberof_callback ldap/servers/plugins/memberof/memberof.c:3319 (libmemberof-plugin.so+0x17848) (BuildId: 4a7a15a731983d62f6dc8f6cc55240745b12832d)
    #1 internal_srch_entry_callback ldap/servers/slapd/plugin_internal_op.c:99 (libslapd.so.0+0x171778) (BuildId: 803f112345cbf6cb85efdc029b3341f00913be8c)
    #2 send_ldap_search_entry_ext ldap/servers/slapd/result.c:1594 (libslapd.so.0+0x19542c) (BuildId: 803f112345cbf6cb85efdc029b3341f00913be8c)
    #3 send_ldap_search_entry <null> (libslapd.so.0+0x195d98) (BuildId: 803f112345cbf6cb85efdc029b3341f00913be8c)
    #4 send_entry.lto_priv.0 <null> (libslapd.so.0+0x153e90) (BuildId: 803f112345cbf6cb85efdc029b3341f00913be8c)
    #5 send_results_ext.constprop.0 ldap/servers/slapd/opshared.c:1328 (libslapd.so.0+0x1dbe44) (BuildId: 803f112345cbf6cb85efdc029b3341f00913be8c)
    #6 op_shared_search <null> (libslapd.so.0+0x15fe34) (BuildId: 803f112345cbf6cb85efdc029b3341f00913be8c)
    #7 search_internal_callback_pb.lto_priv.0 <null> (libslapd.so.0+0x17a8b4) (BuildId: 803f112345cbf6cb85efdc029b3341f00913be8c)
    #8 slapi_search_internal_callback_pb <null> (libslapd.so.0+0x17ab90) (BuildId: 803f112345cbf6cb85efdc029b3341f00913be8c)
    #9 memberof_fix_memberof ldap/servers/plugins/memberof/memberof.c:3087 (libmemberof-plugin.so+0x165ec) (BuildId: 4a7a15a731983d62f6dc8f6cc55240745b12832d)
    #10 memberof_fixup_task_thread ldap/servers/plugins/memberof/memberof.c:2893 (libmemberof-plugin.so+0x165ec)
    #11 _pt_root <null> (libnspr4.so+0x30f3c) (BuildId: f104b07bc930c7bf01e241a2cb46ea281c73a21b)

  Location is global 'fixup_progress_count' of size 4 at 0xffffa8fa0114 (libmemberof-plugin.so+0x40114)

  Mutex M0 (0xffffa1008920) created at:
    #0 pthread_rwlock_init <null> (libtsan.so.2+0x5a0ac) (BuildId: 8d4ecf2b1838dee5e3128e6155efb961118b7f8d)
    #1 mdb_init ldap/servers/slapd/back-ldbm/db-mdb/mdb_config.c:148 (libback-ldbm.so+0xaa130) (BuildId: 167172cdc5fa19f7049dc63c805f0af75017d089)
    #2 dbimpl_setup ldap/servers/slapd/back-ldbm/dblayer.c:232 (libback-ldbm.so+0x53108) (BuildId: 167172cdc5fa19f7049dc63c805f0af75017d089)
    #3 dblayer_setup ldap/servers/slapd/back-ldbm/dblayer.c:249 (libback-ldbm.so+0x53834) (BuildId: 167172cdc5fa19f7049dc63c805f0af75017d089)
    #4 ldbm_back_start ldap/servers/slapd/back-ldbm/start.c:45 (libback-ldbm.so+0xa27a4) (BuildId: 167172cdc5fa19f7049dc63c805f0af75017d089)
    #5 plugin_call_func ldap/servers/slapd/plugin.c:2001 (libslapd.so.0+0x16eb30) (BuildId: 803f112345cbf6cb85efdc029b3341f00913be8c)
    #6 plugin_call_one ldap/servers/slapd/plugin.c:1950 (libslapd.so.0+0x1705d8) (BuildId: 803f112345cbf6cb85efdc029b3341f00913be8c)
    #7 plugin_dependency_startall ldap/servers/slapd/plugin.c:1705 (libslapd.so.0+0x1705d8)
    #8 main <null> (ns-slapd+0x24d04) (BuildId: 86cbd076fcddf331389add272237d51f6d03fced)

  Mutex M1 (0xffffaf164080) created at:
    #0 pthread_mutex_init <null> (libtsan.so.2+0x5cd98) (BuildId: 8d4ecf2b1838dee5e3128e6155efb961118b7f8d)
    #1 mdb_env_setup_locks <null> (liblmdb.so.0.0.0+0x10ef0) (BuildId: 9a258c36d62bedd1d1b75d9b7c00bad327a3bf63)
    #2 dbmdb_start ldap/servers/slapd/back-ldbm/db-mdb/mdb_layer.c:189 (libback-ldbm.so+0x136bd8) (BuildId: 167172cdc5fa19f7049dc63c805f0af75017d089)
    #3 dblayer_start ldap/servers/slapd/back-ldbm/dblayer.c:322 (libback-ldbm.so+0x4c30c) (BuildId: 167172cdc5fa19f7049dc63c805f0af75017d089)
    #4 ldbm_back_start ldap/servers/slapd/back-ldbm/start.c:115 (libback-ldbm.so+0xa28c0) (BuildId: 167172cdc5fa19f7049dc63c805f0af75017d089)
    #5 plugin_call_func ldap/servers/slapd/plugin.c:2001 (libslapd.so.0+0x16eb30) (BuildId: 803f112345cbf6cb85efdc029b3341f00913be8c)
    #6 plugin_call_one ldap/servers/slapd/plugin.c:1950 (libslapd.so.0+0x1705d8) (BuildId: 803f112345cbf6cb85efdc029b3341f00913be8c)
    #7 plugin_dependency_startall ldap/servers/slapd/plugin.c:1705 (libslapd.so.0+0x1705d8)
    #8 main <null> (ns-slapd+0x24d04) (BuildId: 86cbd076fcddf331389add272237d51f6d03fced)

  Mutex M2 (0xffffaaa23b00) created at:
    #0 pthread_rwlock_init <null> (libtsan.so.2+0x5a0ac) (BuildId: 8d4ecf2b1838dee5e3128e6155efb961118b7f8d)
    #1 slapi_new_rwlock <null> (libslapd.so.0+0x1a663c) (BuildId: 803f112345cbf6cb85efdc029b3341f00913be8c)
    #2 slapi_be_new <null> (libslapd.so.0+0xe8674) (BuildId: 803f112345cbf6cb85efdc029b3341f00913be8c)
    #3 ldbm_instance_generate ldap/servers/slapd/back-ldbm/ldbm_instance_config.c:887 (libback-ldbm.so+0x8b178) (BuildId: 167172cdc5fa19f7049dc63c805f0af75017d089)
    #4 ldbm_instance_add_instance_entry_callback ldap/servers/slapd/back-ldbm/ldbm_instance_config.c:1090 (libback-ldbm.so+0x8b5c8) (BuildId: 167172cdc5fa19f7049dc63c805f0af75017d089)
    #5 ldbm_config_read_instance_entries ldap/servers/slapd/back-ldbm/ldbm_config.c:1028 (libback-ldbm.so+0x6fe24) (BuildId: 167172cdc5fa19f7049dc63c805f0af75017d089)
    #6 ldbm_config_load_dse_info_phase1 ldap/servers/slapd/back-ldbm/ldbm_config.c:1155 (libback-ldbm.so+0x702a8) (BuildId: 167172cdc5fa19f7049dc63c805f0af75017d089)
    #7 dbimpl_setup ldap/servers/slapd/back-ldbm/dblayer.c:239 (libback-ldbm.so+0x5317c) (BuildId: 167172cdc5fa19f7049dc63c805f0af75017d089)
    #8 dblayer_setup ldap/servers/slapd/back-ldbm/dblayer.c:249 (libback-ldbm.so+0x53834) (BuildId: 167172cdc5fa19f7049dc63c805f0af75017d089)
    #9 ldbm_back_start ldap/servers/slapd/back-ldbm/start.c:45 (libback-ldbm.so+0xa27a4) (BuildId: 167172cdc5fa19f7049dc63c805f0af75017d089)
    #10 plugin_call_func ldap/servers/slapd/plugin.c:2001 (libslapd.so.0+0x16eb30) (BuildId: 803f112345cbf6cb85efdc029b3341f00913be8c)
    #11 plugin_call_one ldap/servers/slapd/plugin.c:1950 (libslapd.so.0+0x1705d8) (BuildId: 803f112345cbf6cb85efdc029b3341f00913be8c)
    #12 plugin_dependency_startall ldap/servers/slapd/plugin.c:1705 (libslapd.so.0+0x1705d8)
    #13 main <null> (ns-slapd+0x24d04) (BuildId: 86cbd076fcddf331389add272237d51f6d03fced)

  Thread T24 (tid=235474, running) created by thread T9 at:
    #0 pthread_create <null> (libtsan.so.2+0x5e2bc) (BuildId: 8d4ecf2b1838dee5e3128e6155efb961118b7f8d)
    #1 _PR_CreateThread <null> (libnspr4.so+0x30c20) (BuildId: f104b07bc930c7bf01e241a2cb46ea281c73a21b)
    #2 dse_call_callback.isra.0 ldap/servers/slapd/dse.c:2722 (libslapd.so.0+0x1e7568) (BuildId: 803f112345cbf6cb85efdc029b3341f00913be8c)
    #3 dse_add ldap/servers/slapd/dse.c:2410 (libslapd.so.0+0x104270) (BuildId: 803f112345cbf6cb85efdc029b3341f00913be8c)
    #4 op_shared_add ldap/servers/slapd/add.c:759 (libslapd.so.0+0xe5f58) (BuildId: 803f112345cbf6cb85efdc029b3341f00913be8c)
    #5 do_add <null> (libslapd.so.0+0xe70d0) (BuildId: 803f112345cbf6cb85efdc029b3341f00913be8c)
    #6 connection_dispatch_operation ldap/servers/slapd/connection.c:639 (ns-slapd+0x362a8) (BuildId: 86cbd076fcddf331389add272237d51f6d03fced)
    #7 connection_threadmain ldap/servers/slapd/connection.c:1921 (ns-slapd+0x362a8)
    #8 _pt_root <null> (libnspr4.so+0x30f3c) (BuildId: f104b07bc930c7bf01e241a2cb46ea281c73a21b)

  Thread T25 (tid=235475, running) created by thread T11 at:
    #0 pthread_create <null> (libtsan.so.2+0x5e2bc) (BuildId: 8d4ecf2b1838dee5e3128e6155efb961118b7f8d)
    #1 _PR_CreateThread <null> (libnspr4.so+0x30c20) (BuildId: f104b07bc930c7bf01e241a2cb46ea281c73a21b)
    #2 dse_call_callback.isra.0 ldap/servers/slapd/dse.c:2722 (libslapd.so.0+0x1e7568) (BuildId: 803f112345cbf6cb85efdc029b3341f00913be8c)
    #3 dse_add ldap/servers/slapd/dse.c:2410 (libslapd.so.0+0x104270) (BuildId: 803f112345cbf6cb85efdc029b3341f00913be8c)
    #4 op_shared_add ldap/servers/slapd/add.c:759 (libslapd.so.0+0xe5f58) (BuildId: 803f112345cbf6cb85efdc029b3341f00913be8c)
    #5 do_add <null> (libslapd.so.0+0xe70d0) (BuildId: 803f112345cbf6cb85efdc029b3341f00913be8c)
    #6 connection_dispatch_operation ldap/servers/slapd/connection.c:639 (ns-slapd+0x362a8) (BuildId: 86cbd076fcddf331389add272237d51f6d03fced)
    #7 connection_threadmain ldap/servers/slapd/connection.c:1921 (ns-slapd+0x362a8)
    #8 _pt_root <null> (libnspr4.so+0x30f3c) (BuildId: f104b07bc930c7bf01e241a2cb46ea281c73a21b)

SUMMARY: ThreadSanitizer: data race ldap/servers/plugins/memberof/memberof.c:2943 in memberof_fixup_task_thread
==================