[Jan 4 10:49:02] Asterisk 11.2-cert2 built by root @ vvovm2024pdv on a x86_64 running Linux on 2015-09-08 21:17:29 UTC [Jan 4 10:49:02] DEBUG[29614] config.c: Parsing /etc/asterisk/logger.conf [Jan 4 10:49:02] VERBOSE[29614] config.c: == Parsing '/etc/asterisk/logger.conf': Found [Jan 4 10:49:02] VERBOSE[29614] logger.c: Asterisk Queue Logger restarted [Jan 4 10:49:04] DEBUG[29606] chan_sip.c: SIP TIMER: Rescheduling retransmission #9 (6) NOTIFY - 4 [Jan 4 10:49:04] DEBUG[29606] chan_sip.c: ** SIP timers: Rescheduling retransmission 7 to 4000 ms (t1 500 ms (Retrans id #9)) [Jan 4 10:49:04] VERBOSE[29606] chan_sip.c: Retransmitting #6 (no NAT) to 10.116.140.43:5060: NOTIFY sip:6022823054@10.116.140.43:5060 SIP/2.0 Via: SIP/2.0/UDP 10.93.118.24:5060;branch=z9hG4bK46bc78eb Max-Forwards: 70 From: ;tag=as563dac7b To: Contact: Call-ID: 7bcd94b92957a6007e6480d26697819e@10.93.118.24:5060 CSeq: 102 NOTIFY User-Agent: Asterisk PBX 11.2-cert2 Event: message-summary Content-Type: application/simple-message-summary Content-Length: 94 Messages-Waiting: no Message-Account: sip:6022823054@10.93.118.24 Voice-Message: 0/0 (0/0) --- [Jan 4 10:49:04] DEBUG[29606] chan_sip.c: Trying to put 'NOTIFY sip:' onto UDP socket destined for 10.116.140.43:5060 [Jan 4 10:49:04] DEBUG[29606] chan_sip.c: SIP TIMER: Rescheduling retransmission #11 (6) NOTIFY - 4 [Jan 4 10:49:04] DEBUG[29606] chan_sip.c: ** SIP timers: Rescheduling retransmission 7 to 4000 ms (t1 500 ms (Retrans id #11)) [Jan 4 10:49:04] VERBOSE[29606] chan_sip.c: Retransmitting #6 (no NAT) to 10.116.140.43:5060: NOTIFY sip:6022823054@10.116.140.43:5060 SIP/2.0 Via: SIP/2.0/UDP 10.93.118.24:5060;branch=z9hG4bK08e31dac Max-Forwards: 70 From: ;tag=as7f05c00f To: Contact: Call-ID: 55dcbe523cdb484862b3176c6707d913@10.93.118.24:5060 CSeq: 102 NOTIFY User-Agent: Asterisk PBX 11.2-cert2 Event: message-summary Content-Type: application/simple-message-summary Content-Length: 96 Messages-Waiting: yes Message-Account: sip:6022823054@10.93.118.24 Voice-Message: 25/2 (0/0) --- [Jan 4 10:49:04] DEBUG[29606] chan_sip.c: Trying to put 'NOTIFY sip:' onto UDP socket destined for 10.116.140.43:5060 [Jan 4 10:49:05] VERBOSE[29606] chan_sip.c: <--- SIP read from UDP:10.93.118.12:5060 ---> INVITE sip:6022823054@10.93.118.24:5060 SIP/2.0 From: "CHARLES SCHWAB" ;tag=0084891A-A574-1654-B05A-0C765D0AAA77-2940418 To: Call-ID: 008488FC-A574-1654-B05A-0C765D0AAA77-2904520@10.93.118.12 CSeq: 1 INVITE Content-Length: 177 Content-Type: application/sdp Via: SIP/2.0/UDP 10.93.118.12:5060;branch=z9hG4bK00848924-A574-1654-B05A-0C765D0AAA77-2475 Contact: X-Genesys-CallInfo: routed X-Genesys-Profile: Branch_OH_Cleveland_Test X-Genesys-OrigDestDN: 6022826397 X-Genesys-OrigANI: 7204183373 geo-location: CLE Diversion: ;reason=unknown;privacy="off" Allow: ACK, BYE, CANCEL, INFO, INVITE, MESSAGE, NOTIFY, OPTIONS, PRACK, REFER, UPDATE Max-Forwards: 69 X-Genesys-geo-location: CLE X-Genesys-CallUUID: 0270JJ55EGB59C2Q1HR5Q2LAES0000CS X-ISCC-CofId: location=Branch_CLE;cofid=16778825 Session-Expires: 1800;refresher=uac Min-SE: 90 Supported: uui,timer v=0 o=Sonus_UAC 1448398848 1 IN IP4 10.93.107.65 s=SIP Media Capabilities c=IN IP4 10.93.107.65 t=0 0 m=audio 4988 RTP/AVP 0 a=sendrecv a=ptime:20 a=rtpmap:0 PCMU/8000 <-------------> [Jan 4 10:49:05] DEBUG[29606] chan_sip.c: Header 0 [ 47]: INVITE sip:6022823054@10.93.118.24:5060 SIP/2.0 [Jan 4 10:49:05] DEBUG[29606] chan_sip.c: Header 1 [101]: From: "CHARLES SCHWAB" ;tag=0084891A-A574-1654-B05A-0C765D0AAA77-2940418 [Jan 4 10:49:05] DEBUG[29606] chan_sip.c: Header 2 [ 38]: To: [Jan 4 10:49:05] DEBUG[29606] chan_sip.c: Header 3 [ 66]: Call-ID: 008488FC-A574-1654-B05A-0C765D0AAA77-2904520@10.93.118.12 [Jan 4 10:49:05] DEBUG[29606] chan_sip.c: Header 4 [ 14]: CSeq: 1 INVITE [Jan 4 10:49:05] DEBUG[29606] chan_sip.c: Header 5 [ 19]: Content-Length: 177 [Jan 4 10:49:05] DEBUG[29606] chan_sip.c: Header 6 [ 29]: Content-Type: application/sdp [Jan 4 10:49:05] DEBUG[29606] chan_sip.c: Header 7 [ 90]: Via: SIP/2.0/UDP 10.93.118.12:5060;branch=z9hG4bK00848924-A574-1654-B05A-0C765D0AAA77-2475 [Jan 4 10:49:05] DEBUG[29606] chan_sip.c: Header 8 [ 43]: Contact: [Jan 4 10:49:05] DEBUG[29606] chan_sip.c: Header 9 [ 26]: X-Genesys-CallInfo: routed [Jan 4 10:49:05] DEBUG[29606] chan_sip.c: Header 10 [ 43]: X-Genesys-Profile: Branch_OH_Cleveland_Test [Jan 4 10:49:05] DEBUG[29606] chan_sip.c: Header 11 [ 32]: X-Genesys-OrigDestDN: 6022826397 [Jan 4 10:49:05] DEBUG[29606] chan_sip.c: Header 12 [ 29]: X-Genesys-OrigANI: 7204183373 [Jan 4 10:49:05] DEBUG[29606] chan_sip.c: Header 13 [ 17]: geo-location: CLE [Jan 4 10:49:05] DEBUG[29606] chan_sip.c: Header 14 [ 69]: Diversion: ;reason=unknown;privacy="off" [Jan 4 10:49:05] DEBUG[29606] chan_sip.c: Header 15 [ 85]: Allow: ACK, BYE, CANCEL, INFO, INVITE, MESSAGE, NOTIFY, OPTIONS, PRACK, REFER, UPDATE [Jan 4 10:49:05] DEBUG[29606] chan_sip.c: Header 16 [ 16]: Max-Forwards: 69 [Jan 4 10:49:05] DEBUG[29606] chan_sip.c: Header 17 [ 27]: X-Genesys-geo-location: CLE [Jan 4 10:49:05] DEBUG[29606] chan_sip.c: Header 18 [ 52]: X-Genesys-CallUUID: 0270JJ55EGB59C2Q1HR5Q2LAES0000CS [Jan 4 10:49:05] DEBUG[29606] chan_sip.c: Header 19 [ 48]: X-ISCC-CofId: location=Branch_CLE;cofid=16778825 [Jan 4 10:49:05] DEBUG[29606] chan_sip.c: Header 20 [ 35]: Session-Expires: 1800;refresher=uac [Jan 4 10:49:05] DEBUG[29606] chan_sip.c: Header 21 [ 10]: Min-SE: 90 [Jan 4 10:49:05] DEBUG[29606] chan_sip.c: Header 22 [ 20]: Supported: uui,timer [Jan 4 10:49:05] DEBUG[29606] chan_sip.c: Header 23 [ 0]: [Jan 4 10:49:05] DEBUG[29606] chan_sip.c: Body 0 [ 3]: v=0 [Jan 4 10:49:05] DEBUG[29606] chan_sip.c: Body 1 [ 44]: o=Sonus_UAC 1448398848 1 IN IP4 10.93.107.65 [Jan 4 10:49:05] DEBUG[29606] chan_sip.c: Body 2 [ 24]: s=SIP Media Capabilities [Jan 4 10:49:05] DEBUG[29606] chan_sip.c: Body 3 [ 21]: c=IN IP4 10.93.107.65 [Jan 4 10:49:05] DEBUG[29606] chan_sip.c: Body 4 [ 5]: t=0 0 [Jan 4 10:49:05] DEBUG[29606] chan_sip.c: Body 5 [ 22]: m=audio 4988 RTP/AVP 0 [Jan 4 10:49:05] DEBUG[29606] chan_sip.c: Body 6 [ 10]: a=sendrecv [Jan 4 10:49:05] DEBUG[29606] chan_sip.c: Body 7 [ 10]: a=ptime:20 [Jan 4 10:49:05] DEBUG[29606] chan_sip.c: Body 8 [ 20]: a=rtpmap:0 PCMU/8000 [Jan 4 10:49:05] VERBOSE[29606] chan_sip.c: --- (23 headers 9 lines) --- [Jan 4 10:49:05] DEBUG[29606] chan_sip.c: = Looking for Call ID: 008488FC-A574-1654-B05A-0C765D0AAA77-2904520@10.93.118.12 (Checking From) --From tag 0084891A-A574-1654-B05A-0C765D0AAA77-2940418 --To-tag [Jan 4 10:49:05] DEBUG[29606] logger.c: CALL_ID [C-00000001] created by thread. [Jan 4 10:49:05] DEBUG[29606] acl.c: For destination '10.93.118.12', our source address is '10.93.118.24'. [Jan 4 10:49:05] DEBUG[29606] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.93.118.24:5060 [Jan 4 10:49:05] DEBUG[29606] chan_sip.c: Allocating new SIP dialog for 008488FC-A574-1654-B05A-0C765D0AAA77-2904520@10.93.118.12 - INVITE (No RTP) [Jan 4 10:49:05] DEBUG[29606][C-00000001] logger.c: CALL_ID [C-00000001] bound to thread. [Jan 4 10:49:05] DEBUG[29606][C-00000001] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Jan 4 10:49:05] DEBUG[29606][C-00000001] sip/reqresp_parser.c: Begin: parsing SIP "Supported: uui,timer" [Jan 4 10:49:05] DEBUG[29606][C-00000001] sip/reqresp_parser.c: Found SIP option: -uui- [Jan 4 10:49:05] DEBUG[29606][C-00000001] sip/reqresp_parser.c: Found no match for SIP option: uui (Please file bug report!) [Jan 4 10:49:05] DEBUG[29606][C-00000001] sip/reqresp_parser.c: Found SIP option: -timer- [Jan 4 10:49:05] DEBUG[29606][C-00000001] sip/reqresp_parser.c: Matched SIP option: timer [Jan 4 10:49:05] DEBUG[29606][C-00000001] netsock2.c: Splitting '10.93.118.12:5060' into... [Jan 4 10:49:05] DEBUG[29606][C-00000001] netsock2.c: ...host '10.93.118.12' and port '5060'. [Jan 4 10:49:05] VERBOSE[29606][C-00000001] chan_sip.c: Sending to 10.93.118.12:5060 (no NAT) [Jan 4 10:49:05] DEBUG[29606][C-00000001] chan_sip.c: Initializing initreq for method INVITE - callid 008488FC-A574-1654-B05A-0C765D0AAA77-2904520@10.93.118.12 [Jan 4 10:49:05] VERBOSE[29606][C-00000001] chan_sip.c: Using INVITE request as basis request - 008488FC-A574-1654-B05A-0C765D0AAA77-2904520@10.93.118.12 [Jan 4 10:49:05] DEBUG[29606][C-00000001] netsock2.c: Splitting '10.93.107.67' into... [Jan 4 10:49:05] DEBUG[29606][C-00000001] netsock2.c: ...host '10.93.107.67' and port ''. [Jan 4 10:49:05] DEBUG[29606][C-00000001] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM DYN_SIP_PEERS WHERE name = ? AND host = ? [Jan 4 10:49:05] DEBUG[29606][C-00000001] res_config_odbc.c: Parameter 1 ('name') = '7204183373' [Jan 4 10:49:05] DEBUG[29606][C-00000001] res_config_odbc.c: Parameter 2 ('host') = 'dynamic' [Jan 4 10:49:05] DEBUG[29606][C-00000001] res_odbc.c: odbc_release_obj2(0x85d8728) called (obj->txf = (nil)) [Jan 4 10:49:05] DEBUG[29606][C-00000001] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM DYN_SIP_PEERS WHERE name = ? [Jan 4 10:49:05] DEBUG[29606][C-00000001] res_config_odbc.c: Parameter 1 ('name') = '7204183373' [Jan 4 10:49:05] DEBUG[29606][C-00000001] res_odbc.c: odbc_release_obj2(0x85d8728) called (obj->txf = (nil)) [Jan 4 10:49:05] DEBUG[29606][C-00000001] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM DYN_SIP_PEERS WHERE host = ? AND port = ? AND callbackextension = ? [Jan 4 10:49:05] DEBUG[29606][C-00000001] res_config_odbc.c: Parameter 1 ('host') = '10.93.118.12' [Jan 4 10:49:05] DEBUG[29606][C-00000001] res_config_odbc.c: Parameter 2 ('port') = '5060' [Jan 4 10:49:05] DEBUG[29606][C-00000001] res_config_odbc.c: Parameter 3 ('callbackextension') = '6022823054' [Jan 4 10:49:05] DEBUG[29606][C-00000001] res_odbc.c: odbc_release_obj2(0x85d8728) called (obj->txf = (nil)) [Jan 4 10:49:05] DEBUG[29606][C-00000001] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM DYN_SIP_PEERS WHERE host = ? AND port = ? [Jan 4 10:49:05] DEBUG[29606][C-00000001] res_config_odbc.c: Parameter 1 ('host') = '10.93.118.12' [Jan 4 10:49:05] DEBUG[29606][C-00000001] res_config_odbc.c: Parameter 2 ('port') = '5060' [Jan 4 10:49:05] DEBUG[29606][C-00000001] res_odbc.c: odbc_release_obj2(0x85d8728) called (obj->txf = (nil)) [Jan 4 10:49:05] DEBUG[29606][C-00000001] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM DYN_SIP_PEERS WHERE ipaddr = ? AND port = ? [Jan 4 10:49:05] DEBUG[29606][C-00000001] res_config_odbc.c: Parameter 1 ('ipaddr') = '10.93.118.12' [Jan 4 10:49:05] DEBUG[29606][C-00000001] res_config_odbc.c: Parameter 2 ('port') = '5060' [Jan 4 10:49:05] DEBUG[29606][C-00000001] res_odbc.c: odbc_release_obj2(0x85d8728) called (obj->txf = (nil)) [Jan 4 10:49:05] DEBUG[29606][C-00000001] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM DYN_SIP_PEERS WHERE host = ? AND insecure LIKE ? ORDER BY host [Jan 4 10:49:05] DEBUG[29606][C-00000001] res_config_odbc.c: Parameter 1 ('host') = '10.93.118.12' [Jan 4 10:49:05] DEBUG[29606][C-00000001] res_config_odbc.c: Parameter 2 ('insecure LIKE') = '%port%' [Jan 4 10:49:05] DEBUG[29606][C-00000001] res_odbc.c: odbc_release_obj2(0x85d8728) called (obj->txf = (nil)) [Jan 4 10:49:05] DEBUG[29606][C-00000001] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM DYN_SIP_PEERS WHERE ipaddr = ? AND insecure LIKE ? ORDER BY ipaddr [Jan 4 10:49:05] DEBUG[29606][C-00000001] res_config_odbc.c: Parameter 1 ('ipaddr') = '10.93.118.12' [Jan 4 10:49:05] DEBUG[29606][C-00000001] res_config_odbc.c: Parameter 2 ('insecure LIKE') = '%port%' [Jan 4 10:49:05] DEBUG[29606][C-00000001] res_odbc.c: odbc_release_obj2(0x85d8728) called (obj->txf = (nil)) [Jan 4 10:49:05] VERBOSE[29606][C-00000001] chan_sip.c: Found peer 'Asterisk_CLE' for '7204183373' from 10.93.118.12:5060 [Jan 4 10:49:05] DEBUG[29606][C-00000001] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x888f268' [Jan 4 10:49:05] DEBUG[29606][C-00000001] res_rtp_asterisk.c: Allocated port 14366 for RTP instance '0x888f268' [Jan 4 10:49:05] DEBUG[29606][C-00000001] netsock2.c: Splitting '10.93.118.24' into... [Jan 4 10:49:05] DEBUG[29606][C-00000001] netsock2.c: ...host '10.93.118.24' and port ''. [Jan 4 10:49:05] DEBUG[29606][C-00000001] rtp_engine.c: RTP instance '0x888f268' is setup and ready to go [Jan 4 10:49:05] DEBUG[29606][C-00000001] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x888f268' [Jan 4 10:49:05] VERBOSE[29606][C-00000001] netsock2.c: == Using SIP RTP TOS bits 184 [Jan 4 10:49:05] VERBOSE[29606][C-00000001] netsock2.c: == Using SIP RTP CoS mark 5 [Jan 4 10:49:05] DEBUG[29606][C-00000001] chan_sip.c: Setting NAT on RTP to Off [Jan 4 10:49:05] DEBUG[29606][C-00000001] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [Jan 4 10:49:05] DEBUG[29606][C-00000001] chan_sip.c: Processing session-level SDP o=Sonus_UAC 1448398848 1 IN IP4 10.93.107.65... OK. [Jan 4 10:49:05] DEBUG[29606][C-00000001] chan_sip.c: Processing session-level SDP s=SIP Media Capabilities... UNSUPPORTED OR FAILED. [Jan 4 10:49:05] DEBUG[29606][C-00000001] netsock2.c: Splitting '10.93.107.65' into... [Jan 4 10:49:05] DEBUG[29606][C-00000001] netsock2.c: ...host '10.93.107.65' and port ''. [Jan 4 10:49:05] DEBUG[29606][C-00000001] chan_sip.c: Processing session-level SDP c=IN IP4 10.93.107.65... OK. [Jan 4 10:49:05] DEBUG[29606][C-00000001] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. [Jan 4 10:49:05] VERBOSE[29606][C-00000001] chan_sip.c: Found RTP audio format 0 [Jan 4 10:49:05] DEBUG[29606][C-00000001] rtp_engine.c: Setting payload 0 based on m type on 0x2b4eab3fe7b0 [Jan 4 10:49:05] DEBUG[29606][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [Jan 4 10:49:05] DEBUG[29606][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=ptime:20... OK. [Jan 4 10:49:05] VERBOSE[29606][C-00000001] chan_sip.c: Found audio description format PCMU for ID 0 [Jan 4 10:49:05] DEBUG[29606][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [Jan 4 10:49:05] VERBOSE[29606][C-00000001] chan_sip.c: Capabilities: us - (gsm|ulaw|alaw|h263|testlaw), peer - audio=(ulaw)/video=(nothing)/text=(nothing), combined - (ulaw) [Jan 4 10:49:05] VERBOSE[29606][C-00000001] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x0 (nothing), combined - 0x0 (nothing) [Jan 4 10:49:05] DEBUG[29606][C-00000001] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x888f268' [Jan 4 10:49:05] VERBOSE[29606][C-00000001] chan_sip.c: Peer audio RTP is at port 10.93.107.65:4988 [Jan 4 10:49:05] DEBUG[29606][C-00000001] rtp_engine.c: Copying payload 0 from 0x2b4eab3fe7b0 to 0x888f430 [Jan 4 10:49:05] DEBUG[29606][C-00000001] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x888f268' [Jan 4 10:49:05] DEBUG[29606][C-00000001] chan_sip.c: We're settling with these formats: (ulaw) [Jan 4 10:49:05] DEBUG[29606][C-00000001] chan_sip.c: Checking SIP call limits for device [Jan 4 10:49:05] DEBUG[29606][C-00000001] chan_sip.c: Updating call counter for incoming call [Jan 4 10:49:05] DEBUG[29606][C-00000001] netsock2.c: Splitting '10.93.118.24:5060' into... [Jan 4 10:49:05] DEBUG[29606][C-00000001] netsock2.c: ...host '10.93.118.24' and port ''. [Jan 4 10:49:05] DEBUG[29606][C-00000001] netsock2.c: Splitting '10.93.107.67' into... [Jan 4 10:49:05] DEBUG[29606][C-00000001] netsock2.c: ...host '10.93.107.67' and port ''. [Jan 4 10:49:05] VERBOSE[29606][C-00000001] chan_sip.c: Looking for 6022823054 in sip (domain 10.93.118.24) [Jan 4 10:49:05] DEBUG[29606][C-00000001] format_pref.c: Could not find preferred codec - Going for the best codec [Jan 4 10:49:05] DEBUG[29606][C-00000001] chan_sip.c: *** Our native formats are (ulaw) [Jan 4 10:49:05] DEBUG[29606][C-00000001] chan_sip.c: *** Joint capabilities are (ulaw) [Jan 4 10:49:05] DEBUG[29606][C-00000001] chan_sip.c: *** Our capabilities are (gsm|ulaw|alaw|h263|testlaw) [Jan 4 10:49:05] DEBUG[29606][C-00000001] chan_sip.c: *** AST_CODEC_CHOOSE formats are ulaw [Jan 4 10:49:05] DEBUG[29606][C-00000001] chan_sip.c: This channel will not be able to handle video. [Jan 4 10:49:05] DEBUG[29606][C-00000001] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [Jan 4 10:49:05] DEBUG[29606][C-00000001] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 [Jan 4 10:49:05] DEBUG[29606][C-00000001] chan_sip.c: build_route: Contact hop: [Jan 4 10:49:05] VERBOSE[29606][C-00000001] chan_sip.c: list_route: hop: [Jan 4 10:49:05] VERBOSE[29606][C-00000001] chan_sip.c: RDNIS for this call is 6022826398 (reason unknown) [Jan 4 10:49:05] DEBUG[29606][C-00000001] chan_sip.c: Got redirecting from number 6022826398 [Jan 4 10:49:05] DEBUG[29606][C-00000001] chan_sip.c: Got redirecting to number 6022823054 [Jan 4 10:49:05] DEBUG[29606][C-00000001] chan_sip.c: Incoming INVITE with 'timer' option supported [Jan 4 10:49:05] DEBUG[29606][C-00000001] chan_sip.c: INVITE also has "Session-Expires" header. [Jan 4 10:49:05] DEBUG[29606][C-00000001] chan_sip.c: Session-Expires: 1800 [Jan 4 10:49:05] DEBUG[29606][C-00000001] chan_sip.c: Refresher: UAC [Jan 4 10:49:05] DEBUG[29606][C-00000001] chan_sip.c: INVITE also has "Min-SE" header. [Jan 4 10:49:05] DEBUG[29606][C-00000001] chan_sip.c: Received Min-SE: 90 [Jan 4 10:49:05] DEBUG[29606][C-00000001] chan_sip.c: Session timer started: 16 - 008488FC-A574-1654-B05A-0C765D0AAA77-2904520@10.93.118.12 [Jan 4 10:49:05] DEBUG[29606][C-00000001] chan_sip.c: SIP/Asterisk_CLE-00000001: New call is still down.... Trying... [Jan 4 10:49:05] VERBOSE[29606][C-00000001] chan_sip.c: <--- Transmitting (no NAT) to 10.93.118.12:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.93.118.12:5060;branch=z9hG4bK00848924-A574-1654-B05A-0C765D0AAA77-2475;received=10.93.118.12 From: "CHARLES SCHWAB" ;tag=0084891A-A574-1654-B05A-0C765D0AAA77-2940418 To: Call-ID: 008488FC-A574-1654-B05A-0C765D0AAA77-2904520@10.93.118.12 CSeq: 1 INVITE Server: Asterisk PBX 11.2-cert2 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Session-Expires: 1800;refresher=uac Contact: Content-Length: 0 <------------> [Jan 4 10:49:05] DEBUG[29606][C-00000001] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 10.93.118.12:5060 [Jan 4 10:49:05] DEBUG[29606][C-00000001] logger.c: Call_ID [C-00000001] being removed from thread. [Jan 4 10:49:05] DEBUG[29607] devicestate.c: No provider found, checking channel drivers for SIP - Asterisk_CLE [Jan 4 10:49:05] DEBUG[29607] chan_sip.c: Checking device state for peer Asterisk_CLE [Jan 4 10:49:05] DEBUG[29607] devicestate.c: Changing state for SIP/Asterisk_CLE - state 1 (Not in use) [Jan 4 10:49:05] DEBUG[29607] devicestate.c: device 'SIP/Asterisk_CLE' state '1' [Jan 4 10:49:05] DEBUG[29622] app_queue.c: Device 'SIP/Asterisk_CLE' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jan 4 10:49:05] DEBUG[29630][C-00000001] logger.c: CALL_ID [C-00000001] bound to thread. [Jan 4 10:49:05] DEBUG[29630][C-00000001] pbx.c: Launching 'Wait' [Jan 4 10:49:05] VERBOSE[29630][C-00000001] pbx.c: -- Executing [6022823054@sip:1] Wait("SIP/Asterisk_CLE-00000001", "1") in new stack [Jan 4 10:49:06] DEBUG[29630][C-00000001] pbx.c: Launching 'Set' [Jan 4 10:49:06] VERBOSE[29630][C-00000001] pbx.c: -- Executing [6022823054@sip:2] Set("SIP/Asterisk_CLE-00000001", "SIP_CODEC=ulaw") in new stack [Jan 4 10:49:06] DEBUG[29630][C-00000001] pbx.c: Result of 'CHANNEL' is 'SIP/Asterisk_CLE-00000001' [Jan 4 10:49:06] DEBUG[29630][C-00000001] pbx.c: Launching 'Set' [Jan 4 10:49:06] VERBOSE[29630][C-00000001] pbx.c: -- Executing [6022823054@sip:3] Set("SIP/Asterisk_CLE-00000001", "GLOBAL(INITIAL_CHANNEL)=SIP/Asterisk_CLE-00000001") in new stack [Jan 4 10:49:06] VERBOSE[29630][C-00000001] pbx.c: == Setting global variable 'INITIAL_CHANNEL' to 'SIP/Asterisk_CLE-00000001' [Jan 4 10:49:06] DEBUG[29630][C-00000001] pbx.c: Function result is '10.93.118.12' [Jan 4 10:49:06] DEBUG[29630][C-00000001] pbx.c: Launching 'Set' [Jan 4 10:49:06] VERBOSE[29630][C-00000001] pbx.c: -- Executing [6022823054@sip:4] Set("SIP/Asterisk_CLE-00000001", "GLOBAL(INCOMING_SIP_PEER)=10.93.118.12") in new stack [Jan 4 10:49:06] VERBOSE[29630][C-00000001] pbx.c: == Setting global variable 'INCOMING_SIP_PEER' to '10.93.118.12' [Jan 4 10:49:06] DEBUG[29630][C-00000001] pbx.c: Function result is '7204183373' [Jan 4 10:49:06] DEBUG[29630][C-00000001] pbx.c: Result of 'EXTEN' is '6022823054' [Jan 4 10:49:06] DEBUG[29630][C-00000001] pbx.c: Expression result is '0' [Jan 4 10:49:06] DEBUG[29630][C-00000001] pbx.c: Launching 'GotoIf' [Jan 4 10:49:06] VERBOSE[29630][C-00000001] pbx.c: -- Executing [6022823054@sip:5] GotoIf("SIP/Asterisk_CLE-00000001", "0?internal:next1") in new stack [Jan 4 10:49:06] VERBOSE[29630][C-00000001] pbx.c: -- Goto (sip,6022823054,14) [Jan 4 10:49:06] DEBUG[29630][C-00000001] pbx.c: Result of 'EXTEN' is '6022823054' [Jan 4 10:49:06] DEBUG[29630][C-00000001] pbx.c: Result of 'VM_EXTERNAL_LAB_NUMBER' is '8775721013' [Jan 4 10:49:06] DEBUG[29630][C-00000001] pbx.c: Expression result is '0' [Jan 4 10:49:06] DEBUG[29630][C-00000001] pbx.c: Launching 'GotoIf' [Jan 4 10:49:06] VERBOSE[29630][C-00000001] pbx.c: -- Executing [6022823054@sip:14] GotoIf("SIP/Asterisk_CLE-00000001", "0?external:customer") in new stack [Jan 4 10:49:06] VERBOSE[29630][C-00000001] pbx.c: -- Goto (sip,6022823054,17) [Jan 4 10:49:06] DEBUG[29630][C-00000001] pbx.c: Result of 'EXTEN' is '6022823054' [Jan 4 10:49:06] DEBUG[29630][C-00000001] pbx.c: Launching 'Dial' [Jan 4 10:49:06] VERBOSE[29630][C-00000001] pbx.c: -- Executing [6022823054@sip:17] Dial("SIP/Asterisk_CLE-00000001", "local/6022823054@Leave_VoiceMail/b,8,r") in new stack [Jan 4 10:49:06] DEBUG[29630][C-00000001] channel_internal_api.c: Channel Call ID changing from [C-00000001] to [C-00000001] [Jan 4 10:49:06] DEBUG[29630][C-00000001] rtp_engine.c: Can't find native functions for channel 'Local/6022823054@Leave_VoiceMail-00000001;1' [Jan 4 10:49:06] DEBUG[29630][C-00000001] channel.c: Not copying variable DIALEDTIME. [Jan 4 10:49:06] DEBUG[29630][C-00000001] channel.c: Not copying variable ANSWEREDTIME. [Jan 4 10:49:06] DEBUG[29630][C-00000001] channel.c: Not copying variable DIALEDPEERNAME. [Jan 4 10:49:06] DEBUG[29630][C-00000001] channel.c: Not copying variable DIALEDPEERNUMBER. [Jan 4 10:49:06] DEBUG[29630][C-00000001] channel.c: Not copying variable DIALSTATUS. [Jan 4 10:49:06] DEBUG[29630][C-00000001] channel.c: Not copying variable SIP_CODEC. [Jan 4 10:49:06] DEBUG[29630][C-00000001] channel.c: Copying hard-transferable variable SIPRDNISDOMAIN. [Jan 4 10:49:06] DEBUG[29630][C-00000001] channel.c: Copying hard-transferable variable SIPREDIRECTREASON. [Jan 4 10:49:06] DEBUG[29630][C-00000001] channel.c: Copying hard-transferable variable PRIREDIRECTREASON. [Jan 4 10:49:06] DEBUG[29630][C-00000001] channel.c: Not copying variable SIPCALLID. [Jan 4 10:49:06] DEBUG[29630][C-00000001] channel.c: Not copying variable SIPDOMAIN. [Jan 4 10:49:06] DEBUG[29630][C-00000001] channel.c: Not copying variable SIPURI. [Jan 4 10:49:06] VERBOSE[29630][C-00000001] app_dial.c: -- Called local/6022823054@Leave_VoiceMail/b [Jan 4 10:49:06] VERBOSE[29630][C-00000001] chan_sip.c: <--- Transmitting (no NAT) to 10.93.118.12:5060 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 10.93.118.12:5060;branch=z9hG4bK00848924-A574-1654-B05A-0C765D0AAA77-2475;received=10.93.118.12 From: "CHARLES SCHWAB" ;tag=0084891A-A574-1654-B05A-0C765D0AAA77-2940418 To: ;tag=as6c6776bb Call-ID: 008488FC-A574-1654-B05A-0C765D0AAA77-2904520@10.93.118.12 CSeq: 1 INVITE Server: Asterisk PBX 11.2-cert2 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Session-Expires: 1800;refresher=uac Contact: Content-Length: 0 <------------> [Jan 4 10:49:06] DEBUG[29630][C-00000001] chan_sip.c: Trying to put 'SIP/2.0 180' onto UDP socket destined for 10.93.118.12:5060 [Jan 4 10:49:06] DEBUG[29631][C-00000001] logger.c: CALL_ID [C-00000001] bound to thread. [Jan 4 10:49:06] DEBUG[29631][C-00000001] pbx.c: Result of 'EXTEN' is '6022823054' [Jan 4 10:49:06] DEBUG[29631][C-00000001] pbx.c: Result of 'VM_CONTEXT' is 'GVMA_DN' [Jan 4 10:49:06] DEBUG[29631][C-00000001] pbx.c: Launching 'VoiceMail' [Jan 4 10:49:06] VERBOSE[29631][C-00000001] pbx.c: -- Executing [6022823054@Leave_VoiceMail:1] VoiceMail("Local/6022823054@Leave_VoiceMail-00000001;2", "6022823054@GVMA_DN,su") in new stack [Jan 4 10:49:06] VERBOSE[29630][C-00000001] app_dial.c: -- Local/6022823054@Leave_VoiceMail-00000001;1 answered SIP/Asterisk_CLE-00000001 [Jan 4 10:49:06] NOTICE[29630][C-00000001] chan_sip.c: Changing codec to 'ulaw' for this call because of ${SIP_CODEC} variable [Jan 4 10:49:06] DEBUG[29630][C-00000001] chan_sip.c: SIP answering channel: SIP/Asterisk_CLE-00000001 [Jan 4 10:49:06] DEBUG[29630][C-00000001] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jan 4 10:49:06] DEBUG[29630][C-00000001] chan_sip.c: Setting framing from config on incoming call [Jan 4 10:49:06] NOTICE[29630][C-00000001] chan_sip.c: Changing codec to 'ulaw' for this call because of ${SIP_CODEC} variable [Jan 4 10:49:06] DEBUG[29630][C-00000001] chan_sip.c: ** Our capability: (ulaw) Video flag: True Text flag: True [Jan 4 10:49:06] DEBUG[29630][C-00000001] chan_sip.c: ** Our prefcodec: (nothing) [Jan 4 10:49:06] VERBOSE[29630][C-00000001] chan_sip.c: Audio is at 14366 [Jan 4 10:49:06] VERBOSE[29630][C-00000001] chan_sip.c: Adding codec 100003 (ulaw) to SDP [Jan 4 10:49:06] DEBUG[29630][C-00000001] chan_sip.c: -- Done with adding codecs to SDP [Jan 4 10:49:06] DEBUG[29630][C-00000001] chan_sip.c: Done building SDP. Settling with this capability: (ulaw) [Jan 4 10:49:06] VERBOSE[29630][C-00000001] chan_sip.c: <--- Reliably Transmitting (no NAT) to 10.93.118.12:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.93.118.12:5060;branch=z9hG4bK00848924-A574-1654-B05A-0C765D0AAA77-2475;received=10.93.118.12 From: "CHARLES SCHWAB" ;tag=0084891A-A574-1654-B05A-0C765D0AAA77-2940418 To: ;tag=as6c6776bb Call-ID: 008488FC-A574-1654-B05A-0C765D0AAA77-2904520@10.93.118.12 CSeq: 1 INVITE Server: Asterisk PBX 11.2-cert2 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Session-Expires: 1800;refresher=uac Contact: Content-Type: application/sdp Require: timer Content-Length: 208 v=0 o=root 410556143 410556143 IN IP4 10.93.118.24 s=Asterisk PBX 11.2-cert2 c=IN IP4 10.93.118.24 t=0 0 m=audio 14366 RTP/AVP 0 a=rtpmap:0 PCMU/8000 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv <------------> [Jan 4 10:49:06] DEBUG[29630][C-00000001] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #19 [Jan 4 10:49:06] DEBUG[29630][C-00000001] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.93.118.12:5060 [Jan 4 10:49:06] DEBUG[29630][C-00000001] features.c: bridge answer set, chan answer set [Jan 4 10:49:06] DEBUG[29630][C-00000001] features.c: Removing dialed interfaces datastore on Local/6022823054@Leave_VoiceMail-00000001;1 since we're bridging [Jan 4 10:49:06] DEBUG[29630][C-00000001] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jan 4 10:49:06] DEBUG[29607] devicestate.c: No provider found, checking channel drivers for Local - 6022823054@Leave_VoiceMail [Jan 4 10:49:06] DEBUG[29607] chan_local.c: Checking if extension 6022823054@Leave_VoiceMail exists (devicestate) [Jan 4 10:49:06] DEBUG[29607] devicestate.c: Changing state for Local/6022823054@Leave_VoiceMail - state 2 (In use) [Jan 4 10:49:06] DEBUG[29607] devicestate.c: device 'Local/6022823054@Leave_VoiceMail' state '2' [Jan 4 10:49:06] DEBUG[29607] devicestate.c: No provider found, checking channel drivers for SIP - Asterisk_CLE [Jan 4 10:49:06] DEBUG[29607] chan_sip.c: Checking device state for peer Asterisk_CLE [Jan 4 10:49:06] DEBUG[29607] devicestate.c: Changing state for SIP/Asterisk_CLE - state 1 (Not in use) [Jan 4 10:49:06] DEBUG[29607] devicestate.c: device 'SIP/Asterisk_CLE' state '1' [Jan 4 10:49:06] DEBUG[29622] app_queue.c: Device 'Local/6022823054@Leave_VoiceMail' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Jan 4 10:49:06] DEBUG[29622] app_queue.c: Device 'SIP/Asterisk_CLE' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jan 4 10:49:06] DEBUG[29607] devicestate.c: No provider found, checking channel drivers for Local - 6022823054@Leave_VoiceMail [Jan 4 10:49:06] DEBUG[29607] chan_local.c: Checking if extension 6022823054@Leave_VoiceMail exists (devicestate) [Jan 4 10:49:06] DEBUG[29607] devicestate.c: Changing state for Local/6022823054@Leave_VoiceMail - state 2 (In use) [Jan 4 10:49:06] DEBUG[29607] devicestate.c: device 'Local/6022823054@Leave_VoiceMail' state '2' [Jan 4 10:49:06] DEBUG[29622] app_queue.c: Device 'Local/6022823054@Leave_VoiceMail' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Jan 4 10:49:06] DEBUG[29631][C-00000001] chan_local.c: Blocked indication -1 [Jan 4 10:49:07] VERBOSE[29606] chan_sip.c: <--- SIP read from UDP:10.93.118.12:5060 ---> ACK sip:6022823054@10.93.118.24:5060 SIP/2.0 From: "CHARLES SCHWAB" ;tag=0084891A-A574-1654-B05A-0C765D0AAA77-2940418 To: ;tag=as6c6776bb Call-ID: 008488FC-A574-1654-B05A-0C765D0AAA77-2904520@10.93.118.12 CSeq: 1 ACK Content-Length: 0 Via: SIP/2.0/UDP 10.93.118.12:5060;branch=z9hG4bK00848924-A574-1654-B05A-0C765D0AAA77-2476 Allow: INVITE, ACK, PRACK, CANCEL, BYE, REFER, INFO, UPDATE, MESSAGE, NOTIFY, OPTIONS Max-Forwards: 69 <-------------> [Jan 4 10:49:07] DEBUG[29606] chan_sip.c: Header 0 [ 44]: ACK sip:6022823054@10.93.118.24:5060 SIP/2.0 [Jan 4 10:49:07] DEBUG[29606] chan_sip.c: Header 1 [101]: From: "CHARLES SCHWAB" ;tag=0084891A-A574-1654-B05A-0C765D0AAA77-2940418 [Jan 4 10:49:07] DEBUG[29606] chan_sip.c: Header 2 [ 53]: To: ;tag=as6c6776bb [Jan 4 10:49:07] DEBUG[29606] chan_sip.c: Header 3 [ 66]: Call-ID: 008488FC-A574-1654-B05A-0C765D0AAA77-2904520@10.93.118.12 [Jan 4 10:49:07] DEBUG[29606] chan_sip.c: Header 4 [ 11]: CSeq: 1 ACK [Jan 4 10:49:07] DEBUG[29606] chan_sip.c: Header 5 [ 17]: Content-Length: 0 [Jan 4 10:49:07] DEBUG[29606] chan_sip.c: Header 6 [ 90]: Via: SIP/2.0/UDP 10.93.118.12:5060;branch=z9hG4bK00848924-A574-1654-B05A-0C765D0AAA77-2476 [Jan 4 10:49:07] DEBUG[29606] chan_sip.c: Header 7 [ 85]: Allow: INVITE, ACK, PRACK, CANCEL, BYE, REFER, INFO, UPDATE, MESSAGE, NOTIFY, OPTIONS [Jan 4 10:49:07] DEBUG[29606] chan_sip.c: Header 8 [ 16]: Max-Forwards: 69 [Jan 4 10:49:07] VERBOSE[29606] chan_sip.c: --- (9 headers 0 lines) --- [Jan 4 10:49:07] DEBUG[29606] chan_sip.c: = Looking for Call ID: 008488FC-A574-1654-B05A-0C765D0AAA77-2904520@10.93.118.12 (Checking From) --From tag 0084891A-A574-1654-B05A-0C765D0AAA77-2940418 --To-tag as6c6776bb [Jan 4 10:49:07] DEBUG[29606][C-00000001] logger.c: CALL_ID [C-00000001] bound to thread. [Jan 4 10:49:07] DEBUG[29606][C-00000001] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Jan 4 10:49:07] DEBUG[29606][C-00000001] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #19 [Jan 4 10:49:07] DEBUG[29606][C-00000001] chan_sip.c: Stopping retransmission on '008488FC-A574-1654-B05A-0C765D0AAA77-2904520@10.93.118.12' of Response 1: Match Found [Jan 4 10:49:07] DEBUG[29606][C-00000001] logger.c: Call_ID [C-00000001] being removed from thread. [Jan 4 10:49:07] DEBUG[29630][C-00000001] res_rtp_asterisk.c: 0x8935be0 -- Probation learning mode pass with source address 10.93.107.65:4988 [Jan 4 10:49:07] DEBUG[29631][C-00000001] app_voicemail.c: Before find_user [Jan 4 10:49:07] DEBUG[29631][C-00000001] res_config_odbc.c: Skip: 0; SQL: SELECT * FROM DYN_VM_USERS WHERE mailbox = ? AND context = ? [Jan 4 10:49:07] DEBUG[29631][C-00000001] res_config_odbc.c: Parameter 1 ('mailbox') = '6022823054' [Jan 4 10:49:07] DEBUG[29631][C-00000001] res_config_odbc.c: Parameter 2 ('context') = 'GVMA_DN' [Jan 4 10:49:07] DEBUG[29631][C-00000001] res_odbc.c: odbc_release_obj2(0x85d8728) called (obj->txf = (nil)) [Jan 4 10:49:07] DEBUG[29631][C-00000001] res_odbc.c: odbc_release_obj2(0x85d8728) called (obj->txf = (nil)) [Jan 4 10:49:07] DEBUG[29631][C-00000001] res_odbc.c: odbc_release_obj2(0x85d8728) called (obj->txf = (nil)) [Jan 4 10:49:07] DEBUG[29631][C-00000001] channel.c: Set channel Local/6022823054@Leave_VoiceMail-00000001;2 to write format slin [Jan 4 10:49:07] DEBUG[29630][C-00000001] res_rtp_asterisk.c: Ooh, format changed from unknown to ulaw [Jan 4 10:49:07] DEBUG[29630][C-00000001] res_rtp_asterisk.c: Created smoother: format: ulaw ms: 20 len: 160 [Jan 4 10:49:07] VERBOSE[29631][C-00000001] file.c: -- Playing '/var/spool/asterisk/voicemail/GVMA_DN/6022823054/unavail.slin' (language 'en') [Jan 4 10:49:08] DEBUG[29606] chan_sip.c: SIP TIMER: Rescheduling retransmission #9 (7) NOTIFY - 4 [Jan 4 10:49:08] DEBUG[29606] chan_sip.c: ** SIP timers: Rescheduling retransmission 8 to 4000 ms (t1 500 ms (Retrans id #9)) [Jan 4 10:49:08] VERBOSE[29606] chan_sip.c: Retransmitting #7 (no NAT) to 10.116.140.43:5060: NOTIFY sip:6022823054@10.116.140.43:5060 SIP/2.0 Via: SIP/2.0/UDP 10.93.118.24:5060;branch=z9hG4bK46bc78eb Max-Forwards: 70 From: ;tag=as563dac7b To: Contact: Call-ID: 7bcd94b92957a6007e6480d26697819e@10.93.118.24:5060 CSeq: 102 NOTIFY User-Agent: Asterisk PBX 11.2-cert2 Event: message-summary Content-Type: application/simple-message-summary Content-Length: 94 Messages-Waiting: no Message-Account: sip:6022823054@10.93.118.24 Voice-Message: 0/0 (0/0) --- [Jan 4 10:49:08] DEBUG[29606] chan_sip.c: Trying to put 'NOTIFY sip:' onto UDP socket destined for 10.116.140.43:5060 [Jan 4 10:49:08] DEBUG[29606] chan_sip.c: SIP TIMER: Rescheduling retransmission #11 (7) NOTIFY - 4 [Jan 4 10:49:08] DEBUG[29606] chan_sip.c: ** SIP timers: Rescheduling retransmission 8 to 4000 ms (t1 500 ms (Retrans id #11)) [Jan 4 10:49:08] VERBOSE[29606] chan_sip.c: Retransmitting #7 (no NAT) to 10.116.140.43:5060: NOTIFY sip:6022823054@10.116.140.43:5060 SIP/2.0 Via: SIP/2.0/UDP 10.93.118.24:5060;branch=z9hG4bK08e31dac Max-Forwards: 70 From: ;tag=as7f05c00f To: Contact: Call-ID: 55dcbe523cdb484862b3176c6707d913@10.93.118.24:5060 CSeq: 102 NOTIFY User-Agent: Asterisk PBX 11.2-cert2 Event: message-summary Content-Type: application/simple-message-summary Content-Length: 96 Messages-Waiting: yes Message-Account: sip:6022823054@10.93.118.24 Voice-Message: 25/2 (0/0) --- [Jan 4 10:49:08] DEBUG[29606] chan_sip.c: Trying to put 'NOTIFY sip:' onto UDP socket destined for 10.116.140.43:5060 [Jan 4 10:49:09] VERBOSE[29606] chan_sip.c: <--- SIP read from UDP:10.93.118.12:5060 ---> INFO sip:6022823054@10.93.118.24:5060 SIP/2.0 From: "CHARLES SCHWAB" ;tag=0084891A-A574-1654-B05A-0C765D0AAA77-2940418 To: ;tag=as6c6776bb Call-ID: 008488FC-A574-1654-B05A-0C765D0AAA77-2904520@10.93.118.12 CSeq: 2 INFO Content-Length: 25 Content-Type: application/dtmf-relay Via: SIP/2.0/UDP 10.93.118.12:5060;branch=z9hG4bK00848924-A574-1654-B05A-0C765D0AAA77-2477 Contact: Max-Forwards: 69 Signal= 0 Duration= 60 <-------------> [Jan 4 10:49:09] DEBUG[29606] chan_sip.c: Header 0 [ 45]: INFO sip:6022823054@10.93.118.24:5060 SIP/2.0 [Jan 4 10:49:09] DEBUG[29606] chan_sip.c: Header 1 [101]: From: "CHARLES SCHWAB" ;tag=0084891A-A574-1654-B05A-0C765D0AAA77-2940418 [Jan 4 10:49:09] DEBUG[29606] chan_sip.c: Header 2 [ 53]: To: ;tag=as6c6776bb [Jan 4 10:49:09] DEBUG[29606] chan_sip.c: Header 3 [ 66]: Call-ID: 008488FC-A574-1654-B05A-0C765D0AAA77-2904520@10.93.118.12 [Jan 4 10:49:09] DEBUG[29606] chan_sip.c: Header 4 [ 12]: CSeq: 2 INFO [Jan 4 10:49:09] DEBUG[29606] chan_sip.c: Header 5 [ 18]: Content-Length: 25 [Jan 4 10:49:09] DEBUG[29606] chan_sip.c: Header 6 [ 36]: Content-Type: application/dtmf-relay [Jan 4 10:49:09] DEBUG[29606] chan_sip.c: Header 7 [ 90]: Via: SIP/2.0/UDP 10.93.118.12:5060;branch=z9hG4bK00848924-A574-1654-B05A-0C765D0AAA77-2477 [Jan 4 10:49:09] DEBUG[29606] chan_sip.c: Header 8 [ 43]: Contact: [Jan 4 10:49:09] DEBUG[29606] chan_sip.c: Header 9 [ 16]: Max-Forwards: 69 [Jan 4 10:49:09] DEBUG[29606] chan_sip.c: Header 10 [ 0]: [Jan 4 10:49:09] DEBUG[29606] chan_sip.c: Body 0 [ 9]: Signal= 0 [Jan 4 10:49:09] DEBUG[29606] chan_sip.c: Body 1 [ 12]: Duration= 60 [Jan 4 10:49:09] VERBOSE[29606] chan_sip.c: --- (10 headers 2 lines) --- [Jan 4 10:49:09] DEBUG[29606] chan_sip.c: = Looking for Call ID: 008488FC-A574-1654-B05A-0C765D0AAA77-2904520@10.93.118.12 (Checking From) --From tag 0084891A-A574-1654-B05A-0C765D0AAA77-2940418 --To-tag as6c6776bb [Jan 4 10:49:09] DEBUG[29606][C-00000001] logger.c: CALL_ID [C-00000001] bound to thread. [Jan 4 10:49:09] DEBUG[29606][C-00000001] chan_sip.c: **** Received INFO (13) - Command in SIP INFO [Jan 4 10:49:09] VERBOSE[29606][C-00000001] chan_sip.c: Receiving INFO! [Jan 4 10:49:09] VERBOSE[29606][C-00000001] chan_sip.c: * DTMF-relay event received: 0 [Jan 4 10:49:09] VERBOSE[29606][C-00000001] chan_sip.c: <--- Transmitting (no NAT) to 10.93.118.12:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.93.118.12:5060;branch=z9hG4bK00848924-A574-1654-B05A-0C765D0AAA77-2477;received=10.93.118.12 From: "CHARLES SCHWAB" ;tag=0084891A-A574-1654-B05A-0C765D0AAA77-2940418 To: ;tag=as6c6776bb Call-ID: 008488FC-A574-1654-B05A-0C765D0AAA77-2904520@10.93.118.12 CSeq: 2 INFO Server: Asterisk PBX 11.2-cert2 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0 <------------> [Jan 4 10:49:09] DEBUG[29606][C-00000001] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.93.118.12:5060 [Jan 4 10:49:09] DEBUG[29606][C-00000001] logger.c: Call_ID [C-00000001] being removed from thread. [Jan 4 10:49:09] DTMF[29630][C-00000001] channel.c: DTMF end '0' received on SIP/Asterisk_CLE-00000001, duration 60 ms [Jan 4 10:49:09] DTMF[29630][C-00000001] channel.c: DTMF begin emulation of '0' with duration 80 queued on SIP/Asterisk_CLE-00000001 [Jan 4 10:49:09] DTMF[29631][C-00000001] channel.c: DTMF begin '0' received on Local/6022823054@Leave_VoiceMail-00000001;2 [Jan 4 10:49:09] DTMF[29631][C-00000001] channel.c: DTMF begin ignored '0' on Local/6022823054@Leave_VoiceMail-00000001;2 [Jan 4 10:49:09] DTMF[29630][C-00000001] channel.c: DTMF end emulation of '0' queued on SIP/Asterisk_CLE-00000001 [Jan 4 10:49:09] DTMF[29631][C-00000001] channel.c: DTMF end '0' received on Local/6022823054@Leave_VoiceMail-00000001;2, duration 86 ms [Jan 4 10:49:09] DTMF[29631][C-00000001] channel.c: DTMF end passthrough '0' on Local/6022823054@Leave_VoiceMail-00000001;2 [Jan 4 10:49:09] DEBUG[29631][C-00000001] channel.c: Set channel Local/6022823054@Leave_VoiceMail-00000001;2 to write format ulaw [Jan 4 10:49:09] VERBOSE[29631][C-00000001] file.c: -- Playing 'transfer.ulaw' (language 'en') [Jan 4 10:49:11] DEBUG[29631][C-00000001] pbx.c: Launching 'BackGround' [Jan 4 10:49:11] VERBOSE[29631][C-00000001] pbx.c: -- Executing [o@toSvcCenter:1] BackGround("Local/6022823054@Leave_VoiceMail-00000001;2", "one-moment-please") in new stack [Jan 4 10:49:11] VERBOSE[29631][C-00000001] file.c: -- Playing 'one-moment-please.ulaw' (language 'en') [Jan 4 10:49:12] DEBUG[29606] chan_sip.c: SIP TIMER: Rescheduling retransmission #9 (8) NOTIFY - 4 [Jan 4 10:49:12] DEBUG[29606] chan_sip.c: ** SIP timers: Rescheduling retransmission 9 to 4000 ms (t1 500 ms (Retrans id #9)) [Jan 4 10:49:12] VERBOSE[29606] chan_sip.c: Retransmitting #8 (no NAT) to 10.116.140.43:5060: NOTIFY sip:6022823054@10.116.140.43:5060 SIP/2.0 Via: SIP/2.0/UDP 10.93.118.24:5060;branch=z9hG4bK46bc78eb Max-Forwards: 70 From: ;tag=as563dac7b To: Contact: Call-ID: 7bcd94b92957a6007e6480d26697819e@10.93.118.24:5060 CSeq: 102 NOTIFY User-Agent: Asterisk PBX 11.2-cert2 Event: message-summary Content-Type: application/simple-message-summary Content-Length: 94 Messages-Waiting: no Message-Account: sip:6022823054@10.93.118.24 Voice-Message: 0/0 (0/0) --- [Jan 4 10:49:12] DEBUG[29606] chan_sip.c: Trying to put 'NOTIFY sip:' onto UDP socket destined for 10.116.140.43:5060 [Jan 4 10:49:12] DEBUG[29606] chan_sip.c: SIP TIMER: Rescheduling retransmission #11 (8) NOTIFY - 4 [Jan 4 10:49:12] DEBUG[29606] chan_sip.c: ** SIP timers: Rescheduling retransmission 9 to 4000 ms (t1 500 ms (Retrans id #11)) [Jan 4 10:49:12] VERBOSE[29606] chan_sip.c: Retransmitting #8 (no NAT) to 10.116.140.43:5060: NOTIFY sip:6022823054@10.116.140.43:5060 SIP/2.0 Via: SIP/2.0/UDP 10.93.118.24:5060;branch=z9hG4bK08e31dac Max-Forwards: 70 From: ;tag=as7f05c00f To: Contact: Call-ID: 55dcbe523cdb484862b3176c6707d913@10.93.118.24:5060 CSeq: 102 NOTIFY User-Agent: Asterisk PBX 11.2-cert2 Event: message-summary Content-Type: application/simple-message-summary Content-Length: 96 Messages-Waiting: yes Message-Account: sip:6022823054@10.93.118.24 Voice-Message: 25/2 (0/0) --- [Jan 4 10:49:12] DEBUG[29606] chan_sip.c: Trying to put 'NOTIFY sip:' onto UDP socket destined for 10.116.140.43:5060 [Jan 4 10:49:12] DEBUG[29631][C-00000001] pbx.c: Result of 'INCOMING_SIP_PEER' is '10.93.118.12' [Jan 4 10:49:12] DEBUG[29631][C-00000001] pbx.c: Launching 'Transfer' [Jan 4 10:49:12] VERBOSE[29631][C-00000001] pbx.c: -- Executing [o@toSvcCenter:2] Transfer("Local/6022823054@Leave_VoiceMail-00000001;2", "SIP/ToSvcCenter@10.93.118.12") in new stack [Jan 4 10:49:12] DEBUG[29631][C-00000001] pbx.c: Launching 'Hangup' [Jan 4 10:49:12] VERBOSE[29631][C-00000001] pbx.c: -- Executing [o@toSvcCenter:3] Hangup("Local/6022823054@Leave_VoiceMail-00000001;2", "") in new stack [Jan 4 10:49:12] DEBUG[29631][C-00000001] channel.c: Soft-Hanging up channel 'Local/6022823054@Leave_VoiceMail-00000001;2' [Jan 4 10:49:12] DEBUG[29631][C-00000001] pbx.c: Spawn extension (toSvcCenter,o,3) exited non-zero on 'Local/6022823054@Leave_VoiceMail-00000001;2' [Jan 4 10:49:12] VERBOSE[29631][C-00000001] pbx.c: == Spawn extension (toSvcCenter, o, 3) exited non-zero on 'Local/6022823054@Leave_VoiceMail-00000001;2' [Jan 4 10:49:12] DEBUG[29631][C-00000001] channel.c: Soft-Hanging up channel 'Local/6022823054@Leave_VoiceMail-00000001;2' [Jan 4 10:49:12] DEBUG[29631][C-00000001] channel.c: Hanging up channel 'Local/6022823054@Leave_VoiceMail-00000001;2' [Jan 4 10:49:12] DEBUG[29630][C-00000001] channel.c: Didn't get a frame from channel: Local/6022823054@Leave_VoiceMail-00000001;1 [Jan 4 10:49:12] DEBUG[29630][C-00000001] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jan 4 10:49:12] DEBUG[29630][C-00000001] channel.c: Bridge stops bridging channels SIP/Asterisk_CLE-00000001 and Local/6022823054@Leave_VoiceMail-00000001;1 [Jan 4 10:49:12] DEBUG[29607] devicestate.c: No provider found, checking channel drivers for Local - 6022823054@Leave_VoiceMail [Jan 4 10:49:12] DEBUG[29607] chan_local.c: Checking if extension 6022823054@Leave_VoiceMail exists (devicestate) [Jan 4 10:49:12] DEBUG[29607] devicestate.c: Changing state for Local/6022823054@Leave_VoiceMail - state 1 (Not in use) [Jan 4 10:49:12] DEBUG[29607] devicestate.c: device 'Local/6022823054@Leave_VoiceMail' state '1' [Jan 4 10:49:12] DEBUG[29622] app_queue.c: Device 'Local/6022823054@Leave_VoiceMail' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jan 4 10:49:12] DEBUG[29630][C-00000001] channel.c: Hanging up channel 'Local/6022823054@Leave_VoiceMail-00000001;1' [Jan 4 10:49:12] DEBUG[29607] devicestate.c: No provider found, checking channel drivers for Local - 6022823054@Leave_VoiceMail [Jan 4 10:49:12] DEBUG[29607] chan_local.c: Checking if extension 6022823054@Leave_VoiceMail exists (devicestate) [Jan 4 10:49:12] DEBUG[29607] devicestate.c: Changing state for Local/6022823054@Leave_VoiceMail - state 1 (Not in use) [Jan 4 10:49:12] DEBUG[29607] devicestate.c: device 'Local/6022823054@Leave_VoiceMail' state '1' [Jan 4 10:49:12] DEBUG[29622] app_queue.c: Device 'Local/6022823054@Leave_VoiceMail' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jan 4 10:49:13] DEBUG[29630][C-00000001] app_dial.c: Exiting with DIALSTATUS=ANSWER. [Jan 4 10:49:13] DEBUG[29630][C-00000001] pbx.c: Spawn extension (sip,6022823054,17) exited non-zero on 'SIP/Asterisk_CLE-00000001' [Jan 4 10:49:13] VERBOSE[29630][C-00000001] pbx.c: == Spawn extension (sip, 6022823054, 17) exited non-zero on 'SIP/Asterisk_CLE-00000001' [Jan 4 10:49:13] DEBUG[29630][C-00000001] channel.c: Soft-Hanging up channel 'SIP/Asterisk_CLE-00000001' [Jan 4 10:49:13] DEBUG[29630][C-00000001] channel.c: Hanging up channel 'SIP/Asterisk_CLE-00000001' [Jan 4 10:49:13] DEBUG[29630][C-00000001] chan_sip.c: Hangup call SIP/Asterisk_CLE-00000001, SIP callid 008488FC-A574-1654-B05A-0C765D0AAA77-2904520@10.93.118.12 [Jan 4 10:49:13] DEBUG[29630][C-00000001] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x888f268' [Jan 4 10:49:13] VERBOSE[29630][C-00000001] chan_sip.c: Scheduling destruction of SIP dialog '008488FC-A574-1654-B05A-0C765D0AAA77-2904520@10.93.118.12' in 32000 ms (Method: INFO) [Jan 4 10:49:13] DEBUG[29630][C-00000001] chan_sip.c: Session timer stopped: 16 - 008488FC-A574-1654-B05A-0C765D0AAA77-2904520@10.93.118.12 [Jan 4 10:49:13] DEBUG[29630][C-00000001] chan_sip.c: Strict routing enforced for session 008488FC-A574-1654-B05A-0C765D0AAA77-2904520@10.93.118.12 [Jan 4 10:49:13] VERBOSE[29630][C-00000001] chan_sip.c: set_destination: Parsing for address/port to send to [Jan 4 10:49:13] DEBUG[29630][C-00000001] netsock2.c: Splitting '10.93.118.12:5060' into... [Jan 4 10:49:13] DEBUG[29630][C-00000001] netsock2.c: ...host '10.93.118.12' and port '5060'. [Jan 4 10:49:13] VERBOSE[29630][C-00000001] chan_sip.c: set_destination: set destination to 10.93.118.12:5060 [Jan 4 10:49:13] VERBOSE[29630][C-00000001] chan_sip.c: Reliably Transmitting (no NAT) to 10.93.118.12:5060: BYE sip:7204183373@10.93.118.12:5060 SIP/2.0 Via: SIP/2.0/UDP 10.93.118.24:5060;branch=z9hG4bK06f69f89 Max-Forwards: 70 From: ;tag=as6c6776bb To: "CHARLES SCHWAB" ;tag=0084891A-A574-1654-B05A-0C765D0AAA77-2940418 Call-ID: 008488FC-A574-1654-B05A-0C765D0AAA77-2904520@10.93.118.12 CSeq: 102 BYE User-Agent: Asterisk PBX 11.2-cert2 X-Asterisk-HangupCause: Normal Clearing X-Asterisk-HangupCauseCode: 16 Content-Length: 0 --- [Jan 4 10:49:13] DEBUG[29630][C-00000001] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #22 [Jan 4 10:49:13] DEBUG[29630][C-00000001] chan_sip.c: Trying to put 'BYE sip:720' onto UDP socket destined for 10.93.118.12:5060 [Jan 4 10:49:13] DEBUG[29607] devicestate.c: No provider found, checking channel drivers for SIP - Asterisk_CLE [Jan 4 10:49:13] DEBUG[29607] chan_sip.c: Checking device state for peer Asterisk_CLE [Jan 4 10:49:13] DEBUG[29607] devicestate.c: Changing state for SIP/Asterisk_CLE - state 1 (Not in use) [Jan 4 10:49:13] DEBUG[29607] devicestate.c: device 'SIP/Asterisk_CLE' state '1' [Jan 4 10:49:13] DEBUG[29622] app_queue.c: Device 'SIP/Asterisk_CLE' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jan 4 10:49:13] VERBOSE[29606] chan_sip.c: <--- SIP read from UDP:10.93.118.12:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.93.118.24:5060;branch=z9hG4bK06f69f89;received=10.93.118.24 From: ;tag=as6c6776bb To: "CHARLES SCHWAB" ;tag=0084891A-A574-1654-B05A-0C765D0AAA77-2940418 Call-ID: 008488FC-A574-1654-B05A-0C765D0AAA77-2904520@10.93.118.12 CSeq: 102 BYE Contact: X-Genesys-geo-location: CLE X-Genesys-CallUUID: 0270JJ55EGB59C2Q1HR5Q2LAES0000CS Allow: INVITE, ACK, PRACK, CANCEL, BYE, REFER, INFO, UPDATE, MESSAGE, NOTIFY, OPTIONS Supported: uui Content-Length: 0 <-------------> [Jan 4 10:49:13] DEBUG[29606] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Jan 4 10:49:13] DEBUG[29606] chan_sip.c: Header 1 [ 79]: Via: SIP/2.0/UDP 10.93.118.24:5060;branch=z9hG4bK06f69f89;received=10.93.118.24 [Jan 4 10:49:13] DEBUG[29606] chan_sip.c: Header 2 [ 55]: From: ;tag=as6c6776bb [Jan 4 10:49:13] DEBUG[29606] chan_sip.c: Header 3 [ 99]: To: "CHARLES SCHWAB" ;tag=0084891A-A574-1654-B05A-0C765D0AAA77-2940418 [Jan 4 10:49:13] DEBUG[29606] chan_sip.c: Header 4 [ 66]: Call-ID: 008488FC-A574-1654-B05A-0C765D0AAA77-2904520@10.93.118.12 [Jan 4 10:49:13] DEBUG[29606] chan_sip.c: Header 5 [ 13]: CSeq: 102 BYE [Jan 4 10:49:13] DEBUG[29606] chan_sip.c: Header 6 [ 43]: Contact: [Jan 4 10:49:13] DEBUG[29606] chan_sip.c: Header 7 [ 27]: X-Genesys-geo-location: CLE [Jan 4 10:49:13] DEBUG[29606] chan_sip.c: Header 8 [ 52]: X-Genesys-CallUUID: 0270JJ55EGB59C2Q1HR5Q2LAES0000CS [Jan 4 10:49:13] DEBUG[29606] chan_sip.c: Header 9 [ 85]: Allow: INVITE, ACK, PRACK, CANCEL, BYE, REFER, INFO, UPDATE, MESSAGE, NOTIFY, OPTIONS [Jan 4 10:49:13] DEBUG[29606] chan_sip.c: Header 10 [ 14]: Supported: uui [Jan 4 10:49:13] DEBUG[29606] chan_sip.c: Header 11 [ 17]: Content-Length: 0 [Jan 4 10:49:13] VERBOSE[29606] chan_sip.c: --- (12 headers 0 lines) --- [Jan 4 10:49:13] DEBUG[29606] chan_sip.c: = Looking for Call ID: 008488FC-A574-1654-B05A-0C765D0AAA77-2904520@10.93.118.12 (Checking To) --From tag as6c6776bb --To-tag 0084891A-A574-1654-B05A-0C765D0AAA77-2940418 [Jan 4 10:49:13] DEBUG[29606][C-00000001] logger.c: CALL_ID [C-00000001] bound to thread. [Jan 4 10:49:13] DEBUG[29606][C-00000001] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #22 [Jan 4 10:49:13] DEBUG[29606][C-00000001] chan_sip.c: Stopping retransmission on '008488FC-A574-1654-B05A-0C765D0AAA77-2904520@10.93.118.12' of Request 102: Match Found [Jan 4 10:49:13] VERBOSE[29606][C-00000001] chan_sip.c: SIP Response message for INCOMING dialog BYE arrived [Jan 4 10:49:13] DEBUG[29606][C-00000001] logger.c: Call_ID [C-00000001] being removed from thread. [Jan 4 10:49:13] DEBUG[29606] chan_sip.c: Destroying SIP dialog 008488FC-A574-1654-B05A-0C765D0AAA77-2904520@10.93.118.12 [Jan 4 10:49:13] VERBOSE[29606] chan_sip.c: Really destroying SIP dialog '008488FC-A574-1654-B05A-0C765D0AAA77-2904520@10.93.118.12' Method: INFO [Jan 4 10:49:13] DEBUG[29606] rtp_engine.c: Destroyed RTP instance '0x888f268' [Jan 4 10:49:14] DEBUG[29606] chan_sip.c: Auto destroying SIP dialog '008488FC-A574-1654-B05A-0C765D0AAA77-2904497@10.93.118.12' [Jan 4 10:49:14] DEBUG[29606] chan_sip.c: Destroying SIP dialog 008488FC-A574-1654-B05A-0C765D0AAA77-2904497@10.93.118.12 [Jan 4 10:49:14] VERBOSE[29606] chan_sip.c: Really destroying SIP dialog '008488FC-A574-1654-B05A-0C765D0AAA77-2904497@10.93.118.12' Method: OPTIONS [Jan 4 10:49:16] DEBUG[29606] chan_sip.c: SIP TIMER: Rescheduling retransmission #9 (9) NOTIFY - 4 [Jan 4 10:49:16] DEBUG[29606] chan_sip.c: ** SIP timers: Rescheduling retransmission 10 to 4000 ms (t1 500 ms (Retrans id #9)) [Jan 4 10:49:16] VERBOSE[29606] chan_sip.c: Retransmitting #9 (no NAT) to 10.116.140.43:5060: NOTIFY sip:6022823054@10.116.140.43:5060 SIP/2.0 Via: SIP/2.0/UDP 10.93.118.24:5060;branch=z9hG4bK46bc78eb Max-Forwards: 70 From: ;tag=as563dac7b To: Contact: Call-ID: 7bcd94b92957a6007e6480d26697819e@10.93.118.24:5060 CSeq: 102 NOTIFY User-Agent: Asterisk PBX 11.2-cert2 Event: message-summary Content-Type: application/simple-message-summary Content-Length: 94 Messages-Waiting: no Message-Account: sip:6022823054@10.93.118.24 Voice-Message: 0/0 (0/0) --- [Jan 4 10:49:16] DEBUG[29606] chan_sip.c: Trying to put 'NOTIFY sip:' onto UDP socket destined for 10.116.140.43:5060 [Jan 4 10:49:16] DEBUG[29606] chan_sip.c: SIP TIMER: Rescheduling retransmission #11 (9) NOTIFY - 4 [Jan 4 10:49:16] DEBUG[29606] chan_sip.c: ** SIP timers: Rescheduling retransmission 10 to 4000 ms (t1 500 ms (Retrans id #11)) [Jan 4 10:49:16] VERBOSE[29606] chan_sip.c: Retransmitting #9 (no NAT) to 10.116.140.43:5060: NOTIFY sip:6022823054@10.116.140.43:5060 SIP/2.0 Via: SIP/2.0/UDP 10.93.118.24:5060;branch=z9hG4bK08e31dac Max-Forwards: 70 From: ;tag=as7f05c00f To: Contact: Call-ID: 55dcbe523cdb484862b3176c6707d913@10.93.118.24:5060 CSeq: 102 NOTIFY User-Agent: Asterisk PBX 11.2-cert2 Event: message-summary Content-Type: application/simple-message-summary Content-Length: 96 Messages-Waiting: yes Message-Account: sip:6022823054@10.93.118.24 Voice-Message: 25/2 (0/0) --- [Jan 4 10:49:16] DEBUG[29606] chan_sip.c: Trying to put 'NOTIFY sip:' onto UDP socket destined for 10.116.140.43:5060 [Jan 4 10:49:20] DEBUG[29606] chan_sip.c: SIP TIMER: Rescheduling retransmission #9 (10) NOTIFY - 4 [Jan 4 10:49:20] DEBUG[29606] chan_sip.c: ** SIP timers: Rescheduling retransmission 11 to 4000 ms (t1 500 ms (Retrans id #9)) [Jan 4 10:49:20] VERBOSE[29606] chan_sip.c: Retransmitting #10 (no NAT) to 10.116.140.43:5060: NOTIFY sip:6022823054@10.116.140.43:5060 SIP/2.0 Via: SIP/2.0/UDP 10.93.118.24:5060;branch=z9hG4bK46bc78eb Max-Forwards: 70 From: ;tag=as563dac7b To: Contact: Call-ID: 7bcd94b92957a6007e6480d26697819e@10.93.118.24:5060 CSeq: 102 NOTIFY User-Agent: Asterisk PBX 11.2-cert2 Event: message-summary Content-Type: application/simple-message-summary Content-Length: 94 Messages-Waiting: no Message-Account: sip:6022823054@10.93.118.24 Voice-Message: 0/0 (0/0) --- [Jan 4 10:49:20] DEBUG[29606] chan_sip.c: Trying to put 'NOTIFY sip:' onto UDP socket destined for 10.116.140.43:5060 [Jan 4 10:49:20] DEBUG[29606] chan_sip.c: SIP TIMER: Rescheduling retransmission #11 (10) NOTIFY - 4 [Jan 4 10:49:20] DEBUG[29606] chan_sip.c: ** SIP timers: Rescheduling retransmission 11 to 4000 ms (t1 500 ms (Retrans id #11)) [Jan 4 10:49:20] VERBOSE[29606] chan_sip.c: Retransmitting #10 (no NAT) to 10.116.140.43:5060: NOTIFY sip:6022823054@10.116.140.43:5060 SIP/2.0 Via: SIP/2.0/UDP 10.93.118.24:5060;branch=z9hG4bK08e31dac Max-Forwards: 70 From: ;tag=as7f05c00f To: Contact: Call-ID: 55dcbe523cdb484862b3176c6707d913@10.93.118.24:5060 CSeq: 102 NOTIFY User-Agent: Asterisk PBX 11.2-cert2 Event: message-summary Content-Type: application/simple-message-summary Content-Length: 96 Messages-Waiting: yes Message-Account: sip:6022823054@10.93.118.24 Voice-Message: 25/2 (0/0) --- [Jan 4 10:49:20] DEBUG[29606] chan_sip.c: Trying to put 'NOTIFY sip:' onto UDP socket destined for 10.116.140.43:5060 [Jan 4 10:49:20] DEBUG[29606] chan_sip.c: Re-scheduled destruction of SIP call 7bcd94b92957a6007e6480d26697819e@10.93.118.24:5060 [Jan 4 10:49:20] WARNING[29606] chan_sip.c: Retransmission timeout reached on transmission 7bcd94b92957a6007e6480d26697819e@10.93.118.24:5060 for seqno 102 (Non-critical Request) -- See https://wiki.asterisk.org/wiki/display/AST/SIP+Retransmissions Packet timed out after 32000ms with no response [Jan 4 10:49:20] DEBUG[29606] chan_sip.c: Re-scheduled destruction of SIP call 55dcbe523cdb484862b3176c6707d913@10.93.118.24:5060 [Jan 4 10:49:20] WARNING[29606] chan_sip.c: Retransmission timeout reached on transmission 55dcbe523cdb484862b3176c6707d913@10.93.118.24:5060 for seqno 102 (Non-critical Request) -- See https://wiki.asterisk.org/wiki/display/AST/SIP+Retransmissions Packet timed out after 32000ms with no response [Jan 4 10:49:27] VERBOSE[29606] chan_sip.c: Really destroying SIP dialog '008488FC-A574-1654-B05A-0C765D0AAA77-2904505@10.93.118.12' Method: BYE [Jan 4 10:49:34] VERBOSE[29614] asterisk.c: -- Remote UNIX connection disconnected [Jan 4 10:49:37] VERBOSE[29597] asterisk.c: Asterisk cleanly ending (0). [Jan 4 10:49:37] VERBOSE[29597] asterisk.c: Executing last minute cleanups [Jan 4 10:49:37] VERBOSE[29597] res_musiconhold.c: == Destroying musiconhold processes [Jan 4 10:49:37] VERBOSE[29597] pbx.c: == Unregistered application 'CallCompletionCancel' [Jan 4 10:49:37] VERBOSE[29597] pbx.c: == Unregistered application 'CallCompletionRequest' [Jan 4 10:49:37] VERBOSE[29597] pbx.c: == Unregistered custom function FEATUREMAP [Jan 4 10:49:37] VERBOSE[29597] pbx.c: == Unregistered custom function FEATURE [Jan 4 10:49:37] VERBOSE[29597] manager.c: == Manager unregistered action Bridge [Jan 4 10:49:37] VERBOSE[29597] manager.c: == Manager unregistered action Park [Jan 4 10:49:37] VERBOSE[29597] manager.c: == Manager unregistered action Parkinglots [Jan 4 10:49:37] VERBOSE[29597] manager.c: == Manager unregistered action ParkedCalls [Jan 4 10:49:37] VERBOSE[29597] pbx.c: == Unregistered application 'Park' [Jan 4 10:49:37] VERBOSE[29597] pbx.c: == Unregistered application 'ParkedCall' [Jan 4 10:49:37] VERBOSE[29597] pbx.c: == Unregistered application 'Bridge' [Jan 4 10:49:37] VERBOSE[29597] pbx.c: == Unregistered application 'Answer' [Jan 4 10:49:37] VERBOSE[29597] pbx.c: == Unregistered application 'BackGround' [Jan 4 10:49:37] VERBOSE[29597] pbx.c: == Unregistered application 'Busy' [Jan 4 10:49:37] VERBOSE[29597] pbx.c: == Unregistered application 'Congestion' [Jan 4 10:49:37] VERBOSE[29597] pbx.c: == Unregistered application 'ExecIfTime' [Jan 4 10:49:37] VERBOSE[29597] pbx.c: == Unregistered application 'Goto' [Jan 4 10:49:37] VERBOSE[29597] pbx.c: == Unregistered application 'GotoIf' [Jan 4 10:49:37] VERBOSE[29597] pbx.c: == Unregistered application 'GotoIfTime' [Jan 4 10:49:37] VERBOSE[29597] pbx.c: == Unregistered application 'ImportVar' [Jan 4 10:49:37] VERBOSE[29597] pbx.c: == Unregistered application 'Hangup' [Jan 4 10:49:37] VERBOSE[29597] pbx.c: == Unregistered application 'Incomplete' [Jan 4 10:49:37] VERBOSE[29597] pbx.c: == Unregistered application 'NoOp' [Jan 4 10:49:37] VERBOSE[29597] pbx.c: == Unregistered application 'Proceeding' [Jan 4 10:49:37] VERBOSE[29597] pbx.c: == Unregistered application 'Progress' [Jan 4 10:49:37] VERBOSE[29597] pbx.c: == Unregistered application 'RaiseException' [Jan 4 10:49:37] VERBOSE[29597] pbx.c: == Unregistered application 'ResetCDR' [Jan 4 10:49:37] VERBOSE[29597] pbx.c: == Unregistered application 'Ringing' [Jan 4 10:49:37] VERBOSE[29597] pbx.c: == Unregistered application 'SayAlpha' [Jan 4 10:49:37] VERBOSE[29597] pbx.c: == Unregistered application 'SayDigits' [Jan 4 10:49:37] VERBOSE[29597] pbx.c: == Unregistered application 'SayNumber' [Jan 4 10:49:37] VERBOSE[29597] pbx.c: == Unregistered application 'SayPhonetic' [Jan 4 10:49:37] VERBOSE[29597] pbx.c: == Unregistered application 'Set' [Jan 4 10:49:37] VERBOSE[29597] pbx.c: == Unregistered application 'MSet' [Jan 4 10:49:37] VERBOSE[29597] pbx.c: == Unregistered application 'SetAMAFlags' [Jan 4 10:49:37] VERBOSE[29597] pbx.c: == Unregistered application 'Wait' [Jan 4 10:49:37] VERBOSE[29597] pbx.c: == Unregistered application 'WaitExten' [Jan 4 10:49:37] VERBOSE[29597] manager.c: == Manager unregistered action ShowDialPlan [Jan 4 10:49:37] VERBOSE[29597] pbx.c: == Unregistered custom function EXCEPTION [Jan 4 10:49:37] VERBOSE[29597] pbx.c: == Unregistered custom function TESTTIME [Jan 4 10:49:37] VERBOSE[29597] manager.c: == Manager unregistered action Ping [Jan 4 10:49:37] VERBOSE[29597] manager.c: == Manager unregistered action Events [Jan 4 10:49:37] VERBOSE[29597] manager.c: == Manager unregistered action Logoff [Jan 4 10:49:37] VERBOSE[29597] manager.c: == Manager unregistered action Login [Jan 4 10:49:37] VERBOSE[29597] manager.c: == Manager unregistered action Challenge [Jan 4 10:49:37] VERBOSE[29597] manager.c: == Manager unregistered action Hangup [Jan 4 10:49:37] VERBOSE[29597] manager.c: == Manager unregistered action Status [Jan 4 10:49:37] VERBOSE[29597] manager.c: == Manager unregistered action Setvar [Jan 4 10:49:37] VERBOSE[29597] manager.c: == Manager unregistered action Getvar [Jan 4 10:49:37] VERBOSE[29597] manager.c: == Manager unregistered action GetConfig [Jan 4 10:49:37] VERBOSE[29597] manager.c: == Manager unregistered action GetConfigJSON [Jan 4 10:49:37] VERBOSE[29597] manager.c: == Manager unregistered action UpdateConfig [Jan 4 10:49:37] VERBOSE[29597] manager.c: == Manager unregistered action CreateConfig [Jan 4 10:49:37] VERBOSE[29597] manager.c: == Manager unregistered action ListCategories [Jan 4 10:49:37] VERBOSE[29597] manager.c: == Manager unregistered action Redirect [Jan 4 10:49:37] VERBOSE[29597] manager.c: == Manager unregistered action Atxfer [Jan 4 10:49:37] VERBOSE[29597] manager.c: == Manager unregistered action Originate [Jan 4 10:49:37] VERBOSE[29597] manager.c: == Manager unregistered action Command [Jan 4 10:49:37] VERBOSE[29597] manager.c: == Manager unregistered action ExtensionState [Jan 4 10:49:37] VERBOSE[29597] manager.c: == Manager unregistered action PresenceState [Jan 4 10:49:37] VERBOSE[29597] manager.c: == Manager unregistered action AbsoluteTimeout [Jan 4 10:49:37] VERBOSE[29597] manager.c: == Manager unregistered action MailboxStatus [Jan 4 10:49:37] VERBOSE[29597] manager.c: == Manager unregistered action MailboxCount [Jan 4 10:49:37] VERBOSE[29597] manager.c: == Manager unregistered action ListCommands [Jan 4 10:49:37] VERBOSE[29597] manager.c: == Manager unregistered action SendText [Jan 4 10:49:37] VERBOSE[29597] manager.c: == Manager unregistered action UserEvent [Jan 4 10:49:37] VERBOSE[29597] manager.c: == Manager unregistered action WaitEvent [Jan 4 10:49:37] VERBOSE[29597] manager.c: == Manager unregistered action CoreSettings [Jan 4 10:49:37] VERBOSE[29597] manager.c: == Manager unregistered action CoreStatus [Jan 4 10:49:37] VERBOSE[29597] manager.c: == Manager unregistered action Reload [Jan 4 10:49:37] VERBOSE[29597] manager.c: == Manager unregistered action CoreShowChannels [Jan 4 10:49:37] VERBOSE[29597] manager.c: == Manager unregistered action ModuleLoad [Jan 4 10:49:37] VERBOSE[29597] manager.c: == Manager unregistered action ModuleCheck [Jan 4 10:49:37] VERBOSE[29597] manager.c: == Manager unregistered action AOCMessage [Jan 4 10:49:37] VERBOSE[29597] manager.c: == Manager unregistered action Filter [Jan 4 10:49:37] VERBOSE[29597] pbx.c: == Unregistered custom function AMI_CLIENT [Jan 4 10:49:37] VERBOSE[29597] manager.c: == Manager unregistered action DataGet [Jan 4 10:49:37] VERBOSE[29597] pbx.c: == Unregistered custom function MESSAGE [Jan 4 10:49:37] VERBOSE[29597] pbx.c: == Unregistered custom function MESSAGE_DATA [Jan 4 10:49:37] VERBOSE[29597] pbx.c: == Unregistered application 'MessageSend' [Jan 4 10:49:37] VERBOSE[29597] manager.c: == Manager unregistered action MessageSend [Jan 4 10:49:37] VERBOSE[29597] manager.c: == Manager unregistered action DBGet [Jan 4 10:49:37] VERBOSE[29597] manager.c: == Manager unregistered action DBPut [Jan 4 10:49:37] VERBOSE[29597] manager.c: == Manager unregistered action DBDel [Jan 4 10:49:37] VERBOSE[29597] manager.c: == Manager unregistered action DBDelTree