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.
pull/142/head^2
Micah Snyder 4 years ago committed by Micah Snyder (micasnyd)
parent 15f5b1669e
commit c522f45267
  1. 2
      clamd/scanner.c
  2. 18
      clamdscan/client.c
  3. 8
      clamdscan/proto.c
  4. 40
      clamonacc/client/client.c
  5. 12
      clamonacc/client/communication.c
  6. 53
      clamonacc/client/protocol.c
  7. 2
      clamonacc/misc/utils.c
  8. 3
      clamonacc/scan/onas_queue.c
  9. 10
      clamonacc/scan/thread.c
  10. 116
      libclamav/others.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 {

@ -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) {

@ -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

@ -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;

@ -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) {

@ -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;
}
}
}

@ -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;

@ -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");

@ -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;

@ -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 */

Loading…
Cancel
Save