Communication hanging for long hours: Q2687

[pawelal]

I have some issues with my Q2687RD application. I have the computer in the internet and this computer once ever 10s sends a small data packet to the modem. Usually everything is fine, but occasionally I have something like this in TRACES:

ADL_GPRS_EVENT_ME_ATTACH
[WIP] CID NOT FOUND [5]

followed by

CSQ:99,99

After this the modem itself closes all sockets and until I make a full reset no communication is possible. The CSQ however gets back to normal (20,0) in few seconds.
This is the situation with FW 7.47.6

Additionally in FW 7.47.4 I have another problem:
The above situation also happens quite frequently, but I make a restart if I don’t receive any data for longer than 30s so… I can live with it…
But once a couple of days/hours I get something similar to this:

2013-07-15	13:12:32:628	1	ADL	1	UNKTNOWN gprsHandler ERROR 23
2013-07-15	13:12:32:629	1	ADL	1	UNKTNOWN gprsHandler ERROR 23
2013-07-15	13:12:32:630	1	ADL	1	UNKTNOWN gprsHandler ERROR 23
2013-07-15	13:12:32:630	2	ADL	1	UNKTNOWN gprsHandler ERROR 23
2013-07-15	13:12:32:631	1	ADL	1	UNKTNOWN gprsHandler ERROR 23
2013-07-15	13:12:32:632	1	ADL	1	UNKTNOWN gprsHandler ERROR 23
2013-07-15	13:12:32:633	1	ADL	1	UNKTNOWN gprsHandler ERROR 23
2013-07-15	13:12:32:633	2	ADL	1	UNKTNOWN gprsHandler ERROR 23
2013-07-15	13:12:32:634	1	ADL	1	UNKTNOWN gprsHandler ERROR 23
2013-07-15	13:12:32:634	2	ADL	1	UNKTNOWN gprsHandler ERROR 23
2013-07-15	13:12:32:635	1	ADL	1	UNKTNOWN gprsHandler ERROR 23
2013-07-15	13:12:32:636	1	ADL	1	UNKTNOWN gprsHandler ERROR 23
2013-07-15	13:12:32:637	1	ADL	1	UNKTNOWN gprsHandler ERROR 23
2013-07-15	13:12:32:637	2	ADL	1	UNKTNOWN gprsHandler ERROR 23
2013-07-15	13:12:32:638	1	ADL	1	UNKTNOWN gprsHandler ERROR 23
2013-07-15	13:12:32:639	1	ADL	1	UNKTNOWN gprsHandler ERROR 23
2013-07-15	13:12:32:639	2	ADL	1	UNKTNOWN gprsHandler ERROR 23
2013-07-15	13:12:32:640	1	ADL	1	UNKTNOWN gprsHandler ERROR 23
2013-07-15	13:12:32:641	1	ADL	1	UNKTNOWN gprsHandler ERROR 23
2013-07-15	13:12:32:641	2	ADL	1	UNKTNOWN gprsHandler ERROR 23
2013-07-15	13:12:32:642	1	ADL	1	UNKTNOWN gprsHandler ERROR 23
2013-07-15	13:12:32:643	1	ADL	1	UNKTNOWN gprsHandler ERROR 23
2013-07-15	13:12:32:643	2	ADL	1	UNKTNOWN gprsHandler ERROR 23
2013-07-15	13:12:32:644	1	ADL	1	UNKTNOWN gprsHandler ERROR 23
2013-07-15	13:12:32:645	1	ADL	31	[ADL] GPRS unsubs 00265509 : 0
2013-07-15	13:12:32:645	2	ADL	3	bearerHandler
2013-07-15	13:12:32:646	1	ADL	1	WIP_BEV_CONN_FAILED
2013-07-15	13:12:32:647	1	ADL	3	bearerHandler
2013-07-15	13:12:32:647	2	ADL	1	WIP_BEV_STOPPED
2013-07-15	13:12:32:648	1	ADL	3	wip_bearerClose == OK
2013-07-15	13:12:32:649	1	ADL	20	[ADL] tmr unsubs 
2013-07-15	13:12:32:649	2	ADL	3	wip_netExit: okay (allways returns 0)
2013-07-15	13:12:32:650	1	ADL	20	[ADL] tmr unsubs 
2013-07-15	13:12:32:651	1	ADL	2	adl_tmrUnSubscribe: -7
2013-07-15	13:12:32:652	1	ADL	20	[ADL] tmr subs 
2013-07-15	13:12:32:652	2	ADL	3	wip_bearerStop == OK
2013-07-15	13:12:32:653	1	ADL	20	[ADL] tmr subs 
2013-07-15	13:12:32:654	1	ADL	3	pollCregCallback
2013-07-15	13:12:32:654	2	ADL	3	rsp info: 1
2013-07-15	13:12:32:655	1	ADL	3	sim logged
2013-07-15	13:12:32:655	2	ADL	3	connect
2013-07-15	13:12:32:656	1	ADL	3	OpenAndStartBearer
2013-07-15	13:12:32:657	1	ADL	20	[ADL] tmr subs 
2013-07-15	13:12:32:657	2	ADL	31	[ADL] Gprs subs 00261AFD : 0
2013-07-15	13:12:32:658	1	ADL	3	wip_bearerOpen = 0
2013-07-15	13:12:32:659	1	ADL	3	wip_bearerSetOpts = 0
2013-07-15	13:12:32:659	2	ADL	31	[ADL] Gprs subs 00265509 : 0
2013-07-15	13:12:32:660	1	ADL	16	[ADL port] IsAvailable(80) : 1
2013-07-15	13:12:32:661	1	ADL	31	[ADL] Gprs setup 1 : 0
2013-07-15	13:12:32:661	2	ADL	3	wip_bearerStart = -27
2013-07-15	13:12:32:662	1	ADL	3	openAndStartBearer: OK
2013-07-15	13:12:32:663	1	ADL	3	ADL_GPRS_EVENT_SETUP_OK
2013-07-15	13:12:32:663	2	ADL	3	ADL_GPRS_EVENT_SETUP_OK
2013-07-15	13:12:32:664	1	ADL	3	ADL_GPRS_EVENT_SETUP_OK
2013-07-15	13:12:32:664	2	ADL	3	ADL_GPRS_EVENT_SETUP_OK
2013-07-15	13:12:32:665	1	ADL	3	ADL_GPRS_EVENT_SETUP_OK
2013-07-15	13:12:32:666	1	ADL	3	ADL_GPRS_EVENT_SETUP_OK
2013-07-15	13:12:32:667	1	ADL	3	ADL_GPRS_EVENT_SETUP_OK
2013-07-15	13:12:32:667	2	ADL	3	ADL_GPRS_EVENT_SETUP_OK
2013-07-15	13:12:32:668	1	ADL	3	ADL_GPRS_EVENT_SETUP_OK
2013-07-15	13:12:32:669	1	ADL	3	ADL_GPRS_EVENT_SETUP_OK
2013-07-15	13:12:32:669	2	ADL	3	ADL_GPRS_EVENT_SETUP_OK
2013-07-15	13:12:32:670	1	ADL	3	ADL_GPRS_EVENT_SETUP_OK
2013-07-15	13:12:32:671	1	ADL	3	ADL_GPRS_EVENT_SETUP_OK
2013-07-15	13:12:32:671	2	ADL	3	ADL_GPRS_EVENT_SETUP_OK
2013-07-15	13:12:32:672	1	ADL	3	ADL_GPRS_EVENT_SETUP_OK
2013-07-15	13:12:32:672	2	ADL	3	ADL_GPRS_EVENT_SETUP_OK
2013-07-15	13:12:32:673	1	ADL	3	ADL_GPRS_EVENT_SETUP_OK
2013-07-15	13:12:32:674	1	ADL	3	ADL_GPRS_EVENT_SETUP_OK
2013-07-15	13:12:32:674	2	ADL	3	ADL_GPRS_EVENT_SETUP_OK
2013-07-15	13:12:32:675	1	ADL	3	ADL_GPRS_EVENT_SETUP_OK
2013-07-15	13:12:32:676	1	ADL	3	ADL_GPRS_EVENT_SETUP_OK
2013-07-15	13:12:32:676	2	ADL	3	ADL_GPRS_EVENT_SETUP_OK
2013-07-15	13:12:32:677	1	ADL	3	ADL_GPRS_EVENT_SETUP_OK
2013-07-15	13:12:32:678	1	ADL	3	ADL_GPRS_EVENT_SETUP_OK
2013-07-15	13:12:32:678	2	ADL	3	ADL_GPRS_EVENT_SETUP_OK
2013-07-15	13:12:32:679	1	ADL	3	ADL_GPRS_EVENT_SETUP_OK
2013-07-15	13:12:32:679	2	ADL	3	ADL_GPRS_EVENT_SETUP_OK
2013-07-15	13:12:32:679	3	ADL	3	ADL_GPRS_EVENT_SETUP_OK
2013-07-15	13:12:32:679	4	ADL	3	ADL_GPRS_EVENT_SETUP_OK
2013-07-15	13:12:32:679	5	ADL	3	ADL_GPRS_EVENT_SETUP_OK
2013-07-15	13:12:32:680	1	ADL	3	ADL_GPRS_EVENT_SETUP_OK
2013-07-15	13:12:32:680	2	ADL	3	ADL_GPRS_EVENT_SETUP_OK
2013-07-15	13:12:32:680	3	ADL	3	ADL_GPRS_EVENT_SETUP_OK
2013-07-15	13:12:32:680	4	ADL	3	ADL_GPRS_EVENT_SETUP_OK
2013-07-15	13:12:32:680	5	ADL	3	ADL_GPRS_EVENT_SETUP_OK
2013-07-15	13:12:32:680	6	ADL	3	ADL_GPRS_EVENT_SETUP_OK
2013-07-15	13:12:32:681	1	ADL	3	ADL_GPRS_EVENT_SETUP_OK
2013-07-15	13:12:32:681	2	ADL	3	ADL_GPRS_EVENT_SETUP_OK
2013-07-15	13:12:32:681	3	ADL	3	ADL_GPRS_EVENT_SETUP_OK
2013-07-15	13:12:32:681	4	ADL	3	ADL_GPRS_EVENT_SETUP_OK
2013-07-15	13:12:32:681	5	ADL	3	ADL_GPRS_EVENT_SETUP_OK
2013-07-15	13:12:32:681	6	ADL	3	ADL_GPRS_EVENT_SETUP_OK
2013-07-15	13:12:32:682	1	ADL	3	ADL_GPRS_EVENT_SETUP_OK
2013-07-15	13:12:32:682	2	ADL	16	[ADL port] IsAvailable(80) : 1

The basic effect is that modem is “locked” for hours and I have very long gaps in communication (even up to 2 days!)
The “UNKNOWN GPRS HANDLER 23” is ADL_GPRS_EVENT_ACTIVATE_KO/X. It also looks like I’m having LOTS of adl_gprsSubscribe executions (it’s not the problem with my application!! The problem does not exist on 7.47.6).

So basically I would like to ask if someone has any solution for the “CID NOT FOUND” issue and hope that strange things happening at 7.47.4 would help to track down the reason of problem.

Thank you in advance for any help.

[davidc]

Hiya,

I’ve seen this in the Q2686. The app was datalogging in a vehicle, and I suspect that it was continual changing of mobile cell towers and having intermittent cell disconnects due to dead zones that was causing the issue - although I could not prove it.

Unfortunately I’m not in front of my Dev PC at the moment, so I’m working from memory for some of the AT commands.

I had a couple of solutions for it.

1. I shortened the TCP timeouts from the default 12 minutes(!) to approx 2 minutes so that I could quickly detect if the TCP (over GPRS) connection had gone away. Look at the WIP_INIT configuration parameters as a starting point.

2. If I got a TCP timeout from my comms task, I would then unwind the GPRS connection - using the unsubscribe/disconnect routines. I would unwind right back to checking for the SIM PIN - and then attempt to walk forward again to re-establish the link.

What I did notice was that when this happened, AT+CREG? was returning odd results indicating that the device was not registered on the network. I experimented with another AT command (Can’t remember at the moment - not in front of my dev PC) to force network reconnection - but that was somewhat problematic as well.

Hope this helps a little.

ciao, Dave

[pawelal]

Thank you for suggestions.
I have looked into my wip_netInit and I use the default settings. I assume that you had in mind the WIP_NET_OPT_TCP_KEEP_IDLE parameter, which is by default 7200s (2 hours)!!! So now I will try with wip_netInitOpts() an check if the situation would improve.

Still, any other suggestions on CID NOT FOUND and its consequences would be much appreciated.

[davidc]

Hiya,

Managed to get back to my Dev machine. I’m using the following settings in my wip_netSetOpts():

#define MAIN_TCP_REXMIT_MAX 31 			// retry time (seconds) Default is 64
#define MAIN_TCP_REXMIT_MAXCNT 4		// max retries. Default is 12

result = wip_netSetOpts(
					WIP_NET_OPT_TCP_REXMT_MAX, MAIN_TCP_REXMIT_MAX,
					WIP_NET_OPT_TCP_REXMT_MAXCNT, MAIN_TCP_REXMIT_MAXCNT,
					WIP_NET_OPT_END
				);

