kyuupichan / electrumx Goto Github PK

It's easy to hammer bitcoind with async requests causing it to panic with "workflow depth exceeded"

I'm not sure if these are my problem or an asyncio issue, as I don't immediately see how I have control over this:

2016-11-10 23:34:54.130892500 INFO:BlockServer:flush #310 to height 438,232 txs: 169,621,221 took 5s
2016-11-10 23:34:54.818801500 ERROR:asyncio:Task was destroyed but it is pending!
2016-11-10 23:34:54.818807500 task: <Task pending coro=<BaseSelectorEventLoop._accept_connection2() done, defined at /usr/local/lib/python3.5/asyncio/selector_events.py:192> wait_for=>
2016-11-10 23:35:00.566001500 INFO:MemPool:10,924 txs touching 22,790 addresses

Currently, if your bitcoin daemon goes offline, electrumx is basically offline too.

It would be nice if one could specify multiple bitcoin daemons as a failsafe.

The biggest problem about this is probably how to configure more than one daemon.

This is just confusing:

DAEMON_HOST=a.bitcoind.com;b.bitcoind.com
DAEMON_PORT=1234;54321
....

This isn't great either:

DAEMON_HOST.1=a.bitcoind.com
DAEMON_HOST.2=b.bitcoind.com
DAEMON_PORT.1=1234
DAEMON_PORT.2=54321
...

We should start serving immediately; mempool can be done asynchronously

Running 0.7.6

Nov 24 06:31:57 electrum electrumx_server.py[8385]: INFO:BlockProcessor:chain reorg detected
Nov 24 06:31:57 electrum electrumx_server.py[8385]: INFO:BlockProcessor:finding common height...
Nov 24 06:31:57 electrum electrumx_server.py[8385]: INFO:BlockProcessor:chain was reorganised for 1 blocks over heights 440,364-440,364 inclusive
Nov 24 06:31:57 electrum electrumx_server.py[8385]: INFO:MemPool:50,168 txs touching 194,297 addresses
Nov 24 06:31:57 electrum electrumx_server.py[8385]: INFO:BlockProcessor:backing up 1 blocks
Nov 24 06:31:59 electrum electrumx_server.py[8385]: INFO:BlockProcessor:backed up to height 440,363
Nov 24 06:31:59 electrum electrumx_server.py[8385]: INFO:BlockProcessor:backing up history to height 440,363 tx_count 173,355,460
Nov 24 06:33:04 electrum electrumx_server.py[8385]: INFO:BlockProcessor:removed 5,131 history entries from 4,626 addresses
Nov 24 06:33:05 electrum electrumx_server.py[8385]: INFO:BlockProcessor:flush #568 took 65.5s. Height 440,363 txs: 173,355,460
Nov 24 06:33:05 electrum electrumx_server.py[8385]: INFO:BlockProcessor:prefetcher reset
Nov 24 06:33:05 electrum electrumx_server.py[8385]: Traceback (most recent call last):
Nov 24 06:33:05 electrum electrumx_server.py[8385]: File "/usr/local/lib/python3.5/dist-packages/electrumx-0.7.6-py3.5.egg/EGG-INFO/scripts/electrumx_server.py", line 67, in main
Nov 24 06:33:05 electrum electrumx_server.py[8385]: File "/usr/local/lib/python3.5/dist-packages/electrumx-0.7.6-py3.5.egg/EGG-INFO/scripts/electrumx_server.py", line 58, in main_loop
Nov 24 06:33:05 electrum electrumx_server.py[8385]: File "/usr/lib/python3.5/asyncio/base_events.py", line 387, in run_until_complete
Nov 24 06:33:05 electrum electrumx_server.py[8385]: return future.result()
Nov 24 06:33:05 electrum electrumx_server.py[8385]: File "/usr/lib/python3.5/asyncio/futures.py", line 274, in result
Nov 24 06:33:05 electrum electrumx_server.py[8385]: raise self._exception
Nov 24 06:33:05 electrum electrumx_server.py[8385]: File "/usr/lib/python3.5/asyncio/tasks.py", line 239, in _step
Nov 24 06:33:05 electrum electrumx_server.py[8385]: result = coro.send(None)
Nov 24 06:33:05 electrum electrumx_server.py[8385]: File "/usr/local/lib/python3.5/dist-packages/electrumx-0.7.6-py3.5.egg/server/protocol.py", line 263, in main_loop
Nov 24 06:33:05 electrum electrumx_server.py[8385]: await future # Note: future is not one of self.futures
Nov 24 06:33:05 electrum electrumx_server.py[8385]: File "/usr/lib/python3.5/asyncio/tasks.py", line 492, in _wait_for_one
Nov 24 06:33:05 electrum electrumx_server.py[8385]: return f.result() # May raise f.exception().
Nov 24 06:33:05 electrum electrumx_server.py[8385]: File "/usr/lib/python3.5/asyncio/futures.py", line 274, in result
Nov 24 06:33:05 electrum electrumx_server.py[8385]: raise self._exception
Nov 24 06:33:05 electrum electrumx_server.py[8385]: File "/usr/lib/python3.5/asyncio/tasks.py", line 239, in _step
Nov 24 06:33:05 electrum electrumx_server.py[8385]: result = coro.send(None)
Nov 24 06:33:05 electrum electrumx_server.py[8385]: File "/usr/local/lib/python3.5/dist-packages/electrumx-0.7.6-py3.5.egg/server/block_processor.py", line 195, in main_loop
Nov 24 06:33:05 electrum electrumx_server.py[8385]: await self._wait_for_update()
Nov 24 06:33:05 electrum electrumx_server.py[8385]: File "/usr/local/lib/python3.5/dist-packages/electrumx-0.7.6-py3.5.egg/server/block_processor.py", line 228, in _wait_for_update
Nov 24 06:33:05 electrum electrumx_server.py[8385]: self.flush(True)
Nov 24 06:33:05 electrum electrumx_server.py[8385]: File "/usr/local/lib/python3.5/dist-packages/electrumx-0.7.6-py3.5.egg/server/block_processor.py", line 368, in flush
Nov 24 06:33:05 electrum electrumx_server.py[8385]: self.assert_flushed()
Nov 24 06:33:05 electrum electrumx_server.py[8385]: File "/usr/local/lib/python3.5/dist-packages/electrumx-0.7.6-py3.5.egg/server/block_processor.py", line 356, in assert_flushed
Nov 24 06:33:05 electrum electrumx_server.py[8385]: assert self.tx_count == self.fs_tx_count == self.db_tx_count
Nov 24 06:33:05 electrum electrumx_server.py[8385]: AssertionError
Nov 24 06:33:05 electrum electrumx_server.py[8385]: CRITICAL:root:ElectrumX server terminated abnormally
Nov 24 06:33:05 electrum electrumx_server.py[8385]: Exception ignored in: <bound method BaseEventLoop.del of <_UnixSelectorEventLoop running=False closed=True debug=False>>
Nov 24 06:33:05 electrum electrumx_server.py[8385]: Traceback (most recent call last):
Nov 24 06:33:05 electrum electrumx_server.py[8385]: File "/usr/lib/python3.5/asyncio/base_events.py", line 431, in del
Nov 24 06:33:05 electrum electrumx_server.py[8385]: File "/usr/lib/python3.5/asyncio/unix_events.py", line 58, in close
Nov 24 06:33:05 electrum electrumx_server.py[8385]: File "/usr/lib/python3.5/asyncio/unix_events.py", line 139, in remove_signal_handler
Nov 24 06:33:05 electrum electrumx_server.py[8385]: File "/usr/lib/python3.5/signal.py", line 47, in signal
Nov 24 06:33:05 electrum electrumx_server.py[8385]: TypeError: signal handler must be signal.SIG_IGN, signal.SIG_DFL, or a callable object
Nov 24 06:33:05 electrum electrumx_server.py[8385]: ERROR:asyncio:Task was destroyed but it is pending!
Nov 24 06:33:05 electrum electrumx_server.py[8385]: task: <Task pending coro=<MemPool.main_loop() running at /usr/local/lib/python3.5/dist-packages/electrumx-0.7.6-py3.5.egg/server/protocol.py:63> wait_for=<Future pending cb=[_chain_future.._call_check_cancel() at /usr/lib/python3.5/asyncio/futures.py:431, Task._wakeup()]> cb=[as_completed.._on_completion() at /usr/lib/python3.5/asyncio/tasks.py:478]>
Nov 24 06:33:05 electrum electrumx_server.py[8385]: ERROR:asyncio:Task was destroyed but it is pending!
Nov 24 06:33:05 electrum electrumx_server.py[8385]: task: <Task pending coro=<Prefetcher.main_loop() running at /usr/local/lib/python3.5/dist-packages/electrumx-0.7.6-py3.5.egg/server/block_processor.py:80> wait_for=<Future pending cb=[_chain_future.._call_check_cancel() at /usr/lib/python3.5/asyncio/futures.py:431, Task._wakeup()]> cb=[as_completed.._on_completion() at /usr/lib/python3.5/asyncio/tasks.py:478]>

Should not be in our UTXO set. It currently is.

electrum@vps792:~/src/electrumx$ ./electrumx_rpc.py getinfo
INFO:LocalRPC:[31] connection from ::1:52502, 16 total
Traceback (most recent call last):
File "./electrumx_rpc.py", line 76, in
main()
File "./electrumx_rpc.py", line 68, in main
loop.run_until_complete(coro)
File "/home/electrum/.pyenv/versions/3.5.2/lib/python3.5/asyncio/base_events.py", line 387, in run_until_complete
return future.result()
File "/home/electrum/.pyenv/versions/3.5.2/lib/python3.5/asyncio/futures.py", line 274, in result
raise self._exception
File "/home/electrum/.pyenv/versions/3.5.2/lib/python3.5/asyncio/tasks.py", line 239, in step
result = coro.send(None)
File "./electrumx_rpc.py", line 28, in send_and_wait
self.send_json_request(method, id=method, params=params)
AttributeError: 'RPCClient' object has no attribute 'send_json_request'

Will help diagnose persistent issues

Around 12:09 UTC, all ElectrumX servers dropped from IRC due to a peer that joined with a hostname in the realname akin to .domain.com, and the logs show ERROR:IRC:encoding with 'idna' codec failed (UnicodeError: label empty or too long).

More info on this exception: https://stackoverflow.com/questions/25103126/label-empty-or-too-long-python-urllib2/25103444#25103444

Source of exception:

I propose we catch UnicodeError and ignore the peer altogether since the hostname is very likely to be invalid and unconnectable to anyone (and might even crash clients).

While we're at it, maybe we want another except: block to account for all exceptions that may be raised by socket.gethostbyname().

Goal is to merge the notifications for a new block and the mempool update. The block will take a few seconds to process, during that time we should not send mempool address updates.

Updated to 0.9.0a and started to get these two new exceptions:

ERROR:ElectrumX:[94] error handling request <server.protocol.ServerManager.NotificationRequest object at 0x7fcee6750588>
Traceback (most recent call last):
File "/usr/local/lib/python3.5/dist-packages/electrumx-0.9.0a0-py3.5.egg/server/protocol.py", line 590, in serve_requests
await request.process(self)
File "/usr/local/lib/python3.5/dist-packages/electrumx-0.9.0a0-py3.5.egg/server/protocol.py", line 50, in process
await session.notify(self.height, self.touched)
File "/usr/local/lib/python3.5/dist-packages/electrumx-0.9.0a0-py3.5.egg/server/protocol.py", line 722, in notify
status = await self.address_status(hash168)
File "/usr/local/lib/python3.5/dist-packages/electrumx-0.9.0a0-py3.5.egg/server/protocol.py", line 743, in address_status
mempool = await self.manager.mempool_transactions(hash168)
File "/usr/local/lib/python3.5/dist-packages/electrumx-0.9.0a0-py3.5.egg/server/protocol.py", line 96, in mempool_transactions
return await self.mempool.transactions(hash168)
File "/usr/local/lib/python3.5/dist-packages/electrumx-0.9.0a0-py3.5.egg/server/mempool.py", line 262, in transactions
for hex_hash, raw_tx in zip(hex_hashes, raw_txs):
TypeError: zip argument #2 must support iteration
/usr/local/lib/python3.5/dist-packages/electrumx-0.9.0a0-py3.5.egg/server/protocol.py:598: RuntimeWarning: coroutine 'Daemon.getrawtransactions' was never awaited
errs.append(request)

ERROR:ElectrumX:[199] error handling request <server.protocol.ServerManager.NotificationRequest object at 0x7fcee5ebe048>
Traceback (most recent call last):
File "/usr/local/lib/python3.5/dist-packages/electrumx-0.9.0a0-py3.5.egg/server/protocol.py", line 590, in serve_requests
await request.process(self)
File "/usr/local/lib/python3.5/dist-packages/electrumx-0.9.0a0-py3.5.egg/server/protocol.py", line 50, in process
await session.notify(self.height, self.touched)
File "/usr/local/lib/python3.5/dist-packages/electrumx-0.9.0a0-py3.5.egg/server/protocol.py", line 722, in notify
status = await self.address_status(hash168)
File "/usr/local/lib/python3.5/dist-packages/electrumx-0.9.0a0-py3.5.egg/server/protocol.py", line 743, in address_status
mempool = await self.manager.mempool_transactions(hash168)
File "/usr/local/lib/python3.5/dist-packages/electrumx-0.9.0a0-py3.5.egg/server/protocol.py", line 96, in mempool_transactions
return await self.mempool.transactions(hash168)
File "/usr/local/lib/python3.5/dist-packages/electrumx-0.9.0a0-py3.5.egg/server/mempool.py", line 262, in transactions
for hex_hash, raw_tx in zip(hex_hashes, raw_txs):
TypeError: zip argument #2 must support iteration

Hi,
I'm using ElectrumX with Dash Core github master branch. It get fully indexed only for a 1.5 hours on 2 core Intel Atom (took ~4 days on original code), but after ~1 hour ElectrumX are crashing with error (attached log).
electrumx.txt

The only what help is full database remove and reindex, but it crashing again soon after complete.
I did not tried with original Dash Core binaries because them are incompatible with my server, but, according to "README.md", Dash team consider their git master branch as stable, so this issue may be mostly in ElecturmX.
Also never seen this on original Electrum-Server with the same daemon.

OS Ubuntu 16.04
RocksDB database

Definitely on startup; maybe on sync

DBError can happen when flushing a newly processed block and the executor thread reads the 'h' table before the flush commits and the 'u' table after.

I'm trying to disconnect the sessions with client "Send 0.006886BTC to 1CyNqxEVrej8Mup1FJtBSsRZMyz5SyMmnN to stop atack plox".
What I did yesterday was:

electrumx/electrumx_rpc.py sessions  | grep plox | cut -d" " -f 1 | tr '\n' '\0\' | xargs -0 -I % electrumx/electrumx_rpc.py disconnect %

which shows the disconnected message for all IDs I feed to electrum_rpc.py. However, now, almost 24 hours later, the sessions are still there.

I'll try and get a sample for today.

http://hastebin.com/ekatigumep.sql

This happens when the daemon has moved a block ahead of us and reports its mempool with txs spending UTXOs in that block that we have not processed and are also not in our mempool.

