res_pjsip_logger.c

Go to the documentation of this file.

/*
 * Asterisk -- An open source telephony toolkit.
 *
 * Copyright (C) 2013, Digium, Inc.
 *
 * Mark Michelson <[email protected]>
 *
 * 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.cur - 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",
);