Problem with PJSIP and FAX

ast2301 · January 8, 2018, 11:08am

Today I tried to receive a fax with ReceiveFax(fax.tif, d). Unfortunately Asterisk 15.1.5 crashed:

DEBUG[2831][C-00000001]: channel.c:5551 set_format: Channel PJSIP/100-00000000 setting write format path: g722 -> g722
DEBUG[2831][C-00000001]: channel.c:3192 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second
DEBUG[2831][C-00000001]: res_fax.c:1923 receivefax_t38_init: Negotiating T.38 for receive on PJSIP/100-00000000
DEBUG[2798]: res_pjsip_t38.c:273 t38_initialize_session: UDPTL initialized on session for PJSIP/100-00000000
DEBUG[2798]: res_pjsip_t38.c:143 t38_change_state: T.38 state changed to '1' from '0' on channel 'PJSIP/100-00000000'
DEBUG[2798]: res_pjsip_session.c:1577 ast_sip_session_refresh: Sending session refresh SDP via re-INVITE to 100
DEBUG[2798]: res_pjsip_session.c:3203 handle_outgoing_request: Method is INVITE
DEBUG[2798]: res_pjsip_session.c:3108 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE
DEBUG[2798]: res_pjsip_session.c:3122 __print_debug_details: The state change pertains to the endpoint '100(PJSIP/100-00000000)'
DEBUG[2798]: res_pjsip_session.c:3127 __print_debug_details: The inv session still has an invite_tsx (0x7f....)
DEBUG[2798]: res_pjsip_session.c:3133 __print_debug_details: The UAC INVITE transaction involved in this state change is 0x7f....
DEBUG[2798]: res_pjsip_session.c:3137 __print_debug_details: The current transaction state is Calling
DEBUG[2798]: res_pjsip_session.c:3139 __print_debug_details: The transaction state change event is TX_MSG
DEBUG[2798]: res_pjsip_session.c:3144 __print_debug_details: The current inv state is CONFIRMED
DEBUG[2797]: res_pjsip/pjsip_distributor.c:502 distributor: Searching for serializer associated with dialog dlg0x7f... for Response msg 100/INVITE/cseq=2255 (rdata0x7f21ec000ae8)
DEBUG[2797]: res_pjsip/pjsip_distributor.c:510 distributor: Found serializer pjsip/distributor-00000040 associated with dialog dlg0x7f...
DEBUG[2798]: res_pjsip_session.c:3108 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE
DEBUG[2798]: res_pjsip_session.c:3122 __print_debug_details: The state change pertains to the endpoint '100(PJSIP/100-00000000)'
DEBUG[2798]: res_pjsip_session.c:3127 __print_debug_details: The inv session still has an invite_tsx (0x7f....)
DEBUG[2798]: res_pjsip_session.c:3133 __print_debug_details: The UAC INVITE transaction involved in this state change is 0x7f....
DEBUG[2798]: res_pjsip_session.c:3137 __print_debug_details: The current transaction state is Proceeding
DEBUG[2798]: res_pjsip_session.c:3139 __print_debug_details: The transaction state change event is RX_MSG
DEBUG[2798]: res_pjsip_session.c:3144 __print_debug_details: The current inv state is CONFIRMED
DEBUG[2798]: res_pjsip_session.c:3187 handle_incoming: Received response
DEBUG[2798]: res_pjsip_session.c:3171 handle_incoming_response: Response is 100 Trying
DEBUG[2797]: res_pjsip/pjsip_distributor.c:502 distributor: Searching for serializer associated with dialog dlg0x7f... for Response msg 100/INVITE/cseq=2255 (rdata0x7f21ec000ae8)
DEBUG[2797]: res_pjsip/pjsip_distributor.c:510 distributor: Found serializer pjsip/distributor-00000040 associated with dialog dlg0x7f...
WARNING[2831][C-00000001]: res_fax.c:1951 receivefax_t38_init: error on 'PJSIP/100-00000000' while waiting for T.38 negotiation.
DEBUG[2798]: res_pjsip_session.c:3108 __print_debug_details: Function session_inv_on_tsx_state_changed called on event TSX_STATE
DEBUG[2798]: res_pjsip_session.c:3122 __print_debug_details: The state change pertains to the endpoint '100(PJSIP/100-00000000)'
DEBUG[2798]: res_pjsip_session.c:3130 __print_debug_details: The inv session does NOT have an invite_tsx
DEBUG[2798]: res_pjsip_session.c:3133 __print_debug_details: The UAC INVITE transaction involved in this state change is 0x7f....
DEBUG[2798]: res_pjsip_session.c:3137 __print_debug_details: The current transaction state is Terminated
DEBUG[2798]: res_pjsip_session.c:3139 __print_debug_details: The transaction state change event is RX_MSG
DEBUG[2798]: res_pjsip_session.c:3144 __print_debug_details: The current inv state is CONFIRMED
DEBUG[2798]: res_pjsip_session.c:3187 handle_incoming: Received response
DEBUG[2798]: res_pjsip_session.c:3171 handle_incoming_response: Response is 100 OK
ERROR[2831][C-00000001]: res_fax.c:2253 receivefax_exec: error initializing channel 'PJSIP/100-00000000' in T.38 mode
DEBUG[2831][C-00000001]: pbx.c:4390 __ast_pbx_run: Spawn extension (user,10,1) exited non-zero on 'PJSIP/100-00000000'
DEBUG[2831][C-00000001]: channel.c:2496 ast_softhangup_nolock: Soft-Hanging (0x10) up channel 'PJSIP/100-00000000'
DEBUG[2831][C-00000001]: pbx_lua.c:1485 lua_find_extension: Looking up h@user:1
DEBUG[2831][C-00000001]: channel.c:2587 ast_hangup: Channel 0x7f21b4034328 'PJSIP/100-00000000' hanging up.  Refs: 2
DEBUG[2798]: res_pjsip_t38.c:143 t38_change_state: T.38 state changed to '3' from '1' on channel 'PJSIP/100-00000000'
Segmentation fault (core dumped)

