We have a problem with part of our devices which are using ppp to connect to the internet using 3G modem in US. The issue seems really odd as only few of the devices have this problem but it is a permanent problem on them (connection was never established). Here are the logs with debug mode ON from the device which get timeout:
May 9 18:49:06 AppName1 kernel: [ 810.365121]
May 9 18:49:07 AppName1 pppd[1640]: pppd 2.4.6 started by root, uid 0
May 9 18:49:07 AppName1 pppd[1640]: using channel 1
May 9 18:49:07 AppName1 pppd[1640]: Using interface ppp0
May 9 18:49:07 AppName1 pppd[1640]: Connect: ppp0 <--> /dev/ttyUSB3
May 9 18:49:07 AppName1 pppd[1640]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0xa1e27395> <pcomp> <accomp>]
May 9 18:49:07 AppName1 pppd[1640]: rcvd [LCP ConfReq id=0x0 <asyncmap 0x0> <auth chap MD5> <magic 0x45291790> <pcomp> <accomp>]
May 9 18:49:07 AppName1 pppd[1640]: sent [LCP ConfAck id=0x0 <asyncmap 0x0> <auth chap MD5> <magic 0x45291790> <pcomp> <accomp>]
May 9 18:49:07 AppName1 pppd[1640]: rcvd [LCP ConfAck id=0x1 <asyncmap 0x0> <magic 0xa1e27395> <pcomp> <accomp>]
May 9 18:49:07 AppName1 pppd[1640]: sent [LCP EchoReq id=0x0 magic=0xa1e27395]
May 9 18:49:07 AppName1 pppd[1640]: rcvd [LCP DiscReq id=0x1 magic=0x45291790]
May 9 18:49:07 AppName1 pppd[1640]: rcvd [CHAP Challenge id=0x1 <9ee875714217fbf3306bb4e92e94e943>, name = "UMTS_CHAP_SRVR"]
May 9 18:49:07 AppName1 pppd[1640]: sent [CHAP Response id=0x1 <c1fe100b1636f52bf0cf44bbe34210b1>, name = "AppName1"]
May 9 18:49:07 AppName1 pppd[1640]: rcvd [LCP EchoRep id=0x0 magic=0x45291790 a1 e2 73 95]
May 9 18:49:07 AppName1 pppd[1640]: rcvd [CHAP Success id=0x1 ""]
May 9 18:49:07 AppName1 pppd[1640]: CHAP authentication succeeded
May 9 18:49:07 AppName1 pppd[1640]: CHAP authentication succeeded
May 9 18:49:07 AppName1 pppd[1640]: sent [CCP ConfReq id=0x1 <deflate 15> <deflate(old#) 15> <bsd v1 15>]
May 9 18:49:07 AppName1 pppd[1640]: sent [IPCP ConfReq id=0x1 <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns2 0.0.0.0>]
May 9 18:49:07 AppName1 pppd[1640]: rcvd [LCP ProtRej id=0x2 80 fd 01 01 00 0f 1a 04 78 00 18 04 78 00 15 03 2f]
May 9 18:49:07 AppName1 pppd[1640]: Protocol-Reject for 'Compression Control Protocol' (0x80fd) received
May 9 18:49:10 AppName1 pppd[1640]: sent [IPCP ConfReq id=0x1 <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns2 0.0.0.0>]
May 9 18:49:13 AppName1 pppd[1640]: sent [IPCP ConfReq id=0x1 <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns2 0.0.0.0>]
May 9 18:49:16 AppName1 pppd[1640]: sent [IPCP ConfReq id=0x1 <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns2 0.0.0.0>]
May 9 18:49:19 AppName1 pppd[1640]: sent [IPCP ConfReq id=0x1 <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns2 0.0.0.0>]
May 9 18:49:22 AppName1 pppd[1640]: sent [IPCP ConfReq id=0x1 <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns2 0.0.0.0>]
May 9 18:49:25 AppName1 pppd[1640]: sent [IPCP ConfReq id=0x1 <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns2 0.0.0.0>]
May 9 18:49:28 AppName1 pppd[1640]: sent [IPCP ConfReq id=0x1 <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns2 0.0.0.0>]
May 9 18:49:31 AppName1 pppd[1640]: sent [IPCP ConfReq id=0x1 <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns2 0.0.0.0>]
May 9 18:49:32 AppName1 dhclient: DHCPDISCOVER on eth0 to 255.255.255.255 port 67 interval 7
May 9 18:49:34 AppName1 pppd[1640]: sent [IPCP ConfReq id=0x1 <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns2 0.0.0.0>]
May 9 18:49:37 AppName1 pppd[1640]: sent [LCP EchoReq id=0x1 magic=0xa1e27395]
May 9 18:49:37 AppName1 pppd[1640]: IPCP: timeout sending Config-Requests
May 9 18:49:37 AppName1 pppd[1640]: sent [LCP TermReq id=0x2 "No network protocols running"]
May 9 18:49:39 AppName1 dhclient: DHCPDISCOVER on eth0 to 255.255.255.255 port 67 interval 14
May 9 18:49:40 AppName1 pppd[1640]: sent [LCP TermReq id=0x3 "No network protocols running"]
May 9 18:49:43 AppName1 pppd[1640]: Connection terminated.
May 9 18:49:43 AppName1 pppd[1640]: Modem hangup
For comparison here is the log of correctly working device:
May 9 20:00:15 AppName1 kernel: [ 72.451218]
May 9 20:00:16 AppName1 pppd[1406]: pppd 2.4.6 started by root, uid 0
May 9 20:00:16 AppName1 pppd[1406]: using channel 1
May 9 20:00:16 AppName1 pppd[1406]: Using interface ppp0
May 9 20:00:16 AppName1 pppd[1406]: Connect: ppp0 <--> /dev/ttyUSB3
May 9 20:00:16 AppName1 pppd[1406]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x21e96b39> <pcomp> <accomp>]
May 9 20:00:16 AppName1 pppd[1406]: rcvd [LCP ConfReq id=0x0 <asyncmap 0x0> <auth chap MD5> <magic 0x451c1623> <pcomp> <accomp>]
May 9 20:00:16 AppName1 pppd[1406]: sent [LCP ConfAck id=0x0 <asyncmap 0x0> <auth chap MD5> <magic 0x451c1623> <pcomp> <accomp>]
May 9 20:00:16 AppName1 pppd[1406]: rcvd [LCP ConfAck id=0x1 <asyncmap 0x0> <magic 0x21e96b39> <pcomp> <accomp>]
May 9 20:00:16 AppName1 pppd[1406]: sent [LCP EchoReq id=0x0 magic=0x21e96b39]
May 9 20:00:16 AppName1 pppd[1406]: rcvd [LCP DiscReq id=0x1 magic=0x451c1623]
May 9 20:00:16 AppName1 pppd[1406]: rcvd [CHAP Challenge id=0x1 <38f21dc5a29f0931d45dcf6e204219f0>, name = "UMTS_CHAP_SRVR"]
May 9 20:00:16 AppName1 pppd[1406]: sent [CHAP Response id=0x1 <c50702c97f49e37f8e9b519ed363086e>, name = "AppName1"]
May 9 20:00:16 AppName1 pppd[1406]: rcvd [LCP EchoRep id=0x0 magic=0x451c1623 21 e9 6b 39]
May 9 20:00:16 AppName1 pppd[1406]: rcvd [CHAP Success id=0x1 ""]
May 9 20:00:16 AppName1 pppd[1406]: CHAP authentication succeeded
May 9 20:00:16 AppName1 pppd[1406]: CHAP authentication succeeded
May 9 20:00:16 AppName1 pppd[1406]: sent [CCP ConfReq id=0x1 <deflate 15> <deflate(old#) 15> <bsd v1 15>]
May 9 20:00:16 AppName1 pppd[1406]: sent [IPCP ConfReq id=0x1 <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns2 0.0.0.0>]
May 9 20:00:16 AppName1 pppd[1406]: rcvd [LCP ProtRej id=0x2 80 fd 01 01 00 0f 1a 04 78 00 18 04 78 00 15 03 2f]
May 9 20:00:16 AppName1 pppd[1406]: Protocol-Reject for 'Compression Control Protocol' (0x80fd) received
May 9 20:00:16 AppName1 pppd[1406]: rcvd [IPCP ConfReq id=0x0]
May 9 20:00:16 AppName1 pppd[1406]: sent [IPCP ConfNak id=0x0 <addr 0.0.0.0>]
May 9 20:00:16 AppName1 pppd[1406]: rcvd [IPCP ConfRej id=0x1 <compress VJ 0f 01>]
May 9 20:00:16 AppName1 pppd[1406]: sent [IPCP ConfReq id=0x2 <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns2 0.0.0.0>]
May 9 20:00:16 AppName1 pppd[1406]: rcvd [IPCP ConfReq id=0x1]
May 9 20:00:16 AppName1 pppd[1406]: sent [IPCP ConfAck id=0x1]
May 9 20:00:16 AppName1 pppd[1406]: rcvd [IPCP ConfNak id=0x2 <addr 100.77.21.211> <ms-dns1 130.244.127.161> <ms-dns2 130.244.127.169>]
May 9 20:00:16 AppName1 pppd[1406]: sent [IPCP ConfReq id=0x3 <addr 100.77.21.211> <ms-dns1 130.244.127.161> <ms-dns2 130.244.127.169>]
May 9 20:00:16 AppName1 pppd[1406]: rcvd [IPCP ConfAck id=0x3 <addr 100.77.21.211> <ms-dns1 130.244.127.161> <ms-dns2 130.244.127.169>]
May 9 20:00:16 AppName1 pppd[1406]: Could not determine remote IP address: defaulting to 10.64.64.64
May 9 20:00:16 AppName1 pppd[1406]: local IP address 100.77.21.211
May 9 20:00:16 AppName1 pppd[1406]: remote IP address 10.64.64.64
May 9 20:00:16 AppName1 pppd[1406]: primary DNS address 130.244.127.161
May 9 20:00:16 AppName1 pppd[1406]: secondary DNS address 130.244.127.169
May 9 20:00:16 AppName1 pppd[1406]: Script /etc/ppp/ip-up started (pid 1413)
May 9 20:00:16 AppName1 pppd[1406]: Script /etc/ppp/ip-up finished (pid 1413), status = 0x0
May 9 20:00:18 AppName1 ntpd_intres[1222]: DNS 0.debian.pool.ntp.org -> 91.209.0.17
May 9 20:00:18 AppName1 ntpd_intres[1222]: DNS 1.debian.pool.ntp.org -> 83.251.208.60
May 9 20:00:18 AppName1 ntpd_intres[1222]: DNS 2.debian.pool.ntp.org -> 91.216.111.52
May 9 20:00:18 AppName1 dhclient: No DHCPOFFERS received.
May 9 20:00:18 AppName1 dhclient: No working leases in persistent database - sleeping.
May 9 20:00:18 AppName1 ifplugd(eth0)[946]: client: No DHCPOFFERS received.
May 9 20:00:18 AppName1 ifplugd(eth0)[946]: client: No working leases in persistent database - sleeping.
May 9 20:00:18 AppName1 ntpd[1214]: Listen normally on 3 ppp0 100.77.21.211 UDP 123
May 9 20:00:18 AppName1 ntpd[1214]: 91.216.111.52 interface 10.0.0.18 -> 100.77.21.211
May 9 20:00:18 AppName1 ntpd[1214]: 83.251.208.60 interface 10.0.0.18 -> 100.77.21.211
May 9 20:00:18 AppName1 ntpd[1214]: 91.209.0.17 interface 10.0.0.18 -> 100.77.21.211
May 9 20:00:18 AppName1 ntpd[1214]: peers refreshed
May 9 20:00:18 AppName1 ntpd_intres[1222]: DNS 3.debian.pool.ntp.org -> 31.220.5.58
May 9 20:00:19 AppName1 ntpdate[1441]: the NTP socket is in use, exiting
May 9 20:00:19 AppName1 ifplugd(eth0)[946]: Program executed successfully.
Any clues what may cause this problem?
ppphas various options to select the compression protocol and to set characters that are valid over the modem connection. Play around with them, esp. with the valid characters (start very conservatively), and see if it fixes the problem. The modem firmware might want to interpret some characters in a special way.