[svn-commits] wedhorn: trunk r370881 - in /trunk: build_tools/ channels/

SVN commits to the Digium repositories svn-commits at lists.digium.com
Tue Aug 7 16:58:08 CDT 2012


Author: wedhorn
Date: Tue Aug  7 16:58:01 2012
New Revision: 370881

URL: http://svnview.digium.com/svn/asterisk?view=rev&rev=370881
Log:
Rewrite of skinny debugging.

Debugging messages and associated controls only compiled in if configured with --enable-dev-mode. Debug messages provide more detail (including thread id) and are grouped so the user/dev can limit the type of messages displayed. Functionally no real change to chan_skinny.

Review: https://reviewboard.asterisk.org/r/2040/

Modified:
    trunk/build_tools/cflags-devmode.xml
    trunk/channels/chan_skinny.c

Modified: trunk/build_tools/cflags-devmode.xml
URL: http://svnview.digium.com/svn/asterisk/trunk/build_tools/cflags-devmode.xml?view=diff&rev=370881&r1=370880&r2=370881
==============================================================================
--- trunk/build_tools/cflags-devmode.xml (original)
+++ trunk/build_tools/cflags-devmode.xml Tue Aug  7 16:58:01 2012
@@ -27,9 +27,6 @@
 		<member name="CHANNEL_TRACE" displayname="Enable CHANNEL(trace) function">
 			<support_level>extended</support_level>
 		</member>
-		<member name="SKINNY_DEVMODE" displayname="Enable Skinny Dev Mode">
-			<support_level>extended</support_level>
-		</member>
 		<member name="TEST_FRAMEWORK" displayname="Enable Test Framework API">
 			<support_level>extended</support_level>
 		</member>

Modified: trunk/channels/chan_skinny.c
URL: http://svnview.digium.com/svn/asterisk/trunk/channels/chan_skinny.c?view=diff&rev=370881&r1=370880&r2=370881
==============================================================================
--- trunk/channels/chan_skinny.c (original)
+++ trunk/channels/chan_skinny.c Tue Aug  7 16:58:01 2012
@@ -131,18 +131,28 @@
 	</manager>
  ***/
 
