Unable to parse the mule logs in logstash

Elastic Stack Logstash
1

Hi Team,

I am trying to parse the mule application logs logstash, tried different options but unable to achieve it.

My sample logs:

2020-12-18 10:27:10,666 [[hl7v2-ORU-message-processor-api].hl7v2-fhir-api-flowsFlow.stage1.01] ERROR com.refarch.logging.dip.ExceptionLoggingInterceptor - {"environment":"devrcf_us-env","applicationName":"hl7v2-ORU-message-processor-api","correlationId":"0-962a5052-411b-11eb-bb83-0623f984381d","apiProcessingTime":245,"totalProcessingTime":64579,"tracePoint":"EXCEPTION","logMessage":"{\n "status": "ERROR",\n "bundleId": "6fd1b970-411b-11eb-bb83-0623f984381d",\n "serviceName": "hl7v2-message-processor Service",\n "errorMessage": "Technical error occurred.",\n "errorDesc": "Exception while executing flowRef common-mapping-custom-flow (java.lang.RuntimeException)."\n}","txnMetadata":{"bundleId":"6fd1b970-411b-11eb-bb83-0623f984381d","messageType":"HL7V2","facilityAlias":"ROCHE","systemName":"REFARCH_V2","messageSubType":"ORU R01","transactionStartTime":1608287166087,"relatesToPatientMerge":false}}

2020-12-21 12:47:38,907 [[hl7v2-message-processor-api].hl7v2-fhir-api-flowsFlow.stage1.01] INFO com.refarch.dip.logging.CustomLoggingInterceptor - {"environment":"devrcf_us-env","applicationName":"hl7v2-message-processor-api","correlationId":"0-b15f1b02-438a-11eb-8eaf-0623f984381d","apiProcessingTime":6376,"totalProcessingTime":8635,"tracePoint":"END","logMessage":null,"txnMetadata":{"bundleId":"b006de03-438a-11eb-8eaf-0623f984381d","messageType":"HL7V2","facilityAlias":"ROCHE","systemName":"REFARCH_V2","messageSubType":"ORM O01","transactionStartTime":1608554850272,"relatesToPatientMerge":false}}

2020-12-21 12:47:30,790 [[object-store-api].object-store-api-httpListenerConfig.worker.652] INFO com.refarch.dip.logging.CustomLoggingInterceptor - {"environment":"devrcf_us-env","applicationName":"object-store-api","correlationId":"0-b0552512-438a-11eb-8eaf-0623f984381d","apiProcessingTime":0,"totalProcessingTime":0,"tracePoint":"START","logMessage":"START Logger","txnMetadata":{"bundleId":"b006de03-438a-11eb-8eaf-0623f984381d","messageType":"HL7V2","facilityAlias":"ROCHE","systemName":"REFARCH_V2","messageSubType":"ORM O01","transactionStartTime":1608554850272,"relatesToPatientMerge":false}}

like this i have different patterns, i want to generalize parsing of the logs and also want view custom fields in kibana like "transaction metada,bundleId,facilityAlias,etc.."

could you please help me to achieve this

2

What have you tried?

3

Hi Badger,

I am sending the input from filebeat and parsing in logstash for the same i have tried below code

input {
beats {
port => 5044
ssl => true
ssl_certificate => "/etc/logstash/logstash.crt"
ssl_key => "/etc/logstash/logstash.key"
#Multiline filter is for combining multiple logs lines if it doen't starts with the timestamp

               }
      }

