PPP LCP configuration issue

PPP LCP configuration issue

[Marcel Holtmann]

[-- Attachment #1: Type: text/plain, Size: 1644 bytes --]

Hi Kristen,

so I added some debug code to actually print the options during the
configuration stage. And something seems to be wrong here.

lcp: pppcp_open_event: current state 0:INITIAL
lcp: pppcp_up_event: current state 1:STARTING
lcp: pppcp_initialize_restart_count: current state 1:STARTING
lcp: pppcp_send_configure_request: current state 1:STARTING
lcp: option 2 len 6 (Async-Control-Character-Map) 00 00 00 00
lcp: pppcp_process_configure_request: current state 6:REQSENT
lcp: option 2 len 6 (Async-Control-Character-Map) 00 00 00 00
lcp: option 3 len 5 (Authentication-Protocol) c2 23 05
lcp: option 5 len 6 (Magic-Number) 01 ff ef e0
lcp: option 7 len 2 (Protocol-Field-Compression)
lcp: option 8 len 2 (Address-and-Control-Field-Compression)
lcp: pppcp_rcr_plus_event: current state 6:REQSENT
lcp: pppcp_send_configure_ack: current state 6:REQSENT
lcp: option 2 len 6 (Async-Control-Character-Map) 00 00 00 00
lcp: option 3 len 5 (Authentication-Protocol) c2 23 05
lcp: option 5 len 6 (Magic-Number) 01 ff ef e0
lcp: option 7 len 2 (Protocol-Field-Compression)
lcp: option 8 len 2 (Address-and-Control-Field-Compression)
lcp: pppcp_process_configure_ack: current state 8:ACKSENT
lcp: option 2 len 6 (Async-Control-Character-Map) 00 00 00 00
oops -- found acked option 2 we didn't request
lcp: pppcp_rca_event: current state 8:ACKSENT
lcp: pppcp_initialize_restart_count: current state 8:ACKSENT

I see the oops comment here, but we clearly requested the async control
character map. So why does it get recognized as not requested? This is
clearly a bug and needs to be fixed.

Regards

Marcel

Re: PPP LCP configuration issue

[Marcel Holtmann]

[-- Attachment #1: Type: text/plain, Size: 2064 bytes --]

Hi Kristen,

> so I added some debug code to actually print the options during the
> configuration stage. And something seems to be wrong here.
> 
> lcp: pppcp_open_event: current state 0:INITIAL
> lcp: pppcp_up_event: current state 1:STARTING
> lcp: pppcp_initialize_restart_count: current state 1:STARTING
> lcp: pppcp_send_configure_request: current state 1:STARTING
> lcp: option 2 len 6 (Async-Control-Character-Map) 00 00 00 00
> lcp: pppcp_process_configure_request: current state 6:REQSENT
> lcp: option 2 len 6 (Async-Control-Character-Map) 00 00 00 00
> lcp: option 3 len 5 (Authentication-Protocol) c2 23 05
> lcp: option 5 len 6 (Magic-Number) 01 ff ef e0
> lcp: option 7 len 2 (Protocol-Field-Compression)
> lcp: option 8 len 2 (Address-and-Control-Field-Compression)
> lcp: pppcp_rcr_plus_event: current state 6:REQSENT
> lcp: pppcp_send_configure_ack: current state 6:REQSENT
> lcp: option 2 len 6 (Async-Control-Character-Map) 00 00 00 00
> lcp: option 3 len 5 (Authentication-Protocol) c2 23 05
> lcp: option 5 len 6 (Magic-Number) 01 ff ef e0
> lcp: option 7 len 2 (Protocol-Field-Compression)
> lcp: option 8 len 2 (Address-and-Control-Field-Compression)
> lcp: pppcp_process_configure_ack: current state 8:ACKSENT
> lcp: option 2 len 6 (Async-Control-Character-Map) 00 00 00 00
> oops -- found acked option 2 we didn't request
> lcp: pppcp_rca_event: current state 8:ACKSENT
> lcp: pppcp_initialize_restart_count: current state 8:ACKSENT
> 
> I see the oops comment here, but we clearly requested the async control
> character map. So why does it get recognized as not requested? This is
> clearly a bug and needs to be fixed.

so I added pppdump support to GAtPPP and gsmdial. This allows us to
create log files that can be read by pppdump and Wireshark. The method
of debugging with strace is just not feasible. The attached log file is
one of these. I see a couple of confirmation requests that were send
twice in a row. That seems to be wrong. Can you explain what is going
on.

Regards

Marcel


[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #2: ppptest.log --]
[-- Type: text/x-log, Size: 4018 bytes --]

\aKµ\x12û\x01\0\x1d~ÿ}#À!}!}!} }*}"}&} } } } X{~\aKµ\x12û\x02\0U~ÿ}#À!}!} } }9}"}&} } } } }#}%Â#}%}%}&}!œ}]+}'}"}(}"˜Ú~~ÿ}#À!}"}!} }*}"}&} } } } 1}/~\aKµ\x12û\x01\08~ÿ}#À!}"} } }9}"}&} } } } }#}%Â#}%}%}&}!œ}]+}'}"}(}"}5Ö~\aKµ\x12û\x01\0\x12~ÿ\x03€!\x01\x01\0
\x03\x06\0\0\0\0\x13(~\aKµ\x12û\x02\0D~ÿ}#À!}+}!} }(}!œ}]+}-}5~~ÿ\x03Â#\x01\x01\0#\x10\x1cÚ!\0Tdv®F µÞäEZEUMTS_CHAP_SRVR[¦~\aKµ\x12û\x01\0\x1d~ÿ\x03Â#\x02\x01\0\x15\x10\x155Ü=ï‰W…×GÉ/꽃®äò~\aKµ\x12û\x02\0\f~ÿ\x03Â#\x03\x01\0\x04y’~\aKµ\x12ü\x02\0$~ÿ\x03€!\x03\x01\0\x1c\x06
\v\f\rƒ\x06
\v\f\x0e‚\x06
\v\f\r„\x06
\v\f\x0eåº~\aKµ\x12ü\x01\0*~ÿ\x03€!\x01\x02\0"\x03\x06\0\0\0\0\x06
\v\f\rƒ\x06
\v\f\x0e‚\x06
\v\f\r„\x06
\v\f\x0eüB~\aKµ\x12ý\x02\0$~ÿ\x03€!\x03\x02\0\x1c\x06
\v\f\rƒ\x06
\v\f\x0e‚\x06
\v\f\r„\x06
\v\f\x0e=L~\aKµ\x12ý\x01\0*~ÿ\x03€!\x01\x03\0"\x03\x06\0\0\0\0\x06
\v\f\rƒ\x06
\v\f\x0e‚\x06
\v\f\r„\x06
\v\f\x0eŸ\x02~\aKµ\x12þ\x02\0$~ÿ\x03€!\x03\x03\0\x1c\x06
\v\f\rƒ\x06
\v\f\x0e‚\x06
\v\f\r„\x06
\v\f\x0eu\x1e~\aKµ\x12þ\x01\0*~ÿ\x03€!\x01\x04\0"\x03\x06\0\0\0\0\x06
\v\f\rƒ\x06
\v\f\x0e‚\x06
\v\f\r„\x06
\v\f\x0e§Ë~\aKµ\x12þ\x01\0*~ÿ\x03€!\x01\x04\0"\x03\x06\0\0\0\0\x06
\v\f\rƒ\x06
\v\f\x0e‚\x06
\v\f\r„\x06
\v\f\x0e§Ë~\aKµ\x12ÿ\x02\0$~ÿ\x03€!\x03\x04\0\x1c\x06
\v\f\rƒ\x06
\v\f\x0e‚\x06
\v\f\r„\x06
\v\f\x0eœ©~\aKµ\x12ÿ\x01\0*~ÿ\x03€!\x01\x05\0"\x03\x06\0\0\0\0\x06
\v\f\rƒ\x06
\v\f\x0e‚\x06
\v\f\r„\x06
\v\f\x0eÄ‹~\aKµ\x13\0\x02\0$~ÿ\x03€!\x03\x05\0\x1c\x06
\v\f\rƒ\x06
\v\f\x0e‚\x06
\v\f\r„\x06
\v\f\x0eÔû~\aKµ\x13\0\x01\0*~ÿ\x03€!\x01\x06\0"\x03\x06\0\0\0\0\x06
\v\f\rƒ\x06
\v\f\x0e‚\x06
\v\f\r„\x06
\v\f\x0eaK~\aKµ\x13\x01\x01\0*~ÿ\x03€!\x01\x06\0"\x03\x06\0\0\0\0\x06
\v\f\rƒ\x06
\v\f\x0e‚\x06
\v\f\r„\x06
\v\f\x0eaK~\aKµ\x13\x02\x02\0$~ÿ\x03€!\x03\x06\0\x1c\x06
\v\f\rƒ\x06
\v\f\x0e‚\x06
\v\f\r„\x06
\v\f\x0e\f\r~\aKµ\x13\x02\x01\0*~ÿ\x03€!\x01\a\0"\x03\x06\0\0\0\0\x06
\v\f\rƒ\x06
\v\f\x0e‚\x06
\v\f\r„\x06
\v\f\x0e\x02\v~\aKµ\x13\x03\x02\0$~ÿ\x03€!\x03\a\0\x1c\x06
\v\f\rƒ\x06
\v\f\x0e‚\x06
\v\f\r„\x06
\v\f\x0eD_~\aKµ\x13\x03\x01\0*~ÿ\x03€!\x01\b\0"\x03\x06\0\0\0\0\x06
\v\f\rƒ\x06
\v\f\x0e‚\x06
\v\f\r„\x06
\v\f\x0e\0Ñ~\aKµ\x13\x04\x01\0*~ÿ\x03€!\x01\b\0"\x03\x06\0\0\0\0\x06
\v\f\rƒ\x06
\v\f\x0e‚\x06
\v\f\r„\x06
\v\f\x0e\0Ñ~\aKµ\x13\x05\x02\0$~ÿ\x03€!\x03\b\0\x1c\x06
\v\f\rƒ\x06
\v\f\x0e‚\x06
\v\f\r„\x06
\v\f\x0eÏj~\aKµ\x13\x05\x01\0*~ÿ\x03€!\x01	\0"\x03\x06\0\0\0\0\x06
\v\f\rƒ\x06
\v\f\x0e‚\x06
\v\f\r„\x06
\v\f\x0ec‘~\aKµ\x13\x06\x02\0$~ÿ\x03€!\x03	\0\x1c\x06
\v\f\rƒ\x06
\v\f\x0e‚\x06
\v\f\r„\x06
\v\f\x0e‡8~\aKµ\x13\x06\x01\0*~ÿ\x03€!\x01
\0"\x03\x06\0\0\0\0\x06
\v\f\rƒ\x06
\v\f\x0e‚\x06
\v\f\r„\x06
\v\f\x0eÆQ~\aKµ\x13\a\x01\0*~ÿ\x03€!\x01
\0"\x03\x06\0\0\0\0\x06
\v\f\rƒ\x06
\v\f\x0e‚\x06
\v\f\r„\x06
\v\f\x0eÆQ~\aKµ\x13\b\x02\0$~ÿ\x03€!\x03
\0\x1c\x06
\v\f\rƒ\x06
\v\f\x0e‚\x06
\v\f\r„\x06
\v\f\x0e_Î~\aKµ\x13\b\x01\0*~ÿ\x03€!\x01\v\0"\x03\x06\0\0\0\0\x06
\v\f\rƒ\x06
\v\f\x0e‚\x06
\v\f\r„\x06
\v\f\x0e¥\x11~\aKµ\x13	\x02\0$~ÿ\x03€!\x03\v\0\x1c\x06
\v\f\rƒ\x06
\v\f\x0e‚\x06
\v\f\r„\x06
\v\f\x0e\x17œ~\aKµ\x13	\x01\0*~ÿ\x03€!\x01\f\0"\x03\x06\0\0\0\0\x06
\v\f\rƒ\x06
\v\f\x0e‚\x06
\v\f\r„\x06
\v\f\x0eØ~\aKµ\x13
\x01\0*~ÿ\x03€!\x01\f\0"\x03\x06\0\0\0\0\x06
\v\f\rƒ\x06
\v\f\x0e‚\x06
\v\f\r„\x06
\v\f\x0eØ~\aKµ\x13\v\x02\0$~ÿ\x03€!\x03\f\0\x1c\x06
\v\f\rƒ\x06
\v\f\x0e‚\x06
\v\f\r„\x06
\v\f\x0eþ+~\aKµ\x13\v\x01\0*~ÿ\x03€!\x01\r\0"\x03\x06\0\0\0\0\x06
\v\f\rƒ\x06
\v\f\x0e‚\x06
\v\f\r„\x06
\v\f\x0eþ˜~\aKµ\x13\f\x02\0$~ÿ\x03€!\x03\r\0\x1c\x06
\v\f\rƒ\x06
\v\f\x0e‚\x06
\v\f\r„\x06
\v\f\x0e¶y~\aKµ\x13\f\x01\0*~ÿ\x03€!\x01\x0e\0"\x03\x06\0\0\0\0\x06
\v\f\rƒ\x06
\v\f\x0e‚\x06
\v\f\r„\x06
\v\f\x0e[X~\aKµ\x13\r\x01\0*~ÿ\x03€!\x01\x0e\0"\x03\x06\0\0\0\0\x06
\v\f\rƒ\x06
\v\f\x0e‚\x06
\v\f\r„\x06
\v\f\x0e[X~\aKµ\x13\x0e\x02\0$~ÿ\x03€!\x03\x0e\0\x1c\x06
\v\f\rƒ\x06
\v\f\x0e‚\x06
\v\f\r„\x06
\v\f\x0en~\aKµ\x13\x0e\x01\0*~ÿ\x03€!\x01\x0f\0"\x03\x06\0\0\0\0\x06
\v\f\rƒ\x06
\v\f\x0e‚\x06
\v\f\r„\x06
\v\f\x0e8\x18~\aKµ\x13\x0f\x02\0$~ÿ\x03€!\x03\x0f\0\x1c\x06
\v\f\rƒ\x06
\v\f\x0e‚\x06
\v\f\r„\x06
\v\f\x0e&Ý~\aKµ\x13\x0f\x01\0*~ÿ\x03€!\x01\x10\0"\x03\x06\0\0\0\0\x06
\v\f\rƒ\x06
\v\f\x0e‚\x06
\v\f\r„\x06
\v\f\x0eNä~\aKµ\x13\x10\x01\0*~ÿ\x03€!\x01\x10\0"\x03\x06\0\0\0\0\x06
\v\f\rƒ\x06
\v\f\x0e‚\x06
\v\f\r„\x06
\v\f\x0eNä~\aKµ\x13\x11\x02\0$~ÿ\x03€!\x03\x10\0\x1c\x06
\v\f\rƒ\x06
\v\f\x0e‚\x06
\v\f\r„\x06
\v\f\x0exä~\aKµ\x13\x11\x01\0*~ÿ\x03€!\x01\x11\0"\x03\x06\0\0\0\0\x06
\v\f\rƒ\x06
\v\f\x0e‚\x06
\v\f\r„\x06
\v\f\x0e-¤~\aKµ\x13\x12\x02\0$~ÿ\x03€!\x03\x11\0\x1c\x06
\v\f\rƒ\x06
\v\f\x0e‚\x06
\v\f\r„\x06
\v\f\x0e0¶~\aKµ\x13\x12\x01\0*~ÿ\x03€!\x01\x12\0"\x03\x06\0\0\0\0\x06
\v\f\rƒ\x06
\v\f\x0e‚\x06
\v\f\r„\x06
\v\f\x0eˆd~\aKµ\x13\x13\x01\0*~ÿ\x03€!\x01\x12\0"\x03\x06\0\0\0\0\x06
\v\f\rƒ\x06
\v\f\x0e‚\x06
\v\f\r„\x06
\v\f\x0eˆd~\aKµ\x13\x14\x02\0$~ÿ\x03€!\x03\x12\0\x1c\x06
\v\f\rƒ\x06
\v\f\x0e‚\x06
\v\f\r„\x06
\v\f\x0eè@~\aKµ\x13\x14\x01\0*~ÿ\x03€!\x01\x13\0"\x03\x06\0\0\0\0\x06
\v\f\rƒ\x06
\v\f\x0e‚\x06
\v\f\r„\x06
\v\f\x0eë$~\aKµ\x13\x15\x02\0$~ÿ\x03€!\x03\x13\0\x1c\x06
\v\f\rƒ\x06
\v\f\x0e‚\x06
\v\f\r„\x06
\v\f\x0e \x12~\aKµ\x13\x15\x01\0*~ÿ\x03€!\x01\x14\0"\x03\x06\0\0\0\0\x06
\v\f\rƒ\x06
\v\f\x0e‚\x06
\v\f\r„\x06
\v\f\x0eÓí~\aKµ\x13\x16\x01\0*~ÿ\x03€!\x01\x14\0"\x03\x06\0\0\0\0\x06
\v\f\rƒ\x06
\v\f\x0e‚\x06
\v\f\r„\x06
\v\f\x0eÓí~\aKµ\x13\x17\x02\0$~ÿ\x03€!\x03\x14\0\x1c\x06
\v\f\rƒ\x06
\v\f\x0e‚\x06
\v\f\r„\x06
\v\f\x0eI¥~\aKµ\x13\x17\x01\0*~ÿ\x03€!\x01\x15\0"\x03\x06\0\0\0\0\x06
\v\f\rƒ\x06
\v\f\x0e‚\x06
\v\f\r„\x06
\v\f\x0e°­~\aKµ\x13\x18\x02\0$~ÿ\x03€!\x03\x15\0\x1c\x06
\v\f\rƒ\x06
\v\f\x0e‚\x06
\v\f\r„\x06
\v\f\x0e\x01÷~\aKµ\x13\x18\x01\0*~ÿ\x03€!\x01\x16\0"\x03\x06\0\0\0\0\x06
\v\f\rƒ\x06
\v\f\x0e‚\x06
\v\f\r„\x06
\v\f\x0e\x15m~\aKµ\x13\x19\x01\0*~ÿ\x03€!\x01\x16\0"\x03\x06\0\0\0\0\x06
\v\f\rƒ\x06
\v\f\x0e‚\x06
\v\f\r„\x06
\v\f\x0e\x15m~\aKµ\x13\x1a\x02\0$~ÿ\x03€!\x03\x16\0\x1c\x06
\v\f\rƒ\x06
\v\f\x0e‚\x06
\v\f\r„\x06
\v\f\x0eÙ\x01~\aKµ\x13\x1a\x01\0*~ÿ\x03€!\x01\x17\0"\x03\x06\0\0\0\0\x06
\v\f\rƒ\x06
\v\f\x0e‚\x06
\v\f\r„\x06
\v\f\x0ev-~\aKµ\x13^[\x02\0$~ÿ\x03€!\x03\x17\0\x1c\x06
\v\f\rƒ\x06
\v\f\x0e‚\x06
\v\f\r„\x06
\v\f\x0e‘S~\aKµ\x13^[\x01\0*~ÿ\x03€!\x01\x18\0"\x03\x06\0\0\0\0\x06
\v\f\rƒ\x06
\v\f\x0e‚\x06
\v\f\r„\x06
\v\f\x0et÷~\aKµ\x13\x1c\x01\0*~ÿ\x03€!\x01\x18\0"\x03\x06\0\0\0\0\x06
\v\f\rƒ\x06
\v\f\x0e‚\x06
\v\f\r„\x06
\v\f\x0et÷~\aKµ\x13\x1d\x02\0$~ÿ\x03€!\x03\x18\0\x1c\x06
\v\f\rƒ\x06
\v\f\x0e‚\x06
\v\f\r„\x06
\v\f\x0e\x1af~\aKµ\x13\x1d\x01\0*~ÿ\x03€!\x01\x19\0"\x03\x06\0\0\0\0\x06
\v\f\rƒ\x06
\v\f\x0e‚\x06
\v\f\r„\x06
\v\f\x0e\x17·~\aKµ\x13\x1e\x02\0$~ÿ\x03€!\x03\x19\0\x1c\x06
\v\f\rƒ\x06
\v\f\x0e‚\x06
\v\f\r„\x06
\v\f\x0eR4~\aKµ\x13\x1e\x01\0*~ÿ\x03€!\x01\x1a\0"\x03\x06\0\0\0\0\x06
\v\f\rƒ\x06
\v\f\x0e‚\x06
\v\f\r„\x06
\v\f\x0e²w~\aKµ\x13\x1f\x01\0*~ÿ\x03€!\x01\x1a\0"\x03\x06\0\0\0\0\x06
\v\f\rƒ\x06
\v\f\x0e‚\x06
\v\f\r„\x06
\v\f\x0e²w~\aKµ\x13 \x02\0$~ÿ\x03€!\x01\0\0\x04Üí~~ÿ\x03€!\x04\x1a\0\x10‚\x06
\v\f\r„\x06
\v\f\x0eÙO~\aKµ\x13 \x01\0*~ÿ\x03€!\x03\0\0"\x03\x06\0\0\0\0\x06\0\0\0\0ƒ\x06\0\0\0\0‚\x06\0\0\0\0„\x06\0\0\0\0Y±~\aKµ\x13 \x01\0\x1e~ÿ\x03€!\x01^[\0\x16\x03\x06\0\0\0\0\x06
\v\f\rƒ\x06
\v\f\x0eeP~\aKµ\x13 \x02\0*~ÿ\x03€!\x01\x01\0\x04\0·~~ÿ\x03€!\x03^[\0\x16\x03\x06¬\x1c\x1c0\x06@Gÿƃ\x06@Gÿý\x14!~\aKµ\x13 \x01\0\x1e~ÿ\x03€!\x03\x01\0\x16\x03\x06\0\0\0\0\x06\0\0\0\0ƒ\x06\0\0\0\0Ł~\aKµ\x13 \x01\0\x1e~ÿ\x03€!\x01\x1c\0\x16\x03\x06¬\x1c\x1c0\x06@Gÿƃ\x06@Gÿý»ÿ~\aKµ\x13 \x02\0*~ÿ\x03€!\x01\x02\0\x04dX~~ÿ\x03€!\x02\x1c\0\x16\x03\x06¬\x1c\x1c0\x06@Gÿƃ\x06@GÿýM\f~\aKµ\x13 \x01\0\x1e~ÿ\x03€!\x03\x02\0\x16\x03\x06\0\0\0\0\x06\0\0\0\0ƒ\x06\0\0\0\0qØ~\aKµ\x13 \x02\0\f~ÿ\x03€!\x01\x03\0\x04¸\x02~\aKµ\x13 \x01\0\f~ÿ\x03€!\x02\x03\0\x04u'~\aKµ\x13u\x01\0\x11~ÿ}#À!}%}!} }$=Ç~\aKµ\x13v\x02\0\x11~ÿ}#À!}&}!} }$ðâ~\aKµ\x13x\x02\0\x0e
NO CARRIER

Re: PPP LCP configuration issue

[Kristen Carlson Accardi]

[-- Attachment #1: Type: text/plain, Size: 2421 bytes --]

On Thu, 01 Apr 2010 00:25:45 -0700
Marcel Holtmann <marcel@holtmann.org> wrote:

> Hi Kristen,
> 
> so I added some debug code to actually print the options during the
> configuration stage. And something seems to be wrong here.
> 
> lcp: pppcp_open_event: current state 0:INITIAL
> lcp: pppcp_up_event: current state 1:STARTING
> lcp: pppcp_initialize_restart_count: current state 1:STARTING
> lcp: pppcp_send_configure_request: current state 1:STARTING
> lcp: option 2 len 6 (Async-Control-Character-Map) 00 00 00 00
> lcp: pppcp_process_configure_request: current state 6:REQSENT
> lcp: option 2 len 6 (Async-Control-Character-Map) 00 00 00 00
> lcp: option 3 len 5 (Authentication-Protocol) c2 23 05
> lcp: option 5 len 6 (Magic-Number) 01 ff ef e0
> lcp: option 7 len 2 (Protocol-Field-Compression)
> lcp: option 8 len 2 (Address-and-Control-Field-Compression)
> lcp: pppcp_rcr_plus_event: current state 6:REQSENT
> lcp: pppcp_send_configure_ack: current state 6:REQSENT
> lcp: option 2 len 6 (Async-Control-Character-Map) 00 00 00 00
> lcp: option 3 len 5 (Authentication-Protocol) c2 23 05
> lcp: option 5 len 6 (Magic-Number) 01 ff ef e0
> lcp: option 7 len 2 (Protocol-Field-Compression)
> lcp: option 8 len 2 (Address-and-Control-Field-Compression)
> lcp: pppcp_process_configure_ack: current state 8:ACKSENT
> lcp: option 2 len 6 (Async-Control-Character-Map) 00 00 00 00
> oops -- found acked option 2 we didn't request
> lcp: pppcp_rca_event: current state 8:ACKSENT
> lcp: pppcp_initialize_restart_count: current state 8:ACKSENT
> 
> I see the oops comment here, but we clearly requested the async control
> character map. So why does it get recognized as not requested? This is
> clearly a bug and needs to be fixed.

what is happening is that we are first send a Config-Request with 
the accm option as our only option.  We then receive a Config-Request
from the modem, with accm along with several other options requested.
We ack the modem's Config-Request and apply the options, and then delete
them from the list of options that we need to have.  Then the modem
response to our original Config-Request with an ack to our accm option.
Because we already applied this option and removed it from the list of
things we care about, it shows up as an option we didn't request.
I think I could just delete the error message, and silently ignore 
this condition. 

Re: PPP LCP configuration issue

[Marcel Holtmann]

[-- Attachment #1: Type: text/plain, Size: 2654 bytes --]

Hi Kristen,

> > so I added some debug code to actually print the options during the
> > configuration stage. And something seems to be wrong here.
> > 
> > lcp: pppcp_open_event: current state 0:INITIAL
> > lcp: pppcp_up_event: current state 1:STARTING
> > lcp: pppcp_initialize_restart_count: current state 1:STARTING
> > lcp: pppcp_send_configure_request: current state 1:STARTING
> > lcp: option 2 len 6 (Async-Control-Character-Map) 00 00 00 00
> > lcp: pppcp_process_configure_request: current state 6:REQSENT
> > lcp: option 2 len 6 (Async-Control-Character-Map) 00 00 00 00
> > lcp: option 3 len 5 (Authentication-Protocol) c2 23 05
> > lcp: option 5 len 6 (Magic-Number) 01 ff ef e0
> > lcp: option 7 len 2 (Protocol-Field-Compression)
> > lcp: option 8 len 2 (Address-and-Control-Field-Compression)
> > lcp: pppcp_rcr_plus_event: current state 6:REQSENT
> > lcp: pppcp_send_configure_ack: current state 6:REQSENT
> > lcp: option 2 len 6 (Async-Control-Character-Map) 00 00 00 00
> > lcp: option 3 len 5 (Authentication-Protocol) c2 23 05
> > lcp: option 5 len 6 (Magic-Number) 01 ff ef e0
> > lcp: option 7 len 2 (Protocol-Field-Compression)
> > lcp: option 8 len 2 (Address-and-Control-Field-Compression)
> > lcp: pppcp_process_configure_ack: current state 8:ACKSENT
> > lcp: option 2 len 6 (Async-Control-Character-Map) 00 00 00 00
> > oops -- found acked option 2 we didn't request
> > lcp: pppcp_rca_event: current state 8:ACKSENT
> > lcp: pppcp_initialize_restart_count: current state 8:ACKSENT
> > 
> > I see the oops comment here, but we clearly requested the async control
> > character map. So why does it get recognized as not requested? This is
> > clearly a bug and needs to be fixed.
> 
> what is happening is that we are first send a Config-Request with 
> the accm option as our only option.  We then receive a Config-Request
> from the modem, with accm along with several other options requested.
> We ack the modem's Config-Request and apply the options, and then delete
> them from the list of options that we need to have.  Then the modem
> response to our original Config-Request with an ack to our accm option.
> Because we already applied this option and removed it from the list of
> things we care about, it shows up as an option we didn't request.
> I think I could just delete the error message, and silently ignore 
> this condition. 

are these options really negotiated for both sides in common. Or is the
negotiation process for each side individual?

Personally I like to keep such error messages. We need to cope with
these cases nicely.

Regards

Marcel

Re: PPP LCP configuration issue

[Kristen Carlson Accardi]

[-- Attachment #1: Type: text/plain, Size: 2908 bytes --]

On Fri, 02 Apr 2010 14:01:58 -0700
Marcel Holtmann <marcel@holtmann.org> wrote:

> Hi Kristen,
> 
> > > so I added some debug code to actually print the options during the
> > > configuration stage. And something seems to be wrong here.
> > > 
> > > lcp: pppcp_open_event: current state 0:INITIAL
> > > lcp: pppcp_up_event: current state 1:STARTING
> > > lcp: pppcp_initialize_restart_count: current state 1:STARTING
> > > lcp: pppcp_send_configure_request: current state 1:STARTING
> > > lcp: option 2 len 6 (Async-Control-Character-Map) 00 00 00 00
> > > lcp: pppcp_process_configure_request: current state 6:REQSENT
> > > lcp: option 2 len 6 (Async-Control-Character-Map) 00 00 00 00
> > > lcp: option 3 len 5 (Authentication-Protocol) c2 23 05
> > > lcp: option 5 len 6 (Magic-Number) 01 ff ef e0
> > > lcp: option 7 len 2 (Protocol-Field-Compression)
> > > lcp: option 8 len 2 (Address-and-Control-Field-Compression)
> > > lcp: pppcp_rcr_plus_event: current state 6:REQSENT
> > > lcp: pppcp_send_configure_ack: current state 6:REQSENT
> > > lcp: option 2 len 6 (Async-Control-Character-Map) 00 00 00 00
> > > lcp: option 3 len 5 (Authentication-Protocol) c2 23 05
> > > lcp: option 5 len 6 (Magic-Number) 01 ff ef e0
> > > lcp: option 7 len 2 (Protocol-Field-Compression)
> > > lcp: option 8 len 2 (Address-and-Control-Field-Compression)
> > > lcp: pppcp_process_configure_ack: current state 8:ACKSENT
> > > lcp: option 2 len 6 (Async-Control-Character-Map) 00 00 00 00
> > > oops -- found acked option 2 we didn't request
> > > lcp: pppcp_rca_event: current state 8:ACKSENT
> > > lcp: pppcp_initialize_restart_count: current state 8:ACKSENT
> > > 
> > > I see the oops comment here, but we clearly requested the async control
> > > character map. So why does it get recognized as not requested? This is
> > > clearly a bug and needs to be fixed.
> > 
> > what is happening is that we are first send a Config-Request with 
> > the accm option as our only option.  We then receive a Config-Request
> > from the modem, with accm along with several other options requested.
> > We ack the modem's Config-Request and apply the options, and then delete
> > them from the list of options that we need to have.  Then the modem
> > response to our original Config-Request with an ack to our accm option.
> > Because we already applied this option and removed it from the list of
> > things we care about, it shows up as an option we didn't request.
> > I think I could just delete the error message, and silently ignore 
> > this condition. 
> 
> are these options really negotiated for both sides in common. Or is the
> negotiation process for each side individual?

I think you are right for accm - they are separate.  I did have a note to 
myself to figure out how to do separate transmit accm and receive accm.  I'll
move that item up the priority list.