tport_logging.c 6.63 KB
Newer Older
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24
/*
 * This file is part of the Sofia-SIP package
 *
 * Copyright (C) 2006 Nokia Corporation.
 *
 * Contact: Pekka Pessi <pekka.pessi@nokia.com>
 *
 * This library is free software; you can redistribute it and/or
 * modify it under the terms of the GNU Lesser General Public License
 * as published by the Free Software Foundation; either version 2.1 of
 * the License, or (at your option) any later version.
 *
 * This library is distributed in the hope that it will be useful, but
 * WITHOUT ANY WARRANTY; without even the implied warranty of
 * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU
 * Lesser General Public License for more details.
 *
 * You should have received a copy of the GNU Lesser General Public
 * License along with this library; if not, write to the Free Software
 * Foundation, Inc., 51 Franklin St, Fifth Floor, Boston, MA
 * 02110-1301 USA
 *
 */

25
/**@CFILE tport_logging.c Logging transported messages.
26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75
 *
 * See tport.docs for more detailed description of tport interface.
 *
 * @author Pekka Pessi <Pekka.Pessi@nokia.com>
 * @author Martti Mela <Martti.Mela@nokia.com>
 *
 * @date Created: Fri Mar 24 08:45:49 EET 2006 ppessi
 */

#include "config.h"

#include "tport_internal.h"

#include <sofia-sip/string0.h>
#include <stdlib.h>
#include <time.h>
#include <assert.h>
#include <errno.h>
#include <limits.h>

/**@var TPORT_LOG
 *
 * Environment variable determining if parsed message contents are logged.
 *
 * If the TPORT_LOG environment variable is set, the tport module logs the
 * contents of parsed messages. This eases debugging the signaling greatly.
 * 
 * @sa TPORT_DUMP, TPORT_DEBUG, tport_log
 */
extern char const TPORT_LOG[];	/* dummy declaration for Doxygen */

/**@var TPORT_DUMP
 *
 * Environment variable for transport data dump.
 *
 * The received and sent data is dumped to the file specified by TPORT_DUMP
 * environment variable. This can be used to save message traces and help
 * hairy debugging tasks.
 * 
 * @sa TPORT_LOG, TPORT_DEBUG, tport_log
 */
extern char const TPORT_DUMP[];	/* dummy declaration for Doxygen */

/**@var TPORT_DEBUG
 *
 * Environment variable determining the debug log level for @b tport module.
 *
 * The TPORT_DEBUG environment variable is used to determine the debug logging
 * level for @b tport module. The default level is 3.
 * 
Pekka Pessi's avatar
Pekka Pessi committed
76
 * @sa <sofia-sip/su_debug.h>, tport_log, SOFIA_DEBUG
77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92
 */
extern char const TPORT_DEBUG[]; /* dummy declaration for Doxygen */

/**Debug log for @b tport module. 
 * 
 * The tport_log is the log object used by @b tport module. The level of
 * #tport_log is set using #TPORT_DEBUG environment variable.
 */
su_log_t tport_log[] = { 
  SU_LOG_INIT("tport", "TPORT_DEBUG", SU_DEBUG)
};


/** Initialize logging. */
void tport_open_log(tport_master_t *mr, tagi_t *tags)
{
93 94 95 96 97 98 99 100 101 102 103 104 105 106 107 108 109 110
  char const *log = NULL;
  int log_msg = 0;

  tl_gets(tags, TPTAG_LOG_REF(log_msg), TAG_END());

  if (getenv("MSG_STREAM_LOG") != NULL || getenv("TPORT_LOG") != NULL)
    log_msg = 1;

  mr->mr_log = log_msg ? MSG_DO_EXTRACT_COPY : 0;

  tl_gets(tags, TPTAG_DUMP_REF(log), TAG_END());

  if (getenv("MSG_DUMP"))
    log = getenv("MSG_DUMP");
  if (getenv("TPORT_DUMP"))
    log = getenv("TPORT_DUMP");

  if (log) {
111 112 113 114 115 116 117 118 119 120 121 122 123 124 125 126 127
    time_t now;

    if (strcmp(log, "-")) 
      mr->mr_dump_file = fopen(log, "ab"); /* XXX */
    else
      mr->mr_dump_file = stdout;

    if (mr->mr_dump_file) {
      time(&now);
      fprintf(mr->mr_dump_file, "dump started at %s\n\n", ctime(&now));
    }
  }
}

