Issue 6599 - Access JSON logging - lib389/CI/minor fixes

Description:

Update lib389 for the JSON format, added a CI test, and fixed some minor
bugs

Relates: #6599

Reviewed by: jchapman, progier (Thanks!!)

ldap/servers/slapd/accesslog.c

@@ -602,7 +602,7 @@ slapd_log_access_modrdn(slapd_log_pblock *logpb)
     if (logpb->newsup) {
         json_object_object_add(json_obj, "newsup", json_obj_add_str(logpb->newsup));
     }
-    json_object_object_add(json_obj, "deletoldrdn", json_object_new_boolean(logpb->deletoldrdn));
+    json_object_object_add(json_obj, "deleteoldrdn", json_object_new_boolean(logpb->deleteoldrdn));
 
     /* Convert json object to string and log it */
     msg = (char *)json_object_to_json_string_ext(json_obj, logpb->log_format);
@@ -643,6 +643,7 @@ slapd_log_access_modrdn(slapd_log_pblock *logpb)
 int32_t
 slapd_log_access_result(slapd_log_pblock *logpb)
 {
+    Connection *conn = NULL;
     int32_t rc = 0;
     char *msg = NULL;
     json_object *json_obj = NULL;
@@ -651,23 +652,28 @@ slapd_log_access_result(slapd_log_pblock *logpb)
         return rc;
     }
 
+    slapi_pblock_get(logpb->pb, SLAPI_CONNECTION, &conn); /* For IP addr */
+
     json_object_object_add(json_obj, "tag", json_object_new_int(logpb->tag));
     json_object_object_add(json_obj, "err", json_object_new_int(logpb->err));
     json_object_object_add(json_obj, "nentries", json_object_new_int(logpb->nentries));
     json_object_object_add(json_obj, "wtime", json_obj_add_str(logpb->wtime));
     json_object_object_add(json_obj, "optime", json_obj_add_str(logpb->optime));
     json_object_object_add(json_obj, "etime", json_obj_add_str(logpb->etime));
+    if (conn) {
+        json_object_object_add(json_obj, "client_ip", json_obj_add_str(conn->c_ipaddr));
+    } else {
+        json_object_object_add(json_obj, "client_ip", json_obj_add_str("Internal"));
+    }
     if (logpb->csn) {
         char csn_str[CSN_STRSIZE] = {0};
         csn_as_string(logpb->csn, PR_FALSE, csn_str);
         json_object_object_add(json_obj, "csn",
                                json_obj_add_str(csn_str));
     }
