Skip to content
Snippets Groups Projects
New look: Off

Too many connection_edge_process_relay_cell warnings

    • Closed (moved) Issue created by s7r @s7r

    Hosting multiple hidden services on a Debian server running Tor 0.2.6.10 (no special setup or config options). I see thousands of such lines in the log files:

    Jul 31 07:55:39.000 [warn] connection_edge_process_relay_cell (at origin) failed.
Jul 31 07:57:59.000 [warn] connection_edge_process_relay_cell (at origin) failed.
Jul 31 08:00:36.000 [warn] connection_edge_process_relay_cell (at origin) failed.
Jul 31 08:02:49.000 [warn] connection_edge_process_relay_cell (at origin) failed.
Jul 31 08:05:12.000 [warn] connection_edge_process_relay_cell (at origin) failed.
Jul 31 08:07:30.000 [warn] connection_edge_process_relay_cell (at origin) failed.
Jul 31 08:09:49.000 [warn] connection_edge_process_relay_cell (at origin) failed.
Jul 31 08:12:09.000 [warn] connection_edge_process_relay_cell (at origin) failed.
Jul 31 08:14:30.000 [warn] connection_edge_process_relay_cell (at origin) failed.
Jul 31 08:16:50.000 [warn] connection_edge_process_relay_cell (at origin) failed.
Jul 31 08:19:11.000 [warn] connection_edge_process_relay_cell (at origin) failed.
Jul 31 08:21:45.000 [warn] connection_edge_process_relay_cell (at origin) failed.
Jul 31 08:24:14.000 [warn] connection_edge_process_relay_cell (at origin) failed.
Jul 31 08:26:27.000 [warn] connection_edge_process_relay_cell (at origin) failed.
Jul 31 08:29:01.000 [warn] connection_edge_process_relay_cell (at origin) failed.
Jul 31 08:31:18.000 [warn] connection_edge_process_relay_cell (at origin) failed.
Jul 31 08:33:38.000 [warn] connection_edge_process_relay_cell (at origin) failed.
Jul 31 08:35:58.000 [warn] connection_edge_process_relay_cell (at origin) failed.

    All hidden services are working and accessible, didn't reload/restart Tor. What is concerning is that there are so so many of these messages in a very short time. #9635 (moved) mentioned this as well, but along with other error messages which were indicating a wrong nTor key. Here we only have a single line, heavily repeated at short time intervals.

    To upload designs, you'll need to enable LFS and have an admin enable hashed storage. More information

    Child items ...

    • Activity

    • s7r changed milestone to %Tor: 0.3.1.x-final

      changed milestone to %Tor: 0.3.1.x-final

    • s7r added component::core tor/tor milestone::Tor: 0.3.1.x-final nickm-deferred-20161017 owner::dgoulet points::3 priority::medium resolution::fixed reviewer::nickm severity::normal sponsor::R-can status::closed tor-hs triage-out-030-201612 type::defect version::tor 0.2.6.10 labels

      added component::core tor/tor milestone::Tor: 0.3.1.x-final nickm-deferred-20161017 owner::dgoulet points::3 priority::medium resolution::fixed reviewer::nickm severity::normal sponsor::R-can status::closed tor-hs triage-out-030-201612 type::defect version::tor 0.2.6.10 labels

    • S
      s7r @s7r ·
      Author

      Trac:
      Description: Hosting multiple hidden services on a Debian server running Tor 0.2.6.10 (no special setup or config options). I see thousands of such lines in the log files:

      Jul 31 07:55:39.000 [warn] connection_edge_process_relay_cell (at origin) failed.
Jul 31 07:57:59.000 [warn] connection_edge_process_relay_cell (at origin) failed.
Jul 31 08:00:36.000 [warn] connection_edge_process_relay_cell (at origin) failed.
Jul 31 08:02:49.000 [warn] connection_edge_process_relay_cell (at origin) failed.
Jul 31 08:05:12.000 [warn] connection_edge_process_relay_cell (at origin) failed.
Jul 31 08:07:30.000 [warn] connection_edge_process_relay_cell (at origin) failed.
Jul 31 08:09:49.000 [warn] connection_edge_process_relay_cell (at origin) failed.
Jul 31 08:12:09.000 [warn] connection_edge_process_relay_cell (at origin) failed.
Jul 31 08:14:30.000 [warn] connection_edge_process_relay_cell (at origin) failed.
Jul 31 08:16:50.000 [warn] connection_edge_process_relay_cell (at origin) failed.
Jul 31 08:19:11.000 [warn] connection_edge_process_relay_cell (at origin) failed.
Jul 31 08:21:45.000 [warn] connection_edge_process_relay_cell (at origin) failed.
Jul 31 08:24:14.000 [warn] connection_edge_process_relay_cell (at origin) failed.
Jul 31 08:26:27.000 [warn] connection_edge_process_relay_cell (at origin) failed.
Jul 31 08:29:01.000 [warn] connection_edge_process_relay_cell (at origin) failed.
Jul 31 08:31:18.000 [warn] connection_edge_process_relay_cell (at origin) failed.
Jul 31 08:33:38.000 [warn] connection_edge_process_relay_cell (at origin) failed.
Jul 31 08:35:58.000 [warn] connection_edge_process_relay_cell (at origin) failed.

      All hidden services are working and accessible, didn't reload/restart Tor. What is concerning is that there are so so many of these messages in a very short time.

      to

      Hosting multiple hidden services on a Debian server running Tor 0.2.6.10 (no special setup or config options). I see thousands of such lines in the log files:

      Jul 31 07:55:39.000 [warn] connection_edge_process_relay_cell (at origin) failed.
