From 8ac096b5bf9da1b3961a3ac4a03d083629222a63 Mon Sep 17 00:00:00 2001 From: Guus Sliepen Date: Sun, 26 Feb 2012 18:37:36 +0100 Subject: [PATCH] Allow log messages to be captured by tincctl. This allows tincctl to receive log messages from a running tincd, independent of what is logged to syslog or to file. Tincctl can receive debug messages with an arbitrary level. --- doc/tinc.texi | 4 ++ doc/tincctl.8.in | 4 ++ src/bsd/device.c | 40 +++++++++--------- src/conf.c | 20 ++++----- src/conf.h | 2 - src/connection.h | 9 +++-- src/control.c | 17 +++++--- src/control_common.h | 1 + src/cygwin/device.c | 34 ++++++++-------- src/dummy_device.c | 8 ++-- src/gcrypt/cipher.c | 20 ++++----- src/gcrypt/digest.c | 6 +-- src/gcrypt/rsa.c | 14 +++---- src/gcrypt/rsagen.c | 8 ++-- src/graph.c | 12 +++--- src/linux/device.c | 26 ++++++------ src/logger.c | 89 +++++++++++++++++++++++++---------------- src/logger.h | 5 +-- src/meta.c | 26 ++++++------ src/mingw/device.c | 26 ++++++------ src/net.c | 28 ++++++------- src/net_packet.c | 60 +++++++++++++-------------- src/net_setup.c | 78 ++++++++++++++++++------------------ src/net_socket.c | 58 +++++++++++++-------------- src/netutl.c | 13 +++--- src/node.c | 6 +-- src/openssl/cipher.c | 18 ++++----- src/openssl/digest.c | 6 +-- src/openssl/ecdh.c | 12 +++--- src/openssl/ecdsa.c | 10 ++--- src/openssl/rsa.c | 8 ++-- src/process.c | 32 +++++++-------- src/protocol.c | 50 +++++------------------ src/protocol_auth.c | 54 ++++++++++++------------- src/protocol_edge.c | 26 ++++++------ src/protocol_key.c | 48 +++++++++++----------- src/protocol_misc.c | 10 ++--- src/protocol_subnet.c | 28 ++++++------- src/raw_socket_device.c | 24 +++++------ src/route.c | 62 ++++++++++++++-------------- src/solaris/device.c | 32 +++++++-------- src/sptps_test.c | 5 +++ src/subnet.c | 6 +-- src/tincctl.c | 46 ++++++++++++++++----- src/tincd.c | 36 ++++++++--------- src/uml_device.c | 50 +++++++++++------------ src/vde_device.c | 18 ++++----- 47 files changed, 613 insertions(+), 582 deletions(-) diff --git a/doc/tinc.texi b/doc/tinc.texi index c26bf770..526a6c96 100644 --- a/doc/tinc.texi +++ b/doc/tinc.texi @@ -2023,6 +2023,10 @@ Purges all information remembered about unreachable nodes. @item debug @var{level} Sets debug level to @var{level}. +@item log [@var{level}] +Capture log messages from a running tinc daemon. +An optional debug level can be given that will be applied only for log messages sent to tincctl. + @item retry Forces tinc to try to connect to all uplinks immediately. Usually tinc attempts to do this itself, diff --git a/doc/tincctl.8.in b/doc/tincctl.8.in index a3168ba9..0c86e3d5 100644 --- a/doc/tincctl.8.in +++ b/doc/tincctl.8.in @@ -93,6 +93,10 @@ Purges all information remembered about unreachable nodes. .It debug Ar N Sets debug level to .Ar N . +.It log Op Ar N +Capture log messages from a running tinc daemon. +An optional debug level can be given that will be applied only for log messages sent to +.Nm tincctl . .It retry Forces .Xr tincd 8 diff --git a/src/bsd/device.c b/src/bsd/device.c index 9a1688a8..f8a55968 100644 --- a/src/bsd/device.c +++ b/src/bsd/device.c @@ -81,7 +81,7 @@ static bool setup_device(void) { else if(!strcasecmp(type, "tap")) device_type = DEVICE_TYPE_TAP; else { - logger(LOG_ERR, "Unknown device type %s!", type); + logger(DEBUG_ALWAYS, LOG_ERR, "Unknown device type %s!", type); return false; } } else { @@ -102,7 +102,7 @@ static bool setup_device(void) { } if(device_fd < 0) { - logger(LOG_ERR, "Could not open %s: %s", device, strerror(errno)); + logger(DEBUG_ALWAYS, LOG_ERR, "Could not open %s: %s", device, strerror(errno)); return false; } @@ -118,7 +118,7 @@ static bool setup_device(void) { { const int zero = 0; if(ioctl(device_fd, TUNSIFHEAD, &zero, sizeof zero) == -1) { - logger(LOG_ERR, "System call `%s' failed: %s", "ioctl", strerror(errno)); + logger(DEBUG_ALWAYS, LOG_ERR, "System call `%s' failed: %s", "ioctl", strerror(errno)); return false; } } @@ -137,7 +137,7 @@ static bool setup_device(void) { { const int one = 1; if(ioctl(device_fd, TUNSIFHEAD, &one, sizeof one) == -1) { - logger(LOG_ERR, "System call `%s' failed: %s", "ioctl", strerror(errno)); + logger(DEBUG_ALWAYS, LOG_ERR, "System call `%s' failed: %s", "ioctl", strerror(errno)); return false; } } @@ -174,7 +174,7 @@ static bool setup_device(void) { #endif } - logger(LOG_INFO, "%s is a %s", device, device_info); + logger(DEBUG_ALWAYS, LOG_INFO, "%s is a %s", device, device_info); return true; } @@ -208,7 +208,7 @@ static bool read_packet(vpn_packet_t *packet) { inlen = read(device_fd, packet->data + 14, MTU - 14); if(inlen <= 0) { - logger(LOG_ERR, "Error while reading from %s %s: %s", device_info, + logger(DEBUG_ALWAYS, LOG_ERR, "Error while reading from %s %s: %s", device_info, device, strerror(errno)); return false; } @@ -223,7 +223,7 @@ static bool read_packet(vpn_packet_t *packet) { packet->data[13] = 0xDD; break; default: - ifdebug(TRAFFIC) logger(LOG_ERR, + logger(DEBUG_TRAFFIC, LOG_ERR, "Unknown IP version %d while reading packet from %s %s", packet->data[14] >> 4, device_info, device); return false; @@ -237,7 +237,7 @@ static bool read_packet(vpn_packet_t *packet) { struct iovec vector[2] = {{&type, sizeof type}, {packet->data + 14, MTU - 14}}; if((inlen = readv(device_fd, vector, 2)) <= 0) { - logger(LOG_ERR, "Error while reading from %s %s: %s", device_info, + logger(DEBUG_ALWAYS, LOG_ERR, "Error while reading from %s %s: %s", device_info, device, strerror(errno)); return false; } @@ -254,7 +254,7 @@ static bool read_packet(vpn_packet_t *packet) { break; default: - ifdebug(TRAFFIC) logger(LOG_ERR, + logger(DEBUG_TRAFFIC, LOG_ERR, "Unknown address family %x while reading packet from %s %s", ntohl(type), device_info, device); return false; @@ -266,7 +266,7 @@ static bool read_packet(vpn_packet_t *packet) { case DEVICE_TYPE_TAP: if((inlen = read(device_fd, packet->data, MTU)) <= 0) { - logger(LOG_ERR, "Error while reading from %s %s: %s", device_info, + logger(DEBUG_ALWAYS, LOG_ERR, "Error while reading from %s %s: %s", device_info, device, strerror(errno)); return false; } @@ -280,20 +280,20 @@ static bool read_packet(vpn_packet_t *packet) { device_total_in += packet->len; - ifdebug(TRAFFIC) logger(LOG_DEBUG, "Read packet of %d bytes from %s", + logger(DEBUG_TRAFFIC, LOG_DEBUG, "Read packet of %d bytes from %s", packet->len, device_info); return true; } static bool write_packet(vpn_packet_t *packet) { - ifdebug(TRAFFIC) logger(LOG_DEBUG, "Writing packet of %d bytes to %s", + logger(DEBUG_TRAFFIC, LOG_DEBUG, "Writing packet of %d bytes to %s", packet->len, device_info); switch(device_type) { case DEVICE_TYPE_TUN: if(write(device_fd, packet->data + 14, packet->len - 14) < 0) { - logger(LOG_ERR, "Error while writing to %s %s: %s", device_info, + logger(DEBUG_ALWAYS, LOG_ERR, "Error while writing to %s %s: %s", device_info, device, strerror(errno)); return false; } @@ -314,14 +314,14 @@ static bool write_packet(vpn_packet_t *packet) { type = htonl(AF_INET6); break; default: - ifdebug(TRAFFIC) logger(LOG_ERR, + logger(DEBUG_TRAFFIC, LOG_ERR, "Unknown address family %x while writing packet to %s %s", af, device_info, device); return false; } if(writev(device_fd, vector, 2) < 0) { - logger(LOG_ERR, "Can't write to %s %s: %s", device_info, device, + logger(DEBUG_ALWAYS, LOG_ERR, "Can't write to %s %s: %s", device_info, device, strerror(errno)); return false; } @@ -330,7 +330,7 @@ static bool write_packet(vpn_packet_t *packet) { case DEVICE_TYPE_TAP: if(write(device_fd, packet->data, packet->len) < 0) { - logger(LOG_ERR, "Error while writing to %s %s: %s", device_info, + logger(DEBUG_ALWAYS, LOG_ERR, "Error while writing to %s %s: %s", device_info, device, strerror(errno)); return false; } @@ -339,7 +339,7 @@ static bool write_packet(vpn_packet_t *packet) { #ifdef HAVE_TUNEMU case DEVICE_TYPE_TUNEMU: if(tunemu_write(device_fd, packet->data + 14, packet->len - 14) < 0) { - logger(LOG_ERR, "Error while writing to %s %s: %s", device_info, + logger(DEBUG_ALWAYS, LOG_ERR, "Error while writing to %s %s: %s", device_info, device, strerror(errno)); return false; } @@ -356,9 +356,9 @@ static bool write_packet(vpn_packet_t *packet) { } static void dump_device_stats(void) { - logger(LOG_DEBUG, "Statistics for %s %s:", device_info, device); - logger(LOG_DEBUG, " total bytes in: %10"PRIu64, device_total_in); - logger(LOG_DEBUG, " total bytes out: %10"PRIu64, device_total_out); + logger(DEBUG_ALWAYS, LOG_DEBUG, "Statistics for %s %s:", device_info, device); + logger(DEBUG_ALWAYS, LOG_DEBUG, " total bytes in: %10"PRIu64, device_total_in); + logger(DEBUG_ALWAYS, LOG_DEBUG, " total bytes out: %10"PRIu64, device_total_out); } const devops_t os_devops = { diff --git a/src/conf.c b/src/conf.c index f47faefb..d7df4e96 100644 --- a/src/conf.c +++ b/src/conf.c @@ -141,7 +141,7 @@ bool get_config_bool(const config_t *cfg, bool *result) { return true; } - logger(LOG_ERR, "\"yes\" or \"no\" expected for configuration variable %s in %s line %d", + logger(DEBUG_ALWAYS, LOG_ERR, "\"yes\" or \"no\" expected for configuration variable %s in %s line %d", cfg->variable, cfg->file, cfg->line); return false; @@ -154,7 +154,7 @@ bool get_config_int(const config_t *cfg, int *result) { if(sscanf(cfg->value, "%d", result) == 1) return true; - logger(LOG_ERR, "Integer expected for configuration variable %s in %s line %d", + logger(DEBUG_ALWAYS, LOG_ERR, "Integer expected for configuration variable %s in %s line %d", cfg->variable, cfg->file, cfg->line); return false; @@ -182,7 +182,7 @@ bool get_config_address(const config_t *cfg, struct addrinfo **result) { return true; } - logger(LOG_ERR, "Hostname or IP address expected for configuration variable %s in %s line %d", + logger(DEBUG_ALWAYS, LOG_ERR, "Hostname or IP address expected for configuration variable %s in %s line %d", cfg->variable, cfg->file, cfg->line); return false; @@ -195,7 +195,7 @@ bool get_config_subnet(const config_t *cfg, subnet_t ** result) { return false; if(!str2net(&subnet, cfg->value)) { - logger(LOG_ERR, "Subnet expected for configuration variable %s in %s line %d", + logger(DEBUG_ALWAYS, LOG_ERR, "Subnet expected for configuration variable %s in %s line %d", cfg->variable, cfg->file, cfg->line); return false; } @@ -206,7 +206,7 @@ bool get_config_subnet(const config_t *cfg, subnet_t ** result) { && !maskcheck(&subnet.net.ipv4.address, subnet.net.ipv4.prefixlength, sizeof subnet.net.ipv4.address)) || ((subnet.type == SUBNET_IPV6) && !maskcheck(&subnet.net.ipv6.address, subnet.net.ipv6.prefixlength, sizeof subnet.net.ipv6.address))) { - logger(LOG_ERR, "Network address and prefix length do not match for configuration variable %s in %s line %d", + logger(DEBUG_ALWAYS, LOG_ERR, "Network address and prefix length do not match for configuration variable %s in %s line %d", cfg->variable, cfg->file, cfg->line); return false; } @@ -265,10 +265,10 @@ config_t *parse_config_line(char *line, const char *fname, int lineno) { if(!*value) { const char err[] = "No value for variable"; if (fname) - logger(LOG_ERR, "%s `%s' on line %d while reading config file %s", + logger(DEBUG_ALWAYS, LOG_ERR, "%s `%s' on line %d while reading config file %s", err, variable, lineno, fname); else - logger(LOG_ERR, "%s `%s' in command line option %d", + logger(DEBUG_ALWAYS, LOG_ERR, "%s `%s' in command line option %d", err, variable, lineno); return NULL; } @@ -298,7 +298,7 @@ bool read_config_file(splay_tree_t *config_tree, const char *fname) { fp = fopen(fname, "r"); if(!fp) { - logger(LOG_ERR, "Cannot open config file %s: %s", fname, strerror(errno)); + logger(DEBUG_ALWAYS, LOG_ERR, "Cannot open config file %s: %s", fname, strerror(errno)); return false; } @@ -379,7 +379,7 @@ bool read_server_config(void) { x = read_config_file(config_tree, fname); if(!x) { /* System error: complain */ - logger(LOG_ERR, "Failed to read `%s': %s", fname, strerror(errno)); + logger(DEBUG_ALWAYS, LOG_ERR, "Failed to read `%s': %s", fname, strerror(errno)); } free(fname); @@ -407,7 +407,7 @@ bool append_config_file(const char *name, const char *key, const char *value) { FILE *fp = fopen(fname, "a"); if(!fp) { - logger(LOG_ERR, "Cannot open config file %s: %s", fname, strerror(errno)); + logger(DEBUG_ALWAYS, LOG_ERR, "Cannot open config file %s: %s", fname, strerror(errno)); } else { fprintf(fp, "\n# The following line was automatically added by tinc\n%s = %s\n", key, value); fclose(fp); diff --git a/src/conf.h b/src/conf.h index bd3850bf..1ae5b735 100644 --- a/src/conf.h +++ b/src/conf.h @@ -62,8 +62,6 @@ extern void read_config_options(splay_tree_t *, const char *); extern bool read_server_config(void); extern bool read_connection_config(struct connection_t *); extern bool append_config_file(const char *, const char *, const char *); -extern FILE *ask_and_open(const char *, const char *, const char *); -extern bool is_safe_path(const char *); extern bool disable_old_keys(FILE *); #endif /* __TINC_CONF_H__ */ diff --git a/src/connection.h b/src/connection.h index 2d84aced..58eea4e6 100644 --- a/src/connection.h +++ b/src/connection.h @@ -1,6 +1,6 @@ /* connection.h -- header for connection.c - Copyright (C) 2000-2010 Guus Sliepen , + Copyright (C) 2000-2012 Guus Sliepen , 2000-2005 Ivo Timmermans This program is free software; you can redistribute it and/or modify @@ -43,9 +43,10 @@ typedef struct connection_status_t { unsigned int encryptout:1; /* 1 if we can encrypt outgoing traffic */ unsigned int decryptin:1; /* 1 if we have to decrypt incoming traffic */ unsigned int mst:1; /* 1 if this connection is part of a minimum spanning tree */ - unsigned int control:1; - unsigned int pcap:1; - unsigned int unused:21; + unsigned int control:1; /* 1 if this is a control connection */ + unsigned int pcap:1; /* 1 if this is a control connection requesting packet capture */ + unsigned int log:1; /* 1 if this is a control connection requesting log dump */ + unsigned int unused:20; } connection_status_t; #include "ecdh.h" diff --git a/src/control.c b/src/control.c index 86224c29..d074ebba 100644 --- a/src/control.c +++ b/src/control.c @@ -1,6 +1,6 @@ /* control.c -- Control socket handling. - Copyright (C) 2007 Guus Sliepen + Copyright (C) 2012 Guus Sliepen This program is free software; you can redistribute it and/or modify it under the terms of the GNU General Public License as published by @@ -48,12 +48,12 @@ bool control_h(connection_t *c, char *request) { int type; if(!c->status.control || c->allow_request != CONTROL) { - logger(LOG_ERR, "Unauthorized control request from %s (%s)", c->name, c->hostname); + logger(DEBUG_ALWAYS, LOG_ERR, "Unauthorized control request from %s (%s)", c->name, c->hostname); return false; } if(sscanf(request, "%*d %d", &type) != 1) { - logger(LOG_ERR, "Got bad %s from %s (%s)", "CONTROL", c->name, c->hostname); + logger(DEBUG_ALWAYS, LOG_ERR, "Got bad %s from %s (%s)", "CONTROL", c->name, c->hostname); return false; } @@ -93,7 +93,7 @@ bool control_h(connection_t *c, char *request) { return control_ok(c, REQ_RETRY); case REQ_RELOAD: - logger(LOG_NOTICE, "Got '%s' command", "reload"); + logger(DEBUG_ALWAYS, LOG_NOTICE, "Got '%s' command", "reload"); int result = reload_configuration(); return control_return(c, REQ_RELOAD, result); @@ -122,10 +122,17 @@ bool control_h(connection_t *c, char *request) { return dump_traffic(c); case REQ_PCAP: + sscanf(request, "%*d %*d %d", &c->outmaclength); c->status.pcap = true; pcap = true; return true; + case REQ_LOG: + sscanf(request, "%*d %*d %d", &c->outcompression); + c->status.log = true; + logcontrol = true; + return true; + default: return send_request(c, "%d %d", CONTROL, REQ_INVALID); } @@ -137,7 +144,7 @@ bool init_control(void) { FILE *f = fopen(pidfilename, "w"); if(!f) { - logger(LOG_ERR, "Cannot write control socket cookie file %s: %s", pidfilename, strerror(errno)); + logger(DEBUG_ALWAYS, LOG_ERR, "Cannot write control socket cookie file %s: %s", pidfilename, strerror(errno)); return false; } diff --git a/src/control_common.h b/src/control_common.h index 615e10a7..34bae47c 100644 --- a/src/control_common.h +++ b/src/control_common.h @@ -39,6 +39,7 @@ enum request_type { REQ_DISCONNECT, REQ_DUMP_TRAFFIC, REQ_PCAP, + REQ_LOG, }; #define TINC_CTL_VERSION_CURRENT 0 diff --git a/src/cygwin/device.c b/src/cygwin/device.c index cf9f1b57..869116a8 100644 --- a/src/cygwin/device.c +++ b/src/cygwin/device.c @@ -64,7 +64,7 @@ static bool setup_device(void) { /* Open registry and look for network adapters */ if(RegOpenKeyEx(HKEY_LOCAL_MACHINE, NETWORK_CONNECTIONS_KEY, 0, KEY_READ, &key)) { - logger(LOG_ERR, "Unable to read registry: %s", winerror(GetLastError())); + logger(DEBUG_ALWAYS, LOG_ERR, "Unable to read registry: %s", winerror(GetLastError())); return false; } @@ -116,7 +116,7 @@ static bool setup_device(void) { RegCloseKey(key); if(!found) { - logger(LOG_ERR, "No Windows tap device found!"); + logger(DEBUG_ALWAYS, LOG_ERR, "No Windows tap device found!"); return false; } @@ -133,7 +133,7 @@ static bool setup_device(void) { Furthermore I don't really know how to do it the "Windows" way. */ if(socketpair(AF_UNIX, SOCK_DGRAM, PF_UNIX, sp)) { - logger(LOG_DEBUG, "System call `%s' failed: %s", "socketpair", strerror(errno)); + logger(DEBUG_ALWAYS, LOG_DEBUG, "System call `%s' failed: %s", "socketpair", strerror(errno)); return false; } @@ -142,7 +142,7 @@ static bool setup_device(void) { device_handle = CreateFile(tapname, GENERIC_WRITE, FILE_SHARE_READ, 0, OPEN_EXISTING, FILE_ATTRIBUTE_SYSTEM , 0); if(device_handle == INVALID_HANDLE_VALUE) { - logger(LOG_ERR, "Could not open Windows tap device %s (%s) for writing: %s", device, iface, winerror(GetLastError())); + logger(DEBUG_ALWAYS, LOG_ERR, "Could not open Windows tap device %s (%s) for writing: %s", device, iface, winerror(GetLastError())); return false; } @@ -151,7 +151,7 @@ static bool setup_device(void) { /* Get MAC address from tap device */ if(!DeviceIoControl(device_handle, TAP_IOCTL_GET_MAC, mymac.x, sizeof mymac.x, mymac.x, sizeof mymac.x, &len, 0)) { - logger(LOG_ERR, "Could not get MAC address from Windows tap device %s (%s): %s", device, iface, winerror(GetLastError())); + logger(DEBUG_ALWAYS, LOG_ERR, "Could not get MAC address from Windows tap device %s (%s): %s", device, iface, winerror(GetLastError())); return false; } @@ -164,7 +164,7 @@ static bool setup_device(void) { reader_pid = fork(); if(reader_pid == -1) { - logger(LOG_DEBUG, "System call `%s' failed: %s", "fork", strerror(errno)); + logger(DEBUG_ALWAYS, LOG_DEBUG, "System call `%s' failed: %s", "fork", strerror(errno)); return false; } @@ -180,13 +180,13 @@ static bool setup_device(void) { device_handle = CreateFile(tapname, GENERIC_READ, FILE_SHARE_WRITE, 0, OPEN_EXISTING, FILE_ATTRIBUTE_SYSTEM, 0); if(device_handle == INVALID_HANDLE_VALUE) { - logger(LOG_ERR, "Could not open Windows tap device %s (%s) for reading: %s", device, iface, winerror(GetLastError())); + logger(DEBUG_ALWAYS, LOG_ERR, "Could not open Windows tap device %s (%s) for reading: %s", device, iface, winerror(GetLastError())); buf[0] = 0; write(sp[1], buf, 1); exit(1); } - logger(LOG_DEBUG, "Tap reader forked and running."); + logger(DEBUG_ALWAYS, LOG_DEBUG, "Tap reader forked and running."); /* Notify success */ @@ -203,13 +203,13 @@ static bool setup_device(void) { read(device_fd, &gelukt, 1); if(gelukt != 1) { - logger(LOG_DEBUG, "Tap reader failed!"); + logger(DEBUG_ALWAYS, LOG_DEBUG, "Tap reader failed!"); return false; } device_info = "Windows tap device"; - logger(LOG_INFO, "%s (%s) is a %s", device, iface, device_info); + logger(DEBUG_ALWAYS, LOG_INFO, "%s (%s) is a %s", device, iface, device_info); return true; } @@ -229,7 +229,7 @@ static bool read_packet(vpn_packet_t *packet) { int inlen; if((inlen = read(sp[0], packet->data, MTU)) <= 0) { - logger(LOG_ERR, "Error while reading from %s %s: %s", device_info, + logger(DEBUG_ALWAYS, LOG_ERR, "Error while reading from %s %s: %s", device_info, device, strerror(errno)); return false; } @@ -238,7 +238,7 @@ static bool read_packet(vpn_packet_t *packet) { device_total_in += packet->len; - ifdebug(TRAFFIC) logger(LOG_DEBUG, "Read packet of %d bytes from %s", packet->len, + logger(DEBUG_TRAFFIC, LOG_DEBUG, "Read packet of %d bytes from %s", packet->len, device_info); return true; @@ -247,11 +247,11 @@ static bool read_packet(vpn_packet_t *packet) { static bool write_packet(vpn_packet_t *packet) { long outlen; - ifdebug(TRAFFIC) logger(LOG_DEBUG, "Writing packet of %d bytes to %s", + logger(DEBUG_TRAFFIC, LOG_DEBUG, "Writing packet of %d bytes to %s", packet->len, device_info); if(!WriteFile (device_handle, packet->data, packet->len, &outlen, NULL)) { - logger(LOG_ERR, "Error while writing to %s %s: %s", device_info, device, winerror(GetLastError())); + logger(DEBUG_ALWAYS, LOG_ERR, "Error while writing to %s %s: %s", device_info, device, winerror(GetLastError())); return false; } @@ -261,9 +261,9 @@ static bool write_packet(vpn_packet_t *packet) { } static void dump_device_stats(void) { - logger(LOG_DEBUG, "Statistics for %s %s:", device_info, device); - logger(LOG_DEBUG, " total bytes in: %10"PRIu64, device_total_in); - logger(LOG_DEBUG, " total bytes out: %10"PRIu64, device_total_out); + logger(DEBUG_ALWAYS, LOG_DEBUG, "Statistics for %s %s:", device_info, device); + logger(DEBUG_ALWAYS, LOG_DEBUG, " total bytes in: %10"PRIu64, device_total_in); + logger(DEBUG_ALWAYS, LOG_DEBUG, " total bytes out: %10"PRIu64, device_total_out); } const devops_t os_devops = { diff --git a/src/dummy_device.c b/src/dummy_device.c index 9dd3fae7..7fdbd5c6 100644 --- a/src/dummy_device.c +++ b/src/dummy_device.c @@ -31,7 +31,7 @@ static uint64_t device_total_out = 0; static bool setup_device(void) { device = "dummy"; iface = "dummy"; - logger(LOG_INFO, "%s (%s) is a %s", device, iface, device_info); + logger(DEBUG_ALWAYS, LOG_INFO, "%s (%s) is a %s", device, iface, device_info); return true; } @@ -48,9 +48,9 @@ static bool write_packet(vpn_packet_t *packet) { } static void dump_device_stats(void) { - logger(LOG_DEBUG, "Statistics for %s %s:", device_info, device); - logger(LOG_DEBUG, " total bytes in: %10"PRIu64, device_total_in); - logger(LOG_DEBUG, " total bytes out: %10"PRIu64, device_total_out); + logger(DEBUG_ALWAYS, LOG_DEBUG, "Statistics for %s %s:", device_info, device); + logger(DEBUG_ALWAYS, LOG_DEBUG, " total bytes in: %10"PRIu64, device_total_in); + logger(DEBUG_ALWAYS, LOG_DEBUG, " total bytes out: %10"PRIu64, device_total_out); } const devops_t dummy_devops = { diff --git a/src/gcrypt/cipher.c b/src/gcrypt/cipher.c index 6a2cc5a1..cf46dec8 100644 --- a/src/gcrypt/cipher.c +++ b/src/gcrypt/cipher.c @@ -97,12 +97,12 @@ static bool cipher_open(cipher_t *cipher, int algo, int mode) { gcry_error_t err; if(!ciphertonid(algo, mode, &cipher->nid)) { - logger(LOG_DEBUG, "Cipher %d mode %d has no corresponding nid!", algo, mode); + logger(DEBUG_ALWAYS, LOG_DEBUG, "Cipher %d mode %d has no corresponding nid!", algo, mode); return false; } if((err = gcry_cipher_open(&cipher->handle, algo, mode, 0))) { - logger(LOG_DEBUG, "Unable to intialise cipher %d mode %d: %s", algo, mode, gcry_strerror(err)); + logger(DEBUG_ALWAYS, LOG_DEBUG, "Unable to intialise cipher %d mode %d: %s", algo, mode, gcry_strerror(err)); return false; } @@ -118,7 +118,7 @@ bool cipher_open_by_name(cipher_t *cipher, const char *name) { int algo, mode; if(!nametocipher(name, &algo, &mode)) { - logger(LOG_DEBUG, "Unknown cipher name '%s'!", name); + logger(DEBUG_ALWAYS, LOG_DEBUG, "Unknown cipher name '%s'!", name); return false; } @@ -129,7 +129,7 @@ bool cipher_open_by_nid(cipher_t *cipher, int nid) { int algo, mode; if(!nidtocipher(nid, &algo, &mode)) { - logger(LOG_DEBUG, "Unknown cipher ID %d!", nid); + logger(DEBUG_ALWAYS, LOG_DEBUG, "Unknown cipher ID %d!", nid); return false; } @@ -199,7 +199,7 @@ bool cipher_encrypt(cipher_t *cipher, const void *indata, size_t inlen, void *ou size_t reqlen = ((inlen + cipher->blklen) / cipher->blklen) * cipher->blklen; if(*outlen < reqlen) { - logger(LOG_ERR, "Error while encrypting: not enough room for padding"); + logger(DEBUG_ALWAYS, LOG_ERR, "Error while encrypting: not enough room for padding"); return false; } @@ -217,13 +217,13 @@ bool cipher_encrypt(cipher_t *cipher, const void *indata, size_t inlen, void *ou gcry_cipher_setiv(cipher->handle, cipher->key + cipher->keylen, cipher->blklen); if((err = gcry_cipher_encrypt(cipher->handle, outdata, *outlen, indata, inlen))) { - logger(LOG_ERR, "Error while encrypting: %s", gcry_strerror(err)); + logger(DEBUG_ALWAYS, LOG_ERR, "Error while encrypting: %s", gcry_strerror(err)); return false; } if(cipher->padding) { if((err = gcry_cipher_encrypt(cipher->handle, outdata + inlen, cipher->blklen, pad, cipher->blklen))) { - logger(LOG_ERR, "Error while encrypting: %s", gcry_strerror(err)); + logger(DEBUG_ALWAYS, LOG_ERR, "Error while encrypting: %s", gcry_strerror(err)); return false; } @@ -241,7 +241,7 @@ bool cipher_decrypt(cipher_t *cipher, const void *indata, size_t inlen, void *ou gcry_cipher_setiv(cipher->handle, cipher->key + cipher->keylen, cipher->blklen); if((err = gcry_cipher_decrypt(cipher->handle, outdata, *outlen, indata, inlen))) { - logger(LOG_ERR, "Error while decrypting: %s", gcry_strerror(err)); + logger(DEBUG_ALWAYS, LOG_ERR, "Error while decrypting: %s", gcry_strerror(err)); return false; } @@ -252,7 +252,7 @@ bool cipher_decrypt(cipher_t *cipher, const void *indata, size_t inlen, void *ou uint8_t padbyte = ((uint8_t *)outdata)[inlen - 1]; if(padbyte == 0 || padbyte > cipher->blklen || padbyte > inlen) { - logger(LOG_ERR, "Error while decrypting: invalid padding"); + logger(DEBUG_ALWAYS, LOG_ERR, "Error while decrypting: invalid padding"); return false; } @@ -260,7 +260,7 @@ bool cipher_decrypt(cipher_t *cipher, const void *indata, size_t inlen, void *ou for(int i = inlen - 1; i >= origlen; i--) if(((uint8_t *)outdata)[i] != padbyte) { - logger(LOG_ERR, "Error while decrypting: invalid padding"); + logger(DEBUG_ALWAYS, LOG_ERR, "Error while decrypting: invalid padding"); return false; } diff --git a/src/gcrypt/digest.c b/src/gcrypt/digest.c index 066600f9..a845afa1 100644 --- a/src/gcrypt/digest.c +++ b/src/gcrypt/digest.c @@ -75,7 +75,7 @@ static bool digesttonid(int algo, int *nid) { static bool digest_open(digest_t *digest, int algo, int maclength) { if(!digesttonid(algo, &digest->nid)) { - logger(LOG_DEBUG, "Digest %d has no corresponding nid!", algo); + logger(DEBUG_ALWAYS, LOG_DEBUG, "Digest %d has no corresponding nid!", algo); return false; } @@ -96,7 +96,7 @@ bool digest_open_by_name(digest_t *digest, const char *name, int maclength) { int algo; if(!nametodigest(name, &algo)) { - logger(LOG_DEBUG, "Unknown digest name '%s'!", name); + logger(DEBUG_ALWAYS, LOG_DEBUG, "Unknown digest name '%s'!", name); return false; } @@ -107,7 +107,7 @@ bool digest_open_by_nid(digest_t *digest, int nid, int maclength) { int algo; if(!nidtodigest(nid, &algo)) { - logger(LOG_DEBUG, "Unknown digest ID %d!", nid); + logger(DEBUG_ALWAYS, LOG_DEBUG, "Unknown digest ID %d!", nid); return false; } diff --git a/src/gcrypt/rsa.c b/src/gcrypt/rsa.c index ceb16389..11d452ce 100644 --- a/src/gcrypt/rsa.c +++ b/src/gcrypt/rsa.c @@ -187,7 +187,7 @@ bool rsa_set_hex_public_key(rsa_t *rsa, char *n, char *e) { ?: gcry_mpi_scan(&rsa->e, GCRYMPI_FMT_HEX, e, 0, NULL); if(err) { - logger(LOG_ERR, "Error while reading RSA public key: %s", gcry_strerror(errno)); + logger(DEBUG_ALWAYS, LOG_ERR, "Error while reading RSA public key: %s", gcry_strerror(errno)); return false; } @@ -202,7 +202,7 @@ bool rsa_set_hex_private_key(rsa_t *rsa, char *n, char *e, char *d) { ?: gcry_mpi_scan(&rsa->d, GCRYMPI_FMT_HEX, d, 0, NULL); if(err) { - logger(LOG_ERR, "Error while reading RSA public key: %s", gcry_strerror(errno)); + logger(DEBUG_ALWAYS, LOG_ERR, "Error while reading RSA public key: %s", gcry_strerror(errno)); return false; } @@ -216,7 +216,7 @@ bool rsa_read_pem_public_key(rsa_t *rsa, FILE *fp) { size_t derlen; if(!pem_decode(fp, "RSA PUBLIC KEY", derbuf, sizeof derbuf, &derlen)) { - logger(LOG_ERR, "Unable to read RSA public key: %s", strerror(errno)); + logger(DEBUG_ALWAYS, LOG_ERR, "Unable to read RSA public key: %s", strerror(errno)); return NULL; } @@ -224,7 +224,7 @@ bool rsa_read_pem_public_key(rsa_t *rsa, FILE *fp) { || !ber_read_mpi(&derp, &derlen, &rsa->n) || !ber_read_mpi(&derp, &derlen, &rsa->e) || derlen) { - logger(LOG_ERR, "Error while decoding RSA public key"); + logger(DEBUG_ALWAYS, LOG_ERR, "Error while decoding RSA public key"); return NULL; } @@ -236,7 +236,7 @@ bool rsa_read_pem_private_key(rsa_t *rsa, FILE *fp) { size_t derlen; if(!pem_decode(fp, "RSA PRIVATE KEY", derbuf, sizeof derbuf, &derlen)) { - logger(LOG_ERR, "Unable to read RSA private key: %s", strerror(errno)); + logger(DEBUG_ALWAYS, LOG_ERR, "Unable to read RSA private key: %s", strerror(errno)); return NULL; } @@ -251,7 +251,7 @@ bool rsa_read_pem_private_key(rsa_t *rsa, FILE *fp) { || !ber_read_mpi(&derp, &derlen, NULL) || !ber_read_mpi(&derp, &derlen, NULL) // u || derlen) { - logger(LOG_ERR, "Error while decoding RSA private key"); + logger(DEBUG_ALWAYS, LOG_ERR, "Error while decoding RSA private key"); return NULL; } @@ -267,7 +267,7 @@ size_t rsa_size(rsa_t *rsa) { */ // TODO: get rid of this macro, properly clean up gcry_ structures after use -#define check(foo) { gcry_error_t err = (foo); if(err) {logger(LOG_ERR, "gcrypt error %s/%s at %s:%d", gcry_strsource(err), gcry_strerror(err), __FILE__, __LINE__); return false; }} +#define check(foo) { gcry_error_t err = (foo); if(err) {logger(DEBUG_ALWAYS, LOG_ERR, "gcrypt error %s/%s at %s:%d", gcry_strsource(err), gcry_strerror(err), __FILE__, __LINE__); return false; }} bool rsa_public_encrypt(rsa_t *rsa, void *in, size_t len, void *out) { gcry_mpi_t inmpi; diff --git a/src/gcrypt/rsagen.c b/src/gcrypt/rsagen.c index 7d37d196..2cdbcccf 100644 --- a/src/gcrypt/rsagen.c +++ b/src/gcrypt/rsagen.c @@ -164,12 +164,12 @@ bool rsa_write_pem_public_key(rsa_t *rsa, FILE *fp) { if(!ber_write_mpi(&derp1, &derlen1, &rsa->n) || !ber_write_mpi(&derp1, &derlen1, &rsa->e) || !ber_write_sequence(&derp2, &derlen2, derbuf1, derlen1)) { - logger(LOG_ERR, "Error while encoding RSA public key"); + logger(DEBUG_ALWAYS, LOG_ERR, "Error while encoding RSA public key"); return false; } if(!pem_encode(fp, "RSA PUBLIC KEY", derbuf2, derlen2)) { - logger(LOG_ERR, "Unable to write RSA public key: %s", strerror(errno)); + logger(DEBUG_ALWAYS, LOG_ERR, "Unable to write RSA public key: %s", strerror(errno)); return false; } @@ -193,12 +193,12 @@ bool rsa_write_pem_private_key(rsa_t *rsa, FILE *fp) { || ber_write_mpi(&derp1, &derlen1, &exp1) || ber_write_mpi(&derp1, &derlen1, &exp2) || ber_write_mpi(&derp1, &derlen1, &coeff)) - logger(LOG_ERR, "Error while encoding RSA private key"); + logger(DEBUG_ALWAYS, LOG_ERR, "Error while encoding RSA private key"); return false; } if(!pem_encode(fp, "RSA PRIVATE KEY", derbuf2, derlen2)) { - logger(LOG_ERR, "Unable to write RSA private key: %s", strerror(errno)); + logger(DEBUG_ALWAYS, LOG_ERR, "Unable to write RSA private key: %s", strerror(errno)); return false; } diff --git a/src/graph.c b/src/graph.c index 17252411..4a9af9bc 100644 --- a/src/graph.c +++ b/src/graph.c @@ -78,7 +78,7 @@ static void mst_kruskal(void) { c->status.mst = false; } - ifdebug(SCARY_THINGS) logger(LOG_DEBUG, "Running Kruskal's algorithm:"); + logger(DEBUG_SCARY_THINGS, LOG_DEBUG, "Running Kruskal's algorithm:"); /* Clear visited status on nodes */ @@ -105,7 +105,7 @@ static void mst_kruskal(void) { if(e->reverse->connection) e->reverse->connection->status.mst = true; - ifdebug(SCARY_THINGS) logger(LOG_DEBUG, " Adding edge %s - %s weight %d", e->from->name, + logger(DEBUG_SCARY_THINGS, LOG_DEBUG, " Adding edge %s - %s weight %d", e->from->name, e->to->name, e->weight); } } @@ -124,7 +124,7 @@ static void sssp_dijkstra(void) { todo_list = list_alloc(NULL); - ifdebug(SCARY_THINGS) logger(LOG_DEBUG, "Running Dijkstra's algorithm:"); + logger(DEBUG_SCARY_THINGS, LOG_DEBUG, "Running Dijkstra's algorithm:"); /* Clear visited status on nodes */ @@ -204,7 +204,7 @@ static void sssp_dijkstra(void) { if(e->to->address.sa.sa_family == AF_UNSPEC && e->address.sa.sa_family != AF_UNKNOWN) update_node_udp(e->to, &e->address); - ifdebug(SCARY_THINGS) logger(LOG_DEBUG, " Updating edge %s - %s weight %d distance %d", e->from->name, + logger(DEBUG_SCARY_THINGS, LOG_DEBUG, " Updating edge %s - %s weight %d distance %d", e->from->name, e->to->name, e->weight, e->to->distance); } } @@ -315,10 +315,10 @@ static void check_reachability(void) { n->status.reachable = !n->status.reachable; if(n->status.reachable) { - ifdebug(TRAFFIC) logger(LOG_DEBUG, "Node %s (%s) became reachable", + logger(DEBUG_TRAFFIC, LOG_DEBUG, "Node %s (%s) became reachable", n->name, n->hostname); } else { - ifdebug(TRAFFIC) logger(LOG_DEBUG, "Node %s (%s) became unreachable", + logger(DEBUG_TRAFFIC, LOG_DEBUG, "Node %s (%s) became unreachable", n->name, n->hostname); } diff --git a/src/linux/device.c b/src/linux/device.c index ccb9a3f0..ede68198 100644 --- a/src/linux/device.c +++ b/src/linux/device.c @@ -64,7 +64,7 @@ static bool setup_device(void) { device_fd = open(device, O_RDWR | O_NONBLOCK); if(device_fd < 0) { - logger(LOG_ERR, "Could not open %s: %s", device, strerror(errno)); + logger(DEBUG_ALWAYS, LOG_ERR, "Could not open %s: %s", device, strerror(errno)); return false; } @@ -77,7 +77,7 @@ static bool setup_device(void) { get_config_string(lookup_config(config_tree, "DeviceType"), &type); if(type && strcasecmp(type, "tun") && strcasecmp(type, "tap")) { - logger(LOG_ERR, "Unknown device type %s!", type); + logger(DEBUG_ALWAYS, LOG_ERR, "Unknown device type %s!", type); return false; } @@ -107,13 +107,13 @@ static bool setup_device(void) { if(iface) free(iface); iface = xstrdup(ifrname); } else if(!ioctl(device_fd, (('T' << 8) | 202), &ifr)) { - logger(LOG_WARNING, "Old ioctl() request was needed for %s", device); + logger(DEBUG_ALWAYS, LOG_WARNING, "Old ioctl() request was needed for %s", device); strncpy(ifrname, ifr.ifr_name, IFNAMSIZ); if(iface) free(iface); iface = xstrdup(ifrname); } - logger(LOG_INFO, "%s is a %s", device, device_info); + logger(DEBUG_ALWAYS, LOG_INFO, "%s is a %s", device, device_info); return true; } @@ -134,7 +134,7 @@ static bool read_packet(vpn_packet_t *packet) { inlen = read(device_fd, packet->data + 10, MTU - 10); if(inlen <= 0) { - logger(LOG_ERR, "Error while reading from %s %s: %s", + logger(DEBUG_ALWAYS, LOG_ERR, "Error while reading from %s %s: %s", device_info, device, strerror(errno)); return false; } @@ -145,7 +145,7 @@ static bool read_packet(vpn_packet_t *packet) { inlen = read(device_fd, packet->data, MTU); if(inlen <= 0) { - logger(LOG_ERR, "Error while reading from %s %s: %s", + logger(DEBUG_ALWAYS, LOG_ERR, "Error while reading from %s %s: %s", device_info, device, strerror(errno)); return false; } @@ -159,28 +159,28 @@ static bool read_packet(vpn_packet_t *packet) { device_in_packets++; device_in_bytes += packet->len; - ifdebug(TRAFFIC) logger(LOG_DEBUG, "Read packet of %d bytes from %s", packet->len, + logger(DEBUG_TRAFFIC, LOG_DEBUG, "Read packet of %d bytes from %s", packet->len, device_info); return true; } static bool write_packet(vpn_packet_t *packet) { - ifdebug(TRAFFIC) logger(LOG_DEBUG, "Writing packet of %d bytes to %s", + logger(DEBUG_TRAFFIC, LOG_DEBUG, "Writing packet of %d bytes to %s", packet->len, device_info); switch(device_type) { case DEVICE_TYPE_TUN: packet->data[10] = packet->data[11] = 0; if(write(device_fd, packet->data + 10, packet->len - 10) < 0) { - logger(LOG_ERR, "Can't write to %s %s: %s", device_info, device, + logger(DEBUG_ALWAYS, LOG_ERR, "Can't write to %s %s: %s", device_info, device, strerror(errno)); return false; } break; case DEVICE_TYPE_TAP: if(write(device_fd, packet->data, packet->len) < 0) { - logger(LOG_ERR, "Can't write to %s %s: %s", device_info, device, + logger(DEBUG_ALWAYS, LOG_ERR, "Can't write to %s %s: %s", device_info, device, strerror(errno)); return false; } @@ -196,9 +196,9 @@ static bool write_packet(vpn_packet_t *packet) { } static void dump_device_stats(void) { - logger(LOG_DEBUG, "Statistics for %s %s:", device_info, device); - logger(LOG_DEBUG, " total bytes in: %10"PRIu64, device_in_bytes); - logger(LOG_DEBUG, " total bytes out: %10"PRIu64, device_out_bytes); + logger(DEBUG_ALWAYS, LOG_DEBUG, "Statistics for %s %s:", device_info, device); + logger(DEBUG_ALWAYS, LOG_DEBUG, " total bytes in: %10"PRIu64, device_in_bytes); + logger(DEBUG_ALWAYS, LOG_DEBUG, " total bytes out: %10"PRIu64, device_out_bytes); } const devops_t os_devops = { diff --git a/src/logger.c b/src/logger.c index 08f97954..028cbaef 100644 --- a/src/logger.c +++ b/src/logger.c @@ -21,7 +21,10 @@ #include "system.h" #include "conf.h" +#include "meta.h" #include "logger.h" +#include "connection.h" +#include "control_common.h" debug_t debug_level = DEBUG_NOTHING; static logmode_t logmode = LOGMODE_STDERR; @@ -32,6 +35,7 @@ static FILE *logfile = NULL; static HANDLE loghandle = NULL; #endif static const char *logident = NULL; +bool logcontrol = false; void openlogger(const char *ident, logmode_t mode) { logident = ident; @@ -75,61 +79,76 @@ void reopenlogger() { fflush(logfile); FILE *newfile = fopen(logfilename, "a"); if(!newfile) { - logger(LOG_ERR, "Unable to reopen log file %s: %s\n", logfilename, strerror(errno)); + logger(DEBUG_ALWAYS, LOG_ERR, "Unable to reopen log file %s: %s\n", logfilename, strerror(errno)); return; } fclose(logfile); logfile = newfile; } -void logger(int priority, const char *format, ...) { +void logger(int level, int priority, const char *format, ...) { va_list ap; char timestr[32] = ""; + char message[1024] = ""; time_t now; + static bool suppress = false; + + // Bail out early if there is nothing to do. + if(suppress) + return; + + if(!logcontrol && (level > debug_level || logmode == LOGMODE_NULL)) + return; va_start(ap, format); + vsnprintf(message, sizeof message, format, ap); + va_end(ap); - switch(logmode) { - case LOGMODE_STDERR: - vfprintf(stderr, format, ap); - fprintf(stderr, "\n"); - fflush(stderr); - break; - case LOGMODE_FILE: - now = time(NULL); - strftime(timestr, sizeof timestr, "%Y-%m-%d %H:%M:%S", localtime(&now)); - fprintf(logfile, "%s %s[%ld]: ", timestr, logident, (long)logpid); - vfprintf(logfile, format, ap); - fprintf(logfile, "\n"); - fflush(logfile); - break; - case LOGMODE_SYSLOG: + if(level <= debug_level) { + switch(logmode) { + case LOGMODE_STDERR: + fprintf(stderr, "%s\n", message); + fflush(stderr); + break; + case LOGMODE_FILE: + now = time(NULL); + strftime(timestr, sizeof timestr, "%Y-%m-%d %H:%M:%S", localtime(&now)); + fprintf(logfile, "%s %s[%ld]: %s\n", timestr, logident, (long)logpid, message); + fflush(logfile); + break; + case LOGMODE_SYSLOG: #ifdef HAVE_MINGW - { - char message[4096]; - const char *messages[] = {message}; - vsnprintf(message, sizeof message, format, ap); - ReportEvent(loghandle, priority, 0, 0, NULL, 1, 0, messages, NULL); - } + { + const char *messages[] = {message}; + ReportEvent(loghandle, priority, 0, 0, NULL, 1, 0, messages, NULL); + } #else #ifdef HAVE_SYSLOG_H -#ifdef HAVE_VSYSLOG - vsyslog(priority, format, ap); -#else - { - char message[4096]; - vsnprintf(message, sizeof message, format, ap); syslog(priority, "%s", message); - } -#endif - break; #endif #endif - case LOGMODE_NULL: - break; + break; + case LOGMODE_NULL: + break; + } } - va_end(ap); + if(logcontrol) { + suppress = true; + logcontrol = false; + for(splay_node_t *node = connection_tree->head; node; node = node->next) { + connection_t *c = node->data; + if(!c->status.log) + continue; + logcontrol = true; + if(level > (c->outcompression >= 0 ? c->outcompression : debug_level)) + continue; + int len = strlen(message); + if(send_request(c, "%d %d %d", CONTROL, REQ_LOG, len)) + send_meta(c, message, len); + } + suppress = false; + } } void closelogger(void) { diff --git a/src/logger.h b/src/logger.h index ff2cb345..4bd267f8 100644 --- a/src/logger.h +++ b/src/logger.h @@ -46,11 +46,10 @@ enum { #endif extern debug_t debug_level; +extern bool logcontrol; extern void openlogger(const char *, logmode_t); extern void reopenlogger(void); -extern void logger(int, const char *, ...) __attribute__ ((__format__(printf, 2, 3))); +extern void logger(int, int, const char *, ...) __attribute__ ((__format__(printf, 3, 4))); extern void closelogger(void); -#define ifdebug(l) if(debug_level >= DEBUG_##l) - #endif /* __TINC_LOGGER_H__ */ diff --git a/src/meta.c b/src/meta.c index fa031dbd..e286aea9 100644 --- a/src/meta.c +++ b/src/meta.c @@ -35,11 +35,11 @@ bool send_meta_sptps(void *handle, const char *buffer, size_t length) { connection_t *c = handle; if(!c) { - logger(LOG_ERR, "send_meta_sptps() called with NULL pointer!"); + logger(DEBUG_ALWAYS, LOG_ERR, "send_meta_sptps() called with NULL pointer!"); abort(); } - logger(LOG_DEBUG, "send_meta_sptps(%s, %p, %zu)", c->name, buffer, length); + logger(DEBUG_ALWAYS, LOG_DEBUG, "send_meta_sptps(%s, %p, %zu)", c->name, buffer, length); buffer_add(&c->outbuf, buffer, length); event_add(&c->outevent, NULL); @@ -49,11 +49,11 @@ bool send_meta_sptps(void *handle, const char *buffer, size_t length) { bool send_meta(connection_t *c, const char *buffer, int length) { if(!c) { - logger(LOG_ERR, "send_meta() called with NULL pointer!"); + logger(DEBUG_ALWAYS, LOG_ERR, "send_meta() called with NULL pointer!"); abort(); } - ifdebug(META) logger(LOG_DEBUG, "Sending %d bytes of metadata to %s (%s)", length, + logger(DEBUG_META, LOG_DEBUG, "Sending %d bytes of metadata to %s (%s)", length, c->name, c->hostname); if(c->protocol_minor >= 2) @@ -64,7 +64,7 @@ bool send_meta(connection_t *c, const char *buffer, int length) { size_t outlen = length; if(!cipher_encrypt(&c->outcipher, buffer, length, buffer_prepare(&c->outbuf, length), &outlen, false) || outlen != length) { - logger(LOG_ERR, "Error while encrypting metadata to %s (%s)", + logger(DEBUG_ALWAYS, LOG_ERR, "Error while encrypting metadata to %s (%s)", c->name, c->hostname); return false; } @@ -94,11 +94,11 @@ bool receive_meta_sptps(void *handle, uint8_t type, const char *data, uint16_t l connection_t *c = handle; if(!c) { - logger(LOG_ERR, "receive_meta_sptps() called with NULL pointer!"); + logger(DEBUG_ALWAYS, LOG_ERR, "receive_meta_sptps() called with NULL pointer!"); abort(); } - logger(LOG_DEBUG, "receive_meta_sptps(%s, %d, %p, %hu)", c->name, type, data, length); + logger(DEBUG_ALWAYS, LOG_DEBUG, "receive_meta_sptps(%s, %d, %p, %hu)", c->name, type, data, length); if(type == SPTPS_HANDSHAKE) { if(c->allow_request == ACK) @@ -142,7 +142,7 @@ bool receive_meta(connection_t *c) { buffer_compact(&c->inbuf, MAXBUFSIZE); if(sizeof inbuf <= c->inbuf.len) { - logger(LOG_ERR, "Input buffer full for %s (%s)", c->name, c->hostname); + logger(DEBUG_ALWAYS, LOG_ERR, "Input buffer full for %s (%s)", c->name, c->hostname); return false; } @@ -150,19 +150,19 @@ bool receive_meta(connection_t *c) { if(inlen <= 0) { if(!inlen || !errno) { - ifdebug(CONNECTIONS) logger(LOG_NOTICE, "Connection closed by %s (%s)", + logger(DEBUG_CONNECTIONS, LOG_NOTICE, "Connection closed by %s (%s)", c->name, c->hostname); } else if(sockwouldblock(sockerrno)) return true; else - logger(LOG_ERR, "Metadata socket read error for %s (%s): %s", + logger(DEBUG_ALWAYS, LOG_ERR, "Metadata socket read error for %s (%s): %s", c->name, c->hostname, sockstrerror(sockerrno)); return false; } do { if(c->protocol_minor >= 2) { - logger(LOG_DEBUG, "Receiving %d bytes of SPTPS data", inlen); + logger(DEBUG_ALWAYS, LOG_DEBUG, "Receiving %d bytes of SPTPS data", inlen); return sptps_receive_data(&c->sptps, bufp, inlen); } @@ -179,10 +179,10 @@ bool receive_meta(connection_t *c) { bufp = endp; } else { size_t outlen = inlen; - ifdebug(META) logger(LOG_DEBUG, "Received encrypted %d bytes", inlen); + logger(DEBUG_META, LOG_DEBUG, "Received encrypted %d bytes", inlen); if(!cipher_decrypt(&c->incipher, bufp, inlen, buffer_prepare(&c->inbuf, inlen), &outlen, false) || inlen != outlen) { - logger(LOG_ERR, "Error while decrypting metadata from %s (%s)", + logger(DEBUG_ALWAYS, LOG_ERR, "Error while decrypting metadata from %s (%s)", c->name, c->hostname); return false; } diff --git a/src/mingw/device.c b/src/mingw/device.c index e4683386..46ad9eb7 100644 --- a/src/mingw/device.c +++ b/src/mingw/device.c @@ -50,7 +50,7 @@ static DWORD WINAPI tapreader(void *bla) { OVERLAPPED overlapped; vpn_packet_t packet; - logger(LOG_DEBUG, "Tap reader running"); + logger(DEBUG_ALWAYS, LOG_DEBUG, "Tap reader running"); /* Read from tap device and send to parent */ @@ -69,7 +69,7 @@ static DWORD WINAPI tapreader(void *bla) { if(!GetOverlappedResult(device_handle, &overlapped, &len, FALSE)) continue; } else { - logger(LOG_ERR, "Error while reading from %s %s: %s", device_info, + logger(DEBUG_ALWAYS, LOG_ERR, "Error while reading from %s %s: %s", device_info, device, strerror(errno)); return -1; } @@ -105,7 +105,7 @@ static bool setup_device(void) { /* Open registry and look for network adapters */ if(RegOpenKeyEx(HKEY_LOCAL_MACHINE, NETWORK_CONNECTIONS_KEY, 0, KEY_READ, &key)) { - logger(LOG_ERR, "Unable to read registry: %s", winerror(GetLastError())); + logger(DEBUG_ALWAYS, LOG_ERR, "Unable to read registry: %s", winerror(GetLastError())); return false; } @@ -156,7 +156,7 @@ static bool setup_device(void) { RegCloseKey(key); if(!found) { - logger(LOG_ERR, "No Windows tap device found!"); + logger(DEBUG_ALWAYS, LOG_ERR, "No Windows tap device found!"); return false; } @@ -174,14 +174,14 @@ static bool setup_device(void) { } if(device_handle == INVALID_HANDLE_VALUE) { - logger(LOG_ERR, "%s (%s) is not a usable Windows tap device: %s", device, iface, winerror(GetLastError())); + logger(DEBUG_ALWAYS, LOG_ERR, "%s (%s) is not a usable Windows tap device: %s", device, iface, winerror(GetLastError())); return false; } /* Get MAC address from tap device */ if(!DeviceIoControl(device_handle, TAP_IOCTL_GET_MAC, mymac.x, sizeof mymac.x, mymac.x, sizeof mymac.x, &len, 0)) { - logger(LOG_ERR, "Could not get MAC address from Windows tap device %s (%s): %s", device, iface, winerror(GetLastError())); + logger(DEBUG_ALWAYS, LOG_ERR, "Could not get MAC address from Windows tap device %s (%s): %s", device, iface, winerror(GetLastError())); return false; } @@ -194,7 +194,7 @@ static bool setup_device(void) { thread = CreateThread(NULL, 0, tapreader, NULL, 0, NULL); if(!thread) { - logger(LOG_ERR, "System call `%s' failed: %s", "CreateThread", winerror(GetLastError())); + logger(DEBUG_ALWAYS, LOG_ERR, "System call `%s' failed: %s", "CreateThread", winerror(GetLastError())); return false; } @@ -205,7 +205,7 @@ static bool setup_device(void) { device_info = "Windows tap device"; - logger(LOG_INFO, "%s (%s) is a %s", device, iface, device_info); + logger(DEBUG_ALWAYS, LOG_INFO, "%s (%s) is a %s", device, iface, device_info); return true; } @@ -225,11 +225,11 @@ static bool write_packet(vpn_packet_t *packet) { long outlen; OVERLAPPED overlapped = {0}; - ifdebug(TRAFFIC) logger(LOG_DEBUG, "Writing packet of %d bytes to %s", + logger(DEBUG_TRAFFIC, LOG_DEBUG, "Writing packet of %d bytes to %s", packet->len, device_info); if(!WriteFile(device_handle, packet->data, packet->len, &outlen, &overlapped)) { - logger(LOG_ERR, "Error while writing to %s %s: %s", device_info, device, winerror(GetLastError())); + logger(DEBUG_ALWAYS, LOG_ERR, "Error while writing to %s %s: %s", device_info, device, winerror(GetLastError())); return false; } @@ -239,9 +239,9 @@ static bool write_packet(vpn_packet_t *packet) { } static void dump_device_stats(void) { - logger(LOG_DEBUG, "Statistics for %s %s:", device_info, device); - logger(LOG_DEBUG, " total bytes in: %10"PRIu64, device_total_in); - logger(LOG_DEBUG, " total bytes out: %10"PRIu64, device_total_out); + logger(DEBUG_ALWAYS, LOG_DEBUG, "Statistics for %s %s:", device_info, device); + logger(DEBUG_ALWAYS, LOG_DEBUG, " total bytes in: %10"PRIu64, device_total_in); + logger(DEBUG_ALWAYS, LOG_DEBUG, " total bytes out: %10"PRIu64, device_total_out); } const devops_t os_devops = { diff --git a/src/net.c b/src/net.c index c743d598..10a2d206 100644 --- a/src/net.c +++ b/src/net.c @@ -49,7 +49,7 @@ void purge(void) { edge_t *e; subnet_t *s; - ifdebug(PROTOCOL) logger(LOG_DEBUG, "Purging unreachable nodes"); + logger(DEBUG_PROTOCOL, LOG_DEBUG, "Purging unreachable nodes"); /* Remove all edges and subnets owned by unreachable nodes. */ @@ -58,8 +58,7 @@ void purge(void) { n = nnode->data; if(!n->status.reachable) { - ifdebug(SCARY_THINGS) logger(LOG_DEBUG, "Purging node %s (%s)", n->name, - n->hostname); + logger(DEBUG_SCARY_THINGS, LOG_DEBUG, "Purging node %s (%s)", n->name, n->hostname); for(snode = n->subnet_tree->head; snode; snode = snext) { snext = snode->next; @@ -109,7 +108,7 @@ void purge(void) { - Deactivate the host */ void terminate_connection(connection_t *c, bool report) { - ifdebug(CONNECTIONS) logger(LOG_NOTICE, "Closing connection with %s (%s)", + logger(DEBUG_CONNECTIONS, LOG_NOTICE, "Closing connection with %s (%s)", c->name, c->hostname); c->status.active = false; @@ -171,7 +170,7 @@ static void timeout_handler(int fd, short events, void *event) { if(c->last_ping_time + pingtimeout <= now) { if(c->status.active) { if(c->status.pinged) { - ifdebug(CONNECTIONS) logger(LOG_INFO, "%s (%s) didn't respond to PING in %ld seconds", + logger(DEBUG_CONNECTIONS, LOG_INFO, "%s (%s) didn't respond to PING in %ld seconds", c->name, c->hostname, now - c->last_ping_time); terminate_connection(c, true); continue; @@ -180,13 +179,12 @@ static void timeout_handler(int fd, short events, void *event) { } } else { if(c->status.connecting) { - ifdebug(CONNECTIONS) - logger(LOG_WARNING, "Timeout while connecting to %s (%s)", c->name, c->hostname); + logger(DEBUG_CONNECTIONS, LOG_WARNING, "Timeout while connecting to %s (%s)", c->name, c->hostname); c->status.connecting = false; closesocket(c->socket); do_outgoing_connection(c); } else { - ifdebug(CONNECTIONS) logger(LOG_WARNING, "Timeout from %s (%s) during authentication", c->name, c->hostname); + logger(DEBUG_CONNECTIONS, LOG_WARNING, "Timeout from %s (%s) during authentication", c->name, c->hostname); terminate_connection(c, false); continue; } @@ -195,7 +193,7 @@ static void timeout_handler(int fd, short events, void *event) { } if(contradicting_del_edge > 100 && contradicting_add_edge > 100) { - logger(LOG_WARNING, "Possible node with same Name as us! Sleeping %d seconds.", sleeptime); + logger(DEBUG_ALWAYS, LOG_WARNING, "Possible node with same Name as us! Sleeping %d seconds.", sleeptime); usleep(sleeptime * 1000000LL); sleeptime *= 2; if(sleeptime < 0) @@ -225,7 +223,7 @@ void handle_meta_connection_data(int fd, short events, void *data) { if(!result) finish_connecting(c); else { - ifdebug(CONNECTIONS) logger(LOG_DEBUG, + logger(DEBUG_CONNECTIONS, LOG_DEBUG, "Error while connecting to %s (%s): %s", c->name, c->hostname, sockstrerror(result)); closesocket(c->socket); @@ -241,18 +239,18 @@ void handle_meta_connection_data(int fd, short events, void *data) { } static void sigterm_handler(int signal, short events, void *data) { - logger(LOG_NOTICE, "Got %s signal", strsignal(signal)); + logger(DEBUG_ALWAYS, LOG_NOTICE, "Got %s signal", strsignal(signal)); event_loopexit(NULL); } static void sighup_handler(int signal, short events, void *data) { - logger(LOG_NOTICE, "Got %s signal", strsignal(signal)); + logger(DEBUG_ALWAYS, LOG_NOTICE, "Got %s signal", strsignal(signal)); reopenlogger(); reload_configuration(); } static void sigalrm_handler(int signal, short events, void *data) { - logger(LOG_NOTICE, "Got %s signal", strsignal(signal)); + logger(DEBUG_ALWAYS, LOG_NOTICE, "Got %s signal", strsignal(signal)); retry(); } @@ -269,7 +267,7 @@ int reload_configuration(void) { init_configuration(&config_tree); if(!read_server_config()) { - logger(LOG_ERR, "Unable to reread configuration file, exitting."); + logger(DEBUG_ALWAYS, LOG_ERR, "Unable to reread configuration file, exitting."); event_loopexit(NULL); return EINVAL; } @@ -381,7 +379,7 @@ int main_loop(void) { #endif if(event_loop(0) < 0) { - logger(LOG_ERR, "Error while waiting for input: %s", strerror(errno)); + logger(DEBUG_ALWAYS, LOG_ERR, "Error while waiting for input: %s", strerror(errno)); return 1; } diff --git a/src/net_packet.c b/src/net_packet.c index 870f9858..66bcfe4b 100644 --- a/src/net_packet.c +++ b/src/net_packet.c @@ -87,7 +87,7 @@ static void send_mtu_probe_handler(int fd, short events, void *data) { n->mtuprobes++; if(!n->status.reachable || !n->status.validkey) { - ifdebug(TRAFFIC) logger(LOG_INFO, "Trying to send MTU probe to unreachable or rekeying node %s (%s)", n->name, n->hostname); + logger(DEBUG_TRAFFIC, LOG_INFO, "Trying to send MTU probe to unreachable or rekeying node %s (%s)", n->name, n->hostname); n->mtuprobes = 0; return; } @@ -99,14 +99,14 @@ static void send_mtu_probe_handler(int fd, short events, void *data) { goto end; } - ifdebug(TRAFFIC) logger(LOG_INFO, "%s (%s) did not respond to UDP ping, restarting PMTU discovery", n->name, n->hostname); + logger(DEBUG_TRAFFIC, LOG_INFO, "%s (%s) did not respond to UDP ping, restarting PMTU discovery", n->name, n->hostname); n->mtuprobes = 1; n->minmtu = 0; n->maxmtu = MTU; } if(n->mtuprobes >= 10 && n->mtuprobes < 32 && !n->minmtu) { - ifdebug(TRAFFIC) logger(LOG_INFO, "No response to MTU probes from %s (%s)", n->name, n->hostname); + logger(DEBUG_TRAFFIC, LOG_INFO, "No response to MTU probes from %s (%s)", n->name, n->hostname); n->mtuprobes = 31; } @@ -116,7 +116,7 @@ static void send_mtu_probe_handler(int fd, short events, void *data) { else n->maxmtu = n->minmtu; n->mtu = n->minmtu; - ifdebug(TRAFFIC) logger(LOG_INFO, "Fixing MTU of %s (%s) to %d after %d probes", n->name, n->hostname, n->mtu, n->mtuprobes); + logger(DEBUG_TRAFFIC, LOG_INFO, "Fixing MTU of %s (%s) to %d after %d probes", n->name, n->hostname, n->mtu, n->mtuprobes); n->mtuprobes = 31; } @@ -144,7 +144,7 @@ static void send_mtu_probe_handler(int fd, short events, void *data) { else packet.priority = 0; - ifdebug(TRAFFIC) logger(LOG_INFO, "Sending MTU probe length %d to %s (%s)", len, n->name, n->hostname); + logger(DEBUG_TRAFFIC, LOG_INFO, "Sending MTU probe length %d to %s (%s)", len, n->name, n->hostname); send_udppacket(n, &packet); } @@ -160,7 +160,7 @@ void send_mtu_probe(node_t *n) { } static void mtu_probe_h(node_t *n, vpn_packet_t *packet, length_t len) { - ifdebug(TRAFFIC) logger(LOG_INFO, "Got MTU probe length %d from %s (%s)", packet->len, n->name, n->hostname); + logger(DEBUG_TRAFFIC, LOG_INFO, "Got MTU probe length %d from %s (%s)", packet->len, n->name, n->hostname); if(!packet->data[0]) { packet->data[0] = 1; @@ -242,7 +242,7 @@ static length_t uncompress_packet(uint8_t *dest, const uint8_t *source, length_t /* VPN packet I/O */ static void receive_packet(node_t *n, vpn_packet_t *packet) { - ifdebug(TRAFFIC) logger(LOG_DEBUG, "Received packet of %d bytes from %s (%s)", + logger(DEBUG_TRAFFIC, LOG_DEBUG, "Received packet of %d bytes from %s (%s)", packet->len, n->name, n->hostname); n->in_packets++; @@ -266,7 +266,7 @@ static void receive_udppacket(node_t *n, vpn_packet_t *inpkt) { size_t outlen; if(!cipher_active(&n->incipher)) { - ifdebug(TRAFFIC) logger(LOG_DEBUG, "Got packet from %s (%s) but he hasn't got our key yet", + logger(DEBUG_TRAFFIC, LOG_DEBUG, "Got packet from %s (%s) but he hasn't got our key yet", n->name, n->hostname); return; } @@ -274,7 +274,7 @@ static void receive_udppacket(node_t *n, vpn_packet_t *inpkt) { /* Check packet length */ if(inpkt->len < sizeof inpkt->seqno + digest_length(&n->indigest)) { - ifdebug(TRAFFIC) logger(LOG_DEBUG, "Got too short packet from %s (%s)", + logger(DEBUG_TRAFFIC, LOG_DEBUG, "Got too short packet from %s (%s)", n->name, n->hostname); return; } @@ -284,7 +284,7 @@ static void receive_udppacket(node_t *n, vpn_packet_t *inpkt) { if(digest_active(&n->indigest)) { inpkt->len -= n->indigest.maclength; if(!digest_verify(&n->indigest, &inpkt->seqno, inpkt->len, (const char *)&inpkt->seqno + inpkt->len)) { - ifdebug(TRAFFIC) logger(LOG_DEBUG, "Got unauthenticated packet from %s (%s)", n->name, n->hostname); + logger(DEBUG_TRAFFIC, LOG_DEBUG, "Got unauthenticated packet from %s (%s)", n->name, n->hostname); return; } } @@ -295,7 +295,7 @@ static void receive_udppacket(node_t *n, vpn_packet_t *inpkt) { outlen = MAXSIZE; if(!cipher_decrypt(&n->incipher, &inpkt->seqno, inpkt->len, &outpkt->seqno, &outlen, true)) { - ifdebug(TRAFFIC) logger(LOG_DEBUG, "Error decrypting packet from %s (%s)", n->name, n->hostname); + logger(DEBUG_TRAFFIC, LOG_DEBUG, "Error decrypting packet from %s (%s)", n->name, n->hostname); return; } @@ -312,16 +312,16 @@ static void receive_udppacket(node_t *n, vpn_packet_t *inpkt) { if(inpkt->seqno != n->received_seqno + 1) { if(inpkt->seqno >= n->received_seqno + replaywin * 8) { if(n->farfuture++ < replaywin >> 2) { - logger(LOG_WARNING, "Packet from %s (%s) is %d seqs in the future, dropped (%u)", + logger(DEBUG_ALWAYS, LOG_WARNING, "Packet from %s (%s) is %d seqs in the future, dropped (%u)", n->name, n->hostname, inpkt->seqno - n->received_seqno - 1, n->farfuture); return; } - logger(LOG_WARNING, "Lost %d packets from %s (%s)", + logger(DEBUG_ALWAYS, LOG_WARNING, "Lost %d packets from %s (%s)", inpkt->seqno - n->received_seqno - 1, n->name, n->hostname); memset(n->late, 0, replaywin); } else if (inpkt->seqno <= n->received_seqno) { if((n->received_seqno >= replaywin * 8 && inpkt->seqno <= n->received_seqno - replaywin * 8) || !(n->late[(inpkt->seqno / 8) % replaywin] & (1 << inpkt->seqno % 8))) { - logger(LOG_WARNING, "Got late or replayed packet from %s (%s), seqno %d, last received %d", + logger(DEBUG_ALWAYS, LOG_WARNING, "Got late or replayed packet from %s (%s), seqno %d, last received %d", n->name, n->hostname, inpkt->seqno, n->received_seqno); return; } @@ -349,7 +349,7 @@ static void receive_udppacket(node_t *n, vpn_packet_t *inpkt) { outpkt = pkt[nextpkt++]; if((outpkt->len = uncompress_packet(outpkt->data, inpkt->data, inpkt->len, n->incompression)) < 0) { - ifdebug(TRAFFIC) logger(LOG_ERR, "Error while uncompressing packet from %s (%s)", + logger(DEBUG_TRAFFIC, LOG_ERR, "Error while uncompressing packet from %s (%s)", n->name, n->hostname); return; } @@ -394,7 +394,7 @@ static void send_udppacket(node_t *n, vpn_packet_t *origpkt) { #endif if(!n->status.reachable) { - ifdebug(TRAFFIC) logger(LOG_INFO, "Trying to send UDP packet to unreachable node %s (%s)", n->name, n->hostname); + logger(DEBUG_TRAFFIC, LOG_INFO, "Trying to send UDP packet to unreachable node %s (%s)", n->name, n->hostname); return; } @@ -403,7 +403,7 @@ static void send_udppacket(node_t *n, vpn_packet_t *origpkt) { if(!n->status.validkey) { time_t now = time(NULL); - ifdebug(TRAFFIC) logger(LOG_INFO, + logger(DEBUG_TRAFFIC, LOG_INFO, "No valid key known yet for %s (%s), forwarding via TCP", n->name, n->hostname); @@ -418,7 +418,7 @@ static void send_udppacket(node_t *n, vpn_packet_t *origpkt) { } if(n->options & OPTION_PMTU_DISCOVERY && inpkt->len > n->minmtu && (inpkt->data[12] | inpkt->data[13])) { - ifdebug(TRAFFIC) logger(LOG_INFO, + logger(DEBUG_TRAFFIC, LOG_INFO, "Packet for %s (%s) larger than minimum MTU, forwarding via %s", n->name, n->hostname, n != n->nexthop ? n->nexthop->name : "TCP"); @@ -436,7 +436,7 @@ static void send_udppacket(node_t *n, vpn_packet_t *origpkt) { outpkt = pkt[nextpkt++]; if((outpkt->len = compress_packet(outpkt->data, inpkt->data, inpkt->len, n->outcompression)) < 0) { - ifdebug(TRAFFIC) logger(LOG_ERR, "Error while compressing packet to %s (%s)", + logger(DEBUG_TRAFFIC, LOG_ERR, "Error while compressing packet to %s (%s)", n->name, n->hostname); return; } @@ -456,7 +456,7 @@ static void send_udppacket(node_t *n, vpn_packet_t *origpkt) { outlen = MAXSIZE; if(!cipher_encrypt(&n->outcipher, &inpkt->seqno, inpkt->len, &outpkt->seqno, &outlen, true)) { - ifdebug(TRAFFIC) logger(LOG_ERR, "Error while encrypting packet to %s (%s)", n->name, n->hostname); + logger(DEBUG_TRAFFIC, LOG_ERR, "Error while encrypting packet to %s (%s)", n->name, n->hostname); goto end; } @@ -511,9 +511,9 @@ static void send_udppacket(node_t *n, vpn_packet_t *origpkt) { if(priorityinheritance && origpriority != priority && listen_socket[n->sock].sa.sa.sa_family == AF_INET) { priority = origpriority; - ifdebug(TRAFFIC) logger(LOG_DEBUG, "Setting outgoing packet priority to %d", priority); + logger(DEBUG_TRAFFIC, LOG_DEBUG, "Setting outgoing packet priority to %d", priority); if(setsockopt(listen_socket[n->sock].udp, SOL_IP, IP_TOS, &priority, sizeof(priority))) /* SO_PRIORITY doesn't seem to work */ - logger(LOG_ERR, "System call `%s' failed: %s", "setsockopt", strerror(errno)); + logger(DEBUG_ALWAYS, LOG_ERR, "System call `%s' failed: %s", "setsockopt", strerror(errno)); } #endif @@ -524,7 +524,7 @@ static void send_udppacket(node_t *n, vpn_packet_t *origpkt) { if(n->mtu >= origlen) n->mtu = origlen - 1; } else - logger(LOG_ERR, "Error sending packet to %s (%s): %s", n->name, n->hostname, sockstrerror(sockerrno)); + logger(DEBUG_ALWAYS, LOG_ERR, "Error sending packet to %s (%s): %s", n->name, n->hostname, sockstrerror(sockerrno)); } end: @@ -546,11 +546,11 @@ void send_packet(node_t *n, vpn_packet_t *packet) { return; } - ifdebug(TRAFFIC) logger(LOG_ERR, "Sending packet of %d bytes to %s (%s)", + logger(DEBUG_TRAFFIC, LOG_ERR, "Sending packet of %d bytes to %s (%s)", packet->len, n->name, n->hostname); if(!n->status.reachable) { - ifdebug(TRAFFIC) logger(LOG_INFO, "Node %s (%s) is not reachable", + logger(DEBUG_TRAFFIC, LOG_INFO, "Node %s (%s) is not reachable", n->name, n->hostname); return; } @@ -561,7 +561,7 @@ void send_packet(node_t *n, vpn_packet_t *packet) { via = (packet->priority == -1 || n->via == myself) ? n->nexthop : n->via; if(via != n) - ifdebug(TRAFFIC) logger(LOG_INFO, "Sending packet to %s via %s (%s)", + logger(DEBUG_TRAFFIC, LOG_INFO, "Sending packet to %s via %s (%s)", n->name, via->name, n->via->hostname); if(packet->priority == -1 || ((myself->options | via->options) & OPTION_TCPONLY)) { @@ -577,7 +577,7 @@ void broadcast_packet(const node_t *from, vpn_packet_t *packet) { splay_node_t *node; connection_t *c; - ifdebug(TRAFFIC) logger(LOG_INFO, "Broadcasting packet of %d bytes from %s (%s)", + logger(DEBUG_TRAFFIC, LOG_INFO, "Broadcasting packet of %d bytes from %s (%s)", packet->len, from->name, from->hostname); if(from != myself) { @@ -643,7 +643,7 @@ void handle_incoming_vpn_data(int sock, short events, void *data) { if(len <= 0 || len > MAXSIZE) { if(!sockwouldblock(sockerrno)) - logger(LOG_ERR, "Receiving packet failed: %s", sockstrerror(sockerrno)); + logger(DEBUG_ALWAYS, LOG_ERR, "Receiving packet failed: %s", sockstrerror(sockerrno)); return; } @@ -657,9 +657,9 @@ void handle_incoming_vpn_data(int sock, short events, void *data) { n = try_harder(&from, &pkt); if(n) update_node_udp(n, &from); - else ifdebug(PROTOCOL) { + else if(debug_level >= DEBUG_PROTOCOL) { hostname = sockaddr2hostname(&from); - logger(LOG_WARNING, "Received UDP packet from unknown source %s", hostname); + logger(DEBUG_PROTOCOL, LOG_WARNING, "Received UDP packet from unknown source %s", hostname); free(hostname); return; } diff --git a/src/net_setup.c b/src/net_setup.c index d292d850..f63059f8 100644 --- a/src/net_setup.c +++ b/src/net_setup.c @@ -80,7 +80,7 @@ bool node_read_ecdsa_public_key(node_t *n) { fp = fopen(fname, "r"); if(!fp) { - logger(LOG_ERR, "Error reading ECDSA public key file `%s': %s", fname, strerror(errno)); + logger(DEBUG_ALWAYS, LOG_ERR, "Error reading ECDSA public key file `%s': %s", fname, strerror(errno)); goto exit; } @@ -115,7 +115,7 @@ bool read_ecdsa_public_key(connection_t *c) { fp = fopen(fname, "r"); if(!fp) { - logger(LOG_ERR, "Error reading ECDSA public key file `%s': %s", + logger(DEBUG_ALWAYS, LOG_ERR, "Error reading ECDSA public key file `%s': %s", fname, strerror(errno)); free(fname); return false; @@ -125,7 +125,7 @@ bool read_ecdsa_public_key(connection_t *c) { fclose(fp); if(!result) - logger(LOG_ERR, "Reading ECDSA public key file `%s' failed: %s", fname, strerror(errno)); + logger(DEBUG_ALWAYS, LOG_ERR, "Reading ECDSA public key file `%s' failed: %s", fname, strerror(errno)); free(fname); return result; } @@ -152,7 +152,7 @@ bool read_rsa_public_key(connection_t *c) { fp = fopen(fname, "r"); if(!fp) { - logger(LOG_ERR, "Error reading RSA public key file `%s': %s", fname, strerror(errno)); + logger(DEBUG_ALWAYS, LOG_ERR, "Error reading RSA public key file `%s': %s", fname, strerror(errno)); free(fname); return false; } @@ -161,7 +161,7 @@ bool read_rsa_public_key(connection_t *c) { fclose(fp); if(!result) - logger(LOG_ERR, "Reading RSA public key file `%s' failed: %s", fname, strerror(errno)); + logger(DEBUG_ALWAYS, LOG_ERR, "Reading RSA public key file `%s' failed: %s", fname, strerror(errno)); free(fname); return result; } @@ -179,7 +179,7 @@ static bool read_ecdsa_private_key(void) { fp = fopen(fname, "r"); if(!fp) { - logger(LOG_ERR, "Error reading ECDSA private key file `%s': %s", fname, strerror(errno)); + logger(DEBUG_ALWAYS, LOG_ERR, "Error reading ECDSA private key file `%s': %s", fname, strerror(errno)); free(fname); return false; } @@ -188,20 +188,20 @@ static bool read_ecdsa_private_key(void) { struct stat s; if(fstat(fileno(fp), &s)) { - logger(LOG_ERR, "Could not stat ECDSA private key file `%s': %s'", fname, strerror(errno)); + logger(DEBUG_ALWAYS, LOG_ERR, "Could not stat ECDSA private key file `%s': %s'", fname, strerror(errno)); free(fname); return false; } if(s.st_mode & ~0100700) - logger(LOG_WARNING, "Warning: insecure file permissions for ECDSA private key file `%s'!", fname); + logger(DEBUG_ALWAYS, LOG_WARNING, "Warning: insecure file permissions for ECDSA private key file `%s'!", fname); #endif result = ecdsa_read_pem_private_key(&myself->connection->ecdsa, fp); fclose(fp); if(!result) - logger(LOG_ERR, "Reading ECDSA private key file `%s' failed: %s", fname, strerror(errno)); + logger(DEBUG_ALWAYS, LOG_ERR, "Reading ECDSA private key file `%s' failed: %s", fname, strerror(errno)); free(fname); return result; } @@ -216,7 +216,7 @@ static bool read_rsa_private_key(void) { if(get_config_string(lookup_config(config_tree, "PrivateKey"), &d)) { if(!get_config_string(lookup_config(config_tree, "PublicKey"), &n)) { - logger(LOG_ERR, "PrivateKey used but no PublicKey found!"); + logger(DEBUG_ALWAYS, LOG_ERR, "PrivateKey used but no PublicKey found!"); free(d); return false; } @@ -234,7 +234,7 @@ static bool read_rsa_private_key(void) { fp = fopen(fname, "r"); if(!fp) { - logger(LOG_ERR, "Error reading RSA private key file `%s': %s", + logger(DEBUG_ALWAYS, LOG_ERR, "Error reading RSA private key file `%s': %s", fname, strerror(errno)); free(fname); return false; @@ -244,20 +244,20 @@ static bool read_rsa_private_key(void) { struct stat s; if(fstat(fileno(fp), &s)) { - logger(LOG_ERR, "Could not stat RSA private key file `%s': %s'", fname, strerror(errno)); + logger(DEBUG_ALWAYS, LOG_ERR, "Could not stat RSA private key file `%s': %s'", fname, strerror(errno)); free(fname); return false; } if(s.st_mode & ~0100700) - logger(LOG_WARNING, "Warning: insecure file permissions for RSA private key file `%s'!", fname); + logger(DEBUG_ALWAYS, LOG_WARNING, "Warning: insecure file permissions for RSA private key file `%s'!", fname); #endif result = rsa_read_pem_private_key(&myself->connection->rsa, fp); fclose(fp); if(!result) - logger(LOG_ERR, "Reading RSA private key file `%s' failed: %s", fname, strerror(errno)); + logger(DEBUG_ALWAYS, LOG_ERR, "Reading RSA private key file `%s' failed: %s", fname, strerror(errno)); free(fname); return result; } @@ -270,7 +270,7 @@ static void keyexpire_handler(int fd, short events, void *data) { void regenerate_key(void) { if(timeout_initialized(&keyexpire_event)) { - ifdebug(STATUS) logger(LOG_INFO, "Expiring symmetric keys"); + logger(DEBUG_STATUS, LOG_INFO, "Expiring symmetric keys"); event_del(&keyexpire_event); send_key_changed(); } else { @@ -297,7 +297,7 @@ void load_all_subnets(void) { xasprintf(&dname, "%s/hosts", confbase); dir = opendir(dname); if(!dir) { - logger(LOG_ERR, "Could not open %s: %s", dname, strerror(errno)); + logger(DEBUG_ALWAYS, LOG_ERR, "Could not open %s: %s", dname, strerror(errno)); free(dname); return; } @@ -368,12 +368,12 @@ static bool setup_myself(void) { myself->connection->protocol_minor = PROT_MINOR; if(!get_config_string(lookup_config(config_tree, "Name"), &name)) { /* Not acceptable */ - logger(LOG_ERR, "Name for tinc daemon required!"); + logger(DEBUG_ALWAYS, LOG_ERR, "Name for tinc daemon required!"); return false; } if(!check_id(name)) { - logger(LOG_ERR, "Invalid name for myself!"); + logger(DEBUG_ALWAYS, LOG_ERR, "Invalid name for myself!"); free(name); return false; } @@ -444,7 +444,7 @@ static bool setup_myself(void) { else if(!strcasecmp(mode, "hub")) routing_mode = RMODE_HUB; else { - logger(LOG_ERR, "Invalid routing mode!"); + logger(DEBUG_ALWAYS, LOG_ERR, "Invalid routing mode!"); return false; } free(mode); @@ -458,7 +458,7 @@ static bool setup_myself(void) { else if(!strcasecmp(mode, "kernel")) forwarding_mode = FMODE_KERNEL; else { - logger(LOG_ERR, "Invalid forwarding mode!"); + logger(DEBUG_ALWAYS, LOG_ERR, "Invalid forwarding mode!"); return false; } free(mode); @@ -480,7 +480,7 @@ static bool setup_myself(void) { #if !defined(SOL_IP) || !defined(IP_TOS) if(priorityinheritance) - logger(LOG_WARNING, "%s not supported on this platform", "PriorityInheritance"); + logger(DEBUG_ALWAYS, LOG_WARNING, "%s not supported on this platform", "PriorityInheritance"); #endif if(!get_config_int(lookup_config(config_tree, "MACExpire"), &macexpire)) @@ -488,7 +488,7 @@ static bool setup_myself(void) { if(get_config_int(lookup_config(config_tree, "MaxTimeout"), &maxtimeout)) { if(maxtimeout <= 0) { - logger(LOG_ERR, "Bogus maximum timeout!"); + logger(DEBUG_ALWAYS, LOG_ERR, "Bogus maximum timeout!"); return false; } } else @@ -496,21 +496,21 @@ static bool setup_myself(void) { if(get_config_int(lookup_config(config_tree, "UDPRcvBuf"), &udp_rcvbuf)) { if(udp_rcvbuf <= 0) { - logger(LOG_ERR, "UDPRcvBuf cannot be negative!"); + logger(DEBUG_ALWAYS, LOG_ERR, "UDPRcvBuf cannot be negative!"); return false; } } if(get_config_int(lookup_config(config_tree, "UDPSndBuf"), &udp_sndbuf)) { if(udp_sndbuf <= 0) { - logger(LOG_ERR, "UDPSndBuf cannot be negative!"); + logger(DEBUG_ALWAYS, LOG_ERR, "UDPSndBuf cannot be negative!"); return false; } } if(get_config_int(lookup_config(config_tree, "ReplayWindow"), &replaywin_int)) { if(replaywin_int < 0) { - logger(LOG_ERR, "ReplayWindow cannot be negative!"); + logger(DEBUG_ALWAYS, LOG_ERR, "ReplayWindow cannot be negative!"); return false; } replaywin = (unsigned)replaywin_int; @@ -524,7 +524,7 @@ static bool setup_myself(void) { else if(!strcasecmp(afname, "any")) addressfamily = AF_UNSPEC; else { - logger(LOG_ERR, "Invalid address family!"); + logger(DEBUG_ALWAYS, LOG_ERR, "Invalid address family!"); return false; } free(afname); @@ -538,7 +538,7 @@ static bool setup_myself(void) { cipher = xstrdup("blowfish"); if(!cipher_open_by_name(&myself->incipher, cipher)) { - logger(LOG_ERR, "Unrecognized cipher type!"); + logger(DEBUG_ALWAYS, LOG_ERR, "Unrecognized cipher type!"); return false; } @@ -553,7 +553,7 @@ static bool setup_myself(void) { get_config_int(lookup_config(config_tree, "MACLength"), &maclength); if(maclength < 0) { - logger(LOG_ERR, "Bogus MAC length!"); + logger(DEBUG_ALWAYS, LOG_ERR, "Bogus MAC length!"); return false; } @@ -561,7 +561,7 @@ static bool setup_myself(void) { digest = xstrdup("sha1"); if(!digest_open_by_name(&myself->indigest, digest, maclength)) { - logger(LOG_ERR, "Unrecognized digest type!"); + logger(DEBUG_ALWAYS, LOG_ERR, "Unrecognized digest type!"); return false; } @@ -569,7 +569,7 @@ static bool setup_myself(void) { if(get_config_int(lookup_config(config_tree, "Compression"), &myself->incompression)) { if(myself->incompression < 0 || myself->incompression > 11) { - logger(LOG_ERR, "Bogus compression level!"); + logger(DEBUG_ALWAYS, LOG_ERR, "Bogus compression level!"); return false; } } else @@ -615,7 +615,7 @@ static bool setup_myself(void) { event_set(&device_ev, device_fd, EV_READ|EV_PERSIST, handle_device_data, NULL); if (event_add(&device_ev, NULL) < 0) { - logger(LOG_ERR, "event_add failed: %s", strerror(errno)); + logger(DEBUG_ALWAYS, LOG_ERR, "event_add failed: %s", strerror(errno)); devops.close(); return false; } @@ -656,14 +656,14 @@ static bool setup_myself(void) { free(address); if(err || !ai) { - logger(LOG_ERR, "System call `%s' failed: %s", "getaddrinfo", + logger(DEBUG_ALWAYS, LOG_ERR, "System call `%s' failed: %s", "getaddrinfo", gai_strerror(err)); return false; } for(aip = ai; aip; aip = aip->ai_next) { if(listen_sockets >= MAXSOCKETS) { - logger(LOG_ERR, "Too many listening sockets"); + logger(DEBUG_ALWAYS, LOG_ERR, "Too many listening sockets"); return false; } @@ -686,7 +686,7 @@ static bool setup_myself(void) { EV_READ|EV_PERSIST, handle_new_meta_connection, NULL); if(event_add(&listen_socket[listen_sockets].ev_tcp, NULL) < 0) { - logger(LOG_ERR, "event_add failed: %s", strerror(errno)); + logger(DEBUG_ALWAYS, LOG_ERR, "event_add failed: %s", strerror(errno)); abort(); } @@ -695,13 +695,13 @@ static bool setup_myself(void) { EV_READ|EV_PERSIST, handle_incoming_vpn_data, (void *)(intptr_t)listen_sockets); if(event_add(&listen_socket[listen_sockets].ev_udp, NULL) < 0) { - logger(LOG_ERR, "event_add failed: %s", strerror(errno)); + logger(DEBUG_ALWAYS, LOG_ERR, "event_add failed: %s", strerror(errno)); abort(); } - ifdebug(CONNECTIONS) { + if(debug_level >= DEBUG_CONNECTIONS) { hostname = sockaddr2hostname((sockaddr_t *) aip->ai_addr); - logger(LOG_NOTICE, "Listening on %s", hostname); + logger(DEBUG_CONNECTIONS, LOG_NOTICE, "Listening on %s", hostname); free(hostname); } @@ -713,9 +713,9 @@ static bool setup_myself(void) { } while(cfg); if(listen_sockets) - logger(LOG_NOTICE, "Ready"); + logger(DEBUG_ALWAYS, LOG_NOTICE, "Ready"); else { - logger(LOG_ERR, "Unable to create any listening socket!"); + logger(DEBUG_ALWAYS, LOG_ERR, "Unable to create any listening socket!"); return false; } diff --git a/src/net_socket.c b/src/net_socket.c index 28206697..af3f2fe6 100644 --- a/src/net_socket.c +++ b/src/net_socket.c @@ -57,13 +57,13 @@ static void configure_tcp(connection_t *c) { int flags = fcntl(c->socket, F_GETFL); if(fcntl(c->socket, F_SETFL, flags | O_NONBLOCK) < 0) { - logger(LOG_ERR, "fcntl for %s: %s", c->hostname, strerror(errno)); + logger(DEBUG_ALWAYS, LOG_ERR, "fcntl for %s: %s", c->hostname, strerror(errno)); } #elif defined(WIN32) unsigned long arg = 1; if(ioctlsocket(c->socket, FIONBIO, &arg) != 0) { - logger(LOG_ERR, "ioctlsocket for %s: %d", c->hostname, sockstrerror(sockerrno)); + logger(DEBUG_ALWAYS, LOG_ERR, "ioctlsocket for %s: %d", c->hostname, sockstrerror(sockerrno)); } #endif @@ -96,12 +96,12 @@ static bool bind_to_interface(int sd) { status = setsockopt(sd, SOL_SOCKET, SO_BINDTODEVICE, (void *)&ifr, sizeof(ifr)); if(status) { - logger(LOG_ERR, "Can't bind to interface %s: %s", iface, + logger(DEBUG_ALWAYS, LOG_ERR, "Can't bind to interface %s: %s", iface, strerror(errno)); return false; } #else /* if !defined(SOL_SOCKET) || !defined(SO_BINDTODEVICE) */ - logger(LOG_WARNING, "%s not supported on this platform", "BindToInterface"); + logger(DEBUG_ALWAYS, LOG_WARNING, "%s not supported on this platform", "BindToInterface"); #endif return true; @@ -116,7 +116,7 @@ int setup_listen_socket(const sockaddr_t *sa) { nfd = socket(sa->sa.sa_family, SOCK_STREAM, IPPROTO_TCP); if(nfd < 0) { - ifdebug(STATUS) logger(LOG_ERR, "Creating metasocket failed: %s", sockstrerror(sockerrno)); + logger(DEBUG_STATUS, LOG_ERR, "Creating metasocket failed: %s", sockstrerror(sockerrno)); return -1; } @@ -144,26 +144,26 @@ int setup_listen_socket(const sockaddr_t *sa) { if(setsockopt(nfd, SOL_SOCKET, SO_BINDTODEVICE, (void *)&ifr, sizeof ifr)) { closesocket(nfd); - logger(LOG_ERR, "Can't bind to interface %s: %s", iface, + logger(DEBUG_ALWAYS, LOG_ERR, "Can't bind to interface %s: %s", iface, strerror(sockerrno)); return -1; } #else - logger(LOG_WARNING, "%s not supported on this platform", "BindToInterface"); + logger(DEBUG_ALWAYS, LOG_WARNING, "%s not supported on this platform", "BindToInterface"); #endif } if(bind(nfd, &sa->sa, SALEN(sa->sa))) { closesocket(nfd); addrstr = sockaddr2hostname(sa); - logger(LOG_ERR, "Can't bind to %s/tcp: %s", addrstr, sockstrerror(sockerrno)); + logger(DEBUG_ALWAYS, LOG_ERR, "Can't bind to %s/tcp: %s", addrstr, sockstrerror(sockerrno)); free(addrstr); return -1; } if(listen(nfd, 3)) { closesocket(nfd); - logger(LOG_ERR, "System call `%s' failed: %s", "listen", sockstrerror(sockerrno)); + logger(DEBUG_ALWAYS, LOG_ERR, "System call `%s' failed: %s", "listen", sockstrerror(sockerrno)); return -1; } @@ -178,7 +178,7 @@ int setup_vpn_in_socket(const sockaddr_t *sa) { nfd = socket(sa->sa.sa_family, SOCK_DGRAM, IPPROTO_UDP); if(nfd < 0) { - logger(LOG_ERR, "Creating UDP socket failed: %s", sockstrerror(sockerrno)); + logger(DEBUG_ALWAYS, LOG_ERR, "Creating UDP socket failed: %s", sockstrerror(sockerrno)); return -1; } @@ -192,7 +192,7 @@ int setup_vpn_in_socket(const sockaddr_t *sa) { if(fcntl(nfd, F_SETFL, flags | O_NONBLOCK) < 0) { closesocket(nfd); - logger(LOG_ERR, "System call `%s' failed: %s", "fcntl", + logger(DEBUG_ALWAYS, LOG_ERR, "System call `%s' failed: %s", "fcntl", strerror(errno)); return -1; } @@ -202,7 +202,7 @@ int setup_vpn_in_socket(const sockaddr_t *sa) { unsigned long arg = 1; if(ioctlsocket(nfd, FIONBIO, &arg) != 0) { closesocket(nfd); - logger(LOG_ERR, "Call to `%s' failed: %s", "ioctlsocket", sockstrerror(sockerrno)); + logger(DEBUG_ALWAYS, LOG_ERR, "Call to `%s' failed: %s", "ioctlsocket", sockstrerror(sockerrno)); return -1; } } @@ -213,10 +213,10 @@ int setup_vpn_in_socket(const sockaddr_t *sa) { setsockopt(nfd, SOL_SOCKET, SO_BROADCAST, (void *)&option, sizeof option); if(udp_rcvbuf && setsockopt(nfd, SOL_SOCKET, SO_RCVBUF, (void *)&udp_rcvbuf, sizeof(udp_rcvbuf))) - logger(LOG_WARNING, "Can't set UDP SO_RCVBUF to %i: %s", udp_rcvbuf, strerror(errno)); + logger(DEBUG_ALWAYS, LOG_WARNING, "Can't set UDP SO_RCVBUF to %i: %s", udp_rcvbuf, strerror(errno)); if(udp_sndbuf && setsockopt(nfd, SOL_SOCKET, SO_SNDBUF, (void *)&udp_sndbuf, sizeof(udp_sndbuf))) - logger(LOG_WARNING, "Can't set UDP SO_SNDBUF to %i: %s", udp_sndbuf, strerror(errno)); + logger(DEBUG_ALWAYS, LOG_WARNING, "Can't set UDP SO_SNDBUF to %i: %s", udp_sndbuf, strerror(errno)); #if defined(IPPROTO_IPV6) && defined(IPV6_V6ONLY) if(sa->sa.sa_family == AF_INET6) @@ -263,7 +263,7 @@ int setup_vpn_in_socket(const sockaddr_t *sa) { if(bind(nfd, &sa->sa, SALEN(sa->sa))) { closesocket(nfd); addrstr = sockaddr2hostname(sa); - logger(LOG_ERR, "Can't bind to %s/udp: %s", addrstr, sockstrerror(sockerrno)); + logger(DEBUG_ALWAYS, LOG_ERR, "Can't bind to %s/udp: %s", addrstr, sockstrerror(sockerrno)); free(addrstr); return -1; } @@ -284,13 +284,13 @@ void retry_outgoing(outgoing_t *outgoing) { timeout_set(&outgoing->ev, retry_outgoing_handler, outgoing); event_add(&outgoing->ev, &(struct timeval){outgoing->timeout, 0}); - ifdebug(CONNECTIONS) logger(LOG_NOTICE, + logger(DEBUG_CONNECTIONS, LOG_NOTICE, "Trying to re-establish outgoing connection in %d seconds", outgoing->timeout); } void finish_connecting(connection_t *c) { - ifdebug(CONNECTIONS) logger(LOG_INFO, "Connected to %s (%s)", c->name, c->hostname); + logger(DEBUG_CONNECTIONS, LOG_INFO, "Connected to %s (%s)", c->name, c->hostname); configure_tcp(c); @@ -305,14 +305,14 @@ bool do_outgoing_connection(connection_t *c) { int result; if(!c->outgoing) { - logger(LOG_ERR, "do_outgoing_connection() for %s called without c->outgoing", c->name); + logger(DEBUG_ALWAYS, LOG_ERR, "do_outgoing_connection() for %s called without c->outgoing", c->name); abort(); } begin: if(!c->outgoing->ai) { if(!c->outgoing->cfg) { - ifdebug(CONNECTIONS) logger(LOG_ERR, "Could not set up a meta connection to %s", + logger(DEBUG_CONNECTIONS, LOG_ERR, "Could not set up a meta connection to %s", c->name); retry_outgoing(c->outgoing); c->outgoing = NULL; @@ -354,7 +354,7 @@ begin: c->hostname = sockaddr2hostname(&c->address); - ifdebug(CONNECTIONS) logger(LOG_INFO, "Trying to connect to %s (%s)", c->name, + logger(DEBUG_CONNECTIONS, LOG_INFO, "Trying to connect to %s (%s)", c->name, c->hostname); c->socket = socket(c->address.sa.sa_family, SOCK_STREAM, IPPROTO_TCP); @@ -364,7 +364,7 @@ begin: #endif if(c->socket == -1) { - ifdebug(CONNECTIONS) logger(LOG_ERR, "Creating socket for %s failed: %s", c->hostname, sockstrerror(sockerrno)); + logger(DEBUG_CONNECTIONS, LOG_ERR, "Creating socket for %s failed: %s", c->hostname, sockstrerror(sockerrno)); goto begin; } @@ -392,7 +392,7 @@ begin: closesocket(c->socket); - ifdebug(CONNECTIONS) logger(LOG_ERR, "%s: %s", c->hostname, sockstrerror(sockerrno)); + logger(DEBUG_CONNECTIONS, LOG_ERR, "%s: %s", c->hostname, sockstrerror(sockerrno)); goto begin; } @@ -403,13 +403,11 @@ begin: } static void handle_meta_write(int sock, short events, void *data) { - ifdebug(META) logger(LOG_DEBUG, "handle_meta_write() called"); - connection_t *c = data; ssize_t outlen = send(c->socket, c->outbuf.data + c->outbuf.offset, c->outbuf.len - c->outbuf.offset, 0); if(outlen <= 0) { - logger(LOG_ERR, "Onoes, outlen = %d (%s)", (int)outlen, strerror(errno)); + logger(DEBUG_ALWAYS, LOG_ERR, "Onoes, outlen = %d (%s)", (int)outlen, strerror(errno)); terminate_connection(c, c->status.active); return; } @@ -430,7 +428,7 @@ void setup_outgoing_connection(outgoing_t *outgoing) { if(n) if(n->connection) { - ifdebug(CONNECTIONS) logger(LOG_INFO, "Already connected to %s", outgoing->name); + logger(DEBUG_CONNECTIONS, LOG_INFO, "Already connected to %s", outgoing->name); n->connection->outgoing = outgoing; return; @@ -449,7 +447,7 @@ void setup_outgoing_connection(outgoing_t *outgoing) { outgoing->cfg = lookup_config(c->config_tree, "Address"); if(!outgoing->cfg) { - logger(LOG_ERR, "No address specified for %s", c->name); + logger(DEBUG_ALWAYS, LOG_ERR, "No address specified for %s", c->name); free_connection(c); return; } @@ -479,7 +477,7 @@ void handle_new_meta_connection(int sock, short events, void *data) { fd = accept(sock, &sa.sa, &len); if(fd < 0) { - logger(LOG_ERR, "Accepting a new connection failed: %s", sockstrerror(sockerrno)); + logger(DEBUG_ALWAYS, LOG_ERR, "Accepting a new connection failed: %s", sockstrerror(sockerrno)); return; } @@ -497,7 +495,7 @@ void handle_new_meta_connection(int sock, short events, void *data) { c->socket = fd; c->last_ping_time = time(NULL); - ifdebug(CONNECTIONS) logger(LOG_NOTICE, "Connection from %s", c->hostname); + logger(DEBUG_CONNECTIONS, LOG_NOTICE, "Connection from %s", c->hostname); event_set(&c->inevent, c->socket, EV_READ | EV_PERSIST, handle_meta_connection_data, c); event_set(&c->outevent, c->socket, EV_WRITE | EV_PERSIST, handle_meta_write, c); @@ -532,7 +530,7 @@ void try_outgoing_connections(void) { get_config_string(cfg, &name); if(!check_id(name)) { - logger(LOG_ERR, + logger(DEBUG_ALWAYS, LOG_ERR, "Invalid name for outgoing connection in %s line %d", cfg->file, cfg->line); free(name); diff --git a/src/netutl.c b/src/netutl.c index 8db252dd..9d848dc4 100644 --- a/src/netutl.c +++ b/src/netutl.c @@ -42,7 +42,7 @@ struct addrinfo *str2addrinfo(const char *address, const char *service, int sock err = getaddrinfo(address, service, &hint, &ai); if(err) { - logger(LOG_WARNING, "Error looking up %s port %s: %s", address, + logger(DEBUG_ALWAYS, LOG_WARNING, "Error looking up %s port %s: %s", address, service, gai_strerror(err)); return NULL; } @@ -62,8 +62,7 @@ sockaddr_t str2sockaddr(const char *address, const char *port) { err = getaddrinfo(address, port, &hint, &ai); if(err || !ai) { - ifdebug(SCARY_THINGS) - logger(LOG_DEBUG, "Unknown type address %s port %s", address, port); + logger(DEBUG_SCARY_THINGS, LOG_DEBUG, "Unknown type address %s port %s", address, port); result.sa.sa_family = AF_UNKNOWN; result.unknown.address = xstrdup(address); result.unknown.port = xstrdup(port); @@ -91,7 +90,7 @@ void sockaddr2str(const sockaddr_t *sa, char **addrstr, char **portstr) { err = getnameinfo(&sa->sa, SALEN(sa->sa), address, sizeof address, port, sizeof port, NI_NUMERICHOST | NI_NUMERICSERV); if(err) { - logger(LOG_ERR, "Error while translating addresses: %s", + logger(DEBUG_ALWAYS, LOG_ERR, "Error while translating addresses: %s", gai_strerror(err)); abort(); } @@ -121,7 +120,7 @@ char *sockaddr2hostname(const sockaddr_t *sa) { err = getnameinfo(&sa->sa, SALEN(sa->sa), address, sizeof address, port, sizeof port, hostnames ? 0 : (NI_NUMERICHOST | NI_NUMERICSERV)); if(err) { - logger(LOG_ERR, "Error while looking up hostname: %s", + logger(DEBUG_ALWAYS, LOG_ERR, "Error while looking up hostname: %s", gai_strerror(err)); } @@ -152,7 +151,7 @@ int sockaddrcmp_noport(const sockaddr_t *a, const sockaddr_t *b) { return memcmp(&a->in6.sin6_addr, &b->in6.sin6_addr, sizeof(a->in6.sin6_addr)); default: - logger(LOG_ERR, "sockaddrcmp() was called with unknown address family %d, exitting!", + logger(DEBUG_ALWAYS, LOG_ERR, "sockaddrcmp() was called with unknown address family %d, exitting!", a->sa.sa_family); abort(); } @@ -195,7 +194,7 @@ int sockaddrcmp(const sockaddr_t *a, const sockaddr_t *b) { return memcmp(&a->in6.sin6_port, &b->in6.sin6_port, sizeof a->in6.sin6_port); default: - logger(LOG_ERR, "sockaddrcmp() was called with unknown address family %d, exitting!", + logger(DEBUG_ALWAYS, LOG_ERR, "sockaddrcmp() was called with unknown address family %d, exitting!", a->sa.sa_family); abort(); } diff --git a/src/node.c b/src/node.c index 38123e20..18a02a4c 100644 --- a/src/node.c +++ b/src/node.c @@ -147,7 +147,7 @@ node_t *lookup_node_udp(const sockaddr_t *sa) { void update_node_udp(node_t *n, const sockaddr_t *sa) { if(n == myself) { - logger(LOG_WARNING, "Trying to update UDP address of myself!"); + logger(DEBUG_ALWAYS, LOG_WARNING, "Trying to update UDP address of myself!"); return; } @@ -160,11 +160,11 @@ void update_node_udp(node_t *n, const sockaddr_t *sa) { n->address = *sa; n->hostname = sockaddr2hostname(&n->address); splay_insert(node_udp_tree, n); - ifdebug(PROTOCOL) logger(LOG_DEBUG, "UDP address of %s set to %s", n->name, n->hostname); + logger(DEBUG_PROTOCOL, LOG_DEBUG, "UDP address of %s set to %s", n->name, n->hostname); } else { memset(&n->address, 0, sizeof n->address); n->hostname = NULL; - ifdebug(PROTOCOL) logger(LOG_DEBUG, "UDP address of %s cleared", n->name); + logger(DEBUG_PROTOCOL, LOG_DEBUG, "UDP address of %s cleared", n->name); } } diff --git a/src/openssl/cipher.c b/src/openssl/cipher.c index 63892f3a..9b9e3446 100644 --- a/src/openssl/cipher.c +++ b/src/openssl/cipher.c @@ -44,7 +44,7 @@ bool cipher_open_by_name(cipher_t *cipher, const char *name) { if(cipher->cipher) return cipher_open(cipher); - logger(LOG_ERR, "Unknown cipher name '%s'!", name); + logger(DEBUG_ALWAYS, LOG_ERR, "Unknown cipher name '%s'!", name); return false; } @@ -54,7 +54,7 @@ bool cipher_open_by_nid(cipher_t *cipher, int nid) { if(cipher->cipher) return cipher_open(cipher); - logger(LOG_ERR, "Unknown cipher nid %d!", nid); + logger(DEBUG_ALWAYS, LOG_ERR, "Unknown cipher nid %d!", nid); return false; } @@ -86,7 +86,7 @@ bool cipher_set_key(cipher_t *cipher, void *key, bool encrypt) { if(result) return true; - logger(LOG_ERR, "Error while setting key: %s", ERR_error_string(ERR_get_error(), NULL)); + logger(DEBUG_ALWAYS, LOG_ERR, "Error while setting key: %s", ERR_error_string(ERR_get_error(), NULL)); return false; } @@ -101,14 +101,14 @@ bool cipher_set_key_from_rsa(cipher_t *cipher, void *key, size_t len, bool encry if(result) return true; - logger(LOG_ERR, "Error while setting key: %s", ERR_error_string(ERR_get_error(), NULL)); + logger(DEBUG_ALWAYS, LOG_ERR, "Error while setting key: %s", ERR_error_string(ERR_get_error(), NULL)); return false; } bool cipher_set_counter_key(cipher_t *cipher, void *key) { int result = EVP_EncryptInit_ex(&cipher->ctx, cipher->cipher, NULL, (unsigned char *)key, NULL); if(!result) { - logger(LOG_ERR, "Error while setting key: %s", ERR_error_string(ERR_get_error(), NULL)); + logger(DEBUG_ALWAYS, LOG_ERR, "Error while setting key: %s", ERR_error_string(ERR_get_error(), NULL)); return false; } @@ -124,7 +124,7 @@ bool cipher_set_counter_key(cipher_t *cipher, void *key) { bool cipher_counter_xor(cipher_t *cipher, const void *indata, size_t inlen, void *outdata) { if(!cipher->counter) { - logger(LOG_ERR, "Counter not initialized"); + logger(DEBUG_ALWAYS, LOG_ERR, "Counter not initialized"); return false; } @@ -136,7 +136,7 @@ bool cipher_counter_xor(cipher_t *cipher, const void *indata, size_t inlen, void if(!cipher->counter->n) { int len; if(!EVP_EncryptUpdate(&cipher->ctx, cipher->counter->block, &len, cipher->counter->counter, cipher->cipher->block_size)) { - logger(LOG_ERR, "Error while encrypting: %s", ERR_error_string(ERR_get_error(), NULL)); + logger(DEBUG_ALWAYS, LOG_ERR, "Error while encrypting: %s", ERR_error_string(ERR_get_error(), NULL)); return false; } @@ -173,7 +173,7 @@ bool cipher_encrypt(cipher_t *cipher, const void *indata, size_t inlen, void *ou } } - logger(LOG_ERR, "Error while encrypting: %s", ERR_error_string(ERR_get_error(), NULL)); + logger(DEBUG_ALWAYS, LOG_ERR, "Error while encrypting: %s", ERR_error_string(ERR_get_error(), NULL)); return false; } @@ -194,7 +194,7 @@ bool cipher_decrypt(cipher_t *cipher, const void *indata, size_t inlen, void *ou } } - logger(LOG_ERR, "Error while decrypting: %s", ERR_error_string(ERR_get_error(), NULL)); + logger(DEBUG_ALWAYS, LOG_ERR, "Error while decrypting: %s", ERR_error_string(ERR_get_error(), NULL)); return false; } diff --git a/src/openssl/digest.c b/src/openssl/digest.c index 88bdeb31..3159e7a3 100644 --- a/src/openssl/digest.c +++ b/src/openssl/digest.c @@ -41,7 +41,7 @@ bool digest_open_by_name(digest_t *digest, const char *name, int maclength) { digest->key = NULL; if(!digest->digest) { - logger(LOG_DEBUG, "Unknown digest name '%s'!", name); + logger(DEBUG_ALWAYS, LOG_DEBUG, "Unknown digest name '%s'!", name); return false; } @@ -54,7 +54,7 @@ bool digest_open_by_nid(digest_t *digest, int nid, int maclength) { digest->key = NULL; if(!digest->digest) { - logger(LOG_DEBUG, "Unknown digest nid %d!", nid); + logger(DEBUG_ALWAYS, LOG_DEBUG, "Unknown digest nid %d!", nid); return false; } @@ -95,7 +95,7 @@ bool digest_create(digest_t *digest, const void *indata, size_t inlen, void *out if(!EVP_DigestInit(&ctx, digest->digest) || !EVP_DigestUpdate(&ctx, indata, inlen) || !EVP_DigestFinal(&ctx, tmpdata, NULL)) { - logger(LOG_DEBUG, "Error creating digest: %s", ERR_error_string(ERR_get_error(), NULL)); + logger(DEBUG_ALWAYS, LOG_DEBUG, "Error creating digest: %s", ERR_error_string(ERR_get_error(), NULL)); return false; } } diff --git a/src/openssl/ecdh.c b/src/openssl/ecdh.c index 804605c4..dd8f53f5 100644 --- a/src/openssl/ecdh.c +++ b/src/openssl/ecdh.c @@ -31,19 +31,19 @@ bool ecdh_generate_public(ecdh_t *ecdh, void *pubkey) { *ecdh = EC_KEY_new_by_curve_name(NID_secp521r1); if(!EC_KEY_generate_key(*ecdh)) { - logger(LOG_ERR, "Generating EC key failed: %s", ERR_error_string(ERR_get_error(), NULL)); + logger(DEBUG_ALWAYS, LOG_ERR, "Generating EC key failed: %s", ERR_error_string(ERR_get_error(), NULL)); return false; } const EC_POINT *point = EC_KEY_get0_public_key(*ecdh); if(!point) { - logger(LOG_ERR, "Getting public key failed: %s", ERR_error_string(ERR_get_error(), NULL)); + logger(DEBUG_ALWAYS, LOG_ERR, "Getting public key failed: %s", ERR_error_string(ERR_get_error(), NULL)); return false; } size_t result = EC_POINT_point2oct(EC_KEY_get0_group(*ecdh), point, POINT_CONVERSION_COMPRESSED, pubkey, ECDH_SIZE, NULL); if(!result) { - logger(LOG_ERR, "Converting EC_POINT to binary failed: %s", ERR_error_string(ERR_get_error(), NULL)); + logger(DEBUG_ALWAYS, LOG_ERR, "Converting EC_POINT to binary failed: %s", ERR_error_string(ERR_get_error(), NULL)); return false; } @@ -53,13 +53,13 @@ bool ecdh_generate_public(ecdh_t *ecdh, void *pubkey) { bool ecdh_compute_shared(ecdh_t *ecdh, const void *pubkey, void *shared) { EC_POINT *point = EC_POINT_new(EC_KEY_get0_group(*ecdh)); if(!point) { - logger(LOG_ERR, "EC_POINT_new() failed: %s", ERR_error_string(ERR_get_error(), NULL)); + logger(DEBUG_ALWAYS, LOG_ERR, "EC_POINT_new() failed: %s", ERR_error_string(ERR_get_error(), NULL)); return false; } int result = EC_POINT_oct2point(EC_KEY_get0_group(*ecdh), point, pubkey, ECDH_SIZE, NULL); if(!result) { - logger(LOG_ERR, "Converting binary to EC_POINT failed: %s", ERR_error_string(ERR_get_error(), NULL)); + logger(DEBUG_ALWAYS, LOG_ERR, "Converting binary to EC_POINT failed: %s", ERR_error_string(ERR_get_error(), NULL)); return false; } @@ -69,7 +69,7 @@ bool ecdh_compute_shared(ecdh_t *ecdh, const void *pubkey, void *shared) { *ecdh = NULL; if(!result) { - logger(LOG_ERR, "Computing Elliptic Curve Diffie-Hellman shared key failed: %s", ERR_error_string(ERR_get_error(), NULL)); + logger(DEBUG_ALWAYS, LOG_ERR, "Computing Elliptic Curve Diffie-Hellman shared key failed: %s", ERR_error_string(ERR_get_error(), NULL)); return false; } diff --git a/src/openssl/ecdsa.c b/src/openssl/ecdsa.c index 50165e59..a2c7deb4 100644 --- a/src/openssl/ecdsa.c +++ b/src/openssl/ecdsa.c @@ -37,7 +37,7 @@ bool ecdsa_set_base64_public_key(ecdsa_t *ecdsa, const char *p) { len = b64decode(p, (char *)pubkey, len); if(!o2i_ECPublicKey(ecdsa, &ppubkey, len)) { - logger(LOG_DEBUG, "o2i_ECPublicKey failed: %s", ERR_error_string(ERR_get_error(), NULL)); + logger(DEBUG_ALWAYS, LOG_DEBUG, "o2i_ECPublicKey failed: %s", ERR_error_string(ERR_get_error(), NULL)); return false; } @@ -64,7 +64,7 @@ bool ecdsa_read_pem_public_key(ecdsa_t *ecdsa, FILE *fp) { if(*ecdsa) return true; - logger(LOG_ERR, "Unable to read ECDSA public key: %s", ERR_error_string(ERR_get_error(), NULL)); + logger(DEBUG_ALWAYS, LOG_ERR, "Unable to read ECDSA public key: %s", ERR_error_string(ERR_get_error(), NULL)); return false; } @@ -74,7 +74,7 @@ bool ecdsa_read_pem_private_key(ecdsa_t *ecdsa, FILE *fp) { if(*ecdsa) return true; - logger(LOG_ERR, "Unable to read ECDSA private key: %s", ERR_error_string(ERR_get_error(), NULL)); + logger(DEBUG_ALWAYS, LOG_ERR, "Unable to read ECDSA private key: %s", ERR_error_string(ERR_get_error(), NULL)); return false; } @@ -93,7 +93,7 @@ bool ecdsa_sign(ecdsa_t *ecdsa, const void *in, size_t len, void *sig) { memset(sig, 0, siglen); if(!ECDSA_sign(0, hash, sizeof hash, sig, &siglen, *ecdsa)) { - logger(LOG_DEBUG, "ECDSA_sign() failed: %s", ERR_error_string(ERR_get_error(), NULL)); + logger(DEBUG_ALWAYS, LOG_DEBUG, "ECDSA_sign() failed: %s", ERR_error_string(ERR_get_error(), NULL)); return false; } @@ -107,7 +107,7 @@ bool ecdsa_verify(ecdsa_t *ecdsa, const void *in, size_t len, const void *sig) { SHA512(in, len, hash); if(!ECDSA_verify(0, hash, sizeof hash, sig, siglen, *ecdsa)) { - logger(LOG_DEBUG, "ECDSA_verify() failed: %s", ERR_error_string(ERR_get_error(), NULL)); + logger(DEBUG_ALWAYS, LOG_DEBUG, "ECDSA_verify() failed: %s", ERR_error_string(ERR_get_error(), NULL)); return false; } diff --git a/src/openssl/rsa.c b/src/openssl/rsa.c index c3ea692d..9c880e69 100644 --- a/src/openssl/rsa.c +++ b/src/openssl/rsa.c @@ -55,7 +55,7 @@ bool rsa_read_pem_public_key(rsa_t *rsa, FILE *fp) { if(*rsa) return true; - logger(LOG_ERR, "Unable to read RSA public key: %s", ERR_error_string(ERR_get_error(), NULL)); + logger(DEBUG_ALWAYS, LOG_ERR, "Unable to read RSA public key: %s", ERR_error_string(ERR_get_error(), NULL)); return false; } @@ -65,7 +65,7 @@ bool rsa_read_pem_private_key(rsa_t *rsa, FILE *fp) { if(*rsa) return true; - logger(LOG_ERR, "Unable to read RSA private key: %s", ERR_error_string(ERR_get_error(), NULL)); + logger(DEBUG_ALWAYS, LOG_ERR, "Unable to read RSA private key: %s", ERR_error_string(ERR_get_error(), NULL)); return false; } @@ -77,7 +77,7 @@ bool rsa_public_encrypt(rsa_t *rsa, void *in, size_t len, void *out) { if(RSA_public_encrypt(len, in, out, *rsa, RSA_NO_PADDING) == len) return true; - logger(LOG_ERR, "Unable to perform RSA encryption: %s", ERR_error_string(ERR_get_error(), NULL)); + logger(DEBUG_ALWAYS, LOG_ERR, "Unable to perform RSA encryption: %s", ERR_error_string(ERR_get_error(), NULL)); return false; } @@ -85,7 +85,7 @@ bool rsa_private_decrypt(rsa_t *rsa, void *in, size_t len, void *out) { if(RSA_private_decrypt(len, in, out, *rsa, RSA_NO_PADDING) == len) return true; - logger(LOG_ERR, "Unable to perform RSA decryption: %s", ERR_error_string(ERR_get_error(), NULL)); + logger(DEBUG_ALWAYS, LOG_ERR, "Unable to perform RSA decryption: %s", ERR_error_string(ERR_get_error(), NULL)); return false; } diff --git a/src/process.c b/src/process.c index a7d0f260..aa6dc560 100644 --- a/src/process.c +++ b/src/process.c @@ -61,7 +61,7 @@ static bool install_service(void) { manager = OpenSCManager(NULL, NULL, SC_MANAGER_ALL_ACCESS); if(!manager) { - logger(LOG_ERR, "Could not open service manager: %s", winerror(GetLastError())); + logger(DEBUG_ALWAYS, LOG_ERR, "Could not open service manager: %s", winerror(GetLastError())); return false; } @@ -93,22 +93,22 @@ static bool install_service(void) { if(!service) { DWORD lasterror = GetLastError(); - logger(LOG_ERR, "Could not create %s service: %s", identname, winerror(lasterror)); + logger(DEBUG_ALWAYS, LOG_ERR, "Could not create %s service: %s", identname, winerror(lasterror)); if(lasterror != ERROR_SERVICE_EXISTS) return false; } if(service) { ChangeServiceConfig2(service, SERVICE_CONFIG_DESCRIPTION, &description); - logger(LOG_INFO, "%s service installed", identname); + logger(DEBUG_ALWAYS, LOG_INFO, "%s service installed", identname); } else { service = OpenService(manager, identname, SERVICE_ALL_ACCESS); } if(!StartService(service, 0, NULL)) - logger(LOG_WARNING, "Could not start %s service: %s", identname, winerror(GetLastError())); + logger(DEBUG_ALWAYS, LOG_WARNING, "Could not start %s service: %s", identname, winerror(GetLastError())); else - logger(LOG_INFO, "%s service started", identname); + logger(DEBUG_ALWAYS, LOG_INFO, "%s service started", identname); return true; } @@ -119,13 +119,13 @@ DWORD WINAPI controlhandler(DWORD request, DWORD type, LPVOID boe, LPVOID bah) { SetServiceStatus(statushandle, &status); return NO_ERROR; case SERVICE_CONTROL_STOP: - logger(LOG_NOTICE, "Got %s request", "SERVICE_CONTROL_STOP"); + logger(DEBUG_ALWAYS, LOG_NOTICE, "Got %s request", "SERVICE_CONTROL_STOP"); break; case SERVICE_CONTROL_SHUTDOWN: - logger(LOG_NOTICE, "Got %s request", "SERVICE_CONTROL_SHUTDOWN"); + logger(DEBUG_ALWAYS, LOG_NOTICE, "Got %s request", "SERVICE_CONTROL_SHUTDOWN"); break; default: - logger(LOG_WARNING, "Got unexpected request %d", request); + logger(DEBUG_ALWAYS, LOG_WARNING, "Got unexpected request %d", request); return ERROR_CALL_NOT_IMPLEMENTED; } @@ -150,7 +150,7 @@ VOID WINAPI run_service(DWORD argc, LPTSTR* argv) { statushandle = RegisterServiceCtrlHandlerEx(identname, controlhandler, NULL); if (!statushandle) { - logger(LOG_ERR, "System call `%s' failed: %s", "RegisterServiceCtrlHandlerEx", winerror(GetLastError())); + logger(DEBUG_ALWAYS, LOG_ERR, "System call `%s' failed: %s", "RegisterServiceCtrlHandlerEx", winerror(GetLastError())); err = 1; } else { status.dwWaitHint = 30000; @@ -183,7 +183,7 @@ bool init_service(void) { return false; } else - logger(LOG_ERR, "System call `%s' failed: %s", "StartServiceCtrlDispatcher", winerror(GetLastError())); + logger(DEBUG_ALWAYS, LOG_ERR, "System call `%s' failed: %s", "StartServiceCtrlDispatcher", winerror(GetLastError())); } return true; @@ -218,7 +218,7 @@ bool detach(void) { openlogger(identname, use_logfile?LOGMODE_FILE:(do_detach?LOGMODE_SYSLOG:LOGMODE_STDERR)); - logger(LOG_NOTICE, "tincd %s (%s %s) starting, debug level %d", + logger(DEBUG_ALWAYS, LOG_NOTICE, "tincd %s (%s %s) starting, debug level %d", VERSION, __DATE__, __TIME__, debug_level); return true; @@ -249,7 +249,7 @@ bool execute_script(const char *name, char **envp) { } #endif - ifdebug(STATUS) logger(LOG_INFO, "Executing script %s", name); + logger(DEBUG_STATUS, LOG_INFO, "Executing script %s", name); #ifdef HAVE_PUTENV /* Set environment */ @@ -279,20 +279,20 @@ bool execute_script(const char *name, char **envp) { if(status != -1) { if(WIFEXITED(status)) { /* Child exited by itself */ if(WEXITSTATUS(status)) { - logger(LOG_ERR, "Script %s exited with non-zero status %d", + logger(DEBUG_ALWAYS, LOG_ERR, "Script %s exited with non-zero status %d", name, WEXITSTATUS(status)); return false; } } else if(WIFSIGNALED(status)) { /* Child was killed by a signal */ - logger(LOG_ERR, "Script %s was killed by signal %d (%s)", + logger(DEBUG_ALWAYS, LOG_ERR, "Script %s was killed by signal %d (%s)", name, WTERMSIG(status), strsignal(WTERMSIG(status))); return false; } else { /* Something strange happened */ - logger(LOG_ERR, "Script %s terminated abnormally", name); + logger(DEBUG_ALWAYS, LOG_ERR, "Script %s terminated abnormally", name); return false; } } else { - logger(LOG_ERR, "System call `%s' failed: %s", "system", strerror(errno)); + logger(DEBUG_ALWAYS, LOG_ERR, "System call `%s' failed: %s", "system", strerror(errno)); return false; } #endif diff --git a/src/protocol.c b/src/protocol.c index 116e139e..8b62916b 100644 --- a/src/protocol.c +++ b/src/protocol.c @@ -80,19 +80,12 @@ bool send_request(connection_t *c, const char *format, ...) { va_end(args); if(len < 0 || len > MAXBUFSIZE - 1) { - logger(LOG_ERR, "Output buffer overflow while sending request to %s (%s)", + logger(DEBUG_ALWAYS, LOG_ERR, "Output buffer overflow while sending request to %s (%s)", c->name, c->hostname); return false; } - ifdebug(PROTOCOL) { - ifdebug(META) - logger(LOG_DEBUG, "Sending %s to %s (%s): %s", - request_name[atoi(request)], c->name, c->hostname, request); - else - logger(LOG_DEBUG, "Sending %s to %s (%s)", request_name[atoi(request)], - c->name, c->hostname); - } + logger(DEBUG_META, LOG_DEBUG, "Sending %s to %s (%s): %s", request_name[atoi(request)], c->name, c->hostname, request); request[len++] = '\n'; @@ -105,14 +98,7 @@ bool send_request(connection_t *c, const char *format, ...) { void forward_request(connection_t *from, char *request) { /* Note: request is not zero terminated anymore after a call to this function! */ - ifdebug(PROTOCOL) { - ifdebug(META) - logger(LOG_DEBUG, "Forwarding %s from %s (%s): %s", - request_name[atoi(request)], from->name, from->hostname, request); - else - logger(LOG_DEBUG, "Forwarding %s from %s (%s)", - request_name[atoi(request)], from->name, from->hostname); - } + logger(DEBUG_META, LOG_DEBUG, "Forwarding %s from %s (%s): %s", request_name[atoi(request)], from->name, from->hostname, request); int len = strlen(request); request[len++] = '\n'; @@ -124,41 +110,25 @@ bool receive_request(connection_t *c, char *request) { if(reqno || *request == '0') { if((reqno < 0) || (reqno >= LAST) || !request_handlers[reqno]) { - ifdebug(META) - logger(LOG_DEBUG, "Unknown request from %s (%s): %s", - c->name, c->hostname, request); - else - logger(LOG_ERR, "Unknown request from %s (%s)", - c->name, c->hostname); - + logger(DEBUG_META, LOG_DEBUG, "Unknown request from %s (%s): %s", c->name, c->hostname, request); return false; } else { - ifdebug(PROTOCOL) { - ifdebug(META) - logger(LOG_DEBUG, "Got %s from %s (%s): %s", - request_name[reqno], c->name, c->hostname, request); - else - logger(LOG_DEBUG, "Got %s from %s (%s)", - request_name[reqno], c->name, c->hostname); - } + logger(DEBUG_META, LOG_DEBUG, "Got %s from %s (%s): %s", request_name[reqno], c->name, c->hostname, request); } if((c->allow_request != ALL) && (c->allow_request != reqno)) { - logger(LOG_ERR, "Unauthorized request from %s (%s)", c->name, - c->hostname); + logger(DEBUG_ALWAYS, LOG_ERR, "Unauthorized request from %s (%s)", c->name, c->hostname); return false; } if(!request_handlers[reqno](c, request)) { /* Something went wrong. Probably scriptkiddies. Terminate. */ - logger(LOG_ERR, "Error while processing %s from %s (%s)", - request_name[reqno], c->name, c->hostname); + logger(DEBUG_ALWAYS, LOG_ERR, "Error while processing %s from %s (%s)", request_name[reqno], c->name, c->hostname); return false; } } else { - logger(LOG_ERR, "Bogus data received from %s (%s)", - c->name, c->hostname); + logger(DEBUG_ALWAYS, LOG_ERR, "Bogus data received from %s (%s)", c->name, c->hostname); return false; } @@ -184,7 +154,7 @@ bool seen_request(char *request) { p.request = request; if(splay_search(past_request_tree, &p)) { - ifdebug(SCARY_THINGS) logger(LOG_DEBUG, "Already seen request"); + logger(DEBUG_SCARY_THINGS, LOG_DEBUG, "Already seen request"); return true; } else { new = xmalloc(sizeof *new); @@ -213,7 +183,7 @@ static void age_past_requests(int fd, short events, void *data) { } if(left || deleted) - ifdebug(SCARY_THINGS) logger(LOG_DEBUG, "Aging past requests: deleted %d, left %d", + logger(DEBUG_SCARY_THINGS, LOG_DEBUG, "Aging past requests: deleted %d, left %d", deleted, left); if(left) diff --git a/src/protocol_auth.c b/src/protocol_auth.c index c91723b1..d3eef21e 100644 --- a/src/protocol_auth.c +++ b/src/protocol_auth.c @@ -61,7 +61,7 @@ bool id_h(connection_t *c, char *request) { char name[MAX_STRING_SIZE]; if(sscanf(request, "%*d " MAX_STRING " %d.%d", name, &c->protocol_major, &c->protocol_minor) < 2) { - logger(LOG_ERR, "Got bad %s from %s (%s)", "ID", c->name, + logger(DEBUG_ALWAYS, LOG_ERR, "Got bad %s from %s (%s)", "ID", c->name, c->hostname); return false; } @@ -78,7 +78,7 @@ bool id_h(connection_t *c, char *request) { /* Check if identity is a valid name */ if(!check_id(name)) { - logger(LOG_ERR, "Got bad %s from %s (%s): %s", "ID", c->name, + logger(DEBUG_ALWAYS, LOG_ERR, "Got bad %s from %s (%s): %s", "ID", c->name, c->hostname, "invalid name"); return false; } @@ -87,7 +87,7 @@ bool id_h(connection_t *c, char *request) { if(c->outgoing) { if(strcmp(c->name, name)) { - logger(LOG_ERR, "Peer %s is %s instead of %s", c->hostname, name, + logger(DEBUG_ALWAYS, LOG_ERR, "Peer %s is %s instead of %s", c->hostname, name, c->name); return false; } @@ -100,7 +100,7 @@ bool id_h(connection_t *c, char *request) { /* Check if version matches */ if(c->protocol_major != myself->connection->protocol_major) { - logger(LOG_ERR, "Peer %s (%s) uses incompatible version %d.%d", + logger(DEBUG_ALWAYS, LOG_ERR, "Peer %s (%s) uses incompatible version %d.%d", c->name, c->hostname, c->protocol_major, c->protocol_minor); return false; } @@ -119,7 +119,7 @@ bool id_h(connection_t *c, char *request) { init_configuration(&c->config_tree); if(!read_connection_config(c)) { - logger(LOG_ERR, "Peer %s had unknown identity (%s)", c->hostname, + logger(DEBUG_ALWAYS, LOG_ERR, "Peer %s had unknown identity (%s)", c->hostname, c->name); return false; } @@ -183,9 +183,9 @@ bool send_metakey(connection_t *c) { cipher_set_key_from_rsa(&c->outcipher, key, len, true); - ifdebug(SCARY_THINGS) { + if(debug_level >= DEBUG_SCARY_THINGS) { bin2hex(key, hexkey, len); - logger(LOG_DEBUG, "Generated random meta key (unencrypted): %s", hexkey); + logger(DEBUG_SCARY_THINGS, LOG_DEBUG, "Generated random meta key (unencrypted): %s", hexkey); } /* Encrypt the random data @@ -196,7 +196,7 @@ bool send_metakey(connection_t *c) { */ if(!rsa_public_encrypt(&c->rsa, key, len, enckey)) { - logger(LOG_ERR, "Error during encryption of meta key for %s (%s)", c->name, c->hostname); + logger(DEBUG_ALWAYS, LOG_ERR, "Error during encryption of meta key for %s (%s)", c->name, c->hostname); return false; } @@ -223,7 +223,7 @@ bool metakey_h(connection_t *c, char *request) { char key[len]; if(sscanf(request, "%*d %d %d %d %d " MAX_STRING, &cipher, &digest, &maclength, &compression, hexkey) != 5) { - logger(LOG_ERR, "Got bad %s from %s (%s)", "METAKEY", c->name, c->hostname); + logger(DEBUG_ALWAYS, LOG_ERR, "Got bad %s from %s (%s)", "METAKEY", c->name, c->hostname); return false; } @@ -234,31 +234,31 @@ bool metakey_h(connection_t *c, char *request) { /* Check if the length of the meta key is all right */ if(inlen != len) { - logger(LOG_ERR, "Possible intruder %s (%s): %s", c->name, c->hostname, "wrong keylength"); + logger(DEBUG_ALWAYS, LOG_ERR, "Possible intruder %s (%s): %s", c->name, c->hostname, "wrong keylength"); return false; } /* Decrypt the meta key */ if(!rsa_private_decrypt(&myself->connection->rsa, enckey, len, key)) { - logger(LOG_ERR, "Error during decryption of meta key for %s (%s)", c->name, c->hostname); + logger(DEBUG_ALWAYS, LOG_ERR, "Error during decryption of meta key for %s (%s)", c->name, c->hostname); return false; } - ifdebug(SCARY_THINGS) { + if(debug_level >= DEBUG_SCARY_THINGS) { bin2hex(key, hexkey, len); - logger(LOG_DEBUG, "Received random meta key (unencrypted): %s", hexkey); + logger(DEBUG_SCARY_THINGS, LOG_DEBUG, "Received random meta key (unencrypted): %s", hexkey); } /* Check and lookup cipher and digest algorithms */ if(!cipher_open_by_nid(&c->incipher, cipher) || !cipher_set_key_from_rsa(&c->incipher, key, len, false)) { - logger(LOG_ERR, "Error during initialisation of cipher from %s (%s)", c->name, c->hostname); + logger(DEBUG_ALWAYS, LOG_ERR, "Error during initialisation of cipher from %s (%s)", c->name, c->hostname); return false; } if(!digest_open_by_nid(&c->indigest, digest, -1)) { - logger(LOG_ERR, "Error during initialisation of digest from %s (%s)", c->name, c->hostname); + logger(DEBUG_ALWAYS, LOG_ERR, "Error during initialisation of digest from %s (%s)", c->name, c->hostname); return false; } @@ -296,7 +296,7 @@ bool challenge_h(connection_t *c, char *request) { char digest[digestlen]; if(sscanf(request, "%*d " MAX_STRING, buffer) != 1) { - logger(LOG_ERR, "Got bad %s from %s (%s)", "CHALLENGE", c->name, c->hostname); + logger(DEBUG_ALWAYS, LOG_ERR, "Got bad %s from %s (%s)", "CHALLENGE", c->name, c->hostname); return false; } @@ -307,7 +307,7 @@ bool challenge_h(connection_t *c, char *request) { /* Check if the length of the challenge is all right */ if(inlen != len) { - logger(LOG_ERR, "Possible intruder %s (%s): %s", c->name, c->hostname, "wrong challenge length"); + logger(DEBUG_ALWAYS, LOG_ERR, "Possible intruder %s (%s): %s", c->name, c->hostname, "wrong challenge length"); return false; } @@ -330,7 +330,7 @@ bool chal_reply_h(connection_t *c, char *request) { char hishash[MAX_STRING_SIZE]; if(sscanf(request, "%*d " MAX_STRING, hishash) != 1) { - logger(LOG_ERR, "Got bad %s from %s (%s)", "CHAL_REPLY", c->name, + logger(DEBUG_ALWAYS, LOG_ERR, "Got bad %s from %s (%s)", "CHAL_REPLY", c->name, c->hostname); return false; } @@ -342,7 +342,7 @@ bool chal_reply_h(connection_t *c, char *request) { /* Check if the length of the hash is all right */ if(inlen != digest_length(&c->outdigest)) { - logger(LOG_ERR, "Possible intruder %s (%s): %s", c->name, c->hostname, "wrong challenge reply length"); + logger(DEBUG_ALWAYS, LOG_ERR, "Possible intruder %s (%s): %s", c->name, c->hostname, "wrong challenge reply length"); return false; } @@ -350,7 +350,7 @@ bool chal_reply_h(connection_t *c, char *request) { /* Verify the hash */ if(!digest_verify(&c->outdigest, c->hischallenge, rsa_size(&c->rsa), hishash)) { - logger(LOG_ERR, "Possible intruder %s (%s): %s", c->name, c->hostname, "wrong challenge reply"); + logger(DEBUG_ALWAYS, LOG_ERR, "Possible intruder %s (%s): %s", c->name, c->hostname, "wrong challenge reply"); return false; } @@ -451,16 +451,16 @@ static bool upgrade_h(connection_t *c, char *request) { char pubkey[MAX_STRING_SIZE]; if(sscanf(request, "%*d " MAX_STRING, pubkey) != 1) { - logger(LOG_ERR, "Got bad %s from %s (%s)", "ACK", c->name, c->hostname); + logger(DEBUG_ALWAYS, LOG_ERR, "Got bad %s from %s (%s)", "ACK", c->name, c->hostname); return false; } if(ecdsa_active(&c->ecdsa) || read_ecdsa_public_key(c)) { - logger(LOG_INFO, "Already have ECDSA public key from %s (%s), not upgrading.", c->name, c->hostname); + logger(DEBUG_ALWAYS, LOG_INFO, "Already have ECDSA public key from %s (%s), not upgrading.", c->name, c->hostname); return false; } - logger(LOG_INFO, "Got ECDSA public key from %s (%s), upgrading!", c->name, c->hostname); + logger(DEBUG_ALWAYS, LOG_INFO, "Got ECDSA public key from %s (%s), upgrading!", c->name, c->hostname); append_config_file(c->name, "ECDSAPublicKey", pubkey); c->allow_request = TERMREQ; return send_termreq(c); @@ -478,7 +478,7 @@ bool ack_h(connection_t *c, char *request) { bool choice; if(sscanf(request, "%*d " MAX_STRING " %d %x", hisport, &weight, &options) != 3) { - logger(LOG_ERR, "Got bad %s from %s (%s)", "ACK", c->name, + logger(DEBUG_ALWAYS, LOG_ERR, "Got bad %s from %s (%s)", "ACK", c->name, c->hostname); return false; } @@ -494,11 +494,11 @@ bool ack_h(connection_t *c, char *request) { } else { if(n->connection) { /* Oh dear, we already have a connection to this node. */ - ifdebug(CONNECTIONS) logger(LOG_DEBUG, "Established a second connection with %s (%s), closing old connection", n->connection->name, n->connection->hostname); + logger(DEBUG_CONNECTIONS, LOG_DEBUG, "Established a second connection with %s (%s), closing old connection", n->connection->name, n->connection->hostname); if(n->connection->outgoing) { if(c->outgoing) - logger(LOG_WARNING, "Two outgoing connections to the same node!"); + logger(DEBUG_ALWAYS, LOG_WARNING, "Two outgoing connections to the same node!"); else c->outgoing = n->connection->outgoing; @@ -540,7 +540,7 @@ bool ack_h(connection_t *c, char *request) { c->allow_request = ALL; c->status.active = true; - ifdebug(CONNECTIONS) logger(LOG_NOTICE, "Connection with %s (%s) activated", c->name, + logger(DEBUG_CONNECTIONS, LOG_NOTICE, "Connection with %s (%s) activated", c->name, c->hostname); /* Send him everything we know */ diff --git a/src/protocol_edge.c b/src/protocol_edge.c index e6736945..bf283dd6 100644 --- a/src/protocol_edge.c +++ b/src/protocol_edge.c @@ -63,7 +63,7 @@ bool add_edge_h(connection_t *c, char *request) { if(sscanf(request, "%*d %*x "MAX_STRING" "MAX_STRING" "MAX_STRING" "MAX_STRING" %x %d", from_name, to_name, to_address, to_port, &options, &weight) != 6) { - logger(LOG_ERR, "Got bad %s from %s (%s)", "ADD_EDGE", c->name, + logger(DEBUG_ALWAYS, LOG_ERR, "Got bad %s from %s (%s)", "ADD_EDGE", c->name, c->hostname); return false; } @@ -71,7 +71,7 @@ bool add_edge_h(connection_t *c, char *request) { /* Check if names are valid */ if(!check_id(from_name) || !check_id(to_name)) { - logger(LOG_ERR, "Got bad %s from %s (%s): %s", "ADD_EDGE", c->name, + logger(DEBUG_ALWAYS, LOG_ERR, "Got bad %s from %s (%s): %s", "ADD_EDGE", c->name, c->hostname, "invalid name"); return false; } @@ -88,7 +88,7 @@ bool add_edge_h(connection_t *c, char *request) { from != myself && from != c->node && to != myself && to != c->node) { /* ignore indirect edge registrations for tunnelserver */ - ifdebug(PROTOCOL) logger(LOG_WARNING, + logger(DEBUG_PROTOCOL, LOG_WARNING, "Ignoring indirect %s from %s (%s)", "ADD_EDGE", c->name, c->hostname); return true; @@ -118,12 +118,12 @@ bool add_edge_h(connection_t *c, char *request) { if(e) { if(e->weight != weight || e->options != options || sockaddrcmp(&e->address, &address)) { if(from == myself) { - ifdebug(PROTOCOL) logger(LOG_WARNING, "Got %s from %s (%s) for ourself which does not match existing entry", + logger(DEBUG_PROTOCOL, LOG_WARNING, "Got %s from %s (%s) for ourself which does not match existing entry", "ADD_EDGE", c->name, c->hostname); send_add_edge(c, e); return true; } else { - ifdebug(PROTOCOL) logger(LOG_WARNING, "Got %s from %s (%s) which does not match existing entry", + logger(DEBUG_PROTOCOL, LOG_WARNING, "Got %s from %s (%s) which does not match existing entry", "ADD_EDGE", c->name, c->hostname); edge_del(e); graph(); @@ -131,7 +131,7 @@ bool add_edge_h(connection_t *c, char *request) { } else return true; } else if(from == myself) { - ifdebug(PROTOCOL) logger(LOG_WARNING, "Got %s from %s (%s) for ourself which does not exist", + logger(DEBUG_PROTOCOL, LOG_WARNING, "Got %s from %s (%s) for ourself which does not exist", "ADD_EDGE", c->name, c->hostname); contradicting_add_edge++; e = new_edge(); @@ -174,7 +174,7 @@ bool del_edge_h(connection_t *c, char *request) { node_t *from, *to; if(sscanf(request, "%*d %*x "MAX_STRING" "MAX_STRING, from_name, to_name) != 2) { - logger(LOG_ERR, "Got bad %s from %s (%s)", "DEL_EDGE", c->name, + logger(DEBUG_ALWAYS, LOG_ERR, "Got bad %s from %s (%s)", "DEL_EDGE", c->name, c->hostname); return false; } @@ -182,7 +182,7 @@ bool del_edge_h(connection_t *c, char *request) { /* Check if names are valid */ if(!check_id(from_name) || !check_id(to_name)) { - logger(LOG_ERR, "Got bad %s from %s (%s): %s", "DEL_EDGE", c->name, + logger(DEBUG_ALWAYS, LOG_ERR, "Got bad %s from %s (%s): %s", "DEL_EDGE", c->name, c->hostname, "invalid name"); return false; } @@ -199,20 +199,20 @@ bool del_edge_h(connection_t *c, char *request) { from != myself && from != c->node && to != myself && to != c->node) { /* ignore indirect edge registrations for tunnelserver */ - ifdebug(PROTOCOL) logger(LOG_WARNING, + logger(DEBUG_PROTOCOL, LOG_WARNING, "Ignoring indirect %s from %s (%s)", "DEL_EDGE", c->name, c->hostname); return true; } if(!from) { - ifdebug(PROTOCOL) logger(LOG_ERR, "Got %s from %s (%s) which does not appear in the edge tree", + logger(DEBUG_PROTOCOL, LOG_ERR, "Got %s from %s (%s) which does not appear in the edge tree", "DEL_EDGE", c->name, c->hostname); return true; } if(!to) { - ifdebug(PROTOCOL) logger(LOG_ERR, "Got %s from %s (%s) which does not appear in the edge tree", + logger(DEBUG_PROTOCOL, LOG_ERR, "Got %s from %s (%s) which does not appear in the edge tree", "DEL_EDGE", c->name, c->hostname); return true; } @@ -222,13 +222,13 @@ bool del_edge_h(connection_t *c, char *request) { e = lookup_edge(from, to); if(!e) { - ifdebug(PROTOCOL) logger(LOG_WARNING, "Got %s from %s (%s) which does not appear in the edge tree", + logger(DEBUG_PROTOCOL, LOG_WARNING, "Got %s from %s (%s) which does not appear in the edge tree", "DEL_EDGE", c->name, c->hostname); return true; } if(e->from == myself) { - ifdebug(PROTOCOL) logger(LOG_WARNING, "Got %s from %s (%s) for ourself", + logger(DEBUG_PROTOCOL, LOG_WARNING, "Got %s from %s (%s) for ourself", "DEL_EDGE", c->name, c->hostname); contradicting_del_edge++; send_add_edge(c, e); /* Send back a correction */ diff --git a/src/protocol_key.c b/src/protocol_key.c index c392a469..c62c0481 100644 --- a/src/protocol_key.c +++ b/src/protocol_key.c @@ -56,7 +56,7 @@ bool key_changed_h(connection_t *c, char *request) { node_t *n; if(sscanf(request, "%*d %*x " MAX_STRING, name) != 1) { - logger(LOG_ERR, "Got bad %s from %s (%s)", "KEY_CHANGED", + logger(DEBUG_ALWAYS, LOG_ERR, "Got bad %s from %s (%s)", "KEY_CHANGED", c->name, c->hostname); return false; } @@ -67,7 +67,7 @@ bool key_changed_h(connection_t *c, char *request) { n = lookup_node(name); if(!n) { - logger(LOG_ERR, "Got %s from %s (%s) origin %s which does not exist", + logger(DEBUG_ALWAYS, LOG_ERR, "Got %s from %s (%s) origin %s which does not exist", "KEY_CHANGED", c->name, c->hostname, name); return true; } @@ -94,20 +94,20 @@ bool req_key_h(connection_t *c, char *request) { int kx_version = 0; if(sscanf(request, "%*d " MAX_STRING " " MAX_STRING " %d", from_name, to_name, &kx_version) < 2) { - logger(LOG_ERR, "Got bad %s from %s (%s)", "REQ_KEY", c->name, + logger(DEBUG_ALWAYS, LOG_ERR, "Got bad %s from %s (%s)", "REQ_KEY", c->name, c->hostname); return false; } if(!check_id(from_name) || !check_id(to_name)) { - logger(LOG_ERR, "Got bad %s from %s (%s): %s", "REQ_KEY", c->name, c->hostname, "invalid name"); + logger(DEBUG_ALWAYS, LOG_ERR, "Got bad %s from %s (%s): %s", "REQ_KEY", c->name, c->hostname, "invalid name"); return false; } from = lookup_node(from_name); if(!from) { - logger(LOG_ERR, "Got %s from %s (%s) origin %s which does not exist in our connection list", + logger(DEBUG_ALWAYS, LOG_ERR, "Got %s from %s (%s) origin %s which does not exist in our connection list", "REQ_KEY", c->name, c->hostname, from_name); return true; } @@ -115,7 +115,7 @@ bool req_key_h(connection_t *c, char *request) { to = lookup_node(to_name); if(!to) { - logger(LOG_ERR, "Got %s from %s (%s) destination %s which does not exist in our connection list", + logger(DEBUG_ALWAYS, LOG_ERR, "Got %s from %s (%s) destination %s which does not exist in our connection list", "REQ_KEY", c->name, c->hostname, to_name); return true; } @@ -124,7 +124,7 @@ bool req_key_h(connection_t *c, char *request) { if(to == myself) { /* Yes, send our own key back */ if(experimental && kx_version >= 1) { - logger(LOG_DEBUG, "Got ECDH key request from %s", from->name); + logger(DEBUG_ALWAYS, LOG_DEBUG, "Got ECDH key request from %s", from->name); from->status.ecdh = true; } send_ans_key(from); @@ -133,7 +133,7 @@ bool req_key_h(connection_t *c, char *request) { return true; if(!to->status.reachable) { - logger(LOG_WARNING, "Got %s from %s (%s) destination %s which is not reachable", + logger(DEBUG_ALWAYS, LOG_WARNING, "Got %s from %s (%s) destination %s which is not reachable", "REQ_KEY", c->name, c->hostname, to_name); return true; } @@ -214,20 +214,20 @@ bool ans_key_h(connection_t *c, char *request) { if(sscanf(request, "%*d "MAX_STRING" "MAX_STRING" "MAX_STRING" %d %d %d %d "MAX_STRING" "MAX_STRING, from_name, to_name, key, &cipher, &digest, &maclength, &compression, address, port) < 7) { - logger(LOG_ERR, "Got bad %s from %s (%s)", "ANS_KEY", c->name, + logger(DEBUG_ALWAYS, LOG_ERR, "Got bad %s from %s (%s)", "ANS_KEY", c->name, c->hostname); return false; } if(!check_id(from_name) || !check_id(to_name)) { - logger(LOG_ERR, "Got bad %s from %s (%s): %s", "ANS_KEY", c->name, c->hostname, "invalid name"); + logger(DEBUG_ALWAYS, LOG_ERR, "Got bad %s from %s (%s): %s", "ANS_KEY", c->name, c->hostname, "invalid name"); return false; } from = lookup_node(from_name); if(!from) { - logger(LOG_ERR, "Got %s from %s (%s) origin %s which does not exist in our connection list", + logger(DEBUG_ALWAYS, LOG_ERR, "Got %s from %s (%s) origin %s which does not exist in our connection list", "ANS_KEY", c->name, c->hostname, from_name); return true; } @@ -235,7 +235,7 @@ bool ans_key_h(connection_t *c, char *request) { to = lookup_node(to_name); if(!to) { - logger(LOG_ERR, "Got %s from %s (%s) destination %s which does not exist in our connection list", + logger(DEBUG_ALWAYS, LOG_ERR, "Got %s from %s (%s) destination %s which does not exist in our connection list", "ANS_KEY", c->name, c->hostname, to_name); return true; } @@ -247,14 +247,14 @@ bool ans_key_h(connection_t *c, char *request) { return true; if(!to->status.reachable) { - logger(LOG_WARNING, "Got %s from %s (%s) destination %s which is not reachable", + logger(DEBUG_ALWAYS, LOG_WARNING, "Got %s from %s (%s) destination %s which is not reachable", "ANS_KEY", c->name, c->hostname, to_name); return true; } if(!*address && from->address.sa.sa_family != AF_UNSPEC) { char *address, *port; - ifdebug(PROTOCOL) logger(LOG_DEBUG, "Appending reflexive UDP address to ANS_KEY from %s to %s", from->name, to->name); + logger(DEBUG_PROTOCOL, LOG_DEBUG, "Appending reflexive UDP address to ANS_KEY from %s to %s", from->name, to->name); sockaddr2str(&from->address, &address, &port); send_request(to->nexthop->connection, "%s %s %s", request, address, port); free(address); @@ -268,22 +268,22 @@ bool ans_key_h(connection_t *c, char *request) { /* Check and lookup cipher and digest algorithms */ if(!cipher_open_by_nid(&from->outcipher, cipher)) { - logger(LOG_ERR, "Node %s (%s) uses unknown cipher!", from->name, from->hostname); + logger(DEBUG_ALWAYS, LOG_ERR, "Node %s (%s) uses unknown cipher!", from->name, from->hostname); return false; } if(!digest_open_by_nid(&from->outdigest, digest, maclength)) { - logger(LOG_ERR, "Node %s (%s) uses unknown digest!", from->name, from->hostname); + logger(DEBUG_ALWAYS, LOG_ERR, "Node %s (%s) uses unknown digest!", from->name, from->hostname); return false; } if(maclength != digest_length(&from->outdigest)) { - logger(LOG_ERR, "Node %s (%s) uses bogus MAC length!", from->name, from->hostname); + logger(DEBUG_ALWAYS, LOG_ERR, "Node %s (%s) uses bogus MAC length!", from->name, from->hostname); return false; } if(compression < 0 || compression > 11) { - logger(LOG_ERR, "Node %s (%s) uses bogus compression level!", from->name, from->hostname); + logger(DEBUG_ALWAYS, LOG_ERR, "Node %s (%s) uses bogus compression level!", from->name, from->hostname); return true; } @@ -301,7 +301,7 @@ bool ans_key_h(connection_t *c, char *request) { if(!node_read_ecdsa_public_key(from)) { if(!pubkey) { - logger(LOG_ERR, "No ECDSA public key known for %s (%s), cannot verify ECDH key exchange!", from->name, from->hostname); + logger(DEBUG_ALWAYS, LOG_ERR, "No ECDSA public key known for %s (%s), cannot verify ECDH key exchange!", from->name, from->hostname); return true; } @@ -315,17 +315,17 @@ bool ans_key_h(connection_t *c, char *request) { int keylen = b64decode(key + 5, key + 5, sizeof key - 5); if(keylen != ECDH_SIZE + siglen) { - logger(LOG_ERR, "Node %s (%s) uses wrong keylength! %d != %d", from->name, from->hostname, keylen, ECDH_SIZE + siglen); + logger(DEBUG_ALWAYS, LOG_ERR, "Node %s (%s) uses wrong keylength! %d != %d", from->name, from->hostname, keylen, ECDH_SIZE + siglen); return true; } if(ECDH_SHARED_SIZE < cipher_keylength(&from->outcipher)) { - logger(LOG_ERR, "ECDH key too short for cipher of %s!", from->name); + logger(DEBUG_ALWAYS, LOG_ERR, "ECDH key too short for cipher of %s!", from->name); return true; } if(!ecdsa_verify(&from->ecdsa, key + 5, ECDH_SIZE, key + 5 + ECDH_SIZE)) { - logger(LOG_ERR, "Possible intruder %s (%s): %s", from->name, from->hostname, "invalid ECDSA signature"); + logger(DEBUG_ALWAYS, LOG_ERR, "Possible intruder %s (%s): %s", from->name, from->hostname, "invalid ECDSA signature"); return true; } @@ -386,7 +386,7 @@ bool ans_key_h(connection_t *c, char *request) { keylen = hex2bin(key, key, sizeof key); if(keylen != cipher_keylength(&from->outcipher)) { - logger(LOG_ERR, "Node %s (%s) uses wrong keylength!", from->name, from->hostname); + logger(DEBUG_ALWAYS, LOG_ERR, "Node %s (%s) uses wrong keylength!", from->name, from->hostname); return true; } @@ -400,7 +400,7 @@ bool ans_key_h(connection_t *c, char *request) { from->sent_seqno = 0; if(*address && *port) { - ifdebug(PROTOCOL) logger(LOG_DEBUG, "Using reflexive UDP address from %s: %s port %s", from->name, address, port); + logger(DEBUG_PROTOCOL, LOG_DEBUG, "Using reflexive UDP address from %s: %s port %s", from->name, address, port); sockaddr_t sa = str2sockaddr(address, port); update_node_udp(from, &sa); } diff --git a/src/protocol_misc.c b/src/protocol_misc.c index 225d7b4e..37bc110a 100644 --- a/src/protocol_misc.c +++ b/src/protocol_misc.c @@ -45,12 +45,12 @@ bool status_h(connection_t *c, char *request) { char statusstring[MAX_STRING_SIZE]; if(sscanf(request, "%*d %d " MAX_STRING, &statusno, statusstring) != 2) { - logger(LOG_ERR, "Got bad %s from %s (%s)", "STATUS", + logger(DEBUG_ALWAYS, LOG_ERR, "Got bad %s from %s (%s)", "STATUS", c->name, c->hostname); return false; } - ifdebug(STATUS) logger(LOG_NOTICE, "Status message from %s (%s): %d: %s", + logger(DEBUG_STATUS, LOG_NOTICE, "Status message from %s (%s): %d: %s", c->name, c->hostname, statusno, statusstring); return true; @@ -68,12 +68,12 @@ bool error_h(connection_t *c, char *request) { char errorstring[MAX_STRING_SIZE]; if(sscanf(request, "%*d %d " MAX_STRING, &err, errorstring) != 2) { - logger(LOG_ERR, "Got bad %s from %s (%s)", "ERROR", + logger(DEBUG_ALWAYS, LOG_ERR, "Got bad %s from %s (%s)", "ERROR", c->name, c->hostname); return false; } - ifdebug(ERROR) logger(LOG_NOTICE, "Error message from %s (%s): %d: %s", + logger(DEBUG_ERROR, LOG_NOTICE, "Error message from %s (%s): %d: %s", c->name, c->hostname, err, errorstring); return false; @@ -132,7 +132,7 @@ bool tcppacket_h(connection_t *c, char *request) { short int len; if(sscanf(request, "%*d %hd", &len) != 1) { - logger(LOG_ERR, "Got bad %s from %s (%s)", "PACKET", c->name, + logger(DEBUG_ALWAYS, LOG_ERR, "Got bad %s from %s (%s)", "PACKET", c->name, c->hostname); return false; } diff --git a/src/protocol_subnet.c b/src/protocol_subnet.c index 6f9e626e..26cb5606 100644 --- a/src/protocol_subnet.c +++ b/src/protocol_subnet.c @@ -48,7 +48,7 @@ bool add_subnet_h(connection_t *c, char *request) { subnet_t s = {NULL}, *new, *old; if(sscanf(request, "%*d %*x " MAX_STRING " " MAX_STRING, name, subnetstr) != 2) { - logger(LOG_ERR, "Got bad %s from %s (%s)", "ADD_SUBNET", c->name, + logger(DEBUG_ALWAYS, LOG_ERR, "Got bad %s from %s (%s)", "ADD_SUBNET", c->name, c->hostname); return false; } @@ -56,7 +56,7 @@ bool add_subnet_h(connection_t *c, char *request) { /* Check if owner name is valid */ if(!check_id(name)) { - logger(LOG_ERR, "Got bad %s from %s (%s): %s", "ADD_SUBNET", c->name, + logger(DEBUG_ALWAYS, LOG_ERR, "Got bad %s from %s (%s): %s", "ADD_SUBNET", c->name, c->hostname, "invalid name"); return false; } @@ -64,7 +64,7 @@ bool add_subnet_h(connection_t *c, char *request) { /* Check if subnet string is valid */ if(!str2net(&s, subnetstr)) { - logger(LOG_ERR, "Got bad %s from %s (%s): %s", "ADD_SUBNET", c->name, + logger(DEBUG_ALWAYS, LOG_ERR, "Got bad %s from %s (%s): %s", "ADD_SUBNET", c->name, c->hostname, "invalid subnet string"); return false; } @@ -78,7 +78,7 @@ bool add_subnet_h(connection_t *c, char *request) { if(tunnelserver && owner != myself && owner != c->node) { /* in case of tunnelserver, ignore indirect subnet registrations */ - ifdebug(PROTOCOL) logger(LOG_WARNING, "Ignoring indirect %s from %s (%s) for %s", + logger(DEBUG_PROTOCOL, LOG_WARNING, "Ignoring indirect %s from %s (%s) for %s", "ADD_SUBNET", c->name, c->hostname, subnetstr); return true; } @@ -97,7 +97,7 @@ bool add_subnet_h(connection_t *c, char *request) { /* If we don't know this subnet, but we are the owner, retaliate with a DEL_SUBNET */ if(owner == myself) { - ifdebug(PROTOCOL) logger(LOG_WARNING, "Got %s from %s (%s) for ourself", + logger(DEBUG_PROTOCOL, LOG_WARNING, "Got %s from %s (%s) for ourself", "ADD_SUBNET", c->name, c->hostname); s.owner = myself; send_del_subnet(c, &s); @@ -107,7 +107,7 @@ bool add_subnet_h(connection_t *c, char *request) { /* In tunnel server mode, we should already know all allowed subnets */ if(tunnelserver) { - logger(LOG_WARNING, "Ignoring unauthorized %s from %s (%s): %s", + logger(DEBUG_ALWAYS, LOG_WARNING, "Ignoring unauthorized %s from %s (%s): %s", "ADD_SUBNET", c->name, c->hostname, subnetstr); return true; } @@ -115,7 +115,7 @@ bool add_subnet_h(connection_t *c, char *request) { /* Ignore if strictsubnets is true, but forward it to others */ if(strictsubnets) { - logger(LOG_WARNING, "Ignoring unauthorized %s from %s (%s): %s", + logger(DEBUG_ALWAYS, LOG_WARNING, "Ignoring unauthorized %s from %s (%s): %s", "ADD_SUBNET", c->name, c->hostname, subnetstr); forward_request(c, request); return true; @@ -158,7 +158,7 @@ bool del_subnet_h(connection_t *c, char *request) { subnet_t s = {NULL}, *find; if(sscanf(request, "%*d %*x " MAX_STRING " " MAX_STRING, name, subnetstr) != 2) { - logger(LOG_ERR, "Got bad %s from %s (%s)", "DEL_SUBNET", c->name, + logger(DEBUG_ALWAYS, LOG_ERR, "Got bad %s from %s (%s)", "DEL_SUBNET", c->name, c->hostname); return false; } @@ -166,7 +166,7 @@ bool del_subnet_h(connection_t *c, char *request) { /* Check if owner name is valid */ if(!check_id(name)) { - logger(LOG_ERR, "Got bad %s from %s (%s): %s", "DEL_SUBNET", c->name, + logger(DEBUG_ALWAYS, LOG_ERR, "Got bad %s from %s (%s): %s", "DEL_SUBNET", c->name, c->hostname, "invalid name"); return false; } @@ -174,7 +174,7 @@ bool del_subnet_h(connection_t *c, char *request) { /* Check if subnet string is valid */ if(!str2net(&s, subnetstr)) { - logger(LOG_ERR, "Got bad %s from %s (%s): %s", "DEL_SUBNET", c->name, + logger(DEBUG_ALWAYS, LOG_ERR, "Got bad %s from %s (%s): %s", "DEL_SUBNET", c->name, c->hostname, "invalid subnet string"); return false; } @@ -188,13 +188,13 @@ bool del_subnet_h(connection_t *c, char *request) { if(tunnelserver && owner != myself && owner != c->node) { /* in case of tunnelserver, ignore indirect subnet deletion */ - ifdebug(PROTOCOL) logger(LOG_WARNING, "Ignoring indirect %s from %s (%s) for %s", + logger(DEBUG_PROTOCOL, LOG_WARNING, "Ignoring indirect %s from %s (%s) for %s", "DEL_SUBNET", c->name, c->hostname, subnetstr); return true; } if(!owner) { - ifdebug(PROTOCOL) logger(LOG_WARNING, "Got %s from %s (%s) for %s which is not in our node tree", + logger(DEBUG_PROTOCOL, LOG_WARNING, "Got %s from %s (%s) for %s which is not in our node tree", "DEL_SUBNET", c->name, c->hostname, name); return true; } @@ -206,7 +206,7 @@ bool del_subnet_h(connection_t *c, char *request) { find = lookup_subnet(owner, &s); if(!find) { - ifdebug(PROTOCOL) logger(LOG_WARNING, "Got %s from %s (%s) for %s which does not appear in his subnet tree", + logger(DEBUG_PROTOCOL, LOG_WARNING, "Got %s from %s (%s) for %s which does not appear in his subnet tree", "DEL_SUBNET", c->name, c->hostname, name); if(strictsubnets) forward_request(c, request); @@ -216,7 +216,7 @@ bool del_subnet_h(connection_t *c, char *request) { /* If we are the owner of this subnet, retaliate with an ADD_SUBNET */ if(owner == myself) { - ifdebug(PROTOCOL) logger(LOG_WARNING, "Got %s from %s (%s) for ourself", + logger(DEBUG_PROTOCOL, LOG_WARNING, "Got %s from %s (%s) for ourself", "DEL_SUBNET", c->name, c->hostname); send_add_subnet(c, find); return true; diff --git a/src/raw_socket_device.c b/src/raw_socket_device.c index 3785dcf6..48954d5d 100644 --- a/src/raw_socket_device.c +++ b/src/raw_socket_device.c @@ -51,7 +51,7 @@ static bool setup_device(void) { device_info = "raw socket"; if((device_fd = socket(PF_PACKET, SOCK_RAW, htons(ETH_P_ALL))) < 0) { - logger(LOG_ERR, "Could not open %s: %s", device_info, + logger(DEBUG_ALWAYS, LOG_ERR, "Could not open %s: %s", device_info, strerror(errno)); return false; } @@ -65,7 +65,7 @@ static bool setup_device(void) { strncpy(ifr.ifr_ifrn.ifrn_name, iface, IFNAMSIZ); if(ioctl(device_fd, SIOCGIFINDEX, &ifr)) { close(device_fd); - logger(LOG_ERR, "Can't find interface %s: %s", iface, + logger(DEBUG_ALWAYS, LOG_ERR, "Can't find interface %s: %s", iface, strerror(errno)); return false; } @@ -76,11 +76,11 @@ static bool setup_device(void) { sa.sll_ifindex = ifr.ifr_ifindex; if(bind(device_fd, (struct sockaddr *) &sa, (socklen_t) sizeof sa)) { - logger(LOG_ERR, "Could not bind %s to %s: %s", device, iface, strerror(errno)); + logger(DEBUG_ALWAYS, LOG_ERR, "Could not bind %s to %s: %s", device, iface, strerror(errno)); return false; } - logger(LOG_INFO, "%s is a %s", device, device_info); + logger(DEBUG_ALWAYS, LOG_INFO, "%s is a %s", device, device_info); return true; } @@ -96,7 +96,7 @@ static bool read_packet(vpn_packet_t *packet) { int inlen; if((inlen = read(device_fd, packet->data, MTU)) <= 0) { - logger(LOG_ERR, "Error while reading from %s %s: %s", device_info, + logger(DEBUG_ALWAYS, LOG_ERR, "Error while reading from %s %s: %s", device_info, device, strerror(errno)); return false; } @@ -105,18 +105,18 @@ static bool read_packet(vpn_packet_t *packet) { device_total_in += packet->len; - ifdebug(TRAFFIC) logger(LOG_DEBUG, "Read packet of %d bytes from %s", packet->len, + logger(DEBUG_TRAFFIC, LOG_DEBUG, "Read packet of %d bytes from %s", packet->len, device_info); return true; } static bool write_packet(vpn_packet_t *packet) { - ifdebug(TRAFFIC) logger(LOG_DEBUG, "Writing packet of %d bytes to %s", + logger(DEBUG_TRAFFIC, LOG_DEBUG, "Writing packet of %d bytes to %s", packet->len, device_info); if(write(device_fd, packet->data, packet->len) < 0) { - logger(LOG_ERR, "Can't write to %s %s: %s", device_info, device, + logger(DEBUG_ALWAYS, LOG_ERR, "Can't write to %s %s: %s", device_info, device, strerror(errno)); return false; } @@ -127,9 +127,9 @@ static bool write_packet(vpn_packet_t *packet) { } static void dump_device_stats(void) { - logger(LOG_DEBUG, "Statistics for %s %s:", device_info, device); - logger(LOG_DEBUG, " total bytes in: %10"PRIu64, device_total_in); - logger(LOG_DEBUG, " total bytes out: %10"PRIu64, device_total_out); + logger(DEBUG_ALWAYS, LOG_DEBUG, "Statistics for %s %s:", device_info, device); + logger(DEBUG_ALWAYS, LOG_DEBUG, " total bytes in: %10"PRIu64, device_total_in); + logger(DEBUG_ALWAYS, LOG_DEBUG, " total bytes out: %10"PRIu64, device_total_out); } const devops_t raw_socket_devops = { @@ -143,7 +143,7 @@ const devops_t raw_socket_devops = { #else static bool not_supported(void) { - logger(LOG_ERR, "Raw socket device not supported on this platform"); + logger(DEBUG_ALWAYS, LOG_ERR, "Raw socket device not supported on this platform"); return false; } diff --git a/src/route.c b/src/route.c index c73ac9f2..c7604668 100644 --- a/src/route.c +++ b/src/route.c @@ -101,7 +101,7 @@ static bool ratelimit(int frequency) { static bool checklength(node_t *source, vpn_packet_t *packet, length_t length) { if(packet->len < length) { - ifdebug(TRAFFIC) logger(LOG_WARNING, "Got too short packet from %s (%s)", source->name, source->hostname); + logger(DEBUG_TRAFFIC, LOG_WARNING, "Got too short packet from %s (%s)", source->name, source->hostname); return false; } else return true; @@ -164,7 +164,7 @@ static void clamp_mss(const node_t *source, const node_t *via, vpn_packet_t *pac if(oldmss <= newmss) break; - ifdebug(TRAFFIC) logger(LOG_INFO, "Clamping MSS of packet from %s to %s to %d", source->name, via->name, newmss); + logger(DEBUG_TRAFFIC, LOG_INFO, "Clamping MSS of packet from %s to %s to %d", source->name, via->name, newmss); /* Update the MSS value and the checksum */ packet->data[start + 22 + i] = newmss >> 8; @@ -197,10 +197,10 @@ static void age_subnets(int fd, short events, void *data) { next = node->next; s = node->data; if(s->expires && s->expires < now) { - ifdebug(TRAFFIC) { + if(debug_level >= DEBUG_TRAFFIC) { char netstr[MAXNETSTR]; if(net2str(netstr, sizeof netstr, s)) - logger(LOG_INFO, "Subnet %s expired", netstr); + logger(DEBUG_TRAFFIC, LOG_INFO, "Subnet %s expired", netstr); } for(node2 = connection_tree->head; node2; node2 = node2->next) { @@ -230,7 +230,7 @@ static void learn_mac(mac_t *address) { /* If we don't know this MAC address yet, store it */ if(!subnet) { - ifdebug(TRAFFIC) logger(LOG_INFO, "Learned new MAC address %hx:%hx:%hx:%hx:%hx:%hx", + logger(DEBUG_TRAFFIC, LOG_INFO, "Learned new MAC address %hx:%hx:%hx:%hx:%hx:%hx", address->x[0], address->x[1], address->x[2], address->x[3], address->x[4], address->x[5]); @@ -350,11 +350,11 @@ static void fragment_ipv4_packet(node_t *dest, vpn_packet_t *packet) { todo = ntohs(ip.ip_len) - ip_size; if(ether_size + ip_size + todo != packet->len) { - ifdebug(TRAFFIC) logger(LOG_WARNING, "Length of packet (%d) doesn't match length in IPv4 header (%d)", packet->len, (int)(ether_size + ip_size + todo)); + logger(DEBUG_TRAFFIC, LOG_WARNING, "Length of packet (%d) doesn't match length in IPv4 header (%d)", packet->len, (int)(ether_size + ip_size + todo)); return; } - ifdebug(TRAFFIC) logger(LOG_INFO, "Fragmenting packet of %d bytes to %s (%s)", packet->len, dest->name, dest->hostname); + logger(DEBUG_TRAFFIC, LOG_INFO, "Fragmenting packet of %d bytes to %s (%s)", packet->len, dest->name, dest->hostname); offset = packet->data + ether_size + ip_size; maxlen = (dest->mtu - ether_size - ip_size) & ~0x7; @@ -391,7 +391,7 @@ static void route_ipv4_unicast(node_t *source, vpn_packet_t *packet) { subnet = lookup_subnet_ipv4(&dest); if(!subnet) { - ifdebug(TRAFFIC) logger(LOG_WARNING, "Cannot route packet from %s (%s): unknown IPv4 destination address %d.%d.%d.%d", + logger(DEBUG_TRAFFIC, LOG_WARNING, "Cannot route packet from %s (%s): unknown IPv4 destination address %d.%d.%d.%d", source->name, source->hostname, dest.x[0], dest.x[1], @@ -403,7 +403,7 @@ static void route_ipv4_unicast(node_t *source, vpn_packet_t *packet) { } if(subnet->owner == source) { - ifdebug(TRAFFIC) logger(LOG_WARNING, "Packet looping back to %s (%s)!", source->name, source->hostname); + logger(DEBUG_TRAFFIC, LOG_WARNING, "Packet looping back to %s (%s)!", source->name, source->hostname); return; } @@ -419,7 +419,7 @@ static void route_ipv4_unicast(node_t *source, vpn_packet_t *packet) { via = (subnet->owner->via == myself) ? subnet->owner->nexthop : subnet->owner->via; if(via == source) { - ifdebug(TRAFFIC) logger(LOG_ERR, "Routing loop for packet from %s (%s)!", source->name, source->hostname); + logger(DEBUG_TRAFFIC, LOG_ERR, "Routing loop for packet from %s (%s)!", source->name, source->hostname); return; } @@ -427,7 +427,7 @@ static void route_ipv4_unicast(node_t *source, vpn_packet_t *packet) { return route_ipv4_unreachable(source, packet, ICMP_DEST_UNREACH, ICMP_NET_ANO); if(via && packet->len > MAX(via->mtu, 590) && via != myself) { - ifdebug(TRAFFIC) logger(LOG_INFO, "Packet for %s (%s) length %d larger than MTU %d", subnet->owner->name, subnet->owner->hostname, packet->len, via->mtu); + logger(DEBUG_TRAFFIC, LOG_INFO, "Packet for %s (%s) length %d larger than MTU %d", subnet->owner->name, subnet->owner->hostname, packet->len, via->mtu); if(packet->data[20] & 0x40) { packet->len = MAX(via->mtu, 590); route_ipv4_unreachable(source, packet, ICMP_DEST_UNREACH, ICMP_FRAG_NEEDED); @@ -546,7 +546,7 @@ static void route_ipv6_unicast(node_t *source, vpn_packet_t *packet) { subnet = lookup_subnet_ipv6(&dest); if(!subnet) { - ifdebug(TRAFFIC) logger(LOG_WARNING, "Cannot route packet from %s (%s): unknown IPv6 destination address %hx:%hx:%hx:%hx:%hx:%hx:%hx:%hx", + logger(DEBUG_TRAFFIC, LOG_WARNING, "Cannot route packet from %s (%s): unknown IPv6 destination address %hx:%hx:%hx:%hx:%hx:%hx:%hx:%hx", source->name, source->hostname, ntohs(dest.x[0]), ntohs(dest.x[1]), @@ -562,7 +562,7 @@ static void route_ipv6_unicast(node_t *source, vpn_packet_t *packet) { } if(subnet->owner == source) { - ifdebug(TRAFFIC) logger(LOG_WARNING, "Packet looping back to %s (%s)!", source->name, source->hostname); + logger(DEBUG_TRAFFIC, LOG_WARNING, "Packet looping back to %s (%s)!", source->name, source->hostname); return; } @@ -575,7 +575,7 @@ static void route_ipv6_unicast(node_t *source, vpn_packet_t *packet) { via = (subnet->owner->via == myself) ? subnet->owner->nexthop : subnet->owner->via; if(via == source) { - ifdebug(TRAFFIC) logger(LOG_ERR, "Routing loop for packet from %s (%s)!", source->name, source->hostname); + logger(DEBUG_TRAFFIC, LOG_ERR, "Routing loop for packet from %s (%s)!", source->name, source->hostname); return; } @@ -583,7 +583,7 @@ static void route_ipv6_unicast(node_t *source, vpn_packet_t *packet) { return route_ipv6_unreachable(source, packet, ICMP6_DST_UNREACH, ICMP6_DST_UNREACH_ADMIN); if(via && packet->len > MAX(via->mtu, 1294) && via != myself) { - ifdebug(TRAFFIC) logger(LOG_INFO, "Packet for %s (%s) length %d larger than MTU %d", subnet->owner->name, subnet->owner->hostname, packet->len, via->mtu); + logger(DEBUG_TRAFFIC, LOG_INFO, "Packet for %s (%s) length %d larger than MTU %d", subnet->owner->name, subnet->owner->hostname, packet->len, via->mtu); packet->len = MAX(via->mtu, 1294); route_ipv6_unreachable(source, packet, ICMP6_PACKET_TOO_BIG, 0); return; @@ -617,7 +617,7 @@ static void route_neighborsol(node_t *source, vpn_packet_t *packet) { has_opt = packet->len >= ether_size + ip6_size + ns_size + opt_size + ETH_ALEN; if(source != myself) { - ifdebug(TRAFFIC) logger(LOG_WARNING, "Got neighbor solicitation request from %s (%s) while in router mode!", source->name, source->hostname); + logger(DEBUG_TRAFFIC, LOG_WARNING, "Got neighbor solicitation request from %s (%s) while in router mode!", source->name, source->hostname); return; } @@ -637,7 +637,7 @@ static void route_neighborsol(node_t *source, vpn_packet_t *packet) { if(ns.nd_ns_hdr.icmp6_type != ND_NEIGHBOR_SOLICIT || (has_opt && opt.nd_opt_type != ND_OPT_SOURCE_LINKADDR)) { - ifdebug(TRAFFIC) logger(LOG_WARNING, "Cannot route packet: received unknown type neighbor solicitation request"); + logger(DEBUG_TRAFFIC, LOG_WARNING, "Cannot route packet: received unknown type neighbor solicitation request"); return; } @@ -661,7 +661,7 @@ static void route_neighborsol(node_t *source, vpn_packet_t *packet) { } if(checksum) { - ifdebug(TRAFFIC) logger(LOG_WARNING, "Cannot route packet: checksum error for neighbor solicitation request"); + logger(DEBUG_TRAFFIC, LOG_WARNING, "Cannot route packet: checksum error for neighbor solicitation request"); return; } @@ -670,7 +670,7 @@ static void route_neighborsol(node_t *source, vpn_packet_t *packet) { subnet = lookup_subnet_ipv6((ipv6_t *) &ns.nd_ns_target); if(!subnet) { - ifdebug(TRAFFIC) logger(LOG_WARNING, "Cannot route packet: neighbor solicitation request for unknown address %hx:%hx:%hx:%hx:%hx:%hx:%hx:%hx", + logger(DEBUG_TRAFFIC, LOG_WARNING, "Cannot route packet: neighbor solicitation request for unknown address %hx:%hx:%hx:%hx:%hx:%hx:%hx:%hx", ntohs(((uint16_t *) &ns.nd_ns_target)[0]), ntohs(((uint16_t *) &ns.nd_ns_target)[1]), ntohs(((uint16_t *) &ns.nd_ns_target)[2]), @@ -761,7 +761,7 @@ static void route_arp(node_t *source, vpn_packet_t *packet) { return; if(source != myself) { - ifdebug(TRAFFIC) logger(LOG_WARNING, "Got ARP request from %s (%s) while in router mode!", source->name, source->hostname); + logger(DEBUG_TRAFFIC, LOG_WARNING, "Got ARP request from %s (%s) while in router mode!", source->name, source->hostname); return; } @@ -778,7 +778,7 @@ static void route_arp(node_t *source, vpn_packet_t *packet) { if(ntohs(arp.arp_hrd) != ARPHRD_ETHER || ntohs(arp.arp_pro) != ETH_P_IP || arp.arp_hln != ETH_ALEN || arp.arp_pln != sizeof addr || ntohs(arp.arp_op) != ARPOP_REQUEST) { - ifdebug(TRAFFIC) logger(LOG_WARNING, "Cannot route packet: received unknown type ARP request"); + logger(DEBUG_TRAFFIC, LOG_WARNING, "Cannot route packet: received unknown type ARP request"); return; } @@ -787,7 +787,7 @@ static void route_arp(node_t *source, vpn_packet_t *packet) { subnet = lookup_subnet_ipv4((ipv4_t *) &arp.arp_tpa); if(!subnet) { - ifdebug(TRAFFIC) logger(LOG_WARNING, "Cannot route packet: ARP request for unknown address %d.%d.%d.%d", + logger(DEBUG_TRAFFIC, LOG_WARNING, "Cannot route packet: ARP request for unknown address %d.%d.%d.%d", arp.arp_tpa[0], arp.arp_tpa[1], arp.arp_tpa[2], arp.arp_tpa[3]); return; @@ -840,7 +840,7 @@ static void route_mac(node_t *source, vpn_packet_t *packet) { } if(subnet->owner == source) { - ifdebug(TRAFFIC) logger(LOG_WARNING, "Packet looping back to %s (%s)!", source->name, source->hostname); + logger(DEBUG_TRAFFIC, LOG_WARNING, "Packet looping back to %s (%s)!", source->name, source->hostname); return; } @@ -855,7 +855,7 @@ static void route_mac(node_t *source, vpn_packet_t *packet) { return; if(via && packet->len > via->mtu && via != myself) { - ifdebug(TRAFFIC) logger(LOG_INFO, "Packet for %s (%s) length %d larger than MTU %d", subnet->owner->name, subnet->owner->hostname, packet->len, via->mtu); + logger(DEBUG_TRAFFIC, LOG_INFO, "Packet for %s (%s) length %d larger than MTU %d", subnet->owner->name, subnet->owner->hostname, packet->len, via->mtu); uint16_t type = packet->data[12] << 8 | packet->data[13]; if(type == ETH_P_IP && packet->len > 590) { if(packet->data[20] & 0x40) { @@ -883,10 +883,14 @@ static void send_pcap(vpn_packet_t *packet) { connection_t *c = node->data; if(!c->status.pcap) continue; - else - pcap = true; - if(send_request(c, "%d %d %d", CONTROL, REQ_PCAP, packet->len)) - send_meta(c, (char *)packet->data, packet->len); + + pcap = true; + int len = packet->len; + if(c->outmaclength && c->outmaclength < len) + len = c->outmaclength; + + if(send_request(c, "%d %d %d", CONTROL, REQ_PCAP, len)) + send_meta(c, (char *)packet->data, len); } } @@ -971,7 +975,7 @@ void route(node_t *source, vpn_packet_t *packet) { break; default: - ifdebug(TRAFFIC) logger(LOG_WARNING, "Cannot route packet from %s (%s): unknown type %hx", source->name, source->hostname, type); + logger(DEBUG_TRAFFIC, LOG_WARNING, "Cannot route packet from %s (%s): unknown type %hx", source->name, source->hostname, type); break; } } diff --git a/src/solaris/device.c b/src/solaris/device.c index 365561fd..6584b7f1 100644 --- a/src/solaris/device.c +++ b/src/solaris/device.c @@ -51,7 +51,7 @@ static bool setup_device(void) { device = xstrdup(DEFAULT_DEVICE); if((device_fd = open(device, O_RDWR | O_NONBLOCK)) < 0) { - logger(LOG_ERR, "Could not open %s: %s", device, strerror(errno)); + logger(DEBUG_ALWAYS, LOG_ERR, "Could not open %s: %s", device, strerror(errno)); return false; } @@ -67,7 +67,7 @@ static bool setup_device(void) { ppa = atoi(ptr); if((ip_fd = open("/dev/ip", O_RDWR, 0)) < 0) { - logger(LOG_ERR, "Could not open /dev/ip: %s", strerror(errno)); + logger(DEBUG_ALWAYS, LOG_ERR, "Could not open /dev/ip: %s", strerror(errno)); return false; } @@ -77,12 +77,12 @@ static bool setup_device(void) { /* Assign a new PPA and get its unit number. */ if((ppa = ioctl(device_fd, TUNNEWPPA, ppa)) < 0) { - logger(LOG_ERR, "Can't assign new interface: %s", strerror(errno)); + logger(DEBUG_ALWAYS, LOG_ERR, "Can't assign new interface: %s", strerror(errno)); return false; } if((if_fd = open(device, O_RDWR, 0)) < 0) { - logger(LOG_ERR, "Could not open %s twice: %s", device, + logger(DEBUG_ALWAYS, LOG_ERR, "Could not open %s twice: %s", device, strerror(errno)); return false; } @@ -92,18 +92,18 @@ static bool setup_device(void) { #endif if(ioctl(if_fd, I_PUSH, "ip") < 0) { - logger(LOG_ERR, "Can't push IP module: %s", strerror(errno)); + logger(DEBUG_ALWAYS, LOG_ERR, "Can't push IP module: %s", strerror(errno)); return false; } /* Assign ppa according to the unit number returned by tun device */ if(ioctl(if_fd, IF_UNITSEL, (char *) &ppa) < 0) { - logger(LOG_ERR, "Can't set PPA %d: %s", ppa, strerror(errno)); + logger(DEBUG_ALWAYS, LOG_ERR, "Can't set PPA %d: %s", ppa, strerror(errno)); return false; } if(ioctl(ip_fd, I_LINK, if_fd) < 0) { - logger(LOG_ERR, "Can't link TUN device to IP: %s", strerror(errno)); + logger(DEBUG_ALWAYS, LOG_ERR, "Can't link TUN device to IP: %s", strerror(errno)); return false; } @@ -112,7 +112,7 @@ static bool setup_device(void) { device_info = "Solaris tun device"; - logger(LOG_INFO, "%s is a %s", device, device_info); + logger(DEBUG_ALWAYS, LOG_INFO, "%s is a %s", device, device_info); return true; } @@ -130,7 +130,7 @@ static bool read_packet(vpn_packet_t *packet) { int inlen; if((inlen = read(device_fd, packet->data + 14, MTU - 14)) <= 0) { - logger(LOG_ERR, "Error while reading from %s %s: %s", device_info, + logger(DEBUG_ALWAYS, LOG_ERR, "Error while reading from %s %s: %s", device_info, device, strerror(errno)); return false; } @@ -145,7 +145,7 @@ static bool read_packet(vpn_packet_t *packet) { packet->data[13] = 0xDD; break; default: - ifdebug(TRAFFIC) logger(LOG_ERR, + logger(DEBUG_TRAFFIC, LOG_ERR, "Unknown IP version %d while reading packet from %s %s", packet->data[14] >> 4, device_info, device); return false; @@ -155,18 +155,18 @@ static bool read_packet(vpn_packet_t *packet) { device_total_in += packet->len; - ifdebug(TRAFFIC) logger(LOG_DEBUG, "Read packet of %d bytes from %s", packet->len, + logger(DEBUG_TRAFFIC, LOG_DEBUG, "Read packet of %d bytes from %s", packet->len, device_info); return true; } static bool write_packet(vpn_packet_t *packet) { - ifdebug(TRAFFIC) logger(LOG_DEBUG, "Writing packet of %d bytes to %s", + logger(DEBUG_TRAFFIC, LOG_DEBUG, "Writing packet of %d bytes to %s", packet->len, device_info); if(write(device_fd, packet->data + 14, packet->len - 14) < 0) { - logger(LOG_ERR, "Can't write to %s %s: %s", device_info, + logger(DEBUG_ALWAYS, LOG_ERR, "Can't write to %s %s: %s", device_info, device, strerror(errno)); return false; } @@ -177,9 +177,9 @@ static bool write_packet(vpn_packet_t *packet) { } static void dump_device_stats(void) { - logger(LOG_DEBUG, "Statistics for %s %s:", device_info, device); - logger(LOG_DEBUG, " total bytes in: %10"PRIu64, device_total_in); - logger(LOG_DEBUG, " total bytes out: %10"PRIu64, device_total_out); + logger(DEBUG_ALWAYS, LOG_DEBUG, "Statistics for %s %s:", device_info, device); + logger(DEBUG_ALWAYS, LOG_DEBUG, " total bytes in: %10"PRIu64, device_total_in); + logger(DEBUG_ALWAYS, LOG_DEBUG, " total bytes out: %10"PRIu64, device_total_out); } const devops_t os_devops = { diff --git a/src/sptps_test.c b/src/sptps_test.c index 06d8deab..56dcc886 100644 --- a/src/sptps_test.c +++ b/src/sptps_test.c @@ -25,7 +25,12 @@ #include "sptps.h" #include "utils.h" +// Symbols necessary to link with logger.o char *logfilename; +char *connection_tree; +char *send_request; +char *send_meta; + ecdsa_t mykey, hiskey; static bool send_data(void *handle, const char *data, size_t len) { diff --git a/src/subnet.c b/src/subnet.c index 2c67dcc1..e1de1012 100644 --- a/src/subnet.c +++ b/src/subnet.c @@ -135,7 +135,7 @@ int subnet_compare(const subnet_t *a, const subnet_t *b) { case SUBNET_IPV6: return subnet_compare_ipv6(a, b); default: - logger(LOG_ERR, "subnet_compare() was called with unknown subnet type %d, exitting!", + logger(DEBUG_ALWAYS, LOG_ERR, "subnet_compare() was called with unknown subnet type %d, exitting!", a->type); exit(0); } @@ -274,7 +274,7 @@ bool str2net(subnet_t *subnet, const char *subnetstr) { bool net2str(char *netstr, int len, const subnet_t *subnet) { if(!netstr || !subnet) { - logger(LOG_ERR, "net2str() was called with netstr=%p, subnet=%p!", netstr, subnet); + logger(DEBUG_ALWAYS, LOG_ERR, "net2str() was called with netstr=%p, subnet=%p!", netstr, subnet); return false; } @@ -315,7 +315,7 @@ bool net2str(char *netstr, int len, const subnet_t *subnet) { break; default: - logger(LOG_ERR, + logger(DEBUG_ALWAYS, LOG_ERR, "net2str() was called with unknown subnet type %d, exiting!", subnet->type); exit(0); diff --git a/src/tincctl.c b/src/tincctl.c index d1df07be..63b75895 100644 --- a/src/tincctl.c +++ b/src/tincctl.c @@ -1,6 +1,6 @@ /* tincctl.c -- Controlling a running tincd - Copyright (C) 2007-2011 Guus Sliepen + Copyright (C) 2007-2012 Guus Sliepen This program is free software; you can redistribute it and/or modify it under the terms of the GNU General Public License as published by @@ -94,7 +94,8 @@ static void usage(bool status) { #ifdef HAVE_CURSES " top Show real-time statistics\n" #endif - " pcap Dump traffic in pcap format\n" + " pcap [snaplen] Dump traffic in pcap format [up to snaplen bytes per packet]\n" + " log [level] Dump log output [up to the specified level]\n" "\n"); printf("Report bugs to tinc@tinc-vpn.org.\n"); } @@ -147,7 +148,7 @@ static bool parse_options(int argc, char **argv) { return true; } -FILE *ask_and_open(const char *filename, const char *what, const char *mode) { +static FILE *ask_and_open(const char *filename, const char *what, const char *mode) { FILE *r; char *directory; char buf[PATH_MAX]; @@ -390,7 +391,7 @@ bool recvline(int fd, char *line, size_t len) { return true; } -bool recvdata(int fd, char *data, size_t len) { +static bool recvdata(int fd, char *data, size_t len) { while(blen < len) { int result = recv(fd, buffer + blen, sizeof buffer - blen, 0); if(result == -1 && errno == EINTR) @@ -436,8 +437,8 @@ bool sendline(int fd, char *format, ...) { return true; } -void pcap(int fd, FILE *out) { - sendline(fd, "%d %d", CONTROL, REQ_PCAP); +static void pcap(int fd, FILE *out, int snaplen) { + sendline(fd, "%d %d %d", CONTROL, REQ_PCAP, snaplen); char data[9018]; struct { @@ -452,7 +453,7 @@ void pcap(int fd, FILE *out) { 0xa1b2c3d4, 2, 4, 0, 0, - sizeof data, + snaplen ?: sizeof data, 1, }; @@ -487,6 +488,24 @@ void pcap(int fd, FILE *out) { } } +static void logcontrol(int fd, FILE *out, int level) { + sendline(fd, "%d %d %d", CONTROL, REQ_LOG, level); + char data[1024]; + char line[32]; + + while(recvline(fd, line, sizeof line)) { + int code, req, len; + int n = sscanf(line, "%d %d %d", &code, &req, &len); + if(n != 3 || code != CONTROL || req != REQ_LOG || len < 0 || len > sizeof data) + break; + if(!recvdata(fd, data, len)) + break; + fwrite(data, len, 1, out); + fputc('\n', out); + fflush(out); + } +} + #ifdef HAVE_MINGW static bool remove_service(void) { SC_HANDLE manager = NULL; @@ -539,7 +558,7 @@ int main(int argc, char *argv[]) { if(show_version) { printf("%s version %s (built %s %s, protocol %d.%d)\n", PACKAGE, VERSION, __DATE__, __TIME__, PROT_MAJOR, PROT_MINOR); - printf("Copyright (C) 1998-2009 Ivo Timmermans, Guus Sliepen and others.\n" + printf("Copyright (C) 1998-2012 Ivo Timmermans, Guus Sliepen and others.\n" "See the AUTHORS file for a complete list.\n\n" "tinc comes with ABSOLUTELY NO WARRANTY. This is free software,\n" "and you are welcome to redistribute it under certain conditions;\n" @@ -562,7 +581,7 @@ int main(int argc, char *argv[]) { // First handle commands that don't involve connecting to a running tinc daemon. if(!strcasecmp(argv[optind], "generate-rsa-keys")) { - return !rsa_keygen(optind > argc ? atoi(argv[optind + 1]) : 2048); + return !rsa_keygen(optind < argc - 1 ? atoi(argv[optind + 1]) : 2048); } if(!strcasecmp(argv[optind], "generate-ecdsa-keys")) { @@ -570,7 +589,7 @@ int main(int argc, char *argv[]) { } if(!strcasecmp(argv[optind], "generate-keys")) { - return !(rsa_keygen(optind > argc ? atoi(argv[optind + 1]) : 2048) && ecdsa_keygen()); + return !(rsa_keygen(optind < argc - 1 ? atoi(argv[optind + 1]) : 2048) && ecdsa_keygen()); } if(!strcasecmp(argv[optind], "start")) { @@ -842,7 +861,12 @@ int main(int argc, char *argv[]) { #endif if(!strcasecmp(argv[optind], "pcap")) { - pcap(fd, stdout); + pcap(fd, stdout, optind < argc - 1 ? atoi(argv[optind + 1]) : 0); + return 0; + } + + if(!strcasecmp(argv[optind], "log")) { + logcontrol(fd, stdout, optind < argc - 1 ? atoi(argv[optind + 1]) : -1); return 0; } diff --git a/src/tincd.c b/src/tincd.c index 7970bcc9..a78ca0c4 100644 --- a/src/tincd.c +++ b/src/tincd.c @@ -162,7 +162,7 @@ static bool parse_options(int argc, char **argv) { case 'L': /* no detach */ #ifndef HAVE_MLOCKALL - logger(LOG_ERR, "%s not supported on this platform", "mlockall()"); + logger(DEBUG_ALWAYS, LOG_ERR, "%s not supported on this platform", "mlockall()"); return false; #else do_mlock = true; @@ -276,7 +276,7 @@ static void make_names(void) { if(!confbase) xasprintf(&confbase, CONFDIR "/tinc/%s", netname); else - logger(LOG_INFO, "Both netname and configuration directory given, using the latter..."); + logger(DEBUG_ALWAYS, LOG_INFO, "Both netname and configuration directory given, using the latter..."); } else { if(!confbase) xasprintf(&confbase, CONFDIR "/tinc"); @@ -294,11 +294,11 @@ static void free_names(void) { static bool drop_privs(void) { #ifdef HAVE_MINGW if (switchuser) { - logger(LOG_ERR, "%s not supported on this platform", "-U"); + logger(DEBUG_ALWAYS, LOG_ERR, "%s not supported on this platform", "-U"); return false; } if (do_chroot) { - logger(LOG_ERR, "%s not supported on this platform", "-R"); + logger(DEBUG_ALWAYS, LOG_ERR, "%s not supported on this platform", "-R"); return false; } #else @@ -306,13 +306,13 @@ static bool drop_privs(void) { if (switchuser) { struct passwd *pw = getpwnam(switchuser); if (!pw) { - logger(LOG_ERR, "unknown user `%s'", switchuser); + logger(DEBUG_ALWAYS, LOG_ERR, "unknown user `%s'", switchuser); return false; } uid = pw->pw_uid; if (initgroups(switchuser, pw->pw_gid) != 0 || setgid(pw->pw_gid) != 0) { - logger(LOG_ERR, "System call `%s' failed: %s", + logger(DEBUG_ALWAYS, LOG_ERR, "System call `%s' failed: %s", "initgroups", strerror(errno)); return false; } @@ -322,7 +322,7 @@ static bool drop_privs(void) { if (do_chroot) { tzset(); /* for proper timestamps in logs */ if (chroot(confbase) != 0 || chdir("/") != 0) { - logger(LOG_ERR, "System call `%s' failed: %s", + logger(DEBUG_ALWAYS, LOG_ERR, "System call `%s' failed: %s", "chroot", strerror(errno)); return false; } @@ -331,7 +331,7 @@ static bool drop_privs(void) { } if (switchuser) if (setuid(uid) != 0) { - logger(LOG_ERR, "System call `%s' failed: %s", + logger(DEBUG_ALWAYS, LOG_ERR, "System call `%s' failed: %s", "setuid", strerror(errno)); return false; } @@ -375,7 +375,7 @@ int main(int argc, char **argv) { #ifdef HAVE_MINGW if(WSAStartup(MAKEWORD(2, 2), &wsa_state)) { - logger(LOG_ERR, "System call `%s' failed: %s", "WSAStartup", winerror(GetLastError())); + logger(DEBUG_ALWAYS, LOG_ERR, "System call `%s' failed: %s", "WSAStartup", winerror(GetLastError())); return 1; } #endif @@ -383,7 +383,7 @@ int main(int argc, char **argv) { openlogger("tinc", use_logfile?LOGMODE_FILE:LOGMODE_STDERR); if(!event_init()) { - logger(LOG_ERR, "Error initializing libevent!"); + logger(DEBUG_ALWAYS, LOG_ERR, "Error initializing libevent!"); return 1; } @@ -401,7 +401,7 @@ int main(int argc, char **argv) { #ifdef HAVE_LZO if(lzo_init() != LZO_E_OK) { - logger(LOG_ERR, "Error initializing LZO compressor!"); + logger(DEBUG_ALWAYS, LOG_ERR, "Error initializing LZO compressor!"); return 1; } #endif @@ -427,7 +427,7 @@ int main2(int argc, char **argv) { * This has to be done after daemon()/fork() so it works for child. * No need to do that in parent as it's very short-lived. */ if(do_mlock && mlockall(MCL_CURRENT | MCL_FUTURE) != 0) { - logger(LOG_ERR, "System call `%s' failed: %s", "mlockall", + logger(DEBUG_ALWAYS, LOG_ERR, "System call `%s' failed: %s", "mlockall", strerror(errno)); return 1; } @@ -450,24 +450,24 @@ int main2(int argc, char **argv) { if(get_config_string(lookup_config(config_tree, "ProcessPriority"), &priority)) { if(!strcasecmp(priority, "Normal")) { if (setpriority(NORMAL_PRIORITY_CLASS) != 0) { - logger(LOG_ERR, "System call `%s' failed: %s", + logger(DEBUG_ALWAYS, LOG_ERR, "System call `%s' failed: %s", "setpriority", strerror(errno)); goto end; } } else if(!strcasecmp(priority, "Low")) { if (setpriority(BELOW_NORMAL_PRIORITY_CLASS) != 0) { - logger(LOG_ERR, "System call `%s' failed: %s", + logger(DEBUG_ALWAYS, LOG_ERR, "System call `%s' failed: %s", "setpriority", strerror(errno)); goto end; } } else if(!strcasecmp(priority, "High")) { if (setpriority(HIGH_PRIORITY_CLASS) != 0) { - logger(LOG_ERR, "System call `%s' failed: %s", + logger(DEBUG_ALWAYS, LOG_ERR, "System call `%s' failed: %s", "setpriority", strerror(errno)); goto end; } } else { - logger(LOG_ERR, "Invalid priority `%s`!", priority); + logger(DEBUG_ALWAYS, LOG_ERR, "Invalid priority `%s`!", priority); goto end; } } @@ -482,7 +482,7 @@ int main2(int argc, char **argv) { /* Shutdown properly. */ - ifdebug(CONNECTIONS) + if(debug_level >= DEBUG_CONNECTIONS) devops.dump_stats(); close_network_connections(); @@ -491,7 +491,7 @@ end: exit_control(); end_nonet: - logger(LOG_NOTICE, "Terminating"); + logger(DEBUG_ALWAYS, LOG_NOTICE, "Terminating"); free(priority); diff --git a/src/uml_device.c b/src/uml_device.c index f0a9869b..744080a1 100644 --- a/src/uml_device.c +++ b/src/uml_device.c @@ -72,7 +72,7 @@ static bool setup_device(void) { device_info = "UML network socket"; if((write_fd = socket(PF_UNIX, SOCK_DGRAM, 0)) < 0) { - logger(LOG_ERR, "Could not open write %s: %s", device_info, strerror(errno)); + logger(DEBUG_ALWAYS, LOG_ERR, "Could not open write %s: %s", device_info, strerror(errno)); running = false; return false; } @@ -84,13 +84,13 @@ static bool setup_device(void) { setsockopt(write_fd, SOL_SOCKET, SO_REUSEADDR, &one, sizeof one); if(fcntl(write_fd, F_SETFL, O_NONBLOCK) < 0) { - logger(LOG_ERR, "System call `%s' failed: %s", "fcntl", strerror(errno)); + logger(DEBUG_ALWAYS, LOG_ERR, "System call `%s' failed: %s", "fcntl", strerror(errno)); running = false; return false; } if((data_fd = socket(PF_UNIX, SOCK_DGRAM, 0)) < 0) { - logger(LOG_ERR, "Could not open data %s: %s", device_info, strerror(errno)); + logger(DEBUG_ALWAYS, LOG_ERR, "Could not open data %s: %s", device_info, strerror(errno)); running = false; return false; } @@ -102,7 +102,7 @@ static bool setup_device(void) { setsockopt(data_fd, SOL_SOCKET, SO_REUSEADDR, &one, sizeof one); if(fcntl(data_fd, F_SETFL, O_NONBLOCK) < 0) { - logger(LOG_ERR, "System call `%s' failed: %s", "fcntl", strerror(errno)); + logger(DEBUG_ALWAYS, LOG_ERR, "System call `%s' failed: %s", "fcntl", strerror(errno)); running = false; return false; } @@ -115,13 +115,13 @@ static bool setup_device(void) { memcpy(&data_sun.sun_path, &name, sizeof name); if(bind(data_fd, (struct sockaddr *)&data_sun, sizeof data_sun) < 0) { - logger(LOG_ERR, "Could not bind data %s: %s", device_info, strerror(errno)); + logger(DEBUG_ALWAYS, LOG_ERR, "Could not bind data %s: %s", device_info, strerror(errno)); running = false; return false; } if((listen_fd = socket(PF_UNIX, SOCK_STREAM, 0)) < 0) { - logger(LOG_ERR, "Could not open %s: %s", device_info, + logger(DEBUG_ALWAYS, LOG_ERR, "Could not open %s: %s", device_info, strerror(errno)); return false; } @@ -133,26 +133,26 @@ static bool setup_device(void) { setsockopt(listen_fd, SOL_SOCKET, SO_REUSEADDR, &one, sizeof one); if(fcntl(listen_fd, F_SETFL, O_NONBLOCK) < 0) { - logger(LOG_ERR, "System call `%s' failed: %s", "fcntl", strerror(errno)); + logger(DEBUG_ALWAYS, LOG_ERR, "System call `%s' failed: %s", "fcntl", strerror(errno)); return false; } listen_sun.sun_family = AF_UNIX; strncpy(listen_sun.sun_path, device, sizeof listen_sun.sun_path); if(bind(listen_fd, (struct sockaddr *)&listen_sun, sizeof listen_sun) < 0) { - logger(LOG_ERR, "Could not bind %s to %s: %s", device_info, device, strerror(errno)); + logger(DEBUG_ALWAYS, LOG_ERR, "Could not bind %s to %s: %s", device_info, device, strerror(errno)); return false; } if(listen(listen_fd, 1) < 0) { - logger(LOG_ERR, "Could not listen on %s %s: %s", device_info, device, strerror(errno)); + logger(DEBUG_ALWAYS, LOG_ERR, "Could not listen on %s %s: %s", device_info, device, strerror(errno)); return false; } device_fd = listen_fd; state = 0; - logger(LOG_INFO, "%s is a %s", device, device_info); + logger(DEBUG_ALWAYS, LOG_INFO, "%s is a %s", device, device_info); if(routing_mode == RMODE_ROUTER) overwrite_mac = true; @@ -189,7 +189,7 @@ static bool read_packet(vpn_packet_t *packet) { request_fd = accept(listen_fd, &sa, &salen); if(request_fd < 0) { - logger(LOG_ERR, "Could not accept connection to %s %s: %s", device_info, device, strerror(errno)); + logger(DEBUG_ALWAYS, LOG_ERR, "Could not accept connection to %s %s: %s", device_info, device, strerror(errno)); return false; } @@ -198,7 +198,7 @@ static bool read_packet(vpn_packet_t *packet) { #endif if(fcntl(listen_fd, F_SETFL, O_NONBLOCK) < 0) { - logger(LOG_ERR, "System call `%s' failed: %s", "fcntl", strerror(errno)); + logger(DEBUG_ALWAYS, LOG_ERR, "System call `%s' failed: %s", "fcntl", strerror(errno)); running = false; return false; } @@ -213,21 +213,21 @@ static bool read_packet(vpn_packet_t *packet) { case 1: { if((inlen = read(request_fd, &request, sizeof request)) != sizeof request) { - logger(LOG_ERR, "Error while reading request from %s %s: %s", device_info, + logger(DEBUG_ALWAYS, LOG_ERR, "Error while reading request from %s %s: %s", device_info, device, strerror(errno)); running = false; return false; } if(request.magic != 0xfeedface || request.version != 3 || request.type != REQ_NEW_CONTROL) { - logger(LOG_ERR, "Unknown magic %x, version %d, request type %d from %s %s", + logger(DEBUG_ALWAYS, LOG_ERR, "Unknown magic %x, version %d, request type %d from %s %s", request.magic, request.version, request.type, device_info, device); running = false; return false; } if(connect(write_fd, &request.sock, sizeof request.sock) < 0) { - logger(LOG_ERR, "Could not bind write %s: %s", device_info, strerror(errno)); + logger(DEBUG_ALWAYS, LOG_ERR, "Could not bind write %s: %s", device_info, strerror(errno)); running = false; return false; } @@ -235,7 +235,7 @@ static bool read_packet(vpn_packet_t *packet) { write(request_fd, &data_sun, sizeof data_sun); device_fd = data_fd; - logger(LOG_INFO, "Connection with UML established"); + logger(DEBUG_ALWAYS, LOG_INFO, "Connection with UML established"); state = 2; return false; @@ -243,7 +243,7 @@ static bool read_packet(vpn_packet_t *packet) { case 2: { if((inlen = read(data_fd, packet->data, MTU)) <= 0) { - logger(LOG_ERR, "Error while reading from %s %s: %s", device_info, + logger(DEBUG_ALWAYS, LOG_ERR, "Error while reading from %s %s: %s", device_info, device, strerror(errno)); running = false; return false; @@ -253,31 +253,31 @@ static bool read_packet(vpn_packet_t *packet) { device_total_in += packet->len; - ifdebug(TRAFFIC) logger(LOG_DEBUG, "Read packet of %d bytes from %s", packet->len, + logger(DEBUG_TRAFFIC, LOG_DEBUG, "Read packet of %d bytes from %s", packet->len, device_info); return true; } default: - logger(LOG_ERR, "Invalid value for state variable in " __FILE__); + logger(DEBUG_ALWAYS, LOG_ERR, "Invalid value for state variable in " __FILE__); abort(); } } static bool write_packet(vpn_packet_t *packet) { if(state != 2) { - ifdebug(TRAFFIC) logger(LOG_DEBUG, "Dropping packet of %d bytes to %s: not connected to UML yet", + logger(DEBUG_TRAFFIC, LOG_DEBUG, "Dropping packet of %d bytes to %s: not connected to UML yet", packet->len, device_info); return false; } - ifdebug(TRAFFIC) logger(LOG_DEBUG, "Writing packet of %d bytes to %s", + logger(DEBUG_TRAFFIC, LOG_DEBUG, "Writing packet of %d bytes to %s", packet->len, device_info); if(write(write_fd, packet->data, packet->len) < 0) { if(errno != EINTR && errno != EAGAIN) { - logger(LOG_ERR, "Can't write to %s %s: %s", device_info, device, strerror(errno)); + logger(DEBUG_ALWAYS, LOG_ERR, "Can't write to %s %s: %s", device_info, device, strerror(errno)); running = false; } @@ -290,9 +290,9 @@ static bool write_packet(vpn_packet_t *packet) { } static void dump_device_stats(void) { - logger(LOG_DEBUG, "Statistics for %s %s:", device_info, device); - logger(LOG_DEBUG, " total bytes in: %10"PRIu64, device_total_in); - logger(LOG_DEBUG, " total bytes out: %10"PRIu64, device_total_out); + logger(DEBUG_ALWAYS, LOG_DEBUG, "Statistics for %s %s:", device_info, device); + logger(DEBUG_ALWAYS, LOG_DEBUG, " total bytes in: %10"PRIu64, device_total_in); + logger(DEBUG_ALWAYS, LOG_DEBUG, " total bytes out: %10"PRIu64, device_total_out); } const devops_t uml_devops = { diff --git a/src/vde_device.c b/src/vde_device.c index 258945ed..ab2ffdcd 100644 --- a/src/vde_device.c +++ b/src/vde_device.c @@ -45,7 +45,7 @@ static bool setup_device(void) { libvdeplug_dynopen(plug); if(!plug.dl_handle) { - logger(LOG_ERR, "Could not open libvdeplug library!"); + logger(DEBUG_ALWAYS, LOG_ERR, "Could not open libvdeplug library!"); return false; } @@ -68,7 +68,7 @@ static bool setup_device(void) { conn = plug.vde_open(device, identname, &args); if(!conn) { - logger(LOG_ERR, "Could not open VDE socket %s", device); + logger(DEBUG_ALWAYS, LOG_ERR, "Could not open VDE socket %s", device); return false; } @@ -78,7 +78,7 @@ static bool setup_device(void) { fcntl(device_fd, F_SETFD, FD_CLOEXEC); #endif - logger(LOG_INFO, "%s is a %s", device, device_info); + logger(DEBUG_ALWAYS, LOG_INFO, "%s is a %s", device, device_info); if(routing_mode == RMODE_ROUTER) overwrite_mac = true; @@ -101,14 +101,14 @@ static void close_device(void) { static bool read_packet(vpn_packet_t *packet) { int lenin = plug.vde_recv(conn, packet->data, MTU, 0); if(lenin <= 0) { - logger(LOG_ERR, "Error while reading from %s %s: %s", device_info, device, strerror(errno)); + logger(DEBUG_ALWAYS, LOG_ERR, "Error while reading from %s %s: %s", device_info, device, strerror(errno)); running = false; return false; } packet->len = lenin; device_total_in += packet->len; - ifdebug(TRAFFIC) logger(LOG_DEBUG, "Read packet of %d bytes from %s", packet->len, device_info); + logger(DEBUG_TRAFFIC, LOG_DEBUG, "Read packet of %d bytes from %s", packet->len, device_info); return true; } @@ -116,7 +116,7 @@ static bool read_packet(vpn_packet_t *packet) { static bool write_packet(vpn_packet_t *packet) { if(plug.vde_send(conn, packet->data, packet->len, 0) < 0) { if(errno != EINTR && errno != EAGAIN) { - logger(LOG_ERR, "Can't write to %s %s: %s", device_info, device, strerror(errno)); + logger(DEBUG_ALWAYS, LOG_ERR, "Can't write to %s %s: %s", device_info, device, strerror(errno)); running = false; } @@ -129,9 +129,9 @@ static bool write_packet(vpn_packet_t *packet) { } static void dump_device_stats(void) { - logger(LOG_DEBUG, "Statistics for %s %s:", device_info, device); - logger(LOG_DEBUG, " total bytes in: %10"PRIu64, device_total_in); - logger(LOG_DEBUG, " total bytes out: %10"PRIu64, device_total_out); + logger(DEBUG_ALWAYS, LOG_DEBUG, "Statistics for %s %s:", device_info, device); + logger(DEBUG_ALWAYS, LOG_DEBUG, " total bytes in: %10"PRIu64, device_total_in); + logger(DEBUG_ALWAYS, LOG_DEBUG, " total bytes out: %10"PRIu64, device_total_out); } const devops_t vde_devops = { -- 2.20.1