/** Create log stamp */
void tport_stamp(tport_t const *self, msg_t *msg, 
		 char stamp[128], char const *what, 
128
		 size_t n, char const *via,
129 130 131 132 133 134 135 136 137 138 139 140 141 142 143 144 145 146 147 148 149 150 151 152 153
		 su_time_t now)
{
  char label[24] = "";
  char *comp = "";
  char name[SU_ADDRSIZE] = "";
  su_sockaddr_t const *su = msg_addr(msg);
  unsigned short second, minute, hour;

  second = (unsigned short)(now.tv_sec % 60);
  minute = (unsigned short)((now.tv_sec / 60) % 60);
  hour = (unsigned short)((now.tv_sec / 3600) % 24);

#if SU_HAVE_IN6
  if (su->su_family == AF_INET6) {
    if (su->su_sin6.sin6_flowinfo)
      snprintf(label, sizeof(label), "/%u", ntohl(su->su_sin6.sin6_flowinfo));
  }
#endif

  if (msg_addrinfo(msg)->ai_flags & TP_AI_COMPRESSED)
    comp = ";comp=sigcomp";

  inet_ntop(su->su_family, SU_ADDR(su), name, sizeof(name));

  snprintf(stamp, 128,
154
	   "%s "MOD_ZU" bytes %s %s/[%s]:%u%s%s at %02u:%02u:%02u.%06lu:\n",
155
	   what, (size_t)n, via, self->tp_name->tpn_proto,
156 157 158 159 160 161
	   name, ntohs(su->su_port), label[0] ? label : "", comp,
	   hour, minute, second, now.tv_usec);
}

/** Dump the data from the iovec */
void tport_dump_iovec(tport_t const *self, msg_t *msg, 
162
		      size_t n, su_iovec_t const iov[], size_t iovused,
163 164 165 166
		      char const *what, char const *how)
{
  tport_master_t *mr = self->tp_master;
  char stamp[128];
167
  size_t i;
168 169 170 171 172 173 174 175

  if (!mr->mr_dump_file)
    return;

  tport_stamp(self, msg, stamp, what, n, how, su_now());
  fputs(stamp, mr->mr_dump_file);

  for (i = 0; i < iovused && n > 0; i++) {
176
    size_t len = iov[i].mv_len;
177 178
    if (len > n)
      len = n;
179 180
    if (fwrite(iov[i].mv_base, len, 1, mr->mr_dump_file) != len)
      break;
181 182 183 184 185 186 187 188 189 190
    n -= len;
  }

  fputs("\v\n", mr->mr_dump_file);
  fflush(mr->mr_dump_file);
}

/** Log the message. */
void tport_log_msg(tport_t *self, msg_t *msg, 
		   char const *what, char const *via,
191
		   su_time_t now)
192 193 194
{
  char stamp[128];
  msg_iovec_t iov[80];
195 196 197
  size_t i, iovlen = msg_iovec(msg, iov, 80);
  size_t linelen = 0, n, logged = 0, truncated = 0;
  int skip_lf = 0;
198 199 200 201

#define MSG_SEPARATOR \
  "------------------------------------------------------------------------\n"
#define MAX_LINELEN 2047
202 203 204 205 206 207

  for (i = n = 0; i < iovlen && i < 80; i++)
    n += iov[i].mv_len;

  tport_stamp(self, msg, stamp, what, n, via, now);
  su_log(stamp);
208 209 210
  su_log("   " MSG_SEPARATOR);
 
  for (i = 0; truncated == 0 && i < iovlen && i < 80; i++) {
211 212
    char *s = iov[i].mv_base, *end = s + iov[i].mv_len;

213
    if (skip_lf && s < end && s[0] == '\n') { s++; logged++; skip_lf = 0; }
214 215 216

    while (s < end) {
      if (s[0] == '\0') {
217 218
	truncated = logged;
	break;
219 220 221
      }

      n = strncspn(s, end - s, "\r\n");
222 223

      if (linelen + n > MAX_LINELEN) {
224
	n = MAX_LINELEN - linelen;
225
	truncated = logged + n;
226
      }
227

228
      su_log("%s%.*s", linelen > 0 ? "" : "   ", (int)n, s);
229 230 231 232 233
      s += n, linelen += n, logged += n;

      if (truncated)
	break;
      if (s == end)
234
	break;
235 236 237 238 239 240 241 242 243 244 245

      linelen = 0;
      su_log("\n");

      /* Skip eol */
      if (s[0] == '\r') {
	s++, logged++;
	if (s == end) {
	  skip_lf = 1;
	  continue;
	}
246
      }
247 248
      if (s[0] == '\n')
	s++, logged++;
249 250 251
    }
  }

252
  su_log("%s   " MSG_SEPARATOR, linelen > 0 ? "\n" : "");
253

254 255 256 257
  if (!truncated && i == 80)
    truncated = logged;

  if (truncated)
258
    su_log("   *** message truncated at "MOD_ZU" ***\n", truncated);
259
}