appmetrics icon indicating copy to clipboard operation
appmetrics copied to clipboard

Published 20 hours ago • verified publisher icon RuntimeTools

'http' event is triggered twice for one request

Open yuecchen opened this issue 7 years ago • 7 comments

version: [email protected]

write the code in an application:

var appmetrics = require('appmetrics');
var health = appmetrics.monitor();
health.on('http',function(http){console.info('http');});

when I trigger one request, two 'http' are printed.

yuecchen avatar Jul 11 '18 08:07 yuecchen

have you looked to see what other information is in the http object ? Are they identical objects for each request ?

tobespc avatar Jul 25 '18 08:07 tobespc

It seems they are exactly same:

{ time: 1532577638457,
  method: 'GET',
  url: '/api/pets',
  duration: 54.228775,
  header: 'HTTP/1.1 304 Not Modified\r\nVary: Origin\r\nAccess-Control-Allow-Credentials: true\r\nX-XSS-Protection: 1; mode=block\r\nX-Frame-Options: DENY\r\nX-Download-Options: noopen\r\nX-Content-Type-Options: nosniff\r\nETag: W/"82-Rwd7IXe6ytzCSKsdxTVmiU9Hmhw"\r\nDate: Thu, 26 Jul 2018 04:00:38 GMT\r\nConnection: keep-alive\r\n\r\n',
  statusCode: 304,
  contentType: undefined,
  requestHeader:
   { host: 'joycevm.rtp.raleigh.ibm.com:3000',
     'user-agent': 'Mozilla/5.0 (Windows NT 6.1; WOW64; rv:52.0) Gecko/20100101 Firefox/52.0',
     accept: '*/*',
     'accept-language': 'en-US,en;q=0.94,zh-CN;q=0.88,de;q=0.81,th;q=0.75,es;q=0.69,ru;q=0.63,pl;q=0.56,hu;q=0.5,cs;q=0.44,it;q=0.38,ko;q=0.31,fr;q=0.25,ja;q=0.19,pt-BR;q=0.13,zh;q=0.06',
     'accept-encoding': 'gzip, deflate',
     cookie: 'CoreID6=34937740567015278173609&ci=51040000|_50200000|ECOM_52640000|ECOM_50200000|GLOBAL_50200000|MYIBM_50200000|ESTKCS_50200000|devwrkscon_50200000|IBM_GlobalMarketing_50200000|ESTSPN_50200000|ESTFIX_51040000|PP_51040000|HR_51040000|IBMTESTW3_50200000|DEVWRKS_50200000|www_50200000|IBMTESTWWW_50200000|E021_50200000|Bluemix_52640000|Bluemix_51040000|HAIPRD; OPTOUTMULTI=0:0%7Cc1:1%7Cc2:0%7Cc3:0; utag_main=v_id:0163b922f55a0016c16b0f34eecf26048002500d00845$_sn:35$_ss:0$_st:1532484648866$is_country_member_of_eu:false$dc_visit:30$ses_id:1532482793210%3Bexp-session$_pn:2%3Bexp-session$mm_sync:1%3Bexp-session$dc_event:2%3Bexp-session$dc_region:ap-northeast-1%3Bexp-session; CoreM_State=25~-1~-1~-1~-1~3~3~5~3~3~7~7~|~8CD0CB6F~|~~|~~|~0||||||~|~1527819759698~|~~|~~|~~|~~|~~|~~|~; CoreM_State_Content=6~|~F1EC2BADFFCB267B~DD182845A36373E8~ACD0010B6BABB48C~35D284AD3E918183~64EF7EE3468C2798~64C4C0297FC34ED6~|~0~1~2~3~4~5; optimizelyEndUserId=oeu1527819467970r0.5207737436187673; BMAID=489aa1dc-2647-4acf-ab7d-dad19b89c1cc; cvo_sid1=MFPNUV89DBNX; cvo_tid1=BoCi47_wCuM|1527819457|1530496290|-9; ajs_user_id=null; ajs_group_id=null; ajs_anonymous_id=%22489aa1dc-2647-4acf-ab7d-dad19b89c1cc%22; intercom-id-ydoy8e4i=1eac358d-dd2c-4d25-9b33-c390e2131fb8; LPVID=FkYjUyNzIzM2Q2YjVkZjdk; FC_ASE_PERSIST=rNqMNP3wqZEedOEUy+3bWA==; IBM_W3SSO_ACCESS=; _ga=GA1.2.1253921230.1528266629; UnicaNIODID=ieyspGN4ORT-a4slVAq; __auc=3f3ea57116439b66e3240fd0a5b; ccf-medallia-web-exp=%7B%22date%22%3A%201530510744362%2C%22type%22%3A%20%22medallia%22%2C%22id%22%3A%20%22web-exp%22%7D; issiGeoIDSelected=na; issiGeoNameSelected=North%20America; issiCarouselLastDate=2018-07-05; issiCarouselView=open; 51040000_clogin=l=40278411532052266054&v=1&e=1532054077810; JSESSIONID_IC_BMIX_N=0000RiwYnO6ohGKn6VLWb0aSS5q:ICWikis104:ICCommunities105:ICBlogs101:ICForum105:ICFiles103; idaasRedirectUrl=https://idaas.iam.ibm.com/idaas/oidc/endpoint/default/authorize?client_id=ZTdhOWU4MmQtOTA1MC00&scope=openid&state=f4b74017-36f6-46da-af55-eb100d5f7c9e&nonce=5fe51e2e-d0ea-4cb1-b3fb-e73405034774&response_type=code&redirect_uri=https%3A//iam-id-1.au-syd.bluemix.net/oidc/callback/IBMid; TLTSID=LFE7RZU8ARQ342IROEJE1219Z27L5GUP; MYSAPSSO2=AjExMDAgABBwb3J0YWw6OTE5NDI2NjcyiAATYmFzaWNhdXRoZW50aWNhdGlvbgEACTkxOTQyNjY3MgIAAzAwMAMAA1RQQQQADDIwMTgwNjI5MDIwNAUABAAAABAKAAk5MTk0MjY2NzL%2FAQUwggEBBgkqhkiG9w0BBwKggfMwgfACAQExCzAJBgUrDgMCGgUAMAsGCSqGSIb3DQEHATGB0DCBzQIBATAiMB0xDDAKBgNVBAMTA1RQQTENMAsGA1UECxMESjJFRQIBADAJBgUrDgMCGgUAoF0wGAYJKoZIhvcNAQkDMQsGCSqGSIb3DQEHATAcBgkqhkiG9w0BCQUxDxcNMTgwNjI5MDIwNDI3WjAjBgkqhkiG9w0BCQQxFgQUlIOsrxcVN3RzLCOCgiuqu9Bs7BwwCQYHKoZIzjgEAwQvMC0CFHKemKwYmDWUvya8vDIqiYCXWWQYAhUApiWJRqB4WjXAuiCapYQC0ZIOk2Q%3D; SAPWP_active=1; 50200000_clogin=l=63207871532482814576&v=1&e=1532484649086; 52640000_clogin=v=1&l=14711221530243621402&e=1530245442810; ibmSurvey=1530580488942; prevProdID=IBM_PWB_681391021185; notice_behavior=implied|eu',
     connection: 'keep-alive',
     'if-none-match': 'W/"82-Rwd7IXe6ytzCSKsdxTVmiU9Hmhw"' } }
{ time: 1532577638457,
  method: 'GET',
  url: '/api/pets',
  duration: 54.228775,
  header: 'HTTP/1.1 304 Not Modified\r\nVary: Origin\r\nAccess-Control-Allow-Credentials: true\r\nX-XSS-Protection: 1; mode=block\r\nX-Frame-Options: DENY\r\nX-Download-Options: noopen\r\nX-Content-Type-Options: nosniff\r\nETag: W/"82-Rwd7IXe6ytzCSKsdxTVmiU9Hmhw"\r\nDate: Thu, 26 Jul 2018 04:00:38 GMT\r\nConnection: keep-alive\r\n\r\n',
  statusCode: 304,
  contentType: undefined,
  requestHeader:
   { host: 'joycevm.rtp.raleigh.ibm.com:3000',
     'user-agent': 'Mozilla/5.0 (Windows NT 6.1; WOW64; rv:52.0) Gecko/20100101 Firefox/52.0',
     accept: '*/*',
     'accept-language': 'en-US,en;q=0.94,zh-CN;q=0.88,de;q=0.81,th;q=0.75,es;q=0.69,ru;q=0.63,pl;q=0.56,hu;q=0.5,cs;q=0.44,it;q=0.38,ko;q=0.31,fr;q=0.25,ja;q=0.19,pt-BR;q=0.13,zh;q=0.06',
     'accept-encoding': 'gzip, deflate',
     cookie: 'CoreID6=34937740567015278173609&ci=51040000|_50200000|ECOM_52640000|ECOM_50200000|GLOBAL_50200000|MYIBM_50200000|ESTKCS_50200000|devwrkscon_50200000|IBM_GlobalMarketing_50200000|ESTSPN_50200000|ESTFIX_51040000|PP_51040000|HR_51040000|IBMTESTW3_50200000|DEVWRKS_50200000|www_50200000|IBMTESTWWW_50200000|E021_50200000|Bluemix_52640000|Bluemix_51040000|HAIPRD; OPTOUTMULTI=0:0%7Cc1:1%7Cc2:0%7Cc3:0; utag_main=v_id:0163b922f55a0016c16b0f34eecf26048002500d00845$_sn:35$_ss:0$_st:1532484648866$is_country_member_of_eu:false$dc_visit:30$ses_id:1532482793210%3Bexp-session$_pn:2%3Bexp-session$mm_sync:1%3Bexp-session$dc_event:2%3Bexp-session$dc_region:ap-northeast-1%3Bexp-session; CoreM_State=25~-1~-1~-1~-1~3~3~5~3~3~7~7~|~8CD0CB6F~|~~|~~|~0||||||~|~1527819759698~|~~|~~|~~|~~|~~|~~|~; CoreM_State_Content=6~|~F1EC2BADFFCB267B~DD182845A36373E8~ACD0010B6BABB48C~35D284AD3E918183~64EF7EE3468C2798~64C4C0297FC34ED6~|~0~1~2~3~4~5; optimizelyEndUserId=oeu1527819467970r0.5207737436187673; BMAID=489aa1dc-2647-4acf-ab7d-dad19b89c1cc; cvo_sid1=MFPNUV89DBNX; cvo_tid1=BoCi47_wCuM|1527819457|1530496290|-9; ajs_user_id=null; ajs_group_id=null; ajs_anonymous_id=%22489aa1dc-2647-4acf-ab7d-dad19b89c1cc%22; intercom-id-ydoy8e4i=1eac358d-dd2c-4d25-9b33-c390e2131fb8; LPVID=FkYjUyNzIzM2Q2YjVkZjdk; FC_ASE_PERSIST=rNqMNP3wqZEedOEUy+3bWA==; IBM_W3SSO_ACCESS=; _ga=GA1.2.1253921230.1528266629; UnicaNIODID=ieyspGN4ORT-a4slVAq; __auc=3f3ea57116439b66e3240fd0a5b; ccf-medallia-web-exp=%7B%22date%22%3A%201530510744362%2C%22type%22%3A%20%22medallia%22%2C%22id%22%3A%20%22web-exp%22%7D; issiGeoIDSelected=na; issiGeoNameSelected=North%20America; issiCarouselLastDate=2018-07-05; issiCarouselView=open; 51040000_clogin=l=40278411532052266054&v=1&e=1532054077810; JSESSIONID_IC_BMIX_N=0000RiwYnO6ohGKn6VLWb0aSS5q:ICWikis104:ICCommunities105:ICBlogs101:ICForum105:ICFiles103; idaasRedirectUrl=https://idaas.iam.ibm.com/idaas/oidc/endpoint/default/authorize?client_id=ZTdhOWU4MmQtOTA1MC00&scope=openid&state=f4b74017-36f6-46da-af55-eb100d5f7c9e&nonce=5fe51e2e-d0ea-4cb1-b3fb-e73405034774&response_type=code&redirect_uri=https%3A//iam-id-1.au-syd.bluemix.net/oidc/callback/IBMid; TLTSID=LFE7RZU8ARQ342IROEJE1219Z27L5GUP; MYSAPSSO2=AjExMDAgABBwb3J0YWw6OTE5NDI2NjcyiAATYmFzaWNhdXRoZW50aWNhdGlvbgEACTkxOTQyNjY3MgIAAzAwMAMAA1RQQQQADDIwMTgwNjI5MDIwNAUABAAAABAKAAk5MTk0MjY2NzL%2FAQUwggEBBgkqhkiG9w0BBwKggfMwgfACAQExCzAJBgUrDgMCGgUAMAsGCSqGSIb3DQEHATGB0DCBzQIBATAiMB0xDDAKBgNVBAMTA1RQQTENMAsGA1UECxMESjJFRQIBADAJBgUrDgMCGgUAoF0wGAYJKoZIhvcNAQkDMQsGCSqGSIb3DQEHATAcBgkqhkiG9w0BCQUxDxcNMTgwNjI5MDIwNDI3WjAjBgkqhkiG9w0BCQQxFgQUlIOsrxcVN3RzLCOCgiuqu9Bs7BwwCQYHKoZIzjgEAwQvMC0CFHKemKwYmDWUvya8vDIqiYCXWWQYAhUApiWJRqB4WjXAuiCapYQC0ZIOk2Q%3D; SAPWP_active=1; 50200000_clogin=l=63207871532482814576&v=1&e=1532484649086; 52640000_clogin=v=1&l=14711221530243621402&e=1530245442810; ibmSurvey=1530580488942; prevProdID=IBM_PWB_681391021185; notice_behavior=implied|eu',
     connection: 'keep-alive',
     'if-none-match': 'W/"82-Rwd7IXe6ytzCSKsdxTVmiU9Hmhw"' } }

yuecchen avatar Jul 26 '18 04:07 yuecchen

@yuecchen which version of Node.js is this happening with please?

sjanuary avatar Aug 13 '18 10:08 sjanuary

Node.js version that we are using to find this issue is: v6.14.2

yuecchen avatar Aug 13 '18 14:08 yuecchen

@yuecchen I can't reproduce this, I'm using Node.js 6.14.4 and appmetrics 4.0.1 with this test server:

var monitoring = require('appmetrics').monitor();
var http = require('http');

monitoring.on('http', function(http) {
  console.info('http event: ' + JSON.stringify(http));
});

module.exports.server = http.createServer((req, res) => {
  // Send "Hello World" to every request
  res.writeHead(200, { 'Content-Type': 'text/plain' });
  res.end('Hello World');
});

this.server.listen(3000);

I then refresh localhost:3000 in the browser and I only see one event.

Could you please re-try with the latest appmetrics (4.0.1) and if you still see the problem could you paste in your test application here so I can see what you're doing differently to me?

sjanuary avatar Sep 17 '18 11:09 sjanuary

I can recreate this failure with the following code:

require('appmetrics-dash').attach();
const express = require('express');
const app = express();
const server = require('http').Server(app);
const io = require('socket.io')(server);
const bodyParser = require('body-parser')

app.use(bodyParser.urlencoded({     // to support URL-encoded bodies
  extended: true
}));

app.post('/number', function(req, res){
  console.log("new request")
  res.send("Your number was: " + req.body.number)
});

server.listen(3000)

output:

new request
new request
Error: Can't set headers after they are sent.
    at validateHeader (_http_outgoing.js:491:11)
    at ServerResponse.setHeader (_http_outgoing.js:498:3)
    at ServerResponse.header (/Users/george/tmp/appmetrics-dash/node_modules/express/lib/response.js:767:10)
    at ServerResponse.send (/Users/george/tmp/appmetrics-dash/node_modules/express/lib/response.js:170:12)
    at /Users/george/tmp/appmetrics-dash/server.js:14:7
    at Layer.handle [as handle_request] (/Users/george/tmp/appmetrics-dash/node_modules/express/lib/router/layer.js:95:5)
    at next (/Users/george/tmp/appmetrics-dash/node_modules/express/lib/router/route.js:137:13)
    at Route.dispatch (/Users/george/tmp/appmetrics-dash/node_modules/express/lib/router/route.js:112:3)
    at Layer.handle [as handle_request] (/Users/george/tmp/appmetrics-dash/node_modules/express/lib/router/layer.js:95:5)
    at /Users/george/tmp/appmetrics-dash/node_modules/express/lib/router/index.js:281:22

It seems to be to do with the fact that we are binding express and another service on the same http port (socket.io) in this case.

gdams avatar Sep 26 '18 09:09 gdams

@sjanuary tested with [email protected], with my pets application which have sent through mail. Still two http event is triggered for each request.

yuecchen avatar Oct 16 '18 04:10 yuecchen