PPPD call on MTCDP-H5 vs MTCDP-E1

[Ben Eisemann]

Hello,

I am trying to migrate some code from a MTCDP-E1 unit to the newer MTCDP-H5. I am using the SIM card and carrier as the previous unit.

When trying to establish a PPPD connection on the MTCDP-H5, it drops the connection almost immediately. I suspect my issue lies in this error report in /var/log/messages:
mtcdp daemon.err pppd[436]: Could not determine local IP address

I also noticed further up in the same file, this error that does not appear when making a connection with the MTCDP-E1:
daemon.warn pppd[436]: kernel does not support PPP filtering

I am able to establish a succesful PPPD connection using the exact same code on an MTCDP-E1 but it disconnects almost immediately when trying to use it on a MTCDP-H5.

I will attach some relevant code:

/etc/ppp/peers

linkname ppp0
230400
defaultroute
replacedefaultroute
usepeerdns
ipcp-max-failure 4
noauth
crtscts
novj
connect '/usr/sbin/chat -v -t 90 -f /custom/att_chat -r /custom/ppp.log'

/custom/att_chat

SAY "GSM chat\n"
ECHO OFF
ABORT 'NO DIAL TONE'
ABORT 'NO DIALTONE'
ABORT 'NO ANSWER'
ABORT 'NO CARRIER'
ABORT 'DELAYED'
ABORT 'VOICE'
ABORT 'BUSY'
'' 'AT'
OK 'AT#CCID' REPORT 'ID:'
OK 'ATZ'
#OK 'AT+CPIN?'
#OK 'AT+CREG?'
#OK 'AT+CSQ'
OK 'AT+CGDCONT=1,"IP","m2m.com.attz"'
SAY "Dialing...\n"
#OK 'AT+CGATT=1'
OK 'ATD*99***1#'
#OK 'AT+CGACT=1, 1'
SAY "Waiting for CONNECT...\n"
# cat /custom/att_chat
SAY "GSM chat\n"
ECHO OFF
ABORT 'NO DIAL TONE'
ABORT 'NO DIALTONE'
ABORT 'NO ANSWER'
ABORT 'NO CARRIER'
ABORT 'DELAYED'
ABORT 'VOICE'
ABORT 'BUSY'
'' 'AT'
OK 'AT#CCID' REPORT 'ID:'
OK 'ATZ'
#OK 'AT+CPIN?'
#OK 'AT+CREG?'
#OK 'AT+CSQ'
OK 'AT+CGDCONT=1,"IP","m2m.com.attz"'
SAY "Dialing...\n"
#OK 'AT+CGATT=1'
OK 'ATD*99***1#'
#OK 'AT+CGACT=1, 1'
SAY "Waiting for CONNECT...\n"
TIMEOUT 120
CONNECT ''
SAY "Connected\n"