Nov 12 17:11:54.747358 electrumx_server.py[15359]: WARNING:asyncio:socket.send() raised exception.
Nov 12 17:11:54.747586 electrumx_server.py[15359]: WARNING:asyncio:socket.send() raised exception.
Nov 12 17:11:54.751002 electrumx_server.py[15359]: WARNING:asyncio:socket.send() raised exception.
Nov 12 17:11:54.751251 electrumx_server.py[15359]: WARNING:asyncio:socket.send() raised exception.
Nov 12 17:11:54.751480 electrumx_server.py[15359]: WARNING:asyncio:socket.send() raised exception.
Nov 12 17:11:54.751701 electrumx_server.py[15359]: WARNING:asyncio:socket.send() raised exception.
Nov 12 17:11:54.751884 electrumx_server.py[15359]: WARNING:asyncio:socket.send() raised exception.
Nov 12 17:11:54.755163 electrumx_server.py[15359]: WARNING:asyncio:socket.send() raised exception.
Nov 12 17:11:54.755394 electrumx_server.py[15359]: WARNING:asyncio:socket.send() raised exception.
Nov 12 17:11:54.755606 electrumx_server.py[15359]: WARNING:asyncio:socket.send() raised exception.
Nov 12 17:11:54.755836 electrumx_server.py[15359]: WARNING:asyncio:socket.send() raised exception.
Nov 12 17:11:54.756104 electrumx_server.py[15359]: WARNING:asyncio:socket.send() raised exception.
Nov 12 17:11:54.760869 electrumx_server.py[15359]: WARNING:asyncio:socket.send() raised exception.
Nov 12 17:11:54.765330 electrumx_server.py[15359]: WARNING:asyncio:socket.send() raised exception.
Nov 12 17:11:54.765623 electrumx_server.py[15359]: WARNING:asyncio:socket.send() raised exception.
Nov 12 17:11:54.765993 electrumx_server.py[15359]: WARNING:asyncio:socket.send() raised exception.
Nov 12 17:11:54.766367 electrumx_server.py[15359]: WARNING:asyncio:socket.send() raised exception.
Nov 12 17:11:54.766639 electrumx_server.py[15359]: WARNING:asyncio:socket.send() raised exception.
Nov 12 17:11:54.766845 electrumx_server.py[15359]: WARNING:asyncio:socket.send() raised exception.
Nov 12 17:11:54.767040 electrumx_server.py[15359]: WARNING:asyncio:socket.send() raised exception.
Nov 12 17:11:54.769331 electrumx_server.py[15359]: WARNING:asyncio:socket.send() raised exception.
Nov 12 17:11:54.769665 electrumx_server.py[15359]: WARNING:asyncio:socket.send() raised exception.
Nov 12 17:11:54.769971 electrumx_server.py[15359]: WARNING:asyncio:socket.send() raised exception.
Nov 12 17:11:54.771440 electrumx_server.py[15359]: WARNING:asyncio:socket.send() raised exception.
Nov 12 17:11:54.771824 electrumx_server.py[15359]: WARNING:asyncio:socket.send() raised exception.
Nov 12 17:11:54.772138 electrumx_server.py[15359]: WARNING:asyncio:socket.send() raised exception.
Nov 12 17:11:54.776474 electrumx_server.py[15359]: WARNING:asyncio:socket.send() raised exception.
Nov 12 17:11:54.776741 electrumx_server.py[15359]: WARNING:asyncio:socket.send() raised exception.
Nov 12 17:11:54.777059 electrumx_server.py[15359]: WARNING:asyncio:socket.send() raised exception.
Nov 12 17:11:54.777344 electrumx_server.py[15359]: WARNING:asyncio:socket.send() raised exception.
Nov 12 17:11:54.778795 electrumx_server.py[15359]: WARNING:asyncio:socket.send() raised exception.
Nov 12 17:11:54.779048 electrumx_server.py[15359]: WARNING:asyncio:socket.send() raised exception.
Nov 12 17:11:54.781157 electrumx_server.py[15359]: WARNING:asyncio:socket.send() raised exception.
Nov 12 17:11:54.781645 electrumx_server.py[15359]: WARNING:asyncio:socket.send() raised exception.
Nov 12 17:11:54.784465 electrumx_server.py[15359]: WARNING:asyncio:socket.send() raised exception.
Nov 12 17:11:54.784699 electrumx_server.py[15359]: WARNING:asyncio:socket.send() raised exception.
Nov 12 17:11:54.789581 electrumx_server.py[15359]: WARNING:asyncio:socket.send() raised exception.
Nov 12 17:11:54.789776 electrumx_server.py[15359]: WARNING:asyncio:socket.send() raised exception.
Nov 12 17:11:54.790003 electrumx_server.py[15359]: WARNING:asyncio:socket.send() raised exception.
Nov 12 17:11:54.792096 electrumx_server.py[15359]: WARNING:asyncio:socket.send() raised exception.
Nov 12 17:11:54.792407 electrumx_server.py[15359]: WARNING:asyncio:socket.send() raised exception.
Nov 12 17:11:54.792731 electrumx_server.py[15359]: WARNING:asyncio:socket.send() raised exception.
Nov 12 17:11:54.793063 electrumx_server.py[15359]: WARNING:asyncio:socket.send() raised exception.
Nov 12 17:11:54.793447 electrumx_server.py[15359]: WARNING:asyncio:socket.send() raised exception.
Nov 12 17:11:54.794666 electrumx_server.py[15359]: WARNING:asyncio:socket.send() raised exception.
Nov 12 17:11:54.794975 electrumx_server.py[15359]: WARNING:asyncio:socket.send() raised exception.
Nov 12 17:11:54.795842 electrumx_server.py[15359]: WARNING:asyncio:socket.send() raised exception.
Nov 12 17:11:54.798113 electrumx_server.py[15359]: WARNING:asyncio:socket.send() raised exception.
Nov 12 17:11:54.798418 electrumx_server.py[15359]: WARNING:asyncio:socket.send() raised exception.
Nov 12 17:11:54.798727 electrumx_server.py[15359]: WARNING:asyncio:socket.send() raised exception.
Nov 12 17:11:54.799161 electrumx_server.py[15359]: WARNING:asyncio:socket.send() raised exception.
Nov 12 17:11:54.799435 electrumx_server.py[15359]: WARNING:asyncio:socket.send() raised exception.
Nov 12 17:11:54.799743 electrumx_server.py[15359]: WARNING:asyncio:socket.send() raised exception.
Nov 12 17:11:54.800111 electrumx_server.py[15359]: WARNING:asyncio:socket.send() raised exception.
Nov 12 17:11:54.801778 electrumx_server.py[15359]: WARNING:asyncio:socket.send() raised exception.
Nov 12 17:11:54.802231 electrumx_server.py[15359]: WARNING:asyncio:socket.send() raised exception.
Nov 12 17:11:54.819961 electrumx_server.py[15359]: INFO:ElectrumX:78.56.XXX.XXX:51315 disconnected. Sent 2,719,624 bytes in 57,826 messages 0 errors

http://www.hastebin.com/mocudejomu.sql

Version 0.9.9
ElectrumX runnning on VM (Ubuntu) and host crashed to kernel panic (Debian).
I started host and VM again, but ElectrumX BTC does not start anymore (LTC and DASH started ok)
Is there any possibility to fix this database or should I start from scratch?

-- Logs begin at Fri 2016-12-16 20:13:00 EET. --
Dec 16 20:14:40 ubuntu systemd[1]: Started Electrumx-btc.
Dec 16 20:14:42 ubuntu electrumx_server.py[1073]: INFO:root:ElectrumX server starting
Dec 16 20:14:42 ubuntu electrumx_server.py[1073]: INFO:BlockProcessor:switching current directory to /home/santzi/debian_shares/electrumx_db/BTC/
Dec 16 20:14:42 ubuntu electrumx_server.py[1073]: INFO:BlockProcessor:reorg limit is 200 blocks
Dec 16 20:14:43 ubuntu electrumx_server.py[1073]: Traceback (most recent call last):
Dec 16 20:14:43 ubuntu electrumx_server.py[1073]: File "/usr/local/lib/python3.5/dist-packages/electrumx-0.9.9-py3.5.egg/EGG-INFO/scripts/electrumx_server.py", line 68, in main
Dec 16 20:14:43 ubuntu electrumx_server.py[1073]: File "/usr/local/lib/python3.5/dist-packages/electrumx-0.9.9-py3.5.egg/EGG-INFO/scripts/electrumx_server.py", line 49, in main_loop
Dec 16 20:14:43 ubuntu electrumx_server.py[1073]: File "/usr/local/lib/python3.5/dist-packages/electrumx-0.9.9-py3.5.egg/server/protocol.py", line 57, in init
Dec 16 20:14:43 ubuntu electrumx_server.py[1073]: self.bp = BlockProcessor(env)
Dec 16 20:14:43 ubuntu electrumx_server.py[1073]: File "/usr/local/lib/python3.5/dist-packages/electrumx-0.9.9-py3.5.egg/server/block_processor.py", line 142, in init
Dec 16 20:14:43 ubuntu electrumx_server.py[1073]: super().init(env)
Dec 16 20:14:43 ubuntu electrumx_server.py[1073]: File "/usr/local/lib/python3.5/dist-packages/electrumx-0.9.9-py3.5.egg/server/db.py", line 54, in init
Dec 16 20:14:43 ubuntu electrumx_server.py[1073]: self.reopen_db(True)
Dec 16 20:14:43 ubuntu electrumx_server.py[1073]: File "/usr/local/lib/python3.5/dist-packages/electrumx-0.9.9-py3.5.egg/server/db.py", line 86, in reopen_db
Dec 16 20:14:43 ubuntu electrumx_server.py[1073]: self.db = open_db(db_name, self.env.db_engine, max_open_files)
Dec 16 20:14:43 ubuntu electrumx_server.py[1073]: File "/usr/local/lib/python3.5/dist-packages/electrumx-0.9.9-py3.5.egg/server/storage.py", line 24, in open_db
Dec 16 20:14:43 ubuntu electrumx_server.py[1073]: return db_class(name, for_sync)
Dec 16 20:14:43 ubuntu electrumx_server.py[1073]: File "/usr/local/lib/python3.5/dist-packages/electrumx-0.9.9-py3.5.egg/server/storage.py", line 34, in init
Dec 16 20:14:43 ubuntu electrumx_server.py[1073]: self.open(name, create=self.is_new, for_sync=for_sync)
Dec 16 20:14:43 ubuntu electrumx_server.py[1073]: File "/usr/local/lib/python3.5/dist-packages/electrumx-0.9.9-py3.5.egg/server/storage.py", line 85, in open
Dec 16 20:14:43 ubuntu electrumx_server.py[1073]: max_open_files=mof, compression=None)
Dec 16 20:14:43 ubuntu electrumx_server.py[1073]: File "_plyvel.pyx", line 236, in plyvel._plyvel.DB.init (plyvel/_plyvel.cpp:3129)
Dec 16 20:14:43 ubuntu electrumx_server.py[1073]: File "_plyvel.pyx", line 83, in plyvel._plyvel.raise_for_status (plyvel/_plyvel.cpp:1733)
Dec 16 20:14:43 ubuntu electrumx_server.py[1073]: plyvel._plyvel.CorruptionError: b'Corruption: 12 missing files; e.g.: Bitcoin-mainnet/872883.ldb'
Dec 16 20:14:43 ubuntu electrumx_server.py[1073]: CRITICAL:root:ElectrumX server terminated abnormally

