bigchaindb: cannot post transactions WORKER TIMEOUT

Bug Report

What computer are you on (hardware)? VMWare Workstation 14 Player
What operating system are you using, including version. e.g. Ubuntu 14.04? Fedora 23? Debian 9.4.0
What version of BigchainDB software were you using? Is that the latest version? v2.0.0a6

Hi,

I am running a local instance of BigchainDB using make run. It is a stock version of bigchaindb which is cloned from the repository with no changes.

I am experiencing an issue where I loose the ability to post new transactions to the chain. Retrieving existing transactions still works.

I have attached a python script that can replicate this problem. All it does is continuously post transactions to the bigchaindb node. At around transaction number 136 the python driver times out and the script crashes. After this no more transactions to the chain are possible. If more transactions are attempted the bigchaindb will have the following error bigchaindb_1 | [2018-05-31 00:48:02] [CRITICAL] (gunicorn.error) WORKER TIMEOUT (pid:46) (webapi - pid: 32)

from bigchaindb_driver import BigchainDB
from bigchaindb_driver.crypto import generate_keypair
import time

#taken stragiht off https://docs.bigchaindb.com/projects/py-driver/en/latest/usage.html
def transaction(bdb):
	bicycle = {
	'data': {
		'bicycle': {
		'serial_number': 'abcd1234',
		'manufacturer': 'bkfab',
		},
	}}
	alice = generate_keypair()
	prepared_creation_tx = bdb.transactions.prepare(
	operation='CREATE',
	signers=alice.public_key,
	asset=bicycle,
	)
	fulfilled_creation_tx = bdb.transactions.fulfill(prepared_creation_tx, private_keys=alice.private_key)
	sent_creation_tx      = bdb.transactions.send(fulfilled_creation_tx)
	print(str(sent_creation_tx == fulfilled_creation_tx))


def run():
	bdb = BigchainDB("http://192.168.239.131:9984")
	count = 0
	while True:
		start_time= time.perf_counter()
		transaction(bdb)
		duration = time.perf_counter() - start_time
		count = count + 1
		print("Request " + str(count) + " took " + str(duration) + " ms")


if __name__ == '__main__':
	run()

Here are the logs for the test script and for the bigchaindb node.

bigchaindb_1         | [2018-05-31 00:47:31] [DEBUG] (bigchaindb.tendermint.core) check_tx: b'{"inputs": [{"owners_before": ["3i7evvYbN3XT2oJEM9biGDrA9tpEsvZG8Yh9tsQBUhKh"], "fulfills": null, "fulfillment": "pGSAICg_te9ALDpEcJkUYFutd8gS892Tfy3NzNmSjyVdlLQUgUB6rTKf2OjqZFAA2zcxvZ9jqurxI0kSm9bhLhj-y3_ZHS2IWvrs19A6T-tC7em8e8NCAEqTb0ePB7ZdV411VgEK"}], "outputs": [{"public_keys": ["3i7evvYbN3XT2oJEM9biGDrA9tpEsvZG8Yh9tsQBUhKh"], "condition": {"details": {"type": "ed25519-sha-256", "public_key": "3i7evvYbN3XT2oJEM9biGDrA9tpEsvZG8Yh9tsQBUhKh"}, "uri": "ni:///sha-256;mA7b2G7SDA7abHMPcUSQdX0HaNQq87KJiANQ3uBHMkY?fpt=ed25519-sha-256&cost=131072"}, "amount": "1"}], "operation": "CREATE", "metadata": null, "asset": {"data": {"bicycle": {"serial_number": "abcd1234", "manufacturer": "bkfab"}}}, "version": "2.0", "id": "854facdae529bb41c1702116b48fac78d75982c1481900b585e5adacc47fa52d"}' (MainProcess - pid: 7)

bigchaindb_1         | [2018-05-31 00:47:31] [DEBUG] (bigchaindb.tendermint.core) check_tx: VALID (MainProcess - pid: 7)

