Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add record-prefix to varnishncsa.(%{VSL}x) #2077

Closed
wants to merge 3 commits into from

Conversation

@xcir
Copy link
Contributor

@xcir xcir commented Sep 6, 2016

Current Version %{VSL}x formatter is only output the Start event in TimeStamp tag.
Can't get the Resp, Fetch...other event.
This PR supports record-prefix in %{VSL}x formatter.
Can select all event in TimeStamp tag.

Output sample

#Raw log
$ sudo /opt/trunk-varnish/bin/varnishlog -graw -itimestamp
     65542 Timestamp      c Start: 1473174473.455523 0.000000 0.000000
     65542 Timestamp      c Req: 1473174473.455523 0.000000 0.000000
     65542 Timestamp      c Fetch: 1473174473.456650 0.001127 0.001127
     65542 Timestamp      c Process: 1473174473.456665 0.001143 0.000015
     65542 Timestamp      c Resp: 1473174473.456773 0.001251 0.000108
     65545 Timestamp      c Start: 1473174507.979415 0.000000 0.000000
     65545 Timestamp      c Req: 1473174507.979415 0.000000 0.000000
     65545 Timestamp      c Process: 1473174507.979477 0.000063 0.000063
     65545 Timestamp      c Resp: 1473174507.979630 0.000215 0.000152

#patched varnishncsa
$ sudo /opt/trunk-varnish/bin/varnishncsa  -F "TimeStamp: %{VSL:TimeStamp}x\nTimpStamp[2]: %{VSL:TimeStamp[2]}x\nTimeStamp:Resp: %{VSL:TimeStamp:resp}x\nTimeStamp:Resp[2]: %{VSL:TimeStamp:resp[2]}x\nTitamp:foo: %{VSL:TimeStamp:foo}x\nvxid: %{Varnish:vxid}x\n------"
TimeStamp: Start: 1473174473.455523 0.000000 0.000000
TimpStamp[2]: 1473174473.455523
TimeStamp:Resp: 1473174473.456773 0.001251 0.000108
TimeStamp:Resp[2]: 0.001251
TimeStamp:foo: -
vxid: 65542
------
TimeStamp: Start: 1473174507.979415 0.000000 0.000000
TimpStamp[2]: 1473174507.979415
TimeStamp:Resp: 1473174507.979630 0.000215 0.000152
TimeStamp:Resp[2]: 0.000215
TimeStamp:foo: -
vxid: 65545
------
xcir added 3 commits Sep 5, 2016
%{VSL:tag:record-prefix[field]}x
@fgsch fgsch self-assigned this Oct 24, 2016
fgsch added a commit that referenced this pull request Apr 14, 2017
The parsing still requires some TLC but this does not make it any
worse so let's get this in first.

Prompted by and ideas from github::xcir via #2077.
@fgsch
Copy link
Member

@fgsch fgsch commented Apr 14, 2017

Thanks for the PR and apologies for taking so long to take some action on this.

I just committed support for this taking some ideas from your code.
Please give it a go and report any issues.

@fgsch fgsch closed this Apr 14, 2017
@xcir xcir deleted the xcir:feature/varnishncsa-vsl-record-prefix branch Apr 14, 2017
@JonathanHuot
Copy link
Contributor

@JonathanHuot JonathanHuot commented May 10, 2017

This PR is very useful for 4.1 branch, until this, we did custom modifications to varnishncsa, and it is more than welcome to have it mainstream.

@Dridi
Copy link
Member

@Dridi Dridi commented May 10, 2017

The backport label is still present so 396316b will be considered for a back-port. Unfortunately it didn't make it in 4.1.6 so maybe 4.1.7 instead.

To help the back-port review, I also suggest the related commits:

@fgsch
Copy link
Member

@fgsch fgsch commented May 10, 2017

I can backport this if that's the consensus.

@JonathanHuot
Copy link
Contributor

@JonathanHuot JonathanHuot commented May 10, 2017

I would like to ask few questions on the original PR though:

  • what happen if a request is restarted? which timestamp it will take ?
  • ditto: if std.timestamp("curl") called three times, how to select the 2nd?
  • it seems no VTC has been provided, not sure if it needs to?
@fgsch
Copy link
Member

@fgsch fgsch commented May 10, 2017

what happen if a request is restarted? which timestamp it will take ?

It's in the docs:

If a tag appears multiple times in a single transaction, the first occurrence is used.

ditto: if std.timestamp("curl") called three times, how to select the 2nd?

Not in the scope of this PR.

it seems no VTC has been provided, not sure if it needs to?

Tests were included. Please refer to the commit.

@hermunn
Copy link
Member

@hermunn hermunn commented May 11, 2017

@fgsch, if you want to port this to 4.1, then please do. Thanks.

@fgsch
Copy link
Member

@fgsch fgsch commented May 12, 2017

@fgsch, if you want to port this to 4.1, then please do. Thanks.

Sure. I will prepare it during the weekend.

fgsch added a commit that referenced this pull request Jun 12, 2017
The parsing still requires some TLC but this does not make it any
worse so let's get this in first.

Prompted by and ideas from github::xcir via #2077.
@hermunn
Copy link
Member

@hermunn hermunn commented Jun 12, 2017

Backport review: Many thanks to @fgsch for backporting this to 4.1. See ac4f336.

ibreger added a commit to Refinitiv/varnish-cache that referenced this pull request Jun 27, 2017
The parsing still requires some TLC but this does not make it any
worse so let's get this in first.

Prompted by and ideas from github::xcir via varnishcache#2077.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Linked issues

Successfully merging this pull request may close these issues.

None yet

6 participants
You can’t perform that action at this time.