/* * Asterisk -- An open source telephony toolkit. * * Copyright (C) 2013, Digium, Inc. * * Mark Michelson * * 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 pjproject res_pjsip yes core ***/ #include "asterisk.h" #include /* For IPPROTO_UDP and in6_addr */ #include #include "asterisk/res_pjsip.h" #include "asterisk/vector.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 */ }; struct method_logging_info { pj_str_t pj_name; /*! \brief A PJSIP string for the method */ pjsip_method method; /*! \brief The PJSIP method structure used for comparisons */ char name[]; /*! \brief The method name */ }; /*! \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 Vector of SIP methods to log */ AST_VECTOR(, struct method_logging_info *) log_methods; }; /*! \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); AST_VECTOR_RESET(&session->log_methods, ast_free); AST_VECTOR_FREE(&session->log_methods); } /*! \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; AST_VECTOR_INIT(&session->log_methods, 0); return session; } /*! \note Must be called with the pjsip_logger_session lock held */ static int apply_method_filter(const struct pjsip_logger_session *session, const pjsip_method *method) { size_t size = AST_VECTOR_SIZE(&session->log_methods); size_t i; if (size == 0) { /* Nothing in the vector means everything matches */ return 0; } for (i = 0; i < size; ++i) { struct method_logging_info *candidate = AST_VECTOR_GET(&session->log_methods, i); if (pjsip_method_cmp(&candidate->method, method) == 0) { return 0; } } /* Nothing matched */ return 1; } /*! \brief See if we pass debug filter */ static inline int pjsip_log_test_filter(const struct pjsip_logger_session *session, const char *address, int port, const pjsip_method *method) { struct ast_sockaddr test_addr; if (!session->enabled) { return 0; } if (session->log_all_traffic) { return 1; } if (apply_method_filter(session, method)) { /* The method filter didn't match anything, so reject. */ return 0; } /* A null address was passed in or no explicit matches. Just reject it. */ if (ast_strlen_zero(address) || !session->matches) { /* If we matched on method and host is empty, accept, otherwise reject. */ return AST_VECTOR_SIZE(&session->log_methods) > 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_filter(default_logger, tdata->tp_info.dst_name, tdata->tp_info.dst_port, &tdata->msg->line.req.method)) { 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_filter(default_logger, rdata->pkt_info.src_name, rdata->pkt_info.src_port, &rdata->msg_info.msg->line.req.method)) { 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 struct method_logging_info *method_logging_info_alloc(const char *method) { size_t method_bytes = strlen(method); struct method_logging_info *info; info = ast_calloc(1, sizeof(struct method_logging_info) + method_bytes + 1); if (!info) { return NULL; } memcpy(info->name, method, method_bytes + 1); pj_strset(&info->pj_name, info->name, method_bytes); pjsip_method_init_np(&info->method, &info->pj_name); return info; } static int method_logging_info_cmp(const struct method_logging_info *element, const struct method_logging_info *candidate) { return pjsip_method_cmp(&element->method, &candidate->method) == 0 ? CMP_MATCH | CMP_STOP : 0; } static int method_logging_info_sort_cmp(const void *a, const void *b) { const struct method_logging_info *const *m_a = a; const struct method_logging_info *const *m_b = b; return strcasecmp((*m_a)->name, (*m_b)->name); } /*! \brief Add the current or an additional method to match for filtering */ static char *pjsip_enable_logger_method(int fd, const char *arg, int add_method) { struct ast_str *str; struct method_logging_info *method; method = method_logging_info_alloc(arg); if (!method) { return CLI_FAILURE; } ao2_wrlock(default_logger); default_logger->enabled = 1; if (!add_method) { /* Remove what already exists */ AST_VECTOR_RESET(&default_logger->log_methods, ast_free); } /* Already in the list? */ if (AST_VECTOR_CALLBACK(&default_logger->log_methods, method_logging_info_cmp, NULL, method) != NULL) { ast_cli(fd, "Method '%s' is already enabled\n", method->name); ao2_unlock(default_logger); ast_free(method); return CLI_SUCCESS; } if (AST_VECTOR_APPEND(&default_logger->log_methods, method)) { ast_log(LOG_ERROR, "Cannot register logger method '%s'. Unable to append.\n", method->name); ao2_unlock(default_logger); ast_free(method); return CLI_SUCCESS; } AST_VECTOR_SORT(&default_logger->log_methods, method_logging_info_sort_cmp); str = ast_str_create(256); if (str) { size_t i; for (i = 0; i < AST_VECTOR_SIZE(&default_logger->log_methods); i++) { method = AST_VECTOR_GET(&default_logger->log_methods, i); ast_str_append(&str, 0, "%s%.*s", ast_str_strlen(str) ? ", " : "", (int) method->pj_name.slen, method->pj_name.ptr); } ast_cli(fd, "PJSIP Logging Enabled for SIP Methods: %s\n", ast_str_buffer(str)); ast_free(str); } ao2_unlock(default_logger); 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; AST_VECTOR_RESET(&default_logger->log_methods, ast_free); /* 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) { static const char * const method_choices[] = { "INVITE", "CANCEL", "ACK", "BYE", "REGISTER", "OPTION", "SUBSCRIBE", "NOTIFY", "PUBLISH", "INFO", "MESSAGE", NULL }; const char *what; if (cmd == CLI_INIT) { e->command = "pjsip set logger {on|off|host|add|method|methodadd|verbose|pcap}"; e->usage = "Usage: pjsip set logger {on|off|host |add |method |methodadd |verbose |pcap }\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 or particular SIP method(s).\n" " Messages can be filtered by SIP request methods\n" " INVITE, CANCEL, ACK, BYE, REGISTER, OPTION\n" " SUBSCRIBE, NOTIFY, PUBLISH, INFO, and MESSAGE\n"; return NULL; } else if (cmd == CLI_GENERATE) { if (a->argc && !strncasecmp(a->argv[e->args - 1], "method", 6)) { return ast_cli_complete(a->word, method_choices, a->n); } 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, "method")) { return pjsip_enable_logger_method(a->fd, a->argv[e->args], 0); } else if (!strcasecmp(what, "methodadd")) { return pjsip_enable_logger_method(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", );