NEO 1.10

* tag 'v1.10': (55 commits)
  Release version 1.10
  Maximize resiliency by taking into account the topology of storage nodes
  storage: also commit updated cell TID at each replicated chunk of 'obj' records
  storage: skip useless work when unlocking transactions
  qa: flush logs at the end of each test when -L is not used
  qa: add a log in case that a mysterious bug happens again
  storage: clarify log about data deletion of discarded cells
  debug: new example to run the profiler for 1 minute
  mysql: fix replication of big oids (> 16M)
  tests/cluster: speedup waiting a bit
  protocol: update packet docstrings
  Bump protocol version
  protocol: a single byte is more than enough to encode enums
  protocol: small cleanup in packet registration
  Optimize resumption of replication by starting from a greater TID
  importer: update comment about a workaround for ZODB3
  Micro-optimization of p64/u64
  qa: add a log in testBackupNodeLost for easier debugging
  Document that the bug when checking replicas may also cause the master to crash
  storage: stop logging 'Abort TXN' for txn that have been locked
  storage: split _migrate2() for reusable _alterTable()
  qa: new testStorageUpgrade
  qa: update testStorageUpgrade data for what is not automatically upgraded
  qa: original data for the future testStorageUpgrade
  sqlite: fix indexes of upgraded db
  importer: fix NameError when recovering during tpc_finish
  fixup! importer: fetch and process the data to import in a separate process
  Serialize empty transaction extension with an empty string
  client: fix partial import from a source storage
  qa: give a title to subprocesses of functional tests
  importer: give a title to the 'import' and 'writeback' subprocesses
  importer: fetch and process the data to import in a separate process
  importer: new option to write back new transactions to the source database
  importer: log when the transaction index for FileStorage DB is built
  importer: open imported zodb in read-only whenever possible
  fixup! mysql: fix remaining places where a server disconnection was not catched
  fixup! storage: speed up replication by sending bigger network packets
  mysql: do not full-scan for duplicates of big oids if deduplication is disabled
  mysql: fix remaining places where a server disconnection was not catched
  fixup! Add support for custom compression levels
  importer: reenable compression by default
  qa: review testImporter
  qa: remove a few uses of 'chr'
  Fix a few issues with ZODB5
  importer: small code cleanup in speedupFileStorageTxnLookup patch
  importer: do not trigger speedupFileStorageTxnLookup uselessly
  Add support for custom compression levels
  setup: update MANIFEST.in
  importer: do not checksum data twice
  client: store uncompressed if compressed size is equal
  fixup! master: automatically discard feeding cells that get out-of-date
  master: automatically discard feeding cells that get out-of-date
  qa: remove useless indentation in testSafeTweak
  bench: new option to mesure ZEO perfs in matrix test
  bench: reduce number of partitions in matrix test
  storage: fix replication of creation undone

ZEO4 does not have msgpack support and does not take $ZEO_MSGPACK into
account. With ZEO4 this test was failing before:

	--- FAIL: TestHandshake (0.46s)
	    --- FAIL: TestHandshake/py/msgpack=true (0.24s)
	        zeo_test.go:241: handshake: encoding=Z  ; want M

We don't have infrastructure to check python packages versions, so
check it by verifying ZEO.asyncio presence.

