[ARVADOS] created: 694b8e7db124233ec947f5fa7b6fe0702577c3a0
git at public.curoverse.com
git at public.curoverse.com
Tue Aug 12 17:42:16 EDT 2014
at 694b8e7db124233ec947f5fa7b6fe0702577c3a0 (commit)
commit 694b8e7db124233ec947f5fa7b6fe0702577c3a0
Author: Brett Smith <brett at curoverse.com>
Date: Tue Aug 12 17:43:28 2014 -0400
3457: Revamp Python SDK and tool logging.
The primary goal of this commit is to introduce a dedicated logging
object to the arvados module, which we configure to our
specifications, and use it consistently throughout the SDK and tools.
This lets us handle our logging configuration consistently in one
place, and avoid interfering with logging in SDK users. I made some
minor style changes to logging calls while I was at it.
diff --git a/sdk/python/arvados/__init__.py b/sdk/python/arvados/__init__.py
index 42c4b3a..66aa16e 100644
--- a/sdk/python/arvados/__init__.py
+++ b/sdk/python/arvados/__init__.py
@@ -25,6 +25,18 @@ from stream import *
import errors
import util
+logger = logging.getLogger('arvados')
+if config.get('ARVADOS_DEBUG'):
+ logger.setLevel(logging.DEBUG)
+ log_handler = logging.StreamHandler()
+else:
+ log_handler = logging.NullHandler()
+log_handler.setFormatter(logging.Formatter(
+ '%(asctime)s %(name)s %(levelname)s: %(message)s',
+ '%Y-%m-%d %H:%M:%S'))
+log_handler.setLevel(logger.level)
+logger.addHandler(log_handler)
+
def task_set_output(self,s):
api('v1').job_tasks().update(uuid=self['uuid'],
body={
diff --git a/sdk/python/arvados/api.py b/sdk/python/arvados/api.py
index 8a71b90..7c60f51 100644
--- a/sdk/python/arvados/api.py
+++ b/sdk/python/arvados/api.py
@@ -12,6 +12,7 @@ import config
import errors
import util
+_logger = logging.getLogger('arvados.api')
services = {}
class CredentialsFromEnv(object):
@@ -82,14 +83,11 @@ def api(version=None, cache=True, **kwargs):
`apiclient.discovery.build`. If the `discoveryServiceUrl` or `http`
keyword arguments are missing, this function will set default values for
them, based on the current Arvados configuration settings."""
- if config.get('ARVADOS_DEBUG'):
- logging.basicConfig(level=logging.DEBUG)
-
if not cache or not services.get(version):
if not version:
version = 'v1'
- logging.info("Using default API version. " +
- "Call arvados.api('%s') instead." %
+ _logger.info("Using default API version. " +
+ "Call arvados.api('%s') instead.",
version)
if 'discoveryServiceUrl' not in kwargs:
diff --git a/sdk/python/arvados/collection.py b/sdk/python/arvados/collection.py
index e420a67..0c8b620 100644
--- a/sdk/python/arvados/collection.py
+++ b/sdk/python/arvados/collection.py
@@ -27,6 +27,8 @@ import config
import errors
import util
+_logger = logging.getLogger('arvados.collection')
+
def normalize_stream(s, stream):
stream_tokens = [s]
sortedfiles = list(stream.keys())
@@ -117,8 +119,8 @@ class CollectionReader(object):
uuid=self._manifest_locator).execute()
self._manifest_text = c['manifest_text']
except Exception as e:
- logging.warning("API lookup failed for collection %s (%s: %s)" %
- (self._manifest_locator, type(e), str(e)))
+ _logger.warning("API lookup failed for collection %s (%s: %s)",
+ self._manifest_locator, type(e), str(e))
self._manifest_text = Keep.get(self._manifest_locator)
self._streams = []
for stream_line in self._manifest_text.split("\n"):
diff --git a/sdk/python/arvados/events.py b/sdk/python/arvados/events.py
index 06f3b34..0dbfe63 100644
--- a/sdk/python/arvados/events.py
+++ b/sdk/python/arvados/events.py
@@ -8,6 +8,8 @@ import re
import config
import logging
+_logger = logging.getLogger('arvados.events')
+
class EventClient(WebSocketClient):
def __init__(self, url, filters, on_event):
ssl_options = None
@@ -41,8 +43,8 @@ def subscribe(api, filters, on_event):
ws = EventClient(url, filters, on_event)
ws.connect()
return ws
- except:
- logging.exception('')
+ except Exception:
+ _logger.exception('')
if (ws):
- ws.close_connection()
+ ws.close_connection()
raise
diff --git a/sdk/python/arvados/keep.py b/sdk/python/arvados/keep.py
index fdb27f0..b5d5d72 100644
--- a/sdk/python/arvados/keep.py
+++ b/sdk/python/arvados/keep.py
@@ -21,6 +21,7 @@ import timer
import datetime
import ssl
+_logger = logging.getLogger('arvados.keep')
global_client_object = None
from api import *
@@ -200,10 +201,10 @@ class KeepClient(object):
self.run_with_limiter(limiter)
def run_with_limiter(self, limiter):
- logging.debug("KeepWriterThread %s proceeding %s %s" %
- (str(threading.current_thread()),
- self.args['data_hash'],
- self.args['service_root']))
+ _logger.debug("KeepWriterThread %s proceeding %s %s",
+ str(threading.current_thread()),
+ self.args['data_hash'],
+ self.args['service_root'])
h = httplib2.Http(timeout=self.args.get('timeout', None))
url = self.args['service_root'] + self.args['data_hash']
api_token = config.get('ARVADOS_API_TOKEN')
@@ -215,7 +216,7 @@ class KeepClient(object):
headers['X-Keep-Desired-Replication'] = str(self.args['want_copies'])
try:
- logging.debug("Uploading to {}".format(url))
+ _logger.debug("Uploading to {}".format(url))
resp, content = h.request(url.encode('utf-8'), 'PUT',
headers=headers,
body=self.args['data'])
@@ -230,10 +231,10 @@ class KeepClient(object):
body=body)
if re.match(r'^2\d\d$', resp['status']):
self._success = True
- logging.debug("KeepWriterThread %s succeeded %s %s" %
- (str(threading.current_thread()),
- self.args['data_hash'],
- self.args['service_root']))
+ _logger.debug("KeepWriterThread %s succeeded %s %s",
+ str(threading.current_thread()),
+ self.args['data_hash'],
+ self.args['service_root'])
replicas_stored = 1
if 'x-keep-replicas-stored' in resp:
# Tick the 'done' counter for the number of replica
@@ -246,15 +247,15 @@ class KeepClient(object):
pass
limiter.save_response(content.strip(), replicas_stored)
else:
- logging.warning("Request fail: PUT %s => %s %s" %
- (url, resp['status'], content))
+ _logger.warning("Request fail: PUT %s => %s %s",
+ url, resp['status'], content)
except (httplib2.HttpLib2Error,
httplib.HTTPException,
ssl.SSLError) as e:
# When using https, timeouts look like ssl.SSLError from here.
# "SSLError: The write operation timed out"
- logging.warning("Request fail: PUT %s => %s: %s" %
- (url, type(e), str(e)))
+ _logger.warning("Request fail: PUT %s => %s: %s",
+ url, type(e), str(e))
def __init__(self, **kwargs):
self.lock = threading.Lock()
@@ -298,7 +299,7 @@ class KeepClient(object):
f['service_port']))
for f in keep_services)
self.service_roots = sorted(set(roots))
- logging.debug(str(self.service_roots))
+ _logger.debug(str(self.service_roots))
finally:
self.lock.release()
@@ -343,7 +344,7 @@ class KeepClient(object):
# Remove the digits just used from the seed
seed = seed[8:]
- logging.debug(str(pseq))
+ _logger.debug(str(pseq))
return pseq
class CacheSlot(object):
@@ -401,8 +402,6 @@ class KeepClient(object):
self._cache_lock.release()
def get(self, locator):
- #logging.debug("Keep.get %s" % (locator))
-
if re.search(r',', locator):
return ''.join(self.get(x) for x in locator.split(','))
if 'KEEP_LOCAL_STORE' in os.environ:
@@ -410,7 +409,6 @@ class KeepClient(object):
expect_hash = re.sub(r'\+.*', '', locator)
slot, first = self.reserve_cache(expect_hash)
- #logging.debug("%s %s %s" % (slot, first, expect_hash))
if not first:
v = slot.get()
@@ -448,23 +446,23 @@ class KeepClient(object):
def get_url(self, url, headers, expect_hash):
h = httplib2.Http()
try:
- logging.info("Request: GET %s" % (url))
+ _logger.info("Request: GET %s", url)
with timer.Timer() as t:
resp, content = h.request(url.encode('utf-8'), 'GET',
headers=headers)
- logging.info("Received %s bytes in %s msec (%s MiB/sec)" % (len(content),
- t.msecs,
- (len(content)/(1024*1024))/t.secs))
+ _logger.info("Received %s bytes in %s msec (%s MiB/sec)",
+ len(content), t.msecs,
+ (len(content)/(1024*1024))/t.secs)
if re.match(r'^2\d\d$', resp['status']):
m = hashlib.new('md5')
m.update(content)
md5 = m.hexdigest()
if md5 == expect_hash:
return content
- logging.warning("Checksum fail: md5(%s) = %s" % (url, md5))
+ _logger.warning("Checksum fail: md5(%s) = %s", url, md5)
except Exception as e:
- logging.info("Request fail: GET %s => %s: %s" %
- (url, type(e), str(e)))
+ _logger.info("Request fail: GET %s => %s: %s",
+ url, type(e), str(e))
return None
def put(self, data, **kwargs):
@@ -498,9 +496,9 @@ class KeepClient(object):
threads_retry = []
for t in threads:
if not t.success():
- logging.warning("Retrying: PUT %s %s" % (
- t.args['service_root'],
- t.args['data_hash']))
+ _logger.warning("Retrying: PUT %s %s",
+ t.args['service_root'],
+ t.args['data_hash'])
retry_with_args = t.args.copy()
t_retry = KeepClient.KeepWriterThread(**retry_with_args)
t_retry.start()
diff --git a/sdk/python/arvados/stream.py b/sdk/python/arvados/stream.py
index fd84435..7a29100 100644
--- a/sdk/python/arvados/stream.py
+++ b/sdk/python/arvados/stream.py
@@ -1,7 +1,6 @@
import gflags
import httplib
import httplib2
-import logging
import os
import pprint
import sys
diff --git a/sdk/python/bin/arv-get b/sdk/python/bin/arv-get
index 7f07e22..5c16f2c 100755
--- a/sdk/python/bin/arv-get
+++ b/sdk/python/bin/arv-get
@@ -8,7 +8,9 @@ import string
import sys
import logging
-logger = logging.getLogger(os.path.basename(sys.argv[0]))
+import arvados
+
+logger = logging.getLogger('arvados.arv-get')
parser = argparse.ArgumentParser(
description='Copy data from Keep to a local file or pipe.')
@@ -87,7 +89,7 @@ if not args.r and (os.path.isdir(args.destination) or
args.destination[-1] == os.path.sep):
args.destination = os.path.join(args.destination,
os.path.basename(args.locator))
- logger.debug("Appended source file name to destination directory: %s" %
+ logger.debug("Appended source file name to destination directory: %s",
args.destination)
# Turn on --progress by default if stderr is a tty and stdout isn't.
@@ -107,8 +109,6 @@ else:
args.destination = args.destination.rstrip(os.sep)
-import arvados
-
r = re.search(r'^(.*?)(/.*)?$', args.locator)
collection = r.group(1)
get_prefix = r.group(2)
@@ -121,7 +121,7 @@ if not get_prefix:
try:
if not args.n:
if not args.f and os.path.exists(args.destination):
- logger.error('Local file %s already exists' % args.destination)
+ logger.error('Local file %s already exists', args.destination)
sys.exit(1)
with open(args.destination, 'wb') as f:
try:
@@ -130,8 +130,8 @@ if not get_prefix:
manifest = c['manifest_text']
except Exception as e:
logging.warning(
- "API lookup failed for collection %s (%s: %s)" %
- (collection, type(e), str(e)))
+ "API lookup failed for collection %s (%s: %s)",
+ collection, type(e), str(e))
manifest = arvados.Keep.get(collection)
f.write(manifest)
sys.exit(0)
@@ -156,7 +156,7 @@ try:
os.path.join(s.name(), f.name())[len(get_prefix)+1:])
if (not (args.n or args.f or args.skip_existing) and
os.path.exists(dest_path)):
- logger.error('Local file %s already exists' % dest_path)
+ logger.error('Local file %s already exists', dest_path)
sys.exit(1)
else:
if os.path.join(s.name(), f.name()) != '.' + get_prefix:
@@ -176,20 +176,20 @@ for s,f,outfilename in todo:
digestor = None
if not args.n:
if args.skip_existing and os.path.exists(outfilename):
- logger.debug('Local file %s exists. Skipping.' % outfilename)
+ logger.debug('Local file %s exists. Skipping.', outfilename)
continue
elif not args.f and (os.path.isfile(outfilename) or
os.path.isdir(outfilename)):
# Good thing we looked again: apparently this file wasn't
# here yet when we checked earlier.
- logger.error('Local file %s already exists' % outfilename)
+ logger.error('Local file %s already exists', outfilename)
sys.exit(1)
if args.r:
arvados.util.mkdir_dash_p(os.path.dirname(outfilename))
try:
outfile = open(outfilename, 'wb')
except Exception as e:
- logger.error('Open(%s) failed: %s' % (outfilename, e))
+ logger.error('Open(%s) failed: %s', outfilename, e)
sys.exit(1)
if args.hash:
digestor = hashlib.new(args.hash)
diff --git a/sdk/python/bin/arv-ls b/sdk/python/bin/arv-ls
index 1432274..ee74bb8 100755
--- a/sdk/python/bin/arv-ls
+++ b/sdk/python/bin/arv-ls
@@ -6,9 +6,6 @@ import os
import re
import string
import sys
-import logging
-
-logger = logging.getLogger(os.path.basename(sys.argv[0]))
parser = argparse.ArgumentParser(
description='List contents of a manifest')
diff --git a/sdk/python/bin/arv-normalize b/sdk/python/bin/arv-normalize
index 0506381..478a74c 100755
--- a/sdk/python/bin/arv-normalize
+++ b/sdk/python/bin/arv-normalize
@@ -6,9 +6,6 @@ import os
import re
import string
import sys
-import logging
-
-logger = logging.getLogger(os.path.basename(sys.argv[0]))
parser = argparse.ArgumentParser(
description='Read manifest on standard input and put normalized manifest on standard output.')
diff --git a/sdk/python/bin/arv-ws b/sdk/python/bin/arv-ws
index 58b6281..ce7f066 100755
--- a/sdk/python/bin/arv-ws
+++ b/sdk/python/bin/arv-ws
@@ -6,6 +6,8 @@ import argparse
import arvados
from arvados.events import subscribe
+logger = logging.getLogger('arvados.arv-ws')
+
parser = argparse.ArgumentParser()
parser.add_argument('-u', '--uuid', type=str, default="")
args = parser.parse_args()
@@ -22,9 +24,7 @@ ws = None
try:
ws = subscribe(api, filters, lambda ev: on_message(ev))
ws.run_forever()
-except KeyboardInterrupt:
- print '' # don't log it
-except:
- logging.exception('')
+except Exception:
+ logger.exception('')
if (ws):
ws.close_connection()
diff --git a/services/fuse/arvados_fuse/__init__.py b/services/fuse/arvados_fuse/__init__.py
index c0ea03f..ec5e94a 100644
--- a/services/fuse/arvados_fuse/__init__.py
+++ b/services/fuse/arvados_fuse/__init__.py
@@ -17,6 +17,8 @@ import apiclient
import json
import logging
+_logger = logging.getLogger('arvados.arvados_fuse')
+
from time import time
from llfuse import FUSEError
@@ -124,7 +126,7 @@ class Directory(FreshBase):
try:
self.update()
except apiclient.errors.HttpError as e:
- logging.debug(e)
+ _logger.debug(e)
def __getitem__(self, item):
self.checkupdate()
@@ -197,7 +199,8 @@ class CollectionDirectory(Directory):
self.fresh()
return True
except Exception as detail:
- logging.debug("arv-mount %s: error: %s" % (self.collection_locator,detail))
+ _logger.debug("arv-mount %s: error: %s",
+ self.collection_locator, detail)
return False
class MagicDirectory(Directory):
@@ -225,7 +228,7 @@ class MagicDirectory(Directory):
else:
return False
except Exception as e:
- logging.debug('arv-mount exception keep %s', e)
+ _logger.debug('arv-mount exception keep %s', e)
return False
def __getitem__(self, item):
@@ -476,7 +479,8 @@ class Operations(llfuse.Operations):
return entry
def lookup(self, parent_inode, name):
- logging.debug("arv-mount lookup: parent_inode %i name %s", parent_inode, name)
+ _logger.debug("arv-mount lookup: parent_inode %i name %s",
+ parent_inode, name)
inode = None
if name == '.':
@@ -512,7 +516,7 @@ class Operations(llfuse.Operations):
return fh
def read(self, fh, off, size):
- logging.debug("arv-mount read %i %i %i", fh, off, size)
+ _logger.debug("arv-mount read %i %i %i", fh, off, size)
if fh in self._filehandles:
handle = self._filehandles[fh]
else:
@@ -529,7 +533,7 @@ class Operations(llfuse.Operations):
del self._filehandles[fh]
def opendir(self, inode):
- logging.debug("arv-mount opendir: inode %i", inode)
+ _logger.debug("arv-mount opendir: inode %i", inode)
if inode in self.inodes:
p = self.inodes[inode]
@@ -550,14 +554,14 @@ class Operations(llfuse.Operations):
return fh
def readdir(self, fh, off):
- logging.debug("arv-mount readdir: fh %i off %i", fh, off)
+ _logger.debug("arv-mount readdir: fh %i off %i", fh, off)
if fh in self._filehandles:
handle = self._filehandles[fh]
else:
raise llfuse.FUSEError(errno.EBADF)
- logging.debug("arv-mount handle.entry %s", handle.entry)
+ _logger.debug("arv-mount handle.entry %s", handle.entry)
e = off
while e < len(handle.entry):
diff --git a/services/fuse/bin/arv-mount b/services/fuse/bin/arv-mount
index 0f3e871..ed74d95 100755
--- a/services/fuse/bin/arv-mount
+++ b/services/fuse/bin/arv-mount
@@ -7,10 +7,11 @@ import logging
import os
import signal
import subprocess
-import traceback
from arvados_fuse import *
+logger = logging.getLogger('arvados.arv-mount')
+
if __name__ == '__main__':
# Handle command line parameters
parser = argparse.ArgumentParser(
@@ -53,16 +54,15 @@ collections on the server.""")
daemon_ctx = None
# Set up logging.
- # If we're daemonized without a logfile, there's nowhere to log, so don't.
- if args.logfile or (daemon_ctx is None):
- log_conf = {}
- if args.debug:
- log_conf['level'] = logging.DEBUG
- arvados.config.settings()['ARVADOS_DEBUG'] = 'true'
- if args.logfile:
- log_conf['filename'] = args.logfile
- logging.basicConfig(**log_conf)
- logging.debug("arv-mount debugging enabled")
+ arv_logger = logging.getLogger('arvados')
+ if args.logfile:
+ if hasattr(arvados, 'log_handler'):
+ arv_logger.removeHandler(arvados.log_handler)
+ arv_logger.addHandler(logging.FileHandler(args.logfile))
+
+ if args.debug:
+ arv_logger.setLevel(logging.DEBUG)
+ logger.debug("arv-mount debugging enabled")
try:
# Create the request handler
@@ -79,9 +79,8 @@ collections on the server.""")
else:
# Set up the request handler with the 'magic directory' at the root
operations.inodes.add_entry(MagicDirectory(llfuse.ROOT_INODE, operations.inodes))
- except Exception as ex:
- logging.error("arv-mount: exception during API setup")
- logging.error(traceback.format_exc())
+ except Exception:
+ logger.exception("arv-mount: exception during API setup")
exit(1)
# FUSE options, see mount.fuse(8)
@@ -115,8 +114,8 @@ collections on the server.""")
signal.signal(signal.SIGTERM, signal.SIG_DFL)
signal.signal(signal.SIGQUIT, signal.SIG_DFL)
except Exception as e:
- logging.error('arv-mount: exception during exec %s' % (args.exec_args,))
- logging.error(traceback.format_exc())
+ logger.exception('arv-mount: exception during exec %s',
+ args.exec_args)
try:
rc = e.errno
except AttributeError:
@@ -130,6 +129,5 @@ collections on the server.""")
llfuse.init(operations, args.mountpoint, opts)
llfuse.main()
except Exception as e:
- logging.error('arv-mount: exception during mount')
- logging.error(traceback.format_exc())
+ logger.exception('arv-mount: exception during mount')
exit(getattr(e, 'errno', 1))
-----------------------------------------------------------------------
hooks/post-receive
--
More information about the arvados-commits
mailing list