Logstash pipeline stalling without any error

Stephy · October 21, 2021, 8:35am

Hello,
We have a Logstash pipeline (using the official elastic.co Docker Image v7.9.3) running with a JDBC input plugin and Elasticsearch output. Pipeline is set to run with a schedule every 1 minute (* * * * *). The input plugin fetches data from a Oracle DB via a select statement.
Logstash version used: 7.9.3
Elasticsearch version used: 7.9.3

Config: 
input {
  jdbc {
    jdbc_driver_library => "/usr/share/logstash/driver/ojdbc8.jar"
    jdbc_driver_class => "Java::oracle.jdbc.driver.OracleDriver"
    jdbc_connection_string => ""
    jdbc_user => ""
    jdbc_password => ""
    jdbc_fetch_size => 1000
    statement => 'select * from [TABLE] WHERE ("[TIMESTAMP COLUMN]" IS NOT NULL) AND ("[TIMESTAMP COLUMN]" > :sql_last_value)'
    tracking_column => [TIMESTAMP COLUMN]
    tracking_column_type => "timestamp"
    record_last_run => true
    schedule => "* * * * *"
    last_run_metadata_path => "/usr/share/logstash/config/lastrun/[FILENAME].yml"
 }
}

Problem: This is running fine for days, even weeks. However, at some time, seemingly random, the SQL statement is not executed any longer. This means new data is not indexed.

So sometimes the pipeline suddenly stops executing/stalls until restarted, the timestamp for the last_run doesn’t get updated but the container stays up and the Logstash pipeline is running. We are still able to exec into the container and verify that Java processes are running. Elasticsearch is also running.

Evidence: The last logs that we have in the pipeline is DEBUG and as follows:
Note that these logs are not from when the error occurred (we couldn’t get the logs for the error as they were much older) but these logs keep appearing again and again after

[2021-10-12T06:21:18,783][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ParNew"}
[2021-10-12T06:21:18,784][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ConcurrentMarkSweep"}
[2021-10-12T06:21:19,623][DEBUG][org.logstash.execution.PeriodicFlush][main] Pushing flush onto pipeline.
[2021-10-12T06:21:23,787][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ParNew"}
[2021-10-12T06:21:23,787][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ConcurrentMarkSweep"}
[2021-10-12T06:21:24,623][DEBUG][org.logstash.execution.PeriodicFlush][main] Pushing flush onto pipeline.
[2021-10-12T06:21:28,789][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ParNew"}
[2021-10-12T06:21:28,789][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ConcurrentMarkSweep"}
[2021-10-12T06:21:29,623][DEBUG][org.logstash.execution.PeriodicFlush][main] Pushing flush onto pipeline.
[2021-10-12T06:21:33,791][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ParNew"}
[2021-10-12T06:21:33,792][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ConcurrentMarkSweep"}
[2021-10-12T06:21:34,623][DEBUG][org.logstash.execution.PeriodicFlush][main] Pushing flush onto pipeline.
[2021-10-12T06:21:38,795][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ParNew"}
[2021-10-12T06:21:38,795][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ConcurrentMarkSweep"}
[2021-10-12T06:21:39,623][DEBUG][org.logstash.execution.PeriodicFlush][main] Pushing flush onto pipeline.

grumo35 · October 21, 2021, 9:19am

Hey,

Could you manage to find older logs or reproduce this ?

Really tough to know what is happening here.

Stephy · October 25, 2021, 1:58pm

Hello, @grumo35 thanks for the quick response!

As we said earlier we didn't have the logs for the time when the error occured, but it happened again and we managed to get the logs and they are as follows:

Note 25.10.2021 at 8.33 am last run --- 2021-10-23 22:33:00.430548000 Z

[2021-10-23T22:33:00,129][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ParNew"}
[2021-10-23T22:33:00,129][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ConcurrentMarkSweep"}
[2021-10-23T22:33:00,432][INFO ][logstash.inputs.jdbc     ][main][4543523041e9fa437a13e2badb0b37fd40ddd6daf0b037c957d478599992b93b] (0.001213s) select version from PRODUCT_COMPONENT_VERSION where lower(product) like 'oracle%'
[2021-10-s:33:02,127][DEBUG][org.logstash.execution.PeriodicFlush][main] Pushing flush onto pipeline.
[2021-10-23T22:33:05,132][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ParNew"}
[2021-10-23T22:33:05,132][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ConcurrentMarkSweep"}
[2021-10-23T22:33:07,127][DEBUG][org.logstash.execution.PeriodicFlush][main] Pushing flush onto pipeline.
[2021-10-23T22:33:10,135][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ParNew"}
[2021-10-23T22:33:10,135][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ConcurrentMarkSweep"}
[2021-10-23T22:33:12,127][DEBUG][org.logstash.execution.PeriodicFlush][main] Pushing flush onto pipeline.
[2021-10-23T22:33:14,504][INFO ][logstash.inputs.jdbc     ][main][4543523041e9fa437a13e2badb0b37fd40ddd6daf0b037c957d478599992b93b] (14.071635s) SELECT count(*) "COUNT" FROM (select * from [TABLE] WHERE ("[TIMESTAMP]" IS NOT NULL) AND ("[TIMESTAMP]" > TIMESTAMP '2021-10-23 22:32:00.380394 +00:00')) "T1" FETCH NEXT 1 ROWS ONLY
[2021-10-23T22:33:14,504][DEBUG][logstash.inputs.jdbc     ][main][4543523041e9fa437a13e2badb0b37fd40ddd6daf0b037c957d478599992b93b] Executing JDBC query {:statement=>"select * from [TABLE] WHERE (\"[TIMESTAMP]\" IS NOT NULL) AND (\"[TIMESTAMP]\" > :sql_last_value)", :parameters=>{:sql_last_value=>2021-10-23 22:32:00 UTC}, :count=>1}
[2021-10-23T22:33:15,137][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ParNew"}
[2021-10-23T22:33:15,137][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ConcurrentMarkSweep"}
[2021-10-23T22:33:17,127][DEBUG][org.logstash.execution.PeriodicFlush][main] Pushing flush onto pipeline.
[2021-10-23T22:33:20,140][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ParNew"}
[2021-10-23T22:33:20,140][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ConcurrentMarkSweep"}
[2021-10-23T22:33:22,127][DEBUG][org.logstash.execution.PeriodicFlush][main] Pushing flush onto pipeline.
[2021-10-23T22:33:25,143][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ParNew"}
[2021-10-23T22:33:25,143][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ConcurrentMarkSweep"}
[2021-10-23T22:33:27,127][DEBUG][org.logstash.execution.PeriodicFlush][main] Pushing flush onto pipeline.
[2021-10-23T22:33:28,849][INFO ][logstash.inputs.jdbc     ][main][4543523041e9fa437a13e2badb0b37fd40ddd6daf0b037c957d478599992b93b] (14.344335s) select * from [TABLE] WHERE ("[TIMESTAMP]" IS NOT NULL) AND ("[TIMESTAMP]" > TIMESTAMP '2021-10-23 22:32:00.380394 +00:00')
[2021-10-23T22:33:28,950][DEBUG][logstash.filters.json    ][main][ea78aa9d17e89f4752df02bc56b1364d558e4f25b793dc35bc730cdb26fe6bc7] Running json filter {:event=>#<LogStash::Event:0x6c63d838>}
[2021-10-23T22:33:28,950][DEBUG][logstash.filters.json    ][main][ea78aa9d17e89f4752df02bc56b1364d558e4f25b793dc35bc730cdb26fe6bc7] Event after json filter {:event=>#<LogStash::Event:0x6c63d838>}
[2021-10-23T22:33:28,950][DEBUG][logstash.filters.mutate  ][main][781a094209145cf7fe1e3636912095c1bd19ad7f01e1dd153c727792627a2cd1] filters/LogStash::Filters::Mutate: removing field {:field=>"title_attribute_array"}
[2021-10-23T22:33:28,950][DEBUG][logstash.filters.mutate  ][main][781a094209145cf7fe1e3636912095c1bd19ad7f01e1dd153c727792627a2cd1] filters/LogStash::Filters::Mutate: removing field {:field=>"title_attribute"}
[2021-10-23T22:33:28,950][DEBUG][logstash.filters.mutate  ][main][781a094209145cf7fe1e3636912095c1bd19ad7f01e1dd153c727792627a2cd1] filters/LogStash::Filters::Mutate: removing field {:field=>"metadata_value"}
[2021-10-23T22:33:28,950][DEBUG][logstash.filters.mutate  ][main][781a094209145cf7fe1e3636912095c1bd19ad7f01e1dd153c727792627a2cd1] filters/LogStash::Filters::Mutate: removing field {:field=>"metadata_value_array"}
[2021-10-23T22:33:28,950][DEBUG][logstash.filters.mutate  ][main][781a094209145cf7fe1e3636912095c1bd19ad7f01e1dd153c727792627a2cd1] filters/LogStash::Filters::Mutate: removing field {:field=>"metadata_value_array_new"}
[2021-10-23T22:33:28,950][DEBUG][logstash.util.decorators ][main][e668bebbd841e4d6fb2ede5fc59336b35fb64279b42fc6acbd225e8d17162921] filters/LogStash::Filters::Mutate: adding value to field {"field"=>"i_autocomplete", "value"=>["%{short_title}"]}
[2021-10-23T22:33:28,950][DEBUG][logstash.util.decorators ][main][4fbd7d4a0c1af8d282ea4baab6a71a3e4718182d1a48b187c6a82fee15e02b04] filters/LogStash::Filters::Mutate: adding value to field {"field"=>"title_complement_spelling_correction", "value"=>["%{title_complement}"]}
[2021-10-23T22:33:28,951][DEBUG][org.apache.http.client.protocol.RequestAuthCache][main][4d240c3e583460b56a6c34de864823c32285dfb39611226f8de2edd061136e19] Re-using cached 'basic' auth scheme for [PROTOCOL:URL:PORT]
[2021-10-23T22:33:28,951][DEBUG][org.apache.http.impl.conn.PoolingHttpClientConnectionManager][main][4d240c3e583460b56a6c34de864823c32285dfb39611226f8de2edd061136e19] Connection request: [route: {s}->[PROTOCOL:URL:PORT]][total kept alive: 1; route allocated: 1 of 100; total allocated: 1 of 1000]
[2021-10-23T22:33:28,951][DEBUG][org.apache.http.impl.conn.CPool][main][4d240c3e583460b56a6c34de864823c32285dfb39611226f8de2edd061136e19] Connection [id:320486][route:{s}->[PROTOCOL:URL:PORT]][state:null] expired @ Sat Oct 23 22:32:32 UTC 2021
[2021-10-23T22:33:28,951][DEBUG][org.apache.http.impl.conn.DefaultManagedHttpClientConnection][main][4d240c3e583460b56a6c34de864823c32285dfb39611226f8de2edd061136e19] http-outgoing-320486: Close connection
[2021-10-23T22:33:28,951][DEBUG][org.apache.http.impl.conn.PoolingHttpClientConnectionManager][main][4d240c3e583460b56a6c34de864823c32285dfb39611226f8de2edd061136e19] Connection leased: [id: 320487][route: {s}->[PROTOCOL:URL:PORT]][total kept alive: 0; route allocated: 1 of 100; total allocated: 1 of 1000]
[2021-10-23T22:33:28,951][DEBUG][org.apache.http.impl.execchain.MainClientExec][main][4d240c3e583460b56a6c34de864823c32285dfb39611226f8de2edd061136e19] Opening connection {s}->[PROTOCOL:URL:PORT]
[2021-10-23T22:33:28,955][DEBUG][org.apache.http.impl.conn.DefaultHttpClientConnectionOperator][main][4d240c3e583460b56a6c34de864823c32285dfb39611226f8de2edd061136e19] Connecting to [URL]/[IP]:443
[2021-10-23T22:33:28,955][DEBUG][org.apache.http.conn.ssl.SSLConnectionSocketFactory][main][4d240c3e583460b56a6c34de864823c32285dfb39611226f8de2edd061136e19] Connecting socket to [URL]/[IP]:443 with timeout 10000
[2021-10-23T22:33:28,955][DEBUG][org.apache.http.conn.ssl.SSLConnectionSocketFactory][main][4d240c3e583460b56a6c34de864823c32285dfb39611226f8de2edd061136e19] Enabled protocols: [TLSv1.3, TLSv1.2, TLSv1.1, TLSv1]
[2021-10-23T22:33:28,955][DEBUG][org.apache.http.conn.ssl.SSLConnectionSocketFactory][main][4d240c3e583460b56a6c34de864823c32285dfb39611226f8de2edd061136e19] Enabled cipher suites:[TLS_AES_128_GCM_SHA256, TLS_AES_256_GCM_SHA384, TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384, TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256, TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384, TLS_RSA_WITH_AES_256_GCM_SHA384, TLS_ECDH_ECDSA_WITH_AES_256_GCM_SHA384, TLS_ECDH_RSA_WITH_AES_256_GCM_SHA384, TLS_DHE_RSA_WITH_AES_256_GCM_SHA384, TLS_DHE_DSS_WITH_AES_256_GCM_SHA384, TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256, TLS_RSA_WITH_AES_128_GCM_SHA256, TLS_ECDH_ECDSA_WITH_AES_128_GCM_SHA256, TLS_ECDH_RSA_WITH_AES_128_GCM_SHA256, TLS_DHE_RSA_WITH_AES_128_GCM_SHA256, TLS_DHE_DSS_WITH_AES_128_GCM_SHA256, TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA384, TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA384, TLS_RSA_WITH_AES_256_CBC_SHA256, TLS_ECDH_ECDSA_WITH_AES_256_CBC_SHA384, TLS_ECDH_RSA_WITH_AES_256_CBC_SHA384, TLS_DHE_RSA_WITH_AES_256_CBC_SHA256, TLS_DHE_DSS_WITH_AES_256_CBC_SHA256, TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA, TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA, TLS_RSA_WITH_AES_256_CBC_SHA, TLS_ECDH_ECDSA_WITH_AES_256_CBC_SHA, TLS_ECDH_RSA_WITH_AES_256_CBC_SHA, TLS_DHE_RSA_WITH_AES_256_CBC_SHA, TLS_DHE_DSS_WITH_AES_256_CBC_SHA, TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA256, TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA256, TLS_RSA_WITH_AES_128_CBC_SHA256, TLS_ECDH_ECDSA_WITH_AES_128_CBC_SHA256, TLS_ECDH_RSA_WITH_AES_128_CBC_SHA256, TLS_DHE_RSA_WITH_AES_128_CBC_SHA256, TLS_DHE_DSS_WITH_AES_128_CBC_SHA256, TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA, TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA, TLS_RSA_WITH_AES_128_CBC_SHA, TLS_ECDH_ECDSA_WITH_AES_128_CBC_SHA, TLS_ECDH_RSA_WITH_AES_128_CBC_SHA, TLS_DHE_RSA_WITH_AES_128_CBC_SHA, TLS_DHE_DSS_WITH_AES_128_CBC_SHA, TLS_EMPTY_RENEGOTIATION_INFO_SCSV]

Stephy · October 25, 2021, 2:00pm

Continuation of the logs:

[2021-10-23T22:33:28,955][DEBUG][org.apache.http.conn.ssl.SSLConnectionSocketFactory][main][4d240c3e583460b56a6c34de864823c32285dfb39611226f8de2edd061136e19] Starting handshake
[2021-10-23T22:33:28,962][DEBUG][org.apache.http.conn.ssl.SSLConnectionSocketFactory][main][4d240c3e583460b56a6c34de864823c32285dfb39611226f8de2edd061136e19] Secure session established
[2021-10-23T22:33:28,962][DEBUG][org.apache.http.conn.ssl.SSLConnectionSocketFactory][main][4d240c3e583460b56a6c34de864823c32285dfb39611226f8de2edd061136e19]  negotiated protocol: TLSv1.2
[2021-10-23T22:33:28,962][DEBUG][org.apache.http.conn.ssl.SSLConnectionSocketFactory][main][4d240c3e583460b56a6c34de864823c32285dfb39611226f8de2edd061136e19]  negotiated cipher suite: TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384
[2021-10-23T22:33:28,962][DEBUG][org.apache.http.conn.ssl.SSLConnectionSocketFactory][main][4d240c3e583460b56a6c34de864823c32285dfb39611226f8de2edd061136e19]  peer principal: CN=[URL], O=[O], C=[C]
[2021-10-23T22:33:28,962][DEBUG][org.apache.http.conn.ssl.SSLConnectionSocketFactory][main][4d240c3e583460b56a6c34de864823c32285dfb39611226f8de2edd061136e19]  peer alternative names: [[URL]]
[2021-10-23T22:33:28,962][DEBUG][org.apache.http.conn.ssl.SSLConnectionSocketFactory][main][4d240c3e583460b56a6c34de864823c32285dfb39611226f8de2edd061136e19]  issuer principal: CN=[CN], O=[O], C=[C]
[2021-10-23T22:33:28,962][DEBUG][org.apache.http.impl.conn.DefaultHttpClientConnectionOperator][main][4d240c3e583460b56a6c34de864823c32285dfb39611226f8de2edd061136e19] Connection established [IP]:[PORT]<->[IP]:443
[2021-10-23T22:33:28,962][DEBUG][org.apache.http.impl.conn.DefaultManagedHttpClientConnection][main][4d240c3e583460b56a6c34de864823c32285dfb39611226f8de2edd061136e19] http-outgoing-320487: set socket timeout to 60000
[2021-10-23T22:33:28,962][DEBUG][org.apache.http.impl.execchain.MainClientExec][main][4d240c3e583460b56a6c34de864823c32285dfb39611226f8de2edd061136e19] Executing request POST /_bulk HTTP/1.1
[2021-10-23T22:33:28,962][DEBUG][org.apache.http.impl.execchain.MainClientExec][main][4d240c3e583460b56a6c34de864823c32285dfb39611226f8de2edd061136e19] Target auth state: CHALLENGED
[2021-10-23T22:33:28,962][DEBUG][org.apache.http.impl.execchain.MainClientExec][main][4d240c3e583460b56a6c34de864823c32285dfb39611226f8de2edd061136e19] Proxy auth state: UNCHALLENGED
[2021-10-23T22:33:28,962][DEBUG][org.apache.http.headers  ][main][4d240c3e583460b56a6c34de864823c32285dfb39611226f8de2edd061136e19] http-outgoing-320487 >> POST /_bulk HTTP/1.1
[2021-10-23T22:33:28,962][DEBUG][org.apache.http.headers  ][main][4d240c3e583460b56a6c34de864823c32285dfb39611226f8de2edd061136e19] http-outgoing-320487 >> Connection: Keep-Alive
[2021-10-23T22:33:28,962][DEBUG][org.apache.http.headers  ][main][4d240c3e583460b56a6c34de864823c32285dfb39611226f8de2edd061136e19] http-outgoing-320487 >> Content-Type: application/json
[2021-10-23T22:33:28,962][DEBUG][org.apache.http.headers  ][main][4d240c3e583460b56a6c34de864823c32285dfb39611226f8de2edd061136e19] http-outgoing-320487 >> Content-Length: 3376
[2021-10-23T22:33:28,962][DEBUG][org.apache.http.headers  ][main][4d240c3e583460b56a6c34de864823c32285dfb39611226f8de2edd061136e19] http-outgoing-320487 >> Host: [URL]:443
[2021-10-23T22:33:28,962][DEBUG][org.apache.http.headers  ][main][4d240c3e583460b56a6c34de864823c32285dfb39611226f8de2edd061136e19] http-outgoing-320487 >> User-Agent: Manticore 0.7.0
[2021-10-23T22:33:28,962][DEBUG][org.apache.http.headers  ][main][4d240c3e583460b56a6c34de864823c32285dfb39611226f8de2edd061136e19] http-outgoing-320487 >> Accept-Encoding: gzip,deflate
[2021-10-23T22:33:28,962][DEBUG][org.apache.http.headers  ][main][4d240c3e583460b56a6c34de864823c32285dfb39611226f8de2edd061136e19] http-outgoing-320487 >> Authorization: Basic [KEY]
[2021-10-23T22:33:28,962][DEBUG][org.apache.http.wire     ][main][4d240c3e583460b56a6c34de864823c32285dfb39611226f8de2edd061136e19] http-outgoing-320487 >> "POST /_bulk HTTP/1.1[\r][\n]"
[2021-10-23T22:33:28,962][DEBUG][org.apache.http.wire     ][main][4d240c3e583460b56a6c34de864823c32285dfb39611226f8de2edd061136e19] http-outgoing-320487 >> "Connection: Keep-Alive[\r][\n]"
[2021-10-23T22:33:28,962][DEBUG][org.apache.http.wire     ][main][4d240c3e583460b56a6c34de864823c32285dfb39611226f8de2edd061136e19] http-outgoing-320487 >> "Content-Type: application/json[\r][\n]"
[2021-10-23T22:33:28,962][DEBUG][org.apache.http.wire     ][main][4d240c3e583460b56a6c34de864823c32285dfb39611226f8de2edd061136e19] http-outgoing-320487 >> "Content-Length: 3376[\r][\n]"
[2021-10-23T22:33:28,962][DEBUG][org.apache.http.wire     ][main][4d240c3e583460b56a6c34de864823c32285dfb39611226f8de2edd061136e19] http-outgoing-320487 >> "Host: [URL]:443[\r][\n]"
[2021-10-23T22:33:28,962][DEBUG][org.apache.http.wire     ][main][4d240c3e583460b56a6c34de864823c32285dfb39611226f8de2edd061136e19] http-outgoing-320487 >> "User-Agent: Manticore 0.7.0[\r][\n]"
[2021-10-23T22:33:28,962][DEBUG][org.apache.http.wire     ][main][4d240c3e583460b56a6c34de864823c32285dfb39611226f8de2edd061136e19] http-outgoing-320487 >> "Accept-Encoding: gzip,deflate[\r][\n]"
[2021-10-23T22:33:28,962][DEBUG][org.apache.http.wire     ][main][4d240c3e583460b56a6c34de864823c32285dfb39611226f8de2edd061136e19] http-outgoing-320487 >> "Authorization: Basic [KEY]"
[2021-10-23T22:33:28,962][DEBUG][org.apache.http.wire     ][main][4d240c3e583460b56a6c34de864823c32285dfb39611226f8de2edd061136e19] http-outgoing-320487 >> "[\r][\n]"
[2021-10-23T22:33:28,963][DEBUG][org.apache.http.wire     ][main][4d240c3e583460b56a6c34de864823c32285dfb39611226f8de2edd061136e19] http-outgoing-320487 >> "{"update":{"_id":"[DOCID]","_index":"[INDEX]","routing":null,"_type":"_doc","retry_on_conflict":1}}[\n]"
[2021-10-23T22:33:28,963][DEBUG][org.apache.http.wire     ][main][4d240c3e583460b56a6c34de864823c32285dfb39611226f8de2edd061136e19] http-outgoing-320487 >> "{"doc":{[DOCUMENT]},"doc_as_upsert":true}[\n]"
[2021-10-23T22:33:28,984][DEBUG][org.apache.http.wire     ][main][4d240c3e583460b56a6c34de864823c32285dfb39611226f8de2edd061136e19] http-outgoing-320487 << "HTTP/1.1 200 OK[\r][\n]"
[2021-10-23T22:33:28,985][DEBUG][org.apache.http.wire     ][main][4d240c3e583460b56a6c34de864823c32285dfb39611226f8de2edd061136e19] http-outgoing-320487 << "Date: Sat, 23 Oct 2021 22:33:28 GMT[\r][\n]"
[2021-10-23T22:33:28,985][DEBUG][org.apache.http.wire     ][main][4d240c3e583460b56a6c34de864823c32285dfb39611226f8de2edd061136e19] http-outgoing-320487 << "Server: Apache/2.4.6 (Red Hat Enterprise Linux) OpenSSL/1.0.2k-fips[\r][\n]"
[2021-10-23T22:33:28,985][DEBUG][org.apache.http.wire     ][main][4d240c3e583460b56a6c34de864823c32285dfb39611226f8de2edd061136e19] http-outgoing-320487 << "Strict-Transport-Security: max-age=63072000; includeSubDomains[\r][\n]"
[2021-10-23T22:33:28,985][DEBUG][org.apache.http.wire     ][main][4d240c3e583460b56a6c34de864823c32285dfb39611226f8de2edd061136e19] http-outgoing-320487 << "content-type: application/json; charset=UTF-8[\r][\n]"
[2021-10-23T22:33:28,985][DEBUG][org.apache.http.wire     ][main][4d240c3e583460b56a6c34de864823c32285dfb39611226f8de2edd061136e19] http-outgoing-320487 << "content-encoding: gzip[\r][\n]"
[2021-10-23T22:33:28,985][DEBUG][org.apache.http.wire     ][main][4d240c3e583460b56a6c34de864823c32285dfb39611226f8de2edd061136e19] http-outgoing-320487 << "content-length: 244[\r][\n]"
[2021-10-23T22:33:28,985][DEBUG][org.apache.http.wire     ][main][4d240c3e583460b56a6c34de864823c32285dfb39611226f8de2edd061136e19] http-outgoing-320487 << "Warning: 299 Elasticsearch-7.9.3-c4138e51121ef06a6404866cddc601906fe5c868 "[types removal] Specifying types in bulk requests is deprecated."[\r][\n]"
[2021-10-23T22:33:28,985][DEBUG][org.apache.http.wire     ][main][4d240c3e583460b56a6c34de864823c32285dfb39611226f8de2edd061136e19] http-outgoing-320487 << "Via: 1.1 [URL][\r][\n]"
[2021-10-23T22:33:28,985][DEBUG][org.apache.http.wire     ][main][4d240c3e583460b56a6c34de864823c32285dfb39611226f8de2edd061136e19] http-outgoing-320487 << "Keep-Alive: timeout=5, max=100[\r][\n]"
[2021-10-23T22:33:28,985][DEBUG][org.apache.http.wire     ][main][4d240c3e583460b56a6c34de864823c32285dfb39611226f8de2edd061136e19] http-outgoing-320487 << "Connection: Keep-Alive[\r][\n]"
[2021-10-23T22:33:28,985][DEBUG][org.apache.http.wire     ][main][4d240c3e583460b56a6c34de864823c32285dfb39611226f8de2edd061136e19] http-outgoing-320487 << "[\r][\n]"
[2021-10-23T22:33:28,985][DEBUG][org.apache.http.headers  ][main][4d240c3e583460b56a6c34de864823c32285dfb39611226f8de2edd061136e19] http-outgoing-320487 << HTTP/1.1 200 OK
[2021-10-23T22:33:28,985][DEBUG][org.apache.http.headers  ][main][4d240c3e583460b56a6c34de864823c32285dfb39611226f8de2edd061136e19] http-outgoing-320487 << Date: Sat, 23 Oct 2021 22:33:28 GMT
[2021-10-23T22:33:28,985][DEBUG][org.apache.http.headers  ][main][4d240c3e583460b56a6c34de864823c32285dfb39611226f8de2edd061136e19] http-outgoing-320487 << Server: Apache/2.4.6 (Red Hat Enterprise Linux) OpenSSL/1.0.2k-fips
[2021-10-23T22:33:28,985][DEBUG][org.apache.http.headers  ][main][4d240c3e583460b56a6c34de864823c32285dfb39611226f8de2edd061136e19] http-outgoing-320487 << Strict-Transport-Security: max-age=63072000; includeSubDomains
[2021-10-23T22:33:28,985][DEBUG][org.apache.http.headers  ][main][4d240c3e583460b56a6c34de864823c32285dfb39611226f8de2edd061136e19] http-outgoing-320487 << content-type: application/json; charset=UTF-8
[2021-10-23T22:33:28,985][DEBUG][org.apache.http.headers  ][main][4d240c3e583460b56a6c34de864823c32285dfb39611226f8de2edd061136e19] http-outgoing-320487 << content-encoding: gzip
[2021-10-23T22:33:28,985][DEBUG][org.apache.http.headers  ][main][4d240c3e583460b56a6c34de864823c32285dfb39611226f8de2edd061136e19] http-outgoing-320487 << content-length: 244
[2021-10-23T22:33:28,985][DEBUG][org.apache.http.headers  ][main][4d240c3e583460b56a6c34de864823c32285dfb39611226f8de2edd061136e19] http-outgoing-320487 << Warning: 299 Elasticsearch-7.9.3-c4138e51121ef06a6404866cddc601906fe5c868 "[types removal] Specifying types in bulk requests is deprecated."
[2021-10-23T22:33:28,985][DEBUG][org.apache.http.headers  ][main][4d240c3e583460b56a6c34de864823c32285dfb39611226f8de2edd061136e19] http-outgoing-320487 << Via: 1.1 [URL]
[2021-10-23T22:33:28,985][DEBUG][org.apache.http.headers  ][main][4d240c3e583460b56a6c34de864823c32285dfb39611226f8de2edd061136e19] http-outgoing-320487 << Keep-Alive: timeout=5, max=100
[2021-10-23T22:33:28,985][DEBUG][org.apache.http.headers  ][main][4d240c3e583460b56a6c34de864823c32285dfb39611226f8de2edd061136e19] http-outgoing-320487 << Connection: Keep-Alive
[2021-10-23T22:33:28,985][DEBUG][org.apache.http.impl.execchain.MainClientExec][main][4d240c3e583460b56a6c34de864823c32285dfb39611226f8de2edd061136e19] Connection can be kept alive for 5000 MILLISECONDS

Stephy · October 25, 2021, 2:02pm

Continuation of the logs:

[2021-10-23T22:33:28,985][DEBUG][org.apache.http.impl.auth.HttpAuthenticator][main][4d240c3e583460b56a6c34de864823c32285dfb39611226f8de2edd061136e19] Authentication succeeded
[2021-10-23T22:33:28,985][DEBUG][org.apache.http.wire     ][main][4d240c3e583460b56a6c34de864823c32285dfb39611226f8de2edd061136e19] http-outgoing-320487 << "[0x1f][0x8b][0x8][0x0][0x0][0x0][0x0][0x0][0x0][0x0]$[0x8f]Mk[0x84]0[0x10][0x86][0xff][0xcb][0x9c]%[0xa8]+[0xc5][0xe6](]/[0xdd][0x85]b[0xb1][0x97]R[0x86][0xd4][0x8c]44[0x1a][0x9b][0x8f][0xd2]E[0xfc][0xef][0x9d][0xb0][0xb7]y[0x87]g[0x1e][0xde][0xd9]!:[0xf7][\r][0xb2]z,[0x80][0xbc]w>[0x80][0x9c][0x95][\r]T[0x80][0x89][0xb4]pz[0xdf]!mZE[0x2][0xb9][0x3][0x9a]U[0xd3][0x1f]Hh[0xda][0xea]>#M[0x9f][0x18][0xc8][0x1b][\n]"
[2021-10-23T22:33:28,985][DEBUG][org.apache.http.wire     ][main][4d240c3e583460b56a6c34de864823c32285dfb39611226f8de2edd061136e19] http-outgoing-320487 << "[0xa8][0xac]EZ[0xa1][0x0][0x8c][0xb7][0x8d]y@[0xed][0xa6][0x1c][0x8d][0xce]'[0xb5]8[0xbf]>u[0xf8]2v[0xa2][0xbf][0x8a]N[0x8c][0xbc][0x18][0x7][0xd1][0xf4][0xe2]y[0x10][0xd7]K?[0x88][0xcb][0xf9]-[0xe3][0xbf][0xe4][0x83]q+[0xb7][0xaa][0xdb][0x7].[0xe6])$[0x1b]Yq/[0xa2]3[0x13][0xbe][0x94][0xd7]\o[0xe7][0x7][0xa2][0xb2] [0xeb][0x2]B[0x9a]&[\n]"
[2021-10-23T22:33:28,985][DEBUG][org.apache.http.wire     ][main][4d240c3e583460b56a6c34de864823c32285dfb39611226f8de2edd061136e19] http-outgoing-320487 << "aN[0x1c][0xab][0x2]fe,[0xc3][0xb2]<2O?[0xb8]:[0xc6][0xea][0xa6]l[0xab][0xf6][0xc4]Z[0xdc][0xbc]Y[0x94][0xbf]a$[0xbf][0x80]<[0xb1] [0xaa][0x98]XZ[0x97][0xe5]q|[0x1c][0xff][0x0][0x0][0x0][0xff][0xff][0x3][0x0]3[0xfd]+][0x1d][0x1][0x0][0x0]"
[2021-10-23T22:33:28,985][DEBUG][org.apache.http.impl.conn.PoolingHttpClientConnectionManager][main][4d240c3e583460b56a6c34de864823c32285dfb39611226f8de2edd061136e19] Connection [id: 320487][route: {s}->[PROTOCOL:URL:PORT]] can be kept alive for 5.0 seconds
[2021-10-23T22:33:28,985][DEBUG][org.apache.http.impl.conn.PoolingHttpClientConnectionManager][main][4d240c3e583460b56a6c34de864823c32285dfb39611226f8de2edd061136e19] Connection released: [id: 320487][route: {s}->[PROTOCOL:URL:PORT]][total kept alive: 1; route allocated: 1 of 100; total allocated: 1 of 1000]
[2021-10-23T22:33:30,146][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ParNew"}
[2021-10-23T22:33:30,146][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ConcurrentMarkSweep"}
[2021-10-23T22:33:32,127][DEBUG][org.logstash.execution.PeriodicFlush][main] Pushing flush onto pipeline.
[2021-10-23T22:33:35,148][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ParNew"}
[2021-10-23T22:33:35,148][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ConcurrentMarkSweep"}
[2021-10-23T22:33:37,127][DEBUG][org.logstash.execution.PeriodicFlush][main] Pushing flush onto pipeline.
[2021-10-23T22:33:40,150][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ParNew"}
[2021-10-23T22:33:40,151][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ConcurrentMarkSweep"}
[2021-10-23T22:33:42,127][DEBUG][org.logstash.execution.PeriodicFlush][main] Pushing flush onto pipeline.
[2021-10-23T22:33:45,153][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ParNew"}
[2021-10-23T22:33:45,153][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ConcurrentMarkSweep"}
[2021-10-23T22:33:47,127][DEBUG][org.logstash.execution.PeriodicFlush][main] Pushing flush onto pipeline.
[2021-10-23T22:33:50,155][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ParNew"}
[2021-10-23T22:33:50,155][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ConcurrentMarkSweep"}
[2021-10-23T22:33:52,127][DEBUG][org.logstash.execution.PeriodicFlush][main] Pushing flush onto pipeline.
[2021-10-23T22:33:55,157][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ParNew"}
[2021-10-23T22:33:55,157][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ConcurrentMarkSweep"}
[2021-10-23T22:33:57,127][DEBUG][org.logstash.execution.PeriodicFlush][main] Pushing flush onto pipeline.
[2021-10-23T22:34:00,160][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ParNew"}
[2021-10-23T22:34:00,160][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ConcurrentMarkSweep"}
[2021-10-23T22:34:00,488][INFO ][logstash.inputs.jdbc     ][main][4543523041e9fa437a13e2badb0b37fd40ddd6daf0b037c957d478599992b93b] (0.001252s) select version from PRODUCT_COMPONENT_VERSION where lower(product) like 'oracle%'
[2021-10-23T22:34:02,127][DEBUG][org.logstash.execution.PeriodicFlush][main] Pushing flush onto pipeline.
[2021-10-23T22:34:05,163][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ParNew"}
[2021-10-23T22:34:05,163][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ConcurrentMarkSweep"}
[2021-10-23T22:34:07,127][DEBUG][org.logstash.execution.PeriodicFlush][main] Pushing flush onto pipeline.
[2021-10-23T22:34:10,166][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ParNew"}
[2021-10-23T22:34:10,166][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ConcurrentMarkSweep"}
[2021-10-23T22:34:12,127][DEBUG][org.logstash.execution.PeriodicFlush][main] Pushing flush onto pipeline.
[2021-10-23T22:34:15,169][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ParNew"}
[2021-10-23T22:34:15,169][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ConcurrentMarkSweep"}
[2021-10-23T22:34:17,127][DEBUG][org.logstash.execution.PeriodicFlush][main] Pushing flush onto pipeline.
[2021-10-23T22:34:20,171][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ParNew"}
[2021-10-23T22:34:20,171][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ConcurrentMarkSweep"}
[2021-10-23T22:34:22,127][DEBUG][org.logstash.execution.PeriodicFlush][main] Pushing flush onto pipeline.
[2021-10-23T22:34:25,173][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ParNew"}
[2021-10-23T22:34:25,173][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ConcurrentMarkSweep"}
[2021-10-23T22:34:27,127][DEBUG][org.logstash.execution.PeriodicFlush][main] Pushing flush onto pipeline.
[2021-10-23T22:34:30,176][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ParNew"}
[2021-10-23T22:34:30,176][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ConcurrentMarkSweep"}
[2021-10-23T22:34:32,127][DEBUG][org.logstash.execution.PeriodicFlush][main] Pushing flush onto pipeline.
[2021-10-23T22:34:35,178][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ParNew"}
[2021-10-23T22:34:35,178][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ConcurrentMarkSweep"}
[2021-10-23T22:34:37,127][DEBUG][org.logstash.execution.PeriodicFlush][main] Pushing flush onto pipeline.
[2021-10-23T22:34:40,180][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ParNew"}
[2021-10-23T22:34:40,180][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ConcurrentMarkSweep"}
[2021-10-23T22:34:42,127][DEBUG][org.logstash.execution.PeriodicFlush][main] Pushing flush onto pipeline.
[2021-10-23T22:34:45,182][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ParNew"}
[2021-10-23T22:34:45,182][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ConcurrentMarkSweep"}
[2021-10-23T22:34:47,127][DEBUG][org.logstash.execution.PeriodicFlush][main] Pushing flush onto pipeline.
[2021-10-23T22:34:50,185][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ParNew"}
[2021-10-23T22:34:50,185][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ConcurrentMarkSweep"}
[2021-10-23T22:34:52,127][DEBUG][org.logstash.execution.PeriodicFlush][main] Pushing flush onto pipeline.
[2021-10-23T22:34:55,187][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ParNew"}
[2021-10-23T22:34:55,187][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ConcurrentMarkSweep"}
[2021-10-23T22:34:57,127][DEBUG][org.logstash.execution.PeriodicFlush][main] Pushing flush onto pipeline.
[2021-10-23T22:35:00,190][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ParNew"}
[2021-10-23T22:35:00,190][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ConcurrentMarkSweep"}
[2021-10-23T22:35:02,127][DEBUG][org.logstash.execution.PeriodicFlush][main] Pushing flush onto pipeline.
[2021-10-23T22:35:05,192][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ParNew"}
[2021-10-23T22:35:05,192][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ConcurrentMarkSweep"}
[2021-10-23T22:35:07,127][DEBUG][org.logstash.execution.PeriodicFlush][main] Pushing flush onto pipeline.
[2021-10-23T22:35:10,195][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ParNew"}
[2021-10-23T22:35:10,195][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ConcurrentMarkSweep"}
[2021-10-23T22:35:12,127][DEBUG][org.logstash.execution.PeriodicFlush][main] Pushing flush onto pipeline.
[2021-10-23T22:35:15,197][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ParNew"}
[2021-10-23T22:35:15,197][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ConcurrentMarkSweep"}
[2021-10-23T22:35:17,127][DEBUG][org.logstash.execution.PeriodicFlush][main] Pushing flush onto pipeline.
[2021-10-23T22:35:20,199][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ParNew"}
[2021-10-23T22:35:20,199][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ConcurrentMarkSweep"}
[2021-10-23T22:35:22,127][DEBUG][org.logstash.execution.PeriodicFlush][main] Pushing flush onto pipeline.
[2021-10-23T22:35:25,201][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ParNew"}
[2021-10-23T22:35:25,201][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ConcurrentMarkSweep"}
[2021-10-23T22:35:27,127][DEBUG][org.logstash.execution.PeriodicFlush][main] Pushing flush onto pipeline.
[2021-10-23T22:35:30,203][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ParNew"}
[2021-10-23T22:35:30,203][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ConcurrentMarkSweep"}
[2021-10-23T22:35:32,127][DEBUG][org.logstash.execution.PeriodicFlush][main] Pushing flush onto pipeline.
[2021-10-23T22:35:35,205][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ParNew"}
[2021-10-23T22:35:35,205][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ConcurrentMarkSweep"}
[2021-10-23T22:35:37,127][DEBUG][org.logstash.execution.PeriodicFlush][main] Pushing flush onto pipeline.
[2021-10-23T22:35:40,207][DEBUG][logstash.instrument.periodicpoller.jvm] collector name {:name=>"ParNew"}

grumo35 · October 25, 2021, 3:32pm

https://hc.apache.org/httpcomponents-client-4.5.x/current/httpclient/apidocs/org/apache/http/impl/conn/PoolingHttpClientConnectionManager.html

It looks like the shutdown() is used in the last moments, i honestly think you'll have to get some help other than me

Looks like Debug log aren't worth a lot, are you on linux ? can you manage to setup some advanced debug using somethinkg like jstack or strace/ptrace ?

Badger · October 25, 2021, 6:52pm

Stephy:

[2021-10-23T22:33:00,432][INFO ][logstash.inputs.jdbc ][main][4543523041e9fa437a13e2badb0b37fd40ddd6daf0b037c957d478599992b93b] (0.001213s) select version from PRODUCT_COMPONENT_VERSION where lower(product) like 'oracle%'
[2021-10-23T22:33:14,504][INFO ][logstash.inputs.jdbc ][main][4543523041e9fa437a13e2badb0b37fd40ddd6daf0b037c957d478599992b93b] (14.071635s) SELECT count(*) "COUNT" FROM (select * from [TABLE] WHERE ("[TIMESTAMP]" IS NOT NULL) AND ("[TIMESTAMP]" > TIMESTAMP '2021-10-23 22:32:00.380394 +00:00')) "T1" FETCH NEXT 1 ROWS ONLY
[2021-10-23T22:33:28,849][INFO ][logstash.inputs.jdbc ][main][4543523041e9fa437a13e2badb0b37fd40ddd6daf0b037c957d478599992b93b] (14.344335s) select * from [TABLE] WHERE ("[TIMESTAMP]" IS NOT NULL) AND ("[TIMESTAMP]" > TIMESTAMP '2021-10-23 22:32:00.380394 +00:00')

[2021-10-23T22:33:28,962][DEBUG][org.apache.http.impl.execchain.MainClientExec][main][4d240c3e583460b56a6c34de864823c32285dfb39611226f8de2edd061136e19] Executing request POST /_bulk HTTP/1.1

Your input is configured to run once a minute. The last run completed at 22:32:00.380394, which means it took less than half a second to complete.

At 22:33:00,432 the inputs starts its next run. It takes 14 seconds to get as far as executing the COUNT version of the query, and another 14 seconds before it actually tries to run the query itself. It takes 70 times as long as the previous run. It then processes the result and indexes it a tenth of a second later.

At first I thought it might be endless stop-the-world mark and re-mark phases in the ConcurrentMarkSweep GC, but that doesn't feel right.

I agree that you need to find out what the JVM is doing if it is not running the file input. A thread dump would be the place to start.

Stephy · October 27, 2021, 8:28am

Hello , @Badger @grumo35

As requested, we have a full thread dump in the link(some repetitive passages have been removed for better readability) : https://drive.google.com/file/d/1-dUTkriXPGE23JPTNtwHJ4e1yH5I8d8l/view?usp=sharing

There are some excerpts from the dump which we suspect might be the cause but still doubtful and are as follows:

"oracle.jdbc.driver.BlockSource.ThreadedCachingBlockSource.BlockReleaser" #92 daemon prio=4 os_prio=0 cpu=634.36ms elapsed=1132346.24s tid=0x00007f2d702e3000 nid=0xbb in Object.wait()  [0x00007f2d67efd000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
	at java.lang.Object.wait(java.base@11.0.8/Native Method)
	- waiting on <no object reference available>
	at oracle.jdbc.driver.BlockSource$ThreadedCachingBlockSource$BlockReleaser.run(BlockSource.java:331)
	- waiting to re-lock in wait() <0x00000000dc5e4970> (a oracle.jdbc.driver.BlockSource$ThreadedCachingBlockSource$BlockReleaser)
"InterruptTimer" #93 daemon prio=5 os_prio=0 cpu=47074.95ms elapsed=1132346.17s tid=0x00007f2d701da800 nid=0xbc in Object.wait()  [0x00007f2d669ad000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
	at java.lang.Object.wait(java.base@11.0.8/Native Method)
	- waiting on <no object reference available>
	at java.util.TimerThread.mainLoop(java.base@11.0.8/Timer.java:553)
	- waiting to re-lock in wait() <0x00000000dcb3cd18> (a java.util.TaskQueue)
	at java.util.TimerThread.run(java.base@11.0.8/Timer.java:506)

Badger · October 27, 2021, 4:27pm

"[main]<jdbc" #65 daemon prio=5 os_prio=0 cpu=203863.44ms elapsed=1132374.76s tid=0x00007f2d041e4800 nid=0x9b in Object.wait()  [0x00007f2cbf8f7000]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
	at java.lang.Object.wait(java.base@11.0.8/Native Method)
	- waiting on <no object reference available>
	at java.lang.Thread.join(java.base@11.0.8/Thread.java:1313)
	- waiting to re-lock in wait() <0x00000000dc5f1068> (a java.lang.Thread)
	at org.jruby.internal.runtime.NativeThread.join(NativeThread.java:75)

I think this is the jdbc input. It is parked, waiting for something.

"Ruby-0-Thread-62: :1" #90 daemon prio=5 os_prio=0 cpu=14200726.79ms elapsed=1132346.68s tid=0x00007f2d4891f800 nid=0xb8 runnable  [0x00007f2d9cd9f000]
   java.lang.Thread.State: RUNNABLE
	at sun.nio.ch.FileDispatcherImpl.read0(java.base@11.0.8/Native Method)
	at sun.nio.ch.SocketDispatcher.read(java.base@11.0.8/SocketDispatcher.java:39)
	at sun.nio.ch.IOUtil.readIntoNativeBuffer(java.base@11.0.8/IOUtil.java:276)
	at sun.nio.ch.IOUtil.read(java.base@11.0.8/IOUtil.java:245)
	at sun.nio.ch.IOUtil.read(java.base@11.0.8/IOUtil.java:223)
	at sun.nio.ch.SocketChannelImpl.read(java.base@11.0.8/SocketChannelImpl.java:355)
	at oracle.net.nt.TimeoutSocketChannel.read(TimeoutSocketChannel.java:174)

This is a thread waiting on Oracle. I have a feeling the problem may be in the database rather than logstash, although if restarting logstash clears the issue I am not sure how the problem could be in Oracle.

system · November 24, 2021, 4:28pm

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