Opened 2 years ago

Last modified 9 months ago

#20421 assigned defect

Investigate invalid descriptors in out/ and recent/ subdirectories

Reported by: karsten Owned by: metrics-team
Priority: Medium Milestone:
Component: Metrics/CollecTor Version:
Severity: Normal Keywords: metrics-2018
Cc: iwakeh Actual Points:
Parent ID: #20548 Points:
Reviewer: Sponsor:

Description

I just found more bad descriptors like the one mentioned in #20412 by looking through Onionoo logs. This might be a bigger problem than first thought.

I don't have the time to investigate this now, but it looks like we might not be flushing a buffer properly somewhere. For example:

hidden-@uploaded-at 2016-10-19 06:53:16

The hidden- part still belongs to the previous descriptor and then we start writing @uploaded-at 2016-10-19 06:53:16 as the first line of the next descriptor. Note that we wouldn't include that line under normal circumstances. How does it get there?

I'll attach four files from CollecTor's recent/ subdirectory which would otherwise be deleted soon.

I'm afraid we'll not only have to fix this bug but also go through the tarballs from the past months and see if those contain invalid descriptors. Hopefully it's a new bug.

Child Tickets

Attachments (4)

Change History (14)

comment:1 Changed 2 years ago by karsten

Ah, some more information from the CollecTor logs:

2016-10-19 04:05:00,001 INFO o.t.c.c.CollecTorMain:54 Starting relaydescs module of CollecTor.
2016-10-19 04:05:10,870 INFO o.t.c.r.ArchiveWriter:842 Could not parse relay descriptor out/relay-descriptors/server-descriptor/2016/10/5/7/57077357a8bc1d431e89e29e3cec7d9a31d59332 before storing it to disk.  Storing anyway.
org.torproject.descriptor.DescriptorParseException: Either keyword 'accept' or 'reject' must be contained at least once.
        at org.torproject.descriptor.impl.ServerDescriptorImpl.<init>(ServerDescriptorImpl.java:49) ~[collector-1.0.2.jar:1.0.2-c43d0ad]
        at org.torproject.descriptor.impl.RelayServerDescriptorImpl.<init>(RelayServerDescriptorImpl.java:35) ~[collector-1.0.2.jar:1.0.2-c43d0ad]
        at org.torproject.descriptor.impl.RelayServerDescriptorImpl.parseDescriptors(RelayServerDescriptorImpl.java:24) ~[collector-1.0.2.jar:1.0.2-c43d0ad]
        at org.torproject.descriptor.impl.DescriptorImpl.parseDescriptors(DescriptorImpl.java:61) ~[collector-1.0.2.jar:1.0.2-c43d0ad]
        at org.torproject.descriptor.impl.DescriptorParserImpl.parseDescriptors(DescriptorParserImpl.java:26) ~[collector-1.0.2.jar:1.0.2-c43d0ad]
        at org.torproject.collector.relaydescs.ArchiveWriter.store(ArchiveWriter.java:836) [collector-1.0.2.jar:1.0.2-c43d0ad]
        at org.torproject.collector.relaydescs.ArchiveWriter.storeServerDescriptor(ArchiveWriter.java:752) [collector-1.0.2.jar:1.0.2-c43d0ad]
        at org.torproject.collector.relaydescs.RelayDescriptorParser.parse(RelayDescriptorParser.java:266) [collector-1.0.2.jar:1.0.2-c43d0ad]
        at org.torproject.collector.relaydescs.CachedRelayDescriptorReader.<init>(CachedRelayDescriptorReader.java:216) [collector-1.0.2.jar:1.0.2-c43d0ad]
        at org.torproject.collector.relaydescs.ArchiveWriter.startProcessing(ArchiveWriter.java:166) [collector-1.0.2.jar:1.0.2-c43d0ad]
        at org.torproject.collector.cron.CollecTorMain.run(CollecTorMain.java:56) [collector-1.0.2.jar:1.0.2-c43d0ad]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) [na:1.7.0_111]
        at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:304) [na:1.7.0_111]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:178) [na:1.7.0_111]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [na:1.7.0_111]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [na:1.7.0_111]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [na:1.7.0_111]
        at java.lang.Thread.run(Thread.java:745) [na:1.7.0_111]
2016-10-19 04:05:18,322 INFO o.t.c.r.ArchiveWriter:842 Could not parse relay descriptor out/relay-descriptors/extra-info/2016/10/4/8/481a2c9b4db3a29e499b9ce0b8bf26ca0c344e0f before storing it to disk.  Storing anyway.
org.torproject.descriptor.DescriptorParseException: Mismatch between identity-ed25519 and master-key-ed25519.
        at org.torproject.descriptor.impl.ExtraInfoDescriptorImpl.parseIdentityEd25519CryptoBlock(ExtraInfoDescriptorImpl.java:789) ~[collector-1.0.2.jar:1.0.2-c43d0ad]
        at org.torproject.descriptor.impl.ExtraInfoDescriptorImpl.parseDescriptorBytes(ExtraInfoDescriptorImpl.java:260) ~[collector-1.0.2.jar:1.0.2-c43d0ad]
        at org.torproject.descriptor.impl.ExtraInfoDescriptorImpl.<init>(ExtraInfoDescriptorImpl.java:35) ~[collector-1.0.2.jar:1.0.2-c43d0ad]
        at org.torproject.descriptor.impl.RelayExtraInfoDescriptorImpl.<init>(RelayExtraInfoDescriptorImpl.java:35) ~[collector-1.0.2.jar:1.0.2-c43d0ad]
        at org.torproject.descriptor.impl.RelayExtraInfoDescriptorImpl.parseDescriptors(RelayExtraInfoDescriptorImpl.java:24) ~[collector-1.0.2.jar:1.0.2-c43d0ad]
        at org.torproject.descriptor.impl.DescriptorImpl.parseDescriptors(DescriptorImpl.java:71) ~[collector-1.0.2.jar:1.0.2-c43d0ad]
        at org.torproject.descriptor.impl.DescriptorParserImpl.parseDescriptors(DescriptorParserImpl.java:26) ~[collector-1.0.2.jar:1.0.2-c43d0ad]
        at org.torproject.collector.relaydescs.ArchiveWriter.store(ArchiveWriter.java:836) [collector-1.0.2.jar:1.0.2-c43d0ad]
        at org.torproject.collector.relaydescs.ArchiveWriter.storeExtraInfoDescriptor(ArchiveWriter.java:782) [collector-1.0.2.jar:1.0.2-c43d0ad]
        at org.torproject.collector.relaydescs.RelayDescriptorParser.parse(RelayDescriptorParser.java:305) [collector-1.0.2.jar:1.0.2-c43d0ad]
        at org.torproject.collector.relaydescs.CachedRelayDescriptorReader.<init>(CachedRelayDescriptorReader.java:216) [collector-1.0.2.jar:1.0.2-c43d0ad]
        at org.torproject.collector.relaydescs.ArchiveWriter.startProcessing(ArchiveWriter.java:166) [collector-1.0.2.jar:1.0.2-c43d0ad]
        at org.torproject.collector.cron.CollecTorMain.run(CollecTorMain.java:56) [collector-1.0.2.jar:1.0.2-c43d0ad]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) [na:1.7.0_111]
        at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:304) [na:1.7.0_111]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:178) [na:1.7.0_111]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [na:1.7.0_111]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [na:1.7.0_111]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [na:1.7.0_111]
        at java.lang.Thread.run(Thread.java:745) [na:1.7.0_111]
2016-10-19 04:05:18,590 INFO o.t.c.r.CachedRelayDescriptorReader:255 Finished importing relay descriptors from local Tor data directories:
2016-10-19 07:05:00,001 INFO o.t.c.c.CollecTorMain:54 Starting relaydescs module of CollecTor.
2016-10-19 07:05:10,500 INFO o.t.c.r.ArchiveWriter:842 Could not parse relay descriptor out/relay-descriptors/server-descriptor/2016/10/4/6/4630ff545faaf16f8102311c4a1506a7497a70f2 before storing it to disk.  Storing anyway.
org.torproject.descriptor.DescriptorParseException: Unrecognized character in keyword 'hidden-@uploaded-at' in line 'hidden-@uploaded-at 2016-10-19 06:53:16'.
        at org.torproject.descriptor.impl.ParseHelper.parseKeyword(ParseHelper.java:30) ~[collector-1.0.2.jar:1.0.2-c43d0ad]
        at org.torproject.descriptor.impl.ServerDescriptorImpl.parseDescriptorBytes(ServerDescriptorImpl.java:228) ~[collector-1.0.2.jar:1.0.2-c43d0ad]
        at org.torproject.descriptor.impl.ServerDescriptorImpl.<init>(ServerDescriptorImpl.java:30) ~[collector-1.0.2.jar:1.0.2-c43d0ad]
        at org.torproject.descriptor.impl.RelayServerDescriptorImpl.<init>(RelayServerDescriptorImpl.java:35) ~[collector-1.0.2.jar:1.0.2-c43d0ad]
        at org.torproject.descriptor.impl.RelayServerDescriptorImpl.parseDescriptors(RelayServerDescriptorImpl.java:24) ~[collector-1.0.2.jar:1.0.2-c43d0ad]
        at org.torproject.descriptor.impl.DescriptorImpl.parseDescriptors(DescriptorImpl.java:61) ~[collector-1.0.2.jar:1.0.2-c43d0ad]
        at org.torproject.descriptor.impl.DescriptorParserImpl.parseDescriptors(DescriptorParserImpl.java:26) ~[collector-1.0.2.jar:1.0.2-c43d0ad]
        at org.torproject.collector.relaydescs.ArchiveWriter.store(ArchiveWriter.java:836) [collector-1.0.2.jar:1.0.2-c43d0ad]
        at org.torproject.collector.relaydescs.ArchiveWriter.storeServerDescriptor(ArchiveWriter.java:752) [collector-1.0.2.jar:1.0.2-c43d0ad]
        at org.torproject.collector.relaydescs.RelayDescriptorParser.parse(RelayDescriptorParser.java:266) [collector-1.0.2.jar:1.0.2-c43d0ad]
        at org.torproject.collector.relaydescs.CachedRelayDescriptorReader.<init>(CachedRelayDescriptorReader.java:216) [collector-1.0.2.jar:1.0.2-c43d0ad]
        at org.torproject.collector.relaydescs.ArchiveWriter.startProcessing(ArchiveWriter.java:166) [collector-1.0.2.jar:1.0.2-c43d0ad]
        at org.torproject.collector.cron.CollecTorMain.run(CollecTorMain.java:56) [collector-1.0.2.jar:1.0.2-c43d0ad]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) [na:1.7.0_111]
        at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:304) [na:1.7.0_111]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:178) [na:1.7.0_111]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [na:1.7.0_111]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [na:1.7.0_111]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [na:1.7.0_111]
        at java.lang.Thread.run(Thread.java:745) [na:1.7.0_111]
2016-10-19 07:05:10,978 INFO o.t.c.r.ArchiveWriter:842 Could not parse relay descriptor out/relay-descriptors/extra-info/2016/10/3/6/36d5e078af899d327f286e5cd0bdc48189ea2a1d before storing it to disk.  Storing anyway.
org.torproject.descriptor.DescriptorParseException: Keyword 'published' is contained 2 times, but must be contained exactly once.
        at org.torproject.descriptor.impl.DescriptorImpl.checkExactlyOnceKeywords(DescriptorImpl.java:293) ~[collector-1.0.2.jar:1.0.2-c43d0ad]
        at org.torproject.descriptor.impl.ExtraInfoDescriptorImpl.<init>(ExtraInfoDescriptorImpl.java:40) ~[collector-1.0.2.jar:1.0.2-c43d0ad]
        at org.torproject.descriptor.impl.RelayExtraInfoDescriptorImpl.<init>(RelayExtraInfoDescriptorImpl.java:35) ~[collector-1.0.2.jar:1.0.2-c43d0ad]
        at org.torproject.descriptor.impl.RelayExtraInfoDescriptorImpl.parseDescriptors(RelayExtraInfoDescriptorImpl.java:24) ~[collector-1.0.2.jar:1.0.2-c43d0ad]
        at org.torproject.descriptor.impl.DescriptorImpl.parseDescriptors(DescriptorImpl.java:71) ~[collector-1.0.2.jar:1.0.2-c43d0ad]
        at org.torproject.descriptor.impl.DescriptorParserImpl.parseDescriptors(DescriptorParserImpl.java:26) ~[collector-1.0.2.jar:1.0.2-c43d0ad]
        at org.torproject.collector.relaydescs.ArchiveWriter.store(ArchiveWriter.java:836) [collector-1.0.2.jar:1.0.2-c43d0ad]
        at org.torproject.collector.relaydescs.ArchiveWriter.storeExtraInfoDescriptor(ArchiveWriter.java:782) [collector-1.0.2.jar:1.0.2-c43d0ad]
        at org.torproject.collector.relaydescs.RelayDescriptorParser.parse(RelayDescriptorParser.java:305) [collector-1.0.2.jar:1.0.2-c43d0ad]
        at org.torproject.collector.relaydescs.CachedRelayDescriptorReader.<init>(CachedRelayDescriptorReader.java:216) [collector-1.0.2.jar:1.0.2-c43d0ad]
        at org.torproject.collector.relaydescs.ArchiveWriter.startProcessing(ArchiveWriter.java:166) [collector-1.0.2.jar:1.0.2-c43d0ad]
        at org.torproject.collector.cron.CollecTorMain.run(CollecTorMain.java:56) [collector-1.0.2.jar:1.0.2-c43d0ad]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) [na:1.7.0_111]
        at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:304) [na:1.7.0_111]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:178) [na:1.7.0_111]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [na:1.7.0_111]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [na:1.7.0_111]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [na:1.7.0_111]
        at java.lang.Thread.run(Thread.java:745) [na:1.7.0_111]
2016-10-19 07:05:14,710 INFO o.t.c.r.CachedRelayDescriptorReader:255 Finished importing relay descriptors from local Tor data directories:

So, we can probably expect invalid descriptors to be contained in the tarballs since we allowed descriptors that we cannot parse. Heh, makes more sense now, though we probably cannot do much about this. Still, ugh!

These descriptors confuse CollecTor's reference checker which relies on metrics-lib, making it think it's missing a whole lot of descriptors. I wonder if we need to make it more robust and continue reading until it finds the next valid descriptor.

Changed 2 years ago by karsten

Changed 2 years ago by karsten

Changed 2 years ago by karsten

Changed 2 years ago by karsten

comment:2 Changed 2 years ago by iwakeh

While testing sync I found also descriptors with multiple 'accept' and 'reject' lines recent example.

comment:3 Changed 2 years ago by iwakeh

reply to comment:1:
We discussed a lenient parser elsewhere before: #19842.

comment:4 Changed 2 years ago by iwakeh

A summary

The four following parsing exceptions seem to be the only ones in the current recent directory of the main collector instance (the two above and two further ones):

collector.torproject.org/recent/relay-descriptors/extra-infos/2016-10-19-04-05-00-extra-infos caused Exception(s
). Processing anyway.
org.torproject.descriptor.DescriptorParseException: Mismatch between identity-ed25519 and master-key-ed25519.

collector.torproject.org/recent/relay-descriptors/extra-infos/2016-10-19-07-05-00-extra-infos caused Exception(s
). Processing anyway.
org.torproject.descriptor.DescriptorParseException: Keyword 'published' is contained 2 times, but must be contained exactly once.

collector.torproject.org/recent/relay-descriptors/server-descriptors/2016-10-19-04-05-00-server-descriptors caused Exception(s). Processing anyway.
org.torproject.descriptor.DescriptorParseException: Either keyword 'accept' or 'reject' must be contained at least once.

collector.torproject.org/recent/relay-descriptors/server-descriptors/2016-10-19-07-05-00-server-descriptors caused Exception(s). Processing anyway.
org.torproject.descriptor.DescriptorParseException: Unrecognized character in keyword 'hidden-@uploaded-at' in line 'hidden-@uploaded-at 2016-10-19 06:53:16'.

comment:5 Changed 2 years ago by iwakeh

Btw, the mirror has been running fine during the last months and doesn't have these invalid descriptors.
Could this again be due to the cached descriptor import?

comment:6 Changed 2 years ago by karsten

Yes, I think this is due to the cached descriptor import.

comment:7 Changed 2 years ago by iwakeh

Parent ID: #20548

Depends on discussion for all Metrics' products, see parent #20548.

comment:8 Changed 14 months ago by karsten

Keywords: metrics-2018 added

comment:9 Changed 14 months ago by karsten

Owner: set to metrics-team
Status: newassigned

comment:10 Changed 9 months ago by karsten

Priority: HighMedium

This ticket has not been modified in the last 2 months or even longer. Setting priority to medium.

Note: See TracTickets for help on using tickets.