search

jonnystorm / snmp-elixir

An SNMP client library for Elixir
Mozilla Public License 2.0
33 stars 12 forks source link

DiscoveryAgent times out with SNMPv3 authNoPriv #43

Closed YasminWagenfeld closed 5 years ago

YasminWagenfeld commented 5 years ago

When running 

SNMP.get([1,3,6,1,2,1,1,5,0], "192.168.0.251", SNMP.credential([ :v3, :auth_no_priv, "read", :md5, "Admin123"]))

It returns {:error, :etimedout}, which comes from SNMP.DiscoveryAgent where it comes from :snmpa.discovery().

However, a get-request is sent and a report with a proper EngineID is sent back in response, which seems to be ignored by the agent. As a result the actual get-request (with the OID) is sent with the wrong EngineID and doesn't receive a reply.

Using the command line, this works:

snmpget -v3 -l authNoPriv -u 'read' -a MD5 -A 'Admin123' 192.168.0.251 1.3.6.1.2.1.1.5.0

I would think that this is a bug in Erlang's snmpa, but the comments in #6 indicate that the authNoPriv discovery should work by now.
Am I missing something?

I enabled SNMP trace logging: :snmpa.verbosity(:all, :trace). Here is the log:

Click to expand 
*** [2019-07-17 14:11:00.052] SNMP A-LOCAL-DB LOG ***
   table create row [persistent]:
   Name:    snmpTargetAddrTable
   Indexes: "discovery_agent_192_168_0_251"
   Row:     {"discovery_agent_192_168_0_251",
             [1,3,6,1,2,1,100,1,1],
             [192,168,0,251,0,161],
             100,2,[],"discovery_params",3,1,[],[],2048}
*** [2019-07-17 14:11:00.053] SNMP A-LOCAL-DB TRACE ***
   insert(persistent) -> entry with
   Key: {snmpTargetAddrTable,first}
   Val: {undef,"discovery_agent_192_168_0_251",
               "discovery_agent_192_168_0_251"}
*** [2019-07-17 14:11:00.053] SNMP A-LOCAL-DB TRACE ***
   insert(persistent) -> entry with
   Key: {snmpTargetAddrTable,"discovery_agent_192_168_0_251"}
   Val: {{"discovery_agent_192_168_0_251",
          [1,3,6,1,2,1,100,1,1],
          [192,168,0,251,0,161],
          100,2,[],"discovery_params",3,1,[],[],2048},
         first,first}
*** [2019-07-17 14:11:00.053] SNMP A-LOCAL-DB DEBUG ***
   table create row result:
   true
*** [2019-07-17 14:11:00.065] SNMP MASTER-AGENT LOG ***
   [handle_call] initiate discovery process:
   TargetName:   "discovery_agent_192_168_0_251"
   Notification: coldStart
   ContextName:  []
   Vbs:          []
   DiscoHandler: snmpa_discovery_handler_default
   ExtraInfo:    undefined
*** [2019-07-17 14:11:00.066] SNMP MASTER-AGENT TRACE ***
   handle_discovery -> entry with
   TargetName:   "discovery_agent_192_168_0_251"
   Notification: coldStart
   ContextName:  []
   Varbinds:     []
*** [2019-07-17 14:11:00.082] SNMP MASTER-AGENT TRAP DEBUG ***
   construct_trap -> entry with
   Trap: coldStart
*** [2019-07-17 14:11:00.082] SNMP A-SYMBOLIC-STORE LOG ***
   get notification: coldStart
*** [2019-07-17 14:11:00.082] SNMP A-SYMBOLIC-STORE MS-ETS TRACE ***
   read from table #Ref<0.2894402398.2515140609.172113>: {trap,coldStart}
*** [2019-07-17 14:11:00.082] SNMP A-SYMBOLIC-STORE DEBUG ***
   get notification result: {value,
                                {notification,coldStart,
                                    [1,3,6,1,6,3,1,1,5,1],
                                    [],undefined}}
*** [2019-07-17 14:11:00.082] SNMP MASTER-AGENT TRAP DEBUG ***
   construct_trap -> notification
   {notification,coldStart,[1,3,6,1,6,3,1,1,5,1],[],undefined}
*** [2019-07-17 14:11:00.082] SNMP MASTER-AGENT TRACE ***
   handle_discovery -> trap construction complete:
   Record:   {notification,coldStart,[1,3,6,1,6,3,1,1,5,1],[],undefined}
   InitVars: []
*** [2019-07-17 14:11:00.082] SNMP MASTER-AGENT GENERIC TRACE ***
   table_get_elements -> entry with
   NameDb:        {snmpTargetAddrTable,persistent}
   RowIndex:      "discovery_agent_192_168_0_251"
   Cols:          [2,3,4,5,7,9]
   FirstOwnIndex: 1
*** [2019-07-17 14:11:00.082] SNMP A-LOCAL-DB LOG ***
   table get row [persistent]:
   Name:    snmpTargetAddrTable
   Indexes: "discovery_agent_192_168_0_251"
*** [2019-07-17 14:11:00.082] SNMP A-LOCAL-DB DEBUG ***
   table get row result:
   {"discovery_agent_192_168_0_251",
    [1,3,6,1,2,1,100,1,1],
    [192,168,0,251,0,161],
    100,2,[],"discovery_params",3,1,[],[],2048}
*** [2019-07-17 14:11:00.083] SNMP MASTER-AGENT GENERIC TRACE ***
   handle_table_get -> Res:
   [[1,3,6,1,2,1,100,1,1],[192,168,0,251,0,161],100,2,"discovery_params",1]
*** [2019-07-17 14:11:00.083] SNMP MASTER-AGENT TRAP TRACE ***
   find_dest -> found snmpTargetAddrTable info:
   TDomain:    [1,3,6,1,2,1,100,1,1]
   TAddress:   [192,168,0,251,0,161]
   Timeout:    100
   RetryCount: 2
   Params:     "discovery_params"
*** [2019-07-17 14:11:00.083] SNMP MASTER-AGENT GENERIC TRACE ***
   table_get_elements -> entry with
   NameDb:        {snmpTargetParamsTable,persistent}
   RowIndex:      "discovery_params"
   Cols:          [2,3,4,5,7]
   FirstOwnIndex: 1
*** [2019-07-17 14:11:00.083] SNMP A-LOCAL-DB LOG ***
   table get row [persistent]:
   Name:    snmpTargetParamsTable
   Indexes: "discovery_params"
*** [2019-07-17 14:11:00.083] SNMP A-LOCAL-DB DEBUG ***
   table get row result:
   {"discovery_params",3,3,[],1,3,1}
*** [2019-07-17 14:11:00.083] SNMP MASTER-AGENT GENERIC TRACE ***
   handle_table_get -> Res:
   [3,3,[],1,1]
*** [2019-07-17 14:11:00.083] SNMP MASTER-AGENT TRAP TRACE ***
   find_dest -> found snmpTargetParamsTable info:
   SecModel: 3
   SecName:  []
   SecLevel: 1
*** [2019-07-17 14:11:00.084] SNMP MASTER-AGENT TRAP DEBUG ***
   send_discovery_pdu -> entry with
   Destination address: {[1,3,6,1,2,1,100,1,1],[192,168,0,251,0,161]}
   Target name:         "discovery_agent_192_168_0_251"
   Sec model:           3
   Sec name:            []
   Sec level:           1
   Timeout:             100
   Retry:               2
   Record:              {notification,coldStart,
                                      [1,3,6,1,6,3,1,1,5,1],
                                      [],undefined}
   ContextName:         []
   ExtraInfo:           undefined
*** [2019-07-17 14:11:00.084] SNMP MASTER-AGENT VACM TRACE ***
   auth -> entry with
   ViewType:    notify
   SecModel:    3
   SecName:     []
   SecLevel:    1
   ContextName: []
*** [2019-07-17 14:11:00.084] SNMP MASTER-AGENT VACM DEBUG ***
   check that the context ([]) is known to us
*** [2019-07-17 14:11:00.084] SNMP MASTER-AGENT GENERIC TRACE ***
   table_get_elements -> entry with
   NameDb:        {intContextTable,volatile}
   RowIndex:      []
   Cols:          [1]
   FirstOwnIndex: 1
*** [2019-07-17 14:11:00.084] SNMP A-LOCAL-DB LOG ***
   table get row [volatile]:
   Name:    intContextTable
   Indexes: []
*** [2019-07-17 14:11:00.084] SNMP A-LOCAL-DB DEBUG ***
   table get row result:
   undefined
