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.

Sign up for GitHub

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

Jump to bottom

Protocol decode mismatch and severe packet loss #5

Closed
deba12 opened this issue Jul 8, 2015 · 12 comments
Closed

Protocol decode mismatch and severe packet loss #5

deba12 opened this issue Jul 8, 2015 · 12 comments
Labels
bug

Comments

@deba12
Copy link
Contributor

deba12 commented Jul 8, 2015

Hello,
i have just tried your last version there are errors in pppd log about unsupported protocol.
After that errors windows clients expirience severe packet loss that leads to disconnection
logs from pppd

2015-07-09T00:23:53.402367+03:00 vpn-server pppd[8403]: pppd 2.4.6 started by root, uid 0
2015-07-09T00:23:53.402586+03:00 vpn-server pppd[8403]: using channel 1033
2015-07-09T00:23:53.402939+03:00 vpn-server pppd[8403]: Using interface ppp0
2015-07-09T00:23:53.403059+03:00 vpn-server pppd[8403]: Connect: ppp0 <--> /dev/pts/3
2015-07-09T00:23:53.403264+03:00 vpn-server pppd[8403]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <auth chap MS-v2> <magic 0xd79088c7> <pcomp> <accomp>]
2015-07-09T00:23:53.509403+03:00 vpn-server pppd[8403]: rcvd [LCP ConfReq id=0x0 <mru 4091> <magic 0x3a00292c> <pcomp> <accomp> <callback CBCP> <mrru 1614> <endpoint [local:b5.1f.d9.e8.f4.86.46.e3.bc.98.5c.9a.4a.7c.b2.62.00.00.00.0c]>]
2015-07-09T00:23:53.509428+03:00 vpn-server pppd[8403]: sent [LCP ConfRej id=0x0 <callback CBCP> <mrru 1614>]
2015-07-09T00:23:53.546378+03:00 vpn-server pppd[8403]: rcvd [LCP ConfAck id=0x1 <asyncmap 0x0> <auth chap MS-v2> <magic 0xd79088c7> <pcomp> <accomp>]
2015-07-09T00:23:53.583447+03:00 vpn-server pppd[8403]: rcvd [LCP ConfReq id=0x1 <mru 4091> <magic 0x3a00292c> <pcomp> <accomp> <endpoint [local:b5.1f.d9.e8.f4.86.46.e3.bc.98.5c.9a.4a.7c.b2.62.00.00.00.0c]>]
2015-07-09T00:23:53.583465+03:00 vpn-server pppd[8403]: sent [LCP ConfAck id=0x1 <mru 4091> <magic 0x3a00292c> <pcomp> <accomp> <endpoint [local:b5.1f.d9.e8.f4.86.46.e3.bc.98.5c.9a.4a.7c.b2.62.00.00.00.0c]>]
2015-07-09T00:23:53.583493+03:00 vpn-server pppd[8403]: sent [LCP EchoReq id=0x0 magic=0xd79088c7]
2015-07-09T00:23:53.583512+03:00 vpn-server pppd[8403]: sent [CHAP Challenge id=0x95 <a3181101c5c77845fac665897416225a>, name = "sstpd"]
2015-07-09T00:23:53.624084+03:00 vpn-server pppd[8403]: rcvd [LCP Ident id=0x2 magic=0x3a00292c "MSRASV5.20"] c0 21 0c 03 00 1f 3a 00 29 2c 4d 53 52 41 53 2d 30 2d 57 49 4e 2d 48 47 41 42 52 4e 55 54 30 4d ...
2015-07-09T00:23:53.625795+03:00 vpn-server pppd[8403]: rcvd [LCP EchoRep id=0x0 magic=0x3a00292c]
2015-07-09T00:23:53.628134+03:00 vpn-server pppd[8403]: rcvd [CHAP Response id=0x95 <24555f687d362359bd911b8bd86820cc0000000000000000f4ac22e29ecd6b76bdc2173aaf32f413e789c073d558787800>, name = "user"]
2015-07-09T00:23:53.628880+03:00 vpn-server pppd[8403]: sent [CHAP Success id=0x95 "S=6A6C5B424560B3BFF323DE614A54DE5D71281117 M=Access granted"]
2015-07-09T00:23:53.628980+03:00 vpn-server pppd[8403]: sent [IPCP ConfReq id=0x1 <addr 10.51.0.1>]
2015-07-09T00:23:53.669201+03:00 vpn-server pppd[8403]: rcvd [IPCP ConfReq id=0x5 <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-wins 0.0.0.0> <ms-dns2 0.0.0.0> <ms-wins 0.0.0.0>]
2015-07-09T00:23:53.669216+03:00 vpn-server pppd[8403]: sent [IPCP ConfRej id=0x5 <ms-wins 0.0.0.0> <ms-wins 0.0.0.0>]
2015-07-09T00:23:53.669844+03:00 vpn-server pppd[8403]: rcvd [IPCP ConfAck id=0x1 <addr 10.51.0.1>]
2015-07-09T00:23:53.707833+03:00 vpn-server pppd[8403]: rcvd [IPCP ConfReq id=0x6 <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns2 0.0.0.0>]
2015-07-09T00:23:53.707850+03:00 vpn-server pppd[8403]: sent [IPCP ConfNak id=0x6 <addr 10.51.0.2> <ms-dns1 8.8.8.8> <ms-dns2 8.8.4.4>]
2015-07-09T00:23:53.745637+03:00 vpn-server pppd[8403]: rcvd [IPCP ConfReq id=0x7 <addr 10.51.0.2> <ms-dns1 8.8.8.8> <ms-dns2 8.8.4.4>]
2015-07-09T00:23:53.745653+03:00 vpn-server pppd[8403]: sent [IPCP ConfAck id=0x7 <addr 10.51.0.2> <ms-dns1 8.8.8.8> <ms-dns2 8.8.4.4>]
2015-07-09T00:23:53.746306+03:00 vpn-server pppd[8403]: local  IP address 10.51.0.1
2015-07-09T00:23:53.746320+03:00 vpn-server pppd[8403]: remote IP address 10.51.0.2
2015-07-09T00:23:53.746705+03:00 vpn-server pppd[8403]: Script /etc/ppp/ip-up started (pid 8406)
2015-07-09T00:23:53.748707+03:00 vpn-server pppd[8403]: Script /etc/ppp/ip-up finished (pid 8406), status = 0x0
2015-07-09T00:24:20.347745+03:00 vpn-server pppd[8403]: rcvd [proto=0xb5] ed 97 71 cc 0c 43 c2 77 07 0e 2e f2 d7 17 69 ae fb 45 a0 11 22 4a 7f 3c 3a 0d 2e f2 99 96 20 f8 ...
2015-07-09T00:24:20.347754+03:00 vpn-server pppd[8403]: Unsupported protocol 0xb5 received
2015-07-09T00:24:20.347764+03:00 vpn-server pppd[8403]: sent [LCP ProtRej id=0x2 00 b5 ed 97 71 cc 0c 43 c2 77 07 0e 2e f2 d7 17 69 ae fb 45 a0 11 22 4a 7f 3c 3a 0d 2e f2 99 96 ...]
2015-07-09T00:25:23.371749+03:00 vpn-server pppd[8403]: Hangup (SIGHUP)

logs from sstpd

2015-07-09 00:23:53,395 INFO: SSTP control packet (type 1) received.
2015-07-09 00:23:53,667 INFO: SSTP control packet (type 4) received.
2015-07-09 00:23:53,667 INFO: Connection established.
2015-07-09 00:25:23,371 INFO: Connection finished.
2015-07-09 00:25:23,382 INFO: pppd stopped.
@deba12
Copy link
Contributor Author

deba12 commented Jul 8, 2015

After some debugging, i think i found what is the problem:
if ppp data frame is larger than mtu, sstpd drops link in few seconds
logs from sstpd -v 5

2015-07-09 01:00:38,648 DEBUG: Forwarding SSTP data to pppd (41 bytes).
2015-07-09 01:00:38,663 DEBUG: Forwarding SSTP data to pppd (1234 bytes).
2015-07-09 01:00:38,673 DEBUG: PPP data frame received (51369 bytes).
2015-07-09 01:00:38,693 DEBUG: Forwarding SSTP data to pppd (41 bytes).
2015-07-09 01:00:38,693 DEBUG: Forwarding SSTP data to pppd (41 bytes).
2015-07-09 01:00:38,694 DEBUG: Forwarding SSTP data to pppd (41 bytes).
2015-07-09 01:00:38,694 DEBUG: Forwarding SSTP data to pppd (41 bytes).
2015-07-09 01:00:38,694 DEBUG: Forwarding SSTP data to pppd (41 bytes).
2015-07-09 01:00:38,695 DEBUG: Forwarding SSTP data to pppd (41 bytes).
2015-07-09 01:00:38,695 DEBUG: Forwarding SSTP data to pppd (41 bytes).
2015-07-09 01:00:38,695 DEBUG: Forwarding SSTP data to pppd (41 bytes).
2015-07-09 01:00:38,695 DEBUG: Forwarding SSTP data to pppd (53 bytes).
2015-07-09 01:00:38,697 DEBUG: Forwarding SSTP data to pppd (41 bytes).
2015-07-09 01:00:38,697 DEBUG: Forwarding SSTP data to pppd (41 bytes).
2015-07-09 01:00:38,697 DEBUG: Forwarding SSTP data to pppd (87 bytes).
2015-07-09 01:00:38,698 DEBUG: Forwarding SSTP data to pppd (41 bytes).
2015-07-09 01:00:38,698 DEBUG: Forwarding SSTP data to pppd (41 bytes).
2015-07-09 01:00:38,698 DEBUG: Forwarding SSTP data to pppd (41 bytes).
2015-07-09 01:00:38,699 DEBUG: Forwarding SSTP data to pppd (41 bytes).
2015-07-09 01:00:38,700 DEBUG: Forwarding SSTP data to pppd (41 bytes).
2015-07-09 01:00:38,700 DEBUG: Forwarding SSTP data to pppd (41 bytes).
2015-07-09 01:00:38,701 DEBUG: Forwarding SSTP data to pppd (41 bytes).
2015-07-09 01:00:38,701 DEBUG: Forwarding SSTP data to pppd (41 bytes).
2015-07-09 01:00:38,702 DEBUG: Forwarding SSTP data to pppd (41 bytes).
2015-07-09 01:00:38,702 DEBUG: Forwarding SSTP data to pppd (41 bytes).
2015-07-09 01:00:38,703 DEBUG: Forwarding SSTP data to pppd (41 bytes).
2015-07-09 01:00:38,703 DEBUG: Forwarding SSTP data to pppd (130 bytes).
2015-07-09 01:00:38,786 INFO: Connection finished.
2015-07-09 01:00:38,794 INFO: pppd stopped.

@sorz
Copy link
Owner

sorz commented Jul 9, 2015

Hello,
Thanks for provide those information.
The unusual large frame seem be caused by a sort of incorrect decoding.
I will review the code and try to identify the problem.

@sorz
Copy link
Owner

sorz commented Jul 9, 2015

there are errors in pppd log about unsupported protocol.

This problems seem due to the pppd fail to parsing the frames which sstpd sent.

By adding record option to pppd to inspect the data flow, pppd seems randomly (?) combine
multiple PPP frames (IP packets) as one. And then, cut the last frame to two part, and recognize
the latter half part as a new frames which has unsupported (actually, random) "protocol number".

if ppp data frame is larger than mtu, sstpd drops link in few seconds

This one cause by sstpd cannot parsing the frames which pppd sent correctly.

I found pppd sent a half frame to sstpd, and follow by a complete one.
(a1a2a3a4 become to a1a2a1a2a3a4, where a1~a4 stands for a complete ppp frame.)

It is my understanding that the only way to determine the "gap" between each ppp frames
is reading the length field of each frames. But now, I'm unsure about it....

@deba12
Copy link
Contributor Author

deba12 commented Jul 10, 2015

Ok. Let me know if you found something.
I will check different implementations such as ppp over ssh, ppp over ssl
how they solved that problem

@deba12
Copy link
Contributor Author

deba12 commented Jul 10, 2015

I found one sstpd implementation written in javascript, but that implementation barely able to survive to open google.com :) anyway there is handling for large ppp frames
https://github.com/deba12/sstpd/blob/master/sstpd.js#L554
i hope that helps

@sorz
Copy link
Owner

sorz commented Jul 10, 2015

En.. I added the option sync to pppd, but other implementations don't.
I don't know exactly what it stand for, but... after added it, frames look like what SSTP client sent.
So, maybe I have to remove this option and write some code to covert the frames by myself.. just like what other people did.

@deba12
Copy link
Contributor Author

deba12 commented Jul 13, 2015

Interesting, with sync i am able to get ip addres 1/10 cases
sync does not work as I expected.

@sorz
Copy link
Owner

sorz commented Jul 13, 2015

Try out the async branch and see if fix. 😄

@sorz sorz added the bug label Jul 13, 2015
@deba12
Copy link
Contributor Author

deba12 commented Jul 14, 2015

It works :)
i see 2 problems

  1. Very high cpu usage (bandwidth was around 20mbit/s but cpu usage was over 70% on sandy bridge xeon), may be there can be specified which ciphers to be used (aes-128 or rc4)
  2. Some times sstp peer discards lcp traffic and unable to complete connection. I will get some logs later today and post them here.

@sorz
Copy link
Owner

sorz commented Jul 14, 2015

FCS calculation is written in C now. (unsure whether effective)
--ciphers was added, RC4 seem be rejected by Windows 8 but AES128 works.

@deba12
Copy link
Contributor Author

deba12 commented Jul 14, 2015

thanks i will test all the things
and get logs tomorrow

@deba12
Copy link
Contributor Author

deba12 commented Jul 15, 2015

I have do some profile with vmprofile module for python
to see what is eating so many cpu cycles.
i am wandering why outReceived takes so many cpu cycles?
Also i do some tests with pypy, it works much much better
two to three times low cpu usage :)

vmprof output:
 %:      name:                               location:
 100.0%  <module>                            /usr/local/bin/sstpd:3
 100.0%  _run_module_code                    /usr/lib/python2.7/runpy.py:75
 100.0%  _run_code                           /usr/lib/python2.7/runpy.py:62
 100.0%  run_path                            /usr/lib/python2.7/runpy.py:223
 96.0%   main                                build/bdist.linux-x86_64/egg/sstpd/__init__.py:70
 95.8%   run                                 /usr/local/lib/python2.7/dist-packages/twisted/internet/base.py:1192
 95.8%   mainLoop                            /usr/local/lib/python2.7/dist-packages/twisted/internet/base.py:1197
 93.8%   doPoll                              /usr/local/lib/python2.7/dist-packages/twisted/internet/epollreactor.py:367
 91.9%   callWithLogger                      /usr/local/lib/python2.7/dist-packages/twisted/python/log.py:88
 91.2%   callWithContext                     /usr/local/lib/python2.7/dist-packages/twisted/python/log.py:81
 89.4%   callWithContext                     /usr/local/lib/python2.7/dist-packages/twisted/python/context.py:117
 89.0%   callWithContext                     /usr/local/lib/python2.7/dist-packages/twisted/python/context.py:61
 88.5%   _doReadOrWrite                      /usr/local/lib/python2.7/dist-packages/twisted/internet/posixbase.py:569
 67.2%   doRead                              /usr/local/lib/python2.7/dist-packages/twisted/internet/process.py:1079
 67.0%   readFromFD                          /usr/local/lib/python2.7/dist-packages/twisted/internet/fdesc.py:62
 65.7%   <lambda>                            /usr/local/lib/python2.7/dist-packages/twisted/internet/process.py:1085
 65.6%   childDataReceived                   /usr/local/lib/python2.7/dist-packages/twisted/internet/protocol.py:595
 65.5%   outReceived                         build/bdist.linux-x86_64/egg/sstpd/protocols.py:36
 15.6%   doRead                              /usr/local/lib/python2.7/dist-packages/twisted/internet/tcp.py:193
 14.7%   _dataReceived                       /usr/local/lib/python2.7/dist-packages/twisted/internet/tcp.py:212
 14.6%   dataReceived                        /usr/local/lib/python2.7/dist-packages/twisted/protocols/tls.py:400
 14.0%   _flushReceiveBIO                    /usr/local/lib/python2.7/dist-packages/twisted/protocols/tls.py:346
 13.4%   pppFrameReceived                    build/bdist.linux-x86_64/egg/sstpd/protocols.py:59
 12.1%   pppDataFrameReceived                build/bdist.linux-x86_64/egg/sstpd/protocols.py:80
 10.5%   writeTo                             build/bdist.linux-x86_64/egg/sstpd/packets.py:15
 9.9%    write                               /usr/local/lib/python2.7/dist-packages/twisted/protocols/tls.py:515
 9.5%    _write                              /usr/local/lib/python2.7/dist-packages/twisted/protocols/tls.py:533
 8.1%    dataReceived                        /usr/local/lib/python2.7/dist-packages/twisted/protocols/policies.py:119
 7.9%    dataReceived                        build/bdist.linux-x86_64/egg/sstpd/protocols.py:125
 7.8%    sstpDataReceived                    build/bdist.linux-x86_64/egg/sstpd/protocols.py:158

@sorz sorz mentioned this issue Jul 15, 2015
Closed
@sorz sorz closed this as completed in 912b4b3 Jul 15, 2015
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@deba12 @sorz