Need help with proxy on different platforms

[elgatito]

Hello.

First, thanks for your library!

I have used proxy for making an internal proxy for making all the requests through it.
Initially I tested it on linux-x64 and then released for linux/windows/android, for x64/x86/arm platforms.
Then it came out that proxy runs differently on linux-x64 and linux-armv7 (and probably other, because people complain on that) platforms.

I tried to change some lines, move some functionality, but that did not help. On Linux-x64 it's fine, on linux-arm requests are very slow.

Here is the proxy code: https://github.com/elgatito/elementum/blob/master/scrape/proxy.go

I have tried to run curl with timings, so same code, same functionality, 2 devices, on the same network (tried one more on arm, but different OS, same problem).

Curl on linux-x64 (this is good):

$ time curl -x 127.0.0.1:65222 https://reddit.com -k --verbose -o /dev/null --trace-time
23:11:11.568105 * Rebuilt URL to: https://reddit.com/
23:11:11.568319 *   Trying 127.0.0.1...
23:11:11.568372 * TCP_NODELAY set
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     023:11:11.569270 * Connected to 127.0.0.1 (127.0.0.1) port 65222 (#0)
23:11:11.569358 * allocate connect buffer!
23:11:11.569393 * Establish HTTP proxy tunnel to reddit.com:443
23:11:11.569499 > CONNECT reddit.com:443 HTTP/1.1
23:11:11.569499 > Host: reddit.com:443
23:11:11.569499 > User-Agent: curl/7.58.0
23:11:11.569499 > Proxy-Connection: Keep-Alive
23:11:11.569499 > 
23:11:11.569749 < HTTP/1.0 200 OK
23:11:11.569791 < 
23:11:11.569830 * Proxy replied 200 to CONNECT request
23:11:11.569869 * CONNECT phase completed!
23:11:11.570529 * ALPN, offering h2
23:11:11.570579 * ALPN, offering http/1.1
23:11:11.576310 * successfully set certificate verify locations:
23:11:11.576364 *   CAfile: /etc/ssl/certs/ca-certificates.crt
  CApath: /etc/ssl/certs
23:11:11.576491 } [5 bytes data]
23:11:11.576563 * TLSv1.2 (OUT), TLS handshake, Client hello (1):
23:11:11.576600 } [208 bytes data]
23:11:11.576707 * CONNECT phase completed!
23:11:11.576746 * CONNECT phase completed!
23:11:11.722434 { [5 bytes data]
23:11:11.722530 * TLSv1.2 (IN), TLS handshake, Server hello (2):
23:11:11.722564 { [49 bytes data]
23:11:11.722654 * TLSv1.2 (IN), TLS handshake, Certificate (11):
23:11:11.722683 { [2771 bytes data]
23:11:11.722966 * TLSv1.2 (IN), TLS handshake, Server key exchange (12):
23:11:11.723000 { [300 bytes data]
23:11:11.723156 * TLSv1.2 (IN), TLS handshake, Server finished (14):
23:11:11.723190 { [4 bytes data]
23:11:11.723449 * TLSv1.2 (OUT), TLS handshake, Client key exchange (16):
23:11:11.723481 } [37 bytes data]
23:11:11.723563 * TLSv1.2 (OUT), TLS change cipher, Client hello (1):
23:11:11.723594 } [1 bytes data]
23:11:11.723710 * TLSv1.2 (OUT), TLS handshake, Finished (20):
23:11:11.723741 } [16 bytes data]
23:11:11.724014 * TLSv1.2 (IN), TLS handshake, Finished (20):
23:11:11.724050 { [16 bytes data]
23:11:11.724118 * SSL connection using TLSv1.2 / ECDHE-RSA-AES256-GCM-SHA384
23:11:11.724152 * ALPN, server did not agree to a protocol
23:11:11.724191 * Server certificate:
23:11:11.724229 *  subject: O=GoProxy untrusted MITM proxy Inc; CN=reddit.com
23:11:11.724265 *  start date: Jan  1 00:00:00 1970 GMT
23:11:11.724297 *  expire date: Dec 31 00:00:00 2049 GMT
23:11:11.724337 *  issuer: C=IL; ST=Center; L=Lod; O=GoProxy; OU=GoProxy; CN=goproxy.github.io; emailAddress=elazarl@gmail.com
23:11:11.724372 *  SSL certificate verify result: self signed certificate in certificate chain (19), continuing anyway.
23:11:11.724417 } [5 bytes data]
23:11:11.724488 > GET / HTTP/1.1
23:11:11.724488 > Host: reddit.com
23:11:11.724488 > User-Agent: curl/7.58.0
23:11:11.724488 > Accept: */*
23:11:11.724488 > 
23:11:12.141697 { [5 bytes data]
23:11:12.142134 < HTTP/1.1 301 Moved Permanently
  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     023:11:12.142898 { [5 bytes data]
23:11:12.143170 < Accept-Ranges: bytes
23:11:12.143255 { [5 bytes data]
23:11:12.143454 < Cache-Control: private, max-age=3600
23:11:12.143542 { [5 bytes data]
23:11:12.143782 < Connection: close
23:11:12.143881 { [5 bytes data]
23:11:12.144105 < Date: Mon, 17 Dec 2018 22:11:12 GMT
23:11:12.144185 { [5 bytes data]
23:11:12.144372 < Location: https://www.reddit.com/
23:11:12.144450 { [5 bytes data]
23:11:12.144619 < Retry-After: 0
23:11:12.144685 { [5 bytes data]
23:11:12.144837 < Server: snooserv
23:11:12.144905 { [5 bytes data]
23:11:12.145057 < Transfer-Encoding: chunked
23:11:12.145125 { [5 bytes data]
23:11:12.145280 < Via: 1.1 varnish
23:11:12.145351 { [5 bytes data]
23:11:12.145509 < X-Cache: HIT
23:11:12.145556 { [5 bytes data]
23:11:12.145663 < X-Cache-Hits: 0
23:11:12.145714 { [5 bytes data]
23:11:12.145825 < X-Served-By: cache-bma1622-BMA
23:11:12.145878 { [5 bytes data]
23:11:12.145991 < X-Timer: S1545084672.024461,VS0,VE0
23:11:12.146039 { [5 bytes data]
23:11:12.146112 < 
23:11:12.146161 { [5 bytes data]
  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0
23:11:12.146433 * Closing connection 0
23:11:12.146481 } [5 bytes data]
23:11:12.146577 * TLSv1.2 (OUT), TLS alert, Client hello (1):
23:11:12.146628 } [2 bytes data]

real	0m0,601s
user	0m0,020s
sys	0m0,010s

This is from arm device:

$ time curl -x 192.168.1.153:65222 https://reddit.com -k --verbose -o /dev/null --trace-time
23:03:44.737112 * Rebuilt URL to: https://reddit.com/
23:03:44.737350 *   Trying 192.168.1.153...
23:03:44.737416 * TCP_NODELAY set
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     023:03:44.740533 * Connected to 192.168.1.153 (192.168.1.153) port 65222 (#0)
23:03:44.740638 * allocate connect buffer!
23:03:44.740696 * Establish HTTP proxy tunnel to reddit.com:443
23:03:44.740780 > CONNECT reddit.com:443 HTTP/1.1
23:03:44.740780 > Host: reddit.com:443
23:03:44.740780 > User-Agent: curl/7.58.0
23:03:44.740780 > Proxy-Connection: Keep-Alive
23:03:44.740780 > 
23:03:44.747046 < HTTP/1.0 200 OK
23:03:44.747144 < 
23:03:44.747207 * Proxy replied 200 to CONNECT request
23:03:44.747266 * CONNECT phase completed!
23:03:44.748143 * ALPN, offering h2
23:03:44.748212 * ALPN, offering http/1.1
23:03:44.756415 * successfully set certificate verify locations:
23:03:44.756512 *   CAfile: /etc/ssl/certs/ca-certificates.crt
  CApath: /etc/ssl/certs
23:03:44.756849 } [5 bytes data]
23:03:44.756909 * TLSv1.2 (OUT), TLS handshake, Client hello (1):
23:03:44.756938 } [208 bytes data]
23:03:44.757091 * CONNECT phase completed!
23:03:44.757135 * CONNECT phase completed!
  0     0    0     0    0     0      0      0 --:--:--  0:00:08 --:--:--     023:03:53.598259 { [5 bytes data]
23:03:53.598533 * TLSv1.2 (IN), TLS handshake, Server hello (2):
23:03:53.598733 { [49 bytes data]
23:03:53.599114 * TLSv1.2 (IN), TLS handshake, Certificate (11):
23:03:53.599260 { [2771 bytes data]
23:03:53.600221 * TLSv1.2 (IN), TLS handshake, Server key exchange (12):
23:03:53.600352 { [300 bytes data]
23:03:53.600960 * TLSv1.2 (IN), TLS handshake, Server finished (14):
23:03:53.601097 { [4 bytes data]
23:03:53.602044 * TLSv1.2 (OUT), TLS handshake, Client key exchange (16):
23:03:53.602170 } [37 bytes data]
23:03:53.602498 * TLSv1.2 (OUT), TLS change cipher, Client hello (1):
23:03:53.602619 } [1 bytes data]
23:03:53.603029 * TLSv1.2 (OUT), TLS handshake, Finished (20):
23:03:53.603161 } [16 bytes data]
  0     0    0     0    0     0      0      0 --:--:--  0:00:08 --:--:--     023:03:53.609484 * TLSv1.2 (IN), TLS handshake, Finished (20):
23:03:53.609552 { [16 bytes data]
23:03:53.609682 * SSL connection using TLSv1.2 / ECDHE-RSA-AES256-GCM-SHA384
23:03:53.609748 * ALPN, server did not agree to a protocol
23:03:53.609822 * Server certificate:
23:03:53.609899 *  subject: O=GoProxy untrusted MITM proxy Inc; CN=reddit.com
23:03:53.609968 *  start date: Jan  1 00:00:00 1970 GMT
23:03:53.610033 *  expire date: Dec 31 00:00:00 2049 GMT
23:03:53.610110 *  issuer: C=IL; ST=Center; L=Lod; O=GoProxy; OU=GoProxy; CN=goproxy.github.io; emailAddress=elazarl@gmail.com
23:03:53.610175 *  SSL certificate verify result: self signed certificate in certificate chain (19), continuing anyway.
23:03:53.610261 } [5 bytes data]
23:03:53.610395 > GET / HTTP/1.1
23:03:53.610395 > Host: reddit.com
23:03:53.610395 > User-Agent: curl/7.58.0
23:03:53.610395 > Accept: */*
23:03:53.610395 > 
23:03:54.396922 { [5 bytes data]
23:03:54.397208 < HTTP/1.1 301 Moved Permanently
  0     0    0     0    0     0      0      0 --:--:--  0:00:09 --:--:--     023:03:54.397830 { [5 bytes data]
23:03:54.398145 < Accept-Ranges: bytes
23:03:54.398291 { [5 bytes data]
23:03:54.398579 < Cache-Control: private, max-age=3600
23:03:54.398712 { [5 bytes data]
23:03:54.398998 < Connection: close
23:03:54.399141 { [5 bytes data]
23:03:54.399457 < Date: Mon, 17 Dec 2018 22:03:54 GMT
23:03:54.399603 { [5 bytes data]
23:03:54.399943 < Location: https://www.reddit.com/
23:03:54.400064 { [5 bytes data]
23:03:54.400206 < Retry-After: 0
23:03:54.400261 { [5 bytes data]
23:03:54.400393 < Server: snooserv
23:03:54.400458 { [5 bytes data]
23:03:54.400591 < Transfer-Encoding: chunked
23:03:54.400655 { [5 bytes data]
23:03:54.400787 < Via: 1.1 varnish
23:03:54.400847 { [5 bytes data]
23:03:54.400979 < X-Cache: HIT
23:03:54.401045 { [5 bytes data]
23:03:54.401172 < X-Cache-Hits: 0
23:03:54.401236 { [5 bytes data]
23:03:54.401365 < X-Served-By: cache-bma1641-BMA
23:03:54.401429 { [5 bytes data]
23:03:54.401560 < X-Timer: S1545084234.105838,VS0,VE0
23:03:54.401598 { [5 bytes data]
23:03:54.401651 < 
23:03:54.401683 { [5 bytes data]
  0     0    0     0    0     0      0      0 --:--:--  0:00:09 --:--:--     0
23:03:54.401900 * Closing connection 0
23:03:54.401928 } [5 bytes data]
23:03:54.401987 * TLSv1.2 (OUT), TLS alert, Client hello (1):
23:03:54.402025 } [2 bytes data]

real	0m9,680s
user	0m0,036s
sys	0m0,009s

Maybe you can help with it.

[elgatito]

Maybe this is related - golang/go#19840 ?

[elgatito]

Not optimal work of crypto on arm I understand, but 10 seconds difference?

Here is the request to same host:

$ time curl -x 192.168.1.153:65222 https://reddit.com -k --verbose -o /dev/null --trace-time
23:33:56.575436 * Rebuilt URL to: https://reddit.com/
23:33:56.575599 *   Trying 192.168.1.153...
23:33:56.575681 * TCP_NODELAY set
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     023:33:56.578377 * Connected to 192.168.1.153 (192.168.1.153) port 65222 (#0)
23:33:56.578497 * allocate connect buffer!
23:33:56.578536 * Establish HTTP proxy tunnel to reddit.com:443
23:33:56.578628 > CONNECT reddit.com:443 HTTP/1.1
23:33:56.578628 > Host: reddit.com:443
23:33:56.578628 > User-Agent: curl/7.58.0
23:33:56.578628 > Proxy-Connection: Keep-Alive
23:33:56.578628 > 
23:33:56.583665 < HTTP/1.0 200 OK
23:33:56.583760 < 
23:33:56.583812 * Proxy replied 200 to CONNECT request
23:33:56.583869 * CONNECT phase completed!
23:33:56.584701 * ALPN, offering h2
23:33:56.584766 * ALPN, offering http/1.1
23:33:56.591776 * successfully set certificate verify locations:
23:33:56.591892 *   CAfile: /etc/ssl/certs/ca-certificates.crt
  CApath: /etc/ssl/certs
23:33:56.592199 } [5 bytes data]
23:33:56.592294 * TLSv1.2 (OUT), TLS handshake, Client hello (1):
23:33:56.592350 } [208 bytes data]
23:33:56.592575 * CONNECT phase completed!
23:33:56.592635 * CONNECT phase completed!
  0     0    0     0    0     0      0      0 --:--:--  0:00:03 --:--:--     023:34:00.120623 { [5 bytes data]
23:34:00.120809 * TLSv1.2 (IN), TLS handshake, Server hello (2):
23:34:00.120856 { [49 bytes data]
23:34:00.120974 * TLSv1.2 (IN), TLS handshake, Certificate (11):
23:34:00.121015 { [2771 bytes data]
23:34:00.121404 * TLSv1.2 (IN), TLS handshake, Server key exchange (12):
23:34:00.121560 { [300 bytes data]
23:34:00.121896 * TLSv1.2 (IN), TLS handshake, Server finished (14):
23:34:00.122016 { [4 bytes data]
23:34:00.122704 * TLSv1.2 (OUT), TLS handshake, Client key exchange (16):
23:34:00.122770 } [37 bytes data]
23:34:00.123052 * TLSv1.2 (OUT), TLS change cipher, Client hello (1):
23:34:00.123136 } [1 bytes data]
23:34:00.123447 * TLSv1.2 (OUT), TLS handshake, Finished (20):
23:34:00.123524 } [16 bytes data]
  0     0    0     0    0     0      0      0 --:--:--  0:00:03 --:--:--     023:34:00.130040 * TLSv1.2 (IN), TLS handshake, Finished (20):
23:34:00.130106 { [16 bytes data]
23:34:00.130251 * SSL connection using TLSv1.2 / ECDHE-RSA-AES256-GCM-SHA384
23:34:00.130320 * ALPN, server did not agree to a protocol
23:34:00.130396 * Server certificate:
23:34:00.130474 *  subject: O=GoProxy untrusted MITM proxy Inc; CN=reddit.com
23:34:00.130544 *  start date: Jan  1 00:00:00 1970 GMT
23:34:00.130597 *  expire date: Dec 31 00:00:00 2049 GMT
23:34:00.130679 *  issuer: C=IL; ST=Center; L=Lod; O=GoProxy; OU=GoProxy; CN=goproxy.github.io; emailAddress=elazarl@gmail.com
23:34:00.130746 *  SSL certificate verify result: self signed certificate in certificate chain (19), continuing anyway.
23:34:00.130837 } [5 bytes data]
23:34:00.130970 > GET / HTTP/1.1
23:34:00.130970 > Host: reddit.com
23:34:00.130970 > User-Agent: curl/7.58.0
23:34:00.130970 > Accept: */*
23:34:00.130970 > 
23:34:00.751110 { [5 bytes data]
23:34:00.751432 < HTTP/1.1 301 Moved Permanently
23:34:00.751574 { [5 bytes data]
23:34:00.751804 < Accept-Ranges: bytes
23:34:00.751872 { [5 bytes data]
23:34:00.752254 < Cache-Control: private, max-age=3600
23:34:00.752422 { [5 bytes data]
23:34:00.752782 < Connection: close
23:34:00.752934 { [5 bytes data]
23:34:00.753305 < Date: Mon, 17 Dec 2018 22:34:00 GMT
23:34:00.753451 { [5 bytes data]
23:34:00.753819 < Location: https://www.reddit.com/
23:34:00.753969 { [5 bytes data]
23:34:00.754314 < Retry-After: 0
23:34:00.754467 { [5 bytes data]
23:34:00.754817 < Server: snooserv
23:34:00.754969 { [5 bytes data]
23:34:00.755321 < Transfer-Encoding: chunked
23:34:00.755459 { [5 bytes data]
23:34:00.755796 < Via: 1.1 varnish
23:34:00.755919 { [5 bytes data]
23:34:00.756262 < X-Cache: HIT
23:34:00.756387 { [5 bytes data]
23:34:00.756706 < X-Cache-Hits: 0
23:34:00.756843 { [5 bytes data]
23:34:00.757151 < X-Served-By: cache-bma1649-BMA
23:34:00.757281 { [5 bytes data]
23:34:00.757595 < X-Timer: S1545086040.478384,VS0,VE0
23:34:00.757734 { [5 bytes data]
23:34:00.757948 < 
23:34:00.758095 { [5 bytes data]
  0     0    0     0    0     0      0      0 --:--:--  0:00:04 --:--:--     0
23:34:00.758771 * Closing connection 0
23:34:00.758860 } [5 bytes data]
23:34:00.759032 * TLSv1.2 (OUT), TLS alert, Client hello (1):
23:34:00.759111 } [2 bytes data]

real	0m4,205s
user	0m0,029s
sys	0m0,013s

Now it's 4 seconds...

[elgatito]

I have noticed, from proxy side, that OnResponse is fired much earlier then the response comes to the requestor (client), so it looks like a problem between the proxy and requestor?
Can we remove securities from the proxy, assuming we control clients and we can bypass any security check and validations?

[elgatito]

Okay. Issue is caused by not-optimized (no ASM code) crypto work on Arm devices, described here golang/go#19840
Could bypass by removing signHost function and making custom TLS config callback.
https://github.com/elgatito/elementum/blob/b548d602b657c22c4535fad02f3c98ffaeb558b4/scrape/proxy.go#L43

It will work only if you control your clients and can disable certificate checks.