Otherwise user can send a tx and wonder why history hasn't updated

I don't really know what the issue is but the database seems to be broken:

Nov 21 21:29:02 helicarrier electrumx_server.py[31020]: INFO:BlockServer:backing up 1 blocks
Nov 21 21:29:03 helicarrier electrumx_server.py[31020]: Traceback (most recent call last):
Nov 21 21:29:03 helicarrier electrumx_server.py[31020]:   File "/home/electrumx/electrumx/server/block_processor.py", line 228, in _wait_for_update
Nov 21 21:29:03 helicarrier electrumx_server.py[31020]:     self.advance_block(block, self.caught_up)
Nov 21 21:29:03 helicarrier electrumx_server.py[31020]:   File "/home/electrumx/electrumx/server/block_processor.py", line 576, in advance_block
Nov 21 21:29:03 helicarrier electrumx_server.py[31020]:     raise ChainReorg
Nov 21 21:29:03 helicarrier electrumx_server.py[31020]: server.block_processor.ChainReorg
Nov 21 21:29:03 helicarrier electrumx_server.py[31020]: During handling of the above exception, another exception occurred:
Nov 21 21:29:03 helicarrier electrumx_server.py[31020]: Traceback (most recent call last):
Nov 21 21:29:03 helicarrier electrumx_server.py[31020]:   File "/home/electrumx/electrumx/electrumx_server.py", line 67, in main
Nov 21 21:29:03 helicarrier electrumx_server.py[31020]:     main_loop()
Nov 21 21:29:03 helicarrier electrumx_server.py[31020]:   File "/home/electrumx/electrumx/electrumx_server.py", line 58, in main_loop
Nov 21 21:29:03 helicarrier electrumx_server.py[31020]:     loop.run_until_complete(future)
Nov 21 21:29:03 helicarrier electrumx_server.py[31020]:   File "/usr/lib/python3.5/asyncio/base_events.py", line 387, in run_until_complete
Nov 21 21:29:03 helicarrier electrumx_server.py[31020]:     return future.result()
Nov 21 21:29:03 helicarrier electrumx_server.py[31020]:   File "/usr/lib/python3.5/asyncio/futures.py", line 274, in result
Nov 21 21:29:03 helicarrier electrumx_server.py[31020]:     raise self._exception
Nov 21 21:29:03 helicarrier electrumx_server.py[31020]:   File "/usr/lib/python3.5/asyncio/tasks.py", line 239, in _step
Nov 21 21:29:03 helicarrier electrumx_server.py[31020]:     result = coro.send(None)
Nov 21 21:29:03 helicarrier electrumx_server.py[31020]:   File "/home/electrumx/electrumx/server/block_processor.py", line 195, in main_loop
Nov 21 21:29:03 helicarrier electrumx_server.py[31020]:     await self._wait_for_update()
Nov 21 21:29:03 helicarrier electrumx_server.py[31020]:   File "/home/electrumx/electrumx/server/block_processor.py", line 231, in _wait_for_update
Nov 21 21:29:03 helicarrier electrumx_server.py[31020]:     await self.handle_chain_reorg()
Nov 21 21:29:03 helicarrier electrumx_server.py[31020]:   File "/home/electrumx/electrumx/server/block_processor.py", line 269, in handle_chain_reorg
Nov 21 21:29:03 helicarrier electrumx_server.py[31020]:     self.backup_blocks(blocks)
Nov 21 21:29:03 helicarrier electrumx_server.py[31020]:   File "/home/electrumx/electrumx/server/block_processor.py", line 648, in backup_blocks
Nov 21 21:29:03 helicarrier electrumx_server.py[31020]:     self.backup_txs(tx_hashes, txs, touched)
Nov 21 21:29:03 helicarrier electrumx_server.py[31020]:   File "/home/electrumx/electrumx/server/block_processor.py", line 679, in backup_txs
Nov 21 21:29:03 helicarrier electrumx_server.py[31020]:     cache_value = spend_utxo(tx_hash, idx)
Nov 21 21:29:03 helicarrier electrumx_server.py[31020]:   File "/home/electrumx/electrumx/server/block_processor.py", line 788, in spend_utxo
Nov 21 21:29:03 helicarrier electrumx_server.py[31020]:     .format(hash_to_str(tx_hash), tx_idx))
Nov 21 21:29:03 helicarrier electrumx_server.py[31020]: server.block_processor.ChainError: UTXO d46f7dc5c2e41918bbe84fa933a497d9f61a640f90aabea433313889ea7d4e7d / 0 not found in "h" table
Nov 21 21:29:03 helicarrier electrumx_server.py[31020]: CRITICAL:root:ElectrumX server terminated abnormally
Nov 21 21:29:06 helicarrier electrumx_server.py[31020]: Exception ignored in: <bound method BaseEventLoop.__del__ of <_UnixSelectorEventLoop running=False closed=True debug=False>>
Nov 21 21:29:06 helicarrier electrumx_server.py[31020]: Traceback (most recent call last):
Nov 21 21:29:06 helicarrier electrumx_server.py[31020]:   File "/usr/lib/python3.5/asyncio/base_events.py", line 431, in __del__
Nov 21 21:29:06 helicarrier electrumx_server.py[31020]:   File "/usr/lib/python3.5/asyncio/unix_events.py", line 58, in close
Nov 21 21:29:06 helicarrier electrumx_server.py[31020]:   File "/usr/lib/python3.5/asyncio/unix_events.py", line 139, in remove_signal_handler
Nov 21 21:29:06 helicarrier electrumx_server.py[31020]:   File "/usr/lib/python3.5/signal.py", line 47, in signal
Nov 21 21:29:06 helicarrier electrumx_server.py[31020]: TypeError: signal handler must be signal.SIG_IGN, signal.SIG_DFL, or a callable object
Nov 21 21:29:06 helicarrier electrumx_server.py[31020]: ERROR:asyncio:Task was destroyed but it is pending!
Nov 21 21:29:06 helicarrier electrumx_server.py[31020]: task: <Task pending coro=<Session.serve_requests() running at /home/electrumx/electrumx/server/protocol.py:466> wait_for=<Future finished result=None>>
Nov 21 21:29:06 helicarrier electrumx_server.py[31020]: ERROR:asyncio:Task was destroyed but it is pending!
Nov 21 21:29:06 helicarrier electrumx_server.py[31020]: task: <Task pending coro=<Session.serve_requests() running at /home/electrumx/electrumx/server/protocol.py:466> wait_for=<Future finished result=None>>
Nov 21 21:29:06 helicarrier electrumx_server.py[31020]: ERROR:asyncio:Task was destroyed but it is pending!
Nov 21 21:29:06 helicarrier electrumx_server.py[31020]: task: <Task pending coro=<Session.serve_requests() running at /home/electrumx/electrumx/server/protocol.py:466> wait_for=<Future finished result=None>>
Nov 21 21:29:06 helicarrier electrumx_server.py[31020]: ERROR:asyncio:Task was destroyed but it is pending!
Nov 21 21:29:06 helicarrier electrumx_server.py[31020]: task: <Task pending coro=<Session.serve_requests() running at /home/electrumx/electrumx/server/protocol.py:466> wait_for=<Future finished result=None>>
Nov 21 21:29:06 helicarrier electrumx_server.py[31020]: ERROR:asyncio:Task was destroyed but it is pending!
Nov 21 21:29:06 helicarrier electrumx_server.py[31020]: task: <Task pending coro=<Session.serve_requests() running at /home/electrumx/electrumx/server/protocol.py:466> wait_for=<Future finished result=None>>
Nov 21 21:29:06 helicarrier electrumx_server.py[31020]: ERROR:asyncio:Task was destroyed but it is pending!
Nov 21 21:29:06 helicarrier electrumx_server.py[31020]: task: <Task pending coro=<Session.serve_requests() running at /home/electrumx/electrumx/server/protocol.py:466> wait_for=<Future finished result=None>>
Nov 21 21:29:06 helicarrier electrumx_server.py[31020]: ERROR:asyncio:Task was destroyed but it is pending!
Nov 21 21:29:06 helicarrier electrumx_server.py[31020]: task: <Task pending coro=<Prefetcher.main_loop() running at /home/electrumx/electrumx/server/block_processor.py:84> wait_for=<Future pending cb=[Task._wakeup()]>>
Nov 21 21:29:06 helicarrier electrumx_server.py[31020]: ERROR:asyncio:Task was destroyed but it is pending!
Nov 21 21:29:06 helicarrier electrumx_server.py[31020]: task: <Task pending coro=<MemPool.main_loop() running at /home/electrumx/electrumx/server/protocol.py:111> wait_for=<Future pending cb=[Task._wakeup()]>>
Nov 21 21:29:06 helicarrier electrumx_server.py[31020]: ERROR:asyncio:Task was destroyed but it is pending!
Nov 21 21:29:06 helicarrier electrumx_server.py[31020]: task: <Task pending coro=<IRC.start() running at /home/electrumx/electrumx/server/irc.py:55> wait_for=<Future pending cb=[Task._wakeup()]>>
Nov 21 21:29:06 helicarrier electrumx_server.py[31020]: ERROR:asyncio:Fatal write error on socket transport
Nov 21 21:29:06 helicarrier electrumx_server.py[31020]: protocol: <asyncio.sslproto.SSLProtocol object at 0x7f9f1b806da0>
Nov 21 21:29:06 helicarrier electrumx_server.py[31020]: transport: <_SelectorSocketTransport fd=71>
Nov 21 21:29:06 helicarrier electrumx_server.py[31020]: Traceback (most recent call last):
Nov 21 21:29:06 helicarrier electrumx_server.py[31020]:   File "/usr/lib/python3.5/asyncio/selector_events.py", line 700, in write
Nov 21 21:29:06 helicarrier electrumx_server.py[31020]:     n = self._sock.send(data)
Nov 21 21:29:06 helicarrier electrumx_server.py[31020]: OSError: [Errno 9] Bad file descriptor
Nov 21 21:29:06 helicarrier electrumx_server.py[31020]: ERROR:asyncio:Fatal error on SSL transport
Nov 21 21:29:06 helicarrier electrumx_server.py[31020]: protocol: <asyncio.sslproto.SSLProtocol object at 0x7f9f1b806da0>
Nov 21 21:29:06 helicarrier electrumx_server.py[31020]: transport: <_SelectorSocketTransport closing fd=71>
Nov 21 21:29:06 helicarrier electrumx_server.py[31020]: Traceback (most recent call last):
Nov 21 21:29:06 helicarrier electrumx_server.py[31020]:   File "/usr/lib/python3.5/asyncio/selector_events.py", line 700, in write
Nov 21 21:29:06 helicarrier electrumx_server.py[31020]:     n = self._sock.send(data)
Nov 21 21:29:06 helicarrier electrumx_server.py[31020]: OSError: [Errno 9] Bad file descriptor
Nov 21 21:29:06 helicarrier electrumx_server.py[31020]: During handling of the above exception, another exception occurred:
Nov 21 21:29:06 helicarrier electrumx_server.py[31020]: Traceback (most recent call last):
Nov 21 21:29:06 helicarrier electrumx_server.py[31020]:   File "/usr/lib/python3.5/asyncio/sslproto.py", line 632, in _process_write_backlog
Nov 21 21:29:06 helicarrier electrumx_server.py[31020]:     self._transport.write(chunk)
Nov 21 21:29:06 helicarrier electrumx_server.py[31020]:   File "/usr/lib/python3.5/asyncio/selector_events.py", line 704, in write
Nov 21 21:29:06 helicarrier electrumx_server.py[31020]:     self._fatal_error(exc, 'Fatal write error on socket transport')
Nov 21 21:29:06 helicarrier electrumx_server.py[31020]:   File "/usr/lib/python3.5/asyncio/selector_events.py", line 589, in _fatal_error
Nov 21 21:29:06 helicarrier electrumx_server.py[31020]:     self._force_close(exc)
Nov 21 21:29:06 helicarrier electrumx_server.py[31020]:   File "/usr/lib/python3.5/asyncio/selector_events.py", line 601, in _force_close
Nov 21 21:29:06 helicarrier electrumx_server.py[31020]:     self._loop.call_soon(self._call_connection_lost, exc)
Nov 21 21:29:06 helicarrier electrumx_server.py[31020]:   File "/usr/lib/python3.5/asyncio/base_events.py", line 497, in call_soon
Nov 21 21:29:06 helicarrier electrumx_server.py[31020]:     handle = self._call_soon(callback, args)
Nov 21 21:29:06 helicarrier electrumx_server.py[31020]:   File "/usr/lib/python3.5/asyncio/base_events.py", line 506, in _call_soon
Nov 21 21:29:06 helicarrier electrumx_server.py[31020]:     self._check_closed()
Nov 21 21:29:06 helicarrier electrumx_server.py[31020]:   File "/usr/lib/python3.5/asyncio/base_events.py", line 334, in _check_closed
Nov 21 21:29:06 helicarrier electrumx_server.py[31020]:     raise RuntimeError('Event loop is closed')

