Opened 13 years ago

Last modified 13 years ago

#1138 new Defect

Uploading through SOCKS proxy fails often with error "transient upload error" / "Received invalid version in initial SOCKS5 response" (WCG)

Reported by: blueyed Owned by:
Priority: Undetermined Milestone: Undetermined
Component: Undetermined Version: 6.12.33
Keywords: Cc:

Description

I am trying to upload through a SOCKS proxy created using:

ssh -v -N -T -D 4096 -i id_foo -o PasswordAuthentication=no user@host.com
05-Sep-2011 19:58:31 [---] [proxy] HTTP_OP::no_proxy_for_url(): http://srv3.bakerlab.org/rosetta_cgi/file_upload_handler
05-Sep-2011 19:58:31 [---] [proxy] returning false
05-Sep-2011 19:58:31 [rosetta@home] Started upload of Job20_EEDe_EEDe_2jli_ProteinInterfaceDesign_9Aug2011_30138_1593_0_0
05-Sep-2011 19:58:31 [---] [http] [ID#9] Info:  Connection #0 seems to be dead!
05-Sep-2011 19:58:31 [---] [http] [ID#9] Info:  Closing connection #0
05-Sep-2011 19:58:31 [---] [http] [ID#9] Info:  Connection #2 seems to be dead!
05-Sep-2011 19:58:31 [---] [http] [ID#9] Info:  Closing connection #2
05-Sep-2011 19:58:31 [---] [http] [ID#9] Info:  Connection #3 seems to be dead!
05-Sep-2011 19:58:31 [---] [http] [ID#9] Info:  Closing connection #3
05-Sep-2011 19:58:31 [---] [http] [ID#9] Info:  Connection #4 seems to be dead!
05-Sep-2011 19:58:31 [---] [http] [ID#9] Info:  Closing connection #4
05-Sep-2011 19:58:31 [---] [http] [ID#9] Info:  About to connect() to proxy localhost port 4096 (#0)
05-Sep-2011 19:58:31 [---] [http] [ID#9] Info:    Trying 127.0.0.1... 
05-Sep-2011 19:58:31 [---] [http] [ID#9] Info:  connected
05-Sep-2011 19:58:31 [---] [http] [ID#9] Info:  Connected to localhost (127.0.0.1) port 4096 (#0)
05-Sep-2011 19:58:31 [---] [http] [ID#9] Info:  0x97b1670 is at send pipe head!
05-Sep-2011 19:58:31 [---] [http] [ID#9] Sent header to server: POST /rosetta_cgi/file_upload_handler HTTP/1.1
05-Sep-2011 19:58:31 [---] [http] [ID#9] Sent header to server: User-Agent: BOINC client (i686-pc-linux-gnu 6.12.33)
05-Sep-2011 19:58:31 [---] [http] [ID#9] Sent header to server: Host: srv3.bakerlab.org
05-Sep-2011 19:58:31 [---] [http] [ID#9] Sent header to server: Accept: */*
05-Sep-2011 19:58:31 [---] [http] [ID#9] Sent header to server: Accept-Encoding: deflate, gzip
05-Sep-2011 19:58:31 [---] [http] [ID#9] Sent header to server: Content-Type: application/x-www-form-urlencoded
05-Sep-2011 19:58:31 [---] [http] [ID#9] Sent header to server: Content-Length: 321
05-Sep-2011 19:58:31 [---] [http] [ID#9] Sent header to server: 
05-Sep-2011 19:58:31 [---] [http] [ID#9] Info:  Expire cleared
05-Sep-2011 19:58:31 [---] [http] [ID#9] Received header from server: HTTP/1.1 200 OK
05-Sep-2011 19:58:31 [---] [http] [ID#9] Received header from server: Date: Mon, 05 Sep 2011 18:02:27 GMT
05-Sep-2011 19:58:31 [---] [http] [ID#9] Received header from server: Server: Apache/2.2.3 (Red Hat)
05-Sep-2011 19:58:31 [---] [http] [ID#9] Received header from server: Connection: close
05-Sep-2011 19:58:31 [---] [http] [ID#9] Received header from server: Transfer-Encoding: chunked
05-Sep-2011 19:58:31 [---] [http] [ID#9] Received header from server: Content-Type: text/plain; charset=UTF-8
05-Sep-2011 19:58:31 [---] [http] [ID#9] Received header from server: 
05-Sep-2011 19:58:32 [---] [http] [ID#9] Info:  Closing connection #0
05-Sep-2011 19:58:32 [---] [http] [ID#9] Info:  Expire cleared
05-Sep-2011 19:58:32 [rosetta@home] Temporarily failed upload of Job20_EEDe_EEDe_2jli_ProteinInterfaceDesign_9Aug2011_30138_1593_0_0: transient upload error
05-Sep-2011 19:58:32 [rosetta@home] Backing off 5 hr 52 min 30 sec on upload of Job20_EEDe_EEDe_2jli_ProteinInterfaceDesign_9Aug2011_30138_1593_0_0

Download appears to work fine, and it does not fail always for uploads:

05-Sep-2011 20:08:06 [---] [proxy] HTTP_OP::no_proxy_for_url(): http://srv1.bakerlab.org/rosetta_cgi/file_upload_handler
05-Sep-2011 20:08:06 [---] [proxy] returning false
05-Sep-2011 20:08:06 [rosetta@home] Started upload of 3alipt_1_CYCA_2byo_ProteinInterfaceDesign_26Aug2011_30692_100_0_0
05-Sep-2011 20:08:06 [---] [http] [ID#15] Info:  About to connect() to proxy localhost port 4096 (#0)
05-Sep-2011 20:08:06 [---] [http] [ID#15] Info:    Trying 127.0.0.1... 
05-Sep-2011 20:08:06 [---] [http] [ID#15] Info:  connected
05-Sep-2011 20:08:06 [---] [http] [ID#15] Info:  Connected to localhost (127.0.0.1) port 4096 (#0)
05-Sep-2011 20:08:06 [---] [http] [ID#15] Info:  0x97b1670 is at send pipe head!
05-Sep-2011 20:08:06 [---] [http] [ID#15] Sent header to server: POST /rosetta_cgi/file_upload_handler HTTP/1.1
05-Sep-2011 20:08:06 [---] [http] [ID#15] Sent header to server: User-Agent: BOINC client (i686-pc-linux-gnu 6.12.33)
05-Sep-2011 20:08:06 [---] [http] [ID#15] Sent header to server: Host: srv1.bakerlab.org
05-Sep-2011 20:08:06 [---] [http] [ID#15] Sent header to server: Accept: */*
05-Sep-2011 20:08:06 [---] [http] [ID#15] Sent header to server: Accept-Encoding: deflate, gzip
05-Sep-2011 20:08:06 [---] [http] [ID#15] Sent header to server: Content-Type: application/x-www-form-urlencoded
05-Sep-2011 20:08:06 [---] [http] [ID#15] Sent header to server: Content-Length: 319
05-Sep-2011 20:08:06 [---] [http] [ID#15] Sent header to server: 
05-Sep-2011 20:08:07 [---] [http] [ID#15] Received header from server: HTTP/1.1 200 OK
05-Sep-2011 20:08:07 [---] [http] [ID#15] Received header from server: Date: Mon, 05 Sep 2011 18:08:07 GMT
05-Sep-2011 20:08:07 [---] [http] [ID#15] Received header from server: Server: Apache/2.2.3 (Red Hat)
05-Sep-2011 20:08:07 [---] [http] [ID#15] Received header from server: Connection: close
05-Sep-2011 20:08:07 [---] [http] [ID#15] Received header from server: Transfer-Encoding: chunked
05-Sep-2011 20:08:07 [---] [http] [ID#15] Received header from server: Content-Type: text/plain; charset=UTF-8
05-Sep-2011 20:08:07 [---] [http] [ID#15] Received header from server: 
05-Sep-2011 20:08:07 [---] [http] [ID#15] Info:  Closing connection #0
05-Sep-2011 20:08:07 [---] [http] [ID#15] Info:  Expire cleared
05-Sep-2011 20:08:08 [---] [proxy] HTTP_OP::no_proxy_for_url(): http://srv1.bakerlab.org/rosetta_cgi/file_upload_handler
05-Sep-2011 20:08:08 [---] [proxy] returning false
05-Sep-2011 20:08:08 [---] [http] [ID#15] Info:  About to connect() to proxy localhost port 4096 (#0)
05-Sep-2011 20:08:08 [---] [http] [ID#15] Info:    Trying 127.0.0.1... 
05-Sep-2011 20:08:08 [---] [http] [ID#15] Info:  connected
05-Sep-2011 20:08:08 [---] [http] [ID#15] Info:  Connected to localhost (127.0.0.1) port 4096 (#0)
05-Sep-2011 20:08:08 [---] [http] [ID#15] Info:  0x97b1670 is at send pipe head!
05-Sep-2011 20:08:08 [---] [http] [ID#15] Sent header to server: POST /rosetta_cgi/file_upload_handler HTTP/1.1
05-Sep-2011 20:08:08 [---] [http] [ID#15] Sent header to server: User-Agent: BOINC client (i686-pc-linux-gnu 6.12.33)
05-Sep-2011 20:08:08 [---] [http] [ID#15] Sent header to server: Host: srv1.bakerlab.org
05-Sep-2011 20:08:08 [---] [http] [ID#15] Sent header to server: Accept: */*
05-Sep-2011 20:08:08 [---] [http] [ID#15] Sent header to server: Accept-Encoding: deflate, gzip
05-Sep-2011 20:08:08 [---] [http] [ID#15] Sent header to server: Content-Type: application/x-www-form-urlencoded
05-Sep-2011 20:08:08 [---] [http] [ID#15] Sent header to server: Content-Length: 17576
05-Sep-2011 20:08:08 [---] [http] [ID#15] Sent header to server: Expect: 100-continue
05-Sep-2011 20:08:08 [---] [http] [ID#15] Sent header to server: 
05-Sep-2011 20:08:09 [---] [http] [ID#15] Received header from server: HTTP/1.1 100 Continue
05-Sep-2011 20:08:09 [---] [http] [ID#15] Received header from server: HTTP/1.1 200 OK
05-Sep-2011 20:08:09 [---] [http] [ID#15] Received header from server: Date: Mon, 05 Sep 2011 18:08:09 GMT
05-Sep-2011 20:08:09 [---] [http] [ID#15] Received header from server: Server: Apache/2.2.3 (Red Hat)
05-Sep-2011 20:08:09 [---] [http] [ID#15] Received header from server: Connection: close
05-Sep-2011 20:08:09 [---] [http] [ID#15] Received header from server: Transfer-Encoding: chunked
05-Sep-2011 20:08:09 [---] [http] [ID#15] Received header from server: Content-Type: text/plain; charset=UTF-8
05-Sep-2011 20:08:09 [---] [http] [ID#15] Received header from server: 
05-Sep-2011 20:08:09 [---] [http] [ID#15] Info:  Closing connection #0
05-Sep-2011 20:08:09 [---] [http] [ID#15] Info:  Expire cleared
05-Sep-2011 20:08:10 [rosetta@home] Finished upload of 3alipt_1_CYCA_2byo_ProteinInterfaceDesign_26Aug2011_30692_100_0_0

I am using a SOCKS proxy only, no HTTP_PROXY:

05-Sep-2011 19:56:39 [---] Using proxy info from environment variables
05-Sep-2011 19:56:39 [---] Using SOCKS proxy localhost:4096

Change History (3)

comment:1 Changed 13 years ago by blueyed

The Upload to rosetta@from above now worked, and I only have uploads to WCG pending. Having enabled http_xfer_debug now, too, I am seeing this:

05-Sep-2011 20:21:15 [---] [proxy] HTTP_OP::no_proxy_for_url(): https://grid.worldcommunitygrid.org/boinc/wcg_cgi/file_upload_handler
05-Sep-2011 20:21:15 [---] [proxy] returning false
05-Sep-2011 20:21:15 [World Community Grid] Started upload of faah24240_ZINC00808923_x2IEN_wtHIV_04_0_0
05-Sep-2011 20:21:16 [---] [http] [ID#10] Info:  About to connect() to proxy localhost port 4096 (#2)
05-Sep-2011 20:21:16 [---] [http] [ID#10] Info:    Trying 127.0.0.1... 
05-Sep-2011 20:21:16 [---] [http] [ID#10] Info:  connected
05-Sep-2011 20:21:16 [---] [http] [ID#10] Info:  Connected to localhost (127.0.0.1) port 4096 (#2)
05-Sep-2011 20:21:16 [---] [http] [ID#10] Info:  successfully set certificate verify locations:
05-Sep-2011 20:21:16 [---] [http] [ID#10] Info:    CAfile: ca-bundle.crt
05-Sep-2011 20:21:16 [---] [http] [ID#10] Info:    CApath: /etc/ssl/certs
05-Sep-2011 20:21:16 [---] [http] [ID#10] Info:  SSLv3, TLS handshake, Client hello (1):
05-Sep-2011 20:21:16 [---] [http] [ID#10] Info:  0x9f85480 is at send pipe head!
05-Sep-2011 20:21:16 [---] [http] [ID#10] Info:  Received invalid version in initial SOCKS5 response.
05-Sep-2011 20:21:16 [---] [http] [ID#10] Info:  Closing connection #2
05-Sep-2011 20:21:16 [---] [http] HTTP error: Couldn't connect to server
05-Sep-2011 20:21:16 [---] [http] [ID#10] Info:  Expire cleared
05-Sep-2011 20:21:17 [---] Project communication failed: attempting access to reference site
05-Sep-2011 20:21:17 [---] [http] HTTP_OP::init_get(): http://www.google.com/
05-Sep-2011 20:21:17 [---] [proxy] HTTP_OP::no_proxy_for_url(): http://www.google.com/
05-Sep-2011 20:21:17 [---] [proxy] returning false
05-Sep-2011 20:21:17 [World Community Grid] Temporarily failed upload of faah24240_ZINC00808923_x2IEN_wtHIV_04_0_0: connect() failed

This is the verbose output from ssh:

debug1: Connection to port 4096 forwarding to socks port 0 requested.
debug1: channel 2: new [dynamic-tcpip]
debug1: channel 2: free: direct-tcpip: listening port 4096 for 198.20.8.241 port 443, connect from 127.0.0.1 port 33699, nchannels 5

comment:2 Changed 13 years ago by blueyed

Having unset SOCKS_SERVER, it now still fails for WCG..

05-Sep-2011 20:26:36 [---] [proxy] HTTP_OP::no_proxy_for_url(): https://grid.worldcommunitygrid.org/boinc/wcg_cgi/file_upload_handler
05-Sep-2011 20:26:36 [---] [proxy] returning false
05-Sep-2011 20:26:36 [World Community Grid] Started upload of faah24240_ZINC00808923_x2IEN_wtHIV_04_0_0
05-Sep-2011 20:26:37 [---] [http] [ID#3] Info:  Connection #0 seems to be dead!
05-Sep-2011 20:26:37 [---] [http] [ID#3] Info:  Closing connection #0
05-Sep-2011 20:26:37 [---] [http] [ID#3] Info:  About to connect() to grid.worldcommunitygrid.org port 443 (#0)
05-Sep-2011 20:26:37 [---] [http] [ID#3] Info:    Trying 198.20.8.241... 
05-Sep-2011 20:26:37 [---] [http] [ID#3] Info:  0x8feb078 is at send pipe head!
05-Sep-2011 20:26:37 [---] [http] [ID#3] Info:  Connected to grid.worldcommunitygrid.org (198.20.8.241) port 443 (#0)
05-Sep-2011 20:26:37 [---] [http] [ID#3] Info:  successfully set certificate verify locations:
05-Sep-2011 20:26:37 [---] [http] [ID#3] Info:    CAfile: ca-bundle.crt
05-Sep-2011 20:26:37 [---] [http] [ID#3] Info:    CApath: /etc/ssl/certs
05-Sep-2011 20:26:37 [---] [http] [ID#3] Info:  SSLv3, TLS handshake, Client hello (1):
05-Sep-2011 20:26:38 [---] [http] [ID#3] Info:  SSLv3, TLS handshake, Server hello (2):
05-Sep-2011 20:26:38 [---] [http] [ID#3] Info:  SSLv3, TLS handshake, CERT (11):
05-Sep-2011 20:26:38 [---] [http] [ID#3] Info:  SSLv3, TLS handshake, Server finished (14):
05-Sep-2011 20:26:38 [---] [http] [ID#3] Info:  SSLv3, TLS handshake, Client key exchange (16):
05-Sep-2011 20:26:38 [---] [http] [ID#3] Info:  SSLv3, TLS change cipher, Client hello (1):
05-Sep-2011 20:26:38 [---] [http] [ID#3] Info:  SSLv3, TLS handshake, Finished (20):
05-Sep-2011 20:26:38 [---] [http] [ID#3] Info:  SSLv3, TLS change cipher, Client hello (1):
05-Sep-2011 20:26:38 [---] [http] [ID#3] Info:  SSLv3, TLS handshake, Finished (20):
05-Sep-2011 20:26:38 [---] [http] [ID#3] Info:  SSL connection using AES256-SHA
05-Sep-2011 20:26:38 [---] [http] [ID#3] Info:  Server certificate:
05-Sep-2011 20:26:38 [---] [http] [ID#3] Info:  	 subject: C=US; ST=Georgia; L=Jasper; O=Sea Blue, Inc; CN=*.worldcommunitygrid.org
05-Sep-2011 20:26:38 [---] [http] [ID#3] Info:  	 start date: 2011-06-23 00:00:00 GMT
05-Sep-2011 20:26:38 [---] [http] [ID#3] Info:  	 expire date: 2013-06-22 23:59:59 GMT
05-Sep-2011 20:26:38 [---] [http] [ID#3] Info:  	 common name: *.worldcommunitygrid.org (matched)
05-Sep-2011 20:26:38 [---] [http] [ID#3] Info:  	 issuer: C=US; O=Thawte, Inc.; CN=Thawte SSL CA
05-Sep-2011 20:26:38 [---] [http] [ID#3] Info:  	 SSL certificate verify ok.
05-Sep-2011 20:26:38 [---] [http] [ID#3] Sent header to server: POST /boinc/wcg_cgi/file_upload_handler HTTP/1.1
05-Sep-2011 20:26:38 [---] [http] [ID#3] Sent header to server: User-Agent: BOINC client (i686-pc-linux-gnu 6.12.33)
05-Sep-2011 20:26:38 [---] [http] [ID#3] Sent header to server: Host: grid.worldcommunitygrid.org
05-Sep-2011 20:26:38 [---] [http] [ID#3] Sent header to server: Accept: */*
05-Sep-2011 20:26:38 [---] [http] [ID#3] Sent header to server: Accept-Encoding: deflate, gzip
05-Sep-2011 20:26:38 [---] [http] [ID#3] Sent header to server: Content-Type: application/x-www-form-urlencoded
05-Sep-2011 20:26:38 [---] [http] [ID#3] Sent header to server: Content-Length: 3762
05-Sep-2011 20:26:38 [---] [http] [ID#3] Sent header to server: Expect: 100-continue
05-Sep-2011 20:26:38 [---] [http] [ID#3] Sent header to server: 
05-Sep-2011 20:26:38 [---] [http] [ID#3] Received header from server: HTTP/1.1 100 Continue
05-Sep-2011 20:26:39 [---] [http] [ID#3] Received header from server: HTTP/1.1 200 OK
05-Sep-2011 20:26:39 [---] [http] [ID#3] Received header from server: Date: Mon, 05 Sep 2011 18:26:19 GMT
05-Sep-2011 20:26:39 [---] [http] [ID#3] Received header from server: Server: IBM_HTTP_Server
05-Sep-2011 20:26:39 [---] [http] [ID#3] Received header from server: Transfer-Encoding: chunked
05-Sep-2011 20:26:39 [---] [http] [ID#3] Received header from server: Content-Type: text/plain
05-Sep-2011 20:26:39 [---] [http] [ID#3] Received header from server: 
05-Sep-2011 20:26:39 [---] [http_xfer] [ID#3] HTTP: wrote 64 bytes
05-Sep-2011 20:26:39 [---] [http] [ID#3] Info:  Connection #0 to host grid.worldcommunitygrid.org left intact
05-Sep-2011 20:26:39 [---] [http] [ID#3] Info:  Expire cleared
05-Sep-2011 20:26:40 [World Community Grid] Temporarily failed upload of faah24240_ZINC00808923_x2IEN_wtHIV_04_0_0: transient upload error

So it's likely that the proxy is not the issue here after all (permanently).

Feel free to close this bug as invalid, but please consider looking at how the transfer (reporting) might get improved.

comment:3 Changed 13 years ago by blueyed

Summary: Uploading through SOCKS proxy fails often with error "transient upload error"Uploading through SOCKS proxy fails often with error "transient upload error" / "Received invalid version in initial SOCKS5 response" (WCG)

I could now upload 4 packets without SOCKS_SERVER to WCG, but enabling it again I am now constantly get "Received invalid version in initial SOCKS5 response"

05-Sep-2011 20:33:32 [World Community Grid] Started upload of faah24240_ZINC00808923_x2IEN_wtHIV_04_0_3
05-Sep-2011 20:33:32 [---] [http] [ID#10] Info:  Connection #0 seems to be dead!
05-Sep-2011 20:33:32 [---] [http] [ID#10] Info:  Closing connection #0
05-Sep-2011 20:33:32 [---] [http] [ID#10] Info:  Connection #2 seems to be dead!
05-Sep-2011 20:33:32 [---] [http] [ID#10] Info:  Closing connection #2
05-Sep-2011 20:33:32 [---] [http] [ID#10] Info:  About to connect() to proxy localhost port 4096 (#0)
05-Sep-2011 20:33:32 [---] [http] [ID#10] Info:    Trying 127.0.0.1... 
05-Sep-2011 20:33:32 [---] [http] [ID#10] Info:  connected
05-Sep-2011 20:33:32 [---] [http] [ID#10] Info:  Connected to localhost (127.0.0.1) port 4096 (#0)
05-Sep-2011 20:33:32 [---] [http] [ID#10] Info:  successfully set certificate verify locations:
05-Sep-2011 20:33:32 [---] [http] [ID#10] Info:    CAfile: ca-bundle.crt
05-Sep-2011 20:33:32 [---] [http] [ID#10] Info:    CApath: /etc/ssl/certs
05-Sep-2011 20:33:32 [---] [http] [ID#10] Info:  SSLv3, TLS handshake, Client hello (1):
05-Sep-2011 20:33:32 [---] [http] [ID#10] Info:  0x86180d0 is at send pipe head!
05-Sep-2011 20:33:32 [---] [http] [ID#10] Info:  Received invalid version in initial SOCKS5 response.
05-Sep-2011 20:33:32 [---] [http] [ID#10] Info:  Closing connection #0
05-Sep-2011 20:33:32 [---] [http] HTTP error: Couldn't connect to server
05-Sep-2011 20:33:32 [---] [http] [ID#10] Info:  Expire cleared
Note: See TracTickets for help on using tickets.