*
* TODO:
* Implement next:
- * - add (more) logging (beyond line ~7500)
* - properly encrypt *all* DV traffic, not only backchannel;
* rename BackchannelEncapsulation logic to DVEncapsulation!
* - realize transport-to-transport flow control (needed in case
*/
struct MessageUUIDP msg_uuid;
+ /**
+ * UUID we use to identify this message in our logs.
+ * Generated by incrementing the "logging_uuid_gen".
+ */
+ unsigned long long logging_uuid;
+
/**
* Type of the pending message.
*/
*/
static struct PendingAcknowledgement *pa_tail;
+/**
+ * Generator of `logging_uuid` in `struct PendingMessage`.
+ */
+static unsigned long long logging_uuid_gen;
+
/**
* Number of entries in the #pa_head/#pa_tail DLL. Used to
* limit the size of the data structure.
{
GNUNET_log (
GNUNET_ERROR_TYPE_DEBUG,
- "Schedule transmission on queue %llu of %s decides to run immediately\n",
+ "Schedule transmission <%llu> on queue %llu of %s decides to run immediately\n",
+ pm->logging_uuid,
(unsigned long long) queue->qid,
GNUNET_i2s (&n->pid));
return; /* we should run immediately! */
GNUNET_SCHEDULER_add_delayed (out_delay, &transmit_on_queue, queue);
if (out_delay.rel_value_us > DELAY_WARN_THRESHOLD.rel_value_us)
GNUNET_log (GNUNET_ERROR_TYPE_WARNING,
- "Next transmission on queue `%s' in %s (high delay)\n",
+ "Next transmission <%llu> on queue `%s' in %s (high delay)\n",
+ pm->logging_uuid,
queue->address,
GNUNET_STRINGS_relative_time_to_string (out_delay, GNUNET_YES));
else
GNUNET_log (GNUNET_ERROR_TYPE_DEBUG,
- "Next transmission on queue `%s' in %s\n",
+ "Next transmission <%llu> on queue `%s' in %s\n",
+ pm->logging_uuid,
queue->address,
GNUNET_STRINGS_relative_time_to_string (out_delay, GNUNET_YES));
}
env = GNUNET_MQ_msg (som, GNUNET_MESSAGE_TYPE_TRANSPORT_SEND_OK);
som->peer = target->pid;
GNUNET_log (GNUNET_ERROR_TYPE_DEBUG,
- "Confirming transmission to %s\n",
+ "Confirming transmission of <%llu> to %s\n",
+ pm->logging_uuid,
GNUNET_i2s (&pm->target->pid));
GNUNET_MQ_send (tc->mq, env);
}
else
dv = NULL;
GNUNET_assert ((NULL != target) || (NULL != dv));
- GNUNET_log (GNUNET_ERROR_TYPE_DEBUG,
- "Sending %u bytes to %s using %s\n",
- bytes_msg,
- GNUNET_i2s (&obm->peer),
- (NULL == target) ? "distance vector path" : "direct queue");
if (NULL == target)
{
unsigned int res;
was_empty = (NULL == target->pending_msg_head);
pm = GNUNET_malloc (sizeof (struct PendingMessage) + payload_size);
+ pm->logging_uuid = logging_uuid_gen++;
pm->prefs = pp;
pm->client = tc;
pm->target = target;
GNUNET_free_non_null (dvb);
dvb = NULL;
pm->dvh = dvh;
+ GNUNET_log (GNUNET_ERROR_TYPE_DEBUG,
+ "Sending %u bytes as <%llu> to %s using %s\n",
+ bytes_msg,
+ pm->logging_uuid,
+ GNUNET_i2s (&obm->peer),
+ (NULL == target) ? "distance vector path" : "direct queue");
if (NULL != dvh)
{
GNUNET_CONTAINER_MDLL_insert (dvh,
struct GNUNET_TRANSPORT_SendMessageTo *smt;
struct GNUNET_MQ_Envelope *env;
- GNUNET_log (GNUNET_ERROR_TYPE_DEBUG,
- "Queueing %u bytes of payload for transmission on queue %llu to %s\n",
- (unsigned int) payload_size,
- (unsigned long long) queue->qid,
- GNUNET_i2s (&queue->neighbour->pid));
+ GNUNET_log (
+ GNUNET_ERROR_TYPE_DEBUG,
+ "Queueing %u bytes of payload for transmission <%llu> on queue %llu to %s\n",
+ (unsigned int) payload_size,
+ pm->logging_uuid,
+ (unsigned long long) queue->qid,
+ GNUNET_i2s (&queue->neighbour->pid));
env = GNUNET_MQ_msg_extra (smt,
payload_size,
GNUNET_MESSAGE_TYPE_TRANSPORT_SEND_MSG);
}
-// FIXME: add logging logic from here!
-
-
/**
* Setup data structure waiting for acknowledgements.
*
GNUNET_CONTAINER_MDLL_insert (dvh, dvh->pa_head, dvh->pa_tail, pa);
pa->transmission_time = GNUNET_TIME_absolute_get ();
pa->message_size = pm->bytes_msg;
+ GNUNET_log (GNUNET_ERROR_TYPE_DEBUG,
+ "Waiting for ACKnowledgment `%s' for <%llu>\n",
+ GNUNET_sh2s (&pa->ack_uuid.value),
+ pm->logging_uuid);
return pa;
}
struct PendingMessage *ff;
uint16_t mtu;
- pa = prepare_pending_acknowledgement (queue, dvh, pm);
mtu = (0 == queue->mtu)
? UINT16_MAX - sizeof (struct GNUNET_TRANSPORT_SendMessageTo)
: queue->mtu;
set_pending_message_uuid (pm);
+ GNUNET_log (GNUNET_ERROR_TYPE_DEBUG,
+ "Fragmenting message %llu <%llu> to %s for MTU %u\n",
+ (unsigned long long) pm->msg_uuid.uuid,
+ pm->logging_uuid,
+ GNUNET_i2s (&pm->target->pid),
+ (unsigned int) mtu);
+ pa = prepare_pending_acknowledgement (queue, dvh, pm);
/* This invariant is established in #handle_add_queue_message() */
GNUNET_assert (mtu > sizeof (struct TransportFragmentBoxMessage));
frag =
GNUNET_malloc (sizeof (struct PendingMessage) +
sizeof (struct TransportFragmentBoxMessage) + fragsize);
+ frag->logging_uuid = logging_uuid_gen++;
frag->target = pm->target;
frag->frag_parent = ff;
frag->timeout = pm->timeout;
client_send_response (pm);
return NULL;
}
+ GNUNET_log (GNUNET_ERROR_TYPE_DEBUG,
+ "Preparing reliability box for message <%llu> to %s on queue %s\n",
+ pm->logging_uuid,
+ GNUNET_i2s (&pm->target->pid),
+ queue->address);
pa = prepare_pending_acknowledgement (queue, dvh, pm);
bpm = GNUNET_malloc (sizeof (struct PendingMessage) + sizeof (rbox) +
pm->bytes_msg);
+ bpm->logging_uuid = logging_uuid_gen++;
bpm->target = pm->target;
bpm->frag_parent = pm;
GNUNET_CONTAINER_MDLL_insert (frag, pm->head_frag, pm->tail_frag, bpm);
struct Neighbour *neighbour = pm->target;
pm->next_attempt = next_attempt;
+ GNUNET_log (GNUNET_ERROR_TYPE_DEBUG,
+ "Next attempt for message <%llu> set to %s\n",
+ pm->logging_uuid,
+ GNUNET_STRINGS_absolute_time_to_string (next_attempt));
+
if (NULL == pm->frag_parent)
{
struct PendingMessage *pos;
if (NULL == (pm = n->pending_msg_head))
{
/* no message pending, nothing to do here! */
+ GNUNET_log (GNUNET_ERROR_TYPE_DEBUG,
+ "No messages waiting on queue %s to %s, going to sleep\n",
+ queue->address,
+ GNUNET_i2s (&n->pid));
return;
}
if (NULL != pm->qe)
{
/* message still pending with communciator!
- LOGGING-FIXME: Use stats? logging? Should this not be rare? */
+ LOGGING-FIXME: Use stats? Should this not be rare? */
+ GNUNET_log (GNUNET_ERROR_TYPE_DEBUG,
+ "Waiting on communicator for queue %s to %s, going to sleep\n",
+ queue->address,
+ GNUNET_i2s (&n->pid));
return;
}
schedule_transmit_on_queue (queue, GNUNET_YES);
if (NULL != queue->transmit_task)
+ {
+ GNUNET_log (
+ GNUNET_ERROR_TYPE_DEBUG,
+ "Scheduled transmission on queue %s to %s for later, going to sleep\n",
+ queue->address,
+ GNUNET_i2s (&n->pid));
return; /* do it later */
+ }
overhead = 0;
if (GNUNET_TRANSPORT_CC_RELIABLE != queue->tc->details.communicator.cc)
overhead += sizeof (struct TransportReliabilityBoxMessage);
if (NULL == s)
{
/* Fragmentation failed, try next message... */
+ GNUNET_log (GNUNET_ERROR_TYPE_DEBUG,
+ "Fragmentation failed queue %s to %s for <%llu>, trying again\n",
+ queue->address,
+ GNUNET_i2s (&n->pid),
+ pm->logging_uuid);
schedule_transmit_on_queue (queue, GNUNET_NO);
return;
}
if (NULL == s)
{
/* Reliability boxing failed, try next message... */
+ GNUNET_log (
+ GNUNET_ERROR_TYPE_DEBUG,
+ "Reliability boxing failed queue %s to %s for <%llu>, trying again\n",
+ queue->address,
+ GNUNET_i2s (&n->pid),
+ pm->logging_uuid);
schedule_transmit_on_queue (queue, GNUNET_NO);
return;
}
/* Pass 's' for transission to the communicator */
+ GNUNET_log (GNUNET_ERROR_TYPE_DEBUG,
+ "Passing message <%llu> to queue %s for peer %s\n",
+ s->logging_uuid,
+ queue->address,
+ GNUNET_i2s (&n->pid));
queue_send_msg (queue, s, &s[1], s->bytes_msg);
// FIXME: do something similar to the logic below
// in defragmentation / reliability ACK handling!
if ((dqm->qid != queue->qid) ||
(0 != GNUNET_memcmp (&dqm->receiver, &neighbour->pid)))
continue;
+ GNUNET_log (GNUNET_ERROR_TYPE_DEBUG,
+ "Dropped queue %s to peer %s\n",
+ queue->address,
+ GNUNET_i2s (&neighbour->pid));
free_queue (queue);
GNUNET_SERVICE_client_continue (tc->client);
return;
qe);
qe->queue->queue_length--;
tc->details.communicator.total_queue_length--;
+ GNUNET_log (GNUNET_ERROR_TYPE_DEBUG,
+ "Received ACK on queue %s to peer %s (new length: %u/%u)\n",
+ qe->queue->address,
+ GNUNET_i2s (&qe->queue->neighbour->pid),
+ qe->queue->queue_length,
+ tc->details.communicator.total_queue_length);
GNUNET_SERVICE_client_continue (tc->client);
/* if applicable, resume transmissions that waited on ACK */
{
GNUNET_log (
GNUNET_ERROR_TYPE_INFO,
- "Queue failed in transmission, will try retransmission immediately\n");
+ "Queue failed in transmission <%llu>, will try retransmission immediately\n",
+ pm->logging_uuid);
update_pm_next_attempt (pm, GNUNET_TIME_UNIT_ZERO_ABS);
}
}
"# Suggestions ignored due to missing communicator",
1,
GNUNET_NO);
+ GNUNET_log (GNUNET_ERROR_TYPE_INFO,
+ "Cannot connect to %s at `%s', no matching communicator present\n",
+ GNUNET_i2s (pid),
+ address);
return;
}
/* forward suggestion for queue creation to communicator */
tvc.reserved = htonl (0);
tvc.challenge = vs->challenge;
tvc.sender_time = GNUNET_TIME_absolute_hton (vs->last_challenge_use);
+ GNUNET_log (GNUNET_ERROR_TYPE_INFO,
+ "Sending address validation challenge %s to %s\n",
+ GNUNET_sh2s (&tvc.challenge.value),
+ GNUNET_i2s (&q->neighbour->pid));
queue_send_msg (q, NULL, &tvc, sizeof (tvc));
}
vs = GNUNET_CONTAINER_heap_peek (validation_heap);
}
if (NULL == vs)
+ {
+ GNUNET_log (GNUNET_ERROR_TYPE_INFO,
+ "Address validation task not scheduled anymore, nothing to do\n");
return; /* woopsie, no more addresses known, should only
happen if we're really a lonely peer */
+ }
q = find_queue (&vs->pid, vs->address);
if (NULL == q)
{
vs->challenge_backoff =
GNUNET_TIME_randomized_backoff (vs->challenge_backoff,
MAX_VALIDATION_CHALLENGE_FREQ);
+ GNUNET_log (GNUNET_ERROR_TYPE_DEBUG,
+ "Address validation task will run again in %s\n",
+ GNUNET_STRINGS_relative_time_to_string (vs->challenge_backoff,
+ GNUNET_YES));
update_next_challenge_time (vs,
GNUNET_TIME_relative_to_absolute (
vs->challenge_backoff));
/* scale our retries by how far we are above the threshold */
factor = qqc.quality_count / DV_LEARN_QUALITY_THRESHOLD;
delay = GNUNET_TIME_relative_multiply (DV_LEARN_BASE_FREQUENCY, factor);
+ GNUNET_log (GNUNET_ERROR_TYPE_DEBUG,
+ "At connection quality %u, will launch DV learn in %s\n",
+ qqc.quality_count,
+ GNUNET_STRINGS_relative_time_to_string (delay, GNUNET_YES));
dvlearn_task = GNUNET_SCHEDULER_add_delayed (delay, &start_dv_learn, NULL);
return;
}
GNUNET_CRYPTO_random_block (GNUNET_CRYPTO_QUALITY_NONCE,
&lle->challenge,
sizeof (lle->challenge));
+ GNUNET_log (GNUNET_ERROR_TYPE_DEBUG,
+ "Starting launch DV learn with challenge %s\n",
+ GNUNET_sh2s (&lle->challenge.value));
GNUNET_CONTAINER_DLL_insert (lle_head, lle_tail, lle);
GNUNET_break (GNUNET_YES ==
GNUNET_CONTAINER_multishortmap_put (
}
addr_len = ntohs (aqm->header.size) - sizeof (*aqm);
addr = (const char *) &aqm[1];
-
+ GNUNET_log (GNUNET_ERROR_TYPE_DEBUG,
+ "New queue %s to %s available with QID %llu\n",
+ addr,
+ GNUNET_i2s (&aqm->receiver),
+ (unsigned long long) aqm->qid);
queue = GNUNET_malloc (sizeof (struct Queue) + addr_len);
queue->tc = tc;
queue->address = (const char *) &queue[1];
&vs->challenge,
sizeof (vs->challenge));
vs->address = GNUNET_strdup (address);
+ GNUNET_log (GNUNET_ERROR_TYPE_DEBUG,
+ "Starting address validation `%s' of peer %s using challenge %s\n",
+ address,
+ GNUNET_i2s (pid),
+ GNUNET_sh2s (&vs->challenge.value));
GNUNET_assert (GNUNET_YES ==
GNUNET_CONTAINER_multipeermap_put (
validation_map,
projects / oweals / gnunet.git / commitdiff