Occasional Net::HTTPBadResponse after sending first message

[gkaklas]

When sending a message with simple_client.rb sometimes it works fine, but other times I get these errors and the program exits after sending the message:

#<Thread:0x000055c9759eba80@/home/user/.gem/ruby/2.5.0/gems/logging-2.2.2/lib/logging/diagnostic_context.rb:471 run> terminated with exception (report_on_exception is true):
Traceback (most recent call last):
        13: from /home/user/.gem/ruby/2.5.0/gems/logging-2.2.2/lib/logging/diagnostic_context.rb:474:in `block in create_with_logging_context'
        12: from /home/user/.gem/ruby/2.5.0/gems/matrix_sdk-0.0.3/lib/matrix_sdk/client.rb:140:in `block in start_listener_thread'
        11: from /home/user/.gem/ruby/2.5.0/gems/matrix_sdk-0.0.3/lib/matrix_sdk/client.rb:162:in `listen_forever'
        10: from /home/user/.gem/ruby/2.5.0/gems/matrix_sdk-0.0.3/lib/matrix_sdk/client.rb:223:in `sync'
         9: from /home/user/.gem/ruby/2.5.0/gems/matrix_sdk-0.0.3/lib/matrix_sdk/api.rb:126:in `sync'
         8: from /home/user/.gem/ruby/2.5.0/gems/matrix_sdk-0.0.3/lib/matrix_sdk/api.rb:610:in `request'
         7: from /home/user/.gem/ruby/2.5.0/gems/matrix_sdk-0.0.3/lib/matrix_sdk/api.rb:610:in `loop'
         6: from /home/user/.gem/ruby/2.5.0/gems/matrix_sdk-0.0.3/lib/matrix_sdk/api.rb:614:in `block in request'
         5: from /usr/lib/ruby/2.5.0/net/http.rb:1464:in `request'
         4: from /usr/lib/ruby/2.5.0/net/http.rb:1491:in `transport_request'
         3: from /usr/lib/ruby/2.5.0/net/http.rb:1491:in `catch'
         2: from /usr/lib/ruby/2.5.0/net/http.rb:1494:in `block in transport_request'
         1: from /usr/lib/ruby/2.5.0/net/http/response.rb:29:in `read_new'
/usr/lib/ruby/2.5.0/net/http/response.rb:42:in `read_status_line': wrong status line: "0" (Net::HTTPBadResponse)
Traceback (most recent call last):
        14: from examples/simple_client.rb:78:in `<main>'
        13: from examples/simple_client.rb:78:in `loop'
        12: from examples/simple_client.rb:87:in `block in <main>'
        11: from /home/user/.gem/ruby/2.5.0/gems/matrix_sdk-0.0.3/lib/matrix_sdk/room.rb:140:in `send_text'
        10: from /home/user/.gem/ruby/2.5.0/gems/matrix_sdk-0.0.3/lib/matrix_sdk/api.rb:289:in `send_message'
         9: from /home/user/.gem/ruby/2.5.0/gems/matrix_sdk-0.0.3/lib/matrix_sdk/api.rb:241:in `send_message_event'
         8: from /home/user/.gem/ruby/2.5.0/gems/matrix_sdk-0.0.3/lib/matrix_sdk/api.rb:610:in `request'
         7: from /home/user/.gem/ruby/2.5.0/gems/matrix_sdk-0.0.3/lib/matrix_sdk/api.rb:610:in `loop'
         6: from /home/user/.gem/ruby/2.5.0/gems/matrix_sdk-0.0.3/lib/matrix_sdk/api.rb:614:in `block in request'
         5: from /usr/lib/ruby/2.5.0/net/http.rb:1464:in `request'
         4: from /usr/lib/ruby/2.5.0/net/http.rb:1491:in `transport_request'
         3: from /usr/lib/ruby/2.5.0/net/http.rb:1491:in `catch'
         2: from /usr/lib/ruby/2.5.0/net/http.rb:1494:in `block in transport_request'
         1: from /usr/lib/ruby/2.5.0/net/http/response.rb:29:in `read_new'
/usr/lib/ruby/2.5.0/net/http/response.rb:42:in `read_status_line': wrong status line: "" (Net::HTTPBadResponse)

By running it a few times, I noticed that this either happens after the first message that is sent after the client is started or it doesn't happen at all. If it happens, it usually takes a few extra seconds to send the message, but it is delivered successfully just before exiting.

[ananace]

That sounds really odd, the stacktrace disappears down into the Ruby HTTP layer itself, and it seems like the server responds with something that's not parsable as a HTTP response.

Could you maybe attach a tcpdump, wireshark, or something similar beside the application - to see if you can get a copy of the request and response that ends up killing the application? (Of course without API keys and other identifiable information)

[gkaklas]

I tried to capture the traffic but the server uses TLS when responding, even if you request using plain HTTP. I started looking on how can someone debug this easily without having to read the traffic, and I found this gist, which produced the following:

<- "PUT /_matrix/client/r0/rooms/%21123456%3Amatrix.org/send/m.room.message/123456 HTTP/1.1\r\nAccept-Encoding: gzip;q=1.0,deflate;q=0.6,identity;q=0.3\r\nA
ccept: application/json\r\nUser-Agent: Ruby Matrix SDK v0.0.3\r\nContent-Type: application/json\r\nContent-Length: 33\r\nAuthorization: Bearer 123456\r\nHost: matrix.org\r\n\r\n"
<- "{\"msgtype\":\"m.text\",\"body\":\"Hello World\"}"
-> "0\r\n"
Conn close because of error wrong status line: "0"
-> "\r\n"
Conn close because of error wrong status line: ""
opening connection to matrix.org:443...
#<Thread:0x000055ca19aec430@/home/user/.gem/ruby/2.5.0/gems/logging-2.2.2/lib/logging/diagnostic_context.rb:471 run> terminated with exception (report_on_exception is tru
e):
Traceback (most recent call last):
        13: from /home/user/.gem/ruby/2.5.0/gems/logging-2.2.2/lib/logging/diagnostic_context.rb:474:in `block in create_with_logging_context'
        12: from /home/user/.gem/ruby/2.5.0/gems/matrix_sdk-0.0.3/lib/matrix_sdk/client.rb:140:in `block in start_listener_thread'
        11: from /home/user/.gem/ruby/2.5.0/gems/matrix_sdk-0.0.3/lib/matrix_sdk/client.rb:162:in `listen_forever'
        10: from /home/user/.gem/ruby/2.5.0/gems/matrix_sdk-0.0.3/lib/matrix_sdk/client.rb:223:in `sync'
         9: from /home/user/.gem/ruby/2.5.0/gems/matrix_sdk-0.0.3/lib/matrix_sdk/api.rb:126:in `sync'
         8: from /home/user/.gem/ruby/2.5.0/gems/matrix_sdk-0.0.3/lib/matrix_sdk/api.rb:610:in `request'
         7: from /home/user/.gem/ruby/2.5.0/gems/matrix_sdk-0.0.3/lib/matrix_sdk/api.rb:610:in `loop'
         6: from /home/user/.gem/ruby/2.5.0/gems/matrix_sdk-0.0.3/lib/matrix_sdk/api.rb:614:in `block in request'
         5: from /usr/lib/ruby/2.5.0/net/http.rb:1464:in `request'
         4: from /usr/lib/ruby/2.5.0/net/http.rb:1491:in `transport_request'
         3: from /usr/lib/ruby/2.5.0/net/http.rb:1491:in `catch'
         2: from /usr/lib/ruby/2.5.0/net/http.rb:1494:in `block in transport_request'
         1: from /usr/lib/ruby/2.5.0/net/http/response.rb:29:in `read_new'
/usr/lib/ruby/2.5.0/net/http/response.rb:42:in `read_status_line': wrong status line: "0" (Net::HTTPBadResponse)
opened
starting SSL for matrix.org:443...
SSL established
<- "POST /_matrix/client/r0/logout HTTP/1.1\r\nAccept-Encoding: gzip;q=1.0,deflate;q=0.6,identity;q=0.3\r\nAccept: application/json\r\nUser-Agent: Ruby Matrix SDK v0.0.3\r\n
Authorization: Bearer 123456\r\nHost: matrix.org\r\nContent-Length: 0\r\nContent-Type
: application/x-www-form-urlencoded\r\n\r\n"
<- ""
-> "HTTP/1.1 200 OK\r\n"
-> "Date: Fri, 23 Nov 2018 09:00:37 GMT\r\n"
-> "Content-Type: application/json\r\n"
-> "Transfer-Encoding: chunked\r\n"
-> "Connection: keep-alive\r\n"
-> "Set-Cookie: __cfduid=123456; expires=Sat, 23-Nov-19 09:00:37 GMT; path=/; domain=.matrix.org; HttpOnly\r\n"
-> "Cache-Control: no-cache, no-store, must-revalidate\r\n"
-> "Access-Control-Allow-Origin: *\r\n"
-> "Access-Control-Allow-Methods: GET, POST, PUT, DELETE, OPTIONS\r\n"
-> "Access-Control-Allow-Headers: Origin, X-Requested-With, Content-Type, Accept, Authorization\r\n"
-> "Content-Encoding: gzip\r\n"
-> "Expect-CT: max-age=604800, report-uri=\"https://report-uri.cloudflare.com/cdn-cgi/beacon/expect-ct\"\r\n"
-> "Server: cloudflare\r\n"
-> "CF-RAY: 123456\r\n"
-> "\r\n"
-> "16\r\n"
reading 22 bytes...
-> "\x1F\x8B\b\x00\x00\x00\x00\x00\x04\x03\xAB\xAE\x05\x00C\xBF\xA6\xA3\x02\x00\x00\x00"
read 22 bytes
reading 2 bytes...
-> "\r\n"
read 2 bytes
-> "0\r\n"
-> "\r\n"
Conn keep-alive
Traceback (most recent call last):
        14: from examples/simple_client.rb:94:in `<main>'
        13: from examples/simple_client.rb:94:in `loop'
        12: from examples/simple_client.rb:103:in `block in <main>'
        11: from /home/user/.gem/ruby/2.5.0/gems/matrix_sdk-0.0.3/lib/matrix_sdk/room.rb:140:in `send_text'
        10: from /home/user/.gem/ruby/2.5.0/gems/matrix_sdk-0.0.3/lib/matrix_sdk/api.rb:289:in `send_message'
         9: from /home/user/.gem/ruby/2.5.0/gems/matrix_sdk-0.0.3/lib/matrix_sdk/api.rb:241:in `send_message_event'
         8: from /home/user/.gem/ruby/2.5.0/gems/matrix_sdk-0.0.3/lib/matrix_sdk/api.rb:610:in `request'
         7: from /home/user/.gem/ruby/2.5.0/gems/matrix_sdk-0.0.3/lib/matrix_sdk/api.rb:610:in `loop'
         6: from /home/user/.gem/ruby/2.5.0/gems/matrix_sdk-0.0.3/lib/matrix_sdk/api.rb:614:in `block in request'
         5: from /usr/lib/ruby/2.5.0/net/http.rb:1464:in `request'
         4: from /usr/lib/ruby/2.5.0/net/http.rb:1491:in `transport_request'
         3: from /usr/lib/ruby/2.5.0/net/http.rb:1491:in `catch'
         2: from /usr/lib/ruby/2.5.0/net/http.rb:1494:in `block in transport_request'
         1: from /usr/lib/ruby/2.5.0/net/http/response.rb:29:in `read_new'
/usr/lib/ruby/2.5.0/net/http/response.rb:42:in `read_status_line': wrong status line: "" (Net::HTTPBadResponse)

On another note, this issue, which was solved with this PR, plus this SE answer suggest that setting Net::HTTP.use_ssl should fix the problem :thinking:

[ananace]

Not quite the same issue there, the linked issue reports an error with a status line filled with non-ASCII garbage - also known as encrypted data.
Your issue on the other hand reports an error with perfectly legible ASCII and correctly delimited using CRLF terminators. (Something that should be impossible unless SSL is decrypted properly)

Also, SSL is used if your homeserver URL uses the https scheme, or in fact if not provided a scheme. So the only way to not use SSL is to explicitly request a connection to a http:// URL. https://github.com/ananace/ruby-matrix-sdk/blob/master/lib/matrix_sdk/api.rb#L899-L907

In all honesty, it seems like the server's responding with just a 0, which seems really odd.
Do you have the ability to test against another HS than matrix.org? Just to see if it happens anywhere else.