search

etingof / pysnmp

Python SNMP library
http://snmplabs.com/pysnmp/
BSD 2-Clause "Simplified" License
578 stars 199 forks source link

SNMPV3 trap: snmpEngineBoots and snmpEngineTime in some trap messages were set to zero #151

Open JonathanHsuHH opened 6 years ago

JonathanHsuHH commented 6 years ago

Hi Ilya, I'm using pysnmp to build a SNMP agent. The SNMP Manager send get-request to my agent regularly, and the agent send trap at times. And I found that the snmpEngineBoots and snmpEngineTime in some trap messages were set to zero, and then these trap message were dropped by SNMP manager. As I know, the snmpEngineBoots and snmpEngineTime from SNMP agent will synchronize after receiving request message from the same EngineID. So I enabled the debug in pysnmp/proto/secmod/rfc3414/service.py and printed the receiving time and expire time. In the debug log, my agent received a message in time 767, the timeline of this EngineID was expired in time 1367. The new incoming messages didn't prevent the timeline expire for this EngineID. I think this may be reason of my problem. I hope you can help to confirm this issue.
Thank you.

Some of the debug log is shown below： Line 227: 2018-04-29 14:06:06,602 pysnmp: processIncomingMsg: store timeline for securityEngineID OctetString(hexValue='8000ea2ffc4a1e86') 1367 767 Line 406: 2018-04-29 14:06:06,652 pysnmp: processIncomingMsg: store timeline for securityEngineID OctetString(hexValue='8000ea2ffc4a1e86') 1368 768 Line 755: 2018-04-29 14:06:34,790 pysnmp: processIncomingMsg: store timeline for securityEngineID OctetString(hexValue='8000ea2ffc4a1e86') 1423 823 Line 934: 2018-04-29 14:06:34,802 pysnmp: processIncomingMsg: store timeline for securityEngineID OctetString(hexValue='8000ea2ffc4a1e86') 1424 824 Line 2392: 2018-04-29 14:06:53,453 pysnmp: processIncomingMsg: store timeline for securityEngineID OctetString(hexValue='8000ea2ffc4a1e86') 1460 860 Line 2571: 2018-04-29 14:06:53,465 pysnmp: processIncomingMsg: store timeline for securityEngineID OctetString(hexValue='8000ea2ffc4a1e86') 1461 861 Line 5138: 2018-04-29 14:07:38,995 pysnmp: processIncomingMsg: store timeline for securityEngineID OctetString(hexValue='8000ea2ffc4a1e86') 1551 951 Line 5317: 2018-04-29 14:07:39,006 pysnmp: processIncomingMsg: store timeline for securityEngineID OctetString(hexValue='8000ea2ffc4a1e86') 1551 951

Line 20720: 2018-04-29 14:11:07,825 pysnmp: __expireTimelineInfo: expiring OctetString(hexValue='8000ea2ffc4a1e86') 1367

etingof commented 6 years ago

This is interesting, TRAPs should always have boots/time initialized.

Keep in mind that boots/time are driven by the authoritative SNMP engine. The non-authoritative ones are supposed to store boots/time of all their authoritative peers indexed by their snmpEngineId's.

Your SNMP agent is running the authoritative engine ID so its boots/time should be the used in both SNMP TRAPs and commands.

I am not sure the log you gathered reveals the problem though. Can you log the same thing for TRAPs?

JonathanHsuHH commented 6 years ago

Yes, boots/time should be driven by SNMP agent. But when I use pysnmp to send a SNMPv3 trap， the boots/time is always zero before receiving a get-request from SNMP manager.
I use the trap method reference to the example in pysnmp/examples/v3arch/asyncore/agent/ntforg/v3-trap.py. ntforg.NotificationOriginator.sendVarBinds() The entire log is too long , and I don't have the permission to upload file because of the firewall policy. So I paste some trap sending log, you can see the snmpEngineBoots and snmpEngineTime are from the stored timeline. Is any possible that I use the wrong api?

