JIT Issue inlining `struct.unpack('<HH', bytearray(...))` produces incorrect results

Create issue
Issue #3014 resolved
Jason Madden created an issue

Versions:

  • Python 2.7.13 (8cdda8b8cdb8, Apr 14 2019, 14:06:58)
    [PyPy 7.1.1 with GCC 4.2.1 Compatible Apple LLVM 10.0.0 (clang-1000.11.45.5)] (macOS 10.14)
  • Python 3.6.1 (784b254d6699, Apr 14 2019, 10:22:55)
    [PyPy 7.1.1-beta0 with GCC 4.2.1 Compatible Apple LLVM 10.0.0 (clang-1000.11.45.5)]
  • Python 2.7.13 (8cdda8b8cdb8, Apr 14 2019, 14:06:58)
    [PyPy 7.1.1 with GCC 4.2.1 Compatible Apple LLVM 10.0.0 (clang-1000.11.45.5)]

I’ve been working on getting RelStorage to run on PyPy with (pure-Python) mysql-connector-python at https://github.com/zodb/relstorage/issues/228, but was running into a very strange, non-sensical error only on PyPy partway through the test sequence.

In a nutshell, the value of the status_flag in the OK result packet from the MySQL server is coming back with the ServerFlag.MORE_RESULTS_EXIST bit set, leading to the error. But that’s not actually the packet that the server is sending.

protocol.py has parse_ok that parses the status_flag from a packet (a bytearray) like this:

    def parse_ok(self, packet):
        """Parse a MySQL OK-packet"""
        if not packet[4] == 0:
            raise errors.InterfaceError("Failed parsing OK packet (invalid).")

        ok_packet = {}
        ok_packet['orig_data'] = bytes(packet)
        try:
            ok_packet['field_count'] = struct_unpack('<xxxxB', packet[0:5])[0]
            (packet, ok_packet['affected_rows']) = utils.read_lc_int(packet[5:])
            (packet, ok_packet['insert_id']) = utils.read_lc_int(packet)
            (ok_packet['status_flag'], # This is the bad value
             ok_packet['warning_count']) = struct_unpack('<HH', packet[0:4]) 
            packet = packet[4:]
            if packet:
                (packet, ok_packet['info_msg']) = utils.read_lc_string(packet)
                ok_packet['info_msg'] = ok_packet['info_msg'].decode('utf-8')
        except ValueError:
            raise errors.InterfaceError("Failed parsing OK packet.")
        return ok_packet

( struct_unpack is a small helper function for Python 2 that wraps a bytearray into a buffer and uses struct.unpack_from; I get the same results if I modify the code to use struct.unpack directly. Python 3 uses struct.unpack directly already.)

I tweaked the error message to report the packet value, and to also unpack the data at that time. (This is a cold branch of code that’s never been taken before)

 if self._have_next_result: # The status_flag was not what we wanted.
     from .catch23 import PY2, struct_unpack
     raise errors.InterfaceError(
         'Use cmd_query_iter for statements with multiple queries.'
         '\n%s\n%r\n%r\nUnpacks to:%r' % (
             query, result, raw_result, 
             struct_unpack('<HH', raw_result[0:4])))
InterfaceError: Use cmd_query_iter for statements with multiple queries.
    INSERT INTO temp_pack_visit (zoid, keep_tid)
    SELECT zoid, 0
    FROM current_object
    WHERE tid > 274639514178723874
{'field_count': 0, 'affected_rows': 0, 'insert_id': 0,
 'status_flag': 3480, 'warning_count': 0, 'info_msg': u'Records: 0  Duplicates: 0  Warnings: 0'}

bytearray(b'.\x00\x00\x01\x00\x00\x00\x02\x00\x00\x00&Records: 0  Duplicates: 0  Warnings: 0')

Unpacks to: (46, 256)

You can see that protocol.py's parse_ok method gets a status_flag of 3480, while performing the same unpacking on the same data in this function gets a value of 46 (which is what CPython gets too).

Running with --jit off solves the problem and lets the tests complete successfully. Also, just running with --jit inlining=0 solves the problem too.

How can I help with this? I imagine you’ll want a JIT log of some sort?

