[asterisk-bugs] [JIRA] (ASTERISK-29947) testsuite: Premature shutdown causes tests to fail
N A (JIRA)
noreply at issues.asterisk.org
Thu Mar 3 14:09:07 CST 2022
[ https://issues.asterisk.org/jira/browse/ASTERISK-29947?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=258262#comment-258262 ]
N A commented on ASTERISK-29947:
--------------------------------
Here's logs/messages.txt, if that's what you mean by "testsuite log":
It indeed seems to be thinking that all channels are gone, which is the other possibility that was in the back of my mind: [Mar 03 14:57:57] INFO[4145206]: asterisk.pluggable_modules:328 __hangup_handler: All channels have hungup; stopping test
The test is coded in a way however such that this should never be the case.
Here are the last few seconds before this seems to kick in: https://paste.interlinked.us/jumafd20px.txt
[Mar 03 14:57:40] INFO[4145206]: asterisk.test_case:175 __init__: Executing tests/intertest/anoncallreject
[Mar 03 14:57:40] INFO[4145206]: asterisk.test_case:286 create_asterisk: Creating Asterisk instance 1
[Mar 03 14:57:40] INFO[4145206]: asterisk.test_case:465 _start_asterisk: Starting Asterisk instance 1
[Mar 03 14:57:41] INFO[4145206]: asterisk.test_case:350 create_ami_factory: Creating AMIFactory 1 to 127.0.0.1
[Mar 03 14:57:41] INFO[4145206]: twisted:154 publishToNewObserver: Starting factory <starpy.manager.AMIFactory instance at 0x7f748ef21550>
[Mar 03 14:57:41] INFO[4145206]: AMI:184 connectionMade: Connection Made
[Mar 03 14:57:41] INFO[4145206]: AMI:203 onComplete: Login Complete: {u'message': u'Authentication accepted', u'response': u'Success', u'actionid': u'pbxdev-140138591094896-1'}
[Mar 03 14:57:41] INFO[4145206]: asterisk.test_case:603 _ami_connect: AMI Connect instance 1
[Mar 03 14:57:41] INFO[4145206]: asterisk.pluggable_modules:93 ami_connect: AMI 0 connected
[Mar 03 14:57:41] INFO[4145206]: asterisk.pluggable_modules:116 originate_call: Originating call
[Mar 03 14:57:54] INFO[4145206]: asterisk.test_case:508 __stop_instances: Stopping Asterisk instance 1
[Mar 03 14:57:57] INFO[4145206]: asterisk.pluggable_modules:328 __hangup_handler: All channels have hungup; stopping test
[Mar 03 14:57:58] INFO[4145206]: AMI:1137 clientConnectionLost: connection lost, reconnecting...
[Mar 03 14:57:58] INFO[4145206]: twisted:154 publishToNewObserver: <twisted.internet.tcp.Connector instance at 0x7f748ef21640 disconnected IPv4Address(type='TCP', host='127.0.0.1', port=5038)> will retr>
[Mar 03 14:57:58] INFO[4145206]: AMI:1140 clientConnectionLost: None
[Mar 03 14:57:58] INFO[4145206]: twisted:154 publishToNewObserver: Stopping factory <starpy.manager.AMIFactory instance at 0x7f748ef21550>
[Mar 03 14:57:58] WARNING[4145206]: asterisk.ami:208 __check_result: Event occurred 1 times, which is out of the allowable range
[Mar 03 14:57:58] WARNING[4145206]: asterisk.ami:209 __check_result: Event description: {'count': 2, 'conditions': {'match': {'UserEvent': 'LineTest', 'Event': 'UserEvent'}}, 'requirements': {'match': {>
[Mar 03 14:57:58] INFO[4145206]: asterisk.test_case:529 __stop_reactor: Stopping Reactor
[Mar 03 14:57:58] INFO[4145206]: twisted:154 publishToNewObserver: Main loop terminated.
[Mar 03 14:57:58] INFO[4145206]: test_runner:313 main: Test run for tests/intertest/anoncallreject completed with result False
Test case:
[test-anoncallreject] ; Expect: 2. Test that Anonymous Call Rejection works.
exten => s1,1,Answer()
same => n,NoOp(${FILTER(${rcfilter},${SHELL(${rcexec} 'RC:LINE,TYP=CHG,ORD=0,TN=${clid1},AYK=ADD!' | ${rcpost})})}) ; add AYK to this line if it's not already on it.
same => n,SendDTMF(*77) ; enable Anonymous Call Rejection, if not already enabled
same => n,Wait(1)
same => n,Originate(Local/02s$[${EXTEN:-1:1}+1]${CONTEXT}@orig-again,app,Wait,5) ; in 0 seconds, go off-hook on peer #2, and send to s2 in this context.
same => n,Hangup()
exten => s2,1,Answer()
same => n,Wait(2)
same => n,Set(GLOBAL(receivecall)=1) ; yes, this call should come through.
same => n,SendDTMF(${peer1dial}) ; call A.
same => n,Wait(3)
same => n,Originate(Local/22s$[${EXTEN:-1:1}+1]${CONTEXT}@orig-again,app,Wait,5) ; in 2 seconds, go off-hook on peer #2, and send to s3 in this context.
same => n,Hangup() ; cancel the call
exten => s3,1,Answer()
same => n,Wait(2)
same => n,Set(GLOBAL(receivecall)=0) ; no, this call should NOT come through.
same => n,SendDTMF(*67${peer1dial}) ; call A, but "block" our Caller ID.
same => n,Wait(3)
same => n,Originate(Local/21s$[${EXTEN:-1:1}+1]${CONTEXT}@orig-again,app,Wait,5) ; in 2 seconds, go off-hook on peer #1, and send to s4 in this context.
same => n,Hangup() ; cancel the call
exten => s4,1,Answer()
same => n,Wait(2)
same => n,SendDTMF(*87) ; disable Anonymous Call Rejection
same => n,Wait(1)
same => n,Originate(Local/02s$[${EXTEN:-1:1}+1]${CONTEXT}@orig-again,app,Wait,5) ; in 0 seconds, go off-hook on peer #2...
same => n,Hangup()
exten => s5,1,Answer()
same => n,Wait(2)
same => n,Set(GLOBAL(receivecall)=1) ; yes, this call should come through.
same => n,SendDTMF(*67${peer1dial}) ; call A.
same => n,Wait(3)
same => n,Hangup()
exten => ${peer1},1,ExecIf($["${receivecall}"!="1"]?UserEvent(LineTest,Result: Fail))
same => n,Assert($["${receivecall}"="1"])
same => n,UserEvent(LineTest,Result: Pass) ; okay, non-anonymous call came through
same => n,Wait(4) ; should get disconnected during this time...
same => n,UserEvent(LineTest,Result: Fail) ; should not get here
same => n,Assert(0)
[orig-again] ; Delayed origination
exten => _X.,1,Answer()
same => n,Wait(0.25) ; wait at least 0.25 seconds, so that if 0 seconds, same line can hang up.
same => n,Wait(${EXTEN:0:1})
same => n,Originate(PJSIP/${plarcode}@${peer${EXTEN:1:1}},exten,${EXTEN:4},${EXTEN:2:2},1)
same => n,Hangup()
> 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)
More information about the asterisk-bugs
mailing list