*** [2019-07-17 14:11:00.085] SNMP MASTER-AGENT GENERIC DEBUG ***
   handle_table_get -> undefined
*** [2019-07-17 14:11:00.085] SNMP MASTER-AGENT VACM DEBUG ***
   check that SecModel (3) and SecName ([]) is valid
*** [2019-07-17 14:11:00.085] SNMP MASTER-AGENT GENERIC TRACE ***
   table_get_elements -> entry with
   NameDb:        {vacmSecurityToGroupTable,persistent}
   RowIndex:      [3,0]
   Cols:          [3,5]
   FirstOwnIndex: 1
*** [2019-07-17 14:11:00.085] SNMP A-LOCAL-DB LOG ***
   table get row [persistent]:
   Name:    vacmSecurityToGroupTable
   Indexes: [3,0]
*** [2019-07-17 14:11:00.085] SNMP A-LOCAL-DB DEBUG ***
   table get row result:
   {3,[],"discovery_group",3,1}
*** [2019-07-17 14:11:00.085] SNMP MASTER-AGENT GENERIC TRACE ***
   handle_table_get -> Res:
   ["discovery_group",1]
*** [2019-07-17 14:11:00.085] SNMP MASTER-AGENT VACM DEBUG ***
   find an access entry and its view name
*** [2019-07-17 14:11:00.085] SNMP MASTER-AGENT VACM TRACE ***
   get_view_name -> entry with
   ViewType:    notify
   GroupName:   "discovery_group"
   ContextName: []
   SecModel:    3
   SecLevel:    1
*** [2019-07-17 14:11:00.085] SNMP MASTER-AGENT VACM TRACE ***
   get_view_name -> Row:
   {1,"discovery","discovery","discovery",3,1}
*** [2019-07-17 14:11:00.085] SNMP MASTER-AGENT VACM DEBUG ***
   find the corresponding mib view (for "discovery")
*** [2019-07-17 14:11:00.086] SNMP MASTER-AGENT VACM TRACE ***
   get_mib_view -> entry with
   ViewName: "discovery"
*** [2019-07-17 14:11:00.086] SNMP A-LOCAL-DB LOG ***
   table vacmViewTreeFamilyTable next [persistent]:
   Indexes: "\tdiscovery"
*** [2019-07-17 14:11:00.086] SNMP A-LOCAL-DB DEBUG ***
   table next result:
   [9,100,105,115,99,111,118,101,114,121,4,1,3,6,1]
*** [2019-07-17 14:11:00.086] SNMP MASTER-AGENT GENERIC TRACE ***
   table_get_elements -> entry with
   NameDb:        {vacmViewTreeFamilyTable,persistent}
   RowIndex:      [9,100,105,115,99,111,118,101,114,121,4,1,3,6,1]
   Cols:          [3,4,6]
   FirstOwnIndex: 1
*** [2019-07-17 14:11:00.086] SNMP A-LOCAL-DB LOG ***
   table get row [persistent]:
   Name:    vacmViewTreeFamilyTable
   Indexes: [9,100,105,115,99,111,118,101,114,121,4,1,3,6,1]
*** [2019-07-17 14:11:00.086] SNMP A-LOCAL-DB DEBUG ***
   table get row result:
   {"discovery",[1,3,6,1],[],1,3,1}
*** [2019-07-17 14:11:00.086] SNMP MASTER-AGENT GENERIC TRACE ***
   handle_table_get -> Res:
   [[],1,1]
*** [2019-07-17 14:11:00.086] SNMP A-LOCAL-DB LOG ***
   table vacmViewTreeFamilyTable next [persistent]:
   Indexes: [9,100,105,115,99,111,118,101,114,121,4,1,3,6,1]
*** [2019-07-17 14:11:00.086] SNMP A-LOCAL-DB DEBUG ***
   table next result:
   endOfTable
*** [2019-07-17 14:11:00.086] SNMP MASTER-AGENT TRAP TRACE ***
   make v2 notification '[1,3,6,1,6,3,1,1,5,1]'
*** [2019-07-17 14:11:00.086] SNMP MASTER-AGENT TRACE ***
   [handle_call] first stage of discovery process initiated
*** [2019-07-17 14:11:00.087] SNMP A-LOCAL-DB LOG ***
   variable get: snmpEngineID [persistent]
*** [2019-07-17 14:11:00.087] SNMP A-NET-IF DEBUG ***
   received send discovery request:
   Pdu:       {pdu,'inform-request',69498947,noError,0,
                   [{varbind,[1,3,6,1,2,1,1,3,0],'TimeTicks',995,undefined},
                    {varbind,[1,3,6,1,6,3,1,1,4,1,0],
                             'OBJECT IDENTIFIER',
                             [1,3,6,1,6,3,1,1,5,1],
                             undefined}]}
   To:        {[1,3,6,1,2,1,100,1,1],[192,168,0,251,0,161]}
   From:      <0.682.0>
   ExtraInfo: undefined
*** [2019-07-17 14:11:00.087] SNMP A-NET-IF TRACE ***
   handle_send_discovery -> entry with
   Pdu:     {pdu,'inform-request',69498947,noError,0,
                 [{varbind,[1,3,6,1,2,1,1,3,0],'TimeTicks',995,undefined},
                  {varbind,[1,3,6,1,6,3,1,1,4,1,0],
                           'OBJECT IDENTIFIER',
                           [1,3,6,1,6,3,1,1,5,1],
                           undefined}]}
   MsgData: {{3,[],0,"discovery_agent_192_168_0_251"},[128,0,0,0,6],[]}
   To:      {[1,3,6,1,2,1,100,1,1],[192,168,0,251,0,161]}
   From:    <0.682.0>
*** [2019-07-17 14:11:00.087] SNMP A-LOCAL-DB LOG ***
   table snmpTargetAddrTable get element [persistent]:
   Indexes: "discovery_agent_192_168_0_251"
   Col:     10
*** [2019-07-17 14:11:00.087] SNMP A-LOCAL-DB DEBUG ***
   table get element result:
   {value,[]}
*** [2019-07-17 14:11:00.094] SNMP A-NET-IF MPD DEBUG ***
   generate_discovery_msg -> 7.1.7 ([])
*** [2019-07-17 14:11:00.094] SNMP A-LOCAL-DB LOG ***
   variable get: snmpEngineMaxMessageSize [persistent]
*** [2019-07-17 14:11:00.094] SNMP A-NET-IF MPD DEBUG ***
   generate_discovery_msg -> 7.1.9b
*** [2019-07-17 14:11:00.098] SNMP A-NET-IF A-USM TRACE ***
   generate_discovery_msg -> entry with
   SecEngineID:     []
   SecName:         []
   SecLevel:        0
   InitialUserName: []
*** [2019-07-17 14:11:00.098] SNMP A-NET-IF A-USM TRACE ***
   encrypt -> 3.1.4b
*** [2019-07-17 14:11:00.102] SNMP A-NET-IF A-USM TRACE ***
   authenticate_outgoing -> encode message only
*** [2019-07-17 14:11:00.102] SNMP A-NET-IF MPD DEBUG ***
   generate_discovery_msg -> 7.1.9c [16]
*** [2019-07-17 14:11:00.102] SNMP A-NOTE-STORE LOG ***
   set note <{agent,1455316769},{note,[],3,[],0,
                                      [128,0,0,0,6],
                                      [],true,69498947}> with life time 1500
*** [2019-07-17 14:11:00.102] SNMP A-NOTE-STORE TRACE ***
   handle_call(set_note) -> SysStartTime: -57646074874
*** [2019-07-17 14:11:00.102] SNMP A-NOTE-STORE TRACE ***
   handle_call(set_note) -> Now: -57646073878
*** [2019-07-17 14:11:00.102] SNMP A-NOTE-STORE TRACE ***
   handle_call(set_note) -> RealUpTime: 996
*** [2019-07-17 14:11:00.102] SNMP A-NOTE-STORE TRACE ***
   handle_call(set_note) -> BestBefore: 2496
*** [2019-07-17 14:11:00.103] SNMP A-NET-IF MPD DEBUG ***
   generate_discovery_msg -> done
*** [2019-07-17 14:11:00.103] SNMP A-NET-IF TRACE ***
   handle_send_discovery -> sent (69498947)
