PYTHON-952 - Fix duration measurements.

We weren't including the time to decode responses in a number of places. This commit also fixes an issue with handling "cursor not found" errors from mongos versions older than 2.4.

Author: behackett

pymongo/command_cursor.py

@@ -14,11 +14,13 @@
 
 """CommandCursor class to iterate over command results."""
 
+import datetime
+
 from collections import deque
 
 from bson.py3compat import integer_types
 from pymongo import helpers, monitoring
-from pymongo.errors import AutoReconnect, CursorNotFound, NotMasterError
+from pymongo.errors import AutoReconnect, NotMasterError, OperationFailure
 from pymongo.message import _GetMore
 
 
@@ -101,16 +103,19 @@ def __send_message(self, operation):
  raise
 
  publish = monitoring.enabled()
- duration = response.duration
+ cmd_duration = response.duration
  rqst_id = response.request_id
+ if publish:
+ start = datetime.datetime.now()
  try:
  doc = helpers._unpack_response(response.data,
  self.__id,
  self.__collection.codec_options)
- except CursorNotFound as exc:
+ except OperationFailure as exc:
  self.__killed = True
 
  if publish:
+ duration = (datetime.datetime.now() - start) + cmd_duration
  monitoring.publish_command_failure(
  duration, exc.details, "getMore", rqst_id, self.__address)
 
@@ -121,13 +126,15 @@ def __send_message(self, operation):
  self.__killed = True
 
  if publish:
+ duration = (datetime.datetime.now() - start) + cmd_duration
  monitoring.publish_command_failure(
  duration, exc.details, "getMore", rqst_id, self.__address)
 
  client._reset_server_and_request_check(self.address)
  raise
 
  if publish:
+ duration = (datetime.datetime.now() - start) + cmd_duration
  # Must publish in getMore command response format.
  res = {"cursor": {"id": doc["cursor_id"],
  "ns": self.__collection.full_name,

pymongo/cursor.py

@@ -822,7 +822,7 @@ def __send_message(self, operation):
  response.pool)
 
  data = response.data
- duration = response.duration
+ cmd_duration = response.duration
  rqst_id = response.request_id
  except AutoReconnect:
  # Don't try to send kill cursors on another socket
@@ -833,7 +833,6 @@ def __send_message(self, operation):
  raise
  else:
  # Exhaust cursor - no getMore message.
- duration = None
  rqst_id = 0
  cmd_name = 'getMore'
  if publish:
@@ -853,8 +852,10 @@ def __send_message(self, operation):
  self.__die()
  raise
  if publish:
- duration = datetime.datetime.now() - start
+ cmd_duration = datetime.datetime.now() - start
 
+ if publish:
+ start = datetime.datetime.now()
  try:
  doc = helpers._unpack_response(response=data,
  cursor_id=self.__id,
@@ -866,6 +867,7 @@ def __send_message(self, operation):
  self.__die()
 
  if publish:
+ duration = (datetime.datetime.now() - start) + cmd_duration
  monitoring.publish_command_failure(
  duration, exc.details, cmd_name, rqst_id, self.__address)
 
@@ -885,13 +887,15 @@ def __send_message(self, operation):
  self.__die()
 
  if publish:
+ duration = (datetime.datetime.now() - start) + cmd_duration
  monitoring.publish_command_failure(
  duration, exc.details, cmd_name, rqst_id, self.__address)
 
  client._reset_server_and_request_check(self.__address)
  raise
 
  if publish:
+ duration = (datetime.datetime.now() - start) + cmd_duration
  # Must publish in find / getMore command response format.
  res = {"cursor": {"id": doc["cursor_id"],
  "ns": self.__collection.full_name},

pymongo/helpers.py

@@ -112,6 +112,8 @@ def _unpack_response(response, cursor_id=None, codec_options=CodecOptions()):
  raise CursorNotFound(msg, 43, errobj)
  elif response_flag & 2:
  error_object = bson.BSON(response[20:]).decode()
+ # Fake the ok field if it doesn't exist.
+ error_object.setdefault("ok", 0)
  if error_object["$err"].startswith("not master"):
  raise NotMasterError(error_object["$err"], error_object)
  elif error_object.get("code") == 50:

pymongo/network.py

@@ -73,23 +73,23 @@ def command(sock, dbname, spec, slave_ok, is_mongos,
 
  sock.sendall(msg)
  response = receive_message(sock, 1, request_id)
- unpacked = helpers._unpack_response(response, codec_options=codec_options)
-
- if publish:
- duration = (datetime.datetime.now() - start) + encoding_duration
+ try:
+ unpacked = helpers._unpack_response(
+ response, codec_options=codec_options)
 
- response_doc = unpacked['data'][0]
- msg = "command %s on namespace %s failed: %%s" % (
- repr(spec).replace("%", "%%"), ns)
- if check:
- try:
+ response_doc = unpacked['data'][0]
+ if check:
+ msg = "command %s on namespace %s failed: %%s" % (
+ repr(spec).replace("%", "%%"), ns)
  helpers._check_command_response(response_doc, msg, allowable_errors)
- except (NotMasterError, OperationFailure) as exc:
- if publish:
- monitoring.publish_command_failure(
- duration, exc.details, name, request_id, address)
- raise
+ except (NotMasterError, OperationFailure) as exc:
+ if publish:
+ duration = (datetime.datetime.now() - start) + encoding_duration
+ monitoring.publish_command_failure(
+ duration, exc.details, name, request_id, address)
+ raise
  if publish:
+ duration = (datetime.datetime.now() - start) + encoding_duration
  monitoring.publish_command_success(
  duration, response_doc, name, request_id, address)
  return response_doc

test/test_monitoring.py

@@ -293,11 +293,7 @@ def test_get_more_failure(self):
  self.assertEqual('getMore', failed.command_name)
  self.assertTrue(isinstance(failed.request_id, int))
  self.assertEqual(cursor.address, failed.connection_id)
- expected_result = {
- 'errmsg': "Cursor not found, cursor id: 12345",
- 'code': 43,
- 'ok': 0}
- self.assertEqual(expected_result, failed.failure)
+ self.assertEqual(0, failed.failure.get("ok"))
 
  @client_context.require_replica_set
  def test_not_master_error(self):