Opened 6 weeks ago

Closed 4 weeks ago

#29042 closed defect (fixed)

Error loading private key after 0.3.5.7 upgrade

Reported by: anong Owned by: nickm
Priority: Very High Milestone: Tor: 0.3.5.x-final
Component: Core Tor/Tor Version: Tor: 0.3.5.7
Severity: Critical Keywords: tor-relay, 035-proposed regression
Cc: Actual Points: .1
Parent ID: Points:
Reviewer: ahf Sponsor:

Description

Hi,

I just upgraded my tor relay from 0.3.4.9 to 0.3.5.7 via the official debian repository. Now my relay is unable to start up:

Jan 10 11:24:48.000 [err] Error loading private key.
Jan 10 11:24:48.000 [err] Error initializing keys; exiting

What can I do to fix it?

root@DietPi:/var/lib/tor/keys# ls -lah
total 44K
drwx--S--- 2 tor tor 4.0K Jan 5 18:55 .
drwx--S--- 5 tor tor 4.0K Jan 10 11:24 ..
-rw-r--r-- 1 tor tor 64 Dec 13 2015 ed25519_master_id_public_key
-rw-r--r-- 1 tor tor 96 Dec 13 2015 ed25519_master_id_secret_key
-rw------- 1 tor tor 172 Dec 18 23:00 ed25519_signing_cert
-rw------- 1 tor tor 96 Dec 18 23:00 ed25519_signing_secret_key
-rw-r--r-- 1 tor tor 902 Nov 6 2013 secret_id_key
-rw------- 1 tor tor 887 Jan 5 18:55 secret_onion_key
-rw------- 1 tor tor 96 Jan 5 18:55 secret_onion_key_ntor
-rw------- 1 tor tor 96 Dec 8 18:07 secret_onion_key_ntor.old
-rw------- 1 tor tor 887 Dec 8 18:07 secret_onion_key.old

Child Tickets

Change History (12)

comment:1 Changed 6 weeks ago by anong

After downgrading to 0.3.4.9-5~bpo9+1 from ftp.debian.org/debian stretch-backports, everything is working again.

comment:2 Changed 6 weeks ago by nickm

Milestone: Tor: 0.3.5.x-final
Priority: HighVery High

comment:3 Changed 6 weeks ago by nickm

Are there any other logs around that error?

comment:4 Changed 6 weeks ago by anong

root@DietPi:~# Jan 10 11:21:37.158 [notice] Tor 0.3.5.7 running on Linux with Libevent 2.0.21-stable, OpenSSL 1.1.0j, Zlib 1.2.8, Liblzma 5.2.2, and Libzstd 1.1.2.
Jan 10 11:21:37.158 [notice] Tor can't help you if you use it wrong! Learn how to be safe at https://www.torproject.org/download/download#warning
Jan 10 11:21:37.159 [notice] Read configuration file "/etc/tor/torrc".
Jan 10 11:21:37.174 [warn] Skipping obsolete configuration option 'SocksListenAddress'
d! You should upgrade your Tor controller as soon as possible.
Jan 10 11:21:37.178 [notice] You configured a non-loopback address '192.168.100.9:9050' for SocksPort. This allows everybody on your local network to use your machine as a proxy. Make sure this is what you wanted.
Jan 10 11:21:37.178 [notice] Opening Socks listener on 192.168.100.9:9050
Jan 10 11:21:37.178 [notice] Opened Socks listener on 192.168.100.9:9050
Jan 10 11:21:37.178 [notice] Opening Control listener on 127.0.0.1:9051
Jan 10 11:21:37.178 [notice] Opened OR listener on 0.0.0.0:443
Jan 10 11:21:37.179 [notice] Opening Directory listener on 0.0.0.0:80
Jan 10 11:21:56.479 [notice] Tor can't help you if you use it wrong! Learn how to be safe at https://www.torproject.org/download/download#warning
Jan 10 11:21:56.479 [notice] Read configuration file "/etc/tor/torrc".
Jan 10 11:22:27.000 [err] Error loading private key.
Jan 10 11:22:27.000 [err] Error initializing keys; exiting

