search

swiftlang / swift-corelibs-libdispatch

The libdispatch Project, (a.k.a. Grand Central Dispatch), for concurrency on multicore hardware
swift.org
Apache License 2.0
2.47k stars 460 forks source link

Re-adding dispatch source for socket file descriptors results in reuse and incorrect update of dispatch_muxnote_t on Ubuntu, Android, and Windows #833

Open hmelder opened 3 months ago

hmelder commented 3 months ago

Creating a dispatch source for a socket file descriptor, removing it, and re-adding it shortly after results in a reuse of the underlying dispatch_muxnote_t which was created with the first dispatch source. This happens on Ubuntu 23.10 and Android API 24,34.

However, during registration of the new unote in _dispatch_unote_register_muxed https://github.com/apple/swift-corelibs-libdispatch/blob/542b7f32311680b11b6fc8fcb2576955460ba7da/src/event/event_epoll.c#L270-L272 _dispatch_epoll_update returns ENOENT and the existing muxnote is in turn not correctly updated.

Sometimes, this is because of https://github.com/apple/swift-corelibs-libdispatch/blob/542b7f32311680b11b6fc8fcb2576955460ba7da/src/event/event_epoll.c#L602-L611 EPOLLHUP.

I also noticed removal of muxnotes which still had an active reader or writer.

Here is a workaround that worked for us:

