BUG: fix various race conditions when starting background processes

[WOnder93]

Changes from #49:

• use POSIX fifo files instead of regular file + tail -f
• clean up the flag files after use
• fix all similar race conditions in other tests as well

NOTE: I didn't test the binder test changes as I don't have an environment right now where it is supported.

(BTW, I had a good laugh at the goto brexit; lines in tests/binder/test_binder.c :)

[WOnder93]

(Force-pushed with reset commit timestamps.)

[stephensmalley]

Testing binder just requires enabling the options specified in the defconfig fragment included in selinux-testsuite. Before your change, they all pass. After your change, the tests on line 64 and line 74 of binder/test fail.

[stephensmalley]

cd tests/binder ./test -v 1..6 Manager PID: 13106 Process context: unconfined_u:unconfined_r:test_binder_mgr_t:s0-s0:c0.c1023 Service Provider PID: 13109 Process context: unconfined_u:unconfined_r:test_binder_provider_t:s0-s0:c0.c1023 Service Provider sending transaction to Manager - ADD_TEST_SERVICE Service Provider read_consumed: 8 Service Provider command: BR_NOOP Service Provider command: BR_FAILED_REPLY not ok 1

Failed test at ./test line 64.

Service Provider PID: 13110 Process context: unconfined_u:unconfined_r:test_binder_provider_no_call_t:s0-s0:c0.c1023 Service Provider sending transaction to Manager - ADD_TEST_SERVICE Service Provider read_consumed: 8 Service Provider command: BR_NOOP Service Provider command: BR_FAILED_REPLY ok 2 Service Provider PID: 13111 Process context: unconfined_u:unconfined_r:test_binder_provider_no_im_t:s0-s0:c0.c1023 Service Provider sending transaction to Manager - ADD_TEST_SERVICE Service Provider read_consumed: 8 Service Provider command: BR_NOOP Service Provider command: BR_FAILED_REPLY not ok 3

Failed test at ./test line 74.

Service Provider PID: 13112 Process context: unconfined_u:unconfined_r:test_binder_provider_no_transfer_t:s0-s0:c0.c1023 Service Provider sending transaction to Manager - ADD_TEST_SERVICE Service Provider read_consumed: 8 Service Provider command: BR_NOOP Service Provider command: BR_FAILED_REPLY ok 4 Manager PID: 13114 Process context: unconfined_u:unconfined_r:test_binder_provider_t:s0-s0:c0.c1023 Failed to become context manager: Permission denied ok 5 Manager PID: 13116 Process context: unconfined_u:unconfined_r:test_binder_mgr_no_fd_t:s0-s0:c0.c1023 Service Provider PID: 13119 Process context: unconfined_u:unconfined_r:test_binder_provider_t:s0-s0:c0.c1023 Service Provider sending transaction to Manager - ADD_TEST_SERVICE Service Provider read_consumed: 8 Service Provider command: BR_NOOP Service Provider command: BR_FAILED_REPLY ok 6

Looks like you failed 2 tests of 6.

[stephensmalley]

