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