[asterisk-bugs] [JIRA] (ASTERISK-29947) testsuite: Premature shutdown causes tests to fail

Thu Mar 3 14:25:06 CST 2022

    [ https://issues.asterisk.org/jira/browse/ASTERISK-29947?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=258264#comment-258264 ] 

N A commented on ASTERISK-29947:
--------------------------------

Here's full.txt: https://paste.interlinked.us/izf6xfiflo.txt

This actually confirms my earlier theory: it can be seen clearly that a core stop gracefully is sent to the Asterisk *IMMEDIATELY* after a Success UserEvent occurs. There isn't any channel hangup in the middle. As soon as that event is processed, BAM, down she goes:

{noformat}
[Mar 03 14:57:54] DEBUG[4145206]: AMI:171 lineReceived: Line In: 'Event: UserEvent'
[Mar 03 14:57:54] DEBUG[4145206]: AMI:171 lineReceived: Line In: 'Privilege: user,all'
[Mar 03 14:57:54] DEBUG[4145206]: AMI:171 lineReceived: Line In: 'Channel: PJSIP/autotest1-00000002'
[Mar 03 14:57:54] DEBUG[4145206]: AMI:171 lineReceived: Line In: 'ChannelState: 4'
[Mar 03 14:57:54] DEBUG[4145206]: AMI:171 lineReceived: Line In: 'ChannelStateDesc: Ring'
[Mar 03 14:57:54] DEBUG[4145206]: AMI:171 lineReceived: Line In: 'CallerIDNum: 2156'
[Mar 03 14:57:54] DEBUG[4145206]: AMI:171 lineReceived: Line In: 'CallerIDName: ALBERT, NAVEEN'
[Mar 03 14:57:54] DEBUG[4145206]: AMI:171 lineReceived: Line In: 'ConnectedLineNum: <unknown>'
[Mar 03 14:57:54] DEBUG[4145206]: AMI:171 lineReceived: Line In: 'ConnectedLineName: <unknown>'
[Mar 03 14:57:54] DEBUG[4145206]: AMI:171 lineReceived: Line In: 'Language: en'
[Mar 03 14:57:54] DEBUG[4145206]: AMI:171 lineReceived: Line In: 'AccountCode: '
[Mar 03 14:57:54] DEBUG[4145206]: AMI:171 lineReceived: Line In: 'Context: test-anoncallreject'
[Mar 03 14:57:54] DEBUG[4145206]: AMI:171 lineReceived: Line In: 'Exten: autotest1'
[Mar 03 14:57:54] DEBUG[4145206]: AMI:171 lineReceived: Line In: 'Priority: 3'
[Mar 03 14:57:54] DEBUG[4145206]: AMI:171 lineReceived: Line In: 'Uniqueid: 1646337474.36'
[Mar 03 14:57:54] DEBUG[4145206]: AMI:171 lineReceived: Line In: 'Linkedid: 1646337474.36'
[Mar 03 14:57:54] DEBUG[4145206]: AMI:171 lineReceived: Line In: 'UserEvent: LineTest'
[Mar 03 14:57:54] DEBUG[4145206]: AMI:171 lineReceived: Line In: 'Result: Pass'
[Mar 03 14:57:54] DEBUG[4145206]: AMI:171 lineReceived: Line In: ''
[Mar 03 14:57:54] DEBUG[4145206]: AMI:233 dispatchIncoming: Dispatch Incoming
[Mar 03 14:57:54] DEBUG[4145206]: AMI:263 dispatchIncoming: Incoming Message: {u'connectedlinenum': u'<unknown>', u'linkedid': u'1646337474.36', u'uniqueid': u'1646337474.36', u'language': u'en', u'accountcode': u'', u'channelstate': u'4', u'exten': u'autotest1', u'calleridnum': u'2156', u'priority': u'3', u'userevent': u'LineTest', u'connectedlinename': u'<unknown>', u'result': u'Pass', u'context': u'test-anoncallreject', u'calleridname': u'ALBERT, NAVEEN', u'privilege': u'user,all', u'event': u'UserEvent', u'channel': u'PJSIP/autotest1-00000002', u'channelstatedesc': u'Ring'}
[Mar 03 14:57:54] DEBUG[4145206]: asterisk.ami:165 __event_callback: Condition UserEvent: LineTest matches UserEvent: LineTest in event
[Mar 03 14:57:54] DEBUG[4145206]: asterisk.ami:165 __event_callback: Condition Event: UserEvent matches Event: UserEvent in event
[Mar 03 14:57:54] DEBUG[4145206]: asterisk.ami:254 event_callback: Requirement Result: Pass matches Result: Pass in event
[Mar 03 14:57:54] INFO[4145206]: asterisk.test_case:508 __stop_instances: Stopping Asterisk instance 1
[Mar 03 14:57:54] DEBUG[4145206]: asterisk.asterisk:574 __send_stop_gracefully: sending stop gracefully
[Mar 03 14:57:54] DEBUG[4145206]: asterisk.asterisk:938 cli_exec: Executing ['/usr/sbin/asterisk', '-C', '/tmp/asterisk-testsuite/238b995b0768752849801561e0174342/run_23/ast1/etc/asterisk/asterisk.conf', '-rx', 'core stop gracefully'] ...
{noformat}

> testsuite: Premature shutdown causes tests to fail
> --------------------------------------------------
>
>                 Key: ASTERISK-29947
>                 URL: https://issues.asterisk.org/jira/browse/ASTERISK-29947
>             Project: Asterisk
>          Issue Type: Bug
>      Security Level: None
>          Components: Tests/testsuite
>    Affects Versions: 18.9.0
>         Environment: Debian 11
>            Reporter: N A
>            Assignee: N A
>
> A problem I've been noticing for a while is that sometimes the test suite will prematurely kill a test if a UserEvent for success has been received, even if the success count hasn't yet hit the required count.
> For instance, I have a test that aborts after 1 success user event, when 2 are required, and then it fails because Asterisk got shut down even though the test was still running, and obviously 1 is not 2 so the test fails.
> If I simply comment out the success user event, the test runs to completion successfully, but obviously this doesn't make it work.
> I have ensured that there is always a channel up at all parts of the test so it isn't the case that Asterisk is shutting down because the test suite has detected there are no channels. Instead, it seems to be reacting in a majorly buggy way.
> The only workaround is simply to include at most 1 success user event, which kind of defeats the point of trying to add rich tests to the test suite in the first place.
> Granted, this doesn't happen with every test, but it seems to with a large number.
> In the past, I've rewritten tests to only include 1 success, to improve reliability, but it seems in some cases it will just consistently fail like this.
> ```
> root at pbxdev:/usr/src/testsuite# ./runtests.py --test=tests/intertest/anoncallreject --timeout=60
> Running tests for Asterisk (run 1 of 1)...
> Tests to run: 1 * 1 time(s) = 1  Maximum test inactivity time: 60 sec.
> --> Running test 'tests/intertest/anoncallreject' ...
> Making sure Asterisk isn't running ...
> Making sure SIPp isn't running...
> Running tests/intertest/anoncallreject ...
> [Mar 03 14:39:02] WARNING[4143745]: asterisk.ami:208 __check_result: Event occurred 1 times, which is out of the allowable range
> [Mar 03 14:39:02] WARNING[4143745]: asterisk.ami:209 __check_result: Event description: {'count': 2, 'conditions': {'match': {'UserEvent': 'LineTest', 'Event': 'UserEvent'}}, 'requirements': {'match': {'Result': 'Pass'}}}
> Test tests/intertest/anoncallreject failed
> <?xml version="1.0" encoding="utf-8"?>
> <testsuites>
>   <testsuite errors="0" failures="1" name="AsteriskTestSuite" tests="1" time="18.62" timestamp="2022-03-03T14:38:43 EST">
>     <testcase classname="intertest" name="anoncallreject" time="18.62">
>       <failure>Running tests/intertest/anoncallreject ...
> [Mar 03 14:39:02] WARNING[4143745]: asterisk.ami:208 __check_result: Event occurred 1 times, which is out of the allowable range
> [Mar 03 14:39:02] WARNING[4143745]: asterisk.ami:209 __check_result: Event description: {'count': 2, 'conditions': {'match': {'UserEvent': 'LineTest', 'Event': 'UserEvent'}}, 'requirements': {'match': {'Result': 'Pass'}}}
> </failure>
>     </testcase>
>   </testsuite>
> </testsuites>
> ```

--
This message was sent by Atlassian JIRA
(v6.2#6252)