Trap sending log: 2018-04-29 14:07:02,831 pysnmp: sendVarBinds: notificationHandle 2015106749, sendRequestHandle None, timeout 3 2018-04-29 14:07:02,831 pysnmp: sendVarBinds: notificationHandle 2015106749, notifyTag all-my-managers yields: transportDomain 1.3.6.1.6.1.1, transportAddress ('192.168.10.3', 162), securityModel 3, securityName trapinit, securityLevel 3 2018-04-29 14:07:02,831 pysnmp: isAccessAllowed: securityModel 3, securityName trapinit, securityLevel 3, viewType notify, contextName for variableName 1.3.6.1.4.1.2011.2.14.6.1.3.6.4.0 2018-04-29 14:07:02,831 pysnmp: StatusInformation: {'errorIndication': <pysnmp.proto.errind.AccessAllowed instance at 0x7f8954b38998>} 2018-04-29 14:07:02,832 pysnmp: sendVarBinds: ACL succeeded for OID 1.3.6.1.4.1.2011.2.14.6.1.3.6.4.0 securityName trapinit 2018-04-29 14:07:02,832 pysnmp: isAccessAllowed: securityModel 3, securityName trapinit, securityLevel 3, viewType notify, contextName for variableName 1.3.6.1.4.1.2011.2.14.6.1.3.6.1.0 2018-04-29 14:07:02,832 pysnmp: StatusInformation: {'errorIndication': <pysnmp.proto.errind.AccessAllowed instance at 0x7f8954b38998>} 2018-04-29 14:07:02,832 pysnmp: sendVarBinds: ACL succeeded for OID 1.3.6.1.4.1.2011.2.14.6.1.3.6.1.0 securityName trapinit 2018-04-29 14:07:02,832 pysnmp: isAccessAllowed: securityModel 3, securityName trapinit, securityLevel 3, viewType notify, contextName for variableName 1.3.6.1.4.1.2011.2.14.6.1.3.6.3.0 2018-04-29 14:07:02,832 pysnmp: StatusInformation: {'errorIndication': <pysnmp.proto.errind.AccessAllowed instance at 0x7f8954b38998>} 2018-04-29 14:07:02,833 pysnmp: sendVarBinds: ACL succeeded for OID 1.3.6.1.4.1.2011.2.14.6.1.3.6.3.0 securityName trapinit 2018-04-29 14:07:02,833 pysnmp: isAccessAllowed: securityModel 3, securityName trapinit, securityLevel 3, viewType notify, contextName for variableName 1.3.6.1.4.1.2011.2.14.6.1.3.6.2.0 2018-04-29 14:07:02,833 pysnmp: StatusInformation: {'errorIndication': <pysnmp.proto.errind.AccessAllowed instance at 0x7f8954b38998>} 2018-04-29 14:07:02,833 pysnmp: sendVarBinds: ACL succeeded for OID 1.3.6.1.4.1.2011.2.14.6.1.3.6.2.0 securityName trapinit 2018-04-29 14:07:02,834 pysnmp: prepareOutgoingMessage: new msgID 14514528 2018-04-29 14:07:02,834 pysnmp: prepareOutgoingMessage: peer SNMP engine data None for transport 1.3.6.1.6.1.1, address ('192.168.10.3', 162) 2018-04-29 14:07:02,834 pysnmp: prepareOutgoingMessage: using contextEngineId SnmpEngineID(hexValue='8000ea2ffc4a1e86'), contextName OctetString('') 2018-04-29 14:07:02,835 pysnmp: prepareOutgoingMessage: SNMPv3Message: msgVersion=3 msgGlobalData=HeaderData: msgID=14514528 msgMaxSize=65507 msgFlags=0x03 msgSecurityModel=3

msgSecurityParameters=0x303304088000ea2ffc4a1e86020102020201b1040874726170696e6974040c0000000000000000000000000408f076df55f11d25bb msgData=ScopedPduData: encryptedPDU=0x2cea29382238b865e82c770362651d4b6971259837e804093f5a89cceb20d5dc65c6d9b980fb61ff3d48863ada1f444bbf4330a54f5fbe6f9fbad65b29b8b49880db7d4a0168428d0e2d1d16074defabf366abeb8f34c48604b4b784b6ed4dc701c615e0e2c8e2c17fe5fdd82cc39382ce9ac363899572bc8e574505d7d7ffb619206073f650c2bed123c3661d4f3f31ec2a468e9127eb93905f590f8ad3ac2eb0832a4cee3e6edf129d0c89a54586bc52070bb51c0de257945f6b9f916138c35e3f4b15f72f3c249876aad91e854c56e5ebbf73cb8252aff3e7c855fc6b21fc

