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

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...

-- 
Joshua Colp
Digium, Inc. | Senior Software Developer
445 Jan Davis Drive NW - Huntsville, AL 35806 - US
Check us out at: www.digium.com & www.asterisk.org

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

On Sun, Jun 11, 2017, at 08:16 AM, Michael Maier wrote:

<snip>
 
> 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!
What was the local problem?
 
> 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):
<snip>
> 
> 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?
PJSIP uses a dispatch model. The request is queued up, acted on, and
then that's it. The act of acting on it removes it from the queue. The
only reason I'd expect to see it again is if there was a retransmission
or something somehow requeued it up - but I don't think we do that
anywhere. Not quite sure why it would be happening...

-- 
Joshua Colp
Digium, Inc. | Senior Software Developer
445 Jan Davis Drive NW - Huntsville, AL 35806 - US
Check us out at: www.digium.com & www.asterisk.org

On Sun, Jun 11, 2017 at 01:16:10PM +0200, Michael Maier
wrote:
> 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):
I'm running Asterisk 11 on my faxserver so not using pjsip but chan_sip.
But IIRC I had problems with asterisk-11/t38modem-2.0.0/hylafax if the
upstream side started the t38 reINVITE on sending a fax. My hylafax
config.ttyT38* contains the AT F command to initiale t38 on the t38modem
side for outgoing calls. For incoming t38modem also starts the reINVITE
but there is no parameter to influence this in my configs.

No idea if this is in anyway related nor what the default is of the
options below and neither if it depends on the t38modem version.

# T.38 dial modifiers
#
# F - enable T.38 mode request after dialing
# V - disable T.38 mode request after dialing (remote host should do it)
#
# calling/called number dial modifiers
#
# L - reset and begin of calling number
# D - continue of called number
#
ModemDialCmd:           ATDF%s          # user can override F by dial V
#ModemDialCmd:          ATDV%s          # user can override V by dial F
#ModemDialCmd:          ATD%sF          # user can't override F
#ModemDialCmd:          ATD%sV          # user can't override V
#ModemDialCmd:          ATD%sVL         # user can't override V or calling
number