logging: Replace ticket id with transfer id

Use the public transfer id instead of the sensitive ticket id used for
authentication. This makes it easier to follow transfer by grepping the
transfer id.

The ticket id is till logged when adding a ticket, we may want to remove
it from the log, or log only a part of the ticket.

Fixes #26

Signed-off-by: Nir Soffer <nsoffer@redhat.com>

ovirt_imageio/_internal/auth.py

@@ -151,10 +151,10 @@ def add_context(self, con_id, context):
         with self._lock:
             if self._canceled:
                 raise errors.AuthorizationError(
-                    "Ticket {} was canceled".format(self.uuid))
+                    "Transfer {} was canceled".format(self.transfer_id))
 
-            log.debug("Adding connection %s context to ticket %s",
-                      con_id, self.uuid)
+            log.debug("Adding connection %s context to transfer %s",
+                      con_id, self.transfer_id)
             self._connections[con_id] = context
 
     def get_context(self, con_id):
@@ -167,8 +167,8 @@ def remove_context(self, con_id):
             except KeyError:
                 return
 
-            log.debug("Removing connection %s context from ticket %s",
-                      con_id, self.uuid)
+            log.debug("Removing connection %s context from transfer %s",
+                      con_id, self.transfer_id)
             context.close()
 
             # If context was closed, it is safe to remove it.
@@ -200,12 +200,12 @@ def _add_operation(self, op):
         with self._lock:
             if self._canceled:
                 raise errors.AuthorizationError(
-                    "Ticket {} was canceled".format(self.uuid))
+                    "Transfer {} was canceled".format(self.transfer_id))
 
             # If this is the first ongoing operation, clear the unused event.
             if not self._ongoing:
-                log.debug("Adding first ongoring operation for ticket %s",
-                          self.uuid)
+                log.debug("Adding first ongoring operation for transfer %s",
+                          self.transfer_id)
                 self._unused.clear()
 
             self._ongoing.add(op)
@@ -217,13 +217,13 @@ def _remove_operation(self, op):
             # If this was the last ongoing operation, wake up caller waiting on
             # cancel().
             if not self._ongoing:
-                log.debug("Removed last ongoring operation for ticket %s",
-                          self.uuid)
+                log.debug("Removed last ongoring operation for transfer %s",
+                          self.transfer_id)
                 self._unused.set()
 
             if self._canceled:
                 raise errors.AuthorizationError(
-                    "Ticket {} was canceled".format(self.uuid))
+                    "Transfer {} was canceled".format(self.transfer_id))
 
             r = measure.Range(op.offset, op.offset + op.done)
             bisect.insort(self._completed, r)
