SNMP ingested into Logstash is garbled

I'm having a strange problem ingesting snmp into Logstash. This is my pipeline:

input {
  snmptrap {
    port => 162
    type => "snmp"
  }
}

output {
  if [type] == "snmp" {
    stdout { codec => rubydebug }
  }
}

This is a raw tcpdump of the incoming SNMP message from the element:

[user@logstash-server mibs]$ sudo tcpdump -i eth0 -vv -A -T snmp -s 0 udp and port 162
tcpdump: listening on eth0, link-type EN10MB (Ethernet), capture size 65535 bytes
18:21:49.957261 IP (tos 0x0, ttl 64, id 29821, offset 0, flags [DF], proto UDP (17), length 288)
    host-172-16-1-13.novalocal.48098 > host-172-16-1-21.novalocal.snmptrap:  { SNMPv2c { V2Trap(242) R=1882514697  system.sysUpTime.0=51634500 S:1.1.4.1.0=E:11610.6799.3.4.0.5 E:11610.435.5213.1.2.1.0="ProActivePTS" system.sysName.0="pro-pts" E:11610.6799.1.10.0=4 E:11610.435.11281.1.11.1.3.11397.6467="ptsd" E:11610.435.11281.1.11.1.5.11397.6467=1 E:11610.435.11281.1.11.1.6.11397.6467=1 E:11610.435.11281.1.11.1.12.11397.6467=0 } }
..........Vt0........public.....p4.     ......0..0...+.......C....D0..
+.....Z......0...+.....Z.3.]......ProActivePTS0...+.........pro-pts0...+.....Z...

....0...+.....Z.3.........C..ptsd0...+.....Z.3.........C...0...+.....Z.3.........C...0...+.....Z.3.........CA..

And this is what I see in stdout from Logstash:

{
                                            "SNMPv2-MIB::sysName.0" => "0\x82\x01\x00\x02\x01\x01",
                  "RFC1065-SMI::enterprises.11610.435.5213.1.2.1.0" => "0\x82\x01\x00\x02\x01\x01\x04\x06pub",
                       "RFC1065-SMI::enterprises.11610.6799.1.10.0" => "4",
     "RFC1065-SMI::enterprises.11610.435.11281.1.11.1.5.11397.6467" => "1",
                                                             "type" => "snmp",
                                                             "tags" => [
        [0] "snmptrap_enabled"
    ],
                                                         "@version" => "1",
                                                       "@timestamp" => 2018-03-27T18:21:50.041Z,
     "RFC1065-SMI::enterprises.11610.435.11281.1.11.1.3.11397.6467" => "0\x82\x01\x00",
     "RFC1065-SMI::enterprises.11610.435.11281.1.11.1.6.11397.6467" => "1",
                                                    "customer_name" => "poc_2",
                              "DISMAN-EVENT-MIB::sysUpTimeInstance" => "5 days, 23:25:45.00",
                                                          "message" => "#<SNMP::SNMPv2_Trap:0x5ff9028a @request_id=1882514697, @error_index=0, @error_status=0, @source_ip=\"172.16.1.13\", @varbind_list=[#<SNMP::VarBind:0x54046e42 @name=[1.3.6.1.2.1.1.3.0], @value=#<SNMP::TimeTicks:0x3a687373 @value=51634500>>, #<SNMP::VarBind:0x2d92cbe6 @name=[1.3.6.1.6.3.1.1.4.1.0], @value=[1.3.6.1.4.1.11610.6799.3.4.0.5]>, #<SNMP::VarBind:0x399a8dc7 @name=[1.3.6.1.4.1.11610.435.5213.1.2.1.0], @value=\"ProActivePTS\">, #<SNMP::VarBind:0x4e1b82c8 @name=[1.3.6.1.2.1.1.5.0], @value=\"pro-pts\">, #<SNMP::VarBind:0x37918393 @name=[1.3.6.1.4.1.11610.6799.1.10.0], @value=#<SNMP::Integer:0xce7a37c @value=4>>, #<SNMP::VarBind:0x61fee392 @name=[1.3.6.1.4.1.11610.435.11281.1.11.1.3.11397.6467], @value=\"ptsd\">, #<SNMP::VarBind:0x73e130a7 @name=[1.3.6.1.4.1.11610.435.11281.1.11.1.5.11397.6467], @value=#<SNMP::Integer:0x4857b853 @value=1>>, #<SNMP::VarBind:0x799a1e66 @name=[1.3.6.1.4.1.11610.435.11281.1.11.1.6.11397.6467], @value=#<SNMP::Integer:0x6f6e90b4 @value=1>>, #<SNMP::VarBind:0x15f0e1f6 @name=[1.3.6.1.4.1.11610.435.11281.1.11.1.12.11397.6467], @value=#<SNMP::Counter32:0x6010563b @value=0>>]>",
                                        "SNMPv2-MIB::snmpTrapOID.0" => "RFC1065-SMI::enterprises.11610.6799.3.4.0.5",
                                                             "host" => "172.16.1.13",
    "RFC1065-SMI::enterprises.11610.435.11281.1.11.1.12.11397.6467" => "0"
}

Somehow the value of various OIDs is getting messed up...best example is the system name.

From the packet:

system.sysName.0="pro-pts"

In Logstash:

"SNMPv2-MIB::sysName.0" => "0\x82\x01\x00\x02\x01\x01"

I can successfully get the sysName of the server transmitting SNMP using snmpget on the Logstash server as follows:

[user@logstash-server mibs]$ sudo snmpget -v 2c -c public 172.16.1.13 SNMPv2-MIB::sysName.0
SNMPv2-MIB::sysName.0 = STRING: pro-pts

Has anyone seen this before? I discovered this while trying to integrate the MIBs from my element to make my OIDs human readable. I backed out everything to the point where it's the simple pipeline I pasted above, and it's still happening.

Any help would be much appreciated!

Geoff

1 Like

Replying to myself because I had some more time to investigate, finally.

I am convinced this is a bug in the snmptrap input plugin in Logstash.

Evidence:

  1. SNMP isn't garbled/messed up when you capture it using tcpdump:

    [user@server mibs]$ sudo tcpdump -i eth0 -vvv -s 0 -T snmp port 162 and udp
    tcpdump: listening on eth0, link-type EN10MB (Ethernet), capture size 65535 bytes
    22:08:06.223359 IP (tos 0x0, ttl 64, id 29699, offset 0, flags [DF], proto UDP (17), length 288)
    host-172-16-1-13.novalocal.47502 > host-172-16-1-21.novalocal.snmptrap: { SNMPv2c { V2Trap(242) R=185942877 system.sysUpTime.0=225792200 S:1.1.4.1.0=E:11610.6799.3.4.0.5 E:11610.435.5213.1.2.1.0="ProActivePTS" system.sysName.0="pro-pts" E:11610.6799.1.10.0=4 E:11610.435.11281.1.11.1.3.11397.6467="ptsd" E:11610.435.11281.1.11.1.5.11397.6467=1 E:11610.435.11281.1.11.1.6.11397.6467=1 E:11610.435.11281.1.11.1.12.11397.6467=31 } }

  2. SNMP isn't garbled/messed up in the original message field in Logstash:

