On a SIM7100A the PPPD connection fails (modem hangup) with nm-ppp-plugin, but a custom pppd script works
Simon Rijk
s.rijk at viriciti.com
Tue May 18 09:23:11 UTC 2021
OK, great! Here is an update:
We have had an active debugging session with Vodafone and we saw that the
modem (a SIMCom SIM7100A) had collected multiple PDP contexts from networks
along the way (4 of them):
AT+CGDCONT?
+CGDCONT: 1,"IP","phone","0.0.0.0",0,0
+CGDCONT: 2,"IP","3gnet","0.0.0.0",0,0
+CGDCONT: 3,"IP","vf-viriciti","0.0.0.0",0,0
+CGDCONT: 4,"IP","viriciti.com.attz","0.0.0.0",0,0
OK
A "phone" (no clue where that comes from), a "3gnet" (this seems to be an
operator in China), the "vf-viriciti" (that is ours!), and a
"viriciti.com.attz" (this is ours for AT&T).
Looking at the selected one:
AT+CGACT?
+CGACT: 1,1
+CGACT: 2,0
+CGACT: 3,0
+CGACT: 4,0
OK
The modem selected the first one! The "phone" APN... That will obviously
not work in our case :)
>From the ModemManager logs (below) we see that ModemManager does select the
right CID (#3) when looking for the best CID matching the "vf-viriciti" APN.
So it seems modem is the issue here: just removing the first context, and
leaving the others, solves the problem of connectivity!!
But why? Is this just a specific SIM7100A modem issue? Is there a
work-around?
(
little extra context: we always use NetworkManager "nmcli" to initiate
the connection using the nm-ppp-plguin, issuing:
"nmcli c add type gsm ifname ttyUSB2 apn vf-viriciti gsm.number *99***1#
ipv6.method "ignore"
where "gsm.number" is deprecated in NetworkManager
)
HERE ARE THE ModemManager LOGS:
(ModemManager just selects the right CID #3 as the active PDP context)
May 18 08:36:52 vc-f14us31817 ModemManager[6547]: <debug> [modem1] user
request to connect modem
May 18 08:36:52 vc-f14us31817 ModemManager[6547]: <info> [modem1] simple
connect started...
May 18 08:36:52 vc-f14us31817 ModemManager[6547]: <debug> [modem1]
PIN: unspecified
May 18 08:36:52 vc-f14us31817 ModemManager[6547]: <debug> [modem1]
operator ID: unspecified
May 18 08:36:52 vc-f14us31817 ModemManager[6547]: <debug> [modem1]
allowed roaming: yes
May 18 08:36:52 vc-f14us31817 ModemManager[6547]: <debug> [modem1]
APN: vf-viriciti
May 18 08:36:52 vc-f14us31817 ModemManager[6547]: <debug> [modem1] IP
family: ipv4
May 18 08:36:52 vc-f14us31817 ModemManager[6547]: <debug> [modem1]
allowed authentication: unspecified
May 18 08:36:52 vc-f14us31817 ModemManager[6547]: <debug> [modem1]
User: unspecified
May 18 08:36:52 vc-f14us31817 ModemManager[6547]: <debug> [modem1]
Password: unspecified
May 18 08:36:52 vc-f14us31817 ModemManager[6547]: <info> [modem1] simple
connect state (4/8): wait to get fully enabled
May 18 08:36:52 vc-f14us31817 ModemManager[6547]: <info> [modem1] simple
connect state (5/8): register
May 18 08:36:52 vc-f14us31817 ModemManager[6547]: <debug> [modem1]
already registered automatically in network '310260', automatic
registration not launched...
May 18 08:36:52 vc-f14us31817 ModemManager[6547]: <info> [modem1] simple
connect state (6/8): bearer
May 18 08:36:52 vc-f14us31817 ModemManager[6547]: <debug> [modem1]
creating new bearer...
May 18 08:36:52 vc-f14us31817 ModemManager[6547]: <debug> [modem1]
creating broadband bearer in broadband modem...
May 18 08:36:52 vc-f14us31817 ModemManager[6547]: <debug>
[modem1/ttyUSB2/at] device open count is 2 (open)
May 18 08:36:52 vc-f14us31817 ModemManager[6547]: <info> [modem1] simple
connect state (7/8): connect
May 18 08:36:52 vc-f14us31817 ModemManager[6547]: <debug>
[modem1/bearer0] connecting...
May 18 08:36:52 vc-f14us31817 ModemManager[6547]: <info> [modem1] state
changed (registered -> connecting)
May 18 08:36:52 vc-f14us31817 ModemManager[6547]: <debug>
[modem1/bearer0] launching 3GPP connection attempt with APN 'vf-viriciti'
May 18 08:36:52 vc-f14us31817 ModemManager[6547]: <debug>
[modem1/bearer0] checking context definition format...
May 18 08:36:52 vc-f14us31817 ModemManager[6547]: <debug>
[modem1/ttyUSB2/at] device open count is 3 (open)
May 18 08:36:52 vc-f14us31817 ModemManager[6547]: <debug>
[modem1/ttyUSB2/at] device open count is 2 (close)
May 18 08:36:52 vc-f14us31817 ModemManager[6547]: <debug>
[modem1/bearer0] unhandled PDP type in CGDCONT=? reply: 'PPP'
May 18 08:36:52 vc-f14us31817 ModemManager[6547]: <debug>
[modem1/bearer0] checking currently defined contexts...
May 18 08:36:52 vc-f14us31817 ModemManager[6547]: <debug>
[modem1/ttyUSB2/at] device open count is 3 (open)
May 18 08:36:52 vc-f14us31817 ModemManager[6547]: <debug>
[modem1/ttyUSB2/at] device open count is 2 (close)
May 18 08:36:52 vc-f14us31817 ModemManager[6547]: <debug>
[modem1/ttyUSB2/at] --> 'AT+CGDCONT?<CR>'
May 18 08:36:52 vc-f14us31817 ModemManager[6547]: <debug>
[modem1/ttyUSB2/at] <-- '<CR><LF>+CGDCONT:
1,"IP","phone","0.0.0.0",0,0<CR><LF>+CGDCONT:
2,"IP","3gnet","0.0.0.0",0,0<CR><LF>+CGDCONT:
3,"IP","vf-viriciti","0.0.0.0",0,0<CR><LF>+CGDCONT:
4,"IP","viriciti.com.attz","0.0.0.0",0,0<CR><LF><CR><LF>OK<CR><LF>'
May 18 08:36:52 vc-f14us31817 ModemManager[6547]: <debug>
[modem1/bearer0] found 4 PDP contexts
May 18 08:36:52 vc-f14us31817 ModemManager[6547]: <debug>
[modem1/bearer0] PDP context [cid=1] [type='ipv4'] [apn='phone']
May 18 08:36:52 vc-f14us31817 ModemManager[6547]: <debug>
[modem1/bearer0] PDP context [cid=2] [type='ipv4'] [apn='3gnet']
May 18 08:36:52 vc-f14us31817 ModemManager[6547]: <debug>
[modem1/bearer0] PDP context [cid=3] [type='ipv4'] [apn='vf-viriciti']
May 18 08:36:52 vc-f14us31817 ModemManager[6547]: <debug>
[modem1/bearer0] PDP context [cid=4] [type='ipv4']
[apn='viriciti.com.attz']
May 18 08:36:52 vc-f14us31817 ModemManager[6547]: <debug>
[modem1/bearer0] looking for best CID matching APN 'vf-viriciti' and PDP
type 'ipv4'...
May 18 08:36:52 vc-f14us31817 ModemManager[6547]: <debug>
[modem1/bearer0] found exact context at CID 3
May 18 08:36:52 vc-f14us31817 ModemManager[6547]: <debug>
[modem1/ttyUSB2/at] device open count is 3 (open)
May 18 08:36:52 vc-f14us31817 ModemManager[6547]: <debug>
[modem1/bearer0] connection through a plain serial AT port: ttyUSB2
May 18 08:36:52 vc-f14us31817 ModemManager[6547]: <debug>
[modem1/ttyUSB2/at] device open count is 4 (open)
May 18 08:36:52 vc-f14us31817 ModemManager[6547]: <debug>
[modem1/ttyUSB2/at] device open count is 3 (close)
May 18 08:36:52 vc-f14us31817 ModemManager[6547]: <debug>
[modem1/ttyUSB2/at] --> 'ATD*99***3#<CR>'
May 18 08:36:52 vc-f14us31817 ModemManager[6547]: <debug>
[modem1/ttyUSB2/at] <-- '<CR><LF>CONNECT 115200<CR><LF>'
May 18 08:36:52 vc-f14us31817 ModemManager[6547]: <debug>
[modem1/bearer0] setting flow control in ttyUSB2: rts-cts
May 18 08:36:52 vc-f14us31817 ModemManager[6547]: <debug>
[modem1/ttyUSB2/at] enabling RTS/CTS flow control
May 18 08:36:52 vc-f14us31817 ModemManager[6547]: <debug>
[modem1/ttyUSB2/at] port attributes not fully set
May 18 08:36:52 vc-f14us31817 ModemManager[6547]: <debug>
[modem1/ttyUSB2/at] flow control settings updated to rts-cts
May 18 08:36:52 vc-f14us31817 ModemManager[6547]: <debug>
[modem1/ttyUSB2/at] port now connected
May 18 08:36:52 vc-f14us31817 ModemManager[6547]: <debug>
[modem1/bearer0] connected
May 18 08:36:52 vc-f14us31817 ModemManager[6547]: <debug>
[modem1/bearer0] PPP is required for connection, will ignore disconnection
reports
May 18 08:36:52 vc-f14us31817 ModemManager[6547]: <info> [modem1] state
changed (connecting -> connected)
May 18 08:36:52 vc-f14us31817 ModemManager[6547]: <info> [modem1] simple
connect state (8/8): all done
May 18 08:36:52 vc-f14us31817 ModemManager[6547]: <debug>
[modem1/ttyUSB2/at] device open count is 2 (close)
May 18 08:36:52 vc-f14us31817 ModemManager[6547]: <debug> [base-manager]
adding port ppp0 at sysfs path: /sys/devices/virtual/net/ppp0
May 18 08:36:52 vc-f14us31817 ModemManager[6547]: <debug> [filter]
(net/ppp0) port filtered: forbidden port type
May 18 08:36:53 vc-f14us31817 ModemManager[6547]: <debug>
[modem1/ttyUSB3/at] <-- '<CR><LF>NO CARRIER<CR><LF>'
May 18 08:36:53 vc-f14us31817 ModemManager[6547]: <debug>
[modem1/ttyUSB3/at] operation failure: 1 (No carrier)
May 18 08:36:53 vc-f14us31817 ModemManager[6547]: <debug>
[modem1/ttyUSB3/at] <-- '<CR><LF>+PPPD: DISCONNECTED<CR><LF>'
May 18 08:36:53 vc-f14us31817 ModemManager[6547]: <debug> [modem1] user
request to disconnect modem (all bearers)
May 18 08:36:53 vc-f14us31817 ModemManager[6547]: <debug>
[modem1/bearer0] disconnecting...
May 18 08:36:53 vc-f14us31817 ModemManager[6547]: <info> [modem1] state
changed (connected -> disconnecting)
May 18 08:36:53 vc-f14us31817 ModemManager[6547]: <debug>
[modem1/bearer0] sending PDP context deactivation in secondary port...
May 18 08:36:53 vc-f14us31817 ModemManager[6547]: <debug>
[modem1/ttyUSB3/at] device open count is 2 (open)
May 18 08:36:53 vc-f14us31817 ModemManager[6547]: <debug>
[modem1/ttyUSB3/at] --> 'AT+CGACT=0,3<CR>'
May 18 08:36:53 vc-f14us31817 ModemManager[6547]: <debug>
[modem1/ttyUSB3/at] <-- '<CR><LF>OK<CR><LF>'
May 18 08:36:53 vc-f14us31817 ModemManager[6547]: <debug>
[modem1/bearer0] reopening data port ttyUSB2...
May 18 08:36:53 vc-f14us31817 ModemManager[6547]: <debug>
[modem1/ttyUSB2/at] reopening port (2)
May 18 08:36:53 vc-f14us31817 ModemManager[6547]: <debug>
[modem1/ttyUSB2/at] device open count is 1 (close)
May 18 08:36:53 vc-f14us31817 ModemManager[6547]: <debug>
[modem1/ttyUSB2/at] device open count is 0 (close)
May 18 08:36:53 vc-f14us31817 ModemManager[6547]: <debug>
[modem1/ttyUSB2/at] closing serial port...
May 18 08:36:53 vc-f14us31817 ModemManager[6547]: <debug>
[modem1/ttyUSB2/at] port now disconnected
May 18 08:36:53 vc-f14us31817 ModemManager[6547]: <debug>
[modem1/ttyUSB2/at] serial port closed
May 18 08:36:53 vc-f14us31817 ModemManager[6547]: <debug>
[modem1/ttyUSB3/at] device open count is 1 (close)
May 18 08:36:53 vc-f14us31817 ModemManager[6547]: <debug> [modem1] user
request to disconnect modem (all bearers)
May 18 08:36:53 vc-f14us31817 ModemManager[6547]: <debug> [modem1] user
request to connect modem
>
On Tue, May 11, 2021 at 8:36 PM Aleksander Morgado <aleksander at aleksander.es>
wrote:
> Hey!
>
> >
> > We have some strange behavior (on a SIM7100A) where NetworkManager
> (using the nm-ppp-plugin) needs to initiate a connection with Vodafone
> (private APN). The modem gets registered successfully on the network
> (roaming over the available T-Mobile or AT&T networks), but receives a
> modem hangup (the modem gives a "NO CARRIER" error) which leads to pppd
> disconnecting. However, when using a custom pppd script (and without using
> ModemManager & NetworkManager), we are able to setup a data connection.
>
> This is a follow up of this email right?
>
> https://lists.freedesktop.org/archives/modemmanager-devel/2021-April/008526.html
> Just for context.
>
yes!
>
> >
> > * MM version is 1.14.10
> > * NM version is 1.28.0
> > * pppd version is 2.4.9
> >
> > When using NetworkManager the pppd options that seem to be used (from
> evaluating debug output of NetworkManager) are:
> > ttyUSB2
> > debug
> > idle 0
> > ipparam
> > lcp-echo-failure 0
> > lcp-echo-interval 0
> > lock
> > noauth
> > nodefaultroute
> > nodetach
> > noipdefault
> > noipv6
> > usepeerdns
> >
> > and this results into the following pppd output:
> > Serial connection established.
> > using channel 23
> > Using interface ppp0
> > Connect: ppp0 <--> /dev/ttyUSB3
> > sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x8e804837> <pcomp>
> <accomp>]
> > rcvd [LCP ConfReq id=0x3f <asyncmap 0x0> <auth chap MD5> <magic
> 0x88528a77> <pcomp> <accomp>]
> > No auth is possible
> > sent [LCP ConfRej id=0x3f <auth chap MD5>]
> > rcvd [LCP ConfAck id=0x1 <asyncmap 0x0> <magic 0x8e804837> <pcomp>
> <accomp>]
> > rcvd [LCP ConfReq id=0x40 <asyncmap 0x0> <magic 0x88528a77> <pcomp>
> <accomp>]
> > sent [LCP ConfAck id=0x40 <asyncmap 0x0> <magic 0x88528a77> <pcomp>
> <accomp>]
> > sent [IPCP ConfReq id=0x1 <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns2
> 0.0.0.0>]
> > sent [IPV6CP ConfReq id=0x1 <addr fe80::9095:1777:829f:47a0>]
> > rcvd [LCP DiscReq id=0x41 magic=0x88528a77]
> > Modem hangup
> > Connection terminated.
> >
> > We do get good results when just running manual pppd script manually (no
> ModemManager and NetworkManager active), but with quite different options
> from the NetworkManager defaults. From the manual pppd script (a script
> taken from Quectel) the options are:
> > debug
> > defaultroute
> > dump
> > hide-password
> > ipcp-accept-local
> > ipcp-accept-remote
> > ipcp-max-failure 30
> > ipparam 3gppp
> > lock
> > modem
> > noauth
> > noccp
> > nocrtscts
> > nodetach
> > noipdefault
> > novj
> > novjccomp
> > remotename 3gppp
> > usepeerdns
> >
> > And that gives a good result (shortened pppd output a bit):
> > $ pppd debug call gprs
> > pppd options in effect:
> > debug debug
> > nodetach
> > dump
> > noauth
> > remotename 3gppp
> > /dev/ttyUSB3
> > 115200
> > lock
> > connect chat -s -v -f /data/ppp/chatscripts/quectel-chat-connect -T
> vf-viriciti
> > disconnect chat -s -v -f
> /data/ppp/chatscripts/quectel-chat-disconnect
> > nocrtscts
> > modem
> > hide-password
> > novj
> > novjccomp
> > ipcp-accept-local
> > ipcp-accept-remote
> > ipparam 3gppp
> > noipdefault
> > ipcp-max-failure 30
> > defaultroute
> > usepeerdns
> > noccp
> > abort on (BUSY)
> > abort on (NO CARRIER)
> > abort on (NO DIALTONE)
> > abort on (ERROR)
> > abort on (NO ANSWER)
> > timeout set to 30 seconds
> > send (AT^M)
> > expect (OK)
> > AT^M^M
> > OK
> > -- got it
> >
> > send (ATE0^M)
> > expect (OK)
> > ^M
> > ATE0^M^M
> > OK
> > -- got it
> >
> > send (ATI;+CSUB;+CSQ;+COPS?;+CGREG?;&D2^M)
> > expect (OK)
> > ^M
> > ^M
> > Manufacturer: SIMCOM INCORPORATED^M
> > Model: SIMCOM_SIM7100A^M
> > Revision: SIM7100A_V4.5^M
> > IMEISV: 014339000429148/05^M
> > +GCAP: +CGSM^M
> > ^M
> > +CSUB: B03V03^M
> > +CSUB: MDM9x15_AP_S_V1.63_161010^M
> > ^M
> > +CSQ: 26,99^M
> > ^M
> > +COPS: 1,0,"T-Mobile DATA ONLY",7^M
> > ^M
> > +CGREG: 0,5^M
> > ^M
> > OK
> > -- got it
> >
> > send (AT+COPS=1,2,310260^M)
> > expect (OK)
> > ^M
> > ^M
> > OK
> > -- got it
> >
> > send (AT+CGDCONT=1,"IP","vf-viriciti",,0,0^M)
> > expect (OK)
> > ^M
> > ^M
> > OK
> > -- got it
> >
> > send (ATDT*99***1#^M)
> > expect (CONNECT)
> > ^M
> > ^M
> > CONNECT
> > -- got it
> >
> > Script chat -s -v -f /data/ppp/chatscripts/quectel-chat-connect -T
> vf-viriciti finished (pid 11933), status = 0x0
> > Serial connection established.
> > using channel 25
> > Using interface ppp0
> > Connect: ppp0 <--> /dev/ttyUSB3
> > sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0xfb7fbc11> <pcomp>
> <accomp>]
> > rcvd [LCP ConfReq id=0x0 <asyncmap 0x0> <auth chap MD5> <magic
> 0x8856fba8> <pcomp> <accomp>]
> > No auth is possible
> > sent [LCP ConfRej id=0x0 <auth chap MD5>]
> > rcvd [LCP ConfAck id=0x1 <asyncmap 0x0> <magic 0xfb7fbc11> <pcomp>
> <accomp>]
> > rcvd [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x8856fba8> <pcomp>
> <accomp>]
> > sent [LCP ConfAck id=0x1 <asyncmap 0x0> <magic 0x8856fba8> <pcomp>
> <accomp>]
> > sent [IPCP ConfReq id=0x1 <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns2
> 0.0.0.0>]
> > sent [IPV6CP ConfReq id=0x1 <addr fe80::64c5:e93a:eca7:5409>]
> > rcvd [LCP DiscReq id=0x2 magic=0x8856fba8]
> > rcvd [IPCP ConfReq id=0x0]
> > sent [IPCP ConfNak id=0x0 <addr 0.0.0.0>]
> > rcvd [IPCP ConfNak id=0x1 <addr 10.141.107.204> <ms-dns1 10.1.2.199>
> <ms-dns2 10.1.2.200>]
> > sent [IPCP ConfReq id=0x2 <addr 10.141.107.204> <ms-dns1 10.1.2.199>
> <ms-dns2 10.1.2.200>]
> > rcvd [IPCP ConfReq id=0x1]
> > sent [IPCP ConfAck id=0x1]
> > rcvd [IPCP ConfAck id=0x2 <addr 10.141.107.204> <ms-dns1 10.1.2.199>
> <ms-dns2 10.1.2.200>]
> > Could not determine remote IP address: defaulting to 10.64.64.64
> > not replacing default route to eth0 [192.168.1.254]
> > local IP address 10.141.107.204
> > remote IP address 10.64.64.64
> > primary DNS address 10.1.2.199
> > secondary DNS address 10.1.2.200
> > sent [IPV6CP ConfReq id=0x1 <addr fe80::64c5:e93a:eca7:5409>]
> > sent [IPV6CP ConfReq id=0x1 <addr fe80::64c5:e93a:eca7:5409>]
> >
> >
> > What we would like of course is for NetworkManager and the nm-ppp-plugin
> to basically also just get the connection up and running. At the moment we
> are clueless why the combination of ModemManager & NetworkManager is not
> able to obtain an active data sessions, but the manual pppd script is.
>
> Have you tried to add to the NM plugin the options that are in the
> manual pppd script?
>
> yes
>
> > More (debug) info if attached in a pdf!
> >
> > I hope someone has any clue on the particular case, how to debug better,
> or can give an idea if this is a network operator sided issue.
> >
>
> I'm afraid I haven't seen an issue like this before myself.
>
> --
> Aleksander
> https://aleksander.es
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.freedesktop.org/archives/modemmanager-devel/attachments/20210518/61256d9e/attachment-0001.htm>
More information about the ModemManager-devel
mailing list