@@ -306,7 +306,7 @@ def cancel(self, timeout=60):
             errors.TicketCancelTimeout if timeout is non-zero and the ticket is
             still used when the timeout expires.
         """
-        log.debug("Cancelling ticket %s", self.uuid)
+        log.debug("Cancelling transfer %s", self.transfer_id)
 
         with self._lock:
             # No operation can start now, and new connections cannot be added
@@ -318,21 +318,22 @@ def cancel(self, timeout=60):
                 # connections - release their resources.
                 for ctx in self._connections.values():
                     ctx.close()
-                log.debug("Ticket %s was canceled", self.uuid)
+                log.debug("Transfer %s was canceled", self.transfer_id)
                 return True
 
-            log.debug("Canceling ticket %s ongoing operations", self.uuid)
+            log.debug("Canceling transfer %s ongoing operations",
+                      self.transfer_id)
             # Cancel ongoing operations. This speeds up cancellation when
             # streaming lot of data. Operations will be canceled once they
             # complete the current I/O.
             for op in self._ongoing:
                 op.cancel()
 
         if timeout:
-            log.info("Waiting until ticket %s ongoing operations finish",
-                     self.uuid)
+            log.info("Waiting until transfer %s ongoing operations finish",
+                     self.transfer_id)
             if not self._unused.wait(timeout):
-                raise errors.TicketCancelTimeout(self.uuid)
+                raise errors.TransferCancelTimeout(self.transfer_id)
 
             # Finished ongoing operations discover that the ticket was canceled
             # and close the connection. We need to release resources used by
@@ -341,7 +342,7 @@ def cancel(self, timeout=60):
                 for ctx in self._connections.values():
                     ctx.close()
 
-            log.info("Ticket %s was canceled", self.uuid)
+            log.info("Transfer %s was canceled", self.transfer_id)
             return True
 
         # The caller need to wait until ongoing operations finish by polling
@@ -419,8 +420,8 @@ def remove(self, ticket_id):
             return
 
         # Cancel the ticket and wait until the ticket is unused. Will raise
-        # errors.TicketCancelTimeout if the ticket could not be canceled within
-        # the timeout.
+        # errors.TransferCancelTimeout if the ticket could not be canceled
+        # within the timeout.
         if ticket.cancel(self._config.control.remove_timeout):
             # Ticket is unused now, so it is safe to remove it.
             del self._tickets[ticket_id]
@@ -439,23 +440,24 @@ def authorize(self, ticket_id, op):
         """
         Authorizing a ticket operation
         """
-        log.debug("AUTH op=%s ticket=%s", op, ticket_id)
         try:
             ticket = self._tickets[ticket_id]
         except KeyError:
             raise errors.AuthorizationError(
                 "No such ticket {}".format(ticket_id))
 
+        log.debug("AUTH op=%s transfer=%s", op, ticket.transfer_id)
+
         if ticket.canceled:
             raise errors.AuthorizationError(
-                "Ticket {} was canceled".format(ticket_id))
+                "Transfer={} was canceled".format(ticket.transfer_id))
 
         if ticket.expires <= util.monotonic_time():
             raise errors.AuthorizationError(
-                "Ticket {} expired".format(ticket_id))
+                "Transfer={} expired".format(ticket.transfer_id))
 
         if not ticket.may(op):
             raise errors.AuthorizationError(
-                "Ticket {} forbids {}".format(ticket_id, op))
+                "Transfer={} forbids {}".format(ticket.transfer_id, op))
 
         return ticket

ovirt_imageio/_internal/errors.py

@@ -50,11 +50,11 @@ def __init__(self, reason):
         self.reason = reason
 
 
-class TicketCancelTimeout(Error):
-    msg = "Timeout cancelling ticket {self.ticket_id}"
+class TransferCancelTimeout(Error):
+    msg = "Timeout cancelling transfer {self.transfer_id}"
 
-    def __init__(self, ticket_id):
-        self.ticket_id = ticket_id
+    def __init__(self, transfer_id):
+        self.transfer_id = transfer_id
 
 
 class UnsupportedOperation(Error):

ovirt_imageio/_internal/handlers/checksum.py

@@ -69,8 +69,8 @@ def get(self, req, resp, ticket_id):
         except errors.AuthorizationError as e:
             raise http.Error(http.FORBIDDEN, str(e))
 
-        log.info("[%s] CHECKSUM ticket=%s algorithm=%s block_size=%s",
-                 req.client_addr, ticket_id, algorithm, block_size)
+        log.info("[%s] CHECKSUM transfer=%s algorithm=%s block_size=%s",
+                 req.client_addr, ticket.transfer_id, algorithm, block_size)
 
         # For simplicity we create a new buffer even if block_size is same as
         # ctx.buffer length.

ovirt_imageio/_internal/handlers/extents.py

@@ -43,8 +43,8 @@ def get(self, req, resp, ticket_id):
             raise http.Error(
                 http.NOT_FOUND, "Ticket does not support dirty extents")
 
-        log.info("[%s] EXTENTS ticket=%s context=%s",
-                 req.client_addr, ticket_id, context)
+        log.info("[%s] EXTENTS transfer=%s context=%s",
+                 req.client_addr, ticket.transfer_id, context)
 
         with req.clock.run("extents"):
             try:

ovirt_imageio/_internal/handlers/images.py

@@ -62,8 +62,8 @@ def put(self, req, resp, ticket_id):
         validate.allowed_range(offset, size, ticket)
 
         log.debug(
-            "[%s] WRITE size=%d offset=%d flush=%s close=%s ticket=%s",
-            req.client_addr, size, offset, flush, close, ticket_id)
+            "[%s] WRITE size=%d offset=%d flush=%s close=%s transfer=%s",
+            req.client_addr, size, offset, flush, close, ticket.transfer_id)
 
         op = ops.Write(
             ctx.backend,
@@ -121,8 +121,8 @@ def get(self, req, resp, ticket_id):
             size = min(ticket.size, ctx.backend.size()) - offset
 
         log.debug(
-            "[%s] READ size=%d offset=%d close=%s ticket=%s",
-            req.client_addr, size, offset, close, ticket_id)
+            "[%s] READ size=%d offset=%d close=%s transfer=%s",
+            req.client_addr, size, offset, close, ticket.transfer_id)
 
         content_disposition = "attachment"
         if ticket.filename:
@@ -187,8 +187,8 @@ def _zero(self, req, resp, ticket_id, msg):
         validate.allowed_range(offset, size, ticket)
 
         log.debug(
-            "[%s] ZERO size=%d offset=%d flush=%s ticket=%s",
-            req.client_addr, size, offset, flush, ticket_id)
+            "[%s] ZERO size=%d offset=%d flush=%s transfer=%s",
+            req.client_addr, size, offset, flush, ticket.transfer_id)
 
         op = ops.Zero(
             ctx.backend,
@@ -213,7 +213,8 @@ def _flush(self, req, resp, ticket_id, msg):
             resp.close_connection()
             raise http.Error(http.FORBIDDEN, str(e))
 
-        log.info("[%s] FLUSH ticket=%s", req.client_addr, ticket_id)
+        log.info("[%s] FLUSH transfer=%s",
+                 req.client_addr, ticket.transfer_id)
 
         op = ops.Flush(ctx.backend, clock=req.clock)
 
@@ -228,14 +229,13 @@ def options(self, req, resp, ticket_id):
         if not ticket_id:
             raise http.Error(http.BAD_REQUEST, "Ticket id is required")
 
-        log.info("[%s] OPTIONS ticket=%s", req.client_addr, ticket_id)
-
         options = {}
 
         if self.config.local.enable:
             options["unix_socket"] = self.config.local.socket
 
         if ticket_id == "*":
+            log.info("[%s] OPTIONS transfer=*", req.client_addr)
             # Reporting the meta-capabilities for all images.
             allow = ["OPTIONS", "GET", "PUT", "PATCH"]
             options["features"] = ALL_FEATURES
@@ -248,6 +248,9 @@ def options(self, req, resp, ticket_id):
                 resp.close_connection()
                 raise http.Error(http.FORBIDDEN, str(e))
 
+            log.info("[%s] OPTIONS transfer=%s",
+                     req.client_addr, ticket.transfer_id)
+
             # Accessing ticket options considered as client activity.
             ticket.touch()
 

ovirt_imageio/_internal/handlers/tickets.py

@@ -36,7 +36,7 @@ def get(self, req, resp, ticket_id):
                 http.NOT_FOUND, "No such ticket {!r}".format(ticket_id))
 
         ticket_info = ticket.info()
-        log.debug("[%s] GET ticket=%s", req.client_addr, ticket_info)
+        log.debug("[%s] GET transfer=%s", req.client_addr, ticket.transfer_id)
         resp.send_json(ticket_info)
 
     def put(self, req, resp, ticket_id):
@@ -52,7 +52,7 @@ def put(self, req, resp, ticket_id):
                 http.BAD_REQUEST,
                 "Ticket is not in a json format: {}".format(e))
 
-        log.info("[%s] ADD ticket=%s", req.client_addr, ticket_dict)
+        log.info("[%s] ADD transfer=%s", req.client_addr, ticket_dict)
         try:
             self.auth.add(ticket_dict)
         except errors.InvalidTicket as e:
@@ -79,8 +79,8 @@ def patch(self, req, resp, ticket_id):
             raise http.Error(
                 http.NOT_FOUND, "No such ticket: {}".format(ticket_id))
 
-        log.info("[%s] EXTEND timeout=%s ticket=%s",
-                 req.client_addr, timeout, ticket_id)
+        log.info("[%s] EXTEND timeout=%s transfer=%s",
+                 req.client_addr, timeout, ticket.transfer_id)
         ticket.extend(timeout)
 
     def delete(self, req, resp, ticket_id):
@@ -91,17 +91,24 @@ def delete(self, req, resp, ticket_id):
         requests in case of network failures. See
         https://tools.ietf.org/html/rfc7231#section-4.2.2.
         """
