Summary:	ASTERISK-28887: sendFAX fail with T.38
Reporter:	Yasiru Gaminda (yasiru)	Labels:	fax
Date Opened:	2020-05-12 05:42:11	Date Closed:	2020-05-15 04:18:19
Priority:	Major	Regression?
Status:	Closed/Complete	Components:	Resources/res_fax Resources/res_fax_spandsp
Versions:	16.2.0	Frequency of Occurrence	Constant
Related Issues:
Environment:	AWS Debian GNU/Linux 10 (buster)	Attachments:
Description:	sendFAX dialplan application stop responding after send OK for T.38 re-invite. I manage to send fax using G711 without issues. Only issue is with T.38. Debug log is like below, {noformat} [May 12 19:25:44] DEBUG[21084][C-00000039] pbx_variables.c: Result of 'fax_file' is '/home/admin/files/20.tiff' [May 12 19:25:44] DEBUG[21084][C-00000039] pbx.c: Launching 'SendFAX' [May 12 19:25:44] DEBUG[21084][C-00000039] res_fax.c: Reserving a FAX session from 'Spandsp FAX Driver'. [May 12 19:25:44] DEBUG[21084][C-00000039] res_fax.c: Selected FAX technology module (Spandsp FAX Driver) does not support reserving sessions. [May 12 19:25:44] DEBUG[21084][C-00000039] channel.c: Channel SIP/staging-mediagw-00000035 setting write format path: slin -> alaw [May 12 19:25:44] DEBUG[21084][C-00000039] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [May 12 19:25:44] DEBUG[21084][C-00000039] res_rtp_asterisk.c: Ooh, format changed from none to alaw [May 12 19:25:44] DEBUG[21084][C-00000039] res_rtp_asterisk.c: Starting RTCP transmission on RTP instance '0x7fb448015560' ... [May 12 19:25:45] DEBUG[21084][C-00000039] chan_sip.c: T38 state changed to 3 on channel SIP/staging-mediagw-00000035 [May 12 19:25:45] DEBUG[21084][C-00000039] chan_sip.c: Done building SDP. Settling with this capability: (nothing) [May 12 19:25:45] DEBUG[21084][C-00000039] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 3.105.135.109:5060 [May 12 19:25:45] DEBUG[21084][C-00000039] channel.c: Channel SIP/staging-mediagw-00000035 setting write format path: alaw -> alaw [May 12 19:25:45] DEBUG[21084][C-00000039] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [May 12 19:25:45] DEBUG[21084][C-00000039] res_fax.c: Negotiated T.38 for send on SIP/staging-mediagw-00000035 [May 12 19:25:45] DEBUG[21084][C-00000039] res_fax.c: Requesting a new FAX session from 'Spandsp FAX Driver'. ... [May 12 19:25:45] DEBUG[21084][C-00000039] res_fax.c: channel 'SIP/staging-mediagw-00000035' using FAX session '46' [May 12 19:25:45] DEBUG[21084][C-00000039] res_fax.c: channel SIP/staging-mediagw-00000035 will wait on FAX fd 27 [May 12 19:25:45] FAX[21084][C-00000039] res_fax.c: FLOW T.38 Tx     0: indicator no-signal [May 12 19:25:45] FAX[21084][C-00000039] res_fax.c: FLOW T.38 Tx     1: indicator cng ... [May 12 19:26:28] DEBUG[21084][C-00000039] res_fax.c: Channel 'SIP/staging-mediagw-00000035' did not return a frame; probably hung up. [May 12 19:26:28] FAX[21084][C-00000039] res_fax.c: FLOW T.30 Status changing to 'The call dropped prematurely' [May 12 19:26:28] DEBUG[21084][C-00000039] res_fax_spandsp.c: FAX session '46' entering phase E [May 12 19:26:28] DEBUG[21084][C-00000039] res_fax_spandsp.c: FAX session '46' completed with result: FAILED (The call dropped prematurely) [May 12 19:26:28] FAX[21084][C-00000039] res_fax.c: FLOW T.30 Changing from state 18 to 30 [May 12 19:26:28] FAX[21084][C-00000039] res_fax.c: FLOW T.30 Changing from phase T30_PHASE_A_CNG to T30_PHASE_CALL_FINISHED [May 12 19:26:28] FAX[21084][C-00000039] res_fax.c: FLOW T.38T Set rx type 9 [May 12 19:26:28] FAX[21084][C-00000039] res_fax.c: FLOW T.38T Set tx type 9 [May 12 19:26:28] FAX[21084][C-00000039] res_fax.c: FLOW T.38T FAX exchange complete [May 12 19:26:28] FAX[21084][C-00000039] res_fax.c: FLOW T.30 Call completed [May 12 19:26:28] DEBUG[21084][C-00000039] res_fax_spandsp.c: FAX session '46' is complete. [May 12 19:26:28] DEBUG[21084][C-00000039] res_fax.c: channel 'SIP/staging-mediagw-00000035' - event loop stopped { timeout: 10000, remaining_time: 9990 } {noformat} Kindly request f you need more information.
Comments:	By: Asterisk Team (asteriskteam) 2020-05-12 05:42:12.836-0500 Thanks for creating a report! The issue has entered the triage process. That means the issue will wait in this status until a Bug Marshal has an opportunity to review the issue. Once the issue has been reviewed you will receive comments regarding the next steps towards resolution. A good first step is for you to review the [Asterisk Issue Guidelines|https://wiki.asterisk.org/wiki/display/AST/Asterisk+Issue+Guidelines] if you haven't already. The guidelines detail what is expected from an Asterisk issue report. Then, if you are submitting a patch, please review the [Patch Contribution Process|https://wiki.asterisk.org/wiki/display/AST/Patch+Contribution+Process]. Please note that once your issue enters an open state it has been accepted. As Asterisk is an open source project there is no guarantee or timeframe on when your issue will be looked into. If you need expedient resolution you will need to find and pay a suitable developer. Asking for an update on your issue will not yield any progress on it and will not result in a response. All updates are posted to the issue when they occur. By: Joshua C. Colp (jcolp) 2020-05-12 05:45:45.697-0500 We do not support old versions of Asterisk, please upgrade to the latest and retest. If the problem still occurs then provide a complete SIP trace in addition to console output. By: Yasiru Gaminda (yasiru) 2020-05-13 02:05:31.602-0500 Sure, I have upgrade asterisk to 16.10 which is the latest LTS version I could found. Retested and issue is still there. I have attached sip trace and debug log to the ticket (fax-trace-20200513.txt and asterisk-debug-20200513.txt). By: Yasiru Gaminda (yasiru) 2020-05-13 02:06:53.047-0500 retest with asterisk 16.10. By: Joshua C. Colp (jcolp) 2020-05-13 04:21:27.441-0500 Can you please also attach a packet capture, and a full console log including verbose? By: Yasiru Gaminda (yasiru) 2020-05-13 23:08:19.865-0500 I have attached pcap and console log from today call sample. By: Joshua C. Colp (jcolp) 2020-05-14 04:41:11.141-0500 Have you port forwarded the UDPTL port range (4000 to 4999) to Asterisk? I see Asterisk sending out the T.38 UDPTL packets, but it is receiving nothing from the remote side. By: Yasiru Gaminda (yasiru) 2020-05-14 21:33:09.926-0500 Thanks Joshua pointing out the issue. It was a firewall issue in middle gateway which wasn't allow in/out 4000-4999 udp port range.