Is it possible to add an option to anonymize logs so that ip addresses are changed to x.x.x.x or something?

I think we need to handle a bad hash more directly

This would greatly speed up new block processing once at tip, particularly for low-spec machines.

It may also speed up syncs from genesis.

Making all requests asynchronous it's easy to flood the daemon and get back a "workqueue depth exceeded" error (which isn't JSON!)

I saw the following error message in my logs:

ERROR:asyncio:Fatal write error on socket transport
protocol: <asyncio.sslproto.SSLProtocol object at 0x7f70c39e5160>
transport: <_SelectorSocketTransport closing fd=25 read=idle write=<idle, bufsize=0>>
Traceback (most recent call last):
File "/usr/local/lib/python3.5/asyncio/selector_events.py", line 730, in _write_ready
n = self._sock.send(self._buffer)
TimeoutError: [Errno 110] Connection timed out

2016-11-19 07:30:37.088055500 ERROR:ElectrumX:error handling request {'id': 5, 'method': 'blockchain.transaction.get', 'params': ['6bbbc4e71c1bdce1c29df61e0fa602410d749235292411f105a93304884ad6c5', 0]}
2016-11-19 07:30:39.753517500 Traceback (most recent call last):
2016-11-19 07:30:39.753521500 File "/home/neil/nb_src/electrumx/server/protocol.py", line 236, in serve_requests
2016-11-19 07:30:39.753524500 await self.handle_json_request(job)
2016-11-19 07:30:39.753527500 File "/home/neil/nb_src/electrumx/lib/jsonrpc.py", line 177, in handle_json_request
2016-11-19 07:30:39.753529500 payload = await self.single_request_payload(request)
2016-11-19 07:30:39.753532500 File "/home/neil/nb_src/electrumx/lib/jsonrpc.py", line 214, in single_request_payload
2016-11-19 07:30:39.753637500 request.get('params', []))
2016-11-19 07:30:39.753639500 File "/home/neil/nb_src/electrumx/lib/jsonrpc.py", line 237, in method_result
2016-11-19 07:30:39.753642500 return await handler(params)
2016-11-19 07:30:39.753644500 File "/home/neil/nb_src/electrumx/server/protocol.py", line 563, in transaction_get
2016-11-19 07:30:39.753647500 return await self.daemon.getrawtransaction(tx_hash)
2016-11-19 07:30:39.753659500 File "/home/neil/nb_src/electrumx/server/daemon.py", line 160, in getrawtransaction
2016-11-19 07:30:39.753662500 return await self._send_single('getrawtransaction', (hex_hash, 0))
2016-11-19 07:30:39.753664500 File "/home/neil/nb_src/electrumx/server/daemon.py", line 105, in _send_single
2016-11-19 07:30:39.753667500 return await self._send(payload, processor)
2016-11-19 07:30:39.753669500 File "/home/neil/nb_src/electrumx/server/daemon.py", line 71, in _send
2016-11-19 07:30:39.753691500 result = processor(await resp.json())
2016-11-19 07:30:39.753694500 File "/home/neil/nb_src/electrumx/server/daemon.py", line 100, in processor
2016-11-19 07:30:39.753696500 raise DaemonError(err)
2016-11-19 07:30:39.753698500 server.daemon.DaemonError: {'code': -5, 'message': 'No information available about transaction'}
20

