An execption during lock renew

[Indy2222]

We are reading messages from a Service Bus topic with a variant of the
following code block:

client = SubscriptionClient.from_connection_string(
    connection_string, subscription, loop=loop)
receiver = client.get_receiver()
batch = receiver.fetch_next(max_batch_size=1, timeout=30)
...

but during message renew done in an async loop with
message.renew_lock we are getting the following exception:

Traceback (most recent call last):
  File "/usr/lib/python3.6/site-packages/azure/servicebus/aio/async_base_handler.py", line 90, in _mgmt_request_response
    callback=callback)
  File "/usr/lib/python3.6/site-packages/uamqp/async_ops/client_async.py", line 333, in mgmt_request_async
    **kwargs))
  File "/usr/lib/python3.6/site-packages/uamqp/async_ops/session_async.py", line 114, in mgmt_request_async
    return parse_response(status, response, description)
  File "/usr/lib/python3.6/site-packages/azure/servicebus/common/mgmt_handlers.py", line 28, in lock_renew_op
    status_code, description, message.get_data()))
azure.servicebus.common.errors.ServiceBusError: Management request returned status code: 500. Description: b'Unsupported type 0x40 for array. TrackingId:de1b2df6-7cf4-4c7b-a741-ff6d9e310f71_G24, SystemTracker:NoSystemTracker, Timestamp:2019-09-18T11:41:00', Data: None

[kaerm]

@Indy2222 thanks for letting us know, we will take a look at it

[luipir]

I had the same error:

`Failed to complete mgmt operation.
Status code: 500
Message: b'Unsupported type 0x40 for array. TrackingId:7bdddf69-a511-4246-8413-4094e9994a0c_G25, SystemTracker:NoSystemTracker, Timestamp:2019-09-18T16:12:44'
2019-09-18 16:12:44,138 MainThread captura ERROR: Traceback (most recent call last):
File "/usr/local/lib/python3.6/site-packages/azure/servicebus/base_handler.py", line 91, in _mgmt_request_response
callback=callback)
File "/usr/local/lib64/python3.6/site-packages/uamqp/client.py", line 328, in mgmt_request
**kwargs)
File "/usr/local/lib64/python3.6/site-packages/uamqp/session.py", line 126, in mgmt_request
return parse_response(status, response, description)
File "/usr/local/lib/python3.6/site-packages/azure/servicebus/common/mgmt_handlers.py", line 28, in lock_renew_op
status_code, description, message.get_data()))
azure.servicebus.common.errors.ServiceBusError: Management request returned status code: 500. Description: b'Unsupported type 0x40 for array. TrackingId:7bdddf69-a511-4246-8413-4094e9994a0c_G25, SystemTracker:NoSystemTracker, Timestamp:2019-09-18T16:12:44', Data: None

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
File "/home/primarecaptura/primare_orchestrator/tools/captura_roudtrip/captura-roundtrip.py", line 212, in main
primareMessage.startManaging()
File "/home/primarecaptura/primare_orchestrator/tools/captura_roudtrip/primare_message.py", line 101, in startManaging
self.renewLock()
File "/home/primarecaptura/primare_orchestrator/tools/captura_roudtrip/primare_message.py", line 106, in renewLock
self.queueManager.renewLockMessage(message=self.message)
File "/home/primarecaptura/primare_orchestrator/azure_queue_manager.py", line 246, in renewLockMessage
message.renew_lock()
File "/usr/local/lib/python3.6/site-packages/azure/servicebus/common/message.py", line 303, in renew_lock
expiry = self._receiver._renew_locks(self.lock_token) # pylint: disable=protected-access
File "/usr/local/lib/python3.6/site-packages/azure/servicebus/receive_handler.py", line 141, in _renew_locks
mgmt_handlers.lock_renew_op)
File "/usr/local/lib/python3.6/site-packages/azure/servicebus/base_handler.py", line 93, in _mgmt_request_response
raise ServiceBusError("Management request failed: {}".format(exp), exp)
azure.servicebus.common.errors.ServiceBusError: Management request failed: Management request returned status code: 500. Description: b'Unsupported type 0x40 for array. TrackingId:7bdddf69-a511-4246-8413-4094e9994a0c_G25, SystemTracker:NoSystemTracker, Timestamp:2019-09-18T16:12:44', Data: None`

[luipir]

this is almost new... the same code worked correctly yesterday. No idea is something changed server side

[annatisch]

Hi @nemakam - can you confirm whether any service updates/changes have been rolled out recently?

[luipir]

In my case the parameter arrived here:
https://github.com/Azure/azure-sdk-for-python/blob/master/sdk/servicebus/azure-servicebus/azure/servicebus/receive_handler.py#L138

are, in order:
b'com.microsoft:renew-lock'
b'entity-mgmt'
{b'lock-tokens': [None]} <<<<--- is it this the problem. would [ ] or none (json encoding) ?
5000

[annatisch]

Thanks @luipir - yeah it looks like an empty array is being sent (0x40 indicates a NULL value).
If we work back up the strack trace you posted above (thank you!) we can see that the messages lock_token attribute appears to be empty...
https://github.com/Azure/azure-sdk-for-python/blob/master/sdk/servicebus/azure-servicebus/azure/servicebus/common/message.py#L237
This would indicate that it's not being returned in the annotation.
My understanding is that there's more than one way to collect a lock token for a message - so maybe we need to investigate the alternative if the delivery annotations are unreliable.
Thoughts @nemakam ?

[luipir]

setting None as token instead of [None] override the Array error, but obviously can't lock the token returning:
Message: b'The service was unable to process the request; please retry the operation. For more information on exception types and proper exception handling, please refer to http://go.microsoft.com/fwlink/?LinkId=761101 Reference:***********, TrackingId:****************, SystemTracker:primare-desa-service-bus:Topic:primare_desa_topic_initplanification|proyestegal_initplanification_suscriber, Timestamp:2019-09-19T14:06:29'

[luipir]

My understanding is that there's more than one way to collect a lock token for a message - so maybe we need to investigate the alternative if the delivery annotations are unreliable.

how to set the lock token of the message again? I'll check if it's empty before to call renew_lock!

[luipir]

BTW is token is None, the raised error is not a correct message to understand it. Should be managed

[Indy2222]

I think that the bug is related to #4598.

Note that the docs say:

Lock tokens are the DeliveryTag property on received messages. See the following example in the .NET SDK which retrieves these. The token may also appear in the 'DeliveryAnnotations' as 'x-opt-lock-token' however, this is not guaranteed and the DeliveryTag should be preferred.