res_pjsip_logger.c

/*
 * Asterisk -- An open source telephony toolkit.
 *
 * Copyright (C) 2013, Digium, Inc.
 *
 * Mark Michelson <mmichelson@digium.com>
 *
 * See http://www.asterisk.org for more information about
 * the Asterisk project. Please do not directly contact
 * any of the maintainers of this project for assistance;
 * the project provides a web site, mailing lists and IRC
 * channels for your use.
 *
 * This program is free software, distributed under the terms of
 * the GNU General Public License Version 2. See the LICENSE file
 * at the top of the source tree.
 */

/*** MODULEINFO
	<depend>pjproject</depend>
	<depend>res_pjsip</depend>
	<defaultenabled>yes</defaultenabled>
	<support_level>core</support_level>
 ***/

#include "asterisk.h"

#include <netinet/in.h>	/* For IPPROTO_UDP and in6_addr */

#include <pjsip.h>

#include "asterisk/res_pjsip.h"
#include "asterisk/module.h"
#include "asterisk/logger.h"
#include "asterisk/cli.h"
#include "asterisk/netsock2.h"
#include "asterisk/acl.h"

/*! \brief PCAP Header */
struct pcap_header {
	uint32_t magic_number; 	/*! \brief PCAP file format magic number */
	uint16_t version_major;	/*! \brief Major version number of the file format */
	uint16_t version_minor;	/*! \brief Minor version number of the file format */
	int32_t thiszone;	/*! \brief GMT to local correction */
	uint32_t sigfigs;	/*! \brief Accuracy of timestamps */
	uint32_t snaplen;	/*! \brief The maximum size that can be recorded in the file */
	uint32_t network;	/*! \brief Type of packets held within the file */
};

/*! \brief PCAP Packet Record Header */
struct pcap_record_header {
	uint32_t ts_sec;	/*! \brief When the record was created */
	uint32_t ts_usec;	/*! \brief When the record was created */
	uint32_t incl_len;	/*! \brief Length of packet as saved in the file */
	uint32_t orig_len;	/*! \brief Length of packet as sent over network */
};

/*! \brief PCAP Ethernet Header */
struct pcap_ethernet_header {
	uint8_t dst[6];	/*! \brief Destination MAC address */
	uint8_t src[6];	/*! \brief Source MAD address */
	uint16_t type;	/*! \brief The type of packet contained within */
} __attribute__((__packed__));

/*! \brief PCAP IPv4 Header */
struct pcap_ipv4_header {
	uint8_t ver_ihl;	/*! \brief IP header version and other bits */
	uint8_t ip_tos;		/*! \brief Type of service details */
	uint16_t ip_len;	/*! \brief Total length of the packet (including IPv4 header) */
	uint16_t ip_id;		/*! \brief Identification value */
	uint16_t ip_off;	/*! \brief Fragment offset */
	uint8_t ip_ttl;		/*! \brief Time to live for the packet */
	uint8_t ip_protocol;	/*! \brief Protocol of the data held within the packet (always UDP) */
	uint16_t ip_sum;	/*! \brief Checksum (not calculated for our purposes */
	uint32_t ip_src;	/*! \brief Source IP address */
	uint32_t ip_dst;	/*! \brief Destination IP address */
};

/*! \brief PCAP IPv6 Header */
struct pcap_ipv6_header {
   union {
      struct ip6_hdrctl {
         uint32_t ip6_un1_flow; /*! \brief Version, traffic class, flow label */
         uint16_t ip6_un1_plen; /*! \brief Length of the packet (not including IPv6 header) */
         uint8_t ip6_un1_nxt; 	/*! \brief Next header field */
         uint8_t ip6_un1_hlim;	/*! \brief Hop Limit */
      } ip6_un1;
      uint8_t ip6_un2_vfc;	/*! \brief Version, traffic class */
   } ip6_ctlun;
   struct in6_addr ip6_src; /*! \brief Source IP address */
   struct in6_addr ip6_dst; /*! \brief Destination IP address */
};

/*! \brief PCAP UDP Header */
struct pcap_udp_header {
	uint16_t src;		/*! \brief Source IP port */
	uint16_t dst;		/*! \brief Destination IP port */
	uint16_t length;	/*! \brief Length of the UDP header plus UDP packet */
	uint16_t checksum;	/*! \brief Packet checksum, left uncalculated for our purposes */
};