diff --git a/src/event/event_epoll.c b/src/event/event_epoll.c
index f31d13e..8654104 100644
--- a/src/event/event_epoll.c
+++ b/src/event/event_epoll.c
@@ -268,7 +268,10 @@ _dispatch_unote_register_muxed(dispatch_unote_t du)
        if (events & ~_dispatch_muxnote_armed_events(dmn)) {
            events |= _dispatch_muxnote_armed_events(dmn);
            if (_dispatch_epoll_update(dmn, events, EPOLL_CTL_MOD) < 0) {
-               dmn = NULL;
+               // The file descriptor was closed, reregister in epoll
+               if (_dispatch_epoll_update(dmn, events, EPOLL_CTL_ADD) < 0) {
+                   dmn = NULL;
+               }
            } else {
                dmn->dmn_events |= events;
                dmn->dmn_disarmed_events &= ~events;
@@ -319,6 +322,8 @@ _dispatch_unote_unregister_muxed(dispatch_unote_t du)
    dispatch_unote_linkage_t dul = _dispatch_unote_get_linkage(du);
    dispatch_muxnote_t dmn = dul->du_muxnote;
    uint32_t events = dmn->dmn_events;
+   int has_readers = 1;
+   int has_writers = 1;

    LIST_REMOVE(dul, du_link);
    _LIST_TRASH_ENTRY(dul, du_link);
@@ -326,6 +331,7 @@ _dispatch_unote_unregister_muxed(dispatch_unote_t du)

    if (LIST_EMPTY(&dmn->dmn_readers_head)) {
        events &= (uint32_t)~EPOLLIN;
+       has_readers = 0;
        if (dmn->dmn_disarmed_events & EPOLLIN) {
            dmn->dmn_disarmed_events &= (uint16_t)~EPOLLIN;
            dmn->dmn_events &= (uint32_t)~EPOLLIN;
@@ -333,13 +339,14 @@ _dispatch_unote_unregister_muxed(dispatch_unote_t du)
    }
    if (LIST_EMPTY(&dmn->dmn_writers_head)) {
        events &= (uint32_t)~EPOLLOUT;
+       has_writers = 0;
        if (dmn->dmn_disarmed_events & EPOLLOUT) {
            dmn->dmn_disarmed_events &= (uint16_t)~EPOLLOUT;
            dmn->dmn_events &= (uint32_t)~EPOLLOUT;
        }
    }
-
-   if (events & (EPOLLIN | EPOLLOUT)) {
+   
+   if (events & (EPOLLIN | EPOLLOUT) || has_readers || has_writers) {
        if (events != _dispatch_muxnote_armed_events(dmn)) {
            dmn->dmn_events = events;
            events = _dispatch_muxnote_armed_events(dmn);
Here is an example on Android API 34 with head at 542b7f3. ```logcat 2024-07-02 14:33:26.479 30762-30762 com.exampl...objectivec com.example.helloobjectivec E [thread:531362555096] Resume Task! 2024-07-02 14:33:26.479 30762-30883 com.exampl...objectivec com.example.helloobjectivec E [thread:531362589848] Timer Callback for Session : multi=0x7c47b37360 timeout_ms=0 2024-07-02 14:33:26.480 30762-30883 com.exampl...objectivec com.example.helloobjectivec E [thread:531362589848] File NSURLSession.m: 382. In [NSURLSession -_resumeTask:] Added task= easy=0x7c07b48780 to multi=0x7c47b37360 with return value 0 2024-07-02 14:33:26.480 30762-30883 com.exampl...objectivec com.example.helloobjectivec E [thread:531362589848] File NSURLSession.m: 280. In [NSURLSession -initWithConfiguration:delegate:delegateQueue:] Timer fired for session with oldTimer=0 timer=0 2024-07-02 14:33:26.482 30762-30883 com.exampl...objectivec com.example.helloobjectivec E [thread:531362589848] Socket Callback for Session : socket=117 easy:0x7c07b48780 what=IN 2024-07-02 14:33:26.482 30762-30883 com.exampl...objectivec com.example.helloobjectivec E [thread:531362589848] File NSURLSession.m: 459. In [NSURLSession -_addSocket:easyHandle:what:] Add Socket: 117 easy: 0x7c07b48780 2024-07-02 14:33:26.483 30762-30883 com.exampl...objectivec com.example.helloobjectivec E [thread:531362589848] File NSURLSession.m: 498. In [NSURLSession -_setSocket:sources:what:] Creating a reading dispatch source: socket=117 sources=0x7be7baba30 what=1 2024-07-02 14:33:26.483 30762-30883 com.exampl...objectivec com.example.helloobjectivec E [thread:531362589848] Timer Callback for Session : multi=0x7c47b37360 timeout_ms=1 2024-07-02 14:33:26.483 30762-30870 GNUstep com.example.helloobjectivec I created new muxnote dmb=0x79fd9343b0 dmn=0x7bc7dd1710 for du=0x7a6bd1a830 events=0x40004001 2024-07-02 14:33:26.483 30762-30870 GNUstep com.example.helloobjectivec I adding reader to muxnote dmn=0x7bc7dd1710 for du=0x7a6bd1a830 2024-07-02 14:33:26.484 30762-30883 com.exampl...objectivec com.example.helloobjectivec E [thread:531362589848] File NSURLSession.m: 280. In [NSURLSession -initWithConfiguration:delegate:delegateQueue:] Timer fired for session with oldTimer=0 timer=1 2024-07-02 14:33:26.484 30762-30883 com.exampl...objectivec com.example.helloobjectivec E [thread:531362589848] Timer Callback for Session : multi=0x7c47b37360 timeout_ms=2 2024-07-02 14:33:26.489 30762-30883 com.exampl...objectivec com.example.helloobjectivec E [thread:531362589848] File NSURLSession.m: 280. In [NSURLSession -initWithConfiguration:delegate:delegateQueue:] Timer fired for session with oldTimer=1 timer=2 2024-07-02 14:33:26.489 30762-30883 com.exampl...objectivec com.example.helloobjectivec E [thread:531362589848] Timer Callback for Session : multi=0x7c47b37360 timeout_ms=4 2024-07-02 14:33:26.493 30762-30870 GNUstep com.example.helloobjectivec I dispatch_event_loop_drain: EVFILT_READ with dmn=0x7bc7dd1710 events=0x1 Dispatch event merge fd dmn=0x7bc7dd1710 events=0x1 dwm 2024-07-02 14:33:26.493 30762-30870 GNUstep com.example.helloobjectivec I _disarmed_events=0x1 dmn_events=0x40004001 dmn_disarmed_events=0x1 armed=0x40004000 dispatch epoll update from merge fd dmn=0x7 2024-07-02 14:33:26.493 30762-30870 GNUstep com.example.helloobjectivec I bc7dd1710 events=0x40004000 2024-07-02 14:33:26.494 30762-30883 com.exampl...objectivec com.example.helloobjectivec E [thread:531362589848] Socket Callback for Session : socket=117 easy:0x7c07b48780 what=REMOVE 2024-07-02 14:33:26.494 30762-30870 GNUstep com.example.helloobjectivec I dispatch_event_loop_drain: EVFILT_READ with dmn=0x7bc7dd1710 events=0x10 Dispatch event merge fd dmn=0x7bc7dd1710 events=0x10 d 2024-07-02 14:33:26.494 30762-30870 GNUstep com.example.helloobjectivec I wm_disarmed_events=0x1 removing muxnote dmn=0x7bc7dd1710 from epoll for hangup 2024-07-02 14:33:26.494 30762-30883 com.exampl...objectivec com.example.helloobjectivec E [thread:531362589848] File NSURLSession.m: 434. In [NSURLSession -_removeSocket:] Remove socket with SourceInfo: 0x7be7baba30 2024-07-02 14:33:26.495 30762-30883 com.exampl...objectivec com.example.helloobjectivec E [thread:531362589848] Socket Callback for Session : socket=117 easy:0x7c07b48780 what=OUT 2024-07-02 14:33:26.496 30762-30883 com.exampl...objectivec com.example.helloobjectivec E [thread:531362589848] File NSURLSession.m: 459. In [NSURLSession -_addSocket:easyHandle:what:] Add Socket: 117 easy: 0x7c07b48780 2024-07-02 14:33:26.496 30762-30883 com.exampl...objectivec com.example.helloobjectivec E [thread:531362589848] File NSURLSession.m: 540. In [NSURLSession -_setSocket:sources:what:] Creating a writing dispatch source: socket=117 sources=0x7be7ba9f30 what=2 2024-07-02 14:33:26.496 30762-30870 GNUstep com.example.helloobjectivec I found existing muxnote dmb=0x79fd9343b0 dmn=0x7bc7dd1710 for du=0x7a6bd1a830 events=0x40004004 dmn_events=0x40004001 dmn_disarm 2024-07-02 14:33:26.496 30762-30870 GNUstep com.example.helloobjectivec I ed_events=0x1 armed=0x40004000 dmn_events=0x40004001 dmn_disarmed_events=0x1 armed=0x40004000 updating existing muxnote dmb=0x7 2024-07-02 14:33:26.496 30762-30870 GNUstep com.example.helloobjectivec I 9fd9343b0 dmn=0x7bc7dd1710 for du=0x7a6bd1a830 events=0x40004004 failed to update epoll dmn: No such file or directory 2024-07-02 14:33:26.496 30762-30883 com.exampl...objectivec com.example.helloobjectivec E [thread:531362589848] Timer Callback for Session : multi=0x7c47b37360 timeout_ms=2 2024-07-02 14:33:26.497 30762-30870 GNUstep com.example.helloobjectivec I unregistering muxnote dmn=0x7bc7dd1710 for du=0x7a6bd1a840 events=0x40004001 no more readers for muxnote dmn=0x7bc7dd1710 for d 2024-07-02 14:33:26.497 30762-30870 GNUstep com.example.helloobjectivec I u=0x7a6bd1a840 events=0x40004000 disarmed EPOLLIN for muxnote dmn=0x7bc7dd1710 for du=0x7a6bd1a840 events=0x40004000 no more wr 2024-07-02 14:33:26.497 30762-30870 GNUstep com.example.helloobjectivec I iters for muxnote dmn=0x7bc7dd1710 for du=0x7a6bd1a840 events=0x40004000 has_readers=0 has_writers=0 removing muxnote dmn=0x7bc 2024-07-02 14:33:26.497 30762-30870 GNUstep com.example.helloobjectivec I 7dd1710 for du=0x7a6bd1a840 removed epoll dmn=0x7bc7dd1710 for du=0x7a6bd1a840 2024-07-02 14:33:26.499 30762-30883 com.exampl...objectivec com.example.helloobjectivec E [thread:531362589848] File NSURLSession.m: 280. In [NSURLSession -initWithConfiguration:delegate:delegateQueue:] Timer fired for session with oldTimer=4 timer=2 2024-07-02 14:33:26.499 30762-30883 com.exampl...objectivec com.example.helloobjectivec E [thread:531362589848] Timer Callback for Session : multi=0x7c47b37360 timeout_ms=29990 ``` The patch with logging ```patch diff --git a/src/event/event_epoll.c b/src/event/event_epoll.c index f31d13e..b65c1ec 100644 --- a/src/event/event_epoll.c +++ b/src/event/event_epoll.c @@ -265,19 +265,29 @@ _dispatch_unote_register_muxed(dispatch_unote_t du) dmb = _dispatch_unote_muxnote_bucket(du); dmn = _dispatch_unote_muxnote_find(dmb, du); if (dmn) { + printf("found existing muxnote dmb=%p dmn=%p for du=%p events=0x%x\n", dmb, dmn, &du, events); if (events & ~_dispatch_muxnote_armed_events(dmn)) { events |= _dispatch_muxnote_armed_events(dmn); + printf("updating existing muxnote dmb=%p dmn=%p for du=%p events=0x%x\n", dmb, dmn, &du, events); if (_dispatch_epoll_update(dmn, events, EPOLL_CTL_MOD) < 0) { - dmn = NULL; + // The file descriptor was closed, reregister in epoll + if (_dispatch_epoll_update(dmn, events, EPOLL_CTL_ADD) < 0) { + //printf("Failed to add epoll after not found dmn=%p for du=%p\n", dmn, &du); + dmn = NULL; + } + printf("Readded epoll dmn=%p for du=%p\n", dmn, &du); } else { dmn->dmn_events |= events; dmn->dmn_disarmed_events &= ~events; + printf("Set dmn_events=0x%x dmn_disarmed_events=0x%x\n", dmn->dmn_events, dmn->dmn_disarmed_events); } } } else { dmn = _dispatch_muxnote_create(du, events); + printf("created new muxnote dmb=%p dmn=%p for du=%p events=0x%x\n", dmb, dmn, &du, events); if (dmn) { if (_dispatch_epoll_update(dmn, events, EPOLL_CTL_ADD) < 0) { + printf("failed to add epoll dmn=%p for du=%p\n", dmn, &du); _dispatch_muxnote_dispose(dmn); dmn = NULL; } else { @@ -289,8 +299,10 @@ _dispatch_unote_register_muxed(dispatch_unote_t du) if (dmn) { dispatch_unote_linkage_t dul = _dispatch_unote_get_linkage(du); if (events & EPOLLOUT) { + printf("adding writer to muxnote dmn=%p for du=%p\n", dmn, &du); LIST_INSERT_HEAD(&dmn->dmn_writers_head, dul, du_link); } else { + printf("adding reader to muxnote dmn=%p for du=%p\n", dmn, &du); LIST_INSERT_HEAD(&dmn->dmn_readers_head, dul, du_link); } dul->du_muxnote = dmn; @@ -306,6 +318,8 @@ _dispatch_unote_resume_muxed(dispatch_unote_t du) dispatch_assert(_dispatch_unote_registered(du)); uint32_t events = _dispatch_unote_required_events(du); + printf("resuming muxnote dmn=%p for du=%p events=0x%x\n", dmn, &du, events); + if (events & dmn->dmn_disarmed_events) { dmn->dmn_disarmed_events &= ~events; events = _dispatch_muxnote_armed_events(dmn); @@ -319,6 +333,10 @@ _dispatch_unote_unregister_muxed(dispatch_unote_t du) dispatch_unote_linkage_t dul = _dispatch_unote_get_linkage(du); dispatch_muxnote_t dmn = dul->du_muxnote; uint32_t events = dmn->dmn_events; + int has_readers = 1; + int has_writers = 1; + + printf("unregistering muxnote dmn=%p for du=%p events=0x%x\n", dmn, &du, events); LIST_REMOVE(dul, du_link); _LIST_TRASH_ENTRY(dul, du_link); @@ -326,27 +344,36 @@ _dispatch_unote_unregister_muxed(dispatch_unote_t du) if (LIST_EMPTY(&dmn->dmn_readers_head)) { events &= (uint32_t)~EPOLLIN; + has_readers = 0; + printf("no more readers for muxnote dmn=%p for du=%p events=0x%x\n", dmn, &du, events); if (dmn->dmn_disarmed_events & EPOLLIN) { dmn->dmn_disarmed_events &= (uint16_t)~EPOLLIN; dmn->dmn_events &= (uint32_t)~EPOLLIN; + printf("disarmed EPOLLIN for muxnote dmn=%p for du=%p events=0x%x\n", dmn, &du, events); } } if (LIST_EMPTY(&dmn->dmn_writers_head)) { events &= (uint32_t)~EPOLLOUT; + has_writers = 0; + printf("no more writers for muxnote dmn=%p for du=%p events=0x%x\n", dmn, &du, events); if (dmn->dmn_disarmed_events & EPOLLOUT) { dmn->dmn_disarmed_events &= (uint16_t)~EPOLLOUT; dmn->dmn_events &= (uint32_t)~EPOLLOUT; + printf("disarmed EPOLLOUT for muxnote dmn=%p for du=%p events=0x%x\n", dmn, &du, events); } } - - if (events & (EPOLLIN | EPOLLOUT)) { + + if (events & (EPOLLIN | EPOLLOUT) || has_readers || has_writers) { if (events != _dispatch_muxnote_armed_events(dmn)) { + printf("updating muxnote dmn=%p for du=%p events=0x%x\n", dmn, &du, events); dmn->dmn_events = events; events = _dispatch_muxnote_armed_events(dmn); _dispatch_epoll_update(dmn, events, EPOLL_CTL_MOD); } } else { + printf("removing muxnote dmn=%p for du=%p\n", dmn, &du); epoll_ctl(_dispatch_epfd, EPOLL_CTL_DEL, dmn->dmn_fd, NULL); + printf("removed epoll dmn=%p for du=%p\n", dmn, &du); LIST_REMOVE(dmn, dmn_list); _dispatch_muxnote_dispose(dmn); } @@ -422,6 +449,7 @@ _dispatch_timeout_program(uint32_t tidx, uint64_t target, return; } } else { + printf("removing timer epoll registration %d\n", tidx); op = EPOLL_CTL_DEL; } dispatch_assume_zero(epoll_ctl(_dispatch_epfd, op, timer->det_fd, &ev)); @@ -572,6 +600,8 @@ _dispatch_event_merge_fd(dispatch_muxnote_t dmn, uint32_t events) dmn->dmn_disarmed_events |= (events & (EPOLLIN | EPOLLOUT)); + printf("Dispatch event merge fd dmn=%p events=0x%x dwm_disarmed_events=0x%x\n", dmn, events, dmn->dmn_disarmed_events); + if (events & EPOLLIN) { data = _dispatch_get_buffer_size(dmn, false); LIST_FOREACH_SAFE(dul, &dmn->dmn_readers_head, du_link, dul_next) { @@ -608,11 +638,13 @@ _dispatch_event_merge_fd(dispatch_muxnote_t dmn, uint32_t events) dispatch_unote_t du = _dispatch_unote_linkage_get_unote(dul); _dispatch_event_merge_hangup(du); } + printf("removing muxnote dmn=%p from epoll for hangup\n", dmn); epoll_ctl(_dispatch_epfd, EPOLL_CTL_DEL, dmn->dmn_fd, NULL); return; } events = _dispatch_muxnote_armed_events(dmn); + printf("dispatch epoll update from merge fd dmn=%p events=0x%x\n", dmn, events); if (events) _dispatch_epoll_update(dmn, events, EPOLL_CTL_MOD); } @@ -674,6 +706,7 @@ retry: break; case EVFILT_READ: + printf("dispatch_event_loop_drain: EVFILT_READ with dmn=%p events=0x%x\n", dmn, ev[i].events); _dispatch_event_merge_fd(dmn, ev[i].events); break; } ```
lxbndr commented 3 months ago

I am guessing that Windows implementation follows epoll logic, at least in some parts. It also suffers from similar dispatch_muxnote_t issue. It is easily reproduced from Foundation by making POST URL request with body larger than 64k (which outstands CURL buffer and makes it to request adding and removing read/write dispatch sources exactly as needed to step on this issue). Our Android team reported that 64k POST is also a working breaker for them.

hmelder commented 3 months ago

It also suffers from similar dispatch_muxnote_t issue

Interesting. We have not encountered the issues on Windows, but I'll investigate that too.

Our Android team reported that 64k POST is also a working breaker for them.

Do you have a hotfix for this that's different from mine?

lxbndr commented 3 months ago

We workarounded it in Foundation by duplicating sockets with dup. This sort of works, because a "new" socket makes a separate muxntote, no collision. Here is the commit. I am wondering if it works for you as well. But, anyway, that is a pure hack, unfortunately. Not to mention that it is not applicable to Windows. It have to be fixed in Dispatch. Your patch seems to be looking in the right direction.

hmelder commented 3 months ago

This sort of works, because a "new" socket makes a separate muxntote, no collision.

Huh forgot that this is actually guaranteed by the API on Linux :)

The new file descriptor number is guaranteed to be the lowest-numbered
file descriptor that was unused in the calling process.
andriydruk commented 3 months ago

Hi, we created this fix with dub in Foundation to fix the 64K problem but I'm not very happy with it. Mostly, because it leads to over usage of file descriptors in runtime.

Android limits FD count to 1024, which may sound reasonable for most applications. But in our application users can add a lot of accounts that will use separate connections and we see that some power users reach this limit from time to time :(

That's why we would be glad to see a fix for this issue in libdispatch 👍