T.38 Fax passthrough via using PJSIP extensions

jdast · November 13, 2017, 9:06am

Hi, I would very much appreciate some assistance if you can please.

I am trying to test T.38 passthrough with Asterisk 15.1.0 (distributed with FreePBX 14) using two Voip Fax endpoints. The clients that I am using are this product: http://www.t38faxvoip.com/fsp/ (Fax Voip Windows Fax Service Provider).

However, I am having troubles with the receiving client having its T.38 Reinvites being rejected by asterisk.

Here’s the packet no 22 from the receiver trace (see below).

Session Description Protocol
    Session Description Protocol Version (v): 0
    Owner/Creator, Session Id (o): - 1510559297 2 IN IP4 192.168.90.15
    Session Name (s): FaxVoip FSP 2.2.1
    Connection Information (c): IN IP4 192.168.90.15
    Time Description, active time (t): 0 0
    Media Description, name and address (m): image 5022 udptl t38
    Media Attribute (a): sendrecv
    Media Attribute (a): T38FaxVersion:0
    Media Attribute (a): T38FaxRateManagement:transferredTCF
    Media Attribute (a): T38FaxMaxBuffer:2000
    Media Attribute (a): T38FaxMaxDatagram:1400
    Media Attribute (a): T38FaxUdpEC:t38UDPRedundancy
    Media Attribute (a): T38MaxBitRate:14400

In response at packet no 28 on receiver (from asterisk) is:

Session Initiation Protocol (488)
Status-Line: SIP/2.0 488 Not Acceptable Here
Message Header

Unfortunately this forum doesn’t allow me to attach the packet capture traces to show full context, so I will just post as text exported from wireshark.

The sender packet trace shown following:


No.     Time           Source                Destination           Protocol Length Info
      1 0.000000       192.168.90.131        192.168.2.92          SIP      522    Request: OPTIONS sip:703@192.168.2.92:54106;rinstance=6c1278869d03f439 | 
      2 0.014320       192.168.2.92          192.168.90.131        SIP      647    Status: 200 OK | 
      3 4.918660       192.168.2.92          192.168.90.131        UDP      46     54106 → 5060 Len=4
      4 20.708163      192.168.2.92          192.168.90.131        SIP/SDP  975    Request: INVITE sip:765@192.168.90.131 | 
      5 20.711369      192.168.90.131        192.168.2.92          SIP      633    Status: 401 Unauthorized | 
      6 20.712473      192.168.2.92          192.168.90.131        SIP      451    Request: ACK sip:765@192.168.90.131 | 
      7 20.713754      192.168.2.92          192.168.90.131        SIP/SDP  1271   Request: INVITE sip:765@192.168.90.131 | 
      8 20.717229      192.168.90.131        192.168.2.92          SIP      432    Status: 100 Trying | 
      9 21.409697      192.168.90.131        192.168.2.92          SIP      674    Status: 180 Ringing | 
     10 21.427231      192.168.90.131        192.168.2.92          SIP      674    Status: 180 Ringing | 
     11 21.714250      192.168.90.131        192.168.2.92          SIP/SDP  1007   Status: 200 OK | 
     12 21.724623      192.168.2.92          192.168.90.131        SIP      794    Request: ACK sip:192.168.90.131:5060 | 
     13 21.731808      192.168.90.131        192.168.2.92          SIP/SDP  1046   Request: INVITE sip:764@192.168.2.92:5069, in-dialog | 
     14 21.733323      192.168.2.92          192.168.90.131        SIP      449    Status: 100 Trying | 
     15 21.736443      192.168.2.92          192.168.90.131        RTP      214    PT=ITU-T G.711 PCMU, SSRC=0xFCF5D408, Seq=32268, Time=0
     16 21.737826      192.168.2.92          192.168.90.131        SIP/SDP  1288   Request: INVITE sip:192.168.90.131:5060, in-dialog | 
     17 21.739013      192.168.2.92          192.168.90.131        SIP      458    Status: 491 Request Pending | 
     18 21.747916      192.168.90.131        192.168.2.92          SIP      505    Status: 491 Another INVITE transaction in progress | 
     19 21.748911      192.168.2.92          192.168.90.131        SIP      742    Request: ACK sip:192.168.90.131:5060 | 
     20 21.749688      192.168.90.131        192.168.2.92          SIP      491    Request: ACK sip:764@192.168.2.92:5069 | 
     21 21.755807      192.168.2.92          192.168.90.131        RTP      214    PT=ITU-T G.711 PCMU, SSRC=0xFCF5D408, Seq=32269, Time=160
     22 21.776123      192.168.2.92          192.168.90.131        RTP      214    PT=ITU-T G.711 PCMU, SSRC=0xFCF5D408, Seq=32270, Time=320
     23 21.796116      192.168.2.92          192.168.90.131        RTP      214    PT=ITU-T G.711 PCMU, SSRC=0xFCF5D408, Seq=32271, Time=480
     24 21.815312      192.168.90.131        192.168.2.92          RTP      214    PT=ITU-T G.711 PCMU, SSRC=0x32E62899, Seq=23120, Time=0
...
     34 21.915776      192.168.2.92          192.168.90.131        RTP      214    PT=ITU-T G.711 PCMU, SSRC=0xFCF5D408, Seq=32277, Time=1440
     35 21.924522      192.168.90.131        192.168.2.92          SIP/SDP  1066   Request: INVITE sip:764@192.168.2.92:5069, in-dialog | 
     36 21.925849      192.168.2.92          192.168.90.131        SIP      449    Status: 100 Trying | 
     37 21.942354      192.168.2.92          192.168.90.131        T.38     48     UDP: UDPTLPacket Seq=00000  t30ind: no-signal
     38 21.947057      192.168.2.92          192.168.90.131        SIP/SDP  971    Status: 200 OK | 
     39 22.142392      192.168.2.92          192.168.90.131        T.38     50     UDP: UDPTLPacket Seq=00001  t30ind: cng
     40 22.192808      192.168.2.92          192.168.90.131        T.38     50     UDP: UDPTLPacket Seq=00001  t30ind: cng
     41 22.263277      192.168.2.92          192.168.90.131        T.38     50     UDP: UDPTLPacket Seq=00001  t30ind: cng
     42 22.313822      192.168.2.92          192.168.90.131        T.38     50     UDP: UDPTLPacket Seq=00001  t30ind: cng
     43 22.364012      192.168.2.92          192.168.90.131        T.38     50     UDP: UDPTLPacket Seq=00001  t30ind: cng
     44 22.415204      192.168.2.92          192.168.90.131        T.38     48     UDP: UDPTLPacket Seq=00001  t30ind: cng
     45 22.447715      192.168.2.92          192.168.90.131        SIP/SDP  970    Status: 200 OK | 
     46 23.448397      192.168.2.92          192.168.90.131        SIP/SDP  970    Status: 200 OK | 
     47 25.460571      192.168.2.92          192.168.90.131        SIP/SDP  970    Status: 200 OK | 
     48 26.738044      192.168.90.131        192.168.2.92          RTCP     142    Sender Report   Source description   
     49 29.459377      192.168.2.92          192.168.90.131        SIP/SDP  970    Status: 200 OK | 
     50 31.738192      192.168.90.131        192.168.2.92          RTCP     122    Receiver Report   Source description   
     51 33.459086      192.168.2.92          192.168.90.131        SIP/SDP  970    Status: 200 OK | 
     52 34.922109      192.168.2.92          192.168.90.131        UDP      46     54106 → 5060 Len=4
     53 36.738480      192.168.90.131        192.168.2.92          RTCP     122    Receiver Report   Source description   
     54 37.457872      192.168.2.92          192.168.90.131        SIP/SDP  970    Status: 200 OK | 
     55 39.592796      192.168.2.92          192.168.90.131        SIP      901    Request: REGISTER sip:192.168.90.131  (1 binding) | 
     56 39.596166      192.168.90.131        192.168.2.92          SIP      634    Status: 401 Unauthorized | 
     57 39.600421      192.168.2.92          192.168.90.131        SIP      901    Request: REGISTER sip:192.168.90.131  (1 binding) | 
     58 39.604890      192.168.90.131        192.168.2.92          SIP      567    Status: 200 OK  (1 binding) | 
     59 41.458583      192.168.2.92          192.168.90.131        SIP/SDP  970    Status: 200 OK | 
     60 41.738351      192.168.90.131        192.168.2.92          RTCP     122    Receiver Report   Source description   
     61 45.457570      192.168.2.92          192.168.90.131        SIP/SDP  970    Status: 200 OK | 
     62 46.738726      192.168.90.131        192.168.2.92          RTCP     122    Receiver Report   Source description   
     63 49.457406      192.168.2.92          192.168.90.131        SIP/SDP  970    Status: 200 OK | 
     64 50.785019      192.168.90.131        192.168.2.92          SIP      467    Request: OPTIONS sip:764@192.168.2.92:5069 | 
     65 50.789902      192.168.2.92          192.168.90.131        SIP      475    Status: 200 OK | 
     66 51.739880      192.168.90.131        192.168.2.92          RTCP     122    Receiver Report   Source description   
     67 53.456803      192.168.2.92          192.168.90.131        SIP/SDP  970    Status: 200 OK | 
     68 53.941521      192.168.2.92          192.168.90.131        SIP      857    Request: BYE sip:192.168.90.131:5060 | 
     69 53.945587      192.168.90.131        192.168.2.92          SIP      466    Status: 200 OK | 
     70 56.738774      192.168.90.131        192.168.2.92          RTCP     122    Receiver Report   Source description   
     71 59.999274      192.168.90.131        192.168.2.92          SIP      522    Request: OPTIONS sip:703@192.168.2.92:54106;rinstance=6c1278869d03f439 |

And the receiver packet capture in this image:


No.     Time           Source                Destination           Protocol Length Info
      1 0.000000       192.168.90.131        192.168.90.15         SIP/SDP  1102   Request: INVITE sip:765@192.168.90.15:5069 | 
      2 0.001203       192.168.90.15         192.168.90.131        SIP      384    Status: 100 Trying | 
      3 0.011687       192.168.90.15         192.168.90.131        SIP      675    Status: 180 Ringing | 
      4 0.012359       192.168.90.131        192.168.90.15         SIP      502    Request: PRACK sip:765@192.168.90.15:5069 | 
      5 0.013121       192.168.90.15         192.168.90.131        SIP      391    Status: 200 OK | 
      6 0.297451       192.168.90.15         192.168.90.131        SIP/SDP  897    Status: 200 OK | 
      7 0.298324       192.168.90.131        192.168.90.15         SIP      468    Request: ACK sip:765@192.168.90.15:5069 | 
      8 0.324468       192.168.90.131        192.168.90.15         RTP      214    PT=ITU-T G.711 PCMU, SSRC=0x7B3F4121, Seq=26044, Time=0
      9 0.343582       192.168.90.131        192.168.90.15         RTP      214    PT=ITU-T G.711 PCMU, SSRC=0x7B3F4121, Seq=26045, Time=160
...
	  21 0.484076       192.168.90.131        192.168.90.15         RTP      214    PT=ITU-T G.711 PCMU, SSRC=0x7B3F4121, Seq=26052, Time=1280
     22 0.505251       192.168.90.15         192.168.90.131        SIP/SDP  993    Request: INVITE sip:asterisk@192.168.90.131:5060, in-dialog | 
     23 0.505317       192.168.90.131        192.168.90.15         T.38     214    UDP: UDPTLPacket Seq=32768  data:v27-4800:[UNKNOWN PER: too long integer(per_normally_small_nonnegative_whole_number)][Malformed Packet]
     24 1.006349       192.168.90.15         192.168.90.131        SIP/SDP  993    Request: INVITE sip:asterisk@192.168.90.131:5060, in-dialog | 
     25 2.007111       192.168.90.15         192.168.90.131        SIP/SDP  993    Request: INVITE sip:asterisk@192.168.90.131:5060, in-dialog | 
     26 4.007732       192.168.90.15         192.168.90.131        SIP/SDP  993    Request: INVITE sip:asterisk@192.168.90.131:5060, in-dialog | 
     27 5.323627       192.168.90.131        192.168.90.15         RTCP     142    Sender Report   Source description   
     28 5.506452       192.168.90.131        192.168.90.15         SIP      741    Status: 488 Not Acceptable Here | 
     29 5.507823       192.168.90.15         192.168.90.131        SIP      430    Request: ACK sip:asterisk@192.168.90.131:5060 | 
     30 5.514103       192.168.90.15         192.168.90.131        SIP/SDP  926    Request: INVITE sip:asterisk@192.168.90.131:5060, in-dialog | 
     31 6.013892       192.168.90.15         192.168.90.131        SIP/SDP  926    Request: INVITE sip:asterisk@192.168.90.131:5060, in-dialog | 
     32 7.039049       192.168.90.15         192.168.90.131        SIP/SDP  926    Request: INVITE sip:asterisk@192.168.90.131:5060, in-dialog | 
     33 9.038782       192.168.90.15         192.168.90.131        SIP/SDP  926    Request: INVITE sip:asterisk@192.168.90.131:5060, in-dialog | 
     34 10.323800      192.168.90.131        192.168.90.15         RTCP     122    Receiver Report   Source description   
     35 10.515670      192.168.90.131        192.168.90.15         SIP      741    Status: 488 Not Acceptable Here | 
     36 10.517083      192.168.90.15         192.168.90.131        SIP      430    Request: ACK sip:asterisk@192.168.90.131:5060 | 
     37 15.323931      192.168.90.131        192.168.90.15         RTCP     122    Receiver Report   Source description   
     38 19.900090      192.168.90.15         192.168.90.131        SIP      932    Request: REGISTER sip:192.168.90.131  (1 binding) | 
     39 19.900906      192.168.90.131        192.168.90.15         SIP      628    Status: 401 Unauthorized | 
     40 19.902874      192.168.90.15         192.168.90.131        SIP      932    Request: REGISTER sip:192.168.90.131  (1 binding) | 
     41 19.904930      192.168.90.131        192.168.90.15         SIP      562    Status: 200 OK  (1 binding) | 
     42 20.324075      192.168.90.131        192.168.90.15         RTCP     122    Receiver Report   Source description   
     43 25.324189      192.168.90.131        192.168.90.15         RTCP     122    Receiver Report   Source description   
     44 25.484609      192.168.90.131        192.168.90.15         SIP      468    Request: OPTIONS sip:765@192.168.90.15:5069 | 
     45 25.485935      192.168.90.15         192.168.90.131        SIP      476    Status: 200 OK | 
     46 30.324322      192.168.90.131        192.168.90.15         RTCP     122    Receiver Report   Source description   
     47 32.532417      192.168.90.131        192.168.90.15         SIP      492    Request: BYE sip:765@192.168.90.15:5069 | 
     48 32.533021      192.168.90.15         192.168.90.131        SIP      389    Status: 200 OK |

For interpreting the packet captures:
192.168.2.92 is the sender T.38 fax client
192.168.90.131 is the asterisk server
192.168.90.15 is the receiver T.38 fax client

The receiving fax client is configured to send a T.38 reinvite once it receives the CNG (Calling Fax Tone).

Note: Although I am using FreePBX I am directly working on the asterisk config (as I have shut down the amportal so it is no longer in control of the config files). (The reason I did this is that FreePBX provides no access (that I can see) to modify the t38_* attributes for endpoints although it does for trunks via its web UI - I think that is a separate matter).

Here is the relavant endpoint fragments included into pjsip.conf:

[765]
type=endpoint
aors=765
auth=765-auth
allow=ulaw,alaw,gsm,g726,g722
context=from-internal
callerid=765 <765>
dtmf_mode=rfc4733
aggregate_mwi=yes
use_avpf=no
rtcp_mux=no
ice_support=no
media_use_received_transport=no
trust_id_inbound=yes
timers=yes
media_encryption_optimistic=no
send_pai=yes
rtp_symmetric=yes
rewrite_contact=yes
force_rport=yes
language=en
t38_udptl=yes
t38_udptl_ec=redundancy
fax_detect=no
t38_udptl_nat=yes

[764]
type=endpoint
aors=764
auth=764-auth
allow=ulaw,alaw,gsm,g726,g722
context=from-internal
callerid=764 <764>
dtmf_mode=rfc4733
aggregate_mwi=yes
use_avpf=no
rtcp_mux=no
ice_support=no
media_use_received_transport=no
trust_id_inbound=yes
timers=yes
media_encryption_optimistic=no
send_pai=yes
rtp_symmetric=yes
rewrite_contact=yes
force_rport=yes
language=en
t38_udptl=yes
t38_udptl_ec=redundancy
fax_detect=no
t38_udptl_nat=yes

Here’s the output in a text file: “pjsip show endpoint config.txt”. (Ok, since I’m a new user the site will not allow me to upload the attachment)

Anyway, there it shows the values have been successfully loaded.
t38_udptl : true
t38_udptl_ec : redundancy
t38_udptl_ipv6 : false
t38_udptl_maxdatagram : 0
t38_udptl_nat : true

In udptl.conf I have the following:
[general]
udptlstart=16000
udptlend=65000
T38FaxUdpEC=t38UDPRedundancy
t38pt_udptl=yes

The following shows that the above udptl.conf is completely ignored. I do not know if this is critical to passthrough via PJSIP?

freepbx*CLI> udptl show config
UDPTL Global options

udptlstart: 4000
udptlend: 4999
udptlfecentries: 0
udptlfecspan: 0
use_even_ports: No
udptlchecksums: Yes

I found this in udptl.c (which is still the same on current master):

Asterisk supports T.38 fax passthrough, origination and termination. It does
not support gateway operation. The only channel driver that supports T.38 at
this time is chan_sip.

I do not know whether to believe this since it may be outdated? There are instructions for using PJSIP with T.38 and asterisk here (in addition to chan_sip):
http://support.t38fax.com/support/solutions/articles/19000008280-asterisk

Anyway, there are a few issues here and I must say I’ve been looking at this all for some days and I’m at the end and really need some help please.

Thanks

Jared

jcolp · November 13, 2017, 11:22am

You would need to add “debug” to the log output in logger.conf and use the “core set debug” CLI command to bump up the debug level to a high amount, such as 9. Once done then the T.38 support will tell you what it is doing in a bit more detail.

As for the comment in udptl.c - it is old. The chan_pjsip module does support T.38, and there is a T.38 gateway dialplan function available as well.

jdast · November 13, 2017, 11:38pm

Thanks for the advice.

I have made a debug log and greped it with regex “(pjsip_t38)|(pjsip_session)” to fit here, hopefully with enough info.

[root@freepbx ~]# less ~/full | grep -P "(pjsip_t38)|(pjsip_session)"
DEBUG[1586] res_pjsip_session.c: Method is INVITE, Response is 100 Trying
DEBUG[1586] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE
DEBUG[1586] res_pjsip_session.c: The state change pertains to the endpoint '764()'
DEBUG[1586] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f2048077df8)
DEBUG[1586] res_pjsip_session.c: There is no transaction involved in this state change
DEBUG[1586] res_pjsip_session.c: The current inv state is INCOMING
DEBUG[1586] res_pjsip_session.c: Source of transaction state change is TX_MSG
DEBUG[1586] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
DEBUG[1586] res_pjsip_session.c: The state change pertains to the endpoint '764()'
DEBUG[1586] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f2048077df8)
DEBUG[1586] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7f2048077df8
DEBUG[1586] res_pjsip_session.c: The current transaction state is Proceeding
DEBUG[1586] res_pjsip_session.c: The transaction state change event is TX_MSG
DEBUG[1586] res_pjsip_session.c: The current inv state is INCOMING
DEBUG[1586] res_pjsip_session.c: Negotiating incoming SDP media stream 'audio' using audio SDP handler
DEBUG[1586] res_pjsip_session.c: Media stream 'audio' handled by audio
DEBUG[1586] res_pjsip_session.c: Method is INVITE
DEBUG[3550] res_pjsip_session.c: Method is INVITE, Response is 180 Ringing
DEBUG[3550] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE
DEBUG[3550] res_pjsip_session.c: The state change pertains to the endpoint '764(PJSIP/764-00000006)'
DEBUG[3550] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f2048077df8)
DEBUG[3550] res_pjsip_session.c: There is no transaction involved in this state change
DEBUG[3550] res_pjsip_session.c: The current inv state is EARLY
DEBUG[3550] res_pjsip_session.c: Source of transaction state change is TX_MSG
DEBUG[3550] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
DEBUG[3550] res_pjsip_session.c: The state change pertains to the endpoint '764(PJSIP/764-00000006)'
DEBUG[3550] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f2048077df8)
DEBUG[3550] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7f2048077df8
DEBUG[3550] res_pjsip_session.c: The current transaction state is Proceeding
DEBUG[3550] res_pjsip_session.c: The transaction state change event is TX_MSG
DEBUG[3550] res_pjsip_session.c: The current inv state is EARLY
DEBUG[1586] res_pjsip_session.c: Method is INVITE
DEBUG[1586] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE
DEBUG[1586] res_pjsip_session.c: The state change pertains to the endpoint '765(PJSIP/765-00000007)'
DEBUG[1586] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f204803bf78)
DEBUG[1586] res_pjsip_session.c: There is no transaction involved in this state change
DEBUG[1586] res_pjsip_session.c: The current inv state is CALLING
DEBUG[1586] res_pjsip_session.c: Source of transaction state change is TX_MSG
DEBUG[1586] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
DEBUG[1586] res_pjsip_session.c: The state change pertains to the endpoint '765(PJSIP/765-00000007)'
DEBUG[1586] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f204803bf78)
DEBUG[1586] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7f204803bf78
DEBUG[1586] res_pjsip_session.c: The current transaction state is Calling
DEBUG[1586] res_pjsip_session.c: The transaction state change event is TX_MSG
DEBUG[1586] res_pjsip_session.c: The current inv state is CALLING
DEBUG[1586] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
DEBUG[1586] res_pjsip_session.c: The state change pertains to the endpoint '765(PJSIP/765-00000007)'
DEBUG[1586] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f204803bf78)
DEBUG[1586] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7f204803bf78
DEBUG[1586] res_pjsip_session.c: The current transaction state is Proceeding
DEBUG[1586] res_pjsip_session.c: The transaction state change event is RX_MSG
DEBUG[1586] res_pjsip_session.c: The current inv state is CALLING
DEBUG[1586] res_pjsip_session.c: Received response
DEBUG[1586] res_pjsip_session.c: Response is 100 Trying
DEBUG[1586] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE
DEBUG[1586] res_pjsip_session.c: The state change pertains to the endpoint '765(PJSIP/765-00000007)'
DEBUG[1586] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f204803bf78)
DEBUG[1586] res_pjsip_session.c: There is no transaction involved in this state change
DEBUG[1586] res_pjsip_session.c: The current inv state is EARLY
DEBUG[1586] res_pjsip_session.c: Source of transaction state change is RX_MSG
DEBUG[1586] res_pjsip_session.c: Received response
DEBUG[1586] res_pjsip_session.c: Response is 180 Ringing
DEBUG[1586] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
DEBUG[1586] res_pjsip_session.c: The state change pertains to the endpoint '765(PJSIP/765-00000007)'
DEBUG[1586] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f204803bf78)
DEBUG[1586] res_pjsip_session.c: The UAC PRACK transaction involved in this state change is 0x7f204801b848
DEBUG[1586] res_pjsip_session.c: The current transaction state is Calling
DEBUG[1586] res_pjsip_session.c: The transaction state change event is TX_MSG
DEBUG[1586] res_pjsip_session.c: The current inv state is EARLY
DEBUG[1586] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
DEBUG[1586] res_pjsip_session.c: The state change pertains to the endpoint '765(PJSIP/765-00000007)'
DEBUG[1586] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f204803bf78)
DEBUG[1586] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7f204803bf78
DEBUG[1586] res_pjsip_session.c: The current transaction state is Proceeding
DEBUG[1586] res_pjsip_session.c: The transaction state change event is RX_MSG
DEBUG[1586] res_pjsip_session.c: The current inv state is EARLY
DEBUG[1586] res_pjsip_session.c: Received response
DEBUG[1586] res_pjsip_session.c: Response is 180 Ringing
DEBUG[1586] res_pjsip_session.c: Method is INVITE, Response is 180 Ringing
DEBUG[1586] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE
DEBUG[1586] res_pjsip_session.c: The state change pertains to the endpoint '764(PJSIP/764-00000006)'
DEBUG[1586] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f2048077df8)
DEBUG[1586] res_pjsip_session.c: There is no transaction involved in this state change
DEBUG[1586] res_pjsip_session.c: The current inv state is EARLY
DEBUG[1586] res_pjsip_session.c: Source of transaction state change is TX_MSG
DEBUG[1586] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
DEBUG[1586] res_pjsip_session.c: The state change pertains to the endpoint '764(PJSIP/764-00000006)'
DEBUG[1586] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f2048077df8)
DEBUG[1586] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7f2048077df8
DEBUG[1586] res_pjsip_session.c: The current transaction state is Proceeding
DEBUG[1586] res_pjsip_session.c: The transaction state change event is TX_MSG
DEBUG[1586] res_pjsip_session.c: The current inv state is EARLY
DEBUG[1586] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
DEBUG[1586] res_pjsip_session.c: The state change pertains to the endpoint '765(PJSIP/765-00000007)'
DEBUG[1586] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f204803bf78)
DEBUG[1586] res_pjsip_session.c: The UAC PRACK transaction involved in this state change is 0x7f204801b848
DEBUG[1586] res_pjsip_session.c: The current transaction state is Completed
DEBUG[1586] res_pjsip_session.c: The transaction state change event is RX_MSG
DEBUG[1586] res_pjsip_session.c: The current inv state is EARLY
DEBUG[1586] res_pjsip_session.c: Received response
DEBUG[1586] res_pjsip_session.c: Response is 200 OK
DEBUG[1586] res_pjsip_session.c: PRACK received final response code 200
DEBUG[1586] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE
DEBUG[1586] res_pjsip_session.c: The state change pertains to the endpoint '765(PJSIP/765-00000007)'
DEBUG[1586] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f204803bf78)
DEBUG[1586] res_pjsip_session.c: There is no transaction involved in this state change
DEBUG[1586] res_pjsip_session.c: The current inv state is CONNECTING
DEBUG[1586] res_pjsip_session.c: Source of transaction state change is RX_MSG
DEBUG[1586] res_pjsip_session.c: Received response
DEBUG[1586] res_pjsip_session.c: Response is 200 OK
DEBUG[1586] res_pjsip_session.c: Applying negotiated SDP media stream 'audio' using audio SDP handler
DEBUG[1586] res_pjsip_session.c: Applied negotiated SDP media stream 'audio' using audio SDP handler
DEBUG[1586] res_pjsip_session.c: Function session_inv_on_state_changed called on event TX_MSG
DEBUG[1586] res_pjsip_session.c: The state change pertains to the endpoint '765(PJSIP/765-00000007)'
DEBUG[1586] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f204803bf78)
DEBUG[1586] res_pjsip_session.c: There is no transaction involved in this state change
DEBUG[1586] res_pjsip_session.c: The current inv state is CONFIRMED
DEBUG[1586] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
DEBUG[1586] res_pjsip_session.c: The state change pertains to the endpoint '765(PJSIP/765-00000007)'
DEBUG[1586] res_pjsip_session.c: The inv session does NOT have an invite_tsx
DEBUG[1586] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7f204803bf78
DEBUG[1586] res_pjsip_session.c: The current transaction state is Terminated
DEBUG[1586] res_pjsip_session.c: The transaction state change event is RX_MSG
DEBUG[1586] res_pjsip_session.c: The current inv state is CONFIRMED
DEBUG[1586] res_pjsip_session.c: Received response
DEBUG[1586] res_pjsip_session.c: Response is 200 OK
DEBUG[1586] res_pjsip_session.c: Applying negotiated SDP media stream 'audio' using audio SDP handler
DEBUG[1586] res_pjsip_session.c: Applied negotiated SDP media stream 'audio' using audio SDP handler
DEBUG[1586] res_pjsip_session.c: Method is INVITE, Response is 200 OK
DEBUG[1586] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE
DEBUG[1586] res_pjsip_session.c: The state change pertains to the endpoint '764(PJSIP/764-00000006)'
DEBUG[1586] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f2048077df8)
DEBUG[1586] res_pjsip_session.c: There is no transaction involved in this state change
DEBUG[1586] res_pjsip_session.c: The current inv state is CONNECTING
DEBUG[1586] res_pjsip_session.c: Source of transaction state change is TX_MSG
DEBUG[1586] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
DEBUG[1586] res_pjsip_session.c: The state change pertains to the endpoint '764(PJSIP/764-00000006)'
DEBUG[1586] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f2048077df8)
DEBUG[1586] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7f2048077df8
DEBUG[1586] res_pjsip_session.c: The current transaction state is Completed
DEBUG[1586] res_pjsip_session.c: The transaction state change event is TX_MSG
DEBUG[1586] res_pjsip_session.c: The current inv state is CONNECTING
DEBUG[1586] res_pjsip_session.c: Delay sending reinvite to 764 because of outstanding transaction...
DEBUG[1586] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
DEBUG[1586] res_pjsip_session.c: The state change pertains to the endpoint '764(PJSIP/764-00000006)'
DEBUG[1586] res_pjsip_session.c: The inv session does NOT have an invite_tsx
DEBUG[1586] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7f2048077df8
DEBUG[1586] res_pjsip_session.c: The current transaction state is Terminated
DEBUG[1586] res_pjsip_session.c: The transaction state change event is USER
DEBUG[1586] res_pjsip_session.c: The current inv state is CONNECTING
DEBUG[1586] res_pjsip_session.c: Endpoint '764(PJSIP/764-00000006)' INVITE delay check. tsx-state:Terminated
DEBUG[1586] res_pjsip_session.c: Function session_inv_on_state_changed called on event RX_MSG
DEBUG[1586] res_pjsip_session.c: The state change pertains to the endpoint '764(PJSIP/764-00000006)'
DEBUG[1586] res_pjsip_session.c: The inv session does NOT have an invite_tsx
DEBUG[1586] res_pjsip_session.c: There is no transaction involved in this state change
DEBUG[1586] res_pjsip_session.c: The current inv state is CONFIRMED
DEBUG[1586] res_pjsip_session.c: Received request
DEBUG[1586] res_pjsip_session.c: Method is ACK
DEBUG[1586] res_pjsip_session.c: Endpoint '764(PJSIP/764-00000006)' sending delayed INVITE request.
DEBUG[1586] res_pjsip_session.c: Sending session refresh SDP via re-INVITE to 764
DEBUG[1586] res_pjsip_session.c: Method is INVITE
DEBUG[1586] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
DEBUG[1586] res_pjsip_session.c: The state change pertains to the endpoint '764(PJSIP/764-00000006)'
DEBUG[1586] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f204803bf78)
DEBUG[1586] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7f204803bf78
DEBUG[1586] res_pjsip_session.c: The current transaction state is Calling
DEBUG[1586] res_pjsip_session.c: The transaction state change event is TX_MSG
DEBUG[1586] res_pjsip_session.c: The current inv state is CONFIRMED
DEBUG[1586] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
DEBUG[1586] res_pjsip_session.c: The state change pertains to the endpoint '764(PJSIP/764-00000006)'
DEBUG[1586] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f204803bf78)
DEBUG[1586] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7f204803bf78
DEBUG[1586] res_pjsip_session.c: The current transaction state is Proceeding
DEBUG[1586] res_pjsip_session.c: The transaction state change event is RX_MSG
DEBUG[1586] res_pjsip_session.c: The current inv state is CONFIRMED
DEBUG[1586] res_pjsip_session.c: Received response
DEBUG[1586] res_pjsip_session.c: Response is 100 Trying
DEBUG[1586] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
DEBUG[1586] res_pjsip_session.c: The state change pertains to the endpoint '764(PJSIP/764-00000006)'
DEBUG[1586] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f204803bf78)
DEBUG[1586] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7f2048077df8
DEBUG[1586] res_pjsip_session.c: The current transaction state is Completed
DEBUG[1586] res_pjsip_session.c: The transaction state change event is TX_MSG
DEBUG[1586] res_pjsip_session.c: The current inv state is CONFIRMED
DEBUG[1586] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
DEBUG[1586] res_pjsip_session.c: The state change pertains to the endpoint '764(PJSIP/764-00000006)'
DEBUG[1586] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f204803bf78)
DEBUG[1586] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7f2048077df8
DEBUG[1586] res_pjsip_session.c: The current transaction state is Completed
DEBUG[1586] res_pjsip_session.c: The transaction state change event is RX_MSG
DEBUG[1586] res_pjsip_session.c: The current inv state is CONFIRMED
DEBUG[1586] res_pjsip_session.c: Received request
DEBUG[1586] res_pjsip_session.c: Method is INVITE
DEBUG[1586] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
DEBUG[1586] res_pjsip_session.c: The state change pertains to the endpoint '764(PJSIP/764-00000006)'
DEBUG[1586] res_pjsip_session.c: The inv session does NOT have an invite_tsx
DEBUG[1586] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7f204803bf78
DEBUG[1586] res_pjsip_session.c: The current transaction state is Completed
DEBUG[1586] res_pjsip_session.c: The transaction state change event is RX_MSG
DEBUG[1586] res_pjsip_session.c: The current inv state is CONFIRMED
DEBUG[1586] res_pjsip_session.c: Received response
DEBUG[1586] res_pjsip_session.c: Response is 491 Request Pending
DEBUG[1586] res_pjsip_session.c: Endpoint '764(PJSIP/764-00000006)' re-INVITE collision.
DEBUG[1586] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
DEBUG[1586] res_pjsip_session.c: The state change pertains to the endpoint '764(PJSIP/764-00000006)'
DEBUG[1586] res_pjsip_session.c: The inv session does NOT have an invite_tsx
DEBUG[1586] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7f2048077df8
DEBUG[1586] res_pjsip_session.c: The current transaction state is Confirmed
DEBUG[1586] res_pjsip_session.c: The transaction state change event is RX_MSG
DEBUG[1586] res_pjsip_session.c: The current inv state is CONFIRMED
DEBUG[1586] res_pjsip_session.c: Received request
DEBUG[1586] res_pjsip_session.c: Method is ACK
DEBUG[1586] res_pjsip_t38.c: UDPTL initialized on session for PJSIP/765-00000007
DEBUG[1586] res_pjsip_t38.c: T.38 state changed to '2' from '0' on channel 'PJSIP/765-00000007'
DEBUG[1586] res_pjsip_t38.c: Deferring incoming SDP stream on PJSIP/765-00000007 for peer re-invite
DEBUG[1586] res_pjsip_t38.c: UDPTL initialized on session for PJSIP/764-00000006
DEBUG[1586] res_pjsip_t38.c: T.38 state changed to '1' from '0' on channel 'PJSIP/764-00000006'
DEBUG[1586] res_pjsip_session.c: Sending session refresh SDP via re-INVITE to 764
DEBUG[1586] res_pjsip_session.c: Method is INVITE
DEBUG[1586] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
DEBUG[1586] res_pjsip_session.c: The state change pertains to the endpoint '764(PJSIP/764-00000006)'
DEBUG[1586] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f2048045b28)
DEBUG[1586] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7f2048045b28
DEBUG[1586] res_pjsip_session.c: The current transaction state is Calling
DEBUG[1586] res_pjsip_session.c: The transaction state change event is TX_MSG
DEBUG[1586] res_pjsip_session.c: The current inv state is CONFIRMED
DEBUG[1586] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
DEBUG[1586] res_pjsip_session.c: The state change pertains to the endpoint '764(PJSIP/764-00000006)'
DEBUG[1586] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f2048045b28)
DEBUG[1586] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7f2048045b28
DEBUG[1586] res_pjsip_session.c: The current transaction state is Proceeding
DEBUG[1586] res_pjsip_session.c: The transaction state change event is RX_MSG
DEBUG[1586] res_pjsip_session.c: The current inv state is CONFIRMED
DEBUG[1586] res_pjsip_session.c: Received response
DEBUG[1586] res_pjsip_session.c: Response is 100 Trying
DEBUG[1586] res_pjsip_session.c: Endpoint '764(PJSIP/764-00000006)' INVITE delay check. tsx-state:Proceeding
DEBUG[1585] res_pjsip_session.c: Endpoint '764(PJSIP/764-00000006)' re-INVITE collision timer expired.
DEBUG[1585] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
DEBUG[1585] res_pjsip_session.c: The state change pertains to the endpoint '765(PJSIP/765-00000007)'
DEBUG[1585] res_pjsip_session.c: The inv session does NOT have an invite_tsx
DEBUG[1585] res_pjsip_session.c: The UAC PRACK transaction involved in this state change is 0x7f204801b848
DEBUG[1585] res_pjsip_session.c: The current transaction state is Terminated
DEBUG[1585] res_pjsip_session.c: The transaction state change event is TIMER
DEBUG[1585] res_pjsip_session.c: The current inv state is CONFIRMED
DEBUG[1585] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
DEBUG[1585] res_pjsip_session.c: The state change pertains to the endpoint '764(PJSIP/764-00000006)'
DEBUG[1585] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f2048045b28)
DEBUG[1585] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7f2048077df8
DEBUG[1585] res_pjsip_session.c: The current transaction state is Terminated
DEBUG[1585] res_pjsip_session.c: The transaction state change event is TIMER
DEBUG[1585] res_pjsip_session.c: The current inv state is CONFIRMED
DEBUG[1585] res_pjsip_session.c: Endpoint '764(PJSIP/764-00000006)' INVITE delay check. tsx-state:Terminated
DEBUG[1586] res_pjsip_session.c: Endpoint '764(PJSIP/764-00000006)' sending delayed INVITE request.
DEBUG[1586] res_pjsip_session.c: Delay sending reinvite to 764 because of outstanding transaction...
DEBUG[1586] res_pjsip_t38.c: Automatically rejecting T.38 request on channel 'PJSIP/765-00000007'
DEBUG[1586] res_pjsip_t38.c: T.38 state changed to '4' from '2' on channel 'PJSIP/765-00000007'
DEBUG[1586] res_pjsip_session.c: Negotiating incoming SDP media stream 'image' using image SDP handler
DEBUG[1586] res_pjsip_t38.c: Declining; T.38 state is rejected or declined
DEBUG[1586] res_pjsip_t38.c: T.38 state changed to '0' from '4' on channel 'PJSIP/765-00000007'
DEBUG[1586] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
DEBUG[1586] res_pjsip_session.c: The state change pertains to the endpoint '765(PJSIP/765-00000007)'
DEBUG[1586] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f2048077df8)
DEBUG[1586] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7f2048077df8
DEBUG[1586] res_pjsip_session.c: The current transaction state is Completed
DEBUG[1586] res_pjsip_session.c: The transaction state change event is TX_MSG
DEBUG[1586] res_pjsip_session.c: The current inv state is CONFIRMED
DEBUG[1586] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
DEBUG[1586] res_pjsip_session.c: The state change pertains to the endpoint '765(PJSIP/765-00000007)'
DEBUG[1586] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f2048077df8)
DEBUG[1586] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7f2048077df8
DEBUG[1586] res_pjsip_session.c: The current transaction state is Completed
DEBUG[1586] res_pjsip_session.c: The transaction state change event is RX_MSG
DEBUG[1586] res_pjsip_session.c: The current inv state is CONFIRMED
DEBUG[1586] res_pjsip_session.c: Received request
DEBUG[1586] res_pjsip_session.c: Method is INVITE
DEBUG[1586] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
DEBUG[1586] res_pjsip_session.c: The state change pertains to the endpoint '765(PJSIP/765-00000007)'
DEBUG[1586] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f2048077df8)
DEBUG[1586] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7f2048077df8
DEBUG[1586] res_pjsip_session.c: The current transaction state is Confirmed
DEBUG[1586] res_pjsip_session.c: The transaction state change event is RX_MSG
DEBUG[1586] res_pjsip_session.c: The current inv state is CONFIRMED
DEBUG[1586] res_pjsip_session.c: Received request
DEBUG[1586] res_pjsip_session.c: Method is ACK
DEBUG[1586] res_pjsip_t38.c: T.38 state changed to '2' from '0' on channel 'PJSIP/765-00000007'
DEBUG[1586] res_pjsip_t38.c: Deferring incoming SDP stream on PJSIP/765-00000007 for peer re-invite
DEBUG[1586] res_pjsip_t38.c: UDPTL initialized on session for PJSIP/764-00000006
DEBUG[1586] res_pjsip_session.c: Delay sending reinvite to 764 because of outstanding transaction...
DEBUG[1585] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
DEBUG[1585] res_pjsip_session.c: The state change pertains to the endpoint '765(PJSIP/765-00000007)'
DEBUG[1585] res_pjsip_session.c: The inv session does NOT have an invite_tsx
DEBUG[1585] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7f2048077df8
DEBUG[1585] res_pjsip_session.c: The current transaction state is Terminated
DEBUG[1585] res_pjsip_session.c: The transaction state change event is TIMER
DEBUG[1585] res_pjsip_session.c: The current inv state is CONFIRMED
DEBUG[1586] res_pjsip_t38.c: Automatically rejecting T.38 request on channel 'PJSIP/765-00000007'
DEBUG[1586] res_pjsip_t38.c: T.38 state changed to '4' from '2' on channel 'PJSIP/765-00000007'
DEBUG[1586] res_pjsip_session.c: Negotiating incoming SDP media stream 'image' using image SDP handler
DEBUG[1586] res_pjsip_t38.c: Declining; T.38 state is rejected or declined
DEBUG[1586] res_pjsip_t38.c: T.38 state changed to '0' from '4' on channel 'PJSIP/765-00000007'
DEBUG[1586] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
DEBUG[1586] res_pjsip_session.c: The state change pertains to the endpoint '765(PJSIP/765-00000007)'
DEBUG[1586] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f2048077df8)
DEBUG[1586] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7f2048077df8
DEBUG[1586] res_pjsip_session.c: The current transaction state is Completed
DEBUG[1586] res_pjsip_session.c: The transaction state change event is TX_MSG
DEBUG[1586] res_pjsip_session.c: The current inv state is CONFIRMED
DEBUG[1586] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
DEBUG[1586] res_pjsip_session.c: The state change pertains to the endpoint '765(PJSIP/765-00000007)'
DEBUG[1586] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f2048077df8)
DEBUG[1586] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7f2048077df8
DEBUG[1586] res_pjsip_session.c: The current transaction state is Completed
DEBUG[1586] res_pjsip_session.c: The transaction state change event is RX_MSG
DEBUG[1586] res_pjsip_session.c: The current inv state is CONFIRMED
DEBUG[1586] res_pjsip_session.c: Received request
DEBUG[1586] res_pjsip_session.c: Method is INVITE
DEBUG[1586] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
DEBUG[1586] res_pjsip_session.c: The state change pertains to the endpoint '765(PJSIP/765-00000007)'
DEBUG[1586] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f2048077df8)
DEBUG[1586] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7f2048077df8
DEBUG[1586] res_pjsip_session.c: The current transaction state is Confirmed
DEBUG[1586] res_pjsip_session.c: The transaction state change event is RX_MSG
DEBUG[1586] res_pjsip_session.c: The current inv state is CONFIRMED
DEBUG[1586] res_pjsip_session.c: Received request
DEBUG[1586] res_pjsip_session.c: Method is ACK
DEBUG[1585] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
DEBUG[1585] res_pjsip_session.c: The state change pertains to the endpoint '765(PJSIP/765-00000007)'
DEBUG[1585] res_pjsip_session.c: The inv session does NOT have an invite_tsx
DEBUG[1585] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7f2048077df8
DEBUG[1585] res_pjsip_session.c: The current transaction state is Terminated
DEBUG[1585] res_pjsip_session.c: The transaction state change event is TIMER
DEBUG[1585] res_pjsip_session.c: The current inv state is CONFIRMED

