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-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:
> ....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@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/modemmanager-devel
