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

Strange SSL error #47

Closed
anamba opened this issue Feb 9, 2019 · 7 comments
Closed

Strange SSL error #47

anamba opened this issue Feb 9, 2019 · 7 comments
Labels
needs more info

Comments

@anamba
Copy link

anamba commented Feb 9, 2019

I'm using Raven 1.2.0. For some reason, it is failing to record a lot of errors. I found this in the log (after this point, Raven does not even attempt to send any more errors). I am not sure how to troubleshoot further, any advice would be appreciated.

E, [2019-02-09 07:25:32 +00:00 #19883] ERROR -- sentry: Unable to record event with remote Sentry server (OpenSSL::SSL::Error - SSL_read: error:1408F119:SSL routines:ssl3_get_record:decryption failed or bad record mac): /usr/share/crystal/src/openssl/ssl/socket.cr:0:9 in 'unbuffered_read'
/usr/share/crystal/src/io/buffered.cr:228:5 in 'gets'
/usr/share/crystal/src/io/stapled.cr:0:5 in 'exec_internal_single'
/usr/share/crystal/src/http/client.cr:499:5 in 'exec'
/usr/share/crystal/src/http/client.cr:612:5 in 'send_event'
/home/app/myapp/lib/raven/src/raven/instance.cr:107:7 in 'capture'
/home/app/myapp/lib/raven/src/raven.cr:10:5 in '->'
/usr/share/crystal/src/fiber.cr:255:3 in '???'
???
E, [2019-02-09 07:25:32 +00:00 #19883] ERROR -- sentry: Failed to submit event: IO::EOFError: End of file reached
@anamba
Copy link
Author

anamba commented Feb 9, 2019

This is another error seen in the same app's logs, also preventing error reporting. Not sure if this is related at all.

I, [2019-02-09 08:25:00 +00:00 #24374]  INFO -- sentry: Sending event c7b72fbf6af1444d9f774ddc15576dd3 to Sentry
E, [2019-02-09 08:25:00 +00:00 #24374] ERROR -- sentry: Unable to record event with remote Sentry server (Errno - Error writing to socket: Broken pipe): /usr/share/crystal/src/thread.cr:64:3 in 'unbuffered_write'
/usr/share/crystal/src/io/buffered.cr:207:5 in 'write'
/usr/share/crystal/src/openssl/bio.cr:24:7 in '->'
/usr/share/crystal/src/hash.cr:1072:30 in '[]='
/usr/share/crystal/src/fiber.cr:116:5 in '???'
/usr/share/crystal/src/gc/boehm.cr:76:5 in 'register_to_matrix'
/usr/share/crystal/src/openssl/ssl/socket.cr:122:5 in 'unbuffered_write'
/usr/share/crystal/src/io/buffered.cr:206:5 in 'write'
/usr/share/crystal/src/io.cr:184:5 in 'exec_internal_single'
/usr/share/crystal/src/http/client.cr:499:5 in 'exec'
/usr/share/crystal/src/http/client.cr:612:5 in 'send_event'
E, [2019-02-09 08:25:00 +00:00 #24374] ERROR -- sentry: Failed to submit event: Errno: Error writing to socket: Broken pipe

@Sija
Copy link
Owner

Sija commented Feb 9, 2019 •
edited
Loading

What's Crystal version you're using?

@Sija
Copy link
Owner

Sija commented Feb 9, 2019 •
edited
Loading

That's weird, both stacktraces you've posted seems off by 1 call:

...
/usr/share/crystal/src/http/client.cr:499:5 in 'exec' # => `HTTP::Client#exec_internal_single`
/usr/share/crystal/src/http/client.cr:612:5 in 'send_event' # => `HTTP::Client#exec`
/home/app/myapp/lib/raven/src/raven/instance.cr:107:7 in 'capture' # => `Raven::Instance#send_event`
...

@anamba anamba closed this as completed Feb 25, 2019
@anamba
Copy link
Author

anamba commented Feb 25, 2019

Haven't been able to reproduce this issue with latest Crystal and Raven.

@sam0x17
Copy link

sam0x17 commented Aug 12, 2019 •
edited
Loading

I am also getting this issue when running from kemal with up.sh (two consecutive requests are shown, the initial request after a cold start, and a follow-up request):

  Aug 11th 09:21:50pm INFO staging 44b5bfa initializing
  Aug 11th 09:21:50pm INFO staging 44b5bfa started app
  Aug 11th 09:21:50pm INFO staging 44b5bfa waiting for app to listen on PORT
  Aug 11th 09:21:51pm INFO staging 44b5bfa I, [2019-08-12 01:21:51 UTC #15]  INFO -- sentry: Raven 1.5.0 ready to catch errors
  Aug 11th 09:21:51pm INFO staging 44b5bfa app listening: duration=1.32s
  Aug 11th 09:21:51pm INFO staging 44b5bfa initialized: duration=1.36s
  Aug 11th 09:21:51pm INFO staging 44b5bfa request: id=8f24b4a8-bc9f-11e9-a3a5-4934cc1c7260 ip=68.0.236.215 method=GET path=/
  Aug 11th 09:21:52pm INFO staging 44b5bfa [development] Kemal is ready to lead at http://0.0.0.0:44695
  Aug 11th 09:21:52pm INFO staging 44b5bfa Exception: an error (Exception)
  Aug 11th 09:21:52pm INFO staging 44b5bfa   from /src/src/api.cr:11:3 in '->'
  Aug 11th 09:21:52pm INFO staging 44b5bfa   from /src/lib/kemal/src/kemal/route_handler.cr:255:3 in 'call'
  Aug 11th 09:21:52pm INFO staging 44b5bfa   from /usr/share/crystal/src/http/server/handler.cr:26:7 in 'call'
  Aug 11th 09:21:52pm INFO staging 44b5bfa   from /usr/share/crystal/src/http/server/handler.cr:26:7 in 'call'
  Aug 11th 09:21:52pm INFO staging 44b5bfa   from /usr/share/crystal/src/http/server/handler.cr:26:7 in 'call_next'
  Aug 11th 09:21:52pm INFO staging 44b5bfa   from /usr/share/crystal/src/http/server/handler.cr:26:7 in 'call'
  Aug 11th 09:21:52pm INFO staging 44b5bfa   from /usr/share/crystal/src/http/server/handler.cr:26:7 in 'call'
  Aug 11th 09:21:52pm INFO staging 44b5bfa   from /usr/share/crystal/src/http/server/handler.cr:26:7 in 'call'
  Aug 11th 09:21:52pm INFO staging 44b5bfa   from /usr/share/crystal/src/http/server/request_processor.cr:39:11 in 'process'
  Aug 11th 09:21:52pm INFO staging 44b5bfa   from /usr/share/crystal/src/fiber.cr:255:3 in '???'
  Aug 11th 09:21:52pm INFO staging 44b5bfa   from ???
  Aug 11th 09:21:52pm INFO staging 44b5bfa 
  Aug 11th 09:21:52pm INFO staging 44b5bfa 2019-08-12 01:21:52 UTC 500 GET / 675.06ms
  Aug 11th 09:21:52pm INFO staging 44b5bfa I, [2019-08-12 01:21:52 UTC #15]  INFO -- sentry: Sending event 2fa15153e73d478cb1e8c65434f61461 to Sentry
  Aug 11th 09:21:52pm ERRO staging 44b5bfa response: duration=699ms id=8f24b4a8-bc9f-11e9-a3a5-4934cc1c7260 ip=68.0.236.215 method=GET path=/ size=656 B status=500
  Aug 11th 09:21:52pm INFO REPORT RequestId: 255dd59c-a2a5-48fd-bd62-e5efdac37d6a    Duration: 2357.01 ms    Billed Duration: 2400 ms        Memory Size: 512 MB  Max Memory Used: 103 MB
  Aug 11th 09:22:39pm ERRO staging 44b5bfa response: duration=77ms id=acdbf941-bc9f-11e9-bd2a-fd0e5007ac07 ip=68.0.236.215 method=GET path=/ size=656 B status=500
  Aug 11th 09:22:39pm INFO staging 44b5bfa Exception: an error (Exception)
  Aug 11th 09:22:39pm INFO staging 44b5bfa   from /src/src/api.cr:11:3 in '->'
  Aug 11th 09:22:39pm INFO staging 44b5bfa   from /src/lib/kemal/src/kemal/route_handler.cr:255:3 in 'call'
  Aug 11th 09:22:39pm INFO staging 44b5bfa   from /usr/share/crystal/src/http/server/handler.cr:26:7 in 'call'
  Aug 11th 09:22:39pm INFO staging 44b5bfa   from /usr/share/crystal/src/http/server/handler.cr:26:7 in 'call'
  Aug 11th 09:22:39pm INFO staging 44b5bfa   from /usr/share/crystal/src/http/server/handler.cr:26:7 in 'call_next'
  Aug 11th 09:22:39pm INFO staging 44b5bfa   from /usr/share/crystal/src/http/server/handler.cr:26:7 in 'call'
  Aug 11th 09:22:39pm INFO staging 44b5bfa   from /usr/share/crystal/src/http/server/handler.cr:26:7 in 'call'
  Aug 11th 09:22:39pm INFO staging 44b5bfa   from /usr/share/crystal/src/http/server/handler.cr:26:7 in 'call'
  Aug 11th 09:22:39pm INFO staging 44b5bfa   from /usr/share/crystal/src/http/server/request_processor.cr:39:11 in 'process'
  Aug 11th 09:22:39pm INFO staging 44b5bfa   from /usr/share/crystal/src/fiber.cr:255:3 in '???'
  Aug 11th 09:22:39pm INFO staging 44b5bfa   from ???
  Aug 11th 09:22:39pm INFO staging 44b5bfa 
  Aug 11th 09:22:39pm INFO staging 44b5bfa 2019-08-12 01:22:39 UTC 500 GET / 75.88ms
  Aug 11th 09:22:39pm INFO staging 44b5bfa E, [2019-08-12 01:22:39 UTC #15] ERROR -- sentry: Not sending event due to previous failure(s)
  Aug 11th 09:22:39pm INFO staging 44b5bfa E, [2019-08-12 01:22:39 UTC #15] ERROR -- sentry: Failed to submit event: Exception: an error
  Aug 11th 09:22:39pm INFO REPORT RequestId: 339d7f0b-3b13-4006-a5c5-3e463f990d41    Duration: 79.13 ms      Billed Duration: 100 ms         Memory Size: 512 MB  Max Memory Used: 104 MB

Code is essentially just this:

require "kemal"
ENV["HOME"] ||= `pwd`
ENV["PORT"] ||= "3000"
require "raven"
require "raven/integrations/kemal"

Raven.configure do |config|
  config.async = true
  config.dsn = "[REDACTED]"
end

add_handler Raven::Kemal::ExceptionHandler.new

get "/" do
  raise "an error"
end

Note: sometimes it explicitly says the SSL error you guys are having above. I'll see if I can get it to do it again.

@sam0x17
Copy link

sam0x17 commented Aug 12, 2019 •
edited
Loading

There, got it -- it's when the lambda first runs. Note that I had to set async to false for it to get this far.

  Aug 11th 09:48:41pm INFO staging 44b5bfa initializing
  Aug 11th 09:48:41pm INFO staging 44b5bfa starting app: PORT=33917 command=./server
  Aug 11th 09:48:41pm INFO staging 44b5bfa started app
  Aug 11th 09:48:41pm INFO staging 44b5bfa waiting for app to listen on PORT
  Aug 11th 09:48:42pm INFO staging 44b5bfa I, [2019-08-12 01:48:42 UTC #15]  INFO -- sentry: Raven 1.5.0 ready to catch errors
  Aug 11th 09:48:43pm INFO staging 44b5bfa app listening: duration=1.32s
  Aug 11th 09:48:43pm INFO staging 44b5bfa initialized: duration=1.36s
  Aug 11th 09:48:43pm INFO staging 44b5bfa [development] Kemal is ready to lead at http://0.0.0.0:33917
  Aug 11th 09:48:43pm INFO staging 44b5bfa I, [2019-08-12 01:48:43 UTC #15]  INFO -- sentry: Sending event 327837c9fa2441e8aa14cc4fdec63f3a to Sentry
  Aug 11th 09:48:43pm INFO staging 44b5bfa E, [2019-08-12 01:48:43 UTC #15] ERROR -- sentry: Unable to record event with remote Sentry server (OpenSSL::SSL::
Error - SSL_connect: error:14090086:SSL routines:ssl3_get_server_certificate:certificate verify failed): /usr/share/crystal/src/openssl/ssl/socket.cr:15:9 in
 'socket'
  Aug 11th 09:48:43pm INFO staging 44b5bfa /usr/share/crystal/src/http/client.cr:643:19 in 'exec_internal_single'
  Aug 11th 09:48:43pm INFO staging 44b5bfa /usr/share/crystal/src/http/client.cr:567:16 in 'send_event'
  Aug 11th 09:48:43pm INFO staging 44b5bfa /src/lib/raven/src/raven/instance.cr:0:5 in 'call'
  Aug 11th 09:48:43pm INFO staging 44b5bfa /usr/share/crystal/src/http/server/handler.cr:26:7 in 'call_next'
  Aug 11th 09:48:43pm INFO staging 44b5bfa /usr/share/crystal/src/http/server/handler.cr:26:7 in 'call'
  Aug 11th 09:48:43pm INFO staging 44b5bfa /usr/share/crystal/src/http/server/handler.cr:26:7 in 'call'
  Aug 11th 09:48:43pm INFO staging 44b5bfa /usr/share/crystal/src/http/server/handler.cr:26:7 in 'call'
  Aug 11th 09:48:43pm INFO staging 44b5bfa /usr/share/crystal/src/http/server/request_processor.cr:39:11 in 'process'
  Aug 11th 09:48:43pm INFO staging 44b5bfa /usr/share/crystal/src/fiber.cr:255:3 in '???'
  Aug 11th 09:48:43pm INFO staging 44b5bfa ???
  Aug 11th 09:48:43pm INFO staging 44b5bfa E, [2019-08-12 01:48:43 UTC #15] ERROR -- sentry: Failed to submit event: Exception: an error
  Aug 11th 09:48:43pm ERRO staging 44b5bfa response: duration=798ms id=4f94224f-bca3-11e9-bcc2-cd51049a152d ip=68.0.236.215 method=GET path=/ size=656 B stat
us=500
  Aug 11th 09:48:43pm INFO REPORT RequestId: 2acc6c00-d7fb-464e-bb9a-8774f3dd028a       Duration: 2437.26 ms    Billed Duration: 2500 ms        Memory Size: 
512 MB  Max Memory Used: 103 MB

@sam0x17 sam0x17 mentioned this issue Aug 12, 2019
Closed
@sam0x17
Copy link

sam0x17 commented Aug 12, 2019 •
edited
Loading

Additional note: it works if I take the s out of https in the link.

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

No branches or pull requests
3 participants
@Sija @anamba @sam0x17