eventlog input: UndefinedConversionError from ASCII-8BIT to UTF-8
Description
Gliffy Diagrams
Activity
Romain Lapoux June 10, 2015 at 6:35 AM
Please test LOGSTASH-1506, it must resolve this problem too.
Paul Nickerson June 6, 2014 at 3:53 PMEdited
This has affected me as well. An event 4227 from Tcpip included a binary data field, which Logstash got caught up on. I'm running logstash 1.4.1, with the contrib plugins added in (I think the contrib plugs are needed to get the eventlog input working at all). The full error I get from logstash is:
{
: timestamp=>"2014-06-05T15:01:30.021000-0400",
: message=>"Failed to flush outgoing items",
: outgoing_count=>97,
: exception=>#<Encoding::UndefinedConversionError: ""\x83"" from ASCII-8BIT to UTF-8>,
: backtrace=>[
"org/jruby/RubyString.java:7575:in `encode'",
"json/ext/GeneratorMethods.java:71:in `to_json'",
"C:/logstash/logstash-dni/lib/logstash/event.rb:148:in `to_json'",
"C:/logstash/logstash-dni/lib/logstash/outputs/elasticsearch_http.rb:210:in `flush'",
"org/jruby/RubyArray.java:2404:in `collect'",
"C:/logstash/logstash-dni/lib/logstash/outputs/elasticsearch_http.rb:198:in `flush'",
"C:/logstash/logstash-dni/vendor/bundle/jruby/1.9/gems/stud-0.0.17/lib/stud/buffer.rb:219:in `buffer_flush'",
"org/jruby/RubyHash.java:1339:in `each'",
"C:/logstash/logstash-dni/vendor/bundle/jruby/1.9/gems/stud-0.0.17/lib/stud/buffer.rb:216:in `buffer_flush'",
"C:/logstash/logstash-dni/vendor/bundle/jruby/1.9/gems/stud-0.0.17/lib/stud/buffer.rb:193:in `buffer_flush'",
"C:/logstash/logstash-dni/vendor/bundle/jruby/1.9/gems/stud-0.0.17/lib/stud/buffer.rb:112:in `buffer_initialize'",
"org/jruby/RubyKernel.java:1521:in `loop'",
"C:/logstash/logstash-dni/vendor/bundle/jruby/1.9/gems/stud-0.0.17/lib/stud/buffer.rb:110:in `buffer_initialize'"
],
: level=>: warn
}I will try removing the data field too. This is what I'm trying:
input {
eventlog {
type => "Win32-EventLog"
}
}
filter {
if [type] == "Win32-EventLog" {
mutate {
remove_field => [ "Data" ]
}
}
}And for reference, here is the Windows even that caused the logstash error:
Log Name: System
Source: Tcpip
Date: 6/5/2014 3:01:27 PM
Event ID: 4227
Task Category: None
Level: Warning
Keywords: Classic
User: N/A
Computer: CWWIN
Description:
TCP/IP failed to establish an outgoing connection because the selected local endpoint was recently used to connect to the same remote endpoint. This error typically occurs when outgoing connections are opened and closed at a high rate, causing all available local ports to be used and forcing TCP/IP to reuse a local port for an outgoing connection. To minimize the risk of data corruption, the TCP/IP standard requires a minimum time period to elapse between successive connections from a given local endpoint to a given remote endpoint.
Event Xml:
<Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
<System>
<Provider Name="Tcpip" />
<EventID Qualifiers="32768">4227</EventID>
<Level>3</Level>
<Task>0</Task>
<Keywords>0x80000000000000</Keywords>
<TimeCreated SystemTime="2014-06-05T19:01:27.931400000Z" />
<EventRecordID>57771</EventRecordID>
<Channel>System</Channel>
<Computer>CWWIN</Computer>
<Security />
</System>
<EventData>
<Data>
</Data>
<Binary>00000000010000000000000083100080000000000000000000000000000000000000000000000000</Binary>
</EventData>
</Event>Before I tried removing the Data field, I wanted to verify that it's the correct field. Restarting logstash got it working again without error, and I saw it successfully ship a Windows event. This is the event:
Log Name: System
Source: Service Control Manager
Date: 6/6/2014 11:51:14 AM
Event ID: 7036
Task Category: None
Level: Information
Keywords: Classic
User: N/A
Computer: CWWIN
Description:
The WinHTTP Web Proxy Auto-Discovery Service service entered the stopped state.
Event Xml:
<Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
<System>
<Provider Name="Service Control Manager" Guid="{555908d1-a6d7-4695-8e1e-26931d2012f4}" EventSourceName="Service Control Manager" />
<EventID Qualifiers="16384">7036</EventID>
<Version>0</Version>
<Level>4</Level>
<Task>0</Task>
<Opcode>0</Opcode>
<Keywords>0x8080000000000000</Keywords>
<TimeCreated SystemTime="2014-06-06T15:51:14.061000000Z" />
<EventRecordID>57852</EventRecordID>
<Correlation />
<Execution ProcessID="492" ThreadID="1396" />
<Channel>System</Channel>
<Computer>CWWIN</Computer>
<Security />
</System>
<EventData>
<Data Name="param1">WinHTTP Web Proxy Auto-Discovery Service</Data>
<Data Name="param2">stopped</Data>
<Binary>570069006E0048007400740070004100750074006F00500072006F00780079005300760063002F0031000000</Binary>
</EventData>
</Event>logstash populated the Data field with "WinHttpAutoProxySvc/1". Notice that that does not appear above anywhere. But, if you take the characters in <Event><EventData><Binary>, interpret it as a representation of hexadecimal, and convert it to ASCII, you will get "W?i?n?H?t?t?p?A?u?t?o?P?r?o?x?y?S?v?c?/?1???", where the ? are null characters. So, it looks like logstash does indeed take <Event><EventData><Binary>, and puts it into the Data field.
So now all I need to do is hope that using a filter to remove this field removes it before logstash tries to convert it from ASCII-8BIT to UTF-8.
Fabrice Bacchella February 5, 2014 at 12:51 PM
I've met the same problem with an udp/msgpack input sent to an ElasticSearch output. Once a invalid message is received, the output loop over the same message and all processing is stuck :
Failed to flush outgoing items {:outgoing_count=>86, :exception=>#<Encoding::UndefinedConversionError: ""\xC3"" from ASCII-8BIT to UTF-8>, :backtrace=>["org/jruby/RubyString.java:7571:in `encode'", "json/ext/GeneratorMethods.java:71:in `to_json'", "file:/opt/logstash/logstash.jar!/logstash/event.rb:168:in `to_json'", "file:/opt/logstash/logstash.jar!/logstash/outputs/elasticsearch.rb:322:in `flush'", "org/jruby/RubyArray.java:1613:in `each'", "file:/opt/logstash/logstash.jar!/logstash/outputs/elasticsearch.rb:310:in `flush'", "file:/opt/logstash/logstash.jar!/stud/buffer.rb:219:in `buffer_flush'", "org/jruby/RubyHash.java:1338:in `each'", "file:/opt/logstash/logstash.jar!/stud/buffer.rb:216:in `buffer_flush'", "file:/opt/logstash/logstash.jar!/stud/buffer.rb:193:in `buffer_flush'", "file:/opt/logstash/logstash.jar!/stud/buffer.rb:112:in `buffer_initialize'", "org/jruby/RubyKernel.java:1519:in `loop'", "file:/opt/logstash/logstash.jar!/stud/buffer.rb:110:in `buffer_initialize'"], :level=>:warn}
Failed to flush outgoing items {:outgoing_count=>86, :exception=>#<Encoding::UndefinedConversionError: ""\xC3"" from ASCII-8BIT to UTF-8>, :backtrace=>["org/jruby/RubyString.java:7571:in `encode'", "json/ext/GeneratorMethods.java:71:in `to_json'", "file:/opt/logstash/logstash.jar!/logstash/event.rb:168:in `to_json'", "file:/opt/logstash/logstash.jar!/logstash/outputs/elasticsearch.rb:322:in `flush'", "org/jruby/RubyArray.java:1613:in `each'", "file:/opt/logstash/logstash.jar!/logstash/outputs/elasticsearch.rb:310:in `flush'", "file:/opt/logstash/logstash.jar!/stud/buffer.rb:219:in `buffer_flush'", "org/jruby/RubyHash.java:1338:in `each'", "file:/opt/logstash/logstash.jar!/stud/buffer.rb:216:in `buffer_flush'", "file:/opt/logstash/logstash.jar!/stud/buffer.rb:193:in `buffer_flush'", "file:/opt/logstash/logstash.jar!/stud/buffer.rb:112:in `buffer_initialize'", "org/jruby/RubyKernel.java:1519:in `loop'", "file:/opt/logstash/logstash.jar!/stud/buffer.rb:110:in `buffer_initialize'"], :level=>:warn}
Failed to flush outgoing items {:outgoing_count=>86, :exception=>#<Encoding::UndefinedConversionError: ""\xC3"" from ASCII-8BIT to UTF-8>, :backtrace=>["org/jruby/RubyString.java:7571:in `encode'", "json/ext/GeneratorMethods.java:71:in `to_json'", "file:/opt/logstash/logstash.jar!/logstash/event.rb:168:in `to_json'", "file:/opt/logstash/logstash.jar!/logstash/outputs/elasticsearch.rb:322:in `flush'", "org/jruby/RubyArray.java:1613:in `each'", "file:/opt/logstash/logstash.jar!/logstash/outputs/elasticsearch.rb:310:in `flush'", "file:/opt/logstash/logstash.jar!/stud/buffer.rb:219:in `buffer_flush'", "org/jruby/RubyHash.java:1338:in `each'", "file:/opt/logstash/logstash.jar!/stud/buffer.rb:216:in `buffer_flush'", "file:/opt/logstash/logstash.jar!/stud/buffer.rb:193:in `buffer_flush'", "file:/opt/logstash/logstash.jar!/stud/buffer.rb:112:in `buffer_initialize'", "org/jruby/RubyKernel.java:1519:in `loop'", "file:/opt/logstash/logstash.jar!/stud/buffer.rb:110:in `buffer_initialize'"], :level=>:warn}
...Con Zyor February 2, 2014 at 3:40 PM
Would a simple begin/rescue around line 45 in json.rb be the appropriate way to fix this?
Con Zyor February 2, 2014 at 3:05 PMEdited
Since I'm going into Elasticsearch/Kibana, I can't think of a reason I'd ever need binary data.
So for now I dropped the Data field via
mutate{ drop_field... }as a workaround.
I concur with others who've run into similar issues; exceptions like this would hopefully result in the message being dropped and an error logged, not the whole process exiting.
I receive the following error when reading from Win32-EventLog to RabbitMQ on 1.4.0.dev.
org.jruby.exceptions.RaiseException: (UndefinedConversionError) ""\xA7"" from ASCII-8BIT to UTF-8The LogStash Shipper terminates immediately afterwards. Until encountering this error, the shipper works correctly. I can reproduce this reliably by establishing a remote desktop connection to the host running the shipper, one of the event log messages generated during login seems to be causing the UndefinedConversionError.
My configuration is:
input { eventlog { type => 'Win32-EventLog' codec => json } } output { rabbitmq { codec => json host => 'xxx.xxx.xxx' port => 5672 exchange => 'xxxx' exchange_type => 'topic' password => 'xxxx' persistent => false user => 'xxxx' vhost => 'xxxx' } }The full error is
org.jruby.exceptions.RaiseException: (UndefinedConversionError) ""\xA7"" from ASCII-8BIT to UTF-8 at org.jruby.RubyString.encode(org/jruby/RubyString.java:7571) at json.ext.GeneratorMethods$RbHash.to_json(json/ext/GeneratorMethods.java:71) at RUBY.to_json(file:/C:/logstash/lib/logstash-1.4.0.dev-flatjar.jar!/logstash/event.rb:168) at RUBY.encode(file:/C:/logstash/lib/logstash-1.4.0.dev-flatjar.jar!/logstash/codecs/json.rb:45) at RUBY.receive(file:/C:/logstash/lib/logstash-1.4.0.dev-flatjar.jar!/logstash/outputs/rabbitmq/march_hare.rb:31) at RUBY.handle(file:/C:/logstash/lib/logstash-1.4.0.dev-flatjar.jar!/logstash/outputs/base.rb:86) at RUBY.initialize((eval):17) at org.jruby.RubyProc.call(org/jruby/RubyProc.java:271) at RUBY.output(file:/C:/logstash/lib/logstash-1.4.0.dev-flatjar.jar!/logstash/pipeline.rb:266) at RUBY.outputworker(file:/C:/logstash/lib/logstash-1.4.0.dev-flatjar.jar!/logstash/pipeline.rb:225) at RUBY.start_outputs(file:/C:/logstash/lib/logstash-1.4.0.dev-flatjar.jar!/logstash/pipeline.rb:152)I am running 1.4.0-dev on the advice of other bug reports because I received a similar error running 1.3.3:
org.jruby.exceptions.RaiseException: (InvalidByteSequenceError) ""\xA7"" on ASCII-8BITI have tried adding charset => UTF-8 to the input and output json codecs, to no avail.
c:\logstash>java -jar .\lib\logstash-1.4.0.dev-flatjar.jar version --verbose logstash 1.4.0.dev jruby 1.7.9 (1.9.3p392) 2013-12-06 87b108a on Java HotSpot(TM) Client VM 1.7.0_51-b13 [Windows Server 2008 R2-x86] java 1.7.0_51 (Oracle Corporation) jvm Java HotSpot(TM) Client VM / 24.51-b03 Elasticsearch: Version: 0.90.9, Build: a968646/2013-12-23T10:35:28Z, JVM: 1.7.0_51