"PPP Link is down" and stays down forever

[Stelios Pa]

Hello community,

I have just installed firmware 1.6.2 on my gateways and I’m facing a very strange problem with PPP.

Previous firmware was 1.4.16

I have both MTCDT-LEU1-266A and MTCDTIP-LEU1-266A gateways.

I have tried a lot of combinations in order to reproduce the problem and I found that it is related to the firmware and not the device/hardware itself.

Tried: MTCDT-LEU1-266A / 1.6.2 and 1.4.16 / different SIM cards and providers.
Tried: MTCDTIP-LEU1-266A / 1.6.2 and 1.4.16 / different SIM cards and providers.

In every situation when the gateways was plugged in power, the PPP link is up and working properly.

When I try to restart the pppd service /etc/init.d/pppd restart, pull out the SIM card and re insert it or if the link goes down from the provider then:

On 1.4.16 it can reconnect successfully with the 1st or 2nd try.
On 1.6.2 it can not reconnect and stays down infinitely.

Below you will find the logs when the PPP stays down (both devices)

/var/log/messages

2018-10-19T05:20:04.709675-05:00 mtcdt chat[21631]: info: Attempting Basic Radio Communication
2018-10-19T05:20:04.710929-05:00 mtcdt chat[21631]: send (AT^M)
2018-10-19T05:20:04.743639-05:00 mtcdt chat[21631]: expect (OK)
2018-10-19T05:20:04.747677-05:00 mtcdt chat[21631]: ^M
2018-10-19T05:20:04.749320-05:00 mtcdt chat[21631]: OK
2018-10-19T05:20:04.750775-05:00 mtcdt chat[21631]:  -- got it
2018-10-19T05:20:04.752130-05:00 mtcdt chat[21631]: info: Checking if SIM is inserted
2018-10-19T05:20:04.753747-05:00 mtcdt chat[21631]: send (AT#SIMDET?^M)
2018-10-19T05:20:04.867113-05:00 mtcdt chat[21631]: expect (#SIMDET: 2,1)
2018-10-19T05:20:04.867542-05:00 mtcdt chat[21631]: ^M
2018-10-19T05:20:04.871898-05:00 mtcdt chat[21631]: ^M
2018-10-19T05:20:04.872389-05:00 mtcdt chat[21631]: #SIMDET: 2,1
2018-10-19T05:20:04.872626-05:00 mtcdt chat[21631]:  -- got it
2018-10-19T05:20:04.872874-05:00 mtcdt chat[21631]: info: Checking if SIM is locked
2018-10-19T05:20:04.875787-05:00 mtcdt chat[21631]: send (AT+CPIN?^M)
2018-10-19T05:20:04.969840-05:00 mtcdt chat[21631]: expect (READY)
2018-10-19T05:20:04.971012-05:00 mtcdt chat[21631]: ^M
2018-10-19T05:20:04.972153-05:00 mtcdt chat[21631]: ^M
2018-10-19T05:20:04.973418-05:00 mtcdt chat[21631]: OK^M
2018-10-19T05:20:04.974758-05:00 mtcdt chat[21631]: ^M
2018-10-19T05:20:04.975948-05:00 mtcdt chat[21631]: ERROR^M
2018-10-19T05:20:05.971208-05:00 mtcdt chat[21631]: alarm
2018-10-19T05:20:05.971603-05:00 mtcdt chat[21631]: send (AT+CPIN?^M)
2018-10-19T05:20:06.063783-05:00 mtcdt chat[21631]: expect (ERROR)
2018-10-19T05:20:06.068159-05:00 mtcdt chat[21631]: ^M
2018-10-19T05:20:06.068487-05:00 mtcdt chat[21631]: ERROR
2018-10-19T05:20:06.068770-05:00 mtcdt chat[21631]:  -- got it
2018-10-19T05:20:06.069036-05:00 mtcdt chat[21631]: send (AT#SIMDET?^M)
2018-10-19T05:20:06.181612-05:00 mtcdt chat[21631]: expect (#SIMDET: 2,0)
2018-10-19T05:20:06.181941-05:00 mtcdt chat[21631]: ^M
2018-10-19T05:20:06.186532-05:00 mtcdt chat[21631]: ^M
2018-10-19T05:20:06.186921-05:00 mtcdt chat[21631]: #SIMDET: 2,1^M
2018-10-19T05:20:06.187195-05:00 mtcdt chat[21631]: ^M
2018-10-19T05:20:06.187477-05:00 mtcdt chat[21631]: OK^M
2018-10-19T05:20:07.182076-05:00 mtcdt chat[21631]: alarm
2018-10-19T05:20:07.182381-05:00 mtcdt chat[21631]: info: No SIM Pin required
2018-10-19T05:20:07.182598-05:00 mtcdt chat[21631]: info: Waiting for minimum signal strength
2018-10-19T05:20:07.182812-05:00 mtcdt chat[21631]: send (AT+CSQ^M)
2018-10-19T05:20:07.254880-05:00 mtcdt chat[21631]: expect (+CSQ: )
2018-10-19T05:20:07.259280-05:00 mtcdt chat[21631]: ^M
2018-10-19T05:20:07.259611-05:00 mtcdt chat[21631]: +CSQ:
2018-10-19T05:20:07.259832-05:00 mtcdt chat[21631]:  -- got it
2018-10-19T05:20:07.260087-05:00 mtcdt chat[21631]: expect (99,99)
2018-10-19T05:20:07.260421-05:00 mtcdt chat[21631]: 29,99^M
2018-10-19T05:20:07.260688-05:00 mtcdt chat[21631]: ^M
2018-10-19T05:20:07.260966-05:00 mtcdt chat[21631]: OK^M
2018-10-19T05:20:08.260544-05:00 mtcdt chat[21631]: alarm
2018-10-19T05:20:08.261236-05:00 mtcdt chat[21631]: send (AT^M)
2018-10-19T05:20:08.292265-05:00 mtcdt chat[21631]: expect (OK)
2018-10-19T05:20:08.296527-05:00 mtcdt chat[21631]: ^M
2018-10-19T05:20:08.296832-05:00 mtcdt chat[21631]: OK
2018-10-19T05:20:08.297048-05:00 mtcdt chat[21631]:  -- got it
2018-10-19T05:20:08.297303-05:00 mtcdt chat[21631]: send (AT^M)
2018-10-19T05:20:08.328365-05:00 mtcdt chat[21631]: abort on (NO CARRIER)
2018-10-19T05:20:08.328640-05:00 mtcdt chat[21631]: abort on (BUSY)
2018-10-19T05:20:08.328883-05:00 mtcdt chat[21631]: abort on (ERROR)
2018-10-19T05:20:08.329128-05:00 mtcdt chat[21631]: expect (OK)
2018-10-19T05:20:08.329511-05:00 mtcdt chat[21631]: ^M
2018-10-19T05:20:08.332659-05:00 mtcdt chat[21631]: ^M
2018-10-19T05:20:08.332971-05:00 mtcdt chat[21631]: OK
2018-10-19T05:20:08.334497-05:00 mtcdt chat[21631]:  -- got it
2018-10-19T05:20:08.335731-05:00 mtcdt chat[21631]: send (AT+CSQ^M)
2018-10-19T05:20:08.408545-05:00 mtcdt chat[21631]: expect (OK)
2018-10-19T05:20:08.408879-05:00 mtcdt chat[21631]: ^M
2018-10-19T05:20:08.413137-05:00 mtcdt chat[21631]: ^M
2018-10-19T05:20:08.414664-05:00 mtcdt chat[21631]: +CSQ: 29,99^M
2018-10-19T05:20:08.415909-05:00 mtcdt chat[21631]: ^M
2018-10-19T05:20:08.417022-05:00 mtcdt chat[21631]: OK
2018-10-19T05:20:08.418086-05:00 mtcdt chat[21631]:  -- got it
2018-10-19T05:20:08.419184-05:00 mtcdt chat[21631]: send (AT+CGDCONT=1,\"IP\",\"XXX.XXX.XX\"^M)
2018-10-19T05:20:08.838540-05:00 mtcdt chat[21631]: expect (OK)
2018-10-19T05:20:08.838871-05:00 mtcdt chat[21631]: ^M
2018-10-19T05:20:08.842902-05:00 mtcdt chat[21631]: ^M
2018-10-19T05:20:08.844739-05:00 mtcdt chat[21631]: ERROR
2018-10-19T05:20:08.846138-05:00 mtcdt chat[21631]:  -- failed
2018-10-19T05:20:08.847784-05:00 mtcdt chat[21631]: Failed (ERROR)
2018-10-19T05:20:08.851221-05:00 mtcdt pppd[21628]: Connect script failed

/var/log/ppp_trace

13:20:3:   Connecting for 0 time
13:20:8:   Physical link failed
13:20:39:   Current timing  60
13:20:39:   Sleeping 24 seconds before next attempt
13:21:3:   Connecting for 1 time
13:21:9:   Physical link failed
13:21:40:   Current timing  60
13:21:40:   Sleeping 24 seconds before next attempt
13:22:4:   Connecting for 2 time
13:22:9:   Physical link failed
13:22:40:   Current timing  60
13:22:40:   Sleeping 23 seconds before next attempt
13:23:3:   Connecting for 3 time
13:23:8:   Physical link failed

Both firmware have the same

/var/run/config/ppp_options and /var/run/config/ppp_chat

/dev/modem_at0
115200
crtscts
linkname ppp0
# disable logging to /etc/ppp/connect-errors
logfile /dev/null
# keep daemon up and redial when needed
persist
# log debug to syslog
debug
defaultroute
usepeerdns
connect 'chat -v -c -t 90 -f /var/run/config/ppp_chat'
# don't negotiate MRU (G3 bug)
-mru
pap-max-authreq 0
chap-max-challenge 0
noccp
novj
maxfail 0
0.0.0.0:
noipdefault
user user<code></code>
"" "AT"
"OK" "AT"
"ABORT" "NO CARRIER"
"ABORT" "BUSY"
"ABORT" "ERROR"
"OK" "AT+CSQ"
"OK" "AT+CGDCONT=1,\"IP\",\"XXX.XXX.XX\""
"OK" "ATDT*99***1#"
"CONNECT" ""

ps -A

1.6.2       21628 ?        00:00:00 pppd
1.4.16      7897 ttyUSB2  00:00:00 pppd

and finally

dmesg 1.4.16

usb usb1: Manufacturer: Linux 3.12.27r15 ehci_hcd
usb usb1: SerialNumber: 700000.ehci
hub 1-0:1.0: USB hub found
hub 1-0:1.0: 3 ports detected
ohci_hcd: USB 1.1 'Open' Host Controller (OHCI) Driver
at91_ohci 600000.ohci: AT91 OHCI
at91_ohci 600000.ohci: new USB bus registered, assigned bus number 2
at91_ohci 600000.ohci: irq 31, io mem 0x00600000
usb usb2: New USB device found, idVendor=1d6b, idProduct=0001
usb usb2: New USB device strings: Mfr=3, Product=2, SerialNumber=1
usb usb2: Product: AT91 OHCI
usb usb2: Manufacturer: Linux 3.12.27r15 ohci_hcd
usb usb2: SerialNumber: at91
hub 2-0:1.0: USB hub found
hub 2-0:1.0: 3 ports detected
rtc (null): invalid alarm value: 1900-1-1 0:0:0
at91_rtc fffffeb0.rtc: rtc core: registered fffffeb0.rtc as rtc0
at91_rtc fffffeb0.rtc: AT91 Real Time Clock driver.
i2c /dev entries driver
at91sam9_wdt: enabled (heartbeat=15 sec, nowayout=0)
Netfilter messages via NETLINK v0.30.
nf_conntrack version 0.5.0 (3964 buckets, 15856 max)
ipip: IPv4 over IPv4 tunneling driver
gre: GRE over IPv4 demultiplexor driver
ip_gre: GRE over IPv4 tunneling driver
IPv4 over IPSec tunneling driver
ip_tables: (C) 2000-2006 Netfilter Core Team
TCP: cubic registered
Initializing XFRM netlink socket
NET: Registered protocol family 10
mip6: Mobile IPv6
sit: IPv6 over IPv4 tunneling driver
NET: Registered protocol family 17
NET: Registered protocol family 15
l2tp_core: L2TP core driver, V2.0
Key type dns_resolver registered
at91_rtc fffffeb0.rtc: setting system clock to 2018-10-19 10:46:41 UTC (1539946001)
usb 2-3: new full-speed USB device number 2 using at91_ohci
usb 2-3: New USB device found, idVendor=04e2, idProduct=1414
usb 2-3: New USB device strings: Mfr=0, Product=0, SerialNumber=0
jffs2: notice: (1) jffs2_build_xattr_subsystem: complete building xattr subsystem, 0 of xdatum (0 unchecked, 0 orphan) and 0 of xref (0 dead, 0 orphan) found.
VFS: Mounted root (jffs2 filesystem) readonly on device 31:8.
devtmpfs: mounted
Freeing unused kernel memory: 168K (c0574000 - c059e000)
udevd[84]: starting version 182
tmp102 0-0048: initialized
pps_core: LinuxPPS API ver. 1 registered
pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <giometti@linux.it>
pps pps0: new PPS source pps.7.-1
pps pps0: Registered IRQ 32 as PPS source
atmel_mci f0008000.mmc: version: 0x504
atmel_mci f0008000.mmc: using dma0chan1 for DMA transfers
usbcore: registered new interface driver cdc_acm
cdc_acm: USB Abstract Control Model driver for USB modems and ISDN adapters
atmel_mci f0008000.mmc: Atmel MCI controller at 0xf0008000 irq 22, 1 slots
atmel_spi f0000000.spi: version: 0x212
atmel_spi f0000000.spi: Using dma0chan2 (tx) and dma0chan3 (rx) for DMA transfers
atmel_spi f0000000.spi: Atmel SPI Controller at 0xf0000000 (irq 28)
atmel_spi f0000000.spi: master is unqueued, this is deprecated
vizzini 2-3:1.0: This device cannot do calls on its own. It is not a modem.
vizzini 2-3:1.0: ttyXRUSB0: XR21v14x usb uart device
vizzini 2-3:1.2: This device cannot do calls on its own. It is not a modem.
vizzini 2-3:1.2: ttyXRUSB1: XR21v14x usb uart device
vizzini 2-3:1.4: This device cannot do calls on its own. It is not a modem.
vizzini 2-3:1.4: ttyXRUSB2: XR21v14x usb uart device
vizzini 2-3:1.6: This device cannot do calls on its own. It is not a modem.
vizzini 2-3:1.6: ttyXRUSB3: XR21v14x usb uart device
usbcore: registered new interface driver vizzini
vizzini: Exar USB UART Driver for XR21V141x
atmel_spi f0004000.spi: version: 0x212
atmel_spi f0004000.spi: Using dma1chan0 (tx) and dma1chan1 (rx) for DMA transfers
atmel_spi f0004000.spi: Atmel SPI Controller at 0xf0004000 (irq 29)
atmel_spi f0004000.spi: master is unqueued, this is deprecated
atmel_usba_udc 500000.gadget: MMIO registers at 0xf803c000 mapped at d0b6a000
atmel_usba_udc 500000.gadget: FIFO at 0x00500000 mapped at e1100000
jffs2: notice: (275) jffs2_build_xattr_subsystem: complete building xattr subsystem, 0 of xdatum (0 unchecked, 0 orphan) and 0 of xref (0 dead, 0 orphan) found.
jffs2: notice: (280) jffs2_build_xattr_subsystem: complete building xattr subsystem, 0 of xdatum (0 unchecked, 0 orphan) and 0 of xref (0 dead, 0 orphan) found.
jffs2: notice: (272) check_node_data: wrong data CRC in data node at 0x0036a990: read 0xe53944b, calculated 0x221fd44d.
[INFO] mts-io:mts_io_init:1007: init: v1.5.16
[INFO] mts-io:mts_id_eeprom_load:913: detected board MTCDTIP-0.0
[INFO] mts-io:mts_id_eeprom_load:921: sizeof: 512
[INFO] mts-io:mts_id_eeprom_load:922: vendor-id: Multi-Tech Systems
[INFO] mts-io:mts_id_eeprom_load:923: product-id: MTCDTIP-LEU1-266A
[INFO] mts-io:mts_id_eeprom_load:924: device-id: 19852181
[INFO] mts-io:mts_id_eeprom_load:925: hw-version: MTCDTIP-0.0
[INFO] mts-io:mts_id_eeprom_load:932: mac-addr: 00:08:00:4A:5F:92
[INFO] mts-io:mts_id_eeprom_load:934: imei: 359852054447553
[INFO] mts-io:mts_id_eeprom_load:935: capa-gps: yes
[INFO] mts-io:mts_id_eeprom_load:936: capa-din: no
[INFO] mts-io:mts_id_eeprom_load:937: capa-dout: no
[INFO] mts-io:mts_id_eeprom_load:938: capa-adc: no
[INFO] mts-io:mts_id_eeprom_load:939: capa-wifi: no
[INFO] mts-io:mts_id_eeprom_load:940: capa-bluetooth: no
[INFO] mts-io:mts_id_eeprom_load:941: capa-lora: no
[INFO] mts-io:mts_id_eeprom_load:966: uuid: 28C80ED1812F996116FF5EAA42F1A216
[INFO] mts-io:load_port:729: accessory card 1 vendor-id: Multi-Tech Systems
[INFO] mts-io:load_port:730: accessory card 1 product-id: MTAC-LORA-H-868
[INFO] mts-io:load_port:731: accessory card 1 device-id: 19801746
[INFO] mts-io:load_port:732: accessory card 1 hw-version: MTAC-LORA-1.5
[INFO] mts-io:load_port:753: accessory card 1 eui: 00:80:00:00:A0:00:31:DD
[INFO] mts-io:lora_setup:60: loading LORA accessory card in port 1
[INFO] mts-io:lora_setup:90: created link [lora] to [ap1], success:0
[INFO] mts-io:lora_setup:125: Substitute pins
[INFO] mts-io:lora_setup:131: LORA H: Replace name AP1_GPIO1 with name AP1_CDONE
[INFO] mts-io:lora_setup:132: LORA H: Replace pin number 70 with number 70
[INFO] mts-io:lora_setup:131: LORA H: Replace name AP1_GPIO2 with name AP1_CRESET
[INFO] mts-io:lora_setup:132: LORA H: Replace pin number 71 with number 71
[INFO] mts-io:lora_setup:189: ap_subdirs[port_index=0] = cf036860 ap_subdirs[port_index=0]=bf0dc948
[INFO] mts-io:load_port:694: no accessory card inserted in port 2
usb 1-2: new high-speed USB device number 2 using atmel-ehci
usb 1-2: New USB device found, idVendor=0424, idProduct=2534
usb 1-2: New USB device strings: Mfr=0, Product=0, SerialNumber=0
hub 1-2:1.0: USB hub found
hub 1-2:1.0: 4 ports detected
[INFO] mts-io:mts_attr_store_radio_reset:289: radio is reset

usb 1-2.1: new high-speed USB device number 3 using atmel-ehci
usb 1-2.1: New USB device found, idVendor=0424, idProduct=2534
usb 1-2.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
hub 1-2.1:1.0: USB hub found
hub 1-2.1:1.0: 4 ports detected
usb 1-2.3: new full-speed USB device number 4 using atmel-ehci
usb 1-2.3: new high-speed USB device number 5 using atmel-ehci
usb 1-2.3: device not accepting address 5, error -71
usb 1-2: USB disconnect, device number 2
usb 1-2.1: USB disconnect, device number 3
usb 1-2: new high-speed USB device number 7 using atmel-ehci
usb 1-2: New USB device found, idVendor=0424, idProduct=2534
usb 1-2: New USB device strings: Mfr=0, Product=0, SerialNumber=0
hub 1-2:1.0: USB hub found
hub 1-2:1.0: 4 ports detected
usb 1-2.1: new high-speed USB device number 8 using atmel-ehci
usb 1-2.1: New USB device found, idVendor=0424, idProduct=2534
usb 1-2.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
hub 1-2.1:1.0: USB hub found
hub 1-2.1:1.0: 4 ports detected
IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
macb f802c000.ethernet eth0: link up (100/Full)
IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
usb 1-2.3: new high-speed USB device number 9 using atmel-ehci
usb 1-2.3: New USB device found, idVendor=1bc7, idProduct=1201
usb 1-2.3: New USB device strings: Mfr=1, Product=2, SerialNumber=3
usb 1-2.3: Product: Android
usb 1-2.3: Manufacturer: Android
usb 1-2.3: SerialNumber: 0123456789ABCDEF
usbcore: registered new interface driver usbserial
usbcore: registered new interface driver usbserial_generic
usbserial: USB Serial support registered for generic
usbcore: registered new interface driver cdc_wdm
usb-storage 1-2.3:1.7: USB Mass Storage device detected
scsi0 : usb-storage 1-2.3:1.7
usbcore: registered new interface driver usb-storage
qmi_wwan 1-2.3:1.2: cdc-wdm0: USB WDM device
qmi_wwan 1-2.3:1.2 wwan0: register 'qmi_wwan' at usb-700000.ehci-2.3, WWAN/QMI device, 5a:11:db:18:60:6e
usbcore: registered new interface driver qmi_wwan
usbcore: registered new interface driver option
usbserial: USB Serial support registered for GSM modem (1-port)
option 1-2.3:1.0: GSM modem (1-port) converter detected
usb 1-2.3: GSM modem (1-port) converter now attached to ttyUSB0
option 1-2.3:1.3: GSM modem (1-port) converter detected
usb 1-2.3: GSM modem (1-port) converter now attached to ttyUSB1
option 1-2.3:1.4: GSM modem (1-port) converter detected
usb 1-2.3: GSM modem (1-port) converter now attached to ttyUSB2
option 1-2.3:1.5: GSM modem (1-port) converter detected
usb 1-2.3: GSM modem (1-port) converter now attached to ttyUSB3
option 1-2.3:1.6: GSM modem (1-port) converter detected
usb 1-2.3: GSM modem (1-port) converter now attached to ttyUSB4
scsi 0:0:0:0: Direct-Access     Linux    File-CD Gadget   0000 PQ: 0 ANSI: 2
sd 0:0:0:0: [sda] Attached SCSI removable disk
g_serial gadget: Gadget Serial v2.4
g_serial gadget: g_serial ready
Bluetooth: Core ver 2.16
NET: Registered protocol family 31
Bluetooth: HCI device and connection manager initialized
Bluetooth: HCI socket layer initialized
Bluetooth: L2CAP socket layer initialized
Bluetooth: SCO socket layer initialized

and finally

dmesg 1.6.2

[INFO] mts-io:lora_setup:90: created link [lora] to [ap1], success:0
[INFO] mts-io:lora_setup:126: Substitute pins
[INFO] mts-io:lora_setup:131: LORA H: Replace name AP1_GPIO1 with name AP1_CDONE
[INFO] mts-io:lora_setup:132: LORA H: Replace pin number 70 with number 70
[INFO] mts-io:lora_setup:131: LORA H: Replace name AP1_GPIO2 with name AP1_CRESET
[INFO] mts-io:lora_setup:132: LORA H: Replace pin number 71 with number 71
[INFO] mts-io:lora_setup:189: ap_subdirs[port_index=0] = cf074ca0 ap_subdirs[port_index=0]=bf0d01b0
[INFO] mts-io:load_port:755: no accessory card inserted in port 2
usb 1-2: new high-speed USB device number 2 using atmel-ehci
usb 1-2: New USB device found, idVendor=0424, idProduct=2534
usb 1-2: New USB device strings: Mfr=0, Product=0, SerialNumber=0
hub 1-2:1.0: USB hub found
hub 1-2:1.0: 4 ports detected
usb 1-2.1: new high-speed USB device number 3 using atmel-ehci
usb 1-2.1: New USB device found, idVendor=0424, idProduct=2534
usb 1-2.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
hub 1-2.1:1.0: USB hub found
hub 1-2.1:1.0: 4 ports detected
usb 1-2.3: new full-speed USB device number 4 using atmel-ehci
usb 1-2.3: new high-speed USB device number 5 using atmel-ehci
usb 1-2.3: New USB device found, idVendor=1bc7, idProduct=1201
usb 1-2.3: New USB device strings: Mfr=1, Product=2, SerialNumber=3
usb 1-2.3: Product: Android
usb 1-2.3: Manufacturer: Android
usb 1-2.3: SerialNumber: 0123456789ABCDEF
usbcore: registered new interface driver usbserial
usbcore: registered new interface driver usbserial_generic
usbserial: USB Serial support registered for generic
usbcore: registered new interface driver cdc_wdm
qmi_wwan 1-2.3:1.2: cdc-wdm0: USB WDM device
qmi_wwan 1-2.3:1.2 wwan0: register 'qmi_wwan' at usb-700000.ehci-2.3, WWAN/QMI device, 22:44:2a:19:4b:85
usbcore: registered new interface driver qmi_wwan
usb-storage 1-2.3:1.7: USB Mass Storage device detected
scsi0 : usb-storage 1-2.3:1.7
usbcore: registered new interface driver usb-storage
usbcore: registered new interface driver option
usbserial: USB Serial support registered for GSM modem (1-port)
option 1-2.3:1.0: GSM modem (1-port) converter detected
usb 1-2.3: GSM modem (1-port) converter now attached to ttyUSB0
option 1-2.3:1.3: GSM modem (1-port) converter detected
usb 1-2.3: GSM modem (1-port) converter now attached to ttyUSB1
option 1-2.3:1.4: GSM modem (1-port) converter detected
usb 1-2.3: GSM modem (1-port) converter now attached to ttyUSB2
option 1-2.3:1.5: GSM modem (1-port) converter detected
usb 1-2.3: GSM modem (1-port) converter now attached to ttyUSB3
option 1-2.3:1.6: GSM modem (1-port) converter detected
usb 1-2.3: GSM modem (1-port) converter now attached to ttyUSB4
usb 1-2: USB disconnect, device number 2
usb 1-2.1: USB disconnect, device number 3
usb 1-2.3: USB disconnect, device number 5
option1 ttyUSB0: GSM modem (1-port) converter now disconnected from ttyUSB0
option 1-2.3:1.0: device disconnected
qmi_wwan 1-2.3:1.2 wwan0: unregister 'qmi_wwan' usb-700000.ehci-2.3, WWAN/QMI device
udevd[700]: failed to execute '/lib/udev/gpsd.hotplug.wrapper' '/lib/udev/gpsd.hotplug.wrapper': No such file or directory
option1 ttyUSB1: GSM modem (1-port) converter now disconnected from ttyUSB1
option 1-2.3:1.3: device disconnected
option1 ttyUSB2: GSM modem (1-port) converter now disconnected from ttyUSB2
option 1-2.3:1.4: device disconnected
option1 ttyUSB3: GSM modem (1-port) converter now disconnected from ttyUSB3
option 1-2.3:1.5: device disconnected
udevd[703]: failed to execute '/lib/udev/gpsd.hotplug.wrapper' '/lib/udev/gpsd.hotplug.wrapper': No such file or directory
option1 ttyUSB4: GSM modem (1-port) converter now disconnected from ttyUSB4
option 1-2.3:1.6: device disconnected
udevd[705]: failed to execute '/lib/udev/gpsd.hotplug.wrapper' '/lib/udev/gpsd.hotplug.wrapper': No such file or directory
udevd[706]: failed to execute '/lib/udev/gpsd.hotplug.wrapper' '/lib/udev/gpsd.hotplug.wrapper': No such file or directory
udevd[707]: failed to execute '/lib/udev/gpsd.hotplug.wrapper' '/lib/udev/gpsd.hotplug.wrapper': No such file or directory
usb 1-2: new high-speed USB device number 6 using atmel-ehci
usb 1-2: New USB device found, idVendor=0424, idProduct=2534
usb 1-2: New USB device strings: Mfr=0, Product=0, SerialNumber=0
hub 1-2:1.0: USB hub found
hub 1-2:1.0: 4 ports detected
usb 1-2.1: new high-speed USB device number 7 using atmel-ehci
usb 1-2.1: New USB device found, idVendor=0424, idProduct=2534
usb 1-2.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
hub 1-2.1:1.0: USB hub found
hub 1-2.1:1.0: 4 ports detected
usb 1-2.3: new full-speed USB device number 8 using atmel-ehci
usb 1-2.3: new high-speed USB device number 9 using atmel-ehci
usb 1-2.3: New USB device found, idVendor=1bc7, idProduct=1201
usb 1-2.3: New USB device strings: Mfr=1, Product=2, SerialNumber=3
usb 1-2.3: Product: Android
usb 1-2.3: Manufacturer: Android
usb 1-2.3: SerialNumber: 0123456789ABCDEF
option 1-2.3:1.0: GSM modem (1-port) converter detected
usb 1-2.3: GSM modem (1-port) converter now attached to ttyUSB0
qmi_wwan 1-2.3:1.2: cdc-wdm0: USB WDM device
qmi_wwan 1-2.3:1.2 wwan0: register 'qmi_wwan' at usb-700000.ehci-2.3, WWAN/QMI device, 22:44:2a:19:4b:85
option 1-2.3:1.3: GSM modem (1-port) converter detected
usb 1-2.3: GSM modem (1-port) converter now attached to ttyUSB1
option 1-2.3:1.4: GSM modem (1-port) converter detected
usb 1-2.3: GSM modem (1-port) converter now attached to ttyUSB2
option 1-2.3:1.5: GSM modem (1-port) converter detected
usb 1-2.3: GSM modem (1-port) converter now attached to ttyUSB3
option 1-2.3:1.6: GSM modem (1-port) converter detected
usb 1-2.3: GSM modem (1-port) converter now attached to ttyUSB4
usb-storage 1-2.3:1.7: USB Mass Storage device detected
scsi1 : usb-storage 1-2.3:1.7
scsi 1:0:0:0: Direct-Access     Linux    File-CD Gadget   0000 PQ: 0 ANSI: 2
sd 1:0:0:0: [sda] Attached SCSI removable disk
IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
macb f802c000.ethernet eth0: link up (100/Full)
IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
g_serial gadget: Gadget Serial v2.4
g_serial gadget: g_serial ready
Bluetooth: Core ver 2.16
NET: Registered protocol family 31
Bluetooth: HCI device and connection manager initialized
Bluetooth: HCI socket layer initialized
Bluetooth: L2CAP socket layer initialized
Bluetooth: SCO socket layer initialized
jffs2: warning: (4800) jffs2_sum_write_data: Not enough space for summary, padsize = -622
[INFO] mts-io:mts_attr_store_radio_reset:345: radio is reset

usb 1-2.3: USB disconnect, device number 9
option1 ttyUSB2: usb_wwan_indat_callback: resubmit read urb failed. (-19)
option1 ttyUSB2: usb_wwan_indat_callback: resubmit read urb failed. (-19)
option1 ttyUSB2: usb_wwan_indat_callback: resubmit read urb failed. (-19)
option1 ttyUSB0: GSM modem (1-port) converter now disconnected from ttyUSB0
option1 ttyUSB2: usb_wwan_indat_callback: resubmit read urb failed. (-19)
option 1-2.3:1.0: device disconnected
qmi_wwan 1-2.3:1.2 wwan0: unregister 'qmi_wwan' usb-700000.ehci-2.3, WWAN/QMI device
udevd[9712]: failed to execute '/lib/udev/gpsd.hotplug.wrapper' '/lib/udev/gpsd.hotplug.wrapper': No such file or directory
option1 ttyUSB1: GSM modem (1-port) converter now disconnected from ttyUSB1
option 1-2.3:1.3: device disconnected
udevd[9716]: failed to execute '/lib/udev/gpsd.hotplug.wrapper' '/lib/udev/gpsd.hotplug.wrapper': No such file or directory
option1 ttyUSB2: GSM modem (1-port) converter now disconnected from ttyUSB2
udevd[9717]: failed to execute '/lib/udev/gpsd.hotplug.wrapper' '/lib/udev/gpsd.hotplug.wrapper': No such file or directory
option 1-2.3:1.4: device disconnected
option1 ttyUSB3: GSM modem (1-port) converter now disconnected from ttyUSB3
option 1-2.3:1.5: device disconnected
option1 ttyUSB4: GSM modem (1-port) converter now disconnected from ttyUSB4
udevd[9720]: failed to execute '/lib/udev/gpsd.hotplug.wrapper' '/lib/udev/gpsd.hotplug.wrapper': No such file or directory
option 1-2.3:1.6: device disconnected
udevd[9728]: failed to execute '/lib/udev/gpsd.hotplug.wrapper' '/lib/udev/gpsd.hotplug.wrapper': No such file or directory
usb 1-2.3: new high-speed USB device number 10 using atmel-ehci
usb 1-2.3: New USB device found, idVendor=1bc7, idProduct=1201
usb 1-2.3: New USB device strings: Mfr=1, Product=2, SerialNumber=3
usb 1-2.3: Product: Android
usb 1-2.3: Manufacturer: Android
usb 1-2.3: SerialNumber: 0123456789ABCDEF
option 1-2.3:1.0: GSM modem (1-port) converter detected
usb 1-2.3: GSM modem (1-port) converter now attached to ttyUSB0
qmi_wwan 1-2.3:1.2: cdc-wdm0: USB WDM device
qmi_wwan 1-2.3:1.2 wwan0: register 'qmi_wwan' at usb-700000.ehci-2.3, WWAN/QMI device, 22:44:2a:19:4b:85
option 1-2.3:1.3: GSM modem (1-port) converter detected
usb 1-2.3: GSM modem (1-port) converter now attached to ttyUSB1
option 1-2.3:1.4: GSM modem (1-port) converter detected
usb 1-2.3: GSM modem (1-port) converter now attached to ttyUSB2
option 1-2.3:1.5: GSM modem (1-port) converter detected
usb 1-2.3: GSM modem (1-port) converter now attached to ttyUSB3
option 1-2.3:1.6: GSM modem (1-port) converter detected
usb 1-2.3: GSM modem (1-port) converter now attached to ttyUSB4
usb-storage 1-2.3:1.7: USB Mass Storage device detected
scsi2 : usb-storage 1-2.3:1.7
scsi 2:0:0:0: Direct-Access     Linux    File-CD Gadget   0000 PQ: 0 ANSI: 2
sd 2:0:0:0: [sda] Attached SCSI removable disk

[Stelios Pa]

Update:

Even after I take out the SIM card, obviously the connection is lost, the pppd and chat seems to ignore it and reconnects ?

2018-10-22T15:37:50.499389+03:00 mtcdt pppcheck: KeepAlive: 4 consecutive ping failures.  Hanging up and redialing ...
2018-10-22T15:37:50.572863+03:00 mtcdt pppd[1852]: Hangup (SIGHUP)
2018-10-22T15:37:50.580653+03:00 mtcdt pppd[1852]: Connect time 5.7 minutes.
2018-10-22T15:37:50.581741+03:00 mtcdt pppd[1852]: Sent 480 bytes, received 240 bytes.
2018-10-22T15:37:53.289125+03:00 mtcdt pppd[1852]: Connection terminated.
2018-10-22T15:37:53.352800+03:00 mtcdt pppd[1852]: Hangup (SIGHUP)
2018-10-22T15:37:54.674415+03:00 mtcdt chat[4784]: info: Attempting Basic Radio Communication
2018-10-22T15:37:54.675655+03:00 mtcdt chat[4784]: send (AT^M)
2018-10-22T15:37:54.710316+03:00 mtcdt chat[4784]: expect (OK)
2018-10-22T15:37:54.714105+03:00 mtcdt chat[4784]: ^M
2018-10-22T15:37:54.714438+03:00 mtcdt chat[4784]: OK
2018-10-22T15:37:54.714659+03:00 mtcdt chat[4784]:  -- got it
2018-10-22T15:37:54.714910+03:00 mtcdt chat[4784]: info: Checking if SIM is inserted
2018-10-22T15:37:54.715139+03:00 mtcdt chat[4784]: send (AT#SIMDET?^M)
2018-10-22T15:37:54.828411+03:00 mtcdt chat[4784]: expect (#SIMDET: 2,1)
2018-10-22T15:37:54.828740+03:00 mtcdt chat[4784]: ^M
2018-10-22T15:37:54.832907+03:00 mtcdt chat[4784]: ^M
2018-10-22T15:37:54.845968+03:00 mtcdt chat[4784]: #SIMDET: 2,1
2018-10-22T15:37:54.850328+03:00 mtcdt chat[4784]:  -- got it
2018-10-22T15:37:54.856521+03:00 mtcdt chat[4784]: info: Checking if SIM is locked
<strong>2018-10-22T15:37:54.857832+03:00 mtcdt chat[4784]: send (AT+CPIN?^M)
2018-10-22T15:37:54.951258+03:00 mtcdt chat[4784]: expect (READY)
2018-10-22T15:37:54.951594+03:00 mtcdt chat[4784]: ^M
2018-10-22T15:37:54.951858+03:00 mtcdt chat[4784]: ^M
2018-10-22T15:37:54.952131+03:00 mtcdt chat[4784]: OK^M
2018-10-22T15:37:54.955405+03:00 mtcdt chat[4784]: ^M
2018-10-22T15:37:54.955777+03:00 mtcdt chat[4784]: +CPIN: READY</strong>
2018-10-22T15:37:54.955992+03:00 mtcdt chat[4784]:  -- got it
2018-10-22T15:37:54.956233+03:00 mtcdt chat[4784]: info: SIM was unlocked
2018-10-22T15:37:54.956455+03:00 mtcdt chat[4784]: info: Waiting for minimum signal strength
2018-10-22T15:37:54.956678+03:00 mtcdt chat[4784]: send (AT+CSQ^M)
2018-10-22T15:37:55.031694+03:00 mtcdt chat[4784]: expect (+CSQ: )
2018-10-22T15:37:55.032016+03:00 mtcdt chat[4784]: ^M
2018-10-22T15:37:55.032279+03:00 mtcdt chat[4784]: ^M
2018-10-22T15:37:55.032557+03:00 mtcdt chat[4784]: OK^M
2018-10-22T15:37:55.036386+03:00 mtcdt chat[4784]: ^M
2018-10-22T15:37:55.036693+03:00 mtcdt chat[4784]: +CSQ:
2018-10-22T15:37:55.036908+03:00 mtcdt chat[4784]:  -- got it
2018-10-22T15:37:55.037146+03:00 mtcdt chat[4784]: expect (99,99)
2018-10-22T15:37:55.037479+03:00 mtcdt chat[4784]: 20,99^M
2018-10-22T15:37:55.037736+03:00 mtcdt chat[4784]: ^M
2018-10-22T15:37:55.038005+03:00 mtcdt chat[4784]: OK^M
2018-10-22T15:37:56.040735+03:00 mtcdt chat[4784]: alarm
2018-10-22T15:37:56.041476+03:00 mtcdt chat[4784]: send (AT^M)
2018-10-22T15:37:56.072660+03:00 mtcdt chat[4784]: expect (OK)
2018-10-22T15:37:56.076639+03:00 mtcdt chat[4784]: ^M
2018-10-22T15:37:56.076946+03:00 mtcdt chat[4784]: OK
2018-10-22T15:37:56.077164+03:00 mtcdt chat[4784]:  -- got it
2018-10-22T15:37:56.077425+03:00 mtcdt chat[4784]: send (AT^M)
2018-10-22T15:37:56.108551+03:00 mtcdt chat[4784]: abort on (NO CARRIER)
2018-10-22T15:37:56.108829+03:00 mtcdt chat[4784]: abort on (BUSY)
2018-10-22T15:37:56.109077+03:00 mtcdt chat[4784]: abort on (ERROR)
2018-10-22T15:37:56.109319+03:00 mtcdt chat[4784]: expect (OK)
2018-10-22T15:37:56.109616+03:00 mtcdt chat[4784]: ^M
2018-10-22T15:37:56.112705+03:00 mtcdt chat[4784]: ^M
2018-10-22T15:37:56.113011+03:00 mtcdt chat[4784]: OK
2018-10-22T15:37:56.123677+03:00 mtcdt chat[4784]:  -- got it
2018-10-22T15:37:56.127214+03:00 mtcdt chat[4784]: send (AT+CSQ^M)
2018-10-22T15:37:56.203873+03:00 mtcdt chat[4784]: expect (OK)
2018-10-22T15:37:56.204212+03:00 mtcdt chat[4784]: ^M
2018-10-22T15:37:56.208027+03:00 mtcdt chat[4784]: ^M
2018-10-22T15:37:56.208428+03:00 mtcdt chat[4784]: +CSQ: 20,99^M
2018-10-22T15:37:56.208698+03:00 mtcdt chat[4784]: ^M
2018-10-22T15:37:56.208970+03:00 mtcdt chat[4784]: OK
2018-10-22T15:37:56.209183+03:00 mtcdt chat[4784]:  -- got it
2018-10-22T15:37:56.209450+03:00 mtcdt chat[4784]: send (AT+CGDCONT=1,\"IP\",\"XX.XX.XX.XX\"^M)
2018-10-22T15:37:56.652476+03:00 mtcdt chat[4784]: expect (OK)
2018-10-22T15:37:56.652807+03:00 mtcdt chat[4784]: ^M
2018-10-22T15:37:56.670669+03:00 mtcdt chat[4784]: ^M
2018-10-22T15:37:56.670963+03:00 mtcdt chat[4784]: OK
2018-10-22T15:37:56.671177+03:00 mtcdt chat[4784]:  -- got it
2018-10-22T15:37:56.671426+03:00 mtcdt chat[4784]: send (ATDT*99***1#^M)
2018-10-22T15:37:56.806693+03:00 mtcdt chat[4784]: expect (CONNECT)
2018-10-22T15:37:56.807016+03:00 mtcdt chat[4784]: ^M
2018-10-22T15:37:56.813824+03:00 mtcdt chat[4784]: ^M
2018-10-22T15:37:56.814159+03:00 mtcdt chat[4784]: CONNECT
2018-10-22T15:37:56.814363+03:00 mtcdt chat[4784]:  -- got it
2018-10-22T15:37:56.814605+03:00 mtcdt chat[4784]: send (^M)
2018-10-22T15:37:56.827046+03:00 mtcdt pppd[1852]: Serial connection established.
2018-10-22T15:37:56.832807+03:00 mtcdt pppd[1852]: Using interface ppp0
2018-10-22T15:37:56.864767+03:00 mtcdt pppd[1852]: Connect: ppp0 <--> /dev/modem_at0
2018-10-22T15:37:57.914887+03:00 mtcdt pppd[1852]: CHAP authentication succeeded
2018-10-22T15:37:57.915203+03:00 mtcdt pppd[1852]: CHAP authentication succeeded
2018-10-22T15:37:57.945277+03:00 mtcdt pppd[1852]: Could not determine remote IP address: defaulting to 10.64.64.64
2018-10-22T15:37:57.972709+03:00 mtcdt pppd[1852]: local  IP address 100.XX.XX.XX
2018-10-22T15:37:57.973684+03:00 mtcdt pppd[1852]: remote IP address 10.64.64.64
2018-10-22T15:37:57.974341+03:00 mtcdt pppd[1852]: primary   DNS address 213.XX.XX.XX
2018-10-22T15:37:57.975004+03:00 mtcdt pppd[1852]: secondary DNS address 213.XX.XX.XX
2018-10-22T15:37:59.816623+03:00 mtcdt ppp-rx-monitor: Started Monitoring

[Jeff Hatch]

Hello Stelios,

Please open a Multitech Support Portal ticket for help with this at https://support.multitech.com.

Thank You,

Jeff

[Stelios Pa]

Thanks Jeff!

[Author]

Posts