Mailing List Archive: logoutput from r1667

logoutput from r1667

Jul 11, 2007, 3:28 PM

Post #1 of 5 (986 views)

Hi

here a logoutput from r1667 with default VCL:

(look at the age header and the http at the end)

12 SessionOpen c 66.249.65.83 36289
12 Debug c /Kategorien/0/Suche?&o=i#212.202.251.212#
12 ReqStart c 66.249.65.83 36289 1350902493
12 RxRequest c GET
12 RxURL c /Kategorien/0/Suche?&o=i
12 RxProtocol c HTTP/1.1
12 RxHeader c Host: 212.202.251.212
12 RxHeader c Connection: Keep-alive
12 RxHeader c User-Agent: Mediapartners-Google/2.1
12 RxHeader c Accept-Encoding: gzip
12 VCL_call c recv lookup
12 VCL_call c hash hash
12 VCL_call c miss fetch
12 Backend c 13 default
12 ObjProtocol c HTTP/1.1
12 ObjStatus c 200
12 ObjResponse c OK
12 ObjHeader c Server: ZenoServer/1.6.10 * DBSERVER/r441 *
Middleware/277
12 ObjHeader c Vary: Accept-Encoding
12 ObjHeader c Date: Wed, 11 Jul 2007 22:16:47 GMT
12 ObjHeader c Content-Encoding: gzip
12 ObjHeader c Content-Type: text/html
12 ObjHeader c Cache-Control: s-maxage=300, max-age=120
12 ObjHeader c Last-Modified: Tue, 10 Jul 2007 15:02:36 GMT
12 TTL c 1350902493 RFC 300 1184192207 1184192207 0 300 0
12 VCL_call c fetch insert
12 Length c 1749
12 VCL_call c deliver deliver
12 TxProtocol c HTTP/1.1
12 TxStatus c 200
12 TxResponse c OK
12 TxHeader c Server: ZenoServer/1.6.10 * DBSERVER/r441 *
Middleware/277
12 TxHeader c Vary: Accept-Encoding
12 TxHeader c Date: Wed, 11 Jul 2007 22:16:47 GMT
12 TxHeader c Content-Encoding: gzip
12 TxHeader c Content-Type: text/html
12 TxHeader c Cache-Control: s-maxage=300, max-age=120
12 TxHeader c Last-Modified: Tue, 10 Jul 2007 15:02:36 GMT
12 TxHeader c Content-Length: 1749
12 TxHeader c X-Varnish: 1350902493
12 TxHeader c Age: 3110775089
12 TxHeader c Via: 1.1 varnish
12 ReqEnd c 1350902493 1184192207.808972096
1184192207.820660509 0.001130623 0.011668019 0.000020394

11 SessionOpen c 66.249.65.83 36244
11 HttpError c Received errno 35
11 SessionClose c silent
11 ReqEnd c 0 1184192211.804295053 1184192211.804295053
5.047401098 0.000000000 0.000000000

Host is a FreeBSD 6.2p3 system

logoutput from r1667 [ In reply to ]

phk at phk

Jul 11, 2007, 3:30 PM

Post #2 of 5 (951 views)

Permalink

In message <16367464-71EA-4233-9348-241363049866 at zeno.org>, Denis Ahrens writes
:
>Hi
>
>here a logoutput from r1667 with default VCL:

Can I get you to check your clock relative to the backend ?

--
Poul-Henning Kamp | UNIX since Zilog Zeus 3.20
phk at FreeBSD.ORG | TCP/IP since RFC 956
FreeBSD committer | BSD since 4.3-tahoe
Never attribute to malice what can adequately be explained by incompetence.

logoutput from r1667 [ In reply to ]

denis at zeno

Jul 11, 2007, 3:36 PM

Post #3 of 5 (953 views)

Permalink

logoutput from r1667 [ In reply to ]

denis at zeno

Jul 11, 2007, 5:53 PM

Post #4 of 5 (956 views)

Permalink

On 12.07.2007, at 00:30, Poul-Henning Kamp wrote:

> In message <16367464-71EA-4233-9348-241363049866 at zeno.org>, Denis
> Ahrens writes
> :
>> Hi
>>
>> here a logoutput from r1667 with default VCL:
>
> Can I get you to check your clock relative to the backend ?

Ok, I (ok, actually it was saite) made a patch to show
the actual problem:

before changeset r1639

RES_WriteObj() was responsible for setting t_resp and the output of
the "Age:" header

after changeset r1639

RES_BuildHTTP() sometimes uses sp->t_resp uninitialized.

Index: bin/varnishd/cache_response.c
===================================================================
--- bin/varnishd/cache_response.c (revision 1667)
+++ bin/varnishd/cache_response.c (working copy)
@@ -134,6 +134,11 @@
else
http_PrintfHeader(sp->wrk, sp->fd, sp->http,
"X-Varnish: %u", sp->xid);
+ if (!sp->t_resp.tv_sec)
+ {
+ http_PrintfHeader(sp->wrk, sp->fd, sp->http, "DEBUG: reorder
problem occured: sp->t_resp.tv_sec is 0");
+ clock_gettime(CLOCK_REALTIME, &sp->t_resp);
+ }
http_PrintfHeader(sp->wrk, sp->fd, sp->http, "Age: %u",
sp->obj->age + sp->t_resp.tv_sec - sp->obj->entered);
http_SetHeader(sp->wrk, sp->fd, sp->http, "Via: 1.1 varnish");

Denis

logoutput from r1667 [ In reply to ]

phk at phk

Jul 13, 2007, 12:58 AM

Post #5 of 5 (959 views)

Permalink

This should be fixed now.

Poul-Henning

In message <1CD232AD-B501-49DA-8B3A-7ED50E0A5C37 at zeno.org>, Denis Ahrens writes
:
>
>On 12.07.2007, at 00:30, Poul-Henning Kamp wrote:
>
>> In message <16367464-71EA-4233-9348-241363049866 at zeno.org>, Denis
>> Ahrens writes
>> :
>>> Hi
>>>
>>> here a logoutput from r1667 with default VCL:
>>
>> Can I get you to check your clock relative to the backend ?
>
>Ok, I (ok, actually it was saite) made a patch to show
>the actual problem:
>
>before changeset r1639
>
>RES_WriteObj() was responsible for setting t_resp and the output of
>the "Age:" header
>
>after changeset r1639
>
>RES_BuildHTTP() sometimes uses sp->t_resp uninitialized.
>
>Index: bin/varnishd/cache_response.c
>===================================================================
>--- bin/varnishd/cache_response.c (revision 1667)
>+++ bin/varnishd/cache_response.c (working copy)
>@@ -134,6 +134,11 @@
> else
> http_PrintfHeader(sp->wrk, sp->fd, sp->http,
> "X-Varnish: %u", sp->xid);
>+ if (!sp->t_resp.tv_sec)
>+ {
>+ http_PrintfHeader(sp->wrk, sp->fd, sp->http, "DEBUG: reorder
>problem occured: sp->t_resp.tv_sec is 0");
>+ clock_gettime(CLOCK_REALTIME, &sp->t_resp);
>+ }
> http_PrintfHeader(sp->wrk, sp->fd, sp->http, "Age: %u",
> sp->obj->age + sp->t_resp.tv_sec - sp->obj->entered);
> http_SetHeader(sp->wrk, sp->fd, sp->http, "Via: 1.1 varnish");
>
>Denis
>
>_______________________________________________
>varnish-misc mailing list
>varnish-misc at projects.linpro.no
>http://projects.linpro.no/mailman/listinfo/varnish-misc
>

--
Poul-Henning Kamp | UNIX since Zilog Zeus 3.20
phk at FreeBSD.ORG | TCP/IP since RFC 956
FreeBSD committer | BSD since 4.3-tahoe
Never attribute to malice what can adequately be explained by incompetence.