Sent message never receives DISPOSITION

[annatisch]

Hi @dcristoloveanu

I'm seeing some interesting behaviour I'm hoping you may have some insight into. My understanding is that max supported messages size is 256kb (maybe this depends on a service).

By default I configure my session/links with the max message and window size - and I have run tests that send a 256kb payload in a message successfully on Windows and Debian. In the logs, I can see the payload divided into 4 frames, followed by the response disposition like so:

2018-10-31 14:46:15,422 uamqp.c_uamqp INFO     b'-> [TRANSFER]* {2,1,<01 00 00 00>,0,false,true}'
2018-10-31 14:46:15,424 uamqp.c_uamqp INFO     b'-> [TRANSFER]* {2,1,<01 00 00 00>,0,false,true}'
2018-10-31 14:46:15,424 uamqp.c_uamqp INFO     b'-> [TRANSFER]* {2,1,<01 00 00 00>,0,false,true}'
2018-10-31 14:46:15,424 uamqp.c_uamqp INFO     b'-> [TRANSFER]* {2,1,<01 00 00 00>,0,false,false}'
2018-10-31 14:46:15,465 uamqp.c_uamqp INFO     b'<- [DISPOSITION]* {true,1,NULL,true,* {},NULL}'

However when I run the same code on OSX (and, according to user report, Ubuntu as well), the message appears to transfer without any error, however never receives a DISPOSITION frame. This happens to any message over about 128kb in size. My code simply continues to poll the connection indefinitely. No other errors/warnings are logged. I inspected the wire-encoded message on both Windows and OSX and can see no apparent difference between them.

I am going to test the same scenario on another service (this was first seen when sending to Event Hubs, I will now test against Service Bus). I will also contact the service teams to check whether they have any logs to indicate whether the message was ever even received.

But in the meantime if you know of anything I can check, or any thoughts as to what might cause this that would be fantastic.

Thanks!

[dcristoloveanu]

There should be no differences in encoding and handling settles between Windows/OSx. As a matter of fact IoTHub SDK uses uAMQP on Windows/Linux/OSx and I have not heard of this issue.

The code actually is the same at uAMQP level. The differences are in the PAL that is underneath.

Windows uses SChannel for TLS. Also it uses WinSock for socket APIs. Linux/OSx will use openssl for TLS. And socketio_berkeley for socket APIs.

openssl can be tested also on Windows with a bit of a headache. There is an option in C shared (use_openssl I believe) which will let you use openssl on Windows. It requires an env var with the path where openssl headers and lib exists and then it would allow debugging with openssl on Windows.

However before investing in any of that, can you get a full log on Windows and OSx so we can compare? The reason I ask for the full log is to see whether some options in setting up the links are somehow different (for example I want to eliminate weird cases like: one of the members of a struct are not properly initialized and then it gets garbage, which on Windows would be a value but on OSx another ... )

Cheers, /Dan

[annatisch]

Thanks @dcristoloveanu!

I also thought it must be related to the OpenSSL TLS layer - however that wouldn't explain why I can run it successfully on Debian, which also uses OpenSSL (unless it has something to do with running debian from a docker container on Windows).

The payload in both cases is a single message of 256000 characters.

My Windows output looks like the following:

2018-11-03 09:34:07,285 uamqp.connection INFO     Connection b'EHSender-5a38cfc2-0aaa-4f90-9e9f-9e18b20ccaf3' state changed from <ConnectionState.UNKNOWN: 999> to <ConnectionState.START: 0>
2018-11-03 09:34:07,368 uamqp.connection INFO     Connection b'EHSender-5a38cfc2-0aaa-4f90-9e9f-9e18b20ccaf3' state changed from <ConnectionState.START: 0> to <ConnectionState.START: 0>
2018-11-03 09:34:07,460 uamqp.c_uamqp INFO     b'-> Header (AMQP 0.1.0.0)'
2018-11-03 09:34:07,461 uamqp.connection INFO     Connection b'EHSender-5a38cfc2-0aaa-4f90-9e9f-9e18b20ccaf3' state changed from <ConnectionState.START: 0> to <ConnectionState.HDR_SENT: 2>
2018-11-03 09:34:07,466 uamqp.c_uamqp INFO     b'<- Header (AMQP 0.1.0.0)'
2018-11-03 09:34:07,466 uamqp.connection INFO     Connection b'EHSender-5a38cfc2-0aaa-4f90-9e9f-9e18b20ccaf3' state changed from <ConnectionState.HDR_SENT: 2> to <ConnectionState.HDR_EXCH: 3>
2018-11-03 09:34:07,466 uamqp.c_uamqp INFO     b'-> [OPEN]* {EHSender-5a38cfc2-0aaa-4f90-9e9f-9e18b20ccaf3,pyevent.servicebus.windows.net,65536,65535,NULL,NULL,NULL,NULL,NULL,{[product:eventhub.python],[version:1.1.1],[framework:Python 3.6.4],[platform:win32]}}'
2018-11-03 09:34:07,467 uamqp.connection INFO     Connection b'EHSender-5a38cfc2-0aaa-4f90-9e9f-9e18b20ccaf3' state changed from <ConnectionState.HDR_EXCH: 3> to <ConnectionState.OPEN_SENT: 7>
2018-11-03 09:34:07,472 uamqp.c_uamqp INFO     b'<- [OPEN]* {1ee5a842e7d54c46a368799481dac7b8_G4,NULL,65536,4999,240000,NULL,NULL,NULL,NULL,NULL}'
2018-11-03 09:34:07,473 uamqp.connection INFO     Connection b'EHSender-5a38cfc2-0aaa-4f90-9e9f-9e18b20ccaf3' state changed from <ConnectionState.OPEN_SENT: 7> to <ConnectionState.OPENED: 9>
2018-11-03 09:34:07,474 uamqp.c_uamqp INFO     b'-> [BEGIN]* {NULL,0,65536,65536,4294967295}'
2018-11-03 09:34:07,480 uamqp.c_uamqp INFO     b'<- [BEGIN]* {0,1,5000,65536,255,NULL,NULL,NULL}'
2018-11-03 09:34:07,480 uamqp.c_uamqp INFO     b'-> [ATTACH]* {$cbs-sender,0,false,0,0,* {$cbs},* {$cbs},NULL,NULL,0,0}'
2018-11-03 09:34:07,480 uamqp.c_uamqp INFO     b'-> [ATTACH]* {$cbs-receiver,1,true,0,0,* {$cbs},* {$cbs},NULL,NULL,NULL,0}'
2018-11-03 09:34:07,486 uamqp.c_uamqp INFO     b'<- [ATTACH]* {$cbs-sender,0,true,0,0,* {$cbs,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL},* {$cbs,NULL,NULL,NULL,NULL,NULL,NULL},NULL,NULL,NULL,18446744073709551615,NULL,NULL,NULL}'
2018-11-03 09:34:07,493 uamqp.c_uamqp INFO     b'<- [FLOW]* {0,5000,1,65536,0,0,100,0,NULL,false,NULL}'
2018-11-03 09:34:07,494 uamqp.c_uamqp INFO     b'Properties:* {0}Application properties:* {[name:sb://pyevent.servicebus.windows.net/pyhub],[operation:put-token],[type:servicebus.windows.net:sastoken]}Body - amqp value:* SharedAccessSignature sr=xxxx-> [TRANSFER]* {0,0,<01 00 00 00>,0,false,false}'
2018-11-03 09:34:07,500 uamqp.c_uamqp INFO     b'<- [ATTACH]* {$cbs-receiver,1,false,0,0,* {$cbs,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL},* {$cbs,NULL,NULL,NULL,NULL,NULL,NULL},NULL,NULL,0,18446744073709551615,NULL,NULL,NULL}'
2018-11-03 09:34:07,501 uamqp.c_uamqp INFO     b'-> [FLOW]* {1,65536,1,65535,1,0,10000}'
2018-11-03 09:34:07,501 uamqp.c_uamqp INFO     CBS for connection b'EHSender-5a38cfc2-0aaa-4f90-9e9f-9e18b20ccaf3' completed opening with status: 0
2018-11-03 09:34:07,507 uamqp.c_uamqp INFO     b'<- [DISPOSITION]* {true,0,NULL,true,* {},NULL}'
2018-11-03 09:34:07,551 uamqp.c_uamqp INFO     b'<- [TRANSFER]* {1,0,<01 00 00 00>,0,NULL,false,NULL,NULL,NULL,NULL,false}'
2018-11-03 09:34:07,552 uamqp.c_uamqp INFO     Token put complete with result: 0, status: 202, description: b'Accepted', connection: b'EHSender-5a38cfc2-0aaa-4f90-9e9f-9e18b20ccaf3'
2018-11-03 09:34:07,553 uamqp.c_uamqp INFO     b'-> [DISPOSITION]* {true,0,0,true,* {}}'
2018-11-03 09:34:07,554 uamqp.sender INFO     Message sender b'sender-link-bffc1114-aef9-454e-a872-ff78dd288c5c' state changed from <MessageSenderState.Idle: 0> to <MessageSenderState.Opening: 1> on connection: b'EHSender-5a38cfc2-0aaa-4f90-9e9f-9e18b20ccaf3'
2018-11-03 09:34:07,554 uamqp.c_uamqp INFO     b'-> [ATTACH]* {sender-link-bffc1114-aef9-454e-a872-ff78dd288c5c,2,false,0,1,* {EHSender-5a38cfc2-0aaa-4f90-9e9f-9e18b20ccaf3},* {amqps://pyevent.servicebus.windows.net/pyhub},NULL,NULL,0,262144}'
2018-11-03 09:34:07,635 uamqp.c_uamqp INFO     b'<- [ATTACH]* {sender-link-bffc1114-aef9-454e-a872-ff78dd288c5c,2,true,0,1,* {EHSender-5a38cfc2-0aaa-4f90-9e9f-9e18b20ccaf3,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL},* {amqps://pyevent.servicebus.windows.net/pyhub,NULL,NULL,NULL,NULL,NULL,NULL},NULL,NULL,NULL,262144,NULL,NULL,{[com.microsoft:tracking-id:1ee5a842e7d54c46a368799481dac7b8_G4]}}'
2018-11-03 09:34:07,635 uamqp.sender INFO     Message sender b'sender-link-bffc1114-aef9-454e-a872-ff78dd288c5c' state changed from <MessageSenderState.Opening: 1> to <MessageSenderState.Open: 2> on connection: b'EHSender-5a38cfc2-0aaa-4f90-9e9f-9e18b20ccaf3'
2018-11-03 09:34:07,679 uamqp.c_uamqp INFO     b'<- [FLOW]* {1,5000,2,65535,2,0,300,0,NULL,false,NULL}'
2018-11-03 09:34:07,680 uamqp.c_uamqp INFO     b'-> [TRANSFER]* {2,1,<01 00 00 00>,0,false,true}'
2018-11-03 09:34:07,681 uamqp.c_uamqp INFO     b'-> [TRANSFER]* {2,1,<01 00 00 00>,0,false,true}'
2018-11-03 09:34:07,681 uamqp.c_uamqp INFO     b'-> [TRANSFER]* {2,1,<01 00 00 00>,0,false,true}'
2018-11-03 09:34:07,682 uamqp.c_uamqp INFO     b'-> [TRANSFER]* {2,1,<01 00 00 00>,0,false,false}'
2018-11-03 09:34:08,864 uamqp.c_uamqp INFO     b'<- [DISPOSITION]* {true,1,NULL,true,* {},NULL}'
2018-11-03 09:34:08,868 uamqp.sender INFO     Message sender b'sender-link-bffc1114-aef9-454e-a872-ff78dd288c5c' state changed from <MessageSenderState.Open: 2> to <MessageSenderState.Closing: 3> on connection: b'EHSender-5a38cfc2-0aaa-4f90-9e9f-9e18b20ccaf3'
2018-11-03 09:34:08,868 uamqp.c_uamqp INFO     b'-> [DETACH]* {2,true}'
2018-11-03 09:34:09,377 uamqp.c_uamqp INFO     b'-> [DETACH]* {0,true}'
2018-11-03 09:34:09,378 uamqp.c_uamqp INFO     b'-> [DETACH]* {1,true}'
2018-11-03 09:34:09,379 uamqp.c_uamqp INFO     b'-> [END]* {}'
2018-11-03 09:34:09,379 uamqp.c_uamqp INFO     b'-> [CLOSE]* {}'
2018-11-03 09:34:09,380 uamqp.connection INFO     Connection b'EHSender-5a38cfc2-0aaa-4f90-9e9f-9e18b20ccaf3' state changed from <ConnectionState.OPENED: 9> to <ConnectionState.END: 13>

I will edit this post to add the OSX output as soon as I get home to my Mac :)

[annatisch]

Okay, here is the output from my Mac. Notice that after the TRANSFER frames, nothing further is received however the client continues to poll the connection which, after 2 minutes or so, sends an empty frame to keep the connection alive - this in turn seems to reveal that the connection is in fact in an invalid state which initiates a client shutdown.

2018-11-05 07:34:08,966 uamqp.connection INFO     Connection b'EHSender-826ef410-f32f-41f0-801b-5549cb129b41' state changed from <ConnectionState.UNKNOWN: 999> to <ConnectionState.START: 0>
2018-11-05 07:34:09,093 uamqp.connection INFO     Connection b'EHSender-826ef410-f32f-41f0-801b-5549cb129b41' state changed from <ConnectionState.START: 0> to <ConnectionState.START: 0>
2018-11-05 07:34:09,140 uamqp.c_uamqp INFO     b'-> Header (AMQP 0.1.0.0)'
2018-11-05 07:34:09,140 uamqp.connection INFO     Connection b'EHSender-826ef410-f32f-41f0-801b-5549cb129b41' state changed from <ConnectionState.START: 0> to <ConnectionState.HDR_SENT: 2>
2018-11-05 07:34:09,147 uamqp.c_uamqp INFO     b'<- Header (AMQP 0.1.0.0)'
2018-11-05 07:34:09,147 uamqp.connection INFO     Connection b'EHSender-826ef410-f32f-41f0-801b-5549cb129b41' state changed from <ConnectionState.HDR_SENT: 2> to <ConnectionState.HDR_EXCH: 3>
2018-11-05 07:34:09,148 uamqp.c_uamqp INFO     b'-> [OPEN]* {EHSender-826ef410-f32f-41f0-801b-5549cb129b41,pyevent.servicebus.windows.net,65536,65535,NULL,NULL,NULL,NULL,NULL,{[product:eventhub.python],[version:1.1.1],[framework:Python 3.6.5],[platform:darwin]}}'
2018-11-05 07:34:09,148 uamqp.connection INFO     Connection b'EHSender-826ef410-f32f-41f0-801b-5549cb129b41' state changed from <ConnectionState.HDR_EXCH: 3> to <ConnectionState.OPEN_SENT: 7>
2018-11-05 07:34:09,157 uamqp.c_uamqp INFO     b'<- [OPEN]* {7da9ad4435f54986b928117c924c730f_G8,NULL,65536,4999,240000,NULL,NULL,NULL,NULL,NULL}'
2018-11-05 07:34:09,157 uamqp.connection INFO     Connection b'EHSender-826ef410-f32f-41f0-801b-5549cb129b41' state changed from <ConnectionState.OPEN_SENT: 7> to <ConnectionState.OPENED: 9>
2018-11-05 07:34:09,158 uamqp.c_uamqp INFO     b'-> [BEGIN]* {NULL,0,65536,65536,4294967295}'
2018-11-05 07:34:09,170 uamqp.c_uamqp INFO     b'<- [BEGIN]* {0,1,5000,65536,255,NULL,NULL,NULL}'
2018-11-05 07:34:09,171 uamqp.c_uamqp INFO     b'-> [ATTACH]* {$cbs-sender,0,false,0,0,* {$cbs},* {$cbs},NULL,NULL,0,0}'
2018-11-05 07:34:09,171 uamqp.c_uamqp INFO     b'-> [ATTACH]* {$cbs-receiver,1,true,0,0,* {$cbs},* {$cbs},NULL,NULL,NULL,0}'
2018-11-05 07:34:09,181 uamqp.c_uamqp INFO     b'<- [ATTACH]* {$cbs-sender,0,true,0,0,* {$cbs,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL},* {$cbs,NULL,NULL,NULL,NULL,NULL,NULL},NULL,NULL,NULL,18446744073709551615,NULL,NULL,NULL}'
2018-11-05 07:34:09,191 uamqp.c_uamqp INFO     b'<- [FLOW]* {0,5000,1,65536,0,0,100,0,NULL,false,NULL}'
2018-11-05 07:34:09,191 uamqp.c_uamqp INFO     b'-> [TRANSFER]* {0,0,<01 00 00 00>,0,false,false}'
2018-11-05 07:34:09,198 uamqp.c_uamqp INFO     b'<- [ATTACH]* {$cbs-receiver,1,false,0,0,* {$cbs,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL},* {$cbs,NULL,NULL,NULL,NULL,NULL,NULL},NULL,NULL,0,18446744073709551615,NULL,NULL,NULL}'
2018-11-05 07:34:09,199 uamqp.c_uamqp INFO     b'-> [FLOW]* {1,65536,1,65535,1,0,10000}'
2018-11-05 07:34:09,199 uamqp.c_uamqp INFO     CBS for connection b'EHSender-826ef410-f32f-41f0-801b-5549cb129b41' completed opening with status: 0
2018-11-05 07:34:09,206 uamqp.c_uamqp INFO     b'<- [DISPOSITION]* {true,0,NULL,true,* {},NULL}'
2018-11-05 07:34:09,216 uamqp.c_uamqp INFO     b'<- [TRANSFER]* {1,0,<01 00 00 00>,0,NULL,false,NULL,NULL,NULL,NULL,false}'
2018-11-05 07:34:09,217 uamqp.c_uamqp INFO     Token put complete with result: 0, status: 202, description: b'Accepted', connection: b'EHSender-826ef410-f32f-41f0-801b-5549cb129b41'
2018-11-05 07:34:09,217 uamqp.c_uamqp INFO     b'-> [DISPOSITION]* {true,0,0,true,* {}}'
2018-11-05 07:34:09,217 uamqp.sender INFO     Message sender b'sender-link-92989f1c-78b5-45be-9a8a-e24c071f729f' state changed from <MessageSenderState.Idle: 0> to <MessageSenderState.Opening: 1> on connection: b'EHSender-826ef410-f32f-41f0-801b-5549cb129b41'
2018-11-05 07:34:09,218 uamqp.c_uamqp INFO     b'-> [ATTACH]* {sender-link-92989f1c-78b5-45be-9a8a-e24c071f729f,2,false,0,1,* {EHSender-826ef410-f32f-41f0-801b-5549cb129b41},* {amqps://pyevent.servicebus.windows.net/pyhub},NULL,NULL,0,262144}'
2018-11-05 07:34:09,296 uamqp.c_uamqp INFO     b'<- [ATTACH]* {sender-link-92989f1c-78b5-45be-9a8a-e24c071f729f,2,true,0,1,* {EHSender-826ef410-f32f-41f0-801b-5549cb129b41,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL},* {amqps://pyevent.servicebus.windows.net/pyhub,NULL,NULL,NULL,NULL,NULL,NULL},NULL,NULL,NULL,262144,NULL,NULL,{[com.microsoft:tracking-id:7da9ad4435f54986b928117c924c730f_G8]}}'
2018-11-05 07:34:09,297 uamqp.sender INFO     Message sender b'sender-link-92989f1c-78b5-45be-9a8a-e24c071f729f' state changed from <MessageSenderState.Opening: 1> to <MessageSenderState.Open: 2> on connection: b'EHSender-826ef410-f32f-41f0-801b-5549cb129b41'
2018-11-05 07:34:09,304 uamqp.c_uamqp INFO     b'<- [FLOW]* {1,5000,2,65535,2,0,300,0,NULL,false,NULL}'
2018-11-05 07:34:09,305 uamqp.c_uamqp INFO     b'-> [TRANSFER]* {2,1,<01 00 00 00>,0,false,true}'
2018-11-05 07:34:09,305 uamqp.c_uamqp INFO     b'-> [TRANSFER]* {2,1,<01 00 00 00>,0,false,true}'
2018-11-05 07:34:09,306 uamqp.c_uamqp INFO     b'-> [TRANSFER]* {2,1,<01 00 00 00>,0,false,true}'
2018-11-05 07:34:09,306 uamqp.c_uamqp INFO     b'-> [TRANSFER]* {2,1,<01 00 00 00>,0,false,false}'
2018-11-05 07:36:09,000 uamqp.c_uamqp INFO     b'-> Empty frame'
2018-11-05 07:36:09,011 uamqp.connection INFO     Connection b'EHSender-826ef410-f32f-41f0-801b-5549cb129b41' state changed from <ConnectionState.OPENED: 9> to <ConnectionState.ERROR: 14>
2018-11-05 07:36:09,011 uamqp.sender INFO     Message sender b'sender-link-92989f1c-78b5-45be-9a8a-e24c071f729f' state changed from <MessageSenderState.Open: 2> to <MessageSenderState.Error: 4> on connection: b'EHSender-826ef410-f32f-41f0-801b-5549cb129b41'
2018-11-05 07:36:09,604 uamqp.c_uamqp INFO     b'Connection not open' (b'/Users/pythondev/Downloads/azure-uamqp-python-dev/src/vendor/azure-uamqp-c/src/connection.c':b'connection_encode_frame':2049)
2018-11-05 07:36:09,604 uamqp.c_uamqp INFO     b'send called while not open' (b'/Users/pythondev/Downloads/azure-uamqp-python-dev/src/vendor/azure-uamqp-c/src/saslclientio.c':b'saslclientio_send_async':1181)
2018-11-05 07:36:09,604 uamqp.c_uamqp INFO     b'Cannot send encoded bytes' (b'/Users/pythondev/Downloads/azure-uamqp-python-dev/src/vendor/azure-uamqp-c/src/connection.c':b'on_bytes_encoded':268)
2018-11-05 07:36:09,605 uamqp.c_uamqp INFO     b'saslclientio_close called while not open' (b'/Users/pythondev/Downloads/azure-uamqp-python-dev/src/vendor/azure-uamqp-c/src/saslclientio.c':b'saslclientio_close_async':1130)
2018-11-05 07:36:09,605 uamqp.c_uamqp INFO     b'xio_close failed' (b'/Users/pythondev/Downloads/azure-uamqp-python-dev/src/vendor/azure-uamqp-c/src/connection.c':b'on_bytes_encoded':272)
2018-11-05 07:36:09,605 uamqp.connection INFO     Connection b'EHSender-826ef410-f32f-41f0-801b-5549cb129b41' state changed from <ConnectionState.ERROR: 14> to <ConnectionState.END: 13>
2018-11-05 07:36:09,605 uamqp.c_uamqp INFO     b'-> [CLOSE]* {}'
2018-11-05 07:36:09,605 uamqp.connection INFO     Connection b'EHSender-826ef410-f32f-41f0-801b-5549cb129b41' state changed from <ConnectionState.END: 13> to <ConnectionState.END: 13>
2018-11-05 07:36:09,608 uamqp.c_uamqp INFO     b'saslclientio_close called while not open' (b'/Users/pythondev/Downloads/azure-uamqp-python-dev/src/vendor/azure-uamqp-c/src/saslclientio.c':b'saslclientio_close_async':1130)
2018-11-05 07:36:09,608 uamqp.c_uamqp INFO     b'xio_close failed' (b'/Users/pythondev/Downloads/azure-uamqp-python-dev/src/vendor/azure-uamqp-c/src/connection.c':b'connection_close':1438)
2018-11-05 07:36:09,609 uamqp.connection INFO     Connection shutdown complete b'EHSender-826ef410-f32f-41f0-801b-5549cb129b41'.

[dcristoloveanu]

PR merged, closing.

[annatisch]

This issue isn't related to the PR :)

[dcristoloveanu]

Oops, not intentional :-)