jcolp · November 13, 2017, 11:45pm

192.168.2.92 is sending a re-invite to Asterisk at the same time that Asterisk is trying to send a re-invite to it. This seems to screw things up some and ultimately runs out the timer for the T.38 renegotiation, thus sending back a 488. Not quite sure what it’s doing. Inlining the SIP traffic using pjsip set logger on could provide further info.

jdast · November 14, 2017, 4:37am

I am not using any of the dialplan features on the following page at present.
https://wiki.asterisk.org/wiki/display/AST/T.38+Fax+Gateway

It was my belief that these are not necessary if both sender and receiver extensions are both T.38 capable. Is that correct?

Here is a trace of another run of the scenario this time with asterisk log with “core set debug 99” and “”. Unfortunately I’m unable to post the patches here. (I have private messaged these to @jcolp).

Here’s an extract:

[2017-11-14 13:59:50] VERBOSE[3063] res_pjsip_logger.c: <--- Received SIP request (951 bytes) from UDP:192.168.90.15:5069 --->
INVITE sip:asterisk@192.168.90.131:5060 SIP/2.0
CSeq: 1 INVITE
Via: SIP/2.0/UDP 192.168.90.15:5069;branch=z9hG4bK0118fe14-d416-1910-8968-005056c00001;rport
User-Agent: FaxVoip FSP 2.2.1
From: <sip:765@192.168.90.15>;tag=01b8fd14-d416-1910-8966-005056c00001
Call-ID: 5221eb88-bd65-4cc5-80ca-5401c20016d3
Supported: 100rel,replaces
Organization: FaxVoip Software
To: "764" <sip:764@192.168.90.131>;tag=f975885e-2cae-4d74-9401-7a2e5648eef9
Contact: "FaxVoip FSP" <sip:765@192.168.90.15:5069>
Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,SUBSCRIBE,NOTIFY,REFER,MESSAGE,INFO,PING,PRACK
Content-Length: 295
Content-Type: application/sdp
Max-Forwards: 70

v=0
o=- 1510631988 2 IN IP4 192.168.90.15
s=FaxVoip FSP 2.2.1
c=IN IP4 192.168.90.15
t=0 0
m=image 5012 udptl t38
a=sendrecv
a=T38FaxVersion:0
a=T38FaxRateManagement:transferredTCF
a=T38FaxMaxBuffer:2000
a=T38FaxMaxDatagram:1400
a=T38FaxUdpEC:t38UDPRedundancy
a=T38MaxBitRate:14400

[2017-11-14 13:59:50] DEBUG[3063] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7fe6840728b8 for Request msg INVITE/cseq=1 (rdata0x7fe650000b28)
[2017-11-14 13:59:50] DEBUG[3063] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/765-00000075 associated with dialog dlg0x7fe6840728b8
[2017-11-14 13:59:50] DEBUG[4153] res_pjsip_t38.c: UDPTL initialized on session for PJSIP/765-0000001b
[2017-11-14 13:59:50] DEBUG[4153] res_pjsip_t38.c: T.38 state changed to '2' from '0' on channel 'PJSIP/765-0000001b'
[2017-11-14 13:59:50] DEBUG[4153] res_pjsip_t38.c: Deferring incoming SDP stream on PJSIP/765-0000001b for peer re-invite
...
[2017-11-14 13:59:50] DEBUG[4153] res_pjsip_t38.c: UDPTL initialized on session for PJSIP/764-0000001a
[2017-11-14 13:59:50] DEBUG[4153] res_pjsip_t38.c: T.38 state changed to '1' from '0' on channel 'PJSIP/764-0000001a'
...
[2017-11-14 13:59:50] DEBUG[4153] res_pjsip_session.c: Sending session refresh SDP via re-INVITE to 764
[2017-11-14 13:59:50] DEBUG[4153] res_pjsip_session.c: Method is INVITE
[2017-11-14 13:59:50] DEBUG[4153] res_pjsip/pjsip_resolver.c: Performing SIP DNS resolution of target '192.168.2.92'
[2017-11-14 13:59:50] DEBUG[4153] res_pjsip/pjsip_resolver.c: Transport type for target '192.168.2.92' is 'UDP'
[2017-11-14 13:59:50] DEBUG[4153] res_pjsip/pjsip_resolver.c: Target '192.168.2.92' is an IP address, skipping resolution
[2017-11-14 13:59:50] DEBUG[4153] res_pjsip/pjsip_message_filter.c: Re-wrote Contact URI host/port to 192.168.90.131:5060 (this may be re-written again later)
[2017-11-14 13:59:50] VERBOSE[4153] res_pjsip_logger.c: <--- Transmitting SIP request (1025 bytes) to UDP:192.168.2.92:5069 --->
INVITE sip:764@192.168.2.92:5069 SIP/2.0
Via: SIP/2.0/UDP 192.168.90.131:5060;rport;branch=z9hG4bKPjf872a5d8-bcfe-4227-8cf1-8873c096d605
From: <sip:765@192.168.90.131>;tag=0f8d912b-2480-42d5-b1a8-3e5101295d0c
To: "FaxVoip FSP" <sip:764@192.168.90.131>;tag=864aef14-d416-1910-8156-0a0027000011
Contact: <sip:192.168.90.131:5060>
Call-ID: b84aef14-d416-1910-8156-0a0027000011@LAPTOP-IVPTU6L1
CSeq: 24949 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
P-Asserted-Identity: "765" <sip:765@192.168.90.131>
Max-Forwards: 70
User-Agent: FPBX-14.0.1.20(15.1.0)
Content-Type: application/sdp
Content-Length:   252

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

[2017-11-14 13:59:50] DEBUG[4153] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[2017-11-14 13:59:50] DEBUG[4153] res_pjsip_session.c: The state change pertains to the endpoint '764(PJSIP/764-0000001a)'
[2017-11-14 13:59:50] DEBUG[4153] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fe6840fd488)
[2017-11-14 13:59:50] DEBUG[4153] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7fe6840fd488
[2017-11-14 13:59:50] DEBUG[4153] res_pjsip_session.c: The current transaction state is Calling
[2017-11-14 13:59:50] DEBUG[4153] res_pjsip_session.c: The transaction state change event is TX_MSG
[2017-11-14 13:59:50] DEBUG[4153] res_pjsip_session.c: The current inv state is CONFIRMED
[2017-11-14 13:59:50] VERBOSE[3063] res_pjsip_logger.c: <--- Received SIP response (408 bytes) from UDP:192.168.2.92:5069 --->
SIP/2.0 100 Trying
CSeq: 24949 INVITE
Via: SIP/2.0/UDP 192.168.90.131:5060;rport=5060;branch=z9hG4bKPjf872a5d8-bcfe-4227-8cf1-8873c096d605;received=192.168.90.131
From: <sip:765@192.168.90.131>;tag=0f8d912b-2480-42d5-b1a8-3e5101295d0c
Call-ID: b84aef14-d416-1910-8156-0a0027000011@LAPTOP-IVPTU6L1
To: "FaxVoip FSP" <sip:764@192.168.90.131>;tag=864aef14-d416-1910-8156-0a0027000011
Content-Length: 0


[2017-11-14 13:59:50] DEBUG[3063] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7fe620056138 for Response msg 100/INVITE/cseq=24949 (rdata0x7fe650000b28)
[2017-11-14 13:59:50] DEBUG[3063] res_pjsip/pjsip_distributor.c: Found serializer pjsip/distributor-00000048 associated with dialog dlg0x7fe620056138
[2017-11-14 13:59:50] DEBUG[4153] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[2017-11-14 13:59:50] DEBUG[4153] res_pjsip_session.c: The state change pertains to the endpoint '764(PJSIP/764-0000001a)'
[2017-11-14 13:59:50] DEBUG[4153] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fe6840fd488)
[2017-11-14 13:59:50] DEBUG[4153] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7fe6840fd488
[2017-11-14 13:59:50] DEBUG[4153] res_pjsip_session.c: The current transaction state is Proceeding
[2017-11-14 13:59:50] DEBUG[4153] res_pjsip_session.c: The transaction state change event is RX_MSG
[2017-11-14 13:59:50] DEBUG[4153] res_pjsip_session.c: The current inv state is CONFIRMED
[2017-11-14 13:59:50] DEBUG[4153] res_pjsip_session.c: Received response
[2017-11-14 13:59:50] DEBUG[4153] res_pjsip_session.c: Response is 100 Trying
[2017-11-14 13:59:50] DEBUG[4153] res_pjsip_session.c: Endpoint '764(PJSIP/764-0000001a)' INVITE delay check. tsx-state:Proceeding
[2017-11-14 13:59:50] VERBOSE[3034] asterisk.c: Remote UNIX connection
[2017-11-14 13:59:50] VERBOSE[3063] res_pjsip_logger.c: <--- Received SIP request (951 bytes) from UDP:192.168.90.15:5069 --->
INVITE sip:asterisk@192.168.90.131:5060 SIP/2.0
CSeq: 1 INVITE
Via: SIP/2.0/UDP 192.168.90.15:5069;branch=z9hG4bK0118fe14-d416-1910-8968-005056c00001;rport
User-Agent: FaxVoip FSP 2.2.1
From: <sip:765@192.168.90.15>;tag=01b8fd14-d416-1910-8966-005056c00001
Call-ID: 5221eb88-bd65-4cc5-80ca-5401c20016d3
Supported: 100rel,replaces
Organization: FaxVoip Software
To: "764" <sip:764@192.168.90.131>;tag=f975885e-2cae-4d74-9401-7a2e5648eef9
Contact: "FaxVoip FSP" <sip:765@192.168.90.15:5069>
Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,SUBSCRIBE,NOTIFY,REFER,MESSAGE,INFO,PING,PRACK
Content-Length: 295
Content-Type: application/sdp
Max-Forwards: 70

v=0
o=- 1510631988 2 IN IP4 192.168.90.15
s=FaxVoip FSP 2.2.1
c=IN IP4 192.168.90.15
t=0 0
m=image 5012 udptl t38
a=sendrecv
a=T38FaxVersion:0
a=T38FaxRateManagement:transferredTCF
a=T38FaxMaxBuffer:2000
a=T38FaxMaxDatagram:1400
a=T38FaxUdpEC:t38UDPRedundancy
a=T38MaxBitRate:14400

[2017-11-14 13:59:50] DEBUG[3063] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7fe6840728b8 for Request msg INVITE/cseq=1 (rdata0x7fe650000b28)
[2017-11-14 13:59:50] DEBUG[3063] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/765-00000075 associated with dialog dlg0x7fe6840728b8
[2017-11-14 13:59:50] DEBUG[3063] res_pjsip_session.c: Endpoint '764(PJSIP/764-0000001a)' re-INVITE collision timer expired.
[2017-11-14 13:59:51] VERBOSE[3063] res_pjsip_logger.c: <--- Received SIP request (951 bytes) from UDP:192.168.90.15:5069 --->
INVITE sip:asterisk@192.168.90.131:5060 SIP/2.0
CSeq: 1 INVITE
Via: SIP/2.0/UDP 192.168.90.15:5069;branch=z9hG4bK0118fe14-d416-1910-8968-005056c00001;rport
User-Agent: FaxVoip FSP 2.2.1
From: <sip:765@192.168.90.15>;tag=01b8fd14-d416-1910-8966-005056c00001
Call-ID: 5221eb88-bd65-4cc5-80ca-5401c20016d3
Supported: 100rel,replaces
Organization: FaxVoip Software
To: "764" <sip:764@192.168.90.131>;tag=f975885e-2cae-4d74-9401-7a2e5648eef9
Contact: "FaxVoip FSP" <sip:765@192.168.90.15:5069>
Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,SUBSCRIBE,NOTIFY,REFER,MESSAGE,INFO,PING,PRACK
Content-Length: 295
Content-Type: application/sdp
Max-Forwards: 70

v=0
o=- 1510631988 2 IN IP4 192.168.90.15
s=FaxVoip FSP 2.2.1
c=IN IP4 192.168.90.15
t=0 0
m=image 5012 udptl t38
a=sendrecv
a=T38FaxVersion:0
a=T38FaxRateManagement:transferredTCF
a=T38FaxMaxBuffer:2000
a=T38FaxMaxDatagram:1400
a=T38FaxUdpEC:t38UDPRedundancy
a=T38MaxBitRate:14400

[2017-11-14 13:59:51] DEBUG[3063] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7fe6840728b8 for Request msg INVITE/cseq=1 (rdata0x7fe650000b28)
[2017-11-14 13:59:51] DEBUG[3063] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/765-00000075 associated with dialog dlg0x7fe6840728b8
[2017-11-14 13:59:53] DEBUG[3063] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[2017-11-14 13:59:53] DEBUG[3063] res_pjsip_session.c: The state change pertains to the endpoint '764()'
[2017-11-14 13:59:53] DEBUG[3063] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fe684092bd8)
[2017-11-14 13:59:53] DEBUG[3063] res_pjsip_session.c: The UAS BYE transaction involved in this state change is 0x7fe684080bb8
[2017-11-14 13:59:53] DEBUG[3063] res_pjsip_session.c: The current transaction state is Terminated
[2017-11-14 13:59:53] DEBUG[3063] res_pjsip_session.c: The transaction state change event is TIMER
[2017-11-14 13:59:53] DEBUG[3063] res_pjsip_session.c: The current inv state is DISCONNCTD
[2017-11-14 13:59:53] DEBUG[4153] res_pjsip_session.c: Destroying SIP session with endpoint 764
[2017-11-14 13:59:53] DEBUG[4153] rtp_engine.c: Destroyed RTP instance '0x7fe68401b498'
[2017-11-14 13:59:53] VERBOSE[3063] res_pjsip_logger.c: <--- Received SIP request (951 bytes) from UDP:192.168.90.15:5069 --->
INVITE sip:asterisk@192.168.90.131:5060 SIP/2.0
CSeq: 1 INVITE
Via: SIP/2.0/UDP 192.168.90.15:5069;branch=z9hG4bK0118fe14-d416-1910-8968-005056c00001;rport
User-Agent: FaxVoip FSP 2.2.1
From: <sip:765@192.168.90.15>;tag=01b8fd14-d416-1910-8966-005056c00001
Call-ID: 5221eb88-bd65-4cc5-80ca-5401c20016d3
Supported: 100rel,replaces
Organization: FaxVoip Software
To: "764" <sip:764@192.168.90.131>;tag=f975885e-2cae-4d74-9401-7a2e5648eef9
Contact: "FaxVoip FSP" <sip:765@192.168.90.15:5069>
Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,SUBSCRIBE,NOTIFY,REFER,MESSAGE,INFO,PING,PRACK
Content-Length: 295
Content-Type: application/sdp
Max-Forwards: 70

v=0
o=- 1510631988 2 IN IP4 192.168.90.15
s=FaxVoip FSP 2.2.1
c=IN IP4 192.168.90.15
t=0 0
m=image 5012 udptl t38
a=sendrecv
a=T38FaxVersion:0
a=T38FaxRateManagement:transferredTCF
a=T38FaxMaxBuffer:2000
a=T38FaxMaxDatagram:1400
a=T38FaxUdpEC:t38UDPRedundancy
a=T38MaxBitRate:14400

[2017-11-14 13:59:53] DEBUG[3063] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7fe6840728b8 for Request msg INVITE/cseq=1 (rdata0x7fe650000b28)
[2017-11-14 13:59:53] DEBUG[3063] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/765-00000075 associated with dialog dlg0x7fe6840728b8
[2017-11-14 13:59:55] DEBUG[3063] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[2017-11-14 13:59:55] DEBUG[3063] res_pjsip_session.c: The state change pertains to the endpoint '765(PJSIP/765-0000001b)'
[2017-11-14 13:59:55] DEBUG[3063] res_pjsip_session.c: The inv session does NOT have an invite_tsx
[2017-11-14 13:59:55] DEBUG[3063] res_pjsip_session.c: The UAC PRACK transaction involved in this state change is 0x7fe6840643e8
[2017-11-14 13:59:55] DEBUG[3063] res_pjsip_session.c: The current transaction state is Terminated
[2017-11-14 13:59:55] DEBUG[3063] res_pjsip_session.c: The transaction state change event is TIMER
[2017-11-14 13:59:55] DEBUG[3063] res_pjsip_session.c: The current inv state is CONFIRMED
[2017-11-14 13:59:55] DEBUG[3063] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[2017-11-14 13:59:55] DEBUG[3063] res_pjsip_session.c: The state change pertains to the endpoint '764(PJSIP/764-0000001a)'
[2017-11-14 13:59:55] DEBUG[3063] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fe6840fd488)
[2017-11-14 13:59:55] DEBUG[3063] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7fe6840734a8
[2017-11-14 13:59:55] DEBUG[3063] res_pjsip_session.c: The current transaction state is Terminated
[2017-11-14 13:59:55] DEBUG[3063] res_pjsip_session.c: The transaction state change event is TIMER
[2017-11-14 13:59:55] DEBUG[3063] res_pjsip_session.c: The current inv state is CONFIRMED
[2017-11-14 13:59:55] DEBUG[3063] res_pjsip_session.c: Endpoint '764(PJSIP/764-0000001a)' INVITE delay check. tsx-state:Terminated
[2017-11-14 13:59:55] DEBUG[4153] res_pjsip_session.c: Endpoint '764(PJSIP/764-0000001a)' sending delayed INVITE request.
[2017-11-14 13:59:55] DEBUG[4153] res_pjsip_session.c: Delay sending reinvite to 764 because of outstanding transaction...
[2017-11-14 13:59:55] DEBUG[4153] res_pjsip_t38.c: Automatically rejecting T.38 request on channel 'PJSIP/765-0000001b'
[2017-11-14 13:59:55] DEBUG[4153] res_pjsip_t38.c: T.38 state changed to '4' from '2' on channel 'PJSIP/765-0000001b'
[2017-11-14 13:59:55] VERBOSE[4153] res_pjsip_logger.c: <--- Received SIP request (951 bytes) from UDP:192.168.90.15:5069 --->
INVITE sip:asterisk@192.168.90.131:5060 SIP/2.0
CSeq: 1 INVITE
Via: SIP/2.0/UDP 192.168.90.15:5069;branch=z9hG4bK0118fe14-d416-1910-8968-005056c00001;rport
User-Agent: FaxVoip FSP 2.2.1
From: <sip:765@192.168.90.15>;tag=01b8fd14-d416-1910-8966-005056c00001
Call-ID: 5221eb88-bd65-4cc5-80ca-5401c20016d3
Supported: 100rel,replaces
Organization: FaxVoip Software
To: "764" <sip:764@192.168.90.131>;tag=f975885e-2cae-4d74-9401-7a2e5648eef9
Contact: "FaxVoip FSP" <sip:765@192.168.90.15:5069>
Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,SUBSCRIBE,NOTIFY,REFER,MESSAGE,INFO,PING,PRACK
Content-Length: 295
Content-Type: application/sdp
Max-Forwards: 70

v=0
o=- 1510631988 2 IN IP4 192.168.90.15
s=FaxVoip FSP 2.2.1
c=IN IP4 192.168.90.15
t=0 0
m=image 5012 udptl t38
a=sendrecv
a=T38FaxVersion:0
a=T38FaxRateManagement:transferredTCF
a=T38FaxMaxBuffer:2000
a=T38FaxMaxDatagram:1400
a=T38FaxUdpEC:t38UDPRedundancy
a=T38MaxBitRate:14400

[2017-11-14 13:59:55] DEBUG[4153] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7fe6840728b8 for Request msg INVITE/cseq=1 (rdata0x7fe6840f0cc8)
[2017-11-14 13:59:55] DEBUG[4153] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/765-00000075 associated with dialog dlg0x7fe6840728b8
[2017-11-14 13:59:55] DEBUG[4153] res_pjsip_session.c: Negotiating incoming SDP media stream 'image' using image SDP handler
[2017-11-14 13:59:55] DEBUG[4153] res_pjsip_t38.c: Declining; T.38 state is rejected or declined
[2017-11-14 13:59:55] DEBUG[4153] res_pjsip_t38.c: T.38 state changed to '0' from '4' on channel 'PJSIP/765-0000001b'
[2017-11-14 13:59:55] VERBOSE[4153] res_pjsip_logger.c: <--- Transmitting SIP response (699 bytes) to UDP:192.168.90.15:5069 --->
SIP/2.0 488 Not Acceptable Here
Via: SIP/2.0/UDP 192.168.90.15:5069;rport=5069;received=192.168.90.15;branch=z9hG4bK0118fe14-d416-1910-8968-005056c00001
Call-ID: 5221eb88-bd65-4cc5-80ca-5401c20016d3
From: <sip:765@192.168.90.15>;tag=01b8fd14-d416-1910-8966-005056c00001
To: "764" <sip:764@192.168.90.131>;tag=f975885e-2cae-4d74-9401-7a2e5648eef9
CSeq: 1 INVITE
Accept: application/sdp, application/simple-message-summary, application/xpidf+xml, application/cpim-pidf+xml, application/pidf+xml, application/dialog-info+xml, application/pidf+xml, application/dialog-info+xml, application/simple-message-summary, message/sipfrag;version=2.0
Server: FPBX-14.0.1.20(15.1.0)
Content-Length:  0


[2017-11-14 13:59:55] DEBUG[4153] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[2017-11-14 13:59:55] DEBUG[4153] res_pjsip_session.c: The state change pertains to the endpoint '765(PJSIP/765-0000001b)'
[2017-11-14 13:59:55] DEBUG[4153] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fe6840734a8)
[2017-11-14 13:59:55] DEBUG[4153] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7fe6840734a8
[2017-11-14 13:59:55] DEBUG[4153] res_pjsip_session.c: The current transaction state is Completed
[2017-11-14 13:59:55] DEBUG[4153] res_pjsip_session.c: The transaction state change event is TX_MSG
[2017-11-14 13:59:55] DEBUG[4153] res_pjsip_session.c: The current inv state is CONFIRMED
[2017-11-14 13:59:55] DEBUG[4153] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[2017-11-14 13:59:55] DEBUG[4153] res_pjsip_session.c: The state change pertains to the endpoint '765(PJSIP/765-0000001b)'
[2017-11-14 13:59:55] DEBUG[4153] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fe6840734a8)
[2017-11-14 13:59:55] DEBUG[4153] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7fe6840734a8
[2017-11-14 13:59:55] DEBUG[4153] res_pjsip_session.c: The current transaction state is Completed
[2017-11-14 13:59:55] DEBUG[4153] res_pjsip_session.c: The transaction state change event is RX_MSG
[2017-11-14 13:59:55] DEBUG[4153] res_pjsip_session.c: The current inv state is CONFIRMED
[2017-11-14 13:59:55] DEBUG[4153] res_pjsip_session.c: Received request
[2017-11-14 13:59:55] DEBUG[4153] res_pjsip_session.c: Method is INVITE
[2017-11-14 13:59:55] VERBOSE[3063] res_pjsip_logger.c: <--- Received SIP request (388 bytes) from UDP:192.168.90.15:5069 --->
ACK sip:asterisk@192.168.90.131:5060 SIP/2.0
CSeq: 1 ACK
Via: SIP/2.0/UDP 192.168.90.15:5069;branch=z9hG4bK0118fe14-d416-1910-8968-005056c00001;rport
From: <sip:765@192.168.90.15>;tag=01b8fd14-d416-1910-8966-005056c00001
Call-ID: 5221eb88-bd65-4cc5-80ca-5401c20016d3
To: "764" <sip:764@192.168.90.131>;tag=f975885e-2cae-4d74-9401-7a2e5648eef9
Content-Length: 0
Max-Forwards: 70


[2017-11-14 13:59:55] DEBUG[3063] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7fe6840728b8 for Request msg ACK/cseq=1 (rdata0x7fe650000b28)
[2017-11-14 13:59:55] DEBUG[3063] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/765-00000075 associated with dialog dlg0x7fe6840728b8
[2017-11-14 13:59:55] DEBUG[4153] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[2017-11-14 13:59:55] DEBUG[4153] res_pjsip_session.c: The state change pertains to the endpoint '765(PJSIP/765-0000001b)'
[2017-11-14 13:59:55] DEBUG[4153] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fe6840734a8)
[2017-11-14 13:59:55] DEBUG[4153] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7fe6840734a8
[2017-11-14 13:59:55] DEBUG[4153] res_pjsip_session.c: The current transaction state is Confirmed
[2017-11-14 13:59:55] DEBUG[4153] res_pjsip_session.c: The transaction state change event is RX_MSG
[2017-11-14 13:59:55] DEBUG[4153] res_pjsip_session.c: The current inv state is CONFIRMED
[2017-11-14 13:59:55] DEBUG[4153] res_pjsip_session.c: Received request
[2017-11-14 13:59:55] DEBUG[4153] res_pjsip_session.c: Method is ACK
[2017-11-14 13:59:55] VERBOSE[3063] res_pjsip_logger.c: <--- Received SIP request (884 bytes) from UDP:192.168.90.15:5069 --->
INVITE sip:asterisk@192.168.90.131:5060 SIP/2.0
CSeq: 2 INVITE
Via: SIP/2.0/UDP 192.168.90.15:5069;branch=z9hG4bK84bc0515-d416-1910-8968-005056c00001;rport
User-Agent: FaxVoip FSP 2.2.1
From: <sip:765@192.168.90.15>;tag=01b8fd14-d416-1910-8966-005056c00001
Call-ID: 5221eb88-bd65-4cc5-80ca-5401c20016d3
Supported: 100rel,replaces
Organization: FaxVoip Software
To: "764" <sip:764@192.168.90.131>;tag=f975885e-2cae-4d74-9401-7a2e5648eef9
Contact: "FaxVoip FSP" <sip:765@192.168.90.15:5069>
Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,SUBSCRIBE,NOTIFY,REFER,MESSAGE,INFO,PING,PRACK
Content-Length: 228
Content-Type: application/sdp
Max-Forwards: 70

v=0
o=- 1510631988 3 IN IP4 192.168.90.15
s=FaxVoip FSP 2.2.1
c=IN IP4 192.168.90.15
t=0 0
m=audio 5012 RTP/AVP 0 101
a=sendrecv
a=rtpmap:0 PCMU/8000/1
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=maxptime:240

[2017-11-14 13:59:55] DEBUG[3063] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7fe6840728b8 for Request msg INVITE/cseq=2 (rdata0x7fe650000b28)
[2017-11-14 13:59:55] DEBUG[3063] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/765-00000075 associated with dialog dlg0x7fe6840728b8
[2017-11-14 13:59:55] DEBUG[4153] res_pjsip_t38.c: T.38 state changed to '2' from '0' on channel 'PJSIP/765-0000001b'
[2017-11-14 13:59:55] DEBUG[4153] res_pjsip_t38.c: Deferring incoming SDP stream on PJSIP/765-0000001b for peer re-invite
...
[2017-11-14 13:59:55] DEBUG[4153] res_pjsip_t38.c: UDPTL initialized on session for PJSIP/764-0000001a
[2017-11-14 13:59:55] DEBUG[4153] res_pjsip_session.c: Delay sending reinvite to 764 because of outstanding transaction...
[2017-11-14 13:59:55] VERBOSE[3063] res_pjsip_logger.c: <--- Received SIP request (884 bytes) from UDP:192.168.90.15:5069 --->
INVITE sip:asterisk@192.168.90.131:5060 SIP/2.0
CSeq: 2 INVITE
Via: SIP/2.0/UDP 192.168.90.15:5069;branch=z9hG4bK84bc0515-d416-1910-8968-005056c00001;rport
User-Agent: FaxVoip FSP 2.2.1
From: <sip:765@192.168.90.15>;tag=01b8fd14-d416-1910-8966-005056c00001
Call-ID: 5221eb88-bd65-4cc5-80ca-5401c20016d3
Supported: 100rel,replaces
Organization: FaxVoip Software
To: "764" <sip:764@192.168.90.131>;tag=f975885e-2cae-4d74-9401-7a2e5648eef9
Contact: "FaxVoip FSP" <sip:765@192.168.90.15:5069>
Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,SUBSCRIBE,NOTIFY,REFER,MESSAGE,INFO,PING,PRACK
Content-Length: 228
Content-Type: application/sdp
Max-Forwards: 70

v=0
o=- 1510631988 3 IN IP4 192.168.90.15
s=FaxVoip FSP 2.2.1
c=IN IP4 192.168.90.15
t=0 0
m=audio 5012 RTP/AVP 0 101
a=sendrecv
a=rtpmap:0 PCMU/8000/1
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=maxptime:240

[2017-11-14 13:59:55] DEBUG[3063] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7fe6840728b8 for Request msg INVITE/cseq=2 (rdata0x7fe650000b28)
[2017-11-14 13:59:55] DEBUG[3063] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/765-00000075 associated with dialog dlg0x7fe6840728b8
[2017-11-14 13:59:56] VERBOSE[3063] res_pjsip_logger.c: <--- Received SIP request (884 bytes) from UDP:192.168.90.15:5069 --->
INVITE sip:asterisk@192.168.90.131:5060 SIP/2.0
CSeq: 2 INVITE
Via: SIP/2.0/UDP 192.168.90.15:5069;branch=z9hG4bK84bc0515-d416-1910-8968-005056c00001;rport
User-Agent: FaxVoip FSP 2.2.1
From: <sip:765@192.168.90.15>;tag=01b8fd14-d416-1910-8966-005056c00001
Call-ID: 5221eb88-bd65-4cc5-80ca-5401c20016d3
Supported: 100rel,replaces
Organization: FaxVoip Software
To: "764" <sip:764@192.168.90.131>;tag=f975885e-2cae-4d74-9401-7a2e5648eef9
Contact: "FaxVoip FSP" <sip:765@192.168.90.15:5069>
Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,SUBSCRIBE,NOTIFY,REFER,MESSAGE,INFO,PING,PRACK
Content-Length: 228
Content-Type: application/sdp
Max-Forwards: 70

v=0
o=- 1510631988 3 IN IP4 192.168.90.15
s=FaxVoip FSP 2.2.1
c=IN IP4 192.168.90.15
t=0 0
m=audio 5012 RTP/AVP 0 101
a=sendrecv
a=rtpmap:0 PCMU/8000/1
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=maxptime:240

[2017-11-14 13:59:56] DEBUG[3063] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7fe6840728b8 for Request msg INVITE/cseq=2 (rdata0x7fe650000b28)
[2017-11-14 13:59:56] DEBUG[3063] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/765-00000075 associated with dialog dlg0x7fe6840728b8
[2017-11-14 13:59:58] VERBOSE[3063] res_pjsip_logger.c: <--- Received SIP request (884 bytes) from UDP:192.168.90.15:5069 --->
INVITE sip:asterisk@192.168.90.131:5060 SIP/2.0
CSeq: 2 INVITE
Via: SIP/2.0/UDP 192.168.90.15:5069;branch=z9hG4bK84bc0515-d416-1910-8968-005056c00001;rport
User-Agent: FaxVoip FSP 2.2.1
From: <sip:765@192.168.90.15>;tag=01b8fd14-d416-1910-8966-005056c00001
Call-ID: 5221eb88-bd65-4cc5-80ca-5401c20016d3
Supported: 100rel,replaces
Organization: FaxVoip Software
To: "764" <sip:764@192.168.90.131>;tag=f975885e-2cae-4d74-9401-7a2e5648eef9
Contact: "FaxVoip FSP" <sip:765@192.168.90.15:5069>
Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,SUBSCRIBE,NOTIFY,REFER,MESSAGE,INFO,PING,PRACK
Content-Length: 228
Content-Type: application/sdp
Max-Forwards: 70

v=0
o=- 1510631988 3 IN IP4 192.168.90.15
s=FaxVoip FSP 2.2.1
c=IN IP4 192.168.90.15
t=0 0
m=audio 5012 RTP/AVP 0 101
a=sendrecv
a=rtpmap:0 PCMU/8000/1
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=maxptime:240

[2017-11-14 13:59:58] DEBUG[3063] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7fe6840728b8 for Request msg INVITE/cseq=2 (rdata0x7fe650000b28)
[2017-11-14 13:59:58] DEBUG[3063] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/765-00000075 associated with dialog dlg0x7fe6840728b8
[2017-11-14 14:00:00] DEBUG[3063] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[2017-11-14 14:00:00] DEBUG[3063] res_pjsip_session.c: The state change pertains to the endpoint '765(PJSIP/765-0000001b)'
[2017-11-14 14:00:00] DEBUG[3063] res_pjsip_session.c: The inv session does NOT have an invite_tsx
[2017-11-14 14:00:00] DEBUG[3063] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7fe6840734a8
[2017-11-14 14:00:00] DEBUG[3063] res_pjsip_session.c: The current transaction state is Terminated
[2017-11-14 14:00:00] DEBUG[3063] res_pjsip_session.c: The transaction state change event is TIMER
[2017-11-14 14:00:00] DEBUG[3063] res_pjsip_session.c: The current inv state is CONFIRMED
[2017-11-14 14:00:00] DEBUG[4153] res_pjsip_t38.c: Automatically rejecting T.38 request on channel 'PJSIP/765-0000001b'
[2017-11-14 14:00:00] DEBUG[4153] res_pjsip_t38.c: T.38 state changed to '4' from '2' on channel 'PJSIP/765-0000001b'
[2017-11-14 14:00:00] VERBOSE[4153] res_pjsip_logger.c: <--- Received SIP request (884 bytes) from UDP:192.168.90.15:5069 --->
INVITE sip:asterisk@192.168.90.131:5060 SIP/2.0
CSeq: 2 INVITE
Via: SIP/2.0/UDP 192.168.90.15:5069;branch=z9hG4bK84bc0515-d416-1910-8968-005056c00001;rport
User-Agent: FaxVoip FSP 2.2.1
From: <sip:765@192.168.90.15>;tag=01b8fd14-d416-1910-8966-005056c00001
Call-ID: 5221eb88-bd65-4cc5-80ca-5401c20016d3
Supported: 100rel,replaces
Organization: FaxVoip Software
To: "764" <sip:764@192.168.90.131>;tag=f975885e-2cae-4d74-9401-7a2e5648eef9
Contact: "FaxVoip FSP" <sip:765@192.168.90.15:5069>
Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,SUBSCRIBE,NOTIFY,REFER,MESSAGE,INFO,PING,PRACK
Content-Length: 228
Content-Type: application/sdp
Max-Forwards: 70

v=0
o=- 1510631988 3 IN IP4 192.168.90.15
s=FaxVoip FSP 2.2.1
c=IN IP4 192.168.90.15
t=0 0
m=audio 5012 RTP/AVP 0 101
a=sendrecv
a=rtpmap:0 PCMU/8000/1
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=maxptime:240

[2017-11-14 14:00:00] DEBUG[4153] res_pjsip/pjsip_distributor.c: Searching for serializer associated with dialog dlg0x7fe6840728b8 for Request msg INVITE/cseq=2 (rdata0x7fe684069b48)
[2017-11-14 14:00:00] DEBUG[4153] res_pjsip/pjsip_distributor.c: Found serializer pjsip/outsess/765-00000075 associated with dialog dlg0x7fe6840728b8
[2017-11-14 14:00:00] DEBUG[4153] res_pjsip_session.c: Negotiating incoming SDP media stream 'image' using image SDP handler
[2017-11-14 14:00:00] DEBUG[4153] res_pjsip_t38.c: Declining; T.38 state is rejected or declined
[2017-11-14 14:00:00] DEBUG[4153] res_pjsip_t38.c: T.38 state changed to '0' from '4' on channel 'PJSIP/765-0000001b'
[2017-11-14 14:00:00] VERBOSE[4153] res_pjsip_logger.c: <--- Transmitting SIP response (699 bytes) to UDP:192.168.90.15:5069 --->
SIP/2.0 488 Not Acceptable Here
Via: SIP/2.0/UDP 192.168.90.15:5069;rport=5069;received=192.168.90.15;branch=z9hG4bK84bc0515-d416-1910-8968-005056c00001
Call-ID: 5221eb88-bd65-4cc5-80ca-5401c20016d3
From: <sip:765@192.168.90.15>;tag=01b8fd14-d416-1910-8966-005056c00001
To: "764" <sip:764@192.168.90.131>;tag=f975885e-2cae-4d74-9401-7a2e5648eef9
CSeq: 2 INVITE
Accept: application/sdp, application/simple-message-summary, application/xpidf+xml, application/cpim-pidf+xml, application/pidf+xml, application/dialog-info+xml, application/pidf+xml, application/dialog-info+xml, application/simple-message-summary, message/sipfrag;version=2.0
Server: FPBX-14.0.1.20(15.1.0)
Content-Length:  0


[2017-11-14 14:00:00] DEBUG[4153] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[2017-11-14 14:00:00] DEBUG[4153] res_pjsip_session.c: The state change pertains to the endpoint '765(PJSIP/765-0000001b)'
[2017-11-14 14:00:00] DEBUG[4153] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fe6840734a8)
[2017-11-14 14:00:00] DEBUG[4153] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7fe6840734a8
[2017-11-14 14:00:00] DEBUG[4153] res_pjsip_session.c: The current transaction state is Completed
[2017-11-14 14:00:00] DEBUG[4153] res_pjsip_session.c: The transaction state change event is TX_MSG
[2017-11-14 14:00:00] DEBUG[4153] res_pjsip_session.c: The current inv state is CONFIRMED
[2017-11-14 14:00:00] DEBUG[4153] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[2017-11-14 14:00:00] DEBUG[4153] res_pjsip_session.c: The state change pertains to the endpoint '765(PJSIP/765-0000001b)'
[2017-11-14 14:00:00] DEBUG[4153] res_pjsip_session.c: The inv session still has an invite_tsx (0x7fe6840734a8)
[2017-11-14 14:00:00] DEBUG[4153] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7fe6840734a8
[2017-11-14 14:00:00] DEBUG[4153] res_pjsip_session.c: The current transaction state is Completed
[2017-11-14 14:00:00] DEBUG[4153] res_pjsip_session.c: The transaction state change event is RX_MSG
[2017-11-14 14:00:00] DEBUG[4153] res_pjsip_session.c: The current inv state is CONFIRMED
[2017-11-14 14:00:00] DEBUG[4153] res_pjsip_session.c: Received request
[2017-11-14 14:00:00] DEBUG[4153] res_pjsip_session.c: Method is INVITE

jcolp · November 14, 2017, 10:26am

In the log you provided it better shows what is going on.

Asterisk receives a T.38 re-invite, we then send a re-invite to the remote side (192.168.2.92). It sends a 100 Trying but doesn’t send any other response. It essentially keeps things in limbo, never denying or accepting the T.38 re-invite. The side that initiated the T.38 re-invite sends some retransmissions until finally our internal timer runs out on accepting the T.38 re-invite and we respond with a 488.

The problem seems to be with 192.168.2.92.

jdast · November 15, 2017, 5:33am

