What does "error: couldn't start network: QMI protocol error (14): 'CallFailed'

jmeyers2 · June 11, 2019, 8:40pm

I’m working on getting Twilio setup with an EC25 LTE chip on the BalenaFin 1.1v board. I’m running OS version balenaOS 2.36.0+rev2. I know the antenna and board works, as I used a Hologram Sim card in it and that connects without any issues, so I’m thinking the issue is with Twilio, but I just wanted confirmation.

It’s connecting for a few minutes, then it will say registered, and then back to connecting.

Output from Modem Manager:
Jun 11 20:36:03 30cf246 ModemManager[673]: verbose call end reason (2,208): [internal] pdn-ipv4-call-disallowed
Jun 11 20:36:03 30cf246 ModemManager[673]: Modem /org/freedesktop/ModemManager1/Modem/0: state changed (connecting -> registered)
Jun 11 20:36:03 30cf246 ModemManager[673]: Simple connect started…
Jun 11 20:36:03 30cf246 ModemManager[673]: Simple connect state (4/8): Wait to get fully enabled
Jun 11 20:36:03 30cf246 ModemManager[673]: Simple connect state (5/8): Register
Jun 11 20:36:03 30cf246 ModemManager[673]: Simple connect state (6/8): Bearer
Jun 11 20:36:03 30cf246 ModemManager[673]: Simple connect state (7/8): Connect
Jun 11 20:36:03 30cf246 ModemManager[673]: Modem /org/freedesktop/ModemManager1/Modem/0: state changed (registered -> connecting)
Jun 11 20:36:04 30cf246 ModemManager[673]: error: couldn’t start network: QMI protocol error (14): ‘CallFailed’
Jun 11 20:36:04 30cf246 ModemManager[673]: call end reason (1): ‘generic-unspecified’

cellular file in file path /etc/NetworkManager/system-connections:
[connection]
id=cellular
type=gsm
autoconnect=true

[gsm]
apn=wireless.Twilio.com
password=Authtoken provided by Twilio
username=Account SID provided by Twilio

[serial]
baud=115200

[ipv4]
method=auto

[ipv6]
addr-gen-mode=stable-privacy
method=ignore

According to my research from here, I need the password and username to use that sim chip.

Does anyone have any idea on why this isn’t connecting or is it a Twilio issue? I can see that it’s trying to connect.

shaunmulligan · June 11, 2019, 8:59pm

Hi @jmeyers2 , I don’t know of anyone using twilio sims yet, but this is super cool. have you tried connecting without setting user and pass? I see in Programmable Wireless: How to Set a Device’s APN | Twilio it says:

The Twilio APN does not require any authentication; therefore, you should leave the username and password fields blank.

jmeyers2 · June 11, 2019, 11:51pm

Hi @shaunmulligan I have tried with and without the username and password but the errors are still the same. Any advice?

zrzka · June 12, 2019, 6:29am

Hi,

I have zero experience with Twilio, but this line apn=wireless.Twilio.com catches my attention. I mean the upper case T. Shot in the dark - does it work with apn=wireless.twilio.com? Lower case t.

jmeyers2 · June 12, 2019, 2:41pm

Hi @zrzka I tried the lowercase “t” as well, and no such luck. I also made sure that there were no extra spaces in the cellular file. I did notice, that when I put in the sim card on a board I got up and running with Hologram and changed the APN parameters to reflect the Twilio APN, and rebooted. The output for mmcli -m 0 is saying Sim is missing. Does that have something to do with it or can you tell me what that error actually means. Both boards are set up the same way, using the same OS and antenna.

shaunmulligan · June 12, 2019, 4:03pm

hey @jmeyers2 , sorry to hear you still are having trouble getting NM and MM to play nicely with the twilio SIM. I wonder if you have an ubuntu laptop and usb modem that you could try test the SIM with. I would like to see what ubuntu would create for the connection file if you follow the click through modem setup.

One other thing to try is something like this config:

[connection]
id=twilio
type=gsm
autoconnect=true
permissions=

[gsm]
apn=wireless.Twilio.com
number=*99# 
password-flags=1

[serial]
baud=115200

[ipv4]
dns-search=
method=auto

[ipv6]
addr-gen-mode=stable-privacy
dns-search=
method=ignore

jmeyers2 · June 12, 2019, 4:11pm

Hi @shaunmulligan I’ll have to set up a pc with Ubuntu on it. In the meantime, I noticed you have permissions in the file, but the Network Manager website I have, https://developer.gnome.org/NetworkManager/stable/settings-gsm.html doesn’t seem to have that file. Can you tell me what it does?

shaunmulligan · June 12, 2019, 4:17pm

I don’t think the permissions= is important, its a hold over from a connection file created by ubuntu. It is used to define users that have permissions to the connection, you can see it in these docs: https://developer.gnome.org/NetworkManager/stable/settings-connection.html (sorry can’t seem to link directly to the section)

jmeyers2 · June 12, 2019, 6:46pm

Thanks for the clarification and the link. I haven’t seen that one yet for Network Manager. I tried the provided file and it didn’t work. The results are the same from the other Cellular config file. Thank you for providing it.

shaunmulligan · June 12, 2019, 6:55pm

hmm, it might be worth asking the Twilio support if they have any examples of using/configuring the sim with NetworkManager (or Ubuntu), I’m sure we are just missing some specific config, but its hard to know what.

jmeyers2 · June 12, 2019, 7:08pm

I think you are correct, I’ll contact them regarding it. Assuming I can get it working, does Balena have a document storage area that the walk through could be stored? I would hate for someone else going down this road to have the same struggles as I do.

shaunmulligan · June 12, 2019, 7:14pm

I plan to add a more thorough docs section for cellular, but we also have a internal knowledge base that we keep for all our support interactions that we can add it to. What would be awesome is if we could get you to write up a little Twilio + balena blog post, that way it would be easily found

jmeyers2 · June 12, 2019, 7:21pm

Sounds good. Once I solve it, I’ll write something up. Let me know if there’s specific guidelines to follow or specific spot to post the blog post.

shaunmulligan · June 12, 2019, 8:10pm

sweet @jmeyers2 , there isn’t really a specific guideline or template, but once you have something you can just reach out to me or @dansku and we can work on getting it up on our blog.

jha · July 25, 2019, 2:13pm

Hi,

I would like to contribute to this and also mention an issue.

We also use a twilio SIM card, using the Quectel UC20. We are able to get a connection with the following config:

[connection]
id=cellular
type=gsm
autoconnect=true

[gsm]
apn=wireless.twilio.com

[serial]
baud=115200

[ipv4]
method=auto

[ipv6]
addr-gen-mode=stable-privacy
method=ignore

However, after a at most a few days, the cellular connection is lost, and even with a reboot it does not always reconnect… As the device is then offline, I cannot get any log information.

@jmeyers2: have you got some news from Twilio? Did you succeed in connecting the device?

krenom · August 21, 2019, 7:19am

Good morning!

We use the Quectel EC20 on a Fin (running balenaOS 2.38.0+rev1), and a POD systems SIM and are facing a similar issue to @jha - we’re fine and connected for about a day or so, and then we can no longer connect.

We have ModemManager logs recovered once the devices are returned that look similar to this, looping per each reconnect attempt:

Aug 20 12:20:26 864cf15 ModemManager[674]: Modem /org/freedesktop/ModemManager1/Modem/0: state changed (connecting -> connected)
Aug 20 12:20:26 864cf15 ModemManager[674]: Simple connect state (8/8): All done
Aug 20 12:30:25 864cf15 ModemManager[674]: Modem /org/freedesktop/ModemManager1/Modem/0: state changed (connected -> disconnecting)
Aug 20 12:30:25 864cf15 ModemManager[674]: Modem /org/freedesktop/ModemManager1/Modem/0: state changed (disconnecting -> registered)
Aug 20 12:30:25 864cf15 ModemManager[674]: Simple connect started...
Aug 20 12:30:25 864cf15 ModemManager[674]: Simple connect state (4/8): Wait to get fully enabled
Aug 20 12:30:25 864cf15 ModemManager[674]: Simple connect state (5/8): Register
Aug 20 12:30:25 864cf15 ModemManager[674]: Simple connect state (6/8): Bearer
Aug 20 12:30:25 864cf15 ModemManager[674]: Simple connect state (7/8): Connect
Aug 20 12:30:25 864cf15 ModemManager[674]: Modem /org/freedesktop/ModemManager1/Modem/0: state changed (registered -> connecting)
Aug 20 12:30:26 864cf15 ModemManager[674]: QMI IPv4 Settings:
Aug 20 12:30:26 864cf15 ModemManager[674]:     Address: x.x.x.x/30
Aug 20 12:30:26 864cf15 ModemManager[674]:     Gateway: x.x.x.x
Aug 20 12:30:26 864cf15 ModemManager[674]:     DNS #1: x.x.x.x
Aug 20 12:30:26 864cf15 ModemManager[674]:     DNS #2: x.x.x.x
Aug 20 12:30:26 864cf15 ModemManager[674]:        MTU: 1500
Aug 20 12:30:26 864cf15 ModemManager[674]: error: couldn't start network: QMI protocol error (14): 'CallFailed'
Aug 20 12:30:26 864cf15 ModemManager[674]: call end reason (1): 'generic-unspecified'
Aug 20 12:30:26 864cf15 ModemManager[674]: verbose call end reason (2,204): [internal] unknown-cause

And associated NetworkManager logs:

Aug 20 12:30:25 864cf15 NetworkManager[741]: <info>  [1566304225.5942] device (cdc-wdm0): state change: activated -> deactivating (reason 'new-activation', sys-iface-state: 'managed')
Aug 20 12:30:25 864cf15 NetworkManager[741]: <info>  [1566304225.6002] manager: NetworkManager state is now CONNECTED_LOCAL
Aug 20 12:30:25 864cf15 NetworkManager[741]: <info>  [1566304225.6246] device (cdc-wdm0): disconnecting for new activation request.
Aug 20 12:30:25 864cf15 NetworkManager[741]: <info>  [1566304225.6260] audit: op="connection-activate" uuid="66663a92-8fcb-4968-b848-c4ba0f365c6c" name="pod" pid=12532 uid=0 result="success"
Aug 20 12:30:25 864cf15 NetworkManager[741]: <info>  [1566304225.6610] dns-mgr: Removing DNS information from /sbin/resolvconf
Aug 20 12:30:25 864cf15 NetworkManager[741]: <info>  [1566304225.6987] modem["cdc-wdm0"]: modem state changed, 'connected' --> 'disconnecting' (reason: user-requested)
Aug 20 12:30:25 864cf15 NetworkManager[741]: <info>  [1566304225.7068] modem["cdc-wdm0"]: modem state changed, 'disconnecting' --> 'registered' (reason: user-requested)
Aug 20 12:30:25 864cf15 NetworkManager[741]: <info>  [1566304225.7074] device (cdc-wdm0): state change: deactivating -> disconnected (reason 'new-activation', sys-iface-state: 'managed')
Aug 20 12:30:25 864cf15 NetworkManager[741]: <info>  [1566304225.7083] dhcp4 (wwan0): canceled DHCP transaction
Aug 20 12:30:25 864cf15 NetworkManager[741]: <info>  [1566304225.7085] dhcp4 (wwan0): state changed bound -> done
Aug 20 12:30:25 864cf15 NetworkManager[741]: <info>  [1566304225.7245] device (cdc-wdm0): Activation: starting connection 'pod' (66663a92-8fcb-4968-b848-c4ba0f365c6c)
Aug 20 12:30:25 864cf15 NetworkManager[741]: <info>  [1566304225.7326] device (cdc-wdm0): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'managed')
Aug 20 12:30:25 864cf15 NetworkManager[741]: <info>  [1566304225.7356] manager: NetworkManager state is now CONNECTING
Aug 20 12:30:25 864cf15 NetworkManager[741]: <info>  [1566304225.7484] modem["cdc-wdm0"]: modem state changed, 'registered' --> 'connecting' (reason: user-requested)
Aug 20 12:30:26 864cf15 NetworkManager[741]: <info>  [1566304226.3215] modem["cdc-wdm0"]: modem state changed, 'connecting' --> 'connected' (reason: user-requested)
Aug 20 12:30:26 864cf15 NetworkManager[741]: <info>  [1566304226.3411] device (cdc-wdm0): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
Aug 20 12:30:26 864cf15 NetworkManager[741]: <info>  [1566304226.3459] device (cdc-wdm0): state change: config -> ip-config (reason 'none', sys-iface-state: 'managed')
Aug 20 12:30:26 864cf15 NetworkManager[741]: <info>  [1566304226.3508] dhcp4 (wwan0): activation: beginning transaction (no timeout)
Aug 20 12:30:26 864cf15 NetworkManager[741]: <info>  [1566304226.3521] modem["cdc-wdm0"]: IPv6 configuration disabled
Aug 20 12:30:26 864cf15 NetworkManager[741]: <info>  [1566304226.3897] dhcp4 (wwan0):   address x.x.x.x
Aug 20 12:30:26 864cf15 NetworkManager[741]: <info>  [1566304226.3900] dhcp4 (wwan0):   plen 30
Aug 20 12:30:26 864cf15 NetworkManager[741]: <info>  [1566304226.3901] dhcp4 (wwan0):   expires in 7200 seconds (at 1566311426)
Aug 20 12:30:26 864cf15 NetworkManager[741]: <info>  [1566304226.3903] dhcp4 (wwan0):   nameserver 'x.x.x.x x.x.x.x'
Aug 20 12:30:26 864cf15 NetworkManager[741]: <info>  [1566304226.3904] dhcp4 (wwan0):   hostname '864cf15'
Aug 20 12:30:26 864cf15 NetworkManager[741]: <info>  [1566304226.3906] dhcp4 (wwan0):   router x.x.x.x
Aug 20 12:30:26 864cf15 NetworkManager[741]: <info>  [1566304226.3907] dhcp4 (wwan0):   mtu 1500
Aug 20 12:30:26 864cf15 NetworkManager[741]: <info>  [1566304226.3919] dhcp4 (wwan0): state changed unknown -> bound
Aug 20 12:30:26 864cf15 NetworkManager[741]: <info>  [1566304226.4008] device (cdc-wdm0): state change: ip-config -> ip-check (reason 'none', sys-iface-state: 'managed')
Aug 20 12:30:26 864cf15 NetworkManager[741]: <info>  [1566304226.4073] device (cdc-wdm0): state change: ip-check -> secondaries (reason 'none', sys-iface-state: 'managed')
Aug 20 12:30:26 864cf15 NetworkManager[741]: <info>  [1566304226.4095] device (cdc-wdm0): state change: secondaries -> activated (reason 'none', sys-iface-state: 'managed')
Aug 20 12:30:26 864cf15 NetworkManager[741]: <info>  [1566304226.4135] manager: NetworkManager state is now CONNECTED_LOCAL
Aug 20 12:30:26 864cf15 NetworkManager[741]: <info>  [1566304226.4347] manager: NetworkManager state is now CONNECTED_SITE
Aug 20 12:30:26 864cf15 NetworkManager[741]: <info>  [1566304226.4369] policy: set 'pod' (wwan0) as default for IPv4 routing and DNS
Aug 20 12:30:26 864cf15 NetworkManager[741]: <info>  [1566304226.4413] dns-mgr: Writing DNS information to /sbin/resolvconf
Aug 20 12:30:26 864cf15 NetworkManager[741]: <info>  [1566304226.5092] device (cdc-wdm0): Activation: successful, device activated.

The devices always reconnect once brought back in and booted back up. However, adding in something to force reboot our devices after losing connection for x amount of time seems like something we should only put in as a last resort, not something that should be required to maintain any kind of connectivity…

Anyone have any insight into this?

Edit: Our own app logs show that the state of the connection during this reconnection period is “NM_CONNECTIVITY_LIMITED” which suggests that it thinks it’s connected (to the mobile network) but not actively able to engage in a session or somesuch?

robertgzr · August 21, 2019, 9:02am

Hi @krenom just for the record, are you also using Twilio?

krenom · August 21, 2019, 9:16am

No, we’re using POD M2M SIMs (currently)

krenom · August 22, 2019, 3:35pm

Update: we noticed that the session usage logs for the SIM show records hitting 100.01MB of data that are timestamped suspiciously close to the time when our devices lose connectivity.

100MB each time. Timestamped the same each time. We happen to have an alternate SIM provider that we’re just starting to trial, and will report back if a similar issue occurs (or not!).

jha · August 30, 2019, 12:22pm

Interested in the result! We are currently using Quectel EG25 to see if the same issue happens…