gtphub: Add logging for ares queries.

Looking for a segfault, I added a lot of logging. This may be useful for
live testing ares, leaving it in there for now.

Note: I still want to clean up the logging concerning log levels etc. once
we're out of alpha.

Sponsored-by: On-Waves ehi

2 files changed, 28 insertions, 15 deletions

diff --git a/openbsc/src/gprs/gtphub.c b/openbsc/src/gprs/gtphub.c
index d6dbb4d0c..b3638fe3f 100644
--- a/openbsc/src/gprs/gtphub.c
+++ b/openbsc/src/gprs/gtphub.c
@@ -960,10 +960,10 @@ static uint32_t gtphub_tei_mapping_have(struct gtphub *hub,
 	return (uint32_t)nrm->repl;
 }
 
-static int gtphub_map_seq(struct gtp_packet_desc *p,
-			  struct gtphub_peer_port *from_port,
-			  struct gtphub_peer_port *to_port,
-			  time_t now)
+static void gtphub_map_seq(struct gtp_packet_desc *p,
+			   struct gtphub_peer_port *from_port,
+			   struct gtphub_peer_port *to_port,
+			   time_t now)
 {
 	/* Store a mapping in to_peer's map, so when we later receive a GTP
 	 * packet back from to_peer, the seq nr can be unmapped back to its
@@ -974,8 +974,6 @@ static int gtphub_map_seq(struct gtp_packet_desc *p,
 
 	/* Change the GTP packet to yield the new, mapped seq nr */
 	set_seq(p, nrm->repl);
-
-	return 0;
 }
 
 static struct gtphub_peer_port *gtphub_unmap_seq(struct gtp_packet_desc *p,
@@ -1681,6 +1679,9 @@ void gtphub_resolved_ggsn(struct gtphub *hub, const char *apn_oi_str,
 	struct gtphub_peer_port *pp;
 	struct gtphub_resolved_ggsn *ggsn;
 
+	LOG("Resolved GGSN callback: %s %s\n",
+	    apn_oi_str, osmo_hexdump((unsigned char*)resolved_addr, sizeof(*resolved_addr)));
+
 	pp = gtphub_port_have(hub, &hub->to_ggsns[GTPH_PLANE_CTRL],
 			      resolved_addr, 2123);
 	if (!pp) {
diff --git a/openbsc/src/gprs/gtphub_ext.c b/openbsc/src/gprs/gtphub_ext.c
index 386ee1318..0d6627350 100644
--- a/openbsc/src/gprs/gtphub_ext.c
+++ b/openbsc/src/gprs/gtphub_ext.c
@@ -64,6 +64,7 @@ static int start_ares_query(struct ggsn_lookup *lookup);
 static void ggsn_lookup_cb(void *arg, int status, int timeouts, struct hostent *hostent)
 {
 	struct ggsn_lookup *lookup = arg;
+	LOGP(DGTPHUB, LOGL_NOTICE, "ggsn_lookup_cb(%p / %p)", lookup, &lookup->expiry_entry);
 
 	if (status != ARES_SUCCESS) {
 		LOGP(DGTPHUB, LOGL_ERROR, "DNS query failed.\n");
@@ -75,7 +76,7 @@ static void ggsn_lookup_cb(void *arg, int status, int timeouts, struct hostent *
 				return;
 		}
 
-		LOGP(DGTPHUB, LOGL_ERROR, "Failed to resolve GGSN.\n");
+		LOGP(DGTPHUB, LOGL_ERROR, "Failed to resolve GGSN. (%p)\n", lookup);
 		goto remove_from_queue;
 	}
 
@@ -96,10 +97,14 @@ static void ggsn_lookup_cb(void *arg, int status, int timeouts, struct hostent *
 	memcpy(&resolved_addr.buf, addr0, hostent->h_length);
 	resolved_addr.len = hostent->h_length;
 
+	LOGP(DGTPHUB, LOGL_NOTICE, "resolved addr %s\n",
+	     osmo_hexdump(&resolved_addr, sizeof(resolved_addr)));
+
 	gtphub_resolved_ggsn(lookup->hub, lookup->apn_oi_str, &resolved_addr,
 			     gtphub_now());
 
 remove_from_queue:
+	LOGP(DGTPHUB, LOGL_ERROR, "Removing GGSN lookup. (%p / %p)\n", lookup, &lookup->expiry_entry);
 	expiring_item_del(&lookup->expiry_entry);
 }
 
@@ -115,7 +120,7 @@ static void make_addr_str(struct ggsn_lookup *lookup)
 
 static int start_ares_query(struct ggsn_lookup *lookup)
 {
-	LOGP(DGTPHUB, LOGL_DEBUG, "Going to query %s\n", lookup->apn_oi_str);
+	LOGP(DGTPHUB, LOGL_DEBUG, "Going to query %s (%p / %p)\n", lookup->apn_oi_str, lookup, &lookup->expiry_entry);
 
 	int rc = sgsn_ares_query(sgsn, lookup->apn_oi_str, ggsn_lookup_cb, &lookup);
 	if (rc != 0)
@@ -125,28 +130,31 @@ static int start_ares_query(struct ggsn_lookup *lookup)
 
 static void ggsn_lookup_del_cb(struct expiring_item *expi)
 {
-	struct ggsn_lookup *ggsn;
-	ggsn = container_of(expi, struct ggsn_lookup, expiry_entry);
+	struct ggsn_lookup *lookup;
+	lookup = container_of(expi, struct ggsn_lookup, expiry_entry);
+
+	LOGP(DGTPHUB, LOGL_NOTICE, "ggsn_lookup_del_cb(%p / %p)\n", lookup, expi);
 
-	ggsn->expiry_entry.del_cb = 0;
+	lookup->expiry_entry.del_cb = 0;
 	expiring_item_del(expi);
 
-	llist_del(&ggsn->entry);
-	talloc_free(ggsn);
+	llist_del(&lookup->entry);
+	talloc_free(lookup);
 }
 
 struct gtphub_peer_port *gtphub_resolve_ggsn_addr(struct gtphub *hub,
 						  const char *imsi_str,
 						  const char *apn_ni_str)
 {
-	LOGP(DGTPHUB, LOGL_NOTICE, "Request to resolve IMSI '%s' with APN-NI '%s'\n",
-	     imsi_str, apn_ni_str);
 	OSMO_ASSERT(imsi_str);
 	OSMO_ASSERT(apn_ni_str);
 
 	struct ggsn_lookup *lookup = talloc_zero(osmo_gtphub_ctx, struct ggsn_lookup);
 	OSMO_ASSERT(lookup);
 
+	LOGP(DGTPHUB, LOGL_NOTICE, "Request to resolve IMSI '%s' with APN-NI '%s' (%p / %p)\n",
+	     imsi_str, apn_ni_str, lookup, &lookup->expiry_entry);
+
 	lookup->hub = hub;
 
 	strncpy(lookup->imsi_str, imsi_str, sizeof(lookup->imsi_str));
@@ -157,6 +165,7 @@ struct gtphub_peer_port *gtphub_resolve_ggsn_addr(struct gtphub *hub,
 
 	make_addr_str(lookup);
 
+	LOGP(DGTPHUB, LOGL_NOTICE, "looking for active queries...\n");
 	struct ggsn_lookup *active;
 	llist_for_each_entry(active, &hub->ggsn_lookups, entry) {
 		if (strncmp(active->apn_oi_str, lookup->apn_oi_str,
@@ -166,6 +175,7 @@ struct gtphub_peer_port *gtphub_resolve_ggsn_addr(struct gtphub *hub,
 		}
 	}
 
+	LOGP(DGTPHUB, LOGL_NOTICE, "looking for already resolved GGSNs...\n");
 	struct gtphub_resolved_ggsn *resolved;
 	llist_for_each_entry(resolved, &hub->resolved_ggsns, entry) {
 		if (strncmp(resolved->apn_oi_str, lookup->apn_oi_str,
@@ -178,6 +188,7 @@ struct gtphub_peer_port *gtphub_resolve_ggsn_addr(struct gtphub *hub,
 	/* Kick off a resolution, but so far return nothing. The hope is that
 	 * the peer will resend the request (a couple of times), and by then
 	 * the GGSN will be resolved. */
+	LOGP(DGTPHUB, LOGL_NOTICE, "kick off resolution.\n");
 
 	llist_add(&lookup->entry, &hub->ggsn_lookups);
 
@@ -185,6 +196,7 @@ struct gtphub_peer_port *gtphub_resolve_ggsn_addr(struct gtphub *hub,
 	expiry_add(&hub->expire_seq_maps, &lookup->expiry_entry, gtphub_now());
 
 	start_ares_query(lookup);
+	LOGP(DGTPHUB, LOGL_NOTICE, "resolution started.\n");
 
 	return NULL;
 }