Successful output of test -v on master branch: ./test -v 1..6 Manager PID: 22148 Process context: unconfined_u:unconfined_r:test_binder_mgr_t:s0-s0:c0.c1023 Service Provider PID: 22149 Process context: unconfined_u:unconfined_r:test_binder_provider_t:s0-s0:c0.c1023 Service Provider sending transaction to Manager - ADD_TEST_SERVICE Service Provider read_consumed: 48 Service Provider command: BR_NOOP Service Provider command: BR_INCREFS Manager read_consumed: 72 Service Provider command: BR_ACQUIRE Manager command: BR_NOOP Service Provider command: BR_TRANSACTION_COMPLETE Manager command: BR_TRANSACTION Manager BR_TRANSACTION data: handle: 0 cookie: 0 code: 100 flag: TF_ACCEPT_FDS sender pid: 22149 sender euid: 0 data_size: 24 offsets_size: 8 hdr: BINDER_TYPE_HANDLE handle: 1 flags: priority: 0x7f accept FDS: YES cookie: 0 Manager has BINDER_TYPE_HANDLE obj->handle: 1 Manager acquired handle: 1 for Service Provider Manager sending BC_REPLY to obtain its FD Manager handle: 0 and its FD: 3 Manager read_consumed: 8 Manager command: BR_NOOP Manager command: BR_TRANSACTION_COMPLETE ok 1 Service Provider PID: 22150 Process context: unconfined_u:unconfined_r:test_binder_provider_no_call_t:s0-s0:c0.c1023 Service Provider sending transaction to Manager - ADD_TEST_SERVICE Service Provider read_consumed: 8 Service Provider command: BR_NOOP Service Provider command: BR_FAILED_REPLY ok 2 Service Provider PID: 22151 Process context: unconfined_u:unconfined_r:test_binder_provider_no_im_t:s0-s0:c0.c1023 Service Provider sending transaction to Manager - ADD_TEST_SERVICE Service Provider read_consumed: 48 Service Provider command: BR_NOOP Service Provider command: BR_INCREFS Manager read_consumed: 72 Service Provider command: BR_ACQUIRE Manager command: BR_NOOP Service Provider command: BR_TRANSACTION_COMPLETE Manager command: BR_TRANSACTION Manager BR_TRANSACTION data: handle: 0 cookie: 0 code: 100 flag: TF_ACCEPT_FDS sender pid: 22151 sender euid: 0 data_size: 24 offsets_size: 8 hdr: BINDER_TYPE_HANDLE handle: 2 flags: priority: 0x7f accept FDS: YES cookie: 0 Manager has BINDER_TYPE_HANDLE obj->handle: 2 Manager acquired handle: 2 for Service Provider Manager sending BC_REPLY to obtain its FD Manager handle: 0 and its FD: 3 Manager read_consumed: 8 Service Provider read_consumed: 72 Manager command: BR_NOOP Service Provider command: BR_NOOP Manager command: BR_TRANSACTION_COMPLETE Service Provider command: BR_REPLY Service Provider BR_REPLY data: handle: 0 cookie: 0 code: 100 flag: TF_ACCEPT_FDS sender pid: 0 sender euid: 0 data_size: 24 offsets_size: 8 hdr: BINDER_TYPE_FD fd: 5 flags: priority: 0x7f accept FDS: YES cookie: 0 Service Provider retrieved Managers fd: 5 st_dev: 6 Service Provider read_consumed: 8 Service Provider command: BR_NOOP Service Provider command: BR_FAILED_REPLY Service Provider using Managers FD Failed response from Service Provider using Managers FD Manager read_consumed: 4 Manager command: BR_NOOP ok 3 Service Provider PID: 22152 Process context: unconfined_u:unconfined_r:test_binder_provider_no_transfer_t:s0-s0:c0.c1023 Service Provider sending transaction to Manager - ADD_TEST_SERVICE Service Provider read_consumed: 8 Service Provider command: BR_NOOP Service Provider command: BR_FAILED_REPLY ok 4 Manager PID: 22153 Process context: unconfined_u:unconfined_r:test_binder_provider_t:s0-s0:c0.c1023 Failed to become context manager: Permission denied ok 5 Manager PID: 22154 Process context: unconfined_u:unconfined_r:test_binder_mgr_no_fd_t:s0-s0:c0.c1023 Service Provider PID: 22155 Process context: unconfined_u:unconfined_r:test_binder_provider_t:s0-s0:c0.c1023 Service Provider sending transaction to Manager - ADD_TEST_SERVICE Service Provider read_consumed: 48 Service Provider command: BR_NOOP Service Provider command: BR_INCREFS Service Provider command: BR_ACQUIRE Service Provider command: BR_TRANSACTION_COMPLETE Manager read_consumed: 72 Manager command: BR_NOOP Manager command: BR_TRANSACTION Manager BR_TRANSACTION data: handle: 0 cookie: 0 code: 100 flag: TF_ACCEPT_FDS sender pid: 22155 sender euid: 0 data_size: 24 offsets_size: 8 hdr: BINDER_TYPE_HANDLE handle: 1 flags: priority: 0x7f accept FDS: YES cookie: 0 Manager has BINDER_TYPE_HANDLE obj->handle: 1 Manager acquired handle: 1 for Service Provider Manager sending BC_REPLY to obtain its FD Manager handle: 0 and its FD: 3 Manager read_consumed: 8 Manager command: BR_NOOP Manager command: BR_TRANSACTION_COMPLETE Service Provider read_consumed: 8 Service Provider command: BR_NOOP Service Provider command: BR_FAILED_REPLY ok 6

[WOnder93]

OK, I have built a scratch Fedora kernel with the binder configs enabled and I am able to reproduce the failures. I am now investigating them...

[WOnder93]

Hm, I don't understand what's going on... I ran the binder test from both master and PR under strace and the order of operations looks as expected, just for some reason in the PR case the manager's second ioctl(3, BINDER_WRITE_READ, ...) never wakes up and the provider's ioctl(3, BINDER_WRITE_READ, ...) just returns immediately with BR_FAILED_REPLY... Here is an excerpt from the strace outputs:

MASTER:
...
[pid 11586] ioctl(3, BINDER_SET_CONTEXT_MGR, 0) = 0
[pid 11586] ioctl(3, BINDER_WRITE_READ, 0x7ffd49815d90) = 0
[pid 11586] ioctl(3, BINDER_WRITE_READ <unfinished ...>
...
[pid 11587] ioctl(3, BINDER_WRITE_READ <unfinished ...>
[pid 11586] <... ioctl resumed> , 0x7ffd49815d90) = 0
[pid 11586] ioctl(3, BINDER_WRITE_READ, 0x7ffd49815be0) = 0
...

PR:
...
[pid 11552] openat(AT_FDCWD, "./flag", O_RDONLY <unfinished ...>
...
[pid 11550] ioctl(3, BINDER_SET_CONTEXT_MGR, 0) = 0
[pid 11550] ioctl(3, BINDER_WRITE_READ, 0x7ffd298935a0) = 0
[pid 11550] openat(AT_FDCWD, "./flag", O_WRONLY|O_CREAT|O_TRUNC, 0666 <unfinished ...>
[pid 11552] <... openat resumed> )      = 3
...
[pid 11552] read(3,  <unfinished ...>
[pid 11550] <... openat resumed> )      = 5
...
[pid 11550] write(5, "listening\n", 10 <unfinished ...>
[pid 11552] <... read resumed> "listening\n", 131072) = 10
...
[pid 11552] read(3,  <unfinished ...>
[pid 11550] <... write resumed> )       = 10
[pid 11550] close(5 <unfinished ...>
[pid 11552] <... read resumed> "", 131072) = 0
...
[pid 11550] <... close resumed> )       = 0
[pid 11550] ioctl(3, BINDER_WRITE_READstrace: Process 11553 attached
 <unfinished ...>
...
[pid 11553] ioctl(3, BINDER_WRITE_READ, 0x7fff8b370f10) = 0
[pid 11553] write(1, "Service Provider read_consumed: "..., 34) = 34
[pid 11553] write(1, "Service Provider command: BR_NOO"..., 34) = 34
[pid 11553] write(1, "Service Provider command: BR_FAI"..., 42) = 42
...

[stephensmalley]

I see two suspicious things in test_binder: 1) valgrind reports various uses ofuninitialised values, 2) there is at least one case where we are calling ioctl BINDER_WRITE_READ with both the write_buffer and the read_buffer pointing to the same buffer.

[stephensmalley]

Another possibility is that the problem lies in the testing of impersonate, which is a rather convoluted/contrived example (and it was never clear to me that they intended to support it at all or if it was just a side effect of their implementation).

[stephensmalley]

diff --git a/tests/binder/test_binder.c b/tests/binder/test_binder.c
index 11fa358..6e5fce2 100644
--- a/tests/binder/test_binder.c
+++ b/tests/binder/test_binder.c
@@ -326,6 +326,8 @@ static void extract_fd_and_respond(struct binder_transaction_data *txn_in,
    } __attribute__((packed)) writebuf;
    unsigned int readbuf[32];

+   memset(readbuf, 0, sizeof readbuf);
+
    binder_size_t *offs = (binder_size_t *)
                  (uintptr_t)txn_in->data.ptr.offsets;

@@ -568,10 +570,10 @@ int main(int argc, char **argv)
            goto brexit;
        }

-       readbuf[0] = BC_ENTER_LOOPER;
-       bwr.write_size = sizeof(readbuf[0]);
+       writebuf.cmd = BC_ENTER_LOOPER;
+       bwr.write_size = sizeof(writebuf.cmd);
        bwr.write_consumed = 0;
-       bwr.write_buffer = (uintptr_t)readbuf;
+       bwr.write_buffer = (uintptr_t)&writebuf;

        bwr.read_size = 0;
        bwr.read_consumed = 0;
@@ -587,6 +589,7 @@ int main(int argc, char **argv)
        }

        while (true) {
+           memset(readbuf, 0, sizeof readbuf);
            bwr.read_size = sizeof(readbuf);
            bwr.read_consumed = 0;
            bwr.read_buffer = (uintptr_t)readbuf;
@@ -643,6 +646,7 @@ int main(int argc, char **argv)

        /* Each test will expect a different number of replies */
        while (provider_replies) {
+           memset(readbuf, 0, sizeof readbuf);
            bwr.read_size = sizeof(readbuf);
            bwr.read_consumed = 0;
            bwr.read_buffer = (uintptr_t)readbuf;
'''

[stephensmalley]

NB The patch above eliminates the valgrind warnings and avoids aliasing the write_buffer/read_buffer, but the tests still fail as before with this pr.

[WOnder93]

I think I managed to fix the binder test now. The problem appears to have been in handling of the offsets array as suggested by Todd Kjos on the mailing list. I also added the fixes from @stephensmalley (I hope you don't mind me stealing your patch :)

[stephensmalley]

Looks good to me but seems to not be based on current master and has conflicts/duplicate commits with it.

[WOnder93]

Ah, yes, I rebased over local master branch, which was out of sync... Should be fixed now.

[pcmoore]

Thanks guys, I went to cherry pick @WOnder93's binder fix to see you had already reviewed and merged the lot :) FWIW, we're back to clean runs on my Rawhide test system again - thanks for the help!