[Jun 20 11:25:12] DEBUG[12945]: asterisk.TestConditions:103 register_observer: Registering: > [Jun 20 11:25:12] DEBUG[12945]: asterisk.TestConditions:103 register_observer: Registering: > [Jun 20 11:25:12] INFO[12945]: asterisk.TestCase:89 __init__: Executing tests/channels/SIP/generic_ccss [Jun 20 11:25:12] INFO[12945]: asterisk.TestCase:138 create_asterisk: Creating Asterisk instance 1 [Jun 20 11:25:13] INFO[12945]: asterisk.TestCase:138 create_asterisk: Creating Asterisk instance 2 [Jun 20 11:25:14] INFO[12945]: asterisk.TestCase:250 __start_asterisk: Starting Asterisk instance 1 [Jun 20 11:25:14] DEBUG[12945]: asterisk.asterisk:123 connectionMade: Asterisk 127.0.0.1 - connection made [Jun 20 11:25:14] DEBUG[12945]: asterisk.asterisk:577 cli_exec: Executing ['/usr/sbin/asterisk', '-C', '/tmp/asterisk-testsuite/channels/SIP/generic_ccss/ast1/etc/asterisk/asterisk.conf', '-rx', 'core waitfullybooted'] ... [Jun 20 11:25:14] INFO[12945]: asterisk.TestCase:250 __start_asterisk: Starting Asterisk instance 2 [Jun 20 11:25:14] DEBUG[12945]: asterisk.asterisk:123 connectionMade: Asterisk 127.0.0.2 - connection made [Jun 20 11:25:14] DEBUG[12945]: asterisk.asterisk:577 cli_exec: Executing ['/usr/sbin/asterisk', '-C', '/tmp/asterisk-testsuite/channels/SIP/generic_ccss/ast2/etc/asterisk/asterisk.conf', '-rx', 'core waitfullybooted'] ... [Jun 20 11:25:14] DEBUG[12945]: asterisk.asterisk:62 __cli_output_callback: Asterisk CLI 127.0.0.2 exited 1 [Jun 20 11:25:14] DEBUG[12945]: asterisk.asterisk:63 __cli_output_callback: Parsing /tmp/asterisk-testsuite/channels/SIP/generic_ccss/ast2/etc/asterisk/extconfig.conf Unable to connect to remote asterisk (does /tmp/asterisk-testsuite/channels/SIP/generic_ccss/ast2/var/run/asterisk/asterisk.ctl exist?) [Jun 20 11:25:14] DEBUG[12945]: asterisk.asterisk:250 __wait_fully_booted_error: Asterisk core waitfullybooted failed, attempting again... [Jun 20 11:25:14] DEBUG[12945]: asterisk.asterisk:577 cli_exec: Executing ['/usr/sbin/asterisk', '-C', '/tmp/asterisk-testsuite/channels/SIP/generic_ccss/ast2/etc/asterisk/asterisk.conf', '-rx', 'core waitfullybooted'] ... [Jun 20 11:25:17] DEBUG[12945]: asterisk.asterisk:62 __cli_output_callback: Asterisk CLI 127.0.0.1 exited 0 [Jun 20 11:25:17] DEBUG[12945]: asterisk.asterisk:63 __cli_output_callback: Asterisk has fully booted. Parsing /tmp/asterisk-testsuite/channels/SIP/generic_ccss/ast1/etc/asterisk/extconfig.conf Asterisk ending (0). [Jun 20 11:25:17] DEBUG[12945]: asterisk.asterisk:62 __cli_output_callback: Asterisk CLI 127.0.0.2 exited 0 [Jun 20 11:25:17] DEBUG[12945]: asterisk.asterisk:63 __cli_output_callback: Asterisk has fully booted. Parsing /tmp/asterisk-testsuite/channels/SIP/generic_ccss/ast2/etc/asterisk/extconfig.conf Asterisk ending (0). [Jun 20 11:25:17] INFO[12945]: asterisk.TestCase:162 create_ami_factory: Creating AMIFactory 1 [Jun 20 11:25:17] INFO[12945]: asterisk.TestCase:162 create_ami_factory: Creating AMIFactory 2 [Jun 20 11:25:17] INFO[12945]: AMI:142 connectionMade: Connection Made [Jun 20 11:25:17] INFO[12945]: AMI:142 connectionMade: Connection Made [Jun 20 11:25:17] INFO[12945]: AMI:156 onComplete: Login Complete: {'message': 'Authentication accepted', 'response': 'Success', 'actionid': 'pigtest-171154124-1'} [Jun 20 11:25:17] INFO[12945]: asterisk.TestCase:381 __ami_connect: AMI Connect instance 2 [Jun 20 11:25:17] INFO[12945]: __main__:41 ami_connect: Initiating the blocking call from dialplan to bob [Jun 20 11:25:17] INFO[12945]: AMI:156 onComplete: Login Complete: {'message': 'Authentication accepted', 'response': 'Success', 'actionid': 'pigtest-171176716-1'} [Jun 20 11:25:17] INFO[12945]: asterisk.TestCase:381 __ami_connect: AMI Connect instance 1 [Jun 20 11:25:18] INFO[12945]: __main__:59 ccss_callback: Bouncing a call off the ccss test instance (ast2) now that bob is occupied [Jun 20 11:25:18] INFO[12945]: __main__:64 ccss_callback: Requesting CCBS [Jun 20 11:25:19] INFO[12945]: __main__:69 ccss_callback: CCBS requested, getting channel list [Jun 20 11:25:19] INFO[12945]: __main__:56 ccss_callback: macro executed as expected [Jun 20 11:25:19] INFO[12945]: __main__:53 ccss_callback: subroutine executed as expected [Jun 20 11:25:19] INFO[12945]: asterisk.TestCase:296 __stop_instances: Stopping Asterisk instance 1 [Jun 20 11:25:19] DEBUG[12945]: asterisk.asterisk:577 cli_exec: Executing ['/usr/sbin/asterisk', '-C', '/tmp/asterisk-testsuite/channels/SIP/generic_ccss/ast1/etc/asterisk/asterisk.conf', '-rx', 'core stop gracefully'] ... [Jun 20 11:25:19] INFO[12945]: asterisk.TestCase:296 __stop_instances: Stopping Asterisk instance 2 [Jun 20 11:25:19] DEBUG[12945]: asterisk.asterisk:577 cli_exec: Executing ['/usr/sbin/asterisk', '-C', '/tmp/asterisk-testsuite/channels/SIP/generic_ccss/ast2/etc/asterisk/asterisk.conf', '-rx', 'core stop gracefully'] ... [Jun 20 11:25:24] DEBUG[12945]: asterisk.asterisk:577 cli_exec: Executing ['/usr/sbin/asterisk', '-C', '/tmp/asterisk-testsuite/channels/SIP/generic_ccss/ast1/etc/asterisk/asterisk.conf', '-rx', 'core stop now'] ... [Jun 20 11:25:24] DEBUG[12945]: asterisk.asterisk:577 cli_exec: Executing ['/usr/sbin/asterisk', '-C', '/tmp/asterisk-testsuite/channels/SIP/generic_ccss/ast2/etc/asterisk/asterisk.conf', '-rx', 'core stop now'] ... [Jun 20 11:25:24] INFO[12945]: __main__:64 ccss_callback: Requesting CCBS [Jun 20 11:25:24] WARNING[12945]: __main__:31 handle_failure: error sending originate: [Jun 20 11:25:24] WARNING[12945]: __main__:32 handle_failure: Traceback (most recent call last): File "/home/rmudgett/.local/lib/python2.6/site-packages/starpy/manager.py", line 132, in lineReceived self.dispatchIncoming() # does dispatch and clears cache File "/home/rmudgett/.local/lib/python2.6/site-packages/starpy/manager.py", line 214, in dispatchIncoming callback(message) File "/usr/lib/python2.6/dist-packages/twisted/internet/defer.py", line 280, in callback self._startRunCallbacks(result) File "/usr/lib/python2.6/dist-packages/twisted/internet/defer.py", line 354, in _startRunCallbacks self._runCallbacks() --- --- File "/usr/lib/python2.6/dist-packages/twisted/internet/defer.py", line 371, in _runCallbacks self.result = callback(self.result, *args, **kw) File "/home/rmudgett/.local/lib/python2.6/site-packages/starpy/manager.py", line 318, in errorUnlessResponse raise error.AMICommandFailure(message) starpy.error.AMICommandFailure: {'message': 'Originate failed', 'response': 'Error', 'actionid': 'pigtest-171176716-6'} [Jun 20 11:25:25] DEBUG[12945]: asterisk.asterisk:118 outReceived: Asterisk 127.0.0.2 received: Parsing /tmp/asterisk-testsuite/channels/SIP/generic_ccss/ast2/etc/asterisk/extconfig.conf Resetting translation matrix Parsing /tmp/asterisk-testsuite/channels/SIP/generic_ccss/ast2/etc/asterisk/logger.conf Parsing /tmp/asterisk-testsuite/channels/SIP/generic_ccss/ast2/etc/asterisk/logger.general.conf.inc Parsing /tmp/asterisk-testsuite/channels/SIP/generic_ccss/ast2/etc/asterisk/logger.logfiles.conf.inc [Jun 20 11:25:25] DEBUG[12945]: asterisk.asterisk:62 __cli_output_callback: Asterisk CLI 127.0.0.2 exited 0 [Jun 20 11:25:25] DEBUG[12945]: asterisk.asterisk:63 __cli_output_callback: Parsing /tmp/asterisk-testsuite/channels/SIP/generic_ccss/ast2/etc/asterisk/extconfig.conf Asterisk ending (0). [Jun 20 11:25:25] DEBUG[12945]: asterisk.asterisk:325 __stop_now_callback: Successfully stopped Asterisk 127.0.0.2 [Jun 20 11:25:25] DEBUG[12945]: asterisk.asterisk:62 __cli_output_callback: Asterisk CLI 127.0.0.2 exited 0 [Jun 20 11:25:25] DEBUG[12945]: asterisk.asterisk:63 __cli_output_callback: Parsing /tmp/asterisk-testsuite/channels/SIP/generic_ccss/ast2/etc/asterisk/extconfig.conf Asterisk ending (0). [Jun 20 11:25:25] DEBUG[12945]: asterisk.asterisk:301 __stop_gracefully_callback: Successfully stopped Asterisk 127.0.0.2 [Jun 20 11:25:25] DEBUG[12945]: asterisk.asterisk:118 outReceived: Asterisk 127.0.0.1 received: Parsing /tmp/asterisk-testsuite/channels/SIP/generic_ccss/ast1/etc/asterisk/extconfig.conf Resetting translation matrix Parsing /tmp/asterisk-testsuite/channels/SIP/generic_ccss/ast1/etc/asterisk/logger.conf Parsing /tmp/asterisk-testsuite/channels/SIP/generic_ccss/ast1/etc/asterisk/logger.general.conf.inc Parsing /tmp/asterisk-testsuite/channels/SIP/generic_ccss/ast1/etc/asterisk/logger.logfiles.conf.inc [Jun 20 11:25:25] DEBUG[12945]: asterisk.asterisk:62 __cli_output_callback: Asterisk CLI 127.0.0.1 exited 0 [Jun 20 11:25:25] DEBUG[12945]: asterisk.asterisk:63 __cli_output_callback: Parsing /tmp/asterisk-testsuite/channels/SIP/generic_ccss/ast1/etc/asterisk/extconfig.conf Asterisk ending (0). [Jun 20 11:25:25] DEBUG[12945]: asterisk.asterisk:325 __stop_now_callback: Successfully stopped Asterisk 127.0.0.1 [Jun 20 11:25:25] DEBUG[12945]: asterisk.asterisk:62 __cli_output_callback: Asterisk CLI 127.0.0.1 exited 0 [Jun 20 11:25:25] DEBUG[12945]: asterisk.asterisk:63 __cli_output_callback: Parsing /tmp/asterisk-testsuite/channels/SIP/generic_ccss/ast1/etc/asterisk/extconfig.conf Asterisk ending (0). [Jun 20 11:25:25] DEBUG[12945]: asterisk.asterisk:301 __stop_gracefully_callback: Successfully stopped Asterisk 127.0.0.1 [Jun 20 11:25:25] INFO[12945]: asterisk.TestCase:318 __stop_reactor: Stopping Reactor