tcp error for address xxxx port 853

chudak

Does not seem to make any difference:(

I wonder if this issue is easy reproducible...

My setup is pretty much out of the box

BBcan177

In Unbound Adv. Settings, increase the "Log Level" to "2" and "Save". Then review the resolver.log for any other clues.... And as a test disable OpenVPN and see if the error stops.

chudak

@bbcan177

Done
Not sure what is suspicious in it, maybe insecured

Feb 12 20:27:32 unbound 80650:3 info: resolving myvisualiq.net. DS IN
Feb 12 20:27:32 unbound 80650:3 info: query response was ANSWER
Feb 12 20:27:32 unbound 80650:3 info: reply from <.> 9.9.9.9#853
Feb 12 20:27:32 unbound 80650:3 info: response for t.myvisualiq.net. A IN
Feb 12 20:27:32 unbound 80650:3 info: Verified that unsigned response is INSECURE
Feb 12 20:27:32 unbound 80650:3 info: NSEC3s for the referral proved no DS.
Feb 12 20:27:32 unbound 80650:3 info: resolving akamaiedge.net. DS IN
Feb 12 20:27:32 unbound 80650:3 info: Verified that unsigned response is INSECURE
Feb 12 20:27:32 unbound 80650:3 info: NSEC3s for the referral proved no DS.

johnpoz

Thought you turned off dnssec?

You sure you don't have multiple copies running of unbound, and your config never got updated? Pfblocker can leave some hanging when it tries to update, etc.

Also that
server:so-reuseport: no

would have to do with how many threads, would not cause a tcp error...

I can not reproduce this problem... Enabling dns over tls is clickity clickity..

What other packages you have? Sorry but installing pfblocker is NOT OUT OF THE BOX... And when asked what packages you didn't even list that.. I only knew you were running it from its entry in your unbound screenshot.

So what else is not out of the box??

chudak

@johnpoz

Ack on so-reuseport: no, and remover it

I’m sure I run one pfsense, how can it be confirmed?
Would it help if I send you my config xml file?

“Enabling dns over tls is clickity clickity..”. Btw how do you test that it actually works fine?

johnpoz

sorry that was "typo" I changed it - meant unbound :) can not run multiple copies of pfsense ;) hehehe

chudak

@johnpoz said in tcp error for address xxxx port 853:

sorry that was "typo" I changed it - meant unbound :) can not run multiple copies of pfsense ;) hehehe

Too late :)

johnpoz

what is output of this

sockstat | grep unbound

Also again going to ask are you running anything else?? Any other packages?

chudak

@johnpoz said in tcp error for address xxxx port 853:

sockstat | grep unbound

