From c522f45267686aaf1586b43336d3f768a2b74618 Mon Sep 17 00:00:00 2001 From: Micah Snyder Date: Sun, 3 Jan 2021 18:40:48 -0800 Subject: [PATCH] clamonacc: Reduce warning log verbosity Users have complained about two specific log events that are extremely verbose in non-critical error conditions: - clamonacc reports "ERROR: Can't send to clamd: Bad address" This may occur when small files are created/destroyed before they can be sent to be scanned. The log message probably should only be reported in verbose mode. - clamonacc reports "ClamMisc: $/proc/XXX vanished before UIDs could be excluded; scanning anyway" This may occur when a process that accessed a file exits before clamonacc find out who accessed the file. This is a fairly frequent occurence. It can still be problematic if `clamd` was the process which accessed the file (like a clamd temp file if watching /tmp), generally it's not an issue and we want to silently scan it anyways. Also addressed copypaste issue in onas_send_stream() wherein fd is set to 0 (aka STDIN) if the provided fd == 0 (should've been -1 for invalid FD) and if filename == NULL. In fact clamonacc never scans STDIN so the scan should fail if filename == NULL and the provided FD is invalid (-1). I also found that "Access denied. ERROR" is easily provoked when using --fdpass or --stream using this simple script: for i in {1..5000}; do echo "blah $i" > tmp-$i && rm tmp-$i; done Clamdscan does not allow for scans to fail quietly because the file does not exist, but for clamonacc it's a common thing and we don't want to output an error. To solve this, I changed it so a return length of -1 will still result in an "internal error" message but return len 0 failures will be silently ignored. I've added a static variable to onas_client_scan() that keeps state in case clamd is stopped and started - that way it won't print an error message for every event when offline. Instead it will log an error for the first connection failure, and log again when the connection is re-established for a future scan. Calls to onas_client_scan() are already wrapped with the onas_scan_lock mutex so the static variable should be safe. Finally, there were a couple of error responses from clamd that can occur if the file isn't found which we want to silently ignore, so I've tweaked the code which checks for specific error messages to account for these. --- clamd/scanner.c | 2 +- clamdscan/client.c | 18 ++++- clamdscan/proto.c | 8 ++- clamonacc/client/client.c | 40 +++++++++-- clamonacc/client/communication.c | 12 +++- clamonacc/client/protocol.c | 53 +++++++------- clamonacc/misc/utils.c | 2 +- clamonacc/scan/onas_queue.c | 3 +- clamonacc/scan/thread.c | 10 +-- libclamav/others.c | 116 ++++++++++++++++--------------- 10 files changed, 157 insertions(+), 107 deletions(-) diff --git a/clamd/scanner.c b/clamd/scanner.c index 4fb4df25c..66a3d2d29 100644 --- a/clamd/scanner.c +++ b/clamd/scanner.c @@ -146,7 +146,7 @@ cl_error_t scan_callback(STATBUF *sb, char *filename, const char *msg, enum cli_ if (NULL != filename) { if (CL_SUCCESS != cli_realpath((const char *)filename, &real_filename)) { - conn_reply_errno(scandata->conn, msg, "real-path check failed:"); + conn_reply_errno(scandata->conn, msg, "Failed to determine real path:"); logg("^Failed to determine real path for: %s\n", filename); logg("*Quarantine of the file may fail if file path contains symlinks.\n"); } else { diff --git a/clamdscan/client.c b/clamdscan/client.c index 0eb469e5b..7dab8ce7e 100644 --- a/clamdscan/client.c +++ b/clamdscan/client.c @@ -235,7 +235,17 @@ int16_t ping_clamd(const struct optstruct *opts) } if (i + 1 < attempts) { - logg("*PINGing again in %" PRIu64 " seconds\n", interval); + if (optget(opts, "wait")->enabled) { + if (interval == 1) + logg("*Could not connect, will try again in %lu second\n", interval); + else + logg("*Could not connect, will try again in %lu seconds\n", interval); + } else { + if (interval == 1) + logg("Could not connect, will PING again in %lu second\n", interval); + else + logg("Could not connect, will PING again in %lu seconds\n", interval); + } sleep(interval); } i++; @@ -243,7 +253,11 @@ int16_t ping_clamd(const struct optstruct *opts) /* timed out */ ret = 1; - logg("*PING timeout exceeded with no response from clamd\n"); + if (optget(opts, "wait")->enabled) { + logg("Wait timeout exceeded; Could not connect to clamd\n"); + } else { + logg("PING timeout exceeded; No response from clamd\n"); + } done: if (attempt_str) { diff --git a/clamdscan/proto.c b/clamdscan/proto.c index 9688ad757..a3fe7eaec 100644 --- a/clamdscan/proto.c +++ b/clamdscan/proto.c @@ -151,11 +151,13 @@ static int send_stream(int sockd, const char *filename) if (filename) { if ((fd = safe_open(filename, O_RDONLY | O_BINARY)) < 0) { - logg("~%s: Access denied. ERROR\n", filename); + logg("~%s: Failed to open file. ERROR\n", filename); return 0; } - } else + } else { + /* Read stream from STDIN */ fd = 0; + } if (sendln(sockd, "zINSTREAM", 10)) { close(fd); @@ -199,7 +201,7 @@ static int send_fdpass(int sockd, const char *filename) if (filename) { if ((fd = open(filename, O_RDONLY)) < 0) { - logg("~%s: Access denied. ERROR\n", filename); + logg("~%s: Failed to open file\n", filename); return 0; } } else diff --git a/clamonacc/client/client.c b/clamonacc/client/client.c index 495dc562a..347070f35 100644 --- a/clamonacc/client/client.c +++ b/clamonacc/client/client.c @@ -133,7 +133,11 @@ int onas_check_remote(struct onas_context **ctx, cl_error_t *err) curlcode = curl_easy_perform(curl); if (CURLE_OK != curlcode) { - logg("!ClamClient: could not connect to remote clam daemon, %s\n", curl_easy_strerror(curlcode)); + if (optget((*ctx)->opts, "ping")->enabled || optget((*ctx)->opts, "wait")->enabled) { + logg("~ClamClient: Initial connection failed, %s. Will try again...\n", curl_easy_strerror(curlcode)); + } else { + logg("!ClamClient: Could not connect to clamd, %s\n", curl_easy_strerror(curlcode)); + } *err = CL_EARG; return ret; } @@ -237,11 +241,13 @@ int16_t onas_ping_clamd(struct onas_context **ctx) do { curlcode = curl_easy_perform(curl); if (CURLE_OK != curlcode) { - logg("*ClamClient: could not connect to clam daemon, %s\n", curl_easy_strerror(curlcode)); + logg("*ClamClient: could not connect to clamd, %s\n", curl_easy_strerror(curlcode)); } else if (CURLE_OK == onas_sendln(curl, "zPING", 5, timeout)) { if (!optget((*ctx)->opts, "wait")->enabled) { logg("PONG\n"); + } else { + logg("*ClamClient: Connected.\n"); } ret = 0; @@ -249,7 +255,17 @@ int16_t onas_ping_clamd(struct onas_context **ctx) } if (i + 1 < attempts) { - logg("*PINGing again in %lu seconds\n", interval); + if (optget((*ctx)->opts, "wait")->enabled) { + if (interval == 1) + logg("*Will try again in %lu second\n", interval); + else + logg("*Will try again in %lu seconds\n", interval); + } else { + if (interval == 1) + logg("PINGing again in %lu second\n", interval); + else + logg("PINGing again in %lu seconds\n", interval); + } sleep(interval); } i++; @@ -257,7 +273,11 @@ int16_t onas_ping_clamd(struct onas_context **ctx) /* timed out */ ret = 1; - logg("*PING timeout exceeded with no response from clamd\n"); + if (optget((*ctx)->opts, "wait")->enabled) { + logg("Wait timeout exceeded; Could not connect to clamd\n"); + } else { + logg("PING timeout exceeded; No response from clamd\n"); + } done: if (curl) { @@ -488,7 +508,7 @@ int onas_get_clamd_version(struct onas_context **ctx) curlcode = curl_easy_perform(curl); if (CURLE_OK != curlcode) { - logg("*ClamClient: could not connect to clam daemon, %s\n", curl_easy_strerror(curlcode)); + logg("*ClamClient: could not connect to clamd, %s\n", curl_easy_strerror(curlcode)); return 2; } @@ -530,6 +550,7 @@ int onas_client_scan(const char *tcpaddr, int64_t portnum, int32_t scantype, uin CURLcode curlcode = CURLE_OK; int errors = 0; int ret; + static bool disconnected = false; *infected = 0; @@ -546,9 +567,16 @@ int onas_client_scan(const char *tcpaddr, int64_t portnum, int32_t scantype, uin curlcode = curl_easy_perform(curl); if (CURLE_OK != curlcode) { - logg("!ClamClient: could not establish connection, %s\n", curl_easy_strerror(curlcode)); + if (!disconnected) { + logg("!ClamClient: Connection to clamd failed, %s.\n", curl_easy_strerror(curlcode)); + disconnected = true; + } return CL_ECREAT; } + if (disconnected) { + logg("~ClamClient: Connection to clamd re-established.\n"); + disconnected = false; + } if ((ret = onas_dsresult(curl, scantype, maxstream, fname, fd, timeout, &ret, err, ret_code)) >= 0) { *infected = ret; diff --git a/clamonacc/client/communication.c b/clamonacc/client/communication.c index 1d2e53c03..4adc27342 100644 --- a/clamonacc/client/communication.c +++ b/clamonacc/client/communication.c @@ -89,7 +89,7 @@ int onas_sendln(CURL *curl, const void *line, size_t len, int64_t timeout) /* Use deprecated CURLINFO_LASTSOCKET option */ long long_sockfd; curlcode = curl_easy_getinfo(curl, CURLINFO_LASTSOCKET, &long_sockfd); - sockfd = (curl_socket_t) long_sockfd; + sockfd = (curl_socket_t)long_sockfd; #endif if (CURLE_OK != curlcode) { @@ -107,9 +107,15 @@ int onas_sendln(CURL *curl, const void *line, size_t len, int64_t timeout) } } while (CURLE_AGAIN == curlcode); - if (sent <= 0) { + if (sent == 0) { if (sent && errno == EINTR) { continue; + } else if (errno == EFAULT) { + /* Users have reported frequent "bad address" errors when files + are created & removed before the file can be sent to be + scanned. This isn't a critical error, so we'll log it in + verbose-mode only. */ + logg("*Can't send to clamd: %s\n", strerror(errno)); } else { logg("!Can't send to clamd: %s\n", strerror(errno)); } @@ -156,7 +162,7 @@ int onas_recvln(struct onas_rcvln *rcv_data, char **ret_bol, char **ret_eol, int /* Use deprecated CURLINFO_LASTSOCKET option */ long long_sockfd; rcv_data->curlcode = curl_easy_getinfo(rcv_data->curl, CURLINFO_LASTSOCKET, &long_sockfd); - sockfd = (curl_socket_t) long_sockfd; + sockfd = (curl_socket_t)long_sockfd; #endif if (CURLE_OK != rcv_data->curlcode) { diff --git a/clamonacc/client/protocol.c b/clamonacc/client/protocol.c index 170255645..37615f2a5 100644 --- a/clamonacc/client/protocol.c +++ b/clamonacc/client/protocol.c @@ -80,16 +80,17 @@ static int onas_send_stream(CURL *curl, const char *filename, int fd, int64_t ti int ret = 1; int close_flag = 0; - if (0 == fd) { - if (filename) { + if (-1 == fd) { + if (NULL == filename) { + logg("!onas_send_stream: Invalid args, a filename or file descriptor must be provided.\n"); + return 0; + } else { if ((fd = safe_open(filename, O_RDONLY | O_BINARY)) < 0) { - logg("~%s: Access denied. ERROR\n", filename); + logg("*%s: Failed to open file. ERROR\n", filename); return 0; } //logg("DEBUG: >>>>> fd is %d\n", fd); close_flag = 1; - } else { - fd = 0; } } @@ -113,8 +114,8 @@ static int onas_send_stream(CURL *curl, const char *filename, int fd, int64_t ti } if (len) { - logg("!Failed to read from %s.\n", filename ? filename : "STDIN"); - ret = 0; + logg("!Failed to read from %s.\n", filename ? filename : "FD"); + ret = -1; goto strm_out; } *buf = 0; @@ -169,15 +170,15 @@ static int onas_fdpass(const char *filename, int fd, int sockd) int ret = 1; int close_flag = 0; - if (0 == fd) { + if (-1 == fd) { if (filename) { if ((fd = open(filename, O_RDONLY)) < 0) { - logg("~%s: Access denied. ERROR\n", filename); + logg("*%s: Failed to open file. ERROR\n", filename); return 0; } close_flag = 1; } else { - fd = 0; + fd = -1; } } @@ -272,8 +273,12 @@ int onas_dsresult(CURL *curl, int scantype, uint64_t maxstream, const char *file if (len <= 0) { *printok = 0; - if (errors) + if (errors && len < 0) { + /* Ignore error if len == 0 to reduce verbosity from file open() + "errors" where the file has been deleted before we have a chance + to scan it. */ (*errors)++; + } infected = len; goto done; } @@ -355,7 +360,8 @@ int onas_dsresult(CURL *curl, int scantype, uint64_t maxstream, const char *file *ret_code = CL_VIRUS; } - } else if (len > 49 && !memcmp(eol - 50, " lstat() failed: No such file or directory. ERROR", 49)) { + } else if ((len > 32 && !memcmp(eol - 33, "No such file or directory. ERROR", 32)) || + (len > 34 && !memcmp(eol - 35, "Can't open file or directory ERROR", 34))) { if (errors) { (*errors)++; } @@ -368,33 +374,22 @@ int onas_dsresult(CURL *curl, int scantype, uint64_t maxstream, const char *file if (ret_code) { *ret_code = CL_ESTAT; } - } else if (len > 41 && !memcmp(eol - 42, " lstat() failed: Permission denied. ERROR", 41)) { + } else if ((len > 21 && !memcmp(eol - 22, " Access denied. ERROR", 21)) || + (len > 23 && !memcmp(eol - 24, "Can't access file ERROR", 23)) || + (len > 41 && !memcmp(eol - 42, " lstat() failed: Permission denied. ERROR", 41))) { if (errors) { (*errors)++; } *printok = 0; if (filename) { - (scantype >= STREAM) ? logg("*%s%s\n", filename, colon) : logg("*%s\n", bol); - } - - if (ret_code) { - *ret_code = CL_ESTAT; - } - } else if (len > 21 && !memcmp(eol - 22, " Access denied. ERROR", 21)) { - if (errors) { - (*errors)++; - } - *printok = 0; - - if (filename) { - (scantype >= STREAM) ? logg("*%s%s\n", filename, colon) : logg("*%s\n", bol); + (scantype >= STREAM) ? logg("~%s%s\n", filename, colon) : logg("~%s\n", bol); } if (ret_code) { *ret_code = CL_EACCES; } - } else if (!memcmp(eol - 7, " ERROR", 6)) { + } else if (len > 6 && !memcmp(eol - 7, " ERROR", 6)) { if (errors) { (*errors)++; } @@ -405,7 +400,7 @@ int onas_dsresult(CURL *curl, int scantype, uint64_t maxstream, const char *file } if (ret_code) { - *ret_code = CL_ESTATE; + *ret_code = CL_ERROR; } } } diff --git a/clamonacc/misc/utils.c b/clamonacc/misc/utils.c index fc5f28d67..4ff0d3665 100644 --- a/clamonacc/misc/utils.c +++ b/clamonacc/misc/utils.c @@ -139,7 +139,7 @@ int onas_fan_checkowner(int pid, const struct optstruct *opts) logg("*ClamMisc: permission denied to stat /proc/%d to exclude UIDs... perhaps SELinux denial?\n", pid); } else if (errno == ENOENT) { /* TODO: should this be configurable? */ - logg("ClamMisc: $/proc/%d vanished before UIDs could be excluded; scanning anyway\n", pid); + logg("*ClamMisc: $/proc/%d vanished before UIDs could be excluded; scanning anyway\n", pid); } return CHK_CLEAN; diff --git a/clamonacc/scan/onas_queue.c b/clamonacc/scan/onas_queue.c index f550791f5..df2865d35 100644 --- a/clamonacc/scan/onas_queue.c +++ b/clamonacc/scan/onas_queue.c @@ -282,8 +282,9 @@ cl_error_t onas_scan_queue_start(struct onas_context **ctx) return CL_SUCCESS; } -static void onas_scan_queue_exit(__attribute__((unused)) void *arg) +static void onas_scan_queue_exit(void *arg) { + UNUSEDPARAM(arg); logg("*ClamScanQueue: onas_scan_queue_exit()\n"); diff --git a/clamonacc/scan/thread.c b/clamonacc/scan/thread.c index df5710e6a..d7b7b4a69 100644 --- a/clamonacc/scan/thread.c +++ b/clamonacc/scan/thread.c @@ -72,17 +72,19 @@ static int onas_scan(struct onas_scan_event *event_data, const char *fname, STAT switch (*ret_code) { case CL_EACCES: case CL_ESTAT: - - logg("*ClamMisc: internal issue (daemon could not access directory/file %s)\n", fname); + logg("*ClamMisc: Scan issue; Daemon could not find or access: %s)\n", fname); break; /* TODO: handle other errors */ case CL_EPARSE: + logg("~ClamMisc: Internal issue; Failed to parse reply from daemon: %s)\n", fname); + break; case CL_EREAD: case CL_EWRITE: case CL_EMEM: case CL_ENULLARG: + case CL_ERROR: default: - logg("~ClamMisc: internal issue (client failed to scan)\n"); + logg("~ClamMisc: Unexpected issue; Daemon failed to scan: %s\n", fname); } if (retry_on_error) { logg("*ClamMisc: reattempting scan ... \n"); @@ -111,7 +113,7 @@ static cl_error_t onas_scan_safe(struct onas_scan_event *event_data, const char { int ret = 0; - int fd = 0; + int fd = -1; #if defined(HAVE_SYS_FANOTIFY_H) uint8_t b_fanotify; diff --git a/libclamav/others.c b/libclamav/others.c index 82df9ede3..852beebc6 100644 --- a/libclamav/others.c +++ b/libclamav/others.c @@ -196,7 +196,7 @@ static void *load_module(const char *name, const char *featurename) #ifdef _WIN32 rhandle = LoadLibraryA(modulename); #else // !_WIN32 - rhandle = dlopen(modulename, RTLD_NOW); + rhandle = dlopen(modulename, RTLD_NOW); #endif // !_WIN32 if (rhandle) { break; @@ -415,6 +415,8 @@ const char *cl_strerror(int clerror) return "Scanner still active"; case CL_ESTATE: return "Bad state (engine not initialized, or already initialized)"; + case CL_ERROR: + return "Unspecified error"; case CL_VERIFIED: return "The scanned object was verified and deemed trusted"; default: @@ -438,7 +440,7 @@ cl_error_t cl_init(unsigned int initoptions) rarload(); } #else - rarload(); + rarload(); #endif gettimeofday(&tv, (struct timezone *)0); @@ -1261,9 +1263,9 @@ int cli_unlink(const char *pathname) } return 0; #else - char err[128]; - cli_warnmsg("cli_unlink: unlink failure - %s\n", cli_strerror(errno, err, sizeof(err))); - return 1; + char err[128]; + cli_warnmsg("cli_unlink: unlink failure - %s\n", cli_strerror(errno, err, sizeof(err))); + return 1; #endif } return 0; @@ -1449,75 +1451,75 @@ int cli_rmdirs(const char *name) return rc; } #else - int cli_rmdirs(const char *dirname) - { - DIR *dd; - struct dirent *dent; - STATBUF maind, statbuf; - char *path; - char err[128]; +int cli_rmdirs(const char *dirname) +{ + DIR *dd; + struct dirent *dent; + STATBUF maind, statbuf; + char *path; + char err[128]; - chmod(dirname, 0700); - if ((dd = opendir(dirname)) != NULL) { - while (CLAMSTAT(dirname, &maind) != -1) { - if (!rmdir(dirname)) break; - if (errno != ENOTEMPTY && errno != EEXIST && errno != EBADF) { - cli_errmsg("cli_rmdirs: Can't remove temporary directory %s: %s\n", dirname, cli_strerror(errno, err, sizeof(err))); - closedir(dd); - return -1; - } + chmod(dirname, 0700); + if ((dd = opendir(dirname)) != NULL) { + while (CLAMSTAT(dirname, &maind) != -1) { + if (!rmdir(dirname)) break; + if (errno != ENOTEMPTY && errno != EEXIST && errno != EBADF) { + cli_errmsg("cli_rmdirs: Can't remove temporary directory %s: %s\n", dirname, cli_strerror(errno, err, sizeof(err))); + closedir(dd); + return -1; + } - while ((dent = readdir(dd))) { - if (dent->d_ino) { - if (strcmp(dent->d_name, ".") && strcmp(dent->d_name, "..")) { - path = cli_malloc(strlen(dirname) + strlen(dent->d_name) + 2); - if (!path) { - cli_errmsg("cli_rmdirs: Unable to allocate memory for path %llu\n", (long long unsigned)(strlen(dirname) + strlen(dent->d_name) + 2)); - closedir(dd); - return -1; - } + while ((dent = readdir(dd))) { + if (dent->d_ino) { + if (strcmp(dent->d_name, ".") && strcmp(dent->d_name, "..")) { + path = cli_malloc(strlen(dirname) + strlen(dent->d_name) + 2); + if (!path) { + cli_errmsg("cli_rmdirs: Unable to allocate memory for path %llu\n", (long long unsigned)(strlen(dirname) + strlen(dent->d_name) + 2)); + closedir(dd); + return -1; + } - sprintf(path, "%s" PATHSEP "%s", dirname, dent->d_name); - - /* stat the file */ - if (LSTAT(path, &statbuf) != -1) { - if (S_ISDIR(statbuf.st_mode) && !S_ISLNK(statbuf.st_mode)) { - if (rmdir(path) == -1) { /* can't be deleted */ - if (errno == EACCES) { - cli_errmsg("cli_rmdirs: Can't remove some temporary directories due to access problem.\n"); - closedir(dd); - free(path); - return -1; - } - if (cli_rmdirs(path)) { - cli_warnmsg("cli_rmdirs: Can't remove nested directory %s\n", path); - free(path); - closedir(dd); - return -1; - } + sprintf(path, "%s" PATHSEP "%s", dirname, dent->d_name); + + /* stat the file */ + if (LSTAT(path, &statbuf) != -1) { + if (S_ISDIR(statbuf.st_mode) && !S_ISLNK(statbuf.st_mode)) { + if (rmdir(path) == -1) { /* can't be deleted */ + if (errno == EACCES) { + cli_errmsg("cli_rmdirs: Can't remove some temporary directories due to access problem.\n"); + closedir(dd); + free(path); + return -1; } - } else { - if (cli_unlink(path)) { + if (cli_rmdirs(path)) { + cli_warnmsg("cli_rmdirs: Can't remove nested directory %s\n", path); free(path); closedir(dd); return -1; } } + } else { + if (cli_unlink(path)) { + free(path); + closedir(dd); + return -1; + } } - free(path); } + free(path); } } - rewinddir(dd); } - - } else { - return -1; + rewinddir(dd); } - closedir(dd); - return 0; + } else { + return -1; } + + closedir(dd); + return 0; +} #endif /* Implement a generic bitset, trog@clamav.net */