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.16-1

However, when we enable MMR and update Passwords on a supplier the server segfaults:

audit log:

dn: uid=testuser@test.de,ou=People,dc=test,dc=de
result: 0
changetype: modify
replace: userPassword
userPassword:: e0JDUllQVH0kMmIkMTYkLi4uLi4uLi4uLkEzTnRlREwxNi4uLkMuYlE4SWhsYXl
 OZ1BaeENGdUxHNnd0LlMuTUova3k=
-
replace: modifiersname
modifiersname: uid=testuser@test.de,ou=people,dc=test,dc=de
-
replace: modifytimestamp
modifytimestamp: 20230403221428Z
-

time: 20230404001431
dn: uid=testuser@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@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@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@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@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.11-1

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