[Mar 29 20:16:09] INFO[3499]: asterisk.test_case:175 __init__: Executing tests/channels/pjsip/subscriptions/rls/lists/nominal/mwi/batched/multiple_resources_single_change [Mar 29 20:16:09] DEBUG[3499]: asterisk.test_conditions:143 register_observer: Registering: [Mar 29 20:16:09] DEBUG[3499]: asterisk.test_conditions:143 register_observer: Registering: [Mar 29 20:16:09] DEBUG[3499]: asterisk.test_conditions:143 register_observer: Registering: > [Mar 29 20:16:09] INFO[3499]: asterisk.test_case:286 create_asterisk: Creating Asterisk instance 1 [Mar 29 20:16:10] DEBUG[3499]: test_runner:141 load_and_parse_module: Importing rls_test.RLSTest [Mar 29 20:16:10] DEBUG[3499]: test_runner:59 find_module: Unable to find module 'pathlib' [Mar 29 20:16:10] DEBUG[3499]: test_runner:59 find_module: Unable to find module 'pathlib' [Mar 29 20:16:10] DEBUG[3499]: test_runner:59 find_module: Unable to find module 'pathlib' [Mar 29 20:16:10] DEBUG[3499]: test_runner:59 find_module: Unable to find module 'ruamel' [Mar 29 20:16:10] DEBUG[3499]: test_runner:59 find_module: Unable to find module 'ruamel' [Mar 29 20:16:10] DEBUG[3499]: test_runner:59 find_module: Unable to find module 'ruamel' [Mar 29 20:16:10] DEBUG[3499]: test_runner:59 find_module: Unable to find module 'generatedssuper' [Mar 29 20:16:10] DEBUG[3499]: test_runner:59 find_module: Unable to find module 'generatedssuper' [Mar 29 20:16:10] DEBUG[3499]: test_runner:59 find_module: Unable to find module 'generatedssuper' [Mar 29 20:16:10] DEBUG[3499]: test_runner:59 find_module: Unable to find module '_xmlplus' [Mar 29 20:16:10] DEBUG[3499]: test_runner:59 find_module: Unable to find module '_xmlplus' [Mar 29 20:16:10] DEBUG[3499]: test_runner:59 find_module: Unable to find module '_xmlplus' [Mar 29 20:16:10] DEBUG[3499]: test_runner:59 find_module: Unable to find module 'ElementC14N' [Mar 29 20:16:10] DEBUG[3499]: test_runner:59 find_module: Unable to find module 'ElementC14N' [Mar 29 20:16:10] DEBUG[3499]: test_runner:59 find_module: Unable to find module 'ElementC14N' [Mar 29 20:16:10] INFO[3499]: twisted:154 publishToNewObserver: ProxyProtocol starting on 5061 [Mar 29 20:16:10] INFO[3499]: twisted:154 publishToNewObserver: Starting protocol [Mar 29 20:16:10] DEBUG[3499]: test_runner:141 load_and_parse_module: Importing driver.TestDriver [Mar 29 20:16:10] INFO[3499]: asterisk.test_case:465 _start_asterisk: Starting Asterisk instance 1 [Mar 29 20:16:10] DEBUG[3499]: asterisk.asterisk:242 connectionMade: Asterisk 127.0.0.1 - connection made [Mar 29 20:16:11] DEBUG[3499]: asterisk.asterisk:938 cli_exec: Executing ['/sbin/asterisk', '-C', '/var/tmp/asterisk-testsuite/352d5d666bcec9f8b254e36c5dfb177c/run_1/ast1/etc/asterisk/asterisk.conf', '-rx', 'core waitfullybooted'] ... [Mar 29 20:16:12] DEBUG[3499]: asterisk.asterisk:182 __cli_output_callback: Asterisk CLI 127.0.0.1 exited 0 [Mar 29 20:16:12] DEBUG[3499]: asterisk.asterisk:938 cli_exec: Executing ['/sbin/asterisk', '-C', '/var/tmp/asterisk-testsuite/352d5d666bcec9f8b254e36c5dfb177c/run_1/ast1/etc/asterisk/asterisk.conf', '-rx', 'sip set debug on'] ... [Mar 29 20:16:12] DEBUG[3499]: asterisk.asterisk:938 cli_exec: Executing ['/sbin/asterisk', '-C', '/var/tmp/asterisk-testsuite/352d5d666bcec9f8b254e36c5dfb177c/run_1/ast1/etc/asterisk/asterisk.conf', '-rx', 'pjsip set logger on'] ... [Mar 29 20:16:12] INFO[3499]: asterisk.test_case:350 create_ami_factory: Creating AMIFactory 1 to 127.0.0.1 [Mar 29 20:16:12] INFO[3499]: twisted:154 publishToNewObserver: Starting factory [Mar 29 20:16:12] INFO[3499]: AMI:184 connectionMade: Connection Made [Mar 29 20:16:12] DEBUG[3499]: AMI:361 sendMessage: MSG OUT: {'action': 'login', 'username': 'user', 'secret': 'mysecret', 'actionid': 'ff3bb070a8b4-140033481909600-1'} [Mar 29 20:16:12] DEBUG[3499]: AMI:171 lineReceived: Line In: 'Asterisk Call Manager/9.0.0' [Mar 29 20:16:12] DEBUG[3499]: asterisk.asterisk:182 __cli_output_callback: Asterisk CLI 127.0.0.1 exited 0 [Mar 29 20:16:12] DEBUG[3499]: AMI:171 lineReceived: Line In: 'Response: Success' [Mar 29 20:16:12] DEBUG[3499]: AMI:171 lineReceived: Line In: 'ActionID: ff3bb070a8b4-140033481909600-1' [Mar 29 20:16:12] DEBUG[3499]: AMI:171 lineReceived: Line In: 'Message: Authentication accepted' [Mar 29 20:16:12] DEBUG[3499]: AMI:171 lineReceived: Line In: '' [Mar 29 20:16:12] DEBUG[3499]: AMI:233 dispatchIncoming: Dispatch Incoming [Mar 29 20:16:12] DEBUG[3499]: AMI:263 dispatchIncoming: Incoming Message: {u'message': u'Authentication accepted', u'response': u'Success', u'actionid': u'ff3bb070a8b4-140033481909600-1'} [Mar 29 20:16:12] INFO[3499]: AMI:203 onComplete: Login Complete: {u'message': u'Authentication accepted', u'response': u'Success', u'actionid': u'ff3bb070a8b4-140033481909600-1'} [Mar 29 20:16:12] INFO[3499]: asterisk.test_case:603 _ami_connect: AMI Connect instance 1 [Mar 29 20:16:12] DEBUG[3499]: AMI:131 registerEvent: Registering function > to handle events of type 'TestEvent' [Mar 29 20:16:12] DEBUG[3499]: asterisk.utils_socket:199 get_avail: Checking the following UDP/IPv4 ports for availability: [0] [Mar 29 20:16:12] DEBUG[3499]: asterisk.utils_socket:199 get_avail: Checking the following UDP/IPv4 ports for availability: [45624, 45625, 45626] [Mar 29 20:16:12] INFO[3499]: asterisk.sipp:705 run: Executing SIPp scenario: subscribe.xml [Mar 29 20:16:12] DEBUG[3499]: asterisk.sipp:706 run: ['/bin/sipp', '127.0.0.1:5061', '-sf', 'tests/channels/pjsip/subscriptions/rls/lists/nominal/mwi/batched/multiple_resources_single_change/sipp/subscribe.xml', '-nostdin', '-skip_rlimit', '-timeout', '20s', '-m', '1', '-i', '127.0.0.1', '-mp', '45623', '-p', '5062', '-s', 'mail_list', '-nr'] [Mar 29 20:16:12] DEBUG[3499]: asterisk.sipp:505 connectionMade: Connection made to SIPp scenario subscribe.xml [Mar 29 20:16:12] DEBUG[3499]: AMI:171 lineReceived: Line In: 'Event: FullyBooted' [Mar 29 20:16:12] DEBUG[3499]: AMI:171 lineReceived: Line In: 'Privilege: system,all' [Mar 29 20:16:12] DEBUG[3499]: AMI:171 lineReceived: Line In: 'Uptime: 2' [Mar 29 20:16:12] DEBUG[3499]: AMI:171 lineReceived: Line In: 'LastReload: 2' [Mar 29 20:16:12] DEBUG[3499]: AMI:171 lineReceived: Line In: 'Status: Fully Booted' [Mar 29 20:16:12] DEBUG[3499]: AMI:171 lineReceived: Line In: '' [Mar 29 20:16:12] DEBUG[3499]: AMI:233 dispatchIncoming: Dispatch Incoming [Mar 29 20:16:12] DEBUG[3499]: AMI:263 dispatchIncoming: Incoming Message: {u'privilege': u'system,all', u'status': u'Fully Booted', u'uptime': u'2', u'event': u'FullyBooted', u'lastreload': u'2'} [Mar 29 20:16:12] DEBUG[3499]: asterisk.asterisk:182 __cli_output_callback: Asterisk CLI 127.0.0.1 exited 0 [Mar 29 20:16:12] DEBUG[3499]: asterisk.sipp:500 outReceived: Received from SIPp scenario subscribe.xml: ------------------------------ Scenario Screen -------- [1-9]: Change Screen -- Call-rate(length) Port Total-time Total-calls Remote-host 10.0(0 ms)/1.000s 5062 0.00 s 0 127.0.0.1:5061(UDP) 0 new calls during 0.001 s period 1 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 200 <---------- 0 0 0 0 NOTIFY <---------- 0 0 0 0 200 ----------> 0 0 NOTIFY <---------- 0 0 0 0 200 ----------> 0 0 SUBSCRIBE ----------> 0 0 0 200 <---------- 0 0 0 0 NOTIFY <---------- 0 0 0 0 200 ----------> 0 0 ------ [+|-|*|/]: Adjust rate ---- [q]: Soft exit ---- [p]: Pause traffic ----- [Mar 29 20:16:12] DEBUG[3499]: asterisk.pcap:822 datagramReceived: Proxy received from 127.0.0.1:5062 SUBSCRIBE sip:mail_list@127.0.0.1:5061 SIP/2.0 Via: SIP/2.0/UDP 127.0.0.1:5062;branch=z9hG4bK-3611-1-0 From: sipp ;tag=3611SIPpTag001 To: sut Call-ID: 1-3611@127.0.0.1 CSeq: 1 SUBSCRIBE Contact: sip:sipp@127.0.0.1:5062 Max-Forwards: 70 Subject: Performance Test Event: message-summary Supported: eventlist Accept: application/rlmi+xml Accept: application/simple-message-summary Accept: multipart/related Expires: 3600 Content-Length: 0 [Mar 29 20:16:12] DEBUG[3499]: asterisk.pcap:754 process_packet: Processing packet from 127.0.0.1:5062 [Mar 29 20:16:12] DEBUG[3499]: rls_test:36 filter_multipart_packet: Ignoring packet, is not a NOTIFY [Mar 29 20:16:12] DEBUG[3499]: asterisk.pcap:832 datagramReceived: Forwarding packet to 127.0.0.1:5060 [Mar 29 20:16:12] DEBUG[3499]: asterisk.pcap:822 datagramReceived: Proxy received from 127.0.0.1:5060 SIP/2.0 200 OK Via: SIP/2.0/UDP 127.0.0.1:5062;rport=5061;received=127.0.0.1;branch=z9hG4bK-3611-1-0 Call-ID: 1-3611@127.0.0.1 From: "sipp" ;tag=3611SIPpTag001 To: "sut" ;tag=660e5373-48ad-4a8c-aaa2-55b5138e11fa CSeq: 1 SUBSCRIBE Expires: 3600 Require: eventlist Contact: Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER Supported: 100rel, timer, replaces, norefersub Server: Asterisk PBX GIT-master-df22e5e Content-Length: 0 [Mar 29 20:16:12] DEBUG[3499]: asterisk.pcap:754 process_packet: Processing packet from 127.0.0.1:5060 [Mar 29 20:16:12] DEBUG[3499]: rls_test:36 filter_multipart_packet: Ignoring packet, is not a NOTIFY [Mar 29 20:16:12] DEBUG[3499]: asterisk.pcap:832 datagramReceived: Forwarding packet to 127.0.0.1:5062 [Mar 29 20:16:12] DEBUG[3499]: asterisk.pcap:822 datagramReceived: Proxy received from 127.0.0.1:5060 NOTIFY sip:sipp@127.0.0.1:5061 SIP/2.0 Via: SIP/2.0/UDP 127.0.0.1:5060;rport;branch=z9hG4bKPj21cc61c2-50ff-4ffc-972d-63f3846185b0 From: "sut" ;tag=660e5373-48ad-4a8c-aaa2-55b5138e11fa To: "sipp" ;tag=3611SIPpTag001 Contact: Call-ID: 1-3611@127.0.0.1 CSeq: 24687 NOTIFY Event: message-summary Subscription-State: active;expires=3599 Allow-Events: presence, dialog, message-summary, refer Require: eventlist Max-Forwards: 70 User-Agent: Asterisk PBX GIT-master-df22e5e Content-Type: multipart/related;type="application/rlmi+xml";boundary=btlif Content-Length: 900 --btlif Content-ID: Content-Type: application/rlmi+xml Content-Length: 454 mail_list alice bob --btlif Content-ID: Content-Type: application/simple-message-summary Content-Length: 48 Messages-Waiting: no Voice-Message: 0/0 (0/0) --btlif Content-ID: Content-Type: application/simple-message-summary Content-Length: 48 Messages-Waiting: no Voice-Message: 0/0 (0/0) --btlif-- [Mar 29 20:16:12] DEBUG[3499]: asterisk.pcap:754 process_packet: Processing packet from 127.0.0.1:5060 [Mar 29 20:16:12] DEBUG[3499]: rls_test:211 multipart_handler: Validating Resource (0) of (4)... [Mar 29 20:16:12] DEBUG[3499]: rls_element:1007 validate: Validating RLS packet... [Mar 29 20:16:12] DEBUG[3499]: rls_element:1030 __validate_part_counts: Processing RLS packet -- Inspecting number of body parts received. Expecting: 2... [Mar 29 20:16:12] DEBUG[3499]: rls_element:1041 __validate_part_counts: Processing RLS packet -- Validation check passed. Received expected number of body parts. [Mar 29 20:16:12] DEBUG[3499]: rls_element:1045 __validate_part_counts: Processing RLS packet -- Inspecting number of RMLI parts received. Expecting: 1... [Mar 29 20:16:12] DEBUG[3499]: rls_element:1057 __validate_part_counts: Processing RLS packet -- Validation check passed. Received expected number of RMLI parts. [Mar 29 20:16:12] DEBUG[3499]: rls_element:622 validate: Validating RLMI list element... [Mar 29 20:16:12] DEBUG[3499]: rls_element:654 __validate_fullstate: Processing RLMI list element -- Inspecting RLMI fullstate value. Expecting: True... [Mar 29 20:16:12] DEBUG[3499]: rls_element:665 __validate_fullstate: Processing RLMI list element -- Validation check passed. Received expected RLMI fullstate value. [Mar 29 20:16:12] DEBUG[3499]: rls_element:676 __validate_name: Processing RLMI list element -- Inspecting number of 'name' elements. Expecting: 1. [Mar 29 20:16:12] DEBUG[3499]: rls_element:688 __validate_name: Processing RLMI list element -- Validation check passed. Received expected number of 'name' elements. [Mar 29 20:16:12] DEBUG[3499]: rls_element:706 __validate_resources: Processing RLMI list element -- Inspecting number of 'resource' elements. Expecting: 2. [Mar 29 20:16:12] DEBUG[3499]: rls_element:718 __validate_resources: Processing RLMI list element -- Validation check passed. Received expected number of 'resource' elements. [Mar 29 20:16:12] DEBUG[3499]: rls_element:760 __validate_rlmi_name: Processing RLMI list element -- Inspecting RLMI list name. Expecting: mail_list. [Mar 29 20:16:12] DEBUG[3499]: rls_element:771 __validate_rlmi_name: Processing RLMI list element -- Validation check passed. Received expected RLMI list name. [Mar 29 20:16:12] DEBUG[3499]: rls_element:738 __validate_rlmi_resources: Processing RLMI list element -- Validating children RLMI resource elements. [Mar 29 20:16:12] DEBUG[3499]: rls_element:830 validate: Validating RLMI resource... [Mar 29 20:16:12] DEBUG[3499]: rls_element:966 __validate_uri: Processing RLMI resource -- Inspecting 'uri' attribute... [Mar 29 20:16:12] DEBUG[3499]: rls_element:975 __validate_uri: Processing RLMI resource -- Validation check passed. Received expected 'uri' attribute. [Mar 29 20:16:12] DEBUG[3499]: rls_element:927 __validate_name: Processing RLMI resource -- Inspecting number of 'name' elements. Expecting: 1. [Mar 29 20:16:12] DEBUG[3499]: rls_element:939 __validate_name: Processing RLMI resource -- Validation check passed. Received expected number of 'name' elements. [Mar 29 20:16:12] DEBUG[3499]: rls_element:942 __validate_name: Processing RLMI resource -- Inspecting RLMI resource name... [Mar 29 20:16:12] DEBUG[3499]: rls_element:954 __validate_name: Processing RLMI list element -- Validation check passed. Received expected RLMI resource name. [Mar 29 20:16:12] DEBUG[3499]: rls_element:854 __validate_instance: Processing RLMI resource -- Inspecting number of 'instance' elements. Expecting: 1. [Mar 29 20:16:12] DEBUG[3499]: rls_element:865 __validate_instance: Processing RLMI resource -- Validation check passed. Received expected number of 'instance' elements. [Mar 29 20:16:12] DEBUG[3499]: rls_element:869 __validate_instance: Processing RLMI resource -- Inspecting RLMI resource instance attributes: state, id, and cid... [Mar 29 20:16:12] DEBUG[3499]: rls_element:890 __validate_instance: Processing RLMI resource -- Validation check passed. Received values for 'instance' element attributes: state, id and cid. [Mar 29 20:16:12] DEBUG[3499]: rls_element:898 __validate_instance: Processing RLMI resource -- Inspecting instance state. Expecting: active... [Mar 29 20:16:12] DEBUG[3499]: rls_element:907 __validate_instance: Processing RLMI resource -- Validation check passed. Received expected value for the RLMI instance state. [Mar 29 20:16:12] DEBUG[3499]: rls_element:830 validate: Validating RLMI resource... [Mar 29 20:16:12] DEBUG[3499]: rls_element:966 __validate_uri: Processing RLMI resource -- Inspecting 'uri' attribute... [Mar 29 20:16:12] DEBUG[3499]: rls_element:975 __validate_uri: Processing RLMI resource -- Validation check passed. Received expected 'uri' attribute. [Mar 29 20:16:12] DEBUG[3499]: rls_element:927 __validate_name: Processing RLMI resource -- Inspecting number of 'name' elements. Expecting: 1. [Mar 29 20:16:12] DEBUG[3499]: rls_element:939 __validate_name: Processing RLMI resource -- Validation check passed. Received expected number of 'name' elements. [Mar 29 20:16:12] DEBUG[3499]: rls_element:942 __validate_name: Processing RLMI resource -- Inspecting RLMI resource name... [Mar 29 20:16:12] DEBUG[3499]: rls_element:954 __validate_name: Processing RLMI list element -- Validation check passed. Received expected RLMI resource name. [Mar 29 20:16:12] DEBUG[3499]: rls_element:854 __validate_instance: Processing RLMI resource -- Inspecting number of 'instance' elements. Expecting: 1. [Mar 29 20:16:12] DEBUG[3499]: rls_element:865 __validate_instance: Processing RLMI resource -- Validation check passed. Received expected number of 'instance' elements. [Mar 29 20:16:12] DEBUG[3499]: rls_element:869 __validate_instance: Processing RLMI resource -- Inspecting RLMI resource instance attributes: state, id, and cid... [Mar 29 20:16:12] DEBUG[3499]: rls_element:890 __validate_instance: Processing RLMI resource -- Validation check passed. Received values for 'instance' element attributes: state, id and cid. [Mar 29 20:16:12] DEBUG[3499]: rls_element:898 __validate_instance: Processing RLMI resource -- Inspecting instance state. Expecting: active... [Mar 29 20:16:12] DEBUG[3499]: rls_element:907 __validate_instance: Processing RLMI resource -- Validation check passed. Received expected value for the RLMI instance state. [Mar 29 20:16:12] DEBUG[3499]: rls_element:346 validate: Validating MWI body ... [Mar 29 20:16:12] DEBUG[3499]: rls_element:380 __validate_content_id: Processing MWI body -- Inspecting 'Content-ID' element... [Mar 29 20:16:12] DEBUG[3499]: rls_element:389 __validate_content_id: Processing MWI body -- Validation check passed. MWI bodycontains a Content-ID. [Mar 29 20:16:12] DEBUG[3499]: rls_element:492 __validate_rlmi_body: Processing MWI body -- Inspecting RLMI body... [Mar 29 20:16:12] DEBUG[3499]: rls_element:500 __validate_rlmi_body: Processing MWI body -- Validation check passed. MWI part contains an RLMI body. [Mar 29 20:16:12] DEBUG[3499]: rls_element:460 __validate_resource_instance: Processing MWI body -- Inspecting RLMI body resource instances... [Mar 29 20:16:12] DEBUG[3499]: rls_element:476 __validate_resource_instance: Processing MWI body -- Validation check passed. RLMI body contains a resource instance for this MWI body. [Mar 29 20:16:12] DEBUG[3499]: rls_element:406 __validate_mwi_resource: Processing MWI body -- Inspecting MWI resource... [Mar 29 20:16:12] DEBUG[3499]: rls_element:445 __validate_mwi_resource: Processing MWI body -- Validation check passed for MWI resource ({'type': 'MWI', 'state': 'active', 'messages_waiting': 'no', 'voice_message': '0/0 (0/0)'}). [Mar 29 20:16:12] DEBUG[3499]: rls_element:346 validate: Validating MWI body ... [Mar 29 20:16:12] DEBUG[3499]: rls_element:380 __validate_content_id: Processing MWI body -- Inspecting 'Content-ID' element... [Mar 29 20:16:12] DEBUG[3499]: rls_element:389 __validate_content_id: Processing MWI body -- Validation check passed. MWI bodycontains a Content-ID. [Mar 29 20:16:12] DEBUG[3499]: rls_element:492 __validate_rlmi_body: Processing MWI body -- Inspecting RLMI body... [Mar 29 20:16:12] DEBUG[3499]: rls_element:500 __validate_rlmi_body: Processing MWI body -- Validation check passed. MWI part contains an RLMI body. [Mar 29 20:16:12] DEBUG[3499]: rls_element:460 __validate_resource_instance: Processing MWI body -- Inspecting RLMI body resource instances... [Mar 29 20:16:12] DEBUG[3499]: rls_element:476 __validate_resource_instance: Processing MWI body -- Validation check passed. RLMI body contains a resource instance for this MWI body. [Mar 29 20:16:12] DEBUG[3499]: rls_element:406 __validate_mwi_resource: Processing MWI body -- Inspecting MWI resource... [Mar 29 20:16:12] DEBUG[3499]: rls_element:445 __validate_mwi_resource: Processing MWI body -- Validation check passed for MWI resource ({'type': 'MWI', 'state': 'active', 'messages_waiting': 'no', 'voice_message': '0/0 (0/0)'}). [Mar 29 20:16:12] DEBUG[3499]: rls_element:1098 __validate_content_ids: Processing RLS packet -- Inspecting number of Content-IDs received. Expecting: 2... [Mar 29 20:16:12] DEBUG[3499]: rls_element:1109 __validate_content_ids: Processing RLS packet -- Validation check passed. Received expected number of Content IDs. [Mar 29 20:16:12] INFO[3499]: rls_test:219 multipart_handler: Resource (0) validated successfully. [Mar 29 20:16:12] DEBUG[3499]: asterisk.pcap:832 datagramReceived: Forwarding packet to 127.0.0.1:5062 [Mar 29 20:16:12] DEBUG[3499]: AMI:171 lineReceived: Line In: 'Event: TestEvent' [Mar 29 20:16:12] DEBUG[3499]: AMI:171 lineReceived: Line In: 'Privilege: reporting,all' [Mar 29 20:16:12] DEBUG[3499]: AMI:171 lineReceived: Line In: 'Type: StateChange' [Mar 29 20:16:12] DEBUG[3499]: AMI:171 lineReceived: Line In: 'State: SUBSCRIPTION_STATE_SET' [Mar 29 20:16:12] DEBUG[3499]: AMI:171 lineReceived: Line In: 'AppFile: res_pjsip_pubsub.c' [Mar 29 20:16:12] DEBUG[3499]: AMI:171 lineReceived: Line In: 'AppFunction: sip_subscription_send_request' [Mar 29 20:16:12] DEBUG[3499]: AMI:171 lineReceived: Line In: 'AppLine: 2044' [Mar 29 20:16:12] DEBUG[3499]: AMI:171 lineReceived: Line In: 'StateText: ACTIVE' [Mar 29 20:16:12] DEBUG[3499]: AMI:171 lineReceived: Line In: 'Endpoint: sipp' [Mar 29 20:16:12] DEBUG[3499]: AMI:171 lineReceived: Line In: '' [Mar 29 20:16:12] DEBUG[3499]: AMI:233 dispatchIncoming: Dispatch Incoming [Mar 29 20:16:12] DEBUG[3499]: AMI:263 dispatchIncoming: Incoming Message: {u'appfile': u'res_pjsip_pubsub.c', u'endpoint': u'sipp', u'appline': u'2044', u'appfunction': u'sip_subscription_send_request', u'state': u'SUBSCRIPTION_STATE_SET', u'statetext': u'ACTIVE', u'privilege': u'reporting,all', u'type': u'StateChange', u'event': u'TestEvent'} [Mar 29 20:16:12] DEBUG[3499]: AMI:171 lineReceived: Line In: '' [Mar 29 20:16:12] DEBUG[3499]: AMI:233 dispatchIncoming: Dispatch Incoming [Mar 29 20:16:12] DEBUG[3499]: AMI:263 dispatchIncoming: Incoming Message: {} [Mar 29 20:16:12] DEBUG[3499]: AMI:171 lineReceived: Line In: 'Event: TestEvent' [Mar 29 20:16:12] DEBUG[3499]: AMI:171 lineReceived: Line In: 'Privilege: reporting,all' [Mar 29 20:16:12] DEBUG[3499]: AMI:171 lineReceived: Line In: 'Type: StateChange' [Mar 29 20:16:12] DEBUG[3499]: AMI:171 lineReceived: Line In: 'State: SUBSCRIPTION_ESTABLISHED' [Mar 29 20:16:12] DEBUG[3499]: AMI:171 lineReceived: Line In: 'AppFile: res_pjsip_pubsub.c' [Mar 29 20:16:12] DEBUG[3499]: AMI:171 lineReceived: Line In: 'AppFunction: initial_notify_task' [Mar 29 20:16:12] DEBUG[3499]: AMI:171 lineReceived: Line In: 'AppLine: 2977' [Mar 29 20:16:12] DEBUG[3499]: AMI:171 lineReceived: Line In: 'Resource: mail_list' [Mar 29 20:16:12] DEBUG[3499]: AMI:171 lineReceived: Line In: '' [Mar 29 20:16:12] DEBUG[3499]: AMI:233 dispatchIncoming: Dispatch Incoming [Mar 29 20:16:12] DEBUG[3499]: AMI:263 dispatchIncoming: Incoming Message: {u'appfile': u'res_pjsip_pubsub.c', u'resource': u'mail_list', u'appline': u'2977', u'appfunction': u'initial_notify_task', u'state': u'SUBSCRIPTION_ESTABLISHED', u'privilege': u'reporting,all', u'type': u'StateChange', u'event': u'TestEvent'} [Mar 29 20:16:12] DEBUG[3499]: driver:68 on_subscription_established: State change to 2 [Mar 29 20:16:12] DEBUG[3499]: AMI:361 sendMessage: MSG OUT: {'action': 'MWIUpdate', 'oldmessages': '0', 'newmessages': '1', 'actionid': 'ff3bb070a8b4-140033481909600-2', 'mailbox': 'alice'} [Mar 29 20:16:12] DEBUG[3499]: AMI:361 sendMessage: MSG OUT: {'action': 'MWIUpdate', 'oldmessages': '0', 'newmessages': '1', 'actionid': 'ff3bb070a8b4-140033481909600-3', 'mailbox': 'bob'} [Mar 29 20:16:12] DEBUG[3499]: asterisk.pcap:822 datagramReceived: Proxy received from 127.0.0.1:5062 SIP/2.0 200 OK Via: SIP/2.0/UDP 127.0.0.1:5060;rport;branch=z9hG4bKPj21cc61c2-50ff-4ffc-972d-63f3846185b0 From: "sut" ;tag=660e5373-48ad-4a8c-aaa2-55b5138e11fa To: "sipp" ;tag=3611SIPpTag001 Call-ID: 1-3611@127.0.0.1 CSeq: 24687 NOTIFY Contact: Content-Length: 0 [Mar 29 20:16:12] DEBUG[3499]: asterisk.pcap:754 process_packet: Processing packet from 127.0.0.1:5062 [Mar 29 20:16:12] DEBUG[3499]: rls_test:36 filter_multipart_packet: Ignoring packet, is not a NOTIFY [Mar 29 20:16:12] DEBUG[3499]: asterisk.pcap:832 datagramReceived: Forwarding packet to 127.0.0.1:5060 [Mar 29 20:16:12] DEBUG[3499]: AMI:171 lineReceived: Line In: 'Response: Success' [Mar 29 20:16:12] DEBUG[3499]: AMI:171 lineReceived: Line In: 'ActionID: ff3bb070a8b4-140033481909600-2' [Mar 29 20:16:12] DEBUG[3499]: AMI:171 lineReceived: Line In: '' [Mar 29 20:16:12] DEBUG[3499]: AMI:233 dispatchIncoming: Dispatch Incoming [Mar 29 20:16:12] DEBUG[3499]: AMI:263 dispatchIncoming: Incoming Message: {u'response': u'Success', u'actionid': u'ff3bb070a8b4-140033481909600-2'} [Mar 29 20:16:12] DEBUG[3499]: AMI:171 lineReceived: Line In: 'Response: Success' [Mar 29 20:16:12] DEBUG[3499]: AMI:171 lineReceived: Line In: 'ActionID: ff3bb070a8b4-140033481909600-3' [Mar 29 20:16:12] DEBUG[3499]: AMI:171 lineReceived: Line In: '' [Mar 29 20:16:12] DEBUG[3499]: AMI:233 dispatchIncoming: Dispatch Incoming [Mar 29 20:16:12] DEBUG[3499]: AMI:263 dispatchIncoming: Incoming Message: {u'response': u'Success', u'actionid': u'ff3bb070a8b4-140033481909600-3'} [Mar 29 20:16:12] DEBUG[3499]: AMI:171 lineReceived: Line In: 'Event: MessageWaiting' [Mar 29 20:16:12] DEBUG[3499]: AMI:171 lineReceived: Line In: 'Privilege: call,all' [Mar 29 20:16:12] DEBUG[3499]: AMI:171 lineReceived: Line In: 'Mailbox: alice' [Mar 29 20:16:12] DEBUG[3499]: AMI:171 lineReceived: Line In: 'Waiting: 1' [Mar 29 20:16:12] DEBUG[3499]: AMI:171 lineReceived: Line In: 'New: 1' [Mar 29 20:16:12] DEBUG[3499]: AMI:171 lineReceived: Line In: 'Old: 0' [Mar 29 20:16:12] DEBUG[3499]: AMI:171 lineReceived: Line In: '' [Mar 29 20:16:12] DEBUG[3499]: AMI:233 dispatchIncoming: Dispatch Incoming [Mar 29 20:16:12] DEBUG[3499]: AMI:263 dispatchIncoming: Incoming Message: {u'old': u'0', u'mailbox': u'alice', u'waiting': u'1', u'privilege': u'call,all', u'new': u'1', u'event': u'MessageWaiting'} [Mar 29 20:16:12] DEBUG[3499]: AMI:171 lineReceived: Line In: 'Event: MessageWaiting' [Mar 29 20:16:12] DEBUG[3499]: AMI:171 lineReceived: Line In: 'Privilege: call,all' [Mar 29 20:16:12] DEBUG[3499]: AMI:171 lineReceived: Line In: 'Mailbox: bob' [Mar 29 20:16:12] DEBUG[3499]: AMI:171 lineReceived: Line In: 'Waiting: 1' [Mar 29 20:16:12] DEBUG[3499]: AMI:171 lineReceived: Line In: 'New: 1' [Mar 29 20:16:12] DEBUG[3499]: AMI:171 lineReceived: Line In: 'Old: 0' [Mar 29 20:16:12] DEBUG[3499]: AMI:171 lineReceived: Line In: '' [Mar 29 20:16:12] DEBUG[3499]: AMI:233 dispatchIncoming: Dispatch Incoming [Mar 29 20:16:12] DEBUG[3499]: AMI:263 dispatchIncoming: Incoming Message: {u'old': u'0', u'mailbox': u'bob', u'waiting': u'1', u'privilege': u'call,all', u'new': u'1', u'event': u'MessageWaiting'} [Mar 29 20:16:12] DEBUG[3499]: AMI:171 lineReceived: Line In: 'Event: DeviceStateChange' [Mar 29 20:16:12] DEBUG[3499]: AMI:171 lineReceived: Line In: 'Privilege: call,all' [Mar 29 20:16:12] DEBUG[3499]: AMI:171 lineReceived: Line In: 'Device: MWI:alice' [Mar 29 20:16:12] DEBUG[3499]: AMI:171 lineReceived: Line In: 'State: INUSE' [Mar 29 20:16:12] DEBUG[3499]: AMI:171 lineReceived: Line In: '' [Mar 29 20:16:12] DEBUG[3499]: AMI:233 dispatchIncoming: Dispatch Incoming [Mar 29 20:16:12] DEBUG[3499]: AMI:263 dispatchIncoming: Incoming Message: {u'privilege': u'call,all', u'device': u'MWI:alice', u'state': u'INUSE', u'event': u'DeviceStateChange'} [Mar 29 20:16:12] DEBUG[3499]: AMI:171 lineReceived: Line In: 'Event: DeviceStateChange' [Mar 29 20:16:12] DEBUG[3499]: AMI:171 lineReceived: Line In: 'Privilege: call,all' [Mar 29 20:16:12] DEBUG[3499]: AMI:171 lineReceived: Line In: 'Device: MWI:bob' [Mar 29 20:16:12] DEBUG[3499]: AMI:171 lineReceived: Line In: 'State: INUSE' [Mar 29 20:16:12] DEBUG[3499]: AMI:171 lineReceived: Line In: '' [Mar 29 20:16:12] DEBUG[3499]: AMI:233 dispatchIncoming: Dispatch Incoming [Mar 29 20:16:12] DEBUG[3499]: AMI:263 dispatchIncoming: Incoming Message: {u'privilege': u'call,all', u'device': u'MWI:bob', u'state': u'INUSE', u'event': u'DeviceStateChange'} [Mar 29 20:16:13] DEBUG[3499]: asterisk.sipp:500 outReceived: Received from SIPp scenario subscribe.xml: ------------------------------ Scenario Screen -------- [1-9]: Change Screen -- Call-rate(length) Port Total-time Total-calls Remote-host 10.0(0 ms)/1.000s 5062 1.00 s 1 127.0.0.1:5061(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, 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 200 <---------- 0 0 0 0 NOTIFY <---------- 0 0 0 0 200 ----------> 0 0 NOTIFY <---------- 0 0 0 0 200 ----------> 0 0 SUBSCRIBE ----------> 0 0 0 200 <---------- 0 0 0 0 NOTIFY <---------- 0 0 0 0 200 ----------> 0 0 ------- Waiting for active calls to end. Press [q] again to force exit. ------- [Mar 29 20:16:14] DEBUG[3499]: asterisk.sipp:500 outReceived: Received from SIPp scenario subscribe.xml: ------------------------------ Scenario Screen -------- [1-9]: Change Screen -- Call-rate(length) Port Total-time Total-calls Remote-host 10.0(0 ms)/1.000s 5062 2.00 s 1 127.0.0.1:5061(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 <---------- 0 0 0 0 200 ----------> 0 0 SUBSCRIBE ----------> 0 0 0 200 <---------- 0 0 0 0 NOTIFY <---------- 0 0 0 0 200 ----------> 0 0 NOTIFY <---------- 0 0 0 0 200 ----------> 0 0 SUBSCRIBE ----------> 0 0 0 200 <---------- 0 0 0 0 NOTIFY <---------- 0 0 0 0 200 ----------> 0 0 ------- Waiting for active calls to end. Press [q] again to force exit. ------- [Mar 29 20:16:15] DEBUG[3499]: asterisk.sipp:500 outReceived: Received from SIPp scenario subscribe.xml: ------------------------------ Scenario Screen -------- [1-9]: Change Screen -- Call-rate(length) Port Total-time Total-calls Remote-host 10.0(0 ms)/1.000s 5062 3.00 s 1 127.0.0.1:5061(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 200 <---------- 0 0 0 0 NOTIFY <---------- 0 0 0 0 200 ----------> 0 0 NOTIFY <---------- 0 0 0 0 200 ----------> 0 0 SUBSCRIBE ----------> 0 0 0 200 <---------- 0 0 0 0 NOTIFY <---------- 0 0 0 0 200 ----------> 0 0 ------- Waiting for active calls to end. Press [q] again to force exit. ------- [Mar 29 20:16:16] DEBUG[3499]: asterisk.sipp:500 outReceived: Received from SIPp scenario subscribe.xml: ------------------------------ Scenario Screen -------- [1-9]: Change Screen -- Call-rate(length) Port Total-time Total-calls Remote-host 10.0(0 ms)/1.000s 5062 4.00 s 1 127.0.0.1:5061(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 200 <---------- 0 0 0 0 NOTIFY <---------- 0 0 0 0 200 ----------> 0 0 NOTIFY <---------- 0 0 0 0 200 ----------> 0 0 SUBSCRIBE ----------> 0 0 0 200 <---------- 0 0 0 0 NOTIFY <---------- 0 0 0 0 200 ----------> 0 0 ------- Waiting for active calls to end. Press [q] again to force exit. ------- [Mar 29 20:16:17] DEBUG[3499]: asterisk.sipp:500 outReceived: Received from SIPp scenario subscribe.xml: ------------------------------ Scenario Screen -------- [1-9]: Change Screen -- Call-rate(length) Port Total-time Total-calls Remote-host 10.0(0 ms)/1.000s 5062 5.00 s 1 127.0.0.1:5061(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 200 <---------- 0 0 0 0 NOTIFY <---------- 0 0 0 0 200 ----------> 0 0 NOTIFY <---------- 0 0 0 0 200 ----------> 0 0 SUBSCRIBE ----------> 0 0 0 200 <---------- 0 0 0 0 NOTIFY <---------- 0 0 0 0 200 ----------> 0 0 ------- Waiting for active calls to end. Press [q] again to force exit. ------- [Mar 29 20:16:17] DEBUG[3499]: asterisk.pcap:822 datagramReceived: Proxy received from 127.0.0.1:5060 NOTIFY sip:127.0.0.1:5061 SIP/2.0 Via: SIP/2.0/UDP 127.0.0.1:5060;rport;branch=z9hG4bKPje2b95925-3585-4077-9950-3e00b1021902 From: "sut" ;tag=660e5373-48ad-4a8c-aaa2-55b5138e11fa To: "sipp" ;tag=3611SIPpTag001 Contact: Call-ID: 1-3611@127.0.0.1 CSeq: 24688 NOTIFY Event: message-summary Subscription-State: active;expires=3594 Allow-Events: presence, dialog, message-summary, refer Require: eventlist Max-Forwards: 70 User-Agent: Asterisk PBX GIT-master-df22e5e Content-Type: multipart/related;type="application/rlmi+xml";boundary=ncrwa Content-Length: 903 --ncrwa Content-ID: Content-Type: application/rlmi+xml Content-Length: 455 mail_list alice bob --ncrwa Content-ID: Content-Type: application/simple-message-summary Content-Length: 49 Messages-Waiting: yes Voice-Message: 1/0 (0/0) --ncrwa Content-ID: Content-Type: application/simple-message-summary Content-Length: 49 Messages-Waiting: yes Voice-Message: 1/0 (0/0) --ncrwa-- [Mar 29 20:16:17] DEBUG[3499]: asterisk.pcap:754 process_packet: Processing packet from 127.0.0.1:5060 [Mar 29 20:16:17] DEBUG[3499]: rls_test:211 multipart_handler: Validating Resource (1) of (4)... [Mar 29 20:16:17] DEBUG[3499]: rls_element:1007 validate: Validating RLS packet... [Mar 29 20:16:17] DEBUG[3499]: rls_element:1030 __validate_part_counts: Processing RLS packet -- Inspecting number of body parts received. Expecting: 2... [Mar 29 20:16:17] DEBUG[3499]: rls_element:1041 __validate_part_counts: Processing RLS packet -- Validation check passed. Received expected number of body parts. [Mar 29 20:16:17] DEBUG[3499]: rls_element:1045 __validate_part_counts: Processing RLS packet -- Inspecting number of RMLI parts received. Expecting: 1... [Mar 29 20:16:17] DEBUG[3499]: rls_element:1057 __validate_part_counts: Processing RLS packet -- Validation check passed. Received expected number of RMLI parts. [Mar 29 20:16:17] DEBUG[3499]: rls_element:622 validate: Validating RLMI list element... [Mar 29 20:16:17] DEBUG[3499]: rls_element:654 __validate_fullstate: Processing RLMI list element -- Inspecting RLMI fullstate value. Expecting: False... [Mar 29 20:16:17] DEBUG[3499]: rls_element:665 __validate_fullstate: Processing RLMI list element -- Validation check passed. Received expected RLMI fullstate value. [Mar 29 20:16:17] DEBUG[3499]: rls_element:676 __validate_name: Processing RLMI list element -- Inspecting number of 'name' elements. Expecting: 1. [Mar 29 20:16:17] DEBUG[3499]: rls_element:688 __validate_name: Processing RLMI list element -- Validation check passed. Received expected number of 'name' elements. [Mar 29 20:16:17] DEBUG[3499]: rls_element:706 __validate_resources: Processing RLMI list element -- Inspecting number of 'resource' elements. Expecting: 2. [Mar 29 20:16:17] DEBUG[3499]: rls_element:718 __validate_resources: Processing RLMI list element -- Validation check passed. Received expected number of 'resource' elements. [Mar 29 20:16:17] DEBUG[3499]: rls_element:760 __validate_rlmi_name: Processing RLMI list element -- Inspecting RLMI list name. Expecting: mail_list. [Mar 29 20:16:17] DEBUG[3499]: rls_element:771 __validate_rlmi_name: Processing RLMI list element -- Validation check passed. Received expected RLMI list name. [Mar 29 20:16:17] DEBUG[3499]: rls_element:738 __validate_rlmi_resources: Processing RLMI list element -- Validating children RLMI resource elements. [Mar 29 20:16:17] DEBUG[3499]: rls_element:830 validate: Validating RLMI resource... [Mar 29 20:16:17] DEBUG[3499]: rls_element:966 __validate_uri: Processing RLMI resource -- Inspecting 'uri' attribute... [Mar 29 20:16:17] DEBUG[3499]: rls_element:975 __validate_uri: Processing RLMI resource -- Validation check passed. Received expected 'uri' attribute. [Mar 29 20:16:17] DEBUG[3499]: rls_element:927 __validate_name: Processing RLMI resource -- Inspecting number of 'name' elements. Expecting: 1. [Mar 29 20:16:17] DEBUG[3499]: rls_element:939 __validate_name: Processing RLMI resource -- Validation check passed. Received expected number of 'name' elements. [Mar 29 20:16:17] DEBUG[3499]: rls_element:942 __validate_name: Processing RLMI resource -- Inspecting RLMI resource name... [Mar 29 20:16:17] DEBUG[3499]: rls_element:954 __validate_name: Processing RLMI list element -- Validation check passed. Received expected RLMI resource name. [Mar 29 20:16:17] DEBUG[3499]: rls_element:854 __validate_instance: Processing RLMI resource -- Inspecting number of 'instance' elements. Expecting: 1. [Mar 29 20:16:17] DEBUG[3499]: rls_element:865 __validate_instance: Processing RLMI resource -- Validation check passed. Received expected number of 'instance' elements. [Mar 29 20:16:17] DEBUG[3499]: rls_element:869 __validate_instance: Processing RLMI resource -- Inspecting RLMI resource instance attributes: state, id, and cid... [Mar 29 20:16:17] DEBUG[3499]: rls_element:890 __validate_instance: Processing RLMI resource -- Validation check passed. Received values for 'instance' element attributes: state, id and cid. [Mar 29 20:16:17] DEBUG[3499]: rls_element:898 __validate_instance: Processing RLMI resource -- Inspecting instance state. Expecting: active... [Mar 29 20:16:17] DEBUG[3499]: rls_element:907 __validate_instance: Processing RLMI resource -- Validation check passed. Received expected value for the RLMI instance state. [Mar 29 20:16:17] DEBUG[3499]: rls_element:830 validate: Validating RLMI resource... [Mar 29 20:16:17] DEBUG[3499]: rls_element:966 __validate_uri: Processing RLMI resource -- Inspecting 'uri' attribute... [Mar 29 20:16:17] DEBUG[3499]: rls_element:975 __validate_uri: Processing RLMI resource -- Validation check passed. Received expected 'uri' attribute. [Mar 29 20:16:17] DEBUG[3499]: rls_element:927 __validate_name: Processing RLMI resource -- Inspecting number of 'name' elements. Expecting: 1. [Mar 29 20:16:17] DEBUG[3499]: rls_element:939 __validate_name: Processing RLMI resource -- Validation check passed. Received expected number of 'name' elements. [Mar 29 20:16:17] DEBUG[3499]: rls_element:942 __validate_name: Processing RLMI resource -- Inspecting RLMI resource name... [Mar 29 20:16:17] DEBUG[3499]: rls_element:954 __validate_name: Processing RLMI list element -- Validation check passed. Received expected RLMI resource name. [Mar 29 20:16:17] DEBUG[3499]: rls_element:854 __validate_instance: Processing RLMI resource -- Inspecting number of 'instance' elements. Expecting: 1. [Mar 29 20:16:17] DEBUG[3499]: rls_element:865 __validate_instance: Processing RLMI resource -- Validation check passed. Received expected number of 'instance' elements. [Mar 29 20:16:17] DEBUG[3499]: rls_element:869 __validate_instance: Processing RLMI resource -- Inspecting RLMI resource instance attributes: state, id, and cid... [Mar 29 20:16:17] DEBUG[3499]: rls_element:890 __validate_instance: Processing RLMI resource -- Validation check passed. Received values for 'instance' element attributes: state, id and cid. [Mar 29 20:16:17] DEBUG[3499]: rls_element:898 __validate_instance: Processing RLMI resource -- Inspecting instance state. Expecting: active... [Mar 29 20:16:17] DEBUG[3499]: rls_element:907 __validate_instance: Processing RLMI resource -- Validation check passed. Received expected value for the RLMI instance state. [Mar 29 20:16:17] DEBUG[3499]: rls_element:346 validate: Validating MWI body ... [Mar 29 20:16:17] DEBUG[3499]: rls_element:380 __validate_content_id: Processing MWI body -- Inspecting 'Content-ID' element... [Mar 29 20:16:17] DEBUG[3499]: rls_element:389 __validate_content_id: Processing MWI body -- Validation check passed. MWI bodycontains a Content-ID. [Mar 29 20:16:17] DEBUG[3499]: rls_element:492 __validate_rlmi_body: Processing MWI body -- Inspecting RLMI body... [Mar 29 20:16:17] DEBUG[3499]: rls_element:500 __validate_rlmi_body: Processing MWI body -- Validation check passed. MWI part contains an RLMI body. [Mar 29 20:16:17] DEBUG[3499]: rls_element:460 __validate_resource_instance: Processing MWI body -- Inspecting RLMI body resource instances... [Mar 29 20:16:17] DEBUG[3499]: rls_element:476 __validate_resource_instance: Processing MWI body -- Validation check passed. RLMI body contains a resource instance for this MWI body. [Mar 29 20:16:17] DEBUG[3499]: rls_element:406 __validate_mwi_resource: Processing MWI body -- Inspecting MWI resource... [Mar 29 20:16:17] DEBUG[3499]: rls_element:445 __validate_mwi_resource: Processing MWI body -- Validation check passed for MWI resource ({'type': 'MWI', 'state': 'active', 'messages_waiting': 'yes', 'voice_message': '1/0 (0/0)'}). [Mar 29 20:16:17] DEBUG[3499]: rls_element:346 validate: Validating MWI body ... [Mar 29 20:16:17] DEBUG[3499]: rls_element:380 __validate_content_id: Processing MWI body -- Inspecting 'Content-ID' element... [Mar 29 20:16:17] DEBUG[3499]: rls_element:389 __validate_content_id: Processing MWI body -- Validation check passed. MWI bodycontains a Content-ID. [Mar 29 20:16:17] DEBUG[3499]: rls_element:492 __validate_rlmi_body: Processing MWI body -- Inspecting RLMI body... [Mar 29 20:16:17] DEBUG[3499]: rls_element:500 __validate_rlmi_body: Processing MWI body -- Validation check passed. MWI part contains an RLMI body. [Mar 29 20:16:17] DEBUG[3499]: rls_element:460 __validate_resource_instance: Processing MWI body -- Inspecting RLMI body resource instances... [Mar 29 20:16:17] DEBUG[3499]: rls_element:476 __validate_resource_instance: Processing MWI body -- Validation check passed. RLMI body contains a resource instance for this MWI body. [Mar 29 20:16:17] DEBUG[3499]: rls_element:406 __validate_mwi_resource: Processing MWI body -- Inspecting MWI resource... [Mar 29 20:16:17] DEBUG[3499]: rls_element:445 __validate_mwi_resource: Processing MWI body -- Validation check passed for MWI resource ({'type': 'MWI', 'state': 'active', 'messages_waiting': 'yes', 'voice_message': '1/0 (0/0)'}). [Mar 29 20:16:17] DEBUG[3499]: rls_element:1098 __validate_content_ids: Processing RLS packet -- Inspecting number of Content-IDs received. Expecting: 2... [Mar 29 20:16:17] DEBUG[3499]: rls_element:1109 __validate_content_ids: Processing RLS packet -- Validation check passed. Received expected number of Content IDs. [Mar 29 20:16:17] INFO[3499]: rls_test:219 multipart_handler: Resource (1) validated successfully. [Mar 29 20:16:17] DEBUG[3499]: asterisk.pcap:832 datagramReceived: Forwarding packet to 127.0.0.1:5062 [Mar 29 20:16:17] DEBUG[3499]: asterisk.pcap:822 datagramReceived: Proxy received from 127.0.0.1:5062 SIP/2.0 200 OK Via: SIP/2.0/UDP 127.0.0.1:5060;rport;branch=z9hG4bKPje2b95925-3585-4077-9950-3e00b1021902 From: "sut" ;tag=660e5373-48ad-4a8c-aaa2-55b5138e11fa To: "sipp" ;tag=3611SIPpTag001 Call-ID: 1-3611@127.0.0.1 CSeq: 24688 NOTIFY Contact: Content-Length: 0 [Mar 29 20:16:17] DEBUG[3499]: asterisk.pcap:754 process_packet: Processing packet from 127.0.0.1:5062 [Mar 29 20:16:17] DEBUG[3499]: rls_test:36 filter_multipart_packet: Ignoring packet, is not a NOTIFY [Mar 29 20:16:17] DEBUG[3499]: asterisk.pcap:832 datagramReceived: Forwarding packet to 127.0.0.1:5060 [Mar 29 20:16:17] DEBUG[3499]: AMI:171 lineReceived: Line In: 'Event: TestEvent' [Mar 29 20:16:17] DEBUG[3499]: AMI:171 lineReceived: Line In: 'Privilege: reporting,all' [Mar 29 20:16:17] DEBUG[3499]: AMI:171 lineReceived: Line In: 'Type: StateChange' [Mar 29 20:16:17] DEBUG[3499]: AMI:171 lineReceived: Line In: 'State: SUBSCRIPTION_STATE_SET' [Mar 29 20:16:17] DEBUG[3499]: AMI:171 lineReceived: Line In: 'AppFile: res_pjsip_pubsub.c' [Mar 29 20:16:17] DEBUG[3499]: AMI:171 lineReceived: Line In: 'AppFunction: sip_subscription_send_request' [Mar 29 20:16:17] DEBUG[3499]: AMI:171 lineReceived: Line In: 'AppLine: 2044' [Mar 29 20:16:17] DEBUG[3499]: AMI:171 lineReceived: Line In: 'StateText: ACTIVE' [Mar 29 20:16:17] DEBUG[3499]: AMI:171 lineReceived: Line In: 'Endpoint: sipp' [Mar 29 20:16:17] DEBUG[3499]: AMI:171 lineReceived: Line In: '' [Mar 29 20:16:17] DEBUG[3499]: AMI:233 dispatchIncoming: Dispatch Incoming [Mar 29 20:16:17] DEBUG[3499]: AMI:263 dispatchIncoming: Incoming Message: {u'appfile': u'res_pjsip_pubsub.c', u'endpoint': u'sipp', u'appline': u'2044', u'appfunction': u'sip_subscription_send_request', u'state': u'SUBSCRIPTION_STATE_SET', u'statetext': u'ACTIVE', u'privilege': u'reporting,all', u'type': u'StateChange', u'event': u'TestEvent'} [Mar 29 20:16:17] DEBUG[3499]: AMI:171 lineReceived: Line In: '' [Mar 29 20:16:17] DEBUG[3499]: AMI:233 dispatchIncoming: Dispatch Incoming [Mar 29 20:16:17] DEBUG[3499]: AMI:263 dispatchIncoming: Incoming Message: {} [Mar 29 20:16:17] DEBUG[3499]: AMI:171 lineReceived: Line In: 'Event: TestEvent' [Mar 29 20:16:17] DEBUG[3499]: AMI:171 lineReceived: Line In: 'Privilege: reporting,all' [Mar 29 20:16:17] DEBUG[3499]: AMI:171 lineReceived: Line In: 'Type: StateChange' [Mar 29 20:16:17] DEBUG[3499]: AMI:171 lineReceived: Line In: 'State: SUBSCRIPTION_STATE_CHANGED' [Mar 29 20:16:17] DEBUG[3499]: AMI:171 lineReceived: Line In: 'AppFile: res_pjsip_pubsub.c' [Mar 29 20:16:17] DEBUG[3499]: AMI:171 lineReceived: Line In: 'AppFunction: serialized_send_notify' [Mar 29 20:16:17] DEBUG[3499]: AMI:171 lineReceived: Line In: 'AppLine: 2531' [Mar 29 20:16:17] DEBUG[3499]: AMI:171 lineReceived: Line In: 'Resource: mail_list' [Mar 29 20:16:17] DEBUG[3499]: AMI:171 lineReceived: Line In: '' [Mar 29 20:16:17] DEBUG[3499]: AMI:233 dispatchIncoming: Dispatch Incoming [Mar 29 20:16:17] DEBUG[3499]: AMI:263 dispatchIncoming: Incoming Message: {u'appfile': u'res_pjsip_pubsub.c', u'resource': u'mail_list', u'appline': u'2531', u'appfunction': u'serialized_send_notify', u'state': u'SUBSCRIPTION_STATE_CHANGED', u'privilege': u'reporting,all', u'type': u'StateChange', u'event': u'TestEvent'} [Mar 29 20:16:17] DEBUG[3499]: driver:93 on_subscription_state_change: State change to 3 [Mar 29 20:16:17] DEBUG[3499]: asterisk.pcap:822 datagramReceived: Proxy received from 127.0.0.1:5062 SUBSCRIBE sip:mail_list@127.0.0.1:5061 SIP/2.0 Via: SIP/2.0/UDP 127.0.0.1:5062;branch=z9hG4bK-3611-1-7 From: sipp ;tag=3611SIPpTag001 To: sut ;tag=660e5373-48ad-4a8c-aaa2-55b5138e11fa Call-ID: 1-3611@127.0.0.1 CSeq: 24689 SUBSCRIBE Contact: sip:sipp@127.0.0.1:5062 Max-Forwards: 70 Subject: Performance Test Event: message-summary Supported: eventlist Accept: application/rlmi+xml Accept: application/simple-message-summary Accept: multipart/related Expires: 3600 Content-Length: 0 [Mar 29 20:16:17] DEBUG[3499]: asterisk.pcap:754 process_packet: Processing packet from 127.0.0.1:5062 [Mar 29 20:16:17] DEBUG[3499]: rls_test:36 filter_multipart_packet: Ignoring packet, is not a NOTIFY [Mar 29 20:16:17] DEBUG[3499]: asterisk.pcap:832 datagramReceived: Forwarding packet to 127.0.0.1:5060 [Mar 29 20:16:18] DEBUG[3499]: asterisk.pcap:822 datagramReceived: Proxy received from 127.0.0.1:5060 SIP/2.0 200 OK Via: SIP/2.0/UDP 127.0.0.1:5062;rport=5061;received=127.0.0.1;branch=z9hG4bK-3611-1-7 Call-ID: 1-3611@127.0.0.1 From: "sipp" ;tag=3611SIPpTag001 To: "sut" ;tag=660e5373-48ad-4a8c-aaa2-55b5138e11fa CSeq: 24689 SUBSCRIBE Require: eventlist Expires: 3600 Contact: Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER Supported: 100rel, timer, replaces, norefersub Server: Asterisk PBX GIT-master-df22e5e Content-Length: 0 [Mar 29 20:16:18] DEBUG[3499]: asterisk.pcap:754 process_packet: Processing packet from 127.0.0.1:5060 [Mar 29 20:16:18] DEBUG[3499]: rls_test:36 filter_multipart_packet: Ignoring packet, is not a NOTIFY [Mar 29 20:16:18] DEBUG[3499]: asterisk.pcap:832 datagramReceived: Forwarding packet to 127.0.0.1:5062 [Mar 29 20:16:18] DEBUG[3499]: asterisk.pcap:822 datagramReceived: Proxy received from 127.0.0.1:5060 NOTIFY sip:sipp@127.0.0.1:5061 SIP/2.0 Via: SIP/2.0/UDP 127.0.0.1:5060;rport;branch=z9hG4bKPjc5124553-6026-446b-9f1c-ba6cfa3c906c From: "sut" ;tag=660e5373-48ad-4a8c-aaa2-55b5138e11fa To: "sipp" ;tag=3611SIPpTag001 Contact: Call-ID: 1-3611@127.0.0.1 CSeq: 24689 NOTIFY Event: message-summary Subscription-State: active;expires=3599 Allow-Events: presence, dialog, message-summary, refer Require: eventlist Max-Forwards: 70 User-Agent: Asterisk PBX GIT-master-df22e5e Content-Type: multipart/related;type="application/rlmi+xml";boundary=bdzqh Content-Length: 902 --bdzqh Content-ID: Content-Type: application/rlmi+xml Content-Length: 454 mail_list alice bob --bdzqh Content-ID: Content-Type: application/simple-message-summary Content-Length: 49 Messages-Waiting: yes Voice-Message: 1/0 (0/0) --bdzqh Content-ID: Content-Type: application/simple-message-summary Content-Length: 49 Messages-Waiting: yes Voice-Message: 1/0 (0/0) --bdzqh-- [Mar 29 20:16:18] DEBUG[3499]: asterisk.pcap:754 process_packet: Processing packet from 127.0.0.1:5060 [Mar 29 20:16:18] DEBUG[3499]: rls_test:211 multipart_handler: Validating Resource (2) of (4)... [Mar 29 20:16:18] DEBUG[3499]: rls_element:1007 validate: Validating RLS packet... [Mar 29 20:16:18] DEBUG[3499]: rls_element:1030 __validate_part_counts: Processing RLS packet -- Inspecting number of body parts received. Expecting: 2... [Mar 29 20:16:18] DEBUG[3499]: rls_element:1041 __validate_part_counts: Processing RLS packet -- Validation check passed. Received expected number of body parts. [Mar 29 20:16:18] DEBUG[3499]: rls_element:1045 __validate_part_counts: Processing RLS packet -- Inspecting number of RMLI parts received. Expecting: 1... [Mar 29 20:16:18] DEBUG[3499]: rls_element:1057 __validate_part_counts: Processing RLS packet -- Validation check passed. Received expected number of RMLI parts. [Mar 29 20:16:18] DEBUG[3499]: rls_element:622 validate: Validating RLMI list element... [Mar 29 20:16:18] DEBUG[3499]: rls_element:654 __validate_fullstate: Processing RLMI list element -- Inspecting RLMI fullstate value. Expecting: True... [Mar 29 20:16:18] DEBUG[3499]: rls_element:665 __validate_fullstate: Processing RLMI list element -- Validation check passed. Received expected RLMI fullstate value. [Mar 29 20:16:18] DEBUG[3499]: rls_element:676 __validate_name: Processing RLMI list element -- Inspecting number of 'name' elements. Expecting: 1. [Mar 29 20:16:18] DEBUG[3499]: rls_element:688 __validate_name: Processing RLMI list element -- Validation check passed. Received expected number of 'name' elements. [Mar 29 20:16:18] DEBUG[3499]: rls_element:706 __validate_resources: Processing RLMI list element -- Inspecting number of 'resource' elements. Expecting: 2. [Mar 29 20:16:18] DEBUG[3499]: rls_element:718 __validate_resources: Processing RLMI list element -- Validation check passed. Received expected number of 'resource' elements. [Mar 29 20:16:18] DEBUG[3499]: rls_element:760 __validate_rlmi_name: Processing RLMI list element -- Inspecting RLMI list name. Expecting: mail_list. [Mar 29 20:16:18] DEBUG[3499]: rls_element:771 __validate_rlmi_name: Processing RLMI list element -- Validation check passed. Received expected RLMI list name. [Mar 29 20:16:18] DEBUG[3499]: rls_element:738 __validate_rlmi_resources: Processing RLMI list element -- Validating children RLMI resource elements. [Mar 29 20:16:18] DEBUG[3499]: rls_element:830 validate: Validating RLMI resource... [Mar 29 20:16:18] DEBUG[3499]: rls_element:966 __validate_uri: Processing RLMI resource -- Inspecting 'uri' attribute... [Mar 29 20:16:18] DEBUG[3499]: rls_element:975 __validate_uri: Processing RLMI resource -- Validation check passed. Received expected 'uri' attribute. [Mar 29 20:16:18] DEBUG[3499]: rls_element:927 __validate_name: Processing RLMI resource -- Inspecting number of 'name' elements. Expecting: 1. [Mar 29 20:16:18] DEBUG[3499]: rls_element:939 __validate_name: Processing RLMI resource -- Validation check passed. Received expected number of 'name' elements. [Mar 29 20:16:18] DEBUG[3499]: rls_element:942 __validate_name: Processing RLMI resource -- Inspecting RLMI resource name... [Mar 29 20:16:18] DEBUG[3499]: rls_element:954 __validate_name: Processing RLMI list element -- Validation check passed. Received expected RLMI resource name. [Mar 29 20:16:18] DEBUG[3499]: rls_element:854 __validate_instance: Processing RLMI resource -- Inspecting number of 'instance' elements. Expecting: 1. [Mar 29 20:16:18] DEBUG[3499]: rls_element:865 __validate_instance: Processing RLMI resource -- Validation check passed. Received expected number of 'instance' elements. [Mar 29 20:16:18] DEBUG[3499]: rls_element:869 __validate_instance: Processing RLMI resource -- Inspecting RLMI resource instance attributes: state, id, and cid... [Mar 29 20:16:18] DEBUG[3499]: rls_element:890 __validate_instance: Processing RLMI resource -- Validation check passed. Received values for 'instance' element attributes: state, id and cid. [Mar 29 20:16:18] DEBUG[3499]: rls_element:898 __validate_instance: Processing RLMI resource -- Inspecting instance state. Expecting: active... [Mar 29 20:16:18] DEBUG[3499]: rls_element:907 __validate_instance: Processing RLMI resource -- Validation check passed. Received expected value for the RLMI instance state. [Mar 29 20:16:18] DEBUG[3499]: rls_element:830 validate: Validating RLMI resource... [Mar 29 20:16:18] DEBUG[3499]: rls_element:966 __validate_uri: Processing RLMI resource -- Inspecting 'uri' attribute... [Mar 29 20:16:18] DEBUG[3499]: rls_element:975 __validate_uri: Processing RLMI resource -- Validation check passed. Received expected 'uri' attribute. [Mar 29 20:16:18] DEBUG[3499]: rls_element:927 __validate_name: Processing RLMI resource -- Inspecting number of 'name' elements. Expecting: 1. [Mar 29 20:16:18] DEBUG[3499]: rls_element:939 __validate_name: Processing RLMI resource -- Validation check passed. Received expected number of 'name' elements. [Mar 29 20:16:18] DEBUG[3499]: rls_element:942 __validate_name: Processing RLMI resource -- Inspecting RLMI resource name... [Mar 29 20:16:18] DEBUG[3499]: rls_element:954 __validate_name: Processing RLMI list element -- Validation check passed. Received expected RLMI resource name. [Mar 29 20:16:18] DEBUG[3499]: rls_element:854 __validate_instance: Processing RLMI resource -- Inspecting number of 'instance' elements. Expecting: 1. [Mar 29 20:16:18] DEBUG[3499]: rls_element:865 __validate_instance: Processing RLMI resource -- Validation check passed. Received expected number of 'instance' elements. [Mar 29 20:16:18] DEBUG[3499]: rls_element:869 __validate_instance: Processing RLMI resource -- Inspecting RLMI resource instance attributes: state, id, and cid... [Mar 29 20:16:18] DEBUG[3499]: rls_element:890 __validate_instance: Processing RLMI resource -- Validation check passed. Received values for 'instance' element attributes: state, id and cid. [Mar 29 20:16:18] DEBUG[3499]: rls_element:898 __validate_instance: Processing RLMI resource -- Inspecting instance state. Expecting: active... [Mar 29 20:16:18] DEBUG[3499]: rls_element:907 __validate_instance: Processing RLMI resource -- Validation check passed. Received expected value for the RLMI instance state. [Mar 29 20:16:18] DEBUG[3499]: rls_element:346 validate: Validating MWI body ... [Mar 29 20:16:18] DEBUG[3499]: rls_element:380 __validate_content_id: Processing MWI body -- Inspecting 'Content-ID' element... [Mar 29 20:16:18] DEBUG[3499]: rls_element:389 __validate_content_id: Processing MWI body -- Validation check passed. MWI bodycontains a Content-ID. [Mar 29 20:16:18] DEBUG[3499]: rls_element:492 __validate_rlmi_body: Processing MWI body -- Inspecting RLMI body... [Mar 29 20:16:18] DEBUG[3499]: rls_element:500 __validate_rlmi_body: Processing MWI body -- Validation check passed. MWI part contains an RLMI body. [Mar 29 20:16:18] DEBUG[3499]: rls_element:460 __validate_resource_instance: Processing MWI body -- Inspecting RLMI body resource instances... [Mar 29 20:16:18] DEBUG[3499]: rls_element:476 __validate_resource_instance: Processing MWI body -- Validation check passed. RLMI body contains a resource instance for this MWI body. [Mar 29 20:16:18] DEBUG[3499]: rls_element:406 __validate_mwi_resource: Processing MWI body -- Inspecting MWI resource... [Mar 29 20:16:18] DEBUG[3499]: rls_element:445 __validate_mwi_resource: Processing MWI body -- Validation check passed for MWI resource ({'type': 'MWI', 'state': 'active', 'messages_waiting': 'yes', 'voice_message': '1/0 (0/0)'}). [Mar 29 20:16:18] DEBUG[3499]: rls_element:346 validate: Validating MWI body ... [Mar 29 20:16:18] DEBUG[3499]: rls_element:380 __validate_content_id: Processing MWI body -- Inspecting 'Content-ID' element... [Mar 29 20:16:18] DEBUG[3499]: rls_element:389 __validate_content_id: Processing MWI body -- Validation check passed. MWI bodycontains a Content-ID. [Mar 29 20:16:18] DEBUG[3499]: rls_element:492 __validate_rlmi_body: Processing MWI body -- Inspecting RLMI body... [Mar 29 20:16:18] DEBUG[3499]: rls_element:500 __validate_rlmi_body: Processing MWI body -- Validation check passed. MWI part contains an RLMI body. [Mar 29 20:16:18] DEBUG[3499]: rls_element:460 __validate_resource_instance: Processing MWI body -- Inspecting RLMI body resource instances... [Mar 29 20:16:18] DEBUG[3499]: rls_element:476 __validate_resource_instance: Processing MWI body -- Validation check passed. RLMI body contains a resource instance for this MWI body. [Mar 29 20:16:18] DEBUG[3499]: rls_element:406 __validate_mwi_resource: Processing MWI body -- Inspecting MWI resource... [Mar 29 20:16:18] DEBUG[3499]: rls_element:445 __validate_mwi_resource: Processing MWI body -- Validation check passed for MWI resource ({'type': 'MWI', 'state': 'active', 'messages_waiting': 'yes', 'voice_message': '1/0 (0/0)'}). [Mar 29 20:16:18] DEBUG[3499]: rls_element:1098 __validate_content_ids: Processing RLS packet -- Inspecting number of Content-IDs received. Expecting: 2... [Mar 29 20:16:18] DEBUG[3499]: rls_element:1109 __validate_content_ids: Processing RLS packet -- Validation check passed. Received expected number of Content IDs. [Mar 29 20:16:18] INFO[3499]: rls_test:219 multipart_handler: Resource (2) validated successfully. [Mar 29 20:16:18] DEBUG[3499]: asterisk.pcap:832 datagramReceived: Forwarding packet to 127.0.0.1:5062 [Mar 29 20:16:18] DEBUG[3499]: asterisk.pcap:822 datagramReceived: Proxy received from 127.0.0.1:5062 SIP/2.0 200 OK Via: SIP/2.0/UDP 127.0.0.1:5060;rport;branch=z9hG4bKPjc5124553-6026-446b-9f1c-ba6cfa3c906c From: "sut" ;tag=660e5373-48ad-4a8c-aaa2-55b5138e11fa To: "sipp" ;tag=3611SIPpTag001 Call-ID: 1-3611@127.0.0.1 CSeq: 24689 NOTIFY Contact: Content-Length: 0 [Mar 29 20:16:18] DEBUG[3499]: asterisk.pcap:754 process_packet: Processing packet from 127.0.0.1:5062 [Mar 29 20:16:18] DEBUG[3499]: rls_test:36 filter_multipart_packet: Ignoring packet, is not a NOTIFY [Mar 29 20:16:18] DEBUG[3499]: asterisk.pcap:832 datagramReceived: Forwarding packet to 127.0.0.1:5060 [Mar 29 20:16:18] DEBUG[3499]: AMI:171 lineReceived: Line In: 'Event: TestEvent' [Mar 29 20:16:18] DEBUG[3499]: AMI:171 lineReceived: Line In: 'Privilege: reporting,all' [Mar 29 20:16:18] DEBUG[3499]: AMI:171 lineReceived: Line In: 'Type: StateChange' [Mar 29 20:16:18] DEBUG[3499]: AMI:171 lineReceived: Line In: 'State: SUBSCRIPTION_STATE_SET' [Mar 29 20:16:18] DEBUG[3499]: AMI:171 lineReceived: Line In: 'AppFile: res_pjsip_pubsub.c' [Mar 29 20:16:18] DEBUG[3499]: AMI:171 lineReceived: Line In: 'AppFunction: sip_subscription_send_request' [Mar 29 20:16:18] DEBUG[3499]: AMI:171 lineReceived: Line In: 'AppLine: 2044' [Mar 29 20:16:18] DEBUG[3499]: AMI:171 lineReceived: Line In: 'StateText: ACTIVE' [Mar 29 20:16:18] DEBUG[3499]: AMI:171 lineReceived: Line In: 'Endpoint: sipp' [Mar 29 20:16:18] DEBUG[3499]: AMI:171 lineReceived: Line In: '' [Mar 29 20:16:18] DEBUG[3499]: AMI:233 dispatchIncoming: Dispatch Incoming [Mar 29 20:16:18] DEBUG[3499]: AMI:263 dispatchIncoming: Incoming Message: {u'appfile': u'res_pjsip_pubsub.c', u'endpoint': u'sipp', u'appline': u'2044', u'appfunction': u'sip_subscription_send_request', u'state': u'SUBSCRIPTION_STATE_SET', u'statetext': u'ACTIVE', u'privilege': u'reporting,all', u'type': u'StateChange', u'event': u'TestEvent'} [Mar 29 20:16:18] DEBUG[3499]: AMI:171 lineReceived: Line In: '' [Mar 29 20:16:18] DEBUG[3499]: AMI:233 dispatchIncoming: Dispatch Incoming [Mar 29 20:16:18] DEBUG[3499]: AMI:263 dispatchIncoming: Incoming Message: {} [Mar 29 20:16:18] DEBUG[3499]: AMI:171 lineReceived: Line In: 'Event: TestEvent' [Mar 29 20:16:18] DEBUG[3499]: AMI:171 lineReceived: Line In: 'Privilege: reporting,all' [Mar 29 20:16:18] DEBUG[3499]: AMI:171 lineReceived: Line In: 'Type: StateChange' [Mar 29 20:16:18] DEBUG[3499]: AMI:171 lineReceived: Line In: 'State: SUBSCRIPTION_REFRESHED' [Mar 29 20:16:18] DEBUG[3499]: AMI:171 lineReceived: Line In: 'AppFile: res_pjsip_pubsub.c' [Mar 29 20:16:18] DEBUG[3499]: AMI:171 lineReceived: Line In: 'AppFunction: pubsub_on_refresh_timeout' [Mar 29 20:16:18] DEBUG[3499]: AMI:171 lineReceived: Line In: 'AppLine: 3929' [Mar 29 20:16:18] DEBUG[3499]: AMI:171 lineReceived: Line In: 'Resource: mail_list' [Mar 29 20:16:18] DEBUG[3499]: AMI:171 lineReceived: Line In: '' [Mar 29 20:16:18] DEBUG[3499]: AMI:233 dispatchIncoming: Dispatch Incoming [Mar 29 20:16:18] DEBUG[3499]: AMI:263 dispatchIncoming: Incoming Message: {u'appfile': u'res_pjsip_pubsub.c', u'resource': u'mail_list', u'appline': u'3929', u'appfunction': u'pubsub_on_refresh_timeout', u'state': u'SUBSCRIPTION_REFRESHED', u'privilege': u'reporting,all', u'type': u'StateChange', u'event': u'TestEvent'} [Mar 29 20:16:18] DEBUG[3499]: driver:109 on_subscription_refreshed: State change to 4 [Mar 29 20:16:18] DEBUG[3499]: AMI:361 sendMessage: MSG OUT: {'action': 'MWIUpdate', 'oldmessages': '0', 'newmessages': '2', 'actionid': 'ff3bb070a8b4-140033481909600-4', 'mailbox': 'alice'} [Mar 29 20:16:18] DEBUG[3499]: AMI:361 sendMessage: MSG OUT: {'action': 'MWIUpdate', 'oldmessages': '0', 'newmessages': '2', 'actionid': 'ff3bb070a8b4-140033481909600-5', 'mailbox': 'bob'} [Mar 29 20:16:18] DEBUG[3499]: AMI:171 lineReceived: Line In: 'Response: Success' [Mar 29 20:16:18] DEBUG[3499]: AMI:171 lineReceived: Line In: 'ActionID: ff3bb070a8b4-140033481909600-4' [Mar 29 20:16:18] DEBUG[3499]: AMI:171 lineReceived: Line In: '' [Mar 29 20:16:18] DEBUG[3499]: AMI:233 dispatchIncoming: Dispatch Incoming [Mar 29 20:16:18] DEBUG[3499]: AMI:263 dispatchIncoming: Incoming Message: {u'response': u'Success', u'actionid': u'ff3bb070a8b4-140033481909600-4'} [Mar 29 20:16:18] DEBUG[3499]: AMI:171 lineReceived: Line In: 'Response: Success' [Mar 29 20:16:18] DEBUG[3499]: AMI:171 lineReceived: Line In: 'ActionID: ff3bb070a8b4-140033481909600-5' [Mar 29 20:16:18] DEBUG[3499]: AMI:171 lineReceived: Line In: '' [Mar 29 20:16:18] DEBUG[3499]: AMI:233 dispatchIncoming: Dispatch Incoming [Mar 29 20:16:18] DEBUG[3499]: AMI:263 dispatchIncoming: Incoming Message: {u'response': u'Success', u'actionid': u'ff3bb070a8b4-140033481909600-5'} [Mar 29 20:16:18] DEBUG[3499]: AMI:171 lineReceived: Line In: 'Event: MessageWaiting' [Mar 29 20:16:18] DEBUG[3499]: AMI:171 lineReceived: Line In: 'Privilege: call,all' [Mar 29 20:16:18] DEBUG[3499]: AMI:171 lineReceived: Line In: 'Mailbox: alice' [Mar 29 20:16:18] DEBUG[3499]: AMI:171 lineReceived: Line In: 'Waiting: 1' [Mar 29 20:16:18] DEBUG[3499]: AMI:171 lineReceived: Line In: 'New: 2' [Mar 29 20:16:18] DEBUG[3499]: AMI:171 lineReceived: Line In: 'Old: 0' [Mar 29 20:16:18] DEBUG[3499]: AMI:171 lineReceived: Line In: '' [Mar 29 20:16:18] DEBUG[3499]: AMI:233 dispatchIncoming: Dispatch Incoming [Mar 29 20:16:18] DEBUG[3499]: AMI:263 dispatchIncoming: Incoming Message: {u'old': u'0', u'mailbox': u'alice', u'waiting': u'1', u'privilege': u'call,all', u'new': u'2', u'event': u'MessageWaiting'} [Mar 29 20:16:18] DEBUG[3499]: AMI:171 lineReceived: Line In: 'Event: MessageWaiting' [Mar 29 20:16:18] DEBUG[3499]: AMI:171 lineReceived: Line In: 'Privilege: call,all' [Mar 29 20:16:18] DEBUG[3499]: AMI:171 lineReceived: Line In: 'Mailbox: bob' [Mar 29 20:16:18] DEBUG[3499]: AMI:171 lineReceived: Line In: 'Waiting: 1' [Mar 29 20:16:18] DEBUG[3499]: AMI:171 lineReceived: Line In: 'New: 2' [Mar 29 20:16:18] DEBUG[3499]: AMI:171 lineReceived: Line In: 'Old: 0' [Mar 29 20:16:18] DEBUG[3499]: AMI:171 lineReceived: Line In: '' [Mar 29 20:16:18] DEBUG[3499]: AMI:233 dispatchIncoming: Dispatch Incoming [Mar 29 20:16:18] DEBUG[3499]: AMI:263 dispatchIncoming: Incoming Message: {u'old': u'0', u'mailbox': u'bob', u'waiting': u'1', u'privilege': u'call,all', u'new': u'2', u'event': u'MessageWaiting'} [Mar 29 20:16:18] DEBUG[3499]: asterisk.sipp:500 outReceived: Received from SIPp scenario subscribe.xml: ------------------------------ Scenario Screen -------- [1-9]: Change Screen -- Call-rate(length) Port Total-time Total-calls Remote-host 10.0(0 ms)/1.000s 5062 6.00 s 1 127.0.0.1:5061(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 200 <---------- 1 0 0 0 NOTIFY <---------- 1 0 0 0 200 ----------> 1 0 NOTIFY <---------- 0 0 0 0 200 ----------> 0 0 SUBSCRIBE ----------> 0 0 0 200 <---------- 0 0 0 0 NOTIFY <---------- 0 0 0 0 200 ----------> 0 0 ------- Waiting for active calls to end. Press [q] again to force exit. ------- [Mar 29 20:16:19] DEBUG[3499]: asterisk.sipp:500 outReceived: Received from SIPp scenario subscribe.xml: ------------------------------ Scenario Screen -------- [1-9]: Change Screen -- Call-rate(length) Port Total-time Total-calls Remote-host 10.0(0 ms)/1.000s 5062 7.01 s 1 127.0.0.1:5061(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 200 <---------- 1 0 0 0 NOTIFY <---------- 1 0 0 0 200 ----------> 1 0 NOTIFY <---------- 0 0 0 0 200 ----------> 0 0 SUBSCRIBE ----------> 0 0 0 200 <---------- 0 0 0 0 NOTIFY <---------- 0 0 0 0 200 ----------> 0 0 ------- Waiting for active calls to end. Press [q] again to force exit. ------- [Mar 29 20:16:20] DEBUG[3499]: asterisk.sipp:500 outReceived: Received from SIPp scenario subscribe.xml: ------------------------------ Scenario Screen -------- [1-9]: Change Screen -- Call-rate(length) Port Total-time Total-calls Remote-host 10.0(0 ms)/1.000s 5062 8.01 s 1 127.0.0.1:5061(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 200 <---------- 1 0 0 0 NOTIFY <---------- 1 0 0 0 200 ----------> 1 0 NOTIFY <---------- 0 0 0 0 200 ----------> 0 0 SUBSCRIBE ----------> 0 0 0 200 <---------- 0 0 0 0 NOTIFY <---------- 0 0 0 0 200 ----------> 0 0 ------- Waiting for active calls to end. Press [q] again to force exit. ------- [Mar 29 20:16:21] DEBUG[3499]: asterisk.sipp:500 outReceived: Received from SIPp scenario subscribe.xml: ------------------------------ Scenario Screen -------- [1-9]: Change Screen -- Call-rate(length) Port Total-time Total-calls Remote-host 10.0(0 ms)/1.000s 5062 9.01 s 1 127.0.0.1:5061(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 200 <---------- 1 0 0 0 NOTIFY <---------- 1 0 0 0 200 ----------> 1 0 NOTIFY <---------- 0 0 0 0 200 ----------> 0 0 SUBSCRIBE ----------> 0 0 0 200 <---------- 0 0 0 0 NOTIFY <---------- 0 0 0 0 200 ----------> 0 0 ------- Waiting for active calls to end. Press [q] again to force exit. ------- [Mar 29 20:16:22] DEBUG[3499]: asterisk.sipp:500 outReceived: Received from SIPp scenario subscribe.xml: ------------------------------ Scenario Screen -------- [1-9]: Change Screen -- Call-rate(length) Port Total-time Total-calls Remote-host 10.0(0 ms)/1.000s 5062 10.01 s 1 127.0.0.1:5061(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 200 <---------- 1 0 0 0 NOTIFY <---------- 1 0 0 0 200 ----------> 1 0 NOTIFY <---------- 0 0 0 0 200 ----------> 0 0 SUBSCRIBE ----------> 0 0 0 200 <---------- 0 0 0 0 NOTIFY <---------- 0 0 0 0 200 ----------> 0 0 ------- Waiting for active calls to end. Press [q] again to force exit. ------- [Mar 29 20:16:23] DEBUG[3499]: asterisk.pcap:822 datagramReceived: Proxy received from 127.0.0.1:5060 NOTIFY sip:127.0.0.1:5061 SIP/2.0 Via: SIP/2.0/UDP 127.0.0.1:5060;rport;branch=z9hG4bKPj2c867d59-7360-4682-8bf7-0250152762c8 From: "sut" ;tag=660e5373-48ad-4a8c-aaa2-55b5138e11fa To: "sipp" ;tag=3611SIPpTag001 Contact: Call-ID: 1-3611@127.0.0.1 CSeq: 24690 NOTIFY Event: message-summary Subscription-State: active;expires=3594 Allow-Events: presence, dialog, message-summary, refer Require: eventlist Max-Forwards: 70 User-Agent: Asterisk PBX GIT-master-df22e5e Content-Type: multipart/related;type="application/rlmi+xml";boundary=fqkki Content-Length: 903 --fqkki Content-ID: Content-Type: application/rlmi+xml Content-Length: 455 mail_list alice bob --fqkki Content-ID: Content-Type: application/simple-message-summary Content-Length: 49 Messages-Waiting: yes Voice-Message: 2/0 (0/0) --fqkki Content-ID: Content-Type: application/simple-message-summary Content-Length: 49 Messages-Waiting: yes Voice-Message: 2/0 (0/0) --fqkki-- [Mar 29 20:16:23] DEBUG[3499]: asterisk.pcap:754 process_packet: Processing packet from 127.0.0.1:5060 [Mar 29 20:16:23] DEBUG[3499]: rls_test:211 multipart_handler: Validating Resource (3) of (4)... [Mar 29 20:16:23] DEBUG[3499]: rls_element:1007 validate: Validating RLS packet... [Mar 29 20:16:23] DEBUG[3499]: rls_element:1030 __validate_part_counts: Processing RLS packet -- Inspecting number of body parts received. Expecting: 2... [Mar 29 20:16:23] DEBUG[3499]: rls_element:1041 __validate_part_counts: Processing RLS packet -- Validation check passed. Received expected number of body parts. [Mar 29 20:16:23] DEBUG[3499]: rls_element:1045 __validate_part_counts: Processing RLS packet -- Inspecting number of RMLI parts received. Expecting: 1... [Mar 29 20:16:23] DEBUG[3499]: rls_element:1057 __validate_part_counts: Processing RLS packet -- Validation check passed. Received expected number of RMLI parts. [Mar 29 20:16:23] DEBUG[3499]: rls_element:622 validate: Validating RLMI list element... [Mar 29 20:16:23] DEBUG[3499]: rls_element:654 __validate_fullstate: Processing RLMI list element -- Inspecting RLMI fullstate value. Expecting: False... [Mar 29 20:16:23] DEBUG[3499]: rls_element:665 __validate_fullstate: Processing RLMI list element -- Validation check passed. Received expected RLMI fullstate value. [Mar 29 20:16:23] DEBUG[3499]: rls_element:676 __validate_name: Processing RLMI list element -- Inspecting number of 'name' elements. Expecting: 1. [Mar 29 20:16:23] DEBUG[3499]: rls_element:688 __validate_name: Processing RLMI list element -- Validation check passed. Received expected number of 'name' elements. [Mar 29 20:16:23] DEBUG[3499]: rls_element:706 __validate_resources: Processing RLMI list element -- Inspecting number of 'resource' elements. Expecting: 2. [Mar 29 20:16:23] DEBUG[3499]: rls_element:718 __validate_resources: Processing RLMI list element -- Validation check passed. Received expected number of 'resource' elements. [Mar 29 20:16:23] DEBUG[3499]: rls_element:760 __validate_rlmi_name: Processing RLMI list element -- Inspecting RLMI list name. Expecting: mail_list. [Mar 29 20:16:23] DEBUG[3499]: rls_element:771 __validate_rlmi_name: Processing RLMI list element -- Validation check passed. Received expected RLMI list name. [Mar 29 20:16:23] DEBUG[3499]: rls_element:738 __validate_rlmi_resources: Processing RLMI list element -- Validating children RLMI resource elements. [Mar 29 20:16:23] DEBUG[3499]: rls_element:830 validate: Validating RLMI resource... [Mar 29 20:16:23] DEBUG[3499]: rls_element:966 __validate_uri: Processing RLMI resource -- Inspecting 'uri' attribute... [Mar 29 20:16:23] DEBUG[3499]: rls_element:975 __validate_uri: Processing RLMI resource -- Validation check passed. Received expected 'uri' attribute. [Mar 29 20:16:23] DEBUG[3499]: rls_element:927 __validate_name: Processing RLMI resource -- Inspecting number of 'name' elements. Expecting: 1. [Mar 29 20:16:23] DEBUG[3499]: rls_element:939 __validate_name: Processing RLMI resource -- Validation check passed. Received expected number of 'name' elements. [Mar 29 20:16:23] DEBUG[3499]: rls_element:942 __validate_name: Processing RLMI resource -- Inspecting RLMI resource name... [Mar 29 20:16:23] DEBUG[3499]: rls_element:954 __validate_name: Processing RLMI list element -- Validation check passed. Received expected RLMI resource name. [Mar 29 20:16:23] DEBUG[3499]: rls_element:854 __validate_instance: Processing RLMI resource -- Inspecting number of 'instance' elements. Expecting: 1. [Mar 29 20:16:23] DEBUG[3499]: rls_element:865 __validate_instance: Processing RLMI resource -- Validation check passed. Received expected number of 'instance' elements. [Mar 29 20:16:23] DEBUG[3499]: rls_element:869 __validate_instance: Processing RLMI resource -- Inspecting RLMI resource instance attributes: state, id, and cid... [Mar 29 20:16:23] DEBUG[3499]: rls_element:890 __validate_instance: Processing RLMI resource -- Validation check passed. Received values for 'instance' element attributes: state, id and cid. [Mar 29 20:16:23] DEBUG[3499]: rls_element:898 __validate_instance: Processing RLMI resource -- Inspecting instance state. Expecting: active... [Mar 29 20:16:23] DEBUG[3499]: rls_element:907 __validate_instance: Processing RLMI resource -- Validation check passed. Received expected value for the RLMI instance state. [Mar 29 20:16:23] DEBUG[3499]: rls_element:830 validate: Validating RLMI resource... [Mar 29 20:16:23] DEBUG[3499]: rls_element:966 __validate_uri: Processing RLMI resource -- Inspecting 'uri' attribute... [Mar 29 20:16:23] DEBUG[3499]: rls_element:975 __validate_uri: Processing RLMI resource -- Validation check passed. Received expected 'uri' attribute. [Mar 29 20:16:23] DEBUG[3499]: rls_element:927 __validate_name: Processing RLMI resource -- Inspecting number of 'name' elements. Expecting: 1. [Mar 29 20:16:23] DEBUG[3499]: rls_element:939 __validate_name: Processing RLMI resource -- Validation check passed. Received expected number of 'name' elements. [Mar 29 20:16:23] DEBUG[3499]: rls_element:942 __validate_name: Processing RLMI resource -- Inspecting RLMI resource name... [Mar 29 20:16:23] DEBUG[3499]: rls_element:954 __validate_name: Processing RLMI list element -- Validation check passed. Received expected RLMI resource name. [Mar 29 20:16:23] DEBUG[3499]: rls_element:854 __validate_instance: Processing RLMI resource -- Inspecting number of 'instance' elements. Expecting: 1. [Mar 29 20:16:23] DEBUG[3499]: rls_element:865 __validate_instance: Processing RLMI resource -- Validation check passed. Received expected number of 'instance' elements. [Mar 29 20:16:23] DEBUG[3499]: rls_element:869 __validate_instance: Processing RLMI resource -- Inspecting RLMI resource instance attributes: state, id, and cid... [Mar 29 20:16:23] DEBUG[3499]: rls_element:890 __validate_instance: Processing RLMI resource -- Validation check passed. Received values for 'instance' element attributes: state, id and cid. [Mar 29 20:16:23] DEBUG[3499]: rls_element:898 __validate_instance: Processing RLMI resource -- Inspecting instance state. Expecting: active... [Mar 29 20:16:23] DEBUG[3499]: rls_element:907 __validate_instance: Processing RLMI resource -- Validation check passed. Received expected value for the RLMI instance state. [Mar 29 20:16:23] DEBUG[3499]: rls_element:346 validate: Validating MWI body ... [Mar 29 20:16:23] DEBUG[3499]: rls_element:380 __validate_content_id: Processing MWI body -- Inspecting 'Content-ID' element... [Mar 29 20:16:23] DEBUG[3499]: rls_element:389 __validate_content_id: Processing MWI body -- Validation check passed. MWI bodycontains a Content-ID. [Mar 29 20:16:23] DEBUG[3499]: rls_element:492 __validate_rlmi_body: Processing MWI body -- Inspecting RLMI body... [Mar 29 20:16:23] DEBUG[3499]: rls_element:500 __validate_rlmi_body: Processing MWI body -- Validation check passed. MWI part contains an RLMI body. [Mar 29 20:16:23] DEBUG[3499]: rls_element:460 __validate_resource_instance: Processing MWI body -- Inspecting RLMI body resource instances... [Mar 29 20:16:23] DEBUG[3499]: rls_element:476 __validate_resource_instance: Processing MWI body -- Validation check passed. RLMI body contains a resource instance for this MWI body. [Mar 29 20:16:23] DEBUG[3499]: rls_element:406 __validate_mwi_resource: Processing MWI body -- Inspecting MWI resource... [Mar 29 20:16:23] DEBUG[3499]: rls_element:445 __validate_mwi_resource: Processing MWI body -- Validation check passed for MWI resource ({'type': 'MWI', 'state': 'active', 'messages_waiting': 'yes', 'voice_message': '2/0 (0/0)'}). [Mar 29 20:16:23] DEBUG[3499]: rls_element:346 validate: Validating MWI body ... [Mar 29 20:16:23] DEBUG[3499]: rls_element:380 __validate_content_id: Processing MWI body -- Inspecting 'Content-ID' element... [Mar 29 20:16:23] DEBUG[3499]: rls_element:389 __validate_content_id: Processing MWI body -- Validation check passed. MWI bodycontains a Content-ID. [Mar 29 20:16:23] DEBUG[3499]: rls_element:492 __validate_rlmi_body: Processing MWI body -- Inspecting RLMI body... [Mar 29 20:16:23] DEBUG[3499]: rls_element:500 __validate_rlmi_body: Processing MWI body -- Validation check passed. MWI part contains an RLMI body. [Mar 29 20:16:23] DEBUG[3499]: rls_element:460 __validate_resource_instance: Processing MWI body -- Inspecting RLMI body resource instances... [Mar 29 20:16:23] DEBUG[3499]: rls_element:476 __validate_resource_instance: Processing MWI body -- Validation check passed. RLMI body contains a resource instance for this MWI body. [Mar 29 20:16:23] DEBUG[3499]: rls_element:406 __validate_mwi_resource: Processing MWI body -- Inspecting MWI resource... [Mar 29 20:16:23] DEBUG[3499]: rls_element:445 __validate_mwi_resource: Processing MWI body -- Validation check passed for MWI resource ({'type': 'MWI', 'state': 'active', 'messages_waiting': 'yes', 'voice_message': '2/0 (0/0)'}). [Mar 29 20:16:23] DEBUG[3499]: rls_element:1098 __validate_content_ids: Processing RLS packet -- Inspecting number of Content-IDs received. Expecting: 2... [Mar 29 20:16:23] DEBUG[3499]: rls_element:1109 __validate_content_ids: Processing RLS packet -- Validation check passed. Received expected number of Content IDs. [Mar 29 20:16:23] INFO[3499]: rls_test:219 multipart_handler: Resource (3) validated successfully. [Mar 29 20:16:23] DEBUG[3499]: asterisk.pcap:832 datagramReceived: Forwarding packet to 127.0.0.1:5062 [Mar 29 20:16:23] DEBUG[3499]: asterisk.pcap:822 datagramReceived: Proxy received from 127.0.0.1:5062 SIP/2.0 200 OK Via: SIP/2.0/UDP 127.0.0.1:5060;rport;branch=z9hG4bKPj2c867d59-7360-4682-8bf7-0250152762c8 From: "sut" ;tag=660e5373-48ad-4a8c-aaa2-55b5138e11fa To: "sipp" ;tag=3611SIPpTag001 Call-ID: 1-3611@127.0.0.1 CSeq: 24690 NOTIFY Contact: Content-Length: 0 [Mar 29 20:16:23] DEBUG[3499]: asterisk.pcap:754 process_packet: Processing packet from 127.0.0.1:5062 [Mar 29 20:16:23] DEBUG[3499]: rls_test:36 filter_multipart_packet: Ignoring packet, is not a NOTIFY [Mar 29 20:16:23] DEBUG[3499]: asterisk.pcap:832 datagramReceived: Forwarding packet to 127.0.0.1:5060 [Mar 29 20:16:23] DEBUG[3499]: asterisk.pcap:822 datagramReceived: Proxy received from 127.0.0.1:5062 SUBSCRIBE sip:mail_list@127.0.0.1:5061 SIP/2.0 Via: SIP/2.0/UDP 127.0.0.1:5062;branch=z9hG4bK-3611-1-13 From: sipp ;tag=3611SIPpTag001 To: sut ;tag=660e5373-48ad-4a8c-aaa2-55b5138e11fa Call-ID: 1-3611@127.0.0.1 CSeq: 24691 SUBSCRIBE Contact: sip:sipp@127.0.0.1:5062 Max-Forwards: 70 Subject: Performance Test Event: message-summary Supported: eventlist Accept: application/rlmi+xml Accept: application/simple-message-summary Accept: multipart/related Expires: 0 Content-Length: 0 [Mar 29 20:16:23] DEBUG[3499]: asterisk.pcap:754 process_packet: Processing packet from 127.0.0.1:5062 [Mar 29 20:16:23] DEBUG[3499]: rls_test:36 filter_multipart_packet: Ignoring packet, is not a NOTIFY [Mar 29 20:16:23] DEBUG[3499]: asterisk.pcap:832 datagramReceived: Forwarding packet to 127.0.0.1:5060 [Mar 29 20:16:23] DEBUG[3499]: asterisk.sipp:500 outReceived: Received from SIPp scenario subscribe.xml: ------------------------------ Scenario Screen -------- [1-9]: Change Screen -- Call-rate(length) Port Total-time Total-calls Remote-host 10.0(0 ms)/1.000s 5062 11.01 s 1 127.0.0.1:5061(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 200 <---------- 1 0 0 0 NOTIFY <---------- 1 0 0 0 200 ----------> 1 0 NOTIFY <---------- 1 0 0 0 200 ----------> 1 0 SUBSCRIBE ----------> 1 0 0 200 <---------- 0 0 0 0 NOTIFY <---------- 0 0 0 0 200 ----------> 0 0 ------- Waiting for active calls to end. Press [q] again to force exit. ------- [Mar 29 20:16:24] DEBUG[3499]: asterisk.pcap:822 datagramReceived: Proxy received from 127.0.0.1:5060 NOTIFY sip:127.0.0.1:5061 SIP/2.0 Via: SIP/2.0/UDP 127.0.0.1:5060;rport;branch=z9hG4bKPj2c867d59-7360-4682-8bf7-0250152762c8 From: "sut" ;tag=660e5373-48ad-4a8c-aaa2-55b5138e11fa To: "sipp" ;tag=3611SIPpTag001 Contact: Call-ID: 1-3611@127.0.0.1 CSeq: 24690 NOTIFY Event: message-summary Subscription-State: active;expires=3594 Allow-Events: presence, dialog, message-summary, refer Require: eventlist Max-Forwards: 70 User-Agent: Asterisk PBX GIT-master-df22e5e Content-Type: multipart/related;type="application/rlmi+xml";boundary=fqkki Content-Length: 903 --fqkki Content-ID: Content-Type: application/rlmi+xml Content-Length: 455 mail_list alice bob --fqkki Content-ID: Content-Type: application/simple-message-summary Content-Length: 49 Messages-Waiting: yes Voice-Message: 2/0 (0/0) --fqkki Content-ID: Content-Type: application/simple-message-summary Content-Length: 49 Messages-Waiting: yes Voice-Message: 2/0 (0/0) --fqkki-- [Mar 29 20:16:24] DEBUG[3499]: asterisk.pcap:754 process_packet: Processing packet from 127.0.0.1:5060 [Mar 29 20:16:24] DEBUG[3499]: rls_test:188 multipart_handler: Out of order or retransmission; dropping [Mar 29 20:16:24] DEBUG[3499]: asterisk.pcap:832 datagramReceived: Forwarding packet to 127.0.0.1:5062 [Mar 29 20:16:24] DEBUG[3499]: asterisk.pcap:822 datagramReceived: Proxy received from 127.0.0.1:5062 BYE sip:sipp@127.0.0.1 SIP/2.0 Via: SIP/2.0/UDP 127.0.0.1:5062;branch=z9hG4bK-3611-1--1 From: "sut" ;tag=660e5373-48ad-4a8c-aaa2-55b5138e11fa To: "sipp" ;tag=3611SIPpTag001 Call-ID: 1-3611@127.0.0.1 CSeq: 24691 BYE Max-Forwards: 70 Contact: Content-Length: 0 [Mar 29 20:16:24] DEBUG[3499]: asterisk.pcap:754 process_packet: Processing packet from 127.0.0.1:5062 [Mar 29 20:16:24] DEBUG[3499]: rls_test:36 filter_multipart_packet: Ignoring packet, is not a NOTIFY [Mar 29 20:16:24] DEBUG[3499]: asterisk.pcap:832 datagramReceived: Forwarding packet to 127.0.0.1:5060 [Mar 29 20:16:24] DEBUG[3499]: asterisk.sipp:500 outReceived: Received from SIPp scenario subscribe.xml: ------------------------------ Scenario Screen -------- [1-9]: Change Screen -- Call-rate(length) Port Total-time Total-calls Remote-host 10.0(0 ms)/1.000s 5062 11.49 s 1 127.0.0.1:5061(UDP) Call limit reached (-m 1), 0.473 s period 1 ms scheduler resolution 0 calls (limit 30) Peak was 1 calls, after 0 s 0 Running, 3 Paused, 1 Woken up 0 dead call msg (discarded) 0 out-of-call msg (discarded) 1 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 200 <---------- 1 0 0 0 NOTIFY <---------- 1 0 0 0 200 ----------> 1 0 NOTIFY <---------- 1 0 0 0 200 ----------> 1 0 SUBSCRIBE ----------> 1 0 0 200 <---------- 0 0 0 1 NOTIFY <---------- 0 0 0 0 200 ----------> 0 0 ------------------------------ Test Terminated -------------------------------- ------------------------------ Scenario Screen -------- [1-9]: Change Screen -- Call-rate(length) Port Total-time Total-calls Remote-host 10.0(0 ms)/1.000s 5062 11.49 s 1 127.0.0.1:5061(UDP) Call limit reached (-m 1), 0.000 s period 0 ms scheduler resolution 0 calls (limit 30) Peak was 1 calls, after 0 s 0 Running, 3 Paused, 0 Woken up 0 dead call msg (discarded) 0 out-of-call msg (discarded) 1 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 200 <---------- 1 0 0 0 NOTIFY <---------- 1 0 0 0 200 ----------> 1 0 NOTIFY <---------- 1 0 0 0 200 ----------> 1 0 SUBSCRIBE ----------> 1 0 0 200 <---------- 0 0 0 1 NOTIFY <---------- 0 0 0 0 200 ----------> 0 0 ------------------------------ Test Terminated -------------------------------- ----------------------------- Statistics Screen ------- [1-9]: Change Screen -- Start Time | 2022-03-29 20:16:12.562804 1648584972.562804 Last Reset Time | 2022-03-29 20:16:24.054436 1648584984.054436 Current Time | 2022-03-29 20:16:24.054468 1648584984.054468 -------------------------+---------------------------+-------------------------- Counter Name | Periodic value | Cumulative value -------------------------+---------------------------+-------------------------- Elapsed Time | 00:00:00:000000 | 00:00:11:491000 Call Rate | 0.000 cps | 0.087 cps -------------------------+---------------------------+-------------------------- Incoming call created | 0 | 0 OutGoing call created | 0 | 1 Total Call created | | 1 Current Call | 0 | -------------------------+---------------------------+-------------------------- Successful call | 0 | 0 Failed call | 0 | 1 -------------------------+---------------------------+-------------------------- Response Time 1 | 00:00:00:000000 | 00:00:00:006000 Call Length | 00:00:00:000000 | 00:00:11:388000 ------------------------------ Test Terminated -------------------------------- [Mar 29 20:16:24] WARNING[3499]: asterisk.sipp:527 processEnded: Resolving remote host '127.0.0.1'... Done. [Mar 29 20:16:24] WARNING[3499]: asterisk.sipp:527 processEnded: 2022-03-29 20:16:24.054136 1648584984.054136: Aborting call on unexpected message for Call-Id '1-3611@127.0.0.1': while expecting '200' (index 14), received 'NOTIFY sip:127.0.0.1:5061 SIP/2.0 Via: SIP/2.0/UDP 127.0.0.1:5060;rport;branch=z9hG4bKPj2c867d59-7360-4682-8bf7-0250152762c8 From: "sut" ;tag=660e5373-48ad-4a8c-aaa2-55b5138e11fa To: "sipp" ;tag=3611SIPpTag001 Contact: Call-ID: 1-3611@127.0.0.1 CSeq: 24690 NOTIFY Event: message-summary Subscription-State: active;expires=3594 Allow-Events: presence, dialog, message-summary, refer Require: eventlist Max-Forwards: 70 User-Agent: Asterisk PBX GIT-master-df22e5e Content-Type: multipart/related;type="application/rlmi+xml";boundary=fqkki Content-Length: 903 --fqkki Content-ID: Content-Type: application/rlmi+xml Content-Length: 455 mail_list alice bob --fqkki Content-ID: Content-Type: application/simple-message-summary Content-Length: 49 Messages-Waiting: yes Voice-Message: 2/0 (0/0) --fqkki Content-ID: Content-Type: application/simple-message-summary Content-Length: 49 Messages-Waiting: yes Voice-Message: 2/0 (0/0) --fqkki-- '. [Mar 29 20:16:24] WARNING[3499]: asterisk.sipp:631 __scenario_callback: SIPp Scenario subscribe.xml Failed [1] [Mar 29 20:16:24] WARNING[3499]: asterisk.sipp:206 _handle_scenario_finished: Scenario subscribe.xml failed [Mar 29 20:16:24] WARNING[3499]: asterisk.sipp:640 __evaluate_scenario_results: SIPp Scenario subscribe.xml Failed [Mar 29 20:16:24] INFO[3499]: asterisk.test_case:508 __stop_instances: Stopping Asterisk instance 1 [Mar 29 20:16:24] INFO[3499]: asterisk.sipp:535 processEnded: SIPp scenario subscribe.xml ended with code 1 [Mar 29 20:16:24] DEBUG[3499]: asterisk.asterisk:574 __send_stop_gracefully: sending stop gracefully [Mar 29 20:16:24] DEBUG[3499]: asterisk.asterisk:938 cli_exec: Executing ['/sbin/asterisk', '-C', '/var/tmp/asterisk-testsuite/352d5d666bcec9f8b254e36c5dfb177c/run_1/ast1/etc/asterisk/asterisk.conf', '-rx', 'core stop gracefully'] ... [Mar 29 20:16:24] DEBUG[3499]: AMI:171 lineReceived: Line In: 'Event: TestEvent' [Mar 29 20:16:24] DEBUG[3499]: AMI:171 lineReceived: Line In: 'Privilege: reporting,all' [Mar 29 20:16:24] DEBUG[3499]: AMI:171 lineReceived: Line In: 'Type: StateChange' [Mar 29 20:16:24] DEBUG[3499]: AMI:171 lineReceived: Line In: 'State: SUBSCRIPTION_STATE_SET' [Mar 29 20:16:24] DEBUG[3499]: AMI:171 lineReceived: Line In: 'AppFile: res_pjsip_pubsub.c' [Mar 29 20:16:24] DEBUG[3499]: AMI:171 lineReceived: Line In: 'AppFunction: sip_subscription_send_request' [Mar 29 20:16:24] DEBUG[3499]: AMI:171 lineReceived: Line In: 'AppLine: 2044' [Mar 29 20:16:24] DEBUG[3499]: AMI:171 lineReceived: Line In: 'StateText: ACTIVE' [Mar 29 20:16:24] DEBUG[3499]: AMI:171 lineReceived: Line In: 'Endpoint: sipp' [Mar 29 20:16:24] DEBUG[3499]: AMI:171 lineReceived: Line In: '' [Mar 29 20:16:24] DEBUG[3499]: AMI:233 dispatchIncoming: Dispatch Incoming [Mar 29 20:16:24] DEBUG[3499]: AMI:263 dispatchIncoming: Incoming Message: {u'appfile': u'res_pjsip_pubsub.c', u'endpoint': u'sipp', u'appline': u'2044', u'appfunction': u'sip_subscription_send_request', u'state': u'SUBSCRIPTION_STATE_SET', u'statetext': u'ACTIVE', u'privilege': u'reporting,all', u'type': u'StateChange', u'event': u'TestEvent'} [Mar 29 20:16:24] DEBUG[3499]: AMI:171 lineReceived: Line In: '' [Mar 29 20:16:24] DEBUG[3499]: AMI:233 dispatchIncoming: Dispatch Incoming [Mar 29 20:16:24] DEBUG[3499]: AMI:263 dispatchIncoming: Incoming Message: {} [Mar 29 20:16:24] DEBUG[3499]: AMI:171 lineReceived: Line In: 'Event: TestEvent' [Mar 29 20:16:24] DEBUG[3499]: AMI:171 lineReceived: Line In: 'Privilege: reporting,all' [Mar 29 20:16:24] DEBUG[3499]: AMI:171 lineReceived: Line In: 'Type: StateChange' [Mar 29 20:16:24] DEBUG[3499]: AMI:171 lineReceived: Line In: 'State: SUBSCRIPTION_STATE_CHANGED' [Mar 29 20:16:24] DEBUG[3499]: AMI:171 lineReceived: Line In: 'AppFile: res_pjsip_pubsub.c' [Mar 29 20:16:24] DEBUG[3499]: AMI:171 lineReceived: Line In: 'AppFunction: serialized_send_notify' [Mar 29 20:16:24] DEBUG[3499]: AMI:171 lineReceived: Line In: 'AppLine: 2531' [Mar 29 20:16:24] DEBUG[3499]: AMI:171 lineReceived: Line In: 'Resource: mail_list' [Mar 29 20:16:24] DEBUG[3499]: AMI:171 lineReceived: Line In: '' [Mar 29 20:16:24] DEBUG[3499]: AMI:233 dispatchIncoming: Dispatch Incoming [Mar 29 20:16:24] DEBUG[3499]: AMI:263 dispatchIncoming: Incoming Message: {u'appfile': u'res_pjsip_pubsub.c', u'resource': u'mail_list', u'appline': u'2531', u'appfunction': u'serialized_send_notify', u'state': u'SUBSCRIPTION_STATE_CHANGED', u'privilege': u'reporting,all', u'type': u'StateChange', u'event': u'TestEvent'} [Mar 29 20:16:24] DEBUG[3499]: driver:100 on_subscription_state_change: State change to 5 [Mar 29 20:16:24] DEBUG[3499]: AMI:171 lineReceived: Line In: 'Event: Shutdown' [Mar 29 20:16:24] DEBUG[3499]: AMI:171 lineReceived: Line In: 'Privilege: system,all' [Mar 29 20:16:24] DEBUG[3499]: AMI:171 lineReceived: Line In: 'Shutdown: Cleanly' [Mar 29 20:16:24] DEBUG[3499]: AMI:171 lineReceived: Line In: 'Restart: False' [Mar 29 20:16:24] DEBUG[3499]: AMI:171 lineReceived: Line In: '' [Mar 29 20:16:24] DEBUG[3499]: AMI:233 dispatchIncoming: Dispatch Incoming [Mar 29 20:16:24] DEBUG[3499]: AMI:263 dispatchIncoming: Incoming Message: {u'privilege': u'system,all', u'restart': u'False', u'event': u'Shutdown', u'shutdown': u'Cleanly'} [Mar 29 20:16:24] DEBUG[3499]: AMI:171 lineReceived: Line In: 'Event: TestEvent' [Mar 29 20:16:24] DEBUG[3499]: AMI:171 lineReceived: Line In: 'Privilege: reporting,all' [Mar 29 20:16:24] DEBUG[3499]: AMI:171 lineReceived: Line In: 'Type: StateChange' [Mar 29 20:16:24] DEBUG[3499]: AMI:171 lineReceived: Line In: 'State: SUBSCRIPTION_TERMINATED' [Mar 29 20:16:24] DEBUG[3499]: AMI:171 lineReceived: Line In: 'AppFile: res_pjsip_pubsub.c' [Mar 29 20:16:24] DEBUG[3499]: AMI:171 lineReceived: Line In: 'AppFunction: pubsub_on_refresh_timeout' [Mar 29 20:16:24] DEBUG[3499]: AMI:171 lineReceived: Line In: 'AppLine: 3929' [Mar 29 20:16:24] DEBUG[3499]: AMI:171 lineReceived: Line In: 'Resource: mail_list' [Mar 29 20:16:24] DEBUG[3499]: AMI:171 lineReceived: Line In: '' [Mar 29 20:16:24] DEBUG[3499]: AMI:233 dispatchIncoming: Dispatch Incoming [Mar 29 20:16:24] DEBUG[3499]: AMI:263 dispatchIncoming: Incoming Message: {u'appfile': u'res_pjsip_pubsub.c', u'resource': u'mail_list', u'appline': u'3929', u'appfunction': u'pubsub_on_refresh_timeout', u'state': u'SUBSCRIPTION_TERMINATED', u'privilege': u'reporting,all', u'type': u'StateChange', u'event': u'TestEvent'} [Mar 29 20:16:24] DEBUG[3499]: driver:128 on_subscription_terminated: State change to 6 [Mar 29 20:16:27] DEBUG[3499]: asterisk.asterisk:182 __cli_output_callback: Asterisk CLI 127.0.0.1 exited 0 [Mar 29 20:16:27] DEBUG[3499]: asterisk.asterisk:580 __stop_gracefully_callback: Successfully stopped Asterisk 127.0.0.1 [Mar 29 20:16:27] INFO[3499]: AMI:1137 clientConnectionLost: connection lost, reconnecting... [Mar 29 20:16:27] INFO[3499]: twisted:154 publishToNewObserver: will retry in 2 seconds [Mar 29 20:16:27] INFO[3499]: AMI:1140 clientConnectionLost: None [Mar 29 20:16:27] INFO[3499]: twisted:154 publishToNewObserver: Stopping factory [Mar 29 20:16:27] INFO[3499]: asterisk.test_case:529 __stop_reactor: Stopping Reactor [Mar 29 20:16:27] INFO[3499]: twisted:154 publishToNewObserver: (UDP Port 5061 Closed) [Mar 29 20:16:27] INFO[3499]: twisted:154 publishToNewObserver: Stopping protocol [Mar 29 20:16:27] INFO[3499]: twisted:154 publishToNewObserver: Main loop terminated. [Mar 29 20:16:27] INFO[3499]: test_runner:313 main: Test run for tests/channels/pjsip/subscriptions/rls/lists/nominal/mwi/batched/multiple_resources_single_change completed with result False [Mar 29 20:16:27] ERROR[3499]: asterisk.test_case:689 evaluate_results: Fail token present: Test execution was interrupted before all NOTIFY packets were accounted for.