Mailing List Archive: Reg: printing ReqURL two times in varnishlog

Reg: printing ReqURL two times in varnishlog

Mar 2, 2019, 12:43 AM

Post #1 of 4 (648 views)

Hi Team,

we can see ReqURL is getting printed twice in varnish shm and so in
varnishlog. It is causing problems while processing this logs further. some
time it is very big URL and have parse twice. Is it possible to make it
print only once. or any other work around ?

** << Request >> 313464548
-- Begin req 313464547 rxreq
-- Timestamp Start: 1548836427.883183 0.000000 0.000000
-- Timestamp Req: 1548836427.883183 0.000000 0.000000
-- ReqStart 127.0.0.1 16962 a3
-- ReqMethod GET
*-- ReqURL /abc/xyz/image.jpeg*
-- ReqProtocol HTTP/1.1
-- ReqHeader X-Forwarded-For: x.x.x.x
-- ReqHeader Host: aaa
-- ReqHeader Connection: close
-- ReqHeader accept: */*
-- ReqHeader x-playback-session-id: xyz
-- ReqHeader user-agent: AppleCoreMedia/1.0.0.16C101 (iPhone; U; CPU
OS 12_1_2 like Mac OS X; en_us)
-- ReqHeader accept-language: en-us
-- ReqHeader accept-encoding: identity
-- ReqHeader cookie: dtCookie==xyz
-- ReqUnset X-Forwarded-For: x.x.x.x
-- ReqHeader X-Forwarded-For: x.x.x.x, 127.0.0.1
-- VCL_call RECV
-- VCL_Log x-xid:313464548
-- VCL_Log req-source:Client
*-- ReqURL /abc/xyz/image.jpeg*
-- ReqHeader X-VCL-Host: aaa
-- VCL_Log checking aaa
-- ReqHeader aaa

Waiting for reply. Thank you in Advance.

- Hardik

Re: Reg: printing ReqURL two times in varnishlog [ In reply to ]

guillaume at varnish-software

Mar 2, 2019, 3:00 AM

Post #2 of 4 (648 views)

Permalink

ReqURL gets printed every time you set req.url, so unless you don't modify
it, you will have multiple lines.

To be fair, it looks like this is an issue with your log parser. Just
ignore those lines if you've already seen one and you're done.

On Fri, Mar 1, 2019, 22:47 Hardik <hetardik.p@gmail.com> wrote:

> Hi Team,
>
> we can see ReqURL is getting printed twice in varnish shm and so in
> varnishlog. It is causing problems while processing this logs further. some
> time it is very big URL and have parse twice. Is it possible to make it
> print only once. or any other work around ?
>
> ** << Request >> 313464548
> -- Begin req 313464547 rxreq
> -- Timestamp Start: 1548836427.883183 0.000000 0.000000
> -- Timestamp Req: 1548836427.883183 0.000000 0.000000
> -- ReqStart 127.0.0.1 16962 a3
> -- ReqMethod GET
> *-- ReqURL /abc/xyz/image.jpeg*
> -- ReqProtocol HTTP/1.1
> -- ReqHeader X-Forwarded-For: x.x.x.x
> -- ReqHeader Host: aaa
> -- ReqHeader Connection: close
> -- ReqHeader accept: */*
> -- ReqHeader x-playback-session-id: xyz
> -- ReqHeader user-agent: AppleCoreMedia/1.0.0.16C101 (iPhone; U; CPU
> OS 12_1_2 like Mac OS X; en_us)
> -- ReqHeader accept-language: en-us
> -- ReqHeader accept-encoding: identity
> -- ReqHeader cookie: dtCookie==xyz
> -- ReqUnset X-Forwarded-For: x.x.x.x
> -- ReqHeader X-Forwarded-For: x.x.x.x, 127.0.0.1
> -- VCL_call RECV
> -- VCL_Log x-xid:313464548
> -- VCL_Log req-source:Client
> *-- ReqURL /abc/xyz/image.jpeg*
> -- ReqHeader X-VCL-Host: aaa
> -- VCL_Log checking aaa
> -- ReqHeader aaa
>
> Waiting for reply. Thank you in Advance.
>
> - Hardik
> _______________________________________________
> varnish-misc mailing list
> varnish-misc@varnish-cache.org
> https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc
>

Re: Reg: printing ReqURL two times in varnishlog [ In reply to ]

hetardik.p at gmail

Mar 6, 2019, 11:30 PM

Post #3 of 4 (644 views)

Permalink

Thank you Guillaume. we already planed to ignore that tag once its done in
parser as you mentioned.
Actually main reason behind asking this question was.. to use varnish shm
maximum. If we print req.url multiple times then it will occupy more space
in varnish shm. Correct me if i am wrong.

One more question I have regarding timestamp...
Timestamps related to Bereq are added in req Timestamps ( timers ) ?

Timestamp Fetch: 1548836428.021777 *0.138593* 0.138593
Timestamp Resp: 1548836428.070475 0.187292 0.048588

Timestamp BerespBody: 1548836428.070220 *0.186739* 0.048602

*As per above logs, we can see 0.138593* < *0.186739 but it should
>0.186739 in fetch timestamp right?*
*or req and bereq counters are totally different and no relation between
those ? Your comments will be really helpful.*

Thank you
Hardik

On Sat, 2 Mar 2019 at 16:31, Guillaume Quintard <
guillaume@varnish-software.com> wrote:

> ReqURL gets printed every time you set req.url, so unless you don't modify
> it, you will have multiple lines.
>
> To be fair, it looks like this is an issue with your log parser. Just
> ignore those lines if you've already seen one and you're done.
>
> On Fri, Mar 1, 2019, 22:47 Hardik <hetardik.p@gmail.com> wrote:
>
>> Hi Team,
>>
>> we can see ReqURL is getting printed twice in varnish shm and so in
>> varnishlog. It is causing problems while processing this logs further. some
>> time it is very big URL and have parse twice. Is it possible to make it
>> print only once. or any other work around ?
>>
>> ** << Request >> 313464548
>> -- Begin req 313464547 rxreq
>> -- Timestamp Start: 1548836427.883183 0.000000 0.000000
>> -- Timestamp Req: 1548836427.883183 0.000000 0.000000
>> -- ReqStart 127.0.0.1 16962 a3
>> -- ReqMethod GET
>> *-- ReqURL /abc/xyz/image.jpeg*
>> -- ReqProtocol HTTP/1.1
>> -- ReqHeader X-Forwarded-For: x.x.x.x
>> -- ReqHeader Host: aaa
>> -- ReqHeader Connection: close
>> -- ReqHeader accept: */*
>> -- ReqHeader x-playback-session-id: xyz
>> -- ReqHeader user-agent: AppleCoreMedia/1.0.0.16C101 (iPhone; U;
>> CPU OS 12_1_2 like Mac OS X; en_us)
>> -- ReqHeader accept-language: en-us
>> -- ReqHeader accept-encoding: identity
>> -- ReqHeader cookie: dtCookie==xyz
>> -- ReqUnset X-Forwarded-For: x.x.x.x
>> -- ReqHeader X-Forwarded-For: x.x.x.x, 127.0.0.1
>> -- VCL_call RECV
>> -- VCL_Log x-xid:313464548
>> -- VCL_Log req-source:Client
>> *-- ReqURL /abc/xyz/image.jpeg*
>> -- ReqHeader X-VCL-Host: aaa
>> -- VCL_Log checking aaa
>> -- ReqHeader aaa
>>
>> Waiting for reply. Thank you in Advance.
>>
>> - Hardik
>> _______________________________________________
>> varnish-misc mailing list
>> varnish-misc@varnish-cache.org
>> https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc
>>
>

Re: Reg: printing ReqURL two times in varnishlog [ In reply to ]

guillaume at varnish-software

Mar 7, 2019, 10:50 AM

Post #4 of 4 (644 views)

Permalink

The VSL is a circular buffer, so consuming more space only means you'll go
through it more quickly, usually not a big deal.

The Fetch timestamp means you have something to send, if streaming is on
(and it is by default), you can start sending well before the body is
completely processed.

--
Guillaume Quintard

On Wed, Mar 6, 2019 at 11:32 PM Hardik <hetardik.p@gmail.com> wrote:

> Thank you Guillaume. we already planed to ignore that tag once its done in
> parser as you mentioned.
> Actually main reason behind asking this question was.. to use varnish shm
> maximum. If we print req.url multiple times then it will occupy more space
> in varnish shm. Correct me if i am wrong.
>
> One more question I have regarding timestamp...
> Timestamps related to Bereq are added in req Timestamps ( timers ) ?
>
> Timestamp Fetch: 1548836428.021777 *0.138593* 0.138593
> Timestamp Resp: 1548836428.070475 0.187292 0.048588
>
> Timestamp BerespBody: 1548836428.070220 *0.186739* 0.048602
>
> *As per above logs, we can see 0.138593* < *0.186739 but it should
> >0.186739 in fetch timestamp right?*
> *or req and bereq counters are totally different and no relation between
> those ? Your comments will be really helpful.*
>
> Thank you
> Hardik
>
> On Sat, 2 Mar 2019 at 16:31, Guillaume Quintard <
> guillaume@varnish-software.com> wrote:
>
>> ReqURL gets printed every time you set req.url, so unless you don't
>> modify it, you will have multiple lines.
>>
>> To be fair, it looks like this is an issue with your log parser. Just
>> ignore those lines if you've already seen one and you're done.
>>
>> On Fri, Mar 1, 2019, 22:47 Hardik <hetardik.p@gmail.com> wrote:
>>
>>> Hi Team,
>>>
>>> we can see ReqURL is getting printed twice in varnish shm and so in
>>> varnishlog. It is causing problems while processing this logs further. some
>>> time it is very big URL and have parse twice. Is it possible to make it
>>> print only once. or any other work around ?
>>>
>>> ** << Request >> 313464548
>>> -- Begin req 313464547 rxreq
>>> -- Timestamp Start: 1548836427.883183 0.000000 0.000000
>>> -- Timestamp Req: 1548836427.883183 0.000000 0.000000
>>> -- ReqStart 127.0.0.1 16962 a3
>>> -- ReqMethod GET
>>> *-- ReqURL /abc/xyz/image.jpeg*
>>> -- ReqProtocol HTTP/1.1
>>> -- ReqHeader X-Forwarded-For: x.x.x.x
>>> -- ReqHeader Host: aaa
>>> -- ReqHeader Connection: close
>>> -- ReqHeader accept: */*
>>> -- ReqHeader x-playback-session-id: xyz
>>> -- ReqHeader user-agent: AppleCoreMedia/1.0.0.16C101 (iPhone; U;
>>> CPU OS 12_1_2 like Mac OS X; en_us)
>>> -- ReqHeader accept-language: en-us
>>> -- ReqHeader accept-encoding: identity
>>> -- ReqHeader cookie: dtCookie==xyz
>>> -- ReqUnset X-Forwarded-For: x.x.x.x
>>> -- ReqHeader X-Forwarded-For: x.x.x.x, 127.0.0.1
>>> -- VCL_call RECV
>>> -- VCL_Log x-xid:313464548
>>> -- VCL_Log req-source:Client
>>> *-- ReqURL /abc/xyz/image.jpeg*
>>> -- ReqHeader X-VCL-Host: aaa
>>> -- VCL_Log checking aaa
>>> -- ReqHeader aaa
>>>
>>> Waiting for reply. Thank you in Advance.
>>>
>>> - Hardik
>>> _______________________________________________
>>> varnish-misc mailing list
>>> varnish-misc@varnish-cache.org
>>> https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc
>>>
>>