sockstat | grep unbound
unbound  unbound    94103 3  udp4   192.168.90.1:53       *:*
unbound  unbound    94103 4  tcp4   192.168.90.1:53       *:*
unbound  unbound    94103 5  udp4   192.168.90.1:853      *:*
unbound  unbound    94103 6  tcp4   192.168.90.1:853      *:*
unbound  unbound    94103 7  udp4   192.168.70.1:53       *:*
unbound  unbound    94103 8  tcp4   192.168.70.1:53       *:*
unbound  unbound    94103 9  udp4   192.168.70.1:853      *:*
unbound  unbound    94103 10 tcp4   192.168.70.1:853      *:*
unbound  unbound    94103 11 udp4   127.0.0.1:53          *:*
unbound  unbound    94103 12 stream /var/run/php-fpm.socket
unbound  unbound    94103 13 stream /var/run/php-fpm.socket
unbound  unbound    94103 14 tcp4   127.0.0.1:53          *:*
unbound  unbound    94103 15 udp4   127.0.0.1:853         *:*
unbound  unbound    94103 16 tcp4   127.0.0.1:853         *:*
unbound  unbound    94103 17 udp4   192.168.90.1:53       *:*
unbound  unbound    94103 18 tcp4   192.168.90.1:53       *:*
unbound  unbound    94103 19 udp4   192.168.90.1:853      *:*
unbound  unbound    94103 20 tcp4   192.168.90.1:853      *:*
unbound  unbound    94103 21 udp4   192.168.70.1:53       *:*
unbound  unbound    94103 22 tcp4   192.168.70.1:53       *:*
unbound  unbound    94103 23 udp4   192.168.70.1:853      *:*
unbound  unbound    94103 24 tcp4   192.168.70.1:853      *:*
unbound  unbound    94103 25 udp4   127.0.0.1:53          *:*
unbound  unbound    94103 26 tcp4   127.0.0.1:53          *:*
unbound  unbound    94103 27 udp4   127.0.0.1:853         *:*
unbound  unbound    94103 28 tcp4   127.0.0.1:853         *:*
unbound  unbound    94103 29 udp4   192.168.90.1:53       *:*
unbound  unbound    94103 30 tcp4   192.168.90.1:53       *:*
unbound  unbound    94103 31 udp4   192.168.90.1:853      *:*
unbound  unbound    94103 32 tcp4   192.168.90.1:853      *:*
unbound  unbound    94103 33 udp4   192.168.70.1:53       *:*
unbound  unbound    94103 34 tcp4   192.168.70.1:53       *:*
unbound  unbound    94103 35 udp4   192.168.70.1:853      *:*
unbound  unbound    94103 36 tcp4   192.168.70.1:853      *:*
unbound  unbound    94103 37 udp4   127.0.0.1:53          *:*
unbound  unbound    94103 38 tcp4   127.0.0.1:53          *:*
unbound  unbound    94103 39 udp4   127.0.0.1:853         *:*
unbound  unbound    94103 40 tcp4   127.0.0.1:853         *:*
unbound  unbound    94103 41 udp4   192.168.90.1:53       *:*
unbound  unbound    94103 42 tcp4   192.168.90.1:53       *:*
unbound  unbound    94103 43 udp4   192.168.90.1:853      *:*
unbound  unbound    94103 44 tcp4   192.168.90.1:853      *:*
unbound  unbound    94103 45 udp4   192.168.70.1:53       *:*
unbound  unbound    94103 46 tcp4   192.168.70.1:53       *:*
unbound  unbound    94103 47 udp4   192.168.70.1:853      *:*
unbound  unbound    94103 48 tcp4   192.168.70.1:853      *:*
unbound  unbound    94103 49 udp4   127.0.0.1:53          *:*
unbound  unbound    94103 50 tcp4   127.0.0.1:53          *:*
unbound  unbound    94103 51 udp4   127.0.0.1:853         *:*
unbound  unbound    94103 52 tcp4   127.0.0.1:853         *:*
unbound  unbound    94103 53 tcp4   127.0.0.1:953         *:*
unbound  unbound    94103 54 dgram  -> /var/run/logpriv
unbound  unbound    94103 55 stream -> ??
unbound  unbound    94103 56 stream -> ??
unbound  unbound    94103 57 stream -> ??
unbound  unbound    94103 58 stream -> ??
unbound  unbound    94103 59 stream -> ??
unbound  unbound    94103 60 stream -> ??
unbound  unbound    94103 61 stream -> ??
unbound  unbound    94103 62 stream -> ??

I run several packages - https://snag.gy/CRfoFM.jpg

Unfortunately I can't easily disable vpn ATM

johnpoz

That looks normal..

Here I just turned with clickity clickity and ZERO errors..

Feb 12 23:34:40 	unbound 	95989:0 	info: query response was ANSWER
Feb 12 23:34:40 	unbound 	95989:0 	info: reply from <.> 9.9.9.9#853
Feb 12 23:34:40 	unbound 	95989:0 	info: response for checkip.synology.com. A IN
Feb 12 23:34:40 	unbound 	95989:0 	info: resolving checkip.synology.com. A IN
Feb 12 23:34:40 	unbound 	95989:0 	info: query response was CNAME
Feb 12 23:34:40 	unbound 	95989:0 	info: reply from <.> 149.112.112.112#853
Feb 12 23:34:40 	unbound 	95989:0 	info: response for checkip.synology.com. A IN
Feb 12 23:34:40 	unbound 	95989:0 	info: resolving checkip.synology.com. A IN
Feb 12 23:34:40 	unbound 	95989:0 	info: query response was CNAME
Feb 12 23:34:40 	unbound 	95989:0 	info: reply from <.> 9.9.9.9#853
Feb 12 23:34:40 	unbound 	95989:0 	info: response for checkip.synology.com. A IN
Feb 12 23:34:40 	unbound 	95989:0 	info: resolving checkip.synology.com. A IN
Feb 12 23:34:35 	unbound 	95989:3 	info: query response was ANSWER
Feb 12 23:34:35 	unbound 	95989:3 	info: reply from <.> 9.9.9.9#853
Feb 12 23:34:35 	unbound 	95989:3 	info: response for t.myvisualiq.net. A IN
Feb 12 23:34:35 	unbound 	95989:3 	info: resolving t.myvisualiq.net. A IN
Feb 12 23:34:35 	unbound 	95989:3 	info: query response was CNAME
Feb 12 23:34:35 	unbound 	95989:3 	info: reply from <.> 9.9.9.9#853
Feb 12 23:34:35 	unbound 	95989:3 	info: response for t.myvisualiq.net. A IN
Feb 12 23:34:34 	unbound 	95989:3 	info: resolving t.myvisualiq.net. A IN
Feb 12 23:33:56 	unbound 	95989:3 	info: query response was ANSWER
Feb 12 23:33:56 	unbound 	95989:3 	info: reply from <.> 9.9.9.9#853
Feb 12 23:33:56 	unbound 	95989:3 	info: response for conemu.github.io. A IN
Feb 12 23:33:56 	unbound 	95989:0 	info: query response was ANSWER
Feb 12 23:33:56 	unbound 	95989:0 	info: reply from <.> 9.9.9.9#853
Feb 12 23:33:56 	unbound 	95989:0 	info: response for conemu.github.io. A IN
Feb 12 23:33:56 	unbound 	95989:2 	info: query response was ANSWER
Feb 12 23:33:56 	unbound 	95989:2 	info: reply from <.> 9.9.9.9#853
Feb 12 23:33:56 	unbound 	95989:2 	info: response for conemu.github.io. A IN
Feb 12 23:33:56 	unbound 	95989:3 	info: resolving conemu.github.io. A IN
Feb 12 23:33:56 	unbound 	95989:0 	info: resolving conemu.github.io. A IN
Feb 12 23:33:56 	unbound 	95989:2 	info: resolving conemu.github.io. A IN
Feb 12 23:33:54 	unbound 	95989:1 	info: query response was nodata ANSWER
Feb 12 23:33:54 	unbound 	95989:1 	info: reply from <.> 149.112.112.112#853
Feb 12 23:33:54 	unbound 	95989:1 	info: response for us.pool.ntp.org. AAAA IN
Feb 12 23:33:53 	unbound 	95989:1 	info: resolving us.pool.ntp.org. AAAA IN
Feb 12 23:33:53 	unbound 	95989:3 	info: query response was ANSWER
Feb 12 23:33:53 	unbound 	95989:3 	info: reply from <.> 149.112.112.112#853
Feb 12 23:33:53 	unbound 	95989:3 	info: response for us.pool.ntp.org. A IN
Feb 12 23:33:53 	unbound 	95989:3 	info: resolving us.pool.ntp.org. A IN
Feb 12 23:33:07 	unbound 	95989:0 	info: start of service (unbound 1.8.1).

I even did a query for that entry you posted up.. Notice nothing about insecure... No errors about tcp errors, etc..

Post up your dns servers you set - you didn't set a gateway did you?

Again for what possible reason or you running TLS local for??? That is just pointless!!! Who would be sniffing your dns traffic locally???
unbound unbound 94103 52 tcp4 127.0.0.1:853 :

Turn that OFF!!! Does that remove your errors?

chudak

@johnpoz ok ok done :)

DNS Server Settings =>
https://snag.gy/g3bnED.jpg

"clickity clickity and ZERO errors.." that's in logs Resolver, what Log Level do you have set ?

johnpoz

2! It wouldn't show that info not at least that.

And Yes its the resolver log.... Where else would it be?

chudak

@johnpoz

try 3 and filter for error in Message

johnpoz

No errors..

Feb 12 23:48:17 	unbound 	27548:3 	debug: cache memory msg=66771 rrset=66949 infra=8306 val=0
Feb 12 23:48:17 	unbound 	27548:3 	info: finishing processing for p14-bookmarks.icloud.com. A IN
Feb 12 23:48:17 	unbound 	27548:3 	info: query response was ANSWER
Feb 12 23:48:17 	unbound 	27548:3 	info: reply from <.> 9.9.9.9#853
Feb 12 23:48:17 	unbound 	27548:3 	info: response for p14-bookmarks.icloud.com. A IN
Feb 12 23:48:17 	unbound 	27548:3 	info: iterator operate: chased to bookmarks.fe.apple-dns.net. A IN
Feb 12 23:48:17 	unbound 	27548:3 	info: iterator operate: query p14-bookmarks.icloud.com. A IN
Feb 12 23:48:17 	unbound 	27548:3 	debug: iterator[module 0] operate: extstate:module_wait_reply event:module_event_reply
Feb 12 23:48:17 	unbound 	27548:3 	debug: cache memory msg=66309 rrset=66537 infra=8306 val=0
Feb 12 23:48:17 	unbound 	27548:3 	debug: sending to target: <.> 9.9.9.9#853
Feb 12 23:48:17 	unbound 	27548:3 	info: sending query: bookmarks.fe.apple-dns.net. A IN
Feb 12 23:48:17 	unbound 	27548:3 	info: processQueryTargets: p14-bookmarks.icloud.com. A IN
Feb 12 23:48:17 	unbound 	27548:3 	info: resolving p14-bookmarks.icloud.com. A IN
Feb 12 23:48:17 	unbound 	27548:3 	info: query response was CNAME
Feb 12 23:48:17 	unbound 	27548:3 	info: reply from <.> 149.112.112.112#853
Feb 12 23:48:17 	unbound 	27548:3 	info: response for p14-bookmarks.icloud.com. A IN
Feb 12 23:48:17 	unbound 	27548:3 	info: sanitize: removing extraneous answer RRset: bookmarks.fe.apple-dns.net. A IN
Feb 12 23:48:17 	unbound 	27548:3 	info: iterator operate: query p14-bookmarks.icloud.com. A IN
Feb 12 23:48:17 	unbound 	27548:3 	debug: iterator[module 0] operate: extstate:module_wait_reply event:module_event_reply
Feb 12 23:48:17 	unbound 	27548:3 	debug: cache memory msg=66309 rrset=66313 infra=8057 val=0
Feb 12 23:48:17 	unbound 	27548:3 	debug: sending to target: <.> 149.112.112.112#853
Feb 12 23:48:17 	unbound 	27548:3 	info: sending query: p14-bookmarks.icloud.com. A IN
Feb 12 23:48:17 	unbound 	27548:3 	info: processQueryTargets: p14-bookmarks.icloud.com. A IN
Feb 12 23:48:17 	unbound 	27548:3 	info: resolving p14-bookmarks.icloud.com. A IN
Feb 12 23:48:17 	unbound 	27548:3 	debug: iterator[module 0] operate: extstate:module_state_initial event:module_event_new
Feb 12 23:48:16 	unbound 	27548:3 	debug: cache memory msg=66309 rrset=66313 infra=8057 val=0
Feb 12 23:48:16 	unbound 	27548:3 	info: finishing processing for _bookmarkdavs._tcp.p14-bookmarks.icloud.com. SRV IN
Feb 12 23:48:16 	unbound 	27548:3 	info: query response was NXDOMAIN ANSWER
Feb 12 23:48:16 	unbound 	27548:3 	info: reply from <.> 149.112.112.112#853
Feb 12 23:48:16 	unbound 	27548:3 	info: response for _bookmarkdavs._tcp.p14-bookmarks.icloud.com. SRV IN
Feb 12 23:48:16 	unbound 	27548:3 	info: iterator operate: query _bookmarkdavs._tcp.p14-bookmarks.icloud.com. SRV IN
Feb 12 23:48:16 	unbound 	27548:3 	debug: iterator[module 0] operate: extstate:module_wait_reply event:module_event_reply
Feb 12 23:48:16 	unbound 	27548:3 	debug: cache memory msg=66072 rrset=66072 infra=8057 val=0
Feb 12 23:48:16 	unbound 	27548:3 	debug: sending to target: <.> 149.112.112.112#853
Feb 12 23:48:16 	unbound 	27548:3 	info: sending query: _bookmarkdavs._tcp.p14-bookmarks.icloud.com. SRV IN
Feb 12 23:48:16 	unbound 	27548:3 	info: processQueryTargets: _bookmarkdavs._tcp.p14-bookmarks.icloud.com. SRV IN
Feb 12 23:48:16 	unbound 	27548:3 	info: resolving _bookmarkdavs._tcp.p14-bookmarks.icloud.com. SRV IN
Feb 12 23:48:16 	unbound 	27548:3 	debug: iterator[module 0] operate: extstate:module_state_initial event:module_event_new
Feb 12 23:47:21 	unbound 	27548:2 	debug: cache memory msg=66072 rrset=66072 infra=7808 val=0
Feb 12 23:47:21 	unbound 	27548:2 	info: DelegationPoint<.>: 0 names (0 missing), 2 addrs (0 result, 2 avail) parentNS
Feb 12 23:47:21 	unbound 	27548:3 	debug: cache memory msg=66072 rrset=66072 infra=7808 val=0
Feb 12 23:47:21 	unbound 	27548:2 	debug: Forward zone server list:
Feb 12 23:47:21 	unbound 	27548:3 	info: DelegationPoint<.>: 0 names (0 missing), 2 addrs (0 result, 2 avail) parentNS
Feb 12 23:47:21 	unbound 	27548:3 	debug: Forward zone server list:

Set to Level 3!

if I filter on errors there is NOTHING to show ;)

chudak

@johnpoz

not for me :(

Feb 12 21:57:02	unbound	54983:3	debug: tcp error for address 9.9.9.9 port 853
Feb 12 21:57:02	unbound	54983:3	debug: tcp error for address 9.9.9.9 port 853
Feb 12 21:56:53	unbound	54983:3	debug: tcp error for address 149.112.112.112 port 853
Feb 12 21:56:53	unbound	54983:3	debug: tcp error for address 9.9.9.9 port 853
Feb 12 21:56:53	unbound	54983:3	debug: tcp error for address 149.112.112.112 port 853
Feb 12 21:56:50	unbound	54983:3	debug: tcp error for address 9.9.9.9 port 853

johnpoz

@chudak said in tcp error for address xxxx port 853:

error

Ok I found 1

Feb 12 23:50:42 	unbound 	27548:1 	debug: sending to target: <.> 149.112.112.112#853
Feb 12 23:50:42 	unbound 	27548:1 	info: sending query: wpad.nafta.cds.t-internal.com. A IN
Feb 12 23:50:42 	unbound 	27548:1 	info: processQueryTargets: wpad.nafta.cds.t-internal.com. A IN
Feb 12 23:50:42 	unbound 	27548:1 	info: iterator operate: query wpad.nafta.cds.t-internal.com. A IN
Feb 12 23:50:42 	unbound 	27548:1 	debug: iterator[module 0] operate: extstate:module_wait_reply event:module_event_noreply
Feb 12 23:50:42 	unbound 	27548:1 	debug: tcp error for address 149.112.112.112 port 853

Well yeah that is not going to get an anwer ;) It asked for wpad.nafta.cds.t-internal.com

Prob just a timeout since it had to resolve it... When I ask again I get NX

And what is the REST OF THE LOG!!! What is before that error?
See in mine
debug: iterator[module 0] operate: extstate:module_wait_reply event:module_event_noreply

So what is NOT working here dude?? What doesn't resolve? Why do you have level 3 logging setup and looking for debug info?

johnpoz

Late here - have to go to bed..

chudak

@johnpoz

