AttributeError:'NoneType' has no attribute 'get'

[jamadden]

I see the following error using threads and concurrency=6 under Python 2.7/RS 2.1. So far I've only observed it with MySQL.

$ zodbshootout -c6 shootout.conf -n 100 --test-reps 200 --threads -s 256 --log
Testing mysql_hf with objects_per_txn=100, object_size=256, mappingtype=<class 'persistent.mapping.PersistentMapping'> and concurrency=6 (threads? shared)
  Running 1/3... add 0.0855s, update 0.0728s, warm 0.0272s, cold 0.4859s, hot 0.0327s, steamin 0.0025s
  Running 2/3... 2017-02-01 06:30:39,082 ERROR [zodbshootout.fork][123145485242368:40573][Thread-18] Failed to run <function write at 0x10f057e60>
Traceback (most recent call last):
  File "///src/zodbshootout/fork.py", line 73, in run
    res = self.func(self.param, self.sync)
  File "//src/zodbshootout/speedtest.py", line 274, in write
    return self.write_test(db_factory, n, sync)
  File "//src/zodbshootout/speedtest.py", line 165, in write_test
    do_add, self.individual_test_reps)
  File "//src/zodbshootout/speedtest.py", line 238, in _execute
    return func(*args)
  File "//src/zodbshootout/speedtest.py", line 144, in _times_of_runs
    run_times = [func(*args) for _ in range(times)]
  File "//src/zodbshootout/speedtest.py", line 156, in do_add
    m.update(self.data_to_store)
  File "//lib/python2.7/site-packages/persistent/mapping.py", line 72, in update
    self._p_changed = 1
  File "//lib/python2.7/site-packages/ZODB/Connection.py", line 821, in register
    self._register(obj)
  File "//lib/python2.7/site-packages/ZODB/Connection.py", line 831, in _register
    self.transaction_manager.get().join(self)
AttributeError: 'NoneType' object has no attribute 'get'

[jamadden]

Worse than the error, this causes the entire run to hang. ^C won't kill it and I have to resort to ^.

[jamadden]

This appears to be happening because the Connection has been closed. If I adjust the Connection.close method to del self.transaction_manager instead of self.tranasction_manager = None (which is what __init__ does) I can distinguish the two cases (because the class has a default value of ValueDoc). And then this error is raised as an AttributeError on ValueDoc.

But that doesn't make much sense, because do_add is explicitly opening a connection:

        def do_add():
            start = time.time()
            conn = db.open()
            root = conn.root()
            m = root['speedtest'][n]
            m.update(self.data_to_store)
            transaction.commit()
            conn.close()
            end = time.time()
            return end - start

So this suggests that db.openis returning a closed connection!?

[jamadden]

By the use of __setattr__ and a bunch of assertstatements in Connection, I've determined that this is happening because the same Connection object is being used by two threads! One thread closes the connection:

Set TM to None ConnID:4466175696 <Thread(Thread-22, started 123145465540608)>

...  File "//lib/python2.7/threading.py", line 754, in run
    self.__target(*self.__args, **self.__kwargs)
  File "//src/zodbshootout/fork.py", line 73, in run
    res = self.func(self.param, self.sync)
  File "//src/zodbshootout/speedtest.py", line 278, in read
    return self.read_test(db_factory, n, sync)
  File "//src/zodbshootout/speedtest.py", line 223, in read_test
    do_read, self.individual_test_reps, (True, True))
  File "//src/zodbshootout/speedtest.py", line 240, in _execute
    return func(*args)
  File "//src/zodbshootout/speedtest.py", line 144, in _times_of_runs
    run_times = [func(*args) for _ in range(times)]
  File "//src/zodbshootout/speedtest.py", line 213, in do_read
    conn.close()
  File "//lib/python2.7/site-packages/ZODB/Connection.py", line 326, in close
    self.transaction_manager = None
  File "//lib/python2.7/site-packages/ZODB/Connection.py", line 731, in __setattr__
    import traceback; traceback.print_stack()

Meanwhile, that same Connection is in use in a different thread. It's concurrently being open...this is the first of the many preceeding assert statements that fail. It fails in newTransaction because that method makes a call to the storage's poll_invalidations method, which in RelStorage's case is going to do RDBMs IO, and the mysqlclient apparently releases the GIL for that, allowing the other thread to run the close method.

Failed to run <function read at 0x10bf12ed8>
Traceback (most recent call last):
  File "//src/zodbshootout/fork.py", line 73, in run
    res = self.func(self.param, self.sync)
  File "//src/zodbshootout/speedtest.py", line 278, in read
    return self.read_test(db_factory, n, sync)
  File "//src/zodbshootout/speedtest.py", line 223, in read_test
    do_read, self.individual_test_reps, (True, True))
  File "//src/zodbshootout/speedtest.py", line 240, in _execute
    return func(*args)
  File "//src/zodbshootout/speedtest.py", line 144, in _times_of_runs
    run_times = [func(*args) for _ in range(times)]
  File "//src/zodbshootout/speedtest.py", line 198, in do_read
    self._clear_all_caches(db)
  File "//src/zodbshootout/speedtest.py", line 130, in _clear_all_caches
    conn = db.open()
  File "//site-packages/ZODB/DB.py", line 772, in open
    result.open(transaction_manager)
  File "//site-packages/ZODB/Connection.py", line 921, in open
    self.newTransaction(None, False)
  File "/site-packages/ZODB/Connection.py", line 741, in newTransaction
    assert self.transaction_manager is not None, (self.transaction_manager, id(self), threading.current_thread())
AssertionError: (None, 4466175696, <Thread(Thread-21, started 123145461334016)>)

So the current hypothesis is that DB.open and Connection.close don't manipulate the connection pool atomically with respect to Connection.transaction_manager.

[jamadden]

Yup, that's what's happening. There's even a comment in Connection.close() about this:

        if primary:
            for connection in self.connections.values():
                if connection is not self:
                    connection.close(False)

            # Return the connection to the pool.
            if self.opened is not None:
                self._db._returnToPool(self)

1>>          # _returnToPool() set self.opened to None.
                # However, we can't assert that here, because self may
                # have been reused (by another thread) by the time we
                # get back here.
        else:
            self.opened = None

        am = self._db._activity_monitor
        if am is not None:
            am.closedConnection(self)

        # Drop transaction manager to release resources and help prevent errors
2>>      self.transaction_manager = None

Note line 1, where we return the connection to the pool, making it available for re-use.

But there is code after that, notably line 2, that modifies the state of the current object, which may have already been reused!