thr3ads.net - asterisk users - [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' [Jun 2017]

If this information is useful, please help other people find it:
Share via:

Michael Maier

2017-Jun-15 06:15 UTC

[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'

On 06/14/2017 at 10:17 PM, Joshua Colp wrote:> On Wed, Jun 14, 2017, at 05:09 PM, Michael Maier wrote:
> 
> <snip>
> 
>>
>> I can now say, that asterisk / pjsip seams to work *mostly* as
expected.
>> Just one exception - and that's the package in question, which
can't be
>> seen in tcpdump.
>>
>> I extended the above patch by adding the info at the last output:
>>
>> ast_debug(3, "PJ_TRUE 3 - ready %s\n",
pjsip_rx_data_get_info(rdata));
>>
>> This gives, that for *all* received packages return PJ_TRUE is reached.
>>
>> But: all packages besides of the phantom resend use the same address
>> rdata0x7f963c0009b8 - only the phantom resent package uses
>> rdata0x7f9654081e18. I think, that's the problem. But I don't
know what
>> it means and where it comes from. Do you have an idea?
> 
> Not without setting up the scenario and digging deep into it. Nothing
> immediately springs to mind.
> 
After enabling pjsip specific debug log in asterisk, I can see, the
following behavior:
Incoming packages from network are always signaled like this (e.g.):

sip_endpoint.c Processing incoming message: Request msg INVITE/cseq=10
(rdata0x7f5f1801a758)
<--- Received SIP request (918 bytes) from UDP:195.185.37.60:5060
...


The path of the critical not existing package is like this and can't 
be seen elsewhere (there wasn't any corresponding incoming 
message entry before):

sip_endpoint.c Distributing rdata to modules: Request msg INVITE/cseq=10
(rdata0x7f5f100e4c38)
<--- Received SIP request (918 bytes) from UDP:195.185.37.60:5060 --->
...

Normally, "Distributing rdata to modules" can be seen only if 
pjsip_rx_data_clone is called like in res_pjsip/pjsip_distributor.c

This is really odd, because if the fax is sent locally (w/o provider) 
directly between the same extension, this behavior can't be seen and 
therefore it's working fine as expected!



That's the complete critical excerpt, starting with the regular reInvite
received from provider:


[2017-06-15 07:43:57] DEBUG[11705]: pjproject:0 <?>:           
sip_endpoint.c Processing incoming message: Request msg INVITE/cseq=10
(rdata0x7f5f1801a758)
<--- Received SIP request (918 bytes) from UDP:195.185.37.60:5060 --->
INVITE sip:+4911111111111 at 42.13.16.27:5061 SIP/2.0
Via: SIP/2.0/UDP 195.185.37.60;branch=z9hG4bKHeVwGavN;rport
From: <sip:111111111111 at
sip.easybell.de>;tag=72F0675F-5942027B00075955-FB9F9700
To: <sip:+4911111111111 at
sip.easybell.de>;tag=f045584d-da09-4913-9b46-102361e397f2
CSeq: 10 INVITE
Call-ID: 7f582402-0ce9-4a1a-87f6-b8de8b2a7bc8
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:64A510CA-5942027B00065C24-6F93C700 at
195.185.37.60;transport=udp>

v=0
o=- 1935061780 1935061784 IN IP4 195.185.37.60
s=-
c=IN IP4 195.185.37.60
t=0 0
m=image 33818 UDPTL t38
a=sendrecv
a=T38FaxVersion:0
a=T38MaxBitRate:14400
a=T38FaxRateManagement:transferredTCF
a=T38FaxMaxDatagram:1393
a=T38FaxUdpEC:t38UDPRedundancy

[2017-06-15 07:43:57] DEBUG[11705]: res_pjsip/pjsip_distributor.c:379
distributor: Searching for serializer on dialog dlg0x7f5f18034698 for Request
msg INVITE/cseq=10 (rdata0x7f5f1801a758)
[2017-06-15 07:43:57] DEBUG[11705]: res_pjsip/pjsip_distributor.c:385
distributor: Found serializer pjsip/outsess/easybellPJSIP-00000076 on dialog
dlg0x7f5f18034698
[2017-06-15 07:43:57] DEBUG[11705]: res_pjsip/pjsip_distributor.c:433
distributor: rdata clone: Request msg INVITE/cseq=10 (rdata0x7f5f18052b08)
[2017-06-15 07:43:57] DEBUG[11705]: res_pjsip/pjsip_distributor.c:446
distributor: PJ_TRUE 3 - ready Request msg INVITE/cseq=10 (rdata0x7f5f1801a758)
[2017-06-15 07:43:57] DEBUG[25171]: pjproject:0 <?>:           
sip_endpoint.c Distributing rdata to modules: Request msg INVITE/cseq=10
(rdata0x7f5f18052b08)
[2017-06-15 07:43:57] DEBUG[25171]: res_pjsip_t38.c:268 t38_initialize_session:
UDPTL initialized on session for PJSIP/easybellPJSIP-00000009
[2017-06-15 07:43:57] DEBUG[25171]: res_pjsip_t38.c:138 t38_change_state: T.38
state changed to '2' from '0' on channel
'PJSIP/easybellPJSIP-00000009'
[2017-06-15 07:43:57] DEBUG[25171]: res_pjsip_t38.c:673
defer_incoming_sdp_stream: Deferring incoming SDP stream on
PJSIP/easybellPJSIP-00000009 for peer re-invite
[2017-06-15 07:43:57] DEBUG[25198][C-00000004]: bridge_native_rtp.c:348
native_rtp_bridge_compatible_check: Bridge
'f8e63423-8fc7-44e4-a33d-c55b7d87d30f' can not use native RTP bridge as
it was forbidden while getting details
[2017-06-15 07:43:57] DEBUG[25198][C-00000004]: bridge.c:506
find_best_technology: Bridge technology native_rtp is not compatible with
properties of existing bridge.
[2017-06-15 07:43:57] DEBUG[25198][C-00000004]: bridge.c:496
find_best_technology: Bridge technology softmix does not have any capabilities
we want.
[2017-06-15 07:43:57] DEBUG[25198][C-00000004]: bridge.c:496
find_best_technology: Bridge technology holding_bridge does not have any
capabilities we want.
[2017-06-15 07:43:57] DEBUG[25171]: res_pjsip/pjsip_distributor.c:785
distribute: rdata clone remove distributed: Request msg INVITE/cseq=10
(rdata0x7f5f18052b08)
[2017-06-15 07:43:57] DEBUG[25198][C-00000004]: bridge.c:515
find_best_technology: Chose bridge technology simple_bridge
[2017-06-15 07:43:57] DEBUG[25198][C-00000004]: bridge.c:1046
smart_bridge_operation: Bridge f8e63423-8fc7-44e4-a33d-c55b7d87d30f is already
using the new technology.
[2017-06-15 07:43:57] DEBUG[25171]: res_pjsip_t38.c:268 t38_initialize_session:
UDPTL initialized on session for PJSIP/91-00000008
[2017-06-15 07:43:57] DEBUG[25171]: res_pjsip_t38.c:138 t38_change_state: T.38
state changed to '1' from '0' on channel
'PJSIP/91-00000008'
[2017-06-15 07:43:57] DEBUG[25171]: res_rtp_asterisk.c:5342 ast_rtp_prop_set:
Ignoring duplicate RTCP property on RTP instance '0x7f5f10009e80'
[2017-06-15 07:43:57] DEBUG[25185][C-00000004]: bridge_native_rtp.c:348
native_rtp_bridge_compatible_check: Bridge
'f8e63423-8fc7-44e4-a33d-c55b7d87d30f' can not use native RTP bridge as
it was forbidden while getting details
[2017-06-15 07:43:57] DEBUG[25185][C-00000004]: bridge.c:506
find_best_technology: Bridge technology native_rtp is not compatible with
properties of existing bridge.
[2017-06-15 07:43:57] DEBUG[25185][C-00000004]: bridge.c:496
find_best_technology: Bridge technology softmix does not have any capabilities
we want.
[2017-06-15 07:43:57] DEBUG[25185][C-00000004]: bridge.c:496
find_best_technology: Bridge technology holding_bridge does not have any
capabilities we want.
[2017-06-15 07:43:57] DEBUG[25185][C-00000004]: bridge.c:515
find_best_technology: Chose bridge technology simple_bridge
[2017-06-15 07:43:57] DEBUG[25185][C-00000004]: bridge.c:1046
smart_bridge_operation: Bridge f8e63423-8fc7-44e4-a33d-c55b7d87d30f is already
using the new technology.
[2017-06-15 07:43:57] DEBUG[25171]: pjproject:0 <?>:                 
endpoint .Request msg INVITE/cseq=24421 (tdta0x7f5f180a98f8) created.
[2017-06-15 07:43:57] DEBUG[25171]: res_pjsip_session.c:971
ast_sip_session_refresh: Sending session refresh SDP via re-INVITE to 91
[2017-06-15 07:43:57] DEBUG[25171]: res_pjsip_session.c:2501
handle_outgoing_request: Method is INVITE
[2017-06-15 07:43:57] DEBUG[25171]: pjproject:0 <?>:        
inv0x7f5f18019fc8 .Sending Request msg INVITE/cseq=24421 (tdta0x7f5f180a98f8)
[2017-06-15 07:43:57] DEBUG[25171]: pjproject:0 <?>:        
dlg0x7f5f18019fc8 ..Sending Request msg INVITE/cseq=24421 (tdta0x7f5f180a98f8)
[2017-06-15 07:43:57] DEBUG[25171]: pjproject:0 <?>:        
tsx0x7f5f18095998 ...Transaction created for Request msg INVITE/cseq=24420
(tdta0x7f5f180a98f8)
[2017-06-15 07:43:57] DEBUG[25171]: pjproject:0 <?>:        
tsx0x7f5f18095998 ..Sending Request msg INVITE/cseq=24420 (tdta0x7f5f180a98f8)
in state Null
[2017-06-15 07:43:57] DEBUG[25171]: pjproject:0 <?>:            
sip_resolve.c ...Target '192.168.10.33:6060' type=Unspecified resolved
to '192.168.10.33:6060' type=UDP (UDP transport)
[2017-06-15 07:43:57] DEBUG[25171]: res_pjsip/pjsip_message_ip_updater.c:257
multihomed_on_tx_message: Re-wrote Contact URI host/port to 192.168.10.33:5061
<--- Transmitting SIP request (980 bytes) to UDP:192.168.10.33:6060 --->
INVITE sip:91 at 192.168.10.33:6060 SIP/2.0
Via: SIP/2.0/UDP
192.168.10.33:5061;rport;branch=z9hG4bKPj201aee1c-20a7-4fe9-b08c-9ec58037f140
From: "CID:+4922222222222" <sip:111111111111 at
192.168.10.33>;tag=d3816d6b-4a00-437b-a525-c2de0f0c3227
To: "root" <sip:91 at
192.168.10.33>;tag=9e9ea185-ea4f-e711-9f85-000db9330d98
Contact: <sip:192.168.10.33:5061>
Call-ID: 48b8a185-ea4f-e711-9f85-000db9330d98 at myfw
CSeq: 24420 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:   250

v=0
o=- 1497498234 5 IN IP4 192.168.10.33
s=Asterisk
c=IN IP4 192.168.10.33
t=0 0
m=image 4640 udptl t38
a=T38FaxVersion:0
a=T38MaxBitRate:14400
a=T38FaxRateManagement:transferredTCF
a=T38FaxMaxDatagram:1393
a=T38FaxUdpEC:t38UDPRedundancy

[2017-06-15 07:43:57] DEBUG[25171]: pjproject:0 <?>:        
tsx0x7f5f18095998 ...State changed from Null to Calling, event=TX_MSG
[2017-06-15 07:43:57] DEBUG[25171]: pjproject:0 <?>:        
dlg0x7f5f18019fc8 ....Transaction tsx0x7f5f18095998 state changed to Calling
[2017-06-15 07:43:57] DEBUG[11705]: pjproject:0 <?>:           
sip_endpoint.c Processing incoming message: Response msg 100/INVITE/cseq=24420
(rdata0x7f5f1801a758)
<--- Received SIP response (415 bytes) from UDP:192.168.10.33:6060 --->
SIP/2.0 100 Trying
CSeq: 24420 INVITE
Via: SIP/2.0/UDP
192.168.10.33:5061;rport=5061;branch=z9hG4bKPj201aee1c-20a7-4fe9-b08c-9ec58037f140;received=192.168.10.33
From: "CID:+4922222222222" <sip:111111111111 at
192.168.10.33>;tag=d3816d6b-4a00-437b-a525-c2de0f0c3227
Call-ID: 48b8a185-ea4f-e711-9f85-000db9330d98 at myfw
To: "root" <sip:91 at
192.168.10.33>;tag=9e9ea185-ea4f-e711-9f85-000db9330d98
Content-Length: 0


[2017-06-15 07:43:57] DEBUG[11705]: res_pjsip/pjsip_distributor.c:379
distributor: Searching for serializer on dialog dlg0x7f5f18019fc8 for Response
msg 100/INVITE/cseq=24420 (rdata0x7f5f1801a758)
[2017-06-15 07:43:57] DEBUG[11705]: res_pjsip/pjsip_distributor.c:385
distributor: Found serializer pjsip/distributor-00000041 on dialog
dlg0x7f5f18019fc8
[2017-06-15 07:43:57] DEBUG[11705]: res_pjsip/pjsip_distributor.c:433
distributor: rdata clone: Response msg 100/INVITE/cseq=24420
(rdata0x7f5f18052b08)
[2017-06-15 07:43:57] DEBUG[11705]: res_pjsip/pjsip_distributor.c:446
distributor: PJ_TRUE 3 - ready Response msg 100/INVITE/cseq=24420
(rdata0x7f5f1801a758)
[2017-06-15 07:43:57] DEBUG[25171]: pjproject:0 <?>:           
sip_endpoint.c Distributing rdata to modules: Response msg 100/INVITE/cseq=24420
(rdata0x7f5f18052b08)
[2017-06-15 07:43:57] DEBUG[25171]: pjproject:0 <?>:        
tsx0x7f5f18095998 .Incoming Response msg 100/INVITE/cseq=24420
(rdata0x7f5f18052b08) in state Calling
[2017-06-15 07:43:57] DEBUG[25171]: pjproject:0 <?>:        
tsx0x7f5f18095998 ..State changed from Calling to Proceeding, event=RX_MSG
[2017-06-15 07:43:57] DEBUG[25171]: pjproject:0 <?>:        
dlg0x7f5f18019fc8 ...Received Response msg 100/INVITE/cseq=24420
(rdata0x7f5f18052b08)
[2017-06-15 07:43:57] DEBUG[25171]: pjproject:0 <?>:        
dlg0x7f5f18019fc8 ...Transaction tsx0x7f5f18095998 state changed to Proceeding
[2017-06-15 07:43:57] DEBUG[25171]: res_pjsip_session.c:2485 handle_incoming:
Received response
[2017-06-15 07:43:57] DEBUG[25171]: res_pjsip_session.c:2469
handle_incoming_response: Response is 100 Trying
[2017-06-15 07:43:57] DEBUG[25171]: res_pjsip/pjsip_distributor.c:785
distribute: rdata clone remove distributed: Response msg 100/INVITE/cseq=24420
(rdata0x7f5f18052b08)
[2017-06-15 07:43:57] DEBUG[11705]: pjproject:0 <?>:           
sip_endpoint.c Processing incoming message: Response msg 200/INVITE/cseq=24420
(rdata0x7f5f1801a758)
<--- Received SIP response (942 bytes) from UDP:192.168.10.33:6060 --->
SIP/2.0 200 OK
CSeq: 24420 INVITE
Via: SIP/2.0/UDP
192.168.10.33:5061;rport=5061;branch=z9hG4bKPj201aee1c-20a7-4fe9-b08c-9ec58037f140;received=192.168.10.33
User-Agent: T38Modem/3.15.2
From: "CID:+4922222222222" <sip:111111111111 at
192.168.10.33>;tag=d3816d6b-4a00-437b-a525-c2de0f0c3227
Call-ID: 48b8a185-ea4f-e711-9f85-000db9330d98 at myfw
Organization: Frolov,Holtschneider,Davidson
To: "root" <sip:91 at
192.168.10.33>;tag=9e9ea185-ea4f-e711-9f85-000db9330d98
Contact: "root" <sip:91 at 192.168.10.33:6060>
Allow:
INVITE,ACK,OPTIONS,BYE,CANCEL,SUBSCRIBE,NOTIFY,REFER,MESSAGE,INFO,PING,PRACK
Content-Length: 294
Content-Type: application/sdp

v=0
o=- 1497498234 3 IN IP4 192.168.10.33
s=T38Modem/3.15.2
c=IN IP4 192.168.10.33
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-15 07:43:57] DEBUG[11705]: res_pjsip/pjsip_distributor.c:379
distributor: Searching for serializer on dialog dlg0x7f5f18019fc8 for Response
msg 200/INVITE/cseq=24420 (rdata0x7f5f1801a758)
[2017-06-15 07:43:57] DEBUG[11705]: res_pjsip/pjsip_distributor.c:385
distributor: Found serializer pjsip/distributor-00000041 on dialog
dlg0x7f5f18019fc8
[2017-06-15 07:43:57] DEBUG[11705]: res_pjsip/pjsip_distributor.c:433
distributor: rdata clone: Response msg 200/INVITE/cseq=24420
(rdata0x7f5f18052b08)
[2017-06-15 07:43:57] DEBUG[11705]: res_pjsip/pjsip_distributor.c:446
distributor: PJ_TRUE 3 - ready Response msg 200/INVITE/cseq=24420
(rdata0x7f5f1801a758)
[2017-06-15 07:43:57] DEBUG[25171]: pjproject:0 <?>:           
sip_endpoint.c Distributing rdata to modules: Response msg 200/INVITE/cseq=24420
(rdata0x7f5f18052b08)
[2017-06-15 07:43:57] DEBUG[25171]: pjproject:0 <?>:        
tsx0x7f5f18095998 .Incoming Response msg 200/INVITE/cseq=24420
(rdata0x7f5f18052b08) in state Proceeding
[2017-06-15 07:43:57] DEBUG[25171]: pjproject:0 <?>:        
tsx0x7f5f18095998 ..State changed from Proceeding to Terminated, event=RX_MSG
[2017-06-15 07:43:57] DEBUG[25171]: pjproject:0 <?>:        
dlg0x7f5f18019fc8 ...Received Response msg 200/INVITE/cseq=24420
(rdata0x7f5f18052b08)
[2017-06-15 07:43:57] DEBUG[25171]: pjproject:0 <?>:        
dlg0x7f5f18019fc8 ...Transaction tsx0x7f5f18095998 state changed to Terminated
[2017-06-15 07:43:57] DEBUG[25171]: pjproject:0 <?>:        
inv0x7f5f18019fc8 ....Got SDP answer in Response msg 200/INVITE/cseq=24420
(rdata0x7f5f18052b08)
[2017-06-15 07:43:57] DEBUG[25171]: pjproject:0 <?>:        
inv0x7f5f18019fc8 ....SDP negotiation done, status=0
[2017-06-15 07:43:57] DEBUG[25171]: res_pjsip_session.c:374
handle_negotiated_sdp_session_media: Stopping SDP media stream 'audio'
as it is not currently negotiated
[2017-06-15 07:43:57] DEBUG[25171]: res_pjsip_session.c:331
handle_negotiated_sdp_session_media: Applying negotiated SDP media stream
'image' using image SDP handler
[2017-06-15 07:43:57] DEBUG[25171]: res_pjsip_session.c:337
handle_negotiated_sdp_session_media: Applied negotiated SDP media stream
'image' using image SDP handler
[2017-06-15 07:43:57] DEBUG[25171]: pjproject:0 <?>:        
inv0x7f5f18019fc8 ....Received Response msg 200/INVITE/cseq=24420
(rdata0x7f5f18052b08), sending ACK
[2017-06-15 07:43:57] DEBUG[25171]: pjproject:0 <?>:                 
endpoint ....Request msg ACK/cseq=24420 (tdta0x7f5f1000f6f8) created.
[2017-06-15 07:43:57] DEBUG[25171]: pjproject:0 <?>:        
dlg0x7f5f18019fc8 .....Sending Request msg ACK/cseq=24420 (tdta0x7f5f1000f6f8)
[2017-06-15 07:43:57] DEBUG[25171]: pjproject:0 <?>:            
sip_resolve.c .....Target '192.168.10.33:6060' type=Unspecified resolved
to '192.168.10.33:6060' type=UDP (UDP transport)
<--- Transmitting SIP request (461 bytes) to UDP:192.168.10.33:6060 --->
ACK sip:91 at 192.168.10.33:6060 SIP/2.0
Via: SIP/2.0/UDP
192.168.10.33:5061;rport;branch=z9hG4bKPj9e6f8c71-088b-4ffc-b6a3-14276194681f
From: "CID:+4922222222222" <sip:111111111111 at
192.168.10.33>;tag=d3816d6b-4a00-437b-a525-c2de0f0c3227
To: "root" <sip:91 at
192.168.10.33>;tag=9e9ea185-ea4f-e711-9f85-000db9330d98
Call-ID: 48b8a185-ea4f-e711-9f85-000db9330d98 at myfw
CSeq: 24420 ACK
Max-Forwards: 70
User-Agent: FPBX-13.0.191.11(13.16.0)
Content-Length:  0


[2017-06-15 07:43:57] DEBUG[25171]: res_pjsip_session.c:2485 handle_incoming:
Received response
[2017-06-15 07:43:57] DEBUG[25171]: res_pjsip_session.c:2469
handle_incoming_response: Response is 200 OK
[2017-06-15 07:43:57] DEBUG[25171]: res_pjsip_t38.c:138 t38_change_state: T.38
state changed to '3' from '1' on channel
'PJSIP/91-00000008'
[2017-06-15 07:43:57] DEBUG[25171]: res_pjsip/pjsip_distributor.c:785
distribute: rdata clone remove distributed: Response msg 200/INVITE/cseq=24420
(rdata0x7f5f18052b08)
[2017-06-15 07:43:57] DEBUG[25185][C-00000004]: channel.c:3986 __ast_read:
Dropping duplicate answer!
[2017-06-15 07:43:57] DEBUG[25171]: res_pjsip_t38.c:138 t38_change_state: T.38
state changed to '3' from '2' on channel
'PJSIP/easybellPJSIP-00000009'
[2017-06-15 07:43:57] DEBUG[25171]: res_pjsip_t38.c:142 t38_change_state:
Automatic T.38 rejection on channel 'PJSIP/easybellPJSIP-00000009'
terminated




[2017-06-15 07:43:57] DEBUG[25171]: pjproject:0 <?>:           
sip_endpoint.c Distributing rdata to modules: Request msg INVITE/cseq=10
(rdata0x7f5f100e4c38)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
<--- Received SIP request (918 bytes) from UDP:195.185.37.60:5060 --->
INVITE sip:+4911111111111 at 42.13.16.27:5061 SIP/2.0
Via: SIP/2.0/UDP 195.185.37.60;branch=z9hG4bKHeVwGavN;rport
From: <sip:111111111111 at
sip.easybell.de>;tag=72F0675F-5942027B00075955-FB9F9700
To: <sip:+4911111111111 at
sip.easybell.de>;tag=f045584d-da09-4913-9b46-102361e397f2
CSeq: 10 INVITE
Call-ID: 7f582402-0ce9-4a1a-87f6-b8de8b2a7bc8
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:64A510CA-5942027B00065C24-6F93C700 at
195.185.37.60;transport=udp>

v=0
o=- 1935061780 1935061784 IN IP4 195.185.37.60
s=-
c=IN IP4 195.185.37.60
t=0 0
m=image 33818 UDPTL t38
a=sendrecv
a=T38FaxVersion:0
a=T38MaxBitRate:14400
a=T38FaxRateManagement:transferredTCF
a=T38FaxMaxDatagram:1393
a=T38FaxUdpEC:t38UDPRedundancy




Regards,
Michael

Michael Maier

2017-Jun-16 05:13 UTC

head link

[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'

On 06/15/2017 at 08:15 AM Michael Maier wrote:> On 06/14/2017 at 10:17 PM, Joshua Colp wrote:
>> On Wed, Jun 14, 2017, at 05:09 PM, Michael Maier wrote:
>>
>> <snip>
>>
>>>
>>> I can now say, that asterisk / pjsip seams to work *mostly* as
expected.
>>> Just one exception - and that's the package in question, which
can't be
>>> seen in tcpdump.
>>>
>>> I extended the above patch by adding the info at the last output:
>>>
>>> ast_debug(3, "PJ_TRUE 3 - ready %s\n",
pjsip_rx_data_get_info(rdata));
>>>
>>> This gives, that for *all* received packages return PJ_TRUE is
reached.
>>>
>>> But: all packages besides of the phantom resend use the same
address
>>> rdata0x7f963c0009b8 - only the phantom resent package uses
>>> rdata0x7f9654081e18. I think, that's the problem. But I
don't know what
>>> it means and where it comes from. Do you have an idea?
>>
>> Not without setting up the scenario and digging deep into it. Nothing
>> immediately springs to mind.
>>
> 
> After enabling pjsip specific debug log in asterisk, I can see, the
> following behavior:
> Incoming packages from network are always signaled like this (e.g.):
> 
> sip_endpoint.c Processing incoming message: Request msg INVITE/cseq=10
(rdata0x7f5f1801a758)
> <--- Received SIP request (918 bytes) from UDP:195.185.37.60:5060
> ...
> 
> 
> The path of the critical not existing package is like this and can't 
> be seen elsewhere (there wasn't any corresponding incoming 
> message entry before):
> 
> sip_endpoint.c Distributing rdata to modules: Request msg INVITE/cseq=10
(rdata0x7f5f100e4c38)
> <--- Received SIP request (918 bytes) from UDP:195.185.37.60:5060
--->
> ...
> 
> Normally, "Distributing rdata to modules" can be seen only if 
> pjsip_rx_data_clone is called like in res_pjsip/pjsip_distributor.c
> 
> This is really odd, because if the fax is sent locally (w/o provider) 
> directly between the same extension, this behavior can't be seen and 
> therefore it's working fine as expected!
> 
> 
> 
> That's the complete critical excerpt, starting with the regular
reInvite received from provider:
> 
> 
> [2017-06-15 07:43:57] DEBUG[11705]: pjproject:0 <?>:           
sip_endpoint.c Processing incoming message: Request msg INVITE/cseq=10
(rdata0x7f5f1801a758)
> <--- Received SIP request (918 bytes) from UDP:195.185.37.60:5060
--->
> INVITE sip:+4911111111111 at 42.13.16.27:5061 SIP/2.0
> Via: SIP/2.0/UDP 195.185.37.60;branch=z9hG4bKHeVwGavN;rport
> From: <sip:111111111111 at
sip.easybell.de>;tag=72F0675F-5942027B00075955-FB9F9700
> To: <sip:+4911111111111 at
sip.easybell.de>;tag=f045584d-da09-4913-9b46-102361e397f2
> CSeq: 10 INVITE
> Call-ID: 7f582402-0ce9-4a1a-87f6-b8de8b2a7bc8
> 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:64A510CA-5942027B00065C24-6F93C700 at
195.185.37.60;transport=udp>
> 
> v=0
> o=- 1935061780 1935061784 IN IP4 195.185.37.60
> s=-
> c=IN IP4 195.185.37.60
> t=0 0
> m=image 33818 UDPTL t38
> a=sendrecv
> a=T38FaxVersion:0
> a=T38MaxBitRate:14400
> a=T38FaxRateManagement:transferredTCF
> a=T38FaxMaxDatagram:1393
> a=T38FaxUdpEC:t38UDPRedundancy
> 
> [2017-06-15 07:43:57] DEBUG[11705]: res_pjsip/pjsip_distributor.c:379
distributor: Searching for serializer on dialog dlg0x7f5f18034698 for Request
msg INVITE/cseq=10 (rdata0x7f5f1801a758)
> [2017-06-15 07:43:57] DEBUG[11705]: res_pjsip/pjsip_distributor.c:385
distributor: Found serializer pjsip/outsess/easybellPJSIP-00000076 on dialog
dlg0x7f5f18034698
> [2017-06-15 07:43:57] DEBUG[11705]: res_pjsip/pjsip_distributor.c:433
distributor: rdata clone: Request msg INVITE/cseq=10 (rdata0x7f5f18052b08)
> [2017-06-15 07:43:57] DEBUG[11705]: res_pjsip/pjsip_distributor.c:446
distributor: PJ_TRUE 3 - ready Request msg INVITE/cseq=10 (rdata0x7f5f1801a758)
> [2017-06-15 07:43:57] DEBUG[25171]: pjproject:0 <?>:           
sip_endpoint.c Distributing rdata to modules: Request msg INVITE/cseq=10
(rdata0x7f5f18052b08)
> [2017-06-15 07:43:57] DEBUG[25171]: res_pjsip_t38.c:268
t38_initialize_session: UDPTL initialized on session for
PJSIP/easybellPJSIP-00000009
> [2017-06-15 07:43:57] DEBUG[25171]: res_pjsip_t38.c:138 t38_change_state:
T.38 state changed to '2' from '0' on channel
'PJSIP/easybellPJSIP-00000009'
> [2017-06-15 07:43:57] DEBUG[25171]: res_pjsip_t38.c:673
defer_incoming_sdp_stream: Deferring incoming SDP stream on
PJSIP/easybellPJSIP-00000009 for peer re-invite
> [2017-06-15 07:43:57] DEBUG[25198][C-00000004]: bridge_native_rtp.c:348
native_rtp_bridge_compatible_check: Bridge
'f8e63423-8fc7-44e4-a33d-c55b7d87d30f' can not use native RTP bridge as
it was forbidden while getting details
> [2017-06-15 07:43:57] DEBUG[25198][C-00000004]: bridge.c:506
find_best_technology: Bridge technology native_rtp is not compatible with
properties of existing bridge.
> [2017-06-15 07:43:57] DEBUG[25198][C-00000004]: bridge.c:496
find_best_technology: Bridge technology softmix does not have any capabilities
we want.
> [2017-06-15 07:43:57] DEBUG[25198][C-00000004]: bridge.c:496
find_best_technology: Bridge technology holding_bridge does not have any
capabilities we want.
> [2017-06-15 07:43:57] DEBUG[25171]: res_pjsip/pjsip_distributor.c:785
distribute: rdata clone remove distributed: Request msg INVITE/cseq=10
(rdata0x7f5f18052b08)
> [2017-06-15 07:43:57] DEBUG[25198][C-00000004]: bridge.c:515
find_best_technology: Chose bridge technology simple_bridge
> [2017-06-15 07:43:57] DEBUG[25198][C-00000004]: bridge.c:1046
smart_bridge_operation: Bridge f8e63423-8fc7-44e4-a33d-c55b7d87d30f is already
using the new technology.
> [2017-06-15 07:43:57] DEBUG[25171]: res_pjsip_t38.c:268
t38_initialize_session: UDPTL initialized on session for PJSIP/91-00000008
> [2017-06-15 07:43:57] DEBUG[25171]: res_pjsip_t38.c:138 t38_change_state:
T.38 state changed to '1' from '0' on channel
'PJSIP/91-00000008'
> [2017-06-15 07:43:57] DEBUG[25171]: res_rtp_asterisk.c:5342
ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance
'0x7f5f10009e80'
> [2017-06-15 07:43:57] DEBUG[25185][C-00000004]: bridge_native_rtp.c:348
native_rtp_bridge_compatible_check: Bridge
'f8e63423-8fc7-44e4-a33d-c55b7d87d30f' can not use native RTP bridge as
it was forbidden while getting details
> [2017-06-15 07:43:57] DEBUG[25185][C-00000004]: bridge.c:506
find_best_technology: Bridge technology native_rtp is not compatible with
properties of existing bridge.
> [2017-06-15 07:43:57] DEBUG[25185][C-00000004]: bridge.c:496
find_best_technology: Bridge technology softmix does not have any capabilities
we want.
> [2017-06-15 07:43:57] DEBUG[25185][C-00000004]: bridge.c:496
find_best_technology: Bridge technology holding_bridge does not have any
capabilities we want.
> [2017-06-15 07:43:57] DEBUG[25185][C-00000004]: bridge.c:515
find_best_technology: Chose bridge technology simple_bridge
> [2017-06-15 07:43:57] DEBUG[25185][C-00000004]: bridge.c:1046
smart_bridge_operation: Bridge f8e63423-8fc7-44e4-a33d-c55b7d87d30f is already
using the new technology.
> [2017-06-15 07:43:57] DEBUG[25171]: pjproject:0 <?>:                 
endpoint .Request msg INVITE/cseq=24421 (tdta0x7f5f180a98f8) created.
> [2017-06-15 07:43:57] DEBUG[25171]: res_pjsip_session.c:971
ast_sip_session_refresh: Sending session refresh SDP via re-INVITE to 91
> [2017-06-15 07:43:57] DEBUG[25171]: res_pjsip_session.c:2501
handle_outgoing_request: Method is INVITE
> [2017-06-15 07:43:57] DEBUG[25171]: pjproject:0 <?>:        
inv0x7f5f18019fc8 .Sending Request msg INVITE/cseq=24421 (tdta0x7f5f180a98f8)
> [2017-06-15 07:43:57] DEBUG[25171]: pjproject:0 <?>:        
dlg0x7f5f18019fc8 ..Sending Request msg INVITE/cseq=24421 (tdta0x7f5f180a98f8)
> [2017-06-15 07:43:57] DEBUG[25171]: pjproject:0 <?>:        
tsx0x7f5f18095998 ...Transaction created for Request msg INVITE/cseq=24420
(tdta0x7f5f180a98f8)
> [2017-06-15 07:43:57] DEBUG[25171]: pjproject:0 <?>:        
tsx0x7f5f18095998 ..Sending Request msg INVITE/cseq=24420 (tdta0x7f5f180a98f8)
in state Null
> [2017-06-15 07:43:57] DEBUG[25171]: pjproject:0 <?>:            
sip_resolve.c ...Target '192.168.10.33:6060' type=Unspecified resolved
to '192.168.10.33:6060' type=UDP (UDP transport)
> [2017-06-15 07:43:57] DEBUG[25171]:
res_pjsip/pjsip_message_ip_updater.c:257 multihomed_on_tx_message: Re-wrote
Contact URI host/port to 192.168.10.33:5061
> <--- Transmitting SIP request (980 bytes) to UDP:192.168.10.33:6060
--->
> INVITE sip:91 at 192.168.10.33:6060 SIP/2.0
> Via: SIP/2.0/UDP
192.168.10.33:5061;rport;branch=z9hG4bKPj201aee1c-20a7-4fe9-b08c-9ec58037f140
> From: "CID:+4922222222222" <sip:111111111111 at
192.168.10.33>;tag=d3816d6b-4a00-437b-a525-c2de0f0c3227
> To: "root" <sip:91 at
192.168.10.33>;tag=9e9ea185-ea4f-e711-9f85-000db9330d98
> Contact: <sip:192.168.10.33:5061>
> Call-ID: 48b8a185-ea4f-e711-9f85-000db9330d98 at myfw
> CSeq: 24420 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:   250
> 
> v=0
> o=- 1497498234 5 IN IP4 192.168.10.33
> s=Asterisk
> c=IN IP4 192.168.10.33
> t=0 0
> m=image 4640 udptl t38
> a=T38FaxVersion:0
> a=T38MaxBitRate:14400
> a=T38FaxRateManagement:transferredTCF
> a=T38FaxMaxDatagram:1393
> a=T38FaxUdpEC:t38UDPRedundancy
> 
> [2017-06-15 07:43:57] DEBUG[25171]: pjproject:0 <?>:        
tsx0x7f5f18095998 ...State changed from Null to Calling, event=TX_MSG
> [2017-06-15 07:43:57] DEBUG[25171]: pjproject:0 <?>:        
dlg0x7f5f18019fc8 ....Transaction tsx0x7f5f18095998 state changed to Calling
> [2017-06-15 07:43:57] DEBUG[11705]: pjproject:0 <?>:           
sip_endpoint.c Processing incoming message: Response msg 100/INVITE/cseq=24420
(rdata0x7f5f1801a758)
> <--- Received SIP response (415 bytes) from UDP:192.168.10.33:6060
--->
> SIP/2.0 100 Trying
> CSeq: 24420 INVITE
> Via: SIP/2.0/UDP
192.168.10.33:5061;rport=5061;branch=z9hG4bKPj201aee1c-20a7-4fe9-b08c-9ec58037f140;received=192.168.10.33
> From: "CID:+4922222222222" <sip:111111111111 at
192.168.10.33>;tag=d3816d6b-4a00-437b-a525-c2de0f0c3227
> Call-ID: 48b8a185-ea4f-e711-9f85-000db9330d98 at myfw
> To: "root" <sip:91 at
192.168.10.33>;tag=9e9ea185-ea4f-e711-9f85-000db9330d98
> Content-Length: 0
> 
> 
> [2017-06-15 07:43:57] DEBUG[11705]: res_pjsip/pjsip_distributor.c:379
distributor: Searching for serializer on dialog dlg0x7f5f18019fc8 for Response
msg 100/INVITE/cseq=24420 (rdata0x7f5f1801a758)
> [2017-06-15 07:43:57] DEBUG[11705]: res_pjsip/pjsip_distributor.c:385
distributor: Found serializer pjsip/distributor-00000041 on dialog
dlg0x7f5f18019fc8
> [2017-06-15 07:43:57] DEBUG[11705]: res_pjsip/pjsip_distributor.c:433
distributor: rdata clone: Response msg 100/INVITE/cseq=24420
(rdata0x7f5f18052b08)
> [2017-06-15 07:43:57] DEBUG[11705]: res_pjsip/pjsip_distributor.c:446
distributor: PJ_TRUE 3 - ready Response msg 100/INVITE/cseq=24420
(rdata0x7f5f1801a758)
> [2017-06-15 07:43:57] DEBUG[25171]: pjproject:0 <?>:           
sip_endpoint.c Distributing rdata to modules: Response msg 100/INVITE/cseq=24420
(rdata0x7f5f18052b08)
> [2017-06-15 07:43:57] DEBUG[25171]: pjproject:0 <?>:        
tsx0x7f5f18095998 .Incoming Response msg 100/INVITE/cseq=24420
(rdata0x7f5f18052b08) in state Calling
> [2017-06-15 07:43:57] DEBUG[25171]: pjproject:0 <?>:        
tsx0x7f5f18095998 ..State changed from Calling to Proceeding, event=RX_MSG
> [2017-06-15 07:43:57] DEBUG[25171]: pjproject:0 <?>:        
dlg0x7f5f18019fc8 ...Received Response msg 100/INVITE/cseq=24420
(rdata0x7f5f18052b08)
> [2017-06-15 07:43:57] DEBUG[25171]: pjproject:0 <?>:        
dlg0x7f5f18019fc8 ...Transaction tsx0x7f5f18095998 state changed to Proceeding
> [2017-06-15 07:43:57] DEBUG[25171]: res_pjsip_session.c:2485
handle_incoming: Received response
> [2017-06-15 07:43:57] DEBUG[25171]: res_pjsip_session.c:2469
handle_incoming_response: Response is 100 Trying
> [2017-06-15 07:43:57] DEBUG[25171]: res_pjsip/pjsip_distributor.c:785
distribute: rdata clone remove distributed: Response msg 100/INVITE/cseq=24420
(rdata0x7f5f18052b08)
> [2017-06-15 07:43:57] DEBUG[11705]: pjproject:0 <?>:           
sip_endpoint.c Processing incoming message: Response msg 200/INVITE/cseq=24420
(rdata0x7f5f1801a758)
> <--- Received SIP response (942 bytes) from UDP:192.168.10.33:6060
--->
> SIP/2.0 200 OK
> CSeq: 24420 INVITE
> Via: SIP/2.0/UDP
192.168.10.33:5061;rport=5061;branch=z9hG4bKPj201aee1c-20a7-4fe9-b08c-9ec58037f140;received=192.168.10.33
> User-Agent: T38Modem/3.15.2
> From: "CID:+4922222222222" <sip:111111111111 at
192.168.10.33>;tag=d3816d6b-4a00-437b-a525-c2de0f0c3227
> Call-ID: 48b8a185-ea4f-e711-9f85-000db9330d98 at myfw
> Organization: Frolov,Holtschneider,Davidson
> To: "root" <sip:91 at
192.168.10.33>;tag=9e9ea185-ea4f-e711-9f85-000db9330d98
> Contact: "root" <sip:91 at 192.168.10.33:6060>
> Allow:
INVITE,ACK,OPTIONS,BYE,CANCEL,SUBSCRIBE,NOTIFY,REFER,MESSAGE,INFO,PING,PRACK
> Content-Length: 294
> Content-Type: application/sdp
> 
> v=0
> o=- 1497498234 3 IN IP4 192.168.10.33
> s=T38Modem/3.15.2
> c=IN IP4 192.168.10.33
> 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-15 07:43:57] DEBUG[11705]: res_pjsip/pjsip_distributor.c:379
distributor: Searching for serializer on dialog dlg0x7f5f18019fc8 for Response
msg 200/INVITE/cseq=24420 (rdata0x7f5f1801a758)
> [2017-06-15 07:43:57] DEBUG[11705]: res_pjsip/pjsip_distributor.c:385
distributor: Found serializer pjsip/distributor-00000041 on dialog
dlg0x7f5f18019fc8
> [2017-06-15 07:43:57] DEBUG[11705]: res_pjsip/pjsip_distributor.c:433
distributor: rdata clone: Response msg 200/INVITE/cseq=24420
(rdata0x7f5f18052b08)
> [2017-06-15 07:43:57] DEBUG[11705]: res_pjsip/pjsip_distributor.c:446
distributor: PJ_TRUE 3 - ready Response msg 200/INVITE/cseq=24420
(rdata0x7f5f1801a758)
> [2017-06-15 07:43:57] DEBUG[25171]: pjproject:0 <?>:           
sip_endpoint.c Distributing rdata to modules: Response msg 200/INVITE/cseq=24420
(rdata0x7f5f18052b08)
> [2017-06-15 07:43:57] DEBUG[25171]: pjproject:0 <?>:        
tsx0x7f5f18095998 .Incoming Response msg 200/INVITE/cseq=24420
(rdata0x7f5f18052b08) in state Proceeding
> [2017-06-15 07:43:57] DEBUG[25171]: pjproject:0 <?>:        
tsx0x7f5f18095998 ..State changed from Proceeding to Terminated, event=RX_MSG
> [2017-06-15 07:43:57] DEBUG[25171]: pjproject:0 <?>:        
dlg0x7f5f18019fc8 ...Received Response msg 200/INVITE/cseq=24420
(rdata0x7f5f18052b08)
> [2017-06-15 07:43:57] DEBUG[25171]: pjproject:0 <?>:        
dlg0x7f5f18019fc8 ...Transaction tsx0x7f5f18095998 state changed to Terminated
> [2017-06-15 07:43:57] DEBUG[25171]: pjproject:0 <?>:        
inv0x7f5f18019fc8 ....Got SDP answer in Response msg 200/INVITE/cseq=24420
(rdata0x7f5f18052b08)
> [2017-06-15 07:43:57] DEBUG[25171]: pjproject:0 <?>:        
inv0x7f5f18019fc8 ....SDP negotiation done, status=0
> [2017-06-15 07:43:57] DEBUG[25171]: res_pjsip_session.c:374
handle_negotiated_sdp_session_media: Stopping SDP media stream 'audio'
as it is not currently negotiated
> [2017-06-15 07:43:57] DEBUG[25171]: res_pjsip_session.c:331
handle_negotiated_sdp_session_media: Applying negotiated SDP media stream
'image' using image SDP handler
> [2017-06-15 07:43:57] DEBUG[25171]: res_pjsip_session.c:337
handle_negotiated_sdp_session_media: Applied negotiated SDP media stream
'image' using image SDP handler
> [2017-06-15 07:43:57] DEBUG[25171]: pjproject:0 <?>:        
inv0x7f5f18019fc8 ....Received Response msg 200/INVITE/cseq=24420
(rdata0x7f5f18052b08), sending ACK
> [2017-06-15 07:43:57] DEBUG[25171]: pjproject:0 <?>:                 
endpoint ....Request msg ACK/cseq=24420 (tdta0x7f5f1000f6f8) created.
> [2017-06-15 07:43:57] DEBUG[25171]: pjproject:0 <?>:        
dlg0x7f5f18019fc8 .....Sending Request msg ACK/cseq=24420 (tdta0x7f5f1000f6f8)
> [2017-06-15 07:43:57] DEBUG[25171]: pjproject:0 <?>:            
sip_resolve.c .....Target '192.168.10.33:6060' type=Unspecified resolved
to '192.168.10.33:6060' type=UDP (UDP transport)
> <--- Transmitting SIP request (461 bytes) to UDP:192.168.10.33:6060
--->
> ACK sip:91 at 192.168.10.33:6060 SIP/2.0
> Via: SIP/2.0/UDP
192.168.10.33:5061;rport;branch=z9hG4bKPj9e6f8c71-088b-4ffc-b6a3-14276194681f
> From: "CID:+4922222222222" <sip:111111111111 at
192.168.10.33>;tag=d3816d6b-4a00-437b-a525-c2de0f0c3227
> To: "root" <sip:91 at
192.168.10.33>;tag=9e9ea185-ea4f-e711-9f85-000db9330d98
> Call-ID: 48b8a185-ea4f-e711-9f85-000db9330d98 at myfw
> CSeq: 24420 ACK
> Max-Forwards: 70
> User-Agent: FPBX-13.0.191.11(13.16.0)
> Content-Length:  0
> 
> 
> [2017-06-15 07:43:57] DEBUG[25171]: res_pjsip_session.c:2485
handle_incoming: Received response
> [2017-06-15 07:43:57] DEBUG[25171]: res_pjsip_session.c:2469
handle_incoming_response: Response is 200 OK
> [2017-06-15 07:43:57] DEBUG[25171]: res_pjsip_t38.c:138 t38_change_state:
T.38 state changed to '3' from '1' on channel
'PJSIP/91-00000008'
> [2017-06-15 07:43:57] DEBUG[25171]: res_pjsip/pjsip_distributor.c:785
distribute: rdata clone remove distributed: Response msg 200/INVITE/cseq=24420
(rdata0x7f5f18052b08)
> [2017-06-15 07:43:57] DEBUG[25185][C-00000004]: channel.c:3986 __ast_read:
Dropping duplicate answer!
> [2017-06-15 07:43:57] DEBUG[25171]: res_pjsip_t38.c:138 t38_change_state:
T.38 state changed to '3' from '2' on channel
'PJSIP/easybellPJSIP-00000009'
> [2017-06-15 07:43:57] DEBUG[25171]: res_pjsip_t38.c:142 t38_change_state:
Automatic T.38 rejection on channel 'PJSIP/easybellPJSIP-00000009'
terminated
After adding some more debugging code, it turned out, that the 
following "received" package is not a real package, but a internal
resume!
It's a very confusing log entry! It would be good if it could
be optimized!


[2017-06-15 19:32:12] DEBUG[26218]: res_pjsip_t38.c:361
t38_interpret_parameters: T38_ENABLED -> calling resume_reinvite
[2017-06-15 19:32:12] DEBUG[26218]: res_pjsip_session.c:1182
ast_sip_session_resume_reinvite: resume reinvite
[2017-06-15 19:32:12] DEBUG[26218]: pjproject:0 <?>:              
sip_endpoint.c Distributing rdata to modules: Request msg INVITE/cseq=10
(rdata0x312eb18)
<--- Received SIP request (918 bytes) from UDP:195.185.37.60:5060 --->
INVITE sip:+4971511336089 at 43.57.37.23:5061 SIP/2.0
Via: SIP/2.0/UDP 195.185.37.60;branch=z9hG4bKVWp6vazu;rport
From: <sip:071511336089 at
sip.easybell.de>;tag=3ED81E00-5942C49A000569DF-FBAFA700
To: <sip:+4971511336089 at
sip.easybell.de>;tag=3449ea7e-91e3-4f39-ae10-ba8a79020e17
CSeq: 10 INVITE
Call-ID: dbe2ff49-aba5-42d5-9a22-1ea9a1bf89d8
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:6F659E5C-5942C49A00049C9D-6F437700 at
195.185.37.60;transport=udp>

v=0
o=- 2129164788 2129164792 IN IP4 195.185.37.60
s=-
c=IN IP4 195.185.37.60
t=0 0
m=image 35622 UDPTL t38
a=sendrecv
a=T38FaxVersion:0
a=T38MaxBitRate:14400
a=T38FaxRateManagement:transferredTCF
a=T38FaxMaxDatagram:1393
a=T38FaxUdpEC:t38UDPRedundancy

[2017-06-15 19:32:12] DEBUG[26218]: res_pjsip/pjsip_distributor.c:379
distributor: Searching for serializer on dialog dlg0x30bc228 for Request msg
INVITE/cseq=10 (rdata0x312eb18)
[2017-06-15 19:32:12] DEBUG[26218]: res_pjsip/pjsip_distributor.c:385
distributor: Found serializer pjsip/outsess/easybellPJSIP-00000072 on dialog
dlg0x30bc228
[2017-06-15 19:32:12] DEBUG[26218]: res_pjsip/pjsip_distributor.c:433
distributor: rdata clone: Request msg INVITE/cseq=10 (rdata0x311ab58)
[2017-06-15 19:32:12] DEBUG[26218]: res_pjsip/pjsip_distributor.c:446
distributor: PJ_TRUE 3 - ready Request msg INVITE/cseq=10 (rdata0x312eb18)
[2017-06-15 19:32:12] DEBUG[26218]: pjproject:0 <?>:           
sip_endpoint.c .rdata not handled: Request msg INVITE/cseq=10 (rdata0x312eb18)
status: 0
[2017-06-15 19:32:12] DEBUG[26218]: res_pjsip/pjsip_distributor.c:773
distribute: distribute cloned data: Request msg INVITE/cseq=10 (rdata0x311ab58)
[2017-06-15 19:32:12] DEBUG[26218]: pjproject:0 <?>:           
sip_endpoint.c Distributing rdata to modules: Request msg INVITE/cseq=10
(rdata0x311ab58)
[2017-06-15 19:32:12] DEBUG[26218]: pjproject:0 <?>:             
dlg0x30bc228 .Received Request msg INVITE/cseq=10 (rdata0x311ab58)
[2017-06-15 19:32:12] DEBUG[26218]: pjproject:0 <?>:             
tsx0x30bb2e8 ...Transaction created for Request msg INVITE/cseq=10
(rdata0x311ab58)
[2017-06-15 19:32:12] DEBUG[26218]: pjproject:0 <?>:             
tsx0x30bb2e8 ..Incoming Request msg INVITE/cseq=10 (rdata0x311ab58) in state
Null
[2017-06-15 19:32:12] DEBUG[26218]: pjproject:0 <?>:             
tsx0x30bb2e8 ...State changed from Null to Trying, event=RX_MSG
[2017-06-15 19:32:12] DEBUG[26218]: pjproject:0 <?>:             
dlg0x30bc228 ....Transaction tsx0x30bb2e8 state changed to Trying
[2017-06-15 19:32:12] DEBUG[26218]: pjproject:0 <?>:             
inv0x30bc228 .....Got SDP offer in Request msg INVITE/cseq=10 (rdata0x311ab58)
[2017-06-15 19:32:12] DEBUG[26218]: res_pjsip_session.c:242 handle_incoming_sdp:
Negotiating incoming SDP media stream 'image' using image SDP handler
[2017-06-15 19:32:12] DEBUG[26218]: res_pjsip_session.c:251 handle_incoming_sdp:
Media stream 'image' handled by image
[2017-06-15 19:32:12] DEBUG[26218]: res_rtp_asterisk.c:5342 ast_rtp_prop_set:
Ignoring duplicate RTCP property on RTP instance '0x30d30e0'
[2017-06-15 19:32:12] DEBUG[26218]: pjproject:0 <?>:                 
endpoint .....Response msg 200/INVITE/cseq=10 (tdta0x3104d28) created
[2017-06-15 19:32:12] DEBUG[26218]: pjproject:0 <?>:             
inv0x30bc228 .....SDP negotiation done, status=0
[2017-06-15 19:32:12] DEBUG[26218]: res_pjsip_session.c:374
handle_negotiated_sdp_session_media: Stopping SDP media stream 'audio'
as it is not currently negotiated
[2017-06-15 19:32:12] DEBUG[26218]: res_pjsip_session.c:331
handle_negotiated_sdp_session_media: Applying negotiated SDP media stream
'image' using image SDP handler
[2017-06-15 19:32:12] DEBUG[26218]: res_pjsip_session.c:337
handle_negotiated_sdp_session_media: Applied negotiated SDP media stream
'image' using image SDP handler
[2017-06-15 19:32:12] DEBUG[26218]: pjproject:0 <?>:             
inv0x30bc228 ......Sending Response msg 200/INVITE/cseq=10 (tdta0x3104d28)
[2017-06-15 19:32:12] DEBUG[26218]: pjproject:0 <?>:             
dlg0x30bc228 .......Sending Response msg 200/INVITE/cseq=10 (tdta0x3104d28)
[2017-06-15 19:32:12] DEBUG[26218]: pjproject:0 <?>:             
tsx0x30bb2e8 .......Sending Response msg 200/INVITE/cseq=10 (tdta0x3104d28) in
state Trying
[2017-06-15 19:32:12] DEBUG[26218]: res_pjsip/pjsip_message_ip_updater.c:257
multihomed_on_tx_message: Re-wrote Contact URI host/port to 43.57.37.23: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=z9hG4bKVWp6vazu
Call-ID: dbe2ff49-aba5-42d5-9a22-1ea9a1bf89d8
From: <sip:111111111111 at
sip.easybell.de>;tag=3ED81E00-5942C49A000569DF-FBAFA700
To: <sip:+4911111111111 at
sip.easybell.de>;tag=3449ea7e-91e3-4f39-ae10-ba8a79020e17
CSeq: 10 INVITE
Contact: <sip:+491111111111 at 43.57.37.23: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=- 2129164788 2129164789 IN IP4 43.57.37.23
s=Asterisk
c=IN IP4 43.57.37.23
t=0 0
m=image 0 UDPTL t38




Has anybody any idea why asterisk drops the media stream in the 200 OK? 
The channel has been T38_ENABLED before! Or is it necessary to add more 
debug code? Who does the negotiating? 
Only asterisk or is pjsip doing some parts, too?


Thanks,
Michael

Joshua Colp

2017-Jun-16 09:12 UTC

head link

[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'

On Fri, Jun 16, 2017, at 02:13 AM, Michael Maier wrote:
> Has anybody any idea why asterisk drops the media stream in the 200 OK? 
> The channel has been T38_ENABLED before! Or is it necessary to add more 
> debug code? Who does the negotiating? 
> Only asterisk or is pjsip doing some parts, too?
Asterisk does the T.38 negotiation and produces the answer SDP, PJSIP
does the SDP negotiation. It's likely in the realm of Asterisk where it
is doing that.

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

Possibly Parallel Threads

Search for more seemingly similar threads

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'

[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'

[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'

[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'

Possibly Parallel Threads