bigchaindb_1         | [2018-05-31 00:47:31] [DEBUG] (bigchaindb.tendermint.core) deliver_tx: b'{"inputs": [{"owners_before": ["3i7evvYbN3XT2oJEM9biGDrA9tpEsvZG8Yh9tsQBUhKh"], "fulfills": null, "fulfillment": "pGSAICg_te9ALDpEcJkUYFutd8gS892Tfy3NzNmSjyVdlLQUgUB6rTKf2OjqZFAA2zcxvZ9jqurxI0kSm9bhLhj-y3_ZHS2IWvrs19A6T-tC7em8e8NCAEqTb0ePB7ZdV411VgEK"}], "outputs": [{"public_keys": ["3i7evvYbN3XT2oJEM9biGDrA9tpEsvZG8Yh9tsQBUhKh"], "condition": {"details": {"type": "ed25519-sha-256", "public_key": "3i7evvYbN3XT2oJEM9biGDrA9tpEsvZG8Yh9tsQBUhKh"}, "uri": "ni:///sha-256;mA7b2G7SDA7abHMPcUSQdX0HaNQq87KJiANQ3uBHMkY?fpt=ed25519-sha-256&cost=131072"}, "amount": "1"}], "operation": "CREATE", "metadata": null, "asset": {"data": {"bicycle": {"serial_number": "abcd1234", "manufacturer": "bkfab"}}}, "version": "2.0", "id": "854facdae529bb41c1702116b48fac78d75982c1481900b585e5adacc47fa52d"}' (MainProcess - pid: 7)

bigchaindb_1         | [2018-05-31 00:47:31] [DEBUG] (bigchaindb.tendermint.core) storing tx (MainProcess - pid: 7)

bigchaindb_1         | [2018-05-31 00:47:31] [DEBUG] (bigchaindb.tendermint.core) Updating PreCommitState: 137 (MainProcess - pid: 7)

bigchaindb_1         | [2018-05-31 00:47:31] [DEBUG] (bigchaindb.tendermint.core) Commit-ing new block with hash: apphash=b'f4856e74b1edf17f92bb44e88aae5ca0ef323b0cca77f290ec32e3383a125c84' ,height=137, txn ids=['854facdae529bb41c1702116b48fac78d75982c1481900b585e5adacc47fa52d'] (MainProcess - pid: 7)

bigchaindb_1         | [2018-05-31 00:47:31] [DEBUG] (urllib3.connectionpool) http://tendermint:46657 "POST / HTTP/1.1" 200 247 (webapi     - pid: 46)

bigchaindb_1         | [2018-05-31 00:47:31] [DEBUG] (bigchaindb.tendermint.lib) {'jsonrpc': '2.0', 'id': '14d06885-b6ab-4ede-bfa4-7cfedcd69475', 'result': {'check_tx': {'fee': {}}, 'deliver_tx': {'fee': {}}, 'hash': 'A2AA6E43132C1FF11BA5380C85E1318C9E2AFB67', 'height': 137}} (webapi     - pid: 46)

bigchaindb_1         | [2018-05-31 00:47:31] [DEBUG] (gunicorn.error) POST /api/v1/transactions/ (webapi     - pid: 46)

bigchaindb_1         | [2018-05-31 00:47:31] [DEBUG] (urllib3.connectionpool) Starting new HTTP connection (1): tendermint (webapi     - pid: 46)