"message" => "#<SNMP::SNMPv2_Trap:0x136bdb8e @request_id=185942878, @error_index=0, @error_status=0, @source_ip=\"172.16.1.13\", @varbind_list=[#<SNMP::VarBind:0x31e57f3c @name=[1.3.6.1.2.1.1.3.0], @value=#<SNMP::TimeTicks:0xa4f5a83 @value=225795500>>, #<SNMP::VarBind:0x47b557ef @name=[1.3.6.1.6.3.1.1.4.1.0], @value=[1.3.6.1.4.1.11610.6799.3.4.0.6]>, #<SNMP::VarBind:0x3576fa8 @name=[1.3.6.1.4.1.11610.435.5213.1.2.1.0], @value=\"ProActivePTS\">, #<SNMP::VarBind:0x1951fc61 @name=[1.3.6.1.2.1.1.5.0], @value=\"pro-pts\">, #<SNMP::VarBind:0x693a368a @name=[1.3.6.1.4.1.11610.6799.1.10.0], @value=#<SNMP::Integer:0x45d1e6d @value=1>>, #<SNMP::VarBind:0x3c4f1b61 @name=[1.3.6.1.4.1.11610.435.11281.1.11.1.3.11397.6467], @value=\"ptsd\">, #<SNMP::VarBind:0x2aeb5a7d @name=[1.3.6.1.4.1.11610.435.11281.1.11.1.5.11397.6467], @value=#<SNMP::Integer:0x12ddb7cc @value=1>>, #<SNMP::VarBind:0x7e9f7d8c @name=[1.3.6.1.4.1.11610.435.11281.1.11.1.6.11397.6467], @value=#<SNMP::Integer:0x3a4ff52d @value=9>>, #<SNMP::VarBind:0x4a0778ab @name=[1.3.6.1.4.1.11610.435.11281.1.11.1.12.11397.6467], @value=#<SNMP::Counter32:0x351bc5f0 @value=32>>]>"

  1. SNMP is messed up once Logstash automatically parses it out into the various fields (original message field removed for readability):

    {
    "host" => "172.16.1.13",
    "RFC1065-SMI::enterprises.11610.435.5213.1.2.1.0" => "0\x82\x01\x00\x02\x01\x01\x04\x06pub",
    "RFC1065-SMI::enterprises.11610.435.11281.1.11.1.3.11397.6467" => "0\x82\x01\x00",
    "DISMAN-EVENT-MIB::sysUpTimeInstance" => "26 days, 03:12:35.00",
    "SNMPv2-MIB::snmpTrapOID.0" => "RFC1065-SMI::enterprises.11610.6799.3.4.0.6",
    "RFC1065-SMI::enterprises.11610.435.11281.1.11.1.5.11397.6467" => "1",
    "@version" => "1",
    "type" => "snmptrap",
    "SNMPv2-MIB::sysName.0" => "0\x82\x01\x00\x02\x01\x01",
    "RFC1065-SMI::enterprises.11610.435.11281.1.11.1.6.11397.6467" => "9",
    "RFC1065-SMI::enterprises.11610.435.11281.1.11.1.12.11397.6467" => "32",
    "RFC1065-SMI::enterprises.11610.6799.1.10.0" => "1",
    "customer_name" => "poc_2",
    "@timestamp" => 2018-04-16T22:08:38.859Z
    }

I have no filters in place in Logstash. I'm not doing anything special with it...but somehow it gets messed up between arriving in the message field and being parsed out into all the other fields. Has to be happening in Logstash.

I have tried this from two different servers and the result is the same...everything in the message is fine. Parsed fields are garbled. One server is running CentOS Linux release 7.3.1611. The other is running CentOS Linux release 7.4.1708. Both are configured to send traps using trap2sink.

Can someone @ Elastic please take this seriously now and investigate? Not being able to ingest snmp traps is a pretty big deal.

G

Great horny toads I SOLVED IT!!!!!

I was reading this post: Logstash Pipeline from 6.1 not working 6.2.1

...because I really, really needed to fix this so I started poking at random (but related) things in a desperate attempt to figure it out. (I don't know about you, but my brain has this bad habit of not letting me sleep properly when it's trying to solve a problem...)

Anyway, this comment from the above thread caught my attention:

I got the same bug, but my logstash 6.2.2 is installed on CentOS7.
And the same, if I sharp the queue.type: persisted in the pipelines.yml, it works.

I distinctly remember this working back in January back when I was using ELK 6.1, so on a lark I tried commenting out queue.type: persisted in my logstash.yml file and suddenly the garbled SNMP problem went away.

This is the very first event I captured after disabling persistent queues...all fields look correct now:

                                            "SNMPv2-MIB::sysName.0" => "pro-pts",
     "RFC1065-SMI::enterprises.11610.435.11281.1.11.1.3.11397.6467" => "ptsd",
                  "RFC1065-SMI::enterprises.11610.435.5213.1.2.1.0" => "ProActivePTS",
    "RFC1065-SMI::enterprises.11610.435.11281.1.11.1.12.11397.6467" => "43",
                                                    "customer_name" => "poc_2",
                                                         "@version" => "1",
                                                       "@timestamp" => 2018-04-17T20:47:12.629Z,
     "RFC1065-SMI::enterprises.11610.435.11281.1.11.1.5.11397.6467" => "1",
                                                             "type" => "snmptrap",
                                        "SNMPv2-MIB::snmpTrapOID.0" => "RFC1065-SMI::enterprises.11610.6799.3.4.0.5",
                              "DISMAN-EVENT-MIB::sysUpTimeInstance" => "27 days, 01:51:09.00",
                       "RFC1065-SMI::enterprises.11610.6799.1.10.0" => "4",
     "RFC1065-SMI::enterprises.11610.435.11281.1.11.1.6.11397.6467" => "1",
                                                         "hostname" => "172.16.1.13"

