Keep getting the same buffer ID when RECV with IOSQE_BUFFER_SELECT

Keep getting the same buffer ID when RECV with IOSQE_BUFFER_SELECT

[Daniele Salvatore Albano]

Hi,

I have recently started to play with io_uring and liburing but I am
facing an odd issue, of course initially I thought it was my code but
after further investigation and testing some other code (
https://github.com/frevib/io_uring-echo-server/tree/io-uring-op-provide-buffers
) I faced the same behaviour.

When using the IOSQE_BUFFER_SELECT with RECV I always get the first
read right but all the subsequent return a buffer id different from
what was used by the kernel.

The problem starts to happen only after io_uring_prep_provide_buffers
is invoked to put back the buffer, the bid set is the one from cflags
>> 16.

The logic is as follow:
- io_uring_prep_provide_buffers + io_uring_submit + io_uring_wait_cqe
initialize all the buffers at the beginning
- within io_uring_for_each_cqe, when accepting a new connection a recv
sqe is submitted with the IOSQE_BUFFER_SELECT flag
- within io_uring_for_each_cqe, when recv a send sqe is submitted
using as buffer the one specified in cflags >> 16
- within io_uring_for_each_cqe, when send a provide buffers for the
bid used to send the data and a recv sqes are submitted.

If I drop io_uring_prep_provide_buffers both in my code and in the
code I referenced above it just works, but of course at some point
there are no more buffers available.

To further debug the issue I reduced the amount of provided buffers
and started to print out the entire bufferset and I noticed that after
the first correct RECV the kernel stores the data in the first buffer
of the group id but always returns the last buffer id.
It is like after calling io_uring_prep_provide_buffers the information
on the kernel side gets corrupted, I tried to follow the logic on the
kernel side but there is nothing apparent that would make me
understand why I am facing this behaviour.

The original author of that code told me on SO that he wrote & tested
it on the kernel 5.6 + the provide buffers branch, I am facing this
issue with 5.7.6, 5.8-rc1 and 5.8-rc3. The liburing library is built
out of the branch, I didn't do too much testing with different
versions but I tried to figure out where the issue was for the last
week and within this period I have pulled multiple times the repo.

Any hint or suggestion?


Thanks!
Daniele

Re: Keep getting the same buffer ID when RECV with IOSQE_BUFFER_SELECT

[Jens Axboe]

On 7/3/20 12:48 PM, Daniele Salvatore Albano wrote:
> Hi,
> 
> I have recently started to play with io_uring and liburing but I am
> facing an odd issue, of course initially I thought it was my code but
> after further investigation and testing some other code (
> https://github.com/frevib/io_uring-echo-server/tree/io-uring-op-provide-buffers
> ) I faced the same behaviour.
> 
> When using the IOSQE_BUFFER_SELECT with RECV I always get the first
> read right but all the subsequent return a buffer id different from
> what was used by the kernel.
> 
> The problem starts to happen only after io_uring_prep_provide_buffers
> is invoked to put back the buffer, the bid set is the one from cflags
>>> 16.
> 
> The logic is as follow:
> - io_uring_prep_provide_buffers + io_uring_submit + io_uring_wait_cqe
> initialize all the buffers at the beginning
> - within io_uring_for_each_cqe, when accepting a new connection a recv
> sqe is submitted with the IOSQE_BUFFER_SELECT flag
> - within io_uring_for_each_cqe, when recv a send sqe is submitted
> using as buffer the one specified in cflags >> 16
> - within io_uring_for_each_cqe, when send a provide buffers for the
> bid used to send the data and a recv sqes are submitted.
> 
> If I drop io_uring_prep_provide_buffers both in my code and in the
> code I referenced above it just works, but of course at some point
> there are no more buffers available.
> 
> To further debug the issue I reduced the amount of provided buffers
> and started to print out the entire bufferset and I noticed that after
> the first correct RECV the kernel stores the data in the first buffer
> of the group id but always returns the last buffer id.
> It is like after calling io_uring_prep_provide_buffers the information
> on the kernel side gets corrupted, I tried to follow the logic on the
> kernel side but there is nothing apparent that would make me
> understand why I am facing this behaviour.
> 
> The original author of that code told me on SO that he wrote & tested
> it on the kernel 5.6 + the provide buffers branch, I am facing this
> issue with 5.7.6, 5.8-rc1 and 5.8-rc3. The liburing library is built
> out of the branch, I didn't do too much testing with different
> versions but I tried to figure out where the issue was for the last
> week and within this period I have pulled multiple times the repo.
> 
> Any hint or suggestion?

