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

zephyr_mirror: Fix logging messages to multiple files under /tmp.

Browse source 
Also fixes the fact that certain output was not logged at all.

(imported from commit 0e63a9ef4105921ad7cbe3f7565ce7832c5db25e)
This commit is contained in:
Jacob Hurwitz 2013-01-14 13:08:33 -05:00 committed by Tim Abbott
parent 9ebfa84385
commit 630b7ae521
2 changed files with 59 additions and 49 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

2
bots/sync-public-streams
View file

@ -20,7 +20,7 @@ def fetch_public_streams():
if res.get("result") == "success": if res.get("result") == "success":
streams = res["streams"] streams = res["streams"]
else: else:
logging.error("Error getting public streams:\n%s" % res) logging.error("Error getting public streams:\n%s" % (res,))
return None return None
except Exception: except Exception:
logging.exception("Error getting public streams:") logging.exception("Error getting public streams:")

106
bots/zephyr_mirror_backend.py
View file

@ -153,19 +153,19 @@ def zephyr_bulk_subscribe(subs):
# 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.
logger.exception("Error subscribing to streams (will retry automatically):") logger.exception("Error subscribing to streams (will retry automatically):")
logging.warning("Streams were: %s" % ([cls for cls, instance, recipient in subs],)) logger.warning("Streams were: %s" % ([cls for cls, instance, recipient in subs],))
return return
try: try:
actual_zephyr_subs = [cls for (cls, _, _) in zephyr._z.getSubscriptions()] actual_zephyr_subs = [cls for (cls, _, _) in zephyr._z.getSubscriptions()]
except IOError: except IOError:
logging.exception("Error getting current Zephyr subscriptions") logger.exception("Error getting current Zephyr subscriptions")
# Don't add anything to current_zephyr_subs so that we'll # Don't add anything to current_zephyr_subs so that we'll
# retry the next time we check for streams to subscribe to # retry the next time we check for streams to subscribe to
# (within 15 seconds). # (within 15 seconds).
return return
for (cls, instance, recipient) in subs: for (cls, instance, recipient) in subs:
if cls not in actual_zephyr_subs: if cls not in actual_zephyr_subs:
logging.error("Zephyr failed to subscribe us to %s; will retry" % (cls,)) logger.error("Zephyr failed to subscribe us to %s; will retry" % (cls,))
try: try:
# We'll retry automatically when we next check for # We'll retry automatically when we next check for
# streams to subscribe to (within 15 seconds), but # streams to subscribe to (within 15 seconds), but
@ -211,13 +211,13 @@ def maybe_restart_mirroring_script():
if child_pid is not None: if child_pid is not None:
os.kill(child_pid, signal.SIGTERM) os.kill(child_pid, signal.SIGTERM)
except OSError: except OSError:
# We don't care if the child process no longer exists, so just print the error # We don't care if the child process no longer exists, so just log the error
logging.exception("") logger.exception("")
try: try:
zephyr._z.cancelSubs() zephyr._z.cancelSubs()
except IOError: except IOError:
# We don't care whether we failed to cancel subs properly, but we should log it # We don't care whether we failed to cancel subs properly, but we should log it
logging.exception("") logger.exception("")
while True: while True:
try: try:
os.execvp(os.path.join(options.root_path, "user_root", "zephyr_mirror_backend.py"), sys.argv) os.execvp(os.path.join(options.root_path, "user_root", "zephyr_mirror_backend.py"), sys.argv)
@ -245,7 +245,7 @@ def process_loop(log):
try: try:
maybe_restart_mirroring_script() maybe_restart_mirroring_script()
except Exception: except Exception:
logging.exception("Error checking whether restart is required:") logger.exception("Error checking whether restart is required:")
time.sleep(sleep_time) time.sleep(sleep_time)
sleep_count += sleep_time sleep_count += sleep_time
@ -256,7 +256,7 @@ def process_loop(log):
try: try:
update_subscriptions() update_subscriptions()
except Exception: except Exception:
logging.exception("Error updating subscriptions from Humbug:") logger.exception("Error updating subscriptions from Humbug:")
def parse_zephyr_body(zephyr_data): def parse_zephyr_body(zephyr_data):
try: try:
@ -346,7 +346,7 @@ def process_notice(notice, log):
if res.get("result") != "success": if res.get("result") != "success":
logger.error("Error relaying zephyr:\n%s\n%s" % (zeph, res)) logger.error("Error relaying zephyr:\n%s\n%s" % (zeph, res))
except Exception: except Exception:
logging.exception("Error relaying zephyr:") logger.exception("Error relaying zephyr:")
finally: finally:
os._exit(0) os._exit(0)
@ -366,7 +366,7 @@ def zephyr_subscribe_autoretry(sub):
zephyr.Subscriptions().add(sub) zephyr.Subscriptions().add(sub)
return return
except IOError: except IOError:
# Probably a SERVNAK from the zephyr server, but print the # Probably a SERVNAK from the zephyr server, but log the
# traceback just in case it's something else # traceback just in case it's something else
logger.exception("Error subscribing to personals (retrying). Traceback:") logger.exception("Error subscribing to personals (retrying). Traceback:")
time.sleep(1) time.sleep(1)
@ -419,15 +419,15 @@ def send_zephyr(zwrite_args, content):
stdout=subprocess.PIPE, stderr=subprocess.PIPE) stdout=subprocess.PIPE, stderr=subprocess.PIPE)
stdout, stderr = p.communicate(input=content.encode("utf-8")) stdout, stderr = p.communicate(input=content.encode("utf-8"))
if p.returncode: if p.returncode:
logging.error("zwrite command '%s' failed with return code %d:" % ( logger.error("zwrite command '%s' failed with return code %d:" % (
" ".join(zwrite_args), p.returncode,)) " ".join(zwrite_args), p.returncode,))
if stdout: if stdout:
logging.info("stdout: " + stdout) logger.info("stdout: " + stdout)
elif stderr: elif stderr:
logging.warning("zwrite command '%s' printed the following warning:" % ( logger.warning("zwrite command '%s' printed the following warning:" % (
" ".join(zwrite_args),)) " ".join(zwrite_args),))
if stderr: if stderr:
logging.warning("stderr: " + stderr) logger.warning("stderr: " + stderr)
return (p.returncode, stderr) return (p.returncode, stderr)
def send_authed_zephyr(zwrite_args, content): def send_authed_zephyr(zwrite_args, content):
@ -597,7 +597,7 @@ def add_humbug_subscriptions(verbose):
zephyr_subscriptions.add(instance) zephyr_subscriptions.add(instance)
continue continue
elif cls.lower() == "mail" and instance.lower() == "inbox": elif cls.lower() == "mail" and instance.lower() == "inbox":
# We forward mail zephyrs, so no need to print a warning. # We forward mail zephyrs, so no need to log a warning.
continue continue
elif len(cls) > 30: elif len(cls) > 30:
skipped.add((cls, instance, recipient, "Class longer than 30 characters")) skipped.add((cls, instance, recipient, "Class longer than 30 characters"))
@ -613,24 +613,20 @@ def add_humbug_subscriptions(verbose):
if len(zephyr_subscriptions) != 0: if len(zephyr_subscriptions) != 0:
res = humbug_client.add_subscriptions(list(zephyr_subscriptions)) res = humbug_client.add_subscriptions(list(zephyr_subscriptions))
if res.get("result") != "success": if res.get("result") != "success":
print "Error subscribing to streams:" logger.error("Error subscribing to streams:\n%s" % (res["msg"],))
print res["msg"]
return return
already = res.get("already_subscribed") already = res.get("already_subscribed")
new = res.get("subscribed") new = res.get("subscribed")
if verbose: if verbose:
if already is not None and len(already) > 0: if already is not None and len(already) > 0:
print logger.info("\nAlready subscribed to: %s" % (", ".join(already),))
print "Already subscribed to:", ", ".join(already)
if new is not None and len(new) > 0: if new is not None and len(new) > 0:
print logger.info("\nSuccessfully subscribed to: %s" % (", ".join(new),))
print "Successfully subscribed to:", ", ".join(new)
if len(skipped) > 0: if len(skipped) > 0:
if verbose: if verbose:
print logger.info("\n" + "\n".join(textwrap.wrap("""\
print "\n".join(textwrap.wrap("""\
You have some lines in ~/.zephyr.subs that could not be You have some lines in ~/.zephyr.subs that could not be
synced to your Humbug subscriptions because they do not synced to your Humbug subscriptions because they do not
use "*" as both the instance and recipient and not one of use "*" as both the instance and recipient and not one of
@ -639,27 +635,23 @@ Humbug has a mechanism for forwarding. Humbug does not
allow subscribing to only some subjects on a Humbug allow subscribing to only some subjects on a Humbug
stream, so this tool has not created a corresponding stream, so this tool has not created a corresponding
Humbug subscription to these lines in ~/.zephyr.subs: Humbug subscription to these lines in ~/.zephyr.subs:
""")) """)) + "\n")
print
for (cls, instance, recipient, reason) in skipped: for (cls, instance, recipient, reason) in skipped:
if verbose: if verbose:
if reason != "": if reason != "":
print " [%s,%s,%s] (%s)" % (cls, instance, recipient, reason) logger.info(" [%s,%s,%s] (%s)" % (cls, instance, recipient, reason))
else: else:
print " [%s,%s,%s]" % (cls, instance, recipient, reason) logger.info(" [%s,%s,%s]" % (cls, instance, recipient))
if len(skipped) > 0: if len(skipped) > 0:
if verbose: if verbose:
print logger.info("\n" + "\n".join(textwrap.wrap("""\
print "\n".join(textwrap.wrap("""\
If you wish to be subscribed to any Humbug streams related If you wish to be subscribed to any Humbug streams related
to these .zephyrs.subs lines, please do so via the Humbug to these .zephyrs.subs lines, please do so via the Humbug
web interface. web interface.
""")) """)) + "\n")
print
if verbose: if verbose:
print logger.info("\nIMPORTANT: Please reload the Humbug app for these changes to take effect.\n")
print "IMPORTANT: Please reload the Humbug app for these changes to take effect."
def valid_stream_name(name): def valid_stream_name(name):
return name != "" return name != ""
@ -669,7 +661,7 @@ def parse_zephyr_subs(verbose=False):
subs_file = os.path.join(os.environ["HOME"], ".zephyr.subs") subs_file = os.path.join(os.environ["HOME"], ".zephyr.subs")
if not os.path.exists(subs_file): if not os.path.exists(subs_file):
if verbose: if verbose:
print >>sys.stderr, "Couldn't find ~/.zephyr.subs!" logger.error("Couldn't find ~/.zephyr.subs!")
return [] return []
for line in file(subs_file, "r").readlines(): for line in file(subs_file, "r").readlines():
@ -683,11 +675,11 @@ def parse_zephyr_subs(verbose=False):
recipient = recipient.replace("%me%", options.user) recipient = recipient.replace("%me%", options.user)
if not valid_stream_name(cls): if not valid_stream_name(cls):
if verbose: if verbose:
print >>sys.stderr, "Skipping subscription to unsupported class name: [%s]" % (line,) logger.error("Skipping subscription to unsupported class name: [%s]" % (line,))
continue continue
except Exception: except Exception:
if verbose: if verbose:
print >>sys.stderr, "Couldn't parse ~/.zephyr.subs line: [%s]" % (line,) logger.error("Couldn't parse ~/.zephyr.subs line: [%s]" % (line,))
continue continue
zephyr_subscriptions.add((cls.strip(), instance.strip(), recipient.strip())) zephyr_subscriptions.add((cls.strip(), instance.strip(), recipient.strip()))
return zephyr_subscriptions return zephyr_subscriptions
@ -705,7 +697,7 @@ def fetch_fullname(username):
return username return username
def configure_logger(direction_name): def open_logger():
if options.forward_class_messages: if options.forward_class_messages:
if options.test_mode: if options.test_mode:
log_file = "/home/humbug/test-mirror-log" log_file = "/home/humbug/test-mirror-log"
@ -719,7 +711,7 @@ def configure_logger(direction_name):
# reopen it anyway. # reopen it anyway.
f.close() f.close()
logger = logging.getLogger(__name__) logger = logging.getLogger(__name__)
log_format = "%(asctime)s " + direction_name + ": %(message)s" log_format = "%(asctime)s <initial>: %(message)s"
formatter = logging.Formatter(log_format) formatter = logging.Formatter(log_format)
logging.basicConfig(format=log_format) logging.basicConfig(format=log_format)
logger.setLevel(logging.DEBUG) logger.setLevel(logging.DEBUG)
@ -728,6 +720,20 @@ def configure_logger(direction_name):
logger.addHandler(file_handler) logger.addHandler(file_handler)
return logger return logger
def configure_logger(logger, direction_name):
if direction_name is None:
log_format = "%(message)s"
else:
log_format = "%(asctime)s [" + direction_name + "] %(message)s"
formatter = logging.Formatter(log_format)
# Replace the formatters for the file and stdout loggers
for handler in logger.handlers:
handler.setFormatter(formatter)
root_logger = logging.getLogger()
for handler in root_logger.handlers:
handler.setFormatter(formatter)
def parse_args(): def parse_args():
parser = optparse.OptionParser() parser = optparse.OptionParser()
parser.add_option('--forward-class-messages', parser.add_option('--forward-class-messages',
@ -791,7 +797,7 @@ def die_gracefully(signal, frame):
zephyr._z.cancelSubs() zephyr._z.cancelSubs()
except IOError: except IOError:
# We don't care whether we failed to cancel subs properly, but we should log it # We don't care whether we failed to cancel subs properly, but we should log it
logging.exception("") logger.exception("")
sys.exit(1) sys.exit(1)
@ -808,6 +814,9 @@ if __name__ == "__main__":
(options, args) = parse_args() (options, args) = parse_args()
logger = open_logger()
configure_logger(logger, "parent")
# The 'api' directory needs to go first, so that 'import humbug' won't pick # The 'api' directory needs to go first, so that 'import humbug' won't pick
# up some other directory named 'humbug'. # up some other directory named 'humbug'.
pyzephyr_lib_path = "python-zephyr/build/lib.linux-" + os.uname()[4] + "-2.6/" pyzephyr_lib_path = "python-zephyr/build/lib.linux-" + os.uname()[4] + "-2.6/"
@ -823,10 +832,10 @@ if __name__ == "__main__":
api_key = os.environ.get("HUMBUG_API_KEY") api_key = os.environ.get("HUMBUG_API_KEY")
else: else:
if not os.path.exists(options.api_key_file): if not os.path.exists(options.api_key_file):
print "\n".join(textwrap.wrap("""\ logger.error("\n" + "\n".join(textwrap.wrap("""\
Could not find API key file. Could not find API key file.
You need to either place your api key file at %s, You need to either place your api key file at %s,
or specify the --api-key-file option.""" % (options.api_key_file,))) or specify the --api-key-file option.""" % (options.api_key_file,))))
sys.exit(1) sys.exit(1)
api_key = file(options.api_key_file).read().strip() api_key = file(options.api_key_file).read().strip()
# Store the API key in the environment so that our children # Store the API key in the environment so that our children
@ -845,7 +854,8 @@ or specify the --api-key-file option.""" % (options.api_key_file,)))
start_time = time.time() start_time = time.time()
if options.sync_subscriptions: if options.sync_subscriptions:
print "Syncing your ~/.zephyr.subs to your Humbug Subscriptions!" configure_logger(logger, None) # make the output cleaner
logger.info("Syncing your ~/.zephyr.subs to your Humbug Subscriptions!")
add_humbug_subscriptions(True) add_humbug_subscriptions(True)
sys.exit(0) sys.exit(0)
@ -863,12 +873,12 @@ or specify the --api-key-file option.""" % (options.api_key_file,)))
continue continue
# Another copy of zephyr_mirror.py! Kill it. # Another copy of zephyr_mirror.py! Kill it.
print "Killing duplicate zephyr_mirror process %s" % (pid,) logger.info("Killing duplicate zephyr_mirror process %s" % (pid,))
try: try:
os.kill(pid, signal.SIGINT) os.kill(pid, signal.SIGINT)
except OSError: except OSError:
# We don't care if the target process no longer exists, so just print the error # We don't care if the target process no longer exists, so just log the error
traceback.print_exc() logger.exception("")
if options.shard is not None and set(options.shard) != set("a"): if options.shard is not None and set(options.shard) != set("a"):
# The shard that is all "a"s is the one that handles personals # The shard that is all "a"s is the one that handles personals
@ -881,7 +891,7 @@ or specify the --api-key-file option.""" % (options.api_key_file,)))
if child_pid == 0: if child_pid == 0:
CURRENT_STATE = States.HumbugToZephyr CURRENT_STATE = States.HumbugToZephyr
# Run the humbug => zephyr mirror in the child # Run the humbug => zephyr mirror in the child
logger = configure_logger("humbug=>zephyr") configure_logger(logger, "humbug=>zephyr")
zsig_fullname = fetch_fullname(options.user) zsig_fullname = fetch_fullname(options.user)
humbug_to_zephyr(options) humbug_to_zephyr(options)
sys.exit(0) sys.exit(0)
@ -897,12 +907,12 @@ or specify the --api-key-file option.""" % (options.api_key_file,)))
zephyr.init() zephyr.init()
break break
except IOError: except IOError:
traceback.print_exc() logger.exception("")
time.sleep(1) time.sleep(1)
logger_name = "zephyr=>humbug" logger_name = "zephyr=>humbug"
if options.shard is not None: if options.shard is not None:
logger_name += "(%s)" % (options.shard,) logger_name += "(%s)" % (options.shard,)
logger = configure_logger(logger_name) configure_logger(logger, logger_name)
# Have the kernel reap children for when we fork off processes to send Humbugs # Have the kernel reap children for when we fork off processes to send Humbugs
signal.signal(signal.SIGCHLD, signal.SIG_IGN) signal.signal(signal.SIGCHLD, signal.SIG_IGN)
zephyr_to_humbug(options) zephyr_to_humbug(options)