Opened 5 years ago

Last modified 2 years ago

#12184 new defect

Circuit on detached list which I had no reason to mark

Reported by: cypherpunks Owned by:
Priority: High Milestone: Tor: unspecified
Component: Core Tor/Tor Version: Tor: 0.2.5.10
Severity: Normal Keywords: tor-relay needs-insight
Cc: andrea, reezer, starlight@… Actual Points:
Parent ID: Points:
Reviewer: Sponsor:

Description

I still get this in combination with other warnings. Using FreeBSD 10, with OpenSSL 1.0.1, Tor 0.2.5.4-alpha (git-d2147cc7ba5c5d51).

Jun 01 09:35:49.000 [warn] No unused circIDs found on channel without wide circID support, with 0 inbound and 11 outbound circuits. Found 0 circuit IDs in use by circuits, and 64 with pending destroy cells.Failing a circuit.
Jun 01 09:35:49.000 [warn] failed to get unique circID.
Jun 01 11:17:45.000 [warn] No unused circIDs found on channel without wide circID support, with 0 inbound and 14 outbound circuits. Found 0 circuit IDs in use by circuits, and 64 with pending destroy cells.Failing a circuit.
Jun 01 13:11:58.000 [warn] No unused circIDs found on channel without wide circID support, with 0 inbound and 6 outbound circuits. Found 0 circuit IDs in use by circuits, and 64 with pending destroy cells.Failing a circuit.
Jun 01 13:11:58.000 [warn] failed to get unique circID. [12 similar message(s) suppressed in last 9600 seconds]
Jun 01 13:37:42.000 [notice] Heartbeat: Tor's uptime is 1 day 0:00 hours, with 26180 circuits open. I've sent 901.07 GB and received 858.20 GB.
Jun 01 13:37:42.000 [notice] Average packaged cell fullness: 99.170%
Jun 01 13:37:42.000 [notice] TLS write overhead: 4%
Jun 01 13:37:42.000 [notice] Circuit handshake stats since last time: 1759080/1759080 TAP, 117360/117360 NTor.
Jun 01 19:37:42.000 [notice] Heartbeat: Tor's uptime is 1 day 6:00 hours, with 24593 circuits open. I've sent 1167.66 GB and received 1110.36 GB.
Jun 01 19:37:42.000 [notice] Average packaged cell fullness: 99.179%
Jun 01 19:37:42.000 [notice] TLS write overhead: 4%
Jun 01 19:37:42.000 [notice] Circuit handshake stats since last time: 2056892/2056893 TAP, 136701/136701 NTor.
Jun 02 01:37:42.000 [notice] Heartbeat: Tor's uptime is 1 day 12:00 hours, with 13869 circuits open. I've sent 1395.03 GB and received 1329.05 GB.
Jun 02 01:37:42.000 [notice] Average packaged cell fullness: 99.181%
Jun 02 01:37:42.000 [notice] TLS write overhead: 4%
Jun 02 01:37:42.000 [notice] Circuit handshake stats since last time: 943086/943086 TAP, 86362/86362 NTor.
Jun 02 04:03:15.000 [warn] void circuit_unlink_all_from_channel(channel_t *, int)(): Bug: Circuit on detached list which I had no reason to mark

Child Tickets

Attachments (2)

jRMYE0N5.svg (91.2 KB) - added by cypherpunks 5 years ago.
3 days graph for 74.109.24.185
k62zhU0x.svg (87.7 KB) - added by cypherpunks 5 years ago.
3 days graph for 84.74.35.60

Download all attachments as: .zip

Change History (69)

comment:1 Changed 5 years ago by arma

Milestone: Tor: 0.2.5.x-final

comment:2 Changed 5 years ago by cypherpunks

Several days before:

May 28 16:31:51.000 [warn] Unexpected sendme cell from client. Closing circ (window 1000).
May 28 16:35:20.000 [warn] No unused circIDs found on channel without wide circID support, with 0 inbound and 6 outbound circuits. Found 0 circuit IDs in use by circuits, and 64 with pending destroy cells.Failing a circuit.
May 28 18:51:24.000 [warn] No unused circIDs found on channel without wide circID support, with 0 inbound and 12 outbound circuits. Found 0 circuit IDs in use by circuits, and 64 with pending destroy cells.Failing a circuit.
May 28 18:51:24.000 [warn] failed to get unique circID. [7 similar message(s) suppressed in last 9600 seconds]

comment:3 Changed 5 years ago by nickm

Interesting. Given that 0+64, 11+64, 14+64 and so on are all much less than 1<<15, it's clear we have a bug here.

It's also interesting that in every case here, the count of pending destroy cells is 64.

comment:4 Changed 5 years ago by nickm

Oh duh. 64 is the number of attempts that were made, not the total number of circuits.

Something must be filling up the circuit ID space with pending destroy cells. :P

comment:5 Changed 5 years ago by nickm

Keywords: 024-backport added

comment:6 Changed 5 years ago by nickm

Cc: andrea added

circuit_unlink_all_from_channel makes me think the circuitmux code could be involved in some stage of this. Still not sure. I made some verbose log code to try to track mismatched destroy pending/destroy un-pending cases. I found in the process that one case I thought was impossible is actually possible, but it does not appear to be responsible.

I don't know at this point whether this is one bug or two.

My verbose logging is in branch "diag12184"

comment:7 Changed 5 years ago by nickm

I wonder if command_process_destroy_cell could be (in part?) at fault. What happens if it gets a DESTROY for a circuit for which it is planning to send a DESTROY?

comment:8 Changed 5 years ago by nickm

And for that matter, look at this stupid code in command_process_destroy_cell.

  if (!CIRCUIT_IS_ORIGIN(circ) &&
      cell->circ_id == TO_OR_CIRCUIT(circ)->p_circ_id) {

That's wrong; a circuit may have the same circ_id for both p_circ_id and n_circ_id.

comment:9 in reply to:  8 Changed 5 years ago by nickm

Replying to nickm:

a circuit may have the same circ_id for both p_circ_id and n_circ_id.

This issue is now #12195

comment:10 Changed 5 years ago by nickm

Keywords: 025-triaged added

comment:11 Changed 5 years ago by nickm

I wonder where I can best stick some diagnostic logs to figure out what's up with this. Unless the cause becomes very apparent quite soon, it would be good to have more ways to track it down.

comment:12 Changed 5 years ago by nickm

Priority: normalmajor

comment:13 Changed 5 years ago by cypherpunks

Reporting of all pending DESTROY cells number (chan->cmux->destroy_ctr) and reporting when channel was actually alive before (difference of channel_when_last_xmit(chan) and time(NULL)) could help too while warn about out of circids.

comment:14 Changed 5 years ago by cypherpunks

chan->cmux->destroy_ctr

Not so easy, but cmux->destroy_ctr for chan needs.

comment:15 in reply to:  11 Changed 5 years ago by reezer

Replying to nickm:

I wonder where I can best stick some diagnostic logs to figure out what's up with this. Unless the cause becomes very apparent quite soon, it would be good to have more ways to track it down.

Original reporter here. Anything I could do to support you? Any logging branch I should use?

comment:16 Changed 5 years ago by nickm

Hi, reezer! The best sggestion I can make is: run 0.2.5.5-alpha when it is released, and if this warning happens again, it will give a little more information than it did before. Please let us know what it says. :)

comment:17 Changed 5 years ago by nickm

Status: newneeds_review

I have a diagnostic patch in "bug12184_diagnostic" that will make the code log more useful information. It needs code review; I want to try to get it into 0.2.5.5-alpha.

comment:18 Changed 5 years ago by nickm

To explain more about my "bug12184_diagnostic" branch, currently pending review:

There are two possibilities behind this bug as far as I can tell:

  1. There really are ~32K pending DESTROY cells waiting to get flushed on these channels.
    1. Because a huge number of circuits all died at once, and we're flushing their DESTROY cells fairly.
    2. Because there is a bug that makes us not flush destroy cells.
  2. These circuit IDs are marked unusable in the (circuitid,channel)->circuit map, but they are not really unusable.
    1. They should never have been marked.
    2. They were marked correctly on this channel, but when we sent a DESTROY cell, they never got un-marked.
    3. They were marked correctly on this channel, but for some reason we never sent a DESTROY cell, so they never got un-marked.
    4. They were marked correctly on another channel. When that channel was freed, the (circuitid,channel) pair was never marked as usable again. Later, another channel was created, and received the same address as the original channel.

I think that we can learn whether case 1.1 or case 1.2 applies by logging how many destroy cells are pending when we hit this error case. (My patch also checks the count of pending destroy cells for correctness, and for consistency with the (circid,channel) map.)

I think we can learn whether one of the 2.1..2.4 subcases applies by the timestamps my patch adds to the placeholder entries. If any entry older than the channel, we'll know that it's case 2.4. If all entries are very new, we can guess case 1.1. If the entries are very old but not older than the channel, we can guess that it's one of 1.2 or 2.1..3, depending on the result from logging how many destroy cells are pending.

At that point, we will know what to investigate more closely.

comment:19 Changed 5 years ago by yawning

Was asked to look over the diff on IRC, and the only thing that stood out was

circuitbuild.c:179

      if (0)
        circuitmux_assert_okay(chan->cmux);

Per nickm:

that's there so I can tell people "remove that line if you know how to use gdb and you want to help us debug it and you don't mind a little extra crashing"

Suggest a comment there stating intent.

circuitmux.c:1912

/*DOCODC; for debugging 12184.  This runs slowly. */

Typeo.

The actual code looks good to me.

comment:20 Changed 5 years ago by andrea

This patch looks fine to me; echo Yawning's remark about wanting an explanatory comment on the 'if (0)' thing.

comment:21 Changed 5 years ago by nickm

Status: needs_reviewneeds_information

Added/tweaked some comments and merged; thanks!

comment:22 Changed 5 years ago by b0b3r

Just for information, I have plenty of those with 0.2.5.5_alpha:

Jun 23 13:25:38 ESBEK-tor2 Tor[30367]: No unused circIDs found on channel without wide circID support, with 0 inbound and 4294682885 outbound circuits. Found 0 circuit IDs in use by circuits, and 64 with pendin
g destroy cells. (0 of those were marked bogusly.) The ones with pending destroy cells have been marked unusable for an average of 53839 seconds and a maximum of 69022 seconds. This channel is 73061 seconds old
. Failing a circuit. [28287 similar message(s) suppressed in last 3600 seconds]
Jun 23 13:25:38 ESBEK-tor2 Tor[30367]: circuitmux_count_queued_destroy_cells(): Bug:   Discrepancy in counts for queued destroy cells on circuitmux. n=317177. queue_size=317177. manual_total=317177. manual_tota
l_in_map=32766.
Jun 23 13:25:38 ESBEK-tor2 Tor[30367]:   Circuitmux on this channel has 0 circuits, of which 0 are active. It says it has 317177 destroy cells queued.
Jun 23 14:05:38 ESBEK-tor2 Tor[30367]: failed to get unique circID. [139652 similar message(s) suppressed in last 9600 seconds]
Jun 23 14:19:54 ESBEK-tor2 Tor[30367]: No unused circIDs found on channel without wide circID support, with 0 inbound and 4294842664 outbound circuits. Found 0 circuit IDs in use by circuits, and 64 with pendin
g destroy cells. (0 of those were marked bogusly.) The ones with pending destroy cells have been marked unusable for an average of 19091 seconds and a maximum of 23348 seconds. This channel is 57391 seconds old
. Failing a circuit. [20164 similar message(s) suppressed in last 3600 seconds]
Jun 23 14:19:54 ESBEK-tor2 Tor[30367]: circuitmux_count_queued_destroy_cells(): Bug:   Discrepancy in counts for queued destroy cells on circuitmux. n=157396. queue_size=157396. manual_total=157396. manual_tota
l_in_map=32764.
Jun 23 14:19:54 ESBEK-tor2 Tor[30367]:   Circuitmux on this channel has 0 circuits, of which 0 are active. It says it has 157396 destroy cells queued.

comment:23 Changed 5 years ago by nickm

Wow; this is pretty tangled. I find this hard to believe:

4294682885 outbound circuits

Do we have a counting bug?

And this could be a bug:

Discrepancy in counts for queued destroy cells on circuitmux

And this might show where stuff is going wrong:

n=317177. queue_size=317177. manual_total=317177. manual_total_in_map=32766.

It looks as if, according to this, these destroy cells are never getting sent at all!

comment:24 Changed 5 years ago by cypherpunks

Last edited 5 years ago by cypherpunks (previous) (diff)

comment:25 Changed 5 years ago by reezer

Getting the same:

Jul 05 18:46:39.000 [warn] No unused circIDs found on channel without wide circID support, with 0 inbound and 4294945635 outbound circuits. Found 0 circuit IDs in use by circuits, and 64 with pending destroy cells. (0 of those were marked bogusly.) The ones with pending destroy cells have been marked unusable for an average of 29141 seconds and a maximum of 43234 seconds. This channel is 55313 seconds old. Failing a circuit. [666 similar message(s) suppressed in last 3600 seconds]
Jul 05 18:46:39.000 [warn] int64_t circuitmux_count_queued_destroy_cells(const channel_t *, const circuitmux_t *)(): Bug:   Discrepancy in counts for queued destroy cells on circuitmux. n=53535. queue_size=53535. manual_total=53535. manual_total_in_map=31872.
Jul 05 18:46:39.000 [warn]   Circuitmux on this channel has 2 circuits, of which 2 are active. It says it has 53535 destroy cells queued.

comment:26 Changed 5 years ago by reezer

Could this be related to using and IPv6 ORPort (or multiple)? I disabled it and didn't get the warning yet (after one day of uptime), but multiple of those:

Jul 11 07:31:53.000 [warn] Unexpected sendme cell from client. Closing circ (window 1000).

Not sure, if this is related though. By the way. The node is pixelminer[1] The only maybe not too thing I can see in common with esbek2[2] is that we both are unnamed currently and that they have non existing family members, but I guess that has nothing to do with it, right?

