BereqMethod shown as HEAD although request is sent with GET

[sbraz]

Expected Behavior

When Varnish sends a GET to the backend, BereqMethod should be GET, not HEAD.

Current Behavior

When a client sends a HEAD, Varnish sends a GET to the backend and incorrectly reports that it used a HEAD.

Possible Solution

No response

Steps to Reproduce (for bugs)

With

vcl 4.1;

backend default {
    # A Debian archive mirror
    .host = "E.F.G.H";
    .port = "80";
}

After building 772d738 or de4b66c (from #4213 as requested by @dridi).

1. Start Varnish: ./bin/varnishd/varnishd -f $(pwd)/test.vcl -F
2. Start varnishlog and varnishncsa -b
3. Start tshark -f "host E.F.G.H" -t ad
4. Execute curl http://localhost/pub/debian/README.html -I
5. tshark shows 24 2024-12-30 16:21:14.070359100 A.B.C.D → E.F.G.H HTTP 262 GET /pub/debian/README.html HTTP/1.1
6. varnishlog shows

*   << BeReq    >> 3                     
-   Begin          bereq 2 fetch      
-   VCL_use        boot                   
-   Timestamp      Start: 1735575674.056417 0.000000 0.000000
-   BereqMethod    HEAD   
-   BereqURL       /pub/debian/README.html           
-   BereqProtocol  HTTP/1.1                      
-   BereqHeader    Host: localhost                 
-   BereqHeader    User-Agent: curl/7.88.1
-   BereqHeader    Accept: */*
-   BereqHeader    X-Forwarded-For: 127.0.0.1
-   BereqHeader    Via: 1.1 ns3082119 (Varnish/trunk)          
-   BereqMethod    GET    
-   BereqHeader    Accept-Encoding: gzip 
-   BereqHeader    X-Varnish: 3       
-   VCL_call       BACKEND_FETCH       
-   VCL_return     fetch                 
-   Timestamp      Fetch: 1735575674.056467 0.000049 0.000049
-   Timestamp      Connected: 1735575674.070265 0.013847 0.013797
-   BackendOpen    24 default E.F.G.H 80 A.B.C.D 33032 connect
-   Timestamp      Bereq: 1735575674.070375 0.013957 0.000109
-   BerespProtocol HTTP/1.1
-   BerespStatus   200       
-   BerespReason   OK           
-   BerespHeader   Date: Mon, 30 Dec 2024 16:21:14 GMT                                                                                       
-   BerespHeader   Server: Apache
-   BerespHeader   X-XSS-Protection: 1
-   BerespHeader   Content-Security-Policy: default-src 'self' *.ircam.fr
-   BerespHeader   X-Content-Type-Options: nosniff
-   BerespHeader   Last-Modified: Sat, 09 Nov 2024 09:23:03 GMT
-   BerespHeader   ETag: "b67-626776a22999e-gzip"
-   BerespHeader   Accept-Ranges: bytes
-   BerespHeader   Vary: Accept-Encoding
-   BerespHeader   Content-Encoding: gzip
-   BerespHeader   Content-Length: 967
-   BerespHeader   Content-Type: text/html
-   Timestamp      Beresp: 1735575674.084192 0.027774 0.013817
-   TTL            RFC 120 10 0 1735575674 1735575674 1735575674 0 0 cacheable
-   VCL_call       BACKEND_RESPONSE
-   VCL_return     deliver
-   Timestamp      Process: 1735575674.084265 0.027847 0.000072
-   Filters         testgunzip
-   Storage        malloc s0
-   Fetch_Body     3 length stream
-   Gzip           u F - 967 2919 80 80 7666
-   BackendClose   24 default recycle
-   Timestamp      BerespBody: 1735575674.084538 0.028120 0.000273
-   Length         967
-   BereqAcct      196 0 196 375 967 1342
-   End

7. varnishncsa shows

E.F.G.H - - [30/Dec/2024:16:21:14 +0000] "HEAD http://localhost/pub/debian/README.html HTTP/1.1" 200 967 "-" "curl/7.88.1"

Context

This makes it harder to understand what request is sent to the backend.

Varnish Cache version

varnishd (varnish-trunk revision 772d738)

Operating system

Debian 12

Source of binary packages used (if any)

N/A

[walid-git]

Current Behavior

When a client sends a HEAD, Varnish sends a GET to the backend and incorrectly reports that it used a HEAD.

It actually reports both of them, if you see the logs:

...
-   BereqMethod    HEAD  
...
-   BereqMethod    GET  
...

I think this is a good thing, at least we know that it was changed (in this case by the core code, but could also happen in VCL).

13. varnishncsa shows

E.F.G.H - - [30/Dec/2024:16:21:14 +0000] "HEAD http://localhost/pub/debian/README.html HTTP/1.1" 200 967 "-" "curl/7.88.1"

Was this captured using varnishncsa from #4213 ? If so, can you share the command line arguments passed to varnishncsa ?

[sbraz]

Sorry, I completely missed the second BereqMethod. I'll perform the test with #4213 and the master branch again.

Was this captured using varnishncsa from #4213 ? If so, can you share the command line arguments passed to varnishncsa ?

Yes, no arguments besides -b.

[sbraz]

My bad, varnishncsa shows GET http://localhost/pub/debian/README.html with #4213.

[walid-git]

No problem, then I guess everything is working as expected. I will close the issue.

[sbraz]

I can confirm that, when building Varnish from #4213, it works as expected:

root@localhost ~/varnish-cache $ ./bin/varnishncsa/varnishncsa -bc
A.B.C.D - - [30/Dec/2024:17:15:57 +0000] "GET http://localhost/pub/debian/README.html HTTP/1.1" 200 967 "-" "curl/7.88.1"
127.0.0.1 - - [30/Dec/2024:17:15:57 +0000] "HEAD http://localhost/pub/debian/README.html HTTP/1.1" 200 0 "-" "curl/7.88.1"

root@localhost ~/varnish-cache $ ./bin/varnishlog/varnishlog -i VCL_call,ReqMethod,BereqMethod,VCL_Log,Length,ReqURL
*   << BeReq    >> 3         
-   BereqMethod    HEAD
-   BereqMethod    GET
-   VCL_call       BACKEND_FETCH
-   VCL_call       BACKEND_RESPONSE
-   Length         967

*   << Request  >> 2         
-   ReqMethod      HEAD
-   ReqURL         /pub/debian/README.html
-   VCL_call       RECV
-   VCL_call       HASH
-   VCL_call       MISS
-   VCL_call       DELIVER

*   << Session  >> 1         

Although it didn't entirely work with master (varnishlog shows the change in BereqMethod but varnishlog shows HEAD for the backend request):

root@localhost ~/varnish-cache $ ./bin/varnishncsa/varnishncsa -bc
A.B.C.D - - [30/Dec/2024:17:17:06 +0000] "HEAD http://localhost/pub/debian/README.html HTTP/1.1" 200 967 "-" "curl/7.88.1"
127.0.0.1 - - [30/Dec/2024:17:17:06 +0000] "HEAD http://localhost/pub/debian/README.html HTTP/1.1" 200 0 "-" "curl/7.88.1"

root@localhost ~/varnish-cache $ ./bin/varnishlog/varnishlog -i VCL_call,ReqMethod,BereqMethod,VCL_Log,Length,ReqURL
*   << BeReq    >> 3         
-   BereqMethod    HEAD
-   BereqMethod    GET
-   VCL_call       BACKEND_FETCH
-   VCL_call       BACKEND_RESPONSE
-   Length         967

*   << Request  >> 2         
-   ReqMethod      HEAD
-   ReqURL         /pub/debian/README.html
-   VCL_call       RECV
-   VCL_call       HASH
-   VCL_call       MISS
-   VCL_call       DELIVER

*   << Session  >> 1         

Sorry for the bother, we can consider that this issue will be fixed by #4213.

everything is working as expected

will be once the PR is merged :) But I can wait, thanks for your help.

[walid-git]

Sorry for the bother, we can consider that this issue will be fixed by #4213.

everything is working as expected

will be once the PR is merged :) But I can wait, thanks for your help.

Yes, that's what I meant :) The issue is known and already tracked in #3528 so no need for a duplicate.