This bug has been migrated to another issue tracking site. It has been closed here and may no longer be being monitored.

If you would like to get updates for this issue, or to participate in it, you may do so at Red Hat Issue Tracker .
RHEL Engineering is moving the tracking of its product development work on RHEL 6 through RHEL 9 to Red Hat Jira (issues.redhat.com). If you're a Red Hat customer, please continue to file support cases via the Red Hat customer portal. If you're not, please head to the "RHEL project" in Red Hat Jira and file new tickets here. Individual Bugzilla bugs in the statuses "NEW", "ASSIGNED", and "POST" are being migrated throughout September 2023. Bugs of Red Hat partners with an assigned Engineering Partner Manager (EPM) are migrated in late September as per pre-agreed dates. Bugs against components "kernel", "kernel-rt", and "kpatch" are only migrated if still in "NEW" or "ASSIGNED". If you cannot log in to RH Jira, please consult article #7032570. That failing, please send an e-mail to the RH Jira admins at rh-issues@redhat.com to troubleshoot your issue as a user management inquiry. The email creates a ServiceNow ticket with Red Hat. Individual Bugzilla bugs that are migrated will be moved to status "CLOSED", resolution "MIGRATED", and set with "MigratedToJIRA" in "Keywords". The link to the successor Jira issue will be found under "Links", have a little "two-footprint" icon next to it, and direct you to the "RHEL project" in Red Hat Jira (issue links are of type "https://issues.redhat.com/browse/RHEL-XXXX", where "X" is a digit). This same link will be available in a blue banner at the top of the page informing you that that bug has been migrated.
Bug 2188545 - dnsmasq does not forward all of the received queries although it does in previous versions.
Summary: dnsmasq does not forward all of the received queries although it does in prev...
Keywords:
Status: CLOSED MIGRATED
Alias: None
Product: Red Hat Enterprise Linux 8
Classification: Red Hat
Component: dnsmasq
Version: 8.6
Hardware: Unspecified
OS: Linux
medium
medium
Target Milestone: rc
: ---
Assignee: Petr Menšík
QA Contact: rhel-cs-infra-services-qe
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2023-04-21 06:25 UTC by rynakamu
Modified: 2023-09-21 19:07 UTC (History)
2 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2023-09-21 19:07:11 UTC
Type: Bug
Target Upstream Version:
Embargoed:
pm-rhel: mirror+


Attachments (Terms of Use)
python script to emulate packet drops (1.16 KB, text/x-python3)
2023-05-04 18:35 UTC, Petr Menšík
no flags Details


Links
System ID Private Priority Status Summary Last Updated
Red Hat Issue Tracker   RHEL-6586 0 None Migrated None 2023-09-21 19:06:05 UTC
Red Hat Issue Tracker RHELPLAN-155359 0 None None None 2023-04-21 06:27:02 UTC

Description rynakamu 2023-04-21 06:25:54 UTC
Description of problem:
dnsmasq does not forward all of the received queries although it does in previous versions.

When dnsmasq received the same queries in a short period of time, some of the queries were not forwarded to outside nameservers.
In the reproducer below, if we execute the dig command five times then 30 queries are sent to dnsmasq as per /etc/resolv.conf.
According to dnsmasq.log and the result of strace, dnsmasq received 30 queries as expected.
But dnsmasq missed to forward 4 queries as per tcpdump and strace.


Version-Release number of selected component (if applicable):
- dnsmasq-2.79-24.el8_7.1.x86_64 (The latest of RHEL8)
- dnsmasq-2.79-24.el8.x86_64
- dnsmasq-2.79-24.el8.aarch64


How reproducible:
Setup dnsmasq with below configuration and execute multiple dig commands.


Steps to Reproduce:
1. Start dnsmasq with below settings

  # cat /etc/dnsmasq.conf
  ~~~
  domain-needed
  bogus-priv
  interface=lo
  bind-interfaces
  listen-address=127.0.0.1
  cache-size=1000
  resolv-file=/etc/resolv.dnsmasq
  no-poll
  ## Can append below two parameters to log host queries
  log-queries
  log-facility=/var/log/dnsmasq.log
  ~~~

  # cat /etc/resolv.conf 
  ~~~
  # Generated by NetworkManager
  nameserver 127.0.0.1
  search ap-northeast-1.compute.internal
  options timeout:2 attempts:5
  ~~~

Note that the nameserver 192.168.122.39 is non-existent DNS server.
Hence dig commands in the next step are expected to be timed out.

  # cat /etc/resolv.dnsmasq 
  ~~~
  nameserver 192.168.122.39
  ~~~

  # systemctl start dnsmasq

2. Execute the dig command 5 times continuously in a short period of time.

  ~~~
  [root@rhel7u9-3 ~]# dig google.com &
  [2] 22689
  [root@rhel7u9-3 ~]# dig google.com &
  [3] 22693
  [root@rhel7u9-3 ~]# dig google.com &
  [4] 22697
  [root@rhel7u9-3 ~]# dig google.com &
  [5] 22701
  [root@rhel7u9-3 ~]# dig google.com &
  [6] 22705
  ~~~

Actual results:
## Note
We set tcpdump and attach strace to dnsmasq before step2 for investigation purpose.
  # tcpdump -nn port 53
  # strace -ttTvfyyx -s 2048 -o /tmp/dnsmasq.strace -p <PID> &
It is not required to reproduce the issue.
##

dnsmasq received 30 queries but forwarded only 26 queries.

As per tcpdump:
~~~
[root@rhel8u4 ~]# tcpdump -nn port 53
dropped privs to tcpdump
tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
listening on enp1s0, link-type EN10MB (Ethernet), capture size 262144 bytes
02:05:34.053295 IP 192.168.122.244.31032 > 192.168.122.39.53: 5020+ [1au] A? google.com. (51)
02:05:36.055429 IP 192.168.122.244.31032 > 192.168.122.39.53: 5020+ [1au] A? google.com. (51)
02:05:36.693097 IP 192.168.122.244.31032 > 192.168.122.39.53: 5020+ [1au] A? google.com. (51)
02:05:37.251990 IP 192.168.122.244.31032 > 192.168.122.39.53: 5020+ [1au] A? google.com. (51)
02:05:37.809456 IP 192.168.122.244.31032 > 192.168.122.39.53: 5020+ [1au] A? google.com. (51)
02:05:38.052601 IP 192.168.122.244.31032 > 192.168.122.39.53: 5020+ [1au] A? google.com. (51)
02:05:38.355890 IP 192.168.122.244.31032 > 192.168.122.39.53: 5020+ [1au] A? google.com. (51)
02:05:38.693503 IP 192.168.122.244.31032 > 192.168.122.39.53: 5020+ [1au] A? google.com. (51)
02:05:39.252428 IP 192.168.122.244.31032 > 192.168.122.39.53: 5020+ [1au] A? google.com. (51)
02:05:39.809996 IP 192.168.122.244.31032 > 192.168.122.39.53: 5020+ [1au] A? google.com. (51)
02:05:40.053837 IP 192.168.122.244.31032 > 192.168.122.39.53: 5020+ [1au] A? google.com. (51)
02:05:40.357148 IP 192.168.122.244.31032 > 192.168.122.39.53: 5020+ [1au] A? google.com. (51)
02:05:40.693653 IP 192.168.122.244.31032 > 192.168.122.39.53: 5020+ [1au] A? google.com. (51)
02:05:41.251730 IP 192.168.122.244.31032 > 192.168.122.39.53: 5020+ [1au] A? google.com. (51)
02:05:41.810211 IP 192.168.122.244.31032 > 192.168.122.39.53: 5020+ [1au] A? google.com. (51)
02:05:42.054093 IP 192.168.122.244.31032 > 192.168.122.39.53: 5020+ [1au] A? google.com. (51)
02:05:42.356754 IP 192.168.122.244.31032 > 192.168.122.39.53: 5020+ [1au] A? google.com. (51)
02:05:42.693896 IP 192.168.122.244.31032 > 192.168.122.39.53: 5020+ [1au] A? google.com. (51)
02:05:43.251842 IP 192.168.122.244.31032 > 192.168.122.39.53: 5020+ [1au] A? google.com. (51)
02:05:43.810632 IP 192.168.122.244.31032 > 192.168.122.39.53: 5020+ [1au] A? google.com. (51)
02:05:44.054270 IP 192.168.122.244.31032 > 192.168.122.39.53: 5020+ [1au] A? google.com. (51)
02:05:44.357849 IP 192.168.122.244.31032 > 192.168.122.39.53: 5020+ [1au] A? google.com. (51)
02:05:44.693101 IP 192.168.122.244.31032 > 192.168.122.39.53: 5020+ [1au] A? google.com. (51)
02:05:45.253189 IP 192.168.122.244.31032 > 192.168.122.39.53: 5020+ [1au] A? google.com. (51)
02:05:45.810437 IP 192.168.122.244.31032 > 192.168.122.39.53: 5020+ [1au] A? google.com. (51)
02:05:46.358110 IP 192.168.122.244.31032 > 192.168.122.39.53: 5020+ [1au] A? google.com. (51)
^C
26 packets captured
26 packets received by filter
0 packets dropped by kernel
~~~

As per strace:
~~~
[root@rhel8u4 ~]# grep recvmsg /tmp/dnsmasq.strace | wc -l
30
[root@rhel8u4 ~]# 
[root@rhel8u4 ~]# grep sendto /tmp/dnsmasq.strace | wc -l
26
[root@rhel8u4 ~]# 
~~~


Expected results:
dnsmasq should forward all of received queries(30 queries should be forward in above case).


Additional info:
We checked several versions of dnsmasq in RHEL8 and RHEL7 with the exact same configuration and testing procedure and confirmed them below.
Details can be seen in the support case 03454752.

RHEL8
dnsmasq-2.79-13.el8_3.1 : Reproduced
dnsmasq-2.79-13.el8     : Not reproduced (which means dnsmasq forwarded all of 30 queries)
dnsmasq-2.79-4.el8      : Not reproduced (the oldest version of RHEL8) 

RHEL7
dnsmasq-2.76-17.el7_9.3 : Not reproduced (the latest of RHEL7)
dnsmasq-2.76-16.el7_9.1 : Reproduced

Best Regards,
Ryo Nakamura.

Comment 2 Petr Menšík 2023-04-21 17:02:12 UTC
That behaviour is quite intentional and is not an error. dnsmasq is a dns cache. It joins intentionally outgoing request received in parallel, until the server responds. Even without using a cache. The same answer is then forwarded to all joined clients. That is not going to change. That were introduced as a fix of vulnerability, do not have exact id at hand. The slower answer of upstream servers is, the more often this happens.

Lower count of forwarded queries than received is okay. The only problem would be if any of clients did not receive a proper reply in such case. Unless that is the case, I would close this as not a bug.

Is there any specific reason, why do you want to ensure outgoing query number matches? Is there another issue being tracked down?

Comment 3 Flos Qi Guo 2023-04-23 08:04:08 UTC
Hello Petr,

Thanks for your reply. In fact I also try to simulate the issue on Fedora 38 with the following packages:
---------------8< ---------------8< ---------------8< ---------------8< ---------------
# rpm -q dnsmasq bind-utils systemd kernel
dnsmasq-2.89-2.fc38.x86_64
bind-utils-9.18.13-1.fc38.x86_64
systemd-253.2-1.fc38.x86_64
kernel-6.2.9-300.fc38.x86_64
---------------8< ---------------8< ---------------8< ---------------8< ---------------

## Testing Procedure.
---------------8< ---------------8< ---------------8< ---------------8< ---------------
# tcpdump -n -nn -w /tmp/dump.cap port 53
# systemctl stop dnsmasq
# systemctl start dnsmasq
# systemctl status dnsmasq | grep Main
==> In my case, the PID is 800
# strace -ttTfvyy -s 2048 -o /tmp/dnsmasq.out -p 800
# for i in {1..5}; do dig google.com & done
# for i in recvmsg sendto; do cat /tmp/dnsmasq.out  | grep google | grep "$i" | wc -l; done
# for i in {1..5}; do dig google.com & done
# for i in recvmsg sendto; do cat /tmp/dnsmasq.out  | grep google | grep "$i" | wc -l; done
# for i in {1..5}; do dig google.com & done
# for i in recvmsg sendto; do cat /tmp/dnsmasq.out  | grep google | grep "$i" | wc -l; done
# for i in {1..5}; do dig google.com & done
# for i in recvmsg sendto; do cat /tmp/dnsmasq.out  | grep google | grep "$i" | wc -l; done
# for i in {1..5}; do dig google.com & done
# for i in recvmsg sendto; do cat /tmp/dnsmasq.out  | grep google | grep "$i" | wc -l; done
# for i in {1..5}; do dig google.com & done
# for i in recvmsg sendto; do cat /tmp/dnsmasq.out  | grep google | grep "$i" | wc -l; done
# for i in {1..5}; do dig google.com & done
# for i in recvmsg sendto; do cat /tmp/dnsmasq.out  | grep google | grep "$i" | wc -l; done
# for i in {1..5}; do dig google.com & done
# for i in recvmsg sendto; do cat /tmp/dnsmasq.out  | grep google | grep "$i" | wc -l; done
---------------8< ---------------8< ---------------8< ---------------8< ---------------

## My Observation
Seems dnsmasq basically follows the '1 query 1 forwarded' pattern when it's running in *stable* state. However, during its startup and the error handling, this rule is broken.

## From the strace output, the 'recvmsg' and 'sendto' syscalls are different:
---------------8< ---------------8< ---------------8< ---------------8< ---------------
# for i in recvmsg sendto; do cat /tmp/dnsmasq.out | grep "$i" | wc -l; done
196
189
---------------8< ---------------8< ---------------8< ---------------8< ---------------

## If we look into the dnsmasq logs, both are recorded:
---------------8< ---------------8< ---------------8< ---------------8< ---------------
# for i in recvmsg sendto; do cat /tmp/dnsmasq.out | grep "$i" | wc -l; done
196
189

# cat /tmp/dnsmasq.out | grep 'write(11' | grep query | wc -l
196

# cat /tmp/dnsmasq.out | grep 'write(11' | grep forwarded | wc -l
189

# cat /tmp/dnsmasq.out | grep 'write(11' | grep -v -e forwarded -e query
800   15:42:29.772770 write(11</var/log/dnsmasq.log>, "Apr 23 15:42:29 dnsmasq[800]: Maximum number of concurrent DNS queries reached (max: 150)\n", 90) = 90 <0.000019>
800   15:42:29.773097 write(11</var/log/dnsmasq.log>, "Apr 23 15:42:29 dnsmasq[800]: config error is REFUSED\n", 54) = 54 <0.000020>
---------------8< ---------------8< ---------------8< ---------------8< ---------------

## Digging into the log, when the dnsmasq starts there're 5 queries but only 1 is forwarded. Later all matches 1 query 1 forwarded pattern until the 'Maximum number of concurrent DNS queries reached (max: 150)' occurrs, after that, there's an incident that 3 queries vs 1 forwarded. Then all returns normal.
---------------8< ---------------8< ---------------8< ---------------8< ---------------
# cat /tmp/dnsmasq.log | awk '{print $5}' | uniq -c
      1 started,
      1 compile
      1 read
      1 using
      1 query[A]
      1 forwarded
      5 query[A] <<<<<< 5 query
      1 forwarded <<<<< 1 forwarded, gap=4
      1 query[A]
      1 forwarded
...
      1 query[A]
      1 forwarded
      1 query[A]
      1 Maximum <<<<<< maximum message displayed, no forwarded, gap=1
      1 config
      1 query[A]
      1 forwarded
      3 query[A] <<<<<< 3 query
      1 forwarded <<<<< 1 forwarded, gap=2
      1 query[A]
      1 forwarded
...
      1 query[A]
      1 forwarded
---------------8< ---------------8< ---------------8< ---------------8< ---------------
total gap=4+1+2=7, matches 196-189=7

In this case, seems '1 query vs 1 forwarded' operation would be a normal behavior for a stably running dnsmasq. This is what the latest dnsmasq on RHEL7.9 and the latest dnsmasq on Fedora 38 follow. However, it's not the case for the latest dnsmasq of RHEL8.

Could you please explain the differences here? After comparing the source code, we're seeing the following patches may change the behavior:
 - https://thekelleys.org.uk/gitweb/?p=dnsmasq.git;a=commitdiff;h=141a26f979b4bc959d8e866a295e24f8cf456920
 - https://thekelleys.org.uk/gitweb/?p=dnsmasq.git;a=commitdiff;h=305cb79c5754d5554729b18a2c06fe7ce699687a

Thank you.

Best regards,
Flos

Comment 7 Petr Menšík 2023-04-28 09:57:26 UTC
Ah, yes, those changes introduce roughly the same number of queries again. But their primary reason is *NOT* to have exactly the same count on incoming queries and outgoing queries.

These queries return back correct retries in case the initial query forwarded to upstream were dropped by network. Because of dnsmasq design, dnsmasq does not do retries itself. I even cannot do that, because it stores just hash of incoming query. Not the query name and type themselves. So it relies on clients to do retries. Commits you mention ensure those retries are too forwarded again, making it more reliable on unreliable networks from dnsmasq to upstream servers.

Later commit 64a16cb [1] again reduced the number of forwarded queries. It prevents dnsmasq clients ability to bombard any upstream server with queries sent to dnsmasq. Because dnsmasq is rate limiting (again) outgoing queries as it should. Still ensures retries are forwarded unless it were already retried less than 2 seconds ago. I think we want also commit 305cb79 [2].

So yes, we need to ensure retries work and are not ignored, but query count on internal network does not have to match forwarded count. That won't be fixed, because we want to prevent that.

[1] http://thekelleys.org.uk/gitweb/?p=dnsmasq.git;a=commit;h=64a16cb376a5248a53fb55e81a8df4d61630d120
[2] http://thekelleys.org.uk/gitweb/?p=dnsmasq.git;a=commit;h=305cb79c5754d5554729b18a2c06fe7ce699687a

Comment 8 Petr Menšík 2023-05-04 18:35:52 UTC
Created attachment 1962321 [details]
python script to emulate packet drops

Attaching simple script, which emulates on address 127.0.0.2, port 2053, forwarder with unreliable connection. It forwards packets to localhost, port domain. But drops first packet, passes another then drops again.

Comment 9 RHEL Program Management 2023-09-21 18:52:20 UTC
Issue migration from Bugzilla to Jira is in process at this time. This will be the last message in Jira copied from the Bugzilla bug.

Comment 10 RHEL Program Management 2023-09-21 19:07:11 UTC
This BZ has been automatically migrated to the issues.redhat.com Red Hat Issue Tracker. All future work related to this report will be managed there.

Due to differences in account names between systems, some fields were not replicated.  Be sure to add yourself to Jira issue's "Watchers" field to continue receiving updates and add others to the "Need Info From" field to continue requesting information.

To find the migrated issue, look in the "Links" section for a direct link to the new issue location. The issue key will have an icon of 2 footprints next to it, and begin with "RHEL-" followed by an integer.  You can also find this issue by visiting https://issues.redhat.com/issues/?jql= and searching the "Bugzilla Bug" field for this BZ's number, e.g. a search like:

"Bugzilla Bug" = 1234567

In the event you have trouble locating or viewing this issue, you can file an issue by sending mail to rh-issues. You can also visit https://access.redhat.com/articles/7032570 for general account information.


Note You need to log in before you can comment on or make changes to this bug.