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-14 20:09 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 05:53 PM Joshua Colp wrote:> On Wed, Jun 14, 2017, at 12:47 PM, Michael Maier wrote:
> 
> <snip>
> 
>>
>> I added this patch to see, if really all packages are are freed after
>> they have been processed:
>>
>> --- b/res/res_pjsip/pjsip_distributor.c 2017-05-30 19:44:16.000000000
>> +0200
>> +++ a/res/res_pjsip/pjsip_distributor.c 2017-06-13 20:25:27.233000000
>> +0200
>> @@ -407,6 +407,7 @@
>>                 /* We have a BYE or CANCEL request without a
serializer.
>>                 */
>>                
pjsip_endpt_respond_stateless(ast_sip_get_pjsip_endpoint(),
>>                 rdata,
>>                         PJSIP_SC_CALL_TSX_DOES_NOT_EXIST, NULL, NULL,
>>                         NULL);
>> +               ast_debug(3, "PJ_TRUE 1\n");
>>                 return PJ_TRUE;
>>         } else {
>>                 if (ast_taskprocessor_alert_get()) {
>> @@ -439,8 +440,8 @@
>>                 pjsip_rx_data_free_cloned(clone);
>>         }
>>  
>> +       ast_debug(3, "PJ_TRUE 3 - ready\n");
>>         ast_taskprocessor_unreference(serializer);
>> -
>>         return PJ_TRUE;
>>  }
>>  
>>
>>
>> Unfortunately, this patch crashes asterisk when debug is enabled. Is
>> there another way to check, if all the packages are really freed?
> 
> That shouldn't cause Asterisk to crash. There's nothing built in to
> specifically try to debug this kind of situation. Adding logging to try
> to understand what is going on is probably the easiest way.
> 
Got it - I had to change the complete asterisk-packages (I'm compiling
on base of spec file) - and not just the asterisk-core.

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?


Thanks,
Michael

Joshua Colp

2017-Jun-14 20:17 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 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.

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

Michael Maier

2017-Jun-15 06:15 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/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

Possibly Parallel Threads

Search for more apparently analagous 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