2018-04-29 14:07:02,835 pysnmp: prepareOutgoingMessage: securityModel SnmpSecurityModel(3, subtypeSpec=ConstraintsIntersection(ConstraintsIntersection(ConstraintsIntersection(ConstraintsIntersection(), ValueRangeConstraint(-2147483648, 2147483647)), ValueRangeConstraint(0, 2147483647)), ValueRangeConstraint(1, 2147483647))), securityEngineId SnmpEngineID(hexValue='8000ea2ffc4a1e86'), securityName SnmpAdminString('trapinit'), securityLevel SnmpSecurityLevel('authPriv') 2018-04-29 14:07:02,836 pysnmp: _sec2usr: using userName SnmpAdminString('trapinit', subtypeSpec=ConstraintsIntersection(ConstraintsIntersection(ConstraintsIntersection(ConstraintsIntersection(), ValueSizeConstraint(0, 65535)), ValueSizeConstraint(0, 255)), ValueSizeConstraint(1, 32))) for snmpEngineId SnmpEngineID(hexValue='8000ea2ffc4a1e86'), securityName SnmpAdminString('trapinit') 2018-04-29 14:07:02,836 pysnmp: generateRequestOrResponseMsg: read user info 2018-04-29 14:07:02,836 pysnmp: generateRequestOrResponseMsg: local usmUserName SnmpAdminString('trapinit', subtypeSpec=ConstraintsIntersection(ConstraintsIntersection(ConstraintsIntersection(ConstraintsIntersection(), ValueSizeConstraint(0, 65535)), ValueSizeConstraint(0, 255)), ValueSizeConstraint(1, 32))) usmUserSecurityName SnmpAdminString('trapinit') usmUserAuthProtocol 1.3.6.1.6.3.10.1.1.3 usmUserPrivProtocol 1.3.6.1.6.3.10.1.2.4 securityEngineID SnmpEngineID(hexValue='8000ea2ffc4a1e86') securityName SnmpAdminString('trapinit') 2018-04-29 14:07:02,836 pysnmp: generateRequestOrResponseMsg: read snmpEngineBoots, snmpEngineTime from timeline 2018-04-29 14:07:02,836 pysnmp: generateRequestOrResponseMsg: use snmpEngineBoots 2 snmpEngineTime 433 for securityEngineID SnmpEngineID(hexValue='8000ea2ffc4a1e86') 2018-04-29 14:07:02,836 pysnmp: __generateRequestOrResponseMsg: scopedPDU ScopedPDU: contextEngineId=0x8000ea2ffc4a1e86 contextName= data=PDUs: snmpV2-trap=SNMPv2TrapPDU: request-id=16625894 error-status='noError' error-index=0 variable-bindings=VarBindList: VarBind: name=1.3.6.1.2.1.1.3.0 =_BindValue: value=ObjectSyntax: application-wide=ApplicationSyntax: timeticks-value=44124

VarBind:
 name=1.3.6.1.6.3.1.1.4.1.0
 =_BindValue:
  value=ObjectSyntax:
   simple=SimpleSyntax:
    objectID-value=1.3.6.1.4.1.2011.2.14.6.1.5.1

VarBind:
 name=1.3.6.1.4.1.2011.2.14.6.1.3.6.4.0
 =_BindValue:
  value=ObjectSyntax:
   simple=SimpleSyntax:
    integer-value=2

VarBind:
 name=1.3.6.1.4.1.2011.2.14.6.1.3.6.1.0
 =_BindValue:
  value=ObjectSyntax:
   simple=SimpleSyntax:
    integer-value=0

VarBind:
 name=1.3.6.1.4.1.2011.2.14.6.1.3.6.3.0
 =_BindValue:
  value=ObjectSyntax:
   simple=SimpleSyntax:
    string-value=DiskUsage=20.45,DiskTotal=96.46G,partition=/

VarBind:
 name=1.3.6.1.4.1.2011.2.14.6.1.3.6.2.0
 =_BindValue:
  value=ObjectSyntax:
   simple=SimpleSyntax:
    integer-value=205

