Asterisk 13.16 / Pjsip / T.38: Res_pjsip_t38.c:207 T38_automatic_reject: Automatically Rejecting T.38 Request On Channel ‘PJSIP/91-00000007’

Home » 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 31 Comments

Hello!

I’m still trying to get a working t.38 configuration w/ pjsip.

I’m now able to send t.38 faxes to my own extension:

hylafax -> t38modem -> extension -> extension -> t38modem -> hylafax.

The fax is sent by t38modem. The receiving part of t38modem accepts the call, sends ReInvite for t.38 and things are working as expected.

Now, let’s do the nearly same thing, but use an ISP:

hylafax -> t38modem -> extension -> trunk -> ISP ->
trunk -> extension -> t39modem(2) -> hylafax

Same procedure: the receiving t38modem(2) sends ReInvite for t.38 – but this time, the extension / asterisk just ignores it. After the 5. retry to switch to T.38, asterisk tells:

res_pjsip_t38.c:207 t38_automatic_reject: Automatically rejecting T.38
request on channel ‘PJSIP/91-00000007’

=> Why does asterisk reject the switch / ReInvite to T.38 this time? It never even tried to send it to the ISP!

Thanks for any hint!

Regards, Michael

31 thoughts on - Asterisk 13.16 / Pjsip / T.38: Res_pjsip_t38.c:207 T38_automatic_reject: Automatically Rejecting T.38 Request On Channel ‘PJSIP/91-00000007’

  • Just a guess (without knowing about your network), but are the two ends points on public networks and visible to one another? If not the reinvite may be passing an internal (nat’ed) address to the other and the connection will fail…just a though

    —–Original Message—

  • t38modem -tt -o /var/log/t38modem.log –no-h323 -u 91 –sip-listen udp\$127.0.0.1:6060 –ptty +/dev/ttyT380,+/dev/ttyT381 –route
    ‘modem:.*=sip:@127.0.0.1:5061′ –route ‘sip:.*=modem:‘
    –sip-register 91@127.0.0.1:5061,password

    I tried it with a global IP (instead of 127.0.0.1) – same behavior.

    The point is, that the receiving part, which initiates the t.38 switch, doesn’t sent the switch to the ISP. It is blocked / ignored by asterisk at all – don’t know why it isn’t sent to the ISP.

    The extension is a normal pjsip extension with these additional options:

    t38_udptl : true t38_udptl_ec : redundancy t38_udptl_ipv6 : false t38_udptl_maxdatagram : 400
    t38_udptl_nat : no (or yes – doesn’t matter)

    The trunk looks exactly the same:

    t38_udptl : true t38_udptl_ec : redundancy t38_udptl_ipv6 : false t38_udptl_maxdatagram : 400
    t38_udptl_nat : no (or yes – doesn’t matter)

    Thanks, Michael

  • I’d suggest providing the console output and SIP traffic (pjsip set logger on) so we can see exactly what is going on.

  • [easybellPJSIP_FAX]
    type=endpoint transport=0.0.0.0-udp context=from-trunk disallow=all allow=alaw,ulaw aors

  • I plugged the provided configuration into an existing testsuite test quickly and things still worked as expected, so it’s something outside of that but nothing stands out in the debug log. I’d suggest filing an issue[1] with all the logs and such, it’ll allow whomever works on the issue to write a specific testsuite test and hopefully recreate it in a controlled environment.

    [1] https://issues.asterisk.org/jira

  • Do you have any idea where to start to look at? Adding additional output in the source code? Which functions could be interesting? I may add own debug code to see why things are happening as they happen here.

    Thanks, Michael

  • The logic for T.38 negotiation lives all in the res_pjsip_t38 module and the request to negotiate works using a control frame which is handled by the t38_interpret_parameters function. It’s up to that to initialize things and then request that a session refresh occurs (which sends the re-invite). That’d be the place to look.

  • I added a debug output at the beginning of the function to see if it’s ever been called.

    t38_interpret_parameters is never been called … .

    [2017-06-05 20:52:21] DEBUG[719]: res_pjsip_t38.c:772 create_outgoing_sdp_stream: Not creating outgoing SDP stream: T.38 not enabled
    [2017-06-05 20:52:22] DEBUG[719]: res_pjsip_t38.c:772 create_outgoing_sdp_stream: Not creating outgoing SDP stream: T.38 not enabled
    [2017-06-05 20:52:22] DEBUG[719]: res_pjsip_t38.c:768 create_outgoing_sdp_stream: Not creating outgoing SDP stream: T.38 not enabled
    [2017-06-05 20:52:23] DEBUG[719]: res_pjsip_t38.c:772 create_outgoing_sdp_stream: Not creating outgoing SDP stream: T.38 not enabled
    [2017-06-05 20:52:23] DEBUG[921]: res_pjsip_t38.c:772 create_outgoing_sdp_stream: Not creating outgoing SDP stream: T.38 not enabled
    [2017-06-05 20:52:24] DEBUG[719]: res_pjsip_t38.c:268 t38_initialize_session: UDPTL initialized on session for PJSIP/91-00000003
    [2017-06-05 20:52:24] DEBUG[719]: res_pjsip_t38.c:138 t38_change_state: T.38 state changed to ‘2’ from ‘0’ on channel ‘PJSIP/91-00000003’
    [2017-06-05 20:52:24] DEBUG[719]: res_pjsip_t38.c:696 defer_incoming_sdp_stream: Deferring incoming SDP stream on PJSIP/91-00000003 for peer re-invite
    [2017-06-05 20:52:29] DEBUG[719]: res_pjsip_t38.c:207 t38_automatic_reject: Automatically rejecting T.38 request on channel ‘PJSIP/91-00000003’
    [2017-06-05 20:52:29] DEBUG[719]: res_pjsip_t38.c:138 t38_change_state: T.38 state changed to ‘4’ from ‘2’ on channel ‘PJSIP/91-00000003’
    [2017-06-05 20:52:29] DEBUG[719]: res_pjsip_t38.c:721 negotiate_incoming_sdp_stream: Declining; T.38 state is rejected or declined
    [2017-06-05 20:52:29] DEBUG[719]: res_pjsip_t38.c:138 t38_change_state: T.38 state changed to ‘0’ from ‘4’ on channel ‘PJSIP/91-00000003’
    [2017-06-05 20:52:29] DEBUG[719]: res_pjsip_t38.c:772 create_outgoing_sdp_stream: Not creating outgoing SDP stream: T.38 not enabled

    Thanks, regards, Michael

  • That would likely mean that the frame is not getting sent (this also happens in that module) or that it is getting lost in the bridging framework. Digging into that is not something that can be expressed in general terms in email…

  • I did some further investigations and fixed a local problem. Now, asterisk is able to successfully activate T.38 – unfortunately just for very shot time because of a phantom package it receives!

    Let’s go into details:
    I’m starting at the point where asterisk / fax client receives the T.38
    reininvite from the server from the provider 195.185.37.60:5060 for the fax client (extension 91):

    <--- Received SIP request (918 bytes) from UDP:195.185.37.60:5060 --->
    INVITE sip:+4971511336089@42.21.35.43:5061 SIP/2.0
    Via: SIP/2.0/UDP 195.185.37.60;branch=z9hG4bKd8EHOaij;rport From: ;tag4E09F9-593D01CC00045378-134F4700
    To: ;tag

  • What was the local problem?

    PJSIP uses a dispatch model. The request is queued up, acted on, and then that’s it. The act of acting on it removes it from the queue. The only reason I’d expect to see it again is if there was a retransmission or something somehow requeued it up – but I don’t think we do that anywhere. Not quite sure why it would be happening…

  • Update of t38modem from 3.13 to 3.15

    That’s the *expected* behavior … . I rechecked again and again. All existing tcpdumps. The “resent” package isn’t part of any tcpdump
    (wireshark doesn’t show it) – and during tcpdump no package was dropped.

    But even if this package would have really been sent (as retransmission)
    – shouldn’t there be another response? T.38 has been successfully enabled before and the faxclient has already sent a valid 200 ok including complete SDP information to asterisk.

    All in all it looks really odd to me.

    Thanks, regards, Michael

  • Depends on how we handle that scenario. I don’t think we have any tests to cover it, so it’s entirely possible that we wouldn’t respond like that. Why it’s happening in the first place I still don’t know though, haven’t seen anything like it.

  • Do you have any idea where to check if acted packages are really removed? Is there a way to check the pjsip-queue? Where could I start to look at? How does asterisk get them from the queue? And how does pjsip know that asterisk has processed them?

    Thanks, Michael

  • The distributor is in res/res_pjsip/pjsip_distributor.c, the distributor function being the entry point. That function returning PJ_TRUE
    indicates to PJSIP that it has been handled and no subsequent modules should be called by that running thread. The distributor itself, though, ends up executing things further in a worker thread using the distribute function.

  • To be more detailed – PJSIP maintains no queue, a message comes in from a transport and is given to modules until one says it has handled the message. We place our distributor close to the transport and it puts the message into a queue for handling in Asterisk ensuring serialization as appropriate, returning that it has handled the message so no other modules handle it at that time. Once the message is handled from the queue it picks back up invoking modules at the point where the original thread left off. This ensures messages are handled as quickly as possible without blocking the transport but also provides guarantees on ordering and simultaneous execution. (Two messages for the same call will be handled in order, one at a time).

  • I’m running Asterisk 11 on my faxserver so not using pjsip but chan_sip. But IIRC I had problems with asterisk-11/t38modem-2.0.0/hylafax if the upstream side started the t38 reINVITE on sending a fax. My hylafax config.ttyT38* contains the AT F command to initiale t38 on the t38modem side for outgoing calls. For incoming t38modem also starts the reINVITE
    but there is no parameter to influence this in my configs.

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

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

  • I forgot to mention the main thing: I initially used *two* trunks (and one number), one “normal” trunk and another trunk_fax additionally enabling udptl. Outbound not a problem – but inbound used the normal trunk – this can’t work. Merging both trunks to one trunk has been the solution, which isn’t a problem with udptl, because it’s initially handled by the extension (t38modem). That’s why I came across line option for the other provider I’m using and which wasn’t that easy to use with FreePBX, because it is not yet directly supported and pjsip.registration_custom_post.conf unfortunately doesn’t work (I’m not the only one experiencing this problem). Therefore I’m using now a trick which works especially for the registration problem within FreePBX as long as it isn’t supported natively.

    Thanks, Michael

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

    Thanks, Michael

  • 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

  • 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 (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 (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 (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: ;tagrF0675F-5942027B00075955-FB9F9700
    To: ;tag

  • 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 (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: ;tag>D81E00-5942C49A000569DF-FBAFA700
    To: ;tag449ea7e-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:

    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 (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 (rdata0x311ab58)
    [2017-06-15 19:32:12] DEBUG[26218]: res_pjsip/pjsip_distributor.c:446 distributor: PJ_TRUE 3 – ready Request msg INVITE/cseq (rdata0x312eb18)
    [2017-06-15 19:32:12] DEBUG[26218]: pjproject:0 : sip_endpoint.c .rdata not handled: Request msg INVITE/cseq (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 (rdata0x311ab58)
    [2017-06-15 19:32:12] DEBUG[26218]: pjproject:0 : sip_endpoint.c Distributing rdata to modules: Request msg INVITE/cseq (rdata0x311ab58)
    [2017-06-15 19:32:12] DEBUG[26218]: pjproject:0 : dlg0x30bc228 .Received Request msg INVITE/cseq (rdata0x311ab58)
    [2017-06-15 19:32:12] DEBUG[26218]: pjproject:0 : tsx0x30bb2e8 …Transaction created for Request msg INVITE/cseq (rdata0x311ab58)
    [2017-06-15 19:32:12] DEBUG[26218]: pjproject:0 : tsx0x30bb2e8 ..Incoming Request msg INVITE/cseq (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 (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 (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 (tdta0x3104d28)
    [2017-06-15 19:32:12] DEBUG[26218]: pjproject:0 : dlg0x30bc228 …….Sending Response msg 200/INVITE/cseq (tdta0x3104d28)
    [2017-06-15 19:32:12] DEBUG[26218]: pjproject:0 : tsx0x30bb2e8 …….Sending Response msg 200/INVITE/cseq (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;rportP60;received5.185.37.60;branch=z9hG4bKVWp6vazu Call-ID: dbe2ff49-aba5-42d5-9a22-1ea9a1bf89d8
    From: ;tag>D81E00-5942C49A000569DF-FBAFA700
    To: ;tag449ea7e-91e3-4f39-ae10-ba8a79020e17
    CSeq: 10 INVITE
    Contact:
    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

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

  • Am 16.06.2017 um 11:12 schrieb Joshua Colp:

    t38modem and asterisk are using

    m=image 35622 udptl t38
    ^^^^^

    Provider uses

    m=image 35622 UDPTL t38
    ^^^^^

    Could this be a problem? If I’m sending internal only, it’s always lowercase.

  • Looking at the tests we have we only use ‘udptl’ as the transport. Without diving deep into the SDP negotiator it is possible that it gets upset at that, as we would only produce ‘udptl’. If the SDP negotiator in PJSIP is case sensitive then you’d get a declined stream like you see. Looking at the T.38 examples from the ITU doc also shows it in lowercase, so uppercase is probably not commonly used.

  • Nope, I don’t really have anything to add to try to make it communicate. T.38 support over all can be very problematic depending on the endpoint.

  • For opal, the sip patch (src/t38/sipt38.cxx) is enough – the other two patches aren’t necessary. It’s only a SIP-problem.

    Regards, Michael