On Fri, Jul 15, 2016 at 05:18:02PM -0700, Calvin Owens wrote:

Hello all,

I've found a nasty source of slab corruption. Based on seeing similar symptoms
on boxes at Facebook, I suspect it's been around since at least 3.10.

It only reproduces under memory pressure so far as I can tell: the issue seems
to be that XFS reclaims pages from buffers that are still in use by
scsi/block. I'm not sure which side the bug lies on, but I've only observed it
with XFS.

[67203.776421] ==================================================================
[67203.792521] BUG: KASAN: use-after-free in xfs_destroy_ioend+0x3bf/0x4c0 at addr ffff8804cf466288
[67203.812036] Read of size 8 by task python2.7/22913
[67203.822713] =============================================================================
[67203.840917] BUG buffer_head (Not tainted): kasan: bad access detected
[67203.855253] -----------------------------------------------------------------------------
[67203.855253]
[67203.876727] Disabling lock debugging due to kernel taint
[67203.888575] INFO: Allocated in 0xffff8804cf465d40 age=18437180719206552994 cpu=2191548261 pid=-1
[67203.908139] 	alloc_buffer_head+0x22/0xd0
[67203.916903] 	___slab_alloc+0x4e0/0x520
[67203.925286] 	__slab_alloc+0x43/0x70
[67203.933087] 	kmem_cache_alloc+0x228/0x2c0
[67203.942042] 	alloc_buffer_head+0x22/0xd0
[67203.950782] 	alloc_page_buffers+0xa9/0x1f0
[67203.959936] 	create_empty_buffers+0x30/0x420
[67203.969495] 	create_page_buffers+0x120/0x1b0
[67203.979029] 	__block_write_begin+0x16b/0x1010
[67203.988756] 	xfs_vm_write_begin+0x55/0x1b0
[67203.997884] 	generic_perform_write+0x288/0x510
[67204.007771] 	xfs_file_buffered_aio_write+0x316/0x780
[67204.018811] 	xfs_file_write_iter+0x26f/0x6c0
[67204.028313] 	__vfs_write+0x2a0/0x620
[67204.036276] 	vfs_write+0x159/0x4c0
[67204.043855] 	SyS_write+0xd2/0x1b0
[67204.051245] INFO: Freed in 0x103fc80ec age=18446651500051355200 cpu=2165122683 pid=-1
[67204.068634] 	free_buffer_head+0x41/0x90
[67204.077175] 	__slab_free+0x1ed/0x340
[67204.085138] 	kmem_cache_free+0x270/0x300
[67204.093867] 	free_buffer_head+0x41/0x90
[67204.102422] 	try_to_free_buffers+0x171/0x240
[67204.111925] 	xfs_vm_releasepage+0xcb/0x3b0
[67204.121101] 	try_to_release_page+0x106/0x190
[67204.130602] 	shrink_page_list+0x118e/0x1a10
[67204.139910] 	shrink_inactive_list+0x42c/0xdf0
[67204.149600] 	shrink_zone_memcg+0xa09/0xfa0
[67204.158715] 	shrink_zone+0x2c3/0xbc0
[67204.166679] 	do_try_to_free_pages+0x42a/0x12f0
[67204.176562] 	try_to_free_pages+0x1a3/0x5d0
[67204.185709] 	__alloc_pages_nodemask+0xbeb/0x20d0
[67204.195979] 	alloc_pages_vma+0x11b/0x5e0
[67204.204709] 	handle_mm_fault+0x2c27/0x47d0
[67204.213823] INFO: Slab 0xffffea00133d1900 objects=37 used=14 fp=0xffff8804cf464530 flags=0x2000000000004080
[67204.235439] INFO: Object 0xffff8804cf466260 @offset=8800 fp=0xbbbbbbbbbbbbbbbb

Hmmm - can only get there with a clean page, so this should be fine.

[67204.455817] CPU: 1 PID: 22913 Comm: python2.7 Tainted: G    B           4.7.0-rc7-calvinowens-1468357363-00001-gcaa3dc6 #1
[67204.480313] Hardware name: Wiwynn   HoneyBadger/PantherPlus, BIOS HBM6.71 02/03/2016
[67204.497509]  ffff88075e99f480 ffff88075ec87a30 ffffffff81e8b8e4 ffff8804cf464000
[67204.514224]  ffff8804cf466260 ffff88075ec87a60 ffffffff8153a995 ffff88075e99f480
[67204.530924]  ffffea00133d1900 ffff8804cf466260 dffffc0000000000 ffff88075ec87a88
[67204.547624] Call Trace:
[67204.553086]  <IRQ>  [<ffffffff81e8b8e4>] dump_stack+0x68/0x94
[67204.565946]  [<ffffffff8153a995>] print_trailer+0x115/0x1a0
[67204.578334]  [<ffffffff81541174>] object_err+0x34/0x40
[67204.589762]  [<ffffffff815436e7>] kasan_report_error+0x217/0x530
[67204.616847]  [<ffffffff81543b33>] __asan_report_load8_noabort+0x43/0x50
[67204.645085]  [<ffffffff819d651f>] xfs_destroy_ioend+0x3bf/0x4c0
[67204.658243]  [<ffffffff819d69d4>] xfs_end_bio+0x154/0x220
[67204.685362]  [<ffffffff81de0c58>] bio_endio+0x158/0x1b0
[67204.696983]  [<ffffffff81dff61b>] blk_update_request+0x18b/0xb80
[67204.710334]  [<ffffffff821baf57>] scsi_end_request+0x97/0x5a0
[67204.723108]  [<ffffffff821c5558>] scsi_io_completion+0x438/0x1690
[67204.807293]  [<ffffffff821a8d95>] scsi_finish_command+0x375/0x4e0
[67204.820838]  [<ffffffff821c3940>] scsi_softirq_done+0x280/0x340
[67204.848884]  [<ffffffff81e1e13f>] blk_done_softirq+0x1ff/0x360
[67204.875074]  [<ffffffff82a08cad>] __do_softirq+0x22d/0x8d7
[67204.887270]  [<ffffffff8113d42c>] irq_exit+0x15c/0x190
[67204.898697]  [<ffffffff82a085e3>] smp_apic_timer_interrupt+0x83/0xa0
[67204.912815]  [<ffffffff82a06b29>] apic_timer_interrupt+0x89/0x90
[67205.029113] ==================================================================

But this indicates that the page is under writeback at this point,
so that tends to indicate that the above freeing was incorrect.

Hmmm - it's clear we've got direct reclaim involved here, and the
suspicion of a dirty page that has had it's bufferheads cleared.
Are there any other warnings in the log from XFS prior to kasan
throwing the error?

Is there anything else I can send that might be helpful?

full console/dmesg output from a crashed machine, plus:

http://xfs.org/index.php/XFS_FAQ#Q:_What_information_should_I_include_when_reporting_a_problem.3F

--
/*
 * Run as "./repro outfile 1000", where "outfile" sits on an XFS filesystem.
 */

#include <stdlib.h>
#include <stdio.h>
#include <fcntl.h>
#include <signal.h>
#include <unistd.h>
#include <sys/stat.h>
#include <sys/types.h>
#include <sys/mman.h>

#define CHUNK (32768)

static const char crap[CHUNK];

int main(int argc, char **argv)
{
	int r, fd, i;
	size_t allocsize, count;
	void *p;

	if (argc != 3) {
		printf("Usage: %s filename count\n", argv[0]);
		return 1;
	}

	fd = open(argv[1], O_RDWR|O_CREAT, 0644);
	if (fd == -1) {
		perror("Can't open");
		return 1;
	}

	if (!fork()) {
		count = atol(argv[2]);

		while (1) {
			for (i = 0; i < count; i++)
				if (write(fd, crap, CHUNK) != CHUNK)
					perror("Eh?");

			fsync(fd);
			ftruncate(fd, 0);
		}

Hmmmm. Truncate is used, but only after fsync. If the truncate
is removed, does the problem go away?

Cheers,

Dave.
-- 
Dave Chinner
david@fromorbit.com