2 * A Simple SIP Logging Plugin for ulogd
4 * (c) 2008 Martin Mares <mj@ucw.cz>
15 #include <ulogd/ulogd.h>
16 #include <ulogd/conffile.h>
18 typedef unsigned char byte;
19 typedef unsigned int uns;
21 /*** Configuration ***/
23 static config_entry_t sip_cf_mail_to = {
26 .type = CONFIG_TYPE_STRING,
27 .options = CONFIG_OPT_NONE,
31 static config_entry_t sip_cf_debug_log = {
32 .next = &sip_cf_mail_to,
34 .type = CONFIG_TYPE_STRING,
35 .options = CONFIG_OPT_NONE,
39 static config_entry_t sip_cf_log = {
40 .next = &sip_cf_debug_log,
42 .type = CONFIG_TYPE_STRING,
43 .options = CONFIG_OPT_NONE,
44 .u.string = "/var/log/ulog/sip.log"
47 /*** Unaligned access ***/
49 static uns get_u16(byte *p)
51 return (p[0] << 8) | p[1];
54 static uns get_u32(byte *p)
56 return (p[0] << 24) | (p[1] << 16) | (p[2] << 8) | p[3];
67 { "oob.time.sec", 0 },
68 { "oob.time.usec", 0 },
80 static int init_keys(void)
82 for (uns i=0; i < sizeof(keys)/sizeof(keys[0]); i++)
83 if (!(keys[i].id = keyh_getid(keys[i].name)))
85 ulogd_log(ULOGD_ERROR, "SIP: Unable to resolve key %s\n", keys[i].name);
91 #define KEY_H(i) ulogd_keyh[keys[i].id].interp->result[ulogd_keyh[keys[i].id].offset]
92 #define KEY_VAL(i) KEY_H(i).value
93 #define KEY_FLAGS(i) KEY_H(i).flags
94 #define KEY_TYPE(i) KEY_H(i).type
95 #define KEY_OK(i,t) ((KEY_FLAGS(i) & ULOGD_RETF_VALID) && KEY_TYPE(i) == ULOGD_RET_##t)
97 /*** Representation of packets ***/
100 time_t time_sec; // Arrival time
103 byte *raw; // Raw packet
106 byte *ip; // Inside IP
108 uns src_addr, dst_addr;
109 byte *udp; // Inside UDP
111 uns src_port, dst_port;
112 char *sip_rr; // Decoded SIP
118 struct call *sip_call;
127 static char *find_hdr(struct pkt *pkt, char *name)
129 for (struct hdr *h=pkt->sip_hdr; h; h=h->next)
130 if (!strcasecmp(h->name, name))
135 static char *find_hdr2(struct pkt *pkt, char *name, char *alt)
137 return find_hdr(pkt, name) ? : find_hdr(pkt, alt);
142 static FILE *siplog, *debuglog;
144 static void debug(char *fmt, ...)
150 fputc('\t', debuglog);
151 vfprintf(debuglog, fmt, args);
152 fputc('\n', debuglog);
156 static int error(struct pkt *pkt, char *fmt, ...)
160 fprintf(siplog, "%s ERR: ", pkt->time);
161 vfprintf(siplog, fmt, args);
167 /*** Auxillary routines ***/
169 static inline int is_white(int c)
171 return (c == ' ' || c == '\t');
174 static char *skip_ws(char *c)
181 static char *skip_nonws(char *c)
183 while (*c && !is_white(*c))
190 #define CALL_ID_LEN 63
209 char call_id[CALL_ID_LEN+1];
210 enum call_state state;
212 char active_seq[CSEQ_LEN+1];
213 char src_party[NUM_LEN+1];
214 char dst_party[NUM_LEN+1];
217 static struct call *call_list;
219 static void log_call(struct pkt *pkt, struct call *c)
221 fprintf(siplog, "%s: CALL %s <%s> -> <%s>", pkt->time, (c->out_p ? "OUT" : "IN"), c->src_party, c->dst_party);
222 if (c->flags & FLAG_ANSWERED)
223 fprintf(siplog, " ANS");
224 else if (c->flags & FLAG_RING)
225 fprintf(siplog, " RING");
226 if (c->flags & FLAG_REDIRECT)
227 fprintf(siplog, " REDIR");
228 if (pkt->sip_status >= 300)
229 fprintf(siplog, " ERR:%s", pkt->sip_msg);
231 fprintf(siplog, " OK");
234 if (sip_cf_mail_to.u.string[0])
237 sprintf(cmd, "mail -s 'SIP CALL' %s", sip_cf_mail_to.u.string);
238 debug("Running %s", cmd);
239 FILE *m = popen(cmd, "w");
242 fprintf(m, "Finished-At: %s\n", pkt->time);
243 fprintf(m, "Direction: %s\n", (c->out_p ? "OUT" : "IN"));
244 fprintf(m, "From: %s\n", c->src_party);
245 fprintf(m, "To: %s\n", c->dst_party);
246 fprintf(m, "Flags:%s%s%s\n",
247 ((c->flags & FLAG_ANSWERED) ? " ANS" : ""),
248 ((c->flags & FLAG_RING) ? " RING" : ""),
249 ((c->flags & FLAG_REDIRECT) ? " REDIR" : ""));
250 fprintf(m, "Status: %s\n", pkt->sip_msg);
254 error(pkt, "Cannot execute `%s': %m", cmd);
258 static void extract_number(char *buf, char *h)
263 // Multiple addresses => use the first one
264 if (c = strchr(h, ','))
266 // Tagged parameters => drop them
267 if (c = strchr(h, ';'))
269 // Quoted part => prefer it
270 if (c = strchr(h, '<'))
273 if (c = strchr(h, '>'))
277 if (c = strchr(h, ':'))
279 // Use only numeric characters, * and #
281 while (d < buf + NUM_LEN)
283 if (*h >= '0' && *h <= '9' || *h == '*')
285 else if (*h == '%' && h[1] == '2' && h[2] == '3')
296 static int parse_request(struct pkt *pkt)
298 struct call *c = pkt->sip_call;
299 if (!strcmp(pkt->sip_seq, c->active_seq))
301 debug("Retransmitted packet");
304 if (!strcasecmp(pkt->sip_method, "INVITE"))
306 if (c->state != CALL_IDLE)
307 return error(pkt, "re-INVITE not supported yet");
308 c->state = CALL_DIALING;
309 c->out_p = pkt->out_p;
310 strcpy(c->active_seq, pkt->sip_seq);
311 extract_number(c->src_party, find_hdr2(pkt, "From", "f"));
312 extract_number(c->dst_party, find_hdr2(pkt, "To", "t"));
314 else if (!strcasecmp(pkt->sip_method, "BYE"))
316 if (c->state != CALL_CONNECTED)
318 c->state = CALL_IDLE;
319 return error(pkt, "Unexpected BYE");
322 strcpy(c->active_seq, pkt->sip_seq);
327 static int parse_reply(struct pkt *pkt)
329 struct call *c = pkt->sip_call;
330 if (strcmp(pkt->sip_seq, c->active_seq))
332 debug("Reply not associated to active request %s", c->active_seq);
336 uns stat = pkt->sip_status;
338 c->active_seq[0] = 0;
340 if (c->state == CALL_DIALING)
346 // Provisional responses
348 c->flags |= FLAG_RING;
353 c->state = CALL_CONNECTED;
354 c->flags |= FLAG_ANSWERED;
359 c->flags |= FLAG_REDIRECT;
361 c->state = CALL_IDLE;
365 // Failure of some sort
369 case 404: // Not found
370 case 403: // Forbidden
371 case 480: // Tmp unavailable
372 case 486: // Busy here
373 case 487: // Cancelled
374 case 600: // Busy everywhere
376 case 604: // Does not exist
377 case 606: // Unaccaptable
380 c->state = CALL_IDLE;
381 // We do not reset flags on failures, because another INVITE may be sent for the same call and we wish to remember redirects etc.
384 else if (c->state == CALL_BYE)
389 c->state = CALL_IDLE;
395 static int parse_call(struct pkt *pkt)
397 char *id = find_hdr2(pkt, "Call-ID", "i");
399 return error(pkt, "Missing Call-ID");
400 char *p = skip_nonws(id);
403 return error(pkt, "Empty Call-ID");
404 if (strlen(id) > CALL_ID_LEN)
405 return error(pkt, "Call-ID too long");
407 pkt->sip_seq = find_hdr(pkt, "CSeq");
409 return error(pkt, "Missing CSeq");
410 if (strlen(pkt->sip_seq) > CSEQ_LEN)
411 return error(pkt, "CSeq too long");
414 for (c=call_list; c && strcasecmp(c->call_id, id); c=c->next)
418 if (!pkt->sip_method)
419 return error(pkt, "Cannot match reply to an existing call");
420 debug("Creating new call <%s>", id);
421 c = malloc(sizeof(struct call));
423 return error(pkt, "Out of memory");
424 memset(c, 0, sizeof(*c));
427 strcpy(c->call_id, id);
428 c->state = CALL_IDLE;
431 debug("Continuing call <%s> in state %d", id, c->state);
433 // FIXME: We should time out the calls
436 return parse_request(pkt);
438 return parse_reply(pkt);
441 static int parse_rr(struct pkt *pkt)
443 char *rr = pkt->sip_rr;
444 if (!strncmp(rr, "SIP/", 4))
447 rr = skip_ws(skip_nonws(rr));
449 return error(pkt, "Truncated SIP response");
451 pkt->sip_status = atol(rr);
452 pkt->sip_method = NULL;
454 debug("SIP status %d (%s)", pkt->sip_status, pkt->sip_msg);
460 pkt->sip_status = -1;
461 pkt->sip_method = rr;
464 return error(pkt, "Missing URI in SIP request");
468 return error(pkt, "Missing URI in SIP request");
472 debug("SIP request %s on %s", pkt->sip_method, pkt->sip_uri);
474 return parse_call(pkt);
477 static int parse_sip(struct pkt *pkt)
479 char *p = (char*) pkt->udp;
480 char *end = p + pkt->udp_len;
484 // Parse the request/reply line first
486 while (p < end && *p != '\r' && *p != '\n')
489 return error(pkt, "Truncated 1st line");
492 if (p < end && *p == '\n')
494 debug(">>> %s", pkt->sip_rr);
496 // Slurp the other header lines and sanitize them
504 return error(pkt, "Truncated SIP headers");
510 if (p < end && is_white(*p) && pkt->sip_rr)
518 else if (*p > 0x20 && *p != 0x7f || *p < 0)
520 else if (is_white(*p))
527 // Got a line, parse it
531 debug(">>> %s", pkt->sip_rr);
534 char *sep = strchr(start, ':');
537 error(pkt, "Malformed header line");
541 for (char *p=sep; p>start && is_white(p[-1]);)
543 while (++sep < end && is_white(*sep))
545 debug("\t%s: %s", start, sep);
546 struct hdr *h = alloca(sizeof(*h));
547 h->next = pkt->sip_hdr;
553 return error(pkt, "Missing SIP header");
555 return parse_rr(pkt);
558 static int parse_udp(struct pkt *pkt)
562 return error(pkt, "Truncated UDP header");
563 pkt->src_port = get_u16(p);
564 pkt->dst_port = get_u16(p+2);
565 uns ulen = get_u16(p+4);
567 return error(pkt, "Invalid UDP length (%d)", ulen);
568 if (ulen > pkt->ip_len)
569 return error(pkt, "Truncated UDP data (have %d, want %d)", pkt->ip_len, ulen);
571 pkt->udp_len = ulen - 8;
572 debug("%08x:%d -> %08x:%d (%d bytes, out_p=%d)", pkt->src_addr, pkt->src_port, pkt->dst_addr, pkt->dst_port, pkt->udp_len, pkt->out_p);
573 return parse_sip(pkt);
576 static int parse_ip(struct pkt *pkt)
579 if (pkt->raw_len < 20)
580 return error(pkt, "Very truncated IP header");
581 uns ipver = p[0] >> 4;
583 return error(pkt, "We don't speak IPv%d", ipver);
584 uns hlen = (p[0] & 0x0f)*4;
585 if (pkt->raw_len < hlen)
586 return error(pkt, "Truncated IP header (want %d)", hlen);
587 uns ilen = get_u16(p+2);
589 return error(pkt, "Invalid IP length (have %d, want at least %d for header)", ilen, hlen);
590 if (ilen > pkt->raw_len)
591 return error(pkt, "Truncated (have %d, want %d)", pkt->raw_len, ilen);
593 return error(pkt, "Not UDP (protocol %02x)", p[9]);
594 if (get_u16(p+6) & 0x3fff)
595 return error(pkt, "Fragmented");
597 pkt->ip_len = ilen - hlen;
598 pkt->src_addr = get_u32(p+12);
599 pkt->dst_addr = get_u32(p+16);
600 return parse_udp(pkt);
603 /*** Interface to ulogd ***/
605 static int sip_output(ulog_iret_t *res __attribute__((unused)))
612 char *prefix = (KEY_OK(K_OOB_PREFIX, STRING) ? KEY_VAL(K_OOB_PREFIX).ptr : "?");
613 if (!strcasecmp(prefix, "phone-in"))
615 else if (!strcasecmp(prefix, "phone-out"))
619 // fprintf(debuglog, "(non-phone packet received, prefix=%s)\n", prefix);
623 if (!KEY_OK(K_RAW_PKT, RAW) ||
624 !KEY_OK(K_RAW_PKTLEN, UINT32) ||
625 !KEY_OK(K_OOB_TIME_SEC, UINT32) ||
626 !KEY_OK(K_OOB_TIME_USEC, UINT32))
628 ulogd_log(ULOGD_ERROR, "SIP: Mandatory keys missing\n");
631 pkt.raw = KEY_VAL(K_RAW_PKT).ptr;
632 pkt.raw_len = KEY_VAL(K_RAW_PKTLEN).ui32;
633 pkt.time_sec = KEY_VAL(K_OOB_TIME_SEC).ui32;
634 pkt.time_usec = KEY_VAL(K_OOB_TIME_USEC).ui32;
635 struct tm *tm = localtime(&pkt.time_sec);
637 sprintf(pkt.time, "<#%d.%06d> ", (int)pkt.time_sec, pkt.time_usec);
639 sprintf(pkt.time, "%04d-%02d-%02d %02d:%02d:%02d.%06d", tm->tm_year+1900, tm->tm_mon+1, tm->tm_mday,
640 tm->tm_hour, tm->tm_min, tm->tm_sec, pkt.time_usec);
642 fprintf(debuglog, "%s\n", pkt.time);
651 /*** Housekeeping ***/
653 static int sip_init(void)
655 if (config_parse_file("SIP", &sip_cf_log))
657 ulogd_log(ULOGD_ERROR, "SIP: Parsing of configuration file failed\n");
660 ulogd_log(ULOGD_INFO, "Initializing SIP plugin, logging to %s\n", sip_cf_debug_log.u.string);
661 siplog = fopen(sip_cf_log.u.string, "a");
664 ulogd_log(ULOGD_ERROR, "Cannot open %s: %s", sip_cf_log.u.string, strerror(errno));
667 if (sip_cf_debug_log.u.string[0])
669 debuglog = fopen(sip_cf_debug_log.u.string, "a");
672 ulogd_log(ULOGD_ERROR, "Cannot open %s: %s", sip_cf_debug_log.u.string, strerror(errno));
679 static void sip_fini(void)
681 // Logging does not work here
682 // ulogd_log(ULOGD_INFO, "siplog fini\n");
685 siplog = debuglog = NULL;
688 static void sip_signal(int sig)
692 // FIXME: Should reopen the log files here
696 static ulog_output_t sip_op = {
700 .output = sip_output,
704 static void __attribute__((constructor)) constr(void)
706 // All logging goes to stderr instead of the log file
707 // ulogd_log(ULOGD_INFO, "Registered siplog plugin\n");
709 register_output(&sip_op);