diff --git a/CHANGES.txt b/CHANGES.txt index 12bbeeb..f4a6618 100644 --- a/CHANGES.txt +++ b/CHANGES.txt @@ -2,6 +2,12 @@ Revision 0.4.6, released XX-01-2019 ----------------------------------- +- The `--log-level` option added +- Default daemon syslog service destination to a local socket +- Fixed timed log file rotation to respect log file creation time + when computing next rotation time +- Fixed possible file permission issues by initializing pysnmp modules, + logger and variation modules subsystems under reduced user privileges - Improve error reporting in `notification` variation module Revision 0.4.5, released 30-12-2018 diff --git a/scripts/pcap2dev.py b/scripts/pcap2dev.py index aa5ccd7..694eba8 100644 --- a/scripts/pcap2dev.py +++ b/scripts/pcap2dev.py @@ -32,6 +32,7 @@ from snmpsim import confdir, error, log # Defaults +PROGRAM_NAME = 'pcap2dev' verboseFlag = True mibSources = [] defaultMibSources = ['http://mibs.snmplabs.com/asn1/@mib@'] @@ -40,6 +41,8 @@ promiscuousMode = False outputDir = '.' transportIdOffset = 0 +loggingMethod = ['stderr'] +loggingLevel = None variationModuleOptions = "" variationModuleName = variationModule = None listenInterface = captureFile = None @@ -69,6 +72,7 @@ [--debug-asn1=<%s>] [--quiet] [--logging-method=<%s[:args]>] + [--log-level=<%s>] [--mib-source=] [--start-object=] [--stop-object=] @@ -85,13 +89,14 @@ '|'.join([x for x in getattr(pysnmp_debug, 'FLAG_MAP', getattr(pysnmp_debug, 'flagMap', ())) if x != 'mibview']), '|'.join([x for x in getattr(pyasn1_debug, 'FLAG_MAP', getattr(pyasn1_debug, 'flagMap', ()))]), - '|'.join(log.gMap) + '|'.join(log.METHODS_MAP), + '|'.join(log.LEVELS_MAP) ) try: opts, params = getopt.getopt(sys.argv[1:], 'hv', [ 'help', 'version', 'debug=', 'debug-snmp=', 'debug-asn1=', - 'quiet', 'logging-method=', 'start-oid=', 'stop-oid=', + 'quiet', 'logging-method=', 'log-level=', 'start-oid=', 'stop-oid=', 'start-object=', 'stop-object=', 'mib-source=', 'output-dir=', 'transport-id-offset=', 'capture-file=', 'listen-interface=', 'promiscuous-mode', @@ -99,6 +104,7 @@ 'variation-modules-dir=', 'variation-module=', 'variation-module-options=' ]) + except Exception: sys.stderr.write( 'ERROR: %s\r\n%s\r\n' % (sys.exc_info()[1], helpMessage)) @@ -145,12 +151,9 @@ pyasn1_debug.setLogger(pyasn1_debug.Debug(*opt[1].split(','), **dict( loggerName='pcap2dev.pyasn1'))) elif opt[0] == '--logging-method': - try: - log.setLogger('pcap2dev', *opt[1].split(':'), **dict(force=True)) - except error.SnmpsimError: - sys.stderr.write( - '%s\r\n%s\r\n' % (sys.exc_info()[1], helpMessage)) - sys.exit(-1) + loggingMethod = opt[1].split(':') + elif opt[0] == '--log-level': + loggingLevel = opt[1] if opt[0] == '--quiet': verboseFlag = False # obsolete begin @@ -199,7 +202,15 @@ sys.stderr.write('ERROR: pylibpcap package is missing!\r\nGet it by running `pip install https://downloads.sourceforge.net/project/pylibpcap/pylibpcap/0.6.4/pylibpcap-0.6.4.tar.gz`\r\n%s\r\n' % helpMessage) sys.exit(-1) -log.setLogger('pcap2dev', 'stdout') +try: + log.setLogger(PROGRAM_NAME, *loggingMethod, force=True) + + if loggingLevel: + log.setLevel(loggingLevel) + +except error.SnmpsimError: + sys.stderr.write('%s\r\n%s\r\n' % (sys.exc_info()[1], helpMessage)) + sys.exit(1) if isinstance(startOID, rfc1902.ObjectIdentity) or \ isinstance(stopOID, rfc1902.ObjectIdentity): @@ -219,14 +230,14 @@ if variationModuleName: for variationModulesDir in confdir.variation: - log.msg('Scanning "%s" directory for variation modules...' % variationModulesDir) + log.info('Scanning "%s" directory for variation modules...' % variationModulesDir) if not os.path.exists(variationModulesDir): - log.msg('Directory "%s" does not exist' % variationModulesDir) + log.info('Directory "%s" does not exist' % variationModulesDir) continue mod = os.path.join(variationModulesDir, variationModuleName + '.py') if not os.path.exists(mod): - log.msg('Variation module "%s" not found' % mod) + log.info('Variation module "%s" not found' % mod) continue ctx = {'path': mod, 'moduleContext': {}} @@ -238,34 +249,36 @@ execfile(mod, ctx) except Exception: - log.msg('Variation module "%s" execution failure: %s' % (mod, sys.exc_info()[1])) + log.error('Variation module "%s" execution failure: %s' % (mod, sys.exc_info()[1])) sys.exit(-1) else: variationModule = ctx - log.msg('Variation module "%s" loaded' % variationModuleName) + log.info('Variation module "%s" loaded' % variationModuleName) break else: - log.msg('ERROR: variation module "%s" not found' % variationModuleName) + log.error('variation module "%s" not found' % variationModuleName) sys.exit(-1) # Variation module initialization if variationModule: - log.msg('Initializing variation module...') + log.info('Initializing variation module...') for x in ('init', 'record', 'shutdown'): if x not in variationModule: - log.msg('ERROR: missing "%s" handler at variation module "%s"' % (x, variationModuleName)) + log.error('missing "%s" handler at variation module "%s"' % (x, variationModuleName)) sys.exit(-1) try: variationModule['init'](options=variationModuleOptions, mode='recording', startOID=startOID, stopOID=stopOID) + except Exception: - log.msg('Variation module "%s" initialization FAILED: %s' % (variationModuleName, sys.exc_info()[1])) + log.error('Variation module "%s" initialization FAILED: %s' % (variationModuleName, sys.exc_info()[1])) + else: - log.msg('Variation module "%s" initialization OK' % variationModuleName) + log.info('Variation module "%s" initialization OK' % variationModuleName) # Data file builder @@ -301,19 +314,19 @@ def formatValue(self, oid, value, **context): if listenInterface: if verboseFlag: - log.msg('Listening on interface %s in %spromiscuous mode' % (listenInterface, promiscuousMode is False and 'non-' or '')) + log.info('Listening on interface %s in %spromiscuous mode' % (listenInterface, promiscuousMode is False and 'non-' or '')) try: pcapObj.open_live(listenInterface, 65536, promiscuousMode, 1000) except Exception: - log.msg('Error opening interface %s for snooping: %s' % (listenInterface, sys.exc_info()[1])) + log.error('Error opening interface %s for snooping: %s' % (listenInterface, sys.exc_info()[1])) sys.exit(-1) elif captureFile: if verboseFlag: - log.msg('Opening capture file %s' % captureFile) + log.info('Opening capture file %s' % captureFile) try: pcapObj.open_offline(captureFile) except Exception: - log.msg('Error opening capture file %s for reading: %s' % (captureFile, sys.exc_info()[1])) + log.error('Error opening capture file %s for reading: %s' % (captureFile, sys.exc_info()[1])) sys.exit(-1) else: sys.stderr.write('ERROR: no capture file or live interface specified\r\n%s\r\n' % helpMessage) @@ -321,11 +334,11 @@ def formatValue(self, oid, value, **context): if packetFilter: if verboseFlag: - log.msg('Applying packet filter \"%s\"' % packetFilter) + log.info('Applying packet filter \"%s\"' % packetFilter) pcapObj.setfilter(packetFilter, 0, 0) if verboseFlag: - log.msg('Processing records from %s till %s' % (startOID or 'the beginning', stopOID or 'the end')) + log.info('Processing records from %s till %s' % (startOID or 'the beginning', stopOID or 'the end')) def parsePacket(s): @@ -435,19 +448,19 @@ def handlePacket(pktlen, data, timestamp): try: if listenInterface: - log.msg( + log.info( 'Listening on interface "%s", kill me when you are done.' % listenInterface) while True: pcapObj.dispatch(1, handlePacket) elif captureFile: - log.msg('Processing capture file "%s"....' % captureFile) + log.info('Processing capture file "%s"....' % captureFile) args = pcapObj.next() while args: handlePacket(*args) args = pcapObj.next() except (TypeError, KeyboardInterrupt): - log.msg('Shutting down process...') + log.info('Shutting down process...') except Exception: exc_info = sys.exc_info() @@ -458,7 +471,7 @@ def handlePacket(pktlen, data, timestamp): filename = os.path.join(outputDir, context + os.path.extsep + SnmprecRecord.ext) if verboseFlag: - log.msg('Creating simulation context %s at %s' % (context, filename)) + log.info('Creating simulation context %s at %s' % (context, filename)) try: os.mkdir(os.path.dirname(filename)) except OSError: @@ -466,7 +479,7 @@ def handlePacket(pktlen, data, timestamp): try: outputFile = open(filename, 'wb') except IOError: - log.msg('ERROR: writing %s: %s' % (filename, sys.exc_info()[1])) + log.error('writing %s: %s' % (filename, sys.exc_info()[1])) sys.exit(-1) count = total = iteration = 0 @@ -523,14 +536,14 @@ def handlePacket(pktlen, data, timestamp): moreDataNotification = sys.exc_info()[1] if 'period' in moreDataNotification: timeOffset += moreDataNotification['period'] - log.msg( + log.info( '%s OIDs dumped, advancing time window to %.2f sec(s)...' % (total, timeOffset)) break except error.NoDataNotification: pass except error.SnmpsimError: - log.msg('ERROR: %s' % (sys.exc_info()[1],)) + log.error((sys.exc_info()[1],)) continue else: outputFile.write(line) @@ -545,22 +558,23 @@ def handlePacket(pktlen, data, timestamp): outputFile.close() if variationModule: - log.msg('Shutting down variation module "%s"...' % variationModuleName) + log.info('Shutting down variation module "%s"...' % variationModuleName) try: variationModule['shutdown'](options=variationModuleOptions, mode='recording') except Exception: - log.msg('Variation module "%s" shutdown FAILED: %s' % (variationModuleName, sys.exc_info()[1])) + log.error('Variation module "%s" shutdown FAILED: %s' % (variationModuleName, sys.exc_info()[1])) + else: - log.msg('Variation module "%s" shutdown OK' % variationModuleName) + log.info('Variation module "%s" shutdown OK' % variationModuleName) -log.msg("""PCap statistics: +log.info("""PCap statistics: packets snooped: %s packets dropped: %s packets dropped: by interface %s""" % pcapObj.stats()) -log.msg("""SNMP statistics: +log.info("""SNMP statistics: %s""" % ' '.join(['%s: %s\r\n' % kv for kv in stats.items()])) if exc_info: for line in traceback.format_exception(*exc_info): - log.msg(line.replace('\n', ';')) + log.error(line.replace('\n', ';')) diff --git a/scripts/snmprec.py b/scripts/snmprec.py index be00181..d317e3e 100644 --- a/scripts/snmprec.py +++ b/scripts/snmprec.py @@ -36,6 +36,7 @@ from snmpsim import confdir, error, log # Defaults +PROGRAM_NAME = 'snmprec' getBulkFlag = False continueOnErrors = 0 getBulkRepetitions = 25 @@ -61,6 +62,8 @@ outputFile = sys.stdout if hasattr(outputFile, 'buffer'): outputFile = outputFile.buffer +loggingMethod = ['stderr'] +loggingLevel = None variationModuleOptions = "" variationModuleName = variationModule = None @@ -92,6 +95,7 @@ [--debug=<%s>] [--debug-asn1=<%s>] [--logging-method=<%s[:args>]>] + [--log-level=<%s>] [--protocol-version=<1|2c|3>] [--community=] [--v3-user=] @@ -119,7 +123,8 @@ '|'.join([x for x in getattr(pysnmp_debug, 'FLAG_MAP', getattr(pysnmp_debug, 'flagMap', ())) if x != 'mibview']), '|'.join([x for x in getattr(pyasn1_debug, 'FLAG_MAP', getattr(pyasn1_debug, 'flagMap', ()))]), - '|'.join(log.gMap), + '|'.join(log.METHODS_MAP), + '|'.join(log.LEVELS_MAP), '|'.join(sorted([x for x in authProtocols if x != 'NONE'])), '|'.join(sorted([x for x in privProtocols if x != 'NONE'])) ) @@ -127,7 +132,7 @@ try: opts, params = getopt.getopt(sys.argv[1:], 'hv', [ 'help', 'version', 'debug=', 'debug-asn1=', 'logging-method=', - 'quiet', + 'log-level=', 'quiet', 'v1', 'v2c', 'v3', 'protocol-version=', 'community=', 'v3-user=', 'v3-auth-key=', 'v3-priv-key=', 'v3-auth-proto=', 'v3-priv-proto=', @@ -144,6 +149,7 @@ 'variation-modules-dir=', 'variation-module=', 'variation-module-options=', 'continue-on-errors=' ]) + except Exception: sys.stderr.write('ERROR: %s\r\n%s\r\n' % (sys.exc_info()[1], helpMessage)) sys.exit(-1) @@ -187,11 +193,9 @@ elif opt[0] == '--debug-asn1': pyasn1_debug.setLogger(pyasn1_debug.Debug(*opt[1].split(','), **dict(loggerName='snmprec.pyasn1'))) elif opt[0] == '--logging-method': - try: - log.setLogger('snmprec', *opt[1].split(':'), **dict(force=True)) - except error.SnmpsimError: - sys.stderr.write('%s\r\n%s\r\n' % (sys.exc_info()[1], helpMessage)) - sys.exit(-1) + loggingMethod = opt[1].split(':') + elif opt[0] == '--log-level': + loggingLevel = opt[1] elif opt[0] == '--quiet': log.setLogger('snmprec', 'null', force=True) elif opt[0] == '--v1': @@ -366,10 +370,18 @@ v3ContextEngineId = None v3ContextName = '' -log.setLogger('snmprec', 'stderr') +try: + log.setLogger(PROGRAM_NAME, *loggingMethod, force=True) + + if loggingLevel: + log.setLevel(loggingLevel) + +except error.SnmpsimError: + sys.stderr.write('%s\r\n%s\r\n' % (sys.exc_info()[1], helpMessage)) + sys.exit(1) if getBulkFlag and not snmpVersion: - log.msg('WARNING: will be using GETNEXT with SNMPv1!') + log.info('will be using GETNEXT with SNMPv1!') getBulkFlag = False # Attempt to reopen std output stream in binary mode @@ -385,15 +397,15 @@ if variationModuleName: for variationModulesDir in confdir.variation: - log.msg( + log.info( 'Scanning "%s" directory for variation modules...' % variationModulesDir) if not os.path.exists(variationModulesDir): - log.msg('Directory "%s" does not exist' % variationModulesDir) + log.info('Directory "%s" does not exist' % variationModulesDir) continue mod = os.path.join(variationModulesDir, variationModuleName + '.py') if not os.path.exists(mod): - log.msg('Variation module "%s" not found' % mod) + log.info('Variation module "%s" not found' % mod) continue ctx = {'path': mod, 'moduleContext': {}} @@ -403,15 +415,17 @@ exec(compile(open(mod).read(), mod, 'exec'), ctx) else: execfile(mod, ctx) + except Exception: - log.msg('Variation module "%s" execution failure: %s' % (mod, sys.exc_info()[1])) + log.error('Variation module "%s" execution failure: %s' % (mod, sys.exc_info()[1])) sys.exit(-1) + else: variationModule = ctx - log.msg('Variation module "%s" loaded' % variationModuleName) + log.info('Variation module "%s" loaded' % variationModuleName) break else: - log.msg('ERROR: variation module "%s" not found' % variationModuleName) + log.error('variation module "%s" not found' % variationModuleName) sys.exit(-1) # SNMP configuration @@ -430,7 +444,9 @@ authProtocols[v3AuthProto], v3AuthKey, privProtocols[v3PrivProto], v3PrivKey ) - log.msg('SNMP version 3, Context EngineID: %s Context name: %s, SecurityName: %s, SecurityLevel: %s, Authentication key/protocol: %s/%s, Encryption (privacy) key/protocol: %s/%s' % ( + log.info('SNMP version 3, Context EngineID: %s Context name: %s, SecurityName: %s, ' + 'SecurityLevel: %s, Authentication key/protocol: %s/%s, Encryption ' + '(privacy) key/protocol: %s/%s' % ( v3ContextEngineId and v3ContextEngineId.prettyPrint() or '', v3Context and v3Context.prettyPrint() or '', v3User, secLevel, v3AuthKey is None and '' or v3AuthKey, @@ -442,7 +458,7 @@ config.addV1System( snmpEngine, v3User, snmpCommunity ) - log.msg('SNMP version %s, Community name: %s' % (snmpVersion == 0 and '1' or '2c', snmpCommunity)) + log.info('SNMP version %s, Community name: %s' % (snmpVersion == 0 and '1' or '2c', snmpCommunity)) config.addTargetParams(snmpEngine, 'pms', v3User, secLevel, snmpVersion) @@ -456,7 +472,8 @@ snmpEngine, 'tgt', udp6.domainName, agentUDPv6Endpoint, 'pms', timeout, retryCount ) - log.msg('Querying UDP/IPv6 agent at [%s]:%s' % agentUDPv6Endpoint) + log.info('Querying UDP/IPv6 agent at [%s]:%s' % agentUDPv6Endpoint) + elif agentUNIXEndpoint: config.addSocketTransport( snmpEngine, @@ -467,7 +484,8 @@ snmpEngine, 'tgt', unix.domainName, agentUNIXEndpoint, 'pms', timeout, retryCount ) - log.msg('Querying UNIX named pipe agent at %s' % agentUNIXEndpoint) + log.info('Querying UNIX named pipe agent at %s' % agentUNIXEndpoint) + elif agentUDPv4Endpoint: config.addSocketTransport( snmpEngine, @@ -478,9 +496,9 @@ snmpEngine, 'tgt', udp.domainName, agentUDPv4Endpoint, 'pms', timeout, retryCount ) - log.msg('Querying UDP/IPv4 agent at %s:%s' % agentUDPv4Endpoint) + log.info('Querying UDP/IPv4 agent at %s:%s' % agentUDPv4Endpoint) -log.msg('Agent response timeout: %.2f secs, retries: %s' % (timeout / 100, retryCount)) +log.info('Agent response timeout: %.2f secs, retries: %s' % (timeout / 100, retryCount)) if (isinstance(startOID, ObjectIdentity) or isinstance(stopOID, ObjectIdentity)): @@ -497,10 +515,10 @@ # Variation module initialization if variationModule: - log.msg('Initializing variation module...') + log.info('Initializing variation module...') for x in ('init', 'record', 'shutdown'): if x not in variationModule: - log.msg('ERROR: missing "%s" handler at variation module "%s"' % (x, variationModuleName)) + log.error('missing "%s" handler at variation module "%s"' % (x, variationModuleName)) sys.exit(-1) try: variationModule['init'](snmpEngine=snmpEngine, @@ -509,9 +527,11 @@ startOID=startOID, stopOID=stopOID) except Exception: - log.msg('Variation module "%s" initialization FAILED: %s' % (variationModuleName, sys.exc_info()[1])) + log.error('Variation module "%s" initialization FAILED: %s' % ( + variationModuleName, sys.exc_info()[1])) + else: - log.msg('Variation module "%s" initialization OK' % variationModuleName) + log.info('Variation module "%s" initialization OK' % variationModuleName) # Data file builder @@ -550,35 +570,44 @@ def formatValue(self, oid, value, **context): def cbFun(snmpEngine, sendRequestHandle, errorIndication, errorStatus, errorIndex, varBindTable, cbCtx): + if errorIndication and not cbCtx['retries']: cbCtx['errors'] += 1 - log.msg('SNMP Engine error: %s' % errorIndication) + log.error('SNMP Engine error: %s' % errorIndication) return + # SNMPv1 response may contain noSuchName error *and* SNMPv2c exception, # so we ignore noSuchName error here if errorStatus and errorStatus != 2 or errorIndication: - log.msg('Remote SNMP error %s' % (errorIndication or errorStatus.prettyPrint())) + log.error('Remote SNMP error %s' % (errorIndication or errorStatus.prettyPrint())) + if cbCtx['retries']: try: nextOID = varBindTable[-1][0][0] + except IndexError: nextOID = cbCtx['lastOID'] + else: - log.msg('Failed OID: %s' % nextOID) + log.error('Failed OID: %s' % nextOID) + # fuzzy logic of walking a broken OID if len(nextOID) < 4: pass + elif (continueOnErrors - cbCtx['retries']) * 10 / continueOnErrors > 5: nextOID = nextOID[:-2] + (nextOID[-2] + 1,) + elif nextOID[-1]: nextOID = nextOID[:-1] + (nextOID[-1] + 1,) + else: nextOID = nextOID[:-2] + (nextOID[-2] + 1, 0) cbCtx['retries'] -= 1 cbCtx['lastOID'] = nextOID - log.msg('Retrying with OID %s (%s retries left)...' % (nextOID, cbCtx['retries'])) + log.info('Retrying with OID %s (%s retries left)...' % (nextOID, cbCtx['retries'])) # initiate another SNMP walk iteration if getBulkFlag: @@ -656,7 +685,8 @@ def cbFun(snmpEngine, sendRequestHandle, errorIndication, moreDataNotification = sys.exc_info()[1] if 'period' in moreDataNotification: - log.msg('%s OIDs dumped, waiting %.2f sec(s)...' % (cbCtx['total'], moreDataNotification['period'])) + log.info('%s OIDs dumped, waiting %.2f sec(s)...' % ( + cbCtx['total'], moreDataNotification['period'])) time.sleep(moreDataNotification['period']) # initiate another SNMP walk iteration @@ -682,9 +712,11 @@ def cbFun(snmpEngine, sendRequestHandle, errorIndication, except error.NoDataNotification: pass + except error.SnmpsimError: - log.msg('ERROR: %s' % (sys.exc_info()[1],)) + log.error((sys.exc_info()[1],)) continue + else: outputFile.write(line) @@ -692,7 +724,7 @@ def cbFun(snmpEngine, sendRequestHandle, errorIndication, cbCtx['total'] += 1 if cbCtx['count'] % 100 == 0: - log.msg('OIDs dumped: %s/%s' % ( + log.error('OIDs dumped: %s/%s' % ( cbCtx['iteration'], cbCtx['count'])) # Next request time @@ -734,7 +766,8 @@ def cbFun(snmpEngine, sendRequestHandle, errorIndication, cbFun, cbCtx ) -log.msg('Sending initial %s request for %s (stop at %s)....' % (getBulkFlag and 'GETBULK' or 'GETNEXT', startOID, stopOID or '')) +log.info('Sending initial %s request for %s (stop at %s)....' % ( + getBulkFlag and 'GETBULK' or 'GETNEXT', startOID, stopOID or '')) t = time.time() @@ -744,22 +777,25 @@ def cbFun(snmpEngine, sendRequestHandle, errorIndication, try: snmpEngine.transportDispatcher.runDispatcher() + except KeyboardInterrupt: - log.msg('Shutting down process...') + log.info('Shutting down process...') + except Exception: exc_info = sys.exc_info() if variationModule: - log.msg('Shutting down variation module %s...' % variationModuleName) + log.info('Shutting down variation module %s...' % variationModuleName) try: variationModule['shutdown'](snmpEngine=snmpEngine, options=variationModuleOptions, mode='recording') except Exception: - log.msg('Variation module %s shutdown FAILED: %s' % ( + log.error('Variation module %s shutdown FAILED: %s' % ( variationModuleName, sys.exc_info()[1])) + else: - log.msg('Variation module %s shutdown OK' % variationModuleName) + log.info('Variation module %s shutdown OK' % variationModuleName) snmpEngine.transportDispatcher.closeDispatcher() @@ -767,11 +803,12 @@ def cbFun(snmpEngine, sendRequestHandle, errorIndication, cbCtx['total'] += cbCtx['count'] -log.msg('OIDs dumped: %s, elapsed: %.2f sec, rate: %.2f OIDs/sec, errors: %d' % (cbCtx['total'], t, t and cbCtx['count'] // t or 0, cbCtx['errors'])) +log.info('OIDs dumped: %s, elapsed: %.2f sec, rate: %.2f OIDs/sec, errors: %d' % ( + cbCtx['total'], t, t and cbCtx['count'] // t or 0, cbCtx['errors'])) if exc_info: for line in traceback.format_exception(*exc_info): - log.msg(line.replace('\n', ';')) + log.error(line.replace('\n', ';')) outputFile.flush() outputFile.close() diff --git a/scripts/snmpsimd.py b/scripts/snmpsimd.py index f3794b4..bda5286 100644 --- a/scripts/snmpsimd.py +++ b/scripts/snmpsimd.py @@ -45,6 +45,7 @@ from snmpsim.record.search.database import RecordIndex # Settings +PROGRAM_NAME = 'snmpsimd' forceIndexBuild = False validateData = False maxVarBinds = 64 @@ -54,6 +55,8 @@ pidFile = '/var/run/snmpsim/snmpsimd.pid' foregroundFlag = True procUser = procGroup = None +loggingMethod = ['stderr'] +loggingLevel = None variationModulesOptions = {} variationModules = {} @@ -79,6 +82,7 @@ 'NONE': config.usmNoPrivProtocol } + # Transport endpoints collection class TransportEndpointsBase: @@ -243,13 +247,13 @@ def close(self): def getHandles(self): if not self.__recordIndex.isOpen(): if len(DataFile.openedQueue) > self.maxQueueEntries: - log.msg('Closing %s' % self) + log.info('Closing %s' % self) DataFile.openedQueue[0].close() del DataFile.openedQueue[0] DataFile.openedQueue.append(self) - log.msg('Opening %s' % self) + log.info('Opening %s' % self) return self.__recordIndex.getHandles() @@ -264,12 +268,12 @@ def processVarBinds(self, varBinds, **context): try: text, db = self.getHandles() except SnmpsimError: - log.msg('Problem with data file or its index: %s' % sys.exc_info()[1]) + log.error('Problem with data file or its index: %s' % sys.exc_info()[1]) return [(vb[0], errorStatus) for vb in varBinds] varsRemaining = varsTotal = len(varBinds) - log.msg('Request var-binds: %s, flags: %s, %s' % (', '.join(['%s=<%s>' % (vb[0], vb[1].prettyPrint()) for vb in varBinds]), context.get('nextFlag') and 'NEXT' or 'EXACT', context.get('setFlag') and 'SET' or 'GET')) + log.info('Request var-binds: %s, flags: %s, %s' % (', '.join(['%s=<%s>' % (vb[0], vb[1].prettyPrint()) for vb in varBinds]), context.get('nextFlag') and 'NEXT' or 'EXACT', context.get('setFlag') and 'SET' or 'GET')) for oid, val in varBinds: textOid = str(univ.OctetString('.'.join(['%s' % x for x in oid]))) @@ -300,7 +304,7 @@ def processVarBinds(self, varBinds, **context): try: _, subtreeFlag, _ = self.__recordIndex.lookup(str(_nextOid)).split(str2octs(','), 2) except KeyError: - log.msg('data error for %s at %s, index broken?' % (self, _nextOid)) + log.error('data error for %s at %s, index broken?' % (self, _nextOid)) line = '' # fatal error else: subtreeFlag = int(subtreeFlag) @@ -318,7 +322,7 @@ def processVarBinds(self, varBinds, **context): try: _, _, _prevOffset = self.__recordIndex.lookup(str(_oid)).split(str2octs(','), 2) except KeyError: - log.msg('data error for %s at %s, index broken?' % (self, _oid)) + log.error('data error for %s at %s, index broken?' % (self, _oid)) line = '' # fatal error else: _prevOffset = int(_prevOffset) @@ -367,13 +371,13 @@ def processVarBinds(self, varBinds, **context): except Exception: _oid = oid _val = errorStatus - log.msg('data error at %s for %s: %s' % (self, textOid, sys.exc_info()[1])) + log.error('data error at %s for %s: %s' % (self, textOid, sys.exc_info()[1])) break rspVarBinds.append((_oid, _val)) - log.msg('Response var-binds: %s' % (', '.join(['%s=<%s>' % (vb[0], vb[1].prettyPrint()) for vb in rspVarBinds]))) + log.info('Response var-binds: %s' % (', '.join(['%s=<%s>' % (vb[0], vb[1].prettyPrint()) for vb in rspVarBinds]))) return rspVarBinds @@ -447,7 +451,10 @@ def __getCallContext(self, acInfo, nextFlag=False, setFlag=False): execCtx['contextName'], execCtx['pdu'].getTagSet()) - log.msg('SNMP EngineID %s, transportDomain %s, transportAddress %s, securityModel %s, securityName %s, securityLevel %s' % (hasattr(snmpEngine, 'snmpEngineID') and snmpEngine.snmpEngineID.prettyPrint() or '', transportDomain, transportAddress, securityModel, securityName, securityLevel)) + log.info('SNMP EngineID %s, transportDomain %s, transportAddress %s, securityModel %s, ' + 'securityName %s, securityLevel %s' % ( + hasattr(snmpEngine, 'snmpEngineID') and snmpEngine.snmpEngineID.prettyPrint() or '', + transportDomain, transportAddress, securityModel, securityName, securityLevel)) return {'snmpEngine': snmpEngine, 'transportDomain': transportDomain, @@ -475,7 +482,7 @@ def writeVars(self, varBinds, acInfo=None): ) -# Data files index as a MIB instrumentaion at a dedicated SNMP context +# Data files index as a MIB instrumentation in a dedicated SNMP context class DataIndexInstrumController: indexSubOid = (1,) @@ -548,6 +555,7 @@ def probeContext(transportDomain, transportAddress, contextName): [--process-user=] [--process-group=] [--pid-file=] [--logging-method=<%s[:args>]>] + [--log-level=<%s>] [--cache-dir=] [--variation-modules-dir=] [--variation-module-options=] @@ -573,7 +581,8 @@ def probeContext(transportDomain, transportAddress, contextName): '|'.join([x for x in getattr(pysnmp_debug, 'FLAG_MAP', getattr(pysnmp_debug, 'flagMap', ())) if x != 'mibview']), '|'.join([x for x in getattr(pyasn1_debug, 'FLAG_MAP', getattr(pyasn1_debug, 'flagMap', ()))]), - '|'.join(log.gMap), + '|'.join(log.METHODS_MAP), + '|'.join(log.LEVELS_MAP), '|'.join(sorted([x for x in authProtocols if x != 'NONE'])), '|'.join(sorted([x for x in privProtocols if x != 'NONE'])) ) @@ -582,7 +591,7 @@ def probeContext(transportDomain, transportAddress, contextName): opts, params = getopt.getopt(sys.argv[1:], 'hv', [ 'help', 'version', 'debug=', 'debug-snmp=', 'debug-asn1=', 'daemonize', 'process-user=', 'process-group=', 'pid-file=', 'logging-method=', - 'device-dir=', 'cache-dir=', 'variation-modules-dir=', + 'log-level=', 'device-dir=', 'cache-dir=', 'variation-modules-dir=', 'force-index-rebuild', 'validate-device-data', 'validate-data', 'v2c-arch', 'v3-only', 'transport-id-offset=', 'variation-module-options=', @@ -597,6 +606,7 @@ def probeContext(transportDomain, transportAddress, contextName): 'max-varbinds=', 'agent-udpv4-endpoint=', 'agent-udpv6-endpoint=', 'agent-unix-endpoint=' ]) + except Exception: sys.stderr.write('ERROR: %s\r\n%s\r\n' % (sys.exc_info()[1], helpMessage)) sys.exit(-1) @@ -645,11 +655,9 @@ def probeContext(transportDomain, transportAddress, contextName): elif opt[0] == '--pid-file': pidFile = opt[1] elif opt[0] == '--logging-method': - try: - log.setLogger('snmpsimd', *opt[1].split(':'), **dict(force=True)) - except SnmpsimError: - sys.stderr.write('%s\r\n%s\r\n' % (sys.exc_info()[1], helpMessage)) - sys.exit(-1) + loggingMethod = opt[1].split(':') + elif opt[0] == '--log-level': + loggingLevel = opt[1] elif opt[0] in ('--device-dir', '--data-dir'): if [x for x in v3Args if x[0] in ('--v3-engine-id', '--v3-context-engine-id')]: @@ -752,13 +760,17 @@ def probeContext(transportDomain, transportAddress, contextName): else: v3Args = v3Args[len(v3Args)//2:] -log.setLogger('snmpsimd', 'stderr') +with daemon.PrivilegesOf(procUser, procGroup): -try: - daemon.dropPrivileges(procUser, procGroup) -except: - sys.stderr.write('ERROR: cant drop priveleges: %s\r\n%s\r\n' % (sys.exc_info()[1], helpMessage)) - sys.exit(-1) + try: + log.setLogger(PROGRAM_NAME, *loggingMethod, force=True) + + if loggingLevel: + log.setLevel(loggingLevel) + + except SnmpsimError: + sys.stderr.write('%s\r\n%s\r\n' % (sys.exc_info()[1], helpMessage)) + sys.exit(1) if not foregroundFlag: try: @@ -770,9 +782,9 @@ def probeContext(transportDomain, transportAddress, contextName): # hook up variation modules for variationModulesDir in confdir.variation: - log.msg('Scanning "%s" directory for variation modules...' % variationModulesDir) + log.info('Scanning "%s" directory for variation modules...' % variationModulesDir) if not os.path.exists(variationModulesDir): - log.msg('Directory "%s" does not exist' % variationModulesDir) + log.info('Directory "%s" does not exist' % variationModulesDir) continue for dFile in os.listdir(variationModulesDir): if dFile[-3:] != '.py': @@ -791,7 +803,7 @@ def probeContext(transportDomain, transportAddress, contextName): for alias, args in _toLoad: if alias in variationModules: - log.msg('WARNING: ignoring duplicate variation module "%s" at "%s"' % (alias, mod)) + log.error('ignoring duplicate variation module "%s" at "%s"' % (alias, mod)) continue ctx = { @@ -807,13 +819,13 @@ def probeContext(transportDomain, transportAddress, contextName): else: execfile(mod, ctx) except Exception: - log.msg('Variation module "%s" execution failure: %s' % (mod, sys.exc_info()[1])) + log.error('Variation module "%s" execution failure: %s' % (mod, sys.exc_info()[1])) sys.exit(-1) else: # moduleContext, agentContexts, recordContexts variationModules[alias] = ctx, {}, {} - log.msg('A total of %s modules found in %s' % (len(variationModules), variationModulesDir)) + log.info('A total of %s modules found in %s' % (len(variationModules), variationModulesDir)) if variationModulesOptions: log.msg('WARNING: unused options for variation modules: %s' % ', '.join(variationModulesOptions.keys())) @@ -822,26 +834,28 @@ def probeContext(transportDomain, transportAddress, contextName): try: os.makedirs(confdir.cache) except OSError: - log.msg('ERROR: failed to create cache directory "%s": %s' % (confdir.cache, sys.exc_info()[1])) + log.error('failed to create cache directory "%s": %s' % (confdir.cache, sys.exc_info()[1])) sys.exit(-1) else: - log.msg('Cache directory "%s" created' % confdir.cache) + log.info('Cache directory "%s" created' % confdir.cache) if variationModules: - log.msg('Initializing variation modules...') + log.info('Initializing variation modules...') for name, modulesContexts in variationModules.items(): body = modulesContexts[0] for x in ('init', 'variate', 'shutdown'): if x not in body: - log.msg('ERROR: missing "%s" handler at variation module "%s"' % (x, name)) + log.error('missing "%s" handler at variation module "%s"' % (x, name)) sys.exit(-1) try: body['init'](options=body['args'], mode='variating') + except Exception: - log.msg('Variation module "%s" from "%s" load FAILED: %s' % (body['alias'], body['path'], - sys.exc_info()[1])) + log.error('Variation module "%s" from "%s" load FAILED: %s' % ( + body['alias'], body['path'], sys.exc_info()[1])) + else: - log.msg('Variation module "%s" from "%s" loaded OK' % (body['alias'], body['path'])) + log.info('Variation module "%s" from "%s" loaded OK' % (body['alias'], body['path'])) # Build pysnmp Managed Objects base from data files information @@ -852,18 +866,19 @@ def configureManagedObjects(dataDirs, dataIndexInstrumController, _dataFiles = {} for dataDir in dataDirs: - log.msg('Scanning "%s" directory for %s data files...' % (dataDir, ','.join([' *%s%s' % (os.path.extsep, x.ext) for x in recordSet.values()]))) + log.info('Scanning "%s" directory for %s data files...' % (dataDir, ','.join([' *%s%s' % (os.path.extsep, x.ext) for x in recordSet.values()]))) if not os.path.exists(dataDir): - log.msg('Directory "%s" does not exist' % dataDir) + log.info('Directory "%s" does not exist' % dataDir) continue log.msg.incIdent() for fullPath, textParser, communityName in getDataFiles(dataDir): if communityName in _dataFiles: - log.msg('WARNING: ignoring duplicate Community/ContextName "%s" for data file %s (%s already loaded)' % (communityName, fullPath, _dataFiles[communityName])) + log.error('ignoring duplicate Community/ContextName "%s" for data file %s ' + '(%s already loaded)' % (communityName, fullPath, _dataFiles[communityName])) continue elif fullPath in _mibInstrums: mibInstrum = _mibInstrums[fullPath] - log.msg('Configuring *shared* %s' % (mibInstrum,)) + log.info('Configuring *shared* %s' % (mibInstrum,)) else: dataFile = DataFile(fullPath, textParser).indexText(forceIndexBuild) mibInstrum = mibInstrumControllerSet[dataFile.layout](dataFile) @@ -871,9 +886,9 @@ def configureManagedObjects(dataDirs, dataIndexInstrumController, _mibInstrums[fullPath] = mibInstrum _dataFiles[communityName] = fullPath - log.msg('Configuring %s' % (mibInstrum,)) + log.info('Configuring %s' % (mibInstrum,)) - log.msg('SNMPv1/2c community name: %s' % (communityName,)) + log.info('SNMPv1/2c community name: %s' % (communityName,)) if v2cArch: contexts[univ.OctetString(communityName)] = mibInstrum @@ -899,13 +914,14 @@ def configureManagedObjects(dataDirs, dataIndexInstrumController, fullPath, communityName, contextName ) - log.msg('SNMPv3 Context Name: %s%s' % (contextName, len(communityName) <= 32 and ' or %s' % communityName or '')) + log.info('SNMPv3 Context Name: %s%s' % (contextName, len(communityName) <= 32 and ' or %s' % communityName or '')) log.msg.decIdent() del _mibInstrums del _dataFiles + if v2cArch: def getBulkHandler(reqVarBinds, nonRepeaters, maxRepetitions, readNextVars): N = min(int(nonRepeaters), len(reqVarBinds)) @@ -936,7 +952,7 @@ def commandResponderCbFun(transportDispatcher, transportDomain, if msgVer in api.protoModules: pMod = api.protoModules[msgVer] else: - log.msg('Unsupported SNMP version %s' % (msgVer,)) + log.error('Unsupported SNMP version %s' % (msgVer,)) return reqMsg, wholeMsg = decoder.decode( wholeMsg, asn1Spec=pMod.Message(), @@ -945,11 +961,16 @@ def commandResponderCbFun(transportDispatcher, transportDomain, communityName = reqMsg.getComponentByPosition(1) for candidate in probeContext(transportDomain, transportAddress, communityName): if candidate in contexts: - log.msg('Using %s selected by candidate %s; transport ID %s, source address %s, community name "%s"' % (contexts[candidate], candidate, univ.ObjectIdentifier(transportDomain), transportAddress[0], communityName)) + log.info('Using %s selected by candidate %s; transport ID %s, source address %s, ' + 'community name "%s"' % ( + contexts[candidate], candidate, univ.ObjectIdentifier(transportDomain), + transportAddress[0], communityName)) communityName = candidate break else: - log.msg('No data file selected for transport ID %s, source address %s, community name "%s"' % (univ.ObjectIdentifier(transportDomain), transportAddress[0], communityName)) + log.error('No data file selected for transport ID %s, source address %s, ' + 'community name "%s"' % ( + univ.ObjectIdentifier(transportDomain), transportAddress[0], communityName)) return wholeMsg rspMsg = pMod.apiMessage.getResponse(reqMsg) @@ -965,7 +986,7 @@ def commandResponderCbFun(transportDispatcher, transportDomain, elif (hasattr(pMod, 'GetBulkRequestPDU') and reqPDU.isSameTypeWith(pMod.GetBulkRequestPDU())): if not msgVer: - log.msg('GETBULK over SNMPv1 from %s:%s' % (transportDomain, transportAddress)) + log.info('GETBULK over SNMPv1 from %s:%s' % (transportDomain, transportAddress)) return wholeMsg def backendFun(varBinds): @@ -975,7 +996,7 @@ def backendFun(varBinds): contexts[communityName].readNextVars ) else: - log.msg('Unsupported PDU type %s from %s:%s' % (reqPDU.__class__.__name__, transportDomain, transportAddress)) + log.error('Unsupported PDU type %s from %s:%s' % (reqPDU.__class__.__name__, transportDomain, transportAddress)) return wholeMsg try: @@ -987,7 +1008,7 @@ def backendFun(varBinds): return wholeMsg except Exception: - log.msg('Ignoring SNMP engine failure: %s' % sys.exc_info()[1]) + log.error('Ignoring SNMP engine failure: %s' % sys.exc_info()[1]) # Poor man's v2c->v1 translation errorMap = { @@ -1033,15 +1054,15 @@ def probeHashContext(self, snmpEngine, stateReference, contextName): except error.PySnmpError: pass else: - log.msg('Using %s selected by candidate %s; transport ID %s, source address %s, context name "%s"' % (mibInstrum, candidate, univ.ObjectIdentifier(transportDomain), transportAddress[0], probedContextName)) + log.info('Using %s selected by candidate %s; transport ID %s, source address %s, context name "%s"' % (mibInstrum, candidate, univ.ObjectIdentifier(transportDomain), transportAddress[0], probedContextName)) contextName = probedContextName break else: mibInstrum = self.snmpContext.getMibInstrum(contextName) - log.msg('Using %s selected by contextName "%s", transport ID %s, source address %s' % (mibInstrum, contextName, univ.ObjectIdentifier(transportDomain), transportAddress[0])) + log.info('Using %s selected by contextName "%s", transport ID %s, source address %s' % (mibInstrum, contextName, univ.ObjectIdentifier(transportDomain), transportAddress[0])) if not isinstance(mibInstrum, (MibInstrumController, DataIndexInstrumController)): - log.msg('Warning: LCD access denied (contextName does not match any data file)') + log.error('LCD access denied (contextName does not match any data file)') raise NoDataNotification() return contextName @@ -1128,10 +1149,10 @@ def handleMgmtOperation(self, snmpEngine, stateReference, contextName, PDU, acIn if (not agentUDPv4Endpoints and not agentUDPv6Endpoints and not agentUnixEndpoints): - log.msg('ERROR: agent endpoint address(es) not specified') + log.error('agent endpoint address(es) not specified') sys.exit(-1) - log.msg('Maximum number of variable bindings in SNMP response: %s' % maxVarBinds) + log.info('Maximum number of variable bindings in SNMP response: %s' % maxVarBinds) # Configure socket server @@ -1142,7 +1163,7 @@ def handleMgmtOperation(self, snmpEngine, stateReference, contextName, PDU, acIn transportDispatcher.registerTransport( transportDomain, agentUDPv4Endpoint[0] ) - log.msg('Listening at UDP/IPv4 endpoint %s, transport ID %s' % (agentUDPv4Endpoint[1], '.'.join([str(x) for x in transportDomain]))) + log.info('Listening at UDP/IPv4 endpoint %s, transport ID %s' % (agentUDPv4Endpoint[1], '.'.join([str(x) for x in transportDomain]))) transportIndex = transportIdOffset for agentUDPv6Endpoint in agentUDPv6Endpoints: @@ -1151,7 +1172,7 @@ def handleMgmtOperation(self, snmpEngine, stateReference, contextName, PDU, acIn transportDispatcher.registerTransport( transportDomain, agentUDPv4Endpoint[0] ) - log.msg('Listening at UDP/IPv6 endpoint %s, transport ID %s' % (agentUDPv4Endpoint[1], '.'.join([str(x) for x in transportDomain]))) + log.info('Listening at UDP/IPv6 endpoint %s, transport ID %s' % (agentUDPv4Endpoint[1], '.'.join([str(x) for x in transportDomain]))) transportIndex = transportIdOffset for agentUnixEndpoint in agentUnixEndpoints: @@ -1160,7 +1181,7 @@ def handleMgmtOperation(self, snmpEngine, stateReference, contextName, PDU, acIn transportDispatcher.registerTransport( transportDomain, agentUnixEndpoint[0] ) - log.msg('Listening at UNIX domain socket endpoint %s, transport ID %s' % (agentUnixEndpoint[1], '.'.join([str(x) for x in transportDomain]))) + log.info('Listening at UNIX domain socket endpoint %s, transport ID %s' % (agentUnixEndpoint[1], '.'.join([str(x) for x in transportDomain]))) transportDispatcher.registerRecvCbFun(commandResponderCbFun) @@ -1168,7 +1189,7 @@ def handleMgmtOperation(self, snmpEngine, stateReference, contextName, PDU, acIn if hasattr(transportDispatcher, 'registerRoutingCbFun'): transportDispatcher.registerRoutingCbFun(lambda td, t, d: td) else: - log.msg('WARNING: upgrade pysnmp to 4.2.5 or later get multi-engine ID feature working!') + log.info('WARNING: upgrade pysnmp to 4.2.5 or later get multi-engine ID feature working!') if v3Args and v3Args[0][0] != '--v3-engine-id': v3Args.insert(0, ('--v3-engine-id', 'auto')) @@ -1199,16 +1220,16 @@ def registerTransportDispatcher(snmpEngine, transportDispatcher, for opt in v3Args: if opt[0] in ('--v3-engine-id', 'end-of-options'): if snmpEngine: - log.msg('--- SNMP Engine configuration') + log.info('--- SNMP Engine configuration') - log.msg('SNMPv3 EngineID: %s' % (hasattr(snmpEngine, 'snmpEngineID') and snmpEngine.snmpEngineID.prettyPrint() or '',)) + log.info('SNMPv3 EngineID: %s' % (hasattr(snmpEngine, 'snmpEngineID') and snmpEngine.snmpEngineID.prettyPrint() or '',)) if not v3ContextEngineIds: v3ContextEngineIds.append((None, [])) log.msg.incIdent() - log.msg('--- Data directories configuration') + log.info('--- Data directories configuration') for v3ContextEngineId, ctxDataDirs in v3ContextEngineIds: snmpContext = context.SnmpContext( @@ -1231,7 +1252,7 @@ def registerTransportDispatcher(snmpEngine, transportDispatcher, config.addV1System(snmpEngine, 'index', 'index', contextName='index') - log.msg('--- SNMPv3 USM configuration') + log.info('--- SNMPv3 USM configuration') if not v3Users: v3Users = ['simulator'] @@ -1245,7 +1266,7 @@ def registerTransportDispatcher(snmpEngine, transportDispatcher, if v3User not in v3AuthProtos: v3AuthProtos[v3User] = 'MD5' elif v3User in v3AuthProtos: - log.msg('ERROR: auth protocol configured without key for user %s' % v3User) + log.error('auth protocol configured without key for user %s' % v3User) sys.exit(-1) else: v3AuthKeys[v3User] = None @@ -1254,13 +1275,13 @@ def registerTransportDispatcher(snmpEngine, transportDispatcher, if v3User not in v3PrivProtos: v3PrivProtos[v3User] = 'DES' elif v3User in v3PrivProtos: - log.msg('ERROR: privacy protocol configured without key for user %s' % v3User) + log.error('privacy protocol configured without key for user %s' % v3User) sys.exit(-1) else: v3PrivKeys[v3User] = None v3PrivProtos[v3User] = 'NONE' if authProtocols[v3AuthProtos[v3User]] == config.usmNoAuthProtocol and privProtocols[v3PrivProtos[v3User]] != config.usmNoPrivProtocol: - log.msg('ERROR: privacy impossible without authentication for USM user %s' % v3User) + log.error('privacy impossible without authentication for USM user %s' % v3User) sys.exit(-1) try: @@ -1273,26 +1294,28 @@ def registerTransportDispatcher(snmpEngine, transportDispatcher, v3PrivKeys[v3User] ) except error.PySnmpError: - log.msg('ERROR: bad USM values for user %s: %s' % (v3User, sys.exc_info()[1])) + log.error('bad USM values for user %s: %s' % (v3User, sys.exc_info()[1])) sys.exit(-1) - log.msg('SNMPv3 USM SecurityName: %s' % v3User) + log.info('SNMPv3 USM SecurityName: %s' % v3User) if authProtocols[v3AuthProtos[v3User]] != config.usmNoAuthProtocol: - log.msg('SNMPv3 USM authentication key: %s, authentication protocol: %s' % (v3AuthKeys[v3User], v3AuthProtos[v3User])) + log.info('SNMPv3 USM authentication key: %s, authentication protocol: %s' % ( + v3AuthKeys[v3User], v3AuthProtos[v3User])) if privProtocols[v3PrivProtos[v3User]] != config.usmNoPrivProtocol: - log.msg('SNMPv3 USM encryption (privacy) key: %s, encryption protocol: %s' % (v3PrivKeys[v3User], v3PrivProtos[v3User])) + log.info('SNMPv3 USM encryption (privacy) key: %s, encryption protocol: %s' % ( + v3PrivKeys[v3User], v3PrivProtos[v3User])) snmpContext.registerContextName('index', dataIndexInstrumController) - log.msg('Maximum number of variable bindings in SNMP response: %s' % localMaxVarBinds) + log.info('Maximum number of variable bindings in SNMP response: %s' % localMaxVarBinds) - log.msg('--- Transport configuration') + log.info('--- Transport configuration') if (not agentUDPv4Endpoints and not agentUDPv6Endpoints and not agentUnixEndpoints): - log.msg('ERROR: agent endpoint address(es) not specified for SNMP engine ID %s' % v3EngineId) + log.error('agent endpoint address(es) not specified for SNMP engine ID %s' % v3EngineId) sys.exit(-1) for agentUDPv4Endpoint in agentUDPv4Endpoints: @@ -1305,7 +1328,8 @@ def registerTransportDispatcher(snmpEngine, transportDispatcher, snmpEngine, transportDomain, agentUDPv4Endpoint[0] ) - log.msg('Listening at UDP/IPv4 endpoint %s, transport ID %s' % (agentUDPv4Endpoint[1], '.'.join([str(x) for x in transportDomain]))) + log.info('Listening at UDP/IPv4 endpoint %s, transport ID %s' % ( + agentUDPv4Endpoint[1], '.'.join([str(x) for x in transportDomain]))) for agentUDPv6Endpoint in agentUDPv6Endpoints: transportDomain = udp6.domainName + (transportIndex['udpv6'],) @@ -1317,7 +1341,8 @@ def registerTransportDispatcher(snmpEngine, transportDispatcher, snmpEngine, transportDomain, agentUDPv6Endpoint[0] ) - log.msg('Listening at UDP/IPv6 endpoint %s, transport ID %s' % (agentUDPv6Endpoint[1], '.'.join([str(x) for x in transportDomain]))) + log.info('Listening at UDP/IPv6 endpoint %s, transport ID %s' % ( + agentUDPv6Endpoint[1], '.'.join([str(x) for x in transportDomain]))) for agentUnixEndpoint in agentUnixEndpoints: transportDomain = unix.domainName + (transportIndex['unix'],) @@ -1329,7 +1354,8 @@ def registerTransportDispatcher(snmpEngine, transportDispatcher, snmpEngine, transportDomain, agentUnixEndpoint[0] ) - log.msg('Listening at UNIX domain socket endpoint %s, transport ID %s' % (agentUnixEndpoint[1], '.'.join([str(x) for x in transportDomain]))) + log.info('Listening at UNIX domain socket endpoint %s, transport ID %s' % ( + agentUnixEndpoint[1], '.'.join([str(x) for x in transportDomain]))) # SNMP applications GetCommandResponder(snmpEngine, snmpContext) @@ -1363,7 +1389,7 @@ def registerTransportDispatcher(snmpEngine, transportDispatcher, else: snmpEngine = engine.SnmpEngine(snmpEngineID=univ.OctetString(hexValue=v3EngineId)) except: - log.msg('ERROR: SNMPv3 Engine initialization failed, EngineID "%s": %s' % (v3EngineId, sys.exc_info()[1])) + log.error('SNMPv3 Engine initialization failed, EngineID "%s": %s' % (v3EngineId, sys.exc_info()[1])) sys.exit(-1) config.addContext(snmpEngine, '') @@ -1381,42 +1407,42 @@ def registerTransportDispatcher(snmpEngine, transportDispatcher, v3Users.append(opt[1]) elif opt[0] == '--v3-auth-key': if not v3Users: - log.msg('ERROR: --v3-user should precede %s' % opt[0]) + log.error('--v3-user should precede %s' % opt[0]) sys.exit(-1) if v3Users[-1] in v3AuthKeys: - log.msg('ERROR: repetitive %s option for user %s' % (opt[0], v3Users[-1])) + log.error('repetitive %s option for user %s' % (opt[0], v3Users[-1])) sys.exit(-1) v3AuthKeys[v3Users[-1]] = opt[1] elif opt[0] == '--v3-auth-proto': if opt[1].upper() not in authProtocols: - log.msg('ERROR: bad v3 auth protocol %s' % opt[1]) + log.error('bad v3 auth protocol %s' % opt[1]) sys.exit(-1) else: if not v3Users: - log.msg('ERROR: --v3-user should precede %s' % opt[0]) + log.error('--v3-user should precede %s' % opt[0]) sys.exit(-1) if v3Users[-1] in v3AuthProtos: - log.msg('ERROR: repetitive %s option for user %s' % (opt[0], v3Users[-1])) + log.error('repetitive %s option for user %s' % (opt[0], v3Users[-1])) sys.exit(-1) v3AuthProtos[v3Users[-1]] = opt[1].upper() elif opt[0] == '--v3-priv-key': if not v3Users: - log.msg('ERROR: --v3-user should precede %s' % opt[0]) + log.error('--v3-user should precede %s' % opt[0]) sys.exit(-1) if v3Users[-1] in v3PrivKeys: - log.msg('ERROR: repetitive %s option for user %s' % (opt[0], v3Users[-1])) + log.error('repetitive %s option for user %s' % (opt[0], v3Users[-1])) sys.exit(-1) v3PrivKeys[v3Users[-1]] = opt[1] elif opt[0] == '--v3-priv-proto': if opt[1].upper() not in privProtocols: - log.msg('ERROR: bad v3 privacy protocol %s' % opt[1]) + log.error('bad v3 privacy protocol %s' % opt[1]) sys.exit(-1) else: if not v3Users: - log.msg('ERROR: --v3-user should precede %s' % opt[0]) + log.error('--v3-user should precede %s' % opt[0]) sys.exit(-1) if v3Users[-1] in v3PrivProtos: - log.msg('ERROR: repetitive %s option for user %s' % (opt[0], v3Users[-1])) + log.error('repetitive %s option for user %s' % (opt[0], v3Users[-1])) sys.exit(-1) v3PrivProtos[v3Users[-1]] = opt[1].upper() elif opt[0] == '--agent-udpv4-endpoint': @@ -1434,28 +1460,35 @@ def registerTransportDispatcher(snmpEngine, transportDispatcher, exc_info = None -try: - transportDispatcher.runDispatcher() -except KeyboardInterrupt: - log.msg('Shutting down process...') -except Exception: - exc_info = sys.exc_info() +with daemon.PrivilegesOf(procUser, procGroup, final=True): -if variationModules: - log.msg('Shutting down variation modules:') - for name, contexts in variationModules.items(): - body = contexts[0] - try: - body['shutdown'](options=body['args'], mode='variation') - except Exception: - log.msg('Variation module "%s" shutdown FAILED: %s' % (name, sys.exc_info()[1])) - else: - log.msg('Variation module "%s" shutdown OK' % name) + try: + transportDispatcher.runDispatcher() + + except KeyboardInterrupt: + log.info('Shutting down process...') + + except Exception: + exc_info = sys.exc_info() + + if variationModules: + log.info('Shutting down variation modules:') + + for name, contexts in variationModules.items(): + body = contexts[0] + try: + body['shutdown'](options=body['args'], mode='variation') + + except Exception: + log.error('Variation module "%s" shutdown FAILED: %s' % (name, sys.exc_info()[1])) + + else: + log.info('Variation module "%s" shutdown OK' % name) -transportDispatcher.closeDispatcher() + transportDispatcher.closeDispatcher() -log.msg('Process terminated') + log.info('Process terminated') -if exc_info: - for line in traceback.format_exception(*exc_info): - log.msg(line.replace('\n', ';')) + if exc_info: + for line in traceback.format_exception(*exc_info): + log.error(line.replace('\n', ';')) diff --git a/snmpsim/daemon.py b/snmpsim/daemon.py index bca6878..8c8c618 100644 --- a/snmpsim/daemon.py +++ b/snmpsim/daemon.py @@ -7,6 +7,7 @@ import sys from snmpsim import error + if sys.platform[:3] == 'win': def daemonize(pidfile): raise error.SnmpsimError('Windows is not inhabited with daemons!') @@ -14,8 +15,14 @@ def daemonize(pidfile): def dropPrivileges(uname, gname): return + else: - import os, pwd, grp, atexit, signal, tempfile + import os + import pwd + import grp + import atexit + import signal + import tempfile def daemonize(pidfile): @@ -53,19 +60,22 @@ def signal_cb(s, f): # write pidfile def atexit_cb(): try: - os.remove(pidfile) + if pidfile: + os.remove(pidfile) except OSError: pass atexit.register(atexit_cb) try: - fd, nm = tempfile.mkstemp(dir=os.path.dirname(pidfile)) - os.write(fd, ('%d\n' % os.getpid()).encode('utf-8')) - os.close(fd) - os.rename(nm, pidfile) - except: - raise error.SnmpsimError('Failed to create PID file %s: %s' % (pidfile, sys.exc_info()[1])) + if pidfile: + fd, nm = tempfile.mkstemp(dir=os.path.dirname(pidfile)) + os.write(fd, ('%d\n' % os.getpid()).encode('utf-8')) + os.close(fd) + os.rename(nm, pidfile) + except Exception: + raise error.SnmpsimError( + 'Failed to create PID file %s: %s' % (pidfile, sys.exc_info()[1])) # redirect standard file descriptors sys.stdout.flush() @@ -79,32 +89,69 @@ def atexit_cb(): os.dup2(se.fileno(), sys.stderr.fileno()) - def dropPrivileges(uname, gname): - if os.getuid() != 0: - if uname and uname != pwd.getpwnam(uname).pw_name or \ - gname and gname != grp.getgrnam(gname).gr_name: - raise error.SnmpsimError('Process is running under different UID/GID') + class PrivilegesOf(object): + + def __init__(self, uname, gname, final=False): + self._uname = uname + self._gname = gname + self._final = final + self._olduid = self._oldgid = None + + def __enter__(self): + if os.getuid() != 0: + if (self._uname and self._uname != pwd.getpwnam(self._uname).pw_name or + self._gname and self._gname != grp.getgrnam(self._gname).gr_name): + raise error.SnmpsimError('Process is running under different UID/GID') + else: + return else: - return - else: - if not uname or not gname: - raise error.SnmpsimError('Must drop priveleges to a non-priveleged user&group') + if not self._uname or not self._gname: + raise error.SnmpsimError('Must drop privileges to a non-privileged user&group') - try: - runningUid = pwd.getpwnam(uname).pw_uid - runningGid = grp.getgrnam(gname).gr_gid - except Exception: - raise error.SnmpsimError('getpwnam()/getgrnam() failed for %s/%s: %s' % (uname, gname, sys.exc_info()[1])) + try: + runningUid = pwd.getpwnam(self._uname).pw_uid + runningGid = grp.getgrnam(self._gname).gr_gid - try: - os.setgroups([]) - except Exception: - raise error.SnmpsimError('setgroups() failed: %s' % sys.exc_info()[1]) + except Exception: + raise error.SnmpsimError( + 'getpwnam()/getgrnam() failed for %s/%s: %s' % ( + self._uname, self._gname, sys.exc_info()[1])) - try: - os.setgid(runningGid) - os.setuid(runningUid) - except Exception: - raise error.SnmpsimError('setgid()/setuid() failed for %s/%s: %s' % (runningGid, runningUid, sys.exc_info()[1])) + try: + os.setgroups([]) + + except Exception: + raise error.SnmpsimError('setgroups() failed: %s' % sys.exc_info()[1]) + + try: + if self._final: + os.setgid(runningGid) + os.setuid(runningUid) + + else: + self._olduid = os.getuid() + self._oldgid = os.getgid() + + os.setegid(runningGid) + os.seteuid(runningUid) + + except Exception: + raise error.SnmpsimError( + '%s failed for %s/%s: %s' % ( + self._final and 'setgid()/setuid()' or 'setegid()/seteuid()', + runningGid, runningUid, sys.exc_info()[1])) + + os.umask(63) # 0077 + + def __exit__(self, *args): + if self._olduid is None or self._oldgid is None: + return + + try: + os.setegid(self._oldgid) + os.seteuid(self._olduid) - os.umask(63) # 0077 + except Exception: + raise error.SnmpsimError( + 'setegid()/seteuid() failed for %s/%s: %s' % ( + self._oldgid, self._olduid, sys.exc_info()[1])) diff --git a/snmpsim/log.py b/snmpsim/log.py index 9eca95e..d869d9b 100644 --- a/snmpsim/log.py +++ b/snmpsim/log.py @@ -4,44 +4,66 @@ # Copyright (c) 2010-2019, Ilya Etingof # License: http://snmplabs.com/snmpsim/license.html # +import os import sys -import time import logging import socket +import stat +import time from logging import handlers -from snmpsim import error +from snmpsim.error import SnmpsimError + +LOG_DEBUG = 0 +LOG_INFO = 1 +LOG_ERROR = 2 -class AbstractLogger: +class AbstractLogger(object): def __init__(self, progId, *priv): self._logger = logging.getLogger(progId) self._logger.setLevel(logging.DEBUG) - self.__ident = 0 + self._progId = progId + self._ident = 0 self.init(*priv) def __call__(self, s): - self._logger.debug(' ' * self.__ident + s) + self._logger.debug(' ' * self._ident + s) def incIdent(self, amount=2): - self.__ident += amount + self._ident += amount def decIdent(self, amount=2): - self.__ident -= amount - if self.__ident < 0: - self.__ident = 0 + self._ident -= amount + if self._ident < 0: + self._ident = 0 def init(self, *priv): pass class SyslogLogger(AbstractLogger): + SYSLOG_SOCKET_PATHS = ( + '/dev/log', + '/var/run/syslog' + ) + def init(self, *priv): if len(priv) < 1: - raise error.SnmpsimError('Bad syslog params, need at least facility, also accept priority, host, port, socktype (tcp|udp)') + raise SnmpsimError( + 'Bad syslog params, need at least facility, also accept ' + 'host, port, socktype (tcp|udp)') if len(priv) < 2: priv = [priv[0], 'debug'] if len(priv) < 3: - priv = [priv[0], priv[1], 'localhost', 514, 'udp'] + # search for syslog local socket + + for dev in self.SYSLOG_SOCKET_PATHS: + if os.path.exists(dev): + priv = [priv[0], priv[1], dev] + break + else: + priv = [priv[0], priv[1], 'localhost', 514, 'udp'] + if not priv[2].startswith('/'): if len(priv) < 4: priv = [priv[0], priv[1], priv[2], 514, 'udp'] @@ -50,20 +72,75 @@ def init(self, *priv): priv = [priv[0], priv[1], priv[2], int(priv[3]), priv[4]] try: - handler = handlers.SysLogHandler(priv[2].startswith('/') and priv[2] or (priv[2], int(priv[3])), - priv[0].lower(), len(priv) > 4 and priv[ - 4] == 'tcp' and socket.SOCK_STREAM or socket.SOCK_DGRAM) + handler = handlers.SysLogHandler( + address=priv[2].startswith('/') and priv[2] or (priv[2], int(priv[3])), + facility=priv[0].lower(), + socktype=len(priv) > 4 and priv[4] == 'tcp' and socket.SOCK_STREAM or socket.SOCK_DGRAM + ) + + except Exception: + raise SnmpsimError('Bad syslog option(s): %s' % sys.exc_info()[1]) - except: - raise error.SnmpsimError('Bad syslog option(s): %s' % sys.exc_info()[1]) handler.setFormatter(logging.Formatter('%(asctime)s %(name)s: %(message)s')) + self._logger.addHandler(handler) class FileLogger(AbstractLogger): + + class TimedRotatingFileHandler(handlers.TimedRotatingFileHandler): + """Store log creation time in a stand-alone file''s mtime""" + + def __init__(self, *args, **kwargs): + handlers.TimedRotatingFileHandler.__init__(self, *args, **kwargs) + + self.__failure = False + + try: + timestamp = os.stat(self.__filename)[stat.ST_MTIME] + + except IOError: + return + + # Use a stand-aside file metadata time instead of the last + # modification of the log file itself, as the stock + # implementation does. + # This is to work-around the increasing rotation intervals + # on process restart. + self.rolloverAt = self.computeRollover(timestamp) + + @property + def __filename(self): + return os.path.join( + os.path.dirname(self.baseFilename), + '.' + os.path.basename(self.baseFilename) + '-timestamp' + ) + + def doRollover(self): + try: + handlers.TimedRotatingFileHandler.doRollover(self) + + # note log file creation time + if os.path.exists(self.__filename): + os.unlink(self.__filename) + + open(self.__filename, 'w').close() + + self.__failure = False + + except IOError: + # File rotation seems to fail, postpone the next run + timestamp = time.time() + self.rolloverAt = self.computeRollover(timestamp) + + if not self.__failure: + self.__failure = True + error('Failed to rotate log/timestamp file ' + '%s: %s' % (self.__filename, sys.exc_info()[1])) + def init(self, *priv): if not priv: - raise error.SnmpsimError('Bad log file params, need filename') + raise SnmpsimError('Bad log file params, need filename') if sys.platform[:3] == 'win': # fix possibly corrupted absolute windows path if len(priv[0]) == 1 and priv[0].isalpha() and len(priv) > 1: @@ -72,40 +149,53 @@ def init(self, *priv): maxsize = 0 maxage = None if len(priv) > 1 and priv[1]: - localtime = time.localtime() - if priv[1][-1] in ('k', 'K'): - maxsize = int(priv[1][:-1]) * 1024 - elif priv[1][-1] in ('m', 'M'): - maxsize = int(priv[1][:-1]) * 1024 * 1024 - elif priv[1][-1] in ('g', 'G'): - maxsize = int(priv[1][:-1]) * 1024 * 1024 * 1024 - elif priv[1][-1] in ('h', 'H'): - maxage = ('H', int(priv[1][:-1])) - elif priv[1][-1] in ('d', 'D'): - maxage = ('D', int(priv[1][:-1])) - else: - raise error.SnmpsimError( - 'Unknown log rotation criteria %s, use K,M,G for size or H,D for time limits' % priv[1] + try: + if priv[1][-1] == 'k': + maxsize = int(priv[1][:-1]) * 1024 + elif priv[1][-1] == 'm': + maxsize = int(priv[1][:-1]) * 1024 * 1024 + elif priv[1][-1] == 'g': + maxsize = int(priv[1][:-1]) * 1024 * 1024 * 1024 + elif priv[1][-1] == 'S': + maxage = ('S', int(priv[1][:-1])) + elif priv[1][-1] == 'M': + maxage = ('M', int(priv[1][:-1])) + elif priv[1][-1] == 'H': + maxage = ('H', int(priv[1][:-1])) + elif priv[1][-1] == 'D': + maxage = ('D', int(priv[1][:-1])) + else: + raise ValueError('Unknown log rotation criterion: %s' % priv[1][-1]) + + except ValueError: + raise SnmpsimError( + 'Error in timed log rotation specification. Use k,m,g ' + 'for size or S,M,H,D for time limits' ) try: if maxsize: handler = handlers.RotatingFileHandler(priv[0], backupCount=30, maxBytes=maxsize) elif maxage: - handler = handlers.TimedRotatingFileHandler(priv[0], backupCount=30, when=maxage[0], interval=maxage[1]) + handler = self.TimedRotatingFileHandler(priv[0], backupCount=30, when=maxage[0], interval=maxage[1]) else: handler = handlers.WatchedFileHandler(priv[0]) - except AttributeError: - raise error.SnmpsimError( - 'Bad log rotation criteria: %s' % sys.exc_info()[1] + except Exception: + raise SnmpsimError( + 'Failure configure logging: %s' % sys.exc_info()[1] ) - handler.setFormatter(logging.Formatter('%(asctime)s %(name)s: %(message)s')) + handler.setFormatter(logging.Formatter('%(message)s')) + self._logger.addHandler(handler) - self('Log file %s, rotation rules: %s' % ( - priv[0], maxsize and '> %sKB' % (maxsize / 1024) or maxage and '%s%s' % (maxage[1], maxage[0]) or '')) + self('Log file %s, rotation rules: %s' % (priv[0], maxsize and '> %sKB' % (maxsize/1024) or maxage and '%s%s' % (maxage[1], maxage[0]) or '')) + + def __call__(self, s): + now = time.time() + timestamp = time.strftime('%Y-%m-%dT%H:%M:%S', time.localtime(now)) + AbstractLogger.__call__(self, '%s.%02d %s: %s' % (timestamp, now % 1 * 100, self._progId, s)) class StreamLogger(AbstractLogger): @@ -116,11 +206,12 @@ def init(self, *priv): handler = logging.StreamHandler(self.stream) except AttributeError: - raise error.SnmpsimError( + raise SnmpsimError( 'Stream logger failure: %s' % sys.exc_info()[1] ) handler.setFormatter(logging.Formatter('%(message)s')) + self._logger.addHandler(handler) @@ -141,7 +232,7 @@ def __call__(self, s): pass -gMap = { +METHODS_MAP = { 'syslog': SyslogLogger, 'file': FileLogger, 'stdout': StdoutLogger, @@ -149,14 +240,48 @@ def __call__(self, s): 'null': NullLogger } +LEVELS_MAP = { + 'debug': LOG_DEBUG, + 'info': LOG_INFO, + 'error': LOG_ERROR, +} + msg = lambda x: None +logLevel = LOG_INFO + + +def error(message, ctx=''): + if logLevel <= LOG_ERROR: + msg('ERROR %s %s' % (message, ctx)) + + +def info(message, ctx=''): + if logLevel <= LOG_INFO: + msg('%s %s' % (message, ctx)) + + +def debug(message, ctx=''): + if logLevel <= LOG_DEBUG: + msg('DEBUG %s %s' % (message, ctx)) + + +def setLevel(level): + global logLevel + + try: + logLevel = LEVELS_MAP[level] + + except KeyError: + raise SnmpsimError('Unknown log level "%s", known levels are: %s' % (level, ', '.join(LEVELS_MAP))) + def setLogger(progId, *priv, **options): global msg - if priv[0] in gMap: + + try: if not isinstance(msg, AbstractLogger) or options.get('force'): - msg = gMap[priv[0]](progId, *priv[1:]) - else: - raise error.SnmpsimError( - 'Unknown logging method "%s", known methods are: %s' % (priv[0], ', '.join(gMap.keys()))) + msg = METHODS_MAP[priv[0]](progId, *priv[1:]) + + except KeyError: + raise SnmpsimError('Unknown logging method "%s", known methods are: %s' % (priv[0], ', '.join(METHODS_MAP)))