[2021-11-09 17:31:27] Asterisk 16.18.0 built by root @ on a armv6l running Linux on 2021-05-15 09:26:04 UTC [2021-11-09 17:31:27] DEBUG[9882] config.c: Parsing /etc/asterisk/logger.conf [2021-11-09 17:31:27] DEBUG[9882] config.c: Parsing /etc/asterisk/logger_general_additional.conf [2021-11-09 17:31:27] DEBUG[9882] config.c: Parsing /etc/asterisk/logger_general_custom.conf [2021-11-09 17:31:27] DEBUG[9882] config.c: Parsing /etc/asterisk/logger_logfiles_additional.conf [2021-11-09 17:31:27] DEBUG[9882] config.c: Parsing /etc/asterisk/logger_logfiles_custom.conf [2021-11-09 17:31:29] DEBUG[22768] manager.c: Running action 'Login' [2021-11-09 17:31:30] VERBOSE[1153] res_pjsip_logger.c: <--- Received SIP request (889 bytes) from TLS::48950 ---> REGISTER sip:;transport=TLS SIP/2.0 Via: SIP/2.0/TLS :41309;branch=z9hG4bK-524287-1---8a835652ab750c87;rport Max-Forwards: 70 Contact: :48950;transport=TLS;rinstance=2c586552061c4a8c> To: ;transport=TLS> From: ;transport=TLS>;tag=a8da667a Call-ID: iWw60LDMFS7heqvvA4PEVw.. CSeq: 9 REGISTER Expires: 60 Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE User-Agent: Zoiper rv2.10.12.3-mod Authorization: Digest username="331",realm="asterisk",nonce="1636475437/7a929a6dde3b4a2908b2515e7a08ac7f",uri="sip:;transport=TLS",response="50def3b121d3bbfc27d7ba489c303de6",cnonce="cc3e9850c5b8c048c8b7935cfaa3f35b",nc=00000002,qop=auth,algorithm=md5,opaque="32054c192e8b8135" Allow-Events: presence, kpml, talk Content-Length: 0 [2021-11-09 17:31:30] DEBUG[1153] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg REGISTER/cseq=9 (rdata0x12ed2ec) [2021-11-09 17:31:30] DEBUG[1153] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000037 to use for Request msg REGISTER/cseq=9 (rdata0x12ed2ec) [2021-11-09 17:31:30] DEBUG[21161] netsock2.c: Splitting '' into... [2021-11-09 17:31:30] DEBUG[21161] netsock2.c: ...host '' and port ''. [2021-11-09 17:31:30] DEBUG[21161] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against [2021-11-09 17:31:30] DEBUG[21161] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '331' domain '' [2021-11-09 17:31:30] DEBUG[21161] res_pjsip_endpoint_identifier_user.c: Identified by From username '331' domain '' [2021-11-09 17:31:30] DEBUG[21161] res_pjsip_authenticator_digest.c: Using default realm 'asterisk' on incoming auth '331-auth'. [2021-11-09 17:31:30] DEBUG[21161] netsock2.c: Splitting '' into... [2021-11-09 17:31:30] DEBUG[21161] netsock2.c: ...host '' and port ''. [2021-11-09 17:31:30] DEBUG[21161] netsock2.c: Splitting '' into... [2021-11-09 17:31:30] DEBUG[21161] netsock2.c: ...host '' and port ''. [2021-11-09 17:31:30] VERBOSE[21161] res_pjsip_logger.c: <--- Transmitting SIP response (529 bytes) to TLS::48950 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/TLS :41309;rport=48950;received=;branch=z9hG4bK-524287-1---8a835652ab750c87 Call-ID: iWw60LDMFS7heqvvA4PEVw.. From: >;tag=a8da667a To: >;tag=z9hG4bK-524287-1---8a835652ab750c87 CSeq: 9 REGISTER WWW-Authenticate: Digest realm="asterisk",nonce="1636475490/9dff56dfcd168b923662e4f384c5527e",opaque="11d226fd3697c1a5",stale=true,algorithm=md5,qop="auth" Server: FPBX-15.0.17.55(16.18.0) Content-Length: 0 [2021-11-09 17:31:30] VERBOSE[1153] res_pjsip_logger.c: <--- Received SIP request (890 bytes) from TLS::48950 ---> REGISTER sip:;transport=TLS SIP/2.0 Via: SIP/2.0/TLS :41309;branch=z9hG4bK-524287-1---3099e8d1dc732cd3;rport Max-Forwards: 70 Contact: :48950;transport=TLS;rinstance=2c586552061c4a8c> To: ;transport=TLS> From: ;transport=TLS>;tag=a8da667a Call-ID: iWw60LDMFS7heqvvA4PEVw.. CSeq: 10 REGISTER Expires: 60 Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE User-Agent: Zoiper rv2.10.12.3-mod Authorization: Digest username="331",realm="asterisk",nonce="1636475490/9dff56dfcd168b923662e4f384c5527e",uri="sip:;transport=TLS",response="a2b4070af4c4b2ff0193c233643c373f",cnonce="8e3870edf3711e041439fdd588dbd2fc",nc=00000001,qop=auth,algorithm=md5,opaque="11d226fd3697c1a5" Allow-Events: presence, kpml, talk Content-Length: 0 [2021-11-09 17:31:30] DEBUG[1153] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg REGISTER/cseq=10 (rdata0x12ed2ec) [2021-11-09 17:31:30] DEBUG[1153] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000037 to use for Request msg REGISTER/cseq=10 (rdata0x12ed2ec) [2021-11-09 17:31:30] DEBUG[21161] netsock2.c: Splitting '' into... [2021-11-09 17:31:30] DEBUG[21161] netsock2.c: ...host '' and port ''. [2021-11-09 17:31:30] DEBUG[21161] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against [2021-11-09 17:31:30] DEBUG[21161] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '331' domain '' [2021-11-09 17:31:30] DEBUG[21161] res_pjsip_endpoint_identifier_user.c: Identified by From username '331' domain '' [2021-11-09 17:31:30] DEBUG[21161] res_pjsip_authenticator_digest.c: Using default realm 'asterisk' on incoming auth '331-auth'. [2021-11-09 17:31:30] DEBUG[21161] res_pjsip_authenticator_digest.c: Calculated nonce 1636475490/9dff56dfcd168b923662e4f384c5527e. Actual nonce is 1636475490/9dff56dfcd168b923662e4f384c5527e [2021-11-09 17:31:30] DEBUG[21161] netsock2.c: Splitting '' into... [2021-11-09 17:31:30] DEBUG[21161] netsock2.c: ...host '' and port ''. [2021-11-09 17:31:30] DEBUG[21161] netsock2.c: Splitting '' into... [2021-11-09 17:31:30] DEBUG[21161] netsock2.c: ...host '' and port ''. [2021-11-09 17:31:30] DEBUG[21161] res_pjsip_registrar.c: Matched id '331' to aor '331' [2021-11-09 17:31:30] DEBUG[21161] res_pjsip_registrar.c: Matched aor '331' by To username [2021-11-09 17:31:30] DEBUG[21161] config.c: extract double from [3.0] in [-inf, inf] gives [3.000000](0) [2021-11-09 17:31:30] DEBUG[21161] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2021-11-09 17:31:30] DEBUG[21161] config.c: extract double from [3.000000] in [-inf, inf] gives [3.000000](0) [2021-11-09 17:31:30] DEBUG[21161] config.c: extract uint from [41309] in [0, 4294967295] gives [41309](0) [2021-11-09 17:31:30] DEBUG[21161] config.c: extract uint from [60] in [0, 86400] gives [60](0) [2021-11-09 17:31:30] DEBUG[21161] config.c: extract double from [3.0] in [-inf, inf] gives [3.000000](0) [2021-11-09 17:31:30] DEBUG[21161] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2021-11-09 17:31:30] DEBUG[21161] config.c: extract double from [3.000000] in [-inf, inf] gives [3.000000](0) [2021-11-09 17:31:30] DEBUG[21161] config.c: extract uint from [41309] in [0, 4294967295] gives [41309](0) [2021-11-09 17:31:30] DEBUG[21161] config.c: extract uint from [60] in [0, 86400] gives [60](0) [2021-11-09 17:31:30] DEBUG[21161] res_pjsip_registrar.c: Refreshed contact 'sip:331@:48950;transport=TLS;rinstance=2c586552061c4a8c' on AOR '331' with new expiration of 60 seconds [2021-11-09 17:31:30] DEBUG[21162] res_pjsip_mwi.c: Sending unsolicited MWI NOTIFY to endpoint 331, new messages: 0, old messages: 25 [2021-11-09 17:31:30] VERBOSE[21161] res_pjsip_logger.c: <--- Transmitting SIP response (505 bytes) to TLS::48950 ---> SIP/2.0 200 OK Via: SIP/2.0/TLS :41309;rport=48950;received=;branch=z9hG4bK-524287-1---3099e8d1dc732cd3 Call-ID: iWw60LDMFS7heqvvA4PEVw.. From: >;tag=a8da667a To: >;tag=z9hG4bK-524287-1---3099e8d1dc732cd3 CSeq: 10 REGISTER Date: Tue, 09 Nov 2021 16:31:30 GMT Contact: :48950;transport=TLS;rinstance=2c586552061c4a8c>;expires=59 Expires: 60 Server: FPBX-15.0.17.55(16.18.0) Content-Length: 0 [2021-11-09 17:31:31] DEBUG[21162] config.c: extract double from [3.0] in [-inf, inf] gives [3.000000](0) [2021-11-09 17:31:31] DEBUG[21162] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2021-11-09 17:31:31] DEBUG[21162] config.c: extract double from [3.000000] in [-inf, inf] gives [3.000000](0) [2021-11-09 17:31:31] DEBUG[21162] config.c: extract uint from [41309] in [0, 4294967295] gives [41309](0) [2021-11-09 17:31:31] DEBUG[21162] config.c: extract uint from [60] in [0, 86400] gives [60](0) [2021-11-09 17:31:31] DEBUG[21162] res_pjsip.c: 0x741070c0: Wrapper created [2021-11-09 17:31:31] DEBUG[21162] res_pjsip/pjsip_resolver.c: Performing SIP DNS resolution of target '' [2021-11-09 17:31:31] DEBUG[21162] res_pjsip/pjsip_resolver.c: Transport type for target '' is 'TLS transport' [2021-11-09 17:31:31] DEBUG[21162] res_pjsip/pjsip_resolver.c: Target '' is an IP address, skipping resolution [2021-11-09 17:31:31] DEBUG[21162] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to :5061 (this may be re-written again later) [2021-11-09 17:31:31] VERBOSE[21162] res_pjsip_logger.c: <--- Transmitting SIP request (721 bytes) to TLS::48950 ---> NOTIFY sip:331@:48950;transport=TLS;rinstance=2c586552061c4a8c SIP/2.0 Via: SIP/2.0/TLS :5061;rport;branch=z9hG4bKPjaf161e6f-bd40-4738-b127-e876814b605a;alias From: >;tag=970c23d1-3fcb-456f-b26d-8cdea8a7bdaf To: ;rinstance=2c586552061c4a8c> Contact: :5061;transport=TLS> Call-ID: a879cc95-d789-47e5-abbc-84be1454a264 CSeq: 29258 NOTIFY Subscription-State: terminated Event: message-summary Allow-Events: presence, dialog, message-summary, refer Max-Forwards: 70 User-Agent: FPBX-15.0.17.55(16.18.0) Content-Type: application/simple-message-summary Content-Length: 49 Messages-Waiting: no Voice-Message: 0/25 (0/0) [2021-11-09 17:31:31] VERBOSE[1153] res_pjsip_logger.c: <--- Received SIP response (456 bytes) from TLS::48950 ---> SIP/2.0 200 OK Via: SIP/2.0/TLS :5061;rport=5061;branch=z9hG4bKPjaf161e6f-bd40-4738-b127-e876814b605a;received=;alias Contact: :41309;transport=tls> To: ;rinstance=2c586552061c4a8c>;tag=9f957f2c From: >;tag=970c23d1-3fcb-456f-b26d-8cdea8a7bdaf Call-ID: a879cc95-d789-47e5-abbc-84be1454a264 CSeq: 29258 NOTIFY User-Agent: Zoiper rv2.10.12.3-mod Content-Length: 0 [2021-11-09 17:31:31] DEBUG[1153] res_pjsip/pjsip_distributor.c: No dialog serializer for Response msg 200/NOTIFY/cseq=29258 (rdata0x12ed2ec). Using request transaction as basis. [2021-11-09 17:31:31] DEBUG[1153] res_pjsip/pjsip_distributor.c: Found transaction tsx0x6a80007c for Response msg 200/NOTIFY/cseq=29258 (rdata0x12ed2ec). [2021-11-09 17:31:31] DEBUG[1153] res_pjsip/pjsip_distributor.c: Found serializer pjsip/mwi-00000067 on transaction tsx0x6a80007c [2021-11-09 17:31:31] DEBUG[21161] res_pjsip.c: 0x741070c0: PJSIP tsx response received [2021-11-09 17:31:31] DEBUG[21161] res_pjsip.c: 0x741070c0: Callbacks executed [2021-11-09 17:31:31] DEBUG[21161] res_pjsip.c: 0x741070c0: wrapper destroyed [2021-11-09 17:31:32] DEBUG[22775] manager.c: Running action 'Login' [2021-11-09 17:31:33] DEBUG[22780] manager.c: Running action 'Login' [2021-11-09 17:31:33] DEBUG[22793] manager.c: Running action 'Login' [2021-11-09 17:31:34] DEBUG[22798] manager.c: Running action 'Login' [2021-11-09 17:31:34] DEBUG[22803] manager.c: Running action 'Login' [2021-11-09 17:31:34] DEBUG[22808] manager.c: Running action 'Login' [2021-11-09 17:31:34] DEBUG[22813] manager.c: Running action 'Login' [2021-11-09 17:31:37] DEBUG[22820] manager.c: Running action 'Login' [2021-11-09 17:31:40] DEBUG[22827] manager.c: Running action 'Login' [2021-11-09 17:31:43] DEBUG[22834] manager.c: Running action 'Login' [2021-11-09 17:31:46] VERBOSE[1153] res_pjsip_logger.c: <--- Received SIP request (1737 bytes) from TLS::48950 ---> INVITE sip:*43@;transport=TLS SIP/2.0 Via: SIP/2.0/TLS :41309;branch=z9hG4bK-524287-1---99d25c68a8ffb40a;rport Max-Forwards: 70 Contact: :48950;transport=TLS> To: > From: ;transport=TLS>;tag=3a643242 Call-ID: CQdLbgtd0ZPU7DIOH8w5hg.. CSeq: 1 INVITE Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE Content-Type: application/sdp User-Agent: Zoiper rv2.10.12.3-mod Allow-Events: presence, kpml, talk Content-Length: 1165 v=0 o=Zoiper 1636475507824 1 IN IP4 s=Z c=IN IP4 t=0 0 m=audio 58962 RTP/SAVP 8 101 3 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=sendrecv a=crypto:5 AES_256_CM_HMAC_SHA1_80 inline:9dZTx0uuBxeCuuTfxGOLsJrxHwHTLrfAgEgMv+LpDSnjH04275yUu0Zh4NG5yQ== a=crypto:6 AES_256_CM_HMAC_SHA1_32 inline:9dZTx0uuBxeCuuTfxGOLsJrxHwHTLrfAgEgMv+LpDSnjH04275yUu0Zh4NG5yQ== a=crypto:9 AES_CM_256_HMAC_SHA1_80 inline:9dZTx0uuBxeCuuTfxGOLsJrxHwHTLrfAgEgMv+LpDSnjH04275yUu0Zh4NG5yQ== a=crypto:10 AES_CM_256_HMAC_SHA1_32 inline:9dZTx0uuBxeCuuTfxGOLsJrxHwHTLrfAgEgMv+LpDSnjH04275yUu0Zh4NG5yQ== a=crypto:3 AES_192_CM_HMAC_SHA1_80 inline:9dZTx0uuBxeCuuTfxGOLsJrxHwHTLrfAgEgMv+LpDSnjH04275w= a=crypto:4 AES_192_CM_HMAC_SHA1_32 inline:9dZTx0uuBxeCuuTfxGOLsJrxHwHTLrfAgEgMv+LpDSnjH04275w= a=crypto:7 AES_CM_192_HMAC_SHA1_80 inline:9dZTx0uuBxeCuuTfxGOLsJrxHwHTLrfAgEgMv+LpDSnjH04275w= a=crypto:8 AES_CM_192_HMAC_SHA1_32 inline:9dZTx0uuBxeCuuTfxGOLsJrxHwHTLrfAgEgMv+LpDSnjH04275w= a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:9dZTx0uuBxeCuuTfxGOLsJrxHwHTLrfAgEgMv+Lp a=crypto:2 AES_CM_128_HMAC_SHA1_32 inline:9dZTx0uuBxeCuuTfxGOLsJrxHwHTLrfAgEgMv+Lp [2021-11-09 17:31:46] DEBUG[1153] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg INVITE/cseq=1 (rdata0x12ed2ec) [2021-11-09 17:31:46] DEBUG[1153] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000045 to use for Request msg INVITE/cseq=1 (rdata0x12ed2ec) [2021-11-09 17:31:46] DEBUG[21161] netsock2.c: Splitting '' into... [2021-11-09 17:31:46] DEBUG[21161] netsock2.c: ...host '' and port ''. [2021-11-09 17:31:46] DEBUG[21161] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against [2021-11-09 17:31:46] DEBUG[21161] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '331' domain '' [2021-11-09 17:31:46] DEBUG[21161] res_pjsip_endpoint_identifier_user.c: Identified by From username '331' domain '' [2021-11-09 17:31:46] DEBUG[21161] res_pjsip_authenticator_digest.c: Using default realm 'asterisk' on incoming auth '331-auth'. [2021-11-09 17:31:46] DEBUG[21161] netsock2.c: Splitting '' into... [2021-11-09 17:31:46] DEBUG[21161] netsock2.c: ...host '' and port ''. [2021-11-09 17:31:46] DEBUG[21161] netsock2.c: Splitting '' into... [2021-11-09 17:31:46] DEBUG[21161] netsock2.c: ...host '' and port ''. [2021-11-09 17:31:46] VERBOSE[21161] res_pjsip_logger.c: <--- Transmitting SIP response (516 bytes) to TLS::48950 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/TLS :41309;rport=48950;received=;branch=z9hG4bK-524287-1---99d25c68a8ffb40a Call-ID: CQdLbgtd0ZPU7DIOH8w5hg.. From: >;tag=3a643242 To: >;tag=z9hG4bK-524287-1---99d25c68a8ffb40a CSeq: 1 INVITE WWW-Authenticate: Digest realm="asterisk",nonce="1636475506/91d4de42b56a453f2bd196c426b7c4c7",opaque="1ab7338a0ed67c69",algorithm=md5,qop="auth" Server: FPBX-15.0.17.55(16.18.0) Content-Length: 0 [2021-11-09 17:31:46] VERBOSE[1153] res_pjsip_logger.c: <--- Received SIP request (363 bytes) from TLS::48950 ---> ACK sip:*43@;transport=TLS SIP/2.0 Via: SIP/2.0/TLS :41309;branch=z9hG4bK-524287-1---99d25c68a8ffb40a;rport Max-Forwards: 70 To: >;tag=z9hG4bK-524287-1---99d25c68a8ffb40a From: ;transport=TLS>;tag=3a643242 Call-ID: CQdLbgtd0ZPU7DIOH8w5hg.. CSeq: 1 ACK Content-Length: 0 [2021-11-09 17:31:46] DEBUG[1153] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg ACK/cseq=1 (rdata0x12ed2ec) [2021-11-09 17:31:46] DEBUG[1153] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000045 to use for Request msg ACK/cseq=1 (rdata0x12ed2ec) [2021-11-09 17:31:46] DEBUG[21161] netsock2.c: Splitting '' into... [2021-11-09 17:31:46] DEBUG[21161] netsock2.c: ...host '' and port ''. [2021-11-09 17:31:46] DEBUG[21161] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against [2021-11-09 17:31:46] DEBUG[21161] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '331' domain '' [2021-11-09 17:31:46] DEBUG[21161] res_pjsip_endpoint_identifier_user.c: Identified by From username '331' domain '' [2021-11-09 17:31:46] VERBOSE[1153] res_pjsip_logger.c: <--- Received SIP request (2038 bytes) from TLS::48950 ---> INVITE sip:*43@;transport=TLS SIP/2.0 Via: SIP/2.0/TLS :41309;branch=z9hG4bK-524287-1---9d893386b9e0b46d;rport Max-Forwards: 70 Contact: :48950;transport=TLS> To: > From: ;transport=TLS>;tag=3a643242 Call-ID: CQdLbgtd0ZPU7DIOH8w5hg.. CSeq: 2 INVITE Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE Content-Type: application/sdp User-Agent: Zoiper rv2.10.12.3-mod Authorization: Digest username="331",realm="asterisk",nonce="1636475506/91d4de42b56a453f2bd196c426b7c4c7",uri="sip:*43@;transport=TLS",response="0a77025d719849ea6c8602035a15e99a",cnonce="9d4c1777b2f6aaf87b3e9d3daa112af8",nc=00000001,qop=auth,algorithm=md5,opaque="1ab7338a0ed67c69" Allow-Events: presence, kpml, talk Content-Length: 1165 v=0 o=Zoiper 1636475507824 1 IN IP4 s=Z c=IN IP4 t=0 0 m=audio 58962 RTP/SAVP 8 101 3 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=sendrecv a=crypto:5 AES_256_CM_HMAC_SHA1_80 inline:9dZTx0uuBxeCuuTfxGOLsJrxHwHTLrfAgEgMv+LpDSnjH04275yUu0Zh4NG5yQ== a=crypto:6 AES_256_CM_HMAC_SHA1_32 inline:9dZTx0uuBxeCuuTfxGOLsJrxHwHTLrfAgEgMv+LpDSnjH04275yUu0Zh4NG5yQ== a=crypto:9 AES_CM_256_HMAC_SHA1_80 inline:9dZTx0uuBxeCuuTfxGOLsJrxHwHTLrfAgEgMv+LpDSnjH04275yUu0Zh4NG5yQ== a=crypto:10 AES_CM_256_HMAC_SHA1_32 inline:9dZTx0uuBxeCuuTfxGOLsJrxHwHTLrfAgEgMv+LpDSnjH04275yUu0Zh4NG5yQ== a=crypto:3 AES_192_CM_HMAC_SHA1_80 inline:9dZTx0uuBxeCuuTfxGOLsJrxHwHTLrfAgEgMv+LpDSnjH04275w= a=crypto:4 AES_192_CM_HMAC_SHA1_32 inline:9dZTx0uuBxeCuuTfxGOLsJrxHwHTLrfAgEgMv+LpDSnjH04275w= a=crypto:7 AES_CM_192_HMAC_SHA1_80 inline:9dZTx0uuBxeCuuTfxGOLsJrxHwHTLrfAgEgMv+LpDSnjH04275w= a=crypto:8 AES_CM_192_HMAC_SHA1_32 inline:9dZTx0uuBxeCuuTfxGOLsJrxHwHTLrfAgEgMv+LpDSnjH04275w= a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:9dZTx0uuBxeCuuTfxGOLsJrxHwHTLrfAgEgMv+Lp a=crypto:2 AES_CM_128_HMAC_SHA1_32 inline:9dZTx0uuBxeCuuTfxGOLsJrxHwHTLrfAgEgMv+Lp [2021-11-09 17:31:46] DEBUG[1153] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg INVITE/cseq=2 (rdata0x12ed2ec) [2021-11-09 17:31:46] DEBUG[1153] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000045 to use for Request msg INVITE/cseq=2 (rdata0x12ed2ec) [2021-11-09 17:31:46] DEBUG[21161] netsock2.c: Splitting '' into... [2021-11-09 17:31:46] DEBUG[21161] netsock2.c: ...host '' and port ''. [2021-11-09 17:31:46] DEBUG[21161] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against [2021-11-09 17:31:46] DEBUG[21161] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '331' domain '' [2021-11-09 17:31:46] DEBUG[21161] res_pjsip_endpoint_identifier_user.c: Identified by From username '331' domain '' [2021-11-09 17:31:46] DEBUG[21161] res_pjsip_authenticator_digest.c: Using default realm 'asterisk' on incoming auth '331-auth'. [2021-11-09 17:31:46] DEBUG[21161] res_pjsip_authenticator_digest.c: Calculated nonce 1636475506/91d4de42b56a453f2bd196c426b7c4c7. Actual nonce is 1636475506/91d4de42b56a453f2bd196c426b7c4c7 [2021-11-09 17:31:46] DEBUG[21161] netsock2.c: Splitting '' into... [2021-11-09 17:31:46] DEBUG[21161] netsock2.c: ...host '' and port ''. [2021-11-09 17:31:46] DEBUG[21161] netsock2.c: Splitting '' into... [2021-11-09 17:31:46] DEBUG[21161] netsock2.c: ...host '' and port ''. [2021-11-09 17:31:46] DEBUG[21161] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000045 to use for Request msg INVITE/cseq=2 (rdata0x289fc9c) [2021-11-09 17:31:46] DEBUG[21161] res_pjsip_session.c: 331 [2021-11-09 17:31:46] DEBUG[21161] res_pjsip_session.c: 331: Call (TLS::48950) to extension '*43' sending 100 Trying [2021-11-09 17:31:46] DEBUG[21161] res_pjsip_session.c: 331: Method is INVITE, Response is 100 Trying [2021-11-09 17:31:46] DEBUG[21161] res_pjsip_session.c: 331 [2021-11-09 17:31:46] VERBOSE[21161] res_pjsip_logger.c: <--- Transmitting SIP response (324 bytes) to TLS::48950 ---> SIP/2.0 100 Trying Via: SIP/2.0/TLS :41309;rport=48950;received=;branch=z9hG4bK-524287-1---9d893386b9e0b46d Call-ID: CQdLbgtd0ZPU7DIOH8w5hg.. From: >;tag=3a643242 To: > CSeq: 2 INVITE Server: FPBX-15.0.17.55(16.18.0) Content-Length: 0 [2021-11-09 17:31:46] DEBUG[21161] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [2021-11-09 17:31:46] DEBUG[21161] res_pjsip_session.c: The state change pertains to the endpoint '331()' [2021-11-09 17:31:46] DEBUG[21161] res_pjsip_session.c: The inv session still has an invite_tsx (0x6a86c384) [2021-11-09 17:31:46] DEBUG[21161] res_pjsip_session.c: There is no transaction involved in this state change [2021-11-09 17:31:46] DEBUG[21161] res_pjsip_session.c: The current inv state is INCOMING [2021-11-09 17:31:46] DEBUG[21161] res_pjsip_session.c: 331: Source of transaction state change is TX_MSG [2021-11-09 17:31:46] DEBUG[21161] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [2021-11-09 17:31:46] DEBUG[21161] res_pjsip_session.c: The state change pertains to the endpoint '331()' [2021-11-09 17:31:46] DEBUG[21161] res_pjsip_session.c: The inv session still has an invite_tsx (0x6a86c384) [2021-11-09 17:31:46] DEBUG[21161] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x6a86c384 [2021-11-09 17:31:46] DEBUG[21161] res_pjsip_session.c: The current transaction state is Proceeding [2021-11-09 17:31:46] DEBUG[21161] res_pjsip_session.c: The transaction state change event is TX_MSG [2021-11-09 17:31:46] DEBUG[21161] res_pjsip_session.c: The current inv state is INCOMING [2021-11-09 17:31:46] DEBUG[21161] res_pjsip_session.c: 331: Media count: 1 [2021-11-09 17:31:46] DEBUG[21161] res_pjsip_session.c: 331: Processing stream 0 [2021-11-09 17:31:46] DEBUG[21161] res_pjsip_session.c: 331: Using audio-0 for new stream name [2021-11-09 17:31:46] DEBUG[21161] res_pjsip_session.c: 331: Using new stream 0:audio-0:audio:sendrecv (nothing) [2021-11-09 17:31:46] DEBUG[21161] res_pjsip_session.c: 331 Adding position 0 [2021-11-09 17:31:46] DEBUG[21161] res_pjsip_session.c: Creating new media session [2021-11-09 17:31:46] DEBUG[21161] res_pjsip_session.c: Setting media session as default for audio [2021-11-09 17:31:46] DEBUG[21161] res_pjsip_session.c: Done [2021-11-09 17:31:46] DEBUG[21161] res_pjsip_session.c: 331: Negotiating incoming SDP media stream 0:audio-0:audio:sendrecv (nothing) using audio SDP handler [2021-11-09 17:31:46] DEBUG[21161] netsock2.c: Splitting '' into... [2021-11-09 17:31:46] DEBUG[21161] netsock2.c: ...host '' and port ''. [2021-11-09 17:31:46] DEBUG[21161] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7401c9f0' [2021-11-09 17:31:46] DEBUG[21161] res_rtp_asterisk.c: (0x7401c9f0) RTP allocated port 19202 [2021-11-09 17:31:46] DEBUG[21161] res_rtp_asterisk.c: (0x7401c9f0) ICE creating session [::]:19202 (19202) [2021-11-09 17:31:46] DEBUG[21161] res_rtp_asterisk.c: (0x7401c9f0) ICE create [2021-11-09 17:31:46] DEBUG[21161] res_rtp_asterisk.c: (0x7401c9f0) ICE add system candidates [2021-11-09 17:31:46] DEBUG[21161] netsock2.c: Splitting '' into... [2021-11-09 17:31:46] DEBUG[21161] netsock2.c: ...host '' and port ''. [2021-11-09 17:31:46] DEBUG[21161] res_rtp_asterisk.c: (0x7401c9f0) ICE add candidate: :19202, 2130706431 [2021-11-09 17:31:46] DEBUG[21161] netsock2.c: Splitting 'fe80::7a3a:fe3a:d413:a10b' into... [2021-11-09 17:31:46] DEBUG[21161] netsock2.c: ...host 'fe80::7a3a:fe3a:d413:a10b' and port ''. [2021-11-09 17:31:46] DEBUG[21161] res_rtp_asterisk.c: (0x7401c9f0) ICE add candidate: [fe80::7a3a:fe3a:d413:a10b]:19202, 2130706431 [2021-11-09 17:31:46] DEBUG[21161] res_rtp_asterisk.c: (0x7401c9f0) ICE request STUN TCP RTP candidate [2021-11-09 17:31:46] DEBUG[21161] netsock2.c: Splitting '' into... [2021-11-09 17:31:46] DEBUG[21161] netsock2.c: ...host '' and port ''. [2021-11-09 17:31:46] DEBUG[21161] netsock2.c: Splitting '' into... [2021-11-09 17:31:46] DEBUG[21161] netsock2.c: ...host '' and port ''. [2021-11-09 17:31:46] DEBUG[21161] res_rtp_asterisk.c: (0x7401c9f0) ICE add candidate: :19202, 1694498815 [2021-11-09 17:31:46] DEBUG[21161] rtp_engine.c: RTP instance '0x7401c9f0' is setup and ready to go [2021-11-09 17:31:46] DEBUG[21161] res_rtp_asterisk.c: (0x7401c9f0) ICE stopped [2021-11-09 17:31:46] VERBOSE[21161] netsock2.c: Using SIP RTP Audio TOS bits 184 [2021-11-09 17:31:46] VERBOSE[21161] netsock2.c: Using SIP RTP Audio TOS bits 184 in TCLASS field. [2021-11-09 17:31:46] VERBOSE[21161] netsock2.c: Using SIP RTP Audio CoS mark 5 [2021-11-09 17:31:46] DEBUG[21161] netsock2.c: Splitting '' into... [2021-11-09 17:31:46] DEBUG[21161] netsock2.c: ...host '' and port ''. [2021-11-09 17:31:46] DEBUG[21161] res_rtp_asterisk.c: (0x7401c9f0) RTCP setup on RTP instance [2021-11-09 17:31:46] DEBUG[21161] res_srtp.c: local_key64 kSC8pYqZ9PzxDleBG4tYR4ociB/ceWNVx0yxW0JK len 40 [2021-11-09 17:31:46] DEBUG[21161] res_srtp.c: local_key64 YHq+56LQqv8suomMPvW05nf6sWfXveKZ4WxgL+D+21eENWqWI54LQUU2aOLyBw== len 64 [2021-11-09 17:31:46] DEBUG[21161] res_srtp.c: Adding new policy for SSRC 573893026 [2021-11-09 17:31:46] DEBUG[21161] res_srtp.c: SRTP policy activated [2021-11-09 17:31:46] DEBUG[21161] res_srtp.c: Crypto line: a=crypto:5 AES_256_CM_HMAC_SHA1_80 inline:YHq+56LQqv8suomMPvW05nf6sWfXveKZ4WxgL+D+21eENWqWI54LQUU2aOLyBw== [2021-11-09 17:31:46] DEBUG[21161] rtp_engine.c: Setting tx payload type 8 based on m type on 0x6b64d1ac [2021-11-09 17:31:46] DEBUG[21161] rtp_engine.c: Setting tx payload type 3 based on m type on 0x6b64d1ac [2021-11-09 17:31:46] DEBUG[21161] rtp_engine.c: Crossover copying tx to rx payload mapping 3 (0x15502c8) from 0x6b64d1ac to 0x6b64d1ac [2021-11-09 17:31:46] DEBUG[21161] rtp_engine.c: Crossover copying tx to rx payload mapping 8 (0xfb5708) from 0x6b64d1ac to 0x6b64d1ac [2021-11-09 17:31:46] DEBUG[21161] rtp_engine.c: Crossover copying tx to rx payload mapping 101 (0x7409f670) from 0x6b64d1ac to 0x6b64d1ac [2021-11-09 17:31:46] DEBUG[21161] rtp_engine.c: Copying rx payload mapping 3 (0x15502c8) from 0x6b64d1ac to 0x7401cbac [2021-11-09 17:31:46] DEBUG[21161] rtp_engine.c: Copying rx payload mapping 8 (0xfb5708) from 0x6b64d1ac to 0x7401cbac [2021-11-09 17:31:46] DEBUG[21161] rtp_engine.c: Copying rx payload mapping 101 (0x7409f670) from 0x6b64d1ac to 0x7401cbac [2021-11-09 17:31:46] DEBUG[21161] rtp_engine.c: Copying tx payload mapping 3 (0x15502c8) from 0x6b64d1ac to 0x7401cbac [2021-11-09 17:31:46] DEBUG[21161] rtp_engine.c: Copying tx payload mapping 8 (0xfb5708) from 0x6b64d1ac to 0x7401cbac [2021-11-09 17:31:46] DEBUG[21161] rtp_engine.c: Copying tx payload mapping 101 (0x7409f670) from 0x6b64d1ac to 0x7401cbac [2021-11-09 17:31:46] DEBUG[21161] res_pjsip_session.c: 331: Media stream 0:audio-0:audio:sendrecv (alaw) handled by audio [2021-11-09 17:31:46] DEBUG[21161] res_pjsip_session.c: 331: Done with stream 0:audio-0:audio:sendrecv (alaw) [2021-11-09 17:31:46] DEBUG[21161] res_pjsip_session.c: 331: Handled? yes [2021-11-09 17:31:46] DEBUG[21161] res_pjsip_session.c: 331 [2021-11-09 17:31:46] DEBUG[21161] res_pjsip_session.c: 331: Processing streams [2021-11-09 17:31:46] DEBUG[21161] res_pjsip_session.c: 331: Processing stream 0:audio-0:audio:sendrecv (alaw) [2021-11-09 17:31:46] DEBUG[21161] res_pjsip_session.c: 331 Adding position 0 [2021-11-09 17:31:46] DEBUG[21161] res_pjsip_session.c: Using existing media_session [2021-11-09 17:31:46] DEBUG[21161] res_rtp_asterisk.c: (0x7401c9f0) RTCP ignoring duplicate property [2021-11-09 17:31:46] DEBUG[21161] res_srtp.c: Crypto line: a=crypto:5 AES_256_CM_HMAC_SHA1_80 inline:YHq+56LQqv8suomMPvW05nf6sWfXveKZ4WxgL+D+21eENWqWI54LQUU2aOLyBw== [2021-11-09 17:31:46] DEBUG[21161] res_pjsip_session.c: 331: Stream 0:audio-0:audio:sendrecv (alaw) added [2021-11-09 17:31:46] DEBUG[21161] res_pjsip_session.c: 331: Done with 0:audio-0:audio:sendrecv (alaw) [2021-11-09 17:31:46] DEBUG[21161] res_pjsip_session.c: 331: Adding bundle groups (if available) [2021-11-09 17:31:46] DEBUG[21161] res_pjsip_session.c: 331: Copying connection details [2021-11-09 17:31:46] DEBUG[21161] res_pjsip_session.c: 331: Processing media 0 [2021-11-09 17:31:46] DEBUG[21161] res_pjsip_session.c: 331: Media 0 reset [2021-11-09 17:31:46] DEBUG[21161] res_pjsip_session.c: 331 [2021-11-09 17:31:46] DEBUG[21161] res_pjsip_session.c: 331: Method is INVITE [2021-11-09 17:31:46] DEBUG[21161] chan_pjsip.c: 331 [2021-11-09 17:31:46] DEBUG[21161] stasis.c: Creating topic. name: channel:1636475506.726, detail: [2021-11-09 17:31:46] DEBUG[21161] stasis.c: Topic 'channel:1636475506.726': 0x7405df78 created [2021-11-09 17:31:46] DEBUG[21161] stasis.c: Creating topic. name: cache:803/channel:1636475506.726, detail: [2021-11-09 17:31:46] DEBUG[21161] stasis.c: Topic 'cache:803/channel:1636475506.726': 0x7409fd98 created [2021-11-09 17:31:46] DEBUG[6884] manager.c: Examining AMI event: Event: Newchannel Privilege: call,all Channel: PJSIP/331-00000112 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 331 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: from-internal Exten: *43 Priority: 1 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 [2021-11-09 17:31:46] DEBUG[21161] channel.c: Channel 0x740eb6b8 'PJSIP/331-00000112' allocated [2021-11-09 17:31:46] DEBUG[6884] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 331 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: de_DE AccountCode: Context: from-internal Exten: *43 Priority: 1 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Variable: SIPDOMAIN Value: [2021-11-09 17:31:46] DEBUG[21161] chan_pjsip.c: PJSIP/331-00000112 [2021-11-09 17:31:46] DEBUG[21161] chan_pjsip.c: Started PBX on new PJSIP channel PJSIP/331-00000112 [2021-11-09 17:31:46] DEBUG[21161] res_pjsip_session.c: PJSIP/331-00000112 [2021-11-09 17:31:46] DEBUG[21161] res_pjsip_session.c: PJSIP/331-00000112 [2021-11-09 17:31:46] DEBUG[22839][C-00000047] pbx.c: Launching 'Set' [2021-11-09 17:31:46] VERBOSE[22839][C-00000047] pbx.c: Executing [*43@from-internal:1] Set("PJSIP/331-00000112", "CONNECTEDLINE(name-charset,i)=utf8") in new stack [2021-11-09 17:31:46] DEBUG[6884] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 331 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: de_DE AccountCode: Context: from-internal Exten: *43 Priority: 1 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Extension: *43 Application: Set AppData: CONNECTEDLINE(name-charset,i)=utf8 [2021-11-09 17:31:46] DEBUG[22839][C-00000047] pbx.c: Launching 'Set' [2021-11-09 17:31:46] VERBOSE[22839][C-00000047] pbx.c: Executing [*43@from-internal:2] Set("PJSIP/331-00000112", "CONNECTEDLINE(name,i)=Echo Test") in new stack [2021-11-09 17:31:46] DEBUG[6884] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 331 CallerIDName: ConnectedLineNum: ConnectedLineName: Language: de_DE AccountCode: Context: from-internal Exten: *43 Priority: 2 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Extension: *43 Application: Set AppData: CONNECTEDLINE(name,i)=Echo Test [2021-11-09 17:31:46] DEBUG[22839][C-00000047] pbx.c: Launching 'Set' [2021-11-09 17:31:46] VERBOSE[22839][C-00000047] pbx.c: Executing [*43@from-internal:3] Set("PJSIP/331-00000112", "CONNECTEDLINE(num,i)=*43") in new stack [2021-11-09 17:31:46] DEBUG[6884] manager.c: Examining AMI event: Event: NewConnectedLine Privilege: call,all Channel: PJSIP/331-00000112 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 331 CallerIDName: ConnectedLineNum: ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: from-internal Exten: *43 Priority: 2 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 [2021-11-09 17:31:46] DEBUG[22839][C-00000047] pbx.c: Launching 'Answer' [2021-11-09 17:31:46] VERBOSE[22839][C-00000047] pbx.c: Executing [*43@from-internal:4] Answer("PJSIP/331-00000112", "") in new stack [2021-11-09 17:31:46] DEBUG[6884] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 331 CallerIDName: ConnectedLineNum: ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: from-internal Exten: *43 Priority: 3 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Extension: *43 Application: Set AppData: CONNECTEDLINE(num,i)=*43 [2021-11-09 17:31:46] DEBUG[1119] devicestate.c: No provider found, checking channel drivers for PJSIP - 331 [2021-11-09 17:31:46] DEBUG[6884] manager.c: Examining AMI event: Event: NewConnectedLine Privilege: call,all Channel: PJSIP/331-00000112 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: from-internal Exten: *43 Priority: 3 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 [2021-11-09 17:31:46] DEBUG[1119] devicestate.c: Changing state for PJSIP/331 - state 2 (In use) [2021-11-09 17:31:46] DEBUG[1122] devicestate.c: No provider found, checking channel drivers for SIP - 99331 [2021-11-09 17:31:46] DEBUG[1122] chan_sip.c: Checking device state for peer 99331 [2021-11-09 17:31:46] DEBUG[1122] app_queue.c: Removed from pending_members [2021-11-09 17:31:46] DEBUG[1122] app_queue.c: Removed from pending_members [2021-11-09 17:31:46] DEBUG[1122] app_queue.c: Removed from pending_members [2021-11-09 17:31:46] DEBUG[1122] app_queue.c: Removed from pending_members [2021-11-09 17:31:46] DEBUG[1122] app_queue.c: Removed from pending_members [2021-11-09 17:31:46] DEBUG[1122] app_queue.c: Removed from pending_members [2021-11-09 17:31:46] DEBUG[1122] app_queue.c: Removed from pending_members [2021-11-09 17:31:46] DEBUG[1122] app_queue.c: Removed from pending_members [2021-11-09 17:31:46] DEBUG[1122] app_queue.c: Removed from pending_members [2021-11-09 17:31:46] DEBUG[1122] app_queue.c: Removed from pending_members [2021-11-09 17:31:46] DEBUG[1122] app_queue.c: Removed from pending_members [2021-11-09 17:31:46] DEBUG[1122] app_queue.c: Extension '331@ext-local' changed to state '2' (In use) [2021-11-09 17:31:46] DEBUG[1122] app_queue.c: Extension '331@ext-local' changed to state '2' (In use) [2021-11-09 17:31:46] DEBUG[1203] app_queue.c: Device 'PJSIP/331' changed to state '2' (In use) but we don't care because they're not a member of any queue. [2021-11-09 17:31:46] DEBUG[6884] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: from-internal Exten: *43 Priority: 4 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Extension: *43 Application: Answer AppData: [2021-11-09 17:31:46] DEBUG[1122] app_queue.c: Extension '331@ext-local' changed to state '2' (In use) [2021-11-09 17:31:46] DEBUG[1122] app_queue.c: Extension '331@ext-local' changed to state '2' (In use) [2021-11-09 17:31:46] DEBUG[6884] manager.c: Examining AMI event: Event: Newstate Privilege: call,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: from-internal Exten: *43 Priority: 4 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 [2021-11-09 17:31:46] DEBUG[1122] app_queue.c: Extension '331@ext-local' changed to state '2' (In use) [2021-11-09 17:31:46] DEBUG[1122] app_queue.c: Extension '331@ext-local' changed to state '2' (In use) [2021-11-09 17:31:46] DEBUG[1122] app_queue.c: Extension '331@ext-local' changed to state '2' (In use) [2021-11-09 17:31:46] DEBUG[1122] app_queue.c: Extension '331@ext-local' changed to state '2' (In use) [2021-11-09 17:31:46] DEBUG[1122] app_queue.c: Extension '331@ext-local' changed to state '2' (In use) [2021-11-09 17:31:46] DEBUG[21161] res_pjsip_session.c: PJSIP/331-00000112 [2021-11-09 17:31:46] DEBUG[1122] app_queue.c: Extension '331@ext-local' changed to state '2' (In use) [2021-11-09 17:31:46] DEBUG[21161] res_pjsip_session.c: PJSIP/331-00000112: Applying negotiated SDP media stream 'audio' using audio SDP handler [2021-11-09 17:31:46] DEBUG[21161] res_rtp_asterisk.c: (0x7401c9f0) RTCP ignoring duplicate property [2021-11-09 17:31:46] DEBUG[21161] res_srtp.c: SRTP remote key unchanged; maintaining current policy [2021-11-09 17:31:46] DEBUG[21161] netsock2.c: Splitting '' into... [2021-11-09 17:31:46] DEBUG[21161] netsock2.c: ...host '' and port ''. [2021-11-09 17:31:46] DEBUG[1122] app_queue.c: Extension '331@ext-local' changed to state '2' (In use) [2021-11-09 17:31:46] DEBUG[21161] acl.c: For destination '', our source address is ''. [2021-11-09 17:31:46] DEBUG[21161] res_rtp_asterisk.c: (0x7401c9f0) RTCP setting address on RTP instance [2021-11-09 17:31:46] VERBOSE[21161] res_rtp_asterisk.c: 0x740cd5d8 -- Strict RTP learning after remote address set to: :58962 [2021-11-09 17:31:46] DEBUG[21161] rtp_engine.c: Setting tx payload type 8 based on m type on 0x6b64d0d4 [2021-11-09 17:31:46] DEBUG[21161] rtp_engine.c: Setting tx payload type 3 based on m type on 0x6b64d0d4 [2021-11-09 17:31:46] DEBUG[21161] rtp_engine.c: Copying tx payload mapping 3 (0x15502c8) from 0x6b64d0d4 to 0x7401cbac [2021-11-09 17:31:46] DEBUG[21161] rtp_engine.c: Copying tx payload mapping 8 (0xfb5708) from 0x6b64d0d4 to 0x7401cbac [2021-11-09 17:31:46] DEBUG[21161] rtp_engine.c: Copying tx payload mapping 101 (0x74033d20) from 0x6b64d0d4 to 0x7401cbac [2021-11-09 17:31:46] DEBUG[21161] channel.c: Channel PJSIP/331-00000112 setting read format path: alaw -> alaw [2021-11-09 17:31:46] DEBUG[21161] channel.c: Channel PJSIP/331-00000112 setting write format path: alaw -> alaw [2021-11-09 17:31:46] DEBUG[21161] res_rtp_asterisk.c: (0x7401c9f0) DTLS - ast_rtp_activate rtp=0x740cd5d8 - setup and perform DTLS' [2021-11-09 17:31:46] DEBUG[21161] res_rtp_asterisk.c: (0x740cd5d8) DTLS perform handshake - ssl = (nil), setup = 0 [2021-11-09 17:31:46] DEBUG[21161] res_rtp_asterisk.c: (0x740cd5d8) DTLS perform handshake - ssl = (nil), setup = 0 [2021-11-09 17:31:46] DEBUG[21161] res_pjsip_session.c: PJSIP/331-00000112: Applied negotiated SDP media stream 'audio' using audio SDP handler [2021-11-09 17:31:46] DEBUG[6884] manager.c: Examining AMI event: Event: ExtensionStatus Privilege: call,all Exten: 331 Context: ext-local Hint: PJSIP/331&SIP/99331&Custom:DND331,CustomPresence:331 Status: 1 StatusText: InUse [2021-11-09 17:31:46] DEBUG[21161] res_pjsip_session.c: PJSIP/331-00000112 [2021-11-09 17:31:46] DEBUG[21161] res_pjsip_session.c: PJSIP/331-00000112: Method is INVITE, Response is 200 OK [2021-11-09 17:31:46] DEBUG[21161] res_pjsip_session.c: PJSIP/331-00000112 [2021-11-09 17:31:46] DEBUG[6884] manager.c: Examining AMI event: Event: DeviceStateChange Privilege: call,all Device: PJSIP/331 State: INUSE [2021-11-09 17:31:46] DEBUG[6884] manager.c: Examining AMI event: Event: QueueMemberStatus Privilege: agent,all Queue: 886 MemberName: Interface: Local/331@from-queue/n StateInterface: hint:331@ext-local Membership: static Penalty: 0 CallsTaken: 0 LastCall: 0 LastPause: 0 InCall: 0 Status: 2 Paused: 0 PausedReason: Ringinuse: 1 Wrapuptime: 0 [2021-11-09 17:31:46] DEBUG[21161] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to :5061 (this may be re-written again later) [2021-11-09 17:31:46] DEBUG[6884] manager.c: Examining AMI event: Event: QueueMemberStatus Privilege: agent,all Queue: 881 MemberName: Interface: Local/331@from-queue/n StateInterface: hint:331@ext-local Membership: static Penalty: 0 CallsTaken: 0 LastCall: 0 LastPause: 0 InCall: 0 Status: 2 Paused: 0 PausedReason: Ringinuse: 1 Wrapuptime: 0 [2021-11-09 17:31:46] DEBUG[6884] manager.c: Examining AMI event: Event: QueueMemberStatus Privilege: agent,all Queue: 300 MemberName: Interface: Local/331@from-queue/n StateInterface: hint:331@ext-local Membership: static Penalty: 0 CallsTaken: 0 LastCall: 0 LastPause: 0 InCall: 0 Status: 2 Paused: 0 PausedReason: Ringinuse: 1 Wrapuptime: 0 [2021-11-09 17:31:46] DEBUG[6884] manager.c: Examining AMI event: Event: QueueMemberStatus Privilege: agent,all Queue: 883 MemberName: Interface: Local/331@from-queue/n StateInterface: hint:331@ext-local Membership: static Penalty: 0 CallsTaken: 0 LastCall: 0 LastPause: 0 InCall: 0 Status: 2 Paused: 0 PausedReason: Ringinuse: 1 Wrapuptime: 0 [2021-11-09 17:31:46] VERBOSE[21161] res_pjsip_logger.c: <--- Transmitting SIP response (997 bytes) to TLS::48950 ---> SIP/2.0 200 OK Via: SIP/2.0/TLS :41309;rport=48950;received=;branch=z9hG4bK-524287-1---9d893386b9e0b46d Call-ID: CQdLbgtd0ZPU7DIOH8w5hg.. From: >;tag=3a643242 To: >;tag=a911c608-2a7e-4a75-9263-164ed164031d CSeq: 2 INVITE Server: FPBX-15.0.17.55(16.18.0) Contact: :5061;transport=TLS> Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER Supported: 100rel, timer, replaces, norefersub P-Asserted-Identity: "Echo Test" > Content-Type: application/sdp Content-Length: 333 v=0 o=- 92968048 3 IN IP4 s=Asterisk c=IN IP4 t=0 0 m=audio 19202 RTP/SAVP 8 101 a=crypto:5 AES_256_CM_HMAC_SHA1_80 inline:YHq+56LQqv8suomMPvW05nf6sWfXveKZ4WxgL+D+21eENWqWI54LQUU2aOLyBw== a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:150 a=sendrecv [2021-11-09 17:31:46] DEBUG[6884] manager.c: Examining AMI event: Event: QueueMemberStatus Privilege: agent,all Queue: 882 MemberName: Interface: Local/331@from-queue/n StateInterface: hint:331@ext-local Membership: static Penalty: 0 CallsTaken: 0 LastCall: 0 LastPause: 0 InCall: 0 Status: 2 Paused: 0 PausedReason: Ringinuse: 1 Wrapuptime: 0 [2021-11-09 17:31:46] DEBUG[6884] manager.c: Examining AMI event: Event: QueueMemberStatus Privilege: agent,all Queue: 590 MemberName: Interface: Local/331@from-queue/n StateInterface: hint:331@ext-local Membership: static Penalty: 0 CallsTaken: 0 LastCall: 0 LastPause: 0 InCall: 0 Status: 2 Paused: 0 PausedReason: Ringinuse: 1 Wrapuptime: 0 [2021-11-09 17:31:46] DEBUG[6884] manager.c: Examining AMI event: Event: QueueMemberStatus Privilege: agent,all Queue: 330 MemberName: Interface: Local/331@from-queue/n StateInterface: hint:331@ext-local Membership: static Penalty: 0 CallsTaken: 0 LastCall: 0 LastPause: 0 InCall: 0 Status: 2 Paused: 0 PausedReason: Ringinuse: 1 Wrapuptime: 0 [2021-11-09 17:31:46] DEBUG[6884] manager.c: Examining AMI event: Event: QueueMemberStatus Privilege: agent,all Queue: 500 MemberName: Interface: Local/331@from-queue/n StateInterface: hint:331@ext-local Membership: static Penalty: 0 CallsTaken: 0 LastCall: 0 LastPause: 0 InCall: 0 Status: 2 Paused: 0 PausedReason: Ringinuse: 1 Wrapuptime: 0 [2021-11-09 17:31:46] DEBUG[21161] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [2021-11-09 17:31:46] DEBUG[21161] res_pjsip_session.c: The state change pertains to the endpoint '331(PJSIP/331-00000112)' [2021-11-09 17:31:46] DEBUG[6884] manager.c: Examining AMI event: Event: QueueMemberStatus Privilege: agent,all Queue: 885 MemberName: Interface: Local/331@from-queue/n StateInterface: hint:331@ext-local Membership: static Penalty: 0 CallsTaken: 0 LastCall: 0 LastPause: 0 InCall: 0 Status: 2 Paused: 0 PausedReason: Ringinuse: 1 Wrapuptime: 0 [2021-11-09 17:31:46] DEBUG[21161] res_pjsip_session.c: The inv session still has an invite_tsx (0x6a86c384) [2021-11-09 17:31:46] DEBUG[21161] res_pjsip_session.c: There is no transaction involved in this state change [2021-11-09 17:31:46] DEBUG[21161] res_pjsip_session.c: The current inv state is CONNECTING [2021-11-09 17:31:46] DEBUG[21161] res_pjsip_session.c: PJSIP/331-00000112: Source of transaction state change is TX_MSG [2021-11-09 17:31:46] DEBUG[6884] manager.c: Examining AMI event: Event: QueueMemberStatus Privilege: agent,all Queue: 884 MemberName: Interface: Local/331@from-queue/n StateInterface: hint:331@ext-local Membership: static Penalty: 0 CallsTaken: 0 LastCall: 0 LastPause: 0 InCall: 0 Status: 2 Paused: 0 PausedReason: Ringinuse: 1 Wrapuptime: 0 [2021-11-09 17:31:46] DEBUG[21161] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [2021-11-09 17:31:46] DEBUG[21161] res_pjsip_session.c: The state change pertains to the endpoint '331(PJSIP/331-00000112)' [2021-11-09 17:31:46] DEBUG[21161] res_pjsip_session.c: The inv session still has an invite_tsx (0x6a86c384) [2021-11-09 17:31:46] DEBUG[21161] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x6a86c384 [2021-11-09 17:31:46] DEBUG[6884] manager.c: Examining AMI event: Event: QueueMemberStatus Privilege: agent,all Queue: 887 MemberName: Interface: Local/331@from-queue/n StateInterface: hint:331@ext-local Membership: static Penalty: 0 CallsTaken: 0 LastCall: 0 LastPause: 0 InCall: 0 Status: 2 Paused: 0 PausedReason: Ringinuse: 1 Wrapuptime: 0 [2021-11-09 17:31:46] DEBUG[21161] res_pjsip_session.c: The current transaction state is Completed [2021-11-09 17:31:46] DEBUG[21161] res_pjsip_session.c: The transaction state change event is TX_MSG [2021-11-09 17:31:46] DEBUG[21161] res_pjsip_session.c: The current inv state is CONNECTING [2021-11-09 17:31:46] DEBUG[22839][C-00000047] chan_pjsip.c: PJSIP/331-00000112: Indicated Stop generators [2021-11-09 17:31:46] DEBUG[22839][C-00000047] chan_pjsip.c: PJSIP/331-00000112 [2021-11-09 17:31:46] DEBUG[22842] manager.c: Running action 'Login' [2021-11-09 17:31:47] DEBUG[1153] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to :5061 (this may be re-written again later) [2021-11-09 17:31:47] VERBOSE[1153] res_pjsip_logger.c: <--- Transmitting SIP response (997 bytes) to TLS::48950 ---> SIP/2.0 200 OK Via: SIP/2.0/TLS :41309;rport=48950;received=;branch=z9hG4bK-524287-1---9d893386b9e0b46d Call-ID: CQdLbgtd0ZPU7DIOH8w5hg.. From: >;tag=3a643242 To: >;tag=a911c608-2a7e-4a75-9263-164ed164031d CSeq: 2 INVITE Server: FPBX-15.0.17.55(16.18.0) Contact: :5061;transport=TLS> Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER Supported: 100rel, timer, replaces, norefersub P-Asserted-Identity: "Echo Test" > Content-Type: application/sdp Content-Length: 333 v=0 o=- 92968048 3 IN IP4 s=Asterisk c=IN IP4 t=0 0 m=audio 19202 RTP/SAVP 8 101 a=crypto:5 AES_256_CM_HMAC_SHA1_80 inline:YHq+56LQqv8suomMPvW05nf6sWfXveKZ4WxgL+D+21eENWqWI54LQUU2aOLyBw== a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:150 a=sendrecv [2021-11-09 17:31:47] DEBUG[22839][C-00000047] channel.c: Didn't receive a media frame from PJSIP/331-00000112 within 500 ms of answering. Continuing anyway [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx.c: Launching 'Macro' [2021-11-09 17:31:47] VERBOSE[22839][C-00000047] pbx.c: Executing [*43@from-internal:5] Macro("PJSIP/331-00000112", "user-callerid,") in new stack [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: from-internal Exten: *43 Priority: 5 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Extension: *43 Application: Macro AppData: user-callerid, [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: from-internal Exten: *43 Priority: 5 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Variable: MACRO_EXTEN Value: *43 [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: from-internal Exten: *43 Priority: 5 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Variable: MACRO_CONTEXT Value: from-internal [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: from-internal Exten: *43 Priority: 5 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Variable: MACRO_PRIORITY Value: 5 [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: from-internal Exten: *43 Priority: 5 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Variable: MACRO_DEPTH Value: 1 [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: from-internal Exten: *43 Priority: 5 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Variable: ARG1 Value: [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: from-internal Exten: *43 Priority: 5 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Variable: MACRO_DEPTH Value: 1 [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Result of 'UNIQUEID' is '1636475506.726' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx.c: Launching 'Set' [2021-11-09 17:31:47] VERBOSE[22839][C-00000047] pbx.c: Executing [s@macro-user-callerid:1] Set("PJSIP/331-00000112", "TOUCH_MONITOR=1636475506.726") in new stack [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 1 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Extension: s Application: Set AppData: TOUCH_MONITOR=1636475506.726 [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 1 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Variable: TOUCH_MONITOR Value: 1636475506.726 [2021-11-09 17:31:47] DEBUG[22839][C-00000047] app_macro.c: Executed application: Set [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 1 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Variable: MACRO_DEPTH Value: 1 [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Evaluating 'CHANNEL' (from 'CHANNEL}' len 7) [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Result of 'CHANNEL' is 'PJSIP/331-00000112' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Function CUT(CHANNEL,@,2) result is '' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx.c: Launching 'Set' [2021-11-09 17:31:47] VERBOSE[22839][C-00000047] pbx.c: Executing [s@macro-user-callerid:2] Set("PJSIP/331-00000112", "CHANCONTEXT=") in new stack [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 2 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Extension: s Application: Set AppData: CHANCONTEXT= [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 2 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Variable: CHANCONTEXT Value: [2021-11-09 17:31:47] DEBUG[22839][C-00000047] app_macro.c: Executed application: Set [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 2 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Variable: MACRO_DEPTH Value: 1 [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Evaluating 'CHANCONTEXT' (from 'CHANCONTEXT}' len 11) [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Result of 'CHANCONTEXT' is '' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Function CUT(CHANCONTEXT,-,1) result is '' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx.c: Launching 'Set' [2021-11-09 17:31:47] VERBOSE[22839][C-00000047] pbx.c: Executing [s@macro-user-callerid:3] Set("PJSIP/331-00000112", "CHANCONTEXT=") in new stack [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 3 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Extension: s Application: Set AppData: CHANCONTEXT= [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 3 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Variable: CHANCONTEXT Value: [2021-11-09 17:31:47] DEBUG[22839][C-00000047] app_macro.c: Executed application: Set [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 3 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Variable: MACRO_DEPTH Value: 1 [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Evaluating 'CHANNEL' (from 'CHANNEL}' len 7) [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Result of 'CHANNEL' is 'PJSIP/331-00000112' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Function CUT(CHANNEL,/,2) result is '331-00000112' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx.c: Launching 'Set' [2021-11-09 17:31:47] VERBOSE[22839][C-00000047] pbx.c: Executing [s@macro-user-callerid:4] Set("PJSIP/331-00000112", "CHANEXTENCONTEXT=331-00000112") in new stack [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 4 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Extension: s Application: Set AppData: CHANEXTENCONTEXT=331-00000112 [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 4 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Variable: CHANEXTENCONTEXT Value: 331-00000112 [2021-11-09 17:31:47] DEBUG[22839][C-00000047] app_macro.c: Executed application: Set [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 4 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Variable: MACRO_DEPTH Value: 1 [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Evaluating 'CHANEXTENCONTEXT' (from 'CHANEXTENCONTEXT}' len 16) [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Result of 'CHANEXTENCONTEXT' is '331-00000112' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Function CUT(CHANEXTENCONTEXT,@,1) result is '331-00000112' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx.c: Launching 'Set' [2021-11-09 17:31:47] VERBOSE[22839][C-00000047] pbx.c: Executing [s@macro-user-callerid:5] Set("PJSIP/331-00000112", "CHANEXTEN=331-00000112") in new stack [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 5 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Extension: s Application: Set AppData: CHANEXTEN=331-00000112 [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 5 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Variable: CHANEXTEN Value: 331-00000112 [2021-11-09 17:31:47] DEBUG[22839][C-00000047] app_macro.c: Executed application: Set [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 5 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Variable: MACRO_DEPTH Value: 1 [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Result of 'CHANCONTEXT' is '' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Expression result is '0' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Result of 'CHANEXTEN' is '331-00000112' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Function CALLERID(number) result is '331' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Function IF(0?331-00000112:331) result is '331' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx.c: Launching 'Set' [2021-11-09 17:31:47] VERBOSE[22839][C-00000047] pbx.c: Executing [s@macro-user-callerid:6] Set("PJSIP/331-00000112", "CALLERID(number)=331") in new stack [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 6 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Extension: s Application: Set AppData: CALLERID(number)=331 [2021-11-09 17:31:47] DEBUG[22839][C-00000047] app_macro.c: Executed application: Set [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 6 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Variable: MACRO_DEPTH Value: 1 [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Result of 'AMPUSER' is NULL [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Expression result is '1' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Function CALLERID(number) result is '331' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Result of 'AMPUSER' is NULL [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Function IF(1?331:) result is '331' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx.c: Launching 'Set' [2021-11-09 17:31:47] VERBOSE[22839][C-00000047] pbx.c: Executing [s@macro-user-callerid:7] Set("PJSIP/331-00000112", "AMPUSER=331") in new stack [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 7 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Extension: s Application: Set AppData: AMPUSER=331 [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 7 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Variable: AMPUSER Value: 331 [2021-11-09 17:31:47] DEBUG[22839][C-00000047] app_macro.c: Executed application: Set [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 7 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Variable: MACRO_DEPTH Value: 1 [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Evaluating 'CHANNEL' (from 'CHANNEL}' len 7) [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Result of 'CHANNEL' is 'PJSIP/331-00000112' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Function CUT(CHANNEL,/,2) result is '331-00000112' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx.c: Launching 'Set' [2021-11-09 17:31:47] VERBOSE[22839][C-00000047] pbx.c: Executing [s@macro-user-callerid:8] Set("PJSIP/331-00000112", "HOTDESCKCHAN=331-00000112") in new stack [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 8 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Extension: s Application: Set AppData: HOTDESCKCHAN=331-00000112 [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 8 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Variable: HOTDESCKCHAN Value: 331-00000112 [2021-11-09 17:31:47] DEBUG[22839][C-00000047] app_macro.c: Executed application: Set [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 8 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Variable: MACRO_DEPTH Value: 1 [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Evaluating 'HOTDESCKCHAN' (from 'HOTDESCKCHAN}' len 12) [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Result of 'HOTDESCKCHAN' is '331-00000112' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Function CUT(HOTDESCKCHAN,-,1) result is '331' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx.c: Launching 'Set' [2021-11-09 17:31:47] VERBOSE[22839][C-00000047] pbx.c: Executing [s@macro-user-callerid:9] Set("PJSIP/331-00000112", "HOTDESKEXTEN=331") in new stack [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 9 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Extension: s Application: Set AppData: HOTDESKEXTEN=331 [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 9 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Variable: HOTDESKEXTEN Value: 331 [2021-11-09 17:31:47] DEBUG[22839][C-00000047] app_macro.c: Executed application: Set [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 9 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Variable: MACRO_DEPTH Value: 1 [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx.c: Launching 'Set' [2021-11-09 17:31:47] VERBOSE[22839][C-00000047] pbx.c: Executing [s@macro-user-callerid:10] Set("PJSIP/331-00000112", "HOTDESKCALL=0") in new stack [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 10 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Extension: s Application: Set AppData: HOTDESKCALL=0 [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 10 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Variable: HOTDESKCALL Value: 0 [2021-11-09 17:31:47] DEBUG[22839][C-00000047] app_macro.c: Executed application: Set [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 10 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Variable: MACRO_DEPTH Value: 1 [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Result of 'HOTDESKEXTEN' is '331' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] db.c: Unable to find key '331/user' in family 'EDEVICE' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] func_db.c: DB: EDEVICE/331/user not found in database. [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Function DB(EDEVICE/331/user) result is '' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Expression result is '0' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx.c: Launching 'ExecIf' [2021-11-09 17:31:47] VERBOSE[22839][C-00000047] pbx.c: Executing [s@macro-user-callerid:11] ExecIf("PJSIP/331-00000112", "0?Set(HOTDESKCALL=1)") in new stack [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 11 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Extension: s Application: ExecIf AppData: 0?Set(HOTDESKCALL=1) [2021-11-09 17:31:47] DEBUG[22839][C-00000047] app_macro.c: Executed application: ExecIf [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Evaluating 'DB(EDEVICE/${HOTDESKEXTEN}/user)' (from 'DB(EDEVICE/${HOTDESKEXTEN}/user)}"="DummyUser"' len 32) [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Evaluating 'HOTDESKEXTEN' (from 'HOTDESKEXTEN}/user)' len 12) [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Result of 'HOTDESKEXTEN' is '331' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] db.c: Unable to find key '331/user' in family 'EDEVICE' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] func_db.c: DB: EDEVICE/331/user not found in database. [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Function DB(EDEVICE/331/user) result is '' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Expression result is '0' [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 11 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Variable: MACRO_DEPTH Value: 1 [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Result of 'HOTDESKCALL' is '0' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Expression result is '0' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Result of 'HOTDESKEXTEN' is '331' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] db.c: Unable to find key '331/location' in family 'EDEVICE' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] func_db.c: DB: EDEVICE/331/location not found in database. [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Function DB(EDEVICE/331/location) result is '' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx.c: Launching 'ExecIf' [2021-11-09 17:31:47] VERBOSE[22839][C-00000047] pbx.c: Executing [s@macro-user-callerid:12] ExecIf("PJSIP/331-00000112", "0?Set(CALLERID(name)=)") in new stack [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 12 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Extension: s Application: ExecIf AppData: 0?Set(CALLERID(name)=) [2021-11-09 17:31:47] DEBUG[22839][C-00000047] app_macro.c: Executed application: ExecIf [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Evaluating 'HOTDESKCALL' (from 'HOTDESKCALL}=1' len 11) [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Result of 'HOTDESKCALL' is '0' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Expression result is '0' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Evaluating 'DB(EDEVICE/${HOTDESKEXTEN}/location)' (from 'DB(EDEVICE/${HOTDESKEXTEN}/location)})' len 36) [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Evaluating 'HOTDESKEXTEN' (from 'HOTDESKEXTEN}/location)' len 12) [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Result of 'HOTDESKEXTEN' is '331' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] db.c: Unable to find key '331/location' in family 'EDEVICE' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] func_db.c: DB: EDEVICE/331/location not found in database. [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Function DB(EDEVICE/331/location) result is '' [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 12 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Variable: MACRO_DEPTH Value: 1 [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Evaluating 'CHANNEL' (from 'CHANNEL}' len 7) [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Result of 'CHANNEL' is 'PJSIP/331-00000112' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Function CUT(CHANNEL,@,2) result is '' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Result of 'AMPUSERCIDNAME' is NULL [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Function LEN() result is '0' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Expression result is '0' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx.c: Launching 'GotoIf' [2021-11-09 17:31:47] VERBOSE[22839][C-00000047] pbx.c: Executing [s@macro-user-callerid:13] GotoIf("PJSIP/331-00000112", "0?report") in new stack [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 13 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Extension: s Application: GotoIf AppData: 0?report [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_builtins.c: Not taking any branch [2021-11-09 17:31:47] DEBUG[22839][C-00000047] app_macro.c: Executed application: GotoIf [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 13 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Variable: MACRO_DEPTH Value: 1 [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Result of 'REALCALLERIDNUM' is NULL [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Expression result is '1' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Function CALLERID(number) result is '331' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx.c: Launching 'ExecIf' [2021-11-09 17:31:47] VERBOSE[22839][C-00000047] pbx.c: Executing [s@macro-user-callerid:14] ExecIf("PJSIP/331-00000112", "1?Set(REALCALLERIDNUM=331)") in new stack [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 14 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Extension: s Application: ExecIf AppData: 1?Set(REALCALLERIDNUM=331) [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 14 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Variable: REALCALLERIDNUM Value: 331 [2021-11-09 17:31:47] DEBUG[22839][C-00000047] app_macro.c: Executed application: ExecIf [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Evaluating 'REALCALLERIDNUM:1:2' (from 'REALCALLERIDNUM:1:2}" = ""' len 19) [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Result of 'REALCALLERIDNUM' is '331' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Expression result is '0' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Evaluating 'CALLERID(number)' (from 'CALLERID(number)})' len 16) [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Function CALLERID(number) result is '331' [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 14 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Variable: MACRO_DEPTH Value: 1 [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Result of 'REALCALLERIDNUM' is '331' [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 14 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Variable: DB_RESULT Value: 331 [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Function DB(DEVICE/331/user) result is '331' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx.c: Launching 'Set' [2021-11-09 17:31:47] VERBOSE[22839][C-00000047] pbx.c: Executing [s@macro-user-callerid:15] Set("PJSIP/331-00000112", "AMPUSER=331") in new stack [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 15 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Extension: s Application: Set AppData: AMPUSER=331 [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 15 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Variable: AMPUSER Value: 331 [2021-11-09 17:31:47] DEBUG[22839][C-00000047] app_macro.c: Executed application: Set [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 15 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Variable: MACRO_DEPTH Value: 1 [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Result of 'AMPUSER' is '331' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Expression result is '0' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx.c: Launching 'GotoIf' [2021-11-09 17:31:47] VERBOSE[22839][C-00000047] pbx.c: Executing [s@macro-user-callerid:16] GotoIf("PJSIP/331-00000112", "0?limit") in new stack [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 16 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Extension: s Application: GotoIf AppData: 0?limit [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_builtins.c: Not taking any branch [2021-11-09 17:31:47] DEBUG[22839][C-00000047] app_macro.c: Executed application: GotoIf [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 16 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Variable: MACRO_DEPTH Value: 1 [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Result of 'AMPUSER' is '331' [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 16 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Variable: DB_RESULT Value: [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Function DB(AMPUSER/331/cidname) result is '' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx.c: Launching 'Set' [2021-11-09 17:31:47] VERBOSE[22839][C-00000047] pbx.c: Executing [s@macro-user-callerid:17] Set("PJSIP/331-00000112", "AMPUSERCIDNAME=") in new stack [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 17 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Extension: s Application: Set AppData: AMPUSERCIDNAME= [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 17 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Variable: AMPUSERCIDNAME Value: [2021-11-09 17:31:47] DEBUG[22839][C-00000047] app_macro.c: Executed application: Set [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 17 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Variable: MACRO_DEPTH Value: 1 [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Result of 'ARG2' is NULL [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Result of 'AMPUSER' is '331' [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 17 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Variable: DB_RESULT Value: 331 [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Function DB_EXISTS(AMPUSER/331/cidnum) result is '1' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Result of 'AMPUSER' is '331' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Result of 'AMPUSER' is '331' [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 17 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Variable: DB_RESULT Value: 331 [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Function DB(AMPUSER/331/cidnum) result is '331' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Expression result is '0' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx.c: Launching 'ExecIf' [2021-11-09 17:31:47] VERBOSE[22839][C-00000047] pbx.c: Executing [s@macro-user-callerid:18] ExecIf("PJSIP/331-00000112", "0?Set(__CIDMASQUERADING=TRUE)") in new stack [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 18 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Extension: s Application: ExecIf AppData: 0?Set(__CIDMASQUERADING=TRUE) [2021-11-09 17:31:47] DEBUG[22839][C-00000047] app_macro.c: Executed application: ExecIf [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Evaluating 'ARG2' (from 'ARG2}" != "EXTERNAL" & ${DB_EXISTS(AMPUSER/${AMPUSER}/cidnum)} & "${AMPUSER}" != "${DB(AMPUSER/${AMPUSER}/cidnum)}"' len 4) [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Result of 'ARG2' is NULL [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Evaluating 'DB_EXISTS(AMPUSER/${AMPUSER}/cidnum)' (from 'DB_EXISTS(AMPUSER/${AMPUSER}/cidnum)} & "${AMPUSER}" != "${DB(AMPUSER/${AMPUSER}/cidnum)}"' len 36) [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Evaluating 'AMPUSER' (from 'AMPUSER}/cidnum)' len 7) [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Result of 'AMPUSER' is '331' [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 18 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Variable: DB_RESULT Value: [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Function DB_EXISTS(AMPUSER/331/cidnum) result is '1' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Evaluating 'AMPUSER' (from 'AMPUSER}" != "${DB(AMPUSER/${AMPUSER}/cidnum)}"' len 7) [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Result of 'AMPUSER' is '331' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Evaluating 'DB(AMPUSER/${AMPUSER}/cidnum)' (from 'DB(AMPUSER/${AMPUSER}/cidnum)}"' len 29) [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Evaluating 'AMPUSER' (from 'AMPUSER}/cidnum)' len 7) [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Result of 'AMPUSER' is '331' [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 18 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Variable: DB_RESULT Value: 331 [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Function DB(AMPUSER/331/cidnum) result is '331' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Expression result is '0' [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 18 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Variable: MACRO_DEPTH Value: 1 [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Result of 'AMPUSERCIDNAME' is '' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Expression result is '0' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx.c: Launching 'GotoIf' [2021-11-09 17:31:47] VERBOSE[22839][C-00000047] pbx.c: Executing [s@macro-user-callerid:19] GotoIf("PJSIP/331-00000112", "0?report") in new stack [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 19 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Extension: s Application: GotoIf AppData: 0?report [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_builtins.c: Not taking any branch [2021-11-09 17:31:47] DEBUG[22839][C-00000047] app_macro.c: Executed application: GotoIf [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 19 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Variable: MACRO_DEPTH Value: 1 [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Result of 'ARG2' is NULL [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Result of 'AMPUSER' is '331' [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 19 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Variable: DB_RESULT Value: 331 [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Function DB_EXISTS(AMPUSER/331/cidnum) result is '1' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Expression result is '1' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Result of 'DB_RESULT' is '331' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Result of 'AMPUSER' is '331' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Function IF(1?331:331) result is '331' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx.c: Launching 'Set' [2021-11-09 17:31:47] VERBOSE[22839][C-00000047] pbx.c: Executing [s@macro-user-callerid:20] Set("PJSIP/331-00000112", "AMPUSERCID=331") in new stack [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 20 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Extension: s Application: Set AppData: AMPUSERCID=331 [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 20 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Variable: AMPUSERCID Value: 331 [2021-11-09 17:31:47] DEBUG[22839][C-00000047] app_macro.c: Executed application: Set [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 20 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Variable: MACRO_DEPTH Value: 1 [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Result of 'AMPUSER' is '331' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] db.c: Unable to find key '331/dialopts' in family 'AMPUSER' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Function DB_EXISTS(AMPUSER/331/dialopts) result is '0' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Expression result is '0' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Result of 'DB_RESULT' is '331' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Result of 'DIAL_OPTIONS' is 'HhTtr' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Function IF(0?331:HhTtr) result is 'HhTtr' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx.c: Launching 'Set' [2021-11-09 17:31:47] VERBOSE[22839][C-00000047] pbx.c: Executing [s@macro-user-callerid:21] Set("PJSIP/331-00000112", "__DIAL_OPTIONS=HhTtr") in new stack [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 21 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Extension: s Application: Set AppData: __DIAL_OPTIONS=HhTtr [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 21 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Variable: __DIAL_OPTIONS Value: HhTtr [2021-11-09 17:31:47] DEBUG[22839][C-00000047] app_macro.c: Executed application: Set [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 21 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Variable: MACRO_DEPTH Value: 1 [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Result of 'AMPUSERCIDNAME' is '' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Result of 'AMPUSERCID' is '331' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx.c: Launching 'Set' [2021-11-09 17:31:47] VERBOSE[22839][C-00000047] pbx.c: Executing [s@macro-user-callerid:22] Set("PJSIP/331-00000112", "CALLERID(all)="" <331>") in new stack [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 22 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Extension: s Application: Set AppData: CALLERID(all)="" <331> [2021-11-09 17:31:47] DEBUG[22839][C-00000047] app_macro.c: Executed application: Set [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 22 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Variable: MACRO_DEPTH Value: 1 [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Result of 'ARG2' is NULL [2021-11-09 17:31:47] DEBUG[22839][C-00000047] db.c: Unable to find key '/tech' in family 'DEVICE' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] func_db.c: DB: DEVICE//tech not found in database. [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Function DB(DEVICE//tech) result is '' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Expression result is '0' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Result of 'ARG2' is NULL [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Evaluating 'CUT(DB(DEVICE//dial),/,2)' (from 'CUT(DB(DEVICE//dial),/,2)}' len 25) [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Evaluating 'DB(DEVICE//dial)' (from 'DB(DEVICE//dial)}' len 16) [2021-11-09 17:31:47] DEBUG[22839][C-00000047] db.c: Unable to find key '/dial' in family 'DEVICE' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] func_db.c: DB: DEVICE//dial not found in database. [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Function DB(DEVICE//dial) result is '' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Function CUT(DB(DEVICE//dial),/,2) result is '' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Function CUT(CUT(DB(DEVICE//dial),/,2),@,1) result is '' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx.c: Launching 'ExecIf' [2021-11-09 17:31:47] VERBOSE[22839][C-00000047] pbx.c: Executing [s@macro-user-callerid:23] ExecIf("PJSIP/331-00000112", "0?Set(CUSDIAL=)") in new stack [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 23 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Extension: s Application: ExecIf AppData: 0?Set(CUSDIAL=) [2021-11-09 17:31:47] DEBUG[22839][C-00000047] app_macro.c: Executed application: ExecIf [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Evaluating 'DB(DEVICE/${ARG2}/tech)' (from 'DB(DEVICE/${ARG2}/tech)}"="custom"' len 23) [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Evaluating 'ARG2' (from 'ARG2}/tech)' len 4) [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Result of 'ARG2' is NULL [2021-11-09 17:31:47] DEBUG[22839][C-00000047] db.c: Unable to find key '/tech' in family 'DEVICE' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] func_db.c: DB: DEVICE//tech not found in database. [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Function DB(DEVICE//tech) result is '' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Expression result is '0' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Evaluating 'CUT(CUT(DB(DEVICE/${ARG2}/dial),/,2),@,1)' (from 'CUT(CUT(DB(DEVICE/${ARG2}/dial),/,2),@,1)})' len 41) [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Evaluating 'ARG2' (from 'ARG2}/dial),/,2),@,1)' len 4) [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Result of 'ARG2' is NULL [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Evaluating 'CUT(DB(DEVICE//dial),/,2)' (from 'CUT(DB(DEVICE//dial),/,2)}' len 25) [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Evaluating 'DB(DEVICE//dial)' (from 'DB(DEVICE//dial)}' len 16) [2021-11-09 17:31:47] DEBUG[22839][C-00000047] db.c: Unable to find key '/dial' in family 'DEVICE' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] func_db.c: DB: DEVICE//dial not found in database. [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Function DB(DEVICE//dial) result is '' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Function CUT(DB(DEVICE//dial),/,2) result is '' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Function CUT(CUT(DB(DEVICE//dial),/,2),@,1) result is '' [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 23 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Variable: MACRO_DEPTH Value: 1 [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Result of 'ARG2' is NULL [2021-11-09 17:31:47] DEBUG[22839][C-00000047] db.c: Unable to find key '/tech' in family 'DEVICE' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] func_db.c: DB: DEVICE//tech not found in database. [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Function DB(DEVICE//tech) result is '' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Result of 'CUSDIAL' is NULL [2021-11-09 17:31:47] DEBUG[22839][C-00000047] db.c: Unable to find key '/type' in family 'DEVICE' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] func_db.c: DB: DEVICE//type not found in database. [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Function DB(DEVICE//type) result is '' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Expression result is '0' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Result of 'ARG2' is NULL [2021-11-09 17:31:47] DEBUG[22839][C-00000047] db.c: Unable to find key '/outboundcid' in family 'AMPUSER' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] func_db.c: DB: AMPUSER//outboundcid not found in database. [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Function DB(AMPUSER//outboundcid) result is '' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Function LEN() result is '0' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Expression result is '0' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Result of 'ARG2' is NULL [2021-11-09 17:31:47] DEBUG[22839][C-00000047] db.c: Unable to find key '/outboundcid' in family 'AMPUSER' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] func_db.c: DB: AMPUSER//outboundcid not found in database. [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Function DB(AMPUSER//outboundcid) result is '' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Function CALLERID(all) result is '"" <331>' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Function IF(0?:"" <331>) result is '"" <331>' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx.c: Launching 'ExecIf' [2021-11-09 17:31:47] VERBOSE[22839][C-00000047] pbx.c: Executing [s@macro-user-callerid:24] ExecIf("PJSIP/331-00000112", "0?Set(CALLERID(all)="" <331>)") in new stack [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 24 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Extension: s Application: ExecIf AppData: 0?Set(CALLERID(all)="" <331>) [2021-11-09 17:31:47] DEBUG[22839][C-00000047] app_macro.c: Executed application: ExecIf [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Evaluating 'DB(DEVICE/${ARG2}/tech)' (from 'DB(DEVICE/${ARG2}/tech)}"="custom" & "${DB(DEVICE/${CUSDIAL}/type)}" =""' len 23) [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Evaluating 'ARG2' (from 'ARG2}/tech)' len 4) [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Result of 'ARG2' is NULL [2021-11-09 17:31:47] DEBUG[22839][C-00000047] db.c: Unable to find key '/tech' in family 'DEVICE' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] func_db.c: DB: DEVICE//tech not found in database. [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Function DB(DEVICE//tech) result is '' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Evaluating 'DB(DEVICE/${CUSDIAL}/type)' (from 'DB(DEVICE/${CUSDIAL}/type)}" =""' len 26) [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Evaluating 'CUSDIAL' (from 'CUSDIAL}/type)' len 7) [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Result of 'CUSDIAL' is NULL [2021-11-09 17:31:47] DEBUG[22839][C-00000047] db.c: Unable to find key '/type' in family 'DEVICE' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] func_db.c: DB: DEVICE//type not found in database. [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Function DB(DEVICE//type) result is '' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Expression result is '0' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Evaluating 'IF($[${LEN(${DB(AMPUSER/${ARG2}/outboundcid)})}]?${DB(AMPUSER/${ARG2}/outboundcid)}:${CALLERID(all)})' (from 'IF($[${LEN(${DB(AMPUSER/${ARG2}/outboundcid)})}]?${DB(AMPUSER/${ARG2}/outboundcid)}:${CALLERID(all)})})' len 101) [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Evaluating 'LEN(${DB(AMPUSER/${ARG2}/outboundcid)})' (from 'LEN(${DB(AMPUSER/${ARG2}/outboundcid)})}' len 39) [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Evaluating 'DB(AMPUSER/${ARG2}/outboundcid)' (from 'DB(AMPUSER/${ARG2}/outboundcid)})' len 31) [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Evaluating 'ARG2' (from 'ARG2}/outboundcid)' len 4) [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Result of 'ARG2' is NULL [2021-11-09 17:31:47] DEBUG[22839][C-00000047] db.c: Unable to find key '/outboundcid' in family 'AMPUSER' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] func_db.c: DB: AMPUSER//outboundcid not found in database. [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Function DB(AMPUSER//outboundcid) result is '' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Function LEN() result is '0' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Expression result is '0' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Evaluating 'DB(AMPUSER/${ARG2}/outboundcid)' (from 'DB(AMPUSER/${ARG2}/outboundcid)}:${CALLERID(all)})' len 31) [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Evaluating 'ARG2' (from 'ARG2}/outboundcid)' len 4) [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Result of 'ARG2' is NULL [2021-11-09 17:31:47] DEBUG[22839][C-00000047] db.c: Unable to find key '/outboundcid' in family 'AMPUSER' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] func_db.c: DB: AMPUSER//outboundcid not found in database. [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Function DB(AMPUSER//outboundcid) result is '' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Evaluating 'CALLERID(all)' (from 'CALLERID(all)})' len 13) [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Function CALLERID(all) result is '"" <331>' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Function IF(0?:"" <331>) result is '"" <331>' [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 24 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Variable: MACRO_DEPTH Value: 1 [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Result of 'ARG1' is '' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Result of 'AMPUSER' is '331' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Function LEN(331) result is '3' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Result of 'AMPUSER' is '331' [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 24 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Variable: DB_RESULT Value: 3 [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Function DB_EXISTS(AMPUSER/331/concurrency_limit) result is '1' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Result of 'AMPUSER' is '331' [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 24 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Variable: DB_RESULT Value: 3 [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Function DB(AMPUSER/331/concurrency_limit) result is '3' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Result of 'AMPUSER' is '331' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Function GROUP_COUNT(331@concurrency_limit) result is '0' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Result of 'AMPUSER' is '331' [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 24 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Variable: DB_RESULT Value: 3 [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Function DB(AMPUSER/331/concurrency_limit) result is '3' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Expression result is '0' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx.c: Launching 'GotoIf' [2021-11-09 17:31:47] VERBOSE[22839][C-00000047] pbx.c: Executing [s@macro-user-callerid:25] GotoIf("PJSIP/331-00000112", "0?limit") in new stack [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 25 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Extension: s Application: GotoIf AppData: 0?limit [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_builtins.c: Not taking any branch [2021-11-09 17:31:47] DEBUG[22839][C-00000047] app_macro.c: Executed application: GotoIf [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 25 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Variable: MACRO_DEPTH Value: 1 [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Result of 'ARG1' is '' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Result of 'AMPUSER' is '331' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Function LEN(331) result is '3' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Expression result is '0' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Result of 'AMPUSER' is '331' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx.c: Launching 'ExecIf' [2021-11-09 17:31:47] VERBOSE[22839][C-00000047] pbx.c: Executing [s@macro-user-callerid:26] ExecIf("PJSIP/331-00000112", "0?Set(GROUP(concurrency_limit)=331)") in new stack [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 26 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Extension: s Application: ExecIf AppData: 0?Set(GROUP(concurrency_limit)=331) [2021-11-09 17:31:47] DEBUG[22839][C-00000047] app_macro.c: Executed application: ExecIf [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Evaluating 'ARG1' (from 'ARG1}"="LIMIT" & ${LEN(${AMPUSER})}' len 4) [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Result of 'ARG1' is '' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Evaluating 'LEN(${AMPUSER})' (from 'LEN(${AMPUSER})}' len 15) [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Evaluating 'AMPUSER' (from 'AMPUSER})' len 7) [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Result of 'AMPUSER' is '331' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Function LEN(331) result is '3' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Expression result is '0' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Evaluating 'AMPUSER' (from 'AMPUSER})' len 7) [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Result of 'AMPUSER' is '331' [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 26 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Variable: MACRO_DEPTH Value: 1 [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Result of 'MACRO_DEPTH' is '1' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx.c: Launching 'NoOp' [2021-11-09 17:31:47] VERBOSE[22839][C-00000047] pbx.c: Executing [s@macro-user-callerid:27] NoOp("PJSIP/331-00000112", "Macro Depth is 1") in new stack [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 27 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Extension: s Application: NoOp AppData: Macro Depth is 1 [2021-11-09 17:31:47] DEBUG[22839][C-00000047] app_macro.c: Executed application: Noop [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 27 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Variable: MACRO_DEPTH Value: 1 [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Result of 'MACRO_DEPTH' is '1' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Result of 'MACRO_DEPTH' is '1' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Expression result is '1' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx.c: Launching 'GotoIf' [2021-11-09 17:31:47] VERBOSE[22839][C-00000047] pbx.c: Executing [s@macro-user-callerid:28] GotoIf("PJSIP/331-00000112", "1?report2:macroerror") in new stack [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 28 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Extension: s Application: GotoIf AppData: 1?report2:macroerror [2021-11-09 17:31:47] VERBOSE[22839][C-00000047] pbx_builtins.c: Goto (macro-user-callerid,s,29) [2021-11-09 17:31:47] DEBUG[22839][C-00000047] app_macro.c: Executed application: GotoIf [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 28 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Variable: MACRO_DEPTH Value: 1 [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Result of 'ARG1' is '' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Result of 'ARG1' is '' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Expression result is '0' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx.c: Launching 'GotoIf' [2021-11-09 17:31:47] VERBOSE[22839][C-00000047] pbx.c: Executing [s@macro-user-callerid:29] GotoIf("PJSIP/331-00000112", "0?continue") in new stack [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 29 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Extension: s Application: GotoIf AppData: 0?continue [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_builtins.c: Not taking any branch [2021-11-09 17:31:47] DEBUG[22839][C-00000047] app_macro.c: Executed application: GotoIf [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 29 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Variable: MACRO_DEPTH Value: 1 [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Result of 'TTL' is NULL [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Expression result is '1' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Result of 'TTL' is NULL [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Expression result is '-1' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Function IF(1?64:-1) result is '64' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx.c: Launching 'Set' [2021-11-09 17:31:47] VERBOSE[22839][C-00000047] pbx.c: Executing [s@macro-user-callerid:30] Set("PJSIP/331-00000112", "__TTL=64") in new stack [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 30 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Extension: s Application: Set AppData: __TTL=64 [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 30 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Variable: __TTL Value: 64 [2021-11-09 17:31:47] DEBUG[22839][C-00000047] app_macro.c: Executed application: Set [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 30 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Variable: MACRO_DEPTH Value: 1 [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Result of 'TTL' is '64' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Expression result is '1' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx.c: Launching 'GotoIf' [2021-11-09 17:31:47] VERBOSE[22839][C-00000047] pbx.c: Executing [s@macro-user-callerid:31] GotoIf("PJSIP/331-00000112", "1?continue") in new stack [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 31 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Extension: s Application: GotoIf AppData: 1?continue [2021-11-09 17:31:47] VERBOSE[22839][C-00000047] pbx_builtins.c: Goto (macro-user-callerid,s,47) [2021-11-09 17:31:47] DEBUG[22839][C-00000047] app_macro.c: Executed application: GotoIf [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 31 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Variable: MACRO_DEPTH Value: 1 [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Function CALLERID(number) result is '331' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx.c: Launching 'Set' [2021-11-09 17:31:47] VERBOSE[22839][C-00000047] pbx.c: Executing [s@macro-user-callerid:47] Set("PJSIP/331-00000112", "CALLERID(number)=331") in new stack [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 47 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Extension: s Application: Set AppData: CALLERID(number)=331 [2021-11-09 17:31:47] DEBUG[22839][C-00000047] app_macro.c: Executed application: Set [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 47 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Variable: MACRO_DEPTH Value: 1 [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Function CALLERID(name) result is '' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx.c: Launching 'Set' [2021-11-09 17:31:47] VERBOSE[22839][C-00000047] pbx.c: Executing [s@macro-user-callerid:48] Set("PJSIP/331-00000112", "CALLERID(name)=") in new stack [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 48 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Extension: s Application: Set AppData: CALLERID(name)= [2021-11-09 17:31:47] DEBUG[22839][C-00000047] app_macro.c: Executed application: Set [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 48 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Variable: MACRO_DEPTH Value: 1 [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Function CALLERID(name) result is '' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Expression result is '0' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx.c: Launching 'GotoIf' [2021-11-09 17:31:47] VERBOSE[22839][C-00000047] pbx.c: Executing [s@macro-user-callerid:49] GotoIf("PJSIP/331-00000112", "0?cnum") in new stack [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 49 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Extension: s Application: GotoIf AppData: 0?cnum [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_builtins.c: Not taking any branch [2021-11-09 17:31:47] DEBUG[22839][C-00000047] app_macro.c: Executed application: GotoIf [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 49 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Variable: MACRO_DEPTH Value: 1 [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Function CALLERID(name) result is '' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx.c: Launching 'Set' [2021-11-09 17:31:47] VERBOSE[22839][C-00000047] pbx.c: Executing [s@macro-user-callerid:50] Set("PJSIP/331-00000112", "CDR(cnam)=") in new stack [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 50 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Extension: s Application: Set AppData: CDR(cnam)= [2021-11-09 17:31:47] DEBUG[22839][C-00000047] app_macro.c: Executed application: Set [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 50 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Variable: MACRO_DEPTH Value: 1 [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Function CALLERID(num) result is '331' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx.c: Launching 'Set' [2021-11-09 17:31:47] VERBOSE[22839][C-00000047] pbx.c: Executing [s@macro-user-callerid:51] Set("PJSIP/331-00000112", "CDR(cnum)=331") in new stack [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 51 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Extension: s Application: Set AppData: CDR(cnum)=331 [2021-11-09 17:31:47] DEBUG[22839][C-00000047] app_macro.c: Executed application: Set [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 51 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Variable: MACRO_DEPTH Value: 1 [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Evaluating 'CHANNEL(language)' (from 'CHANNEL(language)}' len 17) [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Function CHANNEL(language) result is 'de_DE' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx_variables.c: Function MASTER_CHANNEL(CHANNEL(language)) result is 'de_DE' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx.c: Launching 'Set' [2021-11-09 17:31:47] VERBOSE[22839][C-00000047] pbx.c: Executing [s@macro-user-callerid:52] Set("PJSIP/331-00000112", "CHANNEL(language)=de_DE") in new stack [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 52 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Extension: s Application: Set AppData: CHANNEL(language)=de_DE [2021-11-09 17:31:47] DEBUG[22839][C-00000047] app_macro.c: Executed application: Set [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 52 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Variable: MACRO_DEPTH Value: 0 [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 52 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Variable: MACRO_EXTEN Value: [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 52 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Variable: MACRO_CONTEXT Value: [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: macro-user-callerid Exten: s Priority: 52 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Variable: MACRO_PRIORITY Value: [2021-11-09 17:31:47] DEBUG[22839][C-00000047] pbx.c: Launching 'Wait' [2021-11-09 17:31:47] VERBOSE[22839][C-00000047] pbx.c: Executing [*43@from-internal:6] Wait("PJSIP/331-00000112", "1") in new stack [2021-11-09 17:31:47] DEBUG[6884] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: from-internal Exten: *43 Priority: 6 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Extension: *43 Application: Wait AppData: 1 [2021-11-09 17:31:47] DEBUG[22839][C-00000047] channel.c: Channel PJSIP/331-00000112 setting write format path: slin -> alaw [2021-11-09 17:31:47] DEBUG[22839][C-00000047] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [2021-11-09 17:31:47] DEBUG[22839][C-00000047] channel.c: Started silence generator on 'PJSIP/331-00000112' [2021-11-09 17:31:47] DEBUG[22839][C-00000047] res_rtp_asterisk.c: (0x7401c9f0) RTP ooh, format changed from none to alaw [2021-11-09 17:31:47] DEBUG[22839][C-00000047] res_rtp_asterisk.c: (0x7401c9f0) RTCP starting transmission [2021-11-09 17:31:48] DEBUG[1153] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to :5061 (this may be re-written again later) [2021-11-09 17:31:48] VERBOSE[1153] res_pjsip_logger.c: <--- Transmitting SIP response (997 bytes) to TLS::48950 ---> SIP/2.0 200 OK Via: SIP/2.0/TLS :41309;rport=48950;received=;branch=z9hG4bK-524287-1---9d893386b9e0b46d Call-ID: CQdLbgtd0ZPU7DIOH8w5hg.. From: >;tag=3a643242 To: >;tag=a911c608-2a7e-4a75-9263-164ed164031d CSeq: 2 INVITE Server: FPBX-15.0.17.55(16.18.0) Contact: :5061;transport=TLS> Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER Supported: 100rel, timer, replaces, norefersub P-Asserted-Identity: "Echo Test" > Content-Type: application/sdp Content-Length: 333 v=0 o=- 92968048 3 IN IP4 s=Asterisk c=IN IP4 t=0 0 m=audio 19202 RTP/SAVP 8 101 a=crypto:5 AES_256_CM_HMAC_SHA1_80 inline:YHq+56LQqv8suomMPvW05nf6sWfXveKZ4WxgL+D+21eENWqWI54LQUU2aOLyBw== a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:150 a=sendrecv [2021-11-09 17:31:48] DEBUG[22839][C-00000047] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2021-11-09 17:31:48] DEBUG[22839][C-00000047] channel.c: Stopped silence generator on 'PJSIP/331-00000112' [2021-11-09 17:31:48] DEBUG[22839][C-00000047] channel.c: Channel PJSIP/331-00000112 setting write format path: alaw -> alaw [2021-11-09 17:31:48] DEBUG[22839][C-00000047] pbx.c: Launching 'BackGround' [2021-11-09 17:31:48] VERBOSE[22839][C-00000047] pbx.c: Executing [*43@from-internal:7] BackGround("PJSIP/331-00000112", "demo-echotest,,,app-echo-test-echo") in new stack [2021-11-09 17:31:48] DEBUG[6884] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: from-internal Exten: *43 Priority: 7 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Extension: *43 Application: BackGround AppData: demo-echotest,,,app-echo-test-echo [2021-11-09 17:31:48] DEBUG[22839][C-00000047] channel.c: Channel PJSIP/331-00000112 setting write format path: ulaw -> alaw [2021-11-09 17:31:48] DEBUG[22839][C-00000047] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [2021-11-09 17:31:48] VERBOSE[22839][C-00000047] file.c: Playing 'demo-echotest.ulaw' (language 'de_DE') [2021-11-09 17:31:50] DEBUG[1153] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to :5061 (this may be re-written again later) [2021-11-09 17:31:50] VERBOSE[1153] res_pjsip_logger.c: <--- Transmitting SIP response (997 bytes) to TLS::48950 ---> SIP/2.0 200 OK Via: SIP/2.0/TLS :41309;rport=48950;received=;branch=z9hG4bK-524287-1---9d893386b9e0b46d Call-ID: CQdLbgtd0ZPU7DIOH8w5hg.. From: >;tag=3a643242 To: >;tag=a911c608-2a7e-4a75-9263-164ed164031d CSeq: 2 INVITE Server: FPBX-15.0.17.55(16.18.0) Contact: :5061;transport=TLS> Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER Supported: 100rel, timer, replaces, norefersub P-Asserted-Identity: "Echo Test" > Content-Type: application/sdp Content-Length: 333 v=0 o=- 92968048 3 IN IP4 s=Asterisk c=IN IP4 t=0 0 m=audio 19202 RTP/SAVP 8 101 a=crypto:5 AES_256_CM_HMAC_SHA1_80 inline:YHq+56LQqv8suomMPvW05nf6sWfXveKZ4WxgL+D+21eENWqWI54LQUU2aOLyBw== a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:150 a=sendrecv [2021-11-09 17:31:51] DEBUG[22849] manager.c: Running action 'Login' [2021-11-09 17:31:52] DEBUG[1168] res_pjsip_registrar.c: Woke up at 1636475512 Interval: 30 [2021-11-09 17:31:52] DEBUG[1168] res_pjsip_registrar.c: Expiring 0 contacts [2021-11-09 17:31:52] DEBUG[6884] manager.c: Examining AMI event: Event: RTCPSent Privilege: reporting,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: from-internal Exten: *43 Priority: 7 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 To: :58963 From: :19203 SSRC: 0x2234e9a2 PT: 200(SR) ReportCount: 0 SentNTP: 1636475512.427151 SentRTP: 40160 SentPackets: 251 SentOctets: 42670 [2021-11-09 17:31:54] DEBUG[1153] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to :5061 (this may be re-written again later) [2021-11-09 17:31:54] VERBOSE[1153] res_pjsip_logger.c: <--- Transmitting SIP response (997 bytes) to TLS::48950 ---> SIP/2.0 200 OK Via: SIP/2.0/TLS :41309;rport=48950;received=;branch=z9hG4bK-524287-1---9d893386b9e0b46d Call-ID: CQdLbgtd0ZPU7DIOH8w5hg.. From: >;tag=3a643242 To: >;tag=a911c608-2a7e-4a75-9263-164ed164031d CSeq: 2 INVITE Server: FPBX-15.0.17.55(16.18.0) Contact: :5061;transport=TLS> Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER Supported: 100rel, timer, replaces, norefersub P-Asserted-Identity: "Echo Test" > Content-Type: application/sdp Content-Length: 333 v=0 o=- 92968048 3 IN IP4 s=Asterisk c=IN IP4 t=0 0 m=audio 19202 RTP/SAVP 8 101 a=crypto:5 AES_256_CM_HMAC_SHA1_80 inline:YHq+56LQqv8suomMPvW05nf6sWfXveKZ4WxgL+D+21eENWqWI54LQUU2aOLyBw== a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:150 a=sendrecv [2021-11-09 17:31:54] DEBUG[22480] threadpool.c: Worker thread idle timeout reached. Dying. [2021-11-09 17:31:54] DEBUG[1151] threadpool.c: Destroying worker thread 2877 [2021-11-09 17:31:54] DEBUG[22479] threadpool.c: Worker thread idle timeout reached. Dying. [2021-11-09 17:31:54] DEBUG[22481] threadpool.c: Worker thread idle timeout reached. Dying. [2021-11-09 17:31:54] DEBUG[1151] threadpool.c: Destroying worker thread 2876 [2021-11-09 17:31:54] DEBUG[1151] threadpool.c: Destroying worker thread 2878 [2021-11-09 17:31:54] DEBUG[22485] threadpool.c: Worker thread idle timeout reached. Dying. [2021-11-09 17:31:54] DEBUG[1151] threadpool.c: Destroying worker thread 2881 [2021-11-09 17:31:54] DEBUG[22487] threadpool.c: Worker thread idle timeout reached. Dying. [2021-11-09 17:31:54] DEBUG[22477] threadpool.c: Worker thread idle timeout reached. Dying. [2021-11-09 17:31:54] DEBUG[1151] threadpool.c: Destroying worker thread 2883 [2021-11-09 17:31:54] DEBUG[22483] threadpool.c: Worker thread idle timeout reached. Dying. [2021-11-09 17:31:54] DEBUG[1151] threadpool.c: Destroying worker thread 2874 [2021-11-09 17:31:54] DEBUG[1151] threadpool.c: Destroying worker thread 2880 [2021-11-09 17:31:54] DEBUG[22482] threadpool.c: Worker thread idle timeout reached. Dying. [2021-11-09 17:31:54] DEBUG[22486] threadpool.c: Worker thread idle timeout reached. Dying. [2021-11-09 17:31:54] DEBUG[1151] threadpool.c: Destroying worker thread 2879 [2021-11-09 17:31:54] DEBUG[1151] threadpool.c: Destroying worker thread 2882 [2021-11-09 17:31:54] DEBUG[22478] threadpool.c: Worker thread idle timeout reached. Dying. [2021-11-09 17:31:54] DEBUG[1151] threadpool.c: Destroying worker thread 2875 [2021-11-09 17:31:57] DEBUG[6884] manager.c: Examining AMI event: Event: RTCPSent Privilege: reporting,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: from-internal Exten: *43 Priority: 7 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 To: :58963 From: :19203 SSRC: 0x2234e9a2 PT: 200(SR) ReportCount: 0 SentNTP: 1636475517.427541 SentRTP: 80160 SentPackets: 501 SentOctets: 85170 [2021-11-09 17:31:58] DEBUG[21161] res_pjsip/pjsip_options.c: Qualifying all contacts on AOR '331' [2021-11-09 17:31:58] DEBUG[21161] res_pjsip/pjsip_options.c: Qualifying contact '331;@57d02ab183f8e78645ebeded29471ca9' on AOR '331' [2021-11-09 17:31:58] DEBUG[21161] res_pjsip.c: 0x74018440: Wrapper created [2021-11-09 17:31:58] DEBUG[21161] res_pjsip.c: 0x74018440: Set timer to 3000 msec [2021-11-09 17:31:58] DEBUG[21161] res_pjsip/pjsip_resolver.c: Performing SIP DNS resolution of target '' [2021-11-09 17:31:58] DEBUG[21161] res_pjsip/pjsip_resolver.c: Transport type for target '' is 'TLS transport' [2021-11-09 17:31:58] DEBUG[21161] res_pjsip/pjsip_resolver.c: Target '' is an IP address, skipping resolution [2021-11-09 17:31:58] DEBUG[21161] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to :5061 (this may be re-written again later) [2021-11-09 17:31:58] VERBOSE[21161] res_pjsip_logger.c: <--- Transmitting SIP request (509 bytes) to TLS::48950 ---> OPTIONS sip:331@:48950;transport=TLS;rinstance=2c586552061c4a8c SIP/2.0 Via: SIP/2.0/TLS :5061;rport;branch=z9hG4bKPjdcb29b32-7a23-4364-bf47-6bcda3632d6b;alias From: >;tag=3b9d4284-f330-4097-9579-c4d1a26cef28 To: ;rinstance=2c586552061c4a8c> Contact: :5061;transport=TLS> Call-ID: 3a606dc6-6bb0-43e1-a5e6-dba06273b6e5 CSeq: 63556 OPTIONS Max-Forwards: 70 User-Agent: FPBX-15.0.17.55(16.18.0) Content-Length: 0 [2021-11-09 17:31:58] VERBOSE[1153] res_pjsip_logger.c: <--- Received SIP response (731 bytes) from TLS::48950 ---> SIP/2.0 200 OK Via: SIP/2.0/TLS :5061;rport=5061;branch=z9hG4bKPjdcb29b32-7a23-4364-bf47-6bcda3632d6b;received=;alias Contact: :41309;transport=tls> To: ;rinstance=2c586552061c4a8c>;tag=19a17036 From: >;tag=3b9d4284-f330-4097-9579-c4d1a26cef28 Call-ID: 3a606dc6-6bb0-43e1-a5e6-dba06273b6e5 CSeq: 63556 OPTIONS Accept: application/sdp, application/sdp Accept-Language: en Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE Supported: replaces, norefersub, extended-refer, timer, outbound, path, X-cisco-serviceuri User-Agent: Zoiper rv2.10.12.3-mod Allow-Events: presence, kpml, talk Content-Length: 0 [2021-11-09 17:31:58] DEBUG[1153] res_pjsip/pjsip_distributor.c: No dialog serializer for Response msg 200/OPTIONS/cseq=63556 (rdata0x12ed2ec). Using request transaction as basis. [2021-11-09 17:31:58] DEBUG[1153] res_pjsip/pjsip_distributor.c: Found transaction tsx0x74028cf4 for Response msg 200/OPTIONS/cseq=63556 (rdata0x12ed2ec). [2021-11-09 17:31:58] DEBUG[1153] res_pjsip/pjsip_distributor.c: Found serializer pjsip/options/331-00000056 on transaction tsx0x74028cf4 [2021-11-09 17:31:58] DEBUG[21161] res_pjsip.c: 0x74018440: PJSIP tsx response received [2021-11-09 17:31:58] DEBUG[21161] res_pjsip.c: 0x74018440: Cancelling timer [2021-11-09 17:31:58] DEBUG[21161] res_pjsip.c: 0x74018440: Timer cancelled [2021-11-09 17:31:58] DEBUG[21161] res_pjsip.c: 0x74018440: Callbacks executed [2021-11-09 17:31:58] DEBUG[21161] res_pjsip.c: 0x74018440: wrapper destroyed [2021-11-09 17:31:58] DEBUG[21161] res_pjsip/pjsip_options.c: Contact 331/sip:331@:48950;transport=TLS;rinstance=2c586552061c4a8c status didn't change: Reachable, RTT: 82.746 msec [2021-11-09 17:31:58] DEBUG[21161] res_pjsip/pjsip_options.c: AOR '331' now has 1 available contacts [2021-11-09 17:31:58] DEBUG[1153] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to :5061 (this may be re-written again later) [2021-11-09 17:31:58] VERBOSE[1153] res_pjsip_logger.c: <--- Transmitting SIP response (997 bytes) to TLS::48950 ---> SIP/2.0 200 OK Via: SIP/2.0/TLS :41309;rport=48950;received=;branch=z9hG4bK-524287-1---9d893386b9e0b46d Call-ID: CQdLbgtd0ZPU7DIOH8w5hg.. From: >;tag=3a643242 To: >;tag=a911c608-2a7e-4a75-9263-164ed164031d CSeq: 2 INVITE Server: FPBX-15.0.17.55(16.18.0) Contact: :5061;transport=TLS> Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER Supported: 100rel, timer, replaces, norefersub P-Asserted-Identity: "Echo Test" > Content-Type: application/sdp Content-Length: 333 v=0 o=- 92968048 3 IN IP4 s=Asterisk c=IN IP4 t=0 0 m=audio 19202 RTP/SAVP 8 101 a=crypto:5 AES_256_CM_HMAC_SHA1_80 inline:YHq+56LQqv8suomMPvW05nf6sWfXveKZ4WxgL+D+21eENWqWI54LQUU2aOLyBw== a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:150 a=sendrecv [2021-11-09 17:31:59] DEBUG[22856] manager.c: Running action 'Login' [2021-11-09 17:32:01] DEBUG[22867] manager.c: Running action 'Login' [2021-11-09 17:32:02] DEBUG[1153] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to :5061 (this may be re-written again later) [2021-11-09 17:32:02] VERBOSE[1153] res_pjsip_logger.c: <--- Transmitting SIP response (997 bytes) to TLS::48950 ---> SIP/2.0 200 OK Via: SIP/2.0/TLS :41309;rport=48950;received=;branch=z9hG4bK-524287-1---9d893386b9e0b46d Call-ID: CQdLbgtd0ZPU7DIOH8w5hg.. From: >;tag=3a643242 To: >;tag=a911c608-2a7e-4a75-9263-164ed164031d CSeq: 2 INVITE Server: FPBX-15.0.17.55(16.18.0) Contact: :5061;transport=TLS> Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER Supported: 100rel, timer, replaces, norefersub P-Asserted-Identity: "Echo Test" > Content-Type: application/sdp Content-Length: 333 v=0 o=- 92968048 3 IN IP4 s=Asterisk c=IN IP4 t=0 0 m=audio 19202 RTP/SAVP 8 101 a=crypto:5 AES_256_CM_HMAC_SHA1_80 inline:YHq+56LQqv8suomMPvW05nf6sWfXveKZ4WxgL+D+21eENWqWI54LQUU2aOLyBw== a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:150 a=sendrecv [2021-11-09 17:32:02] DEBUG[6884] manager.c: Examining AMI event: Event: RTCPSent Privilege: reporting,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: from-internal Exten: *43 Priority: 7 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 To: :58963 From: :19203 SSRC: 0x2234e9a2 PT: 200(SR) ReportCount: 0 SentNTP: 1636475522.427870 SentRTP: 120160 SentPackets: 751 SentOctets: 127670 [2021-11-09 17:32:02] DEBUG[22878] manager.c: Running action 'Login' [2021-11-09 17:32:05] DEBUG[22886] manager.c: Running action 'Login' [2021-11-09 17:32:06] DEBUG[1153] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to :5061 (this may be re-written again later) [2021-11-09 17:32:06] VERBOSE[1153] res_pjsip_logger.c: <--- Transmitting SIP response (997 bytes) to TLS::48950 ---> SIP/2.0 200 OK Via: SIP/2.0/TLS :41309;rport=48950;received=;branch=z9hG4bK-524287-1---9d893386b9e0b46d Call-ID: CQdLbgtd0ZPU7DIOH8w5hg.. From: >;tag=3a643242 To: >;tag=a911c608-2a7e-4a75-9263-164ed164031d CSeq: 2 INVITE Server: FPBX-15.0.17.55(16.18.0) Contact: :5061;transport=TLS> Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER Supported: 100rel, timer, replaces, norefersub P-Asserted-Identity: "Echo Test" > Content-Type: application/sdp Content-Length: 333 v=0 o=- 92968048 3 IN IP4 s=Asterisk c=IN IP4 t=0 0 m=audio 19202 RTP/SAVP 8 101 a=crypto:5 AES_256_CM_HMAC_SHA1_80 inline:YHq+56LQqv8suomMPvW05nf6sWfXveKZ4WxgL+D+21eENWqWI54LQUU2aOLyBw== a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:150 a=sendrecv [2021-11-09 17:32:07] DEBUG[6884] manager.c: Examining AMI event: Event: RTCPSent Privilege: reporting,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: from-internal Exten: *43 Priority: 7 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 To: :58963 From: :19203 SSRC: 0x2234e9a2 PT: 200(SR) ReportCount: 0 SentNTP: 1636475527.427242 SentRTP: 160160 SentPackets: 1001 SentOctets: 170170 [2021-11-09 17:32:09] DEBUG[22894] manager.c: Running action 'Login' [2021-11-09 17:32:10] DEBUG[1153] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to :5061 (this may be re-written again later) [2021-11-09 17:32:10] VERBOSE[1153] res_pjsip_logger.c: <--- Transmitting SIP response (997 bytes) to TLS::48950 ---> SIP/2.0 200 OK Via: SIP/2.0/TLS :41309;rport=48950;received=;branch=z9hG4bK-524287-1---9d893386b9e0b46d Call-ID: CQdLbgtd0ZPU7DIOH8w5hg.. From: >;tag=3a643242 To: >;tag=a911c608-2a7e-4a75-9263-164ed164031d CSeq: 2 INVITE Server: FPBX-15.0.17.55(16.18.0) Contact: :5061;transport=TLS> Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER Supported: 100rel, timer, replaces, norefersub P-Asserted-Identity: "Echo Test" > Content-Type: application/sdp Content-Length: 333 v=0 o=- 92968048 3 IN IP4 s=Asterisk c=IN IP4 t=0 0 m=audio 19202 RTP/SAVP 8 101 a=crypto:5 AES_256_CM_HMAC_SHA1_80 inline:YHq+56LQqv8suomMPvW05nf6sWfXveKZ4WxgL+D+21eENWqWI54LQUU2aOLyBw== a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:150 a=sendrecv [2021-11-09 17:32:12] DEBUG[6884] manager.c: Examining AMI event: Event: RTCPSent Privilege: reporting,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: from-internal Exten: *43 Priority: 7 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 To: :58963 From: :19203 SSRC: 0x2234e9a2 PT: 200(SR) ReportCount: 0 SentNTP: 1636475532.427630 SentRTP: 200160 SentPackets: 1251 SentOctets: 212670 [2021-11-09 17:32:12] DEBUG[22901] manager.c: Running action 'Login' [2021-11-09 17:32:13] DEBUG[22839][C-00000047] channel.c: Scheduling timer at (51 requested / 51 actual) timer ticks per second [2021-11-09 17:32:13] DEBUG[22839][C-00000047] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2021-11-09 17:32:13] DEBUG[22839][C-00000047] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2021-11-09 17:32:13] DEBUG[22839][C-00000047] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2021-11-09 17:32:13] DEBUG[22839][C-00000047] channel.c: Channel PJSIP/331-00000112 setting write format path: alaw -> alaw [2021-11-09 17:32:13] DEBUG[6884] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: from-internal Exten: *43 Priority: 7 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Variable: BACKGROUNDSTATUS Value: SUCCESS [2021-11-09 17:32:13] DEBUG[22839][C-00000047] pbx.c: Launching 'Goto' [2021-11-09 17:32:13] VERBOSE[22839][C-00000047] pbx.c: Executing [*43@from-internal:8] Goto("PJSIP/331-00000112", "app-echo-test-echo,1,1") in new stack [2021-11-09 17:32:13] DEBUG[6884] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: from-internal Exten: *43 Priority: 8 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Extension: *43 Application: Goto AppData: app-echo-test-echo,1,1 [2021-11-09 17:32:13] VERBOSE[22839][C-00000047] pbx_builtins.c: Goto (app-echo-test-echo,1,1) [2021-11-09 17:32:13] DEBUG[22839][C-00000047] pbx.c: Launching 'Echo' [2021-11-09 17:32:13] VERBOSE[22839][C-00000047] pbx.c: Executing [1@app-echo-test-echo:1] Echo("PJSIP/331-00000112", "") in new stack [2021-11-09 17:32:13] DEBUG[6884] manager.c: Examining AMI event: Event: Newexten Privilege: dialplan,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: app-echo-test-echo Exten: 1 Priority: 1 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Extension: 1 Application: Echo AppData: [2021-11-09 17:32:14] DEBUG[1153] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to :5061 (this may be re-written again later) [2021-11-09 17:32:14] VERBOSE[1153] res_pjsip_logger.c: <--- Transmitting SIP response (997 bytes) to TLS::48950 ---> SIP/2.0 200 OK Via: SIP/2.0/TLS :41309;rport=48950;received=;branch=z9hG4bK-524287-1---9d893386b9e0b46d Call-ID: CQdLbgtd0ZPU7DIOH8w5hg.. From: >;tag=3a643242 To: >;tag=a911c608-2a7e-4a75-9263-164ed164031d CSeq: 2 INVITE Server: FPBX-15.0.17.55(16.18.0) Contact: :5061;transport=TLS> Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER Supported: 100rel, timer, replaces, norefersub P-Asserted-Identity: "Echo Test" > Content-Type: application/sdp Content-Length: 333 v=0 o=- 92968048 3 IN IP4 s=Asterisk c=IN IP4 t=0 0 m=audio 19202 RTP/SAVP 8 101 a=crypto:5 AES_256_CM_HMAC_SHA1_80 inline:YHq+56LQqv8suomMPvW05nf6sWfXveKZ4WxgL+D+21eENWqWI54LQUU2aOLyBw== a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:150 a=sendrecv [2021-11-09 17:32:15] DEBUG[22908] manager.c: Running action 'Login' [2021-11-09 17:32:16] NOTICE[1189] res_pjsip_sdp_rtp.c: Disconnecting channel 'PJSIP/331-00000112' for lack of audio RTP activity in 30 seconds [2021-11-09 17:32:16] DEBUG[1189] channel.c: Soft-Hanging (0x01) up channel 'PJSIP/331-00000112' [2021-11-09 17:32:16] DEBUG[6884] manager.c: Examining AMI event: Event: SoftHangupRequest Privilege: call,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: app-echo-test-echo Exten: 1 Priority: 1 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Cause: 1 [2021-11-09 17:32:16] DEBUG[22839][C-00000047] pbx.c: Spawn extension (app-echo-test-echo,1,1) exited non-zero on 'PJSIP/331-00000112' [2021-11-09 17:32:16] VERBOSE[22839][C-00000047] pbx.c: Spawn extension (app-echo-test-echo, 1, 1) exited non-zero on 'PJSIP/331-00000112' [2021-11-09 17:32:16] DEBUG[22839][C-00000047] channel.c: Soft-Hanging (0x10) up channel 'PJSIP/331-00000112' [2021-11-09 17:32:16] DEBUG[6884] manager.c: Examining AMI event: Event: SoftHangupRequest Privilege: call,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: app-echo-test-echo Exten: 1 Priority: 1 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Cause: 16 [2021-11-09 17:32:16] DEBUG[22839][C-00000047] channel.c: Channel 0x740eb6b8 'PJSIP/331-00000112' hanging up. Refs: 2 [2021-11-09 17:32:16] DEBUG[22839][C-00000047] chan_pjsip.c: AST hangup cause 44 (no match found in PJSIP) [2021-11-09 17:32:16] DEBUG[21161] sched.c: Attempted to delete nonexistent schedule entry 13! [2021-11-09 17:32:16] DEBUG[21161] res_pjsip_sdp_rtp.c: Unable to cancel schedule ID 13. [2021-11-09 17:32:16] DEBUG[21161] res_rtp_asterisk.c: (0x7401c9f0) DTLS srtp - stopped timeout timer' [2021-11-09 17:32:16] DEBUG[21161] res_rtp_asterisk.c: (0x7401c9f0) DTLS srtp - stopped timeout timer' [2021-11-09 17:32:16] DEBUG[21161] res_rtp_asterisk.c: (0x7401c9f0) DTLS stop [2021-11-09 17:32:16] DEBUG[21161] res_rtp_asterisk.c: (0x7401c9f0) DTLS srtp - stopped timeout timer' [2021-11-09 17:32:16] DEBUG[21161] res_rtp_asterisk.c: (0x7401c9f0) DTLS srtp - stopped timeout timer' [2021-11-09 17:32:16] DEBUG[21161] res_rtp_asterisk.c: (0x7401c9f0) ICE RTP transport deallocating [2021-11-09 17:32:16] DEBUG[21161] rtp_engine.c: Destroyed RTP instance '0x7401c9f0' [2021-11-09 17:32:16] DEBUG[21161] res_pjsip_session.c: PJSIP/331-00000112: Method is BYE [2021-11-09 17:32:16] DEBUG[21161] res_pjsip_session.c: PJSIP/331-00000112 [2021-11-09 17:32:16] DEBUG[21161] channel.c: Channel 0x740eb6b8 'PJSIP/331-00000112' destroying [2021-11-09 17:32:16] DEBUG[6884] manager.c: Examining AMI event: Event: Hangup Privilege: call,all Channel: PJSIP/331-00000112 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 331 CallerIDName: ConnectedLineNum: *43 ConnectedLineName: Echo Test Language: de_DE AccountCode: Context: app-echo-test-echo Exten: 1 Priority: 1 Uniqueid: 1636475506.726 Linkedid: 1636475506.726 Cause: 44 Cause-txt: Requested channel not available [2021-11-09 17:32:16] DEBUG[21161] stasis.c: Destroying topic. name: cache:803/channel:1636475506.726, detail: [2021-11-09 17:32:16] DEBUG[21161] stasis.c: Topic 'cache:803/channel:1636475506.726': 0x7409fd98 destroyed [2021-11-09 17:32:16] DEBUG[21161] stasis.c: Destroying topic. name: channel:1636475506.726, detail: [2021-11-09 17:32:16] DEBUG[21161] stasis.c: Topic 'channel:1636475506.726': 0x7405df78 destroyed [2021-11-09 17:32:16] DEBUG[1137] cdr.c: Finalized CDR for PJSIP/331-00000112 - start 1636475506.848915 answer 1636475506.852636 end 1636475536.861012 dur 30.012 bill 30.008 dispo ANSWERED [2021-11-09 17:32:16] DEBUG[1119] devicestate.c: No provider found, checking channel drivers for PJSIP - 331 [2021-11-09 17:32:16] DEBUG[1107] threadpool.c: Increasing threadpool stasis/pool's size by 1 [2021-11-09 17:32:16] DEBUG[1119] devicestate.c: Changing state for PJSIP/331 - state 1 (Not in use) [2021-11-09 17:32:16] DEBUG[6884] manager.c: Examining AMI event: Event: DeviceStateChange Privilege: call,all Device: PJSIP/331 State: NOT_INUSE [2021-11-09 17:32:16] DEBUG[1122] devicestate.c: No provider found, checking channel drivers for SIP - 99331 [2021-11-09 17:32:16] DEBUG[1122] chan_sip.c: Checking device state for peer 99331 [2021-11-09 17:32:16] DEBUG[6884] manager.c: Examining AMI event: Event: ExtensionStatus Privilege: call,all Exten: 331 Context: ext-local Hint: PJSIP/331&SIP/99331&Custom:DND331,CustomPresence:331 Status: 0 StatusText: Idle [2021-11-09 17:32:16] DEBUG[1122] app_queue.c: Removed from pending_members [2021-11-09 17:32:16] DEBUG[1203] app_queue.c: Device 'PJSIP/331' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [2021-11-09 17:32:16] DEBUG[1122] app_queue.c: Removed from pending_members [2021-11-09 17:32:16] DEBUG[1137] res_odbc.c: Reusing ODBC handle 0x73eba208 from class 'asteriskcdrdb' [2021-11-09 17:32:16] DEBUG[1122] app_queue.c: Removed from pending_members [2021-11-09 17:32:16] DEBUG[1122] app_queue.c: Removed from pending_members [2021-11-09 17:32:16] DEBUG[1122] app_queue.c: Removed from pending_members [2021-11-09 17:32:16] DEBUG[1137] cdr_adaptive_odbc.c: Executing [INSERT INTO cdr (calldate, clid, src, dst, dcontext, channel, lastapp, duration, billsec, disposition, amaflags, uniqueid, cnum, cnam, linkedid, sequence) VALUES ({ ts '2021-11-09 17:31:46' }, '"" <331>', '331', '1', 'app-echo-test-echo', 'PJSIP/331-00000112', 'Echo', 30, 30, 'ANSWERED', 3, '1636475506.726', '331', '', '1636475506.726', 951)] [2021-11-09 17:32:16] DEBUG[1122] app_queue.c: Removed from pending_members [2021-11-09 17:32:16] DEBUG[1122] app_queue.c: Removed from pending_members [2021-11-09 17:32:16] DEBUG[1122] app_queue.c: Removed from pending_members [2021-11-09 17:32:16] DEBUG[1122] app_queue.c: Removed from pending_members [2021-11-09 17:32:16] DEBUG[1122] app_queue.c: Removed from pending_members [2021-11-09 17:32:16] DEBUG[1122] app_queue.c: Removed from pending_members [2021-11-09 17:32:16] DEBUG[1122] app_queue.c: Extension '331@ext-local' changed to state '1' (Not in use) [2021-11-09 17:32:16] DEBUG[6884] manager.c: Examining AMI event: Event: QueueMemberStatus Privilege: agent,all Queue: 886 MemberName: Interface: Local/331@from-queue/n StateInterface: hint:331@ext-local Membership: static Penalty: 0 CallsTaken: 0 LastCall: 0 LastPause: 0 InCall: 0 Status: 1 Paused: 0 PausedReason: Ringinuse: 1 Wrapuptime: 0 [2021-11-09 17:32:16] DEBUG[1122] app_queue.c: Extension '331@ext-local' changed to state '1' (Not in use) [2021-11-09 17:32:16] DEBUG[6884] manager.c: Examining AMI event: Event: QueueMemberStatus Privilege: agent,all Queue: 881 MemberName: Interface: Local/331@from-queue/n StateInterface: hint:331@ext-local Membership: static Penalty: 0 CallsTaken: 0 LastCall: 0 LastPause: 0 InCall: 0 Status: 1 Paused: 0 PausedReason: Ringinuse: 1 Wrapuptime: 0 [2021-11-09 17:32:16] DEBUG[1122] app_queue.c: Extension '331@ext-local' changed to state '1' (Not in use) [2021-11-09 17:32:16] DEBUG[6884] manager.c: Examining AMI event: Event: QueueMemberStatus Privilege: agent,all Queue: 300 MemberName: Interface: Local/331@from-queue/n StateInterface: hint:331@ext-local Membership: static Penalty: 0 CallsTaken: 0 LastCall: 0 LastPause: 0 InCall: 0 Status: 1 Paused: 0 PausedReason: Ringinuse: 1 Wrapuptime: 0 [2021-11-09 17:32:16] DEBUG[6884] manager.c: Examining AMI event: Event: QueueMemberStatus Privilege: agent,all Queue: 883 MemberName: Interface: Local/331@from-queue/n StateInterface: hint:331@ext-local Membership: static Penalty: 0 CallsTaken: 0 LastCall: 0 LastPause: 0 InCall: 0 Status: 1 Paused: 0 PausedReason: Ringinuse: 1 Wrapuptime: 0 [2021-11-09 17:32:16] DEBUG[1122] app_queue.c: Extension '331@ext-local' changed to state '1' (Not in use) [2021-11-09 17:32:16] DEBUG[6884] manager.c: Examining AMI event: Event: QueueMemberStatus Privilege: agent,all Queue: 882 MemberName: Interface: Local/331@from-queue/n StateInterface: hint:331@ext-local Membership: static Penalty: 0 CallsTaken: 0 LastCall: 0 LastPause: 0 InCall: 0 Status: 1 Paused: 0 PausedReason: Ringinuse: 1 Wrapuptime: 0 [2021-11-09 17:32:16] DEBUG[6884] manager.c: Examining AMI event: Event: QueueMemberStatus Privilege: agent,all Queue: 590 MemberName: Interface: Local/331@from-queue/n StateInterface: hint:331@ext-local Membership: static Penalty: 0 CallsTaken: 0 LastCall: 0 LastPause: 0 InCall: 0 Status: 1 Paused: 0 PausedReason: Ringinuse: 1 Wrapuptime: 0 [2021-11-09 17:32:16] DEBUG[1122] app_queue.c: Extension '331@ext-local' changed to state '1' (Not in use) [2021-11-09 17:32:16] DEBUG[6884] manager.c: Examining AMI event: Event: QueueMemberStatus Privilege: agent,all Queue: 330 MemberName: Interface: Local/331@from-queue/n StateInterface: hint:331@ext-local Membership: static Penalty: 0 CallsTaken: 0 LastCall: 0 LastPause: 0 InCall: 0 Status: 1 Paused: 0 PausedReason: Ringinuse: 1 Wrapuptime: 0 [2021-11-09 17:32:16] DEBUG[6884] manager.c: Examining AMI event: Event: QueueMemberStatus Privilege: agent,all Queue: 500 MemberName: Interface: Local/331@from-queue/n StateInterface: hint:331@ext-local Membership: static Penalty: 0 CallsTaken: 0 LastCall: 0 LastPause: 0 InCall: 0 Status: 1 Paused: 0 PausedReason: Ringinuse: 1 Wrapuptime: 0 [2021-11-09 17:32:16] DEBUG[1122] app_queue.c: Extension '331@ext-local' changed to state '1' (Not in use) [2021-11-09 17:32:16] DEBUG[6884] manager.c: Examining AMI event: Event: QueueMemberStatus Privilege: agent,all Queue: 885 MemberName: Interface: Local/331@from-queue/n StateInterface: hint:331@ext-local Membership: static Penalty: 0 CallsTaken: 0 LastCall: 0 LastPause: 0 InCall: 0 Status: 1 Paused: 0 PausedReason: Ringinuse: 1 Wrapuptime: 0 [2021-11-09 17:32:16] DEBUG[1122] app_queue.c: Extension '331@ext-local' changed to state '1' (Not in use) [2021-11-09 17:32:16] DEBUG[6884] manager.c: Examining AMI event: Event: QueueMemberStatus Privilege: agent,all Queue: 884 MemberName: Interface: Local/331@from-queue/n StateInterface: hint:331@ext-local Membership: static Penalty: 0 CallsTaken: 0 LastCall: 0 LastPause: 0 InCall: 0 Status: 1 Paused: 0 PausedReason: Ringinuse: 1 Wrapuptime: 0 [2021-11-09 17:32:16] DEBUG[6884] manager.c: Examining AMI event: Event: QueueMemberStatus Privilege: agent,all Queue: 887 MemberName: Interface: Local/331@from-queue/n StateInterface: hint:331@ext-local Membership: static Penalty: 0 CallsTaken: 0 LastCall: 0 LastPause: 0 InCall: 0 Status: 1 Paused: 0 PausedReason: Ringinuse: 1 Wrapuptime: 0 [2021-11-09 17:32:16] DEBUG[1122] app_queue.c: Extension '331@ext-local' changed to state '1' (Not in use) [2021-11-09 17:32:16] DEBUG[1122] app_queue.c: Extension '331@ext-local' changed to state '1' (Not in use) [2021-11-09 17:32:16] DEBUG[1122] app_queue.c: Extension '331@ext-local' changed to state '1' (Not in use) [2021-11-09 17:32:16] DEBUG[1122] app_queue.c: Extension '331@ext-local' changed to state '1' (Not in use) [2021-11-09 17:32:16] DEBUG[1137] res_odbc.c: Releasing ODBC handle 0x73eba208 into pool [2021-11-09 17:32:18] DEBUG[1153] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to :5061 (this may be re-written again later) [2021-11-09 17:32:18] VERBOSE[1153] res_pjsip_logger.c: <--- Transmitting SIP response (997 bytes) to TLS::48950 ---> SIP/2.0 200 OK Via: SIP/2.0/TLS :41309;rport=48950;received=;branch=z9hG4bK-524287-1---9d893386b9e0b46d Call-ID: CQdLbgtd0ZPU7DIOH8w5hg.. From: >;tag=3a643242 To: >;tag=a911c608-2a7e-4a75-9263-164ed164031d CSeq: 2 INVITE Server: FPBX-15.0.17.55(16.18.0) Contact: :5061;transport=TLS> Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER Supported: 100rel, timer, replaces, norefersub P-Asserted-Identity: "Echo Test" > Content-Type: application/sdp Content-Length: 333 v=0 o=- 92968048 3 IN IP4 s=Asterisk c=IN IP4 t=0 0 m=audio 19202 RTP/SAVP 8 101 a=crypto:5 AES_256_CM_HMAC_SHA1_80 inline:YHq+56LQqv8suomMPvW05nf6sWfXveKZ4WxgL+D+21eENWqWI54LQUU2aOLyBw== a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:150 a=sendrecv [2021-11-09 17:32:18] DEBUG[1153] res_pjsip/pjsip_resolver.c: Performing SIP DNS resolution of target '' [2021-11-09 17:32:18] DEBUG[1153] res_pjsip/pjsip_resolver.c: Transport type for target '' is 'TLS transport' [2021-11-09 17:32:18] DEBUG[1153] res_pjsip/pjsip_resolver.c: Target '' is an IP address, skipping resolution [2021-11-09 17:32:18] VERBOSE[1153] res_pjsip_logger.c: <--- Transmitting SIP request (409 bytes) to TLS::48950 ---> BYE sip:331@:48950;transport=TLS SIP/2.0 Via: SIP/2.0/TLS :5061;rport;branch=z9hG4bKPjc2b8d4e1-2fd0-4e46-8363-0f0b4447143c;alias From: >;tag=a911c608-2a7e-4a75-9263-164ed164031d To: >;tag=3a643242 Call-ID: CQdLbgtd0ZPU7DIOH8w5hg.. CSeq: 26389 BYE Max-Forwards: 70 User-Agent: FPBX-15.0.17.55(16.18.0) Content-Length: 0 [2021-11-09 17:32:18] DEBUG[1153] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [2021-11-09 17:32:18] DEBUG[1153] res_pjsip_session.c: The state change pertains to the endpoint '331()' [2021-11-09 17:32:18] DEBUG[1153] res_pjsip_session.c: The inv session still has an invite_tsx (0x6a86c384) [2021-11-09 17:32:18] DEBUG[1153] res_pjsip_session.c: The UAC BYE transaction involved in this state change is 0x74028cf4 [2021-11-09 17:32:18] DEBUG[1153] res_pjsip_session.c: The current transaction state is Calling [2021-11-09 17:32:18] DEBUG[1153] res_pjsip_session.c: The transaction state change event is TX_MSG [2021-11-09 17:32:18] DEBUG[1153] res_pjsip_session.c: The current inv state is CONNECTING [2021-11-09 17:32:18] DEBUG[1153] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [2021-11-09 17:32:18] DEBUG[1153] res_pjsip_session.c: The state change pertains to the endpoint '331()' [2021-11-09 17:32:18] DEBUG[1153] res_pjsip_session.c: The inv session does NOT have an invite_tsx [2021-11-09 17:32:18] DEBUG[1153] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x6a86c384 [2021-11-09 17:32:18] DEBUG[1153] res_pjsip_session.c: The current transaction state is Terminated [2021-11-09 17:32:18] DEBUG[1153] res_pjsip_session.c: The transaction state change event is TIMER [2021-11-09 17:32:18] DEBUG[1153] res_pjsip_session.c: The current inv state is CONNECTING [2021-11-09 17:32:18] VERBOSE[1153] res_pjsip_logger.c: <--- Received SIP response (432 bytes) from TLS::48950 ---> SIP/2.0 200 OK Via: SIP/2.0/TLS :5061;rport=5061;branch=z9hG4bKPjc2b8d4e1-2fd0-4e46-8363-0f0b4447143c;received=;alias Contact: :48950;transport=TLS> To: >;tag=3a643242 From: >;tag=a911c608-2a7e-4a75-9263-164ed164031d Call-ID: CQdLbgtd0ZPU7DIOH8w5hg.. CSeq: 26389 BYE User-Agent: Zoiper rv2.10.12.3-mod Content-Length: 0 [2021-11-09 17:32:18] DEBUG[1153] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x6a80007c for Response msg 200/BYE/cseq=26389 (rdata0x12ed2ec) [2021-11-09 17:32:18] DEBUG[1153] res_pjsip/pjsip_distributor.c: Found serializer pjsip/distributor-00000045 associated with dialog dlg0x6a80007c [2021-11-09 17:32:18] DEBUG[21161] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [2021-11-09 17:32:18] DEBUG[21161] res_pjsip_session.c: The state change pertains to the endpoint '331()' [2021-11-09 17:32:18] DEBUG[21161] res_pjsip_session.c: The inv session does NOT have an invite_tsx [2021-11-09 17:32:18] DEBUG[21161] res_pjsip_session.c: There is no transaction involved in this state change [2021-11-09 17:32:18] DEBUG[21161] res_pjsip_session.c: The current inv state is DISCONNCTD [2021-11-09 17:32:18] DEBUG[21161] res_pjsip_session.c: 331: Source of transaction state change is RX_MSG [2021-11-09 17:32:18] DEBUG[21161] res_pjsip_session.c: 331: Received response [2021-11-09 17:32:18] DEBUG[21161] res_pjsip_session.c: 331: Response is 200 OK [2021-11-09 17:32:18] DEBUG[21161] res_pjsip_session.c: 331 [2021-11-09 17:32:18] DEBUG[21161] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [2021-11-09 17:32:18] DEBUG[21161] res_pjsip_session.c: The state change pertains to the endpoint '331()' [2021-11-09 17:32:18] DEBUG[21161] res_pjsip_session.c: The inv session does NOT have an invite_tsx [2021-11-09 17:32:18] DEBUG[21161] res_pjsip_session.c: The UAC BYE transaction involved in this state change is 0x74028cf4 [2021-11-09 17:32:18] DEBUG[21161] res_pjsip_session.c: The current transaction state is Completed [2021-11-09 17:32:18] DEBUG[21161] res_pjsip_session.c: The transaction state change event is RX_MSG [2021-11-09 17:32:18] DEBUG[21161] res_pjsip_session.c: The current inv state is DISCONNCTD [2021-11-09 17:32:18] DEBUG[21161] res_pjsip_session.c: 331: Response is 200 OK [2021-11-09 17:32:18] DEBUG[21161] res_pjsip_session.c: 331 [2021-11-09 17:32:18] DEBUG[21161] res_pjsip_session.c: 331: BYE received final response code 200 [2021-11-09 17:32:18] DEBUG[1153] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [2021-11-09 17:32:18] DEBUG[1153] res_pjsip_session.c: The state change pertains to the endpoint '331()' [2021-11-09 17:32:18] DEBUG[1153] res_pjsip_session.c: The inv session does NOT have an invite_tsx [2021-11-09 17:32:18] DEBUG[1153] res_pjsip_session.c: The UAC BYE transaction involved in this state change is 0x74028cf4 [2021-11-09 17:32:18] DEBUG[1153] res_pjsip_session.c: The current transaction state is Terminated [2021-11-09 17:32:18] DEBUG[1153] res_pjsip_session.c: The transaction state change event is TIMER [2021-11-09 17:32:18] DEBUG[1153] res_pjsip_session.c: The current inv state is DISCONNCTD [2021-11-09 17:32:18] DEBUG[21161] res_pjsip_session.c: 331: Destroying SIP session [2021-11-09 17:32:19] DEBUG[22916] manager.c: Running action 'Login' [2021-11-09 17:32:22] DEBUG[1168] res_pjsip_registrar.c: Woke up at 1636475542 Interval: 30 [2021-11-09 17:32:22] DEBUG[1168] res_pjsip_registrar.c: Expiring 0 contacts [2021-11-09 17:32:23] DEBUG[22923] manager.c: Running action 'Login' [2021-11-09 17:32:24] VERBOSE[1153] res_pjsip_logger.c: <--- Received SIP request (890 bytes) from TLS::48950 ---> REGISTER sip:;transport=TLS SIP/2.0 Via: SIP/2.0/TLS :41309;branch=z9hG4bK-524287-1---77f3a74208ee41a9;rport Max-Forwards: 70 Contact: :48950;transport=TLS;rinstance=2c586552061c4a8c> To: ;transport=TLS> From: ;transport=TLS>;tag=a8da667a Call-ID: iWw60LDMFS7heqvvA4PEVw.. CSeq: 11 REGISTER Expires: 60 Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE User-Agent: Zoiper rv2.10.12.3-mod Authorization: Digest username="331",realm="asterisk",nonce="1636475490/9dff56dfcd168b923662e4f384c5527e",uri="sip:;transport=TLS",response="738ea9133097950f5ddf4ab1d96f6873",cnonce="c752ef374de655930fd0586d9b887b4c",nc=00000002,qop=auth,algorithm=md5,opaque="11d226fd3697c1a5" Allow-Events: presence, kpml, talk Content-Length: 0 [2021-11-09 17:32:24] DEBUG[1153] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg REGISTER/cseq=11 (rdata0x12ed2ec) [2021-11-09 17:32:24] DEBUG[1153] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000037 to use for Request msg REGISTER/cseq=11 (rdata0x12ed2ec) [2021-11-09 17:32:24] DEBUG[21161] netsock2.c: Splitting '' into... [2021-11-09 17:32:24] DEBUG[21161] netsock2.c: ...host '' and port ''. [2021-11-09 17:32:24] DEBUG[21161] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against [2021-11-09 17:32:24] DEBUG[21161] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '331' domain '' [2021-11-09 17:32:24] DEBUG[21161] res_pjsip_endpoint_identifier_user.c: Identified by From username '331' domain '' [2021-11-09 17:32:24] DEBUG[21161] res_pjsip_authenticator_digest.c: Using default realm 'asterisk' on incoming auth '331-auth'. [2021-11-09 17:32:24] DEBUG[21161] netsock2.c: Splitting '' into... [2021-11-09 17:32:24] DEBUG[21161] netsock2.c: ...host '' and port ''. [2021-11-09 17:32:24] DEBUG[21161] netsock2.c: Splitting '' into... [2021-11-09 17:32:24] DEBUG[21161] netsock2.c: ...host '' and port ''. [2021-11-09 17:32:24] VERBOSE[21161] res_pjsip_logger.c: <--- Transmitting SIP response (530 bytes) to TLS::48950 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/TLS :41309;rport=48950;received=;branch=z9hG4bK-524287-1---77f3a74208ee41a9 Call-ID: iWw60LDMFS7heqvvA4PEVw.. From: >;tag=a8da667a To: >;tag=z9hG4bK-524287-1---77f3a74208ee41a9 CSeq: 11 REGISTER WWW-Authenticate: Digest realm="asterisk",nonce="1636475544/c5ca6456d850587cd41b31dbc2099eeb",opaque="12bfc53c21b7862f",stale=true,algorithm=md5,qop="auth" Server: FPBX-15.0.17.55(16.18.0) Content-Length: 0 [2021-11-09 17:32:24] VERBOSE[1153] res_pjsip_logger.c: <--- Received SIP request (890 bytes) from TLS::48950 ---> REGISTER sip:;transport=TLS SIP/2.0 Via: SIP/2.0/TLS :41309;branch=z9hG4bK-524287-1---016feaad5329b2fe;rport Max-Forwards: 70 Contact: :48950;transport=TLS;rinstance=2c586552061c4a8c> To: ;transport=TLS> From: ;transport=TLS>;tag=a8da667a Call-ID: iWw60LDMFS7heqvvA4PEVw.. CSeq: 12 REGISTER Expires: 60 Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE User-Agent: Zoiper rv2.10.12.3-mod Authorization: Digest username="331",realm="asterisk",nonce="1636475544/c5ca6456d850587cd41b31dbc2099eeb",uri="sip:;transport=TLS",response="1b0128e4beb985bc600a5d1f1d84d781",cnonce="595175c35ae15b1acfd5b0b370b22e5c",nc=00000001,qop=auth,algorithm=md5,opaque="12bfc53c21b7862f" Allow-Events: presence, kpml, talk Content-Length: 0 [2021-11-09 17:32:24] DEBUG[1153] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg REGISTER/cseq=12 (rdata0x12ed2ec) [2021-11-09 17:32:24] DEBUG[1153] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000037 to use for Request msg REGISTER/cseq=12 (rdata0x12ed2ec) [2021-11-09 17:32:24] DEBUG[21161] netsock2.c: Splitting '' into... [2021-11-09 17:32:24] DEBUG[21161] netsock2.c: ...host '' and port ''. [2021-11-09 17:32:24] DEBUG[21161] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against [2021-11-09 17:32:24] DEBUG[21161] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username '331' domain '' [2021-11-09 17:32:24] DEBUG[21161] res_pjsip_endpoint_identifier_user.c: Identified by From username '331' domain '' [2021-11-09 17:32:24] DEBUG[21161] res_pjsip_authenticator_digest.c: Using default realm 'asterisk' on incoming auth '331-auth'. [2021-11-09 17:32:24] DEBUG[21161] res_pjsip_authenticator_digest.c: Calculated nonce 1636475544/c5ca6456d850587cd41b31dbc2099eeb. Actual nonce is 1636475544/c5ca6456d850587cd41b31dbc2099eeb [2021-11-09 17:32:24] DEBUG[21161] netsock2.c: Splitting '' into... [2021-11-09 17:32:24] DEBUG[21161] netsock2.c: ...host '' and port ''. [2021-11-09 17:32:24] DEBUG[21161] netsock2.c: Splitting '' into... [2021-11-09 17:32:24] DEBUG[21161] netsock2.c: ...host '' and port ''. [2021-11-09 17:32:24] DEBUG[21161] res_pjsip_registrar.c: Matched id '331' to aor '331' [2021-11-09 17:32:24] DEBUG[21161] res_pjsip_registrar.c: Matched aor '331' by To username [2021-11-09 17:32:24] DEBUG[21161] config.c: extract double from [3.0] in [-inf, inf] gives [3.000000](0) [2021-11-09 17:32:24] DEBUG[21161] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2021-11-09 17:32:24] DEBUG[21161] config.c: extract double from [3.000000] in [-inf, inf] gives [3.000000](0) [2021-11-09 17:32:24] DEBUG[21161] config.c: extract uint from [41309] in [0, 4294967295] gives [41309](0) [2021-11-09 17:32:24] DEBUG[21161] config.c: extract uint from [60] in [0, 86400] gives [60](0) [2021-11-09 17:32:24] DEBUG[21161] config.c: extract double from [3.0] in [-inf, inf] gives [3.000000](0) [2021-11-09 17:32:24] DEBUG[21161] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2021-11-09 17:32:24] DEBUG[21161] config.c: extract double from [3.000000] in [-inf, inf] gives [3.000000](0) [2021-11-09 17:32:24] DEBUG[21161] config.c: extract uint from [41309] in [0, 4294967295] gives [41309](0) [2021-11-09 17:32:24] DEBUG[21161] config.c: extract uint from [60] in [0, 86400] gives [60](0) [2021-11-09 17:32:24] DEBUG[21161] res_pjsip_registrar.c: Refreshed contact 'sip:331@:48950;transport=TLS;rinstance=2c586552061c4a8c' on AOR '331' with new expiration of 60 seconds [2021-11-09 17:32:24] DEBUG[21162] res_pjsip_mwi.c: Sending unsolicited MWI NOTIFY to endpoint 331, new messages: 0, old messages: 25 [2021-11-09 17:32:24] VERBOSE[21161] res_pjsip_logger.c: <--- Transmitting SIP response (505 bytes) to TLS::48950 ---> SIP/2.0 200 OK Via: SIP/2.0/TLS :41309;rport=48950;received=;branch=z9hG4bK-524287-1---016feaad5329b2fe Call-ID: iWw60LDMFS7heqvvA4PEVw.. From: >;tag=a8da667a To: >;tag=z9hG4bK-524287-1---016feaad5329b2fe CSeq: 12 REGISTER Date: Tue, 09 Nov 2021 16:32:24 GMT Contact: :48950;transport=TLS;rinstance=2c586552061c4a8c>;expires=59 Expires: 60 Server: FPBX-15.0.17.55(16.18.0) Content-Length: 0 [2021-11-09 17:32:24] DEBUG[21162] config.c: extract double from [3.0] in [-inf, inf] gives [3.000000](0) [2021-11-09 17:32:24] DEBUG[21162] config.c: extract uint from [0] in [0, 4294967295] gives [0](0) [2021-11-09 17:32:24] DEBUG[21162] config.c: extract double from [3.000000] in [-inf, inf] gives [3.000000](0) [2021-11-09 17:32:24] DEBUG[21162] config.c: extract uint from [41309] in [0, 4294967295] gives [41309](0) [2021-11-09 17:32:24] DEBUG[21162] config.c: extract uint from [60] in [0, 86400] gives [60](0) [2021-11-09 17:32:24] DEBUG[21162] res_pjsip.c: 0x74111770: Wrapper created [2021-11-09 17:32:24] DEBUG[21162] res_pjsip/pjsip_resolver.c: Performing SIP DNS resolution of target '' [2021-11-09 17:32:24] DEBUG[21162] res_pjsip/pjsip_resolver.c: Transport type for target '' is 'TLS transport' [2021-11-09 17:32:24] DEBUG[21162] res_pjsip/pjsip_resolver.c: Target '' is an IP address, skipping resolution [2021-11-09 17:32:24] DEBUG[21162] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to :5061 (this may be re-written again later) [2021-11-09 17:32:24] VERBOSE[21162] res_pjsip_logger.c: <--- Transmitting SIP request (721 bytes) to TLS::48950 ---> NOTIFY sip:331@:48950;transport=TLS;rinstance=2c586552061c4a8c SIP/2.0 Via: SIP/2.0/TLS :5061;rport;branch=z9hG4bKPj086023b5-1013-498e-b12f-8dbf01b35a98;alias From: >;tag=d9debb81-f1a6-412b-86ef-c239f7b2cbab To: ;rinstance=2c586552061c4a8c> Contact: :5061;transport=TLS> Call-ID: d4ed17fd-50a1-44b7-8fa4-ef51580f8d9e CSeq: 26411 NOTIFY Subscription-State: terminated Event: message-summary Allow-Events: presence, dialog, message-summary, refer Max-Forwards: 70 User-Agent: FPBX-15.0.17.55(16.18.0) Content-Type: application/simple-message-summary Content-Length: 49 Messages-Waiting: no Voice-Message: 0/25 (0/0) [2021-11-09 17:32:24] VERBOSE[1153] res_pjsip_logger.c: <--- Received SIP response (456 bytes) from TLS::48950 ---> SIP/2.0 200 OK Via: SIP/2.0/TLS :5061;rport=5061;branch=z9hG4bKPj086023b5-1013-498e-b12f-8dbf01b35a98;received=;alias Contact: :41309;transport=tls> To: ;rinstance=2c586552061c4a8c>;tag=d1ed2f31 From: >;tag=d9debb81-f1a6-412b-86ef-c239f7b2cbab Call-ID: d4ed17fd-50a1-44b7-8fa4-ef51580f8d9e CSeq: 26411 NOTIFY User-Agent: Zoiper rv2.10.12.3-mod Content-Length: 0 [2021-11-09 17:32:24] DEBUG[1153] res_pjsip/pjsip_distributor.c: No dialog serializer for Response msg 200/NOTIFY/cseq=26411 (rdata0x12ed2ec). Using request transaction as basis. [2021-11-09 17:32:24] DEBUG[1153] res_pjsip/pjsip_distributor.c: Found transaction tsx0x6a80007c for Response msg 200/NOTIFY/cseq=26411 (rdata0x12ed2ec). [2021-11-09 17:32:24] DEBUG[1153] res_pjsip/pjsip_distributor.c: Found serializer pjsip/mwi-00000067 on transaction tsx0x6a80007c [2021-11-09 17:32:24] DEBUG[21161] res_pjsip.c: 0x74111770: PJSIP tsx response received [2021-11-09 17:32:24] DEBUG[21161] res_pjsip.c: 0x74111770: Callbacks executed [2021-11-09 17:32:24] DEBUG[21161] res_pjsip.c: 0x74111770: wrapper destroyed [2021-11-09 17:32:24] DEBUG[22930] manager.c: Running action 'Login'