/*! \brief PJSIP Logging Session */
struct pjsip_logger_session {
	/*! \brief Explicit addresses or ranges being logged */
	struct ast_ha *matches;
	/*! \brief Filename used for the pcap file */
	char pcap_filename[PATH_MAX];
	/*! \brief The pcap file itself */
	FILE *pcap_file;
	/*! \brief Whether the session is enabled or not */
	unsigned int enabled:1;
	/*! \brief Whether the session is logging all traffic or not */
	unsigned int log_all_traffic:1;
	/*! \brief Whether to log to verbose or not */
	unsigned int log_to_verbose:1;
	/*! \brief Whether to log to pcap or not */
	unsigned int log_to_pcap:1;
};

/*! \brief The default logger session */
static struct pjsip_logger_session *default_logger;

/*! \brief Destructor for logger session */
static void pjsip_logger_session_destroy(void *obj)
{
	struct pjsip_logger_session *session = obj;

	if (session->pcap_file) {
		fclose(session->pcap_file);
	}

	ast_free_ha(session->matches);
}

/*! \brief Allocator for logger session */
static struct pjsip_logger_session *pjsip_logger_session_alloc(void)
{
	struct pjsip_logger_session *session;

	session = ao2_alloc_options(sizeof(struct pjsip_logger_session), pjsip_logger_session_destroy,
		AO2_ALLOC_OPT_LOCK_RWLOCK);
	if (!session) {
		return NULL;
	}

	session->log_to_verbose = 1;

	return session;
}

/*! \brief See if we pass debug IP filter */
static inline int pjsip_log_test_addr(const struct pjsip_logger_session *session, const char *address, int port)
{
	struct ast_sockaddr test_addr;

	if (!session->enabled) {
		return 0;
	}

	if (session->log_all_traffic) {
		return 1;
	}

	/* A null address was passed in or no explicit matches. Just reject it. */
	if (ast_strlen_zero(address) || !session->matches) {
		return 0;
	}

	ast_sockaddr_parse(&test_addr, address, PARSE_PORT_IGNORE);
	ast_sockaddr_set_port(&test_addr, port);

	/* Compare the address against the matches */
	if (ast_apply_ha(session->matches, &test_addr) != AST_SENSE_ALLOW) {
		return 1;
	} else {
		return 0;
	}
}

static void pjsip_logger_write_to_pcap(struct pjsip_logger_session *session, const char *msg, size_t msg_len,
	pj_sockaddr *source, pj_sockaddr *destination)
{
	struct timeval now = ast_tvnow();
	struct pcap_record_header pcap_record_header = {
		.ts_sec = now.tv_sec,
		.ts_usec = now.tv_usec,
	};
	struct pcap_ethernet_header pcap_ethernet_header = {
		.type = 0,
	};
	struct pcap_ipv4_header pcap_ipv4_header = {
		.ver_ihl = 0x45, /* IPv4 + 20 bytes of header */
		.ip_ttl = 128, /* We always put a TTL of 128 to keep Wireshark less blue */
	};
	struct pcap_ipv6_header pcap_ipv6_header = {
		.ip6_ctlun.ip6_un2_vfc = 0x60,
	};
	void *pcap_ip_header;
	size_t pcap_ip_header_len;
	struct pcap_udp_header pcap_udp_header;

	/* Packets are always stored as UDP to simplify this logic */
	if (source) {
		pcap_udp_header.src = ntohs(pj_sockaddr_get_port(source));
	} else {
		pcap_udp_header.src = ntohs(0);
	}
	if (destination) {
		pcap_udp_header.dst = ntohs(pj_sockaddr_get_port(destination));
	} else {
		pcap_udp_header.dst = ntohs(0);
	}
	pcap_udp_header.length = ntohs(sizeof(struct pcap_udp_header) + msg_len);

	/* Construct the appropriate IP header */
	if ((source && source->addr.sa_family == pj_AF_INET()) ||
		(destination && destination->addr.sa_family == pj_AF_INET())) {
		pcap_ethernet_header.type = htons(0x0800); /* We are providing an IPv4 packet */
		pcap_ip_header = &pcap_ipv4_header;
		pcap_ip_header_len = sizeof(struct pcap_ipv4_header);
		if (source) {
			memcpy(&pcap_ipv4_header.ip_src, pj_sockaddr_get_addr(source), pj_sockaddr_get_addr_len(source));
		}
		if (destination) {
			memcpy(&pcap_ipv4_header.ip_dst, pj_sockaddr_get_addr(destination), pj_sockaddr_get_addr_len(destination));
		}
		pcap_ipv4_header.ip_len = htons(sizeof(struct pcap_udp_header) + sizeof(struct pcap_ipv4_header) + msg_len);
		pcap_ipv4_header.ip_protocol = IPPROTO_UDP; /* We always provide UDP */
	} else {
		pcap_ethernet_header.type = htons(0x86DD); /* We are providing an IPv6 packet */
		pcap_ip_header = &pcap_ipv6_header;
		pcap_ip_header_len = sizeof(struct pcap_ipv6_header);
		if (source) {
			memcpy(&pcap_ipv6_header.ip6_src, pj_sockaddr_get_addr(source), pj_sockaddr_get_addr_len(source));
		}
		if (destination) {
			memcpy(&pcap_ipv6_header.ip6_dst, pj_sockaddr_get_addr(destination), pj_sockaddr_get_addr_len(destination));
		}
		pcap_ipv6_header.ip6_ctlun.ip6_un1.ip6_un1_plen = htons(sizeof(struct pcap_udp_header) + msg_len);
		pcap_ipv6_header.ip6_ctlun.ip6_un1.ip6_un1_nxt = IPPROTO_UDP;
	}

	/* Add up all the sizes for this record */
	pcap_record_header.incl_len = pcap_record_header.orig_len = sizeof(pcap_ethernet_header) + pcap_ip_header_len + sizeof(pcap_udp_header) + msg_len;

	/* We lock the logger session since we're writing these out in parts */
	ao2_wrlock(session);
	if (session->pcap_file) {
		if (fwrite(&pcap_record_header, sizeof(struct pcap_record_header), 1, session->pcap_file) != 1) {
			ast_log(LOG_WARNING, "Writing PCAP header failed: %s\n", strerror(errno));
		}
		if (fwrite(&pcap_ethernet_header, sizeof(struct pcap_ethernet_header), 1, session->pcap_file) != 1) {
			ast_log(LOG_WARNING, "Writing ethernet header to pcap failed: %s\n", strerror(errno));
		}
		if (fwrite(pcap_ip_header, pcap_ip_header_len, 1, session->pcap_file) != 1) {
			ast_log(LOG_WARNING, "Writing IP header to pcap failed: %s\n", strerror(errno));
		}
		if (fwrite(&pcap_udp_header, sizeof(struct pcap_udp_header), 1, session->pcap_file) != 1) {
			ast_log(LOG_WARNING, "Writing UDP header to pcap failed: %s\n", strerror(errno));
		}
		if (fwrite(msg, msg_len, 1, session->pcap_file) != 1) {
			ast_log(LOG_WARNING, "Writing UDP payload to pcap failed: %s\n", strerror(errno));
		}
	}
	ao2_unlock(session);
}

static pj_status_t logging_on_tx_msg(pjsip_tx_data *tdata)
{
	char buffer[AST_SOCKADDR_BUFLEN];

	ao2_rdlock(default_logger);
	if (!pjsip_log_test_addr(default_logger, tdata->tp_info.dst_name, tdata->tp_info.dst_port)) {
		ao2_unlock(default_logger);
		return PJ_SUCCESS;
	}
	ao2_unlock(default_logger);

	if (default_logger->log_to_verbose) {
		ast_verbose("<--- Transmitting SIP %s (%d bytes) to %s:%s --->\n%.*s\n",
			tdata->msg->type == PJSIP_REQUEST_MSG ? "request" : "response",
			(int) (tdata->buf.cur - tdata->buf.start),
			tdata->tp_info.transport->type_name,
			pj_sockaddr_print(&tdata->tp_info.dst_addr, buffer, sizeof(buffer), 3),
			(int) (tdata->buf.end - tdata->buf.start), tdata->buf.start);
	}

	if (default_logger->log_to_pcap) {
		pjsip_logger_write_to_pcap(default_logger, tdata->buf.start, (int) (tdata->buf.end - tdata->buf.start),
			NULL, &tdata->tp_info.dst_addr);
	}

	return PJ_SUCCESS;
}

static pj_bool_t logging_on_rx_msg(pjsip_rx_data *rdata)
{
	char buffer[AST_SOCKADDR_BUFLEN];

	if (!rdata->msg_info.msg) {
		return PJ_FALSE;
	}

	ao2_rdlock(default_logger);
	if (!pjsip_log_test_addr(default_logger, rdata->pkt_info.src_name, rdata->pkt_info.src_port)) {
		ao2_unlock(default_logger);
		return PJ_FALSE;
	}
	ao2_unlock(default_logger);

	if (default_logger->log_to_verbose) {
		ast_verbose("<--- Received SIP %s (%d bytes) from %s:%s --->\n%s\n",
			rdata->msg_info.msg->type == PJSIP_REQUEST_MSG ? "request" : "response",
			rdata->msg_info.len,
			rdata->tp_info.transport->type_name,
			pj_sockaddr_print(&rdata->pkt_info.src_addr, buffer, sizeof(buffer), 3),
			rdata->pkt_info.packet);
	}

	if (default_logger->log_to_pcap) {
		pjsip_logger_write_to_pcap(default_logger, rdata->pkt_info.packet, rdata->msg_info.len,
			&rdata->pkt_info.src_addr, NULL);
	}

	return PJ_FALSE;
}

static pjsip_module logging_module = {
	.name = { "Logging Module", 14 },
	.priority = 0,
	.on_rx_request = logging_on_rx_msg,
	.on_rx_response = logging_on_rx_msg,
	.on_tx_request = logging_on_tx_msg,
	.on_tx_response = logging_on_tx_msg,
};

static char *pjsip_enable_logger_all(int fd)
{
	ao2_wrlock(default_logger);
	default_logger->enabled = 1;
	default_logger->log_all_traffic = 1;
	ao2_unlock(default_logger);

	if (fd >= 0) {
		ast_cli(fd, "PJSIP Logging enabled\n");
	}

	return CLI_SUCCESS;
}

static char *pjsip_enable_logger_host(int fd, const char *arg, unsigned int add_host)
{
	const char *host = arg;
	char *mask;
	struct ast_sockaddr address;
	int error = 0;

	ao2_wrlock(default_logger);
	default_logger->enabled = 1;

	if (!add_host) {
		/* If this is not adding an additional host or subnet then we have to
		 * remove what already exists.
		 */
		ast_free_ha(default_logger->matches);
		default_logger->matches = NULL;
	}

	mask = strrchr(host, '/');
	if (!mask && !ast_sockaddr_parse(&address, arg, 0)) {
		if (ast_sockaddr_resolve_first_af(&address, arg, 0, AST_AF_UNSPEC)) {
			ao2_unlock(default_logger);
			return CLI_SHOWUSAGE;
		}
		host = ast_sockaddr_stringify(&address);
	}

	default_logger->matches = ast_append_ha_with_port("d", host, default_logger->matches, &error);
	if (!default_logger->matches || error) {
		if (fd >= 0) {
			ast_cli(fd, "Failed to add address '%s' for logging\n", host);
		}
		ao2_unlock(default_logger);
		return CLI_SUCCESS;
	}

	ao2_unlock(default_logger);

	if (fd >= 0) {
		ast_cli(fd, "PJSIP Logging Enabled for host: %s\n", ast_sockaddr_stringify_addr(&address));
	}

	return CLI_SUCCESS;
}

static char *pjsip_disable_logger(int fd)
{
	ao2_wrlock(default_logger);

	/* Default the settings back to the way they were */
	default_logger->enabled = 0;
	default_logger->log_all_traffic = 0;
	default_logger->pcap_filename[0] = '\0';
	default_logger->log_to_verbose = 1;
	default_logger->log_to_pcap = 0;

	/* Stop logging to the PCAP file if active */
	if (default_logger->pcap_file) {
		fclose(default_logger->pcap_file);
		default_logger->pcap_file = NULL;
	}

	ast_free_ha(default_logger->matches);
	default_logger->matches = NULL;

	ao2_unlock(default_logger);

	if (fd >= 0) {
		ast_cli(fd, "PJSIP Logging disabled\n");
	}

	return CLI_SUCCESS;
}

static char *pjsip_set_logger_verbose(int fd, const char *arg)
{
	ao2_wrlock(default_logger);
	default_logger->log_to_verbose = ast_true(arg);
	ao2_unlock(default_logger);

	ast_cli(fd, "PJSIP Logging to verbose has been %s\n", ast_true(arg) ? "enabled" : "disabled");

	return CLI_SUCCESS;
}

static char *pjsip_set_logger_pcap(int fd, const char *arg)
{
	struct pcap_header pcap_header = {
		.magic_number = 0xa1b2c3d4,
		.version_major = 2,
		.version_minor = 4,
		.snaplen = 65535,
		.network = 1, /* We always use ethernet so we can combine IPv4 and IPv6 in same pcap */
	};

	ao2_wrlock(default_logger);
	ast_copy_string(default_logger->pcap_filename, arg, sizeof(default_logger->pcap_filename));

	if (default_logger->pcap_file) {
		fclose(default_logger->pcap_file);
		default_logger->pcap_file = NULL;
	}

	default_logger->pcap_file = fopen(arg, "wb");
	if (!default_logger->pcap_file) {
		ao2_unlock(default_logger);
		ast_cli(fd, "Failed to open file '%s' for pcap writing\n", arg);
		return CLI_SUCCESS;
	}
	fwrite(&pcap_header, 1, sizeof(struct pcap_header), default_logger->pcap_file);

	default_logger->log_to_pcap = 1;
	ao2_unlock(default_logger);

	ast_cli(fd, "PJSIP logging to pcap file '%s'\n", arg);

	return CLI_SUCCESS;
}

static char *pjsip_set_logger(struct ast_cli_entry *e, int cmd, struct ast_cli_args *a)
{
	const char *what;

	if (cmd == CLI_INIT) {
		e->command = "pjsip set logger {on|off|host|add|verbose|pcap}";
		e->usage =
			"Usage: pjsip set logger {on|off|host <name/subnet>|add <name/subnet>|verbose <on/off>|pcap <filename>}\n"
			"       Enables or disabling logging of SIP packets\n"
			"       read on ports bound to PJSIP transports either\n"
			"       globally or enables logging for an individual\n"
			"       host.\n";
		return NULL;
	} else if (cmd == CLI_GENERATE) {
		return NULL;
	}

	what = a->argv[e->args - 1];     /* Guaranteed to exist */

	if (a->argc == e->args) {        /* on/off */
		if (!strcasecmp(what, "on")) {
			return pjsip_enable_logger_all(a->fd);
		} else if (!strcasecmp(what, "off")) {
			return pjsip_disable_logger(a->fd);
		}
	} else if (a->argc == e->args + 1) {
		if (!strcasecmp(what, "host")) {
			return pjsip_enable_logger_host(a->fd, a->argv[e->args], 0);
		} else if (!strcasecmp(what, "add")) {
			return pjsip_enable_logger_host(a->fd, a->argv[e->args], 1);
		} else if (!strcasecmp(what, "verbose")) {
			return pjsip_set_logger_verbose(a->fd, a->argv[e->args]);
		} else if (!strcasecmp(what, "pcap")) {
			return pjsip_set_logger_pcap(a->fd, a->argv[e->args]);
		}
	}

	return CLI_SHOWUSAGE;
}

static struct ast_cli_entry cli_pjsip[] = {
	AST_CLI_DEFINE(pjsip_set_logger, "Enable/Disable PJSIP Logger Output")
};

static void check_debug(void)
{
	RAII_VAR(char *, debug, ast_sip_get_debug(), ast_free);

	if (ast_false(debug)) {
		pjsip_disable_logger(-1);
		return;
	}

	if (ast_true(debug)) {
		pjsip_enable_logger_all(-1);
		return;
	}

	if (pjsip_enable_logger_host(-1, debug, 0) != CLI_SUCCESS) {
		ast_log(LOG_WARNING, "Could not resolve host %s for debug "
			"logging\n", debug);
	}
}

static void global_reloaded(const char *object_type)
{
	check_debug();
}

static const struct ast_sorcery_observer global_observer = {
	.loaded = global_reloaded
};

static int load_module(void)
{
	if (ast_sorcery_observer_add(ast_sip_get_sorcery(), "global", &global_observer)) {
		ast_log(LOG_WARNING, "Unable to add global observer\n");
		return AST_MODULE_LOAD_DECLINE;
	}

	default_logger = pjsip_logger_session_alloc();
	if (!default_logger) {
		ast_sorcery_observer_remove(
			ast_sip_get_sorcery(), "global", &global_observer);
		ast_log(LOG_WARNING, "Unable to create default logger\n");
		return AST_MODULE_LOAD_DECLINE;
	}

	check_debug();

	ast_sip_register_service(&logging_module);
	ast_cli_register_multiple(cli_pjsip, ARRAY_LEN(cli_pjsip));

	return AST_MODULE_LOAD_SUCCESS;
}

static int unload_module(void)
{
	ast_cli_unregister_multiple(cli_pjsip, ARRAY_LEN(cli_pjsip));
	ast_sip_unregister_service(&logging_module);

	ast_sorcery_observer_remove(
		ast_sip_get_sorcery(), "global", &global_observer);

	ao2_cleanup(default_logger);
	default_logger = NULL;

	return 0;
}

AST_MODULE_INFO(ASTERISK_GPL_KEY, AST_MODFLAG_LOAD_ORDER, "PJSIP Packet Logger",
	.support_level = AST_MODULE_SUPPORT_CORE,
	.load = load_module,
	.unload = unload_module,
	.load_pri = AST_MODPRI_APP_DEPEND,
	.requires = "res_pjsip",
);