Opened 7 years ago

Closed 7 years ago

Last modified 7 years ago

#6638 closed defect (fixed)

Lots of Unknown Error in tor.log

Reported by: oyvinds Owned by:
Priority: High Milestone: Tor: 0.2.4.x-final
Component: Core Tor/Tor Version: Tor: unspecified
Severity: Keywords: tor-hs
Cc: andrea Actual Points:
Parent ID: Points:
Reviewer: Sponsor:

Description

using git.

Aug 19 21:17:54.000 [warn] unknown error for INTRODUCE2 on circ 53605
Aug 19 21:18:17.000 [warn] unknown error for INTRODUCE2 on circ 11793
Aug 19 21:18:49.000 [warn] unknown error for INTRODUCE2 on circ 30079
Aug 19 21:19:03.000 [warn] unknown error for INTRODUCE2 on circ 30079
Aug 19 21:19:36.000 [warn] unknown error for INTRODUCE2 on circ 53605

Child Tickets

Change History (10)

comment:1 Changed 7 years ago by rransom

Cc: andrea added
Milestone: Tor: unspecifiedTor: 0.2.4.x-final
Priority: minormajor

Which Git commit?

comment:2 Changed 7 years ago by oyvinds

# git pull
Already up-to-date.

I have the latest git.

Aug 19 19:23:51.000 [warn] unknown error for INTRODUCE2 on circ 56398
Aug 19 19:24:00.000 [warn] unknown error for INTRODUCE2 on circ 56398
Aug 19 19:27:40.000 [warn] unknown error for INTRODUCE2 on circ 10650
(..)
Aug 20 02:36:54.000 [warn] unknown error for INTRODUCE2 on circ 10651
Aug 20 02:47:48.000 [warn] unknown error for INTRODUCE2 on circ 15889

comment:3 Changed 7 years ago by nickm

I'd focus on the instances of "goto err" in rend_service_introduce that are preceded by a log_info. I'm guessing this is the master branch.

andrea, come to think of it, might the problem be that we're logging at all? If the issue that makes us "goto err" is just something we're logging at info-level, there isn't much point in logging a corresponding message at warn level as we leave the function.

comment:4 Changed 7 years ago by oyvinds

Priority: majortrivial

Aug 20 15:50:48.000 [info] rend_service_introduce(): Received INTRODUCE2 cell for service "$service" on circ 20680.
Aug 20 15:50:48.000 [info] rend_service_introduce(): Accepted intro; launching circuit to [scrubbed] (cookie A3FF904F) for service $service.
Aug 20 15:50:50.000 [info] rend_service_rendezvous_has_opened(): Done building circuit 20713 to rendezvous with cookie A3FF904F for service $service
Aug 20 15:50:50.000 [info] rend_service_introduce(): Received INTRODUCE2 cell for service "$service" on circ 20683.
Aug 20 15:50:50.000 [info] rend_service_introduce(): We received an INTRODUCE2 cell with same first part of Diffie-Hellman handshake 2 seconds ago. Dropping cell.
Aug 20 15:50:50.000 [warn] unknown error for INTRODUCE2 on circ 20683

Aug 20 16:02:03.000 [info] rend_service_rendezvous_has_opened(): Done building circuit 3267 to rendezvous with cookie 199D1382 for service $service
Aug 20 16:02:04.000 [info] rend_service_introduce(): Received INTRODUCE2 cell for service "$service" on circ 20680.
Aug 20 16:02:04.000 [info] rend_service_introduce(): Accepted intro; launching circuit to [scrubbed] (cookie 1983E8BE) for service $service.
Aug 20 16:02:04.000 [info] connection_exit_begin_conn(): begin is for rendezvous. configuring stream.
Aug 20 16:02:04.000 [info] connection_exit_begin_conn(): begin is for rendezvous. configuring stream.
Aug 20 16:02:05.000 [info] rend_service_introduce(): Received INTRODUCE2 cell for service "$service" on circ 20683.
Aug 20 16:02:05.000 [info] rend_service_introduce(): We received an INTRODUCE2 cell with same first part of Diffie-Hellman handshake 1 seconds ago. Dropping cell.
Aug 20 16:02:05.000 [warn] unknown error for INTRODUCE2 on circ 20683

Aug 20 16:10:59.000 [info] circuit_build_failed(): Couldn't connect to Alice's chosen rend point "$9F89491CAB7B03685DEABD358E193FFA74D8D836" (non-last hop failed).
Aug 20 16:10:59.000 [info] rend_service_relaunch_rendezvous(): Reattempting rendezvous circuit to '[scrubbed]'
Aug 20 16:11:00.000 [info] connection_exit_begin_conn(): begin is for rendezvous. configuring stream.
Aug 20 16:11:00.000 [info] rend_service_relaunch_rendezvous(): Reattempting rendezvous circuit to '[scrubbed]'
Aug 20 16:11:01.000 [info] rend_service_rendezvous_has_opened(): Done building circuit 46785 to rendezvous with cookie 8F56BED6 for service $service
Aug 20 16:11:01.000 [info] rend_service_rendezvous_has_opened(): Done building circuit 3331 to rendezvous with cookie 68AC6DF4 for service $service
Aug 20 16:11:01.000 [info] rend_service_introduce(): Received INTRODUCE2 cell for service "$service" on circ 20683.
Aug 20 16:11:01.000 [info] rend_service_introduce(): We received an INTRODUCE2 cell with same first part of Diffie-Hellman handshake 4 seconds ago. Dropping cell.
Aug 20 16:11:01.000 [warn] unknown error for INTRODUCE2 on circ 20683

The line "We received an INTRODUCE2 cell with same first part of Diffie-Hellman handshake some seconds ago. Dropping cell." is always there before the unknown error. It seems they are sending Diffie-Hellman handshakes with the same first part and that cases the unknown error.

comment:5 Changed 7 years ago by rransom

Component: Tor RelayTor Hidden Services
Priority: trivialmajor

Oh, this is on a Tor instance which is providing a hidden service, not a relay.

This is a bad bug -- Tor is not supposed to log the times that clients attempt to connect to a hidden service.

comment:6 Changed 7 years ago by nickm

Status: newneeds_review

Please review "bug6638" in my public repo.

comment:7 Changed 7 years ago by andrea

Looks okay to me.

comment:8 Changed 7 years ago by nickm

Resolution: fixed
Status: needs_reviewclosed

thanks! Merged.

comment:9 Changed 7 years ago by nickm

Keywords: tor-hs added

comment:10 Changed 7 years ago by nickm

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