4.9.0 regression in pipe-backed iov_iter with systemd-nspawn

[Alan J. Wylie]

Some time after 4.9.0 was released, I noticed that a cron job running
systemd-nspawn was hanging trying to send mail.

I have trimmed it down to a minimal demo:

/* from crontab */
48	19	*	*	*	date; /work/chroot-shared/test.sh; date

/* script ------8<------8<------8<------8<------8<------8< */
# cat /work/chroot-shared/test.sh
#!/bin/bash
set -x

date

systemd-nspawn -q -D /work/chroot.32 --register=no date

date
/* ------8<------8<------8<------8<------8<------8<------8< */

and bisected it to

$ git --no-pager show 523ac9afc73acdcf9f00bd35b6ffb4a7c624a7d7
commit 523ac9afc73acdcf9f00bd35b6ffb4a7c624a7d7
Author: Al Viro <viro@xxxxxxxxxxxxxxxxxx>
Date:   Fri Sep 23 15:34:57 2016 -0400

    switch default_file_splice_read() to use of pipe-backed iov_iter

    we only use iov_iter_get_pages_alloc() and iov_iter_advance() -
    pages are filled by kernel_readv() via a kvec array (as we used
    to do all along), so iov_iter here is used only as a way of
    arranging for those pages to be in pipe.

    Signed-off-by: Al Viro <viro@xxxxxxxxxxxxxxxxxx>

The system is an up-to-date gentoo. Config attached.

$ eix -ce postfix
[I] mail-mta/postfix (3.1.2-r1@21/12/16): A fast and secure drop-in replacement for sendmail
$ eix -ce vixie-cron
[I] sys-process/vixie-cron (4.1-r14@24/09/15): Paul Vixie's cron daemon, a fully featured crond implementation
$ eix -ce systemd
[I] sys-apps/systemd (231@06/12/16): System and service manager for Linux

Strace shows that the processes are hanging in write() and read() calls.

====================================================================================================
# ps axfu | grep -A5 "[c]ron"
root       990  0.0  0.0  18708  2068 ?        Ss   20:34   0:00 /usr/sbin/cron
root      6399  0.0  0.0  27292  2172 ?        S    21:10   0:00  \_ /usr/sbin/cron
root      6402  0.0  0.0   9864  2480 ?        Ss   21:10   0:00      \_ /bin/bash -c date; /work/chroot-shared/test.sh; date
root      6406  0.0  0.0   9868  2472 ?        S    21:10   0:00      |   \_ /bin/bash /work/chroot-shared/test.sh
root      6405  0.0  0.0  76152  5428 ?        S    21:10   0:00      \_ /usr/sbin/sendmail -FCronDaemon -odi -oem -oi -t
root      6412  0.0  0.0  76140  5600 ?        S    21:10   0:00          \_ /usr/sbin/postdrop -r
at         993  0.0  0.0  16840   160 ?        Ss   20:34   0:00 /usr/sbin/atd

# strace -p 6406
strace: Process 6406 attached
write(2, "+ date\n", 7
^Cstrace: Process 6406 detached
 <detached ...>
#

# strace -p 6405
strace: Process 6405 attached
read(0,
^Cstrace: Process 6405 detached
 <detached ...>
#

====================================================================================================

git bisect start
# good: [c8d2bc9bc39ebea8437fd974fdbc21847bb897a3] Linux 4.8
git bisect good c8d2bc9bc39ebea8437fd974fdbc21847bb897a3
# good: [8bba2e2e62cbf2db0d03e4de1204f7850bc45c44] Linux 4.8.15
git bisect good 8bba2e2e62cbf2db0d03e4de1204f7850bc45c44
# bad: [1001354ca34179f3db924eb66672442a173147dc] Linux 4.9-rc1
git bisect bad 1001354ca34179f3db924eb66672442a173147dc
# good: [41844e36206be90cd4d962ea49b0abc3612a99d0] Merge tag 'staging-4.9-rc1' of git://git.kernel.org/pub/scm/linux/kernel/git/gregkh/staging
git bisect good 41844e36206be90cd4d962ea49b0abc3612a99d0
# bad: [6b5e09a748ad0a0b198d0e268c7e689044bfe48a] Merge git://git.kernel.org/pub/scm/linux/kernel/git/davem/net
git bisect bad 6b5e09a748ad0a0b198d0e268c7e689044bfe48a
# bad: [2c34ff14bf1d03a705f5400888ecac5b6400e981] Merge branch 'for-linus' of git://git.kernel.org/pub/scm/linux/kernel/git/egtvedt/linux-avr32
git bisect bad 2c34ff14bf1d03a705f5400888ecac5b6400e981
# good: [d042380886fb2fc6c4b0fcfe1214ba473769a8e9] Merge tag 'mfd-for-linus-4.9' of git://git.kernel.org/pub/scm/linux/kernel/git/lee/mfd
git bisect good d042380886fb2fc6c4b0fcfe1214ba473769a8e9
# good: [bc75450cc3db3485db1e289fef8c1028ba38296a] Merge branch 'for-linus' of git://git.kernel.org/pub/scm/linux/kernel/git/jikos/hid
git bisect good bc75450cc3db3485db1e289fef8c1028ba38296a
# good: [2eee010d092903ee95716b6c2fbd9d3289839aa4] Merge tag 'ext4_for_linus' of git://git.kernel.org/pub/scm/linux/kernel/git/tytso/ext4
git bisect good 2eee010d092903ee95716b6c2fbd9d3289839aa4
# skip: [ca2431633b414d112c39ec69d85d96f090e49453] powerpc/64s: Consolidate Directed Privileged Doorbell 0xa00 interrupt
git bisect skip ca2431633b414d112c39ec69d85d96f090e49453
# skip: [d312603a44eb9dc0dbb0a642a61899bac188ab71] powerpc/Makefile: CROSS32AS is unused, remove it
git bisect skip d312603a44eb9dc0dbb0a642a61899bac188ab71
# skip: [35066c0d798906d46c352c3f12844d2a162d057d] powerpc/eeh: Export confirm_error_lock
git bisect skip 35066c0d798906d46c352c3f12844d2a162d057d
# bad: [a779638cf622f069a484e8802134cca3c6c71415] pipe: add pipe_buf_release() helper
git bisect bad a779638cf622f069a484e8802134cca3c6c71415
# good: [25869262ef7af24ccde988867ac3eb1c3d4b88d4] skb_splice_bits(): get rid of callback
git bisect good 25869262ef7af24ccde988867ac3eb1c3d4b88d4
# bad: [523ac9afc73acdcf9f00bd35b6ffb4a7c624a7d7] switch default_file_splice_read() to use of pipe-backed iov_iter
git bisect bad 523ac9afc73acdcf9f00bd35b6ffb4a7c624a7d7
# good: [241699cd72a8489c9446ae3910ddd243e9b9061b] new iov_iter flavour: pipe-backed
git bisect good 241699cd72a8489c9446ae3910ddd243e9b9061b
# good: [82c156f853840645604acd7c2cebcb75ed1b6652] switch generic_file_splice_read() to use of ->read_iter()
git bisect good 82c156f853840645604acd7c2cebcb75ed1b6652
# first bad commit: [523ac9afc73acdcf9f00bd35b6ffb4a7c624a7d7] switch default_file_splice_read() to use of pipe-backed iov_iter
====================================================================================================

Attachment: config-4.9.3.bz2
Description: Binary data

-- 
Alan J. Wylie                                          http://www.wylie.me.uk/

Dance like no-one's watching. / Encrypt like everyone is.
Security is inversely proportional to convenience