Multiline not picking up events immediately

Elastic Stack Logstash
#1

This is my conf file -

file{
path => "C:/Logs/*"
codec => multiline
{
pattern => "%{WORD:EventId} : %{NUMBER:EventID}, %{WORD:Level} : %{WORD:EventLevel}, %{WORD:Message} : %{WORD:Operation}, %{WORD:Payload} : [%{WORD:Session_ID} : %{UUID:SessionID}] [%{WORD:IPAddress} : %{IPORHOST:ClientIPAddress}] [%{WORD:Method} : %{WORD:HTTP_Verb}] [%{WORD:requestUri} : %{URI:URL}] [%{WORD:content} : %{DATA:Request}] , %{WORD:EventName} : %{WORD:EventNameValue}, %{WORD:Timestamp} : %{TIMESTAMP_ISO8601:Request_DateTime}, %{WORD:ProcessId} : %{NUMBER:ProcessID}, %{WORD:ThreadID} : %{NUMBER:ThreadID}"
what => next
}
}

The problem is - Multiline not picking up the events as soon as the log is written. It is picking up the the first one only when the second one with the same pattern is written.

eg. my first log -
EventId : 1, Level : Informational, Message : Request, Payload : [sessionID : 3e4ad1b0-2d2d-4f77-90b3-6315aacfacb7] [ipAddress : 67.29.26.92] [method : GET] [requestUri : http://server1:8080/MyService/api/products/6900/availability/] [content : ] , EventName : RequestInfo, Timestamp : 2016-04-05T14:35:36.4947170Z, ProcessId : 8924, ThreadId : 3008

my second log -
EventId : 1, Level : Informational, Message : Request, Payload : [sessionID : 3e4ad1b0-2d2d-4f77-90b3-6315aacfacb7] [ipAddress : 67.29.26.92] [method : GET] [requestUri : http://server1:8080/MyService/api/products/6900/availability/] [content : ] , EventName : RequestInfo, Timestamp : 2016-04-05T14:35:36.4947170Z, ProcessId : 8924, ThreadId : 3008

My first log is captured only when the my second log is written. I tried both "what => next and what => previous". Same result.

What am i missing here ??

#2

Because it needs to wait for the next event to know when the previous one has finished.

#3

But that would be a problem for me. Because in my case, I send a request to my service and i get a response back.

If i need to see the values in Kibana, logstash needs to pull that up immediately.

But now, I have to fire another request-response, then the first one will be captured. Don't you think this is wierd or is there anything that I am missing here.

#4

pattern => "%{WORD:EventId} : %{NUMBER:EventID}, %{WORD:Level} : %{WORD:EventLevel}, %{WORD:Message} : %{WORD:Operation}, %{WORD:Payload} : [%{WORD:Session_ID} : %{UUID:SessionID}] [%{WORD:IPAddress} : %{IPORHOST:ClientIPAddress}] [%{WORD:Method} : %{WORD:HTTP_Verb}] [%{WORD:requestUri} : %{URI:URL}] [%{WORD:content} : %{DATA:Request}] , %{WORD:EventName} : %{WORD:EventNameValue}, %{WORD:Timestamp} : %{TIMESTAMP_ISO8601:Request_DateTime}, %{WORD:ProcessId} : %{NUMBER:ProcessID}, %{WORD:ThreadID} : %{NUMBER:ThreadID}"

This is functionally equivalent to:

pattern => "%{WORD} : %{NUMBER}, %{WORD} : ...

But again, use literal strings when you want literal matches:

pattern => "EventId : %{NUMBER}, Level : ...

Where's the newline character in these log examples, i.e. which two (or more) lines do you want to join? Your multiline pattern doesn't make sense to me and since I don't understand what your input looks like I can't make an improvement suggestion.

#5

I got this to be working. In my above example, multiline was not present. Here is another example where I need to have multiline func.
I have reduced my log example here -

Logs is in below format and keeps on writing on basis of my service hits. Every service call below 2 lines are written.

Log 1 -
ProviderId : 46875d78-3924-5303-f49e-65b8bc0dc289
EventId : 1

Log 2 -
ProviderId : 46875d78-3924-5303-f49e-65b8bc0dc290
EventId : 2

Log 1 is not captured until log 2 is written. Thats my prb. I wanted log 1 to be captured as soon as it is wrritten in the log file.

#6

It seems a configuration like

pattern => "^ProviderId: "
what => "next"

should work and give the desired result. Your most recent example doesn't match the configuration you posted earlier to it's hard to tell what's wrong.

#7

You can ignore my first post.

I have my conf with (pattern => "^ProviderId: " what => "next"). It is capturing the event. The only prb is "it is not capturing the log as soon as it is written to my log file". It is captured only when the next log with same pattern is written into the same file. That is because it is looking for the pattern.

I have figured out a solution for this. I wont be using multiline. I will be using multiple match patterns.
But now another prb has arised :frowning: Need to capture, entire stack trace.

Payload : [sessionID : 20cb9749-3db7-4bb2-bd72-5f397664ed24] [type : InvalidMethodArgumentException] [data : ] [innerException : ] [message : The CallID field is required.] [source : MySol.Services.Common] [stackTrace : at MySol.Services.Common.Entities.Database.BaseEFService1.<SaveAsync>d__0.MoveNext() in e:\Builds\15\CR\Main.QA\src\MyWebService\MySol.Services.Common\Entities\Database\BaseEFService.cs:line 101 --- End of stack trace from previous location where exception was thrown --- at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task) at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at MySol.Services.Common.Entities.Database.BaseEFCreateService3.d__3.MoveNext() in e:\Builds\15\CR\Main.QA\src\MyWebService\MySol.Services.Common\Entities\Database\BaseEFCreateService.cs:line 47
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at MySol.API.Common.MessageHandlers.CreateCRRRequestHeadersMessageHandler.d__0.MoveNext() in e:\Builds\15\CR\Main.QA\src\MyWebService\MySol.API.Common\MessageHandlers\CreateCRRRequestHeadersMessageHandler.cs:line 58] [targetSite : Void MoveNext()]

Got this working in GROK debugger - [stackTrace : (?(.|\r|\n)*)]. But this is not working in my logstash.conf file.

What am I missing here magnus ?

#8

Can you post your config file here?

#9

Conf -

input
{
file
{
path => "C:/MyLogs/*"
#start_position => "beginning"
}
}

filter
{
grok
{
match =>
{
"message" =>
[
"ProviderId : %{UUID:SessionID}",
"EventId : %{NUMBER:EventId}",
"Payload : [sessionID : %{UUID:SessionID}] [type : %{WORD:ExceptionType}] [data : %{DATA:Data}] [innerException : %{DATA:InnerException}] [message : %{DATA:ExceptionMessage}] [source : %{DATA:ExceptionSource}] [stackTrace : (?(.|\r|\n)*)]",
"EventName : %{WORD:EventName}",
"ProcessId : %{NUMBER:ProcessId}",
"ThreadId : %{NUMBER:ThreadId}"
]
}
}

mutate
{
	add_field => { "Type" => "ApiExceptionEventSource" }
	
	rename => { "path" => "Path" }
	rename => { "host" => "Host" }
}

}

output
{
stdout
{
codec => rubydebug
}
}

Log Pattern -

ProviderId : 46875d78-3924-5303-f49e-65b8bc0dc289
EventId : 11
Payload : [sessionID : 19c6fd3f-79d5-406a-9d93-f1ada6bc6fde] [type : InvalidMethodArgumentException] [data : ] [innerException : ExceptionMessage] [message : The CallID field is required.] [source : MySol.Services.Common] [stackTrace : at MySol.Services.Common.Entities.Database.BaseEFService1.<SaveAsync>d__0.MoveNext() in e:\Builds\15\IR\Main.QA\src\WebServiceSln\MySol.Services.Common\Entities\Database\BaseEFService.cs:line 101 --- End of stack trace from previous location where exception was thrown --- at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task) at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at MySol.Services.Common.Entities.Database.BaseEFCreateService3.d__3.MoveNext() in e:\Builds\15\IR\Main.QA\src\WebServiceSln\MySol.Services.Common\Entities\Database\BaseEFCreateService.cs:line 47
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at MySol.API.Common.MessageHandlers.CreateIRRRequestHeadersMessageHandler.d__0.MoveNext() in e:\Builds\15\IR\Main.QA\src\WebServiceSln\MySol.API.Common\MessageHandlers\CreateIRRRequestHeadersMessageHandler.cs:line 58] [targetSite : Void MoveNext()]
EventName : ResponseInfo
ProcessId : 21096
ThreadId : 12336

