Page MenuHomePhabricator
Create Task
Maniphest T346402

beta/deployment-prep Kafka clusters do not support TLS client connections
Closed, ResolvedPublic
Actions

Description

I needed to debug something using beta logstash. I opened the default view, and immediately noticed that logstash is being flooded with kafka-related errors, most of which are KAFKADR: Kafka message delivery error: Local: Message timed out.

Other error messages also mention kafka, but it looks like they're being truncated or something. To give an idea of the numbers, there's a total of 1 018 750 events for today between 00:00 and 22:00, and according to my quick eyeballing, it looks like around 650k are kafka errors.

I've absolutely no idea what's causing this, or what impact it might have.

See comments below: the cause is that clients are trying to connect via TLS, but TLS is not enabled on deployment-prep kafka clusters.

Clients should likely be configured to use non-TLS connection port 9092.

Related Objects

Event Timeline

Daimona created this task.Sep 14 2023, 9:53 PM
Restricted Application added a subscriber: Aklapper. · View Herald TranscriptSep 14 2023, 9:53 PM
colewhite edited projects, added: Data-Engineering; removed: Observability-Logging.EditedSep 14 2023, 10:16 PM
colewhite subscribed.

It appears there is some problem with the kafka-jumbo nodes in deployment prep.

kafka.errors.NoBrokersAvailable: NoBrokersAvailable

Logstash appears functional. Adding Data Engineering for the kafka-jumbo nodes.

colewhite renamed this task from Beta logstash filled with kafka errors to Many kafka errors in beta/deployment-prep.Sep 14 2023, 10:17 PM
BTullis subscribed.Sep 15 2023, 8:51 AM

I've had a quick look at this too. It strikes me that it's affecting both kafka-main and kafka-jumbo nodes.

If I ssh into deployment-webperf21.deployment-prep.eqiad1.wikimedia.cloud and then just tail the syslog, we can see both clusters mentioned.
e.g.

ep 15 08:41:51 deployment-webperf21 python3[1830032]: 2023-09-15 08:41:51,126 <BrokerConnection node_id=bootstrap-1 host=deployment-kafka-main-5.deployment-prep.eqiad1.wikimedia.cloud:9093 <connecting> [IPv4 ('172.16.4.112', 9093)]>: connecting to deployment-kafka-main-5.deployment-prep.eqiad1.wikimedia.cloud:9093 [('172.16.4.112', 9093) IPv4]
Sep 15 08:41:51 deployment-webperf21 python3[1830032]: 2023-09-15 08:41:51,126 Probing node bootstrap-1 broker version
Sep 15 08:41:52 deployment-webperf21 navtiming[1346452]: 2023-09-15 08:41:52,954 [ERROR] (get_kafka_iterator:1040) Unhandled exception in main loop, restarting consumer

Sep 15 08:41:48 deployment-webperf21 navtiming[1346452]: 2023-09-15 08:41:48,929 [INFO] (get_kafka_iterator:986) Starting Kafka connection to brokers (('deployment-kafka-jumbo-5.deployment-prep.eqiad1.wikimedia.cloud:9093', 'deployment-kafka-jumbo-8.deployment-prep.eqiad1.wikimedia.cloud:9093', 'deployment-kafka-jumbo-9.deployment-prep.eqiad1.wikimedia.cloud:9093'))

I checked the same on deployment-webperf22.deployment-prep.eqiad1.wikimedia.cloud and although this doesn't have the kafka error messages, it does have some redis connection errors.

Sep 15 08:43:52 deployment-webperf22 arclamp-log.py[4146001]: Traceback (most recent call last):
Sep 15 08:43:52 deployment-webperf22 arclamp-log.py[4146001]:   File "/usr/lib/python3/dist-packages/redis/connection.py", line 559, in connect
Sep 15 08:43:52 deployment-webperf22 arclamp-log.py[4146001]:     sock = self._connect()
Sep 15 08:43:52 deployment-webperf22 arclamp-log.py[4146001]:   File "/usr/lib/python3/dist-packages/redis/connection.py", line 615, in _connect
Sep 15 08:43:52 deployment-webperf22 arclamp-log.py[4146001]:     raise err
Sep 15 08:43:52 deployment-webperf22 arclamp-log.py[4146001]:   File "/usr/lib/python3/dist-packages/redis/connection.py", line 603, in _connect
Sep 15 08:43:52 deployment-webperf22 arclamp-log.py[4146001]:     sock.connect(socket_address)
Sep 15 08:43:52 deployment-webperf22 arclamp-log.py[4146001]: TimeoutError: [Errno 110] Connection timed out

I'm not familiar enough with deployment-prep yet to know whether this is normal, or what this indicates though.

Looking at the syslog on deployment-kafka-jumbo-8, we can see a lot of dropped packets for port 9093.
e.g.

Sep 15 08:48:17 deployment-kafka-jumbo-8 ulogd[14039]: [fw-in-drop] IN=eth0 OUT= MAC=fa:16:3e:d9:bb:c0:fa:16:3e:14:2e:70:08:00 SRC=172.16.6.76 DST=172.16.5.49 LEN=60 TOS=00 PREC=0x00 TTL=64 ID=18053 DF PROTO=TCP SPT=50084 DPT=9093 SEQ=2253946226 ACK=0 WINDOW=42340 SYN URGP=0 MARK=0 
Sep 15 08:48:18 deployment-kafka-jumbo-8 ulogd[14039]: [fw-in-drop] IN=eth0 OUT= MAC=fa:16:3e:d9:bb:c0:fa:16:3e:14:2e:70:08:00 SRC=172.16.6.76 DST=172.16.5.49 LEN=60 TOS=00 PREC=0x00 TTL=64 ID=18054 DF PROTO=TCP SPT=50084 DPT=9093 SEQ=2253946226 ACK=0 WINDOW=42340 SYN URGP=0 MARK=0 
Sep 15 08:48:18 deployment-kafka-jumbo-8 ulogd[14039]: [fw-in-drop] IN=eth0 OUT= MAC=fa:16:3e:d9:bb:c0:fa:16:3e:71:67:c9:08:00 SRC=172.16.3.164 DST=172.16.5.49 LEN=60 TOS=00 PREC=0x00 TTL=64 ID=52961 DF PROTO=TCP SPT=34596 DPT=9093 SEQ=3777255837 ACK=0 WINDOW=42340 SYN URGP=0 MARK=0 
Sep 15 08:48:20 deployment-kafka-jumbo-8 ulogd[14039]: [fw-in-drop] IN=eth0 OUT= MAC=fa:16:3e:d9:bb:c0:fa:16:3e:71:67:c9:08:00 SRC=172.16.3.164 DST=172.16.5.49 LEN=60 TOS=00 PREC=0x00 TTL=64 ID=52962 DF PROTO=TCP SPT=34596 DPT=9093 SEQ=3777255837 ACK=0 WINDOW=42340 SYN URGP=0 MARK=0 
Sep 15 08:48:22 deployment-kafka-jumbo-8 ulogd[14039]: [fw-in-drop] IN=eth0 OUT= MAC=fa:16:3e:d9:bb:c0:fa:16:3e:71:67:c9:08:00 SRC=172.16.3.164 DST=172.16.5.49 LEN=60 TOS=00 PREC=0x00 TTL=64 ID=52963 DF PROTO=TCP SPT=34596 DPT=9093 SEQ=3777255837 ACK=0 WINDOW=42340 SYN URGP=0 MARK=0 
Sep 15 08:48:27 deployment-kafka-jumbo-8 ulogd[14039]: [fw-in-drop] IN=eth0 OUT= MAC=fa:16:3e:d9:bb:c0:fa:16:3e:71:67:c9:08:00 SRC=172.16.3.164 DST=172.16.5.49 LEN=60 TOS=00 PREC=0x00 TTL=64 ID=52964 DF PROTO=TCP SPT=34596 DPT=9093 SEQ=3777255837 ACK=0 WINDOW=42340 SYN URGP=0 MARK=0

The two hosts mentioned there are:

root@deployment-kafka-jumbo-8:/etc/ferm/conf.d# host 172.16.3.164
164.3.16.172.in-addr.arpa domain name pointer deployment-cache-text08.deployment-prep.eqiad1.wikimedia.cloud.
root@deployment-kafka-jumbo-8:/etc/ferm/conf.d# host 172.16.6.76 
76.6.16.172.in-addr.arpa domain name pointer deployment-webperf21.deployment-prep.eqiad1.wikimedia.cloud.

...so this fits and suggests that it's some kind of change to the ferm rules on these hosts that has caused this problem.

BTullis added a comment.Sep 15 2023, 8:59 AM

However, it seems that this has been happening for more than two weeks, which is all of the data we have in beta-logs.

image.png (1,915×805 px, 148 KB)

So if there has been a change that affected this behaviour, it was longer ago than two weeks.
Do we know of any regular users of beta-logs, who might be able to tell us when this kafka setup (and redis setup?) was definitely working?

BTullis added a comment.Sep 15 2023, 9:36 AM

I think I have found out what is causing this:

The three tools: navtiming::statsv, coal::processor and navtiming::webperf tools are configured always to use TLS, (since this change, I believe) but neither the kafka-main nor kafka-jumbo clusters in deployment-prep have TLS enabled.

(n.b. The kafka-logging cluster does have TLS enabled and rsyslog is configured to use it.)

kafka-jumbo and kafka-main brokers are only listening on port 9092 and only have ferm rules related to this port.

btullis@deployment-kafka-main-5:~$ grep listen /etc/kafka/server.properties
listeners=PLAINTEXT://:9092

Here are the startup scripts for these three tools.

image.png (1,911×206 px, 86 KB)

So it would seem that we have three options:

  • Enable TLS for the kafka-main and kafka-jumbo clusters in deployment-prep
  • Disable TLS for the webperf::processors in deployment-prep
  • Exclude the webperf::processors from deployment-prep
• lbowmaker moved this task from Incoming (new tickets) to Tag with Radar on the Data-Engineering board.Feb 16 2024, 8:58 PM
• VirginiaPoundstone added a project: Data-Engineering-Radar.Jan 6 2025, 9:12 PM
Peter mentioned this in T341176: NoBrokersAvailable for navtiming.py on beta.Mar 19 2025, 8:05 AM
Peter subscribed.
Peter mentioned this in T391273: navtiming: Loss of Kafka connection fills multiple log files with identical stack traces.Apr 9 2025, 12:23 PM
Ottomata renamed this task from Many kafka errors in beta/deployment-prep to beta/deployment-prep Kafka clusters do not support TLS client connections.Apr 9 2025, 3:19 PM
Ottomata updated the task description. (Show Details)
• bd808 added subscribers: elukey, • bd808.Apr 9 2025, 11:50 PM

I think the TLS listener problems were fixed by @elukey in T383096: Multiple kafka Cergen certs expired in beta cluster.

bd808@deployment-kafka-main-6:~$ sudo netstat -tunlp | grep 9092
tcp6       0      0 :::9092                 :::*                    LISTEN      533/java
bd808@deployment-kafka-main-6:~$ sudo netstat -tunlp | grep 9093
tcp6       0      0 :::9093                 :::*                    LISTEN      533/java
• bd808 closed this task as Resolved.Apr 9 2025, 11:57 PM
• bd808 assigned this task to elukey.

I'm giving @elukey credit for this no longer being an active issue. There are only ~300 "Kafka message delivery error" logs in the index at beta-logs.wmcloud.org. They all happened in the same minute on 2025-04-03 when deployment-cache-text08 had timeouts talking to its broker.

Content licensed under Creative Commons Attribution-ShareAlike (CC BY-SA) 4.0 unless otherwise noted; code licensed under GNU General Public License (GPL) 2.0 or later and other open source licenses. By using this site, you agree to the Terms of Use, Privacy Policy, and Code of Conduct. · Wikimedia Foundation · Privacy Policy · Code of Conduct · Terms of Use · Disclaimer · CC-BY-SA · GPL · Credits