Opened 4 years ago

Closed 3 years ago

Last modified 2 years ago

#13287 closed task (wontfix)

Investigate mysterious 24-hour lump in hsdir desc fetches

Reported by: arma Owned by:
Priority: Medium Milestone:
Component: Core Tor/Tor Version:
Severity: Normal Keywords: tor-hs
Cc: isis Actual Points:
Parent ID: Points:
Reviewer: Sponsor: SponsorR

Description

Here are the every-thirty-minutes stats for hidden service descriptor stores and fetches on moria1, using the #13195 patch:

Sep 27 14:00:00.638 [notice] Heartbeat: 16 descs (10/12 stored, 1/910 fetched).
Sep 27 14:30:00.866 [notice] Heartbeat: 30 descs (19/19 stored, 0/895 fetched).
Sep 27 15:00:00.938 [notice] Heartbeat: 43 descs (24/24 stored, 3/934 fetched).
Sep 27 15:30:00.432 [notice] Heartbeat: 49 descs (23/23 stored, 4/915 fetched).
Sep 27 16:00:00.101 [notice] Heartbeat: 52 descs (36/37 stored, 6/1010 fetched).
Sep 27 16:30:00.100 [notice] Heartbeat: 54 descs (18/18 stored, 4/1014 fetched).
Sep 27 17:00:00.872 [notice] Heartbeat: 57 descs (25/25 stored, 3/881 fetched).
Sep 27 17:30:00.917 [notice] Heartbeat: 61 descs (29/30 stored, 15/817 fetched).
Sep 27 18:00:00.486 [notice] Heartbeat: 64 descs (26/26 stored, 6/777 fetched).
Sep 27 18:30:00.779 [notice] Heartbeat: 65 descs (27/27 stored, 7/894 fetched).
Sep 27 19:00:00.848 [notice] Heartbeat: 69 descs (26/27 stored, 7/907 fetched).
Sep 27 19:30:00.843 [notice] Heartbeat: 70 descs (22/23 stored, 6/955 fetched).
Sep 27 20:00:00.441 [notice] Heartbeat: 71 descs (24/24 stored, 89/1135 fetched).
Sep 27 20:30:00.661 [notice] Heartbeat: 75 descs (25/26 stored, 99/1357 fetched).
Sep 27 21:00:00.920 [notice] Heartbeat: 75 descs (23/23 stored, 107/9063 fetched).
Sep 27 21:30:00.323 [notice] Heartbeat: 76 descs (17/19 stored, 95/14189 fetched).
Sep 27 22:00:00.227 [notice] Heartbeat: 76 descs (27/27 stored, 84/14208 fetched).
Sep 27 22:30:00.166 [notice] Heartbeat: 76 descs (16/17 stored, 104/14389 fetched).
Sep 27 23:00:00.886 [notice] Heartbeat: 77 descs (26/27 stored, 120/14871 fetched).
Sep 27 23:30:00.027 [notice] Heartbeat: 78 descs (16/17 stored, 107/15177 fetched).
Sep 28 00:00:00.835 [notice] Heartbeat: 80 descs (22/22 stored, 100/13811 fetched).
Sep 28 00:30:00.923 [notice] Heartbeat: 81 descs (21/23 stored, 111/14907 fetched).
Sep 28 01:00:00.546 [notice] Heartbeat: 82 descs (21/21 stored, 92/15235 fetched).
Sep 28 01:30:00.438 [notice] Heartbeat: 83 descs (19/20 stored, 107/16675 fetched).
Sep 28 02:00:00.873 [notice] Heartbeat: 84 descs (33/33 stored, 101/17955 fetched).
Sep 28 02:30:00.341 [notice] Heartbeat: 85 descs (38/39 stored, 106/18851 fetched).
Sep 28 03:00:00.229 [notice] Heartbeat: 86 descs (20/20 stored, 103/17418 fetched).
Sep 28 03:30:00.700 [notice] Heartbeat: 87 descs (20/21 stored, 99/17837 fetched).
Sep 28 04:00:00.653 [notice] Heartbeat: 88 descs (22/22 stored, 83/18491 fetched).
Sep 28 04:30:00.942 [notice] Heartbeat: 90 descs (18/19 stored, 102/17695 fetched).
Sep 28 05:00:00.150 [notice] Heartbeat: 92 descs (20/20 stored, 105/17357 fetched).
Sep 28 05:30:00.188 [notice] Heartbeat: 93 descs (29/30 stored, 116/18145 fetched).
Sep 28 06:00:00.963 [notice] Heartbeat: 94 descs (34/34 stored, 122/21495 fetched).
Sep 28 06:30:00.193 [notice] Heartbeat: 96 descs (41/41 stored, 100/21956 fetched).
Sep 28 07:00:00.697 [notice] Heartbeat: 98 descs (37/37 stored, 5/22160 fetched).
Sep 28 07:30:00.819 [notice] Heartbeat: 100 descs (42/42 stored, 3/23505 fetched).
Sep 28 08:00:00.385 [notice] Heartbeat: 102 descs (39/39 stored, 7/26988 fetched).
Sep 28 08:30:00.476 [notice] Heartbeat: 104 descs (36/38 stored, 7/23314 fetched).
Sep 28 09:00:00.200 [notice] Heartbeat: 105 descs (32/33 stored, 5/19225 fetched).
Sep 28 09:30:00.343 [notice] Heartbeat: 106 descs (38/39 stored, 5/19588 fetched).
Sep 28 10:00:00.149 [notice] Heartbeat: 113 descs (43/43 stored, 6/19089 fetched).
Sep 28 10:30:00.270 [notice] Heartbeat: 118 descs (40/40 stored, 1/21909 fetched).
Sep 28 11:00:00.842 [notice] Heartbeat: 123 descs (51/53 stored, 8/23061 fetched).
Sep 28 11:30:00.150 [notice] Heartbeat: 127 descs (50/51 stored, 4/20228 fetched).
Sep 28 12:00:00.107 [notice] Heartbeat: 127 descs (50/50 stored, 1/21318 fetched).
Sep 28 12:30:00.157 [notice] Heartbeat: 129 descs (40/41 stored, 4/22286 fetched).
Sep 28 13:00:00.793 [notice] Heartbeat: 130 descs (44/47 stored, 1/19157 fetched).
Sep 28 13:30:00.972 [notice] Heartbeat: 134 descs (60/60 stored, 5/18381 fetched).
Sep 28 14:00:00.714 [notice] Heartbeat: 137 descs (37/37 stored, 1/18463 fetched).
Sep 28 14:30:00.847 [notice] Heartbeat: 143 descs (34/34 stored, 3/19324 fetched).
Sep 28 15:00:00.692 [notice] Heartbeat: 147 descs (35/36 stored, 7/18050 fetched).
Sep 28 15:30:00.779 [notice] Heartbeat: 148 descs (35/35 stored, 3/17446 fetched).
Sep 28 16:00:00.427 [notice] Heartbeat: 150 descs (35/35 stored, 3/18933 fetched).
Sep 28 16:30:00.474 [notice] Heartbeat: 151 descs (36/36 stored, 13/19914 fetched).
Sep 28 17:00:00.355 [notice] Heartbeat: 154 descs (34/35 stored, 4/18437 fetched).
Sep 28 17:30:00.413 [notice] Heartbeat: 156 descs (35/35 stored, 2/18242 fetched).
Sep 28 18:00:00.066 [notice] Heartbeat: 162 descs (34/36 stored, 4/18058 fetched).
Sep 28 18:30:00.081 [notice] Heartbeat: 168 descs (41/41 stored, 4/16913 fetched).
Sep 28 19:00:00.796 [notice] Heartbeat: 171 descs (32/34 stored, 4/16914 fetched).
Sep 28 19:30:00.951 [notice] Heartbeat: 174 descs (42/43 stored, 3/17718 fetched).
Sep 28 20:00:00.864 [notice] Heartbeat: 174 descs (37/39 stored, 0/17791 fetched).
Sep 28 20:30:00.204 [notice] Heartbeat: 176 descs (37/38 stored, 3/18305 fetched).
Sep 28 21:00:00.132 [notice] Heartbeat: 177 descs (29/30 stored, 2/6373 fetched).
Sep 28 21:30:00.500 [notice] Heartbeat: 180 descs (37/37 stored, 1/323 fetched).
Sep 28 22:00:00.225 [notice] Heartbeat: 181 descs (26/26 stored, 1/174 fetched).
Sep 28 22:30:00.303 [notice] Heartbeat: 184 descs (40/41 stored, 1/109 fetched).
Sep 28 23:00:00.020 [notice] Heartbeat: 184 descs (22/23 stored, 4/133 fetched).
Sep 28 23:30:00.281 [notice] Heartbeat: 185 descs (33/33 stored, 0/124 fetched).
Sep 29 00:00:00.107 [notice] Heartbeat: 187 descs (30/30 stored, 3/141 fetched).
Sep 29 00:30:00.559 [notice] Heartbeat: 188 descs (31/31 stored, 1/138 fetched).
Sep 29 01:00:00.309 [notice] Heartbeat: 189 descs (22/23 stored, 1/175 fetched).

That's quite the mysterious 24-hour lump in the middle, isn't it. I feel like the sailor who comes back from the voyage with the tale of the sea monster he saw -- some enormous hidden service picked me for one of its hsdirs for this 24 hour period, and at the end it went back into the ocean deep. And I got a snapshot of it on my little black-and-white camera.

Of course, this measurement coincidences with a growth in crawling and other hs measurements, so maybe it is nothing. But the fact that it lasted about 24 hours (21:00 to 21:00) makes me think it is something. In particular, my first thought is that it's a bunch of bot clients trying to reach their C&C. And as a bonus, I basically couldn't answer any of the fetch requests, which is a good sign.

special asked me about TAP vs NTor handshakes in that period. I have them only in six hour chunks, but here they are:

Sep 27 17:15:38.409 [notice] Circuit handshake stats since last time: 8147/8147 TAP, 1679/1679 NTor.
Sep 27 23:15:38.468 [notice] Circuit handshake stats since last time: 83002/83004 TAP, 3420/3420 NTor.
Sep 28 05:15:38.710 [notice] Circuit handshake stats since last time: 208974/208980 TAP, 3859/3859 NTor.
Sep 28 11:15:38.662 [notice] Circuit handshake stats since last time: 273477/273487 TAP, 2835/2835 NTor.
Sep 28 17:15:38.897 [notice] Circuit handshake stats since last time: 241216/241222 TAP, 2817/2817 NTor.
Sep 28 23:15:38.673 [notice] Circuit handshake stats since last time: 126686/126717 TAP, 2637/2637 NTor.

