Uploaded image for project: 'Qpid Dispatch'
  1. Qpid Dispatch
  2. DISPATCH-2085

system_tests_fallback_dest failure - addr_proxy.c:323: on_conn_event: Assertion `addr->edge_outlink == 0' failed

    XMLWordPrintableJSON

Details

    • Bug
    • Status: Closed
    • Major
    • Resolution: Fixed
    • 1.16.0, 1.17.0
    • 1.19.0
    • None
    • None

    Description

      First spotted on s390x, https://travis-ci.com/github/apache/qpid-dispatch/jobs/501153572#L6607

      62: Router EA2 output file:
62: >>>>
62: 2021-04-26 16:56:05.615255 +0000 AGENT (warning) Attribute 'dir' of entity 'autoLink' has been deprecated. Use 'direction' instead
62: 2021-04-26 16:56:05.615411 +0000 AGENT (warning) Attribute 'dir' of entity 'autoLink' has been deprecated. Use 'direction' instead
62: qdrouterd: /home/travis/build/apache/qpid-dispatch/src/router_core/modules/edge_router/addr_proxy.c:323: on_conn_event: Assertion `addr->edge_outlink == 0' failed.
62: 
62: <<<<
62: 
62: Router EA2 command file:
62: >>>>
62: qdrouterd -c EA2.conf -I /home/travis/build/apache/qpid-dispatch/python
62: pid=14036
62: 
62: <<<<
62: 
62: Router EA2 log file tail:
62: >>>>
62: 2021-04-26 16:58:05.686184 +0000 ROUTER_CORE (trace) Core action 'link_detach' (/home/travis/build/apache/qpid-dispatch/src/router_core/router_core_thread.c:238)
62: 2021-04-26 16:58:05.686235 +0000 ROUTER_CORE (info) [C4][L12] Link lost: del=1 presett=1 psdrop=0 acc=0 rej=0 rel=0 mod=0 delay1=0 delay10=0 blocked=no (/home/travis/build/apache/qpid-dispatch/src/router_core/connections.c:1074)
62: 2021-04-26 16:58:05.686281 +0000 ROUTER_CORE (trace) Core action 'connection_closed' (/home/travis/build/apache/qpid-dispatch/src/router_core/router_core_thread.c:238)
62: 2021-04-26 16:58:05.686346 +0000 ROUTER_CORE (info) [C4] Connection Closed (/home/travis/build/apache/qpid-dispatch/src/router_core/connections.c:1557)
62: 2021-04-26 16:58:05.705484 +0000 SERVER (trace) Accepting connection on 0.0.0.0:23020 (/home/travis/build/apache/qpid-dispatch/src/server.c:852)
62: 2021-04-26 16:58:05.705577 +0000 SERVER (trace) [C5]: Accepting incoming connection to '0.0.0.0:23020' (/home/travis/build/apache/qpid-dispatch/src/server.c:606)
62: 2021-04-26 16:58:05.705691 +0000 POLICY (trace) ALLOW Connection '127.0.0.1' based on global connection count. nConnections= 1 (/home/travis/build/apache/qpid-dispatch/src/policy.c:271)
62: 2021-04-26 16:58:05.705782 +0000 SERVER (info) [C5] Accepted connection to 0.0.0.0:23020 from 127.0.0.1:37922 (/home/travis/build/apache/qpid-dispatch/src/server.c:750)
62: 2021-04-26 16:58:05.706152 +0000 PROTOCOL (trace) [C5]:FRAME:   <- SASL (/home/travis/build/apache/qpid-dispatch/src/server.c:111)
62: 2021-04-26 16:58:05.706180 +0000 PROTOCOL (trace) [C5]:FRAME:   -> SASL (/home/travis/build/apache/qpid-dispatch/src/server.c:111)
62: 2021-04-26 16:58:05.706590 +0000 PROTOCOL (trace) [C5]:FRAME: 0 -> @sasl-mechanisms(64) [sasl-server-mechanisms=@PN_SYMBOL[:ANONYMOUS]] (/home/travis/build/apache/qpid-dispatch/src/server.c:111)
62: 2021-04-26 16:58:05.706949 +0000 PROTOCOL (trace) [C5]:FRAME: 0 <- @sasl-init(65) [mechanism=:ANONYMOUS, initial-response=b"anonymous@travis-job-apache-qpid-dispatch-501153572"] (/home/travis/build/apache/qpid-dispatch/src/server.c:111)
62: 2021-04-26 16:58:05.707025 +0000 PROTOCOL (trace) [C5]:FRAME: 0 -> @sasl-outcome(68) [code=0] (/home/travis/build/apache/qpid-dispatch/src/server.c:111)
62: 2021-04-26 16:58:05.707319 +0000 PROTOCOL (trace) [C5]:FRAME:   <- AMQP (/home/travis/build/apache/qpid-dispatch/src/server.c:111)
62: 2021-04-26 16:58:05.707363 +0000 PROTOCOL (trace) [C5]:FRAME: 0 <- @open(16) [container-id="ac3fab39-661e-44f4-8361-5866a600788d", hostname="0.0.0.0", channel-max=32767] (/home/travis/build/apache/qpid-dispatch/src/server.c:111)
62: 2021-04-26 16:58:05.707432 +0000 PROTOCOL (trace) [C5]:FRAME: 0 <- @begin(17) [next-outgoing-id=0, incoming-window=2147483647, outgoing-window=2147483647] (/home/travis/build/apache/qpid-dispatch/src/server.c:111)
62: 2021-04-26 16:58:05.707500 +0000 PROTOCOL (trace) [C5]:FRAME: 0 <- @attach(18) [name="dest.32_primary_receiver", handle=0, role=true, snd-settle-mode=2, rcv-settle-mode=0, source=@source(40) [address="dest.32", durable=0, timeout=0, dynamic=false], target=@target(41) [durable=0, timeout=0, dynamic=false], initial-delivery-count=0, max-message-size=0] (/home/travis/build/apache/qpid-dispatch/src/server.c:111)
62: 2021-04-26 16:58:05.707557 +0000 PROTOCOL (trace) [C5]:FRAME: 0 <- @flow(19) [incoming-window=2147483647, next-outgoing-id=0, outgoing-window=2147483647, handle=0, delivery-count=0, link-credit=10, drain=false] (/home/travis/build/apache/qpid-dispatch/src/server.c:111)
62: 2021-04-26 16:58:05.707645 +0000 ROUTER_CORE (info) [C5] Connection Opened: dir=in host=127.0.0.1:37922 vhost= encrypted=no auth=ANONYMOUS user=anonymous container_id=ac3fab39-661e-44f4-8361-5866a600788d props= (/home/travis/build/apache/qpid-dispatch/src/router_core/connections.c:135)
62: 2021-04-26 16:58:05.707703 +0000 ROUTER_CORE (trace) Core action 'connection_opened' (/home/travis/build/apache/qpid-dispatch/src/router_core/router_core_thread.c:238)
62: 2021-04-26 16:58:05.707788 +0000 ROUTER_CORE (trace) Core action 'link_first_attach' (/home/travis/build/apache/qpid-dispatch/src/router_core/router_core_thread.c:238)
62: 2021-04-26 16:58:05.707827 +0000 PROTOCOL (trace) [C5]:FRAME:   -> AMQP (/home/travis/build/apache/qpid-dispatch/src/server.c:111)
62: 2021-04-26 16:58:05.707873 +0000 DEFAULT (trace) Parse tree search for 'dest.32' (/home/travis/build/apache/qpid-dispatch/src/parse_tree.c:704)
62: 2021-04-26 16:58:05.707910 +0000 PROTOCOL (trace) [C5]:FRAME: 0 -> @open(16) [container-id="EA2", max-frame-size=16384, channel-max=32767, idle-time-out=60000, offered-capabilities=@PN_SYMBOL[:"ANONYMOUS-RELAY", :"qd.streaming-links"], desired-capabilities=@PN_SYMBOL[:"ANONYMOUS-RELAY", :"qd.streaming-links"], properties={:product="qpid-dispatch-router", :version="1.16.0-SNAPSHOT", :"qd.conn-id"=5}] (/home/travis/build/apache/qpid-dispatch/src/server.c:111)
62: 2021-04-26 16:58:05.707959 +0000 DEFAULT (trace) Parse tree match not found (/home/travis/build/apache/qpid-dispatch/src/parse_tree.c:692)
62: 2021-04-26 16:58:05.707996 +0000 PROTOCOL (trace) [C5]:FRAME: 0 -> @begin(17) [remote-channel=0, next-outgoing-id=0, incoming-window=2147483647, outgoing-window=2147483647] (/home/travis/build/apache/qpid-dispatch/src/server.c:111)
62: 2021-04-26 16:58:05.708043 +0000 DEFAULT (trace) Parse tree search for 'dest.32' (/home/travis/build/apache/qpid-dispatch/src/parse_tree.c:704)
62: 2021-04-26 16:58:05.708196 +0000 ROUTER_CORE (info) [C5][L13] Link attached: dir=out source={dest.32 expire:sess} target={<none> expire:sess} (/home/travis/build/apache/qpid-dispatch/src/router_core/connections.c:1838)
62: 2021-04-26 16:58:05.708231 +0000 ROUTER_CORE (trace) Core action 'link_flow' (/home/travis/build/apache/qpid-dispatch/src/router_core/router_core_thread.c:238)
62: 2021-04-26 16:58:05.708353 +0000 PROTOCOL (trace) [C5]:FRAME: 0 -> @attach(18) [name="dest.32_primary_receiver", handle=0, role=false, snd-settle-mode=2, rcv-settle-mode=0, source=@source(40) [address="dest.32", durable=0, expiry-policy=:"session-end", timeout=0, dynamic=false], target=@target(41) [durable=0, expiry-policy=:"session-end", timeout=0, dynamic=false], initial-delivery-count=0, max-message-size=0] (/home/travis/build/apache/qpid-dispatch/src/server.c:111)
62: 2021-04-26 16:58:06.665127 +0000 ROUTER_CORE (trace) Core action 'process_tick' (/home/travis/build/apache/qpid-dispatch/src/router_core/router_core_thread.c:238)
62: 2021-04-26 16:58:07.665236 +0000 ROUTER_CORE (trace) Core action 'process_tick' (/home/travis/build/apache/qpid-dispatch/src/router_core/router_core_thread.c:238)
62: 2021-04-26 16:58:07.684326 +0000 SERVER (trace) [C6] Connecting to 127.0.0.1:23012 (/home/travis/build/apache/qpid-dispatch/src/server.c:1202)
62: 2021-04-26 16:58:07.684656 +0000 PROTOCOL (trace) [C6]:FRAME:   -> SASL (/home/travis/build/apache/qpid-dispatch/src/server.c:111)
62: 2021-04-26 16:58:07.686448 +0000 PROTOCOL (trace) [C6]:FRAME:   <- SASL (/home/travis/build/apache/qpid-dispatch/src/server.c:111)
62: 2021-04-26 16:58:07.686506 +0000 PROTOCOL (trace) [C6]:FRAME: 0 <- @sasl-mechanisms(64) [sasl-server-mechanisms=@PN_SYMBOL[:ANONYMOUS]] (/home/travis/build/apache/qpid-dispatch/src/server.c:111)
62: 2021-04-26 16:58:07.686654 +0000 PROTOCOL (trace) [C6]:FRAME: 0 -> @sasl-init(65) [mechanism=:ANONYMOUS, initial-response=b"anonymous@travis-job-apache-qpid-dispatch-501153572"] (/home/travis/build/apache/qpid-dispatch/src/server.c:111)
62: 2021-04-26 16:58:07.687181 +0000 PROTOCOL (trace) [C6]:FRAME: 0 <- @sasl-outcome(68) [code=0] (/home/travis/build/apache/qpid-dispatch/src/server.c:111)
62: 2021-04-26 16:58:07.687225 +0000 PROTOCOL (trace) [C6]:FRAME:   -> AMQP (/home/travis/build/apache/qpid-dispatch/src/server.c:111)
62: 2021-04-26 16:58:07.687326 +0000 PROTOCOL (trace) [C6]:FRAME: 0 -> @open(16) [container-id="EA2", hostname="127.0.0.1", max-frame-size=16384, channel-max=32767, idle-time-out=60000, offered-capabilities=@PN_SYMBOL[:"ANONYMOUS-RELAY", :"qd.streaming-links"], desired-capabilities=@PN_SYMBOL[:"ANONYMOUS-RELAY", :"qd.streaming-links"], properties={:product="qpid-dispatch-router", :version="1.16.0-SNAPSHOT", :"qd.conn-id"=6}] (/home/travis/build/apache/qpid-dispatch/src/server.c:111)
62: 2021-04-26 16:58:07.689045 +0000 PROTOCOL (trace) [C6]:FRAME:   <- AMQP (/home/travis/build/apache/qpid-dispatch/src/server.c:111)
62: 2021-04-26 16:58:07.689107 +0000 PROTOCOL (trace) [C6]:FRAME: 0 <- @open(16) [container-id="INT.A", max-frame-size=16384, channel-max=32767, idle-time-out=60000, offered-capabilities=@PN_SYMBOL[:"ANONYMOUS-RELAY", :"qd.streaming-links"], desired-capabilities=@PN_SYMBOL[:"ANONYMOUS-RELAY", :"qd.streaming-links"], properties={:product="qpid-dispatch-router", :version="1.16.0-SNAPSHOT", :"qd.conn-id"=28}] (/home/travis/build/apache/qpid-dispatch/src/server.c:111)
62: 2021-04-26 16:58:07.689596 +0000 ROUTER_CORE (info) [C6] Connection Opened: dir=out host=127.0.0.1:23012 vhost= encrypted=no auth=ANONYMOUS user=(null) container_id=INT.A props={:product="qpid-dispatch-router", :version="1.16.0-SNAPSHOT", :"qd.conn-id"=28} (/home/travis/build/apache/qpid-dispatch/src/router_core/connections.c:135)
62: 2021-04-26 16:58:07.689761 +0000 ROUTER_CORE (trace) Core action 'connection_opened' (/home/travis/build/apache/qpid-dispatch/src/router_core/router_core_thread.c:238)
62: 2021-04-26 16:58:07.689796 +0000 ROUTER_CORE (info) Edge connection (id=6) to interior established (/home/travis/build/apache/qpid-dispatch/src/router_core/modules/edge_router/connection_manager.c:56)
62: 2021-04-26 16:58:07.689912 +0000 ROUTER_CORE (info) [C6][L14] Link attached: dir=out source={<none> expire:link} target={<none> expire:link} (/home/travis/build/apache/qpid-dispatch/src/router_core/connections.c:1173)
62: 2021-04-26 16:58:07.690044 +0000 ROUTER_CORE (info) [C6][L15] Link attached: dir=in source={EA2 expire:link caps::"qd.router-edge-downlink"} target={<none> expire:link caps::"qd.router-edge-downlink"} (/home/travis/build/apache/qpid-dispatch/src/router_core/connections.c:1173)
62: 2021-04-26 16:58:07.690170 +0000 ROUTER_CORE (info) [C6][L16] Link attached: dir=in source={_$qd.edge_addr_tracking expire:link} target={<none> expire:link} (/home/travis/build/apache/qpid-dispatch/src/router_core/connections.c:1173)
62: 2021-04-26 16:58:07.690275 +0000 ROUTER_CORE (info) [C6][L17] Link attached: dir=in source={dest.32 expire:link} target={<none> expire:link} (/home/travis/build/apache/qpid-dispatch/src/router_core/connections.c:1173)
62: 2021-04-26 16:58:07.690438 +0000 ROUTER_CORE (info) [C6][L18] Link attached: dir=out source={<none> expire:link} target={dest.32 expire:link caps::"qd.fallback"} (/home/travis/build/apache/qpid-dispatch/src/router_core/connections.c:1173)
62: 
62: <<<<
62: 
62: Router EA1 output file:
62: >>>>
62: 2021-04-26 16:56:05.467836 +0000 AGENT (warning) Attribute 'dir' of entity 'autoLink' has been deprecated. Use 'direction' instead
62: 2021-04-26 16:56:05.467996 +0000 AGENT (warning) Attribute 'dir' of entity 'autoLink' has been deprecated. Use 'direction' instead
62: 
62: <<<<
62: 
62: Router EA1 debug dump file:
62: >>>>
62: alloc.c: Items of type 'qd_timer_t' remain allocated at shutdown: 1 (SUPPRESSED)
62: alloc.c: Items of type 'qd_buffer_t' remain allocated at shutdown: 13 (SUPPRESSED)
62: alloc.c: Items of type 'qd_connector_t' remain allocated at shutdown: 1 (SUPPRESSED)
62: alloc.c: Items of type 'qd_message_t' remain allocated at shutdown: 13 (SUPPRESSED)
62: alloc.c: Items of type 'qd_message_content_t' remain allocated at shutdown: 13 (SUPPRESSED)
62: alloc.c: Items of type 'qdr_delivery_t' remain allocated at shutdown: 13 (SUPPRESSED)
62: alloc.c: Items of type 'qd_link_ref_t' remain allocated at shutdown: 13 (SUPPRESSED)
62: 
62: <<<<
62: 
62: Router INT.B output file:
62: >>>>
62: 2021-04-26 16:56:05.209684 +0000 AGENT (warning) Attribute 'dir' of entity 'autoLink' has been deprecated. Use 'direction' instead
62: 2021-04-26 16:56:05.209868 +0000 AGENT (warning) Attribute 'dir' of entity 'autoLink' has been deprecated. Use 'direction' instead
62: 
62: <<<<
62: 
62: Router INT.B debug dump file:
62: >>>>
62: alloc.c: Items of type 'qd_timer_t' remain allocated at shutdown: 1 (SUPPRESSED)
62: alloc.c: Items of type 'qd_connector_t' remain allocated at shutdown: 1 (SUPPRESSED)
62: 
62: <<<<
62: 
62: Router INT.A output file:
62: >>>>
62: 2021-04-26 16:56:04.950765 +0000 AGENT (warning) Attribute 'dir' of entity 'autoLink' has been deprecated. Use 'direction' instead
62: 2021-04-26 16:56:04.951002 +0000 AGENT (warning) Attribute 'dir' of entity 'autoLink' has been deprecated. Use 'direction' instead
62: 
62: <<<<
62: ERROR
62: 
62: ======================================================================
62: ERROR: tearDownClass (system_tests_fallback_dest.RouterTest)
62: ----------------------------------------------------------------------
62: Traceback (most recent call last):
62:   File "/home/travis/build/apache/qpid-dispatch/tests/system_test.py", line 865, in tearDownClass
62:     cls.tester.teardown()
62:   File "/home/travis/build/apache/qpid-dispatch/tests/system_test.py", line 808, in teardown
62:     raise RuntimeError("Errors during teardown: \n\n%s" % "\n\n".join([str(e) for e in errors]))
62: RuntimeError: Errors during teardown: 
62: 
62: Process 14036 error: exit code -6, expected -1
62: qdrouterd -c EA2.conf -I /home/travis/build/apache/qpid-dispatch/python
62: /home/travis/build/apache/qpid-dispatch/build/tests/system_test.dir/system_tests_fallback_dest/RouterTest/setUpClass/EA2-4.cmd
62: >>>>
62: 2021-04-26 16:56:05.615255 +0000 AGENT (warning) Attribute 'dir' of entity 'autoLink' has been deprecated. Use 'direction' instead
62: 2021-04-26 16:56:05.615411 +0000 AGENT (warning) Attribute 'dir' of entity 'autoLink' has been deprecated. Use 'direction' instead
62: qdrouterd: /home/travis/build/apache/qpid-dispatch/src/router_core/modules/edge_router/addr_proxy.c:323: on_conn_event: Assertion `addr->edge_outlink == 0' failed.
62: <<<<
62: 
62: ======================================================================
62: FAIL: test_32_switchover_local_interior_alt_remote_edge (system_tests_fallback_dest.RouterTest)
62: ----------------------------------------------------------------------
62: Traceback (most recent call last):
62:   File "/home/travis/build/apache/qpid-dispatch/tests/system_tests_fallback_dest.py", line 328, in test_32_switchover_local_interior_alt_remote_edge
62:     self.assertEqual(None, test.error)
62: AssertionError: None != 'Timeout Expired - n_tx=232, n_rx=0, n_rel=8351, phase=0, local_rel=8351'
62: 
62: ======================================================================
62: FAIL: test_38_switchover_mix_4 (system_tests_fallback_dest.RouterTest)
62: ----------------------------------------------------------------------
62: Traceback (most recent call last):
62:   File "/home/travis/build/apache/qpid-dispatch/tests/system_tests_fallback_dest.py", line 376, in test_38_switchover_mix_4
62:     self.assertEqual(None, test.error)
62: AssertionError: None != 'Timeout Expired - n_tx=0, n_rx=0, n_rel=0, phase=0, local_rel=0'
62: 
62: ----------------------------------------------------------------------
62: Ran 50 tests in 322.245s
62: 
62: FAILED (failures=2, errors=1)
62/74 Test #62: system_tests_fallback_dest ........................***Failed  322.37 sec

      Attachments

        Issue Links

          is caused by

          Bug - A problem which impairs or prevents the functions of the product. DISPATCH-2256 edge router fallback links and addresses incorrect on interior failover

          • Major - Major loss of function.
          • Open

          Activity

            People

              kgiusti Ken Giusti
              jdanek Jiri Daněk
              Votes:
              0 Vote for this issue
              Watchers:
              4 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved: