I'm trying to write a simplified reproducer that reproduces
----------------------------------------
[ 162.905919][ T3399] required_size=2461 ret=0
[ 162.916796][ T3399] required_size=6557 ret=0
[ 162.919587][ T3399] required_size=10653 ret=0
[ 162.923090][ T3399] required_size=14749 ret=0
[ 162.928686][ T3399] required_size=16413 ret=0
[ 162.936894][ T3399] full_record=1 eor=0 sk_msg_full(msg_pl)=0 copied=1664
[ 162.962097][ T3399] required_size=2461 ret=0
[ 162.967270][ T3399] required_size=6557 ret=0
[ 162.992866][ T3399] required_size=10653 ret=0
[ 162.999962][ T3399] required_size=14765 ret=0
[ 163.006420][ T3399] required_size=16413 ret=0
[ 163.012163][ T3399] full_record=1 eor=0 sk_msg_full(msg_pl)=0 copied=1648
----------------------------------------
part, and came to wonder if serialization between splice() and sendmsg() is correct.
A program where splice() and sendmsg() cannot run in parallel due to single-threaded
is shown below.
----------------------------------------
#define _GNU_SOURCE
#include <sys/types.h>
#include <fcntl.h>
#include <unistd.h>
#include <sys/socket.h>
#include <arpa/inet.h>
#define SOL_TCP 6
#define TCP_REPAIR 19
#define TCP_ULP 31
#define TLS_TX 1
int main(int argc, char *argv[])
{
struct iovec iov = {
.iov_base = "@@@@@@@@@@@@@@@@",
.iov_len = 16
};
struct msghdr hdr = {
.msg_iov = &iov,
.msg_iovlen = 1,
.msg_flags = MSG_FASTOPEN
};
const struct sockaddr_in6 addr = { .sin6_family = AF_INET6, .sin6_addr = in6addr_loopback };
const int one = 1;
int ret_ignored = 0;
const int fd = socket(PF_INET6, SOCK_STREAM, IPPROTO_IP);
int pipe_fds[2] = { -1, -1 };
static char buf[32768] = { };
ret_ignored += pipe(pipe_fds);
setsockopt(fd, SOL_TCP, TCP_REPAIR, &one, sizeof(one));
connect(fd, (struct sockaddr *) &addr, sizeof(addr));
setsockopt(fd, SOL_TCP, TCP_ULP, "tls", 4);
setsockopt(fd, SOL_TLS, TLS_TX,"\3\0035\0%T\244\205\333\f0\362B\221\243\234\206\216\220\243u\347\342P|1\24}Q@\377\227\353\222B\354\264u[\346", 40);
ret_ignored += write(pipe_fds[1], buf, 2432);
ret_ignored += write(pipe_fds[1], buf, 10676);
ret_ignored += write(pipe_fds[1], buf, 17996);
if (argc == 1) {
ret_ignored += splice(pipe_fds[0], NULL, fd, NULL, 1048576, 0);
ret_ignored += sendmsg(fd, &hdr, MSG_DONTWAIT | MSG_MORE);
} else {
ret_ignored += sendmsg(fd, &hdr, MSG_DONTWAIT | MSG_MORE);
ret_ignored += splice(pipe_fds[0], NULL, fd, NULL, 1048576, 0);
}
return ret_ignored * 0;
}
----------------------------------------
If you run this program with argc == 1, you will get below output.
----------------------------------------
[ 4030.292376] [ T3896] required_size=2461 ret=0
[ 4030.292376] [ T3896] required_size=6557 ret=0
[ 4030.292376] [ T3896] required_size=10653 ret=0
[ 4030.292376] [ T3896] required_size=14749 ret=0
[ 4030.292376] [ T3896] required_size=16413 ret=0
[ 4030.292376] [ T3896] full_record=1 eor=0 sk_msg_full(msg_pl)=0 copied=1664
[ 4030.330185] [ T3896] required_size=2461 ret=0
[ 4030.330185] [ T3896] required_size=6557 ret=0
[ 4030.330185] [ T3896] required_size=10653 ret=0
[ 4030.335443] [ T3896] required_size=14749 ret=0
[ 4030.335443] [ T3896] full_record=0 eor=1 sk_msg_full(msg_pl)=0 copied=4096
----------------------------------------
If you run this program with argc != 1, you will get below output.
----------------------------------------
[ 4044.312696] [ T3898] required_size=2477 ret=0
[ 4044.312696] [ T3898] required_size=6573 ret=0
[ 4044.312696] [ T3898] required_size=10669 ret=0
[ 4044.312696] [ T3898] required_size=14765 ret=0
[ 4044.312696] [ T3898] required_size=16413 ret=0
[ 4044.312696] [ T3898] full_record=1 eor=0 sk_msg_full(msg_pl)=0 copied=1648
[ 4044.340425] [ T3898] required_size=2477 ret=0
[ 4044.350515] [ T3898] required_size=6573 ret=0
[ 4044.350515] [ T3898] required_size=10669 ret=0
[ 4044.350515] [ T3898] required_size=14765 ret=0
[ 4044.350515] [ T3898] full_record=0 eor=1 sk_msg_full(msg_pl)=0 copied=4096
----------------------------------------
The difference is that the required_size= value differs by "struct iovec"->iov_len
bytes which is the value passed to sendmsg().
If splice() happens before sendmsg() happens, the output does not include
bytes passed to sendmsg(). If sendmsg() happens before splice() happens,
the output includes bytes passed to sendmsg().
Then, where does the difference between
----------------------------------------
[ 162.919587][ T3399] required_size=10653 ret=0
[ 162.923090][ T3399] required_size=14749 ret=0
[ 162.928686][ T3399] required_size=16413 ret=0
----------------------------------------
and
----------------------------------------
[ 162.992866][ T3399] required_size=10653 ret=0
[ 162.999962][ T3399] required_size=14765 ret=0
[ 163.006420][ T3399] required_size=16413 ret=0
----------------------------------------
come from? Both output had the same values until 10653, but
the next value differs by 16. This might suggest that a race between
splice() and sendmsg() caused unexpected required_size= value...
This could explain "for the second time" part below.
> 4125+8221+12317+16413=41076 (the lower 4 bits are 0100)
> 2461+6557+10653+14749+16413=50833 (the lower 4 bits are 0001)
> 2461+6573+10669+14765+16413=50881 (the lower 4 bits are 0001)
>
> KMSAN reports this problem when the lower 4 bits became 0001 for the second time.
> Unless KMSAN's reporting is asynchronous, maybe the reason of "for the second time"
> part is that the previous state is relevant...
