os-tor: Gets stuck in dormant state

[gwk001]

Had this working with transparent proxy in 18.7. It broke at some point (I only use it rarely), and I couldn't get it to work again under 19.1. I did a fresh install for 19.7.1 and rebuilt my rules from scratch, and it started working again. I then upgraded to 19.7.2 and it broke again with Bootstrapping stuck on 0%. 19.7.3 did the same thing. Reverting to opnsense 19.7.1 did not fix. Not sure if it's a plugin issue, core, or some interaction.

Relatively simple setup- single firewall with a bridged ADSL modem on DHCP. Have spent literally days on this. Among other things, tried with "disable force gateway" enabled and disabled. Other local services like NTP and Unbound work. MTU appears to be defaulting to 1492.

torrc

##
## OPNsense autogenerated config file.
## Don't change it because your changes get lost.
##
##

SOCKSPort 127.0.0.1:9050 # localhost IPv4
SOCKSPort [::1]:9050     # localhost IPv6


SOCKSPolicy accept 192.168.XXX.0/24

SOCKSPolicy reject *
SOCKSPolicy reject6 *


Log notice syslog


Scheduler KISTLite,Vanilla

DataDirectory /var/db/tor

ControlPort 9051
HashedControlPassword XXX


FascistFirewall 0

TransPort 9040
DNSPort 9053
VirtualAddrNetwork 172.29.0.0/16
AutomapHostsOnResolve 1

## Client Authentication

syslog

Tor[5597]: Tor 0.4.1.5 running on FreeBSD with Libevent 2.1.11-stable, OpenSSL LibreSSL 2.9.2, Zlib 1.2.11, Liblzma 5.2.3, and Libzstd 1.4.3.
Tor[5597]: Tor can't help you if you use it wrong! Learn how to be safe at https://www.torproject.org/download/download#warning
Tor[5597]: Read configuration file "/usr/local/etc/tor/torrc".
Tor[5597]: The abbreviation 'Scheduler' is deprecated. Please use 'SchedulerLowWaterMark__' instead
Tor[5597]: Skipping obsolete configuration option 'SchedulerLowWaterMark__'
Tor[5597]: Opening Socks listener on 127.0.0.1:9050
Tor[5597]: Opened Socks listener on 127.0.0.1:9050
Tor[5597]: Opening Socks listener on [::1]:9050
Tor[5597]: Opened Socks listener on [::1]:9050
Tor[5597]: Opening DNS listener on 127.0.0.1:9053
Tor[5597]: Opened DNS listener on 127.0.0.1:9053
Tor[5597]: Opening Transparent pf/netfilter listener on 127.0.0.1:9040
Tor[5597]: Opened Transparent pf/netfilter listener on 127.0.0.1:9040
Tor[5597]: Opening Control listener on 127.0.0.1:9051
Tor[5597]: Opened Control listener on 127.0.0.1:9051
Tor[5597]: Parsing GEOIP IPv4 file /usr/local/share/tor/geoip.
Tor[5597]: Parsing GEOIP IPv6 file /usr/local/share/tor/geoip6.
Tor[5597]: We were built to run on a 64-bit CPU, with OpenSSL 1.0.1 or later, but with a version of OpenSSL that apparently lacks accelerated support for the NIST P-224 and P-256 groups. Building openssl with such support (using the enable-ec_nistp_64_gcc_128 option when configuring it) would make ECDH much faster.
Tor[5597]: Bootstrapped 0% (starting): Starting
Tor[5597]: Starting with guard context "default"

[fabianfrz]

From you log the plugin is working but the port may be broken. @fichtner any idea?

[gwk001]

Actually made some progress troubleshooting this. Noticed the most recent dates in /var/db/tor/state were the same day I had done my fresh install a month ago. I tried uninstalling and re-installing the plugin with no change. I then tried to recreate the same conditions as closely as possible by stopping Tor service, uninstalling the plugin, rmuser _tor, and verifying /var/db/tor was gone. I then re-installed the plugin, and Tor now bootstraps to 100% and transparent proxying works. Rebooted and it continues to work.

I will keep an eye on it and see if it breaks again next upgrade. Could be time related too, like maybe some of these Tor files aren't getting updated and cached entries start expiring. For now, does it make sense to close this and re-open if it happens a third time? I think it lasted around two weeks before it broke last time.

[fabianfrz]

Will close now.

[gwk001]

Tested transparent proxy yesterday and it was working. Tested again today and client traffic was failing. Syslogs showed that yesterday, Tor became no longer dormant on receiving traffic. Today, it stayed in a dormant state even though I was generating requests. During that time, I saw multiples of the following messages. Saw these on other occasions when it wasn't working too:

Tor[20391]: Tried for 120 seconds to get a connection to [scrubbed]:0. Giving up.
Tor[20391]: Warning from libevent: Error Can't assign requested address (49) while writing response to port; dropping

Restarting Tor on the Opnsense dashboard did not initially help. It stuck at Bootstrapped 75%. Only then did generating client traffic get it to bootstrap all the way to 100%, at which point it came out of dormant state.
https://trac.torproject.org/projects/tor/ticket/29045#comment:6 looks related. Setting DormantCanceledByStartup 1 in torrc seems like it would at least work around the problem by letting a Tor restart reset dormant state.

[fabianfrz]

@gwk001 I cannot fix the tor daemon as it is not part of the plugin itself but I can add a checkbox for that option if that helps.

[gwk001]

Sure, I understand. It says in that Trac ticket Tor can be woken with a SIGNAL ACTIVE control port command. Is that something that Opnsense could or should be generating on receipt of traffic destined for a transparent proxy? Seems over-engineered to me if that's what Tor is expecting. A checkbox would be helpful for now so my torrc doesn't get overwritten. Want me to try to pursue this upstream with Tor?

[gwk001]

Another option instead of a checkbox might be to add to the default torrc per https://trac.torproject.org/projects/tor/ticket/30380.

[fabianfrz]

can you patch your device using

opnsense-patch -c plugins d0697e05f67990d7af9d51c1db40d1f4118de512

[gwk001]

Patched, put a check-mark in Dormant[...] in Tor advanced service config, verified DormantCanceledByStartup 1 option showed in /usr/local/etc/tor/torrc, restarted Tor service and confirmed it bootstrapped to 100% without choking on the option. Thank you, that makes it easier to recover next time!