FAN-FUGU-TASTIC!

Now...what's all this about persistent queues messing things up? I kinda need those as much as I need to be able to ingest SNMP. :slight_smile:

Hot damn I'm going to actually sleep tonight!

The short version is data goes into the disk buffer (persistent queue) as UTF8 but comes out ASCII 8-bit and it appears most of the filters don't know how to handle ASCII encoding.

I'm glad someone is saving a little bit of their hair after I pulled out most of mine over this issue, lol.

Does that mean I could solve it by configuring the snmptrap plugin to use the plain codec with the "ASCII-8BIT" charset if persistent queues are enabled?

I'll try it tomorrow if someone hasn't already. I'm on daddy duty now so no more playing with Logstash today...

G

Sadly, the answer is that it doesn't work...

Logstash config w/ queues persisted:

[user@pro-govern logstash]$ sudo cat logstash.yml | grep "persisted"
# "persisted" for disk-based acked queueing. Defaults is memory
queue.type: persisted

snmptrap input:

  # snmp traps
  snmptrap {
    port => 162
    type => "snmptrap"
    community => "public"
    yamlmibdir => "/usr/share/logstash/vendor/bundle/jruby/2.3.0/gems/snmp-1.2.0/data/ruby/snmp/mibs"
    codec => plain
    {
      charset => "ASCII-8BIT"
    }
  }

...and garbled SNMP fields:

RFC1065-SMI::enterprises.11610.435.11281.1.11.1.12.11397.6467" => "43",
                                                     "@version" => "1",
              "RFC1065-SMI::enterprises.11610.435.5213.1.2.1.0" => "0\x82\x01\x00\x02\x01\x01\x04\x06pub",
                                        "SNMPv2-MIB::sysName.0" => "0\x82\x01\x00\x02\x01\x01",
                          "DISMAN-EVENT-MIB::sysUpTimeInstance" => "27 days, 04:46:20.00",
                                                   "@timestamp" => 2018-04-17T23:42:24.073Z,
                                                     "hostname" => "172.16.1.13",
 "RFC1065-SMI::enterprises.11610.435.11281.1.11.1.6.11397.6467" => "1",
                                    "SNMPv2-MIB::snmpTrapOID.0" => "RFC1065-SMI::enterprises.11610.6799.3.4.0.5",
                   "RFC1065-SMI::enterprises.11610.6799.1.10.0" => "4",
 "RFC1065-SMI::enterprises.11610.435.11281.1.11.1.5.11397.6467" => "1",
                                                "customer_name" => "poc_2",
 "RFC1065-SMI::enterprises.11610.435.11281.1.11.1.3.11397.6467" => "0\x82\x01\x00",
                                                         "type" => "snmptrap"

Worth a try...

G

Not sure what your flexibility looks like in terms of upgrading, but it looks like they've fixed the issue in Elastic Stack 6.2.4, here's the release notes for Logstash.

Fixed an issue where events passing through the persistent queue had the contents of string type fields corrupted for values containing non-ASCII characters. The solution involved serializing the RubyString as Java String UTF-16 encoded #9167

I saw that and was going to update this post with the information! Thank you.

I'm not in production yet, so I'll be finding out what upgrading my ELK Stack elements looks like this afternoon.

Is there a specific thing we have to do to mark this solved?

Yay Elastic!

G

Just as confirmation for anyone who comes back and checks this thread, the upgrade to Logstash 6.2.4 fixed it. Persistent queues are currently enabled and my SNMP is no longer garbled.

Now, back to INDEXING ALL THE THINGS!

Cheers everyone,

G

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