GXW4108 Call Drops by Grandstream during T38 FAX


#1

Dear Support,

We are using GXW4108 to dial and send a T38 Fax page to an external PSTN Number.
Everything is ok, up to when T38 Image (t4-non-ecm-data) starts to be sent to the Gateway. After about 17 seconds of continuous t4-non-ecm-data is sent to the gateway, GXW4108 sends SIP Bye message with "Reason: SIP ;text=“FX call terminated” " . So the call is dropped and the fax is not sent correctly.
We are using Kapanga softphone to send the fax. The gateway is connected to the softphone peer to peer, and not IP PBX is between them. I have also enabled debug on syslog of the device.

T38 feature is enabled on the GXW4108 device, and ECM mode is active. Max fax rate is set to 9600, as you can see on the log. I have also tested other rates, and also disabled ECM mode, but the device behaviour is not changed.

Grandstream GXW4108 firmware: 1.4.1.5

Here is the log:

16338	2018-12-05 09:45:11.655	10.10.10.113	10.10.10.15	Syslog	178	USER.DEBUG: GS_LOG: [00:0B:82:E1:B5:49][000][9660000223A][1.4.1.5] FXO: Port: 0 <Event> Processing (Line Activity Detected), From: 777 , GWSt: 6
16339	2018-12-05 09:45:11.655	10.10.10.113	10.10.10.15	Syslog	162	USER.DEBUG: GS_LOG: [00:0B:82:E1:B5:49][000][9660000223A][1.4.1.5] fxo_ctl.c  Port: 0 APP: app_State:last_fxo_call_status (6:10)
16341	2018-12-05 09:45:11.673	10.10.10.15	10.10.10.113	T.38	208	UDP: UDPTLPacket Seq=00084  data:v29-9600: t4-non-ecm-data[2a7e7b291a8384...] (t4-data fragment 7)
...
16782	2018-12-05 09:45:28.756	10.10.10.15	10.10.10.113	T.38	208	UDP: UDPTLPacket Seq=00509  data:v29-9600: t4-non-ecm-data[d9d6dfd9482240...] (t4-data fragment 432)	
16783	2018-12-05 09:45:28.797	10.10.10.15	10.10.10.113	T.38	208	UDP: UDPTLPacket Seq=00510  data:v29-9600: t4-non-ecm-data[0ee0e56041605a...] (t4-data fragment 433)	
16784	2018-12-05 09:45:28.837	10.10.10.15	10.10.10.113	T.38	208	UDP: UDPTLPacket Seq=00511  data:v29-9600: t4-non-ecm-data[d9d6dfd9482130...] (t4-data fragment 434)	
16785	2018-12-05 09:45:28.846	10.10.10.113	10.10.10.15	Syslog	150	USER.DEBUG: GS_LOG: [00:0B:82:E1:B5:49][000][9660000223A][1.4.1.5]  cm_t38.c 292 terminate t38 status:4 ch:3 port:0 
16787	2018-12-05 09:45:28.846	10.10.10.113	10.10.10.15	Syslog	159	USER.INFO: GS_LOG: [00:0B:82:E1:B5:49][000][9660000223A][1.4.1.5]  cm_rtp.c 955 Audio RTP stats: R 577, S 3388, RE 0, D 2748	
16788	2018-12-05 09:45:28.876	10.10.10.15	10.10.10.113	T.38	208	UDP: UDPTLPacket Seq=00512  data:v29-9600: t4-non-ecm-data[f008540c050950...] (t4-data fragment 435)
16789	2018-12-05 09:45:28.916	10.10.10.15	10.10.10.113	T.38	208	UDP: UDPTLPacket Seq=00513  data:v29-9600: t4-non-ecm-data[d9d6dfd94822b0...] (t4-data fragment 436)
16790	2018-12-05 09:45:28.958	10.10.10.15	10.10.10.113	T.38	208	UDP: UDPTLPacket Seq=00514  data:v29-9600: t4-non-ecm-data[240214830a63a8...] (t4-data fragment 437)
16791	2018-12-05 09:45:28.998	10.10.10.15	10.10.10.113	T.38	208	UDP: UDPTLPacket Seq=00515  data:v29-9600: t4-non-ecm-data[d9d6dfd9482280...] (t4-data fragment 438)
...
16800	2018-12-05 09:45:29.324	10.10.10.15	10.10.10.113	T.38	208	UDP: UDPTLPacket Seq=00523  data:v29-9600: t4-non-ecm-data[d9d6dfd9482170...] (t4-data fragment 446)
16801	2018-12-05 09:45:29.346	10.10.10.113	10.10.10.15	Syslog	229	USER.DEBUG: GS_LOG: [00:0B:82:E1:B5:49][000][9660000223A][1.4.1.5] 868 cm_utility.c Port: 0 Sess: 3, gw(st: 6, sigTmr: 0, s1pCid: 40), sipSt: 6, cccSt: 5, fxo(cs: 10, FAS: 0), ln#: 308, reason: 0
16802	2018-12-05 09:45:29.346	10.10.10.113	10.10.10.15	Syslog	141	USER.DEBUG: GS_LOG: [00:0B:82:E1:B5:49][000][9660000223A][1.4.1.5] FXO: Port: 0 Initiate Hang-Up, From: 897
16803	2018-12-05 09:45:29.346	10.10.10.113	10.10.10.15	Syslog	135	USER.DEBUG: GS_LOG: [00:0B:82:E1:B5:49][000][9660000223A][1.4.1.5] LEC_FXO: Port: 0 Already disabled.
16804	2018-12-05 09:45:29.347	10.10.10.113	10.10.10.15	Syslog	194	USER.DEBUG: GS_LOG: [00:0B:82:E1:B5:49][000][9660000223A][1.4.1.5] 531 cm_control.c Sess: 3 Teardown call (st:6 est'd:1), cc st:5 , acct:0, reason#:119, ln#:926
16805	2018-12-05 09:45:29.347	10.10.10.113	10.10.10.15	Syslog	179	USER.DEBUG: GS_LOG: [00:0B:82:E1:B5:49][000][9660000223A][1.4.1.5] 692 sip_message.c Sess: 3  oport: 0 build SIP req 4 transport=1 222 87 0 0 100
16806	2018-12-05 09:45:29.347	10.10.10.113	10.10.10.15	SIP	605	Request: BYE sip:Username@10.10.10.15:5060;transport=udp | 
	Via: SIP/2.0/UDP 10.10.10.113:5060;branch=z9hG4bK3d6779a22597ee35
	From: <sip:923033000@10.10.10.113>;tag=bea1db778b27de70
	To: "Your Full Name" <sip:Username@10.10.10.15:5060>;tag=5FEE768C15490A9E509AE1FD6975A7F0
	Call-ID: 8595C14FBFC1D278CCBBC3CFECFD39D818BEA@10.10.10.15
	CSeq: 19648 BYE
	User-Agent: Grandstream GXW4108 (HW 2.3, Ch:3) 1.4.1.5
	Max-Forwards: 70
	Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE,UPDATE,PRACK
	Reason: SIP ;text="FX call terminated"
	Content-Length: 0

16807	2018-12-05 09:45:29.349	10.10.10.113	10.10.10.15	Syslog	699	USER.DEBUG: GS_LOG: [00:0B:82:E1:B5:49][000][9660000223A][1.4.1.5] 1602 sip_transport.c Sess: 3 sent: BYE sip:Username@10.10.10.15:5060;transport=udp SIP/2.0  Via: SIP/2.0/UDP 10.10.10.113:5060;branch=z9hG4bK3d6779a22597ee35  From: <sip:923033000@10.10.10.113>;tag=bea1db778b27de70  To: "Your Full Name" <sip:Username@10.10.10.15:5060>;tag=5FEE768C15490A9E509AE1FD6975A7F0  Call-ID: 8595C14FBFC1D278CCBBC3CFECFD39D818BEA@10.10.10.15  CSeq: 19648 BYE  User-Agent: Grandstream GXW4108 (HW 2.3, Ch:3) 1.4.1.5  Max-Forwards: 70  Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE,UPDATE,PRACK  Reason: SIP ;text="FX call terminated"  Content-Length: 0    
16808	2018-12-05 09:45:29.356	10.10.10.113	10.10.10.15	Syslog	163	USER.DEBUG: GS_LOG: [00:0B:82:E1:B5:49][000][9660000223A][1.4.1.5] FXO: Port: 0 <Event> Processing (On-Hook), From: 777 , GWSt: 9
16809	2018-12-05 09:45:29.356	10.10.10.113	10.10.10.15	Syslog	162	USER.DEBUG: GS_LOG: [00:0B:82:E1:B5:49][000][9660000223A][1.4.1.5] fxo_ctl.c  Port: 0 APP: app_State:last_fxo_call_status (9:10)
16810	2018-12-05 09:45:29.356	10.10.10.113	10.10.10.15	Syslog	147	USER.DEBUG: GS_LOG: [00:0B:82:E1:B5:49][000][9660000223A][1.4.1.5] FXO: Port: 0 Set State to: On-Hook, From: 1044
16811	2018-12-05 09:45:29.356	10.10.10.113	10.10.10.15	Syslog	146	USER.DEBUG: GS_LOG: [00:0B:82:E1:B5:49][000][9660000223A][1.4.1.5] TONE_GEN: Port: 0 Stop tone [0] from Line:700
16812	2018-12-05 09:45:29.356	10.10.10.113	10.10.10.15	Syslog	156	USER.DEBUG: GS_LOG: [00:0B:82:E1:B5:49][000][9660000223A][1.4.1.5] FXO: Port: 0 *Call Status* Dispatching (Idle), From:717
16813	2018-12-05 09:45:29.356	10.10.10.113	10.10.10.15	Syslog	139	USER.DEBUG: GS_LOG: [00:0B:82:E1:B5:49][000][9660000223A][1.4.1.5] TONE_DET: Port: 0 Reset Tone Detection
16814	2018-12-05 09:45:29.356	10.10.10.113	10.10.10.15	Syslog	147	USER.DEBUG: GS_LOG: [00:0B:82:E1:B5:49][000][9660000223A][1.4.1.5] TONE_DET_DTMF: Port: 0 Disable DTMF Detection.
16815	2018-12-05 09:45:29.357	10.10.10.113	10.10.10.15	Syslog	161	USER.DEBUG: GS_LOG: [00:0B:82:E1:B5:49][000][9660000223A][1.4.1.5] TONE_DET_CPT: Port: 0 Disable CPT Detection, tone mask: 000F
16816	2018-12-05 09:45:29.357	10.10.10.113	10.10.10.15	Syslog	153	USER.DEBUG: GS_LOG: [00:0B:82:E1:B5:49][000][9660000223A][1.4.1.5] FXO_CID: Port: 0 Disabling detection, Type: BELLCORE
16817	2018-12-05 09:45:29.357	10.10.10.113	10.10.10.15	Syslog	149	USER.DEBUG: GS_LOG: [00:0B:82:E1:B5:49][000][9660000223A][1.4.1.5] FXO: Port: 0 Get *Call Status* (Idle), From:1871
16818	2018-12-05 09:45:29.357	10.10.10.113	10.10.10.15	Syslog	176	USER.DEBUG: GS_LOG: [00:0B:82:E1:B5:49][000][9660000223A][1.4.1.5] cm_task.c 1899 Port: 0  GWSt: 9 Sess: 3 9 fxoCallStatus last/now=10/0 FAS:0
16819	2018-12-05 09:45:29.357	10.10.10.113	10.10.10.15	Syslog	232	USER.DEBUG: GS_LOG: [00:0B:82:E1:B5:49][000][9660000223A][1.4.1.5] 868 cm_utility.c Port: 0 Sess: 3, gw(st: 9, sigTmr: 1799, s1pCid: 40), sipSt: 6, cccSt: 1, fxo(cs: 0, FAS: 0), ln#: 1925, reason: 0
16820	2018-12-05 09:45:29.365	10.10.10.15	10.10.10.113	T.38	208	UDP: UDPTLPacket Seq=00524  data:v29-9600: t4-non-ecm-data[05f6182481fb1c...] (t4-data fragment 447)
16821	2018-12-05 09:45:29.405	10.10.10.15	10.10.10.113	T.38	208	UDP: UDPTLPacket Seq=00525  data:v29-9600: t4-non-ecm-data[d9d6dfd9482080...] (t4-data fragment 448)
16822	2018-12-05 09:45:29.444	10.10.10.15	10.10.10.113	T.38	208	UDP: UDPTLPacket Seq=00526  data:v29-9600: t4-non-ecm-data[031bd01240fd8e...] (t4-data fragment 449)
16823	2018-12-05 09:45:29.446	10.10.10.113	10.10.10.15	Syslog	197	USER.DEBUG: GS_LOG: [00:0B:82:E1:B5:49][000][9660000223A][1.4.1.5] FXO: Port: 0 Line Event triggered is: 1 Previous Event was: 3 current line Status is: 4 count: 8
16825	2018-12-05 09:45:29.480	10.10.10.15	10.10.10.113	SIP	645	Status: 200 OK | 
16826	2018-12-05 09:45:29.482	10.10.10.113	10.10.10.15	Syslog	756	USER.DEBUG: GS_LOG: [00:0B:82:E1:B5:49][000][9660000223A][1.4.1.5] 1324 sip.c Acct:0 h-port:5060 Received SIP message: SIP/2.0 200 OK  Via: SIP/2.0/UDP 10.10.10.113:5060;branch=z9hG4bK3d6779a22597ee35  User-Agent: Kapanga Softphone Desktop Windows 1.00/2182d+1543930792_1C6F6543B11D_00AC38183110_00FFB3D11AC8_005056C00001_005056C00008_1CBDB980FDF6_1CBDB980FDF0_1CBDB980FDF7 (not registered)  From: <sip:923033000@10.10.10.113>;tag=bea1db778b27de70  To: "Your Full Name" <sip:Username@10.10.10.15:5060>;tag=5FEE768C15490A9E509AE1FD6975A7F0  Call-ID: 8595C14FBFC1D278CCBBC3CFECFD39D818BEA@10.10.10.15  CSeq: 19648 BYE  Contact: <sip:Username@10.10.10.15:5060;transport=udp>  Supported: timer, replaces  Content-Length: 0    
16827	2018-12-05 09:45:29.482	10.10.10.113	10.10.10.15	Syslog	146	USER.DEBUG: GS_LOG: [00:0B:82:E1:B5:49][000][9660000223A][1.4.1.5] TONE_GEN: Port: 0 Stop tone [0] from Line:427
16843	2018-12-05 09:45:29.976	10.10.10.113	10.10.10.15	Syslog	206	USER.DEBUG: GS_LOG: [00:0B:82:E1:B5:49][000][9660000223A][1.4.1.5] 765 cm_utility.c Port: 0 Sess: 3 ST(gw:9 sip:6 cal:1), rtp:1 t38:1 aprt:0 udptl:5112 cs:0, ln#:950, FIN !
16844	2018-12-05 09:45:29.976	10.10.10.113	10.10.10.15	Syslog	159	USER.DEBUG: GS_LOG: [00:0B:82:E1:B5:49][000][9660000223A][1.4.1.5] 247 sip.c Sess: 3, st:6, SIP Init'd, O-0, ln#:798, ogln#:0

Regards,
Jalal Abedinejad


#2

Hi,

I did receive no response!!! Would you please help me?

If you know any softphone which you are sure it can send T.38 fax through GXW4108 without any problem, please tell me to test it.

Thanks


#3

A couple of things:

The forum is a user to user forum, not a Grandstream support forum. If you wish to contact support, you will need to submit a ticket.

The syslog is taken from the GS side. A packet capture would likely provide more insight as to what is happening. From what I gather however, it appears that the GXW saw the call and transitioned to t.38 but the other side did not.

A capture would show the complete messaging in a flow format to include seeing what ports are in use at which stages of the call to include the transition. This may involve ports that if the endpoints are behind firewalls, that may not be open and forwarded.


#4

Sorry I did not know about the goals of this forum.

The GXW and our softphone PC are connected directly with a cross cable. So I’m sure there is no firewall between them, because our firewall on my PC is off.

This is the wireshark capture file:


#5

There were 2 calls. The first never resulted in a t.38 transition, it was all at audio g711u.
The second call, did result in the GXW doing a re-invite to t.38, and their was an attempt between both sites to train to one another at 9600, but it failed with a BYE coming from the GXW after 18 seconds of not being able to negotiate.

While not specifically an issue, but rather an observation, the Kapanga softphone appears to be quite old with little to no development since 2009. The max speed they support is v29 which is 9600. Most fax devices, to include the GXW will support up to v.34 or 14.4Kbps.

Again, this is not to say that it cannot be made to work, but that given what it appears to support and the lack of development in the past 10 years, makes it questionable as to how robust the application is and if the developer has found any issues and made any corrections or improvements in the meantime. Additionally, the user forum appears to be down and inaccessible; so not much help there.

In any event, if it were me, I would insure that the fax machine, Kapanga and the GXW are all set with echo cancellation off, ECM set to off and 9600. If not successful, then lower the speed until such time as all fail or your patience expires.

I noticed that you are also pressing 8# during the calls and am uncertain why, can you enlighten?

There are a few companies that have either a softphone or an application that will accommodate FoIP. I have no personal knowledge of any as I am one who wishes that faxing would simply die and forever be banished from the planet. In any event a Google search will provide some results as it did for me. I have included one such link, but again I have no idea about it other than the search result.

http://www.t38faxvoip.com/


#6

Yes, you are completely correct about 2 calls you mentioned.

You are not correct about limitations of Kapanga, because I have set the rate of fax on GXW to 9600, as it is the default value of GXW. So Kapanga is replied by 200 OK and rate of 9600. It completely suppurts v.17 14400.

I have tested with Kapanga softphone, as we had the same issue with our SIP IVR (implemented by our company). So I’m not here to fix Kapanga’s behavior, I want to find the cause of why GrandStream disconnects the T.38 Call.

As you said “it failed with a BYE coming from the GXW after 18 seconds of not being able to negotiate”: I’m sure GXW has negotiated T.38, because we have received DIS and also CFR t38 packets from GXW part, so that sending the image from Kapanga is started.

So the big question is why GXW terminates the Call with a SIP BYE message. Is there any way to clarify the main reason of this disconnection of Call?

About pressing 8#, I did not enlighten, but it is here, because fax receiver is also IVR on FXO part.

I will test t38faxvoip softphone, and will send you the result soon.

Thanks


#7

Two other things:

1- Your latest firmware for GXW is for year 2013, as you mentioned in the release notes. But it does not mean the project is stopped. Maybe it means you did not find any new issues to be fixed. And the same reason may exist for Kapanga.

2- I have tested Kapanga with Cisco Gateways, and some other Gateways, and I have never had such issue with that. So you may install and test this software with GXW in your company, to trace the issue. Maybe there is some misconfiguration done on GXW by us. Kapanga trial version can be downloaded from their site, and it works for 30 days.


#8

You are indeed correct about my mistake in V.34 versus V.17 with regard to speed. However, my point was that in looking at their website, the application does not appear to be well supported and in that vein may not be as robust as it could be if the developer has not made any improvements over the past 9-10 years. It also may be that they have made improvements that are not reflected in the website, but one would think that if they had and if they wanted to attract potential buyers, they would be more proactive in their efforts to keep the website more up to date.

The 200OK means only that the connection and codec was accepted as a means of conveyance, but it still has to negotiate to the satisfaction of the endpoint faxing devices at the analog level. Why the devices could not find a happy ground, I do not know. I can only say that the GXW did the re-invite and Kapanga OK’ed it. I don’t think that the GXW actually ended the call on its own accord. I suspect that the device behind the GXW, that was not able to negotiate with the other end, timed out and disconnected which is what caused the BYE.


#9

I think it’s better stop discussing about Kapanga, because it is just a sample program for test purposes in our department. As I said before, we have seen the same problem on other softwares too.

Believe me, I’m really an expert on both SIP, T.38, Fax T30. I have implemented both T.38 and Fax Passthrough on our IVR software. So I’m familiar with all aspects of these protocols.

On a T.38 session, when two faxes start to negotiate, they send and receive following signals (based on t30 standard):
Sender Receiver
<-- DIS
DCS+TCF -->
<-- CFR
t4-image -->

When receiver fax sends CFR (Confirmation to Receive), it means the sample data is completely received on prior TCF packet, so the sender is allowed to start sending fax image. Note that here CFR is not sent by the GXW gateway itself, but GXW has received it on FXO line from real fax, and converted to T.38 packet and sent to the Kapanga softphone. CFR packet exists on wireshark sample I sent you before.

So “negotiation problem” supposition is rejected.

Again I did not find my question’s answer: “why GXW terminates the Call with a SIP BYE message. Is there any way to clarify the main reason of this disconnection of Call?”


#10

As far i checked fax should start but it not starting. You can try Syslog from GXW but i doubt it will show something. GXW can be wrong or simply it do not receive anything more.

For test you should try other fax machine and see if it start sending FAX or you will have same problem.
As write at first sending it in reverse work, so GXW correctly translate VOIP to PSTN.

Syslog can show you who disconnect PSTN AFAIR.


#11

Syslog is enabled on the GXW up to debug level. You can see the syslog on the wireshark capture I sent. I did not find any obvious reason for disconnect.

I have recorded FXO line voice, while the above sending fax test is done with Kapanga. During above 18 seconds you mentioned, GXW is sending the image without problem. After GXW terminates the call, T.38 image packets are not translated to FXO, so then there is about 2 seconds silence, and then FXO is onhooked.


#12

This is the Debug syslog received before call termination by GXW:

<15>GS_LOG: [00:0B:82:E1:B5:49][000][9660000223A][1.4.1.5] cm_t38.c 292 terminate t38 status:4 ch:3 port:0

Maybe this should you point to line 292 on cm_t38.c file. You should check your code, and see what’s the terminate reason on this state. Note about status:4 (maybe it can help)


#13

Yeah. Sorry i should check better this log.

I can see 1 correct training then Kapanga initiate next training, but this is real FAX (i think) with 446 fragments, there is no way that is training at all. Training is top 1-2s not >15s.
I guess some timer in GXW make drop there.

But i cannot say for sure as i have no idea what the hell this is: “cm_t38.c 292”

For sure GXW drop it, no indication for external drop (unless no log from PSTN fax order in syslog).


#14

By the standard , fax sender sends a long training first, which is named TCF and is sent after DCS, and is about 2 seconds. After receiving CFR, a short training message is sent and immediately fax image is sent in t4_non_ecm messages. So the second training you mentioned is not by mistake, and is by standard. It takes more than 15 seconds, because it is the real image compressed in t4 packets.

You should check your source code for cm_t38.c line number 292. If you could send me this file in private, I can help you finding the bug.


#15

This is a user to user forum, not the official GS support channel, None of us has access to source code.


#16

Make a ticket to GS directly we cannot help you more.
As for long training: try shot FAX instead of long then maybe it work and confirm bug.


#17

Thanks for your help.

I made a ticket at helpdesk.