Changeset 379

Timestamp:

Apr 4, 2006 1:12:38 PM (19 years ago)

Author:

bennylp

Message:

Added more stats and options in siprtp samples

Location:

pjproject/trunk/pjsip-apps

Files:

• build/Samples-vc.mak (modified) (1 diff)
• build/Samples.mak (modified) (1 diff)
• src/samples/siprtp.c (modified) (44 diffs)

pjproject/trunk/pjsip-apps/build/Samples-vc.mak

@@ -41 +41 @@
           $(BINDIR)\confsample.exe $(BINDIR)\sndinfo.exe \
           $(BINDIR)\level.exe $(BINDIR)\recfile.exe  \
-          $(BINDIR)\resampleplay.exe
+          $(BINDIR)\resampleplay.exe $(BINDIR)\siprtp.exe
 
 

pjproject/trunk/pjsip-apps/build/Samples.mak

@@ -39 +39 @@
 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))

pjproject/trunk/pjsip-apps/src/samples/siprtp.c

@@ -35 +35 @@
 
 
+/* 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
@@ -61 +85 @@
     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  */
@@ -73 +101 @@
     unsigned             media_count;
     struct media_stream  media[2];
+    pj_time_val          start_time;
+    pj_time_val          response_time;
+    pj_time_val          connect_time;
 };
 
@@ -85 +116 @@
     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;
@@ -133 +170 @@
 static void app_perror(const char *sender, const char *title, 
                        pj_status_t status);
+
+
 
 
@@ -158 +197 @@
 
 
+/* 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
@@ -163 +213 @@
 static pj_status_t init_sip()
 {
-    unsigned i;
     pj_status_t status;
 
@@ -241 +290 @@
     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 */
@@ -463 +506 @@
     call->inv->mod_data[mod_siprtp.id] = call;
 
+    /* Mark start of call */
+    pj_gettimeofday(&call->start_time);
+
 
     /* Create initial INVITE request.
@@ -529 +575 @@
     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. */  
@@ -563 +626 @@
 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) {
@@ -584 +651 @@
                                    pjsip_event *e)
 {
+    struct call *call = inv->mod_data[mod_siprtp.id];
+
     PJ_UNUSED_ARG(e);
 
+    if (!call)
+        return;
+
     if (inv->state == PJSIP_INV_STATE_DISCONNECTED) {
-        struct call *call = inv->mod_data[mod_siprtp.id];
-
-        if (!call)
-            return;
+        
+        pj_time_val null_time = {0, 0};
 
         call->inv = NULL;
@@ -596 +666 @@
 
         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);
+
     }
 }
@@ -627 +726 @@
 /* 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"
-"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"
+"Program options:\n"
+"   --count=N,        -c    Set number of calls to create (default:1) \n"
+"\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"
 ;
 
@@ -646 +759 @@
     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 },
     };
@@ -668 +795 @@
     }
 
-    /* Init default */
+    /* Init defaults */
     app.max_calls = 1;
     app.thread_count = 1;
@@ -674 +801 @@
     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) 
     {
@@ -697 +830 @@
             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);
@@ -717 +877 @@
 
 
-//////////////////////////////////////////////////////////////////////////////
-/*
+/*****************************************************************************
  * MEDIA STUFFS
  */
@@ -781 +940 @@
         pjmedia_sdp_rtpmap rtpmap;
         pjmedia_sdp_attr *attr;
-
-        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");
+        char ptstr[10];
+
+        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;
 
@@ -803 +962 @@
      * 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
@@ -823 +982 @@
 
 
-/* Media thread */
+/* 
+ * Media thread 
+ *
+ * This is the thread to send and receive both RTP and RTCP packets.
+ */
 static int media_thread(void *arg)
 {
@@ -881 +1044 @@
             }
 
+            ++strm->rx_stat.pkt;
+            strm->rx_stat.payload += (size - 12);
+
             /* Decode RTP packet. */
             status = pjmedia_rtp_decode_rtp(&strm->in_sess, 
@@ -888 +1054 @@
             if (status != PJ_SUCCESS) {
                 app_perror(THIS_FILE, "RTP decode error", status);
+                strm->rx_stat.discard++;
                 continue;
             }
@@ -900 +1067 @@
                 PJ_LOG(3,(THIS_FILE,"RTP packet detail: pt=%d, seq=%d",
                           hdr->pt, pj_ntohs(hdr->seq)));
+                strm->rx_stat.discard++;
                 continue;
             }
@@ -920 +1088 @@
                 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++;
             }
         }
@@ -970 +1157 @@
             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;
         }
 
@@ -1002 +1193 @@
             
 
+            /* 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;
         }
@@ -1019 +1226 @@
     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];
@@ -1048 +1256 @@
     }
 
+    /* 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;
 
 
@@ -1059 +1283 @@
     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. */
@@ -1082 +1312 @@
         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
  */
@@ -1111 +1368 @@
 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];
-
-    /* Dump invite sesion info. */
-
+    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;
+
+        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)
@@ -1125 +1410 @@
     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),
+           ""
+           );
+
 }
 
@@ -1219 +1579 @@
     unsigned i;
 
+    printf("%s", MENU);
+
     for (;;) {
         printf(">>> "); fflush(stdout);
@@ -1244 +1606 @@
 
         default:
+            puts("Invalid command");
             printf("%s", MENU);
             break;
@@ -1252 +1615 @@
 
 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"
@@ -1273 +1641 @@
 
 /* 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)
 {
     
@@ -1306 +1674 @@
     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()       */
 
@@ -1315 +1683 @@
 
 
+
+/*****************************************************************************
+ * 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;
+    }
+}
 
 
@@ -1322 +1743 @@
 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) {
@@ -1339 +1769 @@
     }
 
+    /* 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) {
@@ -1348 +1780 @@
     }
 
+    /* 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) {
@@ -1358 +1794 @@
             }
         }
-    }
-   
+
+    } else {
+
+        PJ_LOG(3,(THIS_FILE, "Ready for incoming calls (max=%d)", 
+                  app.max_calls));
+    }
+
+    /* 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;