Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Occasional Net::HTTPBadResponse after sending first message #4

Open
gkaklas opened this issue Nov 22, 2018 · 3 comments
Open

Occasional Net::HTTPBadResponse after sending first message #4

gkaklas opened this issue Nov 22, 2018 · 3 comments

Comments

@gkaklas
Copy link

gkaklas commented Nov 22, 2018

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
Copy link
Owner

ananace commented Nov 22, 2018

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
Copy link
Author

gkaklas commented Nov 23, 2018 •
edited
Loading

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 🤔

@ananace
Copy link
Owner

ananace commented Nov 23, 2018

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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@ananace @gkaklas