Advanced
Mailing List Archive

Mailing List Archive

  1. Home >
  2. Varnish>
  3. Misc
Mysterious no content result, from an URL with pass action
jb-varnish at wisemo
May 9, 2023, 6:10 PM
Post #1 of 6 (449 views)
Permalink
Dear Varnish mailing list,

When testing varnish as a reverse proxy for multiple services
including a local JetBrains TeamCity instance, requests to that
teamcity server get corrupted into "204 No Content" replies.

Once again, Varnish fails to say why it is refusing to do its job.
Any sane program should explicitly and loudly report any fatal error
that stops it working.  Loudly means the sysadmin or other user
invoking the program receives the exaxt error message by default
instead of something highly indirect, hidden behind a debug option
or otherwisse highly non-obvious.

Here's a relevant clip from the VCL:

# Various top comments
vcl 4.1;

import std;
import proxy;

# Backend sending requests to the teamcity main server
backend teamcity {
    .host = "2a01:xxxx:xxxx:xxxx:xxxx:xxxx:xxxx:xxxx";
    .port = "8111";
}

# IP ranges allowed to access the build server and staging server
acl buildtrust {
    "127.0.0.0"/8;
    "::"/128;
    "various others"/??;
}

# IP ranges allowed to attempt login to things that use our common login
#    database
acl logintrust {
    "various others"/??;
}

sub vcl_recv {
    # Happens before we check if we have this in cache already.
    #
    # Typically you clean up the request here, removing cookies you
don't need,
    # rewriting the request, etc.
    if (proxy.is_ssl()) {
        set req.http.Scheme = "https";
        set req.http.ssl-version = proxy.ssl_version();
        set req.http.X-Forwarded-Proto = "https";
        set req.http.X-SSL-cipher = proxy.ssl_cipher();
        std.log("TLS-SSL-VERSION: " + proxy.ssl_version());
    } else {
        set req.http.X-Forwarded-Proto = req.http.Scheme;
        unset req.http.ssl-version;
        unset req.http.X-SSL-cipher;
        std.log("TLS-SSL-VERSION: none");
    }
    unset req.http.X-SSL-Subject;
    unset req.http.X-SSL-Issuer;
    unset req.http.X-SSL-notBefore;
    unset req.http.X-SSL-notAfter;
    unset req.http.X-SSL-serial;
    unset req.http.X-SSL-certificate;

    set req.http.X-Forwarded-For = client.ip;

    call vcl_req_host;

    if (req.url ~ "^/something") {
        set req.backend_hint = be1;
    } else if (req.url !~ "^/somethingelse" &&
               !(client.ip ~ logintrust) &&
               !(client.ip ~ buildtrust)) {
        # Treat as unknown by redirecting to public website
        if ((req.url ~ "^/yeatanother") ||
            (req.url ~ "^/yetsomeother")) {
            return (synth(752));
        } else if (req.url ~ "^/yetsomethird") {
            return (synth(753));
        }
        return (synth(751));
    } else if (req.http.Scheme && req.http.Scheme != "https") {
        # See example at
https://www.varnish-software.com/developers/tutorials/redirect/
        return (synth(750));
    } else if (req.url ~ "^/somethingelse") {
        set req.backend_hint = be1;
    } else if (req.url ~ "^/somethingfourth") {
        set req.backend_hint = be2;
    } else if (req.url ~ "^/somethingfifth") {
        set req.backend_hint = be2;
    } else if (!(client.ip ~ buildtrust)) {
        # Treat as unknown by redirecting to public website
        if ((req.url ~ "^/yeatanother") ||
            (req.url ~ "^/yetsomeother")) {
            return (synth(752));
        } else if (req.url ~ "^/yetsomethird") {
            return (synth(753));
        }
        return (synth(751));
    } else if (req.url ~ "^/teamcity") {
        set req.backend_hint= teamcity;
        return (pass);
#    } else if (req.http.host ~ "^somethingsixths") {
#       set req.backend_hint= be4;
    } else {
        set req.backend_hint = be5;
    }
    call vcl_req_method;
    call vcl_req_authorization;
    call vcl_req_cookie;
    return (hash);
}

sub vcl_backend_response {
    # Happens after we have read the response headers from the backend.
    #
    # Here you clean the response headers, removing silly Set-Cookie
headers
    # and other mistakes your backend does.

    # The Java webserver in teamcity is incompatible with varnish
connection
    #    pooling
    if (beresp.backend == teamcity) {
        if (beresp.http.Connection &&
            beresp.http.Connection !~ "keep-alive") {
            set beresp.http.Connection += ", close";
        } else {
            set beresp.http.Connection = "close";
        }
    }
}

+++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
First 43 lines of varnishlog -v 2>&1

