X test that ZBlk objects can be actually removed from ZODB Connection cache and cause invalidation to be missed

____________________________________ test_bigfile_filezodb_vs_cache_invalidation ____________________________________

    def test_bigfile_filezodb_vs_cache_invalidation():
        root = dbopen()
        conn = root._p_jar
        db   = conn.db()
        conn.close()
        del root, conn

        tm1 = TransactionManager()
        tm2 = TransactionManager()

        conn1 = db.open(transaction_manager=tm1)
        root1 = conn1.root()

        # setup zfile with fileh view to it
        root1['zfile3'] = f1 = ZBigFile(blksize)
        tm1.commit()

        fh1 = f1.fileh_open()
        tm1.commit()

        # set zfile initial data
        vma1 = fh1.mmap(0, 1)
        Blk(vma1, 0)[0] = 1
        tm1.commit()

        # read zfile and setup fileh for it in conn2
        conn2 = db.open(transaction_manager=tm2)
        root2 = conn2.root()

        f2 = root2['zfile3']
        fh2 = f2.fileh_open()
        vma2 = fh2.mmap(0, 1)

        assert Blk(vma2, 0)[0] == 1 # read data in conn2 + make sure read correctly

        # now zfile content is both in ZODB.Connection cache and in _ZBigFileH
        # cache for each conn1 and conn2. Modify data in conn1 and make sure it
        # fully propagate to conn2.

        Blk(vma1, 0)[0] = 2
        tm1.commit()

        # still should be read as old value in conn2
        assert Blk(vma2, 0)[0] == 1
        # and even after virtmem pages reclaim
        # ( verifies that _p_invalidate() in ZBlk.loadblkdata() does not lead to
        #   reloading data as updated )
        ram_reclaim_all()
        assert Blk(vma2, 0)[0] == 1

        # FIXME: this simulates ZODB Connection cache pressure and currently
        # removes ZBlk corresponding to blk #0 from conn2 cache.
        # In turn this leads to conn2 missing that block invalidation on follow-up
        # transaction boundary.
        #
        # See FIXME notes on ZBlkBase._p_invalidate() for detailed description.
        conn2._cache.minimize()

        tm2.commit()                # transaction boundary for t2

        # data from tm1 should propagate -> ZODB -> ram pages for _ZBigFileH in conn2
>       assert Blk(vma2, 0)[0] == 2
E       assert 1 == 2

tests/test_filezodb.py:615: AssertionError

This one is less exotic compared to format changes rewrite.

We were checking for `loading.err != nil` as the indication for success
and it should have been `err == nil`. The symphoms of the bug were that
\0 instead of data were read sometimes:

	wcfs: 2018/10/11 19:18:12 < 22: i7.READ {Fh 0 [2097152 +131072)  L 0 RDONLY,0x8000}                             <-- NOTE

	I1011 19:18:12.556125    6330 wcfs.go:538] readBlk #1 dest[0:+2097152]
	I1011 19:18:12.556361    6330 wcfs.go:538] readBlk #1 dest[0:+2097152]
	wcfs: 2018/10/11 19:18:12 ZBlk0.PySetState #11
	wcfs: 2018/10/11 19:18:12 ZBigFile.loadblk(1) -> 2097152B

	wcfs: 2018/10/11 19:18:12 > 22:     OK,  131072B data "\x00\x00\x00\x00\x00\x00\x00\x00"...                     <-- XXX not "hello world"

	wcfs: 2018/10/11 19:18:12 < 24: i7.READ {Fh 0 [2359296 +131072)  L 0 RDONLY,0x8000}
	wcfs: 2018/10/11 19:18:12 > 23:     OK,  131072B data "\x00\x00\x00\x00\x00\x00\x00\x00"...
	wcfs: 2018/10/11 19:18:12 > 0:     NOTIFY_STORE_CACHE, {i7 [2097152 +2097152)} 2097152B data "hello wo"...      <-- NOTE

Else:

	wcfs: 2018/10/10 17:52:15 < 40: i7.READ {Fh 0 [4063232 +131072)  L 0 RDONLY,0x8000}
	wcfs: 2018/10/10 17:52:15 > 39:     OK,  131072B data
	wcfs: 2018/10/10 17:52:15 > 40:     OK,  131072B data
	wcfs: 2018/10/10 17:52:15 < 41: i7.GETATTR {Fh 0}
	wcfs: 2018/10/10 17:52:15 Response: INODE_NOTIFY_STORE_CACHE: OK
	wcfs: 2018/10/10 17:52:15 > 41:     OK, {tA=1s {M0100444 SZ=4194304 L=1 1000:1000 B0*0 i0:7 A 0.000000 M 1539183135.261177 C 1539183135.261177}}

	# XXX vvv why we store 2M after read @4M even though read gives len=0 ?
	wcfs: 2018/10/10 17:52:15 > 0:     NOTIFY_STORE_CACHE, {i7 [4194304 +2097152)} 2097152B data
	wcfs: 2018/10/10 17:52:15 < 42: i7.READ {Fh 0 [4194304 +4096)  L 0 RDONLY,0x8000}
	wcfs: 2018/10/10 17:52:15 > 42:     OK,

	wcfs: 2018/10/10 17:52:15 < 43: i7.GETATTR {Fh 0}
	wcfs: 2018/10/10 17:52:15 > 43:     OK, {tA=1s {M0100444 SZ=4194304 L=1 1000:1000 B0*0 i0:7 A 0.000000 M 1539183135.261177 C 1539183135.261177}}
	wcfs: 2018/10/10 17:52:15 Response: INODE_NOTIFY_STORE_CACHE: OK
	wcfs: 2018/10/10 17:52:15 < 44: i7.READ {Fh 0 [4198400 +4096)  L 0 RDONLY,0x8000}
	wcfs: 2018/10/10 17:52:15 > 44:     OK,

        data = readfile(fpath + "/head/data")
>       assert len(data) == fsize
E       AssertionError: assert 4198400 == 4194304

Got:

	[21871.340400] INFO: task wcfs:27933 blocked for more than 120 seconds.
	[21871.340414]       Not tainted 4.18.0-1-amd64 #1 Debian 4.18.6-1
	[21871.340420] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
	[21871.340427] wcfs            D    0 27933  27889 0x00000004
	[21871.340440] Call Trace:
	[21871.340463]  ? __schedule+0x2b7/0x880
	[21871.340476]  schedule+0x28/0x80
	[21871.340490]  io_schedule+0x12/0x40
	[21871.340506]  __lock_page+0x115/0x160
	[21871.340521]  ? page_cache_tree_insert+0xe0/0xe0
	[21871.340535]  pagecache_get_page+0x185/0x2a0
	[21871.340549]  ? ilookup5+0x45/0x90
	[21871.340572]  fuse_dev_do_write+0x3c8/0xee0 [fuse]
	[21871.340587]  ? futex_wait_queue_me+0xd3/0x120
	[21871.340604]  fuse_dev_write+0x4e/0x80 [fuse]
	[21871.340622]  do_iter_readv_writev+0x145/0x1a0
	[21871.340632]  do_iter_write+0x80/0x190
	[21871.340642]  vfs_writev+0x98/0x110
	[21871.340657]  ? new_sync_write+0x104/0x160
	[21871.340668]  ? do_writev+0x5e/0xf0
	[21871.340676]  do_writev+0x5e/0xf0
	[21871.340685]  ? ksys_write+0x76/0xc0
	[21871.340699]  do_syscall_64+0x55/0x110
	[21871.340714]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
	[21871.340725] RIP: 0033:0x478b70
	[21871.340730] Code: Bad RIP value.
	[21871.340752] RSP: 002b:000000c000149938 EFLAGS: 00000216 ORIG_RAX: 0000000000000014
	[21871.340763] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 0000000000478b70
	[21871.340770] RDX: 0000000000000002 RSI: 000000c00009e020 RDI: 0000000000000008
	[21871.340777] RBP: 000000c000149988 R08: 0000000000000000 R09: 0000000000000000
	[21871.340784] R10: 0000000000000000 R11: 0000000000000216 R12: 0000000000000004
	[21871.340790] R13: 0000000000000055 R14: 000000000068877a R15: 0000000000000038