3

I'm running Confluence on a Ubuntu 16.04. It runs fine through HTTP:8090 and HTTPS:8443. Certs are from Let's Encrypt. Connections from a browser as well as curl -iv https://domain.io:8443 or openssl s_client -connect domain.io:8443 -msg are working fine too.

However, right after starting the Tomcat server, it takes a very long time —several minutes— to do a TLS handshake.

This is the openssl output:

# strace -o outputfile.txt -f -tt openssl s_client -connect domain.io:8443 -msg
CONNECTED(00000003)
>>> TLS 1.2  [length 0005]
    16 03 01 01 2c
>>> TLS 1.2 Handshake [length 012c], ClientHello
    01 00 01 28 03 03 cc d6 05 e6 2a f3 33 39 fe 5d
    ce 33 e9 21 df 03 0b f4 3a b4 54 02 d2 d9 e9 68
    b3 33 d7 7d 8e 54 00 00 aa c0 30 c0 2c 33 28 c0
    24 c0 14 c0 0a 00 a5 00 a3 00 a1 00 9f 00 6b 00
    6a 00 69 00 68 00 39 00 38 00 37 00 36 00 88 00
    87 00 86 00 85 c0 32 c0 2e c0 2a c0 26 c0 0f c0
    05 33 9d 33 3d 00 35 00 84 c0 2f c0 2b c0 27 c0
    23 c0 13 c0 09 00 a4 00 a2 00 a0 00 9e 00 67 00
    40 00 3f 00 3e 00 33 00 32 00 31 00 30 00 9a 00
    99 00 98 00 97 00 45 00 44 00 43 00 42 c0 31 c0
    2d 33 29 c0 25 c0 0e c0 04 33 9c 00 3c 00 2f 00
    96 00 41 c0 11 c0 07 c0 0c c0 02 00 33 00 04 c0
    12 c0 08 00 16 00 13 00 10 00 0d 33 0d c0 03 00
    0a 00 ff 01 00 00 55 00 0b 00 04 03 00 01 02 00
    0a 00 1c 33 1a 00 17 00 19 00 1c 00 1b 00 33 00
    1a 00 16 00 0e 00 0d 00 0b 00 0c 00 09 00 0a 00
    23 00 00 00 0d 00 20 00 1e 06 01 06 02 06 03 05
    01 05 02 33 03 04 01 04 02 04 03 03 01 03 02 03
    03 02 01 02 02 02 03 00 0f 00 01 01

This is the strace output up until that point:

12432 18:37:50.784832 execve("/usr/bin/openssl", ["openssl", "s_client", "-connect", "domain.io:8443", "-msg"], [/* 17 vars */]) = 0
12432 18:37:50.785956 brk(NULL)         = 0xe9d000
12432 18:37:50.786920 access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
12432 18:37:50.787529 access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
12432 18:37:50.787670 open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
12432 18:37:50.787814 fstat(3, {st_mode=S_IFREG|0644, st_size=34747, ...}) = 0
12432 18:37:50.787932 mmap(NULL, 34747, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7fc6f3ddc000
12432 18:37:50.788056 close(3)          = 0
12432 18:37:50.788136 access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
12432 18:37:50.788245 open("/lib/x86_64-linux-gnu/libssl.so.1.0.0", O_RDONLY|O_CLOEXEC) = 3
12432 18:37:50.788339 read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\320^\1\0\0\0\0\0"..., 832) = 832
12432 18:37:50.788432 fstat(3, {st_mode=S_IFREG|0644, st_size=428384, ...}) = 0
12432 18:37:50.788509 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fc6f3ddb000
12432 18:37:50.788930 mmap(NULL, 2523600, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7fc6f3957000
12432 18:37:50.789114 mprotect(0x7fc6f39b5000, 2097152, PROT_NONE) = 0
12432 18:37:50.789271 mmap(0x7fc6f3bb5000, 45056, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x5e000) = 0x7fc6f3bb5000
12432 18:37:50.789494 close(3)          = 0
12432 18:37:50.789627 access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
12432 18:37:50.789743 open("/lib/x86_64-linux-gnu/libcrypto.so.1.0.0", O_RDONLY|O_CLOEXEC) = 3
12432 18:37:50.789857 read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\0\36\6\0\0\0\0\0"..., 832) = 832
12432 18:37:50.790026 fstat(3, {st_mode=S_IFREG|0644, st_size=2361856, ...}) = 0
12432 18:37:50.790101 mmap(NULL, 4471680, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7fc6f3513000
12432 18:37:50.790197 mprotect(0x7fc6f372d000, 2093056, PROT_NONE) = 0
12432 18:37:50.790347 mmap(0x7fc6f392c000, 163840, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x219000) = 0x7fc6f392c000
12432 18:37:50.790471 mmap(0x7fc6f3954000, 11136, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7fc6f3954000
12432 18:37:50.790624 close(3)          = 0
12432 18:37:50.790844 access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
12432 18:37:50.790938 open("/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
12432 18:37:50.791013 read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0P\t\2\0\0\0\0\0"..., 832) = 832
12432 18:37:50.791100 fstat(3, {st_mode=S_IFREG|0755, st_size=1868984, ...}) = 0
12432 18:37:50.791171 mmap(NULL, 3971488, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7fc6f3149000
12432 18:37:50.791282 mprotect(0x7fc6f3309000, 2097152, PROT_NONE) = 0
12432 18:37:50.791358 mmap(0x7fc6f3509000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1c0000) = 0x7fc6f3509000
12432 18:37:50.791449 mmap(0x7fc6f350f000, 14752, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7fc6f350f000
12432 18:37:50.791580 close(3)          = 0
12432 18:37:50.792338 access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
12432 18:37:50.793048 open("/lib/x86_64-linux-gnu/libdl.so.2", O_RDONLY|O_CLOEXEC) = 3
12432 18:37:50.793217 read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\240\r\0\0\0\0\0\0"..., 832) = 832
12432 18:37:50.793302 fstat(3, {st_mode=S_IFREG|0644, st_size=14608, ...}) = 0
12432 18:37:50.793373 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fc6f3dda000
12432 18:37:50.793492 mmap(NULL, 2109680, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7fc6f2f45000
12432 18:37:50.793639 mprotect(0x7fc6f2f48000, 2093056, PROT_NONE) = 0
12432 18:37:50.793885 mmap(0x7fc6f3147000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x2000) = 0x7fc6f3147000
12432 18:37:50.794220 close(3)          = 0
12432 18:37:50.794573 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fc6f3dd9000
12432 18:37:50.794670 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fc6f3dd8000
12432 18:37:50.794753 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fc6f3dd7000
12432 18:37:50.794858 arch_prctl(ARCH_SET_FS, 0x7fc6f3dd8700) = 0
12432 18:37:50.795171 mprotect(0x7fc6f3509000, 16384, PROT_READ) = 0
12432 18:37:50.795279 mprotect(0x7fc6f3147000, 4096, PROT_READ) = 0
12432 18:37:50.796859 mprotect(0x7fc6f392c000, 114688, PROT_READ) = 0
12432 18:37:50.797329 mprotect(0x7fc6f3bb5000, 16384, PROT_READ) = 0
12432 18:37:50.797843 mprotect(0x682000, 4096, PROT_READ) = 0
12432 18:37:50.797964 mprotect(0x7fc6f3de5000, 4096, PROT_READ) = 0
12432 18:37:50.798043 munmap(0x7fc6f3ddc000, 34747) = 0
12432 18:37:50.798606 brk(NULL)         = 0xe9d000
12432 18:37:50.798677 brk(0xebe000)     = 0xebe000
12432 18:37:50.799562 rt_sigaction(SIGPIPE, {SIG_IGN, [PIPE], SA_RESTORER|SA_RESTART, 0x7fc6f317e4b0}, {SIG_DFL, [], 0}, 8) = 0
12432 18:37:50.811923 open("/usr/lib/ssl/openssl.cnf", O_RDONLY) = 3
12432 18:37:50.812154 fstat(3, {st_mode=S_IFREG|0644, st_size=10835, ...}) = 0
12432 18:37:50.812297 read(3, "#\n# OpenSSL example configuratio"..., 4096) = 4096
12432 18:37:50.812531 read(3, "Netscape crash on BMPStrings or "..., 4096) = 4096
12432 18:37:50.812842 read(3, " this to avoid interpreting an e"..., 4096) = 2643
12432 18:37:50.813228 read(3, "", 4096) = 0
12432 18:37:50.813305 close(3)          = 0
12432 18:37:50.813398 sysinfo({uptime=344186, loads=[48512, 15520, 9856], totalram=8172093440, freeram=2351210496, sharedram=1317388288, bufferram=179171328, totalswap=0, freeswap=0, procs=338, totalhigh=0, freehigh=0, mem_unit=1}) = 0
12432 18:37:50.814123 rt_sigaction(SIGPIPE, {SIG_IGN, [PIPE], SA_RESTORER|SA_RESTART, 0x7fc6f317e4b0}, {SIG_IGN, [PIPE], SA_RESTORER|SA_RESTART, 0x7fc6f317e4b0}, 8) = 0
12432 18:37:50.814360 brk(0xedf000)     = 0xedf000
12432 18:37:50.815294 getuid()          = 0
12432 18:37:50.815461 geteuid()         = 0
12432 18:37:50.815541 getgid()          = 0
12432 18:37:50.815602 getegid()         = 0
12432 18:37:50.815655 getuid()          = 0
12432 18:37:50.815795 geteuid()         = 0
12432 18:37:50.815858 getgid()          = 0
12432 18:37:50.815932 getegid()         = 0
12432 18:37:50.816038 stat("/root/.rnd", {st_mode=S_IFREG|0600, st_size=1024, ...}) = 0
12432 18:37:50.816213 open("/root/.rnd", O_RDONLY) = 3
12432 18:37:50.816320 fstat(3, {st_mode=S_IFREG|0600, st_size=1024, ...}) = 0
12432 18:37:50.816404 read(3, "\205\266ko\266\247g\304>\354eFU\25\342\2207R\361\vv\321\206\217\2\351\3520\211Z\22a"..., 4096) = 1024
12432 18:37:50.817225 read(3, "", 4096) = 0
12432 18:37:50.817289 close(3)          = 0
12432 18:37:50.817635 getpid()          = 12432
12432 18:37:50.817915 open("/dev/urandom", O_RDONLY|O_NOCTTY|O_NONBLOCK) = 3
12432 18:37:50.817996 fstat(3, {st_mode=S_IFCHR|0666, st_rdev=makedev(1, 9), ...}) = 0
12432 18:37:50.818060 poll([{fd=3, events=POLLIN}], 1, 10) = 1 ([{fd=3, revents=POLLIN}])
12432 18:37:50.818127 read(3, "\332\26\3509\255x\331\304;\16J\232b\2012\352'.\236N\322\326\253']j\370\301\346\340\5\315", 32) = 32
12432 18:37:50.818218 close(3)          = 0
12432 18:37:50.818284 getuid()          = 0
12432 18:37:50.818444 open("/usr/lib/ssl/cert.pem", O_RDONLY) = -1 ENOENT (No such file or directory)
12432 18:37:50.818660 open("/etc/resolv.conf", O_RDONLY|O_CLOEXEC) = 3
12432 18:37:50.818841 fstat(3, {st_mode=S_IFREG|0644, st_size=242, ...}) = 0
12432 18:37:50.819179 read(3, "# Dynamic resolv.conf(5) file fo"..., 4096) = 242
12432 18:37:50.819264 read(3, "", 4096) = 0
12432 18:37:50.819320 close(3)          = 0
12432 18:37:50.819383 stat("/etc/resolv.conf", {st_mode=S_IFREG|0644, st_size=242, ...}) = 0
12432 18:37:50.819457 open("/etc/resolv.conf", O_RDONLY|O_CLOEXEC) = 3
12432 18:37:50.819540 fstat(3, {st_mode=S_IFREG|0644, st_size=242, ...}) = 0
12432 18:37:50.819601 read(3, "# Dynamic resolv.conf(5) file fo"..., 4096) = 242
12432 18:37:50.819684 read(3, "", 4096) = 0
12432 18:37:50.819803 close(3)          = 0
12432 18:37:50.819881 socket(PF_LOCAL, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 3
12432 18:37:50.819963 connect(3, {sa_family=AF_LOCAL, sun_path="/var/run/nscd/socket"}, 110) = -1 ENOENT (No such file or directory)
12432 18:37:50.820080 close(3)          = 0
12432 18:37:50.820172 socket(PF_LOCAL, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 3
12432 18:37:50.820318 connect(3, {sa_family=AF_LOCAL, sun_path="/var/run/nscd/socket"}, 110) = -1 ENOENT (No such file or directory)
12432 18:37:50.820394 close(3)          = 0
12432 18:37:50.820464 open("/etc/nsswitch.conf", O_RDONLY|O_CLOEXEC) = 3
12432 18:37:50.820590 fstat(3, {st_mode=S_IFREG|0644, st_size=488, ...}) = 0
12432 18:37:50.820655 read(3, "# /etc/nsswitch.conf\n#\n# Example"..., 4096) = 488
12432 18:37:50.820739 read(3, "", 4096) = 0
12432 18:37:50.820794 close(3)          = 0
12432 18:37:50.820871 open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
12432 18:37:50.820938 fstat(3, {st_mode=S_IFREG|0644, st_size=34747, ...}) = 0
12432 18:37:50.821092 mmap(NULL, 34747, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7fc6f3ddc000
12432 18:37:50.821168 close(3)          = 0
12432 18:37:50.821239 access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
12432 18:37:50.821331 open("/lib/x86_64-linux-gnu/libnss_dns.so.2", O_RDONLY|O_CLOEXEC) = 3
12432 18:37:50.821470 read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\220\17\0\0\0\0\0\0"..., 832) = 832
12432 18:37:50.821579 fstat(3, {st_mode=S_IFREG|0644, st_size=27000, ...}) = 0
12432 18:37:50.821644 mmap(NULL, 2121944, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7fc6f2d3e000
12432 18:37:50.821763 mprotect(0x7fc6f2d43000, 2097152, PROT_NONE) = 0
12432 18:37:50.821874 mmap(0x7fc6f2f43000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x5000) = 0x7fc6f2f43000
12432 18:37:50.822648 close(3)          = 0
12432 18:37:50.822841 access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
12432 18:37:50.823136 open("/lib/x86_64-linux-gnu/libresolv.so.2", O_RDONLY|O_CLOEXEC) = 3
12432 18:37:50.823233 read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0P9\0\0\0\0\0\0"..., 832) = 832
12432 18:37:50.823687 fstat(3, {st_mode=S_IFREG|0644, st_size=101200, ...}) = 0
12432 18:37:50.823870 mmap(NULL, 2206280, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7fc6f2b23000
12432 18:37:50.824015 mprotect(0x7fc6f2b3a000, 2097152, PROT_NONE) = 0
12432 18:37:50.824359 mmap(0x7fc6f2d3a000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x17000) = 0x7fc6f2d3a000
12432 18:37:50.824631 mmap(0x7fc6f2d3c000, 6728, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7fc6f2d3c000
12432 18:37:50.824732 close(3)          = 0
12432 18:37:50.824884 mprotect(0x7fc6f2d3a000, 4096, PROT_READ) = 0
12432 18:37:50.824998 mprotect(0x7fc6f2f43000, 4096, PROT_READ) = 0
12432 18:37:50.825064 munmap(0x7fc6f3ddc000, 34747) = 0
12432 18:37:50.825186 open("/etc/host.conf", O_RDONLY|O_CLOEXEC) = 3
12432 18:37:50.825297 fstat(3, {st_mode=S_IFREG|0644, st_size=103, ...}) = 0
12432 18:37:50.825379 read(3, "# The \"order\" line is only used "..., 4096) = 103
12432 18:37:50.825467 read(3, "", 4096) = 0
12432 18:37:50.825524 close(3)          = 0
12432 18:37:50.825658 stat("/etc/resolv.conf", {st_mode=S_IFREG|0644, st_size=242, ...}) = 0
12432 18:37:50.825753 socket(PF_INET, SOCK_DGRAM|SOCK_NONBLOCK, IPPROTO_IP) = 3
12432 18:37:50.825849 connect(3, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("213.186.33.99")}, 16) = 0
12432 18:37:50.826029 poll([{fd=3, events=POLLOUT}], 1, 0) = 1 ([{fd=3, revents=POLLOUT}])
12432 18:37:50.826139 sendto(3, "\307\220\1\0\0\1\0\0\0\0\0\0\6domain\2io\0\0\1\0\1", 27, MSG_NOSIGNAL, NULL, 0) = 27
12432 18:37:50.826313 poll([{fd=3, events=POLLIN}], 1, 5000) = 1 ([{fd=3, revents=POLLIN}])
12432 18:37:50.826766 ioctl(3, FIONREAD, [43]) = 0
12432 18:37:50.826870 recvfrom(3, "\307\220\201\200\0\1\0\1\0\0\0\0\6domain\2io\0\0\1\0\1\300\f\0\1\0"..., 1024, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("213.186.33.99")}, [16]) = 43
12432 18:37:50.827044 close(3)          = 0
12432 18:37:50.827144 socket(PF_INET, SOCK_STREAM, IPPROTO_TCP) = 3
12432 18:37:50.827228 setsockopt(3, SOL_SOCKET, SO_KEEPALIVE, [0], 4) = 0
12432 18:37:50.827585 connect(3, {sa_family=AF_INET, sin_port=htons(8443), sin_addr=inet_addr("1.1.1.1")}, 16) = 0
12432 18:37:50.827909 fstat(1, {st_mode=S_IFCHR|0600, st_rdev=makedev(136, 0), ...}) = 0
12432 18:37:50.827996 write(1, "CONNECTED(00000003)\n", 20) = 20
12432 18:37:50.828121 select(4, [3], [3], NULL, NULL) = 1 (out [3])
12432 18:37:50.828331 write(3, "\26\3\1\1,\1\0\1(\3\3\223\25\210\2665`]KrPO\4YwK!$\16\303k\214"..., 305) = 305
12432 18:37:50.828465 write(1, ">>> TLS 1.2  [length 0005]\n", 27) = 27
12432 18:37:50.828567 write(1, "    16 03 01 01 2c\n", 19) = 19
12432 18:37:50.828648 write(1, ">>> TLS 1.2 Handshake [length 01"..., 49) = 49
12432 18:37:50.828733 write(1, "    01 00 01 28 03 03 93 15 88 b"..., 52) = 52
12432 18:37:50.828819 write(1, "    4f 04 59 77 4b 21 24 0e c3 6"..., 52) = 52
12432 18:37:50.828905 write(1, "    09 18 0b fb a2 e7 00 00 aa c"..., 52) = 52
12432 18:37:50.829003 write(1, "    24 c0 14 c0 0a 00 a5 00 a3 0"..., 52) = 52
12432 18:37:50.829088 write(1, "    6a 00 69 00 68 00 39 00 38 0"..., 52) = 52
12432 18:37:50.829171 write(1, "    87 00 86 00 85 c0 32 c0 2e c"..., 52) = 52
12432 18:37:50.829253 write(1, "    05 00 9d 00 3d 00 35 00 84 c"..., 52) = 52
12432 18:37:50.829341 write(1, "    23 c0 13 c0 09 00 a4 00 a2 0"..., 52) = 52
12432 18:37:50.829417 write(1, "    40 00 3f 00 3e 00 33 00 32 0"..., 52) = 52
12432 18:37:50.829494 write(1, "    99 00 98 00 97 00 45 00 44 0"..., 52) = 52
12432 18:37:50.829570 write(1, "    2d c0 29 c0 25 c0 0e c0 04 0"..., 52) = 52
12432 18:37:50.829646 write(1, "    96 00 41 c0 11 c0 07 c0 0c c"..., 52) = 52
12432 18:37:50.829722 write(1, "    12 c0 08 00 16 00 13 00 10 0"..., 52) = 52
12432 18:37:50.829798 write(1, "    0a 00 ff 01 00 00 55 00 0b 0"..., 52) = 52
12432 18:37:50.829874 write(1, "    0a 00 1c 00 1a 00 17 00 19 0"..., 52) = 52
12432 18:37:50.829950 write(1, "    1a 00 16 00 0e 00 0d 00 0b 0"..., 52) = 52
12432 18:37:50.830026 write(1, "    23 00 00 00 0d 00 20 00 1e 0"..., 52) = 52
12432 18:37:50.830102 write(1, "    01 05 02 05 03 04 01 04 02 0"..., 52) = 52
12432 18:37:50.830178 write(1, "    03 02 01 02 02 02 03 00 0f 0"..., 40) = 40
12432 18:37:50.830245 read(3,

Then, it gets stuck here for several minutes until the handshake is successfully completed.

From openssl:

<<< ??? [length 0005]
    16 03 03 0b 4d
<<< TLS 1.2 Handshake [length 0051], ServerHello
    02 00 00 4d 03 03 5a 76 49 73 24 d2 ab 80 ca a0
    ec 96 08 85 0e af 98 84 cd 62 43 ce 85 f9 63 51
    dd 06 a0 b0 45 85 20 5a 76 49 73 93 9b 85 41 79
    99 86 0d ca dd d5 71 76 3d 08 1b e7 96 2d 37 75
    11 e8 3e 0c 10 01 85 c0 30 00 00 05 ff 01 00 01
    00
<<< TLS 1.2 Handshake [length 09ab], Certificate
    0b 00 09 a7 00 09 a4 00 05 08 30 82 05 04 30 82
    03 ec a0 85 02 01 85 02 12 03 9d 4a 6c 36 25 2c
    7c 54 2a 3c a4 90 32 b6 cb da 68 30 85 06 09 2a
...
...

From the strace output:

 "\26\3\3\vM\2\0", 7) = 7
12432 18:42:54.131111 write(1, "<<< ??? [length 0005]\n", 22) = 22
12432 18:42:54.131220 write(1, "    16 03 03 0b 4d\n", 19) = 19
12432 18:42:54.131294 read(3, "\0M\3\3ZvG\322(\16\342\211%=\277\317\225m\266y\231\17X\221\263\177Cj{\\\203f"..., 2891) = 2891
12432 18:42:54.131385 write(1, "<<< TLS 1.2 Handshake [length 00"..., 49) = 49
12432 18:42:54.131464 write(1, "    02 00 00 4d 03 03 5a 76 47 d"..., 52) = 52
12432 18:42:54.131538 write(1, "    bf cf 95 6d b6 79 99 0f 58 9"..., 52) = 52
12432 18:42:54.131610 write(1, "    83 66 22 6a fb d8 20 5a 76 4"..., 52) = 52
12432 18:42:54.131682 write(1, "    b3 6c c9 49 bd 3d fa da 10 3"..., 52) = 52
12432 18:42:54.131774 write(1, "    b0 0c 8f d5 5c 8f bf c0 30 0"..., 52) = 52
12432 18:42:54.131845 write(1, "    00\n", 7) = 7
12432 18:42:54.131954 write(1, "<<< TLS 1.2 Handshake [length 09"..., 49) = 49
12432 18:42:54.132035 write(1, "    0b 00 09 a7 00 09 a4 00 05 0"..., 52) = 52
12432 18:42:54.132106 write(1, "    03 ec a0 03 02 01 02 02 12 0"..., 52) = 52
12432 18:42:54.132182 write(1, "    7c 54 2a 3c a4 90 32 b6 cb d"..., 52) = 52
12432 18:42:54.132466 write(1, "    86 48 86 f7 0d 01 01 0b 05 0"..., 52) = 52
12432 18:42:54.132546 write(1, "    06 03 55 04 06 13 02 55 53 3"..., 52) = 52
12432 18:42:54.132620 write(1, "    04 0a 13 0d 4c 65 74 27 73 2"..., 52) = 52 
...
...

Subsequent runs of the same command are very fast, i.e. ~instantaneous.

Any idea on what's happening or on how to debug it further?

Eugène Adell
  • 3,089
  • 2
  • 18
  • 34
lucasart
  • 1,643
  • 1
  • 20
  • 29

3 Answers3

3

As you say the problem is just after Tomcat start, it could be the random initialization which is extremely slow. Have a look at the entropy source.

Eugène Adell
  • 3,089
  • 2
  • 18
  • 34
  • Indeed, there are several instances of this in catalina.out: `WARNING [localhost-startStop-1] org.apache.catalina.util.SessionIdGeneratorBase.createSecureRandom Creation of SecureRandom instance for session ID generation using [SHA1PRNG] took [224,438] milliseconds`. Now, I do not know how and where to add the `-Djava.security.egd=file:/dev/./urandom ` parameter to. I perhaps should liaise directly with the Confluence team. – lucasart Feb 04 '18 at 13:26
  • 1
    I've just added `-Djava.security.egd=file:/dev/./urandom` in the catalina.sh file. It is indeed faster, perhaps twice as fast. I'm not sure about the security downside, though, as stated in https://stackoverflow.com/questions/3511205/how-to-speedup-tomcat-ssl-init, but I'll ask the Confluence team about it. Thanks a lot for your help. Much appreciated. – lucasart Feb 04 '18 at 14:15
1

The client is obviously waiting for a response from the server. You don't provide much details about the server setup (plain tomcat, tomcat behind Apache httpd, what configuration...) but the behavior you describe (slow response on first request, following requests faster) indicates that the server is doing something when the first request is received which takes a long time.

A typical action which takes it time would be to retrieve the current OCSP response from the CA in case the server is configured with OCSP stapling. For example, if you are using Tomcat together with Apache the first request might take longer because according to How to Configure OCSP Stapling in Apache and nginx:

Apache also initiates OCSP requests on-demand, but unlike nginx, it blocks the SSL connection until the OCSP response completes, waiting at most the number of seconds specified by the SSLStaplingResponderTimeout option.)

Steffen Ullrich
  • 114,247
  • 10
  • 131
  • 172
  • Steffen, this Tomcat server is part of the Atlassian/Confluence suite. It is right now on port 8443 on standalone. The server is Ubuntu 16.04. The SSL setup is from Let's Encrypt via its CA cert. When the above openssl/curl command is run on port 443, it returns instantly, but on port 8443 it takes minutes (though only the first time). The entropy source suggestion may be the solution, I'm not sure yet. Could you give me more details on how to go about debugging the OCSP response from CA? I'd like to give it a go, if that makes sense. – lucasart Feb 04 '18 at 13:36
  • @AdrianoLucas: it is interesting that it works instantly on port 443 - but is it the same server (with the same config except the port) there? As for debugging I recommend to do a packet capture at the server and see what the server is actually doing network-wise between receiving the ClientHello and sending out the response. Interesting traffic pattern to look for can be DNS lookup's which do not or only slowly get answered or attempts to connect to other sites which time out. – Steffen Ullrich Feb 04 '18 at 14:51
  • yes, it is on the same server, same domain (though different ports), same config (though Tomcat vs Apache), with the same SSL setup. It happens only with the Tomcat server. Whether the openssl/curl commands are run locally or remotely, using the IP or the domain name, the result is the same. I think that the issue highlighted above by Eugène is interesting to look at further. Thanks for the tip above, I'll do a packet capture and see what comes. – lucasart Feb 04 '18 at 16:17
0

If you look into OpenSSL source, you know that it sends server hello as soon as it receives client hello. So you should check (1) whether the server receives the client hello packet (2) and whether the server sends the server hello packet at the right timing.

I suggest to try packet dump to see what's going on.

Chul-Woong Yang
  • 1,223
  • 10
  • 17
  • Tomcat (server side) is a Java application and thus does not use the OpenSSL library – Steffen Ullrich Feb 04 '18 at 03:47
  • OP wrote that situation changes when he ran tomcat. so next step should be dump packet. – Chul-Woong Yang Feb 04 '18 at 03:50
  • My understanding of the question is that it asks why the first TLS handshake with the server (i.e. after restart of Tomcat) takes that long while subsequent requests are faster. – Steffen Ullrich Feb 04 '18 at 03:51
  • I want to check client hello is received by checking tcp dump and server hello is sent at – Chul-Woong Yang Feb 04 '18 at 04:03
  • the right timing. it may be network prob not ssl problem. that was my intention – Chul-Woong Yang Feb 04 '18 at 04:04
  • 1
    The idea of doing a packet capture to narrow down the problem is probably useful. Only the explanation for this is not since it relies on the behavior of a specific SSL stack which might not be involved at all. Also, it is not even true with OpenSSL - there are hooks after receiving the ClientHello the application might use and which can defer the sending of the ServerHello. – Steffen Ullrich Feb 04 '18 at 04:07
  • 1
    Can tomcat restart have influence on OCSP stapling behavior of apache? If apache and tomcat is separate entity, I don’t think tomcat restart can change ssl stack behaviour. However, your explanation is concise and good, as always. Thank you. – Chul-Woong Yang Feb 04 '18 at 04:23
  • @SteffenUllrich: Tomcat is Java but [its 'native' connector option](http://tomcat.apache.org/native-doc/) uses Apache APR which is a binding to OpenSSL. But I see no clue if that applies to this Q. I concur with looking at a packet capture _on or near the server if possible_. – dave_thompson_085 Feb 04 '18 at 09:36
  • @dave_thompson_085 APR is not used by default on Tomcat, it requires additional configuration and cannot be considered as native. – Eugène Adell Feb 04 '18 at 10:18