Connectivity issue with Adafruit FONA and Raspberry Pi

shakkhar · March 14, 2016, 7:47pm

Hi

We are using Adafruit FONA wired to a Raspberry Pi B+ to establish GSM connectivity using Konekt SIM card. We are running into some stability issue with our connection, that are hard to reproduce manually. But I wanted to put it on this forum, in case we find others who have experienced similar problem.

We are using ppp with chat to establish the GSM connection, and we have ppp configured to retry indefinitely when it loses connection. What I have noticed is that most of the time, we can establish the connection just fine. The connection stays up for a long time (days), but sometimes the connection will drop for whatever reason, and then no matter how many times pp tries, it will fail to establish a connection again. This is how the pattern looks like in the syslog:

...snip... (we trigger a connection attempt by running ppp)
Mar 11 21:27:25 placemetersensor chat[2339]: abort on (BUSY)
Mar 11 21:27:25 placemetersensor chat[2339]: abort on (VOICE)
Mar 11 21:27:25 placemetersensor chat[2339]: abort on (NO CARRIER)
Mar 11 21:27:25 placemetersensor chat[2339]: abort on (NO DIALTONE)
Mar 11 21:27:25 placemetersensor chat[2339]: abort on (NO DIAL TONE)
Mar 11 21:27:25 placemetersensor chat[2339]: abort on (NO ANSWER)
Mar 11 21:27:25 placemetersensor chat[2339]: abort on (DELAYED)
Mar 11 21:27:25 placemetersensor chat[2339]: abort on (ERROR)
Mar 11 21:27:25 placemetersensor chat[2339]: abort on (+CGATT: 0)
Mar 11 21:27:25 placemetersensor chat[2339]: send (AT^M)
Mar 11 21:27:25 placemetersensor chat[2339]: timeout set to 12 seconds
Mar 11 21:27:25 placemetersensor chat[2339]: expect (OK)
Mar 11 21:27:25 placemetersensor chat[2339]: AT^M^M
Mar 11 21:27:25 placemetersensor chat[2339]: OK
Mar 11 21:27:25 placemetersensor chat[2339]:  -- got it
Mar 11 21:27:25 placemetersensor chat[2339]: send (ATH^M)
Mar 11 21:27:25 placemetersensor chat[2339]: expect (OK)
Mar 11 21:27:25 placemetersensor chat[2339]: ^M
Mar 11 21:27:25 placemetersensor chat[2339]: ATH^M^M
Mar 11 21:27:25 placemetersensor chat[2339]: OK
Mar 11 21:27:25 placemetersensor chat[2339]:  -- got it
Mar 11 21:27:25 placemetersensor chat[2339]: send (ATE1^M)
Mar 11 21:27:25 placemetersensor chat[2339]: expect (OK)
Mar 11 21:27:25 placemetersensor chat[2339]: ^M
Mar 11 21:27:25 placemetersensor chat[2339]: ATE1^M^M
Mar 11 21:27:25 placemetersensor chat[2339]: OK
Mar 11 21:27:25 placemetersensor chat[2339]:  -- got it
Mar 11 21:27:25 placemetersensor chat[2339]: send (AT+CGDCONT=1,"IP","apn.konekt.io","",0,0^M)
Mar 11 21:27:26 placemetersensor chat[2339]: expect (OK)
Mar 11 21:27:26 placemetersensor chat[2339]: ^M
Mar 11 21:27:26 placemetersensor chat[2339]: AT+CGDCONT=1,"IP","apn.konekt.io","",0,0^M^M
Mar 11 21:27:26 placemetersensor chat[2339]: OK
Mar 11 21:27:26 placemetersensor chat[2339]:  -- got it
Mar 11 21:27:26 placemetersensor chat[2339]: send (ATD*99#^M)
Mar 11 21:27:26 placemetersensor chat[2339]: timeout set to 22 seconds
Mar 11 21:27:26 placemetersensor chat[2339]: expect (CONNECT)
Mar 11 21:27:26 placemetersensor chat[2339]: ^M
Mar 11 21:27:26 placemetersensor chat[2339]: ATD*99#^M^M
Mar 11 21:27:26 placemetersensor chat[2339]: CONNECT
Mar 11 21:27:26 placemetersensor chat[2339]:  -- got it
Mar 11 21:27:26 placemetersensor chat[2339]: send (^M)
Mar 11 21:27:26 placemetersensor pppd[2337]: Script /usr/sbin/chat -v -f /etc/chatscripts/gprs -T apn.konekt.io finished (pid 2338), status = 0x0
Mar 11 21:27:26 placemetersensor pppd[2337]: Serial connection established.
Mar 11 21:27:26 placemetersensor pppd[2337]: using channel 1
Mar 11 21:27:26 placemetersensor pppd[2337]: Using interface ppp0
Mar 11 21:27:26 placemetersensor pppd[2337]: Connect: ppp0 <--> /dev/ttyAMA0
Mar 11 21:27:26 placemetersensor ifplugd(ppp0)[2376]: ifplugd 0.28 initializing.
Mar 11 21:27:26 placemetersensor ifplugd(ppp0)[2376]: Using interface ppp0/00:00:00:00:00:00
Mar 11 21:27:26 placemetersensor ifplugd(ppp0)[2376]: Using detection mode: IFF_RUNNING
Mar 11 21:27:26 placemetersensor ifplugd(ppp0)[2376]: Initialization complete, link beat detected.
Mar 11 21:27:26 placemetersensor ifplugd(ppp0)[2376]: Executing '/etc/ifplugd/ifplugd.action ppp0 up'.
Mar 11 21:27:26 placemetersensor ifplugd(ppp0)[2376]: client: Ignoring unknown interface ppp0=ppp0.
Mar 11 21:27:27 placemetersensor ifplugd(ppp0)[2376]: Program executed successfully.
Mar 11 21:27:27 placemetersensor pppd[2337]: rcvd [LCP ConfReq id=0x1 <asyncmap 0xa0000> <auth pap> <pcomp> <accomp>]
Mar 11 21:27:27 placemetersensor pppd[2337]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x51e12f49> <pcomp> <accomp>]
Mar 11 21:27:27 placemetersensor pppd[2337]: sent [LCP ConfAck id=0x1 <asyncmap 0xa0000> <auth pap> <pcomp> <accomp>]
Mar 11 21:27:27 placemetersensor pppd[2337]: rcvd [LCP ConfNak id=0x1 <asyncmap 0xa0000>]
Mar 11 21:27:27 placemetersensor pppd[2337]: sent [LCP ConfReq id=0x2 <asyncmap 0xa0000> <magic 0x51e12f49> <pcomp> <accomp>]
Mar 11 21:27:27 placemetersensor pppd[2337]: rcvd [LCP ConfAck id=0x2 <asyncmap 0xa0000> <magic 0x51e12f49> <pcomp> <accomp>]
Mar 11 21:27:27 placemetersensor pppd[2337]: sent [LCP EchoReq id=0x0 magic=0x51e12f49]
Mar 11 21:27:27 placemetersensor pppd[2337]: sent [PAP AuthReq id=0x1 user="placemetersensor" password=<hidden>]
Mar 11 21:27:27 placemetersensor pppd[2337]: rcvd [LCP EchoRep id=0x0 magic=0x0]
Mar 11 21:27:27 placemetersensor pppd[2337]: rcvd [PAP AuthAck id=0x1 ""]
Mar 11 21:27:27 placemetersensor pppd[2337]: PAP authentication succeeded
Mar 11 21:27:27 placemetersensor kernel: [   48.605006] PPP BSD Compression module registered
Mar 11 21:27:27 placemetersensor pppd[2337]: sent [CCP ConfReq id=0x1 <deflate 15> <deflate(old#) 15> <bsd v1 15>]
Mar 11 21:27:27 placemetersensor pppd[2337]: sent [IPCP ConfReq id=0x1 <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns2 0.0.0.0>]
Mar 11 21:27:27 placemetersensor pppd[2337]: rcvd [IPCP ConfReq id=0x1]
Mar 11 21:27:27 placemetersensor pppd[2337]: sent [IPCP ConfNak id=0x1 <addr 0.0.0.0>]
Mar 11 21:27:27 placemetersensor kernel: [   48.659053] PPP Deflate Compression module registered
Mar 11 21:27:27 placemetersensor pppd[2337]: rcvd [LCP ProtRej id=0x0 80 fd 01 01 00 0f 1a 04 78 00 18 04 78 00 15 03 2f]
Mar 11 21:27:27 placemetersensor pppd[2337]: Protocol-Reject for 'Compression Control Protocol' (0x80fd) received
Mar 11 21:27:27 placemetersensor pppd[2337]: rcvd [IPCP ConfRej id=0x1 <compress VJ 0f 01>]
Mar 11 21:27:27 placemetersensor pppd[2337]: sent [IPCP ConfReq id=0x2 <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns2 0.0.0.0>]
Mar 11 21:27:27 placemetersensor pppd[2337]: rcvd [IPCP ConfReq id=0x2 <addr 0.0.0.0>]
Mar 11 21:27:27 placemetersensor pppd[2337]: sent [IPCP ConfRej id=0x2 <addr 0.0.0.0>]
Mar 11 21:27:27 placemetersensor pppd[2337]: rcvd [IPCP ConfReq id=0x3]
Mar 11 21:27:27 placemetersensor pppd[2337]: sent [IPCP ConfAck id=0x3]
Mar 11 21:27:28 placemetersensor pppd[2337]: rcvd [IPCP ConfNak id=0x2 <addr 10.52.80.246> <ms-dns1 212.9.0.135> <ms-dns2 212.9.0.136>]
Mar 11 21:27:28 placemetersensor pppd[2337]: sent [IPCP ConfReq id=0x3 <addr 10.52.80.246> <ms-dns1 212.9.0.135> <ms-dns2 212.9.0.136>]
Mar 11 21:27:28 placemetersensor pppd[2337]: rcvd [IPCP ConfAck id=0x3 <addr 10.52.80.246> <ms-dns1 212.9.0.135> <ms-dns2 212.9.0.136>]
Mar 11 21:27:28 placemetersensor pppd[2337]: Could not determine remote IP address: defaulting to 10.64.64.64
Mar 11 21:27:28 placemetersensor pppd[2337]: local  IP address 10.52.80.246
Mar 11 21:27:28 placemetersensor pppd[2337]: remote IP address 10.64.64.64
Mar 11 21:27:28 placemetersensor pppd[2337]: primary   DNS address 212.9.0.135
Mar 11 21:27:28 placemetersensor pppd[2337]: secondary DNS address 212.9.0.136
Mar 11 21:27:28 placemetersensor pppd[2337]: Script /etc/ppp/ip-up started (pid 2393)
Mar 11 21:27:28 placemetersensor dnsmasq[2072]: reading /var/run/dnsmasq/resolv.conf
Mar 11 21:27:28 placemetersensor dnsmasq[2072]: using nameserver 212.9.0.135#53
Mar 11 21:27:28 placemetersensor dnsmasq[2072]: using nameserver 212.9.0.136#53
Mar 11 21:27:29 placemetersensor pppd[2337]: Script /etc/ppp/ip-up finished (pid 2393), status = 0x0

...snip... (connection stays up a long time)

Mar 12 13:54:42 placemetersensor pppd[2337]: rcvd [LCP TermReq id=0x2]
Mar 12 13:54:42 placemetersensor pppd[2337]: LCP terminated by peer
Mar 12 13:54:42 placemetersensor pppd[2337]: Connect time 987.3 minutes.
Mar 12 13:54:42 placemetersensor pppd[2337]: Sent 2259079 bytes, received 3106731 bytes.
Mar 12 13:54:42 placemetersensor pppd[2337]: Script /etc/ppp/ip-down started (pid 9469)
Mar 12 13:54:42 placemetersensor pppd[2337]: sent [LCP TermAck id=0x2]
Mar 12 13:54:43 placemetersensor pppd[2337]: Script /etc/ppp/ip-down finished (pid 9469), status = 0x0
Mar 12 13:54:44 placemetersensor ntpd[2201]: Deleting interface #2 ppp0, 10.52.80.246#123, interface stats: received=16, sent=19, dropped=0, ac
tive_time=56299 secs
Mar 12 13:54:44 placemetersensor ntpd[2201]: 46.8.40.31 interface 10.52.80.246 -> (none)
Mar 12 13:54:44 placemetersensor ntpd[2201]: 89.248.58.156 interface 10.52.80.246 -> (none)
Mar 12 13:54:44 placemetersensor ntpd[2201]: 94.23.210.194 interface 10.52.80.246 -> (none)
Mar 12 13:54:44 placemetersensor ntpd[2201]: 69.164.201.165 interface 10.52.80.246 -> (none)
Mar 12 13:54:44 placemetersensor ntpd[2201]: peers refreshed
Mar 12 13:54:45 placemetersensor pppd[2337]: Connection terminated.
Mar 12 13:54:45 placemetersensor pppd[2337]: Modem hangup
Mar 12 13:54:46 placemetersensor ifplugd(ppp0)[2376]: Link beat lost.
Mar 12 13:54:46 placemetersensor ifplugd(ppp0)[2376]: Exiting.

...snip...

Mar 12 13:55:45 placemetersensor chat[9654]: abort on (BUSY)
Mar 12 13:55:45 placemetersensor chat[9654]: abort on (VOICE)
Mar 12 13:55:45 placemetersensor chat[9654]: abort on (NO CARRIER)
Mar 12 13:55:45 placemetersensor chat[9654]: abort on (NO DIALTONE)
Mar 12 13:55:45 placemetersensor chat[9654]: abort on (NO DIAL TONE)
Mar 12 13:55:45 placemetersensor chat[9654]: abort on (NO ANSWER)
Mar 12 13:55:45 placemetersensor chat[9654]: abort on (DELAYED)
Mar 12 13:55:45 placemetersensor chat[9654]: abort on (ERROR)
Mar 12 13:55:45 placemetersensor chat[9654]: abort on (+CGATT: 0)
Mar 12 13:55:45 placemetersensor chat[9654]: send (AT^M)
Mar 12 13:55:45 placemetersensor chat[9654]: timeout set to 12 seconds
Mar 12 13:55:45 placemetersensor chat[9654]: expect (OK)
Mar 12 13:55:45 placemetersensor chat[9654]: AT^M^M
Mar 12 13:55:45 placemetersensor chat[9654]: OK
Mar 12 13:55:45 placemetersensor chat[9654]:  -- got it
Mar 12 13:55:45 placemetersensor chat[9654]: send (ATH^M)
Mar 12 13:55:45 placemetersensor chat[9654]: expect (OK)
Mar 12 13:55:45 placemetersensor chat[9654]: ^M
Mar 12 13:55:45 placemetersensor chat[9654]: ATH^M^M
Mar 12 13:55:45 placemetersensor chat[9654]: OK
Mar 12 13:55:45 placemetersensor chat[9654]:  -- got it
Mar 12 13:55:45 placemetersensor chat[9654]: send (ATE1^M)
Mar 12 13:55:45 placemetersensor chat[9654]: expect (OK)
Mar 12 13:55:45 placemetersensor chat[9654]: ^M
Mar 12 13:55:45 placemetersensor chat[9654]: ATE1^M^M
Mar 12 13:55:45 placemetersensor chat[9654]: OK
Mar 12 13:55:45 placemetersensor chat[9654]:  -- got it
Mar 12 13:55:45 placemetersensor chat[9654]: send (AT+CGDCONT=1,"IP","apn.konekt.io","",0,0^M)
Mar 12 13:55:46 placemetersensor chat[9654]: expect (OK)
Mar 12 13:55:46 placemetersensor chat[9654]: ^M
Mar 12 13:55:46 placemetersensor chat[9654]: AT+CGDCONT=1,"IP","apn.konekt.io","",0,0^M^M
Mar 12 13:55:46 placemetersensor chat[9654]: ERROR
Mar 12 13:55:46 placemetersensor chat[9654]:  -- failed
Mar 12 13:55:46 placemetersensor chat[9654]: Failed (ERROR)
Mar 12 13:55:46 placemetersensor pppd[2337]: Script /usr/sbin/chat -v -f /etc/chatscripts/gprs -T apn.konekt.io finished (pid 9653), status = 0xb
Mar 12 13:55:46 placemetersensor pppd[2337]: Connect script failed
M

As you can see, the connection stays up for a log time (987 minutes). Then ppp receives a TermReq from the remote peer and terminates the connection. From that point onward, it is just a sequence of retry and failures from ppp. Specifically, AT+CGDCONT keeps failing.

This is what our chat script look like:

ABORT		BUSY
ABORT		VOICE
ABORT		"NO CARRIER"
ABORT		"NO DIALTONE"
ABORT		"NO DIAL TONE"
ABORT		"NO ANSWER"
ABORT		"DELAYED"
ABORT		"ERROR"

# cease if the modem is not attached to the network yet
ABORT		"+CGATT: 0"

""		AT
TIMEOUT		12
OK		ATH
OK		ATE1

OK		AT+CGDCONT=1,"IP","\T","",0,0
OK		ATD*99#
TIMEOUT		22
CONNECT		""

We have not yet been able to find a way to reproduce this issue manually, other than leaving the device connected for a while. After this happens, I have logged into the device to confirm that the network signal is strong (AT+CSQ returns >20). I have also confirmed that the subscription on Konekt is still active.

If you have some insight into what might be causing this problem, or how I can reproduce the issue consistently - that will be really helpful.

Thanks
Shakkhar

HologramPat · March 14, 2016, 7:57pm

Hey @shakkhar,

We’re checking into PPPD and logs at the network level to try to gather some insights into this.

Thanks,
PFW

shakkhar · March 17, 2016, 9:04pm

Hi @KonektPat

Any update on this? We are still running into this issue. We would receive a TermReq from the peer and then the GSM module deregisters from the network. At that point the GSM module won’t register on the network again. I tried sending AT+CFUN=1,1 but that did not solve the problem either. I had to power cycle the device to resolve the issue.

MichaelM · March 17, 2016, 11:55pm

Perhaps a common thread with what I’m working on (see my “modem timeout” thread https://community.konekt.io/t/dash-modem-times-out-and-wont-send-data-after-1-hour/240) – I’m using the Arduino IDE, on the Dash, but I see a similar-acting timeout that causes the modem to lose its marbles and not connect inbound or outbound. As with your situation, only a power cycle brings the modem back. Maybe a general 3G modem thing when combined with Konekt network?

shakkhar · March 18, 2016, 2:48am

@MichaelM Does your modem go into a power saving mode? In our case, the GSM module never loses power. It is still responding to AT commands. (FONA does not respond to AT commands in sleep mode.) It only drops the GSM network registration. (And that is because the remote peer requests termination.) The problem is not due to lack of network activity either.

In your case, it seems that the duration of the connection is pretty stable. I am not familiar with Dash. Can you enable something like “debug mode” in it so that we can get some logs? Does the Dash module let you send AT commands to it?

MichaelM · March 18, 2016, 4:40am

That’s what we’re waiting to see on this end… I suspect it may have something to do with power saving, but for now the modem won’t recover without a power cycle. We don’t have modem calls yet for the Arduino environment, but I do have my debug output posted from the serial monitor at the very top of this thread. All modem commands shown originate in the Dash firmware, so I’m just a passenger in this instance, not a driver! I’ve played around quite a bit with the Ada Fona 3G breakout. Nice device, but I’ve learned 2 things: 3G is seriously different from 2G from a command standpoint – a whole new learning curve. And as much as I like Ada’s stuff, the Dash form factor is amazing. The Ada 3G breakout is a brick by comparison. Once we can drive the Dash modem in the Arduino environment, life should improve for us Dash users, and hopefully we may all learn something that can help us Fona people as well.

shakkhar · March 18, 2016, 2:35pm

@MichaelM I did not notice the debug output before. It looks like your modem really did go to sleep. Otherwise AT commands, I presume, will return something (OK / ERROR), it will not time out.

HologramPat · March 23, 2016, 8:26pm

Hey @shakkhar,

Are you experiencing this issue when idling, while continuously sending data, or both? We’ve been in contact with the carriers and are not seeing any errors, so I’m curious if it’s a timeout that is being hit. Has there been any additional progress?

Thanks,
PFW

shakkhar · March 23, 2016, 8:43pm

@KonektPat When the issue describe above occurred, the connection was being actively used. Unfortunately this still keeps happening. We have implemented a workaround. We send AT+CFUN=1,1 to reset the module and then wait for a bit before attempting to connect again. Then it works.