Skip to content
New issue

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

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

Already on GitHub? Sign in to your account

SSLError spam in logs but everything seems to work #521

Closed
darthginger opened this issue Jul 12, 2018 · 24 comments

Comments

@darthginger
Copy link

commented Jul 12, 2018

Hi,
im using python3.7 and the python package of electrumx (1.5). My electrumx runs at home with a SSH reverse tunnel to my web server so it is reachable over a domain. Web server has letsencrypt certificates that i copied to my electrumx machine.
Everything seems to work fine but i get this spam in my syslog:

Jul 12 20:07:35 debian python3.7[19491]: ERROR:asyncio:SSL handshake failed
Jul 12 20:07:35 debian python3.7[19491]: protocol: <asyncio.sslproto.SSLProtocol object at 0x7f61c1380b70>
Jul 12 20:07:35 debian python3.7[19491]: transport: <_SelectorSocketTransport fd=22 read=polling write=<idle, bufsize=0>>
Jul 12 20:07:35 debian python3.7[19491]: Traceback (most recent call last):
Jul 12 20:07:35 debian python3.7[19491]:   File "/usr/lib/python3.7/asyncio/sslproto.py", line 625, in _on_handshake_complete
Jul 12 20:07:35 debian python3.7[19491]:     raise handshake_exc
Jul 12 20:07:35 debian python3.7[19491]:   File "/usr/lib/python3.7/asyncio/sslproto.py", line 189, in feed_ssldata
Jul 12 20:07:35 debian python3.7[19491]:     self._sslobj.do_handshake()
Jul 12 20:07:35 debian python3.7[19491]:   File "/usr/lib/python3.7/ssl.py", line 763, in do_handshake
Jul 12 20:07:35 debian python3.7[19491]:     self._sslobj.do_handshake()
Jul 12 20:07:35 debian python3.7[19491]: ssl.SSLError: [SSL: TLSV1_ALERT_UNKNOWN_CA] tlsv1 alert unknown ca (_ssl.c:1045)
Jul 12 20:07:35 debian python3.7[19491]: ERROR:asyncio:SSL error in data received
Jul 12 20:07:35 debian python3.7[19491]: protocol: <asyncio.sslproto.SSLProtocol object at 0x7f61c1380b70>
Jul 12 20:07:35 debian python3.7[19491]: transport: <_SelectorSocketTransport closing fd=22 read=idle write=<idle, bufsize=0>>
Jul 12 20:07:35 debian python3.7[19491]: Traceback (most recent call last):
Jul 12 20:07:35 debian python3.7[19491]:   File "/usr/lib/python3.7/asyncio/sslproto.py", line 526, in data_received
Jul 12 20:07:35 debian python3.7[19491]:     ssldata, appdata = self._sslpipe.feed_ssldata(data)
Jul 12 20:07:35 debian python3.7[19491]:   File "/usr/lib/python3.7/asyncio/sslproto.py", line 189, in feed_ssldata
Jul 12 20:07:35 debian python3.7[19491]:     self._sslobj.do_handshake()
Jul 12 20:07:35 debian python3.7[19491]:   File "/usr/lib/python3.7/ssl.py", line 763, in do_handshake
Jul 12 20:07:35 debian python3.7[19491]:     self._sslobj.do_handshake()
Jul 12 20:07:35 debian python3.7[19491]: ssl.SSLError: [SSL: TLSV1_ALERT_UNKNOWN_CA] tlsv1 alert unknown ca (_ssl.c:1045)

These errors repeat like every 2-3 seconds.
Using my desktop Electrum aswell as electrum on my phone (using mobile internet not wifi) seem to work fine.
Is this a misconfiguration on my side?

@darthginger

This comment has been minimized.

Copy link
Author

commented Jul 12, 2018

./electrumx_rpc getinfo
{
    "closing": 0,
    "daemon": "localhost:8332/",
    "daemon_height": 531642,
    "db_height": 531642,
    "errors": 0,
    "groups": 1,
    "logged": 0,
    "paused": 0,
    "peers": {
        "bad": 3,
        "good": 79,
        "never": 33,
        "stale": 0,
        "total": 115
    },
    "pid": 19491,
    "requests": 1,
    "sessions": 12,
    "subs": 99,
    "txs_sent": 0,
    "uptime": "10m 44s",
    "version": "ElectrumX 1.5"
}
@kyuupichan

This comment has been minimized.

Copy link
Owner

commented Jul 13, 2018

Hmm, that's weird. I've not tried 3.7 myself; I'm still on 3.6 because I was concerned about introducing 3.7-isms. Does this happen on 3.6?

@darthginger

This comment has been minimized.

Copy link
Author

commented Jul 13, 2018

no, in python3.6 i get the usual:

Jul 13 03:08:59 debian python3.6[19420]: INFO:ElectrumX:[16] SSL 127.0.0.1:34666, 4 total
Jul 13 03:08:59 debian python3.6[19420]: INFO:ElectrumX:[16] unsupported protocol version request 0.10
Jul 13 03:09:01 debian python3.6[19420]: INFO:ElectrumX:[17] SSL 127.0.0.1:34674, 4 total
Jul 13 03:09:02 debian python3.6[19420]: INFO:ElectrumX:[18] SSL 127.0.0.1:34678, 5 total
Jul 13 03:09:02 debian python3.6[19420]: INFO:ElectrumX:[19] SSL 127.0.0.1:34676, 5 total
Jul 13 03:09:02 debian python3.6[19420]: INFO:ElectrumX:[20] SSL 127.0.0.1:34680, 6 total
Jul 13 03:09:02 debian python3.6[19420]: INFO:ElectrumX:[19] unsupported protocol version request 0.10
Jul 13 03:09:06 debian python3.6[19420]: INFO:ElectrumX:[21] SSL 127.0.0.1:34686, 6 total
Jul 13 03:09:07 debian python3.6[19420]: INFO:ElectrumX:[22] SSL 127.0.0.1:34696, 6 total
Jul 13 03:09:08 debian python3.6[19420]: INFO:ElectrumX:[23] SSL 127.0.0.1:34700, 7 total
Jul 13 03:09:08 debian python3.6[19420]: INFO:ElectrumX:[24] SSL 127.0.0.1:34698, 7 total
@darthginger

This comment has been minimized.

Copy link
Author

commented Jul 13, 2018

sorry i made a mistake with python3.6, i started the electrumx_server.py (reported as 1.4.4p2) instead of electrumx_server (reported as 1.5). Now i get no client spam in the logs but everything still seems to work.

@kyuupichan

This comment has been minimized.

Copy link
Owner

commented Jul 13, 2018

So Python 3.7 with both 1.4.4p2 and 1.5 has log spam?

@kyuupichan

This comment has been minimized.

Copy link
Owner

commented Jul 13, 2018

I've just upgraded mine to 3.7 to test it. I don't get SSL errors, so this seems to be something in your setup for your certificate that python3.7 now rejects. This link

https://docs.python.org/3.7/whatsnew/3.7.html#ssl

has some SSL changes in 3.7.... not sure if related

@darthginger

This comment has been minimized.

Copy link
Author

commented Jul 13, 2018

So Python 3.7 with both 1.4.4p2 and 1.5 has log spam?

I did not use the .py file with python3.7 as is mentioned in the documentation, So i don't know what happens with 1.4.4p2 and python3.7.

has some SSL changes in 3.7.... not sure if related

seems unrelated i think. I'm just doing some noob SSL thing here probably. Normally if i run any service, they don't have separate ports for TCP/SSL and don't require a certificate. I then just use nginx as a reverse proxy on my web server and a reverse ssh tunnel to deal with SSL using the lets encrypt certificate.

@darthginger

This comment has been minimized.

Copy link
Author

commented Jul 13, 2018

As i understand it the SSL: TLSV1_ALERT_UNKNOWN_CA error suggests it can't verify my CA Lets Encrypt, which python3.6 either can or doesn't check at all? I am using the fullchain provided by Lets Encrypt though.

@SomberNight

This comment has been minimized.

Copy link
Contributor

commented Jul 13, 2018

I also have SSL related exceptions printed in my log, running e425b60 with python 3.7.0.
I've noticed two types: the first is the same as in OP.

ssl.SSLError: [SSL: TLSV1_ALERT_UNKNOWN_CA] tlsv1 alert unknown ca (_ssl.c:1045)
ssl.SSLError: [SSL] unknown error (_ssl.c:2460)

These started to appear when I went from 3.6.1 to 3.7.0.
log:

ERROR:asyncio:SSL handshake failed
protocol: <asyncio.sslproto.SSLProtocol object at 0x7f0dbe938128>
transport: <_SelectorSocketTransport fd=550 read=polling write=<idle, bufsize=0>>
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/asyncio/sslproto.py", line 625, in _on_handshake_complete
    raise handshake_exc
  File "/usr/local/lib/python3.7/asyncio/sslproto.py", line 189, in feed_ssldata
    self._sslobj.do_handshake()
  File "/usr/local/lib/python3.7/ssl.py", line 763, in do_handshake
    self._sslobj.do_handshake()
ssl.SSLError: [SSL: TLSV1_ALERT_UNKNOWN_CA] tlsv1 alert unknown ca (_ssl.c:1045)
ERROR:asyncio:SSL error in data received
protocol: <asyncio.sslproto.SSLProtocol object at 0x7f0dbe938128>
transport: <_SelectorSocketTransport closing fd=550 read=idle write=<idle, bufsize=0>>
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/asyncio/sslproto.py", line 526, in data_received
    ssldata, appdata = self._sslpipe.feed_ssldata(data)
  File "/usr/local/lib/python3.7/asyncio/sslproto.py", line 189, in feed_ssldata
    self._sslobj.do_handshake()
  File "/usr/local/lib/python3.7/ssl.py", line 763, in do_handshake
    self._sslobj.do_handshake()