-/* Hack to allow for easy debugging in trunk.
-    This block should be removed in branches. */
-#ifndef SKINNY_DEVMODE
-#define SKINNY_DEVMODE
-#endif
-/* end hack */
-
-#ifdef SKINNY_DEVMODE
-#define SKINNY_DEVONLY(code)	\
-	code
+/* Skinny debugging only available if asterisk configured with --enable-dev-mode */
+#ifdef AST_DEVMODE
+static int skinnydebug = 0;
+char dbgcli_buf[256];
+char dbgreg_buf[256];
+char dbgsub_buf[256];
+#define DEBUG_GENERAL	(1 << 1)
+#define DEBUG_SUB	(1 << 2)
+#define DEBUG_PACKET	(1 << 3)
+#define DEBUG_AUDIO	(1 << 4)
+#define DEBUG_LOCK	(1 << 5)
+#define DEBUG_TEMPLATE	(1 << 6)
+#define DEBUG_THREAD	(1 << 7)
+#define DEBUG_HINT	(1 << 8)
+#define SKINNY_DEBUG(type, verb_level, text, ...)						\
+	do{											\
+		if (skinnydebug & (type)) {							\
+			ast_verb(verb_level, "[%d] " text, ast_get_tid(), ##__VA_ARGS__);	\
+		}										\
+	}while(0)
 #else
-#define SKINNY_DEVONLY(code)
+#define SKINNY_DEBUG(type, verb_level, text, ...)
 #endif
 
 /*************************************
@@ -241,7 +251,7 @@
 };
 static struct ast_jb_conf global_jbconf;
 
-#ifdef SKINNY_DEVMODE
+#ifdef AST_DEVMODE
 AST_THREADSTORAGE(message2str_threadbuf);
 #define MESSAGE2STR_BUFSIZE   35
 #endif
@@ -1096,7 +1106,6 @@
  * Asterisk specific globals *
  *****************************/
 
-static int skinnydebug = 0;
 static int skinnyreload = 0;
 
 /* a hostname, portnumber, socket and such is usefull for VoIP protocols */
@@ -1760,8 +1769,6 @@
 		else if (!checkdevice) {
 			/* This is a match, since we're checking for line on every device. */
 		} else if (!strcasecmp(d->name, device)) {
-			if (skinnydebug)
-				ast_verb(2, "Found device: %s\n", d->name);
 		} else
 			continue;
 
@@ -1770,7 +1777,7 @@
 			/* Search for the right line */
 			if (!strcasecmp(l->name, line)) {
 				if (tmpl) {
-					ast_verb(2, "Ambiguous line name: %s\n", line);
+					ast_log(LOG_WARNING, "Ambiguous line name: %s\n", line);
 					AST_LIST_UNLOCK(&devices);
 					return NULL;
 				} else
@@ -2169,136 +2176,7 @@
 	return -1; /* main loop will destroy the session */
 }
 
-#ifdef SKINNY_DEVMODE
-static char *message2str(int type)
-{
-	char *tmp;
-
-	switch (letohl(type)) {
-	case KEEP_ALIVE_MESSAGE:
-		return "KEEP_ALIVE_MESSAGE";
-	case REGISTER_MESSAGE:
-		return "REGISTER_MESSAGE";
-	case IP_PORT_MESSAGE:
-		return "IP_PORT_MESSAGE";
-	case KEYPAD_BUTTON_MESSAGE:
-		return "KEYPAD_BUTTON_MESSAGE";
-	case ENBLOC_CALL_MESSAGE:
-		return "ENBLOC_CALL_MESSAGE";
-	case STIMULUS_MESSAGE:
-		return "STIMULUS_MESSAGE";
-	case OFFHOOK_MESSAGE:
-		return "OFFHOOK_MESSAGE";
-	case ONHOOK_MESSAGE:
-		return "ONHOOK_MESSAGE";
-	case CAPABILITIES_RES_MESSAGE:
-		return "CAPABILITIES_RES_MESSAGE";
-	case SPEED_DIAL_STAT_REQ_MESSAGE:
-		return "SPEED_DIAL_STAT_REQ_MESSAGE";
-	case LINE_STATE_REQ_MESSAGE:
-		return "LINE_STATE_REQ_MESSAGE";
-	case TIME_DATE_REQ_MESSAGE:
-		return "TIME_DATE_REQ_MESSAGE";
-	case BUTTON_TEMPLATE_REQ_MESSAGE:
-		return "BUTTON_TEMPLATE_REQ_MESSAGE";
-	case VERSION_REQ_MESSAGE:
-		return "VERSION_REQ_MESSAGE";
-	case SERVER_REQUEST_MESSAGE:
-		return "SERVER_REQUEST_MESSAGE";
-	case ALARM_MESSAGE:
-		return "ALARM_MESSAGE";
-	case OPEN_RECEIVE_CHANNEL_ACK_MESSAGE:
-		return "OPEN_RECEIVE_CHANNEL_ACK_MESSAGE";
-	case SOFT_KEY_SET_REQ_MESSAGE:
-		return "SOFT_KEY_SET_REQ_MESSAGE";
-	case SOFT_KEY_EVENT_MESSAGE:
-		return "SOFT_KEY_EVENT_MESSAGE";
-	case UNREGISTER_MESSAGE:
-		return "UNREGISTER_MESSAGE";
-	case SOFT_KEY_TEMPLATE_REQ_MESSAGE:
-		return "SOFT_KEY_TEMPLATE_REQ_MESSAGE";
-	case HEADSET_STATUS_MESSAGE:
-		return "HEADSET_STATUS_MESSAGE";
-	case REGISTER_AVAILABLE_LINES_MESSAGE:
-		return "REGISTER_AVAILABLE_LINES_MESSAGE";
-	case REGISTER_ACK_MESSAGE:
-		return "REGISTER_ACK_MESSAGE";
-	case START_TONE_MESSAGE:
-		return "START_TONE_MESSAGE";
-	case STOP_TONE_MESSAGE:
-		return "STOP_TONE_MESSAGE";
-	case SET_RINGER_MESSAGE:
-		return "SET_RINGER_MESSAGE";
-	case SET_LAMP_MESSAGE:
-		return "SET_LAMP_MESSAGE";
-	case SET_SPEAKER_MESSAGE:
-		return "SET_SPEAKER_MESSAGE";
-	case SET_MICROPHONE_MESSAGE:
-		return "SET_MICROPHONE_MESSAGE";
-	case START_MEDIA_TRANSMISSION_MESSAGE:
-		return "START_MEDIA_TRANSMISSION_MESSAGE";
-	case STOP_MEDIA_TRANSMISSION_MESSAGE:
-		return "STOP_MEDIA_TRANSMISSION_MESSAGE";
-	case CALL_INFO_MESSAGE:
-		return "CALL_INFO_MESSAGE";
-	case FORWARD_STAT_MESSAGE:
-		return "FORWARD_STAT_MESSAGE";
-	case SPEED_DIAL_STAT_RES_MESSAGE:
-		return "SPEED_DIAL_STAT_RES_MESSAGE";
-	case LINE_STAT_RES_MESSAGE:
-		return "LINE_STAT_RES_MESSAGE";
-	case DEFINETIMEDATE_MESSAGE:
-		return "DEFINETIMEDATE_MESSAGE";
-	case BUTTON_TEMPLATE_RES_MESSAGE:
-		return "BUTTON_TEMPLATE_RES_MESSAGE";
-	case VERSION_RES_MESSAGE:
-		return "VERSION_RES_MESSAGE";
-	case DISPLAYTEXT_MESSAGE:
-		return "DISPLAYTEXT_MESSAGE";
-	case CLEAR_NOTIFY_MESSAGE:
-		return "CLEAR_NOTIFY_MESSAGE";
-	case CLEAR_DISPLAY_MESSAGE:
-		return "CLEAR_DISPLAY_MESSAGE";
-	case CAPABILITIES_REQ_MESSAGE:
-		return "CAPABILITIES_REQ_MESSAGE";
-	case REGISTER_REJ_MESSAGE:
-		return "REGISTER_REJ_MESSAGE";
-	case SERVER_RES_MESSAGE:
-		return "SERVER_RES_MESSAGE";
-	case RESET_MESSAGE:
-		return "RESET_MESSAGE";
-	case KEEP_ALIVE_ACK_MESSAGE:
-		return "KEEP_ALIVE_ACK_MESSAGE";
-	case OPEN_RECEIVE_CHANNEL_MESSAGE:
-		return "OPEN_RECEIVE_CHANNEL_MESSAGE";
-	case CLOSE_RECEIVE_CHANNEL_MESSAGE:
-		return "CLOSE_RECEIVE_CHANNEL_MESSAGE";
-	case SOFT_KEY_TEMPLATE_RES_MESSAGE:
-		return "SOFT_KEY_TEMPLATE_RES_MESSAGE";
-	case SOFT_KEY_SET_RES_MESSAGE:
-		return "SOFT_KEY_SET_RES_MESSAGE";
-	case SELECT_SOFT_KEYS_MESSAGE:
-		return "SELECT_SOFT_KEYS_MESSAGE";
-	case CALL_STATE_MESSAGE:
-		return "CALL_STATE_MESSAGE";
-	case DISPLAY_PROMPT_STATUS_MESSAGE:
-		return "DISPLAY_PROMPT_STATUS_MESSAGE";
-	case CLEAR_PROMPT_MESSAGE:
-		return "CLEAR_PROMPT_MESSAGE";
-	case DISPLAY_NOTIFY_MESSAGE:
-		return "DISPLAY_NOTIFY_MESSAGE";
-	case ACTIVATE_CALL_PLANE_MESSAGE:
-		return "ACTIVATE_CALL_PLANE_MESSAGE";
-	case DIALED_NUMBER_MESSAGE:
-		return "DIALED_NUMBER_MESSAGE";
-	default:
-		if (!(tmp = ast_threadstorage_get(&message2str_threadbuf, MESSAGE2STR_BUFSIZE)))
-			return "Unknown";
-		snprintf(tmp, MESSAGE2STR_BUFSIZE, "UNKNOWN_MESSAGE-%d", type);
-		return tmp;
-	}
-}
-
+#ifdef AST_DEVMODE
 static char *callstate2str(int ind)
 {
 	char *tmp;
@@ -2345,8 +2223,6 @@
 
 	ast_mutex_lock(&s->lock);
 
-	SKINNY_DEVONLY(if (skinnydebug>1) ast_verb(4, "Transmitting %s to %s\n", message2str(req->e), s->device->name);)
-
 	if ((letohl(req->len) > SKINNY_MAX_PACKET) || (letohl(req->len) < 0)) {
 		ast_log(LOG_WARNING, "transmit_response: the length of the request (%d) is out of bounds (%d)\n", letohl(req->len), SKINNY_MAX_PACKET);
 		ast_mutex_unlock(&s->lock);
@@ -2358,17 +2234,16 @@
 	memcpy(s->outbuf+skinny_header_size, &req->data, letohl(req->len));
 
 	res = write(s->fd, s->outbuf, letohl(req->len)+8);
-	
+
 	if (res != letohl(req->len)+8) {
 		ast_log(LOG_WARNING, "Transmit: write only sent %d out of %d bytes: %s\n", res, letohl(req->len)+8, strerror(errno));
 		if (res == -1) {
-			if (skinnydebug)
-				ast_log(LOG_WARNING, "Transmit: Skinny Client was lost, unregistering\n");
+			ast_log(LOG_WARNING, "Transmit: Skinny Client was lost, unregistering\n");
 			skinny_unregister(NULL, s);
 		}
-		
-	}
-	
+
+	}
+
 	ast_free(req);
 	ast_mutex_unlock(&s->lock);
 	return 1;
@@ -2390,8 +2265,9 @@
 	memcpy(&name, req->data.reg.name, sizeof(name));
 	snprintf(req->data.regrej.errMsg, sizeof(req->data.regrej.errMsg), "No Authority: %s", name);
 
+	SKINNY_DEBUG(DEBUG_PACKET, 3, "Transmitting REGISTER_REJ_MESSAGE to UNKNOWN_DEVICE\n");
 	transmit_response_bysession(s, req);
-}	
+}
 
 static void transmit_speaker_mode(struct skinny_device *d, int mode)
 {
@@ -2401,6 +2277,8 @@
 		return;
 
 	req->data.setspeaker.mode = htolel(mode);
+
+	SKINNY_DEBUG(DEBUG_PACKET, 3, "Transmitting SET_SPEAKER_MESSAGE to %s, mode %d\n", d->name, mode);
 	transmit_response(d, req);
 }
 
