help needed

27 views
Skip to first unread message

dc3o

unread,
May 14, 2021, 8:12:43 AM5/14/21
to mtail-users
apache log:
```
192.168.1.10 - - [14/May/2021:02:40:37 -0700] "GET /style/images/top_panel_slice.jpg HTTP/1.1" 200 323 "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/90.0.4430.72 Safari/537.36"
```
apache_test.mtail
```
counter apache_http_requests_total by request_method, http_version, request_status
counter apache_http_bytes_total by request_method, http_version, request_status

/^/ +
/(?P<ip>\d+\.\d+\.\d+\.\d+) / + #
/- / + # %l
/- / + # %u
/\[(?P<timestamp>\d{2}\/\w{3}\/\d{4}:\d{2}:\d{2}:\d{2} (\+|-)\d{4})\] / + # %t
/"(?P<request_method>[A-Z]+) (?P<URI>\S+) (?P<http_version>HTTP\/[0-9\.]+)" / + # \"%r\"
/(?P<request_status>\d{3}) / + # %>s
/((?P<response_size>\d+)|-) / + # %b
/"(?P<referer>\S+)" / + # \"%{Referer}i\"
#/"(?P<user_agent>[[:print:]]+)"/ + # \"%{User-agent}i\"
/$/ {
  strptime($timestamp, "02/Jan/2006:15:04:05 -0700") # for tests

  apache_http_requests_total[$request_method][$http_version][$request_status]++
  $response_size > 0 {
      apache_http_bytes_total[$request_method][$http_version][$request_status] += $response_size
  }
}
```

When I start mtail process
```
mtail -progs ~/mtail_progs/apache_test.mtail --logs /var/log/httpd/access_log -logtostderr &
```
I get following:
```
I0514 05:06:44.359932    8098 store.go:178] Starting metric store expiry loop every 1h0m0s
I0514 05:06:44.365800    8098 checker.go:253] declaration of capture group reference `3' at apache_combined.mtail:9:1-3 appears to be unused
I0514 05:06:44.365856    8098 checker.go:253] declaration of capture group reference `8' at apache_combined.mtail:9:1-3 appears to be unused
I0514 05:06:44.365912    8098 checker.go:253] declaration of capture group reference `referer' at apache_combined.mtail:9:1-3 appears to be unused
I0514 05:06:44.365925    8098 checker.go:253] declaration of capture group reference `URI' at apache_combined.mtail:9:1-3 appears to be unused
I0514 05:06:44.365936    8098 checker.go:253] declaration of capture group reference `ip' at apache_combined.mtail:9:1-3 appears to be unused
I0514 05:06:44.365946    8098 checker.go:253] declaration of capture group reference `ip' at apache_combined.mtail:9:1-3 appears to be unused
I0514 05:06:44.365957    8098 checker.go:253] declaration of capture group reference `URI' at apache_combined.mtail:9:1-3 appears to be unused
I0514 05:06:44.365967    8098 checker.go:253] declaration of capture group reference `referer' at apache_combined.mtail:9:1-3 appears to be unused
I0514 05:06:44.366232    8098 loader.go:246] Loaded program apache_combined.mtail
I0514 05:06:44.366432    8098 tail.go:259] Tailing /var/log/httpd/access_log
I0514 05:06:44.366616    8098 mtail.go:193] Listening on 0.0.0.0:3903
```
No apache_http_requests_total and apache_http_bytes_total metrics are exposed.
Where am I doing wrong?

Jamie Wilkinson

unread,
May 14, 2021, 6:49:23 PM5/14/21
to dc3o, mtail-users
When you say they're not exposed, where are you looking?

As the metrics are histograms, they may not appear until the labels have values in them as well, so what might be happening is there isn't any new data read yet. When mtail starts, it reads log files from the end of the file like 'tail -f'.

But if you're testing, try the -one_shot flag as documented here: https://google.github.io/mtail/Deploying.html#troubleshooting
and mtail will read from the start of the file but then exit.

--
You received this message because you are subscribed to the Google Groups "mtail-users" group.
To unsubscribe from this group and stop receiving emails from it, send an email to mtail-users...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/mtail-users/8e02a25b-1e6f-4186-b820-5fbc89641fa1n%40googlegroups.com.
Message has been deleted

Jamie Wilkinson

unread,
May 18, 2021, 2:32:22 AM5/18/21
to dc3o, mtail-users
What version of mtail are you using?  (It's the first line of the INFO log.)

I can't reproduce this at HEAD; I'll tag a new release and ask you to try it.

On Mon, 17 May 2021 at 22:59, dc3o <deln...@gmail.com> wrote:
Problem was with bad format of regex part in test_apache.mtail. This is working version:

counter apache_http_requests_total by request_method, request_uri, request_status
counter apache_http_bytes_total by request_method, request_uri, request_status


/^/ +
/(?P<hostname>[0-9A-Za-z\.:-]+) / + # %h
/(?P<remote_logname>[0-9A-Za-z-]+) / + # %l
/(?P<remote_username>[0-9A-Za-z-]+) / + # %u
/\[(?P<timestamp>\d{2}\/\w{3}\/\d{4}:\d{2}:\d{2}:\d{2} (\+|-)\d{4})\] / + # %t
/"(?P<request_method>[A-Z]+) (?P<request_uri>\S+) (?P<http_version>HTTP\/[0-9\.]+)" / + # \"%r\"
/(?P<request_status>\d{3}) / + # %>s
/((?P<response_size>\d+)|-) / + # %b
#/"(?P<referer>\S+)" / + # \"%{Referer}i\"
/"(?P<user_agent>[[:print:]]+)"/ + # \"%{User-agent}i\"
/$/ {
  strptime($timestamp, "02/Jan/2006:15:04:05 -0700") # for tests

  apache_http_requests_total[$request_method][$request_uri][$request_status]++
  $response_size > 0 {
      apache_http_bytes_total[$request_method][$request_uri][$request_status] += $response_size
  }
}

Seeing weird error in the logs now. This is how a line in real log looks like
-
10.100.31.6 - - [16/May/2021:05:32:48 -0700] "GET /csm.cgi HTTP/0.9" 200 4 "-"
-
What it looks to me that mtail is matching the line but from some reason it does not detect response size being 4 bytes - but sets it to -
I'm pasting the mtail debug log:

Error occurred at instruction 20 {s2i, <nil>}, originating in my_apache_access.mtail at line 22
Full input text from "/var/log/httpd/https_access_ssl.log" was "10.100.31.6 - - [17/May/2021:05:32:48 -0700] \"GET /wapp.cgi HTTP/0.9\" 200 - \"-\""
I0517 05:32:48.936218   20622 vm.go:108] Set logging verbosity higher (-v1 or more) to see full VM state dump.
I0517 05:32:48.936314   20622 vm.go:111] VM stack:
goroutine 43 [running]:
runtime/debug.Stack(0x1, 0x1, 0xaa7854)
        /opt/hostedtoolcache/go/1.16.3/x64/src/runtime/debug/stack.go:24 +0x9f
        /home/runner/work/mtail/mtail/internal/vm/vm.go:111 +0x4d2
        /home/runner/work/mtail/mtail/internal/vm/vm.go:829 +0x57c5
        /home/runner/work/mtail/mtail/internal/vm/vm.go:953 +0x1a5
        /home/runner/work/mtail/mtail/internal/vm/vm.go:1023 +0x109
        /home/runner/work/mtail/mtail/internal/vm/loader.go:261 +0x7f6
I0517 05:32:48.936327   20622 vm.go:112] Dumping vm state
I0517 05:32:48.936336   20622 vm.go:113] Name: my_apache_access.mtail
I0517 05:32:48.936342   20622 vm.go:114] Input: &logline.LogLine{Context:(*context.cancelCtx)(0xc0002e0e80), Filename:"/var/log/httpd/https_access_ssl.log", Line:"10.100.31.6 - - [17/May/2021:05:32:48 -0700] \"GET /wapp.cgi HTTP/0.9\" 200 - \"-\""}
I0517 05:32:48.936364   20622 vm.go:115] Thread:
I0517 05:32:48.936371   20622 vm.go:116]  PC 20
I0517 05:32:48.936377   20622 vm.go:117]  Matched false
I0517 05:32:48.936383   20622 vm.go:118]  Matches map[0:[10.100.31.6 - - [17/May/2021:05:32:48 -0700] "GET /wapp.cgi HTTP/0.9" 200 - "-" 10.100.31.6 - - 17/May/2021:05:32:48 -0700 - GET /wapp.cgi HTTP/0.9 200 -  -]]
I0517 05:32:48.936399   20622 vm.go:119]  Timestamp 2021-05-17 05:32:48 -0700 -0700
I0517 05:32:48.936414   20622 vm.go:120]  Stack [241]
I0517 05:32:48.936544   20622 vm.go:121] Prog: my_apache_access.mtail


Jamie Wilkinson

unread,
May 18, 2021, 5:26:32 AM5/18/21
to dc3o, mtail-users
Please try out -rc46 and tell me how it goes, thanks!

Jamie Wilkinson

unread,
May 18, 2021, 5:27:06 AM5/18/21
to dc3o, mtail-users
Oops, sent before I saw you already tried it.

Thanks for the updates, I'll take another loo.

Nemanja Delic

unread,
May 18, 2021, 5:54:59 AM5/18/21
to Jamie Wilkinson, mtail-users
Great, thanks! 
Reply all
Reply to author
Forward
0 new messages