Collect list of log statements from various services we'd like to get alerts for

[amoeba]

There are a number of silent failures in various services (sync, indexing, etc) that are logged but otherwise tend to go unnoticed until a later date. While we continue working to make services more robust and add instrumentation where needed, it seems to me we can set up some form of proactive monitoring and alerting system on our logs to catch known issues sooner.

We agreed to start by keeping a running list of log output lines for known silent failures. Eventually, the list could be used to set up said monitoring and alerting system.

[amoeba]

From @mbjones:

Synchronizing error for a PID on timeout, which never gets rescheduled, produces log lines like:

[ERROR] 2022-05-05 13:31:21,250 [SynchronizeTask21] (V2TransferObjectTask:call:276) Task-urn:node:mnTestHAKAI_IYS-sha256:bab2a26ca6c8791b0a7042835b2fbbfc84e8a945159c9da379869947b12b6d51 - UnrecoverableException: Unexpected Exception from CN /resolve !getSystemMetadata failed: ServiceFailure - 0000: [CONCURRENT_MAP_CONTAINS_KEY] Operation Timeout (with no response!): 0 - ServiceFailure - getSystemMetadata failed: ServiceFailure - 0000: [CONCURRENT_MAP_CONTAINS_KEY] Operation Timeout (with no response!): 0 org.dataone.cn.batch.exceptions.UnrecoverableException: Unexpected Exception from CN /resolve !getSystemMetadata failed: ServiceFailure - 0000: [CONCURRENT_MAP_CONTAINS_KEY] Operation Timeout (with no response!): 0

[amoeba]

From Metacat, if Solr is unresponsive, an index task can fail without being rescheduled with log lines like:

/var/log/tomcat8/catalina.out.1:metacat-index 20220429-15:07:07: [ERROR]: SolrIndex.update - could not update the solr index for the object resource_map_urn:uuid:15b94a55-e2a7-45ca-b12b-df1d454aa1b6 since Timeout occurred while waiting response from server at: http://localhost:8983/solr/metacat-index [edu.ucsb.nceas.metacat.index.SolrIndex:update:611]

[mbjones]

When indexing fails, the task is removed from the NEW list and does not get retried, with the following in the cn-index-processor-daemon.log:

[ INFO] 2022-05-06 06:30:40,167 (IndexTaskProcessor:saveTask:892) IndexTaskProcess.saveTask save the index task sha256:bab2a26ca6c8791b0a7042835b2fbbfc84e8a945159c9da379869947b12b6d51 [ INFO] 2022-05-06 06:30:40,167 (IndexTaskProcessor:getNextIndexTask:624) Start of indexing pid: sha256:bab2a26ca6c8791b0a7042835b2fbbfc84e8a945159c9da379869947b12b6d51 [ INFO] 2022-05-06 06:30:40,204 (IndexTaskProcessor:isObjectPathReady:834) Valid Object Path could not be found for pid: sha256:bab2a26ca6c8791b0a7042835b2fbbfc84e8a945159c9da379869947b12b6d51 Checked path strings in the task [null] and Hazelcast [null] [ INFO] 2022-05-06 06:30:40,204 (IndexTaskProcessor:newOrFailedIndexTaskExists:917) IndexTaskProcess.newOrFailedIndexTaskExists for id sha256:bab2a26ca6c8791b0a7042835b2fbbfc84e8a945159c9da379869947b12b6d51 [ INFO] 2022-05-06 06:30:40,325 (IndexTaskProcessor:saveTask:892) IndexTaskProcess.saveTask save the index task sha256:bab2a26ca6c8791b0a7042835b2fbbfc84e8a945159c9da379869947b12b6d51 [ INFO] 2022-05-06 06:30:40,325 (IndexTaskProcessor:getNextIndexTask:633) Task for pid: sha256:bab2a26ca6c8791b0a7042835b2fbbfc84e8a945159c9da379869947b12b6d51 not processed since the object path is not ready.

This also leaves behind a FAILED entry in the index queue database which we could monitor via the check_mk check_sql check pretty easily:

d1-index-queue=# select pid,status,formatId from index_task where pid like '%bab2a26ca6c8791b0a7042835b2fbbfc84e8a945159c9da379869947b12b6d51';
                                   pid                                   | status |               formatid
-------------------------------------------------------------------------+--------+---------------------------------------
 sha256:bab2a26ca6c8791b0a7042835b2fbbfc84e8a945159c9da379869947b12b6d51 | FAILED | science-on-schema.org/Dataset;ld+json
(1 row)