@@ -2412,6 +2290,8 @@
 		return;
 
 	req->data.setmicrophone.mode = htolel(mode);
+
+	SKINNY_DEBUG(DEBUG_PACKET, 3, "Transmitting SET_MICROPHONE_MESSAGE to %s, mode %d\n", d->name, mode);
 	transmit_response(d, req);
 }
 
@@ -2423,10 +2303,6 @@
 	if (!(req = req_alloc(sizeof(struct call_info_message), CALL_INFO_MESSAGE)))
 		return;
 
-	if (skinnydebug) {
-		ast_verb(1, "Setting Callinfo to %s(%s) from %s(%s) (dir=%d) on %s(%d)\n", toname, tonum, fromname, fromnum, calldirection, d->name, instance);
-	}
-	
 	ast_copy_string(req->data.callinfo.callingPartyName, fromname, sizeof(req->data.callinfo.callingPartyName));
 	ast_copy_string(req->data.callinfo.callingParty, fromnum, sizeof(req->data.callinfo.callingParty));
 	ast_copy_string(req->data.callinfo.calledPartyName, toname, sizeof(req->data.callinfo.calledPartyName));
@@ -2434,6 +2310,9 @@
 	req->data.callinfo.instance = htolel(instance);
 	req->data.callinfo.reference = htolel(callid);
 	req->data.callinfo.type = htolel(calldirection);
+
+	SKINNY_DEBUG(DEBUG_PACKET, 3, "Transmitting CALL_INFO_MESSAGE to %s, to %s(%s) from %s(%s) (dir=%d) on %s(%d)\n",
+		d->name, toname, tonum, fromname, fromnum, calldirection, d->name, instance);
 	transmit_response(d, req);
 }
 
@@ -2525,6 +2404,9 @@
 	req->data.openreceivechannel.capability = htolel(codec_ast2skinny(&fmt.format));
 	req->data.openreceivechannel.echo = htolel(0);
 	req->data.openreceivechannel.bitrate = htolel(0);
+
+	SKINNY_DEBUG(DEBUG_PACKET, 3, "Transmitting OPEN_RECEIVE_CHANNEL_MESSAGE to %s, confid %d, partyid %d, ms %d, fmt %d, echo %d, brate %d\n",
+		d->name, sub->callid, sub->callid, fmt.cur_ms, codec_ast2skinny(&fmt.format), 0, 0);
 	transmit_response(d, req);
 }
 
@@ -2536,6 +2418,9 @@
 	req->data.starttone.tone = htolel(tone);
 	req->data.starttone.instance = htolel(instance);
 	req->data.starttone.reference = htolel(reference);
+
+	SKINNY_DEBUG(DEBUG_PACKET, 3, "Transmitting START_TONE_MESSAGE to %s, tone %d, inst %d, ref %d\n",
+		d->name, tone, instance, reference);
 	transmit_response(d, req);
 }
 
@@ -2546,6 +2431,9 @@
 		return;
 	req->data.stoptone.instance = htolel(instance);
 	req->data.stoptone.reference = htolel(reference);
+
+	SKINNY_DEBUG(DEBUG_PACKET, 3, "Transmitting STOP_TONE_MESSAGE to %s, inst %d, ref %d\n",
+		d->name, instance, reference);
 	transmit_response(d, req);
 }
 
@@ -2560,6 +2448,9 @@
 	req->data.selectsoftkey.reference = htolel(callid);
 	req->data.selectsoftkey.softKeySetIndex = htolel(softkey);
 	req->data.selectsoftkey.validKeyMask = htolel(0xFFFFFFFF);
+
+	SKINNY_DEBUG(DEBUG_PACKET, 3, "Transmitting SELECT_SOFT_KEYS_MESSAGE to %s, inst %d, callid %d, softkey %d, mask 0xFFFFFFFF\n",
+		d->name, instance, callid, softkey);
 	transmit_response(d, req);
 }
 
@@ -2573,15 +2464,15 @@
 	req->data.setlamp.stimulus = htolel(stimulus);
 	req->data.setlamp.stimulusInstance = htolel(instance);
 	req->data.setlamp.deviceStimulus = htolel(indication);
+
+	SKINNY_DEBUG(DEBUG_PACKET, 3, "Transmitting SET_LAMP_MESSAGE to %s, stim %d, inst %d, ind %d\n",
+		d->name, stimulus, instance, indication);
 	transmit_response(d, req);
 }
 
 static void transmit_ringer_mode(struct skinny_device *d, int mode)
 {
 	struct skinny_req *req;
-
-	if (skinnydebug)
-		ast_verb(1, "Setting ringer mode to '%d'.\n", mode);
 
 	if (!(req = req_alloc(sizeof(struct set_ringer_message), SET_RINGER_MESSAGE)))
 		return;
@@ -2598,6 +2489,9 @@
 	/* XXX the value here doesn't seem to change anything.  Must be higher than 0.
 	   Perhaps a packet capture can shed some light on this. */
 	req->data.setringer.unknown2 = htolel(1);
+
+	SKINNY_DEBUG(DEBUG_PACKET, 3, "Transmitting SET_RINGER_MESSAGE to %s, mode %d, unk1 1, unk2 1\n",
+		d->name, mode);
 	transmit_response(d, req);
 }
 
@@ -2612,8 +2506,7 @@
 	//req->data.clearpromptstatus.lineInstance = instance;
 	//req->data.clearpromptstatus.callReference = reference;
 
-	if (skinnydebug)
-		ast_verb(1, "Clearing Display\n");
+	SKINNY_DEBUG(DEBUG_PACKET, 3, "Transmitting CLEAR_DISPLAY_MESSAGE to %s\n", d->name);
 	transmit_response(d, req);
 }
 
@@ -2631,8 +2524,7 @@
 		return;
 
 	ast_copy_string(req->data.displaytext.text, text, sizeof(req->data.displaytext.text));
-	if (skinnydebug)
-		ast_verb(1, "Displaying message '%s'\n", req->data.displaytext.text);
+	SKINNY_DEBUG(DEBUG_PACKET, 3, "Transmitting DISPLAYTEXT_MESSAGE to %s, text %s\n", d->name, text);
 	transmit_response(d, req);
 } */
 
@@ -2646,9 +2538,7 @@
 	ast_copy_string(req->data.displaynotify.displayMessage, text, sizeof(req->data.displaynotify.displayMessage));
 	req->data.displaynotify.displayTimeout = htolel(t);
 
-	if (skinnydebug)
-		ast_verb(1, "Displaying notify '%s'\n", text);
-
+	SKINNY_DEBUG(DEBUG_PACKET, 3, "Transmitting DISPLAY_NOTIFY_MESSAGE to %s, text %s\n", d->name, text);
 	transmit_response(d, req);
 }
 
@@ -2664,9 +2554,7 @@
 	req->data.displaypromptstatus.lineInstance = htolel(instance);
 	req->data.displaypromptstatus.callReference = htolel(callid);
 
