Blame SOURCES/0013-Issue-5329-Improve-replication-extended-op-logging.patch

cb1cc6
From 508a6dd02986024b03eeef62d135f7e16b0c85e9 Mon Sep 17 00:00:00 2001
cb1cc6
From: Mark Reynolds <mreynolds@redhat.com>
cb1cc6
Date: Thu, 2 Jun 2022 16:57:07 -0400
cb1cc6
Subject: [PATCH 1/4] Issue 5329 - Improve replication extended op logging
cb1cc6
cb1cc6
Description:
cb1cc6
cb1cc6
We need logging around parsing extended op payload, right now when it
cb1cc6
fails we have no idea why.
cb1cc6
cb1cc6
relates: https://github.com/389ds/389-ds-base/issues/5329
cb1cc6
cb1cc6
Reviewed by: progier, firstyear, and spichugi(Thanks!!!)
cb1cc6
---
cb1cc6
 ldap/servers/plugins/replication/repl_extop.c | 207 +++++++++++++++++-
cb1cc6
 ldap/servers/slapd/slapi2runtime.c            |   1 -
cb1cc6
 2 files changed, 197 insertions(+), 11 deletions(-)
cb1cc6
cb1cc6
diff --git a/ldap/servers/plugins/replication/repl_extop.c b/ldap/servers/plugins/replication/repl_extop.c
cb1cc6
index 8b178610b..70c45ec50 100644
cb1cc6
--- a/ldap/servers/plugins/replication/repl_extop.c
cb1cc6
+++ b/ldap/servers/plugins/replication/repl_extop.c
cb1cc6
@@ -73,6 +73,18 @@ done:
cb1cc6
     return rc;
cb1cc6
 }
cb1cc6
 
cb1cc6
+static void
cb1cc6
+ruv_dump_to_log(const RUV *ruv, char *log_name)
cb1cc6
+{
cb1cc6
+    if (!ruv) {
cb1cc6
+        slapi_log_err(SLAPI_LOG_REPL, repl_plugin_name, "%s: RUV: None\n", log_name);
cb1cc6
+    } else {
cb1cc6
+        slapi_log_err(SLAPI_LOG_REPL, repl_plugin_name, "%s: RUV:\n", log_name);
cb1cc6
+        ruv_dump(ruv, log_name, NULL);
cb1cc6
+    }
cb1cc6
+}
cb1cc6
+
cb1cc6
+
cb1cc6
 /* The data_guid and data parameters should only be set if we
cb1cc6
  * are talking with a 9.0 replica. */
cb1cc6
 static struct berval *
