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@42.13.16.27:5061 SIP/2.0 > Via: SIP/2.0/UDP 195.185.37.60;branch=z9hG4bKHeVwGavN;rport > From: > <sip:111111111...@sip.easybell.de>;tag=72F0675F-5942027B00075955-FB9F9700 > To: > <sip:+4911111111...@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@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@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@192.168.10.33>;tag=d3816d6b-4a00-437b-a525-c2de0f0c3227 > To: "root" <sip:91@192.168.10.33>;tag=9e9ea185-ea4f-e711-9f85-000db9330d98 > Contact: <sip:192.168.10.33:5061> > Call-ID: 48b8a185-ea4f-e711-9f85-000db9330d98@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@192.168.10.33>;tag=d3816d6b-4a00-437b-a525-c2de0f0c3227 > Call-ID: 48b8a185-ea4f-e711-9f85-000db9330d98@myfw > To: "root" <sip:91@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@192.168.10.33>;tag=d3816d6b-4a00-437b-a525-c2de0f0c3227 > Call-ID: 48b8a185-ea4f-e711-9f85-000db9330d98@myfw > Organization: Frolov,Holtschneider,Davidson > To: "root" <sip:91@192.168.10.33>;tag=9e9ea185-ea4f-e711-9f85-000db9330d98 > Contact: "root" <sip:91@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@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@192.168.10.33>;tag=d3816d6b-4a00-437b-a525-c2de0f0c3227 > To: "root" <sip:91@192.168.10.33>;tag=9e9ea185-ea4f-e711-9f85-000db9330d98 > Call-ID: 48b8a185-ea4f-e711-9f85-000db9330d98@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@43.57.37.23:5061 SIP/2.0 Via: SIP/2.0/UDP 195.185.37.60;branch=z9hG4bKVWp6vazu;rport From: <sip:071511336...@sip.easybell.de>;tag=3ED81E00-5942C49A000569DF-FBAFA700 To: <sip:+4971511336...@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@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:111111111...@sip.easybell.de>;tag=3ED81E00-5942C49A000569DF-FBAFA700 To: <sip:+4911111111...@sip.easybell.de>;tag=3449ea7e-91e3-4f39-ae10-ba8a79020e17 CSeq: 10 INVITE Contact: <sip:+491111111111@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 -- _____________________________________________________________________ -- Bandwidth and Colocation Provided by http://www.api-digital.com -- Check out the new Asterisk community forum at: https://community.asterisk.org/ New to Asterisk? Start here: https://wiki.asterisk.org/wiki/display/AST/Getting+Started asterisk-users mailing list To UNSUBSCRIBE or update options visit: http://lists.digium.com/mailman/listinfo/asterisk-users
