xenofem/python-zulip-api
1
0
Fork 0
Code Issues Pull requests Packages Projects Releases Wiki Activity

zephyr_mirror: Use python logging module.

Browse source 
(imported from commit 3cd9506d46eb56fbd5a48c789160a45846332633)
This commit is contained in:
Tim Abbott 2012-11-09 17:23:42 -05:00
parent 18cefd37a8
commit defaeb935e
1 changed files with 49 additions and 43 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

92
bots/zephyr_mirror.py
View file

@ -11,6 +11,7 @@ import os
import datetime import datetime
import textwrap import textwrap
import signal import signal
import logging
def to_humbug_username(zephyr_username): def to_humbug_username(zephyr_username):
if "@" in zephyr_username: if "@" in zephyr_username:
@ -100,7 +101,7 @@ def send_humbug(zeph):
message['content'] = unwrap_lines(zeph['content']) message['content'] = unwrap_lines(zeph['content'])
if options.test_mode: if options.test_mode:
print message logger.debug("Message is: %s" % (str(message),))
return {'result': "success"} return {'result': "success"}
return humbug_client.send_message(message) return humbug_client.send_message(message)
@ -116,9 +117,7 @@ def fetch_fullname(username):
if proc.returncode == 0: if proc.returncode == 0:
return out.split(':')[4].split(',')[0] return out.split(':')[4].split(',')[0]
except: except:
print >>sys.stderr, '%s: zephyr=>humbug: Error getting fullname for %s' % \ logger.exception("Error getting fullname for %s:" % (username,))
(datetime.datetime.now(), username)
traceback.print_exc()
if "@" not in username: if "@" not in username:
return username return username
@ -143,8 +142,7 @@ def zephyr_bulk_subscribe(subs):
# continue processing normal messages) and we'll end up # continue processing normal messages) and we'll end up
# retrying the next time the bot checks its subscriptions are # retrying the next time the bot checks its subscriptions are
# up to date. # up to date.
traceback.print_exc() logger.exception("Error subscribing to streams (will retry automatically):")
print "Error subscribing to streams; will retry later."
return return
for (cls, instance, recipient) in subs: for (cls, instance, recipient) in subs:
current_zephyr_subs.add(cls) current_zephyr_subs.add(cls)
@ -154,8 +152,7 @@ def update_subscriptions_from_humbug():
res = humbug_client.get_public_streams() res = humbug_client.get_public_streams()
streams = res["streams"] streams = res["streams"]
except: except:
print "%s: Error getting public streams:" % (datetime.datetime.now(),) logger.exception("Error getting public streams:")
traceback.print_exc()
return return
streams_to_subscribe = [] streams_to_subscribe = []
for stream in streams: for stream in streams:
@ -168,9 +165,8 @@ def maybe_restart_mirroring_script():
if os.stat(os.path.join(options.root_path, "stamps", "restart_stamp")).st_mtime > start_time or \ if os.stat(os.path.join(options.root_path, "stamps", "restart_stamp")).st_mtime > start_time or \
((options.user == "tabbott" or options.user == "tabbott/extra") and ((options.user == "tabbott" or options.user == "tabbott/extra") and
os.stat(os.path.join(options.root_path, "stamps", "tabbott_stamp")).st_mtime > start_time): os.stat(os.path.join(options.root_path, "stamps", "tabbott_stamp")).st_mtime > start_time):
print logger.warning("")
print "%s: zephyr mirroring script has been updated; restarting..." % \ logger.warning("zephyr mirroring script has been updated; restarting...")
(datetime.datetime.now(),)
os.kill(child_pid, signal.SIGTERM) os.kill(child_pid, signal.SIGTERM)
while True: while True:
try: try:
@ -178,8 +174,7 @@ def maybe_restart_mirroring_script():
os.execvp(os.path.join(options.root_path, "extra_mirror.py"), sys.argv) os.execvp(os.path.join(options.root_path, "extra_mirror.py"), sys.argv)
os.execvp(os.path.join(options.root_path, "user_root", "zephyr_mirror.py"), sys.argv) os.execvp(os.path.join(options.root_path, "user_root", "zephyr_mirror.py"), sys.argv)
except: except:
print "Error restarting, trying again." logger.exception("Error restarting mirroring script; trying again... Traceback:")
traceback.print_exc()
time.sleep(1) time.sleep(1)
def process_loop(log): def process_loop(log):
@ -191,9 +186,7 @@ def process_loop(log):
try: try:
process_notice(notice, log) process_notice(notice, log)
except: except:
print >>sys.stderr, '%s: zephyr=>humbug: Error relaying zephyr' % \ logger.exception("Error relaying zephyr:")
(datetime.datetime.now(),)
traceback.print_exc()
time.sleep(2) time.sleep(2)
maybe_restart_mirroring_script() maybe_restart_mirroring_script()
@ -223,8 +216,7 @@ def process_notice(notice, log):
return return
if zsig.endswith("@(@color(blue))"): if zsig.endswith("@(@color(blue))"):
print "%s: zephyr=>humbug: Skipping message we got from Humbug!" % \ logger.debug("Skipping message we got from Humbug!")
(datetime.datetime.now(),)
return return
zephyr_class = notice.cls.lower() zephyr_class = notice.cls.lower()
@ -246,8 +238,8 @@ def process_notice(notice, log):
# Drop messages not to the listed subscriptions # Drop messages not to the listed subscriptions
if (zephyr_class not in current_zephyr_subs) and not \ if (zephyr_class not in current_zephyr_subs) and not \
(is_personal and options.forward_personals): (is_personal and options.forward_personals):
print "%s: zephyr=>humbug: Skipping ... %s/%s/%s" % \ logger.debug("Skipping ... %s/%s/%s" %
(datetime.datetime.now(), zephyr_class, notice.instance, is_personal) (zephyr_class, notice.instance, is_personal))
return return
zeph = { 'time' : str(notice.time), zeph = { 'time' : str(notice.time),
@ -274,17 +266,15 @@ def process_notice(notice, log):
zeph = decode_unicode_byte_strings(zeph) zeph = decode_unicode_byte_strings(zeph)
print "%s: zephyr=>humbug: received a message on %s/%s from %s..." % \ logger.info("Received a message on %s/%s from %s..." %
(datetime.datetime.now(), zephyr_class, notice.instance, notice.sender) (zephyr_class, notice.instance, notice.sender))
if log is not None: if log is not None:
log.write(simplejson.dumps(zeph) + '\n') log.write(simplejson.dumps(zeph) + '\n')
log.flush() log.flush()
res = send_humbug(zeph) res = send_humbug(zeph)
if res.get("result") != "success": if res.get("result") != "success":
print >>sys.stderr, 'Error relaying zephyr' logger.error("Error relaying zephyr:\n%s\n%s" %(zeph, res))
print zeph
print res
def decode_unicode_byte_strings(zeph): def decode_unicode_byte_strings(zeph):
for field in zeph.keys(): for field in zeph.keys():
@ -304,8 +294,7 @@ def zephyr_subscribe_autoretry(sub):
except IOError: except IOError:
# Probably a SERVNAK from the zephyr server, but print the # Probably a SERVNAK from the zephyr server, but print the
# traceback just in case it's something else # traceback just in case it's something else
traceback.print_exc() logger.exception("Error subscribing to personals (retrying). Traceback:")
print "Error subscribing to personals; retrying."
time.sleep(1) time.sleep(1)
def zephyr_to_humbug(options): def zephyr_to_humbug(options):
@ -335,16 +324,15 @@ def zephyr_to_humbug(options):
zeph["stream"] = zeph["class"] zeph["stream"] = zeph["class"]
if "instance" in zeph: if "instance" in zeph:
zeph["subject"] = zeph["instance"] zeph["subject"] = zeph["instance"]
print "%s: zephyr=>humbug: sending saved message to %s from %s..." % \ logger.info("sending saved message to %s from %s..." %
(datetime.datetime.now(), zeph.get('stream', zeph.get('recipient')), (zeph.get('stream', zeph.get('recipient')),
zeph['sender']) zeph['sender']))
send_humbug(zeph) send_humbug(zeph)
except: except:
print >>sys.stderr, 'Could not send saved zephyr' logger.exception("Could not send saved zephyr:")
traceback.print_exc()
time.sleep(2) time.sleep(2)
print "%s: zephyr=>humbug: Starting receive loop." % (datetime.datetime.now(),) logger.info("Starting receive loop.")
if options.log_path is not None: if options.log_path is not None:
with open(options.log_path, 'a') as log: with open(options.log_path, 'a') as log:
@ -355,15 +343,13 @@ def zephyr_to_humbug(options):
def forward_to_zephyr(message): def forward_to_zephyr(message):
zsig = u"%s@(@color(blue))" % (username_to_fullname(message["sender_email"]),) zsig = u"%s@(@color(blue))" % (username_to_fullname(message["sender_email"]),)
if ' dot ' in zsig: if ' dot ' in zsig:
print "%s: humbug=>zephyr: ERROR! Couldn't compute zsig for %s!" % \ logger.error("Error computing zsig for %s!" % (message["sender_email"],))
(datetime.datetime.now(), message["sender_email"])
return return
wrapped_content = "\n".join("\n".join(textwrap.wrap(line)) wrapped_content = "\n".join("\n".join(textwrap.wrap(line))
for line in message["content"].split("\n")) for line in message["content"].split("\n"))
print "%s: humbug=>zephyr: Forwarding message from %s" % \ logger.info("Forwarding message from %s" % (message["sender_email"],))
(datetime.datetime.now(), message["sender_email"])
if message['type'] == "stream": if message['type'] == "stream":
zephyr_class = message["display_recipient"] zephyr_class = message["display_recipient"]
instance = message["subject"] instance = message["subject"]
@ -393,8 +379,8 @@ def forward_to_zephyr(message):
for user in message["display_recipient"]]) for user in message["display_recipient"]])
if options.test_mode: if options.test_mode:
print zwrite_args logger.debug("Would have forwarded: %s\n%s" %
print wrapped_content.encode("utf-8") (zwrite_args, wrapped_content.encode("utf-8")))
return return
p = subprocess.Popen(zwrite_args, stdin=subprocess.PIPE, p = subprocess.Popen(zwrite_args, stdin=subprocess.PIPE,
@ -414,19 +400,19 @@ def maybe_forward_to_zephyr(message):
return return
timestamp_now = datetime.datetime.now().strftime("%s") timestamp_now = datetime.datetime.now().strftime("%s")
if float(message["timestamp"]) < float(timestamp_now) - 15: if float(message["timestamp"]) < float(timestamp_now) - 15:
print "%s humbug=>zephyr: Alert! Out of order message: %s < %s" % \ logger.warning("Skipping out of order message: %s < %s" %
(datetime.datetime.now(), message["timestamp"], timestamp_now) (message["timestamp"], timestamp_now))
return return
try: try:
forward_to_zephyr(message) forward_to_zephyr(message)
except: except:
# Don't let an exception forwarding one message crash the # Don't let an exception forwarding one message crash the
# whole process # whole process
traceback.print_exc() logger.exception("Error forwarding message:")
def humbug_to_zephyr(options): def humbug_to_zephyr(options):
# Sync messages from zephyr to humbug # Sync messages from zephyr to humbug
print "%s: humbug=>zephyr: Starting syncing messages." % (datetime.datetime.now(),) logger.info("Starting syncing messages.")
humbug_client.call_on_each_message(maybe_forward_to_zephyr, humbug_client.call_on_each_message(maybe_forward_to_zephyr,
options={"mirror": 'zephyr_mirror'}) options={"mirror": 'zephyr_mirror'})
@ -555,6 +541,24 @@ def parse_zephyr_subs(verbose=False):
zephyr_subscriptions.add((cls.strip(), instance.strip(), recipient.strip())) zephyr_subscriptions.add((cls.strip(), instance.strip(), recipient.strip()))
return zephyr_subscriptions return zephyr_subscriptions
def configure_logger(direction_name):
if options.forward_class_messages:
if options.test_mode:
log_file = "/home/humbug/test-mirror-log"
else:
log_file = "/home/humbug/mirror-log"
else:
log_file = "/tmp/humbug-log." + options.user
logger = logging.getLogger(__name__)
log_format = "%(asctime)s " + direction_name + ": %(message)s"
formatter = logging.Formatter(log_format)
logging.basicConfig(format=log_format)
logger.setLevel(logging.DEBUG)
file_handler = logging.FileHandler(log_file)
file_handler.setFormatter(formatter)
logger.addHandler(file_handler)
return logger
if __name__ == "__main__": if __name__ == "__main__":
parser = optparse.OptionParser() parser = optparse.OptionParser()
parser.add_option('--forward-class-messages', parser.add_option('--forward-class-messages',
@ -675,6 +679,7 @@ or specify the --api-key-file option.""" % (options.api_key_file,)))
child_pid = os.fork() child_pid = os.fork()
if child_pid == 0: if child_pid == 0:
# Run the humbug => zephyr mirror in the child # Run the humbug => zephyr mirror in the child
logger = configure_logger("humbug=>zephyr")
humbug_to_zephyr(options) humbug_to_zephyr(options)
sys.exit(0) sys.exit(0)
@ -688,4 +693,5 @@ or specify the --api-key-file option.""" % (options.api_key_file,)))
except IOError: except IOError:
traceback.print_exc() traceback.print_exc()
time.sleep(1) time.sleep(1)
logger = configure_logger("zephyr=>humbug")
zephyr_to_humbug(options) zephyr_to_humbug(options)