Hello, I've moved one of my Electrum servers (us.electrum.be) to electrumx and I must I'm impressed :) Syncing took roughly 24 hours (Qemu VM + HDD + relatively busy server).

Are there any performance numbers you might be interested in?

Hello,

After a crash of 0.7.1 yesterday during a reorg, I upgraded to 0.7.3 and restarted electrumx. This resulted in another crash. Full log below:

INFO:root:ElectrumX server starting
INFO:BlockServer:switching current directory to /home/bitcoin/electrumx_db
INFO:BlockServer:successfully opened leveldb database Bitcoin-mainnet
INFO:BlockServer:software version: ElectrumX 0.7.3
INFO:BlockServer:DB version: 3
INFO:BlockServer:coin: Bitcoin
INFO:BlockServer:network: mainnet
INFO:BlockServer:height: 439,973
INFO:BlockServer:tip: 0000000000000000023dc99537a9f3e565a06256ca29a85cb82c028633249f8f
INFO:BlockServer:tx count: 172,573,500
INFO:Daemon:daemon at 162.210.198.184:8332/
INFO:BlockServer:reorg limit is 200 blocks
INFO:BlockServer:deleting 119 stale undo entries
INFO:ServerManager:max subscriptions across all sessions: 250,000
INFO:ServerManager:max subscriptions per session: 50,000
INFO:Prefetcher:catching up to daemon height 440,085...
INFO:BlockServer:chain reorg detected
INFO:BlockServer:finding common height...
INFO:BlockServer:chain was reorganised for 1 blocks from height 439,973 to height 439,973
INFO:BlockServer:backing up 1 blocks
INFO:BlockServer:backed up to height 439,972
INFO:BlockServer:backing up history to height 439,972  tx_count 172,571,879
INFO:BlockServer:removed 13,636 history entries from 12,664 addresses
INFO:BlockServer:flush #713 took 109.6s.  Height 439,972 txs: 172,571,879
INFO:BlockServer:backed up to height 439,972
ERROR:Daemon:disconnected.  Retrying between sleeps...
INFO:Daemon:connection restored
INFO:BlockServer:prefetcher reset
INFO:BlockServer:our height: 439,972 daemon: 440,085 UTXOs 0MB hist -1MB
ERROR:Daemon:HTTP error.  Retrying between sleeps...
INFO:BlockServer:our height: 439,982 daemon: 440,085 UTXOs 13MB hist 15MB
INFO:Daemon:connection restored
ERROR:Daemon:HTTP error.  Retrying between sleeps...
INFO:BlockServer:our height: 439,994 daemon: 440,086 UTXOs 26MB hist 32MB
INFO:Daemon:connection restored
ERROR:Daemon:HTTP error.  Retrying between sleeps...
INFO:BlockServer:our height: 440,005 daemon: 440,087 UTXOs 36MB hist 46MB
INFO:Daemon:connection restored
INFO:BlockServer:our height: 440,016 daemon: 440,087 UTXOs 47MB hist 60MB
INFO:BlockServer:our height: 440,026 daemon: 440,087 UTXOs 55MB hist 72MB
INFO:BlockServer:our height: 440,036 daemon: 440,087 UTXOs 66MB hist 86MB
ERROR:Daemon:HTTP error.  Retrying between sleeps...
INFO:BlockServer:our height: 440,047 daemon: 440,087 UTXOs 74MB hist 98MB
INFO:Daemon:connection restored
INFO:BlockServer:our height: 440,057 daemon: 440,087 UTXOs 82MB hist 108MB
INFO:BlockServer:our height: 440,068 daemon: 440,087 UTXOs 92MB hist 118MB
INFO:BlockServer:our height: 440,079 daemon: 440,087 UTXOs 99MB hist 131MB
INFO:BlockServer:our height: 440,087 daemon: 440,087 UTXOs 106MB hist 140MB
ERROR:Daemon:HTTP error.  Retrying between sleeps...
INFO:Daemon:connection restored
Traceback (most recent call last):
  File "/home/bitcoin/electrumx/electrumx_server.py", line 67, in main
    main_loop()
  File "/home/bitcoin/electrumx/electrumx_server.py", line 58, in main_loop
    loop.run_until_complete(future)
  File "/usr/local/lib/python3.5/asyncio/base_events.py", line 387, in run_until_complete
    return future.result()
  File "/usr/local/lib/python3.5/asyncio/futures.py", line 274, in result
    raise self._exception
  File "/usr/local/lib/python3.5/asyncio/tasks.py", line 239, in _step
    result = coro.send(None)
  File "/home/bitcoin/electrumx/server/block_processor.py", line 195, in main_loop
    await self._wait_for_update()
  File "/home/bitcoin/electrumx/server/block_processor.py", line 219, in _wait_for_update
    await self.first_caught_up()
  File "/home/bitcoin/electrumx/server/protocol.py", line 44, in first_caught_up
    await super().first_caught_up()
  File "/home/bitcoin/electrumx/server/block_processor.py", line 250, in first_caught_up
    self.flush(True)
  File "/home/bitcoin/electrumx/server/block_processor.py", line 391, in flush
    flush_history(batch)
  File "/home/bitcoin/electrumx/server/block_processor.py", line 430, in flush_history
    self.fs_flush()
  File "/home/bitcoin/electrumx/server/block_processor.py", line 457, in fs_flush
    assert len(self.tx_counts) == self.height + 1
AssertionError
CRITICAL:root:ElectrumX server terminated abnormally
Exception ignored in: <bound method BaseEventLoop.__del__ of <_UnixSelectorEventLoop running=False closed=True debug=False>>
Traceback (most recent call last):
  File "/usr/local/lib/python3.5/asyncio/base_events.py", line 431, in __del__
  File "/usr/local/lib/python3.5/asyncio/unix_events.py", line 58, in close
  File "/usr/local/lib/python3.5/asyncio/unix_events.py", line 139, in remove_signal_handler
  File "/usr/local/lib/python3.5/signal.py", line 47, in signal
TypeError: signal handler must be signal.SIG_IGN, signal.SIG_DFL, or a callable object
ERROR:asyncio:Task was destroyed but it is pending!
task: <Task pending coro=<Prefetcher.main_loop() running at /home/bitcoin/electrumx/server/block_processor.py:84> wait_for=<Future pending cb=[Task._wakeup()]>>

Something new in 0.8.7 - seeing on both rigs...

