help needed

[dc3o]

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]

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.

[Jamie Wilkinson]

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

github.com/google/mtail/internal/vm.(*VM).errorf(0xc00039bad0, 0xa82f84, 0x2, 0xc0000cfe38, 0x1, 0x1)

        /home/runner/work/mtail/mtail/internal/vm/vm.go:111 +0x4d2

github.com/google/mtail/internal/vm.(*VM).execute(0xc00039bad0, 0xc000080640, 0x34, 0x0, 0x0, 0x15)

        /home/runner/work/mtail/mtail/internal/vm/vm.go:829 +0x57c5

github.com/google/mtail/internal/vm.(*VM).ProcessLogLine(0xc00039bad0, 0xb45448, 0xc000096008, 0xc000451530)

        /home/runner/work/mtail/mtail/internal/vm/vm.go:953 +0x1a5

github.com/google/mtail/internal/vm.(*VM).Run(0xc00039bad0, 0xc000082a80, 0xc0000e0900)

        /home/runner/work/mtail/mtail/internal/vm/vm.go:1023 +0x109

created by github.com/google/mtail/internal/vm.(*Loader).CompileAndRun

        /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

To view this discussion on the web visit https://groups.google.com/d/msgid/mtail-users/11bb165e-db09-47a4-933b-050c94892cf7n%40googlegroups.com.

[Jamie Wilkinson]

Please try out -rc46 and tell me how it goes, thanks!

https://github.com/google/mtail/releases/tag/v3.0.0-rc46 

[Jamie Wilkinson]

Oops, sent before I saw you already tried it.

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

[Nemanja Delic]

Great, thanks!