How to view elasticsearch publisher errors?

[mbezjak]

Hi Bruno. I'm playing around with mulog with elasticsearch publisher.

Long story short. Here is a minimal example that is causing me trouble.

(mulog/log ::server-started (keyword "") 1)

Some other silly code produced an equivalent of this. However, that got me thinking. How will I see if the app made some error that needs to be corrected?

I saw here that exceptions get put into an atom. But ES is a bit special. Debugging this, here is what I found out:

1. Wireshark confirms that this was sent to ES
2. ES responded with an error

{"took":0,"errors":true,"items":[{"index":{"_index":"mulog-2021.07.23","_type":"_doc","_id":"4dGYOCKQKZHXx3reYDSDyubtuy9keDKG","status":400,"error":{"type":"mapper_parsing_exception","reason":"failed to parse","caused_by":{"type":"illegal_argument_exception","reason":"object field starting or ending with a [.] makes object resolution ambiguous: [.i]"}}}}]}

3. The full response for com.brunobonacci.mulog.publishers.elasticsearch/post-records was

{:cached nil,
 :request-time 7,
 :repeatable? false,
 :protocol-version {:name "HTTP", :major 1, :minor 1},
 :streaming? true,
 :http-client
 #object[org.apache.http.impl.client.InternalHttpClient 0x12783998 "org.apache.http.impl.client.InternalHttpClient@12783998"],
 :chunked? false,
 :reason-phrase "OK",
 :headers
 {"Warning"
  "299 Elasticsearch-7.13.4-c5f60e894ca0c61cdbae4f5a686d9f08bcefc942 \"Elasticsearch built-in security features are not enabled. Without authentication, your cluster could be accessible to anyone. See https://www.elastic.co/guide/en/elasticsearch/reference/7.13/security-minimal-setup.html to enable security.\"",
  "content-type" "application/json; charset=UTF-8",
  "content-length" "268"},
 :orig-content-encoding "gzip",
 :status 200,
 :length 268,
 :body
 "{\"took\":0,\"errors\":true,\"items\":[{\"index\":{\"_index\":\"mulog-2021.07.23\",\"_type\":\"_doc\",\"_id\":\"4dGYlra3A6rkAdFmEdlNerncRn-IRIXI\",\"status\":400,\"error\":{\"type\":\"mapper_parsing_exception\",\"reason\":\"failed to parse\",\"caused_by\":{\"type\":\"illegal_argument_exception\",\"reason\":\"object field starting or ending with a [.] makes object resolution ambiguous: [.i]\"}}}}]}",
 :trace-redirects []}

4. com.brunobonacci.mulog.publishers.elasticsearch/post-records just silently ignored ES errors because the HTTP status was 200

So it seems that ES errors are silently ignored, the event is marked as processed and removed from the buffer.

[BrunoBonacci]

Hi @mbezjak

if the publisher "fails" to publish the message it will log an event called :mulog/publisher-error with the :publisher-type :elasticsearch actual exception,
for example here is a connection error:

{:mulog/event-name :mulog/publisher-error,
 :mulog/timestamp 1627040534626,
 :mulog/trace-id #mulog/flake "4dGcjizz5YJcmAcD3uFXtNPJEMBJ9SwH",
 :mulog/action :publish,
 :mulog/namespace "clojure.core",
 :mulog/origin :mulog/core,
 :exception #error {
 :cause "Connection refused"
 :via
 [{:type java.net.ConnectException
   :message "Connection refused"
   :at [sun.nio.ch.Net pollConnect "Net.java" -2]}]
 :trace
 [[sun.nio.ch.Net pollConnect "Net.java" -2]
  [sun.nio.ch.Net pollConnectNow "Net.java" 669]
  [sun.nio.ch.NioSocketImpl timedFinishConnect "NioSocketImpl.java" 549]
  [sun.nio.ch.NioSocketImpl connect "NioSocketImpl.java" 597]
  [java.net.SocksSocketImpl connect "SocksSocketImpl.java" 333]
  [java.net.Socket connect "Socket.java" 645]
  [org.apache.http.conn.socket.PlainConnectionSocketFactory connectSocket "PlainConnectionSocketFactory.java" 75]
  [....]
  [clj_http.client$post invokeStatic "client.clj" 1192]
  [clj_http.client$post doInvoke "client.clj" 1188]
  [clojure.lang.RestFn invoke "RestFn.java" 423]
  [com.brunobonacci.mulog.publishers.elasticsearch$post_records invokeStatic "elasticsearch.clj" 109]
  [com.brunobonacci.mulog.publishers.elasticsearch$post_records invoke "elasticsearch.clj" 107]
  [com.brunobonacci.mulog.publishers.elasticsearch.ElasticsearchPublisher publish "elasticsearch.clj" 208]
  [com.brunobonacci.mulog.core$start_publisher_BANG_$publish_attempt__6894 invoke "core.clj" 194]
  [clojure.core$binding_conveyor_fn$fn__5772 invoke "core.clj" 2037]
  [...]
  [java.util.concurrent.ThreadPoolExecutor$Worker run "ThreadPoolExecutor.java" 630]
  [java.lang.Thread run "Thread.java" 831]]},
 :publisher-id "4dGceC0jrihRomo3Hbp0vKfZllMlVbjG",
 :publisher-type :elasticsearch}

The event is added to the publishing buffers so if the problem is transitory you'll get the errors in your destination system.
Alternatively, if you have multiple publishers set up the error will be published in the alternative systems.

μ/log elasticsearch publisher considers a "failed" request anything that is not in the HTTP 2xx.

Failed requests are retried automatically with no special code to be added. So transitory issues (network partitions, 1 bad record, etc) will eventually succeed and the system self-heal.

Unfortunately, partial success/failures are generally not handled well in HTTP and each API does it differently.
The HTTP standard committee added HTTP 207 MULTI-STATUS, but the reality is that this status code is rarely used and not well handled. Even if Elasticsearch was using the correct status code, most likely clj-http would just consider it as a successful response anyway.

If you need to quickly work around this issue you can add a custom transformation function at the publisher level and amend the bad records before they are published.

I will have to add a custom fix for this issue, thank you for providing the details of how to reproduce and sample responses.

[BrunoBonacci]

Added this issue: #79