search

zodb / relstorage

A backend for ZODB that stores pickles in a relational database.
Other
54 stars 46 forks source link

zodbconvert broken in 3.4.0 #435

Closed frapell closed 1 year ago

frapell commented 3 years ago

Using zodbconvert to clone a mysql db fails with RelStorage 3.4.0

$ ./bin/zodbconvert clone.conf --clear                                                                                                                       
2021-01-19 16:40:58,429 [relstorage.blobhelper.cached] INFO   Spawning cache checker for /opt/plone/var/instance/blobcache (creating storage)                                         
2021-01-19 16:40:58,436 [relstorage.blobhelper.cached] INFO   Checking blob cache size for /opt/plone/var/instance/blobcache. (target: 72.00 MB)                                      
2021-01-19 16:40:58,438 [relstorage.blobhelper.cached] INFO   Traversed /opt/plone/var/instance/blobcache to compute size 0 KB (<= 72.00 MB); quitting.                               
2021-01-19 16:40:58,438 [relstorage.blobhelper.cached] INFO   Finished checking /opt/plone/var/instance/blobcache (in 0.000s) with size of 0 KB (max: 80.00 MB; target 72.00 MB)      
2021-01-19 16:40:58,447 [relstorage.blobhelper.cached] INFO   Spawning cache checker for /opt/plone/var/instance/blobcache2 (creating storage)                                        
2021-01-19 16:40:58,452 [relstorage.blobhelper.cached] INFO   Checking blob cache size for /opt/plone/var/instance/blobcache2. (target: 72.00 MB)                                     
2021-01-19 16:40:58,453 [zodbconvert] INFO   Storages opened successfully.                                                                                                            
2021-01-19 16:40:58,453 [zodbconvert] INFO   Clearing old data...                                                                                                                     
2021-01-19 16:40:58,454 [relstorage.blobhelper.cached] INFO   Traversed /opt/plone/var/instance/blobcache2 to compute size 0 KB (<= 72.00 MB); quitting.                              
2021-01-19 16:40:58,454 [relstorage.blobhelper.cached] INFO   Finished checking /opt/plone/var/instance/blobcache2 (in 0.000s) with size of 0 KB (max: 80.00 MB; target 72.00 MB)     
2021-01-19 16:41:00,209 [zodbconvert] INFO   Done clearing old data.                                                                                                                  
2021-01-19 16:41:00,213 [relstorage.storage.copy] INFO   Copying transactions to <RelStorage at 0x7f3a0b2beed0 keep_history=False phase=<relstorage.storage.tpc.NotInTransaction objec
t at 0x7f3a0bb3caf0> blobhelper=<CacheBlobHelper at 0x7f3a0bb00f10 blob_dir='/opt/plone/var/instance/blobcache2' txn_blobs=None> cache=<StorageCache at 0x7f3a0b2c70d0 hvt=None bytes=248 len=0 state=<relstorage.cache.mvcc.MVCCDatabaseCoordinator object at 0x7f3a0b2befd0>>> from <RelStorage at 0x7f3a0cab1550 keep_history=False phase=<relstorage.storage.tpc.NotInT$ansaction object at 0x7f3a0bb2ce60> blobhelper=<CacheBlobHelper at 0x7f3a0bb2e410 blob_dir='/opt/plone/var/instance/blobcache' txn_blobs=None> cache=<StorageCache at 0x7f3a0bb0bed0 $vt=None bytes=248 len=0 state=<relstorage.cache.mvcc.MVCCDatabaseCoordinator object at 0x7f3a0bb00fd0>>> (supports IStorageCurrentRecordIteration? True) using <class 'relstorage.sto$age.copy._HistoryFreeCopier'>
2021-01-19 16:41:00,214 [relstorage.storage.copy] INFO   Counting the objects to copy.
2021-01-19 16:41:00,232 [relstorage.storage.copy] INFO   Copying 25992 objects. CAUTION: This number is approximate.
Traceback (most recent call last):
  File "./bin/zodbconvert", line 346, in <module>
    sys.exit(relstorage.zodbconvert.main())
  File "/opt/plone/eggs/RelStorage-3.4.0-py2.7-linux-x86_64.egg/relstorage/zodbconvert.py", line 221, in main
    destination.copyTransactionsFrom(source)
  File "/opt/plone/eggs/RelStorage-3.4.0-py2.7-linux-x86_64.egg/relstorage/storage/__init__.py", line 903, in copyTransactionsFrom
    Copy(self.blobhelper, self, self).copyTransactionsFrom(other)
  File "/opt/plone/eggs/RelStorage-3.4.0-py2.7-linux-x86_64.egg/relstorage/storage/copy.py", line 89, in copyTransactionsFrom
    copier.copy(progress)
  File "/opt/plone/eggs/RelStorage-3.4.0-py2.7-linux-x86_64.egg/relstorage/storage/copy.py", line 384, in copy
    state
  File "/opt/plone/eggs/RelStorage-3.4.0-py2.7-linux-x86_64.egg/relstorage/storage/copy.py", line 177, in restore_one
    oid, tid)
  File "src/perfmetrics/metric.py", line 72, in perfmetrics._metric._AbstractMetricImpl.__call__
  File "/opt/plone/eggs/RelStorage-3.4.0-py2.7-linux-x86_64.egg/relstorage/storage/load.py", line 308, in openCommittedBlobFile
    cursor, oid, serial, blob=blob)
  File "/opt/plone/eggs/RelStorage-3.4.0-py2.7-linux-x86_64.egg/relstorage/blobhelper/abstract.py", line 151, in openCommittedBlobFile
    return self._openCommittedBlobFileInternal(cursor, oid, serial, blob, blob_lock)
  File "/opt/plone/eggs/RelStorage-3.4.0-py2.7-linux-x86_64.egg/relstorage/blobhelper/abstract.py", line 124, in _openCommittedBlobFileInternal
    blob_filename = self._loadBlobInternal(cursor, oid, serial, open_lock)
  File "/opt/plone/eggs/RelStorage-3.4.0-py2.7-linux-x86_64.egg/relstorage/blobhelper/cached.py", line 321, in _loadBlobInternal
    blob_filename = self._loadBlobLocked(cursor, oid, serial, blob_filename)
  File "/opt/plone/eggs/RelStorage-3.4.0-py2.7-linux-x86_64.egg/relstorage/blobhelper/cached.py", line 345, in _loadBlobLocked
    self.download_blob(cursor, oid, serial, blob_filename)
  File "/opt/plone/eggs/RelStorage-3.4.0-py2.7-linux-x86_64.egg/relstorage/blobhelper/cached.py", line 368, in download_blob
    cursor, bytes8_to_int64(oid), bytes8_to_int64(serial), tmp_fn)
  File "src/perfmetrics/metric.py", line 66, in perfmetrics._metric._AbstractMetricImpl.__call__
  File "/opt/plone/eggs/RelStorage-3.4.0-py2.7-linux-x86_64.egg/relstorage/adapters/mover.py", line 566, in download_blob
    cursor.execute(stmt, (oid, tid, chunk_num))
  File "/opt/plone/eggs/mysqlclient-1.4.6-py2.7-linux-x86_64.egg/MySQLdb/cursors.py", line 186, in execute
    while self.nextset():
  File "/opt/plone/eggs/mysqlclient-1.4.6-py2.7-linux-x86_64.egg/MySQLdb/cursors.py", line 139, in nextset
    nr = db.next_result()
