How to track down throughput problems on the Ziti router

Support
1

Hi,

We are building up a new infrastructure where we will heavily use openziti as a core component :wink:
Currently we have a router, a controller and several servers connected via ziti tunnelers. The setup is kubernetes based, using the helm charts. The clients are MacOS.

As we put more and more load on them, we notice from time to time that some of the servers seem to be unresponsive. And others complain about slow response on web pages and so on.

I've been trying to track this down and have noticed that from time to time there is quite a bit of data in the router's receive queue that seems to be stuck there for quite some time:ould

State  Recv-Q  Send-Q      Local Address:Port          Peer Address:Port Process
ESTAB  0       0               10.42.0.4:59148           10.42.0.48:6262  users:(("ziti",pid=1109963,fd=8))
LISTEN 0       4096                    *:3022                     *:*     users:(("ziti",pid=1109963,fd=7))
LISTEN 0       4096                    *:10080                    *:*     users:(("ziti",pid=1109963,fd=3))
ESTAB  0       0      [::ffff:10.42.0.4]:3022  [::ffff:10.42.0.218]:54134 users:(("ziti",pid=1109963,fd=11))
ESTAB  0       0      [::ffff:10.42.0.4]:3022  [::ffff:10.42.0.218]:43088 users:(("ziti",pid=1109963,fd=13))
ESTAB  3103374 0      [::ffff:10.42.0.4]:3022  [::ffff:10.42.0.218]:41124 users:(("ziti",pid=1109963,fd=12))
ESTAB  0       0      [::ffff:10.42.0.4]:3022  [::ffff:10.42.0.218]:54938 users:(("ziti",pid=1109963,fd=9))
ESTAB  0       0      [::ffff:10.42.0.4]:3022  [::ffff:10.42.0.218]:60136 users:(("ziti",pid=1109963,fd=10))

And as long as the data is in the queue, all other clients will not be able to communicate with services on that server (pretty obvious).
At the moment I'm a bit stuck to find out why the data stays in the receive queue for such a long time. I've looked at CPU usage, but I don't see the ziti router hitting CPU limits or anything.

the settings from ziti-router.yaml are the defaults:

forwarder:
    latencyProbeInterval: 10
    xgressDialQueueLength: 1000
    xgressDialWorkerCount: 128
    linkDialQueueLength: 1000

I can reproduce this in my lab. Nothing is logged on the console when I see that the queues are full. What could be causing this behavior? Could it be something related to the Kubernetes infrastructure?

Currently I'm using 0.31.1 from 'next-release' (had 0.30.5 before).

Thanks,
Chris

1 Like
2

When a receive queue is filling up, it is usually due to a missing packet that TCP is waiting for to reassemble the stream. Since this is at the OS level, the ziti process is waiting on this data as well. Of course, it could fill up because ziti isn't draining the queue, but that is unlikely once you have eliminated any resource issues.

Since you say you have the ability to reproduce it in the lab, can you do a packet capture (tcpdump) and see if that is true? Some other tools can capture pieces, but you have to have good timing, generally, so a capture is best in my (network engineering) opinion; that way you can see the whole interaction and go back with various theories if necessary to the same data.

1 Like
3

Hi Mike,
Thanks for your reply. I did the test setup with tcpdump and also made a small video, but I can't upload it here. So I just took some screenshots.
When I triggered the reload, there was a lot of activity on tcpdump at first - all the data came in and the receive queue filled up. But at some point the queue reached a certain level and the activity on tcpdump stopped.
On the screenshots you can see 3 windows: tcpdump on top, in the middle a watch -i 0.5"ss -atnp" to show the Receive-Q status and on the bottom a strace -f -p <pid-of-router> 2>&1 | grep 12, to see the activity on the connection.

This is where the first screenshot. Please not the timestamp in tcpdump (21:37:49) an the queue size 4,8 MB:

Screenshot 1 - 21:37:49 - 4.8 MB
Screenshot 1 - 21:37:49 - 4.8 MB3116×1808 616 KB

The second - 21:37:56. Note the Got 1401 line at the top of the tcpdump screen - this is the line from the first screenshot. The queue is 3.49 MB here....

Screenshot 2- 21:37:56 - 3.49 MB
Screenshot 2- 21:37:56 - 3.49 MB3116×1808 598 KB

The third screenshot is from 21:37.59 - 2.8 MB queue. So we only had about 2 MB in 10 seconds. The tcpdump here also overlaps with the previous screenshot.

Screenshot 3 - 21:37.59 - 2.8 MB
Screenshot 3 - 21:37.59 - 2.8 MB3116×1808 660 KB

And finally - a screenshot from Wireshark showing the 10 second time span. I don't see anything like retransmissions here. There are outgoing TCP window updates as the receive Q is drained, and some new data arriving, but not much.

wireshark
wireshark2996×2082 989 KB

Do you see anything in the tcp stream that could cause this behavior?
The thing with the ACK packets - I think this is for the Send-Q. The data is sitting here until the recipient ACKs the data. But for the Recv-Q, I think the data is directly readable by the process...

From the netstat man page: https://linux.die.net/man/8/netstat

Recv-Q

The count of bytes not copied by the user program connected to this socket.

This also reads like it's not a problem at the OS level....

Can you get anything from the screenshots? I also could provide you the video and the tcpdumps on a separate way...

Thanks & Bye,
Chris

4

I was just wondering if it's a problem for the ziti router to run as a non-privileged container.
So I changed the securityContext from

securityContext:
  allowPrivilegeEscalation: false
  capabilities:
    drop:
    - ALL
  privileged: false
  readOnlyRootFilesystem: true
  runAsGroup: 2171
  runAsNonRoot: true
  runAsUser: 2171
  seccompProfile:
    type: RuntimeDefault

to

securityContext:
  allowPrivilegeEscalation: true
  capabilities:
    add:
    - ALL
  privileged: true
  readOnlyRootFilesystem: true
  runAsNonRoot: false
  runAsGroup: 0
  runAsUser: 0

but it doesn't seem to make a difference...

5

Hi,
During my latest tests, I noticed that the queue flushes very fast at some point. So I recorded another video and took a closer look at the strace output.

At some point the queue starts to fill up. On the strace we initially see reads in a sub-10ms frame (07:21:35.8xxx): Then it seems to start stumbling and later ~ 07:2139.5xxx it just seems to just poll on the connection once every ~100ms.

[pid 512453] 07:21:35.862801 read(10, "\177/#\370\236_\2663\226u\374\353\300\227\247\224\261\264m\202\2475\210\250\0342ox,\365S\334"..., 32768) = 8192
[pid 512453] 07:21:35.863046 read(10,  <unfinished ...>
[pid 512453] 07:21:35.863343 read(10,  <unfinished ...>
[pid 512453] 07:21:35.863755 read(10,  <unfinished ...>
[pid 512453] 07:21:35.864176 read(10,  <unfinished ...>
[pid 512453] 07:21:35.864493 read(10,  <unfinished ...>
[pid 512453] 07:21:35.865112 read(10,  <unfinished ...>
[pid 512453] 07:21:35.865229 read(10,  <unfinished ...>
[pid 512419] 07:21:35.865531 read(10,  <unfinished ...>
[pid 512419] 07:21:35.865609 read(10,  <unfinished ...>
[pid 512418] 07:21:35.866365 read(10,  <unfinished ...>
[pid 512418] 07:21:35.866531 read(10,  <unfinished ...>
[pid 512418] 07:21:35.931905 read(10,  <unfinished ...>
[pid 512453] 07:21:36.230657 read(10, "<\222+\25g\227bm\205\266\310H\365\255\263\252\30\370\246\212s\274\274\304\252]\377X\20&6\202"..., 33012) = 33012
[pid 512425] 07:21:36.430977 read(10,  <unfinished ...>
[pid 512453] 07:21:36.530292 read(10,  <unfinished ...>
[pid 512453] 07:21:36.530589 read(10,  <unfinished ...>
[pid 512419] 07:21:36.530890 read(10,  <unfinished ...>
[pid 512419] 07:21:36.531212 read(10,  <unfinished ...>
[pid 512425] 07:21:36.831383 read(10, "\4L\202\210\35\216\315\231\245\36Xo\363\255\211\221\321\227\314n\361V'\266\363P\311\252\307\n\226\346"..., 33348) = 33348
[pid 512419] 07:21:37.131538 read(10,  <unfinished ...>
[pid 512421] 07:21:37.330630 read(10,  <unfinished ...>
[pid 512453] 07:21:37.430951 read(10,  <unfinished ...>
[pid 512425] 07:21:37.470063 epoll_pwait(4, [], 128, 10, NULL, 0) = 0
[pid 512421] 07:21:37.531448 read(10,  <unfinished ...>
[pid 512421] 07:21:37.531717 read(10,  <unfinished ...>
[pid 512421] 07:21:37.531971 read(10,  <unfinished ...>
[pid 512427] 07:21:37.830186 read(10,  <unfinished ...>
[pid 512427] 07:21:37.830417 read(10,  <unfinished ...>
[pid 512425] 07:21:37.831091 read(10,  <unfinished ...>
[pid 512453] 07:21:38.031014 read(10,  <unfinished ...>
[pid 512489] 07:21:38.130933 read(10,  <unfinished ...>
[pid 512421] 07:21:38.231049 read(10,  <unfinished ...>
[pid 512419] 07:21:38.332719 read(10,  <unfinished ...>
[pid 512453] 07:21:38.629956 read(10,  <unfinished ...>
[pid 512421] 07:21:38.730425 read(10,  <unfinished ...>
[pid 512453] 07:21:38.835548 read(10,  <unfinished ...>
[pid 512489] 07:21:38.930689 read(10,  <unfinished ...>
[pid 512425] 07:21:38.931286 write(12, "\27\3\3\0M\305S\310\204\360\216J9\272!\334t\347\10,/\346/\10W\275'hP8U\213"..., 82) = 82
[pid 512453] 07:21:39.130540 read(10,  <unfinished ...>
[pid 512425] 07:21:39.230809 read(10,  <unfinished ...>
[pid 512425] 07:21:39.331019 read(10,  <unfinished ...>
[pid 512425] 07:21:39.331400 read(10,  <unfinished ...>
[pid 512425] 07:21:39.331802 read(10,  <unfinished ...>
[pid 512419] 07:21:39.411713 epoll_pwait(4, [], 128, 10, NULL, 0) = 0
[pid 512425] 07:21:39.530964 read(10,  <unfinished ...>
[pid 512418] 07:21:39.631178 read(10,  <unfinished ...>
[pid 512489] 07:21:39.730584 read(10,  <unfinished ...>
[pid 512419] 07:21:39.930811 read(10,  <unfinished ...>
[pid 512419] 07:21:40.031096 read(10, "\207\315\337\313\314/&\350h\17\n\356\240\316K(\23\350\343\357F\314\347\375\205'\365u*xo\245"..., 32892) = 32892
[pid 512419] 07:21:40.130839 read(10,  <unfinished ...>
[pid 512489] 07:21:40.330545 read(10, "u\2039\266\206u\342L\362nG,$\216\366\2267\276\324\313\372F\311\231Z\275\244\251\237H\20\""..., 32892) = 32892
[pid 512421] 07:21:40.430835 read(10,  <unfinished ...>
[pid 512425] 07:21:40.530528 read(10,  <unfinished ...>
[pid 512421] 07:21:40.633389 read(10,  <unfinished ...>
[pid 512425] 07:21:40.730685 read(10,  <unfinished ...>
[pid 512425] 07:21:40.830163 read(10,  <unfinished ...>
[pid 512425] 07:21:41.032377 read(10,  <unfinished ...>
[pid 512453] 07:21:41.130180 read(10,  <unfinished ...>
[pid 512489] 07:21:41.330739 read(10, "\23\313\263\334$e\vnK\256Q\226\241\246\227\307\206\360_\346$S\2535!\377\202\256c\267\243N"..., 32892) = 32892
[pid 512421] 07:21:41.429961 read(10,  <unfinished ...>
[pid 512421] 07:21:41.530656 read(10,  <unfinished ...>
[pid 512453] 07:21:41.630240 read(10,  <unfinished ...>
[pid 512421] 07:21:41.730763 read(10,  <unfinished ...>
[pid 512489] 07:21:41.831294 read(10,  <unfinished ...>
[pid 512419] 07:21:41.931201 read(10,  <unfinished ...>
[pid 512453] 07:21:42.130948 read(10,  <unfinished ...>
[pid 512419] 07:21:42.170043 epoll_pwait(4, [], 128, 10, NULL, 0) = 0
[pid 512421] 07:21:42.231301 read(10,  <unfinished ...>
[pid 512489] 07:21:42.430066 read(10, "\24\31\374\266\22S\326\0\327\212\272\374\234\350\313i\227j\371I\313=zg\1\247NO\237\25\366\242"..., 32892) = 32892
[pid 512419] 07:21:42.530344 read(10,  <unfinished ...>
[pid 512418] 07:21:42.630877 read(10,  <unfinished ...>
[pid 512421] 07:21:42.730965 read(10,  <unfinished ...>
[pid 512453] 07:21:42.830711 read(10, "\\\251z\32\2744\3341\234\rB\10\226\25u\274\265\4e]s\371\374\361\355\267[\2557\333p|"..., 32892) = 32892
[pid 512453] 07:21:43.030585 read(10,  <unfinished ...>
[pid 512489] 07:21:43.130684 read(10,  <unfinished ...>
[pid 512453] 07:21:43.230805 read(10,  <unfinished ...>
[pid 512453] 07:21:43.430513 read(10, "\23\375\301\ni\316\207\313\26jz F\267\t\237o\195\274\250\350\242\25\304jj\245\205\214\304"..., 32892) = 32892
[pid 512453] 07:21:43.530752 read(10,  <unfinished ...>
[pid 512425] 07:21:43.630543 read(10, "%\361N\324\313XU\337\225\335\324\357\333\327q7,{\t \245\t\7\0\324\342D\375\260l\323\360"..., 32892) = 32892
[pid 512453] 07:21:43.730619 read(10,  <unfinished ...>
[pid 512419] 07:21:43.831155 read(10,  <unfinished ...>
[pid 512419] 07:21:43.930726 read(10,  <unfinished ...>

This "100ms poll cycle" seems to be constant for quite some time (16 seconds here). Then it speeds up again at 07:22:00.630953:

[pid 512426] 07:21:58.830523 read(10,  <unfinished ...>
[pid 512426] 07:21:58.830638 read(10,  <unfinished ...>
[pid 512421] 07:21:58.930843 read(10,  <unfinished ...>
[pid 512453] 07:21:59.230244 read(10,  <unfinished ...>
[pid 512426] 07:21:59.330339 read(10,  <unfinished ...>
[pid 512421] 07:21:59.430210 read(10,  <unfinished ...>
[pid 512426] 07:21:59.530680 read(10,  <unfinished ...>
[pid 512421] 07:21:59.631143 read(10,  <unfinished ...>
[pid 512427] 07:21:59.730869 read(10,  <unfinished ...>
[pid 512427] 07:21:59.831186 read(10,  <unfinished ...>
[pid 512425] 07:22:00.030327 read(10,  <unfinished ...>
[pid 512427] 07:22:00.130300 read(10, "2\221\362\376\274tX\262\10\303\212\372\373\36)x\355\212\5\256[q\234\357`,\347~\301~~-"..., 32892) = 32892
[pid 512426] 07:22:00.230631 read(10,  <unfinished ...>
[pid 512453] 07:22:00.330389 read(10, "\256G\1?G*\244\242G\311`\251q\10\361\272\346\232K\247#\1\366\307\375\r5y\364\24\306'"..., 32892) = 32892
[pid 512453] 07:22:00.430484 read(10,  <unfinished ...>
[pid 512427] 07:22:00.630953 read(10,  <unfinished ...>
[pid 512427] 07:22:00.631134 read(10,  <unfinished ...>
[pid 512427] 07:22:00.631486 read(10,  <unfinished ...>
[pid 512427] 07:22:00.632002 read(10,  <unfinished ...>
[pid 512427] 07:22:00.632212 read(10,  <unfinished ...>
[pid 512427] 07:22:00.632488 read(10,  <unfinished ...>
[pid 512427] 07:22:00.632756 read(10,  <unfinished ...>
[pid 512427] 07:22:00.633144 read(10,  <unfinished ...>
[pid 512427] 07:22:00.633431 read(10,  <unfinished ...>
[pid 512427] 07:22:00.633702 read(10,  <unfinished ...>
[pid 512427] 07:22:00.634058 read(10,  <unfinished ...>
[pid 512427] 07:22:00.634291 read(10,  <unfinished ...>

I'll upload the video and full strace output and send you a link via chat so you can take a closer look.

Bye,
chris

6

Hi @mike.gorman,

Did you have time to look at the details? Is there anything else I can try / dig into to analyze this behavior?

Thanks & Bye,
chris

7

Hey Chris,

FYI, it was Thanksgiving yesterday so that will have delayed feedback. I am not sure if Mike is ooo today too.

Regards
Philip

8

Hey @PhilipGriffiths

thank's for the info! I wasn't aware of this :wink:
Have a good time!

Chris

9

The screenshots don't show me anything, but if you can post the actual packet traces somewhere for me to grab, I'd love to take a look. I'd also ask @plorenz to look at the strace information, as that isn't my area of expertise, and he might see something that I won't.

10

Hi @marvkis ,
When I'm trying to track down issues with the router code, the two things I usually look at are the router stackdumps and the circuit debug information. You can grab the router stack dumps in a couple of ways. If you're on the same machine, you can use the agent as follows:

ziti agent stack --app-type router

You could also grab them via the inspect mechanism, via the controller:

ziti fabric inspect stackdump <router-id>

To the grab the circuit information, you'll need the circuit id. The circuit id can be found either using ziti fabric list circuits or by streaming circuit events.

ziti fabric inspect circuit --include stacks <circuit id>

That command should return information from all routers about the current stack of that circuit. Mostly what we're looking for there is the state of the flow control, as that will help us figure out if something is back-pressured, causing the one side to pause reads, while it waits for the far side of the circuit to ack payloads.

If you can provide those, I'll take a look and see if I can spot anything problematic.

In addition, if you can share information about the test setup, I can try and reproduce it in a test environment here.

If I can provide more details, let me know.

Thank you,
Paul

11

Hi @plorenz ,

I think I've gathered the details you have asked for. I made a simple loop and generated several stack outputs over a period of time when the connection had a pending Recv-Q. I will PM you a link to the ZIP with all the details.

The setup:
It's a kubernetes based installation using the provided helm charts. My test env is:

  • The 'public' single node instance running the controller and the router (behind the nginx ingress via SNI routing - defaults from the helm charts).
  • An 'internal' (also single node) cluster running the ziti-edge-tunnel and hosting applications. I used nextcloud in my example, but it doesn't matter - I see the same for gitlab, s3 storage, repository servers. We just need a server to send a bunch of data pretty fast.
  • Both clusters run on the same physical machine using optimized network drivers. So the data gets to the router really fast.
  • The client is an OSX macbook running the tunneler.

I think even if everything is running on the same kubernetes 'cluster' (single node :wink: ), it should be possible to reproduce this behavior.

As a 'snapshot' I will attach the data from timecode 09:36:49, which was during a full Recv-Q. Only one circuit stack and had to omit the ziti agent stack --app-type router - I've reached the message post limit... You have everything on the PM :wink:

Thanks for taking a look! Thanks also to Mike!
Chris

===

Schreenshot from Video:

Bildschirmfoto 2023-11-28 um 11.00.44
Bildschirmfoto 2023-11-28 um 11.00.441506×1076 349 KB

The ziti fabric inspect circuit --include stacks output:

============================
Timestamp: 09:36:49.551:
============================
Results: (1)
PrN9ro.gay.circuitAndStacks:yWGeAjo1r
circuitId: yWGeAjo1r
forwards:
  jr0r: x5D7
  x5D7: jr0r
linkDetails: {}
xgressDetails:
  jr0r:
    address: jr0r
    flags: "10"
    goroutines:
    - "goroutine 28527 [select]:\ngithub.com/openziti/ziti/router/xgress.(*LinkSendBuffer).run(0xc00227e400)\n\tgithub.com/openziti/ziti/router/xgress/link_send_buffer.go:217
      +0x3ae\ncreated by github.com/openziti/ziti/router/xgress.NewLinkSendBuffer\n\tgithub.com/openziti/ziti/router/xgress/link_send_buffer.go:116
      +0x1f8\n\n"
    - "goroutine 29028 [select]:\ngithub.com/openziti/ziti/router/xgress.(*LinkSendBuffer).BufferPayload(0xc00227e400,
      0xc0011b8320)\n\tgithub.com/openziti/ziti/router/xgress/link_send_buffer.go:126
      +0x108\ngithub.com/openziti/ziti/router/xgress.(*Xgress).forwardPayload(0xc000ae81c0,
      0x7?)\n\tgithub.com/openziti/ziti/router/xgress/xgress.go:561 +0x48\ngithub.com/openziti/ziti/router/xgress.(*Xgress).rx(0xc000ae81c0)\n\tgithub.com/openziti/ziti/router/xgress/xgress.go:550
      +0x5bd\ncreated by github.com/openziti/ziti/router/xgress.(*Xgress).payloadIngester\n\tgithub.com/openziti/ziti/router/xgress/xgress.go:382
      +0x230\n\n"
    - "goroutine 28528 [select]:\ngithub.com/openziti/ziti/router/xgress.(*Xgress).nextPayload(...)\n\tgithub.com/openziti/ziti/router/xgress/xgress.go:416\ngithub.com/openziti/ziti/router/xgress.(*Xgress).tx(0xc000ae81c0)\n\tgithub.com/openziti/ziti/router/xgress/xgress.go:447
      +0x348\ncreated by github.com/openziti/ziti/router/xgress.(*Xgress).Start\n\tgithub.com/openziti/ziti/router/xgress/xgress.go:241
      +0x2bf\n\n"
    linkSendBufferPointer: "0xc00227e400"
    originator: Terminator
    recvBufferDetail:
      acquiredSafely: true
      lastSizeSent: 97
      maxSequence: 20
      nextPayload: none
      payloadCount: 0
      sequence: 20
      size: 0
    sendBufferDetail:
      accumulator: 367129
      acquiredSafely: true
      blockedByLocalWindow: true
      blockedByRemoteWindow: false
      closeWhenEmpty: false
      closed: false
      duplicateAcks: 14
      linkRecvBufferSize: 0
      linkSendBufferSize: 32785
      retransmits: 12
      retxScale: 1.5
      retxThreshold: 200
      successfulAcks: 25
      timeSinceLastRetx: 3ms
      windowSize: 16384
    sequence: 28
    timeSinceLastLinkRx: 778ms
    xgressPointer: "0xc000ae81c0"
  x5D7:
    address: x5D7
    flags: "0"
    goroutines:
    - "goroutine 29026 [select]:\ngithub.com/openziti/ziti/router/xgress_edge.(*baseMsgQ).Pop(0xc001eba1f8)\n\tgithub.com/openziti/ziti/router/xgress_edge/msg_queue.go:46
      +0x6b\ngithub.com/openziti/ziti/router/xgress_edge.(*edgeXgressConn).ReadPayload(0xc00227e000)\n\tgithub.com/openziti/ziti/router/xgress_edge/fabric.go:193
      +0x178\ngithub.com/openziti/ziti/router/xgress.(*Xgress).rx(0xc000ae82a0)\n\tgithub.com/openziti/ziti/router/xgress/xgress.go:519
      +0x3e4\ncreated by github.com/openziti/ziti/router/xgress.(*Xgress).Start\n\tgithub.com/openziti/ziti/router/xgress/xgress.go:239
      +0x27c\n\n"
    - "goroutine 28529 [select]:\ngithub.com/openziti/ziti/router/xgress.(*LinkSendBuffer).run(0xc00227e500)\n\tgithub.com/openziti/ziti/router/xgress/link_send_buffer.go:217
      +0x3ae\ncreated by github.com/openziti/ziti/router/xgress.NewLinkSendBuffer\n\tgithub.com/openziti/ziti/router/xgress/link_send_buffer.go:116
      +0x1f8\n\n"
    - "goroutine 29027 [select]:\ngithub.com/openziti/ziti/router/xgress.(*Xgress).nextPayload(...)\n\tgithub.com/openziti/ziti/router/xgress/xgress.go:416\ngithub.com/openziti/ziti/router/xgress.(*Xgress).tx(0xc000ae82a0)\n\tgithub.com/openziti/ziti/router/xgress/xgress.go:447
      +0x348\ncreated by github.com/openziti/ziti/router/xgress.(*Xgress).Start\n\tgithub.com/openziti/ziti/router/xgress/xgress.go:241
      +0x2bf\n\n"
    linkSendBufferPointer: "0xc00227e500"
    originator: Initiator
    recvBufferDetail:
      acquiredSafely: true
      lastSizeSent: 0
      maxSequence: 26
      nextPayload: none
      payloadCount: 0
      sequence: 26
      size: 0
    sendBufferDetail:
      accumulator: 3356
      acquiredSafely: true
      blockedByLocalWindow: false
      blockedByRemoteWindow: false
      closeWhenEmpty: false
      closed: false
      duplicateAcks: 0
      linkRecvBufferSize: 97
      linkSendBufferSize: 0
      retransmits: 0
      retxScale: 1.5
      retxThreshold: 200
      successfulAcks: 21
      timeSinceLastRetx: 1.438s
      windowSize: 16384
    sequence: 21
    timeSinceLastLinkRx: 102ms
    xgressPointer: "0xc000ae82a0"
12

Thank you, @marvkis , I'll take a look today.

Paul

13

Hi @marvkis , I've only done a quick look so far, but at the time you pointed me too, I can see that the sending side is blocked and it's not clear why. I'll dig into this more, but initial signs are pointing to it potentially being a fabric flow control issue.

Thank you,
Paul

14

Hi @plorenz,

I am glad to hear that you have discovered something. If you need any further information or want to test something, just let me know

Thanks,
Chris

15

Hi @marvkis , quick update, so you know what to expect: It's going to take me a few days to get to this, as I've got some other issues to tackle first. Currently looking at resolving issues with idle circuits.

My plan is to try and replicate this, so I can try some flow control tweaks. It's hard to say from the initial look if this is a a distributed state bug with the flow control or if the default flow control parameters just aren't optimized well for this use case. Either way, we're looking at adding a few different flow control profiles for different use cases, as we can try to improve the default, but nothing will likely ever be perfect for both short, bursty connections and longer lived throughput oriented connections. If there's also a general issue causing stalls we want to fix that first, of course.

Cheers,
Paul

16

Hi @plorenz ,

Thanks for the detailed update! If needed, I can help you set up a test environment to replicate the issue. I did some initial testing with OpenZiti about a year ago with similar use cases, but didn't see this behavior. So I tried older versions yesterday (down to 0.27.2), but they all showed the same behavior. Now I remember that in my initial tests I was using the proxy as a tunnel terminator for the connections to the services producing the huge data. Maybe that makes the difference. So initially it was svc <> router <> desktop tunneler, now it is svc <> linux tunneler <> router <> macos desktop tunneler. :thinking:

Thanks & Have a nice Weekend,
Chris

17

Hi @marvkis ,

That's really good to know. If you're up for it, I'd be curious if the same issues would arise with the edge-router/tunneler combo. If not, we'd know to focus our efforts on the linux tunneler, or at least how the linux tunneler was interacting with the fabric differently. If you're interested in setting that up and have any questions on the edge-router/tunneler, let me know. Either way I would like to be able to reproduce this locally, just add this scenario to the set of test scenarios we can bring up quickly :slight_smile: I'll likely ping you when I'm done with my current set of tasks to get some help with that.

Cheers,
Paul

18

Hi @plorenz,

I just had time to change the firewall rules to run the 'direct exit on the router' tests.
Since I had to use a different application accessible from the router, the results are not comparable to my other tests. So I ran two sets of tests - one directly through the router, and one through an additional Linux tunneler. I measured page reload times. The reload had 127 requests and transferred 12.34 MB. It seems that all 127 requests are being tunneled through the same (HTTP/2) TCP session, as I only see one active TCP session with the web server.

Times through the router: 8.8s / 8.3s / 7.8s / 8.7s / 7.4s
Times through the tunneler: 24s / 20.1s / 16.5s / 18.7s / 18.5s

As you can see, it takes less than half of the time through the router.

But still, having a lock on the Recv/Send queues, we see data on the Recv-Q on the connection to the service:

Bildschirmfoto 2023-12-03 um 15.04.19
Bildschirmfoto 2023-12-03 um 15.04.191560×386 209 KB

But on the other side it seems that there is nothing queued on the 'outgoing' side to the client - all Send-Q's are 'empty'.

Cheers,
Chris

19

Hi.
I just re-ran the ziti agent stack and ziti fabric inspect circuit log sequences again and updated the collected data. (link via PM). Starting with 14-43-03.365 the Recv-Q is filled again.

Bye,
Chris

20

Hi @plorenz ,

I am currently trying to set up a private router as shown in this diagram Create private router on linux machine - #8 by aepurvis to have an additional router on my internal instance for terminating services.

I am having trouble to getting this to work. I've set up the internal router and it connects to the controller, and I'm also able to bind a service to it and I also see the service bound to the tunneler as a 'terminating router'.
But it doesn't work. When I try to connect the service, my 'public router' logs:

ziti-router [317653.895] WARNING edge/router/xgress_edge.(*edgeClientConn).processConnect [ch{edge}->u{classic}->i{YXBe}]: {connId=[157] type=[EdgeConnectType] error=[can't route from PrN9ro.gay ->
nSFesiP-6] chSeq=[390] edgeSeq=[0] token=[b2c90b0f-ce48-4b48-8b1a-8d573717e7f1]} failed to dial fabric

It appears to me that the 'fabric link' between the private and public routes is not established. In the private router, I only see the outgoing connection to the controller/API, but no connection to the public router.

This is the config snipplet from the public router:

    link:
      dialers:
        - binding: transport
      listeners:
        - binding:          transport
          bind:             tls:0.0.0.0:10080
          advertise:        tls:<transport-name>:443
          options:
            outQueueSize:   4
    listeners:
         [...]

And I'm able to connect to 'transport-name' from my private router.

On the private router, the config just has transport configured as dial:

    link:
      dialers:
        - binding: transport
    listeners:
      - binding: edge
        address: tls:0.0.0.0:3022
        options:
            advertise: edge.internal.domain:443
            connectTimeoutMs: 1000
            getSessionTimeout: 60
      - binding: tunnel
        options:
            mode: host

But I don't see the private router connecting to the public router. I think this is causing the error message.

This is the log from the int router:

[   0.003]    INFO ziti/ziti/router.run: {revision=[5237e2b4794a] configFile=[/etc/ziti/config/ziti-router.yaml] version=[v0.31.0] go-version=[go1.20.10] routerId=[nSFesiP-6] os=[linux] arch=[amd64]
 build-date=[2023-11-01T17:56:17Z]} starting ziti-router
[   0.003]    INFO ziti/common/metrics.GoroutinesPoolMetricsConfigF.func1.1: {idleTime=[30s] poolType=[pool.link.dialer] maxQueueSize=[1000] minWorkers=[0] maxWorkers=[32]} starting goroutine pool
[   0.003]    INFO ziti/common/metrics.GoroutinesPoolMetricsConfigF.func1.1: {maxWorkers=[128] idleTime=[30s] maxQueueSize=[1000] poolType=[pool.route.handler] minWorkers=[0]} starting goroutine poo
l
[   0.004]    INFO ziti/router/forwarder.(*Faulter).run: started
[   0.004]    INFO ziti/router/forwarder.(*Scanner).run: started
[   0.004] WARNING ziti/router/internal/edgerouter.(*Config).LoadConfigFromMap: Invalid heartbeat interval [0] (min: 60, max: 10), setting to default [60]
[   0.004] WARNING ziti/router/internal/edgerouter.parseEdgeListenerOptions: port in [listeners[0].options.advertise] must equal port in [listeners[0].address] for edge binding but did not. Got [443
] [3022]
[   0.004]   ERROR ziti/ziti/router.run: {error=[remove /tmp/gops-agent.1.sock: read-only file system]} unable to start CLI agent
[   0.004]    INFO ziti/router.(*Router).showOptions: ctrl = {"OutQueueSize":4,"MaxQueuedConnects":1,"MaxOutstandingConnects":16,"ConnectTimeout":5000000000,"DelayRxStart":false,"WriteTimeout":0}
[   0.004]    INFO ziti/router.(*Router).showOptions: metrics = {"ReportInterval":60000000000,"IntervalAgeThreshold":0,"MessageQueueSize":10}
[   0.004]    INFO ziti/common/metrics.GoroutinesPoolMetricsConfigF.func1.1: {maxWorkers=[32] idleTime=[30s] maxQueueSize=[5000] minWorkers=[0] poolType=[pool.link.dialer]} starting goroutine pool
[   0.004]    INFO ziti/router.(*Router).initializeHealthChecks: starting health check with ctrl ping initially after 15s, then every 30s, timing out after 15s
[   0.004]    INFO ziti/router.(*Router).startXlinkDialers: started Xlink dialer with binding [transport]
[   0.004]    INFO ziti/router/xgress_edge.(*listener).Listen: {address=[tls:0.0.0.0:3022]} starting channel listener
[   0.004]    INFO ziti/common/metrics.GoroutinesPoolMetricsConfigF.func1.1: {maxWorkers=[16] poolType=[pool.listener.xgress_edge] idleTime=[10s] maxQueueSize=[1] minWorkers=[1]} starting goroutine
pool
[   0.005]    INFO ziti/router.(*Router).startXgressListeners: created xgress listener [edge] at [tls:0.0.0.0:3022]
[   0.005]    INFO ziti/router.(*Router).startXgressListeners: created xgress listener [tunnel] at []
[   0.005]    INFO ziti/router.(*Router).getInitialCtrlEndpoints: controller endpoints file [/etc/ziti/config/endpoints] doesn't exist. Using initial endpoints from config
[   0.005]    INFO ziti/router.(*Router).startControlPlane: router configured with 1 controller endpoints
[   0.005]    INFO ziti/router/xgress_edge.(*Acceptor).Run: starting
[   0.005]    INFO ziti/router/env.(*networkControllers).UpdateControllerEndpoints: {endpoint=[map[tls:control.my-domain-mask:443:{}]]} adding new ctrl endpoint
[   0.005]    INFO ziti/router/env.(*networkControllers).connectToControllerWithBackoff: {endpoint=[tls:control.my-domain-mask:443]} starting connection attempts
[   0.063]    INFO ziti/router/env.(*networkControllers).connectToControllerWithBackoff.func3: {endpoint=[tls:control.my-domain-mask:443]} successfully connected to controller
[   0.064]    INFO ziti/router/handler_edge_ctrl.(*helloHandler).HandleReceive.func1: received server hello, replying
[   0.064]    INFO ziti/router/fabric.(*StateManagerImpl).AddSignerPublicCert: {added=[1] ignored=[0] received=[1]} received signer public certificates
[   0.065]    INFO ziti/router/handler_ctrl.(*validateTerminatorsHandler).validateTerminators: removing invalid terminator 1MR3S3zxyoN2gMd0n9M4Y4 with binding: edge. had dialer? true
[   0.065]    INFO ziti/router/handler_ctrl.(*validateTerminatorsHandler).validateTerminators: removing invalid terminator 2VgQ8yK4Wle2HZ7szmjeZr with binding: edge. had dialer? true
[   0.065]    INFO ziti/router/handler_ctrl.(*validateTerminatorsHandler).validateTerminators: removing invalid terminator 2rlx3ziLFtBslvPI1UBPSk with binding: edge. had dialer? true
[   0.065]    INFO ziti/router/handler_ctrl.(*validateTerminatorsHandler).validateTerminators: removing invalid terminator 2zvJVtvhVcJ4gYe8Qv3Vwq with binding: edge. had dialer? true
[   0.065]    INFO ziti/router/handler_ctrl.(*validateTerminatorsHandler).validateTerminators: removing invalid terminator 31SdzbM3eMof6Jv94wTavP with binding: edge. had dialer? true
[   0.066]    INFO ziti/router/handler_ctrl.(*validateTerminatorsHandler).validateTerminators: removing invalid terminator 3n0qi10AnF4riQfHRD0BBi with binding: edge. had dialer? true
[   0.066]    INFO ziti/router/handler_ctrl.(*validateTerminatorsHandler).validateTerminators: removing invalid terminator 460ed460-0a0e-4a92-b396-f897edc22f54 with binding: tunnel. had dialer? true
[   0.066]    INFO ziti/router/handler_ctrl.(*validateTerminatorsHandler).validateTerminators: removing invalid terminator 5tgYjiguTRslCzy019lcpj with binding: edge. had dialer? true
[   0.066]    INFO ziti/router/handler_ctrl.(*validateTerminatorsHandler).validateTerminators: removing invalid terminator 6w4RvIQIwTcIrqe78ZBLDX with binding: edge. had dialer? true
[   0.066]    INFO ziti/router/handler_ctrl.(*validateTerminatorsHandler).validateTerminators: removing invalid terminator 6z9wrdaziMDMmR1o5YWpXf with binding: edge. had dialer? true
[   0.066]    INFO ziti/router/handler_ctrl.(*validateTerminatorsHandler).validateTerminators: removing invalid terminator 7auKwrsVN3hShkxqH8fFDW with binding: edge. had dialer? true
[   0.066]    INFO ziti/router/handler_ctrl.(*validateTerminatorsHandler).validateTerminators: send batch of 11 terminator deletes
[   0.067]    INFO ziti/router/handler_edge_ctrl.(*apiSessionAddedHandler).instantSync: {strategy=[instant]} first api session syncId [clpqskv7hbda50dg47z2h4ntl], starting
[   0.067]    INFO ziti/router/handler_edge_ctrl.(*apiSessionSyncTracker).Add: received api session sync chunk 0, isLast=true
[   0.077]    INFO ziti/router/fabric.(*StateManagerImpl).StartHeartbeat: heartbeat starting
[   0.078]    INFO ziti/router/xgress_edge_tunnel.(*tunneler).Start: {mode=[host]} creating interceptor
[   0.078]    INFO ziti/router/xgress_edge.(*CertExpirationChecker).Run: waiting 8602h42m0.181410693s to renew certificates
[   0.078] WARNING ziti/tunnel/dns.flushDnsCaches: {error=[exec: "resolvectl": executable file not found in $PATH]} unable to find systemd-resolve or resolvectl in path, consider adding a dns flush
to your restart process
[   0.787]    INFO ziti/tunnel/intercept.SetDnsInterceptIpRange: dns intercept IP range: 100.64.0.1 - 100.127.255.254
[   0.789]    INFO ziti/tunnel/intercept.(*ServiceListener).HandleServicesChange: {service=[iac-int-kube-1.sys.hzr-core-service_80,443_t-2]} adding service
[   0.789]    INFO ziti/tunnel/intercept.(*ServiceListener).addService: {serviceId=[ytM1692EdaOJZurZ2G19P] serviceName=[iac-int-kube-1.sys.hzr-core-service_80,443_t-2]} Hosting newly available servi
ce
[   0.789]    INFO ziti/router/xgress_edge_tunnel.(*fabricProvider).establishTerminatorWithRetry.func1: {service=[iac-int-kube-1.sys.hzr-core-service_80,443_t-2]} attempting to establish terminator
[   0.791]    INFO ziti/router/xgress_edge_tunnel.(*fabricProvider).HandleTunnelResponse: {routerId=[nSFesiP-6] terminatorId=[ebdb6d7d-3ca5-4bd0-aed3-8dd15c907f7c] sessionId=[clpqlve2jb4kn0dg4oakgmh
gy]} received new session
[   0.791]    INFO ziti/router/xgress_edge_tunnel.(*fabricProvider).HandleTunnelResponse: {routerId=[nSFesiP-6] terminatorId=[ebdb6d7d-3ca5-4bd0-aed3-8dd15c907f7c] createDuration=[2.976156ms]} recei
ved terminator created notification
[   1.068]    INFO ziti/router/handler_edge_ctrl.(*apiSessionAddedHandler).applySync: finished sychronizing api sessions [count: 8, syncId: clpqskv7hbda50dg47z2h4ntl, duration: 170.177µs]

What am I missing? Can you point me on something I might look into?

Thanks & Bye,
Chris