Project

General

Profile

Actions

Bug #14898

closed

port_associate PORT_SOURCE_FILE doesn't update user obj properly

Added by Nahum Shalman 2 months ago. Updated about 2 months ago.

Status:
Closed
Priority:
Normal
Category:
kernel
Start date:
Due date:
% Done:

100%

Estimated time:
Difficulty:
Medium
Tags:
Gerrit CR:
External Bug:

Description

Uncovered in https://github.com/golang/go/issues/54254

Some interaction that is only seen when the golang garbage collector is active is causing port_get to return the wrong portev_user pointer.
In my testing it's usually an "old" one, but once I saw the "correct" value somehow stored at the wrong address.

A replication binary can be cross-compiled by any recent golang toolchain:

git clone https://github.com/nshalman/sys
cd sys/unix
git checkout 1bbdf4655b7477087d48f28f5cf216d4a46861de
GOOS=illumos GOARCH=amd64 go test -c
scp unix.test some-illumos-host:

user@some-illumos-host $ ./unix.test -test.run TestEventPortMemoryStress

As noted in https://github.com/golang/go/issues/54254#issuecomment-1207460296, when traced using

fbt:portfs:port_associate_fop:entry
{
    printf(" in: %p->%p", args[2], args[4]);
}
fbt::port_copy_event:entry
/args[1]->portkev_source == 7/
{
    printf("out: %x->%p\n", args[1]->portkev_object, args[1]->portkev_user);
}

fbt::port_pfp_setup:entry
{
    printf(" in: %x->%p", args[4], args[6]);
}

I see output from dtrace and from the test that look like this (I think the lack of `port_pfp_setup:entry` at the end is probably significant.):

 14  70111         port_associate_fop:entry  in: c000130000->c000016090
 14  70103             port_pfp_setup:entry  in: c000130000->c000016090
 14  69995            port_copy_event:entry out: c000130000->c000016090

 14  70111         port_associate_fop:entry  in: c000130050->c0000a0780
 14  70103             port_pfp_setup:entry  in: c000130050->c0000a0780
 14  69995            port_copy_event:entry out: c000130050->c0000a0780

 14  70111         port_associate_fop:entry  in: c00051e000->c000016060
 14  69995            port_copy_event:entry out: c00051e000->c000516b70

Cookie received from port_get at 0xc000516b70: cookie 5796
          A cookie in the jar at 0xc000016060: cookie 5814
 Last cookie port_associate'd at 0xc000016060: cookie 5814
       Address at port_associate 0xc000016060
--- FAIL: TestEventPortMemoryStress (0.11s)
panic: mismanaged memory [recovered]
    panic: mismanaged memory

For comparison, to see how it behaves when the golang garbage collector is not running, you can run

GOGC=off ./unix.test -test.run TestEventPortMemoryStress

Actions #1

Updated by Robert Mustacchi 2 months ago

  • Subject changed from port_get can return the wrong portev_user pointer to port_associate PORT_SOURCE_FILE doesn't update user obj properly
  • Category set to kernel
  • Assignee set to Robert Mustacchi

While inspecting the above with Nahum, I found something that seemed suspicious. While unclear if it is the same bug that golang has tripped over, I have found that unlike a PORT_SOURCE_FD, the PORT_SOURCE_FILE association path does not properly update the user pointer when the object already exists. To make sure this was the case I wrote a very similar program to the golang one that was there but without having to go through the go runtime. This makes it very explicit that my theory is correct. Look at the following program:

#include <port.h>
#include <err.h>
#include <stdio.h>
#include <unistd.h>
#include <fcntl.h>
#include <sys/types.h>
#include <sys/stat.h>
#include <stdlib.h>
#include <strings.h>

uintptr_t port_user = 1;

int
main(void)
{
        int port, fd;
        char *path;
        struct stat st;
        struct file_obj fo;
        uint32_t data;
        port_event_t pe;

        port = port_create();
        if (port < 0) {
                err(EXIT_FAILURE, "failed to create event port");
        }

        if (asprintf(&path, "/tmp/portfs-test.%d", getpid()) < 0) {
                err(EXIT_FAILURE, "failed to create temp file");
        }

        fd = open(path, O_RDWR | O_CREAT, 0644);
        if (fd < 0) {
                err(EXIT_FAILURE, "failed to create %s", path);
        }

        if (fstat(fd, &st) < 0) {
                err(EXIT_FAILURE, "failed to stat %s", path);
        }

        bzero(&fo, sizeof (fo));
        fo.fo_atime = st.st_atim;
        fo.fo_mtime = st.st_mtim;
        fo.fo_ctime = st.st_ctim;
        fo.fo_name = path;

        if (port_associate(port, PORT_SOURCE_FILE, (uintptr_t)&fo,
            FILE_MODIFIED, (void *)port_user) < 0) {
                err(EXIT_FAILURE, "failed to associate to %s", path);
        }

        port_user++;
        if (port_associate(port, PORT_SOURCE_FILE, (uintptr_t)&fo,
            FILE_MODIFIED, (void *)port_user) < 0) {
                err(EXIT_FAILURE, "failed to associate to %s", path);
        }

        data = arc4random();
        if (write(fd, &data, sizeof (data)) < 0) {
                err(EXIT_FAILURE, "failed to write data to fd");
        }

        if (port_get(port, &pe, NULL) < 0) {
                err(EXIT_FAILURE, "failed to get port data");
        }

        printf("portev_events: 0x%x, portev_source: 0x%x\n", pe.portev_events,
            pe.portev_source);
        if (pe.portev_object == (uintptr_t)&fo) {
                printf("portev_obj matches\n");
        } else {
                printf("portev_obj: 0x%lx, orig obj: 0x%lx\n", pe.portev_object,
                    (uintptr_t)&fo);
        }

        if ((uintptr_t)pe.portev_user == port_user) {
                printf("portev_user matches\n");
        } else {
                printf("portev_user: 0x%lx, orig obj: 0x%lx\n",
                    (uintptr_t)pe.portev_user, port_user);
        }

        (void) close(port);
        (void) unlink(path);
        return (0);
}

When we run this we would expect that the association to be updated and that we would get the newer user value. This is what port_associate(3C) says:

                                                                     If the specified object is
       already associated with the specified port, the port_associate()
       function serves to update the events and user arguments of the
       association.

In other words, if something hasn't fired yet, we'd expect to see the newest value. In this case, we'd expect the value of 2 in the portev_user value. Let's run this program:

rm@turin:~$ ./test 
portev_events: 0x2, portev_source: 0x7
portev_obj matches
portev_user: 0x1, orig obj: 0x2

OK, that's bad. And just to sanity check here's what happens if we only do a single association (and remove the increment):

rm@turin:~$ ./test 
portev_events: 0x2, portev_source: 0x7
portev_obj matches
portev_user matches

So what's happening here. In particular the kernel has an internal representation of this data called the port_kevent_t that normally is used to store the user point as well as the original object pointer. In port_associate_fop we go through and check to see if there's already an association on the vnode with our particular object pointer. If there is not, we'll go and create it. However, if there is we will go through and update the events that are associated, but not the actual user pointer. If we look at the PORT_SOURCE_FD path in the case that there already is an association, we make sure to update the portkev_user.

The test program makes it pretty clear that this is a problem. While this part of the fix is straightforward, there are a few things that I need to spend time reading to answer and to better understand:

  • What is expected if we associate an event, it triggers, and we associate again before we call port_get()?
  • What is expected if we are racing here with multiple threads? What guarantees locking or what should the order be?
Actions #2

Updated by Robert Mustacchi 2 months ago

So with a big more reading here are my initial answers to these questions:

  • When we reassociate an event, we basically end up synchronizing with the actual event port it's potentially a part of and if it hasn't been delivered, we remove it. This answers the question of what we expect to happen in those different conditions.
  • More generally the question that I had was what ensures or protects the portfop_t and its related port_kevent_t in pfop_pev. This is only destroyed when the underlying portfop_t has been freed or as part of the general event delivery mechanism. However, we know in this case that in the context of port_associate_fop that the pointer is valid because we use it to try and remove things from the list, so it's reasonable for us to update this.
Actions #3

Updated by Electric Monk 2 months ago

  • Gerrit CR set to 2299
Actions #4

Updated by Nahum Shalman about 2 months ago

The single change in the linked CR so far does fix the issue in the stress test I wrote for x/sys/unix, but I'm still able to trigger a test failure using the fsnotify tests, so there is likely still at least one other edge case lurking.

Actions #5

Updated by Robert Mustacchi about 2 months ago

In updates on the CR, it was mentioned that the additional fsnotify issues were not related to illumos and documented at: https://github.com/golang/go/issues/54363.

In addition to the testing that Nahum did, I wrote a small regression test suite that tests a couple of different interleavings of actions on an event port that is recycled each time. This now runs automatically as part of the os-tests test suite. Here's the output and interleavings (which covers this particular case and a few others) and then it running as part of the broader os-tests:

rm@romulus ~ $ /opt/os-tests/tests/portfs/file_assoc.32 
TEST PASSED: port_get -> no event
TEST PASSED: associate, port_get -> no event
TEST PASSED: associate, trigger, port_get -> first user
TEST PASSED: associate, associate, trigger, port_get -> second user
TEST PASSED: associate, trigger, associate, port_get -> second user
TEST PASSED: associate, disassociate, port_get -> no event
TEST PASSED: associate, trigger, disassociate, port_get -> no event
TEST PASSED: associate, trigger, disassociate, associate, port_get -> second user
TEST PASSED: associate, trigger, disassociate, fstat, associate, port_get -> no event
rm@romulus ~ $ /opt/os-tests/tests/portfs/file_assoc.64 
TEST PASSED: port_get -> no event
TEST PASSED: associate, port_get -> no event
TEST PASSED: associate, trigger, port_get -> first user
TEST PASSED: associate, associate, trigger, port_get -> second user
TEST PASSED: associate, trigger, associate, port_get -> second user
TEST PASSED: associate, disassociate, port_get -> no event
TEST PASSED: associate, trigger, disassociate, port_get -> no event
TEST PASSED: associate, trigger, disassociate, associate, port_get -> second user
TEST PASSED: associate, trigger, disassociate, fstat, associate, port_get -> no event
rm@romulus ~ $ pfexec /opt/os-tests/bin/ostest 
Test: /opt/os-tests/tests/clock_gettime.32 (run as root)          [00:00] [PASS]
Test: /opt/os-tests/tests/clock_gettime.64 (run as root)          [00:00] [PASS]
Test: /opt/os-tests/tests/definit/definit (run as root)           [00:00] [PASS]
Test: /opt/os-tests/tests/eventfd.32 (run as root)                [00:00] [PASS]
Test: /opt/os-tests/tests/eventfd.64 (run as root)                [00:00] [PASS]
Test: /opt/os-tests/tests/imc_test (run as root)                  [00:00] [PASS]
Test: /opt/os-tests/tests/odirectory.32 (run as root)             [00:00] [PASS]
Test: /opt/os-tests/tests/odirectory.64 (run as root)             [00:00] [PASS]
Test: /opt/os-tests/tests/writev.32 (run as root)                 [00:00] [PASS]
Test: /opt/os-tests/tests/writev.64 (run as root)                 [00:00] [PASS]
Test: /opt/os-tests/tests/zen_umc_test (run as root)              [00:00] [PASS]
Test: /opt/os-tests/tests/cores/core_prereqs (run as root)        [00:00] [PASS]
Test: /opt/os-tests/tests/cores/coretests (run as root)           [00:04] [PASS]
Test: /opt/os-tests/tests/ddi_ufm/ufm-test-setup (run as root)    [00:00] [PASS]
Test: /opt/os-tests/tests/ddi_ufm/ufm-test (run as root)          [00:00] [PASS]
Test: /opt/os-tests/tests/ddi_ufm/ufm-test-cleanup (run as root)  [00:00] [PASS]
Test: /opt/os-tests/tests/file-locking/runtests.32 (run as root)  [00:21] [PASS]
Test: /opt/os-tests/tests/file-locking/runtests.64 (run as root)  [00:21] [PASS]
Test: /opt/os-tests/tests/i386/ldt (run as root)                  [00:06] [PASS]
Test: /opt/os-tests/tests/i386/badseg (run as root)               [00:06] [PASS]
Test: /opt/os-tests/tests/ksensor/ksensor_init (run as root)      [00:00] [PASS]
Test: /opt/os-tests/tests/ksensor/ksensor_basic.32 (run as root)  [00:00] [PASS]
Test: /opt/os-tests/tests/ksensor/ksensor_basic.64 (run as root)  [00:00] [PASS]
Test: /opt/os-tests/tests/ksensor/ksensor_err.32 (run as root)    [00:00] [PASS]
Test: /opt/os-tests/tests/ksensor/ksensor_err.64 (run as root)    [00:00] [PASS]
Test: /opt/os-tests/tests/ksensor/ksensor_fini (run as root)      [00:00] [PASS]
Test: /opt/os-tests/tests/libtopo/digraph-test (run as root)      [00:00] [PASS]
Test: /opt/os-tests/tests/pf_key/acquire-compare (run as root)    [00:43] [PASS]
Test: /opt/os-tests/tests/pf_key/kmc-update (run as root)         [00:00] [PASS]
Test: /opt/os-tests/tests/portfs/file_assoc.32 (run as root)      [00:00] [PASS]
Test: /opt/os-tests/tests/portfs/file_assoc.64 (run as root)      [00:00] [PASS]
Test: /opt/os-tests/tests/sdevfs/sdevfs_eisdir (run as root)      [00:00] [PASS]
Test: /opt/os-tests/tests/secflags/secflags_aslr (run as root)    [00:02] [PASS]
Test: /opt/os-tests/tests/secflags/secflags_core (run as root)    [00:01] [PASS]
Test: /opt/os-tests/tests/secflags/secflags_dts (run as root)     [00:11] [PASS]
Test: /opt/os-tests/tests/secflags/secflags_elfdump (run as root) [00:01] [PASS]
Test: /opt/os-tests/tests/secflags/secflags_forbidnullmap (run as root) [00:00] [PASS]
Test: /opt/os-tests/tests/secflags/secflags_limits (run as root)  [00:00] [PASS]
Test: /opt/os-tests/tests/secflags/secflags_noexecstack (run as root) [00:00] [PASS]
Test: /opt/os-tests/tests/secflags/secflags_proc (run as root)    [00:01] [PASS]
Test: /opt/os-tests/tests/secflags/secflags_psecflags (run as root) [00:11] [PASS]
Test: /opt/os-tests/tests/secflags/secflags_syscall (run as root) [00:00] [PASS]
Test: /opt/os-tests/tests/secflags/secflags_truss (run as root)   [00:00] [PASS]
Test: /opt/os-tests/tests/secflags/secflags_zonecfg (run as root) [00:00] [PASS]
Test: /opt/os-tests/tests/sigqueue/sigqueue_queue_size (run as root) [00:00] [PASS]
Test: /opt/os-tests/tests/sockfs/conn (run as root)               [00:05] [PASS]
Test: /opt/os-tests/tests/sockfs/dgram (run as root)              [00:05] [PASS]
Test: /opt/os-tests/tests/sockfs/drop_priv (run as root)          [00:07] [PASS]
Test: /opt/os-tests/tests/sockfs/nosignal (run as root)           [00:02] [PASS]
Test: /opt/os-tests/tests/sockfs/rights.32 (run as root)          [00:00] [PASS]
Test: /opt/os-tests/tests/sockfs/rights.64 (run as root)          [00:00] [PASS]
Test: /opt/os-tests/tests/sockfs/sockpair (run as root)           [00:10] [PASS]
Test: /opt/os-tests/tests/sockfs/recvmsg.32 (run as root)         [00:00] [PASS]
Test: /opt/os-tests/tests/sockfs/recvmsg.64 (run as root)         [00:00] [PASS]
Test: /opt/os-tests/tests/stackalign/stackalign.32 (run as root)  [00:00] [PASS]
Test: /opt/os-tests/tests/stackalign/stackalign.64 (run as root)  [00:00] [PASS]
Test: /opt/os-tests/tests/stress/dladm-kstat (run as root)        [00:20] [PASS]
Test: /opt/os-tests/tests/syscall/fchmodat.32 (run as root)       [00:00] [PASS]
Test: /opt/os-tests/tests/syscall/fchmodat.64 (run as root)       [00:00] [PASS]
Test: /opt/os-tests/tests/syscall/open.32 (run as root)           [00:00] [PASS]
Test: /opt/os-tests/tests/syscall/open.64 (run as root)           [00:00] [PASS]
Test: /opt/os-tests/tests/timer/timer_limit (run as root)         [00:00] [PASS]
Test: /opt/os-tests/tests/uccid/atrparse (run as root)            [00:00] [PASS]

Results Summary
PASS      63

Running Time:   00:03:04
Percent passed: 100.0%
Actions #6

Updated by Electric Monk about 2 months ago

  • Status changed from New to Closed
  • % Done changed from 0 to 100

git commit abb88ab1b9516b1ca12094db7f2cfb5d91e0a135

commit  abb88ab1b9516b1ca12094db7f2cfb5d91e0a135
Author: Robert Mustacchi <rm@fingolfin.org>
Date:   2022-08-22T14:29:48.000Z

    14898 port_associate PORT_SOURCE_FILE doesn't update user obj properly
    Reviewed by: Nahum Shalman <nahamu+illumos@gmail.com>
    Reviewed by: Andy Fiddaman <illumos@fiddaman.net>
    Approved by: Richard Lowe <richlowe@richlowe.net>

Actions

Also available in: Atom PDF