Missing metrics on Grafana about prometheus-nginxlog-exporter

[martin-helmich]

Your response contains metrics like http_response_size_bytes{handler="prometheus",quantile="0.5"}, which seem to belong to Prometheus itself. Are you sure you queried the /metrics endpoint of the NGINX exporter, and not the /metrics endpoint of Prometheus itself?

[omata]

Hello,

I'm sure, my Prometheus server is located at Google Cloud, my nginx server is on a dedicated server with other provider. Only node exporter is running at the nginx server but metrics are different from exposed by prometheus-nginxlog-exporter at port 4040.

So i don't know what is happening.

[omata]

BTW I'm running the 64 bits version downloaded from: https://github.com/martin-helmich/prometheus-nginxlog-exporter/releases/download/v1.0.1/prometheus-nginxlog-exporter-linux-amd64-static

[omata]

I did tests with the other binaries and I got the same result 😕
Tested versions: 1.0.0, 1.0.1 1.0.1-static

P.D. Do I need to install go language?

[martin-helmich]

My mistake, the http_response_size_bytes{handler="prometheus",quantile="0.5"} metrics and others are actually printed by the NGINX exporter, after all. Sorry for the confusion.

The exporter will only start producing NGINX metrics as soon as data has been read from an access log file. Please make sure that the access log file that you have supplied (via command-line parameter or configuration file) is present.

If you have configured your exporter to use an existing access log file, please provide the following information to help me further debug this issue:

• Command-line flags and (if present) contents of your configuration file
• STDOUT contents of the exporter (if running under systemd, use the command journalctl -u prometheus-nginxlog-exporter)
• (If possible) a short excerpt from your NGINX access log file (with all sensitive information redacted, of course)

[omata]

The exporter will only start producing NGINX metrics as soon as data has been read from an access log file. Please make sure that the access log file that you have supplied (via command-line parameter or configuration file) is present

Yes it's present, but I don't know if the owner is related withe the issue, the file has www-data:adm ownership. It is present and increasing in size every second.

• Command-line flags and (if present) contents of your configuration file

/etc/systemd/system/prometheus-nginxlog-exporter.service:

[Unit]
Description=NGINX metrics exporter for Prometheus
After=network-online.target

[Service]
ExecStart=/usr/local/bin/prometheus-nginxlog-exporter -config-file /etc/prometheus-nginxlog-exporter.hcl
Restart=always
ProtectSystem=full
CapabilityBoundingSet=

[Install]
WantedBy=multi-user.target

/etc/prometheus-nginxlog-exporter.hcl

listen {
  port = 4040
  address = "127.0.0.1"
}

namespace "app" {
  source_files = [
    "/home/user/app/logs/nginx/app_access.log"
  ]
  format = "$remote_addr - $remote_user [$time_local] \"$request\" $status $body_bytes_sent \"$http_referer\" \"$http_user_agent\" \"$http_x_forwarded_for\""

  labels {
    app = "myapp"
    environment = "production"
  }
}

Content of /home/user/app/logs/nginx/app_access.log:

000.000.000.000 - - [05/Jan/2018:17:11:01 -0300] "POST /users/activity/ HTTP/1.1" 200 33 "https://www.xxxxxxxx.com/nnnnn/sss/titulo_0_xyxyxyxyxyxy.html" "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/61.0.3163.100 Safari/537.36"
000.000.000.000 - - [05/Jan/2018:17:11:01 -0300] "POST /users/activity/ HTTP/1.1" 200 33 "https://www.xxxxxxxx.com/politica/madre-sindicalista-preso-marcelo-balcedo-defendio-gritos-tv-inventaron-causa-infame_0_By2KwepQz.html" "Mozilla/5.0 (Windows NT 10.0) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/63.0.3239.84 Safari/537.36"
000.000.000.000 - - [05/Jan/2018:17:11:01 -0300] "POST /users/activity/ HTTP/1.1" 200 33 "https://www.xxxxxxxx.com/nnnnn/sss/titulo_0_xyxyxyxyxyxy.html" "Mozilla/5.0 (Linux; Android 6.0.1; SM-G570M Build/MMB29K) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/62.0.3202.84 Mobile Safari/537.36"
000.000.000.000 - - [05/Jan/2018:17:11:01 -0300] "POST /users/activity/ HTTP/1.1" 200 33 "https://www.xxxxxxxx.com/ciudades/tragedia-villa-crespo-mujer-murio-atropellada-auto-control_0_SyOQjQpmf.html" "Mozilla/5.0 (Windows NT 6.1; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/63.0.3239.84 Safari/537.36"
000.000.000.000 - - [05/Jan/2018:17:11:01 -0300] "POST /users/activity/ HTTP/1.1" 200 33 "https://www.xxxxxxxx.com/nnnnn/sss/titulo_0_xyxyxyxyxyxy.html" "Mozilla/5.0 (Linux; Android 6.0.1; SM-G570M Build/MMB29K) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/62.0.3202.84 Mobile Safari/537.36"
000.000.000.000 - - [05/Jan/2018:17:11:01 -0300] "GET /status_clip/?hash_id=y9i6 HTTP/1.1" 200 72 "https://app.com/media_map/view/" "Mozilla/5.0 (Windows NT 6.1; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/63.0.3239.84 Safari/537.36"
000.000.000.000 - - [05/Jan/2018:17:11:01 -0300] "GET /status_clip/?hash_id=y9IE HTTP/1.1" 200 67 "https://app.com/media_map/view/" "Mozilla/5.0 (Windows NT 6.1; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/63.0.3239.84 Safari/537.36"
000.000.000.000 - - [05/Jan/2018:17:11:01 -0300] "GET /player/y9Od/ HTTP/1.1" 200 5461 "https://www.filo.news/actualidad/La-mama-de-la-joven-que-murio-haciendo-parapente-A-mi-hija-la-mataron-20180105-0036.html" "Mozilla/5.0 (Linux; Android 5.1.1; SM-G531M Build/LMY48B) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/61.0.3163.98 Mobile Safari/537.36"
000.000.000.000 - - [05/Jan/2018:17:11:01 -0300] "POST /users/activity/ HTTP/1.1" 200 33 "https://www.xxxxxxxx.com/nnnnn/sss/titulo_0_xyxyxyxyxyxy.html" "Mozilla/5.0 (Linux; Android 6.0.1; SM-G570M Build/MMB29K) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/62.0.3202.84 Mobile Safari/537.36"
000.000.000.000 - - [05/Jan/2018:17:11:01 -0300] "POST /users/activity/ HTTP/1.1" 200 33 "https://www.xxxxxxxx.com/nnnnn/sss/titulo_0_xyxyxyxyxyxy.html" "Mozilla/5.0 (Linux; Android 7.0; Moto G (5) Plus Build/NPN25.137-83) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/63.0.3239.111 Mobile Safari/537.36"
000.000.000.000 - - [05/Jan/2018:17:11:01 -0300] "GET /player/y9Oc/ HTTP/1.1" 200 5464 "https://www.filo.news/actualidad/La-mama-de-la-joven-que-murio-haciendo-parapente-A-mi-hija-la-mataron-20180105-0036.html" "Mozilla/5.0 (Linux; Android 5.1.1; SM-G531M Build/LMY48B) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/61.0.3163.98 Mobile Safari/537.36"
000.000.000.000 - - [05/Jan/2018:17:11:01 -0300] "GET /player/y9Od/ HTTP/1.1" 200 5461 "https://www.filo.news/actualidad/La-mama-de-la-joven-que-murio-haciendo-parapente-A-mi-hija-la-mataron-20180105-0036.html" "Mozilla/5.0 (iPhone; CPU iPhone OS 11_2_1 like Mac OS X) AppleWebKit/604.4.7 (KHTML, like Gecko) Version/11.0 Mobile/15C153 Safari/604.1"
000.000.000.000 - - [05/Jan/2018:17:11:01 -0300] "POST /users/activity/ HTTP/1.1" 200 33 "https://www.xxxxxxxx.com/ciudades/tragedia-villa-crespo-mujer-murio-atropellada-auto-control_0_SyOQjQpmf.html" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_10_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/63.0.3239.84 Safari/537.36"
000.000.000.000 - - [05/Jan/2018:17:11:01 -0300] "POST /users/activity/ HTTP/1.1" 200 33 "https://www.xxxxxxxx.com/nnnnn/sss/titulo_0_xyxyxyxyxyxy.html" "Mozilla/5.0 (Linux; Android 5.1.1; SM-G531M Build/LMY48B; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/61.0.3163.98 Mobile Safari/537.36 [FB_IAB/FB4A;FBAV/148.0.0.51.62;]"
000.000.000.000 - - [05/Jan/2018:17:11:01 -0300] "POST /users/activity/ HTTP/1.1" 200 33 "https://www.xxxxxxxx.com/nnnnn/sss/titulo_0_xyxyxyxyxyxy.html" "Mozilla/5.0 (Linux; Android 5.1.1; SM-G531M Build/LMY48B; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/61.0.3163.98 Mobile Safari/537.36 [FB_IAB/FB4A;FBAV/148.0.0.51.62;]"
000.000.000.000 - - [05/Jan/2018:17:11:01 -0300] "POST /users/activity/ HTTP/1.1" 200 33 "https://www.xxxxxxxx.com/autos/flota-autos-balcedo-valuada-millones-dolares_0_ByjGkbamG.html" "Mozilla/5.0 (Linux; Android 7.0; HUAWEI VNS-L31 Build/HUAWEIVNS-L31) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/59.0.3071.125 Mobile Safari/537.36"
000.000.000.000 - - [05/Jan/2018:17:11:01 -0300] "POST /users/activity/ HTTP/1.1" 200 33 "https://www.xxxxxxxx.com/nnnnn/sss/titulo_0_xyxyxyxyxyxy.html" "Mozilla/5.0 (Linux; Android 5.1.1; SM-G531M Build/LMY48B; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/61.0.3163.98 Mobile Safari/537.36 [FB_IAB/FB4A;FBAV/148.0.0.51.62;]"
000.000.000.000 - - [05/Jan/2018:17:11:02 -0300] "GET /static/js/xxxxxxxx/logo.png HTTP/1.1" 200 1959 "https://vodgc.com/html5/html5lib/v2.57.1/mwEmbedFrame.php/p/102/uiconf_id/23449569/entry_id/0_zwoo4r5x?wid=_102&iframeembed=true&playerId=mediaplayer_5a4f8c515e67fe0e66487ae6_1515166687292_179&entry_id=0_zwoo4r5x&flashvars[streamerType]=auto" "Mozilla/5.0 (Linux; Android 6.0.1; MotoG3 Build/MPIS24.107-55-2-17; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/59.0.3071.125 Mobile Safari/537.36 [FB_IAB/FB4A;FBAV/136.0.0.22.91;]"
000.000.000.000 - - [05/Jan/2018:17:11:02 -0300] "POST /users/activity/ HTTP/1.1" 200 33 "https://www.xxxxxxxx.com/nnnnn/sss/titulo_0_xyxyxyxyxyxy.html" "Mozilla/5.0 (Linux; Android 5.0.1; ALE-L23 Build/HuaweiALE-L23) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/62.0.3202.84 Mobile Safari/537.36"
000.000.000.000 - - [05/Jan/2018:17:11:02 -0300] "POST /users/activity/ HTTP/1.1" 200 33 "https://www.xxxxxxxx.com/nnnnn/sss/titulo_0_xyxyxyxyxyxy.html" "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/61.0.3163.100 Safari/537.36"

SORRY I FORGOT SOMETHING

• STDOUT contents of the exporter (if running under systemd, use the command journalctl -u prometheus-nginxlog-exporter)

Jan 04 16:21:24 server prometheus-nginxlog-exporter[15611]: loading configuration file /etc/prometheus-nginxlog-exporter.hcl
Jan 04 16:21:24 server prometheus-nginxlog-exporter[15611]: &{{4040 127.0.0.1} {false     {  []}} [{myapp [/home/username/app-server/logs/nginx/app_access.log] $remote_addr - $re
Jan 04 16:21:24 server prometheus-nginxlog-exporter[15611]: using configuration {{%!s(int=4040) 127.0.0.1} {%!s(bool=false)     {  []}} [{myapp [/home/username/app-server/logs/nginx/app
Jan 04 16:21:24 server prometheus-nginxlog-exporter[15611]: starting listener for namespace myapp
Jan 04 16:21:24 server prometheus-nginxlog-exporter[15611]: running HTTP server on address 127.0.0.1:4040
Jan 05 12:28:04 server systemd[1]: Stopping NGINX metrics exporter for Prometheus...
Jan 05 12:28:04 server systemd[1]: Stopped NGINX metrics exporter for Prometheus.
Jan 05 12:28:34 server systemd[1]: Started NGINX metrics exporter for Prometheus.
Jan 05 12:28:34 server prometheus-nginxlog-exporter[22448]: loading configuration file /etc/prometheus-nginxlog-exporter.hcl
Jan 05 12:28:34 server prometheus-nginxlog-exporter[22448]: using configuration {{%!s(int=4040) 127.0.0.1} {%!s(bool=false)     {  []}} [{myapp [/home/username/app-server/logs/nginx/app
Jan 05 12:28:34 server prometheus-nginxlog-exporter[22448]: starting listener for namespace myapp
Jan 05 12:28:34 server prometheus-nginxlog-exporter[22448]: running HTTP server on address 127.0.0.1:4040
Jan 05 12:38:31 server systemd[1]: Stopping NGINX metrics exporter for Prometheus...
Jan 05 12:38:31 server systemd[1]: Stopped NGINX metrics exporter for Prometheus.
Jan 05 12:38:31 server systemd[1]: Started NGINX metrics exporter for Prometheus.
Jan 05 12:38:31 server prometheus-nginxlog-exporter[21726]: loading configuration file /etc/prometheus-nginxlog-exporter.hcl
Jan 05 12:38:31 server prometheus-nginxlog-exporter[21726]: using configuration {{%!s(int=4040) 127.0.0.1} {%!s(bool=false)     {  []}} [{my [/home/username/app-server/logs/nginx/app_ac
Jan 05 12:38:31 server prometheus-nginxlog-exporter[21726]: starting listener for namespace my
Jan 05 12:38:31 server prometheus-nginxlog-exporter[21726]: running HTTP server on address 127.0.0.1:4040

[martin-helmich]

Thanks for the response. I'm starting to suspect this might be a permission-related issue. In your case, the exporter runs as root, but is started with an empty capability bounding set (CapabilityBoundingSet=), which takes away most of the privileges that root usually has.

Could you try removing the CapabilityBoundingSet= line from the systemd unit file (followed by systemctl daemon-reload and systemctl restart prometheus-nginxlog-exporter)? This will result in the exporter running with full root privileges -- which is obviously not a suitable solution for a production setup, but it's a quick&easy way to pinpoint a permissions issue.

[omata]

It worked!

The exporter did start to parse the log file, but in some cases I'm getting the message: error while parsing line

BTW: I deleted from format: the end of the expression \"$http_x_forwarded_for\"

[omata]

I'm getting only two metrics right now. Maybe because a wrong format?

app_http_response_count_total
app_http_response_size_bytes

[martin-helmich]

Thanks for the feedback. I've opened a new issue to track the error reporting when opening files -- this is obviously a bug; if a file cannot be opened due to permissions, the exporter should terminate with a comprehensive error message, and not just keep on running.

Regarding the metrics: All other metrics (like app_http_upstream_time_seconds or app_http_response_time_seconds or app_http_response_size_bytes) will only become available when your access log contains the $upstream_response_time,
$request_time and/or $body_bytes_sent variables. These need to be enabled in the NGINX configuration (more precisely, the log_format setting) and then added to the format specified for the exporter.

[omata]

Do you have an example on how to configure nginx to get those metrics?

And a lot of thanks for your help and great work!!!

Regards,

[martin-helmich]

Have a look at NGINX's Logging and Monitoring guide. It contains some good examples that contain the $request_time and $upstream_response_time:

    log_format upstream_time '$remote_addr - $remote_user [$time_local] '
                             '"$request" $status $body_bytes_sent '
                             '"$http_referer" "$http_user_agent"'
                             'rt=$request_time uct="$upstream_connect_time" uht="$upstream_header_time" urt="$upstream_response_time"';

[omata]

Thank you!!!

[martin-helmich]

Happy to help 👍. Closing this issue for now.