Opened 12 years ago

Last modified 7 years ago

#463 closed defect (Fixed)

[notice] dns_cancel_pending_resolve(): Bug: Address [scrubbed] is not pending. Dropping.

Reported by: keb Owned by:
Priority: Low Milestone:
Component: Core Tor/Tor Version: 0.2.0.2-alpha
Severity: Keywords:
Cc: keb, arma, nickm, fk Actual Points:
Parent ID: Points:
Reviewer: Sponsor:

Description

Been getting a bunch of those messages in my server log.
They seem to occur an hour or two after startup, and then in small bunches.
I set logging to debug level. Here follow three of the errors in context;
i can send the full 80MB log file if anyone needs it:

Jul 16 06:26:43.325 [debug] connection_exit_begin_conn(): Creating new exit connection.
Jul 16 06:26:43.325 [debug] buf_get_initial_mem(): Got buf mem from 4096-byte freelist. Freelist has 84 entries.
Jul 16 06:26:43.325 [debug] buf_get_initial_mem(): Got buf mem from 4096-byte freelist. Freelist has 83 entries.
Jul 16 06:26:43.325 [debug] connection_exit_begin_conn(): about to start the dns_resolve().
Jul 16 06:26:43.325 [info] Rejecting invalid destination address [scrubbed]
Jul 16 06:26:43.325 [notice] dns_cancel_pending_resolve(): Bug: Address [scrubbed] is not pending. Dropping.
Jul 16 06:26:43.325 [debug] add_buf_mem_to_freelist(): Add buf mem to 4096-byte freelist. Freelist has 84 entries.
Jul 16 06:26:43.325 [debug] add_buf_mem_to_freelist(): Add buf mem to 4096-byte freelist. Freelist has 85 entries.
Jul 16 06:26:43.325 [debug] relay_send_command_from_edge(): delivering 3 cell backward.
Jul 16 06:26:43.326 [debug] append_cell_to_circuit_queue(): Made a circuit active.
Jul 16 06:26:43.326 [debug] append_cell_to_circuit_queue(): Primed a buffer.
Jul 16 06:26:43.326 [debug] write_to_buf(): added 512 bytes to buf (now 512 total).
Jul 16 06:26:43.326 [debug] connection_or_flush_from_first_active_circuit(): Made a circuit inactive.
Jul 16 06:26:43.326 [debug] connection_or_process_cells_from_inbuf(): 138: starting, inbuf_datalen 15360 (0 pending in tls object).
Jul 16 06:26:43.326 [debug] circuit_receive_relay_cell(): Sending away from origin.
Jul 16 06:26:43.326 [debug] connection_edge_process_relay_cell(): Now seen 199320 relay cells here.
Jul 16 06:26:43.326 [debug] connection_exit_begin_conn(): Creating new exit connection.
Jul 16 06:26:43.326 [debug] buf_get_initial_mem(): Got buf mem from 4096-byte freelist. Freelist has 84 entries.
Jul 16 06:26:43.326 [debug] buf_get_initial_mem(): Got buf mem from 4096-byte freelist. Freelist has 83 entries.
Jul 16 06:26:43.326 [debug] connection_exit_begin_conn(): about to start the dns_resolve().
Jul 16 06:26:43.326 [info] Rejecting invalid destination address [scrubbed]
Jul 16 06:26:43.326 [notice] dns_cancel_pending_resolve(): Bug: Address [scrubbed] is not pending. Dropping.
Jul 16 06:26:43.326 [debug] add_buf_mem_to_freelist(): Add buf mem to 4096-byte freelist. Freelist has 84 entries.
Jul 16 06:26:43.326 [debug] add_buf_mem_to_freelist(): Add buf mem to 4096-byte freelist. Freelist has 85 entries.
Jul 16 06:26:43.326 [debug] relay_send_command_from_edge(): delivering 3 cell backward.
Jul 16 06:26:43.326 [debug] append_cell_to_circuit_queue(): Made a circuit active.
Jul 16 06:26:43.326 [debug] connection_or_process_cells_from_inbuf(): 138: starting, inbuf_datalen 14848 (0 pending in tls object).
Jul 16 06:26:43.327 [debug] circuit_receive_relay_cell(): Sending away from origin.
Jul 16 06:26:43.327 [debug] connection_edge_process_relay_cell(): Now seen 199321 relay cells here.
Jul 16 06:26:43.327 [debug] connection_exit_begin_conn(): Creating new exit connection.
Jul 16 06:26:43.327 [debug] buf_get_initial_mem(): Got buf mem from 4096-byte freelist. Freelist has 84 entries.
Jul 16 06:26:43.327 [debug] buf_get_initial_mem(): Got buf mem from 4096-byte freelist. Freelist has 83 entries.
Jul 16 06:26:43.327 [debug] connection_exit_begin_conn(): about to start the dns_resolve().
Jul 16 06:26:43.327 [info] Rejecting invalid destination address [scrubbed]
Jul 16 06:26:43.327 [notice] dns_cancel_pending_resolve(): Bug: Address [scrubbed] is not pending. Dropping.

