> 
> Try this patch instead...
> 
> Dan
> 
> ---
>  src/mm-iface-modem-3gpp.c | 28 +++++++++++++++-------------
>  1 file changed, 15 insertions(+), 13 deletions(-)
> 
> diff --git a/src/mm-iface-modem-3gpp.c b/src/mm-iface-modem-3gpp.c
> index baf743fb..77b502c0 100644
> --- a/src/mm-iface-modem-3gpp.c
> +++ b/src/mm-iface-modem-3gpp.c
> @@ -119,6 +119,13 @@ get_registration_state_context
> (MMIfaceModem3gpp *self)
>      return ctx;
>  }
> 
> +static gboolean
> +reg_state_is_registered (MMModem3gppRegistrationState state) {
> +    return state == MM_MODEM_3GPP_REGISTRATION_STATE_HOME ||
> +        state == MM_MODEM_3GPP_REGISTRATION_STATE_ROAMING;
> +}
> +
>  static MMModem3gppRegistrationState
>  get_consolidated_reg_state (RegistrationStateContext *ctx)  { @@ -268,8
> +275,7 @@ run_registration_checks_ready (MMIfaceModem3gpp *self,
>      }
> 
>      /* If we got registered, end registration checks */
> -    if (current_registration_state ==
> MM_MODEM_3GPP_REGISTRATION_STATE_HOME ||
> -        current_registration_state ==
> MM_MODEM_3GPP_REGISTRATION_STATE_ROAMING) {
> +    if (reg_state_is_registered (current_registration_state)) {
>          /* Request immediate access tech update */
>          mm_iface_modem_refresh_access_technologies (MM_IFACE_MODEM
> (ctx->self));
>          mm_dbg ("Modem is currently registered in a 3GPP network"); @@ -
> 391,9 +397,11 @@ mm_iface_modem_3gpp_register_in_network
> (MMIfaceModem3gpp *self,
>      }
>      /* Automatic registration requested? */
>      else {
> +        MMModem3gppRegistrationState reg_state =
> + mm_gdbus_modem3gpp_get_registration_state (ctx->skeleton);
> +
>          /* If the modem is already registered and the last time it was asked
>           * automatic registration, we're done */
> -        if (current_operator_code &&
> +        if ((current_operator_code || reg_state_is_registered
> + (reg_state)) &&
>              !registration_state_context->manual_registration) {
>              mm_dbg ("Already registered in network '%s',"
>                      " automatic registration not launched...", @@ -1033,9 
> +1041,7 @@
> mm_iface_modem_3gpp_update_access_technologies
> (MMIfaceModem3gpp *self,
> 
>      /* Even if registration state didn't change, report access technology,
>       * but only if something valid to report */
> -    if (state == MM_MODEM_3GPP_REGISTRATION_STATE_HOME ||
> -        state == MM_MODEM_3GPP_REGISTRATION_STATE_ROAMING ||
> -        ctx->reloading_registration_info) {
> +    if (reg_state_is_registered (state) ||
> + ctx->reloading_registration_info) {
>          if (access_tech != MM_MODEM_ACCESS_TECHNOLOGY_UNKNOWN)
>              mm_iface_modem_update_access_technologies (MM_IFACE_MODEM
> (self),
>                                                         access_tech, @@ 
> -1068,9 +1074,7 @@
> mm_iface_modem_3gpp_update_location (MMIfaceModem3gpp *self,
>       * location updates, but only if something valid to report. For the case
>       * where we're registering (loading current registration info after a 
> state
>       * change to registered), we also allow LAC/CID updates. */
> -    if (ctx->reloading_registration_info ||
> -        state == MM_MODEM_3GPP_REGISTRATION_STATE_HOME ||
> -        state == MM_MODEM_3GPP_REGISTRATION_STATE_ROAMING) {
> +    if (reg_state_is_registered (state) ||
> + ctx->reloading_registration_info) {
>          if (location_area_code > 0 && cell_id > 0)
>              mm_iface_modem_location_3gpp_update_lac_ci
> (MM_IFACE_MODEM_LOCATION (self),
>                                                          location_area_code, 
> @@ -1122,8 +1126,7 @@
> update_non_registered_state (MMIfaceModem3gpp *self,
>       * sent by the carrier during registration or b) by looking at the
>       * registration reject error code.  If b), we want to make sure we
>       * preserve the subscription state */
> -    if (old_state == MM_MODEM_3GPP_REGISTRATION_STATE_HOME ||
> -        old_state == MM_MODEM_3GPP_REGISTRATION_STATE_ROAMING)
> +    if (reg_state_is_registered (old_state))
>          clear_subscription_state (self);
> 
>      /* The property in the interface is bound to the property @@ -1160,8
> +1163,7 @@ update_registration_state (MMIfaceModem3gpp *self,
>      if (new_state == old_state)
>          return;
> 
> -    if (new_state == MM_MODEM_3GPP_REGISTRATION_STATE_HOME ||
> -        new_state == MM_MODEM_3GPP_REGISTRATION_STATE_ROAMING) {
> +    if (reg_state_is_registered (new_state)) {
>          /* If already reloading registration info, skip it */
>          if (ctx->reloading_registration_info)
>              return;
> --
> 2.14.3

Dan

The patch was somewhat mangled by the email client, but I fixed it.  This seems 
to have fixed the issue when manually starting the connection after 
ModemManager has already successfully registered the modem. I am connecting and 
obtaining an IP address on the cell connection within 3 seconds in this 
situation.

There is still an issue that exists where if the GSM connection in 
NetworkManager is setup for "connection.autoconnect yes".  At boot it the GSM 
connection now takes 70-90 seconds to connect after the start of trying, which 
is 1.5 to 2 times as long as it used to be.  It looks like NetworkManager is 
requesting the connection up before the initial modem registration on the 
network and this is causing the delay that was seen always before your patch.  
Is there any way to force NetworkManager to wait for just the GSM connection or 
to have ModemManager wait for auto registration before continuing with the 
Registration step?

I attached some log output attached of the boot output from NetworkManager and 
ModemManager.  At Feb 7 17:35:45, NetworkManager started activating the GSM 
connection.  At Feb 7 17:36:55, the connection was finally successful.

Matt
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.111201] [mm-broadband-modem.c:3139] load_power_state(): loading 
power state...
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.111985] [mm-port-serial.c:1296] mm_port_serial_open(): (ttyACM0) 
device open count is 3 (open)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.112557] [mm-port-serial.c:1353] _close_internal(): (ttyACM0) device 
open count is 2 (close)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.113039] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): --> 
'AT+CFUN?<CR>'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.123862] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): <-- 
'<CR><LF>+CFUN: 1,0<CR><LF><CR><LF>OK<CR><LF>'
Feb  7 17:35:45 canect2 daemon.warn ModemManager[302]: <warn>  
[1518024945.124740] [mm-iface-modem.c:4047] load_power_state_ready(): couldn't 
load Power State: 'Failed to parse +CFUN? response '1,0''
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.125251] [mm-broadband-modem.c:1328] modem_load_unlock_required(): 
checking if unlock required...
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.125679] [mm-port-serial.c:1296] mm_port_serial_open(): (ttyACM0) 
device open count is 3 (open)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.126159] [mm-port-serial.c:1353] _close_internal(): (ttyACM0) device 
open count is 2 (close)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.126628] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): --> 
'AT+CPIN?<CR>'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.137337] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): <-- 
'<CR><LF>+CPIN: READY<CR><LF><CR><LF>OK<CR><LF>'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.138097] [mm-port-serial.c:1353] _close_internal(): (ttyACM0) device 
open count is 1 (close)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.138638] [mm-iface-modem.c:3106] update_lock_info_context_step(): 
SIM is ready, and no need for the after SIM unlock step...
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.140519] [mm-base-sim.c:1004] load_sim_identifier(): loading SIM 
identifier...
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.141076] [mm-port-serial.c:1296] mm_port_serial_open(): (ttyACM0) 
device open count is 2 (open)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.141675] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): --> 
'AT+CRSM=176,12258,0,0,10<CR>'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.184607] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): <-- 
'<CR><LF>+CRSM: 144,0,"XXXXXXXXXXXXXXXXXXXX"<CR><LF><CR><LF>OK<CR><LF>'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.185525] [mm-base-sim.c:993] load_sim_identifier_finish(): loaded 
SIM identifier: XXXXXXXXXXXXXXXXXXXX
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.187213] [mm-base-sim.c:1074] load_imsi(): loading IMSI...
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.187744] [mm-port-serial.c:1296] mm_port_serial_open(): (ttyACM0) 
device open count is 3 (open)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.188263] [mm-port-serial.c:1353] _close_internal(): (ttyACM0) device 
open count is 2 (close)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.188755] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): --> 
'AT+CIMI<CR>'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.198464] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): <-- 
'<CR><LF>XXXXXXXXXXXXXXX<CR><LF><CR><LF>OK<CR><LF>'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.199150] [mm-base-sim.c:1063] load_imsi_finish(): loaded IMSI: 
XXXXXXXXXXXXXXX
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.199683] [mm-base-sim.c:1194] load_operator_identifier(): loading 
Operator ID...
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.200173] [mm-port-serial.c:1296] mm_port_serial_open(): (ttyACM0) 
device open count is 3 (open)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.200698] [mm-port-serial.c:1353] _close_internal(): (ttyACM0) device 
open count is 2 (close)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.201158] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): --> 
'AT+CRSM=176,28589,0,0,4<CR>'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.241671] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): <-- 
'<CR><LF>+CRSM: 144,0,"00000003"<CR><LF><CR><LF>OK<CR><LF>'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.242846] [mm-base-sim.c:1289] load_operator_name(): loading Operator 
Name...
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.243372] [mm-port-serial.c:1296] mm_port_serial_open(): (ttyACM0) 
device open count is 3 (open)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.243958] [mm-port-serial.c:1353] _close_internal(): (ttyACM0) device 
open count is 2 (close)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.244425] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): --> 
'AT+CRSM=176,28486,0,0,17<CR>'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.283974] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): <-- 
'<CR><LF>+CRSM: 106,130<CR><LF><CR><LF>OK<CR><LF>'
Feb  7 17:35:45 canect2 daemon.warn ModemManager[302]: <warn>  
[1518024945.284993] [mm-base-sim.c:1425] load_operator_name_ready(): couldn't 
load Operator name: 'Failed to parse CRSM query result '+CRSM: 106,130''
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.285479] [mm-port-serial.c:1353] _close_internal(): (ttyACM0) device 
open count is 1 (close)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.286506] [mm-broadband-modem.c:1206] modem_load_own_numbers(): 
loading own numbers...
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.286997] [mm-port-serial.c:1296] mm_port_serial_open(): (ttyACM0) 
device open count is 2 (open)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.287565] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): --> 
'AT+CNUM<CR>'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.331472] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): <-- 
'<CR><LF>OK<CR><LF>'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.333185] [mm-port-serial.c:1353] _close_internal(): (ttyACM0) device 
open count is 1 (close)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.335813] [mm-broadband-modem.c:3242] modem_3gpp_load_imei(): loading 
IMEI...
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.336359] [mm-port-serial.c:1296] mm_port_serial_open(): (ttyACM0) 
device open count is 2 (open)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.336947] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): --> 
'AT+CGSN<CR>'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.351471] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): <-- 
'<CR><LF>XXXXXXXXXXXXXXX<CR><LF><CR><LF>OK<CR><LF>'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.352184] [mm-broadband-modem.c:3233] modem_3gpp_load_imei_finish(): 
loaded IMEI: XXXXXXXXXXXXXXX
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.352724] [mm-broadband-modem.c:3401] 
modem_3gpp_load_enabled_facility_locks(): loading enabled facility locks...
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.353160] [mm-port-serial.c:1296] mm_port_serial_open(): (ttyACM0) 
device open count is 3 (open)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.353671] [mm-port-serial.c:1353] _close_internal(): (ttyACM0) device 
open count is 2 (close)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.354188] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): --> 
'AT+CLCK=?<CR>'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.366473] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): <-- 
'<CR><LF>+CLCK: 
("AO","OI","AI","IR","OX","AB","AG","AC","PS","PN","PU","PP","PC","SC","FD")<CR><LF><CR><LF>OK<CR><LF>'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.367545] [mm-port-serial.c:1296] mm_port_serial_open(): (ttyACM0) 
device open count is 3 (open)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.368109] [mm-port-serial.c:1353] _close_internal(): (ttyACM0) device 
open count is 2 (close)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.368591] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): --> 
'AT+CLCK="SC",2<CR>'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.386089] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): <-- 
'<CR><LF>+CLCK: 0<CR><LF><CR><LF>OK<CR><LF>'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.387068] [mm-port-serial.c:1296] mm_port_serial_open(): (ttyACM0) 
device open count is 3 (open)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.387634] [mm-port-serial.c:1353] _close_internal(): (ttyACM0) device 
open count is 2 (close)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.388113] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): --> 
'AT+CLCK="FD",2<CR>'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.405464] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): <-- 
'<CR><LF>+CLCK: 0<CR><LF><CR><LF>OK<CR><LF>'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.406402] [mm-port-serial.c:1296] mm_port_serial_open(): (ttyACM0) 
device open count is 3 (open)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.406963] [mm-port-serial.c:1353] _close_internal(): (ttyACM0) device 
open count is 2 (close)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.407442] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): --> 
'AT+CLCK="PS",2<CR>'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.424964] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): <-- 
'<CR><LF>+CLCK: 0<CR><LF><CR><LF>OK<CR><LF>'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.425884] [mm-port-serial.c:1296] mm_port_serial_open(): (ttyACM0) 
device open count is 3 (open)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.426476] [mm-port-serial.c:1353] _close_internal(): (ttyACM0) device 
open count is 2 (close)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.426968] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): --> 
'AT+CLCK="PN",2<CR>'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.444471] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): <-- 
'<CR><LF>+CLCK: 0<CR><LF><CR><LF>OK<CR><LF>'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.445425] [mm-port-serial.c:1296] mm_port_serial_open(): (ttyACM0) 
device open count is 3 (open)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.445985] [mm-port-serial.c:1353] _close_internal(): (ttyACM0) device 
open count is 2 (close)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.446468] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): --> 
'AT+CLCK="PU",2<CR>'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.464232] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): <-- 
'<CR><LF>+CLCK: 0<CR><LF><CR><LF>OK<CR><LF>'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.465159] [mm-port-serial.c:1296] mm_port_serial_open(): (ttyACM0) 
device open count is 3 (open)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.465721] [mm-port-serial.c:1353] _close_internal(): (ttyACM0) device 
open count is 2 (close)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.466228] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): --> 
'AT+CLCK="PP",2<CR>'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.483856] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): <-- 
'<CR><LF>+CLCK: 0<CR><LF><CR><LF>OK<CR><LF>'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.484793] [mm-port-serial.c:1296] mm_port_serial_open(): (ttyACM0) 
device open count is 3 (open)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.485344] [mm-port-serial.c:1353] _close_internal(): (ttyACM0) device 
open count is 2 (close)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.485820] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): --> 
'AT+CLCK="PC",2<CR>'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.503215] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): <-- 
'<CR><LF>+CLCK: 0<CR><LF><CR><LF>OK<CR><LF>'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.504541] [mm-port-serial.c:1353] _close_internal(): (ttyACM0) device 
open count is 1 (close)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.506635] [mm-port-serial.c:1296] mm_port_serial_open(): (ttyACM0) 
device open count is 2 (open)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.507348] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): --> 
'AT+CUSD=?<CR>'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.524492] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): <-- 
'<CR><LF>+CUSD: (0-2)<CR><LF><CR><LF>OK<CR><LF>'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.525645] [mm-port-serial.c:1353] _close_internal(): (ttyACM0) device 
open count is 1 (close)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.528979] [mm-port-serial.c:1296] mm_port_serial_open(): (ttyACM0) 
device open count is 2 (open)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.529746] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): --> 
'AT+CNMI=?<CR>'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.541595] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): <-- 
'<CR><LF>+CNMI: (0-2),(0-3),(0-3),(0-2),(0-1)<CR><LF><CR><LF>OK<CR><LF>'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.542442] [mm-port-serial.c:1296] mm_port_serial_open(): (ttyACM0) 
device open count is 3 (open)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.543072] [mm-port-serial.c:1353] _close_internal(): (ttyACM0) device 
open count is 2 (close)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.543610] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): --> 
'AT+CPMS=?<CR>'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.555479] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): <-- 
'<CR><LF>+CPMS: 
("BM","ME","SM","SR"),("ME","SM"),("BM","ME","SM","SR")<CR><LF><CR><LF>OK<CR><LF>'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.556702] [mm-iface-modem-messaging.c:1149] 
load_supported_storages_ready(): Supported storages loaded:
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.557136] [mm-iface-modem-messaging.c:1150] 
load_supported_storages_ready():   mem1 (list/read/delete) storages: 'bm, me, 
sm, sr'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.557427] [mm-iface-modem-messaging.c:1151] 
load_supported_storages_ready():   mem2 (write/send) storages:       'me, sm'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.557680] [mm-iface-modem-messaging.c:1152] 
load_supported_storages_ready():   mem3 (reception) storages:        'bm, me, 
sm, sr'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.558234] [mm-port-serial.c:1296] mm_port_serial_open(): (ttyACM0) 
device open count is 3 (open)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.558796] [mm-port-serial.c:1353] _close_internal(): (ttyACM0) device 
open count is 2 (close)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.559288] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): --> 
'AT+CPMS?<CR>'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.570090] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): <-- 
'<CR><LF>+CPMS: "SR",0,10,"ME",1,100,"ME",1,100<CR><LF><CR><LF>OK<CR><LF>'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.571244] [mm-broadband-modem.c:5280] cpms_query_ready(): Current 
storages initialized:
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.571689] [mm-broadband-modem.c:5283] cpms_query_ready():   mem1 
(list/read/delete) storages: 'sr'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.572012] [mm-broadband-modem.c:5287] cpms_query_ready():   mem2 
(write/send) storages:       'me'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.572296] [mm-iface-modem-messaging.c:1232] 
init_current_storages_ready(): Current storages initialized
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.572956] [mm-port-serial.c:1353] _close_internal(): (ttyACM0) device 
open count is 1 (close)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.574165] [mm-port-serial.c:1296] mm_port_serial_open(): (ttyACM0) 
device open count is 2 (open)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.574847] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): --> 
'ATH<CR>'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.580838] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): <-- 
'<CR><LF>OK<CR><LF>'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.581880] [mm-port-serial.c:1353] _close_internal(): (ttyACM0) device 
open count is 1 (close)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.583003] [mm-port-serial.c:1296] mm_port_serial_open(): (ttyACM0) 
device open count is 2 (open)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.583760] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): --> 
'AT+CTZU=1<CR>'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.595843] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): <-- 
'<CR><LF>OK<CR><LF>'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.596671] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): --> 
'AT+CCLK?<CR>'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.607838] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): <-- 
'<CR><LF>+CCLK: "04/01/01,00:00:28-24"<CR><LF><CR><LF>OK<CR><LF>'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.608921] [mm-port-serial.c:1353] _close_internal(): (ttyACM0) device 
open count is 1 (close)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.610198] [mm-port-serial.c:1296] mm_port_serial_open(): (ttyACM0) 
device open count is 2 (open)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.610917] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): --> 
'AT+CESQ=?<CR>'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.622968] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): <-- 
'<CR><LF>+CESQ: 
(0-63,99),(0-7,99),(0-96,255),(0-49,255),(0-34,255),(0-97,255)<CR><LF><CR><LF>OK<CR><LF>'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.624144] [mm-port-serial.c:1353] _close_internal(): (ttyACM0) device 
open count is 1 (close)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.625818] [mm-broadband-modem.c:9715] 
iface_modem_oma_initialize_ready(): Couldn't initialize interface: 'OMA not 
supported'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.627150] [mm-broadband-modem.c:9716] 
iface_modem_firmware_initialize_ready(): Couldn't initialize interface: 
'Firmware interface not available'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <info>  
[1518024945.628497] [mm-iface-modem.c:1433] 
__iface_modem_update_state_internal(): Modem: state changed (unknown -> 
disabled)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.629528] [mm-port-serial.c:1353] _close_internal(): (ttyACM0) device 
open count is 0 (close)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.629999] [mm-port-serial.c:1369] _close_internal(): (ttyACM0) 
closing serial port...
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.634059] [mm-port-serial.c:1417] _close_internal(): (ttyACM0) serial 
port closed
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.634561] [mm-base-modem.c:844] initialize_ready(): modem properly 
initialized
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.654339] [mm-device.c:453] export_modem(): Exported modem 
'/sys/devices/platform/soc/2100000.aips-bus/2184200.usb/ci_hdrc.1/usb1/1-1' at 
path '/org/freedesktop/ModemManager1/Modem/0'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.654880] [mm-device.c:463] export_modem(): 
(/org/freedesktop/ModemManager1/Modem/0): 'Generic' modem, VID 0x1546 PID 
0x1107 (usb)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <info>  
[1518024945.680493] [mm-iface-modem.c:1433] 
__iface_modem_update_state_internal(): Modem 
/org/freedesktop/ModemManager1/Modem/0: state changed (disabled -> enabling)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.682327] [mm-broadband-modem.c:8617] enabling_started(): Skipping 
modem initialization: device hotplugged
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.682481] [mm-port-serial.c:1166] mm_port_serial_open(): (ttyACM0) 
opening serial port...
Feb  7 17:35:45 canect2 daemon.info NetworkManager[308]: <info>  
[1518024945.6873] (ttyACM0): modem state changed, 'disabled' --> 'enabling' 
(reason: user preference)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.688118] [mm-port-serial.c:1296] mm_port_serial_open(): (ttyACM0) 
device open count is 1 (open)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.693649] [mm-port-serial-at.c:496] 
mm_port_serial_at_run_init_sequence(): (ttyACM0): running init sequence...
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.694274] [mm-port-serial.c:1166] mm_port_serial_open(): (ttyACM1) 
opening serial port...
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.695814] [mm-port-serial.c:1296] mm_port_serial_open(): (ttyACM1) 
device open count is 1 (open)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.695990] [mm-port-serial-at.c:496] 
mm_port_serial_at_run_init_sequence(): (ttyACM1): running init sequence...
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.696174] [mm-broadband-modem.c:8633] enabling_started(): Flashing 
primary AT port before enabling...
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.697137] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): --> 
'ATE0<CR>'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.697383] [mm-port-serial-at.c:460] debug_log(): (ttyACM1): --> 
'ATE0<CR>'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.705503] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): <-- 
'<CR><LF>OK<CR><LF>'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.706004] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): --> 
'ATV1<CR>'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.706830] [mm-port-serial-at.c:460] debug_log(): (ttyACM1): <-- 
'<CR><LF>OK<CR><LF>'
Feb  7 17:35:45 canect2 daemon.info NetworkManager[308]: <info>  
[1518024945.7050] manager: (ttyACM0): new Broadband device 
(/org/freedesktop/NetworkManager/Devices/8)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.712832] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): <-- 
'<CR><LF>OK<CR><LF>'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.713350] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): --> 
'AT+CMEE=1<CR>'
Feb  7 17:35:45 canect2 daemon.info NetworkManager[308]: <info>  
[1518024945.7143] device (ttyACM0): state change: unmanaged -> unavailable 
(reason 'managed') [10 20 2]
Feb  7 17:35:45 canect2 daemon.info NetworkManager[308]: <info>  
[1518024945.7195] device (ttyACM0): modem state 'enabling'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.729082] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): <-- 
'<CR><LF>OK<CR><LF>'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.729614] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): --> 
'ATX4<CR>'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.736331] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): <-- 
'<CR><LF>OK<CR><LF>'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.736851] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): --> 
'AT&C1<CR>'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.744813] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): <-- 
'<CR><LF>OK<CR><LF>'
Feb  7 17:35:45 canect2 daemon.info NetworkManager[308]: <info>  
[1518024945.7468] device (ttyACM0): state change: unavailable -> disconnected 
(reason 'none') [20 30 0]
Feb  7 17:35:45 canect2 daemon.info NetworkManager[308]: <info>  
[1518024945.7552] policy: auto-activating connection 'Aeris'
Feb  7 17:35:45 canect2 daemon.info NetworkManager[308]: <info>  
[1518024945.7668] device (ttyACM0): Activation: starting connection 'Aeris' 
(83187ceb-ad3a-4af8-92d8-7a255d9c5e3f)
Feb  7 17:35:45 canect2 daemon.info NetworkManager[308]: <info>  
[1518024945.7714] device (ttyACM0): state change: disconnected -> prepare 
(reason 'none') [30 40 0]
Feb  7 17:35:45 canect2 daemon.info NetworkManager[308]: <info>  
[1518024945.7755] manager: NetworkManager state is now CONNECTING
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <info>  
[1518024945.782158] [mm-iface-modem-simple.c:641] connect_auth_ready(): Simple 
connect started...
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.782636] [mm-iface-modem-simple.c:651] connect_auth_ready():    PIN: 
unspecified
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.782791] [mm-iface-modem-simple.c:653] connect_auth_ready():    
Operator ID: unspecified
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.782887] [mm-iface-modem-simple.c:655] connect_auth_ready():    
Allowed roaming: yes
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.782969] [mm-iface-modem-simple.c:657] connect_auth_ready():    APN: 
iot.aer.net
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.783063] [mm-iface-modem-simple.c:662] connect_auth_ready():    IP 
family: ipv4v6
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.783148] [mm-iface-modem-simple.c:673] connect_auth_ready():    
Allowed authentication: unspecified
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.783228] [mm-iface-modem-simple.c:675] connect_auth_ready():    
User: unspecified
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.783306] [mm-iface-modem-simple.c:677] connect_auth_ready():    
Password: unspecified
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.783383] [mm-iface-modem-simple.c:679] connect_auth_ready():    
Number: *99#
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <info>  
[1518024945.783444] [mm-iface-modem-simple.c:469] connection_step(): Simple 
connect state (4/8): Wait to get fully enabled
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.798987] [mm-broadband-modem.c:3139] load_power_state(): loading 
power state...
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.799248] [mm-port-serial.c:1296] mm_port_serial_open(): (ttyACM0) 
device open count is 2 (open)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.799546] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): --> 
'AT+CFUN?<CR>'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.810593] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): <-- 
'<CR><LF>+CFUN: 1,0<CR><LF><CR><LF>OK<CR><LF>'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.811321] [mm-iface-modem.c:3370] set_power_state_load_ready(): 
Couldn't reload current power state: Failed to parse +CFUN? response '1,0'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.811809] [mm-port-serial.c:1296] mm_port_serial_open(): (ttyACM0) 
device open count is 3 (open)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.812342] [mm-port-serial.c:1353] _close_internal(): (ttyACM0) device 
open count is 2 (close)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.812845] [mm-iface-modem.c:3221] modem_power_up_ready(): Modem set 
in full-power mode...
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.816837] [mm-port-serial.c:1296] mm_port_serial_open(): (ttyACM0) 
device open count is 3 (open)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.818036] [mm-port-serial.c:1296] mm_port_serial_open(): (ttyACM0) 
device open count is 4 (open)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.818690] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): --> 
'AT+CFUN=1<CR>'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.831590] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): <-- 
'<CR><LF>OK<CR><LF>'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.832242] [mm-port-serial.c:1353] _close_internal(): (ttyACM0) device 
open count is 3 (close)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.832766] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): --> 
'AT+IFC=1,1<CR>'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.853865] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): <-- 
'<CR><LF>+CME ERROR: 3<CR><LF>'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.854510] [mm-serial-parsers.c:364] mm_serial_parser_v1_parse(): Got 
failure code 3: Operation not allowed
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.854957] [mm-port-serial.c:1353] _close_internal(): (ttyACM0) device 
open count is 2 (close)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.855513] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): --> 
'AT+CSCS=?<CR>'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.867731] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): <-- 
'<CR><LF>+CSCS: 
("IRA","GSM","PCCP437","8859-1","UCS2","HEX")<CR><LF><CR><LF>OK<CR><LF>'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.868936] [mm-port-serial.c:1296] mm_port_serial_open(): (ttyACM0) 
device open count is 3 (open)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.869531] [mm-port-serial.c:1353] _close_internal(): (ttyACM0) device 
open count is 2 (close)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.870033] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): --> 
'AT+CSCS="UCS2"<CR>'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.887841] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): <-- 
'<CR><LF>OK<CR><LF>'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.888580] [mm-port-serial.c:1296] mm_port_serial_open(): (ttyACM0) 
device open count is 3 (open)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.889131] [mm-port-serial.c:1353] _close_internal(): (ttyACM0) device 
open count is 2 (close)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.889648] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): --> 
'AT+CSCS?<CR>'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.902095] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): <-- 
'<CR><LF>+CSCS: "UCS2"<CR><LF><CR><LF>OK<CR><LF>'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.902873] [mm-port-serial.c:1353] _close_internal(): (ttyACM0) device 
open count is 1 (close)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.903398] [mm-broadband-modem.c:9278] enabling_step(): Modem has 3GPP 
capabilities, enabling the Modem 3GPP interface...
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.903890] [mm-broadband-modem.c:2601] 
modem_3gpp_setup_unsolicited_events(): Checking indicator support...
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.904299] [mm-port-serial.c:1296] mm_port_serial_open(): (ttyACM0) 
device open count is 2 (open)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.904855] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): --> 
'AT+CIND=?<CR>'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.918738] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): <-- 
'<CR><LF>+CIND: 
("battchg",(0-5)),("signal",(0-5)),("service",(0-1)),("sounder",(0-1)),("message",(0-1)),("call",(0-1)),("roam",(0-1))
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.919974] [mm-broadband-modem.c:2554] cind_format_check_ready(): 
Modem supports signal quality indications via CIND at index '2'(min: 0, max: 5)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.920392] [mm-broadband-modem.c:2563] cind_format_check_ready(): 
Modem supports roaming indications via CIND at index '7'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.920689] [mm-broadband-modem.c:2572] cind_format_check_ready(): 
Modem supports service indications via CIND at index '3'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.921084] [mm-broadband-modem.c:2505] 
set_unsolicited_events_handlers(): (ttyACM0) Setting 3GPP unsolicited events 
handlers
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.921404] [mm-broadband-modem.c:2505] 
set_unsolicited_events_handlers(): (ttyACM1) Setting 3GPP unsolicited events 
handlers
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.921872] [mm-port-serial.c:1296] mm_port_serial_open(): (ttyACM0) 
device open count is 3 (open)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.922375] [mm-port-serial.c:1353] _close_internal(): (ttyACM0) device 
open count is 2 (close)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.922851] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): --> 
'AT+CMER=3,0,0,1<CR>'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.941714] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): <-- 
'<CR><LF>OK<CR><LF>'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.942495] [mm-port-serial.c:1296] mm_port_serial_open(): (ttyACM1) 
device open count is 2 (open)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.943036] [mm-port-serial.c:1353] _close_internal(): (ttyACM0) device 
open count is 1 (close)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.943585] [mm-port-serial-at.c:460] debug_log(): (ttyACM1): --> 
'AT+CMER=3,0,0,1<CR>'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.962091] [mm-port-serial-at.c:460] debug_log(): (ttyACM1): <-- 
'<CR><LF>OK<CR><LF>'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.964045] [mm-broadband-modem.c:3601] 
modem_3gpp_setup_unsolicited_registration_events(): (ttyACM0) setting up 3GPP 
unsolicited registration messages handlers
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.964533] [mm-broadband-modem.c:3601] 
modem_3gpp_setup_unsolicited_registration_events(): (ttyACM1) setting up 3GPP 
unsolicited registration messages handlers
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.965036] [mm-port-serial.c:1353] _close_internal(): (ttyACM1) device 
open count is 1 (close)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.965653] [mm-port-serial.c:1296] mm_port_serial_open(): (ttyACM0) 
device open count is 2 (open)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.966275] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): --> 
'AT+CREG=2<CR>'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.978219] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): <-- 
'<CR><LF>OK<CR><LF>'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.978974] [mm-port-serial.c:1296] mm_port_serial_open(): (ttyACM1) 
device open count is 2 (open)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.979509] [mm-port-serial.c:1353] _close_internal(): (ttyACM0) device 
open count is 1 (close)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.979994] [mm-port-serial-at.c:460] debug_log(): (ttyACM1): --> 
'AT+CREG=2<CR>'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.991714] [mm-port-serial-at.c:460] debug_log(): (ttyACM1): <-- 
'<CR><LF>OK<CR><LF>'
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.992451] [mm-port-serial.c:1296] mm_port_serial_open(): (ttyACM0) 
device open count is 2 (open)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.992991] [mm-port-serial.c:1353] _close_internal(): (ttyACM1) device 
open count is 1 (close)
Feb  7 17:35:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518024945.993469] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): --> 
'AT+CGREG=2<CR>'
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.006466] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): <-- 
'<CR><LF>OK<CR><LF>'
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.007337] [mm-port-serial.c:1296] mm_port_serial_open(): (ttyACM1) 
device open count is 2 (open)
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.007902] [mm-port-serial.c:1353] _close_internal(): (ttyACM0) device 
open count is 1 (close)
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.008403] [mm-port-serial-at.c:460] debug_log(): (ttyACM1): --> 
'AT+CGREG=2<CR>'
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.021469] [mm-port-serial-at.c:460] debug_log(): (ttyACM1): <-- 
'<CR><LF>OK<CR><LF>'
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.022213] [mm-port-serial.c:1296] mm_port_serial_open(): (ttyACM0) 
device open count is 2 (open)
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.022760] [mm-port-serial.c:1353] _close_internal(): (ttyACM1) device 
open count is 1 (close)
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.023246] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): --> 
'AT+CEREG=2<CR>'
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.027955] [mm-port-serial-at.c:460] debug_log(): (ttyACM1): <-- 
'<CR><LF>+CIEV: 2,3<CR><LF>'
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.028940] [mm-iface-modem.c:1206] update_signal_quality(): Modem 
/org/freedesktop/ModemManager1/Modem/0: signal quality updated (60)
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.038594] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): <-- 
'<CR><LF>+CIEV: 2,3<CR><LF>'
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.039550] [mm-iface-modem.c:1206] update_signal_quality(): Modem 
/org/freedesktop/ModemManager1/Modem/0: signal quality updated (60)
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.040300] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): <-- 
'<CR><LF>OK<CR><LF>'
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.041049] [mm-port-serial.c:1296] mm_port_serial_open(): (ttyACM1) 
device open count is 2 (open)
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.041599] [mm-port-serial.c:1353] _close_internal(): (ttyACM0) device 
open count is 1 (close)
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.042085] [mm-port-serial-at.c:460] debug_log(): (ttyACM1): --> 
'AT+CEREG=2<CR>'
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.055102] [mm-port-serial-at.c:460] debug_log(): (ttyACM1): <-- 
'<CR><LF>OK<CR><LF>'
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.055793] [mm-port-serial.c:1353] _close_internal(): (ttyACM1) device 
open count is 1 (close)
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.056394] [mm-broadband-modem.c:9291] enabling_step(): Modem has 
3GPP/USSD capabilities, enabling the Modem 3GPP/USSD interface...
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.056926] [mm-broadband-modem.c:4915] 
set_unsolicited_result_code_handlers(): (ttyACM0) Setting unsolicited result 
code handlers
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.057282] [mm-broadband-modem.c:4915] 
set_unsolicited_result_code_handlers(): (ttyACM1) Setting unsolicited result 
code handlers
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.057884] [mm-port-serial.c:1296] mm_port_serial_open(): (ttyACM0) 
device open count is 2 (open)
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.058499] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): --> 
'AT+CUSD=1<CR>'
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.070585] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): <-- 
'<CR><LF>OK<CR><LF>'
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.071516] [mm-port-serial.c:1353] _close_internal(): (ttyACM0) device 
open count is 1 (close)
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.075391] [mm-broadband-modem.c:9319] enabling_step(): Modem has 
location capabilities, enabling the Location interface...
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.076012] [mm-iface-modem-location.c:762] setup_gathering(): Need to 
enable the following location sources: '3gpp-lac-ci'
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.076755] [mm-iface-modem-3gpp.c:767] 
mm_iface_modem_3gpp_run_registration_checks(): Running registration checks (CS: 
'yes', PS: 'yes', EPS: 'yes')
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.077265] [mm-port-serial.c:1296] mm_port_serial_open(): (ttyACM0) 
device open count is 2 (open)
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.081327] [mm-broadband-modem.c:9332] enabling_step(): Modem has 
messaging capabilities, enabling the Messaging interface...
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.082239] [mm-port-serial.c:1296] mm_port_serial_open(): (ttyACM0) 
device open count is 3 (open)
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.082876] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): --> 
'AT+CREG?<CR>'
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.093734] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): <-- 
'<CR><LF>+CREG: 2,3<CR><LF><CR><LF>OK<CR><LF>'
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <info>  
[1518024946.094396] [mm-iface-modem-3gpp.c:1188] update_registration_state(): 
Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP Registration state changed 
(unknown -> denied)
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.095315] [mm-iface-modem.c:1602] get_updated_consolidated_state(): 
Will start keeping track of state for subsystem '3gpp'
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.096211] [mm-port-serial.c:1296] mm_port_serial_open(): (ttyACM0) 
device open count is 4 (open)
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.096758] [mm-port-serial.c:1353] _close_internal(): (ttyACM0) device 
open count is 3 (close)
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.100641] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): --> 
'AT+CMGF=?<CR>'
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.112721] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): <-- 
'<CR><LF>+CMGF: (0-1)<CR><LF><CR><LF>OK<CR><LF>'
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.113831] [mm-port-serial.c:1296] mm_port_serial_open(): (ttyACM0) 
device open count is 4 (open)
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.114372] [mm-port-serial.c:1353] _close_internal(): (ttyACM0) device 
open count is 3 (close)
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.114901] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): --> 
'AT+CGREG?<CR>'
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.127597] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): <-- 
'<CR><LF>+CGREG: 2,3<CR><LF><CR><LF>OK<CR><LF>'
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.128517] [mm-port-serial.c:1296] mm_port_serial_open(): (ttyACM0) 
device open count is 4 (open)
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.129060] [mm-port-serial.c:1353] _close_internal(): (ttyACM0) device 
open count is 3 (close)
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.129576] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): --> 
'AT+CMGF=0<CR>'
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.141471] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): <-- 
'<CR><LF>OK<CR><LF>'
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.142146] [mm-broadband-modem.c:5601] cmgf_set_ready(): Successfully 
set preferred SMS mode: 'PDU'
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.142961] [mm-port-serial.c:1296] mm_port_serial_open(): (ttyACM0) 
device open count is 4 (open)
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.143581] [mm-port-serial.c:1353] _close_internal(): (ttyACM0) device 
open count is 3 (close)
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.147432] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): --> 
'AT+CEREG?<CR>'
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.159600] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): <-- 
'<CR><LF>+CEREG: 2,0<CR><LF><CR><LF>OK<CR><LF>'
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.160503] [mm-port-serial.c:1353] _close_internal(): (ttyACM0) device 
open count is 2 (close)
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.161132] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): --> 
'AT+CPMS="SR","ME","ME"<CR>'
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.187971] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): <-- 
'<CR><LF>+CPMS: 0,10,1,100,1,100<CR><LF><CR><LF>OK<CR><LF>'
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.188711] [mm-broadband-modem.c:6373] 
modem_messaging_load_initial_sms_parts(): Listing SMS parts in storage 'bm'
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.189108] [mm-broadband-modem.c:5483] 
mm_broadband_modem_lock_sms_storages(): Locking SMS storages to: mem1 (BM), 
mem2 (none)...
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.189519] [mm-port-serial.c:1296] mm_port_serial_open(): (ttyACM0) 
device open count is 3 (open)
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.189997] [mm-port-serial.c:1353] _close_internal(): (ttyACM0) device 
open count is 2 (close)
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.190509] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): --> 
'AT+CPMS="BM"<CR>'
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.205990] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): <-- 
'<CR><LF>+CPMS: 0,10,1,100,1,100<CR><LF><CR><LF>OK<CR><LF>'
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.206725] [mm-port-serial.c:1353] _close_internal(): (ttyACM0) device 
open count is 1 (close)
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.207333] [mm-port-serial.c:1296] mm_port_serial_open(): (ttyACM0) 
device open count is 2 (open)
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.207937] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): --> 
'AT+CMGL=4<CR>'
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.220098] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): <-- 
'<CR><LF>OK<CR><LF>'
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.220982] [mm-broadband-modem.c:6373] 
modem_messaging_load_initial_sms_parts(): Listing SMS parts in storage 'me'
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.221407] [mm-broadband-modem.c:5483] 
mm_broadband_modem_lock_sms_storages(): Locking SMS storages to: mem1 (ME), 
mem2 (none)...
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.221828] [mm-port-serial.c:1296] mm_port_serial_open(): (ttyACM0) 
device open count is 3 (open)
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.222311] [mm-port-serial.c:1353] _close_internal(): (ttyACM0) device 
open count is 2 (close)
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.222788] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): --> 
'AT+CPMS="ME"<CR>'
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.238595] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): <-- 
'<CR><LF>+CPMS: 1,100,1,100,1,100<CR><LF><CR><LF>OK<CR><LF>'
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.239336] [mm-port-serial.c:1353] _close_internal(): (ttyACM0) device 
open count is 1 (close)
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.239932] [mm-port-serial.c:1296] mm_port_serial_open(): (ttyACM0) 
device open count is 2 (open)
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.240574] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): --> 
'AT+CMGL=4<CR>'
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.252734] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): <-- 
'<CR><LF>+CMGL: 
1,1,,44<CR><LF>XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.262774] [mm-sms-part-3gpp.c:368] 
mm_sms_part_3gpp_new_from_binary_pdu(): Parsing PDU (1)...
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.263228] [mm-sms-part-3gpp.c:397] 
mm_sms_part_3gpp_new_from_binary_pdu():   SMSC address parsed: '+XXXXXXXXXXX'
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.263584] [mm-sms-part-3gpp.c:410] 
mm_sms_part_3gpp_new_from_binary_pdu():   Deliver type PDU detected
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.263871] [mm-sms-part-3gpp.c:471] 
mm_sms_part_3gpp_new_from_binary_pdu():   Number parsed: '+XXXXX'
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.264133] [mm-sms-part-3gpp.c:575] 
mm_sms_part_3gpp_new_from_binary_pdu():   PID: 0
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.264375] [mm-sms-part-3gpp.c:586] 
mm_sms_part_3gpp_new_from_binary_pdu():   user data encoding is GSM7
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.264608] [mm-sms-part-3gpp.c:614] 
mm_sms_part_3gpp_new_from_binary_pdu():   user data length: 32 elements
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.264849] [mm-sms-part-3gpp.c:620] 
mm_sms_part_3gpp_new_from_binary_pdu():   user data length: 28 bytes
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.265103] [mm-sms-part-3gpp.c:695] 
mm_sms_part_3gpp_new_from_binary_pdu(): Decoding SMS text with '32' elements
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.265358] [mm-sms-part-3gpp.c:244] sms_decode_text(): Converting SMS 
part text from GSM7 to UTF8...
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.265690] [mm-sms-part-3gpp.c:247] sms_decode_text():    Got UTF-8 
text: 'This is a test of the LTE modem.'
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.265969] [mm-broadband-modem.c:6306] sms_pdu_part_list_ready(): 
Correctly parsed PDU (1)
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.266313] [mm-sms-list.c:384] mm_sms_list_take_part(): SMS part at 
'me/1' is from a singlepart SMS
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.268999] [mm-iface-modem-messaging.c:511] sms_added(): Added 
received SMS at '/org/freedesktop/ModemManager1/SMS/0'
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.272736] [mm-broadband-modem.c:6373] 
modem_messaging_load_initial_sms_parts(): Listing SMS parts in storage 'sm'
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.273222] [mm-broadband-modem.c:5483] 
mm_broadband_modem_lock_sms_storages(): Locking SMS storages to: mem1 (SM), 
mem2 (none)...
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.273718] [mm-port-serial.c:1296] mm_port_serial_open(): (ttyACM0) 
device open count is 3 (open)
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.274233] [mm-port-serial.c:1353] _close_internal(): (ttyACM0) device 
open count is 2 (close)
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.278072] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): --> 
'AT+CPMS="SM"<CR>'
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.294243] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): <-- 
'<CR><LF>+CPMS: 0,3,1,100,1,100<CR><LF><CR><LF>OK<CR><LF>'
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.294999] [mm-port-serial.c:1353] _close_internal(): (ttyACM0) device 
open count is 1 (close)
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.295597] [mm-port-serial.c:1296] mm_port_serial_open(): (ttyACM0) 
device open count is 2 (open)
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.296206] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): --> 
'AT+CMGL=4<CR>'
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.308971] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): <-- 
'<CR><LF>OK<CR><LF>'
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.309850] [mm-broadband-modem.c:6373] 
modem_messaging_load_initial_sms_parts(): Listing SMS parts in storage 'sr'
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.310278] [mm-broadband-modem.c:5483] 
mm_broadband_modem_lock_sms_storages(): Locking SMS storages to: mem1 (SR), 
mem2 (none)...
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.310702] [mm-port-serial.c:1296] mm_port_serial_open(): (ttyACM0) 
device open count is 3 (open)
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.311181] [mm-port-serial.c:1353] _close_internal(): (ttyACM0) device 
open count is 2 (close)
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.311653] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): --> 
'AT+CPMS="SR"<CR>'
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.327342] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): <-- 
'<CR><LF>+CPMS: 0,10,1,100,1,100<CR><LF><CR><LF>OK<CR><LF>'
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.328078] [mm-port-serial.c:1353] _close_internal(): (ttyACM0) device 
open count is 1 (close)
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.328712] [mm-port-serial.c:1296] mm_port_serial_open(): (ttyACM0) 
device open count is 2 (open)
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.329335] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): --> 
'AT+CMGL=4<CR>'
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.341344] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): <-- 
'<CR><LF>OK<CR><LF>'
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.342316] [mm-broadband-modem.c:5904] 
set_messaging_unsolicited_events_handlers(): (ttyACM0) Setting messaging 
unsolicited events handlers
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.342744] [mm-broadband-modem.c:5904] 
set_messaging_unsolicited_events_handlers(): (ttyACM1) Setting messaging 
unsolicited events handlers
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.343146] [mm-port-serial.c:1353] _close_internal(): (ttyACM0) device 
open count is 1 (close)
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.343670] [mm-broadband-modem.c:6077] 
modem_messaging_enable_unsolicited_events(): (ttyACM0) Enabling messaging 
unsolicited events on primary port
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.344121] [mm-port-serial.c:1296] mm_port_serial_open(): (ttyACM0) 
device open count is 2 (open)
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.344697] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): --> 
'AT+CNMI=2,1,2,1,0<CR>'
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.365590] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): <-- 
'<CR><LF>OK<CR><LF>'
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.366278] [mm-broadband-modem.c:6038] 
modem_messaging_enable_unsolicited_events_primary_ready(): (ttyACM0) Messaging 
unsolicited events enabled on primary
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.366650] [mm-broadband-modem.c:6043] 
modem_messaging_enable_unsolicited_events_primary_ready(): (ttyACM1) Enabling 
messaging unsolicited events on secondary port
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.367029] [mm-port-serial.c:1296] mm_port_serial_open(): (ttyACM1) 
device open count is 2 (open)
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.367502] [mm-port-serial.c:1353] _close_internal(): (ttyACM0) device 
open count is 1 (close)
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.367975] [mm-port-serial-at.c:460] debug_log(): (ttyACM1): --> 
'AT+CNMI=2,1,2,1,0<CR>'
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.395850] [mm-port-serial-at.c:460] debug_log(): (ttyACM1): <-- 
'<CR><LF>OK<CR><LF>'
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.396514] [mm-broadband-modem.c:6011] 
modem_messaging_enable_unsolicited_events_secondary_ready(): (ttyACM1) 
Messaging unsolicited events enabled on secondary
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.396969] [mm-port-serial.c:1353] _close_internal(): (ttyACM1) device 
open count is 1 (close)
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.397425] [mm-broadband-modem.c:9345] enabling_step(): Modem has 
voice capabilities, enabling the Voice interface...
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.398365] [mm-broadband-modem.c:6541] 
set_voice_unsolicited_events_handlers(): (ttyACM0) Setting voice unsolicited 
events handlers
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.398807] [mm-broadband-modem.c:6541] 
set_voice_unsolicited_events_handlers(): (ttyACM1) Setting voice unsolicited 
events handlers
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.399398] [mm-port-serial.c:1296] mm_port_serial_open(): (ttyACM0) 
device open count is 2 (open)
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.400059] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): --> 
'AT+CLIP=1<CR>'
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.412341] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): <-- 
'<CR><LF>OK<CR><LF>'
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.413193] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): --> 
'AT+CRC=1<CR>'
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.424231] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): <-- 
'<CR><LF>OK<CR><LF>'
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.424963] [mm-port-serial.c:1353] _close_internal(): (ttyACM0) device 
open count is 1 (close)
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.425463] [mm-broadband-modem.c:9358] enabling_step(): Modem has time 
capabilities, enabling the Time interface...
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.426093] [mm-broadband-modem.c:9371] enabling_step(): Modem has 
extended signal reporting capabilities, enabling the Signal interface...
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.426560] [mm-iface-modem-signal.c:206] setup_refresh_context(): 
Extended signal information reporting disabled (rate: 0 seconds)
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <info>  
[1518024946.427409] [mm-iface-modem.c:1433] 
__iface_modem_update_state_internal(): Modem 
/org/freedesktop/ModemManager1/Modem/0: state changed (enabling -> enabled)
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <info>  
[1518024946.428166] [mm-iface-modem-simple.c:478] connection_step(): Simple 
connect state (5/8): Register
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.428694] [mm-iface-modem-3gpp.c:413] 
mm_iface_modem_3gpp_register_in_network(): Launching automatic network 
registration...
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.429159] [mm-port-serial.c:1296] mm_port_serial_open(): (ttyACM0) 
device open count is 2 (open)
Feb  7 17:35:46 canect2 daemon.info NetworkManager[308]: <info>  
[1518024946.4357] (ttyACM0): modem state changed, 'enabling' --> 'enabled' 
(reason: user-requested)
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.439770] [mm-iface-modem-3gpp.c:767] 
mm_iface_modem_3gpp_run_registration_checks(): Running registration checks (CS: 
'yes', PS: 'yes', EPS: 'yes')
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.440356] [mm-port-serial.c:1296] mm_port_serial_open(): (ttyACM0) 
device open count is 3 (open)
Feb  7 17:35:46 canect2 daemon.info ModemManager[302]: <debug> 
[1518024946.440882] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): --> 
'AT+COPS=0<CR>'
Feb  7 17:35:50 canect2 user.alert kernel: [   40.006876] wlan: mlan0 START SCAN
Feb  7 17:35:52 canect2 user.warn kernel: [   41.619338] wlan: SCAN COMPLETED: 
scanned AP count=11
Feb  7 17:35:52 canect2 user.err kernel: [   41.633469] Invalid sched_scan req 
parameter
Feb  7 17:36:19 canect2 daemon.info ModemManager[302]: <debug> 
[1518024979.203832] [mm-port-serial-at.c:460] debug_log(): (ttyACM1): <-- 
'<CR><LF>+CREG: 1,"XXXX","XXXXXXXX",6<CR><LF><CR><LF>+CGREG: 
1,"XXXX","XXXXXXXX",6,"6C"<CR><LF><CR><LF>+CIEV: 3,1<CR><LF><CR><LF>+CIEV
Feb  7 17:36:19 canect2 daemon.info ModemManager[302]: <info>  
[1518024979.204509] [mm-iface-modem-3gpp.c:1173] update_registration_state(): 
Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP Registration state changed 
(denied -> registering)
Feb  7 17:36:19 canect2 daemon.info ModemManager[302]: <debug> 
[1518024979.204695] [mm-broadband-modem.c:3437] 
modem_3gpp_load_operator_code(): loading Operator Code...
Feb  7 17:36:19 canect2 daemon.info ModemManager[302]: <debug> 
[1518024979.204858] [mm-port-serial.c:1296] mm_port_serial_open(): (ttyACM0) 
device open count is 4 (open)
Feb  7 17:36:19 canect2 daemon.info ModemManager[302]: <debug> 
[1518024979.205262] [mm-iface-modem.c:935] 
mm_iface_modem_update_access_technologies(): Modem 
/org/freedesktop/ModemManager1/Modem/0: access technology changed (unknown -> 
hspa)
Feb  7 17:36:19 canect2 daemon.info ModemManager[302]: <debug> 
[1518024979.205480] [mm-iface-modem-location.c:297] 
notify_3gpp_location_update(): Modem /org/freedesktop/ModemManager1/Modem/0: 
3GPP location updated (MCC: '0', MNC: '0', Location area code: 'XXXX', Cell ID:
Feb  7 17:36:23 canect2 user.alert kernel: [   73.011380] wlan: mlan0 START SCAN
Feb  7 17:36:25 canect2 user.warn kernel: [   74.623819] wlan: SCAN COMPLETED: 
scanned AP count=10
Feb  7 17:36:25 canect2 user.err kernel: [   74.645098] Invalid sched_scan req 
parameter
Feb  7 17:36:27 canect2 daemon.info NetworkManager[308]: <info>  
[1518024987.0674] audit: op="connection-add-activate" pid=463 uid=0 
result="fail" reason="A 'wireless' setting is required if no AP path was given."
Feb  7 17:36:45 canect2 daemon.info ModemManager[302]: <debug> 
[1518025005.848538] [mm-iface-modem.c:1142] expire_signal_quality(): Signal 
quality value not updated in 60s, marking as not being recent
Feb  7 17:36:51 canect2 daemon.info ModemManager[302]: <debug> 
[1518025011.798332] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): <-- 
'<CR><LF>OK<CR><LF><CR><LF>+CREG: 1,"XXXX","XXXXXXXX",6<CR><LF><CR><LF>+CGREG: 
1,"XXXX","XXXXXXXX",6,"6C"<CR><LF><CR><LF>+CEREG: 4<CR>
Feb  7 17:36:51 canect2 daemon.info ModemManager[302]: <debug> 
[1518025011.799559] [mm-iface-modem-3gpp.c:767] 
mm_iface_modem_3gpp_run_registration_checks(): Running registration checks (CS: 
'yes', PS: 'yes', EPS: 'yes')
Feb  7 17:36:51 canect2 daemon.info ModemManager[302]: <debug> 
[1518025011.799806] [mm-port-serial.c:1296] mm_port_serial_open(): (ttyACM0) 
device open count is 5 (open)
Feb  7 17:36:51 canect2 daemon.info ModemManager[302]: <debug> 
[1518025011.799998] [mm-port-serial.c:1353] _close_internal(): (ttyACM0) device 
open count is 4 (close)
Feb  7 17:36:51 canect2 daemon.info ModemManager[302]: <debug> 
[1518025011.800239] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): --> 
'AT+CREG?<CR>'
Feb  7 17:36:51 canect2 daemon.info ModemManager[302]: <debug> 
[1518025011.811105] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): <-- 
'<CR><LF>+CREG: 2,1,"XXXX","XXXXXXXX",6<CR><LF><CR><LF>OK<CR><LF>'
Feb  7 17:36:51 canect2 daemon.info ModemManager[302]: <debug> 
[1518025011.812176] [mm-port-serial.c:1296] mm_port_serial_open(): (ttyACM0) 
device open count is 5 (open)
Feb  7 17:36:51 canect2 daemon.info ModemManager[302]: <debug> 
[1518025011.812731] [mm-port-serial.c:1353] _close_internal(): (ttyACM0) device 
open count is 4 (close)
Feb  7 17:36:51 canect2 daemon.info ModemManager[302]: <debug> 
[1518025011.813238] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): --> 
'AT+COPS=3,2;+COPS?<CR>'
Feb  7 17:36:51 canect2 daemon.info ModemManager[302]: <debug> 
[1518025011.835974] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): <-- 
'<CR><LF>+COPS: 0,2,"XXXXXXXXXXXXXXXXXXXXXXXX",6<CR><LF><CR><LF>OK<CR><LF>'
Feb  7 17:36:51 canect2 daemon.info ModemManager[302]: <debug> 
[1518025011.836949] [mm-broadband-modem.c:3427] 
modem_3gpp_load_operator_code_finish(): loaded Operator Code: 
XXXXXXXXXXXXXXXXXXXXXXXX
Feb  7 17:36:51 canect2 daemon.info ModemManager[302]: <debug> 
[1518025011.837591] [mm-iface-modem-3gpp.c:843] parse_mcc_mnc(): Unexpected 
MCC/MNC string 'XXXXXXXXXXXXXXXXXXXXXXXX'
Feb  7 17:36:51 canect2 daemon.info ModemManager[302]: <debug> 
[1518025011.837960] [mm-broadband-modem.c:3473] 
modem_3gpp_load_operator_name(): loading Operator Name...
Feb  7 17:36:51 canect2 daemon.info ModemManager[302]: <debug> 
[1518025011.838334] [mm-port-serial.c:1296] mm_port_serial_open(): (ttyACM0) 
device open count is 5 (open)
Feb  7 17:36:51 canect2 daemon.info ModemManager[302]: <debug> 
[1518025011.838771] [mm-port-serial.c:1353] _close_internal(): (ttyACM0) device 
open count is 4 (close)
Feb  7 17:36:51 canect2 daemon.info ModemManager[302]: <debug> 
[1518025011.842583] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): --> 
'AT+CREG?<CR>'
Feb  7 17:36:51 canect2 daemon.info ModemManager[302]: <debug> 
[1518025011.853483] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): <-- 
'<CR><LF>+CREG: 2,1,"XXXX","XXXXXXXX",6<CR><LF><CR><LF>OK<CR><LF>'
Feb  7 17:36:51 canect2 daemon.info ModemManager[302]: <debug> 
[1518025011.854613] [mm-port-serial.c:1296] mm_port_serial_open(): (ttyACM0) 
device open count is 5 (open)
Feb  7 17:36:51 canect2 daemon.info ModemManager[302]: <debug> 
[1518025011.855156] [mm-port-serial.c:1353] _close_internal(): (ttyACM0) device 
open count is 4 (close)
Feb  7 17:36:51 canect2 daemon.info ModemManager[302]: <debug> 
[1518025011.855664] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): --> 
'AT+CGREG?<CR>'
Feb  7 17:36:51 canect2 daemon.info ModemManager[302]: <debug> 
[1518025011.867606] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): <-- 
'<CR><LF>+CGREG: 2,1,"XXXX","XXXXXXXX",6,"6C"<CR><LF><CR><LF>OK<CR><LF>'
Feb  7 17:36:51 canect2 daemon.info ModemManager[302]: <debug> 
[1518025011.868701] [mm-port-serial.c:1296] mm_port_serial_open(): (ttyACM0) 
device open count is 5 (open)
Feb  7 17:36:51 canect2 daemon.info ModemManager[302]: <debug> 
[1518025011.869253] [mm-port-serial.c:1353] _close_internal(): (ttyACM0) device 
open count is 4 (close)
Feb  7 17:36:51 canect2 daemon.info ModemManager[302]: <debug> 
[1518025011.869763] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): --> 
'AT+COPS=3,0;+COPS?<CR>'
Feb  7 17:36:51 canect2 daemon.info ModemManager[302]: <debug> 
[1518025011.972793] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): <-- 
'<CR><LF>+COPS: 0,0,"0041005400260054",6<CR><LF><CR><LF>OK<CR><LF>'
Feb  7 17:36:51 canect2 daemon.info ModemManager[302]: <debug> 
[1518025011.974232] [mm-broadband-modem.c:3463] 
modem_3gpp_load_operator_name_finish(): loaded Operator Name: AT&T
Feb  7 17:36:51 canect2 daemon.info ModemManager[302]: <debug> 
[1518025011.974972] [mm-port-serial.c:1353] _close_internal(): (ttyACM0) device 
open count is 3 (close)
Feb  7 17:36:51 canect2 daemon.info ModemManager[302]: <info>  
[1518025011.979010] [mm-iface-modem-3gpp.c:1100] 
update_registration_reload_current_registration_info_ready(): Modem 
/org/freedesktop/ModemManager1/Modem/0: 3GPP Registration state changed 
(registering -> hom
Feb  7 17:36:51 canect2 daemon.info ModemManager[302]: <info>  
[1518025011.979801] [mm-iface-modem.c:1433] 
__iface_modem_update_state_internal(): Modem 
/org/freedesktop/ModemManager1/Modem/0: state changed (enabled -> registered)
Feb  7 17:36:51 canect2 daemon.info NetworkManager[308]: <info>  
[1518025011.9864] (ttyACM0): modem state changed, 'enabled' --> 'registered' 
(reason: unknown)
Feb  7 17:36:51 canect2 daemon.info ModemManager[302]: <debug> 
[1518025011.987618] [mm-iface-modem.c:1357] 
periodic_signal_quality_check_enable(): Periodic signal quality checks enabled 
(interval = 3s)
Feb  7 17:36:51 canect2 daemon.info ModemManager[302]: <debug> 
[1518025011.988083] [mm-broadband-modem.c:1991] modem_load_signal_quality(): 
loading signal quality...
Feb  7 17:36:51 canect2 daemon.info ModemManager[302]: <debug> 
[1518025011.988521] [mm-port-serial.c:1296] mm_port_serial_open(): (ttyACM0) 
device open count is 4 (open)
Feb  7 17:36:51 canect2 daemon.info ModemManager[302]: <debug> 
[1518025011.988977] [mm-iface-modem.c:1077] 
periodic_access_technologies_check_enable(): Periodic access technology checks 
enabled
Feb  7 17:36:51 canect2 daemon.info ModemManager[302]: <debug> 
[1518025011.992874] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): --> 
'AT+CGREG?<CR>'
Feb  7 17:36:52 canect2 daemon.info ModemManager[302]: <debug> 
[1518025012.005240] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): <-- 
'<CR><LF>+CGREG: 2,1,"XXXX","XXXXXXXX",6,"6C"<CR><LF><CR><LF>OK<CR><LF>'
Feb  7 17:36:52 canect2 daemon.info ModemManager[302]: <debug> 
[1518025012.006458] [mm-port-serial.c:1296] mm_port_serial_open(): (ttyACM0) 
device open count is 5 (open)
Feb  7 17:36:52 canect2 daemon.info ModemManager[302]: <debug> 
[1518025012.007022] [mm-port-serial.c:1353] _close_internal(): (ttyACM0) device 
open count is 4 (close)
Feb  7 17:36:52 canect2 daemon.info ModemManager[302]: <debug> 
[1518025012.007583] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): --> 
'AT+CEREG?<CR>'
Feb  7 17:36:52 canect2 daemon.info ModemManager[302]: <debug> 
[1518025012.019471] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): <-- 
'<CR><LF>+CEREG: 2,0<CR><LF><CR><LF>OK<CR><LF>'
Feb  7 17:36:52 canect2 daemon.info ModemManager[302]: <debug> 
[1518025012.020342] [mm-port-serial.c:1353] _close_internal(): (ttyACM0) device 
open count is 3 (close)
Feb  7 17:36:52 canect2 daemon.info ModemManager[302]: <debug> 
[1518025012.020945] [mm-broadband-modem.c:8655] 
modem_3gpp_run_registration_checks_ready(): Initial 3GPP registration checks 
finished
Feb  7 17:36:52 canect2 daemon.info ModemManager[302]: <debug> 
[1518025012.021427] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): --> 
'AT+CIND?<CR>'
Feb  7 17:36:52 canect2 daemon.info ModemManager[302]: <debug> 
[1518025012.032351] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): <-- 
'<CR><LF>+CIND: 5,3,1,0,0,0,0,0,2,0,0,0<CR><LF><CR><LF>OK<CR><LF>'
Feb  7 17:36:52 canect2 daemon.info ModemManager[302]: <debug> 
[1518025012.033315] [mm-port-serial.c:1353] _close_internal(): (ttyACM0) device 
open count is 2 (close)
Feb  7 17:36:52 canect2 daemon.info ModemManager[302]: <debug> 
[1518025012.034292] [mm-iface-modem.c:1206] update_signal_quality(): Modem 
/org/freedesktop/ModemManager1/Modem/0: signal quality updated (60)
Feb  7 17:36:52 canect2 daemon.info ModemManager[302]: <debug> 
[1518025012.034781] [mm-iface-modem.c:1276] signal_quality_check_ready(): 
Periodic signal quality checks rescheduled (interval = 30s)
Feb  7 17:36:52 canect2 daemon.info ModemManager[302]: <debug> 
[1518025012.038645] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): --> 
'AT+CEREG?<CR>'
Feb  7 17:36:52 canect2 daemon.info ModemManager[302]: <debug> 
[1518025012.050727] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): <-- 
'<CR><LF>+CEREG: 2,0<CR><LF><CR><LF>OK<CR><LF>'
Feb  7 17:36:52 canect2 daemon.info ModemManager[302]: <debug> 
[1518025012.051601] [mm-port-serial.c:1353] _close_internal(): (ttyACM0) device 
open count is 1 (close)
Feb  7 17:36:52 canect2 daemon.info ModemManager[302]: <debug> 
[1518025012.052297] [mm-iface-modem-3gpp.c:280] 
run_registration_checks_ready(): Modem is currently registered in a 3GPP network
Feb  7 17:36:52 canect2 daemon.info ModemManager[302]: <info>  
[1518025012.052929] [mm-iface-modem-simple.c:501] connection_step(): Simple 
connect state (6/8): Bearer
Feb  7 17:36:52 canect2 daemon.info ModemManager[302]: <debug> 
[1518025012.053347] [mm-iface-modem-simple.c:521] connection_step(): Creating 
new bearer...
Feb  7 17:36:52 canect2 daemon.info ModemManager[302]: <debug> 
[1518025012.053784] [mm-broadband-modem.c:297] modem_create_bearer(): Creating 
Broadband bearer in broadband modem
Feb  7 17:36:52 canect2 daemon.info ModemManager[302]: <debug> 
[1518025012.056341] [mm-port-serial.c:1296] mm_port_serial_open(): (ttyACM0) 
device open count is 2 (open)
Feb  7 17:36:52 canect2 daemon.info ModemManager[302]: <debug> 
[1518025012.056924] [mm-port-serial.c:1353] _close_internal(): (ttyACM0) device 
open count is 1 (close)
Feb  7 17:36:52 canect2 daemon.info ModemManager[302]: <debug> 
[1518025012.057731] [mm-broadband-modem.c:258] modem_create_bearer_finish(): 
New bearer created at DBus path '/org/freedesktop/ModemManager1/Bearer/0'
Feb  7 17:36:52 canect2 daemon.info ModemManager[302]: <info>  
[1518025012.061855] [mm-iface-modem-simple.c:583] connection_step(): Simple 
connect state (7/8): Connect
Feb  7 17:36:52 canect2 daemon.info ModemManager[302]: <debug> 
[1518025012.062396] [mm-base-bearer.c:703] mm_base_bearer_connect(): Connecting 
bearer '/org/freedesktop/ModemManager1/Bearer/0'
Feb  7 17:36:52 canect2 daemon.info ModemManager[302]: <info>  
[1518025012.062928] [mm-iface-modem.c:1433] 
__iface_modem_update_state_internal(): Modem 
/org/freedesktop/ModemManager1/Modem/0: state changed (registered -> connecting)
Feb  7 17:36:52 canect2 daemon.info NetworkManager[308]: <info>  
[1518025012.0695] (ttyACM0): modem state changed, 'registered' --> 'connecting' 
(reason: user-requested)
Feb  7 17:36:52 canect2 daemon.info ModemManager[302]: <debug> 
[1518025012.070832] [mm-broadband-bearer.c:1263] connect(): Launching 3GPP 
connection attempt with APN 'iot.aer.net'
Feb  7 17:36:52 canect2 daemon.info ModemManager[302]: <debug> 
[1518025012.071357] [mm-broadband-bearer.c:1052] connect_3gpp(): Looking for 
best CID...
Feb  7 17:36:52 canect2 daemon.info ModemManager[302]: <debug> 
[1518025012.071794] [mm-port-serial.c:1296] mm_port_serial_open(): (ttyACM0) 
device open count is 2 (open)
Feb  7 17:36:52 canect2 daemon.info ModemManager[302]: <debug> 
[1518025012.072386] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): --> 
'AT+CGDCONT?<CR>'
Feb  7 17:36:52 canect2 daemon.info ModemManager[302]: <debug> 
[1518025012.087648] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): <-- 
'<CR><LF>+CGDCONT: 1,"IPV4V6","nxtgenphone","0.0.0.0 
0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0",0,0,0,0,0,0<CR><LF><CR><LF>+CGDCONT: 
2,"IPV4V6",
Feb  7 17:36:52 canect2 daemon.info ModemManager[302]: <debug> 
[1518025012.089108] [mm-broadband-bearer.c:969] parse_pdp_list(): Found '5' PDP 
contexts
Feb  7 17:36:52 canect2 daemon.info ModemManager[302]: <debug> 
[1518025012.089559] [mm-broadband-bearer.c:978] parse_pdp_list():   PDP context 
[cid=1] [type='ipv4v6'] [apn='nxtgenphone']
Feb  7 17:36:52 canect2 daemon.info ModemManager[302]: <debug> 
[1518025012.089883] [mm-broadband-bearer.c:978] parse_pdp_list():   PDP context 
[cid=2] [type='ipv4v6'] [apn='iot.aer.net']
Feb  7 17:36:52 canect2 daemon.info ModemManager[302]: <debug> 
[1518025012.090153] [mm-broadband-bearer.c:978] parse_pdp_list():   PDP context 
[cid=3] [type='ipv4v6'] [apn='iot.aer.net']
Feb  7 17:36:52 canect2 daemon.info ModemManager[302]: <debug> 
[1518025012.090401] [mm-broadband-bearer.c:978] parse_pdp_list():   PDP context 
[cid=4] [type='ipv4'] [apn='iot.aer.net']
Feb  7 17:36:52 canect2 daemon.info ModemManager[302]: <debug> 
[1518025012.090643] [mm-broadband-bearer.c:978] parse_pdp_list():   PDP context 
[cid=5] [type='ipv6'] [apn='iot.aer.net']
Feb  7 17:36:52 canect2 daemon.info ModemManager[302]: <debug> 
[1518025012.090886] [mm-broadband-bearer.c:1002] parse_pdp_list(): Found PDP 
context with CID 2 and PDP type ipv4v6 for APN 'iot.aer.net'
Feb  7 17:36:52 canect2 daemon.info ModemManager[302]: <debug> 
[1518025012.091227] [mm-port-serial.c:1296] mm_port_serial_open(): (ttyACM0) 
device open count is 3 (open)
Feb  7 17:36:52 canect2 daemon.info ModemManager[302]: <debug> 
[1518025012.091519] [mm-broadband-bearer.c:214] common_get_at_data_port(): 
Connection through a plain serial AT port (ttyACM0)
Feb  7 17:36:52 canect2 daemon.info ModemManager[302]: <debug> 
[1518025012.091888] [mm-port-serial.c:1296] mm_port_serial_open(): (ttyACM0) 
device open count is 4 (open)
Feb  7 17:36:52 canect2 daemon.info ModemManager[302]: <debug> 
[1518025012.092333] [mm-port-serial.c:1353] _close_internal(): (ttyACM0) device 
open count is 3 (close)
Feb  7 17:36:52 canect2 daemon.info ModemManager[302]: <debug> 
[1518025012.092807] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): --> 
'ATD*99***2#<CR>'
Feb  7 17:36:52 canect2 daemon.info ModemManager[302]: <debug> 
[1518025012.109965] [mm-port-serial-at.c:460] debug_log(): (ttyACM0): <-- 
'<CR><LF>CONNECT<CR><LF>'
Feb  7 17:36:52 canect2 daemon.info ModemManager[302]: <debug> 
[1518025012.110837] [mm-port.c:95] mm_port_set_connected(): (ttyACM0): port now 
connected
Feb  7 17:36:52 canect2 daemon.info ModemManager[302]: <debug> 
[1518025012.111485] [mm-port-serial.c:1353] _close_internal(): (ttyACM0) device 
open count is 2 (close)
Feb  7 17:36:52 canect2 daemon.info ModemManager[302]: <debug> 
[1518025012.112171] [mm-base-bearer.c:601] connect_ready(): Connected bearer 
'/org/freedesktop/ModemManager1/Bearer/0'
Feb  7 17:36:52 canect2 daemon.info ModemManager[302]: <info>  
[1518025012.113878] [mm-iface-modem.c:1433] 
__iface_modem_update_state_internal(): Modem 
/org/freedesktop/ModemManager1/Modem/0: state changed (connecting -> connected)
Feb  7 17:36:52 canect2 daemon.info NetworkManager[308]: <info>  
[1518025012.1208] (ttyACM0): modem state changed, 'connecting' --> 'connected' 
(reason: user-requested)
Feb  7 17:36:52 canect2 daemon.info ModemManager[302]: <info>  
[1518025012.122011] [mm-iface-modem-simple.c:602] connection_step(): Simple 
connect state (8/8): All done
Feb  7 17:36:52 canect2 daemon.warn NetworkManager[308]: <warn>  
[1518025012.1782] device (ttyACM0): ip-ifname: set ifname 'ttyACM0', unknown 
ifindex
Feb  7 17:36:52 canect2 daemon.info NetworkManager[308]: <info>  
[1518025012.1810] device (ttyACM0): state change: prepare -> config (reason 
'none') [40 50 0]
Feb  7 17:36:52 canect2 daemon.info NetworkManager[308]: <info>  
[1518025012.1870] device (ttyACM0): state change: config -> ip-config (reason 
'none') [50 70 0]
Feb  7 17:36:52 canect2 daemon.warn NetworkManager[308]: <warn>  
[1518025012.1895] device (ttyACM0): interface ttyACM0 not up for IP 
configuration
Feb  7 17:36:52 canect2 daemon.info NetworkManager[308]: <info>  
[1518025012.1900] (ttyACM0): using modem-specified IP timeout: 20 seconds
Feb  7 17:36:52 canect2 daemon.info NetworkManager[308]: <info>  
[1518025012.2052] loaded PPP plugin /usr/lib/NetworkManager/libnm-ppp-plugin.so
Feb  7 17:36:52 canect2 daemon.info NetworkManager[308]: <info>  
[1518025012.2100] ppp-manager: starting PPP connection
Feb  7 17:36:52 canect2 daemon.info NetworkManager[308]: <info>  
[1518025012.2222] ppp-manager: pppd started with pid 480
Feb  7 17:36:52 canect2 daemon.info pppd[480]: Plugin 
/usr/lib/pppd/2.4.5/nm-pppd-plugin.so loaded.
Feb  7 17:36:52 canect2 daemon.notice pppd[480]: pppd 2.4.7 started by root, 
uid 0
Feb  7 17:36:52 canect2 daemon.info pppd[480]: Using interface ppp0
Feb  7 17:36:52 canect2 daemon.notice pppd[480]: Connect: ppp0 <--> /dev/ttyACM0
Feb  7 17:36:52 canect2 daemon.info NetworkManager[308]: <info>  
[1518025012.3628] manager: (ppp0): new Generic device 
(/org/freedesktop/NetworkManager/Devices/9)
Feb  7 17:36:52 canect2 daemon.info ModemManager[302]: <debug> 
[1518025012.376785] [mm-base-manager.c:368] device_added(): (net/ppp0): could 
not get port's parent device
Feb  7 17:36:55 canect2 daemon.notice pppd[480]: local  IP address 
XXX.XXX.XXX.XXX
Feb  7 17:36:55 canect2 daemon.notice pppd[480]: remote IP address 
XXX.XXX.XXX.XXX
Feb  7 17:36:55 canect2 daemon.notice pppd[480]: primary   DNS address 
XXX.XXX.XXX.XXX
Feb  7 17:36:55 canect2 daemon.notice pppd[480]: secondary DNS address 
XXX.XXX.XXX.XXX
Feb  7 17:36:55 canect2 daemon.info NetworkManager[308]: <info>  
[1518025015.4096] ppp-manager: (IPv4 Config Get) reply received.
Feb  7 17:36:55 canect2 daemon.info NetworkManager[308]: <info>  
[1518025015.4447] device (ttyACM0): state change: ip-config -> ip-check (reason 
'none') [70 80 0]
Feb  7 17:36:55 canect2 daemon.notice dbus[235]: [system] Activating service 
name='org.freedesktop.nm_dispatcher' (using servicehelper)
Feb  7 17:36:55 canect2 daemon.notice dbus[235]: [system] Successfully 
activated service 'org.freedesktop.nm_dispatcher'
Feb  7 17:36:55 canect2 daemon.info nm-dispatcher: req:1 'pre-up' [ppp0]: new 
request (1 scripts)
Feb  7 17:36:55 canect2 daemon.info nm-dispatcher: req:1 'pre-up' [ppp0]: start 
running ordered scripts...
Feb  7 17:36:55 canect2 user.notice root: Starting wifi_config_nm.sh
Feb  7 17:36:55 canect2 daemon.info NetworkManager[308]: <info>  
[1518025015.5773] device (ttyACM0): state change: ip-check -> secondaries 
(reason 'none') [80 90 0]
Feb  7 17:36:55 canect2 daemon.info NetworkManager[308]: <info>  
[1518025015.5809] device (ttyACM0): state change: secondaries -> activated 
(reason 'none') [90 100 0]
Feb  7 17:36:55 canect2 daemon.info NetworkManager[308]: <info>  
[1518025015.5828] manager: NetworkManager state is now CONNECTED_LOCAL
Feb  7 17:36:55 canect2 daemon.warn NetworkManager[308]: <warn>  
[1518025015.5870] 
settings-connection[0x200e130,83187ceb-ad3a-4af8-92d8-7a255d9c5e3f]: error 
saving timestamp to file '/var/lib/NetworkManager/timestamps': Failed to create 
file “/var/lib/NetworkManager/t
Feb  7 17:36:55 canect2 daemon.info NetworkManager[308]: <info>  
[1518025015.5900] manager: NetworkManager state is now CONNECTED_SITE
Feb  7 17:36:55 canect2 daemon.info NetworkManager[308]: <info>  
[1518025015.5921] policy: set 'Aeris' (ppp0) as default for IPv4 routing and DNS
Feb  7 17:36:55 canect2 daemon.info NetworkManager[308]: <info>  
[1518025015.5948] device (ttyACM0): Activation: successful, device activated.
_______________________________________________
ModemManager-devel mailing list
ModemManager-devel@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/modemmanager-devel

Reply via email to