Frontend modules left using RDEBUG, module return codes changed to RDEBUG, this should hopefully produce more consistent debug output, and make radiusd -x more useful
ptr[2] = total & 0xff;
ptr[3] = CHBIND_NSID_RADIUS;
- RDEBUG("Sending chbind response: code %i", (int )(ptr[0]));
+ RDEBUG2("Sending chbind response: code %i", (int )(ptr[0]));
log_request_pair_list(L_DBG_LVL_1, request, request->reply->vps, NULL);
/* Encode the chbind attributes into the response */
return EAP_TLS_INVALID;
}
if (!tls_session->info.initialized) {
- RDEBUG("No SSL info available. Waiting for more SSL data");
+ RDEBUG2("No SSL info available. Waiting for more SSL data");
return EAP_TLS_RECORD_SEND;
}
*/
eap_tls_data = (eap_tls_data_t *)this_round->response->type.data;
if (!eap_tls_data) {
- RDEBUG("Invalid EAP-TLS packet; no data");
+ REDEBUG("Invalid EAP-TLS packet; no data");
return EAP_TLS_INVALID;
}
for (map = maps; map != NULL; map = map->next) {
if (tmpl_expand(&attr, attr_buff, sizeof(attr_buff), request, map->rhs, NULL, NULL) < 0) {
- RDEBUG("Expansion of LDAP attribute \"%s\" failed", map->rhs->name);
+ REDEBUG("Expansion of LDAP attribute \"%s\" failed", map->rhs->name);
TALLOC_FREE(ctx);
return -1;
}
*/
if (cluster->remapping) {
in_progress:
- RDEBUG("Cluster remapping in progress, ignoring remap request");
+ RDEBUG2("Cluster remapping in progress, ignoring remap request");
return CLUSTER_OP_IGNORED;
}
now = time(NULL);
if (now == cluster->last_updated) {
too_soon:
- RDEBUG("Cluster was updated less than a second ago, ignoring remap request");
+ RWARN("Cluster was updated less than a second ago, ignoring remap request");
return CLUSTER_OP_IGNORED;
}
if (!fr_cond_assert(*reply)) return REDIS_RCODE_ERROR;
- RDEBUG("[%i] Processing redirect \"%s\"", state->node->id, (*reply)->str);
+ RDEBUG2("[%i] Processing redirect \"%s\"", state->node->id, (*reply)->str);
if (state->redirects++ >= cluster->conf->max_redirects) {
REDEBUG("[%i] Reached max_redirects (%i)", state->node->id, state->redirects);
return REDIS_RCODE_ERROR;
return REDIS_RCODE_ERROR;
}
- RDEBUG("[%i] Redirected from %s:%i to [%i] %s:%i", state->node->id, state->node->name,
- state->node->addr.port, new->id, new->name, new->addr.port);
+ RDEBUG2("[%i] Redirected from %s:%i to [%i] %s:%i", state->node->id, state->node->name,
+ state->node->addr.port, new->id, new->name, new->addr.port);
state->node = new;
*conn = fr_pool_connection_get(state->node->pool, request);
* **Debug levels**
* Level | Debug arguments | Macro(s) enabled | When to use
* -------- | ----------------------- | --------------------- | -----------
- * 1 | ``-x`` | R*DEBUG | Never - Deprecated
- * 2 | ``-xx`` or ``-X`` | R*DEBUG, R*DEBUG2 | Normal request flow. Operations, Results of queries, or execs, etc...
+ * 1 | ``-x`` | R*DEBUG | Packet processing, entering/exiting virtual servers, results of module calls
+ * 2 | ``-xx`` or ``-X`` | R*DEBUG, R*DEBUG2 | Unlang keyword evaluation. Module debug output, results of queries, or execs, etc...
* 3 | ``-xxx`` or ``-Xx`` | R*DEBUG, R*DEBUG[2-3] | Internal server state or packet input. State machine changes, extra attribute info, etc...
* 4 | ``-xxxx`` or ``-Xxx`` | R*DEBUG, R*DEBUG[2-4] | Verbose internal server state messages or packet input. Hex dumps, structure dumps, pointer values.
* 5 | ``-xxxxx`` or ``-Xxxx`` | R*DEBUG, R*DEBUG[2-5] | Low level internal server state messages.
#ifdef DEBUG_MAP
static void map_dump(REQUEST *request, vp_map_t const *map)
{
- RDEBUG(">>> MAP TYPES LHS: %s, RHS: %s",
- fr_int2str(tmpl_type_table, map->lhs->type, "???"),
- fr_int2str(tmpl_type_table, map->rhs->type, "???"));
+ RDEBUG2(">>> MAP TYPES LHS: %s, RHS: %s",
+ fr_int2str(tmpl_type_table, map->lhs->type, "???"),
+ fr_int2str(tmpl_type_table, map->rhs->type, "???"));
if (map->rhs) {
- RDEBUG(">>> MAP NAMES %s %s", map->lhs->name, map->rhs->name);
+ RDEBUG2(">>> MAP NAMES %s %s", map->lhs->name, map->rhs->name);
}
}
#endif
* If it's an exec, ignore the list
*/
if (map->rhs->type == TMPL_TYPE_EXEC) {
- RDEBUG("%s %s %s%pV%s", mod->lhs->name, fr_int2str(fr_tokens_table, mod->op, "<INVALID>"),
- quote, vb, quote);
+ RDEBUG2("%s %s %s%pV%s", mod->lhs->name, fr_int2str(fr_tokens_table, mod->op, "<INVALID>"),
+ quote, vb, quote);
return;
}
switch (map->lhs->type) {
case TMPL_TYPE_ATTR:
case TMPL_TYPE_LIST:
- RDEBUG("%s %s %s", map->lhs->name, fr_int2str(fr_tokens_table, mod->op, "<INVALID>"), rhs);
+ RDEBUG2("%s %s %s", map->lhs->name, fr_int2str(fr_tokens_table, mod->op, "<INVALID>"), rhs);
break;
default:
*/
if (vp) {
tmpl_snprint(buffer, sizeof(buffer), map->lhs);
- RDEBUG("%s%s %s %s", buffer, vp->da->name, fr_int2str(fr_tokens_table, vp->op, "<INVALID>"), rhs);
+ RDEBUG2("%s%s %s %s", buffer, vp->da->name, fr_int2str(fr_tokens_table, vp->op, "<INVALID>"), rhs);
break;
}
/* FALL-THROUGH */
case TMPL_TYPE_ATTR:
tmpl_snprint(buffer, sizeof(buffer), map->lhs);
- RDEBUG("%s %s %s", buffer, fr_int2str(fr_tokens_table, vp ? vp->op : map->op, "<INVALID>"), rhs);
+ RDEBUG2("%s %s %s", buffer, fr_int2str(fr_tokens_table, vp ? vp->op : map->op, "<INVALID>"), rhs);
break;
default:
case 0:
fr_value_box_copy(vp, &vp->data, enumv->value);
vp->data.enumv = vp->da; /* So we get the correct string alias */
- RDEBUG("Setting &control:%pP", vp);
+ RDEBUG2("Setting &control:%pP", vp);
return true;
case 1:
while (isspace((int) *p)) p++;
if (*p != '&') {
- RDEBUG("First argument must be an attribute reference");
+ REDEBUG("First argument must be an attribute reference");
return 0;
}
pad_len = strtoul(p, &end, 10);
if ((pad_len == ULONG_MAX) || (pad_len > 8192)) {
talloc_free(vpt);
- RDEBUG("Invalid pad_len found at: %s", p);
+ REDEBUG("Invalid pad_len found at: %s", p);
return fmt - p;
}
if (*p) {
if (!isspace(*p)) {
talloc_free(vpt);
- RDEBUG("Invalid text found at: %s", p);
+ REDEBUG("Invalid text found at: %s", p);
return fmt - p;
}
if (p[1] != '\0') {
talloc_free(vpt);
- RDEBUG("Invalid text found at: %s", p);
+ REDEBUG("Invalid text found at: %s", p);
return fmt - p;
}
*/
case 1:
if (data_len < 18) {
- RDEBUG("insufficient data for MS-Machine-Inventory-Packet");
+ RDEBUG2("insufficient data for MS-Machine-Inventory-Packet");
return 0;
}
data_len -= 18;
break;
default:
- RDEBUG("SoH Unknown MS TV %i stopping", c);
+ RDEBUG2("SoH Unknown MS TV %i stopping", c);
return 0;
}
}
hdr.tlv_vendor = soh_pull_be_32(data); data += 4;
if (hdr.tlv_type != 7 || hdr.tlv_vendor != 0x137) {
- RDEBUG("SoH payload is %i %08x not a ms-vendor packet", hdr.tlv_type, hdr.tlv_vendor);
+ RDEBUG2("SoH payload is %i %08x not a ms-vendor packet", hdr.tlv_type, hdr.tlv_vendor);
return -1;
}
hdr.soh_type = soh_pull_be_16(data); data += 2;
hdr.soh_len = soh_pull_be_16(data); data += 2;
if (hdr.soh_type != 1) {
- RDEBUG("SoH tlv %04x is not a response", hdr.soh_type);
+ RDEBUG2("SoH tlv %04x is not a response", hdr.soh_type);
return -1;
}
if ((resp.outer_type != 7) || (resp.vendor != 0x137)) {
- RDEBUG("SoH response outer type %i/vendor %08x not recognised", resp.outer_type, resp.vendor);
+ RDEBUG2("SoH response outer type %i/vendor %08x not recognised", resp.outer_type, resp.vendor);
return -1;
}
switch (resp.inner_type) {
case 1:
/* no mode sub-header */
- RDEBUG("SoH without mode subheader");
+ RDEBUG2("SoH without mode subheader");
break;
case 2:
break;
default:
- RDEBUG("SoH invalid inner type %i", resp.inner_type);
+ RDEBUG2("SoH invalid inner type %i", resp.inner_type);
return -1;
}
break;
default:
- RDEBUG("SoH Unknown TLV %i len=%i", tlv.tlv_type, tlv.tlv_len);
+ RDEBUG2("SoH Unknown TLV %i len=%i", tlv.tlv_type, tlv.tlv_len);
break;
}
uint8_t *buff, *p;
if (!resp) {
- RDEBUG("No response available");
+ REDEBUG("No OCSP response available");
return -1;
}
#endif
fd = mkstemp(filename);
if (fd < 0) {
- RDEBUG("Failed creating file in %s: %s",
- conf->verify_tmp_dir, fr_syserror(errno));
+ RDEBUG2("Failed creating file in %s: %s",
+ conf->verify_tmp_dir, fr_syserror(errno));
break;
}
fp = fdopen(fd, "w");
if (!fp) {
close(fd);
- RDEBUG("Failed opening file \"%s\": %s", filename, fr_syserror(errno));
+ REDEBUG("Failed opening file \"%s\": %s", filename, fr_syserror(errno));
break;
}
if (!PEM_write_X509(fp, cert)) {
fclose(fp);
- RDEBUG("Failed writing certificate to file");
+ REDEBUG("Failed writing certificate to file");
goto do_unlink;
}
fclose(fp);
REDEBUG("Client certificate CN \"%s\" failed external verification", common_name);
my_ok = 0;
} else {
- RDEBUG("Client certificate CN \"%s\" passed external validation", common_name);
+ RDEBUG2("Client certificate CN \"%s\" passed external validation", common_name);
}
do_unlink:
{
RINDENT();
if (!instruction) {
- RDEBUG("instruction = NULL");
+ RDEBUG2("instruction = NULL");
REXDENT();
return;
}
- RDEBUG("type %s", unlang_ops[instruction->type].name);
- RDEBUG("name %s", instruction->name);
- RDEBUG("debug_name %s", instruction->debug_name);
+ RDEBUG2("type %s", unlang_ops[instruction->type].name);
+ RDEBUG2("name %s", instruction->name);
+ RDEBUG2("debug_name %s", instruction->debug_name);
REXDENT();
}
RINDENT();
if (frame->next) {
- RDEBUG("next %s", frame->next->debug_name);
+ RDEBUG2("next %s", frame->next->debug_name);
} else {
- RDEBUG("next <none>");
+ RDEBUG2("next <none>");
}
- RDEBUG("top_frame %s", frame->top_frame ? "yes" : "no");
- RDEBUG("result %s", fr_int2str(mod_rcode_table, frame->result, "<invalid>"));
- RDEBUG("priority %d", frame->priority);
- RDEBUG("unwind %d", frame->unwind);
- RDEBUG("repeat %s", frame->repeat ? "yes" : "no");
+ RDEBUG2("top_frame %s", frame->top_frame ? "yes" : "no");
+ RDEBUG2("result %s", fr_int2str(mod_rcode_table, frame->result, "<invalid>"));
+ RDEBUG2("priority %d", frame->priority);
+ RDEBUG2("unwind %d", frame->unwind);
+ RDEBUG2("repeat %s", frame->repeat ? "yes" : "no");
REXDENT();
}
int i;
unlang_stack_t *stack = request->stack;
- RDEBUG("----- Begin stack debug [depth %i] -----", stack->depth);
+ RDEBUG2("----- Begin stack debug [depth %i] -----", stack->depth);
for (i = stack->depth; i >= 0; i--) {
unlang_stack_frame_t *frame = &stack->frame[i];
- RDEBUG("[%d] Frame contents", i);
+ RDEBUG2("[%d] Frame contents", i);
unlang_dump_frame(request, frame);
}
- RDEBUG("----- End stack debug [depth %i] -------", stack->depth);
+ RDEBUG2("----- End stack debug [depth %i] -------", stack->depth);
}
#define DUMP_STACK if (DEBUG_ENABLED5) unlang_dump_stack(request)
#else
request->rcode = *presult;
done:
- RDEBUG2("%s (%s)", instruction->name ? instruction->name : "",
- fr_int2str(mod_rcode_table, *presult, "<invalid>"));
+ /*
+ * Must be left at RDEBUG() level otherwise RDEBUG becomes pointless
+ */
+ RDEBUG("%s (%s)", instruction->name ? instruction->name : "",
+ fr_int2str(mod_rcode_table, *presult, "<invalid>"));
switch (*presult) {
case RLM_MODULE_YIELD:
* on the caller to look at request->reply->code.
*/
if (final == FR_IO_YIELD) {
- RDEBUG("Noo yield for you!");
+ RDEBUG2("Noo yield for you!");
}
/*
* Run this entry.
*/
case CHILD_RUNNABLE:
- RDEBUG("parallel - running entry %d/%d", i + 1, state->num_children);
+ RDEBUG2("parallel - running entry %d/%d", i + 1, state->num_children);
result = unlang_run(state->children[i].child);
if (result == RLM_MODULE_YIELD) {
state->children[i].state = CHILD_YIELDED;
* parallel section".
*/
if (priority == MOD_ACTION_RETURN) {
- RDEBUG("child %d/%d says 'return' - skipping the remaining children",
- i + 1, state->num_children);
+ RDEBUG2("child %d/%d says 'return' - skipping the remaining children",
+ i + 1, state->num_children);
/*
* Fall through to processing the
unlang_xlat_push(pool, &state->result, request, mx->exp, false);
return UNLANG_ACTION_PUSHED_CHILD;
} else {
- RDEBUG("`%s`", mx->xlat_name);
+ RDEBUG2("`%s`", mx->xlat_name);
radius_exec_program(request, NULL, 0, NULL, request, mx->xlat_name, request->packet->vps,
false, true, EXEC_TIMEOUT);
return UNLANG_ACTION_CONTINUE;
*/
request->dict = dict_dhcpv4;
- if (DEBUG_ENABLED3) {
- RDEBUG("proto_dhcpv4 decode packet");
- fr_dhcpv4_print_hex(fr_log_fp, data, data_len);
- }
+ RHEXDUMP(L_DBG_LVL_3, data, data_len, "proto_dhcpv4 decode packet");
client = address->radclient;
return -1;
}
- if (DEBUG_ENABLED3) {
- RDEBUG("proto_dhcpv4 encode packet");
- fr_dhcpv4_print_hex(fr_log_fp, buffer, data_len);
- }
+ RHEXDUMP(L_DBG_LVL_3, buffer, data_len, "proto_dhcpv4 encode packet");
request->reply->data_len = data_len;
return data_len;
rad_assert(data[0] < FR_MAX_PACKET_CODE);
- if (DEBUG_ENABLED3) {
- RDEBUG("proto_vmps decode packet");
- fr_vmps_print_hex(fr_log_fp, data, data_len);
- }
+ RHEXDUMP(L_DBG_LVL_3, data, data_len, "proto_vmps decode packet");
/*
* Set the request dictionary so that we can do
return -1;
}
- if (DEBUG_ENABLED3) {
- RDEBUG("proto_vmps encode packet");
- fr_vmps_print_hex(fr_log_fp, buffer, data_len);
- }
+ RHEXDUMP(L_DBG_LVL_3, buffer, data_len, "proto_vmps encode packet");
return data_len;
}
map_snprint(buffer, sizeof(buffer), map);
REXDENT();
- RDEBUG("Skipping %s", buffer);
+ RDEBUG2("Skipping %s", buffer);
RINDENT();
continue;
}
ret = inst->driver->find(&c, &inst->config, inst->driver_inst->data, request, *handle, key, key_len);
switch (ret) {
case CACHE_RECONNECT:
- RDEBUG("Reconnecting...");
+ RDEBUG2("Reconnecting...");
if (cache_reconnect(handle, inst, request) == 0) continue;
return RLM_MODULE_FAIL;
static rlm_rcode_t cache_expire(rlm_cache_t const *inst, REQUEST *request,
rlm_cache_handle_t **handle, uint8_t const *key, size_t key_len)
{
- RDEBUG("Expiring cache entry");
+ RDEBUG2("Expiring cache entry");
for (;;) switch (inst->driver->expire(&inst->config, inst->driver_inst->data, request,
*handle, key, key_len)) {
case CACHE_RECONNECT:
last = &c->maps;
- RDEBUG("Creating new cache entry");
+ RDEBUG2("Creating new cache entry");
/*
* Alloc a pool so we don't have excessive allocs when
* as if this were an update section.
*/
if (map_to_vp(pool, &to_cache, request, map, NULL) < 0) {
- RDEBUG("Skipping %s", map->rhs->name);
+ RDEBUG2("Skipping %s", map->rhs->name);
continue;
}
return RLM_MODULE_FAIL;
case CACHE_OK:
- RDEBUG("Committed entry, TTL %d seconds", ttl);
+ RDEBUG2("Committed entry, TTL %d seconds", ttl);
cache_free(inst, &c);
return merge ? RLM_MODULE_UPDATED :
RLM_MODULE_OK;
return RLM_MODULE_FAIL;
case CACHE_OK:
- RDEBUG("Updated entry TTL");
+ RDEBUG2("Updated entry TTL");
return RLM_MODULE_OK;
default:
return RLM_MODULE_FAIL;
case CACHE_OK:
- RDEBUG("Updated entry TTL");
+ RDEBUG2("Updated entry TTL");
return RLM_MODULE_OK;
default:
vp = fr_pair_find_by_da(request->packet->vps, attr_chap_challenge, TAG_ANY);
if (!vp) {
- RDEBUG("creating CHAP-Challenge from the request authenticator");
+ RDEBUG2("Creating CHAP-Challenge from the request authenticator");
MEM(vp = fr_pair_afrom_da(request->packet, attr_chap_challenge));
fr_pair_value_memcpy(vp, request->packet->vector, sizeof(request->packet->vector));
return RLM_MODULE_REJECT;
}
- RDEBUG("CHAP user \"%pV\" authenticated successfully", &request->username->data);
+ RDEBUG2("CHAP user \"%pV\" authenticated successfully", &request->username->data);
return RLM_MODULE_OK;
}
client = client_find(NULL, &ip, IPPROTO_IP);
if (!client) {
RDEBUG("No client found with IP \"%s\"", client_str);
- return 0;
+ rcode = RLM_MODULE_NOTFOUND;
+ goto finish;
}
if (client->cs) {
char *field = NULL;
if (tmpl_aexpand(request, &field, request, map->rhs, NULL, NULL) < 0) {
- RDEBUG("Failed expanding RHS at %s", map->lhs->name);
+ REDEBUG("Failed expanding RHS at %s", map->lhs->name);
rcode = RLM_MODULE_FAIL;
talloc_free(field);
break;
*/
if ((request->packet->src_port != 0) || (request->packet->vps != NULL) ||
(request->parent != NULL)) {
- RDEBUG("Improper configuration");
+ REDEBUG("Improper configuration");
return RLM_MODULE_NOOP;
}
if (!request->client || !request->client->cs) {
- RDEBUG("Unknown client definition");
+ REDEBUG("Unknown client definition");
return RLM_MODULE_NOOP;
}
cp = cf_pair_find(request->client->cs, "directory");
if (!cp) {
- RDEBUG("No directory configuration in the client");
+ REDEBUG("No directory configuration in the client");
return RLM_MODULE_NOOP;
}
value = cf_pair_value(cp);
if (!value) {
- RDEBUG("No value given for the directory entry in the client");
+ REDEBUG("No value given for the directory entry in the client");
return RLM_MODULE_NOOP;
}
length = strlen(value);
if (length > (sizeof(buffer) - 256)) {
- RDEBUG("Directory name too long");
+ REDEBUG("Directory name too long");
return RLM_MODULE_NOOP;
}
/* sanity check */
if ((vp = fr_pair_find_by_da(request->packet->vps, attr_acct_status_type, TAG_ANY)) == NULL) {
/* log debug */
- RDEBUG("could not find status type in packet");
+ RDEBUG2("could not find status type in packet");
/* return */
return RLM_MODULE_NOOP;
}
/* acknowledge the request but take no action */
if (status == FR_STATUS_ACCOUNTING_ON || status == FR_STATUS_ACCOUNTING_OFF) {
/* log debug */
- RDEBUG("handling accounting on/off request without action");
+ RDEBUG2("handling accounting on/off request without action");
/* return */
return RLM_MODULE_OK;
}
/* start json document if needed */
if (docfound != 1) {
/* debugging */
- RDEBUG("no existing document found - creating new json document");
+ RDEBUG2("no existing document found - creating new json document");
/* create new json object */
cookie->jobj = json_object_new_object();
/* set 'docType' element for new document */
if (map->rhs->type != TMPL_TYPE_UNPARSED) {
if (tmpl_aexpand(request, &field_name, request, map->rhs, NULL, NULL) < 0) {
REXDENT();
- RDEBUG("Failed expanding RHS at %s", map->lhs->name);
+ REDEBUG("Failed expanding RHS at %s", map->lhs->name);
rcode = RLM_MODULE_FAIL;
goto finish;
}
if (field < 0) {
REXDENT();
- RDEBUG("No such field name %s", map->rhs->name);
+ REDEBUG("No such field name %s", map->rhs->name);
rcode = RLM_MODULE_FAIL;
goto finish;
}
/*
* Check for proper format of the Digest-Attributes
*/
- RDEBUG("Checking for correctly formatted Digest-Attributes");
+ RDEBUG2("Checking for correctly formatted Digest-Attributes");
rad_assert(attr_digest_attributes);
first = fr_cursor_iter_by_da_init(&cursor, &request->packet->vps, attr_digest_attributes);
* The attribute type must be valid
*/
if ((p[0] == 0) || (p[0] > 10)) {
- RDEBUG("Not formatted as Digest-Attributes: subtlv (%u) invalid", (unsigned int) p[0]);
+ RDEBUG2("Not formatted as Digest-Attributes: subtlv (%u) invalid", (unsigned int) p[0]);
return RLM_MODULE_NOOP;
}
* Too short.
*/
if (attr_len < 3) {
- RDEBUG("Not formatted as Digest-Attributes: TLV too short");
+ RDEBUG2("Not formatted as Digest-Attributes: TLV too short");
return RLM_MODULE_NOOP;
}
* Too long.
*/
if (p + attr_len > end) {
- RDEBUG("Not formatted as Digest-Attributes: TLV too long)");
+ RDEBUG2("Not formatted as Digest-Attributes: TLV too long)");
return RLM_MODULE_NOOP;
}
/*
* Convert them to something sane.
*/
- RDEBUG("Digest-Attributes validated, unpacking into interal attributes");
+ RDEBUG2("Digest-Attributes validated, unpacking into interal attributes");
fr_cursor_head(&cursor);
for (i = fr_cursor_head(&cursor);
i;
case FR_EAP_IDENTITY:
eap_session->identity = eap_identity(request, eap_session, eap_packet);
if (!eap_session->identity) {
- RDEBUG("Invalid identity response");
+ REDEBUG("Invalid identity response");
goto error_session;
}
case FR_EAP_INVALID:
case FR_EAP_NOTIFICATION:
case FR_EAP_NAK:
- RDEBUG("Initial EAP method (%u) invalid", eap_packet->data[0]);
+ REDEBUG("Initial EAP method (%u) invalid", eap_packet->data[0]);
goto error_session;
/*
* common choices.
*/
if (nak->data[i] == 0) {
- RDEBUG("Peer NAK'd indicating it is not willing to continue ");
+ REDEBUG("Peer NAK'd indicating it is not willing to continue ");
return FR_EAP_INVALID;
}
continue;
}
- RDEBUG("Found mutually acceptable type %s (%d)", eap_type2name(nak->data[i]), nak->data[i]);
+ RDEBUG2("Found mutually acceptable type %s (%d)", eap_type2name(nak->data[i]), nak->data[i]);
method = nak->data[i];
}
if (memcmp(checkcode->vp_octets, eap_aka_session->checkcode, eap_aka_session->checkcode_len) == 0) {
- RDEBUG("EAP-AKA-Checkcode matches calculated checkcode");
+ RDEBUG2("EAP-AKA-Checkcode matches calculated checkcode");
} else {
REDEBUG("EAP-AKA-Checkcode does not match calculated checkcode");
RHEXDUMP_INLINE(L_DBG_LVL_2, checkcode->vp_octets, checkcode->vp_length, "Received");
{
eap_packet_raw_t eap_packet;
- RDEBUG("Sending EAP-Identity");
+ RDEBUG2("Sending EAP-Identity");
eap_packet.code = FR_EAP_CODE_REQUEST;
eap_packet.id = eap_session->this_round->response->id + 1;
memset(&pac, 0, sizeof(pac));
memset(&opaque_plaintext, 0, sizeof(opaque_plaintext));
- RDEBUG("Sending Tunnel PAC");
+ RDEBUG2("Sending Tunnel PAC");
pac.key.hdr.type = htons(EAP_FAST_TLV_MANDATORY | attr_eap_fast_pac_key->attr);
pac.key.hdr.length = htons(sizeof(pac.key.data));
eap_tlv_crypto_binding_tlv_t binding = {0};
int const len = sizeof(binding) - (&binding.reserved - (uint8_t *)&binding);
- RDEBUG("Sending Cryptobinding");
+ RDEBUG2("Sending Cryptobinding");
binding.tlv_type = htons(EAP_FAST_TLV_MANDATORY | attr_eap_fast_crypto_binding->attr);
binding.length = htons(len);
present |= 1 << attr;
if (num[attr_eap_fast_eap_payload->attr] > 1) {
- RDEBUG("Too many EAP-Payload TLVs");
+ REDEBUG("Too many EAP-Payload TLVs");
unexpected:
for (int i = 0; i < EAP_FAST_TLV_MAX; i++) {
- if (present & (1 << i)) RDEBUG(" - attribute %d is present", i);
+ if (present & (1 << i)) RDEBUG2(" - attribute %d is present", i);
}
eap_fast_send_error(tls_session, EAP_FAST_ERR_UNEXPECTED_TLV);
return 0;
}
if (num[attr_eap_fast_intermediate_result->attr] > 1) {
- RDEBUG("Too many Intermediate-Result TLVs");
+ REDEBUG("Too many Intermediate-Result TLVs");
goto unexpected;
}
} else {
if ((data[0] & 0x80) != 0) {
- RDEBUG("Unknown mandatory TLV %02x", attr);
+ REDEBUG("Unknown mandatory TLV %02x", attr);
goto unexpected;
}
uint16_t status;
if (length < 2) {
- RDEBUG("EAP-FAST TLV %u is too short. Expected 2, got %d.", attr, length);
+ REDEBUG("EAP-FAST TLV %u is too short. Expected 2, got %d", attr, length);
return 0;
}
status = ntohs(status);
if (status == EAP_FAST_TLV_RESULT_FAILURE) {
- RDEBUG("EAP-FAST TLV %u indicates failure. Rejecting request.", attr);
+ REDEBUG("EAP-FAST TLV %u indicates failure. Rejecting request", attr);
return 0;
}
if (status != EAP_FAST_TLV_RESULT_SUCCESS) {
- RDEBUG("EAP-FAST TLV %u contains unknown value. Rejecting request.", attr);
+ REDEBUG("EAP-FAST TLV %u contains unknown value. Rejecting request", attr);
goto unexpected;
}
}
* Check if the peer mixed & matched TLVs.
*/
if ((num[attr_eap_fast_nak->attr] > 0) && (num[attr_eap_fast_nak->attr] != total)) {
- RDEBUG("NAK TLV sent with non-NAK TLVs. Rejecting request.");
+ REDEBUG("NAK TLV sent with non-NAK TLVs. Rejecting request");
goto unexpected;
}
if (num[attr_eap_fast_intermediate_result->attr] > 0) {
- RDEBUG("NAK TLV sent with non-NAK TLVs. Rejecting request.");
+ REDEBUG("NAK TLV sent with non-NAK TLVs. Rejecting request");
goto unexpected;
}
switch (t->stage) {
case EAP_FAST_TLS_SESSION_HANDSHAKE:
if (present) {
- RDEBUG("Unexpected TLVs in TLS Session Handshake stage");
+ REDEBUG("Unexpected TLVs in TLS Session Handshake stage");
goto unexpected;
}
break;
case EAP_FAST_AUTHENTICATION:
if (present != (uint32_t)(1 << attr_eap_fast_eap_payload->attr)) {
- RDEBUG("Unexpected TLVs in authentication stage");
+ REDEBUG("Unexpected TLVs in authentication stage");
goto unexpected;
}
break;
? 1 << attr_eap_fast_result->attr
: 1 << attr_eap_fast_intermediate_result->attr;
if (present & ~(bits | (1 << attr_eap_fast_crypto_binding->attr) | (1 << attr_eap_fast_pac_tlv->attr))) {
- RDEBUG("Unexpected TLVs in cryptobind checking stage");
+ REDEBUG("Unexpected TLVs in cryptobind checking stage");
goto unexpected;
}
break;
}
case EAP_FAST_PROVISIONING:
if (present & ~((1 << attr_eap_fast_pac_tlv->attr) | (1 << attr_eap_fast_result->attr))) {
- RDEBUG("Unexpected TLVs in provisioning stage");
+ REDEBUG("Unexpected TLVs in provisioning stage");
goto unexpected;
}
break;
case EAP_FAST_COMPLETE:
if (present) {
- RDEBUG("Unexpected TLVs in complete stage");
+ REDEBUG("Unexpected TLVs in complete stage");
goto unexpected;
}
break;
default:
- RDEBUG("Unexpected stage %d", t->stage);
+ REDEBUG("Unexpected stage %d", t->stage);
return 0;
}
*/
switch (reply->code) {
case FR_CODE_ACCESS_ACCEPT:
- RDEBUG("Got tunneled Access-Accept");
+ RDEBUG2("Got tunneled Access-Accept");
rcode = RLM_MODULE_OK;
break;
case FR_MSCHAP2_SUCCESS:
- RDEBUG("Got %s, tunneling it to the client in a challenge", vp->da->name);
+ RDEBUG2("Got %s, tunneling it to the client in a challenge", vp->da->name);
rcode = RLM_MODULE_HANDLED;
t->authenticated = true;
break;
break;
case FR_CODE_ACCESS_REJECT:
- RDEBUG("Got tunneled Access-Reject");
+ REDEBUG("Got tunneled Access-Reject");
rcode = RLM_MODULE_REJECT;
break;
case FR_CODE_ACCESS_CHALLENGE:
- RDEBUG("Got tunneled Access-Challenge");
+ RDEBUG2("Got tunneled Access-Challenge");
/*
* Copy the EAP-Message back to the tunnel.
break;
default:
- RDEBUG("Unknown RADIUS packet type %d: rejecting tunneled user", reply->code);
+ REDEBUG("Unknown RADIUS packet type %d: rejecting tunneled user", reply->code);
rcode = RLM_MODULE_INVALID;
break;
}
eap_fast_tunnel_t *t;
REQUEST *fake;
- RDEBUG("Processing received EAP Payload");
+ RDEBUG2("Processing received EAP Payload");
/*
* Allocate a fake REQUEST structure.
fake->packet->vps = fr_pair_afrom_da(fake->packet, attr_eap_message);
fr_pair_value_memcpy(fake->packet->vps, tlv_eap_payload->vp_octets, tlv_eap_payload->vp_length);
- RDEBUG("Got tunneled request");
+ RDEBUG2("Got tunneled request");
log_request_pair_list(L_DBG_LVL_1, request, fake->packet->vps, NULL);
/*
t->username->vp_tainted = true;
fr_pair_value_bstrncpy(t->username, vp->vp_octets + 5, vp->vp_length - 5);
- RDEBUG("Got tunneled identity of %pV", &t->username->data);
+ RDEBUG2("Got tunneled identity of %pV", &t->username->data);
} else {
/*
* Don't reject the request outright,
int ret;
eap_tunnel_data_t *tunnel;
- RDEBUG("Tunneled authentication will be proxied to %pV", &vp->data);
+ RDEBUG2("Tunneled authentication will be proxied to %pV", &vp->data);
/*
* Tell the original request that it's going to be proxied.
} else
#endif /* WITH_PROXY */
{
- RDEBUG("No tunneled reply was found, and the request was not proxied: rejecting the user.");
+ REDEBUG("No tunneled reply was found, and the request was not proxied: rejecting the user");
code = FR_CODE_ACCESS_REJECT;
}
break;
}
} else if (vp->da == attr_eap_fast_pac_info_pac_type) {
if (vp->vp_uint32 != PAC_TYPE_TUNNEL) {
- RDEBUG("only able to serve Tunnel PAC's, ignoring request");
+ RDEBUG2("only able to serve Tunnel PAC's, ignoring request");
continue;
}
t->pac.send = true;
t->pac.send = true;
} else {
if (SSL_session_reused(tls_session->ssl)) {
- RDEBUG("Session Resumed from PAC");
+ RDEBUG2("Session Resumed from PAC");
t->mode = EAP_FAST_NORMAL_AUTH;
} else {
RDEBUG2("Using authenticated provisioning");
if (eap_fast_decode_pair(request, &cursor, attr_eap_fast_tlv,
data, data_len, NULL) < 0) return FR_CODE_ACCESS_REJECT;
- RDEBUG("Got Tunneled FAST TLVs");
+ RDEBUG2("Got Tunneled FAST TLVs");
log_request_pair_list(L_DBG_LVL_1, request, fast_vps, NULL);
code = eap_fast_process_tlvs(request, eap_session, tls_session, fast_vps);
fr_pair_list_free(&fast_vps);
eap_fast_append_result(tls_session, code);
if (t->pac.send) {
- RDEBUG("Peer requires new PAC");
+ RDEBUG2("Peer requires new PAC");
eap_fast_send_pac_tunnel(request, tls_session);
code = FR_CODE_ACCESS_CHALLENGE;
break;
if (!t->pac.key) return 0;
- RDEBUG("processing PAC-Opaque");
+ RDEBUG2("processing PAC-Opaque");
eap_fast_session_ticket(tls_session, s, secret, secret_len);
t = talloc_get_type_abort(tls_session->opaque, eap_fast_tunnel_t);
- RDEBUG("PAC provided via ClientHello SessionTicket extension");
+ RDEBUG2("PAC provided via ClientHello SessionTicket extension");
RHEXDUMP(L_DBG_LVL_MAX, data, len, "PAC-Opaque");
if ((ntohs(opaque->hdr.type) & EAP_FAST_TLV_TYPE) != attr_eap_fast_pac_opaque_tlv->attr) {
tls_session = eap_tls_session->tls_session;
if (inst->cipher_list) {
- RDEBUG("Over-riding main cipher list with '%s'", inst->cipher_list);
+ RDEBUG2("Over-riding main cipher list with '%s'", inst->cipher_list);
if (!SSL_set_cipher_list(tls_session->ssl, inst->cipher_list)) {
REDEBUG("Failed over-riding cipher list to '%s'. EAP-FAST will likely not work",
* Stage 2 is handled by initiate()
*/
default:
- RDEBUG("Internal sanity check failed on stage");
+ REDEBUG("Internal sanity check failed on stage");
break;
}
fr_pair_add(&packet->vps, vp);
if (data && data[0] == FR_EAP_NAK) {
- RDEBUG("SoH - client NAKed");
+ REDEBUG("SoH - client NAKed");
return;
}
if (!data || data_len < 8) {
- RDEBUG("SoH - eap payload too short");
+ REDEBUG("SoH - eap payload too short");
return;
}
eap_method_base = *data++;
if (eap_method_base != 254) {
- RDEBUG("SoH - response is not extended EAP: %i", eap_method_base);
+ REDEBUG("SoH - response is not extended EAP: %i", eap_method_base);
return;
}
eap_vendor = soh_pull_be_24(data); data += 3;
if (eap_vendor != 0x137) {
- RDEBUG("SoH - extended eap vendor %08x is not Microsoft", eap_vendor);
+ REDEBUG("SoH - extended eap vendor %08x is not Microsoft", eap_vendor);
return;
}
eap_method = soh_pull_be_32(data); data += 4;
if (eap_method != 0x21) {
- RDEBUG("SoH - response eap type %08x is not EAP-SoH", eap_method);
+ REDEBUG("SoH - response eap type %08x is not EAP-SoH", eap_method);
return;
}
-
rv = soh_verify(request, data, data_len - 8);
- if (rv<0) {
- RDEBUG("SoH - error decoding payload: %s", fr_strerror());
+ if (rv < 0) {
+ REDEBUG("SoH - error decoding payload: %s", fr_strerror());
} else {
vp->vp_uint32 = 1;
}
}
}
- RDEBUG("Unknown TLV %02x", data[10]);
+ RDEBUG2("Unknown TLV %02x", data[10]);
return 0;
}
fr_pair_value_bstrncpy(t->username, data + 1, data_len - 1);
- RDEBUG("Got inner identity \"%pV\"", &t->username->data);
+ RDEBUG2("Got inner identity \"%pV\"", &t->username->data);
if (t->soh) {
t->status = PEAP_STATUS_WAIT_FOR_SOH_RESPONSE;
RDEBUG2("Requesting SoH from client");
if (t->soh_virtual_server) fake->server_cs = virtual_server_find(t->soh_virtual_server);
- RDEBUG("Sending SoH request to server %s",
+ RDEBUG2("Sending SoH request to server %s",
fake->server_cs ? cf_section_name2(fake->server_cs) : "NULL");
rad_virtual_server(fake);
return RLM_MODULE_REJECT;
case PEAP_STATUS_PHASE2_INIT:
- RDEBUG("In state machine in phase2 init?");
+ RDEBUG2("In state machine in phase2 init?");
case PEAP_STATUS_PHASE2:
break;
*/
case EAP_TLS_ESTABLISHED:
if (SSL_session_reused(tls_session->ssl)) {
- RDEBUG("Skipping Phase2 due to session resumption");
+ RDEBUG2("Skipping Phase2 due to session resumption");
goto do_keys;
}
switch (reply->code) {
case FR_CODE_ACCESS_ACCEPT:
{
- RDEBUG("Got tunneled Access-Accept");
+ RDEBUG2("Got tunneled Access-Accept");
fr_cursor_init(&to_tunnel, &tunnel_vps);
rcode = RLM_MODULE_OK;
vp;
vp = fr_cursor_next(&cursor)) {
if (vp->da == attr_ms_chap2_success) {
- RDEBUG("Got MS-CHAP2-Success, tunneling it to the client in a challenge");
+ RDEBUG2("Got MS-CHAP2-Success, tunneling it to the client in a challenge");
rcode = RLM_MODULE_HANDLED;
t->authenticated = true;
break;
case FR_CODE_ACCESS_REJECT:
- RDEBUG("Got tunneled Access-Reject");
+ REDEBUG("Got tunneled Access-Reject");
rcode = RLM_MODULE_REJECT;
break;
* a Reply-Message to the client.
*/
case FR_CODE_ACCESS_CHALLENGE:
- RDEBUG("Got tunneled Access-Challenge");
+ RDEBUG2("Got tunneled Access-Challenge");
fr_cursor_init(&to_tunnel, &tunnel_vps);
break;
default:
- RDEBUG("Unknown RADIUS packet type %d: rejecting tunneled user", reply->code);
+ REDEBUG("Unknown RADIUS packet type %d: rejecting tunneled user", reply->code);
rcode = RLM_MODULE_INVALID;
break;
}
* to the supplicant.
*/
if (tunnel_vps) {
- RDEBUG("Sending tunneled reply attributes");
+ RDEBUG2("Sending tunneled reply attributes");
log_request_pair_list(L_DBG_LVL_2, request, tunnel_vps, NULL);
vp2diameter(request, tls_session, tunnel_vps);
*/
if (data_len == 0) {
if (t->authenticated) {
- RDEBUG("Got ACK, and the user was already authenticated");
+ RDEBUG2("Got ACK, and the user was already authenticated");
code = FR_CODE_ACCESS_ACCEPT;
goto finish;
} /* else no session, no data, die. */
MEM(fr_pair_add_by_da(fake->packet, &vp, &fake->packet->vps, attr_freeradius_proxied_to) >= 0);
fr_pair_value_from_str(vp, "127.0.0.1", sizeof("127.0.0.1"), '\0', false);
- RDEBUG("Got tunneled request");
+ RDEBUG2("Got tunneled request");
log_request_pair_list(L_DBG_LVL_1, request, fake->packet->vps, NULL);
/*
fr_pair_value_bstrncpy(t->username, vp->vp_octets + 5, vp->vp_length - 5);
- RDEBUG("Got tunneled identity of %pV", &t->username->data);
+ RDEBUG2("Got tunneled identity of %pV", &t->username->data);
} else {
/*
* Don't reject the request outright,
FR_CODE chbind_code;
CHBIND_REQ *req = talloc_zero(fake, CHBIND_REQ);
- RDEBUG("received chbind request");
+ RDEBUG2("received chbind request");
req->request = chbind;
if (fake->username) {
req->username = fake->username;
/* encapsulate response here */
if (req->response) {
- RDEBUG("sending chbind response");
+ RDEBUG2("sending chbind response");
fr_pair_add(&fake->reply->vps,
eap_chbind_packet2vp(fake->reply, req->response));
} else {
- RDEBUG("no chbind response");
+ RDEBUG2("no chbind response");
}
/* clean up chbind req */
* Decide what to do with the reply.
*/
if (!fake->reply->code) {
- RDEBUG("No tunneled reply was found for request %" PRIu64 ", and the request was not "
+ RDEBUG2("No tunneled reply was found for request %" PRIu64 ", and the request was not "
"proxied: rejecting the user", request->number);
code = FR_CODE_ACCESS_REJECT;
} else {
*/
vp = fr_pair_find_by_da(request->packet->vps, attr_state, TAG_ANY);
if (vp != NULL) {
- RDEBUG("Found reply to access challenge");
+ RDEBUG2("Found reply to access challenge");
return RLM_MODULE_OK;
}
* The server will take care of sending it to the user.
*/
request->reply->code = FR_CODE_ACCESS_CHALLENGE;
- RDEBUG("Sending Access-Challenge");
+ RDEBUG2("Sending Access-Challenge");
return RLM_MODULE_HANDLED;
}
* This frees up 0, for success where it'd normally be reject.
*/
if (status == 0) {
- RDEBUG("Program executed successfully");
+ RDEBUG2("Program executed successfully");
return RLM_MODULE_OK;
}
return RLM_MODULE_USERLOCK;
}
- RDEBUG("Account will expire at '%pV'", &check_item->data);
+ RDEBUG2("Account will expire at '%pV'", &check_item->data);
left = (uint32_t)(((time_t) check_item->vp_date) - request->packet->timestamp.tv_sec);
/* just update... */
if (vp->vp_uint32 > (uint32_t)left) {
vp->vp_uint32 = (uint32_t)left;
- RDEBUG("&reply:Session-Timeout := %pV", &vp->data);
+ RDEBUG2("&reply:Session-Timeout := %pV", &vp->data);
}
break;
case 0: /* no pre-existing */
vp->vp_uint32 = (uint32_t)left;
- RDEBUG("&reply:Session-Timeout := %pV", &vp->data);
+ RDEBUG2("&reply:Session-Timeout := %pV", &vp->data);
break;
default: /* malloc failure */
if (!get_expression(request, &p, &x, TOKEN_NONE)) return false;
if (*p != ')') {
- RDEBUG("No trailing ')'");
+ REDEBUG("No trailing ')'");
return false;
}
p++;
}
if ((*p < '0') || (*p > '9')) {
- RDEBUG2("Not a number at \"%s\"", p);
+ REDEBUG("Not a number at \"%s\"", p);
return false;
}
case TOKEN_REMAINDER:
if (rhs == 0) {
- RDEBUG("Division by zero!");
+ REDEBUG("Division by zero!");
return false;
}
case TOKEN_LSHIFT:
if (rhs > 62) {
- RDEBUG("Shift must be less than 62 (was %lld)", (long long int) rhs);
+ REDEBUG("Shift must be less than 62 (was %lld)", (long long int) rhs);
return false;
}
case TOKEN_RSHIFT:
if (rhs > 62) {
- RDEBUG("Shift must be less than 62 (was %lld)", (long long int) rhs);
+ REDEBUG("Shift must be less than 62 (was %lld)", (long long int) rhs);
return false;
}
}
if (*p) {
- RDEBUG("Invalid text after expression: %s", p);
+ REDEBUG("Invalid text after expression: %s", p);
return -1;
}
}
krb5_unparse_name(context, *client, &princ_name);
- RDEBUG("Using client principal \"%s\"", princ_name);
+ RDEBUG2("Using client principal \"%s\"", princ_name);
#ifdef HEIMDAL_KRB5
free(princ_name);
#else
return RLM_MODULE_USERLOCK;
case KRB5KDC_ERR_C_PRINCIPAL_UNKNOWN:
- RDEBUG("User not found (%i): %s", ret, rlm_krb5_error(inst, conn->context, ret));
+ RDEBUG2("User not found (%i): %s", ret, rlm_krb5_error(inst, conn->context, ret));
return RLM_MODULE_NOTFOUND;
default:
* Retrieve the TGT from the TGS/KDC and check we can decrypt it.
*/
memcpy(&password, &request->password->vp_strvalue, sizeof(password));
- RDEBUG("Retrieving and decrypting TGT");
+ RDEBUG2("Retrieving and decrypting TGT");
ret = krb5_get_init_creds_password(conn->context, &init_creds, client, password,
NULL, NULL, 0, NULL, inst->gic_options);
if (ret) {
goto cleanup;
}
- RDEBUG("Attempting to authenticate against service principal");
+ RDEBUG2("Attempting to authenticate against service principal");
ret = krb5_verify_init_creds(conn->context, &init_creds, inst->server, conn->keytab, NULL, inst->vic_options);
if (ret) rcode = krb5_process_error(inst, request, conn, ret);
return RLM_MODULE_INVALID;
}
- RDEBUG("Converting group name(s) to group DN(s)");
+ RDEBUG2("Converting group name(s) to group DN(s)");
/*
* It'll probably only save a few ms in network latency, but it means we can send a query
break;
case LDAP_PROC_NO_RESULT:
- RDEBUG("Tried to resolve group name(s) to DNs but got no results");
+ RDEBUG2("Tried to resolve group name(s) to DNs but got no results");
goto finish;
default:
}
fr_ldap_util_normalise_dn(*dn, *dn);
- RDEBUG("Got group DN \"%s\"", *dn);
+ RDEBUG2("Got group DN \"%s\"", *dn);
dn++;
} while((entry = ldap_next_entry((*pconn)->handle, entry)));
return RLM_MODULE_INVALID;
}
- RDEBUG("Resolving group DN \"%s\" to group name", dn);
+ RDEBUG2("Resolving group DN \"%s\" to group name", dn);
status = fr_ldap_search(&result, request, pconn, dn, LDAP_SCOPE_BASE, NULL, attrs, NULL, NULL);
switch (status) {
}
*out = fr_ldap_berval_to_string(request, values[0]);
- RDEBUG("Group DN \"%s\" resolves to name \"%s\"", dn, *out);
+ RDEBUG2("Group DN \"%s\" resolves to name \"%s\"", dn, *out);
finish:
if (result) ldap_msgfree(result);
fr_cursor_init(&list_cursor, list);
- RDEBUG("Adding cacheable user object memberships");
+ RDEBUG2("Adding cacheable user object memberships");
RINDENT();
if (RDEBUG_ENABLED) {
for (vp = fr_cursor_head(&groups_cursor);
vp;
vp = fr_cursor_next(&groups_cursor)) {
- RDEBUG("&control:%s += \"%pV\"", inst->cache_da->name, &vp->data);
+ RDEBUG2("&control:%s += \"%pV\"", inst->cache_da->name, &vp->data);
}
}
fr_pair_value_strcpy(vp, *dn_p);
fr_cursor_append(&list_cursor, vp);
- RDEBUG("&control:%s += \"%pV\"", inst->cache_da->name, &vp->data);
+ RDEBUG2("&control:%s += \"%pV\"", inst->cache_da->name, &vp->data);
ldap_memfree(*dn_p);
}
REXDENT();
goto finish;
}
- RDEBUG("Adding cacheable group object memberships");
+ RDEBUG2("Adding cacheable group object memberships");
do {
if (inst->cacheable_group_dn) {
dn = ldap_get_dn((*pconn)->handle, entry);
fr_pair_value_strcpy(vp, dn);
RINDENT();
- RDEBUG("&control:%pP", vp);
+ RDEBUG2("&control:%pP", vp);
REXDENT();
ldap_memfree(dn);
}
fr_pair_value_bstrncpy(vp, values[0]->bv_val, values[0]->bv_len);
RINDENT();
- RDEBUG("&control:%pP", vp);
+ RDEBUG2("&control:%pP", vp);
REXDENT();
ldap_value_free_len(values);
REXDENT();
switch (status) {
case LDAP_PROC_SUCCESS:
- RDEBUG("User found in group object \"%s\"", base_dn);
+ RDEBUG2("User found in group object \"%s\"", base_dn);
break;
case LDAP_PROC_NO_RESULT:
break;
case LDAP_PROC_NO_RESULT:
- RDEBUG("Can't check membership attributes, user object not found");
+ RDEBUG2("Can't check membership attributes, user object not found");
rcode = RLM_MODULE_NOTFOUND;
values = ldap_get_values_len((*pconn)->handle, entry, inst->userobj_membership_attr);
if (!values) {
- RDEBUG("No group membership attribute(s) found in user object");
+ RDEBUG2("No group membership attribute(s) found in user object");
goto finish;
}
if (!name_is_dn && !value_is_dn) {
if ((check->vp_length == values[i]->bv_len) &&
(memcmp(values[i]->bv_val, check->vp_strvalue, values[i]->bv_len) == 0)) {
- RDEBUG("User found in group \"%s\". Comparison between membership: name, check: name",
+ RDEBUG2("User found in group \"%s\". Comparison between membership: name, check: name",
check->vp_strvalue);
rcode = RLM_MODULE_OK;
if (tolower(values[i]->bv_val[j]) != tolower(check->vp_strvalue[j])) break;
}
if (j == (int)values[i]->bv_len) {
- RDEBUG("User found in group DN \"%s\". "
+ RDEBUG2("User found in group DN \"%s\". "
"Comparison between membership: dn, check: dn", check->vp_strvalue);
rcode = RLM_MODULE_OK;
(memcmp(values[i]->bv_val, resolved, values[i]->bv_len) == 0)) eq = true;
talloc_free(resolved);
if (eq) {
- RDEBUG("User found in group \"%pV\". Comparison between membership: name, check: name "
+ RDEBUG2("User found in group \"%pV\". Comparison between membership: name, check: name "
"(resolved from DN \"%s\")",
fr_box_strvalue_len(values[i]->bv_val, values[i]->bv_len), check->vp_strvalue);
rcode = RLM_MODULE_OK;
(memcmp(check->vp_strvalue, resolved, check->vp_length) == 0)) eq = true;
talloc_free(resolved);
if (eq) {
- RDEBUG("User found in group \"%s\". Comparison between membership: name "
+ RDEBUG2("User found in group \"%s\". Comparison between membership: name "
"(resolved from DN \"%s\"), check: name", check->vp_strvalue, value);
rcode = RLM_MODULE_OK;
values = ldap_get_values_len(conn->handle, entry, ldap_url->lud_attrs[0]);
if (!values) {
- RDEBUG("No \"%s\" attributes found in specified object", ldap_url->lud_attrs[0]);
+ RDEBUG2("No \"%s\" attributes found in specified object", ldap_url->lud_attrs[0]);
goto free_result;
}
rad_assert(inst->groupobj_base_dn);
- RDEBUG("Searching for user in group \"%pV\"", &check->data);
+ RDEBUG2("Searching for user in group \"%pV\"", &check->data);
if (check->vp_length == 0) {
REDEBUG("Cannot do comparison (group name is empty)");
if (conn) mod_conn_release(inst, request, conn);
if (!found) {
- RDEBUG("User is not a member of \"%pV\"", &check->data);
+ RDEBUG2("User is not a member of \"%pV\"", &check->data);
return 1;
}
}
}
- RDEBUG("Login attempt by \"%pV\"", &request->username->data);
+ RDEBUG2("Login attempt by \"%pV\"", &request->username->data);
/*
* Get the DN by doing a search.
switch (status) {
case LDAP_PROC_SUCCESS:
rcode = RLM_MODULE_OK;
- RDEBUG("Bind as user \"%s\" was successful", dn);
+ RDEBUG2("Bind as user \"%s\" was successful", dn);
break;
case LDAP_PROC_NOT_PERMITTED:
case LDAP_PROC_BAD_DN:
case LDAP_PROC_NO_RESULT:
- RDEBUG("Profile object \"%s\" not found", dn);
+ RDEBUG2("Profile object \"%s\" not found", dn);
return RLM_MODULE_NOTFOUND;
default:
goto free_result;
}
- RDEBUG("Processing profile attributes");
+ RDEBUG2("Processing profile attributes");
RINDENT();
if (fr_ldap_map_do(request, *pconn, inst->valuepair_attr, expanded, entry) > 0) rcode = RLM_MODULE_UPDATED;
REXDENT();
switch (status) {
case LDAP_PROC_SUCCESS:
rcode = RLM_MODULE_OK;
- RDEBUG("Bind as user '%s' was successful", dn);
+ RDEBUG2("Bind as user '%s' was successful", dn);
break;
case LDAP_PROC_NOT_PERMITTED:
}
if (inst->user_map || inst->valuepair_attr) {
- RDEBUG("Processing user attributes");
+ RDEBUG2("Processing user attributes");
RINDENT();
if (fr_ldap_map_do(request, conn, inst->valuepair_attr,
&expanded, entry) > 0) rcode = RLM_MODULE_UPDATED;
op = cf_pair_operator(cp);
if (!value || (*value == '\0')) {
- RDEBUG("Empty value string, skipping attribute \"%s\"", attr);
+ RDEBUG2("Empty value string, skipping attribute \"%s\"", attr);
continue;
}
char *exp = NULL;
if (xlat_aeval(request, &exp, request, value, NULL, NULL) <= 0) {
- RDEBUG("Skipping attribute \"%s\"", attr);
+ RDEBUG2("Skipping attribute \"%s\"", attr);
talloc_free(exp);
if (!force) {
vp = fr_pair_find_by_da(request->control, attr_ldap_userdn, TAG_ANY);
if (vp) {
- RDEBUG("Using user DN from request \"%pV\"", &vp->data);
+ RDEBUG2("Using user DN from request \"%pV\"", &vp->data);
*rcode = RLM_MODULE_OK;
return vp->vp_strvalue;
}
}
fr_ldap_util_normalise_dn(dn, dn);
- RDEBUG("User object found at DN \"%s\"", dn);
+ RDEBUG2("User object found at DN \"%s\"", dn);
MEM(pair_update_control(&vp, attr_ldap_userdn) >= 0);
fr_pair_value_strcpy(vp, dn);
if (values) {
if (inst->access_positive) {
if ((values[0]->bv_len >= 5) && (strncasecmp(values[0]->bv_val, "false", 5) == 0)) {
- RDEBUG("\"%s\" attribute exists but is set to 'false' - user locked out",
- inst->userobj_access_attr);
+ REDEBUG("\"%s\" attribute exists but is set to 'false' - user locked out",
+ inst->userobj_access_attr);
rcode = RLM_MODULE_USERLOCK;
}
/* RLM_MODULE_OK set above... */
} else if ((values[0]->bv_len < 5) || (strncasecmp(values[0]->bv_val, "false", 5) != 0)) {
- RDEBUG("\"%s\" attribute exists - user locked out", inst->userobj_access_attr);
+ REDEBUG("\"%s\" attribute exists - user locked out", inst->userobj_access_attr);
rcode = RLM_MODULE_USERLOCK;
}
ldap_value_free_len(values);
} else if (inst->access_positive) {
- RDEBUG("No \"%s\" attribute - user locked out", inst->userobj_access_attr);
+ REDEBUG("No \"%s\" attribute - user locked out", inst->userobj_access_attr);
rcode = RLM_MODULE_USERLOCK;
}
}
if (vector_len == 0) {
- RDEBUG("No data to write");
+ RDEBUG2("No data to write");
rcode = RLM_MODULE_NOOP;
goto finish;
}
/*
* Authentication is OK. Now see if this user may login at this time of the day.
*/
- RDEBUG("Checking Login-Time");
+ RDEBUG2("Checking Login-Time");
/*
* Compare the time the request was received with the current Login-Time value
* There's time left in the users session, inform the NAS by including a Session-vp
* attribute in the reply, or modifying the existing one.
*/
- RDEBUG("Login within allowed time-slot, %d seconds left in this session", left);
+ RDEBUG2("Login within allowed time-slot, %d seconds left in this session", left);
switch (pair_update_reply(&vp, attr_session_timeout)) {
case 1:
/* just update... */
if (vp->vp_uint32 > (uint32_t)left) {
vp->vp_uint32 = (uint32_t)left;
- RDEBUG("&reply:Session-Timeout := %pV", &vp->data);
+ RDEBUG2("&reply:Session-Timeout := %pV", &vp->data);
}
break;
case 0: /* no pre-existing */
vp->vp_uint32 = (uint32_t)left;
- RDEBUG("&reply:Session-Timeout := %pV", &vp->data);
+ RDEBUG2("&reply:Session-Timeout := %pV", &vp->data);
break;
case -1: /* malloc failure */
p = (uint8_t const *) lua_tolstring(L, -1, &len);
if (!p) {
- RDEBUG("Unmarshalling failed: Lua bstring was NULL");
+ REDEBUG("Unmarshalling failed: Lua bstring was NULL");
return -1;
}
fr_pair_value_memcpy(vp, p, len);
while ((q = strchr(field, '.'))) {
if ((size_t) (p - q) >= sizeof(buffer)) {
- RDEBUG("Field name too long, maximum is %zu", sizeof(buffer));
+ REDEBUG("Field name too long, maximum is %zu", sizeof(buffer));
return -1;
}
lua_getfield(L, -1, buffer);
}
if (lua_isnil(L, -1)) {
- RDEBUG("Field '%s' does not exist", p);
+ REDEBUG("Field '%s' does not exist", p);
return -1;
}
}
fr_bin2hex(*out, buffer, NT_DIGEST_LENGTH);
(*out)[32] = '\0';
- RDEBUG("NT-Hash of \"known-good\" password: %s", *out);
+ RDEBUG2("NT-Hash of \"known-good\" password: %s", *out);
return 32;
/*
smbdes_lmpwdhash(p, buffer);
fr_bin2hex(*out, buffer, LM_DIGEST_LENGTH);
(*out)[32] = '\0';
- RDEBUG("LM-Hash of %s = %s", p, *out);
+ RDEBUG2("LM-Hash of %s = %s", p, *out);
return 32;
} else {
REDEBUG("Unknown expansion string '%s'", fmt);
char *pmsg;
char const *emsg;
- RDEBUG("Doing MS-CHAPv2 password change via ntlm_auth helper");
+ RDEBUG2("Doing MS-CHAPv2 password change via ntlm_auth helper");
/*
* Start up ntlm_auth with a pipe on stdin and stdout
size_t len = 0;
if (!nt_password) {
- RDEBUG("Local MS-CHAPv2 password change requires NT-Password attribute");
+ RDEBUG2("Local MS-CHAPv2 password change requires NT-Password attribute");
return -1;
} else {
- RDEBUG("Doing MS-CHAPv2 password change locally");
+ RDEBUG2("Doing MS-CHAPv2 password change locally");
}
/*
return -1;
}
- RDEBUG("MS-CHAPv2 password change succeeded: %s", result);
+ RDEBUG2("MS-CHAPv2 password change succeeded: %s", result);
/*
* Update the NT-Password attribute with the new hash this lets us
* and then jump into mschap2 auth with the challenge/
* response.
*/
- RDEBUG("MS-CHAPv2 password change request received");
+ RDEBUG2("MS-CHAPv2 password change request received");
if (cpw->vp_length != 68) {
REDEBUG("MS-CHAP2-CPW has the wrong format: length %zu != 68", cpw->vp_length);
return RLM_MODULE_REJECT;
}
- RDEBUG("Password change successful");
+ RDEBUG2("Password change successful");
return RLM_MODULE_OK;
}
* to have cleared this bit in the config/SQL/wherever.
*/
if (smb_ctrl && smb_ctrl->vp_uint32 & ACB_FR_EXPIRED) {
- RDEBUG("Clearing expiry bit in SMB-Acct-Ctrl to allow authentication");
+ RDEBUG2("Clearing expiry bit in SMB-Acct-Ctrl to allow authentication");
smb_ctrl->vp_uint32 &= ~ACB_FR_EXPIRED;
}
uiCurr = 0;
if (!pUserName) {
- RDEBUG("Failed to find user name");
+ RDEBUG2("Failed to find user name");
break;
}
}
if (ret != RLM_MODULE_OK) {
- RDEBUG("Invalid password: %pV", &request->username->data);
+ RDEBUG2("Invalid password: %pV", &request->username->data);
return ret;
}
gid_t gid;
if (!request->username) {
- RDEBUG("OpenDirectory requires a User-Name attribute");
+ RDEBUG2("OpenDirectory requires a User-Name attribute");
return RLM_MODULE_NOOP;
}
uuid_clear(guid_sacl);
if (rad_getgid(request, &gid, kRadiusSACLName) < 0) {
- RDEBUG("The SACL group \"%s\" does not exist on this system", kRadiusSACLName);
+ RDEBUG2("The SACL group \"%s\" does not exist on this system", kRadiusSACLName);
} else {
err = mbr_gid_to_uuid(gid, guid_sacl);
if (err != 0) {
#endif
{
if (!rad_client) {
- RDEBUG("The client record could not be found for host %s",
+ RDEBUG2("The client record could not be found for host %s",
fr_inet_ntoh(&request->packet->src_ipaddr, host_ipaddr, sizeof(host_ipaddr)));
} else {
- RDEBUG("The host %s does not have an access group",
+ RDEBUG2("The host %s does not have an access group",
fr_inet_ntoh(&request->packet->src_ipaddr, host_ipaddr, sizeof(host_ipaddr)));
}
}
if (uuid_is_null(guid_sacl) && uuid_is_null(guid_nasgroup)) {
- RDEBUG("No access control groups, all users allowed");
+ RDEBUG2("No access control groups, all users allowed");
if (!module_section_type_set(request, attr_auth_type, inst->auth_type)) return RLM_MODULE_NOOP;
RDEBUG3("Unknown header {%s} in Password-With-Header = \"%s\", re-writing to "
"Cleartext-Password", buffer, vp->vp_strvalue);
} else {
- RDEBUG("Unknown header {%s} in Password-With-Header, re-writing to "
+ RDEBUG2("Unknown header {%s} in Password-With-Header, re-writing to "
"Cleartext-Password", buffer);
}
goto unknown_header;
RDEBUG3("No {...} in &Password-With-Header = \"%s\", re-writing to Cleartext-Password",
vp->vp_strvalue);
} else {
- RDEBUG("No {...} in &Password-With-Header, re-writing to Cleartext-Password");
+ RDEBUG2("No {...} in &Password-With-Header, re-writing to Cleartext-Password");
}
unknown_header:
new = fr_pair_afrom_da(request, attr_cleartext_password);
if (RDEBUG_ENABLED3) {
RDEBUG3("Comparing with \"known good\" Cleartext-Password \"%s\" (%zd)", vp->vp_strvalue, vp->vp_length);
} else {
- RDEBUG("Comparing with \"known good\" Cleartext-Password");
+ RDEBUG2("Comparing with \"known good\" Cleartext-Password");
}
if ((vp->vp_length != request->password->vp_length) ||
if (RDEBUG_ENABLED3) {
RDEBUG3("Comparing with \"known good\" Crypt-Password \"%s\"", vp->vp_strvalue);
} else {
- RDEBUG("Comparing with \"known-good\" Crypt-password");
+ RDEBUG2("Comparing with \"known-good\" Crypt-password");
}
if (fr_crypt_check(request->password->vp_strvalue, vp->vp_strvalue) != 0) {
{
uint8_t digest[128];
- RDEBUG("Comparing with \"known-good\" MD5-Password");
+ RDEBUG2("Comparing with \"known-good\" MD5-Password");
if (inst->normify) {
normify(request, vp, MD5_DIGEST_LENGTH);
fr_md5_ctx_t *md5_ctx;
uint8_t digest[128];
- RDEBUG("Comparing with \"known-good\" SMD5-Password");
+ RDEBUG2("Comparing with \"known-good\" SMD5-Password");
if (inst->normify) normify(request, vp, MD5_DIGEST_LENGTH);
if (vp->vp_length <= MD5_DIGEST_LENGTH) {
fr_sha1_ctx sha1_context;
uint8_t digest[128];
- RDEBUG("Comparing with \"known-good\" SHA-Password");
+ RDEBUG2("Comparing with \"known-good\" SHA-Password");
if (inst->normify) normify(request, vp, SHA1_DIGEST_LENGTH);
fr_sha1_ctx sha1_context;
uint8_t digest[128];
- RDEBUG("Comparing with \"known-good\" SSHA-Password");
+ RDEBUG2("Comparing with \"known-good\" SSHA-Password");
if (inst->normify) normify(request, vp, SHA1_DIGEST_LENGTH);
if (inst->normify) normify(request, vp, SHA224_DIGEST_LENGTH);
if (vp->da == attr_sha2_password) {
- RDEBUG("Comparing with \"known-good\" SHA2-Password");
+ RDEBUG2("Comparing with \"known-good\" SHA2-Password");
/*
* All the SHA-2 algorithms produce digests of different lengths,
}
# ifdef HAVE_EVP_SHA3_512
else if (vp->da == attr_sha3_password) {
- RDEBUG("Comparing with \"known-good\" SHA3-Password");
+ RDEBUG2("Comparing with \"known-good\" SHA3-Password");
/*
* All the SHA-3 algorithms produce digests of different lengths,
* so it's trivial to determine which EVP_MD to use.
return RLM_MODULE_INVALID;
}
- RDEBUG("Comparing with \"known-good\" %s-Password", name);
+ RDEBUG2("Comparing with \"known-good\" %s-Password", name);
/*
* Unlike plain SHA2/3 we already know what length
uint8_t hash[EVP_MAX_MD_SIZE];
uint8_t digest[EVP_MAX_MD_SIZE];
- RDEBUG("Comparing with \"known-good\" PBKDF2-Password");
+ RDEBUG2("Comparing with \"known-good\" PBKDF2-Password");
if (len <= 1) {
REDEBUG("PBKDF2-Password is too short");
uint8_t digest[MD4_DIGEST_LENGTH];
uint8_t ucs2_password[512];
- RDEBUG("Comparing with \"known-good\" NT-Password");
+ RDEBUG2("Comparing with \"known-good\" NT-Password");
rad_assert(request->password != NULL);
rad_assert(request->password->da == attr_user_password);
char charbuf[32 + 1];
ssize_t len;
- RDEBUG("Comparing with \"known-good\" LM-Password");
+ RDEBUG2("Comparing with \"known-good\" LM-Password");
if (inst->normify) normify(request, vp, MD4_DIGEST_LENGTH);
uint8_t buff[FR_MAX_STRING_LEN];
uint8_t buff2[FR_MAX_STRING_LEN + 50];
- RDEBUG("Using NT-MTA-MD5-Password");
+ RDEBUG2("Using NT-MTA-MD5-Password");
if (vp->vp_length != 64) {
REDEBUG("\"known good\" NS-MTA-MD5-Password has incorrect length, expected 64 got %zu", vp->vp_length);
RDEBUG3("Login attempt with password \"%s\" (%zd)",
request->password->vp_strvalue, request->password->vp_length);
} else {
- RDEBUG("Login attempt with password");
+ RDEBUG2("Login attempt with password");
}
/*
if (rc == RLM_MODULE_REJECT) REDEBUG("Passwords don't match");
- if (rc == RLM_MODULE_OK) RDEBUG("User authenticated successfully");
+ if (rc == RLM_MODULE_OK) RDEBUG2("User authenticated successfully");
return rc;
}
vp = fr_pair_make(ctx, request->dict,
vps, inst->pwd_fmt->field[i], pw->field[i], T_OP_EQ);
if (vp) {
- RDEBUG("Added %s: '%s' to %s ", inst->pwd_fmt->field[i], pw->field[i], listname);
+ RDEBUG2("Added %s: '%s' to %s ", inst->pwd_fmt->field[i], pw->field[i], listname);
}
} else
- RDEBUG("NOOP %s: '%s' to %s ", inst->pwd_fmt->field[i], pw->field[i], listname);
+ RDEBUG2("NOOP %s: '%s' to %s ", inst->pwd_fmt->field[i], pw->field[i], listname);
}
}
}
strlcpy(*out, tmp, outlen);
ret = strlen(*out);
- RDEBUG("Len is %zu , out is %s freespace is %zu", ret, *out, outlen);
+ RDEBUG2("Len is %zu , out is %s freespace is %zu", ret, *out, outlen);
}
PUTBACK ;
switch (vp->vp_type) {
case FR_TYPE_STRING:
- RDEBUG("$%s{'%s'}[%i] = &%s:%s -> '%s'", hash_name, vp->da->name, *i,
- list_name, vp->da->name, vp->vp_strvalue);
+ RDEBUG2("$%s{'%s'}[%i] = &%s:%s -> '%s'", hash_name, vp->da->name, *i,
+ list_name, vp->da->name, vp->vp_strvalue);
sv = newSVpvn(vp->vp_strvalue, vp->vp_length);
break;
case FR_TYPE_OCTETS:
- RDEBUG("$%s{'%s'}[%i] = &%s:%s -> 0x%pH", hash_name, vp->da->name, *i,
- list_name, vp->da->name, &vp->data);
+ RDEBUG2("$%s{'%s'}[%i] = &%s:%s -> 0x%pH", hash_name, vp->da->name, *i,
+ list_name, vp->da->name, &vp->data);
sv = newSVpvn((char const *)vp->vp_octets, vp->vp_length);
break;
size_t len;
len = fr_pair_value_snprint(buffer, sizeof(buffer), vp, '\0');
- RDEBUG("$%s{'%s'}[%i] = &%s:%s -> '%s'", hash_name, vp->da->name, *i,
- list_name, vp->da->name, buffer);
+ RDEBUG2("$%s{'%s'}[%i] = &%s:%s -> '%s'", hash_name, vp->da->name, *i,
+ list_name, vp->da->name, buffer);
sv = newSVpvn(buffer, truncate_len(len, sizeof(buffer)));
}
break;
*/
switch (vp->vp_type) {
case FR_TYPE_STRING:
- RDEBUG("$%s{'%s'} = &%s:%s -> '%pV'", hash_name, vp->da->name, list_name,
+ RDEBUG2("$%s{'%s'} = &%s:%s -> '%pV'", hash_name, vp->da->name, list_name,
vp->da->name, &vp->data);
(void)hv_store(rad_hv, name, strlen(name), newSVpvn(vp->vp_strvalue, vp->vp_length), 0);
break;
case FR_TYPE_OCTETS:
- RDEBUG("$%s{'%s'} = &%s:%s -> %pV", hash_name, vp->da->name, list_name,
+ RDEBUG2("$%s{'%s'} = &%s:%s -> %pV", hash_name, vp->da->name, list_name,
vp->da->name, &vp->data);
(void)hv_store(rad_hv, name, strlen(name),
newSVpvn((char const *)vp->vp_octets, vp->vp_length), 0);
size_t len;
len = fr_pair_value_snprint(buffer, sizeof(buffer), vp, '\0');
- RDEBUG("$%s{'%s'} = &%s:%s -> '%s'", hash_name, vp->da->name,
+ RDEBUG2("$%s{'%s'} = &%s:%s -> '%s'", hash_name, vp->da->name,
list_name, vp->da->name, buffer);
(void)hv_store(rad_hv, name, strlen(name),
newSVpvn(buffer, truncate_len(len, sizeof(buffer))), 0);
VP_VERIFY(vp);
- RDEBUG("&%s:%s %s $%s{'%s'} -> '%s'", list_name, key, fr_int2str(fr_tokens_table, op, "<INVALID>"),
- hash_name, key, val);
+ RDEBUG2("&%s:%s %s $%s{'%s'} -> '%s'", list_name, key, fr_int2str(fr_tokens_table, op, "<INVALID>"),
+ hash_name, key, val);
return 0;
}
SPAGAIN;
if (SvTRUE(ERRSV)) {
- RDEBUG("perl_embed:: module = %s , func = %s exit status= %s\n",
- inst->module, function_name, SvPV(ERRSV,n_a));
+ REDEBUG("perl_embed:: module = %s , func = %s exit status= %s\n",
+ inst->module, function_name, SvPV(ERRSV,n_a));
(void)POPs;
exitstatus = RLM_MODULE_FAIL;
} else if (count == 1) {
if (pair != NULL) {
acct_status_type = pair->vp_uint32;
} else {
- RDEBUG("Invalid Accounting Packet");
+ REDEBUG("Invalid Accounting Packet");
return RLM_MODULE_INVALID;
}
void *request_io_ctx;
if (!request->packet->code) {
- RDEBUG("You MUST specify a packet code");
+ REDEBUG("You MUST specify a packet code");
return RLM_MODULE_FAIL;
}
* Insert the next retransmission timer.
*/
if (fr_event_timer_insert(u, el, &u->timer.ev, &u->timer.next, status_check_timeout, u) < 0) {
- RDEBUG("Failed inserting retransmission timer for status check - closing connection %s", c->name);
+ REDEBUG("Failed inserting retransmission timer for status check - closing connection %s", c->name);
talloc_free(c);
return;
}
vp = fr_pair_find_by_da(request->packet->vps, attr_acct_status_type, TAG_ANY);
if (!vp) {
- RDEBUG("Could not find account status type in packet");
+ RDEBUG2("Could not find account status type in packet");
return RLM_MODULE_NOOP;
}
dv = fr_dict_enum_by_value(vp->da, &vp->data);
if (!dv) {
- RDEBUG("Unknown Acct-Status-Type %u", vp->vp_uint32);
+ RDEBUG2("Unknown Acct-Status-Type %u", vp->vp_uint32);
return RLM_MODULE_NOOP;
}
cs = cf_section_find(inst->cs, dv->alias, NULL);
if (!cs) {
- RDEBUG("No subsection %s", dv->alias);
+ RDEBUG2("No subsection %s", dv->alias);
return RLM_MODULE_NOOP;
}
if (action != FR_SIGNAL_CANCEL) return;
- RDEBUG("Forcefully cancelling pending REST request");
+ RDEBUG2("Forcefully cancelling pending REST request");
ret = curl_multi_remove_handle(t->mandle, randle->candle); /* Gracefully terminate the request */
if (ret != CURLM_OK) {
*/
q = memchr(p, ' ', s);
if (!q) {
- RDEBUG("Malformed HTTP header: Missing reason code");
+ REDEBUG("Malformed HTTP header: Missing reason code");
goto malformed;
}
char *uri = NULL;
int ret;
- RDEBUG("Expanding URI components");
+ RDEBUG2("Expanding URI components");
/*
* Build xlat'd URI, this allows REST servers to be specified by
uri_len = rest_uri_build(&uri, instance, request, section->uri);
if (uri_len <= 0) return -1;
- RDEBUG("Sending HTTP %s to \"%s\"", fr_int2str(http_method_table, section->method, NULL), uri);
+ RDEBUG2("Sending HTTP %s to \"%s\"", fr_int2str(http_method_table, section->method, NULL), uri);
/*
* Configure various CURL options, and initialise the read/write
*/
memcpy(&rctx->section, &mod_inst->xlat, sizeof(*section));
- RDEBUG("Expanding URI components");
+ RDEBUG2("Expanding URI components");
/*
* Extract the method from the start of the format string (if there is one)
section->data = q;
}
- RDEBUG("Sending HTTP %s to \"%s\"",
+ RDEBUG2("Sending HTTP %s to \"%s\"",
(section->method == HTTP_METHOD_CUSTOM) ?
section->method_str : fr_int2str(http_method_table, section->method, NULL),
uri);
acm_ret = SD_Init(&sdiHandle);
if (acm_ret != ACM_OK) {
- ERROR("Cannot communicate with the ACE/Server");
+ RERROR("Cannot communicate with the ACE/Server");
return -1;
}
acm_ret = SD_Lock(sdiHandle, securid_user);
if (acm_ret != ACM_OK) {
- ERROR("SecurID: Access denied. Name [%s] lock failed", username);
+ REDEBUG("SecurID: Access denied. Name [%s] lock failed", username);
return -2;
}
switch (acm_ret) {
case ACM_OK:
/* we are in now */
- RDEBUG("SecurID authentication successful for %s", username);
+ RDEBUG2("SecurID authentication successful for %s", username);
SD_Close(sdiHandle);
return RC_SECURID_AUTH_SUCCESS;
case ACM_ACCESS_DENIED:
/* not this time */
- RDEBUG("SecurID Access denied for %s", username);
+ RDEBUG2("SecurID Access denied for %s", username);
SD_Close(sdiHandle);
return RC_SECURID_AUTH_ACCESS_DENIED_FAILURE;
case ACM_INVALID_SERVER:
- ERROR("SecurID: Invalid ACE server");
+ RERROR("SecurID: Invalid ACE server");
return RC_SECURID_AUTH_INVALID_SERVER_FAILURE;
case ACM_NEW_PIN_REQUIRED:
}
} else {
/* existing session found */
- RDEBUG("Continuing previous session found for user [%s]", username);
+ RDEBUG2("Continuing previous session found for user [%s]", username);
/* continue previous session */
switch (securid_session->securidSessionState) {
RDEBUG2("Pin confirmation succeeded. Pins match");
acm_ret = SD_Pin(securid_session->sdiHandle, securid_pass);
if (acm_ret == ACM_NEW_PIN_ACCEPTED) {
- RDEBUG("New SecurID pin accepted for %s.", securid_session->identity);
+ RDEBUG2("New SecurID pin accepted for %s.", securid_session->identity);
securid_session->securidSessionState = NEW_PIN_AUTH_VALIDATE_STATE;
rc = RC_SECURID_AUTH_CHALLENGE;
strlcpy(replyMsgBuffer, " \r\n\r\nWait for the code on your card to change, then enter new PIN and TokenCode\r\n\r\nEnter PASSCODE:", replyMsgBufferSize);
} else {
- RDEBUG("SecurID: New SecurID pin rejected for %s.", securid_session->identity);
+ RDEBUG2("SecurID: New SecurID pin rejected for %s.", securid_session->identity);
SD_Pin(securid_session->sdiHandle, &empty_pin[0]); /* cancel PIN */
case NEW_PIN_AUTH_VALIDATE_STATE:
acm_ret = SD_Check(securid_session->sdiHandle, securid_pass, securid_user);
if (acm_ret == ACM_OK) {
- RDEBUG("New SecurID passcode accepted for %s", securid_session->identity);
+ RDEBUG2("New SecurID passcode accepted for %s", securid_session->identity);
rc = RC_SECURID_AUTH_SUCCESS;
} else {
if (RDEBUG_ENABLED3) {
RDEBUG3("Login attempt with password \"%s\"", password);
} else {
- RDEBUG("Login attempt with password");
+ RDEBUG2("Login attempt with password");
}
rcode = securidAuth(inst, request, username, password,
/* Mark the packet as a Acceess-Challenge Packet */
request->reply->code = FR_CODE_ACCESS_CHALLENGE;
- RDEBUG("Sending Access-Challenge");
+ RDEBUG2("Sending Access-Challenge");
rcode = RLM_MODULE_HANDLED;
break;
if (vlen <= 1) {
uint8_t *p;
- RDEBUG("SoH adding NAP marker to DHCP reply");
+ RDEBUG2("SoH adding NAP marker to DHCP reply");
/* client probe; send "NAP" in the reply */
vp = fr_pair_afrom_da(request->reply, attr_dhcp_vendor);
p = talloc_array(vp, uint8_t, 5);
fr_pair_add(&request->reply->vps, vp);
} else {
- RDEBUG("SoH decoding NAP from DHCP request");
+ RDEBUG2("SoH decoding NAP from DHCP request");
/* SoH payload */
rcode = soh_verify(request, data, vlen);
if (rcode < 0) {
/* try to find the MS-SoH payload */
vp = fr_pair_find_by_da(request->packet->vps, attr_ms_quarantine_soh, TAG_ANY);
if (!vp) {
- RDEBUG("SoH radius VP not found");
+ RDEBUG2("SoH radius VP not found");
return RLM_MODULE_NOOP;
}
- RDEBUG("SoH radius VP found");
+ RDEBUG2("SoH radius VP found");
/* decode it */
rv = soh_verify(request, vp->vp_octets, vp->vp_length);
if (rv < 0) {
numaffected = (inst->driver->sql_affected_rows)(handle, inst->config);
if (numaffected < 1) {
- RDEBUG("SQL query affected no rows");
+ RDEBUG2("SQL query affected no rows");
(inst->driver->sql_finish_query)(handle, inst->config);
goto finish;
case RLM_SQL_OK:
if (row[0]) break;
- RDEBUG("NULL value in first column of result");
+ RDEBUG2("NULL value in first column of result");
(inst->driver->sql_finish_select_query)(handle, inst->config);
ret = -1;
goto finish;
case RLM_SQL_NO_MORE_ROWS:
- RDEBUG("SQL query returned no results");
+ RDEBUG2("SQL query returned no results");
(inst->driver->sql_finish_select_query)(handle, inst->config);
ret = -1;
* in the result set.
*/
if (!found_field) {
- RDEBUG("No fields matching map found in query result");
+ RDEBUG2("No fields matching map found in query result");
rcode = RLM_MODULE_NOOP;
(inst->driver->sql_finish_select_query)(handle, inst->config);
goto finish;
if (ret == RLM_SQL_ERROR) goto error;
if (rows == 0) {
- RDEBUG("SQL query returned no results");
+ RDEBUG2("SQL query returned no results");
rcode = RLM_MODULE_NOOP;
}
while (rlm_sql_fetch_row(&row, inst, request, handle) == RLM_SQL_OK) {
if (!row[0]){
- RDEBUG("row[0] returned NULL");
+ RDEBUG2("row[0] returned NULL");
(inst->driver->sql_finish_select_query)(*handle, inst->config);
talloc_free(entry);
return -1;
return 1;
}
- RDEBUG("sql_groupcmp");
+ RDEBUG2("sql_groupcmp");
if (check->vp_length == 0){
- RDEBUG("sql_groupcmp: Illegal group name");
+ RDEBUG2("sql_groupcmp: Illegal group name");
return 1;
}
for (entry = head; entry != NULL; entry = entry->next) {
if (strcmp(entry->name, check->vp_strvalue) == 0){
- RDEBUG("sql_groupcmp finished: User is a member of group %s",
+ RDEBUG2("sql_groupcmp finished: User is a member of group %s",
check->vp_strvalue);
talloc_free(head);
fr_pool_connection_release(inst->pool, request, handle);
talloc_free(head);
fr_pool_connection_release(inst->pool, request, handle);
- RDEBUG("sql_groupcmp finished: User is NOT a member of group %pV", &check->data);
+ RDEBUG2("sql_groupcmp finished: User is NOT a member of group %pV", &check->data);
return 1;
}
while (true) {
value = cf_pair_value(pair);
if (!value) {
- RDEBUG("Ignoring null query");
+ RDEBUG2("Ignoring null query");
rcode = RLM_MODULE_NOOP;
goto finish;
}
if (!*expanded) {
- RDEBUG("Ignoring null query");
+ RDEBUG2("Ignoring null query");
rcode = RLM_MODULE_NOOP;
goto finish;
sql_ret = rlm_sql_query(inst, request, &handle, expanded);
TALLOC_FREE(expanded);
- RDEBUG("SQL query returned: %s", fr_int2str(sql_rcode_table, sql_ret, "<INVALID>"));
+ RDEBUG2("SQL query returned: %s", fr_int2str(sql_rcode_table, sql_ret, "<INVALID>"));
switch (sql_ret) {
/*
*/
numaffected = (inst->driver->sql_affected_rows)(handle, inst->config);
(inst->driver->sql_finish_query)(handle, inst->config);
- RDEBUG("%i record(s) updated", numaffected);
+ RDEBUG2("%i record(s) updated", numaffected);
if (numaffected > 0) break; /* A query succeeded, were done! */
next:
pair = cf_pair_find_next(section->cs, pair, attr);
if (!pair) {
- RDEBUG("No additional queries configured");
+ RDEBUG2("No additional queries configured");
rcode = RLM_MODULE_NOOP;
goto finish;
}
- RDEBUG("Trying next query...");
+ RDEBUG2("Trying next query...");
}
rlen = strlen(row[0]);
if (rlen >= outlen) {
- RDEBUG("insufficient string space");
+ RDEBUG2("insufficient string space");
goto finish;
}
* If there is a Framed-IP-Address attribute in the reply do nothing
*/
if (fr_pair_find_by_da(request->reply->vps, inst->framed_ip_address, TAG_ANY) != NULL) {
- RDEBUG("Framed-IP-Address already exists");
+ RDEBUG2("Framed-IP-Address already exists");
return do_logging(inst, request, inst->log_exists, RLM_MODULE_NOOP);
}
if (fr_pair_find_by_da(request->control, attr_pool_name, TAG_ANY) == NULL) {
- RDEBUG("No Pool-Name defined");
+ RDEBUG2("No Pool-Name defined");
return do_logging(inst, request, inst->log_nopool, RLM_MODULE_NOOP);
}
* that case, we should return
* NOTFOUND
*/
- RDEBUG("pool appears to be full");
+ RDEBUG2("pool appears to be full");
return do_logging(inst, request, inst->log_failed, RLM_MODULE_NOTFOUND);
}
* sqlippool, so we should just ignore this
* allocation failure and return NOOP
*/
- RDEBUG("IP address could not be allocated as no pool exists with that name");
+ RDEBUG2("IP address could not be allocated as no pool exists with that name");
return RLM_MODULE_NOOP;
}
fr_pool_connection_release(inst->sql_inst->pool, request, handle);
- RDEBUG("IP address could not be allocated");
+ RDEBUG2("IP address could not be allocated");
return do_logging(inst, request, inst->log_failed, RLM_MODULE_NOOP);
}
if (fr_pair_value_from_str(vp, allocation, allocation_len, '\0', true) < 0) {
DO_PART(allocate_commit);
- RDEBUG("Invalid IP number [%s] returned from instbase query.", allocation);
+ RDEBUG2("Invalid IP number [%s] returned from instbase query.", allocation);
fr_pool_connection_release(inst->sql_inst->pool, request, handle);
return do_logging(inst, request, inst->log_failed, RLM_MODULE_NOOP);
}
- RDEBUG("Allocated IP %s", allocation);
+ RDEBUG2("Allocated IP %s", allocation);
fr_pair_add(&request->reply->vps, vp);
/*
vp = fr_pair_find_by_da(request->packet->vps, attr_acct_status_type, TAG_ANY);
if (!vp) {
- RDEBUG("Could not find account status type in packet");
+ RDEBUG2("Could not find account status type in packet");
return RLM_MODULE_NOOP;
}
acct_status_type = vp->vp_uint32;
handle = fr_pool_connection_get(inst->sql_inst->pool, request);
if (!handle) {
- RDEBUG("Failed reserving SQL connection");
+ RDEBUG2("Failed reserving SQL connection");
return RLM_MODULE_FAIL;
}
if ((void const *)*ub == (void const *)inst) {
int res;
- RDEBUG("%s - DNS took too long", name);
+ REDEBUG2("%s - DNS took too long", name);
res = ub_cancel(inst->ub, async_id);
if (res) {
}
if (ub->nxdomain) {
- RDEBUG("%s - NXDOMAIN", name);
+ RDEBUG2("%s - NXDOMAIN", name);
return -1;
}
if (!ub->havedata) {
- RDEBUG("%s - Empty result", name);
+ RDEBUG2("%s - Empty result", name);
return -1;
}
* Which type is this.
*/
if ((vp = fr_pair_find_by_da(request->packet->vps, attr_acct_status_type, TAG_ANY)) == NULL) {
- RDEBUG("no Accounting-Status-Type attribute in request");
+ RDEBUG2("no Accounting-Status-Type attribute in request");
return RLM_MODULE_NOOP;
}
status = vp->vp_uint32;
*/
len = strlen(data_name + 2);
if ((len & 0x01) != 0) {
- RDEBUG("Invalid hex string in '%s'", data_name);
+ REDEBUG("Invalid hex string in '%s'", data_name);
goto nothing;
}
input = blob;
msk = fr_pair_find_by_da(request->reply->vps, attr_eap_msk, TAG_ANY);
emsk = fr_pair_find_by_da(request->reply->vps, attr_eap_emsk, TAG_ANY);
if (!msk || !emsk) {
- RDEBUG("No EAP-MSK or EAP-EMSK. Cannot create WiMAX keys");
+ REDEBUG2("No EAP-MSK or EAP-EMSK. Cannot create WiMAX keys");
return RLM_MODULE_NOOP;
}
(mip_rk_1[2] << 8) | mip_rk_1[3]);
if (mip_spi < 256) mip_spi += 256;
- RDEBUG("MIP-RK = 0x%pH", fr_box_octets(mip_rk, rk_len));
- RDEBUG("MIP-SPI = %08x", ntohl(mip_spi));
+ REDEBUG2("MIP-RK = 0x%pH", fr_box_octets(mip_rk, rk_len));
+ REDEBUG2("MIP-SPI = %08x", ntohl(mip_spi));
/*
* FIXME: Perform SPI collision prevention
*/
vp = fr_pair_find_by_da(request->packet->vps, attr_wimax_rrq_mn_ha_spi, TAG_ANY);
if (vp) {
- RDEBUG("Client requested MN-HA key: Should use SPI to look up key from storage");
+ REDEBUG2("Client requested MN-HA key: Should use SPI to look up key from storage");
if (!mn_nai) {
RWDEBUG("MN-NAI was not found!");
}
*/
vp = fr_pair_find_by_da(request->packet->vps, attr_wimax_ha_rk_key_requested, TAG_ANY);
if (vp && (vp->vp_uint32 == 1)) {
- RDEBUG("Client requested HA-RK: Should use IP to look it up from storage");
+ REDEBUG2("Client requested HA-RK: Should use IP to look it up from storage");
}
}
goto error;
}
- RDEBUG2("Trying to find user \"%s\" in group \"%s\"", username, check->vp_strvalue);
+ REDEBUG2("Trying to find user \"%s\" in group \"%s\"", username, check->vp_strvalue);
err = wbcCtxGetGroups(wb_ctx, username, &num_groups, &wb_groups);
switch (err) {
case WBC_ERR_SUCCESS:
rcode = 0;
- RDEBUG2("Successfully retrieved user's groups");
+ REDEBUG2("Successfully retrieved user's groups");
break;
case WBC_ERR_WINBIND_NOT_AVAILABLE:
break;
}
- if (!num_groups) RDEBUG("No groups returned");
+ if (!num_groups) REDEBUG2("No groups returned");
if (rcode) goto finish;
rcode = 1;
continue;
}
- RDEBUG3("Resolved GID %i to name \"%s\"", wb_groups[i], group->gr_name);
+ REDEBUG2("Resolved GID %i to name \"%s\"", wb_groups[i], group->gr_name);
/* Find the backslash in the returned group name */
if ((backslash < strlen(group->gr_name)) && (group->gr_name[backslash] == '\\')) {
}
/* See if the group matches */
- RDEBUG3("Checking plain group name \"%s\"", group_name);
+ REDEBUG2("Checking plain group name \"%s\"", group_name);
if (!strcasecmp(group_name, check->vp_strvalue)) {
- RDEBUG("Found matching group: %s", group_name);
+ REDEBUG2("Found matching group: %s", group_name);
found = true;
rcode = 0;
}
if (found) break;
}
- if (rcode) RDEBUG2("No groups found that match");
+ if (rcode) REDEBUG2("No groups found that match");
finish:
wbcFreeMemory(wb_groups);
rlm_winbind_t const *inst = instance;
if (!request->password || (request->password->da != attr_user_password)) {
- RDEBUG("No User-Password found in the request; not doing winbind authentication.");
+ REDEBUG2("No User-Password found in the request; not doing winbind authentication.");
return RLM_MODULE_NOOP;
}
* Log the password
*/
if (RDEBUG_ENABLED3) {
- RDEBUG3("Login attempt with password \"%s\" (%zd)", request->password->vp_strvalue,
+ REDEBUG("Login attempt with password \"%s\" (%zd)", request->password->vp_strvalue,
request->password->vp_length);
} else {
- RDEBUG("Login attempt with password");
+ REDEBUG2("Login attempt with password");
}
/*
* chatty enough.
*/
if (do_auth_wbclient_pap(inst, request) == 0) {
- RDEBUG("User authenticated successfully using winbind");
+ REDEBUG2("User authenticated successfully using winbind");
return RLM_MODULE_OK;
}
return RLM_MODULE_REJECT;
}
- RDEBUG("Token data decrypted successfully");
+ RDEBUG2("Token data decrypted successfully");
counter = (yubikey_counter(token.ctr) << 8) | token.use;
timestamp = (token.tstph << 16) | token.tstpl;
if (RDEBUG_ENABLED3) {
RDMARKER(otp, -ret, "User-Password (aes-block) value contains non modhex chars");
} else {
- RDEBUG("User-Password (aes-block) value contains non modhex chars");
+ RDEBUG2("User-Password (aes-block) value contains non modhex chars");
}
return RLM_MODULE_NOOP;
}
projects / thirdparty / freeradius-server.git / commitdiff