[1] https://atlas.torproject.org/#details/CE75BF0972ADD52AF8807602374E495C815DB304
[2] https://atlas.torproject.org/#details/CEF77136F1CF939D44D18F4B9E3D8AE3656C6CBF

Last edited 5 years ago by reezer (previous) (diff)

comment:27 Changed 5 years ago by nickm

I added a call to channel_dump_statisticss() here in 5d2045ee8ba42a294291b187234be6ead6864cab . Maybe more information about the channel will help.

comment:28 Changed 5 years ago by reezer

Couldn't really wait for the new version, so I added the line to 2.5.5-alpha manually. This means any other patches from git are not in there. Only that one line of nickm's patch. Here is the output:

Jul 18 13:52:47.000 [warn] No unused circIDs found on channel without wide circID support, with 0 inbound and 7 outbound circuits. Found 0 circuit IDs in use by circuits, and 64 with pending destroy cells. (0 of those were marked bogusly.) The ones with pending destroy cells have been marked unusable for an average of 3765 seconds and a maximum of 7826 seconds. This channel is 8145 seconds old. Failing a circuit.
Jul 18 13:52:47.000 [warn]   Circuitmux on this channel has 7 circuits, of which 4 are active. It says it has 28070 destroy cells queued.
Jul 18 13:52:47.000 [warn] Channel 343 (at 0x8079fa680) with transport TLS channel (connection 368) is in state open (2)
Jul 18 13:52:47.000 [warn]  * Channel 343 was created at 1405683422 (8145 seconds ago) and last active at 1405691384 (183 seconds ago)
Jul 18 13:52:47.000 [warn]  * Channel 343 says it is connected to an OR with digest 4C733BAC82CC609ACC58AD95BFBFF04D5D06188C and no known nickname
Jul 18 13:52:47.000 [warn]  * Channel 343 says its remote address is 74.109.24.185, and gives a canonical description of "74.109.24.185:8443" and an actual description of "74.109.24.185:8443"
Jul 18 13:52:47.000 [warn]  * Channel 343 has these marks: !bad_for_new_circs canonical is_canonical_is_reliable !client !local outgoing
Jul 18 13:52:47.000 [warn]  * Channel 343 has 0 queued incoming cells and 0 queued outgoing cells
Jul 18 13:52:47.000 [warn]  * Channel 343 has 4 active circuits out of 7 in total
Jul 18 13:52:47.000 [warn]  * Channel 343 was last used by a client at 0 (1405691567 seconds ago)
Jul 18 13:52:47.000 [warn]  * Channel 343 was last drained at 1405691296 (271 seconds ago)
Jul 18 13:52:47.000 [warn]  * Channel 343 last received a cell at 1405691384 (183 seconds ago)
Jul 18 13:52:47.000 [warn]  * Channel 343 last trasmitted a cell at 1405691296 (271 seconds ago)
Jul 18 13:52:47.000 [warn]  * Channel 343 has received 111 cells and transmitted 653
Jul 18 13:52:47.000 [warn]  * Channel 343 has averaged 73.378378 seconds between received cells
Jul 18 13:52:47.000 [warn]  * Channel 343 has averaged 12.473201 seconds between transmitted cells
Jul 18 13:52:47.000 [warn] failed to get unique circID.
Jul 18 14:52:47.000 [warn] No unused circIDs found on channel without wide circID support, with 0 inbound and 4294960895 outbound circuits. Found 0 circuit IDs in use by circuits, and 64 with pending destroy cells. (0 of those were marked bogusly.) The ones with pending destroy cells have been marked unusable for an average of 7113 seconds and a maximum of 11407 seconds. This channel is 11745 seconds old. Failing a circuit. [6401 similar message(s) suppressed in last 3600 seconds]
Jul 18 14:52:47.000 [warn] int64_t circuitmux_count_queued_destroy_cells(const channel_t *, const circuitmux_t *)(): Bug:   Discrepancy in counts for queued destroy cells on circuitmux. n=39152. queue_size=39152. manual_total=39152. manual_total_in_map=32750.
Jul 18 14:52:47.000 [warn]   Circuitmux on this channel has 1 circuits, of which 0 are active. It says it has 39152 destroy cells queued.
Jul 18 14:52:47.000 [warn] Channel 343 (at 0x8079fa680) with transport TLS channel (connection 368) is in state open (2)
Jul 18 14:52:47.000 [warn]  * Channel 343 was created at 1405683422 (11745 seconds ago) and last active at 1405695043 (124 seconds ago)
Jul 18 14:52:47.000 [warn]  * Channel 343 says it is connected to an OR with digest 4C733BAC82CC609ACC58AD95BFBFF04D5D06188C and no known nickname
Jul 18 14:52:47.000 [warn]  * Channel 343 says its remote address is 74.109.24.185, and gives a canonical description of "74.109.24.185:8443" and an actual description of "74.109.24.185:8443"
Jul 18 14:52:47.000 [warn]  * Channel 343 has these marks: !bad_for_new_circs canonical is_canonical_is_reliable !client !local outgoing
Jul 18 14:52:47.000 [warn]  * Channel 343 has 0 queued incoming cells and 0 queued outgoing cells
Jul 18 14:52:47.000 [warn]  * Channel 343 has 0 active circuits out of 1 in total
Jul 18 14:52:47.000 [warn]  * Channel 343 was last used by a client at 0 (1405695167 seconds ago)
Jul 18 14:52:47.000 [warn]  * Channel 343 was last drained at 1405694818 (349 seconds ago)
Jul 18 14:52:47.000 [warn]  * Channel 343 last received a cell at 1405695043 (124 seconds ago)
Jul 18 14:52:47.000 [warn]  * Channel 343 last trasmitted a cell at 1405694818 (349 seconds ago)
Jul 18 14:52:47.000 [warn]  * Channel 343 has received 158 cells and transmitted 1144
Jul 18 14:52:47.000 [warn]  * Channel 343 has averaged 74.335443 seconds between received cells
Jul 18 14:52:47.000 [warn]  * Channel 343 has averaged 10.266608 seconds between transmitted cells
Jul 18 15:52:47.000 [warn] No unused circIDs found on channel without wide circID support, with 0 inbound and 4294950748 outbound circuits. Found 0 circuit IDs in use by circuits, and 64 with pending destroy cells. (0 of those were marked bogusly.) The ones with pending destroy cells have been marked unusable for an average of 9601 seconds and a maximum of 14700 seconds. This channel is 15345 seconds old. Failing a circuit. [10146 similar message(s) suppressed in last 3600 seconds]
Jul 18 15:52:47.000 [warn] int64_t circuitmux_count_queued_destroy_cells(const channel_t *, const circuitmux_t *)(): Bug:   Discrepancy in counts for queued destroy cells on circuitmux. n=49289. queue_size=49289. manual_total=49289. manual_total_in_map=32740.
Jul 18 15:52:47.000 [warn]   Circuitmux on this channel has 1 circuits, of which 0 are active. It says it has 49289 destroy cells queued.
Jul 18 15:52:47.000 [warn] Channel 343 (at 0x8079fa680) with transport TLS channel (connection 368) is in state open (2)
Jul 18 15:52:47.000 [warn]  * Channel 343 was created at 1405683422 (15345 seconds ago) and last active at 1405698517 (250 seconds ago)
Jul 18 15:52:47.000 [warn]  * Channel 343 says it is connected to an OR with digest 4C733BAC82CC609ACC58AD95BFBFF04D5D06188C and no known nickname
Jul 18 15:52:47.000 [warn]  * Channel 343 says its remote address is 74.109.24.185, and gives a canonical description of "74.109.24.185:8443" and an actual description of "74.109.24.185:8443"
Jul 18 15:52:47.000 [warn]  * Channel 343 has these marks: !bad_for_new_circs canonical is_canonical_is_reliable !client !local outgoing
Jul 18 15:52:47.000 [warn]  * Channel 343 has 0 queued incoming cells and 0 queued outgoing cells
Jul 18 15:52:47.000 [warn]  * Channel 343 has 0 active circuits out of 1 in total
Jul 18 15:52:47.000 [warn]  * Channel 343 was last used by a client at 0 (1405698767 seconds ago)
Jul 18 15:52:47.000 [warn]  * Channel 343 was last drained at 1405698499 (268 seconds ago)
Jul 18 15:52:47.000 [warn]  * Channel 343 last received a cell at 1405696718 (2049 seconds ago)
Jul 18 15:52:47.000 [warn]  * Channel 343 last trasmitted a cell at 1405698499 (268 seconds ago)
Jul 18 15:52:47.000 [warn]  * Channel 343 has received 163 cells and transmitted 1666
Jul 18 15:52:47.000 [warn]  * Channel 343 has averaged 94.141104 seconds between received cells
Jul 18 15:52:47.000 [warn]  * Channel 343 has averaged 9.210684 seconds between transmitted cells
Jul 18 16:32:47.000 [warn] failed to get unique circID. [23057 similar message(s) suppressed in last 9600 seconds]
Last edited 5 years ago by reezer (previous) (diff)

comment:29 Changed 5 years ago by reezer

Cc: reezer added

comment:30 Changed 5 years ago by nickm

Interesting. It looks like there's one doomed channel here, it's still sending and receiving stuff (since the last read and last transmitted parts keep getting updatd), but that it has a huge number of destroy cells to send, and they're not getting sent. Anybody have any good guesses here?

comment:31 Changed 5 years ago by cypherpunks

Channel 343 was last drained at 1405691296 (271 seconds ago)

Almost 5 minutes. It need 100 new impatient clients per second to append 28070 destroy cells to destroy queue.

Changed 5 years ago by cypherpunks

Attachment: jRMYE0N5.svg added

3 days graph for 74.109.24.185

comment:32 Changed 5 years ago by cypherpunks

74.109.24.185 (MOBILEBURN) was HSDir. According to BW graph, it was actively used since 18 Jul 00:22 till 19 Jul 01:37
3 days graph for 74.109.24.185

Last edited 5 years ago by cypherpunks (previous) (diff)

comment:33 Changed 5 years ago by reezer

Does that mean it could actually be a third bug, since this ticket is older?

comment:34 Changed 5 years ago by reezer

Doesn't appear to be the only one, I get a few with this fingerprint now. It has the same pattern. I hope that's not caused by my relay?

Jul 20 13:31:03.000 [warn] No unused circIDs found on channel without wide circID support, with 0 inbound and 4294964108 outbound circuits. Found 0 circuit IDs in use by circuits, and 64 with pending destroy cells. (0 of those were marked bogusly.) The ones with pending destroy cells have been marked unusable for an average of 9456 seconds and a maximum of 16794 seconds. This channel is 23005 seconds old. Failing a circuit. [3187 similar message(s) suppressed in last 3600 seconds]
Jul 20 13:31:03.000 [warn] int64_t circuitmux_count_queued_destroy_cells(const channel_t *, const circuitmux_t *)(): Bug:   Discrepancy in counts for queued destroy cells on circuitmux. n=35908. queue_size=35908. manual_total=35908. manual_total_in_map=32720.
Jul 20 13:31:03.000 [warn]   Circuitmux on this channel has 0 circuits, of which 0 are active. It says it has 35908 destroy cells queued.
Jul 20 13:31:03.000 [warn] Channel 1280552 (at 0x80f936d00) with transport TLS channel (connection 2606364) is in state open (2)
Jul 20 13:31:03.000 [warn]  * Channel 1280552 was created at 1405840058 (23005 seconds ago) and last active at 1405862958 (105 seconds ago)
Jul 20 13:31:03.000 [warn]  * Channel 1280552 says it is connected to an OR with digest B89A9DA01F72A93F3B9937AE70A6473D0695F3EB and no known nickname
Jul 20 13:31:03.000 [warn]  * Channel 1280552 says its remote address is 84.74.35.60, and gives a canonical description of "84.74.35.60:443" and an actual description of "84.74.35.60:443"
Jul 20 13:31:03.000 [warn]  * Channel 1280552 has these marks: !bad_for_new_circs canonical is_canonical_is_reliable !client !local outgoing
Jul 20 13:31:03.000 [warn]  * Channel 1280552 has 0 queued incoming cells and 0 queued outgoing cells
Jul 20 13:31:03.000 [warn]  * Channel 1280552 has 0 active circuits out of 0 in total
Jul 20 13:31:03.000 [warn]  * Channel 1280552 was last used by a client at 0 (1405863063 seconds ago)
Jul 20 13:31:03.000 [warn]  * Channel 1280552 was last drained at 1405862903 (160 seconds ago)
Jul 20 13:31:03.000 [warn]  * Channel 1280552 last received a cell at 1405862958 (105 seconds ago)
Jul 20 13:31:03.000 [warn]  * Channel 1280552 last trasmitted a cell at 1405862903 (160 seconds ago)
Jul 20 13:31:03.000 [warn]  * Channel 1280552 has received 1000 cells and transmitted 4974
Jul 20 13:31:03.000 [warn]  * Channel 1280552 has averaged 23.005000 seconds between received cells
Jul 20 13:31:03.000 [warn]  * Channel 1280552 has averaged 4.625050 seconds between transmitted cells
Last edited 5 years ago by reezer (previous) (diff)

Changed 5 years ago by cypherpunks

Attachment: k62zhU0x.svg added

3 days graph for 84.74.35.60

comment:35 Changed 5 years ago by cypherpunks

84.74.35.60 (IGWT) was HSDir. According to BW graph, it was actively used since 20 Jul 7:22
3 days graph for 84.74.35.60

comment:36 Changed 5 years ago by cypherpunks

Does that mean it could actually be a third bug, since this ticket is older?

Reports in this ticket includes different bugs for sure.

No unused circIDs found on channel bug could be explained by botnet or something, without any actual bugs in code. According to reported logs, peers hangs for several minutes, which triggers filling of destroy queue:

Jul 18 15:52:47.000 [warn] * Channel 343 last trasmitted a cell at 1405698499 (268 seconds ago)
Jul 18 15:52:47.000 [warn] * Channel 343 has averaged 9.210684 seconds between transmitted cells

Jul 20 13:31:03.000 [warn] * Channel 1280552 last trasmitted a cell at 1405862903 (160 seconds ago)
Jul 20 13:31:03.000 [warn] * Channel 1280552 has averaged 4.625050 seconds between transmitted cells

4294964108 outbound circuits and Discrepancy in counts for queued destroy cells bugs are sign of memory corruption.

comment:37 Changed 5 years ago by cypherpunks

peers hangs for several minutes

Or code stops writing to channel/connection. Then it's yet another bug.

comment:38 Changed 5 years ago by cypherpunks

similar message(s) suppressed in last 3600 seconds

Where is 1st message before suppressing logs in reports? It was reported only once before:

Jul 18 13:52:47.000 [warn] No unused circIDs found on channel without wide circID support, with 0 inbound and 7 outbound circuits. Found 0 circuit IDs in use by circuits, and 64 with pending destroy cells. (0 of those were marked bogusly.) The ones with pending destroy cells have been marked unusable for an average of 3765 seconds and a maximum of 7826 seconds. This channel is 8145 seconds old. Failing a circuit.

Why? Is it bug in code?
Suppressed logs can't reliably show what happened with channel, all seconds from channel_dump_statisticss() can be skipped as nothing showing actual for bug reporting.

comment:39 in reply to:  37 Changed 5 years ago by reezer

Replying to cypherpunks:

peers hangs for several minutes

Or code stops writing to channel/connection. Then it's yet another bug.

Any idea on how to find out which one it is?

comment:40 Changed 5 years ago by cypherpunks

Any idea on how to find out which one it is?

Read code, and collect to compare information about peers for which bug triggered.

MOBILEBURN and ​IGWT are running Tor 0.2.3.25 on Windows 7

Last edited 5 years ago by cypherpunks (previous) (diff)

comment:41 Changed 5 years ago by reezer

I didn't see any of these warnings since July 26th.

comment:42 Changed 5 years ago by reezer

Getting more of these. Posting the whole log since startup. Hope that's okay.

