[Linux-cachefs] Interesting fscache assertion

[Milosz Tanski]

David,

After a week of uptime on one of the machines it looks like the
cachefiles backend ran into an assertion that I haven't seen before.
I've included the kernel log traceback below.

CacheFiles: Assertion failed
8000 < 7d00 is false
------------[ cut here ]------------
kernel BUG at fs/cachefiles/rdwr.c:939!
invalid opcode: 0000 [#1] SMP
Modules linked in: cachefiles auth_rpcgss ghash_clmulni_intel
aesni_intel oid_registry ablk_helper nfsv4 cryptd lrw gf128mul
glue_helper aes_x86_64 microcode nfs ceph lockd libceph sunrpc fscache
raid10 raid456 async_pq async_xor async_memcpy async_raid6_recov
async_tx raid1 raid0 multipath linear btrfs raid6_pq lzo_compress xor
zlib_deflate libcrc32c
CPU: 0 PID: 10628 Comm: kworker/u4:2 Not tainted 3.11.0-virtual #62
Workqueue: fscache_operation fscache_op_work_func [fscache]
task: ffff880425bb2de0 ti: ffff88015f374000 task.ti: ffff88015f374000
RIP: e030:[<ffffffffa0313928>]  [<ffffffffa0313928>]
cachefiles_write_page+0x398/0x430 [cachefiles]
RSP: e02b:ffff88015f375cf8  EFLAGS: 00010296
RAX: 0000000000000014 RBX: ffff8802e47fd500 RCX: 0000000000000006
RDX: 0000000000000007 RSI: 0000000000000007 RDI: ffff88015f3702b8
RBP: ffff88015f375d58 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000774 R11: 0720072007200720 R12: ffffea000d4c11c0
R13: ffff88038b256500 R14: 0000000000007d00 R15: 0000000000001000
FS:  00007f74f4a2f700(0000) GS:ffff880443400000(0000) knlGS:0000000000000000
CS:  e033 DS: 0000 ES: 0000 CR0: 000000008005003b
CR2: 00007fdefa36b000 CR3: 00000004276b0000 CR4: 0000000000002660
Stack:
 0000000000000100 ffff88015f375d58 ffffffff812bd4e9 ffff8804255da920
 ffff8802426d9240 0000000000008000 0000000000000007 ffff8802614be9e0
 ffff8802e47fd500 ffff8802614be9b0 ffffea000d4c11c0 ffff88034a988480
Call Trace:
 [<ffffffff812bd4e9>] ? radix_tree_gang_lookup_tag+0x89/0xd0
 [<ffffffffa01743b0>] fscache_write_op+0x2d0/0x460 [fscache]
 [<ffffffffa01730ea>] fscache_op_work_func+0x3a/0x100 [fscache]
 [<ffffffff8107aa59>] process_one_work+0x179/0x490
 [<ffffffff8107bf5b>] worker_thread+0x11b/0x370
 [<ffffffff8107be40>] ? manage_workers.isra.21+0x2e0/0x2e0
 [<ffffffff81082a80>] kthread+0xc0/0xd0
 [<ffffffff81010000>] ? perf_trace_xen_mmu_set_pud+0xd0/0xd0
 [<ffffffff810829c0>] ? flush_kthread_worker+0xb0/0xb0
 [<ffffffff81572cec>] ret_from_fork+0x7c/0xb0
 [<ffffffff810829c0>] ? flush_kthread_worker+0xb0/0xb0
Code: a0 31 c0 e8 d1 cf 24 e1 48 c7 c7 98 76 31 a0 31 c0 e8 c3 cf 24
e1 48 8b 75 c8 4c 89 f2 48 c7 c7 05 64 31 a0 31 c0 e8 ae cf 24 e1 <0f>
0b 65 48 8b 34 25 80 c7 00 00 48 c7 c2 f0 59 31 a0 48 81 c6
RIP  [<ffffffffa0313928>] cachefiles_write_page+0x398/0x430 [cachefiles]
 RSP <ffff88015f375cf8>
---[ end trace b4b1daf058cb9624 ]---
BUG: unable to handle kernel paging request at ffffffffffffffd8
IP: [<ffffffff81082d71>] kthread_data+0x11/0x20
PGD 1a0f067 PUD 1a11067 PMD 0
Oops: 0000 [#2] SMP
Modules linked in: cachefiles auth_rpcgss ghash_clmulni_intel
aesni_intel oid_registry ablk_helper nfsv4 cryptd lrw gf128mul
glue_helper aes_x86_64 microcode nfs ceph lockd libceph sunrpc fscache
raid10 raid456 async_pq async_xor async_memcpy async_raid6_recov
async_tx raid1 raid0 multipath linear btrfs raid6_pq lzo_compress xor
zlib_deflate libcrc32c
CPU: 0 PID: 10628 Comm: kworker/u4:2 Tainted: G      D      3.11.0-virtual #62
task: ffff880425bb2de0 ti: ffff88015f374000 task.ti: ffff88015f374000
RIP: e030:[<ffffffff81082d71>]  [<ffffffff81082d71>] kthread_data+0x11/0x20
RSP: e02b:ffff88015f3759a0  EFLAGS: 00010046
RAX: 0000000000000000 RBX: 0000000000000000 RCX: ffffffff81c30d00
RDX: 0000000000000000 RSI: 0000000000000000 RDI: ffff880425bb2de0
RBP: ffff88015f3759b8 R08: 0000000000017450 R09: ffffea001096fa00
R10: ffffffff8105dcef R11: 000000000000000e R12: 0000000000000000
R13: ffff880425bb31b8 R14: ffff88042c498000 R15: 0000000000000000
FS:  00007f74f4a2f700(0000) GS:ffff880443400000(0000) knlGS:0000000000000000
CS:  e033 DS: 0000 ES: 0000 CR0: 000000008005003b
CR2: 0000000000000028 CR3: 00000004276b0000 CR4: 0000000000002660
Stack:
 ffffffff8107c3d6 ffff880443413fc0 0000000000000000 ffff88015f375a38
 ffffffff815689f8 0000000000000001 ffff880425bb2de0 ffff880425bb2de0
 ffff88015f375fd8 ffff88015f375fd8 ffff88015f375fd8 ffff88015f375a48
Call Trace:
 [<ffffffff8107c3d6>] ? wq_worker_sleeping+0x16/0x90
 [<ffffffff815689f8>] __schedule+0x5c8/0x820
 [<ffffffff81568d09>] schedule+0x29/0x70
 [<ffffffff81062600>] do_exit+0x6e0/0xa60
 [<ffffffff81560923>] ? printk+0x4d/0x4f
 [<ffffffff8100b482>] ? check_events+0x12/0x20
 [<ffffffff8156b480>] oops_end+0xb0/0xf0
 [<ffffffff81016b28>] die+0x58/0x90
 [<ffffffff8156ad9b>] do_trap+0xcb/0x170
 [<ffffffff8100b482>] ? check_events+0x12/0x20
 [<ffffffff81013f45>] do_invalid_op+0x95/0xb0
 [<ffffffffa0313928>] ? cachefiles_write_page+0x398/0x430 [cachefiles]
 [<ffffffff810a92e4>] ? wake_up_klogd+0x34/0x40
 [<ffffffff810a9575>] ? console_unlock+0x285/0x3c0
 [<ffffffff810a9afd>] ? vprintk_emit+0x1cd/0x490
 [<ffffffff8157445e>] invalid_op+0x1e/0x30
 [<ffffffffa0313928>] ? cachefiles_write_page+0x398/0x430 [cachefiles]
 [<ffffffffa0313928>] ? cachefiles_write_page+0x398/0x430 [cachefiles]
 [<ffffffff812bd4e9>] ? radix_tree_gang_lookup_tag+0x89/0xd0
 [<ffffffffa01743b0>] fscache_write_op+0x2d0/0x460 [fscache]
 [<ffffffffa01730ea>] fscache_op_work_func+0x3a/0x100 [fscache]
 [<ffffffff8107aa59>] process_one_work+0x179/0x490
 [<ffffffff8107bf5b>] worker_thread+0x11b/0x370
 [<ffffffff8107be40>] ? manage_workers.isra.21+0x2e0/0x2e0
 [<ffffffff81082a80>] kthread+0xc0/0xd0
 [<ffffffff81010000>] ? perf_trace_xen_mmu_set_pud+0xd0/0xd0
 [<ffffffff810829c0>] ? flush_kthread_worker+0xb0/0xb0
 [<ffffffff81572cec>] ret_from_fork+0x7c/0xb0
 [<ffffffff810829c0>] ? flush_kthread_worker+0xb0/0xb0
Code: 48 89 e5 5d 48 8b 40 c8 48 c1 e8 02 83 e0 01 c3 66 2e 0f 1f 84
00 00 00 00 00 66 66 66 66 90 48 8b 87 80 03 00 00 55 48 89 e5 5d <48>
8b 40 d8 c3 66 2e 0f 1f 84 00 00 00 00 00 66 66 66 66 90 55
RIP  [<ffffffff81082d71>] kthread_data+0x11/0x20
 RSP <ffff88015f3759a0>
CR2: ffffffffffffffd8
---[ end trace b4b1daf058cb9625 ]---