CLAM-2159: fix clamonacc --log=FILE bug #751

m-sola · 2022-11-10T02:17:41Z

Moves logg setup to start of clamonacc.c main()
Changes all calls to logg which may occure before init to mprintf

Addresses #168

micahsnyder · 2022-11-16T21:41:32Z

It looks like the core of this fix is to initialize logging to occur before startup_checks(ctx) where it runs:

ctx->fan_fd = fanotify_init(...

One minor related thing that is probably not a functional issue:

In onas_clamonacc_exit() it sets g_ctx->fan_fd = 0; instead of g_ctx->fan_fd = -1;.

    if (g_ctx) {
        if (g_ctx->fan_fd) {
            close(g_ctx->fan_fd);
        }
-        g_ctx->fan_fd = 0;
+        g_ctx->fan_fd = -1;
    }

And in onas_init_context() it should probably also initialize fan_fd, like

struct onas_context *onas_init_context(void)
{
    struct onas_context *ctx = (struct onas_context *)cli_malloc(sizeof(struct onas_context));
    if (NULL == ctx) {
        return NULL;
    }

    memset(ctx, 0, sizeof(struct onas_context));

+  ctx->fan_fd = -1;
+
    return ctx;
}

I don't think these are functional issues but I'm mentioning them because I suspect the race condition has something to do with a race condition between the logging fd and ctx->fan_fd (?)

Anyways,... Next up I'll try testing a bit.

micahsnyder · 2022-11-17T01:59:20Z

I have bad news, I was able to reproduce the issue on both the main branch as well as with this PR.

Here is the randomly named file created in my current (install) directory:

clamav-micah-4/build/install on  PR-751 [⇕] took 2m3s
❯ ls
''$'\360''Qi'   bin/   etc/   include/   lib/   sbin/   share/

clamav-micah-4/build/install on  PR-751 [⇕]
❯ sudo cat ./\Xf0Qi
ERROR: ClamClient: Connection to clamd failed, Couldn't connect to server.

To reproduce the issue, I did the following:

started clamd
set up rsync to sync a large directory tree with a new directory. While that was running I ...

started clamonacc and stopped clamonacc repeatedly using:

sudo ./sbin/clamonacc --log=$HOME/clamonacc.log -F --ping 60 --wait --fdpass

It took quite a number of start/stops but eventually it resulted in the randomlly named file in my current directory.

micahsnyder

Forgot to set review status to 'request changes'.
Not sure what change is required -- Outside of the two small things with the ctx->fan_fd, I haven't found any leads on the source of the bug.

A race condition existed where clamonacc would call logg and attempt to write to a logfile either before the logg interface had been initialized or after it had been cleaned up. This happens due to logg calls at cleanup during asynchronous thread shutdowns, and during startup when watching directories with ongoing event triggers. This resulted in new files with garbage-filled names being created and written to under the initial process' runtime path. Changes: Move logg setup to start of clamonacc.c main() Change all raceable calls to logg to mprintf instead

micahsnyder · 2022-11-21T22:04:59Z

@m-sola I was able to trigger it again:

clamav-micah-3/build/install-10 on  PR-751
❯ ls -la
total 36
-rw-r-----  1 root     root      189 Nov 21 13:47 ''$'\360''Q'$'\364\367\215''U'
drwxr-xr-x  8 micasnyd micasnyd 4096 Nov 21 13:47  ./
drwxr-xr-x 29 micasnyd micasnyd 4096 Nov 21 12:32  ../
drwxr-xr-x  2 micasnyd micasnyd 4096 Nov 21 12:32  bin/
drwxr-xr-x  2 micasnyd micasnyd 4096 Nov 21 13:00  etc/
drwxr-xr-x  2 micasnyd micasnyd 4096 Nov 21 12:32  include/
drwxr-xr-x  3 micasnyd micasnyd 4096 Nov 21 12:32  lib/
drwxr-xr-x  2 micasnyd micasnyd 4096 Nov 21 12:32  sbin/
drwxr-xr-x  4 micasnyd micasnyd 4096 Nov 21 12:54  share/

The file content in this case was

❯ sudo cat ./\Xf0Q\Xf4\Xf7\X8dU
/home/micasnyd/tmp/build-debug/unit_tests/input/clamav_hdb_scanfiles/clam_IScab_int.exe: Clamav.Test.File-6 FOUND
ERROR: ClamClient: Connection to clamd failed, Couldn't connect to server.

I suspect it may have happened with I did multiple Ctrl-C's in a row, because clamonacc didn't stop the first time. It also segfault if I do that.

Edit: if that turns out to be true that the outstanding issue only occurs in this edge case where i have to force-kill with extra ctrl-c's, then I won't worry about it and we should just merge this as-is. I'll let you know what I find.

I will try testing some more where I don't do that with lots of start-stops.

micahsnyder · 2022-11-21T22:38:42Z

Yeah I was able to reproduce the same one by sending clamonacc a Ctrl-C when clamonacc was starting to get back a series of FOUND's from clamd from scan-requests of our test files.

What that looked like:

❯ sudo ./sbin/clamonacc --log=$HOME/clamonacc.log -F --fdpass
--------------------------------------
ClamInotif: watching '/home/micasnyd/' (and all sub-directories)
ClamInotif: extra scanning on inotify events enabled
/home/micasnyd/tmp/build/unit_tests/input/clamav_hdb_scanfiles/clam-aspack.exe: Clamav.Test.File-6 FOUND
/home/micasnyd/tmp/build/unit_tests/input/clamav_hdb_scanfiles/clam-fsg.exe: Clamav.Test.File-6 FOUND
^CClamInotif: stopped   # <--- first Ctrl-C when FOUND's start coming back
/home/micasnyd/tmp/build/unit_tests/input/clamav_hdb_scanfiles/clam-mew.exe: Clamav.Test.File-6 FOUND
/home/micasnyd/tmp/build/unit_tests/input/clamav_hdb_scanfiles/clam-fsg.exe: Clamav.Test.File-6 FOUND
/home/micasnyd/tmp/build/unit_tests/input/clamav_hdb_scanfiles/clam-nsis.exe: Clamav.Test.File-6 FOUND
/home/micasnyd/tmp/build/unit_tests/input/clamav_hdb_scanfiles/clam-aspack.exe: Clamav.Test.File-6 FOUND
/home/micasnyd/tmp/build/unit_tests/input/clamav_hdb_scanfiles/clam-mew.exe: Clamav.Test.File-6 FOUND
/home/micasnyd/tmp/build/unit_tests/input/clamav_hdb_scanfiles/clam-petite.exe: Clamav.Test.File-6 FOUND
/home/micasnyd/tmp/build/unit_tests/input/clamav_hdb_scanfiles/clam-fsg.exe: Clamav.Test.File-6 FOUND
/home/micasnyd/tmp/build/unit_tests/input/clamav_hdb_scanfiles/clam-upack.exe: Clamav.Test.File-6 FOUND
^CClamonacc: stopped   # <--- second Ctrl-C because clamonacc wasn't stopping. 
                       # This is the moment when the randomly named file gets written.
/home/micasnyd/tmp/build/unit_tests/input/clamav_hdb_scanfiles/clam_ISmsi_ext.exe: Clamav.Test.File-6 FOUND
ERROR: ClamClient: Connection to clamd failed, Couldn't connect to server.
^CClamonacc: stopped   # <--- third Ctrl-C because clamonacc still hadn't stopped.
fish: 'sudo ./sbin/clamonacc --log=$HO…' terminated by signal SIGSEGV (Address boundary error)

The resulting file:

clamav-micah-3/build/install-10 on  PR-751
❯ ls
''$'\360\241\377\347\241''U'   bin/   etc/   include/   lib/   sbin/   share/

clamav-micah-3/build/install-10 on  PR-751
❯ sudo cat ./\Xf0\Xa1\Xff\Xe7\Xa1U
[sudo] password for micasnyd:
/home/micasnyd/tmp/build/unit_tests/input/clamav_hdb_scanfiles/clam_ISmsi_ext.exe: Clamav.Test.File-6 FOUND
ERROR: ClamClient: Connection to clamd failed, Couldn't connect to server.

The issue of not being able to kill clamonacc gracefully when it is receiving messages from clamd is maybe something else we can follow up on later.
But this PR seems to resolve most of this log bug.
If you're fine with it, I'm happy to merge this.

micahsnyder · 2022-11-21T22:47:07Z

Note: I wasn't able to reproduce the random-named-log bug when doing clean start/stops. Only when doing the extra Ctrl-C's to kill it ... violently.

micahsnyder self-requested a review November 10, 2022 19:51

micahsnyder requested changes Nov 17, 2022

View reviewed changes

m-sola force-pushed the clam-2159 branch from 1e54988 to 761f332 Compare November 21, 2022 19:07

m-sola force-pushed the clam-2159 branch from 761f332 to efd573b Compare November 21, 2022 20:27

micahsnyder approved these changes Nov 21, 2022

View reviewed changes

micahsnyder merged commit da16b63 into Cisco-Talos:main Nov 21, 2022
8 of 27 checks passed

micahsnyder changed the title ~~CLAM-2159: logg init refactor~~ CLAM-2159: fix clamonacc --log=FILE bug Nov 23, 2022

CLAM-2159: fix clamonacc --log=FILE bug #751

CLAM-2159: fix clamonacc --log=FILE bug #751

m-sola commented Nov 10, 2022

micahsnyder commented Nov 16, 2022 •

edited

micahsnyder commented Nov 17, 2022

micahsnyder left a comment

micahsnyder commented Nov 21, 2022 •

edited

micahsnyder commented Nov 21, 2022

micahsnyder commented Nov 21, 2022

CLAM-2159: fix clamonacc --log=FILE bug #751

CLAM-2159: fix clamonacc --log=FILE bug #751

Conversation

m-sola commented Nov 10, 2022

micahsnyder commented Nov 16, 2022 • edited

micahsnyder commented Nov 17, 2022

micahsnyder left a comment

Choose a reason for hiding this comment

micahsnyder commented Nov 21, 2022 • edited

micahsnyder commented Nov 21, 2022

micahsnyder commented Nov 21, 2022

micahsnyder commented Nov 16, 2022 •

edited

micahsnyder commented Nov 21, 2022 •

edited