Unexpected +CGDCONT? error: 'Sending command failed: 'Resource temporarily unavailable''

Ben Chan benchan at chromium.org
Thu Jul 20 07:38:27 UTC 2017 

Hi Aleksander,

I'm looking into an issue with MMBroadbandBearer::cid_selection_3gpp:

<debug> Looking for best CID...
<debug> (ttyUSB3) device open count is 2 (open)
<debug> (ttyUSB3): --> 'ATX4<CR>'
<debug> (ttyUSB3): --> 'AT&C1<CR>'
<debug> (ttyUSB3): --> 'AT+CGDCONT?<CR>'
<debug> loading signal quality...
<debug> (ttyUSB3) device open count is 3 (open)
<debug> Unexpected +CGDCONT? error: 'Sending command failed: 'Resource
temporarily unavailable''

After bisecting the git commits, the issue seems related to commit
8ad868cea27f2ab043e5dfb544d5d70de34f60c2 ("iface-modem: consolidate
signal quality and access tech polling"). I am wondering if the signal
quality update could potentially interfere with an ongoing connect
(and similarly, disconnect) operation.  Have you observed a similar
issue before?

Thanks,
Ben

==========
# Before commit 8ad868cea27f2ab043e5dfb544d5d70de34f60c2

2017-07-20T00:14:14.544140-07:00 INFO ModemManager[29262]: <debug>
(ttyUSB3): --> 'AT+CIND?<CR>'
2017-07-20T00:14:14.555367-07:00 INFO ModemManager[29262]: <info>
Simple connect started...
2017-07-20T00:14:14.555392-07:00 INFO ModemManager[29262]: <debug>
PIN: unspecified
2017-07-20T00:14:14.555406-07:00 INFO ModemManager[29262]: <debug>
Operator ID: unspecified
2017-07-20T00:14:14.555420-07:00 INFO ModemManager[29262]: <debug>
Allowed roaming: no
2017-07-20T00:14:14.555435-07:00 INFO ModemManager[29262]: <debug>
APN: fast.t-mobile.com
2017-07-20T00:14:14.555450-07:00 INFO ModemManager[29262]: <debug>
IP family: unspecified
2017-07-20T00:14:14.555465-07:00 INFO ModemManager[29262]: <debug>
Allowed authentication: unspecified
2017-07-20T00:14:14.555480-07:00 INFO ModemManager[29262]: <debug>
User: unspecified
2017-07-20T00:14:14.555495-07:00 INFO ModemManager[29262]: <debug>
Password: unspecified
2017-07-20T00:14:14.555509-07:00 INFO ModemManager[29262]: <debug>
Number: *99#
2017-07-20T00:14:14.555525-07:00 INFO ModemManager[29262]: <info>
Simple connect state (4/8): Wait to get fully enabled
2017-07-20T00:14:14.556032-07:00 INFO ModemManager[29262]: <info>
Simple connect state (5/8): Register
2017-07-20T00:14:14.556123-07:00 INFO ModemManager[29262]: <debug>
Already registered in network '310260', automatic registration not
launched...
2017-07-20T00:14:14.556188-07:00 INFO ModemManager[29262]: <info>
Simple connect state (6/8): Bearer
2017-07-20T00:14:14.556213-07:00 INFO ModemManager[29262]: <debug>
Using already existing bearer at
'/org/freedesktop/ModemManager1/Bearer/0'...
2017-07-20T00:14:14.556229-07:00 INFO ModemManager[29262]: <info>
Simple connect state (7/8): Connect
2017-07-20T00:14:07.822817-07:00 INFO ModemManager[29262]: <debug>
Connecting bearer '/org/freedesktop/ModemManager1/Bearer/0'
2017-07-20T00:14:07.822856-07:00 INFO ModemManager[29262]: <info>
Modem /org/freedesktop/ModemManager1/Modem/0: state changed
(registered ->
connecting)
2017-07-20T00:14:07.823186-07:00 INFO ModemManager[29262]: <debug>
Launching 3GPP connection attempt with APN 'fast.t-mobile.com'
2017-07-20T00:14:07.823211-07:00 INFO ModemManager[29262]: <debug> No
specific IP family requested, defaulting to ipv4
2017-07-20T00:14:07.823228-07:00 INFO ModemManager[29262]: <debug> No
specific IP family requested, defaulting to ipv4
2017-07-20T00:14:07.823246-07:00 INFO ModemManager[29262]: <debug>
Looking for best CID...
2017-07-20T00:14:07.823273-07:00 INFO ModemManager[29262]: <debug>
(ttyUSB3) device open count is 2 (open)
2017-07-20T00:14:07.823331-07:00 INFO ModemManager[29262]: <debug>
(ttyUSB3): --> 'AT+CGDCONT?<CR>'
2017-07-20T00:14:07.846045-07:00 INFO ModemManager[29262]: <debug>
(ttyUSB3): <-- '<CR><LF>+CGDCONT:
1,"IP","fast.t-mobile.com","0.0.0.0",0,0<CR><LF>+CGDCONT:
2,"IP","Broadband","0.0.0.0",0,0<CR><LF>+CGDCONT:
3,"IP","fast.t-mobile.com","0.0.0.0",0,0<CR><LF><CR><LF>OK<CR><LF>'
2017-07-20T00:14:07.846194-07:00 INFO ModemManager[29262]: <debug>
Found '3' PDP contexts
2017-07-20T00:14:07.846216-07:00 INFO ModemManager[29262]: <debug>
PDP context [cid=1] [type='ipv4'] [apn='fast.t-mobile.com']
2017-07-20T00:14:07.846231-07:00 INFO ModemManager[29262]: <debug>
PDP context [cid=2] [type='ipv4'] [apn='Broadband']
2017-07-20T00:14:07.846246-07:00 INFO ModemManager[29262]: <debug>
PDP context [cid=3] [type='ipv4'] [apn='fast.t-mobile.com']
2017-07-20T00:14:07.846263-07:00 INFO ModemManager[29262]: <debug>
Found PDP context with CID 1 and PDP type ipv4 for APN
'fast.t-mobile.com'

==========
# After commit 8ad868cea27f2ab043e5dfb544d5d70de34f60c2

2017-07-19T23:59:58.200261-07:00 INFO ModemManager[27458]: <debug>
(ttyUSB3): --> 'ATV1<CR>'
2017-07-20T00:00:02.346800-07:00 INFO ModemManager[27458]: <debug>
(ttyUSB3): --> 'AT+CMEE=1<CR>'
2017-07-20T00:00:05.093351-07:00 INFO ModemManager[27458]: <info>
Simple connect started...
2017-07-20T00:00:05.093373-07:00 INFO ModemManager[27458]: <debug>
PIN: unspecified
2017-07-20T00:00:05.093387-07:00 INFO ModemManager[27458]: <debug>
Operator ID: unspecified
2017-07-20T00:00:05.093402-07:00 INFO ModemManager[27458]: <debug>
Allowed roaming: yes
2017-07-20T00:00:05.093416-07:00 INFO ModemManager[27458]: <debug>
APN: fast.t-mobile.com
2017-07-20T00:00:05.093429-07:00 INFO ModemManager[27458]: <debug>
IP family: unspecified
2017-07-20T00:00:05.093444-07:00 INFO ModemManager[27458]: <debug>
Allowed authentication: unspecified
2017-07-20T00:00:05.093457-07:00 INFO ModemManager[27458]: <debug>
User: unspecified
2017-07-20T00:00:05.093471-07:00 INFO ModemManager[27458]: <debug>
Password: unspecified
2017-07-20T00:00:05.093484-07:00 INFO ModemManager[27458]: <debug>
Number: #777
2017-07-20T00:00:05.093498-07:00 INFO ModemManager[27458]: <info>
Simple connect state (4/8): Wait to get fully enabled
2017-07-20T00:00:05.093543-07:00 INFO ModemManager[27458]: <info>
Simple connect state (5/8): Register
2017-07-20T00:00:05.093587-07:00 INFO ModemManager[27458]: <debug>
Already registered in network '310260', automatic registration not
launched...
2017-07-20T00:00:05.093641-07:00 INFO ModemManager[27458]: <info>
Simple connect state (6/8): Bearer
2017-07-20T00:00:05.093663-07:00 INFO ModemManager[27458]: <debug>
Using already existing bearer at
'/org/freedesktop/ModemManager1/Bearer/1'...
2017-07-20T00:00:05.093677-07:00 INFO ModemManager[27458]: <info>
Simple connect state (7/8): Connect
2017-07-20T00:00:05.093702-07:00 INFO ModemManager[27458]: <debug>
Connecting bearer '/org/freedesktop/ModemManager1/Bearer/1'
2017-07-20T00:00:05.093743-07:00 INFO ModemManager[27458]: <info>
Modem /org/freedesktop/ModemManager1/Modem/0: state changed
(registered -> connecting)
2017-07-20T00:00:05.094072-07:00 INFO ModemManager[27458]: <debug>
Launching 3GPP connection attempt with APN 'fast.t-mobile.com'
2017-07-20T00:00:05.094097-07:00 INFO ModemManager[27458]: <debug> No
specific IP family requested, defaulting to ipv4
2017-07-20T00:00:05.094113-07:00 INFO ModemManager[27458]: <debug> No
specific IP family requested, defaulting to ipv4
2017-07-20T00:00:05.094131-07:00 INFO ModemManager[27458]: <debug>
Looking for best CID...
2017-07-20T00:00:05.094158-07:00 INFO ModemManager[27458]: <debug>
(ttyUSB3) device open count is 2 (open)
2017-07-20T00:00:06.426622-07:00 INFO ModemManager[27458]: <debug>
(ttyUSB3): --> 'ATX4<CR>'
2017-07-20T00:00:10.319262-07:00 INFO ModemManager[27458]: <debug>
(ttyUSB3): --> 'AT&C1<CR>'
2017-07-20T00:00:14.189035-07:00 INFO ModemManager[27458]: <debug>
(ttyUSB3): --> 'AT+CGDCONT?<CR>'
2017-07-20T00:00:14.416879-07:00 INFO ModemManager[27458]: <debug>
loading signal quality...
2017-07-20T00:00:14.416943-07:00 INFO ModemManager[27458]: <debug>
(ttyUSB3) device open count is 3 (open)
2017-07-20T00:00:18.061851-07:00 INFO ModemManager[27458]: <debug>
Unexpected +CGDCONT? error: 'Sending command failed: 'Resource
temporarily unavailable''
2017-07-20T00:00:18.061921-07:00 INFO ModemManager[27458]: <debug>
(ttyUSB3): --> 'AT+CIND?<CR>'
2017-07-20T00:00:21.936170-07:00 INFO ModemManager[27458]: <debug>
(ttyUSB3) device open count is 4 (open)
2017-07-20T00:00:21.936221-07:00 INFO ModemManager[27458]: <debug>
(ttyUSB3) device open count is 3 (close)
2017-07-20T00:00:21.936336-07:00 INFO ModemManager[27458]: <debug>
Unhandled PDP type in CGDCONT=? reply: 'PPP'
2017-07-20T00:00:21.936371-07:00 INFO ModemManager[27458]: <debug>
Using empty CID 1 with PDP type 'ipv4'
2017-07-20T00:00:21.936404-07:00 INFO ModemManager[27458]: <debug>
(ttyUSB3) device open count is 4 (open)
2017-07-20T00:00:21.936436-07:00 INFO ModemManager[27458]: <debug>
(ttyUSB3) device open count is 3 (close)
2017-07-20T00:00:21.936472-07:00 INFO ModemManager[27458]: <debug>
(ttyUSB3): --> 'AT+CSQ<CR>'
2017-07-20T00:00:25.808563-07:00 INFO ModemManager[27458]: <debug>
(ttyUSB3) device open count is 2 (close)
2017-07-20T00:00:25.808634-07:00 INFO ModemManager[27458]: <debug>
Couldn't refresh signal quality: 'Sending command failed: 'Resource
temporarily unavailable''
2017-07-20T00:00:25.808681-07:00 INFO ModemManager[27458]: <debug>
(ttyUSB3) device open count is 3 (open)
2017-07-20T00:00:25.808732-07:00 INFO ModemManager[27458]: <debug>
(ttyUSB3): --> 'AT+CGDCONT=1,"IP","fast.t-mobile.com"<CR>'
2017-07-20T00:00:29.691885-07:00 WARNING ModemManager[27458]: <warn>
Couldn't initialize PDP context with our APN: 'Sending command failed:
'Resource temporarily unavailable''
2017-07-20T00:00:29.691924-07:00 INFO ModemManager[27458]: <debug>
(ttyUSB3) device open count is 2 (close)
2017-07-20T00:00:29.691981-07:00 INFO ModemManager[27458]: <debug>
Couldn't connect bearer '/org/freedesktop/ModemManager1/Bearer/1':
'Sending command failed: 'Resource temporarily unavailable''
2017-07-20T00:00:29.692030-07:00 INFO ModemManager[27458]: <info>
Modem /org/freedesktop/ModemManager1/Modem/0: state changed
(connecting -> registered)
2017-07-20T00:00:29.692494-07:00 INFO ModemManager[27458]: <debug>
Couldn't connect bearer: 'Sending command failed: 'Resource
temporarily unavailable''
2017-07-20T00:00:29.692665-07:00 INFO ModemManager[27458]: <debug>
(ttyUSB3): --> 'AT+ZPAS?<CR>'
==========

More information about the ModemManager-devel mailing list