Strang things happened when logstash grok the log message

[houfan]

I use filebeat-1.2.2 to monitor the mysql-slow.log.
when I add two slow query records in it,

and the logstash only give me one :

I do it again,adding two more records into the mysql-slow.log:

hehe.... just like the first time,logstash only give me one result:

I tried the third time:

and aha!!! this I got two results.I don't know why....

could you tell me why ?
really appreciate!!!

[houfan]

this is my logstash.conf .

[magnusbaeck (Magnus Bäck)]

Please don't post screenshots. Use copy/paste.

[houfan]

ok....

[guyboertje]

Do we presume you are using the Filebeat config from here

[guyboertje]

@houfan

You only get one event because the the second one's lines are being buffered internally - filebeat can only know when a previous set of lines is fully collected when the first line of the next set is seen.

[houfan]

after so many times I have tried,I figured out the reason is ：

if [message] =~ "^# administrator" {
drop {}
}
if [message] =~ "^# Time" {
drop {}
}

this part didn't work right .It will drop much more messages than expect. cos when I delete this line

Time: 161214 11:32:21

and then logstash will give the correct two results.
I add this grok pattern at the end :(?:# Time:.*\n).

> (?m)^# User@Host: %{USER:User}\[[^\]]+\] @ (?:(?<clienthost>\S*) )?\[(?:%{IP:Client_IP})?\]\s+Id:\s+%{NUMBER:row_id:int}\n# Schema: %{WORD:Schema}\s+Last_errno: %{NUMBER}\s+Killed: %{NUMBER}\n# Query_time: %{NUMBER:Query_Time:float}\s+Lock_time: %{NUMBER:Lock_Time:float}\s+Rows_sent: %{NUMBER:Rows_Sent:int}\s+Rows_examined: %{NUMBER:Rows_Examined:int}\s+Rows_affected: %{NUMBER:Rows_affected:int}\n(?:# Bytes_sent: %{NUMBER:Byte_sent:int}\n)+(?:use %{DATA:database};\s*\n)?SET\s+timestamp=%{NUMBER:timestamp};(?:\n)?(?<sql>(?<action>\w+)\b.*;)?(?:\n)?(?:# Time:.*\n)?

logstash drop the first line “# Time: 161214 11:32:21”,and the whole messages (that the grok pattern matched )next.
at the end logstash only give one result.