In that case at0 was initialized as 0 and still considered uninitialized
by flushEventq0:

    (neo) (z-dev) (g.env) kirr@deco:~/src/neo/src/lab.nexedi.com/kirr/neo/go/zodb/storage/zeo$ go test -run Empty
    ------
    2020-10-12T07:39:25 INFO ZEO.runzeo (146240) opening storage '1' using FileStorage
    ------
    2020-10-12T07:39:25 INFO ZEO.StorageServer StorageServer created RW with storages: 1:RW:/tmp/zeo905263273/1.fs
    ------
    2020-10-12T07:39:25 INFO ZEO.asyncio.server listening on /tmp/zeo905263273/1.fs.zeosock
    ------
    2020-10-12T07:39:25 INFO ZEO.asyncio.base Connected server protocol
    ------
    2020-10-12T07:39:25 INFO ZEO.asyncio.server received handshake 'Z5'
    2020/10/12 07:39:25 /tmp/zeo905263273/1.fs.zeosock: EOF
    --- FAIL: TestEmptyDB (0.22s)
        --- FAIL: TestEmptyDB/py/msgpack=false (0.22s)
    panic: flush, but .at0 not yet initialized [recovered]
            panic: flush, but .at0 not yet initialized

    goroutine 7 [running]:
    testing.tRunner.func1.1(0x644a60, 0x6e1a50)
            /home/kirr/src/tools/go/go/src/testing/testing.go:1072 +0x30d
    testing.tRunner.func1(0xc000001e00)
            /home/kirr/src/tools/go/go/src/testing/testing.go:1075 +0x41a
    panic(0x644a60, 0x6e1a50)
            /home/kirr/src/tools/go/go/src/runtime/panic.go:969 +0x175
    lab.nexedi.com/kirr/neo/go/zodb/storage/zeo.(*zeo).flushEventq0(0xc00018a000)
            /home/kirr/src/neo/src/lab.nexedi.com/kirr/neo/go/zodb/storage/zeo/zeo.go:180 +0xf3
    lab.nexedi.com/kirr/neo/go/zodb/storage/zeo.openByURL(0x6e9ca0, 0xc000016108, 0xc000138120, 0xc000153d98, 0x0, 0x0, 0x0, 0x0, 0x0)
            /home/kirr/src/neo/src/lab.nexedi.com/kirr/neo/go/zodb/storage/zeo/zeo.go:488 +0x5ba
    lab.nexedi.com/kirr/neo/go/zodb/storage/zeo.zeoOpen(0xc000018740, 0x1e, 0xc000049d98, 0x0, 0x0, 0x0, 0x0)
            /home/kirr/src/neo/src/lab.nexedi.com/kirr/neo/go/zodb/storage/zeo/zeo_test.go:285 +0x17b
    lab.nexedi.com/kirr/neo/go/zodb/storage/zeo.withZEO.func1(0xc000001e00, 0x6e9ea0, 0xc00005e6c0)
            /home/kirr/src/neo/src/lab.nexedi.com/kirr/neo/go/zodb/storage/zeo/zeo_test.go:219 +0xd0
    lab.nexedi.com/kirr/neo/go/zodb/storage/zeo.withZEOSrv.func2.1(0xc0000185c0, 0x16)
            /home/kirr/src/neo/src/lab.nexedi.com/kirr/neo/go/zodb/storage/zeo/zeo_test.go:205 +0xfb
    lab.nexedi.com/kirr/neo/go/zodb/storage/zeo.withZEOSrv.func1(0xc000001e00, 0xc00000e5a0)
            /home/kirr/src/neo/src/lab.nexedi.com/kirr/neo/go/zodb/storage/zeo/zeo_test.go:185 +0x129
    lab.nexedi.com/kirr/neo/go/zodb/storage/zeo.withZEOSrv.func2(0xc000001e00)
            /home/kirr/src/neo/src/lab.nexedi.com/kirr/neo/go/zodb/storage/zeo/zeo_test.go:197 +0x105
    testing.tRunner(0xc000001e00, 0xc00000e440)
            /home/kirr/src/tools/go/go/src/testing/testing.go:1123 +0xef
    created by testing.(*T).Run
            /home/kirr/src/tools/go/go/src/testing/testing.go:1168 +0x2b3
    exit status 2
    FAIL    lab.nexedi.com/kirr/neo/go/zodb/storage/zeo     0.227s

-> Fix it by using dedicated field marking whether .at0 was initialized or not yet.

For virtio NICs /sys/class/net/<NIC>/device lead to $pcidev/virtioX, not just $pcidev, e.g.:

	$ realpath /sys/class/net/ens3/device
	/sys/devices/pci0000:00/0000:00:03.0/virtio0

