Open minzkn opened 2 years ago
sonertari
commented
2 years ago I use the autossl proxyspecs for POP3 and SMTP servers with STARTTLS support. And I am not aware of any HTTP server with STARTTLS support, perhaps it's my ignorance, but why do you use autossl for HTTP? In other words, I think the issue may not be about the sslsplit code for buffer watermarking.
minzkn
commented
2 years ago Dear Soner Tari
The https I mentioned is an example environment.
I wanted to try using sslsplit for well-known protocols including pop3, STARTTLS from smtp, as well as unknown pseudo-SSL communications that start with plaintext and have an SSL client hello in the middle.
In the end, sslsplit was a solution that basically worked well by using autossl for https, pop3, smtp, ... etc.
However, it seems that evbuffer_get_length(outbuf) always returns 0 only for autossl, so I was wondering why.
It is questionable that buffer watermarking does not work in autossl.
sonertari
commented
2 years ago I cannot create your test environment, and it is hard to guess looking at the code, so we need further info.
If you enable debug logging with -D, what does sslsplit say until oom? Does it say Peek found ClientHello or Peek found no ClientHello?
Also, if you enable content logging do you see any content until oom?
Btw, how do you know "evbuffer_get_length(outbuf) always returns 0"?
minzkn
commented
2 years ago Just before oom occurs, the following message is generated. In some cases, this message occurs just before OOM, but in other cases it is not. But this message doesn't seem to be highly related to OOM as it's been mixed with multiple connection tests.
Error from src bufferevent: 0:- 336151574:1046:(null):20:(null):148:(null)
The log confirms that ClientHello is found as follows:
Connecting to [xxx.yyy.zzz.aaa]:443
tcp 192.168.0.111 18334 xxx.yyy.zzz.aaa 443
TCP connected to [xxx.yyy.zzz.aaa]:443
TCP connected from [192.168.0.111]:18334
Checking for a client hello
Peek found ClientHello
Attempt reuse dst SSL session
Replaced dst bufferevent, new one is 0x7f6794008a50
===> Original server certificate:
Subject DN: /CN=<my domain>
Common Names: <my CN...>
Fingerprint: <my Fingerprint>
Certificate cache: HIT
===> Forged server certificate:
Subject DN: /CN=<my domain>
Common Names: <my CN...>
Fingerprint: <my Fingerprint>
Completing autossl upgrade
Certificate cache: KEEP (SNI match or target mode)
SSL connected to [xxx.yyy.zzz.aaa]:443 TLSv1.3 TLS_AES_256_GCM_SHA384
CLIENT_RANDOM CAD0D36791A9A3D628096233B32A1706339B4040BEDA2943DA4C3E145CB476AE 0000000000000000D066009467000000000000000000000000FAA45DA52A519E508A0094677F0000E071140100000000
Certificate cache: KEEP (SNI match or target mode)
upgrade 192.168.0.111 18334 xxx.yyy.zzz.aaa 443 sni:<my domain> names:<my CN...> sproto:TLSv1.3:TLS_AES_128_GCM_SHA256 dproto:TLSv1.3:TLS_AES_256_GCM_SHA384 origcrt:<my ...> usedcrt:<my ...>
SSL connected from [192.168.0.111]:18334 TLSv1.3 TLS_AES_128_GCM_SHA256
CLIENT_RANDOM 6F675B5529C8D7030E25E655AC4B10B5A32BE2A10FF90F6CC8FD8D40AEB68793 A80BB417808D2C1D467FD2A75E972856E84999602EF9B7C6545C43CADA585CC4161A129C677F0000D0660094677F0000
Garbage collecting caches started.
Garbage collecting caches done.
...
<OOM - Out Of Memory>When content logging is enabled, content is displayed up to OOM. Until OOM occurs, it seems to work just fine except for the memory increase of sslsplit.
I found out that evbuffer_get_length(outbuf) returns 0 by inserting the following debugging code in that part.
evbuffer_add_buffer(outbuf, inbuf);
if (OPTS_DEBUG(ctx->opts)) {
log_err_printf("buffer watermark control ! (inbuf=%lu, outbuf=%lu, OUTBUF_LIMIT=%lu)\n", (unsigned long)evbuffer_get_length(inbuf), (unsigned long)evbuffer_get_length(outbuf), (unsigned long)OUTBUF_LIMIT);
}
if (evbuffer_get_length(outbuf) >= OUTBUF_LIMIT) {
/* temporarily disable data source;
* set an appropriate watermark. */
bufferevent_setwatermark(other->bev, EV_WRITE,
OUTBUF_LIMIT/2, OUTBUF_LIMIT);
bufferevent_disable(bev, EV_READ);
}
=> This case always inbuf/outbuf is zero. but ssl case outbuf not zero
buffer watermark control ! (inbuf=0, outbuf=0, OUTBUF_LIMIT=131072)
buffer watermark control ! (inbuf=0, outbuf=0, OUTBUF_LIMIT=131072)
buffer watermark control ! (inbuf=0, outbuf=0, OUTBUF_LIMIT=131072)
...P.s. Even if I look at the sslsplit source, it seems to have been implemented well, but I do not know the cause. The difference between ssl and autossl is the difference in calling bufferevent_openssl_filter_new in pxy_conn_autossl_peek_and_upgrade, but I'm guessing that this is what makes the difference. I tested with libevent-2.1.12 instead of libevent-2.1.8 just in case, but it is the same. The peculiar thing is that if you check evbuffer_get_length(inbuf) before calling evbuffer_add_buffer(outbuf, inbuf) it is not 0, but if you check evbuffer_get_length(outbuf) after calling evbuffer_get_length(outbuf) it is 0.
sonertari
commented
2 years ago I look at the debug logs you have provided, and at the code in pxy_bev_readcb(). So far this is what we know:
Yes, I agree, this is as strange as you say. And, it may be related with libevent, as you have suspected, since you have already tried different versions of libevent.
As you mention you have multiple test connections, so in sslsplit logs it is hard to know which log line is related with which connection.
So, I want to suggest that we use sslproxy instead of sslsplit now. The design of sslproxy is different from sslsplit, but it supports autossl, buffer watermarking, and split style proxyspecs. Also, if you enable the DEBUG_PROXY switch in Mk/main.mk and start sslproxy with -D4, it is going to print very verbose debug logs with connection ids and file descriptor numbers, so we can easily relate debug lines with connections. We can even follow the execution of its source code by looking at those debug logs. (Btw, sslsplit supports the DEBUG_PROXY switch too, but it is much less verbose.)
If we use sslproxy, we can perhaps get more detailed info about the issue, and more importantly perhaps we can rule out libevent as the culprit. Also, since the design and implementation of sslproxy is different from sslsplit, it may be better to try sslproxy now instead of keeping trying sslsplit (for example, if sslproxy succeeds then it is the sslsplit code).
It is possible that sslproxy will not work in your test environment at all. So, it's up to you.
sonertari
commented
2 years ago Also, just to make sure that callbacks for the overridden bevs are disabled, can you apply the following patch and report back please?:
--- pxyconn.c.orig 2022-03-25 22:45:11.607758000 +0300
+++ pxyconn.c 2022-03-25 22:45:32.568031558 +0300
@@ -1691,6 +1691,8 @@
"upgrade\n");
return 0;
}
+ bufferevent_setcb(ctx->dst.bev, NULL, NULL, NULL, NULL);
+ bufferevent_disable(ctx->dst.bev, EV_READ|EV_WRITE);
ctx->dst.bev = bufferevent_openssl_filter_new(
ctx->evbase, ctx->dst.bev, ctx->dst.ssl,
BUFFEREVENT_SSL_CONNECTING,
@@ -2005,6 +2007,8 @@
if (OPTS_DEBUG(ctx->opts)) {
log_dbg_printf("Completing autossl upgrade\n");
}
+ bufferevent_setcb(ctx->src.bev, NULL, NULL, NULL, NULL);
+ bufferevent_disable(ctx->src.bev, EV_READ|EV_WRITE);
ctx->src.bev = bufferevent_openssl_filter_new(
ctx->evbase, ctx->src.bev, ctx->src.ssl,
BUFFEREVENT_SSL_ACCEPTING,It may look unnecessary, but this is what we do while terminating connections and freeing bevs, which we have realized necessary some time ago, so perhaps it is necessary while upgrading too. Just in case.
minzkn
commented
2 years ago I applied the patch you mentioned to sslsplit, but it's the same. (Additionally, I also enabled DEBUG_PROXY in sslsplt.)
Connecting to [xxx.yyy.zzz.aaa]:443
0xf04e90 0xf050e0 eventcb dst connected
0x7f5eb4000a50 pxy_bufferevent_setup
tcp 192.168.0.111 34825 xxx.yyy.zzz.aaa 443
TCP connected to [xxx.yyy.zzz.aaa]:443
TCP connected from [192.168.0.111]:34825
0xf04e90 0x7f5eb4000a50 src writecb
0xf04e90 0x7f5eb4000a50 src readcb
Checking for a client hello
Peek found ClientHello
Replaced dst bufferevent, new one is 0x7f5eb4003670
0xf04e90 0x7f5eb4003670 eventcb dst connected
===> Original server certificate:
Subject DN: /CN=<my domain>
Common Names: <my CN>
Fingerprint: <my Fingerprint>
Certificate cache: MISS
===> Forged server certificate:
Subject DN: /CN=<my domain>
Common Names: <my CN>
Fingerprint: <my Fingerprint>
Completing autossl upgrade
Certificate cache: KEEP (SNI match or target mode)
SSL connected to [xxx.yyy.zzz.aaa]:443 TLSv1.3 TLS_AES_256_GCM_SHA384
CLIENT_RANDOM 5BFDBC4D83DE32FCAADB23DC4821440322FBFC4F20E5F6DA836E2116C9C67712 161A06BE5E7F00001A000000000000000D0000000000000010E0EE0000000000504200B45E7F0000801B12BD5E7F0000
0xf04e90 0x7f5eb4009eb0 eventcb src connected
src buffer event connected: ignoring event
upgrade 192.168.0.111 34825 xxx.yyy.zzz.aaa 443 sni:<my domain> names:<my CN> sproto:TLSv1.2:ECDHE-RSA-AES256-GCM-SHA384 dproto:TLSv1.3:TLS_AES_256_GCM_SHA384 origcrt:2C959DC7A662CF1851A3B6E9AE4EE7C0C132BA71 usedcrt:E32AE26ACFE1F85A709D9C0A7563774AF3ECB7B2
SSL connected from [192.168.0.111]:34825 TLSv1.2 ECDHE-RSA-AES256-GCM-SHA384
CLIENT_RANDOM 6240FFCF2AD01588931F9BE844A2FDB727B22418A09B6B331259D4463F391BEC 9A4C26119BA5F70C4D714505ECE07780910389D3F68E30D51B9923F6B45346D9AF206CBD760B50ECEC17550487EB2B1A
0xf04e90 0x7f5eb4009eb0 src readcb
buffer watermark control ! (inbuf=0, outbuf=0, OUTBUF_LIMIT=131072)
0xf04e90 0x7f5eb4003670 dst writecb
0xf04e90 0x7f5eb4003670 dst readcb
buffer watermark control ! (inbuf=0, outbuf=0, OUTBUF_LIMIT=131072)
0xf04e90 0x7f5eb4009eb0 src writecb
0xf04e90 0x7f5eb4003670 dst readcb
buffer watermark control ! (inbuf=0, outbuf=0, OUTBUF_LIMIT=131072)
0xf04e90 0x7f5eb4009eb0 src writecb
0xf04e90 0x7f5eb4003670 dst readcb
buffer watermark control ! (inbuf=0, outbuf=0, OUTBUF_LIMIT=131072)
0xf04e90 0x7f5eb4009eb0 src writecb
0xf04e90 0x7f5eb4003670 dst readcb
buffer watermark control ! (inbuf=0, outbuf=0, OUTBUF_LIMIT=131072)
0xf04e90 0x7f5eb4009eb0 src writecb
0xf04e90 0x7f5eb4003670 dst readcb
buffer watermark control ! (inbuf=0, outbuf=0, OUTBUF_LIMIT=131072)
0xf04e90 0x7f5eb4009eb0 src writecb
0xf04e90 0x7f5eb4003670 dst readcb
buffer watermark control ! (inbuf=0, outbuf=0, OUTBUF_LIMIT=131072)
0xf04e90 0x7f5eb4009eb0 src writecb
0xf04e90 0x7f5eb4003670 dst readcb
...sslproxy may take some time to test.
minzkn
commented
2 years ago It seems to work well because I set bufferevent_setwatermark in the bev as follows right before the call to bufferevent_openssl_filter_new.
It is probably related to bev_ssl->outbuf_cb of bufferevent_openssl_new_impl function called inside bufferevent_openssl_filter_new .
This is the same behavior that copies when evbuffer_add_buffer is called and is called when evbuffer_invokecallbacks() (consider_writing) is called.
That is, it works if high watermark is properly set before calling bufferevent_openssl_filter_new.
diff -urN sslsplit-0.5.5/pxyconn.c sslsplit-0.5.5-trial-fix/pxyconn.c
--- sslsplit-0.5.5/pxyconn.c 2019-08-30 20:09:00.000000000 +0900
+++ sslsplit-0.5.5-trial-fix/pxyconn.c 2022-03-28 16:42:10.137395144 +0900
@@ -1684,6 +1684,8 @@
"upgrade\n");
return 0;
}
+ bufferevent_setwatermark(ctx->dst.bev, EV_WRITE,
+ OUTBUF_LIMIT/2, OUTBUF_LIMIT);
ctx->dst.bev = bufferevent_openssl_filter_new(
ctx->evbase, ctx->dst.bev, ctx->dst.ssl,
BUFFEREVENT_SSL_CONNECTING,
@@ -1998,6 +2000,8 @@
if (OPTS_DEBUG(ctx->opts)) {
log_dbg_printf("Completing autossl upgrade\n");
}
+ bufferevent_setwatermark(ctx->src.bev, EV_WRITE,
+ OUTBUF_LIMIT/2, OUTBUF_LIMIT);
ctx->src.bev = bufferevent_openssl_filter_new(
ctx->evbase, ctx->src.bev, ctx->src.ssl,
BUFFEREVENT_SSL_ACCEPTING, <N bev> = bufferevent_openssl_filter_new(
<struct event_base *>, <T bev>, <SSL *>,
BUFFEREVENT_SSL_CONNECTING or BUFFEREVENT_SSL_ACCEPTING,
BEV_OPT_DEFER_CALLBACKS);
N != T
need high watermark set to THm, that's interesting. I've also looked into the source code of libevent 2.1.12, and seen that the only time the bufferevent_setwatermark() function is called in the entire libevent code is in bufferevent_openssl_new_impl(), as I guess you have also seen. And I see that it reenables the read (and write) callback which we have disabled in our code for the underlying bev (this is relevant to autossl, since its underlying bev is tcp, and it switches to another ssl bev), but it resets the watermark for the read cb not for the write cb. If that's really the case, then it may explain the strange issue you have seen. Do I understand this correctly?
But, what I don't understand in your trial-fix is that if the theory above is right, your fix was not supposed to work, because you call bufferevent_setwatermark() for the write cb before the call to bufferevent_openssl_filter_new(), which resets the watermark for the read cb and reenables it as I said above. Because in your fix, you set the watermark for the write cb for the underlying bev. So, I currently don't understand why your fix works. In fact, I would expect a fix which would (again) disable the read cb after the call to bufferevent_openssl_filter_new(), of course after checking buffer sizes and watermark limits. Because it seems to me like the actual fix should be about disabling the read cb again, not setting the write watermarks again. Or perhaps they both lead to the same result in our implementation, I don't know yet. Am I missing something?
I may be really missing something, because I am still looking into the source code of libevent, and check with ours. I have also noted that in libevent code both bufferevent_openssl_filter_new() and bufferevent_openssl_socket_new() call bufferevent_openssl_new_impl(). So, I should continue looking into it. But I think you have found a clue.
Btw, if your trial-fix really leads to a solution or a workaround, please do not bother trying sslproxy, unless you want to try it out of interest.
sonertari
commented
2 years ago Also, we enable read callbacks for src and dst bevs after we find ClientHello and while we complete upgrade, not for the underlying bevs, but for the new bevs. I don't know how this affects this issue.
minzkn
commented
2 years ago Here's my understanding of libevent: Of course, since this is the first time I've seen the libevent source, it's not perfect.
Difference between ssl and autossl In the flow, autossl starts with ctx->src|dst.bev as TCP bev and is replaced by bufferevent_openssl_filter_new with SSL bev with this as 'underlying bev'. In other words, I saw the difference in that autossl has an 'underlying bev' unlike ssl.
At this time, in the process of copying from inbuf to outbuf through evbuffer_add_buffer, 'evbuffer_invokecallbacks(outbuf);' It calls be_openssl_outbuf_cb according to the syntax.
If you look at the be_openssl_outbuf_cb function, you will find the following part.
if (bev_ssl->underlying)
consider_writing(bev_ssl);Now looking at the consider_writing function, the following 'target' seems to mean the output of the underlying bev . And there is a comparison condition with high write watermark and write_suspended . This seems to be the part that controls the buffer balance between the ssl bev and the underlying bev.
static void
consider_writing(struct bufferevent_openssl *bev_ssl)
{
...
if (bev_ssl->underlying) {
target = bev_ssl->underlying->output;
wm = &bev_ssl->underlying->wm_write;
}
while ((bev_ssl->bev.bev.enabled & EV_WRITE) &&
(! bev_ssl->bev.write_suspended) &&
evbuffer_get_length(output) &&
(!target || (! wm->high || evbuffer_get_length(target) < wm->high))) {
...
}After all, I think that BIO_new_bufferevent(underlying) / BIO_s_bufferevent() called by bufferevent_openssl_filter_new controls the underlying output through bio_bufferevent_write. (If the high write watermark is not set in the underlying bev, the memory is accumulated as all are added unconditionally by calling evbuffer_add in bio_bufferevent_write )
static int
bio_bufferevent_write(BIO *b, const char *in, int inlen)
{
struct bufferevent *bufev = BIO_get_data(b);
struct evbuffer *output;
size_t outlen;
BIO_clear_retry_flags(b);
if (!BIO_get_data(b))
return -1;
output = bufferevent_get_output(bufev);
outlen = evbuffer_get_length(output);
/* Copy only as much data onto the output buffer as can fit under the
* high-water mark. */
if (bufev->wm_write.high && bufev->wm_write.high <= (outlen+inlen)) {
if (bufev->wm_write.high <= outlen) {
/* If no data can fit, we'll need to retry later. */
BIO_set_retry_write(b);
return -1;
}
inlen = bufev->wm_write.high - outlen;
}
EVUTIL_ASSERT(inlen > 0);
evbuffer_add(output, in, inlen);
return inlen;
}The point in autossl is that you need to set the high write watermark of the underlying bev to control the output of the underlying bev, and the low write watermark doesn't seem to have any special meaning.
The deeper content seems to be getting lost in my understanding of this.
sonertari
commented
2 years ago The purpose of setting a watermark is to call the write callback when the water level drops to some acceptable level, i.e. outbuf has some space now (otherwise, the write events are suspended until the level drops), so that in the write callback we can reenable the read events, i.e. restart accepting data into inbuf.
So, IMO, while we are switching from tcp to ssl bevs in autossl, we should check if any write watermarks are set and also if the read events are disabled for the underlying bevs, and if so, we should set the watermarks and disable the read events for the new bevs accordingly. We should do these checks and updates in the upgrade code.
Therefore, the following patch is my proposal to fix this issue:
--- pxyconn.c.orig 2022-03-25 22:45:11.607758000 +0300
+++ pxyconn.c 2022-03-29 21:35:05.176463169 +0300
@@ -1653,6 +1653,18 @@
}
}
+static int
+pxy_conn_getwatermark_state(struct bufferevent *bev)
+{
+ size_t lowmark = 0;
+ size_t highmark = 0;
+
+ bufferevent_getwatermark(bev, EV_WRITE, &lowmark, &highmark);
+ if (lowmark || highmark)
+ return 1;
+ return 0;
+}
+
/*
* Peek into pending data to see if it is an SSL/TLS ClientHello, and if so,
* upgrade the connection from plain TCP to SSL/TLS.
@@ -1691,6 +1703,10 @@
"upgrade\n");
return 0;
}
+
+ int underlying_read_enabled = bufferevent_get_enabled(ctx->dst.bev) & EV_READ;
+ int underlying_wm_set = pxy_conn_getwatermark_state(ctx->dst.bev);
+
ctx->dst.bev = bufferevent_openssl_filter_new(
ctx->evbase, ctx->dst.bev, ctx->dst.ssl,
BUFFEREVENT_SSL_CONNECTING,
@@ -1703,7 +1719,11 @@
bufferevent_setcb(ctx->dst.bev, pxy_bev_readcb,
pxy_bev_writecb, pxy_bev_eventcb,
ctx);
- bufferevent_enable(ctx->dst.bev, EV_READ|EV_WRITE);
+ bufferevent_enable(ctx->dst.bev, (underlying_read_enabled ? EV_READ:0)|EV_WRITE);
+ if (underlying_wm_set) {
+ bufferevent_setwatermark(ctx->dst.bev, EV_WRITE, OUTBUF_LIMIT/2, OUTBUF_LIMIT);
+ }
+
if (OPTS_DEBUG(ctx->opts)) {
log_err_printf("Replaced dst bufferevent, new "
"one is %p\n",
@@ -2005,6 +2025,10 @@
if (OPTS_DEBUG(ctx->opts)) {
log_dbg_printf("Completing autossl upgrade\n");
}
+
+ int underlying_read_enabled = bufferevent_get_enabled(ctx->src.bev) & EV_READ;
+ int underlying_wm_set = pxy_conn_getwatermark_state(ctx->src.bev);
+
ctx->src.bev = bufferevent_openssl_filter_new(
ctx->evbase, ctx->src.bev, ctx->src.ssl,
BUFFEREVENT_SSL_ACCEPTING,
@@ -2017,8 +2041,10 @@
pxy_bev_writecb,
pxy_bev_eventcb,
ctx);
- bufferevent_enable(ctx->src.bev,
- EV_READ|EV_WRITE);
+ bufferevent_enable(ctx->src.bev, (underlying_read_enabled ? EV_READ:0)|EV_WRITE);
+ if (underlying_wm_set) {
+ bufferevent_setwatermark(ctx->src.bev, EV_WRITE, OUTBUF_LIMIT/2, OUTBUF_LIMIT);
+ }
}
} else {
ctx->src.bev = pxy_bufferevent_setup(ctx, ctx->fd,
@minzkn, can you apply this patch (and this patch only) and try please? So that we can convert this into a pull request if it works.
minzkn
commented
2 years ago @sonertari The patch you suggested still shows the same memory increase. That is, the patch doesn't hit.
The bev passed to the bufferevent_openssl_filter_new argument is read and write enabled as the underlying bev, sets the watermark for READ to low 0, high 0, and creates a new ssl bev and returns it.
Therefore, it is thought that reading and writing should be enabled for the ssl bev returned after the call to bufferevent_openssl_filter_new as the existing implementation, and the WRITE watermark should be set in order not to exceed the buffer limit in the underlying bev passed before calling bufferevent_openssl_filter_new.
The WRITE watermark set on the underlying bev before calling bufferevent_openssl_filter_new will be a control condition inside libevent, and it seems that sslsplit has nothing to control the underlying bev directly after bufferevent_openssl_filter_new.
So, in the trial fix patch I suggested, I think it is right to set the WRITE watermark right before bufferevent_openssl_filter_new.
diff -urN sslsplit-0.5.5/pxyconn.c sslsplit-0.5.5-trial-fix/pxyconn.c
--- sslsplit-0.5.5/pxyconn.c 2019-08-30 20:09:00.000000000 +0900
+++ sslsplit-0.5.5-trial-fix/pxyconn.c 2022-03-28 16:42:10.137395144 +0900
@@ -1684,6 +1684,8 @@
"upgrade\n");
return 0;
}
+ bufferevent_setwatermark(ctx->dst.bev, EV_WRITE,
+ OUTBUF_LIMIT/2, OUTBUF_LIMIT);
ctx->dst.bev = bufferevent_openssl_filter_new(
ctx->evbase, ctx->dst.bev, ctx->dst.ssl,
BUFFEREVENT_SSL_CONNECTING,
@@ -1998,6 +2000,8 @@
if (OPTS_DEBUG(ctx->opts)) {
log_dbg_printf("Completing autossl upgrade\n");
}
+ bufferevent_setwatermark(ctx->src.bev, EV_WRITE,
+ OUTBUF_LIMIT/2, OUTBUF_LIMIT);
ctx->src.bev = bufferevent_openssl_filter_new(
ctx->evbase, ctx->src.bev, ctx->src.ssl,
BUFFEREVENT_SSL_ACCEPTING,Pseudo code :
/* <SSL bev> != <underlying bev>
need high watermark set to <underlying bev> (not <SSL bev>)
*/
+ bufferevent_setwatermark(<underlying bev>, EV_WRITE, OUTBUF_LIMIT/2 /* or zero */, OUTBUF_LIMIT);
<SSL bev> = bufferevent_openssl_filter_new(
<struct event_base *>, <underlying bev>, <SSL *>,
BUFFEREVENT_SSL_CONNECTING or BUFFEREVENT_SSL_ACCEPTING,
BEV_OPT_DEFER_CALLBACKS);
// The underlying bev now has read and write enabled, the READ watermark is 0, 0 and the WRITE watermark has OUTBUF_LIMIT. callback is libevent internal BIO implementation.
// From this point on, I think it's okay to forget the underlying bev
...
bufferevent_setcb(<SSL bev>, <readcb>, <writecb>, <eventcb>, <ctx>);
bufferevent_enable(<SSL bev>, EV_READ | EV_WRITE);I am not surprised about the memory increase you report now, that's why in my earlier post I said we should disable the read events for the underlying bev if we have disabled them, because the bufferevent_openssl_new_impl() function in the libevent code enables them regardless. Back then I wasn't sure how libevent was working if a bev was wrapping an underlying bev, rather than directly connecting to a socket. But I think it is clear now that the main cause for the issue you have reported is the read events for the underlying bev. For example, disabling or watermarking the wrapper bev did not stop filling up the buffer for the underlying bev, as we have observed.
So, contrary to your comments, based on your reports (because I cannot create your test environment), now my theory is that our watermark code should always deal with underlying bevs, never wrapper bevs. To put it perhaps more correctly, we should not disable or watermark wrapper bevs, instead we should always deal with bevs directly connected to sockets. (And the only proxyspec type with underlying bevs is autossl.)
Also, I hope you understand that we cannot use your trial-fix as it is, because it sets watermarks for underlying bevs unconditionally. We should set the watermarks only if the underlying bevs have them set already. Plus, if we deal with wrapper bevs only, as you suggest, who is going to reset the watermarks for the underlying bevs? Note that our read and write callbacks currently deal with wrapper bevs, not underlying bevs.
Therefore, the following patch is my updated proposal to fix this issue:
--- pxyconn.c.orig 2022-03-25 22:45:11.607758000 +0300
+++ pxyconn.c 2022-03-30 16:37:43.785407139 +0300
@@ -1653,6 +1653,18 @@
}
}
+static int
+pxy_conn_getwatermark_state(struct bufferevent *bev)
+{
+ size_t lowmark = 0;
+ size_t highmark = 0;
+
+ bufferevent_getwatermark(bev, EV_WRITE, &lowmark, &highmark);
+ if (lowmark || highmark)
+ return 1;
+ return 0;
+}
+
/*
* Peek into pending data to see if it is an SSL/TLS ClientHello, and if so,
* upgrade the connection from plain TCP to SSL/TLS.
@@ -1691,6 +1703,11 @@
"upgrade\n");
return 0;
}
+
+ int underlying_read_disabled = !(bufferevent_get_enabled(ctx->dst.bev) & EV_READ);
+ int underlying_wm_set = pxy_conn_getwatermark_state(ctx->dst.bev);
+ struct bufferevent *ubev = ctx->dst.bev;
+
ctx->dst.bev = bufferevent_openssl_filter_new(
ctx->evbase, ctx->dst.bev, ctx->dst.ssl,
BUFFEREVENT_SSL_CONNECTING,
@@ -1704,6 +1721,14 @@
pxy_bev_writecb, pxy_bev_eventcb,
ctx);
bufferevent_enable(ctx->dst.bev, EV_READ|EV_WRITE);
+
+ if (underlying_read_disabled) {
+ bufferevent_disable(ubev, EV_READ);
+ }
+ if (underlying_wm_set) {
+ bufferevent_setwatermark(ubev, EV_WRITE, OUTBUF_LIMIT/2, OUTBUF_LIMIT);
+ }
+
if (OPTS_DEBUG(ctx->opts)) {
log_err_printf("Replaced dst bufferevent, new "
"one is %p\n",
@@ -1899,9 +1924,11 @@
if (evbuffer_get_length(outbuf) >= OUTBUF_LIMIT) {
/* temporarily disable data source;
* set an appropriate watermark. */
- bufferevent_setwatermark(other->bev, EV_WRITE,
+ struct bufferevent *ubev = bufferevent_get_underlying(other->bev);
+ bufferevent_setwatermark(ubev ? ubev : other->bev, EV_WRITE,
OUTBUF_LIMIT/2, OUTBUF_LIMIT);
- bufferevent_disable(bev, EV_READ);
+ ubev = bufferevent_get_underlying(bev);
+ bufferevent_disable(ubev ? ubev : bev, EV_READ);
}
}
@@ -1934,11 +1961,15 @@
return;
}
- if (other->bev && !(bufferevent_get_enabled(other->bev) & EV_READ)) {
- /* data source temporarily disabled;
- * re-enable and reset watermark to 0. */
- bufferevent_setwatermark(bev, EV_WRITE, 0, 0);
- bufferevent_enable(other->bev, EV_READ);
+ if (other->bev) {
+ struct bufferevent *ubev = bufferevent_get_underlying(other->bev);
+ if (!(bufferevent_get_enabled(ubev ? ubev : other->bev) & EV_READ)) {
+ /* data source temporarily disabled;
+ * re-enable and reset watermark to 0. */
+ bufferevent_enable(ubev ? ubev : other->bev, EV_READ);
+ ubev = bufferevent_get_underlying(bev);
+ bufferevent_setwatermark(ubev ? ubev : bev, EV_WRITE, 0, 0);
+ }
}
}
@@ -2005,6 +2036,11 @@
if (OPTS_DEBUG(ctx->opts)) {
log_dbg_printf("Completing autossl upgrade\n");
}
+
+ int underlying_read_disabled = !(bufferevent_get_enabled(ctx->src.bev) & EV_READ);
+ int underlying_wm_set = pxy_conn_getwatermark_state(ctx->src.bev);
+ struct bufferevent *ubev = ctx->src.bev;
+
ctx->src.bev = bufferevent_openssl_filter_new(
ctx->evbase, ctx->src.bev, ctx->src.ssl,
BUFFEREVENT_SSL_ACCEPTING,
@@ -2017,8 +2053,14 @@
pxy_bev_writecb,
pxy_bev_eventcb,
ctx);
- bufferevent_enable(ctx->src.bev,
- EV_READ|EV_WRITE);
+ bufferevent_enable(ctx->src.bev, EV_READ|EV_WRITE);
+
+ if (underlying_read_disabled) {
+ bufferevent_disable(ubev, EV_READ);
+ }
+ if (underlying_wm_set) {
+ bufferevent_setwatermark(ubev, EV_WRITE, OUTBUF_LIMIT/2, OUTBUF_LIMIT);
+ }
}
} else {
ctx->src.bev = pxy_bufferevent_setup(ctx, ctx->fd,This patch is supposed to work, because it conditionally includes your trial-fix too. But since I have modified our watermarking code to deal with underlying bevs only, it should be tested properly, with or without autossl.
@minzkn, can you apply this patch (and this patch only) and try please?
minzkn
commented
2 years ago @sonertari: The same thing happens with the watermark control patch for the underlying bev .
It seems that the underlying_wm_set condition in the following part should be reversed, so I tried that, but it didn't work.
- if (underlying_wm_set) {
+ if (!underlying_wm_set) {
bufferevent_setwatermark(ubev, EV_WRITE, OUTBUF_LIMIT/2, OUTBUF_LIMIT);
}Also, in the condition of whether outbuf exceeds OUTBUF_LIMIT, I tried adding an additional condition as follows, but it was not resolved.
- if (evbuffer_get_length(outbuf) >= OUTBUF_LIMIT)
+ struct bufferevent *ubev = bufferevent_get_underlying(other->bev);
+ if ((evbuffer_get_length(outbuf) >= OUTBUF_LIMIT) || (ubev && (evbuffer_get_length(bufferevent_get_output(ubev)) >= OUTBUF_LIMIT))) {I still think it's right to keep the watermark control on the SSL bev in the existing implementation and only control the maximum load on the outbuf of the underlying bev...
The reason is that when trying to set the watermark for the underlying bev set in pxy_bev_readcb, the watermark is immediately initialized by the SSL bev callback, pxy_bev_writecb call, so it seems that something needs to be considered. ( The outbuf of ssl bev is transferred to the underlying bev when evbuffer_add_buffer is called. So the ssl bev's outbuf will immediately drop below the low watermark. So, to control the watermark for the underlying bev, you will need writecb for the underlying bev, not the pxy_bev_writecb , and that is in the libevent internal BIO bufferevent implementation. )
sonertari
commented
2 years ago UPDATE: Please note that I have modified the patch after the first post.
Your report that my last patch does not work is strange, because it includes your trial-fix, which you say works. But it also reveals something else, as I was concerned since the beginning: We don't know the exact moment when the need for watermarking starts (that's why I had proposed the very verbose debug logs of sslproxy earlier). Apparently, and perhaps as expected, it does not coincide with the moment we upgrade from tcp to ssl. Because, the conditional inclusion of your trial-fix does not work at upgrade time. Obviously, it is not needed during upgrade, because the buffer load is not high at that moment, and that is why I say perhaps as expected.
Since we should not unconditionally set the watermarks for underlying bevs, as in your trial-fix, now I think that our watermarking code should deal with both the underlying and wrapper bevs. This seems to be the only way to disable and enable read events, and also set and reset watermarks at the right times that we need them (in other words, this seems to be the only way to include your trial-fix conditionally).
Therefore, the following patch is my proposal to fix this issue. I don't care if some parts of it may be redundant or unnecessary or could be improved at the moment, what I care is that it works hopefully. This may be my last trial, because if this does not work again, first I will feel confused, and second it will mean that I need to create your test environment myself.
--- pxyconn.c.orig 2022-03-25 22:45:11.607758000 +0300
+++ pxyconn.c 2022-03-31 17:39:57.220500039 +0300
@@ -1653,6 +1653,18 @@
}
}
+static int
+pxy_conn_getwatermark(struct bufferevent *bev)
+{
+ size_t lowmark = 0;
+ size_t highmark = 0;
+
+ bufferevent_getwatermark(bev, EV_WRITE, &lowmark, &highmark);
+ if (lowmark || highmark)
+ return 1;
+ return 0;
+}
+
/*
* Peek into pending data to see if it is an SSL/TLS ClientHello, and if so,
* upgrade the connection from plain TCP to SSL/TLS.
@@ -1691,6 +1703,11 @@
"upgrade\n");
return 0;
}
+
+ struct bufferevent *ubev = ctx->dst.bev;
+ int ubev_read_disabled = !(bufferevent_get_enabled(ctx->dst.bev) & EV_READ);
+ int ubev_watermark_set = pxy_conn_getwatermark(ctx->dst.bev);
+
ctx->dst.bev = bufferevent_openssl_filter_new(
ctx->evbase, ctx->dst.bev, ctx->dst.ssl,
BUFFEREVENT_SSL_CONNECTING,
@@ -1704,6 +1721,16 @@
pxy_bev_writecb, pxy_bev_eventcb,
ctx);
bufferevent_enable(ctx->dst.bev, EV_READ|EV_WRITE);
+
+ if (ubev_read_disabled) {
+ bufferevent_disable(ubev, EV_READ);
+ bufferevent_disable(ctx->dst.bev, EV_READ);
+ }
+ if (ubev_watermark_set) {
+ bufferevent_setwatermark(ubev, EV_WRITE, OUTBUF_LIMIT/2, OUTBUF_LIMIT);
+ bufferevent_setwatermark(ctx->dst.bev, EV_WRITE, OUTBUF_LIMIT/2, OUTBUF_LIMIT);
+ }
+
if (OPTS_DEBUG(ctx->opts)) {
log_err_printf("Replaced dst bufferevent, new "
"one is %p\n",
@@ -1896,12 +1923,20 @@
}
}
evbuffer_add_buffer(outbuf, inbuf);
- if (evbuffer_get_length(outbuf) >= OUTBUF_LIMIT) {
+
+ struct bufferevent *ubev_other = bufferevent_get_underlying(other->bev);
+ if (evbuffer_get_length(outbuf) >= OUTBUF_LIMIT ||
+ (ubev_other && evbuffer_get_length(bufferevent_get_output(ubev_other)) >= OUTBUF_LIMIT)) {
/* temporarily disable data source;
* set an appropriate watermark. */
- bufferevent_setwatermark(other->bev, EV_WRITE,
- OUTBUF_LIMIT/2, OUTBUF_LIMIT);
bufferevent_disable(bev, EV_READ);
+ bufferevent_setwatermark(other->bev, EV_WRITE, OUTBUF_LIMIT/2, OUTBUF_LIMIT);
+
+ struct bufferevent *ubev = bufferevent_get_underlying(bev);
+ if (ubev)
+ bufferevent_disable(ubev, EV_READ);
+ if (ubev_other)
+ bufferevent_setwatermark(ubev_other, EV_WRITE, OUTBUF_LIMIT/2, OUTBUF_LIMIT);
}
}
@@ -1937,8 +1972,15 @@
if (other->bev && !(bufferevent_get_enabled(other->bev) & EV_READ)) {
/* data source temporarily disabled;
* re-enable and reset watermark to 0. */
- bufferevent_setwatermark(bev, EV_WRITE, 0, 0);
bufferevent_enable(other->bev, EV_READ);
+ bufferevent_setwatermark(bev, EV_WRITE, 0, 0);
+
+ struct bufferevent *ubev = bufferevent_get_underlying(other->bev);
+ if (ubev)
+ bufferevent_enable(ubev, EV_READ);
+ ubev = bufferevent_get_underlying(bev);
+ if (ubev)
+ bufferevent_setwatermark(ubev, EV_WRITE, 0, 0);
}
}
@@ -2005,6 +2047,11 @@
if (OPTS_DEBUG(ctx->opts)) {
log_dbg_printf("Completing autossl upgrade\n");
}
+
+ struct bufferevent *ubev = ctx->src.bev;
+ int ubev_read_disabled = !(bufferevent_get_enabled(ctx->src.bev) & EV_READ);
+ int ubev_watermark_set = pxy_conn_getwatermark(ctx->src.bev);
+
ctx->src.bev = bufferevent_openssl_filter_new(
ctx->evbase, ctx->src.bev, ctx->src.ssl,
BUFFEREVENT_SSL_ACCEPTING,
@@ -2017,8 +2064,16 @@
pxy_bev_writecb,
pxy_bev_eventcb,
ctx);
- bufferevent_enable(ctx->src.bev,
- EV_READ|EV_WRITE);
+ bufferevent_enable(ctx->src.bev, EV_READ|EV_WRITE);
+
+ if (ubev_read_disabled) {
+ bufferevent_disable(ubev, EV_READ);
+ bufferevent_disable(ctx->src.bev, EV_READ);
+ }
+ if (ubev_watermark_set) {
+ bufferevent_setwatermark(ubev, EV_WRITE, OUTBUF_LIMIT/2, OUTBUF_LIMIT);
+ bufferevent_setwatermark(ctx->src.bev, EV_WRITE, OUTBUF_LIMIT/2, OUTBUF_LIMIT);
+ }
}
} else {
ctx->src.bev = pxy_bufferevent_setup(ctx, ctx->fd,@minzkn, can you apply this patch (and this patch only) and try please, hopefully one last time?
minzkn
commented
2 years ago @sonertari: This patch also increases memory.
So, when I check further debugging as follows, ubev_other outbuf continues to increase.
evbuffer_add_buffer(outbuf, inbuf);
struct bufferevent *ubev_other = bufferevent_get_underlying(other->bev);
if (evbuffer_get_length(outbuf) >= OUTBUF_LIMIT ||
(ubev_other && evbuffer_get_length(bufferevent_get_output(ubev_other)) >= OUTBUF_LIMIT)) {
+ if (OPTS_DEBUG(ctx->opts)) {
+ log_err_printf("buffer watermark control ! (inbuf=%lu, outbuf=%lu[ubev_other=%lu], OUTBUF_LIMIT=%lu)\n", (unsigned long)evbuffer_get_length(inbuf), (unsigned long)evbuffer_get_length(outbuf), ubev_other ? (unsigned long)evbuffer_get_length(bufferevent_get_output(ubev_other)) : 0lu, (unsigned long)OUTBUF_LIMIT);
+ }
/* temporarily disable data source;
* set an appropriate watermark. */
bufferevent_disable(bev, EV_READ);
bufferevent_setwatermark(other->bev, EV_WRITE, OUTBUF_LIMIT/2, OUTBUF_LIMIT);
struct bufferevent *ubev = bufferevent_get_underlying(bev);
if (ubev)
bufferevent_disable(ubev, EV_READ);
if (ubev_other)
bufferevent_setwatermark(ubev_other, EV_WRITE, OUTBUF_LIMIT/2, OUTBUF_LIMIT);
}debug output: (ubev_other outbuf continues to increase)
buffer watermark control ! (inbuf=0, outbuf=0[ubev_other=131536], OUTBUF_LIMIT=131072)
buffer watermark control ! (inbuf=0, outbuf=0[ubev_other=147978], OUTBUF_LIMIT=131072)
buffer watermark control ! (inbuf=0, outbuf=0[ubev_other=164420], OUTBUF_LIMIT=131072)
buffer watermark control ! (inbuf=0, outbuf=0[ubev_other=180862], OUTBUF_LIMIT=131072)
buffer watermark control ! (inbuf=0, outbuf=0[ubev_other=197304], OUTBUF_LIMIT=131072)
buffer watermark control ! (inbuf=0, outbuf=0[ubev_other=213746], OUTBUF_LIMIT=131072)
buffer watermark control ! (inbuf=0, outbuf=0[ubev_other=230188], OUTBUF_LIMIT=131072)
buffer watermark control ! (inbuf=0, outbuf=0[ubev_other=246630], OUTBUF_LIMIT=131072)
buffer watermark control ! (inbuf=0, outbuf=0[ubev_other=263072], OUTBUF_LIMIT=131072)
buffer watermark control ! (inbuf=0, outbuf=0[ubev_other=279514], OUTBUF_LIMIT=131072)
buffer watermark control ! (inbuf=0, outbuf=0[ubev_other=295956], OUTBUF_LIMIT=131072)
buffer watermark control ! (inbuf=0, outbuf=0[ubev_other=312398], OUTBUF_LIMIT=131072)
buffer watermark control ! (inbuf=0, outbuf=0[ubev_other=328840], OUTBUF_LIMIT=131072)
buffer watermark control ! (inbuf=0, outbuf=0[ubev_other=345282], OUTBUF_LIMIT=131072)
buffer watermark control ! (inbuf=0, outbuf=0[ubev_other=361724], OUTBUF_LIMIT=131072)
buffer watermark control ! (inbuf=0, outbuf=0[ubev_other=378166], OUTBUF_LIMIT=131072)
buffer watermark control ! (inbuf=0, outbuf=0[ubev_other=394608], OUTBUF_LIMIT=131072)
buffer watermark control ! (inbuf=0, outbuf=0[ubev_other=411050], OUTBUF_LIMIT=131072)
buffer watermark control ! (inbuf=0, outbuf=0[ubev_other=427492], OUTBUF_LIMIT=131072)
buffer watermark control ! (inbuf=0, outbuf=0[ubev_other=443934], OUTBUF_LIMIT=131072)
buffer watermark control ! (inbuf=0, outbuf=0[ubev_other=460376], OUTBUF_LIMIT=131072)
buffer watermark control ! (inbuf=0, outbuf=0[ubev_other=476818], OUTBUF_LIMIT=131072)
...
buffer watermark control ! (inbuf=0, outbuf=0[ubev_other=253169134], OUTBUF_LIMIT=131072)
buffer watermark control ! (inbuf=0, outbuf=0[ubev_other=253185576], OUTBUF_LIMIT=131072)
buffer watermark control ! (inbuf=0, outbuf=0[ubev_other=253202018], OUTBUF_LIMIT=131072)
buffer watermark control ! (inbuf=0, outbuf=0[ubev_other=253218460], OUTBUF_LIMIT=131072)
...In addition, it seems that the following conditions are necessary for the ubev of the bev of pxy_bev_writecb to drop to a low watermark in the patch contents. This is only to not increase the memory and there is a problem with the operation. I just feel like I need some kind of control like this. I think it may be necessary to additionally register writecb in ubev. I wonder if I need to register an additional ubev writecb that complements each other.
static void
pxy_bev_writecb(struct bufferevent *bev, void *arg)
{
...
if (other->bev && !(bufferevent_get_enabled(other->bev) & EV_READ)) {
+ struct bufferevent *ubev = bufferevent_get_underlying(bev);
+ if (!ubev || (evbuffer_get_length(bufferevent_get_output(ubev)) < (OUTBUF_LIMIT/2))) {
/* data source temporarily disabled;
* re-enable and reset watermark to 0. */
bufferevent_enable(other->bev, EV_READ);
bufferevent_setwatermark(bev, EV_WRITE, 0, 0);
M struct bufferevent *ubev_other = bufferevent_get_underlying(other->bev);
M if (ubev_other)
M bufferevent_enable(ubev_other, EV_READ);
if (ubev)
bufferevent_setwatermark(ubev, EV_WRITE, 0, 0);
+ }
}
}
If I remove the following parts from the patch, it works without increasing memory.
static void
pxy_bev_writecb(struct bufferevent *bev, void *arg)
{
...
if (other->bev && !(bufferevent_get_enabled(other->bev) & EV_READ)) {
/* data source temporarily disabled;
* re-enable and reset watermark to 0. */
bufferevent_enable(other->bev, EV_READ);
bufferevent_setwatermark(bev, EV_WRITE, 0, 0);
struct bufferevent *ubev = bufferevent_get_underlying(other->bev);
if (ubev)
bufferevent_enable(ubev, EV_READ);
- struct bufferevent *ubev = bufferevent_get_underlying(bev);
- if (ubev)
- bufferevent_setwatermark(ubev, EV_WRITE, 0, 0);
}
}To save @sonertari's precious time, I simply rebuilt the test environment out of the secure net. And we provide this test environment. Please refer to the connection method and test method below.
(When the test is complete, the VM environment will be destroyed.)
!!! @sonertari After you log in, it seems that you can use it by changing the password of your account ('sslsplit') for security. ((Please change immediately after reading this article))
{HTTPS real server : www.minzkn.com (My homepage)} <=> {internet} <=> {sslsplit virtual PC (sslsplit.minzkn.com)} <=> {internal virtual private network} <=> {HTTPS client virtual PC : sslsplit-client.minzkn.com}
1. connect to ssh://sslsplit@sslsplit.minzkn.com (SSH password : 'sslsplit')
# ~/run-sslsplit-0.5.5-test.sh
source location : /home/sslsplit/sslsplit-0.5.5-test/
2. connect to ssh://sslsplit@sslsplit-client.minzkn.com (SSH password : 'sslsplit')
# ~/test-downstream.shThe test VM was rebuilt using the following standard distribution environment. (Please refer to show-system-settings.sh which simply checks the sslsplit system configuration environment.)
KVM+QEMU guest VM env (vCPU x 2, 2G ram, virtio network driver, ...)
ubuntu 20.04 LTS (installed packages : libevent-dev, libpcap-dev, libnet-dev, libssl-dev, build-essential, ...)
Configure TPROXY using firewalld (direct rule)
Control QoS rate for downstream direction by running tc command as networkd-dispatcher (routable hook)
Setting fwmark using netplan
I built it with SSLproxy just in case.Thanks @minzkn for giving me access to your test environment. I have started using it. But I didn't know wrapper bevs were so strange. It will take some time until I can convince myself if I can solve this issue or not?
sonertari
commented
2 years ago I think I have found a working solution to this issue. I have tested and convinced myself that the following patch works in the test environment you have provided. It includes your modified debug print, so that you can directly test yourself too.
As I have explained in the comments in the code, what I have realized is that the write events we get may be due to the wrapper bev or the underlying bev. And it seems like the only way of telling which is to check if the buf len of the ubev is below the low mark, which triggers the write event for ubev. If that is not the case, then the write event is for the wrapper bev, so we should not reset the watermark for the ubev. I think this is the correct way of including your trial-fix conditionally.
If this works for you too, we can convert it into a pull request, at long last. Note that I did not test this code until your test download fully finishes, so I hope it works until the end of download. And I hope it works for proxyspecs other than autossl too.
--- pxyconn.c.orig 2022-04-02 15:30:07.871607909 +0300
+++ pxyconn.c 2022-04-02 15:30:19.475759283 +0300
@@ -1653,6 +1653,18 @@
}
}
+static int
+pxy_conn_getwatermark(struct bufferevent *bev)
+{
+ size_t lowmark = 0;
+ size_t highmark = 0;
+
+ bufferevent_getwatermark(bev, EV_WRITE, &lowmark, &highmark);
+ if (lowmark || highmark)
+ return 1;
+ return 0;
+}
+
/*
* Peek into pending data to see if it is an SSL/TLS ClientHello, and if so,
* upgrade the connection from plain TCP to SSL/TLS.
@@ -1691,6 +1703,11 @@
"upgrade\n");
return 0;
}
+
+ struct bufferevent *ubev = ctx->dst.bev;
+ int ubev_read_disabled = !(bufferevent_get_enabled(ctx->dst.bev) & EV_READ);
+ int ubev_watermark_set = pxy_conn_getwatermark(ctx->dst.bev);
+
ctx->dst.bev = bufferevent_openssl_filter_new(
ctx->evbase, ctx->dst.bev, ctx->dst.ssl,
BUFFEREVENT_SSL_CONNECTING,
@@ -1704,6 +1721,16 @@
pxy_bev_writecb, pxy_bev_eventcb,
ctx);
bufferevent_enable(ctx->dst.bev, EV_READ|EV_WRITE);
+
+ if (ubev_read_disabled) {
+ bufferevent_disable(ubev, EV_READ);
+ bufferevent_disable(ctx->dst.bev, EV_READ);
+ }
+ if (ubev_watermark_set) {
+ bufferevent_setwatermark(ubev, EV_WRITE, OUTBUF_LIMIT/2, OUTBUF_LIMIT);
+ bufferevent_setwatermark(ctx->dst.bev, EV_WRITE, OUTBUF_LIMIT/2, OUTBUF_LIMIT);
+ }
+
if (OPTS_DEBUG(ctx->opts)) {
log_err_printf("Replaced dst bufferevent, new "
"one is %p\n",
@@ -1896,12 +1923,33 @@
}
}
evbuffer_add_buffer(outbuf, inbuf);
- if (evbuffer_get_length(outbuf) >= OUTBUF_LIMIT) {
+
+ struct bufferevent *ubev_other = bufferevent_get_underlying(other->bev);
+ if (evbuffer_get_length(outbuf) >= OUTBUF_LIMIT ||
+ (ubev_other && evbuffer_get_length(bufferevent_get_output(ubev_other)) >= OUTBUF_LIMIT)) {
+
+ if (OPTS_DEBUG(ctx->opts)) {
+ struct bufferevent *ubev = bufferevent_get_underlying(bev);
+ log_err_printf("buffer watermark control ! (inbuf=%zu [ubev_inbuf=%zu], outbuf=%zu [ubev_other_outbuf=%zu], OUTBUF_LIMIT=%u)\n",
+ evbuffer_get_length(inbuf),
+ ubev ? evbuffer_get_length(bufferevent_get_input(ubev)) : 0,
+ evbuffer_get_length(outbuf),
+ ubev_other ? evbuffer_get_length(bufferevent_get_output(ubev_other)) : 0,
+ OUTBUF_LIMIT);
+ }
+
/* temporarily disable data source;
* set an appropriate watermark. */
- bufferevent_setwatermark(other->bev, EV_WRITE,
- OUTBUF_LIMIT/2, OUTBUF_LIMIT);
bufferevent_disable(bev, EV_READ);
+ bufferevent_setwatermark(other->bev, EV_WRITE, OUTBUF_LIMIT/2, OUTBUF_LIMIT);
+
+ struct bufferevent *ubev = bufferevent_get_underlying(bev);
+ if (ubev)
+ bufferevent_disable(ubev, EV_READ);
+
+ /* The watermark for ubev_other may be already set, see the write cb */
+ if (ubev_other && !pxy_conn_getwatermark(ubev_other))
+ bufferevent_setwatermark(ubev_other, EV_WRITE, OUTBUF_LIMIT/2, OUTBUF_LIMIT);
}
}
@@ -1934,11 +1982,25 @@
return;
}
- if (other->bev && !(bufferevent_get_enabled(other->bev) & EV_READ)) {
- /* data source temporarily disabled;
- * re-enable and reset watermark to 0. */
- bufferevent_setwatermark(bev, EV_WRITE, 0, 0);
- bufferevent_enable(other->bev, EV_READ);
+ if (other->bev) {
+ struct bufferevent *ubev_other = bufferevent_get_underlying(other->bev);
+ if (!(bufferevent_get_enabled(other->bev) & EV_READ) ||
+ (ubev_other && !(bufferevent_get_enabled(ubev_other) & EV_READ))) {
+ /* data source temporarily disabled;
+ * re-enable and reset watermark to 0. */
+ bufferevent_enable(other->bev, EV_READ);
+ bufferevent_setwatermark(bev, EV_WRITE, 0, 0);
+
+ if (ubev_other)
+ bufferevent_enable(ubev_other, EV_READ);
+
+ /* Do not reset the watermark for ubev without checking its buf len,
+ * because the current write event may be due to the buf len of bev
+ * falling below OUTBUF_LIMIT/2, not that of ubev */
+ struct bufferevent *ubev = bufferevent_get_underlying(bev);
+ if (ubev && evbuffer_get_length(bufferevent_get_output(ubev)) < OUTBUF_LIMIT/2)
+ bufferevent_setwatermark(ubev, EV_WRITE, 0, 0);
+ }
}
}
@@ -2005,6 +2067,11 @@
if (OPTS_DEBUG(ctx->opts)) {
log_dbg_printf("Completing autossl upgrade\n");
}
+
+ struct bufferevent *ubev = ctx->src.bev;
+ int ubev_read_disabled = !(bufferevent_get_enabled(ctx->src.bev) & EV_READ);
+ int ubev_watermark_set = pxy_conn_getwatermark(ctx->src.bev);
+
ctx->src.bev = bufferevent_openssl_filter_new(
ctx->evbase, ctx->src.bev, ctx->src.ssl,
BUFFEREVENT_SSL_ACCEPTING,
@@ -2017,8 +2084,16 @@
pxy_bev_writecb,
pxy_bev_eventcb,
ctx);
- bufferevent_enable(ctx->src.bev,
- EV_READ|EV_WRITE);
+ bufferevent_enable(ctx->src.bev, EV_READ|EV_WRITE);
+
+ if (ubev_read_disabled) {
+ bufferevent_disable(ubev, EV_READ);
+ bufferevent_disable(ctx->src.bev, EV_READ);
+ }
+ if (ubev_watermark_set) {
+ bufferevent_setwatermark(ubev, EV_WRITE, OUTBUF_LIMIT/2, OUTBUF_LIMIT);
+ bufferevent_setwatermark(ctx->src.bev, EV_WRITE, OUTBUF_LIMIT/2, OUTBUF_LIMIT);
+ }
}
} else {
ctx->src.bev = pxy_bufferevent_setup(ctx, ctx->fd,I think the following simplified patch is enough. I have realized that disabling or enabling the read events for ubev has no effect.
--- pxyconn.c.orig 2022-04-02 15:30:07.871607909 +0300
+++ pxyconn.c 2022-04-02 18:05:46.708213786 +0300
@@ -1738,6 +1738,18 @@
pxy_conn_ctx_free(ctx, is_requestor);
}
+static int
+pxy_conn_getwatermark(struct bufferevent *bev)
+{
+ size_t lowmark = 0;
+ size_t highmark = 0;
+
+ bufferevent_getwatermark(bev, EV_WRITE, &lowmark, &highmark);
+ if (lowmark || highmark)
+ return 1;
+ return 0;
+}
+
/*
* Callback for read events on the up- and downstream connection bufferevents.
* Called when there is data ready in the input evbuffer.
@@ -1896,12 +1908,29 @@
}
}
evbuffer_add_buffer(outbuf, inbuf);
- if (evbuffer_get_length(outbuf) >= OUTBUF_LIMIT) {
+
+ struct bufferevent *ubev_other = bufferevent_get_underlying(other->bev);
+ if (evbuffer_get_length(outbuf) >= OUTBUF_LIMIT ||
+ (ubev_other && evbuffer_get_length(bufferevent_get_output(ubev_other)) >= OUTBUF_LIMIT)) {
+
+ if (OPTS_DEBUG(ctx->opts)) {
+ struct bufferevent *ubev = bufferevent_get_underlying(bev);
+ log_err_printf("buffer watermark control ! (inbuf=%zu [ubev_inbuf=%zu], outbuf=%zu [ubev_other_outbuf=%zu], OUTBUF_LIMIT=%u)\n",
+ evbuffer_get_length(inbuf),
+ ubev ? evbuffer_get_length(bufferevent_get_input(ubev)) : 0,
+ evbuffer_get_length(outbuf),
+ ubev_other ? evbuffer_get_length(bufferevent_get_output(ubev_other)) : 0,
+ OUTBUF_LIMIT);
+ }
+
/* temporarily disable data source;
* set an appropriate watermark. */
- bufferevent_setwatermark(other->bev, EV_WRITE,
- OUTBUF_LIMIT/2, OUTBUF_LIMIT);
bufferevent_disable(bev, EV_READ);
+ bufferevent_setwatermark(other->bev, EV_WRITE, OUTBUF_LIMIT/2, OUTBUF_LIMIT);
+
+ /* The watermark for ubev_other may be already set, see the write cb */
+ if (ubev_other && !pxy_conn_getwatermark(ubev_other))
+ bufferevent_setwatermark(ubev_other, EV_WRITE, OUTBUF_LIMIT/2, OUTBUF_LIMIT);
}
}
@@ -1937,8 +1966,15 @@
if (other->bev && !(bufferevent_get_enabled(other->bev) & EV_READ)) {
/* data source temporarily disabled;
* re-enable and reset watermark to 0. */
- bufferevent_setwatermark(bev, EV_WRITE, 0, 0);
bufferevent_enable(other->bev, EV_READ);
+ bufferevent_setwatermark(bev, EV_WRITE, 0, 0);
+
+ /* Do not reset the watermark for ubev without checking its buf len,
+ * because the current write event may be due to the buf len of bev
+ * falling below OUTBUF_LIMIT/2, not that of ubev */
+ struct bufferevent *ubev = bufferevent_get_underlying(bev);
+ if (ubev && evbuffer_get_length(bufferevent_get_output(ubev)) < OUTBUF_LIMIT/2)
+ bufferevent_setwatermark(ubev, EV_WRITE, 0, 0);
}
}
@@ -2017,8 +2053,7 @@
pxy_bev_writecb,
pxy_bev_eventcb,
ctx);
- bufferevent_enable(ctx->src.bev,
- EV_READ|EV_WRITE);
+ bufferevent_enable(ctx->src.bev, EV_READ|EV_WRITE);
}
} else {
ctx->src.bev = pxy_bufferevent_setup(ctx, ctx->fd,Even more simplified:
--- pxyconn.c.orig 2022-04-02 15:30:07.871607909 +0300
+++ pxyconn.c 2022-04-02 21:07:54.359088087 +0300
@@ -1896,12 +1896,20 @@
}
}
evbuffer_add_buffer(outbuf, inbuf);
- if (evbuffer_get_length(outbuf) >= OUTBUF_LIMIT) {
+
+ struct bufferevent *ubev_other = bufferevent_get_underlying(other->bev);
+ if (evbuffer_get_length(outbuf) >= OUTBUF_LIMIT ||
+ (ubev_other && evbuffer_get_length(bufferevent_get_output(ubev_other)) >= OUTBUF_LIMIT)) {
/* temporarily disable data source;
* set an appropriate watermark. */
bufferevent_setwatermark(other->bev, EV_WRITE,
OUTBUF_LIMIT/2, OUTBUF_LIMIT);
bufferevent_disable(bev, EV_READ);
+
+ /* The watermark for ubev_other may be already set, see writecb,
+ * but getting is equally expensive as setting */
+ if (ubev_other)
+ bufferevent_setwatermark(ubev_other, EV_WRITE, OUTBUF_LIMIT/2, OUTBUF_LIMIT);
}
}
@@ -1939,6 +1947,13 @@
* re-enable and reset watermark to 0. */
bufferevent_setwatermark(bev, EV_WRITE, 0, 0);
bufferevent_enable(other->bev, EV_READ);
+
+ /* Do not reset the watermark for ubev without checking its buf len,
+ * because the current write event may be due to the buf len of bev
+ * falling below OUTBUF_LIMIT/2, not that of ubev */
+ struct bufferevent *ubev = bufferevent_get_underlying(bev);
+ if (ubev && evbuffer_get_length(bufferevent_get_output(ubev)) < OUTBUF_LIMIT/2)
+ bufferevent_setwatermark(ubev, EV_WRITE, 0, 0);
}
}The simplified patch seems to work fine for autossl, ssl, https.
However, if the other side is disconnected, I think it is necessary to review the condition until the buffer is empty.
In other words, I am wondering whether there is no need to consider the conditions in which ctx->closed is set or when other->closed is set.
I do not know. Wouldn't there be a problem without considering ubev for the condition that the other side of the Proxy terminates and the buffer exhaustion status as a result?
In the pxy_bev_writecb function
if (other->closed) {
struct evbuffer *outbuf = bufferevent_get_output(bev);
if (evbuffer_get_length(outbuf) == 0) { // ubev's outbuf length need not check ?????
/* finished writing and other end is closed;
* close this end too and clean up memory */
bufferevent_free_and_close_fd(bev, ctx);
pxy_conn_ctx_free(ctx, (bev == ctx->dst.bev));
}
return;
}In the pxy_bev_eventcb function
} else if (!other->closed) {
/* if the other end is still open and doesn't have data
* to send, close it, otherwise its writecb will close
* it after writing what's left in the output buffer */
struct evbuffer *outbuf;
outbuf = bufferevent_get_output(other->bev);
if (evbuffer_get_length(outbuf) == 0) { // ubev's outbuf length need not check ?
bufferevent_free_and_close_fd(other->bev, ctx);
other->bev = NULL;
other->closed = 1;
}
}
...
if (!ctx->connected) {
log_dbg_printf("EOF on outbound connection before "
"connection establishment\n");
evutil_closesocket(ctx->fd);
other->closed = 1;
} else if (!other->closed) {
/* if there is data pending in the closed connection,
* handle it here, otherwise it will be lost. */
if (evbuffer_get_length(bufferevent_get_input(bev))) {
pxy_bev_readcb(bev, ctx);
}
/* if the other end is still open and doesn't
* have data to send, close it, otherwise its
* writecb will close it after writing what's
* left in the output buffer. */
if (evbuffer_get_length(
bufferevent_get_output(other->bev)) == 0) { // ubev's outbuf length need not check ?
bufferevent_free_and_close_fd(other->bev, ctx);
other->bev = NULL;
other->closed = 1;
}
}(
Usually, HTTP(s) server side implements to have a structure that closes the connection later than the client in order to avoid the accumulation of connections in the TIME_WAIT/CLOSE_WAIT state... It is estimated that verification is necessary in a test environment such as uploading the verification environment to the server using WebDAV or POST method additionally, but it is not easy for me to establish such an environment...
)
sonertari
commented
2 years ago It's good to hear that it works.
I guess you are referring to the case where libevent reports that the len of outbuf is 0, but the len of ubev outbuf is not. We don't know if that's still the case while closing. But probably it will happen again, because the client is slow, but sslsplit is fast in processing and moving data from the bev outbuf to the ubev outbuf, making the bev outbuf 0 but not the ubev outbuf.
But I think we can test it with the current setup, if you wait until the end of download, and see if curl reports success or fail. Have you waited until the download completes? I would use a smaller download file though.
minzkn
commented
2 years ago I've been trying to figure out how to test it.
And in the patch part, I set the high watermark for ubev large in pxy_bev_readcb.
if (ubev_other)
- bufferevent_setwatermark(ubev_other, EV_WRITE, OUTBUF_LIMIT/2, OUTBUF_LIMIT);
+ bufferevent_setwatermark(ubev_other, EV_WRITE, OUTBUF_LIMIT/2, OUTBUF_LIMIT * 64);And in iterative testing, quite often in tests like this one, the downloaded file is in an incomplete state like this:
In sslsplit, the connection status is as follows.
...
Error from dst bufferevent: 104:Connection reset by peer 0:0:-:0:-:0:-
SSL_free() in state 00000001 = 0001 = SSLOK (SSL negotiation finished successfully) [accept socket]
SSL disconnected to [59.14.59.180]:443
SSL disconnected from [192.168.253.4]:47840
SSL_free() in state 00000001 = 0001 = SSLOK (SSL negotiation finished successfully) [connect socket]
...curl (https client) will look like this:
...
* transfer closed with 26634105 bytes remaining to read
* Closing connection 0
} [5 bytes data]
* TLSv1.3 (OUT), TLS alert, close notify (256):
} [2 bytes data]
curl: (18) transfer closed with 26634105 bytes remaining to read
...In my test environment, I used the following command in sslsplit-client.minzkn.com (SeeAlso: test-downstream-34MBytes-file.sh script) with a smaller file (about 34MBytes / 34998089 bytes) for testing.
curl -v -k https://www.minzkn.com/public/sample/media/sample.mp4 --output sample.mp4
7fbad59d74f9a89fa392457163a525c5 sample.mp4 <<< Original md5 hash, However, in this test, the size of the downloaded file is small and the hash value is different from the original. Notice that there is a problem with curl as well.
In other words, the high watermark for outbuf of ubev is large, so it is an opinion that it is necessary to take action on the buffer remaining at the time of connection termination during testing. ((if the test method is correct))
sonertari
commented
2 years ago Thanks @minzkn for the analysis. Based on your reports I have modified the source code to keep conn open if underlying buffers have data. Please see the underlying-bevs-issue#303 branch.
I think this branch works, because I have used your test env with a 2.1MB file sample.ogg with the test modification you have (with OUTBUF_LIMIT * 64), and curl can download the file successfully with the same checksum each time.
This can be observed in the debug output of sslsplit:
0x556014a5aef0 0x7fe5ac00ac00 eventcb dst eof
evbuffer size at EOF: i:0 o:0 i:0 o:0
SSL disconnected to [59.14.59.180]:443
SSL disconnected from [192.168.253.4]:47884
0x7fe5ac00ac00 free_and_close_fd
SSL_free() in state 00000001 = 0001 = SSLOK (SSL negotiation finished successfully) [connect socket]
... [SONER: about 2 min later:]
0x556014a5aef0 0x7fe5ac010f30 eventcb src eof
evbuffer size at EOF: i:0 o:0 i:0 o:0
SSL disconnected to [59.14.59.180]:443
SSL disconnected from [192.168.253.4]:47884
0x7fe5ac010f30 free_and_close_fd
SSL_free() in state 00000001 = 0001 = SSLOK (SSL negotiation finished successfully) [accept socket]
0x556014a5aef0 pxy_conn_ctx_freeSo even though one of the conn ends close, the other remains open until its underlying buffer is empty, during which time curl continues to download the file, and then the other conn end closes too.
The debug output of sslsplit look incomplete now, but anyway.
sonertari
commented
2 years ago Debug out underlying bev sizes at EOF:
0x558b96483a50 0x7f977c004730 eventcb dst eof
evbuffer size at EOF: i:0 o:0 i:0 o:0
underlying evbuffer size at EOF: i:0 o:0 i:0 o:2027641
SSL disconnected to [59.14.59.180]:443
SSL disconnected from [192.168.253.4]:47890
0x7f977c004730 free_and_close_fd
SSL_free() in state 00000001 = 0001 = SSLOK (SSL negotiation finished successfully) [connect socket]
...
0x558b96483a50 0x7f977c011420 eventcb src eof
evbuffer size at EOF: i:0 o:0 i:0 o:0
underlying evbuffer size at EOF: i:0 o:0 i:0 o:0
SSL disconnected to [59.14.59.180]:443
SSL disconnected from [192.168.253.4]:47890
0x7f977c011420 free_and_close_fd
SSL_free() in state 00000001 = 0001 = SSLOK (SSL negotiation finished successfully) [accept socket]
0x558b96483a50 pxy_conn_ctx_free
Just FYI, now I have fixed a couple of issues with sslproxy, and it seems to work fine in your test env too.
HTTPS server => (1 Gbps - faster network) sslsplit autossl tproxy (10 Mbps - slower network) => HTTPS client
sslsplit autossl 0.0.0.0 tproxy When the client Big file downloads HTTPS from the server
In the pxy_bev_readcb function, evbuffer_get_length(outbuf) in the following implementation always returns 0.
In an environment where the client side speed is slower than the server side speed in the autossl tproxy setting, the inbuf side continues to accumulate and the memory increases. Eventually oom will be raised.
If you do it with ssl instead of autossl in the same environment, it works fine.
using sslsplit v0.5.5, libevent v2.1.8, openssl v1.1.1k
Thanks for making a great program.