Unrecoverable connection issues with socks5 proxy.

[0xB44EFD8751077F97]

This happens to me with yg-pe.py at least once per 24 hours. While this is happening, on the same host, I am able to make connections on the socks proxy without issue. Bitcoin 0.14.2 has no problem staying connected over the same proxy for instance. Here is a snip of some logs and then a curl test to make sure the proxy is working.

Apologies in advance if this is already being tracked. I couldn't find this exact bug with a search of open issues.

2017-07-25 20:40:25,007 [MCThread    ] [INFO ]  <<pubmsg on CgAn: nick=J5CPeXti2R5AP4yO message=!reloffer 2 205382425 889356757 0 0.0003022878 ~
2017-07-25 20:51:16,829 [PingThread  ] [WARNI]  irc ping timed out
2017-07-25 20:51:16,830 [MCThread    ] [DEBUG]  line was zero length from CgAn
2017-07-25 20:51:16,830 [MCThread    ] [DEBUG]  On disconnect fired, nicks_seen is now: {<joinmarket.irc.IRCMessageChannel object at 0x7adcf91a8c10>: set([])}
2017-07-25 20:51:16,831 [MCThread    ] [INFO ]  disconnected from irc host CgAn
2017-07-25 20:51:46,836 [MCThread    ] [INFO ]  connecting to host CgAn
2017-07-25 20:51:46,836 [MCThread    ] [DEBUG]  Using socks5 proxy 127.0.0.1:9050
2017-07-25 20:53:46,242 [MCThread    ] [DEBUG]  logging traceback from CgAn: 
Traceback (most recent call last):
  File "/home/user/joinmarket/joinmarket/irc.py", line 424, in run
    self.sock.connect(self.serverport)
  File "/home/user/joinmarket/joinmarket/socks.py", line 392, in connect
    self.__negotiatesocks5(destpair[0], destpair[1])
  File "/home/user/joinmarket/joinmarket/socks.py", line 256, in __negotiatesocks5
    raise Socks5Error(_socks5errors[min(9, ord(resp[1]))])
Socks5Error: 'TTL expired'

2017-07-25 20:53:46,243 [MCThread    ] [DEBUG]  On disconnect fired, nicks_seen is now: {<joinmarket.irc.IRCMessageChannel object at 0x7adcf91a8c10>: set([])}
2017-07-25 20:53:46,243 [MCThread    ] [INFO ]  disconnected from irc host CgAn
2017-07-25 20:54:16,258 [MCThread    ] [INFO ]  connecting to host CgAn
2017-07-25 20:54:16,259 [MCThread    ] [DEBUG]  Using socks5 proxy 127.0.0.1:9050
2017-07-25 20:56:15,044 [MCThread    ] [DEBUG]  logging traceback from CgAn: 
Traceback (most recent call last):
  File "/home/user/joinmarket/joinmarket/irc.py", line 424, in run
    self.sock.connect(self.serverport)
  File "/home/user/joinmarket/joinmarket/socks.py", line 392, in connect
    self.__negotiatesocks5(destpair[0], destpair[1])
  File "/home/user/joinmarket/joinmarket/socks.py", line 256, in __negotiatesocks5
    raise Socks5Error(_socks5errors[min(9, ord(resp[1]))])
Socks5Error: 'general SOCKS server failure'

2017-07-25 20:56:15,045 [MCThread    ] [DEBUG]  On disconnect fired, nicks_seen is now: {<joinmarket.irc.IRCMessageChannel object at 0x7adcf91a8c10>: set([])}
2017-07-25 20:56:15,045 [MCThread    ] [INFO ]  disconnected from irc host CgAn
2017-07-25 20:56:16,915 [ThrottleThre] [WARNI]  failed to send ping message on socket
2017-07-25 20:56:45,075 [MCThread    ] [INFO ]  connecting to host CgAn
2017-07-25 20:56:45,075 [MCThread    ] [DEBUG]  Using socks5 proxy 127.0.0.1:9050         
2017-07-25 20:57:16,915 [PingThread  ] [WARNI]  irc ping timed out                        
2017-07-25 20:57:16,919 [MCThread    ] [DEBUG]  logging traceback from CgAn:              
Traceback (most recent call last):                                                        
  File "/home/user/joinmarket/joinmarket/irc.py", line 424, in run                        
    self.sock.connect(self.serverport)                                                    
  File "/home/user/joinmarket/joinmarket/socks.py", line 392, in connect                  
    self.__negotiatesocks5(destpair[0], destpair[1])
  File "/home/user/joinmarket/joinmarket/socks.py", line 249, in __negotiatesocks5
    resp = self.__recvall(4)
  File "/home/user/joinmarket/joinmarket/socks.py", line 155, in __recvall
    data = data + self.recv(bytes - len(data))
  File "/usr/lib/python2.7/socket.py", line 170, in _dummy
    raise error(EBADF, 'Bad file descriptor')
error: [Errno 9] Bad file descriptor

2017-07-25 20:57:16,920 [MCThread    ] [DEBUG]  On disconnect fired, nicks_seen is now: {<joinmarket.irc.IRCMessageChannel object at 0x7adcf91a8c10>: set([])}
2017-07-25 20:57:16,920 [MCThread    ] [INFO ]  disconnected from irc host CgAn
2017-07-25 20:57:46,951 [MCThread    ] [INFO ]  connecting to host CgAn
2017-07-25 20:57:46,951 [MCThread    ] [DEBUG]  Using socks5 proxy 127.0.0.1:9050
2017-07-25 20:59:46,226 [MCThread    ] [DEBUG]  logging traceback from CgAn: 
Traceback (most recent call last):
  File "/home/user/joinmarket/joinmarket/irc.py", line 424, in run
    self.sock.connect(self.serverport)
  File "/home/user/joinmarket/joinmarket/socks.py", line 392, in connect
    self.__negotiatesocks5(destpair[0], destpair[1])
  File "/home/user/joinmarket/joinmarket/socks.py", line 256, in __negotiatesocks5
    raise Socks5Error(_socks5errors[min(9, ord(resp[1]))])
