def search_for_new(config, config_file, post_config_file, process_msg,
store_msg, qseq, fastq):
"""Search for any new unreported directories.
"""
reported = _read_reported(config["msg_db"])
for dname in _get_directories(config):
if os.path.isdir(dname) and dname not in reported:
if _is_finished_dumping(dname):
# Injects run_name on logging calls.
# Convenient for run_name on "Subject" for email notifications
with logbook.Processor(lambda record: record.extra.__setitem__(
'run', os.path.basename(dname))):
logger2.info(
"The instrument has finished dumping on directory %s" %
dname)
_update_reported(config["msg_db"], dname)
_process_samplesheets(dname, config)
if qseq:
logger2.info("Generating qseq files for %s" % dname)
_generate_qseq(get_qseq_dir(dname), config)
fastq_dir = None
if fastq:
logger2.info("Generating fastq files for %s" % dname)
fastq_dir = _generate_fastq(dname, config)
_post_process_run(dname, config, config_file, fastq_dir,
post_config_file, process_msg, store_msg)
def __call__(self):
# Find an open port for the logs
# (that's a race condition, deal with it)
tmpsock = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
tmpsock.bind(('localhost', 0))
log_uri = 'tcp://{}:{}'.format(*tmpsock.getsockname())
tmpsock.close()
setup = logbook.NestedSetup([
logbook.NullHandler(),
logbook.StderrHandler(level=logbook.INFO),
logbook.Processor(self._process_record),
])
self.subscriber = ZeroMQSubscriber(log_uri, multi=True)
self.subscriber.dispatch_in_background(setup=setup)
self.process = sh.python(
'-m',
'onitu',
'--entries',
self.entries,
'--log-uri',
log_uri,
_bg=self.bg,
)
return self.process
def request_id_tag_context(title=None, tag=None, logger=None):
"""
Context that adds a request ID tag logging processor.
:param title: title to write in the log when setting a new tag (if a previous tag was not set).
If ``None`` no log message will be generated.
:param tag: tag to set before calling func. If tag is None and no existing tag is set a new random tag will be
created.
:param logger: logger to use, if None use default logger
"""
if logger is None:
logger = get_logger()
prev_tag, new_tag = get_tag(), tag
if new_tag is not None:
set_tag(new_tag)
elif prev_tag is None:
new_tag = new_random_tag()
set_tag(new_tag)
# We create a logbook.Processor context only if we didn't have a previous tag, otherwise there must already
# be a context in place somewhere down the call stack.
with (logbook.Processor(inject_request_id_tag).greenletbound()
if prev_tag is None else _null_context()):
if prev_tag is None and title is not None:
# Log this function since it's our first "tagged" entry to the greenlet
logger.debug("setting new tag {} on greenlet {}".format(
new_tag, title))
try:
yield
finally:
set_tag(prev_tag)
def create_logger(app):
if app.config.get('ENVIRONMENT') == 'production':
server_addr = ('localhost', 25)
else:
server_addr = ('localhost', 2525)
mail_handler = logbook.MailHandler(
'*****@*****.**',
['*****@*****.**'],
server_addr=server_addr,
level='DEBUG',
format_string=u'''Subject: ERROR at gitorama.com
[{record.time:%Y-%m-%d %H:%M}] {record.extra[request_id]}: {record.level_name}: {record.channel}: {record.message}''',
related_format_string=
u'[{record.time:%Y-%m-%d %H:%M}] {record.extra[request_id]}: {record.level_name}: {record.channel}: {record.message}',
)
file_handler = logbook.FileHandler(
app.config['LOG_FILE'],
level='DEBUG',
format_string=
u'[{record.time:%Y-%m-%d %H:%M}] {record.extra[request_id]}: {record.level_name}: {record.channel}: {record.message}'
)
def inject_id(record):
record.extra['request_id'] = getattr(_request_ctx_stack.top,
'logbook_request_id', None)
logger = logbook.NestedSetup([
logbook.NullHandler(),
logbook.FingersCrossedHandler(mail_handler, reset=True),
logbook.FingersCrossedHandler(file_handler, reset=True, bubble=True),
logbook.Processor(inject_id),
])
return logger
def create_processor(plugin_predicate=_true):
"""
Returns a new logbook Processor object that injects to each record's `extra` dict whatever the enabled plugins
choose to put there.
:param plugin_predicate: predicate that chooses which plugins to enable
:returns: logbook.Processor object
"""
return logbook.Processor(create_inject_extra_data(plugin_predicate))
def process_request(self, request):
def inject_info(record):
record.extra.update(
ip=request.META.get('REMOTE_ADDR'),
method=request.method,
absolute_uri=request.build_absolute_uri(),
)
self._processor = logbook.Processor(inject_info)
self._processor.push_application()
def handle_request(request):
def inject_extra(record):
record.extra['ip'] = request.remote_addr
record.extra['method'] = request.method
record.extra['path'] = request.path
with logbook.Processor(inject_extra):
with handler:
try:
1 / 0
except Exception:
self.log.exception('Exception happened during request')
def inject(**params):
"""
A Logbook processor to inject arbitrary information into log records.
Simply pass in keyword arguments and use as a context manager:
>>> with inject(identifier=str(uuid.uuid4())).applicationbound():
... logger.debug('Something happened')
"""
def callback(log_record):
log_record.extra.update(params)
return logbook.Processor(callback)
def main(config_file, fc_dir, run_info_yaml=None):
config = load_config(config_file)
work_dir = os.getcwd()
if config.get("log_dir", None) is None:
config["log_dir"] = os.path.join(work_dir, "log")
def insert_command(record):
record.extra["command"] = sys.argv
record.extra["version"] = version.get_pipeline_version()
setup_logging(config)
handler = create_log_handler(config)
with handler, \
logbook.Processor(insert_command):
run_main(config, config_file, fc_dir, work_dir, run_info_yaml)
def handle_request(request):
def inject_extra(record):
record.extra['ip'] = request.remote_addr
record.extra['method'] = request.method
record.extra['path'] = request.path
processor = logbook.Processor(inject_extra)
with activation_strategy(processor):
handler.push_thread()
try:
try:
1 / 0
except Exception:
logger.exception('Exception happened during request')
finally:
handler.pop_thread()
def search_for_new(*args, **kwargs):
"""Search for any new unreported directories.
"""
config = args[0]
reported = _read_reported(config["msg_db"])
process_all_option = config["algorithm"].get("process_all", False)
for dname in _get_directories(config):
# Only process a directory if it isn't listed in the transfer db or if it was specifically requested
# on the command line
if os.path.isdir(dname) and \
((kwargs.get("run_id",None) is None and not any(dir.startswith(dname) for dir in reported)) or \
kwargs.get("run_id",None) == os.path.basename(dname)):
# Injects run_name on logging calls.
# Convenient for run_name on "Subject" for email notifications
def run_setter(record):
return record.extra.__setitem__('run', os.path.basename(dname))
with logbook.Processor(run_setter):
if kwargs.get("post_process_only",False):
loc_args = (dname, ) + args + (None, )
_post_process_run(*loc_args, **kwargs)
continue
if _do_initial_processing(dname):
initial_processing(dname, *args, **kwargs)
if not process_all_option:
if _do_first_read_processing(dname):
process_first_read(dname, *args, **kwargs)
elif _do_second_read_processing(dname):
process_second_read(dname, *args, **kwargs)
else:
pass
else:
#Process both reads at once in the same machine
if _is_finished_dumping_checkpoint(dname):
process_all(dname, *args, **kwargs)
# Re-read the reported database to make sure it hasn't
# changed while processing.
reported = _read_reported(config["msg_db"])
def _log_messages(self, log_handler, subject="Test email"):
try:
with log_handler.applicationbound():
with logbook.Processor(lambda record: record.extra.__setitem__(
'run', subject)):
logger2.debug("DEBUG record test generated @ %s" %
time.strftime("%x - %X"))
logger2.info("INFO record test generated @ %s" %
time.strftime("%x - %X"))
logger2.notice("NOTICE record test generated @ %s" %
time.strftime("%x - %X"))
logger2.warning("WARNING record test generated @ %s" %
time.strftime("%x - %X"))
logger2.error("ERROR record test generated @ %s" %
time.strftime("%x - %X"))
logger2.critical("CRITICAL record test generated @ %s" %
time.strftime("%x - %X"))
except Exception as e:
return e
return None
def wrapper(*args, **kwargs):
start_time = time.time()
request_id = self.generate_id()
def inject_request_id(record):
record.extra['request_id'] = request_id
with logbook.Processor(inject_request_id):
logbook.notice(self.request_str(), extra={"api": True})
try:
response = callback(*args, **kwargs)
except OperationalError as e:
logbook.warning("Database is down {}: {}",
conf.database.uri,
e,
exc_info=True)
logbook.error("Database is down {}: {}", conf.database.uri,
e)
response = errors.DatabaseIsDown()
except errors.BadRequest as e:
e.format_response()
response = e
except bottle.HTTPResponse as e:
response = e
except Exception as e:
if self.under_test:
import traceback
traceback.print_exc()
logbook.exception(
"Exception during processing request: %s %s" %
(bottle.request.method, bottle.request.path))
self.log_response(str(e), 500, time.time() - start_time)
raise
finally:
from model import db
db.session.remove()
response = self.response_process(response,
time.time() - start_time)
return response
def inner(*args, **kwargs):
try:
if new_session and not conf.test:
db.session.close()
logbook.debug("Start task {} with args: {} {}", fn.__name__,
args, kwargs)
try:
h = "%8x" % abs(hash(args))
except TypeError:
from pprint import pformat
h = hash(pformat(args))
h = "%8x" % abs(h)
request_id = "%s-%s" % (fn.__name__, h[0:4])
def inject_request_id(record):
record.extra['request_id'] = request_id
with logbook.Processor(inject_request_id):
res = fn(*args, **kwargs)
if auto_commit:
db.session.commit()
logbook.debug("Result of task {}: {}", fn.__name__, res)
return res
except OperationalError as operation_error:
logbook.warning("Database is down {}: {}",
conf.database.uri,
operation_error,
exc_info=True)
logbook.error("Database is down {}: {}", conf.database.uri,
operation_error)
db.session.close()
current_task.retry(exc=operation_error,
countdown=calc_exp_countdown())
except Exception as exc:
logbook.warning("{} failed. Retrying...",
fn.__name__,
exc_info=True)
current_task.retry(exc=exc, countdown=calc_exp_countdown())
def dummy(self):
with logbook.Processor(self.tag_progress):
logger2.info("HACK")
def progress(self, action):
self.step += 1
self._timestamp_file(action)
with logbook.Processor(self.tag_progress):
logger2.info(action)
def process_request(self, request):
"""the main request processing. Gets a :class:`~starflyer.Request` as input and
returns an instance of :class:`~starflyer.Response`. In case of an exception
this will be handled as well
"""
handler = None
# check if we are the first request ever for this application
self.check_first_request(request)
# helper for injecting data into the log record
def inject(record):
"""the injection callback for any log record"""
record.extra['url'] = request.url
record.extra['method'] = request.method
record.extra['ip'] = request.remote_addr
record.hid = id(request)
# TODO: add a hook for adding more information
# use the log context to actually call the handler
with self.setup_logger():
with logbook.Processor(inject):
try:
# find the handler
handler = self.find_handler(request)
# run the before_handler hooks from app and modules
if handler.use_hooks:
for module in self.modules:
rv = module.before_handler(handler)
if rv is not None:
return rv
rv = self.before_handler(handler)
if rv is not None:
return rv
# in case we are in testing mode remember the last used handler
if self.config.testing:
self.last_handler = handler
# call the handler and receive the response
response = handler(**request.view_args)
if handler.use_hooks:
for module in self.modules:
rv = module.after_handler(
handler, response
) # hook for post processing a resposne
if rv is not None:
return rv
rv = self.after_handler(
handler,
response) # hook for post processing a resposne
if rv is not None:
return rv
except Exception, e:
response = self.handle_user_exception(request, e)
# now save the session after the after handlers might have changed it
if handler and not self.session_interface.is_null_session(
handler.session):
self.save_session(handler.session, response)
def report_to_statusdb(fc_name, fc_date, run_info_yaml, dirs, config):
"""
Create statusdb report on a couchdb server.
A FlowcellQCMetrics object holds information about a flowcell. QC
results are stored at the flowcell level and sample level
depending on analysis. Lane level QC data are stored in the
FlowcellQCMetrics object.
"""
success = True
try:
statusdb_config = config.get("statusdb", None)
if statusdb_config is None:
log.info(
"Could not find statusdb section in configuration. No statusdb reporting will be done"
)
return False
statusdb_url = statusdb_config.get("url", None)
if statusdb_url is None:
log.warn("No url field found in statusdb configuration section.")
return False
# Add email notification
email = statusdb_config.get("statusdb_email_notification", None)
smtp_host = config.get("smtp_host", "")
smtp_port = config.get("smtp_port", "")
log_handler = create_log_handler(
{
'email': email,
'smtp_host': smtp_host,
'smtp_port': smtp_port
}, True)
with log_handler.applicationbound():
with logbook.Processor(lambda record: record.extra.__setitem__(
'run', "%s_%s" % (fc_date, fc_name))):
log.info(
"Started creating QC Metrics report on statusdb for %s_%s on %s"
% (fc_date, fc_name, datetime.now().isoformat()))
# Create object and parse all available metrics; no checking
# is currently done for missing files
try:
qc_obj = FlowcellQCMetrics(fc_date, fc_name, run_info_yaml,
dirs.get("work", None),
dirs.get("flowcell", None))
except:
qc_obj = None
# FIXME: error checking!
if qc_obj is not None:
try:
# Save data at a sample level
log.info("Connecting to server at %s" % statusdb_url)
try:
couch = couchdb.Server(url="http://%s" %
statusdb_url)
except:
log.warn("Connecting to server at %s failed" %
statusdb_url)
log.info("Connecting to server at %s succeeded" %
statusdb_url)
db = couch['qc']
# Save samples
for s in qc_obj.sample.keys():
obj = qc_obj.sample[s]
log.info("Saving sample %s" % obj.name())
_save_obj(db, obj, statusdb_url)
# Save flowcell object
_save_obj(db, qc_obj, statusdb_url)
except Exception as e:
success = False
else:
log.warn(
"Couldn't populate FlowcellQCMetrics object. No QC data written to statusdb for %s_%s"
% (fc_date, fc_name))
success = False
if success:
log.info("QC Metrics report successfully written to statusdb for %s_%s on %s" \
% (fc_date, fc_name, datetime.now().isoformat()))
else:
log.warn("Encountered exception when writing to statusdb for %s_%s on %s" \
% (fc_date, fc_name, datetime.now().isoformat()))
except Exception as e:
success = False
log.warn(
"Encountered exception when writing QC metrics to statusdb: %s" %
e)
return success
def main(input_path, transferred_db, run_folder, uppnexid, samplesheet, logfile, email_notification, config_file, force, dryrun):
config = {}
if config_file is not None:
config = load_config(config_file)
if logfile is None:
logfile = config.get("logfile",os.path.normpath(os.path.expanduser(DEFAULT_LOGFILE)))
email_handler = None
# Don't write dry runs to log
if dryrun:
handler = logbook.StreamHandler(sys.stdout)
else:
if not os.path.exists(logfile):
safe_makedir(os.path.dirname(logfile))
open(logfile,"w").close()
handler = logbook.FileHandler(logfile)
if email_notification is None:
email_notification = config.get("email_recipient",DEFAULT_RECIPIENT)
recipients = email_notification.split(",")
if len(recipients) > 0:
email_handler = logbook.MailHandler("*****@*****.**", recipients,
server_addr=[config.get("smtp_host",DEFAULT_SMTP_HOST),config.get("smtp_port",DEFAULT_SMTP_PORT)],
format_string=u'''Subject: [MiSeq delivery] {record.extra[run]}\n\n {record.message}''')
with handler.applicationbound():
if dryrun:
logger2.info("This is just a dry-run. Nothing will be delivered and no directories will be created/changed")
# If no run folder was specified, try with the folders in the input_path
if run_folder is None:
pat = "*_M*_AMS*"
folders = [os.path.relpath(os.path.normpath(file),input_path) for file in glob.glob(os.path.join(input_path,pat))]
else:
run_folder = os.path.basename(os.path.normpath(run_folder))
assert os.path.exists(os.path.join(input_path,run_folder)), "The specified run folder %s does not seem to exist in the %s folder" % (run_folder, input_path)
folders = [run_folder]
logger2.info("Will process %s folders: %s" % (len(folders),folders))
# Parse the supplied db of transferred flowcells, or a db in the default location if present
if transferred_db is None:
transferred_db = os.path.normpath(config.get("transfer_db",os.path.expanduser(DEFAULT_DB)))
assert os.path.exists(transferred_db), "Could not locate transferred_db (expected %s)" % transferred_db
logger2.info("Transferred db is %s" % transferred_db)
# Process each run folder
for folder in folders:
try:
# Skip this folder if it has already been processed
logger2.info("Processing %s" % folder)
if _is_processed(folder,transferred_db) and not force:
logger2.info("%s has already been processed, skipping" % folder)
continue
# Locate the samplesheet and pasre the uppnex id if necessary
if uppnexid is None:
local_samplesheet = samplesheet
if local_samplesheet is None: local_samplesheet = os.path.join(input_path,folder,config.get("samplesheet_name",DEFAULT_SS_NAME))
assert os.path.exists(local_samplesheet), "Could not find expected sample sheet %s" % local_samplesheet
local_uppnexid = _fetch_uppnexid(local_samplesheet, config.get("uppnexid_field",DEFAULT_UPPNEXID_FIELD))
assert local_uppnexid is not None and len(local_uppnexid) > 0, "Could not parse Uppnex ID for project from samplesheet %s" % local_samplesheet
else:
local_uppnexid = uppnexid
logger2.info("Will deliver to inbox of project %s" % local_uppnexid)
# Locate the fastq-files to be delivered
pat = os.path.join(input_path,folder,config.get("fastq_path",DEFAULT_FQ_LOCATION),"*.fastq.gz")
fq_files = glob.glob(pat)
# Also search directly in the folder
pat = os.path.join(input_path,folder,"*.fastq.gz")
fq_files.extend(glob.glob(pat))
assert len(fq_files) > 0, "Could not locate fastq files for folder %s using pattern %s" % (folder,pat)
logger2.info("Found %s fastq files to deliver: %s" % (len(fq_files),fq_files))
if dryrun:
logger2.info("Remember that this is a dry-run. Nothing will be delivered and no directories will be created/changed")
# Create the destination directory if required
dest_dir = os.path.normpath(os.path.join(config.get("project_root",DEFAULT_PROJECT_ROOT),local_uppnexid,"INBOX",folder,"fastq"))
_update_processed(folder,transferred_db,dryrun)
assert _create_destination(dest_dir, dryrun), "Could not create destination %s" % dest_dir
assert _deliver_files(fq_files,dest_dir, dryrun), "Could not transfer files to destination %s" % dest_dir
assert _verify_files(fq_files,dest_dir,dryrun), "Integrity of files in destination directory %s could not be verified. Please investigate" % dest_dir
assert _set_permissions(dest_dir, dryrun), "Could not change permissions on destination %s" % dest_dir
if email_handler is not None:
with email_handler.applicationbound():
with logbook.Processor(lambda record: record.extra.__setitem__('run', folder)):
logger2.info("The MiSeq sequence data for run %s was successfully delivered to the inbox of Uppnex project %s (%s)" % (folder,local_uppnexid,dest_dir))
except AssertionError as e:
logger2.error("Could not deliver data from folder %s. Reason: %s. Please fix problems and retry." % (folder,e))
logger2.info("Rolling back changes to %s" % transferred_db)
_update_processed(folder,transferred_db,dryrun,True)
def create_report_on_gdocs(fc_date, fc_name, run_info_yaml, dirs, config):
"""Create reports on gdocs containing both demultiplexed read counts and QC data.
"""
success = True
try:
# Inject the fc_date and fc_name in the email subject
def record_processor(record):
return record.extra.__setitem__('run',
"%s_%s" % (fc_date, fc_name))
# Parse the run_info.yaml file
log.debug("Loading this run_info: {}".format(run_info_yaml))
with open(run_info_yaml, "r") as fh:
run_info = yaml.load(fh)
# Get the gdocs account credentials
encoded_credentials = get_credentials(config)
if not encoded_credentials:
log.warn(
"Could not find Google Docs account credentials in configuration. \
No sequencing report was written")
return False
# Get the required parameters from the post_process.yaml configuration file
gdocs = config.get("gdocs_upload", None)
# Add email notification
email = gdocs.get("gdocs_email_notification", None)
smtp_host = config.get("smtp_host", "")
smtp_port = config.get("smtp_port", "")
log_handler = create_log_handler({'email': email, \
'smtp_host': smtp_host, \
'smtp_port': smtp_port}, True)
except Exception as e:
success = False
log.warn(
"Encountered exception when writing sequencing report to Google Docs: %s"
% e)
with log_handler.applicationbound(), logbook.Processor(record_processor):
try:
log.info("Started creating sequencing report on Google docs for %s_%s on %s" \
% (fc_date, fc_name, datetime.datetime.now().isoformat()))
# Get a flowcell object
fc = Flowcell(fc_name, fc_date, run_info, dirs.get("work", None))
# Get the GDocs demultiplex result file title
gdocs_dmplx_spreadsheet = gdocs.get("gdocs_dmplx_file", None)
# Get the GDocs QC file title
gdocs_qc_spreadsheet = gdocs.get("gdocs_qc_file", None)
# FIXME: Make the bc stuff use the Flowcell module
if gdocs_dmplx_spreadsheet is not None:
# Upload the data
bc_metrics.write_run_report_to_gdocs(fc, fc_date, \
fc_name, gdocs_dmplx_spreadsheet, encoded_credentials, append=True)
else:
log.warn("Could not find Google Docs demultiplex results file \
title in configuration. No demultiplex counts were \
written to Google Docs for %s_%s" % (fc_date, fc_name))
# Parse the QC metrics
try:
qc = RTAQCMetrics(dirs.get("flowcell", None))
except:
qc = None
if gdocs_qc_spreadsheet is not None and qc is not None:
qc_metrics.write_run_report_to_gdocs(fc, qc,
gdocs_qc_spreadsheet,
encoded_credentials)
else:
log.warn("Could not find Google Docs QC file title in configuration. " \
"No QC data were written to Google Docs " \
"for %s_%s".format(fc_date, fc_name))
# Get the projects parent folder
projects_folder = gdocs.get("gdocs_projects_folder", None)
# Write the bc project summary report
if projects_folder is not None:
create_project_report_on_gdocs(fc, qc, \
encoded_credentials, projects_folder)
except Exception as e:
success = False
log.warn("Encountered exception when writing sequencing report " \
"to Google Docs: {}".format(e))
if success:
log.info("Sequencing report successfully created on Google " \
"docs for {}_{} on {}".format(fc_date, fc_name, datetime.datetime.now().isoformat()))
else:
log.warn("Encountered exception when writing sequencing " \
"report for %s_%s to Google docs on %s" \
% (fc_date, fc_name, datetime.datetime.now().isoformat()))
return success
def _process_test_record(self):
return logbook.Processor(self._add_current_test)
def wrapped(address, *a):
with logbook.Processor(inject_address).threadbound():
return func(address, *a)
