`socket.timeout: timed out` (v9.49.1+)

[mtbitcoin]

This is a on a windows box

Status: Running v9.49.2 of counterpartyd. Status: Connecting to backend. Status: Checking version. Status: Acquiring lock. Status: Connecting to database. Status: Connecting to block explorer. Status: Resuming parsing. ERROR: Traceback (most recent call last): File "C:\counterpartyd_build\dist\counterpartyd\lib\blocks.py", line 977, in follow mempool_tx_index = list_tx(db, None, block_index, curr_time, tx_hash, mempool_tx_index ) File "C:\counterpartyd_build\dist\counterpartyd\lib\blocks.py", line 653, in list_tx source, destination, btc_amount, fee, data = get_tx_info(tx_dict['hex'], block_index) File "C:\counterpartyd_build\dist\counterpartyd\lib\blocks.py", line 341, in get_tx_info

tx_info = get_tx_info2(tx_hex, block_parser=block_parser)

File "C:\counterpartyd_build\dist\counterpartyd\lib\blocks.py", line 560, in get_tx_info 2 vin_ctx = proxy.getrawtransaction(vin.prevout.hash) File "C:\counterpartyd_build\env\lib\site-packages\bitcoin\rpc.py", line 307, in getrawt ransaction r = self._call('getrawtransaction', b2lx(txid), 1 if verbose else 0) File "C:\counterpartyd_build\env\lib\site-packages\bitcoin\rpc.py", line 144, in _call response = self._get_response() File "C:\counterpartyd_build\env\lib\site-packages\bitcoin\rpc.py", line 179, in _get_re sponse http_response = self.__conn.getresponse() File "C:\Python34\Lib\http\client.py", line 1172, in getresponse response.begin() File "C:\Python34\Lib\http\client.py", line 351, in begin version, status, reason = self._read_status() File "C:\Python34\Lib\http\client.py", line 313, in _read_status line = str(self.fp.readline(_MAXLINE + 1), "iso-8859-1") File "C:\Python34\Lib\socket.py", line 371, in readinto return self._sock.recv_into(b) socket.timeout: timed out

During handling of the above exception, another exception occurred:

Traceback (most recent call last): File "C:\counterpartyd_build\dist\counterpartyd\counterpartyd.py", line 956, in

blocks.follow(db)

File "C:\counterpartyd_build\dist\counterpartyd\lib\blocks.py", line 978, in follow except util.BitcoindError: AttributeError: 'module' object has no attribute 'BitcoindError'

[ghost]

replace except util.BitcoindError on line 978 of lib\blocks.py with except backend.BitcoindError and restart your daemon

[adamkrellenstein]

Yes, try this version: https://github.com/CounterpartyXCP/counterpartyd/commit/85f50601c06796d542e6fefc4581fa1abfa245c6

[adamkrellenstein]

It looks like python-bitcoinlib timed out connecting to Bitcoin Core. Does this happen every time you try to start counterpartyd? Immediately? Is Bitcoin Core really ready to start accepting connections?

(Feel free to downgrade to v9.49.1 until we get this fixed, by the way.)

[ghost]

I run the same version on Win 7, but develop branch, and haven't seen this problem. I started/stopped my counterpartyd server several times.

[mtbitcoin]

Restarted bitcoind, and tested with the latest master build. Runs ok this time.

[mtbitcoin]

Reopening issue. The issue should be reproducible by calling the counterpartyd api. I have tested this with the get_block_info and get_running_info API. After awhile it eventually crashes with the following log entry.

2014-12-21-T16:47:21Coordinated Universal Time ERROR: 
Traceback (most recent call last):
  File "C:\counterpartyd_build\dist\counterpartyd\counterpartyd.py", line 956, in <module>
    blocks.follow(db)
  File "C:\counterpartyd_build\dist\counterpartyd\lib\blocks.py", line 977, in follow
    mempool_tx_index = list_tx(db, None, block_index, curr_time, tx_hash, mempool_tx_index)
  File "C:\counterpartyd_build\dist\counterpartyd\lib\blocks.py", line 653, in list_tx
    source, destination, btc_amount, fee, data = get_tx_info(tx_dict['hex'], block_index)
  File "C:\counterpartyd_build\dist\counterpartyd\lib\blocks.py", line 341, in get_tx_info
    tx_info = get_tx_info2(tx_hex, block_parser=block_parser)
  File "C:\counterpartyd_build\dist\counterpartyd\lib\blocks.py", line 560, in get_tx_info2
    vin_ctx = proxy.getrawtransaction(vin.prevout.hash)
  File "C:\counterpartyd_build\env\lib\site-packages\bitcoin\rpc.py", line 307, in getrawtransaction
    r = self._call('getrawtransaction', b2lx(txid), 1 if verbose else 0)
  File "C:\counterpartyd_build\env\lib\site-packages\bitcoin\rpc.py", line 144, in _call
    response = self._get_response()
  File "C:\counterpartyd_build\env\lib\site-packages\bitcoin\rpc.py", line 179, in _get_response
    http_response = self.__conn.getresponse()
  File "C:\Python34\Lib\http\client.py", line 1172, in getresponse
    response.begin()
  File "C:\Python34\Lib\http\client.py", line 351, in begin
    version, status, reason = self._read_status()
  File "C:\Python34\Lib\http\client.py", line 313, in _read_status
    line = str(self.fp.readline(_MAXLINE + 1), "iso-8859-1")
  File "C:\Python34\Lib\socket.py", line 371, in readinto
    return self._sock.recv_into(b)
socket.timeout: timed out

[adamkrellenstein]

Hmm, I've changed the default timeout from 30s to 120s in develop. See 50e846383c763f992a4f2fc3c0eb9e36011b20e4. Try that, I guess?

[mtbitcoin]

Running the latest Develop I am getting the following error:

Traceback (most recent call last): File "C:\counterpartyd_build\dist\counterpartyd\counterpartyd.py", line 623, in

log.set_up(args)

File "C:\counterpartyd_build\dist\counterpartyd\lib\log.py", line 34, in set_up fileh = util_windows.SanitizedRotatingFileHandler(config.LOG, maxBytes=max_log_size, b ackupCount=5) NameError: name 'util_windows' is not defined

[adamkrellenstein]

@mtbitcoin, fixed.

I'm actually getting timeout errors myself, even with the new value. Looking into it.

[mtbitcoin]

Yup.. I am running it with just the modified line..now.. . and still the same timeout issues when an API is called...

-> proxy = bitcoinlib_rpc.Proxy(service_url=config.BACKEND_RPC, timeout=120)

I think if this is indeed an issue, some one should let the exchanges know so that they can hold of the new upgrades .....

[adamkrellenstein]

I don't think the problem has anything to do with the API---it seems to be happening rather randomly for me.

[adamkrellenstein]

Try using the patch in this commit: 685e1f32afabbf48499241b0514535bb93f8a95f

[mtbitcoin]

I have been able to consistently reproduce the error on my end If I call the API. I've let the it run Overnite and the moment I access the api's via curl it will go down shortly (not immediately). I don't think its the API per se causing the crash to, but perhaps something is getting locked when the bitcoin RPC calls gets used.

I noticed this earlier when I was running a some bitcoin rpc calls from another script and thought it had something to do with my custom script. But when I started using back the API's the same happened.

[adamkrellenstein]

So it takes some time after the API call before it goes down? How long? (Can you time it?) And it doesn't go down at all if you don't access the API?

Sorry, just to be clear, is it still happening with the patch from 685e1f3?

[mtbitcoin]

I did not time it But from my observation it does go down shortly... normally from maybe 10-20 secs to 1-2 minutes

And yes, its still happening with the 685e1f3 patch. Are you able to reproduce the issue on your end?

[adamkrellenstein]

Hm, no I am not able to reproduce it. I've seen a couple of socket.timeout errors, but only rarely, and with no connection to API calls (indeed, I've been stress testing with API calls, to both counterpartyd and bitcoind, and I can't get the server to crash).

[adamkrellenstein]

Wait, I was just able to reproduce it.

[adamkrellenstein]

If I run 1000 parallel get_running_info calls, the server hangs and crashes immediately---but only on master, and not on the latest develop.

[adamkrellenstein]

@mtbitcoin, when you run from develop do you still have the problem?

[ghost]

I'm seeing similar issues now when attempting to burn, but haven't had the time to investigate too deeply, possible issue with counterblockd?

[adamkrellenstein]

It doesn't have anything to do with counterblockd, which I'm not running.

[adamkrellenstein]

Pretty sure this is solved with those commits. Let me know if I'm wrong. ;)

[adamkrellenstein]

The problem with the API is gone, but I'm still seeing random timeouts.

[adamkrellenstein]

@ouziel-slama, if you have any ideas, don't hesitate!

[flaneur2020]

this bug could also be reproduced in v9.49.1, on executing counterpartyd server after counterparty rollback.

        Traceback (most recent call last):
          File "/home/mcp/counterpartyd_build/dist/counterpartyd/counterpartyd.py", line 962, in <module>
              blocks.follow(db)
            File "/home/mcp/counterpartyd_build/dist/counterpartyd/lib/blocks.py", line 1575, in follow
              tx_index = list_tx(db, block_hash, block_index, block_time, tx_hash, tx_index)
            File "/home/mcp/counterpartyd_build/dist/counterpartyd/lib/blocks.py", line 1320, in list_tx
              source, destination, btc_amount, fee, data = get_tx_info(tx['hex'], block_index)
            File "/home/mcp/counterpartyd_build/dist/counterpartyd/lib/blocks.py", line 1004, in get_tx_info
              tx_info = get_tx_info2(tx_hex, block_parser=block_parser)
            File "/home/mcp/counterpartyd_build/dist/counterpartyd/lib/blocks.py", line 1228, in get_tx_info2
              vin_ctx = rpc.getrawtransaction(vin.prevout.hash)
            File "/home/mcp/counterpartyd_build/env/lib/python3.4/site-packages/bitcoin/rpc.py", line 307, in getrawtransaction
              r = self._call('getrawtransaction', b2lx(txid), 1 if verbose else 0)
            File "/home/mcp/counterpartyd_build/env/lib/python3.4/site-packages/bitcoin/rpc.py", line 144, in _call
              response = self._get_response()
            File "/home/mcp/counterpartyd_build/env/lib/python3.4/site-packages/bitcoin/rpc.py", line 179, in _get_response
              http_response = self.__conn.getresponse()
            File "/usr/lib/python3.4/http/client.py", line 1173, in getresponse
              response.begin()
            File "/usr/lib/python3.4/http/client.py", line 351, in begin
              version, status, reason = self._read_status()
            File "/usr/lib/python3.4/http/client.py", line 313, in _read_status
              line = str(self.fp.readline(_MAXLINE + 1), "iso-8859-1")
            File "/usr/lib/python3.4/socket.py", line 374, in readinto
              return self._sock.recv_into(b)
          socket.timeout: timed out

[adamkrellenstein]

Doing some testing overnight.

Also, commit 962cae1 might help the issue by dramatically reducing the number times a httplib.HttpConnection is created by python-bitcoinlib.

[adamkrellenstein]

I've brought up the issue with python-bitcoinlib: https://github.com/petertodd/python-bitcoinlib/issues/35

[mtbitcoin]

Its a no go for me. Still running into the timeout issues with the latest develop. I am running windows so any timeout discrepancies could also be a result of the OS type

--
[INFO] Running v9.49.2 of counterpartyd.←[0m
[INFO] Connecting to backend.←[0m
[INFO] Checking version.←[0m
[INFO] Acquiring lock.←[0m
[INFO] Connecting to database.←[0m
[INFO] Connecting to block explorer.←[0m
[INFO] Resuming parsing.←[0m
[INFO] Order: 18jiKNgMx3XvVPXLFgeBTHfz7NpjAudCCX ordered 5000000 MEAT for 1.05 XCP in 10
 blocks, with a provided fee of 0.0002 BTC and a required fee of 0.0 BTC (cca6dcd3d2fe69
f12f101191a994e263d37431e0fb739ea74c809f2732bc19) [open]←[0m
[INFO] Order: 18jiKNgMx3XvVPXLFgeBTHfz7NpjAudCCX ordered 0.85 XCP for 5000000 MEAT in 10
 blocks, with a provided fee of 0.0002 BTC and a required fee of 0.0 BTC (bbbc082a4eec14
4f0cc1bda6a3a3571297a643fc8550fc2b0effbdd6defb88) [open]←[0m
[INFO] Cancel: 3277fa9cc5c3869315adc4bfc81641f9e270ed714112a26edb516b964be05d18 (497bbd9
c29caaa4643d3bab82112ee13fe40f0a6963cbdf3c66edbd218d115) [valid]←[0m
[INFO] Issuance: 1FpH8796RfK2kZUaUFYT4nxNLS4hkkwgQf created 1.0 of divisible asset HUSBA
 (dbe786d85077211557f003573466a924f0065c38eab5eb6025ffd57701407944) [valid]←[0m
[INFO] Issuance: 12gkFcPuuow6TRkK1MbqWgEcrChRSUm5LM transfered asset FRITOLAY to 13gPsUM
kGC1ecLf5hjRBFMW4qhv6xe4P (fd3622c198ef8d566d09fc58de0d1ccf2e91dd1e08ca41c4258e0c4a22d40
f) [valid]←[0m
[INFO] Issuance: 12gkFcPuuow6TRkK1MbqWgEcrChRSUm5LM transfered asset FROZENOJ to 13gPsUM
kGC1ecLf5hjRBFMW4qhv6xe4P (12fa20a6d858166baae1c58810d75b45d3b51fc58352dad720e9071be8ef8
c) [valid]←[0m
[INFO] Issuance: 12gkFcPuuow6TRkK1MbqWgEcrChRSUm5LM transfered asset FOXNEWS to 13gPsUMa
GC1ecLf5hjRBFMW4qhv6xe4P (850f12f492b136c365f3732af5c54420ae8368ead856238668af6f06b0677d
) [valid]←[0m
←[31m[ERROR] API Exception: {'args': ('timed out',), 'type': 'timeout', 'message': 'time
out'}←[0m
Traceback (most recent call last):
  File "C:\counterpartyd_build\env\lib\site-packages\jsonrpc\manager.py", line 88, in _g
_responses
    result = method(*request.args, **request.kwargs)
  File "C:\counterpartyd_build\dist\counterpartyd\lib\api.py", line 558, in get_running_
fo
    latestBlockIndex = proxy.getblockcount()
  File "C:\counterpartyd_build\env\lib\site-packages\bitcoin\rpc.py", line 160, in <lamb
>
    f = lambda *args: self._call(name, *args)
  File "C:\counterpartyd_build\env\lib\site-packages\bitcoin\rpc.py", line 144, in _call
    response = self._get_response()
  File "C:\counterpartyd_build\env\lib\site-packages\bitcoin\rpc.py", line 179, in _get_
sponse
    http_response = self.__conn.getresponse()
  File "C:\Python34\Lib\http\client.py", line 1172, in getresponse
    response.begin()
  File "C:\Python34\Lib\http\client.py", line 351, in begin
    version, status, reason = self._read_status()
  File "C:\Python34\Lib\http\client.py", line 313, in _read_status
    line = str(self.fp.readline(_MAXLINE + 1), "iso-8859-1")
  File "C:\Python34\Lib\socket.py", line 371, in readinto
    return self._sock.recv_into(b)
socket.timeout: timed out←[0m

[adamkrellenstein]

@mtbitcoin, I'm going to ask you to try more things, as the problem seems to be worse on your system than elsewhere.

Try with this patch to the latest version from develop:

diff --git a/lib/backend.py b/lib/backend.py
index eac1864..4805605 100644
--- a/lib/backend.py
+++ b/lib/backend.py
@@ -15,9 +15,11 @@ from lib import script
 from lib import config

 def get_proxy():
+    import  socket
+    socket.setdefaulttimeout(100000)
     if config.TESTNET:
         bitcoinlib.SelectParams('testnet')
-    proxy = bitcoinlib_rpc.Proxy(service_url=config.BACKEND_RPC)
+    proxy = bitcoinlib_rpc.Proxy(service_url=config.BACKEND_RPC, timeout=100000)
     return proxy

[ghost]

I just pulled the latest, removed the counterpartyd db and I'm no longer receiving timeouts- you might have luck with that too @mtbitcoin

[adamkrellenstein]

Removing the database should have no real effect, though it may mask the problem.

[adamkrellenstein]

@mtbitcoin, also try the above patch with very small values (e.g. 0.0001), to see if that triggers the problem more readily.

[ghost]

Removing the database should have no real effect, though it may mask the problem.

Very true, and I was just going to add our timeouts may have not be related to begin with

[ghost]

hate to be a parrot, but i'm still getting timeouts when checking balances, investigating now...

full trace:

 python3 counterparty-cli.py --testnet --unconfirmed --data-dir=/home/ubuntu/.config/counterpartyd/ balances mvMqLp7NhrPcUkMznrBA6TkJAzHoVKqvif                 
Traceback (most recent call last):
  File "counterparty-cli.py", line 970, in <module>
    balances(args.address)
  File "counterparty-cli.py", line 505, in balances
    btc_balance = backend.get_btc_balance(address)
  File "/home/ubuntu/counterpartyd_build/dist/counterpartyd/lib/backend.py", line 230, in get_btc_balance
    all_unspent, confirmed_unspent = get_unspent_txouts(address, return_confirmed=True)
  File "/home/ubuntu/counterpartyd_build/dist/counterpartyd/lib/backend.py", line 181, in get_unspent_txouts
    raw_transactions = blockchain.searchrawtransactions(source)
  File "/home/ubuntu/counterpartyd_build/dist/counterpartyd/lib/blockchain/__init__.py", line 17, in searchrawtransactions
    return sys.modules['lib.blockchain.{}'.format(config.BLOCKCHAIN_SERVICE_NAME)].searchrawtransactions(address)
  File "/home/ubuntu/counterpartyd_build/dist/counterpartyd/lib/blockchain/blockr.py", line 19, in searchrawtransactions
    unconfirmed = backend.unconfirmed_transactions(address)
  File "/home/ubuntu/counterpartyd_build/dist/counterpartyd/lib/backend.py", line 107, in unconfirmed_transactions
    batch_responses = get_proxy()._batch(call_list)
  File "/usr/local/lib/python3.4/dist-packages/bitcoin/rpc.py", line 176, in _batch
    return self._get_response()
  File "/usr/local/lib/python3.4/dist-packages/bitcoin/rpc.py", line 179, in _get_response
    http_response = self.__conn.getresponse()
  File "/usr/lib/python3.4/http/client.py", line 1172, in getresponse
    response.begin()
  File "/usr/lib/python3.4/http/client.py", line 351, in begin
    version, status, reason = self._read_status()
  File "/usr/lib/python3.4/http/client.py", line 313, in _read_status
    line = str(self.fp.readline(_MAXLINE + 1), "iso-8859-1")
  File "/usr/lib/python3.4/socket.py", line 371, in readinto
    return self._sock.recv_into(b)
socket.timeout: timed out

[ghost]

analysis suggests timing out in 'backend' module:

diff --git a/lib/blockchain/blockr.py b/lib/blockchain/blockr.py
index 0cae361..6e31ef4 100644
--- a/lib/blockchain/blockr.py
+++ b/lib/blockchain/blockr.py
@@ -16,8 +16,9 @@ def check():
     pass

 def searchrawtransactions(address):
+    print('1')
     unconfirmed = backend.unconfirmed_transactions(address)
-
+    print('got here')

     confirmed = []
     txs = util.get_url(get_host() + '/api/v1/address/txs/{}'.format(address), abort_on_error=True)
     if 'status' in txs and txs['status'] == 'success':

output:

 python3 counterparty-cli.py --testnet --unconfirmed --data-dir=/home/ubuntu/.config/counterpartyd/ balances mvMqLp7NhrPcUkMznrBA6TkJAzHoVKqvif
1
Traceback (most recent call last):
[stack trace]

[adamkrellenstein]

Update: it seems that socket.setdefaulttimeout($FOO) bitcoinlib_rpc.Proxy(..., timeout=$FOO) are irrelevant here. socket.timeout always appears after 30 seconds, and sometimes Bitcoin Core really does take that long to fill a request.

[adamkrellenstein]

Solution: There was a bug in python-bitcoinlib which was fixed in 0.3.0 with this commit: https://github.com/petertodd/python-bitcoinlib/commit/82d6d9579b6dc806e3052f3ac6954ab134849e62

See 478ce03796ada4b826a5051f70443b464ccf12ec and #551.

I pushed a hotfix to master, as well. (It won't have any effect until python-bitcoinlib is upgraded, or the above patch manually applied, however.)

[ghost]

I disagree here, I just pulled up 0.3.0 with the extended timeout and am still hung, I did more digging and its this call that's failing (https://github.com/petertodd/python-bitcoinlib/blob/master/bitcoin/rpc.py#L126-L128):

            self.__conn = httplib.HTTPConnection(self.__url.hostname, port=port,
                                                 timeout=timeout)

this is in the RawProxy class, which is extended from Proxy; the fix you listed (https://github.com/petertodd/python-bitcoinlib/commit/82d6d9579b6dc806e3052f3ac6954ab134849e62) only correctly passes the timeout, but I still get timed out when attempting a connection.

I don't see this when using the same call to connect to a HTTP server, so perhaps there's something deeper at play, or perhaps I'm just wrong.

[flaneur2020]

@faizkhan00 +1

[flaneur2020]

I wonder if the root cause is the performance issue of searchrawtransactions ?

[ghost]

I don't think so @Fleurer , because I added logging to the HTTPConnection module and I'm seeing this call succeed (https://github.com/CounterpartyXCP/counterpartyd/blob/develop/lib/backend.py#L99) : old_rpc('getrawmempool', []) which uses the requests library on the backend. This makes me believe the state of the HTTP object is being mismanaged by python-bitcoinlib.

[flaneur2020]

@faizkhan00 hmm... pretty weird.

[mtbitcoin]

@adamkrellenstein Where/how do we get the version 0.3.0 of the python-bitcoinlib ? I am doing a pip install and the only version I can get is 0.2.x

[mtbitcoin]

Actually I first noticed this when I was calling the old_rpc('getrawmempool') from a slightly modified script

[ghost]

@mtbitcoin, https://github.com/petertodd/python-bitcoinlib/releases/tag/python-bitcoinlib-v0.3.0

[mtbitcoin]

I am still getting the same issues with 0.3.0 and the latest develop.

@faizkhan00 did the latest commits work for you?

I am currently reverting back to master for now.

[ghost]

No they did not.

I am still debugging, my idea about reusing requests urllib3 didn't work, I'm trying other things.

[ghost]

Here's the workaround guys, simple 1-liner fix:

batch_responses = [old_rpc(r['method'], r['params']) for r in call_list ]

This replaces the method used to get the data using a older method. This should probably be improved via a fallback mechanism, later

full diff: http://0bin.net/paste/EpYO39ac0k3reufd#A3LACorHw02icsYWgyw1T6Nlcz5IHh+N-D+13eQ3ibj

[adamkrellenstein]

@mtbitcoin, @Fleurer, does @faizkhan00's fix work for you? (in addition to the changes I made)

[adamkrellenstein]

@ouziel-slama, what's the best way to fix that batch RPC call, if indeed that's that's the real problem? (It seems very strange to me that it would be.)