[asterisk-users] asterisk 13.16 / pjsip / t.38: res_pjsip_t38.c:207 t38_automatic_reject: Automatically rejecting T.38 request on channel 'PJSIP/91-00000007'

Sun Jun 11 06:16:10 CDT 2017

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:+4971511336089 at 42.21.35.43:5061 SIP/2.0
Via: SIP/2.0/UDP 195.185.37.60;branch=z9hG4bKd8EHOaij;rport
From: <sip:071511336089 at sip.easybell.de>;tag=124E09F9-593D01CC00045378-134F4700
To: <sip:+4971511336089 at sip.easybell.de>;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:38BD4B10-593D01CC0003604C-F1EE2700 at 195.185.37.60;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:91 at 127.0.0.1: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:071511336089 at 127.0.0.1>;tag=a8c70273-1c66-44ef-914e-1e397e262e69
To: "root" <sip:91 at 127.0.0.1>;tag=4625bb2c-ef4c-e711-93c5-000db9330d98
Contact: <sip:127.0.0.1:5061>
Call-ID: 5a43bb2c-ef4c-e711-93c5-000db9330d98 at 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:071511336089 at 127.0.0.1>;tag=a8c70273-1c66-44ef-914e-1e397e262e69
Call-ID: 5a43bb2c-ef4c-e711-93c5-000db9330d98 at myfw
To: "root" <sip:91 at 127.0.0.1>;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:071511336089 at 127.0.0.1>;tag=a8c70273-1c66-44ef-914e-1e397e262e69
Call-ID: 5a43bb2c-ef4c-e711-93c5-000db9330d98 at myfw
Organization: Frolov,Holtschneider,Davidson
To: "root" <sip:91 at 127.0.0.1>;tag=4625bb2c-ef4c-e711-93c5-000db9330d98
Contact: "root" <sip:91 at 127.0.0.1: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:91 at 127.0.0.1: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:071511336089 at 127.0.0.1>;tag=a8c70273-1c66-44ef-914e-1e397e262e69
To: "root" <sip:91 at 127.0.0.1>;tag=4625bb2c-ef4c-e711-93c5-000db9330d98
Call-ID: 5a43bb2c-ef4c-e711-93c5-000db9330d98 at 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:+4971511336089 at 42.21.35.43:5061 SIP/2.0
Via: SIP/2.0/UDP 195.185.37.60;branch=z9hG4bKd8EHOaij;rport
From: <sip:071511336089 at sip.easybell.de>;tag=124E09F9-593D01CC00045378-134F4700
To: <sip:+4971511336089 at sip.easybell.de>;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:38BD4B10-593D01CC0003604C-F1EE2700 at 195.185.37.60;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:071511336089 at sip.easybell.de>;tag=124E09F9-593D01CC00045378-134F4700
To: <sip:+4971511336089 at sip.easybell.de>;tag=dd67e8fd-cd74-40e2-bf58-dc99b182aec9
CSeq: 10 INVITE
Contact: <sip:+4971511336089 at 42.21.35.43: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