Added more stats and options in siprtp samples

git-svn-id: http://svn.pjsip.org/repos/pjproject/trunk@379 74dad513-b988-da41-8d7b-12977e46ad98

3 files changed, 527 insertions, 75 deletions

diff --git a/pjsip-apps/build/Samples-vc.mak b/pjsip-apps/build/Samples-vc.mak
index 59f1fde1..43ed926a 100644
--- a/pjsip-apps/build/Samples-vc.mak
+++ b/pjsip-apps/build/Samples-vc.mak
@@ -40,7 +40,7 @@ BINDIR = ..\bin\samples
 SAMPLES = $(BINDIR)\simpleua.exe $(BINDIR)\playfile.exe $(BINDIR)\playsine.exe \
 	  $(BINDIR)\confsample.exe $(BINDIR)\sndinfo.exe \
 	  $(BINDIR)\level.exe $(BINDIR)\recfile.exe  \
-	  $(BINDIR)\resampleplay.exe
+	  $(BINDIR)\resampleplay.exe $(BINDIR)\siprtp.exe
 
 
 all: $(OBJDIR) $(SAMPLES)
diff --git a/pjsip-apps/build/Samples.mak b/pjsip-apps/build/Samples.mak
index 66479ff2..749c9391 100644
--- a/pjsip-apps/build/Samples.mak
+++ b/pjsip-apps/build/Samples.mak
@@ -38,7 +38,8 @@ SRCDIR := ../src/samples
 OBJDIR := ./output/samples-$(MACHINE_NAME)-$(OS_NAME)-$(CC_NAME)
 BINDIR := ../bin/samples
 
-SAMPLES := simpleua playfile playsine confsample sndinfo level recfile resampleplay
+SAMPLES := simpleua playfile playsine confsample sndinfo level recfile resampleplay \
+	   siprtp
 
 EXES := $(foreach file, $(SAMPLES), $(BINDIR)/$(file)-$(MACHINE_NAME)-$(OS_NAME)-$(CC_NAME)$(HOST_EXE))
 
diff --git a/pjsip-apps/src/samples/siprtp.c b/pjsip-apps/src/samples/siprtp.c
index 72ab5c79..1c16b9cc 100644
--- a/pjsip-apps/src/samples/siprtp.c
+++ b/pjsip-apps/src/samples/siprtp.c
@@ -34,6 +34,30 @@
 #define RTP_START_PORT	44100
 
 
+/* Codec descriptor: */
+struct codec
+{
+    unsigned	pt;
+    char*	name;
+    unsigned	clock_rate;
+    unsigned	bit_rate;
+    unsigned	ptime;
+    char*	description;
+};
+
+
+/* Unidirectional media stat: */
+struct stream_stat
+{
+    pj_uint32_t	    pkt, payload;
+    pj_uint32_t	    discard, reorder;
+    unsigned	    loss_min, loss_avg, loss_max;
+    char	   *loss_type;
+    unsigned	    jitter_min, jitter_avg, jitter_max;
+    unsigned	    rtcp_cnt;
+};
+
+
 /* A bidirectional media stream */
 struct media_stream
 {
@@ -60,6 +84,10 @@ struct media_stream
     pjmedia_rtcp_session rtcp;		    /* incoming RTCP session.	*/
     pjmedia_rtcp_pkt	 rem_rtcp;	    /* received RTCP stat.	*/
 
+    /* More stats: */
+    struct stream_stat	 rx_stat;	    /* incoming stream stat	*/
+    struct stream_stat	 tx_stat;	    /* outgoing stream stat.	*/
+
     /* Thread: */
     pj_bool_t		 thread_quit_flag;  /* worker thread quit flag	*/
     pj_thread_t		*thread;	    /* RTP/RTCP worker thread	*/
@@ -72,6 +100,9 @@ struct call
     pjsip_inv_session	*inv;
     unsigned		 media_count;
     struct media_stream	 media[2];
+    pj_time_val		 start_time;
+    pj_time_val		 response_time;
+    pj_time_val		 connect_time;
 };
 
 
@@ -84,6 +115,12 @@ static struct app
     char		*local_addr;
     pj_str_t		 local_uri;
     pj_str_t		 local_contact;
+    
+    int			 app_log_level;
+    int			 log_level;
+    char		*log_filename;
+
+    struct codec	 audio_codec;
 
     pj_str_t		 uri_to_call;
 
@@ -134,6 +171,8 @@ static void app_perror(const char *sender, const char *title,
 		       pj_status_t status);
 
 
+
+
 /* This is a PJSIP module to be registered by application to handle
  * incoming requests outside any dialogs/transactions. The main purpose
  * here is to handle incoming INVITE request message, where we will
@@ -157,12 +196,22 @@ static pjsip_module mod_siprtp =
 };
 
 
+/* Codec constants */
+struct codec audio_codecs[] = 
+{
+    { 0,  "pcmu", 8000, 64000, 20, "G.711 ULaw" },
+    { 3,  "gsm",  8000, 13200, 20, "GSM" },
+    { 4,  "g723", 8000, 6400,  30, "G.723.1" },
+    { 8,  "pcma", 8000, 64000, 20, "G.711 ALaw" },
+    { 18, "g729", 8000, 8000, 20, "G.729" },
+};
+
+
 /*
  * Init SIP stack
  */
 static pj_status_t init_sip()
 {
-    unsigned i;
     pj_status_t status;
 
     /* init PJLIB-UTIL: */
@@ -241,12 +290,6 @@ static pj_status_t init_sip()
     PJ_ASSERT_RETURN(status == PJ_SUCCESS, status);
 
 
-    /* Start worker threads */
-    for (i=0; i<app.thread_count; ++i) {
-	pj_thread_create( app.pool, "app", &worker_thread, NULL,
-			  0, 0, &app.thread[i]);
-    }
-
     /* Done */
     return PJ_SUCCESS;
 }
@@ -462,6 +505,9 @@ static pj_status_t make_call(const pj_str_t *dst_uri)
     /* Attach call data to invite session */
     call->inv->mod_data[mod_siprtp.id] = call;
 
+    /* Mark start of call */
+    pj_gettimeofday(&call->start_time);
+
 
     /* Create initial INVITE request.
      * This INVITE request will contain a perfectly good request and 
@@ -528,17 +574,34 @@ static void process_incoming_call(pjsip_rx_data *rdata)
     /* Create UAS invite session */
     status = pjsip_inv_create_uas( dlg, rdata, sdp, 0, &call->inv);
     if (status != PJ_SUCCESS) {
-	pjsip_dlg_terminate(dlg);
+	pjsip_dlg_create_response(dlg, rdata, 500, NULL, &tdata);
+	pjsip_dlg_send_response(dlg, pjsip_rdata_get_tsx(rdata), tdata);
 	return;
     }
     
+
     /* Attach call data to invite session */
     call->inv->mod_data[mod_siprtp.id] = call;
 
+    /* Mark start of call */
+    pj_gettimeofday(&call->start_time);
+
+
+
     /* Create 200 response .*/
     status = pjsip_inv_initial_answer(call->inv, rdata, 200, 
 				      NULL, NULL, &tdata);
-    PJ_ASSERT_ON_FAIL(status == PJ_SUCCESS, return);
+    if (status != PJ_SUCCESS) {
+	status = pjsip_inv_initial_answer(call->inv, rdata, 
+					  PJSIP_SC_NOT_ACCEPTABLE,
+					  NULL, NULL, &tdata);
+	if (status == PJ_SUCCESS)
+	    pjsip_inv_send_msg(call->inv, tdata); 
+	else
+	    pjsip_inv_terminate(call->inv, 500, PJ_FALSE);
+	return;
+    }
+
 
     /* Send the 200 response. */  
     status = pjsip_inv_send_msg(call->inv, tdata); 
@@ -562,6 +625,10 @@ static void call_on_forked(pjsip_inv_session *inv, pjsip_event *e)
 /* Callback to be called to handle incoming requests outside dialogs: */
 static pj_bool_t on_rx_request( pjsip_rx_data *rdata )
 {
+    /* Ignore strandled ACKs (must not send respone */
+    if (rdata->msg_info.msg->line.req.method.id == PJSIP_ACK_METHOD)
+	return PJ_FALSE;
+
     /* Respond (statelessly) any non-INVITE requests with 500  */
     if (rdata->msg_info.msg->line.req.method.id != PJSIP_INVITE_METHOD) {
 	pj_str_t reason = pj_str("Unsupported Operation");
@@ -583,18 +650,50 @@ static pj_bool_t on_rx_request( pjsip_rx_data *rdata )
 static void call_on_state_changed( pjsip_inv_session *inv, 
 				   pjsip_event *e)
 {
+    struct call *call = inv->mod_data[mod_siprtp.id];
+
     PJ_UNUSED_ARG(e);
 
-    if (inv->state == PJSIP_INV_STATE_DISCONNECTED) {
-	struct call *call = inv->mod_data[mod_siprtp.id];
+    if (!call)
+	return;
 
-	if (!call)
-	    return;
+    if (inv->state == PJSIP_INV_STATE_DISCONNECTED) {
+	
+	pj_time_val null_time = {0, 0};
 
 	call->inv = NULL;
 	inv->mod_data[mod_siprtp.id] = NULL;
 
 	destroy_call_media(call->index);
+
+	call->start_time = null_time;
+	call->response_time = null_time;
+	call->connect_time = null_time;
+
+	PJ_LOG(3,(THIS_FILE, "Call #%d disconnected. Reason=%s",
+		  call->index,
+		  pjsip_get_status_text(inv->cause)->ptr));
+
+    } else if (inv->state == PJSIP_INV_STATE_CONFIRMED) {
+
+	pj_time_val t;
+
+	pj_gettimeofday(&call->connect_time);
+	if (call->response_time.sec == 0)
+	    call->response_time = call->connect_time;
+
+	t = call->connect_time;
+	PJ_TIME_VAL_SUB(t, call->start_time);
+
+	PJ_LOG(3,(THIS_FILE, "Call #%d connected in %d ms", call->index,
+		  PJ_TIME_VAL_MSEC(t)));
+
+    } else if (	inv->state == PJSIP_INV_STATE_EARLY ||
+		inv->state == PJSIP_INV_STATE_CONNECTING) {
+
+	if (call->response_time.sec == 0)
+	    pj_gettimeofday(&call->response_time);
+
     }
 }
 
@@ -626,16 +725,30 @@ static int worker_thread(void *arg)
 
 /* Usage */
 static const char *USAGE = 
-"Usage:							\n"
-"   siprtp [options]        => to start in server mode	\n"
-"   siprtp [options] URL    => to start in client mode	\n"
+"Usage:\n"
+"   siprtp [options]        => to start in server mode\n"
+"   siprtp [options] URL    => to start in client mode\n"
+"\n"
+"Program options:\n"
+"   --count=N,        -c    Set number of calls to create (default:1) \n"
 "\n"
-"where options are:		\n"
-"   --count=N,       -c     Set number of calls to create (default:1) \n"
-"   --port=PORT      -p     Set local SIP port (default: 5060)	 \n"
-"   --rtp-port=PORT  -r     Set start of RTP port (default: 4000)     \n"
-"   --ip-addr=IP     -i     Set local IP address to use (otherwise it will\n"
+"Address and ports options:\n"
+"   --local-port=PORT,-p    Set local SIP port (default: 5060)\n"
+"   --rtp-port=PORT,  -r    Set start of RTP port (default: 4000)\n"
+"   --ip-addr=IP,     -i    Set local IP address to use (otherwise it will\n"
 "                           try to determine local IP address from hostname)\n"
+"\n"
+"Logging Options:\n"
+"   --log-level=N,    -l    Set log verbosity level (default=5)\n"
+"   --app-log-level=N       Set app screen log verbosity (default=3)\n"
+"   --log-file=FILE         Write log to file FILE\n"
+"\n"
+"Codec Options:\n"
+"   --a-pt=PT               Set audio payload type to PT (default=0)\n"
+"   --a-name=NAME           Set audio codec name to NAME (default=pcmu)\n"
+"   --a-clock=RATE          Set audio codec rate to RATE Hz (default=8000 Hz)\n"
+"   --a-bitrate=BPS         Set audio codec bitrate to BPS (default=64000 bps)\n"
+"   --a-ptime=MS            Set audio frame time to MS msec (default=20 msec)\n"
 ;
 
 
@@ -645,11 +758,25 @@ static pj_status_t init_options(int argc, char *argv[])
     static char ip_addr[32];
     static char local_uri[64];
 
+    enum { OPT_START,
+	   OPT_APP_LOG_LEVEL, OPT_LOG_FILE, 
+	   OPT_A_PT, OPT_A_NAME, OPT_A_CLOCK, OPT_A_BITRATE, OPT_A_PTIME };
+
     struct pj_getopt_option long_options[] = {
-	{ "count",	1, 0, 'c' },
-	{ "port",	1, 0, 'p' },
-	{ "rtp-port",	1, 0, 'r' },
-	{ "ip-addr",	1, 0, 'i' },
+	{ "count",	    1, 0, 'c' },
+	{ "local-port",	    1, 0, 'p' },
+	{ "rtp-port",	    1, 0, 'r' },
+	{ "ip-addr",	    1, 0, 'i' },
+
+	{ "log-level",	    1, 0, 'l' },
+	{ "app-log-level",  1, 0, OPT_APP_LOG_LEVEL },
+	{ "log-file",	    1, 0, OPT_LOG_FILE },
+	{ "a-pt",	    1, 0, OPT_A_PT },
+	{ "a-name",	    1, 0, OPT_A_NAME },
+	{ "a-clock",	    1, 0, OPT_A_CLOCK },
+	{ "a-bitrate",	    1, 0, OPT_A_BITRATE },
+	{ "a-ptime",	    1, 0, OPT_A_PTIME },
+
 	{ NULL, 0, 0, 0 },
     };
     int c;
@@ -667,16 +794,22 @@ static pj_status_t init_options(int argc, char *argv[])
 	pj_ansi_strcpy(ip_addr, addr);
     }
 
-    /* Init default */
+    /* Init defaults */
     app.max_calls = 1;
     app.thread_count = 1;
     app.sip_port = 5060;
     app.rtp_start_port = 4000;
     app.local_addr = ip_addr;
+    app.log_level = 5;
+    app.app_log_level = 3;
+    app.log_filename = NULL;
+
+    /* Default codecs: */
+    app.audio_codec = audio_codecs[0];
 
     /* Parse options */
     pj_optind = 0;
-    while((c=pj_getopt_long(argc,argv, "c:p:r:i:", 
+    while((c=pj_getopt_long(argc,argv, "c:p:r:i:l:", 
 			    long_options, &option_index))!=-1) 
     {
 	switch (c) {
@@ -696,6 +829,33 @@ static pj_status_t init_options(int argc, char *argv[])
 	case 'i':
 	    app.local_addr = pj_optarg;
 	    break;
+
+	case 'l':
+	    app.log_level = atoi(pj_optarg);
+	    break;
+	case OPT_APP_LOG_LEVEL:
+	    app.app_log_level = atoi(pj_optarg);
+	    break;
+	case OPT_LOG_FILE:
+	    app.log_filename = pj_optarg;
+	    break;
+
+	case OPT_A_PT:
+	    app.audio_codec.pt = atoi(pj_optarg);
+	    break;
+	case OPT_A_NAME:
+	    app.audio_codec.name = pj_optarg;
+	    break;
+	case OPT_A_CLOCK:
+	    app.audio_codec.clock_rate = atoi(pj_optarg);
+	    break;
+	case OPT_A_BITRATE:
+	    app.audio_codec.bit_rate = atoi(pj_optarg);
+	    break;
+	case OPT_A_PTIME:
+	    app.audio_codec.ptime = atoi(pj_optarg);
+	    break;
+
 	default:
 	    puts(USAGE);
 	    return 1;
@@ -716,8 +876,7 @@ static pj_status_t init_options(int argc, char *argv[])
 }
 
 
-//////////////////////////////////////////////////////////////////////////////
-/*
+/*****************************************************************************
  * MEDIA STUFFS
  */
 
@@ -780,13 +939,13 @@ static pj_status_t create_sdp( pj_pool_t *pool,
     {
 	pjmedia_sdp_rtpmap rtpmap;
 	pjmedia_sdp_attr *attr;
+	char ptstr[10];
 
-	PJ_TODO(PARAMETERIZE_CODEC);
-
-	m->desc.fmt[0] = pj_str("0");
-	rtpmap.pt = pj_str("0");
-	rtpmap.clock_rate = 8000;
-	rtpmap.enc_name = pj_str("pcmu");
+	sprintf(ptstr, "%d", app.audio_codec.pt);
+	pj_strdup2(pool, &m->desc.fmt[0], ptstr);
+	rtpmap.pt = m->desc.fmt[0];
+	rtpmap.clock_rate = app.audio_codec.clock_rate;
+	rtpmap.enc_name = pj_str(app.audio_codec.name);
 	rtpmap.param.slen = 0;
 
 	pjmedia_sdp_rtpmap_to_attr(pool, &rtpmap, &attr);
@@ -802,16 +961,16 @@ static pj_status_t create_sdp( pj_pool_t *pool,
     /*
      * Add support telephony event
      */
-    m->desc.fmt[m->desc.fmt_count++] = pj_str("101");
+    m->desc.fmt[m->desc.fmt_count++] = pj_str("121");
     /* Add rtpmap. */
     attr = pj_pool_zalloc(pool, sizeof(pjmedia_sdp_attr));
     attr->name = pj_str("rtpmap");
-    attr->value = pj_str(":101 telephone-event/8000");
+    attr->value = pj_str(":121 telephone-event/8000");
     m->attr[m->attr_count++] = attr;
     /* Add fmtp */
     attr = pj_pool_zalloc(pool, sizeof(pjmedia_sdp_attr));
     attr->name = pj_str("fmtp");
-    attr->value = pj_str(":101 0-15");
+    attr->value = pj_str(":121 0-15");
     m->attr[m->attr_count++] = attr;
 #endif
 
@@ -822,7 +981,11 @@ static pj_status_t create_sdp( pj_pool_t *pool,
 }
 
 
-/* Media thread */
+/* 
+ * Media thread 
+ *
+ * This is the thread to send and receive both RTP and RTCP packets.
+ */
 static int media_thread(void *arg)
 {
     struct media_stream *strm = arg;
@@ -880,6 +1043,9 @@ static int media_thread(void *arg)
 		continue;
 	    }
 
+	    ++strm->rx_stat.pkt;
+	    strm->rx_stat.payload += (size - 12);
+
 	    /* Decode RTP packet. */
 	    status = pjmedia_rtp_decode_rtp(&strm->in_sess, 
 					    packet, size, 
@@ -887,6 +1053,7 @@ static int media_thread(void *arg)
 					    &payload, &payload_len);
 	    if (status != PJ_SUCCESS) {
 		app_perror(THIS_FILE, "RTP decode error", status);
+		strm->rx_stat.discard++;
 		continue;
 	    }
 
@@ -899,6 +1066,7 @@ static int media_thread(void *arg)
 		app_perror(THIS_FILE, "RTP update error", status);
 		PJ_LOG(3,(THIS_FILE,"RTP packet detail: pt=%d, seq=%d",
 			  hdr->pt, pj_ntohs(hdr->seq)));
+		strm->rx_stat.discard++;
 		continue;
 	    }
 
@@ -919,10 +1087,29 @@ static int media_thread(void *arg)
 	    if (status != PJ_SUCCESS)
 		app_perror(THIS_FILE, "Error receiving RTCP packet", status);
 	    else {
-		if (size > sizeof(strm->rem_rtcp))
+		if (size > sizeof(strm->rem_rtcp)) {
 		    PJ_LOG(3,(THIS_FILE, "Error: RTCP packet too large"));
-		else
+		    status = -1;
+		} else {
 		    pj_memcpy(&strm->rem_rtcp, packet, size);
+		    status = PJ_SUCCESS;
+		}
+	    }
+
+	    if (status == PJ_SUCCESS) {
+		/* Process RTCP stats */
+		unsigned jitter;
+		
+		jitter = pj_ntohl(strm->rem_rtcp.rr.jitter) * 1000 /
+			 strm->clock_rate;
+		if (jitter < strm->tx_stat.jitter_min)
+		    strm->tx_stat.jitter_min = jitter;
+		if (jitter > strm->tx_stat.jitter_max)
+		    strm->tx_stat.jitter_max = jitter;
+		strm->tx_stat.jitter_avg = (strm->tx_stat.jitter_avg * strm->tx_stat.rtcp_cnt +
+					    jitter) / (strm->tx_stat.rtcp_cnt + 1);
+
+		strm->tx_stat.rtcp_cnt++;
 	    }
 	}
 
@@ -969,6 +1156,10 @@ static int media_thread(void *arg)
 	    /* Schedule next send */
 	    next_rtp.msec += strm->samples_per_frame * 1000 / strm->clock_rate;
 	    pj_time_val_normalize(&next_rtp);
+
+	    /* Update stats */
+	    strm->tx_stat.pkt++;
+	    strm->tx_stat.payload += strm->bytes_per_frame;
 	}
 
 
@@ -1001,6 +1192,22 @@ static int media_thread(void *arg)
 	    }
 	    
 
+	    /* Process RTCP stats */
+	    {
+		unsigned jitter;
+		
+		jitter = pj_ntohl(rtcp_pkt->rr.jitter) * 1000 /
+			 strm->clock_rate;
+		if (jitter < strm->rx_stat.jitter_min)
+		    strm->rx_stat.jitter_min = jitter;
+		if (jitter > strm->rx_stat.jitter_max)
+		    strm->rx_stat.jitter_max = jitter;
+		strm->rx_stat.jitter_avg = (strm->rx_stat.jitter_avg * strm->rx_stat.rtcp_cnt +
+					    jitter) / (strm->rx_stat.rtcp_cnt + 1);
+
+		strm->rx_stat.rtcp_cnt++;
+	    }
+
 	    next_rtcp.sec += 5;
 	}
 
@@ -1018,7 +1225,8 @@ static void call_on_media_update( pjsip_inv_session *inv,
     pj_pool_t *pool;
     struct media_stream *audio;
     pjmedia_sdp_session *local_sdp, *remote_sdp;
-
+    struct codec *codec_desc = NULL;
+    unsigned i;
 
     call = inv->mod_data[mod_siprtp.id];
     pool = inv->dlg->pool;
@@ -1047,11 +1255,27 @@ static void call_on_media_update( pjsip_inv_session *inv,
 	return;
     }
 
+    /* Get the remainder of codec information from codec descriptor */
+    if (audio->si.fmt.pt == app.audio_codec.pt)
+	codec_desc = &app.audio_codec;
+    else {
+	/* Find the codec description in codec array */
+	for (i=0; i<PJ_ARRAY_SIZE(audio_codecs); ++i) {
+	    if (audio_codecs[i].pt == audio->si.fmt.pt) {
+		codec_desc = &audio_codecs[i];
+		break;
+	    }
+	}
+
+	if (codec_desc == NULL) {
+	    PJ_LOG(3, (THIS_FILE, "Error: Invalid codec payload type"));
+	    return;
+	}
+    }
 
     audio->clock_rate = audio->si.fmt.sample_rate;
-    audio->samples_per_frame = audio->clock_rate * 20 / 1000;
-    audio->bytes_per_frame = 160;
-    PJ_TODO(TAKE_CODEC_INFO_FROM_ARGUMENT);
+    audio->samples_per_frame = audio->clock_rate * codec_desc->ptime / 1000;
+    audio->bytes_per_frame = codec_desc->bit_rate * codec_desc->ptime / 1000 / 8;
 
 
     pjmedia_rtp_session_init(&audio->out_sess, audio->si.tx_pt, 
@@ -1059,6 +1283,12 @@ static void call_on_media_update( pjsip_inv_session *inv,
     pjmedia_rtp_session_init(&audio->in_sess, audio->si.fmt.pt, 0);
     pjmedia_rtcp_init(&audio->rtcp, 0);
 
+
+    /* Clear media statistics */
+    pj_memset(&audio->rx_stat, 0, sizeof(audio->rx_stat));
+    pj_memset(&audio->tx_stat, 0, sizeof(audio->tx_stat));
+
+
     /* Start media thread. */
     audio->thread_quit_flag = 0;
     status = pj_thread_create( inv->pool, "media", &media_thread, audio,
@@ -1081,12 +1311,39 @@ static void destroy_call_media(unsigned call_index)
 	pj_thread_destroy(audio->thread);
 	audio->thread = NULL;
 	audio->thread_quit_flag = 0;
+
+	/* Flush RTP/RTCP packets */
+	{
+	    pj_fd_set_t set;
+	    pj_time_val timeout = {0, 0};
+	    char packet[1500];
+	    pj_ssize_t size;
+	    pj_status_t status;
+	    int rc;
+
+	    do {
+		PJ_FD_ZERO(&set);
+		PJ_FD_SET(audio->rtp_sock, &set);
+		PJ_FD_SET(audio->rtcp_sock, &set);
+
+		rc = pj_sock_select(FD_SETSIZE, &set, NULL, NULL, &timeout);
+		if (rc > 0 && PJ_FD_ISSET(audio->rtp_sock, &set)) {
+		    size = sizeof(packet);
+		    status = pj_sock_recv(audio->rtp_sock, packet, &size, 0);
+
+		} 
+		if (rc > 0 && PJ_FD_ISSET(audio->rtcp_sock, &set)) {
+		    size = sizeof(packet);
+		    status = pj_sock_recv(audio->rtcp_sock, packet, &size, 0);
+		}
+
+	    } while (rc > 0);
+	}
     }
 }
 
 
-/////////////////////////////////////////////////////////////////////////////
-/*
+/*****************************************************************************
  * USER INTERFACE STUFFS
  */
 
@@ -1110,41 +1367,144 @@ static const char *good_number(char *buf, pj_int32_t val)
 
 static void print_call(int call_index)
 {
+    struct call *call = &app.call[call_index];
     int len;
-    pjsip_inv_session *inv = app.call[call_index].inv;
+    pjsip_inv_session *inv = call->inv;
     pjsip_dialog *dlg = inv->dlg;
-    struct media_stream *audio = &app.call[call_index].media[0];
+    struct media_stream *audio = &call->media[0];
     char userinfo[128];
-    char packets[16];
+    char duration[80];
+    char bps[16], ipbps[16], packets[16], bytes[16], ipbytes[16];
+    pj_uint32_t total_loss;
+
+
+    /* Print duration */
+    if (inv->state == PJSIP_INV_STATE_CONFIRMED) {
+	pj_time_val now;
 
-    /* Dump invite sesion info. */
+	pj_gettimeofday(&now);
+	PJ_TIME_VAL_SUB(now, call->connect_time);
+
+	sprintf(duration, " [duration: %02d:%02d:%02d.%03d]",
+		now.sec / 3600,
+		(now.sec % 3600) / 60,
+		(now.sec % 60),
+		now.msec);
+
+    } else {
+	duration[0] = '\0';
+    }
 
+
+
+    /* Call number and state */
+    printf("Call #%d: %s%s\n", call_index, pjsip_inv_state_name(inv->state), 
+			       duration);
+
+
+
+    /* Call identification */
     len = pjsip_hdr_print_on(dlg->remote.info, userinfo, sizeof(userinfo));
     if (len < 1)
 	pj_ansi_strcpy(userinfo, "<--uri too long-->");
     else
 	userinfo[len] = '\0';
-    
-    printf("Call #%d: %s\n", call_index, pjsip_inv_state_name(inv->state));
+
     printf("   %s\n", userinfo);
 
-    if (app.call[call_index].media[0].thread == NULL) {
+
+    /* Signaling quality */
+    {
+	char pdd[64], connectdelay[64];
+	pj_time_val t;
+
+	if (call->response_time.sec) {
+	    t = call->response_time;
+	    PJ_TIME_VAL_SUB(t, call->start_time);
+	    sprintf(pdd, "got 1st response in %d ms", PJ_TIME_VAL_MSEC(t));
+	} else {
+	    pdd[0] = '\0';
+	}
+
+	if (call->connect_time.sec) {
+	    t = call->connect_time;
+	    PJ_TIME_VAL_SUB(t, call->start_time);
+	    sprintf(connectdelay, ", connected after: %d ms", PJ_TIME_VAL_MSEC(t));
+	} else {
+	    connectdelay[0] = '\0';
+	}
+
+	printf("   Signaling quality: %s%s\n", pdd, connectdelay);
+    }
+
+
+    if (call->media[0].thread == NULL) {
 	return;
     }
 
-    printf("   Stream #0: audio %.*s@%dHz, %d bytes/sec\n",
+    printf("   Stream #0: audio %.*s@%dHz, %dms/frame, %sbps (%sbps +IP hdr)\n",
 	   (int)audio->si.fmt.encoding_name.slen,
 	   audio->si.fmt.encoding_name.ptr,
 	   audio->clock_rate,
-	   audio->bytes_per_frame * audio->clock_rate / audio->samples_per_frame);
-    printf("              RX pkt=%s, fraction lost=%5.2f%%, jitter=%dms\n",
-	   good_number(packets, audio->rtcp.received),
-	   audio->rtcp.rtcp_pkt.rr.fract_lost/255.0,
-	   pj_ntohl(audio->rtcp.rtcp_pkt.rr.jitter) * 1000 / audio->clock_rate);
-    printf("              TX pkt=%s, fraction lost=%5.2f%%, jitter=%dms\n",
-	   good_number(packets, pj_ntohl(audio->rtcp.rtcp_pkt.sr.sender_pcount)),
-	   audio->rem_rtcp.rr.fract_lost/255.0,
-	   pj_ntohl(audio->rem_rtcp.rr.jitter) * 1000 / audio->clock_rate);
+	   audio->samples_per_frame * 1000 / audio->clock_rate,
+	   good_number(bps, audio->bytes_per_frame * audio->clock_rate / audio->samples_per_frame),
+	   good_number(ipbps, (audio->bytes_per_frame+32) * audio->clock_rate / audio->samples_per_frame));
+
+    total_loss = (audio->rtcp.rtcp_pkt.rr.total_lost_2 << 16) +
+	         (audio->rtcp.rtcp_pkt.rr.total_lost_1 << 8) +
+		 audio->rtcp.rtcp_pkt.rr.total_lost_0;
+
+    printf("              RX total %s packets %sB received (%sB +IP hdr)%s\n"
+	   "                 pkt discards=%d (%3.1f%%), loss=%d (%3.1f%%), reorder=%d (%3.1f%%)%s\n"
+	   "                 loss period min=%d ms, avg=%d ms, max=%d ms%s\n"
+	   "                 jitter min=%d ms, avg=%d ms, max=%d ms, current=%d ms%s\n",
+	   good_number(packets, audio->rx_stat.pkt),
+	   good_number(bytes, audio->rx_stat.payload),
+	   good_number(ipbytes, audio->rx_stat.payload + audio->rx_stat.pkt * 32),
+	   "",
+	   audio->rx_stat.discard, 
+	   audio->rx_stat.discard * 100.0 / audio->rx_stat.pkt,
+	   total_loss,
+	   total_loss * 100.0 / audio->rx_stat.pkt,
+	   0, 0.0,
+	   "",
+	   -1, -1, -1, 
+	   "",
+	   (audio->rx_stat.rtcp_cnt ? audio->rx_stat.jitter_min : -1), 
+	   (audio->rx_stat.rtcp_cnt ? audio->rx_stat.jitter_avg : -1),
+	   (audio->rx_stat.rtcp_cnt ? audio->rx_stat.jitter_max : -1),
+	   (audio->rx_stat.rtcp_cnt ? pj_ntohl(audio->rtcp.rtcp_pkt.rr.jitter)*1000/audio->clock_rate : -1),
+	   ""
+	   );
+
+
+    total_loss = (audio->rem_rtcp.rr.total_lost_2 << 16) +
+	         (audio->rem_rtcp.rr.total_lost_1 << 8) +
+		  audio->rem_rtcp.rr.total_lost_0;
+
+    printf("              TX total %s packets %sB sent (%sB +IP hdr)%s\n"
+	   "                 pkt discards=%d (%3.1f%%), loss=%d (%3.1f%%), reorder=%d (%3.1f%%)%s\n"
+	   "                 loss period min=%d ms, avg=%d ms, max=%d ms%s\n"
+	   "                 jitter min=%d ms, avg=%d ms, max=%d ms, current=%d ms%s\n",
+	   good_number(packets, audio->tx_stat.pkt),
+	   good_number(bytes, audio->tx_stat.payload),
+	   good_number(ipbytes, audio->tx_stat.payload + audio->tx_stat.pkt * 32),
+	   "",
+	   audio->tx_stat.discard, 
+	   audio->tx_stat.discard * 100.0 / audio->tx_stat.pkt,
+	   total_loss,
+	   total_loss * 100.0 / audio->tx_stat.pkt,
+	   0, 0.0,
+	   "",
+	   -1, -1, -1, 
+	   "",
+	   (audio->tx_stat.rtcp_cnt ? audio->tx_stat.jitter_min : -1), 
+	   (audio->tx_stat.rtcp_cnt ? audio->tx_stat.jitter_avg : -1),
+	   (audio->tx_stat.rtcp_cnt ? audio->tx_stat.jitter_max : -1),
+	   (audio->tx_stat.rtcp_cnt ? pj_ntohl(audio->rem_rtcp.rr.jitter)*1000/audio->clock_rate : -1),
+	   ""
+	   );
+
 }
 
 
@@ -1218,6 +1578,8 @@ static void console_main()
     char input1[10];
     unsigned i;
 
+    printf("%s", MENU);
+
     for (;;) {
 	printf(">>> "); fflush(stdout);
 	fgets(input1, sizeof(input1), stdin);
@@ -1243,6 +1605,7 @@ static void console_main()
 	    goto on_exit;
 
 	default:
+	    puts("Invalid command");
 	    printf("%s", MENU);
 	    break;
 	}
@@ -1251,12 +1614,17 @@ static void console_main()
     }
 
 on_exit:
-    ;
+    hangup_all_calls();
 }
 
 
+/*****************************************************************************
+ * Below is a simple module to log all incoming and outgoing SIP messages
+ */
+
+
 /* Notification on incoming messages */
-static pj_bool_t console_on_rx_msg(pjsip_rx_data *rdata)
+static pj_bool_t logger_on_rx_msg(pjsip_rx_data *rdata)
 {
     PJ_LOG(4,(THIS_FILE, "RX %d bytes %s from %s:%d:\n"
 			 "%s\n"
@@ -1272,7 +1640,7 @@ static pj_bool_t console_on_rx_msg(pjsip_rx_data *rdata)
 }
 
 /* Notification on outgoing messages */
-static pj_status_t console_on_tx_msg(pjsip_tx_data *tdata)
+static pj_status_t logger_on_tx_msg(pjsip_tx_data *tdata)
 {
     
     /* Important note:
@@ -1305,32 +1673,94 @@ static pjsip_module msg_logger =
     NULL,				/* start()		*/
     NULL,				/* stop()		*/
     NULL,				/* unload()		*/
-    &console_on_rx_msg,			/* on_rx_request()	*/
-    &console_on_rx_msg,			/* on_rx_response()	*/
-    &console_on_tx_msg,			/* on_tx_request.	*/
-    &console_on_tx_msg,			/* on_tx_response()	*/
+    &logger_on_rx_msg,			/* on_rx_request()	*/
+    &logger_on_rx_msg,			/* on_rx_response()	*/
+    &logger_on_tx_msg,			/* on_tx_request.	*/
+    &logger_on_tx_msg,			/* on_tx_response()	*/
     NULL,				/* on_tsx_state()	*/
 
 };
 
 
 
+/*****************************************************************************
+ * Console application custom logging:
+ */
+
+
+static FILE *log_file;
+
+
+static void app_log_writer(int level, const char *buffer, int len)
+{
+    /* Write to both stdout and file. */
+
+    if (level <= app.app_log_level)
+	pj_log_write(level, buffer, len);
+
+    if (log_file) {
+	fwrite(buffer, len, 1, log_file);
+	fflush(log_file);
+    }
+}
+
+
+pj_status_t app_logging_init(void)
+{
+    /* Redirect log function to ours */
+
+    pj_log_set_log_func( &app_log_writer );
+
+    /* If output log file is desired, create the file: */
+
+    if (app.log_filename) {
+	log_file = fopen(app.log_filename, "wt");
+	if (log_file == NULL) {
+	    PJ_LOG(1,(THIS_FILE, "Unable to open log file %s", 
+		      app.log_filename));   
+	    return -1;
+	}
+    }
+
+    return PJ_SUCCESS;
+}
+
+
+void app_logging_shutdown(void)
+{
+    /* Close logging file, if any: */
+
+    if (log_file) {
+	fclose(log_file);
+	log_file = NULL;
+    }
+}
+
 
 /*
  * main()
  */
 int main(int argc, char *argv[])
 {
+    unsigned i;
     pj_status_t status;
 
+    /* Must init PJLIB first */
     status = pj_init();
     if (status != PJ_SUCCESS)
 	return 1;
 
+    /* Get command line options */
     status = init_options(argc, argv);
     if (status != PJ_SUCCESS)
 	return 1;
 
+    /* Init logging */
+    status = app_logging_init();
+    if (status != PJ_SUCCESS)
+	return 1;
+
+    /* Init SIP etc */
     status = init_sip();
     if (status != PJ_SUCCESS) {
 	app_perror(THIS_FILE, "Initialization has failed", status);
@@ -1338,8 +1768,10 @@ int main(int argc, char *argv[])
 	return 1;
     }
 
+    /* Register module to log incoming/outgoing messages */
     pjsip_endpt_register_module(app.sip_endpt, &msg_logger);
 
+    /* Init media */
     status = init_media();
     if (status != PJ_SUCCESS) {
 	app_perror(THIS_FILE, "Media initialization failed", status);
@@ -1347,9 +1779,13 @@ int main(int argc, char *argv[])
 	return 1;
     }
 
+    /* If URL is specified, then make call immediately */
     if (app.uri_to_call.slen) {
 	unsigned i;
 
+	PJ_LOG(3,(THIS_FILE, "Making %d calls to %s..", app.max_calls,
+		  app.uri_to_call.ptr));
+
 	for (i=0; i<app.max_calls; ++i) {
 	    status = make_call(&app.uri_to_call);
 	    if (status != PJ_SUCCESS) {
@@ -1357,13 +1793,28 @@ int main(int argc, char *argv[])
 		break;
 	    }
 	}
+
+    } else {
+
+	PJ_LOG(3,(THIS_FILE, "Ready for incoming calls (max=%d)", 
+		  app.max_calls));
     }
-   
-    console_main();
 
+    /* Start worker threads */
+    for (i=0; i<app.thread_count; ++i) {
+	pj_thread_create( app.pool, "app", &worker_thread, NULL,
+			  0, 0, &app.thread[i]);
+    }
+
+    /* Start user interface loop */
+    console_main();
 
+    
+    /* Shutting down... */
     destroy_media();
     destroy_sip();
+    app_logging_shutdown();
+
 
     return 0;
 }