From cde2379784eb4744fea9cd9523cccd946ffe5cf7 Mon Sep 17 00:00:00 2001 From: Mark Reynolds Date: Tue, 4 Feb 2025 16:03:21 -0500 Subject: [PATCH] Issue 6599 - Implement option to write access log in jSON Description: Add option to write access log in JSON See design doc for more info: https://www.port389.org/docs/389ds/design/accesslog-json-design.html Relates: https://github.com/389ds/389-ds-base/issues/6599 Reviewed by: progier & jchapman(Thanks!!) --- .../suites/logging/audit_json_logging_test.py | 3 + ldap/servers/slapd/accesslog.c | 708 +++++++++++++++++- ldap/servers/slapd/add.c | 1 + ldap/servers/slapd/back-ldbm/sort.c | 10 +- ldap/servers/slapd/connection.c | 19 +- ldap/servers/slapd/control.c | 10 +- ldap/servers/slapd/delete.c | 8 +- ldap/servers/slapd/extendop.c | 2 +- ldap/servers/slapd/ldapi.c | 4 +- ldap/servers/slapd/libglobs.c | 4 +- ldap/servers/slapd/log.c | 163 +++- ldap/servers/slapd/modify.c | 6 +- ldap/servers/slapd/modrdn.c | 1 + ldap/servers/slapd/opshared.c | 1 + ldap/servers/slapd/proto-slap.h | 7 +- ldap/servers/slapd/result.c | 185 +++-- ldap/servers/slapd/slap.h | 1 + ldap/servers/slapd/slapi-private.h | 13 +- ldap/servers/slapd/time.c | 52 ++ ldap/servers/slapd/util.c | 143 ++++ src/lib389/lib389/dirsrv_log.py | 3 + 21 files changed, 1201 insertions(+), 143 deletions(-) diff --git a/dirsrvtests/tests/suites/logging/audit_json_logging_test.py b/dirsrvtests/tests/suites/logging/audit_json_logging_test.py index 3b702ef0da..2d3b77335c 100644 --- a/dirsrvtests/tests/suites/logging/audit_json_logging_test.py +++ b/dirsrvtests/tests/suites/logging/audit_json_logging_test.py @@ -57,6 +57,9 @@ def get_log_event(inst, dn, op): continue event = audit_log.parse_line(line) + if 'header' in event: + # Skip header line + continue if event['target_dn'].lower() == dn.lower() and op in event: return event diff --git a/ldap/servers/slapd/accesslog.c b/ldap/servers/slapd/accesslog.c index ec4497448b..2de14e3cf1 100644 --- a/ldap/servers/slapd/accesslog.c +++ b/ldap/servers/slapd/accesslog.c @@ -1,5 +1,5 @@ /** BEGIN COPYRIGHT BLOCK - * Copyright (C) 2024 Red Hat, Inc. + * Copyright (C) 2025 Red Hat, Inc. * All rights reserved. * * License: GPL (version 3 or any later version). @@ -10,11 +10,171 @@ #include #endif +#include "log.h" #include "slap.h" +#define MAX_ELEMENT_SIZE 512 #define JBUFSIZE 75 #define KEY_SIZE 50 +struct json_object* +json_obj_add_str(const char *value) +{ + char val_buffer[MAX_ELEMENT_SIZE] = {0}; + + if (strlen(value) > MAX_ELEMENT_SIZE) { + /* we use -4 to leave room for the NULL terminator */ + memcpy(&val_buffer, value, MAX_ELEMENT_SIZE-4); + memcpy(&val_buffer[MAX_ELEMENT_SIZE-4], "...", 3); + } else { + PR_snprintf(val_buffer, sizeof(val_buffer), "%s", value); + } + + return json_object_new_string(val_buffer); + +} + +static json_object * +build_base_obj(slapd_log_pblock *logpb, char *op_type) +{ + json_object *json_obj = NULL; + Connection *conn = NULL; + char local_time[TBUFSIZE] = {0}; + char conn_key[KEY_SIZE] = {0}; + char *time_format = NULL; + int32_t ltlen = TBUFSIZE; + bool haproxied = false; + + if (logpb->loginfo && (!(logpb->level & logpb->loginfo->log_access_level))) { + return NULL; + } + + /* custom local time */ + time_format = config_get_accesslog_time_format(); + if (format_localTime_hr_json_log(&logpb->curr_time, local_time, <len, + time_format) != 0) + { + /* MSG may be truncated */ + PR_snprintf(local_time, sizeof(local_time), + "build_base_obj, Unable to format system time"); + log__error_emergency(local_time, 1, 0); + slapi_ch_free_string(&time_format); + return NULL; + } + slapi_ch_free_string(&time_format); + + if (logpb->pb) { + slapi_pblock_get(logpb->pb, SLAPI_CONNECTION, &conn); + if (conn && conn->c_hapoxied) { + haproxied = true; + } + } + + /* Build connection key */ + PR_snprintf(conn_key, sizeof(conn_key), "%ld-%" PRIu64, + logpb->conn_time, logpb->conn_id); + + json_obj = json_object_new_object(); + json_object_object_add(json_obj, "local_time", json_obj_add_str(local_time)); + json_object_object_add(json_obj, "operation", json_obj_add_str(op_type)); + json_object_object_add(json_obj, "key", json_obj_add_str(conn_key)); + json_object_object_add(json_obj, "conn_id", json_object_new_int64(logpb->conn_id)); + if (logpb->op_id != -1) { + json_object_object_add(json_obj, "op_id", json_object_new_int(logpb->op_id)); + } + if (logpb->op_internal_id != -1) { + json_object_object_add(json_obj, "internal_op", json_object_new_boolean(true)); + json_object_object_add(json_obj, "op_internal_id", json_object_new_int(logpb->op_internal_id)); + } + if (logpb->op_nested_count != -1) { + json_object_object_add(json_obj, "op_internal_nested_count", json_object_new_int(logpb->op_nested_count)); + } + if (logpb->oid) { + const char *oid_name = NULL; + json_object_object_add(json_obj, "oid", json_obj_add_str(logpb->oid)); + oid_name = get_oid_name(logpb->oid); + if (oid_name) { + json_object_object_add(json_obj, "oid_name", json_obj_add_str(oid_name)); + } + } + if (logpb->msg) { + json_object_object_add(json_obj, "msg", json_obj_add_str(logpb->msg)); + } + if (logpb->authzid) { + json_object_object_add(json_obj, "authzid", json_obj_add_str(logpb->authzid)); + } + if (haproxied) { + json_object_object_add(json_obj, "haproxied", json_object_new_boolean(haproxied)); + } + + if (logpb->request_controls) { + json_object *jarray = json_object_new_array(); + LDAPControl **ctrl = logpb->request_controls; + + for (size_t i = 0; ctrl[i] != NULL; i++) { + char *oid = NULL; + char *value = NULL; + bool isCritical = false; + json_object *ctrl_obj = NULL; + + if (i == 10) { + /* We only log a max of 10 controls because anything over 10 + * is very suspicious */ + json_object_array_add(jarray, json_object_new_string("...")); + break; + } + + ctrl_obj = json_object_new_object(); + slapi_parse_control(ctrl[i], &oid, &value, &isCritical); + json_object_object_add(ctrl_obj, "oid", json_obj_add_str(oid)); + json_object_object_add(ctrl_obj, "oid_name", json_obj_add_str(get_oid_name(oid))); + if (value) { + json_object_object_add(ctrl_obj, "value", json_obj_add_str(value)); + } else { + json_object_object_add(ctrl_obj, "value", json_obj_add_str("")); + } + json_object_object_add(ctrl_obj, "isCritical", json_object_new_boolean(isCritical)); + json_object_array_add(jarray, ctrl_obj); + slapi_ch_free_string(&value); + } + json_object_object_add(json_obj, "request_controls", jarray); + } + if (logpb->response_controls) { + json_object *jarray = json_object_new_array(); + LDAPControl **ctrl = logpb->response_controls; + + for (size_t i = 0; ctrl[i] != NULL; i++) { + char *oid = NULL; + char *value = NULL; + bool isCritical = false; + json_object *ctrl_obj = NULL; + + if (i == 10) { + /* We only log a max of 10 controls because anything over 10 + * is very suspicious */ + json_object_array_add(jarray, json_object_new_string("...")); + break; + } + + ctrl_obj = json_object_new_object(); + slapi_parse_control(ctrl[i], &oid, &value, &isCritical); + json_object_object_add(ctrl_obj, "oid", json_obj_add_str(oid)); + json_object_object_add(ctrl_obj, "oid_name", json_obj_add_str(get_oid_name(oid))); + if (value) { + json_object_object_add(ctrl_obj, "value", json_obj_add_str(value)); + } else { + json_object_object_add(ctrl_obj, "value", json_obj_add_str("")); + } + json_object_object_add(ctrl_obj, "isCritical", json_object_new_boolean(isCritical)); + json_object_array_add(jarray, ctrl_obj); + slapi_ch_free_string(&value); + } + json_object_object_add(json_obj, "response_controls", jarray); + } + + return json_obj; +} + /* * ABANDON * @@ -29,26 +189,40 @@ * int64_t tv_sec - for etime * int64_t tv_nsec - for etime */ - int32_t slapd_log_access_abandon(slapd_log_pblock *logpb) { int32_t rc = 0; char etime[BUFSIZ] = {0}; - char conn_key[KEY_SIZE] = {0}; + char *msg = NULL; + json_object *json_obj = NULL; - /* Build the connection key */ - PR_snprintf(conn_key, sizeof(conn_key), "%ld-%" PRIu64, - logpb->conn_time, logpb->conn_id); + if ((json_obj = build_base_obj(logpb, "ABANDON")) == NULL) { + return rc; + } /* Construct the abandon etime */ if (logpb->tv_sec != -1) { PR_snprintf(etime, sizeof(etime), "%" PRId64 ".%010" PRId64, logpb->tv_sec, logpb->tv_nsec); + json_object_object_add(json_obj, "etime", json_obj_add_str(etime)); } - if (logpb->nentries != -1) { + if (logpb->nentries != -1) { + json_object_object_add(json_obj, "nentries", json_object_new_int(logpb->nentries)); } + if (logpb->sid) { + json_object_object_add(json_obj, "sid", json_obj_add_str(logpb->sid)); + } + json_object_object_add(json_obj, "msgid", json_object_new_int(logpb->msgid)); + json_object_object_add(json_obj, "target_op", json_obj_add_str(logpb->target_op)); + + /* Convert json object to string and log it */ + msg = (char *)json_object_to_json_string_ext(json_obj, logpb->log_format); + rc = slapd_log_access_json(msg); + + /* Done with JSON object - free it */ + json_object_put(json_obj); return rc; } @@ -71,6 +245,21 @@ int32_t slapd_log_access_add(slapd_log_pblock *logpb) { int32_t rc = 0; + char *msg = NULL; + json_object *json_obj = NULL; + + if ((json_obj = build_base_obj(logpb, "ADD")) == NULL) { + return rc; + } + + json_object_object_add(json_obj, "target_dn", json_obj_add_str(logpb->target_dn)); + + /* Convert json object to string and log it */ + msg = (char *)json_object_to_json_string_ext(json_obj, logpb->log_format); + rc = slapd_log_access_json(msg); + + /* Done with JSON object - free it */ + json_object_put(json_obj); return rc; } @@ -87,6 +276,21 @@ int32_t slapd_log_access_autobind(slapd_log_pblock *logpb) { int32_t rc = 0; + char *msg = NULL; + json_object *json_obj = NULL; + + if ((json_obj = build_base_obj(logpb, "AUTOBIND")) == NULL) { + return rc; + } + + json_object_object_add(json_obj, "bind_dn", json_obj_add_str(logpb->bind_dn)); + + /* Convert json object to string and log it */ + msg = (char *)json_object_to_json_string_ext(json_obj, logpb->log_format); + rc = slapd_log_access_json(msg); + + /* Done with JSON object - free it */ + json_object_put(json_obj); return rc; } @@ -109,6 +313,26 @@ int32_t slapd_log_access_bind(slapd_log_pblock *logpb) { int32_t rc = 0; + char *msg = NULL; + json_object *json_obj = NULL; + + if ((json_obj = build_base_obj(logpb, "BIND")) == NULL) { + return rc; + } + + json_object_object_add(json_obj, "bind_dn", json_obj_add_str(logpb->bind_dn)); + json_object_object_add(json_obj, "version", json_object_new_int(logpb->version)); + json_object_object_add(json_obj, "method", json_obj_add_str(logpb->method)); + if (logpb->mech) { + json_object_object_add(json_obj, "mech", json_obj_add_str(logpb->mech)); + } + + /* Convert json object to string and log it */ + msg = (char *)json_object_to_json_string_ext(json_obj, logpb->log_format); + rc = slapd_log_access_json(msg); + + /* Done with JSON object - free it */ + json_object_put(json_obj); return rc; } @@ -128,11 +352,27 @@ int32_t slapd_log_access_unbind(slapd_log_pblock *logpb) { int32_t rc = 0; + char *msg = NULL; + json_object *json_obj = NULL; + + if ((json_obj = build_base_obj(logpb, "UNBIND")) == NULL) { + return rc; + } + + if (logpb->err != 0) { + json_object_object_add(json_obj, "err", json_object_new_int(logpb->err)); + } + if (logpb->close_error) { + json_object_object_add(json_obj, "close_error", + json_obj_add_str(logpb->close_error)); + } + + /* Convert json object to string and log it */ + msg = (char *)json_object_to_json_string_ext(json_obj, logpb->log_format); + rc = slapd_log_access_json(msg); - /* - "conn=%" PRIu64 " op=%d UNBIND, error processing controls - error %d (%s)\n", - "conn=%" PRIu64 " op=%d UNBIND, decoding error: UnBindRequest not null\n" - */ + /* Done with JSON object - free it */ + json_object_put(json_obj); return rc; } @@ -145,13 +385,36 @@ slapd_log_access_unbind(slapd_log_pblock *logpb) * uint64_t conn_id * int32_t op_id * int32_t fdnum - * const char *error - * const char *reason + * const char *close_error + * const char *close_reason */ int32_t slapd_log_access_close(slapd_log_pblock *logpb) { int32_t rc = 0; + char *msg = NULL; + json_object *json_obj = NULL; + + if ((json_obj = build_base_obj(logpb, "DISCONNECT")) == NULL) { + return rc; + } + + json_object_object_add(json_obj, "fd", json_object_new_int(logpb->fd)); + if (logpb->close_error) { + json_object_object_add(json_obj, "close_error", + json_obj_add_str(logpb->close_error)); + } + if (logpb->close_reason) { + json_object_object_add(json_obj, "close_reason", + json_obj_add_str(logpb->close_reason)); + } + + /* Convert json object to string and log it */ + msg = (char *)json_object_to_json_string_ext(json_obj, logpb->log_format); + rc = slapd_log_access_json(msg); + + /* Done with JSON object - free it */ + json_object_put(json_obj); return rc; } @@ -165,14 +428,30 @@ slapd_log_access_close(slapd_log_pblock *logpb) * int32_t op_id * int32_t op_internal_id * int32_t op_nested_count - * const char *dn - * char *attr + * const char *target_dn + * char *cmp_attr * LDAPControl **controls */ int32_t slapd_log_access_cmp(slapd_log_pblock *logpb) { int32_t rc = 0; + char *msg = NULL; + json_object *json_obj = NULL; + + if ((json_obj = build_base_obj(logpb, "COMPARE")) == NULL) { + return rc; + } + + json_object_object_add(json_obj, "target_dn", json_obj_add_str(logpb->target_dn)); + json_object_object_add(json_obj, "cmp_attr", json_obj_add_str(logpb->cmp_attr)); + + /* Convert json object to string and log it */ + msg = (char *)json_object_to_json_string_ext(json_obj, logpb->log_format); + rc = slapd_log_access_json(msg); + + /* Done with JSON object - free it */ + json_object_put(json_obj); return rc; } @@ -193,6 +472,27 @@ int32_t slapd_log_access_conn(slapd_log_pblock *logpb) { int32_t rc = 0; + char *msg = NULL; + json_object *json_obj = NULL; + + if ((json_obj = build_base_obj(logpb, "CONNECTION")) == NULL) { + return rc; + } + + json_object_object_add(json_obj, "fd", json_object_new_int(logpb->fd)); + json_object_object_add(json_obj, "slot", json_object_new_int(logpb->slot)); + json_object_object_add(json_obj, "tls", json_object_new_boolean(logpb->using_tls)); + json_object_object_add(json_obj, "client_ip", + json_obj_add_str(logpb->client_ip)); + json_object_object_add(json_obj, "server_ip", + json_obj_add_str(logpb->server_ip)); + + /* Convert json object to string and log it */ + msg = (char *)json_object_to_json_string_ext(json_obj, logpb->log_format); + rc = slapd_log_access_json(msg); + + /* Done with JSON object - free it */ + json_object_put(json_obj); return rc; } @@ -214,6 +514,21 @@ int32_t slapd_log_access_delete(slapd_log_pblock *logpb) { int32_t rc = 0; + char *msg = NULL; + json_object *json_obj = NULL; + + if ((json_obj = build_base_obj(logpb, "DELETE")) == NULL) { + return rc; + } + + json_object_object_add(json_obj, "target_dn", json_obj_add_str(logpb->target_dn)); + + /* Convert json object to string and log it */ + msg = (char *)json_object_to_json_string_ext(json_obj, logpb->log_format); + rc = slapd_log_access_json(msg); + + /* Done with JSON object - free it */ + json_object_put(json_obj); return rc; } @@ -236,6 +551,21 @@ int32_t slapd_log_access_mod(slapd_log_pblock *logpb) { int32_t rc = 0; + char *msg = NULL; + json_object *json_obj = NULL; + + if ((json_obj = build_base_obj(logpb, "MODIFY")) == NULL) { + return rc; + } + + json_object_object_add(json_obj, "target_dn", json_obj_add_str(logpb->target_dn)); + + /* Convert json object to string and log it */ + msg = (char *)json_object_to_json_string_ext(json_obj, logpb->log_format); + rc = slapd_log_access_json(msg); + + /* Done with JSON object - free it */ + json_object_put(json_obj); return rc; } @@ -260,6 +590,26 @@ int32_t slapd_log_access_modrdn(slapd_log_pblock *logpb) { int32_t rc = 0; + char *msg = NULL; + json_object *json_obj = NULL; + + if ((json_obj = build_base_obj(logpb, "MODRDN")) == NULL) { + return rc; + } + + json_object_object_add(json_obj, "target_dn", json_obj_add_str(logpb->target_dn)); + json_object_object_add(json_obj, "newrdn", json_obj_add_str(logpb->newrdn)); + 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)); + + /* Convert json object to string and log it */ + msg = (char *)json_object_to_json_string_ext(json_obj, logpb->log_format); + rc = slapd_log_access_json(msg); + + /* Done with JSON object - free it */ + json_object_put(json_obj); return rc; } @@ -272,6 +622,7 @@ slapd_log_access_modrdn(slapd_log_pblock *logpb) * Slapi_PBlock *pb * time_t conn_time * uint64_t conn_id + * uint32_t tag * int32_t op_id * int32_t op_internal_id * int32_t op_nested_count @@ -282,8 +633,8 @@ slapd_log_access_modrdn(slapd_log_pblock *logpb) * char *etime * char *sid * char *notes - * char *csn - * char *dn + * CSN *csn + * char *bind_dn * int32_t pr_idx - psearch * int32_t pr_cookie - psearch * char *msg @@ -293,15 +644,83 @@ int32_t slapd_log_access_result(slapd_log_pblock *logpb) { int32_t rc = 0; - char *bind_dn = NULL; + char *msg = NULL; + json_object *json_obj = NULL; + + if ((json_obj = build_base_obj(logpb, "RESULT")) == NULL) { + return rc; + } - /* get the bind dn */ - slapi_pblock_get(logpb->pb, SLAPI_CONN_DN, &bind_dn); + 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 (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) { + 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)); + } + if (logpb->notes != 0) { + char *notes[10] = {NULL}; + char *details[10] = {NULL}; + json_object *jarray = json_object_new_array(); + + get_notes_info(logpb->notes, notes, details); + for (size_t i = 0; notes[i]; i++) { + 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)); + } + json_object_array_add(jarray, note); + } + json_object_object_add(json_obj, "notes", jarray); + } + if (logpb->sid) { + json_object_object_add(json_obj, "sid", + json_obj_add_str(logpb->sid)); + } + if (logpb->bind_dn) { + json_object_object_add(json_obj, "bind_dn", + json_obj_add_str(logpb->bind_dn)); + } - /* build JSON object */ + /* Convert json object to string and log it */ + msg = (char *)json_object_to_json_string_ext(json_obj, logpb->log_format); + rc = slapd_log_access_json(msg); - /* free and return */ - slapi_ch_free_string(&bind_dn); + /* Done with JSON object - free it */ + json_object_put(json_obj); return rc; } @@ -328,6 +747,40 @@ int32_t slapd_log_access_search(slapd_log_pblock *logpb) { int32_t rc = 0; + char *msg = NULL; + json_object *json_obj = NULL; + + if ((json_obj = build_base_obj(logpb, "SEARCH")) == NULL) { + return rc; + } + + json_object_object_add(json_obj, "base_dn", json_obj_add_str(logpb->base_dn)); + json_object_object_add(json_obj, "scope", json_object_new_int(logpb->scope)); + json_object_object_add(json_obj, "filter", json_obj_add_str(logpb->filter)); + if (logpb->psearch) { + json_object_object_add(json_obj, "psearch", json_object_new_boolean(logpb->psearch)); + } + if (logpb->attrs) { + size_t attrs_len = 0; + json_object *jarray = json_object_new_array(); + for (size_t i = 0; logpb->attrs[i]; i++) { + attrs_len += strlen(logpb->attrs[i]); + if (attrs_len + 3 > 128) { + /* About to exceed to size limit, truncate the results */ + json_object_array_add(jarray, json_object_new_string("...")); + break; + } + json_object_array_add(jarray, json_obj_add_str(logpb->attrs[i])); + } + json_object_object_add(json_obj, "attrs", jarray); + } + + /* Convert json object to string and log it */ + msg = (char *)json_object_to_json_string_ext(json_obj, logpb->log_format); + rc = slapd_log_access_json(msg); + + /* Done with JSON object - free it */ + json_object_put(json_obj); return rc; } @@ -350,8 +803,35 @@ int32_t slapd_log_access_stat(slapd_log_pblock *logpb) { int32_t rc = 0; + char *msg = NULL; + json_object *json_obj = NULL; + + if ((json_obj = build_base_obj(logpb, "STAT")) == NULL) { + return rc; + } + + if (logpb->stat_etime) { + /* this is the summary stat */ + json_object_object_add(json_obj, "stat_etime", json_obj_add_str(logpb->stat_etime)); + } else { + if (logpb->stat_attr) { + json_object_object_add(json_obj, "stat_attr", json_obj_add_str(logpb->stat_attr)); + } + if (logpb->stat_key) { + json_object_object_add(json_obj, "stat_key", json_obj_add_str(logpb->stat_key)); + } + if (logpb->stat_value) { + json_object_object_add(json_obj, "stat_key_value", json_obj_add_str(logpb->stat_value)); + } + json_object_object_add(json_obj, "stat_count", json_object_new_int(logpb->stat_count)); + } - /* STAT attribute=%s key(%s)=%s --> count %d */ + /* Convert json object to string and log it */ + msg = (char *)json_object_to_json_string_ext(json_obj, logpb->log_format); + rc = slapd_log_access_json(msg); + + /* Done with JSON object - free it */ + json_object_put(json_obj); return rc; } @@ -374,8 +854,22 @@ int32_t slapd_log_access_error(slapd_log_pblock *logpb) { int32_t rc = 0; + char *msg = NULL; + json_object *json_obj = NULL; + + if ((json_obj = build_base_obj(logpb, "ERROR")) == NULL) { + return rc; + } - // slapi_log_access(LDAP_DEBUG_STATS, "conn=%" PRIu64 " op=%d %s dn=\"%s\"%s, %s\n", + json_object_object_add(json_obj, "operation", json_obj_add_str(logpb->op_type)); + json_object_object_add(json_obj, "target_dn", json_obj_add_str(logpb->target_dn)); + + /* Convert json object to string and log it */ + msg = (char *)json_object_to_json_string_ext(json_obj, logpb->log_format); + rc = slapd_log_access_json(msg); + + /* Done with JSON object - free it */ + json_object_put(json_obj); return rc; } @@ -387,8 +881,8 @@ slapd_log_access_error(slapd_log_pblock *logpb) * time_t conn_time * uint64_t conn_id * int32_t op_id - * const char *local_ssf - * const char *ssl_ssf + * int32_t *local_ssf + * int32_t *ssl_ssf * const char *sasl_ssf * const char *msg */ @@ -396,6 +890,23 @@ int32_t slapd_log_access_ssf_error(slapd_log_pblock *logpb) { int32_t rc = 0; + char *msg = NULL; + json_object *json_obj = NULL; + + if ((json_obj = build_base_obj(logpb, "ERROR")) == NULL) { + return rc; + } + + json_object_object_add(json_obj, "local_ssf", json_object_new_int(logpb->local_ssf)); + json_object_object_add(json_obj, "sasl_ssf", json_object_new_int(logpb->sasl_ssf)); + json_object_object_add(json_obj, "ssl_ssf", json_object_new_int(logpb->ssl_ssf)); + + /* Convert json object to string and log it */ + msg = (char *)json_object_to_json_string_ext(json_obj, logpb->log_format); + rc = slapd_log_access_json(msg); + + /* Done with JSON object - free it */ + json_object_put(json_obj); return rc; } @@ -414,8 +925,23 @@ int32_t slapd_log_access_haproxy(slapd_log_pblock *logpb) { int32_t rc = 0; + char *msg = NULL; + json_object *json_obj = NULL; + + if ((json_obj = build_base_obj(logpb, "HAPROXY")) == NULL) { + return rc; + } + + json_object_object_add(json_obj, "fd", json_object_new_int(logpb->fd)); + json_object_object_add(json_obj, "haproxy_ip", json_obj_add_str(logpb->haproxy_ip)); + json_object_object_add(json_obj, "haproxy_destip", json_obj_add_str(logpb->haproxy_destip)); + + /* Convert json object to string and log it */ + msg = (char *)json_object_to_json_string_ext(json_obj, logpb->log_format); + rc = slapd_log_access_json(msg); - /* "conn=%" PRIu64 " fd=%d HAProxy new_address_from=%s to new_address_dest=%s\n" */ + /* Done with JSON object - free it */ + json_object_put(json_obj); return rc; } @@ -446,10 +972,42 @@ int32_t slapd_log_access_vlv(slapd_log_pblock *logpb) { int32_t rc = 0; - /* - * - VLV %d:%d:%d:%d (response status) - * - VLV %d:%d:%s (response status) - */ + char *msg = NULL; + json_object *json_obj = NULL; + json_object *req_obj = NULL; + json_object *resp_obj = NULL; + + if ((json_obj = build_base_obj(logpb, "VLV")) == NULL) { + return rc; + } + + req_obj = json_object_new_object(); + json_object_object_add(req_obj, "request_before_count", json_object_new_int(logpb->vlv_req_before_count)); + json_object_object_add(req_obj, "request_after_count", json_object_new_int(logpb->vlv_req_after_count)); + json_object_object_add(req_obj, "request_index", json_object_new_int(logpb->vlv_req_index)); + json_object_object_add(req_obj, "request_content_count", json_object_new_int(logpb->vlv_req_content_count)); + if (logpb->vlv_req_value) { + json_object_object_add(req_obj, "request_value", json_obj_add_str(logpb->vlv_req_value)); + } + json_object_object_add(req_obj, "request_value_len", json_object_new_int64(logpb->vlv_req_value_len)); + if (logpb->vlv_sort_str) { + json_object_object_add(req_obj, "request_sort", json_obj_add_str(logpb->vlv_sort_str)); + } + json_object_object_add(json_obj, "vlv_request", req_obj); + + resp_obj = json_object_new_object(); + json_object_object_add(resp_obj, "response_target_position", json_object_new_int(logpb->vlv_res_target_position)); + json_object_object_add(resp_obj, "response_content_count", json_object_new_int(logpb->vlv_res_content_count)); + json_object_object_add(resp_obj, "response_result", json_object_new_int(logpb->vlv_res_result)); + json_object_object_add(json_obj, "vlv_response", resp_obj); + + /* Convert json object to string and log it */ + msg = (char *)json_object_to_json_string_ext(json_obj, logpb->log_format); + rc = slapd_log_access_json(msg); + + /* Done with JSON object - free it */ + json_object_put(json_obj); + return rc; } @@ -468,6 +1026,21 @@ int32_t slapd_log_access_entry(slapd_log_pblock *logpb) { int32_t rc = 0; + char *msg = NULL; + json_object *json_obj = NULL; + + if ((json_obj = build_base_obj(logpb, "ENTRY")) == NULL) { + return rc; + } + + json_object_object_add(json_obj, "target_dn", json_obj_add_str(logpb->target_dn)); + + /* Convert json object to string and log it */ + msg = (char *)json_object_to_json_string_ext(json_obj, logpb->log_format); + rc = slapd_log_access_json(msg); + + /* Done with JSON object - free it */ + json_object_put(json_obj); return rc; } @@ -486,11 +1059,20 @@ int32_t slapd_log_access_referral(slapd_log_pblock *logpb) { int32_t rc = 0; + char *msg = NULL; + json_object *json_obj = NULL; - /* - "conn=%" PRIu64 " op=%d REFERRAL"); + if ((json_obj = build_base_obj(logpb, "REFERRAL")) == NULL) { + return rc; + } + + /* Convert json object to string and log it */ + msg = (char *)json_object_to_json_string_ext(json_obj, logpb->log_format); + rc = slapd_log_access_json(msg); + + /* Done with JSON object - free it */ + json_object_put(json_obj); - */ return rc; } @@ -502,16 +1084,64 @@ slapd_log_access_referral(slapd_log_pblock *logpb) * uint64_t conn_id * int32_t op_id * const char* oid - * const char* msg + * const char* name */ int32_t slapd_log_access_extop(slapd_log_pblock *logpb) { int32_t rc = 0; + char *msg = NULL; + json_object *json_obj = NULL; + + if ((json_obj = build_base_obj(logpb, "EXTENDED_OP")) == NULL) { + return rc; + } + + if (logpb->name) { + json_object_object_add(json_obj, "name", json_obj_add_str(logpb->name)); + } + + /* Convert json object to string and log it */ + msg = (char *)json_object_to_json_string_ext(json_obj, logpb->log_format); + rc = slapd_log_access_json(msg); + + /* Done with JSON object - free it */ + json_object_put(json_obj); + + return rc; +} + +/* + * Sort + * + * int32_t log_format + * time_t conn_time + * uint64_t conn_id + * int32_t op_id + * int32_t op_internal_id + * int32_t op_nested_count + * char attr_str + */ +int32_t +slapd_log_access_sort(slapd_log_pblock *logpb) +{ + int32_t rc = 0; + char *msg = NULL; + json_object *json_obj = NULL; + + if ((json_obj = build_base_obj(logpb, "SORT")) == NULL) { + return rc; + } + + json_object_object_add(json_obj, "sort_attrs", + json_obj_add_str(logpb->sort_str)); + + /* Convert json object to string and log it */ + msg = (char *)json_object_to_json_string_ext(json_obj, logpb->log_format); + rc = slapd_log_access_json(msg); - /* - "conn=%" PRIu64 " op=%d oid=%s name=%s"); + /* Done with JSON object - free it */ + json_object_put(json_obj); - */ return rc; } diff --git a/ldap/servers/slapd/add.c b/ldap/servers/slapd/add.c index 48f7fd4a0c..381e9a5d27 100644 --- a/ldap/servers/slapd/add.c +++ b/ldap/servers/slapd/add.c @@ -571,6 +571,7 @@ op_shared_add(Slapi_PBlock *pb) logpb.op_id = op_id; logpb.op_internal_id = op_internal_id; logpb.op_nested_count = op_nested_count; + logpb.level = LDAP_DEBUG_ARGS; slapd_log_access_add(&logpb); } else { slapi_log_access(LDAP_DEBUG_ARGS, diff --git a/ldap/servers/slapd/back-ldbm/sort.c b/ldap/servers/slapd/back-ldbm/sort.c index 70f541ff21..73a483085f 100644 --- a/ldap/servers/slapd/back-ldbm/sort.c +++ b/ldap/servers/slapd/back-ldbm/sort.c @@ -122,7 +122,15 @@ sort_log_access(Slapi_PBlock *pb, sort_spec_thing *s, IDList *candidates, PRBool buffer_copy = slapi_ch_strdup(buffer); } else { /* Log it */ - ldbm_log_access_message(pb, buffer); + int32_t log_format = config_get_accesslog_log_format(); + if (log_format != LOG_FORMAT_DEFAULT) { + slapd_log_pblock logpb = {0}; + slapd_log_pblock_init(&logpb, log_format, pb); + logpb.sort_str = buffer; + slapd_log_access_sort(&logpb); + } else { + ldbm_log_access_message(pb, buffer); + } } if (buffer != stack_buffer) { slapi_ch_free_string(&buffer); diff --git a/ldap/servers/slapd/connection.c b/ldap/servers/slapd/connection.c index ad83ff5089..eddc7e3a75 100644 --- a/ldap/servers/slapd/connection.c +++ b/ldap/servers/slapd/connection.c @@ -425,8 +425,7 @@ connection_reset(Connection *conn, int ns, PRNetAddr *from, int fromLen __attrib /* log useful stuff to our access log */ if (log_format != LOG_FORMAT_DEFAULT) { slapd_log_pblock logpb = {0}; - - logpb.log_format = log_format; + slapd_log_pblock_init(&logpb, log_format, NULL); logpb.conn_time = conn->c_starttime; logpb.conn_id = conn->c_connid; logpb.fd = conn->c_sd; @@ -552,13 +551,12 @@ connection_need_new_password(const Connection *conn, const Operation *op, Slapi_ if (log_format != LOG_FORMAT_DEFAULT) { slapd_log_pblock logpb = {0}; - - logpb.log_format = log_format; + slapd_log_pblock_init(&logpb, log_format, pb); logpb.conn_time = conn->c_starttime; logpb.conn_id = conn->c_connid; logpb.op_id = op->o_opid; logpb.request_controls = operation_get_req_controls(op); - logpb.result_controls = operation_get_result_controls(op); + logpb.response_controls = operation_get_result_controls(op); logpb.msg = "UNPROCESSED OPERATION - need new password"; slapd_log_access_error(&logpb); } else { @@ -621,7 +619,7 @@ connection_dispatch_operation(Connection *conn, Operation *op, Slapi_PBlock *pb) { if (log_format != LOG_FORMAT_DEFAULT) { slapd_log_pblock logpb = {0}; - logpb.log_format = log_format; + slapd_log_pblock_init(&logpb, log_format, pb); logpb.conn_time = conn->c_starttime; logpb.conn_id = conn->c_connid; logpb.op_id = op->o_opid; @@ -664,8 +662,7 @@ connection_dispatch_operation(Connection *conn, Operation *op, Slapi_PBlock *pb) { if (log_format != LOG_FORMAT_DEFAULT) { slapd_log_pblock logpb = {0}; - - logpb.log_format = log_format; + slapd_log_pblock_init(&logpb, log_format, pb); logpb.conn_time = conn->c_starttime; logpb.conn_id = conn->c_connid; logpb.op_id = op->o_opid; @@ -1364,13 +1361,13 @@ connection_read_operation(Connection *conn, Operation *op, ber_tag_t *tag, int * if (log_format != LOG_FORMAT_DEFAULT) { slapd_log_pblock logpb = {0}; - - logpb.log_format = log_format; + slapd_log_pblock_init(&logpb, log_format, NULL); logpb.conn_time = conn->c_starttime; logpb.conn_id =conn->c_connid; logpb.fd = conn->c_sd; logpb.haproxy_ip = str_haproxy_ip; logpb.haproxy_destip = str_haproxy_destip; + logpb.haproxied = true; slapd_log_access_haproxy(&logpb); } else { slapi_log_access(LDAP_DEBUG_STATS, @@ -2498,7 +2495,7 @@ disconnect_server_nomutex_ext(Connection *conn, PRUint64 opconnid, int opid, PRE conn->c_flags |= CONN_FLAG_CLOSING; g_decrement_current_conn_count(); - logpb.log_format = log_format; + slapd_log_pblock_init(&logpb, log_format, NULL); logpb.conn_time = conn->c_starttime; logpb.conn_id = conn->c_connid; logpb.op_id = opid; diff --git a/ldap/servers/slapd/control.c b/ldap/servers/slapd/control.c index 538a387da0..a30716a277 100644 --- a/ldap/servers/slapd/control.c +++ b/ldap/servers/slapd/control.c @@ -1,6 +1,6 @@ /** BEGIN COPYRIGHT BLOCK * Copyright (C) 2001 Sun Microsystems, Inc. Used by permission. - * Copyright (C) 2005 Red Hat, Inc. + * Copyright (C) 2025 Red Hat, Inc. * All rights reserved. * * License: GPL (version 3 or any later version). @@ -14,6 +14,7 @@ /* control.c - routines for dealing with LDAPMessage controls */ #include +#include #include "slap.h" @@ -774,11 +775,14 @@ slapi_build_control_from_berval(char *oid, struct berval *bvp, char iscritical, /* * Parse an LDAP control into its parts + * The caller must free "value" */ void -slapi_parse_control(LDAPControl *ctrl, char **oid, char **value, PRBool *isCritical) +slapi_parse_control(LDAPControl *ctrl, char **oid, char **value, bool *isCritical) { *isCritical = ctrl->ldctl_iscritical; - *value = ctrl->ldctl_value.bv_val; + if (ctrl->ldctl_value.bv_len > 0) { + *value = PL_Base64Encode(ctrl->ldctl_value.bv_val, ctrl->ldctl_value.bv_len, NULL); + } *oid = ctrl->ldctl_oid; } diff --git a/ldap/servers/slapd/delete.c b/ldap/servers/slapd/delete.c index b53b73d334..8a149d7c51 100644 --- a/ldap/servers/slapd/delete.c +++ b/ldap/servers/slapd/delete.c @@ -265,18 +265,15 @@ op_shared_delete(Slapi_PBlock *pb) } /* Prep log pblock */ - logpb.log_format = log_format; + slapd_log_pblock_init(&logpb, log_format, pb); logpb.authzid = proxydn; - logpb.request_controls = operation_get_req_controls(operation); logpb.target_dn = slapi_sdn_get_dn(sdn); if (!internal_op) { Connection *pb_conn = NULL; slapi_pblock_get(pb, SLAPI_CONNECTION, &pb_conn); - if (log_format != LOG_FORMAT_DEFAULT) { - slapd_log_pblock_init(&logpb, log_format, pb); - slapd_log_access_delete(&logpb); + if (log_format != LOG_FORMAT_DEFAULT) { slapd_log_access_delete(&logpb); } else { slapi_log_access(LDAP_DEBUG_STATS, "conn=%" PRIu64 " op=%d DEL dn=\"%s\"%s\n", pb_conn ? pb_conn->c_connid : -1, @@ -298,6 +295,7 @@ op_shared_delete(Slapi_PBlock *pb) logpb.op_id = op_id; logpb.op_internal_id = op_internal_id; logpb.op_nested_count = op_nested_count; + logpb.level = LDAP_DEBUG_ARGS; slapd_log_access_delete(&logpb); } else { slapi_log_access(LDAP_DEBUG_ARGS, diff --git a/ldap/servers/slapd/extendop.c b/ldap/servers/slapd/extendop.c index 48b0be229b..915e68f7f2 100644 --- a/ldap/servers/slapd/extendop.c +++ b/ldap/servers/slapd/extendop.c @@ -339,7 +339,7 @@ do_extended(Slapi_PBlock *pb) } else { slapd_log_pblock_init(&logpb, log_format, pb); logpb.oid = extoid; - logpb.msg = name; + logpb.name = name; slapd_log_access_extop(&logpb); } } diff --git a/ldap/servers/slapd/ldapi.c b/ldap/servers/slapd/ldapi.c index 28d5b49118..52b7a6dc34 100644 --- a/ldap/servers/slapd/ldapi.c +++ b/ldap/servers/slapd/ldapi.c @@ -393,10 +393,10 @@ slapd_bind_local_user(Connection *conn) if (log_format != LOG_FORMAT_DEFAULT) { /* JSON logging */ slapd_log_pblock logpb = {0}; - - logpb.log_format = log_format; + slapd_log_pblock_init(&logpb, log_format, NULL); logpb.conn_time = conn->c_starttime; logpb.conn_id = conn->c_connid; + logpb.op_id = -1; logpb.bind_dn = conn->c_dn; slapd_log_access_autobind(&logpb); } else { diff --git a/ldap/servers/slapd/libglobs.c b/ldap/servers/slapd/libglobs.c index af7dde9fc5..4e72a2b0c4 100644 --- a/ldap/servers/slapd/libglobs.c +++ b/ldap/servers/slapd/libglobs.c @@ -844,7 +844,7 @@ static struct config_get_and_set {CONFIG_ACCESSLOG_TIME_FORMAT_ATTRIBUTE, config_set_accesslog_time_format, NULL, 0, (void **)&global_slapdFrontendConfig.accesslog_time_format, - CONFIG_STRING, NULL, SLAPD_INIT_LOG_TIME_FORMAT, NULL}, + CONFIG_STRING, NULL, SLAPD_INIT_ACCESS_LOG_TIME_FORMAT, NULL}, {CONFIG_ACCESSLOG_BUFFERING_ATTRIBUTE, config_set_accesslogbuffering, NULL, 0, (void **)&global_slapdFrontendConfig.accesslogbuffering, @@ -1888,7 +1888,7 @@ FrontendConfig_init(void) cfg->accesslog_exptimeunit = slapi_ch_strdup(SLAPD_INIT_LOG_EXPTIMEUNIT); cfg->accessloglevel = SLAPD_DEFAULT_ACCESSLOG_LEVEL; cfg->accesslog_log_format = slapi_ch_strdup(SLAPD_INIT_LOG_FORMAT); - cfg->accesslog_time_format = slapi_ch_strdup(SLAPD_INIT_LOG_TIME_FORMAT); + cfg->accesslog_time_format = slapi_ch_strdup(SLAPD_INIT_ACCESS_LOG_TIME_FORMAT); init_accesslogbuffering = cfg->accesslogbuffering = LDAP_ON; init_csnlogging = cfg->csnlogging = LDAP_ON; init_accesslog_compress_enabled = cfg->accesslog_compress = LDAP_OFF; diff --git a/ldap/servers/slapd/log.c b/ldap/servers/slapd/log.c index 31176c2dca..b58e593f35 100644 --- a/ldap/servers/slapd/log.c +++ b/ldap/servers/slapd/log.c @@ -85,7 +85,6 @@ static int slapi_log_map[] = { LDAP_DEBUG_NOTICE, /* SLAPI_LOG_NOTICE */ LDAP_DEBUG_INFO, /* SLAPI_LOG_INFO */ LDAP_DEBUG_DEBUG /* SLAPI_LOG_DEBUG */ - }; #define SLAPI_LOG_MIN SLAPI_LOG_FATAL /* from slapi-plugin.h */ @@ -127,12 +126,13 @@ static time_t log_reverse_convert_time(char *tbuf); static LogBufferInfo *log_create_buffer(size_t sz); static void log_append_security_buffer(time_t tnl, LogBufferInfo *lbi, char *msg, size_t size); static void log_append_access_buffer(time_t tnl, LogBufferInfo *lbi, char *msg1, size_t size1, char *msg2, size_t size2); +static void log_append_access_json_buffer(time_t tnl, LogBufferInfo *lbi, char *msg, size_t size); static void log_append_audit_buffer(time_t tnl, LogBufferInfo *lbi, char *msg, size_t size); static void log_append_auditfail_buffer(time_t tnl, LogBufferInfo *lbi, char *msg, size_t size); static void log_append_error_buffer(time_t tnl, LogBufferInfo *lbi, char *msg, size_t size, int locked); static void log_flush_buffer(LogBufferInfo *lbi, int type, int sync_now, int locked); static void log_write_title(LOGFD fp); -static void log__error_emergency(const char *errstr, int reopen, int locked); +static void log_write_json_title(LOGFD fp, int32_t log_format); static void vslapd_log_emergency_error(LOGFD fp, const char *msg, int locked); static int get_syslog_loglevel(int loglevel); static void log_external_libs_debug_openldap_print(char *buffer); @@ -2237,6 +2237,45 @@ log_set_expirationtimeunit(const char *attrname, char *expunit, int logtype, cha /****************************************************************************** * Write title line in log file *****************************************************************************/ +static void +log_write_json_title(LOGFD fp, int32_t log_format) +{ + json_object *json_header = json_object_new_object(); + json_object *json_obj = json_object_new_object(); + slapdFrontendConfig_t *fe_cfg = getFrontendConfig(); + char log_buffer[SLAPI_LOG_BUFSIZ] = {0}; + char *buildnum = config_get_buildnum(); + char buff[512] = {0}; + int bufflen = sizeof(buff); + char *msg = NULL; + + PR_snprintf(buff, bufflen, "%s B%s", + fe_cfg->versionstring ? fe_cfg->versionstring : CAPBRAND "-Directory/" DS_PACKAGE_VERSION, + buildnum ? buildnum : ""); + json_object_object_add(json_header, "version", json_object_new_string(buff)); + + if (fe_cfg->localhost) { + PR_snprintf(buff, bufflen, "%s:%d (%s)", + fe_cfg->localhost, + fe_cfg->security ? fe_cfg->secureport : fe_cfg->port, + fe_cfg->configdir ? fe_cfg->configdir : ""); + } else { + PR_snprintf(buff, bufflen, ": (%s)", + fe_cfg->configdir ? fe_cfg->configdir : ""); + } + json_object_object_add(json_header, "instance", json_object_new_string(buff)); + json_object_object_add(json_obj, "header", json_header); + msg = (char *)json_object_to_json_string_ext(json_obj, log_format); + + /* Now write the JSON title */ + PR_snprintf(log_buffer, sizeof(log_buffer), "%s\n", msg); + log_write(fp, log_buffer, strlen(log_buffer), 0, FLUSH); + + /* Free it all */ + json_object_put(json_obj); + slapi_ch_free_string(&buildnum); +} + static void log_write_title(LOGFD fp) { @@ -3098,6 +3137,50 @@ vslapd_log_access(const char *fmt, va_list ap) return (rc); } +int32_t +slapd_log_access_json(char *buffer) +{ + /* We use this to route audit log entries to where they need to go */ + int32_t retval = LDAP_SUCCESS; + int32_t lbackend = loginfo.log_backend; /* We copy this to make these next checks atomic */ + + if (lbackend & LOGGING_BACKEND_INTERNAL) { + char log_buffer[SLAPI_LOG_BUFSIZ] = {0}; + int32_t buffer_len = strlen(buffer) + 1; + time_t tnl = slapi_current_utc_time(); + + if (buffer_len > SLAPI_LOG_BUFSIZ) { + /* + * We won't be able to fit the message in! Uh-oh! + * If the issue is not resolved during the fmt string creation (see op_shared_search()), + * we truncate the line and still log the message allowing the admin to check if + * someone is trying to do something bad. + */ + memcpy(&log_buffer, buffer, SLAPI_LOG_BUFSIZ-6); + memcpy(&log_buffer[SLAPI_LOG_BUFSIZ-6], "...\n}\n", 5); /* cap the json event */ + slapi_log_err(SLAPI_LOG_ERR, "slapd_log_access_json", + "Insufficient buffer capacity to fit message! " + "The line in the access log was truncated\n"); + buffer_len = strlen(log_buffer); + retval = -1; + } else { + PR_snprintf(log_buffer, sizeof(log_buffer), "%s\n", buffer); + } + log_append_access_json_buffer(tnl, loginfo.log_access_buffer, log_buffer, buffer_len); + } + + if (lbackend & LOGGING_BACKEND_SYSLOG) { + /* This returns void, so we hope it worked */ + syslog(LOG_NOTICE, "%s\n", buffer); + } +#ifdef HAVE_JOURNALD + if (lbackend & LOGGING_BACKEND_JOURNALD) { + retval = sd_journal_print(LOG_NOTICE, "%s\n", buffer); + } +#endif + return retval; +} + int slapi_log_stat(int loglevel, const char *fmt, ...) { @@ -6045,7 +6128,7 @@ log__auditfail_rotationinfof(char *pathname) return logfile_type; } -static void +void log__error_emergency(const char *errstr, int reopen, int locked) { syslog(LOG_ERR, "%s\n", errstr); @@ -6686,6 +6769,43 @@ log_append_access_buffer(time_t tnl, LogBufferInfo *lbi, char *msg1, size_t size } } +static void +log_append_access_json_buffer(time_t tnl, LogBufferInfo *lbi, char *msg, size_t size) +{ + slapdFrontendConfig_t *slapdFrontendConfig = getFrontendConfig(); + char *insert_point = NULL; + + /* While holding the lock, we determine if there is space in the buffer for our payload, + and if we need to flush. + */ + PR_Lock(lbi->lock); + if (((lbi->current - lbi->top) + size > lbi->maxsize) || + (tnl >= loginfo.log_access_rotationsyncclock && + loginfo.log_access_rotationsync_enabled)) + { + log_flush_buffer(lbi, SLAPD_ACCESS_LOG, + 0 /* do not sync to disk right now */, 1); + } + insert_point = lbi->current; + lbi->current += size; + /* Increment the copy refcount */ + slapi_atomic_incr_64(&(lbi->refcount), __ATOMIC_RELEASE); + PR_Unlock(lbi->lock); + + /* Now we can copy without holding the lock */ + memcpy(insert_point, msg, size); + + /* Decrement the copy refcount */ + slapi_atomic_decr_64(&(lbi->refcount), __ATOMIC_RELEASE); + + /* If we are asked to sync to disk immediately, do so */ + if (!slapdFrontendConfig->accesslogbuffering) { + PR_Lock(lbi->lock); + log_flush_buffer(lbi, SLAPD_ACCESS_LOG, 1 /* sync to disk now */, 1); + PR_Unlock(lbi->lock); + } +} + static time_t log_update_sync_clock(int32_t log_type, int32_t secs) { @@ -6882,7 +7002,34 @@ log_flush_buffer(LogBufferInfo *lbi, int log_type, int sync_now, int locked) } if (log_state & LOGGING_NEED_TITLE) { - log_write_title(fd); + int32_t accesslog_format = config_get_accesslog_log_format(); + int32_t auditlog_format = config_get_auditlog_log_format(); + int32_t securitylog_format = LOG_FORMAT_JSON; + + switch (log_type) { + case SLAPD_ACCESS_LOG: + if (accesslog_format != LOG_FORMAT_DEFAULT) { + log_write_json_title(fd, accesslog_format); + } else { + log_write_title(fd); + } + break; + case SLAPD_AUDIT_LOG: + case SLAPD_AUDITFAIL_LOG: + if (auditlog_format != LOG_FORMAT_DEFAULT) { + log_write_json_title(fd, auditlog_format); + } else { + log_write_title(fd); + } + break; + case SLAPD_SECURITY_LOG: + log_write_json_title(fd, securitylog_format); + break; + default: + /* Error log - standard title */ + log_write_title(fd); + } + log_state_remove_need_title(log_type); } @@ -7084,10 +7231,14 @@ slapd_log_pblock_init(slapd_log_pblock *logpb, int32_t log_format, Slapi_PBlock slapi_pblock_get(pb, SLAPI_CONNECTION, &conn); } + logpb->loginfo = &loginfo; + logpb->level = 256; /* default log level */ logpb->log_format = log_format; logpb->pb = pb; + logpb->op_id = -1; logpb->op_internal_id = -1; logpb->op_nested_count = -1; + logpb->curr_time = slapi_current_utc_time_hr(); if (conn) { logpb->conn_time = conn->c_starttime; @@ -7102,6 +7253,6 @@ slapd_log_pblock_init(slapd_log_pblock *logpb, int32_t log_format, Slapi_PBlock if (op) { logpb->op_id = op->o_opid; logpb->request_controls = operation_get_req_controls(op); - logpb->result_controls = operation_get_result_controls(op); + logpb->response_controls = operation_get_result_controls(op); } -} \ No newline at end of file +} diff --git a/ldap/servers/slapd/modify.c b/ldap/servers/slapd/modify.c index 55131d77c9..356f296056 100644 --- a/ldap/servers/slapd/modify.c +++ b/ldap/servers/slapd/modify.c @@ -658,9 +658,9 @@ op_shared_modify(Slapi_PBlock *pb, int pw_change, char *old_pw) proxystr = slapi_ch_smprintf(" authzid=\"%s\"", proxydn); } + slapd_log_pblock_init(&logpb, log_format, pb); if (!internal_op) { if (log_format != LOG_FORMAT_DEFAULT) { - slapd_log_pblock_init(&logpb, log_format, pb); logpb.target_dn = slapi_sdn_get_dn(sdn); logpb.authzid = proxydn; slapd_log_access_mod(&logpb); @@ -680,7 +680,6 @@ op_shared_modify(Slapi_PBlock *pb, int pw_change, char *old_pw) time_t start_time; get_internal_conn_op(&connid, &op_id, &op_internal_id, &op_nested_count, &start_time); if (log_format != LOG_FORMAT_DEFAULT) { - logpb.log_format = log_format; logpb.conn_time = start_time; logpb.conn_id = connid; logpb.op_id = op_id; @@ -688,6 +687,7 @@ op_shared_modify(Slapi_PBlock *pb, int pw_change, char *old_pw) logpb.op_nested_count = op_nested_count; logpb.target_dn = slapi_sdn_get_dn(sdn); logpb.authzid = proxydn; + logpb.level = LDAP_DEBUG_ARGS; slapd_log_access_mod(&logpb); } else { slapi_log_access(LDAP_DEBUG_ARGS, @@ -1349,6 +1349,7 @@ op_shared_allow_pw_change(Slapi_PBlock *pb, LDAPMod *mod, char **old_pw, Slapi_M logpb.op_nested_count = 0; logpb.authzid = proxydn; logpb.msg = "within password minimum age"; + logpb.level = LDAP_DEBUG_ARGS; slapd_log_access_mod(&logpb); } else { slapi_log_access(LDAP_DEBUG_ARGS, "conn=%s op=%d MOD dn=\"%s\"%s, %s\n", @@ -1399,6 +1400,7 @@ op_shared_allow_pw_change(Slapi_PBlock *pb, LDAPMod *mod, char **old_pw, Slapi_M logpb.op_nested_count = 0; logpb.authzid = proxydn; logpb.msg = "invalid password syntax"; + logpb.level = LDAP_DEBUG_ARGS; slapd_log_access_mod(&logpb); } else { slapi_log_access(LDAP_DEBUG_ARGS, "conn=%s op=%d MOD dn=\"%s\"%s, %s\n", diff --git a/ldap/servers/slapd/modrdn.c b/ldap/servers/slapd/modrdn.c index 12fc1a945a..d8bd4f5028 100644 --- a/ldap/servers/slapd/modrdn.c +++ b/ldap/servers/slapd/modrdn.c @@ -507,6 +507,7 @@ op_shared_rename(Slapi_PBlock *pb, int passin_args) logpb.op_id = op_id; logpb.op_internal_id = op_internal_id; logpb.op_nested_count = op_nested_count; + logpb.level = LDAP_DEBUG_ARGS; slapd_log_access_modrdn(&logpb); } else { slapi_log_access(LDAP_DEBUG_ARGS, diff --git a/ldap/servers/slapd/opshared.c b/ldap/servers/slapd/opshared.c index dda92e1f2e..cce15d7ad6 100644 --- a/ldap/servers/slapd/opshared.c +++ b/ldap/servers/slapd/opshared.c @@ -412,6 +412,7 @@ op_shared_search(Slapi_PBlock *pb, int send_result) logpb.op_id = op_id; logpb.op_internal_id = op_internal_id; logpb.op_nested_count = op_nested_count; + logpb.level = LDAP_DEBUG_ARGS; slapd_log_access_search(&logpb); } else { slapi_log_access(LDAP_DEBUG_ARGS, fmtstr, diff --git a/ldap/servers/slapd/proto-slap.h b/ldap/servers/slapd/proto-slap.h index 205a49c21a..8a3424e4ee 100644 --- a/ldap/servers/slapd/proto-slap.h +++ b/ldap/servers/slapd/proto-slap.h @@ -674,7 +674,7 @@ int get_ldapmessage_controls(Slapi_PBlock *pb, BerElement *ber, LDAPControl ***c int get_ldapmessage_controls_ext(Slapi_PBlock *pb, BerElement *ber, LDAPControl ***controls, int ignore_criticality); int write_controls(BerElement *ber, LDAPControl **ctrls); void add_control(LDAPControl ***ctrlsp, LDAPControl *newctrl); -void slapi_parse_control(LDAPControl *ctrl, char **oid, char **value, PRBool *isCritical); +void slapi_parse_control(LDAPControl *ctrl, char **oid, char **value, bool *isCritical); /* * daemon.c @@ -863,6 +863,7 @@ int slapi_log_security(Slapi_PBlock *pb, const char *event_type, const char *msg int slapi_log_security_tcp(Connection *pb_conn, const char *event_type, PRErrorCode error, const char *msg); int slapd_log_audit(char *buffer, PRBool json); int slapd_log_auditfail(char *buffer, PRBool json); +int32_t slapd_log_access_json(char *buffer); void logs_flush(void); int access_log_openf(char *pathname, int locked); @@ -910,6 +911,7 @@ void g_set_accesslog_level(int val); void g_set_statlog_level(int val); void g_set_securitylog_level(int val); void log__delete_rotated_logs(void); +void log__error_emergency(const char *errstr, int reopen, int locked); void slapd_log_pblock_init(slapd_log_pblock *logpb, int32_t log_format, Slapi_PBlock *pb); /* @@ -1114,7 +1116,7 @@ void g_decrement_current_conn_count(void); void g_set_current_conn_count_mutex(PRLock *plock); PRLock *g_get_current_conn_count_mutex(void); int encode_attr(Slapi_PBlock *pb, BerElement *ber, Slapi_Entry *e, Slapi_Attr *a, int attrsonly, char *type); - +void get_notes_info(unsigned int notes, char **note, char **details); /* access json logging */ /* * schema.c @@ -1265,6 +1267,7 @@ time_t poll_current_time(void); char *format_localTime(time_t from); int format_localTime_log(time_t t, int initsize, char *buf, int *bufsize); int format_localTime_hr_log(time_t t, long nsec, int initsize, char *buf, int *bufsize); +int32_t format_localTime_hr_json_log(struct timespec *ts, char *buf, int *bufsize, char *format); time_t parse_localTime(char *from); #ifndef HAVE_TIME_R diff --git a/ldap/servers/slapd/result.c b/ldap/servers/slapd/result.c index 1581b8a55a..bb93957c17 100644 --- a/ldap/servers/slapd/result.c +++ b/ldap/servers/slapd/result.c @@ -1950,6 +1950,21 @@ static struct slapi_note_map notemap[] = { #define SLAPI_NOTEMAP_COUNT (sizeof(notemap) / sizeof(struct slapi_note_map)) +/* Used for JSON access logging */ +void +get_notes_info(unsigned int notes, char **note, char **details) +{ + int32_t n = 0; + + for (size_t i = 0; i < SLAPI_NOTEMAP_COUNT; i++) { + if (notemap[i].snp_noteid & notes) { + note[n] = notemap[i].snp_string; + details[n] = notemap[i].snp_detail; + n++; + } + } +} + /* * fill buf with a string representation of the bits present in notes. * @@ -2092,7 +2107,7 @@ log_op_stat(Slapi_PBlock *pb, uint64_t connid, int32_t op_id, int32_t op_interna if ((LDAP_STAT_READ_INDEX & config_get_statlog_level()) && op_stat->search_stat) { struct component_keys_lookup *key_info; - logpb.log_format = log_format; + slapd_log_pblock_init(&logpb, log_format, pb); logpb.conn_time = start_time; logpb.conn_id = connid; logpb.op_id = op_id; @@ -2140,14 +2155,30 @@ log_op_stat(Slapi_PBlock *pb, uint64_t connid, int32_t op_id, int32_t op_interna slapi_timespec_diff(&op_stat->search_stat->keys_lookup_end, &op_stat->search_stat->keys_lookup_start, &duration); snprintf(stat_etime, ETIME_BUFSIZ, "%" PRId64 ".%.09" PRId64 "", (int64_t)duration.tv_sec, (int64_t)duration.tv_nsec); if (internal_op) { - slapi_log_stat(LDAP_STAT_READ_INDEX, - connid == 0 ? STAT_LOG_CONN_OP_FMT_INT_INT "STAT read index: duration %s\n": - STAT_LOG_CONN_OP_FMT_EXT_INT "STAT read index: duration %s\n", - connid, op_id, op_internal_id, op_nested_count, stat_etime); + if (log_format != LOG_FORMAT_DEFAULT) { + /* JSON logging */ + logpb.op_internal_id = op_internal_id; + logpb.op_nested_count = op_nested_count; + logpb.stat_etime = stat_etime; + slapd_log_access_stat(&logpb); + } else { + slapi_log_stat(LDAP_STAT_READ_INDEX, + connid == 0 ? STAT_LOG_CONN_OP_FMT_INT_INT "STAT read index: duration %s\n": + STAT_LOG_CONN_OP_FMT_EXT_INT "STAT read index: duration %s\n", + connid, op_id, op_internal_id, op_nested_count, stat_etime); + } } else { - slapi_log_stat(LDAP_STAT_READ_INDEX, - "conn=%" PRIu64 " op=%d STAT read index: duration %s\n", - op->o_connid, op->o_opid, stat_etime); + if (log_format != LOG_FORMAT_DEFAULT) { + /* JSON logging */ + logpb.op_internal_id = -1; + logpb.op_nested_count = -1; + logpb.stat_etime = stat_etime; + slapd_log_access_stat(&logpb); + } else { + slapi_log_stat(LDAP_STAT_READ_INDEX, + "conn=%" PRIu64 " op=%d STAT read index: duration %s\n", + op->o_connid, op->o_opid, stat_etime); + } } } break; @@ -2261,6 +2292,7 @@ log_result(Slapi_PBlock *pb, Operation *op, int err, ber_tag_t tag, int nentries logpb.pr_cookie = 0; logpb.msg = NULL; logpb.sid = sessionTrackingId; + logpb.tag = tag; } #define LOG_CONN_OP_FMT_INT_INT "conn=Internal(%" PRIu64 ") op=%d(%d)(%d) RESULT err=%d" @@ -2289,9 +2321,13 @@ log_result(Slapi_PBlock *pb, Operation *op, int err, ber_tag_t tag, int nentries } else { if (log_format != LOG_FORMAT_DEFAULT) { /* fill in the remaining params*/ + logpb.conn_time = start_time; + logpb.conn_id = connid; + logpb.op_id = op_id; logpb.op_internal_id = op_internal_id; logpb.op_nested_count = op_nested_count; logpb.msg = "SASL bind in progress"; + logpb.level = LDAP_DEBUG_ARGS; slapd_log_access_result(&logpb); } else { #define LOG_SASLMSG_FMT " tag=%" BERTAG_T " nentries=%d wtime=%s optime=%s etime=%s%s%s%s, SASL bind in progress\n" @@ -2309,7 +2345,7 @@ log_result(Slapi_PBlock *pb, Operation *op, int err, ber_tag_t tag, int nentries } } else if (op->o_tag == LDAP_REQ_BIND && err == LDAP_SUCCESS) { char *dn = NULL; - + slapi_pblock_get(pb, SLAPI_CONN_DN, &dn); /* * For methods other than simple, the dn in the bind request * may be irrelevant. Log the actual authenticated dn. @@ -2318,43 +2354,46 @@ log_result(Slapi_PBlock *pb, Operation *op, int err, ber_tag_t tag, int nentries if (log_format != LOG_FORMAT_DEFAULT) { /* fill in the remaining params*/ logpb.msg = "SASL bind in progress"; + logpb.bind_dn = dn; slapd_log_access_result(&logpb); } else { - slapi_pblock_get(pb, SLAPI_CONN_DN, &dn); slapi_log_access(LDAP_DEBUG_STATS, - "conn=%" PRIu64 " op=%d RESULT err=%d" - " tag=%" BERTAG_T " nentries=%d wtime=%s optime=%s etime=%s%s%s%s" - " dn=\"%s\"\n", - op->o_connid, - op->o_opid, - err, tag, nentries, - wtime, optime, etime, - notes_str, csn_str, session_str, dn ? dn : ""); - slapi_ch_free_string(&dn); + "conn=%" PRIu64 " op=%d RESULT err=%d" + " tag=%" BERTAG_T " nentries=%d wtime=%s optime=%s etime=%s%s%s%s" + " dn=\"%s\"\n", + op->o_connid, + op->o_opid, + err, tag, nentries, + wtime, optime, etime, + notes_str, csn_str, session_str, dn ? dn : ""); } } else { if (log_format != LOG_FORMAT_DEFAULT) { /* fill in the remaining params*/ + logpb.conn_time = start_time; + logpb.conn_id = connid; + logpb.op_id = op_id; logpb.op_internal_id = op_internal_id; logpb.op_nested_count = op_nested_count; logpb.msg = "SASL bind in progress"; + logpb.bind_dn = dn; + logpb.level = LDAP_DEBUG_ARGS; slapd_log_access_result(&logpb); } else { - slapi_pblock_get(pb, SLAPI_CONN_DN, &dn); #define LOG_BINDMSG_FMT " tag=%" BERTAG_T " nentries=%d wtime=%s optime=%s etime=%s%s%s%s dn=\"%s\"\n" slapi_log_access(LDAP_DEBUG_ARGS, - connid == 0 ? LOG_CONN_OP_FMT_INT_INT LOG_BINDMSG_FMT : - LOG_CONN_OP_FMT_EXT_INT LOG_BINDMSG_FMT, - connid, - op_id, - op_internal_id, - op_nested_count, - err, tag, nentries, - wtime, optime, etime, - notes_str, csn_str, session_str, dn ? dn : ""); - slapi_ch_free_string(&dn); + connid == 0 ? LOG_CONN_OP_FMT_INT_INT LOG_BINDMSG_FMT : + LOG_CONN_OP_FMT_EXT_INT LOG_BINDMSG_FMT, + connid, + op_id, + op_internal_id, + op_nested_count, + err, tag, nentries, + wtime, optime, etime, + notes_str, csn_str, session_str, dn ? dn : ""); } } + slapi_ch_free_string(&dn); } else { if (pr_idx > -1) { if (!internal_op) { @@ -2365,35 +2404,39 @@ log_result(Slapi_PBlock *pb, Operation *op, int err, ber_tag_t tag, int nentries slapd_log_access_result(&logpb); } else { slapi_log_access(LDAP_DEBUG_STATS, - "conn=%" PRIu64 " op=%d RESULT err=%d" - " tag=%" BERTAG_T " nentries=%d wtime=%s optime=%s etime=%s%s%s%s" - " pr_idx=%d pr_cookie=%d\n", - op->o_connid, - op->o_opid, - err, tag, nentries, - wtime, optime, etime, session_str, - notes_str, csn_str, pr_idx, pr_cookie); + "conn=%" PRIu64 " op=%d RESULT err=%d" + " tag=%" BERTAG_T " nentries=%d wtime=%s optime=%s etime=%s%s%s%s" + " pr_idx=%d pr_cookie=%d\n", + op->o_connid, + op->o_opid, + err, tag, nentries, + wtime, optime, etime, session_str, + notes_str, csn_str, pr_idx, pr_cookie); } } else { if (log_format != LOG_FORMAT_DEFAULT) { /* fill in the remaining params*/ + logpb.conn_time = start_time; + logpb.conn_id = connid; + logpb.op_id = op_id; logpb.op_internal_id = op_internal_id; logpb.op_nested_count = op_nested_count; logpb.pr_idx = pr_idx; logpb.pr_cookie = pr_cookie; + logpb.level = LDAP_DEBUG_ARGS; slapd_log_access_result(&logpb); } else { #define LOG_PRMSG_FMT " tag=%" BERTAG_T " nentries=%d wtime=%s optime=%s etime=%s%s%s%s pr_idx=%d pr_cookie=%d \n" slapi_log_access(LDAP_DEBUG_ARGS, - connid == 0 ? LOG_CONN_OP_FMT_INT_INT LOG_PRMSG_FMT : - LOG_CONN_OP_FMT_EXT_INT LOG_PRMSG_FMT, - connid, - op_id, - op_internal_id, - op_nested_count, - err, tag, nentries, - wtime, optime, etime, - notes_str, csn_str, session_str, pr_idx, pr_cookie); + connid == 0 ? LOG_CONN_OP_FMT_INT_INT LOG_PRMSG_FMT : + LOG_CONN_OP_FMT_EXT_INT LOG_PRMSG_FMT, + connid, + op_id, + op_internal_id, + op_nested_count, + err, tag, nentries, + wtime, optime, etime, + notes_str, csn_str, session_str, pr_idx, pr_cookie); } } } else if (!internal_op) { @@ -2413,13 +2456,13 @@ log_result(Slapi_PBlock *pb, Operation *op, int err, ber_tag_t tag, int nentries slapd_log_access_result(&logpb); } else { slapi_log_access(LDAP_DEBUG_STATS, - "conn=%" PRIu64 " op=%d RESULT err=%d" - " tag=%" BERTAG_T " nentries=%d wtime=%s optime=%s etime=%s%s%s%s%s\n", - op->o_connid, - op->o_opid, - err, tag, nentries, - wtime, optime, etime, - notes_str, csn_str, ext_str, session_str); + "conn=%" PRIu64 " op=%d RESULT err=%d" + " tag=%" BERTAG_T " nentries=%d wtime=%s optime=%s etime=%s%s%s%s%s\n", + op->o_connid, + op->o_opid, + err, tag, nentries, + wtime, optime, etime, + notes_str, csn_str, ext_str, session_str); } if (pbtxt) { /* if !pbtxt ==> ext_str == "". Don't free ext_str. */ @@ -2431,21 +2474,25 @@ log_result(Slapi_PBlock *pb, Operation *op, int err, ber_tag_t tag, int nentries if (log_format != LOG_FORMAT_DEFAULT) { /* fill in the remaining params*/ + logpb.conn_time = start_time; + logpb.conn_id = connid; + logpb.op_id = op_id; logpb.op_internal_id = op_internal_id; logpb.op_nested_count = op_nested_count; + logpb.level = LDAP_DEBUG_ARGS; slapd_log_access_result(&logpb); } else { #define LOG_MSG_FMT " tag=%" BERTAG_T " nentries=%d wtime=%s optime=%s etime=%s%s%s%s\n" slapi_log_access(LDAP_DEBUG_ARGS, - connid == 0 ? LOG_CONN_OP_FMT_INT_INT LOG_MSG_FMT : - LOG_CONN_OP_FMT_EXT_INT LOG_MSG_FMT, - connid, - op_id, - op_internal_id, - op_nested_count, - err, tag, nentries, - wtime, optime, etime, - notes_str, csn_str, session_str); + connid == 0 ? LOG_CONN_OP_FMT_INT_INT LOG_MSG_FMT : + LOG_CONN_OP_FMT_EXT_INT LOG_MSG_FMT, + connid, + op_id, + op_internal_id, + op_nested_count, + err, tag, nentries, + wtime, optime, etime, + notes_str, csn_str, session_str); } /* * If this is an unindexed search we should log it in the error log if @@ -2496,13 +2543,14 @@ log_entry(Operation *op, Slapi_Entry *e) if (log_format != LOG_FORMAT_DEFAULT) { slapd_log_pblock logpb = {0}; - + slapd_log_pblock_init(&logpb, log_format, NULL); logpb.conn_time = op->o_conn_starttime; logpb.conn_id = op->o_connid; logpb.op_id = op->o_opid; logpb.op_internal_id = -1; logpb.op_nested_count = -1; logpb.target_dn = slapi_entry_get_dn_const(e); + logpb.level = LDAP_DEBUG_STATS2; slapd_log_access_entry(&logpb); } else { slapi_log_access(LDAP_DEBUG_STATS2, "conn=%" PRIu64 " op=%d ENTRY dn=\"%s\"\n", @@ -2520,7 +2568,8 @@ log_entry(Operation *op, Slapi_Entry *e) get_internal_conn_op(&connid, &op_id, &op_internal_id, &op_nested_count, &start_time); if (log_format != LOG_FORMAT_DEFAULT) { slapd_log_pblock logpb = {0}; - + slapd_log_pblock_init(&logpb, log_format, NULL); + logpb.level = LDAP_DEBUG_ARGS; logpb.conn_time = start_time; logpb.conn_id = connid; logpb.op_id = op_id; @@ -2554,7 +2603,8 @@ log_referral(Operation *op) if (!internal_op) { if (log_format != LOG_FORMAT_DEFAULT) { slapd_log_pblock logpb = {0}; - + slapd_log_pblock_init(&logpb, log_format, NULL); + logpb.level = LDAP_DEBUG_STATS2; logpb.conn_time = op->o_conn_starttime; logpb.conn_id = op->o_connid; logpb.op_id = op->o_opid; @@ -2576,12 +2626,13 @@ log_referral(Operation *op) if (log_format != LOG_FORMAT_DEFAULT) { slapd_log_pblock logpb = {0}; - + slapd_log_pblock_init(&logpb, log_format, NULL); logpb.conn_time = start_time; logpb.conn_id = connid; logpb.op_id = op_id; logpb.op_internal_id = op_internal_id; logpb.op_nested_count = op_nested_count; + logpb.level = LDAP_DEBUG_ARGS; slapd_log_access_referral(&logpb); } else { slapi_log_access(LDAP_DEBUG_ARGS, diff --git a/ldap/servers/slapd/slap.h b/ldap/servers/slapd/slap.h index 4f44060968..98993a4050 100644 --- a/ldap/servers/slapd/slap.h +++ b/ldap/servers/slapd/slap.h @@ -329,6 +329,7 @@ typedef void (*VFPV)(); /* takes undefined arguments */ #define SLAPD_INIT_AUDITFAILLOG_ROTATIONUNIT "week" #define SLAPD_INIT_LOG_EXPTIMEUNIT "month" #define SLAPD_INIT_LOG_TIME_FORMAT "%FT%TZ" +#define SLAPD_INIT_ACCESS_LOG_TIME_FORMAT "%FT%T" #define SLAPD_INIT_LOG_FORMAT "default" #define LOG_FORMAT_DEFAULT 1 #define LOG_FORMAT_JSON 0 diff --git a/ldap/servers/slapd/slapi-private.h b/ldap/servers/slapd/slapi-private.h index bcf18f0643..ccca06702f 100644 --- a/ldap/servers/slapd/slapi-private.h +++ b/ldap/servers/slapd/slapi-private.h @@ -1261,6 +1261,7 @@ char get_sep(char *path); int mkdir_p(char *dir, unsigned int mode); const char *ldif_getline_ro( const char **next); void dup_ldif_line(struct berval *copy, const char *line, const char *endline); +const char *get_oid_name(const char *oid); /* slapi-memberof.c */ int slapi_memberof(Slapi_MemberOfConfig *config, Slapi_DN *member_sdn, Slapi_MemberOfResult *result); @@ -1528,6 +1529,9 @@ void slapi_log_backtrace(int loglevel); typedef struct slapd_log_pblock { int32_t log_format; Slapi_PBlock *pb; + struct logging_opts *loginfo; + struct timespec curr_time; + uint32_t level; /* log level */ /* Connection */ time_t conn_time; uint64_t conn_id; @@ -1541,7 +1545,7 @@ typedef struct slapd_log_pblock { char *haproxy_ip; char *haproxy_destip; PRBool using_tls; - PRBool hapoxied; + PRBool haproxied; const char *bind_dn; /* Close connection */ const char *close_error; @@ -1574,10 +1578,12 @@ typedef struct slapd_log_pblock { char *filter; char **attrs; PRBool psearch; + char *sort_str; /* Stat */ const char *stat_attr; const char *stat_key; const char *stat_value; + const char *stat_etime; int32_t stat_count; /* * VLV request: @@ -1603,14 +1609,16 @@ typedef struct slapd_log_pblock { char *etime; char *sid; uint32_t notes; + uint32_t tag; CSN *csn; int32_t pr_idx; int32_t pr_cookie; /* Misc */ const char *oid; const char *msg; + const char *name; LDAPControl **request_controls; - LDAPControl **result_controls; + LDAPControl **response_controls; } slapd_log_pblock; int32_t slapd_log_access_abandon(slapd_log_pblock *logpb); @@ -1634,6 +1642,7 @@ int32_t slapd_log_access_vlv(slapd_log_pblock *logpb); int32_t slapd_log_access_entry(slapd_log_pblock *logpb); int32_t slapd_log_access_referral(slapd_log_pblock *logpb); int32_t slapd_log_access_extop(slapd_log_pblock *logpb); +int32_t slapd_log_access_sort(slapd_log_pblock *logpb); #ifdef __cplusplus } diff --git a/ldap/servers/slapd/time.c b/ldap/servers/slapd/time.c index 5bd9279dbe..7bf6e2eeea 100644 --- a/ldap/servers/slapd/time.c +++ b/ldap/servers/slapd/time.c @@ -252,6 +252,58 @@ format_localTime_hr_log(time_t t, long nsec, int initsize __attribute__((unused) return 0; } +/* + * format_localTime_hr_json_log will take a time value, and prepare it for + * json log printing. + * + * \param struct timespec ts - the time to convert + * \param char *buf - The destitation string + * \param int *bufsize - The size of the resulting buffer + * \param char *format - custom strftime format to use + * + * \return int success - 0 on correct format, >= 1 on error. + */ +int +format_localTime_hr_json_log(struct timespec *ts, char *buf, int *bufsize, char *format) +{ + int64_t nsec = ts->tv_nsec; + time_t t = ts->tv_sec; + int64_t tz; + struct tm *tmsp, tms = {0}; + char tbuf[*bufsize]; + char sign; + + /* make sure our buffer will be big enough. Need at least 39 */ + if (*bufsize < 39) { + /* Should this set the buffer to be something? */ + return 1; + } + (void)localtime_r(&t, &tms); + tmsp = &tms; + +#ifdef BSD_TIME + tz = tmsp->tm_gmtoff; +#else /* BSD_TIME */ + tz = -timezone; + if (tmsp->tm_isdst) { + tz += 3600; + } +#endif /* BSD_TIME */ + sign = (tz >= 0 ? '+' : '-'); + if (tz < 0) { + tz = -tz; + } + if (strftime(tbuf, (size_t)*bufsize, format, tmsp) == 0) { + return 1; + } + if (PR_snprintf(buf, *bufsize, "%s.%09ld %c%02d%02d", tbuf, nsec, sign, + (int)(tz / 3600), (int)(tz % 3600 / 60)) == (PRUint32)-1) { + return 1; + } + *bufsize = strlen(buf); + return 0; +} + void slapi_timespec_diff(struct timespec *a, struct timespec *b, struct timespec *diff) { diff --git a/ldap/servers/slapd/util.c b/ldap/servers/slapd/util.c index bf065261f1..565f5ff103 100644 --- a/ldap/servers/slapd/util.c +++ b/ldap/servers/slapd/util.c @@ -1801,3 +1801,146 @@ void dup_ldif_line(struct berval *copy, const char *line, const char *endline) buf[pos] = 0; copy->bv_len = copylen; } + +/* Helper oid function for getting an OID name */ +struct oid_map { + char *oid; + char *name; +}; + +struct oid_map oidmap[] = { + {"2.16.840.1.113730.3.4.2", "LDAP_CONTROL_MANAGEDSAIT"}, + {"2.16.840.1.113730.3.4.18", "LDAP_CONTROL_PROXIEDAUTH"}, + {"1.3.6.1.4.1.4203.1.10.1", "LDAP_CONTROL_SUBENTRIES"}, + {"1.2.826.0.1.3344810.2.3", "LDAP_CONTROL_VALUESRETURNFILTER"}, + {"1.3.6.1.1.12", "LDAP_CONTROL_ASSERT"}, + {"1.3.6.1.1.13.1", "LDAP_CONTROL_PRE_READ_ENTRY"}, + {"1.3.6.1.1.13.2", "LDAP_CONTROL_POST_READ_ENTRY"}, + {"1.2.840.113556.1.4.473", "LDAP_CONTROL_SORTREQUEST"}, + {"1.2.840.113556.1.4.474", "LDAP_CONTROL_SORTRESPONSE"}, + {"1.2.840.113556.1.4.319", "LDAP_CONTROL_PAGEDRESULTS"}, + {"2.16.840.1.113730.3.4.16", "LDAP_CONTROL_AUTH_REQUEST"}, + {"2.16.840.1.113730.3.4.15", "LDAP_CONTROL_AUTH_RESPONSE"}, + {"1.3.6.1.4.1.4203.1.9.1", "LDAP_SYNC_OID"}, + {"1.3.6.1.1.22", "LDAP_CONTROL_DONTUSECOPY"}, + {"1.3.6.1.4.1.42.2.27.8.5.1", "LDAP_CONTROL_PASSWORDPOLICYRESPONSE"}, + {"1.3.6.1.4.1.4203.666.5.2", "LDAP_CONTROL_NOOP"}, + {"1.3.6.1.4.1.4203.666.5.11", "LDAP_CONTROL_NO_SUBORDINATES"}, + {"1.3.6.1.4.1.4203.666.5.12", "LDAP_CONTROL_RELAX"}, + {"1.3.6.1.4.1.4203.666.5.13", "LDAP_CONTROL_SLURP"}, + {"1.3.6.1.4.1.4203.666.5.14", "LDAP_CONTROL_VALSORT"}, + {"1.3.6.1.4.1.4203.666.5.16", "LDAP_CONTROL_X_DEREF"}, + {"1.3.6.1.4.1.4203.666.5.17", "LDAP_CONTROL_X_WHATFAILED"}, + {"1.3.6.1.4.1.4203.666.11.3", "LDAP_CONTROL_X_CHAINING_BEHAVIOR"}, + {"1.2.840.113556.1.4.619", "LDAP_CONTROL_X_LAZY_COMMIT"}, + {"1.2.840.113556.1.4.802", "LDAP_CONTROL_X_INCREMENTAL_VALUES"}, + {"1.2.840.113556.1.4.1339", "LDAP_CONTROL_X_DOMAIN_SCOPE"}, + {"1.2.840.113556.1.4.1413", "LDAP_CONTROL_X_PERMISSIVE_MODIFY"}, + {"1.2.840.113556.1.4.1340", "LDAP_CONTROL_X_SEARCH_OPTIONS"}, + {"1.2.840.113556.1.4.805", "LDAP_CONTROL_X_TREE_DELETE"}, + {"1.2.840.113556.1.4.528", "LDAP_CONTROL_X_SERVER_NOTIFICATION"}, + {"1.2.840.113556.1.4.529", "LDAP_CONTROL_X_EXTENDED_DN"}, + {"1.2.840.113556.1.4.417", "LDAP_CONTROL_X_SHOW_DELETED"}, + {"1.2.840.113556.1.4.841", "LDAP_CONTROL_X_DIRSYNC"}, + {"1.3.6.1.4.1.21008.108.63.1", "LDAP_CONTROL_X_SESSION_TRACKING"}, + {"2.16.840.1.113719.1.27.101.1", "LDAP_CONTROL_DUPENT_REQUEST"}, + {"2.16.840.1.113719.1.27.101.2", "LDAP_CONTROL_DUPENT_RESPONSE"}, + {"2.16.840.1.113719.1.27.101.3", "LDAP_CONTROL_DUPENT_ENTRY"}, + {"2.16.840.1.113730.3.4.3", "LDAP_CONTROL_PERSISTENTSEARCH"}, + {"2.16.840.1.113730.3.4.7", "LDAP_CONTROL_ENTRYCHANGE"}, + {"2.16.840.1.113730.3.4.9", "LDAP_CONTROL_VLVREQUEST"}, + {"2.16.840.1.113730.3.4.10", "LDAP_CONTROL_VLVRESPONSE"}, + {"1.3.6.1.4.1.42.2.27.9.5.8", "LDAP_CONTROL_X_ACCOUNT_USABILITY"}, + {"2.16.840.1.113730.3.4.4", "LDAP_CONTROL_PWEXPIRED"}, + {"2.16.840.1.113730.3.4.5", "LDAP_CONTROL_PWEXPIRING"}, + {"1.3.6.1.4.1.42.2.27.8.5.1", "LDAP_CONTROL_PASSWORDPOLICY"}, + {"2.16.840.1.113730.3.4.12", "LDAP_CONTROL_PROXYAUTH"}, + {"2.16.840.1.113730.3.4.17", "LDAP_CONTROL_REAL_ATTRS_ONLY"}, + {"2.16.840.1.113730.3.4.19", "LDAP_CONTROL_VIRT_ATTRS_ONLY"}, + {"1.3.6.1.4.1.42.2.27.9.5.2", "LDAP_CONTROL_GET_EFFECTIVE_RIGHTS"}, + {"1.3.6.1.4.1.1466.20037", "START_TLS_OID"}, + {"2.16.840.1.113730.3.5.7", "EXTOP_BULK_IMPORT_START_OID"}, + {"2.16.840.1.113730.3.5.8", "EXTOP_BULK_IMPORT_DONE_OID"}, + {"1.3.6.1.4.1.4203.1.11.1", "EXTOP_PASSWD_OID"}, + {"2.16.840.1.113730.3.5.14", "EXTOP_LDAPSSOTOKEN_REQUEST_OID"}, + {"2.16.840.1.113730.3.5.15", "EXTOP_LDAPSSOTOKEN_RESPONSE_OID"}, + {"2.16.840.1.113730.3.5.16", "EXTOP_LDAPSSOTOKEN_REVOKE_OID"}, + {"2.5.13.1", "DNMATCH_OID"}, + {"2.5.13.2", "CASEIGNOREMATCH_OID"}, + {"2.5.13.14", "INTEGERMATCH_OID"}, + {"2.5.13.15", "INTEGERORDERINGMATCH_OID"}, + {"2.5.13.29", "INTFIRSTCOMPMATCH_OID"}, + {"2.5.13.30", "OIDFIRSTCOMPMATCH_OID"}, + {"1.2.840.113556.1.4.1941", "LDAP_MATCHING_RULE_IN_CHAIN_OID"}, + {"1.3.6.1.4.1.1466.115.121.1.5", "BINARY_SYNTAX_OID"}, + {"1.3.6.1.4.1.1466.115.121.1.6", "BITSTRING_SYNTAX_OID"}, + {"1.3.6.1.4.1.1466.115.121.1.7", "BOOLEAN_SYNTAX_OID"}, + {"1.3.6.1.4.1.1466.115.121.1.11", "COUNTRYSTRING_SYNTAX_OID"}, + {"1.3.6.1.4.1.1466.115.121.1.12", "DN_SYNTAX_OID"}, + {"1.3.6.1.4.1.1466.115.121.1.14", "DELIVERYMETHOD_SYNTAX_OID"}, + {"1.3.6.1.4.1.1466.115.121.1.15", "DIRSTRING_SYNTAX_OID"}, + {"1.3.6.1.4.1.1466.115.121.1.21", "ENHANCEDGUIDE_SYNTAX_OID"}, + {"1.3.6.1.4.1.1466.115.121.1.22", "FACSIMILE_SYNTAX_OID"}, + {"1.3.6.1.4.1.1466.115.121.1.23", "FAX_SYNTAX_OID"}, + {"1.3.6.1.4.1.1466.115.121.1.24", "GENERALIZEDTIME_SYNTAX_OID"}, + {"1.3.6.1.4.1.1466.115.121.1.25", "GUIDE_SYNTAX_OID"}, + {"1.3.6.1.4.1.1466.115.121.1.26", "IA5STRING_SYNTAX_OID"}, + {"1.3.6.1.4.1.1466.115.121.1.27", "INTEGER_SYNTAX_OID"}, + {"1.3.6.1.4.1.1466.115.121.1.28", "JPEG_SYNTAX_OID"}, + {"1.3.6.1.4.1.1466.115.121.1.34", "NAMEANDOPTIONALUID_SYNTAX_OID"}, + {"1.3.6.1.4.1.1466.115.121.1.36", "NUMERICSTRING_SYNTAX_OID"}, + {"1.3.6.1.4.1.1466.115.121.1.38", "OID_SYNTAX_OID"}, + {"1.3.6.1.4.1.1466.115.121.1.40", "OCTETSTRING_SYNTAX_OID"}, + {"1.3.6.1.4.1.1466.115.121.1.41", "POSTALADDRESS_SYNTAX_OID"}, + {"1.3.6.1.4.1.1466.115.121.1.44", "PRINTABLESTRING_SYNTAX_OID"}, + {"1.3.6.1.4.1.1466.115.121.1.50", "TELEPHONE_SYNTAX_OID"}, + {"1.3.6.1.4.1.1466.115.121.1.51", "TELETEXTERMID_SYNTAX_OID"}, + {"1.3.6.1.4.1.1466.115.121.1.52", "TELEXNUMBER_SYNTAX_OID"}, + {"2.16.840.1.113730.3.7.1", "SPACE_INSENSITIVE_STRING_SYNTAX_OID"}, + {"2.16.840.1.113730.3.4.14", "MTN_CONTROL_USE_ONE_BACKEND_OID"}, + {"2.16.840.1.113730.3.4.20", "MTN_CONTROL_USE_ONE_BACKEND_EXT_OID"}, + {"2.16.840.1.113730.3.1.2110", "PSEUDO_ATTR_UNHASHEDUSERPASSWORD_OID"}, + {"2.5.13.8", "NUMERICSTRINGMATCH_OID"}, + {"2.5.13.9", "NUMERICSTRINGORDERINGMATCH_OID"}, + {"2.5.13.10", "NUMERICSTRINGSUBSTRINGSMATCH_OID"}, + {"1.3.6.1.4.1.1466.115.121.1.8", "CERTIFICATE_SYNTAX_OID"}, + {"1.3.6.1.4.1.1466.115.121.1.9", "CERTIFICATELIST_SYNTAX_OID"}, + {"1.3.6.1.4.1.1466.115.121.1.10", "CERTIFICATEPAIR_SYNTAX_OID"}, + {"1.3.6.1.4.1.1466.115.121.1.49", "SUPPORTEDALGORITHM_SYNTAX_OID"}, + {"1.2.840.113556.1.4.841", "REPL_DIRSYNC_CONTROL_OID"}, + {"1.2.840.113556.1.4.417", "REPL_RETURN_DELETED_OBJS_CONTROL_OID"}, + {"1.2.840.113556.1.4.1670", "REPL_WIN2K3_AD_OID"}, + {"2.16.840.1.113730.3.5.3", "REPL_START_NSDS50_REPLICATION_REQUEST_OID"}, + {"2.16.840.1.113730.3.5.5", "REPL_END_NSDS50_REPLICATION_REQUEST_OID"}, + {"2.16.840.1.113730.3.5.6", "REPL_NSDS50_REPLICATION_ENTRY_REQUEST_OID"}, + {"2.16.840.1.113730.3.5.4", "REPL_NSDS50_REPLICATION_RESPONSE_OID"}, + {"2.16.840.1.113730.3.4.13", "REPL_NSDS50_UPDATE_INFO_CONTROL_OID"}, + {"2.16.840.1.113730.3.6.1", "REPL_NSDS50_INCREMENTAL_PROTOCOL_OID"}, + {"2.16.840.1.113730.3.6.2", "REPL_NSDS50_TOTAL_PROTOCOL_OID"}, + {"2.16.840.1.113730.3.6.4", "REPL_NSDS71_INCREMENTAL_PROTOCOL_OID"}, + {"2.16.840.1.113730.3.6.3", "REPL_NSDS71_TOTAL_PROTOCOL_OID"}, + {"2.16.840.1.113730.3.5.9", "REPL_NSDS71_REPLICATION_ENTRY_REQUEST_OID"}, + {"2.16.840.1.113730.3.5.12", "REPL_START_NSDS90_REPLICATION_REQUEST_OID"}, + {"2.16.840.1.113730.3.5.13", "REPL_NSDS90_REPLICATION_RESPONSE_OID"}, + {"2.16.840.1.113730.3.6.5", "REPL_CLEANRUV_OID"}, + {"2.16.840.1.113730.3.6.6", "REPL_ABORT_CLEANRUV_OID"}, + {"2.16.840.1.113730.3.6.7", "REPL_CLEANRUV_GET_MAXCSN_OID"}, + {"2.16.840.1.113730.3.6.8", "REPL_CLEANRUV_CHECK_STATUS_OID"}, + {"2.16.840.1.113730.3.6.9", "REPL_ABORT_SESSION_OID"}, + {NULL, NULL}, +}; + +const char * +get_oid_name(const char *oid) +{ + if (oid == NULL) { + return NULL; + } + + for (size_t i = 0; oidmap[i].oid != NULL; i++) { + if (strcmp(oid, oidmap[i].oid) == 0) { + return oidmap[i].name; + } + } + return "Unknown"; +} diff --git a/src/lib389/lib389/dirsrv_log.py b/src/lib389/lib389/dirsrv_log.py index bae44af1c9..bbd2f22e9b 100644 --- a/src/lib389/lib389/dirsrv_log.py +++ b/src/lib389/lib389/dirsrv_log.py @@ -444,6 +444,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['gm_time'] return action