What’s the problem?

Endpoint config for fax:

t38_udptl=yes
t38_udptl_ec=redundancy
t38_udptl_maxdatagram=400

jcolp · January 8, 2018, 11:12am

You would need to provide the full SIP log (using pjsip set logger on) to see the actual negotiation and what was going on. For the crash it may be the same as ASTERISK-27488[1] but a backtrace[2] would confirm it.

[1] https://issues.asterisk.org/jira/browse/ASTERISK-27488
[2] https://wiki.asterisk.org/wiki/display/AST/Getting+a+Backtrace

ast2301 · January 8, 2018, 11:15am

Is the SDP part enough or do you need the complete SIP packets?

jcolp · January 8, 2018, 11:16am

Everything is the best as it shows exactly what is going on in its entirety.

ast2301 · January 8, 2018, 11:19am

<--- Transmitting SIP request (858 bytes) to UDP:SOFTPHONE --->
INVITE sip:200@SOFTPHONE SIP/2.0
Via: SIP/2.0/UDP ASTERISK;rport;branch=z9hG4bKPj7bdf8fa3-1860-45d4-aaf0-27e69713335c
From: <sip:10@ASTERISK>;tag=c6b19710-8ec9-4cba-8111-0315c67daa45
To: <sip:200@ASTERISK>;tag=1276331130
Contact: <sip:ASTERISK>
Call-ID: 260589275
CSeq: 14701 INVITE
Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, REFER, MESSAGE
Supported: 100rel, timer, replaces, norefersub
Session-Expires: 1800
Min-SE: 90
Max-Forwards: 70
User-Agent: Asterisk PBX
Content-Type: application/sdp
Content-Length:   245

v=0
o=- 158 1085 IN IP4 ASTERISK
s=Asterisk
c=IN IP4 ASTERISK
t=0 0
m=image 30231 udptl t38
a=T38FaxVersion:0
a=T38MaxBitRate:14400
a=T38FaxRateManagement:transferredTCF
a=T38FaxMaxDatagram:1400
a=T38FaxUdpEC:t38UDPRedundancy

<--- Received SIP response (338 bytes) from UDP:SOFTPHONE --->
SIP/2.0 100 Trying
Via: SIP/2.0/UDP ASTERISK;rport=5061;branch=z9hG4bKPj7bdf8fa3-1860-45d4-aaf0-27e69713335c
From: <sip:10@ASTERISK>;tag=c6b19710-8ec9-4cba-8111-0315c67daa45
To: <sip:200@ASTERISK>;tag=1276331130
Call-ID: 260589275
CSeq: 14701 INVITE
Content-Length: 0


