-- Goto (faxserver,s,1) [May 4 15:41:37] DEBUG[32702]: pbx.c:4371 pbx_extension_helper: Launching 'NoOp' -- Executing [s@faxserver:1] NoOp("SIP/700001BOUL1-00000001", ">>>>>>> Receive a Fax <<<<<<<") in new stack [May 4 15:41:37] DEBUG[32702]: pbx.c:3966 ast_str_substitute_variables_full: Evaluating 'UNIQUEID' (from 'UNIQUEID}' len 8) [May 4 15:41:37] DEBUG[32702]: pbx.c:3380 ast_str_retrieve_variable: Result of 'UNIQUEID' is '1336138897.1' [May 4 15:41:37] DEBUG[32702]: pbx.c:4199 pbx_substitute_variables_helper_full: Function result is '1336138897' [May 4 15:41:37] DEBUG[32702]: pbx.c:3966 ast_str_substitute_variables_full: Evaluating 'UNIQUEID' (from 'UNIQUEID}' len 8) [May 4 15:41:37] DEBUG[32702]: pbx.c:3380 ast_str_retrieve_variable: Result of 'UNIQUEID' is '1336138897.1' [May 4 15:41:37] DEBUG[32702]: pbx.c:4199 pbx_substitute_variables_helper_full: Function result is '1' [May 4 15:41:37] DEBUG[32702]: pbx.c:4371 pbx_extension_helper: Launching 'Set' -- Executing [s@faxserver:2] Set("SIP/700001BOUL1-00000001", "faxuid=13361388971") in new stack [May 4 15:41:37] DEBUG[32702]: pbx.c:3380 ast_str_retrieve_variable: Result of 'orig_dialed_num' is '554' [May 4 15:41:37] DEBUG[32702]: pbx.c:4371 pbx_extension_helper: Launching 'Set' -- Executing [s@faxserver:3] Set("SIP/700001BOUL1-00000001", "FAXOPT(localstationid)=554") in new stack [May 4 15:41:37] DEBUG[32702]: res_fax.c:3692 acf_faxopt_write: channel 'SIP/700001BOUL1-00000001' setting FAXOPT(localstationid) to '554' [May 4 15:41:37] DEBUG[32702]: pbx.c:4371 pbx_extension_helper: Launching 'Answer' -- Executing [s@faxserver:4] Answer("SIP/700001BOUL1-00000001", "") in new stack [May 4 15:41:37] DEBUG[32702]: chan_sip.c:6522 sip_answer: SIP answering channel: SIP/700001BOUL1-00000001 [May 4 15:41:37] DEBUG[32702]: res_rtp_asterisk.c:826 ast_rtp_update_source: Setting the marker bit due to a source update [May 4 15:41:37] DEBUG[32330]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for SIP - 700001BOUL1 [May 4 15:41:37] DEBUG[32330]: chan_sip.c:27251 sip_devicestate: Checking device state for peer 700001BOUL1 [May 4 15:41:37] DEBUG[32330]: devicestate.c:458 do_state_change: Changing state for SIP/700001BOUL1 - state 1 (Not in use) [May 4 15:41:37] DEBUG[32330]: devicestate.c:438 devstate_event: device 'SIP/700001BOUL1' state '1' [May 4 15:41:37] DEBUG[32702]: chan_sip.c:12126 transmit_response_with_sdp: Setting framing from config on incoming call [May 4 15:41:37] DEBUG[32345]: app_queue.c:1511 handle_statechange: Device 'SIP/700001BOUL1' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [May 4 15:41:37] DEBUG[32702]: chan_sip.c:11702 add_sdp: ** Our capability: (alaw) Video flag: True Text flag: True [May 4 15:41:37] DEBUG[32702]: chan_sip.c:11703 add_sdp: ** Our prefcodec: (nothing) Audio is at 18510 Adding codec 100004 (alaw) to SDP Adding non-codec 0x1 (telephone-event) to SDP [May 4 15:41:37] DEBUG[32702]: chan_sip.c:11822 add_sdp: -- Done with adding codecs to SDP [May 4 15:41:37] DEBUG[32702]: chan_sip.c:12017 add_sdp: Done building SDP. Settling with this capability: (alaw) <--- Reliably Transmitting (NAT) to 1.1.1.1:5070 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 1.1.1.1:5070;branch=z9hG4bK8905.335655a5.0;i=2;received=1.1.1.1;rport=5070 Via: SIP/2.0/TLS 192.168.0.14:5061;received=2.2.2.2;branch=z9hG4bK1424128440;rport=2058;alias Record-Route: Record-Route: From: "grandstream" ;tag=646086968 To: ;tag=as74ae86f0 Call-ID: 367762855-5061-21@BJC.BGI.A.BE CSeq: 201 INVITE Server: vmybox Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces Contact: Content-Type: application/sdp Content-Length: 222 v=0 o=root 862509026 862509026 IN IP4 1.1.1.1 s=vmybox c=IN IP4 1.1.1.1 t=0 0 m=audio 18510 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv <------------> [May 4 15:41:37] DEBUG[32702]: chan_sip.c:3823 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #20 [May 4 15:41:37] DEBUG[32702]: chan_sip.c:3366 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for 1.1.1.1:5070 vmybox*CLI> <--- SIP read from UDP:1.1.1.1:5070 ---> ACK sip:554@1.1.1.1:5060 SIP/2.0 Via: SIP/2.0/UDP 1.1.1.1:5070;branch=z9hG4bKcydzigwkX;i=2 Via: SIP/2.0/TLS 192.168.0.14:5061;received=2.2.2.2;branch=z9hG4bK1417924977;rport=2058 From: "grandstream" ;tag=646086968 To: ;tag=as74ae86f0 Call-ID: 367762855-5061-21@BJC.BGI.A.BE CSeq: 201 ACK Contact: Proxy-Authorization: Digest username="700001BOUL1", realm="1.1.1.1", nonce="T6PdvU+j3JHjF6wlTlyDZOCBNoiExX1z", uri="sip:554@1.1.1.1:5061", response="abe31401b117065933e1c8c74ab721a3", algorithm=MD5 Max-Forwards: 69 Supported: replaces, path, timer, eventlist User-Agent: Grandstream HT-502 V1.1C 1.0.5.10 Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE Content-Length: 0 <-------------> [May 4 15:41:37] DEBUG[32337]: chan_sip.c:8679 parse_request: Header 0 [ 38]: ACK sip:554@1.1.1.1:5060 SIP/2.0 [May 4 15:41:37] DEBUG[32337]: chan_sip.c:8679 parse_request: Header 1 [ 63]: Via: SIP/2.0/UDP 1.1.1.1:5070;branch=z9hG4bKcydzigwkX;i=2 [May 4 15:41:37] DEBUG[32337]: chan_sip.c:8679 parse_request: Header 2 [ 93]: Via: SIP/2.0/TLS 192.168.0.14:5061;received=2.2.2.2;branch=z9hG4bK1417924977;rport=2058 [May 4 15:41:37] DEBUG[32337]: chan_sip.c:8679 parse_request: Header 3 [ 71]: From: "grandstream" ;tag=646086968 [May 4 15:41:37] DEBUG[32337]: chan_sip.c:8679 parse_request: Header 4 [ 48]: To: ;tag=as74ae86f0 [May 4 15:41:37] DEBUG[32337]: chan_sip.c:8679 parse_request: Header 5 [ 39]: Call-ID: 367762855-5061-21@BJC.BGI.A.BE [May 4 15:41:37] DEBUG[32337]: chan_sip.c:8679 parse_request: Header 6 [ 13]: CSeq: 201 ACK [May 4 15:41:37] DEBUG[32337]: chan_sip.c:8679 parse_request: Header 7 [ 59]: Contact: [May 4 15:41:37] DEBUG[32337]: chan_sip.c:8679 parse_request: Header 8 [211]: Proxy-Authorization: Digest username="700001BOUL1", realm="1.1.1.1", nonce="T6PdvU+j3JHjF6wlTlyDZOCBNoiExX1z", uri="sip:554@1.1.1.1:5061", response="abe31401b117065933e1c8c74ab721a3", algorithm=MD5 [May 4 15:41:37] DEBUG[32337]: chan_sip.c:8679 parse_request: Header 9 [ 16]: Max-Forwards: 69 [May 4 15:41:37] DEBUG[32337]: chan_sip.c:8679 parse_request: Header 10 [ 43]: Supported: replaces, path, timer, eventlist [May 4 15:41:37] DEBUG[32337]: chan_sip.c:8679 parse_request: Header 11 [ 46]: User-Agent: Grandstream HT-502 V1.1C 1.0.5.10 [May 4 15:41:37] DEBUG[32337]: chan_sip.c:8679 parse_request: Header 12 [ 80]: Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE [May 4 15:41:37] DEBUG[32337]: chan_sip.c:8679 parse_request: Header 13 [ 17]: Content-Length: 0 [May 4 15:41:37] DEBUG[32337]: chan_sip.c:8679 parse_request: Header 14 [ 0]: --- (14 headers 0 lines) --- [May 4 15:41:37] DEBUG[32337]: chan_sip.c:25940 handle_incoming: **** Received ACK (6) - Command in SIP ACK [May 4 15:41:37] DEBUG[32337]: chan_sip.c:4018 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #20 [May 4 15:41:37] DEBUG[32337]: chan_sip.c:4051 __sip_ack: Stopping retransmission on '367762855-5061-21@BJC.BGI.A.BE' of Response 201: Match Found vmybox*CLI> [May 4 15:41:37] DEBUG[32702]: res_rtp_asterisk.c:2149 ast_rtp_read: 0x629b970 -- start learning mode pass with addr = 2.2.2.2:5004 [May 4 15:41:37] DEBUG[32702]: res_rtp_asterisk.c:500 rtp_learning_rtp_seq_update: 0x629b970 -- probation = 4, seq = 28284 [May 4 15:41:37] DEBUG[32702]: res_rtp_asterisk.c:2155 ast_rtp_read: 0x629b970 -- Condition for learning hasn't exited, so reject the frame. vmybox*CLI> [May 4 15:41:37] DEBUG[32702]: res_rtp_asterisk.c:2149 ast_rtp_read: 0x629b970 -- start learning mode pass with addr = 2.2.2.2:5004 [May 4 15:41:37] DEBUG[32702]: res_rtp_asterisk.c:500 rtp_learning_rtp_seq_update: 0x629b970 -- probation = 3, seq = 28285 [May 4 15:41:37] DEBUG[32702]: res_rtp_asterisk.c:2155 ast_rtp_read: 0x629b970 -- Condition for learning hasn't exited, so reject the frame. [May 4 15:41:37] DEBUG[32702]: res_rtp_asterisk.c:2149 ast_rtp_read: 0x629b970 -- start learning mode pass with addr = 2.2.2.2:5004 [May 4 15:41:37] DEBUG[32702]: res_rtp_asterisk.c:500 rtp_learning_rtp_seq_update: 0x629b970 -- probation = 2, seq = 28286 [May 4 15:41:37] DEBUG[32702]: res_rtp_asterisk.c:2155 ast_rtp_read: 0x629b970 -- Condition for learning hasn't exited, so reject the frame. vmybox*CLI> [May 4 15:41:37] DEBUG[32702]: res_rtp_asterisk.c:2149 ast_rtp_read: 0x629b970 -- start learning mode pass with addr = 2.2.2.2:5004 [May 4 15:41:37] DEBUG[32702]: res_rtp_asterisk.c:500 rtp_learning_rtp_seq_update: 0x629b970 -- probation = 1, seq = 28287 [May 4 15:41:37] DEBUG[32702]: res_rtp_asterisk.c:2159 ast_rtp_read: 0x629b970 -- Probation Ended. Set strict_rtp_state to STRICT_RTP_CLOSED with address 2.2.2.2:5004 [May 4 15:41:37] DEBUG[32702]: res_rtp_asterisk.c:2562 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x6290058' [May 4 15:41:37] DEBUG[32702]: pbx.c:4371 pbx_extension_helper: Launching 'PlayTones' -- Executing [s@faxserver:5] PlayTones("SIP/700001BOUL1-00000001", "ring") in new stack [May 4 15:41:37] DEBUG[32702]: channel.c:5268 set_format: Set channel SIP/700001BOUL1-00000001 to write format slin [May 4 15:41:37] DEBUG[32702]: channel.c:3557 ast_settimeout: Scheduling timer at (50 requested / 50 actual) timer ticks per second [May 4 15:41:37] DEBUG[32702]: pbx.c:4371 pbx_extension_helper: Launching 'Wait' -- Executing [s@faxserver:6] Wait("SIP/700001BOUL1-00000001", "1") in new stack vmybox*CLI> [May 4 15:41:37] DEBUG[32702]: res_rtp_asterisk.c:1355 ast_rtp_write: Ooh, format changed from unknown to alaw [May 4 15:41:37] DEBUG[32702]: res_rtp_asterisk.c:1390 ast_rtp_write: Created smoother: format: alaw ms: 20 len: 160 [May 4 15:41:37] DEBUG[32702]: res_rtp_asterisk.c:2149 ast_rtp_read: 0x629b970 -- start learning mode pass with addr = 2.2.2.2:5004 [May 4 15:41:37] DEBUG[32702]: res_rtp_asterisk.c:500 rtp_learning_rtp_seq_update: 0x629b970 -- probation = 4, seq = 28288 [May 4 15:41:37] DEBUG[32702]: res_rtp_asterisk.c:2155 ast_rtp_read: 0x629b970 -- Condition for learning hasn't exited, so reject the frame. [May 4 15:41:37] DEBUG[32702]: res_rtp_asterisk.c:2149 ast_rtp_read: 0x629b970 -- start learning mode pass with addr = 2.2.2.2:5004 [May 4 15:41:37] DEBUG[32702]: res_rtp_asterisk.c:500 rtp_learning_rtp_seq_update: 0x629b970 -- probation = 3, seq = 28289 [May 4 15:41:37] DEBUG[32702]: res_rtp_asterisk.c:2155 ast_rtp_read: 0x629b970 -- Condition for learning hasn't exited, so reject the frame. vmybox*CLI> [May 4 15:41:37] DEBUG[32702]: res_rtp_asterisk.c:2149 ast_rtp_read: 0x629b970 -- start learning mode pass with addr = 2.2.2.2:5004 [May 4 15:41:37] DEBUG[32702]: res_rtp_asterisk.c:500 rtp_learning_rtp_seq_update: 0x629b970 -- probation = 2, seq = 28290 [May 4 15:41:37] DEBUG[32702]: res_rtp_asterisk.c:2155 ast_rtp_read: 0x629b970 -- Condition for learning hasn't exited, so reject the frame. vmybox*CLI> [May 4 15:41:37] DEBUG[32702]: res_rtp_asterisk.c:2149 ast_rtp_read: 0x629b970 -- start learning mode pass with addr = 2.2.2.2:5004 [May 4 15:41:37] DEBUG[32702]: res_rtp_asterisk.c:500 rtp_learning_rtp_seq_update: 0x629b970 -- probation = 1, seq = 28291 [May 4 15:41:37] DEBUG[32702]: res_rtp_asterisk.c:2159 ast_rtp_read: 0x629b970 -- Probation Ended. Set strict_rtp_state to STRICT_RTP_CLOSED with address 2.2.2.2:5004 [May 4 15:41:38] DEBUG[32702]: pbx.c:4371 pbx_extension_helper: Launching 'StopPlayTones' -- Executing [s@faxserver:7] StopPlayTones("SIP/700001BOUL1-00000001", "") in new stack [May 4 15:41:38] DEBUG[32702]: channel.c:5268 set_format: Set channel SIP/700001BOUL1-00000001 to write format alaw [May 4 15:41:38] DEBUG[32702]: channel.c:3557 ast_settimeout: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 4 15:41:38] DEBUG[32702]: pbx.c:4371 pbx_extension_helper: Launching 'Set' -- Executing [s@faxserver:8] Set("SIP/700001BOUL1-00000001", "TIMEOUT(absolute)=7200") in new stack Channel will hangup at 2012-05-04 17:41:38.696 CEST. [May 4 15:41:38] DEBUG[32702]: pbx.c:3380 ast_str_retrieve_variable: Result of 'faxuid' is '13361388971' [May 4 15:41:38] DEBUG[32702]: pbx.c:4371 pbx_extension_helper: Launching 'ReceiveFAX' -- Executing [s@faxserver:9] ReceiveFAX("SIP/700001BOUL1-00000001", "/tmp/fax-13361388971.tif,f") in new stack -- Channel 'SIP/700001BOUL1-00000001' receiving FAX '/tmp/fax-13361388971.tif' [May 4 15:41:38] DEBUG[32702]: res_fax.c:912 fax_session_reserve: Reserving a FAX session from 'Spandsp FAX Driver'. [May 4 15:41:38] DEBUG[32702]: res_fax.c:927 fax_session_reserve: Selected FAX technology module (Spandsp FAX Driver) does not support reserving sessions. [May 4 15:41:38] DEBUG[32702]: channel.c:5268 set_format: Set channel SIP/700001BOUL1-00000001 to write format slin [May 4 15:41:38] DEBUG[32702]: channel.c:3557 ast_settimeout: Scheduling timer at (50 requested / 50 actual) timer ticks per second [May 4 15:41:41] DEBUG[32702]: channel.c:3124 generator_force: Auto-deactivating generator [May 4 15:41:41] DEBUG[32702]: channel.c:5268 set_format: Set channel SIP/700001BOUL1-00000001 to write format alaw [May 4 15:41:41] DEBUG[32702]: channel.c:3557 ast_settimeout: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 4 15:41:41] DEBUG[32702]: res_fax.c:1617 receivefax_t38_init: Negotiating T.38 for receive on SIP/700001BOUL1-00000001 == Using UDPTL TOS bits 184 == Using UDPTL CoS mark 5 [May 4 15:41:41] DEBUG[32702]: chan_sip.c:6862 initialize_udptl: Setting NAT on UDPTL to On [May 4 15:41:41] DEBUG[32702]: chan_sip.c:5153 change_t38_state: T38 state changed to 1 on channel SIP/700001BOUL1-00000001 set_destination: Parsing for address/port to send to [May 4 15:41:41] DEBUG[32702]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting '1.1.1.1:5070' into... [May 4 15:41:41] DEBUG[32702]: netsock2.c:188 ast_sockaddr_split_hostport: ...host '1.1.1.1' and port '5070'. set_destination: set destination to 1.1.1.1:5070 [May 4 15:41:41] DEBUG[32702]: chan_sip.c:11857 add_sdp: T.38 UDPTL is at 1.1.1.1 port 4363 [May 4 15:41:41] DEBUG[32702]: chan_sip.c:12017 add_sdp: Done building SDP. Settling with this capability: (nothing) [May 4 15:41:41] DEBUG[32702]: chan_sip.c:3093 initialize_initreq: Initializing already initialized SIP dialog 367762855-5061-21@BJC.BGI.A.BE (presumably reinvite) [May 4 15:41:41] DEBUG[32702]: chan_sip.c:8679 parse_request: Header 0 [ 63]: INVITE sip:700001BOUL1@2.2.2.2:2058;transport=tls SIP/2.0 [May 4 15:41:41] DEBUG[32702]: chan_sip.c:8679 parse_request: Header 1 [ 64]: Via: SIP/2.0/UDP 1.1.1.1:5060;branch=z9hG4bK3b0bd1c8;rport [May 4 15:41:41] DEBUG[32702]: chan_sip.c:8679 parse_request: Header 2 [124]: Route: , [May 4 15:41:41] DEBUG[32702]: chan_sip.c:8679 parse_request: Header 3 [ 16]: Max-Forwards: 70 [May 4 15:41:41] DEBUG[32702]: chan_sip.c:8679 parse_request: Header 4 [ 50]: From: ;tag=as74ae86f0 [May 4 15:41:41] DEBUG[32702]: chan_sip.c:8679 parse_request: Header 5 [ 69]: To: "grandstream" ;tag=646086968 [May 4 15:41:41] DEBUG[32702]: chan_sip.c:8679 parse_request: Header 6 [ 37]: Contact: [May 4 15:41:41] DEBUG[32702]: chan_sip.c:8679 parse_request: Header 7 [ 39]: Call-ID: 367762855-5061-21@BJC.BGI.A.BE [May 4 15:41:41] DEBUG[32702]: chan_sip.c:8679 parse_request: Header 8 [ 16]: CSeq: 102 INVITE [May 4 15:41:41] DEBUG[32702]: chan_sip.c:8679 parse_request: Header 9 [ 18]: User-Agent: vmybox [May 4 15:41:41] DEBUG[32702]: chan_sip.c:8679 parse_request: Header 10 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH [May 4 15:41:41] DEBUG[32702]: chan_sip.c:8679 parse_request: Header 11 [ 19]: Supported: replaces [May 4 15:41:41] DEBUG[32702]: chan_sip.c:8679 parse_request: Header 12 [ 52]: X-asterisk-Info: SIP re-invite (External RTP bridge) [May 4 15:41:41] DEBUG[32702]: chan_sip.c:8679 parse_request: Header 13 [ 29]: Content-Type: application/sdp Reliably Transmitting (NAT) to 1.1.1.1:5070: INVITE sip:700001BOUL1@2.2.2.2:2058;transport=tls SIP/2.0 Via: SIP/2.0/UDP 1.1.1.1:5060;branch=z9hG4bK3b0bd1c8;rport Route: , Max-Forwards: 70 From: ;tag=as74ae86f0 To: "grandstream" ;tag=646086968 Contact: Call-ID: 367762855-5061-21@BJC.BGI.A.BE CSeq: 102 INVITE User-Agent: vmybox Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces X-asterisk-Info: SIP re-invite (External RTP bridge) Content-Type: application/sdp Content-Length: 258 v=0 o=root 862509026 862509027 IN IP4 1.1.1.1 s=vmybox c=IN IP4 1.1.1.1 t=0 0 m=image 4363 udptl t38 a=T38FaxVersion:0 a=T38MaxBitRate:14400 a=T38FaxRateManagement:transferredTCF a=T38FaxMaxDatagram:1400 a=T38FaxUdpEC:t38UDPRedundancy --- [May 4 15:41:41] DEBUG[32702]: chan_sip.c:3823 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #22 [May 4 15:41:41] DEBUG[32702]: chan_sip.c:3366 __sip_xmit: Trying to put 'INVITE sip:' onto UDP socket destined for 1.1.1.1:5070 <--- SIP read from UDP:1.1.1.1:5070 ---> SIP/2.0 100 trying -- your call is important to us Via: SIP/2.0/UDP 1.1.1.1:5060;branch=z9hG4bK3b0bd1c8;rport=5060 From: ;tag=as74ae86f0 To: "grandstream" ;tag=646086968 Call-ID: 367762855-5061-21@BJC.BGI.A.BE CSeq: 102 INVITE Server: vmybox Proxy Content-Length: 0 <-------------> [May 4 15:41:41] DEBUG[32337]: chan_sip.c:8679 parse_request: Header 0 [ 50]: SIP/2.0 100 trying -- your call is important to us [May 4 15:41:41] DEBUG[32337]: chan_sip.c:8679 parse_request: Header 1 [ 69]: Via: SIP/2.0/UDP 1.1.1.1:5060;branch=z9hG4bK3b0bd1c8;rport=5060 [May 4 15:41:41] DEBUG[32337]: chan_sip.c:8679 parse_request: Header 2 [ 50]: From: ;tag=as74ae86f0 [May 4 15:41:41] DEBUG[32337]: chan_sip.c:8679 parse_request: Header 3 [ 69]: To: "grandstream" ;tag=646086968 [May 4 15:41:41] DEBUG[32337]: chan_sip.c:8679 parse_request: Header 4 [ 39]: Call-ID: 367762855-5061-21@BJC.BGI.A.BE [May 4 15:41:41] DEBUG[32337]: chan_sip.c:8679 parse_request: Header 5 [ 16]: CSeq: 102 INVITE [May 4 15:41:41] DEBUG[32337]: chan_sip.c:8679 parse_request: Header 6 [ 20]: Server: vmybox Proxy [May 4 15:41:41] DEBUG[32337]: chan_sip.c:8679 parse_request: Header 7 [ 17]: Content-Length: 0 [May 4 15:41:41] DEBUG[32337]: chan_sip.c:8679 parse_request: Header 8 [ 0]: --- (8 headers 0 lines) --- [May 4 15:41:41] DEBUG[32337]: chan_sip.c:4085 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #22 - INVITE (got response) [May 4 15:41:41] DEBUG[32337]: chan_sip.c:4092 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '367762855-5061-21@BJC.BGI.A.BE' Request 102: Found [May 4 15:41:41] DEBUG[32337]: chan_sip.c:20558 handle_response_invite: SIP response 100 to RE-invite on outgoing call 367762855-5061-21@BJC.BGI.A.BE <--- SIP read from UDP:1.1.1.1:5070 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 1.1.1.1:5060;branch=z9hG4bK3b0bd1c8;rport=5060 From: ;tag=as74ae86f0 To: "grandstream" ;tag=646086968 Call-ID: 367762855-5061-21@BJC.BGI.A.BE CSeq: 102 INVITE Contact: Supported: replaces, path, timer, eventlist User-Agent: Grandstream HT-502 V1.1C 1.0.5.10 Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE Content-Type: application/sdp Content-Length: 278 v=0 o=700001BOUL1 8000 8001 IN IP4 192.168.0.14 s=SIP Call c=IN IP4 192.168.0.14 t=0 0 m=image 5004 udptl t38 a=T38FaxVersion:0 a=T38MaxBitRate:14400 a=T38FaxRateManagement:transferredTCF a=T38FaxMaxBuffer:400 a=T38FaxMaxDatagram:1400 a=T38FaxUdpEC:t38UDPRedundancy <-------------> [May 4 15:41:41] DEBUG[32337]: chan_sip.c:8679 parse_request: Header 0 [ 14]: SIP/2.0 200 OK [May 4 15:41:41] DEBUG[32337]: chan_sip.c:8679 parse_request: Header 1 [ 69]: Via: SIP/2.0/UDP 1.1.1.1:5060;branch=z9hG4bK3b0bd1c8;rport=5060 [May 4 15:41:41] DEBUG[32337]: chan_sip.c:8679 parse_request: Header 2 [ 50]: From: ;tag=as74ae86f0 [May 4 15:41:41] DEBUG[32337]: chan_sip.c:8679 parse_request: Header 3 [ 69]: To: "grandstream" ;tag=646086968 [May 4 15:41:41] DEBUG[32337]: chan_sip.c:8679 parse_request: Header 4 [ 39]: Call-ID: 367762855-5061-21@BJC.BGI.A.BE [May 4 15:41:41] DEBUG[32337]: chan_sip.c:8679 parse_request: Header 5 [ 16]: CSeq: 102 INVITE [May 4 15:41:41] DEBUG[32337]: chan_sip.c:8679 parse_request: Header 6 [ 59]: Contact: [May 4 15:41:41] DEBUG[32337]: chan_sip.c:8679 parse_request: Header 7 [ 43]: Supported: replaces, path, timer, eventlist [May 4 15:41:41] DEBUG[32337]: chan_sip.c:8679 parse_request: Header 8 [ 46]: User-Agent: Grandstream HT-502 V1.1C 1.0.5.10 [May 4 15:41:41] DEBUG[32337]: chan_sip.c:8679 parse_request: Header 9 [ 80]: Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE [May 4 15:41:41] DEBUG[32337]: chan_sip.c:8679 parse_request: Header 10 [ 29]: Content-Type: application/sdp [May 4 15:41:41] DEBUG[32337]: chan_sip.c:8679 parse_request: Header 11 [ 21]: Content-Length: 278 [May 4 15:41:41] DEBUG[32337]: chan_sip.c:8679 parse_request: Header 12 [ 0]: [May 4 15:41:41] DEBUG[32337]: chan_sip.c:8679 parse_request: Body 0 [ 3]: v=0 [May 4 15:41:41] DEBUG[32337]: chan_sip.c:8679 parse_request: Body 1 [ 43]: o=700001BOUL1 8000 8001 IN IP4 192.168.0.14 [May 4 15:41:41] DEBUG[32337]: chan_sip.c:8679 parse_request: Body 2 [ 10]: s=SIP Call [May 4 15:41:41] DEBUG[32337]: chan_sip.c:8679 parse_request: Body 3 [ 21]: c=IN IP4 192.168.0.14 [May 4 15:41:41] DEBUG[32337]: chan_sip.c:8679 parse_request: Body 4 [ 5]: t=0 0 [May 4 15:41:41] DEBUG[32337]: chan_sip.c:8679 parse_request: Body 5 [ 22]: m=image 5004 udptl t38 [May 4 15:41:41] DEBUG[32337]: chan_sip.c:8679 parse_request: Body 6 [ 17]: a=T38FaxVersion:0 [May 4 15:41:41] DEBUG[32337]: chan_sip.c:8679 parse_request: Body 7 [ 21]: a=T38MaxBitRate:14400 [May 4 15:41:41] DEBUG[32337]: chan_sip.c:8679 parse_request: Body 8 [ 37]: a=T38FaxRateManagement:transferredTCF [May 4 15:41:41] DEBUG[32337]: chan_sip.c:8679 parse_request: Body 9 [ 21]: a=T38FaxMaxBuffer:400 [May 4 15:41:41] DEBUG[32337]: chan_sip.c:8679 parse_request: Body 10 [ 24]: a=T38FaxMaxDatagram:1400 [May 4 15:41:41] DEBUG[32337]: chan_sip.c:8679 parse_request: Body 11 [ 30]: a=T38FaxUdpEC:t38UDPRedundancy --- (12 headers 12 lines) --- [May 4 15:41:41] DEBUG[32337]: chan_sip.c:4013 __sip_ack: Acked pending invite 102 [May 4 15:41:41] DEBUG[32337]: chan_sip.c:4051 __sip_ack: Stopping retransmission on '367762855-5061-21@BJC.BGI.A.BE' of Request 102: Match Found [May 4 15:41:41] DEBUG[32337]: chan_sip.c:20558 handle_response_invite: SIP response 200 to RE-invite on outgoing call 367762855-5061-21@BJC.BGI.A.BE [May 4 15:41:41] DEBUG[32337]: chan_sip.c:9083 process_sdp: Processing session-level SDP v=0... UNSUPPORTED. [May 4 15:41:41] DEBUG[32337]: chan_sip.c:9083 process_sdp: Processing session-level SDP o=700001BOUL1 8000 8001 IN IP4 192.168.0.14... UNSUPPORTED. [May 4 15:41:41] DEBUG[32337]: chan_sip.c:9083 process_sdp: Processing session-level SDP s=SIP Call... UNSUPPORTED. [May 4 15:41:41] DEBUG[32337]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting '192.168.0.14' into... [May 4 15:41:41] DEBUG[32337]: netsock2.c:188 ast_sockaddr_split_hostport: ...host '192.168.0.14' and port ''. [May 4 15:41:41] DEBUG[32337]: chan_sip.c:9083 process_sdp: Processing session-level SDP c=IN IP4 192.168.0.14... OK. [May 4 15:41:41] DEBUG[32337]: chan_sip.c:9083 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED. Got T.38 offer in SDP in dialog 367762855-5061-21@BJC.BGI.A.BE [May 4 15:41:41] DEBUG[32337]: chan_sip.c:9986 process_sdp_a_image: FaxVersion: 0 [May 4 15:41:41] DEBUG[32337]: chan_sip.c:9318 process_sdp: Processing media-level (image) SDP a=T38FaxVersion:0... OK. [May 4 15:41:41] DEBUG[32337]: chan_sip.c:9963 process_sdp_a_image: T38MaxBitRate: 14400 [May 4 15:41:41] DEBUG[32337]: chan_sip.c:9318 process_sdp: Processing media-level (image) SDP a=T38MaxBitRate:14400... OK. [May 4 15:41:41] DEBUG[32337]: chan_sip.c:10032 process_sdp_a_image: RateManagement: transferredTCF [May 4 15:41:41] DEBUG[32337]: chan_sip.c:9318 process_sdp: Processing media-level (image) SDP a=T38FaxRateManagement:transferredTCF... OK. [May 4 15:41:41] DEBUG[32337]: chan_sip.c:9960 process_sdp_a_image: MaxBufferSize:400 [May 4 15:41:41] DEBUG[32337]: chan_sip.c:9318 process_sdp: Processing media-level (image) SDP a=T38FaxMaxBuffer:400... OK. [May 4 15:41:41] DEBUG[32337]: chan_sip.c:9995 process_sdp_a_image: FaxMaxDatagram: 1400 [May 4 15:41:41] DEBUG[32337]: chan_sip.c:9318 process_sdp: Processing media-level (image) SDP a=T38FaxMaxDatagram:1400... OK. [May 4 15:41:41] DEBUG[32337]: chan_sip.c:10039 process_sdp_a_image: UDP EC: t38UDPRedundancy [May 4 15:41:41] DEBUG[32337]: chan_sip.c:9318 process_sdp: Processing media-level (image) SDP a=T38FaxUdpEC:t38UDPRedundancy... OK. Capabilities: us - (alaw|g722), peer - audio=(nothing)/video=(nothing)/text=(nothing), combined - (nothing) Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x0 (nothing), combined - 0x0 (nothing) Got T.38 Re-invite without audio. Keeping RTP active during T.38 session. [May 4 15:41:41] DEBUG[32337]: chan_sip.c:9525 process_sdp: Peer T.38 UDPTL is at port 192.168.0.14:5004 [May 4 15:41:41] DEBUG[32337]: chan_sip.c:5153 change_t38_state: T38 state changed to 3 on channel SIP/700001BOUL1-00000001 [May 4 15:41:41] DEBUG[32337]: chan_sip.c:9570 process_sdp: Have T.38 but no audio, accepting offer anyway [May 4 15:41:41] DEBUG[32337]: chan_sip.c:5945 update_call_counter: Updating call counter for incoming call set_destination: Parsing for address/port to send to [May 4 15:41:41] DEBUG[32337]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting '1.1.1.1:5070' into... [May 4 15:41:41] DEBUG[32337]: netsock2.c:188 ast_sockaddr_split_hostport: ...host '1.1.1.1' and port '5070'. set_destination: set destination to 1.1.1.1:5070 Transmitting (NAT) to 1.1.1.1:5070: ACK sip:700001BOUL1@2.2.2.2:2058;transport=tls SIP/2.0 Via: SIP/2.0/UDP 1.1.1.1:5060;branch=z9hG4bK3f7d4c53;rport Route: , Max-Forwards: 70 From: ;tag=as74ae86f0 To: "grandstream" ;tag=646086968 Contact: Call-ID: 367762855-5061-21@BJC.BGI.A.BE CSeq: 102 ACK User-Agent: vmybox Content-Length: 0 --- [May 4 15:41:41] DEBUG[32337]: chan_sip.c:3366 __sip_xmit: Trying to put 'ACK sip:700' onto UDP socket destined for 1.1.1.1:5070 [May 4 15:41:41] DEBUG[32702]: res_fax.c:1659 receivefax_t38_init: Negotiated T.38 for receive on SIP/700001BOUL1-00000001 [May 4 15:41:41] DEBUG[32702]: res_fax.c:1029 fax_session_new: Requesting a new FAX session from 'Spandsp FAX Driver'. [May 4 15:41:41] DEBUG[32702]: res_fax.c:1055 fax_session_new: channel 'SIP/700001BOUL1-00000001' using FAX session '1' [May 4 15:41:41] DEBUG[32702]: res_fax.c:1379 generic_fax_exec: channel SIP/700001BOUL1-00000001 will wait on FAX fd 20 [May 4 15:41:41] DEBUG[32702]: udptl.c:696 ast_udptl_read: UDPTL (SIP/700001BOUL1-00000001): NAT, Using address 2.2.2.2:5004 [May 4 15:41:41] DEBUG[32702]: res_fax_spandsp.c:364 t30_phase_e_handler: FAX session '1' entering phase E [May 4 15:41:41] DEBUG[32702]: res_fax_spandsp.c:381 t30_phase_e_handler: FAX session '1' completed with result: FAILED (The call dropped prematurely) [May 4 15:41:42] DEBUG[32702]: res_fax_spandsp.c:619 spandsp_fax_read: FAX session '1' is complete. [May 4 15:41:42] DEBUG[32702]: res_fax.c:1515 generic_fax_exec: channel 'SIP/700001BOUL1-00000001' - event loop stopped { timeout: 10000, ms: 981, res: 0 } [May 4 15:41:42] DEBUG[32702]: res_fax.c:1235 disable_t38: Shutting down T.38 on SIP/700001BOUL1-00000001 set_destination: Parsing for address/port to send to [May 4 15:41:42] DEBUG[32702]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting '1.1.1.1:5070' into... [May 4 15:41:42] DEBUG[32702]: netsock2.c:188 ast_sockaddr_split_hostport: ...host '1.1.1.1' and port '5070'. set_destination: set destination to 1.1.1.1:5070 [May 4 15:41:42] DEBUG[32702]: chan_sip.c:11702 add_sdp: ** Our capability: (alaw) Video flag: True Text flag: True [May 4 15:41:42] DEBUG[32702]: chan_sip.c:11703 add_sdp: ** Our prefcodec: (nothing) Audio is at 18510 Adding codec 100004 (alaw) to SDP Adding non-codec 0x1 (telephone-event) to SDP [May 4 15:41:42] DEBUG[32702]: chan_sip.c:11822 add_sdp: -- Done with adding codecs to SDP [May 4 15:41:42] DEBUG[32702]: chan_sip.c:12017 add_sdp: Done building SDP. Settling with this capability: (alaw) [May 4 15:41:42] DEBUG[32702]: chan_sip.c:3093 initialize_initreq: Initializing already initialized SIP dialog 367762855-5061-21@BJC.BGI.A.BE (presumably reinvite) [May 4 15:41:42] DEBUG[32702]: chan_sip.c:8679 parse_request: Header 0 [ 63]: INVITE sip:700001BOUL1@2.2.2.2:2058;transport=tls SIP/2.0 [May 4 15:41:42] DEBUG[32702]: chan_sip.c:8679 parse_request: Header 1 [ 64]: Via: SIP/2.0/UDP 1.1.1.1:5060;branch=z9hG4bK113c5b34;rport [May 4 15:41:42] DEBUG[32702]: chan_sip.c:8679 parse_request: Header 2 [124]: Route: , [May 4 15:41:42] DEBUG[32702]: chan_sip.c:8679 parse_request: Header 3 [ 16]: Max-Forwards: 70 [May 4 15:41:42] DEBUG[32702]: chan_sip.c:8679 parse_request: Header 4 [ 50]: From: ;tag=as74ae86f0 [May 4 15:41:42] DEBUG[32702]: chan_sip.c:8679 parse_request: Header 5 [ 69]: To: "grandstream" ;tag=646086968 [May 4 15:41:42] DEBUG[32702]: chan_sip.c:8679 parse_request: Header 6 [ 37]: Contact: [May 4 15:41:42] DEBUG[32702]: chan_sip.c:8679 parse_request: Header 7 [ 39]: Call-ID: 367762855-5061-21@BJC.BGI.A.BE [May 4 15:41:42] DEBUG[32702]: chan_sip.c:8679 parse_request: Header 8 [ 16]: CSeq: 103 INVITE [May 4 15:41:42] DEBUG[32702]: chan_sip.c:8679 parse_request: Header 9 [ 18]: User-Agent: vmybox [May 4 15:41:42] DEBUG[32702]: chan_sip.c:8679 parse_request: Header 10 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH [May 4 15:41:42] DEBUG[32702]: chan_sip.c:8679 parse_request: Header 11 [ 19]: Supported: replaces [May 4 15:41:42] DEBUG[32702]: chan_sip.c:8679 parse_request: Header 12 [ 52]: X-asterisk-Info: SIP re-invite (External RTP bridge) [May 4 15:41:42] DEBUG[32702]: chan_sip.c:8679 parse_request: Header 13 [ 29]: Content-Type: application/sdp Reliably Transmitting (NAT) to 1.1.1.1:5070: INVITE sip:700001BOUL1@2.2.2.2:2058;transport=tls SIP/2.0 Via: SIP/2.0/UDP 1.1.1.1:5060;branch=z9hG4bK113c5b34;rport Route: , Max-Forwards: 70 From: ;tag=as74ae86f0 To: "grandstream" ;tag=646086968 Contact: Call-ID: 367762855-5061-21@BJC.BGI.A.BE CSeq: 103 INVITE User-Agent: vmybox Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces X-asterisk-Info: SIP re-invite (External RTP bridge) Content-Type: application/sdp Content-Length: 222 v=0 o=root 862509026 862509028 IN IP4 1.1.1.1 s=vmybox c=IN IP4 1.1.1.1 t=0 0 m=audio 18510 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv --- [May 4 15:41:42] DEBUG[32702]: chan_sip.c:3823 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #23 [May 4 15:41:42] DEBUG[32702]: chan_sip.c:3366 __sip_xmit: Trying to put 'INVITE sip:' onto UDP socket destined for 1.1.1.1:5070 <--- SIP read from UDP:1.1.1.1:5070 ---> SIP/2.0 100 trying -- your call is important to us Via: SIP/2.0/UDP 1.1.1.1:5060;branch=z9hG4bK113c5b34;rport=5060 From: ;tag=as74ae86f0 To: "grandstream" ;tag=646086968 Call-ID: 367762855-5061-21@BJC.BGI.A.BE CSeq: 103 INVITE Server: vmybox Proxy Content-Length: 0 <-------------> [May 4 15:41:42] DEBUG[32337]: chan_sip.c:8679 parse_request: Header 0 [ 50]: SIP/2.0 100 trying -- your call is important to us [May 4 15:41:42] DEBUG[32337]: chan_sip.c:8679 parse_request: Header 1 [ 69]: Via: SIP/2.0/UDP 1.1.1.1:5060;branch=z9hG4bK113c5b34;rport=5060 [May 4 15:41:42] DEBUG[32337]: chan_sip.c:8679 parse_request: Header 2 [ 50]: From: ;tag=as74ae86f0 [May 4 15:41:42] DEBUG[32337]: chan_sip.c:8679 parse_request: Header 3 [ 69]: To: "grandstream" ;tag=646086968 [May 4 15:41:42] DEBUG[32337]: chan_sip.c:8679 parse_request: Header 4 [ 39]: Call-ID: 367762855-5061-21@BJC.BGI.A.BE [May 4 15:41:42] DEBUG[32337]: chan_sip.c:8679 parse_request: Header 5 [ 16]: CSeq: 103 INVITE [May 4 15:41:42] DEBUG[32337]: chan_sip.c:8679 parse_request: Header 6 [ 20]: Server: vmybox Proxy [May 4 15:41:42] DEBUG[32337]: chan_sip.c:8679 parse_request: Header 7 [ 17]: Content-Length: 0 [May 4 15:41:42] DEBUG[32337]: chan_sip.c:8679 parse_request: Header 8 [ 0]: --- (8 headers 0 lines) --- [May 4 15:41:42] DEBUG[32337]: chan_sip.c:4085 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #23 - INVITE (got response) [May 4 15:41:42] DEBUG[32337]: chan_sip.c:4092 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '367762855-5061-21@BJC.BGI.A.BE' Request 103: Found [May 4 15:41:42] DEBUG[32337]: chan_sip.c:20558 handle_response_invite: SIP response 100 to RE-invite on outgoing call 367762855-5061-21@BJC.BGI.A.BE <--- SIP read from UDP:1.1.1.1:5070 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 1.1.1.1:5060;branch=z9hG4bK113c5b34;rport=5060 From: ;tag=as74ae86f0 To: "grandstream" ;tag=646086968 Call-ID: 367762855-5061-21@BJC.BGI.A.BE CSeq: 103 INVITE Contact: Supported: replaces, path, timer, eventlist User-Agent: Grandstream HT-502 V1.1C 1.0.5.10 Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE Content-Type: application/sdp Content-Length: 227 v=0 o=700001BOUL1 8000 8002 IN IP4 192.168.0.14 s=SIP Call c=IN IP4 192.168.0.14 t=0 0 m=audio 5004 RTP/AVP 8 101 a=sendrecv a=rtpmap:8 PCMA/8000 a=ptime:20 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16,32-36,54 <-------------> [May 4 15:41:42] DEBUG[32337]: chan_sip.c:8679 parse_request: Header 0 [ 14]: SIP/2.0 200 OK [May 4 15:41:42] DEBUG[32337]: chan_sip.c:8679 parse_request: Header 1 [ 69]: Via: SIP/2.0/UDP 1.1.1.1:5060;branch=z9hG4bK113c5b34;rport=5060 [May 4 15:41:42] DEBUG[32337]: chan_sip.c:8679 parse_request: Header 2 [ 50]: From: ;tag=as74ae86f0 [May 4 15:41:42] DEBUG[32337]: chan_sip.c:8679 parse_request: Header 3 [ 69]: To: "grandstream" ;tag=646086968 [May 4 15:41:42] DEBUG[32337]: chan_sip.c:8679 parse_request: Header 4 [ 39]: Call-ID: 367762855-5061-21@BJC.BGI.A.BE [May 4 15:41:42] DEBUG[32337]: chan_sip.c:8679 parse_request: Header 5 [ 16]: CSeq: 103 INVITE [May 4 15:41:42] DEBUG[32337]: chan_sip.c:8679 parse_request: Header 6 [ 59]: Contact: [May 4 15:41:42] DEBUG[32337]: chan_sip.c:8679 parse_request: Header 7 [ 43]: Supported: replaces, path, timer, eventlist [May 4 15:41:42] DEBUG[32337]: chan_sip.c:8679 parse_request: Header 8 [ 46]: User-Agent: Grandstream HT-502 V1.1C 1.0.5.10 [May 4 15:41:42] DEBUG[32337]: chan_sip.c:8679 parse_request: Header 9 [ 80]: Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE [May 4 15:41:42] DEBUG[32337]: chan_sip.c:8679 parse_request: Header 10 [ 29]: Content-Type: application/sdp [May 4 15:41:42] DEBUG[32337]: chan_sip.c:8679 parse_request: Header 11 [ 21]: Content-Length: 227 [May 4 15:41:42] DEBUG[32337]: chan_sip.c:8679 parse_request: Header 12 [ 0]: [May 4 15:41:42] DEBUG[32337]: chan_sip.c:8679 parse_request: Body 0 [ 3]: v=0 [May 4 15:41:42] DEBUG[32337]: chan_sip.c:8679 parse_request: Body 1 [ 43]: o=700001BOUL1 8000 8002 IN IP4 192.168.0.14 [May 4 15:41:42] DEBUG[32337]: chan_sip.c:8679 parse_request: Body 2 [ 10]: s=SIP Call [May 4 15:41:42] DEBUG[32337]: chan_sip.c:8679 parse_request: Body 3 [ 21]: c=IN IP4 192.168.0.14 [May 4 15:41:42] DEBUG[32337]: chan_sip.c:8679 parse_request: Body 4 [ 5]: t=0 0 [May 4 15:41:42] DEBUG[32337]: chan_sip.c:8679 parse_request: Body 5 [ 26]: m=audio 5004 RTP/AVP 8 101 [May 4 15:41:42] DEBUG[32337]: chan_sip.c:8679 parse_request: Body 6 [ 10]: a=sendrecv [May 4 15:41:42] DEBUG[32337]: chan_sip.c:8679 parse_request: Body 7 [ 20]: a=rtpmap:8 PCMA/8000 [May 4 15:41:42] DEBUG[32337]: chan_sip.c:8679 parse_request: Body 8 [ 10]: a=ptime:20 [May 4 15:41:42] DEBUG[32337]: chan_sip.c:8679 parse_request: Body 9 [ 33]: a=rtpmap:101 telephone-event/8000 [May 4 15:41:42] DEBUG[32337]: chan_sip.c:8679 parse_request: Body 10 [ 24]: a=fmtp:101 0-16,32-36,54 --- (12 headers 11 lines) --- [May 4 15:41:42] DEBUG[32337]: chan_sip.c:4013 __sip_ack: Acked pending invite 103 [May 4 15:41:42] DEBUG[32337]: chan_sip.c:4051 __sip_ack: Stopping retransmission on '367762855-5061-21@BJC.BGI.A.BE' of Request 103: Match Found [May 4 15:41:42] DEBUG[32337]: chan_sip.c:20558 handle_response_invite: SIP response 200 to RE-invite on outgoing call 367762855-5061-21@BJC.BGI.A.BE [May 4 15:41:42] DEBUG[32337]: chan_sip.c:9083 process_sdp: Processing session-level SDP v=0... UNSUPPORTED. [May 4 15:41:42] DEBUG[32337]: chan_sip.c:9083 process_sdp: Processing session-level SDP o=700001BOUL1 8000 8002 IN IP4 192.168.0.14... UNSUPPORTED. [May 4 15:41:42] DEBUG[32337]: chan_sip.c:9083 process_sdp: Processing session-level SDP s=SIP Call... UNSUPPORTED. [May 4 15:41:42] DEBUG[32337]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting '192.168.0.14' into... [May 4 15:41:42] DEBUG[32337]: netsock2.c:188 ast_sockaddr_split_hostport: ...host '192.168.0.14' and port ''. [May 4 15:41:42] DEBUG[32337]: chan_sip.c:9083 process_sdp: Processing session-level SDP c=IN IP4 192.168.0.14... OK. [May 4 15:41:42] DEBUG[32337]: chan_sip.c:9083 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED. Found RTP audio format 8 [May 4 15:41:42] DEBUG[32337]: rtp_engine.c:473 ast_rtp_codecs_payloads_set_m_type: Setting payload 8 based on m type on 0x2aef987a7d30 Found RTP audio format 101 [May 4 15:41:42] DEBUG[32337]: rtp_engine.c:473 ast_rtp_codecs_payloads_set_m_type: Setting payload 101 based on m type on 0x2aef987a7d30 [May 4 15:41:42] DEBUG[32337]: chan_sip.c:9318 process_sdp: Processing media-level (audio) SDP a=sendrecv... OK. Found audio description format PCMA for ID 8 [May 4 15:41:42] DEBUG[32337]: chan_sip.c:9318 process_sdp: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK. [May 4 15:41:42] DEBUG[32337]: chan_sip.c:9318 process_sdp: Processing media-level (audio) SDP a=ptime:20... OK. Found audio description format telephone-event for ID 101 [May 4 15:41:42] DEBUG[32337]: chan_sip.c:9318 process_sdp: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [May 4 15:41:42] DEBUG[32337]: chan_sip.c:9318 process_sdp: Processing media-level (audio) SDP a=fmtp:101 0-16,32-36,54... UNSUPPORTED. [May 4 15:41:42] DEBUG[32337]: chan_sip.c:5153 change_t38_state: T38 state changed to 0 on channel SIP/700001BOUL1-00000001 [May 4 15:41:42] DEBUG[32337]: rtp_engine.c:594 ast_rtp_codecs_payload_formats: Incorporating payload 8 on 0x2aef987a7d30 [May 4 15:41:42] DEBUG[32337]: rtp_engine.c:594 ast_rtp_codecs_payload_formats: Incorporating payload 101 on 0x2aef987a7d30 apabilities: us - (alaw|g722), peer - audio=(alaw)/video=(nothing)/text=(nothing), combined - (alaw) Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|) Peer audio RTP is at port 192.168.0.14:5004 [May 4 15:41:42] DEBUG[32337]: rtp_engine.c:449 ast_rtp_codecs_payloads_copy: Copying payload 8 from 0x2aef987a7d30 to 0x6290220 [May 4 15:41:42] DEBUG[32337]: rtp_engine.c:449 ast_rtp_codecs_payloads_copy: Copying payload 101 from 0x2aef987a7d30 to 0x6290220 [May 4 15:41:42] DEBUG[32337]: res_rtp_asterisk.c:2522 ast_rtp_prop_set: Setup RTCP on RTP instance '0x6290058' [May 4 15:41:42] DEBUG[32337]: chan_sip.c:9565 process_sdp: Peer doesn't provide T.38 UDPTL [May 4 15:41:42] DEBUG[32337]: chan_sip.c:9576 process_sdp: We're settling with these formats: (alaw) [May 4 15:41:42] DEBUG[32337]: chan_sip.c:9583 process_sdp: We have an owner, now see if we need to change this call [May 4 15:41:42] DEBUG[32337]: chan_sip.c:9589 process_sdp: Setting native formats after processing SDP. peer joint formats (alaw), old nativeformats (alaw) [May 4 15:41:42] DEBUG[32337]: chan_sip.c:5945 update_call_counter: Updating call counter for incoming call set_destination: Parsing for address/port to send to [May 4 15:41:42] DEBUG[32337]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting '1.1.1.1:5070' into... [May 4 15:41:42] DEBUG[32337]: netsock2.c:188 ast_sockaddr_split_hostport: ...host '1.1.1.1' and port '5070'. set_destination: set destination to 1.1.1.1:5070 Transmitting (NAT) to 1.1.1.1:5070: ACK sip:700001BOUL1@2.2.2.2:2058;transport=tls SIP/2.0 Via: SIP/2.0/UDP 1.1.1.1:5060;branch=z9hG4bK311f3c09;rport Route: , Max-Forwards: 70 From: ;tag=as74ae86f0 To: "grandstream" ;tag=646086968 Contact: Call-ID: 367762855-5061-21@BJC.BGI.A.BE CSeq: 103 ACK User-Agent: vmybox Content-Length: 0 --- [May 4 15:41:42] DEBUG[32337]: chan_sip.c:3366 __sip_xmit: Trying to put 'ACK sip:700' onto UDP socket destined for 1.1.1.1:5070 [May 4 15:41:42] DEBUG[32702]: res_fax.c:1266 disable_t38: Shut down T.38 on SIP/700001BOUL1-00000001 [May 4 15:41:42] DEBUG[32702]: pbx.c:3380 ast_str_retrieve_variable: Result of 'CONTEXT' is 'faxserver' [May 4 15:41:42] DEBUG[32702]: pbx.c:3380 ast_str_retrieve_variable: Result of 'EXTEN' is 's' [May 4 15:41:42] DEBUG[32702]: pbx.c:4199 pbx_substitute_variables_helper_full: Function result is '116' [May 4 15:41:42] DEBUG[32702]: pbx.c:4371 pbx_extension_helper: Launching 'Hangup' -- Executing [s@faxserver:10] Hangup("SIP/700001BOUL1-00000001", "") in new stack [May 4 15:41:42] DEBUG[32702]: pbx.c:5206 __ast_pbx_run: Spawn extension (faxserver,s,10) exited non-zero on 'SIP/700001BOUL1-00000001' == Spawn extension (faxserver, s, 10) exited non-zero on 'SIP/700001BOUL1-00000001' [May 4 15:41:42] DEBUG[32702]: channel.c:2711 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/700001BOUL1-00000001' May 4 15:41:42] DEBUG[32702]: pbx.c:3380 ast_str_retrieve_variable: Result of 'FAXSTATUS' is 'FAILED' [May 4 15:41:42] DEBUG[32702]: pbx.c:4371 pbx_extension_helper: Launching 'NoOp' -- Executing [h@faxserver:1] NoOp("SIP/700001BOUL1-00000001", "### FAXSTATUS: FAILED") in new stack [May 4 15:41:42] DEBUG[32702]: pbx.c:3380 ast_str_retrieve_variable: Result of 'FAXERROR' is 'The call dropped prematurely' [May 4 15:41:42] DEBUG[32702]: pbx.c:4267 pbx_substitute_variables_helper_full: Expression result is '0' [May 4 15:41:42] DEBUG[32702]: pbx.c:3380 ast_str_retrieve_variable: Result of 'FAXERROR' is 'The call dropped prematurely' [May 4 15:41:42] DEBUG[32702]: pbx.c:4199 pbx_substitute_variables_helper_full: Function result is 'The call dropped prematurely' [May 4 15:41:42] DEBUG[32702]: pbx.c:4371 pbx_extension_helper: Launching 'NoOp' -- Executing [h@faxserver:2] NoOp("SIP/700001BOUL1-00000001", "### FAXERROR: The call dropped prematurely") in new stack [May 4 15:41:42] DEBUG[32702]: pbx.c:3380 ast_str_retrieve_variable: Result of 'FAXPAGES' is '0' [May 4 15:41:42] DEBUG[32702]: pbx.c:4267 pbx_substitute_variables_helper_full: Expression result is '0' [May 4 15:41:42] DEBUG[32702]: pbx.c:3380 ast_str_retrieve_variable: Result of 'FAXPAGES' is '0' [May 4 15:41:42] DEBUG[32702]: pbx.c:4199 pbx_substitute_variables_helper_full: Function result is '0' [May 4 15:41:42] DEBUG[32702]: pbx.c:4371 pbx_extension_helper: Launching 'NoOp' -- Executing [h@faxserver:3] NoOp("SIP/700001BOUL1-00000001", "### FAXPAGES: 0") in new stack [May 4 15:41:42] DEBUG[32702]: pbx.c:3380 ast_str_retrieve_variable: Result of 'FAXBITRATE' is '14400' [May 4 15:41:42] DEBUG[32702]: pbx.c:4371 pbx_extension_helper: Launching 'NoOp' -- Executing [h@faxserver:4] NoOp("SIP/700001BOUL1-00000001", "### FAXBITRATE: 14400") in new stack [May 4 15:41:42] DEBUG[32702]: pbx.c:3380 ast_str_retrieve_variable: Result of 'FAXRESOLUTION' is '0x0' [May 4 15:41:42] DEBUG[32702]: pbx.c:4371 pbx_extension_helper: Launching 'NoOp' -- Executing [h@faxserver:5] NoOp("SIP/700001BOUL1-00000001", "### FAXRESOLUTION: 0x0") in new stack [May 4 15:41:42] DEBUG[32702]: pbx.c:3377 ast_str_retrieve_variable: Result of 'REMOTESTATIONID' is NULL [May 4 15:41:42] DEBUG[32702]: pbx.c:4371 pbx_extension_helper: Launching 'NoOp' -- Executing [h@faxserver:6] NoOp("SIP/700001BOUL1-00000001", "### REMOTESTATIONID: ") in new stack [May 4 15:41:42] DEBUG[32702]: pbx.c:3377 ast_str_retrieve_variable: Result of 'REMOTESTATIONID' is NULL [May 4 15:41:42] DEBUG[32702]: pbx.c:4267 pbx_substitute_variables_helper_full: Expression result is '0' [May 4 15:41:42] DEBUG[32702]: pbx.c:3377 ast_str_retrieve_variable: Result of 'REMOTESTATIONID' is NULL