Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[ppp] fsm: ignore Configure-Request in opened state option #8

Merged
merged 3 commits into from
Oct 16, 2020

Conversation

avtolstoy
Copy link
Member

@avtolstoy avtolstoy commented Oct 5, 2020

Description

This PR adds a PPP configuration option to ignore standard behavior for receiving a Configure-Request in an already opened state - that is to bring the protocol down and start renegotiation. Instead this option will allow us to respond with ACK immediately without tearing down the protocol if the protocol handler does not disagree with the set of options passed in the request and we are already authenticated and it's not LCP that is going into renegotiation. Otherwise, we'll follow the standard behavior.

NOTE: we are going off standard with this, but it should be an acceptable behavior and the PPP state machine should be able to handle this properly.

The reason why we are adding this is because SARA R4 modems have a broken PPP implementation and immediately after we IPCP up, it will send us another often empty Configure-Requests without any options which increases the connection times by a lot due to us having to perform the renegotiation.

An example of IPCP behavior:


0000092017 [lwip] TRACE: rcvd [IPCP ConfAck id=0x4   ]
0000092018 [system.nm] INFO: State changed: IFACE_UP -> IFACE_LINK_UP
0000092019 [lwip] TRACE: sifup[3]: err_code=0
0000092019 [net.ppp.client] TRACE: PPP thread event UP
0000092020 [system.nm] INFO: State changed: IFACE_LINK_UP -> IP_CONFIGURED
0000092022 [lwip] TRACE: ppp phase changed[3]: phase=10
0000092022 [net.ppp.client] TRACE: PPP phase -> 10
0000093235 [lwip] TRACE: pppos_netif_output[3]: proto=0x21, len = 58
0000093242 [lwip] TRACE: pppos_input[3]: got 10 bytes
0000093243 [lwip] TRACE: rcvd [IPCP ConfReq id=0x5]
0000093243 [system.nm] INFO: State changed: IP_CONFIGURED -> IFACE_UP
0000093244 [lwip] TRACE: sifdown[3]: err_code=0
0000093244 [lwip] TRACE: ppp phase changed[3]: phase=9
0000093245 [net.ppp.client] TRACE: PPP phase -> 9
0000093245 [lwip] TRACE: sent [IPCP ConfReq id=0x5   ]
0000093246 [lwip] TRACE: pppos_write[3]: len=26
0000093247 [lwip] TRACE: sent [IPCP ConfAck id=0x5]
0000093248 [lwip] TRACE: pppos_write[3]: len=8
0000094345 [lwip] TRACE: sent [LCP EchoReq id=0x2 magic=0x585339e5]
0000094345 [lwip] TRACE: pppos_write[3]: len=12
0000094353 [lwip] TRACE: pppos_input[3]: got 10 bytes
0000094354 [lwip] TRACE: rcvd [IPCP ConfReq id=0x6]
0000094354 [lwip] TRACE: sent [IPCP ConfAck id=0x6]
0000094355 [lwip] TRACE: pppos_write[3]: len=8
0000094355 [lwip] TRACE: pppos_input[3]: got 28 bytes
0000094356 [lwip] TRACE: pppos_input[3]: got 25 bytes
0000094357 [lwip] TRACE: rcvd [IPCP ConfNak id=0x5   ]
0000094358 [lwip] TRACE: sent [IPCP ConfReq id=0x6   ]
0000094359 [lwip] TRACE: pppos_write[3]: len=26
0000094360 [lwip] TRACE: rcvd [LCP EchoRep id=0x2 magic=0x3860ec49 58 53 39 e5]
0000094574 [lwip] TRACE: pppos_input[3]: got 10 bytes
0000094575 [lwip] TRACE: pppos_input[3]: got 28 bytes
0000094576 [lwip] TRACE: rcvd [IPCP ConfReq id=0x7]
0000094577 [lwip] TRACE: sent [IPCP ConfAck id=0x7]
0000094577 [lwip] TRACE: pppos_write[3]: len=8
0000094578 [lwip] TRACE: rcvd [IPCP ConfAck id=0x6   ]
0000094579 [system.nm] INFO: State changed: IFACE_UP -> IFACE_LINK_UP
0000094580 [lwip] TRACE: sifup[3]: err_code=0
0000094581 [net.ppp.client] TRACE: PPP thread event UP
0000094581 [system.nm] INFO: State changed: IFACE_LINK_UP -> IP_CONFIGURED

