RequestError: Timeout awaiting 'request' for 15000ms

[skapytek]

[2023-02-09 10:20:06] [DEBUG] [696] [general] disconnected from API: (io server disconnect)
[2023-02-09 10:20:07] [DEBUG] [696] [general] connection to API established
[2023-02-09 10:20:07] [INFO] [696] [api:connect] connected from (Laakirchen, AT, EU) (lat: 47.9819 long: 13.8217)
[2023-02-09 15:04:56] [DEBUG] [696] [general] ping request WdBAAleo3sHN3MWR received
[2023-02-09 15:11:34] [DEBUG] [696] [general] ping request OlRqojedCVZg2kG8 received
[2023-02-10 02:54:29] [DEBUG] [696] [general] ping request 44WdTqOfWwljAL6l received
node:internal/process/promises:288
triggerUncaughtException(err, true /* fromPromise */);
^

RequestError: Timeout awaiting 'request' for 15000ms
at ClientRequest. (file:///app/node_modules/got/dist/source/core/index.js:760:61)
at Object.onceWrapper (node:events:628:26)
at ClientRequest.emit (node:events:525:35)
at TLSSocket.socketErrorListener (node:_http_client:496:9)
at TLSSocket.emit (node:events:513:28)
at emitErrorNT (node:internal/streams/destroy:151:8)
at emitErrorCloseNT (node:internal/streams/destroy:116:3)
at process.processTicksAndRejections (node:internal/process/task_queues:82:21)
at Timeout.timeoutHandler [as _onTimeout] (file:///app/node_modules/got/dist/source/core/timed-out.js:42:25)
at listOnTimeout (node:internal/timers:566:11)
at process.processTimers (node:internal/timers:507:7) {
input: undefined,
code: 'ETIMEDOUT',
timings: {
start: 1676019711941,
socket: 1676019711943,
lookup: undefined,
connect: undefined,
secureConnect: undefined,
upload: undefined,
response: undefined,
end: undefined,
error: 1676019726944,
abort: undefined,
phases: {
wait: 2,
dns: undefined,
tcp: undefined,
tls: undefined,
request: undefined,
firstByte: undefined,
download: undefined,
total: 15003
}
},
name: 'TimeoutError',
options: Options {
_unixOptions: undefined,
_internals: {
request: undefined,
agent: { http: undefined, https: undefined, http2: undefined },
h2session: undefined,
decompress: true,
timeout: {
connect: undefined,
lookup: undefined,
read: undefined,
request: 15000,
response: undefined,
secureConnect: undefined,
send: undefined,
socket: undefined
},
prefixUrl: '',
body: undefined,
form: undefined,
json: undefined,
cookieJar: undefined,
ignoreInvalidCookies: false,
searchParams: undefined,
dnsLookup: undefined,
dnsCache: undefined,
context: {},
hooks: {
init: [],
beforeRequest: [],
beforeError: [],
beforeRedirect: [],
beforeRetry: [],
afterResponse: []
},
followRedirect: true,
maxRedirects: 10,
cache: undefined,
throwHttpErrors: true,
username: '',
password: '',
http2: false,
allowGetBody: false,
headers: {
'user-agent': 'got (https://github.com/sindresorhus/got)',
accept: 'application/json',
'accept-encoding': 'gzip, deflate, br'
},
methodRewriting: false,
dnsLookupIpVersion: undefined,
parseJson: [Function: parse],
stringifyJson: [Function: stringify],
retry: {
limit: 2,
methods: [ 'GET', 'PUT', 'HEAD', 'DELETE', 'OPTIONS', 'TRACE' ],
statusCodes: [
408, 413, 429, 500,
502, 503, 504, 521,
522, 524
],
errorCodes: [
'ETIMEDOUT',
'ECONNRESET',
'EADDRINUSE',
'ECONNREFUSED',
'EPIPE',
'ENOTFOUND',
'ENETUNREACH',
'EAI_AGAIN'
],
maxRetryAfter: undefined,
calculateDelay: [Function: calculateDelay],
backoffLimit: Infinity,
noise: 100
},
localAddress: undefined,
method: 'GET',
createConnection: undefined,
cacheOptions: {
shared: undefined,
cacheHeuristic: undefined,
immutableMinTimeToLive: undefined,
ignoreCargoCult: undefined
},
https: {
alpnProtocols: undefined,
rejectUnauthorized: undefined,
checkServerIdentity: undefined,
certificateAuthority: undefined,
key: undefined,
certificate: undefined,
passphrase: undefined,
pfx: undefined,
ciphers: undefined,
honorCipherOrder: undefined,
minVersion: undefined,
maxVersion: undefined,
signatureAlgorithms: undefined,
tlsSessionLifetime: undefined,
dhparam: undefined,
ecdhCurve: undefined,
certificateRevocationLists: undefined
},
encoding: undefined,
resolveBodyOnly: false,
isStream: false,
responseType: 'text',
url: <ref *1> URL {
[Symbol(context)]: URLContext {
flags: 400,
scheme: 'https:',
username: '',
password: '',
host: 'api.github.com',
port: null,
path: [
'repos',
'jsdelivr',
'globalping-probe',
'releases',
'latest'
],
query: null,
fragment: null
},
[Symbol(query)]: URLSearchParams {
[Symbol(query)]: [],
[Symbol(context)]: [Circular *1]
}
},
pagination: {
transform: [Function: transform],
paginate: [Function: paginate],
filter: [Function: filter],
shouldContinue: [Function: shouldContinue],
countLimit: Infinity,
backoff: 0,
requestLimit: 10000,
stackAllItems: false
},
setHost: true,
maxHeaderSize: undefined
},
_merging: false,
_init: [ { timeout: { request: 15000 } } ]
},
event: 'request'
}

Node.js v18.13.0
Updating certificates in /etc/ssl/certs...
0 added, 0 removed; done.
Running hooks in /etc/ca-certificates/update.d...
done.
Checking for the latest version
Current version 0.12.0
Latest version
[2023-02-10 09:02:55] [INFO] [687] [general] Start probe version 0.12.0 in a production mode
[2023-02-10 09:03:02] [DEBUG] [687] [general] connection to API established
[2023-02-10 09:03:02] [INFO] [687] [api:connect] connected from (Laakirchen, AT, EU) (lat: 47.9819 long: 13.8217)

[jimaek]

@alexey-yarmosh Looks like the same issue I had reported here jsdelivr/globalping-probe#102

Seems like it continues to happen, need to look into it deeper.

[alexey-yarmosh]

Seems like the origin is the checker of new releases:
https://github.com/jsdelivr/globalping-probe/blob/master/src/lib/updater.ts#L17

Most likely github server was down or busy, and in 15 sec error was thrown.
Anyway we need to update the code to gracefully handle that and get our source files in the stacktrace.

[skapytek]

Anything i need/can do?

[alexey-yarmosh]

Not currently, your probe reconnected and proceeded to work as usual. We just need to handle and log such errors more elegant. All the updates will be noted here in the issue.

I'll get back here if more info is required. And thanks for the feedback!

[alexey-yarmosh]

So our current logic seems to be ok. got logs can be enhanced to provide the direct line of error from our sources. But since got is used only in the updater.ts (http-command.ts is not counted) it is not very needed. Data from the log are enough.

Also, we can see that the probe restarted in that specific case, we can update the logic to ignore timeout errors. Or stay as is to "restart probe on every problem".

What is really important is to collect the logs ourselves, to have a mechanism of analyzing errors not from user reports (which are highly appreciated) but from our data. I believe we need to set up a winston-socket.io transport on the probes and send at least error logs, using probe -> API -> newrelic scheme, also we can think about connecting probes directly to newrelic, but I am not sure in that option.

cc @jimaek @MartinKolarik

[MartinKolarik]

Certainly ignore the timeouts. Will comment on the rest later.

[jimaek]

Yeah, lets just ignore the timeouts. And dont restart the probe, otherwise every time Github goes down we will also be super unstable. Also I dont want to collect any logs from users, at least not now.

[alexey-yarmosh]

Also I dont want to collect any logs from users, at least not now.

That is something required to deal with issues like #212 . So postponing will make them even harder to debug.

[jimaek]

I dont want to allow anonymous users to write to our API. Too easy to abuse. Most of the probes are docker containers, getting access and spamming the endpoint would be trivial.

We also have a pretty big network of our own probes, I can provide any logs necessary from them.

[alexey-yarmosh]

Logs question moved here - #289
Timeout bug fixed here - jsdelivr/globalping-probe#113