Fetching signal quality during data connection?
colin.helliwell at ln-systems.com
colin.helliwell at ln-systems.com
Wed Feb 8 14:46:01 UTC 2017
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'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.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:
> ....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
More information about the ModemManager-devel
mailing list