Do you have a simple test case for this that can be run standalone?
I'll take a look, but I'd rather not spend time re-creating a test case
if you already have one.

-- 
Jens Axboe

Re: Keep getting the same buffer ID when RECV with IOSQE_BUFFER_SELECT

[Jens Axboe]

On 7/3/20 1:09 PM, Daniele Salvatore Albano wrote:
> On Fri, 3 Jul 2020, 20:57 Jens Axboe, <axboe@kernel.dk <mailto:axboe@kernel.dk>> wrote:
> 
>     On 7/3/20 12:48 PM, Daniele Salvatore Albano wrote:
>     > Hi,
>     >
>     > I have recently started to play with io_uring and liburing but I am
>     > facing an odd issue, of course initially I thought it was my code but
>     > after further investigation and testing some other code (
>     > https://github.com/frevib/io_uring-echo-server/tree/io-uring-op-provide-buffers
>     > ) I faced the same behaviour.
>     >
>     > When using the IOSQE_BUFFER_SELECT with RECV I always get the first
>     > read right but all the subsequent return a buffer id different from
>     > what was used by the kernel.
>     >
>     > The problem starts to happen only after io_uring_prep_provide_buffers
>     > is invoked to put back the buffer, the bid set is the one from cflags
>     >>> 16.
>     >
>     > The logic is as follow:
>     > - io_uring_prep_provide_buffers + io_uring_submit + io_uring_wait_cqe
>     > initialize all the buffers at the beginning
>     > - within io_uring_for_each_cqe, when accepting a new connection a recv
>     > sqe is submitted with the IOSQE_BUFFER_SELECT flag
>     > - within io_uring_for_each_cqe, when recv a send sqe is submitted
>     > using as buffer the one specified in cflags >> 16
>     > - within io_uring_for_each_cqe, when send a provide buffers for the
>     > bid used to send the data and a recv sqes are submitted.
>     >
>     > If I drop io_uring_prep_provide_buffers both in my code and in the
>     > code I referenced above it just works, but of course at some point
>     > there are no more buffers available.
>     >
>     > To further debug the issue I reduced the amount of provided buffers
>     > and started to print out the entire bufferset and I noticed that after
>     > the first correct RECV the kernel stores the data in the first buffer
>     > of the group id but always returns the last buffer id.
>     > It is like after calling io_uring_prep_provide_buffers the information
>     > on the kernel side gets corrupted, I tried to follow the logic on the
>     > kernel side but there is nothing apparent that would make me
>     > understand why I am facing this behaviour.
>     >
>     > The original author of that code told me on SO that he wrote & tested
>     > it on the kernel 5.6 + the provide buffers branch, I am facing this
>     > issue with 5.7.6, 5.8-rc1 and 5.8-rc3. The liburing library is built
>     > out of the branch, I didn't do too much testing with different
>     > versions but I tried to figure out where the issue was for the last
>     > week and within this period I have pulled multiple times the repo.
>     >
>     > Any hint or suggestion?
> 
>     Do you have a simple test case for this that can be run standalone?
>     I'll take a look, but I'd rather not spend time re-creating a test case
>     if you already have one.
> 
>     -- 
>     Jens Axboe
> 
> 
> I will shrink down the code to produce a simple test case but not sure
> how much code I will be able to lift because it's showing this
> behaviour on a second recv of a connection so I will need to keep all
> the boilerplate code to get there. 

That's fine, I'm just looking to avoid having to write it from scratch.
Plus a test case is easier to deal with than trying to write a test case
based on your description, less room for interpretative errors.

-- 
Jens Axboe

Re: Keep getting the same buffer ID when RECV with IOSQE_BUFFER_SELECT

[Daniele Salvatore Albano]

[-- Attachment #1: Type: text/plain, Size: 4762 bytes --]

On Fri, 3 Jul 2020 at 21:12, Jens Axboe <axboe@kernel.dk> wrote:
>
> On 7/3/20 1:09 PM, Daniele Salvatore Albano wrote:
> > On Fri, 3 Jul 2020, 20:57 Jens Axboe, <axboe@kernel.dk <mailto:axboe@kernel.dk>> wrote:
> >
> >     On 7/3/20 12:48 PM, Daniele Salvatore Albano wrote:
> >     > Hi,
> >     >
> >     > I have recently started to play with io_uring and liburing but I am
> >     > facing an odd issue, of course initially I thought it was my code but
> >     > after further investigation and testing some other code (
> >     > https://github.com/frevib/io_uring-echo-server/tree/io-uring-op-provide-buffers
> >     > ) I faced the same behaviour.
> >     >
> >     > When using the IOSQE_BUFFER_SELECT with RECV I always get the first
> >     > read right but all the subsequent return a buffer id different from
> >     > what was used by the kernel.
> >     >
> >     > The problem starts to happen only after io_uring_prep_provide_buffers
> >     > is invoked to put back the buffer, the bid set is the one from cflags
> >     >>> 16.
> >     >
> >     > The logic is as follow:
> >     > - io_uring_prep_provide_buffers + io_uring_submit + io_uring_wait_cqe
> >     > initialize all the buffers at the beginning
> >     > - within io_uring_for_each_cqe, when accepting a new connection a recv
> >     > sqe is submitted with the IOSQE_BUFFER_SELECT flag
> >     > - within io_uring_for_each_cqe, when recv a send sqe is submitted
> >     > using as buffer the one specified in cflags >> 16
> >     > - within io_uring_for_each_cqe, when send a provide buffers for the
> >     > bid used to send the data and a recv sqes are submitted.
> >     >
> >     > If I drop io_uring_prep_provide_buffers both in my code and in the
> >     > code I referenced above it just works, but of course at some point
> >     > there are no more buffers available.
> >     >
> >     > To further debug the issue I reduced the amount of provided buffers
> >     > and started to print out the entire bufferset and I noticed that after
> >     > the first correct RECV the kernel stores the data in the first buffer
> >     > of the group id but always returns the last buffer id.
> >     > It is like after calling io_uring_prep_provide_buffers the information
> >     > on the kernel side gets corrupted, I tried to follow the logic on the
> >     > kernel side but there is nothing apparent that would make me
> >     > understand why I am facing this behaviour.
> >     >
> >     > The original author of that code told me on SO that he wrote & tested
> >     > it on the kernel 5.6 + the provide buffers branch, I am facing this
> >     > issue with 5.7.6, 5.8-rc1 and 5.8-rc3. The liburing library is built
> >     > out of the branch, I didn't do too much testing with different
> >     > versions but I tried to figure out where the issue was for the last
> >     > week and within this period I have pulled multiple times the repo.
> >     >
> >     > Any hint or suggestion?
> >
> >     Do you have a simple test case for this that can be run standalone?
> >     I'll take a look, but I'd rather not spend time re-creating a test case
> >     if you already have one.
> >
> >     --
> >     Jens Axboe
> >
> >
> > I will shrink down the code to produce a simple test case but not sure
> > how much code I will be able to lift because it's showing this
> > behaviour on a second recv of a connection so I will need to keep all
> > the boilerplate code to get there.
>
> That's fine, I'm just looking to avoid having to write it from scratch.
> Plus a test case is easier to deal with than trying to write a test case
> based on your description, less room for interpretative errors.
>
> --
> Jens Axboe
>

Hi,

attached the test case, to make it as compact as possible I dropped as
well the error code checking as well.

I have added some fprintf around the code, just connect to localhost
port 5001 using telnet (it will send a line, it will be a bit easier
to check the output).

On the first message you will see a like like
[CQE][RECV] fd 5, cqe flags high: 9, cqe flags low: 1

and a number of lines to show the content of the buffers with the last
buffer containing the message sent via telnet.

On the second message you will instead see again
[CQE][RECV] fd 5, cqe flags high: 5, cqe flags low: 1

but the buffer actually containing the sent line will be the number 0.

On all the successive submits the used buffer will still be 0 but the
high part of cqe->flags will still contain 9.

Or at least this is what I am experiencing.

If you comment out line 110, 111 and 112 it will work as (I think)
expected but of course you will finish the buffers (and get an
undefined behaviour because the code is not managing the errors at
all).


Thanks!
Daniele

[-- Attachment #2: test.c --]
[-- Type: application/octet-stream, Size: 4370 bytes --]

#include <stdio.h>
#include <stdlib.h>
#include <stdint.h>
#include <netinet/in.h>

#include <liburing.h>
#include <liburing/io_uring.h>

#define CONNECTIONS_BACKLOG 10
#define BUFFER_COUNT 10
#define BUFFER_LEN 1024

enum {
    OP_ACCEPT = 1,
    OP_RECV = 2,
    OP_PROVIDE_BUFFERS = 3,
};

char bufs[BUFFER_COUNT][BUFFER_LEN] = {0};
int server_port = 5001;
int bgid = 1337;

int main(int argc, char *argv[]) {
    struct sockaddr_in serv_addr = {0}, client_addr = {0};
    struct io_uring_params params = {0};
    struct io_uring ring = {0};
    struct io_uring_sqe *sqe;
    struct io_uring_cqe *cqe;
    const int val = 1;
    socklen_t client_len = sizeof(client_addr);

    int sock_listen_fd = socket(AF_INET, SOCK_STREAM | SOCK_NONBLOCK, 0);
    setsockopt(sock_listen_fd, SOL_SOCKET, SO_REUSEADDR, &val, sizeof(val));

    serv_addr.sin_family = AF_INET;
    serv_addr.sin_port = htons(server_port);
    serv_addr.sin_addr.s_addr = INADDR_ANY;

    bind(sock_listen_fd, (struct sockaddr *) &serv_addr, sizeof(serv_addr));
    listen(sock_listen_fd, CONNECTIONS_BACKLOG);

    io_uring_queue_init_params(1024, &ring, &params);

    // Setup the buffers
    sqe = io_uring_get_sqe(&ring);
    io_uring_prep_provide_buffers(sqe, bufs, BUFFER_LEN, BUFFER_COUNT, bgid, 0);
    io_uring_submit(&ring);
    io_uring_wait_cqe(&ring, &cqe);
    io_uring_cqe_seen(&ring, cqe);

    // Submit an accept sqe
    sqe = io_uring_get_sqe(&ring);
    io_uring_prep_accept(sqe, sock_listen_fd, (struct sockaddr *) &client_addr, &client_len, 0);
    sqe->user_data = ((uint8_t) OP_ACCEPT & 0xFFu);

    fprintf(stdout, "Waiting for connections on port %d\n", server_port);
    fflush(stdout);

    // start event loop
    while (1) {
        io_uring_submit_and_wait(&ring, 1);
        unsigned head;
        unsigned count = 0;

        // go through all CQEs
        io_uring_for_each_cqe(&ring, head, cqe) {
            ++count;

            int type = cqe->user_data & 0xFF;

            if (type == OP_ACCEPT) {
                if (cqe->res >= 0) {
                    int fd = cqe->res;

                    sqe = io_uring_get_sqe(&ring);
                    io_uring_prep_recv(sqe, fd, NULL, BUFFER_LEN, 0);
                    io_uring_sqe_set_flags(sqe, IOSQE_BUFFER_SELECT);
                    sqe->buf_group = bgid;
                    sqe->user_data = ((int64_t) fd << 8) | (OP_RECV & 0xFF);

                    fprintf(stdout, "[CQE][ACCEPT] new connection, fd %d\n", fd);
                    fflush(stdout);
                }

                sqe = io_uring_get_sqe(&ring);
                io_uring_prep_accept(sqe, sock_listen_fd, (struct sockaddr *) &client_addr, &client_len, 0);
                sqe->user_data = (OP_ACCEPT & 0xFF);
            } else if (type == OP_RECV) {
                int fd = (cqe->user_data >> 8) & 0xFFFFFFFF;
                int bytes_read = cqe->res;

                fprintf(stdout, "[CQE][RECV] fd %d, cqe flags high: %d, cqe flags low: %d\n",
                        fd, cqe->flags >> 16, cqe->flags & 0xFFFF);
                fprintf(stdout, "[CQE][RECV] bytes: %d\n", bytes_read);
                fflush(stdout);

                if (bytes_read <= 0) {
                    shutdown(fd, SHUT_RDWR);
                } else {
                    int bid = cqe->flags >> IORING_CQE_BUFFER_SHIFT;

                    fprintf(stdout, "[CQE][RECV] msg: %s\n", bufs[bid]);
                    fflush(stdout);

                    for (uint16_t i = 0; i < BUFFER_COUNT; i++) {
                        fprintf(stdout, "[BUFFER][%d] %s\n", i, bufs[i]);
                    }
                    fflush(stdout);

                    sqe = io_uring_get_sqe(&ring);
                    io_uring_prep_provide_buffers(sqe, bufs, BUFFER_LEN, 1, bgid, bid);
                    sqe->user_data = (OP_PROVIDE_BUFFERS & 0xFF);

                    sqe = io_uring_get_sqe(&ring);
                    io_uring_prep_recv(sqe, fd, NULL, BUFFER_LEN, 0);
                    io_uring_sqe_set_flags(sqe, IOSQE_BUFFER_SELECT);
                    sqe->buf_group = bgid;
                    sqe->user_data = ((int64_t) fd << 8) | (OP_RECV & 0xFF);
                }
            } else {
                fprintf(stdout, "[CQE][OTHER] ignoring\n");
                fflush(stdout);
            }
        }

        io_uring_cq_advance(&ring, count);
    }
}

Re: Keep getting the same buffer ID when RECV with IOSQE_BUFFER_SELECT

[Hieke de Vries]

There was a bug in the echo server code with re-registering the buffer: https://github.com/frevib/io_uring-echo-server/commit/aa6f2a09ca14c6aa17779a22343b9e7d4b3c7994 

Please try the latest master branch, maybe it'll help you with your own code as well. 

--
Hielke de Vries


On Fri, Jul 3, 2020, at 22:22, Daniele Salvatore Albano wrote:
> On Fri, 3 Jul 2020 at 21:12, Jens Axboe <axboe@kernel.dk> wrote:
> >
> > On 7/3/20 1:09 PM, Daniele Salvatore Albano wrote:
> > > On Fri, 3 Jul 2020, 20:57 Jens Axboe, <axboe@kernel.dk <mailto:axboe@kernel.dk>> wrote:
> > >
> > >     On 7/3/20 12:48 PM, Daniele Salvatore Albano wrote:
> > >     > Hi,
> > >     >
> > >     > I have recently started to play with io_uring and liburing but I am
> > >     > facing an odd issue, of course initially I thought it was my code but
> > >     > after further investigation and testing some other code (
> > >     > https://github.com/frevib/io_uring-echo-server/tree/io-uring-op-provide-buffers
> > >     > ) I faced the same behaviour.
> > >     >
> > >     > When using the IOSQE_BUFFER_SELECT with RECV I always get the first
> > >     > read right but all the subsequent return a buffer id different from
> > >     > what was used by the kernel.
> > >     >
> > >     > The problem starts to happen only after io_uring_prep_provide_buffers
> > >     > is invoked to put back the buffer, the bid set is the one from cflags
> > >     >>> 16.
> > >     >
> > >     > The logic is as follow:
> > >     > - io_uring_prep_provide_buffers + io_uring_submit + io_uring_wait_cqe
> > >     > initialize all the buffers at the beginning
> > >     > - within io_uring_for_each_cqe, when accepting a new connection a recv
> > >     > sqe is submitted with the IOSQE_BUFFER_SELECT flag
> > >     > - within io_uring_for_each_cqe, when recv a send sqe is submitted
> > >     > using as buffer the one specified in cflags >> 16
> > >     > - within io_uring_for_each_cqe, when send a provide buffers for the
> > >     > bid used to send the data and a recv sqes are submitted.
> > >     >
> > >     > If I drop io_uring_prep_provide_buffers both in my code and in the
> > >     > code I referenced above it just works, but of course at some point
> > >     > there are no more buffers available.
> > >     >
> > >     > To further debug the issue I reduced the amount of provided buffers
> > >     > and started to print out the entire bufferset and I noticed that after
> > >     > the first correct RECV the kernel stores the data in the first buffer
> > >     > of the group id but always returns the last buffer id.
> > >     > It is like after calling io_uring_prep_provide_buffers the information
> > >     > on the kernel side gets corrupted, I tried to follow the logic on the
> > >     > kernel side but there is nothing apparent that would make me
> > >     > understand why I am facing this behaviour.
> > >     >
> > >     > The original author of that code told me on SO that he wrote & tested
> > >     > it on the kernel 5.6 + the provide buffers branch, I am facing this
> > >     > issue with 5.7.6, 5.8-rc1 and 5.8-rc3. The liburing library is built
> > >     > out of the branch, I didn't do too much testing with different
> > >     > versions but I tried to figure out where the issue was for the last
> > >     > week and within this period I have pulled multiple times the repo.
> > >     >
> > >     > Any hint or suggestion?
> > >
> > >     Do you have a simple test case for this that can be run standalone?
> > >     I'll take a look, but I'd rather not spend time re-creating a test case
> > >     if you already have one.
> > >
> > >     --
> > >     Jens Axboe
> > >
> > >
> > > I will shrink down the code to produce a simple test case but not sure
> > > how much code I will be able to lift because it's showing this
> > > behaviour on a second recv of a connection so I will need to keep all
> > > the boilerplate code to get there.
> >
> > That's fine, I'm just looking to avoid having to write it from scratch.
> > Plus a test case is easier to deal with than trying to write a test case
> > based on your description, less room for interpretative errors.
> >
> > --
> > Jens Axboe
> >
> 
> Hi,
> 
> attached the test case, to make it as compact as possible I dropped as
> well the error code checking as well.
> 
> I have added some fprintf around the code, just connect to localhost
> port 5001 using telnet (it will send a line, it will be a bit easier
> to check the output).
> 
> On the first message you will see a like like
> [CQE][RECV] fd 5, cqe flags high: 9, cqe flags low: 1
> 
> and a number of lines to show the content of the buffers with the last
> buffer containing the message sent via telnet.
> 
> On the second message you will instead see again
> [CQE][RECV] fd 5, cqe flags high: 5, cqe flags low: 1
> 
> but the buffer actually containing the sent line will be the number 0.
> 
> On all the successive submits the used buffer will still be 0 but the
> high part of cqe->flags will still contain 9.
> 
> Or at least this is what I am experiencing.
> 
> If you comment out line 110, 111 and 112 it will work as (I think)
> expected but of course you will finish the buffers (and get an
> undefined behaviour because the code is not managing the errors at
> all).
> 
> 
> Thanks!
> Daniele
> 
> Attachments:
> * test.c

Re: Keep getting the same buffer ID when RECV with IOSQE_BUFFER_SELECT

[Daniele Salvatore Albano]

On Sat, 4 Jul 2020 at 14:00, Hieke de Vries <hdevries@fastmail.com> wrote:
>
> There was a bug in the echo server code with re-registering the buffer: https://github.com/frevib/io_uring-echo-server/commit/aa6f2a09ca14c6aa17779a22343b9e7d4b3c7994
>
> Please try the latest master branch, maybe it'll help you with your own code as well.
>
> --
> Hielke de Vries

Yes, that fixed my issue too!

Thanks a lot!
Daniele

Re: Keep getting the same buffer ID when RECV with IOSQE_BUFFER_SELECT

[Jens Axboe]

On 7/4/20 6:12 AM, Daniele Salvatore Albano wrote:
> On Sat, 4 Jul 2020 at 14:00, Hieke de Vries <hdevries@fastmail.com> wrote:
>>
>> There was a bug in the echo server code with re-registering the buffer: https://github.com/frevib/io_uring-echo-server/commit/aa6f2a09ca14c6aa17779a22343b9e7d4b3c7994
>>
>> Please try the latest master branch, maybe it'll help you with your own code as well.
>>
>> --
>> Hielke de Vries
> 
> Yes, that fixed my issue too!

So I guess this was just app error, nothing wrong on the kernel side?

-- 
Jens Axboe