-	if (skinnydebug)
-		ast_verb(1, "Displaying Prompt Status '%s'\n", text);
-
+	SKINNY_DEBUG(DEBUG_PACKET, 3, "Transmitting DISPLAY_PROMPT_STATUS_MESSAGE to %s, text %s\n", d->name, text);
 	transmit_response(d, req);
 }
 
@@ -2680,9 +2568,8 @@
 	req->data.clearpromptstatus.lineInstance = htolel(instance);
 	req->data.clearpromptstatus.callReference = htolel(callid);
 
-	if (skinnydebug)
-		ast_verb(1, "Clearing Prompt\n");
-
+	SKINNY_DEBUG(DEBUG_PACKET, 3, "Transmitting CLEAR_PROMPT_MESSAGE to %s, inst %d, callid %d\n",
+		d->name, instance, callid);
 	transmit_response(d, req);
 }
 
@@ -2697,6 +2584,8 @@
 	req->data.dialednumber.lineInstance = htolel(instance);
 	req->data.dialednumber.callReference = htolel(callid);
 
+	SKINNY_DEBUG(DEBUG_PACKET, 3, "Transmitting DIALED_NUMBER_MESSAGE to %s, num %s, inst %d, callid %d\n",
+		d->name, text, instance, callid);
 	transmit_response(d, req);
 }
 
@@ -2709,6 +2598,9 @@
 
 	req->data.closereceivechannel.conferenceId = htolel(0);
 	req->data.closereceivechannel.partyId = htolel(sub->callid);
+
+	SKINNY_DEBUG(DEBUG_PACKET, 3, "Transmitting CLOSE_RECEIVE_CHANNEL_MESSAGE to %s, confid %d, callid %d\n",
+		d->name, 0, sub->callid);
 	transmit_response(d, req);
 }
 
@@ -2721,6 +2613,9 @@
 
 	req->data.stopmedia.conferenceId = htolel(0);
 	req->data.stopmedia.passThruPartyId = htolel(sub->callid);
+
+	SKINNY_DEBUG(DEBUG_PACKET, 3, "Transmitting STOP_MEDIA_TRANSMISSION_MESSAGE to %s, confid %d, passthrupartyid %d\n",
+		d->name, 0, sub->callid);
 	transmit_response(d, req);
 }
 
@@ -2755,6 +2650,9 @@
 		req->data.startmedia_ip6.qualifier.packets = htolel(0);
 		req->data.startmedia_ip6.qualifier.bitRate = htolel(0);
 	}
+
+	SKINNY_DEBUG(DEBUG_PACKET, 3, "Transmitting START_MEDIA_TRANSMISSION_MESSAGE to %s, callid %d, passthrupartyid %d, ip %s:%d, ms %d, fmt %d, prec 127\n",
+		d->name, sub->callid, sub->callid, ast_inet_ntoa(dest.sin_addr), dest.sin_port, fmt.cur_ms, codec_ast2skinny(&fmt.format));
 	transmit_response(d, req);
 }
 
@@ -2766,6 +2664,9 @@
 		return;
 
 	req->data.activatecallplane.lineInstance = htolel(l->instance);
+
+	SKINNY_DEBUG(DEBUG_PACKET, 3, "Transmitting ACTIVATE_CALL_PLANE_MESSAGE to %s, inst %d\n",
+		d->name, l->instance);
 	transmit_response(d, req);
 }
 
@@ -2775,16 +2676,13 @@
 
 	if (!(req = req_alloc(sizeof(struct call_state_message), CALL_STATE_MESSAGE)))
 		return;
-	
-#ifdef SKINNY_DEVMODE
-	if (skinnydebug) {
-		ast_verb(3, "Transmitting CALL_STATE_MESSAGE to %s - line %d, callid %d, state %s\n", d->name, buttonInstance, callid, callstate2str(state));
-	}
-#endif
 
 	req->data.callstate.callState = htolel(state);
 	req->data.callstate.lineInstance = htolel(buttonInstance);
 	req->data.callstate.callReference = htolel(callid);
+
+	SKINNY_DEBUG(DEBUG_PACKET, 3, "Transmitting CALL_STATE_MESSAGE to %s, state %s, inst %d, callid %d\n",
+		d->name, callstate2str(state), buttonInstance, callid);
 	transmit_response(d, req);
 }
 
@@ -2829,6 +2727,8 @@
 	else
 		req->data.forwardstat.activeforward = htolel(0);
 
+	SKINNY_DEBUG(DEBUG_PACKET, 3, "Transmitting FORWARD_STAT_MESSAGE to %s, inst %d, all %s, busy %s, noans %s, acitve %d\n",
+		d->name, l->instance, l->call_forward_all, l->call_forward_busy, l->call_forward_noanswer, anyon ? 7 : 0);
 	transmit_response(d, req);
 }
 
@@ -2843,6 +2743,8 @@
 	ast_copy_string(req->data.speeddial.speedDialDirNumber, sd->exten, sizeof(req->data.speeddial.speedDialDirNumber));
 	ast_copy_string(req->data.speeddial.speedDialDisplayName, sd->label, sizeof(req->data.speeddial.speedDialDisplayName));
 
+	SKINNY_DEBUG(DEBUG_PACKET, 3, "Transmitting SPEED_DIAL_STAT_RES_MESSAGE to %s, inst %d, dir %s, display %s\n",
+		d->name, sd->instance, sd->exten, sd->label);
 	transmit_response(d, req);
 }
 
@@ -2865,6 +2767,9 @@
 		memcpy(req->data.linestat.lineDirNumber, sd->label, sizeof(req->data.linestat.lineDirNumber));
 		memcpy(req->data.linestat.lineDisplayName, sd->label, sizeof(req->data.linestat.lineDisplayName));
 	}
+
+	SKINNY_DEBUG(DEBUG_PACKET, 3, "Transmitting LINE_STAT_RES_MESSAGE to %s, inst %d, num %s, label %s\n",
+		d->name, l->instance, req->data.linestat.lineDirNumber, req->data.linestat.lineDisplayName);
 	transmit_response(d, req);
 }
 
@@ -2887,6 +2792,10 @@
 	req->data.definetimedate.seconds = htolel(cmtime.tm_sec);
 	req->data.definetimedate.milliseconds = htolel(cmtime.tm_usec / 1000);
 	req->data.definetimedate.timestamp = htolel(now.tv_sec);
+
+	SKINNY_DEBUG(DEBUG_PACKET, 3, "Transmitting DEFINETIMEDATE_MESSAGE to %s, date %d %d %d dow %d time %d:%d:%d.%d\n",
+		d->name, req->data.definetimedate.year, req->data.definetimedate.month, req->data.definetimedate.day, req->data.definetimedate.dayofweek,
+		req->data.definetimedate.hour, req->data.definetimedate.minute, req->data.definetimedate.seconds, req->data.definetimedate.milliseconds);
 	transmit_response(d, req);
 }
 
@@ -2897,6 +2806,8 @@
 		return;
 
 	ast_copy_string(req->data.version.version, d->version_id, sizeof(req->data.version.version));
+
+	SKINNY_DEBUG(DEBUG_PACKET, 3, "Transmitting VERSION_RES_MESSAGE to %s, version %s\n", d->name, d->version_id);
 	transmit_response(d, req);
 }
 
