[svn-commits] wedhorn: branch wedhorn/skinny-session r391061 - /team/wedhorn/skinny-session...

[SVN commits to the Digium repositories]

Author: wedhorn
Date: Sun Jun  9 17:54:36 2013
New Revision: 391061

URL: http://svnview.digium.com/svn/asterisk?view=rev&rev=391061
Log:
skinny: keepalive debug messages

Modified:
    team/wedhorn/skinny-session/channels/chan_skinny.c

Modified: team/wedhorn/skinny-session/channels/chan_skinny.c
URL: http://svnview.digium.com/svn/asterisk/team/wedhorn/skinny-session/channels/chan_skinny.c?view=diff&rev=391061&r1=391060&r2=391061
==============================================================================
--- team/wedhorn/skinny-session/channels/chan_skinny.c (original)
+++ team/wedhorn/skinny-session/channels/chan_skinny.c Sun Jun  9 17:54:36 2013
@@ -153,6 +153,7 @@
 #define DEBUG_TEMPLATE	(1 << 6)
 #define DEBUG_THREAD	(1 << 7)
 #define DEBUG_HINT	(1 << 8)
+#define DEBUG_KEEPALIVE (1 << 9)
 #define SKINNY_DEBUG(type, verb_level, text, ...)						\
 	do{											\
 		if (skinnydebug & (type)) {							\
@@ -1617,6 +1618,7 @@
 	int auth_timeout_sched;
 	int keepalive_timeout_sched;
 	struct timeval last_keepalive;
+	int keepalive_count;
 };
 
 static struct ast_channel *skinny_request(const char *type, struct ast_format_cap *cap, const struct ast_channel *requestor, const char *dest, int *cause);
@@ -3704,6 +3706,11 @@
 		posn += 5;
 		ptr += 5;
 	}
+	if (skinnydebug & DEBUG_KEEPALIVE) {
+		strncpy(ptr, "keepalive ", 10);
+		posn += 10;
+		ptr += 10;
+	}
 	if (posn > 0) {
 		strncpy(--ptr, "\0", 1);
 	}
@@ -3712,7 +3719,7 @@
 
 static char *complete_skinny_debug(const char *line, const char *word, int pos, int state)
 {
-	const char *debugOpts[]={ "all","audio","hint","lock","off","packet","show","sub","template","thread",NULL };
+	const char *debugOpts[]={ "all","audio","hint","keepalive","lock","off","packet","show","sub","template","thread",NULL };
 	char *wordptr = (char *)word;
 	char buf[32];
 	char *bufptr = buf;
@@ -3752,7 +3759,7 @@
 	case CLI_INIT:
 		e->command = "skinny debug";
 		e->usage =
-			"Usage: skinny debug {audio|hint|lock|off|packet|show|sub|template|thread}\n"
+			"Usage: skinny debug {audio|hint|keepalive|lock|off|packet|show|sub|template|thread}\n"
 			"       Enables/Disables various Skinny debugging messages\n";
 		return NULL;
 	case CLI_GENERATE:
@@ -3778,7 +3785,7 @@
 		}
 
 		if (!strncasecmp(arg, "all", 3)) {
-			skinnydebug = DEBUG_GENERAL|DEBUG_SUB|DEBUG_PACKET|DEBUG_AUDIO|DEBUG_LOCK|DEBUG_TEMPLATE|DEBUG_THREAD|DEBUG_HINT;
+			skinnydebug = DEBUG_GENERAL|DEBUG_SUB|DEBUG_PACKET|DEBUG_AUDIO|DEBUG_LOCK|DEBUG_TEMPLATE|DEBUG_THREAD|DEBUG_HINT|DEBUG_KEEPALIVE;
 			continue;
 		}
 
@@ -3808,6 +3815,8 @@
 			bitmask = DEBUG_THREAD;
 		} else if (!strncasecmp(arg, "hint", 4)) {
 			bitmask = DEBUG_HINT;
+		} else if (!strncasecmp(arg, "keepalive", 9)) {
+			bitmask = DEBUG_KEEPALIVE;
 		} else {
 			ast_cli(a->fd, "Skinny Debugging - option '%s' unknown\n", a->argv[i]);
 			result--;
@@ -6165,12 +6174,19 @@
 	if (ast_sched_del(sched, s->keepalive_timeout_sched)) {
 		return;
 	}
-	
-	if (ast_tvzero(s->last_keepalive)) {
-		SKINNY_DEBUG(DEBUG_PACKET, 3, "Received first keep_alive after %ldms\n", (long) ast_tvdiff_ms(ast_tvnow(), s->start));
-	} else {
-		SKINNY_DEBUG(DEBUG_PACKET, 3, "Received keep_alive %ldms\n", (long) ast_tvdiff_ms(ast_tvnow(), ast_tvadd(s->last_keepalive, ast_tv(keep_alive, 0))));
-	}
+
+#ifdef AST_DEVMODE
+	{
+		long keepalive_diff;
+		keepalive_diff = (long) ast_tvdiff_ms(ast_tvnow(), ast_tvadd(s->last_keepalive, ast_tv(keep_alive, 0)));
+		SKINNY_DEBUG(DEBUG_PACKET|DEBUG_KEEPALIVE, 3,
+			"Keep_alive %d on %s, %.3fs %s\n",
+				++s->keepalive_count,
+				(s->device ? s->device->name : "unregistered"),
+				(float) labs(keepalive_diff) / 1000,
+				(keepalive_diff > 0 ? "late" : "early"));
+	}
+#endif
 
 	s->keepalive_timeout_sched = ast_sched_add(sched, keep_alive*3000, skinny_nokeepalive_cb, s);
 	s->last_keepalive = ast_tvnow();
@@ -7441,6 +7457,8 @@
 	pthread_cleanup_push(skinny_session_cleanup, s);
 
 	s->start = ast_tvnow();
+	s->last_keepalive = ast_tvnow();
+	s->keepalive_count = 0;
 
 	ast_mutex_init(&s->lock);
 	s->lockstate = 0;