Dec 09 01:41:14 electrumx_server.py[26202]: WARNING:asyncio:socket.send() raised exception.
Dec 09 01:41:14 electrumx_server.py[26202]: WARNING:asyncio:socket.send() raised exception.
Dec 09 01:41:14 electrumx_server.py[26202]: WARNING:asyncio:socket.send() raised exception.
Dec 09 01:41:14 electrumx_server.py[26202]: WARNING:asyncio:socket.send() raised exception.
Dec 09 01:41:14 electrumx_server.py[26202]: WARNING:asyncio:socket.send() raised exception.
Dec 09 01:41:14 electrumx_server.py[26202]: WARNING:asyncio:socket.send() raised exception.
Dec 09 01:41:14 electrumx_server.py[26202]: WARNING:asyncio:socket.send() raised exception.
Dec 09 01:41:14 electrumx_server.py[26202]: WARNING:asyncio:socket.send() raised exception.
Dec 09 01:41:14 electrumx_server.py[26202]: WARNING:asyncio:socket.send() raised exception.
Dec 09 01:41:14 electrumx_server.py[26202]: WARNING:asyncio:socket.send() raised exception.
Dec 09 01:41:14 electrumx_server.py[26202]: WARNING:asyncio:socket.send() raised exception.
Dec 09 01:41:14 electrumx_server.py[26202]: WARNING:asyncio:socket.send() raised exception.
Dec 09 01:41:14 electrumx_server.py[26202]: WARNING:asyncio:socket.send() raised exception.
Dec 09 01:41:14 electrumx_server.py[26202]: WARNING:asyncio:socket.send() raised exception.
Dec 09 01:41:14 electrumx_server.py[26202]: WARNING:asyncio:socket.send() raised exception.
Dec 09 01:41:14 electrumx_server.py[26202]: WARNING:asyncio:socket.send() raised exception.
Dec 09 01:41:14 electrumx_server.py[26202]: WARNING:asyncio:socket.send() raised exception.
Dec 09 01:41:14 electrumx_server.py[26202]: WARNING:asyncio:socket.send() raised exception.
Dec 09 01:41:14 electrumx_server.py[26202]: WARNING:asyncio:socket.send() raised exception.
Dec 09 01:41:14 electrumx_server.py[26202]: WARNING:asyncio:socket.send() raised exception.
Dec 09 01:41:14 electrumx_server.py[26202]: WARNING:asyncio:socket.send() raised exception.
Dec 09 01:41:14 electrumx_server.py[26202]: WARNING:asyncio:socket.send() raised exception.
Dec 09 01:41:14 electrumx_server.py[26202]: WARNING:asyncio:socket.send() raised exception.
Dec 09 01:41:14 electrumx_server.py[26202]: WARNING:asyncio:socket.send() raised exception.

http://hastebin.com/uyowuyotup.vbs

http://hastebin.com/agojosoqap.scala

http://www.hastebin.com/eyovebocod.sql

Sometimes when I use the "sessions" rpc it will log this exception and then hang:

/usr/local/bin/electrumx_rpc.py sessions
Exception in callback _SelectorSocketTransport._read_ready()
handle: <Handle _SelectorSocketTransport._read_ready()>
Traceback (most recent call last):
File "/usr/lib/python3.5/asyncio/events.py", line 125, in _run
self._callback(*self._args)
File "/usr/lib/python3.5/asyncio/selector_events.py", line 669, in _read_ready
self._protocol.data_received(data)
File "/usr/local/lib/python3.5/dist-packages/electrumx-0.7.6-py3.5.egg/EGG-INFO/scripts/electrumx_rpc.py", line 62, in data_received
File "/usr/lib/python3.5/json/init.py", line 319, in loads
return _default_decoder.decode(s)
File "/usr/lib/python3.5/json/decoder.py", line 339, in decode
obj, end = self.raw_decode(s, idx=_w(s, 0).end())
File "/usr/lib/python3.5/json/decoder.py", line 355, in raw_decode
obj, end = self.scan_once(s, idx)
json.decoder.JSONDecodeError: Unterminated string starting at: line 1 column 21882 (char 21881)
Exception in callback _SelectorSocketTransport._read_ready()
handle: <Handle _SelectorSocketTransport._read_ready()>
Traceback (most recent call last):
File "/usr/lib/python3.5/asyncio/events.py", line 125, in _run
self._callback(*self._args)
File "/usr/lib/python3.5/asyncio/selector_events.py", line 669, in _read_ready
self._protocol.data_received(data)
File "/usr/local/lib/python3.5/dist-packages/electrumx-0.7.6-py3.5.egg/EGG-INFO/scripts/electrumx_rpc.py", line 62, in data_received
File "/usr/lib/python3.5/json/init.py", line 319, in loads
return _default_decoder.decode(s)
File "/usr/lib/python3.5/json/decoder.py", line 339, in decode
obj, end = self.raw_decode(s, idx=_w(s, 0).end())
File "/usr/lib/python3.5/json/decoder.py", line 357, in raw_decode
raise JSONDecodeError("Expecting value", s, err.value) from None
json.decoder.JSONDecodeError: Expecting value: line 1 column 1 (char 0)

Nov 23 15:08:51 ElectrumX systemd[1]: electrumx.service: Main process exited, code=killed, status=9/KILL
Nov 23 15:08:51 ElectrumX systemd[1]: electrumx.service: Unit entered failed state.
Nov 23 15:08:51 ElectrumX systemd[1]: electrumx.service: Failed with result 'signal'.

2016-11-07 20:05:15.175667500 WARNING:asyncio:socket.send() raised exception.
2016-11-07 20:05:15.186651500 WARNING:asyncio:socket.send() raised exception.
2016-11-07 20:05:15.194733500 WARNING:asyncio:socket.send() raised exception.
2016-11-07 20:05:15.204540500 WARNING:asyncio:socket.send() raised exception.
2016-11-07 20:05:15.211686500 WARNING:asyncio:socket.send() raised exception.
2016-11-07 20:05:15.221668500 WARNING:asyncio:socket.send() raised exception.
2016-11-07 20:05:15.226665500 INFO:ElectrumX:('::1', 1134, 0, 0) disconnected. Sent 28,896 bytes in 295 messages 0 e

I'm almost certain this is the job coros; they should become properly cancelled futures

Index by hash160(script_pubkey). i.e.:

P2PKH: hash160('76a9' + hash160(pubkey) + '88ac')
P2SH: hash160('a9' + hash160(redeem_script) + '87')
P2PubKey: hash160(pubkey + 'ac')

and all strange scripts too. Would save a byte and be generic.

Once synced to tip the logging is effectively turned off to avoid filling the log with cache and mempool info that we are used to seeing when syncing from genesis. So if the server falls a few hundred blocks behind it appears nothing is happening as the logging behavior has changed since it was synced in the past.

I got several this kind of error prints, but server is still up and running:

Nov 28 03:44:49 ubuntu electrumx_server.py[6372]: ERROR:asyncio:Fatal write error on socket transport
Nov 28 03:44:49 ubuntu electrumx_server.py[6372]: protocol: <asyncio.sslproto.SSLProtocol object at 0x7f22cc72b438>
Nov 28 03:44:49 ubuntu electrumx_server.py[6372]: transport: <_SelectorSocketTransport closing fd=21 read=idle write=<idle, bufsize=0>>
Nov 28 03:44:49 ubuntu electrumx_server.py[6372]: Traceback (most recent call last):
Nov 28 03:44:49 ubuntu electrumx_server.py[6372]: File "/usr/lib/python3.5/asyncio/selector_events.py", line 723, in _write_ready
Nov 28 03:44:49 ubuntu electrumx_server.py[6372]: n = self._sock.send(self._buffer)
Nov 28 03:44:49 ubuntu electrumx_server.py[6372]: TimeoutError: [Errno 110] Connection timed out

Nov 28 03:45:53 ubuntu electrumx_server.py[6372]: ERROR:asyncio:Fatal write error on socket transport
Nov 28 03:45:53 ubuntu electrumx_server.py[6372]: protocol: <asyncio.sslproto.SSLProtocol object at 0x7f22cc72b898>
Nov 28 03:45:53 ubuntu electrumx_server.py[6372]: transport: <_SelectorSocketTransport closing fd=25 read=idle write=<idle, bufsize=0>>
Nov 28 03:45:53 ubuntu electrumx_server.py[6372]: Traceback (most recent call last):
Nov 28 03:45:53 ubuntu electrumx_server.py[6372]: File "/usr/lib/python3.5/asyncio/selector_events.py", line 723, in _write_ready
Nov 28 03:45:53 ubuntu electrumx_server.py[6372]: n = self._sock.send(self._buffer)
Nov 28 03:45:53 ubuntu electrumx_server.py[6372]: TimeoutError: [Errno 110] Connection timed out

