More than one CQE during cancellation?

[ioquatix]

Hello, I've done my best to figure this out but don't understand what's going on.

I have an operation that's getting cancelled. All my small test cases seem to work, but running a larger app fails. So, maybe it's not just cancellation.

Anyway, I have an io_uring_prep_poll_add which gets cancelled using io_uring_prep_cancel. For some reason, I get two CQEs, as well as the CQE for the cancellation itself.

Here is the sequence of events, from the logs:

# The `io_uring_prep_poll_add` operation, waiting for `stdin` to become readable.
IO_Event_Selector_URing_io_wait:io_uring_prep_poll_add(descriptor=0, flags=25, fiber=0x7f953bb24dc8)
IO_Event_Selector_URing_Completion_acquire(0x55ee6f0c1a80, limit=3)
IO_Event_Selector_URing_submit_sqe(0x7f9540674140): user_data=0x55ee6f0c1a80 opcode=6
io_uring_submit_pending(ring=0x55ee6f166480, pending=1)
io_uring_submit_flush(pending=1)

# Processing the CQEs:
select_process_completions...

# Let's cancel the operation:
io_wait_ensure:io_uring_prep_cancel(waiting=0x7f953cfd5230, completion=0x55ee6f0c1a80)
IO_Event_Selector_URing_submit_sqe(0x7f9540674180): user_data=(nil) opcode=14
IO_Event_Selector_URing_Waiting_cancel(0x7f953cfd5230, 0x55ee6f0c1a80)

# Start processing CQEs:
select_process_completions...

# The cancellation CQE:
select_process_completions: cqe res=0 user_data=(nil)

# The original operation is also cancelled:
select_process_completions: cqe res=-125 user_data=0x55ee6f0c1a80
select_process_completions: completion=0x55ee6f0c1a80 waiting=(nil)
IO_Event_Selector_URing_Completion_release(0x55ee6f0c1a80)
IO_Event_Selector_URing_Completion_cancel(0x55ee6f0c1a80)

# For some reason, we get another CQE (errno=22 is EINVAL):
select_process_completions: cqe res=-22 user_data=0x55ee6f0c1a80
select_process_completions: completion=0x55ee6f0c1a80 waiting=(nil)
IO_Event_Selector_URing_Completion_release(0x55ee6f0c1a80)
IO_Event_Selector_URing_Completion_cancel(0x55ee6f0c1a80)

# Program dies because this is invalid:
ruby: ./io/event/selector/list.h:41: IO_Event_List_prepend: Assertion `node->head == NULL' failed.
fish: Job 1, 'ruby -rasync -e 'Async{|task| b…' terminated by signal SIGABRT (Abort)

Do you have any idea why this is happening?

Is it possible that polling on the same file descriptor is causing EINVAL? The logs above are truncated to only include the relevant events - between submitting the cancellation and processing it, another request is made to io_uring_prep_poll_add the same file descriptor with the same flags.

[ioquatix]

Okay, I think this again is an application level issue. It looks like maybe the completion token was reused too early in the process causing some kind of invalid argument. I'm going to investigate it further tomorrow.

Oddly enough, this was the fix, but I'm not completely sure why yet: socketry/io-event@6925550#diff-3e7a68b220a9360ead1d2e7a5ec23e7d36de591eab138721efdc61b565fc5194L941-R987

[ioquatix]

Hmm, actually, I think the reason why it's working is because it's no longer using cancellations and just letting them expire naturally using the application layer logic (it has completion tokens which can be canceled and are reclaimed as CQEs are processed, so cancellation at the io_uring level just improves reuse, it's not critical). So, it still seems like there might be some kind of issue.

[isilence]

Yeah, it's hard to imagine it posting 2 cqes. I'd be really surprised. I had somewhere a bpftrace script checking that user_data is unique, might be useful as a sanity check.

[ioquatix]

Okay, I found the issue. I was invoking sqe = io_uring_get_sqe(&selector->ring); and sometimes didn't use it. This created, I can only assume, sqes with random whatever in them.