Antti kirjoitti 10.7.2019 13:45:
Package: rsync
Version: 3.1.3-6
Severity: critical
Justification: breaks unrelated software
-- System Information:
Debian Release: 10.0
APT prefers stable
APT policy: (500, 'stable')
Architecture: amd64 (x86_64)
Kernel: Linux 4.19.0-5-amd64 (SMP w/2 CPU cores)
Locale: LANG=en_US.UTF-8, LC_CTYPE=en_US.UTF-8 (charmap=UTF-8),
LANGUAGE=en_US:en (charmap=UTF-8)
Shell: /bin/sh linked to /bin/dash
Init: systemd (via /run/systemd/system)
Versions of packages rsync depends on:
ii base-files 10.3
ii init-system-helpers 1.56+nmu1
ii libacl1 2.2.53-4
ii libattr1 1:2.4.48-4
ii libc6 2.28-10
ii libpopt0 1.16-12
ii lsb-base 10.2019051400
rsync recommends no packages.
Versions of packages rsync suggests:
ii openssh-client 1:7.9p1-10
ii openssh-server 1:7.9p1-10
-- no debconf information
I am rsyncing files with the following command:
/usr/bin/rsync --progress -avzse ssh 'user@host:/path/a/' '/path/b/'
I have succesfully run this command on Debian Stretch before the
upgrade.
I updated to Debian Buster and now the system hangs when syncing large
(400M) files using the above command. I have tried also a clean Buster
installation but the problem persists.
Initially I suspected this a hardware issue but I tested the disks
with DD (on Buster) and even heavy load did not cause any issues.
This problem seems to be related to rsync and large files. Rsync with
small files works OK.
Disabling AppArmor on Buster does not help.
Symptoms:
Aftert issuing the command, the rsync starts OK. Even large files are
transferring OK at this point.
After a while, the CPU load on the system goes to 100 % and the system
becomes unresponsive.
I am running the system on VMWare ESXi 6.7 U2 host and the system is
using Broadcom 9440-8i RAID controller.
If I switch from Buster to Stretch, everything works OK.
Typically nothing can be seen in the dmesg but once I was able to
capture the following:
Jul 10 07:27:00 nasunas kernel: BUG: unable to handle kernel paging
request at 000000f0416baec0
Jul 10 07:27:00 nasunas kernel: PGD 0 P4D 0
Jul 10 07:27:00 nasunas kernel: Oops: 0000 [#1] SMP PTI
Jul 10 07:27:00 nasunas kernel: CPU: 0 PID: 1053 Comm: rsync Not
tainted 4.19.0-5-amd64 #1 Debian 4.19.37-5
Jul 10 07:27:00 nasunas kernel: Hardware name: VMware, Inc. VMware
Virtual Platform/440BX Desktop Reference Platform, BIOS 6.00
12/12/2018
Jul 10 07:27:00 nasunas kernel: RIP: 0010:__radix_tree_lookup+0x4b/0xe0
Jul 10 07:27:00 nasunas kernel: Code: 48 83 e0 fe 0f b6 08 48 89 d8 48
d3 e0 48 83 e8 01 48 39 c6 0f 87 9e 00 00 00 49 83 f8 01 74 c9 4d 89
c1 48 89 f0 49 83 e1 fe $
Jul 10 07:27:00 nasunas kernel: RSP: 0018:ffff9cba41893c28 EFLAGS:
00010206
Jul 10 07:27:00 nasunas kernel: RAX: 000000000000b580 RBX:
0000000000000040 RCX: 0000000000000000
Jul 10 07:27:00 nasunas kernel: RDX: 0000000000000000 RSI:
000000000000b580 RDI: ffff88b8ef932420
Jul 10 07:27:00 nasunas kernel: RBP: ffff9cba41893c40 R08:
000000f0416baec1 R09: 000000f0416baec0
Jul 10 07:27:00 nasunas kernel: R10: ffff88b844d82dd8 R11:
0000000000000001 R12: 00000000006200ca
Jul 10 07:27:00 nasunas kernel: R13: ffff88b8ef932418 R14:
000000000000b580 R15: ffffffffb8675de0
Jul 10 07:27:00 nasunas kernel: FS: 00007fa4bf1d4b80(0000)
GS:ffff88b8fba00000(0000) knlGS:0000000000000000
Jul 10 07:27:00 nasunas kernel: CS: 0010 DS: 0000 ES: 0000 CR0:
0000000080050033
Jul 10 07:27:00 nasunas kernel: CR2: 000000f0416baec0 CR3:
000000012ed28005 CR4: 00000000003606f0
Jul 10 07:27:00 nasunas kernel: DR0: 0000000000000000 DR1:
0000000000000000 DR2: 0000000000000000
Jul 10 07:27:00 nasunas kernel: DR3: 0000000000000000 DR6:
00000000fffe0ff0 DR7: 0000000000000400
Jul 10 07:27:00 nasunas kernel: Call Trace:
Jul 10 07:27:00 nasunas kernel: radix_tree_lookup_slot+0x1e/0x50
Jul 10 07:27:00 nasunas kernel: find_get_entry+0x19/0xf0
Jul 10 07:27:00 nasunas kernel: pagecache_get_page+0x30/0x2c0
Jul 10 07:27:00 nasunas kernel: ? jbd2_journal_stop+0xef/0x3c0 [jbd2]
Jul 10 07:27:00 nasunas kernel: grab_cache_page_write_begin+0x1f/0x40
Jul 10 07:27:00 nasunas kernel: ext4_da_write_begin+0xce/0x470 [ext4]
Jul 10 07:27:00 nasunas kernel: generic_perform_write+0xf4/0x1b0
Jul 10 07:27:00 nasunas kernel: ? file_update_time+0xed/0x130
Jul 10 07:27:00 nasunas kernel: __generic_file_write_iter+0xfe/0x1c0
Jul 10 07:27:00 nasunas kernel: ext4_file_write_iter+0xc6/0x400 [ext4]
Jul 10 07:27:00 nasunas kernel: new_sync_write+0xfb/0x160
Jul 10 07:27:00 nasunas kernel: vfs_write+0xa5/0x1a0
Jul 10 07:27:00 nasunas kernel: ksys_write+0x4f/0xb0
Jul 10 07:27:00 nasunas kernel: do_syscall_64+0x53/0x110
Jul 10 07:27:00 nasunas kernel:
entry_SYSCALL_64_after_hwframe+0x44/0xa9
Jul 10 07:27:00 nasunas kernel: RIP: 0033:0x7fa4bf2c0504
Jul 10 07:27:00 nasunas kernel: Code: 00 f7 d8 64 89 02 48 c7 c0 ff ff
ff ff eb b3 0f 1f 80 00 00 00 00 48 8d 05 f9 61 0d 00 8b 00 85 c0 75
13 b8 01 00 00 00 0f 05 $
Jul 10 07:27:00 nasunas kernel: RSP: 002b:00007ffc30ac2868 EFLAGS:
00000246 ORIG_RAX: 0000000000000001
Jul 10 07:27:00 nasunas kernel: RAX: ffffffffffffffda RBX:
00005648d01f2ed0 RCX: 00007fa4bf2c0504
Jul 10 07:27:00 nasunas kernel: RDX: 0000000000040000 RSI:
00005648d01f2ed0 RDI: 0000000000000003
Jul 10 07:27:00 nasunas kernel: RBP: 0000000000000000 R08:
0000000000040000 R09: 00005648d0232820
Jul 10 07:27:00 nasunas kernel: R10: 00005648cffd34f6 R11:
0000000000000246 R12: 0000000000000003
Jul 10 07:27:00 nasunas kernel: R13: 00005648cffd27d0 R14:
0000000000004041 R15: 0000000000004041
Jul 10 07:27:00 nasunas kernel: Modules linked in:
vmw_vsock_vmci_transport vsock crct10dif_pclmul crc32_pclmul
ghash_clmulni_intel vmw_balloon intel_rapl_perf joyd$
Jul 10 07:27:00 nasunas kernel: CR2: 000000f0416baec0
Jul 10 07:27:00 nasunas kernel: ---[ end trace 4e40ae786f2374a5 ]---
Jul 10 07:27:00 nasunas kernel: RIP: 0010:__radix_tree_lookup+0x4b/0xe0
Jul 10 07:27:00 nasunas kernel: Code: 48 83 e0 fe 0f b6 08 48 89 d8 48
d3 e0 48 83 e8 01 48 39 c6 0f 87 9e 00 00 00 49 83 f8 01 74 c9 4d 89
c1 48 89 f0 49 83 e1 fe $
Jul 10 07:27:00 nasunas kernel: RSP: 0018:ffff9cba41893c28 EFLAGS:
00010206
Jul 10 07:27:00 nasunas kernel: RAX: 000000000000b580 RBX:
0000000000000040 RCX: 0000000000000000
Jul 10 07:27:00 nasunas kernel: RDX: 0000000000000000 RSI:
000000000000b580 RDI: ffff88b8ef932420
Jul 10 07:27:00 nasunas kernel: RBP: ffff9cba41893c40 R08:
000000f0416baec1 R09: 000000f0416baec0
Jul 10 07:27:00 nasunas kernel: R10: ffff88b844d82dd8 R11:
0000000000000001 R12: 00000000006200ca
Jul 10 07:27:00 nasunas kernel: R13: ffff88b8ef932418 R14:
000000000000b580 R15: ffffffffb8675de0
Jul 10 07:27:00 nasunas kernel: FS: 00007fa4bf1d4b80(0000)
GS:ffff88b8fba00000(0000) knlGS:0000000000000000
Jul 10 07:27:00 nasunas kernel: CS: 0010 DS: 0000 ES: 0000 CR0:
0000000080050033
Jul 10 07:27:00 nasunas kernel: CR2: 000000f0416baec0 CR3:
000000012ed28005 CR4: 00000000003606f0
Jul 10 07:27:00 nasunas kernel: DR0: 0000000000000000 DR1:
0000000000000000 DR2: 0000000000000000
Jul 10 07:27:00 nasunas kernel: DR3: 0000000000000000 DR6:
00000000fffe0ff0 DR7: 0000000000000400
Jul 10 07:27:00 nasunas kernel: ------------[ cut here ]------------
I did more debugging today. With "ssh -vv" flags I get the following
just before the rsync hangs:
debug2: channel 0: window 1966080 sent adjust 131072
debug2: channel 0: window 1966080 sent adjust 131072
debug2: channel 0: window 1966080 sent adjust 32768
debug2: channel 0: write failed
debug2: channel 0: chan_shutdown_write (i0 o0 sock -1 wfd 5 efd 6
[write])
rsync: connection unexpectedly closed (862820 bytes received so far)
[generator]
debug2: channel 0: send eow
debug2: channel 0: output open -> closed
rsync error: error in rsync protocol data stream (code 12) at io.c(235)
[generator=3.1.3]
Broadcast message from systemd-journald@nasunas (Sat 2019-07-13 06:41:21
EEST):
systemd[1]: Caught <ABRT>, dumped core as pid 1581.
Broadcast message from systemd-journald@nasunas (Sat 2019-07-13 06:41:21
EEST):
systemd[1]: Freezing execution.
Message from syslogd@nasunas at Jul 13 06:41:21 ...
systemd[1]: Caught <ABRT>, dumped core as pid 1581.
Message from syslogd@nasunas at Jul 13 06:41:21 ...
systemd[1]: Freezing execution.