2018-04-29 14:07:02,837 pysnmp: generateRequestOrResponseMsg: scopedPDU encoded into 00000: 30 81 D0 04 08 80 00 EA 2F FC 4A 1E 86 04 00 A7 00016: 81 C1 02 04 00 FD B0 E6 02 01 00 02 01 00 30 81 00032: B2 30 0F 06 08 2B 06 01 02 01 01 03 00 43 03 00 00048: AC 5C 30 1B 06 0A 2B 06 01 06 03 01 01 04 01 00 00064: 06 0D 2B 06 01 04 01 8F 5B 02 0E 06 01 05 01 30 00080: 14 06 0F 2B 06 01 04 01 8F 5B 02 0E 06 01 03 06 00096: 04 00 02 01 02 30 14 06 0F 2B 06 01 04 01 8F 5B 00112: 02 0E 06 01 03 06 01 00 02 01 00 30 3F 06 0F 2B 00128: 06 01 04 01 8F 5B 02 0E 06 01 03 06 03 00 04 2C 00144: 44 69 73 6B 55 73 61 67 65 3D 32 30 2E 34 35 2C 00160: 44 69 73 6B 54 6F 74 61 6C 3D 39 36 2E 34 36 47 00176: 2C 70 61 72 74 69 74 69 6F 6E 3D 2F 30 15 06 0F 00192: 2B 06 01 04 01 8F 5B 02 0E 06 01 03 06 02 00 02 00208: 02 00 CD 2018-04-29 14:07:02,838 pysnmp: generateRequestOrResponseMsg: scopedPDU ciphered into 00000: 2A 4A C7 CB F1 E0 7B 12 42 BA 71 10 EB 5D F6 5E 00016: EA A5 78 E0 40 12 1A B7 71 7A 24 2C 86 01 F4 D3 00032: 11 EB A0 79 BC D2 D2 2D 5E E7 8E 11 C6 5A 6E F6 00048: 50 2C 7A 3D CC 13 EC 62 C7 2B 8A 34 62 CB 1A 5B 00064: 75 F9 D4 AD 0D 40 B8 56 C0 F0 11 B4 C7 30 92 6A 00080: 25 0C 0B 73 3B 07 78 78 90 9C AA 1E 28 DD 07 CA 00096: 4F A8 47 CD 55 9F 25 55 3B 67 D8 23 42 AD 77 61 00112: 3A 05 9E DC C7 B7 BD 3F 6A 20 7C E7 F9 5A 57 8F 00128: 37 2A 0C 05 A4 76 2E B4 C3 E9 13 1C 9F CC 31 3E 00144: F4 AB 50 F3 F3 71 5C 47 97 2F 93 3C 3F 99 46 67 00160: 09 EE BB 4F 47 57 68 22 34 36 2B 28 60 7D 8F DE 00176: 47 96 E5 9A AF F9 01 F5 19 16 51 27 69 63 E9 45 00192: 04 47 4B 10 5C 55 37 0B 0D 50 6D 67 ED 9C DC 7E 00208: C4 A1 5C BF A4 6C DB 92 0C 31 65 4D E3 26 29 AB 2018-04-29 14:07:02,838 pysnmp: __generateRequestOrResponseMsg: ScopedPduData: encryptedPDU=0x2a4ac7cbf1e07b1242ba7110eb5df65eeaa578e040121ab7717a242c8601f4d311eba079bcd2d22d5ee78e11c65a6ef6502c7a3dcc13ec62c72b8a3462cb1a5b75f9d4ad0d40b856c0f011b4c730926a250c0b733b077878909caa1e28dd07ca4fa847cd559f25553b67d82342ad77613a059edcc7b7bd3f6a207ce7f95a578f372a0c05a4762eb4c3e9131c9fcc313ef4ab50f3f3715c47972f933c3f99466709eebb4f4757682234362b28607d8fde4796e59aaff901f5191651276963e94504474b105c55370b0d506d67ed9cdc7ec4a15cbfa46cdb920c31654de32629ab

2018-04-29 14:07:02,839 pysnmp: __generateRequestOrResponseMsg: UsmSecurityParameters: msgAuthoritativeEngineID=0x8000ea2ffc4a1e86 msgAuthoritativeEngineBoots=2 msgAuthoritativeEngineTime=433 msgUserName=trapinit msgAuthenticationParameters=0x000000000000000000000000 msgPrivacyParameters=0xf076df55f11d25bc

2018-04-29 14:07:02,839 pysnmp: __generateRequestOrResponseMsg: auth outgoing msg: SNMPv3Message: msgVersion=3 msgGlobalData=HeaderData: msgID=14514528 msgMaxSize=65507 msgFlags=0x03 msgSecurityModel=3

msgSecurityParameters=0x303304088000ea2ffc4a1e86020102020201b1040874726170696e6974040c0000000000000000000000000408f076df55f11d25bc msgData=ScopedPduData: encryptedPDU=0x2a4ac7cbf1e07b1242ba7110eb5df65eeaa578e040121ab7717a242c8601f4d311eba079bcd2d22d5ee78e11c65a6ef6502c7a3dcc13ec62c72b8a3462cb1a5b75f9d4ad0d40b856c0f011b4c730926a250c0b733b077878909caa1e28dd07ca4fa847cd559f25553b67d82342ad77613a059edcc7b7bd3f6a207ce7f95a578f372a0c05a4762eb4c3e9131c9fcc313ef4ab50f3f3715c47972f933c3f99466709eebb4f4757682234362b28607d8fde4796e59aaff901f5191651276963e94504474b105c55370b0d506d67ed9cdc7ec4a15cbfa46cdb920c31654de32629ab

2018-04-29 14:07:02,840 pysnmp: __generateRequestOrResponseMsg: authenticated outgoing msg: 00000: 30 82 01 30 02 01 03 30 11 02 04 00 DD 79 60 02 00016: 03 00 FF E3 04 01 03 02 01 03 04 35 30 33 04 08 00032: 80 00 EA 2F FC 4A 1E 86 02 01 02 02 02 01 B1 04 00048: 08 74 72 61 70 69 6E 69 74 04 0C DB E6 A8 DB 6D 00064: FB CE 3C D6 1E 99 C0 04 08 F0 76 DF 55 F1 1D 25 00080: BC 04 81 E0 2A 4A C7 CB F1 E0 7B 12 42 BA 71 10 00096: EB 5D F6 5E EA A5 78 E0 40 12 1A B7 71 7A 24 2C 00112: 86 01 F4 D3 11 EB A0 79 BC D2 D2 2D 5E E7 8E 11 00128: C6 5A 6E F6 50 2C 7A 3D CC 13 EC 62 C7 2B 8A 34 00144: 62 CB 1A 5B 75 F9 D4 AD 0D 40 B8 56 C0 F0 11 B4 00160: C7 30 92 6A 25 0C 0B 73 3B 07 78 78 90 9C AA 1E 00176: 28 DD 07 CA 4F A8 47 CD 55 9F 25 55 3B 67 D8 23 00192: 42 AD 77 61 3A 05 9E DC C7 B7 BD 3F 6A 20 7C E7 00208: F9 5A 57 8F 37 2A 0C 05 A4 76 2E B4 C3 E9 13 1C 00224: 9F CC 31 3E F4 AB 50 F3 F3 71 5C 47 97 2F 93 3C 00240: 3F 99 46 67 09 EE BB 4F 47 57 68 22 34 36 2B 28 00256: 60 7D 8F DE 47 96 E5 9A AF F9 01 F5 19 16 51 27 00272: 69 63 E9 45 04 47 4B 10 5C 55 37 0B 0D 50 6D 67 00288: ED 9C DC 7E C4 A1 5C BF A4 6C DB 92 0C 31 65 4D 00304: E3 26 29 AB 2018-04-29 14:07:02,841 pysnmp: sendMessage: outgoingMessage queued (308 octets) 00000: 30 82 01 30 02 01 03 30 11 02 04 00 DD 79 60 02 00016: 03 00 FF E3 04 01 03 02 01 03 04 35 30 33 04 08 00032: 80 00 EA 2F FC 4A 1E 86 02 01 02 02 02 01 B1 04 00048: 08 74 72 61 70 69 6E 69 74 04 0C DB E6 A8 DB 6D 00064: FB CE 3C D6 1E 99 C0 04 08 F0 76 DF 55 F1 1D 25 00080: BC 04 81 E0 2A 4A C7 CB F1 E0 7B 12 42 BA 71 10 00096: EB 5D F6 5E EA A5 78 E0 40 12 1A B7 71 7A 24 2C 00112: 86 01 F4 D3 11 EB A0 79 BC D2 D2 2D 5E E7 8E 11 00128: C6 5A 6E F6 50 2C 7A 3D CC 13 EC 62 C7 2B 8A 34 00144: 62 CB 1A 5B 75 F9 D4 AD 0D 40 B8 56 C0 F0 11 B4 00160: C7 30 92 6A 25 0C 0B 73 3B 07 78 78 90 9C AA 1E 00176: 28 DD 07 CA 4F A8 47 CD 55 9F 25 55 3B 67 D8 23 00192: 42 AD 77 61 3A 05 9E DC C7 B7 BD 3F 6A 20 7C E7 00208: F9 5A 57 8F 37 2A 0C 05 A4 76 2E B4 C3 E9 13 1C 00224: 9F CC 31 3E F4 AB 50 F3 F3 71 5C 47 97 2F 93 3C 00240: 3F 99 46 67 09 EE BB 4F 47 57 68 22 34 36 2B 28 00256: 60 7D 8F DE 47 96 E5 9A AF F9 01 F5 19 16 51 27 00272: 69 63 E9 45 04 47 4B 10 5C 55 37 0B 0D 50 6D 67 00288: ED 9C DC 7E C4 A1 5C BF A4 6C DB 92 0C 31 65 4D 00304: E3 26 29 AB 2018-04-29 14:07:02,841 pysnmp: sendPdu: message sent

etingof commented 6 years ago

Looks like a bug in pysnmp. #152 should have fixed it (to pysnmp 4.x branch atm).

Appreciate your testing. ;)

Harm133 commented 5 years ago

@etingof Any comments about why the #152 PR was closed and not merged in? The patch fixes the issue I had, and would like to see it merged in