search

vectordotdev / vector

A high-performance observability data pipeline.
https://vector.dev
Mozilla Public License 2.0
17.58k stars 1.54k forks source link

Parser for Java logs | parsing java in vector #7941

Open alpiua opened 3 years ago

alpiua commented 3 years ago

Hello!

It would be great if Vector will receive more simple management of Java logs. It might be needed in multi line support as well as VRL function similar to "parse_nginx_log" etc.

Multiline I'm using expression like this to combine strings from all cases I faced in my app. Finally it looks complete and no strings left out. Timeout is so huge because when it is lesser logs sometimes are getting splitted.

start_pattern = '^[^\s]'
mode = "continue_through"
condition_pattern = '(?m)^[\s|\W].*$|(?m)^(Caused|java|org|com|net).+$|(?m)^\}.*$'
timeout_ms = 1000000000

Parsing To get a timestamp, level, message etc. It could be a few scenarios

  1. from Java log output - the pattern like this is covering my cases:

    . |= parse_regex!(.message,r'^(?P<timestamp>\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}.\d{3}) (?P<level>\w+) (?s)(?P<message>.*$)')
.timestamp = parse_timestamp(.timestamp,"%Y-%m-%d %H:%M:%S.%3f") ?? now()

  2. from Java app stdout. The difference is that stdout producing only %H:%M:%S timestamp. 

    . |= parse_regex!(.message,r'^(?P<time>\d{2}:\d{2}:\d{2},\d{3}) \|-(?P<level>\w+) (?s)(?P<message>.*$)')                                       
.timestamp = parse_timestamp(join!([format_timestamp!(now(),format: "%Y-%m-%d"),.time],separator:" "),"%Y-%m-%d %H:%M:%S,%3f") ?? now()

    It looks a bit over complicated to set a proper timestamp on this stage - I should get current date before to split it with the extracted time. I think there is no way to determinate timestamp 100% properly, because there can be that the log record from yesterday or a few days ago will get the current date. It seems, the only way to prevent such miscalculation is to setup logrotate on the host os, to prevent Vector from reading yesterdays files.

Appreciate any help improving this, as I'm not very professional in regexp writing, and looking forward to see the function which will cover all diversity in future.

jszwedko commented 3 years ago

Hi @alpi-ua !

Thanks for reporting this.

I'm using expression like this to combine strings from all cases I faced in my app. Finally it looks complete and no strings left out. Timeout is so huge because when it is lesser logs sometimes are getting splitted.

I think this might be fixed by #7944

Regarding parsing the logs, do you mean specifically parsing Java stack traces? Would you be able to share an example log you'd like to parse?

alpiua commented 3 years ago

Would you be able to share an example log you'd like to parse?

I'll check if I can share when have some time. There is a bunch of different log events in different places.

Regarding parsing the logs, do you mean specifically parsing Java stack traces?

Not sure what you mean by parsing Java stack traces. I need to combine trace related to specific timestamp to one log message. So afterwards I can extract a timestamp and level from this event.

I think this might be fixed by #7944

That's great! Will wait until it will be fixed in the new version.

jszwedko commented 3 years ago

Not sure what you mean by parsing Java stack traces. I need to combine trace related to specific timestamp to one log message. So afterwards I can extract a timestamp and level from this event.

:+1: the log examples will be helpful. I just want to get an understanding of the shape of the logs you want to parse (e.g. log4j, vs. stacktraces, vs. sfl4j).

alpiua commented 3 years ago

@jszwedko sorry for the delay

The logs are looks like this:

2021-07-19 18:55:15.842 INFO  [longTaskExecutor-10] c.s.app.iso8583.RoutingAdapter - Sending message: id=iso(mti=1110,rrn=120015860779,stan=860779,transmitted=null,f12=210719185513,f13=null), source=dialectAdapter, request=responseIsoMessage, group=null, payload=IsoMessage
2021-07-19 18:56:03.576 INFO  [Netty-Worker-123-1-8] c.s.s.iso8583.adapter.123 - Iso adapter features updated + -
2021-07-19 18:56:03.577 INFO  [longTaskExecutor-20] c.s.app.iso8583.RoutingAdapter - Sending message: id=TxnModel[class=AUTHORIZATION,category=REQUEST,initiator=ACQUIRER,direction=ORIGINAL,request=true,stan=357270,rrn=120018357270,orn=,rc=], source=dialectAdapter, request=requestIsoMessage, group=iso-upc, payload=TxnModel
2021-07-19 18:56:05.027 INFO  [longTaskExecutor-15] c.s.app.iso8583.RoutingAdapter - Sending message: id=iso(mti=1110,rrn=120018357270,stan=357270,transmitted=null,f12=210719185603,f13=null), source=dialectAdapter, request=responseIsoMessage, group=null, payload=IsoMessage
2021-07-19 18:56:07.569 INFO  [Netty-Worker-123-1-8] c.s.s.iso8583.adapter.123 - Iso adapter features updated + -
2021-07-19 18:56:07.570 INFO  [longTaskExecutor-13] c.s.app.iso8583.RoutingAdapter - Sending message: id=TxnModel[class=AUTHORIZATION,category=REQUEST,initiator=ACQUIRER,direction=ORIGINAL,request=true,stan=086289,rrn=120018086289,orn=,rc=], source=dialectAdapter, request=requestIsoMessage, group=iso-upc, payload=TxnModel