ssl.SSLError: [SSL: TLSV1_ALERT_UNKNOWN_CA] tlsv1 alert unknown ca (_ssl.c:1045)
INFO:ElectrumX:[525964] SSL xx.xx.xx.xx:xx, 790 total
INFO:ElectrumX:[525965] SSL xx.xx.xx.xx:xx, 790 total
INFO:ElectrumX:[525966] SSL xx.xx.xx.xx:xx, 790 total
INFO:LocalRPC:[525967] RPC xx.xx.xx.xx:xx, 791 total
INFO:ElectrumX:[525968] SSL xx.xx.xx.xx:xx, 791 total
INFO:ElectrumX:[525968] unsupported protocol version request 0.10
INFO:ElectrumX:[525969] SSL xx.xx.xx.xx:xx, 791 total
INFO:ElectrumX:[525969] unsupported protocol version request 0.10
INFO:ElectrumX:[525970] SSL xx.xx.xx.xx:xx, 791 total
ERROR:asyncio:SSL error in data received
protocol: <asyncio.sslproto.SSLProtocol object at 0x7f0dbf5ce438>
transport: <_SelectorSocketTransport fd=588 read=polling write=<idle, bufsize=0>>
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/asyncio/sslproto.py", line 526, in data_received
    ssldata, appdata = self._sslpipe.feed_ssldata(data)
  File "/usr/local/lib/python3.7/asyncio/sslproto.py", line 200, in feed_ssldata
    chunk = self._sslobj.read(self.max_size)
  File "/usr/local/lib/python3.7/ssl.py", line 707, in read
    v = self._sslobj.read(len)
ssl.SSLError: [SSL] unknown error (_ssl.c:2460)
@kyuupichan

This comment has been minimized.

Copy link
Owner

commented Jul 14, 2018

I'm not at expert at SSL but I suspect your system CA root file doesn't have your CA. You might want to try updating it

@darthginger

This comment has been minimized.

Copy link
Author

commented Jul 14, 2018

I checked. My system was/is up to date with this root certificate: https://letsencrypt.org/certificates/

@darthginger

This comment has been minimized.

Copy link
Author

commented Jul 16, 2018

Currently running 1.5.2 and python3.7.
There is currently a mix of the mentioned errors and the usual

Jul 16 16:50:36 debian python3.7[31696]: INFO:ElectrumX:[1789] SSL [::1]:43058, 128 total
Jul 16 16:50:37 debian python3.7[31696]: INFO:ElectrumX:[1790] SSL [::1]:43068, 129 total
@erasmospunk

This comment has been minimized.

Copy link
Contributor

commented Jul 16, 2018

Saw something similar with python3.6:

Fatal error on SSL transport
protocol: <asyncio.sslproto.SSLProtocol object at 0x7fc3702be470>
transport: <_SelectorSocketTransport closing fd=84 read=idle write=<idle, bufsize=0>>
Traceback (most recent call last):
  File "/usr/lib/python3.6/asyncio/sslproto.py", line 638, in _process_write_backlog
    ssldata, offset = self._sslpipe.feed_appdata(data, offset)

@darthginger what os version are you running?

@darthginger

This comment has been minimized.

Copy link
Author

commented Jul 16, 2018

lsb_release -a
No LSB modules are available.
Distributor ID: Debian
Description:    Debian GNU/Linux testing (buster)
Release:        testing
Codename:       buster
@atroxes

This comment has been minimized.

Copy link

commented Jul 29, 2018

Also experiencing this issue. ElectrumX 1.7.2, Python 3.7, Raspbian 9.4.

Seeing no issues when using Python 3.6.5 instead.

@kyuupichan

This comment has been minimized.

Copy link
Owner

commented Jul 30, 2018

So this seems to be a thing with the new Python... not much I can do about it as it's not ElectrumX that's generating the logs.

However, asyncio does have an annoying habit of spewing to the logs about other stuff that's out of my control, and so I built in a log-suppression mechanism. This is here:

https://github.com/kyuupichan/electrumx/blob/master/electrumx/lib/server_base.py#L30-L33

I'm not sure if this will work in your case - it's not clear if it's asyncio or ssl dumping the logs.
Can someone suffering this issue please see if adding "SSLProtocol" to the blacklist there gets rid of it? There are 2 items in the blacklist but I think one no longer happens, presumably because it was fixed in 3.6 and happened in 3.5; I've been meaning to check...

@kyuupichan

This comment has been minimized.

Copy link
Owner

commented Jul 30, 2018

