search

Azure / amqpnetlite

AMQP 1.0 .NET Library
Apache License 2.0
402 stars 145 forks source link

NullReferenceException in ReceiverLink #562

Closed lothar7 closed 1 year ago

lothar7 commented 1 year ago

Session.cs line 603 newDelivery = transfer.HasDeliveryId && transfer.DeliveryId > this.incomingDeliveryId;

Seems that when newDelivery is false in Session then link.OnTransfer fails

Session.cs line 633 link.OnTransfer(delivery, transfer, buffer);

Stack Trace Exception occurred: System.NullReferenceException: Object reference not set to an instance of an object. at Amqp.ReceiverLink.OnTransfer(Delivery delivery, Transfer transfer, ByteBuffer buffer) in C:\Repos\amqpnetlite\src\ReceiverLink.cs:line 376 at Amqp.Session.OnTransfer(Transfer transfer, ByteBuffer buffer) in C:\Repos\amqpnetlite\src\Session.cs:line 633 at Amqp.Session.OnCommand(DescribedList command, ByteBuffer buffer) in C:\Repos\amqpnetlite\src\Session.cs:line 389 at Amqp.Connection.OnSessionCommand(UInt16 remoteChannel, DescribedList command, ByteBuffer buffer) in C:\Repos\amqpnetlite\src\Connection.cs:line 691 at Amqp.Connection.OnFrame(ByteBuffer buffer) in C:\Repos\amqpnetlite\src\Connection.cs:line 789

Trace Log 2023-02-21 20:37:12,317 Baze [18] 0 - VERBOSE - RECV 0000015902000000005314C0150B43700000024FA0040000024F4342404040404042005373C0450AA10239394040404040A32E42617A652E44617461456E67696E652E416D71702E4D657373616765732E446174614672616D654D65737361676540408300000186757ADF58005374C15804A10B4D65737361676554797065A12E42617A652E44617461456E67696E652E416D71702E4D657373616765732E446174614672616D654D657373616765A11242617A65496F744875622D486973746F7279A1045472756500537700A32E42617A652E44617461456E67696E652E416D71702E4D657373616765732E446174614672616D654D657373616765D000000057000000064240540140B0000000481F8B0800000000000400FBFF9F81819101020E40E9F84F99ECCE22B73DD0E9A3507946CEA5FC47181997F20BF9BA1AE98687B81B1818EA86A416978424A60300B3C2E4875000000040 2023-02-21 20:37:12,317 Baze [18] 0 - VERBOSE - RECV (ch=0) transfer(handle:0,delivery-id:591,delivery-tag:0000024F,message-format:0,settled:False,batchable:False) payload 311

lothar7 commented 1 year ago

In this test I was running a single connection with a single sessions with a single receiverLink. Inside the messageCallback the messages are forwarded asynchronously onto another senderLink for a remote address.

I also get this error sometimes ByteBuffer.cs 207 Fx.Assert((this.read + size) <= this.write, "Complete size too large.");

xinchen10 commented 1 year ago

What broker was used in your test? Do you have the logs with more frame traces before the issue happened?

lothar7 commented 1 year ago

