Understanding Modem Manager
Dan Williams
dcbw at redhat.com
Tue Dec 10 15:38:38 PST 2013
On Tue, 2013-12-10 at 22:26 +0000, Marc Murphy wrote:
> Hey Aleksander
>
> I have now updated and configured NetworkManager and with the SierraWireless MC8705 can connect and get an IP address (bingo!) With the Huawei however it can enable the modem but when I try to connect there are lots of timeouts. I have run ModemManager in debug to see if there is anything that can be deciphered from the log. (Sorry about the huge amount of info)
This is actually looking more like a NetworkManager problem. Can you
grab the NM logs? The reason I ask is:
[946684922.340885] [mm-iface-modem.c:1176] mm_iface_modem_update_state(): Modem /org/freedesktop/ModemManager1/Modem/0: state changed (connecting -> connected)
[946684922.355045] [mm-iface-modem-simple.c:739] connection_step(): Simple connect state (10/10): All done
[946684922.524632] [mm-bearer.c:687] mm_bearer_disconnect(): Disconnecting bearer '/org/freedesktop/ModemManager1/Bearer/0'
so this could also be a PPP negotiation issue.
Dan
> I issue the
> #nmcli nm wwan on
> #nmcli con up uuid uuid-number
> and it goes through the following, it will eventually time out as it looks like the modem is not responding;
>
> # ModemManager[883]: <info> [946684909.389072] [mm-broadband-modem.c:7349] enabling_step(): Modem enabling...
> ModemManager[883]: <info> [946684909.390262] [mm-iface-modem.c:1176] mm_iface_modem_update_state(): Modem /org/freedesktop/ModemManager1/Modem/0: state changed (disabled -> enabling)
> ModemManager[883]: <info> [946684909.413486] [mm-serial-port.c:857] mm_serial_port_open(): (ttyUSB3) opening serial port...
> ModemManager[883]: <warn> [946684909.415866] [mm-serial-port.c:414] real_config_fd(): (ttyUSB3): port attributes not fully set
> ModemManager[883]: <debug> [946684909.416507] [mm-serial-port.c:926] mm_serial_port_open(): (ttyUSB3) device open count is 1 (open)
> ModemManager[883]: <info> [946684909.416843] [mm-serial-port.c:857] mm_serial_port_open(): (ttyUSB2) opening serial port...
> ModemManager[883]: <debug> [946684909.434696] [mm-serial-port.c:926] mm_serial_port_open(): (ttyUSB2) device open count is 1 (open)
> ModemManager[883]: <debug> [946684909.435184] [mm-broadband-modem.c:6829] enabling_started(): Flashing primary port before enabling...
> ModemManager[883]: <debug> [946684909.538211] [mm-serial-port.c:926] mm_serial_port_open(): (ttyUSB3) device open count is 2 (open)
> ModemManager[883]: <debug> [946684909.539066] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): --> 'ATZ<CR>'
> ModemManager[883]: <debug> [946684909.558139] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): <-- '<CR><LF>OK<CR><LF>'
> ModemManager[883]: <debug> [946684909.559146] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): --> 'ATE0 V1<CR>'
> ModemManager[883]: <debug> [946684909.567661] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): <-- 'ATE0 V'
> ModemManager[883]: <debug> [946684909.570194] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): <-- '1<CR>'
> ModemManager[883]: <debug> [946684909.571109] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): <-- '<CR><LF>OK<CR><LF>'
> ModemManager[883]: <debug> [946684909.571964] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): --> 'AT+CMEE=1<CR>'
> ModemManager[883]: <debug> [946684909.585788] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): <-- '<CR><LF>OK<CR><LF>'
> ModemManager[883]: <debug> [946684909.586765] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): --> 'ATX4 &C1<CR>'
> ModemManager[883]: <debug> [946684909.599155] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): <-- '<CR><LF>OK<CR><LF>'
> ModemManager[883]: <debug> [946684909.600009] [mm-serial-port.c:926] mm_serial_port_open(): (ttyUSB3) device open count is 3 (open)
> ModemManager[883]: <debug> [946684909.600589] [mm-serial-port.c:966] mm_serial_port_close(): (ttyUSB3) device open count is 2 (close)
> ModemManager[883]: <debug> [946684909.601047] [mm-serial-port.c:926] mm_serial_port_open(): (ttyUSB3) device open count is 3 (open)
> ModemManager[883]: <debug> [946684909.601688] [mm-serial-port.c:926] mm_serial_port_open(): (ttyUSB3) device open count is 4 (open)
> ModemManager[883]: <debug> [946684909.602268] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): --> 'AT+CFUN=1<CR>'
> ModemManager[883]: <debug> [946684909.617313] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): <-- '<CR><LF>OK<CR><LF>'
> ModemManager[883]: <debug> [946684909.618076] [mm-serial-port.c:966] mm_serial_port_close(): (ttyUSB3) device open count is 3 (close)
> ModemManager[883]: <debug> [946684909.618595] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): --> 'AT+IFC=1,1<CR>'
> ModemManager[883]: <debug> [946684909.633792] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): <-- '<CR><LF>OK<CR><LF>'
> ModemManager[883]: <debug> [946684909.634525] [mm-serial-port.c:966] mm_serial_port_close(): (ttyUSB3) device open count is 2 (close)
> ModemManager[883]: <debug> [946684909.635013] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): --> 'AT+CSCS=?<CR>'
> ModemManager[883]: <debug> [946684909.650943] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): <-- '<CR><LF>+CSCS: ("IRA","GSM","UCS2")<CR><LF><CR><LF>OK<CR><LF>'
> ModemManager[883]: <debug> [946684909.652530] [mm-serial-port.c:926] mm_serial_port_open(): (ttyUSB3) device open count is 3 (open)
> ModemManager[883]: <debug> [946684909.653110] [mm-serial-port.c:966] mm_serial_port_close(): (ttyUSB3) device open count is 2 (close)
> ModemManager[883]: <debug> [946684909.653598] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): --> 'AT+CSCS="UCS2"<CR>'
> ModemManager[883]: <debug> [946684909.675083] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): <-- '<CR><LF>OK<CR><LF>'
> ModemManager[883]: <debug> [946684909.675876] [mm-serial-port.c:926] mm_serial_port_open(): (ttyUSB3) device open count is 3 (open)
> ModemManager[883]: <debug> [946684909.676395] [mm-serial-port.c:966] mm_serial_port_close(): (ttyUSB3) device open count is 2 (close)
> ModemManager[883]: <debug> [946684909.676914] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): --> 'AT+CSCS?<CR>'
> ModemManager[883]: <debug> [946684909.691440] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): <-- '<CR><LF>+CSCS: "UCS2"<CR><LF><CR><LF>OK<CR><LF>'
> ModemManager[883]: <debug> [946684909.692295] [huawei/mm-broadband-modem-huawei.c:717] load_allowed_modes(): loading allowed_modes (huawei)...
> ModemManager[883]: <debug> [946684909.692752] [mm-serial-port.c:926] mm_serial_port_open(): (ttyUSB3) device open count is 3 (open)
> ModemManager[883]: <debug> [946684909.693210] [mm-serial-port.c:966] mm_serial_port_close(): (ttyUSB3) device open count is 2 (close)
> ModemManager[883]: <debug> [946684909.693698] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): --> 'AT^SYSCFG?<CR>'
> ModemManager[883]: <debug> [946684909.710330] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): <-- '<CR><LF>^SYSCFG:2,0,3FFFFFFF,1,2<CR><LF><CR><LF>OK<CR><LF>'
> ModemManager[883]: <debug> [946684909.712009] [huawei/mm-broadband-modem-huawei.c:579] load_current_bands(): loading current bands (huawei)...
> ModemManager[883]: <debug> [946684909.712436] [mm-serial-port.c:926] mm_serial_port_open(): (ttyUSB3) device open count is 3 (open)
> ModemManager[883]: <debug> [946684909.712863] [mm-serial-port.c:966] mm_serial_port_close(): (ttyUSB3) device open count is 2 (close)
> ModemManager[883]: <debug> [946684909.713352] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): --> 'AT^SYSCFG?<CR>'
> ModemManager[883]: <debug> [946684909.729709] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): <-- '<CR><LF>^SYSCFG:2,0,3FFFFFFF,1,2<CR><LF><CR><LF>OK<CR><LF>'
> ModemManager[883]: <debug> [946684909.731510] [mm-serial-port.c:966] mm_serial_port_close(): (ttyUSB3) device open count is 1 (close)
> ModemManager[883]: <debug> [946684909.732181] [mm-broadband-modem.c:7382] enabling_step(): Modem has 3GPP capabilities, enabling the Modem 3GPP interface...
> ModemManager[883]: <debug> [946684909.732669] [mm-broadband-modem.c:1788] modem_3gpp_setup_unsolicited_events(): Checking indicator support...
> ModemManager[883]: <debug> [946684909.733005] [mm-serial-port.c:926] mm_serial_port_open(): (ttyUSB3) device open count is 2 (open)
> ModemManager[883]: <debug> [946684909.733554] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): --> 'AT+CIND=?<CR>'
> ModemManager[883]: <debug> [946684909.747684] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): <-- '<CR><LF>+CIND: ("battchg",(0-5)),("signal",(0-5)),("service",(0-1)),("call",(0-1)),("roam",(0-1)),("smsfull",(0-1)),("GPRS coverage",(0-1)),("callsetup",(0-3))<CR><LF><CR><LF>OK<CR><LF>'
> ModemManager[883]: <debug> [946684909.749546] [mm-broadband-modem.c:1741] cind_format_check_ready(): Modem supports signal quality indications via CIND at index '2'(min: 0, max: 5)
> ModemManager[883]: <debug> [946684909.750003] [mm-broadband-modem.c:1750] cind_format_check_ready(): Modem supports roaming indications via CIND at index '5'
> ModemManager[883]: <debug> [946684910.086673] [mm-broadband-modem.c:1759] cind_format_check_ready(): Modem supports service indications via CIND at index '3'
> ModemManager[883]: <debug> [946684910.087131] [mm-broadband-modem.c:1692] set_unsolicited_events_handlers(): (ttyUSB3) Setting 3GPP unsolicited events handlers
> ModemManager[883]: <debug> [946684910.087711] [mm-serial-port.c:926] mm_serial_port_open(): (ttyUSB3) device open count is 3 (open)
> ModemManager[883]: <debug> [946684910.088291] [mm-serial-port.c:966] mm_serial_port_close(): (ttyUSB3) device open count is 2 (close)
> ModemManager[883]: <debug> [946684910.088809] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): --> 'AT+CMER=3,0,0,1<CR>'
> ModemManager[883]: <debug> [946684910.113712] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): <-- '<CR><LF>OK<CR><LF>'
> ModemManager[883]: <debug> [946684910.114566] [mm-serial-port.c:926] mm_serial_port_open(): (ttyUSB3) device open count is 3 (open)
> ModemManager[883]: <debug> [946684910.115116] [mm-serial-port.c:966] mm_serial_port_close(): (ttyUSB3) device open count is 2 (close)
> ModemManager[883]: <debug> [946684910.115543] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): --> 'AT^PORTSEL=0<CR>'
> ModemManager[883]: <debug> [946684910.133792] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): <-- '<CR><LF>OK<CR><LF>'
> ModemManager[883]: <debug> [946684910.134738] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): --> 'AT^CURC=1<CR>'
> ModemManager[883]: <debug> [946684910.148563] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): <-- '<CR><LF>OK<CR><LF>'
> ModemManager[883]: <debug> [946684910.150669] [mm-broadband-modem.c:2735] modem_3gpp_setup_unsolicited_registration_events(): (ttyUSB3) setting up 3GPP unsolicited registration messages handlers
> ModemManager[883]: <debug> [946684910.151279] [mm-serial-port.c:966] mm_serial_port_close(): (ttyUSB3) device open count is 1 (close)
> ModemManager[883]: <debug> [946684910.152042] [mm-serial-port.c:926] mm_serial_port_open(): (ttyUSB3) device open count is 2 (open)
> ModemManager[883]: <debug> [946684910.152683] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): --> 'AT+CREG=2<CR>'
> ModemManager[883]: <debug> [946684910.168552] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): <-- '<CR><LF>OK<CR><LF>'
> ModemManager[883]: <debug> [946684910.169406] [mm-serial-port.c:926] mm_serial_port_open(): (ttyUSB3) device open count is 3 (open)
> ModemManager[883]: <debug> [946684910.169864] [mm-serial-port.c:966] mm_serial_port_close(): (ttyUSB3) device open count is 2 (close)
> ModemManager[883]: <debug> [946684910.170322] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): --> 'AT+CGREG=2<CR>'
> ModemManager[883]: <debug> [946684910.186069] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): <-- '<CR><LF>OK<CR><LF>'
> ModemManager[883]: <debug> [946684910.186924] [mm-serial-port.c:966] mm_serial_port_close(): (ttyUSB3) device open count is 1 (close)
> ModemManager[883]: <debug> [946684910.187473] [mm-iface-modem-3gpp.c:732] mm_iface_modem_3gpp_run_registration_checks(): Running registration checks (CS: 'yes', PS: 'yes')
> ModemManager[883]: <debug> [946684910.187931] [mm-serial-port.c:926] mm_serial_port_open(): (ttyUSB3) device open count is 2 (open)
> ModemManager[883]: <debug> [946684910.188480] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): --> 'AT+CREG?<CR>'
> ModemManager[883]: <debug> [946684910.202060] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): <-- '<CR><LF>+CREG: 2,1, CEE, CEEBF08<CR><LF><CR><LF>OK<CR><LF>'
> ModemManager[883]: <info> [946684910.203037] [mm-iface-modem-3gpp.c:1047] update_registration_state(): Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP Registration state changed (unknown -> registering)
> ModemManager[883]: <debug> [946684910.203647] [mm-broadband-modem.c:2619] modem_3gpp_load_operator_code(): loading Operator Code...
> ModemManager[883]: <debug> [946684910.203952] [mm-serial-port.c:926] mm_serial_port_open(): (ttyUSB3) device open count is 3 (open)
> ModemManager[883]: <debug> [946684910.205081] [mm-serial-port.c:926] mm_serial_port_open(): (ttyUSB3) device open count is 4 (open)
> ModemManager[883]: <debug> [946684910.205539] [mm-serial-port.c:966] mm_serial_port_close(): (ttyUSB3) device open count is 3 (close)
> ModemManager[883]: <debug> [946684910.206089] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): --> 'AT+COPS=3,2;+COPS?<CR>'
> ModemManager[883]: <debug> [946684910.228000] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): <-- '<CR><LF>^RSSI:3<CR><LF><CR><LF>^CSNR:-105,-7<CR><LF>'
> ModemManager[883]: <debug> [946684910.228824] [huawei/mm-broadband-modem-huawei.c:851] huawei_signal_changed(): 3GPP signal quality: 9
> ModemManager[883]: <info> [946684910.230320] [mm-iface-modem.c:971] update_signal_quality(): Modem /org/freedesktop/ModemManager1/Modem/0: signal quality updated (9)
> ModemManager[883]: <debug> [946684910.231144] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): <-- '<CR><LF>+COPS: 0,2,"23433",2<CR><LF><CR><LF>OK<CR><LF>'
> ModemManager[883]: <debug> [946684910.232273] [mm-broadband-modem.c:2609] modem_3gpp_load_operator_code_finish(): loaded Operator Code: 23433
> ModemManager[883]: <debug> [946684910.233188] [mm-broadband-modem.c:2655] modem_3gpp_load_operator_name(): loading Operator Name...
> ModemManager[883]: <debug> [946684910.233554] [mm-serial-port.c:926] mm_serial_port_open(): (ttyUSB3) device open count is 4 (open)
> ModemManager[883]: <debug> [946684910.569706] [mm-serial-port.c:966] mm_serial_port_close(): (ttyUSB3) device open count is 3 (close)
> ModemManager[883]: <debug> [946684910.583194] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): --> 'AT+CGREG?<CR>'
> ModemManager[883]: <debug> [946684910.598850] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): <-- '<CR><LF>+CGREG: 2,1, CEE, CEEBF08<CR><LF><CR><LF>OK<CR><LF>'
> ModemManager[883]: <debug> [946684910.600345] [mm-serial-port.c:966] mm_serial_port_close(): (ttyUSB3) device open count is 2 (close)
> ModemManager[883]: <debug> [946684910.601139] [mm-broadband-modem.c:7395] enabling_step(): Modem has 3GPP/USSD capabilities, enabling the Modem 3GPP/USSD interface...
> ModemManager[883]: <debug> [946684910.601780] [mm-broadband-modem.c:3916] set_unsolicited_result_code_handlers(): (ttyUSB3) Setting unsolicited result code handlers
> ModemManager[883]: <debug> [946684910.602481] [mm-serial-port.c:926] mm_serial_port_open(): (ttyUSB3) device open count is 3 (open)
> ModemManager[883]: <debug> [946684910.603000] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): --> 'AT+COPS=3,0;+COPS?<CR>'
> ModemManager[883]: <debug> [946684910.646213] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): <-- '<CR><LF>+COPS: 0,0,"Orange",2<CR><LF><CR><LF>OK<CR><LF>'
> ModemManager[883]: <debug> [946684910.648197] [mm-broadband-modem.c:2645] modem_3gpp_load_operator_name_finish(): loaded Operator Name: Orange
> ModemManager[883]: <debug> [946684910.649387] [mm-serial-port.c:966] mm_serial_port_close(): (ttyUSB3) device open count is 2 (close)
> ModemManager[883]: <info> [946684910.656498] [mm-iface-modem-3gpp.c:1004] update_registration_reload_current_operator_ready(): Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP Registration state changed (registering -> home)
> ModemManager[883]: <debug> [946684910.657901] [mm-iface-modem.c:1320] get_updated_consolidated_state(): Will start keeping track of state for subsystem '3gpp'
> ModemManager[883]: <debug> [946684910.665012] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): --> 'AT+CUSD=1<CR>'
> ModemManager[883]: <debug> [946684910.679844] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): <-- '<CR><LF>OK<CR><LF>'
> ModemManager[883]: <debug> [946684910.681400] [mm-serial-port.c:966] mm_serial_port_close(): (ttyUSB3) device open count is 1 (close)
> ModemManager[883]: <debug> [946684910.688541] [mm-broadband-modem.c:7423] enabling_step(): Modem has location capabilities, enabling the Location interface...
> ModemManager[883]: <debug> [946684910.689365] [mm-iface-modem-location.c:737] setup_gathering(): Need to enable the following location sources: '3gpp-lac-ci'
> ModemManager[883]: <debug> [946684910.690464] [mm-iface-modem-3gpp.c:732] mm_iface_modem_3gpp_run_registration_checks(): Running registration checks (CS: 'yes', PS: 'yes')
> ModemManager[883]: <debug> [946684910.690921] [mm-serial-port.c:926] mm_serial_port_open(): (ttyUSB3) device open count is 2 (open)
> ModemManager[883]: <debug> [946684910.698337] [mm-broadband-modem.c:7436] enabling_step(): Modem has messaging capabilities, enabling the Messaging interface...
> ModemManager[883]: <debug> [946684910.699955] [mm-serial-port.c:926] mm_serial_port_open(): (ttyUSB3) device open count is 3 (open)
> ModemManager[883]: <debug> [946684910.700657] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): --> 'AT+CREG?<CR>'
> ModemManager[883]: <debug> [946684910.713230] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): <-- '<CR><LF>+CREG: 2,1, CEE, CEEBF08<CR><LF><CR><LF>OK<CR><LF>'
> ModemManager[883]: <info> [946684910.714237] [mm-iface-modem-location.c:291] notify_3gpp_location_update(): Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP location updated (MCC: '0', MNC: '0', Location area code: 'CEE', Cell ID: 'CEEBF08')
> ModemManager[883]: <debug> [946684910.715244] [mm-serial-port.c:926] mm_serial_port_open(): (ttyUSB3) device open count is 4 (open)
> ModemManager[883]: <debug> [946684910.715702] [mm-serial-port.c:966] mm_serial_port_close(): (ttyUSB3) device open count is 3 (close)
> ModemManager[883]: <debug> [946684910.716282] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): --> 'AT+CMGF=?<CR>'
> ModemManager[883]: <debug> [946684910.730808] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): <-- '<CR><LF>+CMGF: (0-1)<CR><LF><CR><LF>OK<CR><LF>'
> ModemManager[883]: <debug> [946684910.732029] [mm-serial-port.c:926] mm_serial_port_open(): (ttyUSB3) device open count is 4 (open)
> ModemManager[883]: <debug> [946684910.732486] [mm-serial-port.c:966] mm_serial_port_close(): (ttyUSB3) device open count is 3 (close)
> ModemManager[883]: <debug> [946684910.733036] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): --> 'AT+CGREG?<CR>'
> ModemManager[883]: <debug> [946684910.748203] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): <-- '<CR><LF>+CGREG: 2,1, CEE, CEEBF08<CR><LF><CR><LF>OK<CR><LF>'
> ModemManager[883]: <debug> [946684910.749485] [mm-serial-port.c:966] mm_serial_port_close(): (ttyUSB3) device open count is 2 (close)
> ModemManager[883]: <debug> [946684910.750309] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): --> 'AT+CMGF=0<CR>'
> ModemManager[883]: <debug> [946684910.763950] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): <-- '<CR><LF>OK<CR><LF>'
> ModemManager[883]: <info> [946684910.764713] [mm-broadband-modem.c:4493] cmgf_set_ready(): Successfully set preferred SMS mode: 'PDU'
> ModemManager[883]: <debug> [946684910.765812] [mm-serial-port.c:926] mm_serial_port_open(): (ttyUSB3) device open count is 3 (open)
> ModemManager[883]: <debug> [946684910.766452] [mm-serial-port.c:966] mm_serial_port_close(): (ttyUSB3) device open count is 2 (close)
> ModemManager[883]: <debug> [946684910.773594] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): --> 'AT+CPMS="","MT","MT"<CR>'
> ModemManager[883]: <debug> [946684910.808994] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): <-- '<CR><LF>+CPMS: 0,23,0,23,0,23<CR><LF><CR><LF>OK<CR><LF>'
> ModemManager[883]: <debug> [946684910.810062] [mm-broadband-modem.c:5202] modem_messaging_load_initial_sms_parts(): Listing SMS parts in storage 'me'
> ModemManager[883]: <debug> [946684910.810489] [mm-broadband-modem.c:4387] mm_broadband_modem_lock_sms_storages(): Locking SMS storages to: mem1 (ME), mem2 (none)...
> ModemManager[883]: <debug> [946684910.810764] [mm-serial-port.c:926] mm_serial_port_open(): (ttyUSB3) device open count is 3 (open)
> ModemManager[883]: <debug> [946684910.811191] [mm-serial-port.c:966] mm_serial_port_close(): (ttyUSB3) device open count is 2 (close)
> ModemManager[883]: <debug> [946684910.811679] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): --> 'AT+CPMS="ME"<CR>'
> ModemManager[883]: <debug> [946684911.170108] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): <-- '<CR><LF>+CPMS: 0,23,0,23,0,23<CR><LF><CR><LF>OK<CR><LF>'
> ModemManager[883]: <debug> [946684911.171116] [mm-serial-port.c:926] mm_serial_port_open(): (ttyUSB3) device open count is 3 (open)
> ModemManager[883]: <debug> [946684911.171665] [mm-serial-port.c:966] mm_serial_port_close(): (ttyUSB3) device open count is 2 (close)
> ModemManager[883]: <debug> [946684911.172245] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): --> 'AT+CMGL=4<CR>'
> ModemManager[883]: <debug> [946684911.189914] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): <-- '<CR><LF>OK<CR><LF>'
> ModemManager[883]: <debug> [946684911.190769] [mm-broadband-modem.c:5202] modem_messaging_load_initial_sms_parts(): Listing SMS parts in storage 'sm'
> ModemManager[883]: <debug> [946684911.191105] [mm-broadband-modem.c:4387] mm_broadband_modem_lock_sms_storages(): Locking SMS storages to: mem1 (SM), mem2 (none)...
> ModemManager[883]: <debug> [946684911.191379] [mm-serial-port.c:926] mm_serial_port_open(): (ttyUSB3) device open count is 3 (open)
> ModemManager[883]: <debug> [946684911.191776] [mm-serial-port.c:966] mm_serial_port_close(): (ttyUSB3) device open count is 2 (close)
> ModemManager[883]: <debug> [946684911.192234] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): --> 'AT+CPMS="SM"<CR>'
> ModemManager[883]: <debug> [946684911.211704] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): <-- '<CR><LF>+CPMS: 5,30,0,23,0,23<CR><LF><CR><LF>OK<CR><LF>'
> ModemManager[883]: <debug> [946684911.212528] [mm-serial-port.c:926] mm_serial_port_open(): (ttyUSB3) device open count is 3 (open)
> ModemManager[883]: <debug> [946684911.213047] [mm-serial-port.c:966] mm_serial_port_close(): (ttyUSB3) device open count is 2 (close)
> ModemManager[883]: <debug> [946684911.213504] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): --> 'AT+CMGL=4<CR>'
> ModemManager[883]: <debug> [946684911.287143] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): <-- '<CR><LF>+CMGL: 0,1,,160<CR><LF>0791449737019037400ED0D456F32D4EB3CB000031609131345040A006080432A90201CEE2156496BFDB206AABF916A7D96517E85A3ED9CBA0B1BC1CA697C9A0693B2CA783A0E1F17A0EA2BF41E7B4BD0CCABFEB20F63B4C9E83DA6F7919D44EBBE72C10BD8CA7CF41613719440ED3C32E502006039DCBF43928FFAE8302371CE8FE96D3D1A0B719340EB3D97350D84D06D1CB78FA1C84A2A3C3F4D31C1483C140EDB47B0E0ABBC9<CR><LF>+CMGL: 1,1,,149<CR><LF>0791449737019037440ED0D456F32D4
> ModemManager[883]: <debug> [946684911.322635] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): <-- '3F7781A8653C1D346D06A5D4180C447F8368B418C8FC9683CCF27219447F83C4F53C280C0AC460207878BC06B9DF7717C898769341EF3A1DD47ECBCB2074595E06A1E974B8EEF56ABBE8ADF65B9C66975DE3B7ABBE7ECDDB61391D<CR><LF>+CMGL: 2,1,,156<CR><LF>07914497370190374005B10708F0000031117181415100A006080487F20201D43C1CFD7EBB41C8703A1F7683D0E139885D36D3416F7B590E32BFEB72503BCD66A7DF6ED0189D6693E56537885C9EC3CBF230BD0C32BFE520F3FB4D6681C6EC72D80DBA87E9653928EC2683E6
> ModemManager[883]: <debug> [946684911.325382] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): <-- '50C9297C36C761EE42E97C9<CR><LF>+CMGL: 3,1,,155<CR><LF>07914497370190374405B10708F00000311171814151009E06080487F20202A0FCBB2E07A1CB6C3888FE7EBB405076393C2F83E465383B0FCA16A720FA1B447EBBC3F43228500399DF7250B95D969FCBEE711E34AFC3E1EC7479EE0265DFF5139B0D3AA7ED6550A00632CBDF6D50FE5D9783C6F232394D0785DD64D01D1DA697ED653928FFAE83EAF37A98CDCE83E0E13CC8FC9683C2207A194F07B5CBF379F85C7601<CR><LF>+CMGL: 4,1,,122<CR><LF>079144973701903704
> ModemManager[883]: <debug> [946684911.327518] [mm-sms-part.c:519] mm_sms_part_new_from_binary_pdu(): Parsing PDU (0)...
> ModemManager[883]: <debug> [946684911.327915] [mm-sms-part.c:548] mm_sms_part_new_from_binary_pdu(): SMSC address parsed: '+4479XXXXXXXX'
> ModemManager[883]: <debug> [946684911.328159] [mm-sms-part.c:561] mm_sms_part_new_from_binary_pdu(): Deliver type PDU detected
> ModemManager[883]: <debug> [946684911.328525] [mm-sms-part.c:622] mm_sms_part_new_from_binary_pdu(): Number parsed: 'T-Mobile'
> ModemManager[883]: <debug> [946684911.328769] [mm-sms-part.c:722] mm_sms_part_new_from_binary_pdu(): PID: 0
> ModemManager[883]: <debug> [946684911.328952] [mm-sms-part.c:733] mm_sms_part_new_from_binary_pdu(): user data encoding is GSM7
> ModemManager[883]: <debug> [946684911.329166] [mm-sms-part.c:761] mm_sms_part_new_from_binary_pdu(): user data length: 160 elements
> ModemManager[883]: <debug> [946684911.329349] [mm-sms-part.c:767] mm_sms_part_new_from_binary_pdu(): user data length: 140 bytes
> ModemManager[883]: <debug> [946684911.329563] [mm-sms-part.c:840] mm_sms_part_new_from_binary_pdu(): Decoding SMS text with '152' elements
> ModemManager[883]: <debug> [946684911.329746] [mm-sms-part.c:244] sms_decode_text(): Converting SMS part text from GSM7 to UTF8...
> ModemManager[883]: <debug> [946684911.330112] [mm-sms-part.c:247] sms_decode_text(): Got UTF-8 text: 'NEW from T-Mobile. We've created Smart Packs to give you loads more mins, texts and data. £10 gets you £78 worth of calls and texts (that's 100 mins and'
> ModemManager[883]: <debug> [946684911.330326] [mm-broadband-modem.c:5137] sms_pdu_part_list_ready(): Correctly parsed PDU (0)
> ModemManager[883]: <debug> [946684911.330661] [mm-sms-list.c:369] mm_sms_list_take_part(): SMS part at 'sm/0' is from a multipart SMS (reference: '12969', sequence: '1')
> ModemManager[883]: <debug> [946684911.335453] [mm-iface-modem-messaging.c:500] sms_added(): Added received SMS at '/org/freedesktop/ModemManager1/SMS/0'
> ModemManager[883]: <debug> [946684911.342197] [mm-sms-part.c:519] mm_sms_part_new_from_binary_pdu(): Parsing PDU (1)...
> ModemManager[883]: <debug> [946684911.342716] [mm-sms-part.c:548] mm_sms_part_new_from_binary_pdu(): SMSC address parsed: '+4479XXXXXXXX '
> ModemManager[883]: <debug> [946684911.342960] [mm-sms-part.c:561] mm_sms_part_new_from_binary_pdu(): Deliver type PDU detected
> ModemManager[883]: <debug> [946684911.343235] [mm-sms-part.c:622] mm_sms_part_new_from_binary_pdu(): Number parsed: 'T-Mobile'
> ModemManager[883]: <debug> [946684911.679020] [mm-sms-part.c:722] mm_sms_part_new_from_binary_pdu(): PID: 0
> ModemManager[883]: <debug> [946684911.679233] [mm-sms-part.c:733] mm_sms_part_new_from_binary_pdu(): user data encoding is GSM7
> ModemManager[883]: <debug> [946684911.679447] [mm-sms-part.c:761] mm_sms_part_new_from_binary_pdu(): user data length: 147 elements
> ModemManager[883]: <debug> [946684911.679630] [mm-sms-part.c:767] mm_sms_part_new_from_binary_pdu(): user data length: 129 bytes
> ModemManager[883]: <debug> [946684911.679813] [mm-sms-part.c:840] mm_sms_part_new_from_binary_pdu(): Decoding SMS text with '139' elements
> ModemManager[883]: <debug> [946684911.680057] [mm-sms-part.c:244] sms_decode_text(): Converting SMS part text from GSM7 to UTF8...
> ModemManager[883]: <debug> [946684911.680454] [mm-sms-part.c:247] sms_decode_text(): Got UTF-8 text: ' 400 texts) plus 1GB data for 30 days. Text SMART10 to 441 for free to buy a £10 pack now. Find out more here http://m.t-mobile.co.uk/smart'
> ModemManager[883]: <debug> [946684911.680668] [mm-broadband-modem.c:5137] sms_pdu_part_list_ready(): Correctly parsed PDU (1)
> ModemManager[883]: <debug> [946684911.681034] [mm-sms-list.c:369] mm_sms_list_take_part(): SMS part at 'sm/1' is from a multipart SMS (reference: '12969', sequence: '2')
> ModemManager[883]: <debug> [946684911.683384] [mm-sms-part.c:519] mm_sms_part_new_from_binary_pdu(): Parsing PDU (2)...
> ModemManager[883]: <debug> [946684911.683750] [mm-sms-part.c:548] mm_sms_part_new_from_binary_pdu(): SMSC address parsed: '+4479XXXXXXXX '
> ModemManager[883]: <debug> [946684911.683964] [mm-sms-part.c:561] mm_sms_part_new_from_binary_pdu(): Deliver type PDU detected
> ModemManager[883]: <debug> [946684911.684177] [mm-sms-part.c:622] mm_sms_part_new_from_binary_pdu(): Number parsed: '70800'
> ModemManager[883]: <debug> [946684911.684391] [mm-sms-part.c:722] mm_sms_part_new_from_binary_pdu(): PID: 0
> ModemManager[883]: <debug> [946684911.684604] [mm-sms-part.c:733] mm_sms_part_new_from_binary_pdu(): user data encoding is GSM7
> ModemManager[883]: <debug> [946684911.684787] [mm-sms-part.c:761] mm_sms_part_new_from_binary_pdu(): user data length: 160 elements
> ModemManager[883]: <debug> [946684911.684971] [mm-sms-part.c:767] mm_sms_part_new_from_binary_pdu(): user data length: 140 bytes
> ModemManager[883]: <debug> [946684911.685184] [mm-sms-part.c:840] mm_sms_part_new_from_binary_pdu(): Decoding SMS text with '152' elements
> ModemManager[883]: <debug> [946684911.685367] [mm-sms-part.c:244] sms_decode_text(): Converting SMS part text from GSM7 to UTF8...
> ModemManager[883]: <debug> [946684911.685734] [mm-sms-part.c:247] sms_decode_text(): Got UTF-8 text: 'Typhoon Haiyan has left over four million children desperate for food, clean water and shelter. Together, EE and UNICEF are helping them. We really need'
> ModemManager[883]: <debug> [946684911.686069] [mm-broadband-modem.c:5137] sms_pdu_part_list_ready(): Correctly parsed PDU (2)
> ModemManager[883]: <debug> [946684911.686344] [mm-sms-list.c:369] mm_sms_list_take_part(): SMS part at 'sm/2' is from a multipart SMS (reference: '34802', sequence: '1')
> ModemManager[883]: <debug> [946684911.688511] [mm-iface-modem-messaging.c:500] sms_added(): Added received SMS at '/org/freedesktop/ModemManager1/SMS/1'
> ModemManager[883]: <debug> [946684911.694797] [mm-sms-part.c:519] mm_sms_part_new_from_binary_pdu(): Parsing PDU (3)...
> ModemManager[883]: <debug> [946684911.695255] [mm-sms-part.c:548] mm_sms_part_new_from_binary_pdu(): SMSC address parsed: '+4479XXXXXXXX'
> ModemManager[883]: <debug> [946684911.695499] [mm-sms-part.c:561] mm_sms_part_new_from_binary_pdu(): Deliver type PDU detected
> ModemManager[883]: <debug> [946684911.695835] [mm-sms-part.c:622] mm_sms_part_new_from_binary_pdu(): Number parsed: '70800'
> ModemManager[883]: <debug> [946684911.696079] [mm-sms-part.c:722] mm_sms_part_new_from_binary_pdu(): PID: 0
> ModemManager[883]: <debug> [946684911.696262] [mm-sms-part.c:733] mm_sms_part_new_from_binary_pdu(): user data encoding is GSM7
> ModemManager[883]: <debug> [946684912.032657] [mm-sms-part.c:761] mm_sms_part_new_from_binary_pdu(): user data length: 158 elements
> ModemManager[883]: <debug> [946684912.032902] [mm-sms-part.c:767] mm_sms_part_new_from_binary_pdu(): user data length: 139 bytes
> ModemManager[883]: <debug> [946684912.033115] [mm-sms-part.c:840] mm_sms_part_new_from_binary_pdu(): Decoding SMS text with '150' elements
> ModemManager[883]: <debug> [946684912.033329] [mm-sms-part.c:244] sms_decode_text(): Converting SMS part text from GSM7 to UTF8...
> ModemManager[883]: <debug> [946684912.033695] [mm-sms-part.c:247] sms_decode_text(): Got UTF-8 text: ' your help too. Please reply YES to donate £5 for emergency supplies. You'll give £5 from your credit and whatever you usually pay for a text message.'
> ModemManager[883]: <debug> [946684912.033939] [mm-broadband-modem.c:5137] sms_pdu_part_list_ready(): Correctly parsed PDU (3)
> ModemManager[883]: <debug> [946684912.034275] [mm-sms-list.c:369] mm_sms_list_take_part(): SMS part at 'sm/3' is from a multipart SMS (reference: '34802', sequence: '2')
> ModemManager[883]: <debug> [946684912.036411] [mm-sms-part.c:519] mm_sms_part_new_from_binary_pdu(): Parsing PDU (4)...
> ModemManager[883]: <debug> [946684912.036777] [mm-sms-part.c:548] mm_sms_part_new_from_binary_pdu(): SMSC address parsed: '+4479XXXXXXXX'
> ModemManager[883]: <debug> [946684912.037021] [mm-sms-part.c:561] mm_sms_part_new_from_binary_pdu(): Deliver type PDU detected
> ModemManager[883]: <debug> [946684912.037266] [mm-sms-part.c:622] mm_sms_part_new_from_binary_pdu(): Number parsed: '-EE-'
> ModemManager[883]: <debug> [946684912.037479] [mm-sms-part.c:722] mm_sms_part_new_from_binary_pdu(): PID: 0
> ModemManager[883]: <debug> [946684912.037662] [mm-sms-part.c:733] mm_sms_part_new_from_binary_pdu(): user data encoding is GSM7
> ModemManager[883]: <debug> [946684912.037906] [mm-sms-part.c:761] mm_sms_part_new_from_binary_pdu(): user data length: 119 elements
> ModemManager[883]: <debug> [946684912.038120] [mm-sms-part.c:767] mm_sms_part_new_from_binary_pdu(): user data length: 105 bytes
> ModemManager[883]: <debug> [946684912.038303] [mm-sms-part.c:840] mm_sms_part_new_from_binary_pdu(): Decoding SMS text with '119' elements
> ModemManager[883]: <debug> [946684912.038486] [mm-sms-part.c:244] sms_decode_text(): Converting SMS part text from GSM7 to UTF8...
> ModemManager[883]: <debug> [946684912.038822] [mm-sms-part.c:247] sms_decode_text(): Got UTF-8 text: 'Get £5 FREE credit! Don't miss out, simply make a call by 27 Nov and we'll add £5 FREE credit to your account by 30 Nov'
> ModemManager[883]: <debug> [946684912.039005] [mm-broadband-modem.c:5137] sms_pdu_part_list_ready(): Correctly parsed PDU (4)
> ModemManager[883]: <debug> [946684912.039310] [mm-sms-list.c:382] mm_sms_list_take_part(): SMS part at 'sm/4' is from a singlepart SMS
> ModemManager[883]: <debug> [946684912.042545] [mm-iface-modem-messaging.c:500] sms_added(): Added received SMS at '/org/freedesktop/ModemManager1/SMS/2'
> ModemManager[883]: <debug> [946684912.048862] [mm-broadband-modem.c:5202] modem_messaging_load_initial_sms_parts(): Listing SMS parts in storage 'sr'
> ModemManager[883]: <debug> [946684912.049473] [mm-broadband-modem.c:4387] mm_broadband_modem_lock_sms_storages(): Locking SMS storages to: mem1 (SR), mem2 (none)...
> ModemManager[883]: <debug> [946684912.049778] [mm-serial-port.c:926] mm_serial_port_open(): (ttyUSB3) device open count is 3 (open)
> ModemManager[883]: <debug> [946684912.050236] [mm-serial-port.c:966] mm_serial_port_close(): (ttyUSB3) device open count is 2 (close)
> ModemManager[883]: <debug> [946684912.064701] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): --> 'AT+CPMS="SR"<CR>'
> ModemManager[883]: <debug> [946684912.085209] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): <-- '<CR><LF>+CPMS: 0,0,0,23,0,23<CR><LF><CR><LF>OK<CR><LF>'
> ModemManager[883]: <debug> [946684912.086307] [mm-serial-port.c:926] mm_serial_port_open(): (ttyUSB3) device open count is 3 (open)
> ModemManager[883]: <debug> [946684912.086857] [mm-serial-port.c:966] mm_serial_port_close(): (ttyUSB3) device open count is 2 (close)
> ModemManager[883]: <debug> [946684912.087375] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): --> 'AT+CMGL=4<CR>'
> ModemManager[883]: <debug> [946684912.101444] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): <-- '<CR><LF>OK<CR><LF>'
> ModemManager[883]: <debug> [946684912.102573] [mm-broadband-modem.c:4799] set_messaging_unsolicited_events_handlers(): (ttyUSB3) Setting messaging unsolicited events handlers
> ModemManager[883]: <debug> [946684912.438419] [mm-serial-port.c:966] mm_serial_port_close(): (ttyUSB3) device open count is 1 (close)
> ModemManager[883]: <debug> [946684912.438968] [mm-serial-port.c:926] mm_serial_port_open(): (ttyUSB3) device open count is 2 (open)
> ModemManager[883]: <debug> [946684912.439548] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): --> 'AT+CNMI=2,1,2,1,0<CR>'
> ModemManager[883]: <debug> [946684912.466038] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): <-- '<CR><LF>+CMS ERROR: 303<CR><LF>'
> ModemManager[883]: <debug> [946684912.467380] [mm-serial-parsers.c:316] mm_serial_parser_v1_parse(): Got failure code 303: Operation not supported
> ModemManager[883]: <debug> [946684912.468113] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): --> 'AT+CNMI=2,1,2,2,0<CR>'
> ModemManager[883]: <debug> [946684912.499424] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): <-- '<CR><LF>OK<CR><LF>'
> ModemManager[883]: <debug> [946684912.500370] [mm-serial-port.c:966] mm_serial_port_close(): (ttyUSB3) device open count is 1 (close)
> ModemManager[883]: <info> [946684912.500858] [mm-broadband-modem.c:7469] enabling_step(): Modem fully enabled...
> ModemManager[883]: <info> [946684912.501285] [mm-iface-modem.c:1176] mm_iface_modem_update_state(): Modem /org/freedesktop/ModemManager1/Modem/0: state changed (enabling -> registered)
> ModemManager[883]: <debug> [946684912.518009] [mm-iface-modem.c:1100] periodic_signal_quality_check_enable(): Periodic signal quality checks enabled
> ModemManager[883]: <debug> [946684912.519169] [huawei/mm-broadband-modem-huawei.c:1416] modem_load_signal_quality(): loading signal quality...
> ModemManager[883]: <debug> [946684912.519718] [mm-broadband-modem.c:1592] modem_load_signal_quality(): loading signal quality...
> ModemManager[883]: <debug> [946684912.520084] [mm-serial-port.c:926] mm_serial_port_open(): (ttyUSB3) device open count is 2 (open)
> ModemManager[883]: <debug> [946684912.520481] [mm-iface-modem.c:839] periodic_access_technologies_check_enable(): Periodic access technology checks enabled
> ModemManager[883]: <debug> [946684912.520786] [huawei/mm-broadband-modem-huawei.c:252] load_access_technologies(): loading access technology (huawei)...
> ModemManager[883]: <debug> [946684912.521030] [mm-serial-port.c:926] mm_serial_port_open(): (ttyUSB3) device open count is 3 (open)
> ModemManager[883]: <debug> [946684912.527286] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): --> 'AT+CIND?<CR>'
> ModemManager[883]: <debug> [946684912.542972] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): <-- '<CR><LF>+CIND: 5,1,1,0,0,1,1,0<CR><LF><CR><LF>OK<CR><LF>'
> ModemManager[883]: <debug> [946684912.544407] [mm-serial-port.c:966] mm_serial_port_close(): (ttyUSB3) device open count is 2 (close)
> ModemManager[883]: <info> [946684912.545963] [mm-iface-modem.c:971] update_signal_quality(): Modem /org/freedesktop/ModemManager1/Modem/0: signal quality updated (20)
> ModemManager[883]: <debug> [946684912.553501] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): --> 'AT^SYSINFO<CR>'
> ModemManager[883]: <debug> [946684912.569462] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): <-- '<CR><LF>^SYSINFO:2,3,0,5,1,,4<CR><LF><CR><LF>OK<CR><LF>'
> ModemManager[883]: <debug> [946684912.570927] [huawei/mm-broadband-modem-huawei.c:239] load_access_technologies_finish(): Access Technology: 'umts'
> ModemManager[883]: <info> [946684912.571964] [mm-iface-modem.c:723] mm_iface_modem_update_access_technologies(): Modem /org/freedesktop/ModemManager1/Modem/0: access technology changed (unknown -> umts)
> ModemManager[883]: <debug> [946684912.572422] [mm-serial-port.c:966] mm_serial_port_close(): (ttyUSB3) device open count is 1 (close)
> ModemManager[883]: <debug> [946684913.606602] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): <-- '<CR><LF>^RSSI:3<CR><LF>'
> ModemManager[883]: <debug> [946684913.607700] [huawei/mm-broadband-modem-huawei.c:851] huawei_signal_changed(): 3GPP signal quality: 9
> ModemManager[883]: <info> [946684913.608890] [mm-iface-modem.c:971] update_signal_quality(): Modem /org/freedesktop/ModemManager1/Modem/0: signal quality updated (9)
> ModemManager[883]: <debug> [946684913.609867] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): <-- '<CR><LF>^CSNR:-104,-10<CR><LF>'
> ModemManager[883]: <info> [946684919.997318] [mm-iface-modem-simple.c:778] connect_auth_ready(): Simple connect started...
> ModemManager[883]: <info> [946684919.998325] [mm-iface-modem-simple.c:551] connection_step(): Simple connect state (4/10): Wait to get fully enabled
> ModemManager[883]: <info> [946684919.999027] [mm-iface-modem-simple.c:563] connection_step(): Simple connect state (5/10): Allowed mode
> ModemManager[883]: <debug> [946684920.004765] [mm-iface-modem-simple.c:311] set_allowed_modes_ready(): Will wait to settle down after updating allowed modes
> ModemManager[883]: <info> [946684922.192021] [mm-iface-modem-simple.c:586] connection_step(): Simple connect state (6/10): Bands
> ModemManager[883]: <info> [946684922.192387] [mm-iface-modem-simple.c:615] connection_step(): Simple connect state (7/10): Register
> ModemManager[883]: <debug> [946684922.192875] [mm-iface-modem-3gpp.c:374] mm_iface_modem_3gpp_register_in_network(): Already registered in network '23433', automatic registration not launched...
> ModemManager[883]: <info> [946684922.193424] [mm-iface-modem-simple.c:638] connection_step(): Simple connect state (8/10): Bearer
> ModemManager[883]: <debug> [946684922.193668] [mm-iface-modem-simple.c:658] connection_step(): Creating new bearer...
> ModemManager[883]: <debug> [946684922.193882] [mm-broadband-modem.c:264] modem_create_bearer(): Creating Broadband bearer in broadband modem
> ModemManager[883]: <debug> [946684922.202244] [mm-serial-port.c:926] mm_serial_port_open(): (ttyUSB3) device open count is 2 (open)
> ModemManager[883]: <debug> [946684922.202946] [mm-serial-port.c:966] mm_serial_port_close(): (ttyUSB3) device open count is 1 (close)
> ModemManager[883]: <debug> [946684922.204258] [mm-broadband-modem.c:225] modem_create_bearer_finish(): New bearer created at DBus path '/org/freedesktop/ModemManager1/Bearer/0'
> ModemManager[883]: <info> [946684922.205021] [mm-iface-modem-simple.c:720] connection_step(): Simple connect state (9/10): Connect
> ModemManager[883]: <debug> [946684922.205448] [mm-bearer.c:517] mm_bearer_connect(): Connecting bearer '/org/freedesktop/ModemManager1/Bearer/0'
> ModemManager[883]: <info> [946684922.206028] [mm-iface-modem.c:1176] mm_iface_modem_update_state(): Modem /org/freedesktop/ModemManager1/Modem/0: state changed (registered -> connecting)
> ModemManager[883]: <info> [946684922.219914] [mm-serial-port.c:857] mm_serial_port_open(): (ttyUSB0) opening serial port...
> ModemManager[883]: <warn> [946684922.223209] [mm-serial-port.c:414] real_config_fd(): (ttyUSB0): port attributes not fully set
> ModemManager[883]: <debug> [946684922.223820] [mm-serial-port.c:926] mm_serial_port_open(): (ttyUSB0) device open count is 1 (open)
> ModemManager[883]: <debug> [946684922.224308] [mm-broadband-bearer.c:999] connect_3gpp(): Looking for best CID...
> ModemManager[883]: <debug> [946684922.224766] [mm-serial-port.c:926] mm_serial_port_open(): (ttyUSB3) device open count is 2 (open)
> ModemManager[883]: <debug> [946684922.225468] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): --> 'AT+CGDCONT?<CR>'
> ModemManager[883]: <debug> [946684922.243321] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): <-- '<CR><LF>+CGDCONT: 1,"IP","internet","",0,0<CR><LF>+CGDCONT: 2,"IP","general.t-mobile.uk","",0,0<CR><LF><CR><LF>OK<CR><LF>'
> ModemManager[883]: <debug> [946684922.244846] [mm-broadband-bearer.c:921] parse_pdp_list(): Found '2' PDP contexts
> ModemManager[883]: <debug> [946684922.245274] [mm-broadband-bearer.c:928] parse_pdp_list(): PDP context [cid=1] [type='ipv4'] [apn='internet']
> ModemManager[883]: <debug> [946684922.245518] [mm-broadband-bearer.c:928] parse_pdp_list(): PDP context [cid=2] [type='ipv4'] [apn='general.t-mobile.uk']
> ModemManager[883]: <debug> [946684922.245762] [mm-broadband-bearer.c:949] parse_pdp_list(): Found PDP context with CID 2 and PDP type ipv4 for APN 'general.t-mobile.uk'
> ModemManager[883]: <debug> [946684922.246220] [mm-serial-port.c:926] mm_serial_port_open(): (ttyUSB3) device open count is 3 (open)
> ModemManager[883]: <debug> [946684922.246678] [mm-serial-port.c:966] mm_serial_port_close(): (ttyUSB3) device open count is 2 (close)
> ModemManager[883]: <debug> [946684922.247196] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): --> 'AT+CGDCONT=2,"IP","general.t-mobile.uk"<CR>'
> ModemManager[883]: <debug> [946684922.313023] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): <-- '<CR><LF>OK<CR><LF>'
> ModemManager[883]: <debug> [946684922.313969] [mm-serial-port.c:926] mm_serial_port_open(): (ttyUSB3) device open count is 3 (open)
> ModemManager[883]: <debug> [946684922.314396] [mm-serial-port.c:966] mm_serial_port_close(): (ttyUSB3) device open count is 2 (close)
> ModemManager[883]: <debug> [946684922.314915] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): --> 'ATD*99***2#<CR>'
> ModemManager[883]: <debug> [946684922.335880] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): <-- '<CR><LF>CONNECT 28800000<CR><LF>'
> ModemManager[883]: <debug> [946684922.337406] [mm-serial-port.c:966] mm_serial_port_close(): (ttyUSB3) device open count is 1 (close)
> ModemManager[883]: <debug> [946684922.338291] [mm-port.c:149] mm_port_set_connected(): (ttyUSB0): port now connected
> ModemManager[883]: <debug> [946684922.338932] [mm-bearer.c:413] connect_ready(): Connected bearer '/org/freedesktop/ModemManager1/Bearer/0'
> ModemManager[883]: <info> [946684922.340885] [mm-iface-modem.c:1176] mm_iface_modem_update_state(): Modem /org/freedesktop/ModemManager1/Modem/0: state changed (connecting -> connected)
> ModemManager[883]: <info> [946684922.355045] [mm-iface-modem-simple.c:739] connection_step(): Simple connect state (10/10): All done
> ModemManager[883]: <debug> [946684922.524632] [mm-bearer.c:687] mm_bearer_disconnect(): Disconnecting bearer '/org/freedesktop/ModemManager1/Bearer/0'
> ModemManager[883]: <info> [946684922.525639] [mm-iface-modem.c:1176] mm_iface_modem_update_state(): Modem /org/freedesktop/ModemManager1/Modem/0: state changed (connected -> disconnecting)
> ModemManager[883]: <debug> [946684922.551365] [mm-broadband-bearer.c:1562] disconnect_3gpp(): Flash primary port...
> ModemManager[883]: <debug> [946684923.558964] [mm-broadband-bearer.c:1481] primary_flash_3gpp_ready(): Sending PDP context deactivation in primary port...
> ModemManager[883]: <debug> [946684923.559300] [mm-serial-port.c:926] mm_serial_port_open(): (ttyUSB3) device open count is 2 (open)
> ModemManager[883]: <debug> [946684923.559818] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): --> 'AT+CGACT=0,2<CR>'
> ModemManager[883]: <debug> [946684927.193699] [mm-broadband-bearer.c:1433] cgact_primary_ready(): PDP context deactivation failed (not fatal): Serial command timed out
> ModemManager[883]: <debug> [946684927.194126] [mm-serial-port.c:966] mm_serial_port_close(): (ttyUSB3) device open count is 1 (close)
> ModemManager[883]: <debug> [946684927.194615] [mm-serial-port.c:966] mm_serial_port_close(): (ttyUSB0) device open count is 0 (close)
> ModemManager[883]: <info> [946684927.194798] [mm-serial-port.c:982] mm_serial_port_close(): (ttyUSB0) closing serial port...
> ModemManager[883]: <debug> [946684927.195011] [mm-port.c:149] mm_port_set_connected(): (ttyUSB0): port now disconnected
> ModemManager[883]: <info> [946684927.197148] [mm-serial-port.c:1014] mm_serial_port_close(): (ttyUSB0) serial port closed
> ModemManager[883]: <debug> [946684927.197758] [mm-bearer.c:620] disconnect_ready(): Disconnected bearer '/org/freedesktop/ModemManager1/Bearer/0'
> ModemManager[883]: <info> [946684927.198399] [mm-iface-modem.c:1176] mm_iface_modem_update_state(): Modem /org/freedesktop/ModemManager1/Modem/0: state changed (disconnecting -> registered)
> ModemManager[883]: <debug> [946684943.204961] [huawei/mm-broadband-modem-huawei.c:1416] modem_load_signal_quality(): loading signal quality...
> ModemManager[883]: <debug> [946684943.205479] [mm-broadband-modem.c:1592] modem_load_signal_quality(): loading signal quality...
> ModemManager[883]: <debug> [946684943.205723] [mm-serial-port.c:926] mm_serial_port_open(): (ttyUSB3) device open count is 2 (open)
> ModemManager[883]: <debug> [946684943.206029] [huawei/mm-broadband-modem-huawei.c:252] load_access_technologies(): loading access technology (huawei)...
> ModemManager[883]: <debug> [946684943.206181] [mm-serial-port.c:926] mm_serial_port_open(): (ttyUSB3) device open count is 3 (open)
> ModemManager[883]: <debug> [946684943.206517] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): --> 'AT+CIND?<CR>'
> ModemManager[883]: <debug> [946684946.192448] [mm-serial-port.c:926] mm_serial_port_open(): (ttyUSB3) device open count is 4 (open)
> ModemManager[883]: <debug> [946684946.192937] [mm-serial-port.c:966] mm_serial_port_close(): (ttyUSB3) device open count is 3 (close)
> ModemManager[883]: <debug> [946684946.193394] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): --> 'AT^SYSINFO<CR>'
> ModemManager[883]: <debug> [946684949.192937] [mm-iface-modem.c:761] access_technologies_check_ready(): Couldn't refresh access technologies: 'Serial command timed out'
>
>
> If there is anything I can do I am prepared to change the driver to suit the EM820W modem. I have the AT commands document and datasheet.
>
> Kind Regards
> Marc
>
>
> -----Original Message-----
> From: Aleksander Morgado [mailto:aleksander at lanedo.com]
> Sent: 09 December 2013 11:35
> To: Marc Murphy; modemmanager-devel at lists.freedesktop.org
> Subject: Re: Understanding Modem Manager
>
> Hey Marc,
>
> > I have a platform that has no GUI so I am trying to initialize a couple of 3G modems (Huawei EM820W and Sierra Wireless MC8705) to use as data connections when away from the local network.
> >
> > I have downloaded and compiled ModemManager and it seems to be working well with the daemon, the cards can be detected and various parameters can be extracted using the mmcli app.
> >
> > I am having some trouble in actually getting a useable connection.
> > Previously with one of the cards (Sierra Wireless MC8705) I could manually setup with the AT commands, connect and get a valid IP address with all the dns and routing being setup with dhclient.
> >
> > I would like to have the same result but using ModemManager, if it is possible. Here is some debug about what I am attempting to do:
> >
> > # mmcli -m 0 --list-bearers
> >
> > No bearers were found
> > # mmcli -m 0
> >
> > /org/freedesktop/ModemManager1/Modem/0 (device id
> > '61d98ebe0deeb14a83d951229303f0e8a245cd35')
> > -------------------------
> > Hardware | manufacturer: 'huawei'
> > | model: 'EM820W'
> > | revision: '11.809.05.80.00'
> > | capabilities: 'gsm-umts'
> > | current: 'gsm-umts'
> > | equipment id: '3542830400XXXXX'
> > -------------------------
> > System | device: '/sys/devices/platform/usbhs_omap/ehci-omap.0/usb1/1-1/1-1.1'
> > | drivers: 'option1'
> > | plugin: 'Huawei'
> > | primary port: 'ttyUSB3'
> > -------------------------
> > Numbers | own : '+4475398XXXXX'
> > -------------------------
> > Status | lock: 'none'
> > | unlock retries: 'sim-pin (3), sim-pin2 (3), sim-puk (10), sim-puk2 (10)'
> > | state: 'disabled'
> > | access tech: 'unknown'
> > | signal quality: '0' (cached)
> > -------------------------
> > Modes | supported: '2g, 3g'
> > | allowed: '2g, 3g'
> > | preferred: 'none'
> > -------------------------
> > Bands | supported: 'unknown'
> > | current: 'unknown'
> > -------------------------
> > 3GPP | imei: '3542830400XXXXX'
> > | enabled locks: 'none'
> > | operator id: 'unknown'
> > | operator name: 'unknown'
> > | registration: 'unknown'
> > -------------------------
> > SIM | path: '/org/freedesktop/ModemManager1/SIM/0'
> >
> > So it looks like the modem is detected. I then tried to connect by
> > creating the bearer info (I'm using tmobile in the UK); # mmcli -m 0
> > --create-bearer="apn=general.t-mobile.uk,user=t-mobile,password=tm,
> > number=*99#"
> > Successfully created new bearer in modem:
> > /org/freedesktop/ModemManager1/Bearer/2
>
> No need to pass the "number" parameter there; won't be used.
>
> >
> > # mmcli -m 0 -c -b /org/freedesktop/ModemManager1/Bearer/2
>
>
> You shouldn't pass "-m 0" and then "-b /.../"; just "mmcli -b 2 -c"
> should do it (i.e. only specify the bearer).
>
>
> > ModemManager[805]: <info> Modem
> > /org/freedesktop/ModemManager1/Modem/0: state changed (registered ->
> > connecting)
> > ModemManager[805]: <info> (ttyUSB0) opening serial port...
> > ModemManager[805]: <warn> (ttyUSB0): port attributes not fully set
> > ModemManager[805]: <warn> Couldn't initialize PDP context with our APN: 'Serial command timed out'
> > ModemManager[805]: <info> (ttyUSB0) closing serial port...
> > ModemManager[805]: <info> (ttyUSB0) serial port closed
> > ModemManager[805]: <info> Modem
> > /org/freedesktop/ModemManager1/Modem/0: state changed (connecting ->
> > registered)
> > error: couldn't connect the bearer: 'GDBus.Error:org.freedesktop.ModemManager1.Error.Serial.ResponseTimeout: Serial command timed out'
> >
>
> Oh well;.... Care to run ModemManager with --debug to see what is really happening?
>
>
>
> > Which looked like it failed but the status shows
> >
> > # mmcli -m 0 --simple-status
> >
> > /org/freedesktop/ModemManager1/Modem/0
> > -------------------------
> > Status | state: 'registered'
> > | signal quality: '6' (cached)
> > | bands: 'unknown'
> > | access tech: 'umts'
> > -------------------------
> > 3GPP | registration: 'home'
> > | operator code: '23433'
> > | operator name: 'Orange'
> >
>
> Yeah, it failed. It's only registered, not connected.
>
>
> > So then decided to try the example with simple-connect
> >
> > # mmcli -m 0 --simple-connect="pin=1234,apn=internet"
> > ModemManager[805]: <info> Simple connect started...
> > ModemManager[805]: <info> Simple connect state (4/10): Wait to get
> > fully enabled
> > ModemManager[805]: <info> Simple connect state (5/10): Allowed mode
> > ModemManager[805]: <info> Simple connect state (6/10): Bands
> > ModemManager[805]: <info> Simple connect state (7/10): Register
> > ModemManager[805]: <info> Simple connect state (8/10): Bearer
> > ModemManager[805]: <info> Simple connect state (9/10): Connect
> > ModemManager[805]: <info> Modem
> > /org/freedesktop/ModemManager1/Modem/0: state changed (registered ->
> > connecting)
> > ModemManager[805]: <info> (ttyUSB0) opening serial port...
> > ModemManager[805]: <warn> (ttyUSB0): port attributes not fully set
> > ModemManager[805]: <info> Modem
> > /org/freedesktop/ModemManager1/Modem/0: state changed (connecting ->
> > connected)
> > ModemManager[805]: <info> Simple connect state (10/10): All done
> > successfully connected the modem
> >
> > That seemed to work ???
>
>
> Yeah, it worked.
>
>
> > # mmcli -m 0 --simple-status
> >
> > /org/freedesktop/ModemManager1/Modem/0
> > -------------------------
> > Status | state: 'registered'
> > | signal quality: '6' (cached)
> > | bands: 'unknown'
> > | access tech: 'umts'
> > -------------------------
> > 3GPP | registration: 'home'
> > | operator code: '23433'
> > | operator name: 'Orange'
> >
>
> Hum... "state" should have said "connected" there.
>
>
> > So how do I reliably get to connect and then generate a wwan0 network interface ? Do I need to use NetworkManager to obtain an IP interface to allow for routing ?
> >
>
>
> ModemManager will get the interface connected. Once it is connected, the modem will expose in the "bearer info" (e.g. mmcli -b 2) the "IP setup"
> needed in the 'data' interface. This may be DHCP, or static or PPP. If DHCP is required in the net interface, you'll need to bring the interface up (e.g. ifup) and then run a DHCP client in the interface (e.g. dhclient). If you are using NetworkManager, it will handle all that for you, including the case where the needed setup is PPP or a static IP config.
>
>
>
> > As you can guess I am in the early learning stages with this. Once I get the IP connection sorted I would like to look at the gps. This also isn't working when I try....
> >
> > # mmcli -m 0 --location-status
> >
> > /org/freedesktop/ModemManager1/Modem/0
> > ----------------------------
> > Location | capabilities: '3gpp-lac-ci'
> > | enabled: '3gpp-lac-ci'
> > | signals: 'no'
> >
> > # mmcli -m 0 --location-get-3gpp
> > error: couldn't get 3GPP-based location from the modem: 'not available'
> >
> > # mmcli -m 0 --location-enable-gps-nmea
> > error: couldn't setup location gathering: 'GDBus.Error:org.freedesktop.ModemManager1.Error.Core.Unsupported: Cannot enable unsupported location sources: 'gps-nmea''
> >
> > But the specs for the modem state that it can do NMEA gps?? Confusing.
> >
>
> No GPS location capabilities shown means that ModemManager doesn't know how to manage them. In your case, the Huawei plugin in ModemManager knows nothing about GPS.
>
> --
> Aleksander
> _______________________________________________
> ModemManager-devel mailing list
> ModemManager-devel at lists.freedesktop.org
> http://lists.freedesktop.org/mailman/listinfo/modemmanager-devel
More information about the ModemManager-devel
mailing list