<--- Received SIP response (509 bytes) from UDP:SOFTPHONE --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP ASTERISK;rport=5061;branch=z9hG4bKPj7bdf8fa3-1860-45d4-aaf0-27e69713335c
From: <sip:10@ASTERISK>;tag=c6b19710-8ec9-4cba-8111-0315c67daa45
To: <sip:200@ASTERISK>;tag=1276331130
Call-ID: 260589275
CSeq: 14701 INVITE
Contact: <sip:200@SOFTPHONE>
Content-Type: application/sdp
Content-Length:   107

v=0
o=200 158 1083 IN IP4 SOFTPHONE
s=Talk
c=IN IP4 0.0.0.0
t=0 0
m=image 0 RTP/AVP 0
a=inactive

<--- Transmitting SIP request (345 bytes) to UDP:SOFTPHONE --->
ACK sip:200@SOFTPHONE SIP/2.0
Via: SIP/2.0/UDP ASTERISK;rport;branch=z9hG4bKPjd4f4e5f5-6065-4a7f-a969-abb3f53d3fd2
From: <sip:10@ASTERISK>;tag=c6b19710-8ec9-4cba-8111-0315c67daa45
To: <sip:200@ASTERISK>;tag=1276331130
Call-ID: 260589275
CSeq: 14701 ACK
Max-Forwards: 70
User-Agent: Asterisk PBX
Content-Length:  0
Segmentation fault (core dumped)

jcolp · January 8, 2018, 11:23am

It appears as though they accepted but rejected the T.38 renegotiation. Instead of sending a 488 response they accepted the SDP negotiation but marked the T.38 stream as rejected.

jcolp · January 8, 2018, 11:25am

It’s also possible that is not a particularly case that the new stream code in 15 is handling right now (I don’t think I’ve ever seen that) for fax so filing an issue[1] with a backtrace would be good.

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

ast2301 · January 9, 2018, 9:38pm

My ITSP doesn’t support T.38, so I couldn’t work. I tried with T.30 over G.711 (alaw). Another problem:

WARNING[3160][C-00000001]: res_fax.c:4670 acf_faxopt_write: channel 'PJSIP/ENDPOINT-00000001' set FAXOPT(filename) to '/tmp/fax.tif' is unhandled!

WARNING[3160][C-00000001]: res_fax.c:2508 sendfax_t38_init: Audio FAX not allowed on channel 'PJSIP/ENDPOINT-00000001' and T.38 negotiation failed; aborting.

ERROR[3160][C-00000001]: res_fax.c:2784 sendfax_exec: error initializing channel 'PJSIP/ENDPOINT-00000001' in T.38 mode

NOTICE[3160][C-00000001]: pbx_spool.c:460 attempt_thread: Call completed to PJSIP/ENDPOINT/sip:CALLEDNUMBER

The tif file was generated by

gs -q -dNOPAUSE -dBATCH -sDEVICE=tiffg3 -sPAPERSIZE=a4 -g1680x2285 -sOutputFile=fax.tif fax.pdf

I executed before:

fax set debug on

This info I got from Wireshark:

Screenshot_2018-01-09_22-36-46

Asterisk version 13.18.5 (yes, I changed)

jcolp · January 9, 2018, 9:41pm

You have to explicitly allow audio based faxing on the channel, it’s an argument to the dialplan application. I do not know what it is but it is in its documentation.

ast2301 · January 9, 2018, 9:46pm

Do you mean ‘f’ ?

https://wiki.asterisk.org/wiki/display/AST/Application_SendFAX

jcolp · January 9, 2018, 9:48pm

Yes, that would be the option.

ast2301 · January 9, 2018, 9:51pm

Still this error:

channel 'PJSIP/ENDPOINT-00000004' set FAXOPT(filename) to '/tmp/fax.tif' is unhandled!

but the data was transmitted, I can see it with Wireshark!

ast2301 · January 9, 2018, 9:58pm

My FAXOPT:

ecm: yes
headerinfo:Test
localstationid:12345
maxrate:14400
minrate:2400

Topic		Replies	Views
T.38 fax fails with no specific error Asterisk Fax	7	1030	July 18, 2018
PROBLEM T.38 and FAX PJSIP - 488 NOT ACCEPT HERE Asterisk Support	22	4802	September 26, 2018
PJSIP Incomplete SIP Message Asterisk Support	4	35	August 25, 2024
ReceiveFax problem - disconnected after permitted retries Asterisk Support	0	976	November 19, 2014
Sip Fax lot of error Asterisk Support	9	1396	October 7, 2011

Problem with PJSIP and FAX

Related topics