AWS: investigate 2 seconds delay before response is returned

[tripodsan]

could be:

• epsagon tracing
• coralogix flushing

[tripodsan]

it's probably a http request that is not traced. non of the functions in AWS show http traces, when helix-fetch is the
client.

/cc @ranrib

[ranrib]

Hi @tripodsan - is this using http2 or 1? Are you using webpack or any other method to bundle the functions?

[tripodsan]

Hi @tripodsan - is this using http2 or 1?

I think in this case we try to use http/2. but if the server supports it, i don't know

Are you using webpack or any other method to bundle the functions?

yes. we are using webpack. but no obfuscation / minification.

[stefan-guggisberg]

Hi @tripodsan - is this using http2 or 1?

I think in this case we try to use http/2. but if the server supports it, i don't know

The protocol is negotiated via ALPN, i.e. we don't 'try' http/2. The negotiated protocol is most certainly http/2.

[ranrib]

I've tried to re-create the following scenario:

const epsagon = require('epsagon');
const { fetch } = require('@adobe/helix-fetch');
epsagon.init({
  token: 'test',
  appName: 'Helix Test',
  metadataOnly: false,
});
async function test() {
    const resp = await fetch('https://httpbin.org/get');
    console.log(resp.ok);
}
const testFunction = epsagon.nodeWrapper(test);
testFunction()

And it works for me (I've verified that it's indeed HTTP/2). Do you have any idea or insight what is this different than your code?

[stefan-guggisberg]

Hi @ranrib,
I tried your example but I am struggling to find the generated trace in the Epsagon UI. I used helix-fetch Test for appName but don't see that app on Epsagon. Pointers welcome.

[tripodsan]

@stefan-guggisberg when you set process.env.EPSAGON_DEBUG='true'; so you see the trace sent to the epsagon server?

[stefan-guggisberg]

@tripodsan yes

here's the full output (I also enabled helix-fetch debug output):

[EPSAGON] patching module: aws-sdk
[EPSAGON] found module copies: 0
[EPSAGON] done patching module: aws-sdk
[EPSAGON] patching module: aws-sdk
[EPSAGON] found module copies: 0
[EPSAGON] done patching module: aws-sdk
[EPSAGON] patching module: aws-sdk
[EPSAGON] found module copies: 0
[EPSAGON] done patching module: aws-sdk
[EPSAGON] patching module: fetch-h2/dist/lib/context-http1
[EPSAGON] found module copies: 0
[EPSAGON] done patching module: fetch-h2/dist/lib/context-http1
[EPSAGON] patching module: simple-oauth2/lib/client.js
[EPSAGON] found module copies: 0
[EPSAGON] done patching module: simple-oauth2/lib/client.js
[EPSAGON] patching module: simple-oauth2/lib/client/client.js
[EPSAGON] found module copies: 0
[EPSAGON] done patching module: simple-oauth2/lib/client/client.js
[EPSAGON] Patching http2 module
[EPSAGON] patching module: pg
[EPSAGON] found module copies: 0
[EPSAGON] done patching module: pg
[EPSAGON] patching module: pg-pool
[EPSAGON] found module copies: 0
[EPSAGON] done patching module: pg-pool
[EPSAGON] patching module: mysql2
[EPSAGON] found module copies: 0
[EPSAGON] done patching module: mysql2
[EPSAGON] patching module: mysql2
[EPSAGON] found module copies: 0
[EPSAGON] done patching module: mysql2
[EPSAGON] patching module: mysql/lib/Connection.js
[EPSAGON] found module copies: 0
[EPSAGON] done patching module: mysql/lib/Connection.js
[EPSAGON] patching module: redis
[EPSAGON] found module copies: 0
[EPSAGON] done patching module: redis
[EPSAGON] patching module: ioredis
[EPSAGON] found module copies: 0
[EPSAGON] done patching module: ioredis
[EPSAGON] patching module: dy-ioredis/lib/redis.js
[EPSAGON] found module copies: 0
[EPSAGON] done patching module: dy-ioredis/lib/redis.js
[EPSAGON] patching module: mongodb/lib/core/wireprotocol/index.js
[EPSAGON] found module copies: 0
[EPSAGON] done patching module: mongodb/lib/core/wireprotocol/index.js
[EPSAGON] patching module: mongodb/lib/core/wireprotocol/index.js
[EPSAGON] found module copies: 0
[EPSAGON] done patching module: mongodb/lib/core/wireprotocol/index.js
[EPSAGON] patching module: mongodb/lib/core/wireprotocol/index.js
[EPSAGON] found module copies: 0
[EPSAGON] done patching module: mongodb/lib/core/wireprotocol/index.js
[EPSAGON] patching module: mongodb/lib/core/wireprotocol/index.js
[EPSAGON] found module copies: 0
[EPSAGON] done patching module: mongodb/lib/core/wireprotocol/index.js
[EPSAGON] patching module: mongodb/lib/core/wireprotocol/index.js
[EPSAGON] found module copies: 0
[EPSAGON] done patching module: mongodb/lib/core/wireprotocol/index.js
[EPSAGON] patching module: mongodb/lib/core/wireprotocol/index.js
[EPSAGON] found module copies: 0
[EPSAGON] done patching module: mongodb/lib/core/wireprotocol/index.js
[EPSAGON] patching module: amazon-dax-client
[EPSAGON] found module copies: 0
[EPSAGON] done patching module: amazon-dax-client
[EPSAGON] patching module: amazon-dax-client
[EPSAGON] found module copies: 0
[EPSAGON] done patching module: amazon-dax-client
[EPSAGON] patching module: openwhisk/lib/actions.js
[EPSAGON] found module copies: 0
[EPSAGON] done patching module: openwhisk/lib/actions.js
[EPSAGON] patching module: @google-cloud/common/
[EPSAGON] found module copies: 0
[EPSAGON] done patching module: @google-cloud/common/
[EPSAGON] patching module: @google-cloud/pubsub/
[EPSAGON] found module copies: 0
[EPSAGON] done patching module: @google-cloud/pubsub/
[EPSAGON] patching module: @google-cloud/pubsub/
[EPSAGON] found module copies: 0
[EPSAGON] done patching module: @google-cloud/pubsub/
[EPSAGON] patching module: nats
[EPSAGON] found module copies: 0
[EPSAGON] done patching module: nats
[EPSAGON] patching module: mqtt
[EPSAGON] found module copies: 0
[EPSAGON] done patching module: mqtt
[EPSAGON] patching module: kafkajs
[EPSAGON] found module copies: 0
[EPSAGON] done patching module: kafkajs
[EPSAGON] patching module: kafkajs/src/cluster/index.js
[EPSAGON] found module copies: 0
[EPSAGON] done patching module: kafkajs/src/cluster/index.js
[EPSAGON] patching module: kafka-node
[EPSAGON] found module copies: 0
[EPSAGON] done patching module: kafka-node
[EPSAGON] patching module: bunyan
[EPSAGON] found module copies: 0
[EPSAGON] done patching module: bunyan
[EPSAGON] patching module: pino/lib/tools
[EPSAGON] found module copies: 0
[EPSAGON] done patching module: pino/lib/tools
[EPSAGON] patching module: @azure/storage-blob
[EPSAGON] found module copies: 0
[EPSAGON] done patching module: @azure/storage-blob
[EPSAGON] patching module: @azure/storage-blob
[EPSAGON] found module copies: 0
[EPSAGON] done patching module: @azure/storage-blob
[EPSAGON] patching module: @azure/cosmos
[EPSAGON] found module copies: 0
[EPSAGON] done patching module: @azure/cosmos
[EPSAGON] hooking winston-cloudwatch
[EPSAGON] hooked winston-cloudwatch
[EPSAGON] patching module: winston/lib/winston/logger
[EPSAGON] found module copies: 0
[EPSAGON] done patching module: winston/lib/winston/logger
[EPSAGON] patching module: amqplib/lib/channel.js
[EPSAGON] found module copies: 0
[EPSAGON] done patching module: amqplib/lib/channel.js
[EPSAGON] patching module: amqp/lib/exchange.js
[EPSAGON] found module copies: 0
[EPSAGON] done patching module: amqp/lib/exchange.js
[EPSAGON] patching module: ldapjs
[EPSAGON] found module copies: 0
[EPSAGON] done patching module: ldapjs
[EPSAGON] patching module: cassandra-driver/lib/client
[EPSAGON] found module copies: 0
[EPSAGON] done patching module: cassandra-driver/lib/client
[EPSAGON] loading azure metadata, url: (http://169.254.169.254/metadata/instance?api-version=2019-06-01)
[EPSAGON] Loading EC2 metadata
[EPSAGON] [http] captured call 169.254.169.254
[EPSAGON] [http] filtered ignored hostname 169.254.169.254
[EPSAGON] [http] captured call 169.254.169.254
[EPSAGON] [http] filtered ignored hostname 169.254.169.254
[EPSAGON] [http] captured call 169.254.169.254
[EPSAGON] [http] filtered ignored hostname 169.254.169.254
[EPSAGON] [http] captured call 169.254.169.254
[EPSAGON] [http] filtered ignored hostname 169.254.169.254
[EPSAGON] [http] captured call 169.254.169.254
[EPSAGON] [http] filtered ignored hostname 169.254.169.254
[EPSAGON] [http] captured call 169.254.169.254
[EPSAGON] [http] filtered ignored hostname 169.254.169.254
  helix-fetch:core established TLS connection: #1 (httpbin.org) +0ms
  helix-fetch:core httpbin.org -> h2 +1ms
  helix-fetch:h2 reusing socket #1 (httpbin.org) +0ms
  helix-fetch:h2 GET httpbin.org/get +2ms
  helix-fetch:h2 session https://httpbin.org established +2ms
  helix-fetch:h2 caching session https://httpbin.org +0ms
  helix-fetch:h2 session https://httpbin.org remoteSettings: {"headerTableSize":4096,"enablePush":true,"initialWindowSize":65536,"maxFrameSize":16777215,"maxConcurrentStreams":128,"maxHeaderListSize":4294967295,"maxHeaderSize":4294967295,"enableConnectProtocol":false} +1ms
  helix-fetch:h2 session https://httpbin.org localSettings: {"headerTableSize":4096,"enablePush":true,"initialWindowSize":65535,"maxFrameSize":16384,"maxConcurrentStreams":4294967295,"maxHeaderListSize":4294967295,"maxHeaderSize":4294967295,"enableConnectProtocol":false} +107ms
true
[EPSAGON] Sending trace async...
  helix-fetch:core resetting context +0ms
  helix-fetch:h2 resetContext: destroying session (socket #1, httpbin.org) +10ms
[EPSAGON] [QUEUE] Trace size 1606 Bytes pushed to queue
[EPSAGON] [QUEUE] Queue size: 1 traces, total size of 1606 Bytes
  helix-fetch:h2 session https://httpbin.org closed +4ms
  helix-fetch:h2 discarding cached session https://httpbin.org +0ms
[EPSAGON] Could not load azure metadata
[EPSAGON] Could not load EC2 metadata for instance-id
[EPSAGON] Could not load EC2 metadata for instance-type
[EPSAGON] Could not load EC2 metadata for local-ipv4
[EPSAGON] Could not load EC2 metadata for public-hostname
[EPSAGON] Could not load EC2 metadata for public-ipv4

[stefan-guggisberg]

The above output was generated by running this code with DEBUG=helix-fetch*:

require('dotenv').config();

const epsagon = require('epsagon');
const { fetch, reset } = require('@adobe/helix-fetch');

const { EPSAGON_TOKEN } = process.env;

epsagon.init({
  token: EPSAGON_TOKEN,
  appName: 'helix-fetch Test',
  metadataOnly: false,
});
async function test() {
    const resp = await fetch('https://httpbin.org/get');
    console.log(resp.ok);
}
const testFunction = epsagon.nodeWrapper(test);

testFunction()
  .catch(console.error)
  .finally(reset);

[stefan-guggisberg]

Hi @ranrib, care to comment?

[ranrib]

Hi @stefan-guggisberg ! Sorry for the late reply. Please add as an init parameter the following:
sendBatch: false

You should be able to see the trace afterwards

[stefan-guggisberg]

Thanks @ranrib, that worked. I can see the traces now in epsagon. It would be nice if the http protocol version would be visible in the trace.

Now that we've confirmed that traces of http/2 requests generally work we still have to figure out why not a single http/2 request (there are tons!) is captured in our production env (aws lambda)...

[tripodsan]

sendBatch: false

should update our epsagon instrumentation to always disable batches?

[ranrib]

@tripodsan yes - since you're running on ephemeral envs, batching is less relevant. so please set it for all.

[tripodsan]

@tripodsan yes - since you're running on ephemeral envs, batching is less relevant. so please set it for all.

I just check and we already set it.