Fetching signal quality during data connection?
Dan Williams
dcbw at redhat.com
Sat Feb 11 03:31:18 UTC 2017
On Wed, 2017-02-08 at 14:46 +0000, colin.helliwell at ln-systems.com
wrote:
> I'm re-visiting this initial issue, of MM not spotting the 'NO
> CARRIER' when the modem times out of data mode. Because of aggro
> getting it working direct on the serial port, I'm back with my mux
> driver (which is what I ultimately need to use anyway).
> I've logged debug messages from both driver and MM. You can see that
> it gets the 'CONNECT', and presumably it would filter out the non-
> text data negotiation bytes anyway. But the 'NO CARRIER' - after the
> timeout - is missed.
> If I do a 'cat /dev/ttyMux0' on one shell, and 'printf
> "ATD*99***1#\r" > /dev/ttyMux0' on the other, then I do see the 'NO
> CARRIER'.
> By the way, the driver debug is of the mux messages hence they're in
> the Data Link Layer form (first 4 bytes are header, last 2 are
> trailer)
I think I see what's going wrong here; it's a mismatch of expectations.
MM puts the port in "connected" mode once it sees the CONNECT, and then
immediately lets whatever is actually driving the data connection
(pppd, something else) handle everything after that. MM does this
because were it to try to intercept data on the port, that would screw
up the PPP data flow.
So to actually hang up the port, MM depends on the thing that's doing
the PPP to notify MM that the connection has failed, and that MM should
disconnect the bearer. Once that's done, MM will then re-open the port
and start doing normal stuff like signal strength and registration
checks. But while PPP is happening, and until PPP says it's done, MM
is completely ignorant of any data on the port.
You could test this manually by disconnecting the bearer with mmcli.
Dan
> I'll keep trying to trace upwards out of the driver, but where would
> be a good point 'low down' in MM to try to see where the message
> is/isn't getting to? (i.e. somewhere lower down than [src/mm-port-
> serial-at.c:459] debug_log())
>
>
> Feb 8 14:32:00 wg6s daemon.info ModemManager[969]: <debug>
> [1486564320.276338] [src/mm-broadband-bearer.c:961] parse_pdp_list():
> Found '2' PDP contexts
> Feb 8 14:32:00 wg6s daemon.info ModemManager[969]: <debug>
> [1486564320.276489] [src/mm-broadband-bearer.c:970]
> parse_pdp_list(): PDP context [cid=1] [type='ipv4']
> [apn='mobile.o2.co.uk']
> Feb 8 14:32:00 wg6s daemon.info ModemManager[969]: <debug>
> [1486564320.276613] [src/mm-broadband-bearer.c:970]
> parse_pdp_list(): PDP context [cid=2] [type='ipv4']
> [apn='02.mobile.co.uk']
> Feb 8 14:32:00 wg6s daemon.info ModemManager[969]: <debug>
> [1486564320.276734] [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'
> Feb 8 14:32:00 wg6s daemon.info ModemManager[969]: <debug>
> [1486564320.276920] [src/mm-port-serial.c:1290]
> mm_port_serial_open(): (ttyMux0) device open count is 3 (open)
> Feb 8 14:32:00 wg6s daemon.info ModemManager[969]: <debug>
> [1486564320.277053] [src/mm-broadband-bearer.c:214]
> common_get_at_data_port(): Connection through a plain serial AT port
> (ttyMux0)
> Feb 8 14:32:00 wg6s daemon.info ModemManager[969]: <debug>
> [1486564320.277258] [src/mm-port-serial.c:1290]
> mm_port_serial_open(): (ttyMux0) device open count is 4 (open)
> Feb 8 14:32:00 wg6s daemon.info ModemManager[969]: <debug>
> [1486564320.277516] [src/mm-port-serial.c:1347] _close_internal():
> (ttyMux0) device open count is 3 (close)
> Feb 8 14:32:00 wg6s daemon.info ModemManager[969]: <debug>
> [1486564320.277791] [src/mm-port-serial-at.c:459] debug_log():
> (ttyMux0): --> 'ATD*99***1#<CR>'
> Feb 8 14:32:00 wg6s user.warn kernel: LinMux: <- bp_ThreadMuxMsg()
> Ret=true, Port=a08ad000 [MuxMsg]
> Feb 8 14:32:00 wg6s user.warn kernel: LinMux: -> bp_ThreadMuxMsg()
> Port=a08ad000 [MuxMsg]
> Feb 8 14:32:00 wg6s user.warn kernel: LinMux: 8 of 8 bytes written:
> Feb 8 14:32:00 wg6s user.warn kernel: LinMux: F9 07 EF 05 41 54 30
> F9 ....AT0.
> Feb 8 14:32:00 wg6s user.warn kernel: LinMux: <- bp_ThreadMuxMsg()
> Ret=true, Port=a08ad000 [MuxMsg]
> Feb 8 14:32:00 wg6s user.warn kernel: LinMux: -> bp_ThreadMuxMsg()
> Port=a08ad000 [MuxMsg]
> Feb 8 14:32:00 wg6s user.warn kernel: LinMux: 7 of 7 bytes written:
> Feb 8 14:32:00 wg6s user.warn kernel: LinMux: F9 07 EF 03 44 D4
> F9 ....D..
> Feb 8 14:32:00 wg6s user.warn kernel: LinMux: <- bp_ThreadMuxMsg()
> Ret=true, Port=a08ad000 [MuxMsg]
> Feb 8 14:32:00 wg6s user.warn kernel: LinMux: -> bp_ThreadMuxMsg()
> Port=a08ad000 [MuxMsg]
> Feb 8 14:32:00 wg6s user.warn kernel: LinMux: 7 of 7 bytes written:
> Feb 8 14:32:00 wg6s user.warn kernel: LinMux: F9 07 EF 03 2A D4
> F9 ....*..
> Feb 8 14:32:00 wg6s user.warn kernel: LinMux: <- bp_ThreadMuxMsg()
> Ret=true, Port=a08ad000 [MuxMsg]
> Feb 8 14:32:00 wg6s user.warn kernel: LinMux: -> bp_ThreadMuxMsg()
> Port=a08ad000 [MuxMsg]
> Feb 8 14:32:00 wg6s user.warn kernel: LinMux: 7 of 7 bytes written:
> Feb 8 14:32:00 wg6s user.warn kernel: LinMux: F9 07 EF 03 39 D4
> F9 ....9..
> Feb 8 14:32:00 wg6s user.warn kernel: LinMux: <- bp_ThreadMuxMsg()
> Ret=true, Port=a08ad000 [MuxMsg]
> Feb 8 14:32:00 wg6s user.warn kernel: LinMux: -> bp_ThreadMuxMsg()
> Port=a08ad000 [MuxMsg]
> Feb 8 14:32:00 wg6s user.warn kernel: LinMux: 8 of 8 bytes written:
> Feb 8 14:32:00 wg6s user.warn kernel: LinMux: F9 07 EF 05 39 2A 30
> F9 ....9*0.
> Feb 8 14:32:00 wg6s user.warn kernel: LinMux: <- bp_ThreadMuxMsg()
> Ret=true, Port=a08ad000 [MuxMsg]
> Feb 8 14:32:00 wg6s user.warn kernel: LinMux: -> bp_ThreadMuxMsg()
> Port=a08ad000 [MuxMsg]
> Feb 8 14:32:00 wg6s user.warn kernel: LinMux: 7 of 7 bytes written:
> Feb 8 14:32:00 wg6s user.warn kernel: LinMux: F9 07 EF 03 2A D4
> F9 ....*..
> Feb 8 14:32:00 wg6s user.warn kernel: LinMux: <- bp_ThreadMuxMsg()
> Ret=true, Port=a08ad000 [MuxMsg]
> Feb 8 14:32:00 wg6s user.warn kernel: LinMux: -> bp_ThreadMuxMsg()
> Port=a08ad000 [MuxMsg]
> Feb 8 14:32:00 wg6s user.warn kernel: LinMux: 7 of 7 bytes written:
> Feb 8 14:32:00 wg6s user.warn kernel: LinMux: F9 07 EF 03 2A D4
> F9 ....*..
> Feb 8 14:32:00 wg6s user.warn kernel: LinMux: <- bp_ThreadMuxMsg()
> Ret=true, Port=a08ad000 [MuxMsg]
> Feb 8 14:32:00 wg6s user.warn kernel: LinMux: -> bp_ThreadMuxMsg()
> Port=a08ad000 [MuxMsg]
> Feb 8 14:32:00 wg6s user.warn kernel: LinMux: 7 of 7 bytes written:
> Feb 8 14:32:00 wg6s user.warn kernel: LinMux: F9 07 EF 03 31 D4
> F9 ....1..
> Feb 8 14:32:00 wg6s user.warn kernel: LinMux: <- bp_ThreadMuxMsg()
> Ret=true, Port=a08ad000 [MuxMsg]
> Feb 8 14:32:00 wg6s user.warn kernel: LinMux: -> bp_ThreadMuxMsg()
> Port=a08ad000 [MuxMsg]
> Feb 8 14:32:00 wg6s user.warn kernel: LinMux: 7 of 7 bytes written:
> Feb 8 14:32:00 wg6s user.warn kernel: LinMux: F9 07 EF 03 23 D4
> F9 ....#..
> Feb 8 14:32:00 wg6s user.warn kernel: LinMux: <- bp_ThreadMuxMsg()
> Ret=true, Port=a08ad000 [MuxMsg]
> Feb 8 14:32:00 wg6s user.warn kernel: LinMux: -> bp_ThreadMuxMsg()
> Port=a08ad000 [MuxMsg]
> Feb 8 14:32:00 wg6s user.warn kernel: LinMux: 7 of 7 bytes written:
> Feb 8 14:32:00 wg6s user.warn kernel: LinMux: F9 07 EF 03 0D D4
> F9 .......
> Feb 8 14:32:00 wg6s user.warn kernel: LinMux: <- bp_ThreadMuxMsg()
> Ret=true, Port=a08ad000 [MuxMsg]
> Feb 8 14:32:00 wg6s user.warn kernel: LinMux: -> bp_ThreadMuxMsg()
> Port=a08ad000 [MuxMsg]
> Feb 8 14:32:01 wg6s user.warn kernel: LinMux: 87 of 1024 bytes
> read:
> Feb 8 14:32:01 wg6s user.warn kernel: LinMux: F9 05 EF 17 0D 0A 43
> 4F 4E 4E 45 43 54 0D 0A AE ......CONNECT...
> Feb 8 14:32:01 wg6s user.warn kernel: LinMux: F9 F9 01 EF 09 E3 05
> 07 8D 9A F9 F9 05 EF 6D 7E ..............m~
> Feb 8 14:32:01 wg6s user.warn kernel: LinMux: FF 7D 23 C0 21 7D 21
> 7D 23 7D 20 7D 39 7D 22 7D .}#.!}!}#} }9}"}
> Feb 8 14:32:01 wg6s user.warn kernel: LinMux: 26 7D 20 7D 2A 7D 20
> 7D 20 7D 27 7D 22 7D 28 7D &} }*} } }'}"}(}
> Feb 8 14:32:01 wg6s user.warn kernel: LinMux: 22 7D 25 7D 26 21 F1
> 7D 2F 85 7D 23 7D 25 C2 23 "}
> Feb 8 14:32:01 wg6s user.warn kernel: LinMux: 7D 25 CF AD 7E 17
> F9 }
> Feb 8 14:32:01 wg6s user.warn kernel: LinMux: Rx pkt read from UART
> dlci=1 datalen=11
> Feb 8 14:32:01 wg6s user.warn kernel: LinMux: Rx pkt read from UART
> dlci=0 datalen=4
> Feb 8 14:32:01 wg6s user.warn kernel: LinMux: Received MSC
> params=7,141,78
> Feb 8 14:32:01 wg6s user.warn kernel: LinMux: Rx pkt read from UART
> dlci=1 datalen=54
> Feb 8 14:32:01 wg6s user.warn kernel: LinMux: * Found remote
> flowcontrol dlci=0x01
> Feb 8 14:32:01 wg6s user.warn kernel: LinMux: * local flow control
> on dlci=0x01 is 0
> Feb 8 14:32:01 wg6s user.warn kernel: LinMux: * remote flow control
> on dlci=0x00 is 0
> Feb 8 14:32:01 wg6s user.warn kernel: LinMux: RFC=OFF dlci=1
> v24=141
> Feb 8 14:32:01 wg6s user.warn kernel: LinMux: <- bp_ThreadMuxMsg()
> Ret=true, Port=a08ad000 [MuxMsg]
> Feb 8 14:32:01 wg6s user.warn kernel: LinMux: -> bp_ThreadMuxMsg()
> Port=a08ad000 [MuxMsg]
> Feb 8 14:32:01 wg6s user.warn kernel: LinMux: <- bp_ThreadMuxMsg()
> Ret=true, Port=a08ad000 [MuxMsg]
> Feb 8 14:32:01 wg6s daemon.info ModemManager[969]: <debug>
> [1486564321.202667] [src/mm-port-serial-at.c:459] debug_log():
> (ttyMux0): <-- '<CR><LF>CONNECT<CR><LF>~\255}#\192!}!}#} }9}"}&} }*}
> } }'}"}(}"}%}&!\241}/\133}#}%\194#}%\207\173~'
> Feb 8 14:32:01 wg6s daemon.info ModemManager[969]: <debug>
> [1486564321.204326] [src/mm-port-serial.c:1347] _close_internal():
> (ttyMux0) device open count is 2 (close)
> Feb 8 14:32:01 wg6s user.warn kernel: LinMux: -> bp_ThreadMuxMsg()
> Port=a08ad000 [MuxMsg]
> Feb 8 14:32:01 wg6s user.warn kernel: LinMux: <- bp_ThreadMuxMsg()
> Ret=true, Port=a08ad000 [MuxMsg]
> Feb 8 14:32:01 wg6s user.warn kernel: LinMux: -> bp_ThreadMuxMsg()
> Port=a08ad000 [MuxMsg]
> Feb 8 14:32:01 wg6s user.warn kernel: LinMux: <- bp_ThreadMuxMsg()
> Ret=true, Port=a08ad000 [MuxMsg]
> Feb 8 14:32:01 wg6s user.warn kernel: LinMux: -> bp_ThreadMuxMsg()
> Port=a08ad000 [MuxMsg]
> Feb 8 14:32:01 wg6s user.warn kernel: LinMux: 10 of 10 bytes
> written:
> Feb 8 14:32:01 wg6s user.warn kernel: LinMux: F9 03 EF 09 E1 05 07
> 8D FB F9 ..........
> Feb 8 14:32:01 wg6s user.warn kernel: LinMux: <- bp_ThreadMuxMsg()
> Ret=true, Port=a08ad000 [MuxMsg]
> Feb 8 14:32:01 wg6s daemon.info ModemManager[969]: <debug>
> [1486564321.205661] [src/mm-port.c:95] mm_port_set_connected():
> (ttyMux0): port now connected
> Feb 8 14:32:01 wg6s user.warn kernel: LinMux: -> bp_ThreadMuxMsg()
> Port=a08ad000 [MuxMsg]
> Feb 8 14:32:01 wg6s daemon.info ModemManager[969]: <debug>
> [1486564321.207721] [src/mm-base-bearer.c:601] connect_ready():
> Connected bearer '/org/freedesktop/ModemManager1/Bearer/0'
> Feb 8 14:32:01 wg6s daemon.info ModemManager[969]:
> <info> [1486564321.212150] [src/mm-iface-modem.c:1431]
> __iface_modem_update_state_internal(): Modem
> /org/freedesktop/ModemManager1/Modem/0: state changed (connecting ->
> connected)
> Feb 8 14:32:01 wg6s daemon.info ModemManager[969]:
> <info> [1486564321.219928] [src/mm-iface-modem-simple.c:602]
> connection_step(): Simple connect state (8/8): All done
> Feb 8 14:32:03 wg6s user.warn kernel: LinMux: 60 of 1024 bytes
> read:
> Feb 8 14:32:03 wg6s user.warn kernel: LinMux: F9 05 EF 6D 7E FF 7D
> 23 C0 21 7D 21 7D 23 7D 20 ...m~.}#.!}!}#}
> Feb 8 14:32:03 wg6s user.warn kernel: LinMux: 7D 39 7D 22 7D 26 7D
> 20 7D 2A 7D 20 7D 20 7D 27 }9}"}&} }*} } }'
> Feb 8 14:32:03 wg6s user.warn kernel: LinMux: 7D 22 7D 28 7D 22 7D
> 25 7D 26 21 F1 7D 2F 85 7D }"}(}"}
> Feb 8 14:32:03 wg6s user.warn kernel: LinMux: 23 7D 25 C2 23 7D 25
> CF AD 7E 17 F9 #}
> Feb 8 14:32:03 wg6s user.warn kernel: LinMux: Rx pkt read from UART
> dlci=1 datalen=54
> Feb 8 14:32:03 wg6s user.warn kernel: LinMux: <- bp_ThreadMuxMsg()
> Ret=true, Port=a08ad000 [MuxMsg]
> Feb 8 14:32:03 wg6s user.warn kernel: LinMux: -> bp_ThreadMuxMsg()
> Port=a08ad000 [MuxMsg]
> Feb 8 14:32:06 wg6s daemon.info ModemManager[969]: <debug>
> [1486564326.280208] [src/mm-broadband-modem.c:2003]
> modem_load_signal_quality(): loading signal quality...
> Feb 8 14:32:06 wg6s daemon.info ModemManager[969]: <debug>
> [1486564326.280596] [src/mm-iface-modem.c:1260]
> signal_quality_check_ready(): Couldn't refresh signal quality: 'No AT
> port available to run command'
> Feb 8 14:32:06 wg6s user.warn kernel: LinMux: 60 of 1024 bytes
> read:
> Feb 8 14:32:06 wg6s user.warn kernel: LinMux: F9 05 EF 6D 7E FF 7D
> 23 C0 21 7D 21 7D 23 7D 20 ...m~.}#.!}!}#}
> Feb 8 14:32:06 wg6s user.warn kernel: LinMux: 7D 39 7D 22 7D 26 7D
> 20 7D 2A 7D 20 7D 20 7D 27 }9}"}&} }*} } }'
> Feb 8 14:32:06 wg6s user.warn kernel: LinMux: 7D 22 7D 28 7D 22 7D
> 25 7D 26 21 F1 7D 2F 85 7D }"}(}"}
> Feb 8 14:32:06 wg6s user.warn kernel: LinMux: 23 7D 25 C2 23 7D 25
> CF AD 7E 17 F9 #}
> Feb 8 14:32:06 wg6s user.warn kernel: LinMux: Rx pkt read from UART
> dlci=1 datalen=54
> Feb 8 14:32:06 wg6s user.warn kernel: LinMux: <- bp_ThreadMuxMsg()
> Ret=true, Port=a08ad000 [MuxMsg]
> Feb 8 14:32:06 wg6s user.warn kernel: LinMux: -> bp_ThreadMuxMsg()
> Port=a08ad000 [MuxMsg]
> Feb 8 14:32:09 wg6s user.warn kernel: LinMux: 60 of 1024 bytes
> read:
> Feb 8 14:32:09 wg6s user.warn kernel: LinMux: F9 05 EF 6D 7E FF 7D
> 23 C0 21 7D 21 7D 23 7D 20 ...m~.}#.!}!}#}
> Feb 8 14:32:09 wg6s user.warn kernel: LinMux: 7D 39 7D 22 7D 26 7D
> 20 7D 2A 7D 20 7D 20 7D 27 }9}"}&} }*} } }'
> Feb 8 14:32:09 wg6s user.warn kernel: LinMux: 7D 22 7D 28 7D 22 7D
> 25 7D 26 21 F1 7D 2F 85 7D }"}(}"}
> Feb 8 14:32:09 wg6s user.warn kernel: LinMux: 23 7D 25 C2 23 7D 25
> CF AD 7E 17 F9 #}
> Feb 8 14:32:09 wg6s user.warn kernel: LinMux: Rx pkt read from UART
> dlci=1 datalen=54
> Feb 8 14:32:09 wg6s user.warn kernel: LinMux: <- bp_ThreadMuxMsg()
> Ret=true, Port=a08ad000 [MuxMsg]
> Feb 8 14:32:09 wg6s user.warn kernel: LinMux: -> bp_ThreadMuxMsg()
> Port=a08ad000 [MuxMsg]
> Feb 8 14:32:12 wg6s user.warn kernel: LinMux: 60 of 1024 bytes
> read:
> Feb 8 14:32:12 wg6s user.warn kernel: LinMux: F9 05 EF 6D 7E FF 7D
> 23 C0 21 7D 21 7D 23 7D 20 ...m~.}#.!}!}#}
> Feb 8 14:32:12 wg6s user.warn kernel: LinMux: 7D 39 7D 22 7D 26 7D
> 20 7D 2A 7D 20 7D 20 7D 27 }9}"}&} }*} } }'
> Feb 8 14:32:12 wg6s user.warn kernel: LinMux: 7D 22 7D 28 7D 22 7D
> 25 7D 26 21 F1 7D 2F 85 7D }"}(}"}
> Feb 8 14:32:12 wg6s user.warn kernel: LinMux: 23 7D 25 C2 23 7D 25
> CF AD 7E 17 F9 #}
> Feb 8 14:32:12 wg6s user.warn kernel: LinMux: Rx pkt read from UART
> dlci=1 datalen=54
> Feb 8 14:32:12 wg6s user.warn kernel: LinMux: <- bp_ThreadMuxMsg()
> Ret=true, Port=a08ad000 [MuxMsg]
> Feb 8 14:32:12 wg6s user.warn kernel: LinMux: -> bp_ThreadMuxMsg()
> Port=a08ad000 [MuxMsg]
> Feb 8 14:32:15 wg6s user.warn kernel: LinMux: 60 of 1024 bytes
> read:
> Feb 8 14:32:15 wg6s user.warn kernel: LinMux: F9 05 EF 6D 7E FF 7D
> 23 C0 21 7D 21 7D 23 7D 20 ...m~.}#.!}!}#}
> Feb 8 14:32:15 wg6s user.warn kernel: LinMux: 7D 39 7D 22 7D 26 7D
> 20 7D 2A 7D 20 7D 20 7D 27 }9}"}&} }*} } }'
> Feb 8 14:32:15 wg6s user.warn kernel: LinMux: 7D 22 7D 28 7D 22 7D
> 25 7D 26 21 F1 7D 2F 85 7D }"}(}"}
> Feb 8 14:32:15 wg6s user.warn kernel: LinMux: 23 7D 25 C2 23 7D 25
> CF AD 7E 17 F9 #}
> Feb 8 14:32:15 wg6s user.warn kernel: LinMux: Rx pkt read from UART
> dlci=1 datalen=54
> Feb 8 14:32:15 wg6s user.warn kernel: LinMux: <- bp_ThreadMuxMsg()
> Ret=true, Port=a08ad000 [MuxMsg]
> Feb 8 14:32:15 wg6s user.warn kernel: LinMux: -> bp_ThreadMuxMsg()
> Port=a08ad000 [MuxMsg]
> Feb 8 14:32:18 wg6s user.warn kernel: LinMux: 60 of 1024 bytes
> read:
> Feb 8 14:32:18 wg6s user.warn kernel: LinMux: F9 05 EF 6D 7E FF 7D
> 23 C0 21 7D 21 7D 23 7D 20 ...m~.}#.!}!}#}
> Feb 8 14:32:18 wg6s user.warn kernel: LinMux: 7D 39 7D 22 7D 26 7D
> 20 7D 2A 7D 20 7D 20 7D 27 }9}"}&} }*} } }'
> Feb 8 14:32:18 wg6s user.warn kernel: LinMux: 7D 22 7D 28 7D 22 7D
> 25 7D 26 21 F1 7D 2F 85 7D }"}(}"}
> Feb 8 14:32:18 wg6s user.warn kernel: LinMux: 23 7D 25 C2 23 7D 25
> CF AD 7E 17 F9 #}
> Feb 8 14:32:18 wg6s user.warn kernel: LinMux: Rx pkt read from UART
> dlci=1 datalen=54
> Feb 8 14:32:18 wg6s user.warn kernel: LinMux: <- bp_ThreadMuxMsg()
> Ret=true, Port=a08ad000 [MuxMsg]
> Feb 8 14:32:18 wg6s user.warn kernel: LinMux: -> bp_ThreadMuxMsg()
> Port=a08ad000 [MuxMsg]
> Feb 8 14:32:21 wg6s user.warn kernel: LinMux: 60 of 1024 bytes
> read:
> Feb 8 14:32:21 wg6s user.warn kernel: LinMux: F9 05 EF 6D 7E FF 7D
> 23 C0 21 7D 21 7D 23 7D 20 ...m~.}#.!}!}#}
> Feb 8 14:32:21 wg6s user.warn kernel: LinMux: 7D 39 7D 22 7D 26 7D
> 20 7D 2A 7D 20 7D 20 7D 27 }9}"}&} }*} } }'
> Feb 8 14:32:21 wg6s user.warn kernel: LinMux: 7D 22 7D 28 7D 22 7D
> 25 7D 26 21 F1 7D 2F 85 7D }"}(}"}
> Feb 8 14:32:21 wg6s user.warn kernel: LinMux: 23 7D 25 C2 23 7D 25
> CF AD 7E 17 F9 #}
> Feb 8 14:32:21 wg6s user.warn kernel: LinMux: Rx pkt read from UART
> dlci=1 datalen=54
> Feb 8 14:32:21 wg6s user.warn kernel: LinMux: <- bp_ThreadMuxMsg()
> Ret=true, Port=a08ad000 [MuxMsg]
> Feb 8 14:32:21 wg6s user.warn kernel: LinMux: -> bp_ThreadMuxMsg()
> Port=a08ad000 [MuxMsg]
> Feb 8 14:32:24 wg6s user.warn kernel: LinMux: 60 of 1024 bytes
> read:
> Feb 8 14:32:24 wg6s user.warn kernel: LinMux: F9 05 EF 6D 7E FF 7D
> 23 C0 21 7D 21 7D 23 7D 20 ...m~.}#.!}!}#}
> Feb 8 14:32:24 wg6s user.warn kernel: LinMux: 7D 39 7D 22 7D 26 7D
> 20 7D 2A 7D 20 7D 20 7D 27 }9}"}&} }*} } }'
> Feb 8 14:32:24 wg6s user.warn kernel: LinMux: 7D 22 7D 28 7D 22 7D
> 25 7D 26 21 F1 7D 2F 85 7D }"}(}"}
> Feb 8 14:32:24 wg6s user.warn kernel: LinMux: 23 7D 25 C2 23 7D 25
> CF AD 7E 17 F9 #}
> Feb 8 14:32:24 wg6s user.warn kernel: LinMux: Rx pkt read from UART
> dlci=1 datalen=54
> Feb 8 14:32:24 wg6s user.warn kernel: LinMux: <- bp_ThreadMuxMsg()
> Ret=true, Port=a08ad000 [MuxMsg]
> Feb 8 14:32:24 wg6s user.warn kernel: LinMux: -> bp_ThreadMuxMsg()
> Port=a08ad000 [MuxMsg]
> Feb 8 14:32:27 wg6s user.warn kernel: LinMux: 60 of 1024 bytes
> read:
> Feb 8 14:32:27 wg6s user.warn kernel: LinMux: F9 05 EF 6D 7E FF 7D
> 23 C0 21 7D 21 7D 23 7D 20 ...m~.}#.!}!}#}
> Feb 8 14:32:27 wg6s user.warn kernel: LinMux: 7D 39 7D 22 7D 26 7D
> 20 7D 2A 7D 20 7D 20 7D 27 }9}"}&} }*} } }'
> Feb 8 14:32:27 wg6s user.warn kernel: LinMux: 7D 22 7D 28 7D 22 7D
> 25 7D 26 21 F1 7D 2F 85 7D }"}(}"}
> Feb 8 14:32:27 wg6s user.warn kernel: LinMux: 23 7D 25 C2 23 7D 25
> CF AD 7E 17 F9 #}
> Feb 8 14:32:27 wg6s user.warn kernel: LinMux: Rx pkt read from UART
> dlci=1 datalen=54
> Feb 8 14:32:27 wg6s user.warn kernel: LinMux: <- bp_ThreadMuxMsg()
> Ret=true, Port=a08ad000 [MuxMsg]
> Feb 8 14:32:27 wg6s user.warn kernel: LinMux: -> bp_ThreadMuxMsg()
> Port=a08ad000 [MuxMsg]
> Feb 8 14:32:30 wg6s user.warn kernel: LinMux: 10 of 1024 bytes
> read:
> Feb 8 14:32:30 wg6s user.warn kernel: LinMux: F9 01 EF 09 E3 05 07
> 0D 9A F9 ..........
> Feb 8 14:32:30 wg6s user.warn kernel: LinMux: Rx pkt read from UART
> dlci=0 datalen=4
> Feb 8 14:32:30 wg6s user.warn kernel: LinMux: Received MSC
> params=7,13,192
> Feb 8 14:32:30 wg6s user.warn kernel: LinMux: * Found remote
> flowcontrol dlci=0x01
> Feb 8 14:32:30 wg6s user.warn kernel: LinMux: * local flow control
> on dlci=0x01 is 0
> Feb 8 14:32:30 wg6s user.warn kernel: LinMux: * remote flow control
> on dlci=0x00 is 0
> Feb 8 14:32:30 wg6s user.warn kernel: LinMux: RFC=OFF dlci=1 v24=13
> Feb 8 14:32:30 wg6s user.warn kernel: LinMux: <- bp_ThreadMuxMsg()
> Ret=true, Port=a08ad000 [MuxMsg]
> Feb 8 14:32:30 wg6s user.warn kernel: LinMux: -> bp_ThreadMuxMsg()
> Port=a08ad000 [MuxMsg]
> Feb 8 14:32:30 wg6s user.warn kernel: LinMux: <- bp_ThreadMuxMsg()
> Ret=true, Port=a08ad000 [MuxMsg]
> Feb 8 14:32:30 wg6s user.warn kernel: LinMux: -> bp_ThreadMuxMsg()
> Port=a08ad000 [MuxMsg]
> Feb 8 14:32:30 wg6s user.warn kernel: LinMux: <- bp_ThreadMuxMsg()
> Ret=true, Port=a08ad000 [MuxMsg]
> Feb 8 14:32:30 wg6s user.warn kernel: LinMux: -> bp_ThreadMuxMsg()
> Port=a08ad000 [MuxMsg]
> Feb 8 14:32:30 wg6s user.warn kernel: LinMux: 10 of 10 bytes
> written:
> Feb 8 14:32:30 wg6s user.warn kernel: LinMux: F9 03 EF 09 E1 05 07
> 0D FB F9 ..........
> Feb 8 14:32:30 wg6s user.warn kernel: LinMux: <- bp_ThreadMuxMsg()
> Ret=true, Port=a08ad000 [MuxMsg]
> Feb 8 14:32:30 wg6s user.warn kernel: LinMux: -> bp_ThreadMuxMsg()
> Port=a08ad000 [MuxMsg]
> Feb 8 14:32:30 wg6s user.warn kernel: LinMux: 20 of 1024 bytes
> read:
> Feb 8 14:32:30 wg6s user.warn kernel: LinMux: F9 05 EF 1D 0D 0A 4E
> 4F 20 43 41 52 52 49 45 52 ......NO CARRIER
> Feb 8 14:32:30 wg6s user.warn kernel: LinMux: 0D 0A 43
> F9 ..C.
> Feb 8 14:32:30 wg6s user.warn kernel: LinMux: Rx pkt read from UART
> dlci=1 datalen=14
> Feb 8 14:32:30 wg6s user.warn kernel: LinMux: <- bp_ThreadMuxMsg()
> Ret=true, Port=a08ad000 [MuxMsg]
> Feb 8 14:32:30 wg6s user.warn kernel: LinMux: -> bp_ThreadMuxMsg()
> Port=a08ad000 [MuxMsg]
> Feb 8 14:32:36 wg6s daemon.info ModemManager[969]: <debug>
> [1486564356.278673] [src/mm-iface-modem.c:1140]
> expire_signal_quality(): Signal quality value not updated in 60s,
> marking as not being recent
> Feb 8 14:32:36 wg6s daemon.info ModemManager[969]: <debug>
> [1486564356.279239] [src/mm-broadband-modem.c:2003]
> modem_load_signal_quality(): loading signal quality...
> Feb 8 14:32:36 wg6s daemon.info ModemManager[969]: <debug>
> [1486564356.281377] [src/mm-iface-modem.c:1260]
> signal_quality_check_ready(): Couldn't refresh signal quality: 'No AT
> port available to run command'
> Feb 8 14:33:00 wg6s user.warn kernel: LinMux: 28 of 1024 bytes
> read:
> Feb 8 14:33:00 wg6s user.warn kernel: LinMux: F9 01 EF 09 E3 05 07
> 4D 9A F9 F9 05 EF 19 0D 0A .......M........
> Feb 8 14:33:00 wg6s user.warn kernel: LinMux: 2B 43 52 45 47 3A 20
> 32 0D 0A 44 F9 +CREG: 2..D.
> Feb 8 14:33:00 wg6s user.warn kernel: LinMux: Rx pkt read from UART
> dlci=0 datalen=4
> Feb 8 14:33:00 wg6s user.warn kernel: LinMux: Received MSC
> params=7,77,32
> Feb 8 14:33:00 wg6s user.warn kernel: LinMux: Rx pkt read from UART
> dlci=1 datalen=12
>
>
>
> -----Original Message-----
> From: ModemManager-devel [mailto:modemmanager-devel-bounces at lists.fre
> edesktop.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:
> > ....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.
> > .....
> > 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
>
>
> _______________________________________________
> ModemManager-devel mailing list
> ModemManager-devel at lists.freedesktop.org
> https://lists.freedesktop.org/mailman/listinfo/modemmanager-devel
More information about the ModemManager-devel
mailing list