Her is the frame traces prior to this issue. I was using a modified version of the TestAmqpBroker from microsoft. The broker isnt doing anything strange at all. But perhaps its relevant that it runs "inprocess" with the client. Could there be some kind of racecondition going on? 2023-02-21 20:37:12,309 Baze [27] 0 - VERBOSE - SEND (ch=0) disposition(role:True,first:592,settled:True,state:accepted()) 2023-02-21 20:37:12,309 Baze [27] 0 - VERBOSE - SEND 0000001A02000000005315C00D05417000000250404100532445 2023-02-21 20:37:12,309 Baze [17] 0 - VERBOSE - RECV 0000018702000000005314C0150B437000000251A004000002514342404040404042005373C0900AA1283239342332373663393835662D353964352D343462362D396638612D35343233346163653735386240404040A12439363337373839352D636463632D343963342D616463652D316532313666373963646266A32E42617A652E44617461456E67696E652E416D71702E4D657373616765732E446174614672616D654D65737361676540408300000186757ADF41005374C13E02A10B4D65737361676554797065A12E42617A652E44617461456E67696E652E416D71702E4D657373616765732E446174614672616D654D65737361676500537700A32E42617A652E44617461456E67696E652E416D71702E4D657373616765732E446174614672616D654D657373616765D000000054000000064240540140B0000000451F8B0800000000000400FBFF9F010E0E40E925F392D99D456E7B2CC94843A1193997F2EF62645CCA2FE4EB6AA41B1EE26E6060A81B925A5C1292980E006CF025084800000040 2023-02-21 20:37:12,309 Baze [17] 0 - VERBOSE - RECV (ch=0) transfer(handle:0,delivery-id:593,delivery-tag:00000251,message-format:0,settled:False,batchable:False) payload 357 2023-02-21 20:37:12,310 Baze [17] 0 - VERBOSE - RECV 0000015A02000000005314C0150B437000000252A004000002524342404040404042005373C0460AA1033130314040404040A32E42617A652E44617461456E67696E652E416D71702E4D657373616765732E446174614672616D654D65737361676540408300000186757ADF58005374C15804A10B4D65737361676554797065A12E42617A652E44617461456E67696E652E416D71702E4D657373616765732E446174614672616D654D657373616765A11242617A65496F744875622D486973746F7279A1045472756500537700A32E42617A652E44617461456E67696E652E416D71702E4D657373616765732E446174614672616D654D657373616765D000000057000000064240540140B0000000481F8B0800000000000400FBFF9F81819101020E40E9F84F99ECCE22B73DD0E993507946CEA5FC27181997F20BF9BA1AE98687B81B1818EA86A416978424A60300EB891F745000000040 2023-02-21 20:37:12,310 Baze [17] 0 - VERBOSE - RECV (ch=0) transfer(handle:0,delivery-id:594,delivery-tag:00000252,message-format:0,settled:False,batchable:False) payload 312 2023-02-21 20:37:12,310 Baze [23] 0 - VERBOSE - SEND (ch=0) disposition(role:True,first:593,settled:True,state:accepted()) 2023-02-21 20:37:12,310 Baze [23] 0 - VERBOSE - SEND 0000001A02000000005315C00D05417000000251404100532445 2023-02-21 20:37:12,310 Baze [27] 0 - VERBOSE - SEND (ch=0) disposition(role:True,first:594,settled:True,state:accepted()) 2023-02-21 20:37:12,310 Baze [27] 0 - VERBOSE - SEND 0000001A02000000005315C00D05417000000252404100532445 2023-02-21 20:37:12,310 Baze [17] 0 - VERBOSE - RECV 0000015A02000000005314C0150B437000000253A004000002534342404040404042005373C0460AA1033130324040404040A32E42617A652E44617461456E67696E652E416D71702E4D657373616765732E446174614672616D654D65737361676540408300000186757ADF6C005374C15804A10B4D65737361676554797065A12E42617A652E44617461456E67696E652E416D71702E4D657373616765732E446174614672616D654D657373616765A11242617A65496F744875622D486973746F7279A1045472756500537700A32E42617A652E44617461456E67696E652E416D71702E4D657373616765732E446174614672616D654D657373616765D000000057000000064240540140B0000000481F8B0800000000000400FBFF9F81819101020E4069F77F39ECCE22B73DD0E9D3507946CEA5FCA7181997F20BF9BA1AE98687B81B1818EA86A416978424A6030093E64B525000000040 2023-02-21 20:37:12,310 Baze [17] 0 - VERBOSE - RECV (ch=0) transfer(handle:0,delivery-id:595,delivery-tag:00000253,message-format:0,settled:False,batchable:False) payload 312 2023-02-21 20:37:12,310 Baze [24] 0 - VERBOSE - SEND (ch=0) disposition(role:True,first:595,settled:True,state:accepted()) 2023-02-21 20:37:12,310 Baze [24] 0 - VERBOSE - SEND 0000001A02000000005315C00D05417000000253404100532445 2023-02-21 20:37:12,310 Baze [17] 0 - VERBOSE - RECV 0000015902000000005314C0150B437000000254A004000002544342404040404042005373C0460AA1033130334040404040A32E42617A652E44617461456E67696E652E416D71702E4D657373616765732E446174614672616D654D65737361676540408300000186757ADF6E005374C15804A10B4D65737361676554797065A12E42617A652E44617461456E67696E652E416D71702E4D657373616765732E446174614672616D654D657373616765A11242617A65496F744875622D486973746F7279A1045472756500537700A32E42617A652E44617461456E67696E652E416D71702E4D657373616765732E446174614672616D654D657373616765D000000056000000064240540140B0000000471F8B0800000000000400FBFF9F81819101020E40E9149F5C766791DB1EE8F459A83C23E752FE338C8C4BF9857C5D8D74C343DC0D0C0C7543528B4B4212D301D58C3E7A5000000040 2023-02-21 20:37:12,310 Baze [17] 0 - VERBOSE - RECV (ch=0) transfer(handle:0,delivery-id:596,delivery-tag:00000254,message-format:0,settled:False,batchable:False) payload 311 2023-02-21 20:37:12,311 Baze [16] 0 - VERBOSE - RECV 0000001A02000000005315C00D0541700000024D404100532445 2023-02-21 20:37:12,311 Baze [16] 0 - VERBOSE - RECV (ch=0) disposition(role:True,first:589,settled:True,state:accepted()) 2023-02-21 20:37:12,311 Baze [16] 0 - VERBOSE - RECV 0000001A02000000005315C00D0541700000024E404100532445 2023-02-21 20:37:12,311 Baze [16] 0 - VERBOSE - RECV (ch=0) disposition(role:True,first:590,settled:True,state:accepted()) 2023-02-21 20:37:12,311 Baze [24] 0 - VERBOSE - SEND (ch=0) disposition(role:True,first:596,settled:True,state:accepted()) 2023-02-21 20:37:12,311 Baze [24] 0 - VERBOSE - SEND 0000001A02000000005315C00D05417000000254404100532445 2023-02-21 20:37:12,311 Baze [16] 0 - VERBOSE - RECV 0000001A02000000005315C00D0541700000024F404100532445 2023-02-21 20:37:12,311 Baze [16] 0 - VERBOSE - RECV (ch=0) disposition(role:True,first:591,settled:True,state:accepted()) 2023-02-21 20:37:12,312 Baze [23] 0 - VERBOSE - RECV 0000001A02000000005315C00D0541700000024B404100532445 2023-02-21 20:37:12,312 Baze [23] 0 - VERBOSE - RECV (ch=0) disposition(role:True,first:587,settled:True,state:accepted()) 2023-02-21 20:37:12,315 Baze [16] 0 - VERBOSE - RECV 0000001A02000000005315C00D05417000000250404100532445 2023-02-21 20:37:12,315 Baze [16] 0 - VERBOSE - RECV (ch=0) disposition(role:True,first:592,settled:True,state:accepted()) 2023-02-21 20:37:12,315 Baze [16] 0 - VERBOSE - RECV 0000001A02000000005315C00D05417000000251404100532445 2023-02-21 20:37:12,315 Baze [16] 0 - VERBOSE - RECV (ch=0) disposition(role:True,first:593,settled:True,state:accepted()) 2023-02-21 20:37:12,316 Baze [16] 0 - VERBOSE - RECV 0000001A02000000005315C00D05417000000252404100532445 2023-02-21 20:37:12,316 Baze [16] 0 - VERBOSE - RECV (ch=0) disposition(role:True,first:594,settled:True,state:accepted()) 2023-02-21 20:37:12,316 Baze [16] 0 - VERBOSE - RECV 0000001A02000000005315C00D05417000000253404100532445 2023-02-21 20:37:12,316 Baze [16] 0 - VERBOSE - RECV (ch=0) disposition(role:True,first:595,settled:True,state:accepted()) 2023-02-21 20:37:12,316 Baze [16] 0 - VERBOSE - RECV 0000001A02000000005315C00D05417000000254404100532445 2023-02-21 20:37:12,316 Baze [16] 0 - VERBOSE - RECV (ch=0) disposition(role:True,first:596,settled:True,state:accepted()) 2023-02-21 20:37:12,316 Baze [18] 0 - VERBOSE - RECV 0000018702000000005314C0150B43700000024EA0040000024E4342404040404042005373C0900AA1283239332339326638323062392D393234662D343665652D383066392D66643737313261636663663640404040A12430383439376235622D396331612D346136382D626537652D303437303933316465353936A32E42617A652E44617461456E67696E652E416D71702E4D657373616765732E446174614672616D654D65737361676540408300000186757ADF41005374C13E02A10B4D65737361676554797065A12E42617A652E44617461456E67696E652E416D71702E4D657373616765732E446174614672616D654D65737361676500537700A32E42617A652E44617461456E67696E652E416D71702E4D657373616765732E446174614672616D654D657373616765D000000054000000064240540140B0000000451F8B0800000000000400FBFF9F010E0E40E925F392D99D456E7B2CC94843A1193997F2EF60645CCA2FE4EB6AA41B1EE26E6060A81B925A5C1292980E00633C1ED14800000040 2023-02-21 20:37:12,316 Baze [18] 0 - VERBOSE - RECV (ch=0) transfer(handle:0,delivery-id:590,delivery-tag:0000024E,message-format:0,settled:False,batchable:False) payload 357 2023-02-21 20:37:12,316 Baze [16] 0 - VERBOSE - SEND (ch=0) disposition(role:True,first:590,settled:True,state:accepted()) 2023-02-21 20:37:12,316 Baze [16] 0 - VERBOSE - SEND 0000001A02000000005315C00D0541700000024E404100532445 2023-02-21 20:37:12,317 Baze [17] 0 - VERBOSE - RECV 0000015A02000000005314C0150B43700000012CA0040000012C4342404040404042005373C0460AA1033130314040404040A32E42617A652E44617461456E67696E652E416D71702E4D657373616765732E446174614672616D654D65737361676540408300000186757ADF58005374C15804A10B4D65737361676554797065A12E42617A652E44617461456E67696E652E416D71702E4D657373616765732E446174614672616D654D657373616765A11242617A65496F744875622D486973746F7279A1045472756500537700A32E42617A652E44617461456E67696E652E416D71702E4D657373616765732E446174614672616D654D657373616765D000000057000000064240540140B0000000481F8B0800000000000400FBFF9F81819101020E40E9F84F99ECCE22B73DD0E993507946CEA5FC27181997F20BF9BA1AE98687B81B1818EA86A416978424A60300EB891F745000000040 2023-02-21 20:37:12,317 Baze [17] 0 - VERBOSE - RECV (ch=0) transfer(handle:0,delivery-id:300,delivery-tag:0000012C,message-format:0,settled:False,batchable:False) payload 312

xinchen10 commented 1 year ago

The last a few transfers look suspicious. The delivery-id field goes backwards. That is unexpected.

2023-02-21 20:37:12,310 Baze [17] 0 - VERBOSE - RECV (ch=0) transfer(handle:0,delivery-id:596,delivery-tag:00000254,message-format:0,settled:False,batchable:False) payload 311
2023-02-21 20:37:12,316 Baze [18] 0 - VERBOSE - RECV (ch=0) transfer(handle:0,delivery-id:590,delivery-tag:0000024E,message-format:0,settled:False,batchable:False) payload 357
2023-02-21 20:37:12,317 Baze [17] 0 - VERBOSE - RECV (ch=0) transfer(handle:0,delivery-id:300,delivery-tag:0000012C,message-format:0,settled:False,batchable:False) payload 312

If you remove the forwarding part in the message callback, does it happen? What changes did you do to the test broker?

xinchen10 commented 1 year ago

Feel free to reopen the issue if you have further updates, or some sample code that can reproduce the issue.