[2016-11-03 10:06:26] DEBUG[28966][C-00000056]: chan_sip.c:13568 add_sdp: -- Done with adding codecs to SDP [2016-11-03 10:06:26] DEBUG[28966][C-00000056]: chan_sip.c:13781 add_sdp: Done building SDP. Settling with this capability: (g722|alaw|ulaw|gsm) [2016-11-03 10:06:26] DEBUG[28966][C-00000056]: chan_sip.c:3389 initialize_initreq: Initializing initreq for method INVITE - callid 43fc1d2572c7738c02a4c773605154fe@tel.t-online.de Reliably Transmitting (NAT) to 217.0.20.234:5060: INVITE sip:015175949493@tel.t-online.de SIP/2.0 Via: SIP/2.0/UDP 91.33.188.109:45061;branch=z9hG4bK1fe2d2c1;rport Max-Forwards: 70 From: "+496123456789" ;tag=as22681a60 To: Contact: Call-ID: 43fc1d2572c7738c02a4c773605154fe@tel.t-online.de CSeq: 102 INVITE User-Agent: FPBX-13.0.190.1(13.12.1) Date: Thu, 03 Nov 2016 09:06:26 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces P-Asserted-Identity: "+496123456789" Content-Type: application/sdp Content-Length: 321 v=0 o=root 56681131 56681131 IN IP4 91.33.188.109 s=Asterisk PBX 13.12.1 c=IN IP4 91.33.188.109 t=0 0 m=audio 13780 RTP/AVP 9 8 0 3 101 a=rtpmap:9 G722/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:3 GSM/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:150 a=sendrecv --- [2016-11-03 10:06:26] DEBUG[28966][C-00000056]: chan_sip.c:3746 __sip_xmit: Trying to put 'INVITE sip:' onto UDP socket destined for 217.0.20.234:5060 Retransmitting #1 (NAT) to 217.0.20.234:5060: INVITE sip:015175949493@tel.t-online.de SIP/2.0 Via: SIP/2.0/UDP 91.33.188.109:45061;branch=z9hG4bK1fe2d2c1;rport Max-Forwards: 70 From: "+496123456789" ;tag=as22681a60 To: Contact: Call-ID: 43fc1d2572c7738c02a4c773605154fe@tel.t-online.de CSeq: 102 INVITE User-Agent: FPBX-13.0.190.1(13.12.1) Date: Thu, 03 Nov 2016 09:06:26 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces P-Asserted-Identity: "+496123456789" Content-Type: application/sdp Content-Length: 321 v=0 o=root 56681131 56681131 IN IP4 91.33.188.109 s=Asterisk PBX 13.12.1 c=IN IP4 91.33.188.109 t=0 0 m=audio 13780 RTP/AVP 9 8 0 3 101 a=rtpmap:9 G722/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:3 GSM/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:150 a=sendrecv --- [2016-11-03 10:06:26] DEBUG[14998]: chan_sip.c:3746 __sip_xmit: Trying to put 'INVITE sip:' onto UDP socket destined for 217.0.20.234:5060 <--- SIP read from UDP:217.0.20.234:5060 ---> SIP/2.0 407 Proxy Authentication Required 02035034C Via: SIP/2.0/UDP 91.33.188.109:45061;received=91.33.188.109;rport=45061;branch=z9hG4bK1fe2d2c1 To: ;tag=h7g4Esbg_74bdf46404d8718e30c535d9631fbd09 From: "+496123456789" ;tag=as22681a60 Call-ID: 43fc1d2572c7738c02a4c773605154fe@tel.t-online.de CSeq: 102 INVITE Content-Length: 0 Proxy-Authenticate: Digest nonce="FA1D6B641CFE1A58000000007640273D",realm="tel.t-online.de",algorithm=MD5,qop="auth",stale=true <-------------> --- (8 headers 0 lines) --- [2016-11-03 10:06:26] DEBUG[14998][C-00000056]: chan_sip.c:4511 __sip_ack: Acked pending invite 102 [2016-11-03 10:06:26] DEBUG[14998][C-00000056]: chan_sip.c:4527 __sip_ack: Stopping retransmission on '43fc1d2572c7738c02a4c773605154fe@tel.t-online.de' of Request 102: Match Found Transmitting (NAT) to 217.0.20.234:5060: ACK sip:015175949493@tel.t-online.de SIP/2.0 Via: SIP/2.0/UDP 91.33.188.109:45061;branch=z9hG4bK1fe2d2c1;rport Max-Forwards: 70 From: "+496123456789" ;tag=as22681a60 To: ;tag=h7g4Esbg_74bdf46404d8718e30c535d9631fbd09 Contact: Call-ID: 43fc1d2572c7738c02a4c773605154fe@tel.t-online.de CSeq: 102 ACK User-Agent: FPBX-13.0.190.1(13.12.1) Content-Length: 0 --- [2016-11-03 10:06:26] DEBUG[14998][C-00000056]: chan_sip.c:3746 __sip_xmit: Trying to put 'ACK sip:015' onto UDP socket destined for 217.0.20.234:5060 [2016-11-03 10:06:26] DEBUG[14998][C-00000056]: chan_sip.c:22595 do_proxy_auth: Auth attempt 1 on INVITE [2016-11-03 10:06:26] DEBUG[14998][C-00000056]: chan_sip.c:13397 add_sdp: ** Our capability: (g722|alaw|ulaw|gsm) Video flag: False Text flag: False [2016-11-03 10:06:26] DEBUG[14998][C-00000056]: chan_sip.c:13398 add_sdp: ** Our prefcodec: (g722) Audio is at 13780 Adding codec g722 to SDP Adding codec alaw to SDP Adding codec ulaw to SDP Adding codec gsm to SDP Adding non-codec 0x1 (telephone-event) to SDP [2016-11-03 10:06:26] DEBUG[14998][C-00000056]: chan_sip.c:13568 add_sdp: -- Done with adding codecs to SDP [2016-11-03 10:06:26] DEBUG[14998][C-00000056]: chan_sip.c:13781 add_sdp: Done building SDP. Settling with this capability: (g722|alaw|ulaw|gsm) Reliably Transmitting (NAT) to 217.0.20.234:5060: INVITE sip:015175949493@tel.t-online.de SIP/2.0 Via: SIP/2.0/UDP 91.33.188.109:45061;branch=z9hG4bK53009a9a;rport Max-Forwards: 70 From: "+496123456789" ;tag=as22681a60 To: Contact: Call-ID: 43fc1d2572c7738c02a4c773605154fe@tel.t-online.de CSeq: 103 INVITE User-Agent: FPBX-13.0.190.1(13.12.1) Proxy-Authorization: Digest username="23849394390@t-online.de", realm="tel.t-online.de", algorithm=MD5, uri="sip:015175949493@tel.t-online.de", nonce="FA1D6B641CFE1A58000000007640273D", response="89d60773465ebb8e0afb50c1fc7e73f1", qop=auth, cnonce="277853aa", nc=00000001 Date: Thu, 03 Nov 2016 09:06:26 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces P-Asserted-Identity: "+496123456789" Content-Type: application/sdp Content-Length: 321 v=0 o=root 56681131 56681132 IN IP4 91.33.188.109 s=Asterisk PBX 13.12.1 c=IN IP4 91.33.188.109 t=0 0 m=audio 13780 RTP/AVP 9 8 0 3 101 a=rtpmap:9 G722/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:3 GSM/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:150 a=sendrecv --- [2016-11-03 10:06:26] DEBUG[14998][C-00000056]: chan_sip.c:3746 __sip_xmit: Trying to put 'INVITE sip:' onto UDP socket destined for 217.0.20.234:5060 <--- SIP read from UDP:217.0.20.234:5060 ---> SIP/2.0 407 Proxy Authentication Required 02035034C Via: SIP/2.0/UDP 91.33.188.109:45061;received=91.33.188.109;rport=45061;branch=z9hG4bK1fe2d2c1 To: ;tag=h7g4Esbg_74bdf46404d8718e30c535d9631fbd09 From: "+496123456789" ;tag=as22681a60 Call-ID: 43fc1d2572c7738c02a4c773605154fe@tel.t-online.de CSeq: 102 INVITE Content-Length: 0 Proxy-Authenticate: Digest nonce="FA1D6B641CFE1A58000000007640273D",realm="tel.t-online.de",algorithm=MD5,qop="auth",stale=true <-------------> --- (8 headers 0 lines) --- [2016-11-03 10:06:26] DEBUG[14998][C-00000056]: chan_sip.c:4527 __sip_ack: Stopping retransmission on '43fc1d2572c7738c02a4c773605154fe@tel.t-online.de' of Request 102: Match Not Found Transmitting (NAT) to 217.0.20.234:5060: ACK sip:015175949493@tel.t-online.de SIP/2.0 Via: SIP/2.0/UDP 91.33.188.109:45061;branch=z9hG4bK53009a9a;rport Max-Forwards: 70 From: "+496123456789" ;tag=as22681a60 To: Contact: Call-ID: 43fc1d2572c7738c02a4c773605154fe@tel.t-online.de CSeq: 102 ACK User-Agent: FPBX-13.0.190.1(13.12.1) Content-Length: 0 --- [2016-11-03 10:06:26] DEBUG[14998][C-00000056]: chan_sip.c:3746 __sip_xmit: Trying to put 'ACK sip:015' onto UDP socket destined for 217.0.20.234:5060 Retransmitting #1 (NAT) to 217.0.20.234:5060: INVITE sip:015175949493@tel.t-online.de SIP/2.0 Via: SIP/2.0/UDP 91.33.188.109:45061;branch=z9hG4bK53009a9a;rport Max-Forwards: 70 From: "+496123456789" ;tag=as22681a60 To: Contact: Call-ID: 43fc1d2572c7738c02a4c773605154fe@tel.t-online.de CSeq: 103 INVITE User-Agent: FPBX-13.0.190.1(13.12.1) Proxy-Authorization: Digest username="23849394390@t-online.de", realm="tel.t-online.de", algorithm=MD5, uri="sip:015175949493@tel.t-online.de", nonce="FA1D6B641CFE1A58000000007640273D", response="89d60773465ebb8e0afb50c1fc7e73f1", qop=auth, cnonce="277853aa", nc=00000001 Date: Thu, 03 Nov 2016 09:06:26 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces P-Asserted-Identity: "+496123456789" Content-Type: application/sdp Content-Length: 321 v=0 o=root 56681131 56681132 IN IP4 91.33.188.109 s=Asterisk PBX 13.12.1 c=IN IP4 91.33.188.109 t=0 0 m=audio 13780 RTP/AVP 9 8 0 3 101 a=rtpmap:9 G722/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:3 GSM/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:150 a=sendrecv --- [2016-11-03 10:06:26] DEBUG[14998]: chan_sip.c:3746 __sip_xmit: Trying to put 'INVITE sip:' onto UDP socket destined for 217.0.20.234:5060 [2016-11-03 10:06:26] DEBUG[14998]: chan_sip.c:4351 __sip_autodestruct: Auto destroying SIP dialog '1d23044a66f66614011ef22d09cfd963@tel.t-online.de' [2016-11-03 10:06:26] DEBUG[14998]: chan_sip.c:6579 sip_pvt_dtor: Destroying SIP dialog 1d23044a66f66614011ef22d09cfd963@tel.t-online.de Really destroying SIP dialog '1d23044a66f66614011ef22d09cfd963@tel.t-online.de' Method: INVITE [2016-11-03 10:06:26] DEBUG[14998]: rtp_engine.c:384 instance_destructor: Destroyed RTP instance '0x7f211801f698' <--- SIP read from UDP:217.0.20.234:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 91.33.188.109:45061;received=91.33.188.109;rport=45061;branch=z9hG4bK53009a9a To: From: "+496123456789" ;tag=as22681a60 Call-ID: 43fc1d2572c7738c02a4c773605154fe@tel.t-online.de CSeq: 103 INVITE Content-Length: 0 <-------------> --- (7 headers 0 lines) --- [2016-11-03 10:06:26] DEBUG[14998][C-00000056]: chan_sip.c:4568 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '43fc1d2572c7738c02a4c773605154fe@tel.t-online.de' Request 103: Found <--- SIP read from UDP:217.0.20.234:5060 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 91.33.188.109:45061;received=91.33.188.109;rport=45061;branch=z9hG4bK53009a9a To: ;tag=h7g4Esbg_p65551t1478163986m592189c893905464s1_3747035002-709087048 From: "+496123456789" ;tag=as22681a60 Call-ID: 43fc1d2572c7738c02a4c773605154fe@tel.t-online.de CSeq: 103 INVITE Contact: Record-Route: Supported: timer Content-Length: 0 Allow: UPDATE, REFER, PRACK, OPTIONS, BYE, ACK, CANCEL, INVITE, REGISTER <-------------> --- (11 headers 0 lines) --- [2016-11-03 10:06:27] DEBUG[14998][C-00000056]: chan_sip.c:4568 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '43fc1d2572c7738c02a4c773605154fe@tel.t-online.de' Request 103: Found [2016-11-03 10:06:27] DEBUG[14998][C-00000056]: sip/route.c:105 sip_route_process_header: sip_route_process_header: sip_route_dump: route/path hop: [2016-11-03 10:06:27] DEBUG[14931]: chan_sip.c:30155 sip_devicestate: Checking device state for peer 061129634568 [2016-11-03 10:06:27] DEBUG[14931]: devicestate.c:474 do_state_change: Changing state for SIP/061129634568 - state 1 (Not in use) [2016-11-03 10:06:27] DEBUG[14931]: devicestate.c:474 do_state_change: Changing state for PJSIP/2000 - state 2 (In use) [2016-11-03 10:06:27] DEBUG[22763]: res_pjsip_session.c:2495 handle_outgoing_response: Method is INVITE, Response is 180 Ringing [2016-11-03 10:06:27] DEBUG[14935]: devicestate.c:365 _ast_device_state: Checking if I can find provider for "Custom" - number: DND2000 [2016-11-03 10:06:27] DEBUG[14935]: db.c:376 db_get_common: Unable to find key 'DND2000' in family 'CustomDevstate' [2016-11-03 10:06:27] DEBUG[14935]: app_queue.c:2549 extension_state_cb: Extension '2000@ext-local' changed to state '2' (In use) [2016-11-03 10:06:27] DEBUG[15017]: app_queue.c:2477 device_state_cb: Device 'PJSIP/2000' changed to state '2' (In use) but we don't care because they're not a member of any queue. <--- Transmitting SIP response (621 bytes) to UDP:10.0.1.2:54090 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 10.3.0.6:54090;rport=54090;received=10.0.1.2;branch=z9hG4bKPjJEG1ypjurC6fXIWqgcaXzMlkQYad79MC Call-ID: HoHM5MHo1CYog.PdWo0nc27EoheFhslG From: "Daniel Heckl" ;tag=KjAr421pwUCcTm6rKUl6.CJPMOfjDiF2 To: ;tag=cb145a98-445b-4004-b0fc-3a6e18eac3f9 CSeq: 15659 INVITE Server: FPBX-13.0.190.1(13.12.1) Contact: Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, REFER, MESSAGE P-Asserted-Identity: "CID:+496123456789" Content-Length: 0 [2016-11-03 10:06:27] DEBUG[22763]: res_pjsip_session.c:2608 session_inv_on_state_changed: Source of transaction state change is TX_MSG [2016-11-03 10:06:27] DEBUG[22763]: res_pjsip_session.c:2507 handle_outgoing: Sending response [2016-11-03 10:06:27] DEBUG[22763]: res_pjsip_session.c:2495 handle_outgoing_response: Method is INVITE, Response is 180 Ringing [2016-11-03 10:06:27] DEBUG[22763]: res_pjsip_session.c:2507 handle_outgoing: Sending response [2016-11-03 10:06:27] DEBUG[22763]: res_pjsip_session.c:2495 handle_outgoing_response: Method is INVITE, Response is 180 Ringing <--- Received SIP request (410 bytes) from UDP:10.0.1.2:54090 ---> CANCEL sip:015175949493@10.0.1.12 SIP/2.0 Via: SIP/2.0/UDP 10.3.0.6:54090;rport;branch=z9hG4bKPjJEG1ypjurC6fXIWqgcaXzMlkQYad79MC Max-Forwards: 70 From: "Daniel Heckl" ;tag=KjAr421pwUCcTm6rKUl6.CJPMOfjDiF2 To: Call-ID: HoHM5MHo1CYog.PdWo0nc27EoheFhslG CSeq: 15659 CANCEL Route: User-Agent: Telephone 1.2.4 Content-Length: 0 [2016-11-03 10:06:28] DEBUG[14948]: res_pjsip/pjsip_distributor.c:390 distributor: Searching for serializer on dialog dlg0x7f210c034ad8 for Request msg CANCEL/cseq=15659 (rdata0x7f20dc030a68) [2016-11-03 10:06:28] DEBUG[14948]: res_pjsip/pjsip_distributor.c:396 distributor: Found serializer pjsip/distributor-00000031 on dialog dlg0x7f210c034ad8 [2016-11-03 10:06:28] DEBUG[22545]: res_pjsip_session.c:2464 handle_incoming: Received request [2016-11-03 10:06:28] DEBUG[22545]: res_pjsip_session.c:2431 handle_incoming_request: Method is CANCEL <--- Transmitting SIP response (402 bytes) to UDP:10.0.1.2:54090 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.3.0.6:54090;rport=54090;received=10.0.1.2;branch=z9hG4bKPjJEG1ypjurC6fXIWqgcaXzMlkQYad79MC Call-ID: HoHM5MHo1CYog.PdWo0nc27EoheFhslG From: "Daniel Heckl" ;tag=KjAr421pwUCcTm6rKUl6.CJPMOfjDiF2 To: ;tag=cb145a98-445b-4004-b0fc-3a6e18eac3f9 CSeq: 15659 CANCEL Server: FPBX-13.0.190.1(13.12.1) Content-Length: 0 [2016-11-03 10:06:28] DEBUG[22545]: res_pjsip_session.c:2507 handle_outgoing: Sending response [2016-11-03 10:06:28] DEBUG[22545]: res_pjsip_session.c:2495 handle_outgoing_response: Method is CANCEL, Response is 200 OK <--- Transmitting SIP response (600 bytes) to UDP:10.0.1.2:54090 ---> SIP/2.0 487 Request Terminated Via: SIP/2.0/UDP 10.3.0.6:54090;rport=54090;received=10.0.1.2;branch=z9hG4bKPjJEG1ypjurC6fXIWqgcaXzMlkQYad79MC Call-ID: HoHM5MHo1CYog.PdWo0nc27EoheFhslG From: "Daniel Heckl" ;tag=KjAr421pwUCcTm6rKUl6.CJPMOfjDiF2 To: ;tag=cb145a98-445b-4004-b0fc-3a6e18eac3f9 CSeq: 15659 INVITE Server: FPBX-13.0.190.1(13.12.1) Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, REFER, MESSAGE P-Asserted-Identity: "CID:+496123456789" Content-Length: 0 [2016-11-03 10:06:28] DEBUG[22545]: res_pjsip_session.c:2608 session_inv_on_state_changed: Source of transaction state change is TX_MSG [2016-11-03 10:06:28] DEBUG[22545]: res_pjsip_session.c:2507 handle_outgoing: Sending response [2016-11-03 10:06:28] DEBUG[22545]: res_pjsip_session.c:2495 handle_outgoing_response: Method is INVITE, Response is 487 Request Terminated [2016-11-03 10:06:28] DEBUG[22545]: res_pjsip_session.c:2507 handle_outgoing: Sending response [2016-11-03 10:06:28] DEBUG[22545]: res_pjsip_session.c:2495 handle_outgoing_response: Method is INVITE, Response is 487 Request Terminated [2016-11-03 10:06:28] DEBUG[28966][C-00000056]: channel.c:2683 ast_hangup: Hanging up channel 'SIP/061129634568-00000045' [2016-11-03 10:06:28] DEBUG[14934]: cdr.c:1277 cdr_object_finalize: Finalized CDR for PJSIP/2000-00000057 - start 1478163986.357265 answer 0.000000 end 1478163988.467702 dispo NO ANSWER [2016-11-03 10:06:28] DEBUG[28966][C-00000056]: chan_sip.c:7145 sip_hangup: Hangup call SIP/061129634568-00000045, SIP callid 43fc1d2572c7738c02a4c773605154fe@tel.t-online.de [2016-11-03 10:06:28] DEBUG[28966][C-00000056]: res_rtp_asterisk.c:4925 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7f2110005118' Scheduling destruction of SIP dialog '43fc1d2572c7738c02a4c773605154fe@tel.t-online.de' in 6400 ms (Method: INVITE) [2016-11-03 10:06:28] DEBUG[14934]: cdr.c:1277 cdr_object_finalize: Finalized CDR for SIP/061129634568-00000045 - start 1478163986.384649 answer 0.000000 end 1478163988.467753 dispo NO ANSWER [2016-11-03 10:06:28] DEBUG[14934]: cdr.c:1105 cdr_object_create_public_records: CDR for SIP/061129634568-00000045 is dialed and has no Party B; discarding [2016-11-03 10:06:28] DEBUG[14937]: res_odbc.c:865 _ast_odbc_request_obj2: Reusing ODBC handle 0x7f20d8002458 from class 'asteriskcdrdb' [2016-11-03 10:06:28] DEBUG[14937]: cel_odbc.c:766 odbc_log: Executing SQL statement: [INSERT INTO cel (eventtype,eventtime,cid_name,cid_num,cid_ani,cid_rdnis,cid_dnid,exten,context,channame,appname,appdata,amaflags,accountcode,uniqueid,linkedid,peer,userdeftype,extra) VALUES ('HANGUP',{ts '2016-11-03 10:06:28.467775'},'CID:+496123456789','015175949493','','','','015175949493','from-trunk','SIP/061129634568-00000045','AppDial','(Outgoing Line)',3,'','1478163986.1036','1478163986.1034','','','{"hangupcause":16,"hangupsource":"","dialstatus":""}')] [2016-11-03 10:06:28] DEBUG[14931]: chan_sip.c:30155 sip_devicestate: Checking device state for peer 061129634568 [2016-11-03 10:06:28] DEBUG[14931]: devicestate.c:474 do_state_change: Changing state for SIP/061129634568 - state 1 (Not in use) [2016-11-03 10:06:28] DEBUG[14937]: res_odbc.c:714 ast_odbc_release_obj: Releasing ODBC handle 0x7f20d8002458 into pool [2016-11-03 10:06:28] DEBUG[14937]: res_odbc.c:865 _ast_odbc_request_obj2: Reusing ODBC handle 0x7f20d8002458 from class 'asteriskcdrdb' [2016-11-03 10:06:28] DEBUG[28966][C-00000056]: app_dial.c:3228 dial_exec_full: Exiting with DIALSTATUS=CANCEL. [2016-11-03 10:06:28] DEBUG[28966][C-00000056]: app_macro.c:453 _macro_exec: Spawn extension (macro-dialout-trunk,s,23) exited non-zero on 'PJSIP/2000-00000057' in macro 'dialout-trunk' [2016-11-03 10:06:28] DEBUG[14937]: cel_odbc.c:766 odbc_log: Executing SQL statement: [INSERT INTO cel (eventtype,eventtime,cid_name,cid_num,cid_ani,cid_rdnis,cid_dnid,exten,context,channame,appname,appdata,amaflags,accountcode,uniqueid,linkedid,peer,userdeftype,extra) VALUES ('CHAN_END',{ts '2016-11-03 10:06:28.468377'},'CID:+496123456789','015175949493','','','','015175949493','from-trunk','SIP/061129634568-00000045','AppDial','(Outgoing Line)',3,'','1478163986.1036','1478163986.1034','','','')] [2016-11-03 10:06:28] DEBUG[28966][C-00000056]: pbx.c:4346 __ast_pbx_run: Spawn extension (from-internal,015175949493,5) exited non-zero on 'PJSIP/2000-00000057' [2016-11-03 10:06:28] DEBUG[28966][C-00000056]: channel.c:2534 ast_softhangup_nolock: Soft-Hanging (0x10) up channel 'PJSIP/2000-00000057' [2016-11-03 10:06:28] DEBUG[28966][C-00000056]: channel.c:2534 ast_softhangup_nolock: Soft-Hanging (0x80) up channel 'PJSIP/2000-00000057' [2016-11-03 10:06:28] DEBUG[28966][C-00000056]: pbx.c:2875 pbx_extension_helper: Launching 'Macro' [2016-11-03 10:06:28] DEBUG[14937]: res_odbc.c:714 ast_odbc_release_obj: Releasing ODBC handle 0x7f20d8002458 into pool [2016-11-03 10:06:28] DEBUG[28966][C-00000056]: pbx_variables.c:777 pbx_substitute_variables_helper_full: Expression result is '1' [2016-11-03 10:06:28] DEBUG[28966][C-00000056]: pbx.c:2875 pbx_extension_helper: Launching 'GotoIf' [2016-11-03 10:06:28] DEBUG[28966][C-00000056]: app_macro.c:459 _macro_exec: Executed application: GotoIf [2016-11-03 10:06:28] DEBUG[28966][C-00000056]: pbx_variables.c:708 pbx_substitute_variables_helper_full: Function CDR(recordingfile) result is '' [2016-11-03 10:06:28] DEBUG[28966][C-00000056]: pbx_variables.c:777 pbx_substitute_variables_helper_full: Expression result is '0' [2016-11-03 10:06:28] DEBUG[28966][C-00000056]: pbx.c:2875 pbx_extension_helper: Launching 'ExecIf' [2016-11-03 10:06:28] DEBUG[28966][C-00000056]: app_macro.c:459 _macro_exec: Executed application: ExecIf [2016-11-03 10:06:28] DEBUG[28966][C-00000056]: pbx_variables.c:508 ast_str_substitute_variables_full: Function CDR(recordingfile) result is '' [2016-11-03 10:06:28] DEBUG[28966][C-00000056]: pbx_variables.c:566 ast_str_substitute_variables_full: Expression result is '0' [2016-11-03 10:06:28] DEBUG[28966][C-00000056]: pbx.c:2875 pbx_extension_helper: Launching 'Hangup' [2016-11-03 10:06:28] DEBUG[28966][C-00000056]: channel.c:2534 ast_softhangup_nolock: Soft-Hanging (0x20) up channel 'PJSIP/2000-00000057' [2016-11-03 10:06:28] DEBUG[28966][C-00000056]: app_macro.c:453 _macro_exec: Spawn extension (macro-hangupcall,s,4) exited non-zero on 'PJSIP/2000-00000057' in macro 'hangupcall' [2016-11-03 10:06:28] DEBUG[28966][C-00000056]: pbx.c:4157 ast_pbx_h_exten_run: Spawn extension (from-internal,h,1) exited non-zero on 'PJSIP/2000-00000057' [2016-11-03 10:06:28] DEBUG[28966][C-00000056]: channel.c:2683 ast_hangup: Hanging up channel 'PJSIP/2000-00000057' [2016-11-03 10:06:28] DEBUG[14931]: devicestate.c:474 do_state_change: Changing state for PJSIP/2000 - state 1 (Not in use) [2016-11-03 10:06:28] DEBUG[14935]: devicestate.c:365 _ast_device_state: Checking if I can find provider for "Custom" - number: DND2000 [2016-11-03 10:06:28] DEBUG[14935]: db.c:376 db_get_common: Unable to find key 'DND2000' in family 'CustomDevstate' [2016-11-03 10:06:28] DEBUG[14937]: res_odbc.c:865 _ast_odbc_request_obj2: Reusing ODBC handle 0x7f20d8002458 from class 'asteriskcdrdb' [2016-11-03 10:06:28] DEBUG[14935]: app_queue.c:2549 extension_state_cb: Extension '2000@ext-local' changed to state '1' (Not in use) [2016-11-03 10:06:28] DEBUG[15017]: app_queue.c:2477 device_state_cb: Device 'PJSIP/2000' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [2016-11-03 10:06:28] DEBUG[14937]: cel_odbc.c:766 odbc_log: Executing SQL statement: [INSERT INTO cel (eventtype,eventtime,cid_name,cid_num,cid_ani,cid_rdnis,cid_dnid,exten,context,channame,appname,appdata,amaflags,accountcode,uniqueid,linkedid,peer,userdeftype,extra) VALUES ('HANGUP',{ts '2016-11-03 10:06:28.469545'},'+496123456789','+496123456789','2000','','','h','from-internal','PJSIP/2000-00000057','','',3,'','1478163986.1034','1478163986.1034','','','{"hangupcause":127,"hangupsource":"PJSIP/2000-00000057","dialstatus":"CANCEL"}')] [2016-11-03 10:06:28] DEBUG[14937]: res_odbc.c:714 ast_odbc_release_obj: Releasing ODBC handle 0x7f20d8002458 into pool [2016-11-03 10:06:28] DEBUG[14934]: res_odbc.c:865 _ast_odbc_request_obj2: Reusing ODBC handle 0x7f20d8002458 from class 'asteriskcdrdb' [2016-11-03 10:06:28] DEBUG[14934]: res_odbc.c:714 ast_odbc_release_obj: Releasing ODBC handle 0x7f20d8002458 into pool [2016-11-03 10:06:28] DEBUG[14934]: res_odbc.c:865 _ast_odbc_request_obj2: Reusing ODBC handle 0x7f20d8002458 from class 'asteriskcdrdb' [2016-11-03 10:06:28] DEBUG[14934]: cdr_adaptive_odbc.c:740 odbc_log: Executing [INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,uniqueid,cnum,cnam,outbound_cnum,outbound_cnam) VALUES ({ ts '2016-11-03 10:06:26' },'"+496123456789" <+496123456789>','+496123456789','015175949493','from-internal','PJSIP/2000-00000057','SIP/061129634568-00000045','Dial','SIP/061129634568/015175949493,300,Tt',2,0,'NO ANSWER',3,'1478163986.1034','2000','DWebbuilder IT-Solutions','+496123456789','+496123456789')] [2016-11-03 10:06:28] DEBUG[14934]: res_odbc.c:714 ast_odbc_release_obj: Releasing ODBC handle 0x7f20d8002458 into pool [2016-11-03 10:06:28] DEBUG[14937]: res_odbc.c:865 _ast_odbc_request_obj2: Reusing ODBC handle 0x7f20d8002458 from class 'asteriskcdrdb' [2016-11-03 10:06:28] DEBUG[14937]: cel_odbc.c:766 odbc_log: Executing SQL statement: [INSERT INTO cel (eventtype,eventtime,cid_name,cid_num,cid_ani,cid_rdnis,cid_dnid,exten,context,channame,appname,appdata,amaflags,accountcode,uniqueid,linkedid,peer,userdeftype,extra) VALUES ('CHAN_END',{ts '2016-11-03 10:06:28.470015'},'+496123456789','+496123456789','2000','','','h','from-internal','PJSIP/2000-00000057','','',3,'','1478163986.1034','1478163986.1034','','','')] [2016-11-03 10:06:28] DEBUG[14937]: res_odbc.c:714 ast_odbc_release_obj: Releasing ODBC handle 0x7f20d8002458 into pool [2016-11-03 10:06:28] DEBUG[14937]: res_odbc.c:865 _ast_odbc_request_obj2: Reusing ODBC handle 0x7f20d8002458 from class 'asteriskcdrdb' [2016-11-03 10:06:28] DEBUG[14937]: cel_odbc.c:766 odbc_log: Executing SQL statement: [INSERT INTO cel (eventtype,eventtime,cid_name,cid_num,cid_ani,cid_rdnis,cid_dnid,exten,context,channame,appname,appdata,amaflags,accountcode,uniqueid,linkedid,peer,userdeftype,extra) VALUES ('LINKEDID_END',{ts '2016-11-03 10:06:28.471039'},'+496123456789','+496123456789','2000','','','h','from-internal','PJSIP/2000-00000057','','',3,'','1478163986.1034','1478163986.1034','','','')] [2016-11-03 10:06:28] DEBUG[14937]: res_odbc.c:714 ast_odbc_release_obj: Releasing ODBC handle 0x7f20d8002458 into pool <--- Received SIP request (416 bytes) from UDP:10.0.1.2:54090 ---> ACK sip:015175949493@10.0.1.12 SIP/2.0 Via: SIP/2.0/UDP 10.3.0.6:54090;rport;branch=z9hG4bKPjJEG1ypjurC6fXIWqgcaXzMlkQYad79MC Max-Forwards: 70 From: "Daniel Heckl" ;tag=KjAr421pwUCcTm6rKUl6.CJPMOfjDiF2 To: ;tag=cb145a98-445b-4004-b0fc-3a6e18eac3f9 Call-ID: HoHM5MHo1CYog.PdWo0nc27EoheFhslG CSeq: 15659 ACK Route: Content-Length: 0 [2016-11-03 10:06:28] DEBUG[14948]: res_pjsip/pjsip_distributor.c:390 distributor: Searching for serializer on dialog dlg0x7f210c034ad8 for Request msg ACK/cseq=15659 (rdata0x7f20dc02fab8) [2016-11-03 10:06:28] DEBUG[14948]: res_pjsip/pjsip_distributor.c:396 distributor: Found serializer pjsip/distributor-00000031 on dialog dlg0x7f210c034ad8 [2016-11-03 10:06:28] DEBUG[22545]: res_pjsip_session.c:2464 handle_incoming: Received request [2016-11-03 10:06:28] DEBUG[22545]: res_pjsip_session.c:2431 handle_incoming_request: Method is ACK [2016-11-03 10:06:29] DEBUG[22763]: res_pjsip_session.c:1323 session_destructor: Destroying SIP session with endpoint 2000 [2016-11-03 10:06:29] DEBUG[22763]: res_rtp_asterisk.c:4925 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7f2124022bc8' [2016-11-03 10:06:29] DEBUG[22763]: rtp_engine.c:384 instance_destructor: Destroyed RTP instance '0x7f2124022bc8' [2016-11-03 10:06:30] DEBUG[14998]: chan_sip.c:4351 __sip_autodestruct: Auto destroying SIP dialog '7c26848e0b73f2c12ef12ab538112957@tel.t-online.de' [2016-11-03 10:06:30] DEBUG[14998]: chan_sip.c:6579 sip_pvt_dtor: Destroying SIP dialog 7c26848e0b73f2c12ef12ab538112957@tel.t-online.de Really destroying SIP dialog '7c26848e0b73f2c12ef12ab538112957@tel.t-online.de' Method: INVITE [2016-11-03 10:06:30] DEBUG[14998]: rtp_engine.c:384 instance_destructor: Destroyed RTP instance '0x7f2114070e18' [2016-11-03 10:06:33] DEBUG[22545]: res_pjsip_session.c:1323 session_destructor: Destroying SIP session with endpoint 2000 [2016-11-03 10:06:33] DEBUG[22545]: res_rtp_asterisk.c:4925 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7f2124059d58' [2016-11-03 10:06:33] DEBUG[22545]: rtp_engine.c:384 instance_destructor: Destroyed RTP instance '0x7f2124059d58' [2016-11-03 10:06:33] DEBUG[15000]: res_pjsip_registrar_expire.c:85 check_expiration_thread: Expiring 0 contacts [2016-11-03 10:06:44] DEBUG[22763]: config.c:3742 ast_parse_arg: extract uint from [3] in [0, 4294967295] gives [3](0) [2016-11-03 10:06:44] DEBUG[22763]: config.c:3742 ast_parse_arg: extract uint from [0] in [0, 4294967295] gives [0](0) [2016-11-03 10:06:44] DEBUG[22763]: config.c:3742 ast_parse_arg: extract uint from [2] in [0, 4294967295] gives [2](0) [2016-11-03 10:06:44] DEBUG[22763]: res_pjsip.c:3511 endpt_send_request: 0x7f210c000e38: Wrapper created [2016-11-03 10:06:44] DEBUG[22763]: res_pjsip.c:3528 endpt_send_request: 0x7f210c000e38: Set timer to 3000 msec <--- Transmitting SIP request (410 bytes) to UDP:10.0.1.8:5060 ---> OPTIONS sip:2101@10.0.1.8:5060 SIP/2.0 Via: SIP/2.0/UDP 10.0.1.12:45060;rport;branch=z9hG4bKPj76ff3d7a-dc6e-431f-b826-c6169bf62999 From: ;tag=f8bbf293-3de9-4c8b-8b3e-ff048287b5a9 To: Contact: Call-ID: af7628b4-f9b5-48da-a292-476e5e5cb2f9 CSeq: 45684 OPTIONS Max-Forwards: 70 User-Agent: FPBX-13.0.190.1(13.12.1) Content-Length: 0 <--- Received SIP response (669 bytes) from UDP:10.0.1.8:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.0.1.12:45060;rport=45060;branch=z9hG4bKPj76ff3d7a-dc6e-431f-b826-c6169bf62999 From: ;tag=f8bbf293-3de9-4c8b-8b3e-ff048287b5a9 To: ;tag=g9ccg382-2ed8-5b9c-9c2d-gg159396c4a8 Call-ID: af7628b4-f9b5-48da-a292-476e5e5cb2f9 CSeq: 45684 OPTIONS Supported: replaces User-Agent: N510 IP PRO/42.238.00.000.000 Allow: INVITE, ACK, CANCEL, BYE, OPTIONS, INFO, SUBSCRIBE, NOTIFY, REFER, UPDATE Accept: application/sdp, application/dtmf-relay, message/sipfrag, application/simple-message-summary, application/url, multipart/mixed Accept-Encoding: identity Accept-Language: en Content-Length: 0 [2016-11-03 10:06:44] DEBUG[14948]: res_pjsip/pjsip_distributor.c:406 distributor: No dialog serializer for response Response msg 200/OPTIONS/cseq=45684 (rdata0x7f20dc02db68). Using request transaction as basis [2016-11-03 10:06:44] DEBUG[14948]: res_pjsip/pjsip_distributor.c:138 find_request_serializer: Found serializer pjsip/default-00000011 on transaction tsx0x7f210c017c68 [2016-11-03 10:06:44] DEBUG[22545]: res_pjsip.c:3400 endpt_send_request_cb: 0x7f210c000e38: PJSIP tsx response received [2016-11-03 10:06:44] DEBUG[22545]: res_pjsip.c:3413 endpt_send_request_cb: 0x7f210c000e38: Cancelling timer [2016-11-03 10:06:44] DEBUG[22545]: res_pjsip.c:3423 endpt_send_request_cb: 0x7f210c000e38: Timer cancelled [2016-11-03 10:06:44] DEBUG[22545]: config.c:3742 ast_parse_arg: extract uint from [3] in [0, 4294967295] gives [3](0) [2016-11-03 10:06:44] DEBUG[22545]: config.c:3742 ast_parse_arg: extract uint from [0] in [0, 4294967295] gives [0](0) [2016-11-03 10:06:44] DEBUG[22545]: config.c:3742 ast_parse_arg: extract uint from [2] in [0, 4294967295] gives [2](0) [2016-11-03 10:06:44] DEBUG[22545]: res_pjsip.c:3442 endpt_send_request_cb: 0x7f210c000e38: Callbacks executed [2016-11-03 10:06:44] DEBUG[22545]: res_pjsip.c:3493 send_request_wrapper_destructor: 0x7f210c000e38: wrapper destroyed [2016-11-03 10:06:44] DEBUG[23517]: res_pjsip/pjsip_configuration.c:283 persistent_endpoint_contact_status_observer: Contact 2101/sip:2101@10.0.1.8:5060 status didn't change: Reachable, RTT: 25.749 msec [2016-11-03 10:06:46] DEBUG[28815]: threadpool.c:1137 worker_idle: Worker thread idle timeout reached. Dying. [2016-11-03 10:06:46] DEBUG[14920]: threadpool.c:996 worker_thread_destroy: Destroying worker thread 997 [2016-11-03 10:06:47] DEBUG[22763]: config.c:3742 ast_parse_arg: extract uint from [3] in [0, 4294967295] gives [3](0) [2016-11-03 10:06:47] DEBUG[22763]: config.c:3742 ast_parse_arg: extract uint from [0] in [0, 4294967295] gives [0](0) [2016-11-03 10:06:47] DEBUG[22763]: config.c:3742 ast_parse_arg: extract uint from [2] in [0, 4294967295] gives [2](0) [2016-11-03 10:06:47] DEBUG[22763]: res_pjsip.c:3511 endpt_send_request: 0x7f210c022d18: Wrapper created [2016-11-03 10:06:47] DEBUG[22763]: res_pjsip.c:3528 endpt_send_request: 0x7f210c022d18: Set timer to 3000 msec <--- Transmitting SIP request (410 bytes) to UDP:10.0.1.8:5060 ---> OPTIONS sip:2103@10.0.1.8:5060 SIP/2.0 Via: SIP/2.0/UDP 10.0.1.12:45060;rport;branch=z9hG4bKPjbf965eaa-39cd-4c9d-a12e-d0ec9cd89a3c From: ;tag=ca9c08b8-8dbc-4d4f-8711-20f0d37b3e1e To: Contact: Call-ID: 96530609-c77a-4ae5-830d-cacf6dd58b43 CSeq: 48360 OPTIONS Max-Forwards: 70 User-Agent: FPBX-13.0.190.1(13.12.1) Content-Length: 0 <--- Received SIP response (669 bytes) from UDP:10.0.1.8:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.0.1.12:45060;rport=45060;branch=z9hG4bKPjbf965eaa-39cd-4c9d-a12e-d0ec9cd89a3c From: ;tag=ca9c08b8-8dbc-4d4f-8711-20f0d37b3e1e To: ;tag=ba8b19c9-9ecb-5e5g-9600-31g1e26c2d0d Call-ID: 96530609-c77a-4ae5-830d-cacf6dd58b43 CSeq: 48360 OPTIONS Supported: replaces User-Agent: N510 IP PRO/42.238.00.000.000 Allow: INVITE, ACK, CANCEL, BYE, OPTIONS, INFO, SUBSCRIBE, NOTIFY, REFER, UPDATE Accept: application/sdp, application/dtmf-relay, message/sipfrag, application/simple-message-summary, application/url, multipart/mixed Accept-Encoding: identity Accept-Language: en Content-Length: 0 [2016-11-03 10:06:47] DEBUG[14948]: res_pjsip/pjsip_distributor.c:406 distributor: No dialog serializer for response Response msg 200/OPTIONS/cseq=48360 (rdata0x7f20dc02db68). Using request transaction as basis [2016-11-03 10:06:47] DEBUG[14948]: res_pjsip/pjsip_distributor.c:138 find_request_serializer: Found serializer pjsip/default-00000012 on transaction tsx0x7f21249da048 [2016-11-03 10:06:47] DEBUG[22545]: res_pjsip.c:3400 endpt_send_request_cb: 0x7f210c022d18: PJSIP tsx response received [2016-11-03 10:06:47] DEBUG[22545]: res_pjsip.c:3413 endpt_send_request_cb: 0x7f210c022d18: Cancelling timer [2016-11-03 10:06:47] DEBUG[22545]: res_pjsip.c:3423 endpt_send_request_cb: 0x7f210c022d18: Timer cancelled [2016-11-03 10:06:47] DEBUG[22545]: config.c:3742 ast_parse_arg: extract uint from [3] in [0, 4294967295] gives [3](0) [2016-11-03 10:06:47] DEBUG[22545]: config.c:3742 ast_parse_arg: extract uint from [0] in [0, 4294967295] gives [0](0) [2016-11-03 10:06:47] DEBUG[22545]: config.c:3742 ast_parse_arg: extract uint from [2] in [0, 4294967295] gives [2](0) [2016-11-03 10:06:47] DEBUG[22545]: res_pjsip.c:3442 endpt_send_request_cb: 0x7f210c022d18: Callbacks executed [2016-11-03 10:06:47] DEBUG[22545]: res_pjsip.c:3493 send_request_wrapper_destructor: 0x7f210c022d18: wrapper destroyed [2016-11-03 10:06:47] DEBUG[23517]: res_pjsip/pjsip_configuration.c:283 persistent_endpoint_contact_status_observer: Contact 2103/sip:2103@10.0.1.8:5060 status didn't change: Reachable, RTT: 24.612 msec [2016-11-03 10:06:48] DEBUG[28813]: threadpool.c:1137 worker_idle: Worker thread idle timeout reached. Dying. [2016-11-03 10:06:48] DEBUG[14920]: threadpool.c:996 worker_thread_destroy: Destroying worker thread 996 [2016-11-03 10:06:50] DEBUG[22763]: config.c:3742 ast_parse_arg: extract uint from [3] in [0, 4294967295] gives [3](0) [2016-11-03 10:06:50] DEBUG[22763]: config.c:3742 ast_parse_arg: extract uint from [0] in [0, 4294967295] gives [0](0) [2016-11-03 10:06:50] DEBUG[22763]: config.c:3742 ast_parse_arg: extract uint from [2] in [0, 4294967295] gives [2](0) [2016-11-03 10:06:50] DEBUG[22763]: res_pjsip.c:3511 endpt_send_request: 0x7f210c014a28: Wrapper created [2016-11-03 10:06:50] DEBUG[22763]: res_pjsip.c:3528 endpt_send_request: 0x7f210c014a28: Set timer to 3000 msec <--- Transmitting SIP request (410 bytes) to UDP:10.0.1.9:5060 ---> OPTIONS sip:2005@10.0.1.9:5060 SIP/2.0 Via: SIP/2.0/UDP 10.0.1.12:45060;rport;branch=z9hG4bKPjd92cd398-db18-4a73-8a15-1a99a2be23b3 From: ;tag=c16105c8-c9b3-4132-9019-126529383839 To: Contact: Call-ID: 1d013fe8-fc84-4171-97e1-ad2ea825a1f2 CSeq: 57331 OPTIONS Max-Forwards: 70 User-Agent: FPBX-13.0.190.1(13.12.1) Content-Length: 0 <--- Received SIP response (426 bytes) from UDP:10.0.1.9:5060 ---> SIP/2.0 200 OK To: ;tag=a0116fdea0586172i0 From: ;tag=c16105c8-c9b3-4132-9019-126529383839 Call-ID: 1d013fe8-fc84-4171-97e1-ad2ea825a1f2 CSeq: 57331 OPTIONS Via: SIP/2.0/UDP 10.0.1.12:45060;branch=z9hG4bKPjd92cd398-db18-4a73-8a15-1a99a2be23b3 Server: Cisco/SPA122-1.4.1(002) Content-Length: 0 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER Supported: replaces [2016-11-03 10:06:50] DEBUG[14948]: res_pjsip/pjsip_distributor.c:406 distributor: No dialog serializer for response Response msg 200/OPTIONS/cseq=57331 (rdata0x7f20dc02db68). Using request transaction as basis [2016-11-03 10:06:50] DEBUG[14948]: res_pjsip/pjsip_distributor.c:138 find_request_serializer: Found serializer pjsip/default-00000013 on transaction tsx0x7f210c017c68 [2016-11-03 10:06:50] DEBUG[22545]: res_pjsip.c:3400 endpt_send_request_cb: 0x7f210c014a28: PJSIP tsx response received [2016-11-03 10:06:50] DEBUG[22545]: res_pjsip.c:3413 endpt_send_request_cb: 0x7f210c014a28: Cancelling timer [2016-11-03 10:06:50] DEBUG[22545]: res_pjsip.c:3423 endpt_send_request_cb: 0x7f210c014a28: Timer cancelled [2016-11-03 10:06:50] DEBUG[22545]: config.c:3742 ast_parse_arg: extract uint from [3] in [0, 4294967295] gives [3](0) [2016-11-03 10:06:50] DEBUG[22545]: config.c:3742 ast_parse_arg: extract uint from [0] in [0, 4294967295] gives [0](0) [2016-11-03 10:06:50] DEBUG[22545]: config.c:3742 ast_parse_arg: extract uint from [2] in [0, 4294967295] gives [2](0) [2016-11-03 10:06:50] DEBUG[22545]: res_pjsip.c:3442 endpt_send_request_cb: 0x7f210c014a28: Callbacks executed [2016-11-03 10:06:50] DEBUG[22545]: res_pjsip.c:3493 send_request_wrapper_destructor: 0x7f210c014a28: wrapper destroyed [2016-11-03 10:06:50] DEBUG[23517]: res_pjsip/pjsip_configuration.c:283 persistent_endpoint_contact_status_observer: Contact 2005/sip:2005@10.0.1.9:5060 status didn't change: Reachable, RTT: 35.051 msec <--- SIP read from UDP:217.0.20.234:5060 ---> SIP/2.0 181 Call Is Being Forwarded Via: SIP/2.0/UDP 91.33.188.109:45061;received=91.33.188.109;rport=45061;branch=z9hG4bK53009a9a To: ;tag=h7g4Esbg_p65551t1478163986m592189c893905464s1_3747035002-709087048 From: "+496123456789" ;tag=as22681a60 Call-ID: 43fc1d2572c7738c02a4c773605154fe@tel.t-online.de CSeq: 103 INVITE Contact: Record-Route: Supported: timer Content-Length: 0 Allow: UPDATE, REFER, PRACK, OPTIONS, BYE, ACK, CANCEL, INVITE, REGISTER <-------------> --- (11 headers 0 lines) --- [2016-11-03 10:06:52] DEBUG[14998][C-00000056]: chan_sip.c:4568 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '43fc1d2572c7738c02a4c773605154fe@tel.t-online.de' Request 103: Found [2016-11-03 10:06:52] DEBUG[14998][C-00000056]: sip/route.c:105 sip_route_process_header: sip_route_process_header: sip_route_dump: route/path hop: <--- SIP read from UDP:217.0.20.234:5060 ---> SIP/2.0 183 Session Progress Via: SIP/2.0/UDP 91.33.188.109:45061;received=91.33.188.109;rport=45061;branch=z9hG4bK53009a9a To: ;tag=h7g4Esbg_p65551t1478163986m592189c893905464s1_3747035002-709087048 From: "+496123456789" ;tag=as22681a60 Call-ID: 43fc1d2572c7738c02a4c773605154fe@tel.t-online.de CSeq: 103 INVITE Contact: Record-Route: Supported: timer Content-Type: application/sdp Content-Length: 199 Allow: UPDATE, REFER, PRACK, OPTIONS, BYE, ACK, CANCEL, INVITE, REGISTER v=0 o=- 1173402614 3773835001 IN IP4 217.0.20.234 s=- c=IN IP4 217.0.6.199 t=0 0 m=audio 54182 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=maxptime:20 a=ptime:20 <-------------> --- (12 headers 10 lines) --- [2016-11-03 10:06:53] DEBUG[14998][C-00000056]: chan_sip.c:4568 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '43fc1d2572c7738c02a4c773605154fe@tel.t-online.de' Request 103: Found [2016-11-03 10:06:53] DEBUG[14998][C-00000056]: sip/route.c:105 sip_route_process_header: sip_route_process_header: sip_route_dump: route/path hop: [2016-11-03 10:06:53] DEBUG[14998][C-00000056]: chan_sip.c:10250 process_sdp: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [2016-11-03 10:06:53] DEBUG[14998][C-00000056]: chan_sip.c:10250 process_sdp: Processing session-level SDP o=- 1173402614 3773835001 IN IP4 217.0.20.234... OK. [2016-11-03 10:06:53] DEBUG[14998][C-00000056]: chan_sip.c:10250 process_sdp: Processing session-level SDP s=-... UNSUPPORTED OR FAILED. [2016-11-03 10:06:53] DEBUG[14998][C-00000056]: chan_sip.c:10250 process_sdp: Processing session-level SDP c=IN IP4 217.0.6.199... OK. [2016-11-03 10:06:53] DEBUG[14998][C-00000056]: chan_sip.c:10250 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. Found RTP audio format 8 [2016-11-03 10:06:53] DEBUG[14998][C-00000056]: rtp_engine.c:676 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 8 based on m type on 0x7f207bcfa240 Found RTP audio format 101 [2016-11-03 10:06:53] DEBUG[14998][C-00000056]: rtp_engine.c:676 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 101 based on m type on 0x7f207bcfa240 Found audio description format PCMA for ID 8 [2016-11-03 10:06:53] DEBUG[14998][C-00000056]: chan_sip.c:10705 process_sdp: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK. Found audio description format telephone-event for ID 101 [2016-11-03 10:06:53] DEBUG[14998][C-00000056]: chan_sip.c:10705 process_sdp: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [2016-11-03 10:06:53] DEBUG[14998][C-00000056]: chan_sip.c:10705 process_sdp: Processing media-level (audio) SDP a=maxptime:20... UNSUPPORTED OR FAILED. [2016-11-03 10:06:53] DEBUG[14998][C-00000056]: chan_sip.c:10705 process_sdp: Processing media-level (audio) SDP a=ptime:20... OK. Capabilities: us - (g722|alaw|ulaw|gsm), peer - audio=(alaw)/video=(nothing)/text=(nothing), combined - (alaw) Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|) [2016-11-03 10:06:53] DEBUG[14998][C-00000056]: res_rtp_asterisk.c:847 ast_rtp_ice_set_role: Set role to CONTROLLING (0x7f2110005118) [2016-11-03 10:06:53] DEBUG[14998][C-00000056]: res_rtp_asterisk.c:850 ast_rtp_ice_set_role: Set role failed; no ice instance (0x7f2110005118) [2016-11-03 10:06:53] DEBUG[14998][C-00000056]: res_rtp_asterisk.c:4925 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7f2110005118' Peer audio RTP is at port 217.0.6.199:54182 [2016-11-03 10:06:53] DEBUG[14998][C-00000056]: rtp_engine.c:645 ast_rtp_codecs_payloads_copy: Copying payload 8 (0x2272d70) from 0x7f207bcfa240 to 0x7f21100052e0 [2016-11-03 10:06:53] DEBUG[14998][C-00000056]: rtp_engine.c:645 ast_rtp_codecs_payloads_copy: Copying payload 101 (0x239f250) from 0x7f207bcfa240 to 0x7f21100052e0 [2016-11-03 10:06:53] DEBUG[14998][C-00000056]: res_rtp_asterisk.c:4819 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0x7f2110005118' [2016-11-03 10:06:53] DEBUG[14998][C-00000056]: chan_sip.c:11003 process_sdp: We're settling with these formats: (alaw) Reliably Transmitting (NAT) to 217.0.20.234:5060: CANCEL sip:015175949493@tel.t-online.de SIP/2.0 Via: SIP/2.0/UDP 91.33.188.109:45061;branch=z9hG4bK53009a9a;rport Max-Forwards: 70 From: "+496123456789" ;tag=as22681a60 To: Call-ID: 43fc1d2572c7738c02a4c773605154fe@tel.t-online.de CSeq: 103 CANCEL User-Agent: FPBX-13.0.190.1(13.12.1) Content-Length: 0 --- [2016-11-03 10:06:53] DEBUG[14998]: chan_sip.c:3746 __sip_xmit: Trying to put 'CANCEL sip:' onto UDP socket destined for 217.0.20.234:5060 Scheduling destruction of SIP dialog '43fc1d2572c7738c02a4c773605154fe@tel.t-online.de' in 6400 ms (Method: INVITE) <--- SIP read from UDP:217.0.20.234:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 91.33.188.109:45061;received=91.33.188.109;rport=45061;branch=z9hG4bK53009a9a To: ;tag=h7g4Esbg_p65551t1478163986m592189c893905464s1_3747035002-709087048 From: "+496123456789" ;tag=as22681a60 Call-ID: 43fc1d2572c7738c02a4c773605154fe@tel.t-online.de CSeq: 103 CANCEL Content-Length: 0 <-------------> --- (7 headers 0 lines) --- [2016-11-03 10:06:53] DEBUG[14998][C-00000056]: chan_sip.c:4511 __sip_ack: Acked pending invite 103 [2016-11-03 10:06:53] DEBUG[14998][C-00000056]: chan_sip.c:4527 __sip_ack: Stopping retransmission on '43fc1d2572c7738c02a4c773605154fe@tel.t-online.de' of Request 103: Match Found <--- SIP read from UDP:217.0.20.234:5060 ---> SIP/2.0 183 Session Progress Via: SIP/2.0/UDP 91.33.188.109:45061;received=91.33.188.109;rport=45061;branch=z9hG4bK53009a9a To: ;tag=h7g4Esbg_p65551t1478163986m592189c893905464s1_3773902931-1 From: "+496123456789" ;tag=as22681a60 Call-ID: 43fc1d2572c7738c02a4c773605154fe@tel.t-online.de CSeq: 103 INVITE Contact: Record-Route: Supported: timer Content-Type: application/sdp Content-Length: 238 Allow: UPDATE, REFER, PRACK, OPTIONS, BYE, ACK, CANCEL, INVITE, REGISTER v=0 o=- 1353377535 3773902914 IN IP4 217.0.20.234 s=media server session t=0 0 m=audio 54182 RTP/AVP 8 101 c=IN IP4 217.0.6.199 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15,32,36 a=sendrecv a=ptime:20 <-------------> --- (12 headers 11 lines) --- [2016-11-03 10:06:53] DEBUG[14998][C-00000056]: chan_sip.c:4568 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '43fc1d2572c7738c02a4c773605154fe@tel.t-online.de' Request 103: Found [2016-11-03 10:06:53] DEBUG[14998][C-00000056]: sip/route.c:105 sip_route_process_header: sip_route_process_header: sip_route_dump: route/path hop: [2016-11-03 10:06:53] DEBUG[14998][C-00000056]: chan_sip.c:10250 process_sdp: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [2016-11-03 10:06:53] DEBUG[14998][C-00000056]: chan_sip.c:10250 process_sdp: Processing session-level SDP o=- 1353377535 3773902914 IN IP4 217.0.20.234... OK. [2016-11-03 10:06:53] DEBUG[14998][C-00000056]: chan_sip.c:10250 process_sdp: Processing session-level SDP s=media server session... UNSUPPORTED OR FAILED. [2016-11-03 10:06:53] DEBUG[14998][C-00000056]: chan_sip.c:10250 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. Found RTP audio format 8 [2016-11-03 10:06:53] DEBUG[14998][C-00000056]: rtp_engine.c:676 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 8 based on m type on 0x7f207bcfa240 Found RTP audio format 101 [2016-11-03 10:06:53] DEBUG[14998][C-00000056]: rtp_engine.c:676 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 101 based on m type on 0x7f207bcfa240 [2016-11-03 10:06:53] DEBUG[14998][C-00000056]: chan_sip.c:10705 process_sdp: Processing media-level (audio) SDP c=IN IP4 217.0.6.199... OK. Found audio description format PCMA for ID 8 [2016-11-03 10:06:53] DEBUG[14998][C-00000056]: chan_sip.c:10705 process_sdp: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK. Found audio description format telephone-event for ID 101 [2016-11-03 10:06:53] DEBUG[14998][C-00000056]: chan_sip.c:10705 process_sdp: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [2016-11-03 10:06:53] DEBUG[14998][C-00000056]: chan_sip.c:10705 process_sdp: Processing media-level (audio) SDP a=fmtp:101 0-15,32,36... UNSUPPORTED OR FAILED. [2016-11-03 10:06:53] DEBUG[14998][C-00000056]: chan_sip.c:10705 process_sdp: Processing media-level (audio) SDP a=sendrecv... OK. [2016-11-03 10:06:53] DEBUG[14998][C-00000056]: chan_sip.c:10705 process_sdp: Processing media-level (audio) SDP a=ptime:20... OK. Capabilities: us - (g722|alaw|ulaw|gsm), peer - audio=(alaw)/video=(nothing)/text=(nothing), combined - (alaw) Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|) [2016-11-03 10:06:53] DEBUG[14998][C-00000056]: res_rtp_asterisk.c:847 ast_rtp_ice_set_role: Set role to CONTROLLING (0x7f2110005118) [2016-11-03 10:06:53] DEBUG[14998][C-00000056]: res_rtp_asterisk.c:850 ast_rtp_ice_set_role: Set role failed; no ice instance (0x7f2110005118) [2016-11-03 10:06:53] DEBUG[14998][C-00000056]: res_rtp_asterisk.c:4925 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7f2110005118' Peer audio RTP is at port 217.0.6.199:54182 [2016-11-03 10:06:53] DEBUG[14998][C-00000056]: rtp_engine.c:645 ast_rtp_codecs_payloads_copy: Copying payload 8 (0x14b42d0) from 0x7f207bcfa240 to 0x7f21100052e0 [2016-11-03 10:06:53] DEBUG[14998][C-00000056]: rtp_engine.c:645 ast_rtp_codecs_payloads_copy: Copying payload 101 (0x101a290) from 0x7f207bcfa240 to 0x7f21100052e0 [2016-11-03 10:06:53] DEBUG[14998][C-00000056]: res_rtp_asterisk.c:4819 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0x7f2110005118' [2016-11-03 10:06:53] DEBUG[14998][C-00000056]: chan_sip.c:11003 process_sdp: We're settling with these formats: (alaw) <--- SIP read from UDP:217.0.20.234:5060 ---> SIP/2.0 487 Request Terminated Via: SIP/2.0/UDP 91.33.188.109:45061;received=91.33.188.109;rport=45061;branch=z9hG4bK53009a9a To: ;tag=h7g4Esbg_p65551t1478163986m592189c893905464s1_3747035002-709087048 From: "+496123456789" ;tag=as22681a60 Call-ID: 43fc1d2572c7738c02a4c773605154fe@tel.t-online.de CSeq: 103 INVITE Contact: Supported: timer Content-Length: 0 <-------------> --- (9 headers 0 lines) --- [2016-11-03 10:06:53] DEBUG[14998][C-00000056]: chan_sip.c:4527 __sip_ack: Stopping retransmission on '43fc1d2572c7738c02a4c773605154fe@tel.t-online.de' of Request 103: Match Found Transmitting (NAT) to 217.0.20.234:5060: ACK sip:sgc_c@217.0.20.234;transport=udp SIP/2.0 Via: SIP/2.0/UDP 91.33.188.109:45061;branch=z9hG4bK53009a9a;rport Max-Forwards: 70 From: "+496123456789" ;tag=as22681a60 To: ;tag=h7g4Esbg_p65551t1478163986m592189c893905464s1_3747035002-709087048 Contact: Call-ID: 43fc1d2572c7738c02a4c773605154fe@tel.t-online.de CSeq: 103 ACK User-Agent: FPBX-13.0.190.1(13.12.1) Content-Length: 0 --- [2016-11-03 10:06:53] DEBUG[14998][C-00000056]: chan_sip.c:3746 __sip_xmit: Trying to put 'ACK sip:sgc' onto UDP socket destined for 217.0.20.234:5060 [2016-11-03 10:06:53] DEBUG[14998][C-00000056]: chan_sip.c:6757 update_call_counter: Updating call counter for outgoing call Scheduling destruction of SIP dialog '43fc1d2572c7738c02a4c773605154fe@tel.t-online.de' in 6400 ms (Method: INVITE) [2016-11-03 10:06:58] NOTICE[14998]: chan_sip.c:15603 sip_reregister: -- Re-registration for 061129634569@tel.t-online.de [2016-11-03 10:06:58] DEBUG[14998]: chan_sip.c:8985 __sip_alloc: Allocating new SIP dialog for 346ae5cc01c1c9d66c2e96622eec177b@10.0.1.12 - REGISTER (No RTP) [2016-11-03 10:06:58] DEBUG[14998]: chan_sip.c:3513 obproxy_get: OBPROXY: Not applying OBproxy to this call [2016-11-03 10:06:58] DEBUG[14998]: acl.c:946 ast_ouraddrfor: For destination '217.0.20.234', our source address is '10.0.1.12'. [2016-11-03 10:06:58] DEBUG[14998]: chan_sip.c:3870 ast_sip_ouraddrfor: Target address 217.0.20.234:5060 is not local, substituting externaddr