cb1cc6
@@ -95,33 +107,60 @@ create_ReplicationExtopPayload(const char *protocol_oid,
cb1cc6
     PR_ASSERT(protocol_oid != NULL || send_end);
cb1cc6
     PR_ASSERT(repl_root != NULL);
cb1cc6
 
cb1cc6
-    /* Create the request data */
cb1cc6
+    if (slapi_is_loglevel_set(SLAPI_LOG_REPL)) {
cb1cc6
+        slapi_log_err(SLAPI_LOG_REPL, repl_plugin_name, "create_ReplicationExtopPayload - "
cb1cc6
+                "encoding '%s' payload...\n",
cb1cc6
+                send_end ? "End Replication" : "Start Replication");
cb1cc6
+    }
cb1cc6
 
cb1cc6
+    /* Create the request data */
cb1cc6
     if ((tmp_bere = der_alloc()) == NULL) {
cb1cc6
+        slapi_log_err(SLAPI_LOG_ERR, "create_ReplicationExtopPayload",
cb1cc6
+                "encoding failed: der_alloc failed\n");
cb1cc6
         rc = LDAP_ENCODING_ERROR;
cb1cc6
         goto loser;
cb1cc6
     }
cb1cc6
     if (!send_end) {
cb1cc6
         if (ber_printf(tmp_bere, "{ss", protocol_oid, repl_root) == -1) {
cb1cc6
+            slapi_log_err(SLAPI_LOG_ERR, "create_ReplicationExtopPayload",
cb1cc6
+                    "encoding failed: ber_printf failed - protocol_oid (%s) repl_root (%s)\n",
cb1cc6
+                    protocol_oid, repl_root);
cb1cc6
             rc = LDAP_ENCODING_ERROR;
cb1cc6
             goto loser;
cb1cc6
         }
cb1cc6
+        if (slapi_is_loglevel_set(SLAPI_LOG_REPL)) {
cb1cc6
+            slapi_log_err(SLAPI_LOG_REPL, repl_plugin_name, "create_ReplicationExtopPayload - "
cb1cc6
+                    "encoding protocol_oid: %s\n", protocol_oid);
cb1cc6
+        }
cb1cc6
     } else {
cb1cc6
         if (ber_printf(tmp_bere, "{s", repl_root) == -1) {
cb1cc6
+            slapi_log_err(SLAPI_LOG_ERR, "create_ReplicationExtopPayload",
cb1cc6
+                    "encoding failed: ber_printf failed - repl_root (%s)\n",
cb1cc6
+                    repl_root);
cb1cc6
             rc = LDAP_ENCODING_ERROR;
cb1cc6
             goto loser;
cb1cc6
         }
cb1cc6
+        if (slapi_is_loglevel_set(SLAPI_LOG_REPL)) {
cb1cc6
+            slapi_log_err(SLAPI_LOG_REPL, repl_plugin_name, "create_ReplicationExtopPayload - "
cb1cc6
+                    "encoding repl_root: %s\n", repl_root);
cb1cc6
+        }
cb1cc6
     }
cb1cc6
 
cb1cc6
     sdn = slapi_sdn_new_dn_byref(repl_root);
cb1cc6
     repl = replica_get_replica_from_dn(sdn);
cb1cc6
     if (repl == NULL) {
cb1cc6
+        slapi_log_err(SLAPI_LOG_ERR, "create_ReplicationExtopPayload",
cb1cc6
+                "encoding failed: failed to get replica from dn (%s)\n",
cb1cc6
+                slapi_sdn_get_dn(sdn));
cb1cc6
         rc = LDAP_OPERATIONS_ERROR;
cb1cc6
         goto loser;
cb1cc6
     }
cb1cc6
 
cb1cc6
     ruv_obj = replica_get_ruv(repl);
cb1cc6
     if (ruv_obj == NULL) {
cb1cc6
+        slapi_log_err(SLAPI_LOG_ERR, "create_ReplicationExtopPayload",
cb1cc6
+                "encoding failed: failed to get ruv from replica suffix (%s)\n",
cb1cc6
+                slapi_sdn_get_dn(sdn));
cb1cc6
         rc = LDAP_OPERATIONS_ERROR;
cb1cc6
         goto loser;
cb1cc6
     }
cb1cc6
@@ -134,8 +173,14 @@ create_ReplicationExtopPayload(const char *protocol_oid,
cb1cc6
     /* We need to encode and send each time the local ruv in case we have changed it */
cb1cc6
     rc = encode_ruv(tmp_bere, ruv);
cb1cc6
     if (rc != 0) {
cb1cc6
+        slapi_log_err(SLAPI_LOG_ERR, "create_ReplicationExtopPayload",
cb1cc6
+                "encoding failed: encode_ruv failed for replica suffix (%s)\n",
cb1cc6
+                slapi_sdn_get_dn(sdn));
cb1cc6
         goto loser;
cb1cc6
     }
cb1cc6
+    if (slapi_is_loglevel_set(SLAPI_LOG_REPL)) {
cb1cc6
+        ruv_dump_to_log(ruv, "create_ReplicationExtopPayload");
cb1cc6
+    }
cb1cc6
 
cb1cc6
     if (!send_end) {
cb1cc6
         char s[CSN_STRSIZE];
cb1cc6
@@ -157,36 +202,67 @@ create_ReplicationExtopPayload(const char *protocol_oid,
cb1cc6
         charray_merge(&referrals_to_send, local_replica_referral, 0);
cb1cc6
         if (NULL != referrals_to_send) {
cb1cc6
             if (ber_printf(tmp_bere, "[v]", referrals_to_send) == -1) {
cb1cc6
+                slapi_log_err(SLAPI_LOG_ERR, "create_ReplicationExtopPayload",
cb1cc6
+                        "encoding failed: ber_printf (referrals_to_send)\n");
cb1cc6
                 rc = LDAP_ENCODING_ERROR;
cb1cc6
                 goto loser;
cb1cc6
             }
cb1cc6
+            if (slapi_is_loglevel_set(SLAPI_LOG_REPL)) {
cb1cc6
+                for (size_t i = 0; referrals_to_send[i]; i++) {
cb1cc6
+                    slapi_log_err(SLAPI_LOG_REPL, repl_plugin_name, "create_ReplicationExtopPayload - "
cb1cc6
+                            "encoding ref: %s\n", referrals_to_send[i]);
cb1cc6
+                }
cb1cc6
+            }
cb1cc6
             slapi_ch_free((void **)&referrals_to_send);
cb1cc6
         }
cb1cc6
         /* Add the CSN */
cb1cc6
         PR_ASSERT(NULL != csn);
cb1cc6
         if (ber_printf(tmp_bere, "s", csn_as_string(csn, PR_FALSE, s)) == -1) {
cb1cc6
+            slapi_log_err(SLAPI_LOG_ERR, "create_ReplicationExtopPayload",
cb1cc6
+                    "encoding failed: ber_printf (csnstr)\n");
cb1cc6
             rc = LDAP_ENCODING_ERROR;
cb1cc6
             goto loser;
cb1cc6
         }
cb1cc6
+        if (slapi_is_loglevel_set(SLAPI_LOG_REPL)) {
cb1cc6
+            slapi_log_err(SLAPI_LOG_REPL, repl_plugin_name, "create_ReplicationExtopPayload - "
cb1cc6
+                    "encoding csn: %s\n", csn_as_string(csn, PR_FALSE, s));
cb1cc6
+        }
cb1cc6
     }
cb1cc6
 
cb1cc6
     /* If we have data to send to a 9.0 style replica, set it here. */
cb1cc6
     if (data_guid && data) {
cb1cc6
         if (ber_printf(tmp_bere, "sO", data_guid, data) == -1) {
cb1cc6
+            slapi_log_err(SLAPI_LOG_ERR, "create_ReplicationExtopPayload",
cb1cc6
+                    "encoding failed: ber_printf (data_guid, data)\n");
cb1cc6
             rc = LDAP_ENCODING_ERROR;
cb1cc6
             goto loser;
cb1cc6
         }
cb1cc6
+        if (slapi_is_loglevel_set(SLAPI_LOG_REPL)) {
cb1cc6
+            slapi_log_err(SLAPI_LOG_REPL, repl_plugin_name, "create_ReplicationExtopPayload - "
cb1cc6
+                    "encoding data_guid (%s) data (%s:%ld)\n",
cb1cc6
+                    data_guid, data->bv_val, data->bv_len);
cb1cc6
+        }
cb1cc6
     }
cb1cc6
 
cb1cc6
+
cb1cc6
     if (ber_printf(tmp_bere, "}") == -1) {
cb1cc6
+        slapi_log_err(SLAPI_LOG_ERR, "create_ReplicationExtopPayload",
cb1cc6
+                "encoding failed: ber_printf\n");
cb1cc6
         rc = LDAP_ENCODING_ERROR;
cb1cc6
         goto loser;
cb1cc6
     }
cb1cc6
 
cb1cc6
     if (ber_flatten(tmp_bere, &req_data) == -1) {
cb1cc6
+        slapi_log_err(SLAPI_LOG_ERR, "create_ReplicationExtopPayload",
cb1cc6
+                "encoding failed: ber_flatten failed\n");
cb1cc6
         rc = LDAP_LOCAL_ERROR;
cb1cc6
         goto loser;
cb1cc6
     }
cb1cc6
+    if (slapi_is_loglevel_set(SLAPI_LOG_REPL)) {
cb1cc6
+        slapi_log_err(SLAPI_LOG_REPL, repl_plugin_name, "create_ReplicationExtopPayload - "
cb1cc6
+                "Encoding finished\n");
cb1cc6
+    }
cb1cc6
+
cb1cc6
     /* Success */
cb1cc6
     goto done;
cb1cc6
 
cb1cc6
@@ -293,8 +369,14 @@ decode_startrepl_extop(Slapi_PBlock *pb, char **protocol_oid, char **repl_root,
cb1cc6
     if ((NULL == extop_oid) ||
cb1cc6
         ((strcmp(extop_oid, REPL_START_NSDS50_REPLICATION_REQUEST_OID) != 0) &&
cb1cc6
          (strcmp(extop_oid, REPL_START_NSDS90_REPLICATION_REQUEST_OID) != 0)) ||
cb1cc6
-        !BV_HAS_DATA(extop_value)) {
cb1cc6
+        !BV_HAS_DATA(extop_value))
cb1cc6
+    {
cb1cc6
         /* bogus */
cb1cc6
+        slapi_log_err(SLAPI_LOG_ERR, "decode_startrepl_extop",
cb1cc6
+                "decoding failed: extop_oid (%s) (%s) extop_value (%s)\n",
cb1cc6
+                NULL == extop_oid ? "NULL" : "Ok",
cb1cc6
+                extop_oid ? extop_oid : "",
cb1cc6
+                extop_value ? !BV_HAS_DATA(extop_value) ? "No data" : "Ok" : "No data");
cb1cc6
         rc = -1;
cb1cc6
         goto free_and_return;
cb1cc6
     }
cb1cc6
@@ -307,25 +389,36 @@ decode_startrepl_extop(Slapi_PBlock *pb, char **protocol_oid, char **repl_root,
cb1cc6
     }
cb1cc6
 
cb1cc6
     if ((tmp_bere = ber_init(extop_value)) == NULL) {
cb1cc6
+        slapi_log_err(SLAPI_LOG_ERR, "decode_startrepl_extop",
cb1cc6
+                "decoding failed: ber_init for extop_value (%s:%lu)\n",
cb1cc6
+                extop_value->bv_val, extop_value->bv_len);
cb1cc6
         rc = -1;
cb1cc6
         goto free_and_return;
cb1cc6
     }
cb1cc6
     if (ber_scanf(tmp_bere, "{") == LBER_ERROR) {
cb1cc6
+        slapi_log_err(SLAPI_LOG_ERR, "decode_startrepl_extop",
cb1cc6
+                "decoding failed: ber_scanf 1\n");
cb1cc6
         rc = -1;
cb1cc6
         goto free_and_return;
cb1cc6
     }
cb1cc6
     /* Get the required protocol OID and root of replicated subtree */
cb1cc6
     if (ber_get_stringa(tmp_bere, protocol_oid) == LBER_DEFAULT) {
cb1cc6
+        slapi_log_err(SLAPI_LOG_ERR, "decode_startrepl_extop",
cb1cc6
+                "decoding failed: ber_get_stringa (protocol_oid)\n");
cb1cc6
         rc = -1;
cb1cc6
         goto free_and_return;
cb1cc6
     }
cb1cc6
     if (ber_get_stringa(tmp_bere, repl_root) == LBER_DEFAULT) {
cb1cc6
+        slapi_log_err(SLAPI_LOG_ERR, "decode_startrepl_extop",
cb1cc6
+                "decoding failed: ber_get_stringa (repl_root)\n");
cb1cc6
         rc = -1;
cb1cc6
         goto free_and_return;
cb1cc6
     }
cb1cc6
 
cb1cc6
     /* get supplier's ruv */
cb1cc6
     if (decode_ruv(tmp_bere, supplier_ruv) == -1) {
cb1cc6
+        slapi_log_err(SLAPI_LOG_ERR, "decode_startrepl_extop",
cb1cc6
+                "decoding failed: decode_ruv (supplier_ruv)\n");
cb1cc6
         rc = -1;
cb1cc6
         goto free_and_return;
cb1cc6
     }
cb1cc6
@@ -333,33 +426,45 @@ decode_startrepl_extop(Slapi_PBlock *pb, char **protocol_oid, char **repl_root,
cb1cc6
     /* Get the optional set of referral URLs */
cb1cc6
     if (ber_peek_tag(tmp_bere, &len) == LBER_SET) {
cb1cc6
         if (ber_scanf(tmp_bere, "[v]", extra_referrals) == LBER_ERROR) {
cb1cc6
+            slapi_log_err(SLAPI_LOG_ERR, "decode_startrepl_extop",
cb1cc6
+                    "decoding failed: ber_scanf (extra_referrals)\n");
cb1cc6
             rc = -1;
cb1cc6
             goto free_and_return;
cb1cc6
         }
cb1cc6
     }
cb1cc6
     /* Get the CSN */
cb1cc6
     if (ber_get_stringa(tmp_bere, csnstr) == LBER_ERROR) {
cb1cc6
+        slapi_log_err(SLAPI_LOG_ERR, "decode_startrepl_extop",
cb1cc6
+                "decoding failed: ber_get_stringa (csnstr)\n");
cb1cc6
         rc = -1;
cb1cc6
         goto free_and_return;
cb1cc6
     }
cb1cc6
     /* Get the optional replication session callback data. */
cb1cc6
     if (ber_peek_tag(tmp_bere, &len) == LBER_OCTETSTRING) {
cb1cc6
         if (ber_get_stringa(tmp_bere, data_guid) == LBER_ERROR) {
cb1cc6
+            slapi_log_err(SLAPI_LOG_ERR, "decode_startrepl_extop",
cb1cc6
+                    "decoding failed: ber_get_stringa (data_guid)\n");
cb1cc6
             rc = -1;
cb1cc6
             goto free_and_return;
cb1cc6
         }
cb1cc6
         /* If a data_guid was specified, data must be specified as well. */
cb1cc6
         if (ber_peek_tag(tmp_bere, &len) == LBER_OCTETSTRING) {
cb1cc6
             if (ber_get_stringal(tmp_bere, data) == LBER_ERROR) {
cb1cc6
+                slapi_log_err(SLAPI_LOG_ERR, "decode_startrepl_extop",
cb1cc6
+                        "decoding failed: ber_get_stringal (data)\n");
cb1cc6
                 rc = -1;
cb1cc6
                 goto free_and_return;
cb1cc6
             }
cb1cc6
         } else {
cb1cc6
+            slapi_log_err(SLAPI_LOG_ERR, "decode_startrepl_extop",
cb1cc6
+                    "decoding failed: ber_peek_tag\n");
cb1cc6
             rc = -1;
cb1cc6
             goto free_and_return;
cb1cc6
         }
cb1cc6
     }
cb1cc6
     if (ber_scanf(tmp_bere, "}") == LBER_ERROR) {
cb1cc6
+        slapi_log_err(SLAPI_LOG_ERR, "decode_startrepl_extop",
cb1cc6
+                "decoding failed: ber_scanf 2\n");
cb1cc6
         rc = -1;
cb1cc6
         goto free_and_return;
cb1cc6
     }
cb1cc6
@@ -378,6 +483,22 @@ free_and_return:
cb1cc6
         if (*supplier_ruv) {
cb1cc6
             ruv_destroy(supplier_ruv);
cb1cc6
         }
cb1cc6
+    } else if (slapi_is_loglevel_set(SLAPI_LOG_REPL)) {
cb1cc6
+        slapi_log_err(SLAPI_LOG_REPL, repl_plugin_name,
cb1cc6
+                "decode_startrepl_extop - decoding payload...\n");
cb1cc6
+        slapi_log_err(SLAPI_LOG_REPL, repl_plugin_name,
cb1cc6
+                "decode_startrepl_extop - decoded protocol_oid: %s\n", *protocol_oid);
cb1cc6
+        slapi_log_err(SLAPI_LOG_REPL, repl_plugin_name,
cb1cc6
+                "decode_startrepl_extop - decoded repl_root: %s\n", *repl_root);
cb1cc6
+        slapi_log_err(SLAPI_LOG_REPL, repl_plugin_name,
cb1cc6
+                "decode_startrepl_extop - decoded csn: %s\n", *csnstr);
cb1cc6
+        ruv_dump_to_log(*supplier_ruv, "decode_startrepl_extop");
cb1cc6
+        for (size_t i = 0; *extra_referrals && *extra_referrals[i]; i++) {
cb1cc6
+            slapi_log_err(SLAPI_LOG_REPL, repl_plugin_name, "decode_startrepl_extop - "
cb1cc6
+                "decoded referral: %s\n", *extra_referrals[i]);
cb1cc6
+        }
cb1cc6
+        slapi_log_err(SLAPI_LOG_REPL, repl_plugin_name,
cb1cc6
+                "decode_startrepl_extop - Finshed decoding payload.\n");
cb1cc6
     }
cb1cc6
     if (NULL != tmp_bere) {
cb1cc6
         ber_free(tmp_bere, 1);
cb1cc6
@@ -406,30 +527,54 @@ decode_endrepl_extop(Slapi_PBlock *pb, char **repl_root)
cb1cc6
 
cb1cc6
     if ((NULL == extop_oid) ||
cb1cc6
         (strcmp(extop_oid, REPL_END_NSDS50_REPLICATION_REQUEST_OID) != 0) ||
cb1cc6
-        !BV_HAS_DATA(extop_value)) {
cb1cc6
+        !BV_HAS_DATA(extop_value))
cb1cc6
+    {
cb1cc6
         /* bogus */
cb1cc6
+        slapi_log_err(SLAPI_LOG_ERR, "decode_endrepl_extop",
cb1cc6
+                "decoding failed: extop_oid (%s) correct oid (%s) extop_value data (%s)\n",
cb1cc6
+                extop_oid ? extop_oid : "NULL",
cb1cc6
+                extop_oid ? strcmp(extop_oid, REPL_END_NSDS50_REPLICATION_REQUEST_OID) != 0 ? "wrong oid" : "correct oid" : "NULL",
cb1cc6
+                !BV_HAS_DATA(extop_value) ? "No data" : "Has data");
cb1cc6
         rc = -1;
cb1cc6
         goto free_and_return;
cb1cc6
     }
cb1cc6
 
cb1cc6
     if ((tmp_bere = ber_init(extop_value)) == NULL) {
cb1cc6
+        slapi_log_err(SLAPI_LOG_ERR, "decode_endrepl_extop",
cb1cc6
+                "decoding failed: ber_init failed:  extop_value (%s:%lu)\n",
cb1cc6
+                extop_value->bv_val, extop_value->bv_len);
cb1cc6
         rc = -1;
cb1cc6
         goto free_and_return;
cb1cc6
     }
cb1cc6
     if (ber_scanf(tmp_bere, "{") == LBER_DEFAULT) {
cb1cc6
+        slapi_log_err(SLAPI_LOG_ERR, "decode_endrepl_extop",
cb1cc6
+                "decoding failed: ber_scanf failed1\n");
cb1cc6
         rc = -1;
cb1cc6
         goto free_and_return;
cb1cc6
     }
cb1cc6
     /* Get the required root of replicated subtree */
cb1cc6
     if (ber_get_stringa(tmp_bere, repl_root) == LBER_DEFAULT) {
cb1cc6
+        slapi_log_err(SLAPI_LOG_ERR, "decode_endrepl_extop",
cb1cc6
+                "decoding failed: ber_get_stringa failed\n");
cb1cc6
         rc = -1;
cb1cc6
         goto free_and_return;
cb1cc6
     }
cb1cc6
     if (ber_scanf(tmp_bere, "}") == LBER_DEFAULT) {
cb1cc6
+        slapi_log_err(SLAPI_LOG_ERR, "decode_endrepl_extop",
cb1cc6
+                "decoding failed: ber_scanf2 failed\n");
cb1cc6
         rc = -1;
cb1cc6
         goto free_and_return;
cb1cc6
     }
cb1cc6
 
cb1cc6
+    if (slapi_is_loglevel_set(SLAPI_LOG_REPL)) {
cb1cc6
+        slapi_log_err(SLAPI_LOG_REPL, "decode_endrepl_extop",
cb1cc6
+                "Decoding payload...\n");
cb1cc6
+        slapi_log_err(SLAPI_LOG_REPL, "decode_endrepl_extop",
cb1cc6
+                "Decoded repl_root: %s\n", *repl_root);
cb1cc6
+        slapi_log_err(SLAPI_LOG_REPL, "decode_endrepl_extop",
cb1cc6
+                "Finished decoding payload.\n");
cb1cc6
+    }
cb1cc6
+
cb1cc6
 free_and_return:
cb1cc6
     if (NULL != tmp_bere) {
cb1cc6
         ber_free(tmp_bere, 1);
cb1cc6
@@ -461,27 +606,46 @@ decode_repl_ext_response(struct berval *bvdata, int *response_code, struct berva
cb1cc6
     PR_ASSERT(NULL != ruv_bervals);
cb1cc6
 
cb1cc6
     if ((NULL == response_code) || (NULL == ruv_bervals) ||
cb1cc6
-        (NULL == data_guid) || (NULL == data) || !BV_HAS_DATA(bvdata)) {
cb1cc6
+        (NULL == data_guid) || (NULL == data) || !BV_HAS_DATA(bvdata))
cb1cc6
+    {
cb1cc6
+        slapi_log_err(SLAPI_LOG_ERR, "decode_repl_ext_response",
cb1cc6
+                "decoding failed: response_code (%s) ruv_bervals (%s) data_guid (%s) data (%s) bvdata (%s)\n",
cb1cc6
+                NULL == response_code ? "NULL" : "Ok",
cb1cc6
+                NULL == ruv_bervals ? "NULL" : "Ok",
cb1cc6
+                NULL == data_guid ? "NULL" : "Ok",
cb1cc6
+                NULL == data ? "NULL" : "Ok",
cb1cc6
+               !BV_HAS_DATA(bvdata) ? "No data" : "Ok");
cb1cc6
         return_value = -1;
cb1cc6
     } else {
cb1cc6
         ber_len_t len;
cb1cc6
         ber_int_t temp_response_code = 0;
cb1cc6
         *ruv_bervals = NULL;
cb1cc6
         if ((tmp_bere = ber_init(bvdata)) == NULL) {
cb1cc6
+            slapi_log_err(SLAPI_LOG_ERR, "decode_repl_ext_response",
cb1cc6
+                    "decoding failed: ber_init failed from bvdata (%s:%lu)\n",
cb1cc6
+                    bvdata->bv_val, bvdata->bv_len);
cb1cc6
             return_value = -1;
cb1cc6
         } else if (ber_scanf(tmp_bere, "{e", &temp_response_code) == LBER_ERROR) {
cb1cc6
+            slapi_log_err(SLAPI_LOG_ERR, "decode_repl_ext_response",
cb1cc6
+                    "decoding failed: ber_scanf failed\n");
cb1cc6
             return_value = -1;
cb1cc6
         } else if (ber_peek_tag(tmp_bere, &len) == LBER_SEQUENCE) {
cb1cc6
             if (ber_scanf(tmp_bere, "{V}", ruv_bervals) == LBER_ERROR) {
cb1cc6
+                slapi_log_err(SLAPI_LOG_ERR, "decode_repl_ext_response",
cb1cc6
+                     "decoding failed: ber_scanf2 failed from ruv_bervals\n");
cb1cc6
                 return_value = -1;
cb1cc6
             }
cb1cc6
         }
cb1cc6
         /* Check for optional data from replication session callback */
cb1cc6
         if (ber_peek_tag(tmp_bere, &len) == LBER_OCTETSTRING) {
cb1cc6
             if (ber_scanf(tmp_bere, "aO}", data_guid, data) == LBER_ERROR) {
cb1cc6
+                slapi_log_err(SLAPI_LOG_ERR, "decode_repl_ext_response",
cb1cc6
+                        "decoding failed: ber_scanf3 failed from data_guid & data\n");
cb1cc6
                 return_value = -1;
cb1cc6
             }
cb1cc6
         } else if (ber_scanf(tmp_bere, "}") == LBER_ERROR) {
cb1cc6
+            slapi_log_err(SLAPI_LOG_ERR, "decode_repl_ext_response",
cb1cc6
+                    "decoding failed: ber_scanf4 failed\n");
cb1cc6
             return_value = -1;
cb1cc6
         }
cb1cc6
 
cb1cc6
@@ -934,17 +1098,36 @@ send_response:
cb1cc6
         /* ONREPL - not sure what we suppose to do here */
cb1cc6
     }
cb1cc6
     ber_printf(resp_bere, "{e", response);
cb1cc6
+    if (slapi_is_loglevel_set(SLAPI_LOG_REPL)) {
cb1cc6
+        slapi_log_err(SLAPI_LOG_REPL, repl_plugin_name,
cb1cc6
+                "multisupplier_extop_StartNSDS50ReplicationRequest - encoded response: %d\n",
cb1cc6
+                response);
cb1cc6
+    }
cb1cc6
     if (NULL != ruv_bervals) {
cb1cc6
         ber_printf(resp_bere, "{V}", ruv_bervals);
cb1cc6
+        if (slapi_is_loglevel_set(SLAPI_LOG_REPL)) {
cb1cc6
+            ruv_dump_to_log(ruv, "multisupplier_extop_StartNSDS50ReplicationRequest");
cb1cc6
+        }
cb1cc6
     }
cb1cc6
+
cb1cc6
     /* Add extra data from replication session callback if necessary */
cb1cc6
     if (is90 && data_guid && data) {
cb1cc6
         ber_printf(resp_bere, "sO", data_guid, data);
cb1cc6
+        if (slapi_is_loglevel_set(SLAPI_LOG_REPL)) {
cb1cc6
+            slapi_log_err(SLAPI_LOG_REPL, repl_plugin_name,
cb1cc6
+                    "multisupplier_extop_StartNSDS50ReplicationRequest - encoded data_guid (%s) data (%s:%ld)\n",
cb1cc6
+                    data_guid, data->bv_val, data->bv_len);
cb1cc6
+        }
cb1cc6
     }
cb1cc6
 
cb1cc6
     ber_printf(resp_bere, "}");
cb1cc6
     ber_flatten(resp_bere, &resp_bval);
cb1cc6
 
cb1cc6
+    if (slapi_is_loglevel_set(SLAPI_LOG_REPL)) {
cb1cc6
+        slapi_log_err(SLAPI_LOG_REPL, repl_plugin_name,
cb1cc6
+                "multisupplier_extop_StartNSDS50ReplicationRequest - Finished encoding payload\n");
cb1cc6
+    }
cb1cc6
+
cb1cc6
     if (is90) {
cb1cc6
         slapi_pblock_set(pb, SLAPI_EXT_OP_RET_OID, REPL_NSDS90_REPLICATION_RESPONSE_OID);
cb1cc6
     } else {
cb1cc6
@@ -1005,8 +1188,8 @@ send_response:
cb1cc6
              * sending this request).
cb1cc6
              * The situation is confused
cb1cc6
              */
cb1cc6
-            slapi_log_err(SLAPI_LOG_REPL, repl_plugin_name, "multimaster_extop_StartNSDS50ReplicationRequest - "
cb1cc6
-                                                            "already acquired replica: replica not ready (%d) (replica=%s)\n",
cb1cc6
+            slapi_log_err(SLAPI_LOG_REPL, repl_plugin_name, "multisupplier_extop_StartNSDS50ReplicationRequest - "
cb1cc6
+                          "already acquired replica: replica not ready (%d) (replica=%s)\n",
cb1cc6
                           response, replica_get_name(r) ? replica_get_name(r) : "no name");
cb1cc6
 
cb1cc6
             /*
cb1cc6
@@ -1016,8 +1199,8 @@ send_response:
cb1cc6
             if (r) {
cb1cc6
 
cb1cc6
                 r_locking_conn = replica_get_locking_conn(r);
cb1cc6
-                slapi_log_err(SLAPI_LOG_REPL, repl_plugin_name, "multimaster_extop_StartNSDS50ReplicationRequest - "
cb1cc6
-                                                                "already acquired replica: locking_conn=%" PRIu64 ", current connid=%" PRIu64 "\n",
cb1cc6
+                slapi_log_err(SLAPI_LOG_REPL, repl_plugin_name, "multisupplier_extop_StartNSDS50ReplicationRequest - "
cb1cc6
+                              "already acquired replica: locking_conn=%" PRIu64 ", current connid=%" PRIu64 "\n",
cb1cc6
                               r_locking_conn, connid);
cb1cc6
 
cb1cc6
                 if ((r_locking_conn != ULONG_MAX) && (r_locking_conn == connid)) {
cb1cc6
@@ -1032,8 +1215,8 @@ send_response:
cb1cc6
              * On the supplier, we need to close the connection so
cb1cc6
              * that the RA will restart a new session in a clear state
cb1cc6
              */
cb1cc6
-            slapi_log_err(SLAPI_LOG_REPL, repl_plugin_name, "multimaster_extop_StartNSDS50ReplicationRequest - "
cb1cc6
-                                                            "already acquired replica: disconnect conn=%" PRIu64 "\n",
cb1cc6
+            slapi_log_err(SLAPI_LOG_REPL, repl_plugin_name, "multisupplier_extop_StartNSDS50ReplicationRequest - "
cb1cc6
+                           "already acquired replica: disconnect conn=%" PRIu64 "\n",
cb1cc6
                           connid);
cb1cc6
             slapi_disconnect_server(conn);
cb1cc6
         }
cb1cc6
@@ -1210,6 +1393,10 @@ send_response:
cb1cc6
     if ((resp_bere = der_alloc()) == NULL) {
cb1cc6
         goto free_and_return;
cb1cc6
     }
cb1cc6
+    if (slapi_is_loglevel_set(SLAPI_LOG_REPL)) {
cb1cc6
+        slapi_log_err(SLAPI_LOG_REPL, "multisupplier_extop_EndNSDS50ReplicationRequest",
cb1cc6
+                "encoded response: %d\n", response);
cb1cc6
+    }
cb1cc6
     ber_printf(resp_bere, "{e}", response);
cb1cc6
     ber_flatten(resp_bere, &resp_bval);
cb1cc6
     slapi_pblock_set(pb, SLAPI_EXT_OP_RET_OID, REPL_NSDS50_REPLICATION_RESPONSE_OID);
cb1cc6
diff --git a/ldap/servers/slapd/slapi2runtime.c b/ldap/servers/slapd/slapi2runtime.c
cb1cc6
index 53927934a..e622f1b65 100644
cb1cc6
--- a/ldap/servers/slapd/slapi2runtime.c
cb1cc6
+++ b/ldap/servers/slapd/slapi2runtime.c
cb1cc6
@@ -88,7 +88,6 @@ slapi_lock_mutex(Slapi_Mutex *mutex)
cb1cc6
 inline int __attribute__((always_inline))
cb1cc6
 slapi_unlock_mutex(Slapi_Mutex *mutex)
cb1cc6
 {
cb1cc6
-    PR_ASSERT(mutex != NULL);
cb1cc6
     if (mutex == NULL || pthread_mutex_unlock((pthread_mutex_t *)mutex) != 0) {
cb1cc6
         return (0);
cb1cc6
     } else {
cb1cc6
-- 
cb1cc6
2.37.1
cb1cc6