4.9.0 regression in pipe-backed iov_iter with systemd-nspawn

Alan J. Wylie
2017-01-12T20:35:25Z

[-- Attachment #1: message body text --]
[-- Type: text/plain, Size: 5702 bytes --]

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@zeniv.linux.org.uk>
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@zeniv.linux.org.uk>

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 #2: config-4.9.3.bz2 --]
[-- Type: application/octet-stream, Size: 21088 bytes --]

[-- Attachment #3: .signature --]
[-- Type: text/plain, Size: 194 bytes --]

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

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