On 25/08/2016 10:10, Bjørn Mork wrote:
Try to collect the MM debug logs and see if it provides more hints:
systemctl stop ModemManager
/usr/sbin/ModemManager --debug
nmcli c up SFR
The dump file is attached, everything looks fine except I don't receive
any datagrams. tcpdump on the interface only shows outgoing packets
without any answer.
This should print lots of details of what MM is doing and how if fails.
It can also be useful to rerun the "mmcli -m .." command after the
connection attempt, note the number of the created "bearer" object, and
then run "mmcli -b X" with this number to inspect it.
Bearer '/org/freedesktop/ModemManager1/Bearer/0'
-------------------------
Status | connected: 'yes'
| suspended: 'no'
| interface: 'wwp0s20f0u2i12'
| IP timeout: '20'
-------------------------
Properties | apn: 'websfr'
| roaming: 'allowed'
| IP type: 'ipv4v6'
| user: 'none'
| password: 'none'
| number: '*99#'
| Rm protocol: 'unknown'
-------------------------
IPv4 configuration | method: 'static'
| address: '10.142.166.49'
| prefix: '30'
| gateway: '10.142.166.50'
| DNS: '172.20.2.10', '172.20.2.39'
| MTU: '1500'
-------------------------
IPv6 configuration | method: 'dhcp'
| address: 'unknown'
| prefix: '0'
| gateway: 'unknown'
| DNS: none
-------------------------
Stats | Duration: '0'
| Bytes received: 'N/A'
| Bytes transmitted: 'N/A'
Just one additional warning for later when you are able to connect (or
for anyone else reading this and stopping at the next step): You will
need a kernel update to consistently get IP packets through. There is an
odd timing issue in the firmware of these modems, which sometimes cause
a silent failure if the driver probe is "too fast". The workaround for
this issue is present in kernels v4.7 and later, and also in stable
kernels v4.6.5 and later. I believe the first Debian kernel package
version with this fix will be the soon upcoming "4.7.2-1"
I looking for this kernel.
Regards,
Luc.
ModemManager[17786]: <info> [1472137605.516131] [mm-iface-modem-simple.c:641]
connect_auth_ready(): Simple connect started...
ModemManager[17786]: <debug> [1472137605.516176] [mm-iface-modem-simple.c:651]
connect_auth_ready(): PIN: unspecified
ModemManager[17786]: <debug> [1472137605.516190] [mm-iface-modem-simple.c:653]
connect_auth_ready(): Operator ID: unspecified
ModemManager[17786]: <debug> [1472137605.516199] [mm-iface-modem-simple.c:655]
connect_auth_ready(): Allowed roaming: yes
ModemManager[17786]: <debug> [1472137605.516208] [mm-iface-modem-simple.c:657]
connect_auth_ready(): APN: websfr
ModemManager[17786]: <debug> [1472137605.516217] [mm-iface-modem-simple.c:662]
connect_auth_ready(): IP family: ipv4v6
ModemManager[17786]: <debug> [1472137605.516230] [mm-iface-modem-simple.c:670]
connect_auth_ready(): Allowed authentication: none, pap, chap, mschap,
mschapv2, eap
ModemManager[17786]: <debug> [1472137605.516241] [mm-iface-modem-simple.c:675]
connect_auth_ready(): User: unspecified
ModemManager[17786]: <debug> [1472137605.516249] [mm-iface-modem-simple.c:677]
connect_auth_ready(): Password: unspecified
ModemManager[17786]: <debug> [1472137605.516256] [mm-iface-modem-simple.c:679]
connect_auth_ready(): Number: *99#
ModemManager[17786]: <info> [1472137605.516265] [mm-iface-modem-simple.c:469]
connection_step(): Simple connect state (4/8): Wait to get fully enabled
ModemManager[17786]: <info> [1472137605.516314] [mm-iface-modem-simple.c:478]
connection_step(): Simple connect state (5/8): Register
ModemManager[17786]: <debug> [1472137605.516340] [mm-iface-modem-3gpp.c:400]
mm_iface_modem_3gpp_register_in_network(): Already registered in network
'20810', automatic registration not launched...
ModemManager[17786]: <info> [1472137605.516362] [mm-iface-modem-simple.c:501]
connection_step(): Simple connect state (6/8): Bearer
ModemManager[17786]: <debug> [1472137605.516377] [mm-iface-modem-simple.c:574]
connection_step(): Using already existing bearer at
'/org/freedesktop/ModemManager1/Bearer/0'...
ModemManager[17786]: <info> [1472137605.516386] [mm-iface-modem-simple.c:583]
connection_step(): Simple connect state (7/8): Connect
ModemManager[17786]: <debug> [1472137605.516398] [mm-base-bearer.c:703]
mm_base_bearer_connect(): Connecting bearer
'/org/freedesktop/ModemManager1/Bearer/0'
ModemManager[17786]: <info> [1472137605.516421] [mm-iface-modem.c:1431]
__iface_modem_update_state_internal(): Modem
/org/freedesktop/ModemManager1/Modem/0: state changed (registered -> connecting)
ModemManager[17786]: <debug> [1472137605.516609] [mm-bearer-mbim.c:1026]
_connect(): Launching connection with data port (net/wwp0s20f0u2i12)
ModemManager[17786]: <debug> [1472137605.516631] [mm-bearer-mbim.c:785]
connect_context_step(): Activating packet service...
ModemManager[17786]: [/dev/cdc-wdm0] Sent message...
<<<<<< RAW:
<<<<<< length = 52
<<<<<< data =
03:00:00:00:34:00:00:00:1A:00:00:00:01:00:00:00:00:00:00:00:A2:89:CC:33:BC:BB:8B:4F:B6:B0:13:3E:C2:AA:E6:DF:0A:00:00:00:01:00:00:00:04:00:00:00:00:00:00:00
ModemManager[17786]: [/dev/cdc-wdm0] Sent message (translated)...
<<<<<< Header:
<<<<<< length = 52
<<<<<< type = command (0x00000003)
<<<<<< transaction = 26
<<<<<< Fragment header:
<<<<<< total = 1
<<<<<< current = 0
<<<<<< Contents:
<<<<<< service = 'basic-connect' (a289cc33-bcbb-8b4f-b6b0-133ec2aae6df)
<<<<<< cid = 'packet-service' (0x0000000a)
<<<<<< type = 'set' (0x00000001)
ModemManager[17786]: [/dev/cdc-wdm0] Received message...
>>>>>> RAW:
>>>>>> length = 76
>>>>>> data =
>>>>>> 03:00:00:80:4C:00:00:00:1A:00:00:00:01:00:00:00:00:00:00:00:A2:89:CC:33:BC:BB:8B:4F:B6:B0:13:3E:C2:AA:E6:DF:0A:00:00:00:00:00:00:00:1C:00:00:00:00:00:00:00:02:00:00:00:20:00:00:00:80:F0:FA:02:00:00:00:00:00:A3:E1:11:00:00:00:00
ModemManager[17786]: [/dev/cdc-wdm0] Received message (translated)...
>>>>>> Header:
>>>>>> length = 76
>>>>>> type = command-done (0x80000003)
>>>>>> transaction = 26
>>>>>> Fragment header:
>>>>>> total = 1
>>>>>> current = 0
>>>>>> Contents:
>>>>>> status error = 'None' (0x00000000)
>>>>>> service = 'basic-connect' (a289cc33-bcbb-8b4f-b6b0-133ec2aae6df)
>>>>>> cid = 'packet-service' (0x0000000a)
ModemManager[17786]: <debug> [1472137605.551327] [mm-bearer-mbim.c:724]
packet_service_set_ready(): Packet service update:
ModemManager[17786]: <debug> [1472137605.551343] [mm-bearer-mbim.c:725]
packet_service_set_ready(): state: 'attached'
ModemManager[17786]: <debug> [1472137605.551350] [mm-bearer-mbim.c:726]
packet_service_set_ready(): data class: 'lte'
ModemManager[17786]: <debug> [1472137605.551358] [mm-bearer-mbim.c:727]
packet_service_set_ready(): uplink: '50000000' bps
ModemManager[17786]: <debug> [1472137605.551365] [mm-bearer-mbim.c:728]
packet_service_set_ready(): downlink: '300000000' bps
ModemManager[17786]: <debug> [1472137605.551374] [mm-bearer-mbim.c:806]
connect_context_step(): Listing provisioned contexts...
ModemManager[17786]: [/dev/cdc-wdm0] Sent message...
<<<<<< RAW:
<<<<<< length = 48
<<<<<< data =
03:00:00:00:30:00:00:00:1B:00:00:00:01:00:00:00:00:00:00:00:A2:89:CC:33:BC:BB:8B:4F:B6:B0:13:3E:C2:AA:E6:DF:0D:00:00:00:00:00:00:00:00:00:00:00
ModemManager[17786]: [/dev/cdc-wdm0] Sent message (translated)...
<<<<<< Header:
<<<<<< length = 48
<<<<<< type = command (0x00000003)
<<<<<< transaction = 27
<<<<<< Fragment header:
<<<<<< total = 1
<<<<<< current = 0
<<<<<< Contents:
<<<<<< service = 'basic-connect' (a289cc33-bcbb-8b4f-b6b0-133ec2aae6df)
<<<<<< cid = 'provisioned-contexts' (0x0000000d)
<<<<<< type = 'query' (0x00000000)
ModemManager[17786]: [/dev/cdc-wdm0] Received message...
>>>>>> RAW:
>>>>>> length = 112
>>>>>> data =
>>>>>> 03:00:00:80:70:00:00:00:1B:00:00:00:01:00:00:00:00:00:00:00:A2:89:CC:33:BC:BB:8B:4F:B6:B0:13:3E:C2:AA:E6:DF:0D:00:00:00:00:00:00:00:40:00:00:00:01:00:00:00:0C:00:00:00:34:00:00:00:01:00:00:00:7E:5E:2A:7E:4E:6F:72:72:73:6B:65:6E:7E:5E:2A:7E:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00
ModemManager[17786]: [/dev/cdc-wdm0] Received message (translated)...
>>>>>> Header:
>>>>>> length = 112
>>>>>> type = command-done (0x80000003)
>>>>>> transaction = 27
>>>>>> Fragment header:
>>>>>> total = 1
>>>>>> current = 0
>>>>>> Contents:
>>>>>> status error = 'None' (0x00000000)
>>>>>> service = 'basic-connect' (a289cc33-bcbb-8b4f-b6b0-133ec2aae6df)
>>>>>> cid = 'provisioned-contexts' (0x0000000d)
ModemManager[17786]: <debug> [1472137605.615349] [mm-bearer-mbim.c:659]
provisioned_contexts_query_ready(): Provisioned contexts found (1):
ModemManager[17786]: <debug> [1472137605.615365] [mm-bearer-mbim.c:665]
provisioned_contexts_query_ready(): [1] context type: internet
ModemManager[17786]: <debug> [1472137605.615374] [mm-bearer-mbim.c:666]
provisioned_contexts_query_ready(): uuid:
7e5e2a7e-4e6f-7272-736b-656e7e5e2a7e
ModemManager[17786]: <debug> [1472137605.615382] [mm-bearer-mbim.c:667]
provisioned_contexts_query_ready(): access string:
ModemManager[17786]: <debug> [1472137605.615391] [mm-bearer-mbim.c:668]
provisioned_contexts_query_ready(): username:
ModemManager[17786]: <debug> [1472137605.615400] [mm-bearer-mbim.c:669]
provisioned_contexts_query_ready(): password:
ModemManager[17786]: <debug> [1472137605.615409] [mm-bearer-mbim.c:670]
provisioned_contexts_query_ready(): compression: none
ModemManager[17786]: <debug> [1472137605.615418] [mm-bearer-mbim.c:671]
provisioned_contexts_query_ready(): auth: none
ModemManager[17786]: <debug> [1472137605.615430] [mm-bearer-mbim.c:901]
connect_context_step(): Launching ipv4v6 connection with APN 'websfr'...
ModemManager[17786]: [/dev/cdc-wdm0] Sent message...
<<<<<< RAW:
<<<<<< length = 120
<<<<<< data =
03:00:00:00:78:00:00:00:1C:00:00:00:01:00:00:00:00:00:00:00:A2:89:CC:33:BC:BB:8B:4F:B6:B0:13:3E:C2:AA:E6:DF:0C:00:00:00:01:00:00:00:48:00:00:00:00:00:00:00:01:00:00:00:3C:00:00:00:0C:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:03:00:00:00:7E:5E:2A:7E:4E:6F:72:72:73:6B:65:6E:7E:5E:2A:7E:77:00:65:00:62:00:73:00:66:00:72:00
ModemManager[17786]: [/dev/cdc-wdm0] Sent message (translated)...
<<<<<< Header:
<<<<<< length = 120
<<<<<< type = command (0x00000003)
<<<<<< transaction = 28
<<<<<< Fragment header:
<<<<<< total = 1
<<<<<< current = 0
<<<<<< Contents:
<<<<<< service = 'basic-connect' (a289cc33-bcbb-8b4f-b6b0-133ec2aae6df)
<<<<<< cid = 'connect' (0x0000000c)
<<<<<< type = 'set' (0x00000001)
ModemManager[17786]: [/dev/cdc-wdm0] Received message...
>>>>>> RAW:
>>>>>> length = 80
>>>>>> data =
>>>>>> 07:00:00:80:50:00:00:00:00:00:00:00:01:00:00:00:00:00:00:00:A2:89:CC:33:BC:BB:8B:4F:B6:B0:13:3E:C2:AA:E6:DF:0C:00:00:00:24:00:00:00:00:00:00:00:02:00:00:00:00:00:00:00:03:00:00:00:7E:5E:2A:7E:4E:6F:72:72:73:6B:65:6E:7E:5E:2A:7E:00:00:00:00
ModemManager[17786]: [/dev/cdc-wdm0] Received message (translated)...
>>>>>> Header:
>>>>>> length = 80
>>>>>> type = indicate-status (0x80000007)
>>>>>> transaction = 0
>>>>>> Fragment header:
>>>>>> total = 1
>>>>>> current = 0
>>>>>> Contents:
>>>>>> service = 'basic-connect' (a289cc33-bcbb-8b4f-b6b0-133ec2aae6df)
>>>>>> cid = 'connect' (0x0000000c)
ModemManager[17786]: <debug> [1472137605.679390]
[mm-broadband-modem-mbim.c:2249] device_notification_cb(): Received
notification (service 'basic-connect', command 'connect')
ModemManager[17786]: [/dev/cdc-wdm0] Received message...
>>>>>> RAW:
>>>>>> length = 84
>>>>>> data =
>>>>>> 03:00:00:80:54:00:00:00:1C:00:00:00:01:00:00:00:00:00:00:00:A2:89:CC:33:BC:BB:8B:4F:B6:B0:13:3E:C2:AA:E6:DF:0C:00:00:00:00:00:00:00:24:00:00:00:00:00:00:00:01:00:00:00:00:00:00:00:01:00:00:00:7E:5E:2A:7E:4E:6F:72:72:73:6B:65:6E:7E:5E:2A:7E:00:00:00:00
ModemManager[17786]: [/dev/cdc-wdm0] Received message (translated)...
>>>>>> Header:
>>>>>> length = 84
>>>>>> type = command-done (0x80000003)
>>>>>> transaction = 28
>>>>>> Fragment header:
>>>>>> total = 1
>>>>>> current = 0
>>>>>> Contents:
>>>>>> status error = 'None' (0x00000000)
>>>>>> service = 'basic-connect' (a289cc33-bcbb-8b4f-b6b0-133ec2aae6df)
>>>>>> cid = 'connect' (0x0000000c)
ModemManager[17786]: <debug> [1472137605.743333] [mm-bearer-mbim.c:614]
connect_set_ready(): Session ID '0': activated (IP type: ipv4v6)
ModemManager[17786]: <debug> [1472137605.743346] [mm-bearer-mbim.c:932]
connect_context_step(): Querying IP configuration...
ModemManager[17786]: [/dev/cdc-wdm0] Sent message...
<<<<<< RAW:
<<<<<< length = 108
<<<<<< data =
03:00:00:00:6C:00:00:00:1D:00:00:00:01:00:00:00:00:00:00:00:A2:89:CC:33:BC:BB:8B:4F:B6:B0:13:3E:C2:AA:E6:DF:0F:00:00:00:00:00:00:00:3C:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00
ModemManager[17786]: [/dev/cdc-wdm0] Sent message (translated)...
<<<<<< Header:
<<<<<< length = 108
<<<<<< type = command (0x00000003)
<<<<<< transaction = 29
<<<<<< Fragment header:
<<<<<< total = 1
<<<<<< current = 0
<<<<<< Contents:
<<<<<< service = 'basic-connect' (a289cc33-bcbb-8b4f-b6b0-133ec2aae6df)
<<<<<< cid = 'ip-configuration' (0x0000000f)
<<<<<< type = 'query' (0x00000000)
ModemManager[17786]: [/dev/cdc-wdm0] Received message...
>>>>>> RAW:
>>>>>> length = 128
>>>>>> data =
>>>>>> 03:00:00:80:80:00:00:00:1D:00:00:00:01:00:00:00:00:00:00:00:A2:89:CC:33:BC:BB:8B:4F:B6:B0:13:3E:C2:AA:E6:DF:0F:00:00:00:00:00:00:00:50:00:00:00:00:00:00:00:0F:00:00:00:00:00:00:00:01:00:00:00:3C:00:00:00:00:00:00:00:00:00:00:00:44:00:00:00:00:00:00:00:02:00:00:00:48:00:00:00:00:00:00:00:00:00:00:00:DC:05:00:00:00:00:00:00:1E:00:00:00:0A:8E:A6:31:0A:8E:A6:32:AC:14:02:0A:AC:14:02:27
ModemManager[17786]: [/dev/cdc-wdm0] Received message (translated)...
>>>>>> Header:
>>>>>> length = 128
>>>>>> type = command-done (0x80000003)
>>>>>> transaction = 29
>>>>>> Fragment header:
>>>>>> total = 1
>>>>>> current = 0
>>>>>> Contents:
>>>>>> status error = 'None' (0x00000000)
>>>>>> service = 'basic-connect' (a289cc33-bcbb-8b4f-b6b0-133ec2aae6df)
>>>>>> cid = 'ip-configuration' (0x0000000f)
ModemManager[17786]: <debug> [1472137605.807445] [mm-bearer-mbim.c:319]
ip_configuration_query_ready(): IPv4 configuration available: 'address,
gateway, dns, mtu'
ModemManager[17786]: <debug> [1472137605.807461] [mm-bearer-mbim.c:325]
ip_configuration_query_ready(): IP addresses (1)
ModemManager[17786]: <debug> [1472137605.807492] [mm-bearer-mbim.c:329]
ip_configuration_query_ready(): IP [0]: '10.142.166.49/30'
ModemManager[17786]: <debug> [1472137605.807513] [mm-bearer-mbim.c:338]
ip_configuration_query_ready(): Gateway: '10.142.166.50'
ModemManager[17786]: <debug> [1472137605.807525] [mm-bearer-mbim.c:346]
ip_configuration_query_ready(): DNS addresses (2)
ModemManager[17786]: <debug> [1472137605.807542] [mm-bearer-mbim.c:351]
ip_configuration_query_ready(): DNS [0]: '172.20.2.10'
ModemManager[17786]: <debug> [1472137605.807558] [mm-bearer-mbim.c:351]
ip_configuration_query_ready(): DNS [1]: '172.20.2.39'
ModemManager[17786]: <debug> [1472137605.807570] [mm-bearer-mbim.c:359]
ip_configuration_query_ready(): MTU: '1500'
ModemManager[17786]: <debug> [1472137605.807581] [mm-bearer-mbim.c:365]
ip_configuration_query_ready(): IPv6 configuration available: 'none'
ModemManager[17786]: <debug> [1472137605.807625] [mm-port.c:95]
mm_port_set_connected(): (wwp0s20f0u2i12): port now connected
ModemManager[17786]: <debug> [1472137605.807653] [mm-base-bearer.c:601]
connect_ready(): Connected bearer '/org/freedesktop/ModemManager1/Bearer/0'
ModemManager[17786]: [/dev/cdc-wdm0] Sent message...
<<<<<< RAW:
<<<<<< length = 48
<<<<<< data =
03:00:00:00:30:00:00:00:1E:00:00:00:01:00:00:00:00:00:00:00:A2:89:CC:33:BC:BB:8B:4F:B6:B0:13:3E:C2:AA:E6:DF:14:00:00:00:00:00:00:00:00:00:00:00
ModemManager[17786]: [/dev/cdc-wdm0] Sent message (translated)...
<<<<<< Header:
<<<<<< length = 48
<<<<<< type = command (0x00000003)
<<<<<< transaction = 30
<<<<<< Fragment header:
<<<<<< total = 1
<<<<<< current = 0
<<<<<< Contents:
<<<<<< service = 'basic-connect' (a289cc33-bcbb-8b4f-b6b0-133ec2aae6df)
<<<<<< cid = 'packet-statistics' (0x00000014)
<<<<<< type = 'query' (0x00000000)
ModemManager[17786]: <info> [1472137605.807877] [mm-iface-modem.c:1431]
__iface_modem_update_state_internal(): Modem
/org/freedesktop/ModemManager1/Modem/0: state changed (connecting -> connected)
ModemManager[17786]: <info> [1472137605.808102] [mm-iface-modem-simple.c:602]
connection_step(): Simple connect state (8/8): All done
ModemManager[17786]: [/dev/cdc-wdm0] Received message...
>>>>>> RAW:
>>>>>> length = 96
>>>>>> data =
>>>>>> 03:00:00:80:60:00:00:00:1E:00:00:00:01:00:00:00:00:00:00:00:A2:89:CC:33:BC:BB:8B:4F:B6:B0:13:3E:C2:AA:E6:DF:14:00:00:00:00:00:00:00:30:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00
ModemManager[17786]: [/dev/cdc-wdm0] Received message (translated)...
>>>>>> Header:
>>>>>> length = 96
>>>>>> type = command-done (0x80000003)
>>>>>> transaction = 30
>>>>>> Fragment header:
>>>>>> total = 1
>>>>>> current = 0
>>>>>> Contents:
>>>>>> status error = 'None' (0x00000000)
>>>>>> service = 'basic-connect' (a289cc33-bcbb-8b4f-b6b0-133ec2aae6df)
>>>>>> cid = 'packet-statistics' (0x00000014)