@@ -2910,6 +2821,9 @@
 			sizeof(req->data.serverres.server[0].serverName));
 	req->data.serverres.serverListenPort[0] = htolel(ourport);
 	req->data.serverres.serverIpAddr[0] = htolel(d->ourip.s_addr);
+
+	SKINNY_DEBUG(DEBUG_PACKET, 3, "Transmitting SERVER_RES_MESSAGE to %s, srvname %s %s:%d\n",
+		d->name, ourhost, ast_inet_ntoa(d->ourip), ourport);
 	transmit_response(d, req);
 }
 
@@ -2923,6 +2837,8 @@
 
 	if (!(req = req_alloc(sizeof(struct soft_key_set_res_message), SOFT_KEY_SET_RES_MESSAGE)))
 		return;
+
+	SKINNY_DEBUG(DEBUG_TEMPLATE, 3, "Creating Softkey Template\n");
 
 	req->data.softkeysets.softKeySetOffset = htolel(0);
 	req->data.softkeysets.softKeySetCount = htolel(13);
@@ -2936,13 +2852,16 @@
 				if (defaults[y] == i+1) {
 					req->data.softkeysets.softKeySetDefinition[softkeymode->mode].softKeyTemplateIndex[y] = (i+1);
 					req->data.softkeysets.softKeySetDefinition[softkeymode->mode].softKeyInfoIndex[y] = htoles(i+301);
-				        if (skinnydebug)	
-						ast_verbose("softKeySetDefinition : softKeyTemplateIndex: %d softKeyInfoIndex: %d\n", i+1, i+301);
+					SKINNY_DEBUG(DEBUG_TEMPLATE, 4, "softKeySetDefinition : softKeyTemplateIndex: %d softKeyInfoIndex: %d\n",
+						i+1, i+301);
 				}
 			}
 		}
 		softkeymode++;
 	}
+
+	SKINNY_DEBUG(DEBUG_PACKET | DEBUG_TEMPLATE, 3, "Transmitting SOFT_KEY_SET_RES_MESSAGE to %s, template data\n",
+		d->name);
 	transmit_response(d, req);
 }
 
@@ -2958,6 +2877,9 @@
 	memcpy(req->data.softkeytemplate.softKeyTemplateDefinition,
 		soft_key_template_default,
 		sizeof(soft_key_template_default));
+
+	SKINNY_DEBUG(DEBUG_PACKET, 3, "Transmitting SOFT_KEY_TEMPLATE_RES_MESSAGE to %s, offset 0, keycnt %d, totalkeycnt %d, template data\n",
+		d->name, req->data.softkeytemplate.softKeyCount, req->data.softkeytemplate.totalSoftKeyCount);
 	transmit_response(d, req);
 }
 
@@ -2973,7 +2895,8 @@
 	else
 		req->data.reset.resetType = 1;
 
-	ast_verb(3, "%s device %s.\n", (fullrestart) ? "Restarting" : "Resetting", d->id);
+	SKINNY_DEBUG(DEBUG_PACKET, 3, "Transmitting RESET_MESSAGE to %s, type %s\n",
+		d->name, (fullrestart) ? "Restarting" : "Resetting");
 	transmit_response(d, req);
 }
 
@@ -2984,6 +2907,7 @@
 	if (!(req = req_alloc(0, KEEP_ALIVE_ACK_MESSAGE)))
 		return;
 
+	SKINNY_DEBUG(DEBUG_PACKET, 3, "Transmitting KEEP_ALIVE_ACK_MESSAGE to %s\n", d->name);
 	transmit_response(d, req);
 }
 
@@ -3002,6 +2926,15 @@
 	req->data.regack.res2[1] = '\0';
 	req->data.regack.secondaryKeepAlive = htolel(keep_alive);
 
+#ifdef AST_DEVMODE
+	{
+	short res = req->data.regack.res[0] << 8 | req->data.regack.res[1];
+	int res2 = req->data.regack.res2[0] << 24 | req->data.regack.res2[1] << 16 | req->data.regack.res2[2] << 8 | req->data.regack.res2[3];
+	SKINNY_DEBUG(DEBUG_PACKET, 3, "Transmitting REGISTER_ACK_MESSAGE to %s, keepalive %d, datetemplate %s, seckeepalive %d, res 0x%04x, res2 0x%08x\n",
+		d->name, keep_alive, date_format, keep_alive, res, res2);
+	}
+#endif
+
 	transmit_response(d, req);
 }
 
@@ -3012,9 +2945,7 @@
 	if (!(req = req_alloc(0, CAPABILITIES_REQ_MESSAGE)))
 		return;
 
-	if (skinnydebug)
-		ast_verb(1, "Requesting capabilities\n");
-
+	SKINNY_DEBUG(DEBUG_PACKET, 3, "Transmitting CAPABILITIES_REQ_MESSAGE to %s\n", d->name);
 	transmit_response(d, req);
 }
 
@@ -3034,9 +2965,7 @@
 		struct skinny_speeddial *sd = container->data;
 		d = sd->parent;
 
