[tor-bugs] #16706 [Tor]: Too many connection_edge_process_relay_cell warnings

[Tor Bug Tracker & Wiki]

#16706: Too many connection_edge_process_relay_cell warnings
------------------------+------------------------------
     Reporter:  s7r     |      Owner:
         Type:  defect  |     Status:  new
     Priority:  normal  |  Milestone:
    Component:  Tor     |    Version:  Tor: 0.2.6.10
   Resolution:          |   Keywords:  tor-hs, SponsorR
Actual Points:          |  Parent ID:
       Points:          |
------------------------+------------------------------

Comment (by s7r):

 After ~10 hours the log file grows fast with so so many lines:
 {{{
 Aug 02 08:53:58.000 [warn] connection_edge_process_relay_cell (at origin)
 failed.
 }}}

 Decided to look at it closer and changed log level to info. Left Tor to
 log info level for about ~7 minutes, and I got a log file with 3966 lines,
 out of which 3364 are the same, with an average of about 25 with the exact
 same timestamp:

 {{{
 Aug 02 08:39:24.000 [info] cell_ewma_set_scale_factor(): Enabled cell_ewma
 algorithm because of value in CircuitPriorityHalflifeMsec in consensus;
 scale factor is 0.793701 per 10 seconds
 Aug 02 08:39:24.000 [info] options_act(): Worker-related options changed.
 Rotating workers.
 Aug 02 08:39:24.000 [info] connection_edge_package_raw_inbuf(): called
 with package_window 0. Skipping.
 Aug 02 08:39:24.000 [info] connection_edge_package_raw_inbuf(): called
 with package_window 0. Skipping.
 Aug 02 08:39:24.000 [info] connection_edge_package_raw_inbuf(): called
 with package_window 0. Skipping.
 Aug 02 08:39:24.000 [info] connection_edge_package_raw_inbuf(): called
 with package_window 0. Skipping.
 Aug 02 08:39:24.000 [info] connection_edge_package_raw_inbuf(): called
 with package_window 0. Skipping.
 Aug 02 08:39:24.000 [info] connection_edge_package_raw_inbuf(): called
 with package_window 0. Skipping.
 Aug 02 08:39:24.000 [info] connection_edge_package_raw_inbuf(): called
 with package_window 0. Skipping.
 Aug 02 08:39:24.000 [info] connection_edge_package_raw_inbuf(): called
 with package_window 0. Skipping.
 Aug 02 08:39:24.000 [info] connection_edge_package_raw_inbuf(): called
 with package_window 0. Skipping.
 Aug 02 08:39:24.000 [info] connection_edge_package_raw_inbuf(): called
 with package_window 0. Skipping.
 Aug 02 08:39:24.000 [info] connection_edge_package_raw_inbuf(): called
 with package_window 0. Skipping.
 Aug 02 08:39:24.000 [info] connection_edge_package_raw_inbuf(): called
 with package_window 0. Skipping.
 Aug 02 08:39:24.000 [info] connection_edge_package_raw_inbuf(): called
 with package_window 0. Skipping.
 Aug 02 08:39:24.000 [info] connection_edge_package_raw_inbuf(): called
 with package_window 0. Skipping.
 Aug 02 08:39:24.000 [info] connection_edge_package_raw_inbuf(): called
 with package_window 0. Skipping.
 Aug 02 08:39:24.000 [info] connection_edge_package_raw_inbuf(): called
 with package_window 0. Skipping.
 }}}

 Here are the log messages surrounding the [warn] message:
 {{{
 Aug 02 08:40:03.000 [info] connection_edge_package_raw_inbuf(): called
 with package_window 0. Skipping.
 Aug 02 08:40:03.000 [info] connection_edge_package_raw_inbuf(): called
 with package_window 0. Skipping.
 Aug 02 08:40:03.000 [info] connection_edge_package_raw_inbuf(): called
 with package_window 0. Skipping.
 Aug 02 08:40:03.000 [info] connection_edge_package_raw_inbuf(): called
 with package_window 0. Skipping.
 Aug 02 08:40:03.000 [info] connection_edge_package_raw_inbuf(): called
 with package_window 0. Skipping.
 Aug 02 08:40:03.000 [info] connection_exit_begin_conn(): begin is for
 rendezvous. configuring stream.
 Aug 02 08:40:03.000 [info] rend_service_set_connection_addr_port(): No
 virtual port mapping exists for port 8333 on service dioq2yg3l5ptgpge
 Aug 02 08:40:03.000 [info] connection_exit_begin_conn(): Didn't find
 rendezvous service (port 8333)
 Aug 02 08:40:03.000 [warn] connection_edge_process_relay_cell (at origin)
 failed.
 Aug 02 08:40:03.000 [info] command_process_relay_cell():
 circuit_receive_relay_cell (backward) failed. Closing.
 Aug 02 08:40:03.000 [info] connection_edge_package_raw_inbuf(): called
 with package_window 0. Skipping.
 Aug 02 08:40:03.000 [info] connection_edge_package_raw_inbuf(): called
 with package_window 0. Skipping.
 Aug 02 08:40:03.000 [info] connection_edge_package_raw_inbuf(): called
 with package_window 0. Skipping.
 Aug 02 08:40:03.000 [info] connection_edge_package_raw_inbuf(): called
 with package_window 0. Skipping.
 Aug 02 08:40:03.000 [info] connection_edge_package_raw_inbuf(): called
 with package_window 0. Skipping.
 Aug 02 08:40:03.000 [info] connection_edge_package_raw_inbuf(): called
 with package_window 0. Skipping.
 Aug 02 08:40:03.000 [info] connection_exit_begin_conn(): begin is for
 rendezvous. configuring stream.
 }}}

 The same for the other messages - before each one it appears that a client
 tries to connect to an existent hidden service but at a virtual port which
 is not configured for that hidden service.

--
Ticket URL: <https://trac.torproject.org/projects/tor/ticket/16706#comment:2>
Tor Bug Tracker & Wiki <https://trac.torproject.org/>
The Tor Project: anonymity online