parse_multiline no longer working (worked in legacy agent)

[codeconsole]

Ever since upgrading from the legacy agent, I have not been able to get multiline exception parsing to work. The exception appears in the logs line by line instead of being grouped into an individual entry.

    parse_java_multiline:
      type: parse_multiline
      match_any:
        - type: language_exceptions
          language: java

  service:
    pipelines:
      my_pipeline:
        receivers: [my_log]
        processors: [parse_java_multiline, extract_structure, move_severity]

Sample log entry:

2023-11-16 22:55:02.447 ERROR --- [io-8080-exec-12] com.demo.SearchService                 [192.168.0.1,9002]: co.elastic.clients.elasticsearch._types.ElasticsearchException: [es/search] failed: [search_phase_execution_exception] all shards failed
        at co.elastic.clients.transport.rest_client.RestClientTransport.getHighLevelResponse(RestClientTransport.java:337)
        at co.elastic.clients.transport.rest_client.RestClientTransport.performRequest(RestClientTransport.java:155)
        at co.elastic.clients.elasticsearch.ElasticsearchClient.search(ElasticsearchClient.java:1887)
        at co.elastic.clients.elasticsearch.ElasticsearchClient.search(ElasticsearchClient.java:1904)
        at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at com.demo.DemoService.search(DemoService.groovy:190)
        at com.demo.DemoService.search(DemoService.groovy:318)
        at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at com.demo.DemoController.demo(DemoController.groovy:263)

I followed the documentation here

Why isn't able to capture that exception? Is the formatting very specific or something? Is there documentation on the exact format it is looking for?

[codeconsole]

Here is another exception that does not get processed into 1 line:

2023-11-16 20:50:34.909 ERROR --- [io-8080-exec-16] o.g.web.errors.GrailsExceptionResolver   [192.168.0.1,71619999]: groovy.lang.MissingMethodException: No signature of method: com.demo.DemoService.thumb() is applicable for argument types: (null, null, null, Integer, null, null) values: [null, null, null, 202345, null, null]
Possible solutions: dump(), thumb(long, java.lang.Long, java.lang.Long, java.lang.Integer), thumb(long, java.lang.Long, java.lang.Long, java.lang.Integer, java.lang.Integer), thumb(long, java.lang.Long, java.lang.Long, java.lang.Integer, java.lang.Integer, java.lang.Integer)
        at com.demo.DemoController.thumb(DemoController.groovy:546)

at com.demo.DemoController.thumb(DemoController.groovy:546) ends up as a separate log entry

[codeconsole]

https://github.com/GoogleCloudPlatform/ops-agent/blob/f38c005f422f1336cac23871b2e051e02715eb1b/apps/tomcat.go#L68-L90

[codeconsole]

    "java": {`"start_state, java_start_exception"  "/(?:Exception|Error|Throwable|V8 errors stack trace)[:\r\n]/" "java_after_exception"`,
            `"java_nested_exception" "/(?:Exception|Error|Throwable|V8 errors stack trace)[:\r\n]/" "java_after_exception"`,
            `"java_after_exception" "/^[\t ]*nested exception is:[\\t ]*/" "java_nested_exception"`,
            `"java_after_exception" "/^[\r\n]*$/" "java_after_exception"`,
            `"java_after_exception" "/^[\t ]+(?:eval )?at /" "java_after_exception"`,
            `"java_after_exception" "/^[\t ]+--- End of inner exception stack trace ---$/" "java_after_exception"`,
            `"java_after_exception" "/^--- End of stack trace from previous (?x:)location where exception was thrown ---$/" "java_after_exception"`,
            `"java_after_exception" "/^[\t ]*(?:Caused by|Suppressed):/" "java_after_exception"`,
            `"java_after_exception" "/^[\t ]*... \d+ (?:more|common frames omitted)/" "java_after_exception"`},

[codeconsole]

I am not quite understanding what it doesn't like about the first line

2023-11-16 20:50:34.909 ERROR --- [io-8080-exec-16] o.g.web.errors.GrailsExceptionResolver   [192.168.0.1,71619999]: groovy.lang.MissingMethodException: No signature of...

that causes it to not honor parse_java_multiline

I wish there was better documentation.

[LujieDuan]

Hey @codeconsole,

Thanks for reporting the issue. I tried to reproduce this on my side with this config:

logging:
  receivers:
    files_1:
      type: files
      include_paths: test.log
      record_log_file_path: true
      wildcard_refresh_interval: 30s
  processors:
    multiline_parser_1:
      type: parse_multiline
      match_any:
      - type: language_exceptions
        language: java
  service:
    pipelines:
      p1:
        receivers: [files_1]
        processors: [multiline_parser_1]

The first exception got parsed correctly into one log:

{
  "insertId": ...,
  "jsonPayload": {
    "message": "2023-11-16 22:55:02.447 ERROR --- [io-8080-exec-12] com.demo.SearchService                 [192.168.0.1,9002]: co.elastic.clients.elasticsearch._types.ElasticsearchException: [es/search] failed: [search_phase_execution_exception] all shards failed\n        at co.elastic.clients.transport.rest_client.RestClientTransport.getHighLevelResponse(RestClientTransport.java:337)\n        at co.elastic.clients.transport.rest_client.RestClientTransport.performRequest(RestClientTransport.java:155)\n        at co.elastic.clients.elasticsearch.ElasticsearchClient.search(ElasticsearchClient.java:1887)\n        at co.elastic.clients.elasticsearch.ElasticsearchClient.search(ElasticsearchClient.java:1904)\n        at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)\n        at com.demo.DemoService.search(DemoService.groovy:190)\n        at com.demo.DemoService.search(DemoService.groovy:318)\n        at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)\n        at com.demo.DemoController.demo(DemoController.groovy:263)\n"
  },
  "resource": ...,
  ...
  ]
}

The second exception was not combined, but sent as three individual logs. It is probably caused by the second line:

Possible solutions: dump(), thumb(long, java.lang.Long, java.lang.Long, java.lang.Integer), thumb(long, java.lang.Long, java.lang.Long, java.lang.Integer, java.lang.Integer), thumb(long, java.lang.Long, java.lang.Long, java.lang.Integer, java.lang.Integer, java.lang.Integer)

is not normally expected and did not get matched by any of the java_after_exception or java_nested_exception pattern.

It would work if the second exception is

2023-11-16 20:50:34.909 ERROR --- [io-8080-exec-16] o.g.web.errors.GrailsExceptionResolver   [192.168.0.1,71619999]: groovy.lang.MissingMethodException: No signature of method: com.demo.DemoService.thumb() is applicable for argument types: (null, null, null, Integer, null, null) values: [null, null, null, 202345, null, null] Possible solutions: dump(), thumb(long, java.lang.Long, java.lang.Long, java.lang.Integer), thumb(long, java.lang.Long, java.lang.Long, java.lang.Integer, java.lang.Integer), thumb(long, java.lang.Long, java.lang.Long, java.lang.Integer, java.lang.Integer, java.lang.Integer)
        at com.demo.DemoController.thumb(DemoController.groovy:546)

To further assist with this issue and to help us reproduce on our side:

1. Could you share the full config in order to look into exception 1?
2. For exception 2 - could you check if the second line is indeed on its own new line? And whether the format of the exception can be changed from the application side?
3. Would exception 2 get parsed by the legacy agent for you before?

Thanks!