def _old_request_ended(self, shard_state):
"""Whether previous slice retry has ended according to Logs API.
Args:
shard_state: shard state.
Returns:
True if the request of previous slice retry has ended. False if it has
not or unknown.
"""
assert shard_state.slice_start_time is not None
assert shard_state.slice_request_id is not None
request_ids = [shard_state.slice_request_id]
try:
logs = list(logservice.fetch(request_ids=request_ids))
except logservice.InvalidArgumentError:
global using_modules
if using_modules:
logs = list(logservice.fetch(
request_ids=request_ids,
module_versions=[(modules.get_current_module_name(),
modules.get_current_version_name())]))
else:
logs = list(logservice.fetch(
request_ids=request_ids,
server_versions=[(servers.get_current_server_name(),
servers.get_current_version_name())]))
if not logs or not logs[0].finished:
return False
return True
def get_recent_log(self):
""" see api
https://developers.google.com/appengine/docs/python/logs/functions
"""
out = ""
since = self.last_check if self.last_check else self.datetime()
log_stream = logservice.fetch(
start_time=self.to_unix_time(since),
minimum_log_level=logservice.LOG_LEVEL_ERROR,
include_app_logs=True
)
requests = itertools.islice(
log_stream, 0, self.maximum_requests_to_email)
for r in requests:
log = itertools.islice(
r.app_logs, 0, self.maximum_entries_per_request)
log = [
self.level_map[l.level] + '\t' +
str(self.to_utc_time(l.time)) + '\t' +
l.message + '\n'
for l in log
]
out = out + r.combined + '\n' + ''.join(log) + '\n\n'
return out
def analyze_status():
LOG_LIMIT = 30 # to prevent 'InvalidArgumentError: Too many request ids specified.'
# Asynchronously fetch troubled services
services_in_trouble = get_monitored_services_in_trouble_qry().run()
# Asynchronously fetch rogerthat backend status
rbe_rpc = db.get_async(RogerthatBackendErrors.get_key())
# Fetch queue statusses
default, controller, worker, fast, broadcast = taskqueue.QueueStatistics.fetch(
["default", "highload-controller-queue", "highload-worker-queue", 'fast', 'broadcast-queue'])
rbe = rbe_rpc.get_result()
logs = logservice.fetch(request_ids=rbe.requestIds[:LOG_LIMIT]) if rbe else None
total_error_count = len(rbe.requestIds) if rbe else 0
skipped_error_count = max(0, total_error_count - LOG_LIMIT)
services = list(services_in_trouble)
five_min_ago = (now() - 300) * 1000000
client_errors = ClientError.all().order("-timestamp").fetch(20)
result = dict(queues=dict(default=default, controller=controller, worker=worker, fast=fast, broadcast=broadcast),
rogerthatBackendStatus=logs,
errorCount=total_error_count,
skippedCount=skipped_error_count,
services=services,
five_min_ago=five_min_ago,
client_errors=client_errors)
return result
def get(self):
self.response.headers["Content-Type"] = "application/json"
dict_request_log = None
# This logging_request_id should match a request_id from an App Engine
# request log.
# https://developers.google.com/appengine/docs/python/logs/functions
logging_request_id = self.request.get("logging_request_id")
# Grab the single request log from logservice
logs = logservice.fetch(request_ids=[logging_request_id])
# This slightly strange query result implements __iter__ but not next,
# so we have to iterate to get our expected single result.
for log in logs:
dict_request_log = {
"pending_ms": log.pending_time, # time spent in pending queue
"loading_request": log.was_loading_request, # loading request?
"logging_request_id": logging_request_id
}
# We only expect a single result.
break
# Log fetching doesn't work on the dev server and this data isn't
# relevant in dev server's case, so we return a simple fake response.
if util.dev_server:
dict_request_log = {
"pending_ms": 0,
"loading_request": False,
"logging_request_id": logging_request_id
}
self.response.out.write(json.dumps(dict_request_log))
def get(self):
self.response.headers["Content-Type"] = "application/json"
dict_request_log = None
# This logging_request_id should match a request_id from an App Engine
# request log.
# https://developers.google.com/appengine/docs/python/logs/functions
logging_request_id = self.request.get("logging_request_id")
# Grab the single request log from logservice
logs = logservice.fetch(request_ids=[logging_request_id])
# This slightly strange query result implements __iter__ but not next,
# so we have to iterate to get our expected single result.
for log in logs:
dict_request_log = {
"pending_ms": log.pending_time, # time spent in pending queue
"loading_request": log.was_loading_request, # loading request?
"logging_request_id": logging_request_id
}
# We only expect a single result.
break
# Log fetching doesn't work on the dev server and this data isn't
# relevant in dev server's case, so we return a simple fake response.
if dev_server:
dict_request_log = {
"pending_ms": 0,
"loading_request": False,
"logging_request_id": logging_request_id
}
self.response.out.write(json.dumps(dict_request_log))
def get(self):
count = int(self.request.get('count'))
logs = logservice.fetch(include_app_logs=True)
entries = []
for entry in islice(logs, count):
entries.append([log.message for log in entry.app_logs])
json.dump(entries, self.response)
def any_new_errors(self):
since = self.last_check if self.last_check else self.datetime()
log_stream = logservice.fetch(
start_time=self.to_unix_time(since),
minimum_log_level=logservice.LOG_LEVEL_ERROR)
return next(iter(log_stream), None) is not None
def get(self):
"""URL parameters:
start_time: float, seconds since the epoch
key: string that should appear in the first app log
"""
start_time = util.get_required_param(self, 'start_time')
if not util.is_float(start_time):
self.abort(400,
"Couldn't convert start_time to float: %r" % start_time)
start_time = float(start_time)
key = util.get_required_param(self, 'key')
if not util.is_base64(key):
self.abort(400, 'key is not base64: %r' % key)
key = urllib.unquote(key)
# the propagate task logs the poll task's URL, which includes the source
# entity key as a query param. exclude that with this heuristic.
key_re = re.compile('[^=]' + key)
self.response.headers['Content-Type'] = 'text/html; charset=utf-8'
offset = None
for log in logservice.fetch(start_time=start_time,
end_time=start_time + 120,
offset=offset,
include_app_logs=True,
version_ids=['2', '3', '4', '5', '6',
'7']):
first_lines = '\n'.join([
line.message.decode('utf-8')
for line in log.app_logs[:min(10, len(log.app_logs))]
])
if log.app_logs and key_re.search(first_lines):
# found it! render and return
self.response.out.write("""\
<html>
<body style="font-family: monospace; white-space: pre">
""")
self.response.out.write(sanitize(log.combined))
self.response.out.write('<br /><br />')
for a in log.app_logs:
msg = a.message.decode('utf-8')
# don't sanitize poll task URLs since they have a key= query param
msg = linkify_datastore_keys(
util.linkify(
cgi.escape(msg if msg.startswith(
'Created by this poll:') else sanitize(msg))))
self.response.out.write(
'%s %s %s<br />' %
(datetime.datetime.utcfromtimestamp(a.time),
LEVELS[a.level], msg.replace('\n', '<br />')))
self.response.out.write('</body>\n</html>')
return
offset = log.offset
self.response.out.write('No log found!')
def _log_request_id(request_id):
"""Returns a logservice.RequestLog for a request id or None if not found."""
request = list(logservice.fetch(
include_incomplete=True, include_app_logs=True, request_ids=[request_id]))
if not request:
logging.info('Dang, didn\'t find the request_id %s', request_id)
return None
assert len(request) == 1, request
return request[0]
def _log_request_id(request_id):
"""Returns a logservice.RequestLog for a request id or None if not found."""
request = list(logservice.fetch(
include_incomplete=True, include_app_logs=True, request_ids=[request_id]))
if not request:
logging.info('Dang, didn\'t find the request_id %s', request_id)
return None
assert len(request) == 1, request
return request[0]
def _extract_exceptions_from_logs(start_time, end_time, module_versions):
"""Yields _ErrorRecord objects from the logs.
Arguments:
start_time: epoch time to start searching. If 0 or None, defaults to
1970-01-01.
end_time: epoch time to stop searching. If 0 or None, defaults to
time.time().
module_versions: list of tuple of module-version to gather info about.
"""
if start_time and end_time and start_time >= end_time:
raise webob.exc.HTTPBadRequest(
'Invalid range, start_time must be before end_time.')
try:
for entry in logservice.fetch(
start_time=start_time or None,
end_time=end_time or None,
minimum_log_level=logservice.LOG_LEVEL_ERROR,
include_incomplete=True,
include_app_logs=True,
module_versions=module_versions):
# Merge all error messages. The main reason to do this is that sometimes
# a single logging.error() 'Traceback' is split on each line as an
# individual log_line entry.
msgs = []
log_time = None
for log_line in entry.app_logs:
# TODO(maruel): Specifically handle:
# 'Request was aborted after waiting too long to attempt to service your
# request.'
# For an unknown reason, it is logged at level info (!?)
if log_line.level < logservice.LOG_LEVEL_ERROR:
continue
msg = log_line.message.strip('\n')
if not msg.strip():
continue
# The message here is assumed to be utf-8 encoded but that is not
# guaranteed. The dashboard does prints out utf-8 log entries properly.
try:
msg = msg.decode('utf-8')
except UnicodeDecodeError:
msg = msg.decode('ascii', 'replace')
msgs.append(msg)
log_time = log_time or log_line.time
yield _ErrorRecord(
entry.request_id,
entry.start_time, log_time, entry.latency, entry.mcycles,
entry.ip, entry.nickname, entry.referrer, entry.user_agent,
entry.host, entry.resource, entry.method, entry.task_queue_name,
entry.was_loading_request, entry.version_id, entry.module_id,
entry.url_map_entry, entry.app_engine_release, entry.instance_key,
entry.status, '\n'.join(msgs))
except logservice.Error as e:
# It's not worth generating an error log when logservice is temporarily
# down. Retrying is not worth either.
logging.warning('Failed to scrape log:\n%s', e)
def _extract_exceptions_from_logs(start_time, end_time, module_versions):
"""Yields _ErrorRecord objects from the logs.
Arguments:
start_time: epoch time to start searching. If 0 or None, defaults to
1970-01-01.
end_time: epoch time to stop searching. If 0 or None, defaults to
time.time().
module_versions: list of tuple of module-version to gather info about.
"""
if start_time and end_time and start_time >= end_time:
raise webob.exc.HTTPBadRequest(
'Invalid range, start_time must be before end_time.')
for entry in logservice.fetch(
start_time=start_time or None,
end_time=end_time or None,
minimum_log_level=logservice.LOG_LEVEL_ERROR,
include_incomplete=True,
include_app_logs=True,
module_versions=module_versions):
# Merge all error messages. The main reason to do this is that sometimes
# a single logging.error() 'Traceback' is split on each line as an
# individual log_line entry.
msgs = []
log_time = None
for log_line in entry.app_logs:
# TODO(maruel): Specifically handle:
# 'Request was aborted after waiting too long to attempt to service your
# request.'
# For an unknown reason, it is logged at level info (!?)
if log_line.level < logservice.LOG_LEVEL_ERROR:
continue
msg = log_line.message.strip('\n')
if not msg.strip():
continue
# The message here is assumed to be utf-8 encoded but that is not
# guaranteed. The dashboard does prints out utf-8 log entries properly.
try:
msg = msg.decode('utf-8')
except UnicodeDecodeError:
msg = msg.decode('ascii', 'replace')
msgs.append(msg)
log_time = log_time or log_line.time
yield _ErrorRecord(
entry.request_id,
entry.start_time, log_time, entry.latency, entry.mcycles,
entry.ip, entry.nickname, entry.referrer, entry.user_agent,
entry.host, entry.resource, entry.method, entry.task_queue_name,
entry.was_loading_request, entry.version_id, entry.module_id,
entry.url_map_entry, entry.app_engine_release, entry.instance_key,
entry.status, '\n'.join(msgs))
def getErrorLogCounters(self, from_time, until_time):
result = {}
error_log_url = False
if config.ERROR_LOG_EXPORT_URL:
error_log_url = re.compile(config.ERROR_LOG_EXPORT_URL)
count = 0
for log_entry in logservice.fetch(
minimum_log_level=logservice.LOG_LEVEL_ERROR,
include_app_logs=True, batch_size=config.ERROR_LOG_EXPORT_AMOUNT):
count += 1
if count > config.ERROR_LOG_EXPORT_AMOUNT:
break
end_time = datetime.datetime.fromtimestamp(int(log_entry.end_time))
if end_time <= from_time or end_time > until_time:
continue
name = "AppEngine.ErrorLog.HTTP." + str(log_entry.status)
exception = None
levels = []
for app_log in log_entry.app_logs:
if app_log.level == logservice.LOG_LEVEL_ERROR:
error_lines = app_log.message.split("\n")
stacktrace = False
for line in error_lines:
if line == "Traceback (most recent call last):":
stacktrace = True
elif (stacktrace and not line.startswith(" ") and
not line.startswith("\t")):
exception = line.split(":")[0]
break
if app_log.level >= logservice.LOG_LEVEL_ERROR:
levels += [["Debug", "Info", "Warning", "Error",
"Critical"][app_log.level]]
self.append(end_time, name, 1, result)
if exception:
self.append(end_time, "AppEngine.ErrorLog.Exception", 1, result)
self.append(end_time, "AppEngine.ErrorLog.Exception." + exception, 1,
result)
for level in levels:
self.append(end_time, "AppEngine.ErrorLog.Level." + level, 1, result)
path_key = log_entry.resource
if "?" in path_key:
path_key = path_key[:path_key.find("?")]
if error_log_url and error_log_url.match(path_key):
self.append(end_time, name + "." + path_key, 1, result)
if exception:
self.append(end_time, "AppEngine.ErrorLog.Exception." + exception +
"." + path_key, 1, result)
for level in levels:
self.append(end_time, "AppEngine.ErrorLog.Level." +
level + "." + path_key, 1, result)
return result
def get(self):
"""URL parameters:
start_time: float, seconds since the epoch
key: string that should appear in the first app log
"""
start_time = util.get_required_param(self, 'start_time')
if not util.is_float(start_time):
self.abort(400, "Couldn't convert start_time to float: %r" % start_time)
start_time = float(start_time)
key = util.get_required_param(self, 'key')
if not util.is_base64(key):
self.abort(400, 'key is not base64: %r' % key)
key = urllib.unquote(key)
# the propagate task logs the poll task's URL, which includes the source
# entity key as a query param. exclude that with this heuristic.
key_re = re.compile('[^=]' + key)
self.response.headers['Content-Type'] = 'text/html; charset=utf-8'
offset = None
for log in logservice.fetch(start_time=start_time, end_time=start_time + 120,
offset=offset, include_app_logs=True,
version_ids=['2', '3', '4', '5', '6', '7']):
first_lines = '\n'.join([line.message.decode('utf-8') for line in
log.app_logs[:min(10, len(log.app_logs))]])
if log.app_logs and key_re.search(first_lines):
# found it! render and return
self.response.out.write("""\
<html>
<body style="font-family: monospace; white-space: pre">
""")
self.response.out.write(sanitize(log.combined))
self.response.out.write('<br /><br />')
for a in log.app_logs:
msg = a.message.decode('utf-8')
# don't sanitize poll task URLs since they have a key= query param
msg = linkify_datastore_keys(util.linkify(cgi.escape(
msg if msg.startswith('Created by this poll:') else sanitize(msg))))
self.response.out.write('%s %s %s<br />' %
(datetime.datetime.utcfromtimestamp(a.time), LEVELS[a.level],
msg.replace('\n', '<br />')))
self.response.out.write('</body>\n</html>')
return
offset = log.offset
self.response.out.write('No log found!')
def _old_request_ended(self, shard_state):
"""Whether previous slice retry has ended.
Args:
shard_state: shard state.
Returns:
True if the request of previous slice retry has ended. False if it has
not or unknown.
"""
assert shard_state.slice_start_time is not None
assert shard_state.slice_request_id is not None
logs = list(logservice.fetch(request_ids=[shard_state.slice_request_id]))
if not logs or not logs[0].finished:
return False
return True
def _yield_logs(start_time, end_time):
"""Yields logservice.RequestLogs for the requested time interval.
Meant to be mocked in tests.
"""
# If module_versions is not specified, it will default to the current version
# on current module, which is not what we want.
# TODO(maruel): Keep request.offset and use it to resume the query by using it
# instead of using start_time/end_time.
module_versions = utils.get_module_version_list(None, True)
for request in logservice.fetch(
start_time=start_time - 1 if start_time else start_time,
end_time=end_time + 1 if end_time else end_time,
include_app_logs=True,
module_versions=module_versions):
yield request
def _yield_logs(start_time, end_time):
"""Yields logservice.RequestLogs for the requested time interval.
Meant to be mocked in tests.
"""
# If module_versions is not specified, it will default to the current version
# on current module, which is not what we want.
# TODO(maruel): Keep request.offset and use it to resume the query by using it
# instead of using start_time/end_time.
module_versions = utils.get_module_version_list(None, True)
for request in logservice.fetch(
start_time=start_time - 1 if start_time else start_time,
end_time=end_time + 1 if end_time else end_time,
include_app_logs=True,
module_versions=module_versions):
yield request
def _old_request_ended(self, shard_state):
"""Whether previous slice retry has ended.
Args:
shard_state: shard state.
Returns:
True if the request of previous slice retry has ended. False if it has
not or unknown.
"""
assert shard_state.slice_start_time is not None
assert shard_state.slice_request_id is not None
logs = list(
logservice.fetch(request_ids=[shard_state.slice_request_id]))
if not logs or not logs[0].finished:
return False
return True
def getLogCounters(self, from_time, until_time):
result = {}
log_url = False
if config.LOG_EXPORT_URL:
log_url = re.compile(config.LOG_EXPORT_URL)
count = 0
first_entry = None
last_entry = None
for log_entry in logservice.fetch(include_app_logs=False,
batch_size=config.LOG_EXPORT_AMOUNT):
count += 1
if count >= config.LOG_EXPORT_AMOUNT:
break
end_time = datetime.datetime.fromtimestamp(int(log_entry.end_time))
if end_time <= from_time or end_time > until_time:
continue
first_entry = first_entry or log_entry
last_entry = log_entry
name = "AppEngine.Log.Sampled."
self.append(end_time, name + "Request", 1, result)
if log_entry.pending_time:
self.append(end_time, name + "PendingTimeMs",
int(log_entry.pending_time * 1000), result)
if log_entry.cost:
self.append(end_time, name + "CostPerBillionRequests",
int(log_entry.cost * 1000000000), result)
path_key = log_entry.resource
if "?" in path_key:
path_key = path_key[:path_key.find("?")]
if log_url:
if not log_url.match(path_key):
path_key = "Other"
self.append(end_time, name + "Request." + path_key, 1, result)
if log_entry.cost:
self.append(end_time,
name + "CostPerBillionRequests." + path_key,
int(log_entry.cost * 1000000000), result)
if first_entry:
end_time = datetime.datetime.fromtimestamp(int(
last_entry.end_time))
self.append(end_time, "AppEngine.Log.SampledMs",
(last_entry.end_time - first_entry.end_time) * 1000,
result)
return result
def get(self):
# offset doesn't work. I give up.
site_counter = db.get_site_counter()
log_email_last_offset = site_counter.log_email_last_offset
end_time = time.time()
last_offset = None
message = ""
for req_log in logservice.fetch(
end_time=end_time,
offset=log_email_last_offset,
#minimum_log_level=logservice.LOG_LEVEL_WARNING,
include_app_logs=True):
message += datetime.datetime.fromtimestamp(int(
req_log.end_time)).strftime('%Y-%m-%d %H:%M:%S')
message += "\n"
message += req_log.ip
message += "\n"
if req_log.referrer:
message += req_log.referrer
message += "\n"
message += req_log.resource
message += "\n"
message += "\n APP MESSAGES \n"
for app_log in req_log.app_logs:
if app_log.level >= 3:
message += "Log Level: " + str(app_log.level) + "\n"
message += app_log.message
message += "\n"
message += "\n\n -------------------------------- \n\n"
last_offset = req_log.offset
if last_offset:
site_counter.log_email_last_offset = last_offset
site_counter.put()
logging.info("-------------------------")
logging.info(message)
def log(request_log_id, memcache_hit, link, target_url, cookies):
for rlog in logservice.fetch(request_ids=[request_log_id]):
ga = dict()
ga['v'] = 1 # protocol version
ga['tid'] = 'UA-XXXX-Y' # tracking id
ga['ds'] = 'shorty' # data source
ga['cid'] = uuid.uuid4() # client id
ga['uip'] = rlog.ip # ip address override
ga['ua'] = rlog.user_agent # user agent override
ga['dr'] = rlog.referrer # document referrer
ga['t'] = 'event' # HIT Type
ga['dh'] = rlog.host # host name
ga['dp'] = rlog.resource # path
ga['ec'] = 'shorturl' # event category
ga['ea'] = 'request' # event action
ga['el'] = rlog.resource[1:] # event label
ga['ev'] = short_url.decode_url(rlog.resource[1:]) # event value
ga['plt'] = rlog.latency # page load time
ga['rrt'] = rlog.latency # redirect response time
logger.debug('log ga:%s', ga)
def get_error_summary(self):
""" A short high level overview of the error.
This was designed to serve as the email subject line so that
developers could quickly see if an error was a new type of error.
It returns the resources that were requested as a comma
seperated string:
e.g.
/api/put/pd, /api/...
see google api
https://developers.google.com/appengine/docs/python/logs/functions
"""
# Get a record of all the requests which generated an error
# since the last check was performed, typically this will be
# at most one error, but we don't want to ignore other errors if
# they occurred.
since = self.last_check if self.last_check else self.datetime()
log_stream = logservice.fetch(
start_time=self.to_unix_time(since),
minimum_log_level=logservice.LOG_LEVEL_ERROR,
include_app_logs=True
)
# Limit the maximum number of errors that will be processed
# to avoid insane behavior that should never happen, like
# emailing a report with a googleplex error messages.
requests = itertools.islice(
log_stream, 0, self.maximum_requests_to_email
)
# This should return a list of any requested resources
# that led to an error. Usually there will only be one.
# for example:
# /api/put/pd
# or
# /api/put/pd, /api/another_call
out = ', '.join(set([r.resource for r in requests]))
return out
def get(self):
# offset doesn't work. I give up.
site_counter = db.get_site_counter()
log_email_last_offset = site_counter.log_email_last_offset
end_time = time.time()
last_offset = None
message = ""
for req_log in logservice.fetch(end_time=end_time, offset=log_email_last_offset,
#minimum_log_level=logservice.LOG_LEVEL_WARNING,
include_app_logs=True):
message += datetime.datetime.fromtimestamp(int(req_log.end_time)).strftime('%Y-%m-%d %H:%M:%S')
message += "\n"
message += req_log.ip
message += "\n"
if req_log.referrer:
message += req_log.referrer
message += "\n"
message += req_log.resource
message += "\n"
message += "\n APP MESSAGES \n"
for app_log in req_log.app_logs:
if app_log.level >= 3:
message += "Log Level: " + str(app_log.level) + "\n"
message += app_log.message
message += "\n"
message += "\n\n -------------------------------- \n\n"
last_offset = req_log.offset
if last_offset:
site_counter.log_email_last_offset = last_offset
site_counter.put()
logging.info("-------------------------")
logging.info(message)
def continuation(self, context, obj, token=None):
""" Continuation - see ContinuationFSMAction.continuation(...)
@param context: an FSMContext instance
@param obj: a temporary state dictionary
"""
if not token:
startTime = context[START_TIME_PARAM] # need a recent start_time, or an F1 instance runs out of memory
else:
startTime = pickle.loads(str(token))
offset = None
endTime = None
minimumLogLevel = context.get(MINIMUM_LOG_LEVEL_PARAM, DEFAULT_MINIMUM_LOG_LEVEL)
includeIncomplete = context.get(INCLUDE_INCOMPLETE_PARAM, False)
includeAppLogs = context.get(INCLUDE_APP_LOGS_PARAM, DEFAULT_INCLUDE_APP_LOGS)
versionIds = context.get(VERSION_IDS_PARAM)
if versionIds and not isinstance(versionIds, list):
versionIds = [versionIds]
batchSize = context.get(BATCH_SIZE_PARAM, None)
logRequestsIter = logservice.fetch(start_time=startTime,
end_time=endTime,
offset=offset,
minimum_log_level=minimumLogLevel,
include_incomplete=includeIncomplete,
include_app_logs=includeAppLogs,
version_ids=versionIds,
batch_size=batchSize)
logRequests = list(logRequestsIter)
logRequests = [l for l in logRequests if l.end_time > startTime] # fetch does no strictly obey start_time
# This effectively implements polling with exponential backoff, up to a
# maximum of 60s, as defined in fsm.yaml.
if not logRequests:
raise NoLogsAvailableException()
obj[LOG_REQUESTS_PARAM] = logRequests
return pickle.dumps(logRequests[0].end_time) # pickle the float to avoid loss of precision
def getLogCounters(self, from_time, until_time):
result = {}
log_url = False
if config.LOG_EXPORT_URL:
log_url = re.compile(config.LOG_EXPORT_URL)
count = 0
first_entry = None
last_entry = None
for log_entry in logservice.fetch(
include_app_logs=False, batch_size=config.LOG_EXPORT_AMOUNT):
count += 1
if count >= config.LOG_EXPORT_AMOUNT:
break
end_time = datetime.datetime.fromtimestamp(int(log_entry.end_time))
if end_time <= from_time or end_time > until_time:
continue
first_entry = first_entry or log_entry
last_entry = log_entry
name = "AppEngine.Log.Sampled."
self.append(end_time, name + "Request", 1, result)
if log_entry.pending_time:
self.append(end_time, name + "PendingTimeMs",
int(log_entry.pending_time * 1000), result)
if log_entry.cost:
self.append(end_time, name + "CostPerBillionRequests",
int(log_entry.cost * 1000000000), result)
path_key = log_entry.resource
if "?" in path_key:
path_key = path_key[:path_key.find("?")]
if log_url:
if not log_url.match(path_key):
path_key = "Other"
self.append(end_time, name + "Request." + path_key, 1, result)
if log_entry.cost:
self.append(end_time, name + "CostPerBillionRequests." + path_key,
int(log_entry.cost * 1000000000), result)
if first_entry:
end_time = datetime.datetime.fromtimestamp(int(last_entry.end_time))
self.append(end_time, "AppEngine.Log.SampledMs",
(last_entry.end_time-first_entry.end_time) * 1000, result)
return result
def get(self):
errors = []
end = time.time()
start = end - (24 * 60 * 60)
for log in logservice.fetch(start_time=start, end_time=end, include_app_logs=True,
minimum_log_level=logservice.LOG_LEVEL_ERROR):
for app_log in log.app_logs:
if app_log.level >= 3:
errors.append(app_log.message.split('\n')[-1])
self.response.out.write("There are %s errors.<br />" % len(errors))
for e in errors:
self.response.out.write(e + "<br />")
if len(errors) > 0:
message = EmailMessage()
message.sender = "Rolla CCF Website Errors <*****@*****.**>"
message.to = "*****@*****.**"
message.subject = "CCF Website Errors (%s)" % len(errors)
message.body = "\n".join(errors)
message.send()
def get_request_stats(after=None):
if after is None:
one_minute_ago = datetime.utcnow() - timedelta(minutes=1)
after = time.mktime(one_minute_ago.timetuple())
else:
# cast to float
after = float(after)
logs = logservice.fetch(start_time=after)
stats = defaultdict(list)
for req_log in logs:
stats["start_time"].append(req_log.start_time)
stats["api_mcycles"].append(req_log.api_mcycles)
stats["cost"].append(req_log.cost)
stats["finished"].append(req_log.finished)
stats["latency"].append(req_log.latency)
stats["mcycles"].append(req_log.mcycles)
stats["pending_time"].append(req_log.pending_time)
stats["replica_index"].append(req_log.replica_index)
stats["response_size"].append(req_log.response_size)
stats["version_id"].append(req_log.version_id)
return stats
def get_request_stats(after=None):
if after is None:
one_minute_ago = datetime.utcnow() - timedelta(minutes=1)
after = time.mktime(one_minute_ago.timetuple())
else:
# cast to float
after = float(after)
logs = logservice.fetch(start_time=after)
stats = defaultdict(list)
for req_log in logs:
stats['start_time'].append(req_log.start_time)
stats['api_mcycles'].append(req_log.api_mcycles)
stats['cost'].append(req_log.cost)
stats['finished'].append(req_log.finished)
stats['latency'].append(req_log.latency)
stats['mcycles'].append(req_log.mcycles)
stats['pending_time'].append(req_log.pending_time)
stats['replica_index'].append(req_log.replica_index)
stats['response_size'].append(req_log.response_size)
stats['version_id'].append(req_log.version_id)
return stats
def getErrorLogCounters(self, from_time, until_time):
result = {}
error_log_url = False
if config.ERROR_LOG_EXPORT_URL:
error_log_url = re.compile(config.ERROR_LOG_EXPORT_URL)
count = 0
for log_entry in logservice.fetch(
minimum_log_level=logservice.LOG_LEVEL_ERROR,
include_app_logs=False, batch_size=config.ERROR_LOG_EXPORT_AMOUNT):
count += 1
if count > config.ERROR_LOG_EXPORT_AMOUNT:
break
end_time = datetime.datetime.fromtimestamp(int(log_entry.end_time))
if end_time <= from_time or end_time > until_time:
continue
name = "AppEngine.ErrorLog.HTTP." + str(log_entry.status)
self.append(end_time, name, 1, result)
path_key = log_entry.resource
if "?" in path_key:
path_key = path_key[:path_key.find("?")]
if error_log_url and error_log_url.match(path_key):
self.append(end_time, name + "." + path_key, 1, result)
return result
def get(self):
errors = []
end = time.time()
start = end - (24 * 60 * 60)
for log in logservice.fetch(
start_time=start,
end_time=end,
include_app_logs=True,
minimum_log_level=logservice.LOG_LEVEL_ERROR):
for app_log in log.app_logs:
if app_log.level >= 3:
errors.append(app_log.message.split('\n')[-1])
self.response.out.write("There are %s errors.<br />" % len(errors))
for e in errors:
self.response.out.write(e + "<br />")
if len(errors) > 0:
message = EmailMessage()
message.sender = "Rolla CCF Website Errors <*****@*****.**>"
message.to = "*****@*****.**"
message.subject = "CCF Website Errors (%s)" % len(errors)
message.body = "\n".join(errors)
message.send()
def getErrorLogCounters(self, from_time, until_time):
result = {}
error_log_url = False
if config.ERROR_LOG_EXPORT_URL:
error_log_url = re.compile(config.ERROR_LOG_EXPORT_URL)
count = 0
for log_entry in logservice.fetch(
minimum_log_level=logservice.LOG_LEVEL_ERROR,
include_app_logs=False,
batch_size=config.ERROR_LOG_EXPORT_AMOUNT):
count += 1
if count > config.ERROR_LOG_EXPORT_AMOUNT:
break
end_time = datetime.datetime.fromtimestamp(int(log_entry.end_time))
if end_time <= from_time or end_time > until_time:
continue
name = "AppEngine.ErrorLog.HTTP." + str(log_entry.status)
self.append(end_time, name, 1, result)
path_key = log_entry.resource
if "?" in path_key:
path_key = path_key[:path_key.find("?")]
if error_log_url and error_log_url.match(path_key):
self.append(end_time, name + "." + path_key, 1, result)
return result
def fetch_logs(start_time_t, end_time_t, appengine_versions=None):
return logservice.fetch(start_time=start_time_t, end_time=end_time_t,
include_app_logs=True,
version_ids=appengine_versions)
def fetch_logs(start_time_t, end_time_t, appengine_versions=None):
return logservice.fetch(start_time=start_time_t,
end_time=end_time_t,
include_app_logs=True,
version_ids=appengine_versions)
def _process_logs(self):
total_latency = 0
total_cost = 0
total_pending_time = 0
total_response_size = 0
total_loading_request_latency = 0
offset = self._get_load_log_offset()
end_time = time.time()
if not offset:
start_time = time.time() - 60 * 60
rls = logservice.fetch(
end_time=end_time,
start_time=start_time,
minimum_log_level=logservice.LOG_LEVEL_DEBUG
)
else:
rls = logservice.fetch(
end_time=end_time,
offset=offset,
minimum_log_level=logservice.LOG_LEVEL_DEBUG
)
self.health.log_count = len(rls)
for rl in rls:
self.health.last_log_offset = rl.offset
if not rl.was_loading_request:
total_latency += rl.latency
if rl.latency > self.health.highest_latency:
self.health.highest_latency = rl.latency
else:
total_loading_request_latency += rl.latency
self.health.total_loading_request += 1
if rl.latency > self.health.highest_loading_latency:
self.health.highest_loading_latency = rl.latency
total_cost += rl.cost
if rl.cost > self.health.highest_cost:
self.health.highest_cost = rl.cost
total_pending_time += rl.pending_time
if rl.pending_time > self.health.highest_pending_time:
self.health.highest_pending_time = rl.pending_time
total_response_size += rl.response_size
if rl.response_size > self.health.biggest_response_size:
self.health.biggest_response_size = rl.response_size
if rl.status in self.health.status_count:
self.health.status_count[rl.status] += 1
else:
self.health.status_count[rl.status] = 1
lr = LogRecords.from_requestlog(rl)
lr.put()
self.health.avg_latency = total_latency / (self.health.log_count - self.health.total_loading_request)
self.health.avg_cost = total_cost / self.health.log_count
self.health.avg_pending_time = total_pending_time / self.health.log_count
self.health.avg_response_size = total_response_size / self.health.log_count
self.health.avg_loading_latency = total_loading_request_latency / self.health.total_loading_request
def _analyze(start, end):
from rogerthat.bizz import monitoring
put_rpcs = list()
def qr_code_scanned(request, log_entry, slog_entry, counters):
params = slog_entry["a"]
sid = params["sid"]
if sid is None:
return
service_identity_email = params["service"]
supported_platform = params["supported_platform"]
from_rogerthat = params["from_rogerthat"]
sid_key = (service_identity_email, sid)
counters[sid_key] = counters.get(sid_key, dict(total=0, from_rogerthat=0, supported=0, unsupported=0))
sid_counters = counters[sid_key]
sid_counters["total"] += 1
if from_rogerthat:
sid_counters["from_rogerthat"] += 1
else:
sid_counters['supported' if supported_platform else 'unsupported'] += 1
def store_stats_qr_scans(counters):
sid_rpcs = list()
for (service_identity_email, sid), sid_counters in counters.iteritems():
sid_key = db.Key.from_path(ServiceInteractionDef.kind(), sid,
parent=parent_key(get_service_user_from_service_identity_user(users.User(service_identity_email))))
sid_rpcs.append((db.get_async(sid_key), sid_counters))
for sid_rpc, sid_counters in sid_rpcs:
sid = sid_rpc.get_result()
sid.totalScanCount += sid_counters["total"]
sid.scannedFromRogerthatCount += sid_counters["from_rogerthat"]
sid.scannedFromOutsideRogerthatOnSupportedPlatformCount += sid_counters['supported']
sid.scannedFromOutsideRogerthatOnUnsupportedPlatformCount += sid_counters['unsupported']
put_rpcs.append(db.put_async(sid))
def service_api_failure(request, log_entry, slog_entry, counters):
params = slog_entry["a"]
service_identity_email = params["service"]
call_type = params["call_type"]
counters[service_identity_email] = counters.get(service_identity_email, dict(Call=0, CallBack=0))
sie_counters = counters[service_identity_email]
sie_counters[call_type] += 1
def store_stats_api_failures(counters):
keys = [ServiceAPIFailures.key_from_service_user_email(k) for k in counters.keys()]
safs = db.get(keys)
for i in xrange(len(keys)):
key = keys[i]
saf = safs[i]
if not saf:
saf = ServiceAPIFailures(key=key, creationTime=now(), failedCalls=0, failedCallBacks=0)
safs[i] = saf
saf.failedCalls += counters[key.name()][monitoring.SERVICE_API_CALL]
saf.failedCallBacks += counters[key.name()][monitoring.SERVICE_API_CALLBACK]
for chunk in chunks(safs, 200):
db.put(chunk)
def service_user_stats(request, log_entry, slog_entry, counters):
params = slog_entry["a"]
service_identity_user_email = params["service"]
tag = params["tag"]
type_ = params["type_"]
counters[service_identity_user_email] = counters.get(service_identity_user_email, dict(gained=list(), lost=list(), menuItemPress=list(), recommendViaRogerthat=list(), recommendViaEmail=list()))
sid_counters = counters[service_identity_user_email]
sid_counters[type_].append(tag)
def store_service_user_stats(counters):
sid_rpcs = list()
for (service_identity_user_email), sid_counters in counters.iteritems():
sevice_identity_user = users.User(service_identity_user_email)
sid_key = ServiceIdentityStatistic.create_key(sevice_identity_user)
sid_rpcs.append((db.get_async(sid_key), sid_counters, sid_key, sevice_identity_user))
for sid_rpc, sid_counters, sid_key, sevice_identity_user in sid_rpcs:
sid = sid_rpc.get_result()
new_sid = False
if not sid:
new_sid = True
sid = ServiceIdentityStatistic(key=sid_key)
sid.users_gained = list()
sid.users_lost = list()
sid.last_ten_users_gained = list()
sid.last_ten_users_lost = list()
sid.recommends_via_rogerthat = list()
sid.recommends_via_email = list()
sid.mip_labels = list()
now_ = datetime.datetime.utcnow()
today = int("%d%02d%02d" % (now_.year, now_.month, now_.day))
if today != sid.last_entry_day:
if new_sid:
add_days = 1
else:
tmp = str(sid.last_entry_day)
start = datetime.date(int(tmp[0:4]), int(tmp[4:6]), int(tmp[6:8]))
end = datetime.date(now_.year, now_.month, now_.day)
delta = end - start
add_days = delta.days
sid.last_entry_day = today
def do(lst):
for _ in xrange(add_days):
lst.append(0)
if len(lst) > 1000:
lst.pop(0)
do(sid.users_gained)
do(sid.users_lost)
do(sid.recommends_via_rogerthat)
do(sid.recommends_via_email)
for i in xrange(len(sid.mip_labels)):
do(getattr(sid, 'mip_%s' % i))
gained = sid_counters[SERVICE_STATS_TYPE_GAINED]
if new_sid:
sid.number_of_users = count_users_connected_to_service_identity(sevice_identity_user)
sid.last_ten_users_gained.extend(gained)
sid.last_ten_users_gained = sid.last_ten_users_gained[-10:]
sid.users_gained[-1] = sid.users_gained[-1] + len(gained)
lost = sid_counters[SERVICE_STATS_TYPE_LOST]
sid.last_ten_users_lost.extend(lost)
sid.last_ten_users_lost = sid.last_ten_users_lost[-10:]
sid.users_lost[-1] = sid.users_lost[-1] + len(lost)
recommendsViaRogerthat = sid_counters[SERVICE_STATS_TYPE_RECOMMEND_VIA_ROGERTHAT]
recommendsViaEmail = sid_counters[SERVICE_STATS_TYPE_RECOMMEND_VIA_EMAIL]
sid.recommends_via_rogerthat[-1] = sid.recommends_via_rogerthat[-1] + len(recommendsViaRogerthat)
sid.recommends_via_email[-1] = sid.recommends_via_email[-1] + len(recommendsViaEmail)
if not new_sid:
sid.number_of_users = sid.number_of_users + len(gained) - len(lost)
sid.gained_last_week = sum(sid.users_gained[-7:])
sid.lost_last_week = sum(sid.users_lost[-7:])
for x in sid_counters[SERVICE_STATS_TYPE_MIP]:
if x not in sid.mip_labels:
sid.mip_labels.append(x)
i = sid.mip_labels.index(x)
l = list()
l.append(1)
setattr(sid, 'mip_%s' % i, l)
else:
i = sid.mip_labels.index(x)
l = getattr(sid, 'mip_%s' % i)
l[-1] = l[-1] + 1
setattr(sid, 'mip_%s' % i, l)
put_rpcs.append(db.put_async(sid))
def broadcast_stats(request, log_entry, slog_entry, counters):
params = slog_entry["a"]
service_identity_user_email = params["service"]
type_ = params["type_"]
broadcast_guid = params["broadcast_guid"]
counters[broadcast_guid] = counters.get(broadcast_guid, dict(sent=0, received=0, read=0, service_identity_user_email=service_identity_user_email))
sid_counters = counters[broadcast_guid]
sid_counters[type_] += 1
def store_broadcast_stats(counters):
broadcast_stats_rpcs = list()
for (broadcast_guid), broadcast_counters in counters.iteritems():
service_identity_user = users.User(broadcast_counters["service_identity_user_email"])
broadcast_statistic_key = BroadcastStatistic.create_key(broadcast_guid, service_identity_user)
broadcast_stats_rpcs.append((db.get_async(broadcast_statistic_key), broadcast_counters, broadcast_statistic_key, broadcast_guid, service_identity_user))
for broadcast_stat_rpc, broadcast_counters, broadcast_statistic_key, broadcast_guid, service_identity_user in broadcast_stats_rpcs:
broadcast_statistic = broadcast_stat_rpc.get_result()
if not broadcast_statistic:
broadcast_statistic = BroadcastStatistic(key=broadcast_statistic_key, timestamp=now())
broadcast_statistic.sent = (broadcast_statistic.sent or 0) + broadcast_counters[BROADCAST_STATS_SENT]
broadcast_statistic.received = (broadcast_statistic.received or 0) + broadcast_counters[BROADCAST_STATS_RECEIVED]
broadcast_statistic.read = (broadcast_statistic.read or 0) + broadcast_counters[BROADCAST_STATS_READ]
put_rpcs.append(db.put_async(broadcast_statistic))
def flow_stats(request, log_entry, slog_entry, counters):
params = slog_entry['a']
tag = params['tag']
service_identity_user = users.User(params['service_identity_user'])
if tag:
today = params['today']
flow_stats_key = str(FlowStatistics.create_key(tag, service_identity_user))
# counters: { flow_stats_key : { today : [(breadcrumbs, statuses, current_step_id, current_btn_id)] } }
counters[flow_stats_key][today].append((params['breadcrumbs'],
params['statuses'],
params['current_step_id'],
params['current_btn_id']))
def store_flow_stats(counters):
to_put = list()
flow_stats_keys = counters.keys()
for flow_stats_key, flow_stats in zip(flow_stats_keys, db.get(flow_stats_keys)):
if not flow_stats:
flow_stats = FlowStatistics(key=flow_stats_key)
to_put.append(flow_stats)
for day, stats_list in sorted(counters[flow_stats_key].iteritems()):
flow_stats.set_today(datetime.datetime.utcfromtimestamp(day).date())
for breadcrumbs, statuses, current_step_id, current_btn_id in stats_list:
for status in statuses:
btn_id = current_btn_id if status == FlowStatistics.STATUS_ACKED else None
flow_stats.add(breadcrumbs, current_step_id, status, btn_id)
for chunk in chunks(to_put, 200):
put_rpcs.append(db.put_async(chunk))
amap = {
QRCODE_SCANNED: dict(analysis_func=qr_code_scanned, summarize_func=store_stats_qr_scans, counters=dict()),
SERVICE_MONITOR: dict(analysis_func=service_api_failure, summarize_func=store_stats_api_failures, counters=dict()),
SERVICE_STATS: dict(analysis_func=service_user_stats, summarize_func=store_service_user_stats, counters=dict()),
BROADCAST_STATS: dict(analysis_func=broadcast_stats, summarize_func=store_broadcast_stats, counters=dict()),
FLOW_STATS: dict(analysis_func=flow_stats, summarize_func=store_flow_stats, counters=defaultdict(lambda: defaultdict(list))),
}
slog_header_length = len(SLOG_HEADER)
error_requests = list()
offset = None
while True:
logs = logservice.fetch(start_time=start, end_time=end, offset=offset, \
minimum_log_level=logservice.LOG_LEVEL_INFO, include_incomplete=False, \
include_app_logs=True)
count = 0
for log in logs:
count += 1
store_log = False
offset = log.offset
for app_log in log.app_logs:
if app_log.level in (logservice.LOG_LEVEL_ERROR, logservice.LOG_LEVEL_CRITICAL):
store_log = True
if app_log.message and app_log.message.startswith(SLOG_HEADER):
slog_value = app_log.message[slog_header_length + 1:]
try:
slog_value = json.loads(slog_value)
except:
logging.exception("Failed to parse slog entry:\n%s" % slog_value)
continue
ftie = slog_value.get("f", None)
if not ftie:
continue
analyzer = amap.get(ftie, None)
if not analyzer:
continue
analyzer["analysis_func"](log, app_log, slog_value, analyzer["counters"])
if store_log:
error_requests.append(log.request_id)
if count == 0:
break
# summarize could be paralellized in the future. See http://docs.python.org/library/queue.html
try:
for mapping in amap.itervalues():
mapping["summarize_func"](mapping["counters"])
for rpc_ in put_rpcs:
rpc_.get_result()
except:
logging.exception("Failed to execute summarize!", _suppress=False)
if error_requests:
try:
errors = RogerthatBackendErrors.get()
errors.requestIds.extend(error_requests)
errors.put()
except:
logging.exception("Could not store error ids during analyze.", _suppress=False)
def gen_tiddownload():
template_values = {}
reports = list(ErrorReport.all())
# error reports chart
vers = set(r.appVersionName for r in reports)
reps_by_ver = {ver: [r for r in reports if r.appVersionName == ver] for ver in vers}
data = [{'version': ver, 'reports': len(reps), 'unique': len(set(r.exStackTrace for r in reps))} for ver, reps in sorted(reps_by_ver.items())]
description = {
'version': ('string', 'Version'),
'reports': ('number', 'Total'),
'unique': ('number', 'Unique'),
}
data_table = gviz_api.DataTable(description)
data_table.LoadData(data)
template_values['error_reports_json'] = data_table.ToJSon(columns_order=('version', 'reports', 'unique'))
# error reports statistics
stats = []
template_values['error_reports_stats'] = stats
stats.append(('Total reports', len(reports)))
stats.append(('Unique reports', len(set(r.exStackTrace for r in reports))))
maxVerCode = max(reports, key=attrgetter('appVersionCode')).appVersionCode
stats.append(('Last report (last version)', max((r for r in reports if r.appVersionCode != maxVerCode), key=attrgetter('date')).date + timedelta(hours = 4)))
# songs chart
songs = list(SongEntry.all())
dates = set(s.date.date() for s in songs)
data = [{
'date': date,
'total': len([s for s in songs if s.date.date() == date]),
'unique': len(set(s.song for s in songs if s.date.date() == date)),
'users': len(set(s.id for s in songs if s.date.date() == date)),
} for date in dates]
data_aggr = [{
'date': date,
'total': len([s for s in songs if s.date.date() <= date]),
'unique': len(set(s.song for s in songs if s.date.date() <= date)),
'users': len(set(s.id for s in songs if s.date.date() <= date)),
} for date in dates]
description = {
'date': ('date', 'Date'),
'total': ('number', 'Total'),
'unique': ('number', 'Unique'),
'users': ('number', 'Users'),
}
data_table = gviz_api.DataTable(description)
data_table.LoadData(data)
template_values['songs_json'] = data_table.ToJSon(columns_order=('date', 'total', 'unique', 'users'), order_by='date')
data_table = gviz_api.DataTable(description)
data_table.LoadData(data_aggr)
template_values['songs_aggr_json'] = data_table.ToJSon(columns_order=('date', 'total', 'unique', 'users'), order_by='date')
# songs statistics
stats = []
template_values['songs_stats'] = stats
stats.append(('Total searches', len(songs)))
stats.append(('Unique searches', len(set(s.song for s in songs))))
stats.append(('Unique users', len(set(s.id for s in songs))))
stats.append(('', ''))
stats.append(('Most popular song:', ''))
max_pop = max(((s.song.replace('+', ' '), len(set(ss.id for ss in songs if ss.song == s.song))) for s in songs), key = itemgetter(1))
stats.append(max_pop)
# logs
request_logs = sorted(list(logservice.fetch()) + list(logservice.fetch(version_ids = ['1'])), key = attrgetter('start_time'))
dates = set(datetime.fromtimestamp(r.start_time).date() for r in request_logs)
data = [{
'date': date,
'requests': len([r for r in request_logs if datetime.fromtimestamp(r.start_time).date() == date]),
'ips': len(set(r.ip for r in request_logs if datetime.fromtimestamp(r.start_time).date() == date)),
} for date in dates]
description = {
'date': ('date', 'Date'),
'requests': ('number', 'Requests'),
'ips': ('number', 'IPs'),
}
data_table = gviz_api.DataTable(description)
data_table.LoadData(data)
template_values['logs_json'] = data_table.ToJSon(columns_order=('date', 'requests', 'ips'), order_by='date')
template_values['logs'] = [
('Count', len(request_logs)),
('Cost', sum(r.cost for r in request_logs)),
]
for item in CachedStats.all():
item.delete()
res = CachedStats(content = jinja.get_template('tiddownload_stats.html').render(template_values))
res.put()
def _analyze(start, end):
from rogerthat.bizz import monitoring
put_rpcs = defaultdict(list)
def qr_code_scanned(request, log_entry, slog_entry, counters):
params = slog_entry["a"]
sid = params["sid"]
if sid is None:
return
service_identity_email = params["service"]
supported_platform = params["supported_platform"]
from_rogerthat = params["from_rogerthat"]
sid_key = (service_identity_email, sid)
counters[sid_key] = counters.get(sid_key, dict(total=0, from_rogerthat=0, supported=0, unsupported=0))
sid_counters = counters[sid_key]
sid_counters["total"] += 1
if from_rogerthat:
sid_counters["from_rogerthat"] += 1
else:
sid_counters['supported' if supported_platform else 'unsupported'] += 1
def store_stats_qr_scans(counters):
sid_rpcs = list()
for (service_identity_email, sid), sid_counters in counters.iteritems():
sid_key = db.Key.from_path(ServiceInteractionDef.kind(), sid,
parent=parent_key(get_service_user_from_service_identity_user(users.User(service_identity_email))))
sid_rpcs.append((db.get_async(sid_key), sid_counters))
for sid_rpc, sid_counters in sid_rpcs:
sid = sid_rpc.get_result()
sid.totalScanCount += sid_counters["total"]
sid.scannedFromRogerthatCount += sid_counters["from_rogerthat"]
sid.scannedFromOutsideRogerthatOnSupportedPlatformCount += sid_counters['supported']
sid.scannedFromOutsideRogerthatOnUnsupportedPlatformCount += sid_counters['unsupported']
put_rpcs['qr_scans'].append(db.put_async(sid))
def service_api_failure(request, log_entry, slog_entry, counters):
params = slog_entry["a"]
service_identity_email = params["service"]
call_type = params["call_type"]
counters[service_identity_email] = counters.get(service_identity_email, dict(Call=0, CallBack=0))
sie_counters = counters[service_identity_email]
sie_counters[call_type] += 1
def store_stats_api_failures(counters):
keys = [ServiceAPIFailures.key_from_service_user_email(k) for k in counters.keys()]
safs = db.get(keys)
for i in xrange(len(keys)):
key = keys[i]
saf = safs[i]
if not saf:
saf = ServiceAPIFailures(key=key, creationTime=now(), failedCalls=0, failedCallBacks=0)
safs[i] = saf
saf.failedCalls += counters[key.name()][monitoring.SERVICE_API_CALL]
saf.failedCallBacks += counters[key.name()][monitoring.SERVICE_API_CALLBACK]
for chunk in chunks(safs, 200):
db.put(chunk)
def service_user_stats(request, log_entry, slog_entry, counters):
params = slog_entry["a"]
service_identity_user_email = params["service"]
tag = params["tag"]
type_ = params["type_"]
counters[service_identity_user_email] = counters.get(service_identity_user_email, dict(
gained=list(), lost=list(), menuItemPress=list(), recommendViaRogerthat=list(), recommendViaEmail=list()))
sid_counters = counters[service_identity_user_email]
sid_counters[type_].append(tag)
def store_service_user_stats(counters):
sid_rpcs = list()
for (service_identity_user_email), sid_counters in counters.iteritems():
sevice_identity_user = users.User(service_identity_user_email)
sid_key = ServiceIdentityStatistic.create_key(sevice_identity_user)
sid_rpcs.append((db.get_async(sid_key), sid_counters, sid_key, sevice_identity_user))
for sid_rpc, sid_counters, sid_key, sevice_identity_user in sid_rpcs:
sid = sid_rpc.get_result()
new_sid = False
if not sid:
new_sid = True
sid = ServiceIdentityStatistic(key=sid_key)
sid.users_gained = list()
sid.users_lost = list()
sid.last_ten_users_gained = list()
sid.last_ten_users_lost = list()
sid.recommends_via_rogerthat = list()
sid.recommends_via_email = list()
sid.mip_labels = list()
now_ = datetime.datetime.utcnow()
today = int("%d%02d%02d" % (now_.year, now_.month, now_.day))
if today != sid.last_entry_day:
if new_sid:
add_days = 1
else:
tmp = str(sid.last_entry_day)
start = datetime.date(int(tmp[0:4]), int(tmp[4:6]), int(tmp[6:8]))
end = datetime.date(now_.year, now_.month, now_.day)
delta = end - start
add_days = delta.days
sid.last_entry_day = today
def do(lst):
for _ in xrange(add_days):
lst.append(0)
if len(lst) > 1000:
lst.pop(0)
do(sid.users_gained)
do(sid.users_lost)
do(sid.recommends_via_rogerthat)
do(sid.recommends_via_email)
for i in xrange(len(sid.mip_labels)):
do(getattr(sid, 'mip_%s' % i))
gained = sid_counters[SERVICE_STATS_TYPE_GAINED]
if new_sid:
sid.number_of_users = count_users_connected_to_service_identity(sevice_identity_user)
sid.last_ten_users_gained.extend(gained)
sid.last_ten_users_gained = sid.last_ten_users_gained[-10:]
sid.users_gained[-1] = sid.users_gained[-1] + len(gained)
lost = sid_counters[SERVICE_STATS_TYPE_LOST]
sid.last_ten_users_lost.extend(lost)
sid.last_ten_users_lost = sid.last_ten_users_lost[-10:]
sid.users_lost[-1] = sid.users_lost[-1] + len(lost)
recommendsViaRogerthat = sid_counters[SERVICE_STATS_TYPE_RECOMMEND_VIA_ROGERTHAT]
recommendsViaEmail = sid_counters[SERVICE_STATS_TYPE_RECOMMEND_VIA_EMAIL]
sid.recommends_via_rogerthat[-1] = sid.recommends_via_rogerthat[-1] + len(recommendsViaRogerthat)
sid.recommends_via_email[-1] = sid.recommends_via_email[-1] + len(recommendsViaEmail)
if not new_sid:
sid.number_of_users = sid.number_of_users + len(gained) - len(lost)
sid.gained_last_week = sum(sid.users_gained[-7:])
sid.lost_last_week = sum(sid.users_lost[-7:])
for x in sid_counters[SERVICE_STATS_TYPE_MIP]:
if x not in sid.mip_labels:
sid.mip_labels.append(x)
i = sid.mip_labels.index(x)
l = list()
l.append(1)
setattr(sid, 'mip_%s' % i, l)
else:
i = sid.mip_labels.index(x)
l = getattr(sid, 'mip_%s' % i)
l[-1] = l[-1] + 1
setattr(sid, 'mip_%s' % i, l)
put_rpcs['service_user_stats'].append(db.put_async(sid))
def broadcast_stats(request, log_entry, slog_entry, counters):
params = slog_entry["a"]
service_identity_user_email = params["service"]
type_ = params["type_"]
broadcast_guid = params["broadcast_guid"]
counters[broadcast_guid] = counters.get(
broadcast_guid, dict(sent=0, received=0, read=0, service_identity_user_email=service_identity_user_email))
sid_counters = counters[broadcast_guid]
sid_counters[type_] += 1
def store_broadcast_stats(counters):
broadcast_stats_rpcs = list()
for (broadcast_guid), broadcast_counters in counters.iteritems():
service_identity_user = users.User(broadcast_counters["service_identity_user_email"])
broadcast_statistic_key = BroadcastStatistic.create_key(broadcast_guid, service_identity_user)
broadcast_stats_rpcs.append(
(db.get_async(broadcast_statistic_key), broadcast_counters, broadcast_statistic_key, broadcast_guid, service_identity_user))
for broadcast_stat_rpc, broadcast_counters, broadcast_statistic_key, broadcast_guid, service_identity_user in broadcast_stats_rpcs:
broadcast_statistic = broadcast_stat_rpc.get_result()
if not broadcast_statistic:
broadcast_statistic = BroadcastStatistic(key=broadcast_statistic_key, timestamp=now())
broadcast_statistic.sent = (broadcast_statistic.sent or 0) + broadcast_counters[BROADCAST_STATS_SENT]
broadcast_statistic.received = (
broadcast_statistic.received or 0) + broadcast_counters[BROADCAST_STATS_RECEIVED]
broadcast_statistic.read = (broadcast_statistic.read or 0) + broadcast_counters[BROADCAST_STATS_READ]
put_rpcs['broadcast_stats'].append(db.put_async(broadcast_statistic))
def flow_stats(request, log_entry, slog_entry, counters):
params = slog_entry['a']
tag = params['tag']
# Key names cannot begin and end with two underscores (__*__)
if tag and not (tag.startswith("_") and tag.endswith("_")):
service_identity_user = users.User(params['service_identity_user'])
today = params['today']
flow_stats_key = str(FlowStatistics.create_key(tag, service_identity_user))
# counters: { flow_stats_key : { today : [(breadcrumbs, statuses, current_step_id, current_btn_id)] } }
counters[flow_stats_key][today].append((params['breadcrumbs'],
params['statuses'],
params['current_step_id'],
params['current_btn_id']))
def store_flow_stats(counters):
to_put = list()
flow_stats_keys = counters.keys()
for flow_stats_key, flow_stats in zip(flow_stats_keys, db.get(flow_stats_keys)):
if not flow_stats:
flow_stats = FlowStatistics(key=flow_stats_key)
to_put.append(flow_stats)
for day, stats_list in sorted(counters[flow_stats_key].iteritems()):
flow_stats.set_today(datetime.datetime.utcfromtimestamp(day).date())
for breadcrumbs, statuses, current_step_id, current_btn_id in stats_list:
for status in statuses:
btn_id = current_btn_id if status == FlowStatistics.STATUS_ACKED else None
flow_stats.add(breadcrumbs, current_step_id, status, btn_id)
for chunk in chunks(to_put, 200):
put_rpcs['flow_stats'].append(db.put_async(chunk))
def news_statistics(request, log_entry, slog_entry, counters):
"""counters = {caches_to_clear: {app_id_1, app_id_2...}
},
'news_to_update': {
'465489498': {
'rogerthat': {
'stats_reached': 35,
'stats_gender': [0, 3, 5], # other, male, female
'stats_time': [42, 32, 12, 14, 2, 0], # per hour
'stats_age': [0, 0, 0, 1, 0, 5, 5], # 21 long, first elem = unknown age, 2nd = 0-5, 3rd: 5-10, ...
}
}
}
}
}"""
user_email = slog_entry['e'] if 'e' in slog_entry else None # Should only be None for NEWS_SPONSORING_TIMED_OUT
params = slog_entry['a']
action = params['action']
_now = now()
if action in (NEWS_REACHED, NEWS_ROGERED, NEWS_NEW_FOLLOWER, NEWS_ACTION):
app_id = params['app_id']
user_profile = get_user_profile(users.User(user_email))
age_index = NewsItemStatistics.get_age_index(user_profile.age)
gender_index = NewsItemStatistics.get_gender_index(user_profile.gender)
for news_id in params['news_ids']:
if app_id not in counters['news_to_update'][news_id]:
counters['news_to_update'][news_id][app_id] = {}
news_updates = counters['news_to_update'][news_id][app_id]
if action == NEWS_REACHED:
news_updates['reached'] = news_updates.get('reached', 0) + 1
elif action == NEWS_ROGERED:
users_that_rogered = news_updates.get('rogered', set())
users_that_rogered.add(users.User(user_email))
news_updates['rogered'] = users_that_rogered
elif action == NEWS_NEW_FOLLOWER:
news_updates['follow_count'] = news_updates.get('follow_count', 0) + 1
elif action == NEWS_ACTION:
news_updates['action_count'] = news_updates.get('action_count', 0) + 1
stats_key = 'stats_%s' % action
if stats_key not in news_updates:
news_updates[stats_key] = defaultdict(lambda: dict)
news_updates[stats_key]['gender'] = news_updates[stats_key].get('gender',
NewsItemStatistics.default_gender_stats())
news_updates[stats_key]['gender'][gender_index] += 1
news_updates[stats_key]['time'] = news_updates[stats_key].get('time', {})
news_updates[stats_key]['time'][_now] = news_updates[stats_key]['time'].get(_now, 0) + 1
news_updates[stats_key]['age'] = news_updates[stats_key].get('age',
NewsItemStatistics.default_age_stats())
news_updates[stats_key]['age'][age_index] += 1
elif action == NEWS_CREATED:
# add a new dict if news_id not yet in news_to_update (defaultdict)
counters['news_to_update'][params['news_id']]
elif action == NEWS_SPONSORING_TIMED_OUT:
counters['news_to_update'][params['news_id']]['sticky_timed_out'] = True
elif action == NEWS_UPDATED:
counters['caches_to_clear']['app_ids'].update(params['app_ids'])
def store_news_actions(counters):
from google.appengine.api import memcache
from rogerthat.settings import get_server_settings
from rogerthat.to.news import NewsItemTO
from mcfw.serialization import serialize
from rogerthat.bizz.news import setup_news_statistics_count_for_news_item
news_to_update = counters['news_to_update']
news_ids = news_to_update.keys()
news_ds_objects = NewsItem.get_by_id(news_ids)
news_items = {}
for news_id, news_item in zip(news_ids, news_ds_objects):
if news_item:
news_items[news_id] = news_item
if news_item.statistics is None:
news_item.statistics = NewsStatisticPerApp()
for app_id in news_item.app_ids:
news_item.statistics[app_id] = NewsItemStatistics.default_statistics()
else:
logging.warn('Skipping summarize for news item %s since it was not found.', news_id)
for news_id, news_item in news_items.iteritems():
updated = False
assert (isinstance(news_item, NewsItem))
news_item_datetime = datetime.datetime.utcfromtimestamp(news_item.timestamp)
if news_item.follow_count < 0:
setup_news_statistics_count_for_news_item(news_item)
updated = True
for app_id, update in news_to_update[news_id].iteritems():
if app_id == 'sticky_timed_out':
sponsoring_timed_out = update
if sponsoring_timed_out and news_item.sticky:
news_item.sticky = False
updated = True
continue
reached = update.get('reached')
if reached:
news_item.reach += reached
updated = True
rogered = update.get('rogered')
if rogered:
news_item.rogered = True
news_item.users_that_rogered.extend(rogered)
updated = True
follow_count = update.get('follow_count')
if follow_count:
news_item.follow_count += follow_count
updated = True
action_count = update.get('action_count')
if action_count:
news_item.action_count += action_count
updated = True
for action in (NEWS_REACHED, NEWS_ROGERED, NEWS_NEW_FOLLOWER, NEWS_ACTION):
added_statistics = update.get('stats_%s' % action)
if added_statistics:
updated = True
key = action.replace('news.', '')
for prop in ('age', 'gender', 'time'):
statistic_property = '%s_%s' % (key, prop)
default_stats = getattr(NewsItemStatistics, 'default_%s_stats' % prop)()
original_statistics = getattr(news_item.statistics[app_id], statistic_property,
default_stats)
if prop == 'time':
# This is a dict instead of a list
for timestamp, value in added_statistics[prop].iteritems():
item_date = datetime.datetime.utcfromtimestamp(timestamp)
hour_index = NewsItemStatistics.get_time_index(news_item_datetime, item_date)
diff = hour_index - len(original_statistics) + 1
for i in xrange(diff):
original_statistics.append(0)
original_statistics[hour_index] += value
else:
for i, value in enumerate(added_statistics[prop]):
original_statistics[i] += value
if news_item.statistics[app_id] is None:
news_item.statistics[app_id] = NewsItemStatistics.default_statistics()
setattr(news_item.statistics[app_id], statistic_property, original_statistics)
if not updated:
del news_items[news_id] # don't include in db.put
if len(news_items):
server_settings = get_server_settings()
def create_news_item_to(news_item):
return NewsItemTO.from_model(news_item, server_settings.baseUrl)
logging.info('Summarize: updating %d news items\n%s', len(news_items), news_items.keys())
for chunk in chunks(news_items.values(), 200):
put_rpcs['news_stats'].append(db.put_async(chunk))
memcache_data = dict()
for news_item in chunk:
to = create_news_item_to(news_item)
memcache_data[str(to.id)] = serialize(NewsItemTO, to)
memcache.set_multi(memcache_data, time=600, namespace='v1.news') # @UndefinedVariable
amap = {
QRCODE_SCANNED: dict(analysis_func=qr_code_scanned, summarize_func=store_stats_qr_scans,
counters=dict()),
SERVICE_MONITOR: dict(analysis_func=service_api_failure, summarize_func=store_stats_api_failures,
counters=dict()),
SERVICE_STATS: dict(analysis_func=service_user_stats, summarize_func=store_service_user_stats,
counters=dict()),
BROADCAST_STATS: dict(analysis_func=broadcast_stats, summarize_func=store_broadcast_stats,
counters=dict()),
FLOW_STATS: dict(analysis_func=flow_stats, summarize_func=store_flow_stats,
counters=defaultdict(lambda: defaultdict(list))),
NEWS: {
'analysis_func': news_statistics,
'summarize_func': store_news_actions,
'counters': {
'news_to_update': defaultdict(dict),
'caches_to_clear': {
'news': set(),
'app_ids': set()
}
}
},
}
slog_header_length = len(SLOG_HEADER)
offset = None
while True:
logs = logservice.fetch(start_time=start, end_time=end, offset=offset,
minimum_log_level=logservice.LOG_LEVEL_INFO, include_incomplete=False,
include_app_logs=True)
count = 0
for log in logs:
count += 1
offset = log.offset
for app_log in log.app_logs:
if app_log.message and app_log.message.startswith(SLOG_HEADER):
slog_value = app_log.message[slog_header_length + 1:]
try:
slog_value = json.loads(slog_value)
except:
logging.exception("Failed to parse slog entry:\n%s" % slog_value)
continue
ftie = slog_value.get("f", None)
if not ftie:
continue
analyzer = amap.get(ftie, None)
if not analyzer:
continue
analyzer["analysis_func"](log, app_log, slog_value, analyzer["counters"])
if count == 0:
break
# summarize could be paralellized in the future. See http://docs.python.org/library/queue.html
try:
key = None
for mapping in amap.itervalues():
mapping["summarize_func"](mapping["counters"])
for key, rpc_list in put_rpcs.iteritems():
for rpc_item in rpc_list:
rpc_item.get_result()
except:
logging.exception("Failed to execute summarize of '%s'!" % key, _suppress=False)