another app

2021-07-19 19:03:10.879 TRACE [pool-6-thread-1] c.s.s.i.r.QQQqzzzz - Applied a request to send message to QQQQ: "Message{header=MessageHeader{messageId=43977baa-7b76-43c0-83c8-69868c4bccb6, timestamp=2021-07-19T19:03:10.879119, syncKey=null, sourceApp='null', source='missionControlAdapter', destinationApp='app-apppp', destination='managementServerAdapter', request='mc.statisticsServerService.getNodeStatistics', group='mc-apppp-node1', sourceNodeId='air-node1', destinationNodeId='apppp-node1', allowedConsumer='null', response=null, processingException=null}, payload=[], sessionData=SessionData{userId=42, locale=en_US}, filtersParameters={PRODUCER_PARAMS={"MSG_EXPIRATION":5000,"MSG_DEAD_LETTER_MODE":"RECEIVE_DEAD_LETTER"}}}"
2021-07-19 19:03:10.879 TRACE [pool-6-thread-1] c.s.s.i.r.QQQqzzzz - Destination node is defined explicitly: "apppp-node1"
2021-07-19 19:03:10.879 TRACE [pool-6-thread-1] c.s.s.i.r.QQQqzzzz - Sending message "43977baa-7b76-43c0-83c8-69868c4bccb6" to exchange "app-apppp.apppp-node1.direct" synchronously
2021-07-19 19:03:10.902 TRACE [pool-6-thread-1] c.s.s.i.r.QQQqzzzz - Received synchronous response for message "43977baa-7b76-43c0-83c8-69868c4bccb6"
2021-07-19 19:03:12.080 DEBUG [DefaultDispatcher-worker-1] c.s.app.commons.jdbc.JdbcExecutor - Executing query: pendingReports.ppp

stdout log with error (app logs have the same error style)

14:17:57,302 |-INFO in ch.qos.logback.classic.AsyncAppender[COMMON] - Queue flush finished successfully within timeout.
14:17:57,303 |-ERROR in com..app.commons.logger.logback.appDbAppender[solarDbAppender] - Failed to append the event: [INFO] SmthPool-2 -
        at com..app.commons.exception.appException: java.sql.SQLException: SmthDataSource SmthDataSource (SmthPool-2) has been closed
        at      at com..app.app.datasource.appDataSource.lambda$getConnection$2(gggggDataSource.java:352)
        at      at com..app.app.datasource.appDataSource.getConnection(gggggDataSource.java:430)
        at      at com..app.app.datasource.appDataSource.getConnection(gggggDataSource.java:348)
        at      at ch.qos.logback.core.db.DataSourceConnectionSource.getConnection(DataSourceConnectionSource.java:62)
        at      at com..app.commons.logger.logback.appDbAppender.append(gggggDbAppender.java:230)
        at      at com..app.commons.logger.logback.appDbAppender.append(gggggDbAppender.java:40)
        at      at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:84)
        at      at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:51)
        at      at ch.qos.logback.core.AsyncAppenderBase$Worker.run(AsyncAppenderBase.java:290)
Caused by: java.sql.SQLException: SmthDataSource SmthDataSource (SmthPool-2) has been closed.
        at      at com.zaxxer.smm.SmthDataSource.getConnection(SmthDataSource.java:96)
        at      at com..app.app.datasource.appDataSource.lambda$getConnection$2(gggggDataSource.java:350)
        at      ... 8 common frames omitted
14:17:57,304 |-INFO in ch.qos.logback.classic.AsyncAppender[appAsyncDbAppender] - Worker thread will flush remaining events before exiting.
14:17:57,304 |-INFO in ch.qos.logback.classic.AsyncAppender[appAsyncDbAppender] - Queue flush finished successfully within timeout.
jszwedko commented 3 years ago

Gotcha, thanks for the examples @alpi-ua . That looks vaguely like a log4j layout pattern. Do you know if that is what is being used? The concern I have is that this isn't a standard format so the parsing is likely to need to be customized as you have done.

The stack traces, on the other hand, are a fairly standard format that we could support an automatic parser for.

bbeaudreault commented 12 months ago

I stumbled across this issue. I'm not sure what the original author wanted specific to their case, but I think it'd be great if there was a parse_log4j(.message, "%d{ISO8601} [%t] %p %c: %m%n"). The second argument is a log4j layout pattern as documented here.

mrofisr commented 7 months ago

Hi Folks!

Any update for this issues? because i have some problem to parse stack trace java log

Thanks