bigchaindb_1         | [2018-05-31 00:47:31] [DEBUG] (bigchaindb.tendermint.core) check_tx: b'{"inputs": [{"owners_before": ["14sGcnSjBHmz6ihzxR6F9TAuykiNHEcEoEnhSsrvxQrb"], "fulfills": null, "fulfillment": "pGSAIAD9lQHGIVQ-Kcsp7GbLjrDoH8QuM2sYT1zwvJ3c9j0AgUDzjY3txMcaS91gE28t7Y9a4AeZUd2D7MwHw_ktFlNu6QZXZQ2qGvnstks39RXB8G2w404uDvXS9DfgPsSOrGgB"}], "outputs": [{"public_keys": ["14sGcnSjBHmz6ihzxR6F9TAuykiNHEcEoEnhSsrvxQrb"], "condition": {"details": {"type": "ed25519-sha-256", "public_key": "14sGcnSjBHmz6ihzxR6F9TAuykiNHEcEoEnhSsrvxQrb"}, "uri": "ni:///sha-256;Ype3jMID_J7Rr3Nqwn1X_4kYyiQGfAGl9MfQqIvi43g?fpt=ed25519-sha-256&cost=131072"}, "amount": "1"}], "operation": "CREATE", "metadata": null, "asset": {"data": {"bicycle": {"serial_number": "abcd1234", "manufacturer": "bkfab"}}}, "version": "2.0", "id": "5821963d2ad063abec03279a2f6e74315eee180d9873165bba6967b4d69d338a"}' (MainProcess - pid: 7)

bigchaindb_1         | [2018-05-31 00:47:31] [DEBUG] (bigchaindb.tendermint.core) check_tx: VALID (MainProcess - pid: 7)

bigchaindb_1         | [2018-05-31 00:47:32] [DEBUG] (gunicorn.error) GET / (webapi     - pid: 40)

bigchaindb_1         | [2018-05-31 00:47:40] [DEBUG] (gunicorn.error) GET / (webapi     - pid: 47)

bigchaindb_1         | [2018-05-31 00:47:48] [DEBUG] (gunicorn.error) GET / (webapi     - pid: 47)

bigchaindb_1         | [2018-05-31 00:47:56] [DEBUG] (gunicorn.error) GET / (webapi     - pid: 48)

bigchaindb_1         | [2018-05-31 00:48:02] [CRITICAL] (gunicorn.error) WORKER TIMEOUT (pid:46) (webapi     - pid: 32)

bigchaindb_1         | [2018-05-31 00:48:02] [INFO] (gunicorn.error) Worker exiting (pid: 46) (webapi     - pid: 46)

bigchaindb_1         | [2018-05-31 00:48:02] [INFO] (gunicorn.error) Booting worker with pid: 282 (webapi     - pid: 282)

bigchaindb_1         | [2018-05-31 00:48:04] [DEBUG] (gunicorn.error) GET / (webapi     - pid: 45)

bigchaindb_1         | [2018-05-31 00:48:12] [DEBUG] (gunicorn.error) GET / (webapi     - pid: 45)

bigchaindb_1         | [2018-05-31 00:48:20] [DEBUG] (gunicorn.error) GET / (webapi     - pid: 45)

bigchaindb_1         | [2018-05-31 00:48:28] [DEBUG] (gunicorn.error) GET / (webapi     - pid: 47)

bigchaindb_1         | [2018-05-31 00:48:36] [DEBUG] (gunicorn.error) GET / (webapi     - pid: 45)



bc_write_test.py

True

Request 1 took 0.3851399999111891 ms

True

Request 2 took 0.2983849998563528 ms

True

Request 3 took 0.2989600000437349 ms

True

Request 4 took 0.29390299995429814 ms

True

Request 5 took 0.3301530000753701 ms

True

Request 6 took 0.282039999961853 ms

True

Request 7 took 0.305832999991253 ms

True

Request 8 took 0.28957999986596406 ms

True

Request 9 took 0.2842900000978261 ms

True

Request 10 took 0.2766459998674691 ms

True

Request 11 took 0.28009899985045195 ms

True

Request 12 took 0.28295599995180964 ms

True

Request 13 took 0.27965199993923306 ms

True

Request 14 took 0.3052519999910146 ms

True

Request 15 took 0.2831640001386404 ms

True

Request 16 took 0.2811060000676662 ms

True

Request 17 took 0.2817710000090301 ms

True

Request 18 took 0.28539300011470914 ms

True

Request 19 took 0.284599999897182 ms

True

Request 20 took 0.274807000067085 ms

True

Request 21 took 0.30002299998886883 ms

True

Request 22 took 0.31183800008147955 ms

True

Request 23 took 0.2828750000335276 ms

True

Request 24 took 0.2795019999612123 ms

True

Request 25 took 0.28151399991475046 ms

True

Request 26 took 0.27785399998538196 ms

True

Request 27 took 0.30606800015084445 ms

True

Request 28 took 0.2862989997956902 ms

True

Request 29 took 0.28521499992348254 ms

True

Request 30 took 0.28926300001330674 ms

True

Request 31 took 0.2832510001026094 ms

True

Request 32 took 0.280849999981001 ms

True

Request 33 took 0.27969200001098216 ms

True

Request 34 took 0.2881120000965893 ms

True

Request 35 took 0.29202799987979233 ms

True

Request 36 took 0.2850559998769313 ms

True

Request 37 took 0.2817730000242591 ms

True

Request 38 took 0.28188300016336143 ms

True

Request 39 took 0.2919880000408739 ms

True

Request 40 took 0.2919850000180304 ms

True

Request 41 took 0.3016160000115633 ms

True

Request 42 took 0.2805259998422116 ms

True

Request 43 took 0.28004799992777407 ms

True

Request 44 took 0.2958070000167936 ms

True

Request 45 took 0.29105100012384355 ms

True

Request 46 took 0.28280699998140335 ms

True

Request 47 took 0.2900829999707639 ms

True

Request 48 took 0.28321800008416176 ms

True

Request 49 took 0.27994799986481667 ms

True

Request 50 took 0.2873549999203533 ms

True

Request 51 took 0.28680099989287555 ms

True

Request 52 took 0.2890009998809546 ms

True

Request 53 took 0.28581300005316734 ms

True

Request 54 took 0.2854949999600649 ms

True

Request 55 took 0.2786970001179725 ms

True

Request 56 took 0.2892359998077154 ms

True

Request 57 took 0.3801780000794679 ms

True

Request 58 took 0.2828259998932481 ms

True

Request 59 took 0.28144099982455373 ms

True

Request 60 took 0.28106100019067526 ms

True

Request 61 took 0.28629499999806285 ms

True

Request 62 took 0.2851150000933558 ms

True

Request 63 took 0.2892259999644011 ms

True

Request 64 took 0.2863499999511987 ms

True

Request 65 took 0.2808989998884499 ms

True

Request 66 took 0.2797000000718981 ms

True

Request 67 took 0.282751000020653 ms

True

Request 68 took 0.2775250000413507 ms

True

Request 69 took 0.2842669999226928 ms

True

Request 70 took 0.29466000013053417 ms

True

Request 71 took 0.27923200000077486 ms

True

Request 72 took 0.282981000142172 ms

True

Request 73 took 0.2874710001051426 ms

True

Request 74 took 0.28940200014039874 ms

True

Request 75 took 0.2799419998191297 ms

True

Request 76 took 0.2741010000463575 ms

True

Request 77 took 0.27919399994425476 ms

True

Request 78 took 0.2810749998316169 ms

True

Request 79 took 0.3123109999578446 ms

True

Request 80 took 0.28334500011987984 ms

True

Request 81 took 0.2790460002142936 ms

True

Request 82 took 0.27995400014333427 ms

True

Request 83 took 0.2888970000203699 ms

True

Request 84 took 0.2877400000579655 ms

True

Request 85 took 0.29290000000037253 ms

True

Request 86 took 0.2828229998704046 ms

True

Request 87 took 0.2748709998559207 ms

True

Request 88 took 0.28065100009553134 ms

True

Request 89 took 0.28362299990840256 ms

True

Request 90 took 0.2810360000003129 ms

True

Request 91 took 0.28321800008416176 ms

True

Request 92 took 0.27882299991324544 ms

True

Request 93 took 0.3307990001048893 ms

True

Request 94 took 0.28577199997380376 ms

True

Request 95 took 0.2788349997717887 ms

True

Request 96 took 0.2873309999704361 ms

True

Request 97 took 0.2806160000618547 ms

True

Request 98 took 0.28355600009672344 ms

True

Request 99 took 0.28397799981758 ms

True

Request 100 took 0.28392399987205863 ms

True

Request 101 took 0.2894340001512319 ms

True

Request 102 took 0.29093799996189773 ms

True

Request 103 took 0.2857929999008775 ms

True

Request 104 took 0.2781799999065697 ms

True

Request 105 took 0.2814150000922382 ms

True

Request 106 took 0.2872279998846352 ms

True

Request 107 took 0.2839420000091195 ms

True

Request 108 took 0.2813280001282692 ms

True

Request 109 took 0.2952729999087751 ms

True

Request 110 took 0.28753099986352026 ms

True

Request 111 took 0.2850359999574721 ms

True

Request 112 took 0.2849840000271797 ms

True

Request 113 took 0.2767580000218004 ms

True

Request 114 took 0.3164439999964088 ms

True

Request 115 took 0.28807300003245473 ms

True

Request 116 took 0.2788790001068264 ms

True

Request 117 took 0.27819699980318546 ms

True

Request 118 took 0.2770650000311434 ms

True

Request 119 took 0.28390200017020106 ms

True

Request 120 took 0.2831979999318719 ms

True

Request 121 took 0.277191000059247 ms

True

Request 122 took 0.2831230000592768 ms

True

Request 123 took 0.28787400014698505 ms

True

Request 124 took 0.293781999964267 ms

True

Request 125 took 0.28645800007507205 ms

True

Request 126 took 0.28510300000198185 ms

True

Request 127 took 0.2894520000554621 ms

True

Request 128 took 0.29509299993515015 ms

True

Request 129 took 0.27988599985837936 ms

True

Request 130 took 0.2899150000885129 ms

True

Request 131 took 0.28310199989937246 ms

True

Request 132 took 0.2801380001474172 ms

True

Request 133 took 0.27915699989534914 ms

True

Request 134 took 0.2853079999331385 ms

True

Request 135 took 0.33356499997898936 ms

True

Request 136 took 0.34042100002989173 ms

Traceback (most recent call last):

  File "/usr/local/lib/python3.5/dist-packages/urllib3/connectionpool.py", line 601, in urlopen

    chunked=chunked)

  File "/usr/local/lib/python3.5/dist-packages/urllib3/connectionpool.py", line 387, in _make_request

    six.raise_from(e, None)

  File "<string>", line 2, in raise_from

  File "/usr/local/lib/python3.5/dist-packages/urllib3/connectionpool.py", line 383, in _make_request

    httplib_response = conn.getresponse()

  File "/usr/lib/python3.5/http/client.py", line 1197, in getresponse

    response.begin()

  File "/usr/lib/python3.5/http/client.py", line 297, in begin

    version, status, reason = self._read_status()

  File "/usr/lib/python3.5/http/client.py", line 266, in _read_status

    raise RemoteDisconnected("Remote end closed connection without"

http.client.RemoteDisconnected: Remote end closed connection without response

During handling of the above exception, another exception occurred:

Traceback (most recent call last):

  File "/usr/local/lib/python3.5/dist-packages/requests/adapters.py", line 440, in send

    timeout=timeout

  File "/usr/local/lib/python3.5/dist-packages/urllib3/connectionpool.py", line 639, in urlopen

    _stacktrace=sys.exc_info()[2])

  File "/usr/local/lib/python3.5/dist-packages/urllib3/util/retry.py", line 357, in increment

    raise six.reraise(type(error), error, _stacktrace)

  File "/usr/local/lib/python3.5/dist-packages/urllib3/packages/six.py", line 685, in reraise

    raise value.with_traceback(tb)

  File "/usr/local/lib/python3.5/dist-packages/urllib3/connectionpool.py", line 601, in urlopen

    chunked=chunked)

  File "/usr/local/lib/python3.5/dist-packages/urllib3/connectionpool.py", line 387, in _make_request

    six.raise_from(e, None)

  File "<string>", line 2, in raise_from

  File "/usr/local/lib/python3.5/dist-packages/urllib3/connectionpool.py", line 383, in _make_request

    httplib_response = conn.getresponse()

  File "/usr/lib/python3.5/http/client.py", line 1197, in getresponse

    response.begin()

  File "/usr/lib/python3.5/http/client.py", line 297, in begin

    version, status, reason = self._read_status()

  File "/usr/lib/python3.5/http/client.py", line 266, in _read_status

    raise RemoteDisconnected("Remote end closed connection without"

urllib3.exceptions.ProtocolError: ('Connection aborted.', RemoteDisconnected('Remote end closed connection without response',))

During handling of the above exception, another exception occurred:

Traceback (most recent call last):

  File "bc_write_test.py", line 37, in <module>

    run()

  File "bc_write_test.py", line 30, in run

    transaction(bdb)

  File "bc_write_test.py", line 21, in transaction

    sent_creation_tx      = bdb.transactions.send(fulfilled_creation_tx)

  File "/usr/local/lib/python3.5/dist-packages/bigchaindb_driver-0.5.0a4-py3.5.egg/bigchaindb_driver/driver.py", line 332, in send

    headers=headers)

  File "/usr/local/lib/python3.5/dist-packages/bigchaindb_driver-0.5.0a4-py3.5.egg/bigchaindb_driver/transport.py", line 58, in forward_request

    headers=headers,

  File "/usr/local/lib/python3.5/dist-packages/bigchaindb_driver-0.5.0a4-py3.5.egg/bigchaindb_driver/connection.py", line 48, in request

    **kwargs

  File "/usr/local/lib/python3.5/dist-packages/requests/sessions.py", line 508, in request

    resp = self.send(prep, **send_kwargs)

  File "/usr/local/lib/python3.5/dist-packages/requests/sessions.py", line 618, in send

    r = adapter.send(request, **kwargs)

  File "/usr/local/lib/python3.5/dist-packages/requests/adapters.py", line 490, in send

    raise ConnectionError(err, request=request)

requests.exceptions.ConnectionError: ('Connection aborted.', RemoteDisconnected('Remote end closed connection without response',)

About this issue

Original URL
State: closed
Created 6 years ago
Comments: 19 (11 by maintainers)

Commits related to this issue

Problem: Tendermint RPC server gets stuck. Solution: Upgrade Tendermint to v0.19.0. Fixes #2322. — committed to ldmberman/bigchaindb by ldmberman 6 years ago
Problem: Tendermint RPC server gets stuck. Solution: Upgrade Tendermint to v0.19.0. Fixes #2322. — committed to ldmberman/bigchaindb by ldmberman 6 years ago
Problem: Tendermint RPC server gets stuck. (#2337) Solution: Upgrade Tendermint to v0.19.0. Fixes #2322. — committed to bigchaindb/bigchaindb by ldmberman 6 years ago
Problem: Tendermint freezes due to docker-compose bug. Solution: Do not rely on depends_on when running containers in the foreground. Solves #2322. — committed to ldmberman/bigchaindb by ldmberman 6 years ago
Problem: Tendermint freezes due to docker-compose bug. Solution: Do not rely on depends_on when running containers in the foreground. Solves #2322. — committed to ldmberman/bigchaindb by ldmberman 6 years ago
Problem: Tendermint freezes due to docker-compose bug. (#2341) Solution: Do not rely on depends_on when running containers in the foreground. Solves #2322. — committed to bigchaindb/bigchaindb by ldmberman 6 years ago

Most upvoted comments

@ldmberman Maybe let’s wait for Tendermint v0.20.0. They have been pushing new versions very often lately, so we probably won’t have to wait long.

ttmc on Jun 4, 2018