tport_logging.c 7.15 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
 *
 * 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.
52
 *
53 54
 * @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

/**@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.
66
 *
67 68
 * @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

/**@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.
79
 *
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
/**Debug log for @b tport module.
 *
88 89 90
 * The tport_log is the log object used by @b tport module. The level of
 * #tport_log is set using #TPORT_DEBUG environment variable.
 */
91
su_log_t tport_log[] = {
92 93 94 95 96
  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
  int log_msg = mr->mr_log != 0;
  char const *dump = NULL;
  int n;
102

103
  n = tl_gets(tags,
104
	      TPTAG_LOG_REF(log_msg),
105 106
	      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
    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;

132
    if (strcmp(dumpname, "-"))
133
      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
}

/** Create log stamp */
147 148
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
	   name, ntohs(su->su_port), label[0] ? label : "", comp,
	   hour, minute, second, now.tv_usec);
}

/** Dump the data from the iovec */
186
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
    n -= len;
  }

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

/** Log the message. */
217
void tport_log_msg(tport_t *self, msg_t *msg,
218
		   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
  su_log("   " MSG_SEPARATOR);
237

238
  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
}