tport_logging.c 7.17 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
 *
 * 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
 */
Michael Jerris's avatar
Michael Jerris committed
55
#ifdef DOXYGEN
56
extern char const TPORT_LOG[];	/* dummy declaration for Doxygen */
Michael Jerris's avatar
Michael Jerris committed
57
#endif
58 59 60 61 62 63 64 65 66 67 68

/**@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
 */
Michael Jerris's avatar
Michael Jerris committed
69
#ifdef DOXYGEN
70
extern char const TPORT_DUMP[];	/* dummy declaration for Doxygen */
Michael Jerris's avatar
Michael Jerris committed
71
#endif
72 73 74 75 76 77 78 79

/**@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
80
 * @sa <sofia-sip/su_debug.h>, tport_log, SOFIA_DEBUG
81
 */
Michael Jerris's avatar
Michael Jerris committed
82
#ifdef DOXYGEN
83
extern char const TPORT_DEBUG[]; /* dummy declaration for Doxygen */
Michael Jerris's avatar
Michael Jerris committed
84
#endif
85 86 87 88 89 90 91 92 93 94 95 96

/**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. */
97
int tport_open_log(tport_master_t *mr, tagi_t *tags)
98
{
99 100 101 102 103 104 105 106
  int log_msg = mr->mr_log != 0;
  char const *dump = NULL;
  int n;
  
  n = tl_gets(tags,
	      TPTAG_LOG_REF(log_msg), 
	      TPTAG_DUMP_REF(dump),
	      TAG_END());
107 108 109 110 111 112

  if (getenv("MSG_STREAM_LOG") != NULL || getenv("TPORT_LOG") != NULL)
    log_msg = 1;
  mr->mr_log = log_msg ? MSG_DO_EXTRACT_COPY : 0;

  if (getenv("MSG_DUMP"))
113
    dump = getenv("MSG_DUMP");
114
  if (getenv("TPORT_DUMP"))
115
    dump = getenv("TPORT_DUMP");
116

117
  if (dump) {
118
    time_t now;
119
    char *dumpname;
120

121 122 123 124 125 126 127 128 129 130 131 132 133
    if (mr->mr_dump && strcmp(dump, mr->mr_dump) == 0)
      return n;
    dumpname = su_strdup(mr->mr_home, dump);
    if (dumpname == NULL)
      return n;
    su_free(mr->mr_home, mr->mr_dump);
    mr->mr_dump = dumpname;

    if (mr->mr_dump_file && mr->mr_dump_file != stdout)
      fclose(mr->mr_dump_file), mr->mr_dump_file = NULL;

    if (strcmp(dumpname, "-")) 
      mr->mr_dump_file = fopen(dumpname, "ab"); /* XXX */
134 135 136 137 138 139 140 141
    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));
    }
  }
142 143

  return n;
144 145 146 147 148
}

/** Create log stamp */
void tport_stamp(tport_t const *self, msg_t *msg, 
		 char stamp[128], char const *what, 
149
		 size_t n, char const *via,
150 151 152 153 154
		 su_time_t now)
{
  char label[24] = "";
  char *comp = "";
  char name[SU_ADDRSIZE] = "";
155
  su_sockaddr_t const *su;
156 157
  unsigned short second, minute, hour;

158 159
  assert(self); assert(msg);

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

164 165
  su = msg_addr(msg);

166 167 168 169 170 171 172 173 174 175
#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";

Michael Jerris's avatar
Michael Jerris committed
176
  su_inet_ntop(su->su_family, SU_ADDR(su), name, sizeof(name));
177 178

  snprintf(stamp, 128,
179
	   "%s "MOD_ZU" bytes %s %s/[%s]:%u%s%s at %02u:%02u:%02u.%06lu:\n",
180
	   what, (size_t)n, via, self->tp_name->tpn_proto,
181 182 183 184 185 186
	   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, 
187
		      size_t n, su_iovec_t const iov[], size_t iovused,
188 189
		      char const *what, char const *how)
{
190
  tport_master_t *mr;
191
  char stamp[128];
192
  size_t i;
193

194 195 196
  assert(self); assert(msg);

  mr = self->tp_master;
197 198 199 200 201 202 203
  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++) {
204
    size_t len = iov[i].mv_len;
205 206
    if (len > n)
      len = n;
207 208
    if (fwrite(iov[i].mv_base, len, 1, mr->mr_dump_file) != len)
      break;
209 210 211 212 213 214 215 216 217 218
    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,
219
		   su_time_t now)
220 221 222
{
  char stamp[128];
  msg_iovec_t iov[80];
223 224 225
  size_t i, iovlen = msg_iovec(msg, iov, 80);
  size_t linelen = 0, n, logged = 0, truncated = 0;
  int skip_lf = 0;
226 227 228 229

#define MSG_SEPARATOR \
  "------------------------------------------------------------------------\n"
#define MAX_LINELEN 2047
230 231 232 233 234 235

  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);
236 237 238
  su_log("   " MSG_SEPARATOR);
 
  for (i = 0; truncated == 0 && i < iovlen && i < 80; i++) {
239 240
    char *s = iov[i].mv_base, *end = s + iov[i].mv_len;

241
    if (skip_lf && s < end && s[0] == '\n') { s++; logged++; skip_lf = 0; }
242 243 244

    while (s < end) {
      if (s[0] == '\0') {
245 246
	truncated = logged;
	break;
247 248 249
      }

      n = strncspn(s, end - s, "\r\n");
250 251

      if (linelen + n > MAX_LINELEN) {
252
	n = MAX_LINELEN - linelen;
253
	truncated = logged + n;
254
      }
255

256
      su_log("%s%.*s", linelen > 0 ? "" : "   ", (int)n, s);
257 258 259 260 261
      s += n, linelen += n, logged += n;

      if (truncated)
	break;
      if (s == end)
262
	break;
263 264 265 266 267 268 269 270 271 272 273

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

      /* Skip eol */
      if (s[0] == '\r') {
	s++, logged++;
	if (s == end) {
	  skip_lf = 1;
	  continue;
	}
274
      }
275 276
      if (s[0] == '\n')
	s++, logged++;
277 278 279
    }
  }

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

282 283 284 285
  if (!truncated && i == 80)
    truncated = logged;

  if (truncated)
286
    su_log("   *** message truncated at "MOD_ZU" ***\n", truncated);
287
}