On 06/05/2017 at 09:32 PM Joshua Colp wrote: > On Mon, Jun 5, 2017, at 04:26 PM, Michael Maier wrote: >> On 06/05/2017 at 06:29 PM, Joshua Colp wrote: >>> On Mon, Jun 5, 2017, at 01:22 PM, Michael Maier wrote: >>>> >>>> Do you have any idea where to start to look at? Adding additional output >>>> in the source code? Which functions could be interesting? I may add own >>>> debug code to see why things are happening as they happen here. >>> >>> The logic for T.38 negotiation lives all in the res_pjsip_t38 module and >>> the request to negotiate works using a control frame which is handled by >>> the t38_interpret_parameters function. It's up to that to initialize >>> things and then request that a session refresh occurs (which sends the >>> re-invite). That'd be the place to look. >> >> I added a debug output at the beginning of the function to see if it's >> ever >> been called. >> >> t38_interpret_parameters is never been called ... . > > That would likely mean that the frame is not getting sent (this also > happens in that module) or that it is getting lost in the bridging > framework. Digging into that is not something that can be expressed in > general terms in email...
I did some further investigations and fixed a local problem. Now, asterisk is able to successfully activate T.38 - unfortunately just for very shot time because of a phantom package it receives! Let's go into details: I'm starting at the point where asterisk / fax client receives the T.38 reininvite from the server from the provider 195.185.37.60:5060 for the fax client (extension 91): <--- Received SIP request (918 bytes) from UDP:195.185.37.60:5060 ---> INVITE sip:[email protected]:5061 SIP/2.0 Via: SIP/2.0/UDP 195.185.37.60;branch=z9hG4bKd8EHOaij;rport From: <sip:[email protected]>;tag=124E09F9-593D01CC00045378-134F4700 To: <sip:[email protected]>;tag=dd67e8fd-cd74-40e2-bf58-dc99b182aec9 CSeq: 10 INVITE Call-ID: c34cc459-96f3-47a6-8279-d46cddf9abb7 Max-Forwards: 68 Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, REFER, MESSAGE Supported: 100rel, timer, replaces, norefersub Content-Type: application/sdp Content-Length: 265 Contact: <sip:[email protected];transport=udp> v=0 o=- 2068461195 2068461199 IN IP4 195.185.37.60 s=- c=IN IP4 195.185.37.60 t=0 0 m=image 24842 UDPTL t38 a=sendrecv a=T38FaxVersion:0 a=T38MaxBitRate:14400 a=T38FaxRateManagement:transferredTCF a=T38FaxMaxDatagram:1393 a=T38FaxUdpEC:t38UDPRedundancy [2017-06-11 10:39:42] DEBUG[24434]: res_pjsip/pjsip_distributor.c:379 distributor: Searching for serializer on dialog dlg0x7fdde801e258 for Request msg INVITE/cseq=10 (rdata0x7fddb4012488) [2017-06-11 10:39:42] DEBUG[24434]: res_pjsip/pjsip_distributor.c:385 distributor: Found serializer pjsip/outsess/easybellPJSIP-00000076 on dialog dlg0x7fdde801e258 [2017-06-11 10:39:42] DEBUG[25822]: res_pjsip_t38.c:268 t38_initialize_session: UDPTL initialized on session for PJSIP/easybellPJSIP-00000005 [2017-06-11 10:39:42] DEBUG[25822]: res_pjsip_t38.c:138 t38_change_state: T.38 state changed to '2' from '0' on channel 'PJSIP/easybellPJSIP-00000005' [2017-06-11 10:39:42] DEBUG[25822]: res_pjsip_t38.c:696 defer_incoming_sdp_stream: Deferring incoming SDP stream on PJSIP/easybellPJSIP-00000005 for peer re-invite [2017-06-11 10:39:42] DEBUG[25987][C-00000002]: bridge_native_rtp.c:348 native_rtp_bridge_compatible_check: Bridge 'a10ac2c1-5045-4a7d-ada4-6a6e54671b9d' can not use native RTP bridge as it was forbidden while getting details [2017-06-11 10:39:42] DEBUG[25987][C-00000002]: bridge.c:506 find_best_technology: Bridge technology native_rtp is not compatible with properties of existing bridge. [2017-06-11 10:39:42] DEBUG[25987][C-00000002]: bridge.c:496 find_best_technology: Bridge technology softmix does not have any capabilities we want. [2017-06-11 10:39:42] DEBUG[25987][C-00000002]: bridge.c:496 find_best_technology: Bridge technology holding_bridge does not have any capabilities we want. [2017-06-11 10:39:42] DEBUG[25987][C-00000002]: bridge.c:515 find_best_technology: Chose bridge technology simple_bridge [2017-06-11 10:39:42] DEBUG[25987][C-00000002]: bridge.c:1046 smart_bridge_operation: Bridge a10ac2c1-5045-4a7d-ada4-6a6e54671b9d is already using the new technology. [2017-06-11 10:39:42] DEBUG[25822]: res_pjsip_t38.c:268 t38_initialize_session: UDPTL initialized on session for PJSIP/91-00000004 [2017-06-11 10:39:42] DEBUG[25822]: res_pjsip_t38.c:138 t38_change_state: T.38 state changed to '1' from '0' on channel 'PJSIP/91-00000004' [2017-06-11 10:39:42] DEBUG[25822]: res_rtp_asterisk.c:5342 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0x7fddc8011b10' [2017-06-11 10:39:42] DEBUG[25822]: res_pjsip_session.c:971 ast_sip_session_refresh: Sending session refresh SDP via re-INVITE to 91 [2017-06-11 10:39:42] DEBUG[25822]: res_pjsip_session.c:2501 handle_outgoing_request: Method is INVITE [2017-06-11 10:39:42] DEBUG[25822]: res_pjsip/pjsip_message_ip_updater.c:257 multihomed_on_tx_message: Re-wrote Contact URI host/port to 127.0.0.1:5061 Asterisk hands over the reininvite to extension 91 (127.0.0.1:6060): <--- Transmitting SIP request (952 bytes) to UDP:127.0.0.1:6060 ---> INVITE sip:[email protected]:6060 SIP/2.0 Via: SIP/2.0/UDP 127.0.0.1:5061;rport;branch=z9hG4bKPje73c8edf-a356-4c9b-9b47-08c08415e3f6 From: "CID:+4971519828226" <sip:[email protected]>;tag=a8c70273-1c66-44ef-914e-1e397e262e69 To: "root" <sip:[email protected]>;tag=4625bb2c-ef4c-e711-93c5-000db9330d98 Contact: <sip:127.0.0.1:5061> Call-ID: 5a43bb2c-ef4c-e711-93c5-000db9330d98@myfw CSeq: 26127 INVITE Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, REFER, MESSAGE Supported: 100rel, timer, replaces, norefersub Session-Expires: 1800 Min-SE: 90 Max-Forwards: 70 User-Agent: FPBX-13.0.191.11(13.16.0) Content-Type: application/sdp Content-Length: 242 v=0 o=- 1497170378 5 IN IP4 127.0.0.1 s=Asterisk c=IN IP4 127.0.0.1 t=0 0 m=image 4564 udptl t38 a=T38FaxVersion:0 a=T38MaxBitRate:14400 a=T38FaxRateManagement:transferredTCF a=T38FaxMaxDatagram:1393 a=T38FaxUdpEC:t38UDPRedundancy [2017-06-11 10:39:42] DEBUG[25971][C-00000002]: bridge_native_rtp.c:348 native_rtp_bridge_compatible_check: Bridge 'a10ac2c1-5045-4a7d-ada4-6a6e54671b9d' can not use native RTP bridge as it was forbidden while getting details [2017-06-11 10:39:42] DEBUG[25971][C-00000002]: bridge.c:506 find_best_technology: Bridge technology native_rtp is not compatible with properties of existing bridge. [2017-06-11 10:39:42] DEBUG[25971][C-00000002]: bridge.c:496 find_best_technology: Bridge technology softmix does not have any capabilities we want. [2017-06-11 10:39:42] DEBUG[25971][C-00000002]: bridge.c:496 find_best_technology: Bridge technology holding_bridge does not have any capabilities we want. [2017-06-11 10:39:42] DEBUG[25971][C-00000002]: bridge.c:515 find_best_technology: Chose bridge technology simple_bridge [2017-06-11 10:39:42] DEBUG[25971][C-00000002]: bridge.c:1046 smart_bridge_operation: Bridge a10ac2c1-5045-4a7d-ada4-6a6e54671b9d is already using the new technology. <--- Received SIP response (399 bytes) from UDP:127.0.0.1:6060 ---> SIP/2.0 100 Trying CSeq: 26127 INVITE Via: SIP/2.0/UDP 127.0.0.1:5061;rport=5061;branch=z9hG4bKPje73c8edf-a356-4c9b-9b47-08c08415e3f6;received=127.0.0.1 From: "CID:+4971519828226" <sip:[email protected]>;tag=a8c70273-1c66-44ef-914e-1e397e262e69 Call-ID: 5a43bb2c-ef4c-e711-93c5-000db9330d98@myfw To: "root" <sip:[email protected]>;tag=4625bb2c-ef4c-e711-93c5-000db9330d98 Content-Length: 0 [2017-06-11 10:39:42] DEBUG[24434]: res_pjsip/pjsip_distributor.c:379 distributor: Searching for serializer on dialog dlg0x7fddb400b728 for Response msg 100/INVITE/cseq=26127 (rdata0x7fddb4012488) [2017-06-11 10:39:42] DEBUG[24434]: res_pjsip/pjsip_distributor.c:385 distributor: Found serializer pjsip/distributor-00000033 on dialog dlg0x7fddb400b728 [2017-06-11 10:39:42] DEBUG[25822]: res_pjsip_session.c:2485 handle_incoming: Received response [2017-06-11 10:39:42] DEBUG[25822]: res_pjsip_session.c:2469 handle_incoming_response: Response is 100 Trying Asterisk receives the ok from fax client / extension 91 / 127.0.0.1:6060: <--- Received SIP response (914 bytes) from UDP:127.0.0.1:6060 ---> SIP/2.0 200 OK CSeq: 26127 INVITE Via: SIP/2.0/UDP 127.0.0.1:5061;rport=5061;branch=z9hG4bKPje73c8edf-a356-4c9b-9b47-08c08415e3f6;received=127.0.0.1 User-Agent: T38Modem/3.15.2 From: "CID:+4971519828226" <sip:[email protected]>;tag=a8c70273-1c66-44ef-914e-1e397e262e69 Call-ID: 5a43bb2c-ef4c-e711-93c5-000db9330d98@myfw Organization: Frolov,Holtschneider,Davidson To: "root" <sip:[email protected]>;tag=4625bb2c-ef4c-e711-93c5-000db9330d98 Contact: "root" <sip:[email protected]:6060> Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,SUBSCRIBE,NOTIFY,REFER,MESSAGE,INFO,PING,PRACK Content-Length: 286 Content-Type: application/sdp v=0 o=- 1497170378 3 IN IP4 127.0.0.1 s=T38Modem/3.15.2 c=IN IP4 127.0.0.1 t=0 0 m=image 10000 udptl t38 a=sendrecv a=T38FaxVersion:0 a=T38FaxRateManagement:transferredTCF a=T38FaxMaxBuffer:2000 a=T38FaxMaxDatagram:1400 a=T38FaxUdpEC:t38UDPRedundancy a=T38MaxBitRate:14400 [2017-06-11 10:39:42] DEBUG[24434]: res_pjsip/pjsip_distributor.c:379 distributor: Searching for serializer on dialog dlg0x7fddb400b728 for Response msg 200/INVITE/cseq=26127 (rdata0x7fddb4012488) [2017-06-11 10:39:42] DEBUG[24434]: res_pjsip/pjsip_distributor.c:385 distributor: Found serializer pjsip/distributor-00000033 on dialog dlg0x7fddb400b728 [2017-06-11 10:39:42] DEBUG[25822]: res_pjsip_session.c:374 handle_negotiated_sdp_session_media: Stopping SDP media stream 'audio' as it is not currently negotiated [2017-06-11 10:39:42] DEBUG[25822]: res_pjsip_session.c:331 handle_negotiated_sdp_session_media: Applying negotiated SDP media stream 'image' using image SDP handler [2017-06-11 10:39:42] DEBUG[25822]: res_pjsip_session.c:337 handle_negotiated_sdp_session_media: Applied negotiated SDP media stream 'image' using image SDP handler and acks this ok to fax client / extension 91 / 127.0.0.1:6060: <--- Transmitting SIP request (445 bytes) to UDP:127.0.0.1:6060 ---> ACK sip:[email protected]:6060 SIP/2.0 Via: SIP/2.0/UDP 127.0.0.1:5061;rport;branch=z9hG4bKPj2fef6659-1456-4567-a39b-7f9feaf98864 From: "CID:+4971519828226" <sip:[email protected]>;tag=a8c70273-1c66-44ef-914e-1e397e262e69 To: "root" <sip:[email protected]>;tag=4625bb2c-ef4c-e711-93c5-000db9330d98 Call-ID: 5a43bb2c-ef4c-e711-93c5-000db9330d98@myfw CSeq: 26127 ACK Max-Forwards: 70 User-Agent: FPBX-13.0.191.11(13.16.0) Content-Length: 0 [2017-06-11 10:39:42] DEBUG[25822]: res_pjsip_session.c:2485 handle_incoming: Received response [2017-06-11 10:39:42] DEBUG[25822]: res_pjsip_session.c:2469 handle_incoming_response: Response is 200 OK [2017-06-11 10:39:42] DEBUG[25822]: res_pjsip_t38.c:138 t38_change_state: T.38 state changed to '3' from '1' on channel 'PJSIP/91-00000004' [2017-06-11 10:39:42] DEBUG[25971][C-00000002]: channel.c:3986 __ast_read: Dropping duplicate answer! [2017-06-11 10:39:42] DEBUG[25822]: res_pjsip_t38.c:138 t38_change_state: T.38 state changed to '3' from '2' on channel 'PJSIP/easybellPJSIP-00000005' [2017-06-11 10:39:42] DEBUG[25822]: res_pjsip_t38.c:142 t38_change_state: Automatic T.38 rejection on channel 'PJSIP/easybellPJSIP-00000005' terminated => Great! We're now successfully on T.38!!! But now, something strange happens: Asterisk "receives" a T.38 reinvite package from provider! Why is it strange? Because *this package doesn't exist at all* ! It can't be seen in tcpdump. I did 4 tests - always the same! Where does this package come from? It's exactly the same package which can be seen at the beginning of the trace excerpted here! Isn't it been deleted after it has been processed the first time? <--- Received SIP request (918 bytes) from UDP:195.185.37.60:5060 ---> INVITE sip:[email protected]:5061 SIP/2.0 Via: SIP/2.0/UDP 195.185.37.60;branch=z9hG4bKd8EHOaij;rport From: <sip:[email protected]>;tag=124E09F9-593D01CC00045378-134F4700 To: <sip:[email protected]>;tag=dd67e8fd-cd74-40e2-bf58-dc99b182aec9 CSeq: 10 INVITE Call-ID: c34cc459-96f3-47a6-8279-d46cddf9abb7 Max-Forwards: 68 Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, REFER, MESSAGE Supported: 100rel, timer, replaces, norefersub Content-Type: application/sdp Content-Length: 265 Contact: <sip:[email protected];transport=udp> v=0 o=- 2068461195 2068461199 IN IP4 195.185.37.60 s=- c=IN IP4 195.185.37.60 t=0 0 m=image 24842 UDPTL t38 a=sendrecv a=T38FaxVersion:0 a=T38MaxBitRate:14400 a=T38FaxRateManagement:transferredTCF a=T38FaxMaxDatagram:1393 a=T38FaxUdpEC:t38UDPRedundancy [2017-06-11 10:39:42] DEBUG[25822]: res_pjsip/pjsip_distributor.c:379 distributor: Searching for serializer on dialog dlg0x7fdde801e258 for Request msg INVITE/cseq=10 (rdata0x7fddc80def48) [2017-06-11 10:39:42] DEBUG[25822]: res_pjsip/pjsip_distributor.c:385 distributor: Found serializer pjsip/outsess/easybellPJSIP-00000076 on dialog dlg0x7fdde801e258 [2017-06-11 10:39:42] DEBUG[25822]: res_pjsip_session.c:242 handle_incoming_sdp: Negotiating incoming SDP media stream 'image' using image SDP handler [2017-06-11 10:39:42] DEBUG[25822]: res_pjsip_session.c:251 handle_incoming_sdp: Media stream 'image' handled by image [2017-06-11 10:39:42] DEBUG[25822]: res_rtp_asterisk.c:5342 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0x7fddc8006d90' [2017-06-11 10:39:42] DEBUG[25822]: res_pjsip_session.c:374 handle_negotiated_sdp_session_media: Stopping SDP media stream 'audio' as it is not currently negotiated [2017-06-11 10:39:42] DEBUG[25822]: res_pjsip_session.c:331 handle_negotiated_sdp_session_media: Applying negotiated SDP media stream 'image' using image SDP handler [2017-06-11 10:39:42] DEBUG[25822]: res_pjsip_session.c:337 handle_negotiated_sdp_session_media: Applied negotiated SDP media stream 'image' using image SDP handler [2017-06-11 10:39:42] DEBUG[25822]: res_pjsip/pjsip_message_ip_updater.c:257 multihomed_on_tx_message: Re-wrote Contact URI host/port to 42.21.35.43:5061 <--- Transmitting SIP response (750 bytes) to UDP:195.185.37.60:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 195.185.37.60;rport=5060;received=195.185.37.60;branch=z9hG4bKd8EHOaij Call-ID: c34cc459-96f3-47a6-8279-d46cddf9abb7 From: <sip:[email protected]>;tag=124E09F9-593D01CC00045378-134F4700 To: <sip:[email protected]>;tag=dd67e8fd-cd74-40e2-bf58-dc99b182aec9 CSeq: 10 INVITE Contact: <sip:[email protected]:5061> Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, REFER, MESSAGE Supported: 100rel, timer, replaces, norefersub Server: FPBX-13.0.191.11(13.16.0) Content-Type: application/sdp Content-Length: 117 v=0 o=- 2068461195 2068461196 IN IP4 42.21.35.43 s=Asterisk c=IN IP4 42.21.35.43 t=0 0 m=image 0 UDPTL t38 Asterisk acted on the phantom package and sends ok to provider containing deactivated T.38! Now things go down the hill ... Does anybody has any idea where this phantom package come from? Thanks, regards, Michael -- _____________________________________________________________________ -- Bandwidth and Colocation Provided by http://www.api-digital.com -- Check out the new Asterisk community forum at: https://community.asterisk.org/ New to Asterisk? Start here: https://wiki.asterisk.org/wiki/display/AST/Getting+Started asterisk-users mailing list To UNSUBSCRIBE or update options visit: http://lists.digium.com/mailman/listinfo/asterisk-users
