check7ZODBThreads -> failed with InvalidObjectReference

[navytux]

CI on current master (8a7e3162) failed on windows-py38-pure with:

Error in test check7ZODBThreads (ZODB.tests.testFileStorage.FileStorageTests)
Traceback (most recent call last):
  File "c:\hostedtoolcache\windows\python\3.8.10\x64\lib\unittest\case.py", line 60, in testPartExecutor
    yield
  File "c:\hostedtoolcache\windows\python\3.8.10\x64\lib\unittest\case.py", line 676, in run
    self._callTestMethod(testMethod)
  File "c:\hostedtoolcache\windows\python\3.8.10\x64\lib\unittest\case.py", line 633, in _callTestMethod
    method()
  File "D:\a\ZODB\ZODB\src\ZODB\tests\MTStorage.py", line 241, in check7ZODBThreads
    self._checkNThreads(7, ZODBClientThread, db, self)
  File "D:\a\ZODB\ZODB\src\ZODB\tests\MTStorage.py", line 229, in _checkNThreads
    t.join(60)
  File "D:\a\ZODB\ZODB\src\ZODB\tests\MTStorage.py", line 47, in join
    raise six.reraise(
  File "D:\a\ZODB\ZODB\.tox\py38-pure\lib\site-packages\six.py", line 719, in reraise
    raise value
  File "D:\a\ZODB\ZODB\src\ZODB\tests\MTStorage.py", line 40, in run
    self.runtest()
  File "D:\a\ZODB\ZODB\src\ZODB\tests\MTStorage.py", line 67, in runtest
    d = self.get_thread_dict(root)
  File "D:\a\ZODB\ZODB\src\ZODB\tests\MTStorage.py", line 99, in get_thread_dict
    transaction.commit()
  File "D:\a\ZODB\ZODB\.tox\py38-pure\lib\site-packages\transaction\_manager.py", line 257, in commit
    return self.manager.commit()
  File "D:\a\ZODB\ZODB\.tox\py38-pure\lib\site-packages\transaction\_manager.py", line 134, in commit
    return self.get().commit()
  File "D:\a\ZODB\ZODB\.tox\py38-pure\lib\site-packages\transaction\_transaction.py", line 283, in commit
    reraise(t, v, tb)
  File "D:\a\ZODB\ZODB\.tox\py38-pure\lib\site-packages\transaction\_compat.py", line 50, in reraise
    raise value
  File "D:\a\ZODB\ZODB\.tox\py38-pure\lib\site-packages\transaction\_transaction.py", line 274, in commit
    self._commitResources()
  File "D:\a\ZODB\ZODB\.tox\py38-pure\lib\site-packages\transaction\_transaction.py", line 457, in _commitResources
    reraise(t, v, tb)
  File "D:\a\ZODB\ZODB\.tox\py38-pure\lib\site-packages\transaction\_compat.py", line 50, in reraise
    raise value
  File "D:\a\ZODB\ZODB\.tox\py38-pure\lib\site-packages\transaction\_transaction.py", line 431, in _commitResources
    rm.commit(self)
  File "D:\a\ZODB\ZODB\src\ZODB\Connection.py", line 498, in commit
    self._commit(transaction)
  File "D:\a\ZODB\ZODB\src\ZODB\Connection.py", line 545, in _commit
    self._store_objects(ObjectWriter(obj), transaction)
  File "D:\a\ZODB\ZODB\src\ZODB\Connection.py", line 576, in _store_objects
    p = writer.serialize(obj)  # This calls __getstate__ of obj
  File "D:\a\ZODB\ZODB\src\ZODB\serialize.py", line 434, in serialize
    return self._dump(meta, obj.__getstate__())
  File "D:\a\ZODB\ZODB\src\ZODB\serialize.py", line 443, in _dump
    self._p.dump(state)
  File "D:\a\ZODB\ZODB\src\ZODB\serialize.py", line 367, in persistent_id
    raise InvalidObjectReference(
ZODB.POSException.InvalidObjectReference: <unprintable InvalidObjectReference object>

@d-maurer, do you maybe have an idea about what is going on?

P.S.

Exception in thread T0:
Traceback (most recent call last):
  File "c:\hostedtoolcache\windows\python\3.8.10\x64\lib\threading.py", line 932, in _bootstrap_inner
    self.run()
  File "c:\hostedtoolcache\windows\python\3.8.10\x64\lib\threading.py", line 870, in run
    self._target(*self._args, **self._kwargs)
  File "D:\a\ZODB\ZODB\src\ZODB\tests\racetest.py", line 5[27](https://github.com/zopefoundation/ZODB/actions/runs/5067242751/jobs/9098062772#step:6:28), in _run
    f(self, tx, *argv, **kw)
  File "D:\a\ZODB\ZODB\src\ZODB\tests\test_racetest.py", line 103, in tg_test_function
    raise ValueError(str(tx))
ValueError: 0

that comes before that is "ok" and is expectedly generated by test_racetest.py:test_exception added in 48315c67. Though it might be good to remove that traceback from test output to avoid confusing people when they try to check what is going on in a test failure.

[d-maurer]

Kirill Smelkov wrote at 2023-5-24 03:29 -0700:

... Error in test check7ZODBThreads (ZODB.tests.testFileStorage.FileStorageTests) Traceback (most recent call last): ... File "D:\a\ZODB\ZODB\src\ZODB\serialize.py", line 367, in persistent_id raise InvalidObjectReference( ZODB.POSException.InvalidObjectReference:

@d-maurer, do you maybe have an idea about what is going on?

The code at the exception location: if self._jar.get_connection(database_name) is not obj._p_jar: raise InvalidObjectReference( "Attempt to store a reference to an object from " "a separate connection to the same database or " "multidatabase", self._jar, obj, )

The context: We are serializing an object "obj0"; its connection is self._jar. obj is a subobject of "obj0" for which we want to check whether it has a persistent id. We have obj._p_jar is not self._jar, i.e. obj and "obj0" have different connections. The exception is raised because even though obj and "obj0" belong to the same database, they have different connections.

The test has only a single object which could be "obj0": the root object. obj is the (new) PersistentMapping assigned to root[name] in ZODBClientThread.get_thread_dict.

The test thread uses a single connection. Thus, there should be no reason that "obj0" (i.e. the root object) and obj (i.e. the new PersistentMapping) should get different connections.

The test is likely to cause many conflicts. One hypothesis was that the connection fails to properly clean up its attributes related to the creation of new objects (_added, _creating, _cache) in case of conflicts (and that this might explain the error). However, I could not detect hints supporting the hypothesis.

[navytux]

Thanks, Dieter. I read your explanations and too looked a bit at that code, and after quick inspection could not see how it could be breaking. But at least I've come with one small improvement so that next time instead of <unprintable InvalidObjectReference object> we see a bit more informative error message: https://github.com/zopefoundation/ZODB/pull/384.

[navytux]

I'm not sure it is related, but now ubuntu-py38-pure failed with "FAIL code -11" which means that python interpreted got segmentation fault.

it is somehow suspicious that in both cases it was py38 and "pure" kind of tests.

[navytux]

And check_race_loadopen_vs_local_invalidate "test did not finish within 120 seconds": https://github.com/zopefoundation/ZODB/actions/runs/5091513834/jobs/9151633676 . It seems we need to increase timeout there once again as we already did in ca41ccd1.

[navytux]

(the timeout is again about py38)