elasticsearch output - failed with response of 400 #144
Comments
|
I'm seeing the the same problem running Logstash 1.5.0 on Windows 2012 R2. |
|
I'm running Logstash 1.5.0 on Ubuntu server 14.10. I noticed this when I had uppercased letters in my index, but the --configtest passed it as OK. output { |
|
I'm seeing the same, an extremely long log line for only one single windows eventID sent with nxlog from only one server. This is using Logstash 1.5.0 on Windows. For some reason it seems the log is repeating the message again and again and again. Is it possible that for some reason it doesnt send the event right away but buffers it and then the buffer fills up? That single log line is about 45023 characters long. There are then other log lines since I upgraded to 1.5 with the same event ID from the same server that are about 22510 characters long. Its also possible this bug crashed the indexing process for me yesterday but I'm not sure since I was not around. 15:14 Service started The last event is still coming through every now and then. |
|
@elvarb do you have a copy of your config file? |
|
@naisanza here it is, with all its odds and ends, details retracted. The event that is causing this is from I think our only Windows 2008 32bit server and the eventID is 4616. nxLog is used as a shipper and it converts the messages to json before shipping to Logstash. input {
rabbitmq {
exchange => "logstash"
key => "logs.winserv"
queue => "logs.winserv"
host => "rabbitmq-server"
auto_delete => false
exclusive => false
durable => true
}
}
filter {
if "winserv" in [tags] {
json {
source => "message"
target => "winevent"
}
mutate {
remove_field => [ "message" ]
}
date {
match => ["[winevent][EventTime]", "YYYY-MM-dd HH:mm:ss"]
}
## LogonType
if [winevent][LogonType] {
translate {
field => "[winevent][LogonType]"
destination => "[winevent][LogonTypeDesc]"
dictionary_path => "winevent_logontype.txt"
}
}
## Add sourcegroup field to group similar sourcenames together
if [winevent][SourceName] {
translate {
field => "[winevent][SourceName]"
destination => "[winevent][SourceGroup]"
dictionary_path => "winevent_sourcegroups.txt"
add_tag => [ "%{[winevent][SourceGroup]}" ]
}
}
## Add servicegroup field to group similar services together
if [winevent][SourceName] == "Service Control Manager" {
translate {
field => "[winevent][param1]"
destination => "[winevent][ServiceGroup]"
dictionary_path => "winevent_servicegroups.txt"
add_tag => [ "%{[winevent][ServiceGroup]}" ]
}
}
## Add firewallgroup field to group similar firewall rules together
if [winevent][Category] == "MPSSVC Rule-Level Policy Change" {
translate {
field => "[winevent][RuleName]"
destination => "[winevent][FirewallGroup]"
dictionary_path => "winevent_firewallgroups.txt"
add_tag => [ "%{[winevent][FirewallGroup]}" ]
}
}
## Add filtergroup field to group similar filters together
if [winevent][Category] == "Other Policy Change Events" {
translate {
field => "[winevent][FilterName]"
destination => "[winevent][FilterGroup]"
dictionary_path => "winevent_filtergroups.txt"
add_tag => [ "%{[winevent][FilterGroup]}" ]
}
}
## Parse InternalApp JSON
if [winevent][SourceGroup] == "InternalApp" {
if [winevent][Message] =~ "^{" {
range {
ranges => [
"[winevent][Message]", 0, 30000, "tag:InternalAppNormal",
"[winevent][Message]", 30001, 1000000, "tag:InternalAppLong"
]
#ranges => [ "%{[winevent][Message]}", 31839, 1e1000, "tag:InternalAppLong" ]
}
if "InternalAppNormal" in [tags] {
json {
source => "[winevent][Message]"
target => "InternalApp"
}
}
} else {
mutate {
add_tag => "InternalAppBrokenJSON"
remove_tag => "InternalApp"
}
}
}
## Throttle
## For InternalApp Applications
if [InternalApp][Level] == "Error" and [InternalApp][Environment] == "PROD" {
throttle {
period => 60
before_count => 2
after_count => -1
# Events with the same key will be throttled as a group. Field substitutions are allowed, so you can combine multiple fields.
# For InternalApp events use maybe system,subsystem and logger
#key => "%{host}%{message}"
key => "%{[InternalApp][System]}"
#max_counters => ... # number (optional), default: 100000
#remove_field => ... # array (optional), default: []
#remove_tag => ... # array (optional), default: []
#add_field => ... # hash (optional), default: {}
add_tag => "InternalAppalert"
}
}
}
}
output {
if "winserv" in [tags] {
elasticsearch {
protocol => "http"
host => "logstash-server"
}
if "AV" in [tags] {
elasticsearch {
protocol => "http"
host => "logstash-server"
index => "log365-%{+YYYY.MM.dd}"
}
}
if [InternalApp][Environment] == "DEV" or [InternalApp][Environment] == "TEST" {
elasticsearch {
protocol => "http"
host => "elasticsearch-test-server"
}
}
if "InternalAppalert" in [tags] {
email {
from => "elk@domain.com"
to => "error@domain.com"
subject => "%{[InternalApp][System]} - %{[InternalApp][Level]} in %{[InternalApp][SubSystem]}"
via => "smtp"
options => {
smtpIporHost => "smtp-server"
port => 25
}
htmlbody => "
<body offset='0' class='body' style='padding:0; margin:0; display:block; background:#ECEFF1; font-family: Arial, sans-serif; -webkit-text-size-adjust:none' bgcolor='#ECEFF1'>
<center>
<table cellspacing='0' cellpadding='0' style='background:#607D8B;' bgcolor='#607D8B' width='95%'>
<tr>
<td style='font-size:24px; font-weight: 600; font-family: Arial, sans-serif; color: #FFFFFF; text-align:center;' >
<br>
InternalApp Application Log<br>
</td>
</tr>
<tr>
<td style='font-size:15px; font-family: Arial, sans-serif; text-align:center; padding: 0 75px; color:#ECEFF1;'>
Throttle triggered, please view Kibana for more details<br>
</td>
</tr>
</table>
</center>
<center>
<table cellspacing='0' cellpadding='0' width='95%' style='font-family: Arial, sans-serif;font-size:12px;'>
<tr style='background:#CFD8DC'>
<td style='border-bottom:1px solid #e3e3e3; font-weight: bold; text-align: left;'>
Field
</td>
<td style='border-bottom:1px solid #e3e3e3; font-weight: bold;'>
Value
</td>
</tr>
<tr>
<td style='text-align: left;'>
EventTime
</td>
<td >
%{[winevent][EventTime]}
</td>
</tr>
<tr>
<td style='text-align: left;'>
Hostname
</td>
<td >
%{[winevent][Hostname]}
</td>
</tr>
<tr>
<td style='text-align: left;'>
Environment
</td>
<td >
%{[InternalApp][Environment]}
</td>
</tr>
<tr>
<td style='text-align: left;'>
Level
</td>
<td >
%{[InternalApp][Level]}
</td>
</tr>
<tr>
<td style='text-align: left;'>
System
</td>
<td >
%{[InternalApp][System]}
</td>
</tr>
<tr>
<td style='text-align: left;'>
SubSystem
</td>
<td >
%{[InternalApp][SubSystem]}
</td>
</tr>
<tr>
<td style='text-align: left;'>
Logger
</td>
<td >
%{[InternalApp][Logger]}
</td>
</tr>
</table>
</center>
<center>
<table style='margin: 0 auto; font-family: Arial, sans-serif; font-size:12px; cellspacing='0' cellpadding='0' width='95%'>
<tr style='background:#CFD8DC'>
<td style='border-bottom:1px solid #e3e3e3; font-weight: bold; text-align: left;'>
Message
</td>
</tr>
<tr>
<td>
%{[InternalApp][Message]}
</td>
</tr>
</table>
</center>
<br>
<center>
<table style='margin:0 auto; font-family: Arial, sans-serif;' cellspacing='0' cellpadding='10' width='20%'>
<tr>
<td style='text-align:center; margin:0 auto;background-color:#f5774e;color:#ffffff;display:inline-block;font-family: Arial, sans-serif;;font-size:18px;font-weight:400;line-height:25px;text-align:center;text-decoration:none;width:180px;-webkit-text-size-adjust:none;'>
<a href='http://kibana.domain.com/#/dashboard/elasticsearch/domain%20%{[InternalApp][System]}' style='background-color:#f5774e;color:#ffffff;display:inline-block;font-family: Arial, sans-serif;;font-size:18px;font-weight:400;line-height:25px;text-align:center;text-decoration:none;width:180px;-webkit-text-size-adjust:none;'>
Go to Kibana
</a>
</td>
</tr>
</table>
</center>
</body>"
}
}
}
} |
|
I have logstash 1.5.0 on debian. I getting this error in output for gelf input. |
|
Same problem happened to me last night. Getting "failed action with response of 400" errors all the time, once every hour or so. Also getting "Got error to send bulk of actions to elasticsearch server at servername : Read timed out" But last night the Logstash process stopped again with the same pattern. Edit: Seems that the 45k lines are actually two events of the same type in the same line. The first half is when the process stopped and the second half when the service was restarted. Strange that when the service is started again that it doesnt start with a new line here. |
|
After analyzing the log file better it seems that somewhere a loop is not being closed on the right place. There are nested objects all over. The line contains the following objects The lut one is special because each object there contains the whole data object instead of the actual item. It starts with What is strange is that within the logs the data inside tags comes up like this Is this normal? |
|
I added a output file filter to write the raw event to file before it got shipped to Elasticsearch. For the one that keeps giving me an error this field is added For the one that works this field is added The mapping in elasticsearch is This is the only difference worth noting between them. There is only one tag defined for both and it is exactly the same. |
|
This error spaming to my log every second! +1gb to file size every hour! |
|
@avcherkasov can you provide the versions of logstash and elasticsearch you're using, the logstash configuration and one of those errors? |
|
i have this cluster:http://prntscr.com/7aouan |
|
are you able to reduce the number of inputs and determine which one is causing the 400 errors? for example keeping only the tcp { } inputs |
|
I know that 98% of messages are going by |
|
hi, when I fixed my index name pattern it worked fine. a somewhat nicer error message would be helpful for non es pro's however. thanks, |
|
@MarkusMayer thanks for answer. |
|
@avcherkasov That index pattern is ok, that just means that it prefixes the index name with "logstash-" and then with a datestamp |
|
I modified my config to drop that specific message causing the 400 error, makes no change to me since that message never reached the elasticsearch cluster anyways. What I did notice is that when this error comes up and I kill the service the java.exe process does not die with it. If there are no 400 errors since the java.exe process started the process dies normally. This means that it does not release the log file among other things. |
|
I would have said the same thing - a better error message. I ran into this same problem. However, it is directly documented in the Logstash. You would have had to read the documentation to have known to use the Index field.
On May 29, 2015 8:07:36 AM EDT, MarkusMayer notifications@github.com wrote:
Sent from my Android device with K-9 Mail. Please excuse my brevity. |
|
Was there any update here? I've updated the ES to 1.5.2 and logstash to 1.5.0 and started to had this error. My logstash config looks the next way: upd 1 It started to work better, but I still receive the same message. time to time, which means that a lot of the messages are not hitting the ES. I assume that we had an issue, because index with the name logstash-2015.06.08 was already created, and logstash (ES) doesn't want to write there, or something ** upd 2 **
Any advice how to overcome those issues? |
|
Hi, Its quite frustrating since we thought it would be easy to convert a kafka river to a logstash kafka-input to ES-output.. :) |
|
This was happening to me as well. I was setting the tags field to an empty array instead of none and that seems to kill the transport. Started dropping tags if empty and stuff started working again. |
|
@popsikle |
|
Well, the empty array only fixed a handful of my messages, turns out i still got a problem. |
|
@popsikle But this time array is not empty? I have the messages like this as well, I am also trying to pass the array to the logstash and ES. |
|
The real issue was not the tags. The real issue was that I am sending a bunch of extra fields from my apps to ES via logstash and some of the types clashed between applications. I have auto-mapping turned on and one app was trying to send "client_id" as string and one was sending it as "bool". I figured this out by moving the logstash box that was having an issue to a new index (logstash-appname-DATE) and compared the mappings for my new index with my old index. |
|
Correct, I think we have the same issue. Which I've explained above. Thanks for your input. |
|
I was encountering this same issue when trying to create a template for handling netflow data I was inputting into ES. I'm not sure what field was causing the issue but once I removed the template, everything worked fine. To circumvent possible kibana type issues, ie. a field that should be an integer is a string, I used logstash to convert the fields to their proper type. I guess elasticsearch figured out the mapping on its own. I have to +1 the idea of better logging for this kind of error. A dream scenario would be if the error log mentioned which field transgressed upon the elasticsearch field mapping's / template's type expectation. @julienbeclin , do you have any ES field mappings / templates that could be interfering? Try removing any field mappings / templates you may have. It worked for me/ |
|
i had this, too. |
|
@MarkusMayer So the issue here is that, index name must not contain any upper case character nor space (or others?). I am having problem coming up with a working logstash filter config that cleanses my index name. I tried something like this, but logstash's lowercase/gsub doesn't seem to be doing anything. I am using logstash 1.5.1 |
|
@soichih unfortunately there is a problem with mutate lowercase not working for utf-8 strings in the current version (see elastic/logstash#2973) i had to do some (ugly) workaround for that to cleanse the index name. look here for naming convention: elastic/elasticsearch#6736 |
|
I am using logstash 1.5.2. I do not think this has anything to do with index case name. I've stripped down my logstash config and I have input from exact same data source. Output to two different index name, one works (ei1_mlogstash-%{+YYYY.MM.dd}), the other one (mserver-%{+YYYY.MM.dd}) give me errors in log of "failed action with response of 400, dropping action". The index ei1_mlogstash-%{YYYY.MM.dd} gets created and data added, but the other one does not even get created -- all data are dropped. I am using elasticsearch v1.4.5 at the moment, was using logstash v1.4.2, which works perfectly. Upgraded to 1.5.2 and it breaks. This is very frustrating. input {
file {
path => "/var/log/syslog"
start_position => "beginning"
type => "mobile-server"
}
}
filter {
date { match => ["timestamp", "UNIX_MS"] }
}
output {
elasticsearch {
host => "localhost"
port => "9200"
protocol => "http"
index => "ei1_mlogstash-%{+YYYY.MM.dd}"
}
elasticsearch {
host => "localhost"
port => "9200"
protocol => "http"
index => "mserver-%{+YYYY.MM.dd}"
}
} |
|
I've tested the output with this configuration When I query ES I see that they are correctly created: Can you remove the |
|
See my case #3561 for a detailed example of dynamic mapping a dirty string field to datetime causing this error to spam the logs and fill up the disk. I think the plugin needs to handle these 400 errors more gracefully and not spam multiple copies of the event unless verbose is on. It should be like "Elasticsearch indexing failed action with response of 400, dropping action. Check your index naming, type mappings and elasticsearch logs." |
|
thanks @johnarnold. I followed the progress that was made in #3561 between you and @jordansissel. I understand that such mapping errors would result in many repeated warnings (if the issue exists in many of your documents)... would you prefer to only see such errors in debug mode? or would you prefer a configuration option instead. As these are not debug warnings, but rather real errors occuring which prevent you from successfully indexing messages |
|
I think they are real errors indicating dropping events, which is important to log at default logging level. However, I think that loggingthe whole event (multiple times per attempt/retry?) makes it harder to understand what is actually happening as a user. A simpler, shorter and more succinct log message would be easier to root cause and less likely to blow up your disk. I think that if the logging level is configurable on the plugin, and set to debug then it would be worthwhile to log the whole event. |
|
Perhaps someone can clarify the intended logic of the plugin when errors occur. Here's my confusion: In https://github.com/logstash-plugins/logstash-output-elasticsearch/blob/master/lib/logstash/outputs/elasticsearch/protocol.rb#L84 there's a method def self.normalize_bulk_response(bulk_response) which flattens the elasticsearch response to just the status codes for each item (nuking the actual 'error' property which tells us what's going on). Then in https://github.com/logstash-plugins/logstash-output-elasticsearch/blob/master/lib/logstash/outputs/elasticsearch.rb#L516 the caller handles any bulk responses that contain error codes by logging the whole action, but not the actual error returned from ES. Wouldn't it make more sense for the client to bubble up the errors rather than normalizing them, and actual log the error returned from ES, rather than the response code and action? Also, couldn't the logging of the whole action (event) be moved to logger.debug so as to avoid filling up the disk? |
|
this can be done yes. A normalization step will likely occur regardless to make the responses from both the node and http clients consistent. Please file a ticket with this request and we can work on that |
|
What's the status on this? I think a lot of different people are reporting in this thread but I can find some things in common with some of you. This problem appeared after upgrading ES and LS to 1.5. The problem only affects the gelf input listener in my case and this also happens to be where all my MS Windows EventLogs are coming from. Nxlog sends in gelf to my logstash listener. So I've disabled gelf listener for now to avoid filling disk space, but what is the solution? |
|
Posting if this helps anyone... I was banging my head against a wall trying to figure out what was breaking logstash. Searched the "Error 400" and came across this post. I had a basic output to elasticsearch but have recently been placing more items in for indexing. I added the "index => " it it began spamming the errors. I found the issue I was having was I placed in "index => "PFSense"... When I placed it in as lowercase it fixed my issues. Hope it helps someone. |
|
What is the status of this? At the risk of editorializing I'm not sure why lowercasing json input would fix this. Seems like a major bug to me, and it's blocking our team (at least from our desire to record activity in elasticsearch). |
|
@4n3w could you please explain your specific scenario that is an issue? |
|
@4n3w what exactly is your issue? Please open a new ticket. I am closing this ticket, please open new issues when you see them |
|
Why close this ticket? My issue gives the same error when logstash tries to insert into a field in elasticsearch with a wrong mapping. Thus results in a failed insert and over time crashes logstash without any errors. |
|
@elvarb there are a ton of responses on this issue with some not-entirely-related problems. As a result, it's hard for us to follow exactly what specific issue (one, not many!) needs resolving. To help sort this out, we'd love for new tickets to be filed specific to each person's issue. We can help sort through the problem reports and combine tickets if there are duplicates filed. |
|
Two things to solve
|
|
Makes sense, will make a new ticket, soonish. On vacation 😁 |
|
@elvarb Thanks! Please enjoy your vacation! :) |
|
I had the same problem with previous versions of LogStash output to Elasticsearch, In Short lowercase index name is needed %{environment} can generate upper case, causing this hang / 400 error . you can use the mutate filter on your logstash input { Best of Luck |
|
had the same problem yesterday. it all happened because i turned on PS: just setting it back to
|
|
@yodog If so can you share the ElasticSearch section of your LogStash script . in some cases if the tokens passed to the index name are not resolving properly , they may include some characters causing similar error. |
|
I am facing the same problem for my log events. so I tried to create the same log event multiple times which is causing the issue and found some logs reached elasticsearch just fine, some failed with this exception. Exception: |
and others
(This issue was originally filed by @MarkusMayer at elastic/logstash#3131)
Hi,
I am using 1.5rc3 on Windows. I tried to specify a variable index-naming scheme in my elasticsearch output like this in my output section:
When using this config I my events won't ship to ES and I get the following error in my logstash output:
"failed action with response of 400, dropping action" (full message is below)
Any idea what I've misconfigured?
Thanks in advance,
Markus
Data: https://gist.githubusercontent.com/jordansissel/9d06c66d27f4d09c72d5/raw/36f6d8bda7ee5475c66914b0469140fe9b95361e/data.log
The text was updated successfully, but these errors were encountered: