-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviewboard.asterisk.org/r/4221/
-----------------------------------------------------------
(Updated Dec. 4, 2014, 9:47 a.m.)
Status
------
This change has been marked as submitted.
Review request for Asterisk Developers.
Changes
-------
Committed in revision 428945
Repository: Asterisk
Description
-------
A rather stable test - apps/control_playback/control_reverse - had a sporadic
failure on a build agent. This test uses the AppTest test object, which relies
heavily on AMI events to drive an internal state machine that changes what
action the test should take. During one phase of the test, the test expects the
following:
* Receive a Newexten event, indicating which channel went into the
'application under test' - in this case, ControlPlayback. Remember that channel.
* Look for a TestEvent indicating a playback of tt-monkeys. When we see that,
send a ControlPlayback AMI action to reverse the playback.
The error occurred here in the logs:
[Dec 03 04:20:40] DEBUG[15942]: AMI:160 lineReceived: Line In: 'Event:
TestEvent'
[Dec 03 04:20:40] DEBUG[15942]: AMI:160 lineReceived: Line In: 'Privilege:
test,all'
[Dec 03 04:20:40] DEBUG[15942]: AMI:160 lineReceived: Line In: 'Type:
StateChange'
[Dec 03 04:20:40] DEBUG[15942]: AMI:160 lineReceived: Line In: 'State: PLAYBACK'
[Dec 03 04:20:40] DEBUG[15942]: AMI:160 lineReceived: Line In: 'AppFile: file.c'
[Dec 03 04:20:40] DEBUG[15942]: AMI:160 lineReceived: Line In: 'AppFunction:
ast_streamfile'
[Dec 03 04:20:40] DEBUG[15942]: AMI:160 lineReceived: Line In: 'AppLine: 1108'
[Dec 03 04:20:40] DEBUG[15942]: AMI:160 lineReceived: Line In: 'Message:
tt-monkeys'
[Dec 03 04:20:40] DEBUG[15942]: AMI:160 lineReceived: Line In: 'Channel:
Local/test_remote@default-00000002;2'
[Dec 03 04:20:40] DEBUG[15942]: AMI:160 lineReceived: Line In: ''
[Dec 03 04:20:40] DEBUG[15942]: AMI:221 dispatchIncoming: Dispatch Incoming
[Dec 03 04:20:40] DEBUG[15942]: AMI:248 dispatchIncoming: Incoming Message:
{'appfile': 'file.c', 'appline': '1108', 'appfunction': 'ast_streamfile',
'state': 'PLAYBACK', 'privilege': 'test,all', 'message': 'tt-monkeys', 'type':
'StateChange', 'event': 'TestEvent', 'channel':
'Local/test_remote@default-00000002;2'}
[Dec 03 04:20:40] DEBUG[15942]: ami:144 __event_callback: Condition Message:
tt-monkeys matches Message: tt-monkeys in event
[Dec 03 04:20:40] DEBUG[15942]: ami:144 __event_callback: Condition State:
PLAYBACK matches State: PLAYBACK in event
[Dec 03 04:20:40] DEBUG[15942]: ami:144 __event_callback: Condition Event:
TestEvent matches Event: TestEvent in event
[Dec 03 04:20:40] DEBUG[15942]: apptest:617 execute_next_action: Executing
action 0 on (Controller: ; Application )
[Dec 03 04:20:40] DEBUG[15942]: apptest:820 __call__: Sending message:
{'action': 'ControlPlayback', 'control': 'Reverse', 'Channel': ''}
[Dec 03 04:20:40] DEBUG[15942]: AMI:343 sendMessage: MSG OUT: {'action':
'ControlPlayback', 'control': 'Reverse', 'actionid':
'asterisk-testsuite-32-centos.digium.internal-161149804-9', 'channel': ''}
Egads. We got the TestEvent first! Note that the 'channel' field in the AMI
action sent to Asterisk is empty. No bueno.
[Dec 03 04:20:40] DEBUG[15942]: ami:136 __event_callback: Condition Control not
in event, returning
[Dec 03 04:20:40] DEBUG[15942]: AMI:160 lineReceived: Line In: 'Event: Newexten'
[Dec 03 04:20:40] DEBUG[15942]: AMI:160 lineReceived: Line In: 'Privilege:
call,all'
[Dec 03 04:20:40] DEBUG[15942]: AMI:160 lineReceived: Line In: 'Channel:
Local/test_remote@default-00000002;2'
[Dec 03 04:20:40] DEBUG[15942]: AMI:160 lineReceived: Line In: 'ChannelState: 6'
[Dec 03 04:20:40] DEBUG[15942]: AMI:160 lineReceived: Line In:
'ChannelStateDesc: Up'
[Dec 03 04:20:40] DEBUG[15942]: AMI:160 lineReceived: Line In: 'CallerIDNum:
<unknown>'
[Dec 03 04:20:40] DEBUG[15942]: AMI:160 lineReceived: Line In: 'CallerIDName:
<unknown>'
[Dec 03 04:20:40] DEBUG[15942]: AMI:160 lineReceived: Line In:
'ConnectedLineNum: <unknown>'
[Dec 03 04:20:40] DEBUG[15942]: AMI:160 lineReceived: Line In:
'ConnectedLineName: <unknown>'
[Dec 03 04:20:40] DEBUG[15942]: AMI:160 lineReceived: Line In: 'AccountCode: '
[Dec 03 04:20:40] DEBUG[15942]: AMI:160 lineReceived: Line In: 'Context:
default'
[Dec 03 04:20:40] DEBUG[15942]: AMI:160 lineReceived: Line In: 'Exten:
test_remote'
[Dec 03 04:20:40] DEBUG[15942]: AMI:160 lineReceived: Line In: 'Priority: 3'
[Dec 03 04:20:40] DEBUG[15942]: AMI:160 lineReceived: Line In: 'Uniqueid:
1417602039.26'
[Dec 03 04:20:40] DEBUG[15942]: AMI:160 lineReceived: Line In: 'Extension:
test_remote'
[Dec 03 04:20:40] DEBUG[15942]: AMI:160 lineReceived: Line In: 'Application:
ControlPlayback'
[Dec 03 04:20:40] DEBUG[15942]: AMI:160 lineReceived: Line In: 'AppData:
tt-monkeys'
[Dec 03 04:20:40] DEBUG[15942]: AMI:160 lineReceived: Line In: ''
Whoops. And now we get the Newexten event.
Those are out of order - and as a result, the test fails.
The reason is due to the Test Suite topic not being forwarded to the AMI topic.
The code in manager, prior to this patch, had a dedicated handler for Test
Suite messages that was independent of the topics forwarded to the AMI topic.
Properly forwarding the Test Suite topic to the AMI topic ensures that the
messages are synchronized properly.
This patch does that, and moves the message handling to the Stasis definition
of the Test Suite message in test.c as well.
Diffs
-----
/branches/12/main/test.c 428862
/branches/12/main/manager.c 428862
Diff: https://reviewboard.asterisk.org/r/4221/diff/
Testing
-------
Re-ran the control playback reverse test locally, it passes (although it did
before).
Really, this is a pretty rare failure. It may explain a few rare sporadic
failures we see in 12+.
Thanks,
Matt Jordan
--
_____________________________________________________________________
-- Bandwidth and Colocation Provided by http://www.api-digital.com --
asterisk-dev mailing list
To UNSUBSCRIBE or update options visit:
http://lists.digium.com/mailman/listinfo/asterisk-dev
