xpra icon
Bug tracker and wiki

Opened 4 months ago

Closed 4 months ago

Last modified 3 months ago

#2315 closed defect (fixed)

Seeing ERR_INVALID_HTTP_RESPONSE when connecting with HTML 5 client using 3.0 server

Reported by: zaveri Owned by: Antoine Martin
Priority: major Milestone: 3.0
Component: html5 Version: trunk
Keywords: Cc:

Description

XPRA Version : v3.0-r22848
When Connecting with an HTML5 Client via a Google Chrome 74.0.3729.169 (Official Build) (64-bit) (cohort: Stable) browser, getting Invalid Packet Error Messages on the server side logs.

Checking Console Logs, see the below output

connection_progress( WebSocket connection established ,   ,  80 )
11:20:39.077 Utilities.js:1 sending hello
11:20:39.078 Utilities.js:1 navigator.clipboard= undefined
11:20:39.078 Client.js:1112 Uncaught TypeError: Cannot read property 'readText' of undefined
    at XpraClient._make_hello (Client.js:1112)
    at XpraClient._send_hello (Client.js:988)
    at XpraClient._process_open (Client.js:1482)
    at XpraProtocolWorkerHost.XpraClient._route_packet [as packet_handler] (Client.js:504)
    at Worker.<anonymous> (Protocol.js:1)
11:21:00.013 Protocol.js:1 WebSocket connection to 'ws://10.0.3.198:13500/' failed: One or more reserved bits are on: reserved1 = 1, reserved2 = 1, reserved3 = 0
XpraProtocol.open @ Protocol.js:1
11:21:00.016 Utilities.js:1 websocket error:  undefined reason:  null
cerror @ Utilities.js:1
11:21:00.017 Utilities.js:1 websocket closed:  undefined reason:  null , reconnect:  true , reconnect attempt:  0
11:21:00.018 Utilities.js:1 connection-lost
11:21:00.028 Protocol.js:1 WebSocket is already in CLOSING or CLOSED state.
XpraProtocol.process_send_queue @ Protocol.js:1
11:21:01.031 Utilities.js:1 connection-lost
11:21:01.032 Utilities.js:1 connection_progress( Connecting to server ,  10.0.3.198:13500/ ,  40 )
11:21:01.033 Utilities.js:1 we have webworker support
11:21:05.166 wsworker_check.js:1 Failed to load resource: net::ERR_INVALID_HTTP_RESPONSE

Only Server Logs I see for F30 system

2019-06-04 14:32:08,668 Error: connection timed out: ws socket: 10.0.3.198:13000 <- 10.0.4.36:58383
2019-06-04 14:32:08,671 no ethtool interface speed available for eth0

When trying to launch xpra with Fed 29 system, we get the below logs in the console

[Violation] 'DOMContentLoaded' handler took 275ms
14:23:17.722 Utilities.js:1 mouse set_touchaction() touchaction= none label= zoom
14:23:17.730 Utilities.js:1 debug enabled for: []
14:23:17.805 Utilities.js:1 The AudioContext was not allowed to start. It must be resumed (or created) after a user gesture on the page. https://goo.gl/7K7WLu
getAudioContext @ Utilities.js:1
XpraClient.init_state @ Client.js:1
XpraClient @ Client.js:1
init_client @ (index):488
(anonymous) @ (index):882
mightThrow @ jquery.js:3583
process @ jquery.js:3651
setTimeout (async)
(anonymous) @ jquery.js:3689
fire @ jquery.js:3317
fireWith @ jquery.js:3447
fire @ jquery.js:3455
fire @ jquery.js:3317
fireWith @ jquery.js:3447
ready @ jquery.js:3920
completed @ jquery.js:3930
14:23:17.808 Utilities.js:1 connection_progress( Initializing ,   ,  20 )
14:23:17.814 Utilities.js:1 connection_progress( Connecting to server ,  10.0.3.42:12000/ ,  40 )
14:23:17.815 Utilities.js:1 we have webworker support
14:23:17.819 jquery.js:3649 [Violation] 'setTimeout' handler took 98ms
14:23:18.128 Utilities.js:1 we can use websocket in webworker
14:23:18.129 Utilities.js:1 connection_progress( Opening WebSocket connection ,  ws://10.0.3.42:12000/ ,  60 )
14:23:22.145 Protocol.js:1 GET http://10.0.3.42:12000/js/Protocol.js net::ERR_INVALID_HTTP_RESPONSE

Server Logs on the Fed29 xpra v3.0-r22786

2019-06-04 14:23:12,946 New tcp connection received from 10.0.4.36:57846 on 0.0.0.0:12000
2019-06-04 14:23:13,897 Disconnecting client ('10.0.4.36', 57846):
2019-06-04 14:23:13,897  invalid packet format, HTTP GET request
2019-06-04 14:29:10,619 New tcp connection received from 10.0.4.36:58197 on 0.0.0.0:12000
2019-06-04 14:29:10,619 New tcp connection received from 10.0.4.36:58198 on 0.0.0.0:12000
2019-06-04 14:29:11,651 Disconnecting client ('10.0.4.36', 58197):
2019-06-04 14:29:11,651  invalid packet format, HTTP GET request
2019-06-04 14:29:12,192 Disconnecting client ('10.0.4.36', 58198):
2019-06-04 14:29:12,192  invalid packet format, HTTP GET request
2019-06-04 14:29:13,227 New tcp connection received from 10.0.4.36:58200 on 0.0.0.0:12000
2019-06-04 14:29:17,261 Disconnecting client ('10.0.4.36', 58200):
2019-06-04 14:29:17,261  invalid packet format, HTTP GET request
2019-06-04 14:29:18,292 New tcp connection received from 10.0.4.36:58208 on 0.0.0.0:12000
2019-06-04 14:29:39,298 Error: connection timed out: tcp socket: 10.0.3.42:12000 <- 10.0.4.36:58208

On a Fedora 30 server, unable to connect at all. Pointing to the console log errors.

On the Fedora 29 server, running xpra v3.0-r22786. Start the xpra server and try connecting via the HTML client --> It does not load. Keep at it for about a Minute and then you can connect. Above posted are the console logs this.

On the F29, we are eventually able to connect. We get the below server side logs when using -d network flag

2019-06-04 12:04:06,788 read_parse_thread_loop starting
2019-06-04 12:04:06,788 invalid_header(Protocol(tcp socket: 10.0.3.42:12000 <- 10.0.4.36:49783), 400 bytes: 'invalid packet header byte GET /icons/maximize.png HTTP/1.1
Host: 10.0.3.42:12000
Connection: keep-alive
User-Agent: Mozilla/5.0 (Windows NT 6.1; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/74.0.3729.169 Safari/537.36
Accept: image/webp,image/apng,image/*,*/*;q=0.8
Referer: http://10.0.3.42:12000/
Accept-Encoding: gzip, deflate
Accept-Language: en-US,en;q=0.9
Cookie: _ga=GA1.1.1928512604.1559240501

', 'GET /icons/maximize.png HTTP/1.1\r\nHost: 10.0. .. Cookie: _ga=GA1.1.1928512604.1559240501\r\n\r\n')
2019-06-04 12:04:06,788  input_packetcount=0, tcp_proxy=, html=True, ssl=False
2019-06-04 12:04:06,789 guess_header_protocol("'GET /icons/maximize.png HTTP/1.1\\r\\nHost: 10.0. .. Cookie: _ga=GA1.1.1928512604.1559240501\\r\\n\\r\\n'") first char=0x47
2019-06-04 12:04:06,789 process default packet gibberish
2019-06-04 12:04:06,789 Received uninterpretable nonsense from Protocol(tcp socket: 10.0.3.42:12000 <- 10.0.4.36:49783): invalid packet format, HTTP GET request
2019-06-04 12:04:06,789  data: 'GET /icons/maximize.png HTTP/1.1\r\nHost: 10.0. .. Cookie: _ga=GA1.1.1928512604.1559240501\r\n\r\n'
2019-06-04 12:04:06,789 disconnect_client(Protocol(tcp socket: 10.0.3.42:12000 <- 10.0.4.36:49783), invalid packet format, HTTP GET request, ())
2019-06-04 12:04:06,789 disconnect_protocol(Protocol(tcp socket: 10.0.3.42:12000 <- 10.0.4.36:49783), ('invalid packet format, HTTP GET request',))
2019-06-04 12:04:06,789 Disconnecting client ('10.0.4.36', 49783):
2019-06-04 12:04:06,789  invalid packet format, HTTP GET request
2019-06-04 12:04:06,789 flush_then_close(['disconnect', 'invalid packet format, HTTP GET request'], None) closed=False
2019-06-04 12:04:06,789 flush_then_close: wait_for_write_lock()

Change History (4)

comment:1 Changed 4 months ago by Antoine Martin

Resolution: fixed
Status: newclosed

This should be fixed in r22852.

This was caused by #2312.

comment:2 Changed 3 months ago by zaveri

I can now connect with xpra v3.0-r22875 on a Fed 30 system with an HTML 5 client.

But the handshake does not successfully complete the connection attempts until a Full Minute after the 'xpra is ready'

2019-06-11 15:33:58,757 xpra is ready.
2019-06-11 15:34:02,533 New tcp connection received from 10.0.4.71:60795 on 0.0.0.0:12000
2019-06-11 15:34:02,534 New tcp connection received from 10.0.4.71:60796 on 0.0.0.0:12000
2019-06-11 15:34:03,482 no ethtool interface speed available for eth0
2019-06-11 15:34:03,482 Disconnecting client ('10.0.4.71', 60795):
2019-06-11 15:34:03,482  invalid packet format, HTTP GET request
2019-06-11 15:34:04,949 printer forwarding enabled using postscript and pdf
2019-06-11 15:34:04,964 watching for applications menu changes in:
2019-06-11 15:34:04,964  '/usr/local/share/applications'
2019-06-11 15:34:04,964  '/usr/share/applications'
2019-06-11 15:34:05,090 5.8GB of system memory
2019-06-11 15:34:10,892 Disconnecting client ('10.0.4.71', 60796):
2019-06-11 15:34:10,893  invalid packet format, HTTP GET request
2019-06-11 15:34:11,923 New tcp connection received from 10.0.4.71:60806 on 0.0.0.0:12000
2019-06-11 15:34:12,211 Disconnecting client ('10.0.4.71', 60806):
2019-06-11 15:34:12,211  invalid packet format, HTTP GET request
2019-06-11 15:34:13,242 New tcp connection received from 10.0.4.71:60807 on 0.0.0.0:12000
2019-06-11 15:34:18,787 Disconnecting client ('10.0.4.71', 60807):
2019-06-11 15:34:18,787  invalid packet format, HTTP GET request
2019-06-11 15:34:19,794 New tcp connection received from 10.0.4.71:60815 on 0.0.0.0:12000
2019-06-11 15:34:20,290 Disconnecting client ('10.0.4.71', 60815):
2019-06-11 15:34:20,291  invalid packet format, HTTP GET request
2019-06-11 15:34:21,323 New tcp connection received from 10.0.4.71:60817 on 0.0.0.0:12000
2019-06-11 15:34:21,325 Disconnecting client ('10.0.4.71', 60817):
2019-06-11 15:34:21,325  invalid packet format, HTTP GET request
2019-06-11 15:34:22,189 New tcp connection received from 10.0.4.71:60818 on 0.0.0.0:12000
2019-06-11 15:34:22,509 Disconnecting client ('10.0.4.71', 60818):
2019-06-11 15:34:22,509  invalid packet format, HTTP GET request
2019-06-11 15:34:23,552 New tcp connection received from 10.0.4.71:60819 on 0.0.0.0:12000
2019-06-11 15:34:46,059 Handshake complete; enabling connection
2019-06-11 15:34:46,069  automatic picture encoding enabled, also available:

Should we reopen for that delay?

comment:3 Changed 3 months ago by Antoine Martin

This is likely to be the exact same problem as #2316. Let's debug things there.

comment:4 Changed 3 months ago by Antoine Martin

FWIW: I've just seen this problem, using an MS Windows-7 VM running IE 11.

Note: See TracTickets for help on using tickets.