logmarkerheadername not present on test query #552
Description
Hello,
using
ftw version 1.3.0
commit: 328702a324a39f1b906499d15e4219bf7bf1b0bb
built at: 2025-02-15T06:03:17Z
built by: goreleaser
While trying to create the following test:
tests:
- test_title: "CRS baseline blocks session_start parameter"
stages:
- stage:
input:
method: "POST"
uri: "/crs/?wc-ajax=update_order_review"
headers:
Host: "modsec"
Content-Type: "application/x-www-form-urlencoded"
data: "wc_order_attribution_session_start=2025-11-06%2008:56:22"
output:
log:
expect_ids: [933150]I realized this fails every time.
calling with run --debug
12:38PM DBG Applying overrides for engine '', platform ''
👉 executing tests in file wordpress/1100006.yaml
running 1100006-1: 12:38PM DBG ftw/http: sending data:
GET /status/200 HTTP/1.1
Accept: */*
Connection: close
Host: localhost
User-Agent: go-ftw test agent
X-FTW-Test-ID: 2568ff5f-4aa0-41d1-981a-68ae56b5644b-s
12:38PM DBG ftw/http: received data - "HTTP/1.1 200 OK\r\nDate: Thu, 06 Nov 2025 11:38:21 GMT\r\nContent-Type: text/html\r\nContent-Length: 101\r\nConnection: close\r\nVary: Accept-Encoding\r\nLast-Modified: Fri, 31 Oct 2025 14:36:00 GMT\r\nETag: \"65-6427548cd2eed\"\r\nAccept-Ranges: bytes\r\nContent-Security-Policy: frame-ancestors 'self'\r\nX-Frame-Options: SAMEORIGIN\r\nX-Content-Type-Options: nosniff\r\nAlt-Svc: h3=\":443\"; ma=86400\r\n\r\nOK\n- ici du fake content car pafois on a des ranges a tester et que sur 3 bytes c'est pas ouf ouf...\n"
12:38PM DBG found unexpected marker line while looking for 2568ff5f-4aa0-41d1-981a-68ae56b5644b-s: {"transaction":{"client_ip":"10.0.9.96","time_stamp":"thu nov 6 12:37:55 2025","server_id":"e88ebd680613f73c652a3ede99f7c0b045ec1e9c","client_port":54570,"host_ip":"10.0.9.96","host_port":80,"unique_id":"6f869a3b35d9d80c095494884328cbdb","request":{"method":"get","http_version":1.1,"uri":"/status/200","headers":{"accept":"*/*","connection":"close","host":"localhost","user-agent":"go-ftw test agent","x-ftw-test-id":"7948f6ae-2f9b-4a07-bbd9-160b54ae5bc3-e"}},"response":{"http_code":200,"headers":{"client_body_buffer_size":"","content-type":"text/html","accept-ranges":"bytes","etag":"\"65-6427548cd2eed\"","last-modified":"fri, 31 oct 2025 14:36:00 gmt","last-modified":"fri, 31 oct 2025 14:36:00 gmt","connection":"close","x-powered-by":"","content-length":"101","date":"thu, 06 nov 2025 11:37:55 gmt","server":"","server":"","64m":"","alt-svc":"h3=\":443\"; ma=86400","content-security-policy":"frame-ancestors 'self'","x-frame-options":"sameorigin","x-content-type-options":"nosniff"}},"producer":{"modsecurity":"modsecurity v3.0.14 (linux)","connector":"modsecurity-nginx v1.0.4","secrules_engine":"enabled","components":["dashsec/generic\"","owasp_crs/4.21.0-dev\""]},"messages":[{"message":"ml_vars:profile=generic,host=localhost","details":{"match":"","reference":"","ruleid":"9999101","file":"/etc/nginx/modsec/before.conf","linenumber":"194","data":"","severity":"6","ver":"dashsec-ml/1.0","rev":"","tags":[],"maturity":"0","accuracy":"0"}}]}}
12:38PM DBG ftw/http: sending data:
GET /status/200 HTTP/1.1
Accept: */*
Connection: close
Host: localhost
User-Agent: go-ftw test agent
X-FTW-Test-ID: 2568ff5f-4aa0-41d1-981a-68ae56b5644b-s
12:38PM DBG ftw/http: received data - "HTTP/1.1 200 OK\r\nDate: Thu, 06 Nov 2025 11:38:21 GMT\r\nContent-Type: text/html\r\nContent-Length: 101\r\nConnection: close\r\nVary: Accept-Encoding\r\nLast-Modified: Fri, 31 Oct 2025 14:36:00 GMT\r\nETag: \"65-6427548cd2eed\"\r\nAccept-Ranges: bytes\r\nContent-Security-Policy: frame-ancestors 'self'\r\nX-Frame-Options: SAMEORIGIN\r\nX-Content-Type-Options: nosniff\r\nAlt-Svc: h3=\":443\"; ma=86400\r\n\r\nOK\n- ici du fake content car pafois on a des ranges a tester et que sur 3 bytes c'est pas ouf ouf...\n"
12:38PM DBG ftw/http: sending data:
POST /crs/?wc-ajax=update_order_review HTTP/1.1
Connection: close
Content-Length: 56
Content-Type: application/x-www-form-urlencoded
Host: modsec
wc_order_attribution_session_start=2025-11-06%2008:56:22
12:38PM DBG ftw/http: received data - "HTTP/1.1 403 Forbidden\r\nDate: Thu, 06 Nov 2025 11:38:21 GMT\r\nContent-Type: text/html;charset=utf-8\r\nContent-Length: 9174\r\nConnection: close\r\nVary: Accept-Encoding\r\nCache-Control: no-cache, no-store, must-revalidate\r\nContent-Security-Policy: frame-ancestors 'self'\r\nX-Frame-Options: SAMEORIGIN\r\nX-Content-Type-Options: nosniff\r\n\r\nHTML_ERROR_PAGE_403_CONTENTS_STRIPED"
12:38PM DBG ftw/http: sending data:
GET /status/200 HTTP/1.1
Accept: */*
Connection: close
Host: localhost
User-Agent: go-ftw test agent
X-FTW-Test-ID: 2568ff5f-4aa0-41d1-981a-68ae56b5644b-e
12:38PM DBG ftw/http: received data - "HTTP/1.1 200 OK\r\nDate: Thu, 06 Nov 2025 11:38:21 GMT\r\nContent-Type: text/html\r\nContent-Length: 101\r\nConnection: close\r\nVary: Accept-Encoding\r\nLast-Modified: Fri, 31 Oct 2025 14:36:00 GMT\r\nETag: \"65-6427548cd2eed\"\r\nAccept-Ranges: bytes\r\nContent-Security-Policy: frame-ancestors 'self'\r\nX-Frame-Options: SAMEORIGIN\r\nX-Content-Type-Options: nosniff\r\nAlt-Svc: h3=\":443\"; ma=86400\r\n\r\nOK\n- ici du fake content car pafois on a des ranges a tester et que sur 3 bytes c'est pas ouf ouf...\n"
12:38PM DBG found unexpected marker line while looking for 2568ff5f-4aa0-41d1-981a-68ae56b5644b-e: {"transaction":{"client_ip":"10.0.9.96","time_stamp":"thu nov 6 12:38:21 2025","server_id":"e88ebd680613f73c652a3ede99f7c0b045ec1e9c","client_port":54182,"host_ip":"10.0.9.96","host_port":80,"unique_id":"5d96503788db7a91c7fed5aa06b5cf1b","request":{"method":"get","http_version":1.1,"uri":"/status/200","headers":{"accept":"*/*","connection":"close","host":"localhost","user-agent":"go-ftw test agent","x-ftw-test-id":"2568ff5f-4aa0-41d1-981a-68ae56b5644b-s"}},"response":{"http_code":200,"headers":{"client_body_buffer_size":"","content-type":"text/html","accept-ranges":"bytes","etag":"\"65-6427548cd2eed\"","last-modified":"fri, 31 oct 2025 14:36:00 gmt","last-modified":"fri, 31 oct 2025 14:36:00 gmt","connection":"close","x-powered-by":"","content-length":"101","date":"thu, 06 nov 2025 11:38:21 gmt","server":"","server":"","64m":"","alt-svc":"h3=\":443\"; ma=86400","content-security-policy":"frame-ancestors 'self'","x-frame-options":"sameorigin","x-content-type-options":"nosniff"}},"producer":{"modsecurity":"modsecurity v3.0.14 (linux)","connector":"modsecurity-nginx v1.0.4","secrules_engine":"enabled","components":["dashsec/generic\"","owasp_crs/4.21.0-dev\""]},"messages":[{"message":"ml_vars:profile=generic,host=localhost","details":{"match":"","reference":"","ruleid":"9999101","file":"/etc/nginx/modsec/before.conf","linenumber":"194","data":"","severity":"6","ver":"dashsec-ml/1.0","rev":"","tags":[],"maturity":"0","accuracy":"0"}}]}}
12:38PM DBG ftw/http: sending data:
GET /status/200 HTTP/1.1
Accept: */*
Connection: close
Host: localhost
User-Agent: go-ftw test agent
X-FTW-Test-ID: 2568ff5f-4aa0-41d1-981a-68ae56b5644b-e
12:38PM DBG ftw/http: received data - "HTTP/1.1 200 OK\r\nDate: Thu, 06 Nov 2025 11:38:21 GMT\r\nContent-Type: text/html\r\nContent-Length: 101\r\nConnection: close\r\nVary: Accept-Encoding\r\nLast-Modified: Fri, 31 Oct 2025 14:36:00 GMT\r\nETag: \"65-6427548cd2eed\"\r\nAccept-Ranges: bytes\r\nContent-Security-Policy: frame-ancestors 'self'\r\nX-Frame-Options: SAMEORIGIN\r\nX-Content-Type-Options: nosniff\r\nAlt-Svc: h3=\":443\"; ma=86400\r\n\r\nOK\n- ici du fake content car pafois on a des ranges a tester et que sur 3 bytes c'est pas ouf ouf...\n"
12:38PM DBG ../../../../home/runner/work/go-ftw/go-ftw/check/error.go:17 > Error expected: false. Found: -
12:38PM DBG Failed to find the following IDs in the log: [933150]
💥 1100006-1 failed in 63.422251ms (RTT 52.749118ms)
➕ run 135 total tests in 63.422251ms
⏭ skipped 134 tests
👎 1 test(s) failed to run: ["1100006-1"]
Error: failed 1 tests
I can see 2 things:
During pre-test phase, client sends headers:
Host: localhost
User-Agent: go-ftw test agent
X-FTW-Test-ID: 2568ff5f-4aa0-41d1-981a-68ae56b5644b-s
BTW sends Host: localhost, but my .ftw.yaml was setup with pretest_host: "modsec"
For the real query to test, client sends
Connection: close
Content-Length: 56
Content-Type: application/x-www-form-urlencoded
Host: modsec
Missing X-FTW-Test-ID (and default User-Agent) so ftw can't find the query in the logs and can answer "success" for this test.
am I missing something?