Opened 8 years ago

Closed 7 years ago

#6979 closed defect (fixed)

Assertion on router.c:164 when disabling ORPort

Reported by: eli Owned by:
Priority: Medium Milestone: Tor: 0.2.4.x-final
Component: Core Tor/Tor Version: Tor: 0.2.3.25
Severity: Keywords: tor-bridge tor-relay 023-backport
Cc: thefliegende@… Actual Points:
Parent ID: Points:
Reviewer: Sponsor:

Description

From the Vidalia Message Log:

[Tue Sep 25 14:37:20 2012] The Tor Software is Running - You are currently running version "0.2.2.39 (git-bec76476efb71549)" of the Tor software.
[Tue Sep 25 14:37:39 2012] Tor Software Error - The Tor software encountered an internal bug. Please report the following error message to the Tor developers at bugs.torproject.org: "get_server_identity_key(): Bug: router.c:164: get_server_identity_key: Assertion server_mode(get_options()) failed; aborting.
"
There were several previous instances of this error, without the notice to report.

It's about time this came thru - I haven't been able to get this ver. to talk to my local and router firewalls, and with the fws down, the pgm hangs on my bridge identifying itself. For what it may be worth, here are some of the unexpected and AFAIKS incorrect log entries:

Sep 25 09:45:56.354 [Info] internal circ (length 3, last hop maushaus): Ramsgate(open) $BDB507AC02DC3AF1890A58F318FE68FC64CACCDE(open) $E31ABC8D5BD40F936A758B1C149B75F973E7AD2F(closed)

Sep 25 10:14:36.453 [Info] internal circ (length 3, last hop maushaus): srvph3xat(open) CCN(open) $E31ABC8D5BD40F936A758B1C149B75F973E7AD2F(waiting for keys)

HTH eli----
gpg: 0x3E346824

Child Tickets

Change History (27)

comment:1 Changed 8 years ago by eli

Summary: TBB ver 0,2,2,39 Bug: router.c:164TBB Bug: router.c:164

comment:2 Changed 8 years ago by nickm

Priority: criticalmajor

Hm. Did previous versions work? Which ones? Are you configured as a server? Can you post the contents of your torrc file (with any private information removed)? What platform are you running on?

comment:3 Changed 8 years ago by eli

All previous versions worked. I started running a bridge at least 4 or 5 versions ago. Running on Vista x64 (home premium). The only server I'm running is tor bridges - I'm not sure what "configured as a server" means for a windows machine, please advise. torrc file:


# This file was generated by Tor; if you edit it, comments will not be
preserved
# The old torrc file was renamed to torrc.orig.1 or similar, and Tor
will ignore it

AvoidDiskWrites 1
BridgeRelay 1
ContactInfo eliaz at tormail dot org gpg 0x3E346824
ControlPort 9051
DataDirectory C:/sources/tor/browser bundle extracted/Tor Browser/Data/Tor
DirReqStatistics 0
ExitPolicy reject *:*
GeoIPFile .\Data\Tor\geoip
Log notice stdout
Nickname maushaus
NumCPUs 2
ORPort 443
RelayBandwidthBurst 196608
RelayBandwidthRate 98304
SafeLogging relay
SocksListenAddress 127.0.0.1


comment:4 Changed 8 years ago by arma

Milestone: TorBrowserBundle 2.2.x-stableTor: 0.2.2.x-final

comment:5 Changed 8 years ago by arma

Exciting! Looking at the 0.2.2.39 changelog, I don't think we introduced anything that could have caused it. So it's more likely that the bug is in previous versions too.

Is it repeatable? How often? Can you induce it to happen? See also https://trac.torproject.org/projects/tor/wiki/doc/TorFAQ#MyTorkeepscrashing. for other good questions to answer.

comment:6 in reply to:  5 Changed 8 years ago by eli

Replying to arma:

Exciting! Looking at the 0.2.2.39 changelog, I don't think we introduced anything that could have caused it. So it's more likely that the bug is in previous versions too.

Is it repeatable? How often? Can you induce it to happen? See also https://trac.torproject.org/projects/tor/wiki/doc/TorFAQ#MyTorkeepscrashing. for other good questions to answer.

It was repeatable beffore I rolled back to ver .38. I can't test again, my machine isn't the best of testbeds while I've got so many other things running on it & while I'm trying hard to keep the bridge up long enough to be helpful. I wasn't able to induce the behavior since I could never establish an online presence in the first place. The client always worked OK. I've looked at the doc; it's generally helpful but the problem isn't that Tor crashes but rather that bridge implementation hangs on identifying itself. If no else has experienced the problem I'll for now assume that it's a fault in my system rather than a bug. I'm planning to run the bridge from a separate, dedicated machine. When I build that I'll try to run ver 39 or whatever ver is then current & be able to test more decisively.

BTW check.torproject.org/ indicates I'm running the latest bundle, but the installation changelog shows that I'm running Tor Browser Bundle (2.2.38-2); suite=windows. Just mentioning it. - eli

comment:7 Changed 8 years ago by nickm

Keywords: tor-bridge added

comment:8 Changed 8 years ago by nickm

Component: Tor BridgeTor

comment:9 Changed 8 years ago by eliaz

Priority: majornormal
Resolution: fixed
Status: newclosed

The problem was local after all - some errant non-Tor processes were interfering. cleaning them out, I can now load & run TBB ver. 0.2.2.39 OK. So, no bug. My apologies for the false alarm. - eliaz

comment:10 Changed 8 years ago by arma

Can you give us some hints about how they were interfering? Usually if one person experiences an issue, there are a hundred more who haven't spoken up.

comment:11 Changed 8 years ago by rransom

Resolution: fixed
Status: closedreopened

All assertion failures are bugs.

Perhaps he means that a process (Skype?) was listening on port 443, so Tor could not bind a listening socket on that port in response to Vidalia's SETCONF command.

comment:12 Changed 8 years ago by nickm

Milestone: Tor: 0.2.2.x-finalTor: unspecified
Status: reopenedneeds_information

comment:13 in reply to:  12 Changed 8 years ago by eliaz

Replying to nickm:I'm not sure what information you need. In any case I'm now successfully running tor-browser-2.3.25-4_en-US, cannot reproduce the problem. I recently sent a query to tor-relays ("relay exposed?" 3/9/2013 1:48 AM EST) about the bridge nickname appearing as part of a circuit on the Network Map,but that was fugitive, I saw it only once, and don't think it represents a bug. - eliaz

comment:14 Changed 7 years ago by thefliegendeeep

Cc: thefliegende@… added
Keywords: tor-relay added
Version: Tor: 0.2.2.39Tor: 0.2.3.25

log:
Jul 17 06:25:02.000 [notice] Tor 0.2.3.25 (git-3fed5eb096d2d187) opening new log file.
Jul 17 06:25:02.000 [notice] Closing old Control listener on 127.0.0.1:9051
Jul 17 06:25:02.000 [notice] Closing old Directory listener on 0.0.0.0:80
Jul 17 06:25:02.000 [notice] Closing old OR listener on 0.0.0.0:443
Jul 17 06:25:03.000 [err] get_server_identity_key(): Bug: router.c:171: get_server_identity_key: Assertion server_mode(get_options()) failed; aborting.

torrc:
SocksPort 0 # what port to open for local application connections
SocksListenAddress 127.0.0.1 # accept connections only from localhost
DataDirectory /var/lib/tor
ControlPort 9051
CookieAuthentication 1
ORPort 443
Nickname thefliegendeeep
Address <edited for bugreport>
RelayBandwidthRate 2000 KB # Throttle traffic to 100KB/s (800Kbps)
RelayBandwidthBurst 2200 KB # But allow bursts up to 200KB/s (1600Kbps)
ContactInfo Fliegende Eep <thefliegende AT lavabit dot com>
DirPort 80 # what port to advertise for directory connections
ExitPolicy reject *:* # no exits allowed

I did copy a backed up /var/lib/tor/fingerprint over the installed fingerprint, so maybe that plays a role too.

comment:15 Changed 7 years ago by thefliegendeeep

Status: needs_informationnew

comment:16 Changed 7 years ago by nickm

Looks like this is running on a nice unix-like system. If so, a stack trace would be really helpful here.

comment:17 Changed 7 years ago by thefliegendeeep

I misconfigured things. /etc/tor/torrc was owned by root with 0600. Still a bug, but that seems to be why it occurs. Logs contained more important info too:

Jul 17 04:20:55.000 [notice] Heartbeat: Tor's uptime is 1 day 6:00 hours, with 2053 circuits open. I've sent 1.59 GB and received 1.50 GB.
Jul 17 06:25:02.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Jul 17 06:25:02.000 [notice] Read configuration file "/usr/share/tor/tor-service-defaults-torrc".
Jul 17 06:25:02.000 [warn] Couldn't find $HOME environment variable while expanding "~/.torrc"; defaulting to "".
Jul 17 06:25:02.000 [notice] Configuration file "/etc/tor/torrc" not present, using reasonable defaults.
Jul 17 06:25:02.000 [notice] Opening Socks listener on 127.0.0.1:9050
Jul 17 06:25:02.000 [notice] Closing no-longer-configured Control listener on 127.0.0.1:9051
Jul 17 06:25:02.000 [notice] Closing no-longer-configured Directory listener on 0.0.0.0:80
Jul 17 06:25:02.000 [notice] Closing no-longer-configured OR listener on 0.0.0.0:443

Jul 17 06:25:02.000 [notice] Tor 0.2.3.25 (git-3fed5eb096d2d187) opening new log file.
Jul 17 06:25:02.000 [notice] Closing old Control listener on 127.0.0.1:9051
Jul 17 06:25:02.000 [notice] Closing old Directory listener on 0.0.0.0:80
Jul 17 06:25:02.000 [notice] Closing old OR listener on 0.0.0.0:443
Jul 17 06:25:03.000 [err] get_server_identity_key(): Bug: router.c:171: get_server_identity_key: Assertion server_mode(get_options()) failed; aborting.

Jul 19 05:07:55.000 [notice] Heartbeat: Tor's uptime is 6:00 hours, with 53 circuits open. I've sent 1.34 GB and received 1.28 GB.
Jul 19 06:25:02.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Jul 19 06:25:02.000 [notice] Read configuration file "/usr/share/tor/tor-service-defaults-torrc".
Jul 19 06:25:02.000 [warn] Couldn't find $HOME environment variable while expanding "~/.torrc"; defaulting to "".
Jul 19 06:25:02.000 [notice] Configuration file "/etc/tor/torrc" not present, using reasonable defaults.
Jul 19 06:25:02.000 [notice] Opening Socks listener on 127.0.0.1:9050
Jul 19 06:25:02.000 [notice] Closing no-longer-configured Control listener on 127.0.0.1:9051
Jul 19 06:25:02.000 [notice] Closing no-longer-configured Directory listener on 0.0.0.0:80
Jul 19 06:25:02.000 [notice] Closing no-longer-configured OR listener on 0.0.0.0:443

Jul 19 06:25:02.000 [notice] Tor 0.2.3.25 (git-3fed5eb096d2d187) opening new log file.
Jul 19 06:25:02.000 [notice] Closing old Control listener on 127.0.0.1:9051
Jul 19 06:25:02.000 [notice] Closing old Directory listener on 0.0.0.0:80
Jul 19 06:25:02.000 [notice] Closing old OR listener on 0.0.0.0:443
Jul 19 11:07:55.000 [notice] Heartbeat: Tor's uptime is 12:00 hours, with 1 circuits open. I've sent 2.01 GB and received 1.93 GB.
Jul 19 17:07:55.000 [notice] Heartbeat: Tor's uptime is 18:00 hours, with 2 circuits open. I've sent 2.02 GB and received 1.94 GB.

So, im assuming that it starts with enough privileges to read the config, runs as a server, then receives the reload signal, doesnt have enough privileges anymore, thus defaults to not being a server, but some code can still be running thinking it is, hence the assertion error once.

Still try and get a stacktrace? Maybe send some sighups as well. I could also just fix the permission problem...

comment:18 Changed 7 years ago by nickm

A stack trace would still be excellent. Tor should never crash; if it does, there are other bugs at work here.

(For what it's worth, I just tried creating a root-owned unreadable torrc and running against it, but it didn't get a crash like this, so there's probably something else going on here too.)

comment:19 Changed 7 years ago by thefliegendeeep

Sorry, I was unclear. I meant there is still a bug, just that it seemed it was going to be difficult to reproduce it. I tried sending SIGHUPs myself, but it just fails to find the torrc then, thus going into client mode, but it doesn't have the bug reappear.

Also, somehow gdb fails to get the symbols (though i got the right tor-dbg version). Will try and fix that if it seems worthwhile to keep trying to reproduce (maybe break into some part first that is likely to mess up when the options get changed halfway?)?

comment:20 Changed 7 years ago by thefliegendeeep

Btw, the problem was not so much the permissions on torrc, but the permissions on /etc/tor, those were 0700.

comment:21 in reply to:  18 Changed 7 years ago by arma

Replying to nickm:

(For what it's worth, I just tried creating a root-owned unreadable torrc and running against it, but it didn't get a crash like this, so there's probably something else going on here too.)

Steps to reproduce, as I understood from the bug reporter, would be to start Tor with an init script that runs as root (e.g. on debian), and so can read the torrc file, and then hup tor after it's dropped privileges.

comment:22 Changed 7 years ago by thefliegendeeep

  • Correct arma. But to be complete: The one time the bug occurred it happened when tor got sighupped automatically, as seems to happen on 6:25 each day on my machine. I'm just assuming sending them yourself won't make a crucial difference.
  • Should I really keep running this relay with the permission problem and have it stop each day / when i sighup to try to reproduce?
  • If I keep running it, would it be ok to compile tor with debugging so we would at least get a meaningful backtrace if it occurs again, or would that change too much?

comment:23 Changed 7 years ago by WebSpider

I'm seeing this issue too:

Sep 18 14:46:08.000 [notice] Received reload signal (hup). Reloading config and resetting internal state.
Sep 18 14:46:08.000 [notice] Read configuration file "/usr/share/tor/tor-service-defaults-torrc".
Sep 18 14:46:08.000 [notice] Read configuration file "/etc/tor/torrc".
Sep 18 14:46:08.000 [notice] Closing no-longer-configured OR listener on 0.0.0.0:9001
Sep 18 14:46:08.000 [notice] Tor 0.2.3.25 (git-3fed5eb096d2d187) opening log file.
Sep 18 14:46:08.000 [notice] Closing old OR listener on 0.0.0.0:9001
Sep 18 14:46:08.000 [err] get_server_identity_key(): Bug: router.c:171: get_server_identity_key: Assertion server_mode(get_options()) failed; aborting.

Server is plain wheezy:

root@hosting:/home/nivo# cat /etc/issue.net
Debian GNU/Linux 7
root@hosting:/home/nivo# grep tor /etc/apt/sources.list
# tor
deb http://deb.torproject.org/torproject.org wheezy main

Permissions are default, from the dpkg

root@hosting:/home/nivo# ls -l /etc/tor/torrc
-rw-r--r-- 1 root root 8867 Sep 18 14:46 /etc/tor/torrc

Contents of torrc:

HiddenServiceDir /var/lib/tor/hidden_1/
HiddenServicePort 25 127.0.0.1:25
Nickname MyNick
AccountingMax 500 GB
AccountingStart month 28 0:00
ContactInfo Contact TOR-Relays list < tor-relays located at lists.torproject.org >
ExitPolicy reject *:* # no exits allowed
AllowSingleHopExits 0
AllowSingleHopCircuits 0
EntryStatistics 1
ExitPortStatistics 1
ConnDirectionStatistics 1

If you still need stack traces, let me know.

comment:24 Changed 7 years ago by nickm

Keywords: 023-backport added
Milestone: Tor: unspecifiedTor: 0.2.4.x-final
Summary: TBB Bug: router.c:164Assertion on router.c:164 when disabling ORPort

Interesting. "Closing old OR listener on 0.0.0.0:9001" seems to imply that there was an ORPort, and that when the process is turning it off, it's crashing...

And when I try this, I get this stack trace:

#3  0x00000001000ad542 in get_server_identity_key () at router.c:170
#4  0x00000001000799a2 in accounting_set_wakeup_time [inlined] () at /Users/nickm/src/tor-023/src/or/hibernate.c:531
#5  0x00000001000799a2 in configure_accounting (now=140734799803232) at hibernate.c:400
#6  0x000000010002c226 in set_options (new_val=0x7fff5fbff500, msg=0x7fff5fbff500) at config.c:1572
#7  0x000000010002d576 in options_init_from_string (cf_defaults=0x7fff5fbff590 "", cf=0x7fff5fbff590 "", command=1606415760, command_arg=0x7fff5fbff590 "", msg=0x7fff7696f278) at config.c:4845
#8  0x000000010002dc31 in options_init_from_torrc (argc=1606415872, argv=0x7fff5fbff600) at config.c:4702
#9  0x000000010007b51f in do_hup [inlined] () at /Users/nickm/src/tor-023/src/or/main.c:1796

I think the problem should be fixable with a one-liner -- just a second.

comment:25 Changed 7 years ago by nickm

Status: newneeds_review

One-line fix in branch bug6979_023 in my public repository; needs review.

comment:26 Changed 7 years ago by asn

Looks good to me.

(Maybe change the function comment to say /** Return true iff we are a server *and* the server identity key has been set. */ but it's no biggie.)

comment:27 Changed 7 years ago by nickm

Resolution: fixed
Status: needs_reviewclosed

Merged into 0.2.3 and later; tweaked comment in master. Thanks!

Note: See TracTickets for help on using tickets.