diff --git a/ovirt_imageio/_internal/auth.py b/ovirt_imageio/_internal/auth.py index cb86f03a..b4e22e1d 100644 --- a/ovirt_imageio/_internal/auth.py +++ b/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,10 +318,11 @@ 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. @@ -329,10 +330,10 @@ def cancel(self, timeout=60): 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 diff --git a/ovirt_imageio/_internal/errors.py b/ovirt_imageio/_internal/errors.py index 2dcb8c9f..fb7b891b 100644 --- a/ovirt_imageio/_internal/errors.py +++ b/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): diff --git a/ovirt_imageio/_internal/handlers/checksum.py b/ovirt_imageio/_internal/handlers/checksum.py index e9eacf7b..1f6d59af 100644 --- a/ovirt_imageio/_internal/handlers/checksum.py +++ b/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. diff --git a/ovirt_imageio/_internal/handlers/extents.py b/ovirt_imageio/_internal/handlers/extents.py index b02ad87b..eca7057d 100644 --- a/ovirt_imageio/_internal/handlers/extents.py +++ b/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: diff --git a/ovirt_imageio/_internal/handlers/images.py b/ovirt_imageio/_internal/handlers/images.py index b374ab29..cade4e5e 100644 --- a/ovirt_imageio/_internal/handlers/images.py +++ b/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() diff --git a/ovirt_imageio/_internal/handlers/tickets.py b/ovirt_imageio/_internal/handlers/tickets.py index 3f771be7..9603ccc1 100644 --- a/ovirt_imageio/_internal/handlers/tickets.py +++ b/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 diff --git a/test/auth_test.py b/test/auth_test.py index be6c6c14..9527561d 100644 --- a/test/auth_test.py +++ b/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.