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

Thu Jul 20 08:42:29 UTC 2017

Looking into it a bit more, the periodic signal update doesn't seem to
cause the issue. But it seems like the primary port is closed and then
reopened, and the init sequence runs while a connect operation is
starting.

2017-07-19T23:59:53.027241-07:00 INFO ModemManager[27458]: <debug>
Reopening data port (ttyUSB3)...
2017-07-19T23:59:53.027267-07:00 INFO ModemManager[27458]: <debug>
(ttyUSB3) reopening port (2)
2017-07-19T23:59:53.027284-07:00 INFO ModemManager[27458]: <debug>
(ttyUSB3) device open count is 1 (close)
2017-07-19T23:59:53.027301-07:00 INFO ModemManager[27458]: <debug>
(ttyUSB3) device open count is 0 (close)
2017-07-19T23:59:53.027320-07:00 INFO ModemManager[27458]: <debug>
(ttyUSB3) closing serial port...
2017-07-19T23:59:53.027348-07:00 INFO ModemManager[27458]: <debug>
(ttyUSB3): port now disconnected
2017-07-19T23:59:53.027390-07:00 INFO ModemManager[27458]: <debug>
(ttyUSB3) serial port closed
2017-07-19T23:59:53.027421-07:00 INFO ModemManager[27458]: <debug>
(ttyUSB1) device open count is 1 (close)
2017-07-19T23:59:54.029832-07:00 INFO ModemManager[27458]: <debug>
(ttyUSB3) opening serial port...
2017-07-19T23:59:54.030487-07:00 INFO ModemManager[27458]: <debug>
(ttyUSB3): setting up baudrate: 57600
2017-07-19T23:59:54.030526-07:00 INFO ModemManager[27458]: <debug>
(ttyUSB3): port attributes not fully set
2017-07-19T23:59:54.030589-07:00 INFO ModemManager[27458]: <debug>
(ttyUSB3) device open count is 1 (open)
2017-07-19T23:59:54.030636-07:00 INFO ModemManager[27458]: <debug>
(ttyUSB3): running init sequence...
2017-07-19T23:59:54.030703-07:00 INFO ModemManager[27458]: <debug>
(ttyUSB3) device open count is 2 (open)
2017-07-19T23:59:54.030753-07:00 INFO ModemManager[27458]: <debug>
Flashing data port (ttyUSB3)...
2017-07-19T23:59:54.030783-07:00 INFO ModemManager[27458]: <debug>
(ttyUSB3): port attributes not fully set
2017-07-19T23:59:54.030832-07:00 INFO ModemManager[27458]: <debug>
(ttyUSB3): --> 'ATE0<CR>'
2017-07-19T23:59:55.031070-07:00 INFO ModemManager[27458]: <debug>
(ttyUSB3) device open count is 1 (close)
2017-07-19T23:59:55.031096-07:00 INFO ModemManager[27458]: <debug> PDP
disconnection already sent
2017-07-19T23:59:55.031157-07:00 INFO ModemManager[27458]: <debug>
Disconnected bearer '/org/freedesktop/ModemManager1/Bearer/1'
2017-07-19T23:59:55.031215-07:00 INFO ModemManager[27458]: <info>
Modem /org/freedesktop/ModemManager1/Modem/0: state changed
(disconnecting -> registered)
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.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>'

On Thu, Jul 20, 2017 at 12:38 AM, Ben Chan <benchan at chromium.org> wrote:
> 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>'
> ==========