Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Fix mysql slowlog template to support mysql 5.7.22 #9647

Merged
merged 19 commits into from
Dec 31, 2018
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
19 commits
Select commit Hold shift + click to select a range
aed6cc6
Never default to a qualifier when none of them are set. (#9148)
ph Nov 19, 2018
07c4fa5
Merge branch 'master' of github.com:kaiyan-sheng/beats
kaiyan-sheng Nov 27, 2018
ff52365
Merge branch 'master' of github.com:kaiyan-sheng/beats
kaiyan-sheng Dec 10, 2018
5f9f575
Merge remote-tracking branch 'upstream/master'
kaiyan-sheng Dec 10, 2018
09d8b97
Merge remote-tracking branch 'upstream/master'
kaiyan-sheng Dec 10, 2018
141277e
Merge remote-tracking branch 'upstream/master'
kaiyan-sheng Dec 13, 2018
276a1de
Merge remote-tracking branch 'upstream/master'
kaiyan-sheng Dec 14, 2018
19a705a
Merge remote-tracking branch 'upstream/master'
kaiyan-sheng Dec 17, 2018
e54a566
Merge remote-tracking branch 'upstream/master'
kaiyan-sheng Dec 18, 2018
edd4488
Merge remote-tracking branch 'upstream/master'
kaiyan-sheng Dec 26, 2018
b0d2e22
Merge remote-tracking branch 'upstream/master'
kaiyan-sheng Dec 27, 2018
378b4f9
Merge remote-tracking branch 'upstream/master'
kaiyan-sheng Dec 28, 2018
95c43f1
Fix mysql slowlog template to support mysql 5.7.22
kaiyan-sheng Dec 18, 2018
063e3ea
Add changelog
kaiyan-sheng Dec 18, 2018
087fa94
Remove changes introduced from rebasing that are not related to this …
kaiyan-sheng Dec 26, 2018
0935ce2
Add more log entries to test log file
kaiyan-sheng Dec 26, 2018
e1223ae
Add OR in multiline.pattern to remove # Time from mysql.slowlog.query
kaiyan-sheng Dec 28, 2018
1d5f62b
Use CHANGELOG.next.asciidoc instead
kaiyan-sheng Dec 28, 2018
7c836b8
Merge branch 'master' into mysql_slowlog
kaiyan-sheng Dec 28, 2018
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
1 change: 1 addition & 0 deletions CHANGELOG.next.asciidoc
Original file line number Diff line number Diff line change
Expand Up @@ -85,6 +85,7 @@ https://github.com/elastic/beats/compare/v7.0.0-alpha2...master[Check the HEAD d
- Added netflow input type that supports NetFlow v1, v5, v6, v7, v8, v9 and IPFIX. {issue}9399[9399]
- Add option to modules.yml file to indicate that a module has been moved {pull}9432[9432].
- Fix parsing of GC entries in elasticsearch server log. {issue}9513[9513] {pull}9810[9810]
- Support mysql 5.7.22 slowlog starting with time information. {issue}7892[7892] {pull}9647[9647]

*Heartbeat*

Expand Down
4 changes: 2 additions & 2 deletions filebeat/module/mysql/slowlog/config/slowlog.yml
Original file line number Diff line number Diff line change
Expand Up @@ -5,7 +5,7 @@ paths:
{{ end }}
exclude_files: ['.gz$']
multiline:
pattern: '^# User@Host: '
pattern: '^(# User@Host: |# Time: )'
negate: true
match: after
exclude_lines: ['^[\/\w\.]+, Version: .* started with:.*'] # Exclude the header
exclude_lines: ['^[\/\w\.]+, Version: .* started with:.*', '^# Time:.*'] # Exclude the header and time
Copy link
Contributor

@andrewvc andrewvc Dec 18, 2018

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Maybe I'm misunderstanding this, but should we be using this new Time: header for @timestamp instead of ignoring it?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yeah I think there are some magic here that I don't understand. I'm imagining this exclude_lines is only ignoring it when first time parsing # User@Host. After that somehow this Time still get parsed into @timestamp since it is captured in mysql/slowlog/test/mysql-5.7.22.log-expected.json.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Did not investigate but I'm also a bit confused on why this keeps working. Perhaps the exlcude does not actually work here? Have a look at the pipeline.

Also it would be good to have in the test file below a few more lines to make sure it also works with multiple entries.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@andrewvc @ruflin I looked into this more and found out @timestamp field is generated from mysql.slowlog.timestamp with format UNIX. That's why adding # Time into the exclude_lines and that didn't change the output.

30 changes: 30 additions & 0 deletions filebeat/module/mysql/slowlog/test/mysql-5.7.22.log
Original file line number Diff line number Diff line change
@@ -0,0 +1,30 @@
# Time: 2018-08-07T16:27:47.169604+08:00
# User@Host: root[root] @ [218.76.8.37] Id: 7234
# Query_time: 15.000223 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 0
SET timestamp=1533630467;
select sleep(15);
# Time: 2018-08-07T16:27:47.169604+08:00
# User@Host: debian-sys-maint[debian-sys-maint] @ localhost []
# Query_time: 0.000153 Lock_time: 0.000061 Rows_sent: 1 Rows_examined: 5
SET timestamp=1533630467;
SELECT count(*) FROM mysql.user WHERE user='root' and password='';
# Time: 2018-08-07T16:27:47.169604+08:00
# User@Host: apphost[apphost] @ apphost [1.1.1.1] Id: 10997316
# Query_time: 4.071491 Lock_time: 0.000212 Rows_sent: 1000 Rows_examined: 1489615
SET timestamp=1533630467;
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: 2018-08-07T16:27:47.169604+08:00
# User@Host: apphost[apphost] @ apphost [1.1.1.1] Id: 10999834
# Query_time: 10.346539 Lock_time: 0.000036 Rows_sent: 0 Rows_examined: 4751313
SET timestamp=1533630467;
call load_stats(1, '2017-04-28 00:00:00');
83 changes: 83 additions & 0 deletions filebeat/module/mysql/slowlog/test/mysql-5.7.22.log-expected.json
Original file line number Diff line number Diff line change
@@ -0,0 +1,83 @@
[
{
"@timestamp": "2018-08-07T08:27:47.000Z",
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I worried at first that taking the unix timestamp instead of the title one we would loose the timezone diff. But seems like the timestamp is in UTC which is good.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@ycombinator I remember you saw something different for ES for example?
@kaiyan-sheng Could you try to run mysql in a non UTC timezone environment and check if the timestamp is still correct. If not, we should do a follow up PR that adds convert_timezone.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@ruflin I used to start test environment under beats/testing/environments using make start. Now instead of that, I started Elasticsearch locally on my macbook and ran GENERATE=1 INTEGRATION_TESTS=1 TESTING_FILEBEAT_MODULES=mysql nosetests -v --nocapture tests/system/test_modules.py again. I think this tested the non UTC timezeon environment scenario. Is that right?

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I remember you saw something different for ES for example?

The ES (and LS) logs contain ISO8601 timestamps without the timezone. In MySQL the value of the timestamp system variable needs to be a Unix timestamp, which is in UTC already, so we're good here.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks for the details @ycombinator

"ecs.version": "1.0.0-beta2",
"event.dataset": "slowlog",
"event.module": "mysql",
"input.type": "log",
"log.flags": [
"multiline"
],
"log.offset": 41,
"mysql.slowlog.id": "7234",
"mysql.slowlog.ip": "218.76.8.37",
"mysql.slowlog.lock_time.sec": "0.000000",
"mysql.slowlog.query": "select sleep(15);",
"mysql.slowlog.query_time.sec": "15.000223",
"mysql.slowlog.rows_examined": "0",
"mysql.slowlog.rows_sent": "1",
"mysql.slowlog.timestamp": "1533630467",
"mysql.slowlog.user": "root"
},
{
"@timestamp": "2018-08-07T08:27:47.000Z",
"ecs.version": "1.0.0-beta2",
"event.dataset": "slowlog",
"event.module": "mysql",
"input.type": "log",
"log.flags": [
"multiline"
],
"log.offset": 254,
"mysql.slowlog.host": "localhost",
"mysql.slowlog.lock_time.sec": "0.000061",
"mysql.slowlog.query": "SELECT count(*) FROM mysql.user WHERE user='root' and password='';",
"mysql.slowlog.query_time.sec": "0.000153",
"mysql.slowlog.rows_examined": "5",
"mysql.slowlog.rows_sent": "1",
"mysql.slowlog.timestamp": "1533630467",
"mysql.slowlog.user": "debian-sys-maint"
},
{
"@timestamp": "2018-08-07T08:27:47.000Z",
"ecs.version": "1.0.0-beta2",
"event.dataset": "slowlog",
"event.module": "mysql",
"input.type": "log",
"log.flags": [
"multiline"
],
"log.offset": 526,
"mysql.slowlog.host": "apphost",
"mysql.slowlog.id": "10997316",
"mysql.slowlog.ip": "1.1.1.1",
"mysql.slowlog.lock_time.sec": "0.000212",
"mysql.slowlog.query": "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\n FROM kat_mailcustomerurl mcu, kat_customer cus, kat_mailcampaign mca\n WHERE cus.cus_guid = mcu.cus_guid\n AND cus.pro_code = 'CYB'\n AND cus.cus_offline = 0\n AND mca.cus_guid = cus.cus_guid\n AND (mcu.mcu_date IS NULL OR mcu.mcu_date < CURDATE())\n AND mcu.mcu_crawlelements IS NOT NULL\n GROUP BY mcu.mcu_guid\n ORDER BY mcu.mcu_order ASC\n LIMIT 1000;",
"mysql.slowlog.query_time.sec": "4.071491",
"mysql.slowlog.rows_examined": "1489615",
"mysql.slowlog.rows_sent": "1000",
"mysql.slowlog.timestamp": "1533630467",
"mysql.slowlog.user": "apphost"
},
{
"@timestamp": "2018-08-07T08:27:47.000Z",
"ecs.version": "1.0.0-beta2",
"event.dataset": "slowlog",
"event.module": "mysql",
"input.type": "log",
"log.flags": [
"multiline"
],
"log.offset": 1438,
"mysql.slowlog.host": "apphost",
"mysql.slowlog.id": "10999834",
"mysql.slowlog.ip": "1.1.1.1",
"mysql.slowlog.lock_time.sec": "0.000036",
"mysql.slowlog.query": "call load_stats(1, '2017-04-28 00:00:00');",
"mysql.slowlog.query_time.sec": "10.346539",
"mysql.slowlog.rows_examined": "4751313",
"mysql.slowlog.rows_sent": "0",
"mysql.slowlog.timestamp": "1533630467",
"mysql.slowlog.user": "apphost"
}
]