Hi *,
we digged deeper into the issue: and the problem is a null pointer here,
during replication:
#0 csn_get_replicaid (csn=csn@entry=0x0) at ../ldap/servers/slapd/csn.c:167
#1 0x00007ffff42b2f09 in ruv_cancel_csn_inprogress
(repl=repl@entry=0x5555578a2950, ruv=0x55555789dcc0, csn=csn@entry=0x0,
local_rid=local_rid@entry=104) at ../ldap/servers/plugins/replication/repl5_ruv.c:1594
#2 0x00007ffff429cb10 in cancel_opcsn (pb=pb@entry=0x7fff70000b60)
at ../ldap/servers/plugins/replication/repl5_plugins.c:1322
#3 0x00007ffff429d5a8 in write_changelog_and_ruv (pb=0x7fff70000b60)
at ../ldap/servers/plugins/replication/repl5_plugins.c:983
#4 0x00007ffff429e84d in multimaster_mmr_postop (pb=0x7fff70000b60, flags=561)
at ../ldap/servers/plugins/replication/repl5_plugins.c:618
#5 0x00007ffff7f2820d in plugin_call_mmr_plugin_postop
(pb=pb@entry=0x7fff70000b60, e=e@entry=0x0, flags=flags@entry=561)
at ../ldap/servers/slapd/plugin_mmr.c:65
#6 0x00007ffff438450c in ldbm_back_modify (pb=0x7fff70000b60)
at ../ldap/servers/slapd/back-ldbm/ldbm_modify.c:1089
#7 0x00007ffff7f108ca in op_shared_modify
(pb=pb@entry=0x7fff70000b60, pw_change=pw_change@entry=0, old_pw=0x0)
at ../ldap/servers/slapd/modify.c:1022
#8 0x00007ffff7f117bd in do_modify (pb=pb@entry=0x7fff70000b60)
at ../ldap/servers/slapd/modify.c:377
#9 0x000055555556de9b in connection_dispatch_operation
(pb=0x7fff70000b60, op=<optimized out>, conn=<optimized out>)
at ../ldap/servers/slapd/connection.c:635
#10 connection_threadmain () at ../ldap/servers/slapd/connection.c:1785
#11 0x00007ffff7c11941 in ??? () at /lib/x86_64-linux-gnu/libnspr4.so
and we could reproduce the problem whenever we used an user with an ACI
that had an IP restriction.
Finally the commit message of this bug
/Issue 4797 - ACL IP ADDRESS evaluation may corrupt
c_isreplication_session connection flags (#4799)/
gave us the hint to fix this. We patched the build for debian
and now everything works as espected.
Thanks for your work!
On 04.04.23 02:31, Harald Strack wrote:
Hi Thierry,
we built a new Version based on this commit, that includes the patch:
https://salsa.debian.org/freeipa-team/389-ds-base/-/commits/debian/1.4.4....
However, when we enable MMR and update Passwords on a supplier the
server segfaults:
audit log:
dn: uid=testuser(a)test.de,ou=People,dc=test,dc=de
result: 0
changetype: modify
replace: userPassword
userPassword::
e0JDUllQVH0kMmIkMTYkLi4uLi4uLi4uLkEzTnRlREwxNi4uLkMuYlE4SWhsYXl
OZ1BaeENGdUxHNnd0LlMuTUova3k=
-
replace: modifiersname
modifiersname: uid=testuser(a)test.de,ou=people,dc=test,dc=de
-
replace: modifytimestamp
modifytimestamp: 20230403221428Z
-
time: 20230404001431
dn: uid=testuser(a)test.de,ou=People,dc=test,dc=de
result: 0
changetype: modify
replace: shadowLastChange
shadowLastChange: 19450
-
time: 20230404001437
dn: cn=uniqueid generator,cn=config
result: 0
changetype: modify
replace: nsState
nsState:: gESj62zS7QHVNtk3vH099gAAAAAAAAAA
Just before the server segfaults:
*[04/Apr/2023:00:14:34.906956463 +0200] - ERR - NSMMReplicationPlugin
- IsValidOperation - NULL operation CSN**
**[04/Apr/2023:00:14:35.078898697 +0200] - ERR - NSMMReplicationPlugin
- write_changelog_and_ruv - Can't add a change for
uid=testuser(a)test.de,ou=People,dc=test,dc=de (uniqid: (null), optype:
8) to changelog csn *
When the server is running with
$ /usr/sbin/ns-slapd -D /etc/dirsrv/slapd-ldap02 -i
/run/dirsrv/slapd-ldap02.pid -d 8200
[04/Apr/2023:01:57:46.794635411 +0200] - DEBUG -
connection_table_dump_activity_to_errors_log - activity on 137r
[04/Apr/2023:01:57:46.798242424 +0200] - DEBUG - handle_pr_read_ready
- read activity on 137
[04/Apr/2023:01:57:46.801677697 +0200] - DEBUG - NSMMReplicationPlugin
- release_replica - agmt="cn=168.119.133.209" (168:636): Successfully
released consumer
[04/Apr/2023:01:57:46.826126621 +0200] - DEBUG - NSMMReplicationPlugin
- conn_start_linger -agmt="cn=168.119.133.209" (168:636) - Beginning
linger on the connection
[04/Apr/2023:01:57:46.829122095 +0200] - DEBUG -
connection_check_activity_level - conn 136 activity level = 0
[04/Apr/2023:01:57:46.832174669 +0200] - DEBUG - handle_pr_read_ready
- read activity on 135
[04/Apr/2023:01:57:46.835644233 +0200] - DEBUG -
connection_read_operation - connection 137 waited 1 times for read to
be ready
[04/Apr/2023:01:57:46.842275810 +0200] - DEBUG - NSMMReplicationPlugin
- conn_start_linger -agmt="cn=168.119.133.208" (168:636) - Beginning
linger on the connection
[04/Apr/2023:01:57:46.845508214 +0200] - DEBUG - NSMMReplicationPlugin
- repl5_inc_run - agmt="cn=168.119.133.209" (168:636): State:
sending_updates -> wait_for_changes
[04/Apr/2023:01:57:46.848642908 +0200] - DEBUG -
connection_make_readable_nolock - making readable conn 136 fd=84
[04/Apr/2023:01:57:46.851710732 +0200] - DEBUG - clear_signal -
Listener got signaled
[04/Apr/2023:01:57:46.872921861 +0200] - DEBUG -
connection_read_operation - connection 135 read 128 bytes
[04/Apr/2023:01:57:46.876223625 +0200] - DEBUG - connection_threadmain
- conn 135 read operation successfully - thread_turbo_flag 0 more_data
0 ops_initiated 4 refcnt 2 flags 1
[04/Apr/2023:01:57:46.878961280 +0200] - DEBUG -
connection_make_readable_nolock - making readable conn 135 fd=86
[04/Apr/2023:01:57:46.882027474 +0200] - DEBUG - connection_threadmain
- conn 136 check more_data 0 thread_turbo_flag 0repl_conn_bef 0,
repl_conn_now 0
[04/Apr/2023:01:57:46.895755108 +0200] - DEBUG - NSMMReplicationPlugin
- repl5_inc_run - agmt="cn=168.119.133.208" (168:636): State:
sending_updates -> wait_for_changes
[04/Apr/2023:01:57:46.898725492 +0200] - DEBUG -
connection_read_operation - connection 137 waited 2 times for read to
be ready
[04/Apr/2023:01:57:46.901590277 +0200] - DEBUG - connection_threadmain
- conn 135 check more_data 0 thread_turbo_flag 0repl_conn_bef 0,
repl_conn_now 0
[04/Apr/2023:01:57:46.904535831 +0200] - DEBUG -
connection_read_operation - connection 137 read 69 bytes
[04/Apr/2023:01:57:46.908875673 +0200] - DEBUG - connection_threadmain
- conn 137 read operation successfully - thread_turbo_flag 0 more_data
0 ops_initiated 1 refcnt 2 flags 1
[04/Apr/2023:01:57:46.937355189 +0200] - DEBUG - clear_signal -
Listener got signaled
[04/Apr/2023:01:57:46.940642472 +0200] - DEBUG -
connection_check_activity_level - conn 137 activity level = 0
[04/Apr/2023:01:57:46.943520957 +0200] - DEBUG -
connection_table_dump_activity_to_errors_log - activity on 63r
[04/Apr/2023:01:57:46.946436111 +0200] - DEBUG -
connection_make_readable_nolock - making readable conn 137 fd=91
[04/Apr/2023:01:57:46.949539905 +0200] - DEBUG -
connection_table_dump_activity_to_errors_log - activity on 136r
[04/Apr/2023:01:57:46.971823503 +0200] - DEBUG - connection_threadmain
- conn 137 check more_data 0 thread_turbo_flag 0repl_conn_bef 0,
repl_conn_now 0
[04/Apr/2023:01:57:46.976851863 +0200] - DEBUG - handle_pr_read_ready
- read activity on 136
[04/Apr/2023:01:57:46.980319317 +0200] - DEBUG - handle_pr_read_ready
- read activity on 63
[04/Apr/2023:01:57:46.983570170 +0200] - DEBUG -
connection_read_operation - connection 136 read 7 bytes
[04/Apr/2023:01:57:46.992242074 +0200] - DEBUG -
connection_read_operation - connection 63 read 157 bytes
[04/Apr/2023:01:57:46.995318158 +0200] - DEBUG - connection_threadmain
- conn 136 read operation successfully - thread_turbo_flag 0 more_data
0 ops_initiated 2 refcnt 2 flags 1
[04/Apr/2023:01:57:46.998488642 +0200] - DEBUG - connection_threadmain
- conn 63 read operation successfully - thread_turbo_flag 0 more_data
0 ops_initiated 25 refcnt 2 flags 1
[04/Apr/2023:01:57:47.001869195 +0200] - DEBUG -
connection_table_dump_activity_to_errors_log - activity on 137r
[04/Apr/2023:01:57:47.022358186 +0200] - DEBUG -
disconnect_server_nomutex_ext - Setting conn 136 fd=84 to be
disconnected: reason -4991
[04/Apr/2023:01:57:47.026239889 +0200] - DEBUG -
connection_check_activity_level - conn 63 activity level = 18
[04/Apr/2023:01:57:47.031562919 +0200] - DEBUG - handle_pr_read_ready
- read activity on 137
[04/Apr/2023:01:57:47.056184893 +0200] - DEBUG - connection_threadmain
- conn 136 check more_data 0 thread_turbo_flag 0repl_conn_bef 0,
repl_conn_now 0
[04/Apr/2023:01:57:47.060182805 +0200] - DEBUG -
connection_enter_leave_turbo - conn 63 turbo rank = 0 out of 28 conns
[04/Apr/2023:01:57:47.068125600 +0200] - DEBUG -
connection_read_operation - connection 137 read 77 bytes
[04/Apr/2023:01:57:47.072979011 +0200] - DEBUG - clear_signal -
Listener got signaled
[04/Apr/2023:01:57:47.077046753 +0200] - DEBUG -
connection_enter_leave_turbo - conn 63 entering turbo mode
[04/Apr/2023:01:57:47.091249546 +0200] - DEBUG - connection_threadmain
- conn 137 read operation successfully - thread_turbo_flag 0 more_data
0 ops_initiated 2 refcnt 2 flags 1
[04/Apr/2023:01:57:47.107753434 +0200] - DEBUG -
connection_table_move_connection_out_of_active_list - Moved conn 84
out of active list and freed
[04/Apr/2023:01:57:47.113208364 +0200] - DEBUG - connection_threadmain
- conn 63 check more_data 0 thread_turbo_flag 1repl_conn_bef
583204874, repl_conn_now 583204874
[04/Apr/2023:01:57:47.128344235 +0200] - DEBUG -
connection_make_readable_nolock - making readable conn 137 fd=91
[04/Apr/2023:01:57:47.131891528 +0200] - DEBUG -
connection_read_operation - connection 63 read 125 bytes
[04/Apr/2023:01:57:47.135508682 +0200] - DEBUG - connection_threadmain
- conn 137 check more_data 0 thread_turbo_flag 0repl_conn_bef 0,
repl_conn_now 0
[04/Apr/2023:01:57:47.153368147 +0200] - DEBUG - connection_threadmain
- conn 63 read operation successfully - thread_turbo_flag 1 more_data
0 ops_initiated 26 refcnt 2 flags 1
[04/Apr/2023:01:57:47.171031014 +0200] - DEBUG - clear_signal -
Listener got signaled
[04/Apr/2023:01:57:47.200732177 +0200] - DEBUG - NSMMReplicationPlugin
- purge_entry_state_information - From entry
uid=testuser(a)test.de,ou=People,dc=test,dc=de up to CSN
64222d7c0001006a0000
[04/Apr/2023:01:57:47.208218783 +0200] - DEBUG -
connection_table_dump_activity_to_errors_log - activity on 137r
[04/Apr/2023:01:57:47.211990356 +0200] - DEBUG - handle_pr_read_ready
- read activity on 137
[04/Apr/2023:01:57:47.220433720 +0200] - DEBUG - NSMMReplicationPlugin
- write_changelog_and_ruv - Writing change for
uid=testuser(a)test.de,ou=People,dc=test,dc=de (uniqid: (null), optype:
8) to changelog csn
[04/Apr/2023:01:57:47.230227401 +0200] - DEBUG -
connection_read_operation - connection 137 read 77 bytes
[04/Apr/2023:01:57:47.242081278 +0200] - DEBUG - connection_threadmain
- conn 137 read operation successfully - thread_turbo_flag 0 more_data
0 ops_initiated 3 refcnt 2 flags 1
[04/Apr/2023:01:57:47.250856202 +0200] - DEBUG -
connection_make_readable_nolock - making readable conn 137 fd=91
[04/Apr/2023:01:57:47.255230563 +0200] - DEBUG - replication -
multimaster_mmr_postop - error -1 for operation 561.
[04/Apr/2023:01:57:47.263485397 +0200] - DEBUG - clear_signal -
Listener got signaled
Segmentation fault
Without replication it just runs fine... Any idea what is causing the
NSMMReplicationPlugin - write_changelog_and_ruv - Writing change for
uid=testuser(a)test.de,ou=People,dc=test,dc=de (uniqid: (null), optype:
8) to changelog csn
?
br
Harald
On 28.03.23 15:49, Thierry Bordaz wrote:
> Hi Harald,
>
> I agree a probable cause of your message is #4644. THe impact of the
> bug varies depending on the size of the changelog and how frequent
> you have large updates. The bug slowdown replication but eventually
> replication should succeed. If large updates are rare, then you
> should not hit it that frequently.
>
> regards
> thierry
>
> On 3/28/23 15:40, Harald Strack wrote:
>> Hi Thierry,
>>
>> thanks for digging this out! We use Version 1.4.4.11-2 on debian
>> bullseye:
>>
>>
https://packages.debian.org/bullseye/389-ds
>>
>> appearently the commits from #4644 are missing there, just one month
>> or so :-(
>>
>>
https://salsa.debian.org/freeipa-team/389-ds-base/-/commits/debian/1.4.4....
>>
>>
>> Seems that we have to upgrade and build our own packages? ... or run
>> it all in podman with rocky linux. Any suggestions?
>>
>> br
>>
>> Harald
>>
>>
>>
>> On 28.03.23 14:25, Thierry Bordaz wrote:
>>>
>>> Hi Harald,
>>>
>>> What version of 389ds are you running ?
>>>
>>> This message was introduced with #4492[1] and caught a weird
>>> condition where a replication agreement was loading changes that
>>> are older of the starting point of the replication. Finally it
>>> appeared that #4492 was likely related to #4644 [2] that was
>>> identified a bit later.
>>>
>>> One of the condition to hit #4644 [2] is that some changes are
>>> large (several Mb). Do you know if it applies to your deployment.
>>>
>>> [1]
https://github.com/389ds/389-ds-base/issues/4492
>>> [2]
https://github.com/389ds/389-ds-base/issues/4644
>>>
>>> regards
>>> thierry
>>>
>
--
Harald Strack
Geschäftsführer
ssystems GmbH
Kastanienallee 74
10435 Berlin
_______________________________________________
389-devel mailing list --389-devel(a)lists.fedoraproject.org
To unsubscribe send an email to389-devel-leave(a)lists.fedoraproject.org
Fedora Code of
Conduct:https://docs.fedoraproject.org/en-US/project/code-of-conduct/
List
Guidelines:https://fedoraproject.org/wiki/Mailing_list_guidelines
List
Archives:https://lists.fedoraproject.org/archives/list/389-devel@lists.fe...
Do not reply to spam, report it:https://pagure.io/fedora-infrastructure/new_issue
--
Harald Strack
Geschäftsführer
ssystems GmbH
Kastanienallee 74
10435 Berlin