/var/log/messages
`Oct 18 09:15:53 mtcdp daemon.notice pppd[489]: pppd 2.4.5 started by root, uid 0
Oct 18 09:15:54 mtcdp local2.info chat[491]: abort on (NO DIAL TONE)
Oct 18 09:15:54 mtcdp local2.info chat[491]: abort on (NO DIALTONE)
Oct 18 09:15:54 mtcdp local2.info chat[491]: abort on (NO ANSWER)
Oct 18 09:15:54 mtcdp local2.info chat[491]: abort on (NO CARRIER)
Oct 18 09:15:54 mtcdp local2.info chat[491]: abort on (DELAYED)
Oct 18 09:15:54 mtcdp local2.info chat[491]: abort on (VOICE)
Oct 18 09:15:54 mtcdp local2.info chat[491]: abort on (BUSY)
Oct 18 09:15:54 mtcdp local2.info chat[491]: send (AT^M)
Oct 18 09:15:54 mtcdp local2.info chat[491]: expect (OK)
Oct 18 09:15:54 mtcdp local2.info chat[491]: AT^M^M
Oct 18 09:15:54 mtcdp local2.info chat[491]: OK
Oct 18 09:15:54 mtcdp local2.info chat[491]: — got it
Oct 18 09:15:54 mtcdp local2.info chat[491]: send (AT#CCID^M)
Oct 18 09:15:54 mtcdp local2.info chat[491]: report (ID:)
Oct 18 09:15:54 mtcdp local2.info chat[491]: expect (OK)
Oct 18 09:15:54 mtcdp local2.info chat[491]: ^M
Oct 18 09:15:54 mtcdp local2.info chat[491]: AT#CCID^M^M
Oct 18 09:15:54 mtcdp local2.info chat[491]: #CCID: 89011704258004789701^M
Oct 18 09:15:54 mtcdp local2.info chat[491]: ^M
Oct 18 09:15:54 mtcdp local2.info chat[491]: OK
Oct 18 09:15:54 mtcdp local2.info chat[491]: — got it
Oct 18 09:15:54 mtcdp local2.info chat[491]: send (ATZ^M)
Oct 18 09:15:55 mtcdp local2.info chat[491]: expect (OK)
Oct 18 09:15:55 mtcdp local2.info chat[491]: ^M
Oct 18 09:15:55 mtcdp local2.info chat[491]: ATZ^M^M
Oct 18 09:15:55 mtcdp local2.info chat[491]: OK
Oct 18 09:15:55 mtcdp local2.info chat[491]: — got it
Oct 18 09:15:55 mtcdp local2.info chat[491]: send (AT+CGDCONT=1,”IP”,”m2m.com.attz”^M)
Oct 18 09:15:55 mtcdp local2.info chat[491]: expect (OK)
Oct 18 09:15:55 mtcdp local2.info chat[491]: ^M
Oct 18 09:15:55 mtcdp local2.info chat[491]: AT+CGDCONT=1,”IP”,”m2m.com.attz”^M^M
Oct 18 09:15:55 mtcdp local2.info chat[491]: OK
Oct 18 09:15:55 mtcdp local2.info chat[491]: — got it
Oct 18 09:15:55 mtcdp local2.info chat[491]: send (ATD*99***1#^M)
Oct 18 09:15:55 mtcdp local2.info chat[491]: timeout set to 120 seconds
Oct 18 09:15:55 mtcdp local2.info chat[491]: expect (CONNECT)
Oct 18 09:15:55 mtcdp local2.info chat[491]: ^M
Oct 18 09:15:55 mtcdp local2.info chat[491]: ATD*99***1#^M^M
Oct 18 09:15:55 mtcdp local2.info chat[491]: CONNECT
Oct 18 09:15:55 mtcdp local2.info chat[491]: — got it
Oct 18 09:15:55 mtcdp local2.info chat[491]: send (^M)
Oct 18 09:15:55 mtcdp daemon.debug pppd[489]: Script /usr/sbin/chat -v -t 90 -f /custom/att_chat -r /custom/ppp.log finished (pid 490), status = 0x0
Oct 18 09:15:55 mtcdp daemon.info pppd[489]: Serial connection established.
Oct 18 09:15:55 mtcdp daemon.debug pppd[489]: using channel 2
Oct 18 09:15:55 mtcdp daemon.info pppd[489]: Using interface ppp0
Oct 18 09:15:55 mtcdp daemon.notice pppd[489]: Connect: ppp0 <–> /dev/modem_at0
Oct 18 09:15:56 mtcdp daemon.debug pppd[489]: rcvd [LCP ConfReq id=0x1 <asyncmap 0x0> <auth pap> <magic 0x4be81200> <pcomp> <accomp>]
Oct 18 09:15:56 mtcdp daemon.warn pppd[489]: Warning – secret file /etc/ppp/pap-secrets has world and/or group access
Oct 18 09:15:56 mtcdp daemon.debug pppd[489]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x694e161d> <pcomp> <accomp>]
Oct 18 09:15:56 mtcdp daemon.debug pppd[489]: sent [LCP ConfAck id=0x1 <asyncmap 0x0> <auth pap> <magic 0x4be81200> <pcomp> <accomp>]
Oct 18 09:15:56 mtcdp daemon.debug pppd[489]: rcvd [LCP ConfAck id=0x1 <asyncmap 0x0> <magic 0x694e161d> <pcomp> <accomp>]
Oct 18 09:15:56 mtcdp daemon.warn pppd[489]: Warning – secret file /etc/ppp/pap-secrets has world and/or group access
Oct 18 09:15:56 mtcdp daemon.debug pppd[489]: sent [PAP AuthReq id=0x1 user=”mtcdp” password=<hidden>]
Oct 18 09:15:56 mtcdp daemon.debug pppd[489]: rcvd [PAP AuthAck id=0x1 “”]
Oct 18 09:15:56 mtcdp daemon.notice pppd[489]: PAP authentication succeeded
Oct 18 09:15:56 mtcdp daemon.warn pppd[489]: kernel does not support PPP filtering
Oct 18 09:15:56 mtcdp daemon.debug pppd[489]: sent [CCP ConfReq id=0x1 <deflate 15> <deflate(old#) 15> <bsd v1 15>]
Oct 18 09:15:56 mtcdp daemon.debug pppd[489]: sent [IPCP ConfReq id=0x1 <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns2 0.0.0.0>]
Oct 18 09:15:56 mtcdp daemon.debug pppd[489]: rcvd [LCP ProtRej id=0x2 80 fd 01 01 00 0f 1a 04 78 00 18 04 78 00 15]
Oct 18 09:15:56 mtcdp daemon.debug pppd[489]: Protocol-Reject for ‘Compression Control Protocol’ (0x80fd) received
Oct 18 09:15:56 mtcdp daemon.debug pppd[489]: rcvd [IPCP ConfNak id=0x1 <ms-dns1 10.11.12.13> <ms-dns2 10.11.12.14>]
Oct 18 09:15:56 mtcdp daemon.debug pppd[489]: sent [IPCP ConfReq id=0x2 <addr 0.0.0.0> <ms-dns1 10.11.12.13> <ms-dns2 10.11.12.14>]
Oct 18 09:15:57 mtcdp daemon.debug pppd[489]: rcvd [IPCP ConfNak id=0x2 <ms-dns1 10.11.12.13> <ms-dns2 10.11.12.14>]
Oct 18 09:15:57 mtcdp daemon.debug pppd[489]: sent [IPCP ConfReq id=0x3 <addr 0.0.0.0> <ms-dns1 10.11.12.13> <ms-dns2 10.11.12.14>]
Oct 18 09:15:58 mtcdp daemon.debug pppd[489]: rcvd [IPCP ConfNak id=0x3 <ms-dns1 10.11.12.13> <ms-dns2 10.11.12.14>]
Oct 18 09:15:58 mtcdp daemon.debug pppd[489]: sent [IPCP ConfReq id=0x4 <addr 0.0.0.0> <ms-dns1 10.11.12.13> <ms-dns2 10.11.12.14>]
Oct 18 09:15:59 mtcdp daemon.debug pppd[489]: rcvd [IPCP ConfNak id=0x4 <ms-dns1 10.11.12.13> <ms-dns2 10.11.12.14>]
Oct 18 09:15:59 mtcdp daemon.debug pppd[489]: sent [IPCP ConfReq id=0x5 <addr 0.0.0.0>]
Oct 18 09:16:00 mtcdp daemon.debug pppd[489]: rcvd [IPCP ConfNak id=0x5 <ms-dns1 10.11.12.13> <ms-dns2 10.11.12.14>]
Oct 18 09:16:00 mtcdp daemon.debug pppd[489]: sent [IPCP ConfReq id=0x6 <addr 0.0.0.0> <ms-dns1 10.11.12.13> <ms-dns2 10.11.12.14>]
Oct 18 09:16:00 mtcdp daemon.debug pppd[489]: rcvd [IPCP ConfReq id=0x1]
Oct 18 09:16:00 mtcdp daemon.debug pppd[489]: sent [IPCP ConfNak id=0x1 <addr 0.0.0.0>]
Oct 18 09:16:00 mtcdp daemon.debug pppd[489]: rcvd [IPCP ConfNak id=0x6 <addr 10.210.174.114> <ms-dns1 10.0.2.254> <ms-dns2 10.2.2.36>]
Oct 18 09:16:00 mtcdp daemon.debug pppd[489]: sent [IPCP ConfReq id=0x7]
Oct 18 09:16:00 mtcdp daemon.debug pppd[489]: rcvd [IPCP ConfReq id=0x2 <addr 10.210.174.114>]
Oct 18 09:16:00 mtcdp daemon.debug pppd[489]: sent [IPCP ConfAck id=0x2 <addr 10.210.174.114>]
Oct 18 09:16:00 mtcdp daemon.debug pppd[489]: rcvd [IPCP ConfAck id=0x7]
Oct 18 09:16:00 mtcdp daemon.err pppd[489]: Could not determine local IP address
Oct 18 09:16:00 mtcdp daemon.info pppd[489]: Connect time 0.2 minutes.
Oct 18 09:16:00 mtcdp daemon.info pppd[489]: Sent 159 bytes, received 120 bytes.
Oct 18 09:16:00 mtcdp daemon.debug pppd[489]: sent [IPCP TermReq id=0x8 “Could not determine local IP address”]
Oct 18 09:16:00 mtcdp daemon.debug pppd[489]: rcvd [LCP TermReq id=0x3 “User request”]
Oct 18 09:16:00 mtcdp daemon.info pppd[489]: LCP terminated by peer (User request)
Oct 18 09:16:00 mtcdp daemon.debug pppd[489]: sent [LCP TermAck id=0x3]
Oct 18 09:16:00 mtcdp daemon.debug pppd[489]: rcvd [IPCP TermAck id=0x8]
Oct 18 09:16:00 mtcdp daemon.debug pppd[489]: Discarded non-LCP packet when LCP not open
Oct 18 09:16:03 mtcdp daemon.notice pppd[489]: Connection terminated.
Oct 18 09:16:05 mtcdp daemon.notice pppd[489]: Modem hangup
Oct 18 09:16:05 mtcdp daemon.info pppd[489]: Exit.’

Any suggestions?

Thanks.

– Ben

[Lonny Knudson]

Hi Ben,
In your peer file, could you try changing ipcp-max-failure to 10 and see if this allows the ppp negotiation to complete successfully?

[Ben Eisemann]

Lonny,

That did it!

Thanks for the reply and the sharing of your expertise.

God Bless,

Ben

[Author]

Posts