tport_logging.c 6.41 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 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100 101 102 103 104 105 106 107 108 109 110 111 112 113 114 115 116 117
 *
 * 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.
 * 
 * @sa <su_debug.h>, tport_log, SOFIA_DEBUG
 */
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)
{
  char const *log;
  
  mr->mr_log = 
    getenv("MSG_STREAM_LOG") != NULL ||
    getenv("TPORT_LOG") != NULL 
    ? MSG_DO_EXTRACT_COPY : 0;
    
  if ((log = getenv("TPORT_DUMP")) || (log = getenv("MSG_DUMP"))) {
    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, 
118
		 size_t n, char const *via,
119 120 121 122 123 124 125 126 127 128 129 130 131 132 133 134 135 136 137 138 139 140 141 142 143
		 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,
144
	   "%s "MOD_ZU" bytes %s %s/[%s]:%u%s%s at %02u:%02u:%02u.%06lu:\n",
145
	   what, (size_t)n, via, self->tp_name->tpn_proto,
146 147 148 149 150 151
	   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, 
152
		      size_t n, su_iovec_t const iov[], size_t iovused,
153 154 155 156
		      char const *what, char const *how)
{
  tport_master_t *mr = self->tp_master;
  char stamp[128];
157
  size_t i;
158 159 160 161 162 163 164 165

  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++) {
166
    size_t len = iov[i].mv_len;
167 168 169 170 171 172 173 174 175 176 177 178 179
    if (len > n)
      len = n;
    fwrite(iov[i].mv_base, len, 1, mr->mr_dump_file);
    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,
180
		   su_time_t now)
181 182 183
{
  char stamp[128];
  msg_iovec_t iov[80];
184 185 186
  size_t i, iovlen = msg_iovec(msg, iov, 80);
  size_t linelen = 0, n, logged = 0, truncated = 0;
  int skip_lf = 0;
187 188 189 190

#define MSG_SEPARATOR \
  "------------------------------------------------------------------------\n"
#define MAX_LINELEN 2047
191 192 193 194 195 196

  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);
197 198 199
  su_log("   " MSG_SEPARATOR);
 
  for (i = 0; truncated == 0 && i < iovlen && i < 80; i++) {
200 201
    char *s = iov[i].mv_base, *end = s + iov[i].mv_len;

202
    if (skip_lf && s < end && s[0] == '\n') { s++; logged++; skip_lf = 0; }
203 204 205

    while (s < end) {
      if (s[0] == '\0') {
206 207
	truncated = logged;
	break;
208 209 210
      }

      n = strncspn(s, end - s, "\r\n");
211 212 213 214

      if (linelen + n > MAX_LINELEN) {
	n = MAX_LINELEN - n - linelen;
	truncated = logged + n;
215
      }
216

217
      su_log("%s%.*s", linelen > n ? "" : "   ", (int)n, s);
218 219 220 221 222 223 224 225 226 227 228 229 230 231 232 233 234
      s += n, linelen += n, logged += n;

      if (truncated)
	break;
      if (s == end)
	continue;

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

      /* Skip eol */
      if (s[0] == '\r') {
	s++, logged++;
	if (s == end) {
	  skip_lf = 1;
	  continue;
	}
235
      }
236 237
      if (s[0] == '\n')
	s++, logged++;
238 239 240
    }
  }

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

243 244 245 246
  if (!truncated && i == 80)
    truncated = logged;

  if (truncated)
247
    su_log("   *** message truncated at "MOD_ZU" ***\n", truncated);
248
}