*** [2019-07-17 14:11:00.103] SNMP A-NET-IF DEBUG ***
   loop({state,<0.424.0>,<0.442.0>,<0.441.0>,
               [{transport,#Port<0.22>,transportDomainUdpIpv4,
                           [6000,binary,inet,{reuseaddr,true}],
                           []},
                {transport,#Port<0.23>,transportDomainUdpIpv6,
                           [6000,binary,inet6,
                            {ipv6_v6only,true},
                            {reuseaddr,true}],
                           []}],
               {state,true,true,true},
               {undefined,[]},
               [{69498947,<0.682.0>}],
               false,infinity,snmpa_net_if_filter})
*** [2019-07-17 14:11:01.088] SNMP A-NET-IF DEBUG ***
   received send discovery request:
   Pdu:       {pdu,'inform-request',69498947,noError,0,
                   [{varbind,[1,3,6,1,2,1,1,3,0],'TimeTicks',995,undefined},
                    {varbind,[1,3,6,1,6,3,1,1,4,1,0],
                             'OBJECT IDENTIFIER',
                             [1,3,6,1,6,3,1,1,5,1],
                             undefined}]}
   To:        {[1,3,6,1,2,1,100,1,1],[192,168,0,251,0,161]}
   From:      <0.682.0>
   ExtraInfo: undefined
*** [2019-07-17 14:11:01.088] SNMP A-NET-IF TRACE ***
   handle_send_discovery -> entry with
   Pdu:     {pdu,'inform-request',69498947,noError,0,
                 [{varbind,[1,3,6,1,2,1,1,3,0],'TimeTicks',995,undefined},
                  {varbind,[1,3,6,1,6,3,1,1,4,1,0],
                           'OBJECT IDENTIFIER',
                           [1,3,6,1,6,3,1,1,5,1],
                           undefined}]}
   MsgData: {{3,[],0,"discovery_agent_192_168_0_251"},[128,0,0,0,6],[]}
   To:      {[1,3,6,1,2,1,100,1,1],[192,168,0,251,0,161]}
   From:    <0.682.0>
*** [2019-07-17 14:11:01.089] SNMP A-LOCAL-DB LOG ***
   table snmpTargetAddrTable get element [persistent]:
   Indexes: "discovery_agent_192_168_0_251"
   Col:     10
*** [2019-07-17 14:11:01.089] SNMP A-LOCAL-DB DEBUG ***
   table get element result:
   {value,[]}
*** [2019-07-17 14:11:01.089] SNMP A-NET-IF MPD DEBUG ***
   generate_discovery_msg -> 7.1.7 ([])
*** [2019-07-17 14:11:01.089] SNMP A-LOCAL-DB LOG ***
   variable get: snmpEngineMaxMessageSize [persistent]
*** [2019-07-17 14:11:01.089] SNMP A-NET-IF MPD DEBUG ***
   generate_discovery_msg -> 7.1.9b
*** [2019-07-17 14:11:01.090] SNMP A-NET-IF A-USM TRACE ***
   generate_discovery_msg -> entry with
   SecEngineID:     []
   SecName:         []
   SecLevel:        0
   InitialUserName: []
*** [2019-07-17 14:11:01.090] SNMP A-NET-IF A-USM TRACE ***
   encrypt -> 3.1.4b
*** [2019-07-17 14:11:01.090] SNMP A-NET-IF A-USM TRACE ***
   authenticate_outgoing -> encode message only
*** [2019-07-17 14:11:01.090] SNMP A-NET-IF MPD DEBUG ***
   generate_discovery_msg -> 7.1.9c [16]
*** [2019-07-17 14:11:01.090] SNMP A-NOTE-STORE LOG ***
   set note <{agent,1455316770},{note,[],3,[],0,
                                      [128,0,0,0,6],
                                      [],true,69498947}> with life time 1500
*** [2019-07-17 14:11:01.090] SNMP A-NOTE-STORE TRACE ***
   handle_call(set_note) -> SysStartTime: -57646074874
*** [2019-07-17 14:11:01.091] SNMP A-NOTE-STORE TRACE ***
   handle_call(set_note) -> Now: -57646073779
*** [2019-07-17 14:11:01.091] SNMP A-NOTE-STORE TRACE ***
   handle_call(set_note) -> RealUpTime: 1095
*** [2019-07-17 14:11:01.091] SNMP A-NOTE-STORE TRACE ***
   handle_call(set_note) -> BestBefore: 2595
*** [2019-07-17 14:11:01.091] SNMP A-NET-IF MPD DEBUG ***
   generate_discovery_msg -> done