and we were extracting virtio0 instead of 0000:00:03.0 as PCI device identifier.

-> Fix it by recognizing and stripping /virtioX suffix.

For example under KVM it was failing as

    cpu:	Intel(R) Xeon(R) CPU E5-2678 v3 @ 2.50GHz
    cat: /sys/devices/system/cpu/cpu0/cpufreq/scaling_min_freq: No such file or directory
      File "<string>", line 1
        print '%.2fGHz' % ( / 1E6)
                            ^
    SyntaxError: invalid syntax

    $ lscpu
    Architecture:        x86_64
    CPU op-mode(s):      32-bit, 64-bit
    Byte Order:          Little Endian
    Address sizes:       40 bits physical, 48 bits virtual
    CPU(s):              40
    On-line CPU(s) list: 0-39
    Thread(s) per core:  1
    Core(s) per socket:  1
    Socket(s):           40
    NUMA node(s):        1
    Vendor ID:           GenuineIntel
    CPU family:          6
    Model:               63
    Model name:          Intel(R) Xeon(R) CPU E5-2678 v3 @ 2.50GHz
    Stepping:            2
    CPU MHz:             2494.238
    BogoMIPS:            4988.47
    Virtualization:      VT-x
    Hypervisor vendor:   KVM
    Virtualization type: full
    L1d cache:           32K
    L1i cache:           32K
    L2 cache:            4096K
    L3 cache:            16384K
    NUMA node0 CPU(s):   0-39
    Flags:               fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush mmx fxsr sse sse2 ss syscall nx pdpe1gb rdtscp lm constant_tsc arch_perfmon rep_good nopl xtopology cpuid tsc_known_freq pni pclmulqdq vmx ssse3 fma cx16 pcid sse4_1 sse4_2 x2apic movbe popcnt tsc_deadline_timer aes xsave avx f16c rdrand hypervisor lahf_lm abm invpcid_single pti tpr_shadow vnmi flexpriority ept vpid fsgsbase tsc_adjust bmi1 avx2 smep bmi2 erms invpcid xsaveopt arat

-> Fix it by checking whether cpufreq/cpuidle directories are available, and display "?" if they are not.

Starting from Go1.14 defer is no longer slow:
https://golang.org/doc/go1.14#runtime

Starting from Go1.14 defer is no longer slow:
https://golang.org/doc/go1.14#runtime

This turns zeo tests to pass.
The bug is reported upstream here: https://github.com/zopefoundation/ZODB/issues/318

If xres fails to convert to tuple, we should error about xres, not res
which is always tuple(nil).

Receive invalidation from server and send corresponding events to watchq.
Care to send only events with tid > at0 that we initially returned when opening.

Tests pass, but they need https://github.com/zopefoundation/ZEO/pull/160

This will be used in the next patch to handle invalidateTransaction
messages.

ZEO5 adds way for messages to be encoded via either pickles or MessagePack.
However until now we were always using pickles.
Let's add msgpack support to be able to e.g. use wire encoding that
server prefers.

MsgPack support is almost fully localized in encoding.
We use tinylib/msgp runtime routines to decode/encode msg fields with known types,
and shamaton/msgpack to decode/encode msg.arg, which is interface{},
because msgp does not generally work for arbitrary reflections.

For msgpack=true, tests state is the same as with pickles: handshake
works, but load fails when verifying that Load returns correct error for
deleted object:

    TestLoad/py/msgpack=false: xtesting.go:272: load 0285cbacc06d3a4c:0000000000000007: returned err unexpected:
        have: /tmp/zeo170183943/1.fs.zeosock: load 0285cbacc06d3a4c:0000000000000007: 0000000000000007: no such object
        want: /tmp/zeo170183943/1.fs.zeosock: load 0285cbacc06d3a4c:0000000000000007: 0000000000000007: object was deleted @0285cbacc06d3a4c
    TestLoad/py/msgpack=false: xtesting.go:272: load 0285cbad858bf2e6:0000000000000006: returned err unexpected:
        have: /tmp/zeo170183943/1.fs.zeosock: load 0285cbad858bf2e6:0000000000000006: 0000000000000006: no such object
        want: /tmp/zeo170183943/1.fs.zeosock: load 0285cbad858bf2e6:0000000000000006: 0000000000000006: object was deleted @0285cbad858bf2e6
    TestLoad/py/msgpack=false: xtesting.go:290: load 7fffffffffffffff:0000000000000007: returned err unexpected:
        have: /tmp/zeo170183943/1.fs.zeosock: load 7fffffffffffffff:0000000000000007: 0000000000000007: no such object
        want: /tmp/zeo170183943/1.fs.zeosock: load 7fffffffffffffff:0000000000000007: 0000000000000007: object was deleted @0285cbacc06d3a4c
    TestLoad/py/msgpack=false: xtesting.go:290: load 7fffffffffffffff:0000000000000006: returned err unexpected:
        have: /tmp/zeo170183943/1.fs.zeosock: load 7fffffffffffffff:0000000000000006: 0000000000000006: no such object
        want: /tmp/zeo170183943/1.fs.zeosock: load 7fffffffffffffff:0000000000000006: 0000000000000006: object was deleted @0285cbad858bf2e6

    TestLoad/py/msgpack=true: xtesting.go:272: load 0285cbacc06d3a4c:0000000000000007: returned err unexpected:
        have: /tmp/zeo247652538/1.fs.zeosock: load 0285cbacc06d3a4c:0000000000000007: 0000000000000007: no such object
        want: /tmp/zeo247652538/1.fs.zeosock: load 0285cbacc06d3a4c:0000000000000007: 0000000000000007: object was deleted @0285cbacc06d3a4c
    TestLoad/py/msgpack=true: xtesting.go:272: load 0285cbad858bf2e6:0000000000000006: returned err unexpected:
        have: /tmp/zeo247652538/1.fs.zeosock: load 0285cbad858bf2e6:0000000000000006: 0000000000000006: no such object
        want: /tmp/zeo247652538/1.fs.zeosock: load 0285cbad858bf2e6:0000000000000006: 0000000000000006: object was deleted @0285cbad858bf2e6
    TestLoad/py/msgpack=true: xtesting.go:290: load 7fffffffffffffff:0000000000000007: returned err unexpected:
        have: /tmp/zeo247652538/1.fs.zeosock: load 7fffffffffffffff:0000000000000007: 0000000000000007: no such object
        want: /tmp/zeo247652538/1.fs.zeosock: load 7fffffffffffffff:0000000000000007: 0000000000000007: object was deleted @0285cbacc06d3a4c
    TestLoad/py/msgpack=true: xtesting.go:290: load 7fffffffffffffff:0000000000000006: returned err unexpected:
        have: /tmp/zeo247652538/1.fs.zeosock: load 7fffffffffffffff:0000000000000006: 0000000000000006: no such object
        want: /tmp/zeo247652538/1.fs.zeosock: load 7fffffffffffffff:0000000000000006: 0000000000000006: object was deleted @0285cbad858bf2e6

This is due to https://github.com/zopefoundation/ZODB/issues/318

It is already documented in pktDecodeZ comment that flags is int|bool.
However until now we were decoding it only as int.

As is it was working, but it will fail when receiving e.g.
invalidateTransaction message, because ZEO/py server actually uses bool
when sending it:

    https://github.com/zopefoundation/ZEO/blob/5.2.1-20-gcb26281d/src/ZEO/asyncio/base.py#L139

Fix it.
This will be covered by watch tests, when watch support will be added in a followup patch.

Handle pickled lists as valid input when decoding tuples.

This is more uniform and will be followed by all data types in the next patch.
Here rename tid/oid pack/unpack routines correspondingly.
Add docstrings for X=tid|oid.

Keep information about which message encoding is used on the wire in
encoding type. Make pktDecode/pktEncode and data type conversion
utilities be methods of this type. For now there is only 'pickles'
encoding, but we'll soon introduce 'msgpack'.

Currently not everything related to pickles is localized in encoding -
we'll be moving more bits to encoding in the followup patches.

First step:

- move msg and msgFlags
- move pktDecode
- move functions to pack/unpack tid and oid

more to come.

The same behaviour as ZEO/py does.

Just renaming.

Starting from Go1.14 defer is no longer slow:
https://golang.org/doc/go1.14#runtime

See go123@515a6d14

As promised in b65f6d0f (go/zodb: Teach ZODB/go to access ZEO (draft))
let's start to add tests for ZEO/go client.

The client is tested against ZEO/py server.
Cover handshake and Load.

Load currently fails beause in ZODB/py POSKeyError does not allow to
distinguish whether it is no object at all or object exists and its data
was not found for tid_before.

    --- FAIL: TestLoad/py (0.22s)
        zeo_test.go:217: load 0285cbacc06d3a4c:0000000000000007: returned err unexpected:
            have: /tmp/zeo273044293/1.fs.zeosock: load 0285cbacc06d3a4c:0000000000000007: 0000000000000007: no such object
            want: /tmp/zeo273044293/1.fs.zeosock: load 0285cbacc06d3a4c:0000000000000007: 0000000000000007: object was deleted @0285cbacc06d3a4c
        zeo_test.go:217: load 0285cbad858bf2e6:0000000000000006: returned err unexpected:
            have: /tmp/zeo273044293/1.fs.zeosock: load 0285cbad858bf2e6:0000000000000006: 0000000000000006: no such object
            want: /tmp/zeo273044293/1.fs.zeosock: load 0285cbad858bf2e6:0000000000000006: 0000000000000006: object was deleted @0285cbad858bf2e6
        zeo_test.go:217: load 7fffffffffffffff:0000000000000006: returned err unexpected:
            have: /tmp/zeo273044293/1.fs.zeosock: load 7fffffffffffffff:0000000000000006: 0000000000000006: no such object
            want: /tmp/zeo273044293/1.fs.zeosock: load 7fffffffffffffff:0000000000000006: 0000000000000006: object was deleted @0285cbad858bf2e6
        zeo_test.go:217: load 7fffffffffffffff:0000000000000007: returned err unexpected:
            have: /tmp/zeo273044293/1.fs.zeosock: load 7fffffffffffffff:0000000000000007: 0000000000000007: no such object
            want: /tmp/zeo273044293/1.fs.zeosock: load 7fffffffffffffff:0000000000000007: 0000000000000007: object was deleted @0285cbacc06d3a4c

Problem reported upstream:

-> https://github.com/zopefoundation/ZODB/issues/318

No need to use trailing : suffix as xerr.Contextf automatically adds one.

This is utility to load whole content of a ZODB database.

It will be useful to load data to expect from e.g. dataok.fs and feed it
as txnvOk to DrvTestLoad when verifying another storage driver.

This is utility to create X function, similar to exc.Raisif, but that
would call t.Fatal instead.

We will soon need this infrastructure to test other storage drivers.

