esi-test-server-docker icon indicating copy to clipboard operation
esi-test-server-docker copied to clipboard

Published 20 hours ago • verified publisher icon akamai

Headers not set by using setheader or appendheader attributes on esi:include

Open bkoltoniak opened this issue 1 year ago • 0 comments

I have the following setup

  1. Docker container with express server that acts as the origin server for ETS, which serves the following content
<!DOCTYPE html>
<html >
<head>
</head>
<body class="_widget-auto-layout hiddenElement">
    <esi:include src="http://footer.test:8000/checkheaders" appendheader="X-HEADER: bartek"/>
</body>
</html>
  1. Second docker container with express server that serves the content fetched by esi:include. Request headers are printed to the response
app.use((req, res, next) => {
  log('Executing ' + req.protocol + ' endpoint ' + req.path);
  const headersString = JSON.stringify(req.headers, null, 2);
  log('HEADERS: ' + headersString);
  res.send('<div><h1>THIS IS FRAGMENT FROM ANOTHER ORIGIN <h1><h3>REQUEST HEADERS<h3> <pre>' + headersString + '</pre></div>');
});
  1. ETS server setup with both express servers using docker compose.

The setup is working fine. I am able to see the included ESI fragment in the browser. The problem is headers set using either appendheader or setheader don't have any effect. The only header that comes with the request to fetch esi:include src is the host header.

I did enable apache debug logs in the ETS container to look for something helpful. In the log can be seen that any headers were printed to the response body from 2 container.

[Wed Feb 14 13:33:04.952197 2024] [authz_core:debug] [pid 152:tid 4078283584] mod_authz_core.c(835): [client 172.20.0.1:40360] AH01628: authorization result: granted (no directives)
[Wed Feb 14 13:33:04.952229 2024] [esi:debug] [pid 152:tid 4078283584] esi_ctx.c(39): [client 172.20.0.1:40360] create ctx: config is ok: /login
[Wed Feb 14 13:33:04.952235 2024] [esi:debug] [pid 152:tid 4078283584] mod_esi.c(127): [client 172.20.0.1:40360] esi installing filters for /login
[Wed Feb 14 13:33:04.952240 2024] [proxy:debug] [pid 152:tid 4078283584] mod_proxy.c(1228): [client 172.20.0.1:40360] AH01143: Running scheme http handler (attempt 0)
[Wed Feb 14 13:33:04.952243 2024] [proxy:debug] [pid 152:tid 4078283584] proxy_util.c(2156): AH00942: HTTP: has acquired connection for (auth0.local)
[Wed Feb 14 13:33:04.952246 2024] [proxy:debug] [pid 152:tid 4078283584] proxy_util.c(2209): [client 172.20.0.1:40360] AH00944: connecting http://auth0.local:3000/login to auth0.local:3000
[Wed Feb 14 13:33:04.952248 2024] [proxy:debug] [pid 152:tid 4078283584] proxy_util.c(2418): [client 172.20.0.1:40360] AH00947: connected /login to auth0.local:3000
[Wed Feb 14 13:33:04.952281 2024] [proxy:debug] [pid 152:tid 4078283584] proxy_util.c(2716): AH00951: HTTP: backend socket is disconnected.
[Wed Feb 14 13:33:04.952317 2024] [proxy:debug] [pid 152:tid 4078283584] proxy_util.c(2884): AH02824: HTTP: connection established with 172.20.0.4:3000 (auth0.local)
[Wed Feb 14 13:33:04.952321 2024] [proxy:debug] [pid 152:tid 4078283584] proxy_util.c(3051): AH00962: HTTP: connection complete to 172.20.0.4:3000 (auth0.local)
[Wed Feb 14 13:33:04.952330 2024] [esi:debug] [pid 152:tid 4078283584] esi_core.c(780): [client 172.20.0.1:40360] esi input filter returns 0 for /login
[Wed Feb 14 13:33:04.961504 2024] [proxy:debug] [pid 152:tid 4078283584] proxy_util.c(2171): AH00943: http: has released connection for (auth0.local)
[Wed Feb 14 13:33:04.961539 2024] [esi:debug] [pid 152:tid 4078283584] esi_core.c(614): [client 172.20.0.1:40360] esi_filter_out_init: filter init for /login
[Wed Feb 14 13:33:04.961548 2024] [esi:debug] [pid 152:tid 4078283584] esi_core.c(261): [client 172.20.0.1:40360] esi_ctx_init_response: check Cookie for debug: /login
[Wed Feb 14 13:33:04.961574 2024] [esi:debug] [pid 152:tid 4078283584] esi_core.c(276): [client 172.20.0.1:40360] esi_ctx_init_response: formatted request: /login
[Wed Feb 14 13:33:04.961578 2024] [esi:debug] [pid 152:tid 4078283584] esi_core.c(649): [client 172.20.0.1:40360] filtering response, collecting data
[Wed Feb 14 13:33:04.961581 2024] [esi:debug] [pid 152:tid 4078283584] esi_core.c(667): [client 172.20.0.1:40360] filtering response, collecting 199 bytes
[Wed Feb 14 13:33:04.961583 2024] [esi:debug] [pid 152:tid 4078283584] esi_core.c(652): [client 172.20.0.1:40360] filtering initial request, data complete for /login
[Wed Feb 14 13:33:04.961591 2024] [esi:debug] [pid 152:tid 4078283584] esi_core.c(118): [client 172.20.0.1:40360] find path processor: /login
[Wed Feb 14 13:33:04.961594 2024] [esi:debug] [pid 152:tid 4078283584] esi_core.c(168): [client 172.20.0.1:40360] path processor -1: /login
[Wed Feb 14 13:33:04.961602 2024] [esi:debug] [pid 152:tid 4078283584] esi_core.c(310): [client 172.20.0.1:40360] setupAsiWork url=/login proc=http://localhost:9090/asip, request=GET /login HTTP/1.1\r\nContent-Length: 0\r\nHost: auth0.local:8080\r\nConnection: keep-alive\r\nPragma: no-cache\r\nCache-Control: no-cache\r\nUpgrade-Insecure-Requests: 1\r\nUser-Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/121.0.0.0 Safari/537.36 Edg/121.0.0.0\r\nAccept: text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.7\r\nAccept-Encoding: gzip, deflate\r\nAccept-Language: en-GB,en;q=0.9\r\nCookie: OptanonAlertBoxClosed=2024-02-14T09:16:45.667Z; OptanonIgnored=2024-02-15T09:16:45.785Z; OptUCMOnsiteConsent=false; OptanonConsent=isGpcEnabled=0&datestamp=Wed+Feb+14+2024+12%3A50%3A21+GMT%2B0000+(Greenwich+Mean+Time)&version=202306.2.0&browserGpcFlag=0&isIABGlobal=false&hosts=&consentId=dff1a068-2f12-47cd-bc10-ec36cdf0abef&interactionCount=1&landingPath=NotLandingPage&groups=Targt%3A0%2COntgt%3A0%2CPerf%3A0%2CStNec%3A1&geolocation=%3B&AwaitingReconsent=false\r\n\r\n, response=HTTP/1.1 200 OK\r\nContent-Length: 199\r\nX-Powered-By: Express\r\nContent-Type: text/html; charset=utf-8\r\nETag: W/"c7-m5zu8PIsEnalq4vBF9sd52yTdto"\r\nDate: Wed, 14 Feb 2024 13:33:04 GMT\r\n\r\n<!DOCTYPE html>\n<html >\n<head>\n</head>\n<body class="_widget-auto-layout hiddenElement">\n    <esi:include src="http://footer.test:8000/checkheaders" appendheader="X-HEADER: bartek"/>\n\n</body>\n</html>\n
[Wed Feb 14 13:33:04.961620 2024] [esi:debug] [pid 152:tid 4078283584] esi_asi.c(270): [client 172.20.0.1:40360] esi_asi_process request 0 for /login
[Wed Feb 14 13:33:04.961656 2024] [esi:debug] [pid 152:tid 4078283584] esi_asi.c(277): [client 172.20.0.1:40360] esi_asi_process waiting for work in /login
[Wed Feb 14 13:33:04.961919 2024] [esi:debug] [pid 152:tid 4103461696] esi_asi.c(404): [client 172.20.0.1:40360] esi_asi_dispatch, signal work for /login
[Wed Feb 14 13:33:04.961968 2024] [esi:debug] [pid 152:tid 4078283584] esi_asi.c(303): [client 172.20.0.1:40360] esi_asi_process do work in req=0 /login
[Wed Feb 14 13:33:04.961979 2024] [esi:debug] [pid 152:tid 4078283584] esi_asi.c(309): [client 172.20.0.1:40360] esi_asi_process, fragment request in req=0 /login
[Wed Feb 14 13:33:04.962012 2024] [esi:info] [pid 152:tid 4078283584] [client 172.20.0.1:40360] fragment request to null:footer.test:8000: GET /checkheaders ssl=0 request=GET /checkheaders HTTP/1.0\r\nHost: footer.test:8000\r\nVia: 4.0 asi_server\r\nX-Akamai-ClientIP: 172.20.0.1\r\nAccept: text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.7\r\nAccept-Language: en-GB,en;q=0.9\r\nCache-Control: no-cache\r\nCookie: OptanonAlertBoxClosed=2024-02-14T09:16:45.667Z; OptanonIgnored=2024-02-15T09:16:45.785Z; OptUCMOnsiteConsent=false; OptanonConsent=isGpcEnabled=0&datestamp=Wed+Feb+14+2024+12%3A50%3A21+GMT%2B0000+(Greenwich+Mean+Time)&version=202306.2.0&browserGpcFlag=0&isIABGlobal=false&hosts=&consentId=dff1a068-2f12-47cd-bc10-ec36cdf0abef&interactionCount=1&landingPath=NotLandingPage&groups=Targt%3A0%2COntgt%3A0%2CPerf%3A0%2CStNec%3A1&geolocation=%3B&AwaitingReconsent=false\r\nUser-Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/121.0.0.0 Safari/537.36 Edg/121.0.0.0\r\nConnection: keep-alive\r\nUpgrade-Insecure-Requests: 1\r\nPragma: no-cache\r\nX-Akamai-MD-Component3: \r\nX-Akamai-MD-Component3: <edgeservices:modify-outgoing-request><add-header><status>on</status><name>X-HEADER</name><value> bartek</value></add-header></edgeservices:modify-outgoing-request>\r\n\r\n
[Wed Feb 14 13:33:04.962040 2024] [esi:debug] [pid 152:tid 4078283584] esi_http.c(363): [client 172.20.0.1:40360] set http request timeout to : 30
[Wed Feb 14 13:33:04.963652 2024] [esi:debug] [pid 152:tid 4078283584] esi_core.c(457): [client 172.20.0.1:40360] esi_http_req_run(/checkheaders) -> 200
[Wed Feb 14 13:33:04.963663 2024] [esi:debug] [pid 152:tid 4078283584] esi_ctx.c(54): [client 172.20.0.1:40360] create ctx: config is ok: http://footer.test:8000/checkheaders
[Wed Feb 14 13:33:04.963668 2024] [esi:debug] [pid 152:tid 4078283584] esi_core.c(118): [client 172.20.0.1:40360] find path processor: http://footer.test:8000/checkheaders
[Wed Feb 14 13:33:04.963671 2024] [esi:debug] [pid 152:tid 4078283584] esi_core.c(168): [client 172.20.0.1:40360] path processor -1: http://footer.test:8000/checkheaders
[Wed Feb 14 13:33:04.963680 2024] [esi:debug] [pid 152:tid 4078283584] esi_core.c(348): [client 172.20.0.1:40360] esi_core_setup_http url=/checkheaders proc=http://localhost:9090/asip, request=GET /checkheaders HTTP/1.0\r\nHost: footer.test:8000\r\nVia: 4.0 asi_server\r\nX-Akamai-ClientIP: 172.20.0.1\r\nAccept: text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.7\r\nAccept-Language: en-GB,en;q=0.9\r\nCache-Control: no-cache\r\nCookie: OptanonAlertBoxClosed=2024-02-14T09:16:45.667Z; OptanonIgnored=2024-02-15T09:16:45.785Z; OptUCMOnsiteConsent=false; OptanonConsent=isGpcEnabled=0&datestamp=Wed+Feb+14+2024+12%3A50%3A21+GMT%2B0000+(Greenwich+Mean+Time)&version=202306.2.0&browserGpcFlag=0&isIABGlobal=false&hosts=&consentId=dff1a068-2f12-47cd-bc10-ec36cdf0abef&interactionCount=1&landingPath=NotLandingPage&groups=Targt%3A0%2COntgt%3A0%2CPerf%3A0%2CStNec%3A1&geolocation=%3B&AwaitingReconsent=false\r\nUser-Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/121.0.0.0 Safari/537.36 Edg/121.0.0.0\r\nConnection: keep-alive\r\nUpgrade-Insecure-Requests: 1\r\nPragma: no-cache\r\nX-Akamai-MD-Component3: \r\nX-Akamai-MD-Component3: <edgeservices:modify-outgoing-request><add-header><status>on</status><name>X-HEADER</name><value> bartek</value></add-header></edgeservices:modify-outgoing-request>\r\n\r\n, response=HTTP/1.1 200 OK\r\nX-Powered-By: Express\r\nContent-Type: text/html; charset=utf-8\r\nContent-Length: 123\r\nETag: W/"7b-09IXS3ePQfl2gnXq6I8Xf6QWTAA"\r\nDate: Wed, 14 Feb 2024 13:33:04 GMT\r\nConnection: keep-alive\r\nKeep-Alive: timeout=5\r\n\r\n<div><h1>THIS IS FRAGMENT FROM ANOTHER ORIGIN <h1><h3>REQUEST HEADERS<h3> <pre>{\n  "host": "footer.test:8000"\n}</pre></div>
[Wed Feb 14 13:33:04.963753 2024] [esi:debug] [pid 152:tid 4078283584] esi_asi.c(277): [client 172.20.0.1:40360] esi_asi_process waiting for work in /login
[Wed Feb 14 13:33:04.963919 2024] [esi:debug] [pid 152:tid 4103461696] esi_asi.c(404): [client 172.20.0.1:40360] esi_asi_dispatch, signal work for /login
[Wed Feb 14 13:33:04.963965 2024] [esi:debug] [pid 152:tid 4103461696] esi_asi.c(404): [client 172.20.0.1:40360] esi_asi_dispatch, signal work for /login
[Wed Feb 14 13:33:04.964003 2024] [esi:debug] [pid 152:tid 4078283584] esi_asi.c(303): [client 172.20.0.1:40360] esi_asi_process do work in req=0 /login
[Wed Feb 14 13:33:04.964006 2024] [esi:debug] [pid 152:tid 4078283584] esi_asi.c(321): [client 172.20.0.1:40360] esi_asi_process, got response for req=0 /login
[Wed Feb 14 13:33:04.964007 2024] [esi:debug] [pid 152:tid 4078283584] esi_asi.c(303): [client 172.20.0.1:40360] esi_asi_process do work in req=0 /login
[Wed Feb 14 13:33:04.964023 2024] [esi:debug] [pid 152:tid 4078283584] esi_core.c(557): [client 172.20.0.1:40360] filterByAsi: response: HTTP/1.0 200 OK\r\nLast-Modified: Wed, 14 Feb 2024 13:33:04 GMT\r\nContent-Length: 233\r\nContent-Type: text/html; charset=utf-8\r\nEdge-Control: downstream-ttl=0\r\nDate: Wed, 14 Feb 2024 13:33:04 GMT\r\nX-Akamai-ASIS-Flitload: 0\r\nX-Powered-By: Express\r\nETag: W/"c7-m5zu8PIsEnalq4vBF9sd52yTdto"\r\n\r\n<!DOCTYPE html>\n<html >\n<head>\n</head>\n<body class="_widget-auto-layout hiddenElement">\n    <div><h1>THIS IS FRAGMENT FROM ANOTHER ORIGIN <h1><h3>REQUEST HEADERS<h3> <pre>{\n  "host": "footer.test:8000"\n}</pre></div>\n\n</body>\n</html>\n
[Wed Feb 14 13:33:04.964029 2024] [esi:debug] [pid 152:tid 4078283584] esi_bs.c(165): [client 172.20.0.1:40360] prepending 233 bytes to out brigade\n
[Wed Feb 14 13:33:04.964047 2024] [esi:debug] [pid 152:tid 4078283584] esi_core.c(780): [client 172.20.0.1:40360] esi input filter returns 0 for /login

This piece is interesting. Looks like the heder was added to processing by ESI internally?

X-Akamai-MD-Component3: <edgeservices:modify-outgoing-request><add-header><status>on</status><name>X-HEADER</name><value> bartek</value></add-header></edgeservices:modify-outgoing-request>

bkoltoniak avatar Feb 14 '24 14:02 bkoltoniak