[Apr 16 21:22:34] VERBOSE[5721] config.c: == Parsing '/etc/asterisk/logger.conf': [Apr 16 21:22:34] DEBUG[5721] config.c: Parsing /etc/asterisk/logger.conf [Apr 16 21:22:34] VERBOSE[5721] config.c: == Found [Apr 16 21:22:34] VERBOSE[5721] logger.c: Asterisk Event Logger restarted [Apr 16 21:22:34] WARNING[5721] config.c: Realtime mapping for 'queue_log' found to engine 'mysql', but the engine is not available [Apr 16 21:22:34] VERBOSE[5721] logger.c: Asterisk Queue Logger restarted [Apr 16 21:22:36] VERBOSE[3724] chan_sip.c: <--- SIP read from UDP:192.168.12.120:5060 ---> INVITE sip:400@192.168.12.4:5060;user=phone SIP/2.0 Via: SIP/2.0/UDP 192.168.12.120;branch=z9hG4bKd7516231866FB56C From: "420" ;tag=40E912BB-FDE82BF6 To: CSeq: 1 INVITE Call-ID: 518e25a7-bf7b2e2-15f75d1d@192.168.12.120 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_330-UA/3.2.2.0477 Accept-Language: en Supported: 100rel,replaces Allow-Events: talk,hold,conference Max-Forwards: 70 Content-Type: application/sdp Content-Length: 274 v=0 o=- 1271445752 1271445752 IN IP4 192.168.12.120 s=Polycom IP Phone c=IN IP4 192.168.12.120 t=0 0 a=sendrecv m=audio 2232 RTP/AVP 0 8 18 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 <-------------> [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Header 0 [ 51]: INVITE sip:400@192.168.12.4:5060;user=phone SIP/2.0 [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Header 1 [ 62]: Via: SIP/2.0/UDP 192.168.12.120;branch=z9hG4bKd7516231866FB56C [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Header 2 [ 56]: From: "420" ;tag=40E912BB-FDE82BF6 [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Header 3 [ 37]: To: [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Header 4 [ 14]: CSeq: 1 INVITE [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Header 5 [ 49]: Call-ID: 518e25a7-bf7b2e2-15f75d1d@192.168.12.120 [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Header 6 [ 33]: Contact: [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Header 7 [ 96]: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Header 8 [ 54]: User-Agent: PolycomSoundPointIP-SPIP_330-UA/3.2.2.0477 [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Header 9 [ 19]: Accept-Language: en [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Header 10 [ 26]: Supported: 100rel,replaces [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Header 11 [ 34]: Allow-Events: talk,hold,conference [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Header 12 [ 16]: Max-Forwards: 70 [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Header 13 [ 29]: Content-Type: application/sdp [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Header 14 [ 19]: Content-Length: 274 [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Header 15 [ 0]: [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Body 0 [ 3]: v=0 [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Body 1 [ 47]: o=- 1271445752 1271445752 IN IP4 192.168.12.120 [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Body 2 [ 18]: s=Polycom IP Phone [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Body 3 [ 23]: c=IN IP4 192.168.12.120 [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Body 4 [ 5]: t=0 0 [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Body 5 [ 10]: a=sendrecv [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Body 6 [ 31]: m=audio 2232 RTP/AVP 0 8 18 101 [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Body 7 [ 20]: a=rtpmap:0 PCMU/8000 [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Body 8 [ 20]: a=rtpmap:8 PCMA/8000 [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Body 9 [ 21]: a=rtpmap:18 G729/8000 [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Body 10 [ 19]: a=fmtp:18 annexb=no [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Body 11 [ 33]: a=rtpmap:101 telephone-event/8000 [Apr 16 21:22:36] VERBOSE[3724] chan_sip.c: --- (15 headers 12 lines) --- [Apr 16 21:22:36] DEBUG[3724] acl.c: Found IP address for this socket [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.12.4:5060 [Apr 16 21:22:36] VERBOSE[3724] netsock.c: == Using SIP RTP CoS mark 5 [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Setting NAT on RTP to On [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Allocating new SIP dialog for 518e25a7-bf7b2e2-15f75d1d@192.168.12.120 - INVITE (With RTP) [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Begin: parsing SIP "Supported: 100rel,replaces" [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Found SIP option: -100rel- [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Matched SIP option: 100rel [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Found SIP option: -replaces- [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Matched SIP option: replaces [Apr 16 21:22:36] VERBOSE[3724] chan_sip.c: Sending to 192.168.12.120 : 5060 (NAT) [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Initializing initreq for method INVITE - callid 518e25a7-bf7b2e2-15f75d1d@192.168.12.120 [Apr 16 21:22:36] VERBOSE[3724] chan_sip.c: Using INVITE request as basis request - 518e25a7-bf7b2e2-15f75d1d@192.168.12.120 [Apr 16 21:22:36] VERBOSE[3724] chan_sip.c: Found peer '420' for '420' from 192.168.12.120:5060 [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Setting NAT on RTP to On [Apr 16 21:22:36] VERBOSE[3724] chan_sip.c: <--- Reliably Transmitting (NAT) to 192.168.12.120:5060 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 192.168.12.120;branch=z9hG4bKd7516231866FB56C;received=192.168.12.120 From: "420" ;tag=40E912BB-FDE82BF6 To: ;tag=as3b125d9a Call-ID: 518e25a7-bf7b2e2-15f75d1d@192.168.12.120 CSeq: 1 INVITE Server: Media Labs PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="3603fcd7" Content-Length: 0 <------------> [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #1558 [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 192.168.12.120:5060 [Apr 16 21:22:36] VERBOSE[3724] chan_sip.c: Scheduling destruction of SIP dialog '518e25a7-bf7b2e2-15f75d1d@192.168.12.120' in 6400 ms (Method: INVITE) [Apr 16 21:22:36] VERBOSE[3724] chan_sip.c: <--- SIP read from UDP:192.168.12.120:5060 ---> ACK sip:400@192.168.12.4:5060;user=phone SIP/2.0 Via: SIP/2.0/UDP 192.168.12.120;branch=z9hG4bKd7516231866FB56C From: "420" ;tag=40E912BB-FDE82BF6 To: ;tag=as3b125d9a CSeq: 1 ACK Call-ID: 518e25a7-bf7b2e2-15f75d1d@192.168.12.120 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_330-UA/3.2.2.0477 Accept-Language: en Max-Forwards: 70 Content-Length: 0 <-------------> [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Header 0 [ 48]: ACK sip:400@192.168.12.4:5060;user=phone SIP/2.0 [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Header 1 [ 62]: Via: SIP/2.0/UDP 192.168.12.120;branch=z9hG4bKd7516231866FB56C [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Header 2 [ 56]: From: "420" ;tag=40E912BB-FDE82BF6 [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Header 3 [ 52]: To: ;tag=as3b125d9a [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Header 4 [ 11]: CSeq: 1 ACK [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Header 5 [ 49]: Call-ID: 518e25a7-bf7b2e2-15f75d1d@192.168.12.120 [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Header 6 [ 33]: Contact: [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Header 7 [ 96]: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Header 8 [ 54]: User-Agent: PolycomSoundPointIP-SPIP_330-UA/3.2.2.0477 [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Header 9 [ 19]: Accept-Language: en [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Header 10 [ 16]: Max-Forwards: 70 [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Header 11 [ 17]: Content-Length: 0 [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Header 12 [ 0]: [Apr 16 21:22:36] VERBOSE[3724] chan_sip.c: --- (12 headers 0 lines) --- [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #1558 [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Stopping retransmission on '518e25a7-bf7b2e2-15f75d1d@192.168.12.120' of Response 1: Match Found [Apr 16 21:22:36] VERBOSE[3724] chan_sip.c: <--- SIP read from UDP:192.168.12.120:5060 ---> INVITE sip:400@192.168.12.4:5060;user=phone SIP/2.0 Via: SIP/2.0/UDP 192.168.12.120;branch=z9hG4bK5cd824585AE50893 From: "420" ;tag=40E912BB-FDE82BF6 To: CSeq: 2 INVITE Call-ID: 518e25a7-bf7b2e2-15f75d1d@192.168.12.120 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_330-UA/3.2.2.0477 Accept-Language: en Supported: 100rel,replaces Allow-Events: talk,hold,conference Authorization: Digest username="420", realm="asterisk", nonce="3603fcd7", uri="sip:400@192.168.12.4:5060;user=phone", response="a4be05fec4295b24f4b2dc69d4a1d88d", algorithm=MD5 Max-Forwards: 70 Content-Type: application/sdp Content-Length: 274 v=0 o=- 1271445752 1271445752 IN IP4 192.168.12.120 s=Polycom IP Phone c=IN IP4 192.168.12.120 t=0 0 a=sendrecv m=audio 2232 RTP/AVP 0 8 18 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 <-------------> [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Header 0 [ 51]: INVITE sip:400@192.168.12.4:5060;user=phone SIP/2.0 [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Header 1 [ 62]: Via: SIP/2.0/UDP 192.168.12.120;branch=z9hG4bK5cd824585AE50893 [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Header 2 [ 56]: From: "420" ;tag=40E912BB-FDE82BF6 [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Header 3 [ 37]: To: [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Header 4 [ 14]: CSeq: 2 INVITE [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Header 5 [ 49]: Call-ID: 518e25a7-bf7b2e2-15f75d1d@192.168.12.120 [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Header 6 [ 33]: Contact: [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Header 7 [ 96]: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Header 8 [ 54]: User-Agent: PolycomSoundPointIP-SPIP_330-UA/3.2.2.0477 [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Header 9 [ 19]: Accept-Language: en [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Header 10 [ 26]: Supported: 100rel,replaces [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Header 11 [ 34]: Allow-Events: talk,hold,conference [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Header 12 [176]: Authorization: Digest username="420", realm="asterisk", nonce="3603fcd7", uri="sip:400@192.168.12.4:5060;user=phone", response="a4be05fec4295b24f4b2dc69d4a1d88d", algorithm=MD5 [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Header 13 [ 16]: Max-Forwards: 70 [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Header 14 [ 29]: Content-Type: application/sdp [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Header 15 [ 19]: Content-Length: 274 [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Header 16 [ 0]: [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Body 0 [ 3]: v=0 [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Body 1 [ 47]: o=- 1271445752 1271445752 IN IP4 192.168.12.120 [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Body 2 [ 18]: s=Polycom IP Phone [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Body 3 [ 23]: c=IN IP4 192.168.12.120 [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Body 4 [ 5]: t=0 0 [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Body 5 [ 10]: a=sendrecv [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Body 6 [ 31]: m=audio 2232 RTP/AVP 0 8 18 101 [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Body 7 [ 20]: a=rtpmap:0 PCMU/8000 [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Body 8 [ 20]: a=rtpmap:8 PCMA/8000 [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Body 9 [ 21]: a=rtpmap:18 G729/8000 [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Body 10 [ 19]: a=fmtp:18 annexb=no [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Body 11 [ 33]: a=rtpmap:101 telephone-event/8000 [Apr 16 21:22:36] VERBOSE[3724] chan_sip.c: --- (16 headers 12 lines) --- [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Apr 16 21:22:36] VERBOSE[3724] chan_sip.c: Sending to 192.168.12.120 : 5060 (NAT) [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Initializing initreq for method INVITE - callid 518e25a7-bf7b2e2-15f75d1d@192.168.12.120 [Apr 16 21:22:36] VERBOSE[3724] chan_sip.c: Using INVITE request as basis request - 518e25a7-bf7b2e2-15f75d1d@192.168.12.120 [Apr 16 21:22:36] VERBOSE[3724] chan_sip.c: Found peer '420' for '420' from 192.168.12.120:5060 [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Setting NAT on RTP to On [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED. [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Processing session-level SDP o=- 1271445752 1271445752 IN IP4 192.168.12.120... UNSUPPORTED. [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Processing session-level SDP s=Polycom IP Phone... UNSUPPORTED. [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Processing session-level SDP c=IN IP4 192.168.12.120... OK. [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED. [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Processing session-level SDP a=sendrecv... OK. [Apr 16 21:22:36] VERBOSE[3724] chan_sip.c: Found RTP audio format 0 [Apr 16 21:22:36] VERBOSE[3724] chan_sip.c: Found RTP audio format 8 [Apr 16 21:22:36] VERBOSE[3724] chan_sip.c: Found RTP audio format 18 [Apr 16 21:22:36] VERBOSE[3724] chan_sip.c: Found RTP audio format 101 [Apr 16 21:22:36] VERBOSE[3724] chan_sip.c: Found audio description format PCMU for ID 0 [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [Apr 16 21:22:36] VERBOSE[3724] chan_sip.c: Found audio description format PCMA for ID 8 [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK. [Apr 16 21:22:36] VERBOSE[3724] chan_sip.c: Found audio description format G729 for ID 18 [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:18 G729/8000... OK. [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Processing media-level (audio) SDP a=fmtp:18 annexb=no... UNSUPPORTED. [Apr 16 21:22:36] VERBOSE[3724] chan_sip.c: Found audio description format telephone-event for ID 101 [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Apr 16 21:22:36] VERBOSE[3724] chan_sip.c: Capabilities: us - 0xe (gsm|ulaw|alaw), peer - audio=0x10c (ulaw|alaw|g729)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0xc (ulaw|alaw) [Apr 16 21:22:36] VERBOSE[3724] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Apr 16 21:22:36] VERBOSE[3724] chan_sip.c: Peer audio RTP is at port 192.168.12.120:2232 [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: We're settling with these formats: 0xc (ulaw|alaw) [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Checking SIP call limits for device 420 [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Updating call counter for incoming call [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Call from peer '420' is 1 out of 50 [Apr 16 21:22:36] DEBUG[3705] devicestate.c: No provider found, checking channel drivers for SIP - 420 [Apr 16 21:22:36] DEBUG[3705] chan_sip.c: Checking device state for peer 420 [Apr 16 21:22:36] VERBOSE[3724] chan_sip.c: Looking for 400 in telefoons (domain 192.168.12.4) [Apr 16 21:22:36] DEBUG[3705] devicestate.c: Changing state for SIP/420 - state 2 (In use) [Apr 16 21:22:36] DEBUG[3705] devicestate.c: device 'SIP/420' state '2' [Apr 16 21:22:36] DEBUG[3706] devicestate.c: Checking if I can find provider for "Custom" - number: DND420 [Apr 16 21:22:36] DEBUG[3709] app_queue.c: Device 'SIP/420' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Apr 16 21:22:36] DEBUG[3706] devicestate.c: Checking provider Custom with Custom [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: *** Our native formats are 0x8 (alaw) [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: *** Joint capabilities are 0xc (ulaw|alaw) [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: *** Our capabilities are 0xe (gsm|ulaw|alaw) [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x8 (alaw) [Apr 16 21:22:36] DEBUG[3706] devicestate.c: Checking if I can find provider for "Custom" - number: DND420 [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: This channel will not be able to handle video. [Apr 16 21:22:36] DEBUG[3706] devicestate.c: Checking provider Custom with Custom [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: build_route: Contact hop: [Apr 16 21:22:36] DEBUG[3706] chan_sip.c: Strict routing enforced for session 918cd8471aacfaa1 [Apr 16 21:22:36] VERBOSE[3724] chan_sip.c: list_route: hop: [Apr 16 21:22:36] VERBOSE[3706] chan_sip.c: set_destination: Parsing for address/port to send to [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: SIP/420-0000003f: New call is still down.... Trying... [Apr 16 21:22:36] VERBOSE[3706] chan_sip.c: set_destination: set destination to 192.168.12.100, port 5060 [Apr 16 21:22:36] VERBOSE[3724] chan_sip.c: <--- Transmitting (NAT) to 192.168.12.120:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.12.120;branch=z9hG4bK5cd824585AE50893;received=192.168.12.120 From: "420" ;tag=40E912BB-FDE82BF6 To: Call-ID: 518e25a7-bf7b2e2-15f75d1d@192.168.12.120 CSeq: 2 INVITE Server: Media Labs PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer Contact: Content-Length: 0 <------------> [Apr 16 21:22:36] VERBOSE[3706] chan_sip.c: Reliably Transmitting (NAT) to 192.168.12.100:5060: NOTIFY sip:400@192.168.12.100:5060;transport=udp SIP/2.0 Via: SIP/2.0/UDP 192.168.12.4:5060;branch=z9hG4bK4a0774a5;rport Max-Forwards: 70 From: "" ;tag=as74f11287 To: "400" ;tag=ba85c089a4 Contact: Call-ID: 918cd8471aacfaa1 CSeq: 177 NOTIFY User-Agent: Media Labs PBX Event: dialog Content-Type: application/dialog-info+xml Subscription-State: active Content-Length: 208 confirmed --- [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 192.168.12.120:5060 [Apr 16 21:22:36] DEBUG[3706] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #1560 [Apr 16 21:22:36] DEBUG[3706] chan_sip.c: Trying to put 'NOTIFY sip:' onto UDP socket destined for 192.168.12.100:5060 [Apr 16 21:22:36] VERBOSE[3706] chan_sip.c: == Extension Changed 420[default] new state InUse for Notify User 400 [Apr 16 21:22:36] DEBUG[3705] devicestate.c: No provider found, checking channel drivers for SIP - 420 [Apr 16 21:22:36] DEBUG[3705] chan_sip.c: Checking device state for peer 420 [Apr 16 21:22:36] DEBUG[6224] pbx.c: Launching 'Playback' [Apr 16 21:22:36] DEBUG[3705] devicestate.c: Changing state for SIP/420 - state 2 (In use) [Apr 16 21:22:36] VERBOSE[6224] pbx.c: -- Executing [400@telefoons:1] Playback("SIP/420-0000003f", "beep") in new stack [Apr 16 21:22:36] DEBUG[3705] devicestate.c: device 'SIP/420' state '2' [Apr 16 21:22:36] DEBUG[3705] devicestate.c: No provider found, checking channel drivers for SIP - 420 [Apr 16 21:22:36] DEBUG[6224] chan_sip.c: SIP answering channel: SIP/420-0000003f [Apr 16 21:22:36] DEBUG[3705] chan_sip.c: Checking device state for peer 420 [Apr 16 21:22:36] DEBUG[3709] app_queue.c: Device 'SIP/420' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Apr 16 21:22:36] DEBUG[3706] devicestate.c: Checking if I can find provider for "Custom" - number: DND420 [Apr 16 21:22:36] DEBUG[6224] rtp.c: Setting the marker bit due to a source update [Apr 16 21:22:36] DEBUG[3705] devicestate.c: Changing state for SIP/420 - state 2 (In use) [Apr 16 21:22:36] DEBUG[3705] devicestate.c: device 'SIP/420' state '2' [Apr 16 21:22:36] DEBUG[3706] devicestate.c: Checking provider Custom with Custom [Apr 16 21:22:36] DEBUG[6224] chan_sip.c: Setting framing from config on incoming call [Apr 16 21:22:36] DEBUG[6224] chan_sip.c: ** Our capability: 0xc (ulaw|alaw) Video flag: True Text flag: True [Apr 16 21:22:36] DEBUG[3709] app_queue.c: Device 'SIP/420' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Apr 16 21:22:36] DEBUG[6224] chan_sip.c: ** Our prefcodec: 0x0 (nothing) [Apr 16 21:22:36] DEBUG[3706] devicestate.c: Checking if I can find provider for "Custom" - number: DND420 [Apr 16 21:22:36] VERBOSE[6224] chan_sip.c: Audio is at 192.168.12.4 port 15052 [Apr 16 21:22:36] DEBUG[3706] devicestate.c: Checking provider Custom with Custom [Apr 16 21:22:36] VERBOSE[6224] chan_sip.c: Adding codec 0x8 (alaw) to SDP [Apr 16 21:22:36] VERBOSE[6224] chan_sip.c: Adding codec 0x4 (ulaw) to SDP [Apr 16 21:22:36] VERBOSE[6224] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP [Apr 16 21:22:36] DEBUG[6224] chan_sip.c: -- Done with adding codecs to SDP [Apr 16 21:22:36] DEBUG[6224] chan_sip.c: Done building SDP. Settling with this capability: 0xc (ulaw|alaw) [Apr 16 21:22:36] VERBOSE[6224] chan_sip.c: <--- Reliably Transmitting (NAT) to 192.168.12.120:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.12.120;branch=z9hG4bK5cd824585AE50893;received=192.168.12.120 From: "420" ;tag=40E912BB-FDE82BF6 To: ;tag=as2106040b Call-ID: 518e25a7-bf7b2e2-15f75d1d@192.168.12.120 CSeq: 2 INVITE Server: Media Labs PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer Contact: Content-Type: application/sdp Content-Length: 304 v=0 o=root 1136775280 1136775280 IN IP4 192.168.12.4 s=Asterisk PBX SVN-branch-1.6.2-r257597 c=IN IP4 192.168.12.4 t=0 0 m=audio 15052 RTP/AVP 8 0 101 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv <------------> [Apr 16 21:22:36] DEBUG[6224] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #1562 [Apr 16 21:22:36] DEBUG[6224] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.12.120:5060 [Apr 16 21:22:36] VERBOSE[3724] chan_sip.c: <--- SIP read from UDP:192.168.12.120:5060 ---> ACK sip:400@192.168.12.4 SIP/2.0 Via: SIP/2.0/UDP 192.168.12.120;branch=z9hG4bKaa0263444FADBB7F From: "420" ;tag=40E912BB-FDE82BF6 To: ;tag=as2106040b CSeq: 2 ACK Call-ID: 518e25a7-bf7b2e2-15f75d1d@192.168.12.120 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER User-Agent: PolycomSoundPointIP-SPIP_330-UA/3.2.2.0477 Accept-Language: en Max-Forwards: 70 Content-Length: 0 <-------------> [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Header 0 [ 32]: ACK sip:400@192.168.12.4 SIP/2.0 [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Header 1 [ 62]: Via: SIP/2.0/UDP 192.168.12.120;branch=z9hG4bKaa0263444FADBB7F [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Header 2 [ 56]: From: "420" ;tag=40E912BB-FDE82BF6 [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Header 3 [ 52]: To: ;tag=as2106040b [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Header 4 [ 11]: CSeq: 2 ACK [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Header 5 [ 49]: Call-ID: 518e25a7-bf7b2e2-15f75d1d@192.168.12.120 [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Header 6 [ 33]: Contact: [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Header 7 [ 96]: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Header 8 [ 54]: User-Agent: PolycomSoundPointIP-SPIP_330-UA/3.2.2.0477 [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Header 9 [ 19]: Accept-Language: en [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Header 10 [ 16]: Max-Forwards: 70 [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Header 11 [ 17]: Content-Length: 0 [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Header 12 [ 0]: [Apr 16 21:22:36] VERBOSE[3724] chan_sip.c: --- (12 headers 0 lines) --- [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #1562 [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Stopping retransmission on '518e25a7-bf7b2e2-15f75d1d@192.168.12.120' of Response 2: Match Found [Apr 16 21:22:36] VERBOSE[3724] chan_sip.c: <--- SIP read from UDP:192.168.12.100:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.12.4:5060;branch=z9hG4bK4a0774a5;rport=5060;received=192.168.12.4 From: "" ;tag=as74f11287 To: "400" ;tag=ba85c089a4 Call-ID: 918cd8471aacfaa1 CSeq: 177 NOTIFY Contact: "400" ;+sip.instance="" Server: Aastra 57i/2.5.3.2002 Content-Length: 0 <-------------> [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Header 1 [ 90]: Via: SIP/2.0/UDP 192.168.12.4:5060;branch=z9hG4bK4a0774a5;rport=5060;received=192.168.12.4 [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Header 2 [ 51]: From: "" ;tag=as74f11287 [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Header 3 [ 52]: To: "400" ;tag=ba85c089a4 [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Header 4 [ 25]: Call-ID: 918cd8471aacfaa1 [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Header 5 [ 16]: CSeq: 177 NOTIFY [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Header 6 [122]: Contact: "400" ;+sip.instance="" [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Header 7 [ 29]: Server: Aastra 57i/2.5.3.2002 [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Header 8 [ 17]: Content-Length: 0 [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Header 9 [ 0]: [Apr 16 21:22:36] VERBOSE[3724] chan_sip.c: --- (9 headers 0 lines) --- [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Acked pending invite 177 [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #1560 [Apr 16 21:22:36] DEBUG[3724] chan_sip.c: Stopping retransmission on '918cd8471aacfaa1' of Request 177: Match Found [Apr 16 21:22:36] VERBOSE[3724] chan_sip.c: SIP Response message for INCOMING dialog NOTIFY arrived [Apr 16 21:22:36] DEBUG[6224] channel.c: Set channel SIP/420-0000003f to write format slin [Apr 16 21:22:36] DEBUG[6224] rtp.c: Ooh, format changed from unknown to alaw [Apr 16 21:22:36] DEBUG[6224] rtp.c: Created smoother: format: 8 ms: 20 len: 160 [Apr 16 21:22:36] DEBUG[6224] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Apr 16 21:22:36] VERBOSE[6224] file.c: -- Playing 'beep.slin' (language 'nl') [Apr 16 21:22:37] DEBUG[3724] chan_sip.c: Auto destroying SIP dialog 'f16dbf22c0d1e9fc' [Apr 16 21:22:37] DEBUG[3724] chan_sip.c: Destroying SIP dialog f16dbf22c0d1e9fc [Apr 16 21:22:37] VERBOSE[3724] chan_sip.c: Really destroying SIP dialog 'f16dbf22c0d1e9fc' Method: REGISTER [Apr 16 21:22:37] DEBUG[6224] channel.c: Scheduling timer at (136 requested / 100 actual) timer ticks per second [Apr 16 21:22:37] DEBUG[6224] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Apr 16 21:22:37] DEBUG[6224] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Apr 16 21:22:37] DEBUG[6224] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Apr 16 21:22:37] DEBUG[6224] channel.c: Set channel SIP/420-0000003f to write format alaw [Apr 16 21:22:37] DEBUG[6224] pbx.c: Launching 'Dial' [Apr 16 21:22:37] VERBOSE[6224] pbx.c: -- Executing [400@telefoons:2] Dial("SIP/420-0000003f", "SIP/400") in new stack [Apr 16 21:22:37] DEBUG[6224] chan_sip.c: Asked to create a SIP channel with formats: 0x8 (alaw) [Apr 16 21:22:37] VERBOSE[6224] netsock.c: == Using SIP RTP CoS mark 5 [Apr 16 21:22:37] DEBUG[6224] chan_sip.c: Allocating new SIP dialog for 334563592927761d1e55a80253bbe41d@192.168.12.4 - INVITE (With RTP) [Apr 16 21:22:37] DEBUG[6224] chan_sip.c: Setting NAT on RTP to On [Apr 16 21:22:37] DEBUG[6224] chan_sip.c: OBPROXY: Not applying OBproxy to this call [Apr 16 21:22:37] DEBUG[6224] acl.c: Found IP address for this socket [Apr 16 21:22:37] DEBUG[6224] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.12.4:5060 [Apr 16 21:22:37] DEBUG[6224] chan_sip.c: *** Our native formats are 0x8 (alaw) [Apr 16 21:22:37] DEBUG[6224] chan_sip.c: *** Joint capabilities are 0x8 (alaw) [Apr 16 21:22:37] DEBUG[6224] chan_sip.c: *** Our capabilities are 0xe (gsm|ulaw|alaw) [Apr 16 21:22:37] DEBUG[6224] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x8 (alaw) [Apr 16 21:22:37] DEBUG[6224] chan_sip.c: *** Our preferred formats from the incoming channel are 0x8 (alaw) [Apr 16 21:22:37] DEBUG[6224] chan_sip.c: This channel will not be able to handle video. [Apr 16 21:22:37] DEBUG[6224] channel.c: Not copying variable DIALEDTIME. [Apr 16 21:22:37] DEBUG[6224] channel.c: Not copying variable ANSWEREDTIME. [Apr 16 21:22:37] DEBUG[6224] channel.c: Not copying variable DIALEDPEERNAME. [Apr 16 21:22:37] DEBUG[6224] channel.c: Not copying variable DIALEDPEERNUMBER. [Apr 16 21:22:37] DEBUG[6224] channel.c: Not copying variable DIALSTATUS. [Apr 16 21:22:37] DEBUG[6224] channel.c: Not copying variable PLAYBACKSTATUS. [Apr 16 21:22:37] DEBUG[6224] channel.c: Not copying variable SIPCALLID. [Apr 16 21:22:37] DEBUG[6224] channel.c: Not copying variable SIPDOMAIN. [Apr 16 21:22:37] DEBUG[6224] channel.c: Not copying variable SIPURI. [Apr 16 21:22:37] DEBUG[6224] chan_sip.c: Outgoing Call for 400 [Apr 16 21:22:37] DEBUG[6224] chan_sip.c: Updating call counter for outgoing call [Apr 16 21:22:37] DEBUG[6224] chan_sip.c: Call to peer '400' is 1 out of 50 [Apr 16 21:22:37] DEBUG[3705] devicestate.c: No provider found, checking channel drivers for SIP - 400 [Apr 16 21:22:37] DEBUG[3705] chan_sip.c: Checking device state for peer 400 [Apr 16 21:22:37] DEBUG[3705] devicestate.c: Changing state for SIP/400 - state 6 (Ringing) [Apr 16 21:22:37] DEBUG[6224] chan_sip.c: ** Our capability: 0xe (gsm|ulaw|alaw) Video flag: False Text flag: False [Apr 16 21:22:37] DEBUG[3705] devicestate.c: device 'SIP/400' state '6' [Apr 16 21:22:37] DEBUG[6224] chan_sip.c: ** Our prefcodec: 0x8 (alaw) [Apr 16 21:22:37] VERBOSE[6224] chan_sip.c: Audio is at 192.168.12.4 port 16104 [Apr 16 21:22:37] VERBOSE[6224] chan_sip.c: Adding codec 0x8 (alaw) to SDP [Apr 16 21:22:37] VERBOSE[6224] chan_sip.c: Adding codec 0x4 (ulaw) to SDP [Apr 16 21:22:37] DEBUG[3706] devicestate.c: No provider found, checking channel drivers for SIP - 2-400 [Apr 16 21:22:37] VERBOSE[6224] chan_sip.c: Adding codec 0x2 (gsm) to SDP [Apr 16 21:22:37] DEBUG[3706] chan_sip.c: Checking device state for peer 2-400 [Apr 16 21:22:37] VERBOSE[6224] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP [Apr 16 21:22:37] DEBUG[3706] devicestate.c: Checking if I can find provider for "Custom" - number: DND400 [Apr 16 21:22:37] DEBUG[3706] devicestate.c: Checking provider Custom with Custom [Apr 16 21:22:37] DEBUG[6224] chan_sip.c: -- Done with adding codecs to SDP [Apr 16 21:22:37] DEBUG[6224] chan_sip.c: Done building SDP. Settling with this capability: 0xe (gsm|ulaw|alaw) [Apr 16 21:22:37] DEBUG[6224] chan_sip.c: Initializing initreq for method INVITE - callid 6488bcdb3c17298c197bf63e34f3f85a@192.168.12.4 [Apr 16 21:22:37] DEBUG[3709] app_queue.c: Device 'SIP/400' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Apr 16 21:22:37] DEBUG[6224] chan_sip.c: Header 0 [ 56]: INVITE sip:400@192.168.12.100:5060;transport=udp SIP/2.0 [Apr 16 21:22:37] DEBUG[6224] chan_sip.c: Header 1 [ 63]: Via: SIP/2.0/UDP 192.168.12.4:5060;branch=z9hG4bK0964c426;rport [Apr 16 21:22:37] DEBUG[6224] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Apr 16 21:22:37] DEBUG[6224] chan_sip.c: Header 3 [ 61]: From: "Polycom SPIP330" ;tag=as2a7e2a63 [Apr 16 21:22:37] DEBUG[6224] chan_sip.c: Header 4 [ 47]: To: [Apr 16 21:22:37] DEBUG[6224] chan_sip.c: Header 5 [ 31]: Contact: [Apr 16 21:22:37] DEBUG[6224] chan_sip.c: Header 6 [ 54]: Call-ID: 6488bcdb3c17298c197bf63e34f3f85a@192.168.12.4 [Apr 16 21:22:37] DEBUG[6224] chan_sip.c: Header 7 [ 16]: CSeq: 102 INVITE [Apr 16 21:22:37] DEBUG[6224] chan_sip.c: Header 8 [ 26]: User-Agent: Media Labs PBX [Apr 16 21:22:37] DEBUG[6224] chan_sip.c: Header 9 [ 35]: Date: Fri, 16 Apr 2010 19:22:37 GMT [Apr 16 21:22:37] DEBUG[6224] chan_sip.c: Header 10 [ 72]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO [Apr 16 21:22:37] DEBUG[6224] chan_sip.c: Header 11 [ 26]: Supported: replaces, timer [Apr 16 21:22:37] DEBUG[6224] chan_sip.c: Header 12 [ 29]: Content-Type: application/sdp [Apr 16 21:22:37] DEBUG[6224] chan_sip.c: Header 13 [ 19]: Content-Length: 327 [Apr 16 21:22:37] DEBUG[6224] chan_sip.c: Header 14 [ 0]: [Apr 16 21:22:37] DEBUG[6224] chan_sip.c: Body 0 [ 3]: v=0 [Apr 16 21:22:37] DEBUG[6224] chan_sip.c: Body 1 [ 48]: o=root 1738386923 1738386923 IN IP4 192.168.12.4 [Apr 16 21:22:37] DEBUG[6224] chan_sip.c: Body 2 [ 39]: s=Asterisk PBX SVN-branch-1.6.2-r257597 [Apr 16 21:22:37] DEBUG[6224] chan_sip.c: Body 3 [ 21]: c=IN IP4 192.168.12.4 [Apr 16 21:22:37] DEBUG[6224] chan_sip.c: Body 4 [ 5]: t=0 0 [Apr 16 21:22:37] DEBUG[6224] chan_sip.c: Body 5 [ 31]: m=audio 16104 RTP/AVP 8 0 3 101 [Apr 16 21:22:37] DEBUG[6224] chan_sip.c: Body 6 [ 20]: a=rtpmap:8 PCMA/8000 [Apr 16 21:22:37] DEBUG[6224] chan_sip.c: Body 7 [ 20]: a=rtpmap:0 PCMU/8000 [Apr 16 21:22:37] DEBUG[6224] chan_sip.c: Body 8 [ 19]: a=rtpmap:3 GSM/8000 [Apr 16 21:22:37] DEBUG[6224] chan_sip.c: Body 9 [ 33]: a=rtpmap:101 telephone-event/8000 [Apr 16 21:22:37] DEBUG[6224] chan_sip.c: Body 10 [ 15]: a=fmtp:101 0-16 [Apr 16 21:22:37] DEBUG[6224] chan_sip.c: Body 11 [ 25]: a=silenceSupp:off - - - - [Apr 16 21:22:37] DEBUG[6224] chan_sip.c: Body 12 [ 10]: a=ptime:20 [Apr 16 21:22:37] DEBUG[6224] chan_sip.c: Body 13 [ 10]: a=sendrecv [Apr 16 21:22:37] VERBOSE[6224] chan_sip.c: Reliably Transmitting (NAT) to 192.168.12.100:5060: INVITE sip:400@192.168.12.100:5060;transport=udp SIP/2.0 Via: SIP/2.0/UDP 192.168.12.4:5060;branch=z9hG4bK0964c426;rport Max-Forwards: 70 From: "Polycom SPIP330" ;tag=as2a7e2a63 To: Contact: Call-ID: 6488bcdb3c17298c197bf63e34f3f85a@192.168.12.4 CSeq: 102 INVITE User-Agent: Media Labs PBX Date: Fri, 16 Apr 2010 19:22:37 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer Content-Type: application/sdp Content-Length: 327 v=0 o=root 1738386923 1738386923 IN IP4 192.168.12.4 s=Asterisk PBX SVN-branch-1.6.2-r257597 c=IN IP4 192.168.12.4 t=0 0 m=audio 16104 RTP/AVP 8 0 3 101 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:3 GSM/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [Apr 16 21:22:37] DEBUG[6224] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #1564 [Apr 16 21:22:37] DEBUG[6224] chan_sip.c: Trying to put 'INVITE sip:' onto UDP socket destined for 192.168.12.100:5060 [Apr 16 21:22:37] VERBOSE[6224] app_dial.c: -- Called 400 [Apr 16 21:22:37] VERBOSE[3724] chan_sip.c: <--- SIP read from UDP:192.168.12.120:5060 ---> BYE sip:400@192.168.12.4 SIP/2.0 Via: SIP/2.0/UDP 192.168.12.120;branch=z9hG4bK52fc30ba7C38C2F5 From: "420" ;tag=40E912BB-FDE82BF6 To: ;tag=as2106040b CSeq: 3 BYE Call-ID: 518e25a7-bf7b2e2-15f75d1d@192.168.12.120 Contact: User-Agent: PolycomSoundPointIP-SPIP_330-UA/3.2.2.0477 Accept-Language: en Authorization: Digest username="420", realm="asterisk", nonce="3603fcd7", uri="sip:400@192.168.12.4:5060;user=phone", response="56e35937cea2dac4f466a96db578f782", algorithm=MD5 Max-Forwards: 70 Content-Length: 0 <-------------> [Apr 16 21:22:37] DEBUG[3724] chan_sip.c: Header 0 [ 32]: BYE sip:400@192.168.12.4 SIP/2.0 [Apr 16 21:22:37] DEBUG[3724] chan_sip.c: Header 1 [ 62]: Via: SIP/2.0/UDP 192.168.12.120;branch=z9hG4bK52fc30ba7C38C2F5 [Apr 16 21:22:37] DEBUG[3724] chan_sip.c: Header 2 [ 56]: From: "420" ;tag=40E912BB-FDE82BF6 [Apr 16 21:22:37] DEBUG[3724] chan_sip.c: Header 3 [ 52]: To: ;tag=as2106040b [Apr 16 21:22:37] DEBUG[3724] chan_sip.c: Header 4 [ 11]: CSeq: 3 BYE [Apr 16 21:22:37] DEBUG[3724] chan_sip.c: Header 5 [ 49]: Call-ID: 518e25a7-bf7b2e2-15f75d1d@192.168.12.120 [Apr 16 21:22:37] DEBUG[3724] chan_sip.c: Header 6 [ 33]: Contact: [Apr 16 21:22:37] DEBUG[3724] chan_sip.c: Header 7 [ 54]: User-Agent: PolycomSoundPointIP-SPIP_330-UA/3.2.2.0477 [Apr 16 21:22:37] DEBUG[3724] chan_sip.c: Header 8 [ 19]: Accept-Language: en [Apr 16 21:22:37] DEBUG[3724] chan_sip.c: Header 9 [176]: Authorization: Digest username="420", realm="asterisk", nonce="3603fcd7", uri="sip:400@192.168.12.4:5060;user=phone", response="56e35937cea2dac4f466a96db578f782", algorithm=MD5 [Apr 16 21:22:37] DEBUG[3724] chan_sip.c: Header 10 [ 16]: Max-Forwards: 70 [Apr 16 21:22:37] DEBUG[3724] chan_sip.c: Header 11 [ 17]: Content-Length: 0 [Apr 16 21:22:37] DEBUG[3724] chan_sip.c: Header 12 [ 0]: [Apr 16 21:22:37] VERBOSE[3724] chan_sip.c: --- (12 headers 0 lines) --- [Apr 16 21:22:37] DEBUG[3724] chan_sip.c: **** Received BYE (8) - Command in SIP BYE [Apr 16 21:22:37] DEBUG[3724] chan_sip.c: Initializing initreq for method BYE - callid 518e25a7-bf7b2e2-15f75d1d@192.168.12.120 [Apr 16 21:22:37] VERBOSE[3724] chan_sip.c: Sending to 192.168.12.120 : 5060 (NAT) [Apr 16 21:22:37] DEBUG[3724] chan_sip.c: Setting SIP_ALREADYGONE on dialog 518e25a7-bf7b2e2-15f75d1d@192.168.12.120 [Apr 16 21:22:37] DEBUG[3724] chan_sip.c: Received bye, issuing owner hangup [Apr 16 21:22:37] VERBOSE[3724] chan_sip.c: <--- Transmitting (NAT) to 192.168.12.120:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.12.120;branch=z9hG4bK52fc30ba7C38C2F5;received=192.168.12.120 From: "420" ;tag=40E912BB-FDE82BF6 To: ;tag=as2106040b Call-ID: 518e25a7-bf7b2e2-15f75d1d@192.168.12.120 CSeq: 3 BYE Server: Media Labs PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer Content-Length: 0 <------------> [Apr 16 21:22:37] DEBUG[3724] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.12.120:5060 [Apr 16 21:22:37] DEBUG[6224] rtp.c: Channel '' has no RTP, not doing anything [Apr 16 21:22:37] DEBUG[6224] channel.c: Hanging up channel 'SIP/400-00000040' [Apr 16 21:22:37] DEBUG[6224] chan_sip.c: Hangup call SIP/400-00000040, SIP callid 6488bcdb3c17298c197bf63e34f3f85a@192.168.12.4 [Apr 16 21:22:37] DEBUG[6224] chan_sip.c: update_call_counter(400) - decrement call limit counter on hangup [Apr 16 21:22:37] DEBUG[6224] chan_sip.c: Updating call counter for outgoing call [Apr 16 21:22:37] DEBUG[6224] chan_sip.c: Call to peer '400' removed from call limit 50 [Apr 16 21:22:37] DEBUG[6224] chan_sip.c: Hanging up channel in state Down (not UP) [Apr 16 21:22:37] DEBUG[3705] devicestate.c: No provider found, checking channel drivers for SIP - 400 [Apr 16 21:22:37] DEBUG[6224] chan_sip.c: Acked pending invite 102 [Apr 16 21:22:37] DEBUG[3705] chan_sip.c: Checking device state for peer 400 [Apr 16 21:22:37] DEBUG[6224] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #1564 [Apr 16 21:22:37] DEBUG[3705] devicestate.c: Changing state for SIP/400 - state 1 (Not in use) [Apr 16 21:22:37] DEBUG[3705] devicestate.c: device 'SIP/400' state '1' [Apr 16 21:22:37] DEBUG[6224] chan_sip.c: Stopping retransmission on '6488bcdb3c17298c197bf63e34f3f85a@192.168.12.4' of Request 102: Match Found [Apr 16 21:22:37] VERBOSE[6224] chan_sip.c: Scheduling destruction of SIP dialog '6488bcdb3c17298c197bf63e34f3f85a@192.168.12.4' in 6400 ms (Method: INVITE) [Apr 16 21:22:37] DEBUG[3709] app_queue.c: Device 'SIP/400' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 16 21:22:37] DEBUG[3706] devicestate.c: No provider found, checking channel drivers for SIP - 2-400 [Apr 16 21:22:37] DEBUG[3706] chan_sip.c: Checking device state for peer 2-400 [Apr 16 21:22:37] DEBUG[3706] devicestate.c: Checking if I can find provider for "Custom" - number: DND400 [Apr 16 21:22:37] DEBUG[6224] app_dial.c: Exiting with DIALSTATUS=CANCEL. [Apr 16 21:22:37] DEBUG[3706] devicestate.c: Checking provider Custom with Custom [Apr 16 21:22:37] DEBUG[6224] pbx.c: Spawn extension (telefoons,400,2) exited non-zero on 'SIP/420-0000003f' [Apr 16 21:22:37] VERBOSE[6224] pbx.c: == Spawn extension (telefoons, 400, 2) exited non-zero on 'SIP/420-0000003f' [Apr 16 21:22:37] DEBUG[3705] devicestate.c: No provider found, checking channel drivers for SIP - 400 [Apr 16 21:22:37] DEBUG[3705] chan_sip.c: Checking device state for peer 400 [Apr 16 21:22:37] DEBUG[6224] channel.c: Soft-Hanging up channel 'SIP/420-0000003f' [Apr 16 21:22:37] DEBUG[3705] devicestate.c: Changing state for SIP/400 - state 1 (Not in use) [Apr 16 21:22:37] DEBUG[3705] devicestate.c: device 'SIP/400' state '1' [Apr 16 21:22:37] DEBUG[6224] pbx.c: Launching 'Macro' [Apr 16 21:22:37] VERBOSE[6224] pbx.c: -- Executing [h@telefoons:1] Macro("SIP/420-0000003f", "hangup-call") in new stack [Apr 16 21:22:37] DEBUG[3706] devicestate.c: No provider found, checking channel drivers for SIP - 2-400 [Apr 16 21:22:37] DEBUG[3706] chan_sip.c: Checking device state for peer 2-400 [Apr 16 21:22:37] DEBUG[3706] devicestate.c: Checking if I can find provider for "Custom" - number: DND400 [Apr 16 21:22:37] DEBUG[3706] devicestate.c: Checking provider Custom with Custom [Apr 16 21:22:37] DEBUG[3709] app_queue.c: Device 'SIP/400' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 16 21:22:37] DEBUG[6224] pbx.c: Launching 'NoOp' [Apr 16 21:22:37] VERBOSE[6224] pbx.c: -- Executing [s@macro-hangup-call:1] NoOp("SIP/420-0000003f", "EXTEN_1= EXTEN_2=") in new stack [Apr 16 21:22:37] DEBUG[6224] app_macro.c: Executed application: NooP [Apr 16 21:22:37] DEBUG[6224] pbx.c: Launching 'NoOp' [Apr 16 21:22:37] VERBOSE[6224] pbx.c: -- Executing [s@macro-hangup-call:2] NoOp("SIP/420-0000003f", "HANGUP EXT_RINGTIME= EXT_CHANNEL= EXT_FLOW= EXT_WAV= EXT_CP_MONITOR= PICKUPMARK= CALLED_EXT= BLINDTRANSFER=") in new stack [Apr 16 21:22:37] DEBUG[6224] app_macro.c: Executed application: NooP [Apr 16 21:22:37] DEBUG[6224] pbx.c: Expression result is '0' [Apr 16 21:22:37] DEBUG[6224] pbx.c: Launching 'GotoIf' [Apr 16 21:22:37] VERBOSE[6224] pbx.c: -- Executing [s@macro-hangup-call:3] GotoIf("SIP/420-0000003f", "0?out") in new stack [Apr 16 21:22:37] DEBUG[6224] pbx.c: Not taking any branch [Apr 16 21:22:37] DEBUG[6224] app_macro.c: Executed application: GotoIf [Apr 16 21:22:37] DEBUG[6224] pbx.c: Expression result is '0' [Apr 16 21:22:37] DEBUG[6224] pbx.c: Launching 'GotoIf' [Apr 16 21:22:37] VERBOSE[6224] pbx.c: -- Executing [s@macro-hangup-call:4] GotoIf("SIP/420-0000003f", "0?in") in new stack [Apr 16 21:22:37] DEBUG[6224] pbx.c: Not taking any branch [Apr 16 21:22:37] DEBUG[6224] app_macro.c: Executed application: GotoIf [Apr 16 21:22:37] DEBUG[6224] channel.c: Hanging up channel 'SIP/420-0000003f' [Apr 16 21:22:37] DEBUG[6224] chan_sip.c: Hangup call SIP/420-0000003f, SIP callid 518e25a7-bf7b2e2-15f75d1d@192.168.12.120 [Apr 16 21:22:37] DEBUG[6224] chan_sip.c: update_call_counter(420) - decrement call limit counter on hangup [Apr 16 21:22:37] DEBUG[6224] chan_sip.c: Updating call counter for incoming call [Apr 16 21:22:37] DEBUG[6224] chan_sip.c: Call from peer '420' removed from call limit 50 [Apr 16 21:22:37] DEBUG[3705] devicestate.c: No provider found, checking channel drivers for SIP - 420 [Apr 16 21:22:37] DEBUG[3705] chan_sip.c: Checking device state for peer 420 [Apr 16 21:22:37] DEBUG[3705] devicestate.c: Changing state for SIP/420 - state 1 (Not in use) [Apr 16 21:22:37] DEBUG[3705] devicestate.c: device 'SIP/420' state '1' [Apr 16 21:22:37] DEBUG[3709] app_queue.c: Device 'SIP/420' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 16 21:22:37] DEBUG[3706] devicestate.c: Checking if I can find provider for "Custom" - number: DND420 [Apr 16 21:22:37] DEBUG[3706] devicestate.c: Checking provider Custom with Custom [Apr 16 21:22:37] DEBUG[6224] pbx.c: Function result is '2010-04-16 21:22:36' [Apr 16 21:22:37] DEBUG[3706] devicestate.c: Checking if I can find provider for "Custom" - number: DND420 [Apr 16 21:22:37] DEBUG[3706] devicestate.c: Checking provider Custom with Custom [Apr 16 21:22:37] DEBUG[6224] pbx.c: Function result is '"Polycom SPIP330" <420>' [Apr 16 21:22:37] DEBUG[6224] pbx.c: Function result is 'telefoons' [Apr 16 21:22:37] DEBUG[3706] chan_sip.c: Strict routing enforced for session 918cd8471aacfaa1 [Apr 16 21:22:37] DEBUG[6224] pbx.c: Function result is 'SIP/420-0000003f' [Apr 16 21:22:37] DEBUG[6224] pbx.c: Function result is 'SIP/400-00000040' [Apr 16 21:22:37] VERBOSE[3706] chan_sip.c: set_destination: Parsing for address/port to send to [Apr 16 21:22:37] DEBUG[6224] pbx.c: Function result is 'Dial' [Apr 16 21:22:37] VERBOSE[3706] chan_sip.c: set_destination: set destination to 192.168.12.100, port 5060 [Apr 16 21:22:37] DEBUG[6224] pbx.c: Function result is 'SIP/400' [Apr 16 21:22:37] DEBUG[6224] pbx.c: Function result is '1' [Apr 16 21:22:37] VERBOSE[3706] chan_sip.c: Reliably Transmitting (NAT) to 192.168.12.100:5060: NOTIFY sip:400@192.168.12.100:5060;transport=udp SIP/2.0 Via: SIP/2.0/UDP 192.168.12.4:5060;branch=z9hG4bK12fbe860;rport Max-Forwards: 70 From: "" ;tag=as74f11287 To: "400" ;tag=ba85c089a4 Contact: Call-ID: 918cd8471aacfaa1 CSeq: 178 NOTIFY User-Agent: Media Labs PBX Event: dialog Content-Type: application/dialog-info+xml Subscription-State: active Content-Length: 209 terminated --- [Apr 16 21:22:37] DEBUG[6224] pbx.c: Function result is '1' [Apr 16 21:22:37] DEBUG[3706] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #1567 [Apr 16 21:22:37] DEBUG[6224] pbx.c: Function result is 'ANSWERED' [Apr 16 21:22:37] DEBUG[6224] pbx.c: Function result is 'DOCUMENTATION' [Apr 16 21:22:37] DEBUG[3706] chan_sip.c: Trying to put 'NOTIFY sip:' onto UDP socket destined for 192.168.12.100:5060 [Apr 16 21:22:37] DEBUG[6224] pbx.c: Function result is '(null)' [Apr 16 21:22:37] DEBUG[6224] pbx.c: Function result is '1271445756.63' [Apr 16 21:22:37] DEBUG[6224] pbx.c: Function result is '(null)' [Apr 16 21:22:37] VERBOSE[3706] chan_sip.c: == Extension Changed 420[default] new state Idle for Notify User 400 [Apr 16 21:22:37] DEBUG[6224] pbx.c: Function result is '(null)' [Apr 16 21:22:37] DEBUG[6224] cdr_sqlite3_custom.c: About to log: INSERT INTO cdr (calldate,clid,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid,userfield,test) VALUES ('2010-04-16 21:22:36','"Polycom SPIP330" <420>','telefoons','SIP/420-0000003f','SIP/400-00000040','Dial','SIP/400','1','1','ANSWERED','DOCUMENTATION','','1271445756.63','','') [Apr 16 21:22:37] VERBOSE[3724] chan_sip.c: <--- SIP read from UDP:192.168.12.100:5060 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.12.4:5060;branch=z9hG4bK0964c426;rport=5060;received=192.168.12.4 From: "Polycom SPIP330" ;tag=as2a7e2a63 To: ;tag=4014014111 Call-ID: 6488bcdb3c17298c197bf63e34f3f85a@192.168.12.4 CSeq: 102 INVITE Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, OPTIONS, UPDATE, PRACK, SUBSCRIBE, INFO Allow-Events: talk, hold, conference, aastra-xml, LocalModeStatus Contact: "400" ;+sip.instance="" Server: Aastra 57i/2.5.3.2002 Supported: gruu, path Content-Length: 0 <-------------> [Apr 16 21:22:37] DEBUG[3724] chan_sip.c: Header 0 [ 19]: SIP/2.0 180 Ringing [Apr 16 21:22:37] DEBUG[3724] chan_sip.c: Header 1 [ 90]: Via: SIP/2.0/UDP 192.168.12.4:5060;branch=z9hG4bK0964c426;rport=5060;received=192.168.12.4 [Apr 16 21:22:37] DEBUG[3724] chan_sip.c: Header 2 [ 61]: From: "Polycom SPIP330" ;tag=as2a7e2a63 [Apr 16 21:22:37] DEBUG[3724] chan_sip.c: Header 3 [ 62]: To: ;tag=4014014111 [Apr 16 21:22:37] DEBUG[3724] chan_sip.c: Header 4 [ 54]: Call-ID: 6488bcdb3c17298c197bf63e34f3f85a@192.168.12.4 [Apr 16 21:22:37] DEBUG[3724] chan_sip.c: Header 5 [ 16]: CSeq: 102 INVITE [Apr 16 21:22:37] DEBUG[3724] chan_sip.c: Header 6 [ 88]: Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, OPTIONS, UPDATE, PRACK, SUBSCRIBE, INFO [Apr 16 21:22:37] DEBUG[3724] chan_sip.c: Header 7 [ 65]: Allow-Events: talk, hold, conference, aastra-xml, LocalModeStatus [Apr 16 21:22:37] DEBUG[3724] chan_sip.c: Header 8 [122]: Contact: "400" ;+sip.instance="" [Apr 16 21:22:37] DEBUG[3724] chan_sip.c: Header 9 [ 29]: Server: Aastra 57i/2.5.3.2002 [Apr 16 21:22:37] DEBUG[3724] chan_sip.c: Header 10 [ 21]: Supported: gruu, path [Apr 16 21:22:37] DEBUG[3724] chan_sip.c: Header 11 [ 17]: Content-Length: 0 [Apr 16 21:22:37] DEBUG[3724] chan_sip.c: Header 12 [ 0]: [Apr 16 21:22:37] VERBOSE[3724] chan_sip.c: --- (12 headers 0 lines) --- [Apr 16 21:22:37] DEBUG[3724] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '6488bcdb3c17298c197bf63e34f3f85a@192.168.12.4' Request 102: Found [Apr 16 21:22:37] DEBUG[3724] chan_sip.c: Destroying SIP dialog 518e25a7-bf7b2e2-15f75d1d@192.168.12.120 [Apr 16 21:22:37] VERBOSE[3724] chan_sip.c: Really destroying SIP dialog '518e25a7-bf7b2e2-15f75d1d@192.168.12.120' Method: BYE [Apr 16 21:22:37] VERBOSE[3724] chan_sip.c: <--- SIP read from UDP:192.168.12.100:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.12.4:5060;branch=z9hG4bK12fbe860;rport=5060;received=192.168.12.4 From: "" ;tag=as74f11287 To: "400" ;tag=ba85c089a4 Call-ID: 918cd8471aacfaa1 CSeq: 178 NOTIFY Contact: "400" ;+sip.instance="" Server: Aastra 57i/2.5.3.2002 Content-Length: 0 <-------------> [Apr 16 21:22:37] DEBUG[3724] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Apr 16 21:22:37] DEBUG[3724] chan_sip.c: Header 1 [ 90]: Via: SIP/2.0/UDP 192.168.12.4:5060;branch=z9hG4bK12fbe860;rport=5060;received=192.168.12.4 [Apr 16 21:22:37] DEBUG[3724] chan_sip.c: Header 2 [ 51]: From: "" ;tag=as74f11287 [Apr 16 21:22:37] DEBUG[3724] chan_sip.c: Header 3 [ 52]: To: "400" ;tag=ba85c089a4 [Apr 16 21:22:37] DEBUG[3724] chan_sip.c: Header 4 [ 25]: Call-ID: 918cd8471aacfaa1 [Apr 16 21:22:37] DEBUG[3724] chan_sip.c: Header 5 [ 16]: CSeq: 178 NOTIFY [Apr 16 21:22:37] DEBUG[3724] chan_sip.c: Header 6 [122]: Contact: "400" ;+sip.instance="" [Apr 16 21:22:37] DEBUG[3724] chan_sip.c: Header 7 [ 29]: Server: Aastra 57i/2.5.3.2002 [Apr 16 21:22:37] DEBUG[3724] chan_sip.c: Header 8 [ 17]: Content-Length: 0 [Apr 16 21:22:37] DEBUG[3724] chan_sip.c: Header 9 [ 0]: [Apr 16 21:22:37] VERBOSE[3724] chan_sip.c: --- (9 headers 0 lines) --- [Apr 16 21:22:37] DEBUG[3724] chan_sip.c: Acked pending invite 178 [Apr 16 21:22:37] DEBUG[3724] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #1567 [Apr 16 21:22:37] DEBUG[3724] chan_sip.c: Stopping retransmission on '918cd8471aacfaa1' of Request 178: Match Found [Apr 16 21:22:37] VERBOSE[3724] chan_sip.c: SIP Response message for INCOMING dialog NOTIFY arrived [Apr 16 21:22:38] DEBUG[3705] devicestate.c: No provider found, checking channel drivers for SIP - 420 [Apr 16 21:22:38] DEBUG[3705] chan_sip.c: Checking device state for peer 420 [Apr 16 21:22:38] DEBUG[3705] devicestate.c: Changing state for SIP/420 - state 1 (Not in use) [Apr 16 21:22:38] DEBUG[3705] devicestate.c: device 'SIP/420' state '1' [Apr 16 21:22:38] DEBUG[3709] app_queue.c: Device 'SIP/420' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 16 21:22:38] DEBUG[3706] devicestate.c: Checking if I can find provider for "Custom" - number: DND420 [Apr 16 21:22:38] DEBUG[3706] devicestate.c: Checking provider Custom with Custom [Apr 16 21:22:40] VERBOSE[3724] chan_sip.c: <--- SIP read from UDP:192.168.12.11:5060 ---> REGISTER sip:192.168.12.4 SIP/2.0 Via: SIP/2.0/UDP 192.168.12.11:5060;rport;branch=z9hG4bK07442e3d47 From: "gsm-2" ;tag=117267fe To: "gsm-2" Call-ID: 1fd6d67a519af3ea1403b1817e7a966a@192.168.12.11 Contact: CSeq: 13775 REGISTER Max-Forwards: 70 Expires: 60 Allow: INVITE,CANCEL,ACK,BYE,NOTIFY,REFER,OPTIONS,INFO,MESSAGE,UPDATE Authorization: Digest username="gsm-2",realm="asterisk",nonce="4a7507b4",response="8e47dc5ac771310f9c8552cbfb71e686",uri="sip:192.168.12.4",algorithm=MD5 User-Agent: Mv-37x (904290) Content-Length: 0 <-------------> [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Header 0 [ 33]: REGISTER sip:192.168.12.4 SIP/2.0 [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Header 1 [ 66]: Via: SIP/2.0/UDP 192.168.12.11:5060;rport;branch=z9hG4bK07442e3d47 [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Header 2 [ 51]: From: "gsm-2" ;tag=117267fe [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Header 3 [ 36]: To: "gsm-2" [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Header 4 [ 55]: Call-ID: 1fd6d67a519af3ea1403b1817e7a966a@192.168.12.11 [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Header 5 [ 39]: Contact: [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Header 6 [ 20]: CSeq: 13775 REGISTER [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Header 7 [ 16]: Max-Forwards: 70 [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Header 8 [ 11]: Expires: 60 [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Header 9 [ 69]: Allow: INVITE,CANCEL,ACK,BYE,NOTIFY,REFER,OPTIONS,INFO,MESSAGE,UPDATE [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Header 10 [153]: Authorization: Digest username="gsm-2",realm="asterisk",nonce="4a7507b4",response="8e47dc5ac771310f9c8552cbfb71e686",uri="sip:192.168.12.4",algorithm=MD5 [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Header 11 [ 27]: User-Agent: Mv-37x (904290) [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Header 12 [ 17]: Content-Length: 0 [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Header 13 [ 0]: [Apr 16 21:22:40] VERBOSE[3724] chan_sip.c: --- (13 headers 0 lines) --- [Apr 16 21:22:40] DEBUG[3724] acl.c: Found IP address for this socket [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.12.4:5060 [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Allocating new SIP dialog for 1fd6d67a519af3ea1403b1817e7a966a@192.168.12.11 - REGISTER (No RTP) [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Initializing initreq for method REGISTER - callid 1fd6d67a519af3ea1403b1817e7a966a@192.168.12.11 [Apr 16 21:22:40] VERBOSE[3724] chan_sip.c: Sending to 192.168.12.11 : 5060 (NAT) [Apr 16 21:22:40] VERBOSE[3724] chan_sip.c: <--- Transmitting (NAT) to 192.168.12.11:5060 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 192.168.12.11:5060;branch=z9hG4bK07442e3d47;received=192.168.12.11;rport=5060 From: "gsm-2" ;tag=117267fe To: "gsm-2" ;tag=as743aea32 Call-ID: 1fd6d67a519af3ea1403b1817e7a966a@192.168.12.11 CSeq: 13775 REGISTER Server: Media Labs PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="68d9bd4a" Content-Length: 0 <------------> [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 192.168.12.11:5060 [Apr 16 21:22:40] VERBOSE[3724] chan_sip.c: Scheduling destruction of SIP dialog '1fd6d67a519af3ea1403b1817e7a966a@192.168.12.11' in 32000 ms (Method: REGISTER) [Apr 16 21:22:40] VERBOSE[3724] chan_sip.c: <--- SIP read from UDP:192.168.12.11:5060 ---> REGISTER sip:192.168.12.4 SIP/2.0 Via: SIP/2.0/UDP 192.168.12.11:5060;rport;branch=z9hG4bKe4b7da0df8 From: "gsm-2" ;tag=117267fe To: "gsm-2" Call-ID: 1fd6d67a519af3ea1403b1817e7a966a@192.168.12.11 Contact: CSeq: 13776 REGISTER Max-Forwards: 70 Expires: 60 Allow: INVITE,CANCEL,ACK,BYE,NOTIFY,REFER,OPTIONS,INFO,MESSAGE,UPDATE Authorization: Digest username="gsm-2",realm="asterisk",nonce="68d9bd4a",response="2fa2002bf810240ec73352151cef1c97",uri="sip:192.168.12.4",algorithm=MD5 User-Agent: Mv-37x (904290) Content-Length: 0 <-------------> [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Header 0 [ 33]: REGISTER sip:192.168.12.4 SIP/2.0 [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Header 1 [ 66]: Via: SIP/2.0/UDP 192.168.12.11:5060;rport;branch=z9hG4bKe4b7da0df8 [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Header 2 [ 51]: From: "gsm-2" ;tag=117267fe [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Header 3 [ 36]: To: "gsm-2" [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Header 4 [ 55]: Call-ID: 1fd6d67a519af3ea1403b1817e7a966a@192.168.12.11 [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Header 5 [ 39]: Contact: [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Header 6 [ 20]: CSeq: 13776 REGISTER [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Header 7 [ 16]: Max-Forwards: 70 [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Header 8 [ 11]: Expires: 60 [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Header 9 [ 69]: Allow: INVITE,CANCEL,ACK,BYE,NOTIFY,REFER,OPTIONS,INFO,MESSAGE,UPDATE [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Header 10 [153]: Authorization: Digest username="gsm-2",realm="asterisk",nonce="68d9bd4a",response="2fa2002bf810240ec73352151cef1c97",uri="sip:192.168.12.4",algorithm=MD5 [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Header 11 [ 27]: User-Agent: Mv-37x (904290) [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Header 12 [ 17]: Content-Length: 0 [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Header 13 [ 0]: [Apr 16 21:22:40] VERBOSE[3724] chan_sip.c: --- (13 headers 0 lines) --- [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Initializing initreq for method REGISTER - callid 1fd6d67a519af3ea1403b1817e7a966a@192.168.12.11 [Apr 16 21:22:40] VERBOSE[3724] chan_sip.c: Sending to 192.168.12.11 : 5060 (NAT) [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Allocating new SIP dialog for 1c78de9c17a0477065b9d899098ee9fb@192.168.12.4 - OPTIONS (No RTP) [Apr 16 21:22:40] DEBUG[3724] acl.c: Found IP address for this socket [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.12.4:5060 [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Initializing initreq for method OPTIONS - callid 5ad242472f5b38c74a81f3f83d03c4db@192.168.12.4 [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Header 0 [ 44]: OPTIONS sip:gsm-2@192.168.12.11:5060 SIP/2.0 [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Header 1 [ 63]: Via: SIP/2.0/UDP 192.168.12.4:5060;branch=z9hG4bK4615fdd5;rport [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Header 3 [ 59]: From: "asterisk" ;tag=as40635cf8 [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Header 4 [ 34]: To: [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Header 5 [ 36]: Contact: [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Header 6 [ 54]: Call-ID: 5ad242472f5b38c74a81f3f83d03c4db@192.168.12.4 [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Header 7 [ 17]: CSeq: 102 OPTIONS [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Header 8 [ 26]: User-Agent: Media Labs PBX [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Header 9 [ 35]: Date: Fri, 16 Apr 2010 19:22:40 GMT [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Header 10 [ 72]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Header 11 [ 26]: Supported: replaces, timer [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Header 12 [ 17]: Content-Length: 0 [Apr 16 21:22:40] VERBOSE[3724] chan_sip.c: Reliably Transmitting (NAT) to 192.168.12.11:5060: OPTIONS sip:gsm-2@192.168.12.11:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.12.4:5060;branch=z9hG4bK4615fdd5;rport Max-Forwards: 70 From: "asterisk" ;tag=as40635cf8 To: Contact: Call-ID: 5ad242472f5b38c74a81f3f83d03c4db@192.168.12.4 CSeq: 102 OPTIONS User-Agent: Media Labs PBX Date: Fri, 16 Apr 2010 19:22:40 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer Content-Length: 0 --- [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #1570 [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 192.168.12.11:5060 [Apr 16 21:22:40] VERBOSE[3724] chan_sip.c: <--- Transmitting (NAT) to 192.168.12.11:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.12.11:5060;branch=z9hG4bKe4b7da0df8;received=192.168.12.11;rport=5060 From: "gsm-2" ;tag=117267fe To: "gsm-2" ;tag=as743aea32 Call-ID: 1fd6d67a519af3ea1403b1817e7a966a@192.168.12.11 CSeq: 13776 REGISTER Server: Media Labs PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer Expires: 60 Contact: ;expires=60 Date: Fri, 16 Apr 2010 19:22:40 GMT Content-Length: 0 <------------> [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.12.11:5060 [Apr 16 21:22:40] VERBOSE[3724] chan_sip.c: Scheduling destruction of SIP dialog '1fd6d67a519af3ea1403b1817e7a966a@192.168.12.11' in 32000 ms (Method: REGISTER) [Apr 16 21:22:40] DEBUG[3705] devicestate.c: No provider found, checking channel drivers for SIP - gsm-2 [Apr 16 21:22:40] DEBUG[3705] chan_sip.c: Checking device state for peer gsm-2 [Apr 16 21:22:40] DEBUG[3705] devicestate.c: Changing state for SIP/gsm-2 - state 1 (Not in use) [Apr 16 21:22:40] DEBUG[3705] devicestate.c: device 'SIP/gsm-2' state '1' [Apr 16 21:22:40] DEBUG[3709] app_queue.c: Device 'SIP/gsm-2' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 16 21:22:40] VERBOSE[3724] chan_sip.c: <--- SIP read from UDP:192.168.12.11:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.12.4:5060;rport=5060;received=192.168.12.4;branch=z9hG4bK4615fdd5 From: "asterisk" ;tag=as40635cf8 To: ;tag=4543a00d Call-ID: 5ad242472f5b38c74a81f3f83d03c4db@192.168.12.4 CSeq: 102 OPTIONS Allow: INVITE,CANCEL,ACK,BYE,NOTIFY,REFER,OPTIONS,INFO,MESSAGE,UPDATE Content-Length: 0 <-------------> [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Header 1 [ 90]: Via: SIP/2.0/UDP 192.168.12.4:5060;rport=5060;received=192.168.12.4;branch=z9hG4bK4615fdd5 [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Header 2 [ 59]: From: "asterisk" ;tag=as40635cf8 [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Header 3 [ 47]: To: ;tag=4543a00d [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Header 4 [ 54]: Call-ID: 5ad242472f5b38c74a81f3f83d03c4db@192.168.12.4 [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Header 5 [ 17]: CSeq: 102 OPTIONS [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Header 6 [ 69]: Allow: INVITE,CANCEL,ACK,BYE,NOTIFY,REFER,OPTIONS,INFO,MESSAGE,UPDATE [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Header 7 [ 17]: Content-Length: 0 [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Header 8 [ 0]: [Apr 16 21:22:40] VERBOSE[3724] chan_sip.c: --- (8 headers 0 lines) --- [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #1570 [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Stopping retransmission on '5ad242472f5b38c74a81f3f83d03c4db@192.168.12.4' of Request 102: Match Found [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Allocating new SIP dialog for 77c8b6407f48eaba2e8fd2fa23236386@192.168.12.4 - OPTIONS (No RTP) [Apr 16 21:22:40] DEBUG[3724] acl.c: Found IP address for this socket [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.12.4:5060 [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Initializing initreq for method OPTIONS - callid 4e86a33845766d6d0141b26d64aa7f77@192.168.12.4 [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Header 0 [ 38]: OPTIONS sip:472@192.168.12.170 SIP/2.0 [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Header 1 [ 63]: Via: SIP/2.0/UDP 192.168.12.4:5060;branch=z9hG4bK0047b7da;rport [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Header 3 [ 59]: From: "asterisk" ;tag=as22cac006 [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Header 4 [ 28]: To: [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Header 5 [ 36]: Contact: [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Header 6 [ 54]: Call-ID: 4e86a33845766d6d0141b26d64aa7f77@192.168.12.4 [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Header 7 [ 17]: CSeq: 102 OPTIONS [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Header 8 [ 26]: User-Agent: Media Labs PBX [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Header 9 [ 35]: Date: Fri, 16 Apr 2010 19:22:40 GMT [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Header 10 [ 72]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Header 11 [ 26]: Supported: replaces, timer [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Header 12 [ 17]: Content-Length: 0 [Apr 16 21:22:40] VERBOSE[3724] chan_sip.c: Reliably Transmitting (NAT) to 192.168.12.170:5060: OPTIONS sip:472@192.168.12.170 SIP/2.0 Via: SIP/2.0/UDP 192.168.12.4:5060;branch=z9hG4bK0047b7da;rport Max-Forwards: 70 From: "asterisk" ;tag=as22cac006 To: Contact: Call-ID: 4e86a33845766d6d0141b26d64aa7f77@192.168.12.4 CSeq: 102 OPTIONS User-Agent: Media Labs PBX Date: Fri, 16 Apr 2010 19:22:40 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer Content-Length: 0 --- [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #1574 [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 192.168.12.170:5060 [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Destroying SIP dialog 5ad242472f5b38c74a81f3f83d03c4db@192.168.12.4 [Apr 16 21:22:40] VERBOSE[3724] chan_sip.c: Really destroying SIP dialog '5ad242472f5b38c74a81f3f83d03c4db@192.168.12.4' Method: OPTIONS [Apr 16 21:22:40] VERBOSE[3724] chan_sip.c: <--- SIP read from UDP:192.168.12.170:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.12.4:5060;branch=z9hG4bK0047b7da;rport=5060 From: "asterisk" ;tag=as22cac006 To: ;tag=t-1978a2a07e6b1d3d126 Call-ID: 4e86a33845766d6d0141b26d64aa7f77@192.168.12.4 CSeq: 102 OPTIONS Supported: replaces Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, REFER, NOTIFY, INFO, MESSAGE Content-Type: application/sdp Accept: application/sdp Content-Length: 230 v=0 o=user 1271445760 1271445760 IN IP4 0.0.0.0 s=- c=IN IP4 0.0.0.0 t=0 0 m=audio 0 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-11 a=ptime:20 a=silenceSupp:off - - - - a=sendrecv <-------------> [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Header 1 [ 68]: Via: SIP/2.0/UDP 192.168.12.4:5060;branch=z9hG4bK0047b7da;rport=5060 [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Header 2 [ 59]: From: "asterisk" ;tag=as22cac006 [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Header 3 [ 54]: To: ;tag=t-1978a2a07e6b1d3d126 [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Header 4 [ 54]: Call-ID: 4e86a33845766d6d0141b26d64aa7f77@192.168.12.4 [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Header 5 [ 17]: CSeq: 102 OPTIONS [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Header 6 [ 19]: Supported: replaces [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Header 7 [ 70]: Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, REFER, NOTIFY, INFO, MESSAGE [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Header 8 [ 29]: Content-Type: application/sdp [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Header 9 [ 23]: Accept: application/sdp [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Header 10 [ 21]: Content-Length: 230 [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Header 11 [ 0]: [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Body 0 [ 3]: v=0 [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Body 1 [ 43]: o=user 1271445760 1271445760 IN IP4 0.0.0.0 [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Body 2 [ 3]: s=- [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Body 3 [ 16]: c=IN IP4 0.0.0.0 [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Body 4 [ 5]: t=0 0 [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Body 5 [ 23]: m=audio 0 RTP/AVP 8 101 [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Body 6 [ 20]: a=rtpmap:8 PCMA/8000 [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Body 7 [ 33]: a=rtpmap:101 telephone-event/8000 [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Body 8 [ 15]: a=fmtp:101 0-11 [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Body 9 [ 10]: a=ptime:20 [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Body 10 [ 25]: a=silenceSupp:off - - - - [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Body 11 [ 10]: a=sendrecv [Apr 16 21:22:40] VERBOSE[3724] chan_sip.c: --- (11 headers 12 lines) --- [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #1574 [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Stopping retransmission on '4e86a33845766d6d0141b26d64aa7f77@192.168.12.4' of Request 102: Match Found [Apr 16 21:22:40] DEBUG[3724] chan_sip.c: Destroying SIP dialog 4e86a33845766d6d0141b26d64aa7f77@192.168.12.4 [Apr 16 21:22:40] VERBOSE[3724] chan_sip.c: Really destroying SIP dialog '4e86a33845766d6d0141b26d64aa7f77@192.168.12.4' Method: OPTIONS [Apr 16 21:22:43] DEBUG[3724] chan_sip.c: Auto destroying SIP dialog '6488bcdb3c17298c197bf63e34f3f85a@192.168.12.4' [Apr 16 21:22:43] DEBUG[3724] chan_sip.c: Destroying SIP dialog 6488bcdb3c17298c197bf63e34f3f85a@192.168.12.4 [Apr 16 21:22:43] VERBOSE[3724] chan_sip.c: Really destroying SIP dialog '6488bcdb3c17298c197bf63e34f3f85a@192.168.12.4' Method: INVITE [Apr 16 21:22:46] VERBOSE[3724] chan_sip.c: <--- SIP read from UDP:192.168.12.100:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.12.4:5060;branch=z9hG4bK0964c426;rport=5060;received=192.168.12.4 From: "Polycom SPIP330" ;tag=as2a7e2a63 To: ;tag=4014014111 Call-ID: 6488bcdb3c17298c197bf63e34f3f85a@192.168.12.4 CSeq: 102 INVITE Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, OPTIONS, UPDATE, PRACK, SUBSCRIBE, INFO Allow-Events: talk, hold, conference, aastra-xml, LocalModeStatus Contact: "400" ;+sip.instance="" Server: Aastra 57i/2.5.3.2002 Supported: gruu, path, timer, replaces Content-Type: application/sdp Content-Length: 261 v=0 o=MxSIP 0 0 IN IP4 192.168.12.100 s=SIP Call c=IN IP4 192.168.12.100 t=0 0 m=audio 3000 RTP/AVP 8 0 101 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=silenceSupp:off - - - - a=fmtp:101 0-15 a=ptime:20 a=sendrecv <-------------> [Apr 16 21:22:46] DEBUG[3724] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Apr 16 21:22:46] DEBUG[3724] chan_sip.c: Header 1 [ 90]: Via: SIP/2.0/UDP 192.168.12.4:5060;branch=z9hG4bK0964c426;rport=5060;received=192.168.12.4 [Apr 16 21:22:46] DEBUG[3724] chan_sip.c: Header 2 [ 61]: From: "Polycom SPIP330" ;tag=as2a7e2a63 [Apr 16 21:22:46] DEBUG[3724] chan_sip.c: Header 3 [ 62]: To: ;tag=4014014111 [Apr 16 21:22:46] DEBUG[3724] chan_sip.c: Header 4 [ 54]: Call-ID: 6488bcdb3c17298c197bf63e34f3f85a@192.168.12.4 [Apr 16 21:22:46] DEBUG[3724] chan_sip.c: Header 5 [ 16]: CSeq: 102 INVITE [Apr 16 21:22:46] DEBUG[3724] chan_sip.c: Header 6 [ 88]: Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, OPTIONS, UPDATE, PRACK, SUBSCRIBE, INFO [Apr 16 21:22:46] DEBUG[3724] chan_sip.c: Header 7 [ 65]: Allow-Events: talk, hold, conference, aastra-xml, LocalModeStatus [Apr 16 21:22:46] DEBUG[3724] chan_sip.c: Header 8 [122]: Contact: "400" ;+sip.instance="" [Apr 16 21:22:46] DEBUG[3724] chan_sip.c: Header 9 [ 29]: Server: Aastra 57i/2.5.3.2002 [Apr 16 21:22:46] DEBUG[3724] chan_sip.c: Header 10 [ 38]: Supported: gruu, path, timer, replaces [Apr 16 21:22:46] DEBUG[3724] chan_sip.c: Header 11 [ 29]: Content-Type: application/sdp [Apr 16 21:22:46] DEBUG[3724] chan_sip.c: Header 12 [ 19]: Content-Length: 261 [Apr 16 21:22:46] DEBUG[3724] chan_sip.c: Header 13 [ 0]: [Apr 16 21:22:46] DEBUG[3724] chan_sip.c: Body 0 [ 3]: v=0 [Apr 16 21:22:46] DEBUG[3724] chan_sip.c: Body 1 [ 33]: o=MxSIP 0 0 IN IP4 192.168.12.100 [Apr 16 21:22:46] DEBUG[3724] chan_sip.c: Body 2 [ 10]: s=SIP Call [Apr 16 21:22:46] DEBUG[3724] chan_sip.c: Body 3 [ 23]: c=IN IP4 192.168.12.100 [Apr 16 21:22:46] DEBUG[3724] chan_sip.c: Body 4 [ 5]: t=0 0 [Apr 16 21:22:46] DEBUG[3724] chan_sip.c: Body 5 [ 28]: m=audio 3000 RTP/AVP 8 0 101 [Apr 16 21:22:46] DEBUG[3724] chan_sip.c: Body 6 [ 20]: a=rtpmap:8 PCMA/8000 [Apr 16 21:22:46] DEBUG[3724] chan_sip.c: Body 7 [ 20]: a=rtpmap:0 PCMU/8000 [Apr 16 21:22:46] DEBUG[3724] chan_sip.c: Body 8 [ 33]: a=rtpmap:101 telephone-event/8000 [Apr 16 21:22:46] DEBUG[3724] chan_sip.c: Body 9 [ 25]: a=silenceSupp:off - - - - [Apr 16 21:22:46] DEBUG[3724] chan_sip.c: Body 10 [ 15]: a=fmtp:101 0-15 [Apr 16 21:22:46] DEBUG[3724] chan_sip.c: Body 11 [ 10]: a=ptime:20 [Apr 16 21:22:46] DEBUG[3724] chan_sip.c: Body 12 [ 10]: a=sendrecv [Apr 16 21:22:46] VERBOSE[3724] chan_sip.c: --- (13 headers 13 lines) --- [Apr 16 21:22:46] DEBUG[3724] chan_sip.c: That's odd... Got a response on a call we dont know about. Callid 6488bcdb3c17298c197bf63e34f3f85a@192.168.12.4 [Apr 16 21:22:46] DEBUG[3724] chan_sip.c: Invalid SIP message - rejected , no callid, len 976 [Apr 16 21:22:47] VERBOSE[3724] chan_sip.c: <--- SIP read from UDP:192.168.12.100:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.12.4:5060;branch=z9hG4bK0964c426;rport=5060;received=192.168.12.4 From: "Polycom SPIP330" ;tag=as2a7e2a63 To: ;tag=4014014111 Call-ID: 6488bcdb3c17298c197bf63e34f3f85a@192.168.12.4 CSeq: 102 INVITE Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, OPTIONS, UPDATE, PRACK, SUBSCRIBE, INFO Allow-Events: talk, hold, conference, aastra-xml, LocalModeStatus Contact: "400" ;+sip.instance="" Server: Aastra 57i/2.5.3.2002 Supported: gruu, path, timer, replaces Content-Type: application/sdp Content-Length: 261 v=0 o=MxSIP 0 0 IN IP4 192.168.12.100 s=SIP Call c=IN IP4 192.168.12.100 t=0 0 m=audio 3000 RTP/AVP 8 0 101 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=silenceSupp:off - - - - a=fmtp:101 0-15 a=ptime:20 a=sendrecv <-------------> [Apr 16 21:22:47] DEBUG[3724] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Apr 16 21:22:47] DEBUG[3724] chan_sip.c: Header 1 [ 90]: Via: SIP/2.0/UDP 192.168.12.4:5060;branch=z9hG4bK0964c426;rport=5060;received=192.168.12.4 [Apr 16 21:22:47] DEBUG[3724] chan_sip.c: Header 2 [ 61]: From: "Polycom SPIP330" ;tag=as2a7e2a63 [Apr 16 21:22:47] DEBUG[3724] chan_sip.c: Header 3 [ 62]: To: ;tag=4014014111 [Apr 16 21:22:47] DEBUG[3724] chan_sip.c: Header 4 [ 54]: Call-ID: 6488bcdb3c17298c197bf63e34f3f85a@192.168.12.4 [Apr 16 21:22:47] DEBUG[3724] chan_sip.c: Header 5 [ 16]: CSeq: 102 INVITE [Apr 16 21:22:47] DEBUG[3724] chan_sip.c: Header 6 [ 88]: Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, OPTIONS, UPDATE, PRACK, SUBSCRIBE, INFO [Apr 16 21:22:47] DEBUG[3724] chan_sip.c: Header 7 [ 65]: Allow-Events: talk, hold, conference, aastra-xml, LocalModeStatus [Apr 16 21:22:47] DEBUG[3724] chan_sip.c: Header 8 [122]: Contact: "400" ;+sip.instance="" [Apr 16 21:22:47] DEBUG[3724] chan_sip.c: Header 9 [ 29]: Server: Aastra 57i/2.5.3.2002 [Apr 16 21:22:47] DEBUG[3724] chan_sip.c: Header 10 [ 38]: Supported: gruu, path, timer, replaces [Apr 16 21:22:47] DEBUG[3724] chan_sip.c: Header 11 [ 29]: Content-Type: application/sdp [Apr 16 21:22:47] DEBUG[3724] chan_sip.c: Header 12 [ 19]: Content-Length: 261 [Apr 16 21:22:47] DEBUG[3724] chan_sip.c: Header 13 [ 0]: [Apr 16 21:22:47] DEBUG[3724] chan_sip.c: Body 0 [ 3]: v=0 [Apr 16 21:22:47] DEBUG[3724] chan_sip.c: Body 1 [ 33]: o=MxSIP 0 0 IN IP4 192.168.12.100 [Apr 16 21:22:47] DEBUG[3724] chan_sip.c: Body 2 [ 10]: s=SIP Call [Apr 16 21:22:47] DEBUG[3724] chan_sip.c: Body 3 [ 23]: c=IN IP4 192.168.12.100 [Apr 16 21:22:47] DEBUG[3724] chan_sip.c: Body 4 [ 5]: t=0 0 [Apr 16 21:22:47] DEBUG[3724] chan_sip.c: Body 5 [ 28]: m=audio 3000 RTP/AVP 8 0 101 [Apr 16 21:22:47] DEBUG[3724] chan_sip.c: Body 6 [ 20]: a=rtpmap:8 PCMA/8000 [Apr 16 21:22:47] DEBUG[3724] chan_sip.c: Body 7 [ 20]: a=rtpmap:0 PCMU/8000 [Apr 16 21:22:47] DEBUG[3724] chan_sip.c: Body 8 [ 33]: a=rtpmap:101 telephone-event/8000 [Apr 16 21:22:47] DEBUG[3724] chan_sip.c: Body 9 [ 25]: a=silenceSupp:off - - - - [Apr 16 21:22:47] DEBUG[3724] chan_sip.c: Body 10 [ 15]: a=fmtp:101 0-15 [Apr 16 21:22:47] DEBUG[3724] chan_sip.c: Body 11 [ 10]: a=ptime:20 [Apr 16 21:22:47] DEBUG[3724] chan_sip.c: Body 12 [ 10]: a=sendrecv [Apr 16 21:22:47] VERBOSE[3724] chan_sip.c: --- (13 headers 13 lines) --- [Apr 16 21:22:47] DEBUG[3724] chan_sip.c: That's odd... Got a response on a call we dont know about. Callid 6488bcdb3c17298c197bf63e34f3f85a@192.168.12.4 [Apr 16 21:22:47] DEBUG[3724] chan_sip.c: Invalid SIP message - rejected , no callid, len 976 [Apr 16 21:22:49] VERBOSE[3724] chan_sip.c: <--- SIP read from UDP:192.168.12.100:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.12.4:5060;branch=z9hG4bK0964c426;rport=5060;received=192.168.12.4 From: "Polycom SPIP330" ;tag=as2a7e2a63 To: ;tag=4014014111 Call-ID: 6488bcdb3c17298c197bf63e34f3f85a@192.168.12.4 CSeq: 102 INVITE Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, OPTIONS, UPDATE, PRACK, SUBSCRIBE, INFO Allow-Events: talk, hold, conference, aastra-xml, LocalModeStatus Contact: "400" ;+sip.instance="" Server: Aastra 57i/2.5.3.2002 Supported: gruu, path, timer, replaces Content-Type: application/sdp Content-Length: 261 v=0 o=MxSIP 0 0 IN IP4 192.168.12.100 s=SIP Call c=IN IP4 192.168.12.100 t=0 0 m=audio 3000 RTP/AVP 8 0 101 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=silenceSupp:off - - - - a=fmtp:101 0-15 a=ptime:20 a=sendrecv <-------------> [Apr 16 21:22:49] DEBUG[3724] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Apr 16 21:22:49] DEBUG[3724] chan_sip.c: Header 1 [ 90]: Via: SIP/2.0/UDP 192.168.12.4:5060;branch=z9hG4bK0964c426;rport=5060;received=192.168.12.4 [Apr 16 21:22:49] DEBUG[3724] chan_sip.c: Header 2 [ 61]: From: "Polycom SPIP330" ;tag=as2a7e2a63 [Apr 16 21:22:49] DEBUG[3724] chan_sip.c: Header 3 [ 62]: To: ;tag=4014014111 [Apr 16 21:22:49] DEBUG[3724] chan_sip.c: Header 4 [ 54]: Call-ID: 6488bcdb3c17298c197bf63e34f3f85a@192.168.12.4 [Apr 16 21:22:49] DEBUG[3724] chan_sip.c: Header 5 [ 16]: CSeq: 102 INVITE [Apr 16 21:22:49] DEBUG[3724] chan_sip.c: Header 6 [ 88]: Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, OPTIONS, UPDATE, PRACK, SUBSCRIBE, INFO [Apr 16 21:22:49] DEBUG[3724] chan_sip.c: Header 7 [ 65]: Allow-Events: talk, hold, conference, aastra-xml, LocalModeStatus [Apr 16 21:22:49] DEBUG[3724] chan_sip.c: Header 8 [122]: Contact: "400" ;+sip.instance="" [Apr 16 21:22:49] DEBUG[3724] chan_sip.c: Header 9 [ 29]: Server: Aastra 57i/2.5.3.2002 [Apr 16 21:22:49] DEBUG[3724] chan_sip.c: Header 10 [ 38]: Supported: gruu, path, timer, replaces [Apr 16 21:22:49] DEBUG[3724] chan_sip.c: Header 11 [ 29]: Content-Type: application/sdp [Apr 16 21:22:49] DEBUG[3724] chan_sip.c: Header 12 [ 19]: Content-Length: 261 [Apr 16 21:22:49] DEBUG[3724] chan_sip.c: Header 13 [ 0]: [Apr 16 21:22:49] DEBUG[3724] chan_sip.c: Body 0 [ 3]: v=0 [Apr 16 21:22:49] DEBUG[3724] chan_sip.c: Body 1 [ 33]: o=MxSIP 0 0 IN IP4 192.168.12.100 [Apr 16 21:22:49] DEBUG[3724] chan_sip.c: Body 2 [ 10]: s=SIP Call [Apr 16 21:22:49] DEBUG[3724] chan_sip.c: Body 3 [ 23]: c=IN IP4 192.168.12.100 [Apr 16 21:22:49] DEBUG[3724] chan_sip.c: Body 4 [ 5]: t=0 0 [Apr 16 21:22:49] DEBUG[3724] chan_sip.c: Body 5 [ 28]: m=audio 3000 RTP/AVP 8 0 101 [Apr 16 21:22:49] DEBUG[3724] chan_sip.c: Body 6 [ 20]: a=rtpmap:8 PCMA/8000 [Apr 16 21:22:49] DEBUG[3724] chan_sip.c: Body 7 [ 20]: a=rtpmap:0 PCMU/8000 [Apr 16 21:22:49] DEBUG[3724] chan_sip.c: Body 8 [ 33]: a=rtpmap:101 telephone-event/8000 [Apr 16 21:22:49] DEBUG[3724] chan_sip.c: Body 9 [ 25]: a=silenceSupp:off - - - - [Apr 16 21:22:49] DEBUG[3724] chan_sip.c: Body 10 [ 15]: a=fmtp:101 0-15 [Apr 16 21:22:49] DEBUG[3724] chan_sip.c: Body 11 [ 10]: a=ptime:20 [Apr 16 21:22:49] DEBUG[3724] chan_sip.c: Body 12 [ 10]: a=sendrecv [Apr 16 21:22:49] VERBOSE[3724] chan_sip.c: --- (13 headers 13 lines) --- [Apr 16 21:22:49] DEBUG[3724] chan_sip.c: That's odd... Got a response on a call we dont know about. Callid 6488bcdb3c17298c197bf63e34f3f85a@192.168.12.4 [Apr 16 21:22:49] DEBUG[3724] chan_sip.c: Invalid SIP message - rejected , no callid, len 976 [Apr 16 21:22:50] VERBOSE[3724] chan_sip.c: <--- SIP read from UDP:192.168.12.100:5060 ---> BYE sip:420@192.168.12.4 SIP/2.0 Via: SIP/2.0/UDP 192.168.12.100:5060;branch=z9hG4bKa460bb368a356a39a.bc2292fd43074ee11 Max-Forwards: 70 From: ;tag=4014014111 To: "Polycom SPIP330" ;tag=as2a7e2a63 Call-ID: 6488bcdb3c17298c197bf63e34f3f85a@192.168.12.4 CSeq: 23169 BYE Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, OPTIONS, UPDATE, PRACK, SUBSCRIBE, INFO Allow-Events: talk, hold, conference, aastra-xml, LocalModeStatus Supported: gruu, path, timer User-Agent: Aastra 57i/2.5.3.2002 Content-Length: 0 <-------------> [Apr 16 21:22:50] DEBUG[3724] chan_sip.c: Header 0 [ 32]: BYE sip:420@192.168.12.4 SIP/2.0 [Apr 16 21:22:50] DEBUG[3724] chan_sip.c: Header 1 [ 86]: Via: SIP/2.0/UDP 192.168.12.100:5060;branch=z9hG4bKa460bb368a356a39a.bc2292fd43074ee11 [Apr 16 21:22:50] DEBUG[3724] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Apr 16 21:22:50] DEBUG[3724] chan_sip.c: Header 3 [ 64]: From: ;tag=4014014111 [Apr 16 21:22:50] DEBUG[3724] chan_sip.c: Header 4 [ 59]: To: "Polycom SPIP330" ;tag=as2a7e2a63 [Apr 16 21:22:50] DEBUG[3724] chan_sip.c: Header 5 [ 54]: Call-ID: 6488bcdb3c17298c197bf63e34f3f85a@192.168.12.4 [Apr 16 21:22:50] DEBUG[3724] chan_sip.c: Header 6 [ 15]: CSeq: 23169 BYE [Apr 16 21:22:50] DEBUG[3724] chan_sip.c: Header 7 [ 88]: Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, OPTIONS, UPDATE, PRACK, SUBSCRIBE, INFO [Apr 16 21:22:50] DEBUG[3724] chan_sip.c: Header 8 [ 65]: Allow-Events: talk, hold, conference, aastra-xml, LocalModeStatus [Apr 16 21:22:50] DEBUG[3724] chan_sip.c: Header 9 [ 28]: Supported: gruu, path, timer [Apr 16 21:22:50] DEBUG[3724] chan_sip.c: Header 10 [ 33]: User-Agent: Aastra 57i/2.5.3.2002 [Apr 16 21:22:50] DEBUG[3724] chan_sip.c: Header 11 [ 17]: Content-Length: 0 [Apr 16 21:22:50] DEBUG[3724] chan_sip.c: Header 12 [ 0]: [Apr 16 21:22:50] VERBOSE[3724] chan_sip.c: --- (12 headers 0 lines) --- [Apr 16 21:22:50] DEBUG[3724] acl.c: Found IP address for this socket [Apr 16 21:22:50] DEBUG[3724] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.12.4:5060 [Apr 16 21:22:50] VERBOSE[3724] chan_sip.c: <--- Transmitting (NAT) to 192.168.12.100:5060 ---> SIP/2.0 481 Call leg/transaction does not exist Via: SIP/2.0/UDP 192.168.12.100:5060;branch=z9hG4bKa460bb368a356a39a.bc2292fd43074ee11;received=192.168.12.100 From: ;tag=4014014111 To: "Polycom SPIP330" ;tag=as2a7e2a63 Call-ID: 6488bcdb3c17298c197bf63e34f3f85a@192.168.12.4 CSeq: 23169 BYE Server: Media Labs PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer Content-Length: 0 <------------> [Apr 16 21:22:50] DEBUG[3724] chan_sip.c: Trying to put 'SIP/2.0 481' onto UDP socket destined for 192.168.12.100:5060 [Apr 16 21:22:50] DEBUG[3724] chan_sip.c: That's odd... Got a request in unknown dialog. Callid 6488bcdb3c17298c197bf63e34f3f85a@192.168.12.4 [Apr 16 21:22:50] DEBUG[3724] chan_sip.c: Invalid SIP message - rejected , no callid, len 583 [Apr 16 21:22:51] VERBOSE[3724] chan_sip.c: <--- SIP read from UDP:192.168.12.150:5060 ---> SUBSCRIBE sip:405@192.168.12.4:5060 SIP/2.0 Accept: application/dialog-info+xml Via: SIP/2.0/UDP 192.168.12.150;branch=z9hG4bKd02f07217c58a9083 Max-Forwards: 70 From: "450" ;tag=2548c837e7 To: Call-ID: ef76e4d26c5fd41a CSeq: 1323 SUBSCRIBE Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, OPTIONS, UPDATE, PRACK, SUBSCRIBE, INFO Allow-Events: talk, hold, conference Authorization: Digest username="450",realm="asterisk",nonce="35f380eb",uri="sip:405@192.168.12.4:5060",response="53dd77596bff3786d3d6dd3f4e200f1c",algorithm=MD5 Contact: "450" ;+sip.instance="" Event: dialog Expires: 3600 User-Agent: Aastra 6739i/3.0.1.38 Content-Length: 0 <-------------> [Apr 16 21:22:51] DEBUG[3724] chan_sip.c: Header 0 [ 43]: SUBSCRIBE sip:405@192.168.12.4:5060 SIP/2.0 [Apr 16 21:22:51] DEBUG[3724] chan_sip.c: Header 1 [ 35]: Accept: application/dialog-info+xml [Apr 16 21:22:51] DEBUG[3724] chan_sip.c: Header 2 [ 63]: Via: SIP/2.0/UDP 192.168.12.150;branch=z9hG4bKd02f07217c58a9083 [Apr 16 21:22:51] DEBUG[3724] chan_sip.c: Header 3 [ 16]: Max-Forwards: 70 [Apr 16 21:22:51] DEBUG[3724] chan_sip.c: Header 4 [ 54]: From: "450" ;tag=2548c837e7 [Apr 16 21:22:51] DEBUG[3724] chan_sip.c: Header 5 [ 31]: To: [Apr 16 21:22:51] DEBUG[3724] chan_sip.c: Header 6 [ 25]: Call-ID: ef76e4d26c5fd41a [Apr 16 21:22:51] DEBUG[3724] chan_sip.c: Header 7 [ 20]: CSeq: 1323 SUBSCRIBE [Apr 16 21:22:51] DEBUG[3724] chan_sip.c: Header 8 [ 87]: Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, OPTIONS, UPDATE, PRACK, SUBSCRIBE, INFO [Apr 16 21:22:51] DEBUG[3724] chan_sip.c: Header 9 [ 36]: Allow-Events: talk, hold, conference [Apr 16 21:22:51] DEBUG[3724] chan_sip.c: Header 10 [160]: Authorization: Digest username="450",realm="asterisk",nonce="35f380eb",uri="sip:405@192.168.12.4:5060",response="53dd77596bff3786d3d6dd3f4e200f1c",algorithm=MD5 [Apr 16 21:22:51] DEBUG[3724] chan_sip.c: Header 11 [122]: Contact: "450" ;+sip.instance="" [Apr 16 21:22:51] DEBUG[3724] chan_sip.c: Header 12 [ 13]: Event: dialog [Apr 16 21:22:51] DEBUG[3724] chan_sip.c: Header 13 [ 13]: Expires: 3600 [Apr 16 21:22:51] DEBUG[3724] chan_sip.c: Header 14 [ 33]: User-Agent: Aastra 6739i/3.0.1.38 [Apr 16 21:22:51] DEBUG[3724] chan_sip.c: Header 15 [ 17]: Content-Length: 0 [Apr 16 21:22:51] DEBUG[3724] chan_sip.c: Header 16 [ 0]: [Apr 16 21:22:51] VERBOSE[3724] chan_sip.c: --- (16 headers 0 lines) --- [Apr 16 21:22:51] DEBUG[3724] acl.c: Found IP address for this socket [Apr 16 21:22:51] DEBUG[3724] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.12.4:5060 [Apr 16 21:22:51] DEBUG[3724] chan_sip.c: Allocating new SIP dialog for ef76e4d26c5fd41a - SUBSCRIBE (No RTP) [Apr 16 21:22:51] DEBUG[3724] chan_sip.c: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Apr 16 21:22:51] VERBOSE[3724] chan_sip.c: Creating new subscription [Apr 16 21:22:51] DEBUG[3724] chan_sip.c: Initializing initreq for method SUBSCRIBE - callid ef76e4d26c5fd41a [Apr 16 21:22:51] VERBOSE[3724] chan_sip.c: Sending to 192.168.12.150 : 5060 (NAT) [Apr 16 21:22:51] DEBUG[3724] chan_sip.c: build_route: Contact hop: "450" ;+sip.instance="" [Apr 16 21:22:51] VERBOSE[3724] chan_sip.c: list_route: hop: [Apr 16 21:22:51] VERBOSE[3724] chan_sip.c: Found peer '450' for '450' from 192.168.12.150:5060 [Apr 16 21:22:51] VERBOSE[3724] chan_sip.c: <--- Transmitting (NAT) to 192.168.12.150:5060 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 192.168.12.150;branch=z9hG4bKd02f07217c58a9083;received=192.168.12.150 From: "450" ;tag=2548c837e7 To: ;tag=as55957524 Call-ID: ef76e4d26c5fd41a CSeq: 1323 SUBSCRIBE Server: Media Labs PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="04b392c1" Content-Length: 0 <------------> [Apr 16 21:22:51] DEBUG[3724] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 192.168.12.150:5060 [Apr 16 21:22:51] VERBOSE[3724] chan_sip.c: Scheduling destruction of SIP dialog 'ef76e4d26c5fd41a' in 6400 ms (Method: SUBSCRIBE) [Apr 16 21:22:53] DEBUG[3724] chan_sip.c: Auto destroying SIP dialog '48401bda68e4aa447c668c28307bd5e6@192.168.12.11' [Apr 16 21:22:53] DEBUG[3724] chan_sip.c: Destroying SIP dialog 48401bda68e4aa447c668c28307bd5e6@192.168.12.11 [Apr 16 21:22:53] VERBOSE[3724] chan_sip.c: Really destroying SIP dialog '48401bda68e4aa447c668c28307bd5e6@192.168.12.11' Method: REGISTER [Apr 16 21:22:56] DEBUG[3736] chan_iax2.c: Allocate call number [Apr 16 21:22:56] DEBUG[3736] chan_iax2.c: ip callno count incremented to 3 for 213.206.76.44 [Apr 16 21:22:56] DEBUG[3736] chan_iax2.c: Registration created on call 1979 [Apr 16 21:22:56] DEBUG[3731] chan_iax2.c: schedule decrement of callno used for 213.206.76.44 in 60 seconds [Apr 16 21:22:58] DEBUG[3724] chan_sip.c: Auto destroying SIP dialog 'ef76e4d26c5fd41a' [Apr 16 21:22:58] DEBUG[3724] chan_sip.c: Destroying SIP dialog ef76e4d26c5fd41a [Apr 16 21:22:58] VERBOSE[3724] chan_sip.c: Really destroying SIP dialog 'ef76e4d26c5fd41a' Method: SUBSCRIBE [Apr 16 21:23:02] DEBUG[3724] chan_sip.c: Auto destroying SIP dialog 'ec78b5bd1d52627d' [Apr 16 21:23:02] DEBUG[3724] chan_sip.c: Destroying SIP dialog ec78b5bd1d52627d [Apr 16 21:23:02] VERBOSE[3724] chan_sip.c: Really destroying SIP dialog 'ec78b5bd1d52627d' Method: REGISTER [Apr 16 21:23:05] DEBUG[3724] chan_sip.c: Allocating new SIP dialog for 379ba0061b01b8ce5329b99d2c63c939@192.168.12.4 - OPTIONS (No RTP) [Apr 16 21:23:05] DEBUG[3724] acl.c: Found IP address for this socket [Apr 16 21:23:05] DEBUG[3724] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.12.4:5060 [Apr 16 21:23:05] DEBUG[3724] chan_sip.c: Initializing initreq for method OPTIONS - callid 54cbdad2302c13ee1269517e636f8cdc@192.168.12.4 [Apr 16 21:23:05] DEBUG[3724] chan_sip.c: Header 0 [ 57]: OPTIONS sip:450@192.168.12.150:5060;transport=udp SIP/2.0 [Apr 16 21:23:05] DEBUG[3724] chan_sip.c: Header 1 [ 63]: Via: SIP/2.0/UDP 192.168.12.4:5060;branch=z9hG4bK6e8afd9f;rport [Apr 16 21:23:05] DEBUG[3724] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Apr 16 21:23:05] DEBUG[3724] chan_sip.c: Header 3 [ 59]: From: "asterisk" ;tag=as6ceeee4b [Apr 16 21:23:05] DEBUG[3724] chan_sip.c: Header 4 [ 47]: To: [Apr 16 21:23:05] DEBUG[3724] chan_sip.c: Header 5 [ 36]: Contact: [Apr 16 21:23:05] DEBUG[3724] chan_sip.c: Header 6 [ 54]: Call-ID: 54cbdad2302c13ee1269517e636f8cdc@192.168.12.4 [Apr 16 21:23:05] DEBUG[3724] chan_sip.c: Header 7 [ 17]: CSeq: 102 OPTIONS [Apr 16 21:23:05] DEBUG[3724] chan_sip.c: Header 8 [ 26]: User-Agent: Media Labs PBX [Apr 16 21:23:05] DEBUG[3724] chan_sip.c: Header 9 [ 35]: Date: Fri, 16 Apr 2010 19:23:05 GMT [Apr 16 21:23:05] DEBUG[3724] chan_sip.c: Header 10 [ 72]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO [Apr 16 21:23:05] DEBUG[3724] chan_sip.c: Header 11 [ 26]: Supported: replaces, timer [Apr 16 21:23:05] DEBUG[3724] chan_sip.c: Header 12 [ 17]: Content-Length: 0 [Apr 16 21:23:05] VERBOSE[3724] chan_sip.c: Reliably Transmitting (NAT) to 192.168.12.150:5060: OPTIONS sip:450@192.168.12.150:5060;transport=udp SIP/2.0 Via: SIP/2.0/UDP 192.168.12.4:5060;branch=z9hG4bK6e8afd9f;rport Max-Forwards: 70 From: "asterisk" ;tag=as6ceeee4b To: Contact: Call-ID: 54cbdad2302c13ee1269517e636f8cdc@192.168.12.4 CSeq: 102 OPTIONS User-Agent: Media Labs PBX Date: Fri, 16 Apr 2010 19:23:05 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer Content-Length: 0 --- [Apr 16 21:23:05] DEBUG[3724] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #1578 [Apr 16 21:23:05] DEBUG[3724] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 192.168.12.150:5060 [Apr 16 21:23:05] VERBOSE[3724] chan_sip.c: <--- SIP read from UDP:192.168.12.150:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.12.4:5060;branch=z9hG4bK6e8afd9f;rport=5060;received=192.168.12.4 From: "asterisk" ;tag=as6ceeee4b To: ;tag=202833691 Call-ID: 54cbdad2302c13ee1269517e636f8cdc@192.168.12.4 CSeq: 102 OPTIONS Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, OPTIONS, UPDATE, PRACK, SUBSCRIBE, INFO Server: Aastra 6739i/3.0.1.38 Content-Length: 0 <-------------> [Apr 16 21:23:05] DEBUG[3724] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Apr 16 21:23:05] DEBUG[3724] chan_sip.c: Header 1 [ 90]: Via: SIP/2.0/UDP 192.168.12.4:5060;branch=z9hG4bK6e8afd9f;rport=5060;received=192.168.12.4 [Apr 16 21:23:05] DEBUG[3724] chan_sip.c: Header 2 [ 59]: From: "asterisk" ;tag=as6ceeee4b [Apr 16 21:23:05] DEBUG[3724] chan_sip.c: Header 3 [ 61]: To: ;tag=202833691 [Apr 16 21:23:05] DEBUG[3724] chan_sip.c: Header 4 [ 54]: Call-ID: 54cbdad2302c13ee1269517e636f8cdc@192.168.12.4 [Apr 16 21:23:05] DEBUG[3724] chan_sip.c: Header 5 [ 17]: CSeq: 102 OPTIONS [Apr 16 21:23:05] DEBUG[3724] chan_sip.c: Header 6 [ 87]: Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, OPTIONS, UPDATE, PRACK, SUBSCRIBE, INFO [Apr 16 21:23:05] DEBUG[3724] chan_sip.c: Header 7 [ 29]: Server: Aastra 6739i/3.0.1.38 [Apr 16 21:23:05] DEBUG[3724] chan_sip.c: Header 8 [ 17]: Content-Length: 0 [Apr 16 21:23:05] DEBUG[3724] chan_sip.c: Header 9 [ 0]: [Apr 16 21:23:05] VERBOSE[3724] chan_sip.c: --- (9 headers 0 lines) --- [Apr 16 21:23:05] DEBUG[3724] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #1578 [Apr 16 21:23:05] DEBUG[3724] chan_sip.c: Stopping retransmission on '54cbdad2302c13ee1269517e636f8cdc@192.168.12.4' of Request 102: Match Found [Apr 16 21:23:05] DEBUG[3724] chan_sip.c: Destroying SIP dialog 54cbdad2302c13ee1269517e636f8cdc@192.168.12.4 [Apr 16 21:23:05] VERBOSE[3724] chan_sip.c: Really destroying SIP dialog '54cbdad2302c13ee1269517e636f8cdc@192.168.12.4' Method: OPTIONS [Apr 16 21:23:05] DEBUG[3726] chan_iax2.c: ip callno count decremented to 7 for 127.0.0.1 [Apr 16 21:23:05] DEBUG[3733] chan_iax2.c: ip callno count incremented to 8 for 127.0.0.1 [Apr 16 21:23:05] DEBUG[3726] chan_iax2.c: ip callno count decremented to 7 for 127.0.0.1 [Apr 16 21:23:05] DEBUG[3730] chan_iax2.c: ip callno count incremented to 8 for 127.0.0.1 [Apr 16 21:23:05] DEBUG[3727] chan_iax2.c: ip callno count incremented to 9 for 127.0.0.1 [Apr 16 21:23:05] DEBUG[3736] chan_iax2.c: ip callno count incremented to 10 for 127.0.0.1 [Apr 16 21:23:05] DEBUG[3726] chan_iax2.c: ip callno count decremented to 9 for 127.0.0.1 [Apr 16 21:23:05] DEBUG[3726] chan_iax2.c: ip callno count decremented to 8 for 127.0.0.1 [Apr 16 21:23:05] DEBUG[3732] chan_iax2.c: schedule decrement of callno used for 127.0.0.1 in 60 seconds [Apr 16 21:23:05] DEBUG[3732] chan_iax2.c: Peer iaxfax3: got pong, lastms 1, historicms 1, maxms 2000 [Apr 16 21:23:05] DEBUG[3731] chan_iax2.c: schedule decrement of callno used for 127.0.0.1 in 60 seconds [Apr 16 21:23:05] DEBUG[3735] chan_iax2.c: schedule decrement of callno used for 127.0.0.1 in 60 seconds [Apr 16 21:23:05] DEBUG[3735] chan_iax2.c: Peer iaxfax0: got pong, lastms 3, historicms 3, maxms 2000 [Apr 16 21:23:05] DEBUG[3731] chan_iax2.c: Peer iaxfax2: got pong, lastms 3, historicms 3, maxms 2000 [Apr 16 21:23:05] DEBUG[3734] chan_iax2.c: schedule decrement of callno used for 127.0.0.1 in 60 seconds [Apr 16 21:23:05] DEBUG[3734] chan_iax2.c: Peer iaxfax1: got pong, lastms 3, historicms 3, maxms 2000 [Apr 16 21:23:05] DEBUG[3726] chan_iax2.c: ip callno count decremented to 2 for 213.206.76.44 [Apr 16 21:23:05] DEBUG[3729] chan_iax2.c: ip callno count incremented to 3 for 213.206.76.44 [Apr 16 21:23:05] DEBUG[3728] chan_iax2.c: schedule decrement of callno used for 213.206.76.44 in 60 seconds [Apr 16 21:23:05] DEBUG[3728] chan_iax2.c: Peer ronald-derksen: got pong, lastms 11, historicms 11, maxms 2000 [Apr 16 21:23:05] DEBUG[3726] chan_iax2.c: ip callno count decremented to 0 for 192.168.1.20 [Apr 16 21:23:05] DEBUG[3733] chan_iax2.c: ip callno count incremented to 1 for 192.168.1.20 [Apr 16 21:23:05] DEBUG[3730] chan_iax2.c: schedule decrement of callno used for 192.168.1.20 in 60 seconds [Apr 16 21:23:05] DEBUG[3730] chan_iax2.c: Peer ronald-demo: got pong, lastms 23, historicms 23, maxms 2000 [Apr 16 21:23:05] DEBUG[3724] chan_sip.c: Allocating new SIP dialog for 0571c4ab2a3eebb968e2d46b10bfb8c3@192.168.12.4 - OPTIONS (No RTP) [Apr 16 21:23:06] DEBUG[3724] acl.c: Found IP address for this socket [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 77.249.178.109:5060 [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Initializing initreq for method OPTIONS - callid 73f571af6000cbb26565592b1ff69789@77.249.178.109 [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Header 0 [ 39]: OPTIONS sip:sip1.budgetphone.nl SIP/2.0 [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Header 1 [ 65]: Via: SIP/2.0/UDP 77.249.178.109:5060;branch=z9hG4bK3a1a2173;rport [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Header 3 [ 61]: From: "asterisk" ;tag=as2c5a94d2 [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Header 4 [ 29]: To: [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Header 5 [ 38]: Contact: [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Header 6 [ 56]: Call-ID: 73f571af6000cbb26565592b1ff69789@77.249.178.109 [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Header 7 [ 17]: CSeq: 102 OPTIONS [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Header 8 [ 26]: User-Agent: Media Labs PBX [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Header 9 [ 35]: Date: Fri, 16 Apr 2010 19:23:06 GMT [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Header 10 [ 72]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Header 11 [ 26]: Supported: replaces, timer [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Header 12 [ 17]: Content-Length: 0 [Apr 16 21:23:06] VERBOSE[3724] chan_sip.c: Reliably Transmitting (NAT) to 83.143.188.165:5060: OPTIONS sip:sip1.budgetphone.nl SIP/2.0 Via: SIP/2.0/UDP 77.249.178.109:5060;branch=z9hG4bK3a1a2173;rport Max-Forwards: 70 From: "asterisk" ;tag=as2c5a94d2 To: Contact: Call-ID: 73f571af6000cbb26565592b1ff69789@77.249.178.109 CSeq: 102 OPTIONS User-Agent: Media Labs PBX Date: Fri, 16 Apr 2010 19:23:06 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer Content-Length: 0 --- [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #1581 [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 83.143.188.165:5060 [Apr 16 21:23:06] VERBOSE[3724] chan_sip.c: <--- SIP read from UDP:83.143.188.165:5060 ---> SIP/2.0 404 unknown service Via: SIP/2.0/UDP 77.249.178.109:5060;branch=z9hG4bK3a1a2173;rport=5060 From: "asterisk" ;tag=as2c5a94d2 To: ;tag=91003fdeb24a2cb33b34489016d6cf2c.7b1d Call-ID: 73f571af6000cbb26565592b1ff69789@77.249.178.109 CSeq: 102 OPTIONS Server: OpenSIPS (1.4.5-notls (x86_64/linux)) Content-Length: 0 <-------------> [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Header 0 [ 27]: SIP/2.0 404 unknown service [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Header 1 [ 70]: Via: SIP/2.0/UDP 77.249.178.109:5060;branch=z9hG4bK3a1a2173;rport=5060 [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Header 2 [ 61]: From: "asterisk" ;tag=as2c5a94d2 [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Header 3 [ 71]: To: ;tag=91003fdeb24a2cb33b34489016d6cf2c.7b1d [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Header 4 [ 56]: Call-ID: 73f571af6000cbb26565592b1ff69789@77.249.178.109 [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Header 5 [ 17]: CSeq: 102 OPTIONS [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Header 6 [ 45]: Server: OpenSIPS (1.4.5-notls (x86_64/linux)) [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Header 7 [ 17]: Content-Length: 0 [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Header 8 [ 0]: [Apr 16 21:23:06] VERBOSE[3724] chan_sip.c: --- (8 headers 0 lines) --- [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #1581 [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Stopping retransmission on '73f571af6000cbb26565592b1ff69789@77.249.178.109' of Request 102: Match Found [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Destroying SIP dialog 73f571af6000cbb26565592b1ff69789@77.249.178.109 [Apr 16 21:23:06] VERBOSE[3724] chan_sip.c: Really destroying SIP dialog '73f571af6000cbb26565592b1ff69789@77.249.178.109' Method: OPTIONS [Apr 16 21:23:06] DEBUG[3726] chan_iax2.c: ip callno count decremented to 2 for 213.206.76.44 [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Allocating new SIP dialog for 1619cd5649642a661e0c7de951a743b4@192.168.12.4 - OPTIONS (No RTP) [Apr 16 21:23:06] DEBUG[3724] acl.c: Found IP address for this socket [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 77.249.178.109:5060 [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Initializing initreq for method OPTIONS - callid 6295939c18afaf244a25f409698a07be@77.249.178.109 [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Header 0 [ 39]: OPTIONS sip:sip1.budgetphone.nl SIP/2.0 [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Header 1 [ 65]: Via: SIP/2.0/UDP 77.249.178.109:5060;branch=z9hG4bK4dac6896;rport [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Header 3 [ 61]: From: "asterisk" ;tag=as2e8d0107 [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Header 4 [ 29]: To: [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Header 5 [ 38]: Contact: [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Header 6 [ 56]: Call-ID: 6295939c18afaf244a25f409698a07be@77.249.178.109 [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Header 7 [ 17]: CSeq: 102 OPTIONS [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Header 8 [ 26]: User-Agent: Media Labs PBX [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Header 9 [ 35]: Date: Fri, 16 Apr 2010 19:23:06 GMT [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Header 10 [ 72]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Header 11 [ 26]: Supported: replaces, timer [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Header 12 [ 17]: Content-Length: 0 [Apr 16 21:23:06] VERBOSE[3724] chan_sip.c: Reliably Transmitting (NAT) to 83.143.188.165:5060: OPTIONS sip:sip1.budgetphone.nl SIP/2.0 Via: SIP/2.0/UDP 77.249.178.109:5060;branch=z9hG4bK4dac6896;rport Max-Forwards: 70 From: "asterisk" ;tag=as2e8d0107 To: Contact: Call-ID: 6295939c18afaf244a25f409698a07be@77.249.178.109 CSeq: 102 OPTIONS User-Agent: Media Labs PBX Date: Fri, 16 Apr 2010 19:23:06 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer Content-Length: 0 --- [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #1584 [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 83.143.188.165:5060 [Apr 16 21:23:06] VERBOSE[3724] chan_sip.c: <--- SIP read from UDP:83.143.188.165:5060 ---> SIP/2.0 404 unknown service Via: SIP/2.0/UDP 77.249.178.109:5060;branch=z9hG4bK4dac6896;rport=5060 From: "asterisk" ;tag=as2e8d0107 To: ;tag=91003fdeb24a2cb33b34489016d6cf2c.cb8c Call-ID: 6295939c18afaf244a25f409698a07be@77.249.178.109 CSeq: 102 OPTIONS Server: OpenSIPS (1.4.5-notls (x86_64/linux)) Content-Length: 0 <-------------> [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Header 0 [ 27]: SIP/2.0 404 unknown service [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Header 1 [ 70]: Via: SIP/2.0/UDP 77.249.178.109:5060;branch=z9hG4bK4dac6896;rport=5060 [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Header 2 [ 61]: From: "asterisk" ;tag=as2e8d0107 [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Header 3 [ 71]: To: ;tag=91003fdeb24a2cb33b34489016d6cf2c.cb8c [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Header 4 [ 56]: Call-ID: 6295939c18afaf244a25f409698a07be@77.249.178.109 [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Header 5 [ 17]: CSeq: 102 OPTIONS [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Header 6 [ 45]: Server: OpenSIPS (1.4.5-notls (x86_64/linux)) [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Header 7 [ 17]: Content-Length: 0 [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Header 8 [ 0]: [Apr 16 21:23:06] VERBOSE[3724] chan_sip.c: --- (8 headers 0 lines) --- [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #1584 [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Stopping retransmission on '6295939c18afaf244a25f409698a07be@77.249.178.109' of Request 102: Match Found [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Destroying SIP dialog 6295939c18afaf244a25f409698a07be@77.249.178.109 [Apr 16 21:23:06] VERBOSE[3724] chan_sip.c: Really destroying SIP dialog '6295939c18afaf244a25f409698a07be@77.249.178.109' Method: OPTIONS [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Allocating new SIP dialog for 6aec579310035edd43a882b4714e7c48@192.168.12.4 - OPTIONS (No RTP) [Apr 16 21:23:06] DEBUG[3724] acl.c: Found IP address for this socket [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.12.4:5060 [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Initializing initreq for method OPTIONS - callid 5292cd1d5c488a301dad807615f50042@192.168.12.4 [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Header 0 [ 38]: OPTIONS sip:420@192.168.12.120 SIP/2.0 [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Header 1 [ 63]: Via: SIP/2.0/UDP 192.168.12.4:5060;branch=z9hG4bK435255f5;rport [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Header 3 [ 59]: From: "asterisk" ;tag=as4d7e2e8c [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Header 4 [ 28]: To: [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Header 5 [ 36]: Contact: [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Header 6 [ 54]: Call-ID: 5292cd1d5c488a301dad807615f50042@192.168.12.4 [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Header 7 [ 17]: CSeq: 102 OPTIONS [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Header 8 [ 26]: User-Agent: Media Labs PBX [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Header 9 [ 35]: Date: Fri, 16 Apr 2010 19:23:06 GMT [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Header 10 [ 72]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Header 11 [ 26]: Supported: replaces, timer [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Header 12 [ 17]: Content-Length: 0 [Apr 16 21:23:06] VERBOSE[3724] chan_sip.c: Reliably Transmitting (NAT) to 192.168.12.120:5060: OPTIONS sip:420@192.168.12.120 SIP/2.0 Via: SIP/2.0/UDP 192.168.12.4:5060;branch=z9hG4bK435255f5;rport Max-Forwards: 70 From: "asterisk" ;tag=as4d7e2e8c To: Contact: Call-ID: 5292cd1d5c488a301dad807615f50042@192.168.12.4 CSeq: 102 OPTIONS User-Agent: Media Labs PBX Date: Fri, 16 Apr 2010 19:23:06 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer Content-Length: 0 --- [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #1587 [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 192.168.12.120:5060 [Apr 16 21:23:06] VERBOSE[3724] chan_sip.c: <--- SIP read from UDP:192.168.12.120:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.12.4:5060;branch=z9hG4bK435255f5;rport From: "asterisk" ;tag=as4d7e2e8c To: "420" ;tag=22A83E6B-F17127A6 CSeq: 102 OPTIONS Call-ID: 5292cd1d5c488a301dad807615f50042@192.168.12.4 Contact: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER Supported: 100rel,replaces,100rel,timer,replaces User-Agent: PolycomSoundPointIP-SPIP_330-UA/3.2.2.0477 Accept-Language: en Accept: application/sdp,text/plain,message/sipfrag,application/dialog-info+xml Accept-Encoding: identity Content-Length: 0 <-------------> [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Header 1 [ 63]: Via: SIP/2.0/UDP 192.168.12.4:5060;branch=z9hG4bK435255f5;rport [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Header 2 [ 59]: From: "asterisk" ;tag=as4d7e2e8c [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Header 3 [ 56]: To: "420" ;tag=22A83E6B-F17127A6 [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Header 4 [ 17]: CSeq: 102 OPTIONS [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Header 5 [ 54]: Call-ID: 5292cd1d5c488a301dad807615f50042@192.168.12.4 [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Header 6 [ 33]: Contact: [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Header 7 [ 96]: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Header 8 [ 48]: Supported: 100rel,replaces,100rel,timer,replaces [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Header 9 [ 54]: User-Agent: PolycomSoundPointIP-SPIP_330-UA/3.2.2.0477 [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Header 10 [ 19]: Accept-Language: en [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Header 11 [ 78]: Accept: application/sdp,text/plain,message/sipfrag,application/dialog-info+xml [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Header 12 [ 25]: Accept-Encoding: identity [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Header 13 [ 17]: Content-Length: 0 [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Header 14 [ 0]: [Apr 16 21:23:06] VERBOSE[3724] chan_sip.c: --- (14 headers 0 lines) --- [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #1587 [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Stopping retransmission on '5292cd1d5c488a301dad807615f50042@192.168.12.4' of Request 102: Match Found [Apr 16 21:23:06] DEBUG[3724] chan_sip.c: Destroying SIP dialog 5292cd1d5c488a301dad807615f50042@192.168.12.4 [Apr 16 21:23:06] VERBOSE[3724] chan_sip.c: Really destroying SIP dialog '5292cd1d5c488a301dad807615f50042@192.168.12.4' Method: OPTIONS