Aug 07 18:53:53.000 [notice] Tor 0.2.5.6-alpha (git-390728d85644a6c0) opening log file.
Aug 07 18:53:53.000 [notice] Parsing GEOIP IPv4 file /usr/local/share/tor/geoip.
Aug 07 18:53:53.000 [notice] Parsing GEOIP IPv6 file /usr/local/share/tor/geoip6.
Aug 07 18:53:53.000 [notice] Configured to measure statistics. Look for the *-stats files that will first be written to the data directory in 24 hours from now.
Aug 07 18:53:53.000 [notice] Default OpenSSL engine for RSA is BSD cryptodev engine [cryptodev]
Aug 07 18:53:53.000 [notice] Default OpenSSL engine for DH is BSD cryptodev engine [cryptodev]
Aug 07 18:53:53.000 [notice] Default OpenSSL engine for AES-128-CBC is BSD cryptodev engine [cryptodev]
Aug 07 18:53:53.000 [notice] Default OpenSSL engine for AES-256-CBC is BSD cryptodev engine [cryptodev]
Aug 07 18:53:53.000 [notice] Caching new entry _tor for _tor
Aug 07 18:53:53.000 [notice] Caching new entry _tor for _tor
Aug 07 18:53:53.000 [notice] Your Tor server's identity key fingerprint is 'pixelminer CE75BF0972ADD52AF8807602374E495C815DB304'
Aug 07 18:53:53.000 [notice] Bootstrapped 0%: Starting
Aug 07 18:53:58.000 [notice] We now have enough directory information to build circuits.
Aug 07 18:53:58.000 [notice] Bootstrapped 80%: Connecting to the Tor network
Aug 07 18:53:58.000 [notice] Self-testing indicates your ORPort is reachable from the outside. Excellent. Publishing server descriptor.
Aug 07 18:53:58.000 [notice] Bootstrapped 85%: Finishing handshake with first hop
Aug 07 18:53:59.000 [notice] Bootstrapped 90%: Establishing a Tor circuit
Aug 07 18:54:00.000 [notice] Tor has successfully opened a circuit. Looks like client functionality is working.
Aug 07 18:54:00.000 [notice] Bootstrapped 100%: Done
Aug 07 18:55:00.000 [notice] Self-testing indicates your DirPort is reachable from the outside. Excellent.
Aug 07 18:55:01.000 [notice] Performing bandwidth self-test...done.
Aug 08 00:53:59.000 [notice] Heartbeat: Tor's uptime is 6:00 hours, with 12407 circuits open. I've sent 251.20 GB and received 240.97 GB.
Aug 08 00:53:59.000 [notice] Average packaged cell fullness: 99.222%
Aug 08 00:53:59.000 [notice] TLS write overhead: 3%
Aug 08 00:53:59.000 [notice] Circuit handshake stats since last time: 589649/589649 TAP, 107361/107361 NTor.
Aug 08 01:49:44.000 [warn] Unexpected onionskin length after decryption: 58
Aug 08 06:53:59.000 [notice] Heartbeat: Tor's uptime is 12:00 hours, with 14661 circuits open. I've sent 453.43 GB and received 435.17 GB.
Aug 08 06:53:59.000 [notice] Average packaged cell fullness: 99.228%
Aug 08 06:53:59.000 [notice] TLS write overhead: 3%
Aug 08 06:53:59.000 [notice] Circuit handshake stats since last time: 440176/440176 TAP, 89561/89561 NTor.
Aug 08 10:52:27.000 [warn] No unused circIDs found on channel without wide circID support, with 0 inbound and 0 outbound circuits. Found 0 circuit IDs in use by circuits, and 64 with pending destroy cells. (0 of those were marked bogusly.) The ones with pending destroy cells have been marked unusable for an average of 12191 seconds and a maximum of 26305 seconds. This channel is 36597 seconds old. Failing a circuit.
Aug 08 10:52:27.000 [warn]   Circuitmux on this channel has 0 circuits, of which 0 are active. It says it has 29899 destroy cells queued.
Aug 08 10:52:27.000 [warn] Channel 168983 (at 0x808874c80) with transport TLS channel (connection 387334) is in state open (2)
Aug 08 10:52:27.000 [warn]  * Channel 168983 was created at 1407458550 (36597 seconds ago) and last active at 1407495115 (32 seconds ago)
Aug 08 10:52:27.000 [warn]  * Channel 168983 says it is connected to an OR with digest 4C733BAC82CC609ACC58AD95BFBFF04D5D06188C and no known nickname
Aug 08 10:52:27.000 [warn]  * Channel 168983 says its remote address is [scrubbed], and gives a canonical description of "[scrubbed]" and an actual description of "[scrubbed]"
Aug 08 10:52:27.000 [warn]  * Channel 168983 has these marks: !bad_for_new_circs canonical is_canonical_is_reliable !client !local outgoing
Aug 08 10:52:27.000 [warn]  * Channel 168983 has 0 queued incoming cells and 0 queued outgoing cells
Aug 08 10:52:27.000 [warn]  * Channel 168983 has 0 active circuits out of 0 in total
Aug 08 10:52:27.000 [warn]  * Channel 168983 was last used by a client at 0 (1407495147 seconds ago)
Aug 08 10:52:27.000 [warn]  * Channel 168983 was last drained at 1407495064 (83 seconds ago)
Aug 08 10:52:27.000 [warn]  * Channel 168983 last received a cell at 1407495115 (32 seconds ago)
Aug 08 10:52:27.000 [warn]  * Channel 168983 last transmitted a cell at 1407495064 (83 seconds ago)
Aug 08 10:52:27.000 [warn]  * Channel 168983 has received 351 cells and transmitted 8517
Aug 08 10:52:27.000 [warn]  * Channel 168983 has averaged 104.264957 seconds between received cells
Aug 08 10:52:27.000 [warn]  * Channel 168983 has averaged 4.296936 seconds between transmitted cells
Aug 08 10:52:27.000 [warn] failed to get unique circID.
Aug 08 12:53:59.000 [notice] Heartbeat: Tor's uptime is 18:00 hours, with 16917 circuits open. I've sent 685.60 GB and received 656.94 GB.
Aug 08 12:53:59.000 [notice] Average packaged cell fullness: 99.219%
Aug 08 12:53:59.000 [notice] TLS write overhead: 3%
Aug 08 12:53:59.000 [notice] Circuit handshake stats since last time: 582606/582606 TAP, 89096/89096 NTor.
Aug 08 18:53:54.000 [notice] Caching new entry _tor for _tor
Aug 08 18:53:59.000 [notice] Heartbeat: Tor's uptime is 1 day 0:00 hours, with 19417 circuits open. I've sent 934.30 GB and received 894.42 GB.
Aug 08 18:53:59.000 [notice] Average packaged cell fullness: 99.204%
Aug 08 18:53:59.000 [notice] TLS write overhead: 3%
Aug 08 18:53:59.000 [notice] Circuit handshake stats since last time: 747335/747335 TAP, 111457/111457 NTor.
Aug 08 21:08:56.000 [warn] No unused circIDs found on channel without wide circID support, with 0 inbound and 4 outbound circuits. Found 0 circuit IDs in use by circuits, and 64 with pending destroy cells. (0 of those were marked bogusly.) The ones with pending destroy cells have been marked unusable for an average of 9479 seconds and a maximum of 20277 seconds. This channel is 33029 seconds old. Failing a circuit.
Aug 08 21:08:56.000 [warn]   Circuitmux on this channel has 4 circuits, of which 3 are active. It says it has 28810 destroy cells queued.
Aug 08 21:08:56.000 [warn] Channel 470025 (at 0x80f913400) with transport TLS channel (connection 1062759) is in state open (2)
Aug 08 21:08:56.000 [warn]  * Channel 470025 was created at 1407499107 (33029 seconds ago) and last active at 1407532064 (72 seconds ago)
Aug 08 21:08:56.000 [warn]  * Channel 470025 says it is connected to an OR with digest 92AA57343957296C7EC89A976609DBB33C56E75F and no known nickname
Aug 08 21:08:56.000 [warn]  * Channel 470025 says its remote address is [scrubbed], and gives a canonical description of "[scrubbed]" and an actual description of "[scrubbed]"
Aug 08 21:08:56.000 [warn]  * Channel 470025 has these marks: !bad_for_new_circs canonical is_canonical_is_reliable !client !local outgoing
Aug 08 21:08:56.000 [warn]  * Channel 470025 has 0 queued incoming cells and 0 queued outgoing cells
Aug 08 21:08:56.000 [warn]  * Channel 470025 has 3 active circuits out of 4 in total
Aug 08 21:08:56.000 [warn]  * Channel 470025 was last used by a client at 0 (1407532136 seconds ago)
Aug 08 21:08:56.000 [warn]  * Channel 470025 was last drained at 1407531711 (425 seconds ago)
Aug 08 21:08:56.000 [warn]  * Channel 470025 last received a cell at 1407532064 (72 seconds ago)
Aug 08 21:08:56.000 [warn]  * Channel 470025 last transmitted a cell at 1407531711 (425 seconds ago)
Aug 08 21:08:56.000 [warn]  * Channel 470025 has received 1111 cells and transmitted 7739
Aug 08 21:08:56.000 [warn]  * Channel 470025 has averaged 29.729073 seconds between received cells
Aug 08 21:08:56.000 [warn]  * Channel 470025 has averaged 4.267864 seconds between transmitted cells
Aug 08 21:08:56.000 [warn] failed to get unique circID. [173 similar message(s) suppressed in last 9600 seconds]
Aug 08 22:09:03.000 [warn] No unused circIDs found on channel without wide circID support, with 0 inbound and 4294966947 outbound circuits. Found 0 circuit IDs in use by circuits, and 64 with pending destroy cells. (0 of those were marked bogusly.) The ones with pending destroy cells have been marked unusable for an average of 9669 seconds and a maximum of 22486 seconds. This channel is 36636 seconds old. Failing a circuit. [352 similar message(s) suppressed in last 3600 seconds]
Aug 08 22:09:03.000 [warn] int64_t circuitmux_count_queued_destroy_cells(const channel_t *, const circuitmux_t *)(): Bug:   Discrepancy in counts for queued destroy cells on circuitmux. n=32391. queue_size=32391. manual_total=32391. manual_total_in_map=32038.
Aug 08 22:09:03.000 [warn]   Circuitmux on this channel has 4 circuits, of which 3 are active. It says it has 32391 destroy cells queued.
Aug 08 22:09:03.000 [warn] Channel 470025 (at 0x80f913400) with transport TLS channel (connection 1062759) is in state open (2)
Aug 08 22:09:03.000 [warn]  * Channel 470025 was created at 1407499107 (36636 seconds ago) and last active at 1407535711 (32 seconds ago)
Aug 08 22:09:03.000 [warn]  * Channel 470025 says it is connected to an OR with digest 92AA57343957296C7EC89A976609DBB33C56E75F and no known nickname
Aug 08 22:09:03.000 [warn]  * Channel 470025 says its remote address is [scrubbed], and gives a canonical description of "[scrubbed]" and an actual description of "[scrubbed]"
Aug 08 22:09:03.000 [warn]  * Channel 470025 has these marks: !bad_for_new_circs canonical is_canonical_is_reliable !client !local outgoing
Aug 08 22:09:03.000 [warn]  * Channel 470025 has 0 queued incoming cells and 0 queued outgoing cells
Aug 08 22:09:03.000 [warn]  * Channel 470025 has 3 active circuits out of 4 in total
Aug 08 22:09:03.000 [warn]  * Channel 470025 was last used by a client at 0 (1407535743 seconds ago)
Aug 08 22:09:03.000 [warn]  * Channel 470025 was last drained at 1407535711 (32 seconds ago)
Aug 08 22:09:03.000 [warn]  * Channel 470025 last received a cell at 1407535496 (247 seconds ago)
Aug 08 22:09:03.000 [warn]  * Channel 470025 last transmitted a cell at 1407535711 (32 seconds ago)
Aug 08 22:09:03.000 [warn]  * Channel 470025 has received 1157 cells and transmitted 9472
Aug 08 22:09:03.000 [warn]  * Channel 470025 has averaged 31.664650 seconds between received cells
Aug 08 22:09:03.000 [warn]  * Channel 470025 has averaged 3.867821 seconds between transmitted cells
Aug 08 23:09:03.000 [warn] No unused circIDs found on channel without wide circID support, with 0 inbound and 4294963843 outbound circuits. Found 0 circuit IDs in use by circuits, and 64 with pending destroy cells. (0 of those were marked bogusly.) The ones with pending destroy cells have been marked unusable for an average of 13802 seconds and a maximum of 24216 seconds. This channel is 40236 seconds old. Failing a circuit. [3100 similar message(s) suppressed in last 3600 seconds]
Aug 08 23:09:03.000 [warn] int64_t circuitmux_count_queued_destroy_cells(const channel_t *, const circuitmux_t *)(): Bug:   Discrepancy in counts for queued destroy cells on circuitmux. n=35988. queue_size=35988. manual_total=35988. manual_total_in_map=32534.
Aug 08 23:09:03.000 [warn]   Circuitmux on this channel has 1 circuits, of which 1 are active. It says it has 35988 destroy cells queued.
Aug 08 23:09:03.000 [warn] Channel 470025 (at 0x80f913400) with transport TLS channel (connection 1062759) is in state open (2)
Aug 08 23:09:03.000 [warn]  * Channel 470025 was created at 1407499107 (40236 seconds ago) and last active at 1407539211 (132 seconds ago)
Aug 08 23:09:03.000 [warn]  * Channel 470025 says it is connected to an OR with digest 92AA57343957296C7EC89A976609DBB33C56E75F and no known nickname
Aug 08 23:09:03.000 [warn]  * Channel 470025 says its remote address is [scrubbed], and gives a canonical description of "[scrubbed]" and an actual description of "[scrubbed]"
Aug 08 23:09:03.000 [warn]  * Channel 470025 has these marks: !bad_for_new_circs canonical is_canonical_is_reliable !client !local outgoing
Aug 08 23:09:03.000 [warn]  * Channel 470025 has 0 queued incoming cells and 0 queued outgoing cells
Aug 08 23:09:03.000 [warn]  * Channel 470025 has 1 active circuits out of 1 in total
Aug 08 23:09:03.000 [warn]  * Channel 470025 was last used by a client at 0 (1407539343 seconds ago)
Aug 08 23:09:03.000 [warn]  * Channel 470025 was last drained at 1407539211 (132 seconds ago)
Aug 08 23:09:03.000 [warn]  * Channel 470025 last received a cell at 1407538905 (438 seconds ago)
Aug 08 23:09:03.000 [warn]  * Channel 470025 last transmitted a cell at 1407539211 (132 seconds ago)
Aug 08 23:09:03.000 [warn]  * Channel 470025 has received 1184 cells and transmitted 11506
Aug 08 23:09:03.000 [warn]  * Channel 470025 has averaged 33.983108 seconds between received cells
Aug 08 23:09:03.000 [warn]  * Channel 470025 has averaged 3.496958 seconds between transmitted cells
Aug 08 23:48:56.000 [warn] failed to get unique circID. [6268 similar message(s) suppressed in last 9600 seconds]
Aug 09 00:09:03.000 [warn] No unused circIDs found on channel without wide circID support, with 0 inbound and 4294959578 outbound circuits. Found 0 circuit IDs in use by circuits, and 64 with pending destroy cells. (0 of those were marked bogusly.) The ones with pending destroy cells have been marked unusable for an average of 12737 seconds and a maximum of 26003 seconds. This channel is 43836 seconds old. Failing a circuit. [4264 similar message(s) suppressed in last 3600 seconds]
Aug 09 00:09:03.000 [warn] int64_t circuitmux_count_queued_destroy_cells(const channel_t *, const circuitmux_t *)(): Bug:   Discrepancy in counts for queued destroy cells on circuitmux. n=40192. queue_size=40192. manual_total=40192. manual_total_in_map=32473.
Aug 09 00:09:03.000 [warn]   Circuitmux on this channel has 1 circuits, of which 0 are active. It says it has 40192 destroy cells queued.
Aug 09 00:09:03.000 [warn] Channel 470025 (at 0x80f913400) with transport TLS channel (connection 1062759) is in state open (2)
Aug 09 00:09:03.000 [warn]  * Channel 470025 was created at 1407499107 (43836 seconds ago) and last active at 1407542941 (2 seconds ago)
Aug 09 00:09:03.000 [warn]  * Channel 470025 says it is connected to an OR with digest 92AA57343957296C7EC89A976609DBB33C56E75F and no known nickname
Aug 09 00:09:03.000 [warn]  * Channel 470025 says its remote address is [scrubbed], and gives a canonical description of "[scrubbed]" and an actual description of "[scrubbed]"
Aug 09 00:09:03.000 [warn]  * Channel 470025 has these marks: !bad_for_new_circs canonical is_canonical_is_reliable !client !local outgoing
Aug 09 00:09:03.000 [warn]  * Channel 470025 has 0 queued incoming cells and 0 queued outgoing cells
Aug 09 00:09:03.000 [warn]  * Channel 470025 has 0 active circuits out of 1 in total
Aug 09 00:09:03.000 [warn]  * Channel 470025 was last used by a client at 0 (1407542943 seconds ago)
Aug 09 00:09:03.000 [warn]  * Channel 470025 was last drained at 1407542941 (2 seconds ago)
Aug 09 00:09:03.000 [warn]  * Channel 470025 last received a cell at 1407542525 (418 seconds ago)
Aug 09 00:09:03.000 [warn]  * Channel 470025 last transmitted a cell at 1407542941 (2 seconds ago)
Aug 09 00:09:03.000 [warn]  * Channel 470025 has received 1193 cells and transmitted 13295
Aug 09 00:09:03.000 [warn]  * Channel 470025 has averaged 36.744342 seconds between received cells
Aug 09 00:09:03.000 [warn]  * Channel 470025 has averaged 3.297179 seconds between transmitted cells
Aug 09 00:53:59.000 [notice] Heartbeat: Tor's uptime is 1 day 6:00 hours, with 16366 circuits open. I've sent 1231.13 GB and received 1180.03 GB.
Aug 09 00:53:59.000 [notice] Average packaged cell fullness: 99.210%
Aug 09 00:53:59.000 [notice] TLS write overhead: 3%
Aug 09 00:53:59.000 [notice] Circuit handshake stats since last time: 876089/876089 TAP, 175127/175127 NTor.
Aug 09 01:09:03.000 [warn] No unused circIDs found on channel without wide circID support, with 0 inbound and 4294954530 outbound circuits. Found 0 circuit IDs in use by circuits, and 64 with pending destroy cells. (0 of those were marked bogusly.) The ones with pending destroy cells have been marked unusable for an average of 17421 seconds and a maximum of 28574 seconds. This channel is 47436 seconds old. Failing a circuit. [5046 similar message(s) suppressed in last 3600 seconds]
Aug 09 01:09:03.000 [warn] int64_t circuitmux_count_queued_destroy_cells(const channel_t *, const circuitmux_t *)(): Bug:   Discrepancy in counts for queued destroy cells on circuitmux. n=45357. queue_size=45357. manual_total=45357. manual_total_in_map=32591.
Aug 09 01:09:03.000 [warn]   Circuitmux on this channel has 0 circuits, of which 0 are active. It says it has 45357 destroy cells queued.
Aug 09 01:09:03.000 [warn] Channel 470025 (at 0x80f913400) with transport TLS channel (connection 1062759) is in state open (2)
Aug 09 01:09:03.000 [warn]  * Channel 470025 was created at 1407499107 (47436 seconds ago) and last active at 1407546404 (139 seconds ago)
Aug 09 01:09:03.000 [warn]  * Channel 470025 says it is connected to an OR with digest 92AA57343957296C7EC89A976609DBB33C56E75F and no known nickname
Aug 09 01:09:03.000 [warn]  * Channel 470025 says its remote address is [scrubbed], and gives a canonical description of "[scrubbed]" and an actual description of "[scrubbed]"
Aug 09 01:09:03.000 [warn]  * Channel 470025 has these marks: !bad_for_new_circs canonical is_canonical_is_reliable !client !local outgoing
Aug 09 01:09:03.000 [warn]  * Channel 470025 has 0 queued incoming cells and 0 queued outgoing cells
Aug 09 01:09:03.000 [warn]  * Channel 470025 has 0 active circuits out of 0 in total
Aug 09 01:09:03.000 [warn]  * Channel 470025 was last used by a client at 0 (1407546543 seconds ago)
Aug 09 01:09:03.000 [warn]  * Channel 470025 was last drained at 1407546384 (159 seconds ago)
Aug 09 01:09:03.000 [warn]  * Channel 470025 last received a cell at 1407546104 (439 seconds ago)
Aug 09 01:09:03.000 [warn]  * Channel 470025 last transmitted a cell at 1407546384 (159 seconds ago)
Aug 09 01:09:03.000 [warn]  * Channel 470025 has received 1200 cells and transmitted 14782
Aug 09 01:09:03.000 [warn]  * Channel 470025 has averaged 39.530000 seconds between received cells
Aug 09 01:09:03.000 [warn]  * Channel 470025 has averaged 3.209038 seconds between transmitted cells
Aug 09 02:09:04.000 [warn] No unused circIDs found on channel without wide circID support, with 0 inbound and 4294949612 outbound circuits. Found 0 circuit IDs in use by circuits, and 64 with pending destroy cells. (0 of those were marked bogusly.) The ones with pending destroy cells have been marked unusable for an average of 17100 seconds and a maximum of 29546 seconds. This channel is 51037 seconds old. Failing a circuit. [4918 similar message(s) suppressed in last 3600 seconds]
Aug 09 02:09:04.000 [warn] int64_t circuitmux_count_queued_destroy_cells(const channel_t *, const circuitmux_t *)(): Bug:   Discrepancy in counts for queued destroy cells on circuitmux. n=50306. queue_size=50306. manual_total=50306. manual_total_in_map=32621.
Aug 09 02:09:04.000 [warn]   Circuitmux on this channel has 1 circuits, of which 1 are active. It says it has 50306 destroy cells queued.
Aug 09 02:09:04.000 [warn] Channel 470025 (at 0x80f913400) with transport TLS channel (connection 1062759) is in state open (2)
Aug 09 02:09:04.000 [warn]  * Channel 470025 was created at 1407499107 (51037 seconds ago) and last active at 1407550073 (71 seconds ago)
Aug 09 02:09:04.000 [warn]  * Channel 470025 says it is connected to an OR with digest 92AA57343957296C7EC89A976609DBB33C56E75F and no known nickname
Aug 09 02:09:04.000 [warn]  * Channel 470025 says its remote address is [scrubbed], and gives a canonical description of "[scrubbed]" and an actual description of "[scrubbed]"
Aug 09 02:09:04.000 [warn]  * Channel 470025 has these marks: !bad_for_new_circs canonical is_canonical_is_reliable !client !local outgoing
Aug 09 02:09:04.000 [warn]  * Channel 470025 has 0 queued incoming cells and 0 queued outgoing cells
Aug 09 02:09:04.000 [warn]  * Channel 470025 has 1 active circuits out of 1 in total
Aug 09 02:09:04.000 [warn]  * Channel 470025 was last used by a client at 0 (1407550144 seconds ago)
Aug 09 02:09:04.000 [warn]  * Channel 470025 was last drained at 1407550000 (144 seconds ago)
Aug 09 02:09:04.000 [warn]  * Channel 470025 last received a cell at 1407550073 (71 seconds ago)
Aug 09 02:09:04.000 [warn]  * Channel 470025 last transmitted a cell at 1407550000 (144 seconds ago)
Aug 09 02:09:04.000 [warn]  * Channel 470025 has received 1214 cells and transmitted 16801
Aug 09 02:09:04.000 [warn]  * Channel 470025 has averaged 42.040362 seconds between received cells
Aug 09 02:09:04.000 [warn]  * Channel 470025 has averaged 3.037736 seconds between transmitted cells
Aug 09 02:28:56.000 [warn] failed to get unique circID. [13352 similar message(s) suppressed in last 9600 seconds]
Aug 09 03:09:04.000 [warn] No unused circIDs found on channel without wide circID support, with 0 inbound and 4294943955 outbound circuits. Found 0 circuit IDs in use by circuits, and 64 with pending destroy cells. (0 of those were marked bogusly.) The ones with pending destroy cells have been marked unusable for an average of 18918 seconds and a maximum of 32756 seconds. This channel is 54637 seconds old. Failing a circuit. [5655 similar message(s) suppressed in last 3600 seconds]
Aug 09 03:09:04.000 [warn] int64_t circuitmux_count_queued_destroy_cells(const channel_t *, const circuitmux_t *)(): Bug:   Discrepancy in counts for queued destroy cells on circuitmux. n=56046. queue_size=56046. manual_total=56046. manual_total_in_map=32705.
Aug 09 03:09:04.000 [warn]   Circuitmux on this channel has 0 circuits, of which 0 are active. It says it has 56046 destroy cells queued.
Aug 09 03:09:04.000 [warn] Channel 470025 (at 0x80f913400) with transport TLS channel (connection 1062759) is in state open (2)
Aug 09 03:09:04.000 [warn]  * Channel 470025 was created at 1407499107 (54637 seconds ago) and last active at 1407553736 (8 seconds ago)
Aug 09 03:09:04.000 [warn]  * Channel 470025 says it is connected to an OR with digest 92AA57343957296C7EC89A976609DBB33C56E75F and no known nickname
Aug 09 03:09:04.000 [warn]  * Channel 470025 says its remote address is [scrubbed], and gives a canonical description of "[scrubbed]" and an actual description of "[scrubbed]"
Aug 09 03:09:04.000 [warn]  * Channel 470025 has these marks: !bad_for_new_circs canonical is_canonical_is_reliable !client !local outgoing
Aug 09 03:09:04.000 [warn]  * Channel 470025 has 0 queued incoming cells and 0 queued outgoing cells
Aug 09 03:09:04.000 [warn]  * Channel 470025 has 0 active circuits out of 0 in total
Aug 09 03:09:04.000 [warn]  * Channel 470025 was last used by a client at 0 (1407553744 seconds ago)
Aug 09 03:09:04.000 [warn]  * Channel 470025 was last drained at 1407553390 (354 seconds ago)
Aug 09 03:09:04.000 [warn]  * Channel 470025 last received a cell at 1407553736 (8 seconds ago)
Aug 09 03:09:04.000 [warn]  * Channel 470025 last transmitted a cell at 1407553390 (354 seconds ago)
Aug 09 03:09:04.000 [warn]  * Channel 470025 has received 1230 cells and transmitted 18581
Aug 09 03:09:04.000 [warn]  * Channel 470025 has averaged 44.420325 seconds between received cells
Aug 09 03:09:04.000 [warn]  * Channel 470025 has averaged 2.940477 seconds between transmitted cells
Aug 09 04:09:04.000 [warn] No unused circIDs found on channel without wide circID support, with 0 inbound and 4294936048 outbound circuits. Found 0 circuit IDs in use by circuits, and 64 with pending destroy cells. (0 of those were marked bogusly.) The ones with pending destroy cells have been marked unusable for an average of 21821 seconds and a maximum of 35397 seconds. This channel is 58237 seconds old. Failing a circuit. [7906 similar message(s) suppressed in last 3600 seconds]
Aug 09 04:09:04.000 [warn] int64_t circuitmux_count_queued_destroy_cells(const channel_t *, const circuitmux_t *)(): Bug:   Discrepancy in counts for queued destroy cells on circuitmux. n=63986. queue_size=63986. manual_total=63986. manual_total_in_map=32738.
Aug 09 04:09:04.000 [warn]   Circuitmux on this channel has 0 circuits, of which 0 are active. It says it has 63986 destroy cells queued.
Aug 09 04:09:04.000 [warn] Channel 470025 (at 0x80f913400) with transport TLS channel (connection 1062759) is in state open (2)
Aug 09 04:09:04.000 [warn]  * Channel 470025 was created at 1407499107 (58237 seconds ago) and last active at 1407557166 (178 seconds ago)
Aug 09 04:09:04.000 [warn]  * Channel 470025 says it is connected to an OR with digest 92AA57343957296C7EC89A976609DBB33C56E75F and no known nickname
Aug 09 04:09:04.000 [warn]  * Channel 470025 says its remote address is [scrubbed], and gives a canonical description of "[scrubbed]" and an actual description of "[scrubbed]"
Aug 09 04:09:04.000 [warn]  * Channel 470025 has these marks: !bad_for_new_circs canonical is_canonical_is_reliable !client !local outgoing
Aug 09 04:09:04.000 [warn]  * Channel 470025 has 0 queued incoming cells and 0 queued outgoing cells
Aug 09 04:09:04.000 [warn]  * Channel 470025 has 0 active circuits out of 0 in total
Aug 09 04:09:04.000 [warn]  * Channel 470025 was last used by a client at 0 (1407557344 seconds ago)
Aug 09 04:09:04.000 [warn]  * Channel 470025 was last drained at 1407556906 (438 seconds ago)
Aug 09 04:09:04.000 [warn]  * Channel 470025 last received a cell at 1407557166 (178 seconds ago)
Aug 09 04:09:04.000 [warn]  * Channel 470025 last transmitted a cell at 1407556906 (438 seconds ago)
Aug 09 04:09:04.000 [warn]  * Channel 470025 has received 1243 cells and transmitted 20101
Aug 09 04:09:04.000 [warn]  * Channel 470025 has averaged 46.851971 seconds between received cells
Aug 09 04:09:04.000 [warn]  * Channel 470025 has averaged 2.897219 seconds between transmitted cells
Aug 09 05:08:56.000 [warn] failed to get unique circID. [18000 similar message(s) suppressed in last 9600 seconds]
Aug 09 05:09:05.000 [warn] No unused circIDs found on channel without wide circID support, with 0 inbound and 4294929658 outbound circuits. Found 0 circuit IDs in use by circuits, and 64 with pending destroy cells. (0 of those were marked bogusly.) The ones with pending destroy cells have been marked unusable for an average of 24959 seconds and a maximum of 37832 seconds. This channel is 61838 seconds old. Failing a circuit. [6390 similar message(s) suppressed in last 3600 seconds]
Aug 09 05:09:05.000 [warn] int64_t circuitmux_count_queued_destroy_cells(const channel_t *, const circuitmux_t *)(): Bug:   Discrepancy in counts for queued destroy cells on circuitmux. n=70318. queue_size=70318. manual_total=70318. manual_total_in_map=32679.
Aug 09 05:09:05.000 [warn]   Circuitmux on this channel has 1 circuits, of which 1 are active. It says it has 70318 destroy cells queued.
Aug 09 05:09:05.000 [warn] Channel 470025 (at 0x80f913400) with transport TLS channel (connection 1062759) is in state open (2)
Aug 09 05:09:05.000 [warn]  * Channel 470025 was created at 1407499107 (61838 seconds ago) and last active at 1407560931 (14 seconds ago)
Aug 09 05:09:05.000 [warn]  * Channel 470025 says it is connected to an OR with digest 92AA57343957296C7EC89A976609DBB33C56E75F and no known nickname
Aug 09 05:09:05.000 [warn]  * Channel 470025 says its remote address is [scrubbed], and gives a canonical description of "[scrubbed]" and an actual description of "[scrubbed]"
Aug 09 05:09:05.000 [warn]  * Channel 470025 has these marks: !bad_for_new_circs canonical is_canonical_is_reliable !client !local outgoing
Aug 09 05:09:05.000 [warn]  * Channel 470025 has 0 queued incoming cells and 0 queued outgoing cells
Aug 09 05:09:05.000 [warn]  * Channel 470025 has 1 active circuits out of 1 in total
Aug 09 05:09:05.000 [warn]  * Channel 470025 was last used by a client at 0 (1407560945 seconds ago)
Aug 09 05:09:05.000 [warn]  * Channel 470025 was last drained at 1407560931 (14 seconds ago)
Aug 09 05:09:05.000 [warn]  * Channel 470025 last received a cell at 1407560123 (822 seconds ago)
Aug 09 05:09:05.000 [warn]  * Channel 470025 last transmitted a cell at 1407560931 (14 seconds ago)
Aug 09 05:09:05.000 [warn]  * Channel 470025 has received 1250 cells and transmitted 21929
Aug 09 05:09:05.000 [warn]  * Channel 470025 has averaged 49.470400 seconds between received cells
Aug 09 05:09:05.000 [warn]  * Channel 470025 has averaged 2.819919 seconds between transmitted cells
Aug 09 06:09:05.000 [warn] No unused circIDs found on channel without wide circID support, with 0 inbound and 4294922699 outbound circuits. Found 0 circuit IDs in use by circuits, and 64 with pending destroy cells. (0 of those were marked bogusly.) The ones with pending destroy cells have been marked unusable for an average of 24854 seconds and a maximum of 40566 seconds. This channel is 65438 seconds old. Failing a circuit. [6958 similar message(s) suppressed in last 3600 seconds]
Aug 09 06:09:05.000 [warn] int64_t circuitmux_count_queued_destroy_cells(const channel_t *, const circuitmux_t *)(): Bug:   Discrepancy in counts for queued destroy cells on circuitmux. n=77181. queue_size=77181. manual_total=77181. manual_total_in_map=32583.
Aug 09 06:09:05.000 [warn]   Circuitmux on this channel has 1 circuits, of which 1 are active. It says it has 77181 destroy cells queued.
Aug 09 06:09:05.000 [warn] Channel 470025 (at 0x80f913400) with transport TLS channel (connection 1062759) is in state open (2)
Aug 09 06:09:05.000 [warn]  * Channel 470025 was created at 1407499107 (65438 seconds ago) and last active at 1407564497 (48 seconds ago)
Aug 09 06:09:05.000 [warn]  * Channel 470025 says it is connected to an OR with digest 92AA57343957296C7EC89A976609DBB33C56E75F and no known nickname
Aug 09 06:09:05.000 [warn]  * Channel 470025 says its remote address is [scrubbed], and gives a canonical description of "[scrubbed]" and an actual description of "[scrubbed]"
Aug 09 06:09:05.000 [warn]  * Channel 470025 has these marks: !bad_for_new_circs canonical is_canonical_is_reliable !client !local outgoing
Aug 09 06:09:05.000 [warn]  * Channel 470025 has 0 queued incoming cells and 0 queued outgoing cells
Aug 09 06:09:05.000 [warn]  * Channel 470025 has 1 active circuits out of 1 in total
Aug 09 06:09:05.000 [warn]  * Channel 470025 was last used by a client at 0 (1407564545 seconds ago)
Aug 09 06:09:05.000 [warn]  * Channel 470025 was last drained at 1407564397 (148 seconds ago)
Aug 09 06:09:05.000 [warn]  * Channel 470025 last received a cell at 1407564497 (48 seconds ago)
Aug 09 06:09:05.000 [warn]  * Channel 470025 last transmitted a cell at 1407564397 (148 seconds ago)
Aug 09 06:09:05.000 [warn]  * Channel 470025 has received 1256 cells and transmitted 23401
Aug 09 06:09:05.000 [warn]  * Channel 470025 has averaged 52.100318 seconds between received cells
Aug 09 06:09:05.000 [warn]  * Channel 470025 has averaged 2.796376 seconds between transmitted cells
Aug 09 06:53:59.000 [notice] Heartbeat: Tor's uptime is 1 day 12:00 hours, with 17472 circuits open. I've sent 1480.49 GB and received 1419.77 GB.
Aug 09 06:53:59.000 [notice] Average packaged cell fullness: 99.209%
Aug 09 06:53:59.000 [notice] TLS write overhead: 3%
Aug 09 06:53:59.000 [notice] Circuit handshake stats since last time: 648718/648718 TAP, 150890/150890 NTor.
Aug 09 07:09:05.000 [warn] No unused circIDs found on channel without wide circID support, with 0 inbound and 4294916678 outbound circuits. Found 0 circuit IDs in use by circuits, and 64 with pending destroy cells. (0 of those were marked bogusly.) The ones with pending destroy cells have been marked unusable for an average of 28298 seconds and a maximum of 43255 seconds. This channel is 69038 seconds old. Failing a circuit. [6022 similar message(s) suppressed in last 3600 seconds]
Aug 09 07:09:05.000 [warn] int64_t circuitmux_count_queued_destroy_cells(const channel_t *, const circuitmux_t *)(): Bug:   Discrepancy in counts for queued destroy cells on circuitmux. n=83266. queue_size=83266. manual_total=83266. manual_total_in_map=32645.
Aug 09 07:09:05.000 [warn]   Circuitmux on this channel has 3 circuits, of which 3 are active. It says it has 83266 destroy cells queued.
Aug 09 07:09:05.000 [warn] Channel 470025 (at 0x80f913400) with transport TLS channel (connection 1062759) is in state open (2)
Aug 09 07:09:05.000 [warn]  * Channel 470025 was created at 1407499107 (69038 seconds ago) and last active at 1407568007 (138 seconds ago)
Aug 09 07:09:05.000 [warn]  * Channel 470025 says it is connected to an OR with digest 92AA57343957296C7EC89A976609DBB33C56E75F and no known nickname
Aug 09 07:09:05.000 [warn]  * Channel 470025 says its remote address is [scrubbed], and gives a canonical description of "[scrubbed]" and an actual description of "[scrubbed]"
Aug 09 07:09:05.000 [warn]  * Channel 470025 has these marks: !bad_for_new_circs canonical is_canonical_is_reliable !client !local outgoing
Aug 09 07:09:05.000 [warn]  * Channel 470025 has 0 queued incoming cells and 0 queued outgoing cells
Aug 09 07:09:05.000 [warn]  * Channel 470025 has 3 active circuits out of 3 in total
Aug 09 07:09:05.000 [warn]  * Channel 470025 was last used by a client at 0 (1407568145 seconds ago)
Aug 09 07:09:05.000 [warn]  * Channel 470025 was last drained at 1407567969 (176 seconds ago)
Aug 09 07:09:05.000 [warn]  * Channel 470025 last received a cell at 1407567707 (438 seconds ago)
Aug 09 07:09:05.000 [warn]  * Channel 470025 last transmitted a cell at 1407567969 (176 seconds ago)
Aug 09 07:09:05.000 [warn]  * Channel 470025 has received 1261 cells and transmitted 25150
Aug 09 07:09:05.000 [warn]  * Channel 470025 has averaged 54.748612 seconds between received cells
Aug 09 07:09:05.000 [warn]  * Channel 470025 has averaged 2.745050 seconds between transmitted cells
Aug 09 07:48:56.000 [warn] failed to get unique circID. [18328 similar message(s) suppressed in last 9600 seconds]
Aug 09 08:09:05.000 [warn] No unused circIDs found on channel without wide circID support, with 0 inbound and 4294908158 outbound circuits. Found 0 circuit IDs in use by circuits, and 64 with pending destroy cells. (0 of those were marked bogusly.) The ones with pending destroy cells have been marked unusable for an average of 28696 seconds and a maximum of 45674 seconds. This channel is 72638 seconds old. Failing a circuit. [8518 similar message(s) suppressed in last 3600 seconds]
Aug 09 08:09:05.000 [warn] int64_t circuitmux_count_queued_destroy_cells(const channel_t *, const circuitmux_t *)(): Bug:   Discrepancy in counts for queued destroy cells on circuitmux. n=91752. queue_size=91752. manual_total=91752. manual_total_in_map=32612.
Aug 09 08:09:05.000 [warn]   Circuitmux on this channel has 2 circuits, of which 2 are active. It says it has 91752 destroy cells queued.
Aug 09 08:09:05.000 [warn] Channel 470025 (at 0x80f913400) with transport TLS channel (connection 1062759) is in state open (2)
Aug 09 08:09:05.000 [warn]  * Channel 470025 was created at 1407499107 (72638 seconds ago) and last active at 1407571692 (53 seconds ago)
Aug 09 08:09:05.000 [warn]  * Channel 470025 says it is connected to an OR with digest 92AA57343957296C7EC89A976609DBB33C56E75F and no known nickname
Aug 09 08:09:05.000 [warn]  * Channel 470025 says its remote address is [scrubbed], and gives a canonical description of "[scrubbed]" and an actual description of "[scrubbed]"
Aug 09 08:09:05.000 [warn]  * Channel 470025 has these marks: !bad_for_new_circs canonical is_canonical_is_reliable !client !local outgoing
Aug 09 08:09:05.000 [warn]  * Channel 470025 has 0 queued incoming cells and 0 queued outgoing cells
Aug 09 08:09:05.000 [warn]  * Channel 470025 has 2 active circuits out of 2 in total
Aug 09 08:09:05.000 [warn]  * Channel 470025 was last used by a client at 0 (1407571745 seconds ago)
Aug 09 08:09:05.000 [warn]  * Channel 470025 was last drained at 1407571692 (53 seconds ago)
Aug 09 08:09:05.000 [warn]  * Channel 470025 last received a cell at 1407571192 (553 seconds ago)
Aug 09 08:09:05.000 [warn]  * Channel 470025 last transmitted a cell at 1407571692 (53 seconds ago)
Aug 09 08:09:05.000 [warn]  * Channel 470025 has received 1268 cells and transmitted 26448
Aug 09 08:09:05.000 [warn]  * Channel 470025 has averaged 57.285489 seconds between received cells
Aug 09 08:09:05.000 [warn]  * Channel 470025 has averaged 2.746446 seconds between transmitted cells
Aug 09 09:09:05.000 [warn] No unused circIDs found on channel without wide circID support, with 0 inbound and 4294898090 outbound circuits. Found 0 circuit IDs in use by circuits, and 64 with pending destroy cells. (0 of those were marked bogusly.) The ones with pending destroy cells have been marked unusable for an average of 34344 seconds and a maximum of 48618 seconds. This channel is 76238 seconds old. Failing a circuit. [10067 similar message(s) suppressed in last 3600 seconds]
Aug 09 09:09:05.000 [warn] int64_t circuitmux_count_queued_destroy_cells(const channel_t *, const circuitmux_t *)(): Bug:   Discrepancy in counts for queued destroy cells on circuitmux. n=101730. queue_size=101730. manual_total=101730. manual_total_in_map=32522.
Aug 09 09:09:05.000 [warn]   Circuitmux on this channel has 2 circuits, of which 2 are active. It says it has 101730 destroy cells queued.
Aug 09 09:09:05.000 [warn] Channel 470025 (at 0x80f913400) with transport TLS channel (connection 1062759) is in state open (2)
Aug 09 09:09:05.000 [warn]  * Channel 470025 was created at 1407499107 (76238 seconds ago) and last active at 1407575330 (15 seconds ago)
Aug 09 09:09:05.000 [warn]  * Channel 470025 says it is connected to an OR with digest 92AA57343957296C7EC89A976609DBB33C56E75F and no known nickname
Aug 09 09:09:05.000 [warn]  * Channel 470025 says its remote address is [scrubbed], and gives a canonical description of "[scrubbed]" and an actual description of "[scrubbed]"
Aug 09 09:09:05.000 [warn]  * Channel 470025 has these marks: !bad_for_new_circs canonical is_canonical_is_reliable !client !local outgoing
Aug 09 09:09:05.000 [warn]  * Channel 470025 has 0 queued incoming cells and 0 queued outgoing cells
Aug 09 09:09:05.000 [warn]  * Channel 470025 has 2 active circuits out of 2 in total
Aug 09 09:09:05.000 [warn]  * Channel 470025 was last used by a client at 0 (1407575345 seconds ago)
Aug 09 09:09:05.000 [warn]  * Channel 470025 was last drained at 1407575330 (15 seconds ago)
Aug 09 09:09:05.000 [warn]  * Channel 470025 last received a cell at 1407574837 (508 seconds ago)
Aug 09 09:09:05.000 [warn]  * Channel 470025 last transmitted a cell at 1407575330 (15 seconds ago)
Aug 09 09:09:05.000 [warn]  * Channel 470025 has received 1271 cells and transmitted 27691
Aug 09 09:09:05.000 [warn]  * Channel 470025 has averaged 59.982691 seconds between received cells
Aug 09 09:09:05.000 [warn]  * Channel 470025 has averaged 2.753169 seconds between transmitted cells
Aug 09 10:09:05.000 [warn] No unused circIDs found on channel without wide circID support, with 0 inbound and 4294888026 outbound circuits. Found 0 circuit IDs in use by circuits, and 64 with pending destroy cells. (0 of those were marked bogusly.) The ones with pending destroy cells have been marked unusable for an average of 35343 seconds and a maximum of 51733 seconds. This channel is 79838 seconds old. Failing a circuit. [10061 similar message(s) suppressed in last 3600 seconds]
Aug 09 10:09:05.000 [warn] int64_t circuitmux_count_queued_destroy_cells(const channel_t *, const circuitmux_t *)(): Bug:   Discrepancy in counts for queued destroy cells on circuitmux. n=111952. queue_size=111952. manual_total=111952. manual_total_in_map=32682.
Aug 09 10:09:05.000 [warn]   Circuitmux on this channel has 0 circuits, of which 0 are active. It says it has 111952 destroy cells queued.
Aug 09 10:09:05.000 [warn] Channel 470025 (at 0x80f913400) with transport TLS channel (connection 1062759) is in state open (2)
Aug 09 10:09:05.000 [warn]  * Channel 470025 was created at 1407499107 (79838 seconds ago) and last active at 1407578782 (163 seconds ago)
Aug 09 10:09:05.000 [warn]  * Channel 470025 says it is connected to an OR with digest 92AA57343957296C7EC89A976609DBB33C56E75F and no known nickname
Aug 09 10:09:05.000 [warn]  * Channel 470025 says its remote address is [scrubbed], and gives a canonical description of "[scrubbed]" and an actual description of "[scrubbed]"
Aug 09 10:09:05.000 [warn]  * Channel 470025 has these marks: !bad_for_new_circs canonical is_canonical_is_reliable !client !local outgoing
Aug 09 10:09:05.000 [warn]  * Channel 470025 has 0 queued incoming cells and 0 queued outgoing cells
Aug 09 10:09:05.000 [warn]  * Channel 470025 has 0 active circuits out of 0 in total
Aug 09 10:09:05.000 [warn]  * Channel 470025 was last used by a client at 0 (1407578945 seconds ago)
Aug 09 10:09:05.000 [warn]  * Channel 470025 was last drained at 1407578782 (163 seconds ago)
Aug 09 10:09:05.000 [warn]  * Channel 470025 last received a cell at 1407578394 (551 seconds ago)
Aug 09 10:09:05.000 [warn]  * Channel 470025 last transmitted a cell at 1407578782 (163 seconds ago)
Aug 09 10:09:05.000 [warn]  * Channel 470025 has received 1277 cells and transmitted 28942
Aug 09 10:09:05.000 [warn]  * Channel 470025 has averaged 62.519969 seconds between received cells
Aug 09 10:09:05.000 [warn]  * Channel 470025 has averaged 2.758552 seconds between transmitted cells
Aug 09 10:28:56.000 [warn] failed to get unique circID. [27062 similar message(s) suppressed in last 9600 seconds]
Aug 09 11:09:05.000 [warn] No unused circIDs found on channel without wide circID support, with 0 inbound and 4294876844 outbound circuits. Found 0 circuit IDs in use by circuits, and 64 with pending destroy cells. (0 of those were marked bogusly.) The ones with pending destroy cells have been marked unusable for an average of 29481 seconds and a maximum of 53876 seconds. This channel is 83438 seconds old. Failing a circuit. [11181 similar message(s) suppressed in last 3600 seconds]
Aug 09 11:09:05.000 [warn] int64_t circuitmux_count_queued_destroy_cells(const channel_t *, const circuitmux_t *)(): Bug:   Discrepancy in counts for queued destroy cells on circuitmux. n=123159. queue_size=123159. manual_total=123159. manual_total_in_map=32707.
Aug 09 11:09:05.000 [warn]   Circuitmux on this channel has 0 circuits, of which 0 are active. It says it has 123159 destroy cells queued.
Aug 09 11:09:05.000 [warn] Channel 470025 (at 0x80f913400) with transport TLS channel (connection 1062759) is in state open (2)
Aug 09 11:09:05.000 [warn]  * Channel 470025 was created at 1407499107 (83438 seconds ago) and last active at 1407582321 (224 seconds ago)
Aug 09 11:09:05.000 [warn]  * Channel 470025 says it is connected to an OR with digest 92AA57343957296C7EC89A976609DBB33C56E75F and no known nickname
Aug 09 11:09:05.000 [warn]  * Channel 470025 says its remote address is [scrubbed], and gives a canonical description of "[scrubbed]" and an actual description of "[scrubbed]"
Aug 09 11:09:05.000 [warn]  * Channel 470025 has these marks: !bad_for_new_circs canonical is_canonical_is_reliable !client !local outgoing
Aug 09 11:09:05.000 [warn]  * Channel 470025 has 0 queued incoming cells and 0 queued outgoing cells
Aug 09 11:09:05.000 [warn]  * Channel 470025 has 0 active circuits out of 0 in total
Aug 09 11:09:05.000 [warn]  * Channel 470025 was last used by a client at 0 (1407582545 seconds ago)
Aug 09 11:09:05.000 [warn]  * Channel 470025 was last drained at 1407582321 (224 seconds ago)
Aug 09 11:09:05.000 [warn]  * Channel 470025 last received a cell at 1407578394 (4151 seconds ago)
Aug 09 11:09:05.000 [warn]  * Channel 470025 last transmitted a cell at 1407582321 (224 seconds ago)
Aug 09 11:09:05.000 [warn]  * Channel 470025 has received 1277 cells and transmitted 30207
Aug 09 11:09:05.000 [warn]  * Channel 470025 has averaged 65.339076 seconds between received cells
Aug 09 11:09:05.000 [warn]  * Channel 470025 has averaged 2.762207 seconds between transmitted cells
Aug 09 12:09:05.000 [warn] No unused circIDs found on channel without wide circID support, with 0 inbound and 4294864918 outbound circuits. Found 0 circuit IDs in use by circuits, and 64 with pending destroy cells. (0 of those were marked bogusly.) The ones with pending destroy cells have been marked unusable for an average of 33466 seconds and a maximum of 57106 seconds. This channel is 87038 seconds old. Failing a circuit. [11925 similar message(s) suppressed in last 3600 seconds]
Aug 09 12:09:05.000 [warn] int64_t circuitmux_count_queued_destroy_cells(const channel_t *, const circuitmux_t *)(): Bug:   Discrepancy in counts for queued destroy cells on circuitmux. n=135125. queue_size=135125. manual_total=135125. manual_total_in_map=32747.
Aug 09 12:09:05.000 [warn]   Circuitmux on this channel has 0 circuits, of which 0 are active. It says it has 135125 destroy cells queued.
Aug 09 12:09:05.000 [warn] Channel 470025 (at 0x80f913400) with transport TLS channel (connection 1062759) is in state open (2)
Aug 09 12:09:05.000 [warn]  * Channel 470025 was created at 1407499107 (87038 seconds ago) and last active at 1407585865 (280 seconds ago)
Aug 09 12:09:05.000 [warn]  * Channel 470025 says it is connected to an OR with digest 92AA57343957296C7EC89A976609DBB33C56E75F and no known nickname
Aug 09 12:09:05.000 [warn]  * Channel 470025 says its remote address is [scrubbed], and gives a canonical description of "[scrubbed]" and an actual description of "[scrubbed]"
Aug 09 12:09:05.000 [warn]  * Channel 470025 has these marks: !bad_for_new_circs canonical is_canonical_is_reliable !client !local outgoing
Aug 09 12:09:05.000 [warn]  * Channel 470025 has 0 queued incoming cells and 0 queued outgoing cells
Aug 09 12:09:05.000 [warn]  * Channel 470025 has 0 active circuits out of 0 in total
Aug 09 12:09:05.000 [warn]  * Channel 470025 was last used by a client at 0 (1407586145 seconds ago)
Aug 09 12:09:05.000 [warn]  * Channel 470025 was last drained at 1407585844 (301 seconds ago)
Aug 09 12:09:05.000 [warn]  * Channel 470025 last received a cell at 1407585865 (280 seconds ago)
Aug 09 12:09:05.000 [warn]  * Channel 470025 last transmitted a cell at 1407585844 (301 seconds ago)
Aug 09 12:09:05.000 [warn]  * Channel 470025 has received 1281 cells and transmitted 31719
Aug 09 12:09:05.000 [warn]  * Channel 470025 has averaged 67.945355 seconds between received cells
Aug 09 12:09:05.000 [warn]  * Channel 470025 has averaged 2.744034 seconds between transmitted cells

comment:43 in reply to:  40 Changed 5 years ago by reezer

Replying to cypherpunks:

Any idea on how to find out which one it is?

Read code, and collect to compare information about peers for which bug triggered.

MOBILEBURN and ​IGWT are running Tor 0.2.3.25 on Windows 7

Is there a way to easily query for relays having this version and/or this operating system?

Cause the same is true for this relay and I wonder how many relays with that exact combination there are:

https://atlas.torproject.org/#details/92AA57343957296C7EC89A976609DBB33C56E75F

Also I wonder what this is about:

Aug 08 01:49:44.000 [warn] Unexpected onionskin length after decryption: 58
Last edited 5 years ago by reezer (previous) (diff)

comment:44 Changed 5 years ago by reezer

After many days of silence there is new Tor node, again Tor 0.2.3.35 on Windows 7 and these logs. A new one called default:

https://atlas.torproject.org/#details/DF47CDD59EA05D8D93ECF0D1B20FC9348158F2F8

Sep 03 21:43:53.000 [warn] No unused circIDs found on channel without wide circID support, with 0 inbound and 2 outbound circuits. Found 0 circuit IDs in use by circuits, and 64 with pending destroy cells. (0 of those were marked bogusly.) The ones with pending destroy cells have been marked unusable for an average of 7467 seconds and a maximum of 18661 seconds. This channel is 23448 seconds old. Failing a circuit.
Sep 03 21:43:53.000 [warn]   Circuitmux on this channel has 2 circuits, of which 2 are active. It says it has 29798 destroy cells queued.
Sep 03 21:43:53.000 [warn] Channel 20432304 (at 0x80f636b00) with transport TLS channel (connection 46455456) is in state open (2)
Sep 03 21:43:53.000 [warn]  * Channel 20432304 was created at 1409757185 (23448 seconds ago) and last active at 1409780633 (0 seconds ago)
Sep 03 21:43:53.000 [warn]  * Channel 20432304 says it is connected to an OR with digest DF47CDD59EA05D8D93ECF0D1B20FC9348158F2F8 and no known nickname
Sep 03 21:43:53.000 [warn]  * Channel 20432304 says its remote address is [scrubbed], and gives a canonical description of "[scrubbed]" and an actual description of "[scrubbed]"
Sep 03 21:43:53.000 [warn]  * Channel 20432304 has these marks: !bad_for_new_circs canonical is_canonical_is_reliable !client !local outgoing
Sep 03 21:43:53.000 [warn]  * Channel 20432304 has 0 queued incoming cells and 0 queued outgoing cells
Sep 03 21:43:53.000 [warn]  * Channel 20432304 has 2 active circuits out of 2 in total
Sep 03 21:43:53.000 [warn]  * Channel 20432304 was last used by a client at 0 (1409780633 seconds ago)
Sep 03 21:43:53.000 [warn]  * Channel 20432304 was last drained at 1409780548 (85 seconds ago)
Sep 03 21:43:53.000 [warn]  * Channel 20432304 last received a cell at 1409780333 (300 seconds ago)
Sep 03 21:43:53.000 [warn]  * Channel 20432304 last transmitted a cell at 1409780548 (85 seconds ago)
Sep 03 21:43:53.000 [warn]  * Channel 20432304 has received 431 cells and transmitted 5385
Sep 03 21:43:53.000 [warn]  * Channel 20432304 has averaged 54.403712 seconds between received cells
Sep 03 21:43:53.000 [warn]  * Channel 20432304 has averaged 4.354318 seconds between transmitted cells
Sep 03 21:43:53.000 [warn] failed to get unique circID.
Sep 03 22:43:54.000 [warn] No unused circIDs found on channel without wide circID support, with 0 inbound and 4294966959 outbound circuits. Found 0 circuit IDs in use by circuits, and 64 with pending destroy cells. (0 of those were marked bogusly.) The ones with pending destroy cells have been marked unusable for an average of 11345 seconds and a maximum of 21655 seconds. This channel is 27048 seconds old. Failing a circuit. [337 similar message(s) suppressed in last 3600 seconds]
Sep 03 22:43:54.000 [warn] int64_t circuitmux_count_queued_destroy_cells(const channel_t *, const circuitmux_t *)(): Bug:   Discrepancy in counts for queued destroy cells on circuitmux. n=32611. queue_size=32611. manual_total=32611. manual_total_in_map=32273.
Sep 03 22:43:54.000 [warn]   Circuitmux on this channel has 1 circuits, of which 1 are active. It says it has 32611 destroy cells queued.
Sep 03 22:43:54.000 [warn] Channel 20432304 (at 0x80f636b00) with transport TLS channel (connection 46455456) is in state open (2)
Sep 03 22:43:54.000 [warn]  * Channel 20432304 was created at 1409757185 (27049 seconds ago) and last active at 1409784230 (4 seconds ago)
Sep 03 22:43:54.000 [warn]  * Channel 20432304 says it is connected to an OR with digest DF47CDD59EA05D8D93ECF0D1B20FC9348158F2F8 and no known nickname
Sep 03 22:43:54.000 [warn]  * Channel 20432304 says its remote address is [scrubbed], and gives a canonical description of "[scrubbed]" and an actual description of "[scrubbed]"
Sep 03 22:43:54.000 [warn]  * Channel 20432304 has these marks: !bad_for_new_circs canonical is_canonical_is_reliable !client !local outgoing
Sep 03 22:43:54.000 [warn]  * Channel 20432304 has 0 queued incoming cells and 0 queued outgoing cells
Sep 03 22:43:54.000 [warn]  * Channel 20432304 has 1 active circuits out of 1 in total
Sep 03 22:43:54.000 [warn]  * Channel 20432304 was last used by a client at 0 (1409784234 seconds ago)
Sep 03 22:43:54.000 [warn]  * Channel 20432304 was last drained at 1409784230 (4 seconds ago)
Sep 03 22:43:54.000 [warn]  * Channel 20432304 last received a cell at 1409783939 (295 seconds ago)
Sep 03 22:43:54.000 [warn]  * Channel 20432304 last transmitted a cell at 1409784230 (4 seconds ago)
Sep 03 22:43:54.000 [warn]  * Channel 20432304 has received 470 cells and transmitted 6533
Sep 03 22:43:54.000 [warn]  * Channel 20432304 has averaged 57.551064 seconds between received cells
Sep 03 22:43:54.000 [warn]  * Channel 20432304 has averaged 4.140364 seconds between transmitted cells
Last edited 5 years ago by reezer (previous) (diff)

comment:45 Changed 5 years ago by reezer

New messages after a couple of days with 0.2.5.7-rc. It's MOBILEBURN again in all messages.

Sep 18 04:02:58.000 [warn] No unused circIDs found on channel without wide circID support, with 0 inbound and 0 outbound circuits. Found 0 circuit IDs in use by circuits, and 64 with pending destroy cells. (0 of those were marked bogusly.) The ones with pending destroy cells have been marked unusable for an average of 23963 seconds and a maximum of 37213 seconds. This channel is 47009 seconds old. Failing a circuit. [4208 similar message(s) suppressed in last 3600 seconds]
Sep 18 04:02:58.000 [warn]   Circuitmux on this channel has 0 circuits, of which 0 are active. It says it has 32620 destroy cells queued.
Sep 18 04:02:58.000 [warn] Channel 1561875 (at 0x81259dc00) with transport TLS channel (connection 3985671) is in state open (2)
Sep 18 04:02:58.000 [warn]  * Channel 1561875 was created at 1410965969 (47009 seconds ago) and last active at 1411012909 (69 seconds ago)
Sep 18 04:02:58.000 [warn]  * Channel 1561875 says it is connected to an OR with digest 4C733BAC82CC609ACC58AD95BFBFF04D5D06188C and no known nickname
Sep 18 04:02:58.000 [warn]  * Channel 1561875 says its remote address is [scrubbed], and gives a canonical description of "[scrubbed]" and an actual description of "[scrubbed]"
Sep 18 04:02:58.000 [warn]  * Channel 1561875 has these marks: !bad_for_new_circs canonical is_canonical_is_reliable !client !local outgoing
Sep 18 04:02:58.000 [warn]  * Channel 1561875 has 0 queued incoming cells and 0 queued outgoing cells
Sep 18 04:02:58.000 [warn]  * Channel 1561875 has 0 active circuits out of 0 in total
Sep 18 04:02:58.000 [warn]  * Channel 1561875 was last used by a client at 0 (1411012978 seconds ago)
Sep 18 04:02:58.000 [warn]  * Channel 1561875 was last drained at 1411012909 (69 seconds ago)
Sep 18 04:02:58.000 [warn]  * Channel 1561875 last received a cell at 1411012490 (488 seconds ago)
Sep 18 04:02:58.000 [warn]  * Channel 1561875 last transmitted a cell at 1411012909 (69 seconds ago)
Sep 18 04:02:58.000 [warn]  * Channel 1561875 has received 444 cells and transmitted 10609
Sep 18 04:02:58.000 [warn]  * Channel 1561875 has averaged 105.876126 seconds between received cells
Sep 18 04:02:58.000 [warn]  * Channel 1561875 has averaged 4.431049 seconds between transmitted cells
Sep 18 04:22:59.000 [warn] failed to get unique circID. [10366 similar message(s) suppressed in last 9600 seconds]
Sep 18 05:01:35.000 [warn] Received an inbound RELAY_EARLY cell on circuit 3428737242. Closing circuit. Please report this event, along with the following message.
Sep 18 05:01:35.000 [warn]  upstream=85.159.214.57:9003

comment:46 Changed 5 years ago by reezer

Torland has the same problem[1]. They run Linux[2], so it's not FreeBSD related. Again MOBILEBURN.

[1] https://lists.torproject.org/pipermail/tor-relays/2014-September/005390.html
[2] https://atlas.torproject.org/#search/torland

comment:47 Changed 5 years ago by Spider.007

Same here; did anyone notice all messages are for the same OR-digest?

https://atlas.torproject.org/#details/18B160CD5E22BFC345AEE7BA84B7EA45BF457FCA

Oct 31 03:24:28 tor Tor[42]: No unused circIDs found on channel without wide circID support, with 0 inbound and 4 outbound circuits. Found 0 circuit IDs in use by circuits, and 64 with pending destroy cells. (0
Oct 31 03:24:28 tor Tor[42]: Circuitmux on this channel has 4 circuits, of which 3 are active. It says it has 29984 destroy cells queued.
Oct 31 03:24:28 tor Tor[42]: Channel 247351 (at 0x7f57c379b5b0) with transport TLS channel (connection 601243) is in state open (2)
Oct 31 03:24:28 tor Tor[42]: * Channel 247351 was created at 1414665838 (56430 seconds ago) and last active at 1414722001 (267 seconds ago)
Oct 31 03:24:28 tor Tor[42]: * Channel 247351 says it is connected to an OR with digest 631F87EB8FF7E16E9FAD7BC5C0302A19C4A469A8 and no known nickname
Oct 31 03:24:28 tor Tor[42]: * Channel 247351 says its remote address is [scrubbed], and gives a canonical description of "[scrubbed]" and an actual description of "[scrubbed]"
Oct 31 03:24:28 tor Tor[42]: * Channel 247351 has these marks: !bad_for_new_circs canonical is_canonical_is_reliable !client !local outgoing
Oct 31 03:24:28 tor Tor[42]: * Channel 247351 has 0 queued incoming cells and 0 queued outgoing cells
Oct 31 03:24:28 tor Tor[42]: * Channel 247351 has 3 active circuits out of 4 in total
Oct 31 03:24:28 tor Tor[42]: * Channel 247351 was last used by a client at 0 (1414722268 seconds ago)
Oct 31 03:24:28 tor Tor[42]: * Channel 247351 was last drained at 1414721927 (341 seconds ago)
Oct 31 03:24:28 tor Tor[42]: * Channel 247351 last received a cell at 1414722001 (267 seconds ago)
Oct 31 03:24:28 tor Tor[42]: * Channel 247351 last transmitted a cell at 1414721927 (341 seconds ago)
Oct 31 03:24:28 tor Tor[42]: * Channel 247351 has received 367 cells and transmitted 11443
Oct 31 03:24:28 tor Tor[42]: * Channel 247351 has averaged 153.760218 seconds between received cells
Oct 31 03:24:28 tor Tor[42]: * Channel 247351 has averaged 4.931399 seconds between transmitted cells
Oct 31 03:24:28 tor Tor[42]: failed to get unique circID.
Oct 31 04:24:32 tor Tor[42]: No unused circIDs found on channel without wide circID support, with 0 inbound and 1 outbound circuits. Found 0 circuit IDs in use by circuits, and 64 with pending destroy cells. (0
Oct 31 04:24:32 tor Tor[42]: Circuitmux on this channel has 1 circuits, of which 1 are active. It says it has 32554 destroy cells queued.
Oct 31 04:24:32 tor Tor[42]: Channel 247351 (at 0x7f57c379b5b0) with transport TLS channel (connection 601243) is in state open (2)
Oct 31 04:24:32 tor Tor[42]: * Channel 247351 was created at 1414665838 (60034 seconds ago) and last active at 1414725846 (26 seconds ago)
Oct 31 04:24:32 tor Tor[42]: * Channel 247351 says it is connected to an OR with digest 631F87EB8FF7E16E9FAD7BC5C0302A19C4A469A8 and no known nickname
Oct 31 04:24:32 tor Tor[42]: * Channel 247351 says its remote address is [scrubbed], and gives a canonical description of "[scrubbed]" and an actual description of "[scrubbed]"
Oct 31 04:24:32 tor Tor[42]: * Channel 247351 has these marks: !bad_for_new_circs canonical is_canonical_is_reliable !client !local outgoing
Oct 31 04:24:32 tor Tor[42]: * Channel 247351 has 0 queued incoming cells and 0 queued outgoing cells
Oct 31 04:24:32 tor Tor[42]: * Channel 247351 has 1 active circuits out of 1 in total
Oct 31 04:24:32 tor Tor[42]: * Channel 247351 was last used by a client at 0 (1414725872 seconds ago)
Oct 31 04:24:32 tor Tor[42]: * Channel 247351 was last drained at 1414725846 (26 seconds ago)
Oct 31 04:24:32 tor Tor[42]: * Channel 247351 last received a cell at 1414725511 (361 seconds ago)
Oct 31 04:24:32 tor Tor[42]: * Channel 247351 last transmitted a cell at 1414725846 (26 seconds ago)
Oct 31 04:24:32 tor Tor[42]: * Channel 247351 has received 389 cells and transmitted 11891
Oct 31 04:24:32 tor Tor[42]: * Channel 247351 has averaged 154.329049 seconds between received cells
Oct 31 04:24:32 tor Tor[42]: * Channel 247351 has averaged 5.048692 seconds between transmitted cells
Oct 31 05:24:33 tor Tor[42]: No unused circIDs found on channel without wide circID support, with 0 inbound and 1 outbound circuits. Found 0 circuit IDs in use by circuits, and 64 with pending destroy cells. (0
Oct 31 05:24:33 tor Tor[42]: Circuitmux on this channel has 1 circuits, of which 1 are active. It says it has 32726 destroy cells queued.
Oct 31 05:24:33 tor Tor[42]: Channel 247351 (at 0x7f57c379b5b0) with transport TLS channel (connection 601243) is in state open (2)
Oct 31 05:24:33 tor Tor[42]: * Channel 247351 was created at 1414665838 (63635 seconds ago) and last active at 1414729464 (9 seconds ago)
Oct 31 05:24:33 tor Tor[42]: * Channel 247351 says it is connected to an OR with digest 631F87EB8FF7E16E9FAD7BC5C0302A19C4A469A8 and no known nickname
Oct 31 05:24:33 tor Tor[42]: * Channel 247351 says its remote address is [scrubbed], and gives a canonical description of "[scrubbed]" and an actual description of "[scrubbed]"
Oct 31 05:24:33 tor Tor[42]: * Channel 247351 has these marks: !bad_for_new_circs canonical is_canonical_is_reliable !client !local outgoing
Oct 31 05:24:33 tor Tor[42]: * Channel 247351 has 0 queued incoming cells and 0 queued outgoing cells
Oct 31 05:24:33 tor Tor[42]: * Channel 247351 has 1 active circuits out of 1 in total
Oct 31 05:24:33 tor Tor[42]: * Channel 247351 was last used by a client at 0 (1414729473 seconds ago)
Oct 31 05:24:33 tor Tor[42]: * Channel 247351 was last drained at 1414729049 (424 seconds ago)
Oct 31 05:24:33 tor Tor[42]: * Channel 247351 last received a cell at 1414729165 (308 seconds ago)
Oct 31 05:24:33 tor Tor[42]: * Channel 247351 last transmitted a cell at 1414729049 (424 seconds ago)
Oct 31 05:24:33 tor Tor[42]: * Channel 247351 has received 398 cells and transmitted 12275
Oct 31 05:24:33 tor Tor[42]: * Channel 247351 has averaged 159.886935 seconds between received cells
Oct 31 05:24:33 tor Tor[42]: * Channel 247351 has averaged 5.184114 seconds between transmitted cells
Oct 31 06:04:29 tor Tor[42]: failed to get unique circID. [6369 similar message(s) suppressed in last 9600 seconds]
Oct 31 06:08:47 tor Tor[42]: Heartbeat: Tor's uptime is 1 day 12:00 hours, with 9390 circuits open. I've sent 427.01 GB and received 401.55 GB.
Oct 31 06:08:47 tor Tor[42]: Average packaged cell fullness: 99.008%
Oct 31 06:08:47 tor Tor[42]: TLS write overhead: 3%
Oct 31 06:08:47 tor Tor[42]: Circuit handshake stats since last time: 414493/414614 TAP, 240702/240738 NTor.
Oct 31 06:24:33 tor Tor[42]: No unused circIDs found on channel without wide circID support, with 0 inbound and 0 outbound circuits. Found 0 circuit IDs in use by circuits, and 64 with pending destroy cells. (0
Oct 31 06:24:33 tor Tor[42]: Circuitmux on this channel has 0 circuits, of which 0 are active. It says it has 32696 destroy cells queued.
Oct 31 06:24:33 tor Tor[42]: Channel 247351 (at 0x7f57c379b5b0) with transport TLS channel (connection 601243) is in state open (2)
Oct 31 06:24:33 tor Tor[42]: * Channel 247351 was created at 1414665838 (67235 seconds ago) and last active at 1414732923 (150 seconds ago)
Oct 31 06:24:33 tor Tor[42]: * Channel 247351 says it is connected to an OR with digest 631F87EB8FF7E16E9FAD7BC5C0302A19C4A469A8 and no known nickname
Oct 31 06:24:33 tor Tor[42]: * Channel 247351 says its remote address is [scrubbed], and gives a canonical description of "[scrubbed]" and an actual description of "[scrubbed]"
Oct 31 06:24:33 tor Tor[42]: * Channel 247351 has these marks: !bad_for_new_circs canonical is_canonical_is_reliable !client !local outgoing
Oct 31 06:24:33 tor Tor[42]: * Channel 247351 has 0 queued incoming cells and 0 queued outgoing cells
Oct 31 06:24:33 tor Tor[42]: * Channel 247351 has 0 active circuits out of 0 in total
Oct 31 06:24:33 tor Tor[42]: * Channel 247351 was last used by a client at 0 (1414733073 seconds ago)
Oct 31 06:24:33 tor Tor[42]: * Channel 247351 was last drained at 1414732923 (150 seconds ago)
Oct 31 06:24:33 tor Tor[42]: * Channel 247351 last received a cell at 1414731391 (1682 seconds ago)
Oct 31 06:24:33 tor Tor[42]: * Channel 247351 last transmitted a cell at 1414732923 (150 seconds ago)
Oct 31 06:24:33 tor Tor[42]: * Channel 247351 has received 402 cells and transmitted 12723
Oct 31 06:24:33 tor Tor[42]: * Channel 247351 has averaged 167.251244 seconds between received cells
Oct 31 06:24:33 tor Tor[42]: * Channel 247351 has averaged 5.284524 seconds between transmitted cells
Oct 31 07:24:34 tor Tor[42]: No unused circIDs found on channel without wide circID support, with 0 inbound and 0 outbound circuits. Found 0 circuit IDs in use by circuits, and 64 with pending destroy cells. (0
Oct 31 07:24:34 tor Tor[42]: Circuitmux on this channel has 0 circuits, of which 0 are active. It says it has 32658 destroy cells queued.
Oct 31 07:24:34 tor Tor[42]: Channel 247351 (at 0x7f57c379b5b0) with transport TLS channel (connection 601243) is in state open (2)
Oct 31 07:24:34 tor Tor[42]: * Channel 247351 was created at 1414665838 (70836 seconds ago) and last active at 1414736658 (16 seconds ago)
Oct 31 07:24:34 tor Tor[42]: * Channel 247351 says it is connected to an OR with digest 631F87EB8FF7E16E9FAD7BC5C0302A19C4A469A8 and no known nickname
Oct 31 07:24:34 tor Tor[42]: * Channel 247351 says its remote address is [scrubbed], and gives a canonical description of "[scrubbed]" and an actual description of "[scrubbed]"
Oct 31 07:24:34 tor Tor[42]: * Channel 247351 has these marks: !bad_for_new_circs canonical is_canonical_is_reliable !client !local outgoing
Oct 31 07:24:34 tor Tor[42]: * Channel 247351 has 0 queued incoming cells and 0 queued outgoing cells
Oct 31 07:24:34 tor Tor[42]: * Channel 247351 has 0 active circuits out of 0 in total
Oct 31 07:24:34 tor Tor[42]: * Channel 247351 was last used by a client at 0 (1414736674 seconds ago)
Oct 31 07:24:34 tor Tor[42]: * Channel 247351 was last drained at 1414736658 (16 seconds ago)
Oct 31 07:24:34 tor Tor[42]: * Channel 247351 last received a cell at 1414731391 (5283 seconds ago)
Oct 31 07:24:34 tor Tor[42]: * Channel 247351 last transmitted a cell at 1414736658 (16 seconds ago)
Oct 31 07:24:34 tor Tor[42]: * Channel 247351 has received 402 cells and transmitted 13171
Oct 31 07:24:34 tor Tor[42]: * Channel 247351 has averaged 176.208955 seconds between received cells
Oct 31 07:24:34 tor Tor[42]: * Channel 247351 has averaged 5.378179 seconds between transmitted cells
Oct 31 08:27:01 tor Tor[42]: No unused circIDs found on channel without wide circID support, with 0 inbound and 0 outbound circuits. Found 0 circuit IDs in use by circuits, and 64 with pending destroy cells. (0
Oct 31 08:27:01 tor Tor[42]: Circuitmux on this channel has 0 circuits, of which 0 are active. It says it has 32494 destroy cells queued.
Oct 31 08:27:01 tor Tor[42]: Channel 247351 (at 0x7f57c379b5b0) with transport TLS channel (connection 601243) is in state open (2)
Oct 31 08:27:01 tor Tor[42]: * Channel 247351 was created at 1414665838 (74583 seconds ago) and last active at 1414740358 (63 seconds ago)
Oct 31 08:27:01 tor Tor[42]: * Channel 247351 says it is connected to an OR with digest 631F87EB8FF7E16E9FAD7BC5C0302A19C4A469A8 and no known nickname
Oct 31 08:27:01 tor Tor[42]: * Channel 247351 says its remote address is [scrubbed], and gives a canonical description of "[scrubbed]" and an actual description of "[scrubbed]"
Oct 31 08:27:01 tor Tor[42]: * Channel 247351 has these marks: !bad_for_new_circs canonical is_canonical_is_reliable !client !local outgoing
Oct 31 08:27:01 tor Tor[42]: * Channel 247351 has 0 queued incoming cells and 0 queued outgoing cells
Oct 31 08:27:01 tor Tor[42]: * Channel 247351 has 0 active circuits out of 0 in total
Oct 31 08:27:01 tor Tor[42]: * Channel 247351 was last used by a client at 0 (1414740421 seconds ago)
Oct 31 08:27:01 tor Tor[42]: * Channel 247351 was last drained at 1414740358 (63 seconds ago)
Oct 31 08:27:01 tor Tor[42]: * Channel 247351 last received a cell at 1414737722 (2699 seconds ago)
Oct 31 08:27:01 tor Tor[42]: * Channel 247351 last transmitted a cell at 1414740358 (63 seconds ago)
Oct 31 08:27:01 tor Tor[42]: * Channel 247351 has received 403 cells and transmitted 13619
Oct 31 08:27:01 tor Tor[42]: * Channel 247351 has averaged 185.069479 seconds between received cells
Oct 31 08:27:01 tor Tor[42]: * Channel 247351 has averaged 5.476393 seconds between transmitted cells
Oct 31 08:44:49 tor Tor[42]: failed to get unique circID. [8185 similar message(s) suppressed in last 9600 seconds]

comment:48 Changed 5 years ago by BeagleBone

Same problem here.

OS: Debian 7 ARM
Tor 0.2.5.6-alpha

P.S. Other posters here: "Do you know how to use pastebin"? or you need to post you f... logs.

Last edited 5 years ago by BeagleBone (previous) (diff)

comment:49 Changed 4 years ago by reezer

Not sure what the problem is. Why not have the logs at a central place?

Anyway, the "Circuit on detached list which I had no reason to mark" appeared again on Tor version 0.2.6.1-alpha (git-5a601dd2901644a5), but no more "unused circIDs", so it seems to either be fixed or the attack stopped.

http://pastebin.com/mi7RhAcY

Sorry for putting everything in this ticket. I am not sure how these things might be related.

Last edited 4 years ago by reezer (previous) (diff)

comment:50 Changed 4 years ago by cypherpunks

Hi,

I'm not entirely sure but I guess I'm having the same issue. Tonight my relay's traffic dropped to 0. Atlas told me it is no longer running. The tor process on the system was still running. The logs showed:

[warn] circuit_unlink_all_from_channel(): Bug: Circuit on detached list which I had no reason to mark
[notice] No circuits are opened. Relaxed timeout for circuit 378 (a General-purpose client 1-hop circuit in state doing handshakes with channel state open) to 60000ms. However, it appears the circuit has timed out anyway. 0 guards are live. [1 similar message(s) suppressed in last 3600 seconds]
[notice] Heartbeat: It seems like we are not in the cached consensus.

I'm running tor v0.2.5.10 on debian.

If this is indeed related to this bug here, should I increase the logging verbosity or anything else that would help you getting to the bottom of this bug?

comment:51 Changed 4 years ago by cypherpunks

Version: Tor: 0.2.5.4-alphaTor: 0.2.5.10

Changed the version from 0.2.5.4-alpha to 0.2.5.10.

comment:52 Changed 4 years ago by nickm

Milestone: Tor: 0.2.5.x-finalTor: 0.2.7.x-final

comment:53 Changed 4 years ago by nickm

Keywords: 027-triaged-1-out added

Marking triaged-out items from first round of 0.2.7 triage.

comment:54 Changed 4 years ago by nickm

Milestone: Tor: 0.2.7.x-finalTor: 0.2.???

Make all non-needs_review, non-needs_revision, 027-triaged-1-out items belong to 0.2.???

comment:55 Changed 4 years ago by cypherpunks

I'm also getting a few of these lines on my 0.2.6.7 relay running FreeBSD 10.1 (OpenSSL 1.0.1l-freebsd).

[warn] void circuit_unlink_all_from_channel(channel_t *, int)(): Bug: Circuit on detached list which I had no reason to mark

comment:56 Changed 4 years ago by dgoulet

Got this line two days ago on my 027 relay on Linux.

Jun 14 06:21:44.000 [warn] circuit_unlink_all_from_channel(): Bug: Circuit on detached list which I had no reason to mark (on Tor 0.2.7.1-alpha-dev 646f2021810ceb2c)

comment:57 Changed 4 years ago by starlight

Cc: starlight@… added

Ditto 0.2.6.10

Oct  5 11:11:38 circuit_unlink_all_from_channel(): Bug: Circuit on detached list which I had no reason to mark

comment:58 Changed 3 years ago by arma

Severity: Normal

I just closed #16832 as a duplicate of this one.

comment:59 Changed 3 years ago by teor

Milestone: Tor: 0.2.???Tor: 0.3.???

Milestone renamed

comment:60 Changed 2 years ago by nickm

Keywords: tor-03-unspecified-201612 added
Milestone: Tor: 0.3.???Tor: unspecified

Finally admitting that 0.3.??? was a euphemism for Tor: unspecified all along.

comment:61 Changed 2 years ago by nickm

Keywords: tor-03-unspecified-201612 removed

Remove an old triaging keyword.

comment:62 Changed 2 years ago by nickm

Keywords: 025-triaged removed

remove an old triage keyword.

comment:63 Changed 2 years ago by nickm

Keywords: 027-triaged-in added

comment:64 Changed 2 years ago by nickm

Keywords: 027-triaged-in removed

comment:65 Changed 2 years ago by nickm

Keywords: 027-triaged-1-out removed

comment:66 Changed 2 years ago by nickm

Keywords: 024-backport removed

None of these is ripe for backport to 0.2.4 even if it does get fixed.

comment:67 Changed 2 years ago by nickm

Keywords: tor-relay needs-insight added
Status: needs_informationnew

#19721 was also closed as a duplicate of this; it has happened as recently as 0.2.7.6.

Note: See TracTickets for help on using tickets.