Nov 28 04:01:48 ubuntu electrumx_server.py[6372]: ERROR:asyncio:Fatal write error on socket transport
Nov 28 04:01:48 ubuntu electrumx_server.py[6372]: protocol: <asyncio.sslproto.SSLProtocol object at 0x7f22cc767f98>
Nov 28 04:01:48 ubuntu electrumx_server.py[6372]: transport: <_SelectorSocketTransport closing fd=20 read=idle write=<idle, bufsize=0>>
Nov 28 04:01:48 ubuntu electrumx_server.py[6372]: Traceback (most recent call last):
Nov 28 04:01:48 ubuntu electrumx_server.py[6372]: File "/usr/lib/python3.5/asyncio/selector_events.py", line 723, in _write_ready
Nov 28 04:01:48 ubuntu electrumx_server.py[6372]: n = self._sock.send(self._buffer)
Nov 28 04:01:48 ubuntu electrumx_server.py[6372]: TimeoutError: [Errno 110] Connection timed out

Is there any way to prevent these error prints?
Reason might be that, some Electrum client does not reply in time?

Used version 0.8.6
I have increased file descriptors amount to quite high.
ele@ubuntu:~$ ulimit -Hn; ulimit -Sn; sudo sysctl fs.file-max
500000
300000
fs.file-max = 700000

But I still getting this kind of errors:

Dec 7 23:07:23 ubuntu electrumx_server.py[16158]: ERROR:asyncio:socket.accept() out of system resource
Dec 7 23:07:23 ubuntu electrumx_server.py[16158]: socket: <socket.socket fd=17, family=AddressFamily.AF_INET, type=2049, proto=6, laddr=('192.168.1.41', 50$
Dec 7 23:07:23 ubuntu electrumx_server.py[16158]: Traceback (most recent call last):
Dec 7 23:07:23 ubuntu electrumx_server.py[16158]: File "/usr/lib/python3.5/asyncio/selector_events.py", line 161, in _accept_connection
Dec 7 23:07:23 ubuntu electrumx_server.py[16158]: File "/usr/lib/python3.5/socket.py", line 195, in accept
Dec 7 23:07:23 ubuntu electrumx_server.py[16158]: OSError: [Errno 24] Too many open files

Before these errors, there were tons of warnings about "high bandwidth use" from different connections (>10) , and there are also this kind of errors
"Dec 8 00:18:23 ubuntu electrumx_server.py[16158]: TypeError: signal handler must be signal.SIG_IGN, signal.SIG_DFL, or a callable object
Dec 8 00:18:23 ubuntu electrumx_server.py[16158]: ERROR:asyncio:Task was destroyed but it is pending!
Dec 8 00:18:23 ubuntu electrumx_server.py[16158]: task: <Task pending coro=<Session.serve_requests() running at /usr/local/lib/python3.5/dist-packages/elec$
Dec 8 00:18:23 ubuntu electrumx_server.py[16158]: ERROR:asyncio:Task was destroyed but it is pending!
Dec 8 00:18:23 ubuntu electrumx_server.py[16158]: task: <Task pending coro=<Session.serve_requests() running at /usr/local/lib/python3.5/dist-packages/elec$
Dec 8 00:18:23 ubuntu electrumx_server.py[16158]: ERROR:asyncio:Task was destroyed but it is pending!
Dec 8 00:18:23 ubuntu electrumx_server.py[16158]: task: <Task pending coro=<Session.serve_requests() running at /usr/local/lib/python3.5/dist-packages/elec$
Dec 8 00:18:23 ubuntu electrumx_server.py[16158]: ERROR:asyncio:Task was destroyed but it is pending!"

And finally Electrumx crashed.
Here is short log about this issue:
http://www.filedropper.com/last11klinesltcwarnerrorcrash
I cutted first 15MB "high bandwidth use" warnings away :)
I could upload whole big log, if you needed.

I have also got this "Too many open files" errors with older Electrumx versions, I don't get it, why this occurred..file descriptors should be enough.
I also checked earlier how many file descriptors electrumx process uses, and it was below 2000.

Updated to 0.8.7 and started getting this new exception:

ERROR:ElectrumX:[221] error handling request <lib.jsonrpc.BatchRequest object at 0x7f80da80af60>
Traceback (most recent call last):
File "/usr/local/lib/python3.5/dist-packages/electrumx-0.8.7-py3.5.egg/server/protocol.py", line 623, in serve_requests
await request.process()
File "/usr/local/lib/python3.5/dist-packages/electrumx-0.8.7-py3.5.egg/lib/jsonrpc.py", line 48, in process
for n in range(self.CHUNK_SIZE):
AttributeError: 'BatchRequest' object has no attribute 'CHUNK_SIZE'

I reverted to 0.8.6 and things are back to normal.

In several occasions I have lost IRC connection. Usually when this happens, within a few minutes the electrumx server re-joins the channel and stays in the channel, but afterwards the log continues to show IRC connection resets. It appears it didn't recognize that it did in fact connect.

Here is the log of one such incident:

.. initial loss of connection
INFO:IRC:IRC event type disconnect source irc.freenode.net args ['Connection reset by peer']
ERROR:IRC:disconnected
ERROR:IRC:connection error: Not connected.
ERROR:IRC:connection error: Not connected.
ERROR:IRC:connection error: Not connected.
ERROR:IRC:connection error: Not connected.
ERROR:IRC:connection error: Not connected.
ERROR:IRC:connection error: Not connected.
ERROR:IRC:connection error: Not connected.
ERROR:IRC:connection error: Not connected.

.. re-appears in channel at this point
INFO:IRC:IRC event type disconnect source irc.freenode.net args ['Connection reset by peer']
ERROR:IRC:disconnected
INFO:IRC:IRC event type disconnect source irc.freenode.net args ['Connection reset by peer']
ERROR:IRC:disconnected
INFO:IRC:IRC event type disconnect source irc.freenode.net args ['Connection reset by peer']
ERROR:IRC:disconnected

.. this pattern of errors continues forever until electrumx is restarted
ERROR:IRC:connection error: Not connected.
INFO:IRC:IRC event type disconnect source irc.freenode.net args ['Connection reset by peer']
ERROR:IRC:disconnected
INFO:IRC:IRC event type disconnect source irc.freenode.net args ['Connection reset by peer']
ERROR:IRC:disconnected
INFO:IRC:IRC event type disconnect source irc.freenode.net args ['Connection reset by peer']
ERROR:IRC:disconnected
ERROR:IRC:connection error: Not connected.
INFO:IRC:IRC event type disconnect source irc.freenode.net args ['Connection reset by peer']
ERROR:IRC:disconnected
INFO:IRC:IRC event type disconnect source irc.freenode.net args ['Connection reset by peer']
ERROR:IRC:disconnected
INFO:IRC:IRC event type disconnect source irc.freenode.net args ['Connection reset by peer']
ERROR:IRC:disconnected
INFO:IRC:IRC event type disconnect source irc.freenode.net args ['Connection reset by peer']
ERROR:IRC:disconnected
INFO:IRC:IRC event type disconnect source irc.freenode.net args ['Connection reset by peer']
ERROR:IRC:disconnected
INFO:IRC:IRC event type disconnect source irc.freenode.net args ['Connection reset by peer']
ERROR:IRC:disconnected
ERROR:IRC:connection error: Not connected.
INFO:IRC:IRC event type disconnect source irc.freenode.net args ['Connection reset by peer']
ERROR:IRC:disconnected
INFO:IRC:IRC event type disconnect source irc.freenode.net args ['Connection reset by peer']
ERROR:IRC:disconnected
INFO:IRC:IRC event type disconnect source irc.freenode.net args ['Connection reset by peer']
ERROR:IRC:disconnected
INFO:IRC:IRC event type disconnect source irc.freenode.net args ['Connection reset by peer']
ERROR:IRC:disconnected
INFO:IRC:IRC event type disconnect source irc.freenode.net args ['Connection reset by peer']
ERROR:IRC:disconnected
INFO:IRC:IRC event type disconnect source irc.freenode.net args ['Connection reset by peer']
ERROR:IRC:disconnected
INFO:IRC:IRC event type disconnect source irc.freenode.net args ['Connection reset by peer']
ERROR:IRC:disconnected
ERROR:IRC:connection error: Not connected.
INFO:IRC:IRC event type disconnect source irc.freenode.net args ['Connection reset by peer']
ERROR:IRC:disconnected
INFO:IRC:IRC event type disconnect source irc.freenode.net args ['Connection reset by peer']
ERROR:IRC:disconnected
INFO:IRC:IRC event type disconnect source irc.freenode.net args ['Connection reset by peer']
ERROR:IRC:disconnected
INFO:IRC:IRC event type disconnect source irc.freenode.net args ['Connection reset by peer']
ERROR:IRC:disconnected