If my next entry is indeed much lower on TAP, that would argue that these hsdesc fetches were made by TAP-using clients, which is another vote for the botnet C&C theory.

Child Tickets

Attachments (1)

moria1-hsdir.png (78.2 KB) - added by karsten 4 years ago.

Download all attachments as: .zip

Change History (14)

comment:1 Changed 4 years ago by arma

Keywords: SponsorR tor-hs added

Changed 4 years ago by karsten

Attachment: moria1-hsdir.png added

comment:2 Changed 4 years ago by karsten

See attached graph, which is probably easier to read than moria1's logs.

comment:3 in reply to:  description Changed 4 years ago by arma

Replying to arma:

special asked me about TAP vs NTor handshakes in that period. I have them only in six hour chunks, but here they are:

Sep 27 17:15:38.409 [notice] Circuit handshake stats since last time: 8147/8147 TAP, 1679/1679 NTor.
Sep 27 23:15:38.468 [notice] Circuit handshake stats since last time: 83002/83004 TAP, 3420/3420 NTor.
Sep 28 05:15:38.710 [notice] Circuit handshake stats since last time: 208974/208980 TAP, 3859/3859 NTor.
Sep 28 11:15:38.662 [notice] Circuit handshake stats since last time: 273477/273487 TAP, 2835/2835 NTor.
Sep 28 17:15:38.897 [notice] Circuit handshake stats since last time: 241216/241222 TAP, 2817/2817 NTor.
Sep 28 23:15:38.673 [notice] Circuit handshake stats since last time: 126686/126717 TAP, 2637/2637 NTor.

