1527594 - Firefox connects to the end server instead of the configured socks proxy

Status: RESOLVED INVALID

(Core :: Networking: HTTP, defect, P5)

Description

[firefoxfans]

User Agent: Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:65.0) Gecko/20100101 Firefox/65.0

Steps to reproduce:

start firefox in a fresh profile,setup network to use mannual socks5 proxy 127.0.0.1 on port 1080 on preference. open github.com.

Actual results:

on the status bar it show's "now getting handshake with github.com" ,then the page show's "connect timeout. the github.com server response time too long"(translated from chinese).
But I can use that proxy to access google and all other webs except for github.com. It displays time out error .But when I install switchomega proxy extension and use the same proxy setup ,It works。I use google browser use the same proxy ,I can sucess connecting to github.com. So I thinks there is somehting wrong in the firefox native proxy .

Comment 1

[firefoxfans]

uname -a :
Linux smzhou-desktop 4.15.0-45-lowlatency #48-Ubuntu SMP PREEMPT Tue Jan 29 17:45:27 UTC 2019 x86_64 x86_64 x86_64 GNU/Linux

Comment 2

[firefoxfans]

I downgrade to firefox59 ,the same problem happens.

Comment 3

[Honza Bambas (:mayhemer)]

Please provide logs, it may reveal what's going on:
https://developer.mozilla.org/en-US/docs/Mozilla/Debugging/HTTP_logging

thanks

Comment 4

[firefoxfans]

Attachment: log.tgz

Comment 5

[Honza Bambas (:mayhemer)]

thanks, do you have "Proxy DNS when using SOCKS v5" checked in your firefox proxy settings?

what I can see in the log is that we are trying to actually connect (create a socket to) the end server, not the proxy on localhost. e.g. for start.ubuntu-mate.org, with a successful response, we resolve the host ourselves and connect 104.28.6.92, which is (according 8.8.8.8 result) start.ubuntu-mate.org for me as well.

can you please provide your about:support page? this could be some preference settings corner case, thanks.

Comment 6

[Honza Bambas (:mayhemer)]

and one more question: is this a recent regressions? I'm not aware of any changes in the sock code lately. thanks.

Comment 7

[Honza Bambas (:mayhemer)]

log snippet for githib.com

2019-02-14 13:49:59.656787 UTC - [Parent 7255: Socket Thread]: E/nsSocketTransport nsSocketTransport::Init [this=0x7f8f3bdc2c00 host=github.com:443 origin=github.com:443 proxy=127.0.0.1:1080]
2019-02-14 13:49:59.656801 UTC - [Parent 7255: Socket Thread]: D/nsSocketTransport nsSocketTransport::SetConnectionFlags 0x7f8f3bdc2c00 flags=32
  flags = DISABLE_RFC1918
2019-02-14 13:49:59.656814 UTC - [Parent 7255: Socket Thread]: D/nsSocketTransport nsSocketTransport::OpenOutputStream [this=0x7f8f3bdc2c00 flags=2]
2019-02-14 13:49:59.656819 UTC - [Parent 7255: Socket Thread]: D/nsSocketTransport nsSocketTransport::PostEvent [this=0x7f8f3bdc2c00 type=0 status=0 param=(nil)]
2019-02-14 13:49:59.656832 UTC - [Parent 7255: Socket Thread]: D/nsSocketTransport nsSocketTransport::OpenInputStream [this=0x7f8f3bdc2c00 flags=2]
2019-02-14 13:49:59.656836 UTC - [Parent 7255: Socket Thread]: D/nsSocketTransport nsSocketTransport::PostEvent [this=0x7f8f3bdc2c00 type=0 status=0 param=(nil)]
nsHalfOpenSocket @7f8f3cd50160 --> nsSocketTransport @7f8f3bdc2c00
2019-02-14 13:49:59.657143 UTC - [Parent 7255: Socket Thread]: D/nsSocketTransport nsSocketTransport::OnSocketEvent [this=0x7f8f3bdc2c00 type=0 status=0 param=(nil)]
2019-02-14 13:49:59.657151 UTC - [Parent 7255: Socket Thread]: D/nsSocketTransport nsSocketTransport::ResolveHost [this=0x7f8f3bdc2c00 github.com:443]
2019-02-14 13:49:59.657157 UTC - [Parent 7255: Socket Thread]: E/nsSocketTransport nsSocketTransport::SendStatus [this=0x7f8f3bdc2c00 status=804b0003]
  804b0003 = STATUS_RESOLVING
