[PATCH] Fix bug 9412 - SMB2 server doesn't support recvfile.

[Jones]

2014-04-18 0:10 GMT+08:00 Jeremy Allison <jra at samba.org>:

> (and remember your trace shows
> EAGAIN coming back explicitly
> after we've remove the O_NONBLOCK
> from the socket flag).
>

Hello Jeremy,

Yes! this symptom was a bit confusing for me,
after digging further found that source,
this EAGAIN is came from kernel tcp_recvmsg()
@ linux-3.4.6/net/ipv4/tcp.c
...
if (!timeo) {
copied = -EAGAIN;  // <--- came from here.
break;
}
...

Excuse me to explain more about my linux box,
though following part hmm ... just a bit samba code involved,
most of them are inside kernel.

The kernel is linux-3.4.6 with custom splice patch,
like following link:
https://lkml.org/lkml/2013/7/22/639

A different is the timeout is lower from 8 to 3,
- sock->sk->sk_rcvtimeo = 8 * HZ;
+ sock->sk->sk_rcvtimeo = 3 * HZ;

The 'perf top -G' show the call graph as following:
|--21.73%-- schedule_timeout
|           sk_wait_data
|           tcp_recvmsg
|           inet_recvmsg
|           sock_recvmsg
|           kernel_recvmsg
|           sys_splice
|           ia32_sysret
|           splice

Manually add debug code[1] into tcp_recvmsg(),
and found the kmsg[2] show that:
(1) nonblock:
this variable is always 0,
hence the fcntl() did remove O_NONBLOCK flag as expected.
(2) timeo:
this variable would be lower right after sk_wait_data(sk, &timeo),
and became lower per loop in tcp_recvmsg().
Looks like the schedule_timeout() did the modification of timeo.
Once timeo is lower and reaching 0,
would just hit the EAGAIN returning condition as earlier mentioned.

Hmm perhaps that's why O_NONBLOCK on socket fd is removed by fcntl(),
but splice with EAGAIN is still pop-out on strace log.

Question:
The fcntl() did remove O_NONBLOCK on socket fd but splice with EAGAIN
is still returned (a bit like failed to reach blocking mode?),
if kernel with custom splice patch at my linux box.
Hmm should try other method to replace fcntl(), like poll() / select()?

Or perhaps this is a special case because the custom splice part did this,
so just let it be a known limitation with not normal kernel code.
Under my LAN with RTT<1ms, splice with EAGAIN is likely a rare case,
setup and across a high latency network i could reproduce this symptom,
a quick guess this might also happen if put this linux box over VPN, Wifi,
or WAN.
Any other suggestion is appreciated, thanks.


[1] The debug code as following,
int tcp_recvmsg(struct kiocb *iocb, struct sock *sk, struct msghdr *msg,
size_t len, int nonblock, int flags, int *addr_len)
{
...
  u32 urg_hole = 0;
+ char name[sizeof(current->comm)];
+ int i = 0;
...
  do {
+ i++;
  u32 offset;
...
- } else
+ } else {
+ printk("%s (%d:%s) bef. copied=%d, timeo=%d, "
+ "nonblock=%d, sk_rcvtimeo=%d, "
+ "i=%d, "
+ "pid=%d, comm=%s.\n",
+ __FILE__, __LINE__, __func__,
+ copied, timeo,
+ nonblock, sk->sk_rcvtimeo,
+ i,
+ task_pid_nr(current),
+ get_task_comm(name, current));
  sk_wait_data(sk, &timeo);
+ printk("%s (%d:%s) aft. copied=%d, timeo=%d, "
+ "nonblock=%d, sk_rcvtimeo=%d, "
+ "i=%d, "
+ "pid=%d, comm=%s.\n",
+ __FILE__, __LINE__, __func__,
+ copied, timeo,
+ nonblock, sk->sk_rcvtimeo,
+ i,
+ task_pid_nr(current),
+ get_task_comm(name, current));
+ }
...

[2] kmsg, tail -F /proc/kmsg | grep -nr smbd

368:<4>[  534.480187] net/ipv4/tcp.c (1703:tcp_recvmsg) bef. copied=0,
timeo=3000, nonblock=0, sk_rcvtimeo=3000, i=1, pid=12126, comm=smbd.
369:<4>[  534.574716] net/ipv4/tcp.c (1714:tcp_recvmsg) aft. copied=0,
timeo=2908, nonblock=0, sk_rcvtimeo=3000, i=1, pid=12126, comm=smbd.
370:<4>[  534.577673] net/ipv4/tcp.c (1703:tcp_recvmsg) bef. copied=0,
timeo=2908, nonblock=0, sk_rcvtimeo=3000, i=2, pid=12126, comm=smbd.
378:<4>[  535.810564] net/ipv4/tcp.c (1714:tcp_recvmsg) aft. copied=0,
timeo=1675, nonblock=0, sk_rcvtimeo=3000, i=2, pid=12126, comm=smbd.
379:<4>[  535.813430] net/ipv4/tcp.c (1703:tcp_recvmsg) bef. copied=0,
timeo=1675, nonblock=0, sk_rcvtimeo=3000, i=3, pid=12126, comm=smbd.
411:<4>[  537.486547] net/ipv4/tcp.c (1714:tcp_recvmsg) aft. copied=0,
timeo=0, nonblock=0, sk_rcvtimeo=3000, i=3, pid=12126, comm=smbd.

--
Regards,
Jones