[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'
Michael Maier
m1278468 at mailbox.org
Fri Jun 16 00:13:23 CDT 2017
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
More information about the asterisk-users
mailing list