Fetching signal quality during data connection?

Thu Jan 26 15:21:55 UTC 2017

Log as follows (--debug --log-level=DEBUG). '--connect' done many minutes after the '--enable' and '--create-bearer'
I can rebuild, if you'd like me to add in any further debug messages.

Jan 26 15:15:54 wg2xx-tx6s daemon.info ModemManager[867]: <debug> [1485443754.457980] [src/mm-broadband-modem.c:2003] modem_load_signal_quality(): loading signal quality...
Jan 26 15:15:54 wg2xx-tx6s daemon.info ModemManager[867]: <debug> [1485443754.458270] [src/mm-port-serial.c:1290] mm_port_serial_open(): (ttyMux0) device open count is 2 (open)
Jan 26 15:15:54 wg2xx-tx6s daemon.info ModemManager[867]: <debug> [1485443754.458657] [src/mm-port-serial-at.c:459] debug_log(): (ttyMux0): --> 'AT+CIND?<CR>'
Jan 26 15:15:54 wg2xx-tx6s daemon.info ModemManager[867]: <debug> [1485443754.532816] [src/mm-port-serial-at.c:459] debug_log(): (ttyMux0): <-- '<CR><LF>+CIND: 5,99,1,0,0,0,0,0,2<CR><LF><CR><LF>OK<CR><LF>'
Jan 26 15:15:54 wg2xx-tx6s daemon.info ModemManager[867]: <debug> [1485443754.533657] [src/mm-port-serial.c:1290] mm_port_serial_open(): (ttyMux0) device open count is 3 (open)
Jan 26 15:15:54 wg2xx-tx6s daemon.info ModemManager[867]: <debug> [1485443754.534053] [src/mm-port-serial.c:1347] _close_internal(): (ttyMux0) device open count is 2 (close)
Jan 26 15:15:54 wg2xx-tx6s daemon.info ModemManager[867]: <debug> [1485443754.534426] [src/mm-port-serial-at.c:459] debug_log(): (ttyMux0): --> 'AT+CSQ<CR>'
Jan 26 15:15:54 wg2xx-tx6s daemon.info ModemManager[867]: <debug> [1485443754.577412] [src/mm-port-serial-at.c:459] debug_log(): (ttyMux0): <-- '<CR><LF>+CSQ: 12,99<CR><LF><CR><LF>OK<CR><LF>'
Jan 26 15:15:54 wg2xx-tx6s daemon.info ModemManager[867]: <debug> [1485443754.578057] [src/mm-port-serial.c:1347] _close_internal(): (ttyMux0) device open count is 1 (close)
Jan 26 15:15:54 wg2xx-tx6s daemon.info ModemManager[867]: <debug> [1485443754.578763] [src/mm-iface-modem.c:1204] update_signal_quality(): Modem /org/freedesktop/ModemManager1/Modem/0: signal quality updated (38)
Jan 26 15:16:00 wg2xx-tx6s daemon.info ModemManager[867]: <debug> [1485443760.658971] [src/mm-base-bearer.c:703] mm_base_bearer_connect(): Connecting bearer '/org/freedesktop/ModemManager1/Bearer/0'
Jan 26 15:16:00 wg2xx-tx6s daemon.info ModemManager[867]: <info>  [1485443760.659290] [src/mm-iface-modem.c:1431] __iface_modem_update_state_internal(): Modem /org/freedesktop/ModemManager1/Modem/0: state changed (registered -> connecting)
Jan 26 15:16:00 wg2xx-tx6s daemon.info ModemManager[867]: <debug> [1485443760.661237] [src/mm-broadband-bearer.c:1254] connect(): Launching 3GPP connection attempt with APN 'mobile.o2.co.uk'
Jan 26 15:16:00 wg2xx-tx6s daemon.info ModemManager[867]: <debug> [1485443760.661470] [src/mm-broadband-bearer.c:177] detailed_connect_context_new(): No specific IP family requested, defaulting to ipv4
Jan 26 15:16:00 wg2xx-tx6s daemon.info ModemManager[867]: <debug> [1485443760.661577] [src/mm-broadband-bearer.c:1044] connect_3gpp(): Looking for best CID...
Jan 26 15:16:00 wg2xx-tx6s daemon.info ModemManager[867]: <debug> [1485443760.661740] [src/mm-port-serial.c:1290] mm_port_serial_open(): (ttyMux0) device open count is 2 (open)
Jan 26 15:16:00 wg2xx-tx6s daemon.info ModemManager[867]: <debug> [1485443760.662078] [src/mm-port-serial-at.c:459] debug_log(): (ttyMux0): --> 'AT+CGDCONT?<CR>'
Jan 26 15:16:00 wg2xx-tx6s daemon.info ModemManager[867]: <debug> [1485443760.719807] [src/mm-port-serial-at.c:459] debug_log(): (ttyMux0): <-- '<CR><LF>+CGDCONT: 1,"IP","mobile.o2.co.uk","",0,0<CR><LF><CR><LF>OK<CR><LF>'
Jan 26 15:16:00 wg2xx-tx6s daemon.info ModemManager[867]: <debug> [1485443760.720687] [src/mm-broadband-bearer.c:961] parse_pdp_list(): Found '1' PDP contexts
Jan 26 15:16:00 wg2xx-tx6s daemon.info ModemManager[867]: <debug> [1485443760.720945] [src/mm-broadband-bearer.c:970] parse_pdp_list():   PDP context [cid=1] [type='ipv4'] [apn='mobile.o2.co.uk']
Jan 26 15:16:00 wg2xx-tx6s daemon.info ModemManager[867]: <debug> [1485443760.721169] [src/mm-broadband-bearer.c:994] parse_pdp_list(): Found PDP context with CID 1 and PDP type ipv4 for APN 'mobile.o2.co.uk'
Jan 26 15:16:00 wg2xx-tx6s daemon.info ModemManager[867]: <debug> [1485443760.721445] [src/mm-port-serial.c:1290] mm_port_serial_open(): (ttyMux0) device open count is 3 (open)
Jan 26 15:16:00 wg2xx-tx6s daemon.info ModemManager[867]: <debug> [1485443760.721664] [src/mm-broadband-bearer.c:214] common_get_at_data_port(): Connection through a plain serial AT port (ttyMux0)
Jan 26 15:16:00 wg2xx-tx6s daemon.info ModemManager[867]: <debug> [1485443760.721961] [src/mm-port-serial.c:1290] mm_port_serial_open(): (ttyMux0) device open count is 4 (open)
Jan 26 15:16:00 wg2xx-tx6s daemon.info ModemManager[867]: <debug> [1485443760.722308] [src/mm-port-serial.c:1347] _close_internal(): (ttyMux0) device open count is 3 (close)
Jan 26 15:16:00 wg2xx-tx6s daemon.info ModemManager[867]: <debug> [1485443760.722678] [src/mm-port-serial-at.c:459] debug_log(): (ttyMux0): --> 'ATD*99***1#<CR>'
Jan 26 15:16:02 wg2xx-tx6s daemon.info ModemManager[867]: <debug> [1485443762.240256] [src/mm-port-serial-at.c:459] debug_log(): (ttyMux0): <-- '<CR><LF>CONNECT<CR><LF>~\255}#\192!}!}#} }9}"}&} }*} } }'}"}(}"}%}&\169\152\237.}#}%\194#}%}4\209~'
Jan 26 15:16:02 wg2xx-tx6s daemon.info ModemManager[867]: <debug> [1485443762.240985] [src/mm-port-serial.c:1347] _close_internal(): (ttyMux0) device open count is 2 (close)
Jan 26 15:16:02 wg2xx-tx6s daemon.info ModemManager[867]: <debug> [1485443762.241385] [src/mm-port.c:95] mm_port_set_connected(): (ttyMux0): port now connected
Jan 26 15:16:02 wg2xx-tx6s daemon.info ModemManager[867]: <debug> [1485443762.241610] [src/mm-base-bearer.c:601] connect_ready(): Connected bearer '/org/freedesktop/ModemManager1/Bearer/0'
Jan 26 15:16:02 wg2xx-tx6s daemon.info ModemManager[867]: <info>  [1485443762.242925] [src/mm-iface-modem.c:1431] __iface_modem_update_state_internal(): Modem /org/freedesktop/ModemManager1/Modem/0: state changed (connecting -> connected)
Jan 26 15:16:24 wg2xx-tx6s daemon.info ModemManager[867]: <debug> [1485443784.450337] [src/mm-broadband-modem.c:2003] modem_load_signal_quality(): loading signal quality...
Jan 26 15:16:24 wg2xx-tx6s daemon.info ModemManager[867]: <debug> [1485443784.450737] [src/mm-iface-modem.c:1260] signal_quality_check_ready(): Couldn't refresh signal quality: 'No AT port available to run command'
Jan 26 15:16:54 wg2xx-tx6s daemon.info ModemManager[867]: <debug> [1485443814.449523] [src/mm-broadband-modem.c:2003] modem_load_signal_quality(): loading signal quality...
Jan 26 15:16:54 wg2xx-tx6s daemon.info ModemManager[867]: <debug> [1485443814.449877] [src/mm-iface-modem.c:1140] expire_signal_quality(): Signal quality value not updated in 60s, marking as not being recent
Jan 26 15:16:54 wg2xx-tx6s daemon.info ModemManager[867]: <debug> [1485443814.450419] [src/mm-iface-modem.c:1260] signal_quality_check_ready(): Couldn't refresh signal quality: 'No AT port available to run command'
Jan 26 15:17:24 wg2xx-tx6s daemon.info ModemManager[867]: <debug> [1485443844.449983] [src/mm-broadband-modem.c:2003] modem_load_signal_quality(): loading signal quality...
Jan 26 15:17:24 wg2xx-tx6s daemon.info ModemManager[867]: <debug> [1485443844.450352] [src/mm-iface-modem.c:1260] signal_quality_check_ready(): Couldn't refresh signal quality: 'No AT port available to run command'
-----Original Message-----
From: ModemManager-devel [mailto:modemmanager-devel-bounces at lists.freedesktop.org] On Behalf Of Aleksander Morgado
Sent: 26 January 2017 13:54
To: colin.helliwell at ln-systems.com
Cc: ModemManager (development) <modemmanager-devel at lists.freedesktop.org>
Subject: Re: Fetching signal quality during data connection?

> Regarding the failing PPP:
> Your enhancement probably to prevent a race is still a good idea in general. However I've now experimented manually (with a terminal app), and I don't think it is the Sig Quality which is breaking PPP. What I was actually doing was waiting so long before starting PPP that the *modem* is timing out - after the ATD it sends back 'hex' messages (presumably some sort of LCP request) a number of times, and then eventually times out and sends 'NO CARRIER'. This timeout also happens to be 30secs.
> I haven't found any 'ETSI' spec which defines a timeout from data mode, and nor is one mentioned in my modem's docs. However I did find a uBlox manual which states different negotiation/timeout sequences for their different modems (https://www.u-blox.com/sites/default/files/u-blox-ATCommands_Manual_(UBX-13002752).pdf , para 18.2). So maybe this behaviour is always manufacturer-specific.
> It would though be better if MM caught the 'NO CARRIER' and set the state back to disconnected?

MM should already be catching the NO CARRIER errors; could you gather debug logs while reproducing this to see why it didn't catch it?

--
Aleksander
https://aleksander.es
_______________________________________________
ModemManager-devel mailing list
ModemManager-devel at lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/modemmanager-devel