summaryrefslogtreecommitdiff
path: root/src/transport/gnunet-service-tng.c
diff options
context:
space:
mode:
authorChristian Grothoff <christian@grothoff.org>2019-05-11 15:11:52 +0200
committerChristian Grothoff <christian@grothoff.org>2019-05-11 15:11:52 +0200
commitda604c171418b64fcd37a46c4526ba97b6ee47dc (patch)
tree875241f63d7971ee9334886ed64c299c875890ac /src/transport/gnunet-service-tng.c
parentf390dabd6cf746840484d4f19846a083b49d23da (diff)
complete TNG logging
Diffstat (limited to 'src/transport/gnunet-service-tng.c')
-rw-r--r--src/transport/gnunet-service-tng.c155
1 files changed, 133 insertions, 22 deletions
diff --git a/src/transport/gnunet-service-tng.c b/src/transport/gnunet-service-tng.c
index 2141bc8e1..08a8ec893 100644
--- a/src/transport/gnunet-service-tng.c
+++ b/src/transport/gnunet-service-tng.c
@@ -24,7 +24,6 @@
*
* 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
@@ -1959,6 +1958,12 @@ struct PendingMessage
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.
*/
enum PendingMessageType pmt;
@@ -2545,6 +2550,11 @@ static struct PendingAcknowledgement *pa_head;
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.
*/
@@ -3117,7 +3127,8 @@ schedule_transmit_on_queue (struct Queue *queue, int inside_job)
{
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! */
@@ -3127,12 +3138,14 @@ schedule_transmit_on_queue (struct Queue *queue, int inside_job)
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));
}
@@ -3573,7 +3586,8 @@ client_send_response (struct PendingMessage *pm)
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);
}
@@ -3773,11 +3787,6 @@ handle_client_send (void *cls, const struct OutboundMessage *obm)
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;
@@ -3807,6 +3816,7 @@ handle_client_send (void *cls, const struct OutboundMessage *obm)
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;
@@ -3815,6 +3825,12 @@ handle_client_send (void *cls, const struct OutboundMessage *obm)
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,
@@ -4140,11 +4156,13 @@ queue_send_msg (struct Queue *queue,
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);
@@ -7566,9 +7584,6 @@ set_pending_message_uuid (struct PendingMessage *pm)
}
-// FIXME: add logging logic from here!
-
-
/**
* Setup data structure waiting for acknowledgements.
*
@@ -7604,6 +7619,10 @@ prepare_pending_acknowledgement (struct Queue *queue,
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;
}
@@ -7628,11 +7647,17 @@ fragment_message (struct Queue *queue,
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));
@@ -7676,6 +7701,7 @@ fragment_message (struct Queue *queue,
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;
@@ -7744,10 +7770,16 @@ reliability_box_message (struct Queue *queue,
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);
@@ -7783,6 +7815,11 @@ update_pm_next_attempt (struct PendingMessage *pm,
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;
@@ -7843,17 +7880,32 @@ transmit_on_queue (void *cls)
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);
@@ -7868,6 +7920,11 @@ transmit_on_queue (void *cls)
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;
}
@@ -7877,11 +7934,22 @@ transmit_on_queue (void *cls)
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!
@@ -7971,6 +8039,10 @@ handle_del_queue_message (void *cls,
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;
@@ -8030,6 +8102,12 @@ handle_send_message_ack (void *cls,
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 */
@@ -8078,7 +8156,8 @@ handle_send_message_ack (void *cls,
{
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);
}
}
@@ -8200,6 +8279,10 @@ suggest_to_connect (const struct GNUNET_PeerIdentity *pid, const char *address)
"# 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 */
@@ -8237,6 +8320,10 @@ validation_transmit_on_queue (struct Queue *q, struct ValidationState *vs)
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));
}
@@ -8264,8 +8351,12 @@ validation_start_cb (void *cls)
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)
{
@@ -8278,6 +8369,10 @@ validation_start_cb (void *cls)
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));
@@ -8385,6 +8480,10 @@ start_dv_learn (void *cls)
/* 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;
}
@@ -8405,6 +8504,9 @@ start_dv_learn (void *cls)
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 (
@@ -8568,7 +8670,11 @@ handle_add_queue_message (void *cls,
}
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];
@@ -8788,6 +8894,11 @@ start_address_validation (const struct GNUNET_PeerIdentity *pid,
&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,