[Mar 22 20:32:50] NOTICE[12946] loader.c: 1 modules will be loaded. [Mar 22 20:32:50] NOTICE[12946] manager.c: Invalid keyword = in manager.conf [general] [Mar 22 20:32:50] NOTICE[12946] cdr.c: CDR simple logging enabled. [Mar 22 20:32:50] NOTICE[12946] loader.c: 170 modules will be loaded. [Mar 22 20:32:50] WARNING[12946] loader.c: Module 'res_features.so' was not compiled with the same compile-time options as this version of Asterisk. [Mar 22 20:32:50] WARNING[12946] loader.c: Module 'res_features.so' will not be initialized as it may cause instability. [Mar 22 20:32:50] WARNING[12946] loader.c: Module 'res_features.so' could not be loaded. [Mar 22 20:32:50] WARNING[12946] res_config_ldap.c: Cannot load configuration res_ldap.conf [Mar 22 20:32:50] NOTICE[12946] res_config_ldap.c: Cannot load LDAP RealTime driver. [Mar 22 20:32:50] NOTICE[12946] config.c: Registered Config Engine odbc [Mar 22 20:32:50] NOTICE[12946] res_odbc.c: Adding ENV var: INFORMIXSERVER=my_special_database [Mar 22 20:32:50] NOTICE[12946] res_odbc.c: Adding ENV var: INFORMIXDIR=/opt/informix [Mar 22 20:32:50] NOTICE[12946] res_odbc.c: res_odbc loaded. [Mar 22 20:32:50] NOTICE[12946] res_smdi.c: No SMDI interfaces are available to listen on, not starting SMDI listener. [Mar 22 20:32:50] WARNING[12946] app_voicemail.c: Setting 'maxmessage' has been deprecated in favor of 'maxsecs'. [Mar 22 20:32:50] NOTICE[12946] pbx_ael.c: Starting AEL load process. [Mar 22 20:32:50] NOTICE[12946] pbx_ael.c: AEL load process: parsed config file name '/etc/asterisk/extensions.ael'. [Mar 22 20:32:50] NOTICE[12946] pbx_ael.c: AEL load process: checked config file name '/etc/asterisk/extensions.ael'. [Mar 22 20:32:50] NOTICE[12946] pbx_ael.c: AEL load process: compiled config file name '/etc/asterisk/extensions.ael'. [Mar 22 20:32:50] NOTICE[12946] pbx_ael.c: AEL load process: merged config file name '/etc/asterisk/extensions.ael'. [Mar 22 20:32:50] NOTICE[12946] pbx_ael.c: AEL load process: verified config file name '/etc/asterisk/extensions.ael'. [Mar 22 20:32:50] VERBOSE[12946] logger.c: SIP channel loading... [Mar 22 20:32:50] NOTICE[12946] chan_sip.c: The 'username' field for sip peers has been deprecated in favor of the term 'defaultuser' [Mar 22 20:32:50] WARNING[12946] acl.c: Unable to lookup '192.168.15.101:5070' [Mar 22 20:32:50] WARNING[12946] chan_zap.c: Ignoring userbase at line 12. [Mar 22 20:32:50] WARNING[12946] chan_zap.c: Ignoring hasvoicemail at line 16. [Mar 22 20:32:50] WARNING[12946] chan_zap.c: Ignoring vmsecret at line 20. [Mar 22 20:32:50] WARNING[12946] chan_zap.c: Ignoring hassip at line 24. [Mar 22 20:32:50] WARNING[12946] chan_zap.c: Ignoring hasiax at line 28. [Mar 22 20:32:50] WARNING[12946] chan_zap.c: Ignoring hasmanager at line 36. [Mar 22 20:32:50] WARNING[12946] chan_zap.c: Ignoring localextenlength at line 54. [Mar 22 20:32:50] WARNING[12946] chan_zap.c: Ignoring allow_aliasextns at line 55. [Mar 22 20:32:50] WARNING[12946] translate.c: plc_samples 160 format f [Mar 22 20:32:50] NOTICE[12946] config.c: Registered Config Engine curl [Mar 22 20:32:50] WARNING[12946] pbx_config.c: ==!!== Unknown directive: hasbeensetup at line 553 -- IGNORING!!! [Mar 22 20:32:50] WARNING[12946] pbx_config.c: ==!!== Unknown directive: plancomment at line 559 -- IGNORING!!! [Mar 22 20:32:50] WARNING[12946] pbx_config.c: ==!!== Unknown directive: comment at line 563 -- IGNORING!!! [Mar 22 20:33:27] DEBUG[12946] chan_sip.c: Auto destroying SIP dialog '1f7df6865c4ae5bd64453a264955e807@127.0.0.1' [Mar 22 20:33:27] DEBUG[12946] chan_sip.c: Destroying SIP dialog 1f7df6865c4ae5bd64453a264955e807@127.0.0.1 [Mar 22 20:33:27] VERBOSE[12946] logger.c: Really destroying SIP dialog '1f7df6865c4ae5bd64453a264955e807@127.0.0.1' Method: REGISTER [Mar 22 20:33:27] DEBUG[12946] sched.c: Attempted to delete nonexistent schedule entry -1! [Mar 22 20:33:34] DEBUG[12946] chan_sip.c: Header 0 [ 35]: REGISTER sip:192.168.15.101 SIP/2.0 [Mar 22 20:33:34] DEBUG[12946] chan_sip.c: Header 1 [ 37]: Via: SIP/2.0/TCP 192.168.15.100:13769 [Mar 22 20:33:34] DEBUG[12946] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Mar 22 20:33:34] DEBUG[12946] chan_sip.c: Header 3 [ 84]: From: ;tag=abcdb2676f974344b2d2350b2f1f7743;epid=7f6a19fb3a [Mar 22 20:33:34] DEBUG[12946] chan_sip.c: Header 4 [ 29]: To: [Mar 22 20:33:34] DEBUG[12946] chan_sip.c: Header 5 [ 41]: Call-ID: f59a1257c0684f8f982cd60f6effb625 [Mar 22 20:33:34] DEBUG[12946] chan_sip.c: Header 6 [ 16]: CSeq: 1 REGISTER [Mar 22 20:33:34] DEBUG[12946] chan_sip.c: Header 7 [158]: Contact: ;methods="INVITE, MESSAGE, INFO, SUBSCRIBE, OPTIONS, BYE, CANCEL, NOTIFY, ACK, REFER, BENOTIFY";proxy=replace [Mar 22 20:33:34] DEBUG[12946] chan_sip.c: Header 8 [ 45]: User-Agent: RTC/1.3.5470 (Messenger 5.1.0701) [Mar 22 20:33:34] DEBUG[12946] chan_sip.c: Header 9 [ 50]: Supported: com.microsoft.msrtc.presence, adhoclist [Mar 22 20:33:34] DEBUG[12946] chan_sip.c: Header 10 [ 30]: ms-keep-alive: UAC;hop-hop=yes [Mar 22 20:33:34] DEBUG[12946] chan_sip.c: Header 11 [ 19]: Event: registration [Mar 22 20:33:34] DEBUG[12946] chan_sip.c: Header 12 [ 22]: Allow-Events: presence [Mar 22 20:33:34] DEBUG[12946] chan_sip.c: Header 13 [ 17]: Content-Length: 0 [Mar 22 20:33:34] DEBUG[12946] chan_sip.c: Header 14 [ 0]: [Mar 22 20:33:34] VERBOSE[12946] logger.c: <--- SIP read from TCP://192.168.15.100:3801 ---> REGISTER sip:192.168.15.101 SIP/2.0 Via: SIP/2.0/TCP 192.168.15.100:13769 Max-Forwards: 70 From: ;tag=abcdb2676f974344b2d2350b2f1f7743;epid=7f6a19fb3a To: Call-ID: f59a1257c0684f8f982cd60f6effb625 CSeq: 1 REGISTER Contact: ;methods="INVITE, MESSAGE, INFO, SUBSCRIBE, OPTIONS, BYE, CANCEL, NOTIFY, ACK, REFER, BENOTIFY";proxy=replace User-Agent: RTC/1.3.5470 (Messenger 5.1.0701) Supported: com.microsoft.msrtc.presence, adhoclist ms-keep-alive: UAC;hop-hop=yes Event: registration Allow-Events: presence Content-Length: 0 <-------------> [Mar 22 20:33:34] DEBUG[12946] chan_sip.c: Header 0 [ 35]: REGISTER sip:192.168.15.101 SIP/2.0 [Mar 22 20:33:34] DEBUG[12946] chan_sip.c: Header 1 [ 37]: Via: SIP/2.0/TCP 192.168.15.100:13769 [Mar 22 20:33:34] DEBUG[12946] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Mar 22 20:33:34] DEBUG[12946] chan_sip.c: Header 3 [ 84]: From: ;tag=abcdb2676f974344b2d2350b2f1f7743;epid=7f6a19fb3a [Mar 22 20:33:34] DEBUG[12946] chan_sip.c: Header 4 [ 29]: To: [Mar 22 20:33:34] DEBUG[12946] chan_sip.c: Header 5 [ 41]: Call-ID: f59a1257c0684f8f982cd60f6effb625 [Mar 22 20:33:34] DEBUG[12946] chan_sip.c: Header 6 [ 16]: CSeq: 1 REGISTER [Mar 22 20:33:34] DEBUG[12946] chan_sip.c: Header 7 [158]: Contact: ;methods="INVITE, MESSAGE, INFO, SUBSCRIBE, OPTIONS, BYE, CANCEL, NOTIFY, ACK, REFER, BENOTIFY";proxy=replace [Mar 22 20:33:34] DEBUG[12946] chan_sip.c: Header 8 [ 45]: User-Agent: RTC/1.3.5470 (Messenger 5.1.0701) [Mar 22 20:33:34] DEBUG[12946] chan_sip.c: Header 9 [ 50]: Supported: com.microsoft.msrtc.presence, adhoclist [Mar 22 20:33:34] DEBUG[12946] chan_sip.c: Header 10 [ 30]: ms-keep-alive: UAC;hop-hop=yes [Mar 22 20:33:34] DEBUG[12946] chan_sip.c: Header 11 [ 19]: Event: registration [Mar 22 20:33:34] DEBUG[12946] chan_sip.c: Header 12 [ 22]: Allow-Events: presence [Mar 22 20:33:34] DEBUG[12946] chan_sip.c: Header 13 [ 17]: Content-Length: 0 [Mar 22 20:33:34] DEBUG[12946] chan_sip.c: Header 14 [ 0]: [Mar 22 20:33:34] VERBOSE[12946] logger.c: --- (14 headers 0 lines) --- [Mar 22 20:33:34] DEBUG[12946] acl.c: Found IP address for this socket [Mar 22 20:33:34] DEBUG[12946] chan_sip.c: Allocating new SIP dialog for f59a1257c0684f8f982cd60f6effb625 - REGISTER (No RTP) [Mar 22 20:33:34] DEBUG[12946] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [Mar 22 20:33:34] DEBUG[12946] chan_sip.c: Initializing initreq for method REGISTER - callid f59a1257c0684f8f982cd60f6effb625 [Mar 22 20:33:34] VERBOSE[12946] logger.c: Sending to 192.168.15.100 : 13769 (no NAT) [Mar 22 20:33:34] VERBOSE[12946] logger.c: -- Registered SIP '9001' at 192.168.15.100 port 13769 expires 120 [Mar 22 20:33:34] VERBOSE[12946] logger.c: > Saved useragent "RTC/1.3.5470 (Messenger 5.1.0701)" for peer 9001 [Mar 22 20:33:34] VERBOSE[12946] logger.c: <--- Transmitting (no NAT) to 192.168.15.100:13769 ---> SIP/2.0 200 OK Via: SIP/2.0/TCP 192.168.15.100:13769;received=192.168.15.100 From: ;tag=abcdb2676f974344b2d2350b2f1f7743;epid=7f6a19fb3a To: ;tag=as64dec770 Call-ID: f59a1257c0684f8f982cd60f6effb625 CSeq: 1 REGISTER User-Agent: Asterisk PBX SVN-trunk-r110578M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces, timer Expires: 120 Contact: ;expires=120 Date: Sun, 23 Mar 2008 01:33:34 GMT Content-Length: 0 <------------> [Mar 22 20:33:34] DEBUG[12946] chan_sip.c: Trying to put 'SIP/2.0 20' onto TCP socket destined for 192.168.15.100 [Mar 22 20:33:34] DEBUG[12946] devicestate.c: Notification of state change to be queued on device/channel SIP/9001 [Mar 22 20:33:34] VERBOSE[12946] logger.c: Scheduling destruction of SIP dialog 'f59a1257c0684f8f982cd60f6effb625' in 32000 ms (Method: REGISTER) [Mar 22 20:33:34] DEBUG[12946] devicestate.c: No provider found, checking channel drivers for SIP - 9001 [Mar 22 20:33:34] DEBUG[12946] chan_sip.c: Checking device state for peer 9001 [Mar 22 20:33:34] DEBUG[12946] devicestate.c: Changing state for SIP/9001 - state 1 (Not in use) [Mar 22 20:33:34] DEBUG[12946] devicestate.c: No provider found, checking channel drivers for SIP - 9001 [Mar 22 20:33:34] DEBUG[12946] chan_sip.c: Checking device state for peer 9001 [Mar 22 20:33:34] DEBUG[12946] app_queue.c: Device 'SIP/9001' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Mar 22 20:34:06] DEBUG[12946] chan_sip.c: Auto destroying SIP dialog 'f59a1257c0684f8f982cd60f6effb625' [Mar 22 20:34:06] DEBUG[12946] chan_sip.c: Destroying SIP dialog f59a1257c0684f8f982cd60f6effb625 [Mar 22 20:34:06] VERBOSE[12946] logger.c: Really destroying SIP dialog 'f59a1257c0684f8f982cd60f6effb625' Method: REGISTER [Mar 22 20:34:06] DEBUG[12946] sched.c: Attempted to delete nonexistent schedule entry -1! [Mar 22 20:34:19] VERBOSE[12946] logger.c: <--- SIP read from UDP://192.168.15.100:5061 ---> INVITE sip:9001@192.168.15.101 SIP/2.0 Via: SIP/2.0/UDP 192.168.15.100:5061;branch=z9hG4bK-d87543-286e7e6c1c20685b-1--d87543-;rport Max-Forwards: 70 Contact: To: "9001" From: "Raj Jain";tag=6d1db119 Call-ID: ZGNjMWQ4NTBiN2FkYjVmZGY4ODFjODQ1MTUyNGZhN2U. CSeq: 1 INVITE Session-Expires: 95 Min-SE: 90 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO Content-Type: application/sdp Supported: timer User-Agent: X-Lite release 1011s stamp 41150 Content-Length: 424 v=0 o=- 3 2 IN IP4 192.168.15.100 s=CounterPath X-Lite 3.0 c=IN IP4 192.168.15.100 t=0 0 m=audio 5063 RTP/AVP 107 119 100 106 0 105 98 8 101 a=alt:1 1 : dx4ylbiQ +V3a5XJr 192.168.15.100 5063 a=fmtp:101 0-15 a=rtpmap:107 BV32/16000 a=rtpmap:119 BV32-FEC/16000 a=rtpmap:100 SPEEX/16000 a=rtpmap:106 SPEEX-FEC/16000 a=rtpmap:105 SPEEX-FEC/8000 a=rtpmap:98 iLBC/8000 a=rtpmap:101 telephone-event/8000 a=sendrecv <-------------> [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Header 0 [ 38]: INVITE sip:9001@192.168.15.101 SIP/2.0 [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Header 1 [ 92]: Via: SIP/2.0/UDP 192.168.15.100:5061;branch=z9hG4bK-d87543-286e7e6c1c20685b-1--d87543-;rport [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Header 3 [ 39]: Contact: [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Header 4 [ 35]: To: "9001" [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Header 5 [ 54]: From: "Raj Jain";tag=6d1db119 [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Header 6 [ 53]: Call-ID: ZGNjMWQ4NTBiN2FkYjVmZGY4ODFjODQ1MTUyNGZhN2U. [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Header 7 [ 14]: CSeq: 1 INVITE [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Header 8 [ 19]: Session-Expires: 95 [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Header 9 [ 10]: Min-SE: 90 [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Header 10 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Header 11 [ 29]: Content-Type: application/sdp [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Header 12 [ 16]: Supported: timer [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Header 13 [ 44]: User-Agent: X-Lite release 1011s stamp 41150 [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Header 14 [ 19]: Content-Length: 424 [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Header 15 [ 0]: [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Body 0 [ 3]: v=0 [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Body 1 [ 29]: o=- 3 2 IN IP4 192.168.15.100 [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Body 2 [ 24]: s=CounterPath X-Lite 3.0 [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Body 3 [ 23]: c=IN IP4 192.168.15.100 [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Body 4 [ 5]: t=0 0 [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Body 5 [ 51]: m=audio 5063 RTP/AVP 107 119 100 106 0 105 98 8 101 [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Body 6 [ 49]: a=alt:1 1 : dx4ylbiQ +V3a5XJr 192.168.15.100 5063 [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Body 7 [ 15]: a=fmtp:101 0-15 [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Body 8 [ 23]: a=rtpmap:107 BV32/16000 [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Body 9 [ 27]: a=rtpmap:119 BV32-FEC/16000 [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Body 10 [ 24]: a=rtpmap:100 SPEEX/16000 [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Body 11 [ 28]: a=rtpmap:106 SPEEX-FEC/16000 [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Body 12 [ 27]: a=rtpmap:105 SPEEX-FEC/8000 [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Body 13 [ 21]: a=rtpmap:98 iLBC/8000 [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Body 14 [ 33]: a=rtpmap:101 telephone-event/8000 [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Body 15 [ 10]: a=sendrecv [Mar 22 20:34:19] VERBOSE[12946] logger.c: --- (15 headers 16 lines) --- [Mar 22 20:34:19] DEBUG[12946] acl.c: Found IP address for this socket [Mar 22 20:34:19] VERBOSE[12946] logger.c: == Using SIP RTP CoS mark 5 [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Setting NAT on RTP to Off [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Allocating new SIP dialog for ZGNjMWQ4NTBiN2FkYjVmZGY4ODFjODQ1MTUyNGZhN2U. - INVITE (With RTP) [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Begin: parsing SIP "Supported: timer" [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Found SIP option: -timer- [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Matched SIP option: timer [Mar 22 20:34:19] VERBOSE[12946] logger.c: Sending to 192.168.15.100 : 5061 (NAT) [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Initializing initreq for method INVITE - callid ZGNjMWQ4NTBiN2FkYjVmZGY4ODFjODQ1MTUyNGZhN2U. [Mar 22 20:34:19] VERBOSE[12946] logger.c: Using INVITE request as basis request - ZGNjMWQ4NTBiN2FkYjVmZGY4ODFjODQ1MTUyNGZhN2U. [Mar 22 20:34:19] VERBOSE[12946] logger.c: Found user '9000' for '9000' [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Setting NAT on RTP to Off [Mar 22 20:34:19] VERBOSE[12946] logger.c: Found RTP audio format 107 [Mar 22 20:34:19] VERBOSE[12946] logger.c: Found RTP audio format 119 [Mar 22 20:34:19] VERBOSE[12946] logger.c: Found RTP audio format 100 [Mar 22 20:34:19] VERBOSE[12946] logger.c: Found RTP audio format 106 [Mar 22 20:34:19] VERBOSE[12946] logger.c: Found RTP audio format 0 [Mar 22 20:34:19] VERBOSE[12946] logger.c: Found RTP audio format 105 [Mar 22 20:34:19] VERBOSE[12946] logger.c: Found RTP audio format 98 [Mar 22 20:34:19] VERBOSE[12946] logger.c: Found RTP audio format 8 [Mar 22 20:34:19] VERBOSE[12946] logger.c: Found RTP audio format 101 [Mar 22 20:34:19] VERBOSE[12946] logger.c: Peer audio RTP is at port 192.168.15.100:5063 [Mar 22 20:34:19] VERBOSE[12946] logger.c: Got unsupported a:fmtp in SDP offer [Mar 22 20:34:19] VERBOSE[12946] logger.c: Found unknown media description format BV32 for ID 107 [Mar 22 20:34:19] VERBOSE[12946] logger.c: Found unknown media description format BV32-FEC for ID 119 [Mar 22 20:34:19] VERBOSE[12946] logger.c: Found audio description format SPEEX for ID 100 [Mar 22 20:34:19] VERBOSE[12946] logger.c: Found unknown media description format SPEEX-FEC for ID 106 [Mar 22 20:34:19] VERBOSE[12946] logger.c: Found unknown media description format SPEEX-FEC for ID 105 [Mar 22 20:34:19] VERBOSE[12946] logger.c: Found audio description format iLBC for ID 98 [Mar 22 20:34:19] VERBOSE[12946] logger.c: Found audio description format telephone-event for ID 101 [Mar 22 20:34:19] VERBOSE[12946] logger.c: Capabilities: us - 0x8000e (gsm|ulaw|alaw|h263), peer - audio=0x60c (ulaw|alaw|speex|ilbc)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0xc (ulaw|alaw) [Mar 22 20:34:19] VERBOSE[12946] logger.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Mar 22 20:34:19] VERBOSE[12946] logger.c: Peer audio RTP is at port 192.168.15.100:5063 [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: We're settling with these formats: 0xc (ulaw|alaw) [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Checking SIP call limits for device 9000 [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Updating call counter for incoming call [Mar 22 20:34:19] VERBOSE[12946] logger.c: Looking for 9001 in default (domain 192.168.15.101) [Mar 22 20:34:19] DEBUG[12946] frame.c: Could not find preferred codec - Going for the best codec [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: *** Our native formats are 0x4 (ulaw) [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: *** Joint capabilities are 0xc (ulaw|alaw) [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: *** Our capabilities are 0x8000e (gsm|ulaw|alaw|h263) [Mar 22 20:34:19] DEBUG[12946] frame.c: Could not find preferred codec - Going for the best codec [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: This channel will not be able to handle video. [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: build_route: Contact hop: [Mar 22 20:34:19] VERBOSE[12946] logger.c: list_route: hop: [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Incoming INVITE with 'timer' option enabled [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Session-Expires: 95 [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Received Min-SE: 90 [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Session timer started: 14 - ZGNjMWQ4NTBiN2FkYjVmZGY4ODFjODQ1MTUyNGZhN2U. [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: SIP/9000-09a1f860: New call is still down.... Trying... [Mar 22 20:34:19] VERBOSE[12946] logger.c: <--- Transmitting (no NAT) to 192.168.15.100:5061 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.15.100:5061;branch=z9hG4bK-d87543-286e7e6c1c20685b-1--d87543-;received=192.168.15.100;rport=5061 From: "Raj Jain";tag=6d1db119 To: "9001" Call-ID: ZGNjMWQ4NTBiN2FkYjVmZGY4ODFjODQ1MTUyNGZhN2U. CSeq: 1 INVITE User-Agent: Asterisk PBX SVN-trunk-r110578M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces, timer Require: timer Session-Expires: 95;refresher=uas Contact: Content-Length: 0 <------------> [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Trying to put 'SIP/2.0 10' onto UDP socket destined for 192.168.15.100 [Mar 22 20:34:19] DEBUG[12946] devicestate.c: Notification of state change to be queued on device/channel SIP/9000-09a1f860 [Mar 22 20:34:19] DEBUG[12946] devicestate.c: Notification of state change to be queued on device/channel SIP/9000 [Mar 22 20:34:19] DEBUG[12946] devicestate.c: No provider found, checking channel drivers for SIP - 9000-09a1f860 [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Checking device state for peer 9000-09a1f860 [Mar 22 20:34:19] DEBUG[12946] devicestate.c: Changing state for SIP/9000-09a1f860 - state 1 (Not in use) [Mar 22 20:34:19] DEBUG[12946] devicestate.c: No provider found, checking channel drivers for SIP - 9000 [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Checking device state for peer 9000 [Mar 22 20:34:19] DEBUG[12946] devicestate.c: Changing state for SIP/9000 - state 1 (Not in use) [Mar 22 20:34:19] DEBUG[12946] devicestate.c: No provider found, checking channel drivers for SIP - 9000 [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Checking device state for peer 9000 [Mar 22 20:34:19] DEBUG[12946] app_queue.c: Device 'SIP/9000-09a1f860' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Mar 22 20:34:19] DEBUG[12946] app_queue.c: Device 'SIP/9000' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Mar 22 20:34:19] DEBUG[12946] pbx.c: Launching 'Macro' [Mar 22 20:34:19] VERBOSE[12946] logger.c: -- Executing [9001@default:1] Macro("SIP/9000-09a1f860", "stdexten,9001,SIP/9001") in new stack [Mar 22 20:34:19] DEBUG[12946] pbx.c: Launching 'Dial' [Mar 22 20:34:19] VERBOSE[12946] logger.c: -- Executing [s@macro-stdexten:1] Dial("SIP/9000-09a1f860", "SIP/9001,20") in new stack [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Asked to create a SIP channel with formats: 0x4 (ulaw) [Mar 22 20:34:19] VERBOSE[12946] logger.c: == Using SIP RTP CoS mark 5 [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Setting NAT on RTP to Off [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: OBPROXY: Not applying OBproxy to this call [Mar 22 20:34:19] DEBUG[12946] acl.c: Found IP address for this socket [Mar 22 20:34:19] DEBUG[12946] frame.c: Could not find preferred codec - Going for the best codec [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: *** Our native formats are 0x4 (ulaw) [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: *** Joint capabilities are 0x4 (ulaw) [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: *** Our capabilities are 0x2 (gsm) [Mar 22 20:34:19] DEBUG[12946] frame.c: Could not find preferred codec - Going for the best codec [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: This channel will not be able to handle video. [Mar 22 20:34:19] DEBUG[12946] channel.c: Not copying variable MACRO_DEPTH. [Mar 22 20:34:19] DEBUG[12946] channel.c: Not copying variable ARG2. [Mar 22 20:34:19] DEBUG[12946] channel.c: Not copying variable ARG1. [Mar 22 20:34:19] DEBUG[12946] channel.c: Not copying variable MACRO_PRIORITY. [Mar 22 20:34:19] DEBUG[12946] channel.c: Not copying variable MACRO_CONTEXT. [Mar 22 20:34:19] DEBUG[12946] channel.c: Not copying variable MACRO_EXTEN. [Mar 22 20:34:19] DEBUG[12946] channel.c: Not copying variable SIPCALLID. [Mar 22 20:34:19] DEBUG[12946] channel.c: Not copying variable SIPDOMAIN. [Mar 22 20:34:19] DEBUG[12946] channel.c: Not copying variable SIPURI. [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Outgoing Call for [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Updating call counter for outgoing call [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Our T38 capability (0), joint T38 capability (0) [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: ** Our capability: 0x2 (gsm) Video flag: False Text flag: False [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: ** Our prefcodec: 0x4 (ulaw) [Mar 22 20:34:19] VERBOSE[12946] logger.c: Audio is at 192.168.15.101 port 10812 [Mar 22 20:34:19] VERBOSE[12946] logger.c: Adding codec 0x2 (gsm) to SDP [Mar 22 20:34:19] VERBOSE[12946] logger.c: Adding non-codec 0x1 (telephone-event) to SDP [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: -- Done with adding codecs to SDP [Mar 22 20:34:19] DEBUG[12946] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=32) [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Done building SDP. Settling with this capability: 0x2 (gsm) [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Initializing initreq for method INVITE - callid 45c44f5312d30224671649637e9caf9d@192.168.15.101 [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Header 0 [ 53]: INVITE sip:192.168.15.100:13769;transport=tcp SIP/2.0 [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Header 1 [ 65]: Via: SIP/2.0/TCP 192.168.15.101:5060;branch=z9hG4bK65a3ce83;rport [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Header 3 [ 50]: From: "A" ;tag=as731cd1ff [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Header 4 [ 44]: To: [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Header 5 [ 53]: Contact: [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Header 6 [ 56]: Call-ID: 45c44f5312d30224671649637e9caf9d@192.168.15.101 [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Header 7 [ 16]: CSeq: 102 INVITE [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Header 8 [ 43]: User-Agent: Asterisk PBX SVN-trunk-r110578M [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Header 9 [ 35]: Date: Sun, 23 Mar 2008 01:34:19 GMT [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Header 10 [ 66]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Header 11 [ 26]: Supported: replaces, timer [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Header 12 [ 29]: Content-Type: application/sdp [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Header 13 [ 19]: Content-Length: 277 [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Header 14 [ 0]: [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Body 0 [ 3]: v=0 [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Body 1 [ 50]: o=root 1709494258 1709494258 IN IP4 192.168.15.101 [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Body 2 [ 33]: s=Asterisk PBX SVN-trunk-r110578M [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Body 3 [ 23]: c=IN IP4 192.168.15.101 [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Body 4 [ 5]: t=0 0 [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Body 5 [ 27]: m=audio 10812 RTP/AVP 3 101 [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Body 6 [ 19]: a=rtpmap:3 GSM/8000 [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Body 7 [ 33]: a=rtpmap:101 telephone-event/8000 [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Body 8 [ 15]: a=fmtp:101 0-16 [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Body 9 [ 25]: a=silenceSupp:off - - - - [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Body 10 [ 10]: a=ptime:20 [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Body 11 [ 10]: a=sendrecv [Mar 22 20:34:19] VERBOSE[12946] logger.c: Reliably Transmitting (no NAT) to 192.168.15.100:13769: INVITE sip:192.168.15.100:13769;transport=tcp SIP/2.0 Via: SIP/2.0/TCP 192.168.15.101:5060;branch=z9hG4bK65a3ce83;rport Max-Forwards: 70 From: "A" ;tag=as731cd1ff To: Contact: Call-ID: 45c44f5312d30224671649637e9caf9d@192.168.15.101 CSeq: 102 INVITE User-Agent: Asterisk PBX SVN-trunk-r110578M Date: Sun, 23 Mar 2008 01:34:19 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces, timer Content-Type: application/sdp Content-Length: 277 v=0 o=root 1709494258 1709494258 IN IP4 192.168.15.101 s=Asterisk PBX SVN-trunk-r110578M c=IN IP4 192.168.15.101 t=0 0 m=audio 10812 RTP/AVP 3 101 a=rtpmap:3 GSM/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [Mar 22 20:34:19] DEBUG[12946] chan_sip.c: Trying to put 'INVITE sip' onto TCP socket destined for 192.168.15.100 [Mar 22 20:34:19] DEBUG[12946] sched.c: Attempted to delete nonexistent schedule entry -1! [Mar 22 20:34:19] VERBOSE[12946] logger.c: -- Called 9001 [Mar 22 20:34:34] DEBUG[12946] chan_sip.c: Header 0 [ 35]: REGISTER sip:192.168.15.101 SIP/2.0 [Mar 22 20:34:34] DEBUG[12946] chan_sip.c: Header 1 [ 37]: Via: SIP/2.0/TCP 192.168.15.100:13769 [Mar 22 20:34:34] DEBUG[12946] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Mar 22 20:34:34] DEBUG[12946] chan_sip.c: Header 3 [ 84]: From: ;tag=abcdb2676f974344b2d2350b2f1f7743;epid=7f6a19fb3a [Mar 22 20:34:34] DEBUG[12946] chan_sip.c: Header 4 [ 29]: To: [Mar 22 20:34:34] DEBUG[12946] chan_sip.c: Header 5 [ 41]: Call-ID: f59a1257c0684f8f982cd60f6effb625 [Mar 22 20:34:34] DEBUG[12946] chan_sip.c: Header 6 [ 16]: CSeq: 2 REGISTER [Mar 22 20:34:34] DEBUG[12946] chan_sip.c: Header 7 [158]: Contact: ;methods="INVITE, MESSAGE, INFO, SUBSCRIBE, OPTIONS, BYE, CANCEL, NOTIFY, ACK, REFER, BENOTIFY";proxy=replace [Mar 22 20:34:34] DEBUG[12946] chan_sip.c: Header 8 [ 45]: User-Agent: RTC/1.3.5470 (Messenger 5.1.0701) [Mar 22 20:34:34] DEBUG[12946] chan_sip.c: Header 9 [ 50]: Supported: com.microsoft.msrtc.presence, adhoclist [Mar 22 20:34:34] DEBUG[12946] chan_sip.c: Header 10 [ 30]: ms-keep-alive: UAC;hop-hop=yes [Mar 22 20:34:34] DEBUG[12946] chan_sip.c: Header 11 [ 19]: Event: registration [Mar 22 20:34:34] DEBUG[12946] chan_sip.c: Header 12 [ 22]: Allow-Events: presence [Mar 22 20:34:34] DEBUG[12946] chan_sip.c: Header 13 [ 17]: Content-Length: 0 [Mar 22 20:34:34] DEBUG[12946] chan_sip.c: Header 14 [ 0]: [Mar 22 20:34:34] VERBOSE[12946] logger.c: <--- SIP read from TCP://192.168.15.100:3801 ---> REGISTER sip:192.168.15.101 SIP/2.0 Via: SIP/2.0/TCP 192.168.15.100:13769 Max-Forwards: 70 From: ;tag=abcdb2676f974344b2d2350b2f1f7743;epid=7f6a19fb3a To: Call-ID: f59a1257c0684f8f982cd60f6effb625 CSeq: 2 REGISTER Contact: ;methods="INVITE, MESSAGE, INFO, SUBSCRIBE, OPTIONS, BYE, CANCEL, NOTIFY, ACK, REFER, BENOTIFY";proxy=replace User-Agent: RTC/1.3.5470 (Messenger 5.1.0701) Supported: com.microsoft.msrtc.presence, adhoclist ms-keep-alive: UAC;hop-hop=yes Event: registration Allow-Events: presence Content-Length: 0 <-------------> [Mar 22 20:34:34] DEBUG[12946] chan_sip.c: Header 0 [ 35]: REGISTER sip:192.168.15.101 SIP/2.0 [Mar 22 20:34:34] DEBUG[12946] chan_sip.c: Header 1 [ 37]: Via: SIP/2.0/TCP 192.168.15.100:13769 [Mar 22 20:34:34] DEBUG[12946] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Mar 22 20:34:34] DEBUG[12946] chan_sip.c: Header 3 [ 84]: From: ;tag=abcdb2676f974344b2d2350b2f1f7743;epid=7f6a19fb3a [Mar 22 20:34:34] DEBUG[12946] chan_sip.c: Header 4 [ 29]: To: [Mar 22 20:34:34] DEBUG[12946] chan_sip.c: Header 5 [ 41]: Call-ID: f59a1257c0684f8f982cd60f6effb625 [Mar 22 20:34:34] DEBUG[12946] chan_sip.c: Header 6 [ 16]: CSeq: 2 REGISTER [Mar 22 20:34:34] DEBUG[12946] chan_sip.c: Header 7 [158]: Contact: ;methods="INVITE, MESSAGE, INFO, SUBSCRIBE, OPTIONS, BYE, CANCEL, NOTIFY, ACK, REFER, BENOTIFY";proxy=replace [Mar 22 20:34:34] DEBUG[12946] chan_sip.c: Header 8 [ 45]: User-Agent: RTC/1.3.5470 (Messenger 5.1.0701) [Mar 22 20:34:34] DEBUG[12946] chan_sip.c: Header 9 [ 50]: Supported: com.microsoft.msrtc.presence, adhoclist [Mar 22 20:34:34] DEBUG[12946] chan_sip.c: Header 10 [ 30]: ms-keep-alive: UAC;hop-hop=yes [Mar 22 20:34:34] DEBUG[12946] chan_sip.c: Header 11 [ 19]: Event: registration [Mar 22 20:34:34] DEBUG[12946] chan_sip.c: Header 12 [ 22]: Allow-Events: presence [Mar 22 20:34:34] DEBUG[12946] chan_sip.c: Header 13 [ 17]: Content-Length: 0 [Mar 22 20:34:34] DEBUG[12946] chan_sip.c: Header 14 [ 0]: [Mar 22 20:34:34] VERBOSE[12946] logger.c: --- (14 headers 0 lines) --- [Mar 22 20:34:34] DEBUG[12946] chan_sip.c: = No match Their Call ID: 45c44f5312d30224671649637e9caf9d@192.168.15.101 Their Tag Our tag: as731cd1ff [Mar 22 20:34:34] DEBUG[12946] chan_sip.c: = No match Their Call ID: ZGNjMWQ4NTBiN2FkYjVmZGY4ODFjODQ1MTUyNGZhN2U. Their Tag 6d1db119 Our tag: as794802b5 [Mar 22 20:34:34] DEBUG[12946] acl.c: Found IP address for this socket [Mar 22 20:34:34] DEBUG[12946] chan_sip.c: Allocating new SIP dialog for f59a1257c0684f8f982cd60f6effb625 - REGISTER (No RTP) [Mar 22 20:34:34] DEBUG[12946] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [Mar 22 20:34:34] DEBUG[12946] chan_sip.c: Initializing initreq for method REGISTER - callid f59a1257c0684f8f982cd60f6effb625 [Mar 22 20:34:34] VERBOSE[12946] logger.c: Sending to 192.168.15.100 : 13769 (no NAT) [Mar 22 20:34:34] VERBOSE[12946] logger.c: <--- Transmitting (no NAT) to 192.168.15.100:13769 ---> SIP/2.0 200 OK Via: SIP/2.0/TCP 192.168.15.100:13769;received=192.168.15.100 From: ;tag=abcdb2676f974344b2d2350b2f1f7743;epid=7f6a19fb3a To: ;tag=as42a63db1 Call-ID: f59a1257c0684f8f982cd60f6effb625 CSeq: 2 REGISTER User-Agent: Asterisk PBX SVN-trunk-r110578M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces, timer Expires: 120 Contact: ;expires=120 Date: Sun, 23 Mar 2008 01:34:34 GMT Content-Length: 0 <------------> [Mar 22 20:34:34] DEBUG[12946] chan_sip.c: Trying to put 'SIP/2.0 20' onto TCP socket destined for 192.168.15.100 [Mar 22 20:34:34] DEBUG[12946] devicestate.c: Notification of state change to be queued on device/channel SIP/9001 [Mar 22 20:34:34] VERBOSE[12946] logger.c: Scheduling destruction of SIP dialog 'f59a1257c0684f8f982cd60f6effb625' in 32000 ms (Method: REGISTER) [Mar 22 20:34:34] DEBUG[12946] devicestate.c: No provider found, checking channel drivers for SIP - 9001 [Mar 22 20:34:34] DEBUG[12946] chan_sip.c: Checking device state for peer 9001 [Mar 22 20:34:34] DEBUG[12946] devicestate.c: Changing state for SIP/9001 - state 1 (Not in use) [Mar 22 20:34:34] DEBUG[12946] devicestate.c: No provider found, checking channel drivers for SIP - 9001 [Mar 22 20:34:34] DEBUG[12946] chan_sip.c: Checking device state for peer 9001 [Mar 22 20:34:34] DEBUG[12946] app_queue.c: Device 'SIP/9001' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Mar 22 20:34:39] VERBOSE[12946] logger.c: -- Nobody picked up in 20000 ms [Mar 22 20:34:39] DEBUG[12946] rtp.c: Channel '' has no RTP, not doing anything [Mar 22 20:34:39] DEBUG[12946] channel.c: Hanging up channel 'SIP/9001-09a22d30' [Mar 22 20:34:39] DEBUG[12946] chan_sip.c: Hangup call SIP/9001-09a22d30, SIP callid 45c44f5312d30224671649637e9caf9d@192.168.15.101 [Mar 22 20:34:39] DEBUG[12946] chan_sip.c: Hanging up channel in state Down (not UP) [Mar 22 20:34:39] VERBOSE[12946] logger.c: Reliably Transmitting (no NAT) to 192.168.15.100:13769: CANCEL sip:192.168.15.100:13769;transport=tcp SIP/2.0 Via: SIP/2.0/TCP 192.168.15.101:5060;branch=z9hG4bK65a3ce83;rport Max-Forwards: 70 From: "A" ;tag=as731cd1ff To: Call-ID: 45c44f5312d30224671649637e9caf9d@192.168.15.101 CSeq: 102 CANCEL User-Agent: Asterisk PBX SVN-trunk-r110578M Content-Length: 0 --- [Mar 22 20:34:39] DEBUG[12946] chan_sip.c: Trying to put 'CANCEL sip' onto TCP socket destined for 192.168.15.100 [Mar 22 20:34:39] VERBOSE[12946] logger.c: Scheduling destruction of SIP dialog '45c44f5312d30224671649637e9caf9d@192.168.15.101' in 32000 ms (Method: INVITE) [Mar 22 20:34:39] DEBUG[12946] chan_sip.c: Updating call counter for outgoing call [Mar 22 20:34:39] DEBUG[12946] devicestate.c: Notification of state change to be queued on device/channel SIP/9001-09a22d30 [Mar 22 20:34:39] DEBUG[12946] devicestate.c: Notification of state change to be queued on device/channel SIP/9001 [Mar 22 20:34:39] DEBUG[12946] app_dial.c: Exiting with DIALSTATUS=NOANSWER. [Mar 22 20:34:39] DEBUG[12946] app_macro.c: Executed application: Dial [Mar 22 20:34:39] DEBUG[12946] pbx.c: Launching 'Goto' [Mar 22 20:34:39] VERBOSE[12946] logger.c: -- Executing [s@macro-stdexten:2] Goto("SIP/9000-09a1f860", "s-NOANSWER,1") in new stack [Mar 22 20:34:39] VERBOSE[12946] logger.c: -- Goto (macro-stdexten,s-NOANSWER,1) [Mar 22 20:34:39] DEBUG[12946] app_macro.c: Executed application: Goto [Mar 22 20:34:39] DEBUG[12946] pbx.c: Launching 'VoiceMail' [Mar 22 20:34:39] VERBOSE[12946] logger.c: -- Executing [s-NOANSWER@macro-stdexten:1] VoiceMail("SIP/9000-09a1f860", "9001,u") in new stack [Mar 22 20:34:39] DEBUG[12946] devicestate.c: Notification of state change to be queued on device/channel SIP/9000-09a1f860 [Mar 22 20:34:39] DEBUG[12946] devicestate.c: Notification of state change to be queued on device/channel SIP/9000 [Mar 22 20:34:39] DEBUG[12946] chan_sip.c: SIP answering channel: SIP/9000-09a1f860 [Mar 22 20:34:39] DEBUG[12946] chan_sip.c: Setting framing from config on incoming call [Mar 22 20:34:39] DEBUG[12946] chan_sip.c: ** Our capability: 0xc (ulaw|alaw) Video flag: True Text flag: True [Mar 22 20:34:39] DEBUG[12946] chan_sip.c: ** Our prefcodec: 0x0 (nothing) [Mar 22 20:34:39] VERBOSE[12946] logger.c: Audio is at 192.168.15.101 port 13292 [Mar 22 20:34:39] VERBOSE[12946] logger.c: Adding codec 0x4 (ulaw) to SDP [Mar 22 20:34:39] VERBOSE[12946] logger.c: Adding codec 0x8 (alaw) to SDP [Mar 22 20:34:39] VERBOSE[12946] logger.c: Adding non-codec 0x1 (telephone-event) to SDP [Mar 22 20:34:39] DEBUG[12946] chan_sip.c: -- Done with adding codecs to SDP [Mar 22 20:34:39] DEBUG[12946] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) [Mar 22 20:34:39] DEBUG[12946] chan_sip.c: Done building SDP. Settling with this capability: 0xc (ulaw|alaw) [Mar 22 20:34:39] VERBOSE[12946] logger.c: <--- Reliably Transmitting (no NAT) to 192.168.15.100:5061 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.15.100:5061;branch=z9hG4bK-d87543-286e7e6c1c20685b-1--d87543-;received=192.168.15.100;rport=5061 From: "Raj Jain";tag=6d1db119 To: "9001";tag=as794802b5 Call-ID: ZGNjMWQ4NTBiN2FkYjVmZGY4ODFjODQ1MTUyNGZhN2U. CSeq: 1 INVITE User-Agent: Asterisk PBX SVN-trunk-r110578M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces, timer Require: timer Session-Expires: 95;refresher=uas Contact: Content-Type: application/sdp Content-Length: 300 v=0 o=root 797036654 797036654 IN IP4 192.168.15.101 s=Asterisk PBX SVN-trunk-r110578M c=IN IP4 192.168.15.101 t=0 0 m=audio 13292 RTP/AVP 0 8 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv <------------> [Mar 22 20:34:39] DEBUG[12946] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #19 [Mar 22 20:34:39] DEBUG[12946] chan_sip.c: Trying to put 'SIP/2.0 20' onto UDP socket destined for 192.168.15.100 [Mar 22 20:34:39] DEBUG[12946] devicestate.c: No provider found, checking channel drivers for SIP - 9001-09a22d30 [Mar 22 20:34:39] DEBUG[12946] chan_sip.c: Checking device state for peer 9001-09a22d30 [Mar 22 20:34:39] DEBUG[12946] devicestate.c: Changing state for SIP/9001-09a22d30 - state 1 (Not in use) [Mar 22 20:34:39] DEBUG[12946] devicestate.c: No provider found, checking channel drivers for SIP - 9001 [Mar 22 20:34:39] DEBUG[12946] chan_sip.c: Checking device state for peer 9001 [Mar 22 20:34:39] DEBUG[12946] devicestate.c: Changing state for SIP/9001 - state 1 (Not in use) [Mar 22 20:34:39] DEBUG[12946] devicestate.c: No provider found, checking channel drivers for SIP - 9000-09a1f860 [Mar 22 20:34:39] DEBUG[12946] chan_sip.c: Checking device state for peer 9000-09a1f860 [Mar 22 20:34:39] DEBUG[12946] devicestate.c: Changing state for SIP/9000-09a1f860 - state 1 (Not in use) [Mar 22 20:34:39] DEBUG[12946] devicestate.c: No provider found, checking channel drivers for SIP - 9000 [Mar 22 20:34:39] DEBUG[12946] chan_sip.c: Checking device state for peer 9000 [Mar 22 20:34:39] DEBUG[12946] devicestate.c: Changing state for SIP/9000 - state 1 (Not in use) [Mar 22 20:34:39] DEBUG[12946] devicestate.c: No provider found, checking channel drivers for SIP - 9001 [Mar 22 20:34:39] DEBUG[12946] chan_sip.c: Checking device state for peer 9001 [Mar 22 20:34:39] DEBUG[12946] devicestate.c: No provider found, checking channel drivers for SIP - 9000 [Mar 22 20:34:39] DEBUG[12946] chan_sip.c: Checking device state for peer 9000 [Mar 22 20:34:39] DEBUG[12946] app_queue.c: Device 'SIP/9001-09a22d30' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Mar 22 20:34:39] DEBUG[12946] app_queue.c: Device 'SIP/9001' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Mar 22 20:34:39] DEBUG[12946] app_queue.c: Device 'SIP/9000-09a1f860' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Mar 22 20:34:39] DEBUG[12946] app_queue.c: Device 'SIP/9000' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Mar 22 20:34:39] DEBUG[12946] rtp.c: Got RTCP report of 132 bytes [Mar 22 20:34:39] VERBOSE[12946] logger.c: <--- SIP read from UDP://192.168.15.100:5061 ---> ACK sip:9001@192.168.15.101 SIP/2.0 Via: SIP/2.0/UDP 192.168.15.100:5061;branch=z9hG4bK-d87543-dc17be431a717008-1--d87543-;rport Max-Forwards: 70 Contact: To: "9001";tag=as794802b5 From: "Raj Jain";tag=6d1db119 Call-ID: ZGNjMWQ4NTBiN2FkYjVmZGY4ODFjODQ1MTUyNGZhN2U. CSeq: 1 ACK User-Agent: X-Lite release 1011s stamp 41150 Content-Length: 0 <-------------> [Mar 22 20:34:39] DEBUG[12946] chan_sip.c: Header 0 [ 35]: ACK sip:9001@192.168.15.101 SIP/2.0 [Mar 22 20:34:39] DEBUG[12946] chan_sip.c: Header 1 [ 92]: Via: SIP/2.0/UDP 192.168.15.100:5061;branch=z9hG4bK-d87543-dc17be431a717008-1--d87543-;rport [Mar 22 20:34:39] DEBUG[12946] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Mar 22 20:34:39] DEBUG[12946] chan_sip.c: Header 3 [ 39]: Contact: [Mar 22 20:34:39] DEBUG[12946] chan_sip.c: Header 4 [ 50]: To: "9001";tag=as794802b5 [Mar 22 20:34:39] DEBUG[12946] chan_sip.c: Header 5 [ 54]: From: "Raj Jain";tag=6d1db119 [Mar 22 20:34:39] DEBUG[12946] chan_sip.c: Header 6 [ 53]: Call-ID: ZGNjMWQ4NTBiN2FkYjVmZGY4ODFjODQ1MTUyNGZhN2U. [Mar 22 20:34:39] DEBUG[12946] chan_sip.c: Header 7 [ 11]: CSeq: 1 ACK [Mar 22 20:34:39] DEBUG[12946] chan_sip.c: Header 8 [ 44]: User-Agent: X-Lite release 1011s stamp 41150 [Mar 22 20:34:39] DEBUG[12946] chan_sip.c: Header 9 [ 17]: Content-Length: 0 [Mar 22 20:34:39] DEBUG[12946] chan_sip.c: Header 10 [ 0]: [Mar 22 20:34:39] VERBOSE[12946] logger.c: --- (10 headers 0 lines) --- [Mar 22 20:34:39] DEBUG[12946] chan_sip.c: = No match Their Call ID: f59a1257c0684f8f982cd60f6effb625 Their Tag abcdb2676f974344b2d2350b2f1f7743 Our tag: as42a63db1 [Mar 22 20:34:39] DEBUG[12946] chan_sip.c: = No match Their Call ID: 45c44f5312d30224671649637e9caf9d@192.168.15.101 Their Tag Our tag: as731cd1ff [Mar 22 20:34:39] DEBUG[12946] chan_sip.c: = Found Their Call ID: ZGNjMWQ4NTBiN2FkYjVmZGY4ODFjODQ1MTUyNGZhN2U. Their Tag 6d1db119 Our tag: as794802b5 [Mar 22 20:34:39] DEBUG[12946] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Mar 22 20:34:39] DEBUG[12946] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #19 [Mar 22 20:34:39] DEBUG[12946] chan_sip.c: Stopping retransmission on 'ZGNjMWQ4NTBiN2FkYjVmZGY4ODFjODQ1MTUyNGZhN2U.' of Response 1: Match Found [Mar 22 20:34:39] DEBUG[12946] app_voicemail.c: Before find_user [Mar 22 20:34:39] DEBUG[12946] app_voicemail.c: /var/spool/asterisk/voicemail/default/9001/unavail doesn't exist, doing what we can [Mar 22 20:34:39] DEBUG[12946] channel.c: Set channel SIP/9000-09a1f860 to write format gsm [Mar 22 20:34:39] DEBUG[12946] rtp.c: Ooh, format changed from unknown to ulaw [Mar 22 20:34:39] DEBUG[12946] rtp.c: Created smoother: format: 4 ms: 20 len: 160 [Mar 22 20:34:39] DEBUG[12946] channel.c: Scheduling timer at 160 sample intervals [Mar 22 20:34:39] VERBOSE[12946] logger.c: -- Playing 'vm-theperson.gsm' (language 'en') [Mar 22 20:34:40] DEBUG[12946] chan_sip.c: SIP Registry 192.168.15.101: refcount now 2 [Mar 22 20:34:40] NOTICE[12946] chan_sip.c: -- Re-registration for asterisk@192.168.15.101 [Mar 22 20:34:40] VERBOSE[12946] logger.c: > doing dnsmgr_lookup for '192.168.15.101' [Mar 22 20:34:40] DEBUG[12946] chan_sip.c: Allocating new SIP dialog for 1f7df6865c4ae5bd64453a264955e807@127.0.0.1 - REGISTER (No RTP) [Mar 22 20:34:40] DEBUG[12946] chan_sip.c: OBPROXY: Not applying OBproxy to this call [Mar 22 20:34:40] DEBUG[12946] chan_sip.c: OBPROXY: Not applying OBproxy to this call [Mar 22 20:34:41] DEBUG[12946] chan_sip.c: IP lookup for hostname=192.168.15.101, using dnsmgr resolved to 192.168.15.101... [Mar 22 20:34:41] DEBUG[12946] chan_sip.c: SIP Registry 192.168.15.101: refcount now 3 [Mar 22 20:34:41] DEBUG[12946] acl.c: Found IP address for this socket [Mar 22 20:34:41] DEBUG[12946] chan_sip.c: Scheduled a registration timeout for 192.168.15.101 id #21 [Mar 22 20:34:41] DEBUG[12946] chan_sip.c: Initializing initreq for method REGISTER - callid 1f7df6865c4ae5bd64453a264955e807@127.0.0.1 [Mar 22 20:34:41] DEBUG[12946] chan_sip.c: Header 0 [ 40]: REGISTER sip:192.168.15.101:5070 SIP/2.0 [Mar 22 20:34:41] DEBUG[12946] chan_sip.c: Header 1 [ 65]: Via: SIP/2.0/UDP 192.168.15.101:5060;branch=z9hG4bK56413cf4;rport [Mar 22 20:34:41] DEBUG[12946] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Mar 22 20:34:41] DEBUG[12946] chan_sip.c: Header 3 [ 50]: From: ;tag=as3bf4dd36 [Mar 22 20:34:41] DEBUG[12946] chan_sip.c: Header 4 [ 33]: To: [Mar 22 20:34:41] DEBUG[12946] chan_sip.c: Header 5 [ 51]: Call-ID: 1f7df6865c4ae5bd64453a264955e807@127.0.0.1 [Mar 22 20:34:41] DEBUG[12946] chan_sip.c: Header 6 [ 18]: CSeq: 103 REGISTER [Mar 22 20:34:41] DEBUG[12946] chan_sip.c: Header 7 [ 43]: User-Agent: Asterisk PBX SVN-trunk-r110578M [Mar 22 20:34:41] DEBUG[12946] chan_sip.c: Header 8 [ 12]: Expires: 120 [Mar 22 20:34:41] DEBUG[12946] chan_sip.c: Header 9 [ 36]: Contact: [Mar 22 20:34:41] DEBUG[12946] chan_sip.c: Header 10 [ 19]: Event: registration [Mar 22 20:34:41] DEBUG[12946] chan_sip.c: Header 11 [ 17]: Content-Length: 0 [Mar 22 20:34:41] DEBUG[12946] chan_sip.c: Header 12 [ 2]: Y [Mar 22 20:34:41] VERBOSE[12946] logger.c: REGISTER 13 headers, 0 lines [Mar 22 20:34:41] DEBUG[12946] chan_sip.c: REGISTER attempt 1 to asterisk@192.168.15.101 [Mar 22 20:34:41] VERBOSE[12946] logger.c: Reliably Transmitting (no NAT) to 192.168.15.101:5070: REGISTER sip:192.168.15.101:5070 SIP/2.0 Via: SIP/2.0/UDP 192.168.15.101:5060;branch=z9hG4bK56413cf4;rport Max-Forwards: 70 From: ;tag=as3bf4dd36 To: Call-ID: 1f7df6865c4ae5bd64453a264955e807@127.0.0.1 CSeq: 103 REGISTER User-Agent: Asterisk PBX SVN-trunk-r110578M Expires: 120 Contact: Event: registration Content-Length: 0 --- [Mar 22 20:34:41] DEBUG[12946] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #22 [Mar 22 20:34:41] DEBUG[12946] chan_sip.c: Trying to put 'REGISTER s' onto UDP socket destined for 192.168.15.101 [Mar 22 20:34:41] DEBUG[12946] chan_sip.c: SIP Registry 192.168.15.101: refcount now 2 [Mar 22 20:34:41] VERBOSE[12946] logger.c: <--- SIP read from UDP://192.168.15.101:5070 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.15.101:5060;branch=z9hG4bK56413cf4;rport=5060 From: ;tag=as3bf4dd36 To: ;tag=ee79d8f7133d29a3d14d6af0c7745c41.0f44 Call-ID: 1f7df6865c4ae5bd64453a264955e807@127.0.0.1 CSeq: 103 REGISTER Contact: ;expires=120 Server: OpenSER (1.3.0-notls (i386/linux)) Content-Length: 0 <-------------> [Mar 22 20:34:41] DEBUG[12946] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Mar 22 20:34:41] DEBUG[12946] chan_sip.c: Header 1 [ 70]: Via: SIP/2.0/UDP 192.168.15.101:5060;branch=z9hG4bK56413cf4;rport=5060 [Mar 22 20:34:41] DEBUG[12946] chan_sip.c: Header 2 [ 50]: From: ;tag=as3bf4dd36 [Mar 22 20:34:41] DEBUG[12946] chan_sip.c: Header 3 [ 75]: To: ;tag=ee79d8f7133d29a3d14d6af0c7745c41.0f44 [Mar 22 20:34:41] DEBUG[12946] chan_sip.c: Header 4 [ 51]: Call-ID: 1f7df6865c4ae5bd64453a264955e807@127.0.0.1 [Mar 22 20:34:41] DEBUG[12946] chan_sip.c: Header 5 [ 18]: CSeq: 103 REGISTER [Mar 22 20:34:41] DEBUG[12946] chan_sip.c: Header 6 [ 48]: Contact: ;expires=120 [Mar 22 20:34:41] DEBUG[12946] chan_sip.c: Header 7 [ 42]: Server: OpenSER (1.3.0-notls (i386/linux)) [Mar 22 20:34:41] DEBUG[12946] chan_sip.c: Header 8 [ 17]: Content-Length: 0 [Mar 22 20:34:41] DEBUG[12946] chan_sip.c: Header 9 [ 0]: [Mar 22 20:34:41] VERBOSE[12946] logger.c: --- (9 headers 0 lines) --- [Mar 22 20:34:41] DEBUG[12946] chan_sip.c: = Found Their Call ID: 1f7df6865c4ae5bd64453a264955e807@127.0.0.1 Their Tag Our tag: as3bf4dd36 [Mar 22 20:34:41] DEBUG[12946] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #22 [Mar 22 20:34:41] DEBUG[12946] chan_sip.c: Stopping retransmission on '1f7df6865c4ae5bd64453a264955e807@127.0.0.1' of Request 103: Match Found [Mar 22 20:34:41] DEBUG[12946] chan_sip.c: Registration successful [Mar 22 20:34:41] DEBUG[12946] chan_sip.c: Cancelling timeout 21 [Mar 22 20:34:41] VERBOSE[12946] logger.c: Scheduling destruction of SIP dialog '1f7df6865c4ae5bd64453a264955e807@127.0.0.1' in 32000 ms (Method: REGISTER) [Mar 22 20:34:41] NOTICE[12946] chan_sip.c: Outbound Registration: Expiry for 192.168.15.101 is 120 sec (Scheduling reregistration in 105 s) [Mar 22 20:34:41] DEBUG[12946] chan_sip.c: SIP Registry 192.168.15.101: refcount now 1 [Mar 22 20:34:41] DEBUG[12946] channel.c: Scheduling timer at 0 sample intervals [Mar 22 20:34:41] DEBUG[12946] channel.c: Scheduling timer at 0 sample intervals [Mar 22 20:34:41] DEBUG[12946] channel.c: Set channel SIP/9000-09a1f860 to write format ulaw [Mar 22 20:34:41] DEBUG[12946] channel.c: Set channel SIP/9000-09a1f860 to write format gsm [Mar 22 20:34:41] DEBUG[12946] channel.c: Scheduling timer at 160 sample intervals [Mar 22 20:34:41] VERBOSE[12946] logger.c: -- Playing 'digits/9.gsm' (language 'en') [Mar 22 20:34:42] DEBUG[12946] channel.c: Scheduling timer at 0 sample intervals [Mar 22 20:34:42] DEBUG[12946] channel.c: Scheduling timer at 0 sample intervals [Mar 22 20:34:42] DEBUG[12946] channel.c: Set channel SIP/9000-09a1f860 to write format ulaw [Mar 22 20:34:42] DEBUG[12946] channel.c: Set channel SIP/9000-09a1f860 to write format gsm [Mar 22 20:34:42] DEBUG[12946] channel.c: Scheduling timer at 160 sample intervals [Mar 22 20:34:42] VERBOSE[12946] logger.c: -- Playing 'digits/0.gsm' (language 'en') [Mar 22 20:34:42] DEBUG[12946] rtp.c: Got RTCP report of 176 bytes [Mar 22 20:34:43] DEBUG[12946] channel.c: Scheduling timer at 0 sample intervals [Mar 22 20:34:43] DEBUG[12946] channel.c: Scheduling timer at 0 sample intervals [Mar 22 20:34:43] DEBUG[12946] channel.c: Set channel SIP/9000-09a1f860 to write format ulaw [Mar 22 20:34:43] DEBUG[12946] channel.c: Set channel SIP/9000-09a1f860 to write format gsm [Mar 22 20:34:43] DEBUG[12946] channel.c: Scheduling timer at 160 sample intervals [Mar 22 20:34:43] VERBOSE[12946] logger.c: -- Playing 'digits/0.gsm' (language 'en') [Mar 22 20:34:43] DEBUG[12946] channel.c: Scheduling timer at 0 sample intervals [Mar 22 20:34:43] DEBUG[12946] channel.c: Scheduling timer at 0 sample intervals [Mar 22 20:34:43] DEBUG[12946] channel.c: Set channel SIP/9000-09a1f860 to write format ulaw [Mar 22 20:34:43] DEBUG[12946] channel.c: Set channel SIP/9000-09a1f860 to write format gsm [Mar 22 20:34:43] DEBUG[12946] channel.c: Scheduling timer at 160 sample intervals [Mar 22 20:34:43] VERBOSE[12946] logger.c: -- Playing 'digits/1.gsm' (language 'en') [Mar 22 20:34:44] DEBUG[12946] channel.c: Scheduling timer at 0 sample intervals [Mar 22 20:34:44] DEBUG[12946] channel.c: Scheduling timer at 0 sample intervals [Mar 22 20:34:44] DEBUG[12946] channel.c: Set channel SIP/9000-09a1f860 to write format ulaw [Mar 22 20:34:44] DEBUG[12946] channel.c: Set channel SIP/9000-09a1f860 to write format gsm [Mar 22 20:34:44] DEBUG[12946] channel.c: Scheduling timer at 160 sample intervals [Mar 22 20:34:44] VERBOSE[12946] logger.c: -- Playing 'vm-isunavail.gsm' (language 'en') [Mar 22 20:34:45] DEBUG[12946] channel.c: Scheduling timer at 0 sample intervals [Mar 22 20:34:45] DEBUG[12946] channel.c: Scheduling timer at 0 sample intervals [Mar 22 20:34:45] DEBUG[12946] channel.c: Set channel SIP/9000-09a1f860 to write format ulaw [Mar 22 20:34:45] DEBUG[12946] channel.c: Set channel SIP/9000-09a1f860 to write format gsm [Mar 22 20:34:45] DEBUG[12946] channel.c: Scheduling timer at 160 sample intervals [Mar 22 20:34:45] VERBOSE[12946] logger.c: -- Playing 'vm-intro.gsm' (language 'en') [Mar 22 20:34:46] DEBUG[12946] rtp.c: Got RTCP report of 176 bytes [Mar 22 20:34:49] DEBUG[12946] rtp.c: Got RTCP report of 176 bytes [Mar 22 20:34:51] DEBUG[12946] channel.c: Scheduling timer at 0 sample intervals [Mar 22 20:34:51] DEBUG[12946] channel.c: Scheduling timer at 0 sample intervals [Mar 22 20:34:51] DEBUG[12946] channel.c: Set channel SIP/9000-09a1f860 to write format ulaw [Mar 22 20:34:51] DEBUG[12946] app.c: Locked path '/var/spool/asterisk/voicemail/default/9001/INBOX' [Mar 22 20:34:51] DEBUG[12946] app.c: Unlocked path '/var/spool/asterisk/voicemail/default/9001/INBOX' [Mar 22 20:34:51] DEBUG[12946] channel.c: Set channel SIP/9000-09a1f860 to write format gsm [Mar 22 20:34:51] DEBUG[12946] channel.c: Scheduling timer at 160 sample intervals [Mar 22 20:34:51] DEBUG[12946] channel.c: Scheduling timer at 0 sample intervals [Mar 22 20:34:51] DEBUG[12946] channel.c: Scheduling timer at 0 sample intervals [Mar 22 20:34:51] DEBUG[12946] channel.c: Set channel SIP/9000-09a1f860 to write format ulaw [Mar 22 20:34:51] DEBUG[12946] app.c: play_and_record: , /var/spool/asterisk/voicemail/default/9001/tmp/lwgXxl, 'wav49|gsm|wav' [Mar 22 20:34:51] DEBUG[12946] app.c: Recording Formats: sfmts=wav49 [Mar 22 20:34:51] DEBUG[12946] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [Mar 22 20:34:51] DEBUG[12946] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 [Mar 22 20:34:51] DEBUG[12946] channel.c: Set channel SIP/9000-09a1f860 to read format slin [Mar 22 20:35:34] VERBOSE[12946] logger.c: <--- SIP read from TCP://192.168.15.100:3801 ---> REGISTER sip:192.168.15.101 SIP/2.0 Via: SIP/2.0/TCP 192.168.15.100:13769 Max-Forwards: 70 From: ;tag=abcdb2676f974344b2d2350b2f1f7743;epid=7f6a19fb3a To: Call-ID: f59a1257c0684f8f982cd60f6effb625 CSeq: 3 REGISTER Contact: ;methods="INVITE, MESSAGE, INFO, SUBSCRIBE, OPTIONS, BYE, CANCEL, NOTIFY, ACK, REFER, BENOTIFY";proxy=replace User-Agent: RTC/1.3.5470 (Messenger 5.1.0701) Supported: com.microsoft.msrtc.presence, adhoclist ms-keep-alive: UAC;hop-hop=yes Event: registration Allow-Events: presence Content-Length: 0 <-------------> [Mar 22 20:35:34] VERBOSE[12946] logger.c: --- (14 headers 0 lines) --- [Mar 22 20:36:34] VERBOSE[12946] logger.c: <--- SIP read from TCP://192.168.15.100:3801 ---> REGISTER sip:192.168.15.101 SIP/2.0 Via: SIP/2.0/TCP 192.168.15.100:13769 Max-Forwards: 70 From: ;tag=abcdb2676f974344b2d2350b2f1f7743;epid=7f6a19fb3a To: Call-ID: f59a1257c0684f8f982cd60f6effb625 CSeq: 4 REGISTER Contact: ;methods="INVITE, MESSAGE, INFO, SUBSCRIBE, OPTIONS, BYE, CANCEL, NOTIFY, ACK, REFER, BENOTIFY";proxy=replace User-Agent: RTC/1.3.5470 (Messenger 5.1.0701) Supported: com.microsoft.msrtc.presence, adhoclist ms-keep-alive: UAC;hop-hop=yes Event: registration Allow-Events: presence Content-Length: 0 <-------------> [Mar 22 20:36:34] VERBOSE[12946] logger.c: --- (14 headers 0 lines) --- [Mar 22 20:37:34] VERBOSE[12946] logger.c: <--- SIP read from TCP://192.168.15.100:3801 ---> REGISTER sip:192.168.15.101 SIP/2.0 Via: SIP/2.0/TCP 192.168.15.100:13769 Max-Forwards: 70 From: ;tag=abcdb2676f974344b2d2350b2f1f7743;epid=7f6a19fb3a To: Call-ID: f59a1257c0684f8f982cd60f6effb625 CSeq: 5 REGISTER Contact: ;methods="INVITE, MESSAGE, INFO, SUBSCRIBE, OPTIONS, BYE, CANCEL, NOTIFY, ACK, REFER, BENOTIFY";proxy=replace User-Agent: RTC/1.3.5470 (Messenger 5.1.0701) Supported: com.microsoft.msrtc.presence, adhoclist ms-keep-alive: UAC;hop-hop=yes Event: registration Allow-Events: presence Content-Length: 0 <-------------> [Mar 22 20:37:34] VERBOSE[12946] logger.c: --- (14 headers 0 lines) ---