With this option enabled (and we are only enabling it for R4-based devices) the conversation looks like this:


0000016926 [lwip] TRACE: sent [LCP EchoReq id=0x1 magic=0x585220ef]
0000016927 [lwip] TRACE: pppos_write[3]: len=12
0000016934 [lwip] TRACE: pppos_input[3]: got 10 bytes
0000016935 [lwip] TRACE: rcvd [IPCP ConfReq id=0x5]
0000016936 [lwip] TRACE: sent [IPCP ConfAck id=0x5]
0000016936 [lwip] TRACE: pppos_input[3]: got 28 bytes
0000016937 [lwip] TRACE: pppos_input[3]: got 25 bytes
0000016937 [lwip] TRACE: pppos_write[3]: len=8
0000016938 [lwip] TRACE: rcvd [IPCP ConfAck id=0x2   ]
0000016939 [system.nm] INFO: State changed: IFACE_UP -> IFACE_LINK_UP
0000016940 [lwip] TRACE: sifup[3]: err_code=0
0000016941 [net.ppp.client] TRACE: PPP thread event UP
0000016941 [net.ppp.client] TRACE: State CONNECTING -> CONNECTED
0000016942 [system.nm] INFO: State changed: IFACE_LINK_UP -> IP_CONFIGURED
0000016942 [net.pppncp] TRACE: Negotiated MTU: 1500
0000016944 [lwip] TRACE: ppp phase changed[3]: phase=10
0000016944 [net.ppp.client] TRACE: PPP phase -> 10
0000016944 [system] INFO: Cloud: connecting
0000016947 [system] INFO: Cloud socket connected
0000016947 [comm.protocol.handshake] INFO: Establish secure connection
0000017075 [lwip] TRACE: pppos_input[3]: got 10 bytes
0000017075 [lwip] TRACE: rcvd [IPCP ConfReq id=0x6]
0000017076 [lwip] TRACE: sent [IPCP ConfAck id=0x6]
0000017077 [lwip] TRACE: pppos_write[3]: len=8

