freetdm: completed most of the code for the new core state processing

	 use new core state processing functions in ftmod_r2

libs/freetdm/mod_freetdm/mod_freetdm.c

@@ -421,16 +421,18 @@ static switch_status_t channel_on_routing(switch_core_session_t *session)
 	private_t *tech_pvt = NULL;
 
 	channel = switch_core_session_get_channel(session);
-	assert(channel != NULL);
+	switch_assert(channel != NULL);
 
 	tech_pvt = switch_core_session_get_private(session);
-	assert(tech_pvt != NULL);
+	switch_assert(tech_pvt != NULL);
 
-	assert(tech_pvt->ftdmchan != NULL);
+	switch_assert(tech_pvt->ftdmchan != NULL);
 
 	switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_DEBUG, "%s CHANNEL ROUTING\n", switch_channel_get_name(channel));
 
-	ftdm_channel_call_indicate(tech_pvt->ftdmchan, FTDM_CHANNEL_INDICATE_PROCEED);
+	if (switch_channel_direction(channel) == SWITCH_CALL_DIRECTION_INBOUND) {
+		ftdm_channel_call_indicate(tech_pvt->ftdmchan, FTDM_CHANNEL_INDICATE_PROCEED);
+	}
 	return SWITCH_STATUS_SUCCESS;
 }
 
@@ -441,10 +443,10 @@ static switch_status_t channel_on_execute(switch_core_session_t *session)
 	private_t *tech_pvt = NULL;
 
 	channel = switch_core_session_get_channel(session);
-	assert(channel != NULL);
+	switch_assert(channel != NULL);
 
 	tech_pvt = switch_core_session_get_private(session);
-	assert(tech_pvt != NULL);
+	switch_assert(tech_pvt != NULL);
 
 	switch_log_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_DEBUG, "%s CHANNEL EXECUTE\n", switch_channel_get_name(channel));
 
@@ -2094,6 +2096,7 @@ static FIO_SIGNAL_CB_FUNCTION(on_r2_signal)
 		break;
 
 		case FTDM_SIGEVENT_PROCEED:{} break;
+		case FTDM_SIGEVENT_INDICATION_COMPLETED:{} break;
 
 		default:
 		{

libs/freetdm/src/ftdm_io.c

@@ -1022,6 +1022,8 @@ FT_DECLARE(ftdm_status_t) ftdm_span_add_channel(ftdm_span_t *span, ftdm_socket_t
 		}
 
 		ftdm_set_flag(new_chan, FTDM_CHANNEL_CONFIGURED | FTDM_CHANNEL_READY);		
+		new_chan->state = FTDM_CHANNEL_STATE_DOWN;
+		new_chan->state_status = FTDM_STATE_STATUS_COMPLETED;
 		*chan = new_chan;
 		return FTDM_SUCCESS;
 	}
@@ -2012,10 +2014,14 @@ FT_DECLARE(ftdm_status_t) _ftdm_channel_call_unhold(const char *file, const char
 	return status;
 }
 
-FT_DECLARE(void) ftdm_ack_indication(const ftdm_channel_t *fchan, ftdm_channel_indication_t indication, ftdm_status_t status)
+FT_DECLARE(void) ftdm_ack_indication(ftdm_channel_t *fchan, ftdm_channel_indication_t indication, ftdm_status_t status)
 {
 	ftdm_sigmsg_t msg;
+	ftdm_log_chan(fchan, FTDM_LOG_DEBUG, "Acknowledging indication %s in state %s (rc = %d)\n", 
+			ftdm_channel_indication2str(indication), ftdm_channel_state2str(fchan->state), status);
+	ftdm_clear_flag(fchan, FTDM_CHANNEL_IND_ACK_PENDING);
 	memset(&msg, 0, sizeof(msg));
+	msg.channel = fchan;
 	msg.event_id = FTDM_SIGEVENT_INDICATION_COMPLETED;
 	msg.ev_data.indication_completed.indication = indication;
 	msg.ev_data.indication_completed.status = status;
@@ -2197,21 +2203,39 @@ FT_DECLARE(uint32_t) ftdm_channel_get_ph_span_id(const ftdm_channel_t *ftdmchan)
 
 /*
  * Every user requested indication *MUST* be acknowledged with the proper status (ftdm_status_t)
- * If the indication fails before we notify the signaling stack, we *MUST* acknowledge ourselves,
+ * However, if the indication fails before we notify the signaling stack, we don't need to ack
  * but if we already notified the signaling stack about the indication, the signaling stack is
- * responsible for the acknowledge.
+ * responsible for the acknowledge. Bottom line is, whenever this function returns FTDM_SUCCESS
+ * someone *MUST* acknowledge the indication, either the signaling stack, this function or the core
+ * at some later point
  * */
 FT_DECLARE(ftdm_status_t) _ftdm_channel_call_indicate(const char *file, const char *func, int line, ftdm_channel_t *ftdmchan, ftdm_channel_indication_t indication)
 {
 	ftdm_status_t status = FTDM_SUCCESS;
 
+	ftdm_assert_return(ftdmchan, FTDM_FAIL, "Null channel\n");
+
+	ftdm_log_chan(ftdmchan, FTDM_LOG_DEBUG, "Indicating %s in state %s\n",
+			ftdm_channel_indication2str(indication), ftdm_channel_state2str(ftdmchan->state));
+
 	ftdm_channel_lock(ftdmchan);
 
+	if (ftdm_test_flag(ftdmchan, FTDM_CHANNEL_IND_ACK_PENDING)) {
+		ftdm_log_chan(ftdmchan, FTDM_LOG_WARNING, "Cannot indicate %s in channel with indication %s still pending in state %s\n",
+				ftdm_channel_indication2str(indication), 
+				ftdm_channel_indication2str(ftdmchan->indication),
+				ftdm_channel_state2str(ftdmchan->state));
+		status = FTDM_EBUSY;
+		goto done;
+	}
+
+	ftdmchan->indication = indication;
+	ftdm_set_flag(ftdmchan, FTDM_CHANNEL_IND_ACK_PENDING);
+
 	if (ftdm_test_flag(ftdmchan, FTDM_CHANNEL_OUTBOUND)) {
 		ftdm_log_chan(ftdmchan, FTDM_LOG_WARNING, "Cannot indicate %s in outgoing channel in state %s\n",
 				ftdm_channel_indication2str(indication), ftdm_channel_state2str(ftdmchan->state));
 		status = FTDM_EINVAL;
-		ftdm_ack_indication(ftdmchan, indication, status);
 		goto done;
 	}
 
@@ -2219,7 +2243,6 @@ FT_DECLARE(ftdm_status_t) _ftdm_channel_call_indicate(const char *file, const ch
 		ftdm_log_chan(ftdmchan, FTDM_LOG_DEBUG, "Ignoring indication %s because the call is in %s state\n",
 				ftdm_channel_indication2str(indication), ftdm_channel_state2str(ftdmchan->state));
 		status = FTDM_ECANCELED;
-		ftdm_ack_indication(ftdmchan, indication, status);
 		goto done;
 	}
 
@@ -2228,15 +2251,9 @@ FT_DECLARE(ftdm_status_t) _ftdm_channel_call_indicate(const char *file, const ch
 	 * (particularly isdn stacks I think, we should emulate or just move to hangup with busy cause) */
 	case FTDM_CHANNEL_INDICATE_RINGING:
 		status = ftdm_channel_set_state(file, func, line, ftdmchan, FTDM_CHANNEL_STATE_RINGING, 1);
-		if (status != FTDM_SUCCESS) {
-			ftdm_ack_indication(ftdmchan, indication, status);
-		}
 		break;
 	case FTDM_CHANNEL_INDICATE_BUSY:
 		status = ftdm_channel_set_state(file, func, line, ftdmchan, FTDM_CHANNEL_STATE_BUSY, 1);
-		if (status != FTDM_SUCCESS) {
-			ftdm_ack_indication(ftdmchan, indication, status);
-		}
 		break;
 	case FTDM_CHANNEL_INDICATE_PROCEED:
 		if (!ftdm_test_flag(ftdmchan->span, FTDM_SPAN_USE_PROCEED_STATE)) {
@@ -2244,47 +2261,34 @@ FT_DECLARE(ftdm_status_t) _ftdm_channel_call_indicate(const char *file, const ch
 			goto done;
 		}
 		status = ftdm_channel_set_state(file, func, line, ftdmchan, FTDM_CHANNEL_STATE_PROCEED, 1);
-		if (status != FTDM_SUCCESS) {
-			ftdm_ack_indication(ftdmchan, indication, status);
-		}
 		break;
 	case FTDM_CHANNEL_INDICATE_PROGRESS:
 		status = ftdm_channel_set_state(file, func, line, ftdmchan, FTDM_CHANNEL_STATE_PROGRESS, 1);
-		if (status != FTDM_SUCCESS) {
-			ftdm_ack_indication(ftdmchan, indication, status);
-		}
 		break;
 	case FTDM_CHANNEL_INDICATE_PROGRESS_MEDIA:
 		if (!ftdm_test_flag(ftdmchan->span, FTDM_SPAN_USE_SKIP_STATES)) {
 			if (ftdmchan->state < FTDM_CHANNEL_STATE_PROGRESS) {
 				status = ftdm_channel_set_state(file, func, line, ftdmchan, FTDM_CHANNEL_STATE_PROGRESS, 1);
 				if (status != FTDM_SUCCESS) {
-					ftdm_ack_indication(ftdmchan, indication, status);
 					goto done;
 				}
 			}
 
 			/* set state unlocks the channel so we need to re-confirm that the channel hasn't gone to hell */
 			if (ftdmchan->state == FTDM_CHANNEL_STATE_TERMINATING) {
-				ftdm_log_chan_msg(ftdmchan, FTDM_LOG_DEBUG, "Ignoring answer because the call has moved to TERMINATING while we're moving to PROGRESS\n");
-				status = FTDM_ECANCELED;
-				ftdm_ack_indication(ftdmchan, indication, status);
+				ftdm_log_chan_msg(ftdmchan, FTDM_LOG_DEBUG, "Ignoring progress media because the call is terminating\n");
 				goto done;
 			}
 		}
-		ftdm_channel_set_state(file, func, line, ftdmchan, FTDM_CHANNEL_STATE_PROGRESS_MEDIA, 1);
-		if (status != FTDM_SUCCESS) {
-			ftdm_ack_indication(ftdmchan, indication, status);
-		}
+		status = ftdm_channel_set_state(file, func, line, ftdmchan, FTDM_CHANNEL_STATE_PROGRESS_MEDIA, 1);
 		break;
 	case FTDM_CHANNEL_INDICATE_ANSWER:
-		/* _ftdm_channel_call_indicate takes care of the indication ack */
+		/* _ftdm_channel_call_answer takes care of the indication ack */
 		status = _ftdm_channel_call_answer(file, func, line, ftdmchan);
 		break;
 	default:
 		ftdm_log(file, func, line, FTDM_LOG_LEVEL_WARNING, "Do not know how to indicate %d\n", indication);
-		status = FTDM_FAIL;
-		ftdm_ack_indication(ftdmchan, indication, status);
+		status = FTDM_EINVAL;
 		break;
 	}
 
@@ -2463,6 +2467,7 @@ static ftdm_status_t ftdm_channel_done(ftdm_channel_t *ftdmchan)
 
 	ftdmchan->init_state = FTDM_CHANNEL_STATE_DOWN;
 	ftdmchan->state = FTDM_CHANNEL_STATE_DOWN;
+	ftdmchan->state_status = FTDM_STATE_STATUS_COMPLETED;
 
 	ftdm_channel_command(ftdmchan, FTDM_COMMAND_DISABLE_DEBUG_DTMF, NULL);
 	ftdm_channel_command(ftdmchan, FTDM_COMMAND_DISABLE_INPUT_DUMP, NULL);
@@ -5023,7 +5028,7 @@ FT_DECLARE(ftdm_status_t) ftdm_configure_span_signaling(ftdm_span_t *span, const
 	ftdm_assert_return(parameters != NULL, FTDM_FAIL, "No parameters");
 
 	if (!span->chan_count) {
-		ftdm_log(FTDM_LOG_WARNING, "Cannot configure signaling on span with no channels\n");
+		ftdm_log(FTDM_LOG_WARNING, "Cannot configure signaling on span %s with no channels\n", span->name);
 		return FTDM_FAIL;
 	}
 

libs/freetdm/src/ftdm_state.c

@@ -37,6 +37,9 @@
 FTDM_ENUM_NAMES(CHANNEL_STATE_NAMES, CHANNEL_STATE_STRINGS)
 FTDM_STR2ENUM(ftdm_str2ftdm_channel_state, ftdm_channel_state2str, ftdm_channel_state_t, CHANNEL_STATE_NAMES, FTDM_CHANNEL_STATE_INVALID)
 
+FTDM_ENUM_NAMES(CHANNEL_STATE_STATUS_NAMES, CHANNEL_STATE_STATUS_STRINGS)
+FTDM_STR2ENUM(ftdm_str2ftdm_state_status, ftdm_state_status2str, ftdm_state_status_t, CHANNEL_STATE_STATUS_NAMES, FTDM_STATE_STATUS_INVALID)
+
 /* This function is only needed for boost and we should get rid of it at the next refactoring */
 FT_DECLARE(ftdm_status_t) ftdm_channel_init(ftdm_channel_t *fchan)
 {
@@ -54,12 +57,17 @@ FT_DECLARE(ftdm_status_t) ftdm_channel_init(ftdm_channel_t *fchan)
 FT_DECLARE(ftdm_status_t) _ftdm_channel_complete_state(const char *file, const char *func, int line, ftdm_channel_t *fchan)
 {
 	uint8_t hindex = 0;
+	ftdm_time_t diff = 0;
 	ftdm_channel_state_t state = fchan->state;
 
 	if (fchan->state_status == FTDM_STATE_STATUS_COMPLETED) {
+		ftdm_assert_return(!ftdm_test_flag(fchan, FTDM_CHANNEL_STATE_CHANGE), FTDM_FAIL, 
+				"State change flag set but state is not completed\n");
 		return FTDM_SUCCESS;
 	}
 
+	ftdm_clear_flag(fchan, FTDM_CHANNEL_STATE_CHANGE);
+
 	if (state == FTDM_CHANNEL_STATE_PROGRESS) {
 		ftdm_set_flag(fchan, FTDM_CHANNEL_PROGRESS);
 	} else if (state == FTDM_CHANNEL_STATE_UP) {
@@ -71,19 +79,28 @@ FT_DECLARE(ftdm_status_t) _ftdm_channel_complete_state(const char *file, const c
 		ftdm_set_flag(fchan, FTDM_CHANNEL_MEDIA);	
 	}
 
-	/* if there is a pending ack for an indication */
+	/* if there is a pending ack for an indication
+	 * MAINTENANCE WARNING: we're assuming an indication performed 
+	 * via state change will involve a single state change
+	 */
 	if (ftdm_test_flag(fchan, FTDM_CHANNEL_IND_ACK_PENDING)) {
 		ftdm_ack_indication(fchan, fchan->indication, FTDM_SUCCESS);
-		ftdm_clear_flag(fchan, FTDM_CHANNEL_IND_ACK_PENDING);
 	}
 
-	ftdm_log_chan_ex(fchan, file, func, line, FTDM_LOG_LEVEL_DEBUG, "Completed state change from %s to %s\n", ftdm_channel_state2str(fchan->state), ftdm_channel_state2str(state));
-	hindex = (fchan->hindex == 0) ? (ftdm_array_len(fchan->history) - 1) : (hindex - 1);
+	hindex = (fchan->hindex == 0) ? (ftdm_array_len(fchan->history) - 1) : (fchan->hindex - 1);
 	
 	ftdm_assert(!fchan->history[hindex].end_time, "End time should be zero!\n");
 
 	fchan->history[hindex].end_time = ftdm_current_time_in_ms();
 
+	fchan->state_status = FTDM_STATE_STATUS_COMPLETED;
+
+	diff = fchan->history[hindex].end_time - fchan->history[hindex].time;
+
+	ftdm_log_chan_ex(fchan, file, func, line, FTDM_LOG_LEVEL_DEBUG, "Completed state change from %s to %s in %llums\n", 
+			ftdm_channel_state2str(fchan->last_state), ftdm_channel_state2str(state), diff);
+	
+
 	/* FIXME: broadcast condition to wake up anyone waiting on state completion if the channel 
 	 * is blocking (FTDM_CHANNEL_NONBLOCK is not set) */
 
@@ -93,9 +110,9 @@ FT_DECLARE(ftdm_status_t) _ftdm_channel_complete_state(const char *file, const c
 FT_DECLARE(ftdm_status_t) _ftdm_set_state(const char *file, const char *func, int line,
 		ftdm_channel_t *fchan, ftdm_channel_state_t state)
 {
-	if (fchan->state_status == FTDM_STATE_STATUS_NEW) {
-		/* the current state is new, setting a new state from a signaling module
-		   when the current state is new is equivalent to implicitly acknowledging 
+	if (fchan->state_status != FTDM_STATE_STATUS_COMPLETED) {
+		/* the current state is not completed, setting a new state from a signaling module
+		   when the current state is not completed is equivalent to implicitly acknowledging 
 		   the current state */
 		_ftdm_channel_complete_state(file, func, line, fchan);
 	}
@@ -161,9 +178,11 @@ FT_DECLARE(ftdm_status_t) ftdm_channel_set_state(const char *file, const char *f
 		return FTDM_FAIL;
 	}
 
-	if (ftdm_test_flag(ftdmchan, FTDM_CHANNEL_STATE_CHANGE)) {
-		ftdm_log_chan_ex(ftdmchan, file, func, line, FTDM_LOG_LEVEL_ERROR, "Ignored state change request from %s to %s, the previous state change has not been processed yet\n",
-				ftdm_channel_state2str(ftdmchan->state), ftdm_channel_state2str(state));
+	if (ftdmchan->state_status != FTDM_STATE_STATUS_COMPLETED) {
+		ftdm_log_chan_ex(ftdmchan, file, func, line, FTDM_LOG_LEVEL_ERROR, 
+		"Ignored state change request from %s to %s, the previous state change has not been processed yet (status = %s)\n",
+		ftdm_channel_state2str(ftdmchan->state), ftdm_channel_state2str(state),
+		ftdm_state_status2str(ftdmchan->state_status));
 		return FTDM_FAIL;
 	}
 
@@ -422,9 +441,10 @@ FT_DECLARE(ftdm_status_t) ftdm_channel_advance_states(ftdm_channel_t *fchan, ftd
 	ftdm_channel_lock(fchan);
 	while (fchan->state_status == FTDM_STATE_STATUS_NEW) {
 		state = fchan->state;
+		ftdm_log_chan(fchan, FTDM_LOG_DEBUG, "Executing state processor for %s\n", ftdm_channel_state2str(fchan->state));
 		state_processor(fchan);
-		if (state == fchan->state) {
-			/* if the state did not change, the state status must go to PROCESSED
+		if (state == fchan->state && fchan->state_status == FTDM_STATE_STATUS_NEW) {
+			/* if the state did not change and is still NEW, the state status must go to PROCESSED
 			 * otherwise we don't touch it since is a new state and the old state was
 			 * already completed implicitly by the state_processor() function via some internal
 			 * call to ftdm_set_state() */

libs/freetdm/src/include/freetdm.h

@@ -777,11 +777,17 @@ FT_DECLARE(ftdm_status_t) _ftdm_channel_call_answer(const char *file, const char
 FT_DECLARE(ftdm_status_t) _ftdm_channel_call_place(const char *file, const char *func, int line, ftdm_channel_t *ftdmchan);
 
 /*! \brief Indicate a new condition in an incoming call 
+ *
  *  \note Every indication request will result in FTDM_SIGEVENT_INDICATION_COMPLETED event being delivered with
- *        the proper status that will inform you if the request was successful or not.
- *        Be aware there is no guarantee of whether the event will arrive after or before your execution thread returns
- *        from ftdm_channel_call_indicate. This means you could get FTDM_SIGEVENT_INDICATION_COMPLETED even before
- *        your execution thread returns from the ftdm_channel_call_indicate() API
+ *        the proper status that will inform you if the request was successful or not. The exception is if this
+ *        function returns something different to FTDM_SUCCESS, in which case the request failed right away and no
+ *        further FTDM_SIGEVENT_INDICATION_COMPLETED will be delivered
+ *        Be aware there is no guarantee of whether the completion event will arrive after or before your execution 
+ *        thread returns from ftdm_channel_call_indicate. This means you could get FTDM_SIGEVENT_INDICATION_COMPLETED 
+ *        even before your execution thread returns from the ftdm_channel_call_indicate() API
+ *
+ * \note  You cannot send more than one indication at the time. You must wait for the completed event before 
+ *        calling this function again (unless the return code was different than FTDM_SUCCESS)
  */
 #define ftdm_channel_call_indicate(ftdmchan, indication) _ftdm_channel_call_indicate(__FILE__, __FUNCTION__, __LINE__, (ftdmchan), (indication))
 

libs/freetdm/src/include/ftdm_declare.h

@@ -192,6 +192,7 @@ typedef enum {
 
 	FTDM_EINVAL, /*!< Invalid argument */
 	FTDM_ECANCELED, /*!< Operation cancelled */
+	FTDM_EBUSY, /*!< Device busy */
 } ftdm_status_t;
 
 /*! \brief FreeTDM bool type. */

libs/freetdm/src/include/private/ftdm_core.h

@@ -583,7 +583,7 @@ FT_DECLARE(int) ftdm_vasprintf(char **ret, const char *fmt, va_list ap);
 
 FT_DECLARE(ftdm_status_t) ftdm_span_close_all(void);
 FT_DECLARE(ftdm_status_t) ftdm_channel_open_chan(ftdm_channel_t *ftdmchan);
-FT_DECLARE(void) ftdm_ack_indication(const ftdm_channel_t *ftdmchan, ftdm_channel_indication_t indication, ftdm_status_t status);
+FT_DECLARE(void) ftdm_ack_indication(ftdm_channel_t *ftdmchan, ftdm_channel_indication_t indication, ftdm_status_t status);
 
 /*! 
  * \brief Retrieves an event from the span

libs/freetdm/src/include/private/ftdm_state.h

@@ -138,8 +138,11 @@ FT_DECLARE(int) ftdm_check_state_all(ftdm_span_t *span, ftdm_channel_state_t sta
 typedef enum {
 	FTDM_STATE_STATUS_NEW,
 	FTDM_STATE_STATUS_PROCESSED,
-	FTDM_STATE_STATUS_COMPLETED
+	FTDM_STATE_STATUS_COMPLETED,
+	FTDM_STATE_STATUS_INVALID
 } ftdm_state_status_t;
+#define CHANNEL_STATE_STATUS_STRINGS "NEW", "PROCESSED", "COMPLETED", "INVALID"
+FTDM_STR2ENUM_P(ftdm_str2ftdm_state_status, ftdm_state_status2str, ftdm_state_status_t)
 
 typedef enum {
 	ZSM_NONE,