[Sep 28 11:13:29] INFO[7691]: test_case:158 __init__: Executing tests/channels/SIP/tcpauthlimit/tcp_client_scenario [Sep 28 11:13:29] DEBUG[7691]: test_conditions:143 register_observer: Registering: [Sep 28 11:13:29] DEBUG[7691]: test_conditions:143 register_observer: Registering: [Sep 28 11:13:29] DEBUG[7691]: test_conditions:143 register_observer: Registering: > [Sep 28 11:13:29] INFO[7691]: test_case:233 create_asterisk: Creating Asterisk instance 1 [Sep 28 11:13:29] DEBUG[7691]: test_runner:171 load_and_parse_module: Importing tcpauthlimit.TcpAuthLimitTestModule [Sep 28 11:13:29] DEBUG[7691]: test_runner:42 __init__: TestModuleFinder supports path tests/channels/SIP/tcpauthlimit/tcp_client_scenario [Sep 28 11:13:29] DEBUG[7691]: tcpauthlimit:75 __build_scenarios: TcpAuthLimitTestModule: Building test scenarios. [Sep 28 11:13:29] INFO[7691]: test_case:368 _start_asterisk: Starting Asterisk instance 1 [Sep 28 11:13:29] DEBUG[7691]: asterisk:123 connectionMade: Asterisk 127.0.0.1 - connection made [Sep 28 11:13:30] DEBUG[7691]: asterisk:700 cli_exec: Executing ['/usr/sbin/asterisk', '-C', '/tmp/asterisk-testsuite/c7eaf18a4896145a44d3b287d6e4c1ca/run_1/ast1/etc/asterisk/asterisk.conf', '-rx', 'core waitfullybooted'] ... [Sep 28 11:13:30] DEBUG[7691]: asterisk:64 __cli_output_callback: Asterisk CLI 127.0.0.1 exited 0 [Sep 28 11:13:30] INFO[7691]: test_case:265 create_ami_factory: Creating AMIFactory 1 [Sep 28 11:13:30] INFO[7691]: twisted:154 publishToNewObserver: Starting factory [Sep 28 11:13:30] INFO[7691]: AMI:173 connectionMade: Connection Made [Sep 28 11:13:30] DEBUG[7691]: AMI:343 sendMessage: MSG OUT: {'action': 'login', 'username': 'user', 'secret': 'mysecret', 'actionid': 'genesis-3067125932-1'} [Sep 28 11:13:30] DEBUG[7691]: AMI:160 lineReceived: Line In: 'Asterisk Call Manager/1.3' [Sep 28 11:13:30] DEBUG[7691]: AMI:160 lineReceived: Line In: 'Response: Success' [Sep 28 11:13:30] DEBUG[7691]: AMI:160 lineReceived: Line In: 'ActionID: genesis-3067125932-1' [Sep 28 11:13:30] DEBUG[7691]: AMI:160 lineReceived: Line In: 'Message: Authentication accepted' [Sep 28 11:13:30] DEBUG[7691]: AMI:160 lineReceived: Line In: '' [Sep 28 11:13:30] DEBUG[7691]: AMI:221 dispatchIncoming: Dispatch Incoming [Sep 28 11:13:30] DEBUG[7691]: AMI:248 dispatchIncoming: Incoming Message: {'message': 'Authentication accepted', 'response': 'Success', 'actionid': 'genesis-3067125932-1'} [Sep 28 11:13:30] INFO[7691]: AMI:191 onComplete: Login Complete: {'message': 'Authentication accepted', 'response': 'Success', 'actionid': 'genesis-3067125932-1'} [Sep 28 11:13:30] INFO[7691]: test_case:502 _ami_connect: AMI Connect instance 1 [Sep 28 11:13:30] DEBUG[7691]: tcpauthlimit:261 __run_scenarios: TcpAuthLimitTestModule: Running test scenarios. [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:618 run: TcpClientScenario [felonius-gru]: Starting scenario... [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:640 __start_clients: TcpClientScenario [felonius-gru]: Attempting to connect 10 clients to Asterisk... [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:305 connect: TcpClientFactory [('127.0.0.1', 5062)]: Connecting to host '127.0.0.1:5060'... [Sep 28 11:13:30] INFO[7691]: twisted:154 publishToNewObserver: Starting factory [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:305 connect: TcpClientFactory [('127.0.0.1', 5063)]: Connecting to host '127.0.0.1:5060'... [Sep 28 11:13:30] INFO[7691]: twisted:154 publishToNewObserver: Starting factory [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:305 connect: TcpClientFactory [('127.0.0.1', 5064)]: Connecting to host '127.0.0.1:5060'... [Sep 28 11:13:30] INFO[7691]: twisted:154 publishToNewObserver: Starting factory [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:305 connect: TcpClientFactory [('127.0.0.1', 5065)]: Connecting to host '127.0.0.1:5060'... [Sep 28 11:13:30] INFO[7691]: twisted:154 publishToNewObserver: Starting factory [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:305 connect: TcpClientFactory [('127.0.0.1', 5066)]: Connecting to host '127.0.0.1:5060'... [Sep 28 11:13:30] INFO[7691]: twisted:154 publishToNewObserver: Starting factory [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:305 connect: TcpClientFactory [('127.0.0.1', 5067)]: Connecting to host '127.0.0.1:5060'... [Sep 28 11:13:30] INFO[7691]: twisted:154 publishToNewObserver: Starting factory [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:305 connect: TcpClientFactory [('127.0.0.1', 5068)]: Connecting to host '127.0.0.1:5060'... [Sep 28 11:13:30] INFO[7691]: twisted:154 publishToNewObserver: Starting factory [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:305 connect: TcpClientFactory [('127.0.0.1', 5069)]: Connecting to host '127.0.0.1:5060'... [Sep 28 11:13:30] INFO[7691]: twisted:154 publishToNewObserver: Starting factory [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:305 connect: TcpClientFactory [('127.0.0.1', 5070)]: Connecting to host '127.0.0.1:5060'... [Sep 28 11:13:30] INFO[7691]: twisted:154 publishToNewObserver: Starting factory [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:305 connect: TcpClientFactory [('127.0.0.1', 5071)]: Connecting to host '127.0.0.1:5060'... [Sep 28 11:13:30] INFO[7691]: twisted:154 publishToNewObserver: Starting factory [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:250 buildProtocol: TcpClientFactory [('127.0.0.1', 5062)]: Building a TcpClient protocol... [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:319 disconnect: TcpClientFactory [('127.0.0.1', 5062)]: Attempting to destroy client connection... [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:323 disconnect: TcpClientFactory [('127.0.0.1', 5062)]: I don't have a client connection to destroy. [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:96 connectionMade: TcpClient [127.0.0.1:5062]: Initial connection to 127.0.0.1:5060 established. [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:168 __sync_socket: TcpClient [127.0.0.1:5062]: Syncronizing the connection state... [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:102 connectionMade: TcpClient [127.0.0.1:5062]: Connection state to 127.0.0.1:5060 : DONE [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:118 disconnect: TcpClient [127.0.0.1:5062]: Disconnecting the transport... [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:353 __on_client_connection_made: TcpClientFactory [('127.0.0.1', 5062)]: Client is done with connection attempt to host: '127.0.0.1:5060' [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:581 __on_client_connecting_change: TcpClientScenario [felonius-gru]: Received a connection change notice from client [('127.0.0.1', 5062)]. [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:250 buildProtocol: TcpClientFactory [('127.0.0.1', 5063)]: Building a TcpClient protocol... [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:319 disconnect: TcpClientFactory [('127.0.0.1', 5063)]: Attempting to destroy client connection... [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:323 disconnect: TcpClientFactory [('127.0.0.1', 5063)]: I don't have a client connection to destroy. [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:96 connectionMade: TcpClient [127.0.0.1:5063]: Initial connection to 127.0.0.1:5060 established. [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:168 __sync_socket: TcpClient [127.0.0.1:5063]: Syncronizing the connection state... [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:102 connectionMade: TcpClient [127.0.0.1:5063]: Connection state to 127.0.0.1:5060 : DONE [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:118 disconnect: TcpClient [127.0.0.1:5063]: Disconnecting the transport... [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:353 __on_client_connection_made: TcpClientFactory [('127.0.0.1', 5063)]: Client is done with connection attempt to host: '127.0.0.1:5060' [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:581 __on_client_connecting_change: TcpClientScenario [felonius-gru]: Received a connection change notice from client [('127.0.0.1', 5063)]. [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:250 buildProtocol: TcpClientFactory [('127.0.0.1', 5064)]: Building a TcpClient protocol... [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:319 disconnect: TcpClientFactory [('127.0.0.1', 5064)]: Attempting to destroy client connection... [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:323 disconnect: TcpClientFactory [('127.0.0.1', 5064)]: I don't have a client connection to destroy. [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:96 connectionMade: TcpClient [127.0.0.1:5064]: Initial connection to 127.0.0.1:5060 established. [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:168 __sync_socket: TcpClient [127.0.0.1:5064]: Syncronizing the connection state... [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:102 connectionMade: TcpClient [127.0.0.1:5064]: Connection state to 127.0.0.1:5060 : DONE [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:118 disconnect: TcpClient [127.0.0.1:5064]: Disconnecting the transport... [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:353 __on_client_connection_made: TcpClientFactory [('127.0.0.1', 5064)]: Client is done with connection attempt to host: '127.0.0.1:5060' [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:581 __on_client_connecting_change: TcpClientScenario [felonius-gru]: Received a connection change notice from client [('127.0.0.1', 5064)]. [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:250 buildProtocol: TcpClientFactory [('127.0.0.1', 5065)]: Building a TcpClient protocol... [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:319 disconnect: TcpClientFactory [('127.0.0.1', 5065)]: Attempting to destroy client connection... [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:323 disconnect: TcpClientFactory [('127.0.0.1', 5065)]: I don't have a client connection to destroy. [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:96 connectionMade: TcpClient [127.0.0.1:5065]: Initial connection to 127.0.0.1:5060 established. [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:168 __sync_socket: TcpClient [127.0.0.1:5065]: Syncronizing the connection state... [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:106 connectionMade: TcpClient [127.0.0.1:5065]: Connection to 127.0.0.1:5060 successful. [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:353 __on_client_connection_made: TcpClientFactory [('127.0.0.1', 5065)]: Client is done with connection attempt to host: '127.0.0.1:5060' [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:581 __on_client_connecting_change: TcpClientScenario [felonius-gru]: Received a connection change notice from client [('127.0.0.1', 5065)]. [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:250 buildProtocol: TcpClientFactory [('127.0.0.1', 5066)]: Building a TcpClient protocol... [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:319 disconnect: TcpClientFactory [('127.0.0.1', 5066)]: Attempting to destroy client connection... [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:323 disconnect: TcpClientFactory [('127.0.0.1', 5066)]: I don't have a client connection to destroy. [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:96 connectionMade: TcpClient [127.0.0.1:5066]: Initial connection to 127.0.0.1:5060 established. [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:168 __sync_socket: TcpClient [127.0.0.1:5066]: Syncronizing the connection state... [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:102 connectionMade: TcpClient [127.0.0.1:5066]: Connection state to 127.0.0.1:5060 : DONE [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:118 disconnect: TcpClient [127.0.0.1:5066]: Disconnecting the transport... [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:353 __on_client_connection_made: TcpClientFactory [('127.0.0.1', 5066)]: Client is done with connection attempt to host: '127.0.0.1:5060' [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:581 __on_client_connecting_change: TcpClientScenario [felonius-gru]: Received a connection change notice from client [('127.0.0.1', 5066)]. [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:250 buildProtocol: TcpClientFactory [('127.0.0.1', 5067)]: Building a TcpClient protocol... [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:319 disconnect: TcpClientFactory [('127.0.0.1', 5067)]: Attempting to destroy client connection... [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:323 disconnect: TcpClientFactory [('127.0.0.1', 5067)]: I don't have a client connection to destroy. [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:96 connectionMade: TcpClient [127.0.0.1:5067]: Initial connection to 127.0.0.1:5060 established. [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:168 __sync_socket: TcpClient [127.0.0.1:5067]: Syncronizing the connection state... [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:102 connectionMade: TcpClient [127.0.0.1:5067]: Connection state to 127.0.0.1:5060 : DONE [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:118 disconnect: TcpClient [127.0.0.1:5067]: Disconnecting the transport... [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:353 __on_client_connection_made: TcpClientFactory [('127.0.0.1', 5067)]: Client is done with connection attempt to host: '127.0.0.1:5060' [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:581 __on_client_connecting_change: TcpClientScenario [felonius-gru]: Received a connection change notice from client [('127.0.0.1', 5067)]. [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:250 buildProtocol: TcpClientFactory [('127.0.0.1', 5068)]: Building a TcpClient protocol... [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:319 disconnect: TcpClientFactory [('127.0.0.1', 5068)]: Attempting to destroy client connection... [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:323 disconnect: TcpClientFactory [('127.0.0.1', 5068)]: I don't have a client connection to destroy. [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:96 connectionMade: TcpClient [127.0.0.1:5068]: Initial connection to 127.0.0.1:5060 established. [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:168 __sync_socket: TcpClient [127.0.0.1:5068]: Syncronizing the connection state... [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:102 connectionMade: TcpClient [127.0.0.1:5068]: Connection state to 127.0.0.1:5060 : DONE [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:118 disconnect: TcpClient [127.0.0.1:5068]: Disconnecting the transport... [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:353 __on_client_connection_made: TcpClientFactory [('127.0.0.1', 5068)]: Client is done with connection attempt to host: '127.0.0.1:5060' [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:581 __on_client_connecting_change: TcpClientScenario [felonius-gru]: Received a connection change notice from client [('127.0.0.1', 5068)]. [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:250 buildProtocol: TcpClientFactory [('127.0.0.1', 5069)]: Building a TcpClient protocol... [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:319 disconnect: TcpClientFactory [('127.0.0.1', 5069)]: Attempting to destroy client connection... [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:323 disconnect: TcpClientFactory [('127.0.0.1', 5069)]: I don't have a client connection to destroy. [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:96 connectionMade: TcpClient [127.0.0.1:5069]: Initial connection to 127.0.0.1:5060 established. [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:168 __sync_socket: TcpClient [127.0.0.1:5069]: Syncronizing the connection state... [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:102 connectionMade: TcpClient [127.0.0.1:5069]: Connection state to 127.0.0.1:5060 : DONE [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:118 disconnect: TcpClient [127.0.0.1:5069]: Disconnecting the transport... [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:353 __on_client_connection_made: TcpClientFactory [('127.0.0.1', 5069)]: Client is done with connection attempt to host: '127.0.0.1:5060' [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:581 __on_client_connecting_change: TcpClientScenario [felonius-gru]: Received a connection change notice from client [('127.0.0.1', 5069)]. [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:250 buildProtocol: TcpClientFactory [('127.0.0.1', 5070)]: Building a TcpClient protocol... [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:319 disconnect: TcpClientFactory [('127.0.0.1', 5070)]: Attempting to destroy client connection... [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:323 disconnect: TcpClientFactory [('127.0.0.1', 5070)]: I don't have a client connection to destroy. [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:96 connectionMade: TcpClient [127.0.0.1:5070]: Initial connection to 127.0.0.1:5060 established. [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:168 __sync_socket: TcpClient [127.0.0.1:5070]: Syncronizing the connection state... [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:102 connectionMade: TcpClient [127.0.0.1:5070]: Connection state to 127.0.0.1:5060 : DONE [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:118 disconnect: TcpClient [127.0.0.1:5070]: Disconnecting the transport... [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:353 __on_client_connection_made: TcpClientFactory [('127.0.0.1', 5070)]: Client is done with connection attempt to host: '127.0.0.1:5060' [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:581 __on_client_connecting_change: TcpClientScenario [felonius-gru]: Received a connection change notice from client [('127.0.0.1', 5070)]. [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:250 buildProtocol: TcpClientFactory [('127.0.0.1', 5071)]: Building a TcpClient protocol... [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:319 disconnect: TcpClientFactory [('127.0.0.1', 5071)]: Attempting to destroy client connection... [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:323 disconnect: TcpClientFactory [('127.0.0.1', 5071)]: I don't have a client connection to destroy. [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:96 connectionMade: TcpClient [127.0.0.1:5071]: Initial connection to 127.0.0.1:5060 established. [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:168 __sync_socket: TcpClient [127.0.0.1:5071]: Syncronizing the connection state... [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:106 connectionMade: TcpClient [127.0.0.1:5071]: Connection to 127.0.0.1:5060 successful. [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:353 __on_client_connection_made: TcpClientFactory [('127.0.0.1', 5071)]: Client is done with connection attempt to host: '127.0.0.1:5060' [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:581 __on_client_connecting_change: TcpClientScenario [felonius-gru]: Received a connection change notice from client [('127.0.0.1', 5071)]. [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:524 __handle_state_change: TcpClientScenario [felonius-gru]: All clients have finished connecting. [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:462 __evaluate_results: TcpClientScenario [felonius-gru]: Evaluating scenario results... [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:659 __teardown_state: TcpClientScenario [felonius-gru]: Tearing down the scenario... [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:445 __disconnect_client: TcpClientScenario [felonius-gru]: Disconnecting client [('127.0.0.1', 5062)]... [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:319 disconnect: TcpClientFactory [('127.0.0.1', 5062)]: Attempting to destroy client connection... [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:118 disconnect: TcpClient [127.0.0.1:5062]: Disconnecting the transport... [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:291 clientConnectionLost: TcpClientFactory [('127.0.0.1', 5062)]: Connection has been lost. Reason: Connection was closed cleanly. [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:569 __on_client_disconnect: TcpClientScenario [felonius-gru]: Client [('127.0.0.1', 5062)] is disconnected. [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:445 __disconnect_client: TcpClientScenario [felonius-gru]: Disconnecting client [('127.0.0.1', 5063)]... [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:319 disconnect: TcpClientFactory [('127.0.0.1', 5063)]: Attempting to destroy client connection... [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:118 disconnect: TcpClient [127.0.0.1:5063]: Disconnecting the transport... [Sep 28 11:13:30] INFO[7691]: twisted:154 publishToNewObserver: Stopping factory [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:291 clientConnectionLost: TcpClientFactory [('127.0.0.1', 5063)]: Connection has been lost. Reason: Connection was closed cleanly. [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:569 __on_client_disconnect: TcpClientScenario [felonius-gru]: Client [('127.0.0.1', 5063)] is disconnected. [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:445 __disconnect_client: TcpClientScenario [felonius-gru]: Disconnecting client [('127.0.0.1', 5064)]... [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:319 disconnect: TcpClientFactory [('127.0.0.1', 5064)]: Attempting to destroy client connection... [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:118 disconnect: TcpClient [127.0.0.1:5064]: Disconnecting the transport... [Sep 28 11:13:30] INFO[7691]: twisted:154 publishToNewObserver: Stopping factory [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:291 clientConnectionLost: TcpClientFactory [('127.0.0.1', 5064)]: Connection has been lost. Reason: Connection was closed cleanly. [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:569 __on_client_disconnect: TcpClientScenario [felonius-gru]: Client [('127.0.0.1', 5064)] is disconnected. [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:445 __disconnect_client: TcpClientScenario [felonius-gru]: Disconnecting client [('127.0.0.1', 5065)]... [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:319 disconnect: TcpClientFactory [('127.0.0.1', 5065)]: Attempting to destroy client connection... [Sep 28 11:13:30] INFO[7691]: twisted:154 publishToNewObserver: Stopping factory [Sep 28 11:13:30] DEBUG[7691]: AMI:160 lineReceived: Line In: 'Event: FullyBooted' [Sep 28 11:13:30] DEBUG[7691]: AMI:160 lineReceived: Line In: 'Privilege: system,all' [Sep 28 11:13:30] DEBUG[7691]: AMI:160 lineReceived: Line In: 'Status: Fully Booted' [Sep 28 11:13:30] DEBUG[7691]: AMI:160 lineReceived: Line In: '' [Sep 28 11:13:30] DEBUG[7691]: AMI:221 dispatchIncoming: Dispatch Incoming [Sep 28 11:13:30] DEBUG[7691]: AMI:248 dispatchIncoming: Incoming Message: {'privilege': 'system,all', 'status': 'Fully Booted', 'event': 'FullyBooted'} [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:291 clientConnectionLost: TcpClientFactory [('127.0.0.1', 5065)]: Connection has been lost. Reason: Connection was closed cleanly. [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:569 __on_client_disconnect: TcpClientScenario [felonius-gru]: Client [('127.0.0.1', 5065)] is disconnected. [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:445 __disconnect_client: TcpClientScenario [felonius-gru]: Disconnecting client [('127.0.0.1', 5066)]... [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:319 disconnect: TcpClientFactory [('127.0.0.1', 5066)]: Attempting to destroy client connection... [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:118 disconnect: TcpClient [127.0.0.1:5066]: Disconnecting the transport... [Sep 28 11:13:30] INFO[7691]: twisted:154 publishToNewObserver: Stopping factory [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:291 clientConnectionLost: TcpClientFactory [('127.0.0.1', 5066)]: Connection has been lost. Reason: Connection was closed cleanly. [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:569 __on_client_disconnect: TcpClientScenario [felonius-gru]: Client [('127.0.0.1', 5066)] is disconnected. [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:445 __disconnect_client: TcpClientScenario [felonius-gru]: Disconnecting client [('127.0.0.1', 5067)]... [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:319 disconnect: TcpClientFactory [('127.0.0.1', 5067)]: Attempting to destroy client connection... [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:118 disconnect: TcpClient [127.0.0.1:5067]: Disconnecting the transport... [Sep 28 11:13:30] INFO[7691]: twisted:154 publishToNewObserver: Stopping factory [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:291 clientConnectionLost: TcpClientFactory [('127.0.0.1', 5067)]: Connection has been lost. Reason: Connection was closed cleanly. [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:569 __on_client_disconnect: TcpClientScenario [felonius-gru]: Client [('127.0.0.1', 5067)] is disconnected. [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:445 __disconnect_client: TcpClientScenario [felonius-gru]: Disconnecting client [('127.0.0.1', 5068)]... [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:319 disconnect: TcpClientFactory [('127.0.0.1', 5068)]: Attempting to destroy client connection... [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:118 disconnect: TcpClient [127.0.0.1:5068]: Disconnecting the transport... [Sep 28 11:13:30] INFO[7691]: twisted:154 publishToNewObserver: Stopping factory [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:291 clientConnectionLost: TcpClientFactory [('127.0.0.1', 5068)]: Connection has been lost. Reason: Connection was closed cleanly. [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:569 __on_client_disconnect: TcpClientScenario [felonius-gru]: Client [('127.0.0.1', 5068)] is disconnected. [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:445 __disconnect_client: TcpClientScenario [felonius-gru]: Disconnecting client [('127.0.0.1', 5069)]... [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:319 disconnect: TcpClientFactory [('127.0.0.1', 5069)]: Attempting to destroy client connection... [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:118 disconnect: TcpClient [127.0.0.1:5069]: Disconnecting the transport... [Sep 28 11:13:30] INFO[7691]: twisted:154 publishToNewObserver: Stopping factory [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:291 clientConnectionLost: TcpClientFactory [('127.0.0.1', 5069)]: Connection has been lost. Reason: Connection was closed cleanly. [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:569 __on_client_disconnect: TcpClientScenario [felonius-gru]: Client [('127.0.0.1', 5069)] is disconnected. [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:445 __disconnect_client: TcpClientScenario [felonius-gru]: Disconnecting client [('127.0.0.1', 5070)]... [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:319 disconnect: TcpClientFactory [('127.0.0.1', 5070)]: Attempting to destroy client connection... [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:118 disconnect: TcpClient [127.0.0.1:5070]: Disconnecting the transport... [Sep 28 11:13:30] INFO[7691]: twisted:154 publishToNewObserver: Stopping factory [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:291 clientConnectionLost: TcpClientFactory [('127.0.0.1', 5070)]: Connection has been lost. Reason: Connection was closed cleanly. [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:569 __on_client_disconnect: TcpClientScenario [felonius-gru]: Client [('127.0.0.1', 5070)] is disconnected. [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:445 __disconnect_client: TcpClientScenario [felonius-gru]: Disconnecting client [('127.0.0.1', 5071)]... [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:319 disconnect: TcpClientFactory [('127.0.0.1', 5071)]: Attempting to destroy client connection... [Sep 28 11:13:30] INFO[7691]: twisted:154 publishToNewObserver: Stopping factory [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:291 clientConnectionLost: TcpClientFactory [('127.0.0.1', 5071)]: Connection has been lost. Reason: Connection was closed cleanly. [Sep 28 11:13:30] DEBUG[7691]: tcp_scenario:569 __on_client_disconnect: TcpClientScenario [felonius-gru]: Client [('127.0.0.1', 5071)] is disconnected. [Sep 28 11:13:30] ERROR[7691]: tcp_scenario:595 __report_results: TcpClientScenario [felonius-gru]: Scenario failed. Based on the test configuration, I expected to receive: 5 client connections. Here is what I actually received: 2 client connections. [Sep 28 11:13:30] DEBUG[7691]: tcpauthlimit:257 __tear_down_test: TcpAuthLimitTestModule: Stopping reactor. [Sep 28 11:13:30] INFO[7691]: test_case:411 __stop_instances: Stopping Asterisk instance 1 [Sep 28 11:13:30] DEBUG[7691]: asterisk:418 __send_stop_gracefully: sending stop gracefully [Sep 28 11:13:30] DEBUG[7691]: asterisk:700 cli_exec: Executing ['/usr/sbin/asterisk', '-C', '/tmp/asterisk-testsuite/c7eaf18a4896145a44d3b287d6e4c1ca/run_1/ast1/etc/asterisk/asterisk.conf', '-rx', 'core stop gracefully'] ... [Sep 28 11:13:30] INFO[7691]: twisted:154 publishToNewObserver: Stopping factory [Sep 28 11:13:30] DEBUG[7691]: AMI:160 lineReceived: Line In: 'Event: Shutdown' [Sep 28 11:13:30] DEBUG[7691]: AMI:160 lineReceived: Line In: 'Privilege: system,all' [Sep 28 11:13:30] DEBUG[7691]: AMI:160 lineReceived: Line In: 'Shutdown: Cleanly' [Sep 28 11:13:30] DEBUG[7691]: AMI:160 lineReceived: Line In: 'Restart: False' [Sep 28 11:13:30] DEBUG[7691]: AMI:160 lineReceived: Line In: '' [Sep 28 11:13:30] DEBUG[7691]: AMI:221 dispatchIncoming: Dispatch Incoming [Sep 28 11:13:30] DEBUG[7691]: AMI:248 dispatchIncoming: Incoming Message: {'privilege': 'system,all', 'restart': 'False', 'event': 'Shutdown', 'shutdown': 'Cleanly'} [Sep 28 11:13:30] INFO[7691]: twisted:154 publishToNewObserver: Stopping factory [Sep 28 11:13:31] DEBUG[7691]: tcpauthlimit:207 __evaluate_test_results: TcpAuthLimitTestModule: Evaluating test results... [Sep 28 11:13:31] DEBUG[7691]: tcpauthlimit:151 __evaluate_scenario_results: TcpAuthLimitTestModule: Evaluating SIPp scenario results... [Sep 28 11:13:31] DEBUG[7691]: tcpauthlimit:155 __evaluate_scenario_results: TcpAuthLimitTestModule: No SIPp scenario results to evaluate. [Sep 28 11:13:31] DEBUG[7691]: tcpauthlimit:151 __evaluate_scenario_results: TcpAuthLimitTestModule: Evaluating TCP client scenario results... [Sep 28 11:13:31] DEBUG[7691]: tcpauthlimit:187 __evaluate_scenario_results: TcpAuthLimitTestModule: TCP client scenario 'felonius-gru' failed. [Sep 28 11:13:31] ERROR[7691]: tcpauthlimit:191 __evaluate_scenario_results: TcpAuthLimitTestModule: One or more TCP client scenarios failed. [Sep 28 11:13:31] ERROR[7691]: tcpauthlimit:244 __on_asterisk_stop: TcpAuthLimitTestModule: Test failed. [Sep 28 11:13:31] INFO[7691]: test_case:432 __stop_reactor: Stopping Reactor [Sep 28 11:13:31] INFO[7691]: twisted:154 publishToNewObserver: Main loop terminated. [Sep 28 11:13:31] INFO[7691]: test_runner:326 main: Test run for tests/channels/SIP/tcpauthlimit/tcp_client_scenario completed with result False