[ https://issues.apache.org/jira/browse/PROTON-2255?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17173909#comment-17173909 ]
Jiri Daněk commented on PROTON-2255: ------------------------------------ Replacing the {{assertTrue}} with {{assertIn}} gives much more helpful output from the dispatch test {noformat} 28: ====================================================================== 28: FAIL: test_connector_default (system_tests_protocol_settings.ConnectorSettingsDefaultTest) 28: ---------------------------------------------------------------------- 28: Traceback (most recent call last): 28: File "/main/qpid-dispatch/tests/system_tests_protocol_settings.py", line 328, in test_connector_default 28: self.assertIn(" incoming-window=2147483647,", begin_lines[0]) 28: File "/main/qpid-dispatch/tests/system_test.py", line 824, in assertIn 28: assert item in items, "%s not in %s" % (item, items) 28: AssertionError: incoming-window=2147483647, not in 2020-08-09 14:24:11.835816 +0000 PROTOCOL (trace) [3]:FRAME: 0 <- @begin(17) [next-outgoing-id=0, incoming-window=131071, outgoing-window=2147483647] (/main/qpid-dispatch/src/server.c:112) 28: 28: ====================================================================== 28: FAIL: test_max_frame_max_session_zero (system_tests_protocol_settings.MaxFrameMaxSessionFramesZeroTest) 28: ---------------------------------------------------------------------- 28: Traceback (most recent call last): 28: File "/main/qpid-dispatch/tests/system_tests_protocol_settings.py", line 274, in test_max_frame_max_session_zero 28: self.assertIn(" incoming-window=2147483647,", begin_lines[0]) 28: File "/main/qpid-dispatch/tests/system_test.py", line 824, in assertIn 28: assert item in items, "%s not in %s" % (item, items) 28: AssertionError: incoming-window=2147483647, not in 2020-08-09 14:24:17.990644 +0000 PROTOCOL (trace) [2]:FRAME: 0 -> @begin(17) [remote-channel=0, next-outgoing-id=0, incoming-window=4194303, outgoing-window=2147483647] (/main/qpid-dispatch/src/server.c:112) 28: 28: ====================================================================== 28: FAIL: test_max_session_frames_default (system_tests_protocol_settings.MaxSessionFramesDefaultTest) 28: ---------------------------------------------------------------------- 28: Traceback (most recent call last): 28: File "/main/qpid-dispatch/tests/system_tests_protocol_settings.py", line 238, in test_max_session_frames_default 28: self.assertIn(" incoming-window=2147483647,", begin_lines[0]) 28: File "/main/qpid-dispatch/tests/system_test.py", line 824, in assertIn 28: assert item in items, "%s not in %s" % (item, items) 28: AssertionError: incoming-window=2147483647, not in 2020-08-09 14:24:18.620500 +0000 PROTOCOL (trace) [2]:FRAME: 0 -> @begin(17) [remote-channel=0, next-outgoing-id=0, incoming-window=131071, outgoing-window=2147483647] (/main/qpid-dispatch/src/server.c:112) 28: 28: ---------------------------------------------------------------------- 28: Ran 10 tests in 8.232s 28: 28: FAILED (failures=3) 1/1 Test #28: system_tests_protocol_settings ...***Failed 8.38 sec {noformat} The output suggests that there are actually two different unexpected values for {{incoming-window}}. They are 131071 and also 4194303, in one of the tests. {quote}It would be good to know exactly what went over the wire independent of what Proton says in a trace log. {quote} This is what Qpid JMS thinks is on the wire {noformat} % PN_TRACE_FRM=1 java -jar repos/testing/cli/cli-java/cli-qpid-jms/target/cli-qpid-jms-1.2.2-SNAPSHOT-0.54.0-28.b410db45.jar receiver --address baf --timeout 55 --log-msgs=dict [1209499752:0] -> SASL [1209499752:0] <- SASL [1209499752:0] <- SaslMechanisms{saslServerMechanisms=[ANONYMOUS]} [1209499752:0] -> SaslInit{mechanism=ANONYMOUS, initialResponse=, hostname='localhost'} [1209499752:0] <- SaslOutcome{_code=OK, _additionalData=null} [1209499752:0] -> AMQP [1209499752:0] -> Open{ containerId='ID:b4cefd9b-6877-4c8f-8473-23d7afb3fc7f:1', hostname='localhost', maxFrameSize=1048576, channelMax=32767, idleTimeOut=30000, outgoingLocales=null, incomingLocales=null, offeredCapabilities=null, desiredCapabilities=[sole-connection-for-container, DELAYED_DELIVERY, ANONYMOUS-RELAY, SHARED-SUBS], properties={product=QpidJMS, version=0.54.0-28.b410db45, platform=JVM: 11.0.6-internal, 11.0.6-internal+0-adhoc..jdk11u-jdk-11.0.6-ga, Oracle Corporation, OS: Linux, 5.4.53, amd64}} [1209499752:0] <- AMQP [1209499752:0] <- Open{ containerId='Standalone_k2gbivalv7wYF9Y', hostname='null', maxFrameSize=16384, channelMax=32767, idleTimeOut=8000, outgoingLocales=null, incomingLocales=null, offeredCapabilities=[ANONYMOUS-RELAY], desiredCapabilities=null, properties={product=qpid-dispatch-router, version=1.13.0-SNAPSHOT, qd.conn-id=1}} [1209499752:0] -> Begin{remoteChannel=null, nextOutgoingId=1, incomingWindow=2047, outgoingWindow=2147483647, handleMax=65535, offeredCapabilities=null, desiredCapabilities=null, properties=null} [1209499752:0] <- Begin{remoteChannel=0, nextOutgoingId=0, incomingWindow=2147483647, outgoingWindow=2147483647, handleMax=4294967295, offeredCapabilities=null, desiredCapabilities=null, properties=null} [1209499752:1] -> Begin{remoteChannel=null, nextOutgoingId=1, incomingWindow=2047, outgoingWindow=2147483647, handleMax=65535, offeredCapabilities=null, desiredCapabilities=null, properties=null} [1209499752:1] <- Begin{remoteChannel=1, nextOutgoingId=0, incomingWindow=2147483647, outgoingWindow=2147483647, handleMax=4294967295, offeredCapabilities=null, desiredCapabilities=null, properties=null} [1209499752:1] -> Attach{name='qpid-jms:receiver:ID:918a84f0-4ea9-4289-b6e6-8a1e645ab94f:1:1:1:baf', handle=0, role=RECEIVER, sndSettleMode=UNSETTLED, rcvSettleMode=FIRST, source=Source{address='baf', durable=NONE, expiryPolicy=LINK_DETACH, timeout=0, dynamic=false, dynamicNodeProperties=null, distributionMode=null, filter=null, defaultOutcome=Modified{deliveryFailed=true, undeliverableHere=null, messageAnnotations=null}, outcomes=[amqp:accepted:list, amqp:rejected:list, amqp:released:list, amqp:modified:list], capabilities=[queue]}, target=Target{address='null', durable=NONE, expiryPolicy=SESSION_END, timeout=0, dynamic=false, dynamicNodeProperties=null, capabilities=null}, unsettled=null, incompleteUnsettled=false, initialDeliveryCount=null, maxMessageSize=null, offeredCapabilities=null, desiredCapabilities=null, properties=null} [1209499752:1] <- Attach{name='qpid-jms:receiver:ID:918a84f0-4ea9-4289-b6e6-8a1e645ab94f:1:1:1:baf', handle=0, role=SENDER, sndSettleMode=MIXED, rcvSettleMode=FIRST, source=Source{address='baf', durable=NONE, expiryPolicy=LINK_DETACH, timeout=0, dynamic=false, dynamicNodeProperties=null, distributionMode=null, filter=null, defaultOutcome=null, outcomes=[amqp:accepted:list, amqp:rejected:list, amqp:released:list, amqp:modified:list], capabilities=[queue]}, target=Target{address='null', durable=NONE, expiryPolicy=SESSION_END, timeout=0, dynamic=false, dynamicNodeProperties=null, capabilities=null}, unsettled=null, incompleteUnsettled=false, initialDeliveryCount=0, maxMessageSize=0, offeredCapabilities=null, desiredCapabilities=null, properties=null} [1209499752:1] -> Flow{nextIncomingId=0, incomingWindow=2047, nextOutgoingId=1, outgoingWindow=2147483647, handle=0, deliveryCount=0, linkCredit=1000, available=null, drain=false, echo=false, properties=null} ^C {noformat} (why are there 4 Begins and not 2??? This always happens against a 32bit dispatch with qpid-jms. With a 64 bit dispatch, or with 32 bit dispatch and the proton receive example, I get 2.) The above corresponds with the output from dispatch side, with {{PN_TRACE_FRM}} {noformat} [0xf4c162d8]: AMQP:FRAME:0 -> @open(16) [container-id="Standalone__fdAHw7WnkjepX2", max-frame-size=16384, channel-max=32767, idle-time-out=8000, offered-capabilities=:"ANONYMOUS-RELAY", properties={:product="qpid-dispatch-router", :version="1.13.0-SNAPSHOT", :"qd.conn-id"=1}] [0xf4c162d8]: AMQP:FRAME:0 <- @begin(17) [next-outgoing-id=1, incoming-window=2047, outgoing-window=2147483647, handle-max=65535] [0xf4c162d8]: AMQP:FRAME:0 -> @begin(17) [remote-channel=0, next-outgoing-id=0, incoming-window=131071, outgoing-window=2147483647] [0xf4c162d8]: AMQP:FRAME:1 <- @begin(17) [next-outgoing-id=1, incoming-window=2047, outgoing-window=2147483647, handle-max=65535] [0xf4c162d8]: AMQP:FRAME:1 -> @begin(17) [remote-channel=1, next-outgoing-id=0, incoming-window=131071, outgoing-window=2147483647] {noformat} The value of incoming-window is calculated in {{pni_session_incoming_window}}: {noformat} (gdb) bt #0 pni_session_incoming_window (ssn=0xf486f110) at /main/qpid-proton/c/src/core/transport.c:1961 #1 0xf7f02a79 in pni_process_ssn_setup (transport=0xf48411d8, endpoint=0xf486f110) at /main/qpid-proton/c/src/core/transport.c:2000 #2 0xf7f04672 in pni_phase (transport=0xf48411d8, phase=0xf7f029b5 <pni_process_ssn_setup>) at /main/qpid-proton/c/src/core/transport.c:2542 #3 0xf7f046e0 in pni_process (transport=0xf48411d8) at /main/qpid-proton/c/src/core/transport.c:2553 #4 0xf7f05089 in pn_output_write_amqp (transport=0xf48411d8, layer=0, bytes=0xf486a0f8 "", available=8184) at /main/qpid-proton/c/src/core/transport.c:2712 #5 0xf7f052da in transport_produce (transport=0xf48411d8) at /main/qpid-proton/c/src/core/transport.c:2765 #6 0xf7f05dac in pn_transport_pending (transport=0xf48411d8) at /main/qpid-proton/c/src/core/transport.c:3055 #7 0xf7ef5a7d in pn_connection_driver_write_buffer (d=0xf4841134) at /main/qpid-proton/c/src/core/connection_driver.c:112 #8 0xf7ed18b2 in ensure_wbuf (pc=0xf4841008) at /main/qpid-proton/c/src/proactor/epoll.c:981 #9 0xf7ed22ed in write_flush (pc=0xf4841008) at /main/qpid-proton/c/src/proactor/epoll.c:1227 #10 0xf7ed1b5e in pconnection_batch_next (batch=0xf4841130) at /main/qpid-proton/c/src/proactor/epoll.c:1036 #11 0xf7ed7645 in pn_event_batch_next (batch=0xf4841130) at /main/qpid-proton/c/src/proactor/proactor-internal.c:84 #12 0xf7faa7d9 in thread_run (arg=0x80a42a8) at /main/qpid-dispatch/src/server.c:1056 #13 0xf7f6b812 in _thread_init (arg=0x82c1818) at /main/qpid-dispatch/src/posix/threading.c:172 #14 0xf7eb8bbc in start_thread () from target:/lib/libpthread.so.0 #15 0xf7c350de in clone () from target:/lib/libc.so.6 {noformat} {code:c|title=qpid-proton/c/src/core/transport.c} static size_t pni_session_incoming_window(pn_session_t *ssn) { pn_transport_t *t = ssn->connection->transport; uint32_t size = t->local_max_frame; size_t capacity = ssn->incoming_capacity; if (!size || !capacity) { /* session flow control is not enabled */ return AMQP_MAX_WINDOW_SIZE; } else if (capacity >= size) { /* precondition */ return (capacity - ssn->incoming_bytes) / size; [...] {code} On a 32bit system, this evaluates as {noformat} (gdb) info locals size = 16384 capacity = 2147483647 (gdb) p ssn->incoming_bytes $1 = 0 {noformat} On a 64bit system {noformat} (gdb) info locals size = 16384 capacity = 35184372072448 (gdb) p ssn->incoming_bytes $1 = 0 {noformat} What changes is capacity, and that is something that dispatch sets, in {{connection_manager.c}}. {code:c|title=qpid-dispatch/src/connection_manager.c} // // Given session frame count and max frame size compute session incoming_capacity // >if (ssn_frames == 0) config->incoming_capacity = (sizeof(size_t) < 8) ? 0x7FFFFFFFLL : 0x7FFFFFFFLL * config->max_frame_size; {code} So, I think the Dispatch test is wrong, it should actually expect to get a different incoming-window when it is running on 32bit system. > [proton-c] unexpected incoming-window in begin frame when running Dispatch > test in 32 bit system > ------------------------------------------------------------------------------------------------ > > Key: PROTON-2255 > URL: https://issues.apache.org/jira/browse/PROTON-2255 > Project: Qpid Proton > Issue Type: Bug > Components: proton-c > Affects Versions: proton-c-0.31.0 > Reporter: Ganesh Murthy > Priority: Major > > system_tests_protocol_settings fails in Dispatch with the following error > > {noformat} > ====================================================================== > FAIL: test_connector_default > (system_tests_protocol_settings.ConnectorSettingsDefaultTest) > ---------------------------------------------------------------------- > Traceback (most recent call last): > File > "/home/jenkins/workspace/rh-qpid-dispatch-dist-el6-32-master/build/BUILD/qpid-dispatch-1.13.0/tests/system_tests_protocol_settings.py", > line 343, in test_connector_default > self.assertTrue(" incoming-window=2147483647," in begin_lines[0]) > AssertionError: False is not True > ====================================================================== > FAIL: test_max_frame_max_session_zero > (system_tests_protocol_settings.MaxFrameMaxSessionFramesZeroTest) > ---------------------------------------------------------------------- > Traceback (most recent call last): > File > "/home/jenkins/workspace/rh-qpid-dispatch-dist-el6-32-master/build/BUILD/qpid-dispatch-1.13.0/tests/system_tests_protocol_settings.py", > line 287, in test_max_frame_max_session_zero > self.assertTrue(" incoming-window=2147483647," in begin_lines[0]) > AssertionError: False is not True > ====================================================================== > FAIL: test_max_session_frames_default > (system_tests_protocol_settings.MaxSessionFramesDefaultTest) > ---------------------------------------------------------------------- > Traceback (most recent call last): > File > "/home/jenkins/workspace/rh-qpid-dispatch-dist-el6-32-master/build/BUILD/qpid-dispatch-1.13.0/tests/system_tests_protocol_settings.py", > line 249, in test_max_session_frames_default > self.assertTrue(" incoming-window=2147483647," in begin_lines[0]) > AssertionError: False is not True {noformat} > > The actual line in the log is > {noformat} > 2020-07-30 12:47:53.727396 -0400 PROTOCOL (trace) [3]:FRAME: 0 <- > @begin(17) [next-outgoing-id=0, incoming-window=131071, > outgoing-window=2147483647] > (/root/project/build/BUILD/qpid-dispatch-1.13.0/src/server.c:112) {noformat} > > The test is expecting to see the incoming-window to be 2147483647 but instead > gets 131071. > This could be a possible issue with the way the incoming-window is logged but > really not sure. -- This message was sent by Atlassian Jira (v8.3.4#803005) --------------------------------------------------------------------- To unsubscribe, e-mail: dev-unsubscr...@qpid.apache.org For additional commands, e-mail: dev-h...@qpid.apache.org