If my next entry is indeed much lower on TAP, that would argue that these hsdesc fetches were made by TAP-using clients, which is another vote for the botnet C&C theory.

Sep 29 05:15:38.627 [notice] Circuit handshake stats since last time: 1113/1113 TAP, 2629/2629 NTor.
Sep 29 11:15:38.713 [notice] Circuit handshake stats since last time: 1271/1271 TAP, 2775/2775 NTor.

Looks like it matches the theory.

comment:4 Changed 4 years ago by dgoulet

Just patched my fast relay with the hs-stats branch to monitor that.

Wondering, why so many fetches would fail here? Like if the botnet client was trying a huge amount of onion address and ony a few actually exists? Seems like a poor way of trying to reach a specific C&C...

comment:5 Changed 4 years ago by dgoulet

After a few days, here is a snippet that is consistent across the log on my relay:

Nov 20 08:00:00.000 [notice] Heartbeat: 235 descs (29/29 stored, 1/1100 fetched).
Nov 20 08:30:00.000 [notice] Heartbeat: 239 descs (24/24 stored, 1/911 fetched).
Nov 20 09:00:00.000 [notice] Heartbeat: 238 descs (21/21 stored, 0/917 fetched).

It's not the huge amount moria shows above but still the fact that in a period of 30 minutes, 1100 attempts failed is bothersome.

Looking at it with nickm, here are possible scenarios for why this is happening. (Please add missing scenarios also).

1) HS doesn't exists

i) A very popular HS that for some reasons clients are trying to access it non stop and it moves around.
ii) Client that can't find it don't give up?

2) The HSdir rejected it erroneously?

3) Clients are asking in the wrong place. (see "1i)" and "1ii)" as above).

i) Maybe a bug in the tor client that loops?
ii) Automated client that just retries a single address non stop voluntarily (botnet theory)

4) UNLIKELY: HS enumeration by brute forcing onion address but ouf... that is unlikely.

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

comment:6 Changed 4 years ago by dgoulet

In the last ~12 hours or so, I just got a huge bump, so definitely something is up.

Nov 21 08:00:00.000 [notice] Heartbeat: 225 descs (27/29 stored, 3/21244 fetched).
Nov 21 08:30:00.000 [notice] Heartbeat: 225 descs (27/28 stored, 13/23607 fetched).
Nov 21 09:00:00.000 [notice] Heartbeat: 224 descs (25/25 stored, 8/25501 fetched).

comment:7 Changed 4 years ago by dgoulet

Ok so I added a quick patch to log the desc_id that are being fetched (obfuscated using siphash24g()) and it appears that it is the same desc_id that is being fetched again and again.

 10:45:48 [NOTICE] Attempt on 17195692294194523357 [16117 duplicates hidden]

And each period gets a huge number for the same desc_id. We'll see if in like 24 hours, this address will change. Sounds more and more like a dead C&C a botnet is trying to reach....

comment:8 Changed 4 years ago by isis

Cc: isis added

comment:9 Changed 3 years ago by nickm

Keywords: SponsorR removed
Sponsor: SponsorR

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

comment:10 Changed 3 years ago by arma

Severity: Normal

David: shall we close this ticket, since we're quite sure now that we have a good answer?

comment:11 in reply to:  10 Changed 3 years ago by dgoulet

Resolution: wontfix
Status: newclosed

Replying to arma:

David: shall we close this ticket, since we're quite sure now that we have a good answer?

Yes I think we can close it. My best estimate is that it's some bot trying to find some C&C or a insane application in loop of the wrong .onion... I still see a lot of request for the same .onion on my relay but it went down.

comment:12 Changed 2 years ago by teor

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

Milestone renamed

comment:13 Changed 2 years ago by nickm

Milestone: Tor: 0.3.???

Milestone deleted

Note: See TracTickets for help on using tickets.