From: Aki Tuomi Date: Mon, 3 Dec 2018 08:48:41 +0000 (+0200) Subject: auth: Use event logging for subsys db X-Git-Tag: 2.3.9~767 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=4a0fdfda6846b0b195b2a08a7d50ccea3a7bb8a2;p=thirdparty%2Fdovecot%2Fcore.git auth: Use event logging for subsys db Done with automated change sed -i -e 's/auth_request_log_\(.*\)(\(.*\), AUTH_SUBSYS_DB,/e_\1(\2->authdb_event,/' *.c Followed by coccinelle @@ expression E; @@ -E->authdb_event +authdb_event(E) and some manual cleanup Whitespace fixing done with custom script --- diff --git a/src/auth/auth-request.c b/src/auth/auth-request.c index 1c43a8a42f..0a926542cf 100644 --- a/src/auth/auth-request.c +++ b/src/auth/auth-request.c @@ -101,6 +101,7 @@ static void auth_request_post_alloc_init(struct auth_request *request, struct ev request->extra_fields = auth_fields_init(request->pool); request->event = event_create(parent_event); request->mech_event = event_create(request->event); + p_array_init(&request->authdb_event, request->pool, 2); event_set_log_prefix_callback(request->mech_event, FALSE, get_log_prefix_mech, request); event_set_forced_debug(request->event, request->set->debug); @@ -734,9 +735,9 @@ static void auth_request_master_lookup_finish(struct auth_request *request) return; /* master login successful. update user and master_user variables. */ - auth_request_log_info(request, AUTH_SUBSYS_DB, - "Master user logging in as %s", - request->requested_login_user); + e_info(authdb_event(request), + "Master user logging in as %s", + request->requested_login_user); request->master_user = request->user; request->user = request->requested_login_user; @@ -967,8 +968,8 @@ auth_request_handle_passdb_callback(enum passdb_result *result, lookup returned that user doesn't exist in it. internal errors are fatal here. */ if (*result != PASSDB_RESULT_INTERNAL_FAILURE) { - auth_request_log_info(request, AUTH_SUBSYS_DB, - "User found from deny passdb"); + e_info(authdb_event(request), + "User found from deny passdb"); *result = PASSDB_RESULT_USER_DISABLED; } return TRUE; @@ -1000,7 +1001,7 @@ auth_request_handle_passdb_callback(enum passdb_result *result, result_rule = request->passdb->result_internalfail; break; case PASSDB_RESULT_NEXT: - auth_request_log_debug(request, AUTH_SUBSYS_DB, + e_debug(authdb_event(request), "Not performing authentication (noauthenticate set)"); result_rule = AUTH_DB_RULE_CONTINUE; break; @@ -1097,7 +1098,7 @@ auth_request_handle_passdb_callback(enum passdb_result *result, return FALSE; } else if (*result == PASSDB_RESULT_NEXT) { /* admin forgot to put proper passdb last */ - auth_request_log_error(request, AUTH_SUBSYS_DB, + e_error(authdb_event(request), "Last passdb had noauthenticate field, cannot authenticate user"); *result = PASSDB_RESULT_INTERNAL_FAILURE; } else if (request->passdb_success) { @@ -1120,7 +1121,7 @@ auth_request_verify_plain_callback_finish(enum passdb_result result, if (passdb_template_export(request->passdb->override_fields_tmpl, request, &error) < 0) { - auth_request_log_error(request, AUTH_SUBSYS_DB, + e_error(authdb_event(request), "Failed to expand override_fields: %s", error); result = PASSDB_RESULT_INTERNAL_FAILURE; } @@ -1161,8 +1162,8 @@ void auth_request_verify_plain_callback(enum passdb_result result, if (passdb_cache_verify_plain(request, cache_key, request->mech_password, &result, TRUE)) { - auth_request_log_info(request, AUTH_SUBSYS_DB, - "Falling back to expired data from cache"); + e_info(authdb_event(request), + "Falling back to expired data from cache"); return; } } @@ -1305,8 +1306,8 @@ void auth_request_verify_plain_continue(struct auth_request *request, } if (password_has_illegal_chars(password)) { - auth_request_log_info(request, AUTH_SUBSYS_DB, - "Attempted login with password having illegal chars"); + e_info(authdb_event(request), + "Attempted login with password having illegal chars"); callback(PASSDB_RESULT_USER_UNKNOWN, request); return; } @@ -1347,7 +1348,7 @@ void auth_request_verify_plain_continue(struct auth_request *request, passdb_blocking_verify_plain(request); } else if (passdb_template_export(passdb->default_fields_tmpl, request, &error) < 0) { - auth_request_log_error(request, AUTH_SUBSYS_DB, + e_error(authdb_event(request), "Failed to expand default_fields: %s", error); auth_request_verify_plain_callback( PASSDB_RESULT_INTERNAL_FAILURE, request); @@ -1367,7 +1368,7 @@ auth_request_lookup_credentials_finish(enum passdb_result result, if (passdb_template_export(request->passdb->override_fields_tmpl, request, &error) < 0) { - auth_request_log_error(request, AUTH_SUBSYS_DB, + e_error(authdb_event(request), "Failed to expand override_fields: %s", error); result = PASSDB_RESULT_INTERNAL_FAILURE; } @@ -1398,7 +1399,7 @@ auth_request_lookup_credentials_finish(enum passdb_result result, } if (request->set->debug_passwords && result == PASSDB_RESULT_OK) { - auth_request_log_debug(request, AUTH_SUBSYS_DB, + e_debug(authdb_event(request), "Credentials: %s", binary_to_hex(credentials, size)); } @@ -1442,8 +1443,8 @@ void auth_request_lookup_credentials_callback(enum passdb_result result, if (passdb_cache_lookup_credentials(request, cache_key, &cache_cred, &cache_scheme, &result, TRUE)) { - auth_request_log_info(request, AUTH_SUBSYS_DB, - "Falling back to expired data from cache"); + e_info(authdb_event(request), + "Falling back to expired data from cache"); passdb_handle_credentials( result, cache_cred, cache_scheme, auth_request_lookup_credentials_finish, @@ -1525,7 +1526,7 @@ void auth_request_lookup_credentials_policy_continue(struct auth_request *reques if (passdb->passdb->iface.lookup_credentials == NULL) { /* this passdb doesn't support credentials */ - auth_request_log_debug(request, AUTH_SUBSYS_DB, + e_debug(authdb_event(request), "passdb doesn't support credential lookups"); auth_request_lookup_credentials_callback( PASSDB_RESULT_SCHEME_NOT_AVAILABLE, @@ -1534,7 +1535,7 @@ void auth_request_lookup_credentials_policy_continue(struct auth_request *reques passdb_blocking_lookup_credentials(request); } else if (passdb_template_export(passdb->default_fields_tmpl, request, &error) < 0) { - auth_request_log_error(request, AUTH_SUBSYS_DB, + e_error(authdb_event(request), "Failed to expand default_fields: %s", error); auth_request_lookup_credentials_callback( PASSDB_RESULT_INTERNAL_FAILURE, @@ -1620,14 +1621,14 @@ static bool auth_request_lookup_user_cache(struct auth_request *request, &expired, &neg_expired); if (value == NULL || (expired && !use_expired)) { stats->auth_cache_miss_count++; - auth_request_log_debug(request, AUTH_SUBSYS_DB, - value == NULL ? "userdb cache miss" : - "userdb cache expired"); + e_debug(authdb_event(request), + value == NULL ? "userdb cache miss" : + "userdb cache expired"); return FALSE; } stats->auth_cache_hit_count++; - auth_request_log_debug(request, AUTH_SUBSYS_DB, - "userdb cache hit: %s", value); + e_debug(authdb_event(request), + "userdb cache hit: %s", value); if (*value == '\0') { /* negative cache entry */ @@ -1710,7 +1711,7 @@ void auth_request_userdb_callback(enum userdb_result result, fields */ if (userdb_template_export(userdb->override_fields_tmpl, request, &error) < 0) { - auth_request_log_error(request, AUTH_SUBSYS_DB, + e_error(authdb_event(request), "Failed to expand override_fields: %s", error); request->private_callback.userdb( USERDB_RESULT_INTERNAL_FAILURE, request); @@ -1733,7 +1734,7 @@ void auth_request_userdb_callback(enum userdb_result result, if (request->userdb_success) { if (userdb_template_export(userdb->override_fields_tmpl, request, &error) < 0) { - auth_request_log_error(request, AUTH_SUBSYS_DB, + e_error(authdb_event(request), "Failed to expand override_fields: %s", error); result = USERDB_RESULT_INTERNAL_FAILURE; } else { @@ -1748,7 +1749,7 @@ void auth_request_userdb_callback(enum userdb_result result, /* this was an actual login attempt, the user should have been found. */ if (auth_request_get_auth(request)->userdbs->next == NULL) { - auth_request_log_error(request, AUTH_SUBSYS_DB, + e_error(authdb_event(request), "user not found from userdb"); } else { auth_request_log_error(request, AUTH_SUBSYS_MECH, @@ -1772,8 +1773,8 @@ void auth_request_userdb_callback(enum userdb_result result, if (auth_request_lookup_user_cache(request, cache_key, &result, TRUE)) { - auth_request_log_info(request, AUTH_SUBSYS_DB, - "Falling back to expired data from cache"); + e_info(authdb_event(request), + "Falling back to expired data from cache"); } } @@ -1798,7 +1799,7 @@ void auth_request_lookup_user(struct auth_request *request, unwanted, ":protected" can be used). */ if (userdb_template_export(userdb->default_fields_tmpl, request, &error) < 0) { - auth_request_log_error(request, AUTH_SUBSYS_DB, + e_error(authdb_event(request), "Failed to expand default_fields: %s", error); auth_request_userdb_callback( USERDB_RESULT_INTERNAL_FAILURE, request); @@ -1968,9 +1969,10 @@ bool auth_request_set_login_username(struct auth_request *request, if (request->requested_login_user == NULL) return FALSE; - auth_request_log_debug(request, AUTH_SUBSYS_DB, - "Master user lookup for login: %s", - request->requested_login_user); + e_debug(request->event, + "%sMaster user lookup for login: %s", + get_log_prefix_db(request), + request->requested_login_user); return TRUE; } @@ -1985,7 +1987,7 @@ auth_request_validate_networks(struct auth_request *request, bool found = FALSE; for (net = t_strsplit_spaces(networks, ", "); *net != NULL; net++) { - auth_request_log_debug(request, AUTH_SUBSYS_DB, + e_debug(authdb_event(request), "%s: Matching for network %s", name, *net); if (strcmp(*net, "local") == 0) { @@ -1994,8 +1996,8 @@ auth_request_validate_networks(struct auth_request *request, break; } } else if (net_parse_range(*net, &net_ip, &bits) < 0) { - auth_request_log_info(request, AUTH_SUBSYS_DB, - "%s: Invalid network '%s'", name, *net); + e_info(authdb_event(request), + "%s: Invalid network '%s'", name, *net); } else if (remote_ip->family != 0 && net_is_in_network(remote_ip, &net_ip, bits)) { found = TRUE; @@ -2006,12 +2008,12 @@ auth_request_validate_networks(struct auth_request *request, if (found) ; else if (remote_ip->family == 0) { - auth_request_log_info(request, AUTH_SUBSYS_DB, - "%s check failed: Remote IP not known and 'local' missing", name); + e_info(authdb_event(request), + "%s check failed: Remote IP not known and 'local' missing", name); } else { - auth_request_log_info(request, AUTH_SUBSYS_DB, - "%s check failed: IP %s not in allowed networks", - name, net_ip2addr(remote_ip)); + e_info(authdb_event(request), + "%s check failed: IP %s not in allowed networks", + name, net_ip2addr(remote_ip)); } if (!found) request->failed = TRUE; @@ -2022,7 +2024,7 @@ auth_request_set_password(struct auth_request *request, const char *value, const char *default_scheme, bool noscheme) { if (request->passdb_password != NULL) { - auth_request_log_error(request, AUTH_SUBSYS_DB, + e_error(authdb_event(request), "Multiple password values not supported"); return; } @@ -2084,16 +2086,16 @@ auth_request_try_update_username(struct auth_request *request, if (new_value == NULL) return FALSE; if (new_value[0] == '\0') { - auth_request_log_error(request, AUTH_SUBSYS_DB, + e_error(authdb_event(request), "username attempted to be changed to empty"); request->failed = TRUE; return TRUE; } if (strcmp(request->user, new_value) != 0) { - auth_request_log_debug(request, AUTH_SUBSYS_DB, - "username changed %s -> %s", - request->user, new_value); + e_debug(authdb_event(request), + "username changed %s -> %s", + request->user, new_value); request->user = p_strdup(request->pool, new_value); request->user_changed_by_lookup = TRUE; } @@ -2163,7 +2165,7 @@ void auth_request_set_field(struct auth_request *request, if (p != NULL) { value = t_strdup_until(value, p++); if (str_to_uint(p, &extra_secs) < 0) { - auth_request_log_error(request, AUTH_SUBSYS_DB, + e_error(authdb_event(request), "Invalid delay_until randomness number '%s'", p); request->failed = TRUE; } else { @@ -2171,13 +2173,13 @@ void auth_request_set_field(struct auth_request *request, } } if (str_to_time(value, ×tamp) < 0) { - auth_request_log_error(request, AUTH_SUBSYS_DB, + e_error(authdb_event(request), "Invalid delay_until timestamp '%s'", value); request->failed = TRUE; } else if (timestamp <= ioloop_time) { /* no more delays */ } else if (timestamp - ioloop_time > AUTH_REQUEST_MAX_DELAY_SECS) { - auth_request_log_error(request, AUTH_SUBSYS_DB, + e_error(authdb_event(request), "delay_until timestamp %s is too much in the future, failing", value); request->failed = TRUE; } else { @@ -2216,7 +2218,7 @@ void auth_request_set_field(struct auth_request *request, !auth_fields_exists(request->extra_fields, "noauthenticate")) { (void)password_get_scheme(&password); if (*password != '\0') { - auth_request_log_error(request, AUTH_SUBSYS_DB, + e_error(authdb_event(request), "nopassword set but password is " "non-empty"); return; @@ -2286,7 +2288,7 @@ void auth_request_init_userdb_reply(struct auth_request *request) request->userdb_reply = auth_fields_init(request->pool); if (userdb_template_export(request->userdb->default_fields_tmpl, request, &error) < 0) { - auth_request_log_error(request, AUTH_SUBSYS_DB, + e_error(authdb_event(request), "Failed to expand default_fields: %s", error); } } @@ -2301,12 +2303,12 @@ static void auth_request_set_uidgid_file(struct auth_request *request, path = t_str_new(256); if (auth_request_var_expand(path, path_template, request, NULL, &error) <= 0) { - auth_request_log_error(request, AUTH_SUBSYS_DB, + e_error(authdb_event(request), "Failed to expand uidgid_file=%s: %s", path_template, error); request->userdb_lookup_tempfailed = TRUE; } else if (stat(str_c(path), &st) < 0) { - auth_request_log_error(request, AUTH_SUBSYS_DB, - "stat(%s) failed: %m", str_c(path)); + e_error(authdb_event(request), + "stat(%s) failed: %m", str_c(path)); request->userdb_lookup_tempfailed = TRUE; } else { auth_fields_add(request->userdb_reply, @@ -2423,9 +2425,9 @@ void auth_request_set_userdb_field_values(struct auth_request *request, } else { /* add only one */ if (values[1] != NULL) { - auth_request_log_warning(request, AUTH_SUBSYS_DB, - "Multiple values found for '%s', " - "using value '%s'", name, *values); + e_warning(authdb_event(request), + "Multiple values found for '%s', " + "using value '%s'", name, *values); } auth_request_set_userdb_field(request, name, *values); } diff --git a/src/auth/db-checkpassword.c b/src/auth/db-checkpassword.c index 2fd4ed1630..a21aa043b9 100644 --- a/src/auth/db-checkpassword.c +++ b/src/auth/db-checkpassword.c @@ -130,15 +130,15 @@ checkpassword_request_finish_auth(struct chkpw_auth_request *request) case 1: /* (1 is additionally defined in vpopmail for "pop/smtp/webmail/ imap/access denied") */ - auth_request_log_info(request->request, AUTH_SUBSYS_DB, - "Login failed (status=%d)", - request->exit_status); + e_info(authdb_event(request->request), + "Login failed (status=%d)", + request->exit_status); checkpassword_finish(&request, DB_CHECKPASSWORD_STATUS_FAILURE); break; case 0: if (request->input_buf->used == 0) { - auth_request_log_error(request->request, AUTH_SUBSYS_DB, - "Received no input"); + e_error(authdb_event(request->request), + "Received no input"); checkpassword_internal_failure(&request); break; } @@ -146,7 +146,7 @@ checkpassword_request_finish_auth(struct chkpw_auth_request *request) break; case 2: /* checkpassword is called with wrong parameters? unlikely */ - auth_request_log_error(request->request, AUTH_SUBSYS_DB, + e_error(authdb_event(request->request), "Child %s exited with status 2 (tried to use " "userdb-only checkpassword program for passdb?)", dec2str(request->pid)); @@ -156,7 +156,7 @@ checkpassword_request_finish_auth(struct chkpw_auth_request *request) /* temporary problem, treat as internal error */ default: /* whatever error.. */ - auth_request_log_error(request->request, AUTH_SUBSYS_DB, + e_error(authdb_event(request->request), "Child %s exited with status %d", dec2str(request->pid), request->exit_status); checkpassword_internal_failure(&request); @@ -170,16 +170,16 @@ checkpassword_request_finish_lookup(struct chkpw_auth_request *request) switch (request->exit_status) { case 3: /* User does not exist. */ - auth_request_log_info(request->request, AUTH_SUBSYS_DB, - "User unknown"); + e_info(authdb_event(request->request), + "User unknown"); checkpassword_finish(&request, DB_CHECKPASSWORD_STATUS_FAILURE); break; case 2: /* This is intentionally not 0. checkpassword-reply exits with 2 on success when AUTHORIZED is set. */ if (request->input_buf->used == 0) { - auth_request_log_error(request->request, AUTH_SUBSYS_DB, - "Received no input"); + e_error(authdb_event(request->request), + "Received no input"); checkpassword_internal_failure(&request); break; } @@ -187,7 +187,7 @@ checkpassword_request_finish_lookup(struct chkpw_auth_request *request) break; default: /* whatever error... */ - auth_request_log_error(request->request, AUTH_SUBSYS_DB, + e_error(authdb_event(request->request), "Child %s exited with status %d", dec2str(request->pid), request->exit_status); checkpassword_internal_failure(&request); @@ -308,20 +308,20 @@ static void checkpassword_child_input(struct chkpw_auth_request *request) } if (ret < 0) { - auth_request_log_error(request->request, AUTH_SUBSYS_DB, - "read() failed: %m"); + e_error(authdb_event(request->request), + "read() failed: %m"); checkpassword_internal_failure(&request); } else if (memchr(str_data(request->input_buf), '\0', str_len(request->input_buf)) != NULL) { - auth_request_log_error(request->request, AUTH_SUBSYS_DB, - "NUL characters in checkpassword reply"); + e_error(authdb_event(request->request), + "NUL characters in checkpassword reply"); checkpassword_internal_failure(&request); } else if (strchr(str_c(request->input_buf), '\n') != NULL) { - auth_request_log_error(request->request, AUTH_SUBSYS_DB, - "LF characters in checkpassword reply"); + e_error(authdb_event(request->request), + "LF characters in checkpassword reply"); checkpassword_internal_failure(&request); } else { - auth_request_log_debug(request->request, AUTH_SUBSYS_DB, + e_debug(authdb_event(request->request), "Received input: %s", str_c(request->input_buf)); checkpassword_request_close(request); checkpassword_request_half_finish(request); @@ -359,11 +359,11 @@ static void checkpassword_child_output(struct chkpw_auth_request *request) size - request->output_pos); if (ret <= 0) { if (ret < 0) { - auth_request_log_error(request->request, AUTH_SUBSYS_DB, - "write() failed: %m"); + e_error(authdb_event(request->request), + "write() failed: %m"); } else { - auth_request_log_error(request->request, AUTH_SUBSYS_DB, - "write() returned 0"); + e_error(authdb_event(request->request), + "write() returned 0"); } checkpassword_internal_failure(&request); return; @@ -390,8 +390,8 @@ checkpassword_exec(struct db_checkpassword *db, struct auth_request *request, /* fd 3 is used to send the username+password for the script fd 4 is used to communicate with checkpassword-reply */ if (dup2(fd_out, 3) < 0 || dup2(fd_in, 4) < 0) { - auth_request_log_error(request, AUTH_SUBSYS_DB, - "dup2() failed: %m"); + e_error(authdb_event(request), + "dup2() failed: %m"); exit(111); } @@ -413,7 +413,7 @@ checkpassword_exec(struct db_checkpassword *db, struct auth_request *request, checkpassword_setup_env(request); cmd = checkpassword_get_cmd(request, db->checkpassword_path, db->checkpassword_reply_path); - auth_request_log_debug(request, AUTH_SUBSYS_DB, "execute: %s", cmd); + e_debug(authdb_event(request), "execute: %s", cmd); /* very simple argument splitting. */ args = t_strsplit(cmd, " "); @@ -432,21 +432,21 @@ static void sigchld_handler(const struct child_wait_status *status, request->exited = TRUE; if (WIFSIGNALED(status->status)) { - auth_request_log_error(request->request, AUTH_SUBSYS_DB, + e_error(authdb_event(request->request), "Child %s died with signal %d", dec2str(status->pid), WTERMSIG(status->status)); checkpassword_internal_failure(&request); } else if (WIFEXITED(status->status)) { request->exit_status = WEXITSTATUS(status->status); - auth_request_log_debug(request->request, AUTH_SUBSYS_DB, - "exit_status=%d", request->exit_status); + e_debug(authdb_event(request->request), + "exit_status=%d", request->exit_status); checkpassword_request_half_finish(request); } else { /* shouldn't happen */ - auth_request_log_debug(request->request, AUTH_SUBSYS_DB, - "Child %s exited with status=%d", - dec2str(status->pid), status->status); + e_debug(authdb_event(request->request), + "Child %s exited with status=%d", + dec2str(status->pid), status->status); checkpassword_internal_failure(&request); } } @@ -467,9 +467,9 @@ void db_checkpassword_call(struct db_checkpassword *db, if (auth_password != NULL) output_len += strlen(auth_password); if (output_len > CHECKPASSWORD_MAX_REQUEST_LEN) { - auth_request_log_info(request, AUTH_SUBSYS_DB, - "Username+password combination too long (%"PRIuSIZE_T" bytes)", - output_len); + e_info(authdb_event(request), + "Username+password combination too long (%"PRIuSIZE_T" bytes)", + output_len); callback(request, DB_CHECKPASSWORD_STATUS_FAILURE, NULL, request_callback); return; @@ -477,8 +477,8 @@ void db_checkpassword_call(struct db_checkpassword *db, fd_in[0] = -1; if (pipe(fd_in) < 0 || pipe(fd_out) < 0) { - auth_request_log_error(request, AUTH_SUBSYS_DB, - "pipe() failed: %m"); + e_error(authdb_event(request), + "pipe() failed: %m"); if (fd_in[0] != -1) { i_close_fd(&fd_in[0]); i_close_fd(&fd_in[1]); @@ -490,8 +490,8 @@ void db_checkpassword_call(struct db_checkpassword *db, pid = fork(); if (pid == -1) { - auth_request_log_error(request, AUTH_SUBSYS_DB, - "fork() failed: %m"); + e_error(authdb_event(request), + "fork() failed: %m"); i_close_fd(&fd_in[0]); i_close_fd(&fd_in[1]); i_close_fd(&fd_out[0]); @@ -511,12 +511,12 @@ void db_checkpassword_call(struct db_checkpassword *db, } if (close(fd_in[1]) < 0) { - auth_request_log_error(request, AUTH_SUBSYS_DB, - "close(fd_in[1]) failed: %m"); + e_error(authdb_event(request), + "close(fd_in[1]) failed: %m"); } if (close(fd_out[0]) < 0) { - auth_request_log_error(request, AUTH_SUBSYS_DB, - "close(fd_out[0]) failed: %m"); + e_error(authdb_event(request), + "close(fd_out[0]) failed: %m"); } auth_request_ref(request); diff --git a/src/auth/db-dict.c b/src/auth/db-dict.c index e336c2cdc8..502e2f3a86 100644 --- a/src/auth/db-dict.c +++ b/src/auth/db-dict.c @@ -417,15 +417,15 @@ static int db_dict_iter_lookup_key_values(struct db_dict_value_iter *iter) ret = dict_lookup(iter->conn->dict, iter->pool, str_c(path), &key->value, &error); if (ret > 0) { - auth_request_log_debug(iter->auth_request, AUTH_SUBSYS_DB, - "Lookup: %s = %s", str_c(path), - key->value); + e_debug(authdb_event(iter->auth_request), + "Lookup: %s = %s", str_c(path), + key->value); } else if (ret < 0) { - auth_request_log_error(iter->auth_request, AUTH_SUBSYS_DB, + e_error(authdb_event(iter->auth_request), "Failed to lookup key %s: %s", str_c(path), error); return -1; } else if (key->key->default_value != NULL) { - auth_request_log_debug(iter->auth_request, AUTH_SUBSYS_DB, + e_debug(authdb_event(iter->auth_request), "Lookup: %s not found, using default value %s", str_c(path), key->key->default_value); key->value = key->key->default_value; @@ -469,7 +469,7 @@ int db_dict_value_iter_init(struct dict_connection *conn, if (auth_request_var_expand_with_table(expanded_key, key->key, auth_request, iter->var_expand_table, NULL, &error) <= 0) { - auth_request_log_error(iter->auth_request, AUTH_SUBSYS_DB, + e_error(authdb_event(iter->auth_request), "Failed to expand key %s: %s", key->key, error); pool_unref(&pool); return -1; diff --git a/src/auth/db-ldap.c b/src/auth/db-ldap.c index 2935f0228e..7db536261e 100644 --- a/src/auth/db-ldap.c +++ b/src/auth/db-ldap.c @@ -313,9 +313,9 @@ static int db_ldap_request_bind(struct ldap_connection *conn, request->auth_request->mech_password, LDAP_AUTH_SIMPLE); if (request->msgid == -1) { - auth_request_log_error(request->auth_request, AUTH_SUBSYS_DB, - "ldap_bind(%s) failed: %s", - brequest->dn, ldap_get_error(conn)); + e_error(authdb_event(request->auth_request), + "ldap_bind(%s) failed: %s", + brequest->dn, ldap_get_error(conn)); if (ldap_handle_error(conn) < 0) { /* broken request, remove it */ return 0; @@ -340,9 +340,9 @@ static int db_ldap_request_search(struct ldap_connection *conn, srequest->base, conn->set.ldap_scope, srequest->filter, srequest->attributes, 0); if (request->msgid == -1) { - auth_request_log_error(request->auth_request, AUTH_SUBSYS_DB, - "ldap_search(%s) parsing failed: %s", - srequest->filter, ldap_get_error(conn)); + e_error(authdb_event(request->auth_request), + "ldap_search(%s) parsing failed: %s", + srequest->filter, ldap_get_error(conn)); if (ldap_handle_error(conn) < 0) { /* broken request, remove it */ return 0; @@ -440,7 +440,7 @@ db_ldap_check_hanging(struct ldap_connection *conn, struct ldap_request *request aqueue_idx(conn->request_queue, 0)); secs_diff = ioloop_time - (*first_requestp)->create_time; if (secs_diff > DB_LDAP_REQUEST_LOST_TIMEOUT_SECS) { - auth_request_log_error(request->auth_request, AUTH_SUBSYS_DB, + e_error(authdb_event(request->auth_request), "Connection appears to be hanging, reconnecting"); ldap_conn_reconnect(conn); } @@ -522,11 +522,11 @@ static void db_ldap_abort_requests(struct ldap_connection *conn, conn->pending_count--; } if (error) { - auth_request_log_error(request->auth_request, AUTH_SUBSYS_DB, - "%s", reason); + e_error(authdb_event(request->auth_request), + "%s", reason); } else { - auth_request_log_info(request->auth_request, AUTH_SUBSYS_DB, - "%s", reason); + e_info(authdb_event(request->auth_request), + "%s", reason); } request->callback(conn, request, NULL); max_count--; @@ -570,9 +570,9 @@ static int db_ldap_fields_get_dn(struct ldap_connection *conn, TRUE, TRUE); while (db_ldap_result_iterate_next(ldap_iter, &name, &values)) { if (values[1] != NULL) { - auth_request_log_warning(auth_request, AUTH_SUBSYS_DB, - "Multiple values found for '%s', " - "using value '%s'", name, values[0]); + e_warning(authdb_event(auth_request), + "Multiple values found for '%s', " + "using value '%s'", name, values[0]); } array_foreach_modifiable(&request->named_results, named_res) { if (strcmp(named_res->field->name, name) != 0) @@ -652,8 +652,7 @@ ldap_request_send_subquery(struct ldap_connection *conn, str_truncate(tmp_str, 0); if (var_expand_with_funcs(tmp_str, field->value, table, array_front(&var_funcs_table), &ctx, &error) <= 0) { - auth_request_log_error(auth_request, - AUTH_SUBSYS_DB, + e_error(authdb_event(auth_request), "Failed to expand subquery %s: %s", field->value, error); return -1; @@ -674,9 +673,9 @@ ldap_request_send_subquery(struct ldap_connection *conn, ldap_search(conn->ld, named_res->dn, LDAP_SCOPE_BASE, NULL, array_front_modifiable(&ctx.attr_names), 0); if (request->request.msgid == -1) { - auth_request_log_error(auth_request, AUTH_SUBSYS_DB, - "ldap_search(dn=%s) failed: %s", - named_res->dn, ldap_get_error(conn)); + e_error(authdb_event(auth_request), + "ldap_search(dn=%s) failed: %s", + named_res->dn, ldap_get_error(conn)); return -1; } return 0; @@ -789,14 +788,14 @@ db_ldap_handle_request_result(struct ldap_connection *conn, (struct ldap_request_search *)request; if (!array_is_created(&srequest->named_results)) { - auth_request_log_error(request->auth_request, AUTH_SUBSYS_DB, + e_error(authdb_event(request->auth_request), "ldap_search(base=%s filter=%s) failed: %s", srequest->base, srequest->filter, ldap_err2string(ret)); } else { named_res = array_idx(&srequest->named_results, srequest->name_idx); - auth_request_log_error(request->auth_request, AUTH_SUBSYS_DB, + e_error(authdb_event(request->auth_request), "ldap_search(base=%s) failed: %s", named_res->dn, ldap_err2string(ret)); } @@ -806,7 +805,7 @@ db_ldap_handle_request_result(struct ldap_connection *conn, /* expand any @results */ if (!final_result) { if (db_ldap_search_save_result(srequest, res) < 0) { - auth_request_log_error(request->auth_request, AUTH_SUBSYS_DB, + e_error(authdb_event(request->auth_request), "LDAP search returned multiple entries"); res = NULL; } else { @@ -1660,10 +1659,9 @@ db_ldap_field_expand(const char *data, void *context, return 1; } if (ldap_value->values[1] != NULL) { - auth_request_log_warning(ctx->ldap_request->auth_request, - AUTH_SUBSYS_DB, - "Multiple values found for '%s', using value '%s'", - field_name, ldap_value->values[0]); + e_warning(authdb_event(ctx->ldap_request->auth_request), + "Multiple values found for '%s', using value '%s'", + field_name, ldap_value->values[0]); } *value_r = ldap_value->values[0]; return 1; @@ -1732,11 +1730,10 @@ db_ldap_result_return_value(struct db_ldap_result_iterate_context *ctx, return values; } if (values[0] != NULL && values[1] != NULL) { - auth_request_log_warning(ctx->ldap_request->auth_request, - AUTH_SUBSYS_DB, - "Multiple values found for '%s', " - "using value '%s'", - field->name, values[0]); + e_warning(authdb_event(ctx->ldap_request->auth_request), + "Multiple values found for '%s', " + "using value '%s'", + field->name, values[0]); } /* do this lookup separately for each expansion, because: @@ -1747,10 +1744,9 @@ db_ldap_result_return_value(struct db_ldap_result_iterate_context *ctx, ctx->ldap_request->auth_request, values[0]); if (var_expand_with_funcs(ctx->var, field->value, var_table, ldap_var_funcs_table, ctx, &error) <= 0) { - auth_request_log_warning(ctx->ldap_request->auth_request, - AUTH_SUBSYS_DB, - "Failed to expand template %s: %s", - field->value, error); + e_warning(authdb_event(ctx->ldap_request->auth_request), + "Failed to expand template %s: %s", + field->value, error); } ctx->val_1_arr[0] = str_c(ctx->var); values = ctx->val_1_arr; @@ -1797,9 +1793,8 @@ bool db_ldap_result_iterate_next(struct db_ldap_result_iterate_context *ctx, ctx->ldap_request->auth_request, NULL); if (var_expand_with_funcs(ctx->var, field->name, tab, ldap_var_funcs_table, ctx, &error) <= 0) { - auth_request_log_warning(ctx->ldap_request->auth_request, - AUTH_SUBSYS_DB, - "Failed to expand %s: %s", field->name, error); + e_warning(authdb_event(ctx->ldap_request->auth_request), + "Failed to expand %s: %s", field->name, error); } *name_r = str_c(ctx->var) + pos; } @@ -1825,9 +1820,8 @@ db_ldap_result_finish_debug(struct db_ldap_result_iterate_context *ctx) orig_len = str_len(ctx->debug); if (orig_len == 0) { - auth_request_log_debug(ctx->ldap_request->auth_request, - AUTH_SUBSYS_DB, - "no fields returned by the server"); + e_debug(authdb_event(ctx->ldap_request->auth_request), + "no fields returned by the server"); return; } @@ -1848,8 +1842,8 @@ db_ldap_result_finish_debug(struct db_ldap_result_iterate_context *ctx) str_truncate(ctx->debug, str_len(ctx->debug)-1); str_append(ctx->debug, " unused"); } - auth_request_log_debug(ctx->ldap_request->auth_request, AUTH_SUBSYS_DB, - "result: %s", str_c(ctx->debug) + 1); + e_debug(authdb_event(ctx->ldap_request->auth_request), + "result: %s", str_c(ctx->debug) + 1); ctx->ldap_request->result_logged = TRUE; } diff --git a/src/auth/db-lua.c b/src/auth/db-lua.c index ee4cf48e36..c6cbcb0142 100644 --- a/src/auth/db-lua.c +++ b/src/auth/db-lua.c @@ -126,7 +126,7 @@ static int auth_request_lua_log_debug(lua_State *L) struct dlua_script *script = dlua_script_from_state(L); struct auth_request *request = auth_lua_check_auth_request(script, 1); const char *msg = luaL_checkstring(L, 2); - auth_request_log_debug(request, AUTH_SUBSYS_DB, "db-lua: %s", msg); + e_debug(authdb_event(request), "db-lua: %s", msg); } return 0; } @@ -136,7 +136,7 @@ static int auth_request_lua_log_info(lua_State *L) struct dlua_script *script = dlua_script_from_state(L); struct auth_request *request = auth_lua_check_auth_request(script, 1); const char *msg = luaL_checkstring(L, 2); - auth_request_log_info(request, AUTH_SUBSYS_DB, "db-lua: %s", msg); + e_info(authdb_event(request), "db-lua: %s", msg); return 0; } @@ -145,7 +145,7 @@ static int auth_request_lua_log_warning(lua_State *L) struct dlua_script *script = dlua_script_from_state(L); struct auth_request *request = auth_lua_check_auth_request(script, 1); const char *msg = luaL_checkstring(L, 2); - auth_request_log_warning(request, AUTH_SUBSYS_DB, "db-lua: %s", msg); + e_warning(authdb_event(request), "db-lua: %s", msg); return 0; } @@ -154,7 +154,7 @@ static int auth_request_lua_log_error(lua_State *L) struct dlua_script *script = dlua_script_from_state(L); struct auth_request *request = auth_lua_check_auth_request(script, 1); const char *msg = luaL_checkstring(L, 2); - auth_request_log_error(request, AUTH_SUBSYS_DB, "db-lua: %s", msg); + e_error(authdb_event(request), "db-lua: %s", msg); return 0; } @@ -413,7 +413,7 @@ static int auth_lua_call_lookup(struct dlua_script *script, const char *fn, } if (req->debug) - auth_request_log_debug(req, AUTH_SUBSYS_DB, "Calling %s", fn); + e_debug(authdb_event(req), "Calling %s", fn); /* call with auth request as parameter */ auth_lua_push_auth_request(script, req); @@ -495,9 +495,9 @@ static void auth_lua_export_table(struct dlua_script *script, struct auth_reques value = ""; break; default: - auth_request_log_warning(req, AUTH_SUBSYS_DB, - "db-lua: '%s' has invalid value type %s - ignoring", - key, lua_typename(script->L, -1)); + e_warning(authdb_event(req), + "db-lua: '%s' has invalid value type %s - ignoring", + key, lua_typename(script->L, -1)); value = ""; } @@ -593,7 +593,8 @@ auth_lua_call_password_verify(struct dlua_script *script, } if (req->debug) - auth_request_log_debug(req, AUTH_SUBSYS_DB, "Calling %s", AUTH_LUA_PASSWORD_VERIFY); + e_debug(authdb_event(req), "Calling %s", + AUTH_LUA_PASSWORD_VERIFY); /* call with auth request, password as parameters */ auth_lua_push_auth_request(script, req); @@ -689,18 +690,21 @@ auth_lua_call_userdb_iterate_init(struct dlua_script *script, struct auth_reques } if (req->debug) - auth_request_log_debug(req, AUTH_SUBSYS_DB, "Calling %s", AUTH_LUA_USERDB_ITERATE); + e_debug(authdb_event(req), "Calling %s", + AUTH_LUA_USERDB_ITERATE); if ((ret = lua_pcall(script->L, 0, 1, 0)) != 0) { - auth_request_log_error(req, AUTH_SUBSYS_DB, "db-lua: " AUTH_LUA_USERDB_ITERATE " failed: %s", - lua_tostring(script->L, -1)); + e_error(authdb_event(req), + "db-lua: " AUTH_LUA_USERDB_ITERATE " failed: %s", + lua_tostring(script->L, -1)); actx->ctx.failed = TRUE; lua_pop(script->L, 1); return &actx->ctx; } if (!lua_istable(script->L, -1)) { - auth_request_log_error(req, AUTH_SUBSYS_DB, "db-lua: Cannot iterate, return value is not table"); + e_error(authdb_event(req), + "db-lua: Cannot iterate, return value is not table"); actx->ctx.failed = TRUE; lua_pop(script->L, 1); lua_gc(script->L, LUA_GCCOLLECT, 0); @@ -714,7 +718,8 @@ auth_lua_call_userdb_iterate_init(struct dlua_script *script, struct auth_reques while (lua_next(script->L, -2) != 0) { lua_pushvalue(script->L, -2); if (!lua_isstring(script->L, -1)) { - auth_request_log_error(req, AUTH_SUBSYS_DB, "db-lua: Value is not string"); + e_error(authdb_event(req), + "db-lua: Value is not string"); actx->ctx.failed = TRUE; lua_pop(script->L, 1); lua_gc(script->L, LUA_GCCOLLECT, 0); diff --git a/src/auth/db-oauth2.c b/src/auth/db-oauth2.c index b3ababb11d..c333eaa070 100644 --- a/src/auth/db-oauth2.c +++ b/src/auth/db-oauth2.c @@ -421,9 +421,9 @@ static void db_oauth2_fields_merge(struct db_oauth2_request *req, req->fields = auth_fields_init(req->pool); array_foreach(fields, field) { - auth_request_log_debug(req->auth_request, AUTH_SUBSYS_DB, - "oauth2: Processing field %s", - field->name); + e_debug(authdb_event(req->auth_request), + "oauth2: Processing field %s", + field->name); auth_fields_add(req->fields, field->name, field->value, 0); } } @@ -437,9 +437,9 @@ static void db_oauth2_callback(struct db_oauth2_request *req, i_assert(result == PASSDB_RESULT_OK || error != NULL); - auth_request_log_debug(req->auth_request, AUTH_SUBSYS_DB, - "oauth2: callback(%d, %s)", - result, error); + e_debug(authdb_event(req->auth_request), + "oauth2: callback(%d, %s)", + result, error); if (callback != NULL) { DLLIST_REMOVE(&req->db->head, req); @@ -514,9 +514,9 @@ db_oauth2_token_in_scope(struct db_oauth2_request *req, if (*req->db->set.scope != '\0') { bool found = FALSE; const char *value = auth_fields_find(req->fields, "scope"); - auth_request_log_debug(req->auth_request, AUTH_SUBSYS_DB, - "oauth2: Token scope(s): %s", - value); + e_debug(authdb_event(req->auth_request), + "oauth2: Token scope(s): %s", + value); if (value != NULL) { const char **scopes = t_strsplit_spaces(value, " "); found = str_array_find(scopes, req->db->set.scope); @@ -556,9 +556,9 @@ db_oauth2_introspect_continue(struct oauth2_introspection_result *result, req->req = NULL; - auth_request_log_debug(req->auth_request, AUTH_SUBSYS_DB, - "oauth2: Introspection result: %s", - result->success ? "success" : "failed"); + e_debug(authdb_event(req->auth_request), + "oauth2: Introspection result: %s", + result->success ? "success" : "failed"); if (!result->success) { /* fail here */ @@ -576,9 +576,9 @@ static void db_oauth2_lookup_introspect(struct db_oauth2_request *req) struct oauth2_request_input input; i_zero(&input); - auth_request_log_debug(req->auth_request, AUTH_SUBSYS_DB, - "oauth2: Making introspection request to %s", - req->db->set.introspection_url); + e_debug(authdb_event(req->auth_request), + "oauth2: Making introspection request to %s", + req->db->set.introspection_url); input.token = req->token; input.local_ip = req->auth_request->local_ip; input.local_port = req->auth_request->local_port; @@ -645,8 +645,8 @@ db_oauth2_lookup_continue(struct oauth2_token_validation_result *result, if (*req->db->set.introspection_url != '\0' && (req->db->set.force_introspection || !db_oauth2_have_all_fields(req))) { - auth_request_log_debug(req->auth_request, AUTH_SUBSYS_DB, - "oauth2: Introspection needed after token validation"); + e_debug(authdb_event(req->auth_request), + "oauth2: Introspection needed after token validation"); db_oauth2_lookup_introspect(req); return; } @@ -681,22 +681,22 @@ void db_oauth2_lookup(struct db_oauth2 *db, struct db_oauth2_request *req, input.service = req->auth_request->service; if (db->oauth2_set.use_grant_password) { - auth_request_log_debug(req->auth_request, AUTH_SUBSYS_DB, - "oauth2: Making grant url request to %s", - db->set.grant_url); + e_debug(authdb_event(req->auth_request), + "oauth2: Making grant url request to %s", + db->set.grant_url); req->req = oauth2_passwd_grant_start(&db->oauth2_set, &input, request->user, request->mech_password, db_oauth2_lookup_passwd_grant, req); } else if (*db->oauth2_set.tokeninfo_url == '\0') { - auth_request_log_debug(req->auth_request, AUTH_SUBSYS_DB, - "oauth2: Making introspection request to %s", - db->set.introspection_url); + e_debug(authdb_event(req->auth_request), + "oauth2: Making introspection request to %s", + db->set.introspection_url); req->req = oauth2_introspection_start(&req->db->oauth2_set, &input, db_oauth2_introspect_continue, req); } else { - auth_request_log_debug(req->auth_request, AUTH_SUBSYS_DB, - "oauth2: Making token validation lookup to %s", - db->oauth2_set.tokeninfo_url); + e_debug(authdb_event(req->auth_request), + "oauth2: Making token validation lookup to %s", + db->oauth2_set.tokeninfo_url); req->req = oauth2_token_validation_start(&db->oauth2_set, &input, db_oauth2_lookup_continue, req); } diff --git a/src/auth/db-passwd-file.c b/src/auth/db-passwd-file.c index 3d60035c51..d711e0e9cc 100644 --- a/src/auth/db-passwd-file.c +++ b/src/auth/db-passwd-file.c @@ -266,14 +266,14 @@ static int passwd_file_sync(struct auth_request *request, int ret = -1; if (errno == EACCES) { - auth_request_log_error(request, AUTH_SUBSYS_DB, + e_error(authdb_event(request), "%s", eacces_error_get("stat", pw->path)); } else if (errno == ENOENT) { auth_request_log_info(request, "passwd-file", "missing passwd file: %s", pw->path); ret = 0; } else { - auth_request_log_error(request, AUTH_SUBSYS_DB, + e_error(authdb_event(request), "stat(%s) failed: %m", pw->path); } @@ -285,7 +285,7 @@ static int passwd_file_sync(struct auth_request *request, if (st.st_mtime != pw->stamp || st.st_size != pw->size) { passwd_file_close(pw); if (passwd_file_open(pw, FALSE, &error) < 0) { - auth_request_log_error(request, AUTH_SUBSYS_DB, + e_error(authdb_event(request), "%s", error); return -1; } @@ -446,7 +446,7 @@ int db_passwd_file_lookup(struct db_passwd_file *db, dest = t_str_new(256); if (auth_request_var_expand(dest, db->path, request, path_fix, &error) <= 0) { - auth_request_log_error(request, AUTH_SUBSYS_DB, + e_error(authdb_event(request), "Failed to expand passwd-file path %s: %s", db->path, error); return -1; @@ -467,15 +467,15 @@ int db_passwd_file_lookup(struct db_passwd_file *db, username = t_str_new(256); if (auth_request_var_expand(username, username_format, request, auth_request_str_escape, &error) <= 0) { - auth_request_log_error(request, AUTH_SUBSYS_DB, + e_error(authdb_event(request), "Failed to expand username_format=%s: %s", username_format, error); return -1; } - auth_request_log_debug(request, AUTH_SUBSYS_DB, - "lookup: user=%s file=%s", - str_c(username), pw->path); + e_debug(authdb_event(request), + "lookup: user=%s file=%s", + str_c(username), pw->path); *user_r = hash_table_lookup(pw->users, str_c(username)); if (*user_r == NULL) { diff --git a/src/auth/passdb-blocking.c b/src/auth/passdb-blocking.c index 76f7e821e7..f44258f050 100644 --- a/src/auth/passdb-blocking.c +++ b/src/auth/passdb-blocking.c @@ -68,7 +68,7 @@ passdb_blocking_auth_worker_reply_parse(struct auth_request *request, const char } } - auth_request_log_error(request, AUTH_SUBSYS_DB, + e_error(authdb_event(request), "Received invalid reply from worker: %s", reply); return PASSDB_RESULT_INTERNAL_FAILURE; } @@ -111,7 +111,7 @@ static bool lookup_credentials_callback(const char *reply, void *context) password = request->passdb_password; scheme = password_get_scheme(&password); if (scheme == NULL) { - auth_request_log_error(request, AUTH_SUBSYS_DB, + e_error(authdb_event(request), "Received reply from worker without " "password scheme"); result = PASSDB_RESULT_INTERNAL_FAILURE; diff --git a/src/auth/passdb-bsdauth.c b/src/auth/passdb-bsdauth.c index c67a7d0bf8..5889eee1df 100644 --- a/src/auth/passdb-bsdauth.c +++ b/src/auth/passdb-bsdauth.c @@ -21,12 +21,12 @@ bsdauth_verify_plain(struct auth_request *request, const char *password, const char *type; int result; - auth_request_log_debug(request, AUTH_SUBSYS_DB, "lookup"); + e_debug(authdb_event(request), "lookup"); switch (i_getpwnam(request->user, &pw)) { case -1: - auth_request_log_error(request, AUTH_SUBSYS_DB, - "getpwnam() failed: %m"); + e_error(authdb_event(request), + "getpwnam() failed: %m"); callback(PASSDB_RESULT_INTERNAL_FAILURE, request); return; case 0: diff --git a/src/auth/passdb-cache.c b/src/auth/passdb-cache.c index bf7dbaaf9d..3d9e918148 100644 --- a/src/auth/passdb-cache.c +++ b/src/auth/passdb-cache.c @@ -24,7 +24,7 @@ passdb_cache_log_hit(struct auth_request *request, const char *value) p = strchr(value, '\t'); value = t_strconcat(PASSWORD_HIDDEN_STR, p, NULL); } - auth_request_log_debug(request, AUTH_SUBSYS_DB, "cache hit: %s", value); + e_debug(authdb_event(request), "cache hit: %s", value); } static bool @@ -41,9 +41,9 @@ passdb_cache_lookup(struct auth_request *request, const char *key, &expired, neg_expired_r); if (value == NULL || (expired && !use_expired)) { stats->auth_cache_miss_count++; - auth_request_log_debug(request, AUTH_SUBSYS_DB, - value == NULL ? "cache miss" : - "cache expired"); + e_debug(authdb_event(request), + value == NULL ? "cache miss" : + "cache expired"); return FALSE; } stats->auth_cache_hit_count++; @@ -93,8 +93,8 @@ bool passdb_cache_verify_plain(struct auth_request *request, const char *key, cached_pw = list[0]; if (*cached_pw == '\0') { /* NULL password */ - auth_request_log_info(request, AUTH_SUBSYS_DB, - "Cached NULL password access"); + e_info(authdb_event(request), + "Cached NULL password access"); ret = 1; } else if (request->set->cache_verify_password_with_worker) { string_t *str; @@ -107,8 +107,8 @@ bool passdb_cache_verify_plain(struct auth_request *request, const char *key, str_append_c(str, '\t'); auth_request_export(request, str); - auth_request_log_debug(request, AUTH_SUBSYS_DB, "cache: " - "validating password on worker"); + e_debug(authdb_event(request), "cache: " + "validating password on worker"); auth_request_ref(request); auth_worker_call(request->pool, request->user, str_c(str), passdb_cache_verify_plain_callback, request); diff --git a/src/auth/passdb-checkpassword.c b/src/auth/passdb-checkpassword.c index dd6cc3c38f..b1e5a368b3 100644 --- a/src/auth/passdb-checkpassword.c +++ b/src/auth/passdb-checkpassword.c @@ -47,7 +47,7 @@ auth_checkpassword_callback(struct auth_request *request, auth_request_set_field(request, "password", crypted_pass, scheme); } else { - auth_request_log_error(request, AUTH_SUBSYS_DB, + e_error(authdb_event(request), "password field returned without {scheme} prefix"); } } diff --git a/src/auth/passdb-dict.c b/src/auth/passdb-dict.c index 4048ec9439..0e8c0a8953 100644 --- a/src/auth/passdb-dict.c +++ b/src/auth/passdb-dict.c @@ -41,7 +41,7 @@ dict_query_save_results(struct auth_request *auth_request, } } if (db_dict_value_iter_deinit(&iter, &error) < 0) { - auth_request_log_error(auth_request, AUTH_SUBSYS_DB, "%s", error); + e_error(authdb_event(auth_request), "%s", error); return -1; } return 0; @@ -69,8 +69,8 @@ passdb_dict_lookup_key(struct auth_request *auth_request, if (auth_request->passdb_password == NULL && !auth_fields_exists(auth_request->extra_fields, "nopassword")) { - auth_request_log_info(auth_request, AUTH_SUBSYS_DB, - "No password returned (and no nopassword)"); + e_info(authdb_event(auth_request), + "No password returned (and no nopassword)"); return PASSDB_RESULT_PASSWORD_MISMATCH; } else { return PASSDB_RESULT_OK; @@ -90,7 +90,7 @@ static void passdb_dict_lookup_pass(struct passdb_dict_request *dict_request) if (array_count(&module->conn->set.passdb_fields) == 0 && array_count(&module->conn->set.parsed_passdb_objects) == 0) { - auth_request_log_error(auth_request, AUTH_SUBSYS_DB, + e_error(authdb_event(auth_request), "No passdb_objects or passdb_fields specified"); passdb_result = PASSDB_RESULT_INTERNAL_FAILURE; } else { diff --git a/src/auth/passdb-imap.c b/src/auth/passdb-imap.c index 2f4a5e9f54..a2d16aef56 100644 --- a/src/auth/passdb-imap.c +++ b/src/auth/passdb-imap.c @@ -60,14 +60,14 @@ passdb_imap_login_callback(const struct imapc_command_reply *reply, break; case IMAPC_COMMAND_STATE_NO: result = passdb_imap_get_failure_result(reply); - auth_request_log_info(request->auth_request, AUTH_SUBSYS_DB, - "%s", reply->text_full); + e_info(authdb_event(request->auth_request), + "%s", reply->text_full); break; case IMAPC_COMMAND_STATE_AUTH_FAILED: case IMAPC_COMMAND_STATE_BAD: case IMAPC_COMMAND_STATE_DISCONNECTED: - auth_request_log_error(request->auth_request, AUTH_SUBSYS_DB, - "%s", reply->text_full); + e_error(authdb_event(request->auth_request), + "%s", reply->text_full); break; } request->verify_callback(result, request->auth_request); @@ -106,7 +106,7 @@ passdb_imap_verify_plain(struct auth_request *auth_request, str = t_str_new(128); if (auth_request_var_expand(str, set.username, auth_request, NULL, &error) <= 0) { - auth_request_log_error(auth_request, AUTH_SUBSYS_DB, + e_error(authdb_event(auth_request), "Failed to expand username=%s: %s", set.username, error); callback(PASSDB_RESULT_INTERNAL_FAILURE, auth_request); @@ -117,7 +117,7 @@ passdb_imap_verify_plain(struct auth_request *auth_request, str_truncate(str, 0); if (auth_request_var_expand(str, set.host, auth_request, NULL, &error) <= 0) { - auth_request_log_error(auth_request, AUTH_SUBSYS_DB, + e_error(authdb_event(auth_request), "Failed to expand host=%s: %s", set.host, error); callback(PASSDB_RESULT_INTERNAL_FAILURE, auth_request); @@ -125,8 +125,8 @@ passdb_imap_verify_plain(struct auth_request *auth_request, } set.host = t_strdup(str_c(str)); } - auth_request_log_debug(auth_request, AUTH_SUBSYS_DB, - "lookup host=%s port=%d", set.host, set.port); + e_debug(authdb_event(auth_request), + "lookup host=%s port=%d", set.host, set.port); request = p_new(auth_request->pool, struct imap_auth_request, 1); request->client = imapc_client_init(&set); diff --git a/src/auth/passdb-ldap.c b/src/auth/passdb-ldap.c index ba2ea7a9e7..f73cbbdbed 100644 --- a/src/auth/passdb-ldap.c +++ b/src/auth/passdb-ldap.c @@ -53,9 +53,9 @@ ldap_query_save_result(struct ldap_connection *conn, continue; } if (values[1] != NULL) { - auth_request_log_warning(auth_request, AUTH_SUBSYS_DB, - "Multiple values found for '%s', " - "using value '%s'", name, values[0]); + e_warning(authdb_event(auth_request), + "Multiple values found for '%s', " + "using value '%s'", name, values[0]); } auth_request_set_field(auth_request, name, values[0], conn->set.default_pass_scheme); @@ -78,14 +78,14 @@ ldap_lookup_finish(struct auth_request *auth_request, passdb_result = PASSDB_RESULT_USER_UNKNOWN; auth_request_log_unknown_user(auth_request, AUTH_SUBSYS_DB); } else if (ldap_request->entries > 1) { - auth_request_log_error(auth_request, AUTH_SUBSYS_DB, + e_error(authdb_event(auth_request), "pass_filter matched multiple objects, aborting"); passdb_result = PASSDB_RESULT_INTERNAL_FAILURE; } else if (auth_request->passdb_password == NULL && ldap_request->require_password && !auth_fields_exists(auth_request->extra_fields, "nopassword")) { - auth_request_log_info(auth_request, AUTH_SUBSYS_DB, - "No password returned (and no nopassword)"); + e_info(authdb_event(auth_request), + "No password returned (and no nopassword)"); passdb_result = PASSDB_RESULT_PASSWORD_MISMATCH; } else { /* passdb_password may change on the way, @@ -163,9 +163,9 @@ ldap_auth_bind_callback(struct ldap_connection *conn, auth_request_log_unknown_user(auth_request, AUTH_SUBSYS_DB); } else { - auth_request_log_error(auth_request, AUTH_SUBSYS_DB, - "ldap_bind() failed: %s", - ldap_err2string(ret)); + e_error(authdb_event(auth_request), + "ldap_bind() failed: %s", + ldap_err2string(ret)); } } @@ -185,8 +185,8 @@ static void ldap_auth_bind(struct ldap_connection *conn, /* Assume that empty password fails. This is especially important with Windows 2003 AD, which always returns success with empty passwords. */ - auth_request_log_info(auth_request, AUTH_SUBSYS_DB, - "Login attempt with empty password"); + e_info(authdb_event(auth_request), + "Login attempt with empty password"); passdb_ldap_request->callback. verify_plain(PASSDB_RESULT_PASSWORD_MISMATCH, auth_request); @@ -225,7 +225,7 @@ ldap_bind_lookup_dn_fail(struct auth_request *auth_request, auth_request_log_unknown_user(auth_request, AUTH_SUBSYS_DB); } else { i_assert(request->entries > 1); - auth_request_log_error(auth_request, AUTH_SUBSYS_DB, + e_error(authdb_event(auth_request), "pass_filter matched multiple objects, aborting"); passdb_result = PASSDB_RESULT_INTERNAL_FAILURE; } @@ -299,7 +299,7 @@ static void ldap_lookup_pass(struct auth_request *auth_request, str = t_str_new(512); if (auth_request_var_expand(str, conn->set.base, auth_request, ldap_escape, &error) <= 0) { - auth_request_log_error(auth_request, AUTH_SUBSYS_DB, + e_error(authdb_event(auth_request), "Failed to expand base=%s: %s", conn->set.base, error); passdb_ldap_request_fail(request, PASSDB_RESULT_INTERNAL_FAILURE); return; @@ -309,7 +309,7 @@ static void ldap_lookup_pass(struct auth_request *auth_request, str_truncate(str, 0); if (auth_request_var_expand(str, conn->set.pass_filter, auth_request, ldap_escape, &error) <= 0) { - auth_request_log_error(auth_request, AUTH_SUBSYS_DB, + e_error(authdb_event(auth_request), "Failed to expand pass_filter=%s: %s", conn->set.pass_filter, error); passdb_ldap_request_fail(request, PASSDB_RESULT_INTERNAL_FAILURE); @@ -319,11 +319,11 @@ static void ldap_lookup_pass(struct auth_request *auth_request, srequest->attr_map = &conn->pass_attr_map; srequest->attributes = conn->pass_attr_names; - auth_request_log_debug(auth_request, AUTH_SUBSYS_DB, "pass search: " - "base=%s scope=%s filter=%s fields=%s", - srequest->base, conn->set.scope, - srequest->filter, attr_names == NULL ? "(all)" : - t_strarray_join(attr_names, ",")); + e_debug(authdb_event(auth_request), "pass search: " + "base=%s scope=%s filter=%s fields=%s", + srequest->base, conn->set.scope, + srequest->filter, attr_names == NULL ? "(all)" : + t_strarray_join(attr_names, ",")); srequest->request.callback = ldap_lookup_pass_callback; db_ldap_request(conn, &srequest->request); @@ -345,7 +345,7 @@ static void ldap_bind_lookup_dn(struct auth_request *auth_request, str = t_str_new(512); if (auth_request_var_expand(str, conn->set.base, auth_request, ldap_escape, &error) <= 0) { - auth_request_log_error(auth_request, AUTH_SUBSYS_DB, + e_error(authdb_event(auth_request), "Failed to expand base=%s: %s", conn->set.base, error); passdb_ldap_request_fail(request, PASSDB_RESULT_INTERNAL_FAILURE); return; @@ -355,7 +355,7 @@ static void ldap_bind_lookup_dn(struct auth_request *auth_request, str_truncate(str, 0); if (auth_request_var_expand(str, conn->set.pass_filter, auth_request, ldap_escape, &error) <= 0) { - auth_request_log_error(auth_request, AUTH_SUBSYS_DB, + e_error(authdb_event(auth_request), "Failed to expand pass_filter=%s: %s", conn->set.pass_filter, error); passdb_ldap_request_fail(request, PASSDB_RESULT_INTERNAL_FAILURE); @@ -369,9 +369,9 @@ static void ldap_bind_lookup_dn(struct auth_request *auth_request, srequest->attr_map = &conn->pass_attr_map; srequest->attributes = conn->pass_attr_names; - auth_request_log_debug(auth_request, AUTH_SUBSYS_DB, - "bind search: base=%s filter=%s", - srequest->base, srequest->filter); + e_debug(authdb_event(auth_request), + "bind search: base=%s filter=%s", + srequest->base, srequest->filter); srequest->request.callback = ldap_bind_lookup_dn_callback; db_ldap_request(conn, &srequest->request); @@ -394,7 +394,7 @@ ldap_verify_plain_auth_bind_userdn(struct auth_request *auth_request, dn = t_str_new(512); if (auth_request_var_expand(dn, conn->set.auth_bind_userdn, auth_request, ldap_escape, &error) <= 0) { - auth_request_log_error(auth_request, AUTH_SUBSYS_DB, + e_error(authdb_event(auth_request), "Failed to expand auth_bind_userdn=%s: %s", conn->set.auth_bind_userdn, error); passdb_ldap_request_fail(request, PASSDB_RESULT_INTERNAL_FAILURE); diff --git a/src/auth/passdb-lua.c b/src/auth/passdb-lua.c index 0e3630af2d..672d431924 100644 --- a/src/auth/passdb-lua.c +++ b/src/auth/passdb-lua.c @@ -26,8 +26,8 @@ passdb_lua_verify_password(struct dlua_passdb_module *module, if (result == PASSDB_RESULT_PASSWORD_MISMATCH) { auth_request_log_password_mismatch(request, AUTH_SUBSYS_DB); } else if (result == PASSDB_RESULT_INTERNAL_FAILURE && error != NULL) { - auth_request_log_error(request, AUTH_SUBSYS_DB, "passdb-lua: %s", - error); + e_error(authdb_event(request), "passdb-lua: %s", + error); } return result; } @@ -47,13 +47,13 @@ passdb_lua_lookup(struct auth_request *request, password_r, &error); if (result == PASSDB_RESULT_INTERNAL_FAILURE && error != NULL) { - auth_request_log_error(request, AUTH_SUBSYS_DB, "db-lua: %s", error); + e_error(authdb_event(request), "db-lua: %s", error); } else if (result != PASSDB_RESULT_OK) { /* skip next bit */ } else if (!auth_fields_exists(request->extra_fields, "nopassword")) { if (*password_r == NULL || **password_r == '\0') { - auth_request_log_info(request, AUTH_SUBSYS_DB, - "No password returned (and no nopassword)"); + e_info(authdb_event(request), + "No password returned (and no nopassword)"); result = PASSDB_RESULT_PASSWORD_MISMATCH; } else { if (*scheme_r == NULL) @@ -62,8 +62,8 @@ passdb_lua_lookup(struct auth_request *request, *password_r, *scheme_r); } } else if (*password_r != NULL && **password_r != '\0') { - auth_request_log_info(request, AUTH_SUBSYS_DB, - "nopassword given and password is not empty"); + e_info(authdb_event(request), + "nopassword given and password is not empty"); result = PASSDB_RESULT_PASSWORD_MISMATCH; } return result; diff --git a/src/auth/passdb-oauth2.c b/src/auth/passdb-oauth2.c index 7ba75d4aa1..000d1ec6e8 100644 --- a/src/auth/passdb-oauth2.c +++ b/src/auth/passdb-oauth2.c @@ -15,11 +15,11 @@ oauth2_verify_plain_continue(struct db_oauth2_request *req, struct auth_request *request) { if (result == PASSDB_RESULT_INTERNAL_FAILURE) - auth_request_log_error(request, AUTH_SUBSYS_DB, "oauth2 failed: %s", - error); + e_error(authdb_event(request), "oauth2 failed: %s", + error); else if (result != PASSDB_RESULT_OK) - auth_request_log_info(request, AUTH_SUBSYS_DB, "oauth2 failed: %s", - error); + e_info(authdb_event(request), "oauth2 failed: %s", + error); else { auth_request_set_field(request, "token", req->token, "PLAIN"); } diff --git a/src/auth/passdb-pam.c b/src/auth/passdb-pam.c index 6828f194e2..647899a051 100644 --- a/src/auth/passdb-pam.c +++ b/src/auth/passdb-pam.c @@ -72,10 +72,10 @@ pam_userpass_conv(int num_msg, pam_const struct pam_message **msg, i_fatal_status(FATAL_OUTOFMEM, "Out of memory"); for (i = 0; i < num_msg; i++) { - auth_request_log_debug(ctx->request, AUTH_SUBSYS_DB, - "#%d/%d style=%d msg=%s", i+1, num_msg, - msg[i]->msg_style, - msg[i]->msg != NULL ? msg[i]->msg : ""); + e_debug(authdb_event(ctx->request), + "#%d/%d style=%d msg=%s", i+1, num_msg, + msg[i]->msg_style, + msg[i]->msg != NULL ? msg[i]->msg : ""); switch (msg[i]->msg_style) { case PAM_PROMPT_ECHO_ON: /* Assume we're asking for user. We might not ever @@ -169,7 +169,7 @@ static int try_pam_auth(struct auth_request *request, pam_handle_t *pamh, if (path != NULL) { /* log this as error, since it probably is */ str = t_strdup_printf("%s (%s missing?)", str, path); - auth_request_log_error(request, AUTH_SUBSYS_DB, "%s", str); + e_error(authdb_event(request), "%s", str); } else if (status == PAM_AUTH_ERR) { str = t_strconcat(str, " ("AUTH_LOG_MSG_PASSWORD_MISMATCH"?)", NULL); if (request->set->debug_passwords) { @@ -177,13 +177,13 @@ static int try_pam_auth(struct auth_request *request, pam_handle_t *pamh, request->mech_password, ")", NULL); } - auth_request_log_info(request, AUTH_SUBSYS_DB, "%s", str); + e_info(authdb_event(request), "%s", str); } else { if (status == PAM_USER_UNKNOWN) auth_request_log_unknown_user(request, AUTH_SUBSYS_DB); else { - auth_request_log_info(request, AUTH_SUBSYS_DB, - "%s", str); + e_info(authdb_event(request), + "%s", str); } } return status; @@ -193,42 +193,42 @@ static int try_pam_auth(struct auth_request *request, pam_handle_t *pamh, if (module->pam_setcred) { if ((status = pam_setcred(pamh, PAM_ESTABLISH_CRED)) != PAM_SUCCESS) { - auth_request_log_error(request, AUTH_SUBSYS_DB, - "pam_setcred() failed: %s", - pam_strerror(pamh, status)); + e_error(authdb_event(request), + "pam_setcred() failed: %s", + pam_strerror(pamh, status)); return status; } } #endif if ((status = pam_acct_mgmt(pamh, 0)) != PAM_SUCCESS) { - auth_request_log_error(request, AUTH_SUBSYS_DB, - "pam_acct_mgmt() failed: %s", - pam_strerror(pamh, status)); + e_error(authdb_event(request), + "pam_acct_mgmt() failed: %s", + pam_strerror(pamh, status)); return status; } if (module->pam_session) { if ((status = pam_open_session(pamh, 0)) != PAM_SUCCESS) { - auth_request_log_error(request, AUTH_SUBSYS_DB, - "pam_open_session() failed: %s", - pam_strerror(pamh, status)); + e_error(authdb_event(request), + "pam_open_session() failed: %s", + pam_strerror(pamh, status)); return status; } if ((status = pam_close_session(pamh, 0)) != PAM_SUCCESS) { - auth_request_log_error(request, AUTH_SUBSYS_DB, - "pam_close_session() failed: %s", - pam_strerror(pamh, status)); + e_error(authdb_event(request), + "pam_close_session() failed: %s", + pam_strerror(pamh, status)); return status; } } status = pam_get_item(pamh, PAM_USER, &item); if (status != PAM_SUCCESS) { - auth_request_log_error(request, AUTH_SUBSYS_DB, - "pam_get_item(PAM_USER) failed: %s", - pam_strerror(pamh, status)); + e_error(authdb_event(request), + "pam_get_item(PAM_USER) failed: %s", + pam_strerror(pamh, status)); return status; } auth_request_set_field(request, "user", item, NULL); @@ -267,18 +267,18 @@ pam_verify_plain_call(struct auth_request *request, const char *service, status = pam_start(service, request->user, &conv, &pamh); if (status != PAM_SUCCESS) { - auth_request_log_error(request, AUTH_SUBSYS_DB, - "pam_start() failed: %s", - pam_strerror(pamh, status)); + e_error(authdb_event(request), + "pam_start() failed: %s", + pam_strerror(pamh, status)); return PASSDB_RESULT_INTERNAL_FAILURE; } set_pam_items(request, pamh); status = try_pam_auth(request, pamh, service); if ((status2 = pam_end(pamh, status)) != PAM_SUCCESS) { - auth_request_log_error(request, AUTH_SUBSYS_DB, - "pam_end() failed: %s", - pam_strerror(pamh, status2)); + e_error(authdb_event(request), + "pam_end() failed: %s", + pam_strerror(pamh, status2)); return PASSDB_RESULT_INTERNAL_FAILURE; } @@ -321,15 +321,15 @@ pam_verify_plain(struct auth_request *request, const char *password, if (t_auth_request_var_expand(module->service_name, request, NULL, &service, &error) <= 0) { - auth_request_log_debug(request, AUTH_SUBSYS_DB, + e_debug(authdb_event(request), "Failed to expand service %s: %s", module->service_name, error); callback(PASSDB_RESULT_INTERNAL_FAILURE, request); return; } - auth_request_log_debug(request, AUTH_SUBSYS_DB, - "lookup service=%s", service); + e_debug(authdb_event(request), + "lookup service=%s", service); result = pam_verify_plain_call(request, service, password); callback(result, request); diff --git a/src/auth/passdb-passwd-file.c b/src/auth/passdb-passwd-file.c index 7abb9ff38b..227fab3771 100644 --- a/src/auth/passdb-passwd-file.c +++ b/src/auth/passdb-passwd-file.c @@ -34,7 +34,7 @@ passwd_file_add_extra_fields(struct auth_request *request, char *const *fields) str_truncate(str, 0); if (auth_request_var_expand_with_table(str, value + 1, request, table, NULL, &error) <= 0) { - auth_request_log_error(request, AUTH_SUBSYS_DB, + e_error(authdb_event(request), "Failed to expand extra field %s: %s", fields[i], error); return -1; diff --git a/src/auth/passdb-passwd.c b/src/auth/passdb-passwd.c index 965b659a0a..99ea8de66c 100644 --- a/src/auth/passdb-passwd.c +++ b/src/auth/passdb-passwd.c @@ -14,12 +14,12 @@ static enum passdb_result passwd_lookup(struct auth_request *request, struct passwd *pw_r) { - auth_request_log_debug(request, AUTH_SUBSYS_DB, "lookup"); + e_debug(authdb_event(request), "lookup"); switch (i_getpwnam(request->user, pw_r)) { case -1: - auth_request_log_error(request, AUTH_SUBSYS_DB, - "getpwnam() failed: %m"); + e_error(authdb_event(request), + "getpwnam() failed: %m"); return PASSDB_RESULT_INTERNAL_FAILURE; case 0: auth_request_log_unknown_user(request, AUTH_SUBSYS_DB); @@ -27,8 +27,8 @@ passwd_lookup(struct auth_request *request, struct passwd *pw_r) } if (!IS_VALID_PASSWD(pw_r->pw_passwd)) { - auth_request_log_info(request, AUTH_SUBSYS_DB, - "invalid password field '%s'", pw_r->pw_passwd); + e_info(authdb_event(request), + "invalid password field '%s'", pw_r->pw_passwd); return PASSDB_RESULT_USER_DISABLED; } diff --git a/src/auth/passdb-shadow.c b/src/auth/passdb-shadow.c index 60429c0f11..2e7f67bc98 100644 --- a/src/auth/passdb-shadow.c +++ b/src/auth/passdb-shadow.c @@ -15,7 +15,7 @@ static enum passdb_result shadow_lookup(struct auth_request *request, struct spwd **spw_r) { - auth_request_log_debug(request, AUTH_SUBSYS_DB, "lookup"); + e_debug(authdb_event(request), "lookup"); *spw_r = getspnam(request->user); if (*spw_r == NULL) { @@ -24,8 +24,8 @@ shadow_lookup(struct auth_request *request, struct spwd **spw_r) } if (!IS_VALID_PASSWD((*spw_r)->sp_pwdp)) { - auth_request_log_info(request, AUTH_SUBSYS_DB, - "invalid password field"); + e_info(authdb_event(request), + "invalid password field"); return PASSDB_RESULT_USER_DISABLED; } diff --git a/src/auth/passdb-sia.c b/src/auth/passdb-sia.c index 423cf21704..ccc18159d8 100644 --- a/src/auth/passdb-sia.c +++ b/src/auth/passdb-sia.c @@ -35,7 +35,7 @@ local_sia_verify_plain(struct auth_request *request, const char *password, { char *argutility = "dovecot"; - auth_request_log_debug(request, AUTH_SUBSYS_DB, "lookup"); + e_debug(authdb_event(request), "lookup"); /* check if the password is valid */ if (sia_validate_user(checkpw_collect, 1, &argutility, NULL, diff --git a/src/auth/passdb-sql.c b/src/auth/passdb-sql.c index 3c16c82f59..0c0a2c5795 100644 --- a/src/auth/passdb-sql.c +++ b/src/auth/passdb-sql.c @@ -70,11 +70,11 @@ static void sql_query_callback(struct sql_result *result, db_sql_success(module->conn); if (ret < 0) { if (!module->conn->default_password_query) { - auth_request_log_error(auth_request, AUTH_SUBSYS_DB, - "Password query failed: %s", - sql_result_get_error(result)); + e_error(authdb_event(auth_request), + "Password query failed: %s", + sql_result_get_error(result)); } else { - auth_request_log_error(auth_request, AUTH_SUBSYS_DB, + e_error(authdb_event(auth_request), "Password query failed: %s " "(using built-in default password_query: %s)", sql_result_get_error(result), @@ -92,16 +92,16 @@ static void sql_query_callback(struct sql_result *result, password. */ if (sql_result_find_field(result, "password") < 0 && sql_result_find_field(result, "password_noscheme") < 0) { - auth_request_log_error(auth_request, AUTH_SUBSYS_DB, + e_error(authdb_event(auth_request), "Password query must return a field named " "'password'"); } else if (sql_result_next_row(result) > 0) { - auth_request_log_error(auth_request, AUTH_SUBSYS_DB, + e_error(authdb_event(auth_request), "Password query returned multiple matches"); } else if (auth_request->passdb_password == NULL && !auth_fields_exists(auth_request->extra_fields, "nopassword")) { - auth_request_log_info(auth_request, AUTH_SUBSYS_DB, - "Empty password returned without nopassword"); + e_info(authdb_event(auth_request), + "Empty password returned without nopassword"); passdb_result = PASSDB_RESULT_PASSWORD_MISMATCH; } else { /* passdb_password may change on the way, @@ -159,7 +159,7 @@ static void sql_lookup_pass(struct passdb_sql_request *sql_request) if (t_auth_request_var_expand(module->conn->set.password_query, sql_request->auth_request, passdb_sql_escape, &query, &error) <= 0) { - auth_request_log_debug(sql_request->auth_request, AUTH_SUBSYS_DB, + e_debug(authdb_event(sql_request->auth_request), "Failed to expand password_query=%s: %s", module->conn->set.password_query, error); sql_request->callback.verify_plain(PASSDB_RESULT_INTERNAL_FAILURE, @@ -167,8 +167,8 @@ static void sql_lookup_pass(struct passdb_sql_request *sql_request) return; } - auth_request_log_debug(sql_request->auth_request, AUTH_SUBSYS_DB, - "query: %s", query); + e_debug(authdb_event(sql_request->auth_request), + "query: %s", query); auth_request_ref(sql_request->auth_request); sql_query(module->conn->db, query, @@ -241,7 +241,7 @@ static void sql_set_credentials(struct auth_request *request, if (t_auth_request_var_expand(module->conn->set.update_query, request, passdb_sql_escape, &query, &error) <= 0) { - auth_request_log_error(request, AUTH_SUBSYS_DB, + e_error(authdb_event(request), "Failed to expand update_query=%s: %s", module->conn->set.update_query, error); callback(FALSE, request); diff --git a/src/auth/passdb-static.c b/src/auth/passdb-static.c index 67cac4769f..d55519e330 100644 --- a/src/auth/passdb-static.c +++ b/src/auth/passdb-static.c @@ -22,9 +22,9 @@ static_save_fields(struct auth_request *request, const char **password_r, *password_r = NULL; *scheme_r = NULL; - auth_request_log_debug(request, AUTH_SUBSYS_DB, "lookup"); + e_debug(authdb_event(request), "lookup"); if (passdb_template_export(module->tmpl, request, &error) < 0) { - auth_request_log_error(request, AUTH_SUBSYS_DB, + e_error(authdb_event(request), "Failed to expand template: %s", error); return PASSDB_RESULT_INTERNAL_FAILURE; } @@ -32,7 +32,7 @@ static_save_fields(struct auth_request *request, const char **password_r, if (module->static_password_tmpl != NULL) { if (t_auth_request_var_expand(module->static_password_tmpl, request, NULL, password_r, &error) <= 0) { - auth_request_log_error(request, AUTH_SUBSYS_DB, + e_error(authdb_event(request), "Failed to expand password=%s: %s", module->static_password_tmpl, error); return PASSDB_RESULT_INTERNAL_FAILURE; @@ -40,8 +40,8 @@ static_save_fields(struct auth_request *request, const char **password_r, } else if (auth_fields_exists(request->extra_fields, "nopassword")) { *password_r = ""; } else { - auth_request_log_info(request, AUTH_SUBSYS_DB, - "No password returned (and no nopassword)"); + e_info(authdb_event(request), + "No password returned (and no nopassword)"); return PASSDB_RESULT_PASSWORD_MISMATCH; } diff --git a/src/auth/passdb-vpopmail.c b/src/auth/passdb-vpopmail.c index 733a12655e..57f90fca0c 100644 --- a/src/auth/passdb-vpopmail.c +++ b/src/auth/passdb-vpopmail.c @@ -71,9 +71,9 @@ vpopmail_password_lookup(struct auth_request *auth_request, bool *cleartext, } if (vpopmail_is_disabled(auth_request, vpw)) { - auth_request_log_info(auth_request, AUTH_SUBSYS_DB, - "%s disabled in vpopmail for this user", - auth_request->service); + e_info(authdb_event(auth_request), + "%s disabled in vpopmail for this user", + auth_request->service); password = NULL; *result_r = PASSDB_RESULT_USER_DISABLED; } else { diff --git a/src/auth/passdb.c b/src/auth/passdb.c index 033ceb8500..8b92a47b18 100644 --- a/src/auth/passdb.c +++ b/src/auth/passdb.c @@ -76,11 +76,11 @@ bool passdb_get_credentials(struct auth_request *auth_request, credentials_r, size_r, &error); if (ret <= 0) { if (ret < 0) { - auth_request_log_error(auth_request, AUTH_SUBSYS_DB, + e_error(authdb_event(auth_request), "Password data is not valid for scheme %s: %s", input_scheme, error); } else { - auth_request_log_error(auth_request, AUTH_SUBSYS_DB, + e_error(authdb_event(auth_request), "Unknown scheme %s", input_scheme); } return FALSE; @@ -103,8 +103,8 @@ bool passdb_get_credentials(struct auth_request *auth_request, error = t_strdup_printf("%s (input: %s)", error, input); } - auth_request_log_info(auth_request, AUTH_SUBSYS_DB, - "%s", error); + e_info(authdb_event(auth_request), + "%s", error); return FALSE; } @@ -119,13 +119,13 @@ bool passdb_get_credentials(struct auth_request *auth_request, auth_request->realm, NULL); } if (auth_request->set->debug_passwords) { - auth_request_log_debug(auth_request, AUTH_SUBSYS_DB, + e_debug(authdb_event(auth_request), "Generating %s from user '%s', password '%s'", wanted_scheme, pwd_gen_params.user, plaintext); } if (!password_generate(plaintext, &pwd_gen_params, wanted_scheme, credentials_r, size_r)) { - auth_request_log_error(auth_request, AUTH_SUBSYS_DB, + e_error(authdb_event(auth_request), "Requested unknown scheme %s", wanted_scheme); return FALSE; } @@ -162,9 +162,9 @@ void passdb_handle_credentials(enum passdb_result result, passdb lookup. auth_request_lookup_credentials_finish() will use them. */ } else { - auth_request_log_info(auth_request, AUTH_SUBSYS_DB, - "Requested %s scheme, but we have a NULL password", - auth_request->credentials_scheme); + e_info(authdb_event(auth_request), + "Requested %s scheme, but we have a NULL password", + auth_request->credentials_scheme); result = PASSDB_RESULT_SCHEME_NOT_AVAILABLE; } diff --git a/src/auth/userdb-dict.c b/src/auth/userdb-dict.c index f60631fa6b..636a752496 100644 --- a/src/auth/userdb-dict.c +++ b/src/auth/userdb-dict.c @@ -37,7 +37,7 @@ dict_query_save_results(struct auth_request *auth_request, auth_request_set_userdb_field(auth_request, key, value); } if (db_dict_value_iter_deinit(&iter, &error) < 0) { - auth_request_log_error(auth_request, AUTH_SUBSYS_DB, "%s", error); + e_error(authdb_event(auth_request), "%s", error); return -1; } return 0; @@ -55,7 +55,7 @@ static void userdb_dict_lookup(struct auth_request *auth_request, if (array_count(&module->conn->set.userdb_fields) == 0 && array_count(&module->conn->set.parsed_userdb_objects) == 0) { - auth_request_log_error(auth_request, AUTH_SUBSYS_DB, + e_error(authdb_event(auth_request), "No userdb_objects or userdb_fields specified"); callback(USERDB_RESULT_INTERNAL_FAILURE, auth_request); return; @@ -98,8 +98,8 @@ userdb_dict_iterate_init(struct auth_request *auth_request, if (*module->conn->set.iterate_prefix == '\0') { if (!module->conn->set.iterate_disable) { - auth_request_log_error(auth_request, AUTH_SUBSYS_DB, - "iterate: iterate_prefix not set"); + e_error(authdb_event(auth_request), + "iterate: iterate_prefix not set"); ctx->ctx.failed = TRUE; } return &ctx->ctx; @@ -109,7 +109,7 @@ userdb_dict_iterate_init(struct auth_request *auth_request, str_append(path, DICT_PATH_SHARED); if (auth_request_var_expand(path, module->conn->set.iterate_prefix, auth_request, NULL, &error) <= 0) { - auth_request_log_error(auth_request, AUTH_SUBSYS_DB, + e_error(authdb_event(auth_request), "Failed to expand iterate_prefix=%s: %s", module->conn->set.iterate_prefix, error); ctx->ctx.failed = TRUE; @@ -119,8 +119,8 @@ userdb_dict_iterate_init(struct auth_request *auth_request, ctx->key_prefix_len = strlen(ctx->key_prefix); ctx->iter = dict_iterate_init(module->conn->dict, ctx->key_prefix, 0); - auth_request_log_debug(auth_request, AUTH_SUBSYS_DB, - "iterate: prefix=%s", ctx->key_prefix); + e_debug(authdb_event(auth_request), + "iterate: prefix=%s", ctx->key_prefix); return &ctx->ctx; } diff --git a/src/auth/userdb-ldap.c b/src/auth/userdb-ldap.c index 31b44782a8..13d0055ac3 100644 --- a/src/auth/userdb-ldap.c +++ b/src/auth/userdb-ldap.c @@ -69,7 +69,7 @@ userdb_ldap_lookup_finish(struct auth_request *auth_request, result = USERDB_RESULT_USER_UNKNOWN; auth_request_log_unknown_user(auth_request, AUTH_SUBSYS_DB); } else if (urequest->entries > 1) { - auth_request_log_error(auth_request, AUTH_SUBSYS_DB, + e_error(authdb_event(auth_request), "user_filter matched multiple objects, aborting"); result = USERDB_RESULT_INTERNAL_FAILURE; } else { @@ -120,7 +120,7 @@ static void userdb_ldap_lookup(struct auth_request *auth_request, str = t_str_new(512); if (auth_request_var_expand(str, conn->set.base, auth_request, ldap_escape, &error) <= 0) { - auth_request_log_error(auth_request, AUTH_SUBSYS_DB, + e_error(authdb_event(auth_request), "Failed to expand base=%s: %s", conn->set.base, error); callback(USERDB_RESULT_INTERNAL_FAILURE, auth_request); return; @@ -130,7 +130,7 @@ static void userdb_ldap_lookup(struct auth_request *auth_request, str_truncate(str, 0); if (auth_request_var_expand(str, conn->set.user_filter, auth_request, ldap_escape, &error) <= 0) { - auth_request_log_error(auth_request, AUTH_SUBSYS_DB, + e_error(authdb_event(auth_request), "Failed to expand user_filter=%s: %s", conn->set.user_filter, error); callback(USERDB_RESULT_INTERNAL_FAILURE, auth_request); @@ -141,12 +141,12 @@ static void userdb_ldap_lookup(struct auth_request *auth_request, request->request.attr_map = &conn->user_attr_map; request->request.attributes = conn->user_attr_names; - auth_request_log_debug(auth_request, AUTH_SUBSYS_DB, "user search: " - "base=%s scope=%s filter=%s fields=%s", - request->request.base, conn->set.scope, - request->request.filter, - attr_names == NULL ? "(all)" : - t_strarray_join(attr_names, ",")); + e_debug(authdb_event(auth_request), "user search: " + "base=%s scope=%s filter=%s fields=%s", + request->request.base, conn->set.scope, + request->request.filter, + attr_names == NULL ? "(all)" : + t_strarray_join(attr_names, ",")); request->request.request.auth_request = auth_request; request->request.request.callback = userdb_ldap_lookup_callback; @@ -222,7 +222,7 @@ userdb_ldap_iterate_init(struct auth_request *auth_request, str = t_str_new(512); if (auth_request_var_expand(str, conn->set.base, auth_request, ldap_escape, &error) <= 0) { - auth_request_log_error(auth_request, AUTH_SUBSYS_DB, + e_error(authdb_event(auth_request), "Failed to expand base=%s: %s", conn->set.base, error); ctx->ctx.failed = TRUE; } @@ -231,7 +231,7 @@ userdb_ldap_iterate_init(struct auth_request *auth_request, str_truncate(str, 0); if (auth_request_var_expand(str, conn->set.iterate_filter, auth_request, ldap_escape, &error) <= 0) { - auth_request_log_error(auth_request, AUTH_SUBSYS_DB, + e_error(authdb_event(auth_request), "Failed to expand iterate_filter=%s: %s", conn->set.iterate_filter, error); ctx->ctx.failed = TRUE; diff --git a/src/auth/userdb-lua.c b/src/auth/userdb-lua.c index 04f098bf19..6b75c0d781 100644 --- a/src/auth/userdb-lua.c +++ b/src/auth/userdb-lua.c @@ -24,8 +24,8 @@ static void userdb_lua_lookup(struct auth_request *auth_request, enum userdb_result result = auth_lua_call_userdb_lookup(module->script, auth_request, &error); if (result == USERDB_RESULT_INTERNAL_FAILURE) - auth_request_log_error(auth_request, AUTH_SUBSYS_DB, - "userdb-lua: %s", error); + e_error(authdb_event(auth_request), + "userdb-lua: %s", error); callback(result, auth_request); } diff --git a/src/auth/userdb-passwd-file.c b/src/auth/userdb-passwd-file.c index d90bcab928..466bdb858f 100644 --- a/src/auth/userdb-passwd-file.c +++ b/src/auth/userdb-passwd-file.c @@ -48,7 +48,7 @@ passwd_file_add_extra_fields(struct auth_request *request, char *const *fields) str_truncate(str, 0); if (auth_request_var_expand_with_table(str, value + 1, request, table, NULL, &error) <= 0) { - auth_request_log_error(request, AUTH_SUBSYS_DB, + e_error(authdb_event(request), "Failed to expand extra field %s: %s", fields[i], error); return -1; diff --git a/src/auth/userdb-passwd.c b/src/auth/userdb-passwd.c index 03cbd554ff..ee8edf04ee 100644 --- a/src/auth/userdb-passwd.c +++ b/src/auth/userdb-passwd.c @@ -87,7 +87,7 @@ static void passwd_lookup(struct auth_request *auth_request, const char *error; int ret; - auth_request_log_debug(auth_request, AUTH_SUBSYS_DB, "lookup"); + e_debug(authdb_event(auth_request), "lookup"); if (gettimeofday(&start_tv, NULL) < 0) start_tv.tv_sec = 0; @@ -97,8 +97,8 @@ static void passwd_lookup(struct auth_request *auth_request, switch (ret) { case -1: - auth_request_log_error(auth_request, AUTH_SUBSYS_DB, - "getpwnam() failed: %m"); + e_error(authdb_event(auth_request), + "getpwnam() failed: %m"); callback(USERDB_RESULT_INTERNAL_FAILURE, auth_request); return; case 0: @@ -116,8 +116,8 @@ static void passwd_lookup(struct auth_request *auth_request, auth_request_set_userdb_field(auth_request, "home", pw.pw_dir); if (userdb_template_export(module->tmpl, auth_request, &error) < 0) { - auth_request_log_error(auth_request, AUTH_SUBSYS_DB, - "Failed to expand template: %s", error); + e_error(authdb_event(auth_request), + "Failed to expand template: %s", error); callback(USERDB_RESULT_INTERNAL_FAILURE, auth_request); } diff --git a/src/auth/userdb-prefetch.c b/src/auth/userdb-prefetch.c index b985584158..a5730b9872 100644 --- a/src/auth/userdb-prefetch.c +++ b/src/auth/userdb-prefetch.c @@ -18,24 +18,24 @@ static void prefetch_lookup(struct auth_request *auth_request, if (auth_request_get_auth(auth_request)->userdbs->next == NULL) { /* no other userdbs */ if (auth_request->userdb_lookup) { - auth_request_log_error(auth_request, AUTH_SUBSYS_DB, + e_error(authdb_event(auth_request), "userdb lookup not possible with only userdb prefetch"); } else { - auth_request_log_error(auth_request, AUTH_SUBSYS_DB, + e_error(authdb_event(auth_request), "passdb didn't return userdb entries"); } callback(USERDB_RESULT_INTERNAL_FAILURE, auth_request); return; } /* more userdbs, they may know the user */ - auth_request_log_debug(auth_request, AUTH_SUBSYS_DB, - "passdb didn't return userdb entries, " - "trying the next userdb"); + e_debug(authdb_event(auth_request), + "passdb didn't return userdb entries, " + "trying the next userdb"); callback(USERDB_RESULT_USER_UNKNOWN, auth_request); return; } - auth_request_log_debug(auth_request, AUTH_SUBSYS_DB, "success"); + e_debug(authdb_event(auth_request), "success"); callback(USERDB_RESULT_OK, auth_request); } diff --git a/src/auth/userdb-sql.c b/src/auth/userdb-sql.c index d4ae899142..c69832a629 100644 --- a/src/auth/userdb-sql.c +++ b/src/auth/userdb-sql.c @@ -65,11 +65,11 @@ static void sql_query_callback(struct sql_result *sql_result, db_sql_success(module->conn); if (ret < 0) { if (!module->conn->default_user_query) { - auth_request_log_error(auth_request, AUTH_SUBSYS_DB, + e_error(authdb_event(auth_request), "User query failed: %s", sql_result_get_error(sql_result)); } else { - auth_request_log_error(auth_request, AUTH_SUBSYS_DB, + e_error(authdb_event(auth_request), "User query failed: %s " "(using built-in default user_query: %s)", sql_result_get_error(sql_result), @@ -110,7 +110,7 @@ static void userdb_sql_lookup(struct auth_request *auth_request, if (t_auth_request_var_expand(module->conn->set.user_query, auth_request, userdb_sql_escape, &query, &error) <= 0) { - auth_request_log_error(auth_request, AUTH_SUBSYS_DB, + e_error(authdb_event(auth_request), "Failed to expand user_query=%s: %s", module->conn->set.user_query, error); callback(USERDB_RESULT_INTERNAL_FAILURE, auth_request); @@ -122,7 +122,7 @@ static void userdb_sql_lookup(struct auth_request *auth_request, sql_request->callback = callback; sql_request->auth_request = auth_request; - auth_request_log_debug(auth_request, AUTH_SUBSYS_DB, "%s", query); + e_debug(authdb_event(auth_request), "%s", query); sql_query(module->conn->db, query, sql_query_callback, sql_request); @@ -153,7 +153,7 @@ userdb_sql_iterate_init(struct auth_request *auth_request, if (t_auth_request_var_expand(module->conn->set.iterate_query, auth_request, userdb_sql_escape, &query, &error) <= 0) { - auth_request_log_error(auth_request, AUTH_SUBSYS_DB, + e_error(authdb_event(auth_request), "Failed to expand iterate_query=%s: %s", module->conn->set.iterate_query, error); } @@ -166,7 +166,7 @@ userdb_sql_iterate_init(struct auth_request *auth_request, sql_query(module->conn->db, query, sql_iter_query_callback, ctx); - auth_request_log_debug(auth_request, AUTH_SUBSYS_DB, "%s", query); + e_debug(authdb_event(auth_request), "%s", query); return &ctx->ctx; } diff --git a/src/auth/userdb-static.c b/src/auth/userdb-static.c index 48f41ec16e..599d566f4d 100644 --- a/src/auth/userdb-static.c +++ b/src/auth/userdb-static.c @@ -30,8 +30,8 @@ static void static_lookup_real(struct auth_request *auth_request, const char *error; if (userdb_template_export(module->tmpl, auth_request, &error) < 0) { - auth_request_log_error(auth_request, AUTH_SUBSYS_DB, - "Failed to expand template: %s", error); + e_error(authdb_event(auth_request), + "Failed to expand template: %s", error); callback(USERDB_RESULT_INTERNAL_FAILURE, auth_request); } callback(USERDB_RESULT_OK, auth_request); @@ -61,7 +61,7 @@ static_credentials_callback(enum passdb_result result, ctx->callback(USERDB_RESULT_USER_UNKNOWN, auth_request); break; case PASSDB_RESULT_SCHEME_NOT_AVAILABLE: - auth_request_log_error(auth_request, AUTH_SUBSYS_DB, + e_error(authdb_event(auth_request), "passdb doesn't support lookups, " "can't verify user's existence"); /* fall through */ diff --git a/src/auth/userdb-vpopmail.c b/src/auth/userdb-vpopmail.c index 4291a1049c..fd6b670ff2 100644 --- a/src/auth/userdb-vpopmail.c +++ b/src/auth/userdb-vpopmail.c @@ -31,14 +31,14 @@ struct vqpasswd *vpopmail_lookup_vqp(struct auth_request *request, if (parse_email(request->user, vpop_user, vpop_domain, VPOPMAIL_LIMIT-1) < 0) { - auth_request_log_info(request, AUTH_SUBSYS_DB, - "parse_email() failed"); + e_info(authdb_event(request), + "parse_email() failed"); return NULL; } - auth_request_log_debug(request, AUTH_SUBSYS_DB, - "lookup user=%s domain=%s", - vpop_user, vpop_domain); + e_debug(authdb_event(request), + "lookup user=%s domain=%s", + vpop_user, vpop_domain); vpw = vauth_getpw(vpop_user, vpop_domain); if (vpw == NULL) { @@ -97,8 +97,8 @@ static void vpopmail_lookup(struct auth_request *auth_request, /* we have to get uid/gid separately, because the gid field in struct vqpasswd isn't really gid at all but just some flags... */ if (vget_assign(vpop_domain, NULL, 0, &uid, &gid) == NULL) { - auth_request_log_info(auth_request, AUTH_SUBSYS_DB, - "vget_assign(%s) failed", vpop_domain); + e_info(authdb_event(auth_request), + "vget_assign(%s) failed", vpop_domain); callback(USERDB_RESULT_INTERNAL_FAILURE, auth_request); return; } @@ -111,13 +111,13 @@ static void vpopmail_lookup(struct auth_request *auth_request, if (vpw->pw_dir == NULL || vpw->pw_dir[0] == '\0') { /* user's homedir doesn't exist yet, create it */ - auth_request_log_info(auth_request, AUTH_SUBSYS_DB, - "pw_dir isn't set, creating"); + e_info(authdb_event(auth_request), + "pw_dir isn't set, creating"); if (make_user_dir(vpop_user, vpop_domain, uid, gid) == NULL) { - auth_request_log_error(auth_request, AUTH_SUBSYS_DB, - "make_user_dir(%s, %s) failed", - vpop_user, vpop_domain); + e_error(authdb_event(auth_request), + "make_user_dir(%s, %s) failed", + vpop_user, vpop_domain); callback(USERDB_RESULT_INTERNAL_FAILURE, auth_request); return; } @@ -132,10 +132,10 @@ static void vpopmail_lookup(struct auth_request *auth_request, if (userdb_vpopmail_get_quota(module->quota_template_value, vpw->pw_shell, "a, &error) < 0) { - auth_request_log_error(auth_request, AUTH_SUBSYS_DB, - "userdb_vpopmail_get_quota(%s, %s) failed: %s", - module->quota_template_value, - vpw->pw_shell, error); + e_error(authdb_event(auth_request), + "userdb_vpopmail_get_quota(%s, %s) failed: %s", + module->quota_template_value, + vpw->pw_shell, error); callback(USERDB_RESULT_INTERNAL_FAILURE, auth_request); return; } diff --git a/src/auth/userdb.c b/src/auth/userdb.c index df2a0b763d..aa11025e86 100644 --- a/src/auth/userdb.c +++ b/src/auth/userdb.c @@ -73,8 +73,8 @@ uid_t userdb_parse_uid(struct auth_request *request, const char *str) return (uid_t)-1; case 0: if (request != NULL) { - auth_request_log_error(request, AUTH_SUBSYS_DB, - "Invalid UID value '%s'", str); + e_error(authdb_event(request), + "Invalid UID value '%s'", str); } return (uid_t)-1; default: @@ -99,8 +99,8 @@ gid_t userdb_parse_gid(struct auth_request *request, const char *str) return (gid_t)-1; case 0: if (request != NULL) { - auth_request_log_error(request, AUTH_SUBSYS_DB, - "Invalid GID value '%s'", str); + e_error(authdb_event(request), + "Invalid GID value '%s'", str); } return (gid_t)-1; default: