Blob Blame Raw
From 45f4abd6befa50b129fc49b331b42c280f37199a Mon Sep 17 00:00:00 2001
From: Mark Reynolds <mreynolds@redhat.com>
Date: Thu, 13 Jun 2019 13:01:35 -0400
Subject: [PATCH] Issue 49602 - Revise replication status messages

Bug Description: All agreement status messages start with "Error (##)" followed
                 by a text string.  Even success states start with "Error", and
                 this is confusing.

                 Added new attributes to display the status in a JSON format
                 for easier parsing for applications:

                     replicaLastUpdateStatusJSON
                     replicaLastInitStatusJSON

Design Doc:  https://www.port389.org/docs/389ds/design/repl-agmt-status-design.html

https://pagure.io/389-ds-base/issue/49602

Reviewed by: firstyear(Thanks!)
---
 .../suites/replication/single_master_test.py  | 19 +++--
 ldap/schema/01core389.ldif                    |  2 +
 ldap/servers/plugins/replication/repl5_agmt.c | 84 ++++++++++++++++---
 .../plugins/replication/repl5_protocol_util.c | 13 +--
 4 files changed, 96 insertions(+), 22 deletions(-)

diff --git a/dirsrvtests/tests/suites/replication/single_master_test.py b/dirsrvtests/tests/suites/replication/single_master_test.py
index 5b73e23ae..78f849da7 100644
--- a/dirsrvtests/tests/suites/replication/single_master_test.py
+++ b/dirsrvtests/tests/suites/replication/single_master_test.py
@@ -23,6 +23,7 @@ from lib389._constants import (ReplicaRole, DEFAULT_SUFFIX, REPLICAID_MASTER_1,
                                 REPLICATION_BIND_METHOD, REPLICATION_TRANSPORT, DEFAULT_BACKUPDIR,
                                 RA_NAME, RA_BINDDN, RA_BINDPW, RA_METHOD, RA_TRANSPORT_PROT,
                                 defaultProperties)
+import json
 
 pytestmark = pytest.mark.tier1
 
@@ -95,7 +96,7 @@ def test_mail_attr_repl(topo_r):
     consumer.start()
 
     log.info("Make a search for mail attribute in attempt to crash server")
-    consumer.search_s(DEFAULT_SUFFIX, ldap.SCOPE_SUBTREE, "(mail=testuser@redhat.com)", ["mail"])
+    c_user.get_attr_val("mail")
 
     log.info("Make sure that server hasn't crashed")
     repl.test_replication(master, consumer)
@@ -111,11 +112,13 @@ def test_lastupdate_attr_before_init(topo_nr):
         1. Check nsds5replicaLastUpdateStart value
         2. Check nsds5replicaLastUpdateEnd value
         3. Check nsds5replicaLastUpdateStatus value
+        4. Check nsds5replicaLastUpdateStatusJSON is parsable
     :expectedresults:
         1. nsds5replicaLastUpdateStart should be equal to 0
         2. nsds5replicaLastUpdateEnd should be equal to 0
         3. nsds5replicaLastUpdateStatus should not be equal
-           to "0 Replica acquired successfully: Incremental update started"
+           to "Replica acquired successfully: Incremental update started"
+        4. Success
     """
 
     master = topo_nr.ins["standalone1"]
@@ -139,11 +142,15 @@ def test_lastupdate_attr_before_init(topo_nr):
     with pytest.raises(Exception):
         repl.wait_for_replication(master, consumer, timeout=5)
 
-    assert agmt.get_attr_val_bytes('nsds5replicaLastUpdateStart') == b"19700101000000Z"
-    assert agmt.get_attr_val_bytes("nsds5replicaLastUpdateEnd") == b"19700101000000Z"
-    assert b"Replica acquired successfully" not in agmt.get_attr_val_bytes("nsds5replicaLastUpdateStatus")
-
+    assert agmt.get_attr_val_utf8('nsds5replicaLastUpdateStart') == "19700101000000Z"
+    assert agmt.get_attr_val_utf8("nsds5replicaLastUpdateEnd") == "19700101000000Z"
+    assert "replica acquired successfully" not in agmt.get_attr_val_utf8_l("nsds5replicaLastUpdateStatus")
 
+    # make sure the JSON attribute is parsable
+    json_status = agmt.get_attr_val_utf8("nsds5replicaLastUpdateStatusJSON")
+    if json_status is not None:
+        json_obj = json.loads(json_status)
+        log.debug("JSON status message: {}".format(json_obj))
 
 if __name__ == '__main__':
     # Run isolated
diff --git a/ldap/schema/01core389.ldif b/ldap/schema/01core389.ldif
index 993fa4a6d..7bf4acc5b 100644
--- a/ldap/schema/01core389.ldif
+++ b/ldap/schema/01core389.ldif
@@ -312,6 +312,8 @@ attributeTypes: ( 2.16.840.1.113730.3.1.2341 NAME 'nsslapd-changelogmaxentries'
 attributeTypes: ( 2.16.840.1.113730.3.1.2344 NAME 'nsslapd-tls-check-crl' DESC 'Check CRL when opening outbound TLS connections. Valid options are none, peer, all.' SYNTAX 1.3.6.1.4.1.1466.115.121.1.15 SINGLE-VALUE X-ORIGIN '389 Directory Server' )
 attributeTypes: ( 2.16.840.1.113730.3.1.2353 NAME 'nsslapd-encryptionalgorithm' DESC 'The encryption algorithm used to encrypt the changelog' SYNTAX 1.3.6.1.4.1.1466.115.121.1.15 SINGLE-VALUE X-ORIGIN '389 Directory Server' )
 attributeTypes: ( 2.16.840.1.113730.3.1.2084 NAME 'nsSymmetricKey' DESC 'A symmetric key - currently used by attribute encryption' SYNTAX 1.3.6.1.4.1.1466.115.121.1.40 SINGLE-VALUE X-ORIGIN 'attribute encryption' )
+attributeTypes: ( 2.16.840.1.113730.3.1.2364 NAME 'nsds5replicaLastInitStatusJSON' DESC 'Netscape defined attribute type' SYNTAX 1.3.6.1.4.1.1466.115.121.1.15 SINGLE-VALUE NO-USER-MODIFICATION X-ORIGIN 'Netscape Directory Server' )
+attributeTypes: ( 2.16.840.1.113730.3.1.2365 NAME 'nsds5replicaLastUpdateStatusJSON' DESC 'Netscape defined attribute type' SYNTAX 1.3.6.1.4.1.1466.115.121.1.15 SINGLE-VALUE NO-USER-MODIFICATION X-ORIGIN 'Netscape Directory Server' )
 #
 # objectclasses
 #
diff --git a/ldap/servers/plugins/replication/repl5_agmt.c b/ldap/servers/plugins/replication/repl5_agmt.c
index 53e6708c8..8e4586d8b 100644
--- a/ldap/servers/plugins/replication/repl5_agmt.c
+++ b/ldap/servers/plugins/replication/repl5_agmt.c
@@ -60,7 +60,11 @@
 #define DEFAULT_TIMEOUT 120             /* (seconds) default outbound LDAP connection */
 #define DEFAULT_FLOWCONTROL_WINDOW 1000 /* #entries sent without acknowledgment */
 #define DEFAULT_FLOWCONTROL_PAUSE 2000  /* msec of pause when #entries sent witout acknowledgment */
-#define STATUS_LEN 1024
+#define STATUS_LEN 2048
+#define STATUS_GOOD "green"
+#define STATUS_WARNING "amber"
+#define STATUS_BAD "red"
+
 
 struct changecounter
 {
@@ -93,11 +97,13 @@ typedef struct repl5agmt
     time_t last_update_start_time;       /* Local start time of last update session */
     time_t last_update_end_time;         /* Local end time of last update session */
     char last_update_status[STATUS_LEN]; /* Status of last update. Format = numeric code <space> textual description */
+    char last_update_status_json[STATUS_LEN];
     PRBool update_in_progress;
     PRBool is_enabled;
     time_t last_init_start_time;       /* Local start time of last total init */
     time_t last_init_end_time;         /* Local end time of last total init */
     char last_init_status[STATUS_LEN]; /* Status of last total init. Format = numeric code <space> textual description */
+    char last_init_status_json[STATUS_LEN];
     PRLock *lock;
     Object *consumerRUV;     /* last RUV received from the consumer - used for changelog purging */
     CSN *consumerSchemaCSN;  /* last schema CSN received from the consumer */
@@ -2443,6 +2449,21 @@ agmt_set_last_init_end(Repl_Agmt *ra, time_t end_time)
     }
 }
 
+static void
+agmt_set_last_update_status_json(Repl_Agmt *ra, char *state, int ldaprc, int replrc)
+{
+    char ts[SLAPI_TIMESTAMP_BUFSIZE];
+    time_t now;
+
+    time(&now);
+    strftime(ts, sizeof ts, "%FT%TZ", gmtime(&now));
+    PR_snprintf(ra->last_update_status_json, STATUS_LEN,
+            "{\"state\": \"%s\", \"ldap_rc\": \"%d\", \"ldap_rc_text\": \"%s\", "
+            "\"repl_rc\": \"%d\", \"repl_rc_text\": \"%s\", \"date\": \"%s\", \"message\": \"%s\"}",
+            state, ldaprc, ldap_err2string(ldaprc), replrc, protocol_response2string(replrc),
+            ts, ra->last_update_status);
+}
+
 void
 agmt_set_last_update_status(Repl_Agmt *ra, int ldaprc, int replrc, const char *message)
 {
@@ -2463,19 +2484,29 @@ agmt_set_last_update_status(Repl_Agmt *ra, int ldaprc, int replrc, const char *m
             PR_snprintf(ra->last_update_status, STATUS_LEN, "Error (%d) %s%s - LDAP error: %s%s%s%s",
                         ldaprc, message ? message : "", message ? "" : " - ",
                         slapi_err2string(ldaprc), replmsg ? " (" : "", replmsg ? replmsg : "", replmsg ? ")" : "");
+            agmt_set_last_update_status_json(ra, STATUS_BAD, ldaprc, replrc);
         }
         /* ldaprc == LDAP_SUCCESS */
         else if (replrc != 0) {
             if (replrc == NSDS50_REPL_REPLICA_BUSY) {
                 PR_snprintf(ra->last_update_status, STATUS_LEN,
-                            "Error (%d) Can't acquire busy replica", replrc);
+                            "Error (%d) Can't acquire busy replica (%s)",
+                            replrc, message ? message : "");
+                agmt_set_last_update_status_json(ra, STATUS_WARNING, ldaprc, replrc);
+            } else if (replrc == NSDS50_REPL_TRANSIENT_ERROR  || replrc == NSDS50_REPL_BACKOFF) {
+                PR_snprintf(ra->last_update_status, STATUS_LEN,
+                            "Error (%d) Can't acquire replica (%s)",
+                            replrc, message ? message : "");
+                agmt_set_last_update_status_json(ra, STATUS_WARNING, ldaprc, replrc);
             } else if (replrc == NSDS50_REPL_REPLICA_RELEASE_SUCCEEDED) {
                 PR_snprintf(ra->last_update_status, STATUS_LEN, "Error (0) Replication session successful");
+                agmt_set_last_update_status_json(ra, STATUS_GOOD, ldaprc, replrc);
             } else if (replrc == NSDS50_REPL_DISABLED) {
                 PR_snprintf(ra->last_update_status, STATUS_LEN, "Error (%d) Incremental update aborted: "
                                                                 "Replication agreement for %s\n can not be updated while the replica is disabled.\n"
                                                                 "(If the suffix is disabled you must enable it then restart the server for replication to take place).",
                             replrc, ra->long_name ? ra->long_name : "a replica");
+                agmt_set_last_update_status_json(ra, STATUS_BAD, ldaprc, replrc);
                 /* Log into the errors log, as "ra->long_name" is not accessible from the caller */
                 slapi_log_err(SLAPI_LOG_ERR, repl_plugin_name,
                               "Incremental update aborted: Replication agreement for \"%s\" "
@@ -2487,17 +2518,35 @@ agmt_set_last_update_status(Repl_Agmt *ra, int ldaprc, int replrc, const char *m
                 PR_snprintf(ra->last_update_status, STATUS_LEN,
                             "Error (%d) Replication error acquiring replica: %s%s(%s)",
                             replrc, message ? message : "", message ? " " : "", protocol_response2string(replrc));
+                agmt_set_last_update_status_json(ra, STATUS_BAD, ldaprc, replrc);
             }
         } else if (message != NULL) /* replrc == NSDS50_REPL_REPLICA_READY == 0 */
         {
             PR_snprintf(ra->last_update_status, STATUS_LEN,
                         "Error (0) Replica acquired successfully: %s", message);
+            agmt_set_last_update_status_json(ra, STATUS_GOOD, ldaprc, replrc);
         } else { /* agmt_set_last_update_status(0,0,NULL) to reset agmt */
             ra->last_update_status[0] = '\0';
+            ra->last_update_status_json[0] = '\0';
         }
     }
 }
 
+static void
+agmt_set_last_init_status_json(Repl_Agmt *ra, char *state, int ldaprc, int replrc, int connrc)
+{
+    char ts[SLAPI_TIMESTAMP_BUFSIZE];
+    time_t now;
+
+    time(&now);
+    strftime(ts, sizeof ts, "%FT%TZ", gmtime(&now));
+    PR_snprintf(ra->last_init_status_json, STATUS_LEN,
+            "{\"state\": \"%s\", \"ldap_rc\": \"%d\", \"ldap_rc_text\": \"%s\", \"repl_rc\": \"%d\", \"repl_rc_text\": \"%s\", "
+            "\"conn_rc\": \"%d\", \"conn_rc_text\": \"%s\", \"date\": \"%s\", \"message\": \"%s\"}",
+            state, ldaprc, ldap_err2string(ldaprc), replrc, protocol_response2string(replrc),
+            connrc, conn_result2string(connrc), ts, ra->last_init_status);
+}
+
 void
 agmt_set_last_init_status(Repl_Agmt *ra, int ldaprc, int replrc, int connrc, const char *message)
 {
@@ -2523,16 +2572,16 @@ agmt_set_last_init_status(Repl_Agmt *ra, int ldaprc, int replrc, int connrc, con
                     replmsg = NULL;
                 }
             }
-            PR_snprintf(ra->last_init_status, STATUS_LEN, "Error (%d) %s%sLDAP error: %s%s%s%s%s",
+            PR_snprintf(ra->last_init_status, STATUS_LEN, "Error (%d)%s%sLDAP error: %s%s%s%s%s",
                         ldaprc, message ? message : "", message ? "" : " - ",
                         slapi_err2string(ldaprc), replmsg ? " - " : "", replmsg ? replmsg : "",
                         connrc ? " - " : "", connrc ? connmsg : "");
+            agmt_set_last_init_status_json(ra, STATUS_BAD, ldaprc, replrc, connrc);
         }
         /* ldaprc == LDAP_SUCCESS */
         else if (replrc != 0) {
             if (replrc == NSDS50_REPL_REPLICA_RELEASE_SUCCEEDED) {
-                PR_snprintf(ra->last_init_status, STATUS_LEN, "Error (%d) %s",
-                            ldaprc, "Replication session successful");
+                PR_snprintf(ra->last_init_status, STATUS_LEN, "Replication session successful");
             } else if (replrc == NSDS50_REPL_DISABLED) {
                 if (agmt_is_enabled(ra)) {
                     slapi_log_err(SLAPI_LOG_ERR, repl_plugin_name, "Total update aborted: "
@@ -2543,6 +2592,7 @@ agmt_set_last_init_status(Repl_Agmt *ra, int ldaprc, int replrc, int connrc, con
                                                                   "Replication agreement for \"%s\" can not be updated while the suffix is disabled.\n"
                                                                   "You must enable it then restart the server for replication to take place).",
                                 replrc, ra->long_name ? ra->long_name : "a replica");
+                    agmt_set_last_init_status_json(ra, STATUS_BAD, ldaprc, replrc, connrc);
                 } else {
                     /* You do not need to restart the server after enabling the agreement */
                     slapi_log_err(SLAPI_LOG_ERR, repl_plugin_name, "Total update aborted: "
@@ -2551,6 +2601,7 @@ agmt_set_last_init_status(Repl_Agmt *ra, int ldaprc, int replrc, int connrc, con
                     PR_snprintf(ra->last_init_status, STATUS_LEN, "Error (%d) Total update aborted: "
                                                                   "Replication agreement for \"%s\" can not be updated while the agreement is disabled.",
                                 replrc, ra->long_name ? ra->long_name : "a replica");
+                    agmt_set_last_init_status_json(ra, STATUS_BAD, ldaprc, replrc, connrc);
                 }
             } else {
                 PR_snprintf(ra->last_init_status, STATUS_LEN,
@@ -2558,19 +2609,21 @@ agmt_set_last_init_status(Repl_Agmt *ra, int ldaprc, int replrc, int connrc, con
                             replrc, protocol_response2string(replrc),
                             message ? " - " : "", message ? message : "",
                             connrc ? " - " : "", connrc ? connmsg : "");
+                agmt_set_last_init_status_json(ra, STATUS_BAD, ldaprc, replrc, connrc);
             }
         } else if (connrc != CONN_OPERATION_SUCCESS) {
             PR_snprintf(ra->last_init_status, STATUS_LEN,
                         "Error (%d) connection error: %s%s%s",
                         connrc, connmsg,
                         message ? " - " : "", message ? message : "");
-        } else if (message != NULL) /* replrc == NSDS50_REPL_REPLICA_READY == 0 */
-        {
+            agmt_set_last_init_status_json(ra, STATUS_BAD, ldaprc, replrc, connrc);
+        } else if (message != NULL) { /* replrc == NSDS50_REPL_REPLICA_READY == 0 */
             PR_snprintf(ra->last_init_status, STATUS_LEN,
-                        "Error (%d) %s",
-                        ldaprc, message);
+                        "Error (%d) %s", ldaprc, message);
+            agmt_set_last_init_status_json(ra, STATUS_GOOD, ldaprc, replrc, connrc);
         } else { /* agmt_set_last_init_status(0,0,NULL) to reset agmt */
-            PR_snprintf(ra->last_init_status, STATUS_LEN, "Error (%d)", ldaprc);
+            ra->last_init_status[0] = '\0';
+            ra->last_init_status_json[0] = '\0';
         }
     }
 }
@@ -2705,10 +2758,20 @@ get_agmt_status(Slapi_PBlock *pb __attribute__((unused)),
         agmt_get_changecount_string(ra, changecount_string, sizeof(changecount_string));
         slapi_entry_add_string(e, "nsds5replicaChangesSentSinceStartup", changecount_string);
         if (ra->last_update_status[0] == '\0') {
+            char status_msg[STATUS_LEN];
+            char ts[SLAPI_TIMESTAMP_BUFSIZE];
+            time_t now;
+            time(&now);
+            strftime(ts, sizeof ts, "%FT%TZ", gmtime(&now));
             slapi_entry_add_string(e, "nsds5replicaLastUpdateStatus",
                                    "Error (0) No replication sessions started since server startup");
+            PR_snprintf(status_msg, STATUS_LEN,
+                    "{\"state\": \"green\", \"ldap_rc\": \"0\", \"ldap_rc_text\": \"success\", \"repl_rc\": \"0\", \"repl_rc_text\": \"replica acquired\", "
+                    "\"date\": \"%s\", \"message\": \"Error (0) No replication sessions started since server startup\"}", ts);
+            slapi_entry_add_string(e, "nsds5replicaLastUpdateStatusJSON", status_msg);
         } else {
             slapi_entry_add_string(e, "nsds5replicaLastUpdateStatus", ra->last_update_status);
+            slapi_entry_add_string(e, "nsds5replicaLastUpdateStatusJSON", ra->last_update_status_json);
         }
         slapi_entry_add_string(e, "nsds5replicaUpdateInProgress", ra->update_in_progress ? "TRUE" : "FALSE");
 
@@ -2724,6 +2787,7 @@ get_agmt_status(Slapi_PBlock *pb __attribute__((unused)),
 
         if (ra->last_init_status[0] != '\0') {
             slapi_entry_add_string(e, "nsds5replicaLastInitStatus", ra->last_init_status);
+            slapi_entry_add_string(e, "nsds5replicaLastInitStatusJSON", ra->last_init_status_json);
         }
     }
 bail:
diff --git a/ldap/servers/plugins/replication/repl5_protocol_util.c b/ldap/servers/plugins/replication/repl5_protocol_util.c
index a48d4d02a..bb9f9e7e1 100644
--- a/ldap/servers/plugins/replication/repl5_protocol_util.c
+++ b/ldap/servers/plugins/replication/repl5_protocol_util.c
@@ -374,13 +374,13 @@ acquire_replica(Private_Repl_Protocol *prp, char *prot_oid, RUV **ruv)
                                       "has the same Replica ID as this one. "
                                       "Replication is aborting.\n",
                                       agmt_get_long_name(prp->agmt));
-                        agmt_set_last_update_status(prp->agmt, 0, 0,
-                                                    "Unable to aquire replica: the replica has the same "
+                        agmt_set_last_update_status(prp->agmt, 0, NSDS50_REPL_REPLICAID_ERROR,
+                                                    "Unable to acquire replica: the replica has the same "
                                                     "Replica ID as this one. Replication is aborting.");
                         return_value = ACQUIRE_FATAL_ERROR;
                         break;
                     case NSDS50_REPL_BACKOFF:
-                        /* A replication sesssion hook on the replica
+                        /* A replication session hook on the replica
                          * wants us to go into backoff mode. */
                         slapi_log_err(SLAPI_LOG_ERR, repl_plugin_name,
                                       "acquire_replica - "
@@ -487,9 +487,8 @@ acquire_replica(Private_Repl_Protocol *prp, char *prot_oid, RUV **ruv)
                           "%s: Unable to obtain current CSN. "
                           "Replication is aborting.\n",
                           agmt_get_long_name(prp->agmt));
-            agmt_set_last_update_status(prp->agmt, 0, 0,
-                                        "Unable to obtain current CSN. "
-                                        "Replication is aborting.");
+            agmt_set_last_update_status(prp->agmt, 0, NSDS50_REPL_INTERNAL_ERROR,
+                                        "Unable to obtain current CSN. Replication is aborting.");
             return_value = ACQUIRE_FATAL_ERROR;
         }
     }
@@ -665,6 +664,8 @@ protocol_response2string(int response)
         return "transient warning";
     case NSDS50_REPL_RUV_ERROR:
         return "RUV error";
+    case NSDS50_REPL_REPLICA_NO_RESPONSE:
+        return "no response received";
     default:
         return "unknown error";
     }
-- 
2.21.0