[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: <function handle_condition_failure at 0x7f5c2c865848>
[Mar 29 20:16:09] DEBUG[3499]: asterisk.test_conditions:143 register_observer: Registering: <function handle_condition_failure at 0x7f5c2c865848>
[Mar 29 20:16:09] DEBUG[3499]: asterisk.test_conditions:143 register_observer: Registering: <bound method SIPpTestCase.handle_condition_failure of <asterisk.sipp.SIPpTestCase object at 0x7f5c2ccd1990>>
[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 <asterisk.pcap.ProxyProtocol instance at 0x7f5c15f223b0>
[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 <starpy.manager.AMIFactory instance at 0x7f5c15f388c0>
[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 <bound method TestDriver.on_test_event of <driver.TestDriver object at 0x7f5c15f2b150>> 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 <sip:sipp@127.0.0.1:5062>;tag=3611SIPpTag001
To: sut <sip:mail_list@127.0.0.1:5061>
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" <sip:sipp@127.0.0.1>;tag=3611SIPpTag001
To: "sut" <sip:mail_list@127.0.0.1>;tag=660e5373-48ad-4a8c-aaa2-55b5138e11fa
CSeq: 1 SUBSCRIBE
Expires: 3600
Require: eventlist
Contact: <sip:127.0.0.1:5060>
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" <sip:mail_list@127.0.0.1>;tag=660e5373-48ad-4a8c-aaa2-55b5138e11fa
To: "sipp" <sip:sipp@127.0.0.1>;tag=3611SIPpTag001
Contact: <sip:127.0.0.1:5060>
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: <wzsvn@127.0.0.1>
Content-Type: application/rlmi+xml
Content-Length:   454

<?xml version="1.0" encoding="UTF-8"?>
<list xmlns="urn:ietf:params:xml:ns:rlmi" uri="sip:mail_list@127.0.0.1:5061" version="0" fullState="true">
 <name>mail_list</name>
 <resource uri="sip:alice@127.0.0.1:5061">
  <name>alice</name>
  <instance id="afwqc" state="active" cid="cqqoj@127.0.0.1" />
 </resource>
 <resource uri="sip:bob@127.0.0.1:5061">
  <name>bob</name>
  <instance id="jlrkk" state="active" cid="sxgwh@127.0.0.1" />
 </resource>
</list>

--btlif
Content-ID: <cqqoj@127.0.0.1>
Content-Type: application/simple-message-summary
Content-Length:    48

Messages-Waiting: no
Voice-Message: 0/0 (0/0)

--btlif
Content-ID: <sxgwh@127.0.0.1>
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" <sip:mail_list@127.0.0.1>;tag=660e5373-48ad-4a8c-aaa2-55b5138e11fa
To: "sipp" <sip:sipp@127.0.0.1>;tag=3611SIPpTag001
Call-ID: 1-3611@127.0.0.1
CSeq: 24687 NOTIFY
Contact: <sip:127.0.0.1:5062;transport=UDP>
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" <sip:mail_list@127.0.0.1>;tag=660e5373-48ad-4a8c-aaa2-55b5138e11fa
To: "sipp" <sip:sipp@127.0.0.1>;tag=3611SIPpTag001
Contact: <sip:127.0.0.1:5060>
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: <uyvhv@127.0.0.1>
Content-Type: application/rlmi+xml
Content-Length:   455

<?xml version="1.0" encoding="UTF-8"?>
<list xmlns="urn:ietf:params:xml:ns:rlmi" uri="sip:mail_list@127.0.0.1:5061" version="1" fullState="false">
 <name>mail_list</name>
 <resource uri="sip:alice@127.0.0.1:5061">
  <name>alice</name>
  <instance id="yrqsy" state="active" cid="uixov@127.0.0.1" />
 </resource>
 <resource uri="sip:bob@127.0.0.1:5061">
  <name>bob</name>
  <instance id="ighwz" state="active" cid="rdxcx@127.0.0.1" />
 </resource>
</list>

--ncrwa
Content-ID: <uixov@127.0.0.1>
Content-Type: application/simple-message-summary
Content-Length:    49

Messages-Waiting: yes
Voice-Message: 1/0 (0/0)

--ncrwa
Content-ID: <rdxcx@127.0.0.1>
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" <sip:mail_list@127.0.0.1>;tag=660e5373-48ad-4a8c-aaa2-55b5138e11fa
To: "sipp" <sip:sipp@127.0.0.1>;tag=3611SIPpTag001
Call-ID: 1-3611@127.0.0.1
CSeq: 24688 NOTIFY
Contact: <sip:127.0.0.1:5062;transport=UDP>
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 <sip:sipp@127.0.0.1:5062>;tag=3611SIPpTag001
To: sut <sip:mail_list@127.0.0.1:5061>;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" <sip:sipp@127.0.0.1>;tag=3611SIPpTag001
To: "sut" <sip:mail_list@127.0.0.1>;tag=660e5373-48ad-4a8c-aaa2-55b5138e11fa
CSeq: 24689 SUBSCRIBE
Require: eventlist
Expires: 3600
Contact: <sip:127.0.0.1:5060>
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" <sip:mail_list@127.0.0.1>;tag=660e5373-48ad-4a8c-aaa2-55b5138e11fa
To: "sipp" <sip:sipp@127.0.0.1>;tag=3611SIPpTag001
Contact: <sip:127.0.0.1:5060>
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: <nnonz@127.0.0.1>
Content-Type: application/rlmi+xml
Content-Length:   454

<?xml version="1.0" encoding="UTF-8"?>
<list xmlns="urn:ietf:params:xml:ns:rlmi" uri="sip:mail_list@127.0.0.1:5061" version="2" fullState="true">
 <name>mail_list</name>
 <resource uri="sip:alice@127.0.0.1:5061">
  <name>alice</name>
  <instance id="aawee" state="active" cid="ezzul@127.0.0.1" />
 </resource>
 <resource uri="sip:bob@127.0.0.1:5061">
  <name>bob</name>
  <instance id="lyhpr" state="active" cid="fxega@127.0.0.1" />
 </resource>
</list>

--bdzqh
Content-ID: <ezzul@127.0.0.1>
Content-Type: application/simple-message-summary
Content-Length:    49

Messages-Waiting: yes
Voice-Message: 1/0 (0/0)

--bdzqh
Content-ID: <fxega@127.0.0.1>
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" <sip:mail_list@127.0.0.1>;tag=660e5373-48ad-4a8c-aaa2-55b5138e11fa
To:  "sipp" <sip:sipp@127.0.0.1>;tag=3611SIPpTag001
Call-ID: 1-3611@127.0.0.1
CSeq:  24689 NOTIFY
Contact: <sip:127.0.0.1:5062;transport=UDP>
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" <sip:mail_list@127.0.0.1>;tag=660e5373-48ad-4a8c-aaa2-55b5138e11fa
To: "sipp" <sip:sipp@127.0.0.1>;tag=3611SIPpTag001
Contact: <sip:127.0.0.1:5060>
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: <baxee@127.0.0.1>
Content-Type: application/rlmi+xml
Content-Length:   455

<?xml version="1.0" encoding="UTF-8"?>
<list xmlns="urn:ietf:params:xml:ns:rlmi" uri="sip:mail_list@127.0.0.1:5061" version="3" fullState="false">
 <name>mail_list</name>
 <resource uri="sip:alice@127.0.0.1:5061">
  <name>alice</name>
  <instance id="ukgvh" state="active" cid="hciuw@127.0.0.1" />
 </resource>
 <resource uri="sip:bob@127.0.0.1:5061">
  <name>bob</name>
  <instance id="tprqv" state="active" cid="gupto@127.0.0.1" />
 </resource>
</list>

--fqkki
Content-ID: <hciuw@127.0.0.1>
Content-Type: application/simple-message-summary
Content-Length:    49

Messages-Waiting: yes
Voice-Message: 2/0 (0/0)

--fqkki
Content-ID: <gupto@127.0.0.1>
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" <sip:mail_list@127.0.0.1>;tag=660e5373-48ad-4a8c-aaa2-55b5138e11fa
To: "sipp" <sip:sipp@127.0.0.1>;tag=3611SIPpTag001
Call-ID: 1-3611@127.0.0.1
CSeq: 24690 NOTIFY
Contact: <sip:127.0.0.1:5062;transport=UDP>
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 <sip:sipp@127.0.0.1:5062>;tag=3611SIPpTag001
To: sut <sip:mail_list@127.0.0.1:5061>;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" <sip:mail_list@127.0.0.1>;tag=660e5373-48ad-4a8c-aaa2-55b5138e11fa
To: "sipp" <sip:sipp@127.0.0.1>;tag=3611SIPpTag001
Contact: <sip:127.0.0.1:5060>
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: <baxee@127.0.0.1>
Content-Type: application/rlmi+xml
Content-Length:   455

<?xml version="1.0" encoding="UTF-8"?>
<list xmlns="urn:ietf:params:xml:ns:rlmi" uri="sip:mail_list@127.0.0.1:5061" version="3" fullState="false">
 <name>mail_list</name>
 <resource uri="sip:alice@127.0.0.1:5061">
  <name>alice</name>
  <instance id="ukgvh" state="active" cid="hciuw@127.0.0.1" />
 </resource>
 <resource uri="sip:bob@127.0.0.1:5061">
  <name>bob</name>
  <instance id="tprqv" state="active" cid="gupto@127.0.0.1" />
 </resource>
</list>

--fqkki
Content-ID: <hciuw@127.0.0.1>
Content-Type: application/simple-message-summary
Content-Length:    49

Messages-Waiting: yes
Voice-Message: 2/0 (0/0)

--fqkki
Content-ID: <gupto@127.0.0.1>
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" <sip:mail_list@127.0.0.1>;tag=660e5373-48ad-4a8c-aaa2-55b5138e11fa
To: "sipp" <sip:sipp@127.0.0.1>;tag=3611SIPpTag001
Call-ID: 1-3611@127.0.0.1
CSeq: 24691 BYE
Max-Forwards: 70
Contact: <sip:sipp@127.0.0.1:5062;transport=UDP>
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" <sip:mail_list@127.0.0.1>;tag=660e5373-48ad-4a8c-aaa2-55b5138e11fa
To: "sipp" <sip:sipp@127.0.0.1>;tag=3611SIPpTag001
Contact: <sip:127.0.0.1:5060>
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: <baxee@127.0.0.1>
Content-Type: application/rlmi+xml
Content-Length:   455

<?xml version="1.0" encoding="UTF-8"?>
<list xmlns="urn:ietf:params:xml:ns:rlmi" uri="sip:mail_list@127.0.0.1:5061" version="3" fullState="false">
 <name>mail_list</name>
 <resource uri="sip:alice@127.0.0.1:5061">
  <name>alice</name>
  <instance id="ukgvh" state="active" cid="hciuw@127.0.0.1" />
 </resource>
 <resource uri="sip:bob@127.0.0.1:5061">
  <name>bob</name>
  <instance id="tprqv" state="active" cid="gupto@127.0.0.1" />
 </resource>
</list>

--fqkki
Content-ID: <hciuw@127.0.0.1>
Content-Type: application/simple-message-summary
Content-Length:    49

Messages-Waiting: yes
Voice-Message: 2/0 (0/0)

--fqkki
Content-ID: <gupto@127.0.0.1>
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: <twisted.internet.tcp.Connector instance at 0x7f5c15f38950> 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 <starpy.manager.AMIFactory instance at 0x7f5c15f388c0>
[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 <asterisk.pcap.ProxyProtocol instance at 0x7f5c15f223b0>
[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.