That's all I have. What specific logs are you looking for?

comment:5 Changed 5 weeks ago by anong

Debug log:

Jan 14 14:52:43 DietPi Tor[1561]: circuit_build_times_add_time(): Adding circuit build time 4725
Jan 14 14:52:43 DietPi Tor[1561]: circuit_build_times_add_time(): Adding circuit build time 2147483646
Jan 14 14:52:43 DietPi Tor[1561]: circuit_build_times_add_time(): Adding circuit build time 375
Jan 14 14:52:43 DietPi Tor[1561]: circuit_build_times_parse_state(): Loaded 273/273 values from 74 lines in circuit time histogram
Jan 14 14:52:43 DietPi Tor[1561]: circuit_build_times_get_xm(): Xm mode #0: 525 19
Jan 14 14:52:43 DietPi Tor[1561]: circuit_build_times_set_timeout_worker(): Circuit build measurement period of 38477ms is more than twice the maximum build time we have ever observed. Capping it to 34650ms.
Jan 14 14:52:43 DietPi Tor[1561]: circuit_build_times_set_timeout(): Based on 273 circuit times, it looks like we don't need to wait so long for circuits to finish. We will now assume a circuit is too slow to use after waiting 5 seconds
Jan 14 14:52:43 DietPi Tor[1561]: circuit_build_times_set_timeout(): Circuit timeout data: 5274.074997ms, 60000.000000ms, Xm: 525, a: 0.697584, r: 0.271062
Jan 14 14:52:43 DietPi Tor[1561]: read_file_to_str(): Could not open "/var/lib/tor/router-stability": No such file or directory
Jan 14 14:52:43 DietPi Tor[1561]: check_private_dir(): stat()ing /var/lib/tor/diff-cache
Jan 14 14:53:13 DietPi Tor[1561]: kist_scheduler_run_interval(): KISTSchedRunInterval=0, turning to the consensus.
Jan 14 14:53:13 DietPi Tor[1561]: scheduler_can_use_kist(): Determined KIST sched_run_interval should be 10. Can use KIST.
Jan 14 14:53:13 DietPi Tor[1561]: scheduler_kist_set_full_mode(): Setting KIST scheduler with kernel support (KIST mode)
Jan 14 14:53:13 DietPi Tor[1561]: kist_scheduler_run_interval(): KISTSchedRunInterval=0, turning to the consensus.
Jan 14 14:53:13 DietPi Tor[1561]: cmux_ewma_set_options(): Enabled cell_ewma algorithm because of value in CircuitPriorityHalflifeMsec in consensus; scale factor is 0.793701 per 10 seconds
Jan 14 14:53:13 DietPi Tor[1561]: Parsing GEOIP IPv4 file /usr/share/tor/geoip.
Jan 14 14:53:14 DietPi Tor[1561]: Parsing GEOIP IPv6 file /usr/share/tor/geoip6.
Jan 14 14:53:15 DietPi Tor[1561]: options_act(): Configured to measure hidden service statistics.
Jan 14 14:53:15 DietPi Tor[1561]: Configured to measure statistics. Look for the *-stats files that will first be written to the data directory in 24 hours from now.
Jan 14 14:53:15 DietPi Tor[1561]: mark_my_descriptor_dirty(): Decided to publish new relay descriptor: config change
Jan 14 14:53:15 DietPi Tor[1561]: add_predicted_port(): New port prediction added. Will continue predictive circ building for 2909 more seconds.
Jan 14 14:53:15 DietPi Tor[1561]: crypto_openssl_late_init(): NOT using OpenSSL engine support.
Jan 14 14:53:15 DietPi Tor[1561]: evaluate_evp_for_aes(): This version of OpenSSL has a known-good EVP counter-mode implementation. Using it.
Jan 14 14:53:15 DietPi Tor[1561]: file_status(): stat()ing /var/lib/tor/unparseable-descs
Jan 14 14:53:15 DietPi Tor[1561]: check_private_dir(): stat()ing /var/lib/tor
Jan 14 14:53:15 DietPi Tor[1561]: tor_getpwnam(): Caching new entry tor for tor
Jan 14 14:53:15 DietPi Tor[1561]: check_private_dir(): stat()ing /var/lib/tor/keys
Jan 14 14:53:15 DietPi Tor[1561]: tor_getpwnam(): Caching new entry tor for tor
Jan 14 14:53:15 DietPi Tor[1561]: init_keys(): Reading/making identity key "/var/lib/tor/keys/secret_id_key"...
Jan 14 14:53:15 DietPi Tor[1561]: file_status(): stat()ing /var/lib/tor/keys/secret_id_key
Jan 14 14:53:15 DietPi Tor[1561]: Error loading private key.
Jan 14 14:53:15 DietPi Tor[1561]: Error initializing keys; exiting
Jan 14 14:53:15 DietPi Tor[1561]: tor_rename(): Renaming /var/lib/tor/state.tmp to /var/lib/tor/state
Jan 14 14:53:15 DietPi Tor[1561]: or_state_save(): Saved state to "/var/lib/tor/state"
Jan 14 14:53:15 DietPi Tor[1561]: channel_tls_free_all(): Shutting down TLS channels...
Jan 14 14:53:15 DietPi Tor[1561]: channel_tls_free_all(): Done shutting down TLS channels
Jan 14 14:53:15 DietPi Tor[1561]: channel_free_all(): Shutting down channels...
Jan 14 14:53:15 DietPi Tor[1561]: channel_free_all(): Freeing channel_identity_map
Jan 14 14:53:15 DietPi Tor[1561]: channel_free_all(): Freeing channel_gid_map
Jan 14 14:53:15 DietPi Tor[1561]: channel_free_all(): Done cleaning up after channels
Jan 14 14:53:15 DietPi Tor[1561]: connection_free_minimal(): closing fd 6.
Jan 14 14:53:15 DietPi Tor[1561]: connection_free_minimal(): closing fd 7.
Jan 14 14:53:15 DietPi Tor[1561]: connection_free_minimal(): closing fd 8.
Jan 14 14:53:15 DietPi Tor[1561]: connection_free_minimal(): closing fd 9.
Jan 14 14:53:15 DietPi Tor[1561]: connection_free_minimal(): closing fd 10.
Jan 14 14:53:15 DietPi Tor[1561]: scheduler_free_all(): Shutting down scheduler
Jan 14 14:53:15 DietPi Tor[1561]: tor_lockfile_unlock(): Unlocking "/var/lib/tor/lock"

comment:6 Changed 5 weeks ago by anong

Seems this had something to do with the line endings. After running dos2unix on secret_id_key, everything works fine now. Interesting that 0.3.5.7 is the first version that had a problem with the file.

comment:7 Changed 5 weeks ago by nickm

Not necessarily: we changed how we parsed PEM stuff recently (I think in 0.3.5) to use Tor's base64 code instead of OpenSSL's. It's possible that OpenSSL is more newline-tolerant. If so, we should think about fixing that, if we can do so safely.

comment:8 Changed 5 weeks ago by nickm

Keywords: 035-proposed added
Owner: set to nickm
Status: newaccepted

comment:9 Changed 5 weeks ago by nickm

Actual Points: .1
Keywords: regression added
Status: acceptedneeds_review

I've written a patch as bug29042_035 with PR at https://github.com/torproject/tor/pull/649 to improve the logging in this case. Needs review.

comment:10 Changed 4 weeks ago by dgoulet

Reviewer: ahf

comment:11 Changed 4 weeks ago by ahf

Status: needs_reviewmerge_ready

LGTM.

comment:12 Changed 4 weeks ago by nickm

Resolution: fixed
Status: merge_readyclosed

thanks; merged it!

Note: See TracTickets for help on using tickets.