# HG changeset patch # User Sebastien Decugis # Date 1354225909 -3600 # Node ID 43fb27a9037fad04a350a97ea58c0ec94714a1fb # Parent 8187364e39ea519422ceb82180a126e6c218b5a4 Intrumented socket reception to store the timestamp along the received buffer diff -r 8187364e39ea -r 43fb27a9037f include/freeDiameter/libfdproto.h --- 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 diff -r 8187364e39ea -r 43fb27a9037f libfdcore/cnxctx.c --- 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), { diff -r 8187364e39ea -r 43fb27a9037f libfdcore/cnxctx.h --- 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 */ }; diff -r 8187364e39ea -r 43fb27a9037f libfdcore/fdcore-internal.h --- 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). */ diff -r 8187364e39ea -r 43fb27a9037f libfdcore/sctp.c --- 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; diff -r 8187364e39ea -r 43fb27a9037f libfdcore/sctps.c --- 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; diff -r 8187364e39ea -r 43fb27a9037f libfdproto/messages.c --- 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 */