[DISPATCH-2205] [test] system_tests_routing_protocol fails with unexpected MAU

• Type: Test
• Status: Closed
• Priority: Major
• Resolution: Fixed
• Affects Version/s: 1.16.1
• Fix Version/s: 1.17.0
• Component/s: Tests
• Assignee: Charles E. Rolke
• Reporter: Charles E. Rolke
• Created: 21/Jul/21 16:21
• Updated: 23/Aug/21 15:02
• Resolved: 21/Jul/21 16:30

Description

There is a race between the test succeeding and a normal MAU being received just before the protocol connection is closed.

The fix is to stop handling received messages after success is declared.

◊  2021-07-21 13:57:06.746270 A0#1437 A [A0_9] [] peer_4 Accepting incoming connection to '0.0.0.0:22989'
◊  2021-07-21 13:57:06.746786 A0#1441 A [A0_9] [] peer_4 Accepted connection to 0.0.0.0:22989 from 127.0.0.1:57476
◊  2021-07-21 13:57:06.746915 A0#1442 A [A0_9] <- [] peer_4 SASL
◊  2021-07-21 13:57:06.747022 A0#1444 A [A0_9] -> [] peer_4 SASL
◊  2021-07-21 13:57:06.747279 A0#1448 A [A0_9] -> [] peer_4 sasl-mechanisms [0] @PN_SYMBOL[:ANONYMOUS]
◊  2021-07-21 13:57:06.748037 A0#1450 A [A0_9] <- [] peer_4 sasl-init [0] :ANONYMOUS
◊  2021-07-21 13:57:06.748180 A0#1451 A [A0_9] -> [] peer_4 sasl-outcome [0] code=0
◊  2021-07-21 13:57:06.748873 A0#1454 A [A0_9] <- [] peer_4 AMQP
◊  2021-07-21 13:57:06.748978 A0#1455 A [A0_9] <- [] peer_4 open [0] (peer: "e71ed1b1-c421-448a-9c40-e6ffa2a9bb21")
◊  2021-07-21 13:57:06.751488 A0#1477 A [A0_9] -> [] peer_4 AMQP
◊  2021-07-21 13:57:06.751701 A0#1478 A [A0_9] -> [] peer_4 open [0]
◊  2021-07-21 13:57:06.752737 A0#1479 A [A0_9] <- [] peer_4 begin [0,None)]
◊  2021-07-21 13:57:06.752991 A0#1480 A [A0_9] <- [] peer_4 attach [0,0] receiver link_33 (source: none, target: none, class: router)
◊  2021-07-21 13:57:06.753269 A0#1481 A [A0_9] <- [] peer_4 attach [0,1] sender link_34 (source: none, target: none, class: router)
◊  2021-07-21 13:57:06.753456 A0#1482 A [A0_9] <- [] peer_4 flow [0,0] (0,10)
◊  2021-07-21 13:57:06.753854 A0#1484 A [A0_9] -> [] peer_4 begin [0,0]
◊  2021-07-21 13:57:06.754550 A0#1489 A [A0_9] -> [] peer_4 attach [0,0] sender link_33 (source: none, target: none, class: router)
◊  2021-07-21 13:57:06.754785 A0#1490 A [A0_9] -> [] peer_4 attach [0,1] receiver link_34 (source: none, target: none, class: router)
◊  2021-07-21 13:57:06.754921 A0#1491 A [A0_9] -> [] peer_4 flow [0,1] (0,250)
◊  2021-07-21 13:57:07.719727 A0#1525 A [A0_9] -> [] peer_4 transfer [0,0] (0) HELLO settled transfer_27 de HELLO Sw ; id A pvT area 0 instanceq` ' seen B" - 253 bytes transfer presettled
◊  2021-07-21 13:57:07.723793 A0#1547 A [A0_9] <- [] peer_4 transfer [0,1] (0) HELLO settled transfer_44 e HELLO Sw ; id TEST pvT area 0 instanceUd seen A" - 128 bytes transfer presettled
◊  2021-07-21 13:57:07.725614 A0#1562 A [A0_9] -> [] peer_4 flow [0,1] (1,250)
◊  2021-07-21 13:57:08.233323 A0#1640 A [A0_9] -> [] peer_4 transfer [0,0] (1)    RA settled transfer_33 id B pvT area 0 instanceq` ' ls_seqT mobile_seqT " - 267 bytes transfer presettled
◊  2021-07-21 13:57:08.234758 A0#1648 A [A0_9] <- [] peer_4 flow [0,0] (2,9)
◊  2021-07-21 13:57:08.234921 A0#1649 A [A0_9] <- [] peer_4 transfer [0,1] (1)   MAR settled transfer_47 St opcode MAR Sw ) id TEST pvT area 0 have_seqT " - 115 bytes transfer presettled
◊  2021-07-21 13:57:08.236323 A0#1664 A [A0_9] -> [] peer_4 flow [0,1] (2,250)
◊  2021-07-21 13:57:08.722568 A0#1702 A [A0_9] -> [] peer_4 transfer [0,0] (2) HELLO settled transfer_48 LLO Sw A id A pvT area 0 instanceq` ' seen B TEST" - 259 bytes transfer presettled
◊  2021-07-21 13:57:08.724370 A0#1704 A [A0_9] <- [] peer_4 flow [0,0] (3,9)
◊  2021-07-21 13:57:08.724586 A0#1705 A [A0_9] <- [] peer_4 transfer [0,1] (2) HELLO settled transfer_44 e HELLO Sw ; id TEST pvT area 0 instanceUd seen A" - 128 bytes transfer presettled
◊  2021-07-21 13:57:08.729424 A0#1759 A [A0_9] -> [] peer_4 flow [0,1] (3,250)
◊  2021-07-21 13:57:08.729642 A0#1760 A [A0_9] -> [] peer_4 transfer [0,0] (3)   LSR settled transfer_50 TEST/qdrouter@@@ St opcode LSR Sw id A pvT area 0" - 225 bytes transfer presettled
◊  2021-07-21 13:57:08.729863 A0#1761 A [A0_9] -> [] peer_4 transfer [0,0] (4)    RA settled transfer_49 id A pvT area 0 instanceq` ' ls_seqT mobile_seqT " - 262 bytes transfer presettled
◊  2021-07-21 13:57:08.731488 A0#1762 A [A0_9] <- [] peer_4 flow [0,0] (5,9)
◊  2021-07-21 13:57:08.731670 A0#1763 A [A0_9] <- [] peer_4 transfer [0,1] (3)   MAR settled transfer_51 St opcode MAR Sw ) id TEST pvT area 0 have_seqT " - 115 bytes transfer presettled
◊  2021-07-21 13:57:08.733867 A0#1788 A [A0_9] -> [] peer_4 flow [0,1] (4,250)
◊  2021-07-21 13:57:09.235167 A0#1866 A [A0_9] -> [] peer_4 transfer [0,0] (5)   LSR settled transfer_53 TEST/qdrouter@@@ St opcode LSR Sw id B pvT area 0" - 230 bytes transfer presettled
◊  2021-07-21 13:57:09.236416 A0#1870 A [A0_9] <- [] peer_4 flow [0,0] (6,9)
◊  2021-07-21 13:57:09.726112 A0#1890 A [A0_9] -> [] peer_4 transfer [0,0] (6) HELLO settled transfer_48 LLO Sw A id A pvT area 0 instanceq` ' seen B TEST" - 259 bytes transfer presettled
◊  2021-07-21 13:57:09.728331 A0#1897 A [A0_9] <- [] peer_4 flow [0,0] (7,9)
◊  2021-07-21 13:57:09.728522 A0#1898 A [A0_9] <- [] peer_4 transfer [0,1] (4) HELLO settled transfer_44 e HELLO Sw ; id TEST pvT area 0 instanceUd seen A" - 128 bytes transfer presettled
◊  2021-07-21 13:57:09.729912 A0#1913 A [A0_9] -> [] peer_4 flow [0,1] (5,250)
◊  2021-07-21 13:57:10.727374 A0#1957 A [A0_9] -> [] peer_4 transfer [0,0] (7) HELLO settled transfer_48 LLO Sw A id A pvT area 0 instanceq` ' seen B TEST" - 259 bytes transfer presettled
◊  2021-07-21 13:57:10.728919 A0#1964 A [A0_9] <- [] peer_4 flow [0,0] (8,9)
◊  2021-07-21 13:57:10.729105 A0#1965 A [A0_9] <- [] peer_4 transfer [0,1] (5) HELLO settled transfer_44 e HELLO Sw ; id TEST pvT area 0 instanceUd seen A" - 128 bytes transfer presettled
◊  2021-07-21 13:57:10.730493 A0#1980 A [A0_9] -> [] peer_4 flow [0,1] (6,250)
◊  2021-07-21 13:57:11.728996 A0#2024 A [A0_9] -> [] peer_4 transfer [0,0] (8) HELLO settled transfer_48 LLO Sw A id A pvT area 0 instanceq` ' seen B TEST" - 259 bytes transfer presettled
◊  2021-07-21 13:57:11.731306 A0#2031 A [A0_9] <- [] peer_4 flow [0,0] (9,9)
◊  2021-07-21 13:57:11.731485 A0#2032 A [A0_9] <- [] peer_4 transfer [0,1] (6) HELLO settled transfer_44 e HELLO Sw ; id TEST pvT area 0 instanceUd seen A" - 128 bytes transfer presettled
◊  2021-07-21 13:57:11.734702 A0#2053 A [A0_9] -> [] peer_4 flow [0,1] (7,250)
◊  2021-07-21 13:57:12.240694 A0#2096 A [A0_9] -> [] peer_4 transfer [0,0] (9)    RA settled transfer_33 id B pvT area 0 instanceq` ' ls_seqT mobile_seqT " - 267 bytes transfer presettled
◊  2021-07-21 13:57:12.242356 A0#2099 A [A0_9] <- [] peer_4 flow [0,0] (10,9)
◊  2021-07-21 13:57:12.242527 A0#2100 A [A0_9] <- [] peer_4 transfer [0,1] (7)   MAR settled transfer_47 St opcode MAR Sw ) id TEST pvT area 0 have_seqT " - 115 bytes transfer presettled
◊  2021-07-21 13:57:12.244484 A0#2121 A [A0_9] -> [] peer_4 flow [0,1] (8,250)
◊  2021-07-21 13:57:12.730210 A0#2164 A [A0_9] -> [] peer_4 transfer [0,0] (10)HELLO settled transfer_48 LLO Sw A id A pvT area 0 instanceq` ' seen B TEST" - 259 bytes transfer presettled
◊  2021-07-21 13:57:12.730439 A0#2165 A [A0_9] -> [] peer_4 transfer [0,0] (11)   RA settled transfer_49 id A pvT area 0 instanceq` ' ls_seqT mobile_seqT " - 262 bytes transfer presettled
◊  2021-07-21 13:57:12.739479 A0#2200 A [A0_9] <- [] peer_4 flow [0,0] (12,9)
◊  2021-07-21 13:57:12.739666 A0#2201 A [A0_9] <- [] peer_4 transfer [0,1] (8) HELLO settled transfer_44 e HELLO Sw ; id TEST pvT area 0 instanceUd seen A" - 128 bytes transfer presettled
◊  2021-07-21 13:57:12.739779 A0#2202 A [A0_9] <- [] peer_4 close [0]
◊  2021-07-21 13:57:12.739841 A0#2203 A [A0_9] <- [] peer_4 EOS
◊  2021-07-21 13:57:12.743315 A0#2216 A [A0_9] -> [] peer_4 transfer [0,0] (12)  MAU settled transfer_54 area 0 mobile_seqU hints add del M0mobile_address" - 294 bytes transfer presettled
◊  2021-07-21 13:57:12.743431 A0#2217 A [A0_9] -> [] peer_4 close [0]
◊  2021-07-21 13:57:12.743530 A0#2218 A [A0_9] -> [] peer_4 EOS