/ lots of fixes
authorBen Kramer <bkramer@voicetronix.com.au>
Wed, 18 Aug 2004 05:06:26 +0000 (05:06 +0000)
committerBen Kramer <bkramer@voicetronix.com.au>
Wed, 18 Aug 2004 05:06:26 +0000 (05:06 +0000)
git-svn-id: https://origsvn.digium.com/svn/asterisk/trunk@3621 65c4cc65-6c06-0410-ace0-fbb531ad65f3

channels/chan_vpb.c

index 01d95a8..6587571 100755 (executable)
@@ -23,7 +23,6 @@
 #include <asterisk/module.h>
 #include <asterisk/pbx.h>
 #include <asterisk/options.h>
-#include <asterisk/utils.h>
 #include <sys/socket.h>
 #include <sys/time.h>
 #include <errno.h>
 #include <vpbapi.h>
 #include <assert.h>
 
+#ifdef pthread_create
+#undef pthread_create
+#endif
+
 #define DEFAULT_GAIN 0
 #define DEFAULT_ECHO_CANCEL 1
   
@@ -117,12 +120,18 @@ static VPB_DETECT toned_ungrunt = { 2, VPB_GRUNT, 1, 2000, 1, 0, 0, -40, 0, 0, 3
 /* Use loop drop detection */
 static int UseLoopDrop=1;
 
+/* To use or not to use Native bridging */
+static int UseNativeBridge=1;
+
 #define TIMER_PERIOD_RINGBACK 2000
 #define TIMER_PERIOD_BUSY 700
          
 #define VPB_EVENTS_ALL (VPB_MRING|VPB_MDIGIT|VPB_MDTMF|VPB_MTONEDETECT|VPB_MTIMEREXP|VPB_MPLAY_UNDERFLOW \
                        |VPB_MRECORD_OVERFLOW|VPB_MSTATION_OFFHOOK|VPB_MSTATION_ONHOOK \
                        |VPB_MRING_OFF|VPB_MDROP|VPB_MSTATION_FLASH)
+#define VPB_EVENTS_NODROP (VPB_MRING|VPB_MDIGIT|VPB_MDTMF|VPB_MTONEDETECT|VPB_MTIMEREXP|VPB_MPLAY_UNDERFLOW \
+                       |VPB_MRECORD_OVERFLOW|VPB_MSTATION_OFFHOOK|VPB_MSTATION_ONHOOK \
+                       |VPB_MRING_OFF|VPB_MSTATION_FLASH)
 #define VPB_EVENTS_NODTMF (VPB_MRING|VPB_MDIGIT|VPB_MTONEDETECT|VPB_MTIMEREXP|VPB_MPLAY_UNDERFLOW \
                        |VPB_MRECORD_OVERFLOW|VPB_MSTATION_OFFHOOK|VPB_MSTATION_ONHOOK \
                        |VPB_MRING_OFF|VPB_MDROP|VPB_MSTATION_FLASH)
@@ -226,11 +235,13 @@ static struct vpb_pvt {
        vpb_bridge_t *bridge;
 
        int stopreads;                          /* Stop reading...*/
-
+       int read_state;                         /* Read state */
+       int chuck_count;                        /* a count of packets weve chucked away!*/
        pthread_t readthread;                   /* For monitoring read channel. One per owned channel. */
 
        ast_mutex_t record_lock;                /* This one prevents reentering a record_buf block */
        ast_mutex_t play_lock;                  /* This one prevents reentering a play_buf block */
+       int  play_buf_time;                     /* How long the last play_buf took */
 
        ast_mutex_t play_dtmf_lock;
        char play_dtmf[16];
@@ -251,6 +262,7 @@ static void *do_chanreads(void *pvt);
 // feedback when getting asterisk to do the bridging and when using certain gain settings.
 //#define HALF_DUPLEX_BRIDGE
 
+/* This is the Native bridge code, which Asterisk will try before using its own bridging code */
 static int vpb_bridge(struct ast_channel *c0, struct ast_channel *c1, int flags, struct ast_frame **fo, struct ast_channel **rc)
 {
        struct vpb_pvt *p0 = (struct vpb_pvt *)c0->pvt->pvt;
@@ -261,9 +273,14 @@ static int vpb_bridge(struct ast_channel *c0, struct ast_channel *c1, int flags,
        if(p0->vpb_model==vpb_model_v4pci)
                return -2;
        #endif
+       if ( UseNativeBridge != 1){
+               return -2;
+       }
 
+/*
        ast_mutex_lock(&p0->lock);
        ast_mutex_lock(&p1->lock);
+*/
 
        /* Bridge channels, check if we can.  I believe we always can, so find a slot.*/
 
@@ -363,8 +380,10 @@ static int vpb_bridge(struct ast_channel *c0, struct ast_channel *c1, int flags,
        if (option_verbose>1) 
                ast_verbose(VERBOSE_PREFIX_2 "Bridging call done with [%s, %s] => %d\n", c0->name, c1->name, res);
 
+/*
        ast_mutex_unlock(&p0->lock);
        ast_mutex_unlock(&p1->lock);
+*/
        return (res==VPB_OK)?0:-1;
 }
 
@@ -457,9 +476,9 @@ static void stoptone( int handle)
                ret = vpb_get_event_ch_async(handle,&je);
                if ((ret == VPB_OK)&&(je.type != VPB_DIALEND)){
                        if (option_verbose > 3){
-                                       ast_verbose(VERBOSE_PREFIX_4 "Stop tone collected a wrong event!!\n");
+                                       ast_verbose(VERBOSE_PREFIX_4 "Stop tone collected a wrong event!![%d]\n",je.type);
                        }
-                       vpb_put_event(&je);
+//                     vpb_put_event(&je);
                }
                vpb_sleep(10);
        }
@@ -615,8 +634,9 @@ static inline int monitor_handle_owned(struct vpb_pvt *p, VPB_EVENT *e)
                ast_verbose(VERBOSE_PREFIX_4 "%s: handle_owned: putting frame type[%d]subclass[%d], bridge=%p\n",
                        p->dev, f.frametype, f.subclass, (void *)p->bridge);
 
-       res = ast_mutex_lock(&p->lock); 
        if (option_verbose > 3) ast_verbose("%s: LOCKING in handle_owned [%d]\n", p->dev,res);
+       res = ast_mutex_lock(&p->lock); 
+       if (option_verbose > 3) ast_verbose("%s: LOCKING count[%d] owner[%d] \n", p->dev, p->lock.__m_count,p->lock.__m_owner);
        {
                if (p->bridge) { /* Check what happened, see if we need to report it. */
                        switch (f.frametype) {
@@ -871,9 +891,9 @@ static void *do_monitor(void *unused)
 
                /* flush the event from the channel event Q */
                vpb_get_event_ch_async(e.handle,&je);
-               if (option_verbose > 3){
+               if (option_verbose > 4){
                        vpb_translate_event(&je, str);
-                       ast_verbose( VERBOSE_PREFIX_4 "%s: Flushing event [%d]=>%s\n",p->dev,je.type,str);
+                       ast_verbose("%s: Flushing event [%d]=>%s\n",p->dev,je.type,str);
                }
 
                /* Check for ownership and locks */
@@ -943,7 +963,7 @@ static int restart_monitor(void)
                        vpb_put_event(&e);
                } else {
                        /* Start a new monitor */
-                       int pid = ast_pthread_create(&monitor_thread, NULL, do_monitor, NULL); 
+                       int pid = pthread_create(&monitor_thread, NULL, do_monitor, NULL); 
                        if (option_verbose > 3)
                                ast_verbose(VERBOSE_PREFIX_4 "Created new monitor thread %d\n",pid);
                        if (pid < 0) {
@@ -1025,6 +1045,7 @@ struct vpb_pvt *mkif(int board, int channel, int mode, float txgain, float rxgai
 
        tmp->group = group;
 
+
        strncpy(tmp->language, language, sizeof(tmp->language) - 1);
        strncpy(tmp->context, context, sizeof(tmp->context) - 1);
 
@@ -1068,6 +1089,9 @@ struct vpb_pvt *mkif(int board, int channel, int mode, float txgain, float rxgai
        ast_mutex_init(&tmp->record_lock);
        ast_mutex_init(&tmp->play_lock);
        ast_mutex_init(&tmp->play_dtmf_lock);
+
+       /* set default read state */
+       tmp->read_state = 0;
        
        tmp->golock=0;
 
@@ -1078,7 +1102,7 @@ struct vpb_pvt *mkif(int board, int channel, int mode, float txgain, float rxgai
        vpb_timer_open(&tmp->ringback_timer, tmp->handle, tmp->ringback_timer_id, TIMER_PERIOD_RINGBACK);
              
        if (mode == MODE_FXO){
-               vpb_set_event_mask(tmp->handle, VPB_EVENTS_NODTMF );
+               vpb_set_event_mask(tmp->handle, VPB_EVENTS_ALL );
        }
        else {
                vpb_set_event_mask(tmp->handle, VPB_EVENTS_STAT );
@@ -1106,29 +1130,37 @@ static int vpb_indicate(struct ast_channel *ast, int condition)
        int tmp = 0;
 
        if (option_verbose > 3)
-               ast_verbose(VERBOSE_PREFIX_4 "%s: vpb indicate [%d] state[%d]\n", p->dev, condition,ast->_state);
+               ast_verbose(VERBOSE_PREFIX_4 "%s: vpb_indicate [%d] state[%d]\n", p->dev, condition,ast->_state);
+/*
        if (ast->_state != AST_STATE_UP) {
+               ast_verbose(VERBOSE_PREFIX_4 "%s: vpb_indicate Not in AST_STATE_UP\n", p->dev, condition,ast->_state);
                return res;
        }
+*/
 
        if (option_verbose > 3) ast_verbose("%s: LOCKING in indicate \n", p->dev);
+       if (option_verbose > 3) ast_verbose("%s: LOCKING count[%d] owner[%d] \n", p->dev, p->lock.__m_count,p->lock.__m_owner);
        ast_mutex_lock(&p->lock);
        switch(condition) {
                case AST_CONTROL_BUSY:
                case AST_CONTROL_CONGESTION:
-                       playtone(p->handle, &Busytone);
-                       p->state = VPB_STATE_PLAYBUSY;
-                       vpb_timer_stop(p->busy_timer); 
-                       vpb_timer_start(p->busy_timer); 
+                       if (ast->_state == AST_STATE_UP) {
+                               playtone(p->handle, &Busytone);
+                               p->state = VPB_STATE_PLAYBUSY;
+                               vpb_timer_stop(p->busy_timer); 
+                               vpb_timer_start(p->busy_timer); 
+                       }
                        break;
                case AST_CONTROL_RINGING:
-                       playtone(p->handle, &Ringbacktone);
-                       p->state = VPB_STATE_PLAYRING;
-                       if (option_verbose > 3)
-                               ast_verbose(VERBOSE_PREFIX_4 "%s: vpb indicate: setting ringback timer [%d]\n", p->dev,p->ringback_timer_id);
-                       
-                       vpb_timer_stop(p->ringback_timer);
-                       vpb_timer_start(p->ringback_timer);
+                       if (ast->_state == AST_STATE_UP) {
+                               playtone(p->handle, &Ringbacktone);
+                               p->state = VPB_STATE_PLAYRING;
+                               if (option_verbose > 3)
+                                       ast_verbose(VERBOSE_PREFIX_4 "%s: vpb indicate: setting ringback timer [%d]\n", p->dev,p->ringback_timer_id);
+                               
+                               vpb_timer_stop(p->ringback_timer);
+                               vpb_timer_start(p->ringback_timer);
+                       }
                        break;      
                case AST_CONTROL_ANSWER:
                case -1: /* -1 means stop playing? */
@@ -1137,10 +1169,12 @@ static int vpb_indicate(struct ast_channel *ast, int condition)
                        stoptone(p->handle);
                        break;
                case AST_CONTROL_HANGUP:
-                       playtone(p->handle, &Busytone);
-                       p->state = VPB_STATE_PLAYBUSY;
-                       vpb_timer_stop(p->busy_timer);
-                       vpb_timer_start(p->busy_timer);
+                       if (ast->_state == AST_STATE_UP) {
+                               playtone(p->handle, &Busytone);
+                               p->state = VPB_STATE_PLAYBUSY;
+                               vpb_timer_stop(p->busy_timer);
+                               vpb_timer_start(p->busy_timer);
+                       }
                        break;
 
                default:
@@ -1158,6 +1192,7 @@ static int vpb_fixup(struct ast_channel *oldchan, struct ast_channel *newchan)
        int res = 0;
 
        if (option_verbose > 3) ast_verbose("%s: LOCKING in fixup \n", p->dev);
+       if (option_verbose > 3) ast_verbose("%s: LOCKING count[%d] owner[%d] \n", p->dev, p->lock.__m_count,p->lock.__m_owner);
        ast_mutex_lock(&p->lock);
        ast_log(LOG_DEBUG, "New owner for channel %s is %s\n", p->dev, newchan->name);
 
@@ -1180,6 +1215,7 @@ static int vpb_digit(struct ast_channel *ast, char digit)
        int res = 0;
 
        if (option_verbose > 3) ast_verbose("%s: LOCKING in digit \n", p->dev);
+       if (option_verbose > 3) ast_verbose("%s: LOCKING count[%d] owner[%d] \n", p->dev, p->lock.__m_count,p->lock.__m_owner);
        ast_mutex_lock(&p->lock);
 
 
@@ -1198,6 +1234,7 @@ static int vpb_digit(struct ast_channel *ast, char digit)
        return 0;
 }
 
+/* Places a call out of a VPB channel */
 static int vpb_call(struct ast_channel *ast, char *dest, int timeout)
 {
        struct vpb_pvt *p = (struct vpb_pvt *)ast->pvt->pvt;
@@ -1207,6 +1244,7 @@ static int vpb_call(struct ast_channel *ast, char *dest, int timeout)
        int tmp = 0;
 
        if (option_verbose > 3) ast_verbose("%s: LOCKING in call \n", p->dev);
+       if (option_verbose > 3) ast_verbose("%s: LOCKING count[%d] owner[%d] \n", p->dev, p->lock.__m_count,p->lock.__m_owner);
        ast_mutex_lock(&p->lock);
 
        if (s)
@@ -1263,13 +1301,22 @@ static int vpb_call(struct ast_channel *ast, char *dest, int timeout)
                                        ast->name, call.tone_map[j].tone_id, call.tone_map[j].call_id); 
                }
 
+               if (option_verbose > 4)
+                               ast_verbose("%s: Disabling Loop Drop detection\n",p->dev);
+               vpb_disable_event(p->handle, VPB_MDROP);
                vpb_sethook_sync(p->handle,VPB_OFFHOOK);
                p->state=VPB_STATE_OFFHOOK;
 
                #ifndef DIAL_WITH_CALL_PROGRESS
                vpb_sleep(300);
+               if (option_verbose > 4)
+                               ast_verbose("%s: Disabling Loop Drop detection\n",p->dev);
+               vpb_enable_event(p->handle, VPB_MDROP);
                res = vpb_dial_async(p->handle, dialstring);
                #else
+               if (option_verbose > 4)
+                               ast_verbose("%s: Disabling Loop Drop detection\n",p->dev);
+               vpb_enable_event(p->handle, VPB_MDROP);
                res = vpb_call_async(p->handle, dialstring);
                #endif
 
@@ -1288,7 +1335,7 @@ static int vpb_call(struct ast_channel *ast, char *dest, int timeout)
        }
 
        if (!p->readthread){
-               ast_pthread_create(&p->readthread, NULL, do_chanreads, (void *)p);
+               pthread_create(&p->readthread, NULL, do_chanreads, (void *)p);
        }
 
        tmp = ast_mutex_unlock(&p->lock);
@@ -1303,8 +1350,12 @@ static int vpb_hangup(struct ast_channel *ast)
        char str[VPB_MAX_STR];
        int res =0 ;
 
+/*
        if (option_verbose > 3) ast_verbose("%s: LOCKING in hangup \n", p->dev);
+       if (option_verbose > 3) ast_verbose("%s: LOCKING in hangup count[%d] owner[%d] \n", p->dev, p->lock.__m_count,p->lock.__m_owner);
+       if (option_verbose > 3) ast_verbose("%s: LOCKING pthread_self(%d)\n", p->dev,pthread_self());
        ast_mutex_lock(&p->lock);
+*/
        if (option_verbose > 1) 
                ast_verbose(VERBOSE_PREFIX_2 "%s: Hangup requested\n", ast->name);
 
@@ -1315,9 +1366,6 @@ static int vpb_hangup(struct ast_channel *ast)
                return 0;
        }
 
-       if(option_verbose>3) 
-               ast_verbose( VERBOSE_PREFIX_4 "%s: Setting state down\n",ast->name);
-       ast_setstate(ast,AST_STATE_DOWN);
 
 
        /* Stop record */
@@ -1338,6 +1386,16 @@ static int vpb_hangup(struct ast_channel *ast)
                } ast_mutex_unlock(&p->play_lock);
        }
 
+       if(option_verbose>3) 
+               ast_verbose( VERBOSE_PREFIX_4 "%s: Setting state down\n",ast->name);
+       ast_setstate(ast,AST_STATE_DOWN);
+
+
+       if (option_verbose > 3) ast_verbose("%s: LOCKING in hangup \n", p->dev);
+       if (option_verbose > 3) ast_verbose("%s: LOCKING in hangup count[%d] owner[%d] \n", p->dev, p->lock.__m_count,p->lock.__m_owner);
+       if (option_verbose > 3) ast_verbose("%s: LOCKING pthread_self(%d)\n", p->dev,pthread_self());
+       ast_mutex_lock(&p->lock);
+
        if (p->mode != MODE_FXO) { 
                /* station port. */
                vpb_ring_station_async(p->handle, VPB_RING_STATION_OFF,0);      
@@ -1384,8 +1442,10 @@ static int vpb_hangup(struct ast_channel *ast)
                ast_verbose(VERBOSE_PREFIX_2 "%s: Hangup complete\n", ast->name);
 
        restart_monitor();
+       if (option_verbose > 3) ast_verbose("%s: LOCKING in hangup count[%d] owner[%d] \n", p->dev, p->lock.__m_count,p->lock.__m_owner);
        res = ast_mutex_unlock(&p->lock);
        if (option_verbose > 3) ast_verbose("%s: unLOCKING in hangup [%d]\n", p->dev,res);
+       if (option_verbose > 3) ast_verbose("%s: LOCKING in hangup count[%d] owner[%d] \n", p->dev, p->lock.__m_count,p->lock.__m_owner);
        return 0;
 }
 
@@ -1396,23 +1456,29 @@ static int vpb_answer(struct ast_channel *ast)
        int ret;
        int res = 0;
        if (option_verbose > 3) ast_verbose("%s: LOCKING in answer \n", p->dev);
+       if (option_verbose > 3) ast_verbose("%s: LOCKING count[%d] owner[%d] \n", p->dev, p->lock.__m_count,p->lock.__m_owner);
        ast_mutex_lock(&p->lock);
 
        if (option_verbose > 3)
                        ast_verbose(VERBOSE_PREFIX_4 "%s: Answering channel\n",p->dev);
 
+       if (option_verbose > 4)
+                       ast_verbose("%s: Disabling Loop Drop detection\n",p->dev);
+       vpb_disable_event(p->handle, VPB_MDROP);
+
        if (ast->_state != AST_STATE_UP) {
                if (p->mode == MODE_FXO){
                        vpb_sethook_sync(p->handle, VPB_OFFHOOK);
                        p->state=VPB_STATE_OFFHOOK;
-                       vpb_sleep(500);
+/*                     vpb_sleep(500);
                        ret = vpb_get_event_ch_async(p->handle,&je);
-                       if ((ret == VPB_OK)&&(je.type != VPB_DROP)){
+                       if ((ret == VPB_OK)&&((je.type != VPB_DROP)&&(je.type != VPB_RING))){
                                if (option_verbose > 3){
                                                ast_verbose(VERBOSE_PREFIX_4 "%s: Answer collected a wrong event!!\n",p->dev);
                                }
                                vpb_put_event(&je);
                        }
+*/
                }
                ast_setstate(ast, AST_STATE_UP);
 
@@ -1424,7 +1490,7 @@ static int vpb_answer(struct ast_channel *ast)
                if( !p->readthread ){
        //              res = ast_mutex_unlock(&p->lock);
        //              ast_verbose("%s: unLOCKING in answer [%d]\n", p->dev,res);
-                       ast_pthread_create(&p->readthread, NULL, do_chanreads, (void *)p);
+                       pthread_create(&p->readthread, NULL, do_chanreads, (void *)p);
                } else {
                        if(option_verbose>3) 
                                ast_verbose(VERBOSE_PREFIX_4 "%s: Record thread already running!!\n",p->dev);
@@ -1436,6 +1502,10 @@ static int vpb_answer(struct ast_channel *ast)
        //      res = ast_mutex_unlock(&p->lock);
        //      ast_verbose("%s: unLOCKING in answer [%d]\n", p->dev,res);
        }
+       vpb_sleep(500);
+       if (option_verbose > 4)
+                       ast_verbose("%s: Re-enabling Loop Drop detection\n",p->dev);
+       vpb_enable_event(p->handle,VPB_MDROP);
        res = ast_mutex_unlock(&p->lock);
        if(option_verbose>3) ast_verbose("%s: unLOCKING in answer [%d]\n", p->dev,res);
        return 0;
@@ -1447,7 +1517,8 @@ static struct ast_frame  *vpb_read(struct ast_channel *ast)
        static struct ast_frame f = {AST_FRAME_NULL}; 
 
        f.src = type;
-       ast_log(LOG_NOTICE, "vpb_read should never be called (chan=%s)!\n", p->dev);
+       ast_log(LOG_NOTICE, "%s: vpb_read: should never be called!\n", p->dev);
+       ast_verbose("%s: vpb_read: should never be called!\n", p->dev);
 
        return &f;
 }
@@ -1468,6 +1539,22 @@ static inline int ast2vpbformat(int ast_format)
        }
 }
 
+static inline char * ast2vpbformatname(int ast_format)
+{
+       switch(ast_format) {
+               case AST_FORMAT_ALAW:
+                       return "AST_FORMAT_ALAW:VPB_ALAW";
+               case AST_FORMAT_SLINEAR:
+                       return "AST_FORMAT_SLINEAR:VPB_LINEAR";
+               case AST_FORMAT_ULAW:
+                       return "AST_FORMAT_ULAW:VPB_MULAW";
+               case AST_FORMAT_ADPCM:
+                       return "AST_FORMAT_ADPCM:VPB_OKIADPCM";
+               default:
+                       return "UNKN:UNKN";
+       }
+}
+
 static inline int astformatbits(int ast_format)
 {
        switch(ast_format) {
@@ -1498,60 +1585,93 @@ int gain_vector(float g, short *v, int n)
        return(i);
 }
 
+/* Writes a frame of voice data to a VPB channel */
 static int vpb_write(struct ast_channel *ast, struct ast_frame *frame)
 {
        struct vpb_pvt *p = (struct vpb_pvt *)ast->pvt->pvt; 
        int res = 0, fmt = 0;
+       struct timeval play_buf_time_start,play_buf_time_finish;
 //     ast_mutex_lock(&p->lock);
        if(option_verbose>5) 
-               ast_verbose( VERBOSE_PREFIX_4 "%s: Writing to channel\n", p->dev);
+               ast_verbose("%s: vpb_write: Writing to channel\n", p->dev);
 
        if (frame->frametype != AST_FRAME_VOICE) {
                if(option_verbose>3) 
-                       ast_verbose( VERBOSE_PREFIX_4 "%s: Don't know how to handle from type %d\n", ast->name, frame->frametype);
+                       ast_verbose("%s: vpb_write: Don't know how to handle from type %d\n", ast->name, frame->frametype);
 //             ast_mutex_unlock(&p->lock);
                return 0;
        } else if (ast->_state != AST_STATE_UP) {
                if(option_verbose>3) 
-                       ast_verbose( VERBOSE_PREFIX_4 "%s: Attempt to Write frame type[%d]subclass[%d] on not up chan\n",ast->name, frame->frametype, frame->subclass);
+                       ast_verbose("%s: vpb_write: Attempt to Write frame type[%d]subclass[%d] on not up chan\n",ast->name, frame->frametype, frame->subclass);
                p->lastoutput = -1;
 //             ast_mutex_unlock(&p->lock);
                return 0;
        }
+       ast_log(LOG_DEBUG, "%s: vpb_write: Checked frame type..\n", p->dev);
 
        fmt = ast2vpbformat(frame->subclass);
        if (fmt < 0) {
-               ast_log(LOG_WARNING, "%s: vpb_write Cannot handle frames of %d format!\n",ast->name, frame->subclass);
+               ast_log(LOG_WARNING, "%s: vpb_write: Cannot handle frames of %d format!\n",ast->name, frame->subclass);
                return -1;
        }
+       ast_log(LOG_DEBUG, "%s: vpb_write: Checked frame format..\n", p->dev);
 
        ast_mutex_lock(&p->play_lock);
 
+       ast_log(LOG_DEBUG, "%s: vpb_write: Got play lock..\n", p->dev);
+
+       /* Check if we have set up the play_buf */
        if (p->lastoutput == -1) {
                vpb_play_buf_start(p->handle, fmt);
-               if(option_verbose>1) 
-                       ast_verbose( VERBOSE_PREFIX_2 "%s: Starting play mode (codec=%d)\n",p->dev,fmt);
+               if(option_verbose>1) {
+                       ast_verbose("%s: vpb_write: Starting play mode (codec=%d)[%s]\n",p->dev,fmt,ast2vpbformatname(frame->subclass));
+               }
        } else if (p->lastoutput != fmt) {
                vpb_play_buf_finish(p->handle);
                vpb_play_buf_start(p->handle, fmt);
                if(option_verbose>1) 
-                       ast_verbose( VERBOSE_PREFIX_2 "%s: Changed play format (%d=>%d)\n",p->dev,p->lastoutput,fmt);
+                       ast_verbose("%s: vpb_write: Changed play format (%d=>%d)\n",p->dev,p->lastoutput,fmt);
        }
-
        p->lastoutput = fmt;
 
+
+
        // Apply extra gain !
        if( p->txswgain > MAX_VPB_GAIN )
                gain_vector(p->txswgain - MAX_VPB_GAIN , (short*)frame->data, frame->datalen/sizeof(short));
 
+       ast_log(LOG_DEBUG, "%s: vpb_write: Applied gain..\n", p->dev);
+
+//     gettimeofday(&tv, NULL);
+//     return ((double)tv.tv_sec*1000)+((double)tv.tv_usec/1000);
+
+       if ((p->read_state == 1)&&(p->play_buf_time<5)){
+       gettimeofday(&play_buf_time_start,NULL);
        res = vpb_play_buf_sync(p->handle, (char*)frame->data, frame->datalen);
        if( (res == VPB_OK) && (option_verbose > 5) ) {
                short * data = (short*)frame->data;
-               ast_verbose("%s: Write chan (codec=%d) %d %d\n", p->dev, fmt, data[0],data[1]);
+               ast_verbose("%s: vpb_write: Wrote chan (codec=%d) %d %d\n", p->dev, fmt, data[0],data[1]);
+       }
+       gettimeofday(&play_buf_time_finish,NULL);
+       if (play_buf_time_finish.tv_sec == play_buf_time_start.tv_sec){
+               p->play_buf_time=(int)((play_buf_time_finish.tv_usec-play_buf_time_start.tv_usec)/1000);
+               ast_log(LOG_DEBUG, "%s: vpb_write: Timing start(%d) finish(%d)\n", p->dev,play_buf_time_start.tv_usec,play_buf_time_finish.tv_usec);
+       }
+       else {
+               p->play_buf_time=(int)((play_buf_time_finish.tv_sec - play_buf_time_start.tv_sec)*100)+(int)((play_buf_time_finish.tv_usec-play_buf_time_start.tv_usec)/1000);
+       }
+       ast_log(LOG_DEBUG, "%s: vpb_write: Wrote data [%d](%d=>%s) to play_buf in [%d]ms..\n", p->dev,frame->datalen,fmt,ast2vpbformatname(frame->subclass),p->play_buf_time);
+       }
+       else {
+               p->chuck_count++;
+               ast_log(LOG_DEBUG, "%s: vpb_write: Tossed data away, tooooo much data!![%d]\n", p->dev,p->chuck_count);
+               p->play_buf_time=0;
        }
 
        ast_mutex_unlock(&p->play_lock);
 //     ast_mutex_unlock(&p->lock);
+       if(option_verbose>5) 
+               ast_verbose("%s: vpb_write: Done Writing to channel\n", p->dev);
        return 0;
 }
 
@@ -1562,7 +1682,7 @@ static void *do_chanreads(void *pvt)
        struct ast_frame *fr = &p->fr;
        char *readbuf = ((char *)p->buf) + AST_FRIENDLY_OFFSET;
        int bridgerec = 0;
-       int afmt, readlen, res, fmt;
+       int afmt, readlen, res, fmt, trycnt=0;
        int ignore_dtmf;
        char * getdtmf_var = NULL;
 
@@ -1575,55 +1695,46 @@ static void *do_chanreads(void *pvt)
        fr->offset = AST_FRIENDLY_OFFSET;
        memset(p->buf, 0, sizeof p->buf);
 
-       if (option_verbose > 4) {
+       if (option_verbose > 2) {
                ast_verbose("%s: chanreads: starting thread\n", p->dev);
        }  
        ast_mutex_lock(&p->record_lock);
 
        p->stopreads = 0; 
+       p->read_state = 1;
        while (!p->stopreads && p->owner) {
 
                if (option_verbose > 4)
                        ast_verbose("%s: chanreads: Starting cycle ...\n", p->dev);
-               res = ast_mutex_trylock(&p->lock);
-               if (res !=0){
-                       if (res == EINVAL )
-                               if (option_verbose > 4) ast_verbose("%s: chanreads: try lock gave me EINVAL[%d]\n", p->dev,res);
-                       else if (res == EBUSY )
-                               if (option_verbose > 4) ast_verbose("%s: chanreads: try lock gave me EBUSY[%d]\n", p->dev,res);
-                       res = ast_mutex_unlock(&p->lock);
-                       if (res == EINVAL )
-                               if (option_verbose > 4) ast_verbose("%s: chanreads: Releasing it gave me EINVAL[%d]\n", p->dev,res);
-                       else if (res == EPERM )
-                               if (option_verbose > 4) ast_verbose("%s: chanreads: Releasing it gave me EPERM[%d]\n", p->dev,res);
-                       res = ast_mutex_trylock(&p->lock);
-                       if (res == EINVAL )
-                               if (option_verbose > 4) ast_verbose("%s: chanreads: trying again it gave me EINVAL[%d]\n", p->dev,res);
-                       else if (res == EBUSY )
-                               if (option_verbose > 4) ast_verbose("%s: chanreads: trying again it gave me EBUSY[%d]\n", p->dev,res);
-               }
-               if (res==0)  {
-                       if (option_verbose > 4)
-                               ast_verbose("%s: chanreads: Checking bridge \n", p->dev);
-                       if (p->bridge) {
-                               if (p->bridge->c0 == p->owner && (p->bridge->flags & AST_BRIDGE_REC_CHANNEL_0))
-                                       bridgerec = 1;
-                               else if (p->bridge->c1 == p->owner && (p->bridge->flags & AST_BRIDGE_REC_CHANNEL_1))
-                                       bridgerec = 1;
-                               else 
-                                       bridgerec = 0;
-                       } else {
+               if (option_verbose > 4)
+                       ast_verbose("%s: chanreads: Checking bridge \n", p->dev);
+               if (p->bridge) {
+                       if (p->bridge->c0 == p->owner && (p->bridge->flags & AST_BRIDGE_REC_CHANNEL_0))
                                bridgerec = 1;
-                       }
-                       ast_mutex_unlock(&p->lock);
+                       else if (p->bridge->c1 == p->owner && (p->bridge->flags & AST_BRIDGE_REC_CHANNEL_1))
+                               bridgerec = 1;
+                       else 
+                               bridgerec = 0;
                } else {
                        if (option_verbose > 4)
-                               ast_verbose("%s: chanreads: Couldnt get channel lock to check bridges!!\n", p->dev);
+                               ast_verbose("%s: chanreads: No native bridge.\n", p->dev);
+                       if (p->owner->bridge){
+                               if (option_verbose > 4){
+                                       ast_verbose("%s: chanreads: Got Asterisk bridge with [%s].\n", p->dev,p->owner->bridge->name);
+                               }
+                               bridgerec = 1;
+                       }
+                       else {
+                               bridgerec = 0;
+                       }
                }
 
                if ( (p->owner->_state != AST_STATE_UP) || !bridgerec) {
                        if (option_verbose > 4) {
-                               ast_verbose("%s: chanreads: owner not up[%d] or no bridgerec[%d]\n", p->dev,p->owner->_state,bridgerec);
+                               if (p->owner->_state != AST_STATE_UP)
+                                       ast_verbose("%s: chanreads: Im not up[%d]\n", p->dev,p->owner->_state);
+                               else
+                                       ast_verbose("%s: chanreads: No bridgerec[%d]\n", p->dev,bridgerec);
                        }  
                        vpb_sleep(10);
                        continue;
@@ -1669,7 +1780,15 @@ static void *do_chanreads(void *pvt)
                }
                ast_mutex_unlock(&p->play_dtmf_lock);
 
-               afmt = (p->owner) ? p->owner->pvt->rawreadformat : AST_FORMAT_SLINEAR;
+//             afmt = (p->owner) ? p->owner->pvt->rawreadformat : AST_FORMAT_SLINEAR;
+               if (p->owner){
+                       afmt = p->owner->pvt->rawreadformat;
+                       ast_log(LOG_DEBUG,"%s: Record using owner format [%s]\n", p->dev, ast2vpbformatname(afmt));
+               }
+               else {
+                       afmt = AST_FORMAT_SLINEAR;
+                       ast_log(LOG_DEBUG,"%s: Record using default format [%s]\n", p->dev, ast2vpbformatname(afmt));
+               }
                fmt = ast2vpbformat(afmt);
                if (fmt < 0) {
                        ast_log(LOG_WARNING,"%s: Record failure (unsupported format %d)\n", p->dev, afmt);
@@ -1681,7 +1800,7 @@ static void *do_chanreads(void *pvt)
                        vpb_record_buf_start(p->handle, fmt);
                        vpb_reset_record_fifo_alarm(p->handle);
                        if(option_verbose>1) 
-                               ast_verbose( VERBOSE_PREFIX_2 "%s: Starting record mode (codec=%d)\n",p->dev,fmt);
+                               ast_verbose( VERBOSE_PREFIX_2 "%s: Starting record mode (codec=%d)[%s]\n",p->dev,fmt,ast2vpbformatname(afmt));
                } else if (p->lastinput != fmt) {
                        vpb_record_buf_finish(p->handle);
                        vpb_record_buf_start(p->handle, fmt);
@@ -1713,10 +1832,24 @@ static void *do_chanreads(void *pvt)
                        // (ast_hangup() immediately gets lock)
                        if (p->owner && !p->stopreads ) {
                                if (option_verbose > 5) {
-                                       ast_verbose("%s: chanreads: queueing buffer on frame (state[%d])\n", p->dev,p->owner->_state);
+                                       ast_verbose("%s: chanreads: queueing buffer on read frame q (state[%d])\n", p->dev,p->owner->_state);
                                }  
+                               do {
+                                       res = ast_mutex_trylock(&p->owner->lock);
+                                       trycnt++;
+                               } while((res !=0)&&(trycnt<300));
+                               if (res==0)  {
+                                       ast_queue_frame(p->owner, fr);
+                                       ast_mutex_unlock(&p->owner->lock);
+                               } else {
+                                       if (option_verbose > 4) 
+                                               ast_verbose("%s: chanreads: Couldnt get lock after %d tries!\n", p->dev,trycnt);
+                               }
+                               trycnt=0;
                                
+/*
                                res = ast_mutex_trylock(&p->owner->lock);
+//                             res=0;
                                if (res==0)  {
                                        ast_queue_frame(p->owner, fr);
                                        ast_mutex_unlock(&p->owner->lock);
@@ -1725,17 +1858,9 @@ static void *do_chanreads(void *pvt)
                                                if (option_verbose > 4) ast_verbose("%s: chanreads: try owner->lock gave me EINVAL[%d]\n", p->dev,res);
                                        else if (res == EBUSY )
                                                if (option_verbose > 4) ast_verbose("%s: chanreads: try owner->lock gave me EBUSY[%d]\n", p->dev,res);
-                                       res = ast_mutex_unlock(&p->lock);
-                                       if (res == EINVAL )
-                                               if (option_verbose > 4) ast_verbose("%s: chanreads: Releasing pvt->lock it gave me EINVAL[%d]\n", p->dev,res);
-                                       else if (res == EPERM )
-                                               if (option_verbose > 4) ast_verbose("%s: chanreads: Releasing pvt->lock it gave me EPERM[%d]\n", p->dev,res);
-                                       res = ast_mutex_trylock(&p->lock);
-                                       if (res == EINVAL )
-                                               if (option_verbose > 4) ast_verbose("%s: chanreads: trying pvt->lock again it gave me EINVAL[%d]\n", p->dev,res);
-                                       else if (res == EBUSY )
-                                               if (option_verbose > 4) ast_verbose("%s: chanreads: trying pvt->lock again it gave me EBUSY[%d]\n", p->dev,res);
+                                       while(res !=0){
                                        res = ast_mutex_trylock(&p->owner->lock);
+                                       }
                                        if (res==0)  {
                                                ast_queue_frame(p->owner, fr);
                                                ast_mutex_unlock(&p->owner->lock);
@@ -1745,11 +1870,11 @@ static void *do_chanreads(void *pvt)
                                                        if (option_verbose > 4) ast_verbose("%s: chanreads: try owner->lock gave me EINVAL[%d]\n", p->dev,res);
                                                else if (res == EBUSY )
                                                        if (option_verbose > 4) ast_verbose("%s: chanreads: try owner->lock gave me EBUSY[%d]\n", p->dev,res);
-                                               if (option_verbose > 3) 
-                                                       if (option_verbose > 4) ast_verbose("%s: chanreads: Couldnt get lock on owner channel to send frame!\n", p->dev);
+                                               if (option_verbose > 4) ast_verbose("%s: chanreads: Couldnt get lock on owner[%s][%d][%d] channel to send frame!\n", p->dev,p->owner->name,(int)p->owner->lock.__m_owner,(int)p->owner->lock.__m_count);
                                                //assert(p->dev!=p->dev);
                                        }
                                }
+*/
                                if (option_verbose > 6) {
                                        short * data = (short*)readbuf;
                                        ast_verbose("%s: Read channel (codec=%d) %d %d\n", p->dev, fmt, data[0], data[1] );
@@ -1768,9 +1893,11 @@ static void *do_chanreads(void *pvt)
                if (option_verbose > 4)
                        ast_verbose("%s: chanreads: Finished cycle...\n", p->dev);
        }
+       p->read_state=0;
 
        /* When stopreads seen, go away! */
        vpb_record_buf_finish(p->handle);
+       p->read_state=0;
        ast_mutex_unlock(&p->record_lock);
 
        if (option_verbose > 1)
@@ -1779,18 +1906,20 @@ static void *do_chanreads(void *pvt)
        return NULL;
 }
 
-static struct ast_channel *vpb_new(struct vpb_pvt *i, int state, char *context)
+static struct ast_channel *vpb_new(struct vpb_pvt *me, int state, char *context)
 {
        struct ast_channel *tmp; 
 
-       if (i->owner) {
-           ast_log(LOG_WARNING, "Called vpb_new on owned channel (%s) ?!\n", i->dev);
+       if (me->owner) {
+           ast_log(LOG_WARNING, "Called vpb_new on owned channel (%s) ?!\n", me->dev);
            return NULL;
        }
+       if (option_verbose > 3)
+               ast_verbose("%s: New call for context [%s]\n",me->dev,context);
            
        tmp = ast_channel_alloc(1);
        if (tmp) {
-               strncpy(tmp->name, i->dev, sizeof(tmp->name) - 1);
+               strncpy(tmp->name, me->dev, sizeof(tmp->name) - 1);
                tmp->type = type;
               
                // Linear is the preferred format. Although Voicetronix supports other formats
@@ -1802,7 +1931,7 @@ static struct ast_channel *vpb_new(struct vpb_pvt *i, int state, char *context)
                ast_setstate(tmp, state);
                if (state == AST_STATE_RING)
                        tmp->rings = 1;
-               tmp->pvt->pvt = i;
+               tmp->pvt->pvt = me;
                /* set call backs */
                tmp->pvt->send_digit = vpb_digit;
                tmp->pvt->call = vpb_call;
@@ -1815,23 +1944,23 @@ static struct ast_channel *vpb_new(struct vpb_pvt *i, int state, char *context)
                tmp->pvt->fixup = vpb_fixup;
                
                strncpy(tmp->context, context, sizeof(tmp->context)-1);
-               if (strlen(i->ext))
-                       strncpy(tmp->exten, i->ext, sizeof(tmp->exten)-1);
+               if (strlen(me->ext))
+                       strncpy(tmp->exten, me->ext, sizeof(tmp->exten)-1);
                else
                        strncpy(tmp->exten, "s",  sizeof(tmp->exten) - 1);
-               if (strlen(i->language))
-                       strncpy(tmp->language, i->language, sizeof(tmp->language)-1);
+               if (strlen(me->language))
+                       strncpy(tmp->language, me->language, sizeof(tmp->language)-1);
 
-               i->owner = tmp;
+               me->owner = tmp;
      
-               i->bridge = NULL;
-               i->lastoutput = -1;
-               i->lastinput = -1;
-               i->last_ignore_dtmf = 1;
-               i->readthread = 0;
-               i->play_dtmf[0] = '\0';
+               me->bridge = NULL;
+               me->lastoutput = -1;
+               me->lastinput = -1;
+               me->last_ignore_dtmf = 1;
+               me->readthread = 0;
+               me->play_dtmf[0] = '\0';
                
-               i->lastgrunt  = get_time_in_ms(); /* Assume at least one grunt tone seen now. */
+               me->lastgrunt  = get_time_in_ms(); /* Assume at least one grunt tone seen now. */
 
                ast_mutex_lock(&usecnt_lock);
                usecnt++;
@@ -1962,6 +2091,8 @@ int load_module()
                                group = atoi(v->value);
                        } else  if (strcasecmp(v->name, "useloopdrop") == 0){
                                UseLoopDrop = atoi(v->value);
+                       } else  if (strcasecmp(v->name, "usenativebridge") == 0){
+                               UseNativeBridge = atoi(v->value);
                        } else if (strcasecmp(v->name, "channel") == 0) {
                                int channel = atoi(v->value);
                                tmp = mkif(board, channel, mode, txgain, rxgain, txswgain, rxswgain, bal1, bal2, bal3, callerid, echo_cancel,group);