-        log.info("[%s] REMOVE ticket=%s", req.client_addr, ticket_id)
-
         if ticket_id:
             try:
-                self.auth.remove(ticket_id)
-            except errors.TicketCancelTimeout as e:
-                # The ticket is still used by some connection so we cannot
-                # remove it. The caller can retry the call again when the
-                # number connections reach zero.
-                raise http.Error(http.CONFLICT, str(e))
+                ticket = self.auth.get(ticket_id)
+            except KeyError:
+                # Ticket was already deleted.
+                log.info("[%s] REMOVE transfer=(deleted)", req.client_addr)
+            else:
+                log.info("[%s] REMOVE transfer=%s",
+                         req.client_addr, ticket.transfer_id)
+                try:
+                    self.auth.remove(ticket_id)
+                except errors.TicketCancelTimeout as e:
+                    # The ticket is still used by some connection so we cannot
+                    # remove it. The caller can retry the call again when the
+                    # number connections reach zero.
+                    raise http.Error(http.CONFLICT, str(e))
         else:
+            log.info("[%s] REMOVE all tickets", req.client_addr)
             self.auth.clear()
 
         resp.status_code = http.NO_CONTENT

test/auth_test.py

@@ -405,7 +405,7 @@ def test_cancel_timeout(cfg):
     ticket._add_operation(Operation(0, 100))
 
     # Canceling will time out.
-    with pytest.raises(errors.TicketCancelTimeout):
+    with pytest.raises(errors.TransferCancelTimeout):
         ticket.cancel(timeout=0.001)
 
     # Ticket is marked as canceled, but the context was not closed.
@@ -660,7 +660,7 @@ def test_authorizer_remove_timeout(cfg):
     cfg.control.remove_timeout = 0.001
 
     # Ticket cannot be removed since it is used by connection 1.
-    with pytest.raises(errors.TicketCancelTimeout):
+    with pytest.raises(errors.TransferCancelTimeout):
         auth.remove(ticket.uuid)
 
     # Ticket was not removed.