Comments (15)

  1. Armin Rigo

    It looks like a JIT bug indeed. We can't do anything about that unless we have a way to reproduce it ourselves. Even JIT logs usually don't help.

  2. Jason Madden reporter

    Fortunately it's 100% reproducible, at least for me 😄

    There is an external dependency on a MySQL server (I'm using 5.7.25 on my mac, as was Travis CI) running on localhost on the default port with a specific set of databases and users. A script for creating that is here (also in the .travis/mysql.sh script in the relstorage repo).

    Once MySQL is running, we need to install the right branch of RelStorage into PyPy along with its test dependencies and the problematic database driver. I just tested these steps:

    $ mktmpenv -p `which pypy`
    Already using interpreter /Users/jmadden/bin/pypy/bin/pypy
    New pypy executable in /Users/jmadden/Projects/VirtualEnvs/tmp-178b947c715c5105/bin/pypy
    ...
    (TMP)$ git clone https://github.com/zodb/relstorage
    Cloning into 'relstorage'...
    remote: Enumerating objects: 27, done.
    remote: Counting objects: 100% (27/27), done.
    remote: Compressing objects: 100% (26/26), done.
    remote: Total 7150 (delta 0), reused 3 (delta 0), pack-reused 7123
    Receiving objects: 100% (7150/7150), 3.41 MiB | 7.19 MiB/s, done.
    Resolving deltas: 100% (5144/5144), done.
    (TMP)$ cd ./relstorage
    (TMP)$ git checkout issue228
    Branch 'issue228' set up to track remote branch 'issue228' from 'origin' by rebasing.
    Switched to a new branch 'issue228'
    (TMP)$ pip install -e .[test]
    ...
    Successfully installed BTrees-4.5.1 RelStorage ZConfig-3.4.0 ZEO-5.2.1 ZODB-5.5.1 funcsigs-1.0.2 mock-3.0.5 nti.testing-2.2.0 perfmetrics-2.0 persistent-4.5.0 pyhamcrest-1.9.0 python-memcached-1.59 random2-1.0.1 transaction-2.4.0 trollius-2.2 zc.lockfile-1.4 zc.zlibstorage-1.2.0 zdaemon-4.3 zodbpickle-1.0.3 zope.component-4.5 zope.configuration-4.3.1 zope.deferredimport-4.3 zope.deprecation-4.4.0 zope.event-4.4 zope.exceptions-4.3 zope.hookable-4.2.0 zope.i18nmessageid-4.3.1 zope.interface-4.6.0 zope.proxy-4.3.1 zope.schema-4.9.3 zope.testing-4.7 zope.testrunner-5.0
    (TMP)$ pip install mysql-connector-python
    ...
    Installing collected packages: protobuf, mysql-connector-python
    Successfully installed mysql-connector-python-8.0.16 protobuf-3.8.0rc1
    

    (Note: The branch may get merged into the master (default) branch sometime today.)

    Now we can run the test suite and watch it fail:

    $ python -m zope.testrunner --test-path=src --layer PyMySQL -x
    Running .MySQLPyMySQLConnector_Python_SharedNoHistoryBlobTests tests:
      Set up .MySQLPyMySQLConnector_Python_SharedNoHistoryBlobTests in 0.001 seconds.
      Ran 11 tests with 0 failures, 0 errors and 0 skipped in 9.750 seconds.
    Running .MySQLPyMySQLConnector_Python_SharedWithHistoryBlobTests tests:
      Tear down .MySQLPyMySQLConnector_Python_SharedNoHistoryBlobTests in 0.000 seconds.
      Set up .MySQLPyMySQLConnector_Python_SharedWithHistoryBlobTests in 0.000 seconds.
    
    
    Error in test testRedo (relstorage.tests.blob.testblob.MySQLPyMySQLConnector_Python_SharedWithHistoryBlobUndoTests)
    Traceback (most recent call last):
      File "/Users/jmadden/bin/pypy/lib-python/2.7/unittest/case.py", line 329, in run
        testMethod()
      File "//relstorage/src/relstorage/tests/blob/testblob.py", line 221, in testRedo
        transaction.commit()
      File "/site-packages/transaction/_manager.py", line 252, in commit
        return self.manager.commit()
      File "//site-packages/transaction/_manager.py", line 131, in commit
        return self.get().commit()
      File "//site-packages/transaction/_transaction.py", line 311, in commit
        reraise(t, v, tb)
      File "//site-packages/transaction/_transaction.py", line 302, in commit
        self._commitResources()
      File "//site-packages/transaction/_transaction.py", line 447, in _commitResources
        reraise(t, v, tb)
      File "//site-packages/transaction/_transaction.py", line 421, in _commitResources
        rm.commit(self)
      File "//site-packages/ZODB/DB.py", line 1077, in commit
        self._storage.undo(tid, transaction)
      File "//site-packages/perfmetrics/__init__.py", line 133, in call_with_metric
        return f(*args, **kw)
      File "//relstorage/src/relstorage/storage.py", line 1246, in undo
        adapter.mover.update_current(cursor, self_tid_int)
      File "//relstorage/src/relstorage/adapters/_util.py", line 134, in swizzler
        return getattr(self, meth_name)(*args, **kwargs)
      File "/Users/jmadden/bin/pypy/lib_pypy/_functools.py", line 45, in __call__
        return self._func(*(self._args + fargs), **fkeywords)
      File "//site-packages/perfmetrics/__init__.py", line 133, in call_with_metric
        return f(*args, **kw)
      File "//relstorage/src/relstorage/adapters/mysql/mover.py", line 144, in update_current
        """, (tid,))
      File "//site-packages/mysql/connector/cursor.py", line 573, in execute
        "Use multi=True when executing multiple statements")
    InterfaceError: Use multi=True when executing multiple statements
    

    To see the underlying unpacking error I described above, you need to edit site-packages/mysql/connector/cursor.py at line 570 and make it always just raise instead of rewrapping the exception. That produces this traceback:

      File "//relstorage/src/relstorage/adapters/mover.py", line 395, in move_from_temp
        cursor.execute(stmt, (tid,))
      File "//site-packages/mysql/connector/cursor.py", line 569, in execute
        self._handle_result(self._connection.cmd_query(stmt))
      File "/site-packages/mysql/connector/connection.py", line 557, in cmd_query
        'Use cmd_query_iter for statements with multiple queries.')
    InterfaceError: Use cmd_query_iter for statements with multiple queries.
    

    That leads you to site-packages/mysql/connector/connection.py at line 556, where self._have_next_result is unexpectedly true. You can follow where that gets set through self._handle_ok(packet) in connection.py at line 432 and into protocol.py parse_ok at line 231 to see the erroneous unpacking.

    Turning the JIT inlining off gets a successful test run:

    $ python --jit inlining=0 -m zope.testrunner --test-path=src --layer PyMySQL -x
    Running .MySQLPyMySQLConnector_Python_SharedNoHistoryBlobTests tests:
      Set up .MySQLPyMySQLConnector_Python_SharedNoHistoryBlobTests in 0.001 seconds.
      Ran 11 tests with 0 failures, 0 errors and 0 skipped in 9.804 seconds.
    Running .MySQLPyMySQLConnector_Python_SharedWithHistoryBlobTests tests:
      Tear down .MySQLPyMySQLConnector_Python_SharedNoHistoryBlobTests in 0.000 seconds.
      Set up .MySQLPyMySQLConnector_Python_SharedWithHistoryBlobTests in 0.000 seconds.
      Ran 16 tests with 0 failures, 0 errors and 0 skipped in 12.021 seconds.
    Running .MySQLPyMySQLConnector_Python_UnsharedNoHistoryBlobTests tests:
      Tear down .MySQLPyMySQLConnector_Python_SharedWithHistoryBlobTests in 0.000 seconds.
      Set up .MySQLPyMySQLConnector_Python_UnsharedNoHistoryBlobTests in 0.000 seconds.
      Ran 11 tests with 0 failures, 0 errors and 0 skipped in 12.004 seconds.
    Running .MySQLPyMySQLConnector_Python_UnsharedWithHistoryBlobTests tests:
      Tear down .MySQLPyMySQLConnector_Python_UnsharedNoHistoryBlobTests in 0.000 seconds.
      Set up .MySQLPyMySQLConnector_Python_UnsharedWithHistoryBlobTests in 0.000 seconds.
      Ran 16 tests with 0 failures, 0 errors and 0 skipped in 10.957 seconds.
    Running .MySQLPyMySQL_SharedNoHistoryBlobTests tests:
      Tear down .MySQLPyMySQLConnector_Python_UnsharedWithHistoryBlobTests in 0.000 seconds.
      Set up .MySQLPyMySQL_SharedNoHistoryBlobTests in 0.000 seconds.
      Ran 1 tests with 0 failures, 0 errors and 1 skipped in 0.000 seconds.
    Running .MySQLPyMySQL_SharedWithHistoryBlobTests tests:
      Tear down .MySQLPyMySQL_SharedNoHistoryBlobTests in 0.000 seconds.
      Set up .MySQLPyMySQL_SharedWithHistoryBlobTests in 0.000 seconds.
      Ran 6 tests with 0 failures, 0 errors and 6 skipped in 0.001 seconds.
    Running .MySQLPyMySQL_UnsharedNoHistoryBlobTests tests:
      Tear down .MySQLPyMySQL_SharedWithHistoryBlobTests in 0.000 seconds.
      Set up .MySQLPyMySQL_UnsharedNoHistoryBlobTests in 0.000 seconds.
      Ran 1 tests with 0 failures, 0 errors and 1 skipped in 0.000 seconds.
    Running .MySQLPyMySQL_UnsharedWithHistoryBlobTests tests:
      Tear down .MySQLPyMySQL_UnsharedNoHistoryBlobTests in 0.000 seconds.
      Set up .MySQLPyMySQL_UnsharedWithHistoryBlobTests in 0.000 seconds.
      Ran 6 tests with 0 failures, 0 errors and 6 skipped in 0.001 seconds.
    Running relstorage.tests.testmysql.MySQLPyMySQL tests:
      Tear down .MySQLPyMySQL_UnsharedWithHistoryBlobTests in 0.000 seconds.
      Set up relstorage.tests.testmysql.MySQLPyMySQL in 0.000 seconds.
      Ran 226 tests with 0 failures, 0 errors and 226 skipped in 0.009 seconds.
    Running relstorage.tests.testmysql.MySQLPyMySQLConnector_Python tests:
      Tear down relstorage.tests.testmysql.MySQLPyMySQL in 0.000 seconds.
      Set up relstorage.tests.testmysql.MySQLPyMySQLConnector_Python in 0.000 seconds.
      Ran 226 tests with 0 failures, 0 errors and 4 skipped in 1 minutes 18.750 seconds.
    Tearing down left over layers:
      Tear down relstorage.tests.testmysql.MySQLPyMySQLConnector_Python in 0.000 seconds.
    Total: 520 tests, 0 failures, 0 errors and 244 skipped in 2 minutes 4.068 seconds.
    

    I'm happy to help if you run into any trouble trying to reproduce.

  3. Armin Rigo

    I followed the instructions, but while the mysql commands on the shell work fine (also the ones in .travis/mysql.sh) when running under my regular user name, running python -m zope.testrunner --test-path=src --layer PyMySQL -x fails immediately with:

    ProgrammingError: 1045 (28000): Access denied for user 'relstoragetest'@'localhost' (using password: YES)
    

    I never set any password and I don't know if that's the problem. I also don't know if I should run under a new Unix user name called 'relstoragetest' or if that's unrelated. Can you help?

  4. Jason Madden reporter

    The first line of mysql.sh (mysql -uroot -e "CREATE USER 'relstoragetest' IDENTIFIED BY 'relstoragetest';") both creates the MySQL user relstoragetest and sets its password (the IDENTIFIED BY clause). If running that script Just Worked, I'm not immediately sure what the problem is, but I'm happy to help figure it out!

    I don't think the Unix account name is related. I've run with the same user name and different user names for the server and the Python process (they're always different on Travis, and locally I've just tested both).

    A few questions:

    What happens when you run this shell command? mysql -urelstoragetest --password=relstoragetest -D relstoragetest -e 'select count(*) from object_state'? Access denied or something else? What about this one: mysql -uroot -D relstoragetest -e 'select count(*) from object_state'? Does running the CREATE USER command from above again make any difference?

    Can you describe how you're running the mysql server? Is it a system service running as a different user account, or something you launched with your user account? I've tested with the default daemon running on Travis, the default daemon as set up by MacPorts, but most often when I'm just running the server on the command line.

  5. Armin Rigo

    The first command you describe results in ERROR 1045 (28000): Access denied for user 'relstoragetest'@'localhost' (using password: YES). The second command results in ERROR 1146 (42S02) at line 1: Table 'relstoragetest.object_state' doesn't exist. Running them again doesn't change anything.

    I'm confused because .travis/mysql.sh doesn't seem to set (and never asks me for) a password to give to the new user relstoragetest.

  6. Armin Rigo

    I run the server by running these commands as root:

    mysql_install_db --user=mysql --basedir=/usr --datadir=/var/lib/mysql
    cd '/usr' ; /usr/bin/mysqld_safe --datadir='/var/lib/mysql'
    
  7. Armin Rigo

    I fixed the problem by editing .travis/mysql.sh to replace the user name 'relstoragetest' with 'relstoragetest'@'localhost'. I suspect it's a small difference of the particular version of mysql I'm using (I'm on Linux and it is MariaDB).

  8. Armin Rigo

    Reduced to this program, where the assert fails after the JIT kicks in:

    import struct
    def g():
        while True:
            pppp = bytearray("\x02\x00\x01\x01EXTRA")[:4]
            aabb = struct.unpack('<HH', pppp)
            assert aabb == (2, 257)
    g()
    
  9. Log in to comment