This brings down the TCP retry wait and count down to approx 2 min (rather than 12).

As I’m using a HTTP transfer, if the TCP connection times out, I end up with a WIP_CEV_ERROR event which I handle and start the GPRS unwinding.

I also count the time that the +CREG poll in the GPRS setup takes before getting a registered result. If it’s too long (your choice - I use 3-5 min), I then use AT+COPS=2 to deregister the device from the network, wait for 30 sec or so then use AT+COPS=0 to force the re-registration of the device to the network - which then startes the +CREG process again.

Hope this helps.

ciao, Dave

[tomridl]

@davidc

I also count the time that the +CREG poll in the GPRS setup takes before getting a registered result. If it’s too long (your choice - I use 3-5 min), I then use AT+COPS=2 to deregister the device from the network, wait for 30 sec or so then use AT+COPS=0 to force the re-registration of the device to the network - which then startes the +CREG process again.

Not quite on topic, but I was wondering what the preferred method of GSM registratrion/deregistration was. I see you use AT+COPS, I have always used AT+CFUN=0 to deregister and AT+CFUN=1,0 to restart GSM registration. I wonder if there is any difference or any benefit of using one over the other?

[pawelal]

First of all thank you Dave for sharing your settings. Now it is clear for me what you had in mind. I will try your approach as it sounds that it is a reasonable workaround. It is always better to have max. 2-3 minutes of lost communication, rather than several hours.
I’m a bit disappointed that there is no official information or guideline from Sierra on this problem as it seems to be common.

Regarding AT+COPS and AT+CFUN I’m also curious how it should look like. In my application at “no communication” restart I use only AT+CFUN=1. Is it a mistake not to deregister first? Assuming that I had the correct TCP connection, but for some reason I have made the restart, do I leave the “old” GPRS session opened?

[davidc]

Hiya,

I’m a bit disappointed that there is no official information or guideline from Sierra on this problem as it seems to be common.

You’re not the only one. A nice, complete state diagram of the entire GSM/GPRS connect/disconnect process would be great.

An AT+CFUN=1 essentially does a reset of the modem - tears down everything (both your app and the underlying firmware) and starts from cold. If you’re using a GPS to track the unit, a +CFUN=1 will result in lost data as the modem restarts and re-initializes the GPS.

AT+COPS is supposed to change the GSM registration state - you can use it to change operators etc as well as simply disconnect/reconnect.

That said, I didn’t always have perfect results using +COPS - and occasionally had to do a soft reset using AT+CFUN.

ciao, Dave

[tomridl]

@pawelal

Regarding AT+COPS and AT+CFUN I’m also curious how it should look like. In my application at “no communication” restart I use only AT+CFUN=1. Is it a mistake not to deregister first? Assuming that I had the correct TCP connection, but for some reason I have made the restart, do I leave the “old” GPRS session opened?

When you shutdown the modem, you should do a clean deregistration from the network. If you don’t, when you reconnect it can sometimes take a long time for SMS messages to come through (this was discussed in another post somewhere, couldn’t find it quickly ). You can send AT+CFUN=0, AT+CPOF or AT+COPS=2 to perform a graceful deregistration.

Regarding AT+CFUN, if you send AT+CFUN=0 it just shuts down the GSM stack without resetting the modem. Sending AT+CFUN=1,0 restarts the GSM stack without restarting the entire module. Sending AT+CFUN=1,1 (or AT+CFUN=1 which as a default of 1 for the second parameter if not included) resets the entire module and application. You can also send AT+CFUN=4 to shutdown the GSM stack but retain SIM access if you require.

[pawelal]

Last question around this topic:
Can I detect basing on the line status what is happening to the modem at the moment? For now I assume:

number not avaliable => modem not logged into GSM (no signal)
line busy => GPRS connection ongoing, pings don’t work - modem “hanged”
line available => pings don’t work - bearer not opened yet. pings work - correct connection.

I’m asking because I have one device far far away and experiencing some problems as described before.

[davidc]

Hiya,

You can’t (directly) use the state of the voice line to determine the state of the modem, as any voice activity on the Q26 ‘parks’ (or temporarily disconnects) the GPRS connection for the duration of the voice call.

You could write an SMS handler to bounce you back the status of the GPRS connection when it received an appropriately formatted inbound SMS though…

ciao, Dave