2019-02-14 13:49:59.657226 UTC - [Parent 7255: Socket Thread]: D/nsSocketTransport nsSocketTransport::OnSocketEvent [this=0x7f8f3bdc2c00 type=0 status=0 param=(nil)]
2019-02-14 13:49:59.658496 UTC - [Parent 7255: Socket Thread]: D/nsSocketTransport nsSocketTransport::OnLookupComplete: this=0x7f8f3bdc2c00 status 0.
2019-02-14 13:49:59.658502 UTC - [Parent 7255: Socket Thread]: D/nsSocketTransport nsSocketTransport::PostEvent [this=0x7f8f3bdc2c00 type=1 status=0 param=(nil)]
2019-02-14 13:49:59.658836 UTC - [Parent 7255: Socket Thread]: D/nsSocketTransport nsSocketTransport::OnSocketEvent [this=0x7f8f3bdc2c00 type=1 status=0 param=(nil)]
2019-02-14 13:49:59.658840 UTC - [Parent 7255: Socket Thread]: E/nsSocketTransport nsSocketTransport::SendStatus [this=0x7f8f3bdc2c00 status=804b000b]
  804b000b = STATUS_RESOLVED
2019-02-14 13:49:59.658865 UTC - [Parent 7255: Socket Thread]: D/nsSocketTransport nsSocketTransport::InitiateSocket [this=0x7f8f3bdc2c00]
2019-02-14 13:49:59.658870 UTC - [Parent 7255: Socket Thread]: D/nsSocketTransport nsSocketTransport::BuildSocket [this=0x7f8f3bdc2c00]
2019-02-14 13:49:59.658875 UTC - [Parent 7255: Socket Thread]: D/nsSocketTransport   pushing io layer [0:socks]
2019-02-14 13:49:59.658988 UTC - [Parent 7255: Socket Thread]: D/nsSocketTransport   pushing io layer [1:ssl]
2019-02-14 13:49:59.659041 UTC - [Parent 7255: Socket Thread]: D/nsSocketTransport   [secinfo=0x7f8f3cc3ee20 callbacks=0x7f8f3cd0d820]
2019-02-14 13:49:59.659091 UTC - [Parent 7255: Socket Thread]: D/nsSocketTransport nsSocketTransportService::AttachSocket [handler=0x7f8f3bdc2c00]
2019-02-14 13:49:59.659096 UTC - [Parent 7255: Socket Thread]: D/nsSocketTransport nsSocketTransportService::AddToIdleList [handler=0x7f8f3bdc2c00]
2019-02-14 13:49:59.659100 UTC - [Parent 7255: Socket Thread]: D/nsSocketTransport   active=11 idle=4
2019-02-14 13:49:59.659105 UTC - [Parent 7255: Socket Thread]: D/nsSocketTransport   advancing to STATE_CONNECTING
2019-02-14 13:49:59.659108 UTC - [Parent 7255: Socket Thread]: E/nsSocketTransport nsSocketTransport::SendStatus [this=0x7f8f3bdc2c00 status=804b0007]
  804b0007 = STATUS_CONNECTING_TO
2019-02-14 13:49:59.659128 UTC - [Parent 7255: Socket Thread]: D/nsSocketTransport   trying address: 192.30.252.131
2019-02-14 13:49:59.659452 UTC - [Parent 7255: Socket Thread]: D/nsSocketTransport   idle [3] { handler=0x7f8f3bdc2c00 condition=0 pollflags=6 }
2019-02-14 13:49:59.659460 UTC - [Parent 7255: Socket Thread]: D/nsSocketTransport nsSocketTransportService::AddToPollList [handler=0x7f8f3bdc2c00]

log snippet for start.ubuntu-mate.org

2019-02-14 13:49:56.370860 UTC - [Parent 7255: Socket Thread]: D/nsSocketTransport creating nsSocketTransport @0x7f8f50550000
2019-02-14 13:49:56.370903 UTC - [Parent 7255: Socket Thread]: E/nsSocketTransport nsSocketTransport::Init [this=0x7f8f50550000 host=start.ubuntu-mate.org:443 origin=start.ubuntu-mate.org:443 proxy=127.0.0.1:1080]
2019-02-14 13:49:56.370916 UTC - [Parent 7255: Socket Thread]: D/nsSocketTransport nsSocketTransport::SetConnectionFlags 0x7f8f50550000 flags=34
  flags = ANONYMOUS_CONNECT, DISABLE_RFC1918
2019-02-14 13:49:56.370965 UTC - [Parent 7255: Socket Thread]: D/nsSocketTransport nsSocketTransport::OpenOutputStream [this=0x7f8f50550000 flags=2]
2019-02-14 13:49:56.370971 UTC - [Parent 7255: Socket Thread]: D/nsSocketTransport nsSocketTransport::PostEvent [this=0x7f8f50550000 type=0 status=0 param=(nil)]
2019-02-14 13:49:56.370989 UTC - [Parent 7255: Socket Thread]: D/nsSocketTransport nsSocketTransport::OpenInputStream [this=0x7f8f50550000 flags=2]
2019-02-14 13:49:56.370994 UTC - [Parent 7255: Socket Thread]: D/nsSocketTransport nsSocketTransport::PostEvent [this=0x7f8f50550000 type=0 status=0 param=(nil)]
nsHalfOpenSocket @7f8f500b3600 --> nsSocketTransport @7f8f50550000
2019-02-14 13:49:56.371788 UTC - [Parent 7255: Socket Thread]: D/nsSocketTransport nsSocketTransport::SetConnectionFlags 0x7f8f50550000 flags=2
  flags = ANONYMOUS_CONNECT
2019-02-14 13:49:56.371823 UTC - [Parent 7255: Socket Thread]: D/nsSocketTransport nsSocketTransport::OnSocketEvent [this=0x7f8f50550000 type=0 status=0 param=(nil)]
2019-02-14 13:49:56.371835 UTC - [Parent 7255: Socket Thread]: D/nsSocketTransport nsSocketTransport::ResolveHost [this=0x7f8f50550000 start.ubuntu-mate.org:443]
2019-02-14 13:49:56.371844 UTC - [Parent 7255: Socket Thread]: E/nsSocketTransport nsSocketTransport::SendStatus [this=0x7f8f50550000 status=804b0003]
  804b0003 = STATUS_RESOLVING
2019-02-14 13:49:56.371961 UTC - [Parent 7255: Socket Thread]: D/nsSocketTransport nsSocketTransport::OnSocketEvent [this=0x7f8f50550000 type=0 status=0 param=(nil)]
2019-02-14 13:49:56.373152 UTC - [Parent 7255: Socket Thread]: D/nsSocketTransport nsSocketTransport::OnLookupComplete: this=0x7f8f50550000 status 0.
2019-02-14 13:49:56.373158 UTC - [Parent 7255: Socket Thread]: D/nsSocketTransport nsSocketTransport::PostEvent [this=0x7f8f50550000 type=1 status=0 param=(nil)]
2019-02-14 13:49:56.373620 UTC - [Parent 7255: Socket Thread]: D/nsSocketTransport nsSocketTransport::OnSocketEvent [this=0x7f8f50550000 type=1 status=0 param=(nil)]
2019-02-14 13:49:56.373626 UTC - [Parent 7255: Socket Thread]: E/nsSocketTransport nsSocketTransport::SendStatus [this=0x7f8f50550000 status=804b000b]
  804b000b = STATUS_RESOLVED
2019-02-14 13:49:56.373661 UTC - [Parent 7255: Socket Thread]: D/nsSocketTransport nsSocketTransport::InitiateSocket [this=0x7f8f50550000]
2019-02-14 13:49:56.373668 UTC - [Parent 7255: Socket Thread]: D/nsSocketTransport nsSocketTransport::BuildSocket [this=0x7f8f50550000]
2019-02-14 13:49:56.373674 UTC - [Parent 7255: Socket Thread]: D/nsSocketTransport   pushing io layer [0:socks]
2019-02-14 13:49:56.373721 UTC - [Parent 7255: Socket Thread]: D/nsSocketTransport   pushing io layer [1:ssl]
2019-02-14 13:49:56.373783 UTC - [Parent 7255: Socket Thread]: D/nsSocketTransport   [secinfo=0x7f8f3e313460 callbacks=0x7f8f50955a30]
2019-02-14 13:49:56.373798 UTC - [Parent 7255: Socket Thread]: D/nsSocketTransport nsSocketTransportService::AttachSocket [handler=0x7f8f50550000]
2019-02-14 13:49:56.373824 UTC - [Parent 7255: Socket Thread]: D/nsSocketTransport nsSocketTransportService::AddToIdleList [handler=0x7f8f50550000]
2019-02-14 13:49:56.373829 UTC - [Parent 7255: Socket Thread]: D/nsSocketTransport   active=11 idle=1
2019-02-14 13:49:56.373834 UTC - [Parent 7255: Socket Thread]: D/nsSocketTransport   advancing to STATE_CONNECTING
2019-02-14 13:49:56.373839 UTC - [Parent 7255: Socket Thread]: E/nsSocketTransport nsSocketTransport::SendStatus [this=0x7f8f50550000 status=804b0007]
  804b0007 = STATUS_CONNECTING_TO
2019-02-14 13:49:56.373866 UTC - [Parent 7255: Socket Thread]: D/nsSocketTransport   trying address: 104.28.6.92
2019-02-14 13:49:56.374111 UTC - [Parent 7255: Socket Thread]: D/nsSocketTransport   idle [0] { handler=0x7f8f50550000 condition=0 pollflags=6 }

Comment 8

[Honza Bambas (:mayhemer)]

(Leaving unconfirmed until we check the preference settings for anything non-standard; if this happens with standard prefs and may also be a recent regression, change to P1/Major)

Comment 9

[Honza Bambas (:mayhemer)]

(In reply to firefoxfans from comment #2)

I downgrade to firefox59 ,the same problem happens.

oh, missed this. so not a recent regression, good.

Comment 10

[Selena Deckelmann :selenamarie :selena]

Junior - can you look into this please?

Comment 11

[firefoxfans]

Attachment: about.support.txt

Comment 12

[firefoxfans]

(In reply to Honza Bambas (:mayhemer) from comment #5)

thanks, do you have "Proxy DNS when using SOCKS v5" checked in your firefox proxy settings?

what I can see in the log is that we are trying to actually connect (create a socket to) the end server, not the proxy on localhost. e.g. for start.ubuntu-mate.org, with a successful response, we resolve the host ourselves and connect 104.28.6.92, which is (according 8.8.8.8 result) start.ubuntu-mate.org for me as well.

can you please provide your about:support page? this could be some preference settings corner case, thanks.

No.I don't have that option checked. All I have done is to start a fresh profile and setup mannual socks proxy to 127.0.0.1 on port 1080 except for localhost and 127.0.0.1.

Comment 13

[Honza Bambas (:mayhemer)]

Thanks. I really don't see anything unusual at all in the preferences. And using a fresh profile suggests that too.

Going to turn to P1 and hide, then try to repro locally. Can't believe this has been missed since 59.

Comment 14

[Honza Bambas (:mayhemer)]

Interestingly proxy preferences are not visible in the supports page (confirmed locally too.)

The bug is verified invalid. Locally setup socks proxy (danted) on my virtual ubuntu, running Firefox Release in it and directing to the proxy on 127.0.0.1:1080 - everything works. Running Firefox Nightly and Release on the host machine (port fwd in vbox and fw rule in the virtual ubuntu) - everything works.

The end server IP in the logs goes to nsSOCKSIOLayerConnect that actually connects the proxy (127.0.0.1, or anything else configured, as passed down via nsSOCKSSocketProvider::NewSocket) and uses the address given to PR_Connect() - the logged one - as the SOCK4 connect request fields, sent to the proxy through the SOCKS(5) protocol. This can really be confusing, but makes sense.

This is likely a local misconfiguration (maybe a FW or socks rule blocking outgoing 192/8?) or something wrong with your local DNS. For me (central europe) github.com resolves as: 140.82.118.4, 140.82.118.3. But for you I can see it resolves to 192.30.252.131.

Please try what address github resolves with nslookup and what wget or curl do when connecting directly (no proxy) and then through the proxy.

I no longer believe this is a Firefox bug.

Comment 15

[firefoxfans]

I found the problem. I setup dnsmasq to direct return github.com ip address as 192.30.252.131. When I setup dnsmasq to forward github.com dns request to nameserver ,the problem disappear. But I still think it's a firefox native socks proxy problem,because it's behavour is different from other browsers or other tools because :

when I setup dnsmasq to direct return github.com ip address as 192.30.252.131.
(1) The firefox switchyomega proxy extension can use the same proxy setup to connect to github.com, It's ok。

(2) I setup privoxy to forward to socks5 to 127.0.0.1:1080 and listen on port 8118.I can use wget or git command to success connectting and clone data from github.com:
for example:
env https_proxy="127.0.0.1:8118" env http_proxy="127.0.0.1:8118" env ftp_proxy="127.0.0.1:8118" env HTTP_PROXY="127.0.0.1:8118" env HTTP_PROXY=http://127.0.0.1:8118 env HTTPS_PROXY=https://127.0.0.1:8118 env LC_ALL="C" git clone https://github.com/shadowsocks/ChinaDNS

Cloning into 'ChinaDNS'...
remote: Enumerating objects: 833, done.
remote: Total 833 (delta 0), reused 0 (delta 0), pack-reused 833
Receiving objects: 100% (833/833), 180.40 KiB | 193.00 KiB/s, done.
Resolving deltas: 100% (428/428), done.

(4) google-chrome --proxy-server="socks://127.0.0.1:1080" can access github.com.

Comment 16

[firefoxfans]

if firefox has no problem ,to explain the facts I have to guess that the problem is caused by the reason the connection is interfered by chinese goverments great firewall . or the ip address "192.30.252.131" is hot spot or "man in the middle" ip ?

Comment 17

[firefoxfans]

In China github and google are all blocked by chinese government.I have to setup socks proxy to connect to github.com. If an error ip can still connect to github.com, I think something danagerous has happened in the ip address "192.30.252.131". Thanks for firefox.

Comment 18

[Honza Bambas (:mayhemer)]

Can you provide output of:

curl -v --resolve github.com:443:192.30.252.131 https://github.com/

What exactly is the 192.30.252.131 address? Is it a relay server or another transparent proxy? Thanks.

Comment 19

[David Fifield]

firefoxfans: I suspect your IP address 192.30.252.131 is outdated. Can you try changing it to 192.30.253.112 or 192.30.253.113?

Those two addresses are what I currently get from dig github.com in the U.S. I coincidentally have a record or resolving github.com (from an unrelated project), and it shows that the primary address for github.com changed from 192.30.253.130 to 192.30.253.112 sometime around August 2016. So I suspect that the IP address you are using, 192.30.252.131, is no longer used by GitHub for their frontend web servers.

As far as I know, the GFW does not currently block github.com, but if you have evidence otherwise, please let me know. When github.com was blocked in 2013 and DDoSed in 2015, it was international news, so I'm sure it will be noticed if it happens again. I just now ran a test on GreatFire.org and it says "not blocked"; also notice that it resolves to the IP address 192.30.253.112. OONI's most recent measurement is from October 2018, but it too says "not blocked" and resolves to the IP addresses 192.30.253.112 and 192.30.253.113.

In comment 15, you said that switchyomega and Privoxy do not have a problem with your current configuration. I suspect this is because of what mayhemer said in comment 5 about "Proxy DNS when using SOCKS v5". When that option is unchecked, Firefox queries the dnsmasq server and dnsmasq provides the (wrong) IP address 192.30.252.131. When the option is checked, Firefox will not consult dnsmasq; instead the SOCKS proxy will query its own DNS server for github.com, and get a working IP address. Probably, switchyomega and Privoxy do "Proxy DNS" by default; at least the Privoxy manual says: "With forward-socks5 the DNS resolution will happen on the remote server as well."

Comment 20

[firefoxfans]

I test as David Fifield figure out.when "Proxy DNS when using SOCKS v5" checked,I can connect to github.com even when I setup dnsmasq to return error ip addess "192.30.252.131". I think that is the real cause.