github-actions[bot]
commented
3 months ago @anuchandy @conniey @lmolkova
Closed haraldk closed 2 months ago
github-actions[bot]
commented
3 months ago @anuchandy @conniey @lmolkova
github-actions[bot]
commented
3 months ago Thank you for your feedback. Tagging and routing to the team member best able to assist.
anuchandy
commented
3 months ago Hi @haraldk, could you help with a reference message that ran into this error?
Basically, you would update code to print one of the impacted messages, which I can use to reproduce this. The code change look likes
try {
serviceBusSenderClient.scheduleMessage(retryMessage, OffsetDateTime.now().plusSeconds(delay));
} catch (ServiceBusException sbe) {
if (sbe.getCause() != null && sbe.getCause() instanceof AmqpException) {
final AmqpException amqpException = (AmqpException) sbe.getCause();
if (amqpException.getErrorCondition() == AmqpErrorCondition.LINK_PAYLOAD_SIZE_EXCEEDED) {
final Throwable innerCause = amqpException.getCause();
if (innerCause != null && innerCause instanceof BufferOverflowException) {
System.out.println(innerCause.getMessage());
MessagePrinter.print(retryMessage);
}
}
}
throw sbe;
}The "MessagePrinter" utility class used above can be found here https://gist.github.com/anuchandy/5b08d59e2ac0528dc58b99541c8765f1
haraldk
commented
3 months ago Thanks @anuchandy! I've modified your code slightly to use our logging, but it should otherwise output the same details. Will update the issue with the logged information as soon as possible.
haraldk
commented
2 months ago Here's the output of the extra output from a few occurrences extracted from our logs:
Exception message: null
Message { header=Header{durable=null, priority=4, ttl=1209600000, firstAcquirer=null, deliveryCount=null} properties=Properties{messageId=c344a9cf16bc4926b5bc3426c88b7810, userId=, to='null', subject='https://lydbanken.kubeint.nrk.no/api/archive/record/cab3ff5d-d576-4269-b3ff-5dd576c269de', replyTo='null', correlationId=null, contentType=application/vnd.nrk.lydbanken.archive.v1+json, contentEncoding=null, absoluteExpiryTime=Thu Sep 12 10:45:10 GMT 2024, creationTime=Thu Aug 29 10:45:10 GMT 2024, groupId='null', groupSequence=0, replyToGroupId='null'} application_properties=ApplicationProperties{{x-nrk-delivery-count=2}} message_annotations=MessageAnnotations{{x-opt-scheduled-enqueue-time=Thu Aug 29 10:45:11 GMT 2024}} delivery_annotations=DeliveryAnnotations{{x-opt-transfer-source=SBN-LYDTEAMET-LYDBANKEN-PROD-AZENO-1:TOPIC:LYDBANKEN-ARCHIVE-EVENTS|LYDBANKEN-INTEGRASJONER-VIRTUOSO-UPDATER#24ab2f09-c7bd-4a17-9c22-366989a8048a[5], x-opt-transfer-sn=21384, x-opt-transfer-session=null, x-opt-transfer-hop-count=1, x-opt-transfer-resource=27911146, x-opt-lock-token=15eea98e-c2dc-4b08-8839-05bf80be5555}} body=Data{{"uri":"https://lydbanken.kubeint.nrk.no/api/archive/record/cab3ff5d-d576-4269-b3ff-5dd576c269de","version":3,"changed":"2024-08-29T10:45:09.758605392Z"}} footer=Footer{{}} }
MessageType { application_properties={x-nrk-delivery-count=java.lang.Integer, } message_annotations={x-opt-scheduled-enqueue-time=java.util.Date, } delivery_annotations={x-opt-transfer-source=java.lang.String, x-opt-transfer-sn=java.lang.Long, x-opt-transfer-session=NAN, x-opt-transfer-hop-count=java.lang.Integer, x-opt-transfer-resource=java.lang.Long, x-opt-lock-token=java.util.UUID, } }
Exception message: null
Message { header=Header{durable=null, priority=4, ttl=1209600000, firstAcquirer=null, deliveryCount=null} properties=Properties{messageId=0d6c5bb09140495882da6abfa2e9cb5e, userId=, to='null', subject='https://lydbanken.kubeint.nrk.no/api/archive/record/61054037-fff3-449e-8540-37fff3b49e77', replyTo='null', correlationId=null, contentType=application/vnd.nrk.lydbanken.archive.v1+json, contentEncoding=null, absoluteExpiryTime=Thu Sep 12 10:15:22 GMT 2024, creationTime=Thu Aug 29 10:15:22 GMT 2024, groupId='null', groupSequence=0, replyToGroupId='null'} application_properties=ApplicationProperties{{x-nrk-delivery-count=2}} message_annotations=MessageAnnotations{{x-opt-scheduled-enqueue-time=Thu Aug 29 10:15:29 GMT 2024}} delivery_annotations=DeliveryAnnotations{{x-opt-transfer-source=SBN-LYDTEAMET-LYDBANKEN-PROD-AZENO-1:TOPIC:LYDBANKEN-ARCHIVE-EVENTS|LYDBANKEN-INTEGRASJONER-VIRTUOSO-UPDATER#24ab2f09-c7bd-4a17-9c22-366989a8048a[5], x-opt-transfer-sn=21349, x-opt-transfer-session=null, x-opt-transfer-hop-count=1, x-opt-transfer-resource=27911146, x-opt-lock-token=88f9eabc-7452-4168-a0e1-74b5ba3b5b8d}} body=Data{{"uri":"https://lydbanken.kubeint.nrk.no/api/archive/record/61054037-fff3-449e-8540-37fff3b49e77","version":1,"changed":"2024-08-29T10:15:22.092180924Z"}} footer=Footer{{}} }
MessageType { application_properties={x-nrk-delivery-count=java.lang.Integer, } message_annotations={x-opt-scheduled-enqueue-time=java.util.Date, } delivery_annotations={x-opt-transfer-source=java.lang.String, x-opt-transfer-sn=java.lang.Long, x-opt-transfer-session=NAN, x-opt-transfer-hop-count=java.lang.Integer, x-opt-transfer-resource=java.lang.Long, x-opt-lock-token=java.util.UUID, } }
Exception message: null
Message { header=Header{durable=null, priority=4, ttl=1209600000, firstAcquirer=null, deliveryCount=null} properties=Properties{messageId=0d6c5bb09140495882da6abfa2e9cb5e, userId=, to='null', subject='https://lydbanken.kubeint.nrk.no/api/archive/record/61054037-fff3-449e-8540-37fff3b49e77', replyTo='null', correlationId=null, contentType=application/vnd.nrk.lydbanken.archive.v1+json, contentEncoding=null, absoluteExpiryTime=Thu Sep 12 10:15:22 GMT 2024, creationTime=Thu Aug 29 10:15:22 GMT 2024, groupId='null', groupSequence=0, replyToGroupId='null'} application_properties=ApplicationProperties{{x-nrk-delivery-count=2}} message_annotations=MessageAnnotations{{x-opt-scheduled-enqueue-time=Thu Aug 29 10:15:29 GMT 2024}} delivery_annotations=DeliveryAnnotations{{x-opt-transfer-source=SBN-LYDTEAMET-LYDBANKEN-PROD-AZENO-1:TOPIC:LYDBANKEN-ARCHIVE-EVENTS|LYDBANKEN-INTEGRASJONER-VIRTUOSO-UPDATER#24ab2f09-c7bd-4a17-9c22-366989a8048a[5], x-opt-transfer-sn=21349, x-opt-transfer-session=null, x-opt-transfer-hop-count=1, x-opt-transfer-resource=27911146, x-opt-lock-token=88f9eabc-7452-4168-a0e1-74b5ba3b5b8d}} body=Data{{"uri":"https://lydbanken.kubeint.nrk.no/api/archive/record/61054037-fff3-449e-8540-37fff3b49e77","version":1,"changed":"2024-08-29T10:15:22.092180924Z"}} footer=Footer{{}} }
MessageType { application_properties={x-nrk-delivery-count=java.lang.Integer, } message_annotations={x-opt-scheduled-enqueue-time=java.util.Date, } delivery_annotations={x-opt-transfer-source=java.lang.String, x-opt-transfer-sn=java.lang.Long, x-opt-transfer-session=NAN, x-opt-transfer-hop-count=java.lang.Integer, x-opt-transfer-resource=java.lang.Long, x-opt-lock-token=java.util.UUID, } }
Exception message: null
Message { header=Header{durable=null, priority=4, ttl=1209600000, firstAcquirer=null, deliveryCount=null} properties=Properties{messageId=d6059e2e70304d3a922f71b2d944f462, userId=, to='null', subject='https://lydbanken.kubeint.nrk.no/api/archive/record/658825c8-b0d5-484e-8825-c8b0d5f84ea6', replyTo='null', correlationId=null, contentType=application/vnd.nrk.lydbanken.archive.v1+json, contentEncoding=null, absoluteExpiryTime=Thu Sep 12 10:15:15 GMT 2024, creationTime=Thu Aug 29 10:15:15 GMT 2024, groupId='null', groupSequence=0, replyToGroupId='null'} application_properties=ApplicationProperties{{x-nrk-delivery-count=2}} message_annotations=MessageAnnotations{{x-opt-scheduled-enqueue-time=Thu Aug 29 10:15:17 GMT 2024}} delivery_annotations=DeliveryAnnotations{{x-opt-transfer-source=SBN-LYDTEAMET-LYDBANKEN-PROD-AZENO-1:TOPIC:LYDBANKEN-ARCHIVE-EVENTS|LYDBANKEN-INTEGRASJONER-VIRTUOSO-UPDATER#24ab2f09-c7bd-4a17-9c22-366989a8048a[5], x-opt-transfer-sn=21324, x-opt-transfer-session=null, x-opt-transfer-hop-count=1, x-opt-transfer-resource=27911146, x-opt-lock-token=b4fd5abc-184a-44a9-9bb4-eac3797588b3}} body=Data{{"uri":"https://lydbanken.kubeint.nrk.no/api/archive/record/658825c8-b0d5-484e-8825-c8b0d5f84ea6","version":2,"changed":"2024-08-29T10:15:15.570698376Z"}} footer=Footer{{}} }
MessageType { application_properties={x-nrk-delivery-count=java.lang.Integer, } message_annotations={x-opt-scheduled-enqueue-time=java.util.Date, } delivery_annotations={x-opt-transfer-source=java.lang.String, x-opt-transfer-sn=java.lang.Long, x-opt-transfer-session=NAN, x-opt-transfer-hop-count=java.lang.Integer, x-opt-transfer-resource=java.lang.Long, x-opt-lock-token=java.util.UUID, } }The exception message wasn't very helpful in this case, but I hope the extra details can help in finding the issue! 😀
anuchandy
commented
2 months ago Hi @haraldk, thanks! it looks like the value of the field "Message.Properties.userId" is redacted, possibly a filter in the logging configuration? Could you double check and if so, can we output few new impacted messages again including this field value?
anuchandy
commented
2 months ago Hi @@haraldk, I can repro using the shared messages, no need to pull another set of messages (with userId)
anuchandy
commented
2 months ago hello @haraldk, we have a fix for this https://github.com/Azure/azure-sdk-for-java/pull/41706, thanks for helping with the details and test messages!
haraldk
commented
2 months ago Excellent news! I’ll have look, and will test as soon as possible. 😀
anuchandy
commented
2 months ago The version (7.17.14) with the fix should be available in September release. Closing, now that the changes are merged to the main.
Describe the bug We sometimes (I believe incorrectly) get "Error sending. Size of the payload exceeded maximum message size: 256 kb" error when scheduling a message. The message is a copy of a received message, with a single added client property to control the number of times it is re-scheduled. The error message does not make sense to me, as the message was previously sent fine, and the full message body is at most a few hundred bytes (< 1 kb). It is nowhere near the 256 kb limit.
The scheduling (usually) also works after a few retries.
The cause of the exception, however, says "java.lang.IndexOutOfBoundsException: Requested min remaining bytes(155) exceeds remaining(137) in underlying ByteBuffer: java.nio.HeapByteBuffer[pos=636 lim=773 cap=773]". That makes more sense, but I don't know how/why the limit is set to 773 bytes, as that is outside the control of the client code.
Exception or Stack Trace
To Reproduce Steps to reproduce the behavior:
This happens seemingly at random, and only a very small percentage of the times we invoke
com.azure.messaging.servicebus.ServiceBusSenderClient.scheduleMessage. I don't have a reproducer that can pinpoint the problem at this point, but the full method where the problem happens is attached below. I believe running the code below either by only using the exception path, or by replacingmessageConsumer.consume(message)with something likethrow new RuntimeException("Oh no")and running it enough times will show the problem.As mentioned, the message is (usually) scheduled after a few retries.
Code Snippet Add the code snippet that causes the issue.
Our
processMessagemethod (passed on toServiceBusProcessorClientBuilder.processMessage()) looks like this:Expected behavior
The message should be scheduled without exception.
Screenshots If applicable, add screenshots to help explain your problem.
Setup (please complete the following information):
Additional context Add any other context about the problem here.
Information Checklist Kindly make sure that you have added all the following information above and checkoff the required fields otherwise we will treat the issuer as an incomplete report