MySQLdb._exceptions.ProgrammingError: (2014, "Commands out of sync; you can't run this command now")

It works fine in 3.3.2

$ ./bin/zodbconvert clone.conf --clear                                                                                                                       
2021-01-19 16:42:31,274 [ZODB.blob] INFO (17113) Blob directory '/opt/plone/var/instance/blobcache/' does not exist. Created new directory.                                           
2021-01-19 16:42:31,274 [ZODB.blob] INFO (17113) Blob temporary directory '/opt/plone/var/instance/blobcache/tmp' does not exist. Created new directory.                              
2021-01-19 16:42:31,274 [relstorage.blobhelper.cached] INFO Spawning cache checker for /opt/plone/var/instance/blobcache (creating storage)
2021-01-19 16:42:31,281 [relstorage.blobhelper.cached] INFO Checking blob cache size for /opt/plone/var/instance/blobcache. (target: 72.00 MB)
2021-01-19 16:42:31,283 [relstorage.blobhelper.cached] INFO Traversed /opt/plone/var/instance/blobcache to compute size 0 KB (<= 72.00 MB); quitting.
2021-01-19 16:42:31,286 [relstorage.blobhelper.cached] INFO Finished checking /opt/plone/var/instance/blobcache (in 0.000s) with size of 0 KB (max: 80.00 MB; target 72.00 MB)
2021-01-19 16:42:31,292 [ZODB.blob] INFO (17113) Blob directory '/opt/plone/var/instance/blobcache2/' does not exist. Created new directory.
2021-01-19 16:42:31,292 [ZODB.blob] INFO (17113) Blob temporary directory '/opt/plone/var/instance/blobcache2/tmp' does not exist. Created new directory.
2021-01-19 16:42:31,292 [relstorage.blobhelper.cached] INFO Spawning cache checker for /opt/plone/var/instance/blobcache2 (creating storage)
2021-01-19 16:42:31,297 [relstorage.blobhelper.cached] INFO Checking blob cache size for /opt/plone/var/instance/blobcache2. (target: 72.00 MB)
2021-01-19 16:42:31,297 [zodbconvert] INFO Storages opened successfully.
2021-01-19 16:42:31,298 [zodbconvert] INFO Clearing old data...
2021-01-19 16:42:31,298 [relstorage.blobhelper.cached] INFO Traversed /opt/plone/var/instance/blobcache2 to compute size 0 KB (<= 72.00 MB); quitting.
2021-01-19 16:42:31,298 [relstorage.blobhelper.cached] INFO Finished checking /opt/plone/var/instance/blobcache2 (in 0.000s) with size of 0 KB (max: 80.00 MB; target 72.00 MB)
2021-01-19 16:42:33,117 [zodbconvert] INFO Done clearing old data.
2021-01-19 16:42:33,121 [relstorage.storage.copy] INFO Counting the transactions to copy.
2021-01-19 16:42:33,131 [relstorage.storage.copy] INFO Copying 711 transactions
2021-01-19 16:42:35,615 [relstorage.blobhelper.cached] INFO Spawning cache checker for /opt/plone/var/instance/blobcache (exceeded threshold)
2021-01-19 16:42:35,622 [relstorage.blobhelper.cached] INFO Checking blob cache size for /opt/plone/var/instance/blobcache. (target: 72.00 MB)
2021-01-19 16:42:35,624 [relstorage.blobhelper.cached] INFO Traversed /opt/plone/var/instance/blobcache to compute size 8.00 MB (<= 72.00 MB); quitting.
2021-01-19 16:42:35,624 [relstorage.blobhelper.cached] INFO Finished checking /opt/plone/var/instance/blobcache (in 0.000s) with size of 8.00 MB (max: 80.00 MB; target 72.00 MB)
2021-01-19 16:42:41,322 [relstorage.blobhelper.cached] INFO Spawning cache checker for /opt/plone/var/instance/blobcache (exceeded threshold)
2021-01-19 16:42:41,341 [relstorage.blobhelper.cached] INFO Checking blob cache size for /opt/plone/var/instance/blobcache. (target: 72.00 MB)
2021-01-19 16:42:41,363 [relstorage.blobhelper.cached] INFO Traversed /opt/plone/var/instance/blobcache to compute size 16.45 MB (<= 72.00 MB); quitting.
2021-01-19 16:42:41,363 [relstorage.blobhelper.cached] INFO Finished checking /opt/plone/var/instance/blobcache (in 0.000s) with size of 16.45 MB (max: 80.00 MB; target 72.00 MB)
2021-01-19 16:42:45,138 [relstorage.blobhelper.cached] INFO Spawning cache checker for /opt/plone/var/instance/blobcache (exceeded threshold)
2021-01-19 16:42:45,149 [relstorage.blobhelper.cached] INFO Checking blob cache size for /opt/plone/var/instance/blobcache. (target: 72.00 MB)
2021-01-19 16:42:45,174 [relstorage.blobhelper.cached] INFO Traversed /opt/plone/var/instance/blobcache to compute size 25.62 MB (<= 72.00 MB); quitting.
2021-01-19 16:42:45,174 [relstorage.blobhelper.cached] INFO Finished checking /opt/plone/var/instance/blobcache (in 0.000s) with size of 25.62 MB (max: 80.00 MB; target 72.00 MB)
2021-01-19 16:42:45,557 [relstorage.blobhelper.cached] INFO Spawning cache checker for /opt/plone/var/instance/blobcache (exceeded threshold)
2021-01-19 16:42:45,565 [relstorage.blobhelper.cached] INFO Checking blob cache size for /opt/plone/var/instance/blobcache. (target: 72.00 MB)
2021-01-19 16:42:45,573 [relstorage.blobhelper.cached] INFO Traversed /opt/plone/var/instance/blobcache to compute size 35.45 MB (<= 72.00 MB); quitting.
2021-01-19 16:42:45,573 [relstorage.blobhelper.cached] INFO Finished checking /opt/plone/var/instance/blobcache (in 0.000s) with size of 35.45 MB (max: 80.00 MB; target 72.00 MB)
2021-01-19 16:42:53,061 [relstorage.blobhelper.cached] INFO Spawning cache checker for /opt/plone/var/instance/blobcache (exceeded threshold)
2021-01-19 16:42:53,068 [relstorage.blobhelper.cached] INFO Checking blob cache size for /opt/plone/var/instance/blobcache. (target: 72.00 MB)
2021-01-19 16:42:53,076 [relstorage.blobhelper.cached] INFO Traversed /opt/plone/var/instance/blobcache to compute size 43.47 MB (<= 72.00 MB); quitting.
2021-01-19 16:42:53,076 [relstorage.blobhelper.cached] INFO Finished checking /opt/plone/var/instance/blobcache (in 0.000s) with size of 43.47 MB (max: 80.00 MB; target 72.00 MB)
2021-01-19 16:42:58,429 [relstorage.blobhelper.cached] INFO Spawning cache checker for /opt/plone/var/instance/blobcache (exceeded threshold)
2021-01-19 16:42:58,437 [relstorage.blobhelper.cached] INFO Checking blob cache size for /opt/plone/var/instance/blobcache. (target: 72.00 MB)
2021-01-19 16:42:58,457 [relstorage.blobhelper.cached] INFO Traversed /opt/plone/var/instance/blobcache to compute size 51.52 MB (<= 72.00 MB); quitting.
2021-01-19 16:42:58,457 [relstorage.blobhelper.cached] INFO Finished checking /opt/plone/var/instance/blobcache (in 0.000s) with size of 51.52 MB (max: 80.00 MB; target 72.00 MB)
2021-01-19 16:43:00,647 [relstorage.storage.copy] INFO All 711 transactions copied successfully in  0.5 minutes.

This is my clone.conf

<relstorage source>
  blob-dir /opt/plone/var/instance/blobcache
  blob-cache-size 83886080
  keep-history false
  shared-blob-dir false
  <mysql>
    passwd vagrant1
    db vagrant1
    host localhost
    read_default_file /etc/mysql/my.cnf
    user vagrant1
    port 3306
  </mysql>
</relstorage>
<relstorage destination>
  blob-dir /opt/plone/var/instance/blobcache2
  blob-cache-size 83886080
  keep-history false
  shared-blob-dir false
  <mysql>
    passwd vagrant2
    db vagrant2
    host localhost
    read_default_file /etc/mysql/my.cnf
    user vagrant2
    port 3306
  </mysql>
</relstorage>

This is mysql server 8.0.23

Plone 4.3.11 Zope 2.13.24 ZODB 5.6.0 Python 2.7.17 mysql_connector_python 8.0.22

jamadden commented 3 years ago

I suggest using a different database driver. mysql_connector_python Is very buggy.

frapell commented 3 years ago

@jamadden Thank you for your quick response. Sorry about that, mysql_connector_python slipped through as it is one of the things I tried... if you see in the TB I'm using mysqlclient 1.4.6, which is the recommended driver right?

This appears to be related to blobs, as it doesn't happen on a fresh site. Trying to get a minimum set of steps to reproduce... will update ticket when I get it

frapell commented 3 years ago

@jamadden Unfortunately I am completely unable to reproduce this without providing the actual DB of a (very old) site where it happens, which of course I cannot do...

If I start the instance and navigate to the actual item, the blob is found in the DB and downloaded to the blobcache just fine, so it is not an issue of a missing file or anything like that... furthermore, if I downgrade to RelStorage 3.3.2 and run the zodbconvert, which fully populates the blobcache, and then upgrade to 3.4.0 and run zodbconvert again, it does run fine, because this time it finds the blob in the cache intead of getting it from the DB. If I clear the blobcache and try again, then the error happens again.

I see that a lot of changes went into zodbconvert between 3.3.2 and 3.4.0, so something definitely happened in there, however I am unable to figure it out... I will have to stick to 3.3.2 for the time being

jamadden commented 3 years ago

If you can supply a script that reproduces this, or add to the existing test cases one that fails, I'd be happy to look into it further.

jamadden commented 1 year ago

No additional comments since 2021, and no similar reports; closing as a quirk of that environment.