[strongSwan] High latencies

Tue Sep 19 20:53:34 CEST 2017

On 19 Sep 2017, at 18:28, Turbo Fredriksson <turbo at bayour.com> wrote:

> I’ve really never been a friend of tcpdump. I could never get it to give
> me what I needed.

Well, running:

    sudo tcpdump -i eth0 port 6379 2>&1 | tee /tmp/y &

and then the redis client after that:

    strace -s3000 redis-cli -h elasticache.domain.tld -n 3 get ‘my_key'

gives:

connect(3, {sa_family=AF_INET, sin_port=htons(6379), sin_addr=inet_addr("10.127.1.88")}, 16) = -1 EINPROGRESS (Operation now in progress)
poll([{fd=3, events=POLLOUT}], 1, -1)   = 1 ([{fd=3, revents=POLLOUT}])
getsockopt(3, SOL_SOCKET, SO_ERROR, [0], [4]) = 0
fcntl(3, F_GETFL)                       = 0x802 (flags O_RDWR|O_NONBLOCK)
fcntl(3, F_SETFL, O_RDWR)               = 0
setsockopt(3, SOL_TCP, TCP_NODELAY, [1], 4) = 0
setsockopt(3, SOL_SOCKET, SO_KEEPALIVE, [1], 4) = 0
setsockopt(3, SOL_TCP, TCP_KEEPIDLE, [15], 4) = 0
setsockopt(3, SOL_TCP, TCP_KEEPINTVL, [5], 4) = 0
setsockopt(3, SOL_TCP, TCP_KEEPCNT, [3], 4) = 0
write(3, "*2\r\n$6\r\nSELECT\r\n$1\r\n3\r\n", 23) = 23
read(3, "+OK\r\n", 16384)               = 5
write(3, "*2\r\n$3\r\nget\r\n$61\r\nmy_key\r\n", 81) = 81
read(3, 19:38:46.362921 IP london-host.domain.tld.38992 > elasticache.domain.tld.6379: Flags [S], seq 4048965279, win 26883, options [mss 8961,sackOK,TS val 26646460 ecr 0,nop,wscale 7], length 0
19:38:46.374093 IP elasticache.domain.tld.6379 > london-host.domain.tld.38992: Flags [S.], seq 752350642, ack 4048965280, win 28960, options [mss 1460,sackOK,TS val 3959394223 ecr 26646460,nop,wscale 7], length 0
19:38:46.374114 IP london-host.domain.tld.38992 > elasticache.domain.tld.6379: Flags [.], ack 1, win 211, options [nop,nop,TS val 26646463 ecr 3959394223], length 0
19:38:46.374971 IP london-host.domain.tld.38992 > elasticache.domain.tld.6379: Flags [P.], seq 1:24, ack 1, win 211, options [nop,nop,TS val 26646463 ecr 3959394223], length 23: RESP "SELECT" "3"
19:38:46.385974 IP elasticache.domain.tld.6379 > london-host.domain.tld.38992: Flags [.], ack 24, win 227, options [nop,nop,TS val 3959394226 ecr 26646463], length 0
19:38:46.385983 IP elasticache.domain.tld.6379 > london-host.domain.tld.38992: Flags [P.], seq 1:6, ack 24, win 227, options [nop,nop,TS val 3959394226 ecr 26646463], length 5: RESP "OK"
19:38:46.386007 IP london-host.domain.tld.38992 > elasticache.domain.tld.6379: Flags [.], ack 6, win 211, options [nop,nop,TS val 26646466 ecr 3959394226], length 0
19:38:46.386148 IP london-host.domain.tld.38992 > elasticache.domain.tld.6379: Flags [P.], seq 24:105, ack 6, win 211, options [nop,nop,TS val 26646466 ecr 3959394226], length 81: RESP "get" “my_key"
19:38:46.420651 IP elasticache.domain.tld.6379 > london-host.domain.tld.38992: Flags [P.], seq 14486:14524, ack 105, win 227, options [nop,nop,TS val 3959394235 ecr 26646466], length 38: RESP "YWxpemVFbmQkilxjW/dTC20CAAB4cHh4eAA="
19:38:46.420685 IP london-host.domain.tld.38992 > elasticache.domain.tld.6379: Flags [.], ack 6, win 211, options [nop,nop,TS val 26646475 ecr 3959394226,nop,nop,sack 1 {14486:14524}], length 0
19:39:01.420024 IP london-host.domain.tld.38992 > elasticache.domain.tld.6379: Flags [.], ack 6, win 211, options [nop,nop,TS val 26650225 ecr 3959394226,nop,nop,sack 1 {14486:14524}], length 0
19:39:01.431410 IP elasticache.domain.tld.6379 > london-host.domain.tld.38992: Flags [.], ack 105, win 227, options [nop,nop,TS val 3959397987 ecr 26646475], length 0
19:39:09.558605 IP london-host.domain.tld.38992 > elasticache.domain.tld.6379: Flags [F.], seq 105, ack 6, win 211, options [nop,nop,TS val 26652259 ecr 3959394226,nop,nop,sack 1 {14486:14524}], length 0
19:39:09.569686 IP elasticache.domain.tld.6379 > london-host.domain.tld.38992: Flags [F.], seq 14524, ack 106, win 227, options [nop,nop,TS val 3959400022 ecr 26652259], length 0
19:39:09.569705 IP london-host.domain.tld.38992 > elasticache.domain.tld.6379: Flags [R], seq 4048965385, win 0, length 0
19:39:24.569222 IP london-host.domain.tld.39074 > elasticache.domain.tld.6379: Flags [S], seq 1012226767, win 26883, options [mss 8961,sackOK,TS val 26656012 ecr 0,nop,wscale 7], length 0
19:39:24.580344 IP elasticache.domain.tld.6379 > london-host.domain.tld.39074: Flags [S.], seq 2528408788, ack 1012226768, win 28960, options [mss 1460,sackOK,TS val 3959403774 ecr 26656012,nop,wscale 7], length 0
19:39:24.580364 IP london-host.domain.tld.39074 > elasticache.domain.tld.6379: Flags [.], ack 1, win 211, option

So if I understand this correctly, the response comes back (at 19:38:46.420651), but the client
command doesn’t output it in the shell.. That value it returns, is the last part of the full value.
Not sure if tcpdump “cuts” the data or not.

The rest of all that I have no idea what it means.

The client seems to be doing the SELECT+GET twice, then “something” happens, because
all I get from tcpdump is a repeat of the following two lines, over and over:

19:41:09.864036 IP london-host.domain.tld.39074 > elasticache.domain.tld.6379: Flags [.], ack 6, win 211, options [nop,nop,TS val 26682336 ecr 3959403777,nop,nop,sack 1 {14486:14524}], length 0
19:41:09.876744 IP elasticache.domain.tld.6379 > london-host.domain.tld.39074: Flags [.], ack 105, win 227, options [nop,nop,TS val 3959430098 ecr 26656026], length 0
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 801 bytes
Desc: Message signed with OpenPGP
URL: <http://lists.strongswan.org/pipermail/users/attachments/20170919/b0339390/attachment.sig>