[Jul 16 23:25:55] INFO[19504]: test_case:158 __init__: Executing tests/channels/pjsip/subscriptions/rls/lists/nominal/presence/batched/basic [Jul 16 23:25:55] DEBUG[19504]: test_conditions:143 register_observer: Registering: [Jul 16 23:25:55] DEBUG[19504]: test_conditions:143 register_observer: Registering: [Jul 16 23:25:55] DEBUG[19504]: test_conditions:143 register_observer: Registering: > [Jul 16 23:25:55] INFO[19504]: test_case:233 create_asterisk: Creating Asterisk instance 1 [Jul 16 23:25:55] DEBUG[19504]: test_runner:171 load_and_parse_module: Importing rls_test.IntegrityCheck [Jul 16 23:25:55] DEBUG[19504]: test_runner:42 __init__: TestModuleFinder supports path tests/channels/pjsip/subscriptions/rls/lists/nominal/presence/batched/basic [Jul 16 23:25:55] DEBUG[19504]: test_runner:58 find_module: Unable to find module 'generatedssuper' [Jul 16 23:25:55] DEBUG[19504]: test_runner:42 __init__: TestModuleFinder supports path tests/channels/pjsip/subscriptions/rls [Jul 16 23:25:55] DEBUG[19504]: test_runner:58 find_module: Unable to find module 'generatedssuper' [Jul 16 23:25:55] DEBUG[19504]: test_runner:58 find_module: Unable to find module 'generatedssuper' [Jul 16 23:25:56] DEBUG[19504]: test_runner:171 load_and_parse_module: Importing driver.TestDriver [Jul 16 23:25:56] INFO[19504]: test_case:368 _start_asterisk: Starting Asterisk instance 1 [Jul 16 23:25:56] DEBUG[19504]: asterisk:123 connectionMade: Asterisk 127.0.0.1 - connection made [Jul 16 23:25:56] WARNING[19504]: asterisk:127 errReceived: Asterisk 127.0.0.1 received error: FD 32766 exceeds the maximum size of ast_fdset! [Jul 16 23:25:57] DEBUG[19504]: asterisk:700 cli_exec: Executing ['/usr/sbin/asterisk', '-C', '/tmp/asterisk-testsuite/de342f7f9d82f5836dffb5cc2fb86638/run_1/ast1/etc/asterisk/asterisk.conf', '-rx', 'core waitfullybooted'] ... [Jul 16 23:26:00] DEBUG[19504]: asterisk:64 __cli_output_callback: Asterisk CLI 127.0.0.1 exited 0 [Jul 16 23:26:00] DEBUG[19504]: asterisk:66 __cli_output_callback: FD 32766 exceeds the maximum size of ast_fdset! [Jul 16 23:26:00] INFO[19504]: test_case:265 create_ami_factory: Creating AMIFactory 1 [Jul 16 23:26:00] INFO[19504]: twisted:455 emit: Starting factory [Jul 16 23:26:00] DEBUG[19504]: asterisk:700 cli_exec: Executing ['/usr/sbin/asterisk', '-C', '/tmp/asterisk-testsuite/de342f7f9d82f5836dffb5cc2fb86638/run_1/ast1/etc/asterisk/asterisk.conf', '-rx', 'sip set debug on'] ... [Jul 16 23:26:00] DEBUG[19504]: asterisk:700 cli_exec: Executing ['/usr/sbin/asterisk', '-C', '/tmp/asterisk-testsuite/de342f7f9d82f5836dffb5cc2fb86638/run_1/ast1/etc/asterisk/asterisk.conf', '-rx', 'pjsip set logger on'] ... [Jul 16 23:26:00] INFO[19504]: AMI:173 connectionMade: Connection Made [Jul 16 23:26:00] DEBUG[19504]: AMI:343 sendMessage: MSG OUT: {'action': 'login', 'username': 'user', 'secret': 'mysecret', 'actionid': 'asterisk-testsuite-64-centos-2.digium.internal-40160360-1'} [Jul 16 23:26:00] DEBUG[19504]: AMI:160 lineReceived: Line In: 'Asterisk Call Manager/2.8.0' [Jul 16 23:26:00] DEBUG[19504]: AMI:160 lineReceived: Line In: 'Response: Success' [Jul 16 23:26:00] DEBUG[19504]: AMI:160 lineReceived: Line In: 'ActionID: asterisk-testsuite-64-centos-2.digium.internal-40160360-1' [Jul 16 23:26:00] DEBUG[19504]: AMI:160 lineReceived: Line In: 'Message: Authentication accepted' [Jul 16 23:26:00] DEBUG[19504]: AMI:160 lineReceived: Line In: '' [Jul 16 23:26:00] DEBUG[19504]: AMI:221 dispatchIncoming: Dispatch Incoming [Jul 16 23:26:00] DEBUG[19504]: AMI:248 dispatchIncoming: Incoming Message: {'message': 'Authentication accepted', 'response': 'Success', 'actionid': 'asterisk-testsuite-64-centos-2.digium.internal-40160360-1'} [Jul 16 23:26:00] INFO[19504]: AMI:191 onComplete: Login Complete: {'message': 'Authentication accepted', 'response': 'Success', 'actionid': 'asterisk-testsuite-64-centos-2.digium.internal-40160360-1'} [Jul 16 23:26:00] INFO[19504]: test_case:502 _ami_connect: AMI Connect instance 1 [Jul 16 23:26:00] DEBUG[19504]: AMI:120 registerEvent: Registering function > to handle events of type 'TestEvent' [Jul 16 23:26:00] INFO[19504]: sipp:633 run: Executing SIPp scenario: subscribe.xml [Jul 16 23:26:00] DEBUG[19504]: sipp:634 run: ['/usr/bin/sipp', '127.0.0.1', '-sf', 'tests/channels/pjsip/subscriptions/rls/lists/nominal/presence/batched/basic/sipp/subscribe.xml', '-nostdin', '-skip_rlimit', '-timeout', '20s', '-m', '1', '-i', '127.0.0.1', '-p', '5061', '-s', 'pres_list'] [Jul 16 23:26:00] DEBUG[19504]: sipp:463 connectionMade: Connection made to SIPp scenario subscribe.xml [Jul 16 23:26:00] DEBUG[19504]: AMI:160 lineReceived: Line In: 'Event: FullyBooted' [Jul 16 23:26:00] DEBUG[19504]: AMI:160 lineReceived: Line In: 'Privilege: system,all' [Jul 16 23:26:00] DEBUG[19504]: AMI:160 lineReceived: Line In: 'Status: Fully Booted' [Jul 16 23:26:00] DEBUG[19504]: AMI:160 lineReceived: Line In: '' [Jul 16 23:26:00] DEBUG[19504]: AMI:221 dispatchIncoming: Dispatch Incoming [Jul 16 23:26:00] DEBUG[19504]: AMI:248 dispatchIncoming: Incoming Message: {'privilege': 'system,all', 'status': 'Fully Booted', 'event': 'FullyBooted'} [Jul 16 23:26:00] DEBUG[19504]: asterisk:64 __cli_output_callback: Asterisk CLI 127.0.0.1 exited 0 [Jul 16 23:26:00] DEBUG[19504]: asterisk:66 __cli_output_callback: FD 32766 exceeds the maximum size of ast_fdset! [Jul 16 23:26:00] DEBUG[19504]: asterisk:64 __cli_output_callback: Asterisk CLI 127.0.0.1 exited 0 [Jul 16 23:26:00] DEBUG[19504]: asterisk:66 __cli_output_callback: FD 32766 exceeds the maximum size of ast_fdset! [Jul 16 23:26:00] DEBUG[19504]: sipp:458 outReceived: Received from SIPp scenario subscribe.xml: (B)0[1;24r[m[?7h[2J[2J ------------------------------ Scenario Screen -------- [1-9]: Change Screen -- Call-rate(length) Port Total-time Total-calls Remote-host 10.0(0 ms)/1.000s 5061 0.00 s 0 127.0.0.1:5060(UDP) 0 new calls during 0.000 s period 0 ms scheduler resolution 0 calls (limit 30) Peak was 0 calls, after 0 s 0 Running, 0 Paused, 0 Woken up 0 dead call msg (discarded) 0 out-of-call msg (discarded) 2 open sockets Messages Retrans Timeout Unexpected-Msg SUBSCRIBE ----------> 0 0 0 100 <---------- 0 0 0 0 200 <---------- E-RTD1 0 0 0 0 NOTIFY <---------- 0 0 0 0 200 ----------> 0 0 NOTIFY <---------- 0 0 0 0 200 ----------> 0 0 SUBSCRIBE ----------> 0 0 0 NOTIFY <---------- 0 0 0 0 200 <---------- 0 0 0 0 200 ----------> 0 0 NOTIFY <---------- 0 0 0 0 200 ----------> 0 0 SUBSCRIBE ----------> 0 0 0 NOTIFY <---------- 0 0 0 0 200 <---------- 0 0 0 0 200 ----------> 0 0 ------ [+|-|*|/]: Adjust rate ---- [q]: Soft exit ---- [p]: Pause traffic ----- [Jul 16 23:26:00] DEBUG[19504]: pcap:75 __pcap_callback: [Jul 16 23:26:00] DEBUG[19504]: pcap:559 pcap_callback: Got packet from 127.0.0.1 [Jul 16 23:26:00] DEBUG[19504]: rls_test:83 multipart_handler: Received SIP packet [Jul 16 23:26:00] DEBUG[19504]: rls_test:86 multipart_handler: Ignoring packet, is not a NOTIFY [Jul 16 23:26:00] DEBUG[19504]: pcap:75 __pcap_callback: [Jul 16 23:26:00] DEBUG[19504]: pcap:559 pcap_callback: Got packet from 127.0.0.1 [Jul 16 23:26:00] DEBUG[19504]: rls_test:83 multipart_handler: Received SIP packet [Jul 16 23:26:00] DEBUG[19504]: rls_test:86 multipart_handler: Ignoring packet, is not a NOTIFY [Jul 16 23:26:00] DEBUG[19504]: pcap:75 __pcap_callback: [Jul 16 23:26:00] DEBUG[19504]: pcap:559 pcap_callback: Got packet from 127.0.0.1 [Jul 16 23:26:00] DEBUG[19504]: rls_test:83 multipart_handler: Received SIP packet [Jul 16 23:26:00] DEBUG[19504]: rls_test:107 multipart_handler: validating packet -- expecting {'bob': {'state': 'active', 'type': 'PIDF'}, 'alice': {'state': 'active', 'type': 'PIDF'}} [Jul 16 23:26:00] INFO[19504]: rls_test:113 multipart_handler: Packet validated successfully. Test Phase 0 Completed. [Jul 16 23:26:00] DEBUG[19504]: pcap:75 __pcap_callback: [Jul 16 23:26:00] DEBUG[19504]: pcap:559 pcap_callback: Got packet from 127.0.0.1 [Jul 16 23:26:00] DEBUG[19504]: rls_test:83 multipart_handler: Received SIP packet [Jul 16 23:26:00] DEBUG[19504]: rls_test:86 multipart_handler: Ignoring packet, is not a NOTIFY [Jul 16 23:26:00] DEBUG[19504]: AMI:160 lineReceived: Line In: 'Event: TestEvent' [Jul 16 23:26:00] DEBUG[19504]: AMI:160 lineReceived: Line In: 'Privilege: reporting,all' [Jul 16 23:26:00] DEBUG[19504]: AMI:160 lineReceived: Line In: 'Type: StateChange' [Jul 16 23:26:00] DEBUG[19504]: AMI:160 lineReceived: Line In: 'State: SUBSCRIPTION_STATE_SET' [Jul 16 23:26:00] DEBUG[19504]: AMI:160 lineReceived: Line In: 'AppFile: res_pjsip_pubsub.c' [Jul 16 23:26:00] DEBUG[19504]: AMI:160 lineReceived: Line In: 'AppFunction: sip_subscription_send_request' [Jul 16 23:26:00] DEBUG[19504]: AMI:160 lineReceived: Line In: 'AppLine: 1650' [Jul 16 23:26:00] DEBUG[19504]: AMI:160 lineReceived: Line In: 'StateText: ACTIVE' [Jul 16 23:26:00] DEBUG[19504]: AMI:160 lineReceived: Line In: 'Endpoint: sipp' [Jul 16 23:26:00] DEBUG[19504]: AMI:160 lineReceived: Line In: '' [Jul 16 23:26:00] DEBUG[19504]: AMI:221 dispatchIncoming: Dispatch Incoming [Jul 16 23:26:00] DEBUG[19504]: AMI:248 dispatchIncoming: Incoming Message: {'appfile': 'res_pjsip_pubsub.c', 'endpoint': 'sipp', 'appline': '1650', 'appfunction': 'sip_subscription_send_request', 'state': 'SUBSCRIPTION_STATE_SET', 'statetext': 'ACTIVE', 'privilege': 'reporting,all', 'type': 'StateChange', 'event': 'TestEvent'} [Jul 16 23:26:00] DEBUG[19504]: AMI:160 lineReceived: Line In: '' [Jul 16 23:26:00] DEBUG[19504]: AMI:221 dispatchIncoming: Dispatch Incoming [Jul 16 23:26:00] DEBUG[19504]: AMI:248 dispatchIncoming: Incoming Message: {} [Jul 16 23:26:00] DEBUG[19504]: AMI:160 lineReceived: Line In: 'Event: TestEvent' [Jul 16 23:26:00] DEBUG[19504]: AMI:160 lineReceived: Line In: 'Privilege: reporting,all' [Jul 16 23:26:00] DEBUG[19504]: AMI:160 lineReceived: Line In: 'Type: StateChange' [Jul 16 23:26:00] DEBUG[19504]: AMI:160 lineReceived: Line In: 'State: SUBSCRIPTION_ESTABLISHED' [Jul 16 23:26:00] DEBUG[19504]: AMI:160 lineReceived: Line In: 'AppFile: res_pjsip_pubsub.c' [Jul 16 23:26:00] DEBUG[19504]: AMI:160 lineReceived: Line In: 'AppFunction: pubsub_on_rx_subscribe_request' [Jul 16 23:26:00] DEBUG[19504]: AMI:160 lineReceived: Line In: 'AppLine: 2618' [Jul 16 23:26:00] DEBUG[19504]: AMI:160 lineReceived: Line In: 'Resource: pres_list' [Jul 16 23:26:00] DEBUG[19504]: AMI:160 lineReceived: Line In: '' [Jul 16 23:26:00] DEBUG[19504]: AMI:221 dispatchIncoming: Dispatch Incoming [Jul 16 23:26:00] DEBUG[19504]: AMI:248 dispatchIncoming: Incoming Message: {'appfile': 'res_pjsip_pubsub.c', 'resource': 'pres_list', 'appline': '2618', 'appfunction': 'pubsub_on_rx_subscribe_request', 'state': 'SUBSCRIPTION_ESTABLISHED', 'privilege': 'reporting,all', 'type': 'StateChange', 'event': 'TestEvent'} [Jul 16 23:26:00] DEBUG[19504]: driver:66 on_subscription_established: State change to 2 [Jul 16 23:26:00] DEBUG[19504]: AMI:343 sendMessage: MSG OUT: {'action': 'SetVar', 'variable': 'DEVICE_STATE(Custom:alice)', 'actionid': 'asterisk-testsuite-64-centos-2.digium.internal-40160360-2', 'value': 'InUse'} [Jul 16 23:26:00] DEBUG[19504]: AMI:160 lineReceived: Line In: 'Response: Success' [Jul 16 23:26:00] DEBUG[19504]: AMI:160 lineReceived: Line In: 'ActionID: asterisk-testsuite-64-centos-2.digium.internal-40160360-2' [Jul 16 23:26:00] DEBUG[19504]: AMI:160 lineReceived: Line In: 'Message: Variable Set' [Jul 16 23:26:00] DEBUG[19504]: AMI:160 lineReceived: Line In: '' [Jul 16 23:26:00] DEBUG[19504]: AMI:221 dispatchIncoming: Dispatch Incoming [Jul 16 23:26:00] DEBUG[19504]: AMI:248 dispatchIncoming: Incoming Message: {'message': 'Variable Set', 'response': 'Success', 'actionid': 'asterisk-testsuite-64-centos-2.digium.internal-40160360-2'} [Jul 16 23:26:00] DEBUG[19504]: AMI:160 lineReceived: Line In: 'Event: DeviceStateChange' [Jul 16 23:26:00] DEBUG[19504]: AMI:160 lineReceived: Line In: 'Privilege: call,all' [Jul 16 23:26:00] DEBUG[19504]: AMI:160 lineReceived: Line In: 'Device: Custom:alice' [Jul 16 23:26:00] DEBUG[19504]: AMI:160 lineReceived: Line In: 'State: INUSE' [Jul 16 23:26:00] DEBUG[19504]: AMI:160 lineReceived: Line In: '' [Jul 16 23:26:00] DEBUG[19504]: AMI:221 dispatchIncoming: Dispatch Incoming [Jul 16 23:26:00] DEBUG[19504]: AMI:248 dispatchIncoming: Incoming Message: {'privilege': 'call,all', 'device': 'Custom:alice', 'state': 'INUSE', 'event': 'DeviceStateChange'} [Jul 16 23:26:00] DEBUG[19504]: AMI:160 lineReceived: Line In: 'Event: ExtensionStatus' [Jul 16 23:26:00] DEBUG[19504]: AMI:160 lineReceived: Line In: 'Privilege: call,all' [Jul 16 23:26:00] DEBUG[19504]: AMI:160 lineReceived: Line In: 'Exten: alice' [Jul 16 23:26:00] DEBUG[19504]: AMI:160 lineReceived: Line In: 'Context: default' [Jul 16 23:26:00] DEBUG[19504]: AMI:160 lineReceived: Line In: 'Hint: Custom:alice' [Jul 16 23:26:00] DEBUG[19504]: AMI:160 lineReceived: Line In: 'Status: 1' [Jul 16 23:26:00] DEBUG[19504]: AMI:160 lineReceived: Line In: 'StatusText: InUse' [Jul 16 23:26:00] DEBUG[19504]: AMI:160 lineReceived: Line In: '' [Jul 16 23:26:00] DEBUG[19504]: AMI:221 dispatchIncoming: Dispatch Incoming [Jul 16 23:26:00] DEBUG[19504]: AMI:248 dispatchIncoming: Incoming Message: {'status': '1', 'hint': 'Custom:alice', 'exten': 'alice', 'context': 'default', 'statustext': 'InUse', 'privilege': 'call,all', 'event': 'ExtensionStatus'} [Jul 16 23:26:01] DEBUG[19504]: sipp:458 outReceived: Received from SIPp scenario subscribe.xml: [2J------------------------------ Scenario Screen -------- [1-9]: Change Screen -- Call-rate(length) Port Total-time Total-calls Remote-host 10.0(0 ms)/1.000s 5061 1.00 s 1 127.0.0.1:5060(UDP) Call limit reached (-m 1), 1.002 s period 1 ms scheduler resolution 1 calls (limit 30) Peak was 1 calls, after 0 s 0 Running, 2 Paused, 5 Woken up 0 dead call msg (discarded) 0 out-of-call msg (discarded) 2 open sockets Messages Retrans Timeout Unexpected-Msg SUBSCRIBE ----------> 1 0 0 100 <---------- 0 0 0 0 200 <---------- E-RTD1 1 0 0 0 NOTIFY <---------- 1 0 0 0 200 ----------> 1 0 NOTIFY <---------- 0 0 0 0 200 ----------> 0 0 SUBSCRIBE ----------> 0 0 0 NOTIFY <---------- 0 0 0 0 200 <---------- 0 0 0 0 200 ----------> 0 0 NOTIFY <---------- 0 0 0 0 200 ----------> 0 0 SUBSCRIBE ----------> 0 0 0 NOTIFY <---------- 0 0 0 0 200 <---------- 0 0 0 0 200 ----------> 0 0 ------- Waiting for active calls to end. Press [q] again to force exit. ------- [Jul 16 23:26:02] DEBUG[19504]: sipp:458 outReceived: Received from SIPp scenario subscribe.xml: [2J------------------------------ Scenario Screen -------- [1-9]: Change Screen -- Call-rate(length) Port Total-time Total-calls Remote-host 10.0(0 ms)/1.000s 5061 2.00 s 1 127.0.0.1:5060(UDP) Call limit reached (-m 1), 1.002 s period 1 ms scheduler resolution 1 calls (limit 30) Peak was 1 calls, after 0 s 0 Running, 2 Paused, 3 Woken up 0 dead call msg (discarded) 0 out-of-call msg (discarded) 2 open sockets Messages Retrans Timeout Unexpected-Msg SUBSCRIBE ----------> 1 0 0 100 <---------- 0 0 0 0 200 <---------- E-RTD1 1 0 0 0 NOTIFY <---------- 1 0 0 0 200 ----------> 1 0 NOTIFY <---------- 0 0 0 0 200 ----------> 0 0 SUBSCRIBE ----------> 0 0 0 NOTIFY <---------- 0 0 0 0 200 <---------- 0 0 0 0 200 ----------> 0 0 NOTIFY <---------- 0 0 0 0 200 ----------> 0 0 SUBSCRIBE ----------> 0 0 0 NOTIFY <---------- 0 0 0 0 200 <---------- 0 0 0 0 200 ----------> 0 0 ------- Waiting for active calls to end. Press [q] again to force exit. ------- [Jul 16 23:26:03] DEBUG[19504]: sipp:458 outReceived: Received from SIPp scenario subscribe.xml: [2J------------------------------ Scenario Screen -------- [1-9]: Change Screen -- Call-rate(length) Port Total-time Total-calls Remote-host 10.0(0 ms)/1.000s 5061 3.00 s 1 127.0.0.1:5060(UDP) Call limit reached (-m 1), 1.002 s period 1 ms scheduler resolution 1 calls (limit 30) Peak was 1 calls, after 0 s 0 Running, 2 Paused, 4 Woken up 0 dead call msg (discarded) 0 out-of-call msg (discarded) 2 open sockets Messages Retrans Timeout Unexpected-Msg SUBSCRIBE ----------> 1 0 0 100 <---------- 0 0 0 0 200 <---------- E-RTD1 1 0 0 0 NOTIFY <---------- 1 0 0 0 200 ----------> 1 0 NOTIFY <---------- 0 0 0 0 200 ----------> 0 0 SUBSCRIBE ----------> 0 0 0 NOTIFY <---------- 0 0 0 0 200 <---------- 0 0 0 0 200 ----------> 0 0 NOTIFY <---------- 0 0 0 0 200 ----------> 0 0 SUBSCRIBE ----------> 0 0 0 NOTIFY <---------- 0 0 0 0 200 <---------- 0 0 0 0 200 ----------> 0 0 ------- Waiting for active calls to end. Press [q] again to force exit. ------- [Jul 16 23:26:04] DEBUG[19504]: sipp:458 outReceived: Received from SIPp scenario subscribe.xml: [2J------------------------------ Scenario Screen -------- [1-9]: Change Screen -- Call-rate(length) Port Total-time Total-calls Remote-host 10.0(0 ms)/1.000s 5061 4.00 s 1 127.0.0.1:5060(UDP) Call limit reached (-m 1), 1.003 s period 1 ms scheduler resolution 1 calls (limit 30) Peak was 1 calls, after 0 s 0 Running, 2 Paused, 3 Woken up 0 dead call msg (discarded) 0 out-of-call msg (discarded) 2 open sockets Messages Retrans Timeout Unexpected-Msg SUBSCRIBE ----------> 1 0 0 100 <---------- 0 0 0 0 200 <---------- E-RTD1 1 0 0 0 NOTIFY <---------- 1 0 0 0 200 ----------> 1 0 NOTIFY <---------- 0 0 0 0 200 ----------> 0 0 SUBSCRIBE ----------> 0 0 0 NOTIFY <---------- 0 0 0 0 200 <---------- 0 0 0 0 200 ----------> 0 0 NOTIFY <---------- 0 0 0 0 200 ----------> 0 0 SUBSCRIBE ----------> 0 0 0 NOTIFY <---------- 0 0 0 0 200 <---------- 0 0 0 0 200 ----------> 0 0 ------- Waiting for active calls to end. Press [q] again to force exit. ------- [Jul 16 23:26:05] DEBUG[19504]: sipp:458 outReceived: Received from SIPp scenario subscribe.xml: [2J------------------------------ Scenario Screen -------- [1-9]: Change Screen -- Call-rate(length) Port Total-time Total-calls Remote-host 10.0(0 ms)/1.000s 5061 5.01 s 1 127.0.0.1:5060(UDP) Call limit reached (-m 1), 1.001 s period 1 ms scheduler resolution 1 calls (limit 30) Peak was 1 calls, after 0 s 0 Running, 2 Paused, 4 Woken up 0 dead call msg (discarded) 0 out-of-call msg (discarded) 2 open sockets Messages Retrans Timeout Unexpected-Msg SUBSCRIBE ----------> 1 0 0 100 <---------- 0 0 0 0 200 <---------- E-RTD1 1 0 0 0 NOTIFY <---------- 1 0 0 0 200 ----------> 1 0 NOTIFY <---------- 0 0 0 0 200 ----------> 0 0 SUBSCRIBE ----------> 0 0 0 NOTIFY <---------- 0 0 0 0 200 <---------- 0 0 0 0 200 ----------> 0 0 NOTIFY <---------- 0 0 0 0 200 ----------> 0 0 SUBSCRIBE ----------> 0 0 0 NOTIFY <---------- 0 0 0 0 200 <---------- 0 0 0 0 200 ----------> 0 0 ------- Waiting for active calls to end. Press [q] again to force exit. ------- [Jul 16 23:26:05] DEBUG[19504]: pcap:75 __pcap_callback: [Jul 16 23:26:05] DEBUG[19504]: pcap:559 pcap_callback: Got packet from 127.0.0.1 [Jul 16 23:26:05] DEBUG[19504]: rls_test:83 multipart_handler: Received SIP packet [Jul 16 23:26:05] DEBUG[19504]: rls_test:107 multipart_handler: validating packet -- expecting {'alice': {'state': 'active', 'type': 'PIDF'}} [Jul 16 23:26:05] INFO[19504]: rls_test:113 multipart_handler: Packet validated successfully. Test Phase 1 Completed. [Jul 16 23:26:05] DEBUG[19504]: pcap:75 __pcap_callback: [Jul 16 23:26:05] DEBUG[19504]: pcap:559 pcap_callback: Got packet from 127.0.0.1 [Jul 16 23:26:05] DEBUG[19504]: rls_test:83 multipart_handler: Received SIP packet [Jul 16 23:26:05] DEBUG[19504]: rls_test:86 multipart_handler: Ignoring packet, is not a NOTIFY [Jul 16 23:26:05] DEBUG[19504]: AMI:160 lineReceived: Line In: 'Event: TestEvent' [Jul 16 23:26:05] DEBUG[19504]: AMI:160 lineReceived: Line In: 'Privilege: reporting,all' [Jul 16 23:26:05] DEBUG[19504]: AMI:160 lineReceived: Line In: 'Type: StateChange' [Jul 16 23:26:05] DEBUG[19504]: AMI:160 lineReceived: Line In: 'State: SUBSCRIPTION_STATE_SET' [Jul 16 23:26:05] DEBUG[19504]: AMI:160 lineReceived: Line In: 'AppFile: res_pjsip_pubsub.c' [Jul 16 23:26:05] DEBUG[19504]: AMI:160 lineReceived: Line In: 'AppFunction: sip_subscription_send_request' [Jul 16 23:26:05] DEBUG[19504]: AMI:160 lineReceived: Line In: 'AppLine: 1650' [Jul 16 23:26:05] DEBUG[19504]: AMI:160 lineReceived: Line In: 'StateText: ACTIVE' [Jul 16 23:26:05] DEBUG[19504]: AMI:160 lineReceived: Line In: 'Endpoint: sipp' [Jul 16 23:26:05] DEBUG[19504]: AMI:160 lineReceived: Line In: '' [Jul 16 23:26:05] DEBUG[19504]: AMI:221 dispatchIncoming: Dispatch Incoming [Jul 16 23:26:05] DEBUG[19504]: AMI:248 dispatchIncoming: Incoming Message: {'appfile': 'res_pjsip_pubsub.c', 'endpoint': 'sipp', 'appline': '1650', 'appfunction': 'sip_subscription_send_request', 'state': 'SUBSCRIPTION_STATE_SET', 'statetext': 'ACTIVE', 'privilege': 'reporting,all', 'type': 'StateChange', 'event': 'TestEvent'} [Jul 16 23:26:05] DEBUG[19504]: AMI:160 lineReceived: Line In: '' [Jul 16 23:26:05] DEBUG[19504]: AMI:221 dispatchIncoming: Dispatch Incoming [Jul 16 23:26:05] DEBUG[19504]: AMI:248 dispatchIncoming: Incoming Message: {} [Jul 16 23:26:05] DEBUG[19504]: AMI:160 lineReceived: Line In: 'Event: TestEvent' [Jul 16 23:26:05] DEBUG[19504]: AMI:160 lineReceived: Line In: 'Privilege: reporting,all' [Jul 16 23:26:05] DEBUG[19504]: AMI:160 lineReceived: Line In: 'Type: StateChange' [Jul 16 23:26:05] DEBUG[19504]: AMI:160 lineReceived: Line In: 'State: SUBSCRIPTION_STATE_CHANGED' [Jul 16 23:26:05] DEBUG[19504]: AMI:160 lineReceived: Line In: 'AppFile: res_pjsip_pubsub.c' [Jul 16 23:26:05] DEBUG[19504]: AMI:160 lineReceived: Line In: 'AppFunction: serialized_send_notify' [Jul 16 23:26:05] DEBUG[19504]: AMI:160 lineReceived: Line In: 'AppLine: 2115' [Jul 16 23:26:05] DEBUG[19504]: AMI:160 lineReceived: Line In: 'Resource: pres_list' [Jul 16 23:26:05] DEBUG[19504]: AMI:160 lineReceived: Line In: '' [Jul 16 23:26:05] DEBUG[19504]: AMI:221 dispatchIncoming: Dispatch Incoming [Jul 16 23:26:05] DEBUG[19504]: AMI:248 dispatchIncoming: Incoming Message: {'appfile': 'res_pjsip_pubsub.c', 'resource': 'pres_list', 'appline': '2115', 'appfunction': 'serialized_send_notify', 'state': 'SUBSCRIPTION_STATE_CHANGED', 'privilege': 'reporting,all', 'type': 'StateChange', 'event': 'TestEvent'} [Jul 16 23:26:05] DEBUG[19504]: driver:88 on_subscription_state_change: State change to 3 [Jul 16 23:26:05] DEBUG[19504]: pcap:75 __pcap_callback: [Jul 16 23:26:05] DEBUG[19504]: pcap:559 pcap_callback: Got packet from 127.0.0.1 [Jul 16 23:26:05] DEBUG[19504]: rls_test:83 multipart_handler: Received SIP packet [Jul 16 23:26:05] DEBUG[19504]: rls_test:86 multipart_handler: Ignoring packet, is not a NOTIFY [Jul 16 23:26:05] DEBUG[19504]: AMI:160 lineReceived: Line In: 'Event: TestEvent' [Jul 16 23:26:05] DEBUG[19504]: AMI:160 lineReceived: Line In: 'Privilege: reporting,all' [Jul 16 23:26:05] DEBUG[19504]: AMI:160 lineReceived: Line In: 'Type: StateChange' [Jul 16 23:26:05] DEBUG[19504]: AMI:160 lineReceived: Line In: 'State: SUBSCRIPTION_STATE_SET' [Jul 16 23:26:05] DEBUG[19504]: AMI:160 lineReceived: Line In: 'AppFile: res_pjsip_pubsub.c' [Jul 16 23:26:05] DEBUG[19504]: AMI:160 lineReceived: Line In: 'AppFunction: sip_subscription_send_request' [Jul 16 23:26:05] DEBUG[19504]: AMI:160 lineReceived: Line In: 'AppLine: 1650' [Jul 16 23:26:05] DEBUG[19504]: AMI:160 lineReceived: Line In: 'StateText: ACTIVE' [Jul 16 23:26:05] DEBUG[19504]: AMI:160 lineReceived: Line In: 'Endpoint: sipp' [Jul 16 23:26:05] DEBUG[19504]: AMI:160 lineReceived: Line In: '' [Jul 16 23:26:05] DEBUG[19504]: AMI:221 dispatchIncoming: Dispatch Incoming [Jul 16 23:26:05] DEBUG[19504]: AMI:248 dispatchIncoming: Incoming Message: {'appfile': 'res_pjsip_pubsub.c', 'endpoint': 'sipp', 'appline': '1650', 'appfunction': 'sip_subscription_send_request', 'state': 'SUBSCRIPTION_STATE_SET', 'statetext': 'ACTIVE', 'privilege': 'reporting,all', 'type': 'StateChange', 'event': 'TestEvent'} [Jul 16 23:26:05] DEBUG[19504]: AMI:160 lineReceived: Line In: '' [Jul 16 23:26:05] DEBUG[19504]: AMI:221 dispatchIncoming: Dispatch Incoming [Jul 16 23:26:05] DEBUG[19504]: AMI:248 dispatchIncoming: Incoming Message: {} [Jul 16 23:26:05] DEBUG[19504]: AMI:160 lineReceived: Line In: 'Event: TestEvent' [Jul 16 23:26:05] DEBUG[19504]: AMI:160 lineReceived: Line In: 'Privilege: reporting,all' [Jul 16 23:26:05] DEBUG[19504]: AMI:160 lineReceived: Line In: 'Type: StateChange' [Jul 16 23:26:05] DEBUG[19504]: AMI:160 lineReceived: Line In: 'State: SUBSCRIPTION_REFRESHED' [Jul 16 23:26:05] DEBUG[19504]: AMI:160 lineReceived: Line In: 'AppFile: res_pjsip_pubsub.c' [Jul 16 23:26:05] DEBUG[19504]: AMI:160 lineReceived: Line In: 'AppFunction: pubsub_on_rx_refresh' [Jul 16 23:26:05] DEBUG[19504]: AMI:160 lineReceived: Line In: 'AppLine: 3165' [Jul 16 23:26:05] DEBUG[19504]: AMI:160 lineReceived: Line In: 'Resource: pres_list' [Jul 16 23:26:05] DEBUG[19504]: AMI:160 lineReceived: Line In: '' [Jul 16 23:26:05] DEBUG[19504]: AMI:221 dispatchIncoming: Dispatch Incoming [Jul 16 23:26:05] DEBUG[19504]: AMI:248 dispatchIncoming: Incoming Message: {'appfile': 'res_pjsip_pubsub.c', 'resource': 'pres_list', 'appline': '3165', 'appfunction': 'pubsub_on_rx_refresh', 'state': 'SUBSCRIPTION_REFRESHED', 'privilege': 'reporting,all', 'type': 'StateChange', 'event': 'TestEvent'} [Jul 16 23:26:05] DEBUG[19504]: driver:104 on_subscription_refreshed: State change to 4 [Jul 16 23:26:05] DEBUG[19504]: AMI:343 sendMessage: MSG OUT: {'action': 'SetVar', 'variable': 'DEVICE_STATE(Custom:bob)', 'actionid': 'asterisk-testsuite-64-centos-2.digium.internal-40160360-3', 'value': 'InUse'} [Jul 16 23:26:05] DEBUG[19504]: pcap:75 __pcap_callback: [Jul 16 23:26:05] DEBUG[19504]: pcap:559 pcap_callback: Got packet from 127.0.0.1 [Jul 16 23:26:05] DEBUG[19504]: rls_test:83 multipart_handler: Received SIP packet [Jul 16 23:26:05] DEBUG[19504]: rls_test:86 multipart_handler: Ignoring packet, is not a NOTIFY [Jul 16 23:26:05] DEBUG[19504]: pcap:75 __pcap_callback: [Jul 16 23:26:05] DEBUG[19504]: pcap:559 pcap_callback: Got packet from 127.0.0.1 [Jul 16 23:26:05] DEBUG[19504]: rls_test:83 multipart_handler: Received SIP packet [Jul 16 23:26:05] DEBUG[19504]: rls_test:86 multipart_handler: Ignoring packet, is not a NOTIFY [Jul 16 23:26:05] DEBUG[19504]: AMI:160 lineReceived: Line In: 'Response: Success' [Jul 16 23:26:05] DEBUG[19504]: AMI:160 lineReceived: Line In: 'ActionID: asterisk-testsuite-64-centos-2.digium.internal-40160360-3' [Jul 16 23:26:05] DEBUG[19504]: AMI:160 lineReceived: Line In: 'Message: Variable Set' [Jul 16 23:26:05] DEBUG[19504]: AMI:160 lineReceived: Line In: '' [Jul 16 23:26:05] DEBUG[19504]: AMI:221 dispatchIncoming: Dispatch Incoming [Jul 16 23:26:05] DEBUG[19504]: AMI:248 dispatchIncoming: Incoming Message: {'message': 'Variable Set', 'response': 'Success', 'actionid': 'asterisk-testsuite-64-centos-2.digium.internal-40160360-3'} [Jul 16 23:26:05] DEBUG[19504]: AMI:160 lineReceived: Line In: 'Event: DeviceStateChange' [Jul 16 23:26:05] DEBUG[19504]: AMI:160 lineReceived: Line In: 'Privilege: call,all' [Jul 16 23:26:05] DEBUG[19504]: AMI:160 lineReceived: Line In: 'Device: Custom:bob' [Jul 16 23:26:05] DEBUG[19504]: AMI:160 lineReceived: Line In: 'State: INUSE' [Jul 16 23:26:05] DEBUG[19504]: AMI:160 lineReceived: Line In: '' [Jul 16 23:26:05] DEBUG[19504]: AMI:221 dispatchIncoming: Dispatch Incoming [Jul 16 23:26:05] DEBUG[19504]: AMI:248 dispatchIncoming: Incoming Message: {'privilege': 'call,all', 'device': 'Custom:bob', 'state': 'INUSE', 'event': 'DeviceStateChange'} [Jul 16 23:26:05] DEBUG[19504]: AMI:160 lineReceived: Line In: 'Event: ExtensionStatus' [Jul 16 23:26:05] DEBUG[19504]: AMI:160 lineReceived: Line In: 'Privilege: call,all' [Jul 16 23:26:05] DEBUG[19504]: AMI:160 lineReceived: Line In: 'Exten: bob' [Jul 16 23:26:05] DEBUG[19504]: AMI:160 lineReceived: Line In: 'Context: default' [Jul 16 23:26:05] DEBUG[19504]: AMI:160 lineReceived: Line In: 'Hint: Custom:bob' [Jul 16 23:26:05] DEBUG[19504]: AMI:160 lineReceived: Line In: 'Status: 1' [Jul 16 23:26:05] DEBUG[19504]: AMI:160 lineReceived: Line In: 'StatusText: InUse' [Jul 16 23:26:05] DEBUG[19504]: AMI:160 lineReceived: Line In: '' [Jul 16 23:26:05] DEBUG[19504]: AMI:221 dispatchIncoming: Dispatch Incoming [Jul 16 23:26:05] DEBUG[19504]: AMI:248 dispatchIncoming: Incoming Message: {'status': '1', 'hint': 'Custom:bob', 'exten': 'bob', 'context': 'default', 'statustext': 'InUse', 'privilege': 'call,all', 'event': 'ExtensionStatus'} [Jul 16 23:26:06] DEBUG[19504]: sipp:458 outReceived: Received from SIPp scenario subscribe.xml: [2J------------------------------ Scenario Screen -------- [1-9]: Change Screen -- Call-rate(length) Port Total-time Total-calls Remote-host 10.0(0 ms)/1.000s 5061 6.01 s 1 127.0.0.1:5060(UDP) Call limit reached (-m 1), 1.001 s period 1 ms scheduler resolution 1 calls (limit 30) Peak was 1 calls, after 0 s 0 Running, 2 Paused, 3 Woken up 0 dead call msg (discarded) 0 out-of-call msg (discarded) 2 open sockets Messages Retrans Timeout Unexpected-Msg SUBSCRIBE ----------> 1 0 0 100 <---------- 0 0 0 0 200 <---------- E-RTD1 1 0 0 0 NOTIFY <---------- 1 0 0 0 200 ----------> 1 0 NOTIFY <---------- 1 0 0 0 200 ----------> 1 0 SUBSCRIBE ----------> 1 0 0 NOTIFY <---------- 1 0 0 0 200 <---------- 1 0 0 0 200 ----------> 1 0 NOTIFY <---------- 0 0 0 0 200 ----------> 0 0 SUBSCRIBE ----------> 0 0 0 NOTIFY <---------- 0 0 0 0 200 <---------- 0 0 0 0 200 ----------> 0 0 ------- Waiting for active calls to end. Press [q] again to force exit. ------- [Jul 16 23:26:07] DEBUG[19504]: sipp:458 outReceived: Received from SIPp scenario subscribe.xml: [2J------------------------------ Scenario Screen -------- [1-9]: Change Screen -- Call-rate(length) Port Total-time Total-calls Remote-host 10.0(0 ms)/1.000s 5061 7.01 s 1 127.0.0.1:5060(UDP) Call limit reached (-m 1), 1.001 s period 1 ms scheduler resolution 1 calls (limit 30) Peak was 1 calls, after 0 s 0 Running, 2 Paused, 4 Woken up 0 dead call msg (discarded) 0 out-of-call msg (discarded) 2 open sockets Messages Retrans Timeout Unexpected-Msg SUBSCRIBE ----------> 1 0 0 100 <---------- 0 0 0 0 200 <---------- E-RTD1 1 0 0 0 NOTIFY <---------- 1 0 0 0 200 ----------> 1 0 NOTIFY <---------- 1 0 0 0 200 ----------> 1 0 SUBSCRIBE ----------> 1 0 0 NOTIFY <---------- 1 0 0 0 200 <---------- 1 0 0 0 200 ----------> 1 0 NOTIFY <---------- 0 0 0 0 200 ----------> 0 0 SUBSCRIBE ----------> 0 0 0 NOTIFY <---------- 0 0 0 0 200 <---------- 0 0 0 0 200 ----------> 0 0 ------- Waiting for active calls to end. Press [q] again to force exit. ------- [Jul 16 23:26:08] DEBUG[19504]: sipp:458 outReceived: Received from SIPp scenario subscribe.xml: [2J------------------------------ Scenario Screen -------- [1-9]: Change Screen -- Call-rate(length) Port Total-time Total-calls Remote-host 10.0(0 ms)/1.000s 5061 8.01 s 1 127.0.0.1:5060(UDP) Call limit reached (-m 1), 1.002 s period 1 ms scheduler resolution 1 calls (limit 30) Peak was 1 calls, after 0 s 0 Running, 2 Paused, 3 Woken up 0 dead call msg (discarded) 0 out-of-call msg (discarded) 2 open sockets Messages Retrans Timeout Unexpected-Msg SUBSCRIBE ----------> 1 0 0 100 <---------- 0 0 0 0 200 <---------- E-RTD1 1 0 0 0 NOTIFY <---------- 1 0 0 0 200 ----------> 1 0 NOTIFY <---------- 1 0 0 0 200 ----------> 1 0 SUBSCRIBE ----------> 1 0 0 NOTIFY <---------- 1 0 0 0 200 <---------- 1 0 0 0 200 ----------> 1 0 NOTIFY <---------- 0 0 0 0 200 ----------> 0 0 SUBSCRIBE ----------> 0 0 0 NOTIFY <---------- 0 0 0 0 200 <---------- 0 0 0 0 200 ----------> 0 0 ------- Waiting for active calls to end. Press [q] again to force exit. ------- [Jul 16 23:26:09] DEBUG[19504]: sipp:458 outReceived: Received from SIPp scenario subscribe.xml: [2J------------------------------ Scenario Screen -------- [1-9]: Change Screen -- Call-rate(length) Port Total-time Total-calls Remote-host 10.0(0 ms)/1.000s 5061 9.01 s 1 127.0.0.1:5060(UDP) Call limit reached (-m 1), 1.002 s period 1 ms scheduler resolution 1 calls (limit 30) Peak was 1 calls, after 0 s 0 Running, 2 Paused, 4 Woken up 0 dead call msg (discarded) 0 out-of-call msg (discarded) 2 open sockets Messages Retrans Timeout Unexpected-Msg SUBSCRIBE ----------> 1 0 0 100 <---------- 0 0 0 0 200 <---------- E-RTD1 1 0 0 0 NOTIFY <---------- 1 0 0 0 200 ----------> 1 0 NOTIFY <---------- 1 0 0 0 200 ----------> 1 0 SUBSCRIBE ----------> 1 0 0 NOTIFY <---------- 1 0 0 0 200 <---------- 1 0 0 0 200 ----------> 1 0 NOTIFY <---------- 0 0 0 0 200 ----------> 0 0 SUBSCRIBE ----------> 0 0 0 NOTIFY <---------- 0 0 0 0 200 <---------- 0 0 0 0 200 ----------> 0 0 ------- Waiting for active calls to end. Press [q] again to force exit. ------- [Jul 16 23:26:10] DEBUG[19504]: sipp:458 outReceived: Received from SIPp scenario subscribe.xml: [2J------------------------------ Scenario Screen -------- [1-9]: Change Screen -- Call-rate(length) Port Total-time Total-calls Remote-host 10.0(0 ms)/1.000s 5061 10.01 s 1 127.0.0.1:5060(UDP) Call limit reached (-m 1), 1.001 s period 1 ms scheduler resolution 1 calls (limit 30) Peak was 1 calls, after 0 s 0 Running, 2 Paused, 3 Woken up 0 dead call msg (discarded) 0 out-of-call msg (discarded) 2 open sockets Messages Retrans Timeout Unexpected-Msg SUBSCRIBE ----------> 1 0 0 100 <---------- 0 0 0 0 200 <---------- E-RTD1 1 0 0 0 NOTIFY <---------- 1 0 0 0 200 ----------> 1 0 NOTIFY <---------- 1 0 0 0 200 ----------> 1 0 SUBSCRIBE ----------> 1 0 0 NOTIFY <---------- 1 0 0 0 200 <---------- 1 0 0 0 200 ----------> 1 0 NOTIFY <---------- 0 0 0 0 200 ----------> 0 0 SUBSCRIBE ----------> 0 0 0 NOTIFY <---------- 0 0 0 0 200 <---------- 0 0 0 0 200 ----------> 0 0 ------- Waiting for active calls to end. Press [q] again to force exit. ------- [Jul 16 23:26:10] DEBUG[19504]: pcap:75 __pcap_callback: [Jul 16 23:26:10] DEBUG[19504]: pcap:559 pcap_callback: Got packet from 127.0.0.1 [Jul 16 23:26:10] DEBUG[19504]: rls_test:83 multipart_handler: Received SIP packet [Jul 16 23:26:10] DEBUG[19504]: rls_test:107 multipart_handler: validating packet -- expecting {'bob': {'state': 'active', 'type': 'PIDF'}, 'alice': {'state': 'active', 'type': 'PIDF'}} [Jul 16 23:26:10] ERROR[19504]: rls_integrity:378 fail_test: Unexpected number of parts (2) in multipart body [Jul 16 23:26:10] INFO[19504]: sipp:127 stop_asterisk: Forcibly killing subscribe.xml [Jul 16 23:26:10] WARNING[19504]: sipp:450 kill: Killing SIPp Scenario subscribe.xml [Jul 16 23:26:10] INFO[19504]: test_case:411 __stop_instances: Stopping Asterisk instance 1 [Jul 16 23:26:10] DEBUG[19504]: asterisk:418 __send_stop_gracefully: sending stop gracefully [Jul 16 23:26:10] DEBUG[19504]: asterisk:700 cli_exec: Executing ['/usr/sbin/asterisk', '-C', '/tmp/asterisk-testsuite/de342f7f9d82f5836dffb5cc2fb86638/run_1/ast1/etc/asterisk/asterisk.conf', '-rx', 'core stop gracefully'] ... [Jul 16 23:26:10] ERROR[19504]: rls_test:109 multipart_handler: Integrity Check Failed. [Jul 16 23:26:10] DEBUG[19504]: pcap:75 __pcap_callback: [Jul 16 23:26:10] DEBUG[19504]: pcap:559 pcap_callback: Got packet from 127.0.0.1 [Jul 16 23:26:10] DEBUG[19504]: rls_test:83 multipart_handler: Received SIP packet [Jul 16 23:26:10] DEBUG[19504]: rls_test:86 multipart_handler: Ignoring packet, is not a NOTIFY [Jul 16 23:26:10] DEBUG[19504]: AMI:160 lineReceived: Line In: 'Event: TestEvent' [Jul 16 23:26:10] DEBUG[19504]: AMI:160 lineReceived: Line In: 'Privilege: reporting,all' [Jul 16 23:26:10] DEBUG[19504]: AMI:160 lineReceived: Line In: 'Type: StateChange' [Jul 16 23:26:10] DEBUG[19504]: AMI:160 lineReceived: Line In: 'State: SUBSCRIPTION_STATE_SET' [Jul 16 23:26:10] DEBUG[19504]: AMI:160 lineReceived: Line In: 'AppFile: res_pjsip_pubsub.c' [Jul 16 23:26:10] DEBUG[19504]: AMI:160 lineReceived: Line In: 'AppFunction: sip_subscription_send_request' [Jul 16 23:26:10] DEBUG[19504]: AMI:160 lineReceived: Line In: 'AppLine: 1650' [Jul 16 23:26:10] DEBUG[19504]: AMI:160 lineReceived: Line In: 'StateText: ACTIVE' [Jul 16 23:26:10] DEBUG[19504]: AMI:160 lineReceived: Line In: 'Endpoint: sipp' [Jul 16 23:26:10] DEBUG[19504]: AMI:160 lineReceived: Line In: '' [Jul 16 23:26:10] DEBUG[19504]: AMI:221 dispatchIncoming: Dispatch Incoming [Jul 16 23:26:10] DEBUG[19504]: AMI:248 dispatchIncoming: Incoming Message: {'appfile': 'res_pjsip_pubsub.c', 'endpoint': 'sipp', 'appline': '1650', 'appfunction': 'sip_subscription_send_request', 'state': 'SUBSCRIPTION_STATE_SET', 'statetext': 'ACTIVE', 'privilege': 'reporting,all', 'type': 'StateChange', 'event': 'TestEvent'} [Jul 16 23:26:10] DEBUG[19504]: AMI:160 lineReceived: Line In: '' [Jul 16 23:26:10] DEBUG[19504]: AMI:221 dispatchIncoming: Dispatch Incoming [Jul 16 23:26:10] DEBUG[19504]: AMI:248 dispatchIncoming: Incoming Message: {} [Jul 16 23:26:10] DEBUG[19504]: AMI:160 lineReceived: Line In: 'Event: TestEvent' [Jul 16 23:26:10] DEBUG[19504]: AMI:160 lineReceived: Line In: 'Privilege: reporting,all' [Jul 16 23:26:10] DEBUG[19504]: AMI:160 lineReceived: Line In: 'Type: StateChange' [Jul 16 23:26:10] DEBUG[19504]: AMI:160 lineReceived: Line In: 'State: SUBSCRIPTION_STATE_CHANGED' [Jul 16 23:26:10] DEBUG[19504]: AMI:160 lineReceived: Line In: 'AppFile: res_pjsip_pubsub.c' [Jul 16 23:26:10] DEBUG[19504]: AMI:160 lineReceived: Line In: 'AppFunction: serialized_send_notify' [Jul 16 23:26:10] DEBUG[19504]: AMI:160 lineReceived: Line In: 'AppLine: 2115' [Jul 16 23:26:10] DEBUG[19504]: AMI:160 lineReceived: Line In: 'Resource: pres_list' [Jul 16 23:26:10] DEBUG[19504]: AMI:160 lineReceived: Line In: '' [Jul 16 23:26:10] DEBUG[19504]: AMI:221 dispatchIncoming: Dispatch Incoming [Jul 16 23:26:10] DEBUG[19504]: AMI:248 dispatchIncoming: Incoming Message: {'appfile': 'res_pjsip_pubsub.c', 'resource': 'pres_list', 'appline': '2115', 'appfunction': 'serialized_send_notify', 'state': 'SUBSCRIPTION_STATE_CHANGED', 'privilege': 'reporting,all', 'type': 'StateChange', 'event': 'TestEvent'} [Jul 16 23:26:10] DEBUG[19504]: driver:95 on_subscription_state_change: State change to 5 [Jul 16 23:26:10] INFO[19504]: sipp:584 __scenario_callback: SIPp Scenario subscribe.xml Exited [Jul 16 23:26:10] INFO[19504]: sipp:180 _handle_scenario_finished: Scenario subscribe.xml passed [Jul 16 23:26:10] INFO[19504]: sipp:199 _finish_test: All SIPp Scenarios executed; stopping reactor [Jul 16 23:26:10] INFO[19504]: sipp:493 processEnded: SIPp scenario subscribe.xml ended [Jul 16 23:26:10] DEBUG[19504]: pcap:75 __pcap_callback: [Jul 16 23:26:10] DEBUG[19504]: pcap:559 pcap_callback: Got packet from 127.0.0.1 [Jul 16 23:26:10] DEBUG[19504]: rls_test:83 multipart_handler: Received SIP packet [Jul 16 23:26:10] DEBUG[19504]: rls_test:86 multipart_handler: Ignoring packet, is not a NOTIFY [Jul 16 23:26:11] DEBUG[19504]: AMI:160 lineReceived: Line In: 'Event: TestEvent' [Jul 16 23:26:11] DEBUG[19504]: AMI:160 lineReceived: Line In: 'Privilege: reporting,all' [Jul 16 23:26:11] DEBUG[19504]: AMI:160 lineReceived: Line In: 'Type: StateChange' [Jul 16 23:26:11] DEBUG[19504]: AMI:160 lineReceived: Line In: 'State: SUBSCRIPTION_STATE_SET' [Jul 16 23:26:11] DEBUG[19504]: AMI:160 lineReceived: Line In: 'AppFile: res_pjsip_pubsub.c' [Jul 16 23:26:11] DEBUG[19504]: AMI:160 lineReceived: Line In: 'AppFunction: sip_subscription_send_request' [Jul 16 23:26:11] DEBUG[19504]: AMI:160 lineReceived: Line In: 'AppLine: 1650' [Jul 16 23:26:11] DEBUG[19504]: AMI:160 lineReceived: Line In: 'StateText: TERMINATED' [Jul 16 23:26:11] DEBUG[19504]: AMI:160 lineReceived: Line In: 'Endpoint: sipp' [Jul 16 23:26:11] DEBUG[19504]: AMI:160 lineReceived: Line In: '' [Jul 16 23:26:11] DEBUG[19504]: AMI:221 dispatchIncoming: Dispatch Incoming [Jul 16 23:26:11] DEBUG[19504]: AMI:248 dispatchIncoming: Incoming Message: {'appfile': 'res_pjsip_pubsub.c', 'endpoint': 'sipp', 'appline': '1650', 'appfunction': 'sip_subscription_send_request', 'state': 'SUBSCRIPTION_STATE_SET', 'statetext': 'TERMINATED', 'privilege': 'reporting,all', 'type': 'StateChange', 'event': 'TestEvent'} [Jul 16 23:26:11] DEBUG[19504]: AMI:160 lineReceived: Line In: '' [Jul 16 23:26:11] DEBUG[19504]: AMI:221 dispatchIncoming: Dispatch Incoming [Jul 16 23:26:11] DEBUG[19504]: AMI:248 dispatchIncoming: Incoming Message: {} [Jul 16 23:26:11] DEBUG[19504]: AMI:160 lineReceived: Line In: 'Event: TestEvent' [Jul 16 23:26:11] DEBUG[19504]: AMI:160 lineReceived: Line In: 'Privilege: reporting,all' [Jul 16 23:26:11] DEBUG[19504]: AMI:160 lineReceived: Line In: 'Type: StateChange' [Jul 16 23:26:11] DEBUG[19504]: AMI:160 lineReceived: Line In: 'State: SUBSCRIPTION_TERMINATED' [Jul 16 23:26:11] DEBUG[19504]: AMI:160 lineReceived: Line In: 'AppFile: res_pjsip_pubsub.c' [Jul 16 23:26:11] DEBUG[19504]: AMI:160 lineReceived: Line In: 'AppFunction: pubsub_on_rx_refresh' [Jul 16 23:26:11] DEBUG[19504]: AMI:160 lineReceived: Line In: 'AppLine: 3165' [Jul 16 23:26:11] DEBUG[19504]: AMI:160 lineReceived: Line In: 'Resource: pres_list' [Jul 16 23:26:11] DEBUG[19504]: AMI:160 lineReceived: Line In: '' [Jul 16 23:26:11] DEBUG[19504]: AMI:221 dispatchIncoming: Dispatch Incoming [Jul 16 23:26:11] DEBUG[19504]: AMI:248 dispatchIncoming: Incoming Message: {'appfile': 'res_pjsip_pubsub.c', 'resource': 'pres_list', 'appline': '3165', 'appfunction': 'pubsub_on_rx_refresh', 'state': 'SUBSCRIPTION_TERMINATED', 'privilege': 'reporting,all', 'type': 'StateChange', 'event': 'TestEvent'} [Jul 16 23:26:11] DEBUG[19504]: driver:120 on_subscription_terminated: State change to 6 [Jul 16 23:26:11] DEBUG[19504]: pcap:75 __pcap_callback: [Jul 16 23:26:11] DEBUG[19504]: pcap:559 pcap_callback: Got packet from 127.0.0.1 [Jul 16 23:26:11] DEBUG[19504]: rls_test:83 multipart_handler: Received SIP packet [Jul 16 23:26:11] DEBUG[19504]: rls_test:86 multipart_handler: Ignoring packet, is not a NOTIFY [Jul 16 23:26:11] DEBUG[19504]: AMI:160 lineReceived: Line In: 'Event: Shutdown' [Jul 16 23:26:11] DEBUG[19504]: AMI:160 lineReceived: Line In: 'Privilege: system,all' [Jul 16 23:26:11] DEBUG[19504]: AMI:160 lineReceived: Line In: 'Restart: False' [Jul 16 23:26:11] DEBUG[19504]: AMI:160 lineReceived: Line In: 'Shutdown: Cleanly' [Jul 16 23:26:11] DEBUG[19504]: AMI:160 lineReceived: Line In: '' [Jul 16 23:26:11] DEBUG[19504]: AMI:221 dispatchIncoming: Dispatch Incoming [Jul 16 23:26:11] DEBUG[19504]: AMI:248 dispatchIncoming: Incoming Message: {'privilege': 'system,all', 'shutdown': 'Cleanly', 'event': 'Shutdown', 'restart': 'False'} [Jul 16 23:26:11] INFO[19504]: twisted:455 emit: Stopping factory [Jul 16 23:26:12] INFO[19504]: test_case:432 __stop_reactor: Stopping Reactor [Jul 16 23:26:12] INFO[19504]: twisted:455 emit: Main loop terminated. [Jul 16 23:26:12] INFO[19504]: test_runner:326 main: Test run for tests/channels/pjsip/subscriptions/rls/lists/nominal/presence/batched/basic completed with result False [Jul 16 23:26:12] ERROR[19504]: test_case:567 evaluate_results: Fail token present: Haven't handled all expected NOTIFY packets.