Feb 12 22:02:34	unbound	54983:3	info: processQueryTargets: 241.4.231.195.in-addr.arpa. PTR IN
Feb 12 22:02:34	unbound	54983:3	info: iterator operate: query 241.4.231.195.in-addr.arpa. PTR IN
Feb 12 22:02:34	unbound	54983:3	debug: iterator[module 0] operate: extstate:module_wait_reply event:module_event_noreply
Feb 12 22:02:34	unbound	54983:3	debug: tcp error for address 9.9.9.9 port 853
Feb 12 22:02:34	unbound	54983:3	debug: cache memory msg=115352 rrset=119761 infra=8306 val=0
Feb 12 22:02:34	unbound	54983:3	debug: sending to target: <.> 9.9.9.9#853
Feb 12 22:02:34	unbound	54983:3	info: sending query: 241.4.231.195.in-addr.arpa. PTR IN
Feb 12 22:02:34	unbound	54983:3	info: processQueryTargets: 241.4.231.195.in-addr.arpa. PTR IN
Feb 12 22:02:34	unbound	54983:3	info: resolving 241.4.231.195.in-addr.arpa. PTR IN
Feb 12 22:02:34	unbound	54983:3	debug: iterator[module 0] operate: extstate:module_state_initial event:module_event_new
Feb 12 22:02:32	unbound	54983:0	info: control cmd: stats_noreset

johnpoz

@chudak said in tcp error for address xxxx port 853:

extstate:module_wait_reply event:module_event_noreply

Yeah exactly - see that with every error as well.

So lets ask again - What is NOT working? Whats the rest of the log did it finish the resolving of that? It just tried again, etc.

I don't think this is actual error, but just debug info.. Here is the thing once you put your shit inside an encrypted tunnel it becomes almost impossible to actually troubleshoot..

I can tell you what... Did a sniff... And see a shit ton of retrans when this is on..

Those are retrans on a FIN from quad9.. Why?? Have no idea.. Unbound not answering? Cuz he closed the session already? Are they extra answers from the extra NS in the anycast?

So lets ask again - WHAT is not working?? Or is it you looked in a debug log and don't like it saying error?

Trying to troubleshoot such an error is 9.9.9.9 when its also ANYCAST... So you don't know exactly which server is going to answer is going to be almost impossible.

You can tell you get answers from different NS in their anycast group because you get back different TTL when you do a query back to back..

;; QUESTION SECTION:
;241.4.231.195.in-addr.arpa.    IN      PTR

;; ANSWER SECTION:
241.4.231.195.in-addr.arpa. 5969 IN     PTR     host241-4-231-195.serverdedicati.aruba.it.

;; Query time: 14 msec
;; SERVER: 9.9.9.9#53(9.9.9.9)

Do the query couple seconds later and you get a completely different TTL.. Tell me you got answer from a different cache!

So if you can name an actual dns record that is not resolving.. We can work with that, but working with what looks like WAD debug info?? And trying to think there is a problem is just pointless.

Im back to resolving... This is just pointless... I could give two shits if my ISP knows I did a query for www.pfsense.org

People don't seem to understand that this buys you nothing other then extra overhead, and now your just handing quad 9 EVERY single query you do.. Your isp can still tell where your going just from the SNI in the https request after you get the IP from dns. Are you using ESNI? ;)

chudak

@johnpoz said in tcp error for address xxxx port 853:

I don't think this is actual error, but just debug info.. Here is the thing once you put your shit inside an encrypted tunnel it becomes almost impossible to actually troubleshoot..

I actually suspect this too, debug info and message possibly wrongly tagged as error

So lets ask again - WHAT is not working?? Or is it you looked in a debug log and don't like it saying error?

Guilty, I just didn't like it's saying error. But also trying to make sure it works.

Im back to resolving... This is just pointless... I could give two shits if my ISP knows I did a query for www.pfsense.org

People don't seem to understand that this buys you nothing other then extra overhead, and now your just handing quad 9 EVERY single query you do.. Your isp can still tell where your going just from the SNI in the https request after you get the IP from dns. Are you using ESNI? ;)

This is above my pay grade, I am not an expert and can't comment if using Quad9 is good or bad idea. Wonder what Quad9 guys think about this. Maybe you are right and all this just waste of CPU power.

@johnpoz Thx for detail analysis !