]> git.ipfire.org Git - thirdparty/freeswitch.git/commitdiff
merged threaded ftmod_r2.c with non-threaded version from moy and added support for...
authorArnaldo Pereira <arnaldo@sangoma.com>
Thu, 23 Sep 2010 20:51:45 +0000 (17:51 -0300)
committerArnaldo Pereira <arnaldo@sangoma.com>
Thu, 23 Sep 2010 20:51:45 +0000 (17:51 -0300)
libs/freetdm/src/ftdm_io.c
libs/freetdm/src/ftmod/ftmod_analog/ftmod_analog.c
libs/freetdm/src/ftmod/ftmod_analog_em/ftmod_analog_em.c
libs/freetdm/src/ftmod/ftmod_isdn/ftmod_isdn.c
libs/freetdm/src/ftmod/ftmod_libpri/ftmod_libpri.c
libs/freetdm/src/ftmod/ftmod_r2/ftmod_r2.c
libs/freetdm/src/ftmod/ftmod_sangoma_boost/ftmod_sangoma_boost.c
libs/freetdm/src/ftmod/ftmod_wanpipe/ftmod_wanpipe.c
libs/freetdm/src/include/freetdm.h

index 18ae87c540a4a5c402099898ed6eea70b94e6ff8..2ffa26848e447c83cc002ca2432b4e095f45dd93 100644 (file)
@@ -895,12 +895,12 @@ FT_DECLARE(ftdm_status_t) ftdm_span_find(uint32_t id, ftdm_span_t **span)
        
 }
 
-FT_DECLARE(ftdm_status_t) ftdm_span_poll_event(ftdm_span_t *span, uint32_t ms)
+FT_DECLARE(ftdm_status_t) ftdm_span_poll_event(ftdm_span_t *span, uint32_t ms, short *poll_events)
 {
        assert(span->fio != NULL);
 
        if (span->fio->poll_event) {
-               return span->fio->poll_event(span, ms);
+               return span->fio->poll_event(span, ms, poll_events);
        } else {
                ftdm_log(FTDM_LOG_ERROR, "poll_event method not implemented in module %s!", span->fio->name);
        }
index 4dce1904ac1bfced7965a56cf064fdce1d87c3ca..dacda7e4485103a5deace07d34735b929d26867b 100644 (file)
@@ -966,7 +966,7 @@ static void *ftdm_analog_run(ftdm_thread_t *me, void *obj)
                int waitms = 1000;
                ftdm_status_t status;
 
-               if ((status = ftdm_span_poll_event(span, waitms)) != FTDM_FAIL) {
+               if ((status = ftdm_span_poll_event(span, waitms, NULL)) != FTDM_FAIL) {
                        errs = 0;
                }
                
index 081665b3fcccba0785d6c9fc79eb70bd7b63709a..199bba43a3408afe9dec935a035bede75603a00e 100644 (file)
@@ -657,7 +657,7 @@ static void *ftdm_analog_em_run(ftdm_thread_t *me, void *obj)
                int waitms = 10;
                ftdm_status_t status;
 
-               status = ftdm_span_poll_event(span, waitms);
+               status = ftdm_span_poll_event(span, waitms, NULL);
                
                switch(status) {
                case FTDM_SUCCESS:
index 3715e9844cded3b56ebad68a52bf705978f08e2b..65c9dfc11f90f59ee98f1bf41b03ff56992a0dc5 100644 (file)
@@ -1558,7 +1558,7 @@ static __inline__ void check_events(ftdm_span_t *span)
 {
        ftdm_status_t status;
 
-       status = ftdm_span_poll_event(span, 5);
+       status = ftdm_span_poll_event(span, 5, NULL);
 
        switch(status) {
        case FTDM_SUCCESS:
index ba4049a32f04cda5ea963795df46bac676f69e69..2dc223eb91daf9997ba103a07853c391f92cb76f 100644 (file)
@@ -890,7 +890,7 @@ static __inline__ void check_events(ftdm_span_t *span)
 {
        ftdm_status_t status;
 
-       status = ftdm_span_poll_event(span, 5);
+       status = ftdm_span_poll_event(span, 5, NULL);
 
        switch(status) {
        case FTDM_SUCCESS:
index 564a812496ec0ff8a8c45b098f4c2b3d212c07ab..53d00d126924e52d3e24eabf86e89e7ae8e492d0 100644 (file)
  */
 
 #include <stdio.h>
+#ifdef __linux__
+#include <syscall.h>
+#include <poll.h>
+#endif
 #include <openr2.h>
+#include "freetdm.h"
 #include "private/ftdm_core.h"
 
 /* debug thread count for r2 legs */
 static ftdm_mutex_t* g_thread_count_mutex;
 static int32_t g_thread_count = 0;
 
+typedef int openr2_call_status_t;
+
 /* when the users kills a span we clear this flag to kill the signaling thread */
 /* FIXME: what about the calls that are already up-and-running? */
 typedef enum {
        FTDM_R2_RUNNING = (1 << 0),
 } ftdm_r2_flag_t;
 
+typedef enum {
+       FTDM_R2_PROCESSING = (1 << 0),
+       FTDM_R2_WAITING_ACK = (1 << 1),
+} ftdm_r2_call_flag_t;
+
 /* private call information stored in ftdmchan->call_data void* ptr */
 #define R2CALL(ftdmchan) ((ftdm_r2_call_t*)((ftdmchan)->call_data))
 typedef struct ftdm_r2_call_t {
-    openr2_chan_t *r2chan;
+       openr2_chan_t *r2chan;
+       ftdm_r2_call_flag_t flags;
        int accepted:1;
        int answer_pending:1;
        int state_ack_pending:1;
@@ -58,6 +71,7 @@ typedef struct ftdm_r2_call_t {
        ftdm_size_t dnis_index;
        ftdm_size_t ani_index;
        char name[10];
+       unsigned long txdrops;
 } ftdm_r2_call_t;
 
 /* this is just used as place holder in the stack when configuring the span to avoid using bunch of locals */
@@ -82,6 +96,7 @@ typedef struct ft_r2_conf_s {
        int skip_category;
        int get_ani_first;
        int call_files;
+       int mf_files;
        int double_answer;
        int charge_calls;
        int forced_release;
@@ -104,6 +119,12 @@ typedef struct ftdm_r2_data_s {
        int forced_release:1;
        /* whether accept the call when offered, or wait until the user decides to accept */
        int accept_on_offer:1;
+       /* max time spent in ms doing real work in a single loop */
+       int jobmax;
+       /* total working loops */
+       unsigned long loops;
+       /* LWP */
+       unsigned long monitor_thread_id;
 } ftdm_r2_data_t;
 
 /* one element per span will be stored in g_mod_data_hash global var to keep track of them
@@ -116,9 +137,6 @@ typedef struct ftdm_r2_span_pvt_s {
 /* span monitor thread */
 static void *ftdm_r2_run(ftdm_thread_t *me, void *obj);
 
-/* channel monitor thread */
-static void *ftdm_r2_channel_run(ftdm_thread_t *me, void *obj);
-
 /* hash of all the private span allocations
    we need to keep track of them to destroy them when unloading the module 
    since freetdm does not notify signaling modules when destroying a span
@@ -128,6 +146,82 @@ static ftdm_hash_t *g_mod_data_hash;
 /* IO interface for the command API */
 static ftdm_io_interface_t g_ftdm_r2_interface;
 
+static int ftdm_r2_state_advance(ftdm_channel_t *ftdmchan);
+
+static ftdm_call_cause_t ftdm_r2_cause_to_ftdm_cause(ftdm_channel_t *fchan, openr2_call_disconnect_cause_t cause)
+{
+       switch (cause) {
+
+       case OR2_CAUSE_NORMAL_CLEARING:
+               return FTDM_CAUSE_NORMAL_CLEARING;
+
+       case OR2_CAUSE_BUSY_NUMBER:
+               return FTDM_CAUSE_USER_BUSY;
+
+       case OR2_CAUSE_NETWORK_CONGESTION:
+               return FTDM_CAUSE_SWITCH_CONGESTION;
+
+       case OR2_CAUSE_UNALLOCATED_NUMBER:
+               return FTDM_CAUSE_NO_ROUTE_DESTINATION;
+
+       case OR2_CAUSE_NUMBER_CHANGED:
+               return FTDM_CAUSE_NUMBER_CHANGED;
+
+       case OR2_CAUSE_OUT_OF_ORDER:
+               return FTDM_CAUSE_NETWORK_OUT_OF_ORDER;
+
+       case OR2_CAUSE_NO_ANSWER:
+               return FTDM_CAUSE_NO_ANSWER;
+       
+       case OR2_CAUSE_UNSPECIFIED:
+               return FTDM_CAUSE_NORMAL_UNSPECIFIED;
+
+       case OR2_CAUSE_COLLECT_CALL_REJECTED:
+               return FTDM_CAUSE_CALL_REJECTED;
+
+       case OR2_CAUSE_FORCED_RELEASE:
+               return FTDM_CAUSE_NORMAL_CLEARING;
+       }
+       ftdm_log_chan(fchan, FTDM_LOG_WARNING, "Mapping openr2 cause %d to unspecified\n", cause);
+       return FTDM_CAUSE_NORMAL_UNSPECIFIED;
+}
+
+static openr2_call_disconnect_cause_t ftdm_r2_ftdm_cause_to_openr2_cause(ftdm_channel_t *fchan)
+{
+       switch (fchan->caller_data.hangup_cause) {
+
+       case FTDM_CAUSE_NORMAL_CLEARING:
+               return OR2_CAUSE_NORMAL_CLEARING;
+
+       case FTDM_CAUSE_USER_BUSY:
+               return OR2_CAUSE_BUSY_NUMBER;
+
+       case FTDM_CAUSE_SWITCH_CONGESTION:
+               return OR2_CAUSE_NETWORK_CONGESTION;
+
+       case FTDM_CAUSE_NO_ROUTE_DESTINATION:
+               return OR2_CAUSE_UNALLOCATED_NUMBER;
+
+       case FTDM_CAUSE_NUMBER_CHANGED:
+               return OR2_CAUSE_NUMBER_CHANGED;
+
+       case FTDM_CAUSE_NETWORK_OUT_OF_ORDER:
+       case FTDM_CAUSE_SERVICE_UNAVAILABLE:
+               return OR2_CAUSE_OUT_OF_ORDER;
+
+       case FTDM_CAUSE_NO_ANSWER:
+       case FTDM_CAUSE_NO_USER_RESPONSE:
+               return OR2_CAUSE_NO_ANSWER;
+       
+       case FTDM_CAUSE_NORMAL_UNSPECIFIED:
+               return OR2_CAUSE_UNSPECIFIED;
+
+       }
+       ftdm_log_chan(fchan, FTDM_LOG_WARNING, "freetdm hangup cause %d mapped to openr2 cause %s\n",
+                       fchan->caller_data.hangup_cause, openr2_proto_get_disconnect_string(OR2_CAUSE_UNSPECIFIED));
+       return OR2_CAUSE_UNSPECIFIED;
+}
+
 static void ft_r2_clean_call(ftdm_r2_call_t *call)
 {
     openr2_chan_t *r2chan = call->r2chan;
@@ -143,7 +237,6 @@ static void ft_r2_accept_call(ftdm_channel_t *ftdmchan)
        // hanging up the call with protocol error as the reason, this openr2 API will fail only when there something
        // wrong at the I/O layer or the library itself
        openr2_chan_accept_call(r2chan, OR2_CALL_NO_CHARGE);
-       R2CALL(ftdmchan)->accepted = 1;
 }
 
 static void ft_r2_answer_call(ftdm_channel_t *ftdmchan)
@@ -157,37 +250,66 @@ static void ft_r2_answer_call(ftdm_channel_t *ftdmchan)
        R2CALL(ftdmchan)->answer_pending = 0;
 }
 
+/* this function must be called with the chan mutex held! */
 static FIO_CHANNEL_OUTGOING_CALL_FUNCTION(r2_outgoing_call)
 {
-       ftdm_status_t status;
-       ftdm_mutex_lock(ftdmchan->mutex);
+       openr2_call_status_t callstatus;
+       ftdm_r2_data_t *r2data;
+       int safety = 100;
 
-       /* the channel may be down but the thread not quite done */
-       ftdm_wait_for_flag_cleared(ftdmchan, FTDM_CHANNEL_INTHREAD, 200);
+       r2data = ftdmchan->span->signal_data;
 
-       if (ftdm_test_flag(ftdmchan, FTDM_CHANNEL_INTHREAD)) {
-               ftdm_log(FTDM_LOG_ERROR, "%d:%d Yay! R2 outgoing call in channel that is already in thread.\n", 
-                               ftdmchan->span_id, ftdmchan->chan_id);
-               ftdm_mutex_unlock(ftdmchan->mutex);
+       if (ftdmchan->state != FTDM_CHANNEL_STATE_DOWN) {
+               /* collision, an incoming seized the channel between our take and use timing */
+               ftdm_log_chan(ftdmchan, 
+               FTDM_LOG_CRIT, "R2 cannot dial out in channel in state %s, try another channel!.\n", ftdm_channel_state2str(ftdmchan->state));
                return FTDM_FAIL;
        }
 
        ft_r2_clean_call(ftdmchan->call_data);
-       R2CALL(ftdmchan)->chanstate = FTDM_CHANNEL_STATE_DOWN;
-       ftdm_set_state(ftdmchan, FTDM_CHANNEL_STATE_DIALING);
-       ftdm_set_flag(ftdmchan, FTDM_CHANNEL_OUTBOUND);
        R2CALL(ftdmchan)->ftdm_started = 1;
-       ftdm_mutex_unlock(ftdmchan->mutex);
+       R2CALL(ftdmchan)->chanstate = FTDM_CHANNEL_STATE_DOWN;
+    ftdm_set_state(ftdmchan, FTDM_CHANNEL_STATE_DIALING);
+
+       callstatus = openr2_chan_make_call(R2CALL(ftdmchan)->r2chan, 
+                       ftdmchan->caller_data.cid_num.digits, 
+                       ftdmchan->caller_data.dnis.digits, 
+                       OR2_CALLING_PARTY_CATEGORY_NATIONAL_SUBSCRIBER);
+
+    if (callstatus) {
+        ftdm_log_chan_msg(ftdmchan, FTDM_LOG_CRIT, "Failed to make call in R2 channel, openr2_chan_make_call failed\n");
+        return FTDM_FAIL;
+    }
+
+       /* this waiting for flag cleared function releases the ftdmchan lock to give a chance to the monitor thread 
+        * to process openr2 events and dial out, or see if an incoming call is arriving just now, then openr2 will 
+        * call in the monitor thread the on_call_collision or on_call_acknowledged callbacks where this flag 
+        * will be cleared, the lock will be re-acquired here and we continue within this function to inform the user 
+        * whether the call is being placed or collision occurred and another channel must be hunted */
+       ftdm_set_flag(R2CALL(ftdmchan), FTDM_R2_WAITING_ACK);
+       while (safety-- && ftdm_test_flag(R2CALL(ftdmchan), FTDM_R2_WAITING_ACK)) {
+               ftdm_mutex_unlock(ftdmchan->mutex);
+               ftdm_sleep(10);
+               ftdm_mutex_lock(ftdmchan->mutex);
+       }
 
-       status = ftdm_thread_create_detached(ftdm_r2_channel_run, ftdmchan);
-       if (status == FTDM_FAIL) {
-               ftdm_log(FTDM_LOG_ERROR, "%d:%d Cannot handle request to start call in channel, failed to create thread!\n", 
-                               ftdmchan->span_id, ftdmchan->chan_id);
-               ftdm_channel_done(ftdmchan);
+       if (ftdm_test_flag(R2CALL(ftdmchan), FTDM_R2_WAITING_ACK)) {
+               ftdm_log_chan_msg(ftdmchan, FTDM_LOG_CRIT, "Waiting ack flag was never cleared!\n");
+               ftdm_clear_flag(R2CALL(ftdmchan), FTDM_R2_WAITING_ACK);
                return FTDM_FAIL;
        }
+       
+       if (ftdmchan->state !=  FTDM_CHANNEL_STATE_DIALING) {
+               ftdm_log_chan(ftdmchan, FTDM_LOG_WARNING, "Collision after call attempt, try another channel, new state = %s\n",
+                               ftdm_channel_state2str(ftdmchan->state));
+               ftdm_clear_flag(R2CALL(ftdmchan), FTDM_R2_WAITING_ACK);
+               return FTDM_BREAK;
+       }
 
-       return FTDM_SUCCESS;
+
+    /* non-threaded implementation, we're done here */
+    ftdm_log_chan_msg(ftdmchan, FTDM_LOG_DEBUG, "R2 call placed in non-threaded mode\n");
+    return FTDM_SUCCESS;
 }
 
 static ftdm_status_t ftdm_r2_start(ftdm_span_t *span)
@@ -197,91 +319,137 @@ static ftdm_status_t ftdm_r2_start(ftdm_span_t *span)
        return ftdm_thread_create_detached(ftdm_r2_run, span);
 }
 
+static ftdm_status_t ftdm_r2_stop(ftdm_span_t *span)
+{
+       ftdm_r2_data_t *r2_data = span->signal_data;
+       while (ftdm_test_flag(r2_data, FTDM_R2_RUNNING)) {
+               ftdm_log(FTDM_LOG_DEBUG, "Waiting for R2 span %s\n", span->name);
+               ftdm_sleep(100);
+       }
+       return FTDM_SUCCESS;
+}
+
+#if 0
+static ftdm_status_t ftdm_r2_sig_write(ftdm_channel_t *ftdmchan, void *data, ftdm_size_t size)
+{
+       ftdm_r2_call_t *r2call = R2CALL(ftdmchan);
+       openr2_chan_t *r2chan = r2call->r2chan;
+       if (openr2_chan_get_read_enabled(r2chan) && !ftdm_test_flag(r2call, FTDM_R2_PROCESSING)) {
+               if (r2call->txdrops < 10) {
+                       ftdm_log_chan_msg(ftdmchan, FTDM_LOG_WARNING, "dropping user write because there is R2 processing\n");
+               } else if (r2call->txdrops == 10) {
+                       ftdm_log_chan_msg(ftdmchan, FTDM_LOG_WARNING, "too may drops, not logging any more\n");
+               }
+               r2call->txdrops++;
+               return FTDM_BREAK;
+       }
+       if (!openr2_chan_get_read_enabled(r2chan)) {
+               ftdm_mutex_lock(ftdmchan->mutex);
+               //openr2_chan_process_output(r2chan, data, size);
+               ftdm_mutex_unlock(ftdmchan->mutex);
+       }
+       return FTDM_SUCCESS;
+}
+#endif
+
+static ftdm_status_t ftdm_r2_sig_read(ftdm_channel_t *ftdmchan, void *data, ftdm_size_t size)
+{
+       openr2_chan_t *r2chan = R2CALL(ftdmchan)->r2chan;
+       if (!openr2_chan_get_read_enabled(r2chan)) {
+               ftdm_mutex_lock(ftdmchan->mutex);
+               //openr2_chan_process_input(r2chan, data, size);
+               ftdm_mutex_unlock(ftdmchan->mutex);
+       }
+       return FTDM_SUCCESS;
+}
+
 /* always called from the monitor thread */
 static void ftdm_r2_on_call_init(openr2_chan_t *r2chan)
 {
+       //ftdm_status_t status;
+       ftdm_r2_call_t *r2call;
        ftdm_channel_t *ftdmchan = openr2_chan_get_client_data(r2chan);
-       ftdm_status_t status;
-       ftdm_log(FTDM_LOG_NOTICE, "Received request to start call on chan %d\n", openr2_chan_get_number(r2chan));
+       //ftdm_r2_data_t *r2data = ftdmchan->span->signal_data;
+
+       ftdm_log_chan_msg(ftdmchan, FTDM_LOG_NOTICE, "Received request to start call\n");
 
        ftdm_mutex_lock(ftdmchan->mutex);
 
+       if (ftdm_test_flag(ftdmchan, FTDM_CHANNEL_INUSE)) {
+               ftdm_log_chan(ftdmchan, FTDM_LOG_CRIT, "Cannot start call when channel is in use (state = %s)\n", ftdm_channel_state2str(ftdmchan->state));
+               ftdm_mutex_unlock(ftdmchan->mutex);
+       }
+
        if (ftdmchan->state != FTDM_CHANNEL_STATE_DOWN) {
-               ftdm_log(FTDM_LOG_ERROR, "Cannot handle request to start call in channel %d, invalid state (%d)\n", 
-                               openr2_chan_get_number(r2chan), ftdmchan->state);
+               ftdm_log_chan(ftdmchan, FTDM_LOG_ERROR, "Cannot handle request to start call in state %s\n", ftdm_channel_state2str(ftdmchan->state));
                ftdm_mutex_unlock(ftdmchan->mutex);
                return;
        }
 
-       /* the channel may be down but the thread not quite done */
-       ftdm_wait_for_flag_cleared(ftdmchan, FTDM_CHANNEL_INTHREAD, 200);
-
-       if (ftdm_test_flag(ftdmchan, FTDM_CHANNEL_INTHREAD)) {
-               ftdm_log(FTDM_LOG_ERROR, "Cannot handle request to start call in channel %d, already in thread!\n", 
-                               openr2_chan_get_number(r2chan));
+       if (ftdm_channel_open_chan(ftdmchan) != FTDM_SUCCESS) {
+               ftdm_log_chan(ftdmchan, FTDM_LOG_ERROR, "Failed to open channel during incoming call! [%s]\n", ftdmchan->last_error);
                ftdm_mutex_unlock(ftdmchan->mutex);
                return;
        }
+
+       /* mark the channel in use (so no outgoing calls can be placed here) */
+       ftdm_channel_use(ftdmchan);     
+
+       memset(ftdmchan->caller_data.dnis.digits, 0, sizeof(ftdmchan->caller_data.collected));
+       memset(ftdmchan->caller_data.ani.digits, 0, sizeof(ftdmchan->caller_data.collected));
+
+       /* clean the call data structure but keep the R2 processing flag on! */
        ft_r2_clean_call(ftdmchan->call_data);
-       R2CALL(ftdmchan)->chanstate = FTDM_CHANNEL_STATE_DOWN;
+       r2call = R2CALL(ftdmchan);
+       ftdm_set_flag(r2call, FTDM_R2_PROCESSING);
+
+       if (ftdmchan->state == FTDM_CHANNEL_STATE_DOWN) {
+               R2CALL(ftdmchan)->chanstate = FTDM_CHANNEL_STATE_DOWN;
+       } else {
+               R2CALL(ftdmchan)->chanstate = FTDM_CHANNEL_STATE_DIALING;
+       }
+
        ftdm_set_state(ftdmchan, FTDM_CHANNEL_STATE_COLLECT);
        ftdm_mutex_unlock(ftdmchan->mutex);
 
-       status = ftdm_thread_create_detached(ftdm_r2_channel_run, ftdmchan);
-       if (status == FTDM_FAIL) {
-               ftdm_log(FTDM_LOG_ERROR, "Cannot handle request to start call in channel %d, failed to create thread!\n", 
-                               openr2_chan_get_number(r2chan));
-       }
+    ftdm_log_chan_msg(ftdmchan, FTDM_LOG_DEBUG, "Span is not threaded, not launching thread for this call\n");
+    return;
 }
 
 /* only called for incoming calls when the ANI, DNIS etc is complete and the user has to decide either to accept or reject the call */
 static void ftdm_r2_on_call_offered(openr2_chan_t *r2chan, const char *ani, const char *dnis, openr2_calling_party_category_t category)
 {
-       ftdm_sigmsg_t sigev;
        ftdm_channel_t *ftdmchan = openr2_chan_get_client_data(r2chan);
 
-       ftdm_log(FTDM_LOG_NOTICE, "Call offered on chan %d, ANI = %s, DNIS = %s, Category = %s\n", openr2_chan_get_number(r2chan), 
-                       ani, dnis, openr2_proto_get_category_string(category));
+       ftdm_log_chan(ftdmchan, FTDM_LOG_NOTICE, "Call offered with ANI = %s, DNIS = %s, Priority = (%d)\n", ani, dnis, category);
+       //ftdmchan->caller_data.priority = category;
+       ftdm_set_state_locked(ftdmchan, FTDM_CHANNEL_STATE_RING);
 
-       /* notify the user about the new call */
-       memset(&sigev, 0, sizeof(sigev));
-       sigev.chan_id = ftdmchan->chan_id;
-       sigev.span_id = ftdmchan->span_id;
-       sigev.channel = ftdmchan;
-       sigev.event_id = FTDM_SIGEVENT_START;
-
-       if (ftdm_span_send_signal(ftdmchan->span, &sigev) != FTDM_SUCCESS) {
-               ftdm_log(FTDM_LOG_NOTICE, "Failed to handle call offered on chan %d\n", openr2_chan_get_number(r2chan));
-               openr2_chan_disconnect_call(r2chan, OR2_CAUSE_OUT_OF_ORDER);
-               ftdm_set_state_locked(ftdmchan, FTDM_CHANNEL_STATE_CANCEL);
-               return; 
-       }
-       ftdm_channel_use(ftdmchan);
-       R2CALL(ftdmchan)->ftdm_started = 1; 
 }
 
 static void ftdm_r2_on_call_accepted(openr2_chan_t *r2chan, openr2_call_mode_t mode)
 {
        ftdm_channel_t *ftdmchan = openr2_chan_get_client_data(r2chan);
-       ftdm_log(FTDM_LOG_NOTICE, "Call accepted on chan %d\n", openr2_chan_get_number(r2chan));
+       ftdm_log_chan_msg(ftdmchan, FTDM_LOG_NOTICE, "Call accepted\n");
        /* at this point the MF signaling has ended and there is no point on keep reading */
        openr2_chan_disable_read(r2chan);
+       R2CALL(ftdmchan)->accepted = 1;
        if (OR2_DIR_BACKWARD == openr2_chan_get_direction(r2chan)) {
                R2CALL(ftdmchan)->state_ack_pending = 1;
                if (R2CALL(ftdmchan)->answer_pending) {
-                       ftdm_log(FTDM_LOG_DEBUG, "Answer was pending on chan %d, answering now.\n", openr2_chan_get_number(r2chan));
+                       ftdm_log_chan_msg(ftdmchan, FTDM_LOG_DEBUG, "Answer was pending, answering now.\n");
                        ft_r2_answer_call(ftdmchan);
                        return;
                }
        } else {
-               ftdm_set_state_locked(ftdmchan, FTDM_CHANNEL_STATE_PROGRESS);
+               ftdm_set_state_locked(ftdmchan, FTDM_CHANNEL_STATE_PROGRESS_MEDIA);
        }
 }
 
 static void ftdm_r2_on_call_answered(openr2_chan_t *r2chan)
 {
        ftdm_channel_t *ftdmchan = openr2_chan_get_client_data(r2chan);
-       ftdm_log(FTDM_LOG_NOTICE, "Call answered on chan %d\n", openr2_chan_get_number(r2chan));
+       ftdm_log_chan_msg(ftdmchan, FTDM_LOG_NOTICE, "Call answered\n");
        /* notify the upper layer of progress in the outbound call */
        if (OR2_DIR_FORWARD == openr2_chan_get_direction(r2chan)) {
                ftdm_set_state_locked(ftdmchan, FTDM_CHANNEL_STATE_UP);
@@ -294,14 +462,19 @@ static void ftdm_r2_on_call_disconnect(openr2_chan_t *r2chan, openr2_call_discon
        ftdm_sigmsg_t sigev;
        ftdm_r2_data_t *r2data;
        ftdm_channel_t *ftdmchan = openr2_chan_get_client_data(r2chan);
-       ftdm_log(FTDM_LOG_NOTICE, "Call disconnected on chan %d\n", openr2_chan_get_number(r2chan));
 
-       ftdm_log(FTDM_LOG_DEBUG, "Got openr2 disconnection, clearing call on channel %d\n", ftdmchan->physical_chan_id);
+       ftdm_log_chan_msg(ftdmchan, FTDM_LOG_NOTICE, "Call disconnected\n");
+
+       ftdm_log_chan_msg(ftdmchan, FTDM_LOG_DEBUG, "Got openr2 disconnection, clearing call\n");
 
        R2CALL(ftdmchan)->disconnect_rcvd = 1;
 
-       /* acknowledge the hangup, cause will be ignored. From here to -> HANGUP once the freetdm side hangs up as well */
-       openr2_chan_disconnect_call(r2chan, OR2_CAUSE_NORMAL_CLEARING);
+       if (ftdmchan->state == FTDM_CHANNEL_STATE_HANGUP) {
+               ftdm_log_chan_msg(ftdmchan, FTDM_LOG_DEBUG, "Call had been disconnected already by the user\n");
+               /* just ack the hangup to go down */
+               openr2_chan_disconnect_call(r2chan, OR2_CAUSE_NORMAL_CLEARING);
+               return;
+       }
 
        /* if the call has not been started yet we must go to HANGUP right here */ 
        if (!R2CALL(ftdmchan)->ftdm_started) {
@@ -309,8 +482,7 @@ static void ftdm_r2_on_call_disconnect(openr2_chan_t *r2chan, openr2_call_discon
                return;
        }
 
-       /* FIXME: use the cause received from openr2 and map it to ftdm cause  */
-       ftdmchan->caller_data.hangup_cause  = FTDM_CAUSE_NORMAL_CLEARING; 
+       ftdmchan->caller_data.hangup_cause  = ftdm_r2_cause_to_ftdm_cause(ftdmchan, cause);
 
        /* notify the user of the call terminating */
        memset(&sigev, 0, sizeof(sigev));
@@ -326,27 +498,32 @@ static void ftdm_r2_on_call_disconnect(openr2_chan_t *r2chan, openr2_call_discon
 static void ftdm_r2_on_call_end(openr2_chan_t *r2chan)
 {
        ftdm_channel_t *ftdmchan = openr2_chan_get_client_data(r2chan);
-       ftdm_log(FTDM_LOG_NOTICE, "Call finished on chan %d\n", openr2_chan_get_number(r2chan));
-       /* this means the freetdm side disconnected the call, therefore we must move to DOWN here */
-       if (!R2CALL(ftdmchan)->disconnect_rcvd) {
-               ftdm_set_state_locked(ftdmchan, FTDM_CHANNEL_STATE_DOWN);
-               return;
-       }
+       ftdm_log_chan_msg(ftdmchan, FTDM_LOG_NOTICE, "Call finished\n");
+
+       /* the call is done as far as the stack is concerned, lets move to down here */
+       ftdm_set_state_locked(ftdmchan, FTDM_CHANNEL_STATE_DOWN);
+
+       /* in some circumstances openr2 can call on_call_init right after this, so let's advance the state right here */
+       ftdm_r2_state_advance(ftdmchan);
 }
 
 static void ftdm_r2_on_call_read(openr2_chan_t *r2chan, const unsigned char *buf, int buflen)
 {
+#if 0
        ftdm_log(FTDM_LOG_NOTICE, "Call read data on chan %d\n", openr2_chan_get_number(r2chan));
+#endif
 }
 
 static void ftdm_r2_on_hardware_alarm(openr2_chan_t *r2chan, int alarm)
 {
-       ftdm_log(FTDM_LOG_NOTICE, "Alarm on chan %d (%d)\n", openr2_chan_get_number(r2chan), alarm);
+       ftdm_channel_t *ftdmchan = openr2_chan_get_client_data(r2chan);
+       ftdm_log_chan(ftdmchan, FTDM_LOG_WARNING, "Alarm notification: %d\n", alarm);
 }
 
 static void ftdm_r2_on_os_error(openr2_chan_t *r2chan, int errorcode)
 {
-       ftdm_log(FTDM_LOG_ERROR, "OS error on chan %d: %s\n", openr2_chan_get_number(r2chan), strerror(errorcode));
+       ftdm_channel_t *ftdmchan = openr2_chan_get_client_data(r2chan);
+       ftdm_log_chan(ftdmchan, FTDM_LOG_ERROR, "OS error: %s\n", strerror(errorcode));
 }
 
 static void ftdm_r2_on_protocol_error(openr2_chan_t *r2chan, openr2_protocol_error_t reason)
@@ -355,18 +532,26 @@ static void ftdm_r2_on_protocol_error(openr2_chan_t *r2chan, openr2_protocol_err
        ftdm_r2_data_t *r2data;
        ftdm_channel_t *ftdmchan = openr2_chan_get_client_data(r2chan);
 
-       ftdm_log(FTDM_LOG_ERROR, "Protocol error on chan %d\n", openr2_chan_get_number(r2chan));
+       ftdm_mutex_lock(ftdmchan->mutex);
+
+       if (ftdmchan->state == FTDM_CHANNEL_STATE_DOWN) {
+               ftdm_log_chan_msg(ftdmchan, FTDM_LOG_ERROR, "Got protocol error when we're already down!\n");
+               ftdm_mutex_unlock(ftdmchan->mutex);
+       }
+
+       ftdm_log_chan_msg(ftdmchan, FTDM_LOG_ERROR, "Protocol error\n");
 
        R2CALL(ftdmchan)->disconnect_rcvd = 1;
 
        if (!R2CALL(ftdmchan)->ftdm_started) {
-               ftdm_set_state_locked(ftdmchan, FTDM_CHANNEL_STATE_HANGUP);
+               ftdm_set_state(ftdmchan, FTDM_CHANNEL_STATE_HANGUP);
+               ftdm_mutex_unlock(ftdmchan->mutex);
                return;
        }
 
        ftdmchan->caller_data.hangup_cause  = FTDM_CAUSE_PROTOCOL_ERROR; 
 
-       /* notify the user of the call terminating */
+       /* FIXME: go to terminating and notify the user from the terminating handler instead of notifying here */
        memset(&sigev, 0, sizeof(sigev));
        sigev.chan_id = ftdmchan->chan_id;
        sigev.span_id = ftdmchan->span_id;
@@ -375,63 +560,76 @@ static void ftdm_r2_on_protocol_error(openr2_chan_t *r2chan, openr2_protocol_err
        r2data = ftdmchan->span->signal_data;
 
        ftdm_span_send_signal(ftdmchan->span, &sigev);
+
+       ftdm_mutex_unlock(ftdmchan->mutex);
 }
 
 static void ftdm_r2_on_line_blocked(openr2_chan_t *r2chan)
 {
-       ftdm_log(FTDM_LOG_NOTICE, "Far end blocked on chan %d\n", openr2_chan_get_number(r2chan));
+       ftdm_channel_t *ftdmchan = openr2_chan_get_client_data(r2chan);
+       ftdm_log_chan(ftdmchan, FTDM_LOG_NOTICE, "Far end blocked in state %s\n", ftdm_channel_state2str(ftdmchan->state));
+       ftdm_set_flag(ftdmchan, FTDM_CHANNEL_SUSPENDED);
 }
 
 static void ftdm_r2_on_line_idle(openr2_chan_t *r2chan)
 {
-       ftdm_log(FTDM_LOG_NOTICE, "Far end unblocked on chan %d\n", openr2_chan_get_number(r2chan));
+       ftdm_channel_t *ftdmchan = openr2_chan_get_client_data(r2chan);
+       ftdm_log_chan(ftdmchan, FTDM_LOG_NOTICE, "Far end unblocked in state %s\n", ftdm_channel_state2str(ftdmchan->state));
+       ftdm_clear_flag(ftdmchan, FTDM_CHANNEL_SUSPENDED);
+
+    /* XXX when should we set/unset this flag? XXX */
+    ftdm_set_flag(ftdmchan, FTDM_CHANNEL_SIG_UP);
 }
 
-static void ftdm_r2_write_log(openr2_log_level_t level, const char *message)
+static void ftdm_r2_write_log(openr2_log_level_t level, const char *file, const char *function, int line, const char *message)
 {
        switch (level) {
                case OR2_LOG_NOTICE:
-                       ftdm_log(FTDM_LOG_NOTICE, "%s", message);
+                       ftdm_log(file, function, line, FTDM_LOG_LEVEL_NOTICE, "%s", message);
                        break;
                case OR2_LOG_WARNING:
-                       ftdm_log(FTDM_LOG_WARNING, "%s", message);
+                       ftdm_log(file, function, line, FTDM_LOG_LEVEL_WARNING, "%s", message);
                        break;
                case OR2_LOG_ERROR:
-                       ftdm_log(FTDM_LOG_ERROR, "%s", message);
+                       ftdm_log(file, function, line, FTDM_LOG_LEVEL_ERROR, "%s", message);
                        break;
                case OR2_LOG_STACK_TRACE:
                case OR2_LOG_MF_TRACE:
                case OR2_LOG_CAS_TRACE:
                case OR2_LOG_DEBUG:
                case OR2_LOG_EX_DEBUG:
-                       ftdm_log(FTDM_LOG_DEBUG, "%s", message);
+                       ftdm_log(file, function, line, FTDM_LOG_LEVEL_DEBUG, "%s", message);
                        break;
                default:
                        ftdm_log(FTDM_LOG_WARNING, "We should handle logging level %d here.\n", level);
-                       ftdm_log(FTDM_LOG_DEBUG, "%s", message);
+                       ftdm_log(file, function, line, FTDM_LOG_LEVEL_DEBUG, "%s", message);
                        break;
        }
 }
 
-static void ftdm_r2_on_context_log(openr2_context_t *r2context, openr2_log_level_t level, const char *fmt, va_list ap)
+static void ftdm_r2_on_context_log(openr2_context_t *r2context, const char *file, const char *function, unsigned int line, 
+       openr2_log_level_t level, const char *fmt, va_list ap)
 {
 #define CONTEXT_TAG "Context -"
        char logmsg[256];
        char completemsg[sizeof(logmsg) + sizeof(CONTEXT_TAG) - 1];
        vsnprintf(logmsg, sizeof(logmsg), fmt, ap);
        snprintf(completemsg, sizeof(completemsg), CONTEXT_TAG "%s", logmsg);
-       ftdm_r2_write_log(level, completemsg);
+       ftdm_r2_write_log(level, file, function, line, completemsg);
 #undef CONTEXT_TAG
 }
 
-static void ftdm_r2_on_chan_log(openr2_chan_t *r2chan, openr2_log_level_t level, const char *fmt, va_list ap)
+static void ftdm_r2_on_chan_log(openr2_chan_t *r2chan, const char *file, const char *function, unsigned int line, 
+       openr2_log_level_t level, const char *fmt, va_list ap)
 {
+       ftdm_channel_t *ftdmchan = openr2_chan_get_client_data(r2chan);
 #define CHAN_TAG "Chan "
-       char logmsg[256];
+       char logmsg[512];
        char completemsg[sizeof(logmsg) + sizeof(CHAN_TAG) - 1];
        vsnprintf(logmsg, sizeof(logmsg), fmt, ap);
-       snprintf(completemsg, sizeof(completemsg), CHAN_TAG "%d: %s", openr2_chan_get_number(r2chan), logmsg);
-       ftdm_r2_write_log(level, completemsg);
+       snprintf(completemsg, sizeof(completemsg), CHAN_TAG "%d:%d [%s] %s", 
+                       ftdmchan->span_id, ftdmchan->chan_id, ftdm_channel_state2str(ftdmchan->state), logmsg);
+       ftdm_r2_write_log(level, file, function, line, completemsg);
 #undef CHAN_TAG
 }
 
@@ -442,7 +640,7 @@ static int ftdm_r2_on_dnis_digit_received(openr2_chan_t *r2chan, char digit)
        ftdm_channel_t *ftdmchan = openr2_chan_get_client_data(r2chan);
        ftdm_size_t collected_len = R2CALL(ftdmchan)->dnis_index;
 
-       ftdm_log(FTDM_LOG_DEBUG, "DNIS digit %d received chan %d\n", digit, openr2_chan_get_number(r2chan));
+       ftdm_log_chan(ftdmchan, FTDM_LOG_DEBUG, "DNIS digit %c received\n", digit);
 
        /* save the digit we just received */ 
        ftdmchan->caller_data.dnis.digits[collected_len] = digit;
@@ -458,13 +656,13 @@ static int ftdm_r2_on_dnis_digit_received(openr2_chan_t *r2chan, char digit)
        sigev.event_id = FTDM_SIGEVENT_COLLECTED_DIGIT;
        r2data = ftdmchan->span->signal_data;
        if (ftdm_span_send_signal(ftdmchan->span, &sigev) == FTDM_BREAK) {
-               ftdm_log(FTDM_LOG_NOTICE, "Requested to stop getting DNIS. Current DNIS = %s on chan %d\n", ftdmchan->caller_data.dnis.digits, openr2_chan_get_number(r2chan));
+               ftdm_log_chan(ftdmchan, FTDM_LOG_NOTICE, "Requested to stop getting DNIS. Current DNIS = %s\n", ftdmchan->caller_data.dnis.digits);
                return OR2_STOP_DNIS_REQUEST; 
        }
 
        /* the only other reason to stop requesting DNIS is that there is no more room to save it */
        if (collected_len == (sizeof(ftdmchan->caller_data.dnis.digits) - 1)) {
-               ftdm_log(FTDM_LOG_NOTICE, "No more room for DNIS. Current DNIS = %s on chan %d\n", ftdmchan->caller_data.dnis.digits, openr2_chan_get_number(r2chan));
+               ftdm_log_chan(ftdmchan, FTDM_LOG_WARNING, "No more room for DNIS. Current DNIS = %s\n", ftdmchan->caller_data.dnis.digits);
                return OR2_STOP_DNIS_REQUEST;
        }
 
@@ -478,15 +676,35 @@ static void ftdm_r2_on_ani_digit_received(openr2_chan_t *r2chan, char digit)
 
        /* check if we should drop ANI */
        if (collected_len == (sizeof(ftdmchan->caller_data.ani.digits) - 1)) {
-               ftdm_log(FTDM_LOG_NOTICE, "No more room for ANI %c on chan %d, digit dropped.\n", digit, openr2_chan_get_number(r2chan));
+               ftdm_log_chan(ftdmchan, FTDM_LOG_WARNING, "No more room for ANI, digit dropped: %c\n", digit);
                return;
        }
-       ftdm_log(FTDM_LOG_DEBUG, "ANI digit %c received chan %d\n", digit, openr2_chan_get_number(r2chan));
+       ftdm_log_chan(ftdmchan, FTDM_LOG_DEBUG, "ANI digit %c received\n", digit);
 
        /* save the digit we just received */ 
-       ftdmchan->caller_data.ani.digits[collected_len++] = digit;
+       ftdmchan->caller_data.ani.digits[collected_len] = digit;
+       collected_len++;
        ftdmchan->caller_data.ani.digits[collected_len] = '\0';
+       R2CALL(ftdmchan)->ani_index = collected_len;
+}
+
+/* XXX missing on openr2 XXX */
+#if 0
+static void ftdm_r2_on_call_collision(openr2_chan_t *r2chan)
+{
+       ftdm_channel_t *ftdmchan = openr2_chan_get_client_data(r2chan);
+       ftdm_log_chan(ftdmchan, FTDM_LOG_WARNING, "Call collision detected, outgoing call attempt failed, state = %s\n", ftdm_channel_state2str(ftdmchan->state));
+       ftdm_clear_flag(R2CALL(ftdmchan), FTDM_R2_WAITING_ACK);
+       ftdm_channel_close(&ftdmchan);
+}
+
+static void ftdm_r2_on_call_acknowledged(openr2_chan_t *r2chan)
+{
+       ftdm_channel_t *ftdmchan = openr2_chan_get_client_data(r2chan);
+       ftdm_log_chan_msg(ftdmchan, FTDM_LOG_DEBUG, "Outgoing call proceeding\n");
+       ftdm_clear_flag(R2CALL(ftdmchan), FTDM_R2_WAITING_ACK);
 }
+#endif
 
 static openr2_event_interface_t ftdm_r2_event_iface = {
        .on_call_init = ftdm_r2_on_call_init,
@@ -506,7 +724,13 @@ static openr2_event_interface_t ftdm_r2_event_iface = {
        .on_dnis_digit_received = ftdm_r2_on_dnis_digit_received,
        .on_ani_digit_received = ftdm_r2_on_ani_digit_received,
        /* so far we do nothing with billing pulses */
-       .on_billing_pulse_received = NULL
+       .on_billing_pulse_received = NULL,
+
+    /* XXX these two events are missing on openr2 XXX */
+#if 0
+    .on_call_collision = ftdm_r2_on_call_collision,
+    .on_call_acknowledged = ftdm_r2_on_call_acknowledged,
+#endif
 };
 
 static int ftdm_r2_io_set_cas(openr2_chan_t *r2chan, int cas)
@@ -564,10 +788,11 @@ static int ftdm_r2_io_read(openr2_chan_t *r2chan, const void *buf, int size)
 static int ftdm_r2_io_wait(openr2_chan_t *r2chan, int *flags, int block)
 {
        ftdm_status_t status;
+       int32_t timeout;
        ftdm_wait_flag_t ftdmflags = 0;
 
        ftdm_channel_t *ftdm_chan = openr2_chan_get_fd(r2chan);
-       int32_t timeout = block ? -1 : 0;
+       timeout = block ? -1 : 0;
 
        if (*flags & OR2_IO_READ) {
                ftdmflags |= FTDM_READ;
@@ -578,10 +803,10 @@ static int ftdm_r2_io_wait(openr2_chan_t *r2chan, int *flags, int block)
        if (*flags & OR2_IO_OOB_EVENT) {
                ftdmflags |= FTDM_EVENTS;
        }
-
+       
        status = ftdm_channel_wait(ftdm_chan, &ftdmflags, timeout);
 
-       if (FTDM_SUCCESS != status) {
+       if (FTDM_SUCCESS != status && FTDM_TIMEOUT != status) {
                return -1;
        }
 
@@ -610,23 +835,40 @@ static openr2_io_fd_t ftdm_r2_io_open(openr2_context_t *r2context, int channo)
 /* since freetdm takes care of closing the file descriptor and uses openr2_chan_new_from_fd, openr2 should never call this hook */
 static int ftdm_r2_io_close(openr2_chan_t *r2chan)
 {
-       ftdm_log(FTDM_LOG_ERROR, "I should not be called (I/O close)!!\n");
+       ftdm_channel_t *fchan = openr2_chan_get_client_data(r2chan);
+       ftdm_log_chan_msg(fchan, FTDM_LOG_ERROR, "I should not be called (I/O close)!!\n");
        return 0;
 }
 
 /* since freetdm takes care of opening the file descriptor and using openr2_chan_new_from_fd, openr2 should never call this hook */
 static int ftdm_r2_io_setup(openr2_chan_t *r2chan)
 {
-       ftdm_log(FTDM_LOG_ERROR, "I should not be called (I/O Setup)!!\n");
+       ftdm_channel_t *fchan = openr2_chan_get_client_data(r2chan);
+       ftdm_log_chan_msg(fchan, FTDM_LOG_ERROR, "I should not be called (I/O Setup)!!\n");
        return 0;
 }
 
-/* since the signaling thread calls openr2_chan_process_cas_signaling directly, openr2 should never call this hook */
 static int ftdm_r2_io_get_oob_event(openr2_chan_t *r2chan, openr2_oob_event_t *event)
 {
        *event = 0;
        ftdm_log(FTDM_LOG_ERROR, "I should not be called (I/O get oob event)!!\n");
        return 0;
+
+#if 0
+       ftdm_status_t status;
+       ftdm_event_t *fevent = NULL;
+       ftdm_channel_t *ftdmchan = openr2_chan_get_fd(r2chan);
+       *event = OR2_OOB_EVENT_NONE;
+       status = ftdm_channel_read_event(ftdmchan, &fevent);
+       if (status != FTDM_SUCCESS) {
+               ftdm_log_chan_msg(ftdmchan, FTDM_LOG_ERROR, "failed to retrieve freetdm event!\n");
+               return -1;
+       }
+       if (fevent->e_type == FTDM_EVENT_OOB && fevent->enum_id == FTDM_OOB_CAS_BITS_CHANGE) {
+               *event = OR2_OOB_EVENT_CAS_CHANGE;
+       }
+       return 0;
+#endif
 }
 
 static openr2_io_interface_t ftdm_r2_io_iface = {
@@ -671,9 +913,10 @@ static FIO_SIG_CONFIGURE_FUNCTION(ftdm_r2_configure_span)
                .forced_release = -1,
                .charge_calls = -1,
                .get_ani_first = -1,
-               .call_files = -1,
+               .call_files = 0,
+               .mf_files = 0,
                .logdir = NULL,
-               .advanced_protocol_file = NULL 
+               .advanced_protocol_file = NULL
        };
 
 
@@ -784,6 +1027,9 @@ static FIO_SIG_CONFIGURE_FUNCTION(ftdm_r2_configure_span)
                } else if (!strcasecmp(var, "call_files")) {
                        r2conf.call_files = va_arg(ap, int);
                        ftdm_log(FTDM_LOG_DEBUG, "Configuring R2 span %d with call files = %d\n", span->span_id, r2conf.call_files);
+               } else if (!strcasecmp(var, "mf_files")) {
+                       r2conf.mf_files = va_arg(ap, int);
+                       ftdm_log(FTDM_LOG_DEBUG, "Configuring R2 span %d with mf files = %d\n", span->span_id, r2conf.mf_files);
                } else if (!strcasecmp(var, "mfback_timeout")) {
                        r2conf.mfback_timeout = va_arg(ap, int);
                        ftdm_log(FTDM_LOG_DEBUG, "Configuring R2 span %d with MF backward timeout = %dms\n", span->span_id, r2conf.mfback_timeout);
@@ -834,7 +1080,9 @@ static FIO_SIG_CONFIGURE_FUNCTION(ftdm_r2_configure_span)
        openr2_context_set_metering_pulse_timeout(r2data->r2context, r2conf.metering_pulse_timeout);
        openr2_context_set_double_answer(r2data->r2context, r2conf.double_answer);
        openr2_context_set_immediate_accept(r2data->r2context, r2conf.immediate_accept);
-       if (r2conf.logdir) {
+
+       if (r2conf.logdir && r2conf.logdir[0]) {
+               ftdm_log(FTDM_LOG_DEBUG, "Setting openr2 for span %s logdir to %s\n", span->name, r2conf.logdir);
                openr2_context_set_log_directory(r2data->r2context, r2conf.logdir);
        }
        if (r2conf.advanced_protocol_file) {
@@ -853,9 +1101,14 @@ static FIO_SIG_CONFIGURE_FUNCTION(ftdm_r2_configure_span)
                        snprintf(span->last_error, sizeof(span->last_error), "Cannot create all openr2 channels for span.");
                        goto fail;
                }
+               openr2_chan_set_log_level(r2chan, r2conf.loglevel);
                if (r2conf.call_files) {
                        openr2_chan_enable_call_files(r2chan);
-                       openr2_chan_set_log_level(r2chan, r2conf.loglevel);
+#if 0
+                       if (r2conf.mf_files) {
+                               openr2_chan_enable_mf_files(r2chan);
+                       }
+#endif
                }
 
                r2call = ftdm_malloc(sizeof(*r2call));
@@ -874,13 +1127,16 @@ static FIO_SIG_CONFIGURE_FUNCTION(ftdm_r2_configure_span)
                hashtable_insert(spanpvt->r2calls, (void *)r2call->name, r2call, HASHTABLE_FLAG_FREE_VALUE);
 
        }
+       r2data->flags = 0;
        spanpvt->r2context = r2data->r2context;
 
        /* just the value must be freed by the hash */
        hashtable_insert(g_mod_data_hash, (void *)span->name, spanpvt, HASHTABLE_FLAG_FREE_VALUE);
 
        span->start = ftdm_r2_start;
-       r2data->flags = 0;
+       span->stop = ftdm_r2_stop;
+       span->sig_read = ftdm_r2_sig_read;
+
        span->signal_cb = sig_cb;
        span->signal_type = FTDM_SIGTYPE_R2;
        span->signal_data = r2data;
@@ -902,301 +1158,391 @@ fail:
 
 }
 
-static void *ftdm_r2_channel_run(ftdm_thread_t *me, void *obj)
+/* the channel must be locked when calling this function */
+static int ftdm_r2_state_advance(ftdm_channel_t *ftdmchan)
 {
-       ftdm_channel_t *closed_chan;
-       uint32_t interval = 0;
        ftdm_sigmsg_t sigev;
-       ftdm_channel_t *ftdmchan = (ftdm_channel_t *)obj;
+       int ret;
        openr2_chan_t *r2chan = R2CALL(ftdmchan)->r2chan;
 
-       ftdm_set_flag_locked(ftdmchan, FTDM_CHANNEL_INTHREAD);
-
-       ftdm_mutex_lock(g_thread_count_mutex);
-       g_thread_count++;
-       ftdm_mutex_unlock(g_thread_count_mutex);
+       memset(&sigev, 0, sizeof(sigev));
+       sigev.chan_id = ftdmchan->chan_id;
+       sigev.span_id = ftdmchan->span_id;
+       sigev.channel = ftdmchan;
 
-       ftdm_log(FTDM_LOG_DEBUG, "R2 CHANNEL thread starting on %d in state %s.\n", 
-                       ftdmchan->physical_chan_id,
-                       ftdm_channel_state2str(ftdmchan->state));
+       ret = 0;
 
-       if (ftdm_channel_open_chan(ftdmchan) != FTDM_SUCCESS) {
-               ftdm_log(FTDM_LOG_ERROR, "OPEN ERROR [%s]\n", ftdmchan->last_error);
-               goto endthread;
+       if (R2CALL(ftdmchan)->state_ack_pending) {
+               ftdm_clear_flag(ftdmchan, FTDM_CHANNEL_STATE_CHANGE);
+               ftdm_channel_complete_state(ftdmchan);
+               R2CALL(ftdmchan)->state_ack_pending = 0;
        }
 
-       ftdm_channel_command(ftdmchan, FTDM_COMMAND_GET_INTERVAL, &interval);
+       if (ftdm_test_flag(ftdmchan, FTDM_CHANNEL_STATE_CHANGE) && (R2CALL(ftdmchan)->chanstate != ftdmchan->state)) {
+
+               ftdm_log_chan(ftdmchan, FTDM_LOG_DEBUG, "Executing state handler for %s\n", ftdm_channel_state2str(ftdmchan->state));
+               R2CALL(ftdmchan)->chanstate = ftdmchan->state;
+
+               if (!ftdm_test_flag(ftdmchan, FTDM_CHANNEL_OUTBOUND) && !R2CALL(ftdmchan)->accepted &&
+                               (ftdmchan->state == FTDM_CHANNEL_STATE_PROGRESS ||
+                                ftdmchan->state == FTDM_CHANNEL_STATE_PROGRESS_MEDIA ||
+                                ftdmchan->state == FTDM_CHANNEL_STATE_UP) ) {
+                       /* if an accept ack will be required we should not acknowledge the state change just yet, 
+                          it will be done below after processing the MF signals, otherwise we have a race condition between freetdm calling
+                          openr2_chan_answer_call and openr2 accepting the call first, if freetdm calls openr2_chan_answer_call before the accept cycle
+                          completes, openr2 will fail to answer the call */
+                       ftdm_log_chan(ftdmchan, FTDM_LOG_DEBUG, "State ack for state %s will have to wait a bit\n", ftdm_channel_state2str(ftdmchan->state));
+               } else if (ftdmchan->state != FTDM_CHANNEL_STATE_DOWN){
+                       ftdm_clear_flag(ftdmchan, FTDM_CHANNEL_STATE_CHANGE);
+                       ftdm_channel_complete_state(ftdmchan);
+               }
 
-       assert(interval != 0);
-       ftdm_log(FTDM_LOG_DEBUG, "Got %d interval for chan %d\n", interval, ftdmchan->physical_chan_id);
+               switch (ftdmchan->state) {
 
-       if (!ftdm_test_flag(ftdmchan, FTDM_CHANNEL_OUTBOUND)) {
-               /* FIXME: is this needed? */
-               memset(ftdmchan->caller_data.dnis.digits, 0, sizeof(ftdmchan->caller_data.collected));
-               memset(ftdmchan->caller_data.ani.digits, 0, sizeof(ftdmchan->caller_data.collected));
-       }
+                       /* starting an incoming call */
+                       case FTDM_CHANNEL_STATE_COLLECT: 
+                               {
+                                       uint32_t interval = 0;
+                                       ftdm_channel_command(ftdmchan, FTDM_COMMAND_GET_INTERVAL, &interval);
+                                       ftdm_assert(interval != 0, "Invalid interval!");
+                                       ftdm_log_chan(ftdmchan, FTDM_LOG_DEBUG, "Starting processing of incoming call with interval %d\n", interval);
+                               }
+                               break;
 
-       memset(&sigev, 0, sizeof(sigev));
-       sigev.chan_id = ftdmchan->chan_id;
-       sigev.span_id = ftdmchan->span_id;
-       sigev.channel = ftdmchan;
+                               /* starting an outgoing call */
+                       case FTDM_CHANNEL_STATE_DIALING:
+                               {
+                                       uint32_t interval = 0;
+                                       ftdm_channel_command(ftdmchan, FTDM_COMMAND_GET_INTERVAL, &interval);
+                                       ftdm_assert(interval != 0, "Invalid interval!");
+                                       ftdm_log_chan(ftdmchan, 
+                                               FTDM_LOG_DEBUG, "Starting processing of outgoing call in channel with interval %d\n", interval);
+                               }
+                               break;
 
-       while (ftdm_running()) {
-               int32_t read_enabled = openr2_chan_get_read_enabled(r2chan);
-               ftdm_wait_flag_t flags = read_enabled ? ( FTDM_READ | FTDM_WRITE ) : 0;
-
-               if (ftdm_test_flag(ftdmchan, FTDM_CHANNEL_STATE_CHANGE) && (R2CALL(ftdmchan)->chanstate != ftdmchan->state)) {
-
-                       ftdm_log(FTDM_LOG_DEBUG, "Executing state handler on %d:%d for %s\n", ftdmchan->span_id, ftdmchan->chan_id, ftdm_channel_state2str(ftdmchan->state));
-                       R2CALL(ftdmchan)->chanstate = ftdmchan->state;
-
-                       if (!ftdm_test_flag(ftdmchan, FTDM_CHANNEL_OUTBOUND) && !R2CALL(ftdmchan)->accepted &&
-                                       (ftdmchan->state == FTDM_CHANNEL_STATE_PROGRESS ||
-                                        ftdmchan->state == FTDM_CHANNEL_STATE_PROGRESS_MEDIA ||
-                                        ftdmchan->state == FTDM_CHANNEL_STATE_UP) ) {
-                               /* if an accept ack will be required we should not acknowledge the state change just yet, 
-                                  it will be done below after processing the MF signals, otherwise we have a race condition between freetdm calling
-                                  openr2_chan_answer_call and openr2 accepting the call first, if freetdm calls openr2_chan_answer_call before the accept cycle
-                                  completes, openr2 will fail to answer the call */
-                               ftdm_log(FTDM_LOG_DEBUG, "State ack in chan %d:%d for state %s will have to wait a bit\n", ftdmchan->span_id, ftdmchan->chan_id, ftdm_channel_state2str(ftdmchan->state));
-                       } else if (ftdmchan->state != FTDM_CHANNEL_STATE_DOWN){
-                               /* the down state will be completed in ftdm_channel_done below */
-                               ftdm_clear_flag_locked(ftdmchan, FTDM_CHANNEL_STATE_CHANGE);
-                               ftdm_channel_complete_state(ftdmchan);
-                       }
+                               /* incoming call was offered */
+                       case FTDM_CHANNEL_STATE_RING:
 
-                       switch (ftdmchan->state) {
+                               /* notify the user about the new call */
+                               sigev.event_id = FTDM_SIGEVENT_START;
 
-                               /* starting an incoming call */
-                               case FTDM_CHANNEL_STATE_COLLECT: 
-                                       {
-                                               ftdm_log(FTDM_LOG_DEBUG, "COLLECT: Starting processing of incoming call in channel %d with interval %d\n", ftdmchan->physical_chan_id, interval);
-                                       }
-                                       break;
-
-                                       /* starting an outgoing call */
-                               case FTDM_CHANNEL_STATE_DIALING:
-                                       {
-                                               // FIXME: use user defined calling party
-                                               ftdm_channel_use(ftdmchan);
-                                               ftdm_log(FTDM_LOG_DEBUG, "DIALING: Starting processing of outgoing call in channel %d with interval %d\n", ftdmchan->physical_chan_id, interval);
-                                               if (openr2_chan_make_call(r2chan, ftdmchan->caller_data.cid_num.digits, ftdmchan->caller_data.dnis.digits, OR2_CALLING_PARTY_CATEGORY_NATIONAL_SUBSCRIBER)) {
-                                                       ftdm_log(FTDM_LOG_ERROR, "%d:%d Failed to make call in R2 channel, openr2_chan_make_call failed\n", ftdmchan->span_id, ftdmchan->chan_id);
-                                                       ftdmchan->caller_data.hangup_cause = FTDM_CAUSE_DESTINATION_OUT_OF_ORDER;
-                                                       ftdm_set_state_locked(ftdmchan, FTDM_CHANNEL_STATE_HANGUP);
-                                               }
-                                       }
-                                       break;
-
-                                       /* the call is ringing */
-                               case FTDM_CHANNEL_STATE_PROGRESS:
-                               case FTDM_CHANNEL_STATE_PROGRESS_MEDIA:
-                                       {
-                                               if (!ftdm_test_flag(ftdmchan, FTDM_CHANNEL_OUTBOUND)) {
-                                                       if (!R2CALL(ftdmchan)->accepted) {
-                                                               ftdm_log(FTDM_LOG_DEBUG, "PROGRESS: Accepting call on channel %d\n", ftdmchan->physical_chan_id);
-                                                               ft_r2_accept_call(ftdmchan);
-                                                       } 
-                                               } else {
-                                                       ftdm_log(FTDM_LOG_DEBUG, "PROGRESS: Notifying progress in channel %d\n", ftdmchan->physical_chan_id);
-                                                       sigev.event_id = FTDM_SIGEVENT_PROGRESS;
-                                                       if (ftdm_span_send_signal(ftdmchan->span, &sigev) != FTDM_SUCCESS) {
-                                                               ftdm_set_state_locked(ftdmchan, FTDM_CHANNEL_STATE_HANGUP);
-                                                       }
+                               if (ftdm_span_send_signal(ftdmchan->span, &sigev) != FTDM_SUCCESS) {
+                                       ftdm_log_chan_msg(ftdmchan, FTDM_LOG_NOTICE, "Failed to handle call offered\n");
+                                       openr2_chan_disconnect_call(r2chan, OR2_CAUSE_OUT_OF_ORDER);
+                                       ftdm_set_state(ftdmchan, FTDM_CHANNEL_STATE_CANCEL);
+                                       break; 
+                               }
+                               R2CALL(ftdmchan)->ftdm_started = 1; 
+
+                               break;
+
+                               /* the call is making progress */
+                       case FTDM_CHANNEL_STATE_PROGRESS:
+                       case FTDM_CHANNEL_STATE_PROGRESS_MEDIA:
+                               {
+                                       if (!ftdm_test_flag(ftdmchan, FTDM_CHANNEL_OUTBOUND)) {
+                                               if (!R2CALL(ftdmchan)->accepted) {
+                                                       ftdm_log_chan_msg(ftdmchan, FTDM_LOG_DEBUG, "Accepting call\n");
+                                                       ft_r2_accept_call(ftdmchan);
+                                               } 
+                                       } else {
+                                               ftdm_log_chan_msg(ftdmchan, FTDM_LOG_DEBUG, "Notifying progress\n");
+                                               sigev.event_id = FTDM_SIGEVENT_PROGRESS_MEDIA;
+                                               if (ftdm_span_send_signal(ftdmchan->span, &sigev) != FTDM_SUCCESS) {
+                                                       ftdm_set_state(ftdmchan, FTDM_CHANNEL_STATE_HANGUP);
                                                }
                                        }
-                                       break;
-
-                                       /* the call was answered */
-                               case FTDM_CHANNEL_STATE_UP:
-                                       {
-                                               ftdm_log(FTDM_LOG_DEBUG, "UP: Call was answered on channel %d\n", ftdmchan->physical_chan_id);
-                                               if (!ftdm_test_flag(ftdmchan, FTDM_CHANNEL_OUTBOUND)) {
-                                                       if (!R2CALL(ftdmchan)->accepted) {
-                                                               ftdm_log(FTDM_LOG_DEBUG, "UP: Call has not been accepted, need to accept first\n");
-                                                               // the answering will be done in the on_call_accepted handler
-                                                               ft_r2_accept_call(ftdmchan);
-                                                               R2CALL(ftdmchan)->answer_pending = 1;
-                                                       } else {
-                                                               ft_r2_answer_call(ftdmchan);
-                                                       }
+                               }
+                               break;
+
+                               /* the call was answered */
+                       case FTDM_CHANNEL_STATE_UP:
+                               {
+                                       ftdm_log_chan_msg(ftdmchan, FTDM_LOG_DEBUG, "Call was answered\n");
+                                       if (!ftdm_test_flag(ftdmchan, FTDM_CHANNEL_OUTBOUND)) {
+                                               if (!R2CALL(ftdmchan)->accepted) {
+                                                       ftdm_log_chan_msg(ftdmchan, FTDM_LOG_DEBUG, "Call has not been accepted, need to accept first\n");
+                                                       // the answering will be done in the on_call_accepted handler
+                                                       ft_r2_accept_call(ftdmchan);
+                                                       R2CALL(ftdmchan)->answer_pending = 1;
                                                } else {
-                                                       ftdm_log(FTDM_LOG_DEBUG, "UP: Notifying of call answered in channel %d\n", ftdmchan->physical_chan_id);
-                                                       sigev.event_id = FTDM_SIGEVENT_UP;
-                                                       if (ftdm_span_send_signal(ftdmchan->span, &sigev) != FTDM_SUCCESS) {
-                                                               ftdm_set_state_locked(ftdmchan, FTDM_CHANNEL_STATE_HANGUP);
-                                                       }
+                                                       ft_r2_answer_call(ftdmchan);
                                                }
-                                       }
-                                       break;
-
-                                       /* just got hangup */
-                               case FTDM_CHANNEL_STATE_HANGUP: 
-                                       {
-                                               /* FIXME: the cause should be retrieved from ftdmchan->caller_data.hangup_cause and translated from Q931 to R2 cause */
-                                               ftdm_log(FTDM_LOG_DEBUG, "HANGUP: Clearing call on channel %d\n", ftdmchan->physical_chan_id);
-                                               if (!R2CALL(ftdmchan)->disconnect_rcvd) {
-                                                       /* this will disconnect the call, but need to wait for the call end before moving to DOWN */
-                                                       openr2_chan_disconnect_call(r2chan, OR2_CAUSE_NORMAL_CLEARING);
-                                               } else {
-                                                       /* at this point on_call_end possibly was already called, 
-                                                        * but we needed to wait for the freetdm confirmation before moving to DOWN */
-                                                       ftdm_set_state_locked(ftdmchan, FTDM_CHANNEL_STATE_DOWN);
+                                       } else {
+                                               ftdm_log_chan_msg(ftdmchan, FTDM_LOG_DEBUG, "Notifying of call answered\n");
+                                               sigev.event_id = FTDM_SIGEVENT_UP;
+                                               if (ftdm_span_send_signal(ftdmchan->span, &sigev) != FTDM_SUCCESS) {
+                                                       ftdm_set_state(ftdmchan, FTDM_CHANNEL_STATE_HANGUP);
                                                }
                                        }
-                                       break;
+                               }
+                               break;
 
-                                       /* just got hangup from the freetdm side due to abnormal failure */
-                               case FTDM_CHANNEL_STATE_CANCEL:
-                                       {
-                                               ftdm_log(FTDM_LOG_DEBUG, "CANCEL: Unable to receive call on channel %d\n", ftdmchan->physical_chan_id);
-                                               openr2_chan_disconnect_call(r2chan, OR2_CAUSE_OUT_OF_ORDER);
-                                       }
-                                       break;
-
-                                       /* finished call for good */
-                               case FTDM_CHANNEL_STATE_DOWN: 
-                                       {
-                                               ftdm_log(FTDM_LOG_DEBUG, "DOWN: Placing channel %d back to the pool of available channels\n", ftdmchan->physical_chan_id);
-                                               ftdm_channel_done(ftdmchan);
-                                               goto endthread;
+                               /* just got hangup */
+                       case FTDM_CHANNEL_STATE_HANGUP: 
+                               {
+                                       openr2_call_disconnect_cause_t disconnect_cause = ftdm_r2_ftdm_cause_to_openr2_cause(ftdmchan);
+                                       ftdm_log_chan(ftdmchan, FTDM_LOG_DEBUG, "Clearing call, cause = %s\n", openr2_proto_get_disconnect_string(disconnect_cause));
+                                       openr2_chan_enable_read(r2chan);
+                                       if (!R2CALL(ftdmchan)->disconnect_rcvd) {
+                                               /* this will disconnect the call, but need to wait for the call end before moving to DOWN */
+                                               openr2_chan_disconnect_call(r2chan, disconnect_cause);
+                                       } else {
+                                               /* just ack the hangup, on_call_end will be called by openr2 right after */
+                                               openr2_chan_disconnect_call(r2chan, disconnect_cause);
                                        }
-                                       break;
+                               }
+                               break;
 
-                               default:
-                                       {
-                                               ftdm_log(FTDM_LOG_ERROR, "%s: Unhandled channel state change in channel %d\n", ftdm_channel_state2str(ftdmchan->state), ftdmchan->physical_chan_id);
-                                       }
-                                       break;
+                               /* just got hangup from the freetdm side due to abnormal failure */
+                       case FTDM_CHANNEL_STATE_CANCEL:
+                               {
+                                       ftdm_log_chan_msg(ftdmchan, FTDM_LOG_DEBUG, "Unable to receive call\n");
+                                       openr2_chan_enable_read(r2chan);
+                                       openr2_chan_disconnect_call(r2chan, OR2_CAUSE_OUT_OF_ORDER);
+                               }
+                               break;
 
-                       }
-               }
+                               /* finished call for good */
+                       case FTDM_CHANNEL_STATE_DOWN: 
+                               {
+                                       ftdm_log_chan_msg(ftdmchan, FTDM_LOG_DEBUG, "Call is down\n");
+                                       if (R2CALL(ftdmchan)->txdrops) {
+                                               ftdm_log_chan(ftdmchan, FTDM_LOG_WARNING, "dropped %d tx packets\n", R2CALL(ftdmchan)->txdrops);
+                                       }
+                                       ret = 1;
+                               }
+                               break;
 
-               if (flags) {
-                       if (ftdm_channel_wait(ftdmchan, &flags, interval * 2) != FTDM_SUCCESS) {
-                               ftdm_log(FTDM_LOG_DEBUG, "ftdm_channel_wait did not return FTDM_SUCCESS\n");
-                               continue;
-                       }
+                       default:
+                               {
+                                       ftdm_log_chan(ftdmchan, FTDM_LOG_ERROR, "Unhandled channel state change: %s\n", ftdm_channel_state2str(ftdmchan->state));
+                               }
+                               break;
 
-                       /* handle timeout events first if any */
-                       openr2_chan_run_schedule(r2chan);
-
-                       /* openr2 will now try to detect MF tones, make sense out of them, reply if necessary with another tone and trigger 
-                        * telephony events via the call event interface we provided when creating the R2 context.
-                        * openr2 will also call our I/O callbacks to retrieve audio from the channel and call our wait poll I/O registered callback
-                        * and will not return from this function until the I/O poll callback returns no pending events
-                        * */
-                       openr2_chan_process_mf_signaling(r2chan);
-                       if (R2CALL(ftdmchan)->state_ack_pending) {
-                               ftdm_clear_flag_locked(ftdmchan, FTDM_CHANNEL_STATE_CHANGE);
-                               ftdm_channel_complete_state(ftdmchan);
-                               R2CALL(ftdmchan)->state_ack_pending = 0;
-                       }
-               } else {
-                       /* once the MF signaling has end we just loop here waiting for state changes */
-                       ftdm_sleep(interval);
                }
-
        }
 
-endthread:
-
-       closed_chan = ftdmchan;
-       ftdm_channel_close(&closed_chan);
-       ftdm_clear_flag(ftdmchan, FTDM_CHANNEL_INTHREAD);
-       ftdm_log(FTDM_LOG_DEBUG, "R2 channel %d thread ended.\n", ftdmchan->physical_chan_id);
-
-       ftdm_mutex_lock(g_thread_count_mutex);
-       g_thread_count--;
-       ftdm_mutex_unlock(g_thread_count_mutex);
-
-       return NULL;
+       if (ret) {
+               ftdm_channel_t *closed_chan;
+               closed_chan = ftdmchan;
+               ftdm_channel_close(&closed_chan);
+               ftdm_log_chan_msg(ftdmchan, FTDM_LOG_DEBUG, "State processing ended.\n");
+       }
+       return ret;
 }
 
 static void *ftdm_r2_run(ftdm_thread_t *me, void *obj)
 {
        openr2_chan_t *r2chan;
+    ftdm_r2_call_t *r2call = NULL;
+    ftdm_channel_t *ftdmchan = NULL;
        ftdm_status_t status;
        ftdm_span_t *span = (ftdm_span_t *) obj;
        ftdm_r2_data_t *r2data = span->signal_data;
-       int waitms = 1000;
-       int i;
-
-       ftdm_log(FTDM_LOG_DEBUG, "OpenR2 monitor thread started.\n");
-  r2chan = NULL;
+       int waitms = 20;
+       int i, res;
+       int ms;
+       struct timeval start, end;
+    short *poll_events = ftdm_malloc(sizeof(short)*span->chan_count);
+
+#ifdef __linux__
+       r2data->monitor_thread_id = syscall(SYS_gettid);        
+#endif
+       
+       ftdm_log(FTDM_LOG_DEBUG, "OpenR2 monitor thread %lu started.\n", r2data->monitor_thread_id);
+       r2chan = NULL;
        for (i = 1; i <= span->chan_count; i++) {
                r2chan = R2CALL(span->channels[i])->r2chan;
                openr2_chan_set_idle(r2chan);
                openr2_chan_process_cas_signaling(r2chan);
        }
 
+       memset(&start, 0, sizeof(start));
+       memset(&end, 0, sizeof(end));
        while (ftdm_running() && ftdm_test_flag(r2data, FTDM_R2_RUNNING)) {
-               status = ftdm_span_poll_event(span, waitms);
+               r2data->loops++;
+               res = gettimeofday(&end, NULL);
+               if (start.tv_sec) {
+                       ms = ((end.tv_sec - start.tv_sec) * 1000) 
+                           + ((( 1000000 + end.tv_usec - start.tv_usec) / 1000) - 1000);
+                       if (ms > r2data->jobmax) {
+                               r2data->jobmax = ms;
+                       }
+               }
+
+        /* figure out what event to poll each channel for. POLLIN|POLLOUT for channels that has a call being
+         * setup, POLLPRI otherwise */
+        memset(poll_events, 0, sizeof(short)*span->chan_count);
+        for (i = 0; i < span->chan_count; i++) {
+            r2chan = R2CALL(span->channels[(i+1)])->r2chan;
+            ftdmchan = openr2_chan_get_client_data(r2chan);
+
+            poll_events[i] = ftdmchan->state == FTDM_CHANNEL_STATE_DOWN ? POLLPRI : (POLLPRI | POLLIN | POLLOUT);
+        }
+
+               status = ftdm_span_poll_event(span, waitms, poll_events);
+
+               res = gettimeofday(&start, NULL);
+               if (res) {
+                       ftdm_log(FTDM_LOG_CRIT, "Failure gettimeofday [%s]\n", strerror(errno));
+               }
+
                if (FTDM_FAIL == status) {
-                       ftdm_log(FTDM_LOG_ERROR, "Failure Polling event! [%s]\n", span->last_error);
+                       ftdm_log(FTDM_LOG_CRIT, "Failure waiting I/O! [%s]\n", span->channels[1]->last_error);
                        continue;
                }
-               if (FTDM_SUCCESS == status) {
+
+        if (FTDM_SUCCESS == status) {
                        ftdm_event_t *event;
                        while (ftdm_span_next_event(span, &event) == FTDM_SUCCESS) {
                                if (event->enum_id == FTDM_OOB_CAS_BITS_CHANGE) {
-                    r2chan = R2CALL(event->channel)->r2chan;
+                    r2call = R2CALL(event->channel);
+                    r2chan = r2call->r2chan;
+
                                        ftdm_log(FTDM_LOG_DEBUG, "Handling CAS on channel %d.\n", openr2_chan_get_number(r2chan));
                                        // we only expect CAS and other OOB events on this thread/loop, once a call is started
                                        // the MF events (in-band signaling) are handled in the call thread
                                        openr2_chan_process_cas_signaling(r2chan);
+
                                } else {
                                        ftdm_log(FTDM_LOG_DEBUG, "Ignoring event %d on channel %d.\n", event->enum_id, openr2_chan_get_number(r2chan));
                                        // XXX TODO: handle alarms here XXX
                                }
                        }
+
+            /* XXX when ftdm_span_poll_event() returns FTDM_SUCCESS, means there are events pending on the span,
+             * is it possible to know on what channel there were events, without traversing the span? XXX
+             */
+            for (i = 1; i <= span->chan_count; i++) {
+                r2chan = R2CALL(span->channels[i])->r2chan;
+                ftdmchan = openr2_chan_get_client_data(r2chan);
+                r2call = R2CALL(ftdmchan);
+
+                ftdm_mutex_lock(ftdmchan->mutex);
+                ftdm_set_flag(r2call, FTDM_R2_PROCESSING);
+
+                if (ftdm_r2_state_advance(ftdmchan)) {
+                    ftdm_clear_flag(r2call, FTDM_R2_PROCESSING);
+                    ftdm_mutex_unlock(ftdmchan->mutex);
+                    continue;
+                }
+
+                /* handle timeout events first if any */
+                openr2_chan_run_schedule(r2chan);
+
+                /* process mf tones, if any */
+                if (openr2_chan_get_read_enabled(r2chan))
+                    openr2_chan_process_mf_signaling(r2chan);
+
+                if (ftdm_r2_state_advance(ftdmchan)) {
+                    ftdm_clear_flag(r2call, FTDM_R2_PROCESSING);
+                    ftdm_mutex_unlock(ftdmchan->mutex);
+                    continue;
+                }
+
+                ftdm_clear_flag(r2call, FTDM_R2_PROCESSING);
+                ftdm_mutex_unlock(ftdmchan->mutex);
+            }
                } else if (status != FTDM_TIMEOUT) {
                        ftdm_log(FTDM_LOG_ERROR, "ftdm_span_poll_event returned %d.\n", status);
-               } else {
-                       //ftdm_log(FTDM_LOG_DEBUG, "timed out waiting for event on span %d\n", span->span_id);
-               }
+        } else {
+               } 
+
        }
 
-    /*
-    FIXME: we should set BLOCKED but at this point I/O routines of freetdm caused segfault
        for (i = 1; i <= span->chan_count; i++) {
                r2chan = R2CALL(span->channels[i])->r2chan;
                openr2_chan_set_blocked(r2chan);
        }
-    */
 
        ftdm_clear_flag(r2data, FTDM_R2_RUNNING);
        ftdm_log(FTDM_LOG_DEBUG, "R2 thread ending.\n");
 
        return NULL;
+}
 
+static void __inline__ block_channel(ftdm_channel_t *fchan, ftdm_stream_handle_t *stream)
+{
+       openr2_chan_t *r2chan = R2CALL(fchan)->r2chan;
+       ftdm_mutex_lock(fchan->mutex);
+       if (fchan->state != FTDM_CHANNEL_STATE_DOWN) {
+               stream->write_function(stream, "cannot block channel %d:%d because has a call in progress\n", 
+                               fchan->span_id, fchan->chan_id);
+       } else if (ftdm_test_flag(fchan, FTDM_CHANNEL_SUSPENDED)) {
+               stream->write_function(stream, "cannot block channel %d:%d because is already blocked\n", 
+                               fchan->span_id, fchan->chan_id);
+       } else {
+               if (!openr2_chan_set_blocked(r2chan)) {
+                       ftdm_set_flag(fchan, FTDM_CHANNEL_SUSPENDED);
+                       stream->write_function(stream, "blocked channel %d:%d\n", 
+                                       fchan->span_id, fchan->chan_id);
+               } else {
+                       stream->write_function(stream, "failed to block channel %d:%d\n", 
+                                       fchan->span_id, fchan->chan_id);
+               }
+       }
+       ftdm_mutex_unlock(fchan->mutex);
+}
+
+static void __inline__ unblock_channel(ftdm_channel_t *fchan, ftdm_stream_handle_t *stream)
+{
+       openr2_chan_t *r2chan = R2CALL(fchan)->r2chan;
+       ftdm_mutex_lock(fchan->mutex);
+       if (ftdm_test_flag(fchan, FTDM_CHANNEL_SUSPENDED)) {
+               if (!openr2_chan_set_idle(r2chan)) {
+                       ftdm_clear_flag(fchan, FTDM_CHANNEL_SUSPENDED);
+                       stream->write_function(stream, "unblocked channel %d:%d\n", 
+                                       fchan->span_id, fchan->chan_id);
+               } else {
+                       stream->write_function(stream, "failed to unblock channel %d:%d\n", 
+                                       fchan->span_id, fchan->chan_id);
+               }
+       } else {
+               stream->write_function(stream, "cannot unblock channel %d:%d because is not blocked\n", 
+                               fchan->span_id, fchan->chan_id);
+       }
+       ftdm_mutex_unlock(fchan->mutex);
 }
 
 static FIO_API_FUNCTION(ftdm_r2_api)
 {
+       ftdm_span_t *span = NULL;
        char *mycmd = NULL, *argv[10] = { 0 };
        int argc = 0;
+       int span_id = 0;
+       int chan_id = 0;
+       int i = 0;
 
        if (data) {
                mycmd = ftdm_strdup(data);
                argc = ftdm_separate_string(mycmd, ' ', argv, (sizeof(argv) / sizeof(argv[0])));
        }
 
-       if (argc == 2) {
-               if (!strcasecmp(argv[0], "kill")) {
+       if (argc >= 2) {
+               if (!strcasecmp(argv[0], "block")) {
                        int span_id = atoi(argv[1]);
-                       ftdm_span_t *span = NULL;
 
                        if (ftdm_span_find_by_name(argv[1], &span) == FTDM_SUCCESS || ftdm_span_find(span_id, &span) == FTDM_SUCCESS) {
-                               ftdm_r2_data_t *r2data = span->signal_data;
 
                                if (span->start != ftdm_r2_start) {
                                        stream->write_function(stream, "-ERR invalid span.\n");
                                        goto done;
                                }
 
-                               ftdm_clear_flag(r2data, FTDM_R2_RUNNING);
-                               stream->write_function(stream, "+OK killed.\n");
+                               if (argc > 2) {
+                                       chan_id = atoi(argv[2]);
+                                       if (chan_id && chan_id <= span->chan_count) {
+                                               block_channel(span->channels[chan_id], stream);
+                                       } else {
+                                               stream->write_function(stream, "-ERR invalid chan %d.\n", chan_id);
+                                       }
+                               } else {
+                                       for (i = 1; i <= span->chan_count; i++) {
+                                               block_channel(span->channels[i], stream);
+                                       }
+                               }
+                               stream->write_function(stream, "+OK blocked.\n");
                                goto done;
                        } else {
                                stream->write_function(stream, "-ERR invalid span.\n");
@@ -1204,13 +1550,43 @@ static FIO_API_FUNCTION(ftdm_r2_api)
                        }
                }
 
+               if (!strcasecmp(argv[0], "unblock")) {
+                       span_id = atoi(argv[1]);
+                       if (ftdm_span_find_by_name(argv[1], &span) == FTDM_SUCCESS || ftdm_span_find(span_id, &span) == FTDM_SUCCESS) {
+
+                               if (span->start != ftdm_r2_start) {
+                                       stream->write_function(stream, "-ERR invalid span.\n");
+                                       goto done;
+                               }
+
+                               if (argc > 2) {
+                                       chan_id = atoi(argv[2]);
+                                       if (chan_id && chan_id <= span->chan_count) {
+                                               unblock_channel(span->channels[chan_id], stream);
+                                       } else {
+                                               stream->write_function(stream, "-ERR invalid chan %d.\n", chan_id);
+                                       }
+                               } else {
+                                       for (i = 1; i <= span->chan_count; i++) {
+                                               unblock_channel(span->channels[i], stream);
+                                       }
+                               }
+                               
+                               stream->write_function(stream, "+OK.\n");
+                               goto done;
+                       } else {
+                               stream->write_function(stream, "-ERR invalid span.\n");
+                               goto done;
+                       }
+
+               }
+
                if (!strcasecmp(argv[0], "status")) {
-                       int span_id = atoi(argv[1]);
+                       //openr2_chan_stats_t stats;
+                       span_id = atoi(argv[1]);
                        ftdm_r2_data_t *r2data = NULL;
-                       ftdm_span_t *span = NULL;
                        openr2_chan_t *r2chan = NULL;
                        openr2_context_t *r2context = NULL;
-                       int i = 0;
 
                        if (ftdm_span_find_by_name(argv[1], &span) == FTDM_SUCCESS || ftdm_span_find(span_id, &span) == FTDM_SUCCESS) {
                                if (span->start != ftdm_r2_start) {
@@ -1228,21 +1604,44 @@ static FIO_API_FUNCTION(ftdm_r2_api)
                                                "Max ANI: %d\n"
                                                "Max DNIS: %d\n"
                                                "ANI First: %s\n"
-                                               "Immediate Accept: %s\n",
+                                               "Immediate Accept: %s\n"
+                                               "Side: %s\n"
+                                               "Job Max ms: %d\n"
+                                               "Job Loops: %lu\n"
+                                               "Monitor Thread: %lu\n",
                                                openr2_proto_get_variant_string(r2variant),
                                                openr2_context_get_max_ani(r2context),
                                                openr2_context_get_max_dnis(r2context),
                                                openr2_context_get_ani_first(r2context) ? "Yes" : "No",
-                                               openr2_context_get_immediate_accept(r2context) ? "Yes" : "No");
+                                               openr2_context_get_immediate_accept(r2context) ? "Yes" : "No",
+                                                "no side",
+                                               r2data->jobmax, 
+                                               r2data->loops,
+                                               r2data->monitor_thread_id);
                                stream->write_function(stream, "\n");
-                               stream->write_function(stream, "%4s %-12.12s %-12.12s\n", "Channel", "Tx CAS", "Rx CAS");
+                               stream->write_function(stream, "%4s %-12.12s %-12.12s %6s %6s %6s %6s\n", "Channel", "Tx CAS", "Rx CAS", 
+                                               "Rx Avg", "Tx Avg", "Rx", "Tx");
                                for (i = 1; i <= span->chan_count; i++) {
-                                       if (i == 16) continue;
+                                       char rx_str[25];
+                                       char tx_str[25];
+                                       char rxavg_str[25];
+                                       char txavg_str[25];
                                        r2chan = R2CALL(span->channels[i])->r2chan;
-                                       stream->write_function(stream, "%4d    %-12.12s %-12.12s\n", 
-                                                       span->channels[i]->physical_chan_id,
+#if 0
+                                       openr2_chan_get_stats(r2chan, &stats);
+                                       snprintf(rx_str, sizeof(rx_str), "%lu", stats.rxcount);
+                                       snprintf(tx_str, sizeof(tx_str), "%lu", stats.txcount);
+                                       snprintf(rxavg_str, sizeof(rxavg_str), "%u", stats.rxavg);
+                                       snprintf(txavg_str, sizeof(txavg_str), "%u", stats.txavg);
+#endif
+                                       stream->write_function(stream, "%4d    %-12.12s %-12.12s %6s %6s %6s %6s\n", 
+                                                       span->channels[i]->chan_id,
                                                        openr2_chan_get_tx_cas_string(r2chan),
-                                                       openr2_chan_get_rx_cas_string(r2chan));
+                                                       openr2_chan_get_rx_cas_string(r2chan),
+                                                       rxavg_str,
+                                                       txavg_str,
+                                                       rx_str,
+                                                       tx_str);
                                }
                                stream->write_function(stream, "\n");
                                stream->write_function(stream, "+OK.\n");
index 7234e67183cf7f091845b0c1fdf4f4d7de369312..a975204b6290293cc57d95a3b76b1cf251cb339f 100644 (file)
@@ -1725,7 +1725,7 @@ static __inline__ ftdm_status_t check_events(ftdm_span_t *span, int ms_timeout)
        ftdm_status_t status;
        ftdm_sangoma_boost_data_t *sangoma_boost_data = span->signal_data;
 
-       status = ftdm_span_poll_event(span, ms_timeout);
+       status = ftdm_span_poll_event(span, ms_timeout, NULL);
 
        switch(status) {
        case FTDM_SUCCESS:
index be99f94aff5545e5db02c9f4c9ea72993de0e335..5a472e5a8d65b7172bb62e0bee8ae362410ec5bb 100644 (file)
@@ -865,11 +865,11 @@ FIO_SPAN_POLL_EVENT_FUNCTION(wanpipe_poll_event)
                        continue; /* should never happen but happens when shutting down */
                }
                pfds[j] = ftdmchan->mod_data;
-               inflags[j] = POLLPRI;
+               inflags[j] = poll_events ? poll_events[j] : POLLPRI;
 #else
                memset(&pfds[j], 0, sizeof(pfds[j]));
                pfds[j].fd = span->channels[i]->sockfd;
-               pfds[j].events = POLLPRI;
+               pfds[j].events = poll_events ? poll_events[j] : POLLPRI;
 #endif
 
                /* The driver probably should be able to do this wink/flash/ringing by itself this is sort of a hack to make it work! */
index 078875b09cb3490ffda5b4e448e00df2faab42bf..b1188e35fceb6688574f34c2e875442a562c558f 100644 (file)
@@ -459,7 +459,7 @@ struct ftdm_memory_handler {
 #define FIO_CHANNEL_GET_SIG_STATUS_ARGS (ftdm_channel_t *ftdmchan, ftdm_signaling_status_t *status)
 #define FIO_SPAN_SET_SIG_STATUS_ARGS (ftdm_span_t *span, ftdm_signaling_status_t status)
 #define FIO_SPAN_GET_SIG_STATUS_ARGS (ftdm_span_t *span, ftdm_signaling_status_t *status)
-#define FIO_SPAN_POLL_EVENT_ARGS (ftdm_span_t *span, uint32_t ms)
+#define FIO_SPAN_POLL_EVENT_ARGS (ftdm_span_t *span, uint32_t ms, short *poll_events)
 #define FIO_SPAN_NEXT_EVENT_ARGS (ftdm_span_t *span, ftdm_event_t **event)
 #define FIO_SIGNAL_CB_ARGS (ftdm_sigmsg_t *sigmsg)
 #define FIO_EVENT_CB_ARGS (ftdm_channel_t *ftdmchan, ftdm_event_t *event)
@@ -820,12 +820,13 @@ FT_DECLARE(void) ftdm_channel_flush_dtmf(ftdm_channel_t *ftdmchan);
  *
  * \param span The span to wait events for
  * \param ms Milliseconds timeout
+ * \param poll_events Array of events to poll for, for each channel on the span
  *
  * \retval FTDM_SUCCESS success (at least one event available)
  * \retval FTDM_TIMEOUT Timed out waiting for events
  * \retval FTDM_FAIL failure
  */
-FT_DECLARE(ftdm_status_t) ftdm_span_poll_event(ftdm_span_t *span, uint32_t ms);
+FT_DECLARE(ftdm_status_t) ftdm_span_poll_event(ftdm_span_t *span, uint32_t ms, short *poll_events);
 
 /*! 
  * \brief Find a span by its id