Assertion when setting proxy.config.ssl.max_record_size=-1

[zwoop]

(gdb) bt full
#0  0x00007ffff59111f7 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:56
        resultvar = 0
        pid = 26435
        selftid = 26442
#1  0x00007ffff59128e8 in __GI_abort () at abort.c:90
        save_stage = 2
        act = {__sigaction_handler = {sa_handler = 0x0, sa_sigaction = 0x0}, sa_mask = {__val = {0, 0, 0, 0, 0, 0, 140737352171520, 46912505899232, 5864063237428, 46912505899424, 46912623357424, 46912505899424, 6375826, 46912631844480, 46912505892864, 5864063237368}}, sa_flags = 1432878388, sa_restorer = 0x2aaaab3fe9a0}
        sigs = {__val = {32, 0 <repeats 15 times>}}
#2  0x00007ffff7b4a5c9 in ink_abort (message_format=0x7ffff7b9bc80 "%s:%d: failed assertion `%s`") at ink_error.cc:99
        ap = <error reading variable ap (Cannot access memory at address 0xffffffffffffffc0)>
#3  0x00007ffff7b43674 in _ink_assert (expression=0xdff2a0 "r != 0", file=0xdfed40 "UnixNetVConnection.cc", line=472) at ink_assert.cc:37
No locals.
#4  0x0000000000b3a232 in write_to_net_io (nh=0x7ffff0ee83f0, vc=0x2aaab2c18800, thread=0x7ffff0ee4800) at UnixNetVConnection.cc:472
        s = 0x2aaab2c189a0
        mutex = 0x62a000004cd0
        lock = {m = {m_ptr = 0x2aaab2402df0}, lock_acquired = true}
        __FUNCTION__ = "write_to_net_io"
        ntodo = 9223372036849953872
        buf = @0x2aaab2c189c8: {name = 0x0, mbuf = 0x2aaab2606090, entry = 0x2aaab26060f8}
        towrite = 36037
        signalled = 0
        needs = 0
        total_written = 0
        r = 0
#5  0x0000000000b39813 in write_to_net (nh=0x7ffff0ee83f0, vc=0x2aaab2c18800, thread=0x7ffff0ee4800) at UnixNetVConnection.cc:359
        mutex = 0x62a000004cd0
#6  0x0000000000b23212 in NetHandler::process_ready_list (this=0x7ffff0ee83f0) at UnixNet.cc:413
        vc = 0x2aaab2c18800
#7  0x0000000000b242a5 in NetHandler::waitForActivity (this=0x7ffff0ee83f0, timeout=60000000) at UnixNet.cc:523
        epd = 0x2aaab2c18a60
        lock = {m = {m_ptr = 0x62a000004870}, locked_p = true}
        __FUNCTION__ = "waitForActivity"
        p = 0x7ffff0ee8510
        pd = 0x7ffff088f800
        vc = 0x2aaab2c18800
#8  0x0000000000b903f7 in EThread::execute_regular (this=0x7ffff0ee4800) at UnixEThread.cc:232
        done_one = false
        sleep_time = 60000000
        e = 0x0
        NegativeQueue = {<DLL<Event, Event::Link_link>> = {head = 0x0}, tail = 0x0}
        next_time = 1508878607537980050
#9  0x0000000000b90677 in EThread::execute (this=0x7ffff0ee4800) at UnixEThread.cc:262
        __FUNCTION__ = "execute"
#10 0x0000000000b8db08 in spawn_thread_internal (a=0x6080000090a0) at Thread.cc:91
        p = 0x6080000090a0
#11 0x00007ffff63b4e25 in start_thread (arg=0x2aaaab3ff700) at pthread_create.c:308
        __res = <optimized out>
        pd = 0x2aaaab3ff700
        now = <optimized out>
        unwind_buf = {cancel_jmp_buf = {{jmp_buf = {46912505902848, -4675559604569876457, 0, 140737488347456, 46912505902848, 106102872117408, -1564924797787154409, 4675579984661207063}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
        not_first_call = <optimized out>
        pagesize_m1 = <optimized out>
        sp = <optimized out>
        freesize = <optimized out>
#12 0x00007ffff59d434d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113
No locals.

@oknet thoughts? This might also be related / similar to the old Jira: https://issues.apache.org/jira/browse/TS-4424

[oknet]

@zwoop Do you have last log ?

    case SSL_ERROR_ZERO_RETURN:
      TraceOut(trace, get_remote_addr(), get_remote_port(), "SSL Error: zero return");
      num_really_written = -errno;
      SSL_INCREMENT_DYN_STAT(ssl_error_zero_return);
      Debug("ssl.error", "SSL_write-SSL_ERROR_ZERO_RETURN");
      break;

IMO, the errno may be overwrited.

[oknet]

Within frame 4, the r == 0 and needs == 0, it is strange.

[oknet]

The needs == 0 means:

The value of err is one of the following :

• SSL_ERROR_NONE
• SSL_ERROR_SYSCALL
• SSL_ERROR_ZERO_RETURN
• SSL_ERROR_SSL

PS: err = SSLWriteBuffer(ssl, current_block, l, num_really_written); within SSLNetVConnection::load_buffer_and_write().

The value of r is returned from SSLNetVConnection::load_buffer_and_write().

The r == 0 means num_really_written == 0 within SSLNetVConnection::load_buffer_and_write().

According to num_really_written == 0, there will be 2 possibilities, one is err == SSL_ERROR_NONE the other is errno == 0.

Obviously, the err is not SSL_ERROR_NONE because the towrite is 36037.

From the above analysis, errno is 0. However it is impossible that errno is 0.
In conclusion, the errno is overwritten.

I create a PR #2709 to fix it.

[oknet]

@zwoop

According to the RecordsConfig.cc,

{RECT_CONFIG, "proxy.config.ssl.max_record_size", RECD_INT, "0", RECU_DYNAMIC, RR_NULL, RECC_NULL, "[0-16383]", RECA_NULL}

The -1 is a invalid value to proxy.config.ssl.max_record_size, but the check type is set to RECC_NULL which means skip checking.

[oknet]

According to the SSLNetVConnection::load_buffer_and_write()

 688   do {
 689     // What is remaining left in the next block?
 690     l                   = buf.reader()->block_read_avail();
 691     char *current_block = buf.reader()->start();
 692 
 693     // check if to amount to write exceeds that in this buffer
 694     int64_t wavail = towrite - total_written;
 695 
 696     if (l > wavail) {
 697       l = wavail;
 698     }
 699 
 700     // TS-2365: If the SSL max record size is set and we have
 701     // more data than that, break this into smaller write
 702     // operations.
 703     if (SSLConfigParams::ssl_maxrecord > 0 && l > SSLConfigParams::ssl_maxrecord) {
 704       l = SSLConfigParams::ssl_maxrecord;
 705     } else if (SSLConfigParams::ssl_maxrecord == -1) {
 706       if (sslTotalBytesSent < SSL_DEF_TLS_RECORD_BYTE_THRESHOLD) {
 707         dynamic_tls_record_size = SSL_DEF_TLS_RECORD_SIZE;
 708         SSL_INCREMENT_DYN_STAT(ssl_total_dyn_def_tls_record_count);
 709       } else {
 710         dynamic_tls_record_size = SSL_MAX_TLS_RECORD_SIZE;
 711         SSL_INCREMENT_DYN_STAT(ssl_total_dyn_max_tls_record_count);
 712       }
 713       if (l > dynamic_tls_record_size) {
 714         l = dynamic_tls_record_size;
 715       }
 716     }
 717 
 718     if (!l) {
 719       break;
 720     }
 721 
 722     try_to_write       = l;
 723     num_really_written = 0;
 724     Debug("ssl", "SSLNetVConnection::loadBufferAndCallWrite, before SSLWriteBuffer, l=%" PRId64 ", towrite=%" PRId64 ", b=%p",      l,
 725           towrite, current_block);
 726     err = SSLWriteBuffer(ssl, current_block, l, num_really_written);

The l is no more than a size of IOBufferBlock. The default size for VIO buffer is 4KB.
IMO, the design of TS-2503 is incomplete because the SSL_MAX_TLS_RECORD_SIZE is 16383 which is larger than 4KB.

The sequence of SSL_write size is:

1300, 1300, 1300, 196, 1300, 1300, 1300, 196, ...

after the total send > 1000000:

576, 4096, 4096, 4096, ...

[oknet]

@zwoop @shinrich

According to a PR of php : php/php-src#2330 and the issue : https://bugs.php.net/bug.php?id=72333 , there may be a bug within SSLNetVC.

 +			/* The following mode are added only if we are able to change socket
 +			 * to non blocking mode which is also used for read and write */
 +			SSL_set_mode(
 +				sslsock->ssl_handle,
 +				(
 +					SSL_get_mode(sslsock->ssl_handle) |
 +					SSL_MODE_ENABLE_PARTIAL_WRITE |
 +					SSL_MODE_ACCEPT_MOVING_WRITE_BUFFER
 +				)
 +			);

Maybe a root cause of TS-4424.

[oknet]

@zwoop The #2709 is updated. please test again.

[oknet]

If you could reproduce with the newest #2709 , please try to apply below patch:

diff --git a/iocore/net/SSLNetVConnection.cc b/iocore/net/SSLNetVConnection.cc
index a7996f8..146747e 100644
--- a/iocore/net/SSLNetVConnection.cc
+++ b/iocore/net/SSLNetVConnection.cc
@@ -795,6 +795,7 @@ SSLNetVConnection::load_buffer_and_write(int64_t towrite, MIOBufferAccessor &buf
     } break;
     }
   }
+  ink_assert(num_really_written);
   return num_really_written;
 }

It move the assert into load_buffer_and_write in order to get some useful information.

Please start trafficserver with debug tag ssl and post the result of tail -n 50 traffic.out if possible.

Thanks.

[zwoop]

Yeh, running with current master, and #2709, I still got the same assertion. I applied your patch above (moving the assert), and I get

(gdb) bt full
#0  0x00007ffff59121f7 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:56
        resultvar = 0
        pid = 15518
        selftid = 15524
#1  0x00007ffff59138e8 in __GI_abort () at abort.c:90
        save_stage = 2
        act = {__sigaction_handler = {sa_handler = 0x0, sa_sigaction = 0x0}, sa_mask = {__val = {0, 0, 0, 0, 0, 0, 140737352314880, 46912503800880, 5864062975134, 46912503801072, 0, 46912503802096, 6459778, 140737328759244, 46912503795712, 5864062975074}}, sa_flags = 1432616094, sa_restorer = 0x2aaaab1fe4f0}
        sigs = {__val = {32, 0 <repeats 15 times>}}
#2  0x00007ffff7b4ad49 in ink_abort (message_format=0x7ffff7b9bea0 "%s:%d: failed assertion `%s`") at ink_error.cc:99
        ap = <error reading variable ap (Cannot access memory at address 0xffffffffffffffc0)>
#3  0x00007ffff7b43df4 in _ink_assert (expression=0xe09560 "num_really_written", file=0xe08180 "SSLNetVConnection.cc", line=798) at ink_assert.cc:37
No locals.
#4  0x0000000000b1dade in SSLNetVConnection::load_buffer_and_write (this=0x2aaab2c1a780, towrite=65536, buf=..., total_written=@0x2aaaab1fe950: 0, needs=@0x2aaaab1fe910: 0) at SSLNetVConnection.cc:798
        try_to_write = 1300
        num_really_written = 0
        l = 1300
        dynamic_tls_record_size = 1300
        err = 1
        now = 1509470279892655159
        __FUNCTION__ = "load_buffer_and_write"
        trace = false
#5  0x0000000000b55d6c in write_to_net_io (nh=0x7ffff0fd33f0, vc=0x2aaab2c1a780, thread=0x7ffff0fcf800) at UnixNetVConnection.cc:463
        s = 0x2aaab2c1a920
        mutex = 0x62a000004d40
        lock = {m = {m_ptr = 0x2aaab2403250}, lock_acquired = true}
        __FUNCTION__ = "write_to_net_io"
        ntodo = 9223372036849885067
        buf = @0x2aaab2c1a948: {name = 0x0, mbuf = 0x2aaab2606ae0, entry = 0x2aaab2606b48}
        towrite = 65536
        signalled = 0
        needs = 0
        total_written = 0
        r = 140737349519951
#6  0x0000000000b5545b in write_to_net (nh=0x7ffff0fd33f0, vc=0x2aaab2c1a780, thread=0x7ffff0fcf800) at UnixNetVConnection.cc:359
        mutex = 0x62a000004d40
#7  0x0000000000b3ee5a in NetHandler::process_ready_list (this=0x7ffff0fd33f0) at UnixNet.cc:413
        vc = 0x2aaab2c1a780
#8  0x0000000000b3feed in NetHandler::waitForActivity (this=0x7ffff0fd33f0, timeout=60000000) at UnixNet.cc:523
        epd = 0x2aaab2c1a9e0
        lock = {m = {m_ptr = 0x62a000004950}, locked_p = true}
        __FUNCTION__ = "waitForActivity"
        p = 0x7ffff0fd3510
        pd = 0x7ffff08d2800
        vc = 0x2aaab2c1a780
#9  0x0000000000bae7bf in EThread::execute_regular (this=0x7ffff0fcf800) at UnixEThread.cc:271
        done_one = false
        sleep_time = 60000000
        e = 0x0
        NegativeQueue = {<DLL<Event, Event::Link_link>> = {head = 0x0}, tail = 0x0}
        next_time = 1509470280182438929
        delta = 30191153
        loop_start_time = 1509470279862438929
        loop_finish_time = 1509470279862437223
        prev_metric = 0x7ffff10d1200
        nq_count = 5
        ev_count = 5
        METRIC_INIT = {_loop_time = {_start = 0, _min = 9223372036854775807, _max = 0}, _events = {_min = 2147483647, _max = 0, _total = 0}, _count = 0, _wait = 0}
#10 0x0000000000baee4f in EThread::execute (this=0x7ffff0fcf800) at UnixEThread.cc:324
        __FUNCTION__ = "execute"
#11 0x0000000000bab8d2 in spawn_thread_internal (a=0x608000009120) at Thread.cc:91
        p = 0x608000009120
#12 0x00007ffff63b5e25 in start_thread (arg=0x2aaaab1ff700) at pthread_create.c:308
        __res = <optimized out>
        pd = 0x2aaaab1ff700
        now = <optimized out>
        unwind_buf = {cancel_jmp_buf = {{jmp_buf = {46912503805696, 4495425859176174473, 0, 140737488347104, 46912503805696, 106102872117536, 7725819880746587017, -4495407754884213879}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
        not_first_call = <optimized out>
        pagesize_m1 = <optimized out>
        sp = <optimized out>
        freesize = <optimized out>
#13 0x00007ffff59d534d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113
No locals.

[zwoop]

Obviously, num_really_writte is 0 here :-).