This change cuts down connection times on R4-based devices by 10-20 seconds in some cases and also allows us to get out of the renegotiation loop in LCP (don't have a log currently at hand).

References

  • [CH64715]

@avtolstoy avtolstoy force-pushed the feature/ppp-fsm-ignore-confreq-in-opened branch from 42b4345 to 8c435fd Compare October 5, 2020 23:42
/* Go down and restart negotiation */
fsm_rconfreq_down_restart(f);
} else {
FSMDEBUG(("%s: Non-conflicting Configure-Request in opened state, ACKing", PROTO_NAME(f)));
Copy link
Member

@sergeuz sergeuz Oct 6, 2020

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

in opened state

Can't it also be in stopped state here?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

👍 Good catch. I'll fix this. Might be the reason why it didn't work with LCP issues.

Copy link

@keeramis keeramis left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Nice change! (I believe as long as we are not ignoring true ConfReqs it should be okay.)

Here's an example test log from this PR which works fine.

ppp_pr8.txt

@avtolstoy
Copy link
Member Author

I've changed things a bit and now this properly handles broken R4 behavior with LCP as well:

0000025794 [lwip] TRACE: pppos_connect: unit 3: connecting
0000025795 [lwip] TRACE: ppp_start[3]
0000025795 [lwip] TRACE: ppp phase changed[3]: phase=6
0000025796 [lwip] TRACE: pppos_send_config[3]: out_accm=FF FF FF FF
0000025796 [lwip] TRACE: ppp_send_config[3]
0000025797 [lwip] TRACE: pppos_recv_config[3]: in_accm=FF FF FF FF
0000025797 [lwip] TRACE: ppp_recv_config[3]
0000025798 [lwip] TRACE: ppp: auth protocols:
0000025798 [lwip] TRACE:  PAP=1
0000025798 [lwip] TRACE:  CHAP=1 CHAP_MD5=1
0000025799 [lwip] TRACE:
0000025799 [lwip] TRACE: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x585257fe> <pcomp> <accomp>]
0000025800 [lwip] TRACE: pppos_write[3]: len=24
0000025801 [lwip] TRACE: ppp_start[3]: finished
0000027051 [lwip] TRACE: pppos_input[3]: got 52 bytes
0000027052 [lwip] TRACE: rcvd [LCP ConfReq id=0xa8 <asyncmap 0x0> <auth chap MD5> <magic 0x718fb7a3> <pcomp> <accomp>]
0000027053 [lwip] TRACE: sent [LCP ConfAck id=0xa8 <asyncmap 0x0> <auth chap MD5> <magic 0x718fb7a3> <pcomp> <accomp>]
0000027055 [lwip] TRACE: pppos_write[3]: len=29
0000027053 [lwip] TRACE: pppos_input[3]: got 45 bytes
0000027056 [lwip] TRACE: rcvd [LCP ConfAck id=0x1 <asyncmap 0x0> <magic 0x585257fe> <pcomp> <accomp>]
0000027057 [lwip] TRACE: netif_set_mtu[3]: mtu=1500
0000027057 [lwip] TRACE: pppos_send_config[3]: out_accm=0 0 0 0
0000027058 [lwip] TRACE: ppp_send_config[3]
0000027058 [lwip] TRACE: pppos_recv_config[3]: in_accm=0 0 0 0
0000027059 [lwip] TRACE: ppp_recv_config[3]
0000027059 [lwip] TRACE: sent [LCP EchoReq id=0x0 magic=0x585257fe]
0000027060 [lwip] TRACE: pppos_write[3]: len=12
0000027061 [lwip] TRACE: ppp phase changed[3]: phase=7
0000028331 [lwip] TRACE: pppos_input[3]: got 52 bytes
0000028332 [lwip] TRACE: rcvd [LCP ConfReq id=0xa9 <asyncmap 0x0> <auth chap MD5> <magic 0x718fb7a3> <pcomp> <accomp>]
0000028333 [lwip] TRACE: sent [LCP ConfAck id=0xa9 <asyncmap 0x0> <auth chap MD5> <magic 0x718fb7a3> <pcomp> <accomp>]
0000028334 [lwip] TRACE: pppos_write[3]: len=29
0000029611 [lwip] TRACE: pppos_input[3]: got 53 bytes
0000029612 [lwip] TRACE: rcvd [LCP ConfReq id=0xaa <asyncmap 0x0> <auth chap MD5> <magic 0x718fb7a3> <pcomp> <accomp>]
0000029613 [lwip] TRACE: sent [LCP ConfAck id=0xaa <asyncmap 0x0> <auth chap MD5> <magic 0x718fb7a3> <pcomp> <accomp>]
0000029614 [lwip] TRACE: pppos_write[3]: len=29
0000030891 [lwip] TRACE: pppos_input[3]: got 52 bytes
0000030892 [lwip] TRACE: rcvd [LCP ConfReq id=0xab <asyncmap 0x0> <auth chap MD5> <magic 0x718fb7a3> <pcomp> <accomp>]
0000030893 [lwip] TRACE: sent [LCP ConfAck id=0xab <asyncmap 0x0> <auth chap MD5> <magic 0x718fb7a3> <pcomp> <accomp>]
0000030894 [lwip] TRACE: pppos_write[3]: len=29
0000032060 [lwip] TRACE: sent [LCP EchoReq id=0x1 magic=0x585257fe]
0000032061 [lwip] TRACE: pppos_write[3]: len=12
0000032069 [lwip] TRACE: pppos_input[3]: got 52 bytes
0000032070 [lwip] TRACE: rcvd [LCP ConfReq id=0xac <asyncmap 0x0> <auth chap MD5> <magic 0x718fb7a3> <pcomp> <accomp>]
0000032071 [lwip] TRACE: sent [LCP ConfAck id=0xac <asyncmap 0x0> <auth chap MD5> <magic 0x718fb7a3> <pcomp> <accomp>]
0000032072 [lwip] TRACE: pppos_write[3]: len=29
0000033451 [lwip] TRACE: pppos_input[3]: got 52 bytes
0000033452 [lwip] TRACE: rcvd [LCP ConfReq id=0xad <asyncmap 0x0> <auth chap MD5> <magic 0x718fb7a3> <pcomp> <accomp>]
0000033453 [lwip] TRACE: sent [LCP ConfAck id=0xad <asyncmap 0x0> <auth chap MD5> <magic 0x718fb7a3> <pcomp> <accomp>]
0000033454 [lwip] TRACE: pppos_write[3]: len=29
0000034731 [lwip] TRACE: pppos_input[3]: got 53 bytes
0000034732 [lwip] TRACE: rcvd [LCP ConfReq id=0xae <asyncmap 0x0> <auth chap MD5> <magic 0x718fb7a3> <pcomp> <accomp>]
0000034733 [lwip] TRACE: sent [LCP ConfAck id=0xae <asyncmap 0x0> <auth chap MD5> <magic 0x718fb7a3> <pcomp> <accomp>]
0000034734 [lwip] TRACE: pppos_write[3]: len=29
0000036011 [lwip] TRACE: pppos_input[3]: got 53 bytes
0000036012 [lwip] TRACE: rcvd [LCP ConfReq id=0xaf <asyncmap 0x0> <auth chap MD5> <magic 0x718fb7a3> <pcomp> <accomp>]
0000036013 [lwip] TRACE: sent [LCP ConfAck id=0xaf <asyncmap 0x0> <auth chap MD5> <magic 0x718fb7a3> <pcomp> <accomp>]
0000036014 [lwip] TRACE: pppos_write[3]: len=29
0000037062 [lwip] TRACE: sent [LCP EchoReq id=0x2 magic=0x585257fe]
0000037062 [lwip] TRACE: pppos_write[3]: len=12
0000037070 [lwip] TRACE: pppos_input[3]: got 52 bytes
0000037071 [lwip] TRACE: rcvd [LCP ConfReq id=0xb0 <asyncmap 0x0> <auth chap MD5> <magic 0x718fb7a3> <pcomp> <accomp>]
0000037072 [lwip] TRACE: sent [LCP ConfAck id=0xb0 <asyncmap 0x0> <auth chap MD5> <magic 0x718fb7a3> <pcomp> <accomp>]
0000037073 [lwip] TRACE: pppos_write[3]: len=29
0000037292 [lwip] TRACE: pppos_input[3]: got 52 bytes
0000037292 [lwip] TRACE: rcvd [LCP ConfReq id=0xb1 <asyncmap 0x0> <auth chap MD5> <magic 0x718fb7a3> <pcomp> <accomp>]
0000037294 [lwip] TRACE: sent [LCP ConfAck id=0xb1 <asyncmap 0x0> <auth chap MD5> <magic 0x718fb7a3> <pcomp> <accomp>]
0000037295 [lwip] TRACE: pppos_write[3]: len=29
0000038571 [lwip] TRACE: pppos_input[3]: got 21 bytes
0000038572 [lwip] TRACE: rcvd [LCP DiscReq id=0xb2 magic=0x718fb7a3]
0000038572 [lwip] TRACE: pppos_input[3]: got 41 bytes
0000038573 [lwip] TRACE: rcvd [CHAP Challenge id=0x1 <5afe92f65a3826cc59620cd2ab9a45da>, name = "UMTS_CHAP_SRVR"]
0000038574 [lwip] TRACE: No CHAP secret found for authenticating us to UMTS_CHAP_SRVR
0000038575 [lwip] TRACE: sent [CHAP Response id=0x1 <afdf8cf3a7d9f6225a0b2c77b6f69f77>, name = ""]
0000038576 [lwip] TRACE: pppos_write[3]: len=25
0000039850 [lwip] TRACE: pppos_input[3]: got 10 bytes
0000039851 [lwip] TRACE: rcvd [CHAP Success id=0x1 ""]
0000039851 [lwip] TRACE: CHAP authentication succeeded
0000039852 [lwip] TRACE: CHAP authentication succeeded
0000039852 [lwip] TRACE: ppp phase changed[3]: phase=9
0000039853 [lwip] TRACE: sent [IPCP ConfReq id=0x1 <addr 0.0.0.0> <msdns1 8.8.8.8> <msdns2 8.8.4.4>]
0000039854 [lwip] TRACE: pppos_write[3]: len=26
0000041131 [lwip] TRACE: pppos_input[3]: got 10 bytes

@sergeuz could you please take a look once again? Thanks.

@avtolstoy avtolstoy merged commit 8837180 into particle Oct 16, 2020
@avtolstoy avtolstoy deleted the feature/ppp-fsm-ignore-confreq-in-opened branch October 16, 2020 19:06
avtolstoy added a commit to particle-iot/device-os that referenced this pull request Oct 16, 2020
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants