<--- SIP read from UDP://10.1.1.111:5060 ---> INVITE sip:1010@10.1.1.223 SIP/2.0 Via: SIP/2.0/UDP 10.1.1.111:5060;branch=z9hG4bK-4530786 From: Fax Machine ;tag=b9439086e46d1f86o0 To: Remote-Party-ID: Fax Machine ;screen=yes;party=calling Call-ID: 1b052486-b9789b86@10.1.1.111 CSeq: 101 INVITE Max-Forwards: 70 Contact: Fax Machine Expires: 240 User-Agent: Linksys/SPA2102-5.2.10 Content-Length: 202 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER Supported: x-sipura, replaces Content-Type: application/sdp v=0 o=- 308181 308181 IN IP4 10.1.1.111 s=- c=IN IP4 10.1.1.111 t=0 0 m=audio 16394 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:30 a=sendrecv <-------------> [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Header 0 [ 34]: INVITE sip:1010@10.1.1.223 SIP/2.0 [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Header 1 [ 55]: Via: SIP/2.0/UDP 10.1.1.111:5060;branch=z9hG4bK-4530786 [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Header 2 [ 68]: From: Fax Machine ;tag=b9439086e46d1f86o0 [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Header 3 [ 25]: To: [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Header 4 [ 81]: Remote-Party-ID: Fax Machine ;screen=yes;party=calling [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Header 5 [ 37]: Call-ID: 1b052486-b9789b86@10.1.1.111 [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Header 6 [ 16]: CSeq: 101 INVITE [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Header 7 [ 16]: Max-Forwards: 70 [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Header 8 [ 53]: Contact: Fax Machine [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Header 9 [ 12]: Expires: 240 [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Header 10 [ 34]: User-Agent: Linksys/SPA2102-5.2.10 [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Header 11 [ 19]: Content-Length: 202 [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Header 12 [ 61]: Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Header 13 [ 29]: Supported: x-sipura, replaces [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Header 14 [ 29]: Content-Type: application/sdp [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Header 15 [ 0]: [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Body 0 [ 3]: v=0 [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Body 1 [ 35]: o=- 308181 308181 IN IP4 10.1.1.111 [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Body 2 [ 3]: s=- [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Body 3 [ 19]: c=IN IP4 10.1.1.111 [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Body 4 [ 5]: t=0 0 [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Body 5 [ 27]: m=audio 16394 RTP/AVP 0 101 [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Body 7 [ 33]: a=rtpmap:101 telephone-event/8000 [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Body 8 [ 15]: a=fmtp:101 0-15 [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Body 9 [ 10]: a=ptime:30 [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Body 10 [ 10]: a=sendrecv [Nov 6 13:02:53] VERBOSE[13369] logger.c: --- (15 headers 11 lines) --- [Nov 6 13:02:53] DEBUG[13369] acl.c: Found IP address for this socket [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.1.1.223:5060 [Nov 6 13:02:53] VERBOSE[13369] logger.c: == Using SIP RTP CoS mark 5 [Nov 6 13:02:53] VERBOSE[13369] logger.c: == Using UDPTL CoS mark 5 [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Setting NAT on RTP to Off [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Setting NAT on UDPTL to Off [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Allocating new SIP dialog for 1b052486-b9789b86@10.1.1.111 - INVITE (With RTP) [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Begin: parsing SIP "Supported: x-sipura, replaces" [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Found SIP option: -x-sipura- [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Found private SIP option, not supported: x-sipura [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Found SIP option: -replaces- [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Matched SIP option: replaces [Nov 6 13:02:53] VERBOSE[13369] logger.c: Sending to 10.1.1.111 : 5060 (no NAT) [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Initializing initreq for method INVITE - callid 1b052486-b9789b86@10.1.1.111 [Nov 6 13:02:53] VERBOSE[13369] logger.c: Using INVITE request as basis request - 1b052486-b9789b86@10.1.1.111 [Nov 6 13:02:53] VERBOSE[13369] logger.c: Found user 'faxmachine' for 'faxmachine' [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Setting NAT on RTP to Off [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Setting NAT on UDPTL to Off [Nov 6 13:02:53] VERBOSE[13369] logger.c: <--- Reliably Transmitting (no NAT) to 10.1.1.111:5060 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 10.1.1.111:5060;branch=z9hG4bK-4530786;received=10.1.1.111 From: Fax Machine ;tag=b9439086e46d1f86o0 To: ;tag=as12a38b51 Call-ID: 1b052486-b9789b86@10.1.1.111 CSeq: 101 INVITE User-Agent: Asterisk PBX SVN-branch-1.6.0-r228500 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer WWW-Authenticate: Digest algorithm=MD5, realm="midwestdatasystems.com", nonce="5dba2120" Content-Length: 0 <------------> [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #2 [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 10.1.1.111:5060 [Nov 6 13:02:53] VERBOSE[13369] logger.c: Scheduling destruction of SIP dialog '1b052486-b9789b86@10.1.1.111' in 32000 ms (Method: INVITE) [Nov 6 13:02:53] VERBOSE[13369] logger.c: <--- SIP read from UDP://10.1.1.111:5060 ---> ACK sip:1010@10.1.1.223 SIP/2.0 Via: SIP/2.0/UDP 10.1.1.111:5060;branch=z9hG4bK-4530786 From: Fax Machine ;tag=b9439086e46d1f86o0 To: ;tag=as12a38b51 Call-ID: 1b052486-b9789b86@10.1.1.111 CSeq: 101 ACK Max-Forwards: 70 Contact: Fax Machine User-Agent: Linksys/SPA2102-5.2.10 Content-Length: 0 <-------------> [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Header 0 [ 31]: ACK sip:1010@10.1.1.223 SIP/2.0 [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Header 1 [ 55]: Via: SIP/2.0/UDP 10.1.1.111:5060;branch=z9hG4bK-4530786 [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Header 2 [ 68]: From: Fax Machine ;tag=b9439086e46d1f86o0 [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Header 3 [ 40]: To: ;tag=as12a38b51 [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Header 4 [ 37]: Call-ID: 1b052486-b9789b86@10.1.1.111 [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Header 5 [ 13]: CSeq: 101 ACK [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Header 6 [ 16]: Max-Forwards: 70 [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Header 7 [ 53]: Contact: Fax Machine [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Header 8 [ 34]: User-Agent: Linksys/SPA2102-5.2.10 [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Header 9 [ 17]: Content-Length: 0 [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Header 10 [ 0]: [Nov 6 13:02:53] VERBOSE[13369] logger.c: --- (10 headers 0 lines) --- [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: = Found Their Call ID: 1b052486-b9789b86@10.1.1.111 Their Tag b9439086e46d1f86o0 Our tag: as12a38b51 [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #2 [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Stopping retransmission on '1b052486-b9789b86@10.1.1.111' of Response 101: Match Found [Nov 6 13:02:53] VERBOSE[13369] logger.c: <--- SIP read from UDP://10.1.1.111:5060 ---> INVITE sip:1010@10.1.1.223 SIP/2.0 Via: SIP/2.0/UDP 10.1.1.111:5060;branch=z9hG4bK-470a037a From: Fax Machine ;tag=b9439086e46d1f86o0 To: Remote-Party-ID: Fax Machine ;screen=yes;party=calling Call-ID: 1b052486-b9789b86@10.1.1.111 CSeq: 102 INVITE Max-Forwards: 70 Authorization: Digest username="faxmachine",realm="midwestdatasystems.com",nonce="5dba2120",uri="sip:1010@10.1.1.223",algorithm=MD5,response="105d072dabd931184771c401c46b5823" Contact: Fax Machine Expires: 240 User-Agent: Linksys/SPA2102-5.2.10 Content-Length: 202 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER Supported: x-sipura, replaces Content-Type: application/sdp v=0 o=- 308181 308181 IN IP4 10.1.1.111 s=- c=IN IP4 10.1.1.111 t=0 0 m=audio 16394 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:30 a=sendrecv <-------------> [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Header 0 [ 34]: INVITE sip:1010@10.1.1.223 SIP/2.0 [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Header 1 [ 56]: Via: SIP/2.0/UDP 10.1.1.111:5060;branch=z9hG4bK-470a037a [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Header 2 [ 68]: From: Fax Machine ;tag=b9439086e46d1f86o0 [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Header 3 [ 25]: To: [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Header 4 [ 81]: Remote-Party-ID: Fax Machine ;screen=yes;party=calling [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Header 5 [ 37]: Call-ID: 1b052486-b9789b86@10.1.1.111 [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Header 6 [ 16]: CSeq: 102 INVITE [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Header 7 [ 16]: Max-Forwards: 70 [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Header 8 [175]: Authorization: Digest username="faxmachine",realm="midwestdatasystems.com",nonce="5dba2120",uri="sip:1010@10.1.1.223",algorithm=MD5,response="105d072dabd931184771c401c46b5823" [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Header 9 [ 53]: Contact: Fax Machine [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Header 10 [ 12]: Expires: 240 [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Header 11 [ 34]: User-Agent: Linksys/SPA2102-5.2.10 [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Header 12 [ 19]: Content-Length: 202 [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Header 13 [ 61]: Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Header 14 [ 29]: Supported: x-sipura, replaces [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Header 15 [ 29]: Content-Type: application/sdp [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Header 16 [ 0]: [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Body 0 [ 3]: v=0 [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Body 1 [ 35]: o=- 308181 308181 IN IP4 10.1.1.111 [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Body 2 [ 3]: s=- [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Body 3 [ 19]: c=IN IP4 10.1.1.111 [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Body 4 [ 5]: t=0 0 [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Body 5 [ 27]: m=audio 16394 RTP/AVP 0 101 [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Body 7 [ 33]: a=rtpmap:101 telephone-event/8000 [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Body 8 [ 15]: a=fmtp:101 0-15 [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Body 9 [ 10]: a=ptime:30 [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Body 10 [ 10]: a=sendrecv [Nov 6 13:02:53] VERBOSE[13369] logger.c: --- (16 headers 11 lines) --- [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: = Found Their Call ID: 1b052486-b9789b86@10.1.1.111 Their Tag b9439086e46d1f86o0 Our tag: as12a38b51 [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Nov 6 13:02:53] VERBOSE[13369] logger.c: Sending to 10.1.1.111 : 5060 (no NAT) [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Initializing initreq for method INVITE - callid 1b052486-b9789b86@10.1.1.111 [Nov 6 13:02:53] VERBOSE[13369] logger.c: Using INVITE request as basis request - 1b052486-b9789b86@10.1.1.111 [Nov 6 13:02:53] VERBOSE[13369] logger.c: Found user 'faxmachine' for 'faxmachine' [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Setting NAT on RTP to Off [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Setting NAT on UDPTL to Off [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED. [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Processing session-level SDP o=- 308181 308181 IN IP4 10.1.1.111... UNSUPPORTED. [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Processing session-level SDP s=-... UNSUPPORTED. [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Processing session-level SDP c=IN IP4 10.1.1.111... OK. [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED. [Nov 6 13:02:53] VERBOSE[13369] logger.c: Found RTP audio format 0 [Nov 6 13:02:53] VERBOSE[13369] logger.c: Found RTP audio format 101 [Nov 6 13:02:53] VERBOSE[13369] logger.c: Found audio description format PCMU for ID 0 [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [Nov 6 13:02:53] VERBOSE[13369] logger.c: Found audio description format telephone-event for ID 101 [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED. [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Processing media-level (audio) SDP a=ptime:30... OK. [Nov 6 13:02:53] VERBOSE[13369] logger.c: Capabilities: us - 0x4 (ulaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0x4 (ulaw) [Nov 6 13:02:53] VERBOSE[13369] logger.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Nov 6 13:02:53] VERBOSE[13369] logger.c: Peer audio RTP is at port 10.1.1.111:16394 [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Peer doesn't provide T.38 UDPTL [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: We're settling with these formats: 0x4 (ulaw) [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Checking SIP call limits for device faxmachine [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Updating call counter for incoming call [Nov 6 13:02:53] VERBOSE[13369] logger.c: Looking for 1010 in inbound_fax (domain 10.1.1.223) [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: *** Our native formats are 0x4 (ulaw) [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: *** Joint capabilities are 0x4 (ulaw) [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: *** Our capabilities are 0x4 (ulaw) [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: This channel will not be able to handle video. [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: build_route: Contact hop: Fax Machine [Nov 6 13:02:53] VERBOSE[13369] logger.c: list_route: hop: [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: SIP/faxmachine-00000000: New call is still down.... Trying... [Nov 6 13:02:53] VERBOSE[13369] logger.c: <--- Transmitting (no NAT) to 10.1.1.111:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.1.1.111:5060;branch=z9hG4bK-470a037a;received=10.1.1.111 From: Fax Machine ;tag=b9439086e46d1f86o0 To: Call-ID: 1b052486-b9789b86@10.1.1.111 CSeq: 102 INVITE User-Agent: Asterisk PBX SVN-branch-1.6.0-r228500 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer Contact: Content-Length: 0 <------------> [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 10.1.1.111:5060 [Nov 6 13:02:53] DEBUG[13369] devicestate.c: Notification of state change to be queued on device/channel SIP/faxmachine [Nov 6 13:02:53] DEBUG[13376] pbx.c: Launching 'Answer' [Nov 6 13:02:53] VERBOSE[13376] logger.c: -- Executing [1010@inbound_fax:1] Answer("SIP/faxmachine-00000000", "") in new stack [Nov 6 13:02:53] DEBUG[13362] devicestate.c: No provider found, checking channel drivers for SIP - faxmachine [Nov 6 13:02:53] DEBUG[13362] chan_sip.c: Checking device state for peer faxmachine [Nov 6 13:02:53] DEBUG[13362] devicestate.c: Changing state for SIP/faxmachine - state 5 (Unavailable) [Nov 6 13:02:53] DEBUG[13376] devicestate.c: Notification of state change to be queued on device/channel SIP/faxmachine [Nov 6 13:02:53] DEBUG[13376] chan_sip.c: SIP answering channel: SIP/faxmachine-00000000 [Nov 6 13:02:53] DEBUG[13376] chan_sip.c: Setting framing from config on incoming call [Nov 6 13:02:53] DEBUG[13376] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: True Text flag: True [Nov 6 13:02:53] DEBUG[13376] chan_sip.c: ** Our prefcodec: 0x0 (nothing) [Nov 6 13:02:53] VERBOSE[13376] logger.c: Audio is at 10.1.1.223 port 12730 [Nov 6 13:02:53] VERBOSE[13376] logger.c: Adding codec 0x4 (ulaw) to SDP [Nov 6 13:02:53] VERBOSE[13376] logger.c: Adding non-codec 0x1 (telephone-event) to SDP [Nov 6 13:02:53] DEBUG[13376] chan_sip.c: -- Done with adding codecs to SDP [Nov 6 13:02:53] DEBUG[13376] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Nov 6 13:02:53] DEBUG[13376] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw) [Nov 6 13:02:53] VERBOSE[13376] logger.c: <--- Reliably Transmitting (no NAT) to 10.1.1.111:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.1.1.111:5060;branch=z9hG4bK-470a037a;received=10.1.1.111 From: Fax Machine ;tag=b9439086e46d1f86o0 To: ;tag=as48e9bcab Call-ID: 1b052486-b9789b86@10.1.1.111 CSeq: 102 INVITE User-Agent: Asterisk PBX SVN-branch-1.6.0-r228500 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer Contact: Content-Type: application/sdp Content-Length: 274 v=0 o=root 308369049 308369049 IN IP4 10.1.1.223 s=Asterisk PBX SVN-branch-1.6.0-r228500 c=IN IP4 10.1.1.223 t=0 0 m=audio 12730 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv <------------> [Nov 6 13:02:53] DEBUG[13376] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #5 [Nov 6 13:02:53] DEBUG[13376] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.1.1.111:5060 [Nov 6 13:02:53] DEBUG[13362] devicestate.c: No provider found, checking channel drivers for SIP - faxmachine [Nov 6 13:02:53] DEBUG[13362] chan_sip.c: Checking device state for peer faxmachine [Nov 6 13:02:53] DEBUG[13362] devicestate.c: Changing state for SIP/faxmachine - state 5 (Unavailable) [Nov 6 13:02:53] VERBOSE[13369] logger.c: <--- SIP read from UDP://10.1.1.111:5060 ---> ACK sip:1010@10.1.1.223 SIP/2.0 Via: SIP/2.0/UDP 10.1.1.111:5060;branch=z9hG4bK-2a962925 From: Fax Machine ;tag=b9439086e46d1f86o0 To: ;tag=as48e9bcab Call-ID: 1b052486-b9789b86@10.1.1.111 CSeq: 102 ACK Max-Forwards: 70 Authorization: Digest username="faxmachine",realm="midwestdatasystems.com",nonce="5dba2120",uri="sip:1010@10.1.1.223",algorithm=MD5,response="105d072dabd931184771c401c46b5823" Contact: Fax Machine User-Agent: Linksys/SPA2102-5.2.10 Content-Length: 0 <-------------> [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Header 0 [ 31]: ACK sip:1010@10.1.1.223 SIP/2.0 [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Header 1 [ 56]: Via: SIP/2.0/UDP 10.1.1.111:5060;branch=z9hG4bK-2a962925 [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Header 2 [ 68]: From: Fax Machine ;tag=b9439086e46d1f86o0 [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Header 3 [ 40]: To: ;tag=as48e9bcab [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Header 4 [ 37]: Call-ID: 1b052486-b9789b86@10.1.1.111 [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Header 5 [ 13]: CSeq: 102 ACK [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Header 6 [ 16]: Max-Forwards: 70 [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Header 7 [175]: Authorization: Digest username="faxmachine",realm="midwestdatasystems.com",nonce="5dba2120",uri="sip:1010@10.1.1.223",algorithm=MD5,response="105d072dabd931184771c401c46b5823" [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Header 8 [ 53]: Contact: Fax Machine [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Header 9 [ 34]: User-Agent: Linksys/SPA2102-5.2.10 [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Header 10 [ 17]: Content-Length: 0 [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Header 11 [ 0]: [Nov 6 13:02:53] VERBOSE[13369] logger.c: --- (11 headers 0 lines) --- [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: = Found Their Call ID: 1b052486-b9789b86@10.1.1.111 Their Tag b9439086e46d1f86o0 Our tag: as48e9bcab [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #5 [Nov 6 13:02:53] DEBUG[13369] chan_sip.c: Stopping retransmission on '1b052486-b9789b86@10.1.1.111' of Response 102: Match Found [Nov 6 13:02:53] DEBUG[13376] pbx.c: Launching 'Wait' [Nov 6 13:02:53] VERBOSE[13376] logger.c: -- Executing [1010@inbound_fax:2] Wait("SIP/faxmachine-00000000", "2") in new stack [Nov 6 13:02:55] DEBUG[13376] pbx.c: Launching 'Set' [Nov 6 13:02:55] VERBOSE[13376] logger.c: -- Executing [1010@inbound_fax:3] Set("SIP/faxmachine-00000000", "FAXOPT(ecm)=yes") in new stack [Nov 6 13:02:55] DEBUG[13376] res_fax.c: channel 'SIP/faxmachine-00000000' setting FAXOPT(ecm) to 'yes' [Nov 6 13:02:55] DEBUG[13376] pbx.c: Launching 'Set' [Nov 6 13:02:55] VERBOSE[13376] logger.c: -- Executing [1010@inbound_fax:4] Set("SIP/faxmachine-00000000", "FAXOPT(localstationid)=1010") in new stack [Nov 6 13:02:55] DEBUG[13376] res_fax.c: channel 'SIP/faxmachine-00000000' setting FAXOPT(localstationid) to '1010' [Nov 6 13:02:55] DEBUG[13376] pbx.c: Launching 'Set' [Nov 6 13:02:55] VERBOSE[13376] logger.c: -- Executing [1010@inbound_fax:5] Set("SIP/faxmachine-00000000", "FAXOPT(t38_ecc_data)=1") in new stack [Nov 6 13:02:55] DEBUG[13376] res_fax.c: channel 'SIP/faxmachine-00000000' setting FAXOPT(t38_ecc_data) to '1' [Nov 6 13:02:55] DEBUG[13376] pbx.c: Launching 'ReceiveFAX' [Nov 6 13:02:55] VERBOSE[13376] logger.c: -- Executing [1010@inbound_fax:6] ReceiveFAX("SIP/faxmachine-00000000", "/root/FAX.TIF") in new stack [Nov 6 13:02:55] VERBOSE[13376] logger.c: -- Channel 'SIP/faxmachine-00000000' receiving fax '/root/FAX.TIF' [Nov 6 13:02:55] WARNING[13376] chan_sip.c: Don't know how to indicate condition 19 [Nov 6 13:02:55] DEBUG[13376] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [Nov 6 13:02:55] DEBUG[13376] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 [Nov 6 13:02:55] DEBUG[13376] res_fax.c: Requesting a new fax session from 'Digium Fax G.711 Driver'. [Nov 6 13:02:55] DEBUG[13376] res_fax_digium.c: checking channel limits [Nov 6 13:02:55] DEBUG[13376] res_fax_digium.c: Fax session '0' opened completion pipes (fd0: 22, fd1: 23) [Nov 6 13:02:55] DEBUG[13376] res_fax_digium.c: AST_FAX_TECH_RECEIVE [Nov 6 13:02:55] DEBUG[13376] res_fax_digium.c: returning fax session '0' to channel 'SIP/faxmachine-00000000' [Nov 6 13:02:55] DEBUG[13376] res_fax.c: channel 'SIP/faxmachine-00000000' using fax session '0' [Nov 6 13:02:55] DEBUG[13376] channel.c: Set channel SIP/faxmachine-00000000 to write format slin [Nov 6 13:02:55] DEBUG[13376] channel.c: Set channel SIP/faxmachine-00000000 to read format slin [Nov 6 13:02:55] DEBUG[13376] res_fax_digium.c: session '0' opened fax handle: 0 [Nov 6 13:02:55] DEBUG[13376] res_fax_digium.c: session '0' created document queue for fax handle: 0 [Nov 6 13:02:55] DEBUG[13376] res_fax_digium.c: session '0' obtained default document parameters for fax handle: 0 [Nov 6 13:02:55] DEBUG[13376] res_fax_digium.c: fax resource: 0 queued '/root/FAX.TIF' to document queue as document number: 1 [Nov 6 13:02:55] DEBUG[13376] res_fax_digium.c: session '0' obtained default parameters for fax handle: 0 [Nov 6 13:02:55] DEBUG[13376] res_fax_digium.c: channel 'SIP/faxmachine-00000000' fax session '0' rates { Tx Min: 2400 -> Tx Max: 14400, Rx Min: 2400 } [Nov 6 13:02:55] VERBOSE[13378] logger.c: -- Channel 'SIP/faxmachine-00000000' fax session '0', [ 000.006245 ], STAT_EVT_STRT_RX st: IDLE rt: IDLENSRX [Nov 6 13:02:55] VERBOSE[13378] logger.c: -- Channel 'SIP/faxmachine-00000000' fax session '0', [ 000.006431 ], STAT_EVT_RX_HW_RDY st: WT_RX_HW_RDY rt: RRDYNHRY [Nov 6 13:02:55] VERBOSE[13378] logger.c: -- Channel 'SIP/faxmachine-00000000' fax session '0', [ 000.006504 ], STAT_INFO_CSI [Nov 6 13:02:55] VERBOSE[13378] logger.c: -- Channel 'SIP/faxmachine-00000000' fax session '0', [ 000.006647 ], STAT_INFO_DIS [Nov 6 13:02:55] DEBUG[13376] res_fax_digium.c: fax handle: 0 is receiving fax into document queue: 0x8655cc8 [Nov 6 13:02:55] VERBOSE[13376] logger.c: -- Channel 'SIP/faxmachine-00000000' fax session '0' started [Nov 6 13:02:55] DEBUG[13376] rtp.c: Ooh, format changed from unknown to ulaw [Nov 6 13:02:55] DEBUG[13376] rtp.c: Created smoother: format: 4 ms: 20 len: 160 [Nov 6 13:02:55] DEBUG[13377] res_fax_digium.c: fax channel: 0, resource: 0x8656e88, event: EVN_RECEIVE_STARTED (0x3F3), event data: 0x0 [Nov 6 13:02:55] VERBOSE[13376] logger.c: > Channel 'SIP/faxmachine-00000000' fax session '0', [ 000.053702 ], channel sent 2 frames (40 ms) of silence. [Nov 6 13:02:55] VERBOSE[13376] logger.c: > Channel 'SIP/faxmachine-00000000' fax session '0', [ 000.094356 ], stack sent 7 frames (140 ms) of energy. [Nov 6 13:02:55] VERBOSE[13376] logger.c: > Channel 'SIP/faxmachine-00000000' fax session '0', [ 000.133747 ], stack sent 2 frames (40 ms) of silence. [Nov 6 13:02:56] VERBOSE[13369] logger.c: <--- SIP read from UDP://10.1.1.111:5060 ---> INVITE sip:1010@10.1.1.223 SIP/2.0 Via: SIP/2.0/UDP 10.1.1.111:5060;branch=z9hG4bK-7d0ec879 From: Fax Machine ;tag=b9439086e46d1f86o0 To: ;tag=as48e9bcab Remote-Party-ID: Fax Machine ;screen=yes;party=calling Call-ID: 1b052486-b9789b86@10.1.1.111 CSeq: 103 INVITE Max-Forwards: 70 Authorization: Digest username="faxmachine",realm="midwestdatasystems.com",nonce="5dba2120",uri="sip:1010@10.1.1.223",algorithm=MD5,response="105d072dabd931184771c401c46b5823" Contact: Fax Machine Expires: 30 User-Agent: Linksys/SPA2102-5.2.10 Content-Length: 261 Content-Type: application/sdp v=0 o=- 308443 308443 IN IP4 10.1.1.111 s=- c=IN IP4 10.1.1.111 t=0 0 m=image 16394 udptl t38 a=T38FaxVersion:0 a=T38MaxBitRate:14400 a=T38FaxRateManagement:transferredTCF a=T38FaxMaxBuffer:200 a=T38FaxMaxDatagram:200 a=T38FaxUdpEC:t38UDPRedundancy <-------------> [Nov 6 13:02:56] DEBUG[13369] chan_sip.c: Header 0 [ 34]: INVITE sip:1010@10.1.1.223 SIP/2.0 [Nov 6 13:02:56] DEBUG[13369] chan_sip.c: Header 1 [ 56]: Via: SIP/2.0/UDP 10.1.1.111:5060;branch=z9hG4bK-7d0ec879 [Nov 6 13:02:56] DEBUG[13369] chan_sip.c: Header 2 [ 68]: From: Fax Machine ;tag=b9439086e46d1f86o0 [Nov 6 13:02:56] DEBUG[13369] chan_sip.c: Header 3 [ 40]: To: ;tag=as48e9bcab [Nov 6 13:02:56] DEBUG[13369] chan_sip.c: Header 4 [ 81]: Remote-Party-ID: Fax Machine ;screen=yes;party=calling [Nov 6 13:02:56] DEBUG[13369] chan_sip.c: Header 5 [ 37]: Call-ID: 1b052486-b9789b86@10.1.1.111 [Nov 6 13:02:56] DEBUG[13369] chan_sip.c: Header 6 [ 16]: CSeq: 103 INVITE [Nov 6 13:02:56] DEBUG[13369] chan_sip.c: Header 7 [ 16]: Max-Forwards: 70 [Nov 6 13:02:56] DEBUG[13369] chan_sip.c: Header 8 [175]: Authorization: Digest username="faxmachine",realm="midwestdatasystems.com",nonce="5dba2120",uri="sip:1010@10.1.1.223",algorithm=MD5,response="105d072dabd931184771c401c46b5823" [Nov 6 13:02:56] DEBUG[13369] chan_sip.c: Header 9 [ 53]: Contact: Fax Machine [Nov 6 13:02:56] DEBUG[13369] chan_sip.c: Header 10 [ 11]: Expires: 30 [Nov 6 13:02:56] DEBUG[13369] chan_sip.c: Header 11 [ 34]: User-Agent: Linksys/SPA2102-5.2.10 [Nov 6 13:02:56] DEBUG[13369] chan_sip.c: Header 12 [ 19]: Content-Length: 261 [Nov 6 13:02:56] DEBUG[13369] chan_sip.c: Header 13 [ 29]: Content-Type: application/sdp [Nov 6 13:02:56] DEBUG[13369] chan_sip.c: Header 14 [ 0]: [Nov 6 13:02:56] DEBUG[13369] chan_sip.c: Body 0 [ 3]: v=0 [Nov 6 13:02:56] DEBUG[13369] chan_sip.c: Body 1 [ 35]: o=- 308443 308443 IN IP4 10.1.1.111 [Nov 6 13:02:56] DEBUG[13369] chan_sip.c: Body 2 [ 3]: s=- [Nov 6 13:02:56] DEBUG[13369] chan_sip.c: Body 3 [ 19]: c=IN IP4 10.1.1.111 [Nov 6 13:02:56] DEBUG[13369] chan_sip.c: Body 4 [ 5]: t=0 0 [Nov 6 13:02:56] DEBUG[13369] chan_sip.c: Body 5 [ 23]: m=image 16394 udptl t38 [Nov 6 13:02:56] DEBUG[13369] chan_sip.c: Body 6 [ 17]: a=T38FaxVersion:0 [Nov 6 13:02:56] DEBUG[13369] chan_sip.c: Body 7 [ 21]: a=T38MaxBitRate:14400 [Nov 6 13:02:56] DEBUG[13369] chan_sip.c: Body 8 [ 37]: a=T38FaxRateManagement:transferredTCF [Nov 6 13:02:56] DEBUG[13369] chan_sip.c: Body 9 [ 21]: a=T38FaxMaxBuffer:200 [Nov 6 13:02:56] DEBUG[13369] chan_sip.c: Body 10 [ 23]: a=T38FaxMaxDatagram:200 [Nov 6 13:02:56] DEBUG[13369] chan_sip.c: Body 11 [ 30]: a=T38FaxUdpEC:t38UDPRedundancy [Nov 6 13:02:56] VERBOSE[13369] logger.c: --- (14 headers 12 lines) --- [Nov 6 13:02:56] DEBUG[13369] chan_sip.c: = Found Their Call ID: 1b052486-b9789b86@10.1.1.111 Their Tag b9439086e46d1f86o0 Our tag: as48e9bcab [Nov 6 13:02:56] DEBUG[13369] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Nov 6 13:02:56] VERBOSE[13369] logger.c: Sending to 10.1.1.111 : 5060 (no NAT) [Nov 6 13:02:56] DEBUG[13369] chan_sip.c: Initializing initreq for method INVITE - callid 1b052486-b9789b86@10.1.1.111 [Nov 6 13:02:56] DEBUG[13369] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED. [Nov 6 13:02:56] DEBUG[13369] chan_sip.c: Processing session-level SDP o=- 308443 308443 IN IP4 10.1.1.111... UNSUPPORTED. [Nov 6 13:02:56] DEBUG[13369] chan_sip.c: Processing session-level SDP s=-... UNSUPPORTED. [Nov 6 13:02:56] DEBUG[13369] chan_sip.c: Processing session-level SDP c=IN IP4 10.1.1.111... OK. [Nov 6 13:02:56] DEBUG[13369] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED. [Nov 6 13:02:56] VERBOSE[13369] logger.c: Got T.38 offer in SDP in dialog 1b052486-b9789b86@10.1.1.111 [Nov 6 13:02:56] DEBUG[13369] chan_sip.c: T38 state changed to 2 on channel SIP/faxmachine-00000000 [Nov 6 13:02:56] DEBUG[13369] chan_sip.c: FaxVersion: 0 [Nov 6 13:02:56] DEBUG[13369] chan_sip.c: Processing media-level (image) SDP a=T38FaxVersion:0... OK. [Nov 6 13:02:56] DEBUG[13369] chan_sip.c: T38MaxBitRate: 14400 [Nov 6 13:02:56] DEBUG[13369] chan_sip.c: Processing media-level (image) SDP a=T38MaxBitRate:14400... OK. [Nov 6 13:02:56] DEBUG[13369] chan_sip.c: RateManagement: transferredTCF [Nov 6 13:02:56] DEBUG[13369] chan_sip.c: Processing media-level (image) SDP a=T38FaxRateManagement:transferredTCF... OK. [Nov 6 13:02:56] DEBUG[13369] chan_sip.c: MaxBufferSize:200 [Nov 6 13:02:56] DEBUG[13369] chan_sip.c: Processing media-level (image) SDP a=T38FaxMaxBuffer:200... OK. [Nov 6 13:02:56] DEBUG[13369] chan_sip.c: FaxMaxDatagram: 200 [Nov 6 13:02:56] DEBUG[13369] chan_sip.c: Processing media-level (image) SDP a=T38FaxMaxDatagram:200... OK. [Nov 6 13:02:56] VERBOSE[13369] logger.c: Capabilities: us - 0x4 (ulaw), peer - audio=0x0 (nothing)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0x0 (nothing) [Nov 6 13:02:56] VERBOSE[13369] logger.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x0 (nothing), combined - 0x0 (nothing) [Nov 6 13:02:56] DEBUG[13369] chan_sip.c: Have T.38 but no audio codecs, accepting offer anyway [Nov 6 13:02:56] DEBUG[13369] chan_sip.c: Got a SIP re-invite for call 1b052486-b9789b86@10.1.1.111 [Nov 6 13:02:56] DEBUG[13369] chan_sip.c: SIP/faxmachine-00000000: This call is UP.... [Nov 6 13:02:56] VERBOSE[13369] logger.c: <--- Transmitting (no NAT) to 10.1.1.111:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.1.1.111:5060;branch=z9hG4bK-7d0ec879;received=10.1.1.111 From: Fax Machine ;tag=b9439086e46d1f86o0 To: ;tag=as48e9bcab Call-ID: 1b052486-b9789b86@10.1.1.111 CSeq: 103 INVITE User-Agent: Asterisk PBX SVN-branch-1.6.0-r228500 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer Contact: Content-Length: 0 <------------> [Nov 6 13:02:56] DEBUG[13369] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 10.1.1.111:5060 [Nov 6 13:02:56] VERBOSE[13376] logger.c: > Channel 'SIP/faxmachine-00000000' fax session '0', [ 000.593770 ], channel sent 27 frames (540 ms) of energy. [Nov 6 13:02:58] VERBOSE[13376] logger.c: > Channel 'SIP/faxmachine-00000000' fax session '0', [ 003.154897 ], stack sent 151 frames (3020 ms) of energy. [Nov 6 13:02:58] VERBOSE[13376] logger.c: > Channel 'SIP/faxmachine-00000000' fax session '0', [ 003.194329 ], stack sent 2 frames (40 ms) of silence. [Nov 6 13:03:00] VERBOSE[13378] logger.c: -- Channel 'SIP/faxmachine-00000000' fax session '0', [ 005.215187 ], STAT_EVT_TX_V21_DONE st: WT_DIS_RSP rt: WDSRNT21 [Nov 6 13:03:01] VERBOSE[13376] logger.c: > Channel 'SIP/faxmachine-00000000' fax session '0', [ 005.534755 ], stack sent 117 frames (2340 ms) of energy. [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: T38 state changed to 0 on channel SIP/faxmachine-00000000 [Nov 6 13:03:01] VERBOSE[13369] logger.c: <--- Reliably Transmitting (no NAT) to 10.1.1.111:5060 ---> SIP/2.0 488 Not acceptable here Via: SIP/2.0/UDP 10.1.1.111:5060;branch=z9hG4bK-7d0ec879;received=10.1.1.111 From: Fax Machine ;tag=b9439086e46d1f86o0 To: ;tag=as48e9bcab Call-ID: 1b052486-b9789b86@10.1.1.111 CSeq: 103 INVITE User-Agent: Asterisk PBX SVN-branch-1.6.0-r228500 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer Content-Length: 0 <------------> [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #8 [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: Trying to put 'SIP/2.0 488' onto UDP socket destined for 10.1.1.111:5060 [Nov 6 13:03:01] VERBOSE[13369] logger.c: <--- SIP read from UDP://10.1.1.111:5060 ---> ACK sip:1010@10.1.1.223 SIP/2.0 Via: SIP/2.0/UDP 10.1.1.111:5060;branch=z9hG4bK-7d0ec879 From: Fax Machine ;tag=b9439086e46d1f86o0 To: ;tag=as48e9bcab Call-ID: 1b052486-b9789b86@10.1.1.111 CSeq: 103 ACK Max-Forwards: 70 Authorization: Digest username="faxmachine",realm="midwestdatasystems.com",nonce="5dba2120",uri="sip:1010@10.1.1.223",algorithm=MD5,response="105d072dabd931184771c401c46b5823" Contact: Fax Machine User-Agent: Linksys/SPA2102-5.2.10 Content-Length: 0 <-------------> [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: Header 0 [ 31]: ACK sip:1010@10.1.1.223 SIP/2.0 [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: Header 1 [ 56]: Via: SIP/2.0/UDP 10.1.1.111:5060;branch=z9hG4bK-7d0ec879 [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: Header 2 [ 68]: From: Fax Machine ;tag=b9439086e46d1f86o0 [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: Header 3 [ 40]: To: ;tag=as48e9bcab [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: Header 4 [ 37]: Call-ID: 1b052486-b9789b86@10.1.1.111 [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: Header 5 [ 13]: CSeq: 103 ACK [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: Header 6 [ 16]: Max-Forwards: 70 [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: Header 7 [175]: Authorization: Digest username="faxmachine",realm="midwestdatasystems.com",nonce="5dba2120",uri="sip:1010@10.1.1.223",algorithm=MD5,response="105d072dabd931184771c401c46b5823" [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: Header 8 [ 53]: Contact: Fax Machine [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: Header 9 [ 34]: User-Agent: Linksys/SPA2102-5.2.10 [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: Header 10 [ 17]: Content-Length: 0 [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: Header 11 [ 0]: [Nov 6 13:03:01] VERBOSE[13369] logger.c: --- (11 headers 0 lines) --- [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: = Found Their Call ID: 1b052486-b9789b86@10.1.1.111 Their Tag b9439086e46d1f86o0 Our tag: as48e9bcab [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #8 [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: Stopping retransmission on '1b052486-b9789b86@10.1.1.111' of Response 103: Match Found [Nov 6 13:03:01] VERBOSE[13369] logger.c: <--- SIP read from UDP://10.1.1.111:5060 ---> INVITE sip:1010@10.1.1.223 SIP/2.0 Via: SIP/2.0/UDP 10.1.1.111:5060;branch=z9hG4bK-54a4932a From: Fax Machine ;tag=b9439086e46d1f86o0 To: ;tag=as48e9bcab Remote-Party-ID: Fax Machine ;screen=yes;party=calling Call-ID: 1b052486-b9789b86@10.1.1.111 CSeq: 104 INVITE Max-Forwards: 70 Authorization: Digest username="faxmachine",realm="midwestdatasystems.com",nonce="5dba2120",uri="sip:1010@10.1.1.223",algorithm=MD5,response="105d072dabd931184771c401c46b5823" Contact: Fax Machine Expires: 30 User-Agent: Linksys/SPA2102-5.2.10 Content-Length: 146 Content-Type: application/sdp v=0 o=- 308944 308944 IN IP4 10.1.1.111 s=- c=IN IP4 10.1.1.111 t=0 0 m=audio 16394 RTP/AVP 0 a=rtpmap:0 PCMU/8000 a=ptime:30 a=sendrecv <-------------> [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: Header 0 [ 34]: INVITE sip:1010@10.1.1.223 SIP/2.0 [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: Header 1 [ 56]: Via: SIP/2.0/UDP 10.1.1.111:5060;branch=z9hG4bK-54a4932a [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: Header 2 [ 68]: From: Fax Machine ;tag=b9439086e46d1f86o0 [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: Header 3 [ 40]: To: ;tag=as48e9bcab [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: Header 4 [ 81]: Remote-Party-ID: Fax Machine ;screen=yes;party=calling [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: Header 5 [ 37]: Call-ID: 1b052486-b9789b86@10.1.1.111 [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: Header 6 [ 16]: CSeq: 104 INVITE [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: Header 7 [ 16]: Max-Forwards: 70 [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: Header 8 [175]: Authorization: Digest username="faxmachine",realm="midwestdatasystems.com",nonce="5dba2120",uri="sip:1010@10.1.1.223",algorithm=MD5,response="105d072dabd931184771c401c46b5823" [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: Header 9 [ 53]: Contact: Fax Machine [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: Header 10 [ 11]: Expires: 30 [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: Header 11 [ 34]: User-Agent: Linksys/SPA2102-5.2.10 [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: Header 12 [ 19]: Content-Length: 146 [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: Header 13 [ 29]: Content-Type: application/sdp [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: Header 14 [ 0]: [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: Body 0 [ 3]: v=0 [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: Body 1 [ 35]: o=- 308944 308944 IN IP4 10.1.1.111 [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: Body 2 [ 3]: s=- [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: Body 3 [ 19]: c=IN IP4 10.1.1.111 [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: Body 4 [ 5]: t=0 0 [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: Body 5 [ 23]: m=audio 16394 RTP/AVP 0 [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: Body 7 [ 10]: a=ptime:30 [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: Body 8 [ 10]: a=sendrecv [Nov 6 13:03:01] VERBOSE[13369] logger.c: --- (14 headers 9 lines) --- [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: = Found Their Call ID: 1b052486-b9789b86@10.1.1.111 Their Tag b9439086e46d1f86o0 Our tag: as48e9bcab [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Nov 6 13:03:01] VERBOSE[13369] logger.c: Sending to 10.1.1.111 : 5060 (no NAT) [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: Initializing initreq for method INVITE - callid 1b052486-b9789b86@10.1.1.111 [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED. [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: Processing session-level SDP o=- 308944 308944 IN IP4 10.1.1.111... UNSUPPORTED. [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: Processing session-level SDP s=-... UNSUPPORTED. [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: Processing session-level SDP c=IN IP4 10.1.1.111... OK. [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED. [Nov 6 13:03:01] VERBOSE[13369] logger.c: Found RTP audio format 0 [Nov 6 13:03:01] VERBOSE[13369] logger.c: Found audio description format PCMU for ID 0 [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: Processing media-level (audio) SDP a=ptime:30... OK. [Nov 6 13:03:01] VERBOSE[13369] logger.c: Capabilities: us - 0x4 (ulaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0x4 (ulaw) [Nov 6 13:03:01] VERBOSE[13369] logger.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x0 (nothing), combined - 0x0 (nothing) [Nov 6 13:03:01] VERBOSE[13369] logger.c: Peer audio RTP is at port 10.1.1.111:16394 [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: Peer doesn't provide T.38 UDPTL [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: We're settling with these formats: 0x4 (ulaw) [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: We have an owner, now see if we need to change this call [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: Got a SIP re-invite for call 1b052486-b9789b86@10.1.1.111 [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: SIP/faxmachine-00000000: This call is UP.... [Nov 6 13:03:01] VERBOSE[13369] logger.c: <--- Transmitting (no NAT) to 10.1.1.111:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.1.1.111:5060;branch=z9hG4bK-54a4932a;received=10.1.1.111 From: Fax Machine ;tag=b9439086e46d1f86o0 To: ;tag=as48e9bcab Call-ID: 1b052486-b9789b86@10.1.1.111 CSeq: 104 INVITE User-Agent: Asterisk PBX SVN-branch-1.6.0-r228500 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer Contact: Content-Length: 0 <------------> [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 10.1.1.111:5060 [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: Setting framing from config on incoming call [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: True Text flag: True [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: ** Our prefcodec: 0x0 (nothing) [Nov 6 13:03:01] VERBOSE[13369] logger.c: Audio is at 10.1.1.223 port 12730 [Nov 6 13:03:01] VERBOSE[13369] logger.c: Adding codec 0x4 (ulaw) to SDP [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: -- Done with adding codecs to SDP [Nov 6 13:03:01] DEBUG[13369] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw) [Nov 6 13:03:01] VERBOSE[13369] logger.c: <--- Reliably Transmitting (no NAT) to 10.1.1.111:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.1.1.111:5060;branch=z9hG4bK-54a4932a;received=10.1.1.111 From: Fax Machine ;tag=b9439086e46d1f86o0 To: ;tag=as48e9bcab Call-ID: 1b052486-b9789b86@10.1.1.111 CSeq: 104 INVITE User-Agent: Asterisk PBX SVN-branch-1.6.0-r228500 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer Contact: Content-Type: application/sdp Content-Length: 218 v=0 o=root 308369049 308369050 IN IP4 10.1.1.223 s=Asterisk PBX SVN-branch-1.6.0-r228500 c=IN IP4 10.1.1.223 t=0 0 m=audio 12730 RTP/AVP 0 a=rtpmap:0 PCMU/8000 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv <------------> [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #9 [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.1.1.111:5060 [Nov 6 13:03:01] VERBOSE[13369] logger.c: <--- SIP read from UDP://10.1.1.111:5060 ---> ACK sip:1010@10.1.1.223 SIP/2.0 Via: SIP/2.0/UDP 10.1.1.111:5060;branch=z9hG4bK-499d602e From: Fax Machine ;tag=b9439086e46d1f86o0 To: ;tag=as48e9bcab Call-ID: 1b052486-b9789b86@10.1.1.111 CSeq: 104 ACK Max-Forwards: 70 Authorization: Digest username="faxmachine",realm="midwestdatasystems.com",nonce="5dba2120",uri="sip:1010@10.1.1.223",algorithm=MD5,response="105d072dabd931184771c401c46b5823" Contact: Fax Machine User-Agent: Linksys/SPA2102-5.2.10 Content-Length: 0 <-------------> [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: Header 0 [ 31]: ACK sip:1010@10.1.1.223 SIP/2.0 [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: Header 1 [ 56]: Via: SIP/2.0/UDP 10.1.1.111:5060;branch=z9hG4bK-499d602e [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: Header 2 [ 68]: From: Fax Machine ;tag=b9439086e46d1f86o0 [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: Header 3 [ 40]: To: ;tag=as48e9bcab [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: Header 4 [ 37]: Call-ID: 1b052486-b9789b86@10.1.1.111 [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: Header 5 [ 13]: CSeq: 104 ACK [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: Header 6 [ 16]: Max-Forwards: 70 [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: Header 7 [175]: Authorization: Digest username="faxmachine",realm="midwestdatasystems.com",nonce="5dba2120",uri="sip:1010@10.1.1.223",algorithm=MD5,response="105d072dabd931184771c401c46b5823" [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: Header 8 [ 53]: Contact: Fax Machine [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: Header 9 [ 34]: User-Agent: Linksys/SPA2102-5.2.10 [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: Header 10 [ 17]: Content-Length: 0 [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: Header 11 [ 0]: [Nov 6 13:03:01] VERBOSE[13369] logger.c: --- (11 headers 0 lines) --- [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: = Found Their Call ID: 1b052486-b9789b86@10.1.1.111 Their Tag b9439086e46d1f86o0 Our tag: as48e9bcab [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #9 [Nov 6 13:03:01] DEBUG[13369] chan_sip.c: Stopping retransmission on '1b052486-b9789b86@10.1.1.111' of Response 104: Match Found [Nov 6 13:03:01] VERBOSE[13376] logger.c: > Channel 'SIP/faxmachine-00000000' fax session '0', [ 006.185098 ], channel sent 279 frames (5580 ms) of silence. [Nov 6 13:03:03] VERBOSE[13378] logger.c: -- Channel 'SIP/faxmachine-00000000' fax session '0', [ 007.945083 ], STAT_INFO_TSI [Nov 6 13:03:04] VERBOSE[13378] logger.c: -- Channel 'SIP/faxmachine-00000000' fax session '0', [ 008.365906 ], STAT_INFO_DCS [Nov 6 13:03:04] VERBOSE[13378] logger.c: -- Channel 'SIP/faxmachine-00000000' fax session '0', [ 008.366356 ], STAT_EVT_DCS st: WT_DIS_RSP rt: WDSRNDCS [Nov 6 13:03:04] VERBOSE[13378] logger.c: -- Channel 'SIP/faxmachine-00000000' fax session '0', [ 008.366675 ], STAT_NEG_V17_14400 [Nov 6 13:03:04] VERBOSE[13378] logger.c: -- Channel 'SIP/faxmachine-00000000' fax session '0', [ 008.366996 ], STAT_NEG_MMR [Nov 6 13:03:04] VERBOSE[13378] logger.c: -- Channel 'SIP/faxmachine-00000000' fax session '0', [ 008.367268 ], STAT_NEG_A4 [Nov 6 13:03:04] VERBOSE[13378] logger.c: -- Channel 'SIP/faxmachine-00000000' fax session '0', [ 008.367568 ], STAT_NEG_RES_204x196 [Nov 6 13:03:04] VERBOSE[13378] logger.c: -- Channel 'SIP/faxmachine-00000000' fax session '0', [ 008.367844 ], STAT_NEG_ECM [Nov 6 13:03:04] VERBOSE[13378] logger.c: -- Channel 'SIP/faxmachine-00000000' fax session '0', [ 008.368146 ], STAT_EVT_SW_ECM st: WT_DIS_RSP rt: WDSRNSWE [Nov 6 13:03:04] VERBOSE[13376] logger.c: > Channel 'SIP/faxmachine-00000000' fax session '0', [ 008.485065 ], channel sent 115 frames (2300 ms) of energy. [Nov 6 13:03:04] VERBOSE[13376] logger.c: > Channel 'SIP/faxmachine-00000000' fax session '0', [ 008.545891 ], channel sent 3 frames (60 ms) of silence. [Nov 6 13:03:04] VERBOSE[13378] logger.c: -- Channel 'SIP/faxmachine-00000000' fax session '0', [ 008.746242 ], STAT_EVT_RX_IMG_STRT st: RCV_ECM_TRN rt: UNEXPECT [Nov 6 13:03:07] VERBOSE[13376] logger.c: > Channel 'SIP/faxmachine-00000000' fax session '0', [ 011.645861 ], channel sent 155 frames (3100 ms) of energy. [Nov 6 13:03:07] VERBOSE[13378] logger.c: -- Channel 'SIP/faxmachine-00000000' fax session '0', [ 011.666173 ], STAT_EVT_RX_TRN_END st: RCV_ECM_TRN rt: RTCFNERT [Nov 6 13:03:07] VERBOSE[13378] logger.c: -- Channel 'SIP/faxmachine-00000000' fax session '0', [ 011.666590 ], STAT_FRM_CFR [Nov 6 13:03:07] VERBOSE[13376] logger.c: > Channel 'SIP/faxmachine-00000000' fax session '0', [ 011.825970 ], stack sent 314 frames (6280 ms) of silence. [Nov 6 13:03:08] VERBOSE[13378] logger.c: -- Channel 'SIP/faxmachine-00000000' fax session '0', [ 012.846545 ], STAT_EVT_TX_V21_DONE st: RCV_ECM_STRT rt: RECMNT21 [Nov 6 13:03:08] VERBOSE[13376] logger.c: > Channel 'SIP/faxmachine-00000000' fax session '0', [ 013.166105 ], stack sent 67 frames (1340 ms) of energy. [Nov 6 13:03:09] VERBOSE[13376] logger.c: > Channel 'SIP/faxmachine-00000000' fax session '0', [ 013.886257 ], channel sent 112 frames (2240 ms) of silence. [Nov 6 13:03:09] VERBOSE[13378] logger.c: -- Channel 'SIP/faxmachine-00000000' fax session '0', [ 014.086588 ], STAT_EVT_RX_IMG_STRT st: RCV_ECM_STRT rt: RECMNSRI [Nov 6 13:03:09] DEBUG[13377] res_fax_digium.c: fax channel: 0, resource: 0x8656e88, event: EVN_PHASE_C (0x3FB), event data: 0xB797A71C [Nov 6 13:03:09] DEBUG[13377] res_fax_digium.c: fax channel: 0, resource: 0x8656e88, event: EVN_DOC_START (0x3EC), event data: 0x0 [Nov 6 13:03:09] DEBUG[13377] res_fax_digium.c: fax channel: 0, resource: 0x8656e88, event: EVN_PAGE_START (0x3EA), event data: 0x0 [Nov 6 13:03:17] VERBOSE[13376] logger.c: > Channel 'SIP/faxmachine-00000000' fax session '0', [ 022.308585 ], channel sent 421 frames (8420 ms) of energy. [Nov 6 13:03:17] VERBOSE[13378] logger.c: -- Channel 'SIP/faxmachine-00000000' fax session '0', [ 022.309225 ], STAT_EVT_RX_IMG_END st: RCV_ECM rt: RECMNERI [Nov 6 13:03:18] VERBOSE[13376] logger.c: > Channel 'SIP/faxmachine-00000000' fax session '0', [ 022.368285 ], channel sent 3 frames (60 ms) of silence. [Nov 6 13:03:19] VERBOSE[13378] logger.c: -- Channel 'SIP/faxmachine-00000000' fax session '0', [ 023.689356 ], STAT_INFO_PPS_EOP [Nov 6 13:03:19] VERBOSE[13378] logger.c: -- Channel 'SIP/faxmachine-00000000' fax session '0', [ 023.689825 ], STAT_EVT_PPS_EOP st: F_END_ECM rt: FEEMNP_P [Nov 6 13:03:19] VERBOSE[13378] logger.c: -- Channel 'SIP/faxmachine-00000000' fax session '0', [ 023.690348 ], STAT_FRM_MCF [Nov 6 13:03:19] DEBUG[13377] res_fax_digium.c: fax channel: 0, resource: 0x8656e88, event: EVN_PAGE_END (0x3EB), event data: 0x0 [Nov 6 13:03:19] DEBUG[13377] res_fax_digium.c: fax channel: 0, resource: 0x8656e88, event: EVN_DOC_END (0x3ED), event data: 0x0 [Nov 6 13:03:19] VERBOSE[13376] logger.c: > Channel 'SIP/faxmachine-00000000' fax session '0', [ 023.788267 ], channel sent 71 frames (1420 ms) of energy. [Nov 6 13:03:19] VERBOSE[13376] logger.c: > Channel 'SIP/faxmachine-00000000' fax session '0', [ 023.849094 ], stack sent 534 frames (10680 ms) of silence. [Nov 6 13:03:20] VERBOSE[13378] logger.c: -- Channel 'SIP/faxmachine-00000000' fax session '0', [ 024.868557 ], STAT_EVT_TX_V21_DONE st: F_END_ECM rt: FECMNFCS [Nov 6 13:03:20] VERBOSE[13376] logger.c: > Channel 'SIP/faxmachine-00000000' fax session '0', [ 025.189241 ], stack sent 67 frames (1340 ms) of energy. [Nov 6 13:03:21] VERBOSE[13376] logger.c: > Channel 'SIP/faxmachine-00000000' fax session '0', [ 025.349024 ], channel sent 78 frames (1560 ms) of silence. [Nov 6 13:03:22] VERBOSE[13378] logger.c: -- Channel 'SIP/faxmachine-00000000' fax session '0', [ 026.569968 ], STAT_FRM_DCN [Nov 6 13:03:22] VERBOSE[13378] logger.c: -- Channel 'SIP/faxmachine-00000000' fax session '0', [ 026.570437 ], STAT_EVT_DCN st: F_END_ECM rt: FEEMNDCN [Nov 6 13:03:22] VERBOSE[13376] logger.c: > Channel 'SIP/faxmachine-00000000' fax session '0', [ 026.689118 ], channel sent 67 frames (1340 ms) of energy. [Nov 6 13:03:23] VERBOSE[13376] logger.c: > Channel 'SIP/faxmachine-00000000' fax session '0', [ 027.669291 ], channel sent 49 frames (980 ms) of silence. [Nov 6 13:03:23] VERBOSE[13376] logger.c: > Channel 'SIP/faxmachine-00000000' fax session '0', [ 027.709702 ], channel sent 2 frames (40 ms) of energy. [Nov 6 13:03:24] VERBOSE[13369] logger.c: <--- SIP read from UDP://10.1.1.111:5060 ---> BYE sip:1010@10.1.1.223 SIP/2.0 Via: SIP/2.0/UDP 10.1.1.111:5060;branch=z9hG4bK-90615ff7 From: Fax Machine ;tag=b9439086e46d1f86o0 To: ;tag=as48e9bcab Call-ID: 1b052486-b9789b86@10.1.1.111 CSeq: 105 BYE Max-Forwards: 70 Authorization: Digest username="faxmachine",realm="midwestdatasystems.com",nonce="5dba2120",uri="sip:1010@10.1.1.223",algorithm=MD5,response="e77a9facee91a7d6dbafb8e5a064ae14" User-Agent: Linksys/SPA2102-5.2.10 Content-Length: 0 <-------------> [Nov 6 13:03:24] DEBUG[13369] chan_sip.c: Header 0 [ 31]: BYE sip:1010@10.1.1.223 SIP/2.0 [Nov 6 13:03:24] DEBUG[13369] chan_sip.c: Header 1 [ 56]: Via: SIP/2.0/UDP 10.1.1.111:5060;branch=z9hG4bK-90615ff7 [Nov 6 13:03:24] DEBUG[13369] chan_sip.c: Header 2 [ 68]: From: Fax Machine ;tag=b9439086e46d1f86o0 [Nov 6 13:03:24] DEBUG[13369] chan_sip.c: Header 3 [ 40]: To: ;tag=as48e9bcab [Nov 6 13:03:24] DEBUG[13369] chan_sip.c: Header 4 [ 37]: Call-ID: 1b052486-b9789b86@10.1.1.111 [Nov 6 13:03:24] DEBUG[13369] chan_sip.c: Header 5 [ 13]: CSeq: 105 BYE [Nov 6 13:03:24] DEBUG[13369] chan_sip.c: Header 6 [ 16]: Max-Forwards: 70 [Nov 6 13:03:24] DEBUG[13369] chan_sip.c: Header 7 [175]: Authorization: Digest username="faxmachine",realm="midwestdatasystems.com",nonce="5dba2120",uri="sip:1010@10.1.1.223",algorithm=MD5,response="e77a9facee91a7d6dbafb8e5a064ae14" [Nov 6 13:03:24] DEBUG[13369] chan_sip.c: Header 8 [ 34]: User-Agent: Linksys/SPA2102-5.2.10 [Nov 6 13:03:24] DEBUG[13369] chan_sip.c: Header 9 [ 17]: Content-Length: 0 [Nov 6 13:03:24] DEBUG[13369] chan_sip.c: Header 10 [ 0]: [Nov 6 13:03:24] VERBOSE[13369] logger.c: --- (10 headers 0 lines) --- [Nov 6 13:03:24] DEBUG[13369] chan_sip.c: = Found Their Call ID: 1b052486-b9789b86@10.1.1.111 Their Tag b9439086e46d1f86o0 Our tag: as48e9bcab [Nov 6 13:03:24] DEBUG[13369] chan_sip.c: **** Received BYE (8) - Command in SIP BYE [Nov 6 13:03:24] DEBUG[13369] chan_sip.c: Initializing initreq for method BYE - callid 1b052486-b9789b86@10.1.1.111 [Nov 6 13:03:24] VERBOSE[13369] logger.c: Sending to 10.1.1.111 : 5060 (no NAT) [Nov 6 13:03:24] DEBUG[13369] chan_sip.c: Setting SIP_ALREADYGONE on dialog 1b052486-b9789b86@10.1.1.111 [Nov 6 13:03:24] DEBUG[13369] chan_sip.c: Received bye, issuing owner hangup [Nov 6 13:03:24] VERBOSE[13369] logger.c: <--- Transmitting (no NAT) to 10.1.1.111:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.1.1.111:5060;branch=z9hG4bK-90615ff7;received=10.1.1.111 From: Fax Machine ;tag=b9439086e46d1f86o0 To: ;tag=as48e9bcab Call-ID: 1b052486-b9789b86@10.1.1.111 CSeq: 105 BYE User-Agent: Asterisk PBX SVN-branch-1.6.0-r228500 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer Content-Length: 0 <------------> [Nov 6 13:03:24] DEBUG[13369] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.1.1.111:5060 [Nov 6 13:03:24] NOTICE[13376] res_fax.c: Channel 'SIP/faxmachine-00000000' did not return a frame; probably hung up. [Nov 6 13:03:24] DEBUG[13376] res_fax_digium.c: Ignoring cancellation request on channel 'SIP/faxmachine-00000000' for session '0' [Nov 6 13:03:24] DEBUG[13376] res_fax_digium.c: Channel 'SIP/faxmachine-00000000' fax session '0' generating silence to fax modem. [Nov 6 13:03:28] VERBOSE[13378] logger.c: -- Channel 'SIP/faxmachine-00000000' fax session '0', [ 033.051274 ], STAT_EVT_HW_CLOSE st: WT_HW_CLS rt: WCLSNCLS [Nov 6 13:03:28] VERBOSE[13378] logger.c: -- Channel 'SIP/faxmachine-00000000' fax session '0', [ 033.052308 ], STAT_SES_COMPLETE [Nov 6 13:03:28] DEBUG[13377] res_fax_digium.c: fax channel: 0, resource: 0x8656e88, event: EVN_COMPLETE (0x3E9), event data: 0x0 [Nov 6 13:03:28] VERBOSE[13377] logger.c: -- Channel 'SIP/faxmachine-00000000' fax session '0' is complete, result: 'SUCCESS' (FAX_SUCCESS), error: 'NO_ERROR', pages: 1, resolution: '204x196', transfer rate: '14400', remoteSID: '7157358565' [Nov 6 13:03:28] DEBUG[13376] res_fax.c: channel 'SIP/faxmachine-00000000' - event loop stopped { timeout: 5985, ms: 524, res: 0 } [Nov 6 13:03:28] DEBUG[13376] res_fax_digium.c: destroying session '0' thread [Nov 6 13:03:28] DEBUG[13376] res_fax_digium.c: fax handle: 0 freeing document queue. [Nov 6 13:03:28] DEBUG[13376] res_fax_digium.c: closing fax handle: 0 [Nov 6 13:03:28] DEBUG[13376] res_fax_digium.c: Fax session '0' closed the G.711 link. [Nov 6 13:03:28] DEBUG[13376] res_fax.c: channel 'SIP/faxmachine-00000000' fax session '0' destroyed [Nov 6 13:03:28] DEBUG[13376] pbx.c: Function result is 'faxmachine' [Nov 6 13:03:28] DEBUG[13376] pbx.c: Spawn extension (inbound_fax,1010,6) exited non-zero on 'SIP/faxmachine-00000000' [Nov 6 13:03:28] VERBOSE[13376] logger.c: == Spawn extension (inbound_fax, 1010, 6) exited non-zero on 'SIP/faxmachine-00000000' [Nov 6 13:03:28] DEBUG[13376] channel.c: Soft-Hanging up channel 'SIP/faxmachine-00000000' [Nov 6 13:03:28] DEBUG[13376] channel.c: Hanging up channel 'SIP/faxmachine-00000000' [Nov 6 13:03:28] DEBUG[13376] chan_sip.c: Hangup call SIP/faxmachine-00000000, SIP callid 1b052486-b9789b86@10.1.1.111 [Nov 6 13:03:28] DEBUG[13376] res_fax.c: destroying session details (filename: '/root/FAX.TIF') [Nov 6 13:03:28] DEBUG[13376] devicestate.c: Notification of state change to be queued on device/channel SIP/faxmachine [Nov 6 13:03:28] DEBUG[13362] devicestate.c: No provider found, checking channel drivers for SIP - faxmachine [Nov 6 13:03:28] DEBUG[13362] chan_sip.c: Checking device state for peer faxmachine [Nov 6 13:03:28] DEBUG[13362] devicestate.c: Changing state for SIP/faxmachine - state 5 (Unavailable) [Nov 6 13:03:29] DEBUG[13369] chan_sip.c: Destroying SIP dialog 1b052486-b9789b86@10.1.1.111 [Nov 6 13:03:29] VERBOSE[13369] logger.c: Really destroying SIP dialog '1b052486-b9789b86@10.1.1.111' Method: BYE [Nov 6 13:07:32] VERBOSE[13373] logger.c: -- Remote UNIX connection disconnected [Nov 6 13:11:13] VERBOSE[13369] logger.c: <--- SIP read from UDP://10.1.1.111:5060 ---> REGISTER sip:10.1.1.223 SIP/2.0 Via: SIP/2.0/UDP 10.1.1.111:5060;branch=z9hG4bK-e907200 From: Fax Machine ;tag=42c2c25e41d32613o0 To: Fax Machine Call-ID: eeb73b0f-df4d1afb@10.1.1.111 CSeq: 56322 REGISTER Max-Forwards: 70 Authorization: Digest username="faxmachine",realm="midwestdatasystems.com",nonce="771d292c",uri="sip:10.1.1.223",algorithm=MD5,response="3c247bdad4233aea497b589abd3f3f96" Contact: Fax Machine ;expires=3600 User-Agent: Linksys/SPA2102-5.2.10 Content-Length: 0 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER Supported: x-sipura, replaces <-------------> [Nov 6 13:11:13] DEBUG[13369] chan_sip.c: Header 0 [ 31]: REGISTER sip:10.1.1.223 SIP/2.0 [Nov 6 13:11:13] DEBUG[13369] chan_sip.c: Header 1 [ 55]: Via: SIP/2.0/UDP 10.1.1.111:5060;branch=z9hG4bK-e907200 [Nov 6 13:11:13] DEBUG[13369] chan_sip.c: Header 2 [ 68]: From: Fax Machine ;tag=42c2c25e41d32613o0 [Nov 6 13:11:13] DEBUG[13369] chan_sip.c: Header 3 [ 43]: To: Fax Machine [Nov 6 13:11:13] DEBUG[13369] chan_sip.c: Header 4 [ 37]: Call-ID: eeb73b0f-df4d1afb@10.1.1.111 [Nov 6 13:11:13] DEBUG[13369] chan_sip.c: Header 5 [ 20]: CSeq: 56322 REGISTER [Nov 6 13:11:13] DEBUG[13369] chan_sip.c: Header 6 [ 16]: Max-Forwards: 70 [Nov 6 13:11:13] DEBUG[13369] chan_sip.c: Header 7 [170]: Authorization: Digest username="faxmachine",realm="midwestdatasystems.com",nonce="771d292c",uri="sip:10.1.1.223",algorithm=MD5,response="3c247bdad4233aea497b589abd3f3f96" [Nov 6 13:11:13] DEBUG[13369] chan_sip.c: Header 8 [ 66]: Contact: Fax Machine ;expires=3600 [Nov 6 13:11:13] DEBUG[13369] chan_sip.c: Header 9 [ 34]: User-Agent: Linksys/SPA2102-5.2.10 [Nov 6 13:11:13] DEBUG[13369] chan_sip.c: Header 10 [ 17]: Content-Length: 0 [Nov 6 13:11:13] DEBUG[13369] chan_sip.c: Header 11 [ 61]: Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER [Nov 6 13:11:13] DEBUG[13369] chan_sip.c: Header 12 [ 29]: Supported: x-sipura, replaces [Nov 6 13:11:13] DEBUG[13369] chan_sip.c: Header 13 [ 0]: [Nov 6 13:11:13] VERBOSE[13369] logger.c: --- (13 headers 0 lines) --- [Nov 6 13:11:13] DEBUG[13369] acl.c: Found IP address for this socket [Nov 6 13:11:13] DEBUG[13369] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.1.1.223:5060 [Nov 6 13:11:13] DEBUG[13369] chan_sip.c: Allocating new SIP dialog for eeb73b0f-df4d1afb@10.1.1.111 - REGISTER (No RTP) [Nov 6 13:11:13] DEBUG[13369] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [Nov 6 13:11:13] DEBUG[13369] chan_sip.c: Initializing initreq for method REGISTER - callid eeb73b0f-df4d1afb@10.1.1.111 [Nov 6 13:11:13] VERBOSE[13369] logger.c: Sending to 10.1.1.111 : 5060 (no NAT) [Nov 6 13:11:13] VERBOSE[13369] logger.c: <--- Transmitting (no NAT) to 10.1.1.111:5060 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 10.1.1.111:5060;branch=z9hG4bK-e907200;received=10.1.1.111 From: Fax Machine ;tag=42c2c25e41d32613o0 To: Fax Machine ;tag=as0c1f96fe Call-ID: eeb73b0f-df4d1afb@10.1.1.111 CSeq: 56322 REGISTER User-Agent: Asterisk PBX SVN-branch-1.6.0-r228500 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer WWW-Authenticate: Digest algorithm=MD5, realm="midwestdatasystems.com", nonce="3ebd9c6a" Content-Length: 0 <------------> [Nov 6 13:11:13] DEBUG[13369] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 10.1.1.111:5060 [Nov 6 13:11:13] VERBOSE[13369] logger.c: Scheduling destruction of SIP dialog 'eeb73b0f-df4d1afb@10.1.1.111' in 32000 ms (Method: REGISTER) [Nov 6 13:11:13] VERBOSE[13369] logger.c: <--- SIP read from UDP://10.1.1.111:5060 ---> REGISTER sip:10.1.1.223 SIP/2.0 Via: SIP/2.0/UDP 10.1.1.111:5060;branch=z9hG4bK-b02a6f71 From: Fax Machine ;tag=42c2c25e41d32613o0 To: Fax Machine Call-ID: eeb73b0f-df4d1afb@10.1.1.111 CSeq: 56323 REGISTER Max-Forwards: 70 Authorization: Digest username="faxmachine",realm="midwestdatasystems.com",nonce="3ebd9c6a",uri="sip:10.1.1.223",algorithm=MD5,response="9c96a72eb45f2a728849a5a7eaa48477" Contact: Fax Machine ;expires=3600 User-Agent: Linksys/SPA2102-5.2.10 Content-Length: 0 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER Supported: x-sipura, replaces <-------------> [Nov 6 13:11:13] DEBUG[13369] chan_sip.c: Header 0 [ 31]: REGISTER sip:10.1.1.223 SIP/2.0 [Nov 6 13:11:13] DEBUG[13369] chan_sip.c: Header 1 [ 56]: Via: SIP/2.0/UDP 10.1.1.111:5060;branch=z9hG4bK-b02a6f71 [Nov 6 13:11:13] DEBUG[13369] chan_sip.c: Header 2 [ 68]: From: Fax Machine ;tag=42c2c25e41d32613o0 [Nov 6 13:11:13] DEBUG[13369] chan_sip.c: Header 3 [ 43]: To: Fax Machine [Nov 6 13:11:13] DEBUG[13369] chan_sip.c: Header 4 [ 37]: Call-ID: eeb73b0f-df4d1afb@10.1.1.111 [Nov 6 13:11:13] DEBUG[13369] chan_sip.c: Header 5 [ 20]: CSeq: 56323 REGISTER [Nov 6 13:11:13] DEBUG[13369] chan_sip.c: Header 6 [ 16]: Max-Forwards: 70 [Nov 6 13:11:13] DEBUG[13369] chan_sip.c: Header 7 [170]: Authorization: Digest username="faxmachine",realm="midwestdatasystems.com",nonce="3ebd9c6a",uri="sip:10.1.1.223",algorithm=MD5,response="9c96a72eb45f2a728849a5a7eaa48477" [Nov 6 13:11:13] DEBUG[13369] chan_sip.c: Header 8 [ 66]: Contact: Fax Machine ;expires=3600 [Nov 6 13:11:13] DEBUG[13369] chan_sip.c: Header 9 [ 34]: User-Agent: Linksys/SPA2102-5.2.10 [Nov 6 13:11:13] DEBUG[13369] chan_sip.c: Header 10 [ 17]: Content-Length: 0 [Nov 6 13:11:13] DEBUG[13369] chan_sip.c: Header 11 [ 61]: Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER [Nov 6 13:11:13] DEBUG[13369] chan_sip.c: Header 12 [ 29]: Supported: x-sipura, replaces [Nov 6 13:11:13] DEBUG[13369] chan_sip.c: Header 13 [ 0]: [Nov 6 13:11:13] VERBOSE[13369] logger.c: --- (13 headers 0 lines) --- [Nov 6 13:11:13] DEBUG[13369] chan_sip.c: = Found Their Call ID: eeb73b0f-df4d1afb@10.1.1.111 Their Tag 42c2c25e41d32613o0 Our tag: as0c1f96fe [Nov 6 13:11:13] DEBUG[13369] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [Nov 6 13:11:13] DEBUG[13369] chan_sip.c: Initializing initreq for method REGISTER - callid eeb73b0f-df4d1afb@10.1.1.111 [Nov 6 13:11:13] VERBOSE[13369] logger.c: Sending to 10.1.1.111 : 5060 (no NAT) [Nov 6 13:11:13] VERBOSE[13369] logger.c: -- Registered SIP 'faxmachine' at 10.1.1.111 port 5060 [Nov 6 13:11:13] VERBOSE[13369] logger.c: > Saved useragent "Linksys/SPA2102-5.2.10" for peer faxmachine [Nov 6 13:11:13] VERBOSE[13369] logger.c: <--- Transmitting (no NAT) to 10.1.1.111:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.1.1.111:5060;branch=z9hG4bK-b02a6f71;received=10.1.1.111 From: Fax Machine ;tag=42c2c25e41d32613o0 To: Fax Machine ;tag=as0c1f96fe Call-ID: eeb73b0f-df4d1afb@10.1.1.111 CSeq: 56323 REGISTER User-Agent: Asterisk PBX SVN-branch-1.6.0-r228500 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer Expires: 3600 Contact: sip:faxmachine@10.1.1.111:5060;expires=3600 Date: Fri, 06 Nov 2009 19:11:13 GMT Content-Length: 0 <------------> [Nov 6 13:11:13] DEBUG[13369] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.1.1.111:5060 [Nov 6 13:11:13] DEBUG[13369] devicestate.c: Notification of state change to be queued on device/channel SIP/faxmachine [Nov 6 13:11:13] VERBOSE[13369] logger.c: Scheduling destruction of SIP dialog 'eeb73b0f-df4d1afb@10.1.1.111' in 32000 ms (Method: REGISTER) [Nov 6 13:11:13] DEBUG[13362] devicestate.c: No provider found, checking channel drivers for SIP - faxmachine [Nov 6 13:11:13] DEBUG[13362] chan_sip.c: Checking device state for peer faxmachine [Nov 6 13:11:13] DEBUG[13362] devicestate.c: Changing state for SIP/faxmachine - state 1 (Not in use) [Nov 6 13:11:45] DEBUG[13369] chan_sip.c: Auto destroying SIP dialog 'eeb73b0f-df4d1afb@10.1.1.111' [Nov 6 13:11:45] DEBUG[13369] chan_sip.c: Destroying SIP dialog eeb73b0f-df4d1afb@10.1.1.111 [Nov 6 13:11:45] VERBOSE[13369] logger.c: Really destroying SIP dialog 'eeb73b0f-df4d1afb@10.1.1.111' Method: REGISTER [Nov 6 13:12:34] VERBOSE[13360] logger.c: -- Remote UNIX connection [Nov 6 13:13:28] VERBOSE[13490] logger.c: -- Remote UNIX connection disconnected [Nov 6 13:14:46] VERBOSE[13360] logger.c: -- Remote UNIX connection [Nov 6 13:16:14] VERBOSE[13495] logger.c: -- Remote UNIX connection disconnected