*** [2019-07-17 14:11:01.091] SNMP A-NET-IF TRACE ***
   handle_send_discovery -> sent (69498947)
*** [2019-07-17 14:11:01.092] SNMP A-NET-IF DEBUG ***
   loop({state,<0.424.0>,<0.442.0>,<0.441.0>,
               [{transport,#Port<0.22>,transportDomainUdpIpv4,
                           [6000,binary,inet,{reuseaddr,true}],
                           []},
                {transport,#Port<0.23>,transportDomainUdpIpv6,
                           [6000,binary,inet6,
                            {ipv6_v6only,true},
                            {reuseaddr,true}],
                           []}],
               {state,true,true,true},
               {undefined,[]},
               [{69498947,<0.682.0>}],
               false,infinity,snmpa_net_if_filter})
*** [2019-07-17 14:11:03.089] SNMP A-NET-IF DEBUG ***
   received send discovery request:
   Pdu:       {pdu,'inform-request',69498947,noError,0,
                   [{varbind,[1,3,6,1,2,1,1,3,0],'TimeTicks',995,undefined},
                    {varbind,[1,3,6,1,6,3,1,1,4,1,0],
                             'OBJECT IDENTIFIER',
                             [1,3,6,1,6,3,1,1,5,1],
                             undefined}]}
   To:        {[1,3,6,1,2,1,100,1,1],[192,168,0,251,0,161]}
   From:      <0.682.0>
   ExtraInfo: undefined
*** [2019-07-17 14:11:03.089] SNMP A-NET-IF TRACE ***
   handle_send_discovery -> entry with
   Pdu:     {pdu,'inform-request',69498947,noError,0,
                 [{varbind,[1,3,6,1,2,1,1,3,0],'TimeTicks',995,undefined},
                  {varbind,[1,3,6,1,6,3,1,1,4,1,0],
                           'OBJECT IDENTIFIER',
                           [1,3,6,1,6,3,1,1,5,1],
                           undefined}]}
   MsgData: {{3,[],0,"discovery_agent_192_168_0_251"},[128,0,0,0,6],[]}
   To:      {[1,3,6,1,2,1,100,1,1],[192,168,0,251,0,161]}
   From:    <0.682.0>
*** [2019-07-17 14:11:03.089] SNMP A-LOCAL-DB LOG ***
   table snmpTargetAddrTable get element [persistent]:
   Indexes: "discovery_agent_192_168_0_251"
   Col:     10
*** [2019-07-17 14:11:03.090] SNMP A-LOCAL-DB DEBUG ***
   table get element result:
   {value,[]}
*** [2019-07-17 14:11:03.090] SNMP A-NET-IF MPD DEBUG ***
   generate_discovery_msg -> 7.1.7 ([])
*** [2019-07-17 14:11:03.090] SNMP A-LOCAL-DB LOG ***
   variable get: snmpEngineMaxMessageSize [persistent]
*** [2019-07-17 14:11:03.090] SNMP A-NET-IF MPD DEBUG ***
   generate_discovery_msg -> 7.1.9b
*** [2019-07-17 14:11:03.090] SNMP A-NET-IF A-USM TRACE ***
   generate_discovery_msg -> entry with
   SecEngineID:     []
   SecName:         []
   SecLevel:        0
   InitialUserName: []
*** [2019-07-17 14:11:03.091] SNMP A-NET-IF A-USM TRACE ***
   encrypt -> 3.1.4b
*** [2019-07-17 14:11:03.091] SNMP A-NET-IF A-USM TRACE ***
   authenticate_outgoing -> encode message only
*** [2019-07-17 14:11:03.091] SNMP A-NET-IF MPD DEBUG ***
   generate_discovery_msg -> 7.1.9c [16]
*** [2019-07-17 14:11:03.091] SNMP A-NOTE-STORE LOG ***
   set note <{agent,1455316771},{note,[],3,[],0,
                                      [128,0,0,0,6],
                                      [],true,69498947}> with life time 1500
*** [2019-07-17 14:11:03.091] SNMP A-NOTE-STORE TRACE ***
   handle_call(set_note) -> SysStartTime: -57646074874
*** [2019-07-17 14:11:03.092] SNMP A-NOTE-STORE TRACE ***
   handle_call(set_note) -> Now: -57646073579
*** [2019-07-17 14:11:03.092] SNMP A-NOTE-STORE TRACE ***
   handle_call(set_note) -> RealUpTime: 1295
*** [2019-07-17 14:11:03.092] SNMP A-NOTE-STORE TRACE ***
   handle_call(set_note) -> BestBefore: 2795
*** [2019-07-17 14:11:03.092] SNMP A-NET-IF MPD DEBUG ***
   generate_discovery_msg -> done
*** [2019-07-17 14:11:03.092] SNMP A-NET-IF TRACE ***
   handle_send_discovery -> sent (69498947)
*** [2019-07-17 14:11:03.092] SNMP A-NET-IF DEBUG ***
   loop({state,<0.424.0>,<0.442.0>,<0.441.0>,
               [{transport,#Port<0.22>,transportDomainUdpIpv4,
                           [6000,binary,inet,{reuseaddr,true}],
                           []},
                {transport,#Port<0.23>,transportDomainUdpIpv6,
                           [6000,binary,inet6,
                            {ipv6_v6only,true},
                            {reuseaddr,true}],
                           []}],
               {state,true,true,true},
               {undefined,[]},
               [{69498947,<0.682.0>}],
               false,infinity,snmpa_net_if_filter})

14:11:04.781 [info]  Restoring TTL data
*** [2019-07-17 14:11:07.090] SNMP MASTER-AGENT DEBUG ***
   handle_info(discovery_response) -> entry with
   Response: {error,timeout}
*** [2019-07-17 14:11:07.090] SNMP MASTER-AGENT LOG ***
   handle_discovery_response -> entry with
   From:  {<0.410.0>,#Ref<0.2894402398.2515009537.186952>}
   Error: {error,timeout}
*** [2019-07-17 14:11:07.090] SNMP MASTER-AGENT LOG ***
   <0.682.0> exited for reason normal
*** [2019-07-17 14:11:07.090] SNMP A-MIB-SERVER LOG ***
   info subagents

Here are Wireshark screenshots of the packets sent by snmp-elixir:

wireshark screenshot

get-request

wireshark screenshot

report

wireshark screenshot

get-request with OID

wireshark screenshot

jonnystorm commented 5 years ago

Hi, @YasminWagenfeld! Thank you for the extensive information. I apologize for the wait, but I'll review this later today and let you know what I find.

jonnystorm commented 5 years ago

Just to be clear, @YasminWagenfeld, are you working with :snmp_ex 0.2.3?

It appears to me that USM engineID discovery INFORMs sent to 192.168.0.251 did, indeed, time out, as the SNMPv3 agent should have replied with the initial REPORT much sooner.

In your trace output, we have three notable loop-wait events corresponding to each of the three initial INFORMs:

*** [2019-07-17 14:11:00.103] SNMP A-NET-IF DEBUG ***
   loop({state,<0.424.0>,<0.442.0>,<0.441.0>,
(omitted for brevity)
*** [2019-07-17 14:11:01.092] SNMP A-NET-IF DEBUG ***
   loop({state,<0.424.0>,<0.442.0>,<0.441.0>,
(omitted for brevity)
*** [2019-07-17 14:11:03.092] SNMP A-NET-IF DEBUG ***
   loop({state,<0.424.0>,<0.442.0>,<0.441.0>,
(omitted for brevity)
*** [2019-07-17 14:11:07.090] SNMP MASTER-AGENT DEBUG ***

handle_info(discovery_response) -> entry with

Response: {error,timeout}

Note the exponential backoff being performed, whereby we wait in 1-, 2-, and 4-second intervals, respectively.

After seven seconds and two retries, :snmpa finally times out. Alas, the client never observes the agent's engineId, as can be observed in the "get-request with OID" figure, which contains only the reserved localEngineId, 0x8000000006, rather than the agent's authoritativeEngineId, 0x8000001100300094fb2d182.

Unfortunately, it isn't at all clear to me why your agent is failing to respond in a timely fashion. Is it an HP device? That engineId doesn't quite follow the textual convention for engineIds, but it does contain an SNMP enterprise ID belonging to Hewlett-Packard. If you're working with a Procurve device, you may be able to increase logging sensitivity/verbosity for additional information.

Let me know what you think. Also, for reference, RFC3414 describes the SNMPv3 USM engineId discovery procedure.

jonnystorm commented 5 years ago

I'm closing this issue due to lack of activity. We can alway reopen, if necessary.