Thanks for your help.

I’ve tried all the settings possible in the fax voip software. Here’s a screen shot of the program to give you an idea of the options available for controlling T.38 re-invites.

There are tick boxes on the right hand side of the screen shot to which I have tried all combinations of in an attempt to get the T.38 reinvites to work with Asterisk 15. If no tick box is selected then no T.38 re-invites are sent and the call is processed as PCMU audio. Choosing different options of when to send the T.38 reinvite all give slightly different results (some fail completely and others process as audio), none of which mean that the call ends up being processed as T.38 due to failures of the reinvite mechanism not succeeding. The reasons for which I cannot judge since I have no expertise.

t38faxvoip are disappointingly unwilling to investigate the logs I have supplied since Asterisk is involved and they no longer wish to attempt to support it. So this is a warning for other users of their software who wish to use it with Asterisk in its current form. Yes, it is possible I have made a mistake, but I haven’t yet been able to determine that, and I would be very glad to know that and correct myself.

I have used Asterisk since 1.0 and am quite fond of it but at this point I may not be able to use it much longer if it cannot do this with T.38 fax software since I have a requirement to work with the Windows Fax service API.

I do not really have the knowledge or expertise in SIP and T.38 to investigate this much further without spending significantly more time than I already have to gain that expertise.

The only thing I can really try now apart from trying to debug the program myself is try another PBX which is meant to be compatible with the t38faxvoip software. They have a couple they say they are compatible with here: http://www.t38faxvoip.com/phone/features.htm

I have successfully used the t38faxvoip com software with our SIP provider bypassing Asterisk, so I’m fairly certain that it works separately from Asterisk.

I realise Asterisk is open source and free therefore I cannot expect anything from you in terms of supporting me in this.

If someone suitably skilled is are willing and able to spend the time, to setup an environment to test the scenario with these programs, t38faxvoip.com have a 15 day trial license and work on Windows 10 then it may reveal an incompatibility in the Asterisk software which is probably resolvable. I expect this might help other users in the future. I have spent many days on this, due to the belief I help that it should work.

I suspect that it is probably too difficult to debug it here and solve without one of the parties co-operating in the effort. At least their software is available as a black box to test with.

Thanks for your help to this point, it is much appreciated!

Jared

jdast · November 15, 2017, 7:30am

A follow up. I just tried sending a fax with T.38 passthrough with the software via 3CX PBX and it transmitted fine. When I set the T.38 Fax reception option to switch to T.38 upon CNG tone received.

I successfully sent a detailed 3 page fax of “lorem ipsum” text, the call which lasted for 3:10 seconds. The resulting image was perfect. (I had enabled the Error Correction mode option in the client software too - although it may not have needed it).

Anyway, the fact that the T.38 re-invites worked correctly there means I now have a packet trace showing me what is meant to happen which I have never seen before.

Below is a screen shot of the packet capture.

In this scenario, it is a little harder to follow since both the PBX and the sending fax endpoint are both the same IP. The packet capture is from the perspective of the receiver machine.

192.168.2.92 is both the PBX and the Sender fax software
192.168.90.15 is the receiver fax software

Hopefully this information is helpful in getting to a resolution for asterisk T.38 passthrough with this T.38 fax client software. I’m happy to provide more information if it is of use.

No.     Time           Source                Destination           Protocol Length Info
      1 0.000000       192.168.2.92          192.168.90.15         SIP/SDP  909    Request: INVITE sip:891@192.168.90.15:5069 | 
User Datagram Protocol, Src Port: 5060, Dst Port: 5069
Session Initiation Protocol (INVITE)
      2 0.001135       192.168.90.15         192.168.2.92          SIP      328    Status: 100 Trying | 
User Datagram Protocol, Src Port: 5069, Dst Port: 5060
Session Initiation Protocol (100)
      3 0.011613       192.168.90.15         192.168.2.92          SIP      585    Status: 180 Ringing | 
User Datagram Protocol, Src Port: 5069, Dst Port: 5060
Session Initiation Protocol (180)
      4 0.304477       192.168.90.15         192.168.2.92          SIP/SDP  894    Status: 200 OK | 
User Datagram Protocol, Src Port: 5069, Dst Port: 5060
Session Initiation Protocol (200)
      5 0.385722       192.168.2.92          192.168.90.15         SIP      476    Request: ACK sip:891@192.168.90.15:5069 | 
User Datagram Protocol, Src Port: 5060, Dst Port: 5069
Session Initiation Protocol (ACK)
      6 0.390360       192.168.2.92          192.168.90.15         RTP      214    PT=ITU-T G.711 PCMU, SSRC=0x5340C677, Seq=53894, Time=0
User Datagram Protocol, Src Port: 5000, Dst Port: 5020
Real-Time Transport Protocol
      7 0.406521       192.168.90.15         192.168.2.92          RTP      214    PT=ITU-T G.711 PCMU, SSRC=0xF5DBF3A, Seq=11272, Time=0
User Datagram Protocol, Src Port: 5020, Dst Port: 5000
Real-Time Transport Protocol
      8 0.410088       192.168.2.92          192.168.90.15         RTP      214    PT=ITU-T G.711 PCMU, SSRC=0x5340C677, Seq=53895, Time=160
User Datagram Protocol, Src Port: 5000, Dst Port: 5020
Real-Time Transport Protocol
      9 0.427445       192.168.90.15         192.168.2.92          RTP      214    PT=ITU-T G.711 PCMU, SSRC=0xF5DBF3A, Seq=11273, Time=160
User Datagram Protocol, Src Port: 5020, Dst Port: 5000
Real-Time Transport Protocol
     10 0.429879       192.168.2.92          192.168.90.15         RTP      214    PT=ITU-T G.711 PCMU, SSRC=0x5340C677, Seq=53896, Time=320
User Datagram Protocol, Src Port: 5000, Dst Port: 5020
Real-Time Transport Protocol
     11 0.446453       192.168.90.15         192.168.2.92          RTP      214    PT=ITU-T G.711 PCMU, SSRC=0xF5DBF3A, Seq=11274, Time=320
User Datagram Protocol, Src Port: 5020, Dst Port: 5000
Real-Time Transport Protocol
     12 0.449058       192.168.2.92          192.168.90.15         RTP      214    PT=ITU-T G.711 PCMU, SSRC=0x5340C677, Seq=53897, Time=480
User Datagram Protocol, Src Port: 5000, Dst Port: 5020
Real-Time Transport Protocol
     13 0.466525       192.168.90.15         192.168.2.92          RTP      214    PT=ITU-T G.711 PCMU, SSRC=0xF5DBF3A, Seq=11275, Time=480
User Datagram Protocol, Src Port: 5020, Dst Port: 5000
Real-Time Transport Protocol
     14 0.469742       192.168.2.92          192.168.90.15         RTP      214    PT=ITU-T G.711 PCMU, SSRC=0x5340C677, Seq=53898, Time=640
User Datagram Protocol, Src Port: 5000, Dst Port: 5020
Real-Time Transport Protocol
     15 0.486539       192.168.90.15         192.168.2.92          RTP      214    PT=ITU-T G.711 PCMU, SSRC=0xF5DBF3A, Seq=11276, Time=640
User Datagram Protocol, Src Port: 5020, Dst Port: 5000
Real-Time Transport Protocol
     16 0.490180       192.168.2.92          192.168.90.15         RTP      214    PT=ITU-T G.711 PCMU, SSRC=0x5340C677, Seq=53899, Time=800
User Datagram Protocol, Src Port: 5000, Dst Port: 5020
Real-Time Transport Protocol
     17 0.509716       192.168.2.92          192.168.90.15         RTP      214    PT=ITU-T G.711 PCMU, SSRC=0x5340C677, Seq=53900, Time=960
User Datagram Protocol, Src Port: 5000, Dst Port: 5020
Real-Time Transport Protocol
     18 0.511601       192.168.90.15         192.168.2.92          SIP/SDP  944    Request: INVITE sip:890@192.168.2.92:5060, in-dialog | 
User Datagram Protocol, Src Port: 5069, Dst Port: 5060
Session Initiation Protocol (INVITE)
     19 0.531445       192.168.2.92          192.168.90.15         T.38     214    UDP: UDPTLPacket Seq=32768 [UNKNOWN PER: 10.9 Unconstrained unexpected fragment count][Malformed Packet]
User Datagram Protocol, Src Port: 5000, Dst Port: 5020
ITU-T Recommendation T.38
[Malformed Packet: T.38]
     20 0.551534       192.168.2.92          192.168.90.15         T.38     214    UDP: UDPTLPacket Seq=32768 [UNKNOWN PER: 10.9 Unconstrained unexpected fragment count][Malformed Packet]
User Datagram Protocol, Src Port: 5000, Dst Port: 5020
ITU-T Recommendation T.38
[Malformed Packet: T.38]
     21 0.572251       192.168.2.92          192.168.90.15         T.38     214    UDP: UDPTLPacket Seq=32768 [UNKNOWN PER: 10.9 Unconstrained unexpected fragment count][Malformed Packet]
User Datagram Protocol, Src Port: 5000, Dst Port: 5020
ITU-T Recommendation T.38
[Malformed Packet: T.38]
     22 0.591264       192.168.2.92          192.168.90.15         T.38     214    UDP: UDPTLPacket Seq=32768 [UNKNOWN PER: 10.9 Unconstrained unexpected fragment count][Malformed Packet]
User Datagram Protocol, Src Port: 5000, Dst Port: 5020
ITU-T Recommendation T.38
[Malformed Packet: T.38]
     23 0.611328       192.168.2.92          192.168.90.15         T.38     214    UDP: UDPTLPacket Seq=32768 [UNKNOWN PER: 10.9 Unconstrained unexpected fragment count][Malformed Packet]
User Datagram Protocol, Src Port: 5000, Dst Port: 5020
ITU-T Recommendation T.38
[Malformed Packet: T.38]
     24 0.637432       192.168.2.92          192.168.90.15         T.38     60     UDP: UDPTLPacket Seq=00000  t30ind: no-signal
User Datagram Protocol, Src Port: 5000, Dst Port: 5020
ITU-T Recommendation T.38
     25 0.641597       192.168.2.92          192.168.90.15         SIP      352    Status: 100 Trying | 
User Datagram Protocol, Src Port: 5060, Dst Port: 5069
Session Initiation Protocol (100)
     26 0.718806       192.168.2.92          192.168.90.15         SIP/SDP  902    Status: 200 OK | 
User Datagram Protocol, Src Port: 5060, Dst Port: 5069
Session Initiation Protocol (200)
     27 0.720817       192.168.90.15         192.168.2.92          SIP      434    Request: ACK sip:890@192.168.2.92:5060 | 
User Datagram Protocol, Src Port: 5069, Dst Port: 5060
Session Initiation Protocol (ACK)
     28 0.723536       192.168.90.15         192.168.2.92          T.38     48     UDP: UDPTLPacket Seq=00000  t30ind: no-signal
User Datagram Protocol, Src Port: 5020, Dst Port: 5000
ITU-T Recommendation T.38
     29 0.837624       192.168.2.92          192.168.90.15         T.38     60     UDP: UDPTLPacket Seq=00001  t30ind: cng
User Datagram Protocol, Src Port: 5000, Dst Port: 5020
ITU-T Recommendation T.38
     30 0.923765       192.168.90.15         192.168.2.92          T.38     48     UDP: UDPTLPacket Seq=00001  t30ind: ced
User Datagram Protocol, Src Port: 5020, Dst Port: 5000
ITU-T Recommendation T.38
     31 3.943533       192.168.90.15         192.168.2.92          T.38     48     UDP: UDPTLPacket Seq=00002  t30ind: no-signal
User Datagram Protocol, Src Port: 5020, Dst Port: 5000
ITU-T Recommendation T.38
     32 4.023128       192.168.90.15         192.168.2.92          T.38     48     UDP: UDPTLPacket Seq=00003  t30ind: v21-preamble
User Datagram Protocol, Src Port: 5020, Dst Port: 5000
ITU-T Recommendation T.38
     33 5.023466       192.168.90.15         192.168.2.92          T.38     53     UDP: UDPTLPacket Seq=00004  data:v21: hdlc-data[ff]
User Datagram Protocol, Src Port: 5020, Dst Port: 5000
ITU-T Recommendation T.38
     34 5.063018       192.168.90.15         192.168.2.92          T.38     53     UDP: UDPTLPacket Seq=00005  data:v21: hdlc-data[c0]
User Datagram Protocol, Src Port: 5020, Dst Port: 5000
ITU-T Recommendation T.38
     35 5.083737       192.168.90.15         192.168.2.92          T.38     53     UDP: UDPTLPacket Seq=00006  data:v21: hdlc-data[02]
User Datagram Protocol, Src Port: 5020, Dst Port: 5000
ITU-T Recommendation T.38
     36 5.103700       192.168.90.15         192.168.2.92          T.38     53     UDP: UDPTLPacket Seq=00007  data:v21: hdlc-data[0a]
User Datagram Protocol, Src Port: 5020, Dst Port: 5000
ITU-T Recommendation T.38
     37 5.143752       192.168.90.15         192.168.2.92          T.38     53     UDP: UDPTLPacket Seq=00008  data:v21: hdlc-data[ca]
User Datagram Protocol, Src Port: 5020, Dst Port: 5000
ITU-T Recommendation T.38
     38 5.163269       192.168.90.15         192.168.2.92          T.38     53     UDP: UDPTLPacket Seq=00009  data:v21: hdlc-data[62]
User Datagram Protocol, Src Port: 5020, Dst Port: 5000
ITU-T Recommendation T.38
     39 5.183261       192.168.90.15         192.168.2.92          T.38     53     UDP: UDPTLPacket Seq=00010  data:v21: hdlc-data[04]
User Datagram Protocol, Src Port: 5020, Dst Port: 5000
ITU-T Recommendation T.38
     40 5.223314       192.168.90.15         192.168.2.92          T.38     53     UDP: UDPTLPacket Seq=00011  data:v21: hdlc-data[0e]
User Datagram Protocol, Src Port: 5020, Dst Port: 5000
ITU-T Recommendation T.38
     41 5.243317       192.168.90.15         192.168.2.92          T.38     53     UDP: UDPTLPacket Seq=00012  data:v21: hdlc-data[96]
User Datagram Protocol, Src Port: 5020, Dst Port: 5000
ITU-T Recommendation T.38
     42 5.262854       192.168.90.15         192.168.2.92          T.38     53     UDP: UDPTLPacket Seq=00013  data:v21: hdlc-data[f6]
User Datagram Protocol, Src Port: 5020, Dst Port: 5000
ITU-T Recommendation T.38
     43 5.303913       192.168.90.15         192.168.2.92          T.38     53     UDP: UDPTLPacket Seq=00014  data:v21: hdlc-data[6a]
User Datagram Protocol, Src Port: 5020, Dst Port: 5000
ITU-T Recommendation T.38
     44 5.323883       192.168.90.15         192.168.2.92          T.38     53     UDP: UDPTLPacket Seq=00015  data:v21: hdlc-data[04]
User Datagram Protocol, Src Port: 5020, Dst Port: 5000
ITU-T Recommendation T.38
     45 5.343887       192.168.90.15         192.168.2.92          T.38     53     UDP: UDPTLPacket Seq=00016  data:v21: hdlc-data[1e]
User Datagram Protocol, Src Port: 5020, Dst Port: 5000
ITU-T Recommendation T.38
     46 5.382522       192.168.90.15         192.168.2.92          T.38     53     UDP: UDPTLPacket Seq=00017  data:v21: hdlc-data[86]
User Datagram Protocol, Src Port: 5020, Dst Port: 5000
ITU-T Recommendation T.38
     47 5.403527       192.168.90.15         192.168.2.92          T.38     53     UDP: UDPTLPacket Seq=00018  data:v21: hdlc-data[62]
User Datagram Protocol, Src Port: 5020, Dst Port: 5000
ITU-T Recommendation T.38
     48 5.423517       192.168.90.15         192.168.2.92          T.38     53     UDP: UDPTLPacket Seq=00019  data:v21: hdlc-data[04]
User Datagram Protocol, Src Port: 5020, Dst Port: 5000
ITU-T Recommendation T.38
     49 5.463043       192.168.90.15         192.168.2.92          T.38     53     UDP: UDPTLPacket Seq=00020  data:v21: hdlc-data[04]
User Datagram Protocol, Src Port: 5020, Dst Port: 5000
ITU-T Recommendation T.38
     50 5.483714       192.168.90.15         192.168.2.92          T.38     53     UDP: UDPTLPacket Seq=00021  data:v21: hdlc-data[04]
User Datagram Protocol, Src Port: 5020, Dst Port: 5000
ITU-T Recommendation T.38
     51 5.503756       192.168.90.15         192.168.2.92          T.38     53     UDP: UDPTLPacket Seq=00022  data:v21: hdlc-data[04]
User Datagram Protocol, Src Port: 5020, Dst Port: 5000
ITU-T Recommendation T.38
     52 5.543757       192.168.90.15         192.168.2.92          T.38     53     UDP: UDPTLPacket Seq=00023  data:v21: hdlc-data[04]
User Datagram Protocol, Src Port: 5020, Dst Port: 5000
ITU-T Recommendation T.38
     53 5.563267       192.168.90.15         192.168.2.92          T.38     53     UDP: UDPTLPacket Seq=00024  data:v21: hdlc-data[04]
User Datagram Protocol, Src Port: 5020, Dst Port: 5000
ITU-T Recommendation T.38
     54 5.582493       192.168.90.15         192.168.2.92          T.38     53     UDP: UDPTLPacket Seq=00025  data:v21: hdlc-data[04]
User Datagram Protocol, Src Port: 5020, Dst Port: 5000
ITU-T Recommendation T.38
     55 5.623545       192.168.90.15         192.168.2.92          T.38     53     UDP: UDPTLPacket Seq=00026  data:v21: hdlc-data[04]
User Datagram Protocol, Src Port: 5020, Dst Port: 5000
ITU-T Recommendation T.38
     56 5.643574       192.168.90.15         192.168.2.92          T.38     50     UDP: UDPTLPacket Seq=00027  data:v21: hdlc-fcs-OK (HDLC Reassembled: CSI - Called Subscriber Identification - Number:Fax Voip FSP)
User Datagram Protocol, Src Port: 5020, Dst Port: 5000
ITU-T Recommendation T.38
     57 5.762691       192.168.90.15         192.168.2.92          T.38     53     UDP: UDPTLPacket Seq=00028  data:v21: hdlc-data[ff]
User Datagram Protocol, Src Port: 5020, Dst Port: 5000
ITU-T Recommendation T.38
     58 5.803609       192.168.90.15         192.168.2.92          T.38     53     UDP: UDPTLPacket Seq=00029  data:v21: hdlc-data[c8]
User Datagram Protocol, Src Port: 5020, Dst Port: 5000
ITU-T Recommendation T.38
     59 5.823617       192.168.90.15         192.168.2.92          T.38     53     UDP: UDPTLPacket Seq=00030  data:v21: hdlc-data[01]
User Datagram Protocol, Src Port: 5020, Dst Port: 5000
ITU-T Recommendation T.38
     60 5.843635       192.168.90.15         192.168.2.92          T.38     53     UDP: UDPTLPacket Seq=00031  data:v21: hdlc-data[20]
User Datagram Protocol, Src Port: 5020, Dst Port: 5000
ITU-T Recommendation T.38
     61 5.882584       192.168.90.15         192.168.2.92          T.38     53     UDP: UDPTLPacket Seq=00032  data:v21: hdlc-data[77]
User Datagram Protocol, Src Port: 5020, Dst Port: 5000
ITU-T Recommendation T.38
     62 5.903593       192.168.90.15         192.168.2.92          T.38     53     UDP: UDPTLPacket Seq=00033  data:v21: hdlc-data[5f]
User Datagram Protocol, Src Port: 5020, Dst Port: 5000
ITU-T Recommendation T.38
     63 5.923617       192.168.90.15         192.168.2.92          T.38     53     UDP: UDPTLPacket Seq=00034  data:v21: hdlc-data[23]
User Datagram Protocol, Src Port: 5020, Dst Port: 5000
ITU-T Recommendation T.38
     64 5.963153       192.168.90.15         192.168.2.92          T.38     53     UDP: UDPTLPacket Seq=00035  data:v21: hdlc-data[01]
User Datagram Protocol, Src Port: 5020, Dst Port: 5000
ITU-T Recommendation T.38
     65 5.982629       192.168.90.15         192.168.2.92          T.38     53     UDP: UDPTLPacket Seq=00036  data:v21: hdlc-data[a9]
User Datagram Protocol, Src Port: 5020, Dst Port: 5000
ITU-T Recommendation T.38
     66 6.003656       192.168.90.15         192.168.2.92          T.38     53     UDP: UDPTLPacket Seq=00037  data:v21: hdlc-data[01]
User Datagram Protocol, Src Port: 5020, Dst Port: 5000
ITU-T Recommendation T.38
     67 6.043714       192.168.90.15         192.168.2.92          T.38     53     UDP: UDPTLPacket Seq=00038  data:v21: hdlc-data[01]
User Datagram Protocol, Src Port: 5020, Dst Port: 5000
ITU-T Recommendation T.38
     68 6.062854       192.168.90.15         192.168.2.92          T.38     53     UDP: UDPTLPacket Seq=00039  data:v21: hdlc-data[01]
User Datagram Protocol, Src Port: 5020, Dst Port: 5000
ITU-T Recommendation T.38
     69 6.083737       192.168.90.15         192.168.2.92          T.38     53     UDP: UDPTLPacket Seq=00040  data:v21: hdlc-data[18]
...
    229 15.696067      192.168.2.92          192.168.90.15         T.38     60     UDP: UDPTLPacket Seq=00153  data:v21: hdlc-fcs-OK-sig-end (HDLC Reassembled: PPS - Partial Page Signal - PC:0 BC:0 FC:6)
User Datagram Protocol, Src Port: 5000, Dst Port: 5020
ITU-T Recommendation T.38
    230 15.783233      192.168.90.15         192.168.2.92          T.38     48     UDP: UDPTLPacket Seq=00049  t30ind: v21-preamble
User Datagram Protocol, Src Port: 5020, Dst Port: 5000
ITU-T Recommendation T.38
    231 15.917298      192.168.2.92          192.168.90.15         T.38     60     UDP: UDPTLPacket Seq=00154  t30ind: no-signal
User Datagram Protocol, Src Port: 5000, Dst Port: 5020
ITU-T Recommendation T.38
    232 16.782839      192.168.90.15         192.168.2.92          T.38     53     UDP: UDPTLPacket Seq=00050  data:v21: hdlc-data[ff]
User Datagram Protocol, Src Port: 5020, Dst Port: 5000
ITU-T Recommendation T.38
    233 16.823871      192.168.90.15         192.168.2.92          T.38     53     UDP: UDPTLPacket Seq=00051  data:v21: hdlc-data[c8]
User Datagram Protocol, Src Port: 5020, Dst Port: 5000
ITU-T Recommendation T.38
    234 16.843866      192.168.90.15         192.168.2.92          T.38     53     UDP: UDPTLPacket Seq=00052  data:v21: hdlc-data[31]
User Datagram Protocol, Src Port: 5020, Dst Port: 5000
ITU-T Recommendation T.38
    235 16.863888      192.168.90.15         192.168.2.92          T.38     50     UDP: UDPTLPacket Seq=00053  data:v21: hdlc-fcs-OK-sig-end (HDLC Reassembled: MCF - Message Confirmation)
User Datagram Protocol, Src Port: 5020, Dst Port: 5000
ITU-T Recommendation T.38
    236 16.956324      192.168.2.92          192.168.90.15         T.38     60     UDP: UDPTLPacket Seq=00155  t30ind: v21-preamble
User Datagram Protocol, Src Port: 5000, Dst Port: 5020
ITU-T Recommendation T.38
    237 17.083564      192.168.90.15         192.168.2.92          T.38     48     UDP: UDPTLPacket Seq=00054  t30ind: no-signal
User Datagram Protocol, Src Port: 5020, Dst Port: 5000
ITU-T Recommendation T.38
    238 17.958642      192.168.2.92          192.168.90.15         T.38     60     UDP: UDPTLPacket Seq=00156  data:v21: hdlc-data[ff]
User Datagram Protocol, Src Port: 5000, Dst Port: 5020
ITU-T Recommendation T.38
    239 17.997026      192.168.2.92          192.168.90.15         T.38     60     UDP: UDPTLPacket Seq=00157  data:v21: hdlc-data[c8]
User Datagram Protocol, Src Port: 5000, Dst Port: 5020
ITU-T Recommendation T.38
    240 18.017867      192.168.2.92          192.168.90.15         T.38     60     UDP: UDPTLPacket Seq=00158  data:v21: hdlc-data[df]
User Datagram Protocol, Src Port: 5000, Dst Port: 5020
ITU-T Recommendation T.38
    241 18.039872      192.168.2.92          192.168.90.15         T.38     60     UDP: UDPTLPacket Seq=00159  data:v21: hdlc-fcs-OK-sig-end (HDLC Reassembled: DCN - Disconnect)
User Datagram Protocol, Src Port: 5000, Dst Port: 5020
ITU-T Recommendation T.38
    242 19.045961      192.168.90.15         192.168.2.92          SIP      497    Request: BYE sip:890@192.168.2.92:5060 | 
User Datagram Protocol, Src Port: 5069, Dst Port: 5060
Session Initiation Protocol (BYE)
    243 19.154422      192.168.2.92          192.168.90.15         SIP      429    Status: 200 OK | 
User Datagram Protocol, Src Port: 5060, Dst Port: 5069
Session Initiation Protocol (200)
    244 35.820362      192.168.90.15         192.168.2.92          SIP      848    Request: REGISTER sip:192.168.2.92  (1 binding) | 
User Datagram Protocol, Src Port: 5069, Dst Port: 5060
Session Initiation Protocol (REGISTER)
    245 35.903871      192.168.2.92          192.168.90.15         SIP      563    Status: 407 Proxy Authentication Required | 
User Datagram Protocol, Src Port: 5060, Dst Port: 5069
Session Initiation Protocol (407)
    246 35.905845      192.168.90.15         192.168.2.92          SIP      848    Request: REGISTER sip:192.168.2.92  (1 binding) | 
User Datagram Protocol, Src Port: 5069, Dst Port: 5060
Session Initiation Protocol (REGISTER)
    247 35.984123      192.168.2.92          192.168.90.15         SIP      462    Status: 200 OK  (1 binding) | 
User Datagram Protocol, Src Port: 5060, Dst Port: 5069
Session Initiation Protocol (200)

jcolp · November 15, 2017, 11:10am

As this has now gotten quite deep I’d suggest filing an issue on the issue tracker[1] with the information. I have no timeframe on when it will get looked into though or resolved.

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

jdast · November 15, 2017, 11:46pm

Thank you for your advice and support on this matter.

The issue has been filed:

https://issues.asterisk.org/jira/browse/ASTERISK-27424

Thanks again.

Topic		Replies	Views
T.38 not working - help needed with log interpretation Asterisk Support	0	277	November 29, 2014
PJSIP Incomplete SIP Message Asterisk Support	4	34	August 25, 2024
T38 passthrough problem Asterisk Support	1	168	April 22, 2009
Asterisk 1.6.x t38 passthru Asterisk Support	4	237	August 26, 2009
T38 SIP Reinvites Asterisk Support	0	185	March 31, 2009

T.38 Fax passthrough via using PJSIP extensions

freepbx*CLI> udptl show config UDPTL Global options

Related topics

freepbx*CLI> udptl show config
UDPTL Global options