-		if (skinnydebug) {
-			ast_verb(2, "Got hint %s on speeddial %s\n", ast_extension_state2str(state), sd->label);
-		}
+		SKINNY_DEBUG(DEBUG_HINT, 3, "Got hint %s on speeddial %s\n", ast_extension_state2str(state), sd->label);
 
 		if (ast_get_hint(hint, sizeof(hint), NULL, 0, NULL, sd->context, sd->exten)) {
 			/* If they are not registered, we will override notification and show no availability */
@@ -3048,7 +2977,8 @@
 			switch (state) {
 			case AST_EXTENSION_DEACTIVATED: /* Retry after a while */
 			case AST_EXTENSION_REMOVED:     /* Extension is gone */
-				ast_verb(2, "Extension state: Watcher for hint %s %s. Notify Device %s\n", exten, state == AST_EXTENSION_DEACTIVATED ? "deactivated" : "removed", d->name);
+				SKINNY_DEBUG(DEBUG_HINT, 3, "Extension state: Watcher for hint %s %s. Notify Device %s\n",
+					exten, state == AST_EXTENSION_DEACTIVATED ? "deactivated" : "removed", d->name);
 				sd->stateid = -1;
 				transmit_lamp_indication(d, STIMULUS_LINE, sd->instance, SKINNY_LAMP_OFF);
 				transmit_callstate(d, sd->instance, 0, SKINNY_ONHOOK);
@@ -3080,10 +3010,8 @@
 		struct skinny_line *l = subline->line;
 		d = l->device;
 
-		if (skinnydebug) {
-			ast_verb(2, "Got hint %s on subline %s (%s@%s)\n", ast_extension_state2str(state), subline->name, exten, context);
-		}
-		
+		SKINNY_DEBUG(DEBUG_HINT, 3, "Got hint %s on subline %s (%s@%s)\n", ast_extension_state2str(state), subline->name, exten, context);
+
 		subline->extenstate = state;
 
 		if (subline->callid == 0) {
@@ -3148,10 +3076,8 @@
 		|| ast_strlen_zero(ast_channel_connected(c)->id.number.str))
 		return;
 
-	if (skinnydebug) {
-		ast_verb(3,"Sub %d - Updating\n", sub->callid);
-	}
-	
+	SKINNY_DEBUG(DEBUG_SUB, 3, "Sub %d - Updating\n", sub->callid);
+
 	send_callinfo(sub);
 	if (ast_channel_state(sub->owner) == AST_STATE_UP) {
 		transmit_callstate(d, l->instance, sub->callid, SKINNY_CONNECTED);
@@ -3232,9 +3158,7 @@
 	struct skinny_line *l;
 	enum ast_rtp_glue_result res = AST_RTP_GLUE_RESULT_REMOTE;
 
-	if (skinnydebug)
-		ast_verb(1, "skinny_get_rtp_peer() Channel = %s\n", ast_channel_name(c));
-
+	SKINNY_DEBUG(DEBUG_AUDIO, 4, "skinny_get_rtp_peer() Channel = %s\n", ast_channel_name(c));
 
 	if (!(sub = ast_channel_tech_pvt(c)))
 		return AST_RTP_GLUE_RESULT_FORBID;
@@ -3253,8 +3177,7 @@
 
 	if (!l->directmedia || l->nat){
 		res = AST_RTP_GLUE_RESULT_LOCAL;
-		if (skinnydebug)
-			ast_verb(1, "skinny_get_rtp_peer() Using AST_RTP_GLUE_RESULT_LOCAL \n");
+		SKINNY_DEBUG(DEBUG_AUDIO, 4, "skinny_get_rtp_peer() Using AST_RTP_GLUE_RESULT_LOCAL \n");
 	}
 
 	ast_mutex_unlock(&sub->lock);
@@ -3293,15 +3216,13 @@
 
 		/* Shutdown any early-media or previous media on re-invite */
 		transmit_stopmediatransmission(d, sub);
-		
-		if (skinnydebug)
-			ast_verb(1, "Peerip = %s:%d\n", ast_inet_ntoa(them.sin_addr), ntohs(them.sin_port));
+
+		SKINNY_DEBUG(DEBUG_AUDIO, 4, "Peerip = %s:%d\n", ast_inet_ntoa(them.sin_addr), ntohs(them.sin_port));
 
 		ast_best_codec(l->cap, &tmpfmt);
 		fmt = ast_codec_pref_getsize(&l->prefs, &tmpfmt);
 
-		if (skinnydebug)
-			ast_verb(1, "Setting payloadType to '%s' (%d ms)\n", ast_getformatname(&fmt.format), fmt.cur_ms);
+		SKINNY_DEBUG(DEBUG_AUDIO, 4, "Setting payloadType to '%s' (%d ms)\n", ast_getformatname(&fmt.format), fmt.cur_ms);
 
 		if (!(l->directmedia) || (l->nat)){
 			ast_rtp_instance_get_local_address(rtp, &us_tmp);
@@ -3325,47 +3246,142 @@
 	.update_peer = skinny_set_rtp_peer,
 };
 
+#ifdef AST_DEVMODE
+static char *skinny_debugs(void)
+{
+	char *ptr;
+	int posn = 0;
+
+	ptr = dbgcli_buf;
+	strncpy(ptr, "\0", 1);
+	if (skinnydebug & DEBUG_GENERAL) {
+		strncpy(ptr, "general ", 8);
+		posn += 8;
+		ptr += 8;
+	}
+	if (skinnydebug & DEBUG_SUB) {
+		strncpy(ptr, "sub ", 4);
+		posn += 4;
+		ptr += 4;
+	}
+	if (skinnydebug & DEBUG_AUDIO) {
+		strncpy(ptr, "audio ", 6);
+		posn += 6;
+		ptr += 6;
+	}
+	if (skinnydebug & DEBUG_PACKET) {
+		strncpy(ptr, "packet ", 7);
+		posn += 7;
+		ptr += 7;
+	}
+	if (skinnydebug & DEBUG_LOCK) {
+		strncpy(ptr, "lock ", 5);
+		posn += 5;
+		ptr += 5;
+	}
+	if (skinnydebug & DEBUG_TEMPLATE) {
+		strncpy(ptr, "template ", 9);
+		posn += 9;
+		ptr += 9;
+	}
+	if (skinnydebug & DEBUG_THREAD) {
+		strncpy(ptr, "thread ", 7);
+		posn += 7;
+		ptr += 7;
+	}
+	if (skinnydebug & DEBUG_HINT) {
+		strncpy(ptr, "hint ", 5);
+		posn += 5;
+		ptr += 5;
+	}
+	if (posn > 0) {
+		strncpy(--ptr, "\0", 1);
+	}
+	return dbgcli_buf;
+}
+
 static char *handle_skinny_set_debug(struct ast_cli_entry *e, int cmd, struct ast_cli_args *a)
 {
+	int i;
+	int result = 0;
+	const char *arg;
+	int bitmask;
+	int negate;
+
 	switch (cmd) {
 	case CLI_INIT:
-#ifdef SKINNY_DEVMODE
-		e->command = "skinny set debug {off|on|packet}";
+		e->command = "skinny debug [show|{off|all|packet|sub|audio|template|lock}]";
 		e->usage =
-			"Usage: skinny set debug {off|on|packet}\n"
-			"       Enables/Disables dumping of Skinny packets for debugging purposes\n";
-#else
-		e->command = "skinny set debug {off|on}";
-		e->usage =
-			"Usage: skinny set debug {off|on}\n"
-			"       Enables/Disables dumping of Skinny packets for debugging purposes\n";
-#endif
+			"Usage: skinny debug [show|{off|on|packet|sub|audio|template|lock}]\n"
+			"       Enables/Disables various Skinny debugging messages\n";
 		return NULL;
 	case CLI_GENERATE:
 		return NULL;
 	}
-	
-	if (a->argc != e->args)
+
+	if (a->argc < 3)
 		return CLI_SHOWUSAGE;
 
-	if (!strncasecmp(a->argv[e->args - 1], "on", 2)) {
-		skinnydebug = 1;
-		ast_cli(a->fd, "Skinny Debugging Enabled\n");
+	if (a->argc == 3 && !strncasecmp(a->argv[e->args-1], "show", 4)) {
+		ast_cli(a->fd, "Skinny Debugging - %s\n", skinny_debugs());
 		return CLI_SUCCESS;
-	} else if (!strncasecmp(a->argv[e->args - 1], "off", 3)) {
-		skinnydebug = 0;
-		ast_cli(a->fd, "Skinny Debugging Disabled\n");
+	}
+
+	for(i = e->args-1; i < a->argc; i++) {
+		result++;
+		arg = a->argv[i];
+
+		if (!strncasecmp(arg, "off", 3)) {
+			skinnydebug = 0;
+			continue;
+		}
+
+		if (!strncasecmp(arg, "-", 1) || !strncasecmp(arg, "!", 1)) {
+			negate = 1;
+			arg++;
+		} else if (!strncasecmp(arg, "+", 1)) {
+			negate = 0;
+			arg++;
+		} else {
+			negate = 0;
+		}
+
+		if (!strncasecmp(arg, "general", 7)) {
+			bitmask = DEBUG_GENERAL;
+		} else if (!strncasecmp(arg, "sub", 3)) {
+			bitmask = DEBUG_SUB;
+		} else if (!strncasecmp(arg, "packet", 6)) {
+			bitmask = DEBUG_PACKET;
+		} else if (!strncasecmp(arg, "audio", 5)) {
+			bitmask = DEBUG_AUDIO;
+		} else if (!strncasecmp(arg, "lock", 6)) {
+			bitmask = DEBUG_LOCK;
+		} else if (!strncasecmp(arg, "template", 8)) {
+			bitmask = DEBUG_TEMPLATE;
+		} else if (!strncasecmp(arg, "thread", 6)) {
+			bitmask = DEBUG_THREAD;
+		} else if (!strncasecmp(arg, "hint", 6)) {
+			bitmask = DEBUG_HINT;
+		} else {
+			ast_cli(a->fd, "Skinny Debugging - option '%s' unknown\n", a->argv[i]);
+			result--;
+			continue;
+		}
+
+		if (negate) {
+			skinnydebug &= ~bitmask;
+		} else {
+			skinnydebug |= bitmask;
+		}
+	}
+	if (result) {
+		ast_cli(a->fd, "Skinny Debugging - %s\n", skinnydebug ? skinny_debugs() : "off");
 		return CLI_SUCCESS;
-#ifdef SKINNY_DEVMODE
-	} else if (!strncasecmp(a->argv[e->args - 1], "packet", 6)) {
-		skinnydebug = 2;
-		ast_cli(a->fd, "Skinny Debugging Enabled including Packets\n");
-		return CLI_SUCCESS;
-#endif
 	} else {
 		return CLI_SHOWUSAGE;
 	}
 }
+#endif
 
 static char *handle_skinny_reload(struct ast_cli_entry *e, int cmd, struct ast_cli_args *a)
 {
@@ -4165,7 +4181,9 @@
 	AST_CLI_DEFINE(handle_skinny_show_lines, "List defined Skinny lines per device"),
 	AST_CLI_DEFINE(handle_skinny_show_line, "List Skinny line information"),
 	AST_CLI_DEFINE(handle_skinny_show_settings, "List global Skinny settings"),
+#ifdef AST_DEVMODE
 	AST_CLI_DEFINE(handle_skinny_set_debug, "Enable/Disable Skinny debugging"),
+#endif
 	AST_CLI_DEFINE(handle_skinny_reset, "Reset Skinny device(s)"),
 	AST_CLI_DEFINE(handle_skinny_reload, "Reload Skinny config"),
 };
@@ -4376,7 +4394,7 @@
 	int doautoanswer = 0;
 
 	if (!d || !d->session) {
-		ast_log(LOG_ERROR, "Device not registered, cannot call %s\n", dest);
+		ast_log(LOG_WARNING, "Device not registered, cannot call %s\n", dest);
 		return -1;
 	}
 
@@ -4385,8 +4403,8 @@
 		return -1;
 	}
 
-	if (skinnydebug)
-		ast_verb(3, "skinny_call(%s)\n", ast_channel_name(ast));
+	SKINNY_DEBUG(DEBUG_SUB, 3, "Skinny Call (%s) - Sub %d\n",
+		ast_channel_name(ast), sub->callid);
 
 	if (l->dnd) {
 		ast_queue_control(ast, AST_CONTROL_BUSY);
@@ -4406,7 +4424,6 @@
 				char *stringp = buf, *curstr;
 				ast_copy_string(buf, ast_var_value(current), sizeof(buf));
 				curstr = strsep(&stringp, ":");
-				ast_verb(3, "test %s\n", curstr);
 				aatime = atoi(curstr);
 				while ((curstr = strsep(&stringp, ":"))) {
 					if (!(strcasecmp(curstr,"BEEP"))) {
@@ -4415,8 +4432,8 @@
 						sub->aa_mute = 1;
 					}
 				}
-				if (skinnydebug)
-					ast_verb(3, "Sub %d - setting autoanswer time=%dms %s%s\n", sub->callid, aatime, sub->aa_beep?"BEEP ":"", sub->aa_mute?"MUTE":"");
+				SKINNY_DEBUG(DEBUG_SUB, 3, "Sub %d - setting autoanswer time=%dms %s%s\n",
+					sub->callid, aatime, sub->aa_beep ? "BEEP " : "", sub->aa_mute ? "MUTE" : "");
 				if (aatime) {
 					//sub->aa_sched = ast_sched_add(sched, aatime, skinny_autoanswer_cb, sub);
 					sub->aa_sched = skinny_sched_add(aatime, skinny_autoanswer_cb, sub);
@@ -4442,11 +4459,10 @@
 		ast_debug(1, "Asked to hangup channel not connected\n");
 		return 0;
 	}
-	
+
 	dumpsub(sub, 1);
 
-	if (skinnydebug)
-		ast_verb(3,"Sub %d - Destroying\n", sub->callid);
+	SKINNY_DEBUG(DEBUG_SUB, 3, "Sub %d - Destroying\n", sub->callid);
 
 	ast_mutex_lock(&sub->lock);
 	sub->owner = NULL;
@@ -4465,13 +4481,10 @@
 {
 	int res = 0;
 	struct skinny_subchannel *sub = ast_channel_tech_pvt(ast);
-	struct skinny_line *l = sub->line;
-	struct skinny_device *d = l->device;
 
 	if (sub->blindxfer) {
-		if (skinnydebug)
-			ast_debug(1, "skinny_answer(%s) on %s@%s-%d with BlindXFER, transferring\n",
-				ast_channel_name(ast), l->name, d->name, sub->callid);
+		SKINNY_DEBUG(DEBUG_SUB, 3, "skinny_answer(%s) on %s@%s-%d with BlindXFER, transferring\n",
+			ast_channel_name(ast), sub->line->name, sub->line->device->name, sub->callid);
 		ast_setstate(ast, AST_STATE_UP);
 		skinny_transfer(sub);
 		return 0;
@@ -4479,9 +4492,9 @@
 
 	sub->cxmode = SKINNY_CX_SENDRECV;
 
-	if (skinnydebug)
-		ast_verb(1, "skinny_answer(%s) on %s@%s-%d\n", ast_channel_name(ast), l->name, d->name, sub->callid);
-	
+	SKINNY_DEBUG(DEBUG_SUB, 3, "skinny_answer(%s) on %s@%s-%d\n",
+		ast_channel_name(ast), sub->line->name, sub->line->device->name, sub->callid);
+
 	setsubstate(sub, SUBSTATE_CONNECTED);
 
 	return res;
@@ -4718,12 +4731,11 @@
 			xferee = sub->related;
 		}
 
-		if (skinnydebug) {
-			ast_debug(1, "Transferee channels (local/remote): %s and %s\n",
-				ast_channel_name(xferee->owner), ast_bridged_channel(xferee->owner)?ast_channel_name(ast_bridged_channel(xferee->owner)):"");
-			ast_debug(1, "Transferor channels (local/remote): %s and %s\n",
-				ast_channel_name(xferor->owner), ast_bridged_channel(xferor->owner)?ast_channel_name(ast_bridged_channel(xferor->owner)):"");
-		}
+		SKINNY_DEBUG(DEBUG_SUB, 3, "Transferee channels (local/remote): %s and %s\n",
+			ast_channel_name(xferee->owner), ast_bridged_channel(xferee->owner) ? ast_channel_name(ast_bridged_channel(xferee->owner)) : "");
+		SKINNY_DEBUG(DEBUG_SUB, 3, "Transferor channels (local/remote): %s and %s\n",
+			ast_channel_name(xferor->owner), ast_bridged_channel(xferor->owner) ? ast_channel_name(ast_bridged_channel(xferor->owner)) : "");
+
 		if (ast_bridged_channel(xferor->owner)) {
 			if (ast_bridged_channel(xferee->owner)) {
 				ast_queue_control(xferee->owner, AST_CONTROL_UNHOLD);
@@ -4735,9 +4747,8 @@
 					ts = ast_tone_zone_sound_unref(ts);
 				}
 			}
-			if (skinnydebug)
-				ast_debug(1, "Transfer Masquerading %s to %s\n",
-					ast_channel_name(xferee->owner), ast_bridged_channel(xferor->owner)?ast_channel_name(ast_bridged_channel(xferor->owner)):"");
+			SKINNY_DEBUG(DEBUG_SUB, 3, "Transfer Masquerading %s to %s\n",
+				ast_channel_name(xferee->owner), ast_bridged_channel(xferor->owner) ? ast_channel_name(ast_bridged_channel(xferor->owner)) : "");
 			if (ast_channel_masquerade(xferee->owner, ast_bridged_channel(xferor->owner))) {
 				ast_log(LOG_WARNING, "Unable to masquerade %s as %s\n",
 					ast_channel_name(ast_bridged_channel(xferor->owner)), ast_channel_name(xferee->owner));
@@ -4752,9 +4763,8 @@
 					ts = ast_tone_zone_sound_unref(ts);
 				}
 			}
-			if (skinnydebug)
-				ast_debug(1, "Transfer Masquerading %s to %s\n",
-					ast_channel_name(xferor->owner), ast_bridged_channel(xferee->owner)?ast_channel_name(ast_bridged_channel(xferee->owner)):"");
+			SKINNY_DEBUG(DEBUG_SUB, 3, "Transfer Masquerading %s to %s\n",
+				ast_channel_name(xferor->owner), ast_bridged_channel(xferee->owner) ? ast_channel_name(ast_bridged_channel(xferee->owner)) : "");
 			if (ast_channel_masquerade(xferor->owner, ast_bridged_channel(xferee->owner))) {
 				ast_log(LOG_WARNING, "Unable to masquerade %s as %s\n",
 					ast_channel_name(ast_bridged_channel(xferee->owner)), ast_channel_name(xferor->owner));
@@ -4781,13 +4791,13 @@
 		return -1;
 	}
 
-	if (skinnydebug)
-		ast_verb(3, "Asked to indicate '%s' condition on channel %s\n", control2str(ind), ast_channel_name(ast));
+	SKINNY_DEBUG(DEBUG_SUB, 3, "Asked to indicate '%s' condition on channel %s (Sub %d)\n",
+		control2str(ind), ast_channel_name(ast), sub->callid);
 	switch(ind) {
 	case AST_CONTROL_RINGING:
 		if (sub->blindxfer) {
-			if (skinnydebug)
-				ast_debug(1, "Channel %s set up for Blind Xfer, so Xfer rather than ring device\n", ast_channel_name(ast));
+			SKINNY_DEBUG(DEBUG_SUB, 3, "Channel %s (Sub %d) set up for Blind Xfer, so Xfer rather than ring device\n",
+				ast_channel_name(ast), sub->callid);
 			skinny_transfer(sub);
 			break;
 		}
@@ -4892,12 +4902,9 @@
 			ast_format_cap_copy(ast_channel_nativeformats(tmp), default_cap);
 		}
 		ast_best_codec(ast_channel_nativeformats(tmp), &tmpfmt);
-		if (skinnydebug) {
-			char buf[256];
-			ast_verb(1, "skinny_new: tmp->nativeformats=%s fmt=%s\n",
-				ast_getformatname_multiple(buf, sizeof(buf), ast_channel_nativeformats(tmp)),
-				ast_getformatname(&tmpfmt));
-		}
+		SKINNY_DEBUG(DEBUG_SUB, 3, "skinny_new: tmp->nativeformats=%s fmt=%s\n",
+			ast_getformatname_multiple(dbgsub_buf, sizeof(dbgsub_buf), ast_channel_nativeformats(tmp)),
+			ast_getformatname(&tmpfmt));
 		if (sub->rtp) {
 			ast_channel_set_fd(tmp, 0, ast_rtp_instance_fd(sub->rtp, 0));
 		}
@@ -5146,9 +5153,8 @@
 			transmit_speaker_mode(d, SKINNY_SPEAKERON);
 	}
 
-	if (skinnydebug) {
-		ast_verb(3, "Sub %d - change state from %s to %s\n", sub->callid, substate2str(sub->substate), substate2str(actualstate));
-	}
+	SKINNY_DEBUG(DEBUG_SUB, 3, "Sub %d - change state from %s to %s\n",
+		sub->callid, substate2str(sub->substate), substate2str(actualstate));
 
 	if (actualstate == sub->substate) {
 		send_callinfo(sub);
@@ -5402,9 +5408,7 @@
 	struct skinny_subchannel *activate_sub = NULL;
 	struct skinny_subchannel *tsub;
 
-	if (skinnydebug) {
-		ast_verb(3, "Sub %d - Dumping\n", sub->callid);
-	}
+	SKINNY_DEBUG(DEBUG_SUB, 3, "Sub %d - Dumping\n", sub->callid);
 
 	if (!forcehangup && sub->substate == SUBSTATE_HOLD) {
 		l->activesub = NULL;
@@ -5453,10 +5457,9 @@
 {
 	struct skinny_line *l = sub->line;
 
-	if (skinnydebug) {
-		ast_verb(3, "Sub %d - Activating, and deactivating sub %d\n", sub->callid, l->activesub?l->activesub->callid:0);
-	}
-	
+	SKINNY_DEBUG(DEBUG_SUB, 3, "Sub %d - Activating, and deactivating sub %d\n",
+		sub->callid, l->activesub ? l->activesub->callid : 0);
+
 	ast_channel_lock(sub->owner);
 
 	if (sub == l->activesub) {
@@ -5478,13 +5481,11 @@
 
 static void dialandactivatesub(struct skinny_subchannel *sub, char exten[AST_MAX_EXTENSION])
 {
-	if (skinnydebug) {
-		ast_verb(3, "Sub %d - Dial %s and Activate\n", sub->callid, exten);
-	}
+	SKINNY_DEBUG(DEBUG_SUB, 3, "Sub %d - Dial %s and Activate\n", sub->callid, exten);
 	ast_copy_string(sub->exten, exten, sizeof(sub->exten));
 	activatesub(sub, SUBSTATE_DIALING);
 }
-	
+
 static int handle_hold_button(struct skinny_subchannel *sub)
 {
 	if (!sub)
@@ -5673,8 +5674,7 @@
 			ast_queue_frame(AST_LIST_NEXT(sub, list)->owner, &f);
 		}
 	} else {
-		if (skinnydebug)
-			ast_verb(1, "No owner: %s\n", l->name);
+		ast_log(LOG_WARNING, "Got digit on %s, but not associated with channel\n", l->name);
 	}
 	return 1;
 }
@@ -5693,9 +5693,7 @@
 
 	event = letohl(req->data.stimulus.stimulus);
 	instance = letohl(req->data.stimulus.stimulusInstance);
-	callreference = letohl(req->data.stimulus.callreference); 
-	if (skinnydebug)

[... 822 lines stripped ...]



More information about the svn-commits mailing list