Change Logging Status

Moved most info items into debug to make it less chatty
This commit is contained in:
Cort Buffington 2013-07-20 15:41:21 -05:00
parent 8c4ad5628a
commit 9eddcf762b
2 changed files with 63 additions and 55 deletions

116
ipsc.py
View File

@ -74,46 +74,46 @@ def print_mode_decode(_mode):
ts2 = _mode & IPSC_TS2_MSK ts2 = _mode & IPSC_TS2_MSK
if link_op == 0b01000000: if link_op == 0b01000000:
logger.info('\t\tPeer Operational') logger.debug('\t\tPeer Operational')
elif link_op == 0b00000000: elif link_op == 0b00000000:
logger.info('\t\tPeer Not Operational') logger.debug('\t\tPeer Not Operational')
else: else:
logger.warning('\t\tPeer Mode Invalid') logger.info('\t\tPeer Mode Invalid')
if link_mode == 0b00000000: if link_mode == 0b00000000:
logger.info('\t\tNo RF Interface') logger.debug('\t\tNo RF Interface')
elif link_mode == 0b00010000: elif link_mode == 0b00010000:
logger.info('\t\tRadio in Analog Mode') logger.debug('\t\tRadio in Analog Mode')
elif link_mode == 0b00100000: elif link_mode == 0b00100000:
logger.info('\t\tRadio in Digital Mode') logger.debug('\t\tRadio in Digital Mode')
else: else:
logger.warning('\t\tRadio Mode Invalid') logger.info('\t\tRadio Mode Invalid')
if ts1 == 0b00001000: if ts1 == 0b00001000:
logger.info('\t\tIPSC Enabled on TS1') logger.debug('\t\tIPSC Enabled on TS1')
if ts2 == 0b00000010: if ts2 == 0b00000010:
logger.info('\t\tIPSC Enabled on TS2') logger.debug('\t\tIPSC Enabled on TS2')
# Gratuituous print-out of the peer list.. Pretty much debug stuff. # Gratuituous print-out of the peer list.. Pretty much debug stuff.
# #
def print_peer_list(_network_name): def print_peer_list(_network_name):
logger.info('\t%s', _network_name) logger.debug('\t%s', _network_name)
for dictionary in NETWORK[_network_name]['PEERS']: for dictionary in NETWORK[_network_name]['PEERS']:
logger.info('\tIP Address: %s:%s', dictionary['IP'], dictionary['PORT']) logger.debug('\tIP Address: %s:%s', dictionary['IP'], dictionary['PORT'])
logger.info('\tRADIO ID: %s ', int(binascii.b2a_hex(dictionary['RADIO_ID']), 16)) logger.debug('\tRADIO ID: %s ', int(binascii.b2a_hex(dictionary['RADIO_ID']), 16))
logger.info("\tIPSC Mode:") logger.debug('\tIPSC Mode:')
print_mode_decode(dictionary['RAW_MODE']) print_mode_decode(dictionary['RAW_MODE'])
logger.info('\tConnection Status: %s', dictionary['STATUS']['CONNECTED']) logger.debug('\tConnection Status: %s', dictionary['STATUS']['CONNECTED'])
logger.info('\tKeepAlives Missed: %s', dictionary['STATUS']['KEEP_ALIVES_MISSED']) logger.debug('\tKeepAlives Missed: %s', dictionary['STATUS']['KEEP_ALIVES_MISSED'])
logger.info("") logger.debug('')
#************************************************ #************************************************
#******** *********** #******** ***********
#******** IPSC Network "Engine" *********** #******** IPSC Network 'Engine' ***********
#******** *********** #******** ***********
#************************************************ #************************************************
@ -128,9 +128,14 @@ class IPSC(DatagramProtocol):
# #
def __init__(self, *args, **kwargs): def __init__(self, *args, **kwargs):
if len(args) == 1: if len(args) == 1:
# Housekeeping: create references to the configuration and status data for this IPSC instance.
#
self._network_name = args[0] self._network_name = args[0]
self._config = NETWORK[self._network_name] self._config = NETWORK[self._network_name]
args = () args = ()
# Packet 'constructors' - builds the necessary control packets for this IPSC instance
#
self.TS_FLAGS = (self._config['LOCAL']['MODE'] + self._config['LOCAL']['FLAGS']) self.TS_FLAGS = (self._config['LOCAL']['MODE'] + self._config['LOCAL']['FLAGS'])
self.MASTER_REG_REQ_PKT = (MASTER_REG_REQ + self._config['LOCAL']['RADIO_ID'] + self.TS_FLAGS + IPSC_VER) self.MASTER_REG_REQ_PKT = (MASTER_REG_REQ + self._config['LOCAL']['RADIO_ID'] + self.TS_FLAGS + IPSC_VER)
self.MASTER_ALIVE_PKT = (MASTER_ALIVE_REQ + self._config['LOCAL']['RADIO_ID'] + self.TS_FLAGS + IPSC_VER) self.MASTER_ALIVE_PKT = (MASTER_ALIVE_REQ + self._config['LOCAL']['RADIO_ID'] + self.TS_FLAGS + IPSC_VER)
@ -141,14 +146,18 @@ class IPSC(DatagramProtocol):
self.PEER_ALIVE_REPLY_PKT = (PEER_ALIVE_REPLY + self._config['LOCAL']['RADIO_ID'] + self.TS_FLAGS) self.PEER_ALIVE_REPLY_PKT = (PEER_ALIVE_REPLY + self._config['LOCAL']['RADIO_ID'] + self.TS_FLAGS)
self._peer_list_new = False self._peer_list_new = False
else: else:
logger.error("Unexpected arguments found.") # If we didn't get called correctly, log it!
#
logger.error('Unexpected arguments found.')
# This is called by REACTOR when it starts, We use it to set up the timed # This is called by REACTOR when it starts, We use it to set up the timed
# loop for each instance of the IPSC engine # loop for each instance of the IPSC engine
# #
def startProtocol(self): def startProtocol(self):
#logger.debug("*** config: %s", self._config) # Timed loop for IPSC connection establishment and maintenance
#logger.info("") # Others could be added later for things like updating a Web
# page, etc....
#
self._call = task.LoopingCall(self.timed_loop) self._call = task.LoopingCall(self.timed_loop)
self._loop = self._call.start(self._config['LOCAL']['ALIVE_TIMER']) self._loop = self._call.start(self._config['LOCAL']['ALIVE_TIMER'])
@ -166,10 +175,10 @@ class IPSC(DatagramProtocol):
def peer_list_received(self, _data, (_host, _port)): def peer_list_received(self, _data, (_host, _port)):
self._config['MASTER']['STATUS']['PEER-LIST'] = True self._config['MASTER']['STATUS']['PEER-LIST'] = True
self._peer_list_new = True self._peer_list_new = True
logger.info("<<- The Peer List has been Received from Master:%s:%s ", _host, _port) logger.info('<<- The Peer List has been Received from Master:%s:%s ', _host, _port)
_num_peers = int(str(int(binascii.b2a_hex(_data[5:7]), 16))[1:]) _num_peers = int(str(int(binascii.b2a_hex(_data[5:7]), 16))[1:])
self._config['LOCAL']['NUM_PEERS'] = _num_peers self._config['LOCAL']['NUM_PEERS'] = _num_peers
logger.info(' There are %s peers in this IPSC Network', _num_peers) logger.debug(' There are %s peers in this IPSC Network', _num_peers)
del self._config['PEERS'][:] del self._config['PEERS'][:]
for i in range(7, (_num_peers*11)+7, 11): for i in range(7, (_num_peers*11)+7, 11):
hex_address = (_data[i+4:i+8]) hex_address = (_data[i+4:i+8])
@ -189,7 +198,7 @@ class IPSC(DatagramProtocol):
#************************************************ #************************************************
def timed_loop(self): def timed_loop(self):
print('timed loop started') # temporary debugging to make sure this part runs logger.debug('timed loop started') # temporary debugging to make sure this part runs
_master_connected = self._config['MASTER']['STATUS']['CONNECTED'] _master_connected = self._config['MASTER']['STATUS']['CONNECTED']
_master_alives_missed = self._config['MASTER']['STATUS']['KEEP_ALIVES_MISSED'] _master_alives_missed = self._config['MASTER']['STATUS']['KEEP_ALIVES_MISSED']
_peer_list_rx = self._config['MASTER']['STATUS']['PEER-LIST'] _peer_list_rx = self._config['MASTER']['STATUS']['PEER-LIST']
@ -197,12 +206,12 @@ class IPSC(DatagramProtocol):
if (_master_connected == False): if (_master_connected == False):
reg_packet = hashed_packet(self._config['LOCAL']['AUTH_KEY'], self.MASTER_REG_REQ_PKT) reg_packet = hashed_packet(self._config['LOCAL']['AUTH_KEY'], self.MASTER_REG_REQ_PKT)
self.transport.write(reg_packet, (self._config['MASTER']['IP'], self._config['MASTER']['PORT'])) self.transport.write(reg_packet, (self._config['MASTER']['IP'], self._config['MASTER']['PORT']))
logger.info("->> Master Registration Request To:%s:%s From:%s", self._config['MASTER']['IP'], self._config['MASTER']['PORT'], binascii.b2a_hex(self._config['LOCAL']['RADIO_ID'])) logger.info('->> Master Registration Request To:%s:%s From:%s', self._config['MASTER']['IP'], self._config['MASTER']['PORT'], binascii.b2a_hex(self._config['LOCAL']['RADIO_ID']))
elif (_master_connected == True): elif (_master_connected == True):
master_alive_packet = hashed_packet(self._config['LOCAL']['AUTH_KEY'], self.MASTER_ALIVE_PKT) master_alive_packet = hashed_packet(self._config['LOCAL']['AUTH_KEY'], self.MASTER_ALIVE_PKT)
self.transport.write(master_alive_packet, (self._config['MASTER']['IP'], self._config['MASTER']['PORT'])) self.transport.write(master_alive_packet, (self._config['MASTER']['IP'], self._config['MASTER']['PORT']))
logger.info("->> Master Keep-alive Sent To:%s:%s", self._config['MASTER']['IP'], self._config['MASTER']['PORT']) logger.debug('->> Master Keep-alive Sent To:%s:%s', self._config['MASTER']['IP'], self._config['MASTER']['PORT'])
self._config['MASTER']['STATUS']['KEEP_ALIVES_SENT'] += 1 self._config['MASTER']['STATUS']['KEEP_ALIVES_SENT'] += 1
if (self._config['MASTER']['STATUS']['KEEP_ALIVES_OUTSTANDING']) > 0: if (self._config['MASTER']['STATUS']['KEEP_ALIVES_OUTSTANDING']) > 0:
@ -214,19 +223,19 @@ class IPSC(DatagramProtocol):
logger.error('Maximum Master Keep-Alives Missed -- De-registering the Master') logger.error('Maximum Master Keep-Alives Missed -- De-registering the Master')
else: else:
logger.error("->> Master in UNKOWN STATE:%s:%s", self._config['MASTER']['IP'], self._config['MASTER']['PORT']) logger.error('->> Master in UNKOWN STATE:%s:%s', self._config['MASTER']['IP'], self._config['MASTER']['PORT'])
if ((_master_connected == True) and (_peer_list_rx == False)): if ((_master_connected == True) and (_peer_list_rx == False)):
peer_list_req_packet = hashed_packet(self._config['LOCAL']['AUTH_KEY'], self.PEER_LIST_REQ_PKT) peer_list_req_packet = hashed_packet(self._config['LOCAL']['AUTH_KEY'], self.PEER_LIST_REQ_PKT)
self.transport.write(peer_list_req_packet, (self._config['MASTER']['IP'], self._config['MASTER']['PORT'])) self.transport.write(peer_list_req_packet, (self._config['MASTER']['IP'], self._config['MASTER']['PORT']))
logger.info("->> List Reqested from Master:%s:%s", self._config['MASTER']['IP'], self._config['MASTER']['PORT']) logger.info('->> List Reqested from Master:%s:%s', self._config['MASTER']['IP'], self._config['MASTER']['PORT'])
# Logic problems in the next if.... bad ones. Fix them. # Logic problems in the next if.... bad ones. Fix them.
if (self._peer_list_new == True): if (self._peer_list_new == True):
self._peer_list_new = False self._peer_list_new = False
logger.info('*** NEW PEER LIST RECEIEVED - PROCESSING!') logger.info('*** NEW PEER LIST RECEIEVED - PROCESSING!')
for peer in (self._config['PEERS']): for peer in (self._config['PEERS']):
if (peer['RADIO_ID'] == binascii.b2a_hex(self._config['LOCAL']['RADIO_ID'])): if (peer['RADIO_ID'] == self._config['LOCAL']['RADIO_ID']): # We are in the peer-list, but don't need to talk to ourselves
continue continue
if peer['STATUS']['CONNECTED'] == 0: if peer['STATUS']['CONNECTED'] == 0:
peer_reg_packet = hashed_packet(self._config['LOCAL']['AUTH_KEY'], self.PEER_REG_REQ_PKT) peer_reg_packet = hashed_packet(self._config['LOCAL']['AUTH_KEY'], self.PEER_REG_REQ_PKT)
@ -234,10 +243,10 @@ class IPSC(DatagramProtocol):
logger.info('->> Peer Registration Request To:%s:%s From:%s', peer['IP'], peer['PORT'], binascii.b2a_hex(self._config['LOCAL']['RADIO_ID'])) logger.info('->> Peer Registration Request To:%s:%s From:%s', peer['IP'], peer['PORT'], binascii.b2a_hex(self._config['LOCAL']['RADIO_ID']))
elif peer['STATUS']['CONNECTED'] == 1: elif peer['STATUS']['CONNECTED'] == 1:
peer_alive_req_packet = hashed_packet(self._config['LOCAL']['AUTH_KEY'], self.PEER_ALIVE_REQ_PKT) peer_alive_req_packet = hashed_packet(self._config['LOCAL']['AUTH_KEY'], self.PEER_ALIVE_REQ_PKT)
self.transport.write(peer_reg_packet, (peer['IP'], peer['PORT'])) self.transport.write(peer_alive_req_packet, (peer['IP'], peer['PORT']))
logger.info('->> Peer Keep-Alive Request To:%s:%s From:%s', peer['IP'], peer['PORT'], binascii.b2a_hex(self._config['LOCAL']['RADIO_ID'])) logger.info('->> Peer Keep-Alive Request To:%s:%s From:%s', peer['IP'], peer['PORT'], binascii.b2a_hex(self._config['LOCAL']['RADIO_ID']))
print('timed loop finished') # temporary debugging to make sure this part runs logger.debug('timed loop finished') # temporary debugging to make sure this part runs
@ -249,78 +258,77 @@ class IPSC(DatagramProtocol):
# call a function or process immediately if only a few actions # call a function or process immediately if only a few actions
# #
def datagramReceived(self, data, (host, port)): def datagramReceived(self, data, (host, port)):
print('datagram received') # temporary debugging to make sure this part runs logger.debug('datagram received') # temporary debugging to make sure this part runs
dest_ip = self._config['MASTER']['IP'] dest_ip = self._config['MASTER']['IP']
dest_port = self._config['MASTER']['PORT'] dest_port = self._config['MASTER']['PORT']
#logger.info("received %r from %s:%d", binascii.b2a_hex(data), host, port) #logger.debug('received %r from %s:%d', binascii.b2a_hex(data), host, port)
_packettype = data[0:1] _packettype = data[0:1]
_peerid = data[1:5] _peerid = data[1:5]
if (_packettype == PEER_ALIVE_REQ): if (_packettype == PEER_ALIVE_REQ):
logger.info("<<- Peer Keep-alive Request From Peer ID %s at:%s:%s", int(binascii.b2a_hex(_peerid), 16), host, port) logger.debug('<<- Peer Keep-alive Request From Peer ID %s at:%s:%s', int(binascii.b2a_hex(_peerid), 16), host, port)
peer_alive_reply_packet = hashed_packet(self._config['LOCAL']['AUTH_KEY'], self.PEER_ALIVE_REPLY_PKT) peer_alive_reply_packet = hashed_packet(self._config['LOCAL']['AUTH_KEY'], self.PEER_ALIVE_REPLY_PKT)
self.transport.write(peer_alive_reply_packet, (host, port)) self.transport.write(peer_alive_reply_packet, (host, port))
logger.info("->> Peer Keep-alive Reply sent To:%s:%s", host, port) logger.info('->> Peer Keep-alive Reply sent To:%s:%s', host, port)
elif (_packettype == MASTER_ALIVE_REPLY): elif (_packettype == MASTER_ALIVE_REPLY):
logger.info("<<- Master Keep-alive Reply From:%s:%s", host, port) logger.info('<<- Master Keep-alive Reply From:%s:%s', host, port)
elif (_packettype == PEER_ALIVE_REPLY): elif (_packettype == PEER_ALIVE_REPLY):
self.config['MASTER']['STATUS']['KEEP_ALIVES_OUTSTANDING'] = 0 logger.debug('<<- Peer Keep-alive Reply From:%s:%s', host, port)
logger.info("<<- Peer Keep-alive Reply From:%s:%s", host, port)
elif (_packettype == MASTER_REG_REQ): elif (_packettype == MASTER_REG_REQ):
logger.info("<<- Registration Packet Recieved") logger.debug('<<- Registration Packet Recieved')
elif (_packettype == MASTER_REG_REPLY): elif (_packettype == MASTER_REG_REPLY):
self._config['MASTER']['STATUS']['CONNECTED'] = True self._config['MASTER']['STATUS']['CONNECTED'] = True
self._config['MASTER']['STATUS']['KEEP_ALIVES_OUTSTANDING'] = 0 self._config['MASTER']['STATUS']['KEEP_ALIVES_OUTSTANDING'] = 0
logger.info("<<- Master Registration Reply From:%s:%s ", host, port) logger.info('<<- Master Registration Reply From:%s:%s ', host, port)
elif (_packettype == PEER_REG_REQ): elif (_packettype == PEER_REG_REQ):
logger.info("<<- Peer Registration Request From Peer ID %s at:%s:%s", int(binascii.b2a_hex(_peerid), 16), host, port) logger.debug('<<- Peer Registration Request From Peer ID %s at:%s:%s', int(binascii.b2a_hex(_peerid), 16), host, port)
peer_reg_reply_packet = hashed_packet(self._config['LOCAL']['AUTH_KEY'], self.PEER_REG_REPLY_PKT) peer_reg_reply_packet = hashed_packet(self._config['LOCAL']['AUTH_KEY'], self.PEER_REG_REPLY_PKT)
self.transport.write(peer_reg_reply_packet, (host, port)) self.transport.write(peer_reg_reply_packet, (host, port))
logger.warning("->> Peer Registration Reply Sent To:%s:%s", host, port) logger.info('->> Peer Registration Reply Sent To:%s:%s', host, port)
elif (_packettype == PEER_REG_REPLY): elif (_packettype == PEER_REG_REPLY):
logger.warning('<<- Peer Registration Reply From: %s', int(binascii.b2a_hex(_peerid), 16)) logger.info('<<- Peer Registration Reply From: %s @ IP: %s', int(binascii.b2a_hex(_peerid), 16), host)
elif (_packettype == XCMP_XNL): elif (_packettype == XCMP_XNL):
logger.info("<<- XCMP_XNL From:%s:%s, but we did not indicate XCMP capable!", host, port) logger.debug('<<- XCMP_XNL From:%s:%s, but we did not indicate XCMP capable!', host, port)
elif (_packettype == PEER_LIST_REPLY): elif (_packettype == PEER_LIST_REPLY):
self.peer_list_received(data, (host, port)) self.peer_list_received(data, (host, port))
elif (_packettype == GROUP_VOICE): elif (_packettype == GROUP_VOICE):
logger.info("<<- Group Voice Packet From:%s:%s", host, port) logger.debug('<<- Group Voice Packet From:%s:%s', host, port)
elif (_packettype == PVT_VOICE): elif (_packettype == PVT_VOICE):
logger.info("<<- Voice Packet From:%s:%s", host, port) logger.debug('<<- Voice Packet From:%s:%s', host, port)
elif (_packettype == GROUP_DATA): elif (_packettype == GROUP_DATA):
logger.info("<<- Group Data Packet From:%s:%s", host, port) logger.debug('<<- Group Data Packet From:%s:%s', host, port)
elif (_packettype == PVT_DATA): elif (_packettype == PVT_DATA):
logger.info("<<- Private Data Packet From From:%s:%s", host, port) logger.debug('<<- Private Data Packet From From:%s:%s', host, port)
elif (_packettype == RPT_WAKE_UP): elif (_packettype == RPT_WAKE_UP):
logger.warning("<<- Repeater Wake-Up Packet From:%s:%s", host, port) logger.info('<<- Repeater Wake-Up Packet From:%s:%s', host, port)
elif (_packettype == DE_REG_REQ): elif (_packettype == DE_REG_REQ):
logger.warning("<<- Peer De-Registration Request From:%s:%s", host, port) logger.info('<<- Peer De-Registration Request From:%s:%s', host, port)
elif (_packettype == DE_REG_REPLY): elif (_packettype == DE_REG_REPLY):
logger.info("<<- Peer De-Registration Reply From:%s:%s", host, port) logger.debug('<<- Peer De-Registration Reply From:%s:%s', host, port)
elif (_packettype in (CALL_CTL_1, CALL_CTL_2, CALL_CTL_3)): elif (_packettype in (CALL_CTL_1, CALL_CTL_2, CALL_CTL_3)):
logger.info("<<- Call Control Packet From:%s:%s", host, port) logger.debug('<<- Call Control Packet From:%s:%s', host, port)
else: else:
packet_type = binascii.b2a_hex(_packettype) packet_type = binascii.b2a_hex(_packettype)
logger.error("<<- Received Unprocessed Type %s From:%s:%s", packet_type, host, port) logger.error('<<- Received Unprocessed Type %s From:%s:%s', packet_type, host, port)
@ -329,7 +337,7 @@ class IPSC(DatagramProtocol):
#************************************************ #************************************************
if __name__ == '__main__': if __name__ == '__main__':
logger.info('SYSTEM STARTING UP') logger.debug('SYSTEM STARTING UP')
for ipsc_network in NETWORK: for ipsc_network in NETWORK:
reactor.listenUDP(NETWORK[ipsc_network]['LOCAL']['PORT'], IPSC(ipsc_network)) reactor.listenUDP(NETWORK[ipsc_network]['LOCAL']['PORT'], IPSC(ipsc_network))
reactor.run() reactor.run()

View File

@ -47,7 +47,7 @@ dictConfig({
'ipsc': { 'ipsc': {
# 'handlers': ['file-timed', 'console-timed'], # 'handlers': ['file-timed', 'console-timed'],
'handlers': ['file-timed', 'console-timed'], 'handlers': ['file-timed', 'console-timed'],
'level': 'DEBUG', 'level': 'INFO',
'propagate': True, 'propagate': True,
} }
} }