-    if (logpb->pr_idx > 0) {
+    if (logpb->pr_idx >= 0) {
         json_object_object_add(json_obj, "pr_idx",
                                json_object_new_int(logpb->pr_idx));
-    }
-    if (logpb->pr_cookie != 0) {
         json_object_object_add(json_obj, "pr_cookie",
                                json_object_new_int(logpb->pr_cookie));
     }
@@ -678,27 +684,23 @@ slapd_log_access_result(slapd_log_pblock *logpb)
 
         get_notes_info(logpb->notes, notes, details);
         for (size_t i = 0; notes[i]; i++) {
+            char *filter_str = NULL;
             json_object *note = json_object_new_object();
             json_object_object_add(note, "note", json_obj_add_str(notes[i]));
             json_object_object_add(note, "description", json_obj_add_str(details[i]));
             if ((strcmp("A", notes[i]) == 0 || strcmp("U", notes[i]) == 0) && logpb->pb) {
                 /* Full/partial unindexed search - log more info */
-                Connection *conn = NULL;
-                char *filter_str;
                 char *base_dn;
                 int32_t scope = 0;
 
-                slapi_pblock_get(logpb->pb, SLAPI_CONNECTION, &conn);
                 slapi_pblock_get(logpb->pb, SLAPI_TARGET_DN, &base_dn);
                 slapi_pblock_get(logpb->pb, SLAPI_SEARCH_STRFILTER, &filter_str);
                 slapi_pblock_get(logpb->pb, SLAPI_SEARCH_SCOPE, &scope);
 
                 json_object_object_add(note, "base_dn", json_obj_add_str(base_dn));
                 json_object_object_add(note, "filter", json_obj_add_str(filter_str));
                 json_object_object_add(note, "scope", json_object_new_int(scope));
-                json_object_object_add(note, "client_ip", json_obj_add_str(conn->c_ipaddr));
             } else if (strcmp("F", notes[i]) == 0 && logpb->pb) {
-                char *filter_str;
                 slapi_pblock_get(logpb->pb, SLAPI_SEARCH_STRFILTER, &filter_str);
                 json_object_object_add(note, "filter", json_obj_add_str(filter_str));
             }

ldap/servers/slapd/log.c

@@ -7235,6 +7235,8 @@ slapd_log_pblock_init(slapd_log_pblock *logpb, int32_t log_format, Slapi_PBlock
     logpb->op_id = -1;
     logpb->op_internal_id = -1;
     logpb->op_nested_count = -1;
+    logpb->pr_cookie = -1;
+    logpb->pr_idx = -1;
     logpb->curr_time = slapi_current_utc_time_hr();
 
     if (conn) {

ldap/servers/slapd/modrdn.c

@@ -472,7 +472,7 @@ op_shared_rename(Slapi_PBlock *pb, int passin_args)
         logpb.target_dn = dn;
         logpb.newrdn = newrdn;
         logpb.newsup = newsuperior;
-        logpb.deletoldrdn = deloldrdn ? PR_TRUE : PR_FALSE;
+        logpb.deleteoldrdn = deloldrdn ? PR_TRUE : PR_FALSE;
         logpb.authzid = proxydn;
 
         if (proxydn) {

ldap/servers/slapd/result.c

@@ -2287,8 +2287,6 @@ log_result(Slapi_PBlock *pb, Operation *op, int err, ber_tag_t tag, int nentries
         logpb.etime = etime;
         logpb.notes = operation_notes;
         logpb.csn = operationcsn;
-        logpb.pr_idx = 0;
-        logpb.pr_cookie = 0;
         logpb.msg = NULL;
         logpb.sid = sessionTrackingId;
         logpb.tag = tag;

ldap/servers/slapd/slapi-private.h

@@ -1571,7 +1571,7 @@ typedef struct slapd_log_pblock {
     /* Modrdn */
     const char *newrdn;
     const char *newsup;
-    PRBool deletoldrdn;
+    PRBool deleteoldrdn;
     /* Search */
     const char *base_dn;
     int32_t scope;

src/lib389/lib389/__init__.py

@@ -322,8 +322,8 @@ def __add_brookers__(self):
         from lib389.config import RSA
         from lib389.config import Encryption
         from lib389.dirsrv_log import (
-            DirsrvAccessLog, DirsrvErrorLog, DirsrvAuditLog,
-            DirsrvAuditJSONLog, DirsrvSecurityLog
+            DirsrvAccessLog, DirsrvAccessJSONLog, DirsrvErrorLog,
+            DirsrvAuditLog, DirsrvAuditJSONLog, DirsrvSecurityLog
         )
         from lib389.ldclt import Ldclt
         from lib389.mappingTree import MappingTrees
@@ -368,6 +368,7 @@ def __add_brookers__(self):
         self.rsa = RSA(self)
         self.encryption = Encryption(self)
         self.ds_access_log = DirsrvAccessLog(self)
+        self.ds_access_json_log = DirsrvAccessJSONLog(self)
         self.ds_error_log = DirsrvErrorLog(self)
         self.ds_audit_log = DirsrvAuditLog(self)
         self.ds_audit_json_log = DirsrvAuditJSONLog(self)

src/lib389/lib389/dirsrv_log.py

@@ -51,6 +51,8 @@ def __init__(self, dirsrv):
         self.dirsrv = dirsrv
         self.log = self.dirsrv.log
         self.prog_timestamp = re.compile(r'\[(?P<day>\d*)\/(?P<month>\w*)\/(?P<year>\d*):(?P<hour>\d*):(?P<minute>\d*):(?P<second>\d*)(.(?P<nanosecond>\d*))+\s(?P<tz>[\+\-]\d*)')   # noqa
+        #  JSON timestamp uses strftime %FT%T --> 2025-02-12T17:00:47.663123181 -0500
+        self.prog_json_timestamp = re.compile(r'(?P<year>\d*)-(?P<month>\w*)-(?P<day>\d*)T(?P<hour>\d*):(?P<minute>\d*):(?P<second>\d*)(.(?P<nanosecond>\d*))+\s(?P<tz>[\+\-]\d*)')   # noqa
         self.prog_datetime = re.compile(r'^(?P<timestamp>\[.*\])')
         self.jsonFormat = False
 
@@ -145,17 +147,20 @@ def match(self, pattern, after_pattern=None):
                         results.append(line)
         return results
 
-    def parse_timestamp(self, ts):
+    def parse_timestamp(self, ts, json_format=False):
         """Parse a logs timestamps and break it down into its individual parts
         @param ts - The timestamp string from a log
         @return - a "datetime" object
         """
-        timedata = self.prog_timestamp.match(ts).groupdict()
+        if json_format:
+            timedata = self.prog_json_timestamp.match(ts).groupdict()
+        else:
+            timedata = self.prog_timestamp.match(ts).groupdict()
 
         # Now, have to convert month to an int.
         dt_str = '{YEAR}-{MONTH}-{DAY} {HOUR}-{MINUTE}-{SECOND} {TZ}'.format(
             YEAR=timedata['year'],
-            MONTH=MONTH_LOOKUP[timedata['month']],
+            MONTH=timedata['month'],
             DAY=timedata['day'],
             HOUR=timedata['hour'],
             MINUTE=timedata['minute'],
@@ -168,19 +173,35 @@ def parse_timestamp(self, ts):
         return dt
 
     def get_time_in_secs(self, log_line):
-        """Take the timestamp (not the date) from a DS log and convert it
-           to seconds:
+        """Take the timestamp (not the date) from a DS access log and convert
+           it to seconds:
 
               [25/May/2016:15:24:27.289341875 -0400]...
 
+              JSON format
+
+              2025-02-12T17:00:47.699153015 -0500
+
             @param log_line - A line of txt from a DS error/access log
             @return - time in seconds
         """
 
         total = 0
-        index = log_line.index(':') + 1
-        hms = log_line[index: index + 8]
-        parts = hms.split(':')
+
+        try:
+            log_obj = json.loads(log_line)
+            # JSON format
+            date_str = log_obj["local_time"]
+            time_str = date_str.split('T')[1:]  # splice off the date
+            hms = time_str[:8]
+            parts = hms.split(':')
+
+        except ValueError:
+            # Old format
+            index = log_line.index(':') + 1
+            hms = log_line[index: index + 8]
+            parts = hms.split(':')
+
         if int(parts[0]):
             total += int(parts[0]) * 3600
         if int(parts[1]):
@@ -190,6 +211,118 @@ def get_time_in_secs(self, log_line):
         return total
 
 
+class DirsrvAccessJSONLog(DirsrvLog):
+    """Class for process access logs in JSON format"""
+    def __init__(self, dirsrv):
+        """Init the class
+        @param dirsrv - A DirSrv object
+        """
+        super(DirsrvAccessJSONLog, self).__init__(dirsrv)
+        self.lpath = None
+
+    @classmethod
+    def lint_uid(cls):
+        return 'logs'
+
+    def _log_get_search_stats(self, conn, op):
+        self.lpath = self._get_log_path()
+        if self.lpath is not None:
+            with open(self.lpath, 'r') as lf:
+                for line in lf:
+                    line = line.strip()
+                    action = json.loads(line)
+                    if 'header' in action:
+                        # This is the log title, skip it
+                        continue
+                    if action['operation'] == "SEARCH" and \
+                       action['conn_id'] == op and \
+                       action['op_id'] == op:
+                        return action
+        return None
+
+    def _lint_notes(self):
+        """
+        Check for notes=A (fully unindexed searches), and
+        notes=F (unknown attribute in filter)
+        """
+        for pattern, lint_report in [(".* notes=A", DSLOGNOTES0001), (".* notes=F", DSLOGNOTES0002)]:
+            lines = self.match(pattern)
+            if len(lines) > 0:
+                count = 0
+                searches = []
+                for line in lines:
+                    line = line.strip()
+                    action = json.loads(line)
+                    if action['operation'] == 'RESULT':
+                        # Looks like a valid notes=A/F
+                        conn = action['conn_id']
+                        op = action['op_id']
+                        etime = action['etime']
+                        stats = self._log_get_search_stats(conn, op)
+                        if stats is not None:
+                            timestamp = stats['local_time']
+                            base = stats['base_dn']
+                            scope = stats['scope']
+                            srch_filter = stats['filter']
+                            count += 1
+                            if lint_report == DSLOGNOTES0001:
+                                searches.append(f'\n  [{count}] Unindexed Search\n'
+                                                f'      - date:    {timestamp}\n'
+                                                f'      - conn/op: {conn}/{op}\n'
+                                                f'      - base:    {base}\n'
+                                                f'      - scope:   {scope}\n'
+                                                f'      - filter:  {srch_filter}\n'
+                                                f'      - etime:   {etime}\n')
+                            else:
+                                searches.append(f'\n  [{count}] Invalid Attribute in Filter\n'
+                                                f'      - date:    {timestamp}\n'
+                                                f'      - conn/op: {conn}/{op}\n'
+                                                f'      - filter:  {srch_filter}\n')
+                if len(searches) > 0:
+                    report = copy.deepcopy(lint_report)
+                    report['items'].append(self._get_log_path())
+                    report['detail'] = report['detail'].replace('NUMBER', str(count))
+                    for srch in searches:
+                        report['detail'] += srch
+                    report['check'] = 'logs:notes'
+                    yield report
+
+    def _get_log_path(self):
+        """Return the current log file location"""
+        return self.dirsrv.ds_paths.access_log
+
+    def parse_line(self, line):
+        """
+        This knows how to break up an access log line into the specific fields.
+        @param line - A text line from an access log
+        @return - A dictionary of the log parts
+        """
+        line = line.strip()
+        try:
+            action = json.loads(line)
+        except ValueError:
+            # Old format, skip this line
+            return None
+
+        # First, pull some well known info out.
+        if self.dirsrv.verbose:
+            self.log.info("parse_line --> %s ", line)
+
+        action['datetime'] = self.parse_timestamp(action['local_time'],
+                                                  json_format=True)
+
+        if self.dirsrv.verbose:
+            self.log.info(action)
+        return action
+
+    def parse_lines(self, lines):
+        """Parse multiple log lines
+        @param lines - a list of log lines
+        @return - A dictionary of the log parts for each line
+        """
+        return map(self.parse_line, lines)
+
+
 class DirsrvAccessLog(DirsrvLog):
     """Class for process access logs"""
     def __init__(self, dirsrv):
@@ -371,6 +504,9 @@ def parse_line(self, line):
         """
         line = line.strip()
         action = json.loads(line)
+        if 'header' in action:
+            # This is the log title, return it as is
+            return action
         action['datetime'] = action['date']
         return action