[ThreadPoolEx] [INFO ] b'Value is not of type STRING' (b'/data/src/vendor/azure-uamqp-c/src/amqpvalue.c':b'amqpvalue_get_string':1115)

[mockodin]

• Package Name: azure-servicebus
• Package Version: 7.1.1
• Operating System: Centos
• Python Version: 3.9.1

Describe the bug
ServiceBusMessage passed from get_queue_receiver to AutoLockRenewer.register return "Value is not of type STRING"

To Reproduce
Example Code:
with AutoLockRenewer(max_lock_renewal_duration=60 * 60) as renewer:
with ServiceBusClient.from_connection_string(CONNECTION_STR) as client:
with client.get_queue_receiver(QUEUE_NAME, max_wait_time=30, auto_lock_renewer=renewer) as receiver:
messages = []
for message in receiver: # ServiceBusReceiver instance is a generator.
messages.append(message)
if len(messages) == 5:
break
time.sleep(60)

After ~30 seconds:

2021-04-27 11:49:35,587 [ThreadPoolEx] [INFO ] b'Value is not of type STRING' (b'/data/src/vendor/azure-uamqp-c/src/amqpvalue.c':b'amqpvalue_get_string':1115)
2021-04-27 11:49:35,587 [ThreadPoolEx] [INFO ] b'Value is not of type STRING' (b'/data/src/vendor/azure-uamqp-c/src/amqpvalue.c':b'amqpvalue_get_string':1115)
2021-04-27 11:49:35,588 [ThreadPoolEx] [INFO ] b'Value is not of type STRING' (b'/data/src/vendor/azure-uamqp-c/src/amqpvalue.c':b'amqpvalue_get_string':1115)
2021-04-27 11:49:35,588 [ThreadPoolEx] [INFO ] b'Value is not of type STRING' (b'/data/src/vendor/azure-uamqp-c/src/amqpvalue.c':b'amqpvalue_get_string':1115)
2021-04-27 11:49:35,879 [ThreadPoolEx] [INFO ] b'Value is not of type STRING' (b'/data/src/vendor/azure-uamqp-c/src/amqpvalue.c':b'amqpvalue_get_string':1115)
2021-04-27 11:49:55,644 [ThreadPoolEx] [INFO ] b'Value is not of type STRING' (b'/data/src/vendor/azure-uamqp-c/src/amqpvalue.c':b'amqpvalue_get_string':1115)
2021-04-27 11:49:55,675 [ThreadPoolEx] [INFO ] b'Value is not of type STRING' (b'/data/src/vendor/azure-uamqp-c/src/amqpvalue.c':b'amqpvalue_get_string':1115)
2021-04-27 11:49:55,675 [ThreadPoolEx] [INFO ] b'Value is not of type STRING' (b'/data/src/vendor/azure-uamqp-c/src/amqpvalue.c':b'amqpvalue_get_string':1115)
2021-04-27 11:49:55,676 [ThreadPoolEx] [INFO ] b'Value is not of type STRING' (b'/data/src/vendor/azure-uamqp-c/src/amqpvalue.c':b'amqpvalue_get_string':1115)
2021-04-27 11:49:55,974 [ThreadPoolEx] [INFO ] b'Value is not of type STRING' (b'/data/src/vendor/azure-uamqp-c/src/amqpvalue.c':b'amqpvalue_get_string':1115)

Expected behavior
Successful registration for AutoRenewal of Message

Additional context
Tested Payload as json text, I've also base64 encoded on the off chance of an encoding issue, same results.

[rakshith91]

Thanks for reporting this!! We'll investigate this asap

[mockodin]

Further testing:
Downgraded to azure-servicebus==7.1.0 -- error present

Noting that the error references "/data/src/vendor/azure-uamqp-c/src/amqpvalue.c" as the module throwing the error moved to testing the uamqp python package, retaining azure-servicebus==7.1.0 as it required uamqp==1.3:

Testing azure-servicebus==7.1.0 with differing uamqp version results:
v 1.3 -- error present
v 1.2.15 -- error present
v 1.2.14 -- error present
v 1.2.13 -- Working

Based on the error reference of a c module for uamqp and the release notes f or 1.2.14 I'm guessing the issue is introduced with this change:

• Updated Azure uAMQP C and Azure C Shared Utility dependencies

[yunhaoling]

hey @mockodin , thanks for the report.

I could reproduce it when performing the renew_message_lock operation.
However as far as I know this error info should not impact the renew lock functionality, we have tests covering renew lock operation. Did you run into issues with message lock expiration?

Let me give more context on renew_message_lock, this is a special management operation on the amqp connection based on the request-response model, the service would return status code (200 if succeeds, or error code with error description if fails) and the sdk depends on the status code to check if the operation succeeds, otherwise error would be throwed -- so depending on the logging, the operation is supposed to succeed while parsing the response detail might be failing.

thanks for doing the version comparison, super helpful to me! I'll investigate which part was changed leading to this parsing error. I need to apologize that I didn't notice the logging before when I was updating the underlying dependency. I have some clue -- when the operation succeeds, the service just returns status code 200 leaving other properties None, I will compare 1.2.13 vs 1.2.14 related to the parsing process

[mockodin]

I am seeing "The lock on the message lock has expired" which I don't think I saw when using 1.3 but could have missed with the other noise.

Re: "this error info should not impact the renew lock functionality", OK that is good know, I actually didn't look to see if it was truly breaking anything. I'll reup the modules and see if the 'The lock on the message lock has expired.' notices go away.

[mockodin]

I am seeing the message lock expiration on the current builds as well after.

Processing after receive can take a long time, processing a download queue from Azure Blob, so complete or abandon might be 5 minutes after receive or hours later.

This feels like a different issue? I can open a separate issue for this if preferred.

[mockodin]

So initial bug is still there (expected) the Expiry issue appears to be something different. If I reduce the prefetch it seems to stop returning Expired notices, I believe though that the AutoRenew should prevent that happening so it that issue is there but finicky/specific.

I'll see if I can write something up for Expiry as a separate issue and keep this thread to the uamqp alone.

I'll keep an eye open for the resolution for the STRING notices.

[yunhaoling]

thanks for all the details you gave, I found the cause and had a PR out to fix the misleading error logging: Azure/azure-uamqp-python#235, that should be included in the next uamqp release.

as for the lock expiration, I'll take a look into it, feel free to create a new issue for tracking.

[yunhaoling]

hey @mockodin, we have released uamqp v1.4.0 which fixed the b'Value is not of type STRING' issue, please upgrade uamqp via pip install uamqp --upgrade to try out the fix.

for the message lock, how do you receive and handle your messages and the usage of prefetch?

one thing to call out is that the AutoLockRenewer could not automatically renew the messages that have been received by the underlying socket but not passed to the upper layer -- this is limited by our underlying connection push model.

so what could be happening is that during the sleeping time (handling received message), there're new messages (large prefetch number) arriving at the socket, however, it is until the sleep time ends(your handling finishes), then those messages will be pulled out from the socket in the next iteration call. In this case, the newly-arrived messages get expired already.

I think there're probably two options here:

1. keep prefetch to just one, handle one at a time
2. decouple the receiving and handling logic, use separate thread for message handling

I'm closing this issue now, feel free to create a new issue if you'd like to continue our discussion on the lock expiration one.
I'm always glad to help!

[mockodin]

@yunhaoling Thanks!

Re #1 we're pulling a quantity which is match against an threadpool for processing should always be 1:1 processing. There was an adjustment to precache only the count to be processed immediately. I believe that did help.