Help with sending PHP-FPM logs with custom pipeline

[Slavik_Fursov]

I have Debian 9 server with Nginx+PHP.
Installed Filebeat 7.4.2.
I have PHP-FPM log, which has entries like this:

slavik@deb96:/var/log/php$ sudo cat php7.0-fpm.log
[11-Nov-2019 23:02:37] WARNING: [pool www] child 133043, script '/var/www/RussianChurchVancouver.ca/web/index.php' (request: "GET /index.php") executing too slow (2.092933 sec), logging
[11-Nov-2019 23:16:36] WARNING: [pool www] child 133053, script '/var/www/antipa.site/web/wp-admin/admin-ajax.php' (request: "POST /wp-admin/admin-ajax.php") executing too slow (2.359414 sec), logging
[11-Nov-2019 23:21:03] WARNING: [pool www] child 133051, script '/var/www/hava.propovednik.com/web/index.php' (request: "GET /index.php") executing too slow (2.079449 sec), logging
[11-Nov-2019 23:39:29] WARNING: [pool www] child 133043, script '/var/www/pittsburgh-church.com/web/index.php' (request: "GET /index.php") executing too slow (2.290184 sec), logging

so, added this to my filebeat.yml config:

filebeat.inputs:
# Each - is an input. Most options can be set at the input level, so
# you can use different inputs for various configurations.
# Below are the input specific configurations.

- type: log

  # Change to true to enable this input configuration.
  enabled: true

  # Paths that should be crawled and fetched. Glob based paths.
  paths:
  - /var/log/php/*fpm.log
  close_inactive: 24h

  # Optional additional fields. These fields can be freely picked
  # to add additional information to the crawled log files for filtering
  fields:
    event.dataset: "php.error"
  # The Ingest Node pipeline ID associated with this input. If this is set, it
  # overwrites the pipeline option from the Elasticsearch output.
  pipeline: filebeat-php-slow

I also created pipeline "filebeat-php-slow", which exists. Here is source
I restarted Filebeat.

And I don't see any events from that log.

I also have NGINX module enabled on same host. And it works fine.

What am I missing here? Is there another step I need to do?

I checked syslog, and here is what I see:

slavik@deb96:/var/log$ sudo cat syslog | grep filebeat | grep php
INFO#011log/input.go:152#011Configured paths: [/var/log/php/*fpm.log]
INFO#011log/harvester.go:251#011Harvester started for file: /var/log/php/php7.0-fpm.log

Can you suggest any troubleshooting steps I can do?

[Slavik_Fursov]

Issue was in pipeline definition: it's grok processor resulted in errors.

I was only able to troubleshoot it by sending events to "_simulate" endpoint.

[exekias (Carlos Pérez Aradros)]

Hi @Slavik_Fursov,

I wonder if you got this working then?

It would be quite interesting to convert this into a Filebeat module, what do you think?

Best regards

[Slavik_Fursov]

@exekias
That would be great.

Here is my pipeline and logs example:

php-fpm.pipeline.json ($1913354) · Snippets · Slavik Fursov / share

I'm sure you can make it more efficient.

Description:
Lines 5-15: grok pattern, which is valid for ALL entries of PHP-FPM. Getting TIMESTAMP, LOG_LEVEL and MESSAGE
I'm using php.time for timestamp - not sure, if there is more appropriate name exists.

Lines 16-45: parsing TIMESTAMP

Lines 46-59: grok processor to get url.domain, http.request.method and url.original

• these fields only present for some messages in the log (usually only for slow scripts, if enabled in PHP config). That's why this processor has "ignore_missing": true, "ignore_failure": true
• url.domain parsed based on assumption, that it's part of the PHP script path, which goes after /var/www/. That's obviously in not universally true. It works for my setup, not sure about default pipeline.

Lines 60-72: grok processor to get duration of slow PHP scripts.

• this field only present for some messages in the log (usually only for slow scripts, if enabled in PHP config). That's why this processor has "ignore_missing": true, "ignore_failure": true
• I used php.duration for it. Not sure, if there is a better field.

Lines 73-79: ulrdecode processor is there in case I have non-english characters in the script path.

[Slavik_Fursov]

I think there are 3 types of logs generated by PHP:

1. FPM-PHP error log. Enabled by default for FPM configurations.
   Example is in previous message.
   Configuration here:
   https://github.com/php/php-src/blob/PHP-7.3.12/sapi/fpm/php-fpm.conf.in#L19-L60
   CGI would be different, I'm not familiar with CGI.

2. Slow requests log. Disabled by default.
   See example here:
   https://gitlab.com/SlavikCA/share/snippets/1913365
   Configuration and format defined here:
   https://github.com/php/php-src/blob/PHP-7.3.12/sapi/fpm/www.conf.in#L320-L333

3. PHP access log. Disabled by default.
   Configuration and format defined here:
   https://github.com/php/php-src/blob/PHP-7.3.12/sapi/fpm/www.conf.in#L257-L318