Ask Your Question
0

Cause Of Server Hello Delay

asked 2017-11-24 16:18:59 +0000

I've been trying to pin down the cause of some of my web servers being occasionally slow to respond. This problem seems to occur infrequently at first but then starts to happen more often for several days before going away again. They are Windows servers running an Apache 2.4.27 reverse proxy with a Tomcat (7 or 8) based web server behind them (various Atlassian products, one on each server). Using Wireshark I've managed to track down that there's a delay in the Server Hello being sent back from the server to the client, but I don't know what is causing this delay. I've setup a script to use cURL to request a page every minute to help with the diagnosis.

237 2017/297 07:57:30.571296    10.0.0.6    123.223.100.1   TLSv1.2 571 Client Hello
244 2017/297 07:57:30.796302    10.0.0.6    123.223.100.1   TCP 571 [TCP Retransmission] 56426 → 443 [PSH, ACK] Seq=1 Ack=1 Win=66560 Len=517
245 2017/297 07:57:30.814021    123.223.100.1   10.0.0.6    TCP 66  443 → 56426 [ACK] Seq=1 Ack=518 Win=132096 Len=0 SLE=1 SRE=518
389 2017/297 07:57:41.044311    123.223.100.1   10.0.0.6    TLSv1.2 1506    Server Hello
…
398 2017/297 07:57:41.086327    10.0.0.6    123.223.100.1   TLSv1.2 173 Application Data

Server Trace

64  2017-10-24 07:57:30.574615  212.159.78.240  123.223.100.1   TLSv1.2 571 Client Hello
72  2017-10-24 07:57:30.799403  212.159.78.240  123.223.100.1   TCP 571 [TCP Retransmission] 56426 → 443 [PSH, ACK] Seq=1 Ack=1 Win=66560 Len=517
73  2017-10-24 07:57:30.799441  123.223.100.1   212.159.78.240  TCP 66  443 → 56426 [ACK] Seq=1 Ack=518 Win=132096 Len=0 SLE=1 SRE=518
274 2017-10-24 07:57:41.028342  123.223.100.1   212.159.78.240  TLSv1.2 2958    Server Hello
…
295 2017-10-24 07:57:41.089469  212.159.78.240  123.223.100.1   TLSv1.2 173 Application Data

How can I track down what is causing the delay in the Server Hello message? Is this caused by Apache not responding for this delay or is it something else?

Using strace along with cURL on an Ubuntu client I can see the following extra lines that correspond with the delay, but I've no idea what they mean. Can anyone help with these as well?

19807 18:23:43.514170 poll([{fd=3, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}], 1, 0) = 0 (Timeout)
19807 18:23:43.514371 rt_sigaction(SIGPIPE, {sa_handler=SIG_IGN, sa_mask=[PIPE], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7ff57b636150}, NULL, 8) = 0
19807 18:23:43.514449 poll([{fd=3, events=POLLIN}], 1, 0) = 0 (Timeout)
19807 18:23:43.514502 rt_sigaction(SIGPIPE, NULL, {sa_handler=SIG_IGN, sa_mask=[PIPE], sa_flags=SA_RESTORER ...
(more)
edit retag flag offensive close merge delete

Comments

Not really a Wireshark question. As usual, at the application level Wireshark can tell you what happened but not why.

grahamb gravatar imagegrahamb ( 2017-11-24 16:41:01 +0000 )edit

Thanks for the response, sorry yeah I guess it's not the best place to post this. Maybe some other Wireshark users had come across this though.

Eddy555 gravatar imageEddy555 ( 2017-11-24 20:28:03 +0000 )edit

1 Answer

Sort by » oldest newest most voted
0

answered 2017-11-27 08:14:13 +0000

PaulOfford gravatar image

There are some things you can do, including using Wireshark to dig a bit further - you've done a good job being able to measure the delay so that's a great start. Get a good understanding the moving parts of the system. I imagine it will be something like this:

client PC ---> Reverse Proxy ---> TomCat ---> Database
                              \
                                ------------> Authentication

Using the above as an example (please check your topology though), trace the TCP flows between the Reverse Proxy and TomCat, TomCat to the Database and the Reverse Proxy to the Authentication solution. You can do this using tcpdump on the loopback adapter.

Run the loopback traces at the same time as the traces you were already collecting. Capture some examples of the problem. Start with your external trace to establish a time frame for the problem. So using your trace above as an example, establish the time frame as being from 07:57:30.799403 to 07:57:41.028342 - adjust for time sync difference between your external trace device and the Ubuntu clock. Now look in that time frame for similar delays in the TCP flows you have collected from the loopback adapter.

You can get a blow-by-blow explanation of multi-tier analysis like this in the Network Trace Analysis Guide you'll find here - https://community.tribelab.com/course...

Best regards...Paul

edit flag offensive delete link more

Comments

Hi Paul Thanks for the reply, that's really useful. I'll have a dig around and see what else I can find.

Eddy555 gravatar imageEddy555 ( 2017-11-27 08:51:44 +0000 )edit

I've been doing some more analysis of this issue again (as it reared it's ugly head once more) and there's some strange data between the client hello and server hello. In Wireshark on the server side I see a lot of [ACK] and [PSH, ACK] messages supposedly sent back and forth between the client and the server. However the Wireshark trace from the client shows none of this. How can this be? Is there something wrong with my Wireshark setup on the client that could miss this, or is something else going on?

An example of the trace on the server is shown below, and the pattern continues until Server Hello is sent.

1388    2017/339 21:54:52.134583    10.0.0.6    123.223.100.1   TLSv1.2 583 Client Hello
1390    2017/339 21:54:52.192195    123.223.100.1   10.0.0 ...
(more)
Eddy555 gravatar imageEddy555 ( 2017-12-07 16:20:00 +0000 )edit

I installed npcap on the server and traced the loopback adapter as well. I don't see anything obvious, just a lot of traffic to the database, which seems continuous throughout anyway. I did see some strange TCP data on the server side which wasn't seen in the client trace as I've mentioned in my answer on this post.

Eddy555 gravatar imageEddy555 ( 2017-12-07 16:24:11 +0000 )edit

Your Answer

Please start posting anonymously - your entry will be published after you log in or create a new account.

Add Answer

Question Tools

1 follower

Stats

Asked: 2017-11-24 16:18:59 +0000

Seen: 68 times

Last updated: Dec 07