Opened 9 years ago

Last modified 6 months ago

#1889 new defect

Contradictory bandwidth reports in overlapping extra-info descriptors

Reported by: mwenge Owned by:
Priority: Medium Milestone: Tor: unspecified
Component: Core Tor/Tor Version:
Severity: Normal Keywords: tor-relay metrics extrainfo bandwidth privcount
Cc: karsten Actual Points:
Parent ID: #29129 Points:
Reviewer: Sponsor:

Description

On a randomly sampled day in July there were 2000+ cases where the bw reported by extra-info for a given timeslice on a router was two different measurements, depending on which extra-info descriptor you looked at.

Here is an example in the read history for relay Pounet27TorRelay:

BW NOT EQUAL for 2010-07-30T02:31. Is 439296 : Was 4738048
read-history 2010-07-30 21:46:14 (900 s) 11229184,13546496,11268096,13392896,16567296,9265152,6163456,4869120,8190976,0,0,0,0,0,0,0,0,0,734208,439296,0,0,0,0,0,0,0,0,0,6400000,11721728,12796928,12404736,14963712,13637632,11209728,12163072,10721280,6233088,10669056,9666560,9474048,11543552,11773952,10487808,10580992,10299392,13220864,12548096,11171840,7584768,4970496,3948544,2686976,4140032,4179968,4777984,8782848,9647104,9838592,13700096,10819584,11526144,9906176,14349312,12468224,13254656,8672256,5794816,7155712,3275776,3682304,3339264,6937600,6926336,7901184,8549376,10533888,7639040,9754624,6426624,4097024,5630976,4674560,5093376,6675456,4874240,5531648,3744768,6883328,9871360,11807744,11097088,9028608,9231360,9802752

read-history 2010-07-30 04:46:14 (900 s) 8813568,8123392,9978880,8428544,9339904,6733824,9417728,11633664,11225088,9106432,11148288,7831552,11962368,9401344,8095744,8654848,9501696,7830528,6435840,8958976,4248576,4089856,4747264,6569984,4973568,2717696,5286912,0,0,1968128,0,0,0,0,0,0,0,0,0,2446336,5278720,6597632,4627456,7857152,7080960,8280064,5863424,7086080,5991424,2252800,1883136,5161984,3418112,4377600,3938304,6874112,5746688,2485248,3495936,4019200,6891520,3680256,4489216,4912128,3629056,1320960,7661568,11542528,11229184,13546496,11268096,13392896,16567296,9265152,6163456,4869120,8190976,0,0,0,0,0,0,0,0,0,245760,4738048,5920768,3057664,4745216,6483968,5610496,5480448,5497856,5471232

The difference starts after the zeros in the following sequence in each extra-info:

21:46: 11229184,13546496,11268096,13392896,16567296,9265152,6163456,4869120,8190976,0,0,0,0,0,0,0,0,0,245760,4738048
04:46: 11229184,13546496,11268096,13392896,16567296,9265152,6163456,4869120,8190976,0,0,0,0,0,0,0,0,0,734208,439296

I need to characterize the samples I have better to see if there's a pattern but any idea why this might happen?

Child Tickets

Change History (13)

comment:1 Changed 9 years ago by Sebastian

I'm thinking this could be related to bug #1796 at least in some cases.

comment:2 Changed 9 years ago by mwenge

i was just about to close it as a duplicate! 110 unique routers exhibited this behaviour on the 30th July. The examples I found look mostly like relay/client combinations (45 of them are 'Unnamed'), so I think they are covered by #1796. There's one or two that look like headless servers though and the problem they have looks slightly different:

First Example


You can see with this guy the descriptor at 18:58 reports zero bandwidth almost into the previous day. There are 81 zeroes there and each one represents a 15 minute interval, so that's over 20 hours. It's reporting zero bandwidth for periods that in its previous descriptor reported quite heavy bandwidth.

AnonymTorProxy
write-history 2010-07-30 18:58:09 (900 s) 51016704,54854656,56370176,61966336,87502848,140687360,52063232,39117824,53959680,92855296,45904896,24967168,7930880,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,184320,965632

write-history 2010-07-30 01:43:09 (900 s) 49228800,40128512,22645760,47933440,45445120,32333824,19849216,16937984,30072832,65630208,55131136,50461696,33767424,60020736,51193856,46249984,63535104,80968704,59577344,128847872,104945664,86573056,94878720,95174656,102881280,52918272,47956992,62808064,76340224,42440704,19562496,33812480,59432960,35354624,53516288,57620480,47820800,78172160,76681216,50040832,52646912,52122624,45438976,52240384,103915520,87828480,102213632,125029376,116759552,104132608,80033792,69415936,74482688,103608320,66944000,48066560,47063040,57641984,77840384,61473792,31711232,36148224,37580800,75486208,54866944,51417088,56162304,53396480,31748096,51016704,54854656,56370176,61966336,87502848,140687360,52063232,39117824,53959680,92855296,45904896,24967168,119614464,103352320,51945472,97429504,44146688,63855616,73466880,67643392,43849728,49810432,115605504,101196800,55580672,39632896,78535680

Full descriptors:
extra-info AnonymTorProxy 66F325326B049FC27EF97D544D8257AF3085E872
published 2010-07-30 18:59:06
write-history 2010-07-30 18:58:09 (900 s) 51016704,54854656,56370176,61966336,87502848,140687360,52063232,39117824,53959680,92855296,45904896,24967168,7930880,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,184320,965632
read-history 2010-07-30 18:58:09 (900 s) 50190336,55837696,55800832,62022656,88251392,140708864,51249152,38636544,53901312,93604864,45599744,24365056,7538688,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,911360,1756160
router-signature


leLnLp6i26ZhjNqK+7NCpj6ZMDmhgMZXw8tB6LdJJ1KDuxuEdN8kKg72SnNoNMDl
tkrljowxv6c++2LBzxtryNW6u4WR8jPutLBy6t0JQqJok8MO7gM/FaDXWmaAmJSq
wI6EV+eAS/FCHyHm53ZFtqAhicFkHc+stamzcY2E7c4=


extra-info AnonymTorProxy 66F325326B049FC27EF97D544D8257AF3085E872
published 2010-07-30 01:45:49
write-history 2010-07-30 01:43:09 (900 s) 49228800,40128512,22645760,47933440,45445120,32333824,19849216,16937984,30072832,65630208,55131136,50461696,33767424,60020736,51193856,46249984,63535104,80968704,59577344,128847872,104945664,86573056,94878720,95174656,102881280,52918272,47956992,62808064,76340224,42440704,19562496,33812480,59432960,35354624,53516288,57620480,47820800,78172160,76681216,50040832,52646912,52122624,45438976,52240384,103915520,87828480,102213632,125029376,116759552,104132608,80033792,69415936,74482688,103608320,66944000,48066560,47063040,57641984,77840384,61473792,31711232,36148224,37580800,75486208,54866944,51417088,56162304,53396480,31748096,51016704,54854656,56370176,61966336,87502848,140687360,52063232,39117824,53959680,92855296,45904896,24967168,119614464,103352320,51945472,97429504,44146688,63855616,73466880,67643392,43849728,49810432,115605504,101196800,55580672,39632896,78535680
read-history 2010-07-30 01:43:09 (900 s) 48861184,39711744,21775360,47252480,44870656,31617024,19155968,16345088,29703168,66360320,54417408,49335296,32943104,59510784,50925568,45722624,63747072,81938432,58669056,129881088,105329664,87041024,94388224,95159296,102889472,52442112,48154624,62735360,76195840,41905152,18767872,33336320,58730496,34831360,52738048,57076736,47667200,77825024,76225536,49925120,51943424,51494912,44863488,51666944,103457792,88199168,102104064,124966912,115953664,102737920,79110144,68694016,73610240,102449152,65817600,47467520,46462976,57056256,77469696,60920832,31194112,35255296,36624384,74982400,54017024,51510272,55950336,53445632,31586304,50190336,55837696,55800832,62022656,88251392,140708864,51249152,38636544,53901312,93604864,45599744,24365056,120870912,103043072,51296256,98429952,43932672,63570944,73304064,67204096,42788864,49015808,115565568,100626432,54820864,38676480,78179328
router-signature


XhZWATbE7adTgqIyuqEchk31u2qe8ID42HLzWbCQhQmdwu/vses0LRd8mlkF9r6I
VbWWV5Zk0ke84+YoRsPRk1YPnyflpGCjU7HsKGrW7D5JSH1LaedaNIC/XSCGUL3d
MU46ZUIEtWu/rSN64XMPXUXIyuGi/d2JHT37WoTqVpM=


Second example:


The bw reported by PPrivCom004 just seems plain contradictory.

PPrivCom004:
write-history 2010-07-30 21:25:17 (900 s) 0,0,0,0,0,0,133120,163840,47104,0,0,0,0,0,780288,115712,14336,0,0,0,0,0,0,0,0,0,0,0,0,0,1244160,184320,80896,0,0,0,0,0,0,0,0,0,81920,120832,24576,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,2101248

write-history 2010-07-30 08:25:17 (900 s) 0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,129024,121856,16384,0,0,0,0,0,0,0,0,0,0,0,0,0,190464,103424,22528,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,685056

comment:3 Changed 9 years ago by Sebastian

I'm wondering if the case where we previously reported bandwidth and then don't could be a state file saving/parsing problem

comment:4 Changed 9 years ago by nickm

Milestone: Tor: 0.2.3.x-final

Should do this on an 0.2.3.x timeframe, but possibly consider it a backport candidate.

comment:5 Changed 7 years ago by nickm

Milestone: Tor: 0.2.3.x-finalTor: 0.2.4.x-final

Should do this on an 0.2.4.x timeframe, but possibly consider it a backport candidate.

comment:6 Changed 7 years ago by nickm

Keywords: tor-relay added

comment:7 Changed 7 years ago by nickm

Component: Tor RelayTor

comment:8 Changed 7 years ago by nickm

Milestone: Tor: 0.2.4.x-finalTor: unspecified

comment:9 Changed 3 years ago by arma

Cc: karsten added
Severity: Normal

Karsten, do you have any interest in this one? Do you think it is still an issue, or have we resolved it sometime in the past 5 years? How do the metrics tools handle this possible situation?

comment:10 Changed 2 years ago by nickm

Keywords: metrics extrainfo bandwidth added

comment:11 Changed 6 months ago by teor

Keywords: privcount added

This problem will go away when we put bandwidths in PrivCount.

comment:12 Changed 6 months ago by teor

Parent ID: #24250

This could be a duplicate of #24250.

comment:13 Changed 6 months ago by teor

Parent ID: #24250#29129

This might go away with #29019, but it will definitely go away when we put bandwidths in PrivCount in #29129.

It might also be an issue where multiple relay instances share the same keys. We'll deal with that in PrivCount in #29130.

Note: See TracTickets for help on using tickets.