def __exit__(self, exc_type, exc_val, exc_tb):
if self.debug:
try:
gc.collect()
end_memory = self.process.memory_info().rss
net_memory = end_memory-self.start_memory
if net_memory > 100 * 1000 * 1000:
Log.warning(
"MEMORY WARNING (additional {{net_memory|comma}}bytes): "+self.description,
default_params=self.params,
net_memory=net_memory
)
from pympler import summary
from pympler import muppy
sum1 = sorted(summary.summarize(muppy.get_objects()), key=lambda r: -r[2])[:30]
Log.warning("{{data}}", data=sum1)
elif end_memory > 1000*1000*1000:
Log.warning(
"MEMORY WARNING (over {{end_memory|comma}}bytes): "+self.description,
default_params=self.params,
end_memory=end_memory
)
from pympler import summary
from pympler import muppy
sum1 = sorted(summary.summarize(muppy.get_objects()), key=lambda r: -r[2])[:30]
Log.warning("{{data}}", data=sum1)
except Exception as e:
Log.warning("problem in memory measure", cause=e)
def _send_email(self):
try:
if not self.accumulation:
return
with Emailer(self.settings) as emailer:
# WHO ARE WE SENDING TO
emails = Data()
for template, params in self.accumulation:
content = expand_template(template, params)
emails[literal_field(self.settings.to_address)] += [content]
for c in self.cc:
if any(d in params.params.error for d in c.contains):
emails[literal_field(c.to_address)] += [content]
# SEND TO EACH
for to_address, content in emails.items():
emailer.send_email(
from_address=self.settings.from_address,
to_address=listwrap(to_address),
subject=self.settings.subject,
text_data="\n\n".join(content)
)
self.accumulation = []
except Exception as e:
Log.warning("Could not send", e)
finally:
self.next_send = Date.now() + self.settings.average_interval * (2 * Random.float())
def go(self):
"""
ACTIVATE SIGNAL (DOES NOTHING IF SIGNAL IS ALREADY ACTIVATED)
"""
DEBUG and self._name and Log.note("GO! {{name|quote}}", name=self.name)
if self._go:
return
with self.lock:
if self._go:
return
self._go = True
DEBUG and self._name and Log.note("internal GO! {{name|quote}}", name=self.name)
jobs, self.job_queue = self.job_queue, None
threads, self.waiting_threads = self.waiting_threads, None
if threads:
DEBUG and self._name and Log.note("Release {{num}} threads", num=len(threads))
for t in threads:
t.release()
if jobs:
for j in jobs:
try:
j()
except Exception as e:
Log.warning("Trigger on Signal.go() failed!", cause=e)
def wait(self, till=None):
"""
THE ASSUMPTION IS wait() WILL ALWAYS RETURN WITH THE LOCK ACQUIRED
:param till: WHEN TO GIVE UP WAITING FOR ANOTHER THREAD TO SIGNAL
:return: True IF SIGNALED TO GO, False IF till WAS SIGNALED
"""
waiter = Signal()
if self.waiting:
DEBUG and _Log.note("waiting with {{num}} others on {{name|quote}}", num=len(self.waiting), name=self.name, stack_depth=1)
self.waiting.insert(0, waiter)
else:
DEBUG and _Log.note("waiting by self on {{name|quote}}", name=self.name)
self.waiting = [waiter]
try:
self.lock.release()
DEBUG and _Log.note("out of lock {{name|quote}}", name=self.name)
(waiter | till).wait()
if DEBUG:
_Log.note("done minimum wait (for signal {{till|quote}})", till=till.name if till else "", name=self.name)
except Exception as e:
if not _Log:
_late_import()
_Log.warning("problem", cause=e)
finally:
self.lock.acquire()
DEBUG and _Log.note("re-acquired lock {{name|quote}}", name=self.name)
try:
self.waiting.remove(waiter)
DEBUG and _Log.note("removed own signal from {{name|quote}}", name=self.name)
except Exception:
pass
return bool(waiter)
def pypy_json_encode(value, pretty=False):
"""
pypy DOES NOT OPTIMIZE GENERATOR CODE WELL
"""
global _dealing_with_problem
if pretty:
return pretty_json(value)
try:
_buffer = UnicodeBuilder(2048)
_value2json(value, _buffer)
output = _buffer.build()
return output
except Exception as e:
# THE PRETTY JSON WILL PROVIDE MORE DETAIL ABOUT THE SERIALIZATION CONCERNS
from mo_logs import Log
if _dealing_with_problem:
Log.error("Serialization of JSON problems", e)
else:
Log.warning("Serialization of JSON problems", e)
_dealing_with_problem = True
try:
return pretty_json(value)
except Exception as f:
Log.error("problem serializing object", f)
finally:
_dealing_with_problem = False
def __init__(self, query_path, snowflake):
if not is_list(snowflake.query_paths[0]):
Log.error("Snowflake query paths should be a list of string tuples (well, technically, a list of lists of strings)")
self.snowflake = snowflake
try:
path = [
p
for p in snowflake.query_paths
if untype_path(p[0]) == query_path
]
if path:
# WE DO NOT NEED TO LOOK INTO MULTI-VALUED FIELDS AS A TABLE
self.multi = None
self.query_path = path[0]
else:
# LOOK INTO A SPECIFIC MULTI VALUED COLUMN
try:
self.multi = [
c
for c in self.snowflake.columns
if untype_path(c.name) == query_path and c.multi > 1
][0]
self.query_path = [self.multi.name] + self.multi.nested_path
except Exception as e:
# PROBLEM WITH METADATA UPDATE
self.multi = None
self.query_path = [query_path] + ["."]
Log.warning("Problem getting query path {{path|quote}} in snowflake {{sf|quote}}", path=query_path, sf=snowflake.name, cause=e)
if not is_list(self.query_path) or self.query_path[len(self.query_path) - 1] != ".":
Log.error("error")
except Exception as e:
Log.error("logic error", cause=e)
def _got_result(self, data, message):
global count
data = wrap(data)
with count_locker:
Log.note("{{count}} from {{exchange}}", count=count, exchange=self.pulse.exchange)
data._meta.count = count
data._meta.exchange = self.pulse.exchange
count += 1
if self.settings.debug:
Log.note("{{data}}", data=data)
if self.target_queue != None:
try:
self.target_queue.add(data)
message.ack()
except Exception as e:
e = Except.wrap(e)
if not self.target_queue.closed: # EXPECTED TO HAPPEN, THIS THREAD MAY HAVE BEEN AWAY FOR A WHILE
raise e
else:
try:
self.pulse_target(data)
message.ack()
except Exception as e:
Log.warning("Problem processing pulse (see `data` in structured log)", data=data, cause=e)
def _worker(self, please_stop):
while not please_stop:
pair = self.requests.pop(till=please_stop)
if please_stop:
break
ready, method, path, req_headers, timestamp = pair
try:
url = self.url / path
self.outbound_rate.add(Date.now())
response = http.request(method, url, req_headers)
del response.headers['transfer-encoding']
resp_headers = value2json(response.headers)
resp_content = response.raw.read()
please_cache = self.please_cache(path)
if please_cache:
with self.db.transaction() as t:
t.execute("INSERT INTO cache (path, headers, response, timestamp) VALUES" + quote_list((path, resp_headers, resp_content.decode('latin1'), timestamp)))
with self.cache_locker:
self.cache[path] = (ready, resp_headers, resp_content, timestamp)
except Exception as e:
Log.warning("problem with request to {{path}}", path=path, cause=e)
with self.cache_locker:
ready, headers, response = self.cache[path]
del self.cache[path]
finally:
ready.go()
def not_monitor(self, please_stop):
Log.alert("metadata scan has been disabled")
please_stop.on_go(lambda: self.todo.add(THREAD_STOP))
while not please_stop:
column = self.todo.pop()
if column == THREAD_STOP:
break
if column.jx_type in STRUCT or split_field(column.es_column)[-1] == EXISTS_TYPE:
DEBUG and Log.note("{{column.es_column}} is a struct", column=column)
column.last_updated = Date.now()
continue
elif column.last_updated > Date.now() - TOO_OLD and column.cardinality is not None:
# DO NOT UPDATE FRESH COLUMN METADATA
DEBUG and Log.note("{{column.es_column}} is still fresh ({{ago}} ago)", column=column, ago=(Date.now()-Date(column.last_updated)).seconds)
continue
with Timer("Update {{col.es_index}}.{{col.es_column}}", param={"col": column}, silent=not DEBUG, too_long=0.05):
if untype_path(column.name) in ["build.type", "run.type"]:
try:
self._update_cardinality(column)
except Exception as e:
Log.warning("problem getting cardinality for {{column.name}}", column=column, cause=e)
else:
column.last_updated = Date.now()
def _worker(start):
output = SchemaTree()
root = parquet_schema_list[off.set]
output.element = root
max = start + coalesce(root.num_children, 0)
if off.set == 0:
if root.name not in ['.', 'schema', 'spark_schema', 'm', 'hive_schema', 'root']: # some known root names
Log.warning("first SchemaElement is given name {{name|quote}}, name is ignored", name=root.name)
root.name = '.'
root.repetition_type = REQUIRED
while off.set < max:
off.set += 1
child = _worker(off.set)
parent = output
path = relative_field(child.element.name, root.name)
# path = split_field(relative_field(child.element.name, root.name))
# for i, p in enumerate(path[:-1]):
# new_parent = parent.more[p] = SchemaTree()
# new_parent.element = SchemaElement(
# name=concat_field(root.name, join_field(path[:i+1])),
# repetition_type=REQUIRED
# )
# parent = new_parent
# parent.more[path[-1]] = child
parent.more[path] = child
return output
def main():
try:
settings = startup.read_settings()
Log.start(settings.debug)
with SingleInstance(flavor_id=settings.args.filename):
constants.set(settings.constants)
settings.run_interval = Duration(settings.run_interval)
for u in settings.utility:
u.discount = coalesce(u.discount, 0)
# MARKUP drives WITH EXPECTED device MAPPING
num_ephemeral_volumes = ephemeral_storage[u.instance_type]["num"]
for i, d in enumerate(d for d in u.drives if not d.device):
letter = convert.ascii2char(98 + num_ephemeral_volumes + i)
d.device = "/dev/xvd" + letter
settings.utility = UniqueIndex(["instance_type"], data=settings.utility)
instance_manager = new_instance(settings.instance)
m = SpotManager(instance_manager, kwargs=settings)
if ENABLE_SIDE_EFFECTS:
m.update_spot_requests(instance_manager.required_utility())
if m.watcher:
m.watcher.join()
except Exception as e:
Log.warning("Problem with spot manager", cause=e)
finally:
Log.stop()
MAIN_THREAD.stop()
def write(self, template, params):
try:
with self.file_lock:
self.file.append(expand_template(template, params))
except Exception as e:
Log.warning("Problem writing to file {{file}}, waiting...", file=file.name, cause=e)
time.sleep(5)
def __exit__(self, type, value, traceback):
try:
self.server.quit()
except Exception as e:
Log.warning("Problem with smtp server quit(), ignoring problem", e)
self.server = None
def _send_email(self):
try:
if not self.accumulation:
return
with Closer(connect_to_region(
self.settings.region,
aws_access_key_id=unwrap(self.settings.aws_access_key_id),
aws_secret_access_key=unwrap(self.settings.aws_secret_access_key)
)) as conn:
# WHO ARE WE SENDING TO
emails = Data()
for template, params in self.accumulation:
content = expand_template(template, params)
emails[literal_field(self.settings.to_address)] += [content]
for c in self.cc:
if any(c in params.params.error for c in c.contains):
emails[literal_field(c.to_address)] += [content]
# SEND TO EACH
for to_address, content in emails.items():
conn.send_email(
source=self.settings.from_address,
to_addresses=listwrap(to_address),
subject=self.settings.subject,
body="\n\n".join(content),
format="text"
)
self.next_send = Date.now() + self.settings.max_interval
self.accumulation = []
except Exception as e:
self.next_send = Date.now() + self.settings.max_interval
Log.warning("Could not send", e)
def __init__(self, conn=None, tuid_service=None, start_workers=True, new_table=False, kwargs=None):
try:
self.config = kwargs
self.conn = conn if conn else sql.Sql(self.config.database.name)
self.hg_cache = HgMozillaOrg(kwargs=self.config.hg_cache, use_cache=True) if self.config.hg_cache else Null
self.tuid_service = tuid_service if tuid_service else tuid.service.TUIDService(
kwargs=self.config.tuid, conn=self.conn, clogger=self
)
self.rev_locker = Lock()
self.working_locker = Lock()
if new_table:
with self.conn.transaction() as t:
t.execute("DROP TABLE IF EXISTS csetLog")
self.init_db()
self.next_revnum = coalesce(self.conn.get_one("SELECT max(revnum)+1 FROM csetLog")[0], 1)
self.csets_todo_backwards = Queue(name="Clogger.csets_todo_backwards")
self.deletions_todo = Queue(name="Clogger.deletions_todo")
self.maintenance_signal = Signal(name="Clogger.maintenance_signal")
if 'tuid' in self.config:
self.config = self.config.tuid
self.disable_backfilling = False
self.disable_tipfilling = False
self.disable_deletion = False
self.disable_maintenance = False
self.backfill_thread = None
self.tipfill_thread = None
self.deletion_thread = None
self.maintenance_thread = None
# Make sure we are filled before allowing queries
numrevs = self.conn.get_one("SELECT count(revnum) FROM csetLog")[0]
if numrevs < MINIMUM_PERMANENT_CSETS:
Log.note("Filling in csets to hold {{minim}} csets.", minim=MINIMUM_PERMANENT_CSETS)
oldest_rev = 'tip'
with self.conn.transaction() as t:
tmp = t.query("SELECT min(revnum), revision FROM csetLog").data[0][1]
if tmp:
oldest_rev = tmp
self._fill_in_range(
MINIMUM_PERMANENT_CSETS - numrevs,
oldest_rev,
timestamp=False
)
Log.note(
"Table is filled with atleast {{minim}} entries.",
minim=MINIMUM_PERMANENT_CSETS
)
if start_workers:
self.start_workers()
except Exception as e:
Log.warning("Cannot setup clogger: {{cause}}", cause=str(e))
def copy(self, keys, source, sample_only_filter=None, sample_size=None, done_copy=None):
"""
:param keys: THE KEYS TO LOAD FROM source
:param source: THE SOURCE (USUALLY S3 BUCKET)
:param sample_only_filter: SOME FILTER, IN CASE YOU DO NOT WANT TO SEND EVERYTHING
:param sample_size: FOR RANDOM SAMPLE OF THE source DATA
:param done_copy: CALLBACK, ADDED TO queue, TO FINISH THE TRANSACTION
:return: LIST OF SUB-keys PUSHED INTO ES
"""
num_keys = 0
queue = None
pending = [] # FOR WHEN WE DO NOT HAVE QUEUE YET
for key in keys:
timer = Timer("Process {{key}}", param={"key": key})
try:
with timer:
for rownum, line in enumerate(source.read_lines(strip_extension(key))):
if not line:
continue
if rownum > 0 and rownum % 1000 == 0:
Log.note("Ingested {{num}} records from {{key}} in bucket {{bucket}}", num=rownum, key=key, bucket=source.name)
row, please_stop = fix(rownum, line, source, sample_only_filter, sample_size)
num_keys += 1
if queue == None:
queue = self._get_queue(row)
if queue == None:
pending.append(row)
if len(pending) > 1000:
self._get_queue(row)
Log.error("first 1000 (key={{key}}) records have no indication what index to put data", key=tuple(keys)[0])
continue
elif queue is DATA_TOO_OLD:
break
if pending:
queue.extend(pending)
pending = []
queue.add(row)
if please_stop:
break
except Exception as e:
done_copy = None
Log.warning("Could not process {{key}} after {{duration|round(places=2)}}seconds", key=key, duration=timer.duration.seconds, cause=e)
if done_copy:
if queue == None:
done_copy()
else:
queue.add(done_copy)
if pending:
Log.error("Did not find an index to place the data for key={{key}}", key=tuple(keys)[0])
Log.note("{{num}} keys from {{key|json}} added", num=num_keys, key=keys)
return num_keys
def __enter__(self):
if self.debug:
try:
gc.collect()
self.start_memory = self.process.memory_info().rss
except Exception as e:
Log.warning("problem in memory measure", cause=e)
return self
def run(self, *args, **kwargs):
# ENSURE THE LOGGING IS CLEANED UP
try:
Flask.run(self, *args, **kwargs)
except BaseException as e: # MUST CATCH BaseException BECAUSE argparse LIKES TO EXIT THAT WAY, AND gunicorn WILL NOT REPORT
Log.warning("TUID service shutdown!", cause=e)
finally:
Log.stop()
def fill_forward_continuous(self, please_stop=None):
while not please_stop:
try:
while not please_stop and not self.disable_tipfilling and self.update_tip():
pass
(please_stop | Till(seconds=CSET_TIP_WAIT_TIME)).wait()
except Exception as e:
Log.warning("Unknown error occurred during tip filling:", cause=e)
def create_index(
self,
index,
alias=None,
create_timestamp=None,
schema=None,
limit_replicas=None,
read_only=False,
tjson=False,
kwargs=None
):
if not alias:
alias = kwargs.alias = kwargs.index
index = kwargs.index = proto_name(alias, create_timestamp)
if kwargs.alias == index:
Log.error("Expecting index name to conform to pattern")
if kwargs.schema_file:
Log.error('schema_file attribute not supported. Use {"$ref":<filename>} instead')
if schema == None:
Log.error("Expecting a schema")
elif isinstance(schema, basestring):
schema = mo_json.json2value(schema, leaves=True)
else:
schema = mo_json.json2value(convert.value2json(schema), leaves=True)
if limit_replicas:
# DO NOT ASK FOR TOO MANY REPLICAS
health = self.get("/_cluster/health")
if schema.settings.index.number_of_replicas >= health.number_of_nodes:
Log.warning("Reduced number of replicas: {{from}} requested, {{to}} realized",
{"from": schema.settings.index.number_of_replicas},
to= health.number_of_nodes - 1
)
schema.settings.index.number_of_replicas = health.number_of_nodes - 1
self.post(
"/" + index,
data=schema,
headers={"Content-Type": "application/json"}
)
# CONFIRM INDEX EXISTS
while True:
try:
state = self.get("/_cluster/state", retry={"times": 5}, timeout=3)
if index in state.metadata.indices:
break
Log.note("Waiting for index {{index}} to appear", index=index)
except Exception as e:
Log.warning("Problem while waiting for index {{index}} to appear", index=index, cause=e)
Till(seconds=1).wait()
Log.alert("Made new index {{index|quote}}", index=index)
es = Index(kwargs=kwargs)
return es
def current():
ident = get_ident()
with ALL_LOCK:
output = ALL.get(ident)
if output is None:
Log.warning("this thread is not known. Register this thread at earliest known entry point.")
return BaseThread(get_ident())
return output
def __getslice__(self, i, j):
global _emit_slice_warning
if _emit_slice_warning:
_emit_slice_warning = False
if not Log:
_late_import()
Log.warning("slicing is broken in Python 2.7: a[i:j] == a[i+len(a), j] sometimes. Use [start:stop:step] (see https://github.com/klahnakoski/pyLibrary/blob/master/pyLibrary/dot/README.md#the-slice-operator-in-python27-is-inconsistent)")
return self[i:j:]
def main():
try:
settings = startup.read_settings()
constants.set(settings.constants)
Log.start(settings.debug)
ETL(settings).setup(settings.instance, settings.utility)
except Exception as e:
Log.warning("Problem with setup of ETL", cause=e)
finally:
Log.stop()
def _kill(self):
try:
self.service.kill()
except Exception as e:
ee = Except.wrap(e)
if 'The operation completed successfully' in ee:
return
if 'No such process' in ee:
return
Log.warning("Failure to kill process {{process|quote}}", process=self.name, cause=ee)
def get_logger():
global _Log
if _Log:
return _Log
try:
from mo_logs import Log as _Log
return _Log
except Exception as e:
_Log = PoorLogger()
_Log.warning("`pip install mo-logs` for better logging.", cause=e)
return _Log
def stop_main_thread(*args):
"""
CLEAN OF ALL THREADS CREATED WITH THIS LIBRARY
"""
try:
if len(args) and args[0]:
Log.warning("exit with {{value}}", value=_describe_exit_codes.get(args[0], args[0]))
except Exception as _:
pass
finally:
MAIN_THREAD.stop()
def __iter__(self):
"""
BLOCKING ITERATOR
"""
while not self.please_stop:
try:
value = self.pop()
if value is not THREAD_STOP:
yield value
except Exception as e:
Log.warning("Tell me about what happened here", cause=e)
def __getitem__(self, item):
c = self.get_columns(table_name=self.name, column_name=item)
if c:
if len(c) > 1:
Log.error("Do not know how to handle multipole matches")
return c[0]
e = self.edges[item]
if not c:
Log.warning("Column with name {{column|quote}} can not be found in {{table}}", column=item, table=self.name)
return e
def output(*args, **kwargs):
while True:
try:
return func(*args, **kwargs)
except Exception as e:
e = Except.wrap(e)
if "Request limit exceeded" in e:
Log.warning("AWS Problem", cause=e)
continue
else:
Log.error("Problem with call to AWS", cause=e)
def monitor(self, please_stop):
please_stop.on_go(lambda: self.todo.add(THREAD_STOP))
while not please_stop:
try:
if not self.todo:
old_columns = [
c
for c in self.meta.columns
if (c.last_updated == None or c.last_updated < Date.now()-TOO_OLD) and c.jx_type not in STRUCT
]
if old_columns:
DEBUG and Log.note(
"Old columns {{names|json}} last updated {{dates|json}}",
names=wrap(old_columns).es_column,
dates=[Date(t).format() for t in wrap(old_columns).last_updated]
)
self.todo.extend(old_columns)
# TEST CONSISTENCY
for c, d in product(list(self.todo.queue), list(self.todo.queue)):
if c.es_column == d.es_column and c.es_index == d.es_index and c != d:
Log.error("")
else:
DEBUG and Log.note("no more metatdata to update")
column = self.todo.pop(Till(seconds=(10*MINUTE).seconds))
if column:
if column is THREAD_STOP:
continue
with Timer("update {{table}}.{{column}}", param={"table": column.es_index, "column": column.es_column}, silent=not DEBUG):
if column.es_index in self.index_does_not_exist:
self.meta.columns.update({
"clear": ".",
"where": {"eq": {"es_index": column.es_index}}
})
continue
if column.jx_type in STRUCT or column.es_column.endswith("." + EXISTS_TYPE):
column.last_updated = Date.now()
continue
elif column.last_updated >= Date.now()-TOO_OLD:
continue
try:
self._update_cardinality(column)
(DEBUG and not column.es_index.startswith(TEST_TABLE_PREFIX)) and Log.note("updated {{column.name}}", column=column)
except Exception as e:
if '"status":404' in e:
self.meta.columns.update({
"clear": ".",
"where": {"eq": {"es_index": column.es_index, "es_column": column.es_column}}
})
else:
Log.warning("problem getting cardinality for {{column.name}}", column=column, cause=e)
except Exception as e:
Log.warning("problem in cardinality monitor", cause=e)
def _daemon(self, please_stop):
while not please_stop:
with Explanation("looking for work"):
try:
branch, revisions, after = self.todo.pop(till=please_stop)
except Exception as e:
if please_stop:
break
else:
raise e
if branch.name in DAEMON_DO_NO_SCAN:
continue
revisions = set(revisions)
# FIND THE REVSIONS ON THIS BRANCH
for r in list(revisions):
try:
rev = self.get_revision(
Revision(branch=branch, changeset={"id": r}), None,
False, True, None)
if DAEMON_DEBUG:
Log.note(
"found revision with push date {{date|datetime}}",
date=rev.push.date,
)
revisions.discard(r)
if rev.etl.timestamp > Date.now() - (
DAEMON_RECENT_HG_PULL * SECOND):
# SOME PUSHES ARE BIG, RUNNING THE RISK OTHER MACHINES ARE
# ALSO INTERESTED AND PERFORMING THE SAME SCAN. THIS DELAY
# WILL HAVE SMALL EFFECT ON THE MAJORITY OF SMALL PUSHES
# https://bugzilla.mozilla.org/show_bug.cgi?id=1417720
Till(seconds=Random.float(DAEMON_HG_INTERVAL *
2)).wait()
except Exception as e:
Log.warning(
"Scanning {{branch}} {{revision|left(12)}}",
branch=branch.name,
revision=r,
cause=e,
)
if "Read timed out" in e:
Till(seconds=DAEMON_WAIT_AFTER_TIMEOUT).wait()
# FIND ANY BRANCH THAT MAY HAVE THIS REVISION
for r in list(revisions):
self._find_revision(r)
def show_transactions_blocked_warning(self):
blocker = self.last_command_item
blocked = (self.delayed_queries+self.delayed_transactions)[0]
Log.warning(
"Query on thread {{blocked_thread|json}} at\n"
"{{blocked_trace|indent}}"
"is blocked by {{blocker_thread|json}} at\n"
"{{blocker_trace|indent}}"
"this message brought to you by....",
blocker_trace=format_trace(blocker.trace),
blocked_trace=format_trace(blocked.trace),
blocker_thread=blocker.transaction.thread.name if blocker.transaction is not None else None,
blocked_thread=blocked.transaction.thread.name if blocked.transaction is not None else None
)
def _delete_old_indexes(self, candidates):
for c in candidates:
timestamp = unicode2Date(c.index[-15:], "%Y%m%d_%H%M%S")
if timestamp + self.rollover_interval < Date.today() - self.rollover_max:
# Log.warning("Will delete {{index}}", index=c.index)
try:
self.cluster.delete_index(c.index)
except Exception as e:
Log.warning("could not delete index {{index}}", index=c.index, cause=e)
for t, q in items(self.known_queues):
if unix2Date(t) + self.rollover_interval < Date.today() - self.rollover_max:
with self.locker:
del self.known_queues[t]
pass
def MIN(values, *others):
if others:
from mo_logs import Log
Log.warning("Calling wrong")
return MIN([values] + list(others))
output = None
for v in values:
if v == None:
continue
elif output == None or v < output:
output = v
else:
pass
return output
def test_local_variable_capture(self):
a = {"c": "a", "b": "d"}
b = {"c": "b"}
A = '{\n "b": "d",\n "c": "a"\n}'
B = '{"c": "b"}'
log_queue = StructuredLogger_usingQueue("abba")
backup_log, Log.main_log = Log.main_log, log_queue
Log.note("{{a}} and {{b}}")
self.assertEqual(Log.main_log.pop(), A + ' and ' + B)
Log.warning("{{a}} and {{b}}", a=a, b=b)
self.assertEqual(Log.main_log.pop(), A + ' and ' + B)
def write(self, template, params):
bad = []
for m in self.many:
try:
m.write(template, params)
except Exception as e:
bad.append(m)
Log.warning("Logger failed! It will be removed: {{type}}",
type=m.__class__.__name__,
cause=e)
with suppress_exception:
for b in bad:
self.many.remove(b)
return self
def _get_from_elasticsearch(self, revision, locale=None, get_diff=False):
rev = revision.changeset.id
query = {
"query": {"filtered": {
"query": {"match_all": {}},
"filter": {"and": [
{"term": {"changeset.id12": rev[0:12]}},
{"term": {"branch.name": revision.branch.name}},
{"term": {"branch.locale": coalesce(locale, revision.branch.locale, DEFAULT_LOCALE)}},
{"range": {"etl.timestamp": {"gt": MIN_ETL_AGE}}}
]}
}},
"size": 2000
}
for attempt in range(3):
try:
with self.es_locker:
docs = self.es.search(query).hits.hits
break
except Exception as e:
e = Except.wrap(e)
if "NodeNotConnectedException" in e:
# WE LOST A NODE, THIS MAY TAKE A WHILE
(Till(seconds=Random.int(5 * 60))).wait()
continue
elif "EsRejectedExecutionException[rejected execution (queue capacity" in e:
(Till(seconds=Random.int(30))).wait()
continue
else:
Log.warning("Bad ES call, fall back to TH", cause=e)
return None
best = docs[0]._source
if len(docs) > 1:
for d in docs:
if d._id.endswith(d._source.branch.locale):
best = d._source
Log.warning("expecting no more than one document")
if not GET_DIFF and not get_diff:
return best
elif best.changeset.diff:
return best
elif not best.changeset.files:
return best # NOT EXPECTING A DIFF, RETURN IT ANYWAY
else:
return None
def _update_from_es(self, please_stop):
try:
last_extract = Date.now()
while not please_stop:
now = Date.now()
try:
if (now - last_extract).seconds > COLUMN_EXTRACT_PERIOD:
result = self.es_index.search({
"query": {
"range": {
"last_updated.~n~": {
"gte": self.last_load
}
}
},
"sort":
["es_index.~s~", "name.~s~", "es_column.~s~"],
"from":
0,
"size":
10000,
})
last_extract = now
with self.locker:
for r in result.hits.hits._source:
c = doc_to_column(r)
if c:
self._add(c)
self.last_load = MAX(
(self.last_load, c.last_updated))
while not please_stop:
updates = self.for_es_update.pop_all()
if not updates:
break
DEBUG and updates and Log.note(
"{{num}} columns to push to db", num=len(updates))
self.es_index.extend([{
"value": column.__dict__()
} for column in updates])
except Exception as e:
Log.warning("problem updating database", cause=e)
(Till(seconds=COLUMN_LOAD_PERIOD) | please_stop).wait()
finally:
Log.note("done")
def wait(self, till=None):
"""
THE ASSUMPTION IS wait() WILL ALWAYS RETURN WITH THE LOCK ACQUIRED
:param till: WHEN TO GIVE UP WAITING FOR ANOTHER THREAD TO SIGNAL
:return: True IF SIGNALED TO GO, False IF till WAS SIGNALED
"""
waiter = Signal()
if self.waiting:
# TELL ANOTHER THAT THE LOCK IS READY SOON
other = self.waiting.pop()
other.go()
self.debug and _Log.note(
"waiting with {{num}} others on {{name|quote}}",
num=len(self.waiting),
name=self.name,
stack_depth=1)
self.waiting.insert(0, waiter)
else:
self.debug and _Log.note("waiting by self on {{name|quote}}",
name=self.name)
self.waiting = [waiter]
try:
self.lock.release()
self.debug and _Log.note("out of lock {{name|quote}}",
name=self.name)
(waiter | till).wait()
self.debug and _Log.note(
"done minimum wait (for signal {{till|quote}})",
till=till.name if till else "",
name=self.name)
except Exception as e:
if not _Log:
_late_import()
_Log.warning("problem", cause=e)
finally:
self.lock.acquire()
self.debug and _Log.note("re-acquired lock {{name|quote}}",
name=self.name)
try:
self.waiting.remove(waiter)
self.debug and _Log.note("removed own signal from {{name|quote}}",
name=self.name)
except Exception:
pass
return bool(waiter)
def test_mode_wait(query, please_stop):
"""
WAIT FOR METADATA TO ARRIVE ON INDEX
:param query: dict() OF REQUEST BODY
:return: nothing
"""
if not query["from"]:
return
try:
if query["from"].startswith("meta."):
return
alias = split_field(query["from"])[0]
after = Date.now()
require_cardinality = meta.ENABLE_META_SCAN
with Timer(
"Get columns for {{table}} after {{after}}",
{
"table": alias,
"after": after
},
verbose=DEBUG,
):
metadata_manager = find_container(alias, after=after).namespace
timeout = Till(seconds=MINUTE.seconds) | please_stop
while not timeout:
# GET FRESH VERSIONS
cols = metadata_manager.get_columns(table_name=alias,
after=after,
timeout=timeout)
not_ready = [
c for c in cols if c.jx_type not in STRUCT and (
after >= c.last_updated or
(require_cardinality and c.cardinality == None))
]
if not_ready:
Log.note(
"wait for column (table={{col.es_index}}, name={{col.es_column}}, cardinality={{col.cardinality|json}}, last_updated={{col.last_updated|datetime}}) metadata to arrive",
col=first(not_ready),
)
else:
break
Till(seconds=1).wait()
except Exception as e:
Log.warning("could not pickup columns", cause=e)
def _db_load(self):
self.last_load = Date.now()
try:
self.es_index = self.es_cluster.get_index(
id=ID,
index=META_COLUMNS_NAME,
type=META_COLUMNS_TYPE_NAME,
read_only=False)
result = self.es_index.search({
"query": {
"bool": {
"should": [
{
"bool": {
"must_not": {
"exists": {
"field": "cardinality.~n~"
}
}
}
},
{ # ASSUME UNUSED COLUMNS DO NOT EXIST
"range": {
"cardinality.~n~": {
"gt": 0
}
}
},
]
}
},
"sort": ["es_index.~s~", "name.~s~", "es_column.~s~"],
"size":
10000,
})
Log.note("{{num}} columns loaded", num=result.hits.total)
with self.locker:
for r in result.hits.hits._source:
self._add(doc_to_column(r))
except Exception as e:
Log.warning("no {{index}} exists, making one",
index=META_COLUMNS_NAME,
cause=e)
self._db_create()
def _worker(self, please_stop):
try:
# MAIN EXECUTION LOOP
while not please_stop:
command_item = self.queue.pop(till=please_stop)
if command_item is None:
break
self._process_command_item(command_item)
except Exception as e:
e = Except.wrap(e)
if not please_stop:
Log.warning("Problem with sql", cause=e)
finally:
self.closed = True
DEBUG and Log.note("Database is closed")
self.db.close()
def _shorten(source_key, value, source):
if source.name.startswith("active-data-test-result"):
value.result.subtests = [s for s in value.result.subtests if s.ok is False]
value.result.missing_subtests = True
value.repo.changeset.files = None
shorter_length = len(value2json(value))
if shorter_length > MAX_RECORD_LENGTH:
result_size = len(value2json(value.result))
if source.name == "active-data-test-result":
if result_size > MAX_RECORD_LENGTH:
Log.warning("Epic test failure in {{name}} results in big record for {{id}} of length {{length}}", id=value._id, name=source.name, length=shorter_length)
else:
pass # NOT A PROBLEM
else:
Log.warning("Monstrous {{name}} record {{id}} of length {{length}}", id=source_key, name=source.name, length=shorter_length)
def _convert(file_):
if file_.is_directory():
for f in file_.children:
_convert(f)
elif file_.extension == "json":
try:
json = file_.read_json()
if not json["$schema"]:
return
Log.note("{{json|json}}", json=json)
md = convert.json_schema_to_markdown(json)
file_.set_extension("md").write(md)
except Exception as e:
Log.warning("Can not convert {{filename}}",
filename=file_.name,
cause=e)
def setUpClass(self):
# REMOVE OLD INDEXES
cluster = elasticsearch.Cluster(test_jx.global_settings.backend_es)
aliases = cluster.get_aliases()
for a in aliases:
try:
if a.index.startswith("testing_"):
create_time = Date(
a.index[-15:], "%Y%m%d_%H%M%S"
) # EXAMPLE testing_0ef53e45b320160118_180420
if create_time < Date.now() - 10 * MINUTE:
cluster.delete_index(a.index)
except Exception, e:
Log.warning("Problem removing {{index|quote}}",
index=a.index,
cause=e)
def callback():
try:
auth0.authorize_access_token()
resp = auth0.get("userinfo")
userinfo = resp.json()
session[JWT_PAYLOAD] = userinfo
session[PROFILE_KEY] = {
"user_id": userinfo["sub"],
"name": userinfo["name"],
"picture": userinfo["picture"],
}
return redirect("/dashboard")
except Exception as e:
Log.warning("problem with callback {{url}}", url=request, cause=e)
raise e
def run_pc_daemon(self, please_stop=None):
while not please_stop:
try:
with self.total_locker:
requested = self.total_files_requested
if requested != 0:
mapped = self.total_tuids_mapped
Log.note(
"Percent complete {{mapped}}/{{requested}} = {{percent|percent(0)}}",
requested=requested,
mapped=mapped,
percent=mapped / requested)
(Till(seconds=DAEMON_WAIT_FOR_PC.seconds) | please_stop).wait()
except Exception as e:
Log.warning("Unexpected error in pc-daemon: {{cause}}",
cause=e)
def _wait_for_queue_space(self, timeout=DEFAULT_WAIT_TIME):
"""
EXPECT THE self.lock TO BE HAD, WAITS FOR self.queue TO HAVE A LITTLE SPACE
"""
wait_time = 5
(DEBUG and len(self.queue) > 1 * 1000 * 1000
) and Log.warning("Queue {{name}} has over a million items")
now = time()
if timeout != None:
time_to_stop_waiting = now + timeout
else:
time_to_stop_waiting = now + DEFAULT_WAIT_TIME
if self.next_warning < now:
self.next_warning = now + wait_time
while not self.closed and len(self.queue) >= self.max:
if now > time_to_stop_waiting:
Log.error(THREAD_TIMEOUT)
if self.silent:
self.lock.wait(Till(till=time_to_stop_waiting))
else:
self.lock.wait(Till(seconds=wait_time))
if len(self.queue) >= self.max:
now = time()
if self.next_warning < now:
self.next_warning = now + wait_time
Log.alert(
"Queue by name of {{name|quote}} is full with ({{num}} items), thread(s) have been waiting {{wait_time}} sec",
name=self.name,
num=len(self.queue),
wait_time=wait_time)
def run_flask():
if config.flask.port and config.args.process_num:
config.flask.port += config.args.process_num
# TURN ON /exit FOR WINDOWS DEBUGGING
if config.flask.debug or config.flask.allow_exit:
config.flask.allow_exit = None
Log.warning("ActiveData is in debug mode")
flask_app.add_url_rule('/exit', 'exit', _exit)
if config.flask.ssl_context:
if config.args.process_num:
Log.error("can not serve ssl and multiple Flask instances at once")
setup_flask_ssl()
flask_app.run(**config.flask)
def encode(self, value, pretty=False):
if pretty:
return pretty_json(value)
try:
scrubbed = scrub(value)
return text_type(self.encoder(scrubbed))
except Exception as e:
from mo_logs.exceptions import Except
from mo_logs import Log
e = Except.wrap(e)
Log.warning("problem serializing {{type}}",
type=text_type(repr(value)),
cause=e)
raise e
def _wait_for_queue_space(self, timeout=None):
"""
EXPECT THE self.lock TO BE HAD, WAITS FOR self.queue TO HAVE A LITTLE SPACE
:param timeout: IN SECONDS
"""
wait_time = 5
(DEBUG and len(self.queue) > 1 * 1000 * 1000
) and Log.warning("Queue {{name}} has over a million items")
start = time()
stop_waiting = Till(till=start + coalesce(timeout, DEFAULT_WAIT_TIME))
while not self.closed and len(self.queue) >= self.max:
if stop_waiting:
Log.error(THREAD_TIMEOUT)
if self.silent:
self.lock.wait(stop_waiting)
else:
self.lock.wait(Till(seconds=wait_time))
if not stop_waiting and len(self.queue) >= self.max:
now = time()
Log.alert(
"Queue with name {{name|quote}} is full with ({{num}} items), thread(s) have been waiting {{wait_time}} sec",
name=self.name,
num=len(self.queue),
wait_time=now - start)
def _send_error(active_data_timer, body, e):
record_request(flask.request, None, body, e)
Log.warning("Could not process\n{{body}}",
body=body.decode("latin1"),
cause=e)
e = e.__data__()
e.meta.timing.total = active_data_timer.duration.seconds
# REMOVE TRACES, BECAUSE NICER TO HUMANS
# def remove_trace(e):
# e.trace = e.trace[0:1:]
# for c in listwrap(e.cause):
# remove_trace(c)
# remove_trace(e)
return Response(convert.unicode2utf8(convert.value2json(e)), status=400)
def current():
ident = get_ident()
with ALL_LOCK:
output = ALL.get(ident)
if output is None:
thread = BaseThread(ident)
thread.cprofiler = CProfiler()
thread.cprofiler.__enter__()
with ALL_LOCK:
ALL[ident] = thread
Log.warning(
"this thread is not known. Register this thread at earliest known entry point."
)
return thread
return output
def delete_daemon(file, caller_stack, please_stop):
# WINDOWS WILL HANG ONTO A FILE FOR A BIT AFTER WE CLOSED IT
from mo_threads import Till
while not please_stop:
try:
file.delete()
return
except Exception as e:
e = Except.wrap(e)
e.trace = e.trace[0:2] + caller_stack
Log.warning(u"problem deleting file {{file}}",
file=file.abspath,
cause=e)
(Till(seconds=10) | please_stop).wait()
def setup_flask_ssl():
config.flask.ssl_context = None
if not config.flask.ssl_context:
return
ssl_flask = config.flask.copy()
ssl_flask.debug = False
ssl_flask.port = 443
if is_data(config.flask.ssl_context):
# EXPECTED PEM ENCODED FILE NAMES
# `load_cert_chain` REQUIRES CONCATENATED LIST OF CERTS
with TempFile() as tempfile:
try:
tempfile.write(
File(ssl_flask.ssl_context.certificate_file).read_bytes())
if ssl_flask.ssl_context.certificate_chain_file:
tempfile.write(
File(ssl_flask.ssl_context.certificate_chain_file).
read_bytes())
tempfile.flush()
tempfile.close()
context = SSLContext(PROTOCOL_SSLv23)
context.load_cert_chain(
tempfile.name,
keyfile=File(
ssl_flask.ssl_context.privatekey_file).abspath)
ssl_flask.ssl_context = context
except Exception as e:
Log.error("Could not handle ssl context construction", cause=e)
def runner(please_stop):
Log.warning("ActiveData listening on encrypted port {{port}}",
port=ssl_flask.port)
flask_app.run(**ssl_flask)
Thread.run("SSL Server", runner)
if config.flask.ssl_context and config.flask.port != 80:
Log.warning(
"ActiveData has SSL context, but is still listening on non-encrypted http port {{port}}",
port=config.flask.port)
config.flask.ssl_context = None
def to_esfilter(self, schema):
if is_op(self.lhs, Variable_) and is_literal(self.rhs):
rhs = self.rhs.value
lhs = self.lhs.var
cols = schema.leaves(lhs)
if not cols:
Log.warning(
"{{col}} does not exist while processing {{expr}}",
col=lhs,
expr=self.__data__(),
)
if is_container(rhs):
if len(rhs) == 1:
rhs = rhs[0]
else:
types = Data() # MAP JSON TYPE TO LIST OF LITERALS
for r in rhs:
types[python_type_to_json_type[r.__class__]] += [r]
if len(types) == 1:
jx_type, values = first(types.items())
for c in cols:
if jx_type == c.jx_type or (jx_type in NUMBER_TYPES
and c.jx_type
in NUMBER_TYPES):
return {"terms": {c.es_column: values}}
return FALSE.to_esfilter(schema)
else:
return (OrOp([
EqOp([self.lhs, values])
for t, values in types.items()
]).partial_eval().to_esfilter(schema))
for c in cols:
if c.jx_type == BOOLEAN:
rhs = pull_functions[c.jx_type](rhs)
rhs_type = python_type_to_json_type[rhs.__class__]
if rhs_type == c.jx_type or (rhs_type in NUMBER_TYPES
and c.jx_type in NUMBER_TYPES):
return {"term": {c.es_column: rhs}}
return FALSE.to_esfilter(schema)
else:
return (ES52[CaseOp([
WhenOp(self.lhs.missing(), **{"then": self.rhs.missing()}),
WhenOp(self.rhs.missing(), **{"then": FALSE}),
BasicEqOp([self.lhs, self.rhs]),
]).partial_eval()].to_esfilter(schema))
def _run(self):
self.id = get_ident()
with RegisterThread(self):
try:
if self.target is not None:
a, k, self.args, self.kwargs = self.args, self.kwargs, None, None
self.end_of_thread.response = self.target(*a, **k)
self.parent.remove_child(self) # IF THREAD ENDS OK, THEN FORGET ABOUT IT
except Exception as e:
e = Except.wrap(e)
with self.synch_lock:
self.end_of_thread.exception = e
with self.parent.child_lock:
emit_problem = self not in self.parent.children
if emit_problem:
# THREAD FAILURES ARE A PROBLEM ONLY IF NO ONE WILL BE JOINING WITH IT
try:
Log.fatal("Problem in thread {{name|quote}}", name=self.name, cause=e)
except Exception:
sys.stderr.write(str("ERROR in thread: " + self.name + " " + text_type(e) + "\n"))
finally:
try:
with self.child_lock:
children = copy(self.children)
for c in children:
try:
DEBUG and sys.stdout.write(str("Stopping thread " + c.name + "\n"))
c.stop()
except Exception as e:
Log.warning("Problem stopping thread {{thread}}", thread=c.name, cause=e)
for c in children:
try:
DEBUG and sys.stdout.write(str("Joining on thread " + c.name + "\n"))
c.join()
except Exception as e:
Log.warning("Problem joining thread {{thread}}", thread=c.name, cause=e)
finally:
DEBUG and sys.stdout.write(str("Joined on thread " + c.name + "\n"))
del self.target, self.args, self.kwargs
DEBUG and Log.note("thread {{name|quote}} stopping", name=self.name)
except Exception as e:
DEBUG and Log.warning("problem with thread {{name|quote}}", cause=e, name=self.name)
finally:
self.stopped.go()
DEBUG and Log.note("thread {{name|quote}} is done", name=self.name)
def rollback(self):
if self.pending:
pending, self.pending = self.pending, []
try:
for p in pending:
m = Message()
m.set_body(p.get_body())
self.queue.write(m)
for p in pending:
self.queue.delete_message(p)
if self.settings.debug:
Log.alert("{{num}} messages returned to queue", num=len(pending))
except Exception as e:
Log.warning("Failed to return {{num}} messages to the queue", num=len(pending), cause=e)
def __del__(self):
temp, self.initialized = self.initialized, False
if not temp:
return
try:
if sys.platform == 'win32':
if hasattr(self, 'fd'):
os.close(self.fd)
os.unlink(self.lockfile)
else:
import fcntl
fcntl.lockf(self.fp, fcntl.LOCK_UN)
if os.path.isfile(self.lockfile):
os.unlink(self.lockfile)
except Exception as e:
Log.warning("Problem with SingleInstance __del__()", e)
sys.exit(-1)
def write_lines(self, key, lines):
self._verify_key_format(key)
storage = self.bucket.new_key(key + ".json.gz")
buff = TemporaryFile()
archive = gzip.GzipFile(fileobj=buff, mode='w')
count = 0
for l in lines:
if hasattr(l, "__iter__"):
for ll in l:
archive.write(ll.encode("utf8"))
archive.write(b"\n")
count += 1
else:
archive.write(l.encode("utf8"))
archive.write(b"\n")
count += 1
archive.close()
file_length = buff.tell()
retry = 3
while retry:
try:
with Timer(
"Sending {{count}} lines in {{file_length|comma}} bytes for {{key}}",
{
"key": key,
"file_length": file_length,
"count": count
},
verbose=self.settings.debug):
buff.seek(0)
storage.set_contents_from_file(buff)
break
except Exception as e:
e = Except.wrap(e)
retry -= 1
if retry == 0 or 'Access Denied' in e or "No space left on device" in e:
Log.error("could not push data to s3", cause=e)
else:
Log.warning("could not push data to s3", cause=e)
if self.settings.public:
storage.set_acl('public-read')
return