*              << BeReq    >>   9
-            9 Begin          b bereq 8 pass
-            9 VCL_use        b boot
-            9 Timestamp      b Start: 1681484803.177212 0.000000 0.000000
-            9 BereqMethod    b GET
-            9 BereqURL       b /teamcity/app/agents/v1/commands/next
-            9 BereqProtocol  b HTTP/1.1
-            9 BereqHeader    b TeamCity-AgentSessionId:
L6juFAAt1awJDt6UKToPIxQq7wpBF89C
-            9 BereqHeader    b User-Agent: TeamCity Agent 2021.2.3
-            9 BereqHeader    b Host: vmachine.example.com
-            9 BereqHeader    b Via: 1.1 vmachine (Varnish/7.2)
-            9 BereqHeader    b Scheme: https
-            9 BereqHeader    b ssl-version: TLSv1.3
-            9 BereqHeader    b X-Forwarded-Proto: https
-            9 BereqHeader    b X-SSL-cipher: TLS_AES_256_GCM_SHA384
-            9 BereqHeader    b X-Forwarded-For: 192.168.2.112
-            9 BereqHeader    b X-Varnish: 9
-            9 VCL_call       b BACKEND_FETCH
-            9 VCL_return     b fetch
-            9 Timestamp      b Fetch: 1681484803.177227 0.000014 0.000014
-            9 Timestamp      b Connected: 1681484803.177603 0.000390
0.000375
-            9 BackendOpen    b 24 teamcity
2a01:xxxx:xxxx:xxxx:xxxx:xxxx:xxxx:xxxx 8111 2a01:yyyy:yyyy:yyyy::yyyy
59548 connect
-            9 Timestamp      b Bereq: 1681484803.177645 0.000432 0.000042
-            9 BerespReason   b No Content
-            9 Timestamp      b Beresp: 1681484830.672487 27.495274
27.494842
-            9 BerespProtocol b HTTP/1.1
-            9 BerespStatus   b 204
-            9 BerespReason   b No Content
-            9 BerespHeader   b TeamCity-Node-Id: MAIN_SERVER
-            9 BerespHeader   b Date: Fri, 14 Apr 2023 15:07:10 GMT
-            9 VCL_call       b BACKEND_RESPONSE
-            9 BerespHeader   b Connection: close
-            9 VCL_return     b deliver
-            9 Timestamp      b Process: 1681484830.672563 27.495350
0.000075
-            9 Filters        b
-            9 Storage        b malloc Transient
-            9 Fetch_Body     b 0 none -
-            9 BackendClose   b 24 teamcity close Backend/VCL requested
close
-            9 Timestamp      b BerespBody: 1681484830.672926 27.495713
0.000362
-            9 Length         b 0
-            9 BereqAcct      b 345 0 345 85 0 85
-            9 End            b




Enjoy

Jakob
--
Jakob Bohm, CIO, Partner, WiseMo A/S. https://www.wisemo.com
Transformervej 29, 2860 Søborg, Denmark. Direct +45 31 13 16 10
This public discussion message is non-binding and may contain errors.
WiseMo - Remote Service Management for PCs, Phones and Embedded

_______________________________________________
varnish-misc mailing list
varnish-misc@varnish-cache.org
https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc
Re: Mysterious no content result, from an URL with pass action [ In reply to ]
guillaume.quintard at gmail
May 9, 2023, 9:49 PM
Post #2 of 6 (449 views)
Permalink
Hi Jakob,

(Sorry i didn't see that email sooner, it was in my spam folder)

Looking at the log, I'm not sure what varnish should be loud about :-)
204 is a success code, and more importantly it's generated by the backend,
so varnish is happily passing it along.

At the http level, everything looks about right, but I can guess from your
apparent irritation that something wrong one level up, let's try to debug
that.

What kind of response are you expecting, if not a 204? And maybe, what is
that endpoint supposed to do? Given that the method was GET, and that
there's no body, my only guess is that there's something happening with
the TeamCity-AgentSessionId header, maybe?
Is the 27 seconds processing time expected?

Cheers,

On Tue, May 9, 2023, 15:12 Jakob Bohm <jb-varnish@wisemo.com> wrote:

> Dear Varnish mailing list,
>
> When testing varnish as a reverse proxy for multiple services
> including a local JetBrains TeamCity instance, requests to that
> teamcity server get corrupted into "204 No Content" replies.
>
> Once again, Varnish fails to say why it is refusing to do its job.
> Any sane program should explicitly and loudly report any fatal error
> that stops it working. Loudly means the sysadmin or other user
> invoking the program receives the exaxt error message by default
> instead of something highly indirect, hidden behind a debug option
> or otherwisse highly non-obvious.
>
> Here's a relevant clip from the VCL:
>
> # Various top comments
> vcl 4.1;
>
> import std;
> import proxy;
>
> # Backend sending requests to the teamcity main server
> backend teamcity {
> .host = "2a01:xxxx:xxxx:xxxx:xxxx:xxxx:xxxx:xxxx";
> .port = "8111";
> }
>
> # IP ranges allowed to access the build server and staging server
> acl buildtrust {
> "127.0.0.0"/8;
> "::"/128;
> "various others"/??;
> }
>
> # IP ranges allowed to attempt login to things that use our common login
> # database
> acl logintrust {
> "various others"/??;
> }
>
> sub vcl_recv {
> # Happens before we check if we have this in cache already.
> #
> # Typically you clean up the request here, removing cookies you
> don't need,
> # rewriting the request, etc.
> if (proxy.is_ssl()) {
> set req.http.Scheme = "https";
> set req.http.ssl-version = proxy.ssl_version();
> set req.http.X-Forwarded-Proto = "https";
> set req.http.X-SSL-cipher = proxy.ssl_cipher();
> std.log("TLS-SSL-VERSION: " + proxy.ssl_version());
> } else {
> set req.http.X-Forwarded-Proto = req.http.Scheme;
> unset req.http.ssl-version;
> unset req.http.X-SSL-cipher;
> std.log("TLS-SSL-VERSION: none");
> }
> unset req.http.X-SSL-Subject;
> unset req.http.X-SSL-Issuer;
> unset req.http.X-SSL-notBefore;
> unset req.http.X-SSL-notAfter;
> unset req.http.X-SSL-serial;
> unset req.http.X-SSL-certificate;
>
> set req.http.X-Forwarded-For = client.ip;
>
> call vcl_req_host;
>
> if (req.url ~ "^/something") {
> set req.backend_hint = be1;
> } else if (req.url !~ "^/somethingelse" &&
> !(client.ip ~ logintrust) &&
> !(client.ip ~ buildtrust)) {
> # Treat as unknown by redirecting to public website
> if ((req.url ~ "^/yeatanother") ||
> (req.url ~ "^/yetsomeother")) {
> return (synth(752));
> } else if (req.url ~ "^/yetsomethird") {
> return (synth(753));
> }
> return (synth(751));
> } else if (req.http.Scheme && req.http.Scheme != "https") {
> # See example at
> https://www.varnish-software.com/developers/tutorials/redirect/
> return (synth(750));
> } else if (req.url ~ "^/somethingelse") {
> set req.backend_hint = be1;
> } else if (req.url ~ "^/somethingfourth") {
> set req.backend_hint = be2;
> } else if (req.url ~ "^/somethingfifth") {
> set req.backend_hint = be2;
> } else if (!(client.ip ~ buildtrust)) {
> # Treat as unknown by redirecting to public website
> if ((req.url ~ "^/yeatanother") ||
> (req.url ~ "^/yetsomeother")) {
> return (synth(752));
> } else if (req.url ~ "^/yetsomethird") {
> return (synth(753));
> }
> return (synth(751));
> } else if (req.url ~ "^/teamcity") {
> set req.backend_hint= teamcity;
> return (pass);
> # } else if (req.http.host ~ "^somethingsixths") {
> # set req.backend_hint= be4;
> } else {
> set req.backend_hint = be5;
> }
> call vcl_req_method;
> call vcl_req_authorization;
> call vcl_req_cookie;
> return (hash);
> }
>
> sub vcl_backend_response {
> # Happens after we have read the response headers from the backend.
> #
> # Here you clean the response headers, removing silly Set-Cookie
> headers
> # and other mistakes your backend does.
>
> # The Java webserver in teamcity is incompatible with varnish
> connection
> # pooling
> if (beresp.backend == teamcity) {
> if (beresp.http.Connection &&
> beresp.http.Connection !~ "keep-alive") {
> set beresp.http.Connection += ", close";
> } else {
> set beresp.http.Connection = "close";
> }
> }
> }
>
> +++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
> First 43 lines of varnishlog -v 2>&1
>
> * << BeReq >> 9
> - 9 Begin b bereq 8 pass
> - 9 VCL_use b boot
> - 9 Timestamp b Start: 1681484803.177212 0.000000 0.000000
> - 9 BereqMethod b GET
> - 9 BereqURL b /teamcity/app/agents/v1/commands/next
> - 9 BereqProtocol b HTTP/1.1
> - 9 BereqHeader b TeamCity-AgentSessionId:
> L6juFAAt1awJDt6UKToPIxQq7wpBF89C
> - 9 BereqHeader b User-Agent: TeamCity Agent 2021.2.3
> - 9 BereqHeader b Host: vmachine.example.com
> - 9 BereqHeader b Via: 1.1 vmachine (Varnish/7.2)
> - 9 BereqHeader b Scheme: https
> - 9 BereqHeader b ssl-version: TLSv1.3
> - 9 BereqHeader b X-Forwarded-Proto: https
> - 9 BereqHeader b X-SSL-cipher: TLS_AES_256_GCM_SHA384
> - 9 BereqHeader b X-Forwarded-For: 192.168.2.112
> - 9 BereqHeader b X-Varnish: 9
> - 9 VCL_call b BACKEND_FETCH
> - 9 VCL_return b fetch
> - 9 Timestamp b Fetch: 1681484803.177227 0.000014 0.000014
> - 9 Timestamp b Connected: 1681484803.177603 0.000390
> 0.000375
> - 9 BackendOpen b 24 teamcity
> 2a01:xxxx:xxxx:xxxx:xxxx:xxxx:xxxx:xxxx 8111 2a01:yyyy:yyyy:yyyy::yyyy
> 59548 connect
> - 9 Timestamp b Bereq: 1681484803.177645 0.000432 0.000042
> - 9 BerespReason b No Content
> - 9 Timestamp b Beresp: 1681484830.672487 27.495274
> 27.494842
> - 9 BerespProtocol b HTTP/1.1
> - 9 BerespStatus b 204
> - 9 BerespReason b No Content
> - 9 BerespHeader b TeamCity-Node-Id: MAIN_SERVER
> - 9 BerespHeader b Date: Fri, 14 Apr 2023 15:07:10 GMT
> - 9 VCL_call b BACKEND_RESPONSE
> - 9 BerespHeader b Connection: close
> - 9 VCL_return b deliver
> - 9 Timestamp b Process: 1681484830.672563 27.495350
> 0.000075
> - 9 Filters b
> - 9 Storage b malloc Transient
> - 9 Fetch_Body b 0 none -
> - 9 BackendClose b 24 teamcity close Backend/VCL requested
> close
> - 9 Timestamp b BerespBody: 1681484830.672926 27.495713
> 0.000362
> - 9 Length b 0
> - 9 BereqAcct b 345 0 345 85 0 85
> - 9 End b
>
>
>
>
> Enjoy
>
> Jakob
> --
> Jakob Bohm, CIO, Partner, WiseMo A/S. https://www.wisemo.com
> Transformervej 29, 2860 Søborg, Denmark. Direct +45 31 13 16 10
> This public discussion message is non-binding and may contain errors.
> WiseMo - Remote Service Management for PCs, Phones and Embedded
>
> _______________________________________________
> varnish-misc mailing list
> varnish-misc@varnish-cache.org
> https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc
>
Re: Mysterious no content result, from an URL with pass action [ In reply to ]
jb-varnish at wisemo
May 10, 2023, 1:43 AM
Post #3 of 6 (449 views)
Permalink
On 2023-05-10 06:49, Guillaume Quintard wrote:
> Hi Jakob,
>
> (Sorry i didn't see that email sooner, it was in my spam folder)
>
> Looking at the log, I'm not sure what varnish should be loud about :-)
> 204 is a success code, and more importantly it's generated by the
> backend, so varnish is happily passing it along.
>
> At the http level, everything looks about right, but I can guess from
> your apparent irritation that something wrong one level up, let's try to
> debug that.
>
> What kind of response are you expecting, if not a 204? And maybe, what
> is that endpoint supposed to do? Given that the method was GET, and that
> there's no body, my only guess is that there's something happening with
> the TeamCity-AgentSessionId header, maybe?
> Is the 27 seconds processing time expected?
>

Expecting uncachable results that vary with time and are only sometimes
204, and the response time is also somewhat unexpected, but is not
clearly logged (only a Varnish expert like you can decrypt that it is 27
seconds). It is also unclear if Varnish is always receiving those
responses from the backend.

I also expected some other URLs in the log, but don't see them.

Maybe I should find another day to run the experiments again.

> Cheers,
>
> On Tue, May 9, 2023, 15:12 Jakob Bohm <jb-varnish@wisemo.com
> <mailto:jb-varnish@wisemo.com>> wrote:
>
> Dear Varnish mailing list,
>
> When testing varnish as a reverse proxy for multiple services
> including a local JetBrains TeamCity instance, requests to that
> teamcity server get corrupted into "204 No Content" replies.
>
> Once again, Varnish fails to say why it is refusing to do its job.
> Any sane program should explicitly and loudly report any fatal error
> that stops it working.  Loudly means the sysadmin or other user
> invoking the program receives the exaxt error message by default
> instead of something highly indirect, hidden behind a debug option
> or otherwisse highly non-obvious.
>
> Here's a relevant clip from the VCL:
>
> # Various top comments
> vcl 4.1;
>
> import std;
> import proxy;
>
> # Backend sending requests to the teamcity main server
> backend teamcity {
>      .host = "2a01:xxxx:xxxx:xxxx:xxxx:xxxx:xxxx:xxxx";
>      .port = "8111";
> }
>
> # IP ranges allowed to access the build server and staging server
> acl buildtrust {
>      "127.0.0.0"/8;
>      "::"/128;
>      "various others"/??;
> }
>
> # IP ranges allowed to attempt login to things that use our common login
> #    database
> acl logintrust {
>      "various others"/??;
> }
>
> sub vcl_recv {
>      # Happens before we check if we have this in cache already.
>      #
>      # Typically you clean up the request here, removing cookies you
> don't need,
>      # rewriting the request, etc.
>      if (proxy.is_ssl()) {
>          set req.http.Scheme = "https";
>          set req.http.ssl-version = proxy.ssl_version();
>          set req.http.X-Forwarded-Proto = "https";
>          set req.http.X-SSL-cipher = proxy.ssl_cipher();
>          std.log("TLS-SSL-VERSION: " + proxy.ssl_version());
>      } else {
>          set req.http.X-Forwarded-Proto = req.http.Scheme;
>          unset req.http.ssl-version;
>          unset req.http.X-SSL-cipher;
>          std.log("TLS-SSL-VERSION: none");
>      }
>      unset req.http.X-SSL-Subject;
>      unset req.http.X-SSL-Issuer;
>      unset req.http.X-SSL-notBefore;
>      unset req.http.X-SSL-notAfter;
>      unset req.http.X-SSL-serial;
>      unset req.http.X-SSL-certificate;
>
>      set req.http.X-Forwarded-For = client.ip;
>
>      call vcl_req_host;
>
>      if (req.url ~ "^/something") {
>          set req.backend_hint = be1;
>      } else if (req.url !~ "^/somethingelse" &&
>                 !(client.ip ~ logintrust) &&
>                 !(client.ip ~ buildtrust)) {
>          # Treat as unknown by redirecting to public website
>          if ((req.url ~ "^/yeatanother") ||
>              (req.url ~ "^/yetsomeother")) {
>              return (synth(752));
>          } else if (req.url ~ "^/yetsomethird") {
>              return (synth(753));
>          }
>          return (synth(751));
>      } else if (req.http.Scheme && req.http.Scheme != "https") {
>          # See example at
> https://www.varnish-software.com/developers/tutorials/redirect/
>          return (synth(750));
>      } else if (req.url ~ "^/somethingelse") {
>          set req.backend_hint = be1;
>      } else if (req.url ~ "^/somethingfourth") {
>          set req.backend_hint = be2;
>      } else if (req.url ~ "^/somethingfifth") {
>          set req.backend_hint = be2;
>      } else if (!(client.ip ~ buildtrust)) {
>          # Treat as unknown by redirecting to public website
>          if ((req.url ~ "^/yeatanother") ||
>              (req.url ~ "^/yetsomeother")) {
>              return (synth(752));
>          } else if (req.url ~ "^/yetsomethird") {
>              return (synth(753));
>          }
>          return (synth(751));
>      } else if (req.url ~ "^/teamcity") {
>          set req.backend_hint= teamcity;
>          return (pass);
> #    } else if (req.http.host ~ "^somethingsixths") {
> #       set req.backend_hint= be4;
>      } else {
>          set req.backend_hint = be5;
>      }
>      call vcl_req_method;
>      call vcl_req_authorization;
>      call vcl_req_cookie;
>      return (hash);
> }
>
> sub vcl_backend_response {
>      # Happens after we have read the response headers from the
> backend.
>      #
>      # Here you clean the response headers, removing silly Set-Cookie
> headers
>      # and other mistakes your backend does.
>
>      # The Java webserver in teamcity is incompatible with varnish
> connection
>      #    pooling
>      if (beresp.backend == teamcity) {
>          if (beresp.http.Connection &&
>              beresp.http.Connection !~ "keep-alive") {
>              set beresp.http.Connection += ", close";
>          } else {
>              set beresp.http.Connection = "close";
>          }
>      }
> }
>
> +++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
> First 43 lines of varnishlog -v 2>&1
>
> *              << BeReq    >>   9
> -            9 Begin          b bereq 8 pass
> -            9 VCL_use        b boot
> -            9 Timestamp      b Start: 1681484803.177212 0.000000
> 0.000000
> -            9 BereqMethod    b GET
> -            9 BereqURL       b /teamcity/app/agents/v1/commands/next
> -            9 BereqProtocol  b HTTP/1.1
> -            9 BereqHeader    b TeamCity-AgentSessionId:
> L6juFAAt1awJDt6UKToPIxQq7wpBF89C
> -            9 BereqHeader    b User-Agent: TeamCity Agent 2021.2.3
> -            9 BereqHeader    b Host: vmachine.example.com
> <http://vmachine.example.com>
> -            9 BereqHeader    b Via: 1.1 vmachine (Varnish/7.2)
> -            9 BereqHeader    b Scheme: https
> -            9 BereqHeader    b ssl-version: TLSv1.3
> -            9 BereqHeader    b X-Forwarded-Proto: https
> -            9 BereqHeader    b X-SSL-cipher: TLS_AES_256_GCM_SHA384
> -            9 BereqHeader    b X-Forwarded-For: 192.168.2.112
> -            9 BereqHeader    b X-Varnish: 9
> -            9 VCL_call       b BACKEND_FETCH
> -            9 VCL_return     b fetch
> -            9 Timestamp      b Fetch: 1681484803.177227 0.000014
> 0.000014
> -            9 Timestamp      b Connected: 1681484803.177603 0.000390
> 0.000375
> -            9 BackendOpen    b 24 teamcity
> 2a01:xxxx:xxxx:xxxx:xxxx:xxxx:xxxx:xxxx 8111 2a01:yyyy:yyyy:yyyy::yyyy
> 59548 connect
> -            9 Timestamp      b Bereq: 1681484803.177645 0.000432
> 0.000042
> -            9 BerespReason   b No Content
> -            9 Timestamp      b Beresp: 1681484830.672487 27.495274
> 27.494842
> -            9 BerespProtocol b HTTP/1.1
> -            9 BerespStatus   b 204
> -            9 BerespReason   b No Content
> -            9 BerespHeader   b TeamCity-Node-Id: MAIN_SERVER
> -            9 BerespHeader   b Date: Fri, 14 Apr 2023 15:07:10 GMT
> -            9 VCL_call       b BACKEND_RESPONSE
> -            9 BerespHeader   b Connection: close
> -            9 VCL_return     b deliver
> -            9 Timestamp      b Process: 1681484830.672563 27.495350
> 0.000075
> -            9 Filters        b
> -            9 Storage        b malloc Transient
> -            9 Fetch_Body     b 0 none -
> -            9 BackendClose   b 24 teamcity close Backend/VCL requested
> close
> -            9 Timestamp      b BerespBody: 1681484830.672926 27.495713
> 0.000362
> -            9 Length         b 0
> -            9 BereqAcct      b 345 0 345 85 0 85
> -            9 End            b
>



Enjoy

Jakob
--
Jakob Bohm, CIO, Partner, WiseMo A/S. https://www.wisemo.com
Transformervej 29, 2860 Søborg, Denmark. Direct +45 31 13 16 10
This public discussion message is non-binding and may contain errors.
WiseMo - Remote Service Management for PCs, Phones and Embedded
_______________________________________________
varnish-misc mailing list
varnish-misc@varnish-cache.org
https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc
Re: Mysterious no content result, from an URL with pass action [ In reply to ]
guillaume.quintard at gmail
May 11, 2023, 12:26 PM
Post #4 of 6 (448 views)
Permalink
On Tue, May 9, 2023, 22:45 Jakob Bohm <jb-varnish@wisemo.com> wrote:

> Expecting uncachable results that vary with time and are only sometimes
> 204,


Understood, but that one looks like a backend issue. Also, just to be
clear, the response is uncatchable because the back looked at the url and
deemed the request wouldn't lead to cacheable content, so we knew the
response would be uncatchable before even contacting the backend

and the response time is also somewhat unexpected, but is not
> clearly logged (only a Varnish expert like you can decrypt that it is 27
> seconds).


To be fair, varnishlog's goal is just to provide all the info it can, in an
unopinionated matter. The fact that the response took a long time may or
may not be normal, so there's no reason for varnishlog to fret about it,
and it doesn't necessarily know either what duration you are interested in,
so it gives them all)
For anyone reading along and trying to make sense of the Timestamp lines:
https://varnish-cache.org/docs/6.0/reference/vsl.html#timestamps

Note that varnisncsa would have probably been more concise and maybe useful
to check the timing.

It is also unclear if Varnish is always receiving those
> responses from the backend.
>

As a rule of thumb, by default, varnish only generates 503s in case of an
error (your VCL can also generate other errors, but then you are expected
to know about that).

A quick way to tag the transport-level error that varnish will generate on
the backend side it to have this in your VCL:

``` vcl
sub vcl_backend_error {
set beresp.http.is-a-varnish-error = "true";
}

>
> I also expected some other URLs in the log, but don't see them.
>

You could maybe log more, on disk, and filter for the urls you care about?
If that's not what you are already doing?

This page might help: https://docs.varnish-software.com/tutorials/vsl-query/

Hope that helps!

>
Re: Mysterious no content result, from an URL with pass action [ In reply to ]
jb-varnish at wisemo
Jun 6, 2023, 5:05 AM
Post #5 of 6 (423 views)
Permalink
Hi all,

Just a quick update,

After changing the hitch to varnish connection from AF_UNIX to TCP,
rerunning the experiment with tcpdump active revealed that varnish
7.2.1 seemed to silently ignore HTTP/2 requests whenever my browser
chose that over HTTP/1.x .  Turning off HTTP/2 in hitch seems to
make things work.

I'm still surprised that varnishd drops HTTP/2 over proxyv2 silently
with no logging that a connection was dropped, and in such a way that
web browsers interpret it as an empty page.  Feels very similar to
my earlier issue that failure to bind to a specified listen address
was not shown to the sysadmin starting varnishd .

Now it's time to upgrade to 7.3.0 and improve the configuration.


On 2023-05-10 10:43, Jakob Bohm wrote:
> On 2023-05-10 06:49, Guillaume Quintard wrote:
>> Hi Jakob,
>>
>> (Sorry i didn't see that email sooner, it was in my spam folder)
>>
>> Looking at the log, I'm not sure what varnish should be loud about :-)
>> 204 is a success code, and more importantly it's generated by the
>> backend, so varnish is happily passing it along.
>>
>> At the http level, everything looks about right, but I can guess from
>> your apparent irritation that something wrong one level up, let's try
>> to debug that.
>>
>> What kind of response are you expecting, if not a 204? And maybe,
>> what is that endpoint supposed to do? Given that the method was GET,
>> and that there's no body, my only guess is that there's something
>> happening with the TeamCity-AgentSessionId header, maybe?
>> Is the 27 seconds processing time expected?
>>
>
> Expecting uncachable results that vary with time and are only
> sometimes 204, and the response time is also somewhat unexpected, but
> is not clearly logged (only a Varnish expert like you can decrypt that
> it is 27 seconds).  It is also unclear if Varnish is always receiving
> those responses from the backend.
>
> I also expected some other URLs in the log, but don't see them.
>
> Maybe I should find another day to run the experiments again.
>
>> Cheers,
>>
>> On Tue, May 9, 2023, 15:12 Jakob Bohm <jb-varnish@wisemo.com
>> <mailto:jb-varnish@wisemo.com>> wrote:
>>
>>     Dear Varnish mailing list,
>>
>>     When testing varnish as a reverse proxy for multiple services
>>     including a local JetBrains TeamCity instance, requests to that
>>     teamcity server get corrupted into "204 No Content" replies.
>>
>>     Once again, Varnish fails to say why it is refusing to do its job.
>>     Any sane program should explicitly and loudly report any fatal error
>>     that stops it working.  Loudly means the sysadmin or other user
>>     invoking the program receives the exaxt error message by default
>>     instead of something highly indirect, hidden behind a debug option
>>     or otherwisse highly non-obvious.
>>
>>     Here's a relevant clip from the VCL:
>>
>>     # Various top comments
>>     vcl 4.1;
>>
>>     import std;
>>     import proxy;
>>
>>     # Backend sending requests to the teamcity main server
>>     backend teamcity {
>>           .host = "2a01:xxxx:xxxx:xxxx:xxxx:xxxx:xxxx:xxxx";
>>           .port = "8111";
>>     }
>>
>>     # IP ranges allowed to access the build server and staging server
>>     acl buildtrust {
>>           "127.0.0.0"/8;
>>           "::"/128;
>>           "various others"/??;
>>     }
>>
>>     # IP ranges allowed to attempt login to things that use our
>> common login
>>     #    database
>>     acl logintrust {
>>           "various others"/??;
>>     }
>>
>>     sub vcl_recv {
>>           # Happens before we check if we have this in cache already.
>>           #
>>           # Typically you clean up the request here, removing cookies
>> you
>>     don't need,
>>           # rewriting the request, etc.
>>           if (proxy.is_ssl()) {
>>               set req.http.Scheme = "https";
>>               set req.http.ssl-version = proxy.ssl_version();
>>               set req.http.X-Forwarded-Proto = "https";
>>               set req.http.X-SSL-cipher = proxy.ssl_cipher();
>>               std.log("TLS-SSL-VERSION: " + proxy.ssl_version());
>>           } else {
>>               set req.http.X-Forwarded-Proto = req.http.Scheme;
>>               unset req.http.ssl-version;
>>               unset req.http.X-SSL-cipher;
>>               std.log("TLS-SSL-VERSION: none");
>>           }
>>           unset req.http.X-SSL-Subject;
>>           unset req.http.X-SSL-Issuer;
>>           unset req.http.X-SSL-notBefore;
>>           unset req.http.X-SSL-notAfter;
>>           unset req.http.X-SSL-serial;
>>           unset req.http.X-SSL-certificate;
>>
>>           set req.http.X-Forwarded-For = client.ip;
>>
>>           call vcl_req_host;
>>
>>           if (req.url ~ "^/something") {
>>               set req.backend_hint = be1;
>>           } else if (req.url !~ "^/somethingelse" &&
>>                      !(client.ip ~ logintrust) &&
>>                      !(client.ip ~ buildtrust)) {
>>               # Treat as unknown by redirecting to public website
>>               if ((req.url ~ "^/yeatanother") ||
>>                   (req.url ~ "^/yetsomeother")) {
>>                   return (synth(752));
>>               } else if (req.url ~ "^/yetsomethird") {
>>                   return (synth(753));
>>               }
>>               return (synth(751));
>>           } else if (req.http.Scheme && req.http.Scheme != "https") {
>>               # See example at
>> https://www.varnish-software.com/developers/tutorials/redirect/
>>               return (synth(750));
>>           } else if (req.url ~ "^/somethingelse") {
>>               set req.backend_hint = be1;
>>           } else if (req.url ~ "^/somethingfourth") {
>>               set req.backend_hint = be2;
>>           } else if (req.url ~ "^/somethingfifth") {
>>               set req.backend_hint = be2;
>>           } else if (!(client.ip ~ buildtrust)) {
>>               # Treat as unknown by redirecting to public website
>>               if ((req.url ~ "^/yeatanother") ||
>>                   (req.url ~ "^/yetsomeother")) {
>>                   return (synth(752));
>>               } else if (req.url ~ "^/yetsomethird") {
>>                   return (synth(753));
>>               }
>>               return (synth(751));
>>           } else if (req.url ~ "^/teamcity") {
>>               set req.backend_hint= teamcity;
>>               return (pass);
>>     #    } else if (req.http.host ~ "^somethingsixths") {
>>     #       set req.backend_hint= be4;
>>           } else {
>>               set req.backend_hint = be5;
>>           }
>>           call vcl_req_method;
>>           call vcl_req_authorization;
>>           call vcl_req_cookie;
>>           return (hash);
>>     }
>>
>>     sub vcl_backend_response {
>>           # Happens after we have read the response headers from the
>>     backend.
>>           #
>>           # Here you clean the response headers, removing silly
>> Set-Cookie
>>     headers
>>           # and other mistakes your backend does.
>>
>>           # The Java webserver in teamcity is incompatible with varnish
>>     connection
>>           #    pooling
>>           if (beresp.backend == teamcity) {
>>               if (beresp.http.Connection &&
>>                   beresp.http.Connection !~ "keep-alive") {
>>                   set beresp.http.Connection += ", close";
>>               } else {
>>                   set beresp.http.Connection = "close";
>>               }
>>           }
>>     }
>>
>> +++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
>>     First 43 lines of varnishlog -v 2>&1
>>
>>     *              << BeReq    >>   9
>>     -            9 Begin          b bereq 8 pass
>>     -            9 VCL_use        b boot
>>     -            9 Timestamp      b Start: 1681484803.177212 0.000000
>>     0.000000
>>     -            9 BereqMethod    b GET
>>     -            9 BereqURL       b
>> /teamcity/app/agents/v1/commands/next
>>     -            9 BereqProtocol  b HTTP/1.1
>>     -            9 BereqHeader    b TeamCity-AgentSessionId:
>>     L6juFAAt1awJDt6UKToPIxQq7wpBF89C
>>     -            9 BereqHeader    b User-Agent: TeamCity Agent 2021.2.3
>>     -            9 BereqHeader    b Host: vmachine.example.com
>>     <http://vmachine.example.com>
>>     -            9 BereqHeader    b Via: 1.1 vmachine (Varnish/7.2)
>>     -            9 BereqHeader    b Scheme: https
>>     -            9 BereqHeader    b ssl-version: TLSv1.3
>>     -            9 BereqHeader    b X-Forwarded-Proto: https
>>     -            9 BereqHeader    b X-SSL-cipher: TLS_AES_256_GCM_SHA384
>>     -            9 BereqHeader    b X-Forwarded-For: 192.168.2.112
>>     -            9 BereqHeader    b X-Varnish: 9
>>     -            9 VCL_call       b BACKEND_FETCH
>>     -            9 VCL_return     b fetch
>>     -            9 Timestamp      b Fetch: 1681484803.177227 0.000014
>>     0.000014
>>     -            9 Timestamp      b Connected: 1681484803.177603
>> 0.000390
>>     0.000375
>>     -            9 BackendOpen    b 24 teamcity
>>     2a01:xxxx:xxxx:xxxx:xxxx:xxxx:xxxx:xxxx 8111
>> 2a01:yyyy:yyyy:yyyy::yyyy
>>     59548 connect
>>     -            9 Timestamp      b Bereq: 1681484803.177645 0.000432
>>     0.000042
>>     -            9 BerespReason   b No Content
>>     -            9 Timestamp      b Beresp: 1681484830.672487 27.495274
>>     27.494842
>>     -            9 BerespProtocol b HTTP/1.1
>>     -            9 BerespStatus   b 204
>>     -            9 BerespReason   b No Content
>>     -            9 BerespHeader   b TeamCity-Node-Id: MAIN_SERVER
>>     -            9 BerespHeader   b Date: Fri, 14 Apr 2023 15:07:10 GMT
>>     -            9 VCL_call       b BACKEND_RESPONSE
>>     -            9 BerespHeader   b Connection: close
>>     -            9 VCL_return     b deliver
>>     -            9 Timestamp      b Process: 1681484830.672563 27.495350
>>     0.000075
>>     -            9 Filters        b
>>     -            9 Storage        b malloc Transient
>>     -            9 Fetch_Body     b 0 none -
>>     -            9 BackendClose   b 24 teamcity close Backend/VCL
>> requested
>>     close
>>     -            9 Timestamp      b BerespBody: 1681484830.672926
>> 27.495713
>>     0.000362
>>     -            9 Length         b 0
>>     -            9 BereqAcct      b 345 0 345 85 0 85
>>     -            9 End            b
>>
Enjoy

Jakob
--
Jakob Bohm, CIO, Partner, WiseMo A/S. https://www.wisemo.com
Transformervej 29, 2860 Søborg, Denmark. Direct +45 31 13 16 10
This public discussion message is non-binding and may contain errors.
WiseMo - Remote Service Management for PCs, Phones and Embedded

_______________________________________________
varnish-misc mailing list
varnish-misc@varnish-cache.org
https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc
Re: Mysterious no content result, from an URL with pass action [ In reply to ]
dridi at varni
Jun 6, 2023, 8:08 AM
Post #6 of 6 (422 views)
Permalink
On Tue, Jun 6, 2023 at 12:07?PM Jakob Bohm <jb-varnish@wisemo.com> wrote:
>
> Hi all,
>
> Just a quick update,
>
> After changing the hitch to varnish connection from AF_UNIX to TCP,
> rerunning the experiment with tcpdump active revealed that varnish
> 7.2.1 seemed to silently ignore HTTP/2 requests whenever my browser
> chose that over HTTP/1.x . Turning off HTTP/2 in hitch seems to
> make things work.
>
> I'm still surprised that varnishd drops HTTP/2 over proxyv2 silently
> with no logging that a connection was dropped, and in such a way that
> web browsers interpret it as an empty page. Feels very similar to
> my earlier issue that failure to bind to a specified listen address
> was not shown to the sysadmin starting varnishd .

Did you enable http2 support?

https://varnish-cache.org/docs/7.2/reference/varnishd.html#feature

I don't like the idea that we silently close sessions, could you
please open a github issue explaining what you observe and how to
reproduce it?

> Now it's time to upgrade to 7.3.0 and improve the configuration.

I don't think we improved anything in that area in the 7.3.0 release.

Dridi
_______________________________________________
varnish-misc mailing list
varnish-misc@varnish-cache.org
https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc

©2024 GT.net. A Gossamer Threads company.
5th Floor, 455 Granville St., Vancouver, BC V6C 1T1, Canada | Legal