Socks5Error: 'TTL expired'

2017-07-25 20:59:46,227 [MCThread    ] [DEBUG]  On disconnect fired, nicks_seen is now: {<joinmarket.irc.IRCMessageChannel object at 0x7adcf91a8c10>: set([])}
2017-07-25 20:59:46,227 [MCThread    ] [INFO ]  disconnected from irc host CgAn
2017-07-25 21:00:16,230 [MCThread    ] [INFO ]  connecting to host CgAn
2017-07-25 21:00:16,231 [MCThread    ] [DEBUG]  Using socks5 proxy 127.0.0.1:9050
2017-07-25 21:02:38,000 [MainThread  ] [WARNI]  Quitting! Dumping object contents to logfile.

---

user@host:~/joinmarket$ date; curl --socks5 127.0.0.1:9050 -v https://wtfismyip.com/text
Tue Jul 25 20:56:51 UTC 2017
* Hostname was NOT found in DNS cache
*   Trying 127.0.0.1...
* Hostname was NOT found in DNS cache
* 158
* 69
* 26
* 138
* Connected to 127.0.0.1 (127.0.0.1) port 9050 (#0)
* successfully set certificate verify locations:
*   CAfile: none
  CApath: /etc/ssl/certs
* SSLv3, TLS handshake, Client hello (1):
* SSLv3, TLS handshake, Server hello (2):
* SSLv3, TLS handshake, CERT (11):
* SSLv3, TLS handshake, Server key exchange (12):
* SSLv3, TLS handshake, Server finished (14):
* SSLv3, TLS handshake, Client key exchange (16):
* SSLv3, TLS change cipher, Client hello (1):
* SSLv3, TLS handshake, Finished (20):
* SSLv3, TLS change cipher, Client hello (1):
* SSLv3, TLS handshake, Finished (20):
* SSL connection using TLSv1.2 / ECDHE-RSA-AES128-GCM-SHA256
* Server certificate:
*        subject: CN=wtfismyip.com
*        start date: 2017-07-16 14:58:00 GMT
*        expire date: 2017-10-14 14:58:00 GMT
*        subjectAltName: wtfismyip.com matched
*        issuer: C=US; O=Let's Encrypt; CN=Let's Encrypt Authority X3
*        SSL certificate verify ok.
> GET /text HTTP/1.1
> User-Agent: curl/7.38.0
> Host: wtfismyip.com
> Accept: */*
> 
< HTTP/1.1 200 OK
< X-Hire-Me: clint@wtfismyip.com
< Content-Type: text/plain; charset=utf-8
< Cache-Control: no-cache, no-store, max-age=0, must-revalidate
< Pragma: no-cache
< Expires: 0
< Content-Length: 14
< Date: Tue, 25 Jul 2017 20:56:58 UTC
< Connection: keep-alive
< 
178.209.42.84
* Connection #0 to host wtfismyip.com left intact

[AdamISZ]

Not looking into this now, but: failures to connect/drops to CgAn are not uncommon, same for agora, this is one reason we have multiple IRC channels/servers configured by default, people could use more, people could set up new ones (IRC), people could easily implement new messaging layer implementations (see #650), but haven't done so yet.

Anyway so my point is "Bitcoin handles socks OK" is not, I believe, the point, the point is your connection to CgAn keeps dropping. The bot should continue to operate on agora when that happens, if you have them both configured.

[0xB44EFD8751077F97]

I think the point is not that the connection keeps dropping, but that there is an endless loop of trying to recover and failing in different ways. I understand that the connection drops from time to time, but most of the time the script recovers. It's only some times that there is no recovery or exit, just an infinite loop.

The only reason my copy/paste included a Quitting! line at the end is because I killed the process manually.

this is one reason we have multiple IRC channels/servers

I only have the CgAn in my config because I've never been successful with using both servers.

people could set up new ones (IRC)

Didn't know you were looking for that, I may be interested and I have experience.

[AdamISZ]

I only have the CgAn in my config because I've never been successful with using both servers.

Well something's wrong there; lots of people do, it's been like that for more than a year.

I think the point is not that the connection keeps dropping, but that there is an endless loop of trying to recover and failing in different ways.

Constantly trying to reconnect in a loop is to be expected if the server is just not accepting connections from you. There have been periods like that in the past, but it's hard to keep track of, because it doesn't apply to everyone equally it seems, depends on (a) are you already connected (b) are you using clearnet/onion and other stuff no doubt.

Didn't know you were looking for that, I may be interested and I have experience.

That would be great. I see no downside to having other servers, the server operator has a potential to censor only, but then if people don't trust them they have no obligation to use it (edit: even more to the point: if you are up on all 3, and all users use all 3, then server 1 censoring you is pointless as you'll connect on the other 2). I think the code as-is should quite happily handle configuration of three servers, at least (there is no in-principle limit, don't know the practical actual limit).

[0xB44EFD8751077F97]

I think it had to do with the fact that I was using port 6697 instead of 6698 for CgAn. This seems to be resolved for me, so I will close the issue.

[AdamISZ]

@0xB44EFD8751077F97 Damn, dumb of me not to even think of that possibility :) Thanks for reporting on the resolution though, that'll help us to diagnose similar issues in future.