Jul 31 07:57:59.000 [warn] connection_edge_process_relay_cell (at origin) failed.
Jul 31 08:00:36.000 [warn] connection_edge_process_relay_cell (at origin) failed.
Jul 31 08:02:49.000 [warn] connection_edge_process_relay_cell (at origin) failed.
Jul 31 08:05:12.000 [warn] connection_edge_process_relay_cell (at origin) failed.
Jul 31 08:07:30.000 [warn] connection_edge_process_relay_cell (at origin) failed.
Jul 31 08:09:49.000 [warn] connection_edge_process_relay_cell (at origin) failed.
Jul 31 08:12:09.000 [warn] connection_edge_process_relay_cell (at origin) failed.
Jul 31 08:14:30.000 [warn] connection_edge_process_relay_cell (at origin) failed.
Jul 31 08:16:50.000 [warn] connection_edge_process_relay_cell (at origin) failed.
Jul 31 08:19:11.000 [warn] connection_edge_process_relay_cell (at origin) failed.
Jul 31 08:21:45.000 [warn] connection_edge_process_relay_cell (at origin) failed.
Jul 31 08:24:14.000 [warn] connection_edge_process_relay_cell (at origin) failed.
Jul 31 08:26:27.000 [warn] connection_edge_process_relay_cell (at origin) failed.
Jul 31 08:29:01.000 [warn] connection_edge_process_relay_cell (at origin) failed.
Jul 31 08:31:18.000 [warn] connection_edge_process_relay_cell (at origin) failed.
Jul 31 08:33:38.000 [warn] connection_edge_process_relay_cell (at origin) failed.
Jul 31 08:35:58.000 [warn] connection_edge_process_relay_cell (at origin) failed.

      All hidden services are working and accessible, didn't reload/restart Tor. What is concerning is that there are so so many of these messages in a very short time. #9635 (moved) mentioned this as well, but along with other error messages which were indicating a wrong nTor key. Here we only have a single line, heavily repeated at short time intervals.

    • S
      s7r @s7r ·
      Author

      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.

    • S
      s7r @s7r ·
      Author

      After trying on 0.2.7.2-alpha as well (2 separate servers), I can confirm that the message:

      [warn] connection_edge_process_relay_cell (at origin) failed.

      appears in Tor's log file every time I try to connect to an existent hidden service at a different virtual port than the one(s) configured via HiddenServicePort. Does this bother Tor or puts load on it in any way? Seams like a trivial attack for any script kiddie.

    • Nick Mathewson
      Nick Mathewson @nickm ·

      Trac:
      Keywords: N/A deleted, 026-backport added
      Milestone: N/A to Tor: 0.2.7.x-final

    • Nick Mathewson
      Nick Mathewson @nickm ·

      I'd merge patches for these for 0.2.7 if they come in on time. In some cases, that will require figuring out an as-yet-unsolved bugs.

      Trac:
      Keywords: N/A deleted, PostFreeze027 added

    • Nick Mathewson
      Nick Mathewson @nickm ·

      Moving these tickets into 0.2.8. Not expecting to take patches for any into 0.2.7 at this late date. As usual, please say something if you disagree! :)

      Trac:
      Milestone: Tor: 0.2.7.x-final to Tor: 0.2.8.x-final
      Keywords: PostFreeze027 deleted, N/A added

    • Nick Mathewson
      Nick Mathewson @nickm ·

      Bulk-replace SponsorR keyword with SponsorR sponsor field in Tor component.

      Trac:
      Sponsor: N/A to SponsorR
      Keywords: SponsorR deleted, N/A added

    • David Goulet
      David Goulet @dgoulet ·

      Trac:
      Points: N/A to medium

    • Nick Mathewson
      Nick Mathewson @nickm ·

      Throw most 0.2.8 "NEW" tickets into 0.2.9. I expect that many of them will subsequently get triaged out.

      Trac:
      Milestone: Tor: 0.2.8.x-final to Tor: 0.2.9.x-final

    • David Goulet
      David Goulet @dgoulet ·

      Move those from SponsorR to SponsorR-can.

      Trac:
      Sponsor: SponsorR to SponsorR-can

    • Roger Dingledine
      Roger Dingledine @arma ·

      Trac:
      Reviewer: N/A to N/A
      Owner: N/A to arma
      Severity: N/A to Normal
      Status: new to assigned

    • Isabela Fernandes
      Isabela Fernandes @isabela ·

      Trac:
      Points: medium to 3

    • Nick Mathewson
      Nick Mathewson @nickm ·

      I am fairly sure that these are neither regressions nor major problems. So, deferring from 0.2.9. Please let me know if I'm wrong.

      Trac:
      Milestone: Tor: 0.2.9.x-final to Tor: 0.3.0.x-final
      Keywords: N/A deleted, nickm-deferred-20161017 added

    • Roger Dingledine
      Roger Dingledine @arma ·

      This line occurs every time a client tries to visit a port on your onion service which is not configured. For example, if you put your onion service on virtual port 80, and somebody tries to visit virtual port 22.

      So as onion service crawlers get more popular and more aggressive, we'll be seeing more of these lines.

      I think there's another ticket for this issue open somewhere too.

    • S
      s7r @s7r ·
      Author

      Yes, this is true and confirmed (comment 3 on this ticket). What I think we should do is discover why this log message is printed when the described event occurs and see if it causes any load over the Tor process. Requests on non-configured virtual ports should be discarded in a way that spends the lowest amount of resources possible.

    • David Goulet
      David Goulet @dgoulet ·

      Triaged out on December 2016 from 030 to 031.

      Trac:
      Keywords: N/A deleted, triage-out-030-201612 added
      Milestone: Tor: 0.3.0.x-final to Tor: 0.3.1.x-final

    • Roger Dingledine
      Roger Dingledine @arma ·

      Replying to s7r:

      What I think we should do is discover why this log message is printed when the described event occurs

      It's because some function deep inside Tor returns -1 for failure, and the calling function thinks -1 means it needs to log a warning. It's a great opportunity for refactoring. (In fact, I hear Chelsea enjoys refactoring, so I am cc'ing her on this ticket. :)

      and see if it causes any load over the Tor process. Requests on non-configured virtual ports should be discarded in a way that spends the lowest amount of resources possible.

      I think there isn't any extra load, except for the warning.

      Trac:
      Cc: N/A to chelseakomlo

    • Roger Dingledine
      Roger Dingledine @arma ·

      Somehow I was the owner of this ticket. I am marking it as unclaimed so people can step in.

      Trac:
      Owner: arma to N/A

    • Loading
    • Loading
    • Loading
    • Loading
    • Loading
    • Loading
    • Loading
    • Loading
    • Loading
    • Loading
    Please register or sign in to reply