filter {
grok {

match => { "message" => "%{TIMESTAMP_ISO8601:timestamp} \[%{GREEDYDATA:endpoint}\] %{LOGLEVEL:log_level} %{GREEDYDATA:msgbody}"}

            overwrite => [ "message" ]
            #add_tag => ["log_level", "timestamp", "endpoint" ]

}

if [Log_level] == "INFO" or [Log_level] == "WARN" or [Log_level] == "ERROR" {
kv {
#source => "msgbody"
field_split => ":"
transform_key => "capitalize"
transform_value => "capitalize"
trim_key => "\s"
trim_value => "\s"
include_brackets => false

                    }

mutate
{
gsub => ['message', "\n", " "]
#rename => ["message", "Payload"]
}
output {
elasticsearch {
hosts => ["http://localhost:9200"]

====================================================================
Challenge here is i am able to send the logs(as it is) and view in kibana, but unable to parse and unable to extract the fields from the log message.
Could you please help me here

Thanks,
Vinod

4

Please edit your post, select the logs, and click on </> in the toolbar above the edit pane. It will change the preview pane from

2020-12-21 12:47:38,907 [[hl7v2-message-processor-api].hl7v2-fhir-api-flowsFlow.stage1.01] INFO com.refarch.dip.logging.CustomLoggingInterceptor - {"environment":"devrcf_us-env","applicationName":"hl7v2-message-processor-api","correlationId":"0-b15f1b02-438a-11eb-8eaf-0623f984381d","apiProcessingTime":6376,"totalProcessingTime":8635,"tracePoint":"END","logMessage":null,"txnMetadata":{"bundleId":"b006de03-438a-11eb-8eaf-0623f984381d","messageType":"HL7V2","facilityAlias":"ROCHE","systemName":"REFARCH_V2","messageSubType":"ORM O01","transactionStartTime":1608554850272,"relatesToPatientMerge":false}}

2020-12-21 12:47:30,790 [[object-store-api].object-store-api-httpListenerConfig.worker.652] INFO com.refarch.dip.logging.CustomLoggingInterceptor - {"environment":"devrcf_us-env","applicationName":"object-store-api","correlationId":"0-b0552512-438a-11eb-8eaf-0623f984381d","apiProcessingTime":0,"totalProcessingTime":0,"tracePoint":"START","logMessage":"START Logger","txnMetadata":{"bundleId":"b006de03-438a-11eb-8eaf-0623f984381d","messageType":"HL7V2","facilityAlias":"ROCHE","systemName":"REFARCH_V2","messageSubType":"ORM O01","transactionStartTime":1608554850272,"relatesToPatientMerge":false}}

to

2020-12-21 12:47:38,907 [[hl7v2-message-processor-api].hl7v2-fhir-api-flowsFlow.stage1.01] INFO com.refarch.dip.logging.CustomLoggingInterceptor - {"environment":"devrcf_us-env","applicationName":"hl7v2-message-processor-api","correlationId":"0-b15f1b02-438a-11eb-8eaf-0623f984381d","apiProcessingTime":6376,"totalProcessingTime":8635,"tracePoint":"END","logMessage":null,"txnMetadata":{"bundleId":"b006de03-438a-11eb-8eaf-0623f984381d","messageType":"HL7V2","facilityAlias":"ROCHE","systemName":"REFARCH_V2","messageSubType":"ORM O01","transactionStartTime":1608554850272,"relatesToPatientMerge":false}}

2020-12-21 12:47:30,790 [[object-store-api].object-store-api-httpListenerConfig.worker.652] INFO com.refarch.dip.logging.CustomLoggingInterceptor - {"environment":"devrcf_us-env","applicationName":"object-store-api","correlationId":"0-b0552512-438a-11eb-8eaf-0623f984381d","apiProcessingTime":0,"totalProcessingTime":0,"tracePoint":"START","logMessage":"START Logger","txnMetadata":{"bundleId":"b006de03-438a-11eb-8eaf-0623f984381d","messageType":"HL7V2","facilityAlias":"ROCHE","systemName":"REFARCH_V2","messageSubType":"ORM O01","transactionStartTime":1608554850272,"relatesToPatientMerge":false}}

You could try something like:

    grok { match => { "message" => "%{TIMESTAMP_ISO8601:timestamp} \[%{GREEDYDATA:endpoint}\] %{LOGLEVEL:log_level} %{JAVACLASS:classname} - %{GREEDYDATA:msgbody}"} }
    mutate { gsub => [ "msgbody", "\\n", "" ] }
    json { source => "msgbody" }

The first line does not parse, but that could be because the browser is eating some of the characters. That's why you need the </>, to preserve the text.

5 
2020-12-18 10:27:10,666 [[hl7v2-ORU-message-processor-api].hl7v2-fhir-api-flowsFlow.stage1.01] ERROR com.refarch.logging.dip.ExceptionLoggingInterceptor - {"environment":"devrcf_us-env","applicationName":"hl7v2-ORU-message-processor-api","correlationId":"0-962a5052-411b-11eb-bb83-0623f984381d","apiProcessingTime":245,"totalProcessingTime":64579,"tracePoint":"EXCEPTION","logMessage":"{\n  \"status\": \"ERROR\",\n  \"bundleId\": \"6fd1b970-411b-11eb-bb83-0623f984381d\",\n  \"serviceName\": \"hl7v2-message-processor Service\",\n  \"errorMessage\": \"Technical error occurred.\",\n  \"errorDesc\": \"Exception while executing flowRef common-mapping-custom-flow (java.lang.RuntimeException).\"\n}","txnMetadata":{"bundleId":"6fd1b970-411b-11eb-bb83-0623f984381d","messageType":"HL7V2","facilityAlias":"ROCHE","systemName":"REFARCH_V2","messageSubType":"ORU R01","transactionStartTime":1608287166087,"relatesToPatientMerge":false}}

2020-12-21 12:47:30,790 [[object-store-api].object-store-api-httpListenerConfig.worker.652] INFO  com.refarch.dip.logging.CustomLoggingInterceptor - {"environment":"devrcf_us-env","applicationName":"object-store-api","correlationId":"0-b0552512-438a-11eb-8eaf-0623f984381d","apiProcessingTime":0,"totalProcessingTime":0,"tracePoint":"START","logMessage":"START Logger","txnMetadata":{"bundleId":"b006de03-438a-11eb-8eaf-0623f984381d","messageType":"HL7V2","facilityAlias":"ROCHE","systemName":"REFARCH_V2","messageSubType":"ORM O01","transactionStartTime":1608554850272,"relatesToPatientMerge":false}}

2020-12-21 12:47:38,907 [[hl7v2-message-processor-api].hl7v2-fhir-api-flowsFlow.stage1.01] INFO  com.refarch.dip.logging.CustomLoggingInterceptor - {"environment":"devrcf_us-env","applicationName":"hl7v2-message-processor-api","correlationId":"0-b15f1b02-438a-11eb-8eaf-0623f984381d","apiProcessingTime":6376,"totalProcessingTime":8635,"tracePoint":"END","logMessage":null,"txnMetadata":{"bundleId":"b006de03-438a-11eb-8eaf-0623f984381d","messageType":"HL7V2","facilityAlias":"ROCHE","systemName":"REFARCH_V2","messageSubType":"ORM O01","transactionStartTime":1608554850272,"relatesToPatientMerge":false}}

2020-12-21 05:36:57,171 [[xds-message-api].XDR-HTTP-endpoint.worker.411] ERROR org.mule.module.http.internal.listener.grizzly.MuleSslFilter - SSL handshake error: null cert chain

sorry for the inconvenience, please fine the formatted logs above.
i will try the above method as you suggested. But how can get the custome fields fom the log message. ex: bundleId ,environment, facilityAlias, etc..

6

I changed the grok slightly...

    grok { match => { "message" => "%{TIMESTAMP_ISO8601:timestamp} \[%{GREEDYDATA:endpoint}\] %{LOGLEVEL:log_level}\s+%{JAVACLASS:classname} - %{GREEDYDATA:msgbody}"} }
    mutate { gsub => [ "msgbody", "\\n", "" ] }
    json { source => "msgbody" }

The logs are mostly JSON, so the json filter will produce

          "log_level" => "INFO",
"totalProcessingTime" => 0,
          "timestamp" => "2020-12-21 12:47:30,790",
         "logMessage" => "START Logger",
        "environment" => "devrcf_us-env",
        "txnMetadata" => {
              "messageType" => "HL7V2",
    "relatesToPatientMerge" => false,
                 "bundleId" => "b006de03-438a-11eb-8eaf-0623f984381d",
           "messageSubType" => "ORM O01",
     "transactionStartTime" => 1608554850272,
            "facilityAlias" => "ROCHE",
               "systemName" => "REFARCH_V2"
},

etc.

7

Thank you so much for the solution, but logstash is failling with the below error

[2020-12-21T17:55:15,482][WARN ][logstash.filters.json    ] Error parsing json {:source=>"msgbody", :raw=>"MimeType was not resolved '*/*' delegating to Java.", :exception=>#<LogStash::Json::ParserError: Unrecognized token 'MimeType': was expecting ('true', 'false' or 'null')

Can you please help

8

That one is not JSON, so an error is expected.

9

ok.. In that case how can i generalize the pattern, because application may produce different type of logs.
If i miss some of the logs that might be a issue again. So how can i proceed. Can you please suggest.

10

What do you want to extract from that message?

11 
2020-12-22 07:28:12,635 [[file-message-acceptance-api].post:/validate/message:validate-messages-config.stage1.04] ERROR com.refarch.logging.dip.ExceptionLoggingInterceptor - {"environment":"devrcf_us-env","applicationName":"file-message-acceptance-api","correlationId":"0-3f6c5652-4427-11eb-9e7a-0623f984381d","apiProcessingTime":287,"totalProcessingTime":2594,"tracePoint":"EXCEPTION","logMessage":"{\n  \"status\": \"ERROR\",\n  \"serviceName\": \"Message Acceptance Service\",\n  \"errorMessage\": \"Technical error occured while processing request\",\n  \"errorDesc\": \"Exception while executing: \\n[{cd_paciente=1458358, dh_fechamento=2020-06-23T02:00:00.000Z, fonte=HSL, nm_paciente=MARLENE SILVA DE ABREU------, cd_atendimento=323230011, text_prestador=prestador erika assis de lima - crm: 44444444, estadiamentopatologico_t=1, dt_nascimento=1934-01-19T02:00:00.000Z, cd_prestador=23019, tipodetumor=adenocarcinoma, cd_editor_registro=1419519, estadiamentoclinico_n=1, estadiamentoclinico_m=1, estadiamentopatologico_m=1, tumorboard=hepato, estadiamentopatologico_n=0, nr_cpf=183760972111111, estadiamentoclinico_t=3, localizacaotumor=figado}, {cd_atendimento=3232300, cd_editor_registro=14195198, cd_paciente=1458358, cd_prestador=23019, dh_fechamento=2020-06-23T02:00:00.000Z, dt_nascimento=1934-01-19T02:00:00.000Z, estadiamentoclinico_m=1, estadiamentoclinico_n=1, estadiamentoclinico_t=3, estadiamentopatologico_m=1, estadiamentopatologico_n=0, estadiamentopatologico_t=1, fonte=HSL, localizacaotumor=figado, nm_paciente=MARLENE SILVA DE ABREU, nr_cpf=1837609721, text_prestador=prestador erika assis de lima - crm: 44444444, tipodetumor=adenocarcinoma, tumorboard=hepato}]\\n  ^\\nUnexpected character 'c' at payload@[1:3] (line:column), expected '\\\"'.\"\n}","txnMetadata":{"bundleId":"3e0d6290-4427-11eb-9e7a-0623f984381d-1","messageType":"CUSTOM-JSON-FLATFILE","facilityAlias":"ROCHE","systemName":"REFARCH_FLATFILE","messageSubType":"Custom-PatientFetch","transactionStartTime":1608622090041}}
2020-12-22T11:27:25.953+0000 INFO class com.roche.dip.cep.logging.interceptor.CustomResponseBodyAdviceAdapter: {"path":"/CEP/healthCheck","responseHeaders":{"StatusCode":"200"},"method":"GET","metaDataType":"response","body":"Welcome to CEP!"}

Foe example if you consider the above log which is similar to above log(json log), i am unable to extract the fields from the log message.
Can u please help

12

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