java.lang.StackOverflowError #29

SebScoFr · 2018-04-25T15:34:15Z

I'm running into an issue when trying to start logstash with google_pubsub plugin enabled in the pipeline. I'm using logstash 6.2.2 on Mac (without Docker).

Logstash starts the pipeline correctly, runs for about 30 seconds but eventually fails with
[ERROR][org.logstash.Logstash ] java.lang.StackOverflowError

Here is the plugin configuration:

input {
  google_pubsub {
    project_id => "my-project-id"
    json_key_file => "/path/to/the/file.json"
    topic => "projects/my-project-id/topics/logstash"
    subscription => "projects/my-project-id/subscriptions/logstash"
  }
}

(I've noticed that if I don't provide the full topic path, it will fail with Error: Error 404: Resource not found (resource=logstash))

Any idea what might be going on here?

The text was updated successfully, but these errors were encountered:

josephlewis42 · 2018-04-25T16:28:15Z

Hi @SebScoFr would you mind collecting the following info to help me diagnose the problem?

First, the version number of the plugin, you can get that from the list command:

./logstash-plugin list --installed --verbose --group input

It'll look something like this:

logstash-input-google_pubsub (x.y.z)

Second, would you mind including the full error log you're seeing? Quickly looking at the code I don't see anything glaringly obvious but I'm happy to dig deeper with some more info.

Cheers!

SebScoFr · 2018-04-25T18:45:41Z

Hi @josephlewis42

I am using 1.0.6
I suppose it's worth mentioning that I am using the PubSub emulator locally on my machine.

I tried increasing the heap space for logstash in jvm.options by changing

-Xms1g
-Xmx1g

to

-Xms4g
-Xmx4g

Unfortunately that didn't help.

Here are the logs when I run logstash:

Sebastiens-MBP:config seb$ logstash --log.level=info
Sending Logstash's logs to /usr/local/Cellar/logstash/6.2.2/libexec/logs which is now configured via log4j2.properties
[2018-04-25T19:34:04,996][INFO ][logstash.modules.scaffold] Initializing module {:module_name=>"netflow", :directory=>"/usr/local/Cellar/logstash/6.2.2/libexec/modules/netflow/configuration"}
[2018-04-25T19:34:05,010][INFO ][logstash.modules.scaffold] Initializing module {:module_name=>"fb_apache", :directory=>"/usr/local/Cellar/logstash/6.2.2/libexec/modules/fb_apache/configuration"}
[2018-04-25T19:34:05,174][WARN ][logstash.config.source.multilocal] Ignoring the 'pipelines.yml' file because modules or command line options are specified
[2018-04-25T19:34:05,687][INFO ][logstash.runner          ] Starting Logstash {"logstash.version"=>"6.2.2"}
[2018-04-25T19:34:05,974][INFO ][logstash.agent           ] Successfully started Logstash API endpoint {:port=>9600}
[2018-04-25T19:34:09,687][INFO ][logstash.pipeline        ] Starting pipeline {:pipeline_id=>"main", "pipeline.workers"=>8, "pipeline.batch.size"=>125, "pipeline.batch.delay"=>50}
[2018-04-25T19:34:10,082][INFO ][logstash.outputs.elasticsearch] Elasticsearch pool URLs updated {:changes=>{:removed=>[], :added=>[http://localhost:9200/]}}
[2018-04-25T19:34:10,092][INFO ][logstash.outputs.elasticsearch] Running health check to see if an Elasticsearch connection is working {:healthcheck_url=>http://localhost:9200/, :path=>"/"}
[2018-04-25T19:34:10,375][WARN ][logstash.outputs.elasticsearch] Restored connection to ES instance {:url=>"http://localhost:9200/"}
[2018-04-25T19:34:10,448][INFO ][logstash.outputs.elasticsearch] ES Output version determined {:es_version=>nil}
[2018-04-25T19:34:10,453][WARN ][logstash.outputs.elasticsearch] Detected a 6.x and above cluster: the `type` event field won't be used to determine the document _type {:es_version=>6}
[2018-04-25T19:34:10,476][INFO ][logstash.outputs.elasticsearch] Using mapping template from {:path=>nil}
[2018-04-25T19:34:10,510][INFO ][logstash.outputs.elasticsearch] Attempting to install template {:manage_template=>{"template"=>"logstash-*", "version"=>60001, "settings"=>{"index.refresh_interval"=>"5s"}, "mappings"=>{"_default_"=>{"dynamic_templates"=>[{"message_field"=>{"path_match"=>"message", "match_mapping_type"=>"string", "mapping"=>{"type"=>"text", "norms"=>false}}}, {"string_fields"=>{"match"=>"*", "match_mapping_type"=>"string", "mapping"=>{"type"=>"text", "norms"=>false, "fields"=>{"keyword"=>{"type"=>"keyword", "ignore_above"=>256}}}}}], "properties"=>{"@timestamp"=>{"type"=>"date"}, "@version"=>{"type"=>"keyword"}, "geoip"=>{"dynamic"=>true, "properties"=>{"ip"=>{"type"=>"ip"}, "location"=>{"type"=>"geo_point"}, "latitude"=>{"type"=>"half_float"}, "longitude"=>{"type"=>"half_float"}}}}}}}}
[2018-04-25T19:34:10,566][INFO ][logstash.outputs.elasticsearch] New Elasticsearch output {:class=>"LogStash::Outputs::ElasticSearch", :hosts=>["//localhost:9200"]}
[2018-04-25T19:34:10,578][INFO ][logstash.outputs.elasticsearch] Elasticsearch pool URLs updated {:changes=>{:removed=>[], :added=>[http://localhost:9200/]}}
[2018-04-25T19:34:10,579][INFO ][logstash.outputs.elasticsearch] Running health check to see if an Elasticsearch connection is working {:healthcheck_url=>http://localhost:9200/, :path=>"/"}
[2018-04-25T19:34:10,596][WARN ][logstash.outputs.elasticsearch] Restored connection to ES instance {:url=>"http://localhost:9200/"}
[2018-04-25T19:34:10,601][INFO ][logstash.outputs.elasticsearch] ES Output version determined {:es_version=>nil}
[2018-04-25T19:34:10,603][WARN ][logstash.outputs.elasticsearch] Detected a 6.x and above cluster: the `type` event field won't be used to determine the document _type {:es_version=>6}
[2018-04-25T19:34:10,606][INFO ][logstash.outputs.elasticsearch] Using mapping template from {:path=>nil}
[2018-04-25T19:34:10,611][INFO ][logstash.outputs.elasticsearch] Attempting to install template {:manage_template=>{"template"=>"logstash-*", "version"=>60001, "settings"=>{"index.refresh_interval"=>"5s"}, "mappings"=>{"_default_"=>{"dynamic_templates"=>[{"message_field"=>{"path_match"=>"message", "match_mapping_type"=>"string", "mapping"=>{"type"=>"text", "norms"=>false}}}, {"string_fields"=>{"match"=>"*", "match_mapping_type"=>"string", "mapping"=>{"type"=>"text", "norms"=>false, "fields"=>{"keyword"=>{"type"=>"keyword", "ignore_above"=>256}}}}}], "properties"=>{"@timestamp"=>{"type"=>"date"}, "@version"=>{"type"=>"keyword"}, "geoip"=>{"dynamic"=>true, "properties"=>{"ip"=>{"type"=>"ip"}, "location"=>{"type"=>"geo_point"}, "latitude"=>{"type"=>"half_float"}, "longitude"=>{"type"=>"half_float"}}}}}}}}
[2018-04-25T19:34:10,621][INFO ][logstash.outputs.elasticsearch] New Elasticsearch output {:class=>"LogStash::Outputs::ElasticSearch", :hosts=>["//localhost:9200"]}
[2018-04-25T19:34:10,625][INFO ][logstash.outputs.elasticsearch] Elasticsearch pool URLs updated {:changes=>{:removed=>[], :added=>[http://localhost:9200/]}}
[2018-04-25T19:34:10,625][INFO ][logstash.outputs.elasticsearch] Running health check to see if an Elasticsearch connection is working {:healthcheck_url=>http://localhost:9200/, :path=>"/"}
[2018-04-25T19:34:10,641][WARN ][logstash.outputs.elasticsearch] Restored connection to ES instance {:url=>"http://localhost:9200/"}
[2018-04-25T19:34:10,648][INFO ][logstash.outputs.elasticsearch] ES Output version determined {:es_version=>nil}
[2018-04-25T19:34:10,648][WARN ][logstash.outputs.elasticsearch] Detected a 6.x and above cluster: the `type` event field won't be used to determine the document _type {:es_version=>6}
[2018-04-25T19:34:10,649][INFO ][logstash.outputs.elasticsearch] Using mapping template from {:path=>nil}
[2018-04-25T19:34:10,651][INFO ][logstash.outputs.elasticsearch] Attempting to install template {:manage_template=>{"template"=>"logstash-*", "version"=>60001, "settings"=>{"index.refresh_interval"=>"5s"}, "mappings"=>{"_default_"=>{"dynamic_templates"=>[{"message_field"=>{"path_match"=>"message", "match_mapping_type"=>"string", "mapping"=>{"type"=>"text", "norms"=>false}}}, {"string_fields"=>{"match"=>"*", "match_mapping_type"=>"string", "mapping"=>{"type"=>"text", "norms"=>false, "fields"=>{"keyword"=>{"type"=>"keyword", "ignore_above"=>256}}}}}], "properties"=>{"@timestamp"=>{"type"=>"date"}, "@version"=>{"type"=>"keyword"}, "geoip"=>{"dynamic"=>true, "properties"=>{"ip"=>{"type"=>"ip"}, "location"=>{"type"=>"geo_point"}, "latitude"=>{"type"=>"half_float"}, "longitude"=>{"type"=>"half_float"}}}}}}}}
[2018-04-25T19:34:10,657][INFO ][logstash.outputs.elasticsearch] New Elasticsearch output {:class=>"LogStash::Outputs::ElasticSearch", :hosts=>["//localhost:9200"]}
[2018-04-25T19:34:12,642][INFO ][logstash.inputs.googlepubsub] Client authorization with JSON key ready
[2018-04-25T19:34:12,655][INFO ][logstash.pipeline        ] Pipeline started succesfully {:pipeline_id=>"main", :thread=>"#<Thread:0x5fd17d6b run>"}
[2018-04-25T19:34:12,757][INFO ][logstash.agent           ] Pipelines running {:count=>1, :pipelines=>["main"]}
[2018-04-25T19:36:04,739][ERROR][org.logstash.Logstash    ] java.lang.StackOverflowError

If I run logstash with debug mode enabled, I get flooded by the PubSub Authorization process apparently, it's sending a lot of those requests before eventually crashing like this:

...
...
...
[2018-04-25T19:41:54,532][DEBUG][logstash.inputs.googlepubsub] Sending an API request
[2018-04-25T19:41:54,535][DEBUG][logstash.inputs.googlepubsub] Authorizing...
[2018-04-25T19:41:54,670][DEBUG][logstash.inputs.googlepubsub] ...authorized
[2018-04-25T19:41:54,670][DEBUG][logstash.inputs.googlepubsub] Sending an API request
[2018-04-25T19:41:54,674][DEBUG][logstash.inputs.googlepubsub] Authorizing...
[2018-04-25T19:41:54,791][DEBUG][logstash.inputs.googlepubsub] ...authorized
[2018-04-25T19:41:54,792][DEBUG][logstash.inputs.googlepubsub] Sending an API request
[2018-04-25T19:41:54,795][DEBUG][logstash.inputs.googlepubsub] Authorizing...
[2018-04-25T19:41:54,932][DEBUG][logstash.inputs.googlepubsub] ...authorized
[2018-04-25T19:41:54,932][DEBUG][logstash.inputs.googlepubsub] Sending an API request
[2018-04-25T19:41:54,936][DEBUG][logstash.inputs.googlepubsub] Authorizing...
[2018-04-25T19:41:55,059][DEBUG][logstash.inputs.googlepubsub] ...authorized
[2018-04-25T19:41:55,059][DEBUG][logstash.inputs.googlepubsub] Sending an API request
[2018-04-25T19:41:55,063][DEBUG][logstash.inputs.googlepubsub] Authorizing...
[2018-04-25T19:41:55,192][DEBUG][logstash.inputs.googlepubsub] ...authorized
[2018-04-25T19:41:55,192][DEBUG][logstash.inputs.googlepubsub] Sending an API request
[2018-04-25T19:41:55,196][DEBUG][logstash.inputs.googlepubsub] Authorizing...
[2018-04-25T19:41:55,292][DEBUG][logstash.inputs.googlepubsub] Closing {:plugin=>"LogStash::Inputs::GooglePubSub"}
[2018-04-25T19:41:55,352][DEBUG][logstash.pipeline        ] Pushing flush onto pipeline {:pipeline_id=>"main", :thread=>"#<Thread:0x684fe72f sleep>"}
[2018-04-25T19:41:55,355][DEBUG][logstash.pipeline        ] Shutting down filter/output workers {:pipeline_id=>"main", :thread=>"#<Thread:0x684fe72f run>"}
[2018-04-25T19:41:55,364][DEBUG][logstash.pipeline        ] Pushing shutdown {:pipeline_id=>"main", :thread=>"#<Thread:0x5ab4805a@[main]>worker0 run>"}
[2018-04-25T19:41:55,366][DEBUG][logstash.pipeline        ] Pushing shutdown {:pipeline_id=>"main", :thread=>"#<Thread:0x21a025e7@[main]>worker1 run>"}
[2018-04-25T19:41:55,366][DEBUG][logstash.pipeline        ] Pushing shutdown {:pipeline_id=>"main", :thread=>"#<Thread:0x1bdec9c0@[main]>worker2 run>"}
[2018-04-25T19:41:55,366][DEBUG][logstash.pipeline        ] Pushing shutdown {:pipeline_id=>"main", :thread=>"#<Thread:0x734cb7e@[main]>worker3 run>"}
[2018-04-25T19:41:55,367][DEBUG][logstash.pipeline        ] Pushing shutdown {:pipeline_id=>"main", :thread=>"#<Thread:0x3e1066f7@[main]>worker4 run>"}
[2018-04-25T19:41:55,367][DEBUG][logstash.pipeline        ] Pushing shutdown {:pipeline_id=>"main", :thread=>"#<Thread:0x62d33881@[main]>worker5 run>"}
[2018-04-25T19:41:55,367][DEBUG][logstash.pipeline        ] Pushing shutdown {:pipeline_id=>"main", :thread=>"#<Thread:0x65b22a59@[main]>worker6 run>"}
[2018-04-25T19:41:55,367][DEBUG][logstash.pipeline        ] Pushing shutdown {:pipeline_id=>"main", :thread=>"#<Thread:0x36cefc91@[main]>worker7 run>"}
[2018-04-25T19:41:55,372][DEBUG][logstash.pipeline        ] Shutdown waiting for worker thread {:pipeline_id=>"main", :thread=>"#<Thread:0x5ab4805a@[main]>worker0 run>"}
[2018-04-25T19:41:55,535][DEBUG][logstash.pipeline        ] Shutdown waiting for worker thread {:pipeline_id=>"main", :thread=>"#<Thread:0x21a025e7@[main]>worker1 dead>"}
[2018-04-25T19:41:55,540][DEBUG][logstash.pipeline        ] Shutdown waiting for worker thread {:pipeline_id=>"main", :thread=>"#<Thread:0x1bdec9c0@[main]>worker2 dead>"}
[2018-04-25T19:41:55,540][DEBUG][logstash.pipeline        ] Shutdown waiting for worker thread {:pipeline_id=>"main", :thread=>"#<Thread:0x734cb7e@[main]>worker3 dead>"}
[2018-04-25T19:41:55,541][DEBUG][logstash.pipeline        ] Shutdown waiting for worker thread {:pipeline_id=>"main", :thread=>"#<Thread:0x3e1066f7@[main]>worker4 dead>"}
[2018-04-25T19:41:55,541][DEBUG][logstash.pipeline        ] Shutdown waiting for worker thread {:pipeline_id=>"main", :thread=>"#<Thread:0x62d33881@[main]>worker5 dead>"}
[2018-04-25T19:41:55,541][DEBUG][logstash.pipeline        ] Shutdown waiting for worker thread {:pipeline_id=>"main", :thread=>"#<Thread:0x65b22a59@[main]>worker6 dead>"}
[2018-04-25T19:41:55,541][DEBUG][logstash.pipeline        ] Shutdown waiting for worker thread {:pipeline_id=>"main", :thread=>"#<Thread:0x36cefc91@[main]>worker7 dead>"}
[2018-04-25T19:41:55,567][DEBUG][logstash.outputs.elasticsearch] Closing {:plugin=>"LogStash::Outputs::ElasticSearch"}
[2018-04-25T19:41:55,593][DEBUG][logstash.outputs.elasticsearch] Stopping sniffer
[2018-04-25T19:41:55,600][DEBUG][logstash.outputs.elasticsearch] Stopping resurrectionist
[2018-04-25T19:41:55,613][ERROR][org.logstash.Logstash    ] java.lang.StackOverflowError

Many thanks for the help!

josephlewis42 · 2018-04-25T20:23:45Z

Okay, I think I might know what's going on. The plugin assumes that the only reason an argument error would be thrown is because of a bad access token, but I think it's trying to format your topic and subscription twice so it's recursing until you get the StackOverflowError.

That means the topic is going to be changed to projects/my-project-id/topics/projects/my-project-id/topics/logstash and the subscription will be projects/my-project-id/subscriptions/projects/my-project-id/subscriptions/logstash.

Try changing your topic and subscription to just the topic name and subscription name (are they both logstash?)

input {
  google_pubsub {
    project_id => "my-project-id"
    json_key_file => "/path/to/the/file.json"
    topic => "logstash"
    subscription => "logstash"
  }
}

You can use the following gcloud commands to help:

PROJECT=my-project-id
TOPIC=my-topic

# Make sure the topic exists
gcloud --project=$PROJECT pubsub topics list --filter "name:*($TOPIC)"

# Make sure the subscription exists under that topic
gcloud --project=$PROJECT pubsub topics list-subscriptions $TOPIC

If that's still giving you a 404 double check that the service account in the json_key_file belongs to project_id. If none of those are the issue, let me know and I'll ask around to see if there are any known bugs around this. 😃

SebScoFr · 2018-04-25T21:44:26Z

So when I specify only logstash for the topic and subscription like you suggested I indeed get the 404 error. Here are the logs for it:

[2018-04-25T22:40:09,228][ERROR][logstash.pipeline        ] A plugin had an unrecoverable error. Will restart this plugin.
  Pipeline_id:main
  Plugin: <LogStash::Inputs::GooglePubSub project_id=>"my-project-id", json_key_file=>"/Users/seb/Documents/S8/Platform/gcp/gcp_logstash.json", topic=>"logstash", subscription=>"logstash", id=>"02d311c9b745780e82fd620511c48869798732348aa05c4c830b9d7d363d9a35", enable_metric=>true, codec=><LogStash::Codecs::Plain id=>"plain_6709e6e9-c20e-47b1-beae-5d42830a39f9", enable_metric=>true, charset=>"UTF-8">, max_messages=>5>
  Error: Error 404: Resource not found (resource=logstash).
  Exception: Google::APIClient::ClientError
  Stack: /usr/local/Cellar/logstash/6.2.2/libexec/vendor/bundle/jruby/2.3.0/gems/logstash-input-google_pubsub-1.0.6/lib/logstash/inputs/google_pubsub.rb:225:in `run'
/usr/local/Cellar/logstash/6.2.2/libexec/logstash-core/lib/logstash/pipeline.rb:516:in `inputworker'
/usr/local/Cellar/logstash/6.2.2/libexec/logstash-core/lib/logstash/pipeline.rb:509:in `block in start_input'

Might it have something to do with the fact that I am using the PubSub emulator instead of the live one?

The topic is present on my local PubSub.
GET http://localhost:8085/v1/projects/my-project-id/topics returns

{
    "topics": [
        {
            "name": "projects/my-project-id/topics/logstash"
        }
    ]
}

SebScoFr · 2018-04-26T09:02:22Z

In fact I am pretty sure that is the case. There is no option in the plugin to configure it for communicating with the PubSub emulator so it must interact with the live one and therefore the topic doesn't exist there.

Would it be possible to add a new (optional) host config option? In this case it will be:

input {
  google_pubsub {
    host => "127.0.0.1:8085"
    project_id => "my-project-id"
    json_key_file => "/path/to/the/file.json"
    topic => "logstash"
    subscription => "logstash"
  }
}

josephlewis42 · 2018-04-26T15:52:14Z

Hi @SebScoFr I did some digging and it looks like most Google libraries support pulling the host from the PUBSUB_EMULATOR_HOST environment variable, but the one we're using does not.

If you'll open a feature request in this repository I'd be happy to see what I can do to get it added to this plugin.

I have a few community submissions to merge in right now, one of which is moving from that Ruby library to a newer Java to boost performance and will hopefully make this easy to do.

SebScoFr · 2018-04-26T15:56:59Z

Thanks @josephlewis42 for this.

How do you want me to do this? Can't this issue be used as a feature request?

josephlewis42 · 2018-04-26T16:20:04Z

I think opening a new one is a good idea so when someone comes in to review the code and the problem they won't have to go through the debugging we did here to figure out what was going on.

Or you can edit your original comment/title with the feature request and I can re-tag this issue as an enhancement request.

SebScoFr · 2018-04-26T17:10:40Z

Sure thing. Just created #30

josephlewis42 · 2018-04-26T17:39:15Z

Thanks! I'm closing this one out and we can re-open if we need to re-visit after the fix.

josephlewis42 self-assigned this Apr 25, 2018

josephlewis42 added the bug label Apr 25, 2018

josephlewis42 added help wanted and removed bug labels Apr 26, 2018

josephlewis42 closed this as completed Apr 26, 2018

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

java.lang.StackOverflowError #29

java.lang.StackOverflowError #29

SebScoFr commented Apr 25, 2018 •

edited

Loading

josephlewis42 commented Apr 25, 2018

SebScoFr commented Apr 25, 2018 •

edited

Loading

josephlewis42 commented Apr 25, 2018

SebScoFr commented Apr 25, 2018 •

edited

Loading

SebScoFr commented Apr 26, 2018 •

edited

Loading

josephlewis42 commented Apr 26, 2018

SebScoFr commented Apr 26, 2018

josephlewis42 commented Apr 26, 2018

SebScoFr commented Apr 26, 2018

josephlewis42 commented Apr 26, 2018

java.lang.StackOverflowError #29

java.lang.StackOverflowError #29

Comments

SebScoFr commented Apr 25, 2018 • edited Loading

josephlewis42 commented Apr 25, 2018

SebScoFr commented Apr 25, 2018 • edited Loading

josephlewis42 commented Apr 25, 2018

SebScoFr commented Apr 25, 2018 • edited Loading

SebScoFr commented Apr 26, 2018 • edited Loading

josephlewis42 commented Apr 26, 2018

SebScoFr commented Apr 26, 2018

josephlewis42 commented Apr 26, 2018

SebScoFr commented Apr 26, 2018

josephlewis42 commented Apr 26, 2018

SebScoFr commented Apr 25, 2018 •

edited

Loading

SebScoFr commented Apr 25, 2018 •

edited

Loading

SebScoFr commented Apr 25, 2018 •

edited

Loading

SebScoFr commented Apr 26, 2018 •

edited

Loading