Fix issue 20: Escape unprintable characters when logging packets
This commit is contained in:
Heikki Hannikainen
parent
8906f9b681
commit
5173a3fc06
118
src/hlog.c
118
src/hlog.c
|
|
@ -73,6 +73,46 @@ char *log_destnames[] = {
|
|||
NULL
|
||||
};
|
||||
|
||||
/*
|
||||
* Quote a string, C-style. dst will be null-terminated, always.
|
||||
*/
|
||||
|
||||
static int str_quote(char *dst, int dst_len, const char *src, int src_len)
|
||||
{
|
||||
int si;
|
||||
int di = 0;
|
||||
int dst_use_len = dst_len - 2; /* leave space for terminating NUL and escaping an escape */
|
||||
unsigned char c;
|
||||
|
||||
for (si = 0; si < src_len; si++) {
|
||||
if (di >= dst_use_len)
|
||||
break;
|
||||
|
||||
c = (unsigned char) src[si];
|
||||
|
||||
/* printable ASCII */
|
||||
if (c >= 0x20 && c < 0x7f) {
|
||||
/* escape the escape (space reserved already) */
|
||||
if (c == '\\')
|
||||
dst[di++] = '\\';
|
||||
|
||||
dst[di++] = c;
|
||||
continue;
|
||||
}
|
||||
|
||||
/* hex escape, is going to take more space */
|
||||
if (di >= dst_use_len - 4)
|
||||
break;
|
||||
|
||||
dst[di++] = '\\';
|
||||
dst[di++] = 'x';
|
||||
di += snprintf(dst + di, 3, "%.2X", c);
|
||||
}
|
||||
|
||||
dst[di++] = 0;
|
||||
|
||||
return di;
|
||||
}
|
||||
|
||||
/*
|
||||
* Append a formatted string to a dynamically allocated string
|
||||
|
|
@ -264,31 +304,13 @@ int rotate_log(void)
|
|||
return 0;
|
||||
}
|
||||
|
||||
/*
|
||||
* Log a message
|
||||
*/
|
||||
|
||||
int hlog(int priority, const char *fmt, ...)
|
||||
static int hlog_write(int priority, const char *s)
|
||||
{
|
||||
va_list args;
|
||||
char s[LOG_LEN];
|
||||
char wb[LOG_LEN];
|
||||
int len, w;
|
||||
struct tm lt;
|
||||
struct timeval tv;
|
||||
char wb[LOG_LEN];
|
||||
int len, w;
|
||||
|
||||
if (priority > 7)
|
||||
priority = 7;
|
||||
else if (priority < 0)
|
||||
priority = 0;
|
||||
|
||||
if (priority > log_level)
|
||||
return 0;
|
||||
|
||||
va_start(args, fmt);
|
||||
vsnprintf(s, LOG_LEN, fmt, args);
|
||||
va_end(args);
|
||||
|
||||
gettimeofday(&tv, NULL);
|
||||
gmtime_r(&tv.tv_sec, <);
|
||||
|
||||
|
|
@ -300,6 +322,7 @@ int hlog(int priority, const char *fmt, ...)
|
|||
rwl_rdunlock(&log_file_lock);
|
||||
|
||||
}
|
||||
|
||||
if ((log_dest & L_FILE) && (log_file >= 0)) {
|
||||
len = snprintf(wb, LOG_LEN, "%4d/%02d/%02d %02d:%02d:%02d.%06d %s[%d:%lx] %s: %s\n",
|
||||
lt.tm_year + 1900, lt.tm_mon + 1, lt.tm_mday, lt.tm_hour, lt.tm_min, lt.tm_sec, (int)tv.tv_usec,
|
||||
|
|
@ -318,6 +341,7 @@ int hlog(int priority, const char *fmt, ...)
|
|||
}
|
||||
|
||||
}
|
||||
|
||||
if (log_dest & L_SYSLOG) {
|
||||
rwl_rdlock(&log_file_lock);
|
||||
syslog(priority, "%s: %s", log_levelnames[priority], s);
|
||||
|
|
@ -327,6 +351,58 @@ int hlog(int priority, const char *fmt, ...)
|
|||
return 1;
|
||||
}
|
||||
|
||||
/*
|
||||
* Log a message with a packet (will be quoted)
|
||||
*/
|
||||
|
||||
int hlog(int priority, const char *fmt, ...)
|
||||
{
|
||||
va_list args;
|
||||
char s[LOG_LEN];
|
||||
|
||||
if (priority > 7)
|
||||
priority = 7;
|
||||
else if (priority < 0)
|
||||
priority = 0;
|
||||
|
||||
if (priority > log_level)
|
||||
return 0;
|
||||
|
||||
va_start(args, fmt);
|
||||
vsnprintf(s, LOG_LEN, fmt, args);
|
||||
va_end(args);
|
||||
|
||||
return hlog_write(priority, s);
|
||||
}
|
||||
|
||||
|
||||
/*
|
||||
* Log a message, with a packet in the end.
|
||||
* Packet will be quoted.
|
||||
*/
|
||||
|
||||
int hlog_packet(int priority, const char *packet, int packetlen, const char *fmt, ...)
|
||||
{
|
||||
va_list args;
|
||||
char s[LOG_LEN];
|
||||
int l;
|
||||
|
||||
if (priority > 7)
|
||||
priority = 7;
|
||||
else if (priority < 0)
|
||||
priority = 0;
|
||||
|
||||
if (priority > log_level)
|
||||
return 0;
|
||||
|
||||
va_start(args, fmt);
|
||||
l = vsnprintf(s, LOG_LEN, fmt, args);
|
||||
va_end(args);
|
||||
|
||||
str_quote(s + l, LOG_LEN - l, packet, packetlen);
|
||||
|
||||
return hlog_write(priority, s);
|
||||
}
|
||||
|
||||
/*
|
||||
* Open access log
|
||||
|
|
|
|||
|
|
@ -41,6 +41,7 @@ extern int pick_loglevel(char *s, char **names);
|
|||
extern int open_log(char *name, int reopen);
|
||||
extern int close_log(int reopen);
|
||||
extern int hlog(int priority, const char *fmt, ...);
|
||||
extern int hlog_packet(int priority, const char *packet, int packetlen, const char *fmt, ...);
|
||||
|
||||
extern int accesslog_open(char *logd, int reopen);
|
||||
extern int accesslog_close(char *reopenpath);
|
||||
|
|
|
|||
|
|
@ -538,7 +538,7 @@ static int check_invalid_path_callsign(const char *call, int len, int after_q)
|
|||
const char *p = call;
|
||||
const char *e = call + len;
|
||||
|
||||
//hlog(LOG_DEBUG, "check_invalid_path_callsign: '%.*s'", len, call);
|
||||
//hlog_packet(LOG_DEBUG, call, len, "check_invalid_path_callsign: ");
|
||||
|
||||
/* only check for minimum length first - max length depends on
|
||||
* if there's a * in the end
|
||||
|
|
@ -566,7 +566,7 @@ static int check_invalid_path_callsign(const char *call, int len, int after_q)
|
|||
if (len > CALLSIGNLEN_MAX) {
|
||||
// TODO: more specific test for IPv6 trace address
|
||||
if (after_q && len == 32) {
|
||||
//hlog(LOG_DEBUG, "check_invalid_path_callsign: ipv6 address '%.*s'", len, call);
|
||||
//hlog_packet(LOG_DEBUG, call, len, "check_invalid_path_callsign: ipv6 address: ");
|
||||
return 0;
|
||||
}
|
||||
|
||||
|
|
@ -858,7 +858,7 @@ int incoming_parse(struct worker_t *self, struct client_t *c, char *s, int len)
|
|||
* would result in an error-type counter getting incremented.
|
||||
* This is slightly incorrect (perhaps the packet is not a
|
||||
* duplicate after all), probably there should be a separate
|
||||
* statistics counter for this. TODO: add a counter.
|
||||
* statistics counter for this. TODO: add a "looped" counter.
|
||||
*/
|
||||
//hlog(LOG_DEBUG, "%s/%s: dropping due to source call '%.*s' being logged in on another socket", c->addr_rem, c->username, src_end - s, s);
|
||||
pb->flags |= F_DUPE;
|
||||
|
|
@ -919,7 +919,7 @@ int incoming_parse(struct worker_t *self, struct client_t *c, char *s, int len)
|
|||
pb->dstcall_len = via_start - src_end - 1;
|
||||
pb->info_start = info_start;
|
||||
|
||||
//hlog(LOG_DEBUG, "After parsing and Qc algorithm: %.*s", pb->packet_len-2, pb->data);
|
||||
//hlog_packet(LOG_DEBUG, pb->data, pb->packet_len-2, "After parsing and Qc algorithm: ");
|
||||
|
||||
/* just try APRS parsing */
|
||||
rc = parse_aprs(pb);
|
||||
|
|
@ -995,7 +995,7 @@ int incoming_handler(struct worker_t *self, struct client_t *c, int l4proto, cha
|
|||
|
||||
/* starts with '#' => a comment packet, timestamp or something */
|
||||
if (*s == '#') {
|
||||
hlog(LOG_DEBUG, "%s/%s: #-in: '%.*s'", c->addr_rem, c->username, len, s);
|
||||
hlog_packet(LOG_DEBUG, s, len, "%s/%s: #-in: ", c->addr_rem, c->username);
|
||||
if (l4proto != IPPROTO_UDP && (c->flags & CLFLAGS_USERFILTEROK)) {
|
||||
/* filter adjunct commands ? */
|
||||
char *filtercmd = memcasestr("filter", s, s + len);
|
||||
|
|
@ -1010,11 +1010,11 @@ int incoming_handler(struct worker_t *self, struct client_t *c, int l4proto, cha
|
|||
/* parse and process the packet */
|
||||
e = incoming_parse(self, c, s, len);
|
||||
|
||||
in_drop:
|
||||
in_drop:
|
||||
if (e < 0) {
|
||||
/* failed parsing */
|
||||
hlog(LOG_DEBUG, "%s/%s: Dropped packet (%d: %s) len %d: %.*s",
|
||||
c->addr_rem, c->username, e, incoming_strerror(e), len, len, s);
|
||||
hlog_packet(LOG_DEBUG, s, len, "%s/%s: Dropped packet (%d: %s) len %d: ",
|
||||
c->addr_rem, c->username, e, incoming_strerror(e), len);
|
||||
}
|
||||
|
||||
/* Account the one incoming packet.
|
||||
|
|
|
|||
|
|
@ -87,15 +87,11 @@ static int pbuf_fill_pos(struct pbuf_t *pb, const float lat, const float lng, co
|
|||
|
||||
|
||||
if (bad || lat < -90.0 || lat > 90.0 || lng < -180.0 || lng > 180.0) {
|
||||
#ifdef DEBUG_PARSE_APRS
|
||||
hlog(LOG_DEBUG, "\tposition out of range: lat %.5f lng %.5f", lat, lng);
|
||||
#endif
|
||||
DEBUG_LOG("\tposition out of range: lat %.5f lng %.5f", lat, lng);
|
||||
return 0; /* out of range */
|
||||
}
|
||||
|
||||
#ifdef DEBUG_PARSE_APRS
|
||||
hlog(LOG_DEBUG, "\tposition ok: lat %.5f lng %.5f", lat, lng);
|
||||
#endif
|
||||
DEBUG_LOG("\tposition ok: lat %.5f lng %.5f", lat, lng);
|
||||
|
||||
/* Pre-calculations for A/R/F/M-filter tests */
|
||||
pb->lat = filter_lat2rad(lat); /* deg-to-radians */
|
||||
|
|
@ -113,7 +109,7 @@ static int pbuf_fill_pos(struct pbuf_t *pb, const float lat, const float lng, co
|
|||
|
||||
static int get_symbol_from_dstcall_twochar(const char c1, const char c2, char *sym_table, char *sym_code)
|
||||
{
|
||||
//hlog(LOG_DEBUG, "\ttwochar %c %c", c1, c2);
|
||||
//DEBUG_LOG("\ttwochar %c %c", c1, c2);
|
||||
if (c1 == 'B') {
|
||||
if (c2 >= 'B' && c2 <= 'P') {
|
||||
*sym_table = '/';
|
||||
|
|
@ -253,14 +249,12 @@ static int get_symbol_from_dstcall(struct pbuf_t *pb, char *sym_table, char *sym
|
|||
if (sublength > 3)
|
||||
sublength = 3;
|
||||
|
||||
#ifdef DEBUG_PARSE_APRS
|
||||
hlog(LOG_DEBUG, "get_symbol_from_dstcall: %.*s (%d)", (int)(pb->dstcall_end_or_ssid - d_start), d_start, sublength);
|
||||
#endif
|
||||
DEBUG_LOG("get_symbol_from_dstcall: %.*s (%d)", (int)(pb->dstcall_end_or_ssid - d_start), d_start, sublength);
|
||||
|
||||
if (strncmp(d_start, "GPS", 3) != 0 && strncmp(d_start, "SPC", 3) != 0 && strncmp(d_start, "SYM", 3) != 0)
|
||||
return 0;
|
||||
|
||||
// hlog(LOG_DEBUG, "\ttesting %c %c %c", d_start[3], d_start[4], d_start[5]);
|
||||
// DEBUG_LOG("\ttesting %c %c %c", d_start[3], d_start[4], d_start[5]);
|
||||
if (!isalnum(d_start[3]) || !isalnum(d_start[4]))
|
||||
return 0;
|
||||
|
||||
|
|
@ -283,10 +277,9 @@ static int get_symbol_from_dstcall(struct pbuf_t *pb, char *sym_table, char *sym
|
|||
else
|
||||
*sym_table = '\\';
|
||||
|
||||
#ifdef DEBUG_PARSE_APRS
|
||||
hlog(LOG_DEBUG, "\tnumeric symbol id in dstcall: %.*s: table %c code %c",
|
||||
DEBUG_LOG("\tnumeric symbol id in dstcall: %.*s: table %c code %c",
|
||||
(int)(pb->dstcall_end_or_ssid - d_start - 3), d_start + 3, *sym_table, *sym_code);
|
||||
#endif
|
||||
|
||||
return 1;
|
||||
} else {
|
||||
/* secondary symbol table, with overlay
|
||||
|
|
@ -322,10 +315,9 @@ static int parse_aprs_nmea(struct pbuf_t *pb, const char *body, const char *body
|
|||
|
||||
// Parse symbol from destination callsign, first thing before any possible returns
|
||||
get_symbol_from_dstcall(pb, &sym_table, &sym_code);
|
||||
#ifdef DEBUG_PARSE_APRS
|
||||
hlog(LOG_DEBUG, "get_symbol_from_dstcall: %.*s => %c%c",
|
||||
|
||||
DEBUG_LOG("get_symbol_from_dstcall: %.*s => %c%c",
|
||||
(int)(pb->dstcall_end_or_ssid - pb->srccall_end-1), pb->srccall_end+1, sym_table, sym_code);
|
||||
#endif
|
||||
|
||||
if (memcmp(body,"ULT",3) == 0) {
|
||||
/* Ah.. "$ULT..." - that is, Ultimeter 2000 weather instrument */
|
||||
|
|
@ -521,8 +513,8 @@ static int parse_aprs_nmea(struct pbuf_t *pb, const char *body, const char *body
|
|||
return 0; /* Well.. Not NMEA frame */
|
||||
}
|
||||
|
||||
// hlog(LOG_DEBUG, "NMEA parsing: %.*s", (int)(body_end - body), body);
|
||||
// hlog(LOG_DEBUG, " lat=%.10s lng=%.10s", latp, lngp);
|
||||
// DEBUG_LOG("NMEA parsing: %.*s", (int)(body_end - body), body);
|
||||
// DEBUG_LOG(" lat=%.10s lng=%.10s", latp, lngp);
|
||||
|
||||
i = sscanf(latp, "%2d%f,%c,", &la, &lat, &lac);
|
||||
if (i != 3)
|
||||
|
|
@ -537,7 +529,7 @@ static int parse_aprs_nmea(struct pbuf_t *pb, const char *body, const char *body
|
|||
if (loc != 'E' && loc != 'W' && loc != 'e' && loc != 'w')
|
||||
return 0; // bad indicator value
|
||||
|
||||
// hlog(LOG_DEBUG, " lat: %c %2d %7.4f lng: %c %2d %7.4f",
|
||||
// DEBUG_LOG(" lat: %c %2d %7.4f lng: %c %2d %7.4f",
|
||||
// lac, la, lat, loc, lo, lng);
|
||||
|
||||
lat = (float)la + lat/60.0;
|
||||
|
|
@ -1209,7 +1201,7 @@ static int parse_aprs_body(struct pbuf_t *pb, const char *info_start)
|
|||
}
|
||||
//keybuf[i] = 0;
|
||||
pb->dstname_len = p - body;
|
||||
//hlog(LOG_DEBUG, "message: dstname len %d", pb->dstname_len);
|
||||
//DEBUG_LOG("message: dstname len %d", pb->dstname_len);
|
||||
|
||||
/*
|
||||
* This adds a position for a message based on the
|
||||
|
|
|
|||
|
|
@ -479,7 +479,7 @@ int q_process(struct client_t *c, const char *pdata, char *new_q, int new_q_size
|
|||
*new_q_start = q_start + 1;
|
||||
add_qAO = 0;
|
||||
} else if (pathlen > 2 && *(*path_end -1) == 'I' && *(*path_end -2) == ',') {
|
||||
hlog(LOG_DEBUG, "path has ,I in the end: %s", pdata);
|
||||
hlog_packet(LOG_DEBUG, pdata, pathlen, "path has ,I in the end: ");
|
||||
/* the path is terminated with ,I - lookup previous callsign in path */
|
||||
char *p = *path_end - 3;
|
||||
while (p > via_start && *p != ',')
|
||||
|
|
@ -487,7 +487,7 @@ int q_process(struct client_t *c, const char *pdata, char *new_q, int new_q_size
|
|||
if (*p == ',') {
|
||||
const char *prevcall = p+1;
|
||||
const char *prevcall_end = *path_end - 2;
|
||||
hlog(LOG_DEBUG, "previous callsign is %.*s", (int)(prevcall_end - prevcall), prevcall);
|
||||
//hlog(LOG_DEBUG, "previous callsign is %.*s", (int)(prevcall_end - prevcall), prevcall);
|
||||
/* if the path is terminated with ,login,I */
|
||||
// TODO: Should validate that prevcall is a nice callsign
|
||||
if (1) {
|
||||
|
|
|
|||
|
|
@ -66,6 +66,8 @@ my @pkts = (
|
|||
"SRC\x08>DST,DIGI,qAR,$login:>should drop ctrl-B in srccall",
|
||||
" SRC>DST,DIGI,qAR,$login:>should drop, space in front of srccall",
|
||||
"\x00SRC>DST,DIGI,qAR,$login:>should drop, null in front of srccall",
|
||||
"S\\RC>DST,DIGI,qAR,$login:>should drop, backslash in srccall",
|
||||
"S\xefRC>DST,DIGI,qAR,$login:>should drop, high byte in srccall",
|
||||
"SRCXXXXXXX>APRS,qAR,$login:>should drop, too long srccall",
|
||||
"SRC>APRSXXXXXX,qAR,$login:>should drop, too long dstcall",
|
||||
"SRC>APRS,OH2DIGI-12,qAR,$login:>should drop, too long call in path",
|
||||
|
|
|
|||
Loading…
Reference in New Issue