Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Flaky sqlite failure - Error binding parameter 0 - probably unsupported type #5432

Open
LefterisJP opened this issue Jan 18, 2023 · 6 comments
Labels
bug Something isn't working

Comments

@LefterisJP
Copy link
Member

LefterisJP commented Jan 18, 2023

Problem Definition

During initial blockchain balance query, the ETH query task just died and no ETH balances were shown. It was a shock for a bit but then I realized something was wrong by looking at the logs. Happened first time and has never been seen before.

Restarting,it all went well. The logs of what happened are below.

Logs

[19/01/2023 00:17:48 CET] DEBUG rotkehlchen.api.server Greenlet-8: start rotki api GET /api/1/balances/blockchains/ETH view_args={'blockchain': 'ETH'}, query_string=b'async_query=true'
[19/01/2023 00:17:48 CET] DEBUG rotkehlchen.api.server Greenlet-8: end rotki api GET /api/1/balances/blockchains/ETH view_args={'blockchain': 'ETH'}, query_string=b'async_query=true', status_code=200, result={'result': {'task_id': 7}, 'message': ''}
[19/01/2023 00:17:48 CET] DEBUG rotkehlchen.api.rest Greenlet-24: Async task with task id 7 started
...
...
[19/01/2023 00:18:10 CET] DEBUG rotkehlchen.chain.ethereum.manager Greenlet-7: Querying ethereum chain for ETH balance eth_addresses=["redacted--was about 20 addresses"]
[19/01/2023 00:18:10 CET] DEBUG web3.RequestManager Making request. Method: eth_call
[19/01/2023 00:18:10 CET] DEBUG web3.RequestManager Making request. Method: eth_chainId
[19/01/2023 00:18:10 CET] DEBUG web3.providers.HTTPProvider Making request HTTP. URI: https://eth-mainnet.alchemyapi.io/v2/REDACTEDKEY, Method: eth_chainId
[19/01/2023 00:18:10 CET] ERROR rotkehlchen.api.rest Greenlet with id 140602543744272: Greenlet for task 7 dies with exception: Error binding parameter 0 - probably unsupported type..
Exception Name: <class 'pysqlcipher3.dbapi2.InterfaceError'>
Exception Info: Error binding parameter 0 - probably unsupported type.
Traceback:
   File "src/gevent/greenlet.py", line 908, in gevent._gevent_cgreenlet.Greenlet.run
  File "rotkehlchen/api/rest.py", line 298, in _do_query_async
  File "rotkehlchen/api/rest.py", line 664, in _query_blockchain_balances
  File "rotkehlchen/utils/mixins/lockable.py", line 46, in wrapper
  File "rotkehlchen/utils/mixins/cacheable.py", line 97, in wrapper
  File "rotkehlchen/chain/manager.py", line 616, in query_balances
  File "rotkehlchen/utils/mixins/lockable.py", line 46, in wrapper
  File "rotkehlchen/utils/mixins/cacheable.py", line 97, in wrapper
  File "rotkehlchen/chain/manager.py", line 1150, in query_ethereum_balances
  File "rotkehlchen/chain/manager.py", line 1083, in query_ethereum_tokens
  File "rotkehlchen/chain/evm/tokens.py", line 330, in query_tokens_for_addresses
  File "rotkehlchen/db/dbhandler.py", line 1303, in get_tokens_for_address
  File "rotkehlchen/db/drivers/gevent.py", line 89, in execute

System Description

Operating system: Lunux
Rotki version: v1.26.3

@LefterisJP LefterisJP added bug Something isn't working work queue labels Jan 18, 2023
@LefterisJP
Copy link
Member Author

Will close this as it happened only once in 1.26.3 and has not been seen since and code has changed a lot since then.

@LefterisJP LefterisJP closed this as not planned Won't fix, can't repro, duplicate, stale Feb 7, 2023
@LefterisJP LefterisJP reopened this May 13, 2023
@LefterisJP
Copy link
Member Author

LefterisJP commented May 13, 2023

This has been seen a few times in develop right now (almost 1.28.0).

Suspicions raised by Alexey are it may be related to mutating the BlockchainAccount eth list. But not confirmed or reproduced.

@LefterisJP
Copy link
Member Author

Running on a PR that has the first 2 commits as of today from #6071 showed the same error:

[14/05/2023 16:16:49 CEST] DEBUG rotkehlchen.tasks.manager Greenlet-4: At task scheduling. Current greenlets: 14 Max greenlets: 2. Will not schedule.
[14/05/2023 16:16:49 CEST] ERROR rotkehlchen.api.rest Greenlet with id 140502404829952: Greenlet for task 98 dies with exception: Error binding parameter 0 - probably unsupported type..
Exception Name: <class 'pysqlcipher3.dbapi2.InterfaceError'>
Exception Info: Error binding parameter 0 - probably unsupported type.
Traceback:
   File "src/gevent/greenlet.py", line 908, in gevent._gevent_cgreenlet.Greenlet.run
  File "/home/lefteris/w/rotkehlchen/rotkehlchen/api/rest.py", line 362, in _do_query_async
    result = command(self, **kwargs)
  File "/home/lefteris/w/rotkehlchen/rotkehlchen/api/rest.py", line 674, in query_blockchain_balances
    balances = self.rotkehlchen.chains_aggregator.query_balances(
  File "/home/lefteris/w/rotkehlchen/rotkehlchen/utils/mixins/lockable.py", line 46, in wrapper
    result = f(wrappingobj, *args, **kwargs)
  File "/home/lefteris/w/rotkehlchen/rotkehlchen/utils/mixins/cacheable.py", line 122, in wrapper
    result = f(wrappingobj, *args, **kwargs)
  File "/home/lefteris/w/rotkehlchen/rotkehlchen/chain/aggregator.py", line 455, in query_balances
    getattr(self, query_method)(ignore_cache=ignore_cache)
  File "/home/lefteris/w/rotkehlchen/rotkehlchen/utils/mixins/lockable.py", line 46, in wrapper
    result = f(wrappingobj, *args, **kwargs)
  File "/home/lefteris/w/rotkehlchen/rotkehlchen/utils/mixins/cacheable.py", line 122, in wrapper
    result = f(wrappingobj, *args, **kwargs)
  File "/home/lefteris/w/rotkehlchen/rotkehlchen/chain/aggregator.py", line 907, in query_eth_balances
    self.query_evm_chain_balances(chain=SupportedBlockchain.ETHEREUM)
  File "/home/lefteris/w/rotkehlchen/rotkehlchen/chain/aggregator.py", line 877, in query_evm_chain_balances
    self.query_evm_tokens(manager=manager, balances=chain_balances)
  File "/home/lefteris/w/rotkehlchen/rotkehlchen/chain/aggregator.py", line 815, in query_evm_tokens
    balance_result, token_usd_price = manager.tokens.query_tokens_for_addresses(
  File "/home/lefteris/w/rotkehlchen/rotkehlchen/chain/evm/tokens.py", line 346, in query_tokens_for_addresses
    saved_list, _ = self.db.get_tokens_for_address(
  File "/home/lefteris/w/rotkehlchen/rotkehlchen/db/dbhandler.py", line 1169, in get_tokens_for_address
    cursor.execute(
  File "/home/lefteris/w/rotkehlchen/rotkehlchen/db/drivers/gevent.py", line 90, in execute
    self._cursor.execute(statement, *bindings)

[14/05/2023 16:16:49 CEST] DEBUG rotkehlchen.api.server Greenlet-22: start rotki api GET /api/1/tasks/89 view_args={'task_id': 89}, query_string=b''

@LefterisJP
Copy link
Member Author

LefterisJP commented May 14, 2023

Okay so unfortunately the hypothesis of Alexey was wrong. And if you look at the code it was never possible. Anyway good to have done the immutability changes but here are logs of the bindings when the error happens.

Adding this log

modified   rotkehlchen/db/dbhandler.py
@@ -1166,6 +1166,7 @@ class DBHandler:
         """
         ignored_asset_ids = self.get_ignored_asset_ids(cursor)
         last_queried_ts = None
+        log.debug(f'--> BINDINGS: {(address, blockchain.to_chain_id().serialize_for_db(), EVM_ACCOUNTS_DETAILS_LAST_QUERIED_TS, EVM_ACCOUNTS_DETAILS_TOKENS)}')  # noqa: E501
         cursor.execute(
             'SELECT key, value FROM evm_accounts_details WHERE account=? AND chain_id=? AND (key=? OR key=?)',  # noqa: E501
             (address, blockchain.to_chain_id().serialize_for_db(), EVM_ACCOUNTS_DETAILS_LAST_QUERIED_TS, EVM_ACCOUNTS_DETAILS_TOKENS),  # noqa: E501

This is what appeared in the logs when the error occured again:

[14/05/2023 22:06:43 CEST] DEBUG rotkehlchen.db.dbhandler Greenlet-24: --> BINDINGS: ('0xaddy1', 1, 'last_queried_timestamp', 'tokens')
[14/05/2023 22:06:43 CEST] DEBUG rotkehlchen.db.dbhandler Greenlet-24: --> BINDINGS: ('0xaddy2', 1, 'last_queried_timestamp', 'tokens')
[14/05/2023 22:06:43 CEST] DEBUG rotkehlchen.db.dbhandler Greenlet-24: --> BINDINGS: ('0xaddy3', 1, 'last_queried_timestamp', 'tokens')
[14/05/2023 22:06:43 CEST] DEBUG rotkehlchen.db.dbhandler Greenlet-24: --> BINDINGS: ('0xaddy4', 1, 'last_queried_timestamp', 'tokens')
[14/05/2023 22:06:43 CEST] DEBUG rotkehlchen.db.dbhandler Greenlet-24: --> BINDINGS: ('0xaddy5', 1, 'last_queried_timestamp', 'tokens')
[14/05/2023 22:06:43 CEST] DEBUG rotkehlchen.db.dbhandler Greenlet-24: --> BINDINGS: ('0xaddy6', 1, 'last_queried_timestamp', 'tokens')
[14/05/2023 22:06:43 CEST] DEBUG rotkehlchen.db.dbhandler Greenlet-24: --> BINDINGS: ('0xaddy7', 1, 'last_queried_timestamp', 'tokens')
[14/05/2023 22:06:43 CEST] DEBUG web3.providers.HTTPProvider Getting response HTTP. URI: https://eth-mainnet.alchemyapi.io/v2/XXX, Method: eth_call, Response: {'jsonrpc': '2.0', 'id': 446, 'result': 'XXX'}
[14/05/2023 22:06:43 CEST] DEBUG web3.RequestManager Making request. Method: eth_call
[14/05/2023 22:06:43 CEST] DEBUG web3.providers.HTTPProvider Making request HTTP. URI: https://eth-mainnet.alchemyapi.io/v2/XXX, Method: eth_call
[14/05/2023 22:06:43 CEST] DEBUG rotkehlchen.db.dbhandler Greenlet-24: --> BINDINGS: ('0xaddy8', 1, 'last_queried_timestamp', 'tokens')
[14/05/2023 22:06:43 CEST] ERROR rotkehlchen.api.rest Greenlet with id 139870912437760: Greenlet for task 5 dies with exception: Error binding parameter 0 - probably unsupported type..
Exception Name: <class 'pysqlcipher3.dbapi2.InterfaceError'>
Exception Info: Error binding parameter 0 - probably unsupported type.
Traceback:
   File "src/gevent/greenlet.py", line 908, in gevent._gevent_cgreenlet.Greenlet.run
  File "/home/lefteris/w/rotkehlchen/rotkehlchen/api/rest.py", line 362, in _do_query_async
    result = command(self, **kwargs)
  File "/home/lefteris/w/rotkehlchen/rotkehlchen/api/rest.py", line 488, in query_all_balances
    result = self.rotkehlchen.query_balances(
  File "/home/lefteris/w/rotkehlchen/rotkehlchen/rotkehlchen.py", line 870, in query_balances
    blockchain_result = self.chains_aggregator.query_balances(
  File "/home/lefteris/w/rotkehlchen/rotkehlchen/utils/mixins/lockable.py", line 46, in wrapper
    result = f(wrappingobj, *args, **kwargs)
  File "/home/lefteris/w/rotkehlchen/rotkehlchen/utils/mixins/cacheable.py", line 122, in wrapper
    result = f(wrappingobj, *args, **kwargs)
  File "/home/lefteris/w/rotkehlchen/rotkehlchen/chain/aggregator.py", line 461, in query_balances
    getattr(self, query_method)(ignore_cache=ignore_cache)
  File "/home/lefteris/w/rotkehlchen/rotkehlchen/utils/mixins/lockable.py", line 46, in wrapper
    result = f(wrappingobj, *args, **kwargs)
  File "/home/lefteris/w/rotkehlchen/rotkehlchen/utils/mixins/cacheable.py", line 122, in wrapper
    result = f(wrappingobj, *args, **kwargs)
  File "/home/lefteris/w/rotkehlchen/rotkehlchen/chain/aggregator.py", line 907, in query_eth_balances
    self.query_evm_chain_balances(chain=SupportedBlockchain.ETHEREUM)
  File "/home/lefteris/w/rotkehlchen/rotkehlchen/chain/aggregator.py", line 877, in query_evm_chain_balances
    self.query_evm_tokens(manager=manager, balances=chain_balances)
  File "/home/lefteris/w/rotkehlchen/rotkehlchen/chain/aggregator.py", line 815, in query_evm_tokens
    balance_result, token_usd_price = manager.tokens.query_tokens_for_addresses(
  File "/home/lefteris/w/rotkehlchen/rotkehlchen/chain/evm/tokens.py", line 346, in query_tokens_for_addresses
    saved_list, _ = self.db.get_tokens_for_address(
  File "/home/lefteris/w/rotkehlchen/rotkehlchen/db/dbhandler.py", line 1170, in get_tokens_for_address
    cursor.execute(
  File "/home/lefteris/w/rotkehlchen/rotkehlchen/db/drivers/gevent.py", line 90, in execute
    self._cursor.execute(statement, *bindings)

Parameters at last call are as correct as every other call.

Similar errors in the wild

https://foss.heptapod.net/pypy/pypy/-/issues/3351
nedbat/coveragepy#1010

They seem to mention it's pypy, though I am reproducing it with a cpython implementation so I am afraid it may be independent of underlying implementation.

Reproducing

I am trying really hard to reproduce the bug in a test but it's not trivial. I just had the first positive result after a while but not 100% sure how it happened:

2023-05-14_23-26

@LefterisJP LefterisJP changed the title ETH query task died with Error binding parameter 0 - probably unsupported type Flaky - ETH query task died with Error binding parameter 0 - probably unsupported type - Pypy related? May 14, 2023
@LefterisJP LefterisJP changed the title Flaky - ETH query task died with Error binding parameter 0 - probably unsupported type - Pypy related? Flaky - ETH query task died with Error binding parameter 0 - probably unsupported type May 14, 2023
LefterisJP added a commit to LefterisJP/rotkehlchen that referenced this issue May 14, 2023
This is a "temporary fix" for the error binding parameter 0 flaky
error as seen in rotki#5432.

If I understand it correctly the bug is in the python sqlite drivers
and as such this is just a patch until it's solved properly.

We have a test to reproduce so we should periodically check as we
upgrade python versions to see if this is fixed and then we can revert.
@LefterisJP
Copy link
Member Author

All right so the issue has been reproduced in a test in our repo here: #6071

The error seems to be an sqlite driver implementation error that causes a wrong instance of
"Error binding parameter 0 - probably unsupported type" flakily. Happened once
in a blue moon for our users so was hard to reproduce.

Happens only if opening a parallel write context in the same connection from which
the read only get_tokens_for_address is done. Makes no sense. As a read context
should not be affected. Secondly why only at that location?

Our current fix in the code is to repeat the cursor.execute()
without any delay. It works splendid. Same solution the coveragepy people used:
nedbat/coveragepy#1010

Hopefully we will be able to find a proper solution if this is indeed an sqlite bug.

LefterisJP added a commit that referenced this issue May 14, 2023
This is a "temporary fix" for the error binding parameter 0 flaky
error as seen in #5432.

If I understand it correctly the bug is in the python sqlite drivers
and as such this is just a patch until it's solved properly.

We have a test to reproduce so we should periodically check as we
upgrade python versions to see if this is fixed and then we can revert.
@LefterisJP
Copy link
Member Author

LefterisJP commented Jun 22, 2023

Another occurence in a different place

So unfortunately this happened again and in a different place.

This cursor execute statement:

failed very rarely with the same error:

[22/06/2023 20:06:39 CEST] ERROR rotkehlchen.api.server Error binding parameter 0 - probably unsupported type.
Traceback (most recent call last):
  File "/home/lefteris/.virtualenvs/rotkipy39/lib/python3.9/site-packages/flask/app.py", line 1484, in full_dispatch_request
    rv = self.dispatch_request()
  File "/home/lefteris/.virtualenvs/rotkipy39/lib/python3.9/site-packages/flask/app.py", line 1469, in dispatch_request
    return self.ensure_sync(self.view_functions[rule.endpoint])(**view_args)
  File "/home/lefteris/.virtualenvs/rotkipy39/lib/python3.9/site-packages/flask/views.py", line 109, in view
    return current_app.ensure_sync(self.dispatch_request)(**kwargs)
  File "/home/lefteris/.virtualenvs/rotkipy39/lib/python3.9/site-packages/flask/views.py", line 190, in dispatch_request
    return current_app.ensure_sync(meth)(**kwargs)
  File "/home/lefteris/w/rotkehlchen/rotkehlchen/api/v1/resources.py", line 311, in wrapper
    return f(*args, **kwargs)
  File "/home/lefteris/w/rotkehlchen/rotkehlchen/api/v1/parser.py", line 66, in wrapper
    return func(*args, **kwargs)
  File "/home/lefteris/w/rotkehlchen/rotkehlchen/api/v1/resources.py", line 2499, in get
    return self.rest_api.get_nfts_balances(
  File "/home/lefteris/w/rotkehlchen/rotkehlchen/api/rest.py", line 295, in inner
    response = func(rest_api, **kwargs)
  File "/home/lefteris/w/rotkehlchen/rotkehlchen/api/rest.py", line 3233, in get_nfts_balances
    return self._eth_module_query(
  File "/home/lefteris/w/rotkehlchen/rotkehlchen/api/rest.py", line 2308, in _eth_module_query
    result = getattr(module_obj, method)(**kwargs)
  File "/home/lefteris/w/rotkehlchen/rotkehlchen/chain/ethereum/modules/nft/nfts.py", line 176, in get_db_nft_balances
    cursor.execute(
  File "/home/lefteris/w/rotkehlchen/rotkehlchen/db/drivers/gevent.py", line 90, in execute
    self._cursor.execute(statement, *bindings)
pysqlcipher3.dbapi2.InterfaceError: Error binding parameter 0 - probably unsupported type.
[22/06/2023 20:06:39 CEST] CRITICAL rotkehlchen.api.server Greenlet-0: Unhandled exception when processing endpoint request exc_info=True, exception=Error binding parameter 0 - probably unsupported type.

Unlike the previous place this happened I was not able to reproduce reliably in a test. So for now what I will do is keep the previous test which does reproduce the case this happens in case a fix is found.

Noting down where it happened the second time. But also move the "fix" to all cursor.execute() in case there is an interface error. As it can happen rarely in more places the fix needs to go deeper.

I hate myself for writing this and really need to find a way to address this.

Attempts for test

This is what I tried when I wanted to reproduce by looking at what happened in the wild when it occured:

def _do_read(database):
    with database.conn.read_ctx() as cursor:
        database.get_settings(cursor)
        database.get_all_external_service_credentials()
        database.get_blockchain_accounts(cursor)


def _do_spawn(database):
    while True:
        gevent.spawn(_do_read, database)
        with database.user_write() as write_cursor:
            database.set_setting(write_cursor, 'last_write_ts', 15)
            gevent.sleep(0.1)
            database.set_setting(write_cursor, 'last_write_ts', 15)


@pytest.mark.parametrize('number_of_eth_accounts', [100])
@pytest.mark.parametrize('sql_vm_instructions_cb', [25])
@pytest.mark.parametrize('ethereum_modules', [['nfts']])
def test_flaky_binding_parameter_zero(database, ethereum_accounts, blockchain):
    """Test that reproduces https://github.com/rotki/rotki/issues/5432 for nfts reliably.

    Same as the tokens issue
    """
    nft_module = blockchain.get_module('nfts')
    with database.conn.read_ctx() as cursor:
        asset_ids = [x[0] for x in cursor.execute('SELECT identifier FROM assets LIMIT 250;').fetchall()]
        with database.user_write() as write_cursor:
            write_cursor.executemany(
                'INSERT INTO multisettings(name, value) VALUES(?, ?)',
                [('ignored_asset', x) for x in asset_ids[85:]],
            )
        ignored_assets_filter_params = ('NOT IN', database.get_ignored_asset_ids(cursor))

    stuff = []
    # Populate some data in the evm_accounts_details table, since this is what's used in the bug
    for idx, address in enumerate(ethereum_accounts):
        stuff.append((asset_ids[idx], 'name', '1', 'ETH', 0, address, 0, 'url', 'collection_name'))

    with database.user_write() as write_cursor:
        write_cursor.executemany(
            'INSERT OR REPLACE INTO nfts '
            '(identifier, name, last_price, last_price_asset, manual_price, owner_address, '
            'is_lp, image_url, collection_name) '
            'VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?)',
            stuff,
        )

    # gevent.spawn(_do_spawn, database)
    # gevent.sleep(.1)
    gevent.spawn(
        nft_module.get_db_nft_balances,
        NFTFilterQuery.make(owner_addresses=ethereum_accounts),
    )
    gevent.sleep(.1)
    gevent.spawn(
        nft_module.get_db_nft_balances,
        NFTFilterQuery.make(owner_addresses=ethereum_accounts),
    )
    gevent.sleep(.1)
    gevent.spawn(
        nft_module.get_db_nft_balances,
        NFTFilterQuery.make(owner_addresses=ethereum_accounts, ignored_assets_filter_params=ignored_assets_filter_params),
    )
    gevent.sleep(.1)
    nft_module.get_db_nft_balances(NFTFilterQuery.make(
        owner_addresses=ethereum_accounts,
        ignored_assets_filter_params=ignored_assets_filter_params,
    ))

LefterisJP added a commit to LefterisJP/rotkehlchen that referenced this issue Jun 22, 2023
As I wrote in
rotki#5432 (comment) the
issue popped up again in a different place.

This means that this driver bug is more generic and can hit us in many
different places.

So I am moving the "fix" to the cursor itself.

We really need to find a proper fix for this
@LefterisJP LefterisJP changed the title Flaky - ETH query task died with Error binding parameter 0 - probably unsupported type Flaky sqlite failure - Error binding parameter 0 - probably unsupported type Jun 22, 2023
LefterisJP added a commit that referenced this issue Jun 23, 2023
As I wrote in
#5432 (comment) the
issue popped up again in a different place.

This means that this driver bug is more generic and can hit us in many
different places.

So I am moving the "fix" to the cursor itself.

We really need to find a proper fix for this
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working
Projects
None yet
Development

No branches or pull requests

1 participant