Problem Connecting to T-mobile with MTSMC-H4-IP

[Charles Kang]

I am having some problem connecting to T-mobile network using MTSMC-H4-IP. I used the identical gsm and gsm_chat files that I got from MTCDP-E1 which I used to connect to the T-mobile network without any problem.

messages file shows that the serial connection has been established and ppp connection is made, PAP auth succeeded.

Then it simply hangs up right after that:

Apr 5 15:40:26 fedoraVM chat[2695]: send (AT+CGDCONT=1,”IP”,”telargo.t-mobile.com”^M)

Apr 5 15:40:27 fedoraVM chat[2695]: expect (OK)

Apr 5 15:40:27 fedoraVM chat[2695]: ^M

Apr 5 15:40:27 fedoraVM chat[2695]: AT+CGDCONT=1,”IP”,”telargo.t-mobile.com”^M^M

Apr 5 15:40:27 fedoraVM chat[2695]: OK

Apr 5 15:40:27 fedoraVM chat[2695]: — got it

Apr 5 15:40:27 fedoraVM chat[2695]: send (ATD*99***1#^M)

Apr 5 15:40:27 fedoraVM chat[2695]: timeout set to 60 seconds

Apr 5 15:40:27 fedoraVM chat[2695]: expect (CONNECT)

Apr 5 15:40:27 fedoraVM chat[2695]: ^M

Apr 5 15:40:27 fedoraVM chat[2695]: ATD*99***1#^M^M

Apr 5 15:40:27 fedoraVM chat[2695]: CONNECT

Apr 5 15:40:27 fedoraVM chat[2695]: — got it

Apr 5 15:40:27 fedoraVM chat[2695]: send (^M)

Apr 5 15:40:27 fedoraVM pppd[2694]: Serial connection established.

Apr 5 15:40:27 fedoraVM pppd[2694]: Using interface ppp0

Apr 5 15:40:27 fedoraVM pppd[2694]: Connect: ppp0 <–> /dev/ttyS0

Apr 5 15:40:32 fedoraVM pppd[2694]: PAP authentication succeeded

Apr 5 15:40:33 fedoraVM pppd[2694]: Hangup (SIGHUP)

Apr 5 15:40:33 fedoraVM pppd[2694]: Modem hangup

Apr 5 15:40:33 fedoraVM pppd[2694]: Connection terminated.

Apr 5 15:40:33 fedoraVM avahi-daemon[1304]: Withdrawing workstation service for ppp0.

Apr 5 15:40:34 fedoraVM pppd[2694]: Exit.

I used the following pppd command in Fedora14 linux:

# pppd call gsm

The content of gsm file:

linkname ppp0

115200

/dev/ttyS0

defaultroute

usepeerdns

ipcp-max-failure 4

noauth

crtscts

novj

connect ‘/usr/sbin/chat -v -s -t 90 -f /etc/ppp/peers/gsm_chat’

The content of gsm_chat:

SAY “GSM chatn”

ECHO OFF

ABORT ‘NO DIAL TONE’

ABORT ‘NO DIALTONE’

ABORT ‘NO ANSWER’

ABORT ‘NO CARRIER’

ABORT ‘DELAYED’

ABORT ‘VOICE’

ABORT ‘BUSY’

” ‘AT’

OK ‘ATZ’

OK ‘AT+CSQ’

OK ‘AT+CGDCONT=1,”IP”,”telargo.t-mobile.com”‘

SAY “Dialing…n”

OK ‘ATD*99***1#’

SAY “Waiting for CONNECT…n”

TIMEOUT 120

CONNECT ”

SAY “Connectedn”

I appreciated if anyone who had similar situation share how the problem has been resolved.

Thanks in advance.

CK

[Lonny Knudson]

Hi Charles,

I don’t see a definite cause for the hang up given the information provided. You may want to open a support ticket at http://support.multitech.com

In order to capture more information, it would be helpful to use the chat script below and include the debug option on the command line when you invoke pppd.

pppd debug call gsm

Then get a copy of the log file and post it. Make sure that the log you post includes all events from the connection attempt (the log posted here was missing some of the chat events).

SAY “GSM chatn”

ECHO OFF

ABORT ‘NO DIAL TONE’

ABORT ‘NO DIALTONE’

ABORT ‘NO ANSWER’

ABORT ‘NO CARRIER’

ABORT ‘DELAYED’

ABORT ‘VOICE’

ABORT ‘BUSY’

” ‘AT’

OK ‘AT+CPIN?’

OK ‘AT+CREG?’

OK ‘AT+CSQ’

OK ‘AT+CGDCONT=1,”IP”,”telargo.t-mobile.com”‘

SAY “Dialing…n”

OK ‘ATD*99***1#’

SAY “Waiting for CONNECT…n”

TIMEOUT 120

CONNECT ”

SAY “Connectedn”

[Charles Kang]

Hi Lonny,

Thanks for responding promptly.

Included below is the part of /var/log/messages that covers the logging for: # pppd debug call gsm

As you can see in the log, I have used the gsm_chat script that was suggested.

Please let me know if I should try something else.

Regards,

Charles

========================================================

Apr 10 16:46:26 fedoraVM kernel: [ 467.027308] PPP generic driver version 2.4.2

Apr 10 16:46:26 fedoraVM pppd[2364]: pppd 2.4.5 started by cholsukang, uid 0

Apr 10 16:46:27 fedoraVM chat[2365]: abort on (NO DIAL TONE)

Apr 10 16:46:27 fedoraVM chat[2365]: abort on (NO DIALTONE)

Apr 10 16:46:27 fedoraVM chat[2365]: abort on (NO ANSWER)

Apr 10 16:46:27 fedoraVM chat[2365]: abort on (NO CARRIER)

Apr 10 16:46:27 fedoraVM chat[2365]: abort on (DELAYED)

Apr 10 16:46:27 fedoraVM chat[2365]: abort on (VOICE)

Apr 10 16:46:27 fedoraVM chat[2365]: abort on (BUSY)

Apr 10 16:46:27 fedoraVM chat[2365]: send (AT^M)

Apr 10 16:46:27 fedoraVM chat[2365]: expect (OK)

Apr 10 16:46:27 fedoraVM chat[2365]: AT^M^M

Apr 10 16:46:27 fedoraVM chat[2365]: OK

Apr 10 16:46:27 fedoraVM chat[2365]: — got it

Apr 10 16:46:27 fedoraVM chat[2365]: send (AT+CPIN?^M)

Apr 10 16:46:27 fedoraVM chat[2365]: expect (OK)

Apr 10 16:46:27 fedoraVM chat[2365]: ^M

Apr 10 16:46:27 fedoraVM chat[2365]: AT+CPIN?^M^M

Apr 10 16:46:27 fedoraVM chat[2365]: +CPIN: READY^M

Apr 10 16:46:27 fedoraVM chat[2365]: ^M

Apr 10 16:46:27 fedoraVM chat[2365]: OK

Apr 10 16:46:27 fedoraVM chat[2365]: — got it

Apr 10 16:46:27 fedoraVM chat[2365]: send (AT+CREG?^M)

Apr 10 16:46:27 fedoraVM chat[2365]: expect (OK)

Apr 10 16:46:27 fedoraVM chat[2365]: ^M

Apr 10 16:46:27 fedoraVM chat[2365]: AT+CREG?^M^M

Apr 10 16:46:27 fedoraVM chat[2365]: +CREG: 0,1^M

Apr 10 16:46:27 fedoraVM chat[2365]: ^M

Apr 10 16:46:27 fedoraVM chat[2365]: OK

Apr 10 16:46:27 fedoraVM chat[2365]: — got it

Apr 10 16:46:27 fedoraVM chat[2365]: send (AT+CSQ^M)

Apr 10 16:46:27 fedoraVM chat[2365]: expect (OK)

Apr 10 16:46:27 fedoraVM chat[2365]: ^M

Apr 10 16:46:27 fedoraVM chat[2365]: AT+CSQ^M^M

Apr 10 16:46:27 fedoraVM chat[2365]: +CSQ: 10,99^M

Apr 10 16:46:27 fedoraVM chat[2365]: ^M

Apr 10 16:46:27 fedoraVM chat[2365]: OK

Apr 10 16:46:27 fedoraVM chat[2365]: — got it

Apr 10 16:46:27 fedoraVM chat[2365]: send (AT+CGDCONT=1,”IP”,”telargo.t-mobile.com”^M)

Apr 10 16:46:28 fedoraVM chat[2365]: expect (OK)

Apr 10 16:46:28 fedoraVM chat[2365]: ^M

Apr 10 16:46:28 fedoraVM chat[2365]: AT+CGDCONT=1,”IP”,”telargo.t-mobile.com”^M^M

Apr 10 16:46:28 fedoraVM chat[2365]: OK

Apr 10 16:46:28 fedoraVM chat[2365]: — got it

Apr 10 16:46:28 fedoraVM chat[2365]: send (ATD*99***1#^M)

Apr 10 16:46:28 fedoraVM chat[2365]: timeout set to 120 seconds

Apr 10 16:46:28 fedoraVM chat[2365]: expect (CONNECT)

Apr 10 16:46:28 fedoraVM chat[2365]: ^M

Apr 10 16:46:28 fedoraVM chat[2365]: ATD*99***1#^M^M

Apr 10 16:46:28 fedoraVM chat[2365]: CONNECT

Apr 10 16:46:28 fedoraVM chat[2365]: — got it

Apr 10 16:46:28 fedoraVM chat[2365]: send (^M)

Apr 10 16:46:28 fedoraVM pppd[2364]: Serial connection established.

Apr 10 16:46:28 fedoraVM pppd[2364]: Using interface ppp0

Apr 10 16:46:28 fedoraVM pppd[2364]: Connect: ppp0 <–> /dev/ttyS0

Apr 10 16:46:33 fedoraVM pppd[2364]: PAP authentication succeeded

Apr 10 16:46:33 fedoraVM kernel: [ 474.447382] PPP Deflate Compression module registered

Apr 10 16:46:34 fedoraVM pppd[2364]: Hangup (SIGHUP)

Apr 10 16:46:34 fedoraVM pppd[2364]: Modem hangup

Apr 10 16:46:34 fedoraVM pppd[2364]: Connection terminated.

Apr 10 16:46:34 fedoraVM avahi-daemon[1295]: Withdrawing workstation service for ppp0.

Apr 10 16:46:35 fedoraVM pppd[2364]: Exit.

[Lonny Knudson]

Hi Charles,

Could you check your syslog configuration to see where daemon.debug messages are being written? The log file you are looking at doesn’t appear to have debug level messages included. The debug level messages should show at least some LCP and PAP packets exchanged.

[Charles Kang]

Hi Lonny,

Thanks for the useful tips.

I added a line in rsyslog.conf to log the debug output.

Now, I got much more debug info in /var/log/messages.

Somehow, the host keeps on trying Ethernet interface.

So, I manually disable the Ethernet port and also manually set dns entries in /etc/resolv.conf to the ones from the mobile serviced provider, Wyless, that I am using currently.

Having done that, I am progressing further.

Now, it gets correct IP address, 10.140.207.1.

But, looking at the debug output, it is still having some problem getting the remote IP address and uses the default one, 10.64.64.64. I think that it is a problem.

How should the remote IP address be determined?

Is it received using LCP or IPCP, or do I need to set it in any config file?

Now, I see that /etc/ppp/ip-up script is executed.

I have included the content of /etc/ppp/ip-up at the bottom of this post.

ppp0 link seems to be staying up much longer.

However, it goes down as soon as I initiated a network access using:

# ping ‘www.google.com’

(without the single quotes)

I would appreciate if you have further suggestions that I can try.

Regards,

Charles

Apr 11 17:27:33 fedoraVM pppd[2532]: pppd 2.4.5 started by cholsukang, uid 0

Apr 11 17:27:34 fedoraVM chat[2534]: abort on (NO DIAL TONE)

Apr 11 17:27:34 fedoraVM chat[2534]: abort on (NO DIAL TONE)

Apr 11 17:27:34 fedoraVM chat[2534]: abort on (NO DIALTONE)

Apr 11 17:27:34 fedoraVM chat[2534]: abort on (NO DIALTONE)

Apr 11 17:27:34 fedoraVM chat[2534]: abort on (NO ANSWER)

Apr 11 17:27:34 fedoraVM chat[2534]: abort on (NO ANSWER)

Apr 11 17:27:34 fedoraVM chat[2534]: abort on (NO CARRIER)

Apr 11 17:27:34 fedoraVM chat[2534]: abort on (NO CARRIER)

Apr 11 17:27:34 fedoraVM chat[2534]: abort on (DELAYED)

Apr 11 17:27:34 fedoraVM chat[2534]: abort on (DELAYED)

Apr 11 17:27:34 fedoraVM chat[2534]: abort on (VOICE)

Apr 11 17:27:34 fedoraVM chat[2534]: abort on (VOICE)

Apr 11 17:27:34 fedoraVM chat[2534]: abort on (BUSY)

Apr 11 17:27:34 fedoraVM chat[2534]: abort on (BUSY)

Apr 11 17:27:34 fedoraVM chat[2534]: send (AT^M)

Apr 11 17:27:34 fedoraVM chat[2534]: send (AT^M)

Apr 11 17:27:34 fedoraVM chat[2534]: expect (OK)

Apr 11 17:27:34 fedoraVM chat[2534]: expect (OK)

Apr 11 17:27:34 fedoraVM chat[2534]: AT^M^M

Apr 11 17:27:34 fedoraVM chat[2534]: AT^M^M

Apr 11 17:27:34 fedoraVM chat[2534]: OK

Apr 11 17:27:34 fedoraVM chat[2534]: OK

Apr 11 17:27:34 fedoraVM chat[2534]: — got it

Apr 11 17:27:34 fedoraVM chat[2534]: — got it

Apr 11 17:27:34 fedoraVM chat[2534]: send (AT+CPIN?^M)

Apr 11 17:27:34 fedoraVM chat[2534]: send (AT+CPIN?^M)

Apr 11 17:27:34 fedoraVM chat[2534]: expect (OK)

Apr 11 17:27:34 fedoraVM chat[2534]: expect (OK)

Apr 11 17:27:34 fedoraVM chat[2534]: ^M

Apr 11 17:27:34 fedoraVM chat[2534]: ^M

Apr 11 17:27:34 fedoraVM chat[2534]: AT+CPIN?^M^M

Apr 11 17:27:34 fedoraVM chat[2534]: AT+CPIN?^M^M

Apr 11 17:27:34 fedoraVM chat[2534]: +CPIN: READY^M

Apr 11 17:27:34 fedoraVM chat[2534]: +CPIN: READY^M

Apr 11 17:27:34 fedoraVM chat[2534]: ^M

Apr 11 17:27:34 fedoraVM chat[2534]: ^M

Apr 11 17:27:34 fedoraVM chat[2534]: OK

Apr 11 17:27:34 fedoraVM chat[2534]: OK

Apr 11 17:27:34 fedoraVM chat[2534]: — got it

Apr 11 17:27:34 fedoraVM chat[2534]: — got it

Apr 11 17:27:34 fedoraVM chat[2534]: send (AT+CREG?^M)

Apr 11 17:27:34 fedoraVM chat[2534]: send (AT+CREG?^M)

Apr 11 17:27:34 fedoraVM chat[2534]: expect (OK)

Apr 11 17:27:34 fedoraVM chat[2534]: expect (OK)

Apr 11 17:27:34 fedoraVM chat[2534]: ^M

Apr 11 17:27:34 fedoraVM chat[2534]: ^M

Apr 11 17:27:34 fedoraVM chat[2534]: AT+CREG?^M^M

Apr 11 17:27:34 fedoraVM chat[2534]: AT+CREG?^M^M

Apr 11 17:27:34 fedoraVM chat[2534]: +CREG: 0,1^M

Apr 11 17:27:34 fedoraVM chat[2534]: +CREG: 0,1^M

Apr 11 17:27:34 fedoraVM chat[2534]: ^M

Apr 11 17:27:34 fedoraVM chat[2534]: ^M

Apr 11 17:27:34 fedoraVM chat[2534]: OK

Apr 11 17:27:34 fedoraVM chat[2534]: OK

Apr 11 17:27:34 fedoraVM chat[2534]: — got it

Apr 11 17:27:34 fedoraVM chat[2534]: — got it

Apr 11 17:27:34 fedoraVM chat[2534]: send (AT+CSQ^M)

Apr 11 17:27:34 fedoraVM chat[2534]: send (AT+CSQ^M)

Apr 11 17:27:34 fedoraVM chat[2534]: expect (OK)

Apr 11 17:27:34 fedoraVM chat[2534]: expect (OK)

Apr 11 17:27:34 fedoraVM chat[2534]: ^M

Apr 11 17:27:34 fedoraVM chat[2534]: ^M

Apr 11 17:27:34 fedoraVM chat[2534]: AT+CSQ^M^M

Apr 11 17:27:34 fedoraVM chat[2534]: AT+CSQ^M^M

Apr 11 17:27:34 fedoraVM chat[2534]: +CSQ: 12,99^M

Apr 11 17:27:34 fedoraVM chat[2534]: +CSQ: 12,99^M

Apr 11 17:27:34 fedoraVM chat[2534]: ^M

Apr 11 17:27:34 fedoraVM chat[2534]: ^M

Apr 11 17:27:34 fedoraVM chat[2534]: OK

Apr 11 17:27:34 fedoraVM chat[2534]: OK

Apr 11 17:27:34 fedoraVM chat[2534]: — got it

Apr 11 17:27:34 fedoraVM chat[2534]: — got it

Apr 11 17:27:34 fedoraVM chat[2534]: send (AT+CGDCONT=1,”IP”,”telargo.t-mobile.com”^M)

Apr 11 17:27:34 fedoraVM chat[2534]: send (AT+CGDCONT=1,”IP”,”telargo.t-mobile.com”^M)

Apr 11 17:27:35 fedoraVM chat[2534]: expect (OK)

Apr 11 17:27:35 fedoraVM chat[2534]: expect (OK)

Apr 11 17:27:35 fedoraVM chat[2534]: ^M

Apr 11 17:27:35 fedoraVM chat[2534]: ^M

Apr 11 17:27:35 fedoraVM chat[2534]: AT+CGDCONT=1,”IP”,”telargo.t-mobile.com”^M^M

Apr 11 17:27:35 fedoraVM chat[2534]: AT+CGDCONT=1,”IP”,”telargo.t-mobile.com”^M^M

Apr 11 17:27:35 fedoraVM chat[2534]: OK

Apr 11 17:27:35 fedoraVM chat[2534]: OK

Apr 11 17:27:35 fedoraVM chat[2534]: — got it

Apr 11 17:27:35 fedoraVM chat[2534]: — got it

Apr 11 17:27:35 fedoraVM chat[2534]: send (ATD*99***1#^M)

Apr 11 17:27:35 fedoraVM chat[2534]: send (ATD*99***1#^M)

Apr 11 17:27:35 fedoraVM chat[2534]: timeout set to 120 seconds

Apr 11 17:27:35 fedoraVM chat[2534]: timeout set to 120 seconds

Apr 11 17:27:35 fedoraVM chat[2534]: expect (CONNECT)

Apr 11 17:27:35 fedoraVM chat[2534]: expect (CONNECT)

Apr 11 17:27:35 fedoraVM chat[2534]: ^M

Apr 11 17:27:35 fedoraVM chat[2534]: ^M

Apr 11 17:27:35 fedoraVM chat[2534]: ATD*99***1#^M^M

Apr 11 17:27:35 fedoraVM chat[2534]: ATD*99***1#^M^M

Apr 11 17:27:35 fedoraVM chat[2534]: CONNECT

Apr 11 17:27:35 fedoraVM chat[2534]: CONNECT

Apr 11 17:27:35 fedoraVM chat[2534]: — got it

Apr 11 17:27:35 fedoraVM chat[2534]: — got it

Apr 11 17:27:35 fedoraVM chat[2534]: send (^M)

Apr 11 17:27:35 fedoraVM chat[2534]: send (^M)

Apr 11 17:27:35 fedoraVM pppd[2532]: Script /usr/sbin/chat -v -s -t 90 -f /etc/ppp/peers/gsm_chat finished (pid 2534), status = 0x0

Apr 11 17:27:35 fedoraVM pppd[2532]: Serial connection established.

Apr 11 17:27:35 fedoraVM pppd[2532]: Serial connection established.

Apr 11 17:27:35 fedoraVM pppd[2532]: using channel 3

Apr 11 17:27:35 fedoraVM pppd[2532]: Using interface ppp0

Apr 11 17:27:35 fedoraVM pppd[2532]: Using interface ppp0

Apr 11 17:27:35 fedoraVM pppd[2532]: Connect: ppp0 <–> /dev/ttyS0

Apr 11 17:27:35 fedoraVM pppd[2532]: Connect: ppp0 <–> /dev/ttyS0

Apr 11 17:27:35 fedoraVM modem-manager: (net/ppp0): could not get port’s parent device

Apr 11 17:27:40 fedoraVM pppd[2532]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x726abee8> <pcomp> <accomp>]

Apr 11 17:27:40 fedoraVM pppd[2532]: rcvd [LCP ConfReq id=0x4 <asyncmap 0x0> <auth chap MD5> <magic 0x13f333dd> <pcomp> <accomp>]

Apr 11 17:27:40 fedoraVM pppd[2532]: sent [LCP ConfNak id=0x4 <auth pap>]

Apr 11 17:27:40 fedoraVM pppd[2532]: rcvd [LCP ConfAck id=0x1 <asyncmap 0x0> <magic 0x726abee8> <pcomp> <accomp>]

Apr 11 17:27:40 fedoraVM pppd[2532]: rcvd [LCP ConfReq id=0x5 <asyncmap 0x0> <auth pap> <magic 0x13f333dd> <pcomp> <accomp>]

Apr 11 17:27:40 fedoraVM pppd[2532]: sent [LCP ConfAck id=0x5 <asyncmap 0x0> <auth pap> <magic 0x13f333dd> <pcomp> <accomp>]

Apr 11 17:27:40 fedoraVM pppd[2532]: sent [PAP AuthReq id=0x1 user=”fedoraVM” password=<hidden>]

Apr 11 17:27:40 fedoraVM pppd[2532]: rcvd [LCP DiscReq id=0x6 magic=0x13f333dd]

Apr 11 17:27:40 fedoraVM pppd[2532]: rcvd [PAP AuthAck id=0x1 “”]

Apr 11 17:27:40 fedoraVM pppd[2532]: PAP authentication succeeded

Apr 11 17:27:40 fedoraVM pppd[2532]: PAP authentication succeeded

Apr 11 17:27:40 fedoraVM pppd[2532]: sent [CCP ConfReq id=0x1 <deflate 15> <deflate(old#) 15>]

Apr 11 17:27:40 fedoraVM pppd[2532]: sent [IPCP ConfReq id=0x1 <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns2 0.0.0.0>]

Apr 11 17:27:40 fedoraVM pppd[2532]: rcvd [LCP ProtRej id=0x7 80 fd 01 01 00 0c 1a 04 78 00 18 04 78 00]

Apr 11 17:27:40 fedoraVM pppd[2532]: Protocol-Reject for ‘Compression Control Protocol’ (0x80fd) received

Apr 11 17:27:41 fedoraVM pppd[2532]: rcvd [IPCP ConfReq id=0x0]

Apr 11 17:27:41 fedoraVM pppd[2532]: sent [IPCP ConfNak id=0x0 <addr 0.0.0.0>]

Apr 11 17:27:41 fedoraVM pppd[2532]: rcvd [IPCP ConfNak id=0x1 <addr 10.140.207.1> <ms-dns1 172.17.1.101> <ms-dns2 172.17.1.102>]

Apr 11 17:27:41 fedoraVM pppd[2532]: sent [IPCP ConfReq id=0x2 <addr 10.140.207.1> <ms-dns1 172.17.1.101> <ms-dns2 172.17.1.102>]

Apr 11 17:27:41 fedoraVM pppd[2532]: rcvd [IPCP ConfReq id=0x1]

Apr 11 17:27:41 fedoraVM pppd[2532]: sent [IPCP ConfAck id=0x1]

Apr 11 17:27:41 fedoraVM pppd[2532]: rcvd [IPCP ConfAck id=0x2 <addr 10.140.207.1> <ms-dns1 172.17.1.101> <ms-dns2 172.17.1.102>]

Apr 11 17:27:41 fedoraVM pppd[2532]: Could not determine remote IP address: defaulting to 10.64.64.64

Apr 11 17:27:41 fedoraVM pppd[2532]: Could not determine remote IP address: defaulting to 10.64.64.64

Apr 11 17:27:41 fedoraVM pppd[2532]: local IP address 10.140.207.1

Apr 11 17:27:41 fedoraVM pppd[2532]: local IP address 10.140.207.1

Apr 11 17:27:41 fedoraVM pppd[2532]: remote IP address 10.64.64.64

Apr 11 17:27:41 fedoraVM pppd[2532]: remote IP address 10.64.64.64

Apr 11 17:27:41 fedoraVM pppd[2532]: primary DNS address 172.17.1.101

Apr 11 17:27:41 fedoraVM pppd[2532]: primary DNS address 172.17.1.101

Apr 11 17:27:41 fedoraVM pppd[2532]: secondary DNS address 172.17.1.102

Apr 11 17:27:41 fedoraVM pppd[2532]: secondary DNS address 172.17.1.102

Apr 11 17:27:41 fedoraVM pppd[2532]: Script /etc/ppp/ip-up started (pid 2548)

Apr 11 17:27:41 fedoraVM pppd[2532]: Script /etc/ppp/ip-up finished (pid 2548), status = 0x0

Apr 11 17:28:05 fedoraVM pppd[2532]: Hangup (SIGHUP)

Apr 11 17:28:05 fedoraVM pppd[2532]: Hangup (SIGHUP)

Apr 11 17:28:05 fedoraVM pppd[2532]: Modem hangup

Apr 11 17:28:05 fedoraVM pppd[2532]: Modem hangup

Apr 11 17:28:05 fedoraVM pppd[2532]: Connect time 0.4 minutes.

Apr 11 17:28:05 fedoraVM pppd[2532]: Connect time 0.4 minutes.

Apr 11 17:28:05 fedoraVM pppd[2532]: Sent 60 bytes, received 0 bytes.

Apr 11 17:28:05 fedoraVM pppd[2532]: Sent 60 bytes, received 0 bytes.

Apr 11 17:28:05 fedoraVM pppd[2532]: Script /etc/ppp/ip-down started (pid 2563)

Apr 11 17:28:05 fedoraVM pppd[2532]: Connection terminated.

Apr 11 17:28:05 fedoraVM pppd[2532]: Connection terminated.

Apr 11 17:28:05 fedoraVM avahi-daemon[1292]: Withdrawing workstation service for ppp0.

Apr 11 17:28:05 fedoraVM avahi-daemon[1292]: Withdrawing workstation service for ppp0.

Apr 11 17:28:06 fedoraVM pppd[2532]: Script /etc/ppp/ip-down finished (pid 2563), status = 0x0

Apr 11 17:28:06 fedoraVM pppd[2532]: Exit.

Apr 11 17:28:06 fedoraVM pppd[2532]: Exit.

=================================================

/etc/ppp/if-up

#!/bin/bash

# This file should not be modified — make local changes to

# /etc/ppp/ip-up.local instead

PATH=/sbin:/usr/sbin:/bin:/usr/bin

export PATH

LOGDEVICE=$6

REALDEVICE=$1

[ -f /etc/sysconfig/network-scripts/ifcfg-${LOGDEVICE} ] && /etc/sysconfig/network-scripts/ifup-post –realdevice ${REALDEVICE} ifcfg-${LOGDEVICE}

/etc/ppp/ip-up.ipv6to4 ${LOGDEVICE}

[ -x /etc/ppp/ip-up.local ] && /etc/ppp/ip-up.local “$@”

exit 0

[Darrik Spaude]

Hi Charles,

Regarding the IP addresses, they are negotiated in the IPCP phase. The server is NOT allowing the client to know its IP address even though the client wants to know what it is:

Apr 11 17:27:41 fedoraVM pppd[2532]: rcvd [IPCP ConfReq id=0x0]

Apr 11 17:27:41 fedoraVM pppd[2532]: sent [IPCP ConfNak id=0x0 <addr 0.0.0.0>]

To avoid an endless loop, the client accepts the server’s non-information:

Apr 11 17:27:41 fedoraVM pppd[2532]: rcvd [IPCP ConfReq id=0x1]

Apr 11 17:27:41 fedoraVM pppd[2532]: sent [IPCP ConfAck id=0x1]

[Lonny Knudson]

Hi Charles,

The radio modules in the -H4 products do not negotiate an IP address for their side of the ppp link (remote IP from the perspective of pppd), this is normal for these radios and pppd uses 10.64.64.64 by default. I don’t think it is likely to be the cause of the problem.

From looking at the log it appears like the HUP signal is initiating the termination of the ppp link. This assumption is based on the HUP event occurring before the modem hang up event. However, there doesn’t appear to be anything in the log indicating what process sent the HUP signal.

My first suspicion is the modem-manager process:

Apr 11 17:27:35 fedoraVM modem-manager: (net/ppp0): could not get port’s parent device

I have seen this cause an issue with pppd or the associated tty device on a debian distribution before, however I can’t recall the symptom(s) I was seeing at the time. As a test, you could try to terminate the process and then try pppd and see if it stays up.

The only other suggestion I can think of is to check all of the scripts that are spawned by /etc/ppp/if-up to see if any of them might send a kill signal to the pppd process (most likely syntax would be something like kill -s HUP or kill -s 1).

[Charles Kang]

Hi Lonny,

Thanks for your support.

I switched to Debian Linux version 6.0.1 and it is woking better:

– ppp link stays up

– ppp link is not dropped when trying to ping

I still need to figure out how to make ping work to ping google.com.

Somehow, Debian has quite different /etc/ppp/if-up script than the one in Fedora-14.

I will post further when I make ping working.

[Charles Kang]

Hi Lonny,

I purchased a MTSMC-E1 modem and replaced MTSMC-H4-IP modem on my MTSMI-UDK development board.

MTSMC-E1 is working much better.

The ppp link stays up and I can ping google.com.

It works pretty solid.

I am not sure why MTSMC-H4-IP drops the ppp link as soon as I try to ping google.com. Perhaps, the MTSMC-H4-IP module is damaged. Is there any diagnostic code in the MTSCM-H4-IP whether the modem hardware is ok.

[Lonny Knudson]

Hi Charles,

I don’t know of any diagnostics that would help in this case. I looked over some logs that you had sent to Jeff when you were corresponding with him. It looks like the -H4 has some older firmware, I think it would be a good idea to update to version 1.0.10. To obtain the firmware files and update instructions, please open a ticket in the support portal at http://support.multitech.com . Reference version 1.0.10 in the case description.

[Charles Kang]

Thanks. I will follow up in http://support.multitech.com for the new version.

[Author]

Posts