OS/Distro:
Xubuntu 7.04 fresh install
Tor 0.2.0.2-alpha from Debian Etch distro install

[Automatically added by flyspray2trac: Operating System: Other Linux]

Child Tickets

Change History (7)

comment:1 Changed 12 years ago by arma

Nice. Looks like we're cancelling the resolve request before we put it in
the queue, and then later we are shocked to find that it's not in the queue.

Could you set SafeLogging to 0 briefly so we can see what a few of the
invalid addresses are, just to make sure that part of things is working
right?

comment:2 Changed 12 years ago by arma

r10849 should address the loud log message. Nick, is this an ok patch?

comment:3 Changed 12 years ago by keb

i turned off SafeLogging and got one message 5h after restarting the server:

Jul 17 15:52:15.592 [debug] dns_resolve_impl(): Connection (fd -1) found cached error for "xx.update2.toolbar.yahoo.com"
Jul 17 15:52:15.592 [notice] dns_cancel_pending_resolve(): Bug: Address "xx.update2.toolbar.yahoo.com" is not pending. Dropping.

if i search backwards in the log from there to where this domain name is mentioned, i see:

Jul 17 15:51:58.899 [debug] connection_exit_begin_conn(): about to start the dns_resolve().
Jul 17 15:51:58.899 [debug] dns_resolve_impl(): Launching "xx.update2.toolbar.yahoo.com".
Jul 17 15:51:58.899 [info] launch_resolve(): Launching eventdns request for "xx.update2.toolbar.yahoo.com"
Jul 17 15:51:58.899 [info] eventdns: Resolve requested for xx.update2.toolbar.yahoo.com
Jul 17 15:51:58.899 [info] eventdns: Setting timeout for request 922f050
Jul 17 15:51:58.899 [debug] connection_or_process_cells_from_inbuf(): 68: starting, inbuf_datalen 0 (0 pending in tls object).

let me know if you need more info, i still have the full log file.

After a few more days running the server (with SafeLogging on and Debug off) the pattern seems to be that several hours after awakening from hibernation it gets a bunch of these bugs in a row:

Jul 18 00:02:58.728 [notice] Performing bandwidth self-test...done.
...
Jul 18 06:53:59.587 [notice] dns_cancel_pending_resolve(): Bug: Address [scrubbed] is not pending. Dropping.
Jul 18 08:56:17.500 [notice] dns_cancel_pending_resolve(): Bug: Address [scrubbed] is not pending. Dropping.
Jul 18 08:56:19.513 [notice] dns_cancel_pending_resolve(): Bug: Address [scrubbed] is not pending. Dropping.
Jul 18 08:56:21.514 [notice] dns_cancel_pending_resolve(): Bug: Address [scrubbed] is not pending. Dropping.
Jul 18 08:56:23.557 [notice] dns_cancel_pending_resolve(): Bug: Address [scrubbed] is not pending. Dropping.
Jul 18 08:56:23.817 [notice] dns_cancel_pending_resolve(): Bug: Address [scrubbed] is not pending. Dropping.
Jul 18 08:56:25.585 [notice] dns_cancel_pending_resolve(): Bug: Address [scrubbed] is not pending. Dropping.
Jul 18 09:00:23.938 [notice] dns_cancel_pending_resolve(): Bug: Address [scrubbed] is not pending. Dropping.
Jul 18 12:04:39.719 [notice] dns_cancel_pending_resolve(): Bug: Address [scrubbed] is not pending. Dropping.
Jul 18 12:18:55.598 [notice] dns_cancel_pending_resolve(): Bug: Address [scrubbed] is not pending. Dropping.
Jul 18 12:20:11.384 [notice] dns_cancel_pending_resolve(): Bug: Address [scrubbed] is not pending. Dropping.
Jul 18 12:35:23.779 [notice] Bandwidth soft limit reached; commencing hibernation.
...
Jul 19 00:01:26.577 [notice] Performing bandwidth self-test...done.
Jul 19 00:01:52.863 [notice] Self-testing indicates your DirPort is reachable from the outside. Excellent.
Jul 19 00:02:52.152 [notice] Not advertising DirPort (Reason: AccountingMax enabled)
Jul 19 09:48:38.874 [notice] dns_cancel_pending_resolve(): Bug: Address [scrubbed] is not pending. Dropping.
Jul 19 11:08:12.581 [notice] dns_cancel_pending_resolve(): Bug: Address [scrubbed] is not pending. Dropping.
Jul 19 11:08:14.845 [notice] dns_cancel_pending_resolve(): Bug: Address [scrubbed] is not pending. Dropping.
Jul 19 11:08:16.953 [notice] dns_cancel_pending_resolve(): Bug: Address [scrubbed] is not pending. Dropping.
Jul 19 15:25:11.430 [notice] Bandwidth soft limit reached; commencing hibernation.
...
Jul 20 00:01:42.274 [notice] Hibernation period ended. Resuming normal activity.
Jul 20 00:01:42.274 [notice] Opening OR listener on 0.0.0.0:9001
Jul 20 00:01:42.274 [notice] Opening Directory listener on 0.0.0.0:9030
Jul 20 03:48:32.405 [notice] dns_cancel_pending_resolve(): Bug: Address [scrubbed] is not pending. Dropping.
Jul 20 04:30:52.168 [notice] dns_cancel_pending_resolve(): Bug: Address [scrubbed] is not pending. Dropping.
Jul 20 06:33:06.090 [notice] dns_cancel_pending_resolve(): Bug: Address [scrubbed] is not pending. Dropping.
Jul 20 06:33:06.090 [notice] dns_cancel_pending_resolve(): Bug: Address [scrubbed] is not pending. Dropping.
Jul 20 07:31:06.464 [notice] dns_cancel_pending_resolve(): Bug: Address [scrubbed] is not pending. Dropping.
Jul 20 10:01:58.618 [notice] dns_cancel_pending_resolve(): Bug: Address [scrubbed] is not pending. Dropping.
Jul 20 10:02:46.388 [notice] dns_cancel_pending_resolve(): Bug: Address [scrubbed] is not pending. Dropping.
Jul 20 10:09:43.448 [notice] dns_cancel_pending_resolve(): Bug: Address [scrubbed] is not pending. Dropping.
Jul 20 10:12:03.042 [notice] dns_cancel_pending_resolve(): Bug: Address [scrubbed] is not pending. Dropping.
Jul 20 10:12:03.043 [notice] dns_cancel_pending_resolve(): Bug: Address [scrubbed] is not pending. Dropping.
Jul 20 11:09:52.924 [notice] dns_cancel_pending_resolve(): Bug: Address [scrubbed] is not pending. Dropping.
Jul 20 14:14:15.136 [notice] dns_cancel_pending_resolve(): Bug: Address [scrubbed] is not pending. Dropping.
Jul 20 14:14:15.154 [notice] dns_cancel_pending_resolve(): Bug: Address [scrubbed] is not pending. Dropping.
Jul 20 14:14:15.154 [notice] dns_cancel_pending_resolve(): Bug: Address [scrubbed] is not pending. Dropping.
Jul 20 14:17:17.515 [notice] dns_cancel_pending_resolve(): Bug: Address [scrubbed] is not pending. Dropping.
Jul 20 14:17:49.775 [notice] dns_cancel_pending_resolve(): Bug: Address [scrubbed] is not pending. Dropping.
Jul 20 16:29:30.449 [notice] dns_cancel_pending_resolve(): Bug: Address [scrubbed] is not pending. Dropping.
Jul 20 16:48:22.624 [notice] dns_cancel_pending_resolve(): Bug: Address [scrubbed] is not pending. Dropping.
Jul 20 17:57:52.044 [notice] dns_cancel_pending_resolve(): Bug: Address [scrubbed] is not pending. Dropping.
Jul 20 17:57:52.045 [notice] dns_cancel_pending_resolve(): Bug: Address [scrubbed] is not pending. Dropping.
Jul 20 17:57:53.506 [notice] dns_cancel_pending_resolve(): Bug: Address [scrubbed] is not pending. Dropping.
Jul 20 18:40:40.285 [notice] Bandwidth soft limit reached; commencing hibernation.
...
Jul 21 00:15:32.335 [notice] Hibernation period ended. Resuming normal activity.
Jul 21 00:15:32.335 [notice] Opening OR listener on 0.0.0.0:9001
Jul 21 00:15:32.335 [notice] Opening Directory listener on 0.0.0.0:9030
Jul 21 02:18:26.190 [notice] dns_cancel_pending_resolve(): Bug: Address [scrubbed] is not pending. Dropping.
Jul 21 02:18:26.422 [notice] dns_cancel_pending_resolve(): Bug: Address [scrubbed] is not pending. Dropping.
Jul 21 02:44:52.060 [notice] dns_cancel_pending_resolve(): Bug: Address [scrubbed] is not pending. Dropping.
Jul 21 03:29:34.072 [notice] dns_cancel_pending_resolve(): Bug: Address [scrubbed] is not pending. Dropping.
Jul 21 04:06:10.488 [notice] dns_cancel_pending_resolve(): Bug: Address [scrubbed] is not pending. Dropping.
Jul 21 04:47:00.506 [notice] dns_cancel_pending_resolve(): Bug: Address [scrubbed] is not pending. Dropping.
Jul 21 04:47:00.620 [notice] dns_cancel_pending_resolve(): Bug: Address [scrubbed] is not pending. Dropping.
Jul 21 04:47:00.657 [notice] dns_cancel_pending_resolve(): Bug: Address [scrubbed] is not pending. Dropping.
Jul 21 04:47:00.734 [notice] dns_cancel_pending_resolve(): Bug: Address [scrubbed] is not pending. Dropping.
Jul 21 04:47:00.770 [notice] dns_cancel_pending_resolve(): Bug: Address [scrubbed] is not pending. Dropping.
Jul 21 05:33:18.853 [warn] eventdns: All nameservers have failed
Jul 21 05:33:28.879 [notice] eventdns: Nameserver 192.168.7.1 is back up
Jul 21 05:51:32.361 [notice] dns_cancel_pending_resolve(): Bug: Address [scrubbed] is not pending. Dropping.
Jul 21 06:49:29.091 [notice] dns_cancel_pending_resolve(): Bug: Address [scrubbed] is not pending. Dropping.
Jul 21 06:50:20.109 [notice] dns_cancel_pending_resolve(): Bug: Address [scrubbed] is not pending. Dropping.
Jul 21 07:38:41.619 [notice] dns_cancel_pending_resolve(): Bug: Address [scrubbed] is not pending. Dropping.
Jul 21 07:55:36.131 [notice] dns_cancel_pending_resolve(): Bug: Address [scrubbed] is not pending. Dropping.
Jul 21 08:41:42.324 [notice] dns_cancel_pending_resolve(): Bug: Address [scrubbed] is not pending. Dropping.
Jul 21 08:53:47.608 [notice] dns_cancel_pending_resolve(): Bug: Address [scrubbed] is not pending. Dropping.
Jul 21 12:19:54.281 [notice] dns_cancel_pending_resolve(): Bug: Address [scrubbed] is not pending. Dropping.
Jul 21 12:40:45.952 [notice] dns_cancel_pending_resolve(): Bug: Address [scrubbed] is not pending. Dropping.
Jul 21 12:41:00.891 [notice] dns_cancel_pending_resolve(): Bug: Address [scrubbed] is not pending. Dropping.
Jul 21 12:41:02.014 [notice] dns_cancel_pending_resolve(): Bug: Address [scrubbed] is not pending. Dropping.
Jul 21 12:41:09.668 [notice] dns_cancel_pending_resolve(): Bug: Address [scrubbed] is not pending. Dropping.
Jul 21 12:41:12.472 [notice] dns_cancel_pending_resolve(): Bug: Address [scrubbed] is not pending. Dropping.
Jul 21 12:41:20.111 [notice] dns_cancel_pending_resolve(): Bug: Address [scrubbed] is not pending. Dropping.
Jul 21 12:41:21.355 [notice] dns_cancel_pending_resolve(): Bug: Address [scrubbed] is not pending. Dropping.
Jul 21 12:41:28.863 [notice] dns_cancel_pending_resolve(): Bug: Address [scrubbed] is not pending. Dropping.
Jul 21 12:41:29.348 [notice] dns_cancel_pending_resolve(): Bug: Address [scrubbed] is not pending. Dropping.
Jul 21 12:41:37.609 [notice] dns_cancel_pending_resolve(): Bug: Address [scrubbed] is not pending. Dropping.
Jul 21 12:41:38.656 [notice] dns_cancel_pending_resolve(): Bug: Address [scrubbed] is not pending. Dropping.
Jul 21 12:41:46.817 [notice] dns_cancel_pending_resolve(): Bug: Address [scrubbed] is not pending. Dropping.
Jul 21 12:41:54.852 [notice] dns_cancel_pending_resolve(): Bug: Address [scrubbed] is not pending. Dropping.
Jul 21 12:41:55.160 [notice] dns_cancel_pending_resolve(): Bug: Address [scrubbed] is not pending. Dropping.
Jul 21 13:32:52.202 [notice] dns_cancel_pending_resolve(): Bug: Address [scrubbed] is not pending. Dropping.
Jul 21 13:39:28.263 [notice] dns_cancel_pending_resolve(): Bug: Address [scrubbed] is not pending. Dropping.
Jul 21 14:53:27.075 [notice] dns_cancel_pending_resolve(): Bug: Address [scrubbed] is not pending. Dropping.
Jul 21 15:45:33.994 [notice] dns_cancel_pending_resolve(): Bug: Address [scrubbed] is not pending. Dropping.
Jul 21 15:51:42.458 [notice] dns_cancel_pending_resolve(): Bug: Address [scrubbed] is not pending. Dropping.
Jul 21 15:57:52.083 [notice] Bandwidth soft limit reached; commencing hibernation.

comment:4 Changed 12 years ago by fk

I'm getting similar messages with Tor 0.2.0.4-alpha (r11023)
on FreeBSD 7.0-CURRENT, they look like this:

Aug 18 20:20:52.456 [notice] dns_cancel_pending_resolve(): Bug: Address "bt.cn5566.com" is not pending (state 3). Dropping.
Aug 18 20:20:52.581 [notice] dns_cancel_pending_resolve(): Bug: Address "bt.cn5566.com" is not pending (state 3). Dropping.
Aug 18 20:21:41.448 [notice] dns_cancel_pending_resolve(): Bug: Address "bt.cn5566.com" is not pending (state 3). Dropping.

The message is usually repeated several times in short intervals
and, probably more important, the address is never resolved:

%nslookup bt.cn5566.com
Server: 81.169.148.34
Address: 81.169.148.34#53

server can't find bt.cn5566.com.serverkompetenz.net: NXDOMAIN

I got the same result with about ten others addresses I tried.

A lot of those addresses don't even look valid, some examples:
wpad, fritz.box, ilmioip, hakia, ulra.

State is always 3.

comment:5 Changed 12 years ago by nickm

"State is always 3"?!

Aha! It's not a bug after all. It's just us finding a cached failure, and saying "cancel the pending resolve if any"
and then having dns_cancel_pending_resolve() find the cached failure too and flip out.

Fixing.

comment:6 Changed 12 years ago by nickm

flyspray2trac: bug closed.
Fixed in r11829; fix will appear in 0.2.0.8-alpha.

comment:7 Changed 7 years ago by nickm

Component: Tor RelayTor
Note: See TracTickets for help on using tickets.