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-boun...@lists.freedesktop.org] On Behalf Of Aleksander Morgado Sent: 26 January 2017 13:54 To: colin.helliw...@ln-systems.com Cc: ModemManager (development) <modemmanager-devel@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@lists.freedesktop.org https://lists.freedesktop.org/mailman/listinfo/modemmanager-devel _______________________________________________ ModemManager-devel mailing list ModemManager-devel@lists.freedesktop.org https://lists.freedesktop.org/mailman/listinfo/modemmanager-devel