Actually it's an exact string matching mechanism; you might need to change on_exception to do a substring match instead of exact, or add the exact message that is being given. I think I'd prefer to keep it an exact match, to keep the list of things being blocked precise, so you might need to add one or two entries to the list there.

@kyuupichan

This comment has been minimized.

Copy link
Owner

commented Aug 5, 2018

well no one tried to fix this; I've now upgraded to 3.7 and will fix this soon

@kyuupichan

This comment has been minimized.

Copy link
Owner

commented Aug 5, 2018

What version is shown if you run python3.7 from the command line? I'm using Python 3.7.0b3 which seems to be a pre-release.

There was a bug I think in the pre-releases whereby asyncio is not using its own internal error handling mechanism for all SSL errors, only some. So I cannot capture and suppress some messages. I think that was fixed for the actual 3.7 release but am not certain.

The best I can do is ask you to run a verbose debugging version of ElectrumX for me and that will let me see what if anything I can do to squash these.

Can anyone who cares to improve their logs run https://github.com/kyuupichan/electrumx/tree/log-test branch. This will give me info about all asyncio errors that can be suppressed. After running for about 6-12 hours, please give me a link to a hastebin page with the output of

cat log_file | grep CONTEXT

and I will do what I can.

@kyuupichan kyuupichan added the asyncio label Aug 5, 2018

@kyuupichan

This comment has been minimized.

Copy link
Owner

commented Aug 8, 2018

Well response here has been very disappointing - in 1.8.1 there are 2 regexs in electrumx/lib/server_base.py that will suppress arbitrary aiorpcx messages. However, some pre-release 3.7 Python code didn't use their standard error reporting mechanism so don't call the hook and unconditionally log; there is nothing I can do about those.

Absent tested suggestions for improving the existing regexs I will close this issue in a few days.

@SomberNight

This comment has been minimized.

Copy link
Contributor

commented Aug 9, 2018

I am using release python 3.7.0

$ python3
Python 3.7.0 (default, Aug  4 2018, 02:33:39)
[GCC 6.3.0 20170516] on linux
Type "help", "copyright", "credits" or "license" for more information.

at the moment with 9b22fd3,
I still have both traces spammed in my logs, around 500 per hour.
Sorry for not being helpful so far; I can try to test stuff. :)

@SomberNight

This comment has been minimized.

Copy link
Contributor

commented Aug 9, 2018

If I try to connect with a TCP client to an SSL server port, the server logs print:

ERROR:asyncio:SSL handshake failed
protocol: <asyncio.sslproto.SSLProtocol object at 0x7f0b2c775d30>
transport: <_SelectorSocketTransport fd=104 read=polling write=<idle, bufsize=0>>
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/asyncio/sslproto.py", line 625, in _on_handshake_complete
    raise handshake_exc
  File "/usr/local/lib/python3.7/asyncio/sslproto.py", line 189, in feed_ssldata
    self._sslobj.do_handshake()
  File "/usr/local/lib/python3.7/ssl.py", line 763, in do_handshake
    self._sslobj.do_handshake()
ssl.SSLError: [SSL: WRONG_VERSION_NUMBER] wrong version number (_ssl.c:1045)
ERROR:asyncio:SSL error in data received
protocol: <asyncio.sslproto.SSLProtocol object at 0x7f0b2c775d30>
transport: <_SelectorSocketTransport closing fd=104 read=idle write=<idle, bufsize=0>>
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/asyncio/sslproto.py", line 526, in data_received
    ssldata, appdata = self._sslpipe.feed_ssldata(data)
  File "/usr/local/lib/python3.7/asyncio/sslproto.py", line 189, in feed_ssldata
    self._sslobj.do_handshake()
  File "/usr/local/lib/python3.7/ssl.py", line 763, in do_handshake
    self._sslobj.do_handshake()
ssl.SSLError: [SSL: WRONG_VERSION_NUMBER] wrong version number (_ssl.c:1045)

(with versions spesmilo/electrum@059a4ff, 9b22fd3)

@kyuupichan

This comment has been minimized.

Copy link
Owner

commented Aug 9, 2018

Can you try adding "SSL handshake failed" and "SSL error in data received" to the SUPPRESS_MESSAGE_REGEX in electrumx/lib/server_base.py? It would be good to know if that stops those... but if asyncio isn't using the hooks to log then I can't do much about it.

@SomberNight

This comment has been minimized.

Copy link
Contributor

commented Aug 9, 2018

Looks okay! :)
I've only been running for 15 mins so far on SomberNight@4a5fd3d
but the logs are clean, and my above described way to reproduce is no longer working either.

@kyuupichan kyuupichan closed this in 83813ff Aug 9, 2018

shyba added a commit to lbryio/electrumx that referenced this issue Oct 16, 2018

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
5 participants
You can’t perform that action at this time.