--On Dienstag, Dezember 26, 2006 08:26:17 +0100 Ignatios Souvatzis 
<is@netbsd.org> wrote:
> This happens when ppp connection is trying to start negotiation while
> the modem is in command mode.
>
> crtscts should be ok; combine with (no)modem and maybe (no)local.
>
> And try /dev/dty00 as mentioned above.
>
>> I am running out of things to try. Can somebody give me some more hints?
>> Perhaps I need to look into 8N1 (... not 8-bit clean ...), where is this
>> set in pppd (or outside of pppd?) ?
>
> Always.
>
> If this doesn't help, we'd need a log of the PPP negotiations to find
> out what happens - use kdebug 7 and log the kernel debug messages to
> some file using appropriate syslog.conf settings.

Hello,

thanks for your answer. Tried /dev/dty00, modem, local, but none of this
makes any difference. kdebug 7 does not show any packets, the link is
terminated before ppp takes place, this could be confirmed on the dialin
server side.

As the login dialog worked using minicom, I tried to let chat do the login,
so the server side would definitively be in PPP mode. The link is still
terminated immediately, but now there is some kernel message in the log:

Dec 26 13:30:40 shlab chat[9634]: CONNECT
Dec 26 13:30:40 shlab chat[9634]:  -- got it
Dec 26 13:30:40 shlab chat[9634]: send ()
Dec 26 13:30:40 shlab chat[9634]: expect (ogin:)
Dec 26 13:30:40 shlab chat[9634]:  9600/RLP^M
Dec 26 13:30:42 shlab chat[9634]: ^M
Dec 26 13:30:42 shlab chat[9634]: ^M
Dec 26 13:30:42 shlab chat[9634]:  login:
Dec 26 13:30:42 shlab chat[9634]:  -- got it
Dec 26 13:30:42 shlab chat[9634]: send (<user>^M)
Dec 26 13:30:42 shlab chat[9634]: expect (word:)
Dec 26 13:30:42 shlab chat[9634]: <user>^M
Dec 26 13:30:42 shlab chat[9634]: Password:
Dec 26 13:30:42 shlab chat[9634]:  -- got it
Dec 26 13:30:42 shlab chat[9634]: send (<pwd>^M)
Dec 26 13:30:43 shlab chat[9634]: expect (~)
Dec 26 13:30:43 shlab chat[9634]:  ^M
Dec 26 13:30:44 shlab chat[9634]: PPP session from (<ip1>) to <ip2> 
beginning....~
Dec 26 13:30:44 shlab chat[9634]:  -- got it
Dec 26 13:30:44 shlab pppd[11205]: Serial connection established.
Dec 26 13:30:44 shlab pppd[11205]: Using interface ppp0
Dec 26 13:30:44 shlab pppd[11205]: Connect: ppp0 <--> /dev/dty00
Dec 26 13:30:44 shlab pppd[11205]: Modem hangup
Dec 26 13:30:44 shlab pppd[11205]: Connection terminated.
Dec 26 13:30:44 shlab /netbsd: ppp0: bad protocol 3402
Dec 26 13:30:46 shlab pppd[11205]: Exit.

There is some variety to that kernel message:

Dec 26 13:05:49 shlab /netbsd: ppp0: bad protocol 206c
...
Dec 26 13:10:20 shlab /netbsd: ppp0: bad protocol 14
...
Dec 26 13:12:31 shlab /netbsd: ppp0: bad protocol 206
...
Dec 26 13:17:46 shlab /netbsd: ppp0: bad fcs 470a
...
Dec 26 13:23:45 shlab /netbsd: ppp0: bad protocol 3402
...
Dec 26 13:30:44 shlab /netbsd: ppp0: bad protocol 3402

Then I started hacking at pppd. In main.c, it decides "Modem hangup"
whenever the read from the ttyfd returns with zero length. I disabled
this code section, and here is the result:

  - chat as before
  - "bad protocol" kernel message
  - receiving packets from the dialin server (!)
    (confirmed with a ppp log from server side)
  - sending/replying packets to dialin server
    (but not received at server)
  - lots of "received short packet"


Dec 26 17:55:41 shlab chat[3370]: PPP session from (<ip1>) to <ip2> 
beginning....~
Dec 26 17:55:41 shlab chat[3370]:  -- got it
Dec 26 17:55:41 shlab /netbsd: ppp0: bad protocol 14
Dec 26 17:55:41 shlab pppd[19684]: Serial connection established.
Dec 26 17:55:41 shlab pppd[19684]: Using interface ppp0
Dec 26 17:55:41 shlab pppd[19684]: Connect: ppp0 <--> /dev/dty00
Dec 26 17:55:41 shlab pppd[19684]: received short packet:
Dec 26 17:55:42 shlab last message repeated 7603 times
Dec 26 17:55:42 shlab pppd[19684]: sent [LCP ConfReq id=0x1 <mru 552> 
<asyncmap 0x0> <magic 0x39b2d523> <pcomp> <accomp>]
Dec 26 17:55:42 shlab pppd[19684]: received short packet:
Dec 26 17:55:44 shlab last message repeated 15810 times
Dec 26 17:55:44 shlab /netbsd: ppp0: got 24 bytes
Dec 26 17:55:44 shlab /netbsd: 
ff03c02101020014020600000000050633854f1707020802
Dec 26 17:55:44 shlab pppd[19684]: received short packet:
Dec 26 17:55:44 shlab pppd[19684]: rcvd [LCP ConfReq id=0x2 <asyncmap 0x0> 
<magic 0x33854f17> <pcomp> <accomp>]
Dec 26 17:55:44 shlab pppd[19684]: lcp_reqci: returning CONFACK.
Dec 26 17:55:44 shlab pppd[19684]: sent [LCP ConfAck id=0x2 <asyncmap 0x0> 
<magic 0x33854f17> <pcomp> <accomp>]
Dec 26 17:55:44 shlab pppd[19684]: received short packet:
Dec 26 17:55:45 shlab last message repeated 8592 times
Dec 26 17:55:45 shlab pppd[19684]: sent [LCP ConfReq id=0x1 <mru 552> 
<asyncmap 0x0> <magic 0x39b2d523> <pcomp> <accomp>]
Dec 26 17:55:45 shlab pppd[19684]: received short packet:
Dec 26 17:55:47 shlab last message repeated 16211 times
Dec 26 17:55:47 shlab /netbsd: ppp0: got 24 bytes
Dec 26 17:55:47 shlab /netbsd: 
ff03c02101030014020600000000050633854f1707020802
Dec 26 17:55:47 shlab pppd[19684]: received short packet:
Dec 26 17:55:47 shlab pppd[19684]: rcvd [LCP ConfReq id=0x3 <asyncmap 0x0> 
<magic 0x33854f17> <pcomp> <accomp>]
Dec 26 17:55:47 shlab pppd[19684]: lcp_reqci: returning CONFACK.
Dec 26 17:55:47 shlab pppd[19684]: sent [LCP ConfAck id=0x3 <asyncmap 0x0> 
<magic 0x33854f17> <pcomp> <accomp>]
Dec 26 17:55:47 shlab pppd[19684]: received short packet:

Since packets arrive, there actually was no modem hangup.
pppd tries to send packets, but as the kernel sees the line as being
disconnected, it probably just discards them.
The serial driver must be interpreting some signal from the cellphone
as a modem hangup, which apparently is not correct (either the phone
or the serial driver does it not correctly).
I can see this behaviour with a Siemens ME45, and two Siemens S35i. This
probably means that the behaviour of the cellphones is intended and not
because of a single broken unit.

Is there a way to get the kernel to log events on the serial line? Are there
sysctl knobs to tune serial behaviour?

Best regards
Matthias Ferdinand