BTRFS: unable to add free space :-17

Got this with 4.0.0-rc5 when doing a degraded mount:

Mar 23 13:09:22 server1 kernel: [  665.197957] BTRFS info (device sdb4): allowing degraded mounts
Mar 23 13:09:22 server1 kernel: [  665.198030] BTRFS info (device sdb4): disk space caching is enabled
Mar 23 13:09:22 server1 kernel: [  665.213163] BTRFS warning (device sdb4): devid 2 missing
Mar 23 13:09:22 server1 kernel: [  665.260077] BTRFS: bdev (null) errs: wr 1, rd 1, flush 0, corrupt 0, gen 0
Mar 23 13:10:01 server1 kernel: [  704.310874] ------------[ cut here ]------------
Mar 23 13:10:01 server1 kernel: [  704.310936] WARNING: CPU: 1 PID: 4706 at fs/btrfs/free-space-cache.c:1349 tree_insert_offset+0x7d/0xc3 [btrfs]()
Mar 23 13:10:01 server1 kernel: [  704.310989] Modules linked in: ipv6 cpufreq_stats cpufreq_powersave cpufreq_conservative btrfs xor raid6_pq zlib_deflate ext3 jbd loop 8250_fintek i2c_i801 parport_pc tpm_infineon tpm_tis tpm lpc_ich ehci_pci ehci_hcd mfd_core i2c_core parport pcspkr acpi_cpufreq button video ext4 crc16 jbd2 mbcache raid1 sg sd_mod ahci libahci libata scsi_mod r8169 mii
Mar 23 13:10:01 server1 kernel: [  704.312632] CPU: 1 PID: 4706 Comm: btrfs-transacti Not tainted 4.0.0-rc5 #1
Mar 23 13:10:01 server1 kernel: [  704.312680] Hardware name: System manufacturer System Product Name/P8H67-M PRO, BIOS 1106 10/17/2011
Mar 23 13:10:01 server1 kernel: [  704.312732]  0000000000000009 ffff880819917c18 ffffffff813c2f57 ffff88083fa4d801
Mar 23 13:10:01 server1 kernel: [  704.312928]  0000000000000000 ffff880819917c58 ffffffff8103b031 ffff880036eb9540
Mar 23 13:10:01 server1 kernel: [  704.313124]  ffffffffa03126f6 00000000ffffffef ffff880036eb9540 000001dd651b4000
Mar 23 13:10:01 server1 kernel: [  704.313321] Call Trace:
Mar 23 13:10:01 server1 kernel: [  704.313394]  [<ffffffff813c2f57>] dump_stack+0x45/0x57
Mar 23 13:10:01 server1 kernel: [  704.313469]  [<ffffffff8103b031>] warn_slowpath_common+0x97/0xb1
Mar 23 13:10:01 server1 kernel: [  704.313551]  [<ffffffffa03126f6>] ? tree_insert_offset+0x7d/0xc3 [btrfs]
Mar 23 13:10:01 server1 kernel: [  704.313627]  [<ffffffff8103b060>] warn_slowpath_null+0x15/0x17
Mar 23 13:10:01 server1 kernel: [  704.313707]  [<ffffffffa03126f6>] tree_insert_offset+0x7d/0xc3 [btrfs]
Mar 23 13:10:01 server1 kernel: [  704.313788]  [<ffffffffa0313142>] link_free_space+0x27/0x3c [btrfs]
Mar 23 13:10:01 server1 kernel: [  704.313868]  [<ffffffffa03143cb>] __btrfs_add_free_space+0x354/0x39d [btrfs]
Mar 23 13:10:01 server1 kernel: [  704.313952]  [<ffffffffa02f2864>] ? free_extent_state.part.29+0x34/0x39 [btrfs]
Mar 23 13:10:01 server1 kernel: [  704.314062]  [<ffffffffa02f2864>] ? free_extent_state.part.29+0x34/0x39 [btrfs]
Mar 23 13:10:01 server1 kernel: [  704.314170]  [<ffffffffa02c16b4>] ? block_group_cache_tree_search+0x8e/0xbd [btrfs]
Mar 23 13:10:01 server1 kernel: [  704.314279]  [<ffffffffa02c5518>] unpin_extent_range.isra.78+0xa6/0x199 [btrfs]
Mar 23 13:10:01 server1 kernel: [  704.314387]  [<ffffffffa02c9aa2>] btrfs_finish_extent_commit+0xcb/0xea [btrfs]
Mar 23 13:10:01 server1 kernel: [  704.314497]  [<ffffffffa02dbc57>] btrfs_commit_transaction+0x850/0x9e1 [btrfs]
Mar 23 13:10:01 server1 kernel: [  704.314606]  [<ffffffffa02d9bf0>] transaction_kthread+0xef/0x1c3 [btrfs]
Mar 23 13:10:01 server1 kernel: [  704.314687]  [<ffffffffa02d9b01>] ? open_ctree+0x1d47/0x1d47 [btrfs]
Mar 23 13:10:01 server1 kernel: [  704.314763]  [<ffffffff810501a3>] kthread+0xcd/0xd5
Mar 23 13:10:01 server1 kernel: [  704.314836]  [<ffffffff810500d6>] ? kthread_freezable_should_stop+0x43/0x43
Mar 23 13:10:01 server1 kernel: [  704.314913]  [<ffffffff813c7848>] ret_from_fork+0x58/0x90
Mar 23 13:10:01 server1 kernel: [  704.314987]  [<ffffffff810500d6>] ? kthread_freezable_should_stop+0x43/0x43
Mar 23 13:10:01 server1 kernel: [  704.315063] ---[ end trace 695f505b58a81c8d ]---
Mar 23 13:10:01 server1 kernel: [  704.315135] BTRFS: unable to add free space :-17
Mar 23 13:10:33 server1 kernel: [  736.510895] BTRFS: unable to add free space :-17
Mar 23 13:11:03 server1 kernel: [  765.780069] BTRFS: unable to add free space :-17
Mar 23 13:11:13 server1 kernel: [  776.030671] BTRFS: unable to add free space :-17
Mar 23 13:12:39 server1 kernel: [  861.791031] BTRFS: unable to add free space :-17
Mar 23 13:13:29 server1 kernel: [  911.761852] BTRFS: unable to add free space :-17
Mar 23 13:13:53 server1 kernel: [  936.124674] BTRFS: unable to add free space :-17

Tomasz Chmielewski
http://www.sslrack.com

Do you get this every time, even after going back to rc4?

It should be caused by this commit, but I really don't get how. I'll dig deeper, but if you can trigger this consistently I'd love to hear if reverting this commit helps.

commit ea526d18990018f224e5734748975bea1824545f

Author: Josef Bacik <[email protected]>
Date:   Fri Mar 13 16:40:45 2015 -0400

Btrfs: fix ASSERT(list_empty(&cur_trans->dirty_bgs_list)

To test things, you'll need to revert this one before the ASSERT fix:

commit dcdf7f6ddba006f3482ebee73dfa6b75aec5f07b

Author: Josef Bacik <[email protected]>
Date:   Mon Mar 2 16:37:31 2015 -0500

Btrfs: prepare block group cache before writing

Writing the block group cache will modify the extent tree quite a
bit because it
truncates the old space cache and pre-allocates new stuff. To try
and cut down
on the churn lets do the setup dance first, then later on hopefully
we can avoid
looping with newly dirtied roots. Thanks,

Actually, I didn't try yet (going back to 4.0.0-rc4).

Shortly after, it errored with:

[ 4450.519046] ------------[ cut here ]------------
[ 4450.519066] WARNING: CPU: 4 PID: 4734 at fs/btrfs/super.c:260 __btrfs_abort_transaction+0x4c/0x10e [btrfs]()
[ 4450.519081] BTRFS: Transaction aborted (error -17)
[ 4450.519082] Modules linked in: ipv6 cpufreq_stats cpufreq_powersave cpufreq_conservative btrfs xor raid6_pq zlib_deflate ext3 jbd loop tpm_infineon tpm_tis i2c_i801 parport_pc parport 8250_fintek lpc_ich pcspkr tpm video button acpi_cpufreq i2c_core mfd_core ehci_pci ehci_hcd ext4 crc16 jbd2 mbcache raid1 sg sd_mod ahci libahci libata scsi_mod r8169 mii
[ 4450.519157] CPU: 4 PID: 4734 Comm: kworker/u16:5 Not tainted 4.0.0-rc5 #1
[ 4450.519167] Hardware name: System manufacturer System Product Name/P8H67-M PRO, BIOS 1106 10/17/2011
[ 4450.519190] Workqueue: btrfs-extent-refs btrfs_extent_refs_helper [btrfs]
[ 4450.519201]  0000000000000009 ffff88074e0a7c58 ffffffff813c2f57 0000000000000000
[ 4450.519215]  ffff88074e0a7ca8 ffff88074e0a7c98 ffffffff8103b031 ffff8807b2638e68
[ 4450.519255]  ffffffffa02b6356 00000000ffffffef ffff88081bb7e000 ffff880701ba3210
[ 4450.519323] Call Trace:
[ 4450.519357]  [<ffffffff813c2f57>] dump_stack+0x45/0x57
[ 4450.519394]  [<ffffffff8103b031>] warn_slowpath_common+0x97/0xb1
[ 4450.519434]  [<ffffffffa02b6356>] ? __btrfs_abort_transaction+0x4c/0x10e [btrfs]
[ 4450.519501]  [<ffffffff8103b0df>] warn_slowpath_fmt+0x41/0x43
[ 4450.519540]  [<ffffffffa02b6356>] __btrfs_abort_transaction+0x4c/0x10e [btrfs]
[ 4450.519610]  [<ffffffffa02cd6d7>] btrfs_run_delayed_refs+0x90/0x21b [btrfs]
[ 4450.519653]  [<ffffffffa02cda60>] delayed_ref_async_start+0x37/0x76 [btrfs]
[ 4450.519699]  [<ffffffffa0302c67>] normal_work_helper+0xb5/0x16a [btrfs]
[ 4450.519742]  [<ffffffffa0302e28>] btrfs_extent_refs_helper+0xd/0xf [btrfs]
[ 4450.519782]  [<ffffffff8104c16d>] process_one_work+0x187/0x2b2
[ 4450.519819]  [<ffffffff8104c503>] worker_thread+0x241/0x33e
[ 4450.519856]  [<ffffffff8104c2c2>] ? process_scheduled_works+0x2a/0x2a
[ 4450.519894]  [<ffffffff810501a3>] kthread+0xcd/0xd5
[ 4450.519930]  [<ffffffff810500d6>] ? kthread_freezable_should_stop+0x43/0x43
[ 4450.519969]  [<ffffffff813c7848>] ret_from_fork+0x58/0x90
[ 4450.520005]  [<ffffffff810500d6>] ? kthread_freezable_should_stop+0x43/0x43
[ 4450.520044] ---[ end trace 1aff120928ea0fd5 ]---
[ 4450.520079] BTRFS: error (device sdb4) in btrfs_run_delayed_refs:2790: errno=-17 Object already exists
[ 4450.520148] BTRFS info (device sdb4): forced readonly
[ 4450.641829] BTRFS: error (device sdb4) in btrfs_run_delayed_refs:2790: errno=-17 Object already exists

After reboot to 4.0.0-rc5, I didn't see "unable to add free space :-17" anymore. However, it went again to "forced readonly" some time later.

I'll try going to 4.0.0-rc4 now.

Tomasz Chmielewski
http://www.sslrack.com

Do you have messages for the second time it was forced readonly?

-chris