# Mysql-slow query parsing error

**URL:** <https://discuss.elastic.co/t/mysql-slow-query-parsing-error/83726>\
**Category:** Beats\
**Tags:** filebeat\
**Created:** [April 26, 2017, 3:07pm UTC](https://discuss.elastic.co/t/mysql-slow-query-parsing-error/83726 "2017-04-26T15:07:39Z")\
**Posts on this page:** 13\
**Page:** 1

<div class="post-metadata">

**Author:** ![gnujeremie](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/gnujeremie/32/9198_2.png) [@gnujeremie](https://discuss.elastic.co/u/gnujeremie)\
**Post date:** [April 26, 2017, 3:07pm UTC](https://discuss.elastic.co/t/mysql-slow-query-parsing-error/83726/1 "2017-04-26T15:07:39Z")

</div>

Hi,  
I am using filebeat and the mysql module to send mysql error logs and mysql slow logs to elastic.

Here's an extract from my configuration :

```
 #========================== Modules configuration ============================
 filebeat.modules:
 - module: mysql
   # Error logs
   error:
     enabled: true
   # Slow logs
   slowlog:
     enabled: true

```

The error logs are parsed, no problem. But the mysql-slow logs fail with the following message in my ES documents :

```
Provided Grok expressions do not match field value: [# User@Host: myhost[myhost] @ host [ip] Id: 10540316\n# Query_time: 4.065385 Lock_time: 0.000220 Rows_sent: 1000 Rows_examined: 1481669\nSET timestamp=1493217907;\nSELECT mcu.mcu_guid, mcu.cus_guid, mcu.mcu_url, mcu.mcu_crawlelements, mcu.mcu_order, GROUP_CONCAT(mca.mca_guid SEPARATOR \";\") as mca_guid\n FROM kat_mailcustomerurl mcu, kat_customer cus, kat_mailcampaign mca\n WHERE cus.cus_guid = mcu.cus_guid\n \tAND cus.pro_code = 'CYB'\n \tAND cus.cus_offline = 0\n \tAND mca.cus_guid = cus.cus_guid\n \tAND (mcu.mcu_date IS NULL OR mcu.mcu_date < CURDATE())\n \tAND mcu.mcu_crawlelements IS NOT NULL\n GROUP BY mcu.mcu_guid\n ORDER BY mcu.mcu_order ASC\n LIMIT 1000;]

```

When I copy/paste my logs into [http://grokconstructor.appspot.com](http://grokconstructor.appspot.com) using the grok pattern found in filebeat/module/mysql/slowlog/ingest/pipeline.json, it works. But for a reason I don't understand, filebeat fails. 😓

Thanks for your help

---

<div class="post-metadata">

**Author:** ![ruflin](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/ruflin/32/3116_2.png) [@ruflin](https://discuss.elastic.co/u/ruflin)\
**Post date:** [April 28, 2017, 8:05am UTC](https://discuss.elastic.co/t/mysql-slow-query-parsing-error/83726/2 "2017-04-28T08:05:08Z")

</div>

It seems the mysql log on your side does not match the one we use for testing.

- Which mysql version are you using?
- Could you provide some slow log examples?

---

<div class="post-metadata">

**Author:** ![gnujeremie](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/gnujeremie/32/9198_2.png) [@gnujeremie](https://discuss.elastic.co/u/gnujeremie)\
**Post date:** [April 28, 2017, 9:57am UTC](https://discuss.elastic.co/t/mysql-slow-query-parsing-error/83726/3 "2017-04-28T09:57:26Z")

</div>

I am using Mysql 5.7.17 on debian

here's an extract :

```auto
# Time: 2017-04-28T09:07:39.777791Z
# User@Host: apphost[apphost] @ apphost [ip] Id: 10997316
# Query_time: 4.071491 Lock_time: 0.000212 Rows_sent: 1000 Rows_examined: 1489615
SET timestamp=1493370459;
SELECT mcu.mcu_guid, mcu.cus_guid, mcu.mcu_url, mcu.mcu_crawlelements, mcu.mcu_order, GROUP_CONCAT(mca.mca_guid SEPARATOR ";") as mca_guid
                    FROM kat_mailcustomerurl mcu, kat_customer cus, kat_mailcampaign mca
                    WHERE cus.cus_guid = mcu.cus_guid
                        AND cus.pro_code = 'CYB'
                        AND cus.cus_offline = 0
                        AND mca.cus_guid = cus.cus_guid
                        AND (mcu.mcu_date IS NULL OR mcu.mcu_date < CURDATE())
                        AND mcu.mcu_crawlelements IS NOT NULL
                    GROUP BY mcu.mcu_guid
                    ORDER BY mcu.mcu_order ASC
                    LIMIT 1000;
# Time: 2017-04-28T09:16:30.738365Z
# User@Host: apphost[apphost] @ apphost [ip] Id: 10999834
# Query_time: 10.346539 Lock_time: 0.000036 Rows_sent: 0 Rows_examined: 4751313
SET timestamp=1493370990;
call load_stats(1, '2017-04-28 00:00:00');
# Time: 2017-04-28T09:31:31.133657Z
# User@Host: apphost[apphost] @ apphost [ip] Id: 11004208
# Query_time: 10.508030 Lock_time: 0.000034 Rows_sent: 0 Rows_examined: 4754675
SET timestamp=1493371891;
call load_stats(1, '2017-04-28 00:00:00');
# Time: 2017-04-28T09:32:41.128590Z
# User@Host: apphost[apphost] @ apphost [ip] Id: 11004559
# Query_time: 4.231050 Lock_time: 0.000211 Rows_sent: 1000 Rows_examined: 1489498
SET timestamp=1493371961;
SELECT mcu.mcu_guid, mcu.cus_guid, mcu.mcu_url, mcu.mcu_crawlelements, mcu.mcu_order, GROUP_CONCAT(mca.mca_guid SEPARATOR ";") as mca_guid
                    FROM kat_mailcustomerurl mcu, kat_customer cus, kat_mailcampaign mca
                    WHERE cus.cus_guid = mcu.cus_guid
                        AND cus.pro_code = 'CYB'
                        AND cus.cus_offline = 0
                        AND mca.cus_guid = cus.cus_guid
                        AND (mcu.mcu_date IS NULL OR mcu.mcu_date < CURDATE())
                        AND mcu.mcu_crawlelements IS NOT NULL
                    GROUP BY mcu.mcu_guid
                    ORDER BY mcu.mcu_order ASC
                    LIMIT 1000;
# Time: 2017-04-28T09:38:58.136628Z
# User@Host: apphost[apphost] @ apphost [ip] Id: 11006302
# Query_time: 4.057573 Lock_time: 0.000219 Rows_sent: 1000 Rows_examined: 1489519
SET timestamp=1493372338;
SELECT mcu.mcu_guid, mcu.cus_guid, mcu.mcu_url, mcu.mcu_crawlelements, mcu.mcu_order, GROUP_CONCAT(mca.mca_guid SEPARATOR ";") as mca_guid
                    FROM kat_mailcustomerurl mcu, kat_customer cus, kat_mailcampaign mca
                    WHERE cus.cus_guid = mcu.cus_guid
                        AND cus.pro_code = 'CYB'
                        AND cus.cus_offline = 0
                        AND mca.cus_guid = cus.cus_guid
                        AND (mcu.mcu_date IS NULL OR mcu.mcu_date < CURDATE())
                        AND mcu.mcu_crawlelements IS NOT NULL
                    GROUP BY mcu.mcu_guid
                    ORDER BY mcu.mcu_order ASC
                    LIMIT 1000;
# Time: 2017-04-28T09:46:31.124448Z
# User@Host: apphost[apphost] @ apphost [ip] Id: 11008346
# Query_time: 10.721687 Lock_time: 0.000054 Rows_sent: 0 Rows_examined: 4757952
SET timestamp=1493372791;
call load_stats(1, '2017-04-28 00:00:00');

```

I just changed the hostname and the server IP.  
But as I said, the grok pattern seems to work when I'm trying it on a online tester. That's what's strange :-/

---

<div class="post-metadata">

**Author:** ![gnujeremie](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/gnujeremie/32/9198_2.png) [@gnujeremie](https://discuss.elastic.co/u/gnujeremie)\
**Post date:** [April 28, 2017, 2:39pm UTC](https://discuss.elastic.co/t/mysql-slow-query-parsing-error/83726/4 "2017-04-28T14:39:55Z")

</div>

Ok so now it seems to read the slow-log queries. I didn't do anything, maybe it's okay with the new logs added to the file... 😕

Edit: my bad, only several queries are read (and not the new ones). So the problem is still there.

---

<div class="post-metadata">

**Author:** ![ruflin](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/ruflin/32/3116_2.png) [@ruflin](https://discuss.elastic.co/u/ruflin)\
**Post date:** [April 28, 2017, 2:53pm UTC](https://discuss.elastic.co/t/mysql-slow-query-parsing-error/83726/5 "2017-04-28T14:53:03Z")

</div>

It seems our grok pattern has issues with the following content:

```auto
# User@Host: apphost[apphost] @ apphost [ip] Id: 10997316
# Query_time: 4.071491 Lock_time: 0.000212 Rows_sent: 1000 Rows_examined: 1489615
SET timestamp=1493370459;

```

Our grok pattern looks as following:

```auto
^# User@Host: %{USER:mysql.slowlog.user}(\\[[^\\]]+\\])? @ %{HOSTNAME:mysql.slowlog.host} \\[(IP:mysql.slowlog.ip)?\\](\\s*Id:\\s* %{NUMBER:mysql.slowlog.id})?\n# Query_time: %{NUMBER:mysql.slowlog.query_time.sec}\\s* Lock_time: %{NUMBER:mysql.slowlog.lock_time.sec}\\s* Rows_sent: %{NUMBER:mysql.slowlog.rows_sent}\\s* Rows_examined: %{NUMBER:mysql.slowlog.rows_examined}\n(SET timestamp=%{NUMBER:mysql.slowlog.timestamp};\n)?%{GREEDYMULTILINE:mysql.slowlog.query}

```

I need to check it in detail where it doesn't match. @tudor perhaps knows?

---

<div class="post-metadata">

**Author:** ![gnujeremie](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/gnujeremie/32/9198_2.png) [@gnujeremie](https://discuss.elastic.co/u/gnujeremie)\
**Post date:** [April 28, 2017, 2:58pm UTC](https://discuss.elastic.co/t/mysql-slow-query-parsing-error/83726/6 "2017-04-28T14:58:21Z")

</div>

Okay, I hope you'll find 🙂

Remember that I wrote "apphost" and "ip" myself, in the real logs it's more something like "app\_hostname" and "[ns123456789.ip-1-11-11.eu](http://ns123456789.ip-1-11-11.eu)".  
In case that's the problem...

---

<div class="post-metadata">

**Author:** ![ruflin](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/ruflin/32/3116_2.png) [@ruflin](https://discuss.elastic.co/u/ruflin)\
**Post date:** [April 28, 2017, 2:59pm UTC](https://discuss.elastic.co/t/mysql-slow-query-parsing-error/83726/7 "2017-04-28T14:59:27Z")

</div>

I assume it is an ipv4 address?

---

<div class="post-metadata">

**Author:** ![gnujeremie](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/gnujeremie/32/9198_2.png) [@gnujeremie](https://discuss.elastic.co/u/gnujeremie)\
**Post date:** [April 28, 2017, 3:01pm UTC](https://discuss.elastic.co/t/mysql-slow-query-parsing-error/83726/8 "2017-04-28T15:01:17Z")

</div>

Yes, excuse me I forgot the IP.

---

<div class="post-metadata">

**Author:** ![ruflin](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/ruflin/32/3116_2.png) [@ruflin](https://discuss.elastic.co/u/ruflin)\
**Post date:** [May 3, 2017, 7:53am UTC](https://discuss.elastic.co/t/mysql-slow-query-parsing-error/83726/9 "2017-05-03T07:53:26Z")

</div>

Which filebeat version are you using? Which elasticsearch version? What are the elasticsearch plugins you have installed?

---

<div class="post-metadata">

**Author:** ![ruflin](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/ruflin/32/3116_2.png) [@ruflin](https://discuss.elastic.co/u/ruflin)\
**Post date:** [May 3, 2017, 8:00am UTC](https://discuss.elastic.co/t/mysql-slow-query-parsing-error/83726/10 "2017-05-03T08:00:00Z")

</div>

I created a PR here to test the file. So far I could not reproduce it but lets see what CI thinks: [https://github.com/elastic/beats/pull/4181](https://github.com/elastic/beats/pull/4181)

Update: I managed to reproduce it.

---

<div class="post-metadata">

**Author:** ![tudor](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/tudor/32/3753_2.png) [@tudor](https://discuss.elastic.co/u/tudor)\
**Post date:** [May 3, 2017, 10:03am UTC](https://discuss.elastic.co/t/mysql-slow-query-parsing-error/83726/11 "2017-05-03T10:03:56Z")

</div>

Thank you @ruflin and @gnujeremie for investigating this. I opened [https://github.com/elastic/beats/pull/4183](https://github.com/elastic/beats/pull/4183) with a fix.

You can manually make the same modification in your `module/mysql/slowlog/ingest/pipeline.json` file if you're interested to hotpatch this until we release it.

---

<div class="post-metadata">

**Author:** ![gnujeremie](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/gnujeremie/32/9198_2.png) [@gnujeremie](https://discuss.elastic.co/u/gnujeremie)\
**Post date:** [May 9, 2017, 7:00am UTC](https://discuss.elastic.co/t/mysql-slow-query-parsing-error/83726/12 "2017-05-09T07:00:20Z")

</div>

Sorry for not answering sooner, I was on hollydays last week 🙂

I'm using ES 5.3.1 and filebeats 5.3.1. Only ES plugin is XPack.

But it seems like you managed to find the issue, cool !

---

<div class="post-metadata">

**Author:** ![system](https://us1.discourse-cdn.com/elastic/original/3X/1/a/1ac57faf039f6b580b3f104ef42a2a89e41014de.png) [@system](https://discuss.elastic.co/u/system)\
**Post date:** [June 6, 2017, 7:02am UTC](https://discuss.elastic.co/t/mysql-slow-query-parsing-error/83726/13 "2017-06-06T07:02:16Z")

</div>

This topic was automatically closed 28 days after the last reply. New replies are no longer allowed.