log_result(Slapi_PBlock *pb, Operation *op, int err, ber_tag_t tag, int nentries)
{
    char *notes_str = NULL;
    char notes_buf[256] = {0};
    int internal_op;
    CSN *operationcsn = NULL;
    char csn_str[CSN_STRSIZE + 5];
    char etime[ETIME_BUFSIZ] = {0};
    char wtime[ETIME_BUFSIZ] = {0};
    char optime[ETIME_BUFSIZ] = {0};
    int pr_idx = -1;
    int pr_cookie = -1;
    uint32_t operation_notes;
    uint64_t connid;
    int32_t op_id;
    int32_t op_internal_id;
    int32_t op_nested_count;
    struct timespec o_hr_time_end;

    get_internal_conn_op(&connid, &op_id, &op_internal_id, &op_nested_count);
    slapi_pblock_get(pb, SLAPI_PAGED_RESULTS_INDEX, &pr_idx);
    slapi_pblock_get(pb, SLAPI_PAGED_RESULTS_COOKIE, &pr_cookie);
    internal_op = operation_is_flag_set(op, OP_FLAG_INTERNAL);

    /* total elapsed time */
    slapi_operation_time_elapsed(op, &o_hr_time_end);
    snprintf(etime, ETIME_BUFSIZ, "%" PRId64 ".%.09" PRId64 "", (int64_t)o_hr_time_end.tv_sec, (int64_t)o_hr_time_end.tv_nsec);

    /* wait time */
    slapi_operation_workq_time_elapsed(op, &o_hr_time_end);
    snprintf(wtime, ETIME_BUFSIZ, "%" PRId64 ".%.09" PRId64 "", (int64_t)o_hr_time_end.tv_sec, (int64_t)o_hr_time_end.tv_nsec);

    /* op time */
    slapi_operation_op_time_elapsed(op, &o_hr_time_end);
    snprintf(optime, ETIME_BUFSIZ, "%" PRId64 ".%.09" PRId64 "", (int64_t)o_hr_time_end.tv_sec, (int64_t)o_hr_time_end.tv_nsec);



    operation_notes = slapi_pblock_get_operation_notes(pb);

    if (0 == operation_notes) {
        notes_str = "";
    } else {
        notes_str = notes_buf;
        *notes_buf = ' ';
        notes2str(operation_notes, notes_buf + 1, sizeof(notes_buf) - 1);
    }

    csn_str[0] = '\0';
    if (config_get_csnlogging() == LDAP_ON) {
        operationcsn = operation_get_csn(op);
        if (NULL != operationcsn) {
            char tmp_csn_str[CSN_STRSIZE];
            sprintf(csn_str, " csn=%s", csn_as_string(operationcsn, PR_FALSE, tmp_csn_str));
        }
    }

#define LOG_CONN_OP_FMT_INT_INT "conn=Internal(%" PRIu64 ") op=%d(%d)(%d) RESULT err=%d"
#define LOG_CONN_OP_FMT_EXT_INT "conn=%" PRIu64 " (Internal) op=%d(%d)(%d) RESULT err=%d"
    if (op->o_tag == LDAP_REQ_BIND && err == LDAP_SASL_BIND_IN_PROGRESS) {
        /*
         * Not actually an error.
         * Make that clear in the log.
         */
        if (!internal_op) {
            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"
                             ", SASL bind in progress\n",
                             op->o_connid,
                             op->o_opid,
                             err, tag, nentries,
                             wtime, optime, etime,
                             notes_str, csn_str);
        } else {

#define LOG_SASLMSG_FMT " tag=%" BERTAG_T " nentries=%d wtime=%s optime=%s etime=%s%s%s, SASL bind in progress\n"
            slapi_log_access(LDAP_DEBUG_ARGS,
                             connid == 0 ? LOG_CONN_OP_FMT_INT_INT LOG_SASLMSG_FMT :
                                           LOG_CONN_OP_FMT_EXT_INT LOG_SASLMSG_FMT,
                             connid,
                             op_id,
                             op_internal_id,
                             op_nested_count,
                             err, tag, nentries,
                             wtime, optime, etime,
                             notes_str, csn_str);
        }
    } else if (op->o_tag == LDAP_REQ_BIND && err == LDAP_SUCCESS) {
        char *dn = NULL;

        /*
         * For methods other than simple, the dn in the bind request
         * may be irrelevant. Log the actual authenticated dn.
         */
        slapi_pblock_get(pb, SLAPI_CONN_DN, &dn);
        if (!internal_op) {
            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"
                             " dn=\"%s\"\n",
                             op->o_connid,
                             op->o_opid,
                             err, tag, nentries,
                             wtime, optime, etime,
                             notes_str, csn_str, dn ? dn : "");
        } else {
#define LOG_BINDMSG_FMT " tag=%" BERTAG_T " nentries=%d wtime=%s optime=%s etime=%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, dn ? dn : "");
        }
        slapi_ch_free((void **)&dn);
    } else {
        if (pr_idx > -1) {
            if (!internal_op) {
                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"
                                 " pr_idx=%d pr_cookie=%d\n",
                                 op->o_connid,
                                 op->o_opid,
                                 err, tag, nentries,
                                 wtime, optime, etime,
                                 notes_str, csn_str, pr_idx, pr_cookie);
            } else {
#define LOG_PRMSG_FMT " tag=%" BERTAG_T " nentries=%d wtime=%s optime=%s etime=%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, pr_idx, pr_cookie);
            }
        } else if (!internal_op) {
            char *pbtxt = NULL;
            char *ext_str = NULL;
            slapi_pblock_get(pb, SLAPI_PB_RESULT_TEXT, &pbtxt);
            if (pbtxt) {
                ext_str = slapi_ch_smprintf(" - %s", pbtxt);
            } else {
                ext_str = "";
            }
            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\n",
                             op->o_connid,
                             op->o_opid,
                             err, tag, nentries,
                             wtime, optime, etime,
                             notes_str, csn_str, ext_str);
            if (pbtxt) {
                /* if !pbtxt ==> ext_str == "".  Don't free ext_str. */
                slapi_ch_free_string(&ext_str);
            }
        } else {
            int optype;
#define LOG_MSG_FMT " tag=%" BERTAG_T " nentries=%d wtime=%s optime=%s etime=%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);
            /*
             *  If this is an unindexed search we should log it in the error log if
             *  we didn't log it in the access log.
             */
            slapi_pblock_get(pb, SLAPI_OPERATION_TYPE, &optype);
            if (optype == SLAPI_OPERATION_SEARCH &&                  /* search, */
                strcmp(notes_str, "") &&                             /* that's unindexed, */
                !(config_get_accesslog_level() & LDAP_DEBUG_ARGS) && /* and not logged in access log */
                !(op->o_flags & SLAPI_OP_FLAG_IGNORE_UNINDEXED))     /* and not ignoring unindexed search */
            {
                struct slapdplugin *plugin = NULL;
                struct slapi_componentid *cid = NULL;
                char *filter_str;
                char *plugin_dn;
                char *base_dn;

                slapi_pblock_get(pb, SLAPI_SEARCH_STRFILTER, &filter_str);
                slapi_pblock_get(pb, SLAPI_TARGET_DN, &base_dn);
                slapi_pblock_get(pb, SLAPI_PLUGIN_IDENTITY, &cid);
                if (cid) {
                    plugin = (struct slapdplugin *)cid->sci_plugin;
                } else {
                    slapi_pblock_get(pb, SLAPI_PLUGIN, &plugin);
                }
                plugin_dn = plugin_get_dn(plugin);

                slapi_log_err(SLAPI_LOG_ERR, "log_result", "Internal unindexed search: source (%s) "
                                                           "search base=\"%s\" filter=\"%s\" etime=%s nentries=%d %s\n",
                              plugin_dn, base_dn, filter_str, etime, nentries, notes_str);

                slapi_ch_free_string(&plugin_dn);
            }
        }
    }
}
log_result(Slapi_PBlock *pb, Operation *op, int err, ber_tag_t tag, int nentries)
{
    char *notes_str = NULL;
    char notes_buf[256] = {0};
    int internal_op;
    CSN *operationcsn = NULL;
    char csn_str[CSN_STRSIZE + 5];
    char etime[ETIME_BUFSIZ] = {0};
    char wtime[ETIME_BUFSIZ] = {0};
    char optime[ETIME_BUFSIZ] = {0};
    int pr_idx = -1;
    int pr_cookie = -1;
    uint32_t operation_notes;
    uint64_t connid;
    int32_t op_id;
    int32_t op_internal_id;
    int32_t op_nested_count;
    struct timespec o_hr_time_end;

    get_internal_conn_op(&connid, &op_id, &op_internal_id, &op_nested_count);
    slapi_pblock_get(pb, SLAPI_PAGED_RESULTS_INDEX, &pr_idx);
    slapi_pblock_get(pb, SLAPI_PAGED_RESULTS_COOKIE, &pr_cookie);
    internal_op = operation_is_flag_set(op, OP_FLAG_INTERNAL);

     
    slapi_operation_time_elapsed(op, &o_hr_time_end);
    snprintf(etime, ETIME_BUFSIZ, "%" PRId64 ".%.09" PRId64 "", (int64_t)o_hr_time_end.tv_sec, (int64_t)o_hr_time_end.tv_nsec);

     
    slapi_operation_workq_time_elapsed(op, &o_hr_time_end);
    snprintf(wtime, ETIME_BUFSIZ, "%" PRId64 ".%.09" PRId64 "", (int64_t)o_hr_time_end.tv_sec, (int64_t)o_hr_time_end.tv_nsec);

     
    slapi_operation_op_time_elapsed(op, &o_hr_time_end);
    snprintf(optime, ETIME_BUFSIZ, "%" PRId64 ".%.09" PRId64 "", (int64_t)o_hr_time_end.tv_sec, (int64_t)o_hr_time_end.tv_nsec);



    operation_notes = slapi_pblock_get_operation_notes(pb);

    if (0 == operation_notes) {
        notes_str = "";
    } else {
        notes_str = notes_buf;
        *notes_buf = ' ';
        notes2str(operation_notes, notes_buf + 1, sizeof(notes_buf) - 1);
    }

    csn_str[0] = '\0';
    if (config_get_csnlogging() == LDAP_ON) {
        operationcsn = operation_get_csn(op);
        if (NULL != operationcsn) {
            char tmp_csn_str[CSN_STRSIZE];
            sprintf(csn_str, " csn=%s", csn_as_string(operationcsn, PR_FALSE, tmp_csn_str));
        }
    }

#define LOG_CONN_OP_FMT_INT_INT "conn=Internal(%" PRIu64 ") op=%d(%d)(%d) RESULT err=%d"
#define LOG_CONN_OP_FMT_EXT_INT "conn=%" PRIu64 " (Internal) op=%d(%d)(%d) RESULT err=%d"
    if (op->o_tag == LDAP_REQ_BIND && err == LDAP_SASL_BIND_IN_PROGRESS) {
         
        if (!internal_op) {
            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"
                             ", SASL bind in progress\n",
                             op->o_connid,
                             op->o_opid,
                             err, tag, nentries,
                             wtime, optime, etime,
                             notes_str, csn_str);
        } else {

#define LOG_SASLMSG_FMT " tag=%" BERTAG_T " nentries=%d wtime=%s optime=%s etime=%s%s%s, SASL bind in progress\n"
            slapi_log_access(LDAP_DEBUG_ARGS,
                             connid == 0 ? LOG_CONN_OP_FMT_INT_INT LOG_SASLMSG_FMT :
                                           LOG_CONN_OP_FMT_EXT_INT LOG_SASLMSG_FMT,
                             connid,
                             op_id,
                             op_internal_id,
                             op_nested_count,
                             err, tag, nentries,
                             wtime, optime, etime,
                             notes_str, csn_str);
        }
    } else if (op->o_tag == LDAP_REQ_BIND && err == LDAP_SUCCESS) {
        char *dn = NULL;

         
        slapi_pblock_get(pb, SLAPI_CONN_DN, &dn);
        if (!internal_op) {
            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"
                             " dn=\"%s\"\n",
                             op->o_connid,
                             op->o_opid,
                             err, tag, nentries,
                             wtime, optime, etime,
                             notes_str, csn_str, dn ? dn : "");
        } else {
#define LOG_BINDMSG_FMT " tag=%" BERTAG_T " nentries=%d wtime=%s optime=%s etime=%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, dn ? dn : "");
        }
        slapi_ch_free((void **)&dn);
    } else {
        if (pr_idx > -1) {
            if (!internal_op) {
                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"
                                 " pr_idx=%d pr_cookie=%d\n",
                                 op->o_connid,
                                 op->o_opid,
                                 err, tag, nentries,
                                 wtime, optime, etime,
                                 notes_str, csn_str, pr_idx, pr_cookie);
            } else {
#define LOG_PRMSG_FMT " tag=%" BERTAG_T " nentries=%d wtime=%s optime=%s etime=%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, pr_idx, pr_cookie);
            }
        } else if (!internal_op) {
            char *pbtxt = NULL;
            char *ext_str = NULL;
            slapi_pblock_get(pb, SLAPI_PB_RESULT_TEXT, &pbtxt);
            if (pbtxt) {
                ext_str = slapi_ch_smprintf(" - %s", pbtxt);
            } else {
                ext_str = "";
            }
            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\n",
                             op->o_connid,
                             op->o_opid,
                             err, tag, nentries,
                             wtime, optime, etime,
                             notes_str, csn_str, ext_str);
            if (pbtxt) {
                 
                slapi_ch_free_string(&ext_str);
            }
        } else {
            int optype;
#define LOG_MSG_FMT " tag=%" BERTAG_T " nentries=%d wtime=%s optime=%s etime=%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);
             
            slapi_pblock_get(pb, SLAPI_OPERATION_TYPE, &optype);
            if (optype == SLAPI_OPERATION_SEARCH &&                   
                strcmp(notes_str, "") &&                              
                !(config_get_accesslog_level() & LDAP_DEBUG_ARGS) &&  
                !(op->o_flags & SLAPI_OP_FLAG_IGNORE_UNINDEXED))      
            {
                struct slapdplugin *plugin = NULL;
                struct slapi_componentid *cid = NULL;
                char *filter_str;
                char *plugin_dn;
                char *base_dn;

                slapi_pblock_get(pb, SLAPI_SEARCH_STRFILTER, &filter_str);
                slapi_pblock_get(pb, SLAPI_TARGET_DN, &base_dn);
                slapi_pblock_get(pb, SLAPI_PLUGIN_IDENTITY, &cid);
                if (cid) {
                    plugin = (struct slapdplugin *)cid->sci_plugin;
                } else {
                    slapi_pblock_get(pb, SLAPI_PLUGIN, &plugin);
                }
                plugin_dn = plugin_get_dn(plugin);

                slapi_log_err(SLAPI_LOG_ERR, "log_result", "Internal unindexed search: source (%s) "
                                                           "search base=\"%s\" filter=\"%s\" etime=%s nentries=%d %s\n",
                              plugin_dn, base_dn, filter_str, etime, nentries, notes_str);

                slapi_ch_free_string(&plugin_dn);
            }
        }
    }
}