[Date Prev][Date Next] [Thread Prev][Thread Next] [Date Index] [Thread Index]

Re: very weird problem with PPP (server+client)



On Sun, Dec 06, 1998 at 06:09:52PM +0000, Pere Camps wrote:
> Hi!

Hello Pere, 

Hmm, nobody replied so I will make a try. Forgive me if my answer is wrong but
I am really tired (3:45 am here :)

> 	I used to have a very stable configuration for a PPP connection
> between two debian machines which suddenly has gone away. I'll explain
> myself.
> 
> [detailed description deleted]
>
> 	Any help will be greatly appreciated (even if it's to tell me that
> my modem is broken! I want to blame this on something!)... and sorry, I
> have no other modem to try this on.
> 
> 	TIA!
> 
> Sorry if the logs are too long, but maybe the kdebug 1 messages are
> needed...

Okay. Let's take a look:

> client:
> [...]
> Dec  6 18:35:37 ulivatar kernel: ppp_dev_xmit: writing 14 chars 
> Dec  6 18:35:39 ulivatar pppd[407]: sent [PAP AuthReq id=0x2 user="pere" password="CLASSIFIED"]
> Dec  6 18:35:39 ulivatar kernel: ppp_dev_xmit_lower: fcs is 5419 
> Dec  6 18:35:39 ulivatar kernel: ppp_dev_xmit: writing 24 chars 
> Dec  6 18:35:39 ulivatar kernel: ppp_tty_read: called buf=080645c0 nr=1504 
> Dec  6 18:35:39 ulivatar kernel: ppp_tty_read: no data (EAGAIN) 
> Dec  6 18:35:42 ulivatar pppd[407]: sent [PAP AuthReq id=0x3 user="pere" password="CLASSIFIED"]
> Dec  6 18:35:42 ulivatar kernel: ppp_dev_xmit_lower: fcs is 4416 
> Dec  6 18:35:42 ulivatar kernel: ppp_dev_xmit: writing 24 chars 
> Dec  6 18:35:42 ulivatar kernel: ppp_tty_read: called buf=080645c0 nr=1504 
> Dec  6 18:35:42 ulivatar kernel: ppp_tty_read: no data (EAGAIN) 
> Dec  6 18:35:45 ulivatar pppd[407]: sent [PAP AuthReq id=0x4 user="pere" password="CLASSIFIED"]
> [...]

This looks REALLY weird! Either your modem is broken or your server does not
answer in a reasonable time. Suggestion: Try to connect without ppp using e.g.
minicom. Report if this works and try binary file transfers using rz/sz.

> Dec  6 18:36:06 ulivatar kernel: ppp_tty_read: no data (EAGAIN) 
> Dec  6 18:36:07 ulivatar kernel: ppp_tty_read: called buf=080645c0 nr=1504 
> Dec  6 18:36:07 ulivatar kernel: ppp_tty_read: no data (EAGAIN) 
> Dec  6 18:36:36 ulivatar pppd[407]: sent [LCP EchoReq id=0x2 magic=0xffff8003]
> Dec  6 18:36:36 ulivatar kernel: ppp_dev_xmit_lower: fcs is 56df 
> Dec  6 18:36:36 ulivatar kernel: ppp_dev_xmit: writing 14 chars 
> Dec  6 18:36:36 ulivatar kernel: ppp_tty_read: called buf=080645c0 nr=1504 
> Dec  6 18:36:36 ulivatar kernel: ppp_tty_read: no data (EAGAIN) 
> Dec  6 18:36:57 ulivatar pppd[407]: rcvd [PAP AuthAck id=0x1 "Success"]
> Dec  6 18:36:57 ulivatar pppd[407]: rcvd [IPCP ConfReq id=0x1 <addr 147.83.61.17> <compress VJ 0f 01>]

Hmm, very funny. The kernel says "no data" and pppd receives a packet? What's
that?

> [...]
> Dec  6 18:36:57 ulivatar pppd[407]: rcvd [PAP AuthAck id=0x2 ""]
> Dec  6 18:36:57 ulivatar pppd[407]: rcvd [PAP AuthAck id=0x3 ""]
> Dec  6 18:36:57 ulivatar pppd[407]: rcvd [PAP AuthAck id=0x4 ""]
> Dec  6 18:36:57 ulivatar pppd[407]: rcvd [PAP AuthAck id=0x5 ""]
> Dec  6 18:36:57 ulivatar pppd[407]: rcvd [PAP AuthAck id=0x6 ""]
> Dec  6 18:36:57 ulivatar pppd[407]: rcvd [PAP AuthAck id=0x7 ""]
> Dec  6 18:36:57 ulivatar pppd[407]: rcvd [PAP AuthAck id=0x8 ""]
> Dec  6 18:36:57 ulivatar pppd[407]: rcvd [PAP AuthAck id=0x9 ""]
> Dec  6 18:36:57 ulivatar pppd[407]: rcvd [PAP AuthAck id=0xa ""]
> Dec  6 18:36:57 ulivatar pppd[407]: rcvd [LCP EchoRep id=0x1 magic=0xffffd843]
> Dec  6 18:36:57 ulivatar pppd[407]: rcvd [LCP EchoRep id=0x2 magic=0xffffd843]
> Dec  6 18:36:57 ulivatar kernel: ppp_tty_read: called buf=080645c0 nr=1504 
> Dec  6 18:36:57 ulivatar kernel: ppp_tty_read: len = 7 
> Dec  6 18:36:57 ulivatar kernel: ppp_tty_read: passing 9 bytes up 
> [...]

