changeset 894:43fb27a9037f

Intrumented socket reception to store the timestamp along the received buffer
author Sebastien Decugis <sdecugis@freediameter.net>
date Thu, 29 Nov 2012 22:51:49 +0100
parents 8187364e39ea
children fbf77629cb7b
files include/freeDiameter/libfdproto.h libfdcore/cnxctx.c libfdcore/cnxctx.h libfdcore/fdcore-internal.h libfdcore/sctp.c libfdcore/sctps.c libfdproto/messages.c
diffstat 7 files changed, 44 insertions(+), 7 deletions(-) [+]
line wrap: on
line diff
--- a/include/freeDiameter/libfdproto.h	Fri Nov 23 21:22:54 2012 +0100
+++ b/include/freeDiameter/libfdproto.h	Thu Nov 29 22:51:49 2012 +0100
@@ -203,6 +203,8 @@
 #define FCTS 6  /* Display entry parameters of most functions */
 #define CALL 9  /* Display calls to most functions (with CHECK macros) */
 
+#define TIMING INFO /* Display the message handing time information with this level */
+
 /* Increment the debug level for a file at compilation time by defining -DTRACE_LEVEL=FULL for example. */
 #ifndef TRACE_LEVEL 
 #define TRACE_LEVEL NONE
--- a/libfdcore/cnxctx.c	Fri Nov 23 21:22:54 2012 +0100
+++ b/libfdcore/cnxctx.c	Thu Nov 29 22:51:49 2012 +0100
@@ -640,6 +640,8 @@
 		fd_cnx_markerror(conn);
 	}
 	
+	CHECK_SYS_DO( clock_gettime(CLOCK_REALTIME, &conn->cc_tls_para.recvon), /* continue */ );
+	
 	return ret;
 }
 
@@ -695,6 +697,7 @@
 		size_t  length;
 		ssize_t ret = 0;
 		size_t	received = 0;
+		struct timespec recv_on;
 
 		do {
 			ret = fd_cnx_s_recv(conn, &header[received], sizeof(header) - received);
@@ -717,7 +720,7 @@
 		}
 
 		/* Ok, now we can really receive the data */
-		CHECK_MALLOC_DO(  newmsg = malloc( length ), goto fatal );
+		CHECK_MALLOC_DO(  newmsg = malloc( length + sizeof(struct timespec) ), goto fatal );
 		memcpy(newmsg, header, sizeof(header));
 
 		while (received < length) {
@@ -732,6 +735,10 @@
 			received += ret;
 		}
 		
+		/* Piggy-tail the timestamp of reception */
+		CHECK_SYS_DO( clock_gettime(CLOCK_REALTIME, &recv_on), /* continue */ );
+		memcpy(newmsg + length, &recv_on, sizeof(struct timespec));
+		
 		/* We have received a complete message, pass it to the daemon */
 		CHECK_FCT_DO( fd_event_send( fd_cnx_target_queue(conn), FDEVP_CNX_MSG_RECV, length, newmsg), /* continue or destroy everything? */);
 		
@@ -781,7 +788,7 @@
 			/* Just ignore the notification for now, we will get another error later anyway */
 			continue;
 		}
-		
+		/* Note: the real size of buf is bufsz + struct timespec */
 		CHECK_FCT_DO( fd_event_send( fd_cnx_target_queue(conn), event, bufsz, buf), goto fatal );
 		
 	} while (conn->cc_loop || (event != FDEVP_CNX_MSG_RECV));
@@ -919,6 +926,17 @@
 /* The function that receives TLS data and re-builds a Diameter message -- it exits only on error or cancelation */
 int fd_tls_rcvthr_core(struct cnxctx * conn, gnutls_session_t session)
 {
+	struct timespec * rcv_on;
+	
+	void * ptr = gnutls_transport_get_ptr(session);
+	if (ptr == conn) {
+		rcv_on = &conn->cc_tls_para.recvon;
+	} else {
+		struct sctps_ctx * ctx = (struct sctps_ctx *) ptr;
+		rcv_on = &ctx->recvon;
+	}
+	
+	
 	/* No guarantee that GnuTLS preserves the message boundaries, so we re-build it as in TCP */
 	do {
 		uint8_t header[4];
@@ -926,6 +944,7 @@
 		size_t  length;
 		ssize_t ret = 0;
 		size_t	received = 0;
+		struct timespec recv_on;
 
 		do {
 			ret = fd_tls_recv_handle_error(conn, session, &header[received], sizeof(header) - received);
@@ -948,7 +967,7 @@
 		}
 
 		/* Ok, now we can really receive the data */
-		CHECK_MALLOC(  newmsg = malloc( length ) );
+		CHECK_MALLOC(  newmsg = malloc( length + sizeof(struct timespec)) );
 		memcpy(newmsg, header, sizeof(header));
 
 		while (received < length) {
@@ -963,6 +982,9 @@
 			received += ret;
 		}
 		
+		/* The timestamp of the last TLS chunk received for this rebuilt message lives close to the session pointer, we piggyback it */
+		memcpy(newmsg + length, rcv_on, sizeof(struct timespec));
+		
 		/* We have received a complete message, pass it to the daemon */
 		CHECK_FCT_DO( ret = fd_event_send( fd_cnx_target_queue(conn), FDEVP_CNX_MSG_RECV, length, newmsg), 
 			{ 
--- a/libfdcore/cnxctx.h	Fri Nov 23 21:22:54 2012 +0100
+++ b/libfdcore/cnxctx.h	Thu Nov 29 22:51:49 2012 +0100
@@ -65,6 +65,7 @@
 		DiamId_t 			 cn;		/* If not NULL, remote certif will be checked to match this Common Name */
 		int				 mode; 		/* GNUTLS_CLIENT / GNUTLS_SERVER */
 		gnutls_session_t 		 session;	/* Session object (stream #0 in case of SCTP) */
+		struct timespec  		 recvon;	/* Timestamp of the last chunk of data received on this session -- before uncipher */
 	}		cc_tls_para;
 
 	/* If cc_proto == SCTP */
@@ -129,6 +130,7 @@
 		size_t   bufsz;
 		size_t   offset;
 	} 		 partial;	/* If the pull function did not read the full content of first message in raw, it stores it here for next read call. */
+	struct timespec  recvon;	/* Timestamp of the last chunk of data received on this stream -- before uncipher */
 	pthread_t	 thr;		/* Thread to decrypt raw data in this pair of streams */
 	gnutls_session_t session;	/* TLS context using this pair of streams -- except if strid == 0, in that case session is outside the array */
 };
--- a/libfdcore/fdcore-internal.h	Fri Nov 23 21:22:54 2012 +0100
+++ b/libfdcore/fdcore-internal.h	Thu Nov 29 22:51:49 2012 +0100
@@ -214,7 +214,7 @@
 	/* request to terminate this peer : disconnect, requeue all messages */
 	,FDEVP_TERMINATE
 	
-	/* A connection object has received a message. (data contains the buffer) */
+	/* A connection object has received a message. (data contains the buffer + struct timespec piggytailed -- unaligned) */
 	,FDEVP_CNX_MSG_RECV
 			 
 	/* A connection object has encountered an error (disconnected). */
--- a/libfdcore/sctp.c	Fri Nov 23 21:22:54 2012 +0100
+++ b/libfdcore/sctp.c	Thu Nov 29 22:51:49 2012 +0100
@@ -1067,6 +1067,7 @@
 	size_t 			 bufsz = 0, datasize = 0;
 	size_t			 mempagesz = sysconf(_SC_PAGESIZE); /* We alloc buffer by memory pages for efficiency */
 	int 			 timedout = 0;
+	struct timespec 	 recv_on;
 	
 	TRACE_ENTRY("%p %p %p %p %p", conn, strid, buf, len, event);
 	CHECK_PARAMS( conn && buf && len && event );
@@ -1085,15 +1086,15 @@
 	
 	/* We will loop while all data is not received. */
 incomplete:
-	if (datasize == bufsz) {
+	if (datasize == bufsz - sizeof(struct timespec)) {
 		/* The buffer is full, enlarge it */
 		bufsz += mempagesz;
-		CHECK_MALLOC( data = realloc(data, bufsz) );
+		CHECK_MALLOC( data = realloc(data, bufsz ) );
 	}
 	/* the new data will be received following the preceding */
 	memset(&iov,  0, sizeof(iov));
 	iov.iov_base = data + datasize ;
-	iov.iov_len  = bufsz - datasize;
+	iov.iov_len  = bufsz - sizeof(struct timespec) - datasize;
 
 	/* Receive data from the socket */
 again:
@@ -1187,6 +1188,10 @@
 		return 0;
 	}
 	
+	/* Piggy-tail the timestamp of reception */
+	CHECK_SYS_DO( clock_gettime(CLOCK_REALTIME, &recv_on), /* continue */ );
+	memcpy(data + datasize, &recv_on, sizeof(struct timespec));
+		
 	/* From this point, we have received a message */
 	*event = FDEVP_CNX_MSG_RECV;
 	*buf = data;
--- a/libfdcore/sctps.c	Fri Nov 23 21:22:54 2012 +0100
+++ b/libfdcore/sctps.c	Thu Nov 29 22:51:49 2012 +0100
@@ -91,6 +91,7 @@
 			case FDEVP_CNX_MSG_RECV:
 				/* Demux this message to the appropriate fifo, another thread will pull, gnutls process, and send to target queue */
 				if (strid < conn->cc_sctp_para.pairs) {
+					/* Note, here the timespec is piggytailed to buf */
 					CHECK_FCT_DO(fd_event_send(conn->cc_sctps_data.array[strid].raw_recv, event, bufsz, buf), goto fatal );
 				} else {
 					TRACE_DEBUG(INFO, "Received packet (%d bytes) on out-of-range stream #%d from %s, discarded.", bufsz, strid, conn->cc_remid);
@@ -194,6 +195,9 @@
 			/* Documentations says to return 0 on connection closed, but it does hang within gnutls_handshake */
 			return -1;
 		}
+		if (ev == FDEVP_CNX_MSG_RECV) {
+			memcpy(&ctx->recvon, ctx->partial.buf + ctx->partial.bufsz, sizeof(struct timespec)); /* retrieve piggy-tailed ts */
+		}
 	}
 		
 	pulled = ctx->partial.bufsz - ctx->partial.offset;
--- a/libfdproto/messages.c	Fri Nov 23 21:22:54 2012 +0100
+++ b/libfdproto/messages.c	Thu Nov 29 22:51:49 2012 +0100
@@ -127,6 +127,8 @@
 		}		 msg_cb;		/* Callback to be called when an answer is received, if not NULL */
 	DiamId_t		 msg_src_id;		/* Diameter Id of the peer this message was received from. This string is malloc'd and must be freed */
 	size_t			 msg_src_id_len;	/* cached length of this string */
+	struct timespec		 msg_ts;		/* Timestamp associated with the message */
+	
 };
 
 /* Macro to compute the message header size */
"Welcome to our mercurial repository"