def test_collection_timestamp_returns_now_when_collection_is_empty(self):
before = utils.msec_time()
time.sleep(0.001) # 1 msec
now = self.storage.collection_timestamp(**self.storage_kw)
time.sleep(0.001) # 1 msec
after = utils.msec_time()
self.assertTrue(before < now < after,
'%s < %s < %s' % (before, now, after))
def test_the_timestamp_are_based_on_real_time_milliseconds(self):
before = utils.msec_time()
time.sleep(0.001) # 1 msec
record = self.storage.create(self.resource, self.user_id, {})
now = record['last_modified']
time.sleep(0.001) # 1 msec
after = utils.msec_time()
self.assertTrue(before < now < after,
'%s < %s < %s' % (before, now, after))
def test_the_timestamp_are_based_on_real_time_milliseconds(self):
before = utils.msec_time()
time.sleep(0.002) # 2 msec
record = self.create_record()
now = record['last_modified']
time.sleep(0.002) # 2 msec
after = utils.msec_time()
self.assertTrue(before < now < after,
'%s < %s < %s' % (before, now, after))
def on_new_response(event):
response = event.response
request = event.request
# Compute the request processing time in msec (-1 if unknown)
current = utils.msec_time()
duration = current - getattr(request, "_received_at", current - 1)
isotimestamp = datetime.fromtimestamp(current / 1000).isoformat()
# Bind infos for request summary logger.
logger.bind(time=isotimestamp, code=response.status_code, t=duration)
# Ouput application request summary.
logger.info("request.summary")
def on_new_request(event):
request = event.request
# Save the time the request was received by the server.
event.request._received_at = utils.msec_time()
# New logger context, with infos for request summary logger.
logger.new(agent=request.headers.get('User-Agent'),
path=event.request.path,
method=request.method,
querystring=dict(request.GET),
uid=request.authenticated_userid,
lang=request.headers.get('Accept-Language'),
auth_type=getattr(request, 'auth_type', None),
errno=None)
def on_new_request(event):
request = event.request
# Save the time the request was received by the server.
event.request._received_at = utils.msec_time()
# New logger context, with infos for request summary logger.
logger.new(agent=request.headers.get('User-Agent'),
path=event.request.path,
method=request.method,
querystring=dict(request.GET),
lang=request.headers.get('Accept-Language'),
uid=None,
authn_type=None,
errno=None)
def _bump_timestamp(self, resource, user_id):
"""Timestamp are base on current millisecond.
.. note ::
Here it is assumed that if requests from the same user burst in,
the time will slide into the future. It is not problematic since
the timestamp notion is opaque, and behaves like a revision number.
"""
previous = self._timestamps[resource.name].get(user_id)
current = utils.msec_time()
if previous and previous >= current:
current = previous + 1
self._timestamps[resource.name][user_id] = current
return current
def on_new_response(event):
response = event.response
request = event.request
# Compute the request processing time in msec (-1 if unknown)
current = utils.msec_time()
duration = current - getattr(request, '_received_at', current - 1)
isotimestamp = datetime.fromtimestamp(current / 1000).isoformat()
# Bind infos for request summary logger.
logger.bind(time=isotimestamp, code=response.status_code, t=duration)
# Ouput application request summary.
if not hasattr(request, 'parent'):
logger.info('request.summary')
def _bump_timestamp(self,
collection_id,
parent_id,
record=None,
modified_field=None,
last_modified=None):
key = '{0}.{1}.timestamp'.format(collection_id, parent_id)
while 1:
with self._client.pipeline() as pipe:
try:
pipe.watch(key)
previous = pipe.get(key)
pipe.multi()
# XXX factorize code from memory and redis backends.
is_specified = (record is not None
and modified_field in record
or last_modified is not None)
if is_specified:
# If there is a timestamp in the new record,
# try to use it.
if last_modified is not None:
current = last_modified
else:
current = record[modified_field]
else:
current = utils.msec_time()
if previous and int(previous) >= current:
collection_timestamp = int(previous) + 1
else:
collection_timestamp = current
# Return the newly generated timestamp as the current one
# only if nothing else was specified.
if not is_specified:
current = collection_timestamp
pipe.set(key, collection_timestamp)
pipe.execute()
return current
except redis.WatchError: # pragma: no cover
# Our timestamp has been modified by someone else, let's
# retry.
# XXX: untested.
continue
def __call__(self, logger, name, event_dict):
SYSLOG_LEVELS = {
'critical': 0,
'fatal': 0,
'exception': 2,
'error': 2,
'warning': 4,
'info': 6,
'debug': 7,
}
severity = SYSLOG_LEVELS[name]
MSEC_TO_NANOSEC = 1000000
timestamp = utils.msec_time() * MSEC_TO_NANOSEC
event = event_dict.pop('event', '')
defaults = {
'Timestamp': timestamp,
'Logger': self.appname,
'Type': event,
'Hostname': self.hostname,
'Severity': severity,
'Pid': self.pid,
'EnvVersion': self.ENV_VERSION,
'Fields': {}
}
for f, v in defaults.items():
event_dict.setdefault(f, v)
fields = [k for k in event_dict.keys() if k not in defaults]
for f in fields:
value = event_dict.pop(f)
# Heka relies on Protobuf, which doesn't support recursive objects.
if isinstance(value, (dict)):
value = utils.json.dumps(value)
elif isinstance(value, (list, tuple)):
if not all([isinstance(i, six.string_types) for i in value]):
value = utils.json.dumps(value)
event_dict['Fields'][f] = value
return utils.json.dumps(event_dict)
def __call__(self, logger, name, event_dict):
SYSLOG_LEVELS = {
'critical': 0,
'fatal': 0,
'exception': 2,
'error': 2,
'warning': 4,
'info': 6,
'debug': 7,
}
severity = SYSLOG_LEVELS[name]
MSEC_TO_NANOSEC = 1000000
timestamp = utils.msec_time() * MSEC_TO_NANOSEC
event = event_dict.pop('event', '')
defaults = {
'Timestamp': timestamp,
'Logger': self.appname,
'Type': event,
'Hostname': self.hostname,
'Severity': severity,
'Pid': self.pid,
'EnvVersion': self.ENV_VERSION,
'Fields': {}
}
for f, v in defaults.items():
event_dict.setdefault(f, v)
fields = [k for k in event_dict.keys() if k not in defaults]
for f in fields:
value = event_dict.pop(f)
# Heka relies on Protobuf, which doesn't support recursive objects.
if isinstance(value, dict):
value = utils.json.dumps(value)
elif isinstance(value, (list, tuple)):
if not all([isinstance(i, six.string_types) for i in value]):
value = utils.json.dumps(value)
event_dict['Fields'][f] = value
return utils.json.dumps(event_dict)
def _bump_timestamp(self, collection_id, parent_id, record=None,
modified_field=None, last_modified=None):
key = '{0}.{1}.timestamp'.format(collection_id, parent_id)
while 1:
with self._client.pipeline() as pipe:
try:
pipe.watch(key)
previous = pipe.get(key)
pipe.multi()
# XXX factorize code from memory and redis backends.
is_specified = (record is not None and
modified_field in record or
last_modified is not None)
if is_specified:
# If there is a timestamp in the new record,
# try to use it.
if last_modified is not None:
current = last_modified
else:
current = record[modified_field]
else:
current = utils.msec_time()
if previous and int(previous) >= current:
collection_timestamp = int(previous) + 1
else:
collection_timestamp = current
# Return the newly generated timestamp as the current one
# only if nothing else was specified.
if not is_specified:
current = collection_timestamp
pipe.set(key, collection_timestamp)
pipe.execute()
return current
except redis.WatchError: # pragma: no cover
# Our timestamp has been modified by someone else, let's
# retry.
# XXX: untested.
continue
def _bump_timestamp(self,
collection_id,
parent_id,
record=None,
modified_field=None,
last_modified=None):
"""Timestamp are base on current millisecond.
.. note ::
Here it is assumed that if requests from the same user burst in,
the time will slide into the future. It is not problematic since
the timestamp notion is opaque, and behaves like a revision number.
"""
# XXX factorize code from memory and redis backends.
is_specified = (record is not None and modified_field in record
or last_modified is not None)
if is_specified:
# If there is a timestamp in the new record, try to use it.
if last_modified is not None:
current = last_modified
else:
current = record[modified_field]
else:
# Otherwise, use a new one.
current = utils.msec_time()
# Bump the timestamp only if it's more than the previous one.
previous = self._timestamps[collection_id].get(parent_id)
if previous and previous >= current:
collection_timestamp = previous + 1
else:
collection_timestamp = current
# In case the timestamp was specified, the collection timestamp will
# be different from the updated timestamp. As such, we want to return
# the one of the record, and not the collection one.
if not is_specified:
current = collection_timestamp
self._timestamps[collection_id][parent_id] = collection_timestamp
return current
def _bump_timestamp(self, collection_id, parent_id):
key = '{0}.{1}.timestamp'.format(collection_id, parent_id)
while 1:
with self._client.pipeline() as pipe:
try:
pipe.watch(key)
previous = pipe.get(key)
pipe.multi()
current = utils.msec_time()
if previous and int(previous) >= current:
current = int(previous) + 1
pipe.set(key, current)
pipe.execute()
return current
except redis.WatchError: # pragma: no cover
# Our timestamp has been modified by someone else, let's
# retry.
# XXX: untested.
continue
def _bump_timestamp(self, collection_id, parent_id, record=None,
modified_field=None, last_modified=None):
"""Timestamp are base on current millisecond.
.. note ::
Here it is assumed that if requests from the same user burst in,
the time will slide into the future. It is not problematic since
the timestamp notion is opaque, and behaves like a revision number.
"""
# XXX factorize code from memory and redis backends.
is_specified = (record is not None and
modified_field in record or
last_modified is not None)
if is_specified:
# If there is a timestamp in the new record, try to use it.
if last_modified is not None:
current = last_modified
else:
current = record[modified_field]
else:
# Otherwise, use a new one.
current = utils.msec_time()
# Bump the timestamp only if it's more than the previous one.
previous = self._timestamps[collection_id].get(parent_id)
if previous and previous >= current:
collection_timestamp = previous + 1
else:
collection_timestamp = current
# In case the timestamp was specified, the collection timestamp will
# be different from the updated timestamp. As such, we want to return
# the one of the record, and not the collection one.
if not is_specified:
current = collection_timestamp
self._timestamps[collection_id][parent_id] = collection_timestamp
return current
def expire(self, key, ttl):
self._ttl[self.prefix + key] = utils.msec_time() + int(ttl * 1000.0)
def ttl(self, key):
ttl = self._ttl.get(key)
if ttl is not None:
return (ttl - utils.msec_time()) / 1000.0
return -1
def expire(self, key, ttl):
self._ttl[key] = utils.msec_time() + int(ttl * 1000.0)
def get(self, key):
current = utils.msec_time()
expired = [k for k, v in self._ttl.items() if current > v]
for key in expired:
self.delete(key)
return self._store.get(key)
def deserialize(self, cstruct=colander.null):
if cstruct is colander.null and self.auto_now:
cstruct = msec_time()
return super(TimeStamp, self).deserialize(cstruct)
def ttl(self, key):
ttl = self._ttl.get(self.prefix + key)
if ttl is not None:
return (ttl - utils.msec_time()) / 1000.0
return -1
def deserialize(self, cstruct=colander.null):
if cstruct is colander.null and self.auto_now:
cstruct = msec_time()
return super(TimeStamp, self).deserialize(cstruct)
def get(self, key):
current = utils.msec_time()
expired = [k for k, v in self._ttl.items() if current >= v]
for expired_item_key in expired:
self.delete(expired_item_key[len(self.prefix):])
return self._store.get(self.prefix + key)