Multiline not processing event until pipeline stops
#10

Doesn't the max_age parameter work? By default a multiline message should be flushed after waiting 5 seconds for additional lines. What version of Logstash are you using?

#11

I havent tried the max_age parameter. Will look into that. I am using the logstash 2.2.2 version.

#12

The max_age worked.

multiline
{
pattern => "^ProviderId : "
what => "previous"
negate => true
max_age => 3
}

Also, i saw the same issue logged on github "https://github.com/logstash-plugins/logstash-codec-multiline/issues/11". The fix was the same.

There is only one thing concerning me here is about the THREAD. What challenges/issues will i face being on single thread ?

←[33mDefaulting pipeline worker threads to 1 because there are some filters that
might not work with multiple worker threads {:count_was=>4, :filters=>["multili
ne"], :level=>:warn}←[0m

#13

Running just one pipeline worker could obviously impact the total throughput.

#14

It is also worth noting that the multiline filter is being deprecated. A solution might be to use Fiebeat to send data to Logstash, as it supports multiline processing and allows a timeout to be configured to ensure the last event is sent.

#15

Thanks Christian. I was using FB prev. But removed it since log stash was doing everything it did.

As per your suggestion, i will defn look into the link and will use fb for multiline processing.
If you could provide an sample multiline in fb link, it would be more helpful.

#16

I tried using the multiline in FB. It worked. But, when i tried sending the FB data to Logstash, i could see duplicate entries happening for each log captured.

Pasted image640×511 6.5 KB

LS Conf -
input { beats { port => 4434 } }
output { stdout { codec => rubydebug } }

FB -
multiline:
pattern: "^ProviderId :"
negate: true
match: after

What am I missing here ? Why is it happening twice ?

#17

Any update on this please ?

#18