E.g. before:

    --- FAIL: TestLoad/py (0.22s)
        zeo_test.go:217: load 0285cbacc06d3a4c:0000000000000007: returned err unexpected: /tmp/zeo484021674/1.fs.zeosock: load 0285cbacc06d3a4c:0000000000000007: 0000000000000007: no such object  ; want: /tmp/zeo484021674/1.fs.zeosock: load 0285cbacc06d3a4c:0000000000000007: 0000000000000007: object was deleted @0285cbacc06d3a4c
        zeo_test.go:217: load 0285cbad858bf2e6:0000000000000006: returned err unexpected: /tmp/zeo484021674/1.fs.zeosock: load 0285cbad858bf2e6:0000000000000006: 0000000000000006: no such object  ; want: /tmp/zeo484021674/1.fs.zeosock: load 0285cbad858bf2e6:0000000000000006: 0000000000000006: object was deleted @0285cbad858bf2e6
        zeo_test.go:217: load 7fffffffffffffff:0000000000000006: returned err unexpected: /tmp/zeo484021674/1.fs.zeosock: load 7fffffffffffffff:0000000000000006: 0000000000000006: no such object  ; want: /tmp/zeo484021674/1.fs.zeosock: load 7fffffffffffffff:0000000000000006: 0000000000000006: object was deleted @0285cbad858bf2e6
        zeo_test.go:217: load 7fffffffffffffff:0000000000000007: returned err unexpected: /tmp/zeo484021674/1.fs.zeosock: load 7fffffffffffffff:0000000000000007: 0000000000000007: no such object  ; want: /tmp/zeo484021674/1.fs.zeosock: load 7fffffffffffffff:0000000000000007: 0000000000000007: object was deleted @0285cbacc06d3a4c

After:

    --- FAIL: TestLoad/py (0.22s)
        zeo_test.go:217: load 0285cbacc06d3a4c:0000000000000007: returned err unexpected:
            have: /tmp/zeo087978981/1.fs.zeosock: load 0285cbacc06d3a4c:0000000000000007: 0000000000000007: no such object
            want: /tmp/zeo087978981/1.fs.zeosock: load 0285cbacc06d3a4c:0000000000000007: 0000000000000007: object was deleted @0285cbacc06d3a4c
        zeo_test.go:217: load 0285cbad858bf2e6:0000000000000006: returned err unexpected:
            have: /tmp/zeo087978981/1.fs.zeosock: load 0285cbad858bf2e6:0000000000000006: 0000000000000006: no such object
            want: /tmp/zeo087978981/1.fs.zeosock: load 0285cbad858bf2e6:0000000000000006: 0000000000000006: object was deleted @0285cbad858bf2e6
        zeo_test.go:217: load 7fffffffffffffff:0000000000000007: returned err unexpected:
            have: /tmp/zeo087978981/1.fs.zeosock: load 7fffffffffffffff:0000000000000007: 0000000000000007: no such object
            want: /tmp/zeo087978981/1.fs.zeosock: load 7fffffffffffffff:0000000000000007: 0000000000000007: object was deleted @0285cbacc06d3a4c
        zeo_test.go:217: load 7fffffffffffffff:0000000000000006: returned err unexpected:
            have: /tmp/zeo087978981/1.fs.zeosock: load 7fffffffffffffff:0000000000000006: 0000000000000006: no such object
            want: /tmp/zeo087978981/1.fs.zeosock: load 7fffffffffffffff:0000000000000006: 0000000000000006: object was deleted @0285cbad858bf2e6

We will soon need this infrastructure to test other storage drivers.

This package already provides parts of infrastructure for ZODB testing
(see e.g. 46636b16 and 7f14e2cb), and will be used as the place for such
infrastructure.

Maybe in the future we'll rename it to something like ztesting, but
leaving package name as is for now.

See go123@515a6d14

See go123@515a6d14

Provide way for users to retrieve Connection -> DB from which it was opened.
Wendelin.core 2 might need this to open a second connection given a one.

Provide way for users to go from DB -> IStorage for which it was opened.
Wendelin.core 2 needs it.

Implement "TODO defer stor.Close()" that was sitting there in every subcommand.

Julien Muchembled notices that strictly speaking Head could return tid
that it receives during its call, not strictly as observed before the
call. In other words for which range might be returned it is like below:

           ...\\\\\\\\\\\↓      ↓////////////...
        ──────────────────────────────────────────
               <head call>      <sync call>

Fixes 151d8b79 (go/zodb: LastTid -> Sync + Head).

[1] https://github.com/zopefoundation/ZODB/pull/307#discussion_r436881665

This helps when events are printed and logged.