So the serial link seems to work - very slow.

> and for the server...
> 
> [...]
> Dec  6 18:35:22 casal pppd[20334]: rcvd [PAP AuthReq id=0x1 user="pere" password="CLASSIFIED"]
> Dec  6 18:35:22 casal PAM_pwdb[20334]: (ppp) session opened for user pere by (uid=0) 
> Dec  6 18:35:22 casal pppd[20334]: user pere logged in
> Dec  6 18:35:43 casal last message repeated 6 times

Why that? Logged in 6 times? Huh!

> Dec  6 18:35:45 casal in.smtpd[20337]: connect from 147.83.61.42
> Dec  6 18:36:43 casal pppd[20334]: sent [PAP AuthAck id=0x1 "Success"]
> Dec  6 18:36:43 casal pppd[20334]: sent [IPCP ConfReq id=0x1 <addr 147.83.61.17> <compress VJ 0f 01>]
> Dec  6 18:36:43 casal pppd[20334]: rcvd [LCP EchoRep id=0x0 magic=0xffff8003]
> Dec  6 18:36:43 casal pppd[20334]: rcvd [PAP AuthReq id=0x2 user="pere" password="CLASSIFIED"]
> Dec  6 18:36:43 casal pppd[20334]: sent [PAP AuthAck id=0x2 ""]
> Dec  6 18:36:43 casal pppd[20334]: rcvd [PAP AuthReq id=0x3 user="pere" password="CLASSIFIED"]
> Dec  6 18:36:43 casal pppd[20334]: sent [PAP AuthAck id=0x3 ""]
> Dec  6 18:36:43 casal pppd[20334]: rcvd [PAP AuthReq id=0x4 user="pere" password="CLASSIFIED"]
> Dec  6 18:36:43 casal pppd[20334]: sent [PAP AuthAck id=0x4 ""]
> Dec  6 18:36:43 casal pppd[20334]: rcvd [PAP AuthReq id=0x5 user="pere" password="CLASSIFIED"]
> Dec  6 18:36:43 casal pppd[20334]: sent [PAP AuthAck id=0x5 ""]
> Dec  6 18:36:43 casal pppd[20334]: rcvd [PAP AuthReq id=0x6 user="pere" password="CLASSIFIED"]
> Dec  6 18:36:43 casal pppd[20334]: sent [PAP AuthAck id=0x6 ""]
> Dec  6 18:36:43 casal pppd[20334]: rcvd [PAP AuthReq id=0x7 user="pere" password="CLASSIFIED"]
> Dec  6 18:36:43 casal pppd[20334]: sent [PAP AuthAck id=0x7 ""]
> Dec  6 18:36:43 casal pppd[20334]: rcvd [PAP AuthReq id=0x8 user="pere" password="CLASSIFIED"]
> Dec  6 18:36:43 casal pppd[20334]: sent [PAP AuthAck id=0x8 ""]
> Dec  6 18:36:43 casal pppd[20334]: rcvd [PAP AuthReq id=0x9 user="pere" password="CLASSIFIED"]
> Dec  6 18:36:43 casal pppd[20334]: sent [PAP AuthAck id=0x9 ""]
> Dec  6 18:36:43 casal pppd[20334]: rcvd [PAP AuthReq id=0xa user="pere" password="CLASSIFIED"]
> Dec  6 18:36:43 casal pppd[20334]: sent [PAP AuthAck id=0xa ""]

Look at the times - the data seems to get queued up somewhere. It's impossible
to say if it is the client which queues the data send or the server which
queues the data received...

> [...]
> Dec  6 18:37:10 casal pppd[20334]: sent [IPCP ConfReq id=0x1 <addr 147.83.61.17> <compress VJ 0f 01>]
> Dec  6 18:37:13 casal pppd[20334]: IPCP: timeout sending Config-Requests

I guess the link would work (if only slow) if pppd would be more patient.
Please try the serial link with minicom!

cu
    Torsten

PS: Excuse my bad english!

Attachment: pgpNdF9066fUq.pgp
Description: PGP signature


Reply to: