search

lbryio / lbry.com

lbry.com, the website for the LBRY protocol
https://lbry.com
MIT License
263 stars 234 forks source link

Address/suppress timeout logs in slack #1023

Closed tzarebczan closed 3 years ago

tzarebczan commented 5 years ago

The Slack channel for web errors gets flooded with timeouts like the below. Can we suppress these so they don't pollute the channel?

Eexception 'CurlException' with message 'Operation timed out after 5001 milliseconds with 0 bytes received' in /home/lbry/lbryio/lib/tools/Curl.class.php:147

NetOpWibby commented 5 years ago

I'd love this. No idea how to do it though.

voidfire commented 5 years ago

I believe a) I can either suppress specifically the timeout exceptions going over to slack. Or b) I can increase the default timeout limit on curl requests function (which is currently 5 seconds). I still don't have a clear idea of the whole codebase so I wouldn't know how increasing the timeout on Curl requests may affect the different moving parts of the codebase.

tzarebczan commented 5 years ago

hey @voidfire thanks for taking a peek at this. The below are some of the errors we are seeing and on what pages. @tiger5226 - it happens on https://api.lbry.io/visitor/new which I think was really slow at some point. Maybe increasing the timeout would help. 


incoming-webhook APP [8:02 AM]
@channel /verify
exception 'CurlException' with message 'Operation timed out after 5001 milliseconds with 0 bytes received' in /home/lbry/lbryio/lib/tools/Curl.class.php:147
#0 /home/lbry/lbryio/lib/tools/Curl.class.php(20): Curl::doCurl('POST', 'https://api.lbry.io/visitor/new', Array(3), Array(11))
#1 /home/lbry/lbryio/lib/thirdparty/LBRY.class.php(106): Curl::post('https://api.lbry.io/visitor/new', Array(3), Array(1))
#2 /home/lbry/lbryio/controller/Session.class.php(39): LBRY::logWebVisitor('lbry.com', '1195007899.1558698899', '177.52.51.91')
#3 /home/lbry/lbryio/view/Response.class.php(382): Session::{closure}()
#4 /home/lbry/lbryio/web/index.php(33): Response::invokePostRenderCallbacks()

:japanese_goblin:
incoming-webhook APP [9:26 AM]
@channel /ios
exception 'CurlException' with message 'Operation timed out after 5001 milliseconds with 0 bytes received' in /home/lbry/lbryio/lib/tools/Curl.class.php:147
#0 /home/lbry/lbryio/lib/tools/Curl.class.php(20): Curl::doCurl('POST', 'https://api.lbry.io/visitor/new', Array(3), Array(11))
#1 /home/lbry/lbryio/lib/thirdparty/LBRY.class.php(106): Curl::post('https://api.lbry.io/visitor/new', Array(3), Array(1))
#2 /home/lbry/lbryio/controller/Session.class.php(39): LBRY::logWebVisitor('lbry.com', '1902618674.1558704343', '185.93.1.96')
#3 /home/lbry/lbryio/view/Response.class.php(382): Session::{closure}()
#4 /home/lbry/lbryio/web/index.php(33): Response::invokePostRenderCallbacks()
@channel /verify
exception 'CurlException' with message 'Operation timed out after 5001 milliseconds with 0 bytes received' in /home/lbry/lbryio/lib/tools/Curl.class.php:147
#0 /home/lbry/lbryio/lib/tools/Curl.class.php(20): Curl::doCurl('POST', 'https://api.lbry.io/visitor/new', Array(3), Array(11))
#1 /home/lbry/lbryio/lib/thirdparty/LBRY.class.php(106): Curl::post('https://api.lbry.io/visitor/new', Array(3), Array(1))
#2 /home/lbry/lbryio/controller/Session.class.php(39): LBRY::logWebVisitor('lbry.com', '301051057.1553015150', '24.184.108.248')
#3 /home/lbry/lbryio/view/Response.class.php(382): Session::{closure}()
#4 /home/lbry/lbryio/web/index.php(33): Response::invokePostRenderCallbacks()
:japanese_goblin:
incoming-webhook APP [11:28 AM]
@channel /faq/host-content
exception 'CurlException' with message 'Operation timed out after 5001 milliseconds with 0 bytes received' in /home/lbry/lbryio/lib/tools/Curl.class.php:147
#0 /home/lbry/lbryio/lib/tools/Curl.class.php(20): Curl::doCurl('POST', 'https://api.lbry.io/visitor/new', Array(3), Array(11))
#1 /home/lbry/lbryio/lib/thirdparty/LBRY.class.php(106): Curl::post('https://api.lbry.io/visitor/new', Array(3), Array(1))
#2 /home/lbry/lbryio/controller/Session.class.php(39): LBRY::logWebVisitor('lbry.com', '2110537829.1558705531', '74.109.242.140')
#3 /home/lbry/lbryio/view/Response.class.php(382): Session::{closure}()
#4 /home/lbry/lbryio/web/index.php(33): Response::invokePostRenderCallbacks()
:japanese_goblin:
incoming-webhook APP [12:48 PM]
@channel /verify
exception 'CurlException' with message 'Operation timed out after 5000 milliseconds with 0 bytes received' in /home/lbry/lbryio/lib/tools/Curl.class.php:147
#0 /home/lbry/lbryio/lib/tools/Curl.class.php(20): Curl::doCurl('POST', 'https://api.lbry.io/visitor/new', Array(3), Array(11))
#1 /home/lbry/lbryio/lib/thirdparty/LBRY.class.php(106): Curl::post('https://api.lbry.io/visitor/new', Array(3), Array(1))
#2 /home/lbry/lbryio/controller/Session.class.php(39): LBRY::logWebVisitor('lbry.com', '1771412842.1558714741', '94.61.213.152')
#3 /home/lbry/lbryio/view/Response.class.php(382): Session::{closure}()
#4 /home/lbry/lbryio/web/index.php(33): Response::invokePostRenderCallbacks()
:japanese_goblin:
incoming-webhook APP [1:55 PM]
@channel /list/subscribe
exception 'CurlException' with message 'Operation timed out after 5000 milliseconds with 0 bytes received' in /home/lbry/lbryio/lib/tools/Curl.class.php:147
#0 /home/lbry/lbryio/lib/tools/Curl.class.php(20): Curl::doCurl('POST', 'https://api.lbry.io/visitor/new', Array(3), Array(11))
#1 /home/lbry/lbryio/lib/thirdparty/LBRY.class.php(106): Curl::post('https://api.lbry.io/visitor/new', Array(3), Array(1))
#2 /home/lbry/lbryio/controller/Session.class.php(39): LBRY::logWebVisitor('lbry.com', '594767446.1558719405', '196.137.12.153')
#3 /home/lbry/lbryio/view/Response.class.php(382): Session::{closure}()
#4 /home/lbry/lbryio/web/index.php(33): Response::invokePostRenderCallbacks()```
tiger5226 commented 5 years ago

This call happens multiple times per second. What I think is happening is there is some waiting happening periodically. Most of the time the call only takes 100ms max. There exists a circumstance where it goes beyond the 5 second timeout though. The last time it happened was 1:55pm yesterday. I believe this is caused by some random delay on the internal-apis database. I bet it happens whenever we deploy a release. I deployed a release for our internal apis which deployed around 3:36pm and it happened again at 4:39pm 

incoming-webhook APP [4:39 PM]
@channel /news/comm-update
exception 'CurlException' with message 'Operation timed out after 5001 milliseconds with 0 bytes received' in /home/lbry/lbryio/lib/tools/Curl.class.php:147
#0 /home/lbry/lbryio/lib/tools/Curl.class.php(20): Curl::doCurl('POST', 'https://api.lbry.io/visitor/new', Array(3), Array(11))
#1 /home/lbry/lbryio/lib/thirdparty/LBRY.class.php(106): Curl::post('https://api.lbry.io/visitor/new', Array(3), Array(1))
#2 /home/lbry/lbryio/controller/Session.class.php(39): LBRY::logWebVisitor('lbry.com', '1599353669.1558577350', '177.191.104.210')
#3 /home/lbry/lbryio/view/Response.class.php(382): Session::{closure}()
#4 /home/lbry/lbryio/web/index.php(33): Response::invokePostRenderCallbacks()

@channel /verify
exception 'CurlException' with message 'Operation timed out after 5001 milliseconds with 0 bytes received' in /home/lbry/lbryio/lib/tools/Curl.class.php:147
#0 /home/lbry/lbryio/lib/tools/Curl.class.php(20): Curl::doCurl('POST', 'https://api.lbry.io/visitor/new', Array(3), Array(11))
#1 /home/lbry/lbryio/lib/thirdparty/LBRY.class.php(106): Curl::post('https://api.lbry.io/visitor/new', Array(3), Array(1))
#2 /home/lbry/lbryio/controller/Session.class.php(39): LBRY::logWebVisitor('lbry.com', '450812502.1558816472', '104.238.59.153')
#3 /home/lbry/lbryio/view/Response.class.php(382